[DHCP_RELAY] [IPv6] [202012] Failed to bind socket to link local ipv6 address #11431

vivekrnv · 2022-07-13T02:08:51Z

Description

When started, dhcp6relay tries to bind the socket to ipv6 link local address.
However, in rare scenarios, there might be a race condition b/w the IPv6 device in the kernel becoming oper up and binding the socket to the iface
If the former doesn't happen before the latter the socket bind fails.
There is a retry mechanism in the dhcp6relay which tries for 6 times before giving up but it doesn't seem to be sufficient

Steps to reproduce the issue:

I couldn't repro in manually but is seen during the po/test_po_update.py test and on 202012 image

py.test pc/test_po_update.py --inventory="../ansible/inventory,../ansible/veos" --host-pattern r-tigris-04 --module-path ../ansible/library/ --testbed r-tigris-04-t0-64 --testbed_file ../ansible/testbed.csv --allow_recover --assert plain --log-cli-level debug --show-capture=no -ra --showlocals --topology t0,any,util --skip_sanity

Describe the results you received:

Jul 12 04:11:43.497934 r-tigris-04 WARNING dhcp_relay#dhcp6relay: Retry #1 to bind to sockets on interface Vlan1000
Jul 12 04:11:48.499708 r-tigris-04 WARNING dhcp_relay#dhcp6relay: Retry #2 to bind to sockets on interface Vlan1000
Jul 12 04:11:53.647696 r-tigris-04 WARNING dhcp_relay#dhcp6relay: Retry #3 to bind to sockets on interface Vlan1000
Jul 12 04:11:58.727958 r-tigris-04 WARNING dhcp_relay#dhcp6relay: Retry #4 to bind to sockets on interface Vlan1000
Jul 12 04:12:03.896864 r-tigris-04 WARNING dhcp_relay#dhcp6relay: Retry #5 to bind to sockets on interface Vlan1000
Jul 12 04:12:59.730663 r-tigris-04 WARNING dhcp_relay#dhcp6relay: Retry #6 to bind to sockets on interface Vlan1000
Jul 12 04:13:04.730744 r-tigris-04 ERR dhcp_relay#dhcp6relay: bind: Failed to bind socket to link local ipv6 address on interface Vlan1000 after 6 retries with Success

Describe the results you expected:

Error log should not be seen and dhcp6relay should wait until the iface is ready

Output of `show version`:

(paste your output here)

Output of `show techsupport`:

(paste your output here or download and attach the file here )

Analysis:

Jul 12 04:10:56.971640 r-tigris-04 NOTICE root: Started swss service...
Jul 12 04:10:56.995802 r-tigris-04 NOTICE root: Starting syncd service...
Jul 12 04:10:57.417270 r-tigris-04 NOTICE root: Starting Firmware update procedure
Jul 12 04:11:25.196599 r-tigris-04 NOTICE root: Firmware update procedure ended
Jul 12 04:11:10.724675 r-tigris-04 INFO kernel: [   30.370004] IPv6: ADDRCONF(NETDEV_UP): Vlan1000: link is not ready
Jul 12 04:11:25.751675 r-tigris-04 .INFO systemd[1]: Started syncd service
Jul 12 04:11:25.755073 r-tigris-04 INFO systemd[1]: Starting DHCP relay container...
Jul 12 04:11:31.982029 r-tigris-04 INFO dhcp_relay#/supervisord: start Waiting until interface Vlan1000 is ready...
Jul 12 04:11:32.073738 r-tigris-04 INFO dhcp_relay#/supervisord: start Interface Vlan1000 is ready!

Jul 12 04:11:43.497934 r-tigris-04 WARNING dhcp_relay#dhcp6relay: Retry #1 to bind to sockets on interface Vlan1000
Jul 12 04:11:48.499708 r-tigris-04 WARNING dhcp_relay#dhcp6relay: Retry #2 to bind to sockets on interface Vlan1000
Jul 12 04:11:53.647696 r-tigris-04 WARNING dhcp_relay#dhcp6relay: Retry #3 to bind to sockets on interface Vlan1000
Jul 12 04:11:58.727958 r-tigris-04 WARNING dhcp_relay#dhcp6relay: Retry #4 to bind to sockets on interface Vlan1000
Jul 12 04:12:03.896864 r-tigris-04 WARNING dhcp_relay#dhcp6relay: Retry #5 to bind to sockets on interface Vlan1000
Jul 12 04:12:50.097094 r-tigris-04 NOTICE swss#orchagent: :- addVlan: Create an empty VLAN Vlan1000 vid:1000
Jul 12 04:12:50.102353 r-tigris-04 NOTICE swss#orchagent: :- addVlanMember: Add member Ethernet108 to VLAN Vlan1000 vid:1000 pid100000000132a
.....
......
Jul 12 04:12:50.315249 r-tigris-04 NOTICE swss#orchagent: :- addVlanMember: Add member Ethernet96 to VLAN Vlan1000 vid:1000 pid10000000012a6
Jul 12 04:12:59.730663 r-tigris-04 WARNING dhcp_relay#dhcp6relay: Retry #6 to bind to sockets on interface Vlan1000
Jul 12 04:13:04.730744 r-tigris-04 ERR dhcp_relay#dhcp6relay: bind: Failed to bind socket to link local ipv6 address on interface Vlan1000 after 6 retries with Success
Jul 12 04:13:13.072675 r-tigris-04 INFO kernel: [  152.759749] IPv6: ADDRCONF(NETDEV_CHANGE): Vlan1000: link becomes ready

Firstly, i don't completely understand reason in the delay for the link local address to appear on Vlan1000 netdev. BTW, this is assigned/controlled by kernel. Not managed by SONiC.

Now given that this happens (although very rarely), dhcp6relay should be robust enough to handle this. just doing "six" retries is not a good solution.

Another interesting observation here is that the diff between retry 5 and 6, the time diff should've been 5 sec but it's almost 40 sec. It's likely because of getifaddr call being extremely slow sometimes. There are a few instances elsewhere reported on the slowness of this system call

Additional information you deem important (e.g. issue happens only occasionally):

syslog.gz

The text was updated successfully, but these errors were encountered:

kellyyeh · 2022-07-25T17:08:41Z

Hi @vivekrnv, this PR has fixed interface binding issue #10712, a retry mechanism is added to check for interface's ipv6 global and link-local addresses before binding. Closing the issue

dgsudharsan · 2022-07-25T17:16:06Z

Hi @kellyyeh We are seeing this in spite of the fix @vivekrnv can provide more details

kellyyeh · 2022-07-25T17:18:26Z

@vivekrnv Are both global and link-local addresses available for the interface?

vivekrnv · 2022-07-25T17:29:57Z

Hi @kellyyeh, dhcp6relay failed to bind even after 6 retries here. https://github.com/sonic-net/sonic-dhcp-relay/blob/master/src/relay.cpp#L438 . I think bind_ll_addr variable is itself false here and which means getifaddrs did not return the IPv6 Link Local address in its linked list.

This seems weird since the retry mechanism waits for almost 5 secs between every try and i.e. 30 secs overall. I would've expected the Link local address to be a part of the kernel data structures by then.

vivekrnv · 2022-07-25T19:10:06Z

@vivekrnv Are both global and link-local addresses available for the interface?

Had the bind to global address failed, i would've seen this log https://github.com/sonic-net/sonic-dhcp-relay/blob/master/src/relay.cpp#L434 i suppose. Since, i haven't, i'm assuming bind to global address did not fail

kellyyeh · 2022-07-25T20:52:22Z

@vivekrnv what's the cause for the missing ipv6 link local address on interface? Six retries should be enough for the interface to come up and addresses to be available
Can you check that while the binding/retries fail, the interface is up and has an ipv6 link local address

vivekrnv · 2022-07-25T21:09:04Z

@vivekrnv what's the cause for the missing ipv6 link local address on interface? Six retries should be enough for the interface to come up and addresses to be available Can you check that while the binding/retries fail, the interface is up and has an ipv6 link local address

I agree that six retries should be good enough, but i've no clue as to why it isn't available. It's hard to repro actually and is only seen during boot. I kinda have other priorities now so i can't get that info immediately.

But i've noticed this, this script, https://github.com/Azure/sonic-buildimage/blob/master/dockers/docker-dhcp-relay/wait_for_intf.sh.j2 only checks for IPv4 prefixes. Shouldn't it also check for IPv6 prefixes?

yxieca · 2022-07-25T22:45:13Z

@vivekrnv That is a great suggestion. however, we do need to be careful here. I think we do need to know if we have IPv6 and/or IPv4 configuration for the wait_for_intf.sh script so that it can wait for the right things to show up.

dprital · 2022-07-26T11:44:43Z

@yxieca - Can you please share the PR that fix this issue ?

vivekrnv · 2022-07-27T23:46:44Z

@vivekrnv That is a great suggestion. however, we do need to be careful here. I think we do need to know if we have IPv6 and/or IPv4 configuration for the wait_for_intf.sh script so that it can wait for the right things to show up.

Yup, i agree. We check the STATE_DB to determine if the state is up. I'm not sure if that can be used for IPv6 Link local addresses though. If i'm not wrong, a IPv6 link local address is automatically assigned to netdev object by the kernel (or it is probably controlled by SDK, i'm not certain here) after the creation of Vlan here https://github.com/Azure/sonic-swss/blob/master/cfgmgr/vlanmgr.cpp#L122

vivekrnv · 2022-09-28T06:12:29Z

@yxieca

root@sonic:/home/admin# config vlan add 20
root@sonic:/home/admin# ip addr show Vlan20
231: Vlan20@Bridge: <NO-CARRIER,BROADCAST,MULTICAST,UP> mtu 9100 qdisc noqueue state LOWERLAYERDOWN group default qlen 1000
    link/ether 1c:34:da:1d:42:00 brd ff:ff:ff:ff:ff:ff
root@sonic:/home/admin# config vlan member add 20 Ethernet0
root@sonic:/home/admin# ip addr show Vlan20
231: Vlan20@Bridge: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 9100 qdisc noqueue state UP group default qlen 1000
    link/ether 1c:34:da:1d:42:00 brd ff:ff:ff:ff:ff:ff
    inet6 fe80::1e34:daff:fe1d:4200/64 scope link
       valid_lft forever preferred_lft forever

The link local address is added to the vlan iface after a member is added to it. I guess kernel adds the link local address only after a member is added

Also, the info is not populated in STATE_DB and so how would you suggest in updating this script https://github.com/sonic-net/sonic-buildimage/blob/202205/dockers/docker-dhcp-relay/wait_for_intf.sh.j2 to check for this interface before starting the dhcp6relay

yxieca · 2022-09-28T20:40:53Z

@vivekrnv are you going to add a fix to address this issue?

vivekrnv · 2022-09-28T22:12:31Z

@vivekrnv are you going to add a fix to address this issue?

The fix i thought of adding is to add a check to the wait_for_intf.sh script to wait until the link local address is assigned to the Vlan Iface. And as i've mentioned in the above comment, it's not populated in the STATE_DB and thus has to find other ways.

But i guess @kellyyeh should take it up if she can

jcaiMR · 2022-10-04T01:14:23Z

@kellyyeh Since binding operation is critical to us, is it possible we set SO_REUSEADDR for binding socket. With this we can avoid some case that LLA already bind by other unknown app and still keep dhcpv6 relay work.

kellyyeh · 2022-10-04T17:12:35Z

@jcaiMR dhcpv6 server needs to know the lla for address assignment, so link local is a must in our case

…k local addr (#12273) - Why I did it Fixes #11431 - How I did it dhcp6relay binds to ipv6 addresses configured on these vlan interfaces Thus check if they are ready before launching dhcp6relay - How to verify it Unit Tests Tested on a live device Signed-off-by: Vivek Reddy Karri <vkarri@nvidia.com>

kellyyeh closed this as completed Jul 25, 2022

kellyyeh linked a pull request Jul 25, 2022 that will close this issue

[dhcp6relay] Add retry mechanism for binding socket to interface ipv6 addresses #10712

Merged

6 tasks

dgsudharsan reopened this Jul 25, 2022

liat-grozovik added Issue for 202012 Issue for 202205 labels Jul 28, 2022

yxieca added the Triaged this issue has been triaged label Aug 17, 2022

yxieca assigned kellyyeh Sep 28, 2022

vivekrnv mentioned this issue Oct 5, 2022

[DHCP_RELAY] Updated wait_for_intf.sh to wait for ipv6 global and link local addr #12273

Merged

7 tasks

liat-grozovik closed this as completed in #12273 Oct 12, 2022

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[DHCP_RELAY] [IPv6] [202012] Failed to bind socket to link local ipv6 address #11431

[DHCP_RELAY] [IPv6] [202012] Failed to bind socket to link local ipv6 address #11431

vivekrnv commented Jul 13, 2022 •

edited

Loading

kellyyeh commented Jul 25, 2022

dgsudharsan commented Jul 25, 2022

kellyyeh commented Jul 25, 2022

vivekrnv commented Jul 25, 2022

vivekrnv commented Jul 25, 2022

kellyyeh commented Jul 25, 2022

vivekrnv commented Jul 25, 2022

yxieca commented Jul 25, 2022

dprital commented Jul 26, 2022

vivekrnv commented Jul 27, 2022

vivekrnv commented Sep 28, 2022 •

edited

Loading

yxieca commented Sep 28, 2022

vivekrnv commented Sep 28, 2022 •

edited

Loading

jcaiMR commented Oct 4, 2022

kellyyeh commented Oct 4, 2022

[DHCP_RELAY] [IPv6] [202012] Failed to bind socket to link local ipv6 address #11431

[DHCP_RELAY] [IPv6] [202012] Failed to bind socket to link local ipv6 address #11431

Comments

vivekrnv commented Jul 13, 2022 • edited Loading

Description

Steps to reproduce the issue:

Describe the results you received:

Describe the results you expected:

Output of show version:

Output of show techsupport:

Analysis:

Additional information you deem important (e.g. issue happens only occasionally):

kellyyeh commented Jul 25, 2022

dgsudharsan commented Jul 25, 2022

kellyyeh commented Jul 25, 2022

vivekrnv commented Jul 25, 2022

vivekrnv commented Jul 25, 2022

kellyyeh commented Jul 25, 2022

vivekrnv commented Jul 25, 2022

yxieca commented Jul 25, 2022

dprital commented Jul 26, 2022

vivekrnv commented Jul 27, 2022

vivekrnv commented Sep 28, 2022 • edited Loading

yxieca commented Sep 28, 2022

vivekrnv commented Sep 28, 2022 • edited Loading

jcaiMR commented Oct 4, 2022

kellyyeh commented Oct 4, 2022

vivekrnv commented Jul 13, 2022 •

edited

Loading

Output of `show version`:

Output of `show techsupport`:

vivekrnv commented Sep 28, 2022 •

edited

Loading

vivekrnv commented Sep 28, 2022 •

edited

Loading