[strongSwan] rekeying issues connecting to cisco asa

[Justin Pryzby]

On Sat, Feb 03, 2018 at 10:56:50PM -0600, Justin Pryzby wrote:
> 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.

Find below logs showing same issue with strongswan-5.6.1 compiled locally.

At this point, c tunnel is working, but a and b tunnels are dead and I'll have
to manually restart it.

I wanted to add that we previously used an vyatta connection (strongswan 4.5.2
on a "virtual router" appliance) to this remote gateway with no issue.

I'm looking at this bug/patch:
https://wiki.strongswan.org/issues/1236
https://wiki.strongswan.org/projects/strongswan/repository/revisions/24ab8530e5e6ec209aff5292026b7d1e84d5ccab/diff

..which was added to address interoperability issue between strongswan-5.0.1
and strongswan-5.3.5.

Justin

Security Associations (2 up, 0 connecting):
 customer.ike[7]: ESTABLISHED 23 minutes ago, xxx.yy.190.17[xxx.yy.190.17]...xx.yyy.24.246[xx.yyy.24.246]
 customer.ike[7]: IKEv1 SPIs: 4801a63fa7482fe5_i f7512dd17e38ea33_r*, pre-shared key reauthentication in 23 hours
 customer.ike[7]: IKE proposal: 3DES_CBC/HMAC_SHA1_96/PRF_HMAC_SHA1/MODP_1024
   b.customer{48}:  INSTALLED, TUNNEL, reqid 4, ESP SPIs: cb5797ae_i a9f7a6d0_o
   b.customer{48}:  3DES_CBC/HMAC_SHA1_96, 24960 bytes_i (260 pkts, 1658s ago), 28008 bytes_o (292 pkts, 96s ago), rekeying in 2 hours
   b.customer{48}:   10.124.252.132/32 === 10.10.10.4/32
   a.customer{47}:  INSTALLED, TUNNEL, reqid 3, ESP SPIs: c000ad8a_i 32b5a400_o
   a.customer{47}:  3DES_CBC/HMAC_SHA1_96, 16983916 bytes_i (24344 pkts, 1658s ago), 1850872 bytes_o (18653 pkts, 29s ago), rekeying in 3 hours
   a.customer{47}:   10.124.252.132/32 === 10.5.1.109/32
   c.customer{46}:  REKEYED, TUNNEL, reqid 5, expires in 3 hours
   c.customer{46}:   10.124.252.132/32 === 10.20.1.7/32
   c.customer{54}:  INSTALLED, TUNNEL, reqid 5, ESP SPIs: c085bdf7_i 7f38081c_o
   c.customer{54}:  3DES_CBC/HMAC_SHA1_96, 10706608 bytes_i (13635 pkts, 17s ago), 1105386 bytes_o (11070 pkts, 84s ago), rekeying in 7 hours
   c.customer{54}:   10.124.252.132/32 === 10.20.1.7/32

2018-02-04 23:52:41 16[IKE] <customer.ike|3> sending DPD request
2018-02-04 23:52:41 16[ENC] <customer.ike|3> generating INFORMATIONAL_V1 request 1175993905 [ HASH N(DPD) ]
2018-02-04 23:52:41 16[NET] <customer.ike|3> sending packet: from xxx.yy.190.17[500] to xx.yyy.24.246[500] (92 bytes)
2018-02-04 23:52:43 10[NET] <7> received packet: from xx.yyy.24.246[500] to xxx.yy.190.17[500] (320 bytes)
2018-02-04 23:52:43 10[ENC] <7> parsed ID_PROT request 0 [ SA V V V V ]
2018-02-04 23:52:43 10[IKE] <7> received draft-ietf-ipsec-nat-t-ike-02\n vendor ID
2018-02-04 23:52:43 10[IKE] <7> received draft-ietf-ipsec-nat-t-ike-03 vendor ID
2018-02-04 23:52:43 10[IKE] <7> received NAT-T (RFC 3947) vendor ID
2018-02-04 23:52:43 10[IKE] <7> received FRAGMENTATION vendor ID
2018-02-04 23:52:43 10[IKE] <7> xx.yyy.24.246 is initiating a Main Mode IKE_SA
2018-02-04 23:52:43 10[ENC] <7> generating ID_PROT response 0 [ SA V V V ]
2018-02-04 23:52:43 10[NET] <7> sending packet: from xxx.yy.190.17[500] to xx.yyy.24.246[500] (136 bytes)
2018-02-04 23:52:43 04[NET] <7> received packet: from xx.yyy.24.246[500] to xxx.yy.190.17[500] (304 bytes)
2018-02-04 23:52:43 04[ENC] <7> parsed ID_PROT request 0 [ KE No V V V V NAT-D NAT-D ]
2018-02-04 23:52:43 04[IKE] <7> received Cisco Unity vendor ID
2018-02-04 23:52:43 04[IKE] <7> received XAuth vendor ID
2018-02-04 23:52:43 04[ENC] <7> received unknown vendor ID: bd:c6:01:22:a7:49:2f:e5:ee:4d:ff:4e:db:45:4e:6a
2018-02-04 23:52:43 04[ENC] <7> received unknown vendor ID: 1f:07:f7:0e:aa:65:14:d3:b0:fa:96:54:2a:50:01:00
2018-02-04 23:52:43 04[ENC] <7> generating ID_PROT response 0 [ KE No NAT-D NAT-D ]
2018-02-04 23:52:43 04[NET] <7> sending packet: from xxx.yy.190.17[500] to xx.yyy.24.246[500] (244 bytes)
2018-02-04 23:52:43 12[NET] <7> received packet: from xx.yyy.24.246[500] to xxx.yy.190.17[500] (84 bytes)
2018-02-04 23:52:43 12[ENC] <7> parsed ID_PROT request 0 [ ID HASH V ]
2018-02-04 23:52:43 12[IKE] <7> received DPD vendor ID
2018-02-04 23:52:43 12[CFG] <7> looking for pre-shared key peer configs matching xxx.yy.190.17...xx.yyy.24.246[xx.yyy.24.246]
2018-02-04 23:52:43 12[CFG] <7> selected peer config "customer.ike"
2018-02-04 23:52:43 12[IKE] <customer.ike|7> IKE_SA customer.ike[7] established between xxx.yy.190.17[xxx.yy.190.17]...xx.yyy.24.246[xx.yyy.24.246]
2018-02-04 23:52:43 12[IKE] <customer.ike|7> scheduling reauthentication in 85469s
2018-02-04 23:52:43 12[IKE] <customer.ike|7> maximum IKE_SA lifetime 86009s
2018-02-04 23:52:43 12[ENC] <customer.ike|7> generating ID_PROT response 0 [ ID HASH ]
2018-02-04 23:52:43 12[NET] <customer.ike|7> sending packet: from xxx.yy.190.17[500] to xx.yyy.24.246[500] (68 bytes)
2018-02-04 23:52:43 04[IKE] <customer.ike|3> detected reauth of existing IKE_SA, adopting 3 children and 0 virtual IPs
=> NOTE WELL
2018-02-04 23:52:43 07[NET] <customer.ike|7> received packet: from xx.yyy.24.246[500] to xxx.yy.190.17[500] (188 bytes)
2018-02-04 23:52:43 07[ENC] <customer.ike|7> parsed QUICK_MODE request 441777317 [ HASH SA No ID ID N(INITIAL_CONTACT) ]
2018-02-04 23:52:43 07[IKE] <customer.ike|7> received 4608000000 lifebytes, configured 0
2018-02-04 23:52:43 07[IKE] <customer.ike|7> detected rekeying of CHILD_SA c.customer{46}
2018-02-04 23:52:43 07[ENC] <customer.ike|7> generating QUICK_MODE response 441777317 [ HASH SA No ID ID ]
2018-02-04 23:52:43 07[NET] <customer.ike|7> sending packet: from xxx.yy.190.17[500] to xx.yyy.24.246[500] (180 bytes)
2018-02-04 23:52:43 12[NET] <customer.ike|7> received packet: from xx.yyy.24.246[500] to xxx.yy.190.17[500] (76 bytes)
2018-02-04 23:52:43 12[ENC] <customer.ike|7> parsed QUICK_MODE request 441777317 [ HASH ]
2018-02-04 23:52:43 12[IKE] <customer.ike|7> CHILD_SA c.customer{54} established with SPIs c085bdf7_i 7f38081c_o and TS 10.124.252.132/32 === 10.20.1.7/32

2018-02-04 23:52:53 11[IKE] <customer.ike|3> deleting IKE_SA customer.ike[3] between xxx.yy.190.17[xxx.yy.190.17]...xx.yyy.24.246[xx.yyy.24.246]
2018-02-04 23:52:53 11[IKE] <customer.ike|3> sending DELETE for IKE_SA customer.ike[3]
2018-02-04 23:52:53 11[ENC] <customer.ike|3> generating INFORMATIONAL_V1 request 2309986449 [ HASH D ]
2018-02-04 23:52:53 11[NET] <customer.ike|3> sending packet: from xxx.yy.190.17[500] to xx.yyy.24.246[500] (84 bytes)
2018-02-04 23:53:13 09[IKE] <customer.ike|7> sending DPD request
2018-02-04 23:53:13 09[ENC] <customer.ike|7> generating INFORMATIONAL_V1 request 1870966267 [ HASH N(DPD) ]
2018-02-04 23:53:13 09[NET] <customer.ike|7> sending packet: from xxx.yy.190.17[500] to xx.yyy.24.246[500] (92 bytes)
2018-02-04 23:53:13 10[NET] <customer.ike|7> received packet: from xx.yyy.24.246[500] to xxx.yy.190.17[500] (84 bytes)
2018-02-04 23:53:13 10[ENC] <customer.ike|7> parsed INFORMATIONAL_V1 request 2465482506 [ HASH N(DPD_ACK) ]
2018-02-04 23:53:30 16[NET] <customer.ike|7> received packet: from xx.yyy.24.246[500] to xxx.yy.190.17[500] (68 bytes)
2018-02-04 23:53:30 16[ENC] <customer.ike|7> parsed INFORMATIONAL_V1 request 2638448113 [ HASH N(INVAL_SPI) ]
2018-02-04 23:53:30 16[IKE] <customer.ike|7> received INVALID_SPI error notify

2018-02-04 23:54:02 07[IKE] <customer.ike|7> sending DPD request
2018-02-04 23:54:02 07[ENC] <customer.ike|7> generating INFORMATIONAL_V1 request 560050942 [ HASH N(DPD) ]
2018-02-04 23:54:02 07[NET] <customer.ike|7> sending packet: from xxx.yy.190.17[500] to xx.yyy.24.246[500] (92 bytes)
2018-02-04 23:54:02 04[NET] <customer.ike|7> received packet: from xx.yyy.24.246[500] to xxx.yy.190.17[500] (84 bytes)
2018-02-04 23:54:02 04[ENC] <customer.ike|7> parsed INFORMATIONAL_V1 request 1131049446 [ HASH N(DPD_ACK) ]
2018-02-04 23:54:30 04[NET] <customer.ike|7> received packet: from xx.yyy.24.246[500] to xxx.yy.190.17[500] (68 bytes)
2018-02-04 23:54:30 04[ENC] <customer.ike|7> parsed INFORMATIONAL_V1 request 2689804831 [ HASH N(INVAL_SPI) ]
2018-02-04 23:54:30 04[IKE] <customer.ike|7> received INVALID_SPI error notify

2018-02-04 23:55:01 14[IKE] <customer.ike|7> sending DPD request
2018-02-04 23:55:01 14[ENC] <customer.ike|7> generating INFORMATIONAL_V1 request 1203981677 [ HASH N(DPD) ]
2018-02-04 23:55:01 14[NET] <customer.ike|7> sending packet: from xxx.yy.190.17[500] to xx.yyy.24.246[500] (92 bytes)
2018-02-04 23:55:01 10[NET] <customer.ike|7> received packet: from xx.yyy.24.246[500] to xxx.yy.190.17[500] (84 bytes)
2018-02-04 23:55:01 10[ENC] <customer.ike|7> parsed INFORMATIONAL_V1 request 1282693781 [ HASH N(DPD_ACK) ]
2018-02-04 23:55:31 11[IKE] <customer.ike|7> sending DPD request
2018-02-04 23:55:31 11[ENC] <customer.ike|7> generating INFORMATIONAL_V1 request 3073496679 [ HASH N(DPD) ]
2018-02-04 23:55:31 11[NET] <customer.ike|7> sending packet: from xxx.yy.190.17[500] to xx.yyy.24.246[500] (92 bytes)
2018-02-04 23:55:31 14[NET] <customer.ike|7> received packet: from xx.yyy.24.246[500] to xxx.yy.190.17[500] (84 bytes)
2018-02-04 23:55:31 14[ENC] <customer.ike|7> parsed INFORMATIONAL_V1 request 724817690 [ HASH N(DPD_ACK) ]

2018-02-04 23:56:01 10[IKE] <customer.ike|7> sending DPD request
2018-02-04 23:56:01 10[ENC] <customer.ike|7> generating INFORMATIONAL_V1 request 2077870791 [ HASH N(DPD) ]
2018-02-04 23:56:01 10[NET] <customer.ike|7> sending packet: from xxx.yy.190.17[500] to xx.yyy.24.246[500] (92 bytes)
2018-02-04 23:56:01 06[NET] <customer.ike|7> received packet: from xx.yyy.24.246[500] to xxx.yy.190.17[500] (84 bytes)
2018-02-04 23:56:01 06[ENC] <customer.ike|7> parsed INFORMATIONAL_V1 request 1918014656 [ HASH N(DPD_ACK) ]
2018-02-04 23:56:31 12[IKE] <customer.ike|7> sending DPD request
2018-02-04 23:56:31 12[ENC] <customer.ike|7> generating INFORMATIONAL_V1 request 3354783639 [ HASH N(DPD) ]
2018-02-04 23:56:31 12[NET] <customer.ike|7> sending packet: from xxx.yy.190.17[500] to xx.yyy.24.246[500] (92 bytes)
2018-02-04 23:56:31 13[NET] <customer.ike|7> received packet: from xx.yyy.24.246[500] to xxx.yy.190.17[500] (84 bytes)
2018-02-04 23:56:31 13[ENC] <customer.ike|7> parsed INFORMATIONAL_V1 request 1724387852 [ HASH N(DPD_ACK) ]