dhcpcd-discuss

On Mon, 20 Nov 2017 14:29:00 +0000
Roy Marples <roy@xxxxxxxxxxxx> wrote:

> Hi Neal
> 
> On 14/11/2017 20:34, Neal P. Murphy wrote:
> > OK, now using HEAD (well, three commits shy of HEAD).
> > 
> > First run, I saw individual DELEGATED6 calls for eth0 and eth2. Next runs, I see only DELEGATED6 for eth2. Hmmm. Odd. Sometimes I see one for each eth0 and eth2, sometimes only for eth2, sometimes none. And never for eth3, even though it does get a delegated prefix.
> > 
> > HEAD doesn't remove the /64 from eth3, either. But it does remove the /128.
> > 
> > Is there a way to build with 'extra instrumentation' so you can see what dhcpcd's doing?  
> 
> Where you able to get any better logs?
> Ideally add this to the top of /etc/dhcpcd.conf
> 
> debug
> logfile /var/log/dhcpcd.log
> 
> Then /var/log/dhcpcd.log is just dhcpcd debugging, which means it easy 
> for me to see what's going on to try and address this before another 
> release.
> 
> Roy

Did I screw up the kernel config this time? I had to redo the config so the kernel would run on the Atom N270 I have; I may've botched something else in it.

Built rc4 just like rc3, definitely using 3.4.x kernel headers. Built and installed the latest SWE3.1-SP4 build running Linux 3.16.51.

rc4 *and* rc3 both give me the same results: I see router adverts from comcrash, but no attempt to request an address. The problem almost has to be on my end, but darned if I know what. (Unless comcrash are ignoring me now....) Maybe a night's sleep will let me figure out what I done did.

From 'tcpdump -i eth3 ip6', this is what I see:
----
02:19:41.924637 IP6 fe80::201:5cff:fe8e:ea46 > ff02::1: ICMP6, router advertisement, length 144
02:19:45.354697 IP6 fe80::201:5cff:fe8e:ea46 > ff02::1: ICMP6, router advertisement, length 144
02:19:47.155284 IP6 fe80::290:bff:fe17:f27d > ff02::2: ICMP6, router solicitation, length 16
02:19:48.364857 IP6 fe80::201:5cff:fe8e:ea46 > ff02::1: ICMP6, router advertisement, length 144
02:19:52.364772 IP6 fe80::201:5cff:fe8e:ea46 > ff02::1: ICMP6, router advertisement, length 144
----
A little light on comms. :)

And the debug log:
----
Dec 07 01:52:35 [18035]: dhcpcd-7.0.0-rc4 starting
Dec 07 01:52:35 [18035]: eth3: if_disable_autolinklocal: Operation not supported
Dec 07 01:52:35 [18035]: eth0: executing `/etc/rc.d/rc.update6red' PREINIT
Dec 07 01:52:35 [18035]: eth0: executing `/etc/rc.d/rc.update6red' CARRIER
Dec 07 01:52:35 [18035]: eth1: executing `/etc/rc.d/rc.update6red' PREINIT
Dec 07 01:52:35 [18035]: eth1: executing `/etc/rc.d/rc.update6red' NOCARRIER
Dec 07 01:52:35 [18035]: eth2: executing `/etc/rc.d/rc.update6red' PREINIT
Dec 07 01:52:35 [18035]: eth2: executing `/etc/rc.d/rc.update6red' CARRIER
Dec 07 01:52:35 [18035]: eth3: executing `/etc/rc.d/rc.update6red' PREINIT
Dec 07 01:52:35 [18035]: eth3: executing `/etc/rc.d/rc.update6red' CARRIER
Dec 07 01:52:35 [18035]: DUID 00:01:00:01:21:ba:a9:8c:00:90:0b:17:f2:7d
Dec 07 01:52:35 [18035]: eth0: IAID 0b:17:f2:7a
Dec 07 01:52:35 [18035]: eth2: IAID 0b:17:f2:7c
Dec 07 01:52:35 [18035]: eth3: IAID 0b:17:f2:7d
Dec 07 01:52:35 [18035]: eth3: IAID 4b:17:f2:7d
Dec 07 01:52:35 [18035]: eth3: IAID 00:00:00:01
Dec 07 01:52:35 [18035]: eth3: delaying IPv6 router solicitation for 0.2 seconds
Dec 07 01:52:35 [18035]: dhcp6_listen: Address already in use
Dec 07 01:52:35 [18035]: eth1: waiting for carrier
Dec 07 01:52:35 [18035]: eth3: soliciting an IPv6 router
Dec 07 01:52:35 [18035]: eth3: sending Router Solicitation
Dec 07 01:52:38 [18035]: eth3: Router Advertisement from fe80::201:5cff:fe8e:ea46
Dec 07 01:52:38 [18035]: eth3: adding default route via fe80::201:5cff:fe8e:ea46
Dec 07 01:52:38 [18035]: eth3: executing `/etc/rc.d/rc.update6red' ROUTERADVERT
Dec 07 01:52:41 [18035]: eth3: Router Advertisement from fe80::201:5cff:fe8e:ea46
Dec 07 01:52:41 [18035]: eth3: executing `/etc/rc.d/rc.update6red' ROUTERADVERT
Dec 07 01:52:44 [18035]: eth3: Router Advertisement from fe80::201:5cff:fe8e:ea46
Dec 07 01:52:44 [18035]: eth3: executing `/etc/rc.d/rc.update6red' ROUTERADVERT
Dec 07 01:52:48 [18035]: eth3: Router Advertisement from fe80::201:5cff:fe8e:ea46
Dec 07 01:52:48 [18035]: eth3: executing `/etc/rc.d/rc.update6red' ROUTERADVERT
Dec 07 01:52:48 [18035]: received SIGINT, stopping
Dec 07 01:52:48 [18035]: eth1: removing interface
Dec 07 01:52:48 [18035]: eth1: executing `/etc/rc.d/rc.update6red' STOPPED
Dec 07 01:52:48 [18035]: eth2: removing interface
Dec 07 01:52:48 [18035]: eth2: executing `/etc/rc.d/rc.update6red' STOPPED
Dec 07 01:52:48 [18035]: eth0: removing interface
Dec 07 01:52:48 [18035]: eth0: executing `/etc/rc.d/rc.update6red' STOPPED
Dec 07 01:52:48 [18035]: eth3: removing interface
Dec 07 01:52:48 [18035]: eth3: executing `/etc/rc.d/rc.update6red' STOPPED
Dec 07 01:52:49 [18035]: dhcpcd exited
----


Wait, what's that 'address already in use' doing there? Both rc3 and rc4 do that. 'ss -ln' yields:
----
udp    UNCONN     0      0         fe80::290:bff:fe17:f27d%eth3:546    :::*

Oho! "/usr/sbin/dhcpcd -4 ...." opens that socket. Replace that prog with rc3 and....

With the ipv4-only not opening ipv6, I get:
----
dhcpcd-7.0.0-rc4 starting
eth3: if_disable_autolinklocal: Operation not supported
eth0: executing `/etc/rc.d/rc.update6red' PREINIT
eth0: executing `/etc/rc.d/rc.update6red' CARRIER
eth1: executing `/etc/rc.d/rc.update6red' PREINIT
eth1: executing `/etc/rc.d/rc.update6red' NOCARRIER
eth2: executing `/etc/rc.d/rc.update6red' PREINIT
eth2: executing `/etc/rc.d/rc.update6red' CARRIER
eth3: executing `/etc/rc.d/rc.update6red' PREINIT
eth3: executing `/etc/rc.d/rc.update6red' CARRIER
DUID 00:01:00:01:21:ba:a9:8c:00:90:0b:17:f2:7d
eth0: IAID 0b:17:f2:7a
eth2: IAID 0b:17:f2:7c
eth3: IAID 0b:17:f2:7d
eth3: IAID 4b:17:f2:7d
eth3: IAID 00:00:00:01
eth3: delaying IPv6 router solicitation for 1.0 seconds
eth3: reading lease `/var/db/dhcpcd/eth3.lease6'
eth3: soliciting a DHCPv6 lease
eth3: delaying SOLICIT6 (xid 0x664120), next in 0.6 seconds
eth1: waiting for carrier
eth3: broadcasting SOLICIT6 (xid 0x664120), next in 1.1 seconds
eth3: soliciting an IPv6 router
eth3: sending Router Solicitation
eth3: broadcasting SOLICIT6 (xid 0x664120), next in 2.2 seconds
eth3: Router Advertisement from fe80::201:5cff:fe8e:ea46
eth3: adding default route via fe80::201:5cff:fe8e:ea46
eth3: executing `/etc/rc.d/rc.update6red' ROUTERADVERT
eth3: broadcasting SOLICIT6 (xid 0x664120), next in 4.4 seconds
eth3: ADV 2001:558:6036:65:8d7e:3f36:aa01:26cc/128 from fe80::201:5cff:fe8e:ea46
eth3: broadcasting REQUEST6 (xid 0x2545a1), next in 1.1 seconds
eth3: accepted reconfigure key
eth3: REPLY6 received from fe80::201:5cff:fe8e:ea46
eth3: adding address 2001:558:6036:65:8d7e:3f36:aa01:26cc/128
eth3: pltime 3600 seconds, vltime 3600 seconds
eth3: renew in 1800, rebind in 2880, expire in 3600 seconds
lo: adding reject route to 2601:5ca:4400:960::/60
eth3: writing lease `/var/db/dhcpcd/eth3.lease6'
eth3: delegated prefix 2601:5ca:4400:960::/60
eth0: adding address 2601:5ca:4400:962::1/64
eth0: pltime 3600 seconds, vltime 3600 seconds
eth0: waiting for DHCPv6 DAD to complete
eth2: adding address 2601:5ca:4400:964::1/64
eth2: pltime 3600 seconds, vltime 3600 seconds
eth2: waiting for DHCPv6 DAD to complete
eth1: has no carrier, cannot delegate addresses
eth0: adding route to 2601:5ca:4400:962::/64
eth2: adding route to 2601:5ca:4400:964::/64
eth3: waiting for DHCPv6 DAD to complete
eth3: DHCPv6 DAD completed
eth3: executing `/etc/rc.d/rc.update6red' BOUND6
..DHCP6 lease bound (BOUND6) and prefix delegated; update RED6 info
forking to background
forked to background, child pid 21990
----
Looks better.

When I stopped it, dhcpcd left the /64 on eth3 but removed the /128 and removed the /64s on eth0 and eth2. It also left these routes behind:
----
2001:558:6036:65:8d7e:3f36:aa01:26cc dev eth3  proto kernel  metric 256  expires 3347sec
2601:5ca:4400:960::/64 dev eth3  proto kernel  metric 256 
unreachable 2601:5ca:4400:960::/60 dev lo  proto dhcp  metric 201  error -101
----

Beyond the above, the log file only contained a few RAs and the signal/wait messages when I killed it.


Perhaps dhcpcd should croak if it can't open port 546?

Neal