PPTP VPN doesn't work out of the box - nf_conntrack_pptp missing

[Ante Karamatić]

PPTP based VPN doesn't work out of the box on Focal Fossa. From syslog:

Jan 29 19:41:35 thinkpad pppd[8734]: Plugin /usr/lib/pppd/2.4.7/nm-pptp-pppd-plugin.so loaded.
Jan 29 19:41:35 thinkpad NetworkManager[8734]: Plugin /usr/lib/pppd/2.4.7/nm-pptp-pppd-plugin.so loaded.
Jan 29 19:41:35 thinkpad pptp[8739]: nm-pptp-service-8722 log[main:pptp.c:353]: The synchronous pptp option is NOT activated
Jan 29 19:41:35 thinkpad pptp[8750]: nm-pptp-service-8722 log[ctrlp_rep:pptp_ctrl.c:258]: Sent control packet type is 1 'Start-Control-Connection-Request'
Jan 29 19:41:35 thinkpad pptp[8750]: nm-pptp-service-8722 log[ctrlp_disp:pptp_ctrl.c:781]: Received Start Control Connection Reply
Jan 29 19:41:35 thinkpad pptp[8750]: nm-pptp-service-8722 log[ctrlp_disp:pptp_ctrl.c:815]: Client connection established.
Jan 29 19:41:36 thinkpad pptp[8750]: nm-pptp-service-8722 log[ctrlp_rep:pptp_ctrl.c:258]: Sent control packet type is 7 'Outgoing-Call-Request'
Jan 29 19:41:36 thinkpad pptp[8750]: nm-pptp-service-8722 log[ctrlp_disp:pptp_ctrl.c:900]: Received Outgoing Call Reply.
Jan 29 19:41:36 thinkpad pptp[8750]: nm-pptp-service-8722 log[ctrlp_disp:pptp_ctrl.c:938]: Outgoing call established (call ID 44616, peer's call ID 0).
Jan 29 19:42:03 thinkpad pptp[8750]: nm-pptp-service-8722 log[ctrlp_disp:pptp_ctrl.c:976]: Call disconnect notification received (call id 44616)
Jan 29 19:42:06 thinkpad pptp[8750]: nm-pptp-service-8722 log[logecho:pptp_ctrl.c:719]: Echo Request received.
Jan 29 19:42:06 thinkpad pptp[8750]: nm-pptp-service-8722 log[ctrlp_rep:pptp_ctrl.c:258]: Sent control packet type is 6 'Echo-Reply'
Jan 29 19:42:06 thinkpad pptp[8739]: nm-pptp-service-8722 warn[decaps_hdlc:pptp_gre.c:226]: short read (-1): Input/output error
Jan 29 19:42:06 thinkpad pptp[8739]: nm-pptp-service-8722 warn[decaps_hdlc:pptp_gre.c:238]: pppd may have shutdown, see pppd log
Jan 29 19:42:06 thinkpad pppd[8734]: Child process /usr/sbin/pptp 161.53.xxx.yyy --nolaunchpppd --loglevel 0 --logstring nm-pptp-service-8722 (pid 8737) terminated with signal 15
Jan 29 19:42:06 thinkpad NetworkManager[8734]: Child process /usr/sbin/pptp 161.53.xxx.yyy --nolaunchpppd --loglevel 0 --logstring nm-pptp-service-8722 (pid 8737) terminated with signal 15
Jan 29 19:42:06 thinkpad pptp[8750]: nm-pptp-service-8722 log[callmgr_main:pptp_callmgr.c:245]: Closing connection (unhandled)
Jan 29 19:42:06 thinkpad pptp[8750]: nm-pptp-service-8722 log[ctrlp_rep:pptp_ctrl.c:258]: Sent control packet type is 12 'Call-Clear-Request'
Jan 29 19:42:06 thinkpad pptp[8750]: nm-pptp-service-8722 log[call_callback:pptp_callmgr.c:84]: Closing connection (call state)

Once nf_conntrack_pptp kernel module is loaded, VPN connection succeeds:

Jan 29 19:44:02 thinkpad pppd[10166]: Plugin /usr/lib/pppd/2.4.7/nm-pptp-pppd-plugin.so loaded.
Jan 29 19:44:02 thinkpad NetworkManager[10166]: Plugin /usr/lib/pppd/2.4.7/nm-pptp-pppd-plugin.so loaded.
Jan 29 19:44:02 thinkpad pptp[10170]: nm-pptp-service-10156 log[main:pptp.c:353]: The synchronous pptp option is NOT activated
Jan 29 19:44:02 thinkpad pptp[10183]: nm-pptp-service-10156 log[ctrlp_rep:pptp_ctrl.c:258]: Sent control packet type is 1 'Start-Control-Connection-Request'
Jan 29 19:44:02 thinkpad pptp[10183]: nm-pptp-service-10156 log[ctrlp_disp:pptp_ctrl.c:781]: Received Start Control Connection Reply
Jan 29 19:44:02 thinkpad pptp[10183]: nm-pptp-service-10156 log[ctrlp_disp:pptp_ctrl.c:815]: Client connection established.
Jan 29 19:44:03 thinkpad pptp[10183]: nm-pptp-service-10156 log[ctrlp_rep:pptp_ctrl.c:258]: Sent control packet type is 7 'Outgoing-Call-Request'
Jan 29 19:44:03 thinkpad pptp[10183]: nm-pptp-service-10156 log[ctrlp_disp:pptp_ctrl.c:900]: Received Outgoing Call Reply.
Jan 29 19:44:03 thinkpad pptp[10183]: nm-pptp-service-10156 log[ctrlp_disp:pptp_ctrl.c:938]: Outgoing call established (call ID 61223, peer's call ID 0).

[Sebastien Bacher (seb128)]

Thank you for your bug report. Is that issue new to focal? Could you add a 'journalctl -b 0' log after triggering the error?

The code does
 char *conntrack_module[] = { "/sbin/modprobe", "nf_conntrack_pptp", NULL };
 if (!g_spawn_sync (NULL, conntrack_module, NULL, 0, NULL, NULL, NULL, NULL, NULL, &error)) {
  _LOGW ("modprobing nf_conntrack_pptp failed: %s", error->message);

so it should either load the module or print an error...

[Ante Karamatić (ivoks)]

Hi Seb

It seems I can't reproduce the problem any more. I now can clearly see nf_conntrack_pptp loading when I try to establish PPTP connection in NM. I have no idea how this changed. Thank you for looking into it, I'll close the bug and reopen it occurs again.