With a little side of applesauce...

Tuesday, August 17, 2010

PPTP - NetworkManager config issue with MPPE encryption?

I just found this VPN issue when connecting Ubuntu 10.04 LTS to a POPTOP PPTP server. I'm not sure what is causing it exactly, but it appears that when setting NetworkManager->VPN Name->Advanced->Use Point-to-Point Encryption (MPPE) to 'All Available (default)', the connection handshake will not check 'All Available' encryption levels:
Aug 17 20:51:05 mycomputer NetworkManager: <info>  Starting VPN service 'org.freedesktop.NetworkManager.pptp'...
Aug 17 20:51:05 mycomputer NetworkManager: <info> VPN service 'org.freedesktop.NetworkManager.pptp' started (org.freedesktop.NetworkManager.pptp), PID 2294
Aug 17 20:51:05 mycomputer NetworkManager: <info> VPN service 'org.freedesktop.NetworkManager.pptp' just appeared, activating connections
Aug 17 20:51:05 mycomputer NetworkManager: <info> VPN plugin state changed: 1
Aug 17 20:51:05 mycomputer NetworkManager: <info> VPN plugin state changed: 3
Aug 17 20:51:05 mycomputer NetworkManager: <info> VPN connection 'stolaf' (Connect) reply received.
Aug 17 20:51:05 mycomputer pppd[2296]: Plugin /usr/lib/pppd/2.4.5//nm-pptp-pppd-plugin.so loaded.
Aug 17 20:51:05 mycomputer pppd[2296]: pppd 2.4.5 started by root, uid 0
Aug 17 20:51:05 mycomputer pppd[2296]: Using interface ppp0
Aug 17 20:51:05 mycomputer pppd[2296]: Connect: ppp0 <--> /dev/pts/1
Aug 17 20:51:05 mycomputer NetworkManager: SCPlugin-Ifupdown: devices added (path: /sys/devices/virtual/net/ppp0, iface: ppp0)
Aug 17 20:51:05 mycomputer NetworkManager: SCPlugin-Ifupdown: device added (path: /sys/devices/virtual/net/ppp0, iface: ppp0): no ifupdown configuration found.
Aug 17 20:51:05 mycomputer pptp[2301]: nm-pptp-service-2294 log[main:pptp.c:314]: The synchronous pptp option is NOT activated
Aug 17 20:51:05 mycomputer pptp[2314]: nm-pptp-service-2294 log[ctrlp_rep:pptp_ctrl.c:251]: Sent control packet type is 1 'Start-Control-Connection-Request'
Aug 17 20:51:05 mycomputer pptp[2314]: nm-pptp-service-2294 log[ctrlp_disp:pptp_ctrl.c:739]: Received Start Control Connection Reply
Aug 17 20:51:05 mycomputer pptp[2314]: nm-pptp-service-2294 log[ctrlp_disp:pptp_ctrl.c:773]: Client connection established.
Aug 17 20:51:06 mycomputer pptp[2314]: nm-pptp-service-2294 log[ctrlp_rep:pptp_ctrl.c:251]: Sent control packet type is 7 'Outgoing-Call-Request'
Aug 17 20:51:06 mycomputer pptp[2314]: nm-pptp-service-2294 log[ctrlp_disp:pptp_ctrl.c:858]: Received Outgoing Call Reply.
Aug 17 20:51:06 mycomputer pptp[2314]: nm-pptp-service-2294 log[ctrlp_disp:pptp_ctrl.c:897]: Outgoing call established (call ID 0, peer's call ID 2688).
Aug 17 20:51:09 mycomputer pptp[2301]: nm-pptp-service-2294 log[decaps_gre:pptp_gre.c:414]: buffering packet 5 (expecting 4, lost or reordered)
Aug 17 20:51:09 mycomputer pppd[2296]: CHAP authentication succeeded
Aug 17 20:51:10 mycomputer pppd[2296]: LCP terminated by peer (MPPE required but peer negotiation failed)
Aug 17 20:51:10 mycomputer pptp[2314]: nm-pptp-service-2294 log[pptp_read_some:pptp_ctrl.c:544]: read returned zero, peer has closed
Aug 17 20:51:10 mycomputer pptp[2314]: nm-pptp-service-2294 log[callmgr_main:pptp_callmgr.c:258]: Closing connection (shutdown)
Aug 17 20:51:10 mycomputer pptp[2314]: nm-pptp-service-2294 log[ctrlp_rep:pptp_ctrl.c:251]: Sent control packet type is 12 'Call-Clear-Request'
Aug 17 20:51:10 mycomputer pptp[2314]: nm-pptp-service-2294 log[pptp_read_some:pptp_ctrl.c:544]: read returned zero, peer has closed
Aug 17 20:51:10 mycomputer pptp[2314]: nm-pptp-service-2294 log[call_callback:pptp_callmgr.c:79]: Closing connection (call state)
Aug 17 20:51:10 mycomputer pppd[2296]: Modem hangup
Aug 17 20:51:10 mycomputer pppd[2296]: Connection terminated.
Aug 17 20:51:10 mycomputer NetworkManager: <info> VPN plugin failed: 1
Aug 17 20:51:10 mycomputer NetworkManager: SCPlugin-Ifupdown: devices removed (path: /sys/devices/virtual/net/ppp0, iface: ppp0)
Aug 17 20:51:10 mycomputer pppd[2296]: Exit.
Aug 17 20:51:10 mycomputer NetworkManager: <info> VPN plugin failed: 1
Aug 17 20:51:10 mycomputer NetworkManager: <info> VPN plugin failed: 1
Aug 17 20:51:10 mycomputer NetworkManager: <info> VPN plugin state changed: 6
Aug 17 20:51:10 mycomputer NetworkManager: <info> VPN plugin state change reason: 0
Aug 17 20:51:10 mycomputer NetworkManager: <WARN> connection_state_changed(): Could not process the request because no VPN connection was active.
Aug 17 20:51:10 mycomputer NetworkManager: <info> Policy set 'Auto blah' (wlan0) as default for routing and DNS.

I actually succeed with my connection when explicitly setting the value to '128-bit (most secure)':
Aug 17 20:56:46 mycomputer NetworkManager: <debug> [1282096606.002379] ensure_killed(): waiting for vpn service pid 2371 to exit
Aug 17 20:56:46 mycomputer NetworkManager: <debug> [1282096606.002579] ensure_killed(): vpn service pid 2371 cleaned up
Aug 17 20:57:14 mycomputer NetworkManager: <info> Starting VPN service 'org.freedesktop.NetworkManager.pptp'...
Aug 17 20:57:14 mycomputer NetworkManager: <info> VPN service 'org.freedesktop.NetworkManager.pptp' started (org.freedesktop.NetworkManager.pptp), PID 2396
Aug 17 20:57:14 mycomputer NetworkManager: <info> VPN service 'org.freedesktop.NetworkManager.pptp' just appeared, activating connections
Aug 17 20:57:14 mycomputer NetworkManager: <info> VPN plugin state changed: 1
Aug 17 20:57:14 mycomputer NetworkManager: <info> VPN plugin state changed: 3
Aug 17 20:57:14 mycomputer NetworkManager: <info> VPN connection 'stolaf' (Connect) reply received.
Aug 17 20:57:14 mycomputer pppd[2398]: Plugin /usr/lib/pppd/2.4.5//nm-pptp-pppd-plugin.so loaded.
Aug 17 20:57:14 mycomputer pppd[2398]: pppd 2.4.5 started by root, uid 0
Aug 17 20:57:14 mycomputer pppd[2398]: Using interface ppp0
Aug 17 20:57:14 mycomputer pppd[2398]: Connect: ppp0 <--> /dev/pts/1
Aug 17 20:57:14 mycomputer NetworkManager: SCPlugin-Ifupdown: devices added (path: /sys/devices/virtual/net/ppp0, iface: ppp0)
Aug 17 20:57:14 mycomputer NetworkManager: SCPlugin-Ifupdown: device added (path: /sys/devices/virtual/net/ppp0, iface: ppp0): no ifupdown configuration found.
Aug 17 20:57:14 mycomputer pptp[2403]: nm-pptp-service-2396 log[main:pptp.c:314]: The synchronous pptp option is NOT activated
Aug 17 20:57:14 mycomputer pptp[2416]: nm-pptp-service-2396 log[ctrlp_rep:pptp_ctrl.c:251]: Sent control packet type is 1 'Start-Control-Connection-Request'
Aug 17 20:57:14 mycomputer pptp[2416]: nm-pptp-service-2396 log[ctrlp_disp:pptp_ctrl.c:739]: Received Start Control Connection Reply
Aug 17 20:57:14 mycomputer pptp[2416]: nm-pptp-service-2396 log[ctrlp_disp:pptp_ctrl.c:773]: Client connection established.
Aug 17 20:57:15 mycomputer pptp[2416]: nm-pptp-service-2396 log[ctrlp_rep:pptp_ctrl.c:251]: Sent control packet type is 7 'Outgoing-Call-Request'
Aug 17 20:57:16 mycomputer pptp[2416]: nm-pptp-service-2396 log[ctrlp_disp:pptp_ctrl.c:858]: Received Outgoing Call Reply.
Aug 17 20:57:16 mycomputer pptp[2416]: nm-pptp-service-2396 log[ctrlp_disp:pptp_ctrl.c:897]: Outgoing call established (call ID 0, peer's call ID 3072).
Aug 17 20:57:19 mycomputer pppd[2398]: CHAP authentication succeeded
Aug 17 20:57:19 mycomputer pppd[2398]: MPPE 128-bit stateless compression enabled
...

Some config info is:
speeves@mycomputer:~$ dpkg -l | grep ppp | grep Point-to-Point
ii ppp 2.4.5~git20081126t100229-0ubuntu3 Point-to-Point Protocol (PPP) - daemon
speeves@mycomputer:~$ uname -a
Linux mycomputer 2.6.32-24-generic #39-Ubuntu SMP Wed Jul 28 06:07:29 UTC 2010 i686 GNU/Linux

I'm not sure if this has to do with our POPTOP configuration, a kernel upgrade, or my ppp daemon, so am not submitting this as a bug.

2 comments:

Shannon Eric Peevey said...

Possibly related:
https://bugs.launchpad.net/ubuntu/+source/network-manager-pptp/+bug/346768

Shannon Eric Peevey said...

This debugging info is helpful:
http://pptpclient.sourceforge.net/howto-diagnosis.phtml#mppe_rbpnf