Martin, Thanks for responding. I have modified both sides of the VPN with ‘reauth=no’ and the problem persists.
Here is another occurrence of an issue that we got with our VPN. This happened to my colleague, who characterized the incidence like this: Here's the log snippet. I had 2 ssh sessions open to host1. The one that I was actively working in got disconnected with "Write failed: Broken pipe" less than a second after running a successful command. Like I say, I was actively working in that shell. Meanwhile, the other shell, which was open but I was *not* actively working in, did not disconnect, and was viable as soon as I switched over to it. Here’s the log whose messages span the duration of the incident: Oct 15 19:51:39 CloudOpsVpns charon: 14[IKE] reauthenticating IKE_SA vpn1[21] Oct 15 19:51:39 CloudOpsVpns charon: 14[IKE] deleting IKE_SA vpn1[21] between AAA.AA.AAA.AAA[[email protected]]...BB.BBB.BBB.BBB[host-us-west-1b] Oct 15 19:51:39 CloudOpsVpns charon: 14[IKE] sending DELETE for IKE_SA vpn1[21] Oct 15 19:51:39 CloudOpsVpns charon: 14[ENC] generating INFORMATIONAL request 2 [ D ] Oct 15 19:51:39 CloudOpsVpns charon: 14[NET] sending packet: from AAA.AA.AAA.AAA[4500] to BB.BBB.BBB.BBB[4500] (76 bytes) Oct 15 19:51:40 CloudOpsVpns charon: 02[NET] received packet: from BB.BBB.BBB.BBB[4500] to AAA.AA.AAA.AAA[4500] (76 bytes) Oct 15 19:51:40 CloudOpsVpns charon: 02[ENC] parsed INFORMATIONAL response 2 [ ] Oct 15 19:51:40 CloudOpsVpns charon: 02[IKE] IKE_SA deleted Oct 15 19:51:40 CloudOpsVpns vpn: - host-us-west-1b 10.0.0.0/28 == BB.BBB.BBB.BBB -- AAA.AA.AAA.AAA == 10.100.255.2/32 Oct 15 19:51:40 CloudOpsVpns charon: 02[IKE] installing new virtual IP 10.100.255.2 Oct 15 19:51:40 CloudOpsVpns charon: 02[IKE] restarting CHILD_SA vpn1 Oct 15 19:51:40 CloudOpsVpns charon: 02[IKE] initiating IKE_SA vpn1[23] to BB.BBB.BBB.BBB Oct 15 19:51:40 CloudOpsVpns charon: 02[ENC] generating IKE_SA_INIT request 0 [ SA KE No N(NATD_S_IP) N(NATD_D_IP) ] Oct 15 19:51:40 CloudOpsVpns charon: 02[NET] sending packet: from AAA.AA.AAA.AAA[500] to BB.BBB.BBB.BBB[500] (1212 bytes) Oct 15 19:51:40 CloudOpsVpns charon: 07[NET] received packet: from BB.BBB.BBB.BBB[500] to AAA.AA.AAA.AAA[500] (465 bytes) Oct 15 19:51:40 CloudOpsVpns charon: 07[ENC] parsed IKE_SA_INIT response 0 [ SA KE No N(NATD_S_IP) N(NATD_D_IP) CERTREQ N(MULT_AUTH) ] Oct 15 19:51:40 CloudOpsVpns charon: 07[IKE] local host is behind NAT, sending keep alives Oct 15 19:51:40 CloudOpsVpns charon: 07[IKE] remote host is behind NAT Oct 15 19:51:40 CloudOpsVpns charon: 07[IKE] received 1 cert requests for an unknown ca Oct 15 19:51:40 CloudOpsVpns charon: 07[IKE] authentication of '[email protected]' (myself) with RSA signature successful Oct 15 19:51:40 CloudOpsVpns charon: 07[IKE] sending end entity cert "C=USA, O=iRise, [email protected]" Oct 15 19:51:40 CloudOpsVpns charon: 07[IKE] establishing CHILD_SA vpn1{1} Oct 15 19:51:40 CloudOpsVpns charon: 07[ENC] generating IKE_AUTH request 1 [ IDi CERT N(INIT_CONTACT) IDr AUTH CPRQ(ADDR DNS) SA TSi TSr N(MOBIKE_SUP) N(NO_ADD_ADDR) N(MULT_AUTH) N(EAP_ONLY) ] Oct 15 19:51:40 CloudOpsVpns charon: 07[NET] sending packet: from AAA.AA.AAA.AAA[4500] to BB.BBB.BBB.BBB[4500] (1772 bytes) Oct 15 19:51:40 CloudOpsVpns charon: 12[NET] received packet: from BB.BBB.BBB.BBB[4500] to AAA.AA.AAA.AAA[4500] (492 bytes) Oct 15 19:51:40 CloudOpsVpns charon: 12[ENC] parsed IKE_AUTH response 1 [ IDr AUTH CPRP(ADDR) SA TSi TSr N(AUTH_LFT) N(MOBIKE_SUP) N(NO_ADD_ADDR) ] Oct 15 19:51:40 CloudOpsVpns charon: 12[CFG] no issuer certificate found for "C=USA, O=iRise, CN=host-us-west-1b" Oct 15 19:51:40 CloudOpsVpns charon: 12[CFG] using trusted certificate "C=USA, O=iRise, CN=host-us-west-1b" Oct 15 19:51:40 CloudOpsVpns charon: 12[IKE] authentication of 'host-us-west-1b' with RSA signature successful Oct 15 19:51:40 CloudOpsVpns charon: 12[IKE] IKE_SA vpn1[23] established between AAA.AA.AAA.AAA[[email protected]]...BB.BBB.BBB.BBB[host-us-west-1b] Oct 15 19:51:40 CloudOpsVpns charon: 12[IKE] scheduling rekeying in 9787s Oct 15 19:51:40 CloudOpsVpns charon: 12[IKE] maximum IKE_SA lifetime 10327s Oct 15 19:51:40 CloudOpsVpns charon: 12[IKE] installing new virtual IP 10.100.255.2 Oct 15 19:51:40 CloudOpsVpns charon: 12[IKE] CHILD_SA vpn1{1} established with SPIs cb5d4d03_i c25d94db_o and TS 10.100.255.2/32 === 10.0.0.0/28 Oct 15 19:51:40 CloudOpsVpns vpn: + host-us-west-1b 10.0.0.0/28 == BB.BBB.BBB.BBB -- AAA.AA.AAA.AAA == 10.100.255.2/32 Oct 15 19:51:40 CloudOpsVpns charon: 12[IKE] received AUTH_LIFETIME of 3381s, scheduling reauthentication in 2841s Oct 15 19:51:40 CloudOpsVpns charon: 12[IKE] peer supports MOBIKE Oct 15 19:51:49 CloudOpsVpns charon: 07[IKE] sending keep alive to 54.183.207.28[4500] On Oct 15, 2014, at 11:02 AM, John Emerson <[email protected]> wrote: > Martin, > I added ‘reauth=no’ to the client connection, but the problem persists. I > didn’t need to add it to the server’s config too did I? Here are the log > files showing what is happening when I get hung on the server side. Note that > unfortunately, the clocks aren’t synced. The server’s clock is ~ 00:01:06 > seconds ahead of the client’s clock. > > I’d appreciate any help in this regard. > > Thanks, > John Emerson > Software Architect, iRise > > Client log > Oct 15 17:31:48 CloudOpsVM charon: 12[NET] received packet: from > XX.XXX.XXX.XXX[4500] to YYY.YY.YYY.YYY[4500] (348 bytes) > Oct 15 17:31:48 CloudOpsVM charon: 12[ENC] parsed CREATE_CHILD_SA request 4 [ > N(REKEY_SA) SA No TSi TSr ] > Oct 15 17:31:48 CloudOpsVM charon: 12[IKE] CHILD_SA vpn1{1} established with > SPIs c9cc0f20_i c743c079_o and TS 10.100.255.1/32 === 10.0.0.0/28 > Oct 15 17:31:48 CloudOpsVM charon: 12[ENC] generating CREATE_CHILD_SA > response 4 [ SA No TSi TSr ] > Oct 15 17:31:48 CloudOpsVM charon: 12[NET] sending packet: from > YYY.YY.YYY.YYY[4500] to XX.XXX.XXX.XXX[4500] (204 bytes) > Oct 15 17:31:48 CloudOpsVM charon: 05[NET] received packet: from > XX.XXX.XXX.XXX[4500] to YYY.YY.YYY.YYY[4500] (76 bytes) > Oct 15 17:31:48 CloudOpsVM charon: 05[ENC] parsed INFORMATIONAL request 5 [ D > ] > Oct 15 17:31:48 CloudOpsVM charon: 05[IKE] received DELETE for ESP CHILD_SA > with SPI cdb2d89f > Oct 15 17:31:48 CloudOpsVM charon: 05[IKE] closing CHILD_SA vpn1{1} with SPIs > cf785086_i (14744 bytes) cdb2d89f_o (8048 bytes) and TS 10.100.255.1/32 === > 10.0.0.0/28 > Oct 15 17:31:48 CloudOpsVM charon: 05[IKE] sending DELETE for ESP CHILD_SA > with SPI cf785086 > Oct 15 17:31:48 CloudOpsVM charon: 05[IKE] CHILD_SA closed > Oct 15 17:31:48 CloudOpsVM charon: 05[ENC] generating INFORMATIONAL response > 5 [ D ] > Oct 15 17:31:48 CloudOpsVM charon: 05[NET] sending packet: from > YYY.YY.YYY.YYY[4500] to XX.XXX.XXX.XXX[4500] (76 bytes) > Oct 15 17:32:04 CloudOpsVM charon: 04[IKE] sending keep alive to > ZZ.ZZZ.ZZZ.ZZ[4500] > > Server: > Oct 15 17:32:54 host-us-west-1b charon: 04[KNL] creating rekey job for ESP > CHILD_SA with SPI cf785086 and reqid {182} > Oct 15 17:32:54 host-us-west-1b charon: 04[IKE] establishing CHILD_SA rw{182} > Oct 15 17:32:54 host-us-west-1b charon: 04[ENC] generating CREATE_CHILD_SA > request 4 [ N(REKEY_SA) SA No TSi TSr ] > Oct 15 17:32:54 host-us-west-1b charon: 04[NET] sending packet: from > 10.0.0.6[4500] to AA.AAA.AA.A[32279] (348 bytes) > Oct 15 17:32:54 host-us-west-1b charon: 13[NET] received packet: from > AA.AAA.AA.A[32279] to 10.0.0.6[4500] (204 bytes) > Oct 15 17:32:54 host-us-west-1b charon: 13[ENC] parsed CREATE_CHILD_SA > response 4 [ SA No TSi TSr ] > Oct 15 17:32:54 host-us-west-1b charon: 13[IKE] CHILD_SA rw{182} established > with SPIs c743c079_i c9cc0f20_o and TS 10.0.0.0/28 === 10.100.255.1/32 > Oct 15 17:32:54 host-us-west-1b charon: 13[IKE] closing CHILD_SA rw{182} with > SPIs cdb2d89f_i (8048 bytes) cf785086_o (17744 bytes) and TS 10.0.0.0/28 === > 10.100.255.1/32 > Oct 15 17:32:54 host-us-west-1b charon: 13[IKE] sending DELETE for ESP > CHILD_SA with SPI cdb2d89f > Oct 15 17:32:54 host-us-west-1b charon: 13[ENC] generating INFORMATIONAL > request 5 [ D ] > Oct 15 17:32:54 host-us-west-1b charon: 13[NET] sending packet: from > 10.0.0.6[4500] to AA.AAA.AA.A[32279] (76 bytes) > Oct 15 17:32:54 host-us-west-1b charon: 01[NET] received packet: from > AA.AAA.AA.A[32279] to 10.0.0.6[4500] (76 bytes) > Oct 15 17:32:54 host-us-west-1b charon: 01[ENC] parsed INFORMATIONAL response > 5 [ D ] > Oct 15 17:32:54 host-us-west-1b charon: 01[IKE] received DELETE for ESP > CHILD_SA with SPI cf785086 > Oct 15 17:32:54 host-us-west-1b charon: 01[IKE] CHILD_SA closed > Oct 15 17:33:02 host-us-west-1b charon: 12[IKE] sending keep alive to > BBB.BB.BBB.BBB[61756] > Oct 15 17:33:20 host-us-west-1b charon: 05[IKE] sending keep alive to > AA.AAA.AA.A[32279] > Oct 15 17:33:22 host-us-west-1b charon: 15[IKE] sending keep alive to > BBB.BB.BBB.BBB[61756] > Oct 15 17:33:40 host-us-west-1b charon: 14[IKE] sending keep alive to > AA.AAA.AA.A[32279] > Oct 15 17:33:42 host-us-west-1b charon: 04[IKE] sending keep alive to > BBB.BB.BBB.BBB[61756] > Oct 15 17:33:50 host-us-west-1b charon: 16[NET] received packet: from > AA.AAA.AA.A[32279] to 10.0.0.6[4500] (76 bytes) > Oct 15 17:33:50 host-us-west-1b charon: 16[ENC] parsed INFORMATIONAL request > 2 [ D ] > Oct 15 17:33:50 host-us-west-1b charon: 16[IKE] received DELETE for IKE_SA > rw[183] > Oct 15 17:33:50 host-us-west-1b charon: 16[IKE] deleting IKE_SA rw[183] > between > 10.0.0.6[host-us-west-1b]...AA.AAA.AA.A[[email protected]]host-us-west-1b > Oct 15 17:33:50 host-us-west-1b charon: 16[IKE] IKE_SA deleted > Oct 15 17:33:50 host-us-west-1b vpn: - [email protected] 10.100.255.1/32 == > AA.AAA.AA.A -- 10.0.0.6 == 10.0.0.0/28 > Oct 15 17:33:50 host-us-west-1b charon: 16[ENC] generating INFORMATIONAL > response 2 [ ] > Oct 15 17:33:50 host-us-west-1b charon: 16[NET] sending packet: from > 10.0.0.6[4500] to AA.AAA.AA.A[32279] (76 bytes) > Oct 15 17:33:50 host-us-west-1b charon: 16[CFG] lease 10.100.255.1 by > '[email protected]' went offline > Oct 15 17:33:50 host-us-west-1b charon: 01[NET] received packet: from > AA.AAA.AA.A[6297] to 10.0.0.6[500] (1212 bytes) > Oct 15 17:33:50 host-us-west-1b charon: 01[ENC] parsed IKE_SA_INIT request 0 > [ SA KE No N(NATD_S_IP) N(NATD_D_IP) ] > Oct 15 17:33:50 host-us-west-1b charon: 01[IKE] AA.AAA.AA.A is initiating an > IKE_SA > Oct 15 17:33:50 host-us-west-1b charon: 01[IKE] local host is behind NAT, > sending keep alives > Oct 15 17:33:50 host-us-west-1b charon: 01[IKE] remote host is behind NAT > Oct 15 17:33:50 host-us-west-1b charon: 01[IKE] sending cert request for > "C=USA, O=iRise, CN=iRise Host Root CA" > Oct 15 17:33:50 host-us-west-1b charon: 01[ENC] generating IKE_SA_INIT > response 0 [ SA KE No N(NATD_S_IP) N(NATD_D_IP) CERTREQ N(MULT_AUTH) ] > Oct 15 17:33:50 host-us-west-1b charon: 01[NET] sending packet: from > 10.0.0.6[500] to AA.AAA.AA.A[6297] (465 bytes) > Oct 15 17:33:50 host-us-west-1b charon: 02[NET] received packet: from > AA.AAA.AA.A[32279] to 10.0.0.6[4500] (1772 bytes) > Oct 15 17:33:50 host-us-west-1b charon: 02[ENC] parsed IKE_AUTH request 1 [ > IDi CERT N(INIT_CONTACT) IDr AUTH CPRQ(ADDR DNS) SA TSi TSr N(MOBIKE_SUP) > N(NO_ADD_ADDR) N(MULT_AUTH) N(EAP_ONLY) ] > Oct 15 17:33:50 host-us-west-1b charon: 02[IKE] received end entity cert > "C=USA, O=iRise, [email protected]" > Oct 15 17:33:50 host-us-west-1b charon: 02[CFG] looking for peer configs > matching > 10.0.0.6[host-us-west-1b]...AA.AAA.AA.A[[email protected]]host-us-west-1b > Oct 15 17:33:50 host-us-west-1b charon: 02[CFG] selected peer config 'rw' > Oct 15 17:33:50 host-us-west-1b charon: 02[CFG] using certificate "C=USA, > O=iRise, [email protected]" > Oct 15 17:33:50 host-us-west-1b charon: 02[CFG] using trusted ca > certificate "C=USA, O=iRise, CN=iRise Host Root CA" > Oct 15 17:33:50 host-us-west-1b charon: 02[CFG] checking certificate status > of "C=USA, O=iRise, [email protected]" > Oct 15 17:33:50 host-us-west-1b charon: 02[CFG] certificate status is not > available > Oct 15 17:33:50 host-us-west-1b charon: 02[CFG] reached self-signed root ca > with a path length of 0 > Oct 15 17:33:50 host-us-west-1b charon: 02[IKE] authentication of > '[email protected]' with RSA signature successful > Oct 15 17:33:50 host-us-west-1b charon: 02[IKE] peer supports MOBIKE > Oct 15 17:33:50 host-us-west-1b charon: 02[IKE] authentication of > 'host-us-west-1b' (myself) with RSA signature successfulhost-us-west-1b > Oct 15 17:33:50 host-us-west-1b charon: 02[IKE] IKE_SA rw[185] established > between > 10.0.0.6[host-us-west-1b]...AA.AAA.AA.A[[email protected]]host-us-west-1b > Oct 15 17:33:50 host-us-west-1b charon: 02[IKE] scheduling reauthentication > in 3369s > Oct 15 17:33:50 host-us-west-1b charon: 02[IKE] maximum IKE_SA lifetime 3549s > Oct 15 17:33:50 host-us-west-1b charon: 02[IKE] peer requested virtual IP > 10.100.255.1 > Oct 15 17:33:50 host-us-west-1b charon: 02[CFG] reassigning offline lease to > '[email protected]' > Oct 15 17:33:50 host-us-west-1b charon: 02[IKE] assigning virtual IP > 10.100.255.1 to peer '[email protected]' > Oct 15 17:33:50 host-us-west-1b charon: 02[IKE] CHILD_SA rw{184} established > with SPIs c40f1157_i c92cfa10_o and TS 10.0.0.0/28 === 10.100.255.1/32 > Oct 15 17:33:50 host-us-west-1b vpn: + [email protected] 10.100.255.1/32 == > AA.AAA.AA.A -- 10.0.0.6 == 10.0.0.0/28 > Oct 15 17:33:50 host-us-west-1b charon: 02[ENC] generating IKE_AUTH response > 1 [ IDr AUTH CPRP(ADDR) SA TSi TSr N(AUTH_LFT) N(MOBIKE_SUP) N(NO_ADD_ADDR) ] > Oct 15 17:33:50 host-us-west-1b charon: 02[NET] sending packet: from > 10.0.0.6[4500] to AA.AAA.AA.A[32279] (492 bytes) > Oct 15 17:34:02 host-us-west-1b charon: 12[IKE] sending keep alive to > BBB.BB.BBB.BBB[61756] > Oct 15 17:34:11 host-us-west-1b charon: 05[IKE] sending keep alive to > AA.AAA.AA.A[32279] > Oct 15 17:34:17 host-us-west-1b charon: 15[KNL] creating rekey job for ESP > CHILD_SA with SPI cbf1b8a5 and reqid {183} > Oct 15 17:34:17 host-us-west-1b charon: 15[IKE] establishing CHILD_SA rw{183} > Oct 15 17:34:17 host-us-west-1b charon: 15[ENC] generating CREATE_CHILD_SA > request 4 [ N(REKEY_SA) SA No TSi TSr ] > Oct 15 17:34:17 host-us-west-1b charon: 15[NET] sending packet: from > 10.0.0.6[4500] to BBB.BB.BBB.BBB[61756] (348 bytes) > Oct 15 17:34:17 host-us-west-1b charon: 04[NET] received packet: from > BBB.BB.BBB.BBB[61756] to 10.0.0.6[4500] (204 bytes) > Oct 15 17:34:17 host-us-west-1b charon: 04[ENC] parsed CREATE_CHILD_SA > response 4 [ SA No TSi TSr ] > Oct 15 17:34:17 host-us-west-1b charon: 04[IKE] CHILD_SA rw{183} established > with SPIs cc186286_i cb0e6ae5_o and TS 10.0.0.0/28 === 10.100.255.3/32 > Oct 15 17:34:17 host-us-west-1b charon: 04[IKE] closing CHILD_SA rw{183} with > SPIs cbf1b8a5_i (0 bytes) c886414e_o (0 bytes) and TS 10.0.0.0/28 === > 10.100.255.3/32 > Oct 15 17:34:17 host-us-west-1b charon: 04[IKE] sending DELETE for ESP > CHILD_SA with SPI cbf1b8a5 > Oct 15 17:34:17 host-us-west-1b charon: 04[ENC] generating INFORMATIONAL > request 5 [ D ] > Oct 15 17:34:17 host-us-west-1b charon: 04[NET] sending packet: from > 10.0.0.6[4500] to BBB.BB.BBB.BBB[61756] (76 bytes) > Oct 15 17:34:17 host-us-west-1b charon: 13[NET] received packet: from > BBB.BB.BBB.BBB[61756] to 10.0.0.6[4500] (76 bytes) > Oct 15 17:34:17 host-us-west-1b charon: 13[ENC] parsed INFORMATIONAL response > 5 [ D ] > Oct 15 17:34:17 host-us-west-1b charon: 13[IKE] received DELETE for ESP > CHILD_SA with SPI c886414e > Oct 15 17:34:17 host-us-west-1b charon: 13[IKE] CHILD_SA closed > Oct 15 17:34:40 host-us-west-1b charon: 12[IKE] sending keep alive to > AA.AAA.AA.A[32279] > Oct 15 17:34:41 host-us-west-1b charon: 11[IKE] sending keep alive to > BBB.BB.BBB.BBB[61756] > Oct 15 17:35:00 host-us-west-1b login_duo: Successful Duo login for > 'jemerson' from 10.100.255.1 > Oct 15 17:35:01 host-us-west-1b charon: 15[IKE] sending keep alive to > BBB.BB.BBB.BBB[61756] > Oct 15 17:35:08 host-us-west-1b charon: 14[IKE] sending keep alive to > AA.AAA.AA.A[32279] > Oct 15 17:35:21 host-us-west-1b charon: 04[IKE] sending keep alive to > BBB.BB.BBB.BBB[61756] > > On Oct 14, 2014, at 1:22 AM, Martin Willi <[email protected]> wrote: > >> Hi, >> >>> From the client, I ssh to the server to do work. I use this VPN without >>> issue for many minutes. Then I perform some command like ‘ps -ef’ or >>> ‘vi foo’ and the VPN output hangs. While ‘hung’, from another shell >>> session I still see heartbeats on the VPN. If I wait around long enough >>> (30 minutes or less), output from the command eventually is fully >>> written after which I see a shell prompt. >> >> Sounds like you are losing packets on your SSH TCP connection for some >> time, and then after the problem is solved your connections comes back >> to live. >> >> The question is if you see any IKE activity (rekeying etc.) during that >> "hung" and the "restore" events. The strongSwan log should give you more >> information what exactly is going on during these events. >> >>> While hung in one shell, using a different shell, I can connect to the >>> same machine over the same VPN and work normally. >> >> This implies that the connection on the IP level is ok, but something is >> wrong on your TCP session layer; likely related to your virtual IP. >> >> As you are using (the default) re-authentication, your IKE_SA gets >> periodically re-negotiated. As this procedure includes the removal and >> addition of your virtual IP, it is not unlikely that your TCP session >> over that same IP breaks. >> >> I'd recommend to set reauth=no to see if that helps. This should make >> sure your virtual IP does not get reinstalled. The IKE_SA still gets >> fresh key material, but the peer certificates don't get re-evaluated >> periodically. >> >> Regards >> Martin
smime.p7s
Description: S/MIME cryptographic signature
_______________________________________________ Users mailing list [email protected] https://lists.strongswan.org/mailman/listinfo/users
