Can log into Yosemite server (4.0) VPN service with a Mavericks client, but not Yosemite client
Sever Info:
Yosemite Server 4.0 running on a late 2009 Mac Mini with 8 GB RAM with vpnd service enabled
The server was upgraded to Yosemite - not clean install - this may not matter (see below)
Airport extreme router with standard VPN UDP ports for L2TP forwarded to server (500, 1701, 4500)
Client info:
MB Air 13" early 2014 with 8 GB RAM
Yosemite
Mavericks 10.9.5 running as a Parallels virtual machine (don't ask - I need it to run an app for work that is not yet compatible with Yosemite)
OD service is NOT running - no VPN connections ever occurred from ANY client with this service running - OD is not needed in my case fortunately
With the OD service off, I can connect via the Mavericks virtual machine just fine, but not with Yosemite. With Yosemite, the ppp connection appears to occur, but server config requests appear to fall on deaf ears (client side doesn't appear to respond) until the connection times out. Can't figure out what triggers the client response to a server config request. Client side complains about no route to host and IP addresses don't get assigned to the connection.
The connection happens successfully in an eyeblink with the Mavericks client. Same username/password/shared secret in both instances.
Tried a generated .vpnconfig from the server, this also did not work.
It's possible that it is an auth problem, but can't figure out how the process occurs or what may be going wrong. There does not seem to be an obvious way to increase the granularity of the logging such that it might give other hints - at least that I can find. I found plenty of references to VPN issues when people upgraded from Mountain Lion to Mavericks as well as work arounds for this. I tried the most promising looking of those - no love. I reverted everything back to stock install since I could at least connect with Mavericks.
If log entries would be helpful, they are included below. I've stared at them long enough - perhaps a new set of eyes can provide a hint.
In addition, I can find no documentation regarding the VPN service in Yosemite server so as to get a clue as to whether there have been changes in racoon since Mavericks.
Thanks in advance for any suggestions. I would be glad to supply any other info needed for an accurate diagnosis 🙂 .
Pat
==
Regarding the Yosemite client connection in the Yosemite server VPN Service log:
2014-10-21 12:18:30 MDT | Incoming call... Address given to client = 192.168.1.228 |
Tue Oct 21 12:18:30 2014 : Directory Services Authentication plugin initialized
Tue Oct 21 12:18:30 2014 : Directory Services Authorization plugin initialized
Tue Oct 21 12:18:30 2014 : publish_entry SCDSet() failed: Success!
Tue Oct 21 12:18:30 2014 : publish_entry SCDSet() failed: Success!
Tue Oct 21 12:18:30 2014 : publish_entry SCDSet() failed: Success!
Tue Oct 21 12:18:30 2014 : L2TP incoming call in progress from 'my.dotted.quad.address'...
Tue Oct 21 12:18:30 2014 : L2TP received SCCRQ
Tue Oct 21 12:18:30 2014 : L2TP sent SCCRP
Tue Oct 21 12:18:30 2014 : L2TP received SCCCN
Tue Oct 21 12:18:30 2014 : L2TP received ICRQ
Tue Oct 21 12:18:30 2014 : L2TP sent ICRP
Tue Oct 21 12:18:30 2014 : L2TP received ICCN
Tue Oct 21 12:18:30 2014 : L2TP connection established.
Tue Oct 21 12:18:30 2014 : using link 0
Tue Oct 21 12:18:30 2014 : Using interface ppp0
Tue Oct 21 12:18:30 2014 : Connect: ppp0 <--> socket[34:18]
Tue Oct 21 12:18:30 2014 : sent [LCP ConfReq id=0x1 <asyncmap 0x0> <auth chap MS-v2> <magic 0x93542b1> <pcomp> <accomp>]
Tue Oct 21 12:18:33 2014 : sent [LCP ConfReq id=0x1 <asyncmap 0x0> <auth chap MS-v2> <magic 0x93542b1> <pcomp> <accomp>]
Tue Oct 21 12:18:36 2014 : sent [LCP ConfReq id=0x1 <asyncmap 0x0> <auth chap MS-v2> <magic 0x93542b1> <pcomp> <accomp>]
Tue Oct 21 12:18:39 2014 : sent [LCP ConfReq id=0x1 <asyncmap 0x0> <auth chap MS-v2> <magic 0x93542b1> <pcomp> <accomp>]
Tue Oct 21 12:18:42 2014 : sent [LCP ConfReq id=0x1 <asyncmap 0x0> <auth chap MS-v2> <magic 0x93542b1> <pcomp> <accomp>]
Tue Oct 21 12:18:45 2014 : sent [LCP ConfReq id=0x1 <asyncmap 0x0> <auth chap MS-v2> <magic 0x93542b1> <pcomp> <accomp>]
Tue Oct 21 12:18:48 2014 : sent [LCP ConfReq id=0x1 <asyncmap 0x0> <auth chap MS-v2> <magic 0x93542b1> <pcomp> <accomp>]
Tue Oct 21 12:18:51 2014 : sent [LCP ConfReq id=0x1 <asyncmap 0x0> <auth chap MS-v2> <magic 0x93542b1> <pcomp> <accomp>]
Tue Oct 21 12:18:54 2014 : sent [LCP ConfReq id=0x1 <asyncmap 0x0> <auth chap MS-v2> <magic 0x93542b1> <pcomp> <accomp>]
Tue Oct 21 12:18:57 2014 : sent [LCP ConfReq id=0x1 <asyncmap 0x0> <auth chap MS-v2> <magic 0x93542b1> <pcomp> <accomp>]
Tue Oct 21 12:19:00 2014 : LCP: timeout sending Config-Requests
Tue Oct 21 12:19:00 2014 : Connection terminated.
Tue Oct 21 12:19:00 2014 : L2TP disconnecting...
Tue Oct 21 12:19:00 2014 : L2TP sent CDN
Tue Oct 21 12:19:00 2014 : L2TP sent StopCCN
Tue Oct 21 12:19:00 2014 : L2TP disconnected
2014-10-21 12:19:00 MDT | --> Client with address = 192.168.1.228 has hungup |
==
Client side log for this connection using the Yosemite client:
Tue Oct 21 14:32:08 2014 : publish_entry SCDSet() failed: Success!
Tue Oct 21 14:32:08 2014 : publish_entry SCDSet() failed: Success!
Tue Oct 21 14:32:08 2014 : L2TP connecting to server 'myserver.com' (my.dotted.quad.address)...
Tue Oct 21 14:32:08 2014 : IPSec connection started
Tue Oct 21 14:32:09 2014 : IPSec connection established
Tue Oct 21 14:32:10 2014 : L2TP connection established.
Tue Oct 21 14:32:10 2014 : L2TP set port-mapping for en0, interface: 4, protocol: 0, privatePort: 0
Tue Oct 21 14:32:10 2014 : Using interface ppp0
Tue Oct 21 14:32:10 2014 : Connect: ppp0 <--> socket[34:18]
Tue Oct 21 14:32:10 2014 : L2TP port-mapping for en0, interfaceIndex: 0, Protocol: None, Private Port: 0, Public Address: 3fe4b3e8, Public Port: 0, TTL: 0.
Tue Oct 21 14:32:10 2014 : L2TP port-mapping for en0 inconsistent. is Connected: 1, Previous interface: 4, Current interface 0
Tue Oct 21 14:32:10 2014 : L2TP port-mapping for en0 initialized. is Connected: 1, Previous publicAddress: (0), Current publicAddress 3fe4b3e8
Tue Oct 21 14:32:10 2014 : L2TP port-mapping for en0 fully initialized. Flagging up
Tue Oct 21 14:32:25 2014 : write: No route to host
Tue Oct 21 14:32:25 2014 : write: Host is down
Tue Oct 21 14:32:28 2014 : write: Host is down
Tue Oct 21 14:32:28 2014 : write: Host is down
Tue Oct 21 14:32:31 2014 : write: Host is down
Tue Oct 21 14:32:31 2014 : write: Host is down
Tue Oct 21 14:32:34 2014 : write: Host is down
Tue Oct 21 14:32:34 2014 : write: Host is down
Tue Oct 21 14:32:37 2014 : write: Host is down
Tue Oct 21 14:32:37 2014 : write: Host is down
Tue Oct 21 14:32:40 2014 : LCP: timeout sending Config-Requests
Tue Oct 21 14:32:40 2014 : Connection terminated.
Tue Oct 21 14:32:40 2014 : L2TP disconnecting...
Tue Oct 21 14:32:40 2014 : L2TP error sending CDN (Host is down)
Tue Oct 21 14:32:40 2014 : L2TP clearing port-mapping for en0
Tue Oct 21 14:32:40 2014 : L2TP disconnected
==
Pertinent client side log for connection of Mavericks client to Yosemite server:
Tue Oct 21 13:29:13 2014 : Connect: ppp0 <--> socket[34:18]
Tue Oct 21 13:29:13 2014 : L2TP port-mapping for en0, interfaceIndex: 0, Protocol: None, Private Port: 0, Public Address: 3fe4b3e8, Public Port: 0, TTL: 0.
Tue Oct 21 13:29:13 2014 : L2TP port-mapping for en0 inconsistent. is Connected: 1, Previous interface: 4, Current interface 0
Tue Oct 21 13:29:13 2014 : L2TP port-mapping for en0 initialized. is Connected: 1, Previous publicAddress: (0), Current publicAddress 3fe4b3e8
Tue Oct 21 13:29:13 2014 : L2TP port-mapping for en0 fully initialized. Flagging up
Tue Oct 21 13:29:21 2014 : local IP address 192.168.1.229
Tue Oct 21 13:29:21 2014 : remote IP address 192.168.1.2
Tue Oct 21 13:29:21 2014 : primary DNS address 192.168.1.2
Tue Oct 21 13:29:21 2014 : secondary DNS address 8.8.8.8
Tue Oct 21 13:29:21 2014 : l2tp_wait_input: Address added. previous interface setting (name: en0, address: 10.0.1.38), current interface setting (name: ppp0, family: PPP, address: 192.168.1.229, subnet: 255.255.255.0, destination: 192.168.1.2).
Tue Oct 21 13:29:21 2014 : Committed PPP store
Tue Oct 21 13:29:21 2014 : Committed PPP store
Tue Oct 21 13:52:32 2014 : [DISCONNECT]
Tue Oct 21 13:52:32 2014 : Hangup (SIGHUP)
Tue Oct 21 13:52:32 2014 : Connection terminated.
Tue Oct 21 13:52:32 2014 : Connect time 23.4 minutes.
Tue Oct 21 13:52:32 2014 : Sent 2674664 bytes, received 10680854 bytes.
Tue Oct 21 13:52:32 2014 : L2TP disconnecting...
Tue Oct 21 13:52:32 2014 : L2TP clearing port-mapping for en0
Tue Oct 21 13:52:32 2014 : L2TP disconnected
==
Regarding the Mavericks client connection in the Yosemite server VPN Service log:
2014-10-21 12:09:48 MDT Incoming call... Address given to client = 192.168.1.226
Tue Oct 21 12:09:48 2014 : Directory Services Authentication plugin initialized
Tue Oct 21 12:09:48 2014 : Directory Services Authorization plugin initialized
Tue Oct 21 12:09:48 2014 : publish_entry SCDSet() failed: Success!
Tue Oct 21 12:09:48 2014 : publish_entry SCDSet() failed: Success!
Tue Oct 21 12:09:48 2014 : publish_entry SCDSet() failed: Success!
Tue Oct 21 12:09:48 2014 : L2TP incoming call in progress from ‘my.dotted.quad.address’…
Tue Oct 21 12:09:48 2014 : L2TP received SCCRQ
Tue Oct 21 12:09:48 2014 : L2TP sent SCCRP
Tue Oct 21 12:09:48 2014 : L2TP received SCCCN
Tue Oct 21 12:09:48 2014 : L2TP received ICRQ
Tue Oct 21 12:09:48 2014 : L2TP sent ICRP
Tue Oct 21 12:09:49 2014 : L2TP received ICCN
Tue Oct 21 12:09:49 2014 : L2TP connection established.
Tue Oct 21 12:09:49 2014 : using link 0
Tue Oct 21 12:09:49 2014 : Using interface ppp0
Tue Oct 21 12:09:49 2014 : Connect: ppp0 <--> socket[34:18]
Tue Oct 21 12:09:49 2014 : sent [LCP ConfReq id=0x1 <asyncmap 0x0> <auth chap MS-v2> <magic 0x4bc40d9f> <pcomp> <accomp>]
Tue Oct 21 12:09:49 2014 : rcvd [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0x71598937> <pcomp> <accomp>]
Tue Oct 21 12:09:49 2014 : lcp_reqci: returning CONFACK.
Tue Oct 21 12:09:49 2014 : sent [LCP ConfAck id=0x1 <asyncmap 0x0> <magic 0x71598937> <pcomp> <accomp>]
Tue Oct 21 12:09:49 2014 : rcvd [LCP ConfAck id=0x1 <asyncmap 0x0> <auth chap MS-v2> <magic 0x4bc40d9f> <pcomp> <accomp>]
Tue Oct 21 12:09:49 2014 : sent [LCP EchoReq id=0x0 magic=0x4bc40d9f]
Tue Oct 21 12:09:49 2014 : sent [CHAP Challenge id=0x73 <074a110a5e0620296b1937345c34090e>, name = “myserver.private”]
Tue Oct 21 12:09:49 2014 : rcvd [LCP EchoReq id=0x0 magic=0x71598937]
Tue Oct 21 12:09:49 2014 : sent [LCP EchoRep id=0x0 magic=0x4bc40d9f]
Tue Oct 21 12:09:49 2014 : rcvd [LCP EchoRep id=0x0 magic=0x71598937]
Tue Oct 21 12:09:49 2014 : rcvd [CHAP Response id=0x73 <dfed1e41e1fb8c1132387c3d7792b1880000000000000000b2b163259cbe410aae792093680ba7 a89da3b46737c0d8d200>, name = "somelocaluser"]
Tue Oct 21 12:09:54 2014 : sent [CHAP Success id=0x73 "S=00EDB07933CE697641E2263A2A76386389512329 M=Access granted"]
Tue Oct 21 12:09:54 2014 : CHAP peer authentication succeeded for somelocaluser
Tue Oct 21 12:09:54 2014 : DSAccessControl plugin: User 'somelocaluser' authorized for access
Tue Oct 21 12:09:54 2014 : sent [IPCP ConfReq id=0x1 <addr 192.168.1.2>]
Tue Oct 21 12:09:54 2014 : sent [ACSCP ConfReq id=0x1]
Tue Oct 21 12:09:54 2014 : rcvd [CHAP Response id=0x73 <dfed1e41e1fb8c1132387c3d7792b1880000000000000000b2b163259cbe410aae792093680ba7 a89da3b46737c0d8d200>, name = "somelocaluser"]
Tue Oct 21 12:09:54 2014 : sent [CHAP Success id=0x73 "S=00EDB07933CE697641E2263A2A76386389512329 M=Access granted"]
Tue Oct 21 12:09:54 2014 : rcvd [IPCP ConfReq id=0x1 <addr 0.0.0.0> <ms-dns1 0.0.0.0> <ms-dns3 0.0.0.0>]
Tue Oct 21 12:09:54 2014 : ipcp: returning Configure-NAK
Tue Oct 21 12:09:54 2014 : sent [IPCP ConfNak id=0x1 <addr 192.168.1.226> <ms-dns1 192.168.1.2> <ms-dns3 8.8.8.8>]
Tue Oct 21 12:09:54 2014 : rcvd [IPV6CP ConfReq id=0x1 <addr fe80::021c:42ff:febf:bf66>]
Tue Oct 21 12:09:54 2014 : Unsupported protocol 0x8057 received
Tue Oct 21 12:09:54 2014 : sent [LCP ProtRej id=0x2 80 57 01 01 00 0e 01 0a 02 1c 42 ff fe bf bf 66]
Tue Oct 21 12:09:54 2014 : rcvd [ACSCP ConfReq id=0x1 <route vers 16777216> <domain vers 16777216>]
Tue Oct 21 12:09:54 2014 : sent [ACSCP ConfRej id=0x1 <route vers 16777216>]
Tue Oct 21 12:09:54 2014 : rcvd [IPCP ConfAck id=0x1 <addr 192.168.1.2>]
Tue Oct 21 12:09:54 2014 : rcvd [ACSCP ConfAck id=0x1]
Tue Oct 21 12:09:54 2014 : rcvd [IPCP ConfReq id=0x2 <addr 192.168.1.226> <ms-dns1 192.168.1.2> <ms-dns3 8.8.8.8>]
Tue Oct 21 12:09:54 2014 : ipcp: returning Configure-ACK
Tue Oct 21 12:09:54 2014 : sent [IPCP ConfAck id=0x2 <addr 192.168.1.226> <ms-dns1 192.168.1.2> <ms-dns3 8.8.8.8>]
Tue Oct 21 12:09:54 2014 : ipcp: up
Tue Oct 21 12:09:54 2014 : found interface en0 for proxy arp
Tue Oct 21 12:09:54 2014 : local IP address 192.168.1.2
Tue Oct 21 12:09:54 2014 : remote IP address 192.168.1.226
Tue Oct 21 12:09:54 2014 : Received acsp/dhcp dictionaries
Tue Oct 21 12:09:54 2014 : Received acsp/dhcp dictionaries
Tue Oct 21 12:09:54 2014 : l2tp_wait_input: Address added. previous interface setting (name: en0, address: 192.168.1.2), current interface setting (name: ppp0, family: PPP, address: 192.168.1.2, subnet: 255.255.255.0, destination: 192.168.1.226).
Tue Oct 21 12:09:54 2014 : rcvd [ACSCP ConfReq id=0x2 <domain vers 16777216>]
Tue Oct 21 12:09:54 2014 : sent [ACSCP ConfAck id=0x2 <domain vers 16777216>]
Tue Oct 21 12:09:54 2014 : Received protocol dictionaries
Tue Oct 21 12:09:54 2014 : Committed PPP store
Tue Oct 21 12:09:54 2014 : sent [ACSP data <payload len 24, packet seq 0, CI_DOMAINS, flags: START END REQUIRE-ACK>
<domain: name private>
<domain: name local>]
Tue Oct 21 12:09:54 2014 : rcvd [IP data <src addr 192.168.1.226> <dst addr 255.255.255.255> <BOOTP Request> <type INFORM> <client id 0x08000000010000> <parameters = 0x6 0x2c 0x2b 0x1 0xf9 0xf>]
Tue Oct 21 12:09:54 2014 : sent [IP data <src addr 192.168.1.2> <dst addr 192.168.1.226> <BOOTP Reply> <type ACK> <server id 0xc0a80102> <domain name "local">]
Tue Oct 21 12:09:57 2014 : sent [ACSP data <payload len 24, packet seq 0, CI_DOMAINS, flags: START END REQUIRE-ACK>
<domain: name private>
<domain: name local>]
Tue Oct 21 12:10:00 2014 : sent [ACSP data <payload len 24, packet seq 0, CI_DOMAINS, flags: START END REQUIRE-ACK>
<domain: name private>
<domain: name local>]
Tue Oct 21 12:10:03 2014 : sent [ACSP data <payload len 24, packet seq 0, CI_DOMAINS, flags: START END REQUIRE-ACK>
<domain: name private>
<domain: name local>]
Tue Oct 21 12:10:06 2014 : sent [ACSP data <payload len 24, packet seq 0, CI_DOMAINS, flags: START END REQUIRE-ACK>
<domain: name private>
<domain: name local>]
Tue Oct 21 12:10:09 2014 : sent [ACSP data <payload len 24, packet seq 0, CI_DOMAINS, flags: START END REQUIRE-ACK>
<domain: name private>
<domain: name local>]
Tue Oct 21 12:10:09 2014 : rcvd [LCP TermReq id=0x2 "User request"]
Tue Oct 21 12:10:09 2014 : LCP terminated by peer (User request)
Tue Oct 21 12:10:09 2014 : ipcp: down
Tue Oct 21 12:10:09 2014 : sent [LCP TermAck id=0x2]
Tue Oct 21 12:10:09 2014 : l2tp_wait_input: Address deleted. previous interface setting (name: en0, address: 192.168.1.2), deleted interface setting (name: ppp0, family: PPP, address: 192.168.1.2, subnet: 255.255.255.0, destination: 192.168.1.226).
Tue Oct 21 12:10:09 2014 : L2TP received CDN
Tue Oct 21 12:10:09 2014 : Connection terminated.
Tue Oct 21 12:10:09 2014 : Connect time 0.4 minutes.
Tue Oct 21 12:10:09 2014 : Sent 1003 bytes, received 646 bytes.
Tue Oct 21 12:10:09 2014 : L2TP disconnecting...
Tue Oct 21 12:10:09 2014 : L2TP disconnected
2014-10-21 12:10:09 MDT --> Client with address = 192.168.1.226 has hungup