[strongSwan] MacOS: IKEv1 fails after wakeup

[Harald Dunkel]

Hi Tobias,

On 03/11/2016 10:03 AM, Tobias Brunner wrote:
> 
> Just as a side note, you might want to adjust your logger/syslog
> settings to avoid the duplicate log messages.
> 
This is debug mode. Usually I have

	charondebug="dmn 1, mgr 1, ike 1, chd 1, cfg 1, net 1"

Which setting would you recommend for this problem?

>> How comes that destroying the IKE_SA works, even though strongswan
>> on the left side has lost the IKE_SA (following your description)?
> 
> The client deletes the new SA (id 65) that it failed to establish, not
> the old one.  The log does only show the reconnection attempt so it's
> not clear whether the old SA was still there or not.  You configured
> dpdtimeout=500s, so how long was the client away? 

That was clearly more than 500s. The log file shows:

Mar 11 07:02:50 srvl047 charon: 21[MGR] checkin IKE_SA CiscoIPSec[62]
Mar 11 07:02:50 srvl047 charon: 26[MGR] IKE_SA CiscoIPSec[62] successfully checked out
Mar 11 07:02:50 srvl047 charon: 26[MGR] checkin IKE_SA CiscoIPSec[62]
Mar 11 07:02:50 srvl047 charon: 05[MGR] IKE_SA CiscoIPSec[62] successfully checked out
Mar 11 07:02:50 srvl047 charon: 05[IKE] IKE_SA CiscoIPSec[62] established between 10.0.0.17[gate1.example.com]...10.0.0.13[C=DE, O=example AG, OU=TI, CN=ppcm018.ws.example.com]
Mar 11 07:02:50 srvl047 charon: 05[IKE] IKE_SA CiscoIPSec[62] state change: CONNECTING => ESTABLISHED
Mar 11 07:02:50 srvl047 charon: 05[MGR] checkin IKE_SA CiscoIPSec[62]
Mar 11 07:02:50 srvl047 charon: 28[MGR] IKE_SA CiscoIPSec[62] successfully checked out
Mar 11 07:02:50 srvl047 charon: 28[MGR] checkin IKE_SA CiscoIPSec[62]
Mar 11 07:02:50 srvl047 charon: 30[MGR] IKE_SA CiscoIPSec[62] successfully checked out
Mar 11 07:02:50 srvl047 charon: 30[MGR] checkin IKE_SA CiscoIPSec[62]
Mar 11 07:02:50 srvl047 charon: 09[MGR] IKE_SA CiscoIPSec[62] successfully checked out
Mar 11 07:02:50 srvl047 charon: 09[MGR] checkin IKE_SA CiscoIPSec[62]
Mar 11 07:02:50 srvl047 charon: 08[MGR] IKE_SA CiscoIPSec[62] successfully checked out
Mar 11 07:02:50 srvl047 charon: 08[MGR] checkin IKE_SA CiscoIPSec[62]
Mar 11 07:02:54 srvl047 charon: 24[MGR] IKE_SA CiscoIPSec[62] successfully checked out
Mar 11 07:02:54 srvl047 charon: 24[MGR] checkin IKE_SA CiscoIPSec[62]
Mar 11 07:02:54 srvl047 charon: 23[MGR] IKE_SA CiscoIPSec[62] successfully checked out
Mar 11 07:02:54 srvl047 charon: 23[MGR] checkin IKE_SA CiscoIPSec[62]
Mar 11 07:02:54 srvl047 charon: 29[MGR] IKE_SA CiscoIPSec[62] successfully checked out
Mar 11 07:02:54 srvl047 charon: 29[MGR] checkin IKE_SA CiscoIPSec[62]
Mar 11 07:03:20 srvl047 charon: 24[MGR] IKE_SA CiscoIPSec[62] successfully checked out
Mar 11 07:03:20 srvl047 charon: 24[MGR] checkin IKE_SA CiscoIPSec[62]
Mar 11 07:04:30 srvl047 charon: 17[MGR] IKE_SA CiscoIPSec[62] successfully checked out
Mar 11 07:04:30 srvl047 charon: 17[MGR] checkin IKE_SA CiscoIPSec[62]
Mar 11 07:06:09 srvl047 charon: 21[MGR] IKE_SA CiscoIPSec[62] successfully checked out
Mar 11 07:06:09 srvl047 charon: 21[MGR] checkin IKE_SA CiscoIPSec[62]
Mar 11 07:06:38 srvl047 charon: 07[MGR] IKE_SA CiscoIPSec[62] successfully checked out
Mar 11 07:06:38 srvl047 charon: 07[MGR] checkin IKE_SA CiscoIPSec[62]
Mar 11 07:08:18 srvl047 charon: 16[MGR] IKE_SA CiscoIPSec[62] successfully checked out
Mar 11 07:08:18 srvl047 charon: 16[MGR] checkin IKE_SA CiscoIPSec[62]
Mar 11 07:09:58 srvl047 charon: 06[MGR] IKE_SA CiscoIPSec[62] successfully checked out
Mar 11 07:09:58 srvl047 charon: 06[MGR] checkin IKE_SA CiscoIPSec[62]
Mar 11 07:11:38 srvl047 charon: 23[MGR] IKE_SA CiscoIPSec[62] successfully checked out
Mar 11 07:11:38 srvl047 charon: 23[MGR] checkin IKE_SA CiscoIPSec[62]
Mar 11 07:13:18 srvl047 charon: 05[MGR] IKE_SA CiscoIPSec[62] successfully checked out
Mar 11 07:13:18 srvl047 charon: 05[MGR] checkin and destroy IKE_SA CiscoIPSec[62]
Mar 11 07:13:18 srvl047 charon: 05[IKE] IKE_SA CiscoIPSec[62] state change: ESTABLISHED => DESTROYING

> And do you see the
> DPDs and the deletion of the previous SA in the log?
> 

The DPD notifications are shown too.

Mar 11 07:06:39 srvl047 ipsec[11514]: 07[ENC] generating INFORMATIONAL_V1 request 565589809 [ HASH N(DPD) ]
Mar 11 07:06:39 srvl047 ipsec[11514]: 07[NET] sending packet: from 10.0.0.17[4500] to 10.0.0.13[64402] (92 bytes)

BTW, currently I have set dpdaction = none. It still fails to reconnect.

> One potential issue I hadn't considered so far is that while the client
> is asleep the mapping on the NAT router might time out (it probably does
> not send keepalives while asleep).  So when it reconnects it will do so
> from different source ports from the server's point of view.  Due to
> that the reauthentication detection will not recognize the new SA as
> reauthentication attempt and therefore not migrate the previous virtual
> IP.  So you'd end up in the same situation as before (i.e. the traffic
> selectors don't match and the CHILD_SA can't be established).  Try to
> compare the client's source ports to see if that's what happens here.
> 

You are right, the right side's port number is different before and
after wakeup. I have doubled the size of the states table on both
firewalls now. I also increased the inactivity timeout for udp state
information from 120 to 240 secs.

To avoid the NAT mess I also have IPv6 in place on both peers, but
by now the Mac refused to use it for IPsec (IKEv1). IKEv2 support
on MacOS appears to be premature yet.


Regards
Harri