dhcpcd-discuss

On 28/09/17 15:14, Roy Marples wrote:

> Maybe start over with a clean slate.
> 
> I would recommend this course of action:
> 
>  * add `debug` to dhcpcd.conf so it's plenty verbose about what and why
>  * add `logfile /var/log/dhcpcd.log` to dhcpcd.conf incase capturing
>    console output is hard
>  * start dhcpcd. I generally do `dhcpcd -dB` to force debugging and not
>    forking to the background so I can monitor console output
>  * one finished, post either the log file or console output here
>    and state what you think is wrong

Okay, I've got a log attached.  This includes more than dhcpcd's output
because it's what we already have set up.  You can see what attributes
are being passed to the hooks.  You'll also notice that there are
multiple dhcpcd processes running, which is an eccentricity that I don't
think is important because I've tested on a single process for a single
interface.

I can see something at the top I hadn't noticed before:

Sep 28 14:52:27 [5713]: eth1: if_disable_autolinklocal: Operation not
supported

Hmm.

What I think's wrong is that SLAAC addresses are being set with a /64
but DHCPv6 addresses for apparently equivalent subnets are using /128.


I'll leave discussion of the architecture, because it's interesting but
I don't really have anything to add to it.


           Graham

-- 
------------------------------

*Graham Breed*
Systems Developer, ApplianSys

ApplianSys House
Harry Weston Road
Coventry CV3 2UB

www.appliansys.com

*Our sales team sells by referral:*
Less time looking for customers, more time looking after them

ApplianSys Limited registered in England & Wales #: 07608382 at ApplianSys
House, Harry Weston Road, Coventry CV3 2UB

Sep 28 14:52:27 [5713]: dhcpcd-7.0.0-rc2 starting
Sep 28 14:52:27 [5713]: eth1: if_disable_autolinklocal: Operation not supported
Sep 28 14:52:27 [5713]: eth1: executing `/usr/sbin/dhcpcd_hook.py' PREINIT
Sep 28 14:52:28 [5776]: dhcpcd-7.0.0-rc2 starting
Sep 28 14:52:28 [5776]: eth2: if_disable_autolinklocal: Operation not supported
Sep 28 14:52:28 [5776]: eth2: executing `/usr/sbin/dhcpcd_hook.py' PREINIT
Sep 28 14:52:28 [5794]: dhcpcd-7.0.0-rc2 starting
Sep 28 14:52:28 [5794]: eth3: if_disable_autolinklocal: Operation not supported
Sep 28 14:52:28 [5794]: eth3: executing `/usr/sbin/dhcpcd_hook.py' PREINIT
[2017-09-28T14:52:28+00:00] [DEBUG] [5738] [dhcpcd_hook] [dhcpcd_hook.py:38] dhcpcd_hook.update() environment: environ({'interface': 'eth1', 'reason': 'PREINIT', 'pid': '5713', 'ifcarrier': 'up', 'ifmetric': '203', 'ifwireless': '0', 'ifflags': '4163', 'ifmtu': '1500', 'interface_order': 'lo eth0 eth1 eth2 eth3', 'if_up': 'false', 'if_down': 'false', 'syslog_debug': 'true', 'PATH': '/sbin:/usr/sbin:/bin:/usr/bin'})
Sep 28 14:52:28 [5713]: eth1: executing `/usr/sbin/dhcpcd_hook.py' CARRIER
[2017-09-28T14:52:29+00:00] [DEBUG] [5778] [dhcpcd_hook] [dhcpcd_hook.py:38] dhcpcd_hook.update() environment: environ({'interface': 'eth2', 'reason': 'PREINIT', 'pid': '5776', 'ifcarrier': 'down', 'ifmetric': '204', 'ifwireless': '0', 'ifflags': '4099', 'ifmtu': '1500', 'interface_order': 'lo eth0 eth1 eth2 eth3', 'if_up': 'false', 'if_down': 'false', 'syslog_debug': 'true', 'PATH': '/sbin:/usr/sbin:/bin:/usr/bin'})
[2017-09-28T14:52:29+00:00] [DEBUG] [5795] [dhcpcd_hook] [dhcpcd_hook.py:38] dhcpcd_hook.update() environment: environ({'interface': 'eth3', 'reason': 'PREINIT', 'pid': '5794', 'ifcarrier': 'up', 'ifmetric': '205', 'ifwireless': '0', 'ifflags': '4163', 'ifmtu': '1500', 'interface_order': 'lo eth0 eth1 eth2 eth3', 'if_up': 'false', 'if_down': 'false', 'syslog_debug': 'true', 'PATH': '/sbin:/usr/sbin:/bin:/usr/bin'})
Sep 28 14:52:29 [5776]: eth2: executing `/usr/sbin/dhcpcd_hook.py' NOCARRIER
Sep 28 14:52:29 [5794]: eth3: executing `/usr/sbin/dhcpcd_hook.py' CARRIER
[2017-09-28T14:52:30+00:00] [DEBUG] [5866] [dhcpcd_hook] [dhcpcd_hook.py:38] dhcpcd_hook.update() environment: environ({'interface': 'eth1', 'reason': 'CARRIER', 'pid': '5713', 'ifcarrier': 'up', 'ifmetric': '203', 'ifwireless': '0', 'ifflags': '4163', 'ifmtu': '1500', 'interface_order': 'lo eth0 eth1 eth2 eth3', 'if_up': 'false', 'if_down': 'false', 'syslog_debug': 'true', 'PATH': '/sbin:/usr/sbin:/bin:/usr/bin'})
Sep 28 14:52:30 [5713]: DUID 00:01:00:01:21:5f:c9:2e:08:00:27:89:e0:1f
Sep 28 14:52:30 [5713]: eth1: IAID 27:89:e0:1f
Sep 28 14:52:30 [5713]: eth1: delaying IPv6 router solicitation for 0.4 seconds
Sep 28 14:52:30 [5713]: eth1: delaying IPv4 for 0.2 seconds
Sep 28 14:52:30 [5713]: eth1: using ClientID 01:08:00:27:89:e0:1f
[2017-09-28T14:52:30+00:00] [DEBUG] [5920] [dhcpcd_hook] [dhcpcd_hook.py:38] dhcpcd_hook.update() environment: environ({'interface': 'eth2', 'reason': 'NOCARRIER', 'pid': '5776', 'ifcarrier': 'down', 'ifmetric': '204', 'ifwireless': '0', 'ifflags': '4099', 'ifmtu': '1500', 'interface_order': 'lo eth0 eth1 eth2 eth3', 'if_up': 'false', 'if_down': 'true', 'syslog_debug': 'true', 'PATH': '/sbin:/usr/sbin:/bin:/usr/bin'})
Sep 28 14:52:30 [5713]: eth1: soliciting a DHCP lease
Sep 28 14:52:30 [5713]: eth1: sending DISCOVER (xid 0x7e4a7bd0), next in 3.4 seconds
Sep 28 14:52:30 [5776]: eth2: waiting for carrier
[2017-09-28T14:52:30+00:00] [DEBUG] [5931] [dhcpcd_hook] [dhcpcd_hook.py:38] dhcpcd_hook.update() environment: environ({'interface': 'eth3', 'reason': 'CARRIER', 'pid': '5794', 'ifcarrier': 'up', 'ifmetric': '205', 'ifwireless': '0', 'ifflags': '4163', 'ifmtu': '1500', 'interface_order': 'lo eth0 eth1 eth2 eth3', 'if_up': 'false', 'if_down': 'false', 'syslog_debug': 'true', 'PATH': '/sbin:/usr/sbin:/bin:/usr/bin'})
Sep 28 14:52:30 [5713]: eth1: soliciting an IPv6 router
Sep 28 14:52:30 [5713]: eth1: sending Router Solicitation
Sep 28 14:52:30 [5713]: eth1: Router Advertisement from fe80::a00:27ff:fe5d:6607
Sep 28 14:52:30 [5713]: eth1: adding address fd70:a6a5:a58b:5:a00:27ff:fe89:e01f/64
Sep 28 14:52:30 [5713]: eth1: pltime 14400 seconds, vltime 86400 seconds
Sep 28 14:52:30 [5713]: eth1: adding route to fd70:a6a5:a58b:4::/64
Sep 28 14:52:30 [5713]: eth1: adding route to fd70:a6a5:a58b:5::/64
Sep 28 14:52:30 [5713]: eth1: adding default route via fe80::a00:27ff:fe5d:6607
Sep 28 14:52:30 [5713]: eth1: waiting for Router Advertisement DAD to complete
Sep 28 14:52:30 [5713]: eth1: reading lease `/var/db/dhcpcd/eth1.lease6'
Sep 28 14:52:30 [5713]: eth1: soliciting a DHCPv6 lease
Sep 28 14:52:30 [5713]: eth1: delaying SOLICIT6 (xid 0x5a5436), next in 1.0 seconds
Sep 28 14:52:30 [5794]: DUID 00:01:00:01:21:5f:c9:2e:08:00:27:89:e0:1f
Sep 28 14:52:30 [5794]: eth3: IAID 27:a6:36:85
Sep 28 14:52:30 [5794]: eth3: delaying IPv6 router solicitation for 0.7 seconds
Sep 28 14:52:30 [5794]: eth3: delaying IPv4 for 0.0 seconds
Sep 28 14:52:30 [5794]: eth3: using ClientID 01:08:00:27:a6:36:85
Sep 28 14:52:30 [5794]: eth3: soliciting a DHCP lease
Sep 28 14:52:30 [5794]: eth3: sending DISCOVER (xid 0x19e5ce8d), next in 3.8 seconds
Sep 28 14:52:30 [5794]: eth0: truncated packet (24) from 127.0.0.1
Sep 28 14:52:30 [5794]: eth0: truncated packet (24) from 127.0.0.1
Sep 28 14:52:31 [5794]: eth3: soliciting an IPv6 router
Sep 28 14:52:31 [5794]: eth3: sending Router Solicitation
Sep 28 14:52:31 [5713]: eth1: offered 10.9.16.1 from 10.9.25.143
Sep 28 14:52:31 [5713]: eth1: sending REQUEST (xid 0x7e4a7bd0), next in 3.6 seconds
Sep 28 14:52:31 [5713]: eth1: acknowledged 10.9.16.1 from 10.9.25.143
Sep 28 14:52:31 [5713]: eth1: probing address 10.9.16.1/20
Sep 28 14:52:31 [5713]: eth1: probing for 10.9.16.1
Sep 28 14:52:31 [5713]: eth1: ARP probing 10.9.16.1 (1 of 3), next in 1.1 seconds
Sep 28 14:52:31 [5713]: eth1: broadcasting SOLICIT6 (xid 0x5a5436), next in 1.0 seconds
Sep 28 14:52:31 [5713]: eth1: ADV fd70:a6a5:a58b:4:ffff:ffff:ffff:fff6/128 from fe80::a00:27ff:fe5d:6607
Sep 28 14:52:31 [5713]: eth1: broadcasting REQUEST6 (xid 0x5083a0), next in 1.0 seconds
Sep 28 14:52:31 [5713]: eth1: REPLY6 received from fe80::a00:27ff:fe5d:6607
Sep 28 14:52:31 [5713]: eth1: adding address fd70:a6a5:a58b:4:ffff:ffff:ffff:fff6/128
Sep 28 14:52:31 [5713]: eth1: pltime 11250 seconds, vltime 18000 seconds
Sep 28 14:52:31 [5713]: eth1: renew in 5625, rebind in 9000, expire in 18000 seconds
Sep 28 14:52:31 [5713]: eth1: writing lease `/var/db/dhcpcd/eth1.lease6'
Sep 28 14:52:31 [5713]: eth1: waiting for DHCPv6 DAD to complete
Sep 28 14:52:31 [5713]: eth1: Router Advertisement DAD completed
Sep 28 14:52:31 [5713]: eth1: executing `/usr/sbin/dhcpcd_hook.py' ROUTERADVERT
[2017-09-28T14:52:32+00:00] [DEBUG] [6294] [dhcpcd_hook] [dhcpcd_hook.py:38] dhcpcd_hook.update() environment: environ({'interface': 'eth1', 'reason': 'ROUTERADVERT', 'pid': '5713', 'ifcarrier': 'up', 'ifmetric': '203', 'ifwireless': '0', 'ifflags': '4163', 'ifmtu': '1500', 'interface_order': 'eth1 lo eth0 eth2 eth3', 'if_up': 'true', 'if_down': 'false', 'syslog_debug': 'true', 'nd1_from': 'fe80::a00:27ff:fe5d:6607', 'nd1_acquired': '36', 'nd1_now': '38', 'nd1_prefix_information1_length': '64', 'nd1_prefix_information1_flags': 'L', 'nd1_prefix_information1_vltime': '86400', 'nd1_prefix_information1_pltime': '14400', 'nd1_prefix_information1_prefix': 'fd70:a6a5:a58b:4::', 'nd1_prefix_information2_length': '64', 'nd1_prefix_information2_flags': 'LA', 'nd1_prefix_information2_vltime': '86400', 'nd1_prefix_information2_pltime': '14400', 'nd1_prefix_information2_prefix': 'fd70:a6a5:a58b:5::', 'nd1_mtu': '1280', 'nd1_source_address': '0800275d6607', 'nd1_addr1': 'fd70:a6a5:a58b:5:a00:27ff:fe89:e01f/64', 'PATH': '/sbin:/usr/sbin:/bin:/usr/bin'})
[2017-09-28T14:52:32+00:00] [INFO] [6294] [dhcpcd_hook] [dhcpcd_hook.py:157] Recording 'fe80::a00:27ff:fe5d:6607' as dynamic default route for eth1
[2017-09-28T14:52:32+00:00] [INFO] [6294] [dhcpcd_hook] [dhcpcd_hook.py:109] Recording fd70:a6a5:a58b:5:a00:27ff:fe89:e01f/64 as a dynamic address
[2017-09-28T14:52:32+00:00] [DEBUG] [6294] [pyroserver.connector] [connector.py:31] My PID: 6294, API PID: 4698
Sep 28 14:52:32 [5713]: eth1: ARP probing 10.9.16.1 (2 of 3), next in 1.3 seconds
Sep 28 14:52:33 [5713]: eth1: DHCPv6 DAD completed
Sep 28 14:52:33 [5713]: eth1: executing `/usr/sbin/dhcpcd_hook.py' BOUND6
[2017-09-28T14:52:34+00:00] [DEBUG] [6384] [dhcpcd_hook] [dhcpcd_hook.py:38] dhcpcd_hook.update() environment: environ({'interface': 'eth1', 'reason': 'BOUND6', 'pid': '5713', 'ifcarrier': 'up', 'ifmetric': '203', 'ifwireless': '0', 'ifflags': '4163', 'ifmtu': '1500', 'interface_order': 'eth1 lo eth0 eth2 eth3', 'if_up': 'true', 'if_down': 'false', 'syslog_debug': 'true', 'new_dhcp6_ia_na1_iaid': '2789e01f', 'new_dhcp6_ia_na1_t1': '0', 'new_dhcp6_ia_na1_t2': '0', 'new_dhcp6_ia_na1_ia_addr1': 'fd70:a6a5:a58b:4:ffff:ffff:ffff:fff6', 'new_dhcp6_ia_na1_ia_addr1_pltime': '11250', 'new_dhcp6_ia_na1_ia_addr1_vltime': '18000', 'new_dhcp6_client_id': '00010001215fc92e08002789e01f', 'new_dhcp6_server_id': '00010001215f8d9e0800275d6607', 'new_dhcp6_reconfigure_accept': '1', 'new_dhcp6_name_servers': 'fd70:a6a5:a58b:4::144', 'PATH': '/sbin:/usr/sbin:/bin:/usr/bin'})
[2017-09-28T14:52:34+00:00] [INFO] [6384] [dhcpcd_hook] [dhcpcd_hook.py:109] Recording fd70:a6a5:a58b:4:ffff:ffff:ffff:fff6/64 as a dynamic address
[2017-09-28T14:52:34+00:00] [DEBUG] [6384] [pyroserver.connector] [connector.py:31] My PID: 6384, API PID: 4698
Sep 28 14:52:34 [5713]: eth1: ARP probing 10.9.16.1 (3 of 3), next in 2.0 seconds
Sep 28 14:52:34 [5794]: eth3: sending DISCOVER (xid 0x19e5ce8d), next in 7.1 seconds
Sep 28 14:52:35 [5794]: eth3: sending Router Solicitation
Sep 28 14:52:35 [5794]: eth3: probing for an IPv4LL address
Sep 28 14:52:35 [5794]: eth3: probing for 169.254.146.151
Sep 28 14:52:35 [5794]: eth3: ARP probing 169.254.146.151 (1 of 3), next in 1.2 seconds
Sep 28 14:52:36 [5713]: eth1: DAD completed for 10.9.16.1
Sep 28 14:52:36 [5713]: eth1: leased 10.9.16.1 for 1409 seconds
Sep 28 14:52:36 [5713]: eth1: renew in 704 seconds, rebind in 1232 seconds
Sep 28 14:52:36 [5713]: eth1: writing lease `/var/db/dhcpcd/eth1.lease'
Sep 28 14:52:36 [5713]: eth1: adding IP address 10.9.16.1/20 broadcast 10.9.31.255
Sep 28 14:52:36 [5713]: eth1: adding route to 10.9.16.0/20
Sep 28 14:52:36 [5713]: eth1: adding default route via 10.9.25.143
Sep 28 14:52:36 [5713]: eth1: ARP announcing 10.9.16.1 (1 of 2), next in 2.0 seconds
Sep 28 14:52:36 [5713]: eth1: executing `/usr/sbin/dhcpcd_hook.py' BOUND
[2017-09-28T14:52:36+00:00] [DEBUG] [6447] [dhcpcd_hook] [dhcpcd_hook.py:38] dhcpcd_hook.update() environment: environ({'interface': 'eth1', 'reason': 'BOUND', 'pid': '5713', 'ifcarrier': 'up', 'ifmetric': '203', 'ifwireless': '0', 'ifflags': '4163', 'ifmtu': '1500', 'interface_order': 'eth1 lo eth0 eth2 eth3', 'if_up': 'true', 'if_down': 'false', 'syslog_debug': 'true', 'new_ip_address': '10.9.16.1', 'new_subnet_cidr': '20', 'new_broadcast_address': '10.9.31.255', 'new_network_number': '10.9.16.0', 'new_subnet_mask': '255.255.240.0', 'new_routers': '10.9.25.143', 'new_domain_name_servers': '10.9.25.143', 'new_dhcp_lease_time': '1409', 'new_dhcp_message_type': '5', 'new_dhcp_server_identifier': '10.9.25.143', 'PATH': '/sbin:/usr/sbin:/bin:/usr/bin'})
[2017-09-28T14:52:36+00:00] [INFO] [6447] [dhcpcd_hook] [dhcpcd_hook.py:109] Recording 10.9.16.1/20 as a dynamic address
[2017-09-28T14:52:36+00:00] [DEBUG] [6447] [pyroserver.connector] [connector.py:31] My PID: 6447, API PID: 4698
Sep 28 14:52:36 [5794]: eth3: ARP probing 169.254.146.151 (2 of 3), next in 1.7 seconds
[2017-09-28T14:52:36+00:00] [INFO] [6447] [dhcpcd_hook] [dhcpcd_hook.py:157] Recording '10.9.25.143' as dynamic default route for eth1
Sep 28 14:52:38 [5713]: eth1: ARP announcing 10.9.16.1 (2 of 2)
Sep 28 14:52:38 [5794]: eth3: ARP probing 169.254.146.151 (3 of 3), next in 2.0 seconds
Sep 28 14:52:39 [5794]: eth3: sending Router Solicitation
Sep 28 14:52:40 [5794]: eth3: using IPv4LL address 169.254.146.151
Sep 28 14:52:40 [5794]: eth3: adding IP address 169.254.146.151/16 broadcast 169.254.255.255
Sep 28 14:52:40 [5794]: eth3: adding route to 169.254.0.0/16
Sep 28 14:52:40 [5794]: eth3: adding default route
Sep 28 14:52:40 [5794]: eth3: ARP announcing 169.254.146.151 (1 of 2), next in 2.0 seconds
Sep 28 14:52:40 [5794]: eth3: executing `/usr/sbin/dhcpcd_hook.py' IPV4LL
[2017-09-28T14:52:41+00:00] [DEBUG] [6527] [dhcpcd_hook] [dhcpcd_hook.py:38] dhcpcd_hook.update() environment: environ({'interface': 'eth3', 'reason': 'IPV4LL', 'pid': '5794', 'ifcarrier': 'up', 'ifmetric': '205', 'ifwireless': '0', 'ifflags': '4163', 'ifmtu': '1500', 'interface_order': 'eth3 lo eth0 eth1 eth2', 'if_up': 'true', 'if_down': 'false', 'syslog_debug': 'true', 'new_ip_address': '169.254.146.151', 'new_subnet_mask': '255.255.0.0', 'new_subnet_cidr': '16', 'new_broadcast_address': '169.254.255.255', 'new_network_number': '169.254.0.0', 'PATH': '/sbin:/usr/sbin:/bin:/usr/bin'})
Sep 28 14:52:41 [5794]: eth3: sending DISCOVER (xid 0x19e5ce8d), next in 16.0 seconds
Sep 28 14:52:42 [5794]: eth3: ARP announcing 169.254.146.151 (2 of 2)
Sep 28 14:52:43 [5794]: eth3: sending Router Solicitation
Sep 28 14:52:43 [5794]: eth3: no IPv6 Routers available
Sep 28 14:52:58 [5794]: eth3: sending DISCOVER (xid 0x19e5ce8d), next in 32.8 seconds
Sep 28 14:53:30 [5794]: eth3: sending DISCOVER (xid 0x19e5ce8d), next in 63.3 seconds
Sep 28 14:53:59 [5713]: eth1: Router Advertisement from fe80::a00:27ff:fe5d:6607
Sep 28 14:53:59 [5713]: eth1: adding address fd70:a6a5:a58b:5:a00:27ff:fe89:e01f/64
Sep 28 14:53:59 [5713]: eth1: pltime 14400 seconds, vltime 86400 seconds
Sep 28 14:53:59 [5713]: eth1: executing `/usr/sbin/dhcpcd_hook.py' ROUTERADVERT
[2017-09-28T14:54:00+00:00] [DEBUG] [7252] [dhcpcd_hook] [dhcpcd_hook.py:38] dhcpcd_hook.update() environment: environ({'interface': 'eth1', 'reason': 'ROUTERADVERT', 'pid': '5713', 'ifcarrier': 'up', 'ifmetric': '203', 'ifwireless': '0', 'ifflags': '4163', 'ifmtu': '1500', 'interface_order': 'eth1 lo eth0 eth2 eth3', 'if_up': 'true', 'if_down': 'false', 'syslog_debug': 'true', 'nd1_from': 'fe80::a00:27ff:fe5d:6607', 'nd1_acquired': '125', 'nd1_now': '125', 'nd1_prefix_information1_length': '64', 'nd1_prefix_information1_flags': 'L', 'nd1_prefix_information1_vltime': '86400', 'nd1_prefix_information1_pltime': '14400', 'nd1_prefix_information1_prefix': 'fd70:a6a5:a58b:4::', 'nd1_prefix_information2_length': '64', 'nd1_prefix_information2_flags': 'LA', 'nd1_prefix_information2_vltime': '86400', 'nd1_prefix_information2_pltime': '14400', 'nd1_prefix_information2_prefix': 'fd70:a6a5:a58b:5::', 'nd1_mtu': '1280', 'nd1_source_address': '0800275d6607', 'nd1_addr1': 'fd70:a6a5:a58b:5:a00:27ff:fe89:e01f/64', 'PATH': '/sbin:/usr/sbin:/bin:/usr/bin'})
[2017-09-28T14:54:00+00:00] [INFO] [7252] [dhcpcd_hook] [dhcpcd_hook.py:157] Recording 'fe80::a00:27ff:fe5d:6607' as dynamic default route for eth1
[2017-09-28T14:54:00+00:00] [INFO] [7252] [dhcpcd_hook] [dhcpcd_hook.py:109] Recording fd70:a6a5:a58b:5:a00:27ff:fe89:e01f/64 as a dynamic address
[2017-09-28T14:54:00+00:00] [DEBUG] [7252] [pyroserver.connector] [connector.py:31] My PID: 7252, API PID: 4698