L2TP closes connection for unknown reason

jimp

Based on the contents of the log I'd say something is breaking the connection between them. pfSense is not getting a response on the line so it drops the connection.

Something is broken in the network between pfSense and the Mikrotik.

lifeboy

@jimp Strangely enough nothing is down when this happens. We have a ping running to keep IPSec links alive all the time and that continues.

I'll set up some extra checks to see if anything does actually go down.

Question: I'd like to keep L2TP up all the time and retry the connection when it goes down so that this situation doesn't ever occur, except if the actual connection is down. What are the options to achieve this?

biggsy

@lifeboy said in L2TP closes connection for unknown reason:

... 2 Mikrotik routers that have been running for more than a year. No software update or changes have been made on the Mikrotik in a long time ...

How long is a long time? There have been a couple of serious vulnerabilities discovered and patched in Routeros during the past year.

jimp

pfSense is trying to reconnect, but it's getting no response from the other side. Something is preventing them from communicating, and it's not likely to be anything directly on pfSense.

lifeboy

@biggsy I have the latest version of RouterOS installed, but have now upgraded everything (packages) to the latest as well.

I'll monitor it and will see what happens.

lifeboy

@jimp I have some more info. I have various locations that connect over different network to pfSense via L2TP. I also have a two server locations that they connect to. So:

routeros1 -> L2TP -> pfSense 2.4.3_1 (location H)
routeros1 -> L2TP -> pfSense 2.4.3_1 (location V)
routeros2 -> L2TP -> pfSense 2.4.3_1 (location H)
routeros2 -> L2TP -> pfSense 2.4.3_1 (location V)

Is the above scenario both routeros1 and routeros2 links to location H drop all the time, but both stay up during that time to location V. That seems to indicate that the pfSense is not happy with something that routeros does and it fails the link.

Everything is the same (software versions), except location V runs on AMD Opteron hardware (Sun X2100) and location H run on Intel (Super Micro I think).

lifeboy

Here is the l2tp log for an event where the L2TP link is established and then closed again by pfSense.

Aug 14 07:28:24 	l2tps 		[l2tp_b-2] CCP: LayerFinish
Aug 14 07:28:24 	l2tps 		[l2tp_b-2] CCP: state change Stopping --> Stopped
Aug 14 07:28:24 	l2tps 		[l2tp_b-2] CCP: rec'd Terminate Ack #2 (Stopping)
Aug 14 07:28:24 	l2tps 		[l2tp_b-2] CCP: SendTerminateAck #3
Aug 14 07:28:24 	l2tps 		[l2tp_b-2] CCP: rec'd Terminate Request #12 (Stopping)
Aug 14 07:28:24 	l2tps 		[l2tp_b-2] IFACE: Add group l2tp to ng1
Aug 14 07:28:24 	l2tps 		[l2tp_b-2] IFACE: Rename interface ng1 to l2tp2
Aug 14 07:28:24 	l2tps 		[l2tp_b-2] IFACE: Up event
Aug 14 07:28:24 	l2tps 		[l2tp_b-2] 192.168.0.223 -> 192.168.0.225
Aug 14 07:28:24 	l2tps 		[l2tp_b-2] IPCP: LayerUp
Aug 14 07:28:24 	l2tps 		[l2tp_b-2] IPCP: state change Ack-Sent --> Opened
Aug 14 07:28:24 	l2tps 		[l2tp_b-2] IPADDR 192.168.0.223
Aug 14 07:28:24 	l2tps 		[l2tp_b-2] IPCP: rec'd Configure Ack #2 (Ack-Sent)
Aug 14 07:28:24 	l2tps 		[l2tp_b-2] CCP: LayerDown
Aug 14 07:28:24 	l2tps 		[l2tp_b-2] CCP: SendTerminateReq #2
Aug 14 07:28:24 	l2tps 		[l2tp_b-2] CCP: state change Opened --> Stopping
Aug 14 07:28:24 	l2tps 		[l2tp_b-2] CCP: parameter negotiation failed
Aug 14 07:28:24 	l2tps 		[l2tp_b-2] CCP: No compression negotiated
Aug 14 07:28:24 	l2tps 		[l2tp_b-2] CCP: LayerUp
Aug 14 07:28:24 	l2tps 		[l2tp_b-2] CCP: state change Ack-Rcvd --> Opened
Aug 14 07:28:24 	l2tps 		[l2tp_b-2] CCP: SendConfigAck #11
Aug 14 07:28:24 	l2tps 		[l2tp_b-2] CCP: rec'd Configure Request #11 (Ack-Rcvd)
Aug 14 07:28:24 	l2tps 		[l2tp_b-2] IPCP: state change Req-Sent --> Ack-Sent
Aug 14 07:28:24 	l2tps 		[l2tp_b-2] IPADDR 192.168.0.225
Aug 14 07:28:24 	l2tps 		[l2tp_b-2] IPCP: SendConfigAck #8
Aug 14 07:28:24 	l2tps 		[l2tp_b-2] 192.168.0.225 is OK
Aug 14 07:28:24 	l2tps 		[l2tp_b-2] IPADDR 192.168.0.225
Aug 14 07:28:24 	l2tps 		[l2tp_b-2] IPCP: rec'd Configure Request #8 (Req-Sent)
Aug 14 07:28:24 	l2tps 		[l2tp_b-2] CCP: state change Req-Sent --> Ack-Rcvd
Aug 14 07:28:24 	l2tps 		[l2tp_b-2] CCP: rec'd Configure Ack #1 (Req-Sent)
Aug 14 07:28:24 	l2tps 		[l2tp_b-2] IPADDR 192.168.0.223
Aug 14 07:28:24 	l2tps 		[l2tp_b-2] IPCP: SendConfigReq #2
Aug 14 07:28:24 	l2tps 		[l2tp_b-2] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
Aug 14 07:28:24 	l2tps 		[l2tp_b-2] IPCP: rec'd Configure Reject #1 (Req-Sent)
Aug 14 07:28:24 	l2tps 		[l2tp_b-2] 0x01000040:MPPE(128 bits), stateless
Aug 14 07:28:24 	l2tps 		[l2tp_b-2] MPPC
Aug 14 07:28:24 	l2tps 		[l2tp_b-2] CCP: SendConfigRej #10
Aug 14 07:28:24 	l2tps 		[l2tp_b-2] 0x01000040:MPPE(128 bits), stateless
Aug 14 07:28:24 	l2tps 		[l2tp_b-2] MPPC
Aug 14 07:28:24 	l2tps 		[l2tp_b-2] CCP: rec'd Configure Request #10 (Req-Sent)
Aug 14 07:28:24 	l2tps 		[l2tp_l-2] rec'd unexpected protocol MPLS Control Protocol (RFC 3032), rejecting
Aug 14 07:28:24 	l2tps 		[l2tp_b-2] IPADDR 192.168.0.225
Aug 14 07:28:24 	l2tps 		[l2tp_b-2] IPCP: SendConfigNak #7
Aug 14 07:28:24 	l2tps 		[l2tp_b-2] NAKing with 192.168.0.225
Aug 14 07:28:24 	l2tps 		[l2tp_b-2] IPADDR 0.0.0.0
Aug 14 07:28:24 	l2tps 		[l2tp_b-2] IPCP: rec'd Configure Request #7 (Req-Sent)
Aug 14 07:28:24 	l2tps 		[l2tp_b-2] CCP: SendConfigReq #1
Aug 14 07:28:24 	l2tps 		[l2tp_b-2] CCP: state change Starting --> Req-Sent
Aug 14 07:28:24 	l2tps 		[l2tp_b-2] CCP: Protocol mppc disabled as useless for this setup
Aug 14 07:28:24 	l2tps 		[l2tp_b-2] CCP: Up event
Aug 14 07:28:24 	l2tps 		[l2tp_b-2] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
Aug 14 07:28:24 	l2tps 		[l2tp_b-2] IPADDR 192.168.0.223
Aug 14 07:28:24 	l2tps 		[l2tp_b-2] IPCP: SendConfigReq #1
Aug 14 07:28:24 	l2tps 		[l2tp_b-2] IPCP: state change Starting --> Req-Sent
Aug 14 07:28:24 	l2tps 		[l2tp_b-2] IPCP: Got IP 192.168.0.225 from pool "p0" for peer
Aug 14 07:28:24 	l2tps 		[l2tp_b-2] IPCP: Up event
Aug 14 07:28:24 	l2tps 		[l2tp_b-2] CCP: LayerStart
Aug 14 07:28:24 	l2tps 		[l2tp_b-2] CCP: state change Initial --> Starting
Aug 14 07:28:24 	l2tps 		[l2tp_b-2] CCP: Open event
Aug 14 07:28:24 	l2tps 		[l2tp_b-2] IPCP: LayerStart
Aug 14 07:28:24 	l2tps 		[l2tp_b-2] IPCP: state change Initial --> Starting
Aug 14 07:28:24 	l2tps 		[l2tp_b-2] IPCP: Open event
Aug 14 07:28:24 	l2tps 		[l2tp_b-2] Bundle: Status update: up 1 link, total bandwidth 64000 bps
Aug 14 07:28:24 	l2tps 		[l2tp_l-2] Link: Join bundle "l2tp_b-2"
Aug 14 07:28:24 	l2tps 		[l2tp_b-2] Bundle: Interface ng1 created
Aug 14 07:28:24 	l2tps 		[l2tp_l-2] Creating new bundle using template "l2tp_b".
Aug 14 07:28:24 	l2tps 		[l2tp_l-2] Link: Matched action 'bundle "l2tp_b" ""'
Aug 14 07:28:24 	l2tps 		[l2tp_l-2] LCP: authorization successful
Aug 14 07:28:24 	l2tps 		[l2tp_l-2] CHAP: sending SUCCESS #1 len: 46
Aug 14 07:28:24 	l2tps 		[l2tp_l-2] CHAP: Reply message: S=C2DEDC922DFA427071447E9665569CC230FEAC34
Aug 14 07:28:24 	l2tps 		[l2tp_l-2] CHAP: Response is valid
Aug 14 07:28:24 	l2tps 		[l2tp_l-2] CHAP: Auth return status: undefined
Aug 14 07:28:24 	l2tps 		[l2tp_l-2] AUTH: INTERNAL returned: undefined
Aug 14 07:28:24 	l2tps 		[l2tp_l-2] AUTH: Trying INTERNAL
Aug 14 07:28:24 	l2tps 		[l2tp_l-2] Name: "imb-router"
Aug 14 07:28:24 	l2tps 		[l2tp_l-2] CHAP: rec'd RESPONSE #1 len: 64
Aug 14 07:28:24 	l2tps 		[l2tp_l-2] LCP: LayerUp
Aug 14 07:28:24 	l2tps 		[l2tp_l-2] CHAP: sending CHALLENGE #1 len: 21
Aug 14 07:28:24 	l2tps 		[l2tp_l-2] LCP: auth: peer wants nothing, I want CHAP
Aug 14 07:28:24 	l2tps 		[l2tp_l-2] LCP: state change Ack-Sent --> Opened
Aug 14 07:28:24 	l2tps 		[l2tp_l-2] AUTHPROTO CHAP MSOFTv2
Aug 14 07:28:24 	l2tps 		[l2tp_l-2] MAGICNUM 0xf47c96f8
Aug 14 07:28:24 	l2tps 		[l2tp_l-2] MRU 1500
Aug 14 07:28:24 	l2tps 		[l2tp_l-2] LCP: rec'd Configure Ack #3 (Ack-Sent)
Aug 14 07:28:24 	l2tps 		[l2tp_l-2] AUTHPROTO CHAP MSOFTv2
Aug 14 07:28:24 	l2tps 		[l2tp_l-2] MAGICNUM 0xf47c96f8
Aug 14 07:28:24 	l2tps 		[l2tp_l-2] MRU 1500
Aug 14 07:28:24 	l2tps 		[l2tp_l-2] LCP: SendConfigReq #3
Aug 14 07:28:24 	l2tps 		[l2tp_l-2] MP SHORTSEQ
Aug 14 07:28:24 	l2tps 		[l2tp_l-2] ENDPOINTDISC [802.1] 0c c4 7a ce c4 f1
Aug 14 07:28:24 	l2tps 		[l2tp_l-2] MP MRRU 2048
Aug 14 07:28:24 	l2tps 		[l2tp_l-2] PROTOCOMP
Aug 14 07:28:24 	l2tps 		[l2tp_l-2] ACFCOMP
Aug 14 07:28:24 	l2tps 		[l2tp_l-2] LCP: rec'd Configure Reject #2 (Ack-Sent)
Aug 14 07:28:24 	l2tps 		[l2tp_l-2] ENDPOINTDISC [802.1] 0c c4 7a ce c4 f1
Aug 14 07:28:24 	l2tps 		[l2tp_l-2] MP SHORTSEQ
Aug 14 07:28:24 	l2tps 		[l2tp_l-2] MP MRRU 2048
Aug 14 07:28:24 	l2tps 		[l2tp_l-2] AUTHPROTO CHAP MSOFTv2
Aug 14 07:28:24 	l2tps 		[l2tp_l-2] MAGICNUM 0xf47c96f8
Aug 14 07:28:24 	l2tps 		[l2tp_l-2] MRU 1500
Aug 14 07:28:24 	l2tps 		[l2tp_l-2] PROTOCOMP
Aug 14 07:28:24 	l2tps 		[l2tp_l-2] ACFCOMP
Aug 14 07:28:24 	l2tps 		[l2tp_l-2] LCP: SendConfigReq #2
Aug 14 07:28:23 	l2tps 		[l2tp_l-2] MAGICNUM 0x7fe0f9fc
Aug 14 07:28:23 	l2tps 		[l2tp_l-2] MRU 1450
Aug 14 07:28:23 	l2tps 		[l2tp_l-2] LCP: SendConfigAck #9
Aug 14 07:28:23 	l2tps 		[l2tp_l-2] MAGICNUM 0x7fe0f9fc
Aug 14 07:28:23 	l2tps 		[l2tp_l-2] MRU 1450
Aug 14 07:28:23 	l2tps 		[l2tp_l-2] LCP: rec'd Configure Request #9 (Ack-Sent)
Aug 14 07:28:22 	l2tps 		[l2tp_l-2] LCP: state change Req-Sent --> Ack-Sent
Aug 14 07:28:22 	l2tps 		[l2tp_l-2] MAGICNUM 0x7fe0f9fc
Aug 14 07:28:22 	l2tps 		[l2tp_l-2] MRU 1450
Aug 14 07:28:22 	l2tps 		[l2tp_l-2] LCP: SendConfigAck #8
Aug 14 07:28:22 	l2tps 		[l2tp_l-2] MAGICNUM 0x7fe0f9fc
Aug 14 07:28:22 	l2tps 		[l2tp_l-2] MRU 1450
Aug 14 07:28:22 	l2tps 		[l2tp_l-2] LCP: rec'd Configure Request #8 (Req-Sent)
Aug 14 07:28:22 	l2tps 		[l2tp_l-2] ENDPOINTDISC [802.1] 0c c4 7a ce c4 f1
Aug 14 07:28:22 	l2tps 		[l2tp_l-2] MP SHORTSEQ
Aug 14 07:28:22 	l2tps 		[l2tp_l-2] MP MRRU 2048
Aug 14 07:28:22 	l2tps 		[l2tp_l-2] AUTHPROTO CHAP MSOFTv2
Aug 14 07:28:22 	l2tps 		[l2tp_l-2] MAGICNUM 0xf47c96f8
Aug 14 07:28:22 	l2tps 		[l2tp_l-2] MRU 1500
Aug 14 07:28:22 	l2tps 		[l2tp_l-2] PROTOCOMP
Aug 14 07:28:22 	l2tps 		[l2tp_l-2] ACFCOMP
Aug 14 07:28:22 	l2tps 		[l2tp_l-2] LCP: SendConfigReq #1
Aug 14 07:28:22 	l2tps 		[l2tp_l-2] LCP: state change Starting --> Req-Sent
Aug 14 07:28:22 	l2tps 		[l2tp_l-2] LCP: Up event
Aug 14 07:28:22 	l2tps 		[l2tp_l-2] Link: UP event
Aug 14 07:28:22 	l2tps 		[l2tp_l-2] L2TP: Call #5 connected
Aug 14 07:28:22 	l2tps 		[l2tp_l-2] LCP: LayerStart
Aug 14 07:28:22 	l2tps 		[l2tp_l-2] LCP: state change Initial --> Starting
Aug 14 07:28:22 	l2tps 		[l2tp_l-2] LCP: Open event
Aug 14 07:28:22 	l2tps 		[l2tp_l-2] Link: OPEN event
Aug 14 07:28:22 	l2tps 		[l2tp_l-2] L2TP: Incoming call #5 via control connection 0x803257f10 accepted
Aug 14 07:28:22 	l2tps 		L2TP: Incoming call #5 via connection 0x803257f10 received
Aug 14 07:28:22 	l2tps 		[l2tp_l-2] Link: Shutdown
Aug 14 07:28:22 	l2tps 		[l2tp_l-2] Link: SHUTDOWN event
Aug 14 07:28:22 	l2tps 		[l2tp_l-2] LCP: state change Closing --> Initial
Aug 14 07:28:22 	l2tps 		[l2tp_l-2] LCP: LayerFinish
Aug 14 07:28:22 	l2tps 		[l2tp_l-2] LCP: Down event
Aug 14 07:28:22 	l2tps 		[l2tp_l-2] LCP: state change Stopping --> Closing
Aug 14 07:28:22 	l2tps 		[l2tp_l-2] LCP: Close event
Aug 14 07:28:22 	l2tps 		[l2tp_l-2] Link: DOWN event
Aug 14 07:28:22 	l2tps 		[l2tp_l-2] L2TP: call #4 terminated: result=1 error=0 errmsg=""
Aug 14 07:28:21 	l2tps 		[l2tp_l-2] LCP: LayerDown
Aug 14 07:28:21 	l2tps 		[l2tp_l-2] LCP: SendTerminateAck #4
Aug 14 07:28:21 	l2tps 		[l2tp_b-2] Bundle: Shutdown
Aug 14 07:28:21 	l2tps 		[l2tp_b-2] CCP: state change Closed --> Initial
Aug 14 07:28:21 	l2tps 		[l2tp_b-2] CCP: Down event
Aug 14 07:28:21 	l2tps 		[l2tp_b-2] IPCP: state change Closing --> Initial
Aug 14 07:28:21 	l2tps 		[l2tp_b-2] Bundle: No NCPs left. Closing links...
Aug 14 07:28:21 	l2tps 		[l2tp_b-2] IPCP: LayerFinish
Aug 14 07:28:21 	l2tps 		[l2tp_b-2] IPCP: Down event
Aug 14 07:28:21 	l2tps 		[l2tp_b-2] CCP: state change Stopped --> Closed
Aug 14 07:28:21 	l2tps 		[l2tp_b-2] CCP: Close event
Aug 14 07:28:21 	l2tps 		[l2tp_b-2] IFACE: Rename interface l2tp2 to l2tp2
Aug 14 07:28:21 	l2tps 		[l2tp_b-2] IFACE: Down event
Aug 14 07:28:21 	l2tps 		[l2tp_b-2] IPCP: LayerDown
Aug 14 07:28:21 	l2tps 		[l2tp_b-2] IPCP: SendTerminateReq #3
Aug 14 07:28:21 	l2tps 		[l2tp_b-2] IPCP: state change Opened --> Closing
Aug 14 07:28:21 	l2tps 		[l2tp_b-2] IPCP: Close event
Aug 14 07:28:21 	l2tps 		[l2tp_b-2] Bundle: Status update: up 0 links, total bandwidth 9600 bps
Aug 14 07:28:21 	l2tps 		[l2tp_l-2] Link: Leave bundle "l2tp_b-2"
Aug 14 07:28:21 	l2tps 		[l2tp_l-2] LCP: state change Opened --> Stopping
Aug 14 07:28:21 	l2tps 		[l2tp_l-2] LCP: rec'd Terminate Request #7 (Opened)

Note the lines:
Aug 14 07:28:24 l2tps [l2tp_b-2] CCP: state change Opened --> Stopping
Aug 14 07:28:24 l2tps [l2tp_b-2] CCP: parameter negotiation failed
Aug 14 07:28:24 l2tps [l2tp_b-2] CCP: No compression negotiated
Aug 14 07:28:24 l2tps [l2tp_b-2] CCP: LayerUp

It's seems to me that there is some parameter that cannot be negotiated, so the layer is closed. How do I get more details on what happens?

lifeboy

I'm not getting any responses which seems to indicate nobody has any more clue of what is happening here than I have? Is there a way to get more verbose logging for L2TP?

Didier.C

It's seems there is a bug in renaming interface

i have the same problem.
Ì use two L2TP interface, one to connect as client.
the second with a L2TP/IPSEC inteface for VPN.

each time somebody disconnect from VPN, my client interface disconnect. It seems this is referenced as a bug referenced :

https://redmine.pfsense.org/issues/8164

I don't know how to bypass this bug.

lifeboy

I have sort of bypassed my problem by downgrading my mikrotik routeros version, but of course that opens me up to possible exploits with may have been fixed since. I have not considered that client connecting/disconnecting could be causing this though, so I will careful note what happens next time I have a disconnect.