PPPoE connection drops in irregular intervals

[Bene93]

Hello everyone.

I am having an issue with PPPoE since upgrading from 23.1 to 23.1.9. OPNsense is directly installed on a Sophos SG 115 Appliance and I have just been using it for about a week.

The problem is, that my WAN-connection, which is a PPPoE connection, currently completely drops and resyncs in very irregular intervals, which also binds a new set of IP-addresses to my WAN-interface. This happens at least every 45-60 minutes, but in most cases, the connection resynced after just 5-10 minutes.

My ISP is 1&1, so it is a standard consumer VDSL-line.

Every time the connection drops, the general system log shows the following:

Code: [Select]

<13>1 2023-06-08T12:40:17+02:00 HOST opnsense 56809 - [meta sequenceId="6"] /usr/local/etc/rc.newwanip: Failed to detect IP for WAN[wan]
<13>1 2023-06-08T12:40:18+02:00 HOST opnsense 64083 - [meta sequenceId="7"] /usr/local/etc/rc.newwanipv6: Failed to detect IP for WAN[wan]
<13>1 2023-06-08T12:40:24+02:00 HOST opnsense 81683 - [meta sequenceId="8"] /usr/local/etc/rc.newwanipv6: Failed to detect IP for WAN[wan]
<13>1 2023-06-08T12:40:24+02:00 HOST opnsense 83672 - [meta sequenceId="9"] /usr/local/etc/rc.newwanip: IP renewal starting (new: XXX.XXX.XXX.XXX, old: XXX.XXX.XXX.XXX, interface: WAN[wan], device: pppoe0, force: yes)
<13>1 2023-06-08T12:40:24+02:00 HOST dhcp6c 87108 - [meta sequenceId="10"] RTSOLD script - Sending SIGHUP to dhcp6c
<13>1 2023-06-08T12:40:24+02:00 HOST opnsense 83672 - [meta sequenceId="11"] /usr/local/etc/rc.newwanip: ROUTING: entering configure using 'wan'
<13>1 2023-06-08T12:40:24+02:00 HOST opnsense 83672 - [meta sequenceId="12"] /usr/local/etc/rc.newwanip: ROUTING: configuring inet default gateway on wan
<13>1 2023-06-08T12:40:24+02:00 HOST opnsense 83672 - [meta sequenceId="13"] /usr/local/etc/rc.newwanip: ROUTING: keeping current inet default gateway 'XXX.XXX.XXX.XXX'
<13>1 2023-06-08T12:40:24+02:00 HOST opnsense 83672 - [meta sequenceId="14"] /usr/local/etc/rc.newwanip: plugins_configure monitor (,WAN_PPPOE)
<13>1 2023-06-08T12:40:24+02:00 HOST opnsense 83672 - [meta sequenceId="15"] /usr/local/etc/rc.newwanip: plugins_configure monitor (execute task : dpinger_configure_do(,WAN_PPPOE))
<13>1 2023-06-08T12:40:24+02:00 HOST opnsense 83672 - [meta sequenceId="16"] /usr/local/etc/rc.newwanip: Chose to bind WAN_PPPOE on XXX.XXX.XXX.XXX since we could not find a proper match.
<13>1 2023-06-08T12:40:24+02:00 HOST dhcp6c 90916 - [meta sequenceId="17"] dhcp6c_script: REQUEST on pppoe0 executing
<13>1 2023-06-08T12:40:24+02:00 HOST dhcp6c 92496 - [meta sequenceId="18"] dhcp6c_script: REQUEST on pppoe0 renewal
<13>1 2023-06-08T12:40:24+02:00 HOST dhcp6c 93596 - [meta sequenceId="19"] RTSOLD script - Sending SIGHUP to dhcp6c
<13>1 2023-06-08T12:40:25+02:00 HOST opnsense 83672 - [meta sequenceId="20"] /usr/local/etc/rc.newwanip: IP address change detected, killing states of old ip XXX.XXX.XXX.XXX
<13>1 2023-06-08T12:40:25+02:00 HOST opnsense 83672 - [meta sequenceId="21"] /usr/local/etc/rc.newwanip: plugins_configure vpn (,wan)
<13>1 2023-06-08T12:40:25+02:00 HOST opnsense 83672 - [meta sequenceId="22"] /usr/local/etc/rc.newwanip: plugins_configure vpn (execute task : ipsec_configure_do(,wan))
<13>1 2023-06-08T12:40:25+02:00 HOST opnsense 83672 - [meta sequenceId="23"] /usr/local/etc/rc.newwanip: plugins_configure vpn (execute task : openvpn_configure_do(,wan))
<13>1 2023-06-08T12:40:25+02:00 HOST opnsense 83672 - [meta sequenceId="24"] /usr/local/etc/rc.newwanip: plugins_configure newwanip (,wan)
<13>1 2023-06-08T12:40:25+02:00 HOST opnsense 83672 - [meta sequenceId="25"] /usr/local/etc/rc.newwanip: plugins_configure newwanip (execute task : dnsmasq_configure_do())
<13>1 2023-06-08T12:40:25+02:00 HOST opnsense 83672 - [meta sequenceId="26"] /usr/local/etc/rc.newwanip: plugins_configure newwanip (execute task : ntpd_configure_do())
<13>1 2023-06-08T12:40:25+02:00 HOST opnsense 83672 - [meta sequenceId="27"] /usr/local/etc/rc.newwanip: plugins_configure newwanip (execute task : opendns_configure_do())
<13>1 2023-06-08T12:40:25+02:00 HOST opnsense 83672 - [meta sequenceId="28"] /usr/local/etc/rc.newwanip: plugins_configure newwanip (execute task : openssh_configure_do(,wan))
<13>1 2023-06-08T12:40:25+02:00 HOST opnsense 83672 - [meta sequenceId="29"] /usr/local/etc/rc.newwanip: plugins_configure newwanip (execute task : unbound_configure_do(,wan))
<13>1 2023-06-08T12:40:25+02:00 HOST opnsense 93703 - [meta sequenceId="30"] /usr/local/etc/rc.newwanipv6: IP renewal starting (new: XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX, old: XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX, interface: WAN[wan], device: pppoe0, force: yes)
<13>1 2023-06-08T12:40:25+02:00 HOST opnsense 93703 - [meta sequenceId="31"] /usr/local/etc/rc.newwanipv6: plugins_configure dhcp (,inet6)
<13>1 2023-06-08T12:40:25+02:00 HOST opnsense 93703 - [meta sequenceId="32"] /usr/local/etc/rc.newwanipv6: plugins_configure dhcp (execute task : dhcpd_dhcp_configure(,inet6))
<13>1 2023-06-08T12:40:25+02:00 HOST dhcp6c 99164 - [meta sequenceId="33"] dhcp6c_script: REQUEST on pppoe0 executing
<13>1 2023-06-08T12:40:25+02:00 HOST dhcp6c 1200 - [meta sequenceId="34"] dhcp6c_script: REQUEST on pppoe0 renewal
<13>1 2023-06-08T12:40:27+02:00 HOST opnsense 1350 - [meta sequenceId="35"] /usr/local/etc/rc.newwanipv6: IP renewal starting (new: XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX, old: XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX:XXXX, interface: WAN[wan], device: pppoe0, force: yes)
<13>1 2023-06-08T12:40:27+02:00 HOST opnsense 1350 - [meta sequenceId="36"] /usr/local/etc/rc.newwanipv6: plugins_configure dhcp (,inet6)
<13>1 2023-06-08T12:40:27+02:00 HOST opnsense 1350 - [meta sequenceId="37"] /usr/local/etc/rc.newwanipv6: plugins_configure dhcp (execute task : dhcpd_dhcp_configure(,inet6))
<11>1 2023-06-08T12:40:27+02:00 HOST opnsense 1350 - [meta sequenceId="38"] /usr/local/etc/rc.newwanipv6: The command '/bin/kill -'TERM' '6390'' returned exit code '1', the output was 'kill: 6390: No such process'
<13>1 2023-06-08T12:40:30+02:00 HOST opnsense 83672 - [meta sequenceId="39"] /usr/local/etc/rc.newwanip: plugins_configure newwanip (execute task : vxlan_configure_do())
<13>1 2023-06-08T12:40:30+02:00 HOST opnsense 83672 - [meta sequenceId="40"] /usr/local/etc/rc.newwanip: plugins_configure newwanip (execute task : webgui_configure_do(,wan))
<11>1 2023-06-08T12:40:31+02:00 HOST opnsense 93703 - [meta sequenceId="41"] /usr/local/etc/rc.newwanipv6: The command '/usr/local/sbin/dhcpd -6 -user dhcpd -group dhcpd -chroot /var/dhcpd -cf /etc/dhcpdv6.conf -pf /var/run/dhcpdv6.pid igb0' returned exit code '1', the output was 'Internet Systems Consortium DHCP Server 4.4.3-P1 Copyright 2004-2022 Internet Systems Consortium. All rights reserved. For info, please visit https://www.isc.org/software/dhcp/ Config file: /etc/dhcpdv6.conf Database file: /var/db/dhcpd6.leases PID file: /var/run/dhcpdv6.pid There's already a DHCP server running.  If you think you have received this message due to a bug rather than a configuration issue please read the section on submitting bugs on either our web page at www.isc.org or in the README file before submitting a bug.  These pages explain the proper process and the information we find helpful for debugging.  exiting.'
<11>1 2023-06-08T12:40:31+02:00 HOST opnsense 93703 - [meta sequenceId="42"] /usr/local/etc/rc.newwanipv6: The command '/usr/sbin/daemon -f -p '/var/run/dhcpleases6.pid' '/usr/local/opnsense/scripts/dhcp/prefixes.sh'' returned exit code '3', the output was 'daemon: process already running, pid: 19561'
<13>1 2023-06-08T12:40:32+02:00 HOST opnsense 93703 - [meta sequenceId="43"] /usr/local/etc/rc.newwanipv6: ROUTING: entering configure using 'wan'
<13>1 2023-06-08T12:40:32+02:00 HOST opnsense 93703 - [meta sequenceId="44"] /usr/local/etc/rc.newwanipv6: ROUTING: configuring inet6 default gateway on wan
<13>1 2023-06-08T12:40:32+02:00 HOST opnsense 1350 - [meta sequenceId="45"] /usr/local/etc/rc.newwanipv6: ROUTING: entering configure using 'wan'
<13>1 2023-06-08T12:40:32+02:00 HOST opnsense 93703 - [meta sequenceId="46"] /usr/local/etc/rc.newwanipv6: ROUTING: keeping current inet6 default gateway 'fe80::XXXX:XXXX:XXXX:XXXX%pppoe0'
<13>1 2023-06-08T12:40:32+02:00 HOST opnsense 93703 - [meta sequenceId="47"] /usr/local/etc/rc.newwanipv6: plugins_configure monitor (,WAN_DHCP6)
<13>1 2023-06-08T12:40:32+02:00 HOST opnsense 93703 - [meta sequenceId="48"] /usr/local/etc/rc.newwanipv6: plugins_configure monitor (execute task : dpinger_configure_do(,WAN_DHCP6))
<13>1 2023-06-08T12:40:32+02:00 HOST opnsense 1350 - [meta sequenceId="49"] /usr/local/etc/rc.newwanipv6: ROUTING: configuring inet6 default gateway on wan
<13>1 2023-06-08T12:40:32+02:00 HOST opnsense 1350 - [meta sequenceId="50"] /usr/local/etc/rc.newwanipv6: ROUTING: keeping current inet6 default gateway 'fe80::XXXX:XXXX:XXXX:XXXX%pppoe0'
<13>1 2023-06-08T12:40:32+02:00 HOST opnsense 1350 - [meta sequenceId="51"] /usr/local/etc/rc.newwanipv6: plugins_configure monitor (,WAN_DHCP6)
<13>1 2023-06-08T12:40:32+02:00 HOST opnsense 1350 - [meta sequenceId="52"] /usr/local/etc/rc.newwanipv6: plugins_configure monitor (execute task : dpinger_configure_do(,WAN_DHCP6))
<13>1 2023-06-08T12:40:32+02:00 HOST opnsense 93703 - [meta sequenceId="53"] /usr/local/etc/rc.newwanipv6: ROUTING: entering configure using 'lan'
<13>1 2023-06-08T12:40:32+02:00 HOST opnsense 1350 - [meta sequenceId="54"] /usr/local/etc/rc.newwanipv6: ROUTING: entering configure using 'lan'
<13>1 2023-06-08T12:40:33+02:00 HOST opnsense 93703 - [meta sequenceId="55"] /usr/local/etc/rc.newwanipv6: plugins_configure vpn (,wan)
<13>1 2023-06-08T12:40:33+02:00 HOST opnsense 93703 - [meta sequenceId="56"] /usr/local/etc/rc.newwanipv6: plugins_configure vpn (execute task : ipsec_configure_do(,wan))
<13>1 2023-06-08T12:40:33+02:00 HOST opnsense 93703 - [meta sequenceId="57"] /usr/local/etc/rc.newwanipv6: plugins_configure vpn (execute task : openvpn_configure_do(,wan))
<13>1 2023-06-08T12:40:33+02:00 HOST opnsense 93703 - [meta sequenceId="58"] /usr/local/etc/rc.newwanipv6: plugins_configure newwanip (,wan)
<13>1 2023-06-08T12:40:33+02:00 HOST opnsense 93703 - [meta sequenceId="59"] /usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : dnsmasq_configure_do())
<13>1 2023-06-08T12:40:33+02:00 HOST opnsense 93703 - [meta sequenceId="60"] /usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : ntpd_configure_do())
<13>1 2023-06-08T12:40:33+02:00 HOST opnsense 93703 - [meta sequenceId="61"] /usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : opendns_configure_do())
<13>1 2023-06-08T12:40:33+02:00 HOST opnsense 93703 - [meta sequenceId="62"] /usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : openssh_configure_do(,wan))
<13>1 2023-06-08T12:40:33+02:00 HOST opnsense 93703 - [meta sequenceId="63"] /usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : unbound_configure_do(,wan))
<13>1 2023-06-08T12:40:34+02:00 HOST opnsense 1350 - [meta sequenceId="64"] /usr/local/etc/rc.newwanipv6: plugins_configure vpn (,wan)
<13>1 2023-06-08T12:40:34+02:00 HOST opnsense 1350 - [meta sequenceId="65"] /usr/local/etc/rc.newwanipv6: plugins_configure vpn (execute task : ipsec_configure_do(,wan))
<13>1 2023-06-08T12:40:34+02:00 HOST opnsense 1350 - [meta sequenceId="66"] /usr/local/etc/rc.newwanipv6: plugins_configure vpn (execute task : openvpn_configure_do(,wan))
<13>1 2023-06-08T12:40:34+02:00 HOST opnsense 1350 - [meta sequenceId="67"] /usr/local/etc/rc.newwanipv6: plugins_configure newwanip (,wan)
<13>1 2023-06-08T12:40:34+02:00 HOST opnsense 1350 - [meta sequenceId="68"] /usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : dnsmasq_configure_do())
<13>1 2023-06-08T12:40:34+02:00 HOST opnsense 1350 - [meta sequenceId="69"] /usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : ntpd_configure_do())
<13>1 2023-06-08T12:40:43+02:00 HOST opnsense 1350 - [meta sequenceId="70"] /usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : opendns_configure_do())
<13>1 2023-06-08T12:40:43+02:00 HOST opnsense 1350 - [meta sequenceId="71"] /usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : openssh_configure_do(,wan))
<13>1 2023-06-08T12:40:43+02:00 HOST opnsense 1350 - [meta sequenceId="72"] /usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : unbound_configure_do(,wan))
<11>1 2023-06-08T12:40:49+02:00 HOST opnsense 1350 - [meta sequenceId="73"] /usr/local/etc/rc.newwanipv6: The command '/sbin/mount -r -t nullfs '/usr/local/lib/python3.9' '/var/unbound/usr/local/lib/python3.9'' returned exit code '1', the output was 'mount_nullfs: /var/unbound/usr/local/lib/python3.9: Resource deadlock avoided'
<13>1 2023-06-08T12:40:52+02:00 HOST opnsense 93703 - [meta sequenceId="74"] /usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : vxlan_configure_do())
<13>1 2023-06-08T12:40:52+02:00 HOST opnsense 93703 - [meta sequenceId="75"] /usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : webgui_configure_do(,wan))
<13>1 2023-06-08T12:40:52+02:00 HOST opnsense 93703 - [meta sequenceId="76"] /usr/local/etc/rc.newwanipv6: plugins_configure vpn (,lan)
<13>1 2023-06-08T12:40:52+02:00 HOST opnsense 93703 - [meta sequenceId="77"] /usr/local/etc/rc.newwanipv6: plugins_configure vpn (execute task : ipsec_configure_do(,lan))
<13>1 2023-06-08T12:40:52+02:00 HOST opnsense 93703 - [meta sequenceId="78"] /usr/local/etc/rc.newwanipv6: plugins_configure vpn (execute task : openvpn_configure_do(,lan))
<13>1 2023-06-08T12:40:52+02:00 HOST opnsense 93703 - [meta sequenceId="79"] /usr/local/etc/rc.newwanipv6: Resyncing OpenVPN instances for interface LAN.
<13>1 2023-06-08T12:40:52+02:00 HOST opnsense 93703 - [meta sequenceId="80"] /usr/local/etc/rc.newwanipv6: plugins_configure newwanip (,lan)
<13>1 2023-06-08T12:40:52+02:00 HOST opnsense 93703 - [meta sequenceId="81"] /usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : dnsmasq_configure_do())
<13>1 2023-06-08T12:40:52+02:00 HOST opnsense 93703 - [meta sequenceId="82"] /usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : ntpd_configure_do())
<13>1 2023-06-08T12:40:52+02:00 HOST opnsense 1350 - [meta sequenceId="83"] /usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : vxlan_configure_do())
<13>1 2023-06-08T12:40:52+02:00 HOST opnsense 1350 - [meta sequenceId="84"] /usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : webgui_configure_do(,wan))
<13>1 2023-06-08T12:40:52+02:00 HOST opnsense 1350 - [meta sequenceId="85"] /usr/local/etc/rc.newwanipv6: plugins_configure vpn (,lan)
<13>1 2023-06-08T12:40:52+02:00 HOST opnsense 1350 - [meta sequenceId="86"] /usr/local/etc/rc.newwanipv6: plugins_configure vpn (execute task : ipsec_configure_do(,lan))
<13>1 2023-06-08T12:40:52+02:00 HOST opnsense 1350 - [meta sequenceId="87"] /usr/local/etc/rc.newwanipv6: plugins_configure vpn (execute task : openvpn_configure_do(,lan))
<13>1 2023-06-08T12:40:52+02:00 HOST opnsense 1350 - [meta sequenceId="88"] /usr/local/etc/rc.newwanipv6: Resyncing OpenVPN instances for interface LAN.
<13>1 2023-06-08T12:40:52+02:00 HOST opnsense 1350 - [meta sequenceId="89"] /usr/local/etc/rc.newwanipv6: plugins_configure newwanip (,lan)
<13>1 2023-06-08T12:40:52+02:00 HOST opnsense 1350 - [meta sequenceId="90"] /usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : dnsmasq_configure_do())
<13>1 2023-06-08T12:40:52+02:00 HOST opnsense 1350 - [meta sequenceId="91"] /usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : ntpd_configure_do())
<13>1 2023-06-08T12:40:56+02:00 HOST opnsense 93703 - [meta sequenceId="92"] /usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : opendns_configure_do())
<13>1 2023-06-08T12:40:56+02:00 HOST opnsense 93703 - [meta sequenceId="93"] /usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : openssh_configure_do(,lan))
<13>1 2023-06-08T12:40:56+02:00 HOST opnsense 93703 - [meta sequenceId="94"] /usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : unbound_configure_do(,lan))
<11>1 2023-06-08T12:40:56+02:00 HOST opnsense 1350 - [meta sequenceId="95"] /usr/local/etc/rc.newwanipv6: The command '/usr/local/sbin/ntpd -g -c '/var/etc/ntpd.conf'' returned exit code '1', the output was ''
<13>1 2023-06-08T12:40:56+02:00 HOST opnsense 1350 - [meta sequenceId="96"] /usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : opendns_configure_do())
<13>1 2023-06-08T12:40:56+02:00 HOST opnsense 1350 - [meta sequenceId="97"] /usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : openssh_configure_do(,lan))
<13>1 2023-06-08T12:40:56+02:00 HOST opnsense 1350 - [meta sequenceId="98"] /usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : unbound_configure_do(,lan))
<11>1 2023-06-08T12:41:09+02:00 HOST opnsense 93703 - [meta sequenceId="99"] /usr/local/etc/rc.newwanipv6: The command '/sbin/mount -r -t nullfs '/usr/local/lib/python3.9' '/var/unbound/usr/local/lib/python3.9'' returned exit code '1', the output was 'mount_nullfs: /var/unbound/usr/local/lib/python3.9: Resource deadlock avoided'
<13>1 2023-06-08T12:41:12+02:00 HOST opnsense 1350 - [meta sequenceId="100"] /usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : vxlan_configure_do())
<13>1 2023-06-08T12:41:12+02:00 HOST opnsense 93703 - [meta sequenceId="101"] /usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : vxlan_configure_do())
<13>1 2023-06-08T12:41:12+02:00 HOST opnsense 1350 - [meta sequenceId="102"] /usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : webgui_configure_do(,lan))
<13>1 2023-06-08T12:41:12+02:00 HOST opnsense 93703 - [meta sequenceId="103"] /usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : webgui_configure_do(,lan))

Looking also at the log for the point-to-point device pppoe0, it reveals, that it receives a Terminate Request via LCP, which apparently triggers the whole process in the first place:

Code: [Select]

<30>1 2023-06-08T12:40:17+02:00 HOST ppp 66269 - [meta sequenceId="1"] [wan_link0] LCP: rec'd Terminate Request #3 (Opened)
<30>1 2023-06-08T12:40:17+02:00 HOST ppp 66269 - [meta sequenceId="2"] [wan_link0] LCP: state change Opened --> Stopping
<30>1 2023-06-08T12:40:17+02:00 HOST ppp 66269 - [meta sequenceId="3"] [wan_link0] Link: Leave bundle "wan"
<30>1 2023-06-08T12:40:17+02:00 HOST ppp 66269 - [meta sequenceId="4"] [wan] Bundle: Status update: up 0 links, total bandwidth 9600 bps
<30>1 2023-06-08T12:40:17+02:00 HOST ppp 66269 - [meta sequenceId="5"] [wan] IPCP: Close event
<30>1 2023-06-08T12:40:17+02:00 HOST ppp 66269 - [meta sequenceId="6"] [wan] IPCP: state change Opened --> Closing
<30>1 2023-06-08T12:40:17+02:00 HOST ppp 66269 - [meta sequenceId="7"] [wan] IPCP: SendTerminateReq #20
<30>1 2023-06-08T12:40:17+02:00 HOST ppp 66269 - [meta sequenceId="8"] [wan] IPCP: LayerDown
<30>1 2023-06-08T12:40:17+02:00 HOST ppp 66269 - [meta sequenceId="9"] [wan] IPV6CP: Close event
<30>1 2023-06-08T12:40:17+02:00 HOST ppp 66269 - [meta sequenceId="10"] [wan] IPV6CP: state change Opened --> Closing
<30>1 2023-06-08T12:40:17+02:00 HOST ppp 66269 - [meta sequenceId="11"] [wan] IPV6CP: SendTerminateReq #10
<30>1 2023-06-08T12:40:17+02:00 HOST ppp 66269 - [meta sequenceId="12"] [wan] IPV6CP: LayerDown
<30>1 2023-06-08T12:40:17+02:00 HOST ppp 66269 - [meta sequenceId="13"] [wan] IFACE: Down event
<30>1 2023-06-08T12:40:17+02:00 HOST ppp 66269 - [meta sequenceId="14"] [wan] IFACE: Rename interface pppoe0 to pppoe0
<30>1 2023-06-08T12:40:17+02:00 HOST ppp 66269 - [meta sequenceId="15"] [wan] IPCP: Down event
<30>1 2023-06-08T12:40:17+02:00 HOST ppp 66269 - [meta sequenceId="16"] [wan] IPCP: LayerFinish
<30>1 2023-06-08T12:40:17+02:00 HOST ppp 66269 - [meta sequenceId="17"] [wan] IPCP: state change Closing --> Initial
<30>1 2023-06-08T12:40:17+02:00 HOST ppp 66269 - [meta sequenceId="18"] [wan] IPV6CP: Down event
<30>1 2023-06-08T12:40:17+02:00 HOST ppp 66269 - [meta sequenceId="19"] [wan] IPV6CP: LayerFinish
<30>1 2023-06-08T12:40:17+02:00 HOST ppp 66269 - [meta sequenceId="20"] [wan] Bundle: No NCPs left. Closing links...
<30>1 2023-06-08T12:40:17+02:00 HOST ppp 66269 - [meta sequenceId="21"] [wan] IPV6CP: state change Closing --> Initial
<30>1 2023-06-08T12:40:17+02:00 HOST ppp 66269 - [meta sequenceId="22"] [wan_link0] LCP: SendTerminateAck #20
<30>1 2023-06-08T12:40:17+02:00 HOST ppp 66269 - [meta sequenceId="23"] [wan_link0] LCP: LayerDown
<30>1 2023-06-08T12:40:17+02:00 HOST ppp 66269 - [meta sequenceId="24"] [wan_link0] PPPoE: connection closed
<30>1 2023-06-08T12:40:17+02:00 HOST ppp 66269 - [meta sequenceId="25"] [wan_link0] Link: DOWN event
<30>1 2023-06-08T12:40:17+02:00 HOST ppp 66269 - [meta sequenceId="26"] [wan_link0] LCP: Down event
<30>1 2023-06-08T12:40:17+02:00 HOST ppp 66269 - [meta sequenceId="27"] [wan_link0] LCP: state change Stopping --> Starting
<30>1 2023-06-08T12:40:17+02:00 HOST ppp 66269 - [meta sequenceId="28"] [wan_link0] Link: reconnection attempt 1 in 2 seconds
<30>1 2023-06-08T12:40:19+02:00 HOST ppp 66269 - [meta sequenceId="29"] [wan_link0] Link: reconnection attempt 1
<30>1 2023-06-08T12:40:19+02:00 HOST ppp 66269 - [meta sequenceId="30"] [wan_link0] PPPoE: Connecting to ''
<30>1 2023-06-08T12:40:20+02:00 HOST ppp 66269 - [meta sequenceId="31"] PPPoE: rec'd ACNAME "ess0015aihk001"
<30>1 2023-06-08T12:40:20+02:00 HOST ppp 66269 - [meta sequenceId="32"] [wan_link0] PPPoE: connection successful
<30>1 2023-06-08T12:40:20+02:00 HOST ppp 66269 - [meta sequenceId="33"] [wan_link0] Link: UP event
<30>1 2023-06-08T12:40:20+02:00 HOST ppp 66269 - [meta sequenceId="34"] [wan_link0] LCP: Up event
<30>1 2023-06-08T12:40:20+02:00 HOST ppp 66269 - [meta sequenceId="35"] [wan_link0] LCP: state change Starting --> Req-Sent
<30>1 2023-06-08T12:40:20+02:00 HOST ppp 66269 - [meta sequenceId="36"] [wan_link0] LCP: SendConfigReq #21
<30>1 2023-06-08T12:40:20+02:00 HOST ppp 66269 - [meta sequenceId="37"] [wan_link0]   PROTOCOMP
<30>1 2023-06-08T12:40:20+02:00 HOST ppp 66269 - [meta sequenceId="38"] [wan_link0]   MRU 1492
<30>1 2023-06-08T12:40:20+02:00 HOST ppp 66269 - [meta sequenceId="39"] [wan_link0]   MAGICNUM 0x68b5918b
<30>1 2023-06-08T12:40:20+02:00 HOST ppp 66269 - [meta sequenceId="40"] [wan_link0] LCP: rec'd Configure Reject #21 (Req-Sent)
<30>1 2023-06-08T12:40:20+02:00 HOST ppp 66269 - [meta sequenceId="41"] [wan_link0]   PROTOCOMP
<30>1 2023-06-08T12:40:20+02:00 HOST ppp 66269 - [meta sequenceId="42"] [wan_link0] LCP: SendConfigReq #22
<30>1 2023-06-08T12:40:20+02:00 HOST ppp 66269 - [meta sequenceId="43"] [wan_link0]   MRU 1492
<30>1 2023-06-08T12:40:20+02:00 HOST ppp 66269 - [meta sequenceId="44"] [wan_link0]   MAGICNUM 0x68b5918b
<30>1 2023-06-08T12:40:20+02:00 HOST ppp 66269 - [meta sequenceId="45"] [wan_link0] LCP: rec'd Configure Ack #22 (Req-Sent)
<30>1 2023-06-08T12:40:20+02:00 HOST ppp 66269 - [meta sequenceId="46"] [wan_link0]   MRU 1492
<30>1 2023-06-08T12:40:20+02:00 HOST ppp 66269 - [meta sequenceId="47"] [wan_link0]   MAGICNUM 0x68b5918b
<30>1 2023-06-08T12:40:20+02:00 HOST ppp 66269 - [meta sequenceId="48"] [wan_link0] LCP: state change Req-Sent --> Ack-Rcvd
<30>1 2023-06-08T12:40:22+02:00 HOST ppp 66269 - [meta sequenceId="49"] [wan_link0] LCP: state change Ack-Rcvd --> Req-Sent
<30>1 2023-06-08T12:40:22+02:00 HOST ppp 66269 - [meta sequenceId="50"] [wan_link0] LCP: SendConfigReq #23
<30>1 2023-06-08T12:40:22+02:00 HOST ppp 66269 - [meta sequenceId="51"] [wan_link0]   MRU 1492
<30>1 2023-06-08T12:40:22+02:00 HOST ppp 66269 - [meta sequenceId="52"] [wan_link0]   MAGICNUM 0x68b5918b
<30>1 2023-06-08T12:40:22+02:00 HOST ppp 66269 - [meta sequenceId="53"] [wan_link0] LCP: rec'd Configure Ack #23 (Req-Sent)
<30>1 2023-06-08T12:40:22+02:00 HOST ppp 66269 - [meta sequenceId="54"] [wan_link0]   MRU 1492
<30>1 2023-06-08T12:40:22+02:00 HOST ppp 66269 - [meta sequenceId="55"] [wan_link0]   MAGICNUM 0x68b5918b
<30>1 2023-06-08T12:40:22+02:00 HOST ppp 66269 - [meta sequenceId="56"] [wan_link0] LCP: state change Req-Sent --> Ack-Rcvd
<30>1 2023-06-08T12:40:23+02:00 HOST ppp 66269 - [meta sequenceId="57"] [wan_link0] LCP: rec'd Configure Request #2 (Ack-Rcvd)
<30>1 2023-06-08T12:40:23+02:00 HOST ppp 66269 - [meta sequenceId="58"] [wan_link0]   MRU 1492
<30>1 2023-06-08T12:40:23+02:00 HOST ppp 66269 - [meta sequenceId="59"] [wan_link0]   AUTHPROTO PAP
<30>1 2023-06-08T12:40:23+02:00 HOST ppp 66269 - [meta sequenceId="60"] [wan_link0]   MAGICNUM 0xbcc6350b
<30>1 2023-06-08T12:40:23+02:00 HOST ppp 66269 - [meta sequenceId="61"] [wan_link0] LCP: SendConfigAck #2
<30>1 2023-06-08T12:40:23+02:00 HOST ppp 66269 - [meta sequenceId="62"] [wan_link0]   MRU 1492
<30>1 2023-06-08T12:40:23+02:00 HOST ppp 66269 - [meta sequenceId="63"] [wan_link0]   AUTHPROTO PAP
<30>1 2023-06-08T12:40:23+02:00 HOST ppp 66269 - [meta sequenceId="64"] [wan_link0]   MAGICNUM 0xbcc6350b
<30>1 2023-06-08T12:40:23+02:00 HOST ppp 66269 - [meta sequenceId="65"] [wan_link0] LCP: state change Ack-Rcvd --> Opened
<30>1 2023-06-08T12:40:23+02:00 HOST ppp 66269 - [meta sequenceId="66"] [wan_link0] LCP: auth: peer wants PAP, I want nothing
<30>1 2023-06-08T12:40:23+02:00 HOST ppp 66269 - [meta sequenceId="67"] [wan_link0] PAP: using authname "H1und1/XXXX-XXX@online.de"
<30>1 2023-06-08T12:40:23+02:00 HOST ppp 66269 - [meta sequenceId="68"] [wan_link0] PAP: sending REQUEST #1 len: 39
<30>1 2023-06-08T12:40:23+02:00 HOST ppp 66269 - [meta sequenceId="69"] [wan_link0] LCP: LayerUp
<30>1 2023-06-08T12:40:23+02:00 HOST ppp 66269 - [meta sequenceId="70"] [wan_link0] PAP: rec'd ACK #1 len: 58
<30>1 2023-06-08T12:40:23+02:00 HOST ppp 66269 - [meta sequenceId="71"] [wan_link0]   MESG: [UI-SBR:116796,45769;UI-LINEID:1UND1.DEU.DTAG.CIP8N;]
<30>1 2023-06-08T12:40:23+02:00 HOST ppp 66269 - [meta sequenceId="72"] [wan_link0] LCP: authorization successful
<30>1 2023-06-08T12:40:23+02:00 HOST ppp 66269 - [meta sequenceId="73"] [wan_link0] Link: Matched action 'bundle "wan" ""'
<30>1 2023-06-08T12:40:23+02:00 HOST ppp 66269 - [meta sequenceId="74"] [wan_link0] Link: Join bundle "wan"
<30>1 2023-06-08T12:40:23+02:00 HOST ppp 66269 - [meta sequenceId="75"] [wan] Bundle: Status update: up 1 link, total bandwidth 64000 bps
<30>1 2023-06-08T12:40:23+02:00 HOST ppp 66269 - [meta sequenceId="76"] [wan] IPCP: Open event
<30>1 2023-06-08T12:40:23+02:00 HOST ppp 66269 - [meta sequenceId="77"] [wan] IPCP: state change Initial --> Starting
<30>1 2023-06-08T12:40:23+02:00 HOST ppp 66269 - [meta sequenceId="78"] [wan] IPCP: LayerStart
<30>1 2023-06-08T12:40:23+02:00 HOST ppp 66269 - [meta sequenceId="79"] [wan] IPV6CP: Open event
<30>1 2023-06-08T12:40:23+02:00 HOST ppp 66269 - [meta sequenceId="80"] [wan] IPV6CP: state change Initial --> Starting
<30>1 2023-06-08T12:40:23+02:00 HOST ppp 66269 - [meta sequenceId="81"] [wan] IPV6CP: LayerStart
<30>1 2023-06-08T12:40:23+02:00 HOST ppp 66269 - [meta sequenceId="82"] [wan] IPCP: Up event
<30>1 2023-06-08T12:40:23+02:00 HOST ppp 66269 - [meta sequenceId="83"] [wan] IPCP: state change Starting --> Req-Sent
<30>1 2023-06-08T12:40:23+02:00 HOST ppp 66269 - [meta sequenceId="84"] [wan] IPCP: SendConfigReq #21
<30>1 2023-06-08T12:40:23+02:00 HOST ppp 66269 - [meta sequenceId="85"] [wan]   IPADDR 0.0.0.0
<30>1 2023-06-08T12:40:23+02:00 HOST ppp 66269 - [meta sequenceId="86"] [wan]   COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
<30>1 2023-06-08T12:40:23+02:00 HOST ppp 66269 - [meta sequenceId="87"] [wan] IPV6CP: Up event
<30>1 2023-06-08T12:40:23+02:00 HOST ppp 66269 - [meta sequenceId="88"] [wan] IPV6CP: state change Starting --> Req-Sent
<30>1 2023-06-08T12:40:23+02:00 HOST ppp 66269 - [meta sequenceId="89"] [wan] IPV6CP: SendConfigReq #11
<30>1 2023-06-08T12:40:23+02:00 HOST ppp 66269 - [meta sequenceId="90"] [wan] IPCP: rec'd Configure Request #1 (Req-Sent)
<30>1 2023-06-08T12:40:23+02:00 HOST ppp 66269 - [meta sequenceId="91"] [wan]   IPADDR XX.XXX.XXX.XXX
<30>1 2023-06-08T12:40:23+02:00 HOST ppp 66269 - [meta sequenceId="92"] [wan]     XX.XXX.XXX.XXX is OK
<30>1 2023-06-08T12:40:23+02:00 HOST ppp 66269 - [meta sequenceId="93"] [wan] IPCP: SendConfigAck #1
<30>1 2023-06-08T12:40:23+02:00 HOST ppp 66269 - [meta sequenceId="94"] [wan]   IPADDR XX.XXX.XXX.XXX
<30>1 2023-06-08T12:40:23+02:00 HOST ppp 66269 - [meta sequenceId="95"] [wan] IPCP: state change Req-Sent --> Ack-Sent
<30>1 2023-06-08T12:40:23+02:00 HOST ppp 66269 - [meta sequenceId="96"] [wan] IPV6CP: rec'd Configure Request #1 (Req-Sent)
<30>1 2023-06-08T12:40:23+02:00 HOST ppp 66269 - [meta sequenceId="97"] [wan] IPV6CP: SendConfigAck #1
<30>1 2023-06-08T12:40:23+02:00 HOST ppp 66269 - [meta sequenceId="98"] [wan] IPV6CP: state change Req-Sent --> Ack-Sent
<30>1 2023-06-08T12:40:23+02:00 HOST ppp 66269 - [meta sequenceId="99"] [wan] IPCP: rec'd Configure Reject #21 (Ack-Sent)
<30>1 2023-06-08T12:40:23+02:00 HOST ppp 66269 - [meta sequenceId="100"] [wan]   COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
<30>1 2023-06-08T12:40:23+02:00 HOST ppp 66269 - [meta sequenceId="101"] [wan] IPCP: SendConfigReq #22
<30>1 2023-06-08T12:40:23+02:00 HOST ppp 66269 - [meta sequenceId="102"] [wan]   IPADDR 0.0.0.0
<30>1 2023-06-08T12:40:23+02:00 HOST ppp 66269 - [meta sequenceId="103"] [wan] IPV6CP: rec'd Configure Ack #11 (Ack-Sent)
<30>1 2023-06-08T12:40:23+02:00 HOST ppp 66269 - [meta sequenceId="104"] [wan] IPV6CP: state change Ack-Sent --> Opened
<30>1 2023-06-08T12:40:23+02:00 HOST ppp 66269 - [meta sequenceId="105"] [wan] IPV6CP: LayerUp
<30>1 2023-06-08T12:40:23+02:00 HOST ppp 66269 - [meta sequenceId="106"] [wan]   XXXX:XXXX:XXXX:XXXX -> XXXX:XXXX:XXXX:XXXX
<30>1 2023-06-08T12:40:23+02:00 HOST ppp 66269 - [meta sequenceId="107"] [wan] IFACE: Up event
<30>1 2023-06-08T12:40:23+02:00 HOST ppp 66269 - [meta sequenceId="108"] [wan] IFACE: Rename interface ng0 to pppoe0
<30>1 2023-06-08T12:40:23+02:00 HOST ppp 66269 - [meta sequenceId="109"] [wan] IPCP: rec'd Configure Nak #22 (Ack-Sent)
<30>1 2023-06-08T12:40:23+02:00 HOST ppp 66269 - [meta sequenceId="110"] [wan]   IPADDR XXX.XXX.XXX.XXX
<30>1 2023-06-08T12:40:23+02:00 HOST ppp 66269 - [meta sequenceId="111"] [wan]     XXX.XXX.XXX.XXX is OK
<30>1 2023-06-08T12:40:23+02:00 HOST ppp 66269 - [meta sequenceId="112"] [wan] IPCP: SendConfigReq #23
<30>1 2023-06-08T12:40:23+02:00 HOST ppp 66269 - [meta sequenceId="113"] [wan]   IPADDR XXX.XXX.XXX.XXX
<30>1 2023-06-08T12:40:23+02:00 HOST ppp 66269 - [meta sequenceId="114"] [wan] IPCP: rec'd Configure Ack #23 (Ack-Sent)
<30>1 2023-06-08T12:40:23+02:00 HOST ppp 66269 - [meta sequenceId="115"] [wan]   IPADDR XXX.XXX.XXX.XXX
<30>1 2023-06-08T12:40:23+02:00 HOST ppp 66269 - [meta sequenceId="116"] [wan] IPCP: state change Ack-Sent --> Opened
<30>1 2023-06-08T12:40:23+02:00 HOST ppp 66269 - [meta sequenceId="117"] [wan] IPCP: LayerUp
<30>1 2023-06-08T12:40:23+02:00 HOST ppp 66269 - [meta sequenceId="118"] [wan]   XXX.XXX.XXX.XXX -> XX.XXX.XXX.XXX

The initial setup was with OPNsense 23.1 and this ran flawlessly for at least three days. Only upon upgrading to the most recent version 23.1.9 I am having these issues. Curiously, reverting back to 23.1 did not help at all.

What am I missing? Maybe I'm doing something wrong, I'm fairly new to using OPNsense behind a VDSL line.

Any help would greatly be appreciated. Thanks in advance.
Cheers!

[franco]

That sounds like ISP territory. While I can't rule out changes made to mpd5 daemon I can relatively safely rule out any other change in 23.1.x so far since this is just PPPoE session failing for whatever reason.

# opnsense-revert -r 23.1 mpd5

And restart to see if that helps. But I wouldn't bet on it either. I'd say this is more either equipment or maintenance related to the ISP side.


Cheers,
Franco

[stesoell]

I think its a DTAG related issue. Since Tuesday I have similar disco/reconnects. LCP echo requests timeouts preceded the disconnects. Maybe due to DLM after switching to a supervectoring
connection (250Mbit)

[seed]

This looks like a 1und1 + telekom problem to me.
When there are resyncs... meaning that your modem is doing training over and over again that is most likely caused by an issue on the circuit. Check your modem for training logs and counters. If so call your isp and make them shedule a field engineer.

if your modem is sync since a long time and its just pppoe. its also likely that your isp is having problems on their BNG router with their l2tp tunnel ehere they get the pppoe sessions from telekom. Also their bng could have connection problems to the radius or telekom doesnt deliver the l2tp consistently to 1und1.

My assumption is that this issue is caused by your isp.
If there are errors or multiple resyncs in your modem log -> Call ISP for technicion on site
If its just a pppoe issue chances are that you are not the only customer with this problem and 1und1 is already working on it.

[Cyberturtle]

When your PPPoE reconnects does your modem resync too? It looks like a ISP issue I had last year. Due to increasing ambient temperature and insufficient cooling the line card of the DSLAM died a few days later. Since the line card got replaced for the whole neighborhood everything went back to normal.
Sometimes also new DLM/ASSIA profiles can run into LCP echo reply timeouts. If the profile doesn't match to the line conditions like SNR, G.INP etc. there could be a high rate of retransmissons. Especially on SVDSL250/175 lines a nightly optimization should take place and will change the target connection speeds to lower ones to increase stability.

[Bene93]

Sorry for replying so late.

I actually got it to work properly again.
My ISP provides me with the DSL, which I need to tag VLAN ID 7 in order to work. Previously my VDSL-Modem did that and provided the OPNsense Box with the untagged Ethernet network.
I switched this and now the OPNsense Box itself is tagging the WAN network over VLAN 7 and this completely solved my problem.

Thanks for everyones input on this matter. You definitely pushed me in the right direction.
Cheers!