L2TP closes connection for unknown reason



  • We have noticed that during the last few days we had repeated L2TP disconnects from 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, and I'm not aware of any changes on pfSense either.

    Here's the log when the disconnect occurs:

    Aug 3 16:56:51 l2tps: [l2tp_l-2] LCP: no reply to 1 echo request(s)
    Aug 3 16:55:21 l2tps: [l2tp_l-2] LCP: no reply to 1 echo request(s)
    Aug 3 16:54:11 l2tps: [l2tp_l-2] LCP: no reply to 1 echo request(s)
    Aug 3 16:53:41 l2tps: [l2tp_l-2] LCP: no reply to 1 echo request(s)
    Aug 3 16:53:01 l2tps: [l2tp_l-2] LCP: no reply to 1 echo request(s)
    Aug 3 16:45:01 l2tps: [l2tp_l-2] LCP: no reply to 1 echo request(s)
    Aug 3 16:44:01 l2tps: [l2tp_l-2] LCP: no reply to 1 echo request(s)
    Aug 3 16:17:18 l2tps: L2TP: Control connection 0x803257910 destroyed
    Aug 3 16:17:07 l2tps: [l2tp_l-1] Link: Shutdown
    Aug 3 16:17:07 l2tps: [l2tp_l-1] Link: SHUTDOWN event
    Aug 3 16:17:07 l2tps: L2TP: Control connection 0x803257910 terminated: 0 ()
    Aug 3 16:17:07 l2tps: [l2tp_l-1] LCP: state change Closing --> Initial
    Aug 3 16:17:07 l2tps: [l2tp_l-1] LCP: LayerFinish
    Aug 3 16:17:07 l2tps: [l2tp_l-1] LCP: Down event
    Aug 3 16:17:07 l2tps: [l2tp_l-1] LCP: LayerDown
    Aug 3 16:17:07 l2tps: [l2tp_l-1] LCP: SendTerminateReq #4
    Aug 3 16:17:07 l2tps: [l2tp_b-1] Bundle: Shutdown
    Aug 3 16:17:07 l2tps: [l2tp_b-1] CCP: state change Closed --> Initial
    Aug 3 16:17:07 l2tps: [l2tp_b-1] CCP: Down event
    Aug 3 16:17:07 l2tps: [l2tp_b-1] IPCP: state change Closing --> Initial
    Aug 3 16:17:07 l2tps: [l2tp_b-1] Bundle: No NCPs left. Closing links...
    Aug 3 16:17:07 l2tps: [l2tp_b-1] IPCP: LayerFinish
    Aug 3 16:17:07 l2tps: [l2tp_b-1] IPCP: Down event
    Aug 3 16:17:07 l2tps: [l2tp_b-1] CCP: state change Stopped --> Closed
    Aug 3 16:17:07 l2tps: [l2tp_b-1] CCP: Close event
    Aug 3 16:17:07 l2tps: [l2tp_b-1] IFACE: Rename interface l2tp1 to l2tp1
    Aug 3 16:17:07 l2tps: [l2tp_b-1] IFACE: Down event
    Aug 3 16:17:07 l2tps: [l2tp_b-1] IPCP: LayerDown
    Aug 3 16:17:07 l2tps: [l2tp_b-1] IPCP: SendTerminateReq #3
    Aug 3 16:17:07 l2tps: [l2tp_b-1] IPCP: state change Opened --> Closing
    Aug 3 16:17:07 l2tps: [l2tp_b-1] IPCP: Close event
    Aug 3 16:17:07 l2tps: [l2tp_b-1] Bundle: Status update: up 0 links, total bandwidth 9600 bps
    Aug 3 16:17:07 l2tps: [l2tp_l-1] Link: Leave bundle "l2tp_b-1"
    Aug 3 16:17:07 l2tps: [l2tp_l-1] LCP: state change Opened --> Closing
    Aug 3 16:17:07 l2tps: [l2tp_l-1] LCP: Close event
    Aug 3 16:17:07 l2tps: [l2tp_l-1] Link: DOWN event
    Aug 3 16:17:07 l2tps: [l2tp_l-1] L2TP: call #14 terminated: result=2 error=6 errmsg="control connection closing"
    Aug 3 16:17:06 l2tps: [l2tp_l-1] LCP: no reply to 11 echo request(s)
    Aug 3 16:16:56 l2tps: [l2tp_l-1] LCP: no reply to 10 echo request(s)
    Aug 3 16:16:46 l2tps: [l2tp_l-1] LCP: no reply to 9 echo request(s)
    Aug 3 16:16:36 l2tps: [l2tp_l-1] LCP: no reply to 8 echo request(s)
    Aug 3 16:16:28 l2tps: [l2tp_b-5] CCP: LayerFinish
    Aug 3 16:16:28 l2tps: [l2tp_b-5] CCP: state change Stopping --> Stopped
    Aug 3 16:16:28 l2tps: [l2tp_b-5] CCP: rec'd Terminate Ack #2 (Stopping)
    Aug 3 16:16:28 l2tps: [l2tp_b-5] CCP: SendTerminateAck #3
    Aug 3 16:16:28 l2tps: [l2tp_b-5] CCP: rec'd Terminate Request #18 (Stopping)
    Aug 3 16:16:28 l2tps: [l2tp_b-5] IFACE: Add group l2tp to ng4
    Aug 3 16:16:28 l2tps: [l2tp_b-5] IFACE: Rename interface ng4 to l2tp5
    Aug 3 16:16:28 l2tps: [l2tp_b-5] IFACE: Up event
    Aug 3 16:16:28 l2tps: [l2tp_b-5]   192.168.0.223 -> 192.168.0.220
    Aug 3 16:16:28 l2tps: [l2tp_b-5] IPCP: LayerUp
    Aug 3 16:16:28 l2tps: [l2tp_b-5] IPCP: state change Ack-Sent --> Opened
    Aug 3 16:16:28 l2tps: [l2tp_b-5]   IPADDR 192.168.0.223
    Aug 3 16:16:28 l2tps: [l2tp_b-5] IPCP: rec'd Configure Ack #2 (Ack-Sent)
    Aug 3 16:16:28 l2tps: [l2tp_b-5] CCP: LayerDown
    Aug 3 16:16:28 l2tps: [l2tp_b-5] CCP: SendTerminateReq #2
    Aug 3 16:16:28 l2tps: [l2tp_b-5] CCP: state change Opened --> Stopping
    Aug 3 16:16:28 l2tps: [l2tp_b-5] CCP: parameter negotiation failed
    Aug 3 16:16:28 l2tps: [l2tp_b-5] CCP: No compression negotiated
    Aug 3 16:16:28 l2tps: [l2tp_b-5] CCP: LayerUp
    Aug 3 16:16:28 l2tps: [l2tp_b-5] CCP: state change Ack-Rcvd --> Opened
    Aug 3 16:16:28 l2tps: [l2tp_b-5] CCP: SendConfigAck #17
    Aug 3 16:16:28 l2tps: [l2tp_b-5] CCP: rec'd Configure Request #17 (Ack-Rcvd)
    Aug 3 16:16:28 l2tps: [l2tp_b-5] IPCP: state change Req-Sent --> Ack-Sent
    Aug 3 16:16:28 l2tps: [l2tp_b-5]   IPADDR 192.168.0.220
    Aug 3 16:16:28 l2tps: [l2tp_b-5] IPCP: SendConfigAck #12
    Aug 3 16:16:28 l2tps: [l2tp_b-5]     192.168.0.220 is OK
    Aug 3 16:16:28 l2tps: [l2tp_b-5]   IPADDR 192.168.0.220
    Aug 3 16:16:28 l2tps: [l2tp_b-5] IPCP: rec'd Configure Request #12 (Req-Sent)
    Aug 3 16:16:28 l2tps: [l2tp_b-5] CCP: state change Req-Sent --> Ack-Rcvd
    Aug 3 16:16:28 l2tps: [l2tp_b-5] CCP: rec'd Configure Ack #1 (Req-Sent)
    Aug 3 16:16:28 l2tps: [l2tp_b-5]   IPADDR 192.168.0.223
    Aug 3 16:16:28 l2tps: [l2tp_b-5] IPCP: SendConfigReq #2
    Aug 3 16:16:28 l2tps: [l2tp_b-5]   COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
    Aug 3 16:16:28 l2tps: [l2tp_b-5] IPCP: rec'd Configure Reject #1 (Req-Sent)
    Aug 3 16:16:28 l2tps: [l2tp_b-5]     0x01000040:MPPE(128 bits), stateless
    Aug 3 16:16:28 l2tps: [l2tp_b-5]   MPPC
    Aug 3 16:16:28 l2tps: [l2tp_b-5] CCP: SendConfigRej #16
    Aug 3 16:16:28 l2tps: [l2tp_b-5]     0x01000040:MPPE(128 bits), stateless
    Aug 3 16:16:28 l2tps: [l2tp_b-5]   MPPC
    Aug 3 16:16:28 l2tps: [l2tp_b-5] CCP: rec'd Configure Request #16 (Req-Sent)
    Aug 3 16:16:28 l2tps: [l2tp_l-5] rec'd unexpected protocol MPLS Control Protocol (RFC 3032), rejecting
    Aug 3 16:16:28 l2tps: [l2tp_b-5]   IPADDR 192.168.0.220
    Aug 3 16:16:28 l2tps: [l2tp_b-5] IPCP: SendConfigNak #11
    Aug 3 16:16:28 l2tps: [l2tp_b-5]     NAKing with 192.168.0.220
    Aug 3 16:16:28 l2tps: [l2tp_b-5]   IPADDR 0.0.0.0
    Aug 3 16:16:28 l2tps: [l2tp_b-5] IPCP: rec'd Configure Request #11 (Req-Sent)
    Aug 3 16:16:28 l2tps: [l2tp_b-5] CCP: SendConfigReq #1
    Aug 3 16:16:28 l2tps: [l2tp_b-5] CCP: state change Starting --> Req-Sent
    Aug 3 16:16:28 l2tps: [l2tp_b-5] CCP: Protocol mppc disabled as useless for this setup
    Aug 3 16:16:28 l2tps: [l2tp_b-5] CCP: Up event
    Aug 3 16:16:28 l2tps: [l2tp_b-5]   COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
    Aug 3 16:16:28 l2tps: [l2tp_b-5]   IPADDR 192.168.0.223
    Aug 3 16:16:28 l2tps: [l2tp_b-5] IPCP: SendConfigReq #1
    Aug 3 16:16:28 l2tps: [l2tp_b-5] IPCP: state change Starting --> Req-Sent
    Aug 3 16:16:28 l2tps: [l2tp_b-5] IPCP: Up event
    Aug 3 16:16:28 l2tps: [l2tp_b-5] CCP: LayerStart
    Aug 3 16:16:28 l2tps: [l2tp_b-5] CCP: state change Initial --> Starting
    Aug 3 16:16:28 l2tps: [l2tp_b-5] CCP: Open event
    Aug 3 16:16:28 l2tps: [l2tp_b-5] IPCP: LayerStart
    Aug 3 16:16:28 l2tps: [l2tp_b-5] IPCP: state change Initial --> Starting
    Aug 3 16:16:28 l2tps: [l2tp_b-5] IPCP: Open event
    Aug 3 16:16:28 l2tps: [l2tp_b-5] Bundle: Status update: up 1 link, total bandwidth 64000 bps
    Aug 3 16:16:28 l2tps: [l2tp_l-5] Link: Join bundle "l2tp_b-5"
    Aug 3 16:16:28 l2tps: [l2tp_b-5] Bundle: Interface ng4 created
    Aug 3 16:16:28 l2tps: [l2tp_l-5] Creating new bundle using template "l2tp_b".
    Aug 3 16:16:28 l2tps: [l2tp_l-5] Link: Matched action 'bundle "l2tp_b" ""'
    Aug 3 16:16:28 l2tps: [l2tp_l-5] LCP: authorization successful
    Aug 3 16:16:28 l2tps: [l2tp_l-5] CHAP: sending SUCCESS #1 len: 46
    Aug 3 16:16:28 l2tps: [l2tp_l-5] CHAP: Reply message: S=B0EE82416C391333984215D6C915B640BAE3FFBF
    Aug 3 16:16:28 l2tps: [l2tp_l-5] CHAP: Response is valid
    Aug 3 16:16:28 l2tps: [l2tp_l-5] CHAP: Auth return status: undefined
    Aug 3 16:16:28 l2tps: [l2tp_l-5] AUTH: INTERNAL returned: undefined
    Aug 3 16:16:28 l2tps: [l2tp_l-5] AUTH: Trying INTERNAL
    Aug 3 16:16:28 l2tps: [l2tp_l-5]   Name: "imb-router"
    Aug 3 16:16:28 l2tps: [l2tp_l-5] CHAP: rec'd RESPONSE #1 len: 64
    Aug 3 16:16:28 l2tps: [l2tp_l-5] LCP: LayerUp
    Aug 3 16:16:28 l2tps: [l2tp_l-5] CHAP: sending CHALLENGE #1 len: 21
    Aug 3 16:16:28 l2tps: [l2tp_l-5] LCP: auth: peer wants nothing, I want CHAP
    Aug 3 16:16:28 l2tps: [l2tp_l-5] LCP: state change Ack-Sent --> Opened
    Aug 3 16:16:28 l2tps: [l2tp_l-5]   AUTHPROTO CHAP MSOFTv2
    Aug 3 16:16:28 l2tps: [l2tp_l-5]   MAGICNUM 0xcdeb1d4c
    Aug 3 16:16:28 l2tps: [l2tp_l-5]   MRU 1500
    Aug 3 16:16:28 l2tps: [l2tp_l-5] LCP: rec'd Configure Ack #3 (Ack-Sent)
    Aug 3 16:16:28 l2tps: [l2tp_l-5]   AUTHPROTO CHAP MSOFTv2
    Aug 3 16:16:28 l2tps: [l2tp_l-5]   MAGICNUM 0xcdeb1d4c
    Aug 3 16:16:28 l2tps: [l2tp_l-5]   MRU 1500
    Aug 3 16:16:28 l2tps: [l2tp_l-5] LCP: SendConfigReq #3
    Aug 3 16:16:28 l2tps: [l2tp_l-5]   MP SHORTSEQ
    Aug 3 16:16:28 l2tps: [l2tp_l-5]   ENDPOINTDISC [802.1] 00 1e 67 ce 84 59
    Aug 3 16:16:28 l2tps: [l2tp_l-5]   MP MRRU 2048
    Aug 3 16:16:28 l2tps: [l2tp_l-5]   PROTOCOMP
    Aug 3 16:16:28 l2tps: [l2tp_l-5]   ACFCOMP
    Aug 3 16:16:28 l2tps: [l2tp_l-5] LCP: rec'd Configure Reject #2 (Ack-Sent)
    Aug 3 16:16:28 l2tps: [l2tp_l-5]   ENDPOINTDISC [802.1] 00 1e 67 ce 84 59
    Aug 3 16:16:28 l2tps: [l2tp_l-5]   MP SHORTSEQ
    Aug 3 16:16:28 l2tps: [l2tp_l-5]   MP MRRU 2048
    Aug 3 16:16:28 l2tps: [l2tp_l-5]   AUTHPROTO CHAP MSOFTv2
    Aug 3 16:16:28 l2tps: [l2tp_l-5]   MAGICNUM 0xcdeb1d4c
    Aug 3 16:16:28 l2tps: [l2tp_l-5]   MRU 1500
    Aug 3 16:16:28 l2tps: [l2tp_l-5]   PROTOCOMP
    Aug 3 16:16:28 l2tps: [l2tp_l-5]   ACFCOMP
    Aug 3 16:16:28 l2tps: [l2tp_l-5] LCP: SendConfigReq #2
    Aug 3 16:16:27 l2tps: [l2tp_l-5]   MAGICNUM 0x3426beea
    Aug 3 16:16:27 l2tps: [l2tp_l-5]   MRU 1450
    Aug 3 16:16:27 l2tps: [l2tp_l-5] LCP: SendConfigAck #12
    Aug 3 16:16:27 l2tps: [l2tp_l-5]   MAGICNUM 0x3426beea
    Aug 3 16:16:27 l2tps: [l2tp_l-5]   MRU 1450
    Aug 3 16:16:27 l2tps: [l2tp_l-5] LCP: rec'd Configure Request #12 (Ack-Sent)
    Aug 3 16:16:26 l2tps: [l2tp_l-5] LCP: state change Req-Sent --> Ack-Sent
    Aug 3 16:16:26 l2tps: [l2tp_l-5]   MAGICNUM 0x3426beea
    Aug 3 16:16:26 l2tps: [l2tp_l-5]   MRU 1450
    Aug 3 16:16:26 l2tps: [l2tp_l-5] LCP: SendConfigAck #11
    Aug 3 16:16:26 l2tps: [l2tp_l-5]   MAGICNUM 0x3426beea
    Aug 3 16:16:26 l2tps: [l2tp_l-5]   MRU 1450
    Aug 3 16:16:26 l2tps: [l2tp_l-5] LCP: rec'd Configure Request #11 (Req-Sent)
    Aug 3 16:16:26 l2tps: [l2tp_l-5]   ENDPOINTDISC [802.1] 00 1e 67 ce 84 59
    Aug 3 16:16:26 l2tps: [l2tp_l-5]   MP SHORTSEQ
    Aug 3 16:16:26 l2tps: [l2tp_l-5]   MP MRRU 2048
    Aug 3 16:16:26 l2tps: [l2tp_l-5]   AUTHPROTO CHAP MSOFTv2
    Aug 3 16:16:26 l2tps: [l2tp_l-5]   MAGICNUM 0xcdeb1d4c
    Aug 3 16:16:26 l2tps: [l2tp_l-5]   MRU 1500
    Aug 3 16:16:26 l2tps: [l2tp_l-5]   PROTOCOMP
    Aug 3 16:16:26 l2tps: [l2tp_l-5]   ACFCOMP
    Aug 3 16:16:26 l2tps: [l2tp_l-5] LCP: SendConfigReq #1
    Aug 3 16:16:26 l2tps: [l2tp_l-5] LCP: state change Starting --> Req-Sent
    Aug 3 16:16:26 l2tps: [l2tp_l-5] LCP: Up event
    Aug 3 16:16:26 l2tps: [l2tp_l-5] Link: UP event
    Aug 3 16:16:26 l2tps: [l2tp_l-5] L2TP: Call #18 connected
    Aug 3 16:16:26 l2tps: [l2tp_l-5] LCP: LayerStart
    Aug 3 16:16:26 l2tps: [l2tp_l-5] LCP: state change Initial --> Starting
    Aug 3 16:16:26 l2tps: [l2tp_l-5] LCP: Open event
    Aug 3 16:16:26 l2tps: [l2tp_l-5] Link: OPEN event
    Aug 3 16:16:26 l2tps: [l2tp_l-5] L2TP: Incoming call #18 via control connection 0x803258b10 accepted
    Aug 3 16:16:26 l2tps: L2TP: Incoming call #18 via connection 0x803258b10 received
    Aug 3 16:16:26 l2tps: [l2tp_l-1] LCP: no reply to 7 echo request(s)
    Aug 3 16:16:26 l2tps: L2TP: Control connection 0x803258b10 129.232.211.141 1701 <-> 105.27.116.62 62827 connected
    Aug 3 16:16:25 l2tps: Incoming L2TP packet from 105.27.116.62 62827
    

    This is pfSense 2.4.2_1.

    What is causing this and how can I fix this please?

    thanks

    Roland


  • Rebel Alliance Developer Netgate

    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.



  • @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?



  • @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.


  • Rebel Alliance Developer Netgate

    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.



  • @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.



  • @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).



  • 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?



  • 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?



  • 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.



  • 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.