[Swan] IKEv2 connection from Android drops after a few minutes
Paul Wouters
paul at nohats.ca
Thu Mar 5 18:44:22 UTC 2020
On Wed, 4 Mar 2020, Beat Zahnd wrote:
> The client is the strongswan app. Initiating a connection works well and no problem is observed as long as the mobile phone is not put to sleep. After a few minutes on sleep no traffic goes trough anymore and the connection needs to be restarted first.
>
> But I still see UDP-encap ESP traffic on my server network interface...
Did the NAT port change? Likely the client is not using MOBIKE to send
an UPDATE_ADDRESS request to the server to share the information that
the NAT router has changed its ports mapping.
Paul
>
> I configured my VPN server on Debian as per the wiki on https://libreswan.org/wiki/VPN_server_for_remote_clients_using_IKEv2
>
> config setup # from Debian default ipsec.conf
> virtual_private=%v4:10.0.0.0/8,%v4:192.168.0.0/16,%v4:172.16.0.0/12,%v4:25.0.0.0/8,%v4:100.64.0.0/10,%v6:fd00::/8,%v6:fe80::/10,%v4:!10.76.1.0/24
> interfaces="%defaultroute"
>
> conn ikev2-cp
> left=%defaultroute
> leftcert="test VPN"
> leftid=@vpn.hidden.ch
> leftsendcert=always
> leftsubnet=0.0.0.0/0
> leftrsasigkey=%cert
> right=%any
> rightaddresspool=192.168.1.100-192.168.1.200
> rightca=%same
> rightrsasigkey=%cert
> modecfgdns=10.76.1.1
> narrowing=yes
> dpddelay=12h
> dpdtimeout=13h
> dpdaction=clear
> auto=add
> ikev2=insist
> rekey=no
> fragmentation=yes
>
> As per some strongswan tickets I put a long dpddelay. But without success.
>
> In the log on the server nothing appears after the connection is started:
>
> Mar 4 21:59:04 core pluto[25972]: "ikev2-cp"[28] 178.197.x.x #29: deleting other state #29 (STATE_CHILDSA_DEL) and NOT sending notification
> Mar 4 21:59:04 core pluto[25972]: "ikev2-cp"[28] 178.197.x.x #28: deleting state (STATE_IKESA_DEL) and NOT sending notification
> Mar 4 21:59:04 core pluto[25972]: packet from 178.197.x.x:21081: deleting connection "ikev2-cp"[28] 178.197.x.x instance with peer 178.197.x.x {isakmp=#0/ipsec=#0}
> Mar 4 21:59:04 core pluto[25972]: packet from 178.197.x.x:36649: constructed local IKE proposals for ikev2-cp (IKE SA responder matching remote proposals): 1:IKE:ENCR=AES_GCM_C_256;PRF=HMAC_SHA2_512,HMAC_SHA2_256,HMAC_SHA1;INTEG=NONE;DH=MODP2048,MODP3072,MODP4096,MODP8192,ECP_256 2:IKE:ENCR=AES_GCM_C_128;PRF=HMAC_SHA2_512,HMAC_SHA2_256,HMAC_SHA1;INTEG=NONE;DH=MODP2048,MODP3072,MODP4096,MODP8192,ECP_256 3:IKE:ENCR=AES_CBC_256;PRF=HMAC_SHA2_512,HMAC_SHA2_256,HMAC_SHA1;INTEG=HMAC_SHA2_512_256,HMAC_SHA2_256_128,HMAC_SHA1_96;DH=MODP2048,MODP3072,MODP4096,MODP8192,ECP_256 4:IKE:ENCR=AES_CBC_128;PRF=HMAC_SHA2_512,HMAC_SHA2_256,HMAC_SHA1;INTEG=HMAC_SHA2_512_256,HMAC_SHA2_256_128,HMAC_SHA1_96;DH=MODP2048,MODP3072,MODP4096,MODP8192,ECP_256 (default)
> Mar 4 21:59:04 core pluto[25972]: packet from 178.197.x.x:36649: proposal 2:IKE:ENCR=AES_GCM_C_256;PRF=HMAC_SHA2_512;DH=MODP2048 chosen from remote proposals 1:IKE:ENCR=AES_CBC_128;ENCR=AES_CBC_192;ENCR=AES_CBC_256;ENCR=3DES;INTEG=HMAC_SHA2_256_128;INTEG=HMAC_SHA2_384_192;INTEG=HMAC_SHA2_512_256;INTEG=HMAC_SHA1_96;INTEG=AES_XCBC_96;PRF=HMAC_SHA2_256;PRF=HMAC_SHA2_384;PRF=HMAC_SHA2_512;PRF=AES128_XCBC;PRF=HMAC_SHA1;DH=ECP_256;DH=ECP_384;DH=ECP_521;DH=BRAINPOOL_P256R1;DH=BRAINPOOL_P384R1;DH=BRAINPOOL_P512R1;DH=CURVE25519;DH=MODP3072;DH=MODP4096;DH=MODP6144;DH=MODP8192;DH=MODP2048[first-match] 2:IKE:ENCR=AES_GCM_C_128;ENCR=AES_GCM_C_192;ENCR=AES_GCM_C_256;ENCR=CHACHA20_POLY1305;ENCR=AES_GCM_B_128;ENCR=AES_GCM_B_192;ENCR=AES_GCM_B_256;ENCR=AES_GCM_A_128;ENCR=AES_GCM_A_192;ENCR=AES_GCM_A_256;PRF=HMAC_SHA2_256;PRF=HMAC_SHA2_384;PRF=HMAC_SHA2_512;PRF=AES128_XCBC;PRF=HMAC_SHA1;DH=ECP_256;DH=ECP_384;DH=ECP_521;DH=BRAINPOOL_P256R1;DH=BRAINPOOL_P384R1;DH=BRAINPOOL_P512R1;DH=CURVE25519;DH=MOD
P3
> 072;DH=MODP4096;DH=MODP6144;DH=MODP8192;DH=MODP2048[...
> Mar 4 21:59:04 core pluto[25972]: packet from 178.197.x.x:36649: initiator guessed wrong keying material group (ECP_256); responding with INVALID_KE_PAYLOAD requesting MODP2048
> Mar 4 21:59:04 core pluto[25972]: packet from 178.197.x.x:36649: responding to SA_INIT message (ID 0) from 178.197.x.x:36649 with unencrypted notification INVALID_KE_PAYLOAD
> Mar 4 21:59:04 core pluto[25972]: packet from 178.197.x.x:36649: proposal 2:IKE:ENCR=AES_GCM_C_256;PRF=HMAC_SHA2_512;DH=MODP2048 chosen from remote proposals 1:IKE:ENCR=AES_CBC_128;ENCR=AES_CBC_192;ENCR=AES_CBC_256;ENCR=3DES;INTEG=HMAC_SHA2_256_128;INTEG=HMAC_SHA2_384_192;INTEG=HMAC_SHA2_512_256;INTEG=HMAC_SHA1_96;INTEG=AES_XCBC_96;PRF=HMAC_SHA2_256;PRF=HMAC_SHA2_384;PRF=HMAC_SHA2_512;PRF=AES128_XCBC;PRF=HMAC_SHA1;DH=MODP2048;DH=ECP_256;DH=ECP_384;DH=ECP_521;DH=BRAINPOOL_P256R1;DH=BRAINPOOL_P384R1;DH=BRAINPOOL_P512R1;DH=CURVE25519;DH=MODP3072;DH=MODP4096;DH=MODP6144;DH=MODP8192[first-match] 2:IKE:ENCR=AES_GCM_C_128;ENCR=AES_GCM_C_192;ENCR=AES_GCM_C_256;ENCR=CHACHA20_POLY1305;ENCR=AES_GCM_B_128;ENCR=AES_GCM_B_192;ENCR=AES_GCM_B_256;ENCR=AES_GCM_A_128;ENCR=AES_GCM_A_192;ENCR=AES_GCM_A_256;PRF=HMAC_SHA2_256;PRF=HMAC_SHA2_384;PRF=HMAC_SHA2_512;PRF=AES128_XCBC;PRF=HMAC_SHA1;DH=MODP2048;DH=ECP_256;DH=ECP_384;DH=ECP_521;DH=BRAINPOOL_P256R1;DH=BRAINPOOL_P384R1;DH=BRAINPOOL_P512R1;DH=CURVE
25
> 519;DH=MODP3072;DH=MODP4096;DH=MODP6144;DH=MODP8192[...
> Mar 4 21:59:04 core pluto[25972]: "ikev2-cp"[29] 178.197.x.x #30: STATE_PARENT_R1: received v2I1, sent v2R1 {auth=IKEv2 cipher=AES_GCM_16_256 integ=n/a prf=HMAC_SHA2_512 group=MODP2048}
> Mar 4 21:59:05 core pluto[25972]: "ikev2-cp"[29] 178.197.x.x #30: certificate verified OK: CN=bz
> Mar 4 21:59:05 core pluto[25972]: "ikev2-cp"[29] 178.197.x.x #30: No matching subjectAltName found
> Mar 4 21:59:05 core pluto[25972]: "ikev2-cp"[29] 178.197.x.x #30: certificate does not contain ID_IP subjectAltName=178.197.x.x
> Mar 4 21:59:05 core pluto[25972]: "ikev2-cp"[29] 178.197.x.x #30: Peer public key SubjectAltName does not match peer ID for this connection
> Mar 4 21:59:05 core pluto[25972]: "ikev2-cp"[29] 178.197.x.x #30: switched from "ikev2-cp"[29] 178.197.x.x to "ikev2-cp"
> Mar 4 21:59:05 core pluto[25972]: "ikev2-cp"[30] 178.197.x.x #30: deleting connection "ikev2-cp"[29] 178.197.x.x instance with peer 178.197.x.x {isakmp=#0/ipsec=#0}
> Mar 4 21:59:05 core pluto[25972]: "ikev2-cp"[30] 178.197.x.x #30: certificate verified OK: CN=bz
> Mar 4 21:59:05 core pluto[25972]: "ikev2-cp"[30] 178.197.x.x #30: IKEv2 mode peer ID is ID_DER_ASN1_DN: 'CN=bz'
> Mar 4 21:59:05 core pluto[25972]: "ikev2-cp"[30] 178.197.x.x #30: Authenticated using RSA
> Mar 4 21:59:05 core pluto[25972]: "ikev2-cp"[30] 178.197.x.x #30: constructed local ESP/AH proposals for ikev2-cp (IKE SA responder matching remote ESP/AH proposals): 1:ESP:ENCR=AES_GCM_C_256;INTEG=NONE;ESN=DISABLED 2:ESP:ENCR=AES_GCM_C_128;INTEG=NONE;ESN=DISABLED 3:ESP:ENCR=AES_CBC_256;INTEG=HMAC_SHA2_512_256,HMAC_SHA2_256_128;ESN=DISABLED 4:ESP:ENCR=AES_CBC_128;INTEG=HMAC_SHA2_512_256,HMAC_SHA2_256_128;ESN=DISABLED 5:ESP:ENCR=AES_CBC_128;INTEG=HMAC_SHA1_96;ESN=DISABLED (default)
> Mar 4 21:59:05 core pluto[25972]: "ikev2-cp"[30] 178.197.x.x #30: proposal 1:ESP:SPI=7af3f1a1;ENCR=AES_GCM_C_256;ESN=DISABLED chosen from remote proposals 1:ESP:ENCR=AES_GCM_C_256;ENCR=AES_GCM_C_128;ENCR=CHACHA20_POLY1305;ESN=DISABLED[first-match] 2:ESP:ENCR=AES_CBC_256;ENCR=AES_CBC_192;ENCR=AES_CBC_128;INTEG=HMAC_SHA2_384_192;INTEG=HMAC_SHA2_256_128;INTEG=HMAC_SHA2_512_256;INTEG=HMAC_SHA1_96;ESN=DISABLED
> Mar 4 21:59:05 core pluto[25972]: "ikev2-cp"[30] 178.197.x.x #30: received unsupported NOTIFY v2N_NO_ADDITIONAL_ADDRESSES
> Mar 4 21:59:05 core pluto[25972]: "ikev2-cp"[30] 178.197.x.x #30: received unsupported NOTIFY v2N_EAP_ONLY_AUTHENTICATION
> Mar 4 21:59:05 core pluto[25972]: "ikev2-cp"[30] 178.197.x.x #30: received unsupported NOTIFY v2N_IKEV2_MESSAGE_ID_SYNC_SUPPORTED
> Mar 4 21:59:05 core pluto[25972]: "ikev2-cp"[30] 178.197.x.x #31: negotiated connection [0.0.0.0-255.255.255.255:0-65535 0] -> [192.168.1.100-192.168.1.100:0-65535 0]
> Mar 4 21:59:05 core pluto[25972]: "ikev2-cp"[30] 178.197.x.x #31: STATE_V2_IPSEC_R: IPsec SA established tunnel mode {ESP/NAT=>0x7af3f1a1 <0x7ae96631 xfrm=AES_GCM_16_256-NONE NATOA=none NATD=178.197.x.x:21764 DPD=active}
>
>
> The client shows keep-alive attempts. Not sure if they are answered:
>
> ar 4 21:59:03 00[DMN] +-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+
> Mar 4 21:59:03 00[DMN] Starting IKE service (strongSwan 5.8.2dr1, Android 8.0.0 - 34.4.A.2.118/2018-09-01, F5321 - Sony/F5321/Sony, Linux 3.10.84-perf-g51b663cc723-04742-g5bcfaca9e61, aarch64)
> Mar 4 21:59:03 00[LIB] loaded plugins: androidbridge charon android-log openssl fips-prf random nonce pubkey chapoly curve25519 pkcs1 pkcs8 pem xcbc hmac socket-default revocation eap-identity eap-mschapv2 eap-md5 eap-gtc eap-tls x509
> Mar 4 21:59:03 00[JOB] spawning 16 worker threads
> Mar 4 21:59:03 07[CFG] loaded user certificate 'CN=bz' and private key
> Mar 4 21:59:03 07[CFG] loaded CA certificate 'C=CH, ST=ZH, O=xxxx'
> Mar 4 21:59:03 07[IKE] initiating IKE_SA android[2] to 84.75.x.x
> Mar 4 21:59:03 07[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) ]
> Mar 4 21:59:03 07[NET] sending packet: from 10.80.175.163[45162] to 84.75.x.x[500] (716 bytes)
> Mar 4 21:59:03 10[NET] received packet: from 84.75.x.x[500] to 10.80.175.163[45162] (38 bytes)
> Mar 4 21:59:03 10[ENC] parsed IKE_SA_INIT response 0 [ N(INVAL_KE) ]
> Mar 4 21:59:03 10[IKE] peer didn't accept DH group ECP_256, it requested MODP_2048
> Mar 4 21:59:03 10[IKE] initiating IKE_SA android[2] to 84.75.x.x
> Mar 4 21:59:03 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) ]
> Mar 4 21:59:03 10[NET] sending packet: from 10.80.175.163[45162] to 84.75.x.x[500] (908 bytes)
> Mar 4 21:59:03 11[NET] received packet: from 84.75.x.x[500] to 10.80.175.163[45162] (457 bytes)
> Mar 4 21:59:03 11[ENC] parsed IKE_SA_INIT response 0 [ SA KE No N(FRAG_SUP) N(NATD_S_IP) N(NATD_D_IP) CERTREQ ]
> Mar 4 21:59:03 11[CFG] selected proposal: IKE:AES_GCM_16_256/PRF_HMAC_SHA2_512/MODP_2048
> Mar 4 21:59:03 11[IKE] local host is behind NAT, sending keep alives
> Mar 4 21:59:03 11[IKE] received cert request for "C=CH, ST=ZH, O=xxx"
> Mar 4 21:59:03 11[IKE] sending cert request for "C=CH, ST=ZH, O=xxx"
> Mar 4 21:59:04 11[IKE] authentication of 'CN=bz' (myself) with RSA signature successful
> Mar 4 21:59:04 11[IKE] sending end entity cert "CN=bz"
> Mar 4 21:59:04 11[IKE] establishing CHILD_SA android{2}
> Mar 4 21:59:04 11[ENC] generating IKE_AUTH request 1 [ IDi CERT N(INIT_CONTACT) CERTREQ AUTH CPRQ(ADDR ADDR6 DNS DNS6) N(ESP_TFC_PAD_N) SA TSi TSr N(MOBIKE_SUP) N(NO_ADD_ADDR) N(EAP_ONLY) N(MSG_ID_SYN_SUP) ]
> Mar 4 21:59:04 11[ENC] splitting IKE message (2022 bytes) into 2 fragments
> Mar 4 21:59:04 11[ENC] generating IKE_AUTH request 1 [ EF(1/2) ]
> Mar 4 21:59:04 11[ENC] generating IKE_AUTH request 1 [ EF(2/2) ]
> Mar 4 21:59:04 11[NET] sending packet: from 10.80.175.163[43158] to 84.75.x.x[4500] (1368 bytes)
> Mar 4 21:59:04 11[NET] sending packet: from 10.80.175.163[43158] to 84.75.x.x[4500] (719 bytes)
> Mar 4 21:59:04 12[NET] received packet: from 84.75.x.x[4500] to 10.80.175.163[43158] (535 bytes)
> Mar 4 21:59:04 12[ENC] parsed IKE_AUTH response 1 [ EF(1/4) ]
> Mar 4 21:59:04 12[ENC] received fragment #1 of 4, waiting for complete IKE message
> Mar 4 21:59:04 13[NET] received packet: from 84.75.x.x[4500] to 10.80.175.163[43158] (535 bytes)
> Mar 4 21:59:04 13[ENC] parsed IKE_AUTH response 1 [ EF(2/4) ]
> Mar 4 21:59:04 13[ENC] received fragment #2 of 4, waiting for complete IKE message
> Mar 4 21:59:04 15[NET] received packet: from 84.75.x.x[4500] to 10.80.175.163[43158] (535 bytes)
> Mar 4 21:59:04 15[ENC] parsed IKE_AUTH response 1 [ EF(3/4) ]
> Mar 4 21:59:04 15[ENC] received fragment #3 of 4, waiting for complete IKE message
> Mar 4 21:59:04 14[NET] received packet: from 84.75.x.x[4500] to 10.80.175.163[43158] (366 bytes)
> Mar 4 21:59:04 14[ENC] parsed IKE_AUTH response 1 [ EF(4/4) ]
> Mar 4 21:59:04 14[ENC] received fragment #4 of 4, reassembled fragmented IKE message (1784 bytes)
> Mar 4 21:59:04 14[ENC] parsed IKE_AUTH response 1 [ IDr CERT AUTH CPRP(ADDR DNS) SA TSi TSr ]
> Mar 4 21:59:04 14[IKE] received end entity cert "CN=vpn.hidden.ch"
> Mar 4 21:59:04 14[CFG] using trusted ca certificate "C=CH, ST=ZH, O=xxx"
> Mar 4 21:59:04 14[CFG] checking certificate status of "CN=bz"
> Mar 4 21:59:04 14[CFG] certificate status is not available
> Mar 4 21:59:04 14[CFG] reached self-signed root ca with a path length of 0
> Mar 4 21:59:04 14[CFG] using trusted certificate "CN=bz"
> Mar 4 21:59:04 14[IKE] signature validation failed, looking for another key
> Mar 4 21:59:04 14[CFG] using certificate "CN=vpn.hidden.ch"
> Mar 4 21:59:04 14[CFG] using trusted ca certificate "C=CH, ST=ZH, O=xxx"
> Mar 4 21:59:04 14[CFG] checking certificate status of "CN=vpn.hidden.ch"
> Mar 4 21:59:04 14[CFG] certificate status is not available
> Mar 4 21:59:04 14[CFG] reached self-signed root ca with a path length of 0
> Mar 4 21:59:04 14[IKE] authentication of 'vpn.hidden.ch' with RSA signature successful
> Mar 4 21:59:04 14[IKE] IKE_SA android[2] established between 10.80.175.163[CN=bz]...84.75.x.x[vpn.hidden.ch]
> Mar 4 21:59:04 14[IKE] scheduling rekeying in 35942s
> Mar 4 21:59:04 14[IKE] maximum IKE_SA lifetime 36542s
> Mar 4 21:59:04 14[IKE] installing DNS server 10.76.1.1
> Mar 4 21:59:04 14[IKE] installing new virtual IP 192.168.1.100
> Mar 4 21:59:04 14[IKE] CHILD_SA android{2} established with SPIs 7af3f1a1_i 7ae96631_o and TS 192.168.1.100/32 === 0.0.0.0/0
> Mar 4 21:59:04 14[DMN] setting up TUN device for CHILD_SA android{2}
> Mar 4 21:59:04 14[DMN] successfully created TUN device
> Mar 4 22:00:29 11[IKE] sending keep alive to 84.75.x.x[4500]
> Mar 4 22:11:10 15[IKE] sending keep alive to 84.75.x.x[4500]
> Mar 4 22:11:55 14[IKE] sending keep alive to 84.75.x.x[4500]
> Mar 4 22:13:07 09[IKE] sending keep alive to 84.75.x.x[4500]
>
>
> The firewall is OK from my perspective:
>
> Chain INPUT (policy ACCEPT 0 packets, 0 bytes)
> pkts bytes target prot opt in out source destination
> 103M 142G ACCEPT all -- vlan5 * 0.0.0.0/0 0.0.0.0/0 ctstate RELATED,ESTABLISHED
> 5981 386K ACCEPT all -- vlan5 * 192.168.1.0/24 0.0.0.0/0 policy match dir in pol ipsec
> 469 247K ACCEPT udp -- vlan5 * 0.0.0.0/0 0.0.0.0/0 udp dpt:500
> 7671 1465K ACCEPT udp -- vlan5 * 0.0.0.0/0 0.0.0.0/0 udp dpt:4500
> 372 52561 ACCEPT udp -- vlan5 * 0.0.0.0/0 0.0.0.0/0 udp dpt:1701
> 711K 42M DROP all -- vlan5 * 0.0.0.0/0 0.0.0.0/0
>
> Chain FORWARD (policy ACCEPT 0 packets, 0 bytes)
> pkts bytes target prot opt in out source destination
> 184M 234G ACCEPT all -- vlan5 * 0.0.0.0/0 0.0.0.0/0 ctstate RELATED,ESTABLISHED
> 4244 726K ACCEPT all -- vlan5 * 192.168.1.0/24 0.0.0.0/0 policy match dir in pol ipsec
> 754 82552 DROP all -- vlan5 * 0.0.0.0/0 0.0.0.0/0
>
> Chain POSTROUTING (policy ACCEPT 0 packets, 0 bytes)
> pkts bytes target prot opt in out source destination
> 0 0 RETURN all -- * vlan5 0.0.0.0/0 0.0.0.0/0 policy match dir out pol ipsec
> 3938K 460M MASQUERADE all -- * vlan5 0.0.0.0/0 0.0.0.0/0
>
>
>
> Both server and client show active connections even when the connection has stalled...
>
> # ipsec trafficstatus
> 006 #33: "ikev2-cp"[32] 178.197.x.x, type=ESP, add_time=1583356793, inBytes=136685, outBytes=207835, id='CN=bz', lease=192.168.1.100/32
>
>
>
> Any ideas? Cheers
> _______________________________________________
> Swan mailing list
> Swan at lists.libreswan.org
> https://lists.libreswan.org/mailman/listinfo/swan
>
More information about the Swan
mailing list