bosh agent may enter endless loop of restart after restarting network

Question

bosh agent may enter endless loop of restart after restarting network

Closed this issue 4 years ago · 9 comments

During bosh agent start up, after invoking systemctl restart systemd-networkd shell command to restart network https://github.com/cloudfoundry/bosh-agent/blob/master/platform/net/ubuntu_net_manager.go#L134, it immediately validates if the required ip addresses have been bound to the interfaces https://github.com/cloudfoundry/bosh-agent/blob/master/platform/net/ip/interface_addresses_validator.go#L21.

During network restart, there is a short period of time in which no ip address is bound to the interface eth1 or eth0. As the network restart shell command is invoked asynchronously, there is a high probability to hit the error https://github.com/cloudfoundry/bosh-agent/blob/master/platform/net/ip/interface_addresses_validator.go#L32 when doing the validation. Then bosh agent will exit with that error and restart again. And then it will likely repeat the process - restart network, validate ip addresses, hit the error and restart bosh agent again and again... The only chance to break the loop is that the network restart shell command is lucky enough to finish before the validation so that the validation can succeed.

In our environment, especially for the VMs that have static ip configured, it often takes tens of minutes or an hour to start the bosh agent. And sometimes the bosh agent drops into endless loop of restart.

I think there should be some retry mechanism in the validation. If the validation fails, it should retry for some time, not just exit and restart bosh agent.

Answer 1 · 2019-12-03T05:13:45.000Z

We have created an issue in Pivotal Tracker to manage this:

https://www.pivotaltracker.com/story/show/170068245

The labels on this github issue will be updated when the story is started.

Answer 2 · 2019-12-03T17:06:38.000Z

The CLI is invoked synchronously - I don't see a call to RunComplexCommandAsync.

The implementation is https://github.com/cloudfoundry/bosh-linux-stemcell-builder/blob/master/stemcell_builder/stages/bosh_go_agent/apply.sh#L56

As --no-block isn't specified, systemctl start's behaviour is "the job will be verified, enqueued and systemctl will wait until the unit's start-up is completed"

It sounds like IP addresses are not allocated as part of systemd-networkd's "start-up"?

Answer 3 · 2019-12-03T17:09:19.000Z

If that's the case, maybe restart_networking should include a call to https://www.freedesktop.org/software/systemd/man/systemd-networkd-wait-online.service.html#

Answer 4 · 2019-12-03T19:05:17.000Z

@gu-bin can you share logs demonstrating this problem? I created a deployment with static IPs and network configuration took a fraction of a second.

Answer 5 · 2019-12-04T03:36:25.000Z

@xtreme-conor-nosal
See bosh-agent-current.log for bosh agent log. You can see the following errors that make bosh agent to restart multiple times:

2019-12-04_02:18:48.60346 [main] 2019/12/04 02:18:48 ERROR - Agent exited with error: Running bootstrap: Setting up networking: Validating static network configuration: Validating network interface 'eth1' IP addresses, no interface configured with that name

It's caused by no ip address bound to eth1.

To monitor the ip addresses bound to the interfaces during systemctl restart systemd-networkd, I opened two terminals for the VM. The binary addr built from addr.go is used to monitor continuously. addr.go simulates part of the bosh agent validation behavior.

In terminal#1, launch ./addr 0.5
In terminal#2, launch systemctl restart systemd-networkd
In terminal#1, ctrl+C to stop the monitoring

addr.log is the output of ./addr 0.5. You can see no address bound to the interfaces as indicated in

addrs:
[]

More specific:
No ip address is bound to eth1 from
2019-12-04 02:40:37.48802852 +0000 UTC m=+2.280465142
to
2019-12-04 02:40:37.507600346 +0000 UTC m=+2.300036806

No ip address is bound to eth0 from
2019-12-04 02:40:37.509194293 +0000 UTC m=+2.301630847
to
2019-12-04 02:40:37.521256749 +0000 UTC m=+2.313693315

If the bosh agent validation hit this period of time, it will throw the above error and restart.

addr.log
bosh-agent-current.log
addr.go.txt
(It's not supported to upload .go file. So just change the file name to .txt)

Answer 6 · 2019-12-04T15:47:21.000Z

After running:

cat << EOF  > /etc/systemd/system/systemd-networkd.service.d/10-debug.conf
[Service]
Environment=SYSTEMD_LOG_LEVEL=debug
EOF
systemctl daemon-reload
journalctl -b -u systemd-networkd -f &
echo restarting
systemctl restart systemd-networkd

it looks like the interface always has an IP when it comes up, but removes it when renewing the DHCP lease. The lease renewal appears to be asynchronous from networkd bringing up the interface, so it sometimes happens before or after networkd completes.

DHCP lease during network service restart

Dec 04 15:28:18 7c05b9ae-0457-4b6f-8756-13d116e6da5f systemd[1]: Starting Network Service...
Dec 04 15:28:18 7c05b9ae-0457-4b6f-8756-13d116e6da5f systemd-networkd[22455]: Failed to open configuration file '/etc/systemd/networkd.conf': No such file or directory
Dec 04 15:28:18 7c05b9ae-0457-4b6f-8756-13d116e6da5f systemd-networkd[22455]: timestamp of '/etc/systemd/network' changed
Dec 04 15:28:18 7c05b9ae-0457-4b6f-8756-13d116e6da5f systemd-networkd[22455]: eth0: Flags change: +UP +LOWER_UP +RUNNING +MULTICAST +BROADCAST
Dec 04 15:28:18 7c05b9ae-0457-4b6f-8756-13d116e6da5f systemd-networkd[22455]: eth0: Link 2 added
Dec 04 15:28:18 7c05b9ae-0457-4b6f-8756-13d116e6da5f systemd-networkd[22455]: eth0: udev initialized link
Dec 04 15:28:18 7c05b9ae-0457-4b6f-8756-13d116e6da5f systemd-networkd[22455]: eth0: Saved original MTU: 1460
Dec 04 15:28:18 7c05b9ae-0457-4b6f-8756-13d116e6da5f systemd-networkd[22455]: lo: Flags change: +LOOPBACK +UP +LOWER_UP +RUNNING
Dec 04 15:28:18 7c05b9ae-0457-4b6f-8756-13d116e6da5f systemd-networkd[22455]: lo: Link 1 added
Dec 04 15:28:18 7c05b9ae-0457-4b6f-8756-13d116e6da5f systemd-networkd[22455]: lo: udev initialized link
Dec 04 15:28:18 7c05b9ae-0457-4b6f-8756-13d116e6da5f systemd-networkd[22455]: lo: Saved original MTU: 0
Dec 04 15:28:18 7c05b9ae-0457-4b6f-8756-13d116e6da5f systemd-networkd[22455]: eth0: Adding address: 10.0.255.11/32 (valid for 23h 58min 59s)
Dec 04 15:28:18 7c05b9ae-0457-4b6f-8756-13d116e6da5f systemd-networkd[22455]: lo: Adding address: 169.254.0.2/32 (valid forever)
Dec 04 15:28:18 7c05b9ae-0457-4b6f-8756-13d116e6da5f systemd-networkd[22455]: lo: Adding address: 127.0.0.1/8 (valid forever)
Dec 04 15:28:18 7c05b9ae-0457-4b6f-8756-13d116e6da5f systemd-networkd[22455]: Enumeration completed
Dec 04 15:28:18 7c05b9ae-0457-4b6f-8756-13d116e6da5f systemd-networkd[22455]: eth0: Link state is up-to-date
Dec 04 15:28:18 7c05b9ae-0457-4b6f-8756-13d116e6da5f systemd-networkd[22455]: eth0: found matching network '/etc/systemd/network/10_eth0.network'
Dec 04 15:28:18 7c05b9ae-0457-4b6f-8756-13d116e6da5f systemd-networkd[22455]: LLDP: Started LLDP client
Dec 04 15:28:18 7c05b9ae-0457-4b6f-8756-13d116e6da5f systemd-networkd[22455]: eth0: Started LLDP.
Dec 04 15:28:18 7c05b9ae-0457-4b6f-8756-13d116e6da5f systemd-networkd[22455]: eth0: Acquiring DHCPv4 lease
Dec 04 15:28:18 7c05b9ae-0457-4b6f-8756-13d116e6da5f systemd-networkd[22455]: DHCP CLIENT (0xf037e2e4): STARTED on ifindex 2
Dec 04 15:28:18 7c05b9ae-0457-4b6f-8756-13d116e6da5f systemd-networkd[22455]: DHCP CLIENT (0xf037e2e4): DISCOVER
Dec 04 15:28:18 7c05b9ae-0457-4b6f-8756-13d116e6da5f systemd-networkd[22455]: lo: Link state is up-to-date
Dec 04 15:28:18 7c05b9ae-0457-4b6f-8756-13d116e6da5f systemd-networkd[22455]: lo: Unmanaged
Dec 04 15:28:18 7c05b9ae-0457-4b6f-8756-13d116e6da5f systemd-networkd[22455]: Ignoring option DHCP option 119 while parsing.
Dec 04 15:28:18 7c05b9ae-0457-4b6f-8756-13d116e6da5f systemd-networkd[22455]: DHCP CLIENT (0xf037e2e4): OFFER
Dec 04 15:28:18 7c05b9ae-0457-4b6f-8756-13d116e6da5f systemd-networkd[22455]: DHCP CLIENT (0xf037e2e4): REQUEST (requesting)
Dec 04 15:28:18 7c05b9ae-0457-4b6f-8756-13d116e6da5f systemd-networkd[22455]: eth0: Removing address: 10.0.255.11/32 (valid for 23h 58min 59s)
Dec 04 15:28:18 7c05b9ae-0457-4b6f-8756-13d116e6da5f systemd-networkd[22455]: Ignoring option DHCP option 119 while parsing.
Dec 04 15:28:18 7c05b9ae-0457-4b6f-8756-13d116e6da5f systemd-networkd[22455]: DHCP CLIENT (0xf037e2e4): ACK
Dec 04 15:28:18 7c05b9ae-0457-4b6f-8756-13d116e6da5f systemd-networkd[22455]: DHCP CLIENT (0xf037e2e4): lease expires in 23h 59min 58s
Dec 04 15:28:18 7c05b9ae-0457-4b6f-8756-13d116e6da5f systemd-networkd[22455]: DHCP CLIENT (0xf037e2e4): T2 expires in 20h 59min 57s
Dec 04 15:28:18 7c05b9ae-0457-4b6f-8756-13d116e6da5f systemd-networkd[22455]: DHCP CLIENT (0xf037e2e4): T1 expires in 11h 59min 59s
Dec 04 15:28:18 7c05b9ae-0457-4b6f-8756-13d116e6da5f systemd-networkd[22455]: eth0: DHCPv4 address 10.0.255.11/32 via 10.0.0.1
Dec 04 15:28:18 7c05b9ae-0457-4b6f-8756-13d116e6da5f systemd-networkd[22455]: eth0: Setting MTU: 1460
Dec 04 15:28:18 7c05b9ae-0457-4b6f-8756-13d116e6da5f systemd-networkd[22455]: eth0: Setting transient hostname: 'vm-05c04d11-8ed9-4efb-431a-f0db0b1c20a0.c.cf-bosh-king.internal'
Dec 04 15:28:18 7c05b9ae-0457-4b6f-8756-13d116e6da5f systemd-networkd[22455]: eth0: Updating address: 10.0.255.11/32 (valid for 1d)
Dec 04 15:28:18 7c05b9ae-0457-4b6f-8756-13d116e6da5f systemd-networkd[22455]: eth0: Configured
Dec 04 15:28:18 7c05b9ae-0457-4b6f-8756-13d116e6da5f systemd[1]: Started Network Service.

DHCP lease after network service restarted

Dec 04 15:32:09 7c05b9ae-0457-4b6f-8756-13d116e6da5f systemd[1]: Stopped Network Service.
Dec 04 15:32:09 7c05b9ae-0457-4b6f-8756-13d116e6da5f systemd[1]: Starting Network Service...
Dec 04 15:32:09 7c05b9ae-0457-4b6f-8756-13d116e6da5f systemd-networkd[22528]: Failed to open configuration file '/etc/systemd/networkd.conf': No such file or directory
Dec 04 15:32:09 7c05b9ae-0457-4b6f-8756-13d116e6da5f systemd-networkd[22528]: timestamp of '/etc/systemd/network' changed
Dec 04 15:32:09 7c05b9ae-0457-4b6f-8756-13d116e6da5f systemd-networkd[22528]: eth0: Flags change: +UP +LOWER_UP +RUNNING +MULTICAST +BROADCAST
Dec 04 15:32:09 7c05b9ae-0457-4b6f-8756-13d116e6da5f systemd-networkd[22528]: eth0: Link 2 added
Dec 04 15:32:09 7c05b9ae-0457-4b6f-8756-13d116e6da5f systemd-networkd[22528]: eth0: udev initialized link
Dec 04 15:32:09 7c05b9ae-0457-4b6f-8756-13d116e6da5f systemd-networkd[22528]: eth0: Saved original MTU: 1460
Dec 04 15:32:09 7c05b9ae-0457-4b6f-8756-13d116e6da5f systemd-networkd[22528]: lo: Flags change: +LOOPBACK +UP +LOWER_UP +RUNNING
Dec 04 15:32:09 7c05b9ae-0457-4b6f-8756-13d116e6da5f systemd-networkd[22528]: lo: Link 1 added
Dec 04 15:32:09 7c05b9ae-0457-4b6f-8756-13d116e6da5f systemd-networkd[22528]: lo: udev initialized link
Dec 04 15:32:09 7c05b9ae-0457-4b6f-8756-13d116e6da5f systemd-networkd[22528]: lo: Saved original MTU: 0
Dec 04 15:32:09 7c05b9ae-0457-4b6f-8756-13d116e6da5f systemd-networkd[22528]: eth0: Adding address: 10.0.255.11/32 (valid for 23h 56min 10s)
Dec 04 15:32:09 7c05b9ae-0457-4b6f-8756-13d116e6da5f systemd-networkd[22528]: lo: Adding address: 169.254.0.2/32 (valid forever)
Dec 04 15:32:09 7c05b9ae-0457-4b6f-8756-13d116e6da5f systemd-networkd[22528]: lo: Adding address: 127.0.0.1/8 (valid forever)
Dec 04 15:32:09 7c05b9ae-0457-4b6f-8756-13d116e6da5f systemd-networkd[22528]: Enumeration completed
Dec 04 15:32:09 7c05b9ae-0457-4b6f-8756-13d116e6da5f systemd[1]: Started Network Service.
Dec 04 15:32:09 7c05b9ae-0457-4b6f-8756-13d116e6da5f systemd-networkd[22528]: eth0: Link state is up-to-date
Dec 04 15:32:09 7c05b9ae-0457-4b6f-8756-13d116e6da5f systemd-networkd[22528]: eth0: found matching network '/etc/systemd/network/10_eth0.network'
Dec 04 15:32:09 7c05b9ae-0457-4b6f-8756-13d116e6da5f systemd-networkd[22528]: LLDP: Started LLDP client
Dec 04 15:32:09 7c05b9ae-0457-4b6f-8756-13d116e6da5f systemd-networkd[22528]: eth0: Started LLDP.
Dec 04 15:32:09 7c05b9ae-0457-4b6f-8756-13d116e6da5f systemd-networkd[22528]: eth0: Acquiring DHCPv4 lease
Dec 04 15:32:09 7c05b9ae-0457-4b6f-8756-13d116e6da5f systemd-networkd[22528]: DHCP CLIENT (0xd1ca8c6b): STARTED on ifindex 2
Dec 04 15:32:09 7c05b9ae-0457-4b6f-8756-13d116e6da5f systemd-networkd[22528]: DHCP CLIENT (0xd1ca8c6b): DISCOVER
Dec 04 15:32:09 7c05b9ae-0457-4b6f-8756-13d116e6da5f systemd-networkd[22528]: lo: Link state is up-to-date
Dec 04 15:32:09 7c05b9ae-0457-4b6f-8756-13d116e6da5f systemd-networkd[22528]: lo: Unmanaged
Dec 04 15:32:09 7c05b9ae-0457-4b6f-8756-13d116e6da5f systemd-networkd[22528]: Ignoring option DHCP option 119 while parsing.
Dec 04 15:32:09 7c05b9ae-0457-4b6f-8756-13d116e6da5f systemd-networkd[22528]: DHCP CLIENT (0xd1ca8c6b): OFFER
Dec 04 15:32:09 7c05b9ae-0457-4b6f-8756-13d116e6da5f systemd-networkd[22528]: DHCP CLIENT (0xd1ca8c6b): REQUEST (requesting)
Dec 04 15:32:09 7c05b9ae-0457-4b6f-8756-13d116e6da5f systemd-networkd[22528]: eth0: Removing address: 10.0.255.11/32 (valid for 23h 56min 10s)
Dec 04 15:32:09 7c05b9ae-0457-4b6f-8756-13d116e6da5f systemd-networkd[22528]: Ignoring option DHCP option 119 while parsing.
Dec 04 15:32:09 7c05b9ae-0457-4b6f-8756-13d116e6da5f systemd-networkd[22528]: DHCP CLIENT (0xd1ca8c6b): ACK
Dec 04 15:32:09 7c05b9ae-0457-4b6f-8756-13d116e6da5f systemd-networkd[22528]: DHCP CLIENT (0xd1ca8c6b): lease expires in 23h 59min 58s
Dec 04 15:32:09 7c05b9ae-0457-4b6f-8756-13d116e6da5f systemd-networkd[22528]: DHCP CLIENT (0xd1ca8c6b): T2 expires in 20h 59min 59s
Dec 04 15:32:09 7c05b9ae-0457-4b6f-8756-13d116e6da5f systemd-networkd[22528]: DHCP CLIENT (0xd1ca8c6b): T1 expires in 11h 59min 59s
Dec 04 15:32:09 7c05b9ae-0457-4b6f-8756-13d116e6da5f systemd-networkd[22528]: eth0: DHCPv4 address 10.0.255.11/32 via 10.0.0.1
Dec 04 15:32:09 7c05b9ae-0457-4b6f-8756-13d116e6da5f systemd-networkd[22528]: eth0: Setting MTU: 1460
Dec 04 15:32:09 7c05b9ae-0457-4b6f-8756-13d116e6da5f systemd-networkd[22528]: eth0: Setting transient hostname: 'vm-05c04d11-8ed9-4efb-431a-f0db0b1c20a0.c.cf-bosh-king.internal'
Dec 04 15:32:09 7c05b9ae-0457-4b6f-8756-13d116e6da5f systemd-networkd[22528]: eth0: Updating address: 10.0.255.11/32 (valid for 1d)
Dec 04 15:32:09 7c05b9ae-0457-4b6f-8756-13d116e6da5f systemd-networkd[22528]: eth0: Configured

Answer 7 · 2019-12-11T23:39:24.000Z

I'm also surprised that the agent continues to restart the network. Theoretically, we're only supposed to be executing restart-networking if and only if we've changed the network configuration that we write out.

It does feel appropriate to add some retry logic though.

Answer 8 · 2020-01-09T21:42:26.000Z

I added retry logic to this validation step, waiting up to 10 seconds until it fails. I cherry-picked the commit onto the branch feeding into xenial 621.x stemcells as well.

Commits:

develop - 40b2f35
2.268.x (621.x stemcell) - 8d60e69

Looking forward to hearing if this helps.

Answer 9 · 2021-03-03T15:31:02.000Z

Closing as this seems to have helped