1
24.1 Legacy Series / DSL-Verbindung kann nach Störung nicht wiederhergestellt werden
« on: March 24, 2024, 04:55:31 pm »
Hallo,
es ist mir schon ein paar Mal aufgefallen, heute habe ich dann genauer nachgeschaut. Es kommt ab und zu vor, dass die PPPoE-Verbindung nicht wiederhergestellt werden kann, wenn providerseitig ein Fehler auftritt. Mein Setup ist aktuellste OPNSense-Version auf Proxmox, ein Draytek Vigor 165 ist per pci-passthrough direkt an die OPNSense-VM angeschlossen. Der zweite Anschluss des Vigors hängt am LAN, so dass ich aus dem Modem die Logs per rsyslogd habe.
Heute Nacht gegen 05:20 Uhr gab es wohl irgendeine Art Störung, die OPNSense meldete einen LCP Timeout, und hat die Verbindung geschlossen. Interessanterweise zeigt das Log vom Draytek keine Auffälligkeiten, außer das ab dann PPPoE-Passthrough durch die OPNSense versucht wurde für den Wiederaufbau. Der scheitert allerdings.
Gegen 16 Uhr habe ich das dann erst bemerkt, und habe zuerst das DSL-Modem stromlos gemacht und neugestartet. Das hat allerdings nichts gebracht, die OPNSense konnte die Verbindung weiterhin nicht aufbauen. Erst ein Neustart der OPNSense hat das Problem gelöst.
Die Logs der OPNSense zeigen da ggf. einen Fehler ("No such file or directory"). Am Draytek-Log ist zu sehen, dass der Status der Leitung weiterhin "SHOWTIME" war, also dort wohl kein Problem bestand. Der Status wurde weiter periodisch abgerufen.
OPNSense:
DrayTek
es ist mir schon ein paar Mal aufgefallen, heute habe ich dann genauer nachgeschaut. Es kommt ab und zu vor, dass die PPPoE-Verbindung nicht wiederhergestellt werden kann, wenn providerseitig ein Fehler auftritt. Mein Setup ist aktuellste OPNSense-Version auf Proxmox, ein Draytek Vigor 165 ist per pci-passthrough direkt an die OPNSense-VM angeschlossen. Der zweite Anschluss des Vigors hängt am LAN, so dass ich aus dem Modem die Logs per rsyslogd habe.
Heute Nacht gegen 05:20 Uhr gab es wohl irgendeine Art Störung, die OPNSense meldete einen LCP Timeout, und hat die Verbindung geschlossen. Interessanterweise zeigt das Log vom Draytek keine Auffälligkeiten, außer das ab dann PPPoE-Passthrough durch die OPNSense versucht wurde für den Wiederaufbau. Der scheitert allerdings.
Gegen 16 Uhr habe ich das dann erst bemerkt, und habe zuerst das DSL-Modem stromlos gemacht und neugestartet. Das hat allerdings nichts gebracht, die OPNSense konnte die Verbindung weiterhin nicht aufbauen. Erst ein Neustart der OPNSense hat das Problem gelöst.
Die Logs der OPNSense zeigen da ggf. einen Fehler ("No such file or directory"). Am Draytek-Log ist zu sehen, dass der Status der Leitung weiterhin "SHOWTIME" war, also dort wohl kein Problem bestand. Der Status wurde weiter periodisch abgerufen.
OPNSense:
Code: [Select]
2024-03-24T15:59:52 Informational ppp [opt6_link0] LCP: LayerStart
2024-03-24T15:59:52 Informational ppp [opt6_link0] LCP: state change Initial --> Starting
2024-03-24T15:59:52 Informational ppp [opt6_link0] LCP: Open event
2024-03-24T15:59:52 Informational ppp [opt6_link0] Link: OPEN event
2024-03-24T15:59:52 Informational ppp [opt6] Bundle: Interface ng0 created
2024-03-24T15:59:52 Informational ppp web: web is not running
2024-03-24T15:59:52 Informational ppp process 56420 started, version 5.9
2024-03-24T15:59:52 Informational ppp
2024-03-24T15:59:52 Informational ppp Multi-link PPP daemon for FreeBSD
### reboot ###
2024-03-24T15:54:31 Informational ppp [opt6_link0] PPPoE: Connecting to ''
2024-03-24T15:54:31 Informational ppp [opt6_link0] Link: reconnection attempt 3272
2024-03-24T15:54:28 Informational ppp [opt6_link0] Link: reconnection attempt 3272 in 3 seconds
2024-03-24T15:54:28 Informational ppp [opt6_link0] LCP: Down event
2024-03-24T15:54:28 Informational ppp [opt6_link0] Link: DOWN event
###################################################################################################
2024-03-24T05:23:45 Informational ppp [opt6_link0] Link: DOWN event
2024-03-24T05:23:45 Informational ppp [opt6_link0] PPPoE connection timeout after 9 seconds
2024-03-24T05:23:36 Informational ppp [opt6_link0] PPPoE: Connecting to ''
2024-03-24T05:23:36 Informational ppp [opt6_link0] Link: reconnection attempt 4
2024-03-24T05:23:32 Informational ppp [opt6_link0] Link: reconnection attempt 4 in 4 seconds
2024-03-24T05:23:32 Informational ppp [opt6_link0] LCP: Down event
2024-03-24T05:23:32 Informational ppp [opt6_link0] Link: DOWN event
2024-03-24T05:23:32 Informational ppp [opt6_link0] PPPoE connection timeout after 9 seconds
2024-03-24T05:23:23 Informational ppp [opt6_link0] PPPoE: Connecting to ''
2024-03-24T05:23:23 Informational ppp [opt6_link0] Link: reconnection attempt 3
2024-03-24T05:23:22 Informational ppp [opt6_link0] Link: reconnection attempt 3 in 1 seconds
2024-03-24T05:23:22 Informational ppp [opt6_link0] LCP: Down event
2024-03-24T05:23:22 Informational ppp [opt6_link0] Link: DOWN event
2024-03-24T05:23:22 Informational ppp [opt6_link0] PPPoE connection timeout after 9 seconds
2024-03-24T05:23:13 Informational ppp [opt6_link0] PPPoE: Connecting to ''
2024-03-24T05:23:13 Informational ppp [opt6_link0] Link: reconnection attempt 2
2024-03-24T05:23:12 Informational ppp [opt6_link0] Link: reconnection attempt 2 in 1 seconds
2024-03-24T05:23:12 Informational ppp [opt6_link0] LCP: Down event
2024-03-24T05:23:12 Informational ppp [opt6_link0] Link: DOWN event
2024-03-24T05:23:12 Informational ppp [opt6_link0] PPPoE: can't connect "[11]:"->"mpd51462-0" and "[9]:"->"left": No such file or directory ####### Fehler?
2024-03-24T05:23:12 Informational ppp [opt6_link0] Link: reconnection attempt 1
2024-03-24T05:23:11 Informational ppp [opt6_link0] Link: reconnection attempt 1 in 1 seconds
2024-03-24T05:23:11 Informational ppp [opt6_link0] LCP: state change Stopping --> Starting
2024-03-24T05:23:11 Informational ppp [opt6_link0] LCP: Down event
2024-03-24T05:23:11 Informational ppp [opt6_link0] Link: DOWN event
2024-03-24T05:23:11 Informational ppp [opt6_link0] can't remove hook mpd51462-0 from node "[11]:": No such file or directory ###### Fehler ?
2024-03-24T05:23:11 Informational ppp [opt6_link0] PPPoE: connection closed
2024-03-24T05:23:11 Informational ppp [opt6_link0] LCP: LayerDown
2024-03-24T05:23:11 Informational ppp [opt6_link0] LCP: SendTerminateReq #2
2024-03-24T05:23:11 Informational ppp [opt6] IPCP: state change Closing --> Initial
2024-03-24T05:23:11 Informational ppp [opt6] Bundle: No NCPs left. Closing links...
2024-03-24T05:23:11 Informational ppp [opt6] IPCP: LayerFinish
2024-03-24T05:23:11 Informational ppp [opt6] IPCP: Down event
2024-03-24T05:23:11 Informational ppp [opt6] IFACE: Rename interface pppoe1 to pppoe1
2024-03-24T05:23:11 Informational ppp [opt6] IFACE: Down event
2024-03-24T05:23:11 Informational ppp [opt6] IPCP: LayerDown
2024-03-24T05:23:11 Informational ppp [opt6] IPCP: SendTerminateReq #4
2024-03-24T05:23:11 Informational ppp [opt6] IPCP: state change Opened --> Closing
2024-03-24T05:23:11 Informational ppp [opt6] IPCP: Close event
2024-03-24T05:23:11 Informational ppp [opt6] Bundle: Status update: up 0 links, total bandwidth 9600 bps
2024-03-24T05:23:11 Informational ppp [opt6_link0] Link: Leave bundle "opt6"
2024-03-24T05:23:11 Informational ppp [opt6_link0] LCP: state change Opened --> Stopping
2024-03-24T05:23:11 Informational ppp [opt6_link0] LCP: peer not responding to echo requests
2024-03-24T05:23:11 Informational ppp [opt6_link0] LCP: no reply to 5 echo request(s)
2024-03-24T05:23:01 Informational ppp [opt6_link0] LCP: no reply to 4 echo request(s)
2024-03-24T05:22:51 Informational ppp [opt6_link0] LCP: no reply to 3 echo request(s)
2024-03-24T05:22:41 Informational ppp [opt6_link0] LCP: no reply to 2 echo request(s)
2024-03-24T05:22:31 Informational ppp [opt6_link0] LCP: no reply to 1 echo request(s
2024-03-22T13:03:11 Informational ppp [opt6] IFACE: Rename interface ng0 to pppoe1
2024-03-22T13:03:11 Informational ppp [opt6] IFACE: Up event
DrayTek
Code: [Select]
Mar 24 05:17:58 192.168.6.252 DrayTek: ADSL_Status:[Mode=35B States=SHOWTIME UpSpeed=46717000 DownSpeed=258775000 SNR=4 Atten=16 ]
Mar 24 05:19:09 192.168.6.252 DrayTek: ADSL_Status:[Mode=35B States=SHOWTIME UpSpeed=46717000 DownSpeed=258775000 SNR=4 Atten=16 ]
Mar 24 05:20:21 192.168.6.252 DrayTek: ADSL_Status:[Mode=35B States=SHOWTIME UpSpeed=46717000 DownSpeed=258775000 SNR=4 Atten=16 ]
Mar 24 05:21:32 192.168.6.252 DrayTek: ADSL_Status:[Mode=35B States=SHOWTIME UpSpeed=46717000 DownSpeed=258775000 SNR=4 Atten=16 ]
Mar 24 05:22:43 192.168.6.252 DrayTek: ADSL_Status:[Mode=35B States=SHOWTIME UpSpeed=46717000 DownSpeed=258775000 SNR=4 Atten=16 ]
Mar 24 05:23:04 192.168.6.252 DrayTek: PASS THROUGH PPPoE <== V:1 T:1 PADI ID:0
Mar 24 05:23:06 192.168.6.252 DrayTek: PASS THROUGH PPPoE <== V:1 T:1 PADI ID:0
Mar 24 05:23:10 192.168.6.252 DrayTek: PASS THROUGH PPPoE <== V:1 T:1 PADI ID:0
Mar 24 05:23:14 192.168.6.252 DrayTek: PASS THROUGH PPPoE <== V:1 T:1 PADI ID:0
Mar 24 05:23:16 192.168.6.252 DrayTek: PASS THROUGH PPPoE <== V:1 T:1 PADI ID:0
Mar 24 05:23:20 192.168.6.252 DrayTek: PASS THROUGH PPPoE <== V:1 T:1 PADI ID:0
Mar 24 05:23:27 192.168.6.252 DrayTek: PASS THROUGH PPPoE <== V:1 T:1 PADI ID:0
Mar 24 05:23:29 192.168.6.252 DrayTek: PASS THROUGH PPPoE <== V:1 T:1 PADI ID:0
Mar 24 05:23:33 192.168.6.252 DrayTek: PASS THROUGH PPPoE <== V:1 T:1 PADI ID:0
Mar 24 05:23:38 192.168.6.252 DrayTek: PASS THROUGH PPPoE <== V:1 T:1 PADI ID:0
Mar 24 05:23:40 192.168.6.252 DrayTek: PASS THROUGH PPPoE <== V:1 T:1 PADI ID:0
Mar 24 05:23:44 192.168.6.252 DrayTek: PASS THROUGH PPPoE <== V:1 T:1 PADI ID:0
Mar 24 05:23:50 192.168.6.252 DrayTek: PASS THROUGH PPPoE <== V:1 T:1 PADI ID:0
Mar 24 05:23:52 192.168.6.252 DrayTek: PASS THROUGH PPPoE <== V:1 T:1 PADI ID:0
Mar 24 05:23:55 192.168.6.252 DrayTek: ADSL_Status:[Mode=35B States=SHOWTIME UpSpeed=46717000 DownSpeed=258775000 SNR=4 Atten=16 ] ###### Status OK
Mar 24 05:23:56 192.168.6.252 DrayTek: PASS THROUGH PPPoE <== V:1 T:1 PADI ID:0
Mar 24 05:24:03 192.168.6.252 DrayTek: PASS THROUGH PPPoE <== V:1 T:1 PADI ID:0
Mar 24 05:24:05 192.168.6.252 DrayTek: PASS THROUGH PPPoE <== V:1 T:1 PADI ID:0
Mar 24 05:24:09 192.168.6.252 DrayTek: PASS THROUGH PPPoE <== V:1 T:1 PADI ID:0
Mar 24 05:24:14 192.168.6.252 DrayTek: PASS THROUGH PPPoE <== V:1 T:1 PADI ID:0
Mar 24 05:24:16 192.168.6.252 DrayTek: PASS THROUGH PPPoE <== V:1 T:1 PADI ID:0
Mar 24 05:24:20 192.168.6.252 DrayTek: PASS THROUGH PPPoE <== V:1 T:1 PADI ID:0
Mar 24 05:24:24 192.168.6.252 DrayTek: PASS THROUGH PPPoE <== V:1 T:1 PADI ID:0
Mar 24 05:24:26 192.168.6.252 DrayTek: PASS THROUGH PPPoE <== V:1 T:1 PADI ID:0
Mar 24 05:24:49 192.168.6.252 DrayTek: PASS THROUGH PPPoE <== V:1 T:1 PADI ID:0
Mar 24 05:24:53 192.168.6.252 DrayTek: PASS THROUGH PPPoE <== V:1 T:1 PADI ID:0
Mar 24 05:24:58 192.168.6.252 DrayTek: PASS THROUGH PPPoE <== V:1 T:1 PADI ID:0
Mar 24 05:25:00 192.168.6.252 DrayTek: PASS THROUGH PPPoE <== V:1 T:1 PADI ID:0
Mar 24 05:25:04 192.168.6.252 DrayTek: PASS THROUGH PPPoE <== V:1 T:1 PADI ID:0
Mar 24 05:25:06 192.168.6.252 DrayTek: ADSL_Status:[Mode=35B States=SHOWTIME UpSpeed=46717000 DownSpeed=258775000 SNR=4 Atten=16 ] ###### Status OK
Mar 24 05:25:11 192.168.6.252 DrayTek: PASS THROUGH PPPoE <== V:1 T:1 PADI ID:0
Mar 24 05:25:13 192.168.6.252 DrayTek: PASS THROUGH PPPoE <== V:1 T:1 PADI ID:0
Mar 24 05:25:17 192.168.6.252 DrayTek: PASS THROUGH PPPoE <== V:1 T:1 PADI ID:0
Mar 24 05:25:21 192.168.6.252 DrayTek: PASS THROUGH PPPoE <== V:1 T:1 PADI ID:0
Mar 24 05:25:23 192.168.6.252 DrayTek: PASS THROUGH PPPoE <== V:1 T:1 PADI ID:0
Mar 24 05:25:27 192.168.6.252 DrayTek: PASS THROUGH PPPoE <== V:1 T:1 PADI ID:0
Mar 24 05:25:31 192.168.6.252 DrayTek: PASS THROUGH PPPoE <== V:1 T:1 PADI ID:0
Mar 24 05:25:33 192.168.6.252 DrayTek: PASS THROUGH PPPoE <== V:1 T:1 PADI ID:0
Mar 24 05:25:37 192.168.6.252 DrayTek: PASS THROUGH PPPoE <== V:1 T:1 PADI ID:0
Mar 24 05:25:42 192.168.6.252 DrayTek: PASS THROUGH PPPoE <== V:1 T:1 PADI ID:0
Mar 24 05:25:44 192.168.6.252 DrayTek: PASS THROUGH PPPoE <== V:1 T:1 PADI ID:0
Mar 24 05:25:48 192.168.6.252 DrayTek: PASS THROUGH PPPoE <== V:1 T:1 PADI ID:0
Mar 24 05:25:54 192.168.6.252 DrayTek: PASS THROUGH PPPoE <== V:1 T:1 PADI ID:0
Mar 24 05:25:56 192.168.6.252 DrayTek: PASS THROUGH PPPoE <== V:1 T:1 PADI ID:0
Mar 24 05:26:00 192.168.6.252 DrayTek: PASS THROUGH PPPoE <== V:1 T:1 PADI ID:0
Mar 24 05:26:07 192.168.6.252 DrayTek: PASS THROUGH PPPoE <== V:1 T:1 PADI ID:0
Mar 24 05:26:09 192.168.6.252 DrayTek: PASS THROUGH PPPoE <== V:1 T:1 PADI ID:0
Mar 24 05:26:13 192.168.6.252 DrayTek: PASS THROUGH PPPoE <== V:1 T:1 PADI ID:0
Mar 24 05:26:18 192.168.6.252 DrayTek: ADSL_Status:[Mode=35B States=SHOWTIME UpSpeed=46717000 DownSpeed=258775000 SNR=4 Atten=16 ] ###### Status OK