interfaces: properly react to RENEW/REBIND from dhcp6c #6522

agowa · 2023-04-24T12:17:57Z

Important notices

Before you add a new report, we ask you kindly to acknowledge the following:

I have read the contributing guide lines at https://github.com/opnsense/core/blob/master/CONTRIBUTING.md
I am convinced that my issue is new after having checked both open and closed issues at https://github.com/opnsense/core/issues?q=is%3Aissue

Describe the bug

In other tickets (like #6515), it was already reported that OPNsense sometimes fails to update delegated prefixes. But now I discovered another bug that interrupts network communication even if OPNsense detects the prefix change.

dhcp6c changes the prefix within radvd.conf file and restarts radvd. Somehow this causes radvd to fail to send a deprecation message using the OLD prefix (even though DeprecatePrefix on is already configured). So the old prefix does not get deprecated and hosts on LAN have preferred IPv6 addresses from both prefixes, but OPNsense itself no longer knows about the old prefix (nor do upstream routers), so network communication fails.
I then tried to stop radvd manually. But that just deprecated the NEW prefix (hence why even a reboot of OPNsense can't fix this issue, but all devices on LAN need to be touched)

To Reproduce

Steps to reproduce the behavior:

Router with DHCPv6-PD on WAN
IP on WAN via DHCPv6
IP on LAN interface dependent
Wait until dhcp6c receives a RENEW event
(dhcp6c now reconfigures interfaces and overwrites /var/etc/radvd.conf to use the new prefix)
(While that observe radvd messages on LAN)

Steps to reproduce in a Lab environment (a bit more deterministic and maybe easier to reproduce):

Router with DHCPv6-PD on WAN
IP on WAN via DHCPv6
IP on LAN interface dependent
Manually overwrite /var/etc/radvd.conf to use some random prefix (P1).
Retart radvd (so that it advertises P1 now)
kill -1 dhcp6c-pid to have dhcp6c rewrite the radvd config file (replacing P1 with another prefix P2) and restart it.
Observe radvd and P1 deprecation (this currently does not occur in my instance).
Stop radvd and observe deprecation (this only deprecates P2, but not P1)

Expected behavior

radvd deprecating old prefix

Describe alternatives you considered

Maybe patching /var/etc/dhcp6c_wan_script.sh to write the old prefix into /var/etc/radvd.conf, stop radvd (so that it sends a deprecation message with the old prefix), write the new prefix into radvd, and restart it.

Screenshots

If applicable, add screenshots to help explain your problem.

Relevant log files

Additional context

/var/etc/radvd.conf (Sensitive information replaced with $-Pseudo-Variables):

# Automatically generated, do not edit
# Generated for DHCPv6 server lan
interface hn0 {
        AdvSendAdvert on;
        MinRtrAdvInterval 3;
        MaxRtrAdvInterval 60;
        AdvLinkMTU 1492;
        AdvDefaultPreference medium;
        AdvManagedFlag on;
        AdvOtherConfigFlag on;
        prefix $P2/64 {
                DeprecatePrefix on;
                AdvOnLink on;
                AdvAutonomous on;
        };
        RDNSS $OPNsenseIP {
        };
        DNSSL $myDNSSL {
        };
};

/var/etc/dhcp6c.conf:

interface hn1 {
  send ia-pd 0; # request prefix delegation
  request domain-name-servers;
  request domain-name;
  script "/var/etc/dhcp6c_wan_script.sh"; # we'd like some nameservers please
};
id-assoc pd 0 {
  prefix ::/62 infinity;
  prefix-interface hn0 {
    sla-id 0;
    sla-len 2;
  };
};

/var/etc/dhcp6c_wan.conf:

interface hn1 {
  send ia-pd 0; # request prefix delegation
  request domain-name-servers;
  request domain-name;
  script "/var/etc/dhcp6c_wan_script.sh"; # we'd like some nameservers please
};
id-assoc pd 0 {
  prefix ::/62 infinity;
  prefix-interface hn0 {
    sla-id 0;
    sla-len 2;
  };
};

/var/etc/dhcp6c_wan_script.sh:

#!/bin/sh
if [ -n "2" ]; then
    /usr/bin/logger -t dhcp6c "dhcp6c $REASON on hn1"
fi
case $REASON in
INFOREQ|REQUEST)
    /usr/bin/logger -t dhcp6c "dhcp6c $REASON on hn1 - running newipv6"
    ARGS=
    for NAMESERVER in ${new_domain_name_servers}; do
        ARGS="${ARGS} -a ${NAMESERVER}"
    done
    /usr/local/sbin/ifctl -i hn1 -6nd ${ARGS}
    ARGS=
    for DOMAIN in ${new_domain_name}; do
        ARGS="${ARGS} -a ${DOMAIN}"
    done
    /usr/local/sbin/ifctl -i hn1 -6sd ${ARGS}
    /usr/local/sbin/ifctl -i hn1 -6pd ${PDINFO:+"-a ${PDINFO}"}
    FORCE=
    if [ ${REASON} = "REQUEST" ]; then
        FORCE=force
    fi
    /usr/local/sbin/configctl -d interface newipv6 hn1 ${FORCE}
    ;;
EXIT|RELEASE)
    /usr/bin/logger -t dhcp6c "dhcp6c $REASON on hn1 - running newipv6"
    /usr/local/sbin/ifctl -i hn1 -6nd
    /usr/local/sbin/ifctl -i hn1 -6sd
    /usr/local/sbin/ifctl -i hn1 -6pd
    /usr/local/sbin/configctl -d interface newipv6 hn1
    ;;
*)
    ;;
esac

Environment

Software version used and hardware type if relevant, e.g.:

OPNsense 23.1.6-amd64
FreeBSD 13.1-RELEASE-p7
OpenSSL 1.1.1t 7 Feb 2023
AMD Ryzen 7 3800X 8-Core Processor (4 cores, 8 threads)

The text was updated successfully, but these errors were encountered:

fichtner · 2023-04-24T12:23:27Z

That's the case since 23.1.5? Since DeprecatePrefix on; is set I doubt we can do more here other than moving back to an unsatisfactory state of 23.1.4 and below. The ravd man page specifically says "on shutdown" so I think we are stuck between a rock and a hard place. ;)

fichtner · 2023-04-24T12:30:10Z

Reverting eec08e0 might be worth a try...

# opnsense-patch eec08e05502

Better?

agowa · 2023-04-24T13:44:06Z

Reverting this fixes the issue. However, it also causes a new one in Windows. Even though the prefix is now correctly listed as deprecated, it still tries to use it. Until I force the interface down and up again (which removes the deprecated prefixes). But there is probably nothing we can do about that. Interestingly I did not have this issues previously on my self-made lab router with alpine linux, dhcpcd and radvd. I think I still have a configuration backup somewhere. I could have a look if it helps.

Edit: Found it, my radvd config looked like this (note that I used ::/64 as prefix, which causes radvd to use whatever the interface has):

# cat /etc/radvd.conf
interface eth1
{
  AdvSendAdvert on;
  AdvOtherConfigFlag off;
  AdvManagedFlag off;
  AdvLinkMTU 1500;
  MinRtrAdvInterval 3;
  MaxRtrAdvInterval 10;
  prefix ::/64 {
    AdvOnLink on;
    AdvAutonomous on;
    AdvRouterAddr on;
  };
  route ::/0 {};
};

fichtner · 2023-04-24T13:53:01Z

I can't help with the latter part but I can issue a radvd restart once a full IPv6 renew event is being handled. That should give us the best of both worlds.

agowa · 2023-04-24T13:59:51Z

Scratch the windows part. It turned out to be a "just" Chrome thing🤦 for all tabs I had open, it kept using the deprecated IP (even for new webpages or for forced refreshes). But restarting the browser made it use the new IP (without touching the interface).

fichtner · 2023-04-24T14:15:22Z

Ok, sounds good. This is going to be a bit complicated but I'll take a closer look later this week.

prefix is not deprecated unless we shut down

fichtner · 2023-04-24T15:08:56Z

@agowa338 I'm trying the following instead: 3cb2dd7669

# opnsense-revert opnsense && opnsense-patch 3cb2dd7669

Not sure if you use auto-mode or manual configuration. The auto-mode has a caveat in the form of 165327b which could mess up the hashing of the prefix/tracking configuration changes.

agowa · 2023-04-24T15:25:30Z

That works 👍 thanks for the quick fix.
(We don't have any option to force clients to not just deprecate the old IP but to deconfigure it completely, or do we?)

fichtner · 2023-04-24T15:29:28Z

Actually the only way to do this is set DeprecatePrefix on and shut radvd down. All I'm attempting to do here in 23.1.x is to try and prevent radvd from sending deprecation messages for when ravd restarts without IPv6 reconnecting underneath, which can happen on a few GUI pages causing spurious disconnects. macOS seems to react the worst to this.

agowa · 2023-04-24T15:33:22Z

Should we consider trying to patch radvd to "fix" that? Because sending a deprecation message without a prefix change sounds like a bug anyway...

fichtner · 2023-04-24T15:34:01Z

It's being discussed since 2014 over at radvd. I don't have much hope :)

fichtner · 2023-04-24T15:36:26Z

Refs radvd-project/radvd#91 radvd-project/radvd#85 radvd-project/radvd#39

meyergru · 2023-04-24T15:38:50Z

It would be a whole lot easier if radvd had a kill signal to reload its config... then it could run forever and with GUI changes, only a signal would be neccessary...

fichtner · 2023-04-24T15:40:39Z

@meyergru that's what SIGHUP does :) but it mimicks a restart, only that it forget to deprecate the previous prefix... but the underlying issue is a bit more challenging, because on SIGHUP it would have to check IF the prefix configured changes in order to deprecate it. I don't think this works considering you can stuff multiple prefixes in there at any time.

meyergru · 2023-04-24T15:42:57Z

But in that case, you could set DeprecatePrefix on, and on GUI/configuration changes only issue a SIGHUP.

When you see that the prefix has changed (e.g. when the connection is brought up again and the old prefix is different from the new one), you could restart the daemon. That is, you can check for prefix change outside of the daemon and decide which way to restart it.

fichtner · 2023-04-24T15:44:50Z

There is no way to track this through the code without ripping it all open across multiple files. And even then it might be on a configuration change and we miss it by issuing a faulty SIGHUP.

I don't want to start tracking deprecated prefixes... I thought we had multiple software solutions for that :/

fichtner · 2023-04-24T15:48:47Z

Just to reiterate, sending SIGHUP may be a better option if the config doesn't change (and the service is started).

For any other case we restart properly. Just the "::/64" case has me worried, which does "magic" that we can neither track nor verify functionally (doing a simple test setup forcing this aside). Here my point is that this may have had negative effects on people's deployments all along, see commit for details on weird AdvRouterAddr option use.

agowa · 2023-04-24T15:49:10Z

I think the work around we have now is all we can do. And the other thing is something that maybe should be brought up again in the radvd side. Because they can much more easily compare the running config with the configuration file...

meyergru · 2023-04-24T15:49:22Z

I am aware of where the real problem lies. I am just lucky to get the same prefix again on reconnects...

fichtner · 2023-04-24T15:52:14Z

I am aware of where the real problem lies. I am just lucky to get the same prefix again on reconnects...

Sad but true :)

@agowa338 @meyergru appreciate the feedback!

agowa · 2023-04-24T15:52:28Z

The only other thing we could do (without code change to radvd) is to set the lifetimes to their minimum and have clients more or less constantly renew them (also bad)...

fichtner · 2023-04-24T15:53:10Z

RFC junkies will argue it drains all power from mobile stack ;)

(cherry picked from commit 2db028d)

fichtner · 2023-05-11T08:06:12Z

31961bf is perhaps what you are looking for here. I fiddled a bit too much on the master branch so apply with opnsense-patch may be tricky. We still have to solve the primary IP "changing" but I think we can manage that easily with more debug data from your end.

agowa · 2023-05-11T15:05:49Z

The flapping between ULA and GUA is not nice indeed.

Does the ifconfig output reorder the addresses when you run the command multiple times? The thing is it only tries to read one "primary" address but if there are multiple and their ordering changes we can end up with a random one which would make sorting addresses useful before picking one.

No, it stays constant, I however don't know if this may be a race condition thing when the GUA expired and gets renewed but the ULA is still valid...

Question is if your prefix actually changes? I think we can detect that then...

Yes it is changing, and when you look at the logs I provided, I made sure to censor it in a way that preserved which values were equal. I.E. **1** is always the same value and different from **2**.
Do you need more information? What exactly would help? (I executed the two commands you provided right now, but I cannot really force the issue to occur, as it (at least until now) only occurs when stuff changes upstream outside of my control, I could try hitting the reconnect button in the CE though, but that may have slightly different behavior...)

agowa · 2023-05-11T16:17:03Z

I restarted opnsense after the patches, looks unchanged so far.

The log still says:

2023-05-11T15:55:53	Error	opnsense	/usr/local/etc/rc.routing_configure: ROUTING: not a valid default gateway address: ''	
2023-05-11T15:55:53	Error	opnsense	/usr/local/etc/rc.newwanipv6: The command '/bin/kill -'TERM' '90332'' returned exit code '1', the output was 'kill: 90332: No such process'

For some reason, the console now lists the link-local (fe80::) IPv6 as "v6/DHCP6" for the wan interface.

And I also noticed that the service startup order is suspicious. radvd, crony, unbound, and then newwanip. crony and unbound also logged some errors to the screen about unreachable IPs (as it started before newwanip gets called).

Also, can you have a quick look at the logged kill command? (this is the one responsible for the deprecation of the IP, right?) I tried to execute it as it was logged, and it doesn't work. Is the quotation of the logged command different from what is actually executed? Or does it log an incorrect error message?

# ps aux | grep dhcp
# kill -'TERM' '27995'
TERM: Unknown signal; kill -l lists signals.

fichtner · 2023-05-12T06:21:08Z

I don't think the errors are all that relevant.

Ok, if the GUA is deprecated it would pick up the ULA when that one is not yet set to deprecated.

Clear about the PD changing then. The master branch state is probably what you are looking for. I've made a backport as
05c6f2e which should apply to 23.1.7 as well.

# opnsense-patch 05c6f2e

I'd recommend a reboot just to be sure. If this isn't working for some reason best to revert all for now:

# opnsense-revert opnsense

Cheers,
Franco

fichtner · 2023-05-24T07:49:48Z

I think from my side this is a wrap. 23.1.8 will ship all the relevant code. Also see https://forum.opnsense.org/index.php?topic=26832.0 for more discussion and test results.

TheekshanaA · 2023-05-31T08:54:27Z

I think from my side this is a wrap. 23.1.8 will ship all the relevant code. Also see https://forum.opnsense.org/index.php?topic=26832.0 for more discussion and test results.
I've got the same issue, still occurring randomly too running latest 23.1.8 If you need any logs let me know :)

fichtner · 2023-05-31T08:58:39Z

@TheekshanaA so did you try the patch and reboot?

TheekshanaA · 2023-05-31T09:16:15Z

@TheekshanaA so did you try the patch and reboot?

I did apply this patch and rebooted yep, I was running 23.8.1 kernel as another forum post said that helped them.

opnsense-patch 05c6f2e

got these same errors

fichtner · 2023-05-31T09:22:41Z

I am unsure what the error even is. "got these same errors" might be nothing. What's wrong operationally?

TheekshanaA · 2023-05-31T09:34:08Z

I am unsure what the error even is. "got these same errors" might be nothing. What's wrong operationally?

Sorry for the vague message, with the errors a lan outage is synchronised, it lasts around 30 seconds roughly maybe a bit less. I'll get you the errors once it reoccurs. I reverted back to 23.1.8 and applied patches as mentioned in the above message.
opnsense-patch 2db028d and # opnsense-revert -z dhcp6c

I can't seem to reproduce it on demand but it seems to occur "randomly" once a hour or so. I'll get you the logs as soon as the issue reoccurs. I apologise if something isn't clear as this is my first time using opnsense since I used pfSence as a kid almost 10 years ago.

EDIT: It might be worth noting I am using a Realtek USB NIC for my LAN, I am currently awaiting delivery for my Intel dual NIC.

Kind Regards,
Nimesh

TheekshanaA · 2023-05-31T10:39:30Z

@fichtner
Here is my errors from "General" logs. Again as I mentioned this could purely be the realtek usb NIC playing up but maybe you see something out of order.
Kind Regards,
Nimesh

2023-05-31T20:00:36	Notice	opnsense	/usr/local/etc/rc.newwanipv6: plugins_configure vpn (,wan)	
2023-05-31T20:00:36	Notice	kernel	<6>ue0: link state changed to UP	
2023-05-31T20:00:36	Notice	kernel	<6>ue0: link state changed to DOWN	
2023-05-31T20:00:36	Notice	kernel	<6>ue0: link state changed to UP	
2023-05-31T20:00:36	Notice	kernel	<6>ue0: link state changed to DOWN	
2023-05-31T20:00:36	Notice	kernel	<6>ue0: link state changed to UP	
2023-05-31T20:00:36	Notice	kernel	<6>ue0: link state changed to DOWN	
2023-05-31T20:00:36	Notice	opnsense	/usr/local/etc/rc.linkup: plugins_configure dns (execute task : unbound_configure_do())	
2023-05-31T20:00:36	Notice	opnsense	/usr/local/etc/rc.linkup: plugins_configure dns (execute task : dnsmasq_configure_do())	
2023-05-31T20:00:36	Notice	opnsense	/usr/local/etc/rc.linkup: plugins_configure dns ()	
2023-05-31T20:00:36	Notice	opnsense	/usr/local/etc/rc.newwanipv6: ROUTING: entering configure using 'lan'	
2023-05-31T20:00:36	Notice	opnsense	/usr/local/etc/rc.newwanipv6: plugins_configure monitor (execute task : dpinger_configure_do(,WAN_DHCP6))	
2023-05-31T20:00:36	Notice	opnsense	/usr/local/etc/rc.newwanipv6: plugins_configure monitor (,WAN_DHCP6)	
2023-05-31T20:00:36	Notice	opnsense	/usr/local/etc/rc.newwanipv6: ROUTING: keeping current inet6 default gateway 'fe80::4e16:fcff:fe2e:a88a%em0'	
2023-05-31T20:00:36	Notice	opnsense	/usr/local/etc/rc.newwanipv6: ROUTING: configuring inet6 default gateway on wan	
2023-05-31T20:00:36	Notice	opnsense	/usr/local/etc/rc.newwanipv6: ROUTING: entering configure using 'wan'	
2023-05-31T20:00:36	Error	opnsense	/usr/local/etc/rc.linkup: 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: 84563'	
2023-05-31T20:00:36	Error	opnsense	/usr/local/etc/rc.linkup: The command '/usr/local/sbin/dhcpd -6 -user dhcpd -group dhcpd -chroot /var/dhcpd -cf /etc/dhcpdv6.conf -pf /var/run/dhcpdv6.pid ue0' 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.'	
2023-05-31T20:00:26	Notice	opnsense	/usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : webgui_configure_do(,lan))	
2023-05-31T20:00:26	Notice	opnsense	/usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : vxlan_configure_do())	
2023-05-31T20:00:24	Notice	opnsense	/usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : unbound_configure_do(,lan))	
2023-05-31T20:00:24	Notice	opnsense	/usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : openssh_configure_do(,lan))	
2023-05-31T20:00:24	Notice	opnsense	/usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : opendns_configure_do())	
2023-05-31T20:00:21	Notice	opnsense	/usr/local/etc/rc.newwanipv6: No IP change detected for WAN[wan]	
2023-05-31T20:00:21	Notice	dhcp6c	dhcp6c_script: RELEASE on em0 executing	
2023-05-31T20:00:20	Error	opnsense	/usr/local/etc/rc.newwanipv6: The command '/bin/kill -'TERM' '17760'' returned exit code '1', the output was 'kill: 17760: No such process'	
2023-05-31T20:00:20	Notice	opnsense	/usr/local/etc/rc.newwanipv6: plugins_configure dhcp (execute task : dhcpd_dhcp_configure(,inet6))	
2023-05-31T20:00:20	Notice	opnsense	/usr/local/etc/rc.newwanipv6: plugins_configure dhcp (,inet6)	
2023-05-31T20:00:20	Notice	opnsense	/usr/local/etc/rc.newwanipv6: IP renewal starting (new: 2001:8003:f00:8204:7972:6de0:daea:e19f, old: 2001:8003:f00:8204:7972:6de0:daea:e19f, interface: WAN[wan], device: em0, force: yes)	
2023-05-31T20:00:20	Notice	dhcp6c	dhcp6c_script: REQUEST on em0 renewal (REASON)	
2023-05-31T20:00:20	Notice	dhcp6c	dhcp6c_script: REQUEST on em0 executing	
2023-05-31T20:00:19	Notice	kernel	<7>cannot forward src fe80:6::8433:dfff:fe22:2f23, dst 2001:8003:ac09:bc00:2e0:4cff:fe68:54, nxt 17, rcvif ue0, outif em0	
2023-05-31T20:00:18	Notice	opnsense	/usr/local/etc/rc.linkup: plugins_configure dhcp (execute task : dhcpd_dhcp_configure())	
2023-05-31T20:00:18	Notice	opnsense	/usr/local/etc/rc.linkup: plugins_configure dhcp ()	
2023-05-31T20:00:18	Notice	opnsense	/usr/local/etc/rc.linkup: plugins_configure ipsec (execute task : ipsec_configure_do(,lan))	
2023-05-31T20:00:18	Notice	opnsense	/usr/local/etc/rc.linkup: plugins_configure ipsec (,lan)	
2023-05-31T20:00:18	Notice	opnsense	/usr/local/etc/rc.linkup: ROUTING: entering configure using 'lan'	
2023-05-31T20:00:18	Notice	opnsense	/usr/local/etc/rc.linkup: DEVD: Ethernet attached event for lan(ue0)	
2023-05-31T20:00:18	Notice	opnsense	/usr/local/etc/rc.linkup: DEVD: Ethernet detached event for lan(ue0)	
2023-05-31T20:00:17	Notice	kernel	<6>ue0: link state changed to UP	
2023-05-31T20:00:17	Notice	kernel	<6>ue0: link state changed to DOWN	
2023-05-31T20:00:17	Notice	opnsense	/usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : ntpd_configure_do())	
2023-05-31T20:00:17	Notice	opnsense	/usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : dnsmasq_configure_do())	
2023-05-31T20:00:17	Notice	opnsense	/usr/local/etc/rc.newwanipv6: plugins_configure newwanip (,lan)	
2023-05-31T20:00:17	Notice	opnsense	/usr/local/etc/rc.newwanipv6: Resyncing OpenVPN instances for interface LAN.	
2023-05-31T20:00:17	Notice	opnsense	/usr/local/etc/rc.newwanipv6: plugins_configure vpn (execute task : openvpn_configure_do(,lan))	
2023-05-31T20:00:17	Notice	opnsense	/usr/local/etc/rc.newwanipv6: plugins_configure vpn (execute task : ipsec_configure_do(,lan))	
2023-05-31T20:00:17	Notice	opnsense	/usr/local/etc/rc.newwanipv6: plugins_configure vpn (,lan)	
2023-05-31T20:00:17	Notice	opnsense	/usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : webgui_configure_do(,wan))
2023-05-31T20:00:17	Notice	opnsense	/usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : vxlan_configure_do())	
2023-05-31T20:00:17	Notice	kernel	<6>ue0: link state changed to UP	
2023-05-31T20:00:17	Notice	kernel	<6>ue0: link state changed to DOWN	
2023-05-31T20:00:17	Error	opnsense	/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'	
2023-05-31T20:00:16	Error	opnsense	/usr/local/etc/rc.linkup: The command '/sbin/mount -t devfs devfs '/var/unbound/dev'' returned exit code '1', the output was 'mount: devfs: Device busy'	
2023-05-31T20:00:16	Notice	opnsense	/usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : unbound_configure_do(,wan))	
2023-05-31T20:00:16	Notice	opnsense	/usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : openssh_configure_do(,wan))	
2023-05-31T20:00:16	Notice	opnsense	/usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : opendns_configure_do())	
2023-05-31T20:00:16	Notice	opnsense	/usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : ntpd_configure_do())	
2023-05-31T20:00:16	Notice	opnsense	/usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : dnsmasq_configure_do())	
2023-05-31T20:00:16	Notice	opnsense	/usr/local/etc/rc.newwanipv6: plugins_configure newwanip (,wan)	
2023-05-31T20:00:16	Notice	opnsense	/usr/local/etc/rc.newwanipv6: Resyncing OpenVPN instances for interface WAN.	
2023-05-31T20:00:16	Notice	opnsense	/usr/local/etc/rc.newwanipv6: plugins_configure vpn (execute task : openvpn_configure_do(,wan))	
2023-05-31T20:00:16	Notice	opnsense	/usr/local/etc/rc.newwanipv6: plugins_configure vpn (execute task : ipsec_configure_do(,wan))	
2023-05-31T20:00:16	Notice	opnsense	/usr/local/etc/rc.newwanipv6: plugins_configure vpn (,wan)	
2023-05-31T20:00:16	Notice	opnsense	/usr/local/etc/rc.newwanipv6: ROUTING: entering configure using 'lan'	
2023-05-31T20:00:16	Notice	opnsense	/usr/local/etc/rc.newwanipv6: plugins_configure monitor (execute task : dpinger_configure_do(,WAN_DHCP6))	
2023-05-31T20:00:16	Notice	opnsense	/usr/local/etc/rc.newwanipv6: plugins_configure monitor (,WAN_DHCP6)	
2023-05-31T20:00:16	Notice	opnsense	/usr/local/etc/rc.newwanipv6: ROUTING: keeping current inet6 default gateway 'fe80::4e16:fcff:fe2e:a88a%em0'	
2023-05-31T20:00:16	Notice	opnsense	/usr/local/etc/rc.newwanipv6: ROUTING: configuring inet6 default gateway on wan	
2023-05-31T20:00:16	Notice	opnsense	/usr/local/etc/rc.linkup: plugins_configure dns (execute task : unbound_configure_do())	
2023-05-31T20:00:16	Notice	opnsense	/usr/local/etc/rc.linkup: plugins_configure dns (execute task : dnsmasq_configure_do())	
2023-05-31T20:00:16	Notice	opnsense	/usr/local/etc/rc.linkup: plugins_configure dns ()	
2023-05-31T20:00:16	Notice	opnsense	/usr/local/etc/rc.newwanipv6: ROUTING: entering configure using 'wan'	
2023-05-31T20:00:16	Notice	kernel	<6>ue0: link state changed to UP	
2023-05-31T20:00:16	Notice	kernel	<6>ue0: link state changed to DOWN	
2023-05-31T20:00:16	Error	opnsense	/usr/local/etc/rc.linkup: 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: 18379'	
2023-05-31T20:00:16	Error	opnsense	/usr/local/etc/rc.linkup: The command '/usr/local/sbin/dhcpd -6 -user dhcpd -group dhcpd -chroot /var/dhcpd -cf /etc/dhcpdv6.conf -pf /var/run/dhcpdv6.pid ue0' 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.'	
2023-05-31T20:00:03	Notice	opnsense	/usr/local/etc/rc.newwanipv6: No IP change detected for WAN[wan]	
2023-05-31T20:00:03	Notice	dhcp6c	dhcp6c_script: RELEASE on em0 executing	
2023-05-31T20:00:03	Error	opnsense	/usr/local/etc/rc.newwanipv6: The command '/bin/kill -'TERM' '54098'' returned exit code '1', the output was 'kill: 54098: No such process'	
2023-05-31T20:00:03	Notice	opnsense	/usr/local/etc/rc.newwanipv6: plugins_configure dhcp (execute task : dhcpd_dhcp_configure(,inet6))	
2023-05-31T20:00:03	Notice	opnsense	/usr/local/etc/rc.newwanipv6: plugins_configure dhcp (,inet6)	
2023-05-31T20:00:03	Notice	opnsense	/usr/local/etc/rc.newwanipv6: IP renewal starting (new: 2001:8003:f00:8204:7972:6de0:daea:e19f, old: 2001:8003:f00:8204:7972:6de0:daea:e19f, interface: WAN[wan], device: em0, force: yes)	
2023-05-31T20:00:03	Notice	dhcp6c	dhcp6c_script: REQUEST on em0 renewal (REASON)	
2023-05-31T20:00:03	Notice	dhcp6c	dhcp6c_script: REQUEST on em0 executing	
2023-05-31T20:00:00	Notice	opnsense	/usr/local/etc/rc.newwanipv6: Failed to detect IP for WAN[wan]	
2023-05-31T20:00:00	Notice	dhcp6c	dhcp6c_script: RELEASE on em0 executing	
2023-05-31T20:00:00	Notice	opnsense	/usr/local/etc/rc.linkup: plugins_configure dhcp (execute task : dhcpd_dhcp_configure())	
2023-05-31T20:00:00	Notice	opnsense	/usr/local/etc/rc.linkup: plugins_configure dhcp ()	
2023-05-31T20:00:00	Notice	opnsense	/usr/local/etc/rc.linkup: plugins_configure ipsec (execute task : ipsec_configure_do(,lan))	
2023-05-31T20:00:00	Notice	opnsense	/usr/local/etc/rc.linkup: plugins_configure ipsec (,lan)	
2023-05-31T20:00:00	Notice	opnsense	/usr/local/etc/rc.linkup: ROUTING: entering configure using 'lan'	
2023-05-31T20:00:00	Notice	opnsense	/usr/local/etc/rc.linkup: DEVD: Ethernet attached event for lan(ue0)	
2023-05-31T20:00:00	Notice	kernel	<6>ue0: link state changed to UP	
2023-05-31T20:00:00	Notice	kernel	<6>ue0: link state changed to DOWN	
2023-05-31T20:00:00	Notice	opnsense	/usr/local/etc/rc.linkup: DEVD: Ethernet detached event for lan(ue0)```

Edit occured again:

2023-05-31T21:25:18	Notice	kernel	<7>cannot forward src fe80:6::8433:dfff:fe22:2f23, dst 2a03:2880:f234:1c7:face:b00c:0:7260, nxt 6, rcvif ue0, outif em0	
2023-05-31T21:24:42	Notice	opnsense	/usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : webgui_configure_do(,lan))	
2023-05-31T21:24:42	Notice	opnsense	/usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : vxlan_configure_do())	
2023-05-31T21:24:41	Notice	opnsense	/usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : unbound_configure_do(,lan))	
2023-05-31T21:24:41	Notice	opnsense	/usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : openssh_configure_do(,lan))	
2023-05-31T21:24:41	Notice	opnsense	/usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : opendns_configure_do())	
2023-05-31T21:24:36	Notice	opnsense	/usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : ntpd_configure_do())	
2023-05-31T21:24:36	Notice	opnsense	/usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : dnsmasq_configure_do())	
2023-05-31T21:24:36	Notice	opnsense	/usr/local/etc/rc.newwanipv6: plugins_configure newwanip (,lan)	
2023-05-31T21:24:36	Notice	opnsense	/usr/local/etc/rc.newwanipv6: Resyncing OpenVPN instances for interface LAN.	
2023-05-31T21:24:36	Notice	opnsense	/usr/local/etc/rc.newwanipv6: plugins_configure vpn (execute task : openvpn_configure_do(,lan))	
2023-05-31T21:24:36	Notice	opnsense	/usr/local/etc/rc.newwanipv6: plugins_configure vpn (execute task : ipsec_configure_do(,lan))	
2023-05-31T21:24:36	Notice	opnsense	/usr/local/etc/rc.newwanipv6: plugins_configure vpn (,lan)	
2023-05-31T21:24:36	Notice	opnsense	/usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : webgui_configure_do(,wan))	
2023-05-31T21:24:36	Notice	opnsense	/usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : vxlan_configure_do())	
2023-05-31T21:24:35	Notice	opnsense	/usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : unbound_configure_do(,wan))	
2023-05-31T21:24:35	Notice	opnsense	/usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : openssh_configure_do(,wan))	
2023-05-31T21:24:35	Notice	opnsense	/usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : opendns_configure_do())	
2023-05-31T21:24:35	Notice	opnsense	/usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : ntpd_configure_do())	
2023-05-31T21:24:35	Notice	opnsense	/usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : dnsmasq_configure_do())
2023-05-31T21:24:35	Notice	opnsense	/usr/local/etc/rc.newwanipv6: plugins_configure newwanip (execute task : dnsmasq_configure_do())	
2023-05-31T21:24:35	Notice	opnsense	/usr/local/etc/rc.newwanipv6: plugins_configure newwanip (,wan)	
2023-05-31T21:24:35	Notice	opnsense	/usr/local/etc/rc.newwanipv6: Resyncing OpenVPN instances for interface WAN.	
2023-05-31T21:24:35	Notice	opnsense	/usr/local/etc/rc.newwanipv6: plugins_configure vpn (execute task : openvpn_configure_do(,wan))	
2023-05-31T21:24:35	Notice	opnsense	/usr/local/etc/rc.newwanipv6: plugins_configure vpn (execute task : ipsec_configure_do(,wan))	
2023-05-31T21:24:35	Notice	opnsense	/usr/local/etc/rc.newwanipv6: plugins_configure vpn (,wan)	
2023-05-31T21:24:35	Notice	opnsense	/usr/local/etc/rc.newwanipv6: ROUTING: entering configure using 'lan'	
2023-05-31T21:24:35	Notice	opnsense	/usr/local/etc/rc.newwanipv6: plugins_configure monitor (execute task : dpinger_configure_do(,WAN_DHCP6))	
2023-05-31T21:24:35	Notice	opnsense	/usr/local/etc/rc.newwanipv6: plugins_configure monitor (,WAN_DHCP6)	
2023-05-31T21:24:35	Notice	opnsense	/usr/local/etc/rc.newwanipv6: ROUTING: keeping current inet6 default gateway 'fe80::4e16:fcff:fe2e:a88a%em0'	
2023-05-31T21:24:35	Notice	opnsense	/usr/local/etc/rc.newwanipv6: ROUTING: configuring inet6 default gateway on wan	
2023-05-31T21:24:35	Notice	opnsense	/usr/local/etc/rc.newwanipv6: ROUTING: entering configure using 'wan'	
2023-05-31T21:24:35	Error	opnsense	/usr/local/etc/rc.newwanipv6: The command '/bin/kill -'TERM' '63101'' returned exit code '1', the output was 'kill: 63101: No such process'	
2023-05-31T21:24:35	Notice	opnsense	/usr/local/etc/rc.newwanipv6: plugins_configure dhcp (execute task : dhcpd_dhcp_configure(,inet6))	
2023-05-31T21:24:35	Notice	opnsense	/usr/local/etc/rc.newwanipv6: plugins_configure dhcp (,inet6)	
2023-05-31T21:24:35	Notice	opnsense	/usr/local/etc/rc.newwanipv6: IP renewal starting (new: 2001:8003:f00:8204:7972:6de0:daea:e19f, old: 2001:8003:f00:8204:7972:6de0:daea:e19f, interface: WAN[wan], device: em0, force: yes)	
2023-05-31T21:24:35	Notice	dhcp6c	dhcp6c_script: REQUEST on em0 renewal (REASON)	
2023-05-31T21:24:35	Notice	dhcp6c	dhcp6c_script: REQUEST on em0 executing
```

fichtner · 2023-05-31T14:59:12Z

Hmm, you are patching the wrong thing. Try a plain 23.1.9 it should be better already.

Sieboldianus · 2023-06-02T04:45:11Z

I just updated to 23.1.9 and also get the same error as others above:

2023-06-02T06:37:09	Error	opnsense	/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'	
2023-06-02T06:37:09	Error	opnsense	/usr/local/etc/rc.newwanipv6: The command '/bin/kill -'TERM' '3872'' returned exit code '1', the output was 'kill: 3872: No such process'

this log directly appeared after restarting after update to 23.1.9
Unbound was stopped after reboot after update
manually starting unbound worked

Briefly after the error above, I also saw this one:

2023-06-02T06:37:14	Error	opnsense	/usr/local/etc/rc.newwanipv6: Error: Invalid certificate hash info for

My IPv6 configuration is all green and working, from the OPNsense side, but when checked with external services (https://test-ipv6.com/), I have no IPv6 connectivity. This is since 23.1.8. On 23.1.7, I had all green lights with the same connection settings (default, from the docs).

fichtner · 2023-06-02T04:54:00Z

@Sieboldianus I don’t see anything related to what you are describing.

Sieboldianus · 2023-06-02T04:57:49Z

@fichtner: Yes, my IPv6 problems may be unrelated to the logs above (the only thing that pointed me to IPv6 was seeing newwanipv6 in the logs).

Perhaps also unrelated is that https://test-ipv6.com/ suddenly shows all green lights. I was just going to update my answer above. It seems the update to 23.1.9 has fixed my IPv6 problem.

fichtner · 2023-06-02T05:30:26Z

hmm, ok. An interface reconfiguration is required to replace the faulty script and a reboot or kill for dhcp6c to pick up the updated binary. If you still see issues later I’d recommend a reboot just to be sure.

robert1993 · 2023-06-09T13:24:04Z

Interestingly I'm seeing exactly the same behaviour since the last update. dhcpv6 constantly crashing for some reason with the same log entries as shared by @TheekshanaA.

fichtner · 2023-06-09T13:30:02Z

Which error? Do you also use „ue“
USB Ethernet driver? Not very reliable.

TheekshanaA · 2023-06-09T13:51:36Z

I thought I'd give an update. I've switched to a intel pcie NIC and my setup has been extremely reliable however I am still getting the cannot forward ipv6 errors. I'm not sure if this is related to the dhcpv6 issue or not. Definitely will not be using a USB ethernet adapter again however I had no choice as I was waiting for my intel NIC to arrive. Thanks for the update

robert1993 · 2023-06-09T14:43:50Z

The errors as shown in the general log which where shared by TheekshanaA. I'm not using a USB Ethernet driver, I have a Intel I350 NICs in a Sophos XG430 appliance.

I did run the proposed reverts and patches, and it seems more stable now. But I will update you with my logs once it happens again.

robert1993 · 2023-06-11T10:40:18Z

It happened again. Not that often as before, but the issue persists.
system.log.csv

fichtner · 2023-06-12T08:52:18Z

cannot forward src fe80:6::8433:dfff:fe22:2f23, dst 2a03:2880:f234:1c7:face:b00c:0:7260, nxt 6, rcvif ue0, outif em0

These are most likely Android phones failing to acquire a GUA via SLAAC. They send out garbage anyway.

Not much we can do about it and no relation to WAN side dhcp6c being discussed here. Check your LAN settings and also see https://docs.opnsense.org/manual/ipv6.html#basic-setup-and-troubleshooting

Cheers,
Franco

TheekshanaA · 2023-06-12T10:23:48Z

cannot forward src fe80:6::8433:dfff:fe22:2f23, dst 2a03:2880:f234:1c7:face:b00c:0:7260, nxt 6, rcvif ue0, outif em0

These are most likely Android phones failing to acquire a GUA via SLAAC. They send out garbage anyway.

Not much we can do about it and no relation to WAN side dhcp6c being discussed here. Check your LAN settings and also see https://docs.opnsense.org/manual/ipv6.html#basic-setup-and-troubleshooting

Cheers, Franco

Can confirm, I have multiple android devices on my network so you are likely correct. Thought I'd also mention there are no more DHCP failing to renew errors that the others are reporting on my router. It may be worth noting I did spoof my MAC address to be the same as my original router's WAN port however I am not sure if this is related or not. Furthermore, my IPv6 tests do fail on my network.

fichtner · 2023-06-29T12:20:26Z

Closing this since initial topic fixed. Likely more issues exist in certain setups and it would be better to work on details reports for each one.

agowa changed the title ~~radvd not prefix deprecation old prefix on dhcp6c RENEW~~ radvd not deprecation old prefix on dhcp6c RENEW Apr 24, 2023

fichtner added the support Community support label Apr 24, 2023

fichtner mentioned this issue Apr 24, 2023

IPV6 Routing problem on LAN if re0 #6475

Closed

fichtner self-assigned this Apr 24, 2023

fichtner added feature Adding new functionality and removed support Community support labels Apr 24, 2023

fichtner added this to the 23.7 milestone Apr 24, 2023

fichtner added a commit that referenced this issue Apr 24, 2023

dhcp: restart radvd on config changes #6522

3cb2dd7

prefix is not deprecated unless we shut down

fichtner added a commit that referenced this issue May 11, 2023

interfaces: report current IP for #6522

660206e

(cherry picked from commit 2db028d)

fichtner added a commit that referenced this issue May 11, 2023

interfaces: protect against INFOREQ in PDINFO force case #6522

485bd39

fichtner added a commit that referenced this issue May 12, 2023

interfaces: rebind/renew backport for #6522

05c6f2e

fichtner changed the title ~~radvd not deprecation old prefix on dhcp6c RENEW~~ interfaces: properly react to RENEW/REBIND from dhcp6c May 12, 2023

fichtner added a commit that referenced this issue May 16, 2023

interfaces: rebind/renew DHCPv6 handling backport; #6522

dcc57e1

fichtner closed this as completed Jun 29, 2023

interfaces: properly react to RENEW/REBIND from dhcp6c #6522

interfaces: properly react to RENEW/REBIND from dhcp6c #6522

Comments

agowa commented Apr 24, 2023

fichtner commented Apr 24, 2023

fichtner commented Apr 24, 2023

agowa commented Apr 24, 2023 • edited Loading

fichtner commented Apr 24, 2023

agowa commented Apr 24, 2023

fichtner commented Apr 24, 2023

fichtner commented Apr 24, 2023 • edited Loading

agowa commented Apr 24, 2023

fichtner commented Apr 24, 2023

agowa commented Apr 24, 2023

fichtner commented Apr 24, 2023

fichtner commented Apr 24, 2023

meyergru commented Apr 24, 2023 • edited Loading

fichtner commented Apr 24, 2023

meyergru commented Apr 24, 2023 • edited Loading

fichtner commented Apr 24, 2023

fichtner commented Apr 24, 2023

agowa commented Apr 24, 2023

meyergru commented Apr 24, 2023

fichtner commented Apr 24, 2023

agowa commented Apr 24, 2023 • edited Loading

fichtner commented Apr 24, 2023

fichtner commented May 11, 2023

agowa commented May 11, 2023 • edited Loading

agowa commented May 11, 2023 • edited Loading

fichtner commented May 12, 2023

fichtner commented May 24, 2023

TheekshanaA commented May 31, 2023

fichtner commented May 31, 2023

TheekshanaA commented May 31, 2023 • edited Loading

fichtner commented May 31, 2023

TheekshanaA commented May 31, 2023 • edited Loading

TheekshanaA commented May 31, 2023 • edited Loading

fichtner commented May 31, 2023

Sieboldianus commented Jun 2, 2023 • edited Loading

fichtner commented Jun 2, 2023

Sieboldianus commented Jun 2, 2023

fichtner commented Jun 2, 2023

robert1993 commented Jun 9, 2023

fichtner commented Jun 9, 2023

TheekshanaA commented Jun 9, 2023

robert1993 commented Jun 9, 2023 • edited Loading

robert1993 commented Jun 11, 2023

fichtner commented Jun 12, 2023

TheekshanaA commented Jun 12, 2023 • edited Loading

fichtner commented Jun 29, 2023

agowa commented Apr 24, 2023 •

edited

Loading

fichtner commented Apr 24, 2023 •

edited

Loading

meyergru commented Apr 24, 2023 •

edited

Loading

meyergru commented Apr 24, 2023 •

edited

Loading

agowa commented Apr 24, 2023 •

edited

Loading

agowa commented May 11, 2023 •

edited

Loading

agowa commented May 11, 2023 •

edited

Loading

TheekshanaA commented May 31, 2023 •

edited

Loading

TheekshanaA commented May 31, 2023 •

edited

Loading

TheekshanaA commented May 31, 2023 •

edited

Loading

Sieboldianus commented Jun 2, 2023 •

edited

Loading

robert1993 commented Jun 9, 2023 •

edited

Loading

TheekshanaA commented Jun 12, 2023 •

edited

Loading