[strongSwan] Flaky B2B connection

Mon Jul 27 19:51:31 CEST 2015

Hi All,

Issue:

The tunnel is UP, but stops forwarding traffic over it.

I’m troubleshooting a B2B connection utilizing the following:

Endpoint A:
Strongswan U5.1.3/K2.6.32-431.23.3.el6.x86_64
Config:

conn business-sa-01
  auto=start
  also=business-default
  leftsubnet=10.90.209.0/24
  rightsubnet=10.23.34.0/28

conn business-default
  keyingtries=%forever
  rekey=no
  authby=psk
  left=10.90.200.41
  right=(publicip)
  compress=no
  aggressive=no
  keyexchange=ikev1
  mobike=no
  ikelifetime=3h
  lifetime=1h
  ike=3des-sha1-modp1024
  esp=3des-md5

Endpoint B:

Device: Cisco ASA 5512
Software Version:  9.4.1

What other information do you guys need to help me troubleshoot this issue?

==========================================================================================
LOG FILE OUTPUT
==========================================================================================

Jul 27 12:44:01 12[KNL] received a XFRM_MSG_EXPIRE
Jul 27 12:44:01 12[KNL] creating rekey job for ESP CHILD_SA with SPI 20bbcb7d and reqid {22}
Jul 27 12:44:01 06[NET] waiting for data on sockets
Jul 27 12:44:05 08[KNL] received a XFRM_MSG_EXPIRE
Jul 27 12:44:05 08[KNL] creating rekey job for ESP CHILD_SA with SPI 4ad63563 and reqid {7}
Jul 27 12:44:06 11[MGR] IKE_SA business-sa-01[92] successfully checked out
Jul 27 12:44:06 11[KNL] <business-sa-01|92> querying policy 10.90.209.0/24 === 10.23.34.0/28 out  (mark 0/0x00000000)
Jul 27 12:44:06 11[MGR] <business-sa-01|92> checkin IKE_SA business-sa-01[92]
Jul 27 12:44:06 11[MGR] <business-sa-01|92> check-in of IKE_SA successful.
Jul 27 12:44:18 12[MGR] IKE_SA business-sa-01[92] successfully checked out
Jul 27 12:44:18 12[KNL] <business-sa-01|92> querying policy 10.90.209.0/24 === 10.23.34.0/28 out  (mark 0/0x00000000)
Jul 27 12:44:18 12[MGR] <business-sa-01|92> checkin IKE_SA business-sa-01[92]
Jul 27 12:44:18 12[MGR] <business-sa-01|92> check-in of IKE_SA successful.
Jul 27 12:44:28 06[NET] received packet: from 11.222.33.444[4500] to 10.90.200.41[4500]
Jul 27 12:44:28 06[NET] waiting for data on sockets
Jul 27 12:44:28 14[MGR] IKE_SA business-sa-01[92] successfully checked out
Jul 27 12:44:28 14[NET] <business-sa-01|92> received packet: from 11.222.33.444[4500] to 10.90.200.41[4500] (84 bytes)
Jul 27 12:44:28 14[ENC] <business-sa-01|92> parsed INFORMATIONAL_V1 request 2660848954 [ HASH N(DPD) ]
Jul 27 12:44:28 14[IKE] <business-sa-01|92> queueing ISAKMP_DPD task
Jul 27 12:44:28 14[IKE] <business-sa-01|92> activating new tasks
Jul 27 12:44:28 14[IKE] <business-sa-01|92>   activating ISAKMP_DPD task
Jul 27 12:44:28 14[ENC] <business-sa-01|92> generating INFORMATIONAL_V1 request 2674446023 [ HASH N(DPD_ACK) ]
Jul 27 12:44:28 14[NET] <business-sa-01|92> sending packet: from 10.90.200.41[4500] to 11.222.33.444[4500] (92 bytes)
Jul 27 12:44:28 14[IKE] <business-sa-01|92> activating new tasks
Jul 27 12:44:28 14[IKE] <business-sa-01|92> nothing to initiate
Jul 27 12:44:28 14[MGR] <business-sa-01|92> checkin IKE_SA business-sa-01[92]
Jul 27 12:44:28 14[MGR] <business-sa-01|92> check-in of IKE_SA successful.
Jul 27 12:44:28 07[NET] sending packet: from 10.90.200.41[4500] to 11.222.33.444[4500]
Jul 27 12:44:36 11[MGR] IKE_SA business-sa-01[92] successfully checked out
Jul 27 12:44:36 11[KNL] <business-sa-01|92> querying policy 10.90.209.0/24 === 10.23.34.0/28 out  (mark 0/0x00000000)
Jul 27 12:44:36 11[MGR] <business-sa-01|92> checkin IKE_SA business-sa-01[92]
Jul 27 12:44:36 11[MGR] <business-sa-01|92> check-in of IKE_SA successful.
Jul 27 12:44:48 13[MGR] IKE_SA business-sa-01[92] successfully checked out
Jul 27 12:44:48 13[KNL] <business-sa-01|92> querying policy 10.90.209.0/24 === 10.23.34.0/28 out  (mark 0/0x00000000)
Jul 27 12:44:48 13[MGR] <business-sa-01|92> checkin IKE_SA business-sa-01[92]
Jul 27 12:44:48 13[MGR] <business-sa-01|92> check-in of IKE_SA successful.
Jul 27 12:44:58 06[NET] received packet: from 11.222.33.444[4500] to 10.90.200.41[4500]
Jul 27 12:44:58 06[NET] waiting for data on sockets
Jul 27 12:44:58 15[MGR] IKE_SA business-sa-01[92] successfully checked out
Jul 27 12:44:58 15[NET] <business-sa-01|92> received packet: from 11.222.33.444[4500] to 10.90.200.41[4500] (84 bytes)
Jul 27 12:44:58 15[ENC] <business-sa-01|92> parsed INFORMATIONAL_V1 request 1719707204 [ HASH N(DPD) ]
Jul 27 12:44:58 15[IKE] <business-sa-01|92> queueing ISAKMP_DPD task
Jul 27 12:44:58 15[IKE] <business-sa-01|92> activating new tasks
Jul 27 12:44:58 15[IKE] <business-sa-01|92>   activating ISAKMP_DPD task
Jul 27 12:44:58 15[ENC] <business-sa-01|92> generating INFORMATIONAL_V1 request 1861554224 [ HASH N(DPD_ACK) ]
Jul 27 12:44:58 15[NET] <business-sa-01|92> sending packet: from 10.90.200.41[4500] to 11.222.33.444[4500] (92 bytes)
Jul 27 12:44:58 15[IKE] <business-sa-01|92> activating new tasks
Jul 27 12:44:58 15[IKE] <business-sa-01|92> nothing to initiate
Jul 27 12:44:58 15[MGR] <business-sa-01|92> checkin IKE_SA business-sa-01[92]
Jul 27 12:44:58 15[MGR] <business-sa-01|92> check-in of IKE_SA successful.
Jul 27 12:44:58 07[NET] sending packet: from 10.90.200.41[4500] to 11.222.33.444[4500]
Jul 27 12:45:06 09[MGR] IKE_SA business-sa-01[92] successfully checked out
Jul 27 12:45:06 09[KNL] <business-sa-01|92> querying policy 10.90.209.0/24 === 10.23.34.0/28 out  (mark 0/0x00000000)
Jul 27 12:45:06 09[MGR] <business-sa-01|92> checkin IKE_SA business-sa-01[92]
Jul 27 12:45:06 09[MGR] <business-sa-01|92> check-in of IKE_SA successful.
Jul 27 12:45:18 02[MGR] IKE_SA business-sa-01[92] successfully checked out
Jul 27 12:45:18 02[KNL] <business-sa-01|92> querying policy 10.90.209.0/24 === 10.23.34.0/28 out  (mark 0/0x00000000)
Jul 27 12:45:18 02[MGR] <business-sa-01|92> checkin IKE_SA business-sa-01[92]
Jul 27 12:45:18 02[MGR] <business-sa-01|92> check-in of IKE_SA successful.
Jul 27 12:45:28 06[NET] received packet: from 11.222.33.444[4500] to 10.90.200.41[4500]
Jul 27 12:45:28 06[NET] waiting for data on sockets
Jul 27 12:45:28 16[MGR] IKE_SA business-sa-01[92] successfully checked out
Jul 27 12:45:28 16[NET] <business-sa-01|92> received packet: from 11.222.33.444[4500] to 10.90.200.41[4500] (84 bytes)
Jul 27 12:45:28 16[ENC] <business-sa-01|92> parsed INFORMATIONAL_V1 request 1587871339 [ HASH N(DPD) ]
Jul 27 12:45:28 16[IKE] <business-sa-01|92> queueing ISAKMP_DPD task
Jul 27 12:45:28 16[IKE] <business-sa-01|92> activating new tasks
Jul 27 12:45:28 16[IKE] <business-sa-01|92>   activating ISAKMP_DPD task
Jul 27 12:45:28 16[ENC] <business-sa-01|92> generating INFORMATIONAL_V1 request 1564690391 [ HASH N(DPD_ACK) ]
Jul 27 12:45:28 16[NET] <business-sa-01|92> sending packet: from 10.90.200.41[4500] to 11.222.33.444[4500] (92 bytes)
Jul 27 12:45:28 16[IKE] <business-sa-01|92> activating new tasks
Jul 27 12:45:28 16[IKE] <business-sa-01|92> nothing to initiate
Jul 27 12:45:28 16[MGR] <business-sa-01|92> checkin IKE_SA business-sa-01[92]
Jul 27 12:45:28 16[MGR] <business-sa-01|92> check-in of IKE_SA successful.
Jul 27 12:45:28 07[NET] sending packet: from 10.90.200.41[4500] to 11.222.33.444[4500]
Jul 27 12:45:36 15[MGR] IKE_SA business-sa-01[92] successfully checked out
Jul 27 12:45:36 15[KNL] <business-sa-01|92> querying policy 10.90.209.0/24 === 10.23.34.0/28 out  (mark 0/0x00000000)
Jul 27 12:45:36 15[MGR] <business-sa-01|92> checkin IKE_SA business-sa-01[92]
Jul 27 12:45:36 15[MGR] <business-sa-01|92> check-in of IKE_SA successful.
Jul 27 12:45:45 06[NET] received packet: from 11.222.33.444[4500] to 10.90.200.41[4500]
Jul 27 12:45:45 06[NET] waiting for data on sockets
Jul 27 12:45:45 11[MGR] created IKE_SA (unnamed)[119]
Jul 27 12:45:45 11[NET] <119> received packet: from 11.222.33.444[4500] to 10.90.200.41[4500] (128 bytes)
Jul 27 12:45:45 11[ENC] <119> parsed ID_PROT request 0 [ SA V V ]
Jul 27 12:45:45 11[CFG] <119> looking for an ike config for 10.90.200.41...11.222.33.444
Jul 27 12:45:45 11[CFG] <119>   candidate: 10.90.200.41...11.222.33.444, prio 3100
Jul 27 12:45:45 11[CFG] <119> found matching ike config: 10.90.200.41...11.222.33.444 with prio 3100
Jul 27 12:45:45 11[IKE] <119> received NAT-T (RFC 3947) vendor ID
Jul 27 12:45:45 11[IKE] <119> received FRAGMENTATION vendor ID
Jul 27 12:45:45 11[IKE] <119> 11.222.33.444 is initiating a Main Mode IKE_SA
Jul 27 12:45:45 11[IKE] <119> IKE_SA (unnamed)[119] state change: CREATED => CONNECTING
Jul 27 12:45:45 11[CFG] <119> selecting proposal:
Jul 27 12:45:45 11[CFG] <119>   proposal matches
Jul 27 12:45:45 11[CFG] <119> received proposals: IKE:3DES_CBC/HMAC_SHA1_96/PRF_HMAC_SHA1/MODP_1024
Jul 27 12:45:45 11[CFG] <119> configured proposals: IKE:3DES_CBC/HMAC_SHA1_96/PRF_HMAC_SHA1/MODP_1024, IKE:3DES_CBC/AES_CBC_128/AES_CBC_192/AES_CBC_256/HMAC_MD5_96/HMAC_SHA1_96/AES_XCBC_96/AES_CMAC_96/HMAC_SHA2_256_128/HMAC_SHA2_384_192/HMAC_SHA2_512_256/PRF_HMAC_MD5/PRF_HMAC_SHA1/PRF_AES128_XCBC/PRF_HMAC_SHA2_256/PRF_HMAC_SHA2_384/PRF_HMAC_SHA2_512/PRF_AES128_CMAC/MODP_1024/MODP_1536/MODP_2048/MODP_3072/MODP_4096/MODP_8192/MODP_1024_160/MODP_2048_224/MODP_2048_256
Jul 27 12:45:45 11[CFG] <119> selected proposal: IKE:3DES_CBC/HMAC_SHA1_96/PRF_HMAC_SHA1/MODP_1024
Jul 27 12:45:45 11[IKE] <119> sending XAuth vendor ID
Jul 27 12:45:45 11[IKE] <119> sending DPD vendor ID
Jul 27 12:45:45 11[IKE] <119> sending NAT-T (RFC 3947) vendor ID
Jul 27 12:45:45 11[ENC] <119> generating ID_PROT response 0 [ SA V V V ]
Jul 27 12:45:45 11[NET] <119> sending packet: from 10.90.200.41[4500] to 11.222.33.444[4500] (136 bytes)
Jul 27 12:45:45 11[MGR] <119> checkin IKE_SA (unnamed)[119]
Jul 27 12:45:45 11[MGR] <119> check-in of IKE_SA successful.
Jul 27 12:45:45 07[NET] sending packet: from 10.90.200.41[4500] to 11.222.33.444[4500]
Jul 27 12:45:45 06[NET] received packet: from 11.222.33.444[4500] to 10.90.200.41[4500]
Jul 27 12:45:45 06[NET] waiting for data on sockets
Jul 27 12:45:45 02[MGR] IKE_SA (unnamed)[119] successfully checked out
Jul 27 12:45:45 02[NET] <119> received packet: from 11.222.33.444[4500] to 10.90.200.41[4500] (304 bytes)
Jul 27 12:45:45 02[ENC] <119> parsed ID_PROT request 0 [ KE No V V V V NAT-D NAT-D ]
Jul 27 12:45:45 02[IKE] <119> received Cisco Unity vendor ID
Jul 27 12:45:45 02[IKE] <119> received XAuth vendor ID
Jul 27 12:45:45 02[ENC] <119> received unknown vendor ID: 99:58:82:25:25:50:c9:85:fc:7c:da:2a:48:bb:9e:7b
Jul 27 12:45:45 02[ENC] <119> received unknown vendor ID: 1f:07:f7:0e:aa:65:14:d3:b0:fa:96:54:2a:50:01:00
Jul 27 12:45:45 02[LIB] <119> size of DH secret exponent: 1023 bits
Jul 27 12:45:45 02[IKE] <119> local host is behind NAT, sending keep alives
Jul 27 12:45:45 02[ENC] <119> generating ID_PROT response 0 [ KE No NAT-D NAT-D ]
Jul 27 12:45:45 02[NET] <119> sending packet: from 10.90.200.41[4500] to 11.222.33.444[4500] (244 bytes)
Jul 27 12:45:45 07[NET] sending packet: from 10.90.200.41[4500] to 11.222.33.444[4500]
Jul 27 12:45:45 02[MGR] <119> checkin IKE_SA (unnamed)[119]
Jul 27 12:45:45 02[MGR] <119> check-in of IKE_SA successful.
Jul 27 12:45:45 06[NET] received packet: from 11.222.33.444[4500] to 10.90.200.41[4500]
Jul 27 12:45:45 06[NET] waiting for data on sockets
Jul 27 12:45:45 01[MGR] IKE_SA (unnamed)[119] successfully checked out
Jul 27 12:45:45 01[NET] <119> received packet: from 11.222.33.444[4500] to 10.90.200.41[4500] (84 bytes)
Jul 27 12:45:45 01[ENC] <119> parsed ID_PROT request 0 [ ID HASH V ]
Jul 27 12:45:45 01[IKE] <119> received DPD vendor ID
Jul 27 12:45:45 01[CFG] <119> looking for pre-shared key peer configs matching 10.90.200.41...11.222.33.444[11.222.33.444]
Jul 27 12:45:45 01[CFG] <119>   candidate "business-sa-01", match: 1/20/3100 (me/other/ike)
Jul 27 12:45:45 01[CFG] <119> selected peer config "business-sa-01"
Jul 27 12:45:45 01[IKE] <business-sa-01|119> IKE_SA business-sa-01[119] established between 10.90.200.41[10.90.200.41]...11.222.33.444[11.222.33.444]
Jul 27 12:45:45 01[IKE] <business-sa-01|119> IKE_SA business-sa-01[119] state change: CONNECTING => ESTABLISHED
Jul 27 12:45:45 01[ENC] <business-sa-01|119> generating ID_PROT response 0 [ ID HASH ]
Jul 27 12:45:45 01[NET] <business-sa-01|119> sending packet: from 10.90.200.41[4500] to 11.222.33.444[4500] (68 bytes)
Jul 27 12:45:45 01[MGR] <business-sa-01|119> checkin IKE_SA business-sa-01[119]
Jul 27 12:45:45 01[MGR] <business-sa-01|119> check-in of IKE_SA successful.
Jul 27 12:45:45 01[MGR] IKE_SA business-sa-01[119] successfully checked out
Jul 27 12:45:45 01[MGR] <business-sa-01|119> checkin IKE_SA business-sa-01[119]
Jul 27 12:45:45 01[MGR] <business-sa-01|119> check-in of IKE_SA successful.
Jul 27 12:45:45 01[MGR] IKE_SA business-sa-01[92] successfully checked out
Jul 27 12:45:45 01[IKE] <business-sa-01|92> detected reauth of existing IKE_SA, adopting 1 children
Jul 27 12:45:45 01[IKE] <business-sa-01|92> IKE_SA business-sa-01[92] state change: ESTABLISHED => DELETING
Jul 27 12:45:45 01[MGR] <business-sa-01|92> checkin and destroy IKE_SA business-sa-01[92]
Jul 27 12:45:45 01[IKE] <business-sa-01|92> IKE_SA business-sa-01[92] state change: DELETING => DESTROYING
Jul 27 12:45:45 01[MGR] check-in and destroy of IKE_SA successful
Jul 27 12:45:45 01[MGR] IKE_SA business-sa-01[119] successfully checked out
Jul 27 12:45:45 01[MGR] <business-sa-01|119> checkin IKE_SA business-sa-01[119]
Jul 27 12:45:45 01[MGR] <business-sa-01|119> check-in of IKE_SA successful.
Jul 27 12:45:45 07[NET] sending packet: from 10.90.200.41[4500] to 11.222.33.444[4500]
Jul 27 12:45:58 06[NET] received packet: from 11.222.33.444[4500] to 10.90.200.41[4500]
Jul 27 12:45:58 06[NET] waiting for data on sockets

_____________________________________________________________ This e-mail transmission contains information that is confidential and may be privileged. It is intended only for the addressee(s) named above. If you receive this e-mail in error, please do not read, copy or disseminate it in any manner. If you are not the intended recipient, any disclosure, copying, distribution or use of the contents of this information is prohibited. Please reply to the message immediately by informing the sender that the message was misdirected. After replying, please erase it from your computer system. Your assistance in correcting this error is appreciated.