Bug 1654037

There are messages

  CHAP authentication failed

but it's unclear why.



Note that you may be able to enable more debug logging of the plugin, by setting

  sudo nmcli general logging level TRACE domains ALL,VPN_PLUGIN:TRACE

and re-activate the profile. Note that the logfile may contain private data (beware before posting).

Does that trace logging give more indication of the error?

Created attachment 1510469 [details]
log with debug information

(In reply to Thomas Haller from comment #1)
> There are messages
> 
>   CHAP authentication failed
> 
> but it's unclear why.

I saw that, but as you say "it's unclear why".

> Note that you may be able to enable more debug logging of the plugin, by
> setting
> 
>   sudo nmcli general logging level TRACE domains ALL,VPN_PLUGIN:TRACE

Aaah. Thank you, I didn't know that one.

I did as you suggested and also added the pppd "dump" option.
In the first round the additional data suggested that the login is not
working. I contacted my VPN provider, they "refreshed" my login and
amazingly, the CHAP now succeeds. Instead, now comes the message
"MPPE required, but MS-CHAP[v2] nor EAP-TLS auth are performed."
and that's as far as we get. I interpret it as the provider not
having MS-CHAPv2 available, but if there is any other interpretation
I would like to hear it.

I am attaching a copy of the (sanitized) log; the critical message
is flagged with "problem".

And yes, it is urgent, but I am dependent on getting an answer from
my provider, so there is a delay involved...

My provider is saying that on their side MSCHAPv2 is OK.
They recommended to switch off the MPPE and after it gets
switched off the connection works. Of course it is now not
encrypted, but at least it runs.

So the next question is - what's wrong with the new MPPE?
Since I have to find where the break is: which modules are
involved? ppp, NetworkManager, kernel-modules - what else?

And "severity" can scale down to High.

The connection did run OK with:
kernel-4.18.16-200.fc28.x86_64
kernel-modules-4.18.16-200.fc28.x86_64
NetworkManager-pptp-1:1.2.8-1.fc28.x86_64
NetworkManager-ppp-1:1.10.12-1.fc28.x86_64
NetworkManager-1:1.10.12-1.fc28.x86_64
pptp-1.10.0-3.fc28.x86_64                                        
ppp-2.4.7-22.fc28.x86_64                                         

Stopped running with:
kernel-4.19.4-300.fc29.x86_64
kernel-modules-4.19.4-300.fc29.x86_64
NetworkManager-pptp-1:1.2.8-1.fc29.x86_64
NetworkManager-ppp-1:1.12.4-2.fc29.x86_64
NetworkManager-1:1.12.4-2.fc29.x86_64
pptp-1.10.0-5.fc29.x86_64                                        
ppp-2.4.7-28.fc29.x86_64                                         

New with fc29 came network-scripts-ppp-2.4.7-28.fc29.x86_64
I don't know if it changes anything.

Latest upgrade didn't change much. Let me show you some tests.
On a fresh boot the situation is as follows:

  current kernel: 4.19.5-300.fc29.x86_64
 
  current modules: 
  kernel-4.19.5-300.fc29.x86_64
  kernel-modules-4.19.5-300.fc29.x86_64
  NetworkManager-1.12.4-2.fc29.x86_64
  NetworkManager-pptp-1.2.8-1.fc29.x86_64
  NetworkManager-ppp-1.12.4-2.fc29.x86_64
  pptp-1.10.0-5.fc29.x86_64
  ppp-2.4.7-28.fc29.x86_64

  current kernel config has: CONFIG_PPP_MPPE=m

  modprobe finds: "alias ppp_compress_18 ppp_mppe
  "

  lsmod on ppp finds: ""

  lsmod on pptp finds: ""

  lsmod on mppe finds: ""

  dry run to load ppp_compress_18:
  insmod /lib/modules/4.19.5-300.fc29.x86_64/kernel/drivers/net/slip/slhc.ko.xz 
  insmod /lib/modules/4.19.5-300.fc29.x86_64/kernel/drivers/net/ppp/
         ppp_generic.ko.xz 
  insmod /lib/modules/4.19.5-300.fc29.x86_64/kernel/drivers/net/ppp/
         ppp_mppe.ko.xz 

Tried to load the full connection and failed. The changes after
the failure are as follows:

  lsmod on ppp finds: "ppp_async              20480  0
  ppp_generic            45056  1 ppp_async
  slhc                   16384  1 ppp_generic
  "

  lsmod on pptp finds: "nf_conntrack_pptp      16384  0
  nf_conntrack_proto_gre    16384  1 nf_conntrack_pptp
  nf_conntrack          163840  4 xt_conntrack,xt_state,nf_conntrack_pptp,
                                  nf_conntrack_proto_gre
  "

  lsmod on mppe finds: ""

  dry run to load ppp_compress_18:
  insmod /lib/modules/4.19.5-300.fc29.x86_64/kernel/drivers/net/ppp/
         ppp_mppe.ko.xz 

It looks like the system didn't even try to load the mppe kernel module.
I load it manually:

# modprobe --first-time ppp_compress_18

and get now 

  lsmod on mppe finds: "ppp_mppe               20480  0
  ppp_generic            45056  2 ppp_mppe,ppp_async
  "

  dry run to load ppp_compress_18:
  modprobe: ERROR: could not insert 'ppp_mppe': Module already in kernel

Of course the startup of the connection fails as before.
Without MPPE it works OK.

I tried today to look at the source, but it turns out it is
not available.

The current ppp version is ppp-2.4.7-28.fc29.x86_64, but the
latest source version I could find is ppp-2.4.7-26.fc29.src.rpm

And interestingly enough the error message

  MPPE required, but MS-CHAP[v2] nor EAP-TLS auth are performed.

which kills the connection effort, is NOT in the source. (Yes,
I do not understand it either, the text doesn't seem to be correct.)

The working hypothesis is now: change from 2.4.7-26 to 2.4.7-28
is the culprit.

Anybody listening?

Executive Summary: It's my VPN provider, NOT any part of the OS.

Details:

After I downgraded from 2.4.7-28 to 2.4.7-26, I discovered that the
message is still there. It turns out that
a) It is not in the source as such, but in a patch which I did not check
   and
b) The meaning is "MPPE required, but neither MS-CHAP[v2] nor EAP-TLS
   auth are performed."

After looking at the source for the 2.4.7-22 version which used to
function, I did a diff over the whole tree and discovered, that (apart
from ppp.spec) the distribution trees for -26 and -22 are identical.

I found one machine which actually still had an OS version which
hasn't been updated for about a year. Using it to connect to the
VPN failed in the same way as with the current updates. I can see
only one explanation: it is NOT a fault in the system, but something
must have been changed in the provider's setup.