Acquiring ipv6 address can take 5 to 10 minutes.

[marjohn56]

I've installed 20.1 on my test router ( damn it, just remembered I forgot to copy over some of the dev work! ), it was showing the same issue.


I've found it quicker to test just use my Android mobile, a disable/enable wifi and using the Net Analyzer App shows me an immediate v6 address if RADVD is working. Again it appears to be my primary switch causing the issue. I disabled MLD on the switch and immediately IPv6 was back up on my mobile.


Still testing, but at the moment it's all good again, slightly baffled, as I'm sure I did the same thing yesterday too.  :-\

[gpb]

@marjohn56, Did you do a packet capture?  The ipad I tested with performed three identical solicitations before the RA to ALL hosts was received, then it was able to establish a unicast global address.  That took about 90 seconds.  I hate to put this on github for support if this is a config issue on my side...though I didn't have the problem until the power outage we had made it noticeable.  I think in the past the hosts would all keep their addresses during a router reboot...but shutting everything down caused a full reset.  Speculating...but that's how it seems as I didn't have the problem with 20.7RC/20.7 initially then network reset and problem became visible.

I wonder if radvd is seeing the request and not responding or just never seeing it.  And if it's not seeing it, why.  Not sure if it can be monitored with some kind of verbose output...couldn't find much.

Thanks.

[marjohn56]

Sorry it took a while to get back, been busy. I did use Wireshark but only on my PC, which is a couple of switches away from Opnsense. Over the weekend I saved off the config, did a fresh install of 20.7, updated to 20.7.1 and re-imported the config - it's my usual routine if I have strangeness. I reset all of my switches too, now 48 hours plus later and no further issues on any of my devices, mobile or fixed, everything appears happy.

[gpb]

Thanks @marjohn56, so just to clarify, when you say "no further issues" you mean you verified that RADVD is now replying to solicitations?  Cheers!

[marjohn56]

Correct, no issues here with radvd,

[staticznld]

Still isseus here.

I see in the firewall log an message from a link local address to the FF02::2 and it passed.
So I assume the Router solicitation will come to Radvd.

When the link local address of the OPNsense box sends the router advertisements to FF02::2 then the client can configure its ip address.

[gpb]

I'm also still looking at this trying to understand the radvd advertisement process.  As I understand it, it sends unsolicited and (should send) solicited adv's...but I never see the solicited responses, any response goes to ff02::1 (all-nodes).  And I'm not sure if @marjohn56 ever did either, he indicated only that he's not having an issue (and I don't have an issue once I get an address).  Was more interested from a learning and debugging aspect.  Can't find a lot of info unfortunately...still looking tho.

[dave]

I'm experiencing this with an Android device.  Not noticeable on my Win10 box because as soon as ipv4 connectivity's established Windows is happy; but Android reports my WLAN has no internet connectivity until IPv6 kicks in which can take ~20 seconds.  For the time being I've just disabled IPv6 on my WLAN.

[marjohn56]

I still see this randomly, so I have enabled debug on RADVD to see what's happening, of course, since I've enabled the debug it's behaving itself!


If you want to enable full debug and see if you can see something odd in your logs do this. Firstly you need to kill the existing RADVD daemon, either from the GUI or shell. Next you need to re-launch it from the shell. Normally what little logging it gives in default mode goes to syslog, we'll send it to a new log of its own. Issue the following command in the shell.


# /usr/local/sbin/radvd -d 5 -p /var/run/radvd.pid -C /var/etc/radvd.conf -m logfile -l /var/log/radvd.log

You'll now get verbose output in the /var/log/radvd.log file. In the log you SHOULD see something like, this, it's an RS from my PC which I had disabled then re-enabled IPv6.

[Aug 19 15:07:16] radvd (21158): igb1_vlan101 received RS from: fe80::2887:a02e:93cd:6d96

See if gives any clues.

[gpb]

Thanks for that.  It looks like I am having an issue with these three messages repeating frequently (every 20 secs or so). 

EDIT: This appears normal, it's apparently just a router advertisement from WAN (igb1).

Code Select Expand

[Aug 19 13:07:30] radvd (85849): igb1 recvmsg len=16
[Aug 19 13:07:30] radvd (85849): igb1 received a packet
[Aug 19 13:07:30] radvd (85849): igb1 received icmpv6 RS/RA packet on an unknown interface with index 2

My network is simplistic, WAN (igb1), LAN (igb0) and VLAN (no ipv6; igb0).

I re-ran the ipad test and there is nothing in the log that radvd received a request.  It actually never shows a request received from ibg0 ever.  The above snippet continues repeatedly until about 90 seconds past when I initiated the test and then there's finally a mention of igb0:

Code Select Expand

[Aug 19 13:15:22] radvd (85849): igb1 received icmpv6 RS/RA packet on an unknown interface with index 2
[Aug 19 13:15:22] radvd (85849): polling for 3.394 second(s), next iface is igb0
[Aug 19 13:15:26] radvd (85849): timer_handler called for igb0
[Aug 19 13:15:26] radvd (85849): ioctl(SIOCGIFFLAGS) succeeded on igb0
[Aug 19 13:15:26] radvd (85849): igb0 is up
[Aug 19 13:15:26] radvd (85849): igb0 is running
[Aug 19 13:15:26] radvd (85849): igb0 supports multicast or is point-to-point
[Aug 19 13:15:26] radvd (85849): mtu for igb0 is 1500
[Aug 19 13:15:26] radvd (85849): link layer token length for igb0 is 48
[Aug 19 13:15:26] radvd (85849): prefix length for igb0 is 64
[Aug 19 13:15:26] radvd (85849): checking ipv6 forwarding of interface not supported
[Aug 19 13:15:26] radvd (85849): igb0 linklocal address: fe80::f6ce:46ff:fea9:7ad0
[Aug 19 13:15:26] radvd (85849): igb0 address: 2607:fcc8:f142:xxxx:f6ce:46ff:fea9:7ad0
[Aug 19 13:15:26] radvd (85849): igb0 address: fe80::f6ce:46ff:fea9:7ad0
[Aug 19 13:15:26] radvd (85849): igb0 is ready
[Aug 19 13:15:26] radvd (85849): checking ipv6 forwarding not supported
[Aug 19 13:15:26] radvd (85849): sending RA to ff02::1 on igb0 (fe80::f6ce:46ff:fea9:7ad0), 5 options (using 104/1210 bytes)
[Aug 19 13:15:26] radvd (85849): igb0 next scheduled RA in 124.646 second(s)
[Aug 19 13:15:26] radvd (85849): polling for 124.645 second(s), next iface is igb0
[Aug 19 13:15:26] radvd (85849): igb0 recvmsg len=104
[Aug 19 13:15:26] radvd (85849): igb0 received a packet
[Aug 19 13:15:26] radvd (85849): igb0 received RA from: fe80::f6ce:46ff:fea9:7ad0 (myself)
[Aug 19 13:15:26] radvd (85849): processed RA on igb0
[Aug 19 13:15:26] radvd (85849): polling for 124.645 second(s), next iface is igb0
[Aug 19 13:15:29] radvd (85849): igb1 recvmsg len=16


Here is the radvd initialization section:

Code Select Expand

[Aug 19 12:56:18] radvd (84538): version 2.18 started
[Aug 19 12:56:18] radvd (84538): igb0 interface definition ok
[Aug 19 12:56:18] radvd (84538): config file, /var/etc/radvd.conf, syntax ok
[Aug 19 12:56:18] radvd (84538): checking ipv6 forwarding not supported
[Aug 19 12:56:18] radvd (84538): radvd startup PID is 84538
[Aug 19 12:56:18] radvd (84538): opened pid file /var/run/radvd.pid
[Aug 19 12:56:18] radvd (84538): locked pid file /var/run/radvd.pid
[Aug 19 12:56:18] radvd (85849): opened pid file /var/run/radvd.pid
[Aug 19 12:56:18] radvd (85849): radvd PID is 85849
[Aug 19 12:56:18] radvd (85849): wrote pid 85849 to pid file: /var/run/radvd.pid
[Aug 19 12:56:18] radvd (84538): child signaled pid file written: 85849
[Aug 19 12:56:18] radvd (84538): Freeing Interfaces
[Aug 19 12:56:18] radvd (84538): freeing interface igb0
[Aug 19 12:56:18] radvd (85849): validated pid file, /var/run/radvd.pid: 85849
[Aug 19 12:56:18] radvd (85849): igb0 if_index changed from 0 to 1
[Aug 19 12:56:18] radvd (85849): ioctl(SIOCGIFFLAGS) succeeded on igb0
[Aug 19 12:56:18] radvd (85849): igb0 is up
[Aug 19 12:56:18] radvd (85849): igb0 is running
[Aug 19 12:56:18] radvd (85849): igb0 supports multicast or is point-to-point
[Aug 19 12:56:18] radvd (85849): mtu for igb0 is 1500
[Aug 19 12:56:18] radvd (85849): link layer token length for igb0 is 48
[Aug 19 12:56:18] radvd (85849): prefix length for igb0 is 64
[Aug 19 12:56:18] radvd (85849): checking ipv6 forwarding of interface not supported
[Aug 19 12:56:18] radvd (85849): igb0 linklocal address: fe80::f6ce:46ff:fea9:7ad0
[Aug 19 12:56:18] radvd (85849): igb0 address: 2607:fcc8:f142:xxxx:f6ce:46ff:fea9:7ad0
[Aug 19 12:56:18] radvd (85849): igb0 address: fe80::f6ce:46ff:fea9:7ad0
[Aug 19 12:56:18] radvd (85849): igb0 is ready
[Aug 19 12:56:18] radvd (85849): setting LinkMTU (1500) for igb0 is not supported
[Aug 19 12:56:18] radvd (85849): setting CurHopLimit (64) for igb0 is not supported
[Aug 19 12:56:18] radvd (85849): ioctl(SIOCGIFFLAGS) succeeded on igb0
[Aug 19 12:56:18] radvd (85849): igb0 is up
[Aug 19 12:56:18] radvd (85849): igb0 is running
[Aug 19 12:56:18] radvd (85849): igb0 supports multicast or is point-to-point
[Aug 19 12:56:18] radvd (85849): mtu for igb0 is 1500
[Aug 19 12:56:18] radvd (85849): link layer token length for igb0 is 48
[Aug 19 12:56:18] radvd (85849): prefix length for igb0 is 64
[Aug 19 12:56:18] radvd (85849): checking ipv6 forwarding of interface not supported
[Aug 19 12:56:18] radvd (85849): igb0 linklocal address: fe80::f6ce:46ff:fea9:7ad0
[Aug 19 12:56:18] radvd (85849): igb0 address: 2607:fcc8:f142:xxxx:f6ce:46ff:fea9:7ad0
[Aug 19 12:56:18] radvd (85849): igb0 address: fe80::f6ce:46ff:fea9:7ad0
[Aug 19 12:56:18] radvd (85849): igb0 is ready
[Aug 19 12:56:18] radvd (85849): checking ipv6 forwarding not supported
[Aug 19 12:56:18] radvd (85849): sending RA to ff02::1 on igb0 (fe80::f6ce:46ff:fea9:7ad0), 5 options (using 104/1210 bytes)
[Aug 19 12:56:18] radvd (85849): igb0 next scheduled RA in 16 second(s)
[Aug 19 12:56:18] radvd (85849): polling for 16 second(s), next iface is igb0
[Aug 19 12:56:18] radvd (85849): igb0 recvmsg len=104
[Aug 19 12:56:18] radvd (85849): igb0 received a packet
[Aug 19 12:56:18] radvd (85849): igb0 received RA from: fe80::f6ce:46ff:fea9:7ad0 (myself)

I'm not sure what to make of this.  Any ideas...?  Thanks!

[Maurice]

This has finally improved with the recent 21.1.a_296 update (development branch). Not sure yet whether it's fixed for good, but radvd's responsiveness seems to be more or less back to what it was pre-20.7.

[Update]
Issue occurred again, so either it's only partially fixed or the apparent improvement was just a coincidence.
[/Update]