Menu
▾
▴
1 Attachments
#76 MPD5 crashed - ASSERT "new == PHASE_ESTABLISH" failed: file "lcp.c", line 415
Some time ago my FreeBSD MPD5+Racoon VPN server started crashing periodically.
In the mpd.log I found the following records at the crash moment (sorry, but not "all" log setting was used that time).
<...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_pptp-15] PPTP call terminated
Oct 20 05:12:13 VNP_Server mpd[337]: [l_pptp-15] Link: DOWN event
Oct 20 05:12:13 VNP_Server mpd[337]: [l_pptp-15] LCP: Down event
Oct 20 05:12:13 VNP_Server mpd[337]: [l_pptp-15] 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_pptp-7] IFACE: Close event
Oct 20 05:12:13 VNP_Server mpd[337]: [b_pptp-7] IPCP: Close event
Oct 20 05:12:13 VNP_Server mpd[337]: [b_pptp-7] CCP: Close event
Oct 20 05:12:13 VNP_Server mpd[337]: [b_pptp-8] IFACE: Close event
Oct 20 05:12:13 VNP_Server mpd[337]: [b_pptp-8] IPCP: Close event
Oct 20 05:12:13 VNP_Server mpd[337]: [b_pptp-8] CCP: Close event
Oct 20 05:12:13 VNP_Server mpd[337]: [b_pptp-9] IFACE: Close event
Oct 20 05:12:13 VNP_Server mpd[337]: [b_pptp-9] IPCP: Close event
Oct 20 05:12:13 VNP_Server mpd[337]: [b_pptp-9] IPCP: state change Opened --> Closing
Oct 20 05:12:13 VNP_Server mpd[337]: [b_pptp-9] IPCP: SendTerminateReq #2
Oct 20 05:12:13 VNP_Server mpd[337]: [b_pptp-9] IPCP: LayerDown
<.../cut...>
mpd5 was installed from the FreeBSD ports (mpd5-5.9_4), all options are off.
System: FreeBSD 13.0-RELEASE-p4 #0 GENERIC amd64 (without any changes in kernel config)
Also tried with FreeBSD 12.2-RELEASE-p7 GENERIC amd64 - same problem.
And another one anomaly is observed after updating mpd5 from 5.8 to 5.9: all VPN connections are halted every night at ~ 04:51:10 (by local EEST timezone).
Here are the latest records in the mpd.log before halt.
<...cut...>
Oct 21 04:51:10 VNP_Server mpd[47279]: pptp1: send EchoRequest msg
Oct 21 04:51:10 VNP_Server mpd[47279]: len=16 msgType=1 magic=0x1a2b3c4d type=5
Oct 21 04:51:10 VNP_Server mpd[47279]: id=0x3b9
Oct 21 04:51:10 VNP_Server mpd[47279]: pptp1: wrote 16 bytes ctrl data
Oct 21 04:51:10 VNP_Server mpd[47279]: 00 10 00 01 1a 2b 3c 4d 00 05 00 00 00 00 03 b9 .....+<M........
Oct 21 04:51:10 VNP_Server mpd[47279]: EVENT: Starting timer "PptpReply" PptpCtrlReplyTimeout() for 60000 ms at pptp_ctrl.c:1168
Oct 21 04:51:10 VNP_Server mpd[47279]: EVENT: Registering event EVENT_TIMEOUT TimerExpires() at timer.c:50
Oct 21 04:51:10 VNP_Server mpd[47279]: EVENT: Registering event EVENT_TIMEOUT TimerExpires() done at timer.c:50
Oct 21 04:51:10 VNP_Server mpd[47279]: EVENT: Processing timer "PptpIdle" PptpCtrlIdleTimeout() done
Oct 21 04:51:10 VNP_Server mpd[47279]: EVENT: Processing event EVENT_TIMEOUT TimerExpires() done
Oct 21 04:51:10 VNP_Server mpd[47279]: EVENT: Processing event EVENT_READ PptpCtrlReadCtrl()
Oct 21 04:51:10 VNP_Server mpd[47279]: pptp1: read 12 bytes ctrl data
Oct 21 04:51:10 VNP_Server mpd[47279]: 00 10 00 01 1a 2b 3c 4d 00 05 00 00 .....+<M....
Oct 21 04:51:10 VNP_Server mpd[47279]: pptp1: got hdr
Oct 21 04:51:10 VNP_Server mpd[47279]: len=16 msgType=1 magic=0x1a2b3c4d type=5
Oct 21 04:51:10 VNP_Server mpd[47279]: EVENT: Processing event EVENT_READ PptpCtrlReadCtrl() done
Oct 21 04:51:10 VNP_Server mpd[47279]: EVENT: Processing event EVENT_READ PptpCtrlReadCtrl()
Oct 21 04:51:10 VNP_Server mpd[47279]: pptp1: read 4 bytes ctrl data
Oct 21 04:51:10 VNP_Server mpd[47279]: 00 00 03 c7 ....
Oct 21 04:51:10 VNP_Server mpd[47279]: pptp1: recv EchoRequest
Oct 21 04:51:10 VNP_Server mpd[47279]: id=0x3c7
Oct 21 04:51:10 VNP_Server mpd[47279]: EVENT: Starting timer "PptpIdle" PptpCtrlIdleTimeout() for 60000 ms at pptp_ctrl.c:1692
Oct 21 04:51:10 VNP_Server mpd[47279]: EVENT: Registering event EVENT_TIMEOUT TimerExpires() at timer.c:50
Oct 21 04:51:10 VNP_Server mpd[47279]: EVENT: Registering event EVENT_TIMEOUT TimerExpires() done at timer.c:50
Oct 21 04:51:10 VNP_Server mpd[47279]: pptp1: send EchoReply msg
Oct 21 04:51:10 VNP_Server mpd[47279]: len=20 msgType=1 magic=0x1a2b3c4d type=6
Oct 21 04:51:10 VNP_Server mpd[47279]: id=0x3c7 result=1 err=0 ignore=0
Oct 21 04:51:10 VNP_Server mpd[47279]: pptp1: wrote 20 bytes ctrl data
Oct 21 04:51:10 VNP_Server mpd[47279]: 00 14 00 01 1a 2b 3c 4d 00 06 00 00 00 00 03 c7 .....+<M........
Oct 21 04:51:10 VNP_Server mpd[47279]: 01 00 00 00 ....
Oct 21 04:51:10 VNP_Server mpd[47279]: EVENT: Processing event EVENT_READ PptpCtrlReadCtrl() done
Oct 21 04:51:10 VNP_Server mpd[47279]: EVENT: Processing event EVENT_READ PptpCtrlReadCtrl()
Oct 21 04:51:10 VNP_Server mpd[47279]: pptp1: read 12 bytes ctrl data
Oct 21 04:51:10 VNP_Server mpd[47279]: 00 14 00 01 1a 2b 3c 4d 00 06 00 00 .....+<M....
Oct 21 04:51:10 VNP_Server mpd[47279]: pptp1: got hdr
Oct 21 04:51:10 VNP_Server mpd[47279]: len=20 msgType=1 magic=0x1a2b3c4d type=6
Oct 21 04:51:10 VNP_Server mpd[47279]: EVENT: Processing event EVENT_READ PptpCtrlReadCtrl() done
Oct 21 04:51:10 VNP_Server mpd[47279]: EVENT: Processing event EVENT_READ PptpCtrlReadCtrl()
Oct 21 04:51:10 VNP_Server mpd[47279]: pptp1: read 8 bytes ctrl data
Oct 21 04:51:10 VNP_Server mpd[47279]: 00 00 03 b9 01 00 00 00 ........
Oct 21 04:51:10 VNP_Server mpd[47279]: pptp1: recv EchoReply
Oct 21 04:51:10 VNP_Server mpd[47279]: id=0x3b9 result=1 err=0 ignore=0
Oct 21 04:51:10 VNP_Server mpd[47279]: EVENT: Stopping timer "PptpIdle" PptpCtrlIdleTimeout() at pptp_ctrl.c:1689
Oct 21 04:51:10 VNP_Server mpd[47279]: EVENT: Unregistering event EVENT_TIMEOUT TimerExpires() at timer.c:83
Oct 21 04:51:10 VNP_Server mpd[47279]: EVENT: Unregistering event EVENT_TIMEOUT TimerExpires() done at timer.c:83
Oct 21 04:51:10 VNP_Server mpd[47279]: EVENT: Starting timer "PptpIdle" PptpCtrlIdleTimeout() for 60000 ms at pptp_ctrl.c:1692
Oct 21 04:51:10 VNP_Server mpd[47279]: EVENT: Registering event EVENT_TIMEOUT TimerExpires() at timer.c:50
Oct 21 04:51:10 VNP_Server mpd[47279]: EVENT: Registering event EVENT_TIMEOUT TimerExpires() done at timer.c:50
Oct 21 04:51:10 VNP_Server mpd[47279]: EVENT: Stopping timer "PptpReply" PptpCtrlReplyTimeout() at pptp_ctrl.c:1087
Oct 21 04:51:10 VNP_Server mpd[47279]: EVENT: Unregistering event EVENT_TIMEOUT TimerExpires() at timer.c:83
Oct 21 04:51:10 VNP_Server mpd[47279]: EVENT: Unregistering event EVENT_TIMEOUT TimerExpires() done at timer.c:83
Oct 21 04:51:10 VNP_Server mpd[47279]: EVENT: Processing event EVENT_READ PptpCtrlReadCtrl() done
Oct 21 04:51:10 VNP_Server mpd[47279]: EVENT: Processing event EVENT_READ L2tpServerEvent()
<end>
after this mpd5 service cannot be stopped normally (i.e. command 'service mpd5 stop' just endless) - have to reboot whole server.
Tried to 'force' mpd5 stop using
killall -z -9 mpd5
No luck.
mpd5 process is killed, but after new start nobody can establish VPN connection to this server.
Also tried to kill all 'connections' after killing mpd5 'zombie':
ngctl shutdown ng0:
ngctl shutdown ng1:
...
Then start mpd5 service.
But in this case mpd5 works very unstable at all - some client can connect, other - not; some clients who were able to connect - has no traffic flow, for other works new connection works good.
So the only solution of this issue I found so far - scheduling full server restart at 05:00 (by local time).
The config is attached.
Previous version of mpd5 worked perfectly with it.
Maybe I miss some update related to the new version... and just have to adjust my config accordingly.
Can you run unstripped version mpd5 ?
With it I can see function's names in backtrace.
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
If you'll tell me how to do this - I'll try.
Rebuild the ports with debug info included:
cd /usr/ports/net/mpd5
make WITH_DEBUG=yes clean all deinstall install
As for nightly hangs, I'm sure this is some kernel level problem with FreeBSD 13. If you can afford it, please use FreeBSD 12 for now until we solve this distinct ASSERT problem of mpd5.
Thanks. I'll rebuild port with this option this night.
As for the FreeBSD - as I said - I also have another one VPN server with FreeBSD 12.2-RELEASE-p7 GENERIC amd64.
And the same problem appeared there after last ports update (i.e. when mpd5 was updated from 5.9 to 5.9_4)
There are two distinct problems: one with ASSERT inherent to mpd5 code; and another one is about hangs in kernel code, it depends on FreeBSD version. Do you have hangs in FreeBSD 12?
Crash (first log) was caught on FreeBSD 13.
Regular nightly hang (second log) - on both - 12 and 13.
Did you install FreeBSD OS using pre-build binaries (bsdinstall or freebsd-update) or did you build it from sources with buildworld/buildkernel? In the latter case, please share /etc/src.conf for build system.
FreeBSD was installed and updated using pre-build binaries.
In that case I advise you to rebuild the port with default options:
make BATCH=yes WITH_DEBUG=yes rmconfig clean all deinstall install
See if default build of mpd5 port is stable.
No changes - again halted at the same time - 04:52...
On all servers
It seems I'm the only one who has this issue, so will try to reinstall all servers from the scratch. Maybe one 'buggy' server or client fails all other VPN servers.
I need to see the log with "+lcp +lcp2" log options enabled and ASSERT etc.
Here is the log
The file has no ASSERT line nor LCP2 level logs.
Please do not use "log +all" unless specifically asked, it is quite excessive. Instead, add "log +lcp +lcp2" and when this ASSERT problem reproduces, post resulting log.
I gave up - rolled back to the 5.9 version (from the latest 5.9_4).
The issue with nightly halts is gone.
Will go with this version until the next version will be released. Then will try new version once again.
Can you run mpd5 with debug symbols ?
Rebuild latest MPD5 port (5.9_4) the following way:
make BATCH=yes WITH_DEBUG=yes rmconfig clean all deinstall install
Here is today's MPD5 log (VPN stopped 1 hour earlier today... maybe due to daylight time change)
The reason of hangs for mpd-5.9_4 is discovered and the solution is in works. It affects L2TP servers only. As work-around, one may add the command "set l2tp self X.X.X.X" to L2TP configuration to restore behavior of mpd-5.9 version.
As for crashes, we need backtrace and/or coredump.
Last edit: Eugene Grosbein 2021-11-26
If you like to test a patch to make sure next mpd5 revision does not hang for you, replace /usr/ports/net/mpd5/files/patch-l2tp-multihomed with attached fixed variant and rebuild/restart mpd5.
You may update your ports tree and upgrade to the version 5.9_5 or newer to fix hangs.
Thank you.
Updated to v.5.9_6 - will check tomorrow morning.
it helps
no nightly hangs/halts anymore
thank you
Please track FreeBSD kernel level problem with FreeBSD Bugzilla PR: https://bugs.freebsd.org/bugzilla/show_bug.cgi?id=241133