Bug #193
Race condition between acquire jobs and Mobike update while switching WLANs
Description
Hi,
I installed and build strongSwan on my Android device and I have been
trying to switch my device between 2 WLANs requiring tunnel setup on WLAN_2
but not on WLAN_1. Following diagram explains my setup. Generally the
transition is smooth between the WLANs but occasionally, I encounter some
mobike related issues while switching from WLAN_1 to WLAN_2.
Android device: strongSwan client. Configuring the virtual IP in ipsec.conf
as 192.168.3.3
AP: WLAN_1: subnet 192.168.2.0/24: for which traffic needs to go in clear
text
AP: WLAN_2: subnet 192.168.3.0/24: for which traffic needs to be encrypted
strongSwan server: IP 192.168.1.154
Traffic: ICMP packets to server 192.168.1.154
To make it possible I used the following ipsec.conf at device:
config setup plutostart=no charondebug="knl 3, cfg 2, ike 2, chd 2, mgr 2, dmn 2" conn %default ikelifetime=60m keylife=20m keyexchange=ikev2 installpolicy=no reauth=no conn android left=%any leftid="abc" leftauth=eap leftsourceip=192.168.3.3 eap_identity=deepika right=192.168.1.154 rightid=192.168.1.154 rightauth=pubkey reqid=1 auto=route
I am manually adding security policies using:
ip xfrm policy add dir out src 192.168.3.3/32 dst 192.168.1.154/32 proto any priority 1000 tmpl src 192.168.3.3 dst 192.168.1.154 proto esp mode tunnel reqid 1 level required ip xfrm policy add dir in src 192.168.1.154/32 dst 192.168.3.3/32 proto any priority 1000 tmpl src 192.168.1.154 dst 192.168.3.3 proto esp mode tunnel reqid 1 level required ip xfrm policy add dir fwd src 192.168.1.154/32 dst 192.168.3.3/32 proto any priority 1000 tmpl src 192.168.1.154 dst 192.168.3.3 proto esp mode tunnel reqid 1 level required
Following are the logs of a successful transition from WLAN_1 to WLAN_2::
05-09 15:15:36.531: INFO/charon(16016): 03[KNL] 192.168.2.221 disappeared from wlan0 05-09 15:15:36.539: INFO/charon(16016): 03[KNL] fe80::a20b:baff:fec3:cf31 disappeared from wlan0 05-09 15:15:36.632: INFO/charon(16016): 14[IKE] old path is not available anymore, try to find another 05-09 15:15:36.632: INFO/charon(16016): 14[IKE] no route found to reach 192.168.1.154, MOBIKE update deferred 05-09 15:15:40.312: INFO/charon(16016): 03[KNL] 192.168.3.3 appeared on wlan0 05-09 15:15:40.406: INFO/charon(16016): 09[IKE] old path is not available anymore, try to find another 05-09 15:15:40.406: INFO/charon(16016): 09[IKE] *requesting address change using MOBIKE* 05-09 15:15:40.406: INFO/charon(16016): 09[ENC] generating INFORMATIONAL request 63 [ ] 05-09 15:15:40.414: INFO/charon(16016): 09[IKE] checking original path 192.168.3.3[4500] - 192.168.1.154[4500] 05-09 15:15:40.414: INFO/charon(16016): 09[NET] sending packet: from 192.168.3.3[4500] to 192.168.1.154[4500] 05-09 15:15:40.429: INFO/charon(16016): 13[NET] received packet: from 192.168.1.154[4500] to 192.168.3.3[4500] 05-09 15:15:40.429: INFO/charon(16016): 13[ENC] parsed INFORMATIONAL response 63 [ ] 05-09 15:15:40.460: INFO/charon(16016): 02[KNL] *creating acquire job for policy 192.168.3.3/32[1/8] === 192.168.1.154/32[1] with reqid {1}* 05-09 15:15:40.500: INFO/charon(16016): 03[KNL] fe80::a20b:baff:fec3:cf31 appeared on wlan0 05-09 15:15:40.601: INFO/charon(16016): 13[ENC] generating INFORMATIONAL request 64 [ N(UPD_SA_ADDR) N(NATD_S_IP) N(NATD_D_IP) N(COOKIE2) N(NO_ADD_ADDR) ] 05-09 15:15:40.601: INFO/charon(16016): 13[NET] sending packet: from 192.168.3.3[4500] to 192.168.1.154[4500] 05-09 15:15:40.617: INFO/charon(16016): 08[IKE] sending address list update using MOBIKE 05-09 15:15:40.750: INFO/charon(16016): 15[NET] received packet: from 192.168.1.154[4500] to 192.168.3.3[4500] 05-09 15:15:40.750: INFO/charon(16016): 15[ENC] parsed INFORMATIONAL response 64 [ N(NATD_S_IP) N(NATD_D_IP) N(COOKIE2) ] 05-09 15:15:40.750: INFO/charon(16016): 15[IKE] establishing CHILD_SA android{1} 05-09 15:15:40.765: INFO/charon(16016): 15[ENC] generating CREATE_CHILD_SA request 65 [ SA No TSi TSr ] 05-09 15:15:40.765: INFO/charon(16016): 15[NET] sending packet: from 192.168.3.3[4500] to 192.168.1.154[4500] 05-09 15:15:41.046: INFO/charon(16016): 14[NET] received packet: from 192.168.1.154[4500] to 192.168.3.3[4500] 05-09 15:15:41.046: INFO/charon(16016): 14[ENC] parsed CREATE_CHILD_SA response 65 [ SA No TSi TSr ] 05-09 15:15:41.085: INFO/charon(16016): 14[IKE] CHILD_SA android{1} established with SPIs cd7bd6f2_i c2f459fa_o and TS 192.168.3.3/32 === 192.168.1.154/32 05-09 15:15:41.085: INFO/charon(16016): 14[ENC] generating INFORMATIONAL request 66 [ N(NO_ADD_ADDR) ] 05-09 15:15:41.085: INFO/charon(16016): 14[NET] sending packet: from 192.168.3.3[4500] to 192.168.1.154[4500] 05-09 15:15:41.195: INFO/charon(16016): 10[NET] received packet: from 192.168.1.154[4500] to 192.168.3.3[4500] 05-09 15:15:41.195: INFO/charon(16016): 10[ENC] parsed INFORMATIONAL response 66 [ ]
Following are the logs of a unsuccessful transition from WLAN_1 to WLAN_2
(traffic halts in this case)::
05-09 15:16:55.843: INFO/charon(16016): 03[KNL] 192.168.2.221 disappeared from wlan0 05-09 15:16:55.851: INFO/charon(16016): 03[KNL] fe80::a20b:baff:fec3:cf31 disappeared from wlan0 05-09 15:16:55.945: INFO/charon(16016): 10[IKE] old path is not available anymore, try to find another 05-09 15:16:55.945: INFO/charon(16016): 10[IKE] no route found to reach 192.168.1.154, MOBIKE update deferred 05-09 15:16:56.187: INFO/charon(16016): 13[IKE] sending keep alive 05-09 15:16:56.187: INFO/charon(16016): 13[NET] sending packet: from 192.168.2.221[4500] to 192.168.1.154[4500] 05-09 15:16:56.187: INFO/charon(16016): 05[NET] error writing to socket: Invalid argument 05-09 15:16:59.429: INFO/charon(16016): 03[KNL] fe80::a20b:baff:fec3:cf31 appeared on wlan0 05-09 15:16:59.531: INFO/charon(16016): 07[IKE] old path is not available anymore, try to find another 05-09 15:16:59.531: INFO/charon(16016): 07[IKE] *no route found to reach 192.168.1.154, MOBIKE update deferred* 05-09 15:16:59.546: INFO/charon(16016): 03[KNL] 192.168.3.3 appeared on wlan0 05-09 15:16:59.609: INFO/charon(16016): 02[KNL] *creating acquire job for policy 192.168.3.3/32[1/8] === 192.168.1.154/32[1] with reqid {1}* 05-09 15:16:59.609: INFO/charon(16016): 08[IKE] establishing CHILD_SA android{1} 05-09 15:16:59.625: INFO/charon(16016): 08[ENC] generating CREATE_CHILD_SA request 70 [ SA No TSi TSr ] 05-09 15:16:59.632: INFO/charon(16016): 08[NET] sending packet: from 192.168.2.221[4500] to 192.168.1.154[4500] 05-09 15:16:59.632: INFO/charon(16016): 05[NET] error writing to socket: Invalid argument 05-09 15:16:59.640: INFO/charon(16016): 16[IKE] old path is not available anymore, try to find another 05-09 15:16:59.640: INFO/charon(16016): 16[IKE] requesting address change using MOBIKE 05-09 15:17:00.023: INFO/charon(16016): 15[IKE] old path is not available anymore, try to find another 05-09 15:17:00.023: INFO/charon(16016): 15[IKE] requesting address change using MOBIKE 05-09 15:17:03.640: INFO/charon(16016): 09[IKE] retransmit 1 of request with message ID 70 05-09 15:17:03.640: INFO/charon(16016): 09[NET] sending packet: from 192.168.2.221[4500] to 192.168.1.154[4500] 05-09 15:17:03.640: INFO/charon(16016): 05[NET] error writing to socket: Invalid argument 05-09 15:17:10.843: INFO/charon(16016): 10[IKE] retransmit 2 of request with message ID 70 05-09 15:17:10.843: INFO/charon(16016): 10[NET] sending packet: from 192.168.2.221[4500] to 192.168.1.154[4500] 05-09 15:17:10.843: INFO/charon(16016): 05[NET] error writing to socket: Invalid argument 05-09 15:17:23.804: INFO/charon(16016): 12[IKE] retransmit 3 of request with message ID 70 05-09 15:17:23.804: INFO/charon(16016): 12[NET] sending packet: from 192.168.2.221[4500] to 192.168.1.154[4500] 05-09 15:17:23.804: INFO/charon(16016): 05[NET] error writing to socket: Invalid argument 05-09 15:17:44.210: INFO/charon(16016): 08[IKE] sending keep alive 05-09 15:17:44.210: INFO/charon(16016): 08[NET] sending packet: from 192.168.2.221[4500] to 192.168.1.154[4500] 05-09 15:17:44.218: INFO/charon(16016): 05[NET] error writing to socket: Invalid argument 05-09 15:17:47.140: INFO/charon(16016): 14[IKE] retransmit 4 of request with message ID 70 05-09 15:17:47.140: INFO/charon(16016): 14[NET] sending packet: from 192.168.2.221[4500] to 192.168.1.154[4500] 05-09 15:17:47.140: INFO/charon(16016): 05[NET] error writing to socket: Invalid argument 05-09 15:18:07.234: INFO/charon(16016): 11[IKE] sending keep alive 05-09 15:18:07.234: INFO/charon(16016): 11[NET] sending packet: from 192.168.2.221[4500] to 192.168.1.154[4500] 05-09 15:18:07.234: INFO/charon(16016): 05[NET] error writing to socket: Invalid argument 05-09 15:18:27.250: INFO/charon(16016): 15[IKE] sending keep alive 05-09 15:18:27.250: INFO/charon(16016): 15[NET] sending packet: from 192.168.2.221[4500] to 192.168.1.154[4500] 05-09 15:18:27.257: INFO/charon(16016): 05[NET] error writing to socket: Invalid argument 05-09 15:18:29.125: INFO/charon(16016): 09[IKE] retransmit 5 of request with message ID 70 05-09 15:18:29.125: INFO/charon(16016): 09[NET] sending packet: from 192.168.2.221[4500] to 192.168.1.154[4500] 05-09 15:18:29.125: INFO/charon(16016): 05[NET] error writing to socket: Invalid argument 05-09 15:18:49.281: INFO/charon(16016): 13[IKE] sending keep alive 05-09 15:18:49.281: INFO/charon(16016): 13[NET] sending packet: from 192.168.2.221[4500] to 192.168.1.154[4500] 05-09 15:18:49.281: INFO/charon(16016): 05[NET] error writing to socket: Invalid argument 05-09 15:19:01.656: INFO/charon(16016): 02[KNL] creating rekey job for ESP CHILD_SA with SPI cf645ae7 and reqid {1} 05-09 15:19:09.289: INFO/charon(16016): 07[IKE] sending keep alive 05-09 15:19:09.289: INFO/charon(16016): 07[NET] sending packet: from 192.168.2.221[4500] to 192.168.1.154[4500] 05-09 15:19:09.289: INFO/charon(16016): 05[NET] error writing to socket: Invalid argument 05-09 15:19:29.304: INFO/charon(16016): 08[IKE] sending keep alive 05-09 15:19:29.304: INFO/charon(16016): 08[NET] sending packet: from 192.168.2.221[4500] to 192.168.1.154[4500] 05-09 15:19:29.304: INFO/charon(16016): 05[NET] error writing to socket: Invalid argument 05-09 15:19:30.757: INFO/charon(16016): 02[KNL] creating rekey job for ESP CHILD_SA with SPI c2f459fa and reqid {1} 05-09 15:19:44.632: INFO/charon(16016): 02[KNL] creating delete job for ESP CHILD_SA with SPI cae8bd23 and reqid {1} 05-09 15:19:44.718: INFO/charon(16016): 11[IKE] giving up after 5 retransmits 05-09 15:19:44.718: INFO/charon(16016): 11[KNL] received netlink error: No such process (3) 05-09 15:19:44.718: INFO/charon(16016): 11[KNL] unable to delete SAD entry with SPI cae8bd23 05-09 15:19:44.750: INFO/charon(16016): 03[KNL] 192.168.3.3 disappeared from wlan0
From the logs it can be inferred that in successful case, mobike
successfully updates the address before charon tries to acquire job for
policy to set up new SAs.However, in unsuccessful case address update
through mobike could not take place before charon tries to acquire job for
policy. It seems like some race condition is occurring.
I guess lowering the value of timer tv_usec of function "fire_roam_event" might avoid this condition upto an extent. I am not sure what other impacts it will further leave.
Thanks and regards,
Nitin
History
#1 Updated by Tobias Brunner over 8 years ago
- Description updated (diff)
- Status changed from New to Assigned
- Assignee changed from Nitin Verma to Tobias Brunner
Yes, this is an issue if the acquire event is handled before the address update (roam event). In that case the CREATE_CHILD_SA exchange is sent with the old endpoints and the roam event has no effect on that.
You could try to lower the time in fire_roam_event but that will probably not always work and could result in superfluous roam events (which is not really a problem, but still).
I guess the proper solution would be to somehow abort the current exchange (CREATE_CHILD_SA or whatever) in case of a roam event that results in the notion that the current path is not available anymore. Then do a MOBIKE update and if that worked continue with the previous exchange.