Bug 1998448

See also: bug 1810172

Hmm, trying to improve the error handling doesn't have the intended effect.

--- a/NetworkPkg/Dhcp6Dxe/Dhcp6Io.c
+++ b/NetworkPkg/Dhcp6Dxe/Dhcp6Io.c
@@ -2261,6 +2261,20 @@ Dhcp6HandleReplyMsg (
       }
       break;
 
+    case Dhcp6StsNoAddrsAvail:
+      DEBUG ((DEBUG_INFO, "%a: Dhcp6StsNoAddrsAvail (%d)\n", __FUNCTION__,
+              Instance->IaCb.Ia->State));
+      if (Instance->IaCb.Ia->State == Dhcp6Requesting) {
+        //
+        // dnsmasq changed its mind, try start over
+        //
+        Status = Dhcp6InitSolicitMsg (Instance);
+        if (EFI_ERROR (Status)) {
+          return  Status;
+        }
+      }
+      break;
+
     case Dhcp6StsNotOnLink:
       if (Instance->IaCb.Ia->State == Dhcp6Confirming) {
         //

14:17:39 DEBUG| [stderr] + exec /usr/sbin/dnsmasq --no-daemon --leasefile-ro --log-dhcp --interface net0 '--dhcp-host=52:54:00:12:34:56,qemu.network,192.168.42.200,[fd42::200/126]' --dhcp-range=192.168.42.10,192.168.42.99 --dhcp-range=fd42::10,fd42::ff --dhcp-boot=/404 '--dhcp-option=option6:bootfile-url,tftp://[fd42::1]/EFI/BOOT/grub.efi' --enable-tftp --tftp-root=/home/kraxel/projects/edk2-tests/buildroot/initrd-x86_64
[ ... ]
14:17:48 DEBUG| [stderr] dnsmasq-dhcp: 14547842 available DHCP range: fd42::10 -- fd42::ff
14:17:48 DEBUG| [stderr] dnsmasq-dhcp: 14547842 vendor class: 343
14:17:48 DEBUG| [stderr] dnsmasq-dhcp: 14547842 client MAC address: 52:54:00:12:34:56
14:17:48 DEBUG| [stderr] dnsmasq-dhcp: 14547842 DHCPSOLICIT(net0) 00:01:00:01:28:3d:04:67:52:54:00:12:34:56 
14:17:48 DEBUG| [stderr] dnsmasq-dhcp: 14547842 DHCPADVERTISE(net0) fd42::200 00:01:00:01:28:3d:04:67:52:54:00:12:34:56 qemu
14:17:48 DEBUG| [stderr] dnsmasq-dhcp: 14547842 requested options: 59:bootfile-url, 60:bootfile-param, 23:dns-server, 
14:17:48 DEBUG| [stderr] dnsmasq-dhcp: 14547842 requested options: 16:vendor-class
14:17:48 DEBUG| [stderr] dnsmasq-dhcp: 14547842 tags: known, dhcpv6, net0
14:17:48 DEBUG| [stderr] dnsmasq-dhcp: 14547842 sent size: 14 option:  1 client-id  00:01:00:01:28:3d:04:67:52:54:00:12:34:56
14:17:48 DEBUG| [stderr] dnsmasq-dhcp: 14547842 sent size: 10 option:  2 server-id  00:03:00:01:b6:fe:38:22:4e:b7
14:17:48 DEBUG| [stderr] dnsmasq-dhcp: 14547842 sent size: 40 option:  3 ia-na  IAID=1917410942 T1=43200 T2=75600
14:17:48 DEBUG| [stderr] dnsmasq-dhcp: 14547842 nest size: 24 option:  5 iaaddr  fd42::200 PL=86400 VL=86400
14:17:48 DEBUG| [stderr] dnsmasq-dhcp: 14547842 sent size:  9 option: 13 status  0 success
14:17:48 DEBUG| [stderr] dnsmasq-dhcp: 14547842 sent size:  1 option:  7 preference  0
14:17:48 DEBUG| [stderr] dnsmasq-dhcp: 14547842 sent size: 34 option: 59 bootfile-url  tftp://[fd42::1]/EFI/BOOT/grub.efi
14:17:48 DEBUG| [stderr] dnsmasq-dhcp: 14547842 sent size: 16 option: 23 dns-server  fd42::1
14:17:48 DEBUG| [stderr] dnsmasq-dhcp: 14547842 sent size:  6 option: 39 FQDN  qemu
14:17:49 DEBUG| [stderr] dnsmasq-dhcp: 14613378 available DHCP range: fd42::10 -- fd42::ff
14:17:49 DEBUG| [stderr] dnsmasq-dhcp: 14613378 client MAC address: 52:54:00:12:34:56
14:17:49 DEBUG| [stderr] dnsmasq-dhcp: 14613378 DHCPSOLICIT(net0) 00:01:00:01:28:3d:04:67:52:54:00:12:34:56 
14:17:49 DEBUG| [stderr] dnsmasq-dhcp: 14613378 DHCPADVERTISE(net0) fd42::200 00:01:00:01:28:3d:04:67:52:54:00:12:34:56 qemu
14:17:49 DEBUG| [stderr] dnsmasq-dhcp: 14613378 requested options: 23:dns-server
14:17:49 DEBUG| [stderr] dnsmasq-dhcp: 14613378 tags: known, dhcpv6, net0
14:17:49 DEBUG| [stderr] dnsmasq-dhcp: 14613378 sent size: 14 option:  1 client-id  00:01:00:01:28:3d:04:67:52:54:00:12:34:56
14:17:49 DEBUG| [stderr] dnsmasq-dhcp: 14613378 sent size: 10 option:  2 server-id  00:03:00:01:b6:fe:38:22:4e:b7
14:17:49 DEBUG| [stderr] dnsmasq-dhcp: 14613378 sent size: 40 option:  3 ia-na  IAID=2066765558 T1=43200 T2=75600
14:17:49 DEBUG| [stderr] dnsmasq-dhcp: 14613378 nest size: 24 option:  5 iaaddr  fd42::200 PL=86400 VL=86400
14:17:49 DEBUG| [stderr] dnsmasq-dhcp: 14613378 sent size:  9 option: 13 status  0 success
14:17:49 DEBUG| [stderr] dnsmasq-dhcp: 14613378 sent size:  1 option:  7 preference  0
14:17:49 DEBUG| [stderr] dnsmasq-dhcp: 14613378 sent size: 16 option: 23 dns-server  fd42::1
14:17:49 DEBUG| [stderr] dnsmasq-dhcp: 14613378 sent size:  6 option: 39 FQDN  qemu
14:17:49 DEBUG| [stderr] dnsmasq-dhcp: 14678914 available DHCP range: fd42::10 -- fd42::ff
14:17:49 DEBUG| [stderr] dnsmasq-dhcp: 14678914 client MAC address: 52:54:00:12:34:56
14:17:49 DEBUG| [stderr] dnsmasq-dhcp: 14678914 DHCPREQUEST(net0) 00:01:00:01:28:3d:04:67:52:54:00:12:34:56 
14:17:49 DEBUG| [stderr] dnsmasq-dhcp: Ignoring domain network for DHCP host name qemu
14:17:49 DEBUG| [stderr] dnsmasq-dhcp: 14678914 DHCPREPLY(net0) fd42::200 00:01:00:01:28:3d:04:67:52:54:00:12:34:56 qemu
14:17:49 DEBUG| [stderr] dnsmasq-dhcp: 
14:17:49 DEBUG| [stderr] 14678914 requested options: 23:dns-server
14:17:49 DEBUG| [stderr] dnsmasq-dhcp: 14678914 tags: known, dhcpv6, net0
14:17:49 DEBUG| [stderr] dnsmasq-dhcp: 14678914 sent size: 14 option:  1 client-id  00:01:00:01:28:3d:04:67:52:54:00:12:34:56
14:17:49 DEBUG| [stderr] dnsmasq-dhcp: 14678914 sent size: 10 option:  2 server-id  00:03:00:01:b6:fe:38:22:4e:b7
14:17:49 DEBUG| [stderr] dnsmasq-dhcp: 14678914 sent size: 40 option:  3 ia-na  IAID=2066765558 T1=43200 T2=75600
14:17:49 DEBUG| [stderr] dnsmasq-dhcp: 14678914 nest size: 24 option:  5 iaaddr  fd42::200 PL=86400 VL=86400
14:17:49 DEBUG| [stderr] dnsmasq-dhcp: 14678914 sent size:  9 option: 13 status  0 success
14:17:49 DEBUG| [stderr] dnsmasq-dhcp: 14678914 sent size: 16 option: 23 dns-server  fd42::1
14:17:49 DEBUG| [stderr] dnsmasq-dhcp: 14678914 sent size:  6 option: 39 FQDN  qemu
14:17:52 DEBUG| [stderr] dnsmasq-dhcp: 14744450 available DHCP range: fd42::10 -- fd42::ff
14:17:52 DEBUG| [stderr] dnsmasq-dhcp: 14744450 vendor class: 343
14:17:52 DEBUG| [stderr] dnsmasq-dhcp: 14744450 client MAC address: 52:54:00:12:34:56
14:17:52 DEBUG| [stderr] dnsmasq-dhcp: 14744450 DHCPREQUEST(net0) 00:01:00:01:28:3d:04:67:52:54:00:12:34:56 
14:17:52 DEBUG| [stderr] dnsmasq-dhcp: 14744450 DHCPREPLY(net0) 00:01:00:01:28:3d:04:67:52:54:00:12:34:56 no addresses available
14:17:52 DEBUG| [stderr] dnsmasq-dhcp: 14744450 requested options: 59:bootfile-url, 60:bootfile-param, 23:dns-server, 
14:17:52 DEBUG| [stderr] dnsmasq-dhcp: 14744450 requested options: 16:vendor-class
14:17:52 DEBUG| [stderr] dnsmasq-dhcp: 14744450 tags: known, dhcpv6, net0
14:17:52 DEBUG| [stderr] dnsmasq-dhcp: 14744450 sent size: 14 option:  1 client-id  00:01:00:01:28:3d:04:67:52:54:00:12:34:56
14:17:52 DEBUG| [stderr] dnsmasq-dhcp: 14744450 sent size: 10 option:  2 server-id  00:03:00:01:b6:fe:38:22:4e:b7
14:17:52 DEBUG| [stderr] dnsmasq-dhcp: 14744450 sent size: 32 option:  3 ia-na  IAID=1917410942 T1=4294967295 T2=4294967295
14:17:52 DEBUG| [stderr] dnsmasq-dhcp: 14744450 nest size: 16 option: 13 status  1 address in use
14:17:52 DEBUG| [stderr] dnsmasq-dhcp: 14744450 sent size: 24 option: 13 status  2 no addresses available

failure ...

14:17:52 DEBUG| [stderr] dnsmasq-dhcp: 14744450 sent size: 34 option: 59 bootfile-url  tftp://[fd42::1]/EFI/BOOT/grub.efi
14:17:52 DEBUG| [stderr] dnsmasq-dhcp: 14744450 sent size: 16 option: 23 dns-server  fd42::1
14:17:52 DEBUG| [stderr] dnsmasq-dhcp: 14744450 sent size:  6 option: 39 FQDN  qemu
14:17:52 DEBUG| [stderr] dnsmasq-dhcp: 14809986 available DHCP range: fd42::10 -- fd42::ff
14:17:52 DEBUG| [stderr] dnsmasq-dhcp: 14809986 vendor class: 343
14:17:52 DEBUG| [stderr] dnsmasq-dhcp: 14809986 client MAC address: 52:54:00:12:34:56
14:17:52 DEBUG| [stderr] dnsmasq-dhcp: 14809986 DHCPSOLICIT(net0) 00:01:00:01:28:3d:04:67:52:54:00:12:34:56 
14:17:52 DEBUG| [stderr] dnsmasq-dhcp: 14809986 DHCPADVERTISE(net0) fd42::201 00:01:00:01:28:3d:04:67:52:54:00:12:34:56 qemu

try ask for an ip again, getting a different one now ...

14:17:52 DEBUG| [stderr] dnsmasq-dhcp: 14809986 requested options: 59:bootfile-url, 60:bootfile-param, 23:dns-server, 
14:17:52 DEBUG| [stderr] dnsmasq-dhcp: 14809986 requested options: 16:vendor-class
14:17:52 DEBUG| [stderr] dnsmasq-dhcp: 14809986 tags: known, dhcpv6, net0
14:17:52 DEBUG| [stderr] dnsmasq-dhcp: 14809986 sent size: 14 option:  1 client-id  00:01:00:01:28:3d:04:67:52:54:00:12:34:56
14:17:52 DEBUG| [stderr] dnsmasq-dhcp: 14809986 sent size: 10 option:  2 server-id  00:03:00:01:b6:fe:38:22:4e:b7
14:17:52 DEBUG| [stderr] dnsmasq-dhcp: 14809986 sent size: 40 option:  3 ia-na  IAID=1917410942 T1=43200 T2=75600
14:17:52 DEBUG| [stderr] dnsmasq-dhcp: 14809986 nest size: 24 option:  5 iaaddr  fd42::201 PL=86400 VL=86400
14:17:52 DEBUG| [stderr] dnsmasq-dhcp: 14809986 sent size:  9 option: 13 status  0 success
14:17:52 DEBUG| [stderr] dnsmasq-dhcp: 14809986 sent size:  1 option:  7 preference  0
14:17:52 DEBUG| [stderr] dnsmasq-dhcp: 14809986 sent size: 34 option: 59 bootfile-url  tftp://[fd42::1]/EFI/BOOT/grub.efi
14:17:52 DEBUG| [stderr] dnsmasq-dhcp: 14809986 sent size: 16 option: 23 dns-server  fd42::1
14:17:52 DEBUG| [stderr] dnsmasq-dhcp: 14809986 sent size:  6 option: 39 FQDN  qemu
14:17:54 DEBUG| [stderr] dnsmasq-dhcp: 14744450 available DHCP range: fd42::10 -- fd42::ff
14:17:54 DEBUG| [stderr] dnsmasq-dhcp: 14744450 vendor class: 343
14:17:54 DEBUG| [stderr] dnsmasq-dhcp: 14744450 client MAC address: 52:54:00:12:34:56
14:17:54 DEBUG| [stderr] dnsmasq-dhcp: 14744450 DHCPREQUEST(net0) 00:01:00:01:28:3d:04:67:52:54:00:12:34:56 
14:17:54 DEBUG| [stderr] dnsmasq-dhcp: 14744450 DHCPREPLY(net0) 00:01:00:01:28:3d:04:67:52:54:00:12:34:56 no addresses available
14:17:54 DEBUG| [stderr] dnsmasq-dhcp: 14744450 requested options: 59:bootfile-url, 60:bootfile-param, 23:dns-server, 
14:17:54 DEBUG| [stderr] dnsmasq-dhcp: 14744450 requested options: 16:vendor-class
14:17:54 DEBUG| [stderr] dnsmasq-dhcp: 14744450 tags: known, dhcpv6, net0
14:17:54 DEBUG| [stderr] dnsmasq-dhcp: 14744450 sent size: 14 option:  1 client-id  00:01:00:01:28:3d:04:67:52:54:00:12:34:56
14:17:54 DEBUG| [stderr] dnsmasq-dhcp: 14744450 sent size: 10 option:  2 server-id  00:03:00:01:b6:fe:38:22:4e:b7
14:17:54 DEBUG| [stderr] dnsmasq-dhcp: 14744450 sent size: 32 option:  3 ia-na  IAID=1917410942 T1=4294967295 T2=4294967295
14:17:54 DEBUG| [stderr] dnsmasq-dhcp: 14744450 nest size: 16 option: 13 status  1 address in use
14:17:54 DEBUG| [stderr] dnsmasq-dhcp: 14744450 sent size: 24 option: 13 status  2 no addresses available

nope.  still nacked by dnsmasq

I raised the issue seen with recovery added as in comment #20 to the dnsmasq-discuss mailing list:
  https://lists.thekelleys.org.uk/pipermail/dnsmasq-discuss/2021q3/015585.html

(In reply to Gerd Hoffmann from comment #20)
> Hmm, trying to improve the error handling doesn't have the intended effect.
> 
> --- a/NetworkPkg/Dhcp6Dxe/Dhcp6Io.c
> +++ b/NetworkPkg/Dhcp6Dxe/Dhcp6Io.c
> @@ -2261,6 +2261,20 @@ Dhcp6HandleReplyMsg (
>        }
>        break;
>  
> +    case Dhcp6StsNoAddrsAvail:
> +      DEBUG ((DEBUG_INFO, "%a: Dhcp6StsNoAddrsAvail (%d)\n", __FUNCTION__,
> +              Instance->IaCb.Ia->State));
> +      if (Instance->IaCb.Ia->State == Dhcp6Requesting) {
> +        //
> +        // dnsmasq changed its mind, try start over
> +        //
> +        Status = Dhcp6InitSolicitMsg (Instance);
> +        if (EFI_ERROR (Status)) {
> +          return  Status;
> +        }
> +      }
> +      break;
> +
>      case Dhcp6StsNotOnLink:
>        if (Instance->IaCb.Ia->State == Dhcp6Confirming) {
>          //
> 

Hi Greg,

I tested this patch and did a traffic capture.
The IP address in the REQUEST happining after recovery is still the initially advertised address.

19	73.362476	fe80::2057:f8ff:fedd:fe3b	fe80::284:edff:fe01:10	DHCPv6	208	Advertise XID: 0x1646c1 CID: 00010001283e92480084ed010010 IAA: 2001::22
22	75.360796	fe80::284:edff:fe01:10	ff02::1:2	DHCPv6	219	Request XID: 0x1546c1 CID: 00010001283e92480084ed010010 IAA: 2001::23 

I think we need to reset more than the "Status" ?

I will attach my traffic capture in a subsequent comment.

Created attachment 1823410 [details]
Ttraffic capture of DHCPv6 traffic with error recovery patch from comment #20

Applying the patch from comment #20 to add error recovery, the traffic capture shows that despite a new address being present in the ADVERTISE message the subsequent REQUEST messages are still requesting the initial address which is leased to the other DHCPv6 client instance.

> I tested this patch and did a traffic capture.
> The IP address in the REQUEST happining after recovery is still the
> initially advertised address.

ACK. Noticed that too meanwhile.

> I think we need to reset more than the "Status" ?

Yep.  Seems edk2 has the initial response cached somewhere and continues reusing that.
Still debugging, stay tuned ...

> Still debugging, stay tuned ...

Ok, found it.  There is one extra level of indirection.

The dhcp6 driver (Dhcp6Dxe) will notify the caller (UefiPxeBcDxe)
about all offers it got, and allows the caller to pick the offer
to be accepted.  Which allows UefiPxeBcDxe to pick the best offer
in case multiple offers did arrive, for example select the one
which has bootfile set.

There are a bunch of notifications (see EFI_DHCP6_EVENT), but there
isn't one for "oops, that offer turned out to be not valid, please
drop it from the list".  So UefiPxeBcDxe continues to ask for the
offer it initially got.

I don't see an easy way out ...

It seems to me there is pretty bad design of DHCP requests. According to first message, client requests first address with some IAID. Dnsmasq responds immediately with DHCPADVERTISE, but client does not wait for it. Instead it requests a new address with different IAID for PXE (!!). This time it waits for it.

After it confirms first address it requested the second time, it continues with attempt to finish the first request only after that. But because sequential assignments are used, this address were already offered the second (now finished) request. I think with demand for sequential assignments, it would advertise first not allocated address. Because they overlap, it succeeds only once. That seems predictable to me.

It is unclear, why it requests address(es) separate way. It seems to me it should just note router advertisement but do not send Solicitation until it knows, whether and what PXE parameters should be sent. Then it should send them only once.

Alternative way might be, delay sending second PXE request until it processes answer and request for original IP. That way, offered IP would change, because the first one were already confirmed.

Gerd, is there strong reason for current way of implementation? Why does it need to request multiple addresses before it even tries to use the first one requested? Fixed ordering would make this problem disappear. Alternative way might be omitting dhcp-sequential-ip (mentioned in comment #16). It might then offer different addresses for the request. If not, that perhaps might be modified. It requests still address solicited the first time, when it was not yet assigned. It did not update the address according to dump in comment #26.

From the RFC it seems the server might send different IP than it got from client request [1]. Would such change work to you? If the prefix is still the same, it might find the same IP it would find on the next Solicit message. I guess someone more experimenced with DHCPv6 might answer such question.

1. https://datatracker.ietf.org/doc/html/rfc8415#section-18.3.2

(In reply to Harald Jensås from comment #26)
> Created attachment 1823410 [details]
> Ttraffic capture of DHCPv6 traffic with error recovery patch from comment #20
> 
> Applying the patch from comment #20 to add error recovery, the traffic
> capture shows that despite a new address being present in the ADVERTISE
> message the subsequent REQUEST messages are still requesting the initial
> address which is leased to the other DHCPv6 client instance.

Can we make this attachment public? It seems there is no any internal information we need to hide. Geert on upstream discuss list [1] requested exactly this. I doubt we can get any real help from upstream without detailed communications. I don't think current public comments are sufficient. IAIDs are not always logged, but can be seen in wireshark. In your original post to upstream (comment #23) you said it is still nacked by the server. But different address than offered were nacked, which is not visible just from dnsmasq logs.

Missing link for comment #33.

1. https://lists.thekelleys.org.uk/pipermail/dnsmasq-discuss/2021q3/015595.html

According to RFC 8415, section 18.2.10.1 [1], start of page 70, it appears correct resolution on client side would be to restart the request with empty addresses. But I doubt Renew [2] or Rebind is correct when such address were just advertised, but never committed for the IAID.

1. https://datatracker.ietf.org/doc/html/rfc8415#section-18.2.10.1
2. https://datatracker.ietf.org/doc/html/rfc8415#section-18.3.4

Created attachment 1823674 [details]
Traffice capture Tianocore edk2-ovmf with Kea

As an experiment I tried kea-dhcp6 in Fedora 34:

2021-09-16 22:43:10.102 INFO  [kea-dhcp6.alloc-engine/11530.139835009403008] ALLOC_ENGINE_V6_HR_ADDR_GRANTED reserved address 2001::20 was assigned to client duid=[00:04:e2:0a:d1:ed:6c:7a:ec:4b:99:d9:4d:a0:8f:6c:26:cc], tid=0x1cf708
2021-09-16 22:43:10.102 INFO  [kea-dhcp6.leases/11530.139835009403008] DHCP6_LEASE_ADVERT duid=[00:04:e2:0a:d1:ed:6c:7a:ec:4b:99:d9:4d:a0:8f:6c:26:cc], tid=0x1cf708: lease for address 2001::20 and iaid=3083853311 will be advertised
2021-09-16 22:43:11.000 INFO  [kea-dhcp6.alloc-engine/11530.139835009403008] ALLOC_ENGINE_V6_HR_ADDR_GRANTED reserved address 2001::20 was assigned to client duid=[00:04:e2:0a:d1:ed:6c:7a:ec:4b:99:d9:4d:a0:8f:6c:26:cc], tid=0x1df708
2021-09-16 22:43:11.000 INFO  [kea-dhcp6.leases/11530.139835009403008] DHCP6_LEASE_ADVERT duid=[00:04:e2:0a:d1:ed:6c:7a:ec:4b:99:d9:4d:a0:8f:6c:26:cc], tid=0x1df708: lease for address 2001::20 and iaid=3068264439 will be advertised
2021-09-16 22:43:11.001 INFO  [kea-dhcp6.alloc-engine/11530.139835009403008] ALLOC_ENGINE_V6_HR_ADDR_GRANTED reserved address 2001::20 was assigned to client duid=[00:04:e2:0a:d1:ed:6c:7a:ec:4b:99:d9:4d:a0:8f:6c:26:cc], tid=0x1ef708

Initially 2001::20 is advertised to both iaid=3083853311 and iaid=3068264439.

2021-09-16 22:43:11.001 INFO  [kea-dhcp6.leases/11530.139835009403008] DHCP6_LEASE_ALLOC duid=[00:04:e2:0a:d1:ed:6c:7a:ec:4b:99:d9:4d:a0:8f:6c:26:cc], tid=0x1ef708: lease for address 2001::20 and iaid=3068264439 has been allocated for 4000 seconds

iaid=3068264439 got the 2001::20 lease

2021-09-16 22:43:15.100 INFO  [kea-dhcp6.alloc-engine/11530.139835009403008] ALLOC_ENGINE_V6_HR_ADDR_GRANTED reserved address 2001::21 was assigned to client duid=[00:04:e2:0a:d1:ed:6c:7a:ec:4b:99:d9:4d:a0:8f:6c:26:cc], tid=0x1ff708
2021-09-16 22:43:15.100 INFO  [kea-dhcp6.leases/11530.139835009403008] DHCP6_LEASE_ALLOC duid=[00:04:e2:0a:d1:ed:6c:7a:ec:4b:99:d9:4d:a0:8f:6c:26:cc], tid=0x1ff708: lease for address 2001::21 and iaid=3083853311 has been allocated for 4000 seconds

2001::21 is assigned, and iaid=3083853311 got that, NOTE that there was no ADVERTISE. The server simply replied: "you can have this address instead".

2021-09-16 22:43:15.100 INFO  [kea-dhcp6.leases/11530.139835009403008] DHCP6_RELEASE_NA duid=[00:04:e2:0a:d1:ed:6c:7a:ec:4b:99:d9:4d:a0:8f:6c:26:cc], tid=0x20f708: binding for address 2001::20 and iaid=3068264439 was released properly
2021-09-16 22:43:16.920 INFO  [kea-dhcp6.leases/11530.139835009403008] DHCP6_RELEASE_NA duid=[00:04:e2:0a:d1:ed:6c:7a:ec:4b:99:d9:4d:a0:8f:6c:26:cc], tid=0x21f708: binding for address 2001::21 and iaid=3083853311 was released properly


Looking at the traffic capture you can see that Kea DHCP6 server does a reply with a different address, from the one in the request. Not setting error flags.

7	4.997525	fe80::5054:ff:fe92:a499	ff02::1:2	DHCPv6	223	Request XID: 0x1ff708 CID: 0004e20ad1ed6c7aec4b99d94da08f6c26cc IAA: 2001::20 
8	4.997914	fe80::5054:ff:fe2d:3c77	fe80::5054:ff:fe92:a499	DHCPv6	182	Reply XID: 0x1ff708 CID: 0004e20ad1ed6c7aec4b99d94da08f6c26cc IAA: 2001::21 


It seems this might be ok based on rfc8415 18.3.2 [1].
"""
   The server MAY assign different addresses and/or delegated prefixes
   to an IA than those included within the IA of the client's Request
   message.
"""


The Kea DHCP6 config I used:
{
  "Dhcp6": {
    "valid-lifetime": 4000,
    "renew-timer": 1000,
    "rebind-timer": 2000,
    "preferred-lifetime": 3000,
    "interfaces-config": {
       "interfaces": [ "enp2s0" ]
    },
    "lease-database": {
      "type": "memfile",
      "persist": true,
      "name": "/var/lib/kea/dhcp6.leases"
    },
    "subnet6": [
      {
        "subnet": "2001::/64",
        "interface": "enp2s0",
        "pools": [
          { 
            "pool": "2001::10-2001::100",
            "option-data": [
              { "name": "bootfile-url", "code": 59, "data": "tftp://[2001::1]/shimx64.efi" }
            ]
          }
        ],
        "reservations": [
          { "duid": "00:04:e2:0a:d1:ed:6c:7a:ec:4b:99:d9:4d:a0:8f:6c:26:cc",
            "ip-addresses": [ "2001::20", "2001::21", "2001::22", "2001::23" ] }
        ]
      }
    ]
  }
}



[1] https://datatracker.ietf.org/doc/html/rfc8415#section-18.3.2

> It is unclear, why it requests address(es) separate way. It seems to me it
> should just note router advertisement but do not send Solicitation until it
> knows, whether and what PXE parameters should be sent. Then it should send
> them only once.

It's two completely separate dhcpv6 client instances.  One created by the
pxe boot driver (that is the one which requests the bootfile url).  The other
created by ipv6 interface configuration code.  The latter is only send in case
the router advertisement says clients should ask for an address via dhcp.
See comment 19 for more details.

> From the RFC it seems the server might send different IP than it got from
> client request [1]. Would such change work to you?

Probably it would, but I don't know for sure.
I happily test patches.

It seems somehow similar situation occurs on bug #1969908 for IPv4. Not sure DHCPv4 should behave the same way.

(In reply to Gerd Hoffmann from comment #38)
> It's two completely separate dhcpv6 client instances.  One created by the
> pxe boot driver (that is the one which requests the bootfile url).  The other
> created by ipv6 interface configuration code.  The latter is only send in
> case
> the router advertisement says clients should ask for an address via dhcp.
> See comment 19 for more details.
> 
I don't understand why it uses separate IPv6 client instances for the same hosts. It requires bigger allocation units, just because it tries to request separate address for each subsystem during boot. All of those at the same time, not sequentially. I think no real system ever requests two separate addresses from the same range. I understand it might be easier to implement without internal coordination. It seems basic cooperation should be done within boot firmware. Why is pxe boot driver separate? I know, it needs some options to request correct boot file. What is purpose of reacting to router advertisement then? It should know it already asked for an address on that interface, so it should reuse any response for PXE boot. It seems like multiple "processes" in boot firmware do communicate between themselves and DHCP server has to solve it for them. I do not think every process on normal system should request address for it communication. Why does boot firmware need that?

There are multiple steps boot firmware has to do. I think they should appear more integrated. I would understand if they were sequential, but not when they run at the same time. But I guess that cannot be changed in RHEL8 lifetime. But definitely one address should be enough for a booting process.

> > From the RFC it seems the server might send different IP than it got from
> > client request [1]. Would such change work to you?
> 
> Probably it would, but I don't know for sure.
> I happily test patches.

Created attachment 1823867 [details]
Traffic capture with dnsmasq patch to reply with new address in request

With the below patch I got dnsmasq to reply with a new address to the request with the already leased address.
This makes dnsmasq behave similar to kea-dhcp6, see comment: #36

I testet this with both static, and dynamic range with "sequential-ip", it seems to work.
The traffic capture attached is with the static only configuration.

If I change the 'dhcp-host' entry in the static config to contain just *one* address, it fails as expected with:
Sep 17 07:09:51 server dnsmasq-dhcp[1841]: 10083164 nest size: 21 option: 13 status  2 address unavailable                                                                                                
Sep 17 07:09:51 server dnsmasq-dhcp[1841]: 10083164 sent size: 24 option: 13 status  2 no addresses available 


Static config
-------------
log-dhcp
port=0
dhcp-range=set:range0,2001::,static,64,10m
dhcp-host=00:84:ed:01:00:10,tag:dhcpv6,client.localdomain,[2001::20],[2001::21],[2001::22],[2001::23]
dhcp-sequential-ip
# dhcpv6s for Client System Architecture Type (61)
dhcp-match=set:efi6,option6:61,0007
dhcp-match=set:efi6,option6:61,0009
dhcp-match=set:efi6,option6:61,0011
dhcp-option=tag:efi6,option6:bootfile-url,tftp://[2001::2]/shimx64.efi

Dynamic config with sequential-ip:
---------------------------------
log-dhcp
port=0

dhcp-range=set:range0,2001::10,2001::100,64,10m
dhcp-sequential-ip
# dhcpv6s for Client System Architecture Type (61)
dhcp-match=set:efi6,option6:61,0007
dhcp-match=set:efi6,option6:61,0009
dhcp-match=set:efi6,option6:61,0011
dhcp-option=tag:efi6,option6:bootfile-url,tftp://[2001::2]/shimx64.efi



diff --git a/src/rfc3315.c b/src/rfc3315.c
index 5c2ff97..90fb77f 100644
--- a/src/rfc3315.c
+++ b/src/rfc3315.c
@@ -847,7 +847,16 @@ static int dhcp6_no_relay(struct state *state, int msg_type, void *inbuff, size_
                memcpy(&req_addr, opt6_ptr(ia_option, 0), IN6ADDRSZ);
                
                if ((c = address6_valid(state->context, &req_addr, tagif, 1)))
-                 config_ok = (config_implies(config, c, &req_addr) != NULL);
+                 if (check_address(state, &req_addr)) {
+                   config_ok = (config_implies(config, c, &req_addr) != NULL);
+                 }
+                 else {
+                       /* If the address is already leased to another DUID/IAID, treat it like
+                          a SOLICIT with rapid commit set. I.e try to assign a different address
+                          if available. */
+                        save_counter(start);
+                        goto request_no_address; 
+                 }
                
                if ((dynamic = address6_available(state->context, &req_addr, tagif, 1)) || c)
                  {

> It requires bigger allocation units, just because it tries to request
> separate address for each subsystem during boot.

Well, dhcpd seems to happily hand out the same ip address multiple
times (as long as the DUID is the same).

> It seems like
> multiple "processes" in boot firmware do communicate between themselves and
> DHCP server has to solve it for them. I do not think every process on normal
> system should request address for it communication. Why does boot firmware
> need that?

With ipv4 the pxe driver needs both ip address and bootfile.
With ipv6 bootfile should be enough thanks to autoconfiguration.

Speculation: Changing UEFI spec is hard, so they fitted ipv6 pxe support into
the existing ipv4 pxe interfaces without changing the underlying workflow.

Looking through the dhcpv6 rfc it looks legit to ask for the bootfile url using
an InfoRequest.  The concept of an InfoRequest (aka stateless configuration)
doesn't exist in dhcpv4 though, so that's how we ended up with the pxe driver
asking for an ipv6 address.

It's not ideal, but I think not fixable without an UEFI spec update.
Which I suspect can easily take months if not years.

Given the code is also shipped in the edk development toolkit for
hardware OEMs I'd expect you can see physical hardware show the
same behavior.

What I did for testing this issue:

IFACE=host0 # change to whatever is used in the environment

ip address add 2620:dead:beef:4::1/64 dev host0

cat << EOF > /etc/dnsmasq.d/bz1998448.conf
log-dhcp
port=0
interface=host0

dhcp-sequential-ip
dhcp-range=::,static
dhcp-match=ipxe,175
# dhcpv6s for Client System Architecture Type (61)
dhcp-match=set:efi6,option6:61,0007
dhcp-match=set:efi6,option6:61,0009
dhcp-match=set:efi6,option6:61,0011
dhcp-userclass=set:ipxe6,iPXE
# Client is PXE booting over EFI without iPXE ROM; send EFI version of iPXE chainloader
dhcp-option=tag:efi6,tag:!ipxe6,option6:bootfile-url,tftp://[2620:dead:beef:4::1]/shimx64.efi

enable-tftp
tftp-root=/tftproot # use /var/lib/tftproot as alternative, tftp-server package

# Use static allocated only, replace with MAC of your client VM
dhcp-host=52:54:00:06:57:c3,tag:dhcpv6,netboot.test,[2620:dead:beef:4::d1],[2620:dead:beef:4::d2],[2620:dead:beef:4::d3],120
EOF

mkdir /tftproot
dnf install -y radvd shim-x64 && cp /boot/efi/EFI/redhat/shimx64.efi /tftproot/ && chmod a+r /tftproot/*.efi

cat << EOF > /etc/radvd.conf
interface host0
{
        AdvSendAdvert on;
        AdvManagedFlag on;
        prefix 2620:dead:beef:4::/64;
};
EOF

systemctl restart dnsmasq radvd

Now try to boot your VM few times. It would fail sometimes without modified version. It should pass always with a new version.

dnsmasq logs each tftp access, so it can be used to verify machine got an address, downloaded it. I kept missing grub.efi to check first step on booting, which is enough. Does not matter IPXE6 boot fails, but it tries needed steps.

Created attachment 1825881 [details]
dnsmasq change proposal

Created attachment 1825882 [details]
option6:client-arch support, optional

Optional option6 support for option6:client-arch,7 and option6:client-interface-id,01:03:01, useful especially for dhcp-match parameter. Not usually sent as requested option.

(In reply to Gerd Hoffmann from comment #42)
> > It requires bigger allocation units, just because it tries to request
> > separate address for each subsystem during boot.
> 
> Well, dhcpd seems to happily hand out the same ip address multiple
> times (as long as the DUID is the same).
> 

I think dhcpd is breaking the DHCPv6 specification when it is doing this.
While it is "helpful" for this usecase, it also means a client that actually want to allocate multiple addresses to the same DUID won't be able to.

Over time I assume ISC will deprecate ISC-DHCP in favor of it's new Kea DHCP implementation.

> > It seems like
> > multiple "processes" in boot firmware do communicate between themselves and
> > DHCP server has to solve it for them. I do not think every process on normal
> > system should request address for it communication. Why does boot firmware
> > need that?
> 
> With ipv4 the pxe driver needs both ip address and bootfile.
> With ipv6 bootfile should be enough thanks to autoconfiguration.
> 
> Speculation: Changing UEFI spec is hard, so they fitted ipv6 pxe support into
> the existing ipv4 pxe interfaces without changing the underlying workflow.
> 
> Looking through the dhcpv6 rfc it looks legit to ask for the bootfile url
> using
> an InfoRequest.  The concept of an InfoRequest (aka stateless configuration)
> doesn't exist in dhcpv4 though, so that's how we ended up with the pxe driver
> asking for an ipv6 address.
> 
> It's not ideal, but I think not fixable without an UEFI spec update.
> Which I suspect can easily take months if not years.
> 

I think it should be a long-term goal to update the UEFI spec.

It is quite unfortunate that UEFI requires IP address from a DHCP server.
It would be a nice improvement to UEFI if it would support address autoconfiguration and using InfoRequest only for the boot file.

Even with managed addresses from DHCP, it would be good if the firmware would:
 1. Configure the interface based on M flag in RA's.
 2. Use InfoRequest for options (i.e bootfile url)

> Given the code is also shipped in the edk development toolkit for
> hardware OEMs I'd expect you can see physical hardware show the
> same behavior.

I can confirm that we do see same behavior with physical hardware.
On the positive side, if the edk development toolkit is improved, the improvements would end up on actual hardware as well.

(In reply to Gerd Hoffmann from comment #42)
> Well, dhcpd seems to happily hand out the same ip address multiple
> times (as long as the DUID is the same).
> 
> With ipv4 the pxe driver needs both ip address and bootfile.
> With ipv6 bootfile should be enough thanks to autoconfiguration.

I do not think DHCP request for bootfile it the problem here. I think main difference between IPv4 and IPv6 is that router announcement may arrive before PXE request. Because firmware reacts on it straight away by sending separate DHCP solicitation request, there may be two simultaneous DHCP sessions for the single host. Can DHCPv4 request multiple times IP address in some case?
> 
> Speculation: Changing UEFI spec is hard, so they fitted ipv6 pxe support into
> the existing ipv4 pxe interfaces without changing the underlying workflow.
> 
> Looking through the dhcpv6 rfc it looks legit to ask for the bootfile url
> using
> an InfoRequest.  The concept of an InfoRequest (aka stateless configuration)
> doesn't exist in dhcpv4 though, so that's how we ended up with the pxe driver
> asking for an ipv6 address.
> 
> It's not ideal, but I think not fixable without an UEFI spec update.
> Which I suspect can easily take months if not years.

Does UEFI spec define, when should be EFI_DHCP6_PROTOCOL.Configure() called and with which options? I think the main problem here is PXE boot and router advertisement reactions are separate, unrelated actions. If all those submodules could first gather requested options and only once actually request address, it would work just fine. Much like on IPv4. It should work also with just InfoRequest, if address handling remained on router announce reaction.

It seems InfoRequest is already part of UEFI 2.7 spec [1], 29.3.2 DHCP6 protocol. I have no idea, how hard would it be using it from the edk firmware code. I guess you know how it is. Can we request changing it for RHEL9, maybe also RHEL 10? Because it always uses release after booting, I think no unusual expectation would be just single address should work for booting over PXE.

> 
> Given the code is also shipped in the edk development toolkit for
> hardware OEMs I'd expect you can see physical hardware show the
> same behavior.

I have checked shortly DHCP packets from Lenovo laptop seem similar. I have no native IPv6 booting configured in my real network, haven't tested this case on real devices.

There are already some uses of InfoRequest on iSCSI and DNS modules [2]. Whereas Configure requests are used from PXE and HTTP boots [3] in addition to Stateful router advertisement reaction. It seems to me all required parts should be already present on edk2 upstream. Just are used different way.

1. https://uefi.org/sites/default/files/resources/UEFI_Spec_2_7.pdf
2. https://github.com/tianocore/edk2/search?q=Dhcp6-%3EInfoRequest
3. https://github.com/tianocore/edk2/search?q=Dhcp6-%3EConfigure

I have checked edk2 a bit. It seems to me EfiDhcp6GetModeData can be used to fetch existing DHCPv6 session. If that exist, the same IAID should be extracted and only EfiDhcp6InfoRequest could be used to fetch missing boot parameters. It could request address in the other case by EfiDhcp6Configure, as it does now.

I think dnsmasq should be fixed anyway, but I filled new bug #2007642 on RHEL9. I think there are already ways to improve current booting without standards update.

(In reply to Harald Jensås from comment #49)
> I think dhcpd is breaking the DHCPv6 specification when it is doing this.
> While it is "helpful" for this usecase, it also means a client that actually
> want to allocate multiple addresses to the same DUID won't be able to.
> 
> Over time I assume ISC will deprecate ISC-DHCP in favor of it's new Kea DHCP
> implementation.
> 

Sure, DHCP client and relay would be deprecated by the end of this year [1]. Server part would be maintained for some longer time, but eventually should be replaced by kea.

1. https://lists.isc.org/pipermail/dhcp-announce/2021-June/000433.html

Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory (dnsmasq bug fix and enhancement update), and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHBA-2022:1839