[strongSwan] sa payload missing after reconnection, strongSwan v5.0.4 <> Cisco 3925 ASR v15.0(1)M3
Paul Theodoropoulos
paul at anastrophe.com
Thu May 16 21:57:26 CEST 2013
This seems similar/related to Bharath Kumar's thread of January this
year, "Strongswan 5.0.1 tears down IPSec SA before the last Quick Mode
message (Hash) is received". Unfortunately either the code between 5.0.1
and 5.0.4 has changed drastically, or I'm just clueless, as I'm unable
to successfully compile task_manager_v1.c after applying his modifications.
I'm afraid I'm new to most things VPN, so I apologize if I over-document
or use terms incorrectly. I appreciate any help I can get!
We are establishing an IKEv1 transport between Amazon Web Services VPC
and part of Verizon's cellular network. The VZW side is the Cisco 3925,
on my side I have a 'small' instance of Debian Squeeze (Linux
2.6.32-5-xen-amd64) acting as the strongSwan router.
I compiled and installed 5.0.4. I am able to establish a successful
session that runs stable, no problem. However, actually getting to that
stable place required countless 'ipsec stop, ipsec start' iterations
over the last week or more as I poked at the configurations.
Since finally bringing up the stable session - while testing failure
modes thereafter but with no configuration changes - sometimes the
session will obstinately refuse to re-establish. It appears to be
partially timing - 'ipsec restart' is quite prone to it, however 'ipsec
stop' followed by several minutes waiting (effective elapsed time not
determined yet), then the 'ipsec start', will bring up the connection.
The problem of course is that waiting five or N minutes to restart the
VPN is not acceptable in a production environment. Here's the whole of
my ipsec.conf, addresses obfuscated:
config setup
#charondebug="ike 2"
uniqueids=yes
conn %default
ikelifetime=28800s
keylife=20m
rekeymargin=3m
keyingtries=1
keyexchange=ikev1
ike=3des-sha1-modp1024!
esp=3des-sha1!
type=transport
conn us-them
leftauth=psk
leftid=192.168.88.88
left=10.1.1.1
leftsubnet=10.1.1.0/24
leftfirewall=yes
lefthostaccess=yes
rightauth=psk
right=192.168.22.22
rightid=192.168.22.22
rightsubnet=10.238.0.0/15
auto=add
include /var/lib/strongswan/ipsec.conf.inc
And here's a section of logs showing the failure. I've added
"<<<<<<<<<<<<<<<" to call out the relevant error lines. About halfway
through you can see at 11:18:21 where I ipsec stopped, waited fifteen
minutes, then ipsec started successfully. Addresses obfuscated
identically to config.
May 16 11:16:56 localhost charon: 00[DMN] Starting IKE charon daemon
(strongSwan 5.0.4, Linux 2.6.32-5-xen-amd64, x86_64)
May 16 11:16:56 localhost charon: 00[CFG] loading ca certificates from
'/usr/local/etc/ipsec.d/cacerts'
May 16 11:16:56 localhost charon: 00[CFG] loading aa certificates from
'/usr/local/etc/ipsec.d/aacerts'
May 16 11:16:56 localhost charon: 00[CFG] loading ocsp signer
certificates from '/usr/local/etc/ipsec.d/ocspcerts'
May 16 11:16:56 localhost charon: 00[CFG] loading attribute certificates
from '/usr/local/etc/ipsec.d/acerts'
May 16 11:16:56 localhost charon: 00[CFG] loading crls from
'/usr/local/etc/ipsec.d/crls'
May 16 11:16:56 localhost charon: 00[CFG] loading secrets from
'/usr/local/etc/ipsec.secrets'
May 16 11:16:56 localhost charon: 00[CFG] expanding file expression
'/var/lib/strongswan/ipsec.secrets.inc' failed
May 16 11:16:56 localhost charon: 00[CFG] loaded IKE secret for %any
May 16 11:16:56 localhost charon: 00[DMN] loaded plugins: charon aes des
sha1 sha2 md5 random nonce x509 revocation constraints pubkey pkcs1
pkcs8 pgp dnskey pem fips-prf gmp xcbc cmac hmac attr kernel-netlink
resolve socket-default stroke updown xauth-generic
May 16 11:16:56 localhost charon: 00[JOB] spawning 16 worker threads
May 16 11:16:56 localhost charon: 10[CFG] received stroke: add
connection 'us-them'
May 16 11:16:56 localhost charon: 10[CFG] added configuration 'us-them'
May 16 11:16:57 localhost charon: 12[NET] received packet: from
192.168.22.22[500] to 10.1.1.1[500] (936 bytes)
May 16 11:16:57 localhost charon: 12[ENC] parsed ID_PROT request 0 [ SA
V V V V ]
May 16 11:16:57 localhost charon: 12[IKE] received NAT-T (RFC 3947)
vendor ID
May 16 11:16:57 localhost charon: 12[IKE] received
draft-ietf-ipsec-nat-t-ike-07 vendor ID
May 16 11:16:57 localhost charon: 12[IKE] received
draft-ietf-ipsec-nat-t-ike-03 vendor ID
May 16 11:16:57 localhost charon: 12[IKE] received
draft-ietf-ipsec-nat-t-ike-02\n vendor ID
May 16 11:16:57 localhost charon: 12[IKE] 192.168.22.22 is initiating a
Main Mode IKE_SA
May 16 11:16:57 localhost charon: 12[ENC] generating ID_PROT response 0
[ SA V V V ]
May 16 11:16:57 localhost charon: 12[NET] sending packet: from
10.1.1.1[500] to 192.168.22.22[500] (136 bytes)
May 16 11:16:57 localhost charon: 13[NET] received packet: from
192.168.22.22[500] to 10.1.1.1[500] (284 bytes)
May 16 11:16:57 localhost charon: 13[ENC] parsed ID_PROT request 0 [ KE
No V V V NAT-D NAT-D ]
May 16 11:16:57 localhost charon: 13[IKE] local host is behind NAT,
sending keep alives
May 16 11:16:57 localhost charon: 13[ENC] generating ID_PROT response 0
[ KE No NAT-D NAT-D ]
May 16 11:16:57 localhost charon: 13[NET] sending packet: from
10.1.1.1[500] to 192.168.22.22[500] (244 bytes)
May 16 11:16:57 localhost charon: 14[NET] received packet: from
192.168.22.22[4500] to 10.1.1.1[4500] (100 bytes)
May 16 11:16:57 localhost charon: 14[ENC] parsed ID_PROT request 0 [ ID
HASH N(INITIAL_CONTACT) ]
May 16 11:16:57 localhost charon: 14[CFG] looking for pre-shared key
peer configs matching 10.1.1.1...192.168.22.22[192.168.22.22]
May 16 11:16:57 localhost charon: 14[CFG] selected peer config "us-them"
May 16 11:16:57 localhost charon: 14[IKE] IKE_SA us-them[1] established
between 10.1.1.1[192.168.88.88]...192.168.22.22[192.168.22.22]
May 16 11:16:57 localhost charon: 14[IKE] scheduling reauthentication in
28547s
May 16 11:16:57 localhost charon: 14[IKE] maximum IKE_SA lifetime 28727s
May 16 11:16:57 localhost charon: 14[ENC] generating ID_PROT response 0
[ ID HASH ]
May 16 11:16:57 localhost charon: 14[NET] sending packet: from
10.1.1.1[4500] to 192.168.22.22[4500] (68 bytes)
May 16 11:16:57 localhost charon: 16[NET] received packet: from
192.168.22.22[4500] to 10.1.1.1[4500] (428 bytes)
May 16 11:16:57 localhost charon: 16[ENC] parsed QUICK_MODE request
3295287818 [ HASH SA No ID ID ]
May 16 11:16:57 localhost charon: 16[IKE] received 28800s lifetime,
configured 1200s
May 16 11:16:57 localhost charon: 16[IKE] received 4608000000 lifebytes,
configured 0
May 16 11:16:57 localhost charon: 16[ENC] generating QUICK_MODE response
3295287818 [ HASH SA No ID ID ]
May 16 11:16:57 localhost charon: 16[NET] sending packet: from
10.1.1.1[4500] to 192.168.22.22[4500] (188 bytes)
May 16 11:16:57 localhost charon: 02[NET] received packet: from
192.168.22.22[4500] to 10.1.1.1[4500] (428 bytes)
May 16 11:16:57 localhost charon: 02[ENC] parsed QUICK_MODE request
1762205300 [ HASH SA No ID ID ]
May 16 11:16:57 localhost charon: 02[IKE] CHILD_SA us-them{1}
established with SPIs c5e47bc9_i de34d76b_o and TS 10.1.1.0/24 ===
10.238.0.0/15
May 16 11:16:57 localhost charon: 01[NET] received packet: from
192.168.22.22[4500] to 10.1.1.1[4500] (60 bytes)
May 16 11:16:57 localhost charon: 01[ENC] parsed QUICK_MODE request
3295287818 [ HASH ]
May 16 11:16:57 localhost charon: 01[IKE] sa payload missing
<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
May 16 11:16:57 localhost charon: 01[ENC] generating INFORMATIONAL_V1
request 3951884773 [ HASH N(CRIT) ] <<<<<<<<<<<<
May 16 11:16:57 localhost charon: 01[NET] sending packet: from
10.1.1.1[4500] to 192.168.22.22[4500] (76 bytes)
May 16 11:16:58 localhost charon: 11[NET] received packet: from
192.168.22.22[4500] to 10.1.1.1[4500] (428 bytes)
May 16 11:16:58 localhost charon: 11[ENC] parsed QUICK_MODE request
1627657055 [ HASH SA No ID ID ]
May 16 11:16:58 localhost charon: 11[IKE] received 28800s lifetime,
configured 1200s
May 16 11:16:58 localhost charon: 11[IKE] received 4608000000 lifebytes,
configured 0
May 16 11:16:58 localhost charon: 11[IKE] detected rekeying of CHILD_SA
us-them{1}
May 16 11:16:58 localhost charon: 11[ENC] generating QUICK_MODE response
1627657055 [ HASH SA No ID ID ]
May 16 11:16:58 localhost charon: 11[NET] sending packet: from
10.1.1.1[4500] to 192.168.22.22[4500] (188 bytes)
May 16 11:16:58 localhost charon: 10[NET] received packet: from
192.168.22.22[4500] to 10.1.1.1[4500] (60 bytes)
May 16 11:16:58 localhost charon: 10[ENC] parsed QUICK_MODE request
1627657055 [ HASH ]
May 16 11:16:58 localhost charon: 10[IKE] CHILD_SA us-them{1}
established with SPIs c601b39d_i f425f56a_o and TS 10.1.1.0/24 ===
10.238.0.0/15
May 16 11:17:07 localhost charon: 14[NET] received packet: from
192.168.22.22[4500] to 10.1.1.1[4500] (428 bytes)
May 16 11:17:07 localhost charon: 14[ENC] parsed QUICK_MODE request
1762205300 [ HASH SA No ID ID ]
May 16 11:17:07 localhost charon: 14[ENC] received HASH payload does not
match <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
May 16 11:17:07 localhost charon: 14[IKE] integrity check failed
<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
May 16 11:17:07 localhost charon: 14[ENC] generating INFORMATIONAL_V1
request 1159462642 [ HASH N(INVAL_HASH) ] <<<<<<
May 16 11:17:07 localhost charon: 14[NET] sending packet: from
10.1.1.1[4500] to 192.168.22.22[4500] (68 bytes)
May 16 11:17:07 localhost charon: 14[IKE] QUICK_MODE request with
message ID 1762205300 processing failed <<<<<<<<<<<<
May 16 11:17:07 localhost charon: 15[NET] received packet: from
192.168.22.22[4500] to 10.1.1.1[4500] (84 bytes)
May 16 11:17:07 localhost charon: 15[ENC] parsed INFORMATIONAL_V1
request 3386190435 [ HASH D ]
May 16 11:17:07 localhost charon: 15[IKE] received DELETE for IKE_SA
us-them[1]
May 16 11:17:07 localhost charon: 15[IKE] deleting IKE_SA us-them[1]
between 10.1.1.1[192.168.88.88]...192.168.22.22[192.168.22.22]
May 16 11:17:07 localhost charon: 15[CHD] updown: iptables: Bad rule
(does a matching rule exist in that chain?).
May 16 11:17:07 localhost charon: 15[CHD] updown: iptables: Bad rule
(does a matching rule exist in that chain?).
May 16 11:17:07 localhost charon: 15[CHD] updown: iptables: Bad rule
(does a matching rule exist in that chain?).
May 16 11:17:07 localhost charon: 15[CHD] updown: iptables: Bad rule
(does a matching rule exist in that chain?).
May 16 11:17:19 localhost charon: 02[NET] received packet: from
192.168.22.22[4500] to 10.1.1.1[4500] (936 bytes)
May 16 11:17:19 localhost charon: 02[ENC] parsed ID_PROT request 0 [ SA
V V V V ]
May 16 11:17:19 localhost charon: 02[IKE] received NAT-T (RFC 3947)
vendor ID
May 16 11:17:19 localhost charon: 02[IKE] received
draft-ietf-ipsec-nat-t-ike-07 vendor ID
May 16 11:17:19 localhost charon: 02[IKE] received
draft-ietf-ipsec-nat-t-ike-03 vendor ID
May 16 11:17:19 localhost charon: 02[IKE] received
draft-ietf-ipsec-nat-t-ike-02\n vendor ID
May 16 11:17:19 localhost charon: 02[IKE] 192.168.22.22 is initiating a
Main Mode IKE_SA
May 16 11:17:19 localhost charon: 02[ENC] generating ID_PROT response 0
[ SA V V V ]
May 16 11:17:19 localhost charon: 02[NET] sending packet: from
10.1.1.1[4500] to 192.168.22.22[4500] (136 bytes)
May 16 11:17:19 localhost charon: 01[NET] received packet: from
192.168.22.22[4500] to 10.1.1.1[4500] (284 bytes)
May 16 11:17:19 localhost charon: 01[ENC] parsed ID_PROT request 0 [ KE
No V V V NAT-D NAT-D ]
May 16 11:17:19 localhost charon: 01[IKE] local host is behind NAT,
sending keep alives
May 16 11:17:19 localhost charon: 01[ENC] generating ID_PROT response 0
[ KE No NAT-D NAT-D ]
May 16 11:17:19 localhost charon: 01[NET] sending packet: from
10.1.1.1[4500] to 192.168.22.22[4500] (244 bytes)
May 16 11:17:19 localhost charon: 11[NET] received packet: from
192.168.22.22[4500] to 10.1.1.1[4500] (68 bytes)
May 16 11:17:19 localhost charon: 11[ENC] parsed ID_PROT request 0 [ ID
HASH ]
May 16 11:17:19 localhost charon: 11[CFG] looking for pre-shared key
peer configs matching 10.1.1.1...192.168.22.22[192.168.22.22]
May 16 11:17:19 localhost charon: 11[CFG] selected peer config "us-them"
May 16 11:17:19 localhost charon: 11[IKE] IKE_SA us-them[2] established
between 10.1.1.1[192.168.88.88]...192.168.22.22[192.168.22.22]
May 16 11:17:19 localhost charon: 11[IKE] scheduling reauthentication in
28490s
May 16 11:17:19 localhost charon: 11[IKE] maximum IKE_SA lifetime 28670s
May 16 11:17:19 localhost charon: 11[ENC] generating ID_PROT response 0
[ ID HASH ]
May 16 11:17:19 localhost charon: 11[NET] sending packet: from
10.1.1.1[4500] to 192.168.22.22[4500] (68 bytes)
May 16 11:17:39 localhost charon: 13[IKE] sending keep alive to
192.168.22.22[4500]
May 16 11:17:42 localhost charon: 14[NET] received packet: from
192.168.22.22[4500] to 10.1.1.1[4500] (92 bytes)
May 16 11:17:42 localhost charon: 14[ENC] parsed INFORMATIONAL_V1
request 4257417210 [ HASH N(DPD) ]
May 16 11:17:42 localhost charon: 14[ENC] generating INFORMATIONAL_V1
request 3714412322 [ HASH N(DPD_ACK) ]
May 16 11:17:42 localhost charon: 14[NET] sending packet: from
10.1.1.1[4500] to 192.168.22.22[4500] (92 bytes)
May 16 11:18:02 localhost charon: 02[IKE] sending keep alive to
192.168.22.22[4500]
May 16 11:18:04 localhost charon: 01[NET] received packet: from
192.168.22.22[4500] to 10.1.1.1[4500] (92 bytes)
May 16 11:18:04 localhost charon: 01[ENC] parsed INFORMATIONAL_V1
request 4255035676 [ HASH N(DPD) ]
May 16 11:18:04 localhost charon: 01[ENC] generating INFORMATIONAL_V1
request 3019338463 [ HASH N(DPD_ACK) ]
May 16 11:18:04 localhost charon: 01[NET] sending packet: from
10.1.1.1[4500] to 192.168.22.22[4500] (92 bytes)
May 16 11:18:21 localhost charon: 00[DMN] signal of type SIGINT
received. Shutting down
May 16 11:18:21 localhost charon: 00[IKE] deleting IKE_SA us-them[2]
between 10.1.1.1[192.168.88.88]...192.168.22.22[192.168.22.22]
May 16 11:18:21 localhost charon: 00[IKE] sending DELETE for IKE_SA
us-them[2]
May 16 11:18:21 localhost charon: 00[ENC] generating INFORMATIONAL_V1
request 1338694348 [ HASH D ]
May 16 11:18:21 localhost charon: 00[NET] sending packet: from
10.1.1.1[4500] to 192.168.22.22[4500] (84 bytes)
May 16 11:34:41 localhost charon: 00[DMN] Starting IKE charon daemon
(strongSwan 5.0.4, Linux 2.6.32-5-xen-amd64, x86_64)
May 16 11:34:41 localhost charon: 00[CFG] loading ca certificates from
'/usr/local/etc/ipsec.d/cacerts'
May 16 11:34:41 localhost charon: 00[CFG] loading aa certificates from
'/usr/local/etc/ipsec.d/aacerts'
May 16 11:34:41 localhost charon: 00[CFG] loading ocsp signer
certificates from '/usr/local/etc/ipsec.d/ocspcerts'
May 16 11:34:41 localhost charon: 00[CFG] loading attribute certificates
from '/usr/local/etc/ipsec.d/acerts'
May 16 11:34:41 localhost charon: 00[CFG] loading crls from
'/usr/local/etc/ipsec.d/crls'
May 16 11:34:41 localhost charon: 00[CFG] loading secrets from
'/usr/local/etc/ipsec.secrets'
May 16 11:34:41 localhost charon: 00[CFG] expanding file expression
'/var/lib/strongswan/ipsec.secrets.inc' failed
May 16 11:34:41 localhost charon: 00[CFG] loaded IKE secret for %any
May 16 11:34:41 localhost charon: 00[DMN] loaded plugins: charon aes des
sha1 sha2 md5 random nonce x509 revocation constraints pubkey pkcs1
pkcs8 pgp dnskey pem fips-prf gmp xcbc cmac hmac attr kernel-netlink
resolve socket-default stroke updown xauth-generic
May 16 11:34:41 localhost charon: 00[JOB] spawning 16 worker threads
May 16 11:34:41 localhost charon: 10[CFG] received stroke: add
connection 'us-them'
May 16 11:34:41 localhost charon: 10[CFG] added configuration 'us-them'
May 16 11:34:50 localhost charon: 12[NET] received packet: from
192.168.22.22[500] to 10.1.1.1[500] (936 bytes)
May 16 11:34:50 localhost charon: 12[ENC] parsed ID_PROT request 0 [ SA
V V V V ]
May 16 11:34:50 localhost charon: 12[IKE] received NAT-T (RFC 3947)
vendor ID
May 16 11:34:50 localhost charon: 12[IKE] received
draft-ietf-ipsec-nat-t-ike-07 vendor ID
May 16 11:34:50 localhost charon: 12[IKE] received
draft-ietf-ipsec-nat-t-ike-03 vendor ID
May 16 11:34:50 localhost charon: 12[IKE] received
draft-ietf-ipsec-nat-t-ike-02\n vendor ID
May 16 11:34:50 localhost charon: 12[IKE] 192.168.22.22 is initiating a
Main Mode IKE_SA
May 16 11:34:50 localhost charon: 12[ENC] generating ID_PROT response 0
[ SA V V V ]
May 16 11:34:50 localhost charon: 12[NET] sending packet: from
10.1.1.1[500] to 192.168.22.22[500] (136 bytes)
May 16 11:34:50 localhost charon: 13[NET] received packet: from
192.168.22.22[500] to 10.1.1.1[500] (284 bytes)
May 16 11:34:50 localhost charon: 13[ENC] parsed ID_PROT request 0 [ KE
No V V V NAT-D NAT-D ]
May 16 11:34:50 localhost charon: 13[IKE] local host is behind NAT,
sending keep alives
May 16 11:34:50 localhost charon: 13[ENC] generating ID_PROT response 0
[ KE No NAT-D NAT-D ]
May 16 11:34:50 localhost charon: 13[NET] sending packet: from
10.1.1.1[500] to 192.168.22.22[500] (244 bytes)
May 16 11:34:50 localhost charon: 14[NET] received packet: from
192.168.22.22[4500] to 10.1.1.1[4500] (100 bytes)
May 16 11:34:50 localhost charon: 14[ENC] parsed ID_PROT request 0 [ ID
HASH N(INITIAL_CONTACT) ]
May 16 11:34:50 localhost charon: 14[CFG] looking for pre-shared key
peer configs matching 10.1.1.1...192.168.22.22[192.168.22.22]
May 16 11:34:50 localhost charon: 14[CFG] selected peer config "us-them"
May 16 11:34:50 localhost charon: 14[IKE] IKE_SA us-them[1] established
between 10.1.1.1[192.168.88.88]...192.168.22.22[192.168.22.22]
May 16 11:34:50 localhost charon: 14[IKE] scheduling reauthentication in
28593s
May 16 11:34:50 localhost charon: 14[IKE] maximum IKE_SA lifetime 28773s
May 16 11:34:50 localhost charon: 14[ENC] generating ID_PROT response 0
[ ID HASH ]
May 16 11:34:50 localhost charon: 14[NET] sending packet: from
10.1.1.1[4500] to 192.168.22.22[4500] (68 bytes)
May 16 11:34:50 localhost charon: 16[NET] received packet: from
192.168.22.22[4500] to 10.1.1.1[4500] (428 bytes)
May 16 11:34:50 localhost charon: 16[ENC] parsed QUICK_MODE request
1028264643 [ HASH SA No ID ID ]
May 16 11:34:50 localhost charon: 16[IKE] received 28800s lifetime,
configured 1200s
May 16 11:34:50 localhost charon: 16[IKE] received 4608000000 lifebytes,
configured 0
May 16 11:34:50 localhost charon: 16[ENC] generating QUICK_MODE response
1028264643 [ HASH SA No ID ID ]
May 16 11:34:50 localhost charon: 16[NET] sending packet: from
10.1.1.1[4500] to 192.168.22.22[4500] (188 bytes)
May 16 11:34:50 localhost charon: 02[NET] received packet: from
192.168.22.22[4500] to 10.1.1.1[4500] (60 bytes)
May 16 11:34:50 localhost charon: 02[ENC] parsed QUICK_MODE request
1028264643 [ HASH ]
May 16 11:34:50 localhost charon: 02[IKE] CHILD_SA us-them{1}
established with SPIs c4b6e328_i 13519923_o and TS 10.1.1.0/24 ===
10.238.0.0/15
Again, thanks for any insight.
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.strongswan.org/pipermail/users/attachments/20130516/0c091143/attachment.html>
More information about the Users
mailing list