MPD5 crashed - ASSERT "new == PHASE_ESTABLISH" failed: file "lcp.c", line 415

Selin · Oct 20, 2021

Hi

Some time ago my MPD5 VPN server started crashing periodically.
In the mpd.log I found the following records at the crash moment.

Code:

<...cut...>
Oct 20 05:12:13 VNP_Server mpd[337]: 0x255da1 <???> at /usr/local/sbin/mpd5
Oct 20 05:12:13 VNP_Server mpd[337]: 0x2781ce <???> at /usr/local/sbin/mpd5
Oct 20 05:12:13 VNP_Server mpd[337]: 0x278838 <???> at /usr/local/sbin/mpd5
Oct 20 05:12:13 VNP_Server mpd[337]: 0x26932a <???> at /usr/local/sbin/mpd5
Oct 20 05:12:13 VNP_Server mpd[337]: 0x2697e0 <???> at /usr/local/sbin/mpd5
Oct 20 05:12:13 VNP_Server mpd[337]: 0x27af8f <???> at /usr/local/sbin/mpd5
Oct 20 05:12:13 VNP_Server mpd[337]: 0x2825b7 <???> at /usr/local/sbin/mpd5
Oct 20 05:12:13 VNP_Server mpd[337]: 0x23e835 <???> at /usr/local/sbin/mpd5
Oct 20 05:12:13 VNP_Server mpd[337]: 0x2419d9 <???> at /usr/local/sbin/mpd5
Oct 20 05:12:13 VNP_Server mpd[337]: 0x268e2f <???> at /usr/local/sbin/mpd5
Oct 20 05:12:13 VNP_Server mpd[337]: 0x28b97c <???> at /usr/local/sbin/mpd5
Oct 20 05:12:13 VNP_Server mpd[337]: 0x28b378 <???> at /usr/local/sbin/mpd5
Oct 20 05:12:13 VNP_Server mpd[337]: ASSERT "new == PHASE_ESTABLISH" failed: file "lcp.c", line 415
Oct 20 05:12:13 VNP_Server mpd[337]: fatal error, exiting
<.../cut...>

Googling gives almost nothing - the only forum thread I found tells "just update the system", but I already have the latest 13.0-RELEASE with all ports updated.

13.0-RELEASE-p4 FreeBSD 13.0-RELEASE-p4 #0
mpd5-5.9_4

Kernel is GENERIC amd64 (original)
mpd5 port config - all options off

What should I do to prevent such crashes?

Thanks

Jose · Oct 20, 2021

File a bug with mpd?

MPD: FreeBSD PPP daemon / Bugs

sourceforge.net

Your log looks truncated, BTW.

Selin · Oct 20, 2021

Ok - will try to report a bug when will be sure this is not something I might do wrong.

As for the log...
Records above are regular mpd log - just 'connect'/'disconnect', etc. So I just skipped it.
Records below are about 'closing connections' - I guess it is due to shutting down the mpd5 service due to its crash.

Code:

<...cut...>
Oct 20 05:12:13 VNP_Server mpd[337]: [l_pptp-14] Accepting PPTP connection
Oct 20 05:12:13 VNP_Server mpd[337]: [l_pptp-14] Link: OPEN event
Oct 20 05:12:13 VNP_Server mpd[337]: [l_pptp-14] LCP: Open event
Oct 20 05:12:13 VNP_Server mpd[337]: [l_pptp-14] LCP: state change Initial --> Starting
Oct 20 05:12:13 VNP_Server mpd[337]: [l_pptp-14] LCP: LayerStart
Oct 20 05:12:13 VNP_Server mpd[337]: [l_pptp-14] PPTP: attaching to peer's outgoing call
Oct 20 05:12:13 VNP_Server mpd[337]: [l_pptp-14] Link: UP event
Oct 20 05:12:13 VNP_Server mpd[337]: [l_pptp-14] LCP: Up event
Oct 20 05:12:13 VNP_Server mpd[337]: [l_pptp-14] LCP: state change Starting --> Req-Sent
Oct 20 05:12:13 VNP_Server mpd[337]: [l_pptp-14] LCP: SendConfigReq #1
Oct 20 05:12:13 VNP_Server mpd[337]: [l_pptp-14]   ACFCOMP
Oct 20 05:12:13 VNP_Server mpd[337]: [l_pptp-14]   PROTOCOMP
Oct 20 05:12:13 VNP_Server mpd[337]: [l_pptp-14]   MRU 1460
Oct 20 05:12:13 VNP_Server mpd[337]: [l_pptp-14]   MAGICNUM 0x77539ea4
Oct 20 05:12:13 VNP_Server mpd[337]: [l_pptp-14]   AUTHPROTO CHAP MSOFTv2
Oct 20 05:12:13 VNP_Server mpd[337]: [l_pptp-14]   MP MRRU 2048
Oct 20 05:12:13 VNP_Server mpd[337]: [l_pptp-14]   MP SHORTSEQ
Oct 20 05:12:13 VNP_Server mpd[337]: [l_pptp-14]   ENDPOINTDISC [Magic] f7 73 6b 7e 55 71 6b 7e
Oct 20 05:12:13 VNP_Server mpd[337]: [l_Client_B] PPTP call terminated
Oct 20 05:12:13 VNP_Server mpd[337]: [l_Client_B] Link: DOWN event
Oct 20 05:12:13 VNP_Server mpd[337]: [l_Client_B] LCP: Down event
Oct 20 05:12:13 VNP_Server mpd[337]: [l_Client_B] LCP: state change Opened --> Starting
Oct 20 05:12:13 VNP_Server mpd[337]: 0x255da1 <???> at /usr/local/sbin/mpd5
Oct 20 05:12:13 VNP_Server mpd[337]: 0x2781ce <???> at /usr/local/sbin/mpd5
Oct 20 05:12:13 VNP_Server mpd[337]: 0x278838 <???> at /usr/local/sbin/mpd5
Oct 20 05:12:13 VNP_Server mpd[337]: 0x26932a <???> at /usr/local/sbin/mpd5
Oct 20 05:12:13 VNP_Server mpd[337]: 0x2697e0 <???> at /usr/local/sbin/mpd5
Oct 20 05:12:13 VNP_Server mpd[337]: 0x27af8f <???> at /usr/local/sbin/mpd5
Oct 20 05:12:13 VNP_Server mpd[337]: 0x2825b7 <???> at /usr/local/sbin/mpd5
Oct 20 05:12:13 VNP_Server mpd[337]: 0x23e835 <???> at /usr/local/sbin/mpd5
Oct 20 05:12:13 VNP_Server mpd[337]: 0x2419d9 <???> at /usr/local/sbin/mpd5
Oct 20 05:12:13 VNP_Server mpd[337]: 0x268e2f <???> at /usr/local/sbin/mpd5
Oct 20 05:12:13 VNP_Server mpd[337]: 0x28b97c <???> at /usr/local/sbin/mpd5
Oct 20 05:12:13 VNP_Server mpd[337]: 0x28b378 <???> at /usr/local/sbin/mpd5
Oct 20 05:12:13 VNP_Server mpd[337]: ASSERT "new == PHASE_ESTABLISH" failed: file "lcp.c", line 415
Oct 20 05:12:13 VNP_Server mpd[337]: fatal error, exiting
Oct 20 05:12:13 VNP_Server mpd[337]: [b_Client-A] IFACE: Close event
Oct 20 05:12:13 VNP_Server mpd[337]: [b_Client-A] IPCP: Close event
Oct 20 05:12:13 VNP_Server mpd[337]: [b_Client-A] CCP: Close event
Oct 20 05:12:13 VNP_Server mpd[337]: [b_Client-B] IFACE: Close event
Oct 20 05:12:13 VNP_Server mpd[337]: [b_Client-B] IPCP: Close event
Oct 20 05:12:13 VNP_Server mpd[337]: [b_Client-B] CCP: Close event
Oct 20 05:12:13 VNP_Server mpd[337]: [b_Client-C] IFACE: Close event
Oct 20 05:12:13 VNP_Server mpd[337]: [b_Client-C] IPCP: Close event
Oct 20 05:12:13 VNP_Server mpd[337]: [b_Client-C] IPCP: state change Opened --> Closing
Oct 20 05:12:13 VNP_Server mpd[337]: [b_Client-C] IPCP: SendTerminateReq #2
Oct 20 05:12:13 VNP_Server mpd[337]: [b_Client-C] IPCP: LayerDown
<.../cut...>

One more thing I forgot to mention - I'm also using Racoon to support L2TP/IPSec connections. If it might matter...
But its log has nothing unusual at all.

Will try to trace with full (debug-level) logs...

Jose · Oct 20, 2021

Selin said:
Ok - will try to report a bug when will be sure this is not something I might do wrong.

You should not be able to crash the server like this. You're definitely not doing anything wrong.

Selin · Oct 20, 2021

You are right...

If only there will be a stable case to reproduce this crash...
Or I can report a bug without 'steps to reproduce'?

Jose · Oct 20, 2021

It's worth a shot, but you might not get an answer without the steps. They do seem to be relatively responsive on their bug tracker, though.

Selin · Oct 21, 2021

Thanks

Registered a bug

MPD: FreeBSD PPP daemon / Bugs / #76 MPD5 crashed - ASSERT "new == PHASE_ESTABLISH" failed: file "lcp.c", line 415

sourceforge.net

BTW - another one anomaly is detected after updating to 5.9 - mpd5 halted every night at the same time (~04:51:10 EEST).
Not able to stop/restart mpd5 service after that. Killing doesn't help as well - service can be started, but it is not operational - nobody can connect.
Have to reboot the whole server (

covacat · Oct 21, 2021

try to unload ng modules, see if you can restart after (keep in mind it might panic if they are left in some unstable state)

Selin · Oct 21, 2021

I tried to close all ng interfaces
> ngctl shutdown ng0:
> ngctl shutdown ng1:
But it didn't help much - mpd5 (re)started, but connections are either always failed or connected, but without traffic.
It seems I'm missing something else...

covacat · Oct 21, 2021

mpd5 loads some ng_ kernel modules
like ng_ppp ng_ppp... ng_l2tp
try to kldunload them