WAN Interface lost connection after "reset interface" (pppoe)

Started by ducky87, January 31, 2022, 09:45:01 AM

Previous topic - Next topic
Print
Go Down Pages 1 2
User actions
February 02, 2022, 01:28:33 PM #15
Quote from: franco on February 02, 2022, 12:38:01 PM
Still missing the system log here.

Any specifics to look out for in the system.log?

The patch seems to work. Below the log from the cron triggered disconnect.

Code Select

2022-02-02T13:15:38 Informational ppp [wan]   <IP> -> <IP>
2022-02-02T13:15:38 Informational ppp [wan] IPCP: LayerUp
2022-02-02T13:15:38 Informational ppp [wan] IPCP: state change Ack-Sent --> Opened
2022-02-02T13:15:38 Informational ppp [wan]   IPADDR <IP>
2022-02-02T13:15:38 Informational ppp [wan] IPCP: rec'd Configure Ack #3 (Ack-Sent)
2022-02-02T13:15:38 Informational ppp [wan]   IPADDR <IP>
2022-02-02T13:15:38 Informational ppp [wan] IPCP: SendConfigReq #3
2022-02-02T13:15:38 Informational ppp [wan]     <IP> is OK
2022-02-02T13:15:38 Informational ppp [wan]   IPADDR <IP>
2022-02-02T13:15:38 Informational ppp [wan] IPCP: rec'd Configure Nak #2 (Ack-Sent)
2022-02-02T13:15:38 Informational ppp [wan] IFACE: Rename interface ng0 to pppoe1
2022-02-02T13:15:38 Informational ppp [wan] IFACE: Up event
2022-02-02T13:15:37 Informational ppp [wan]   <IPv6> -> <IPv6>
2022-02-02T13:15:37 Informational ppp [wan] IPV6CP: LayerUp
2022-02-02T13:15:37 Informational ppp [wan] IPV6CP: state change Ack-Sent --> Opened
2022-02-02T13:15:37 Informational ppp [wan] IPV6CP: rec'd Configure Ack #1 (Ack-Sent)
2022-02-02T13:15:37 Informational ppp [wan]   IPADDR 0.0.0.0
2022-02-02T13:15:37 Informational ppp [wan] IPCP: SendConfigReq #2
2022-02-02T13:15:37 Informational ppp [wan]   COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
2022-02-02T13:15:37 Informational ppp [wan] IPCP: rec'd Configure Reject #1 (Ack-Sent)
2022-02-02T13:15:37 Informational ppp [wan] IPV6CP: state change Req-Sent --> Ack-Sent
2022-02-02T13:15:37 Informational ppp [wan] IPV6CP: SendConfigAck #1
2022-02-02T13:15:37 Informational ppp [wan] IPV6CP: rec'd Configure Request #1 (Req-Sent)
2022-02-02T13:15:37 Informational ppp [wan] IPCP: state change Req-Sent --> Ack-Sent
2022-02-02T13:15:37 Informational ppp [wan]   IPADDR <IP>
2022-02-02T13:15:37 Informational ppp [wan] IPCP: SendConfigAck #1
2022-02-02T13:15:37 Informational ppp [wan]     <IP> is OK
2022-02-02T13:15:37 Informational ppp [wan]   IPADDR <IP>
2022-02-02T13:15:37 Informational ppp [wan] IPCP: rec'd Configure Request #1 (Req-Sent)
2022-02-02T13:15:37 Informational ppp [wan] IPV6CP: SendConfigReq #1
2022-02-02T13:15:37 Informational ppp [wan] IPV6CP: state change Starting --> Req-Sent
2022-02-02T13:15:37 Informational ppp [wan] IPV6CP: Up event
2022-02-02T13:15:37 Informational ppp [wan]   COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
2022-02-02T13:15:37 Informational ppp [wan]   IPADDR 0.0.0.0
2022-02-02T13:15:37 Informational ppp [wan] IPCP: SendConfigReq #1
2022-02-02T13:15:37 Informational ppp [wan] IPCP: state change Starting --> Req-Sent
2022-02-02T13:15:37 Informational ppp [wan] IPCP: Up event
2022-02-02T13:15:37 Informational ppp [wan] IPV6CP: LayerStart
2022-02-02T13:15:37 Informational ppp [wan] IPV6CP: state change Initial --> Starting
2022-02-02T13:15:37 Informational ppp [wan] IPV6CP: Open event
2022-02-02T13:15:37 Informational ppp [wan] IPCP: LayerStart
2022-02-02T13:15:37 Informational ppp [wan] IPCP: state change Initial --> Starting
2022-02-02T13:15:37 Informational ppp [wan] IPCP: Open event
2022-02-02T13:15:37 Informational ppp [wan] Bundle: Status update: up 1 link, total bandwidth 64000 bps
2022-02-02T13:15:37 Informational ppp [wan_link0] Link: Join bundle "wan"
2022-02-02T13:15:37 Informational ppp [wan_link0] Link: Matched action 'bundle "wan" ""'
2022-02-02T13:15:37 Informational ppp [wan_link0] LCP: authorization successful
2022-02-02T13:15:37 Informational ppp [wan_link0]   MESG: [UI-SBR:55040,11136;UI-LINEID:1UND1.DEU.DTAG.CX6JK;]
2022-02-02T13:15:37 Informational ppp [wan_link0] PAP: rec'd ACK #1 len: 57
2022-02-02T13:15:37 Informational ppp [wan_link0] LCP: LayerUp
2022-02-02T13:15:37 Informational ppp [wan_link0] PAP: sending REQUEST #1 len: 52
2022-02-02T13:15:37 Informational ppp [wan_link0] PAP: using authname "***********"
2022-02-02T13:15:37 Informational ppp [wan_link0] LCP: auth: peer wants PAP, I want nothing
2022-02-02T13:15:37 Informational ppp [wan_link0] LCP: state change Ack-Rcvd --> Opened
2022-02-02T13:15:37 Informational ppp [wan_link0]   MAGICNUM 0xb51e5e1f
2022-02-02T13:15:37 Informational ppp [wan_link0]   AUTHPROTO PAP
2022-02-02T13:15:37 Informational ppp [wan_link0]   MRU 1492
2022-02-02T13:15:37 Informational ppp [wan_link0] LCP: SendConfigAck #2
2022-02-02T13:15:37 Informational ppp [wan_link0]   MAGICNUM 0xb51e5e1f
2022-02-02T13:15:37 Informational ppp [wan_link0]   AUTHPROTO PAP
2022-02-02T13:15:37 Informational ppp [wan_link0]   MRU 1492
2022-02-02T13:15:37 Informational ppp [wan_link0] LCP: rec'd Configure Request #2 (Ack-Rcvd)
2022-02-02T13:15:37 Informational ppp [wan_link0] LCP: state change Req-Sent --> Ack-Rcvd
2022-02-02T13:15:37 Informational ppp [wan_link0]   MAGICNUM 0xe0085d10
2022-02-02T13:15:37 Informational ppp [wan_link0]   MRU 1492
2022-02-02T13:15:37 Informational ppp [wan_link0] LCP: rec'd Configure Ack #3 (Req-Sent)
2022-02-02T13:15:37 Informational ppp [wan_link0]   MAGICNUM 0xe0085d10
2022-02-02T13:15:37 Informational ppp [wan_link0]   MRU 1492
2022-02-02T13:15:37 Informational ppp [wan_link0] LCP: SendConfigReq #3
2022-02-02T13:15:37 Informational ppp [wan_link0] LCP: state change Ack-Rcvd --> Req-Sent
2022-02-02T13:15:35 Informational ppp [wan_link0] LCP: state change Req-Sent --> Ack-Rcvd
2022-02-02T13:15:35 Informational ppp [wan_link0]   MAGICNUM 0xe0085d10
2022-02-02T13:15:35 Informational ppp [wan_link0]   MRU 1492
2022-02-02T13:15:35 Informational ppp [wan_link0] LCP: rec'd Configure Ack #2 (Req-Sent)
2022-02-02T13:15:35 Informational ppp [wan_link0]   MAGICNUM 0xe0085d10
2022-02-02T13:15:35 Informational ppp [wan_link0]   MRU 1492
2022-02-02T13:15:35 Informational ppp [wan_link0] LCP: SendConfigReq #2
2022-02-02T13:15:35 Informational ppp [wan_link0]   PROTOCOMP
2022-02-02T13:15:35 Informational ppp [wan_link0] LCP: rec'd Configure Reject #1 (Req-Sent)
2022-02-02T13:15:35 Informational ppp [wan_link0]   MAGICNUM 0xe0085d10
2022-02-02T13:15:35 Informational ppp [wan_link0]   MRU 1492
2022-02-02T13:15:35 Informational ppp [wan_link0]   PROTOCOMP
2022-02-02T13:15:35 Informational ppp [wan_link0] LCP: SendConfigReq #1
2022-02-02T13:15:35 Informational ppp [wan_link0] LCP: state change Starting --> Req-Sent
2022-02-02T13:15:35 Informational ppp [wan_link0] LCP: Up event
2022-02-02T13:15:35 Informational ppp [wan_link0] Link: UP event
2022-02-02T13:15:35 Informational ppp [wan_link0] PPPoE: connection successful
2022-02-02T13:15:34 Informational ppp PPPoE: rec'd ACNAME "************"
2022-02-02T13:15:34 Informational ppp [wan_link0] PPPoE: Connecting to '1und1'
2022-02-02T13:15:34 Informational ppp [wan_link0] LCP: LayerStart
2022-02-02T13:15:34 Informational ppp [wan_link0] LCP: state change Initial --> Starting
2022-02-02T13:15:34 Informational ppp [wan_link0] LCP: Open event
2022-02-02T13:15:34 Informational ppp [wan_link0] Link: OPEN event
2022-02-02T13:15:34 Informational ppp [wan] Bundle: Interface ng0 created
2022-02-02T13:15:34 Informational ppp web: web is not running
2022-02-02T13:15:34 Informational ppp process 14684 started, version 5.9
2022-02-02T13:15:34 Informational ppp
2022-02-02T13:15:34 Informational ppp Multi-link PPP daemon for FreeBSD
2022-02-02T13:15:34 Informational ppp process 53531 terminated
2022-02-02T13:15:34 Informational ppp [wan_link0] Link: Shutdown
2022-02-02T13:15:34 Informational ppp [wan] Bundle: Shutdown
2022-02-02T13:15:32 Informational ppp [wan_link0] LCP: Close event
2022-02-02T13:15:32 Informational ppp [wan_link0] Link: CLOSE event
2022-02-02T13:15:32 Informational ppp [wan_link0] LCP: state change Closing --> Initial
2022-02-02T13:15:32 Informational ppp [wan_link0] LCP: LayerFinish
2022-02-02T13:15:32 Informational ppp [wan_link0] LCP: Down event
2022-02-02T13:15:32 Informational ppp [wan_link0] LCP: state change Stopping --> Closing
2022-02-02T13:15:32 Informational ppp [wan_link0] LCP: Close event
2022-02-02T13:15:32 Informational ppp [wan_link0] Link: giving up after 0 reconnection attempts
2022-02-02T13:15:32 Informational ppp [wan_link0] Link: DOWN event
2022-02-02T13:15:32 Informational ppp [wan_link0] PPPoE: connection closed
2022-02-02T13:15:32 Informational ppp [wan_link0] LCP: LayerDown
2022-02-02T13:15:32 Informational ppp [wan_link0] LCP: SendTerminateAck #4
2022-02-02T13:15:32 Informational ppp [wan] IPV6CP: state change Closed --> Initial
2022-02-02T13:15:32 Informational ppp [wan] IPV6CP: Down event
2022-02-02T13:15:32 Informational ppp [wan] IPCP: state change Closed --> Initial
2022-02-02T13:15:32 Informational ppp [wan] IPCP: Down event
2022-02-02T13:15:32 Informational ppp [wan] IPV6CP: Close event
2022-02-02T13:15:32 Informational ppp [wan] IPCP: Close event
2022-02-02T13:15:32 Informational ppp [wan] Bundle: Status update: up 0 links, total bandwidth 9600 bps
2022-02-02T13:15:32 Informational ppp [wan_link0] Link: Leave bundle "wan"
2022-02-02T13:15:32 Informational ppp [wan_link0] LCP: state change Opened --> Stopping
2022-02-02T13:15:32 Informational ppp [wan_link0] LCP: rec'd Terminate Request #3 (Opened)
2022-02-02T13:15:32 Informational ppp [wan] Bundle: closing link "wan_link0"...
2022-02-02T13:15:32 Informational ppp [wan] Bundle: No NCPs left. Closing links...
2022-02-02T13:15:32 Informational ppp [wan] IPV6CP: LayerFinish
2022-02-02T13:15:32 Informational ppp [wan] IPV6CP: state change Closing --> Closed
2022-02-02T13:15:32 Informational ppp [wan] IPV6CP: rec'd Terminate Ack #2 (Closing)
2022-02-02T13:15:32 Informational ppp [wan] IPCP: LayerFinish
2022-02-02T13:15:32 Informational ppp [wan] IPCP: state change Closing --> Closed
2022-02-02T13:15:32 Informational ppp [wan] IPCP: rec'd Terminate Ack #4 (Closing)
2022-02-02T13:15:32 Informational ppp [wan] IPCP: SendTerminateReq #5
2022-02-02T13:15:32 Informational ppp [wan] IPV6CP: SendTerminateReq #3
2022-02-02T13:15:32 Informational ppp [wan] IFACE: Rename interface pppoe1 to pppoe1
2022-02-02T13:15:32 Informational ppp [wan] IFACE: Down event
2022-02-02T13:15:01 Informational ppp [wan] IPV6CP: LayerDown
2022-02-02T13:15:01 Informational ppp [wan] IPV6CP: SendTerminateReq #2
2022-02-02T13:15:01 Informational ppp [wan] IPV6CP: state change Opened --> Closing
2022-02-02T13:15:01 Informational ppp [wan] IPV6CP: Close event
2022-02-02T13:15:01 Informational ppp [wan] IFACE: Removing IPv4 address from pppoe1 failed: Can't assign requested address
2022-02-02T13:15:01 Informational ppp [wan] IFACE: Delete route 0.0.0.0/0 <IP> failed: No such process
2022-02-02T13:15:00 Informational ppp [wan] IPCP: LayerDown
2022-02-02T13:15:00 Informational ppp [wan] IPCP: SendTerminateReq #4
2022-02-02T13:15:00 Informational ppp [wan] IPCP: state change Opened --> Closing
2022-02-02T13:15:00 Informational ppp [wan] IPCP: Close event
2022-02-02T13:15:00 Informational ppp [wan] IFACE: Close event
2022-02-02T13:15:00 Informational ppp caught fatal signal TERM
February 02, 2022, 01:31:55 PM #16 Last Edit: February 02, 2022, 02:23:14 PM by franco
"DEVD" events from system log would be most helpful.

I mean we could get rid of -k option now and leave it at that. This sure is interesting and might explain some of the issues we've had the past with reconnect loops.


Cheers,
Franco
February 02, 2022, 02:21:28 PM #17
Patched my system too. Will report back tomorrow. Thanks so far.
Assumption is the mother of all f... ups!
February 02, 2022, 09:06:31 PM #18
Quote from: franco on February 02, 2022, 01:31:55 PM
"DEVD" events from system log would be most helpful.

Hmm... a grep for "DEVD" on my latest log in /var/log/system does not find anything. Do I need to up some logging levels somewhere?
February 02, 2022, 09:10:47 PM #19
Should look something like this

2022-01-06T08:05:58   Error   opnsense-devel   /usr/local/etc/rc.linkup: DEVD: Ethernet attached event for dynamic lan(igb0)


Cheers,
Franco
February 03, 2022, 08:59:34 AM #20
Nothing in my logs, however I have the patch installed. I assume this would only occur without the patch?
February 03, 2022, 09:09:40 AM #21
No this would always be, but maybe I'm overthinking it and it doesn't happen on the PPPoE interface.

So now with the patch this works better?


Cheers,
Franco
February 03, 2022, 09:17:41 AM #22
So this morning everything is working fine. So I would say: problem solved.

BTW
No DEVD in the logging over here.
Assumption is the mother of all f... ups!
February 03, 2022, 09:19:57 AM #23
And that's with only one nightly cron job in there? Apply might have been forgotten (happens to me too). Just double-checking.


Cheers,
Franco
February 03, 2022, 09:35:09 AM #24
Yes, patch was working tonight in one single cron job, so far no issues. Definitely applied the cron table, as I changed it multiple times yesterday for testing.
February 03, 2022, 09:37:34 AM #25
Super, thanks. I think we'll add this to 22.1.1 then. I don't have a technical objection at this point.


Cheers,
Franco
February 03, 2022, 10:03:15 AM #26
Quote from: franco on February 03, 2022, 09:19:57 AM
And that's with only one nightly cron job in there? Apply might have been forgotten (happens to me too). Just double-checking.

Yes this is with running the cron at 3:07 only  :)
Assumption is the mother of all f... ups!
Print
Go Up Pages 1 2
User actions