[strongSwan] rekeying issues connecting to cisco asa

Sun Feb 4 05:56:50 CET 2018

I'm running strongswan-5.4.0-2.el6.x86_64
connecting to an cisco asa with ios 8.2(5).
I've also had issues with 5.6.1, compiled locally.

I consistently see odd disconnections and failures to reconnect, seemingly
related to rekeying.

uniqueids=no
...
keyingtries=%forever
keyexchange=ikev1
dpdaction=hold
auto=route
ikelifetime=86400s
lifetime=28800s
dpddelay=30s
dpdtimeout=120s

Currently:
Security Associations (2 up, 0 connecting):
 customer.ike[374]: ESTABLISHED 6 hours ago, xxx.yy.190.17[xxx.yy.190.17]...xx.yyy.24.246[xx.yyy.24.246]
 customer.ike[374]: IKEv1 SPIs: 2779959ad3114235_i* cd4bccae55b49464_r, pre-shared key reauthentication in 16 hours
 customer.ike[374]: IKE proposal: 3DES_CBC/HMAC_SHA1_96/PRF_HMAC_SHA1/MODP_1024
   c.customer{646}:  INSTALLED, TUNNEL, reqid 5, ESP SPIs: cdbccf48_i 7243c769_o
   c.customer{646}:  3DES_CBC/HMAC_SHA1_96, 188023768 bytes_i (259546 pkts, 598s ago), 22291336 bytes_o (219963 pkts, 4s ago), rekeying in 46 minutes
   c.customer{646}:   10.124.252.132/32 === 10.20.1.7/32

[pryzbyj at appserver ~]$ ping 10.20.1.7
PING 10.20.1.7 (10.20.1.7) 56(84) bytes of data.
^C
--- 10.20.1.7 ping statistics ---
3 packets transmitted, 0 received, 100% packet loss, time 2059ms

No problems before this time, and no INVAL_SPIs.

2018-02-03 22:22:06 08[NET] <customer.ike|374> received packet: from xx.yyy.24.246[500] to xxx.yy.190.17[500] (84 bytes)
2018-02-03 22:22:06 08[ENC] <customer.ike|374> parsed INFORMATIONAL_V1 request 694494406 [ HASH N(DPD) ]
2018-02-03 22:22:06 08[ENC] <customer.ike|374> generating INFORMATIONAL_V1 request 2758689726 [ HASH N(DPD_ACK) ]
2018-02-03 22:22:06 08[NET] <customer.ike|374> sending packet: from xxx.yy.190.17[500] to xx.yyy.24.246[500] (92 bytes)
2018-02-03 22:22:35 05[IKE] <customer.ike|374> sending DPD request
2018-02-03 22:22:35 05[ENC] <customer.ike|374> generating INFORMATIONAL_V1 request 232262974 [ HASH N(DPD) ]
2018-02-03 22:22:35 05[NET] <customer.ike|374> sending packet: from xxx.yy.190.17[500] to xx.yyy.24.246[500] (92 bytes)
2018-02-03 22:22:35 09[NET] <customer.ike|374> received packet: from xx.yyy.24.246[500] to xxx.yy.190.17[500] (84 bytes)
2018-02-03 22:22:35 09[ENC] <customer.ike|374> parsed INFORMATIONAL_V1 request 1644430845 [ HASH N(DPD_ACK) ]
2018-02-03 22:22:39 06[NET] <customer.ike|374> received packet: from xx.yyy.24.246[500] to xxx.yy.190.17[500] (68 bytes)
2018-02-03 22:22:39 06[ENC] <customer.ike|374> parsed INFORMATIONAL_V1 request 2086353609 [ HASH N(INVAL_SPI) ]
2018-02-03 22:22:39 06[IKE] <customer.ike|374> received INVALID_SPI error notify
2018-02-03 22:22:50 07[NET] <customer.ike|374> received packet: from xx.yyy.24.246[500] to xxx.yy.190.17[500] (68 bytes)
2018-02-03 22:22:50 07[ENC] <customer.ike|374> parsed INFORMATIONAL_V1 request 718871565 [ HASH N(INVAL_SPI) ]
2018-02-03 22:22:50 07[IKE] <customer.ike|374> received INVALID_SPI error notify
2018-02-03 22:23:02 13[NET] <customer.ike|374> received packet: from xx.yyy.24.246[500] to xxx.yy.190.17[500] (68 bytes)
2018-02-03 22:23:02 13[ENC] <customer.ike|374> parsed INFORMATIONAL_V1 request 4023539875 [ HASH N(INVAL_SPI) ]
2018-02-03 22:23:02 13[IKE] <customer.ike|374> received INVALID_SPI error notify
2018-02-03 22:23:25 11[NET] <customer.ike|374> received packet: from xx.yyy.24.246[500] to xxx.yy.190.17[500] (68 bytes)
2018-02-03 22:23:25 11[ENC] <customer.ike|374> parsed INFORMATIONAL_V1 request 855928773 [ HASH N(INVAL_SPI) ]
2018-02-03 22:23:25 11[IKE] <customer.ike|374> received INVALID_SPI error notify
2018-02-03 22:23:55 09[IKE] <customer.ike|374> sending DPD request
2018-02-03 22:23:55 09[ENC] <customer.ike|374> generating INFORMATIONAL_V1 request 213196210 [ HASH N(DPD) ]
2018-02-03 22:23:55 09[NET] <customer.ike|374> sending packet: from xxx.yy.190.17[500] to xx.yyy.24.246[500] (92 bytes)
2018-02-03 22:23:55 10[NET] <customer.ike|374> received packet: from xx.yyy.24.246[500] to xxx.yy.190.17[500] (84 bytes)
2018-02-03 22:23:55 10[ENC] <customer.ike|374> parsed INFORMATIONAL_V1 request 2080978438 [ HASH N(DPD_ACK) ]
2018-02-03 22:24:02 14[NET] <customer.ike|374> received packet: from xx.yyy.24.246[500] to xxx.yy.190.17[500] (68 bytes)
2018-02-03 22:24:02 14[ENC] <customer.ike|374> parsed INFORMATIONAL_V1 request 2978089029 [ HASH N(INVAL_SPI) ]
2018-02-03 22:24:02 14[IKE] <customer.ike|374> received INVALID_SPI error notify
2018-02-03 22:24:12 14[NET] <customer.ike|374> received packet: from xx.yyy.24.246[500] to xxx.yy.190.17[500] (68 bytes)
2018-02-03 22:24:12 14[ENC] <customer.ike|374> parsed INFORMATIONAL_V1 request 1907087874 [ HASH N(INVAL_SPI) ]
2018-02-03 22:24:12 14[IKE] <customer.ike|374> received INVALID_SPI error notify
2018-02-03 22:24:41 05[IKE] <customer.ike|374> sending DPD request
2018-02-03 22:24:41 05[ENC] <customer.ike|374> generating INFORMATIONAL_V1 request 1123907568 [ HASH N(DPD) ]
2018-02-03 22:24:41 05[NET] <customer.ike|374> sending packet: from xxx.yy.190.17[500] to xx.yyy.24.246[500] (92 bytes)
2018-02-03 22:24:41 08[NET] <customer.ike|374> received packet: from xx.yyy.24.246[500] to xxx.yy.190.17[500] (84 bytes)
2018-02-03 22:24:41 08[ENC] <customer.ike|374> parsed INFORMATIONAL_V1 request 3968440810 [ HASH N(DPD_ACK) ]

Shortly after I see rekeys of a.customer and b.customer..
but c.customer is still inacessible.

2018-02-03 22:24:59 08[NET] <customer.ike|374> received packet: from xx.yyy.24.246[500] to xxx.yy.190.17[500] (164 bytes)
2018-02-03 22:24:59 08[ENC] <customer.ike|374> parsed QUICK_MODE request 2825157240 [ HASH SA No ID ID ]
2018-02-03 22:24:59 08[IKE] <customer.ike|374> received 4608000000 lifebytes, configured 0
2018-02-03 22:24:59 08[IKE] <customer.ike|374> detected rekeying of CHILD_SA a.customer{647}
2018-02-03 22:24:59 08[ENC] <customer.ike|374> generating QUICK_MODE response 2825157240 [ HASH SA No ID ID ]
2018-02-03 22:24:59 08[NET] <customer.ike|374> sending packet: from xxx.yy.190.17[500] to xx.yyy.24.246[500] (180 bytes)
2018-02-03 22:24:59 06[NET] <customer.ike|374> received packet: from xx.yyy.24.246[500] to xxx.yy.190.17[500] (76 bytes)
2018-02-03 22:24:59 06[ENC] <customer.ike|374> parsed QUICK_MODE request 2825157240 [ HASH ]
2018-02-03 22:24:59 06[IKE] <customer.ike|374> CHILD_SA a.customer{658} established with SPIs c2998f96_i 080e0ad7_o and TS 10.124.252.132/32 === 10.5.1.109/32
2018-02-03 22:24:59 09[NET] <customer.ike|374> received packet: from xx.yyy.24.246[500] to xxx.yy.190.17[500] (164 bytes)
2018-02-03 22:24:59 09[ENC] <customer.ike|374> parsed QUICK_MODE request 2019525969 [ HASH SA No ID ID ]
2018-02-03 22:24:59 09[IKE] <customer.ike|374> received 4608000000 lifebytes, configured 0
2018-02-03 22:24:59 09[IKE] <customer.ike|374> detected rekeying of CHILD_SA b.customer{648}
2018-02-03 22:24:59 09[ENC] <customer.ike|374> generating QUICK_MODE response 2019525969 [ HASH SA No ID ID ]
2018-02-03 22:24:59 09[NET] <customer.ike|374> sending packet: from xxx.yy.190.17[500] to xx.yyy.24.246[500] (180 bytes)
2018-02-03 22:24:59 14[NET] <customer.ike|374> received packet: from xx.yyy.24.246[500] to xxx.yy.190.17[500] (76 bytes)
2018-02-03 22:24:59 14[ENC] <customer.ike|374> parsed QUICK_MODE request 2019525969 [ HASH ]
2018-02-03 22:24:59 14[IKE] <customer.ike|374> CHILD_SA b.customer{659} established with SPIs c2da3b0f_i 4b18190f_o and TS 10.124.252.132/32 === 10.10.10.4/32
2018-02-03 22:25:29 14[IKE] <customer.ike|374> sending DPD request
2018-02-03 22:25:29 14[ENC] <customer.ike|374> generating INFORMATIONAL_V1 request 2790165652 [ HASH N(DPD) ]
2018-02-03 22:25:29 14[NET] <customer.ike|374> sending packet: from xxx.yy.190.17[500] to xx.yyy.24.246[500] (92 bytes)
2018-02-03 22:25:29 09[NET] <customer.ike|374> received packet: from xx.yyy.24.246[500] to xxx.yy.190.17[500] (84 bytes)
2018-02-03 22:25:29 09[ENC] <customer.ike|374> parsed INFORMATIONAL_V1 request 3298781880 [ HASH N(DPD_ACK) ]
2018-02-03 22:25:29 05[NET] <customer.ike|374> received packet: from xx.yyy.24.246[500] to xxx.yy.190.17[500] (68 bytes)
2018-02-03 22:25:29 05[ENC] <customer.ike|374> parsed INFORMATIONAL_V1 request 3905431230 [ HASH D ]
2018-02-03 22:25:29 05[IKE] <customer.ike|374> received DELETE for ESP CHILD_SA with SPI 0875d30a
2018-02-03 22:25:29 05[IKE] <customer.ike|374> closing CHILD_SA a.customer{647} with SPIs c7878b47_i (25373198 bytes) 0875d30a_o (2710904 bytes) and TS 10.124.252.132/32 === 10.5.1.109/32
2018-02-03 22:25:29 08[NET] <customer.ike|374> received packet: from xx.yyy.24.246[500] to xxx.yy.190.17[500] (68 bytes)
2018-02-03 22:25:29 08[ENC] <customer.ike|374> parsed INFORMATIONAL_V1 request 1689538111 [ HASH D ]
2018-02-03 22:25:29 08[IKE] <customer.ike|374> received DELETE for ESP CHILD_SA with SPI 00b8fcc4
2018-02-03 22:25:29 08[IKE] <customer.ike|374> closing CHILD_SA b.customer{648} with SPIs cba06a81_i (40224 bytes) 00b8fcc4_o (40320 bytes) and TS 10.124.252.132/32 === 10.10.10.4/32
2018-02-03 22:25:45 12[NET] <customer.ike|374> received packet: from xx.yyy.24.246[500] to xxx.yy.190.17[500] (68 bytes)
2018-02-03 22:25:45 12[ENC] <customer.ike|374> parsed INFORMATIONAL_V1 request 444361537 [ HASH N(INVAL_SPI) ]
2018-02-03 22:25:45 12[IKE] <customer.ike|374> received INVALID_SPI error notify

Every time I ping I see:
parsed INFORMATIONAL_V1 request 63204947 [ HASH N(INVAL_SPI) ]
received INVALID_SPI error notify

Please let me know if a deubg log or log from 5.6 will be useful.

Thanks,
Justin