[Swan-dev] iphone ios8 gets xauth request before isakmp is established

Wolfgang Nothdurft wolfgang at linogate.de
Fri Dec 5 17:18:29 EET 2014


A customer reported a problem with an iphone (IOS8) xauth connection and 
libreswan 3.9.

The same connection works from one net without problems, but if trying 
from another net, the connection can't be established.

After examine the log, the problem seems to be that the iphone get the 
xauth login request before finishing phase one.

Dec  5 13:10:58 iPad-von-roe racoon[455] <Error>: mode config 6 from 
xxx.x.xx.xxx[4500], but ISAKMP-SA 23dc52d8e2241e77:1ce13e6f0962d19e 
isn't established.
Dec  5 13:10:58 iPad-von-roe racoon[455] <Notice>: IPSec Phase 1 
established (Initiated by me).

See attached logs from both sides.

A quick and dirty workaround was putting a delay before xauth_send_request.

See attached patch.

I will try to tweak this parameter next week.

Is this a known problem?

Wolfgang
-------------- next part --------------
Dec  5 13:10:57 iPad-von-roe nesessionmanager[191] <Notice>: NESMLegacySession[SX-GATE IPSec VPN xxx.x.xx.xxx:XXXXXXXXX-XXXX-XXXX-XXXX-XXXXXXXXXXXX]: Received a start command from Preferences[190]
Dec  5 13:10:57 iPad-von-roe nesessionmanager[191] <Notice>: IPSec connecting to server xxx.x.xx.xxx
Dec  5 13:10:57 iPad-von-roe nesessionmanager[191] <Notice>: IPSec Phase1 starting.
Dec  5 13:10:57 iPad-von-roe racoon[455] <Notice>: accepted connection on vpn control socket.
Dec  5 13:10:57 iPad-von-roe racoon[455] <Notice>: accepted connection on vpn control socket.
Dec  5 13:10:57 iPad-von-roe racoon[455] <Notice>: IPSec Phase 1 started (Initiated by me).
Dec  5 13:10:57 iPad-von-roe racoon[455] <Notice>: >>>>> phase change status = Phase 1 started by peer
Dec  5 13:10:57 iPad-von-roe racoon[455] <Notice>: >>>>> phase change status = Phase 1 started by peer
Dec  5 13:10:58 iPad-von-roe racoon[455] <Error>: mode config 6 from xxx.x.xx.xxx[4500], but ISAKMP-SA 23dc52d8e2241e77:1ce13e6f0962d19e isn't established.
Dec  5 13:10:58 iPad-von-roe racoon[455] <Error>: mode config 6 from xxx.x.xx.xxx[4500], but ISAKMP-SA 23dc52d8e2241e77:1ce13e6f0962d19e isn't established.
Dec  5 13:10:58 iPad-von-roe racoon[455] <Notice>: IPSec Phase 1 established (Initiated by me).
Dec  5 13:11:27 iPad-von-roe nesessionmanager[191] <Notice>: NESMLegacySession[SX-GATE IPSec VPN xxx.x.xx.xxx:XXXXXXXXX-XXXX-XXXX-XXXX-XXXXXXXXXXXX]: status changed to disconnecting
Dec  5 13:11:27 iPad-von-roe nesessionmanager[191] <Notice>: NESMLegacySession[SX-GATE IPSec VPN xxx.x.xx.xxx:XXXXXXXXX-XXXX-XXXX-XXXX-XXXXXXXXXXXX]: status changed to disconnected, last stop reason 0
Dec  5 13:11:27 iPad-von-roe racoon[455] <Notice>: IPSec disconnecting from server xxx.x.xx.xxx
Dec  5 13:11:27 iPad-von-roe racoon[455] <Notice>: IPSec disconnecting from server xxx.x.xx.xxx
Dec  5 13:11:27 iPad-von-roe racoon[455] <Error>: failed to send vpn_control message: Broken pipe
Dec  5 13:11:27 iPad-von-roe racoon[455] <Error>: failed to send vpn_control message: Broken pipe
Dec  5 13:11:27 iPad-von-roe racoon[455] <Warning>: glob found no matches for path "/var/run/racoon/*.conf"
Dec  5 13:11:28 iPad-von-roe locationd[62] <Notice>: Gesture EnabledForTopCLient: 0, EnabledInDaemonSettings: 0
Dec  5 13:11:33 iPad-von-roe locationd[62] <Notice>: Gesture EnabledForTopCLient: 0, EnabledInDaemonSettings: 0
-------------- next part --------------
Dec  5 10:21:35 defendo pluto[29609]: packet from xx.xxx.xxx.xx:61435: received Vendor ID payload [RFC 3947]
Dec  5 10:21:35 defendo pluto[29609]: packet from xx.xxx.xxx.xx:61435: ignoring Vendor ID payload [draft-ietf-ipsec-nat-t-ike]
Dec  5 10:21:35 defendo pluto[29609]: packet from xx.xxx.xxx.xx:61435: ignoring Vendor ID payload [draft-ietf-ipsec-nat-t-ike-08]
Dec  5 10:21:35 defendo pluto[29609]: packet from xx.xxx.xxx.xx:61435: ignoring Vendor ID payload [draft-ietf-ipsec-nat-t-ike-07]
Dec  5 10:21:35 defendo pluto[29609]: packet from xx.xxx.xxx.xx:61435: ignoring Vendor ID payload [draft-ietf-ipsec-nat-t-ike-06]
Dec  5 10:21:35 defendo pluto[29609]: packet from xx.xxx.xxx.xx:61435: ignoring Vendor ID payload [draft-ietf-ipsec-nat-t-ike-05]
Dec  5 10:21:35 defendo pluto[29609]: packet from xx.xxx.xxx.xx:61435: ignoring Vendor ID payload [draft-ietf-ipsec-nat-t-ike-04]
Dec  5 10:21:35 defendo pluto[29609]: packet from xx.xxx.xxx.xx:61435: ignoring Vendor ID payload [draft-ietf-ipsec-nat-t-ike-03]
Dec  5 10:21:35 defendo pluto[29609]: packet from xx.xxx.xxx.xx:61435: ignoring Vendor ID payload [draft-ietf-ipsec-nat-t-ike-02]
Dec  5 10:21:35 defendo pluto[29609]: packet from xx.xxx.xxx.xx:61435: ignoring Vendor ID payload [draft-ietf-ipsec-nat-t-ike-02_n]
Dec  5 10:21:35 defendo pluto[29609]: packet from xx.xxx.xxx.xx:61435: received Vendor ID payload [XAUTH]
Dec  5 10:21:35 defendo pluto[29609]: packet from xx.xxx.xxx.xx:61435: received Vendor ID payload [Cisco-Unity]
Dec  5 10:21:35 defendo pluto[29609]: packet from xx.xxx.xxx.xx:61435: received Vendor ID payload [FRAGMENTATION 80000000]
Dec  5 10:21:35 defendo pluto[29609]: packet from xx.xxx.xxx.xx:61435: received Vendor ID payload [Dead Peer Detection]
Dec  5 10:21:35 defendo pluto[29609]: packet from xx.xxx.xxx.xx:61435: OS detection: MacOS X
Dec  5 10:21:35 defendo pluto[29609]: "xauth_0-iPhone_sn-sn_0.0.0.0_0-0.0.0.0_0"[11] xx.xxx.xxx.xx #22: enabling possible NAT-traversal with method RFC 3947 (NAT-Traversal)
Dec  5 10:21:35 defendo pluto[29609]: "xauth_0-iPhone_sn-sn_0.0.0.0_0-0.0.0.0_0"[11] xx.xxx.xxx.xx #22: responding to Main Mode from unknown peer xx.xxx.xxx.xx
Dec  5 10:21:35 defendo pluto[29609]: "xauth_0-iPhone_sn-sn_0.0.0.0_0-0.0.0.0_0"[11] xx.xxx.xxx.xx #22: transition from state STATE_MAIN_R0 to state STATE_MAIN_R1
Dec  5 10:21:35 defendo pluto[29609]: "xauth_0-iPhone_sn-sn_0.0.0.0_0-0.0.0.0_0"[11] xx.xxx.xxx.xx #22: STATE_MAIN_R1: sent MR1, expecting MI2
Dec  5 10:21:35 defendo pluto[29609]: "xauth_0-iPhone_sn-sn_0.0.0.0_0-0.0.0.0_0"[11] xx.xxx.xxx.xx #22: NAT-Traversal: Result using RFC 3947 (NAT-Traversal) sender port 61435: peer behind NAT
Dec  5 10:21:35 defendo pluto[29609]: "xauth_0-iPhone_sn-sn_0.0.0.0_0-0.0.0.0_0"[11] xx.xxx.xxx.xx #22: transition from state STATE_MAIN_R1 to state STATE_MAIN_R2
Dec  5 10:21:35 defendo pluto[29609]: "xauth_0-iPhone_sn-sn_0.0.0.0_0-0.0.0.0_0"[11] xx.xxx.xxx.xx #22: STATE_MAIN_R2: sent MR2, expecting MI3
Dec  5 10:21:35 defendo pluto[29609]: "xauth_0-iPhone_sn-sn_0.0.0.0_0-0.0.0.0_0"[11] xx.xxx.xxx.xx #22: ignoring informational payload IPSEC_INITIAL_CONTACT, msgid=00000000, length=28
Dec  5 10:21:35 defendo pluto[29609]: | ISAKMP Notification Payload
Dec  5 10:21:35 defendo pluto[29609]: |   00 00 00 1c  00 00 00 01  01 10 60 02
Dec  5 10:21:35 defendo pluto[29609]: "xauth_0-iPhone_sn-sn_0.0.0.0_0-0.0.0.0_0"[11] xx.xxx.xxx.xx #22: Main mode peer ID is ID_DER_ASN1_DN: 'C=XX, ST=XXXXXX, L=XXXXXXXx, O=XXXXXXXXXXXx, OU=XXXX, CN=XXXXXX, E=XXXXXXXXXXXXXXXXXXXXXXXXXX'
Dec  5 10:21:35 defendo pluto[29609]: "xauth_0-iPhone_sn-sn_0.0.0.0_0-0.0.0.0_0"[11] xx.xxx.xxx.xx #22: Warning: gntoid() failed to initaddr(): (null)
Dec  5 10:21:35 defendo pluto[29609]: "xauth_0-iPhone_sn-sn_0.0.0.0_0-0.0.0.0_0"[11] xx.xxx.xxx.xx #22: switched from "xauth_0-iPhone_sn-sn_0.0.0.0_0-0.0.0.0_0" to "xauth_0-iPhone_sn-sn_0.0.0.0_0-0.0.0.0_0"
Dec  5 10:21:35 defendo pluto[29609]: "xauth_0-iPhone_sn-sn_0.0.0.0_0-0.0.0.0_0"[12] xx.xxx.xxx.xx #22: deleting connection "xauth_0-iPhone_sn-sn_0.0.0.0_0-0.0.0.0_0" instance with peer xx.xxx.xxx.xx {isakmp=#0/ipsec=#0}
Dec  5 10:21:35 defendo pluto[29609]: "xauth_0-iPhone_sn-sn_0.0.0.0_0-0.0.0.0_0"[12] xx.xxx.xxx.xx #22: I am sending my cert
Dec  5 10:21:35 defendo pluto[29609]: "xauth_0-iPhone_sn-sn_0.0.0.0_0-0.0.0.0_0"[12] xx.xxx.xxx.xx #22: transition from state STATE_MAIN_R2 to state STATE_MAIN_R3
Dec  5 10:21:35 defendo pluto[29609]: "xauth_0-iPhone_sn-sn_0.0.0.0_0-0.0.0.0_0"[12] xx.xxx.xxx.xx #22: new NAT mapping for #22, was xx.xxx.xxx.xx:61435, now xx.xxx.xxx.xx:61436
Dec  5 10:21:35 defendo pluto[29609]: "xauth_0-iPhone_sn-sn_0.0.0.0_0-0.0.0.0_0"[12] xx.xxx.xxx.xx #22: STATE_MAIN_R3: sent MR3, ISAKMP SA established {auth=RSA_SIG cipher=aes_256 prf=sha group=MODP1536}
Dec  5 10:21:35 defendo pluto[29609]: "xauth_0-iPhone_sn-sn_0.0.0.0_0-0.0.0.0_0"[12] xx.xxx.xxx.xx #22: XAUTH: Sending XAUTH Login/Password Request
Dec  5 10:21:35 defendo pluto[29609]: "xauth_0-iPhone_sn-sn_0.0.0.0_0-0.0.0.0_0"[12] xx.xxx.xxx.xx #22: XAUTH: Sending Username/Password request (XAUTH_R0)
Dec  5 10:22:05 defendo pluto[29609]: "xauth_0-iPhone_sn-sn_0.0.0.0_0-0.0.0.0_0"[12] xx.xxx.xxx.xx #22: received Delete SA payload: deleting ISAKMP State #22
Dec  5 10:22:05 defendo pluto[29609]: "xauth_0-iPhone_sn-sn_0.0.0.0_0-0.0.0.0_0"[12] xx.xxx.xxx.xx: deleting connection "xauth_0-iPhone_sn-sn_0.0.0.0_0-0.0.0.0_0" instance with peer xx.xxx.xxx.xx {isakmp=#0/ipsec=#0}
-------------- next part --------------
A non-text attachment was scrubbed...
Name: libreswan-3.9-xauth_delay.patch
Type: text/x-patch
Size: 511 bytes
Desc: not available
URL: <https://lists.libreswan.org/pipermail/swan-dev/attachments/20141205/2ce044cb/attachment.bin>


More information about the Swan-dev mailing list