Dhcpv6 client doesn't complete negotiation, no delegated prefix

I have this issue with dhcpv6 client on my RPi4. The RPi sends dhcp solicit, gets the advertise but won't send the request. Instead it keeps resending the solicit over and over and never installs the /56 delegated prefix, the interface wan6 only gets the /64 address.

ubus call system board
{
	"kernel": "5.4.82",
	"hostname": "magiatiko",
	"model": "Raspberry Pi 4 Model B Rev 1.2",
	"board_name": "raspberrypi,4-model-b",
	"release": {
		"distribution": "OpenWrt",
		"version": "SNAPSHOT",
		"revision": "r15199-5d2b577a53",
		"target": "bcm27xx/bcm2711",
		"description": "OpenWrt SNAPSHOT r15199-5d2b577a53"
	}
}

network.wan6=interface
network.wan6.proto='dhcpv6'
network.wan6.peerdns='0'
network.wan6.ifname='@wan'
network.wan6.metric='20'
network.wan6.sourcerouting='0'
network.wan6.reqaddress='try'
network.wan6.reqprefix='auto'
network.wan6.macaddr='00:1e:10:1f:00:00'
network.wan6.clientid='00030001001e101f0000'

root@magiatiko / > opkg list-installed | grep dhcp6
odhcp6c - 2020-12-08-0ffa3a31-16

root@magiatiko / > tcpdump -i pppoe-wan -evn udp port 547 or icmp6
tcpdump: listening on pppoe-wan, link-type LINUX_SLL (Linux cooked v1), capture size 262144 bytes
18:03:22.699840 Out ethertype IPv6 (0x86dd), length 64: (flowlabel 0xc41b3, hlim 255, next-header ICMPv6 (58) payload length: 8) fe80::31fa:bcbc:5651:16b8 > ff02::2: [icmp6 sum ok] ICMP6, router solicitation, length 8
18:03:22.703273  In ethertype IPv6 (0x86dd), length 144: (class 0xc0, hlim 255, next-header ICMPv6 (58) payload length: 88) fe80::10c > ff02::1: [icmp6 sum ok] ICMP6, router advertisement, length 88
	hop limit 64, Flags [managed], pref medium, router lifetime 1800s, reachable time 0ms, retrans timer 0ms
	  rdnss option (25), length 40 (5):  lifetime 900s, addr: 2001:4860:4860::8844 addr: 2001:4860:4860::8888
	  prefix info option (3), length 32 (4): 2222:3333:227:75d3::/64, Flags [onlink, auto], valid time 2592000s, pref. time 604800s
18:03:22.978595 Out ethertype IPv6 (0x86dd), length 168: (flowlabel 0x68036, hlim 1, next-header UDP (17) payload length: 112) fe80::31fa:bcbc:5651:16b8.546 > ff02::1:2.547: [udp sum ok] dhcp6 solicit (xid=7411fe (elapsed-time 0) (option-request SIP-servers-domain SIP-servers-address DNS-server DNS-search-list SNTP-servers NTP-server AFTR-Name opt_67 opt_94 opt_95 opt_96 opt_82) (client-ID hwaddr type 1 001e101f0000) (reconfigure-accept) (Client-FQDN) (IA_NA IAID:1 T1:0 T2:0) (IA_PD IAID:1 T1:0 T2:0))
18:03:22.984957  In ethertype IPv6 (0x86dd), length 182: (hlim 64, next-header UDP (17) payload length: 126) fe80::10c.547 > fe80::31fa:bcbc:5651:16b8.546: [udp sum ok] dhcp6 advertise (xid=7411fe (client-ID hwaddr type 1 001e101f0000) (server-ID hwaddr type 1 6c3b6bee0d46) (preference 255) (DNS-server 2001:4860:4860::8888 2001:4860:4860::8844) (IA_PD IAID:1 T1:450 T2:720 (IA_PD-prefix 2222:3333:225:7500::/56 pltime:810 vltime:900)))

If I reboot it works fine for some time, then it goes back to this non working state. Nothing interesting in the logs.
Anyone has a clue what can be triggering this?

could be build related... ( did it just begin on this build? ) what says;

ps w | grep odhcp6c | grep -v grep
build related notes

i've tested some debugging mods... but I dont run so many settings so could be a bug... to rule it out... run this...

curl https://raw.githubusercontent.com/wulfy23/rpi4/master/utilities/dhcpv6.sh > /lib/netifd/proto/dhcpv6.sh
rm /etc/odhcp6c.user

there were also some mwan things going on... either side of that release... lemme check which build had the latter PR's...

yeah.. that build is on the 'pre' side of the recent PR's

$ diff r15233_testing/rpi-4_snapshot_2.3.653-26_r15233_extra/*ani* rpi-4_snapshot_2.3.637-2_r15199_extra/*ani* | grep mwan3
< mwan3 - 2.10.4-1
> mwan3 - 2.10.3-3
mwan3: update version
mwan3: add more error logging to routing
mwan3: improve route flushing on mwan3
mwan3: fix race condition in route loading
mwan3: fix linkdown routes not being added

and a third possibility might be one/some of the recently added 'ip6-nat-type' modules to the build...

diff rpi-4_snapshot_2.3.637-2_r15199_extra/*mani* rpi-4_snapshot_2.3.637-3_r15199_std/*mani* | grep ip | grep 6
< ip6tables-extra - 1.8.4-1
< ip6tables-mod-nat - 1.8.4-1
< kmod-ip6-tunnel - 5.4.82-1
< kmod-ip6tables-extra - 5.4.82-1
< kmod-ipt-nat6 - 5.4.82-1
< kmod-ipt-raw6 - 5.4.82-1
< kmod-iptunnel6 - 5.4.82-1
< luci-proto-ipip - git-19.307.61018-284918b

and number 4 which goes back to the 8th... ( my money would be on these? )

2020-12-08	dhcpv6: harden reconfigure logic

Check if a valid DHCPv6 message is returned by dhcpv6_request in
dhcpv6_poll_reconfigure as only RENEW/REBIND/INFORMATION REQUEST
messages can trigger the transmission of these messages in reply
to a RECONFIGURE

2020-12-08	dhcpv6: rework DHCPv6 message to string implementation

As the DHCPv6 messages handled by odhcp6c are not numerical consecutive drop the DHCPv6 message string array

2020-12-07	dhcpv6: fix regression

Fixes regression introduced in commit faed29a.
The DHCPv6 message type need to be returned by dhcpv6_handle_reconfigure via dhcpv6_request when different from -1 so the correct message type is passed to dhcpv6_request


2020-12-07	dhcpv6: improve syslog tracing
2020-12-03	dhcpv6: only refresh timers when reconfigure is valid
2020-12-03	dhcpv6: fix printing identity association id
2020-12-01	dhcpv6: avoid sending continuous renew/rebind messages
1 Like

8305 root 972 S odhcp6c -s /lib/netifd/dhcpv6.script -Ntry -P0 -c00030001001e101f0000 -t120 pppoe-wan

Done, now it runs as odhcp6c -s /lib/netifd/dhcpv6.script -Ntry -P0 -c00030001001e101f0000 -t120 pppoe-wan

This is the sole ipv6 interface, not sure if it should be affected by mwan3 at this point.

1 Like

just in case you wanted to switch back the debugging script ( enables -e and -v options for odhcp6c );

curl https://raw.githubusercontent.com/wulfy23/rpi4/master/utilities/dhcpv6.sh.debug > /lib/netifd/proto/dhcpv6.sh
echo 'IPV6cVERBOSE=1' >> /root/wrt.ini
1 Like

I enabled the debugging and rebooted.
It worked fine upon first boot. However when I restarted the wan6 interface, it seems that the advertisement packet never reaches the odhcp6c process, although it seems to reach the router from tcpdump output.

root@magiatiko / > logread -e dhcp6c
Tue Dec 22 20:54:29 2020 daemon.notice odhcp6c[10716]: (re)starting transaction on pppoe-wan
Tue Dec 22 20:54:29 2020 daemon.notice netifd: wan6 (10716): odhcp6c[10716]: (re)starting transaction on pppoe-wan
Tue Dec 22 20:54:30 2020 daemon.notice odhcp6c[10716]: Starting SOLICIT transaction (timeout 4294967295s, max rc 0)
Tue Dec 22 20:54:30 2020 daemon.notice netifd: wan6 (10716): odhcp6c[10716]: Starting SOLICIT transaction (timeout 4294967295s, max rc 0)
Tue Dec 22 20:54:30 2020 daemon.notice odhcp6c[10716]: Got a valid ADVERTISE after 4ms
Tue Dec 22 20:54:30 2020 daemon.info odhcp6c[10716]: IAID 0001 T1 450 T2 720
Tue Dec 22 20:54:30 2020 daemon.info odhcp6c[10716]: 2222:3333:225:7500::/56 preferred 810 valid 900
Tue Dec 22 20:54:30 2020 daemon.notice netifd: wan6 (10716): odhcp6c[10716]: Got a valid ADVERTISE after 4ms
Tue Dec 22 20:54:30 2020 daemon.notice netifd: wan6 (10716): odhcp6c[10716]: IAID 0001 T1 450 T2 720
Tue Dec 22 20:54:30 2020 daemon.notice netifd: wan6 (10716): odhcp6c[10716]: 2222:3333:225:7500::/56 preferred 810 valid 900
Tue Dec 22 20:54:30 2020 daemon.notice odhcp6c[10716]: Starting SOLICIT transaction (timeout 4294967295s, max rc 0)
Tue Dec 22 20:54:30 2020 daemon.notice netifd: wan6 (10716): odhcp6c[10716]: Starting SOLICIT transaction (timeout 4294967295s, max rc 0)
Tue Dec 22 20:54:30 2020 daemon.notice odhcp6c[10716]: Got a valid ADVERTISE after 3ms
Tue Dec 22 20:54:30 2020 daemon.info odhcp6c[10716]: IAID 0001 T1 450 T2 720
Tue Dec 22 20:54:30 2020 daemon.info odhcp6c[10716]: 2222:3333:225:7500::/56 preferred 810 valid 900
Tue Dec 22 20:54:30 2020 daemon.notice netifd: wan6 (10716): odhcp6c[10716]: Got a valid ADVERTISE after 3ms
Tue Dec 22 20:54:30 2020 daemon.notice netifd: wan6 (10716): odhcp6c[10716]: IAID 0001 T1 450 T2 720
Tue Dec 22 20:54:30 2020 daemon.notice netifd: wan6 (10716): odhcp6c[10716]: 2222:3333:225:7500::/56 preferred 810 valid 900
Tue Dec 22 20:54:31 2020 daemon.notice odhcp6c[10716]: Starting REQUEST transaction (timeout 4294967295s, max rc 10)
Tue Dec 22 20:54:31 2020 daemon.notice odhcp6c[10716]: Send REQUEST message (elapsed 0ms, rc 0)
Tue Dec 22 20:54:31 2020 daemon.notice netifd: wan6 (10716): odhcp6c[10716]: Starting REQUEST transaction (timeout 4294967295s, max rc 10)
Tue Dec 22 20:54:31 2020 daemon.notice netifd: wan6 (10716): odhcp6c[10716]: Send REQUEST message (elapsed 0ms, rc 0)
Tue Dec 22 20:54:31 2020 daemon.notice odhcp6c[10716]: Got a valid REPLY after 27ms
Tue Dec 22 20:54:31 2020 daemon.info odhcp6c[10716]: IAID 0001 T1 450 T2 720
Tue Dec 22 20:54:31 2020 daemon.info odhcp6c[10716]: 2222:3333:225:7500::/56 preferred 810 valid 900
Tue Dec 22 20:54:31 2020 daemon.info odhcp6c[10716]: T1 450s, T2 720s, T3 900s
Tue Dec 22 20:54:31 2020 daemon.notice netifd: wan6 (10716): odhcp6c[10716]: Got a valid REPLY after 27ms
Tue Dec 22 20:54:31 2020 daemon.notice netifd: wan6 (10716): odhcp6c[10716]: IAID 0001 T1 450 T2 720
Tue Dec 22 20:54:31 2020 daemon.notice netifd: wan6 (10716): odhcp6c[10716]: 2222:3333:225:7500::/56 preferred 810 valid 900
Tue Dec 22 20:54:31 2020 daemon.notice netifd: wan6 (10716): odhcp6c[10716]: T1 450s, T2 720s, T3 900s
Tue Dec 22 20:54:31 2020 daemon.notice odhcp6c[10716]: entering stateful-mode on pppoe-wan
Tue Dec 22 20:54:31 2020 daemon.notice odhcp6c[10716]: Starting <POLL> transaction (timeout 450s, max rc 0)
Tue Dec 22 20:54:31 2020 daemon.notice netifd: wan6 (10716): odhcp6c[10716]: entering stateful-mode on pppoe-wan
Tue Dec 22 20:54:31 2020 daemon.notice netifd: wan6 (10716): odhcp6c[10716]: Starting <POLL> transaction (timeout 450s, max rc 0)

<wan6 restart>

Tue Dec 22 20:56:07 2020 daemon.notice odhcp6c[10716]: Starting RELEASE transaction (timeout 4294967295s, max rc 5)
Tue Dec 22 20:56:07 2020 daemon.notice odhcp6c[10716]: Send RELEASE message (elapsed 0ms, rc 0)
Tue Dec 22 20:56:07 2020 daemon.notice netifd: wan6 (10716): odhcp6c[10716]: Starting RELEASE transaction (timeout 4294967295s, max rc 5)
Tue Dec 22 20:56:07 2020 daemon.notice netifd: wan6 (10716): odhcp6c[10716]: Send RELEASE message (elapsed 0ms, rc 0)
Tue Dec 22 20:56:07 2020 daemon.notice odhcp6c[26361]: (re)starting transaction on pppoe-wan
Tue Dec 22 20:56:07 2020 daemon.notice netifd: wan6 (26361): odhcp6c[26361]: (re)starting transaction on pppoe-wan
Tue Dec 22 20:56:07 2020 daemon.notice odhcp6c[26361]: Starting SOLICIT transaction (timeout 4294967295s, max rc 0)
Tue Dec 22 20:56:07 2020 daemon.notice netifd: wan6 (26361): odhcp6c[26361]: Starting SOLICIT transaction (timeout 4294967295s, max rc 0)

It doesn't seem to be blocked on the firewall.

I restarted the wan6 one more time. Now it seems that it gets the advertisement, sends a request, reply is seen on tcpdump, but not in the logs.

ue Dec 22 21:14:22 2020 daemon.notice odhcp6c[9270]: (re)starting transaction on pppoe-wan
Tue Dec 22 21:14:22 2020 daemon.notice netifd: wan6 (9270): odhcp6c[9270]: (re)starting transaction on pppoe-wan
Tue Dec 22 21:14:22 2020 daemon.notice odhcp6c[9270]: Starting SOLICIT transaction (timeout 4294967295s, max rc 0)
Tue Dec 22 21:14:22 2020 daemon.notice netifd: wan6 (9270): odhcp6c[9270]: Starting SOLICIT transaction (timeout 4294967295s, max rc 0)
Tue Dec 22 21:14:25 2020 daemon.notice odhcp6c[9270]: Got a valid ADVERTISE after 3348ms
Tue Dec 22 21:14:25 2020 daemon.info odhcp6c[9270]: IAID 0001 T1 450 T2 720
Tue Dec 22 21:14:25 2020 daemon.notice netifd: wan6 (9270): odhcp6c[9270]: Got a valid ADVERTISE after 3348ms
Tue Dec 22 21:14:25 2020 daemon.notice netifd: wan6 (9270): odhcp6c[9270]: IAID 0001 T1 450 T2 720
Tue Dec 22 21:14:25 2020 daemon.info odhcp6c[9270]: 2222:3333:225:7500::/56 preferred 810 valid 900
Tue Dec 22 21:14:25 2020 daemon.notice netifd: wan6 (9270): odhcp6c[9270]: 2222:3333:225:7500::/56 preferred 810 valid 900
Tue Dec 22 21:14:26 2020 daemon.notice odhcp6c[9270]: Starting SOLICIT transaction (timeout 4294967295s, max rc 0)
Tue Dec 22 21:14:26 2020 daemon.notice netifd: wan6 (9270): odhcp6c[9270]: Starting SOLICIT transaction (timeout 4294967295s, max rc 0)
Tue Dec 22 21:14:26 2020 daemon.notice odhcp6c[9270]: Got a valid ADVERTISE after 2ms
Tue Dec 22 21:14:26 2020 daemon.info odhcp6c[9270]: IAID 0001 T1 450 T2 720
Tue Dec 22 21:14:26 2020 daemon.notice netifd: wan6 (9270): odhcp6c[9270]: Got a valid ADVERTISE after 2ms
Tue Dec 22 21:14:26 2020 daemon.info odhcp6c[9270]: 2222:3333:225:7500::/56 preferred 810 valid 900
Tue Dec 22 21:14:26 2020 daemon.notice netifd: wan6 (9270): odhcp6c[9270]: IAID 0001 T1 450 T2 720
Tue Dec 22 21:14:26 2020 daemon.notice netifd: wan6 (9270): odhcp6c[9270]: 2222:3333:225:7500::/56 preferred 810 valid 900
Tue Dec 22 21:14:27 2020 daemon.notice odhcp6c[9270]: Starting REQUEST transaction (timeout 4294967295s, max rc 10)
Tue Dec 22 21:14:27 2020 daemon.notice odhcp6c[9270]: Send REQUEST message (elapsed 0ms, rc 0)
Tue Dec 22 21:14:27 2020 daemon.notice netifd: wan6 (9270): odhcp6c[9270]: Starting REQUEST transaction (timeout 4294967295s, max rc 10)
Tue Dec 22 21:14:27 2020 daemon.notice netifd: wan6 (9270): odhcp6c[9270]: Send REQUEST message (elapsed 0ms, rc 0)
Tue Dec 22 21:14:28 2020 daemon.notice odhcp6c[9270]: Send REQUEST message (elapsed 1072ms, rc 1)
Tue Dec 22 21:14:28 2020 daemon.notice netifd: wan6 (9270): odhcp6c[9270]: Send REQUEST message (elapsed 1072ms, rc 1)
Tue Dec 22 21:14:31 2020 daemon.notice odhcp6c[9270]: Send REQUEST message (elapsed 3504ms, rc 2)
Tue Dec 22 21:14:31 2020 daemon.notice netifd: wan6 (9270): odhcp6c[9270]: Send REQUEST message (elapsed 3504ms, rc 2)
Tue Dec 22 21:14:35 2020 daemon.notice odhcp6c[9270]: Send REQUEST message (elapsed 8112ms, rc 3)
Tue Dec 22 21:14:35 2020 daemon.notice netifd: wan6 (9270): odhcp6c[9270]: Send REQUEST message (elapsed 8112ms, rc 3)
Tue Dec 22 21:14:45 2020 daemon.notice odhcp6c[9270]: Send REQUEST message (elapsed 17584ms, rc 4)
Tue Dec 22 21:14:45 2020 daemon.notice netifd: wan6 (9270): odhcp6c[9270]: Send REQUEST message (elapsed 17584ms, rc 4)
Tue Dec 22 21:15:05 2020 daemon.notice odhcp6c[9270]: Send REQUEST message (elapsed 37296ms, rc 5)

TCPDUMP keeps repeating.

21:16:37.317255 Out ethertype IPv6 (0x86dd), length 193: (flowlabel 0x7b102, hlim 1, next-header UDP (17) payload length: 137) fe80::1454:125a:23bc:995d.546 > ff02::1:2.547: [udp sum ok] dhcp6 request (xid=18012d (elapsed-time 12945) (option-request SIP-servers-domain SIP-servers-address DNS-server DNS-search-list SNTP-servers NTP-server AFTR-Name opt_67 opt_94 opt_95 opt_96) (client-ID hwaddr type 1 001e101f0000) (server-ID hwaddr type 1 6c3b6bee0d46) (reconfigure-accept) (Client-FQDN) (IA_PD IAID:1 T1:0 T2:0 (IA_PD-prefix 2222:3333:225:7500::/56 pltime:810 vltime:900)))
21:16:37.321214  In ethertype IPv6 (0x86dd), length 177: (hlim 64, next-header UDP (17) payload length: 121) fe80::10c.547 > fe80::1454:125a:23bc:995d.546: [udp sum ok] dhcp6 reply (xid=18012d (client-ID hwaddr type 1 001e101f0000) (server-ID hwaddr type 1 6c3b6bee0d46) (DNS-server 2001:4860:4860::8888 2001:4860:4860::8844) (IA_PD IAID:1 T1:450 T2:720 (IA_PD-prefix 2222:3333:225:7500::/56 pltime:810 vltime:900)))

1 Like

Check the output when the issue happens:

ifstatus wan6

And check right after reboot when it works.

Also check if the issue persists with the firewall stopped.

2 Likes

Stopping firewall didn't change anything.
When it works it has the section

        "updated": [
                "addresses",
                "routes",
                "prefixes",
                "data"
        ],

the ipv6-prefix section, an additional route for the /56 prefix, and the passthrough data at the bottom. Do you need me to post them here?

1 Like

So, do these sections disappear later, or they are still present but effectively non-functional?
I.e. is there any difference between the working and not working output?

Does it work if you manually perform the following when the issue happens:

/etc/init.d/network restart
ifup wan6
killall -SIGUSR2 odhcp6c
killall -SIGUSR1 odhcp6c
2 Likes

this is a strace from an RA rcv to a ubus notify proto... ( UPDATE )

you might see something different or nothing at all from a similar command... ( best run after boot and prior to the first RA UPDATE )

note: very messy to sanitize... but curious if any signals at all hit odhcp6c after the update arrives...

[root@dca632 /usbstick 46°]# strace -f -s 10000 -p $(pidof odhcp6c) 2>&1 | grep -A20 RT_1


[pid 23451] rt_sigprocmask(SIG_UNBLOCK, [RT_1 RT_2], NULL, 8) = 0
[pid 23451] rt_sigaction(SIGCHLD, {sa_handler=0x438d3c, sa_mask=~[RTMIN RT_1 RT_2], sa_flags=SA_RESTORER, sa_restorer=0x7f9cb82d18}, NULL, 8) = 0
[pid 23451] rt_sigaction(SIGHUP, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7f9cb82d18}, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
[pid 23451] getppid()                   = 13803
[pid 23451] uname({sysname="Linux", nodename="rpi-dca6325631", ...}) = 0

[pid 23451] getcwd("/lib/netifd/proto", 4096) = 18
[pid 23451] openat(AT_FDCWD, "/lib/netifd/dhcpv6.script", O_RDONLY|O_LARGEFILE|O_CLOEXEC) = 3

[pid 23451] fcntl(3, F_SETFD, FD_CLOEXEC) = 0
[pid 23451] fcntl(3, F_DUPFD_CLOEXEC, 10) = 10
[pid 23451] fcntl(10, F_SETFD, FD_CLOEXEC) = 0
[pid 23451] close(3)                    = 0
[pid 23451] rt_sigaction(SIGINT, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
[pid 23451] rt_sigaction(SIGINT, {sa_handler=0x438d3c, sa_mask=~[RTMIN RT_1 RT_2], sa_flags=SA_RESTORER, sa_restorer=0x7f9cb82d18}, NULL, 8) = 0
[pid 23451] rt_sigaction(SIGQUIT, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
[pid 23451] rt_sigaction(SIGQUIT, {sa_handler=SIG_IGN, sa_mask=~[RTMIN RT_1 RT_2], sa_flags=SA_RESTORER, sa_restorer=0x7f9cb82d18}, NULL, 8) = 0
[pid 23451] rt_sigaction(SIGTERM, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0

[pid 23451] read(10, "#!/bin/sh\n[ -z \"$2\" ] && echo \"Error: should be run by odhcpc6c\" && exit 1\n. /lib/functions.sh\n. /lib/netifd/netifd-proto.sh\n\nsetup_interface () {\n\tlocal device=\"$1\"\n\tlocal prefsig=\"\"\n\tlocal addrsig=\"\"\n\n\t# Apply IPv6 / ND configuration\n\tHOPLIMIT=$(cat /proc/sys/net/ipv6/conf/$device/hop_limit)\n\t[ -n \"$RA_HOPLIMIT\" -a -n \"$HOPLIMIT\" ] && [ \"$RA_HOPLIMIT\" -gt \"$HOPLIMIT\" ] && echo \"$RA_HOPLIMIT\" > /proc/sys/net/ipv6/conf/$device/hop_limit\n\t[ -n \"$RA_MTU\" ] && [ \"$RA_MTU\" -ge 1280 ] && echo \"$RA_MTU\" > /proc/", 511) = 511

[pid 23451] wait4(-1, 0x7fd33d291c, WNOHANG, NULL) = -1 ECHILD (No child process)
[pid 23451] wait4(-1, 0x7fd33d29dc, WNOHANG, NULL) = -1 ECHILD (No child process)
[pid 23451] openat(AT_FDCWD, "/lib/functions.sh", O_RDONLY|O_LARGEFILE|O_CLOEXEC) = 3
[pid 23451] fcntl(3, F_SETFD, FD_CLOEXEC) = 0
[pid 23451] fcntl(3, F_DUPFD_CLOEXEC, 10) = 14
[pid 23451] fcntl(14, F_SETFD, FD_CLOEXEC) = 0
[pid 23451] close(3)                    = 0

[pid 23451] read(14, "#!/bin/sh\n# Copyright (C) 2006-2014 OpenWrt.org\n# Copyright (C) 2006 Fokus Fraunhofer <carsten.tittel@fokus.fraunhofer.de>\n# Copyright (C) 2010 Vertical Communications\n\n\ndebug () {\n\t${DEBUG:-:} \"$@\"\n}\n\n# newline\nN=\"\n\"\n\n_C=0\nNO_EXPORT=1\nLOAD_STATE=1\nLIST_SEP=\" \"\n\n# xor multiple hex values of the same length\nxor() {\n\tlocal val\n\tlocal ret=\"0x$1\"\n\tlocal retlen=${#1}\n\n\tshift\n\twhile [ -n \"$1\" ]; do\n\t\tval=\"0x$1\"\n\t\tret=$((ret ^ val))\n\t\tshift\n\tdone\n\n\tprintf \"%0${retlen}x\" \"$ret\"\n}\n\nappend() {\n\tlocal var=\"$1\"\n\tlocal", 511) = 511


[pid 23451] wait4(-1, 0x7fd33d25cc, WNOHANG, NULL) = -1 ECHILD (No child process)

[pid 23451] read(14, " value=\"$2\"\n\tlocal sep=\"${3:- }\"\n\n\teval \"export ${NO_EXPORT:+-n} -- \\\"$var=\\${$var:+\\${$var}\\${value:+\\$sep}}\\$value\\\"\"\n}\n\nlist_contains() {\n\tlocal var=\"$1\"\n\tlocal str=\"$2\"\n\tlocal val\n\n\teval \"val=\\\" \\${$var} \\\"\"\n\t[ \"${val%% $str *}\" != \"$val\" ]\n}\n\nconfig_load() {\n\t[ -n \"$IPKG_INSTROOT\" ] && return 0\n\tuci_load \"$@\"\n}\n\nreset_cb() {\n\tconfig_cb() { return 0; }\n\toption_cb() { return 0; }\n\tlist_cb() { return 0; }\n}\nreset_cb\n\npackage() {\n\treturn 0\n}\n\nconfig () {\n\tlocal cfgtype=\"$1\"\n\tlocal name=\"$2\"\n\n\texport ${NO_", 511) = 511
[pid 23451] brk(NULL)                   = 0x1f014000
[pid 23451] brk(0x1f015000)             = 0x1f015000
[pid 23451] wait4(-1, 0x7fd33d25cc, WNOHANG, NULL) = -1 ECHILD (No child process)
[pid 23451] read(14, "EXPORT:+-n} CONFIG_NUM_SECTIONS=$((CONFIG_NUM_SECTIONS + 1))\n\tname=\"${name:-cfg$CONFIG_NUM_SECTIONS}\"\n\tappend CONFIG_SECTIONS \"$name\"\n\texport ${NO_EXPORT:+-n} CONFIG_SECTION=\"$name\"\n\tconfig_set \"$CONFIG_SECTION\" \"TYPE\" \"${cfgtype}\"\n\t[ -n \"$NO_CALLBACK\" ] || config_cb \"$cfgtype\" \"$name\"\n}\n\noption () {\n\tlocal varname=\"$1\"; shift\n\tlocal value=\"$*\"\n\n\tconfig_set \"$CONFIG_SECTION\" \"${varname}\" \"${value}\"\n\t[ -n \"$NO_CALLBACK\" ] || option_cb \"$varname\" \"$*\"\n}\n\nlist() {\n\tlocal varname=\"$1\"; shift\n\tlocal value=\"$*\"\n", 511) = 511
--
[pid 23453] rt_sigaction(SIGQUIT, {sa_handler=SIG_DFL, sa_mask=~[RTMIN RT_1 RT_2], sa_flags=SA_RESTORER, sa_restorer=0x7f9cb82d18}, NULL, 8) = 0
[pid 23453] close(3)                    = 0
[pid 23453] dup3(4, 1, 0)               = 1
[pid 23453] close(4)                    = 0


[pid 23453] newfstatat(AT_FDCWD, "/bin/cat", {st_mode=S_IFREG|0755, st_size=413729, ...}, 0) = 0

[pid 23453] execve("/bin/cat", ["cat", "/proc/sys/net/ipv6/conf/eth1/hop_limit"], 0x1f031830 /* 31 vars */) = 0

[pid 23453] set_tid_address(0x7f9c24c0cc) = 23453

[pid 23453] openat(AT_FDCWD, "/etc/ld-musl-aarch64.path", O_RDONLY|O_LARGEFILE|O_CLOEXEC) = -1 ENOENT (No such file or directory)
[pid 23453] openat(AT_FDCWD, "/lib/libgcc_s.so.1", O_RDONLY|O_LARGEFILE|O_CLOEXEC) = 3
[pid 23453] fcntl(3, F_SETFD, FD_CLOEXEC) = 0
[pid 23453] fstat(3, {st_mode=S_IFREG|0644, st_size=73744, ...}) = 0

[pid 23453] read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0\267\0\1\0\0\0p-\0\0\0\0\ LOTSOFELFHERE

[pid 23453] mmap(NULL, 143360, PROT_READ|PROT_EXEC, MAP_PRIVATE, 3, 0) = 0x7f9c198000
[pid 23453] mmap(0x7f9c1b9000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED, 3, 0x11000) = 0x7f9c1b9000
[pid 23453] close(3)                    = 0
[pid 23453] mprotect(0x7f9c1b9000, 4096, PROT_READ) = 0
[pid 23453] mprotect(0x474000, 4096, PROT_READ) = 0
[pid 23453] prctl(PR_SET_NAME, "cat")   = 0
--
[pid 23454] rt_sigaction(SIGQUIT, {sa_handler=SIG_DFL, sa_mask=~[RTMIN RT_1 RT_2], sa_flags=SA_RESTORER, sa_restorer=0x7f9cb82d18}, NULL, 8) = 0
[pid 23454] close(3)                    = 0
[pid 23454] dup3(4, 1, 0)               = 1
[pid 23454] close(4)                    = 0
[pid 23454] wait4(-1, 0x7fd33d199c, WNOHANG, NULL) = -1 ECHILD (No child process)
[pid 23454] newfstatat(AT_FDCWD, "/usr/sbin/jshn", 0x7fd33d1598, 0) = -1 ENOENT (No such file or directory)
[pid 23454] newfstatat(AT_FDCWD, "/usr/bin/jshn", {st_mode=S_IFREG|0755, st_size=12299, ...}, 0) = 0
[pid 23454] rt_sigprocmask(SIG_BLOCK, ~[], [], 8) = 0
[pid 23454] clone(child_stack=NULL, flags=SIGCHLDstrace: Process 23455 attached
 <unfinished ...>
[pid 23455] gettid( <unfinished ...>
[pid 23454] <... clone resumed>)        = 23455
[pid 23455] <... gettid resumed>)       = 23455
[pid 23454] rt_sigprocmask(SIG_SETMASK, [],  <unfinished ...>
[pid 23455] rt_sigprocmask(SIG_SETMASK, [],  <unfinished ...>
[pid 23454] <... rt_sigprocmask resumed>NULL, 8) = 0
[pid 23455] <... rt_sigprocmask resumed>NULL, 8) = 0
[pid 23454] wait4(-1,  <unfinished ...>
[pid 23455] execve("/usr/bin/jshn", ["jshn", "-w"], 0x1f03fc08 /* 112 vars */) = 0
[pid 23455] set_tid_address(0x7fa06f50cc) = 23455
[pid 23455] openat(AT_FDCWD, "/etc/ld-musl-aarch64.path", O_RDONLY|O_LARGEFILE|O_CLOEXEC) = -1 ENOENT (No such file or directory)
--
[pid 23456] rt_sigaction(SIGQUIT, {sa_handler=SIG_DFL, sa_mask=~[RTMIN RT_1 RT_2], sa_flags=SA_RESTORER, sa_restorer=0x7f9cb82d18}, NULL, 8) = 0
[pid 23456] execve("/bin/ubus", ["ubus", "call", "network.interface", "notify_proto", "{ \"action\": 0, \"link-up\": true, \"data\": { \"passthru\": \"100050000000000000242\" }, \
"keep\": false, \"ip6addr\": [ { \"ipaddr\": \"2403\", \"mask\": \"128\", \
"preferred\": 2847, \"valid\": 3847, \"offlink\": true } ], \
"routes6\": [ { \"target\": \"::\", \"netmask\": \"0\", \
"gateway\": \"fe80\", \"metric\": 384, \"valid\": 1799, \
"source\": \"2403" }, { \"target\": \"::\", \"netmask\": \"0\", \
"gateway\": \"fe80\", \"metric\": 384, \"valid\": 1799, \
"source\": \"2403\" } ], \"ip6prefix\": [ \"2403\" ], \
"dns\": [ \"2403", \"2403\" ], \"interface\": \"wan6\" }"], 0x1f040028 /* 112 vars */) = 0

( further down there was something about 'target' empty in the proto handler but that could normal... who knows... )

I restarted the wan6, now it is not working again. I got:

"updated": [
		"addresses",
		"routes"
	],

it is missing the prefixes and data, the whole ipv6-prefix section is empty, the route for the /56 delegated prefix, and the passthrough data.

Made it work!

Didn't work.

Not sure if it is somehow connected, but after I run the ifup wan6 there are 2 odhcp6c instances running and after some time one of them dies.

root@magiatiko / > ps wwww | grep odhcp6c
  989 root       972 S    odhcp6c -s /lib/netifd/dhcpv6.script -Ntry -P0 -c00030001001e101f0000 -e -v -t120 pppoe-wan
root@magiatiko / > ifup wan6
root@magiatiko / > ps wwww | grep odhcp6c
 7467 root       972 S    odhcp6c -s /lib/netifd/dhcpv6.script -Ntry -P0 -c00030001001e101f0000 -e -v -t120 pppoe-wan
 7542 root       972 S    odhcp6c -s /lib/netifd/dhcpv6.script -Ntry -P0 -c00030001001e101f0000 -e -v -t120 pppoe-wan
[...]
root@magiatiko / > ps wwww | grep odhcp6c
 7467 root       972 S    odhcp6c -s /lib/netifd/dhcpv6.script -Ntry -P0 -c00030001001e101f0000 -e -v -t120 pppoe-wan

@anon50098793 I'll try to run this strace immediately after reboot. I tried to run it after ifup but it immediately terminated.

2 Likes

must have latched onto the second ( quickly terminated ) instance... ( or pidof has issues with two PIDs returned )

also run worth testing with less options in /etc/config/network...
i.e.;

config interface 'wan6'
	option ifname 'eth1'
	option proto 'dhcpv6'
	option reqaddress 'try'
	option reqprefix '56'

or just plain;

config interface 'wan6'
	option ifname 'eth1'
	option proto 'dhcpv6'

if it's possible in your environment ( can safely run without the options you have )

what I find unusual about this is that lots of people are not having issues also? so... build, ppp, mac setting, additional package-proto conflicts all rise to the top of the list...

'modem/isp' specific quirks go lower on the list just due to user skill level ( and what we have seen and discussed this far is not really pointing in that direction specifically )...

2 Likes

This is probably related to DHCPv6 release/renew.

Good, you can try to debug the network init script to find out what exactly triggers the restart action that makes it work again.

1 Like

I tried with a bare minimum:

network.wan6=interface
network.wan6.proto='dhcpv6'
network.wan6.ifname='@wan'
network.wan6.metric='20'

After sending 7 solicits and getting 7 advertisements, eventually it sent a request, got the reply and concluded the negotiation.
What troubles me are the logs:

Wed Dec 23 14:55:54 2020 daemon.notice netifd: wan6 (8621): odhcp6c[8621]: (re)starting transaction on pppoe-wan
Wed Dec 23 14:55:55 2020 daemon.notice odhcp6c[8621]: Starting SOLICIT transaction (timeout 4294967295s, max rc 0)
Wed Dec 23 14:55:55 2020 daemon.notice netifd: wan6 (8621): odhcp6c[8621]: Starting SOLICIT transaction (timeout 4294967295s, max rc 0)
...
Wed Dec 23 14:56:32 2020 daemon.notice odhcp6c[8621]: Got a valid ADVERTISE after 36608ms
Wed Dec 23 14:56:32 2020 daemon.info odhcp6c[8621]: IAID 0001 T1 450 T2 720
Wed Dec 23 14:56:32 2020 daemon.notice netifd: wan6 (8621): odhcp6c[8621]: Got a valid ADVERTISE after 36608ms

It only detected the seventh advertisement.
The same occurs now with renew.

Wed Dec 23 15:04:04 2020 daemon.notice odhcp6c[8621]: Starting RENEW transaction (timeout 270s, max rc 0)
Wed Dec 23 15:04:04 2020 daemon.notice odhcp6c[8621]: Send RENEW message (elapsed 0ms, rc 0)
Wed Dec 23 15:04:04 2020 daemon.notice netifd: wan6 (8621): odhcp6c[8621]: Starting RENEW transaction (timeout 270s, max rc 0)
Wed Dec 23 15:04:04 2020 daemon.notice netifd: wan6 (8621): odhcp6c[8621]: Send RENEW message (elapsed 0ms, rc 0)
Wed Dec 23 15:04:15 2020 daemon.notice odhcp6c[8621]: Send RENEW message (elapsed 10496ms, rc 1)
Wed Dec 23 15:04:15 2020 daemon.notice netifd: wan6 (8621): odhcp6c[8621]: Send RENEW message (elapsed 10496ms, rc 1)
Wed Dec 23 15:04:37 2020 daemon.notice odhcp6c[8621]: Send RENEW message (elapsed 32768ms, rc 2)
Wed Dec 23 15:04:37 2020 daemon.notice netifd: wan6 (8621): odhcp6c[8621]: Send RENEW message (elapsed 32768ms, rc 2)
Wed Dec 23 15:05:22 2020 daemon.notice odhcp6c[8621]: Send RENEW message (elapsed 77824ms, rc 3)
Wed Dec 23 15:05:22 2020 daemon.notice netifd: wan6 (8621): odhcp6c[8621]: Send RENEW message (elapsed 77824ms, rc 3)

I can see the renew-reply in tcpdump, but odhcp6c doesn't seem to get it in the logs.
After some time it starts sending rebinds, I can see the reply in tcpdump, but again they are ignored.
Eventually the lease times out and starts solicits again.

Also the strace, if you can spot anything unusual in there.

I guess this is the next step in case the strace or the recent findings don't reveal anything.

1 Like

worth trying this i suppose... ( pastebin be broken ) pm it if you like...

renice -n -1 -p $(pidof odhcp6c)

and another thing, can you uninstall bash too... ( just want to exclude something for a few more tests onwards )...

1 Like

bash removed (wasn't using it anyway) and odhcp6c reniced, unfortunately that didn't help.

1 Like

a log ( tcpdump ) from when it was working / month or so ago... would be interesting to see if anything has changed...

edit not so relavent

NOTE: my ipv6 knowledge is limited so some of what I say could be normal / no problem...

some general observations;

  • the RA(isp-server) and dhcp server addresses are different...
  • the second route entry in the ubus call from strace may be odd...; no source... ( +no pd )...

i wonder if your isp made the dhcp server separate recently or something like that...

from your descriptions of the symptoms... initial SOLICIT generally works... it seems to be the 'switching to statefull mode'... where something goes weird...

i believe odhcp6c not 'seeing' responses is an 'after effect' of this 'weird' state being triggered... and not the cause of it... prior to the weird-state... odhcp6c-logread output looks good... but I dont see these options in the ubus call from strace ( perhaps the trace was just from a failed-state capture session )...

  • would be good if you also monitor ubus in another terminal... and get all the calls from initial success onwards... then compare with

  • what is sent in tcp dump... pay attention to the routes and sending server addresses

ubus monitor | grep notify_proto | grep ip6addr

in other words... i think the issue within the proto state tables... or something in the (pre?)renew/advertise proto formatting goes whacky...

we might be able to track down 'why'... ( inspection of raw options sent )

but tracking down how is likely a low level developer task... ( inspection of handling those options )...

No such luck unfortunately. However the same issue was part of a misconfiguration of mtu, but was supposed to be solved after the mtu was correct.

No, they always had it like this. In general they are very helpful and since it is a small village provider they were quite happy to test ipv6 connectivity with me as the first client.

That is partially correct. The RPi will eventually get the advertise, but after a lot of delay and many unread responses.

Wed Dec 23 21:03:17 2020 daemon.notice odhcp6c[15600]: Starting SOLICIT transaction (timeout 4294967295s, max rc 0)
Wed Dec 23 21:03:17 2020 daemon.notice netifd: wan6 (15600): odhcp6c[15600]: Starting SOLICIT transaction (timeout 4294967295s, max rc 0)
Wed Dec 23 21:03:33 2020 daemon.notice odhcp6c[15600]: Got a valid ADVERTISE after 15253ms

During my tests yesterday I had one time that everything worked fine, but didn't stay like this.

Wed Dec 23 21:01:38 2020 daemon.notice odhcp6c[4812]: Starting SOLICIT transaction (timeout 4294967295s, max rc 0)
Wed Dec 23 21:01:38 2020 daemon.notice netifd: wan6 (4812): odhcp6c[4812]: Starting SOLICIT transaction (timeout 4294967295s, max rc 0)
Wed Dec 23 21:01:38 2020 daemon.notice odhcp6c[4812]: Got a valid ADVERTISE after 2ms
Wed Dec 23 21:01:38 2020 daemon.info odhcp6c[4812]: IAID 0001 T1 450 T2 720
Wed Dec 23 21:01:38 2020 daemon.notice netifd: wan6 (4812): odhcp6c[4812]: Got a valid ADVERTISE after 2ms
Wed Dec 23 21:01:38 2020 daemon.info odhcp6c[4812]: 2222:3333:225:7500::/56 preferred 810 valid 900
Wed Dec 23 21:01:38 2020 daemon.notice netifd: wan6 (4812): odhcp6c[4812]: IAID 0001 T1 450 T2 720
Wed Dec 23 21:01:38 2020 daemon.notice netifd: wan6 (4812): odhcp6c[4812]: 2222:3333:225:7500::/56 preferred 810 valid 900
Wed Dec 23 21:01:39 2020 daemon.notice odhcp6c[4812]: Starting REQUEST transaction (timeout 4294967295s, max rc 10)
Wed Dec 23 21:01:39 2020 daemon.notice odhcp6c[4812]: Send REQUEST message (elapsed 0ms, rc 0)
Wed Dec 23 21:01:39 2020 daemon.notice netifd: wan6 (4812): odhcp6c[4812]: Starting REQUEST transaction (timeout 4294967295s, max rc 10)
Wed Dec 23 21:01:39 2020 daemon.notice netifd: wan6 (4812): odhcp6c[4812]: Send REQUEST message (elapsed 0ms, rc 0)
Wed Dec 23 21:01:39 2020 daemon.notice odhcp6c[4812]: Got a valid REPLY after 3ms
Wed Dec 23 21:01:39 2020 daemon.info odhcp6c[4812]: IAID 0001 T1 450 T2 720
Wed Dec 23 21:01:39 2020 daemon.notice netifd: wan6 (4812): odhcp6c[4812]: Got a valid REPLY after 3ms
Wed Dec 23 21:01:39 2020 daemon.info odhcp6c[4812]: 2222:3333:225:7500::/56 preferred 810 valid 900
Wed Dec 23 21:01:39 2020 daemon.notice netifd: wan6 (4812): odhcp6c[4812]: IAID 0001 T1 450 T2 720
Wed Dec 23 21:01:39 2020 daemon.info odhcp6c[4812]: T1 450s, T2 720s, T3 900s
Wed Dec 23 21:01:39 2020 daemon.notice netifd: wan6 (4812): odhcp6c[4812]: 2222:3333:225:7500::/56 preferred 810 valid 900
Wed Dec 23 21:01:39 2020 daemon.notice netifd: wan6 (4812): odhcp6c[4812]: T1 450s, T2 720s, T3 900s
Wed Dec 23 21:01:39 2020 daemon.notice odhcp6c[4812]: entering stateful-mode on pppoe-wan
Wed Dec 23 21:01:39 2020 daemon.notice odhcp6c[4812]: Starting <POLL> transaction (timeout 450s, max rc 0)
Wed Dec 23 21:01:39 2020 daemon.notice netifd: wan6 (4812): odhcp6c[4812]: entering stateful-mode on pppoe-wan
Wed Dec 23 21:01:39 2020 daemon.notice netifd: wan6 (4812): odhcp6c[4812]: Starting <POLL> transaction (timeout 450s, max rc 0)

I tried once again. For more than 20 minutes they are exchanging solicit-advertise.

root@magiatiko / > tcpdump -i pppoe-wan -evn udp port 547
tcpdump: listening on pppoe-wan, link-type LINUX_SLL (Linux cooked v1), capture size 262144 bytes

13:28:18.817648 Out ethertype IPv6 (0x86dd), length 168: (flowlabel 0x72d87, hlim 1, next-header UDP (17) payload length: 112) fe80::d832:bada:97ad:e74b.546 > ff02::1:2.547: [udp sum ok] dhcp6 solicit (xid=70612e (elapsed-time 0) (option-request SIP-servers-domain SIP-servers-address DNS-server DNS-search-list SNTP-servers NTP-server AFTR-Name opt_67 opt_94 opt_95 opt_96 opt_82) (client-ID hwaddr type 1 001e101f0000) (reconfigure-accept) (Client-FQDN) (IA_NA IAID:1 T1:0 T2:0) (IA_PD IAID:1 T1:0 T2:0))
13:28:18.821227  In ethertype IPv6 (0x86dd), length 182: (hlim 64, next-header UDP (17) payload length: 126) fe80::10c.547 > fe80::d832:bada:97ad:e74b.546: [udp sum ok] dhcp6 advertise (xid=70612e (client-ID hwaddr type 1 001e101f0000) (server-ID hwaddr type 1 6c3b6bee0d46) (preference 255) (DNS-server 2001:4860:4860::8888 2001:4860:4860::8844) (IA_PD IAID:1 T1:450 T2:720 (IA_PD-prefix 2222:3333:225:7500::/56 pltime:810 vltime:900)))
...
13:50:09.867416 Out ethertype IPv6 (0x86dd), length 168: (flowlabel 0x72d87, hlim 1, next-header UDP (17) payload length: 112) fe80::d832:bada:97ad:e74b.546 > ff02::1:2.547: [udp sum ok] dhcp6 solicit (xid=70612e (elapsed-time 65535) (option-request SIP-servers-domain SIP-servers-address DNS-server DNS-search-list SNTP-servers NTP-server AFTR-Name opt_67 opt_94 opt_95 opt_96 opt_82) (client-ID hwaddr type 1 001e101f0000) (reconfigure-accept) (Client-FQDN) (IA_NA IAID:1 T1:0 T2:0) (IA_PD IAID:1 T1:0 T2:0))
13:50:09.870379  In ethertype IPv6 (0x86dd), length 182: (hlim 64, next-header UDP (17) payload length: 126) fe80::10c.547 > fe80::d832:bada:97ad:e74b.546: [udp sum ok] dhcp6 advertise (xid=70612e (client-ID hwaddr type 1 001e101f0000) (server-ID hwaddr type 1 6c3b6bee0d46) (preference 255) (DNS-server 2001:4860:4860::8888 2001:4860:4860::8844) (IA_PD IAID:1 T1:450 T2:720 (IA_PD-prefix 2222:3333:225:7500::/56 pltime:810 vltime:900)))

In the logs odhcp6c has not detected any response:

Thu Dec 24 13:28:18 2020 daemon.notice odhcp6c[5506]: (re)starting transaction on pppoe-wan
Thu Dec 24 13:28:18 2020 daemon.notice netifd: wan6 (5506): odhcp6c[5506]: (re)starting transaction on pppoe-wan
Thu Dec 24 13:28:18 2020 daemon.notice odhcp6c[5506]: Starting SOLICIT transaction (timeout 4294967295s, max rc 0)
Thu Dec 24 13:28:18 2020 daemon.notice netifd: wan6 (5506): odhcp6c[5506]: Starting SOLICIT transaction (timeout 4294967295s, max rc 0)

root@magiatiko / > date
Thu Dec 24 13:52:47 CET 2020

Regarding ubus, I managed to capture both scenarios. The working one:

<- 9569fa05 #43084bd1         invoke: {"objid":1124617169,"method":"notify_proto","data":{"action":0,"link-up":true,"data":{"passthru":"001700202001486048600000000000000000888820014860486000000000000000008844"},"keep":false,"ip6addr":[{"ipaddr":"2222:3333:227:75d3:d832:bada:97ad:e74b","mask":"64","preferred":604796,"valid":2591996,"offlink":true}],"routes6":[{"target":"::","netmask":"0","gateway":"fe80::10c","metric":512,"valid":1796,"source":"2222:3333:225:7500::/56"},{"target":"::","netmask":"0","gateway":"fe80::10c","metric":512,"valid":1796,"source":"2222:3333:227:75d3:d832:bada:97ad:e74b/64"},{"target":"2222:3333:227:75d3::","netmask":"64","metric":256,"valid":2591996}],"ip6prefix":["2222:3333:225:7500::/56,810,900"],"dns":["2001:4860:4860::8888","2001:4860:4860::8844"],"interface":"wan6"}}
-> 9d8725df #9569fa05         invoke: {"objid":1124617169,"method":"notify_proto","data":{"action":0,"link-up":true,"data":{"passthru":"001700202001486048600000000000000000888820014860486000000000000000008844"},"keep":false,"ip6addr":[{"ipaddr":"2222:3333:227:75d3:d832:bada:97ad:e74b","mask":"64","preferred":604796,"valid":2591996,"offlink":true}],"routes6":[{"target":"::","netmask":"0","gateway":"fe80::10c","metric":512,"valid":1796,"source":"2222:3333:225:7500::/56"},{"target":"::","netmask":"0","gateway":"fe80::10c","metric":512,"valid":1796,"source":"2222:3333:227:75d3:d832:bada:97ad:e74b/64"},{"target":"2222:3333:227:75d3::","netmask":"64","metric":256,"valid":2591996}],"ip6prefix":["2222:3333:225:7500::/56,810,900"],"dns":["2001:4860:4860::8888","2001:4860:4860::8844"],"interface":"wan6"},"user":"root","group":"root"}

and the failed one:

<- c2ea4cec #43084bd1         invoke: {"objid":1124617169,"method":"notify_proto","data":{"action":0,"link-up":true,"data":{},"keep":false,"ip6addr":[{"ipaddr":"2222:3333:227:75d3:d832:bada:97ad:e74b","mask":"64","preferred":604790,"valid":2591990,"offlink":true}],"routes6":[{"target":"::","netmask":"0","gateway":"fe80::10c","metric":512,"valid":1790,"source":"2222:3333:227:75d3:d832:bada:97ad:e74b/64"},{"target":"2222:3333:227:75d3::","netmask":"64","metric":256,"valid":2591990}],"dns":["2001:4860:4860::8844","2001:4860:4860::8888"],"interface":"wan6"}}
-> 9d8725df #c2ea4cec         invoke: {"objid":1124617169,"method":"notify_proto","data":{"action":0,"link-up":true,"data":{},"keep":false,"ip6addr":[{"ipaddr":"2222:3333:227:75d3:d832:bada:97ad:e74b","mask":"64","preferred":604790,"valid":2591990,"offlink":true}],"routes6":[{"target":"::","netmask":"0","gateway":"fe80::10c","metric":512,"valid":1790,"source":"2222:3333:227:75d3:d832:bada:97ad:e74b/64"},{"target":"2222:3333:227:75d3::","netmask":"64","metric":256,"valid":2591990}],"dns":["2001:4860:4860::8844","2001:4860:4860::8888"],"interface":"wan6"},"user":"root","group":"root"}

I hope it can provide some insight what is going on.

1 Like

odd indeed...

i'm thinking we should try dropping in an older binary... then if the issue is still present... we know it's config / ppp / install specific...

https://github.com/wulfy23/rpi4-opkg/blob/master/odhcp6c-previous/odhcp6c_2020-03-28-f575351c-16_aarch64_cortex-a72.ipk?raw=true

I think I found the culprit. I started disabling services, like sqm, mwan3, modemmanager, removed the LTE dongle and after I disabled banIP I have a couple of successful ifup wan6
What puzzles me is why didn't it have any effect after I stopped the firewall with fw3 stop
Maybe @dibdot can help us understand?

2 Likes

I think the correct syntax is /etc/init.d/firewall stop or fw3 flush to flush all existing firewall rules/chains (incl. the conntrack table).

2 Likes