[strongSwan] Android Client - issue on long running connection

Andre Valentin avalentin at marcant.net
Thu Sep 19 22:00:13 CEST 2013


Hi,

I really like the android strongswan app. It is small, battery-efficient 
and gives immediate VPN access after a connection problem (i.e. after a 
short coverage hole on the road..). I do not know any better app. But as 
always, there's a little problem. After some hours, or perhaps days, the 
tunnel is down. I receive these errors in the log:

09-19 09:11:24.950 I/charon  (12923): 08[IKE] giving up after 10 path probings
09-19 09:11:24.950 I/charon  (12923): 08[IKE] looking up interface for virtual IP 10.150.240.194 failed
09-19 09:11:24.950 I/charon  (12923): 08[IKE] looking up interface for virtual IP 2abc:123:123:8002:1::12 failed
09-19 09:11:24.950 I/charon  (12923): 08[IKE] restarting CHILD_SA android
09-19 09:11:24.950 I/charon  (12923): 08[IKE] initiating IKE_SA android[5] to X.Y.Z.65
09-19 09:11:27.575 D/AlarmManagerService( 2371): Kernel timezone updated to -120 minutes west of GMT
09-19 09:11:27.580 D/Tethering( 2371): MasterInitialState.processMessage what=3
09-19 09:11:27.840 I/charon  (12923): 08[ENC] generating IKE_SA_INIT request 0 [ SA KE No N(NATD_S_IP) N(NATD_D_IP) ]
09-19 09:11:27.845 I/charon  (12923): 08[NET] sending packet: from 192.168.203.96[49398] to X.Y.Z.65[4500] (648 bytes)
09-19 09:11:28.100 D/PicasaUploaderSyncManager(  619): active network: NetworkInfo: type: mobile[UMTS], state: CONNECTED/CONNECTED, reason: (unspecified), extra: web.vodafone.de, roaming: false, failover: false,
  isAvailable: true
09-19 09:11:28.205 D/GCM     ( 5657): GcmService start Intent { act=android.net.conn.CONNECTIVITY_CHANGE flg=0x8000010 cmp=com.google.android.gms/.gcm.GcmService (has extras) } android.net.conn.CONNECTIVITY_CHAN
GE
09-19 09:11:28.495 D/dalvikvm(27068): GC_EXPLICIT freed 274K, 49% free 5570K/10780K, paused 1ms+13ms, total 83ms
09-19 09:11:28.625 D/dalvikvm( 2371): GC_EXPLICIT freed 1075K, 27% free 22526K/30740K, paused 3ms+6ms, total 75ms
09-19 09:11:29.775 D/AlarmManagerService( 2371): Kernel timezone updated to -120 minutes west of GMT
09-19 09:11:29.845 I/charon  (12923): 14[IKE] retransmit 1 of request with message ID 0
09-19 09:11:29.845 I/charon  (12923): 14[NET] sending packet: from 192.168.203.96[49398] to X.Y.Z.65[4500] (648 bytes)
09-19 09:11:30.030 I/charon  (12923): 15[NET] received packet: from X.Y.Z.65[4500] to 10.27.3.195[49398] (465 bytes)
09-19 09:11:30.030 I/charon  (12923): 15[ENC] parsed IKE_SA_INIT response 0 [ SA KE No N(NATD_S_IP) N(NATD_D_IP) CERTREQ N(MULT_AUTH) ]
09-19 09:11:30.325 I/charon  (12923): 15[IKE] local host is behind NAT, sending keep alives
09-19 09:11:30.330 I/charon  (12923): 15[IKE] received cert request for "C=DE, O=test.loc, CN=test.loc"
09-19 09:11:30.330 I/charon  (12923): 15[IKE] sending cert request for "C=DE, CN=test.loc"
09-19 09:11:30.330 I/charon  (12923): 15[IKE] sending cert request for "C=DE, O=test.loc, CN=test.loc"
09-19 09:11:30.395 I/charon  (12923): 15[IKE] authentication of 'C=DE, O=test.loc, CN=avalentin-nexus' (myself) with RSA signature successful
09-19 09:11:30.395 I/charon  (12923): 15[IKE] sending end entity cert "C=DE, O=test.loc, CN=avalentin-nexus"
09-19 09:11:30.395 I/charon  (12923): 15[IKE] establishing CHILD_SA android{3}
09-19 09:11:30.395 I/charon  (12923): 15[ENC] generating IKE_AUTH request 1 [ IDi CERT N(INIT_CONTACT) CERTREQ AUTH CP(ADDR ADDR6 DNS DNS6) N(ESP_TFC_PAD_N) SA TSi TSr N(MOBIKE_SUP) N(ADD_4_ADDR) N(MULT_AUTH) N(
EAP_ONLY) ]
09-19 09:11:30.400 I/charon  (12923): 15[NET] sending packet: from 192.168.203.96[49398] to X.Y.Z.65[4500] (1900 bytes)
09-19 09:11:30.660 D/dalvikvm(27068): GC_EXPLICIT freed 242K, 49% free 5549K/10780K, paused 2ms+5ms, total 31ms
09-19 09:11:30.755 D/dalvikvm(32532): GC_EXPLICIT freed 553K, 72% free 3097K/10780K, paused 4ms+11ms, total 69ms
09-19 09:11:30.800 I/charon  (12923): 16[NET] received packet: from X.Y.Z.65[4500] to 10.27.3.195[49398] (1836 bytes)
09-19 09:11:30.800 I/charon  (12923): 16[ENC] parsed IKE_AUTH response 1 [ IDr CERT AUTH CP(ADDR ADDR6 DNS) SA TSi TSr N(MOBIKE_SUP) N(ADD_6_ADDR) ]
09-19 09:11:30.805 I/charon  (12923): 16[IKE] received end entity cert "C=DE, O=test.loc, CN=vpn.test.loc"
09-19 09:11:30.805 I/charon  (12923): 16[CFG]   using certificate "C=DE, O=test.loc, CN=vpn.test.loc"
09-19 09:11:30.805 I/charon  (12923): 16[CFG]   using trusted ca certificate "C=DE, O=test.loc, CN=test.loc"
09-19 09:11:30.805 I/charon  (12923): 16[CFG]   reached self-signed root ca with a path length of 0
09-19 09:11:30.805 I/charon  (12923): 16[IKE] authentication of 'vpn.test.loc' with RSA signature successful
09-19 09:11:30.805 I/charon  (12923): 16[IKE] IKE_SA android[5] established between 192.168.203.96[C=DE, O=test.loc, CN=avalentin-nexus]...X.Y.Z.65[vpn.test.loc]
09-19 09:11:30.805 I/charon  (12923): 16[IKE] scheduling rekeying in 35411s
09-19 09:11:30.805 I/charon  (12923): 16[IKE] maximum IKE_SA lifetime 36011s
09-19 09:11:30.805 I/charon  (12923): 16[IKE] looking up interface for virtual IP 10.150.240.194 failed
09-19 09:11:30.805 I/charon  (12923): 16[IKE] looking up interface for virtual IP 2abc:123:123:8002:1::12 failed
09-19 09:11:30.805 I/charon  (12923): 16[IKE] CHILD_SA android{3} established with SPIs 6413df23_i cda5eef7_o and TS 10.150.240.194/32 2abc:123:123:8002:1::12/128 === 10.150.240.0/23 2abc:123:123::/48
09-19 09:11:30.810 I/charon  (12923): 16[DMN] setting up TUN device for CHILD_SA android{3}
09-19 09:11:30.810 I/charon  (12923): 16[DMN] setting up TUN device failed, no virtual IP found
09-19 09:11:30.810 I/charon  (12923): 16[DMN] failed to setup TUN device
09-19 09:11:30.815 I/charon  (12923): 16[IKE] peer supports MOBIKE
09-19 09:11:30.830 W/System.err(12923): java.lang.IllegalStateException: Can not perform this action after onSaveInstanceState
09-19 09:11:30.830 W/System.err(12923):         at android.app.FragmentManagerImpl.checkStateLoss(FragmentManager.java:1318)
09-19 09:11:30.830 W/System.err(12923):         at android.app.FragmentManagerImpl.enqueueAction(FragmentManager.java:1329)
09-19 09:11:30.830 W/System.err(12923):         at android.app.BackStackRecord.commitInternal(BackStackRecord.java:595)
09-19 09:11:30.830 W/System.err(12923):         at android.app.BackStackRecord.commit(BackStackRecord.java:574)
09-19 09:11:30.830 W/System.err(12923):         at org.strongswan.android.ui.ImcStateFragment.updateView(ImcStateFragment.java:176)
09-19 09:11:30.830 W/System.err(12923):         at org.strongswan.android.ui.ImcStateFragment.stateChanged(ImcStateFragment.java:152)
09-19 09:11:30.830 W/System.err(12923):         at org.strongswan.android.logic.VpnStateService$1.run(VpnStateService.java:213)
09-19 09:11:30.830 W/System.err(12923):         at android.os.Handler.handleCallback(Handler.java:730)
09-19 09:11:30.830 W/System.err(12923):         at android.os.Handler.dispatchMessage(Handler.java:92)
09-19 09:11:30.830 W/System.err(12923):         at android.os.Looper.loop(Looper.java:137)
09-19 09:11:30.830 W/System.err(12923):         at android.app.ActivityThread.main(ActivityThread.java:5289)
09-19 09:11:30.830 W/System.err(12923):         at java.lang.reflect.Method.invokeNative(Native Method)
09-19 09:11:30.830 W/System.err(12923):         at java.lang.reflect.Method.invoke(Method.java:525)
09-19 09:11:30.830 W/System.err(12923):         at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:739)
09-19 09:11:30.830 W/System.err(12923):         at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:555)
09-19 09:11:30.830 W/System.err(12923):         at dalvik.system.NativeStart.main(Native Method)
09-19 09:11:30.840 I/charon  (12923): 00[IKE] deleting IKE_SA android[5] between 192.168.203.96[C=DE, O=test.loc, CN=avalentin-nexus]...X.Y.Z.65[vpn.test.loc]
09-19 09:11:30.840 I/charon  (12923): 00[IKE] sending DELETE for IKE_SA android[5]
09-19 09:11:30.845 I/charon  (12923): 00[ENC] generating INFORMATIONAL request 2 [ D ]
09-19 09:11:30.845 I/charon  (12923): 00[NET] sending packet: from 192.168.203.96[49398] to X.Y.Z.65[4500] (76 bytes)
09-19 09:11:30.845 W/System.err(12923): java.lang.IllegalStateException: Can not perform this action after onSaveInstanceState
09-19 09:11:30.845 W/System.err(12923):         at android.app.FragmentManagerImpl.checkStateLoss(FragmentManager.java:1318)
09-19 09:11:30.845 W/System.err(12923):         at android.app.FragmentManagerImpl.enqueueAction(FragmentManager.java:1329)
09-19 09:11:30.845 W/System.err(12923):         at android.app.BackStackRecord.commitInternal(BackStackRecord.java:595)
09-19 09:11:30.845 W/System.err(12923):         at android.app.BackStackRecord.commit(BackStackRecord.java:574)
09-19 09:11:30.845 W/System.err(12923):         at org.strongswan.android.ui.ImcStateFragment.updateView(ImcStateFragment.java:176)
09-19 09:11:30.845 W/System.err(12923):         at org.strongswan.android.ui.ImcStateFragment.stateChanged(ImcStateFragment.java:152)
09-19 09:11:30.850 W/System.err(12923):         at org.strongswan.android.logic.VpnStateService$1.run(VpnStateService.java:213)
09-19 09:11:30.850 W/System.err(12923):         at android.os.Handler.handleCallback(Handler.java:730)
09-19 09:11:30.850 W/System.err(12923):         at android.os.Handler.dispatchMessage(Handler.java:92)
09-19 09:11:30.850 W/System.err(12923):         at android.os.Looper.loop(Looper.java:137)
09-19 09:11:30.850 W/System.err(12923):         at android.app.ActivityThread.main(ActivityThread.java:5289)
09-19 09:11:30.850 W/System.err(12923):         at java.lang.reflect.Method.invokeNative(Native Method)
09-19 09:11:30.850 W/System.err(12923):         at java.lang.reflect.Method.invoke(Method.java:525)
09-19 09:11:30.850 W/System.err(12923):         at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:739)
09-19 09:11:30.850 W/System.err(12923):         at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:555)
09-19 09:11:30.850 W/System.err(12923):         at dalvik.system.NativeStart.main(Native Method)
09-19 09:11:30.860 W/Netd    ( 1952): No subsystem found in netlink event
09-19 09:11:30.860 D/NetlinkEvent( 1952): Unexpected netlink message. type=0x11
09-19 09:11:30.870 D/Vpn     ( 2371): setting state=DISCONNECTED, reason=interfaceRemoved
09-19 09:11:30.885 I/CharonVpnService(12923): charon stopped
09-19 09:11:30.885 W/System.err(12923): java.lang.IllegalStateException: Can not perform this action after onSaveInstanceState
09-19 09:11:30.885 W/System.err(12923):         at android.app.FragmentManagerImpl.checkStateLoss(FragmentManager.java:1318)
09-19 09:11:30.885 W/System.err(12923):         at android.app.FragmentManagerImpl.enqueueAction(FragmentManager.java:1329)
09-19 09:11:30.885 W/System.err(12923):         at android.app.BackStackRecord.commitInternal(BackStackRecord.java:595)
09-19 09:11:30.885 W/System.err(12923):         at android.app.BackStackRecord.commit(BackStackRecord.java:574)
09-19 09:11:30.885 W/System.err(12923):         at org.strongswan.android.ui.ImcStateFragment.updateView(ImcStateFragment.java:176)
09-19 09:11:30.885 W/System.err(12923):         at org.strongswan.android.ui.ImcStateFragment.stateChanged(ImcStateFragment.java:152)
09-19 09:11:30.885 W/System.err(12923):         at org.strongswan.android.logic.VpnStateService$1.run(VpnStateService.java:213)
09-19 09:11:30.885 W/System.err(12923):         at android.os.Handler.handleCallback(Handler.java:730)
09-19 09:11:30.885 W/System.err(12923):         at android.os.Handler.dispatchMessage(Handler.java:92)
09-19 09:11:30.885 W/System.err(12923):         at android.os.Looper.loop(Looper.java:137)
09-19 09:11:30.885 W/System.err(12923):         at android.app.ActivityThread.main(ActivityThread.java:5289)
09-19 09:11:30.885 W/System.err(12923):         at java.lang.reflect.Method.invokeNative(Native Method)
09-19 09:11:30.885 W/System.err(12923):         at java.lang.reflect.Method.invoke(Method.java:525)
09-19 09:11:30.885 W/System.err(12923):         at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:739)
09-19 09:11:30.885 W/System.err(12923):         at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:555)
09-19 09:11:30.885 W/System.err(12923):         at dalvik.system.NativeStart.main(Native Method)
09-19 09:11:31.050 W/NetworkManagementSocketTagger(32532): untagSocket(41) failed with errno -22



I think it has to do something with this:

09-19 09:11:30.810 I/charon  (12923): 16[DMN] failed to setup TUN device
09-19 09:11:30.815 I/charon  (12923): 16[IKE] peer supports MOBIKE
09-19 09:11:30.830 W/System.err(12923): java.lang.IllegalStateException: Can not perform this action after onSaveInstanceState

But I'm not sure, if the timestamps are accurate enough to tell if 
charon is the origin of the error, or perhaps the frontend 
[org.strongswan.android.ui.ImcStateFragment.updateView]
Please notice that I use cyanogenmod (based on 4.3). But I do not think 
it has to do with it.

Kind regards,

André

P.S.: I left some additional events in the log to indicate the enviroment.
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.strongswan.org/pipermail/users/attachments/20130919/3067741d/attachment.html>


More information about the Users mailing list