Bug 1956209

Summary: dhclient -6 -P ppp0 does not complete prefix acquire
Product: [Fedora] Fedora Reporter: udo <udovdh>
Component: dhcpAssignee: Martin Osvald 🛹 <mosvald>
Status: CLOSED EOL QA Contact: Fedora Extras Quality Assurance <extras-qa>
Severity: urgent Docs Contact:
Priority: unspecified    
Version: 34CC: mosvald, pemensik, pzhukov
Target Milestone: ---Keywords: Reopened
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2022-06-08 00:06:46 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:

Description udo 2021-05-03 08:15:57 UTC
Description of problem:
We use dhclient to obtain ipv6 prefix from our ISP.
We see that dhclient keeps handshaking and does not complete.


Version-Release number of selected component (if applicable):
dhcp-client-4.4.2-9.b1.fc34.x86_64

How reproducible:
Have vdsl with pppoE connection up with ISP that supports ipv6 prefix delegation.
Run `dhclient -6 -P ppp0 -d`.
See the handshake continue.
See that we do not continue beyond PREINIT6 phase by dumping environment in dhclient-exit-hooks.

Actual results:
See below.


Expected results:
Prefix acquired, BOUND6 or RENEW6 state reached.


Additional info:
# dhclient -6 -P ppp0 -d
Internet Systems Consortium DHCP Client 4.4.2b1
Copyright 2004-2019 Internet Systems Consortium.
All rights reserved.
For info, please visit https://www.isc.org/software/dhcp/

Listening on Socket/ppp0
Sending on   Socket/ppp0
xid: rand init seed (0x9cfbab24) built using all available interfaces
PRC: Soliciting for leases (INIT).
XMT: Forming Solicit, 0 ms elapsed.
XMT:  X-- IA_PD 00:00:00:00
XMT:  | X-- Request renew in  +3600
XMT:  | X-- Request rebind in +5400
XMT: Solicit on ppp0, interval 1080ms.
XMT: Forming Solicit, 1080 ms elapsed.
XMT:  X-- IA_PD 00:00:00:00
XMT:  | X-- Request renew in  +3600
XMT:  | X-- Request rebind in +5400
XMT: Solicit on ppp0, interval 2220ms.
XMT: Forming Solicit, 3300 ms elapsed.
XMT:  X-- IA_PD 00:00:00:00
XMT:  | X-- Request renew in  +3600
XMT:  | X-- Request rebind in +5400
XMT: Solicit on ppp0, interval 4240ms.
XMT: Forming Solicit, 7550 ms elapsed.
XMT:  X-- IA_PD 00:00:00:00
XMT:  | X-- Request renew in  +3600
XMT:  | X-- Request rebind in +5400
XMT: Solicit on ppp0, interval 8330ms.
^C

At similar time ran tcpdump:

# tcpdump -i ppp0 -v port 546
dropped privs to tcpdump
tcpdump: listening on ppp0, link-type LINUX_SLL (Linux cooked v1), snapshot length 262144 bytes
10:07:16.692661 IP6 (flowlabel 0xf8863, hlim 1, next-header UDP (17) payload length: 60) vuurmuur.dhcpv6-client > ff02::1:2.dhcpv6-server: [udp sum ok] dhcp6 solicit (xid=6fd0c0 (client-ID hwaddr/time type 1 time 394565497 004063f60200) (option-request DNS-server DNS-search-list) (elapsed-time 0) (IA_PD IAID:0 T1:3600 T2:5400))
10:07:16.707444 IP6 (class 0xc0, hlim 64, next-header UDP (17) payload length: 141) fe80::9ecc:83ff:fec6:e7e5.dhcpv6-server > vuurmuur.dhcpv6-client: [udp sum ok] dhcp6 advertise (xid=6fd0c0 (client-ID hwaddr/time type 1 time 394565497 004063f60200) (server-ID vid 0000058339633a63) (IA_PD IAID:0 T1:3600 T2:5760 (IA_PD-prefix 2001:981:a812::/48 pltime:7200 vltime:7200)) (DNS-server resolver.xs4all.nl resolver.xs4all.nl))
10:07:16.707632 IP6 (class 0xc0, hlim 63, next-header UDP (17) payload length: 141) fe80::9ecc:83ff:fec6:e7e5.dhcpv6-server > vuurmuur.dhcpv6-client: [udp sum ok] dhcp6 advertise (xid=6fd0c0 (client-ID hwaddr/time type 1 time 394565497 004063f60200) (server-ID vid 0000058339633a63) (IA_PD IAID:0 T1:3600 T2:5760 (IA_PD-prefix 2001:981:a812::/48 pltime:7200 vltime:7200)) (DNS-server resolver.xs4all.nl resolver.xs4all.nl))
10:07:17.775036 IP6 (flowlabel 0xf8863, hlim 1, next-header UDP (17) payload length: 60) vuurmuur.dhcpv6-client > ff02::1:2.dhcpv6-server: [udp sum ok] dhcp6 solicit (xid=6fd0c0 (client-ID hwaddr/time type 1 time 394565497 004063f60200) (option-request DNS-server DNS-search-list) (elapsed-time 108) (IA_PD IAID:0 T1:3600 T2:5400))
10:07:17.794564 IP6 (class 0xc0, hlim 64, next-header UDP (17) payload length: 141) fe80::9ecc:83ff:fec6:e7e5.dhcpv6-server > vuurmuur.dhcpv6-client: [udp sum ok] dhcp6 advertise (xid=6fd0c0 (client-ID hwaddr/time type 1 time 394565497 004063f60200) (server-ID vid 0000058339633a63) (IA_PD IAID:0 T1:3600 T2:5760 (IA_PD-prefix 2001:981:a812::/48 pltime:7200 vltime:7200)) (DNS-server resolver.xs4all.nl resolver.xs4all.nl))
10:07:17.794892 IP6 (class 0xc0, hlim 63, next-header UDP (17) payload length: 141) fe80::9ecc:83ff:fec6:e7e5.dhcpv6-server > vuurmuur.dhcpv6-client: [udp sum ok] dhcp6 advertise (xid=6fd0c0 (client-ID hwaddr/time type 1 time 394565497 004063f60200) (server-ID vid 0000058339633a63) (IA_PD IAID:0 T1:3600 T2:5760 (IA_PD-prefix 2001:981:a812::/48 pltime:7200 vltime:7200)) (DNS-server resolver.xs4all.nl resolver.xs4all.nl))
10:07:19.998336 IP6 (flowlabel 0xf8863, hlim 1, next-header UDP (17) payload length: 60) vuurmuur.dhcpv6-client > ff02::1:2.dhcpv6-server: [udp sum ok] dhcp6 solicit (xid=6fd0c0 (client-ID hwaddr/time type 1 time 394565497 004063f60200) (option-request DNS-server DNS-search-list) (elapsed-time 330) (IA_PD IAID:0 T1:3600 T2:5400))
10:07:20.013191 IP6 (class 0xc0, hlim 64, next-header UDP (17) payload length: 141) fe80::9ecc:83ff:fec6:e7e5.dhcpv6-server > vuurmuur.dhcpv6-client: [udp sum ok] dhcp6 advertise (xid=6fd0c0 (client-ID hwaddr/time type 1 time 394565497 004063f60200) (server-ID vid 0000058339633a63) (IA_PD IAID:0 T1:3600 T2:5760 (IA_PD-prefix 2001:981:a812::/48 pltime:7200 vltime:7200)) (DNS-server resolver.xs4all.nl resolver.xs4all.nl))
10:07:20.013450 IP6 (class 0xc0, hlim 63, next-header UDP (17) payload length: 141) fe80::9ecc:83ff:fec6:e7e5.dhcpv6-server > vuurmuur.dhcpv6-client: [udp sum ok] dhcp6 advertise (xid=6fd0c0 (client-ID hwaddr/time type 1 time 394565497 004063f60200) (server-ID vid 0000058339633a63) (IA_PD IAID:0 T1:3600 T2:5760 (IA_PD-prefix 2001:981:a812::/48 pltime:7200 vltime:7200)) (DNS-server resolver.xs4all.nl resolver.xs4all.nl))
10:07:24.243585 IP6 (flowlabel 0xf8863, hlim 1, next-header UDP (17) payload length: 60) vuurmuur.dhcpv6-client > ff02::1:2.dhcpv6-server: [udp sum ok] dhcp6 solicit (xid=6fd0c0 (client-ID hwaddr/time type 1 time 394565497 004063f60200) (option-request DNS-server DNS-search-list) (elapsed-time 755) (IA_PD IAID:0 T1:3600 T2:5400))
10:07:24.595880 IP6 (class 0xc0, hlim 64, next-header UDP (17) payload length: 141) fe80::9ecc:83ff:fec6:e7e5.dhcpv6-server > vuurmuur.dhcpv6-client: [udp sum ok] dhcp6 advertise (xid=6fd0c0 (client-ID hwaddr/time type 1 time 394565497 004063f60200) (server-ID vid 0000058339633a63) (IA_PD IAID:0 T1:3600 T2:5760 (IA_PD-prefix 2001:981:a812::/48 pltime:7200 vltime:7200)) (DNS-server resolver.xs4all.nl resolver.xs4all.nl))
10:07:24.596120 IP6 (class 0xc0, hlim 63, next-header UDP (17) payload length: 141) fe80::9ecc:83ff:fec6:e7e5.dhcpv6-server > vuurmuur.dhcpv6-client: [udp sum ok] dhcp6 advertise (xid=6fd0c0 (client-ID hwaddr/time type 1 time 394565497 004063f60200) (server-ID vid 0000058339633a63) (IA_PD IAID:0 T1:3600 T2:5760 (IA_PD-prefix 2001:981:a812::/48 pltime:7200 vltime:7200)) (DNS-server resolver.xs4all.nl resolver.xs4all.nl))
^C

Comment 1 udo 2021-05-03 09:18:56 UTC
BTW:

`man 8 dhclient-script` does not really mention the ipv6 cases, dhclient.d, etc.

Comment 2 udo 2021-05-03 14:18:51 UTC
firewall off does not matter.
We do have active VDSL connection, indicated by ipv4 ping.

Comment 3 udo 2021-05-04 15:29:57 UTC
Questions that come to mind:

What is unacceptable in the dhcp-server responses that apparently reach dhclient? (see `strace`)
Why isn't this logged? It would be helpful to know what is wrong...
Why doesn't -v help here?
How to debug this?

Comment 4 udo 2021-05-09 09:39:06 UTC
Adding log_debug's to any receive-related functions in dhc6.c does not reveal any activity in those funcions.
What is the right spot to check if the packets from the dhcp server actually reach dhclient?

(Although firewall off makes no difference and we have the tcpdump...)

Comment 5 udo 2021-05-09 10:42:24 UTC
What Is ee after adding the log_debugs:

# ./dhclient -6 -P ppp0 -v -d 
dhcpv6_client_assignments
Internet Systems Consortium DHCP Client 4.4.2b1
Copyright 2004-2019 Internet Systems Consortium.
All rights reserved.
For info, please visit https://www.isc.org/software/dhcp/

Listening on Socket/ppp0
Sending on   Socket/ppp0
xid: rand init seed (0x9cfbab24) built using all available interfaces
PRC: Soliciting for leases (INIT).
dhc6_retrans_init
dhc6_rand
do_init6
check_timing6
XMT: Forming Solicit, 0 ms elapsed.
make_client6_options
dhc6_create_iaid
XMT:  X-- IA_PD 00:00:00:00
XMT:  | X-- Request renew in  +3600
XMT:  | X-- Request rebind in +5400
XMT: Solicit on ppp0, interval 1080ms.
dhc6_retrans_advance
dhc6_rand
do_init6
check_timing6
XMT: Forming Solicit, 1080 ms elapsed.
make_client6_options
dhc6_create_iaid
XMT:  X-- IA_PD 00:00:00:00
XMT:  | X-- Request renew in  +3600
XMT:  | X-- Request rebind in +5400
XMT: Solicit on ppp0, interval 2070ms.
dhc6_retrans_advance
dhc6_rand
do_init6
check_timing6
XMT: Forming Solicit, 3150 ms elapsed.
make_client6_options
dhc6_create_iaid
XMT:  X-- IA_PD 00:00:00:00
XMT:  | X-- Request renew in  +3600
XMT:  | X-- Request rebind in +5400
XMT: Solicit on ppp0, interval 4150ms.
dhc6_retrans_advance
dhc6_rand
do_init6
check_timing6
XMT: Forming Solicit, 7310 ms elapsed.
make_client6_options
dhc6_create_iaid
XMT:  X-- IA_PD 00:00:00:00
XMT:  | X-- Request renew in  +3600
XMT:  | X-- Request rebind in +5400
XMT: Solicit on ppp0, interval 8190ms.
dhc6_retrans_advance
dhc6_rand
do_init6
check_timing6
XMT: Forming Solicit, 15500 ms elapsed.
make_client6_options
dhc6_create_iaid
XMT:  X-- IA_PD 00:00:00:00
XMT:  | X-- Request renew in  +3600
XMT:  | X-- Request rebind in +5400
XMT: Solicit on ppp0, interval 16810ms.
dhc6_retrans_advance
dhc6_rand
do_init6
check_timing6
XMT: Forming Solicit, 32320 ms elapsed.
make_client6_options
dhc6_create_iaid
XMT:  X-- IA_PD 00:00:00:00
XMT:  | X-- Request renew in  +3600
XMT:  | X-- Request rebind in +5400
XMT: Solicit on ppp0, interval 32850ms.
dhc6_retrans_advance
dhc6_rand
do_init6
check_timing6
XMT: Forming Solicit, 65170 ms elapsed.
make_client6_options
dhc6_create_iaid
XMT:  X-- IA_PD 00:00:00:00
XMT:  | X-- Request renew in  +3600
XMT:  | X-- Request rebind in +5400
XMT: Solicit on ppp0, interval 67850ms.
dhc6_retrans_advance
dhc6_rand
dhc6_rand
^C
#

While running tcpdump partly through this sequence:

# tcpdump -i ppp0 -v port 546
dropped privs to tcpdump
tcpdump: listening on ppp0, link-type LINUX_SLL (Linux cooked v1), snapshot length 262144 bytes
12:39:28.452817 IP6 (flowlabel 0x0133d, hlim 1, next-header UDP (17) payload length: 60) vuurmuur.dhcpv6-client > ff02::1:2.dhcpv6-server: [udp sum ok] dhcp6 solicit (xid=99c6e1 (client-ID hwaddr/time type 1 time 394565497 004063f60200) (option-request DNS-server DNS-search-list) (elapsed-time 3232) (IA_PD IAID:0 T1:3600 T2:5400))
12:39:28.468153 IP6 (class 0xc0, hlim 64, next-header UDP (17) payload length: 141) fe80::9ecc:83ff:fec6:e7e5.dhcpv6-server > vuurmuur.dhcpv6-client: [udp sum ok] dhcp6 advertise (xid=99c6e1 (client-ID hwaddr/time type 1 time 394565497 004063f60200) (server-ID vid 0000058339633a63) (IA_PD IAID:0 T1:3600 T2:5760 (IA_PD-prefix 2001:981:a812::/48 pltime:7200 vltime:7200)) (DNS-server 2001:888:0:6::66 resolver.xs4all.nl))
12:40:01.305491 IP6 (flowlabel 0x0133d, hlim 1, next-header UDP (17) payload length: 60) vuurmuur.dhcpv6-client > ff02::1:2.dhcpv6-server: [udp sum ok] dhcp6 solicit (xid=99c6e1 (client-ID hwaddr/time type 1 time 394565497 004063f60200) (option-request DNS-server DNS-search-list) (elapsed-time 6517) (IA_PD IAID:0 T1:3600 T2:5400))
12:40:01.320604 IP6 (class 0xc0, hlim 64, next-header UDP (17) payload length: 141) fe80::9ecc:83ff:fec6:e7e5.dhcpv6-server > vuurmuur.dhcpv6-client: [udp sum ok] dhcp6 advertise (xid=99c6e1 (client-ID hwaddr/time type 1 time 394565497 004063f60200) (server-ID vid 0000058339633a63) (IA_PD IAID:0 T1:3600 T2:5760 (IA_PD-prefix 2001:981:a812::/48 pltime:7200 vltime:7200)) (DNS-server 2001:888:0:6::66 resolver.xs4all.nl))
^C
4 packets captured
#

The ipv6 firwall was emptied beforehand:

# ip6tables -L -v -n -x
Chain INPUT (policy DROP 211 packets, 57041 bytes)
    pkts      bytes target     prot opt in     out     source               destination         

Chain FORWARD (policy DROP 97 packets, 8216 bytes)
    pkts      bytes target     prot opt in     out     source               destination         

Chain OUTPUT (policy ACCEPT 244 packets, 43209 bytes)
    pkts      bytes target     prot opt in     out     source               destination         

Chain BLOCK (0 references)
    pkts      bytes target     prot opt in     out     source               destination         

Chain CHECK (0 references)
    pkts      bytes target     prot opt in     out     source               destination         

Chain LDROP (0 references)
    pkts      bytes target     prot opt in     out     source               destination         

Chain LOG-FORWARD (0 references)
    pkts      bytes target     prot opt in     out     source               destination         

Chain LOG-INPUT (0 references)
    pkts      bytes target     prot opt in     out     source               destination         

Chain LOG-OUTPUT (0 references)
    pkts      bytes target     prot opt in     out     source               destination         


So waht is to be fixed here?

Comment 6 udo 2021-05-19 15:31:02 UTC
I was playing around with the IPv6 side of the ethernet interface that is the connection to the vdsl modem, and thus carries the PPPoE connection, etc.
I removed IPv6 from the ethernet interface and also from the vlan interface over this ethernet. 
At this point ppp0 still has IPv6 link address.
After restarting pppd etc the box received dhcp responses again.

Comment 7 udo 2021-05-24 05:02:14 UTC
No, the change for the good did not persist.
Currently we see no dhcp-server replies processed by dhclient.

I do not understand why it worked and now why it stopped working.


UDP packet with dhcp-server reply comes in, is going to FORWARD ip6tables rule and then does not reach dhclient.
As dhclient is local, why does the UDP go to the FORWARD ip6tables rule?

We have a ppp interface:
# ip -6 a s dev ppp0
20: ppp0: <POINTOPOINT,MULTICAST,NOARP,UP,LOWER_UP> mtu 1492 qdisc cbq state UNKNOWN group default qlen 3
    inet6 fe80::c5d5:e942:39c7:7eb7 peer fe80::9ecc:83ff:fec6:e7e5/128 scope link 
       valid_lft forever preferred_lft forever

We have dhclient listening at ppp0:
# lsof -p 4066992 -n
COMMAND      PID USER   FD   TYPE             DEVICE SIZE/OFF     NODE NAME
dhclient 4066992 root  cwd    DIR              254,0     4096    40961 /root
dhclient 4066992 root  rtd    DIR              254,0     4096        2 /
dhclient 4066992 root  txt    REG              254,2  2018144   141553 /usr/sbin/dhclient
dhclient 4066992 root  mem    REG              254,2    53728    22104 /usr/lib64/libnss_files-2.33.so
dhclient 4066992 root  mem    REG              254,2  1913544    21939 /usr/lib64/libc-2.33.so
dhclient 4066992 root  mem    REG              254,2    32696    30196 /usr/lib64/libcap-ng.so.0.0.0
dhclient 4066992 root  mem    REG              254,2   842360    30776 /usr/lib64/ld-2.33.so
dhclient 4066992 root    0u   CHR              136,4      0t0        7 /dev/pts/4 (deleted)
dhclient 4066992 root    1u   CHR              136,4      0t0        7 /dev/pts/4 (deleted)
dhclient 4066992 root    2u   CHR              136,4      0t0        7 /dev/pts/4 (deleted)
dhclient 4066992 root    3u  unix 0x000000001f2593f7      0t0 16525445 type=DGRAM (UNCONNECTED)
dhclient 4066992 root    4w   REG              254,4       64      251 /var/lib/dhclient/dhclient6.leases
dhclient 4066992 root    5w  FIFO                0,8      0t0 16525446 pipe
dhclient 4066992 root    6u  IPv6           16524541      0t0      UDP [fe80::c5d5:e942:39c7:7eb7]:dhcpv6-client 

That appears to be all correct.

Then the packets that come in:
# tcpdump -i ppp0 -vn port 546
dropped privs to tcpdump
tcpdump: listening on ppp0, link-type LINUX_SLL (Linux cooked v1), snapshot length 262144 bytes
06:53:09.236781 IP6 (flowlabel 0x7f0d8, hlim 1, next-header UDP (17) payload length: 60) fe80::c5d5:e942:39c7:7eb7.dhcpv6-client > ff02::1:2.dhcpv6-server: [udp sum ok] dhcp6 solicit (xid=b68ba1 (client-ID hwaddr/time type 1 time 394565497 004063f60200) (option-request DNS-server DNS-search-list) (elapsed-time 65535) (IA_PD IAID:0 T1:3600 T2:5400))
06:53:09.469530 IP6 (class 0xc0, hlim 64, next-header UDP (17) payload length: 141) fe80::9ecc:83ff:fec6:e7e5.dhcpv6-server > fe80::c5d5:e942:39c7:7eb7.dhcpv6-client: [udp sum ok] dhcp6 advertise (xid=b68ba1 (client-ID hwaddr/time type 1 time 394565497 004063f60200) (server-ID vid 0000058339633a63) (IA_PD IAID:0 T1:3600 T2:5760 (IA_PD-prefix 2001:981:a812::/48 pltime:7200 vltime:7200)) (DNS-server 2001:888:0:6::66 2001:888:0:9::99))
06:53:09.469756 IP6 (class 0xc0, hlim 63, next-header UDP (17) payload length: 141) fe80::9ecc:83ff:fec6:e7e5.dhcpv6-server > fe80::c5d5:e942:39c7:7eb7.dhcpv6-client: [udp sum ok] dhcp6 advertise (xid=b68ba1 (client-ID hwaddr/time type 1 time 394565497 004063f60200) (server-ID vid 0000058339633a63) (IA_PD IAID:0 T1:3600 T2:5760 (IA_PD-prefix 2001:981:a812::/48 pltime:7200 vltime:7200)) (DNS-server 2001:888:0:6::66 2001:888:0:9::99))
^C

Appear to be addressed correctly, to the dhclient interface.

So why doesn't dhclient receive?

Comment 8 udo 2022-02-15 12:30:22 UTC
Things work well after a fresh reboot.
But do not when pppd and thus dhclient are restarted.
Even when firewall is off.

Comment 9 Ben Cotton 2022-05-12 16:15:47 UTC
This message is a reminder that Fedora Linux 34 is nearing its end of life.
Fedora will stop maintaining and issuing updates for Fedora Linux 34 on 2022-06-07.
It is Fedora's policy to close all bug reports from releases that are no longer
maintained. At that time this bug will be closed as EOL if it remains open with a
'version' of '34'.

Package Maintainer: If you wish for this bug to remain open because you
plan to fix it in a currently maintained version, change the 'version' 
to a later Fedora Linux version.

Thank you for reporting this issue and we are sorry that we were not 
able to fix it before Fedora Linux 34 is end of life. If you would still like 
to see this bug fixed and are able to reproduce it against a later version 
of Fedora Linux, you are encouraged to change the 'version' to a later version
prior to this bug being closed.

Comment 10 Ben Cotton 2022-06-08 00:06:46 UTC
Fedora Linux 34 entered end-of-life (EOL) status on 2022-06-07.

Fedora Linux 34 is no longer maintained, which means that it
will not receive any further security or bug fix updates. As a result we
are closing this bug.

If you can reproduce this bug against a currently maintained version of
Fedora please feel free to reopen this bug against that version. If you
are unable to reopen this bug, please file a new report against the
current release.

Thank you for reporting this bug and we are sorry it could not be fixed.