Project

General

Profile

Issue #3297

Android - Loss internet connection after a while

Added by Total Privacy 8 months ago. Updated 8 months ago.

Status:
Feedback
Priority:
Normal
Assignee:
-
Category:
android
Affected version:
dr|rc|master
Resolution:

Description

I am using the StrongSwan library in my application.
I am connected to the VPN for a few hours before losing internet connectivity

Below is the log:

Dec 16 01:38:37 09[NET] sending packet: from <IP> to <IP> (80 bytes)
Dec 16 01:39:38 16[NET] received packet: from <IP>to <IP> (80 bytes)
Dec 16 01:39:38 16[ENC] parsed INFORMATIONAL request 175 [ ]
Dec 16 01:39:38 16[ENC] generating INFORMATIONAL response 175 [ ]
Dec 16 01:39:38 16[NET] sending packet: from <IP> to <IP> (80 bytes)
Dec 16 01:40:08 10[NET] received packet: from <IP> to <IP> (80 bytes)
Dec 16 01:40:08 10[ENC] parsed INFORMATIONAL request 176 [ ]
Dec 16 01:40:08 10[ENC] generating INFORMATIONAL response 176 [ ]
Dec 16 01:40:08 10[NET] sending packet: from <IP> to <IP> (80 bytes)
Dec 16 01:40:39 14[NET] received packet: from <IP> to <IP> (80 bytes)
Dec 16 01:40:39 14[ENC] parsed INFORMATIONAL request 177 [ ]
Dec 16 01:40:39 14[ENC] generating INFORMATIONAL response 177 [ ]
Dec 16 01:40:39 14[NET] sending packet: from <IP> to <IP> (80 bytes)
Dec 16 01:40:45 11[IKE] sending address list update using MOBIKE
Dec 16 01:40:45 11[ENC] generating INFORMATIONAL request 4 [ N(NO_ADD_ADDR) ]
Dec 16 01:40:45 11[NET] sending packet: from <IP> to <IP> (80 bytes)
Dec 16 01:40:46 08[NET] received packet: from <IP> to <IP> (80 bytes)
Dec 16 01:40:46 08[ENC] parsed INFORMATIONAL response 4 [ ]
Dec 16 01:44:38 06[NET] received packet: from <IP> to <IP> (80 bytes)
Dec 16 01:44:38 06[ENC] parsed INFORMATIONAL request 178 [ ]
Dec 16 01:44:38 06[ENC] generating INFORMATIONAL response 178 [ ]
Dec 16 01:44:38 06[NET] sending packet: from <IP> to 168.245.223.11[4500] (80 bytes)
Dec 16 01:46:08 07[NET] received packet: from 168.245.223.11[4500] to 192.0.0.2[44457] (80 bytes)
Dec 16 01:46:08 07[ENC] parsed INFORMATIONAL request 179 [ ]
Dec 16 01:46:08 07[ENC] generating INFORMATIONAL response 179 [ ]
Dec 16 01:46:08 07[NET] sending packet: from 192.0.0.2[44457] to 168.245.223.11[4500] (80 bytes)
Dec 16 01:47:08 11[NET] received packet: from 168.245.223.11[4500] to 192.0.0.2[44457] (80 bytes)
Dec 16 01:47:08 11[ENC] parsed INFORMATIONAL request 180 [ ]
Dec 16 01:47:08 11[ENC] generating INFORMATIONAL response 180 [ ]
Dec 16 01:47:08 11[NET] sending packet: from 192.0.0.2[44457] to 168.245.223.11[4500] (80 bytes)
Dec 16 01:47:38 08[NET] received packet: from 168.245.223.11[4500] to 192.0.0.2[44457] (384 bytes)
Dec 16 01:47:38 08[ENC] parsed CREATE_CHILD_SA request 181 [ N(REKEY_SA) SA No TSi TSr ]
Dec 16 01:47:38 08[CFG] selected proposal: ESP:AES_GCM_16_128/NO_EXT_SEQ
Dec 16 01:47:38 08[IKE] inbound CHILD_SA android{3} established with SPIs f5c98a25_i 2269fac4_o and TS 100.65.1.6/32 2a0a:4b00:1ae:9c:6e00:a002:0:8c2/128 === 0.0.0.0/0 ::/0
Dec 16 01:47:38 08[ENC] generating CREATE_CHILD_SA response 181 [ N(ESP_TFC_PAD_N) SA No TSi TSr ]
Dec 16 01:47:38 08[NET] sending packet: from 192.0.0.2[44457] to 168.245.223.11[4500] (288 bytes)
Dec 16 01:47:38 12[NET] received packet: from 168.245.223.11[4500] to 192.0.0.2[44457] (80 bytes)
Dec 16 01:47:38 12[ENC] parsed INFORMATIONAL request 182 [ D ]
Dec 16 01:47:38 12[IKE] received DELETE for ESP CHILD_SA with SPI 20a646cd
Dec 16 01:47:38 12[IKE] closing CHILD_SA android{2} with SPIs 4d247a5b_i (564963 bytes) 20a646cd_o (276119 bytes) and TS 100.65.1.6/32 2a0a:4b00:1ae:9c:6e00:a002:0:8c2/128 === 0.0.0.0/0 ::/0
Dec 16 01:47:38 12[IKE] sending DELETE for ESP CHILD_SA with SPI 4d247a5b
Dec 16 01:47:38 12[IKE] CHILD_SA closed
Dec 16 01:47:38 12[IKE] outbound CHILD_SA android{3} established with SPIs f5c98a25_i 2269fac4_o and TS 100.65.1.6/32 2a0a:4b00:1ae:9c:6e00:a002:0:8c2/128 === 0.0.0.0/0 ::/0
Dec 16 01:47:38 12[ENC] generating INFORMATIONAL response 182 [ D ]
Dec 16 01:47:38 12[NET] sending packet: from <IP> to <IP> (80 bytes)
Dec 16 01:48:10 16[NET] received packet: from <IP> to <IP> (80 bytes)
Dec 16 01:48:10 16[ENC] parsed INFORMATIONAL request 183 [ ]
Dec 16 01:48:10 16[ENC] generating INFORMATIONAL response 183 [ ]
Dec 16 01:48:10 16[NET] sending packet: from <IP> to <IP> (80 bytes)
Dec 16 03:40:49 07[IKE] sending address list update using MOBIKE
Dec 16 03:40:49 07[ENC] generating INFORMATIONAL request 5 [ N(NO_ADD_ADDR) ]
Dec 16 03:40:49 07[NET] sending packet: from <IP> to <IP> (80 bytes)
Dec 16 03:40:51 08[IKE] retransmit 1 of request with message ID 5
Dec 16 03:40:51 08[NET] sending packet: from <IP> to <IP> (80 bytes)
Dec 16 03:40:54 12[IKE] retransmit 2 of request with message ID 5
Dec 16 03:40:54 12[NET] sending packet: from <IP> to <IP> (80 bytes)
Dec 16 03:40:58 09[IKE] retransmit 3 of request with message ID 5
Dec 16 03:40:58 09[NET] sending packet: from <IP> to <IP> (80 bytes)
Dec 16 03:41:04 10[IKE] giving up after 3 retransmits
Dec 16 03:41:04 10[DMN] setting up TUN device without DNS
Dec 16 03:41:04 10[DMN] successfully created TUN device without DNS
Dec 16 03:41:08 10[IKE] installing new virtual IP 100.6.....
Dec 16 03:41:08 10[IKE] installing new virtual IP 2a0a:4b00:1ae:....
Dec 16 03:41:08 10[IKE] restarting CHILD_SA android
Dec 16 03:41:08 10[IKE] initiating IKE_SA android[2] to 168.2....
Dec 16 03:41:08 10[ENC] generating IKE_SA_INIT request 0 [ SA KE No N(NATD_S_IP) N(NATD_D_IP) N(FRAG_SUP) N(HASH_ALG) N(REDIR_SUP) ]
Dec 16 03:41:08 10[NET] sending packet: from <IP> to <IP> (256 bytes)
Dec 16 03:41:09 18[LIB] resolving 'host_name' failed: No address associated with hostname
Dec 16 08:46:52 13[DMN] select on TUN device failed: Interrupted system call

- Why the gap between 01:48:10AM and 03:40:49AM? There is no sending and receiving packet activities?
- After 'resolving 'host_name' failed: No address associated with hostname' i see that the foreground service seem to crash and the system notification is still there.

History

#1 Updated by Tobias Brunner 8 months ago

  • Status changed from New to Feedback
  • Priority changed from High to Normal

- Why the gap between 01:48:10AM and 03:40:49AM? There is no sending and receiving packet activities?

No idea. Maybe your device was sleeping?

- After 'resolving 'host_name' failed: No address associated with hostname' i see that the foreground service seem to crash and the system notification is still there.

No idea, in particular if you modified the code etc.

#2 Updated by Total Privacy 8 months ago

Yes, the device was sleeping but shouldn't the foreground service still be sending and receiving packets? Is this the limitation? Connection loss for prolonged device sleeping?

I was able to reproduce this in the current StrongSwan android where i woke up without internet connectivity

Dec 17 04:22:51 12[NET] sending packet: from <IP_ADDR> to <IP_ADDR> (80 bytes)
Dec 17 04:23:09 16[NET] received packet: from <IP_ADDR>[4500] to <IP_ADDR>[57644] (384 bytes)
Dec 17 04:23:09 16[ENC] parsed CREATE_CHILD_SA request 308 [ N(REKEY_SA) SA No TSi TSr ]
Dec 17 04:23:09 16[IKE] inbound CHILD_SA android{5} established with SPIs <IP_ADDR> === 0.0.0.0/0 ::/0
Dec 17 04:23:09 16[ENC] generating CREATE_CHILD_SA response 308 [ N(ESP_TFC_PAD_N) SA No TSi TSr ]
Dec 17 04:23:09 16[NET] sending packet: from <IP_ADDR>57644] to <IP_ADDR>[4500] (288 bytes)
Dec 17 04:23:09 13[NET] received packet: from <IP_ADDR>[4500] to <IP_ADDR>[57644] (80 bytes)
Dec 17 04:23:09 13[ENC] parsed INFORMATIONAL request 309 [ D ]
Dec 17 04:23:09 13[IKE] received DELETE for ESP CHILD_SA with SPI 0ddc2133
Dec 17 04:23:09 13[IKE] closing CHILD_SA android{4} with SPIs <IP_ADDR>(68548 bytes) and TS <IP_ADDR>
Dec 17 04:23:09 13[IKE] sending DELETE for ESP CHILD_SA with SPI 7e417d73
Dec 17 04:23:09 13[IKE] CHILD_SA closed
Dec 17 04:23:09 13[IKE] outbound CHILD_SA android{5} established with SPIs <IP_ADDR> and TS <IP_ADDR>
Dec 17 04:23:09 13[ENC] generating INFORMATIONAL response 309 [ D ]
Dec 17 04:23:09 13[NET] sending packet: from<IP_ADDR>[57644] to <IP_ADDR>[4500] (80 bytes)
Dec 17 04:23:39 07[NET] received packet: from <IP_ADDR>4500] to <IP_ADDR>[57644] (80 bytes)
Dec 17 04:23:39 07[ENC] parsed INFORMATIONAL request 310 [ ]
Dec 17 04:23:39 07[ENC] generating INFORMATIONAL response 310 [ ]
Dec 17 04:23:39 07[NET] sending packet: from <IP_ADDR>[57644] to <IP_ADDR>[4500] (80 bytes)
Dec 17 04:24:40 10[NET] received packet: from <IP_ADDR>[4500] to <IP_ADDR>[57644] (80 bytes)
Dec 17 04:24:40 10[ENC] parsed INFORMATIONAL request 311 [ ]
Dec 17 04:24:40 10[ENC] generating INFORMATIONAL response 311 [ ]
Dec 17 04:24:40 10[NET] sending packet: from <IP_ADDR>[57644] to <IP_ADDR>[4500] (80 bytes)
Dec 17 04:25:10 09[NET] received packet: from <IP_ADDR>[4500] to <IP_ADDR>[57644] (80 bytes)
Dec 17 04:25:10 09[ENC] parsed INFORMATIONAL request 312 [ ]
Dec 17 04:25:10 09[ENC] generating INFORMATIONAL response 312 [ ]
Dec 17 04:25:10 09[NET] sending packet: from <IP_ADDR>[57644] to <IP_ADDR>[4500] (80 bytes)
Dec 17 04:25:41 11[NET] received packet: from <IP_ADDR>[4500] to <IP_ADDR>[57644] (80 bytes)
Dec 17 04:25:41 11[ENC] parsed INFORMATIONAL request 313 [ ]
Dec 17 04:25:41 11[ENC] generating INFORMATIONAL response 313 [ ]
Dec 17 04:25:41 11[NET] sending packet: from <IP_ADDR>[ to <IP_ADDR>[[4500] (80 bytes)
Dec 17 05:01:51 07[IKE] sending keep alive to <IP_ADDR>[4500]
Dec 17 05:35:59 10[IKE] sending keep alive to <IP_ADDR>[4500]
Dec 17 06:58:00 11[IKE] sending keep alive to <IP_ADDR>4500]
Dec 17 06:58:45 12[IKE] sending keep alive to <IP_ADDR>[4500]
Dec 17 07:41:34 12[IKE] sending keep alive to <IP_ADDR>4500]

Lost internet connectivity right around 7:30am when i woke up.

#3 Updated by Tobias Brunner 8 months ago

Yes, the device was sleeping but shouldn't the foreground service still be sending and receiving packets?

Probably depends on the device and system image (and perhaps even some system/app-specific settings).

I was able to reproduce this in the current StrongSwan android where i woke up without internet connectivity

That happens if the server uses DPDs with a short interval. If the client has no connectivity for a while (e.g. due to roaming or sleeping) the server might terminate the IKE_SA if it can't reach the client. That happens without the client knowing about it. So when the client has connectivity again, it still assumes the connection is up, until it learns that's not the case when it perhaps sends a MOBIKE update or rekeys the SAs. To avoid that it's recommended to use long DPD intervals (just to weed out really abandoned SAs), however, other exchanges initiated by the server e.g. rekeyings can also cause this effect so look out for that too.

Also available in: Atom PDF