Re: Getting dhcpcd to pass BCT?
Roy Marples
Wed Jun 03 13:31:41 2020
Hi Michael
On 03/06/2020 02:23, Michael Sweet wrote:
Roy,
I started with v8.0.2 (what is normally packaged with Yocto Zeus), then tried
v8.1.6 (Yocto Dunfell's version), then v9.0.2 last week, then I saw v9.1.0 just
got posted and tried that. All of them fail in the same way during the IPv4LL
tests... :/
Wow. If those versions all fail then something must be seriously wrong!
For reference this is what I get when I set my Proxy ARP Daemon running for the
169.254/16 network:
Jun 03 12:58:24 [3762]: dhcpcd-9.1.0 starting
Jun 03 12:58:24 [3762]: no such user _dhcpcdx
Jun 03 12:58:24 [3764]: udev: starting
Jun 03 12:58:24 [3764]: dev: loaded udev
Jun 03 12:58:24 [3764]: DUID 00:01:00:01:26:4d:67:88:fa:73:78:00:00:11
Jun 03 12:58:24 [3764]: lo: ignoring due to interface type and no config
Jun 03 12:58:24 [3764]: eth0: executing `/libexec/dhcpcd-run-hooks' PREINIT
Jun 03 12:58:24 [3764]: eth0: executing `/libexec/dhcpcd-run-hooks' CARRIER
Jun 03 12:58:24 [3764]: eth0: IAID 78:00:00:11
Jun 03 12:58:24 [3764]: eth0: delaying IPv4 for 1.4 seconds
Jun 03 12:58:26 [3764]: eth0: probing for an IPv4LL address
Jun 03 12:58:26 [3764]: eth0: probing for 169.254.108.163
Jun 03 12:58:26 [3764]: eth0: ARP probing 169.254.108.163 (1 of 3), next in 1.6
seconds
Jun 03 12:58:26 [3764]: eth0: b4:2e:99:c8:d8:2a(b4:2e:99:c8:d8:2a) claims
169.254.108.163
Jun 03 12:58:27 [3764]: eth0: probing for an IPv4LL address
Jun 03 12:58:27 [3764]: eth0: probing for 169.254.252.203
Jun 03 12:58:27 [3764]: eth0: ARP probing 169.254.252.203 (1 of 3), next in 1.3
seconds
Jun 03 12:58:27 [3764]: eth0: b4:2e:99:c8:d8:2a(b4:2e:99:c8:d8:2a) claims
169.254.252.203
Jun 03 12:58:28 [3764]: eth0: probing for an IPv4LL address
Jun 03 12:58:28 [3764]: eth0: probing for 169.254.51.155
Jun 03 12:58:28 [3764]: eth0: ARP probing 169.254.51.155 (1 of 3), next in 2.0
seconds
Jun 03 12:58:28 [3764]: eth0: b4:2e:99:c8:d8:2a(b4:2e:99:c8:d8:2a) claims
169.254.51.155
Jun 03 12:58:29 [3764]: eth0: probing for an IPv4LL address
Jun 03 12:58:29 [3764]: eth0: probing for 169.254.140.25
Jun 03 12:58:29 [3764]: eth0: ARP probing 169.254.140.25 (1 of 3), next in 1.3
seconds
Jun 03 12:58:29 [3764]: eth0: b4:2e:99:c8:d8:2a(b4:2e:99:c8:d8:2a) claims
169.254.140.25
Jun 03 12:58:30 [3764]: eth0: probing for an IPv4LL address
Jun 03 12:58:30 [3764]: eth0: probing for 169.254.99.151
Jun 03 12:58:30 [3764]: eth0: ARP probing 169.254.99.151 (1 of 3), next in 1.3
seconds
Jun 03 12:58:30 [3764]: eth0: b4:2e:99:c8:d8:2a(b4:2e:99:c8:d8:2a) claims
169.254.99.151
Jun 03 12:58:31 [3764]: eth0: probing for an IPv4LL address
Jun 03 12:58:31 [3764]: eth0: probing for 169.254.45.158
Jun 03 12:58:31 [3764]: eth0: ARP probing 169.254.45.158 (1 of 3), next in 1.9
seconds
Jun 03 12:58:31 [3764]: eth0: b4:2e:99:c8:d8:2a(b4:2e:99:c8:d8:2a) claims
169.254.45.158
Jun 03 12:58:32 [3764]: eth0: probing for an IPv4LL address
Jun 03 12:58:32 [3764]: eth0: probing for 169.254.68.191
Jun 03 12:58:32 [3764]: eth0: ARP probing 169.254.68.191 (1 of 3), next in 1.5
seconds
Jun 03 12:58:32 [3764]: eth0: b4:2e:99:c8:d8:2a(b4:2e:99:c8:d8:2a) claims
169.254.68.191
Jun 03 12:58:33 [3764]: eth0: probing for an IPv4LL address
Jun 03 12:58:33 [3764]: eth0: probing for 169.254.93.208
Jun 03 12:58:33 [3764]: eth0: ARP probing 169.254.93.208 (1 of 3), next in 1.9
seconds
Jun 03 12:58:33 [3764]: eth0: b4:2e:99:c8:d8:2a(b4:2e:99:c8:d8:2a) claims
169.254.93.208
Jun 03 12:58:34 [3764]: eth0: probing for an IPv4LL address
Jun 03 12:58:34 [3764]: eth0: probing for 169.254.170.121
Jun 03 12:58:34 [3764]: eth0: ARP probing 169.254.170.121 (1 of 3), next in 1.4
seconds
Jun 03 12:58:34 [3764]: eth0: b4:2e:99:c8:d8:2a(b4:2e:99:c8:d8:2a) claims
169.254.170.121
Jun 03 12:58:35 [3764]: eth0: probing for an IPv4LL address
Jun 03 12:58:35 [3764]: eth0: probing for 169.254.189.182
Jun 03 12:58:35 [3764]: eth0: ARP probing 169.254.189.182 (1 of 3), next in 1.6
seconds
Jun 03 12:58:35 [3764]: eth0: b4:2e:99:c8:d8:2a(b4:2e:99:c8:d8:2a) claims
169.254.189.182
Jun 03 12:58:35 [3764]: eth0: failed to acquire an IPv4LL address
Jun 03 12:58:37 [3764]: received SIGINT, stopping
Jun 03 12:58:37 [3764]: eth0: removing interface
Jun 03 12:58:37 [3764]: eth0: executing `/libexec/dhcpcd-run-hooks' STOPPED
Jun 03 12:58:37 [3764]: dev: unloaded udev
Jun 03 12:58:37 [3764]: dhcpcd exited
I deliberately configred privsep for a bogus user to match your output.
But it works either way.
On Jun 2, 2020, at 3:05 PM, Roy Marples <roy@xxxxxxxxxxxx
<mailto:roy@xxxxxxxxxxxx>> wrote:
...
I've been digging through the source but am still coming up to speed to
understand how dhcpcd decides to stop trying new IPv4LL addresses, and how
this might be fixed (or if this is even the problem...) I was also wondering
why dhcpcd only chooses 169.254.x.0 addresses on my Pi - the code looks like
it should have randomness in the entire lower 16 bits of the IPv4 address...
Hmmmmm, it should use the entire lower 16 bits of the address.
At least it does on litle endian machines. I'll try and test a BE machine
later - but might take some time as it's an ERLITE router running NetBSD.
I did a little testing and it looks like the first random number out of random()
has a lower 8 bits of zeroes - probably just coincidental on this particular
hardware...
Most of the time all I can get are the initial probes with dhcpcd not seeing any
of the deny messages:
Bonjour Conformance Test Version 1.5.1(15100)
Starting Test: 2020-06-02 18:16:19.665838-0400
*** Please Power On Device ***
*** Beginning Link-Local Address Allocation Test ***
START (INITIAL PROBING)
NOTICE 2020-06-02 18:16:24.025271-0400: Received probe for 169.254.194.0
[b8:27:eb:15:f4:fd].
PASSED (INITIAL PROBING)
START (PROBING)
NOTICE 2020-06-02 18:16:24.026110-0400: Denying probe for
169.254.194.0
ERROR 2020-06-02 18:16:25.168398-0400: Device did not probe for new
address after it's chosen address was denied.
NOTICE 2020-06-02 18:16:25.168451-0400: Denying probe for
169.254.194.0
ERROR 2020-06-02 18:16:26.372102-0400: Device did not probe for new
address after it's chosen address was denied.
NOTICE 2020-06-02 18:16:26.372140-0400: Denying probe for
169.254.194.0
WARNING 2020-06-02 18:16:28.407480-0400: Source address non-zero 169.254.194.0
WARNING 2020-06-02 18:16:28.615814-0400: Received address record query
(name: pieb15f4fd.local., address: 169.254.194.0) before device successfully
acquired a link-local IP address in subtest PROBING.
WARNING 2020-06-02 18:16:30.422856-0400: Source address non-zero 169.254.194.0
WARNING 2020-06-02 18:17:03.301368-0400: Have not received initial probe
from device. Listening...
The debug log from dhcpcd has the following (ignore the dates/times - clock
isn't set on the 'Pi):
May 21 21:26:06 [236]: dhcpcd-9.1.0 starting
May 21 21:26:06 [236]: no such user dhcpcd
May 21 21:26:06 [238]: DUID 00:01:00:01:26:59:ac:41:b8:27:eb:15:f4:fd
May 21 21:26:06 [238]: wlan0: executing `/usr/libexec/dhcpcd-run-hooks' PREINIT
May 21 21:26:06 [238]: wlan0: executing `/usr/libexec/dhcpcd-run-hooks'
NOCARRIER
May 21 21:26:06 [238]: wlan0: waiting for carrier
May 21 21:26:07 [238]: wlan0: carrier acquired
May 21 21:26:07 [238]: wlan0: connected to Access Point `Lakeside Test'
May 21 21:26:07 [238]: wlan0: executing `/usr/libexec/dhcpcd-run-hooks' CARRIER
May 21 21:26:07 [238]: wlan0: IAID eb:15:f4:fd
May 21 21:26:07 [238]: wlan0: adding address fe80::1d96:c613:8cdd:4ba8
May 21 21:26:07 [238]: wlan0: pltime infinity, vltime infinity
May 21 21:26:07 [238]: wlan0: soliciting an IPv6 router
May 21 21:26:07 [238]: wlan0: delaying Router Solicitation for LL address
May 21 21:26:07 [238]: wlan0: reading lease
`/var/db/dhcpcd/wlan0-Lakeside\040Test.lease'
May 21 21:26:07 [238]: wlan0: soliciting a DHCP lease
May 21 21:26:07 [238]: wlan0: sending DISCOVER (xid 0x978005e7), next in 4.1
seconds
May 21 21:26:08 [238]: wlan0: probing for an IPv4LL address
May 21 21:26:08 [238]: wlan0: probing for 169.254.194.0
May 21 21:26:08 [238]: wlan0: ARP probing 169.254.194.0 (1 of 3), next in
1.1 seconds
May 21 21:26:08 [238]: wlan0: sending Router Solicitation
May 21 21:26:09 [238]: wlan0: ARP probing 169.254.194.0 (2 of 3), next in
1.2 seconds
May 21 21:26:10 [238]: wlan0: ARP probing 169.254.194.0 (3 of 3), next in
2.0 seconds
May 21 21:26:11 [238]: wlan0: sending DISCOVER (xid 0x978005e7), next in 7.4
seconds
May 21 21:26:12 [238]: wlan0: using IPv4LL address 169.254.194.0
May 21 21:26:12 [238]: wlan0: adding IP address 169.254.194.0/16 broadcast
169.254.255.255
May 21 21:26:12 [238]: wlan0: adding route to 169.254.0.0/16
May 21 21:26:12 [238]: wlan0: adding default route
May 21 21:26:12 [238]: wlan0: ARP announcing 169.254.194.0 (1 of 2), next in
2.0 seconds
May 21 21:26:12 [238]: wlan0: executing `/usr/libexec/dhcpcd-run-hooks' IPV4LL
May 21 21:26:13 [238]: wlan0: sending Router Solicitation
May 21 21:26:14 [238]: wlan0: ARP announcing 169.254.194.0 (2 of 2)
May 21 21:26:17 [238]: wlan0: sending Router Solicitation
May 21 21:26:18 [238]: wlan0: sending DISCOVER (xid 0x978005e7), next in
15.5 seconds
May 21 21:26:21 [238]: wlan0: sending Router Solicitation
May 21 21:26:21 [238]: wlan0: no IPv6 Routers available
May 21 21:26:34 [238]: wlan0: sending DISCOVER (xid 0x978005e7), next in
31.4 seconds
May 21 21:27:05 [238]: wlan0: sending DISCOVER (xid 0x978005e7), next in
64.6 seconds
May 21 21:28:10 [238]: wlan0: sending DISCOVER (xid 0x978005e7), next in
64.2 seconds
May 21 21:29:14 [238]: wlan0: sending DISCOVER (xid 0x978005e7), next in
63.7 seconds
I also have a dump of the network traffic showing my MacBook Pro claiming the
169.254.194.0 address each time but the 'Pi either isn't seeing it or it isn't
getting to dhcpcd for some reason...
For reference, the MacBook Pro is connected via Ethernet to an AirPort Time
Capsule, and the Pi Zero is connected via Wi-Fi to the Time Capsule (as required
by the BCT manual). I have also tested with a Pi 3b over Wi-Fi and Ethernet,
with the same results...
The only patch to the dhcpcd software is the Yocto "INCLUDEDIR" patch (so that
dhcpcd builds against the embedded system/SDK headers).
Can you try the attached patch please?
It will hopefully provide some debug info to help show where the issue is.
Roy
diff --git a/src/arp.c b/src/arp.c
index fef12425..772271bb 100644
--- a/src/arp.c
+++ b/src/arp.c
@@ -233,6 +233,8 @@ arp_packet(struct interface *ifp, uint8_t *data, size_t len,
struct arp_state *astate, *astaten;
uint8_t *hw_s, *hw_t;
+ logerrx("GOT ARP!");
+
/* Copy the frame header source and destination out */
memset(&arm, 0, sizeof(arm));
if (fl != 0) {
@@ -249,14 +251,16 @@ arp_packet(struct interface *ifp, uint8_t *data, size_t len,
}
/* We must have a full ARP header */
- if (len < sizeof(ar))
+ if (len < sizeof(ar)) {
+ logerrx("%s: ARP too short", ifp->name);
return;
+ }
memcpy(&ar, data, sizeof(ar));
if (!arp_validate(ifp, &ar)) {
-#ifdef BPF_DEBUG
+//#ifdef BPF_DEBUG
logerrx("%s: ARP BPF validation failure", ifp->name);
-#endif
+//#endif
return;
}
@@ -264,8 +268,10 @@ arp_packet(struct interface *ifp, uint8_t *data, size_t len,
hw_s = data + sizeof(ar);
hw_t = hw_s + ar.ar_hln + ar.ar_pln;
/* Ensure we got all the data */
- if ((size_t)((hw_t + ar.ar_hln + ar.ar_pln) - data) > len)
+ if ((size_t)((hw_t + ar.ar_hln + ar.ar_pln) - data) > len) {
+ logerrx("%s: ARP packet truncated", ifp->name);
return;
+ }
/* Ignore messages from ourself */
TAILQ_FOREACH(ifn, ifp->ctx->ifaces, next) {
if (ar.ar_hln == ifn->hwlen &&
@@ -273,11 +279,12 @@ arp_packet(struct interface *ifp, uint8_t *data, size_t len,
break;
}
if (ifn) {
-#ifdef ARP_DEBUG
+//#ifdef ARP_DEBUG
logdebugx("%s: ignoring ARP from self", ifp->name);
-#endif
+//#endif
return;
}
+
/* Copy out the HW and IP addresses */
memcpy(&arm.sha, hw_s, ar.ar_hln);
memcpy(&arm.sip.s_addr, hw_s + ar.ar_hln, ar.ar_pln);
@@ -287,14 +294,18 @@ arp_packet(struct interface *ifp, uint8_t *data, size_t len,
/* Match the ARP probe to our states.
* Ignore Unicast Poll, RFC1122. */
state = ARP_CSTATE(ifp);
- if (state == NULL)
+ if (state == NULL) {
+ logerrx("%s: no ARP state", ifp->name);
return;
+ }
TAILQ_FOREACH_SAFE(astate, &state->arp_states, next, astaten) {
if (IN_ARE_ADDR_EQUAL(&arm.sip, &astate->addr) ||
(IN_IS_ADDR_UNSPECIFIED(&arm.sip) &&
IN_ARE_ADDR_EQUAL(&arm.tip, &astate->addr) &&
bpf_flags & BPF_BCAST))
arp_found(astate, &arm);
+ else
+ logerrx("did not match ARP state %s", inet_ntoa(astate->addr));
}
}
diff --git a/src/bpf.c b/src/bpf.c
index f450a043..fd246b70 100644
--- a/src/bpf.c
+++ b/src/bpf.c
@@ -510,6 +510,13 @@ bpf_arp_rw(const struct bpf *bpf, const struct in_addr *ia, bool recv)
memcpy(bp, bpf_arp_filter, sizeof(bpf_arp_filter));
bp += BPF_ARP_FILTER_LEN;
+
+ /* ARP test - pass the packet */
+ BPF_SET_STMT(bp, BPF_RET + BPF_K, arp_len);
+ bp++;
+ goto done;
+
+
/* Ensure it's not from us. */
bp += bpf_cmp_hwaddr(bp, BPF_CMP_HWADDR_LEN, sizeof(struct arphdr),
!recv, ifp->hwaddr, ifp->hwlen);
@@ -543,6 +550,7 @@ bpf_arp_rw(const struct bpf *bpf, const struct in_addr *ia, bool recv)
BPF_SET_STMT(bp, BPF_RET + BPF_K, 0);
bp++;
+done:
#ifdef BIOCSETWF
if (!recv)
return bpf_wattach(bpf->bpf_fd, buf, (unsigned int)(bp - buf));
Archive administrator: postmaster@marples.name