ec2: zesty tempfile sandbox dhclient.pid file can't be created

Bug Description

=== Begin SRU Template ===
[Impact]
Ec2 instances could hit race condition with tempdir removal where dhclient doesn't write a pidfile and DataSourceEc2Local hits a traceback trying to read that non-existent pidfile. This traceback causes the instance to fallback and get discovered in init-network stage as DataSourceEc2. The thrashing costs instances a couple extra seconds to boot while re-discovering in a different stage.

[Test Case]

# Launch instance under test
$ for release in xenial zesty artful; do
echo "Handling $release";
launch-ec2 --series $release;
ssh ubuntu@<ec2-address> cat /run/cloud-init/result.json;
ssh ubuntu@<ec2-address> grep Trace /var/log/cloud-init.log;
ssh ubuntu@<ec2-address> sudo sed 's/ $release / $release-proposed /' /etc/apt/sources.list;
ssh ubuntu@<ec2-address> sudo apt update;
ssh ubuntu@<ec2-address> sudo apt install cloud-init;
# Show upgrade without restart doesn't break
ssh ubuntu@<ec2-address> sudo cloud-init init;
# Show clean install doesn't break
ssh ubuntu@<ec2-address> 'sudo rm -rf /var/log/cloud-init* /var/lib/cloud; sudo reboot'
ssh ubuntu@<ec2-address> 'sudo cat /run/cloud-init/result.json
ssh ubuntu@<ec2-address> 'sudo grep Trace /var/log/cloud-init*';
# Asssert no intermittent tracebacks from dhcp_discovery and no leaked dhcpclients;
ssh ubuntu@<ec2-address> "sudo python3 -c 'from cloudinit.net.dhcp import maybe_perform_dhcp_discovery; maybe_perform_dhcp_discovery()";
sudo ps -afe |grep dhclient;
done

[Regression Potential]
Regression would still result in Tracebacks in DataSourceEc2Local which would cause cloud-init to fallback to DataSourceEc2 in init-network stage.

[Other Info]
Upstream commit at
https://git.launchpad.net/cloud-init/commit/?id=7acc9e68f
=== End SRU Template ===

=== Original Description ===

Saw an issue once on EC2 zesty image with 17.1.41 during SRU testing.

Looks like we hit an inability to create the pid file (from syslog)

#### syslog
Nov 30 04:20:35 ip-10-0-20-176 cloud-init[440]: Cloud-init v. 17.1 running 'init-local' at 2017年11月30日 04:20:32 +0000. Up 7.16 seconds.
Nov 30 04:20:35 ip-10-0-20-176 cloud-init[440]: 2017年11月30日 04:20:32,768 - util.py[WARNING]: Getting data from <class 'cloudinit.sources.DataSourceEc2.DataSourceEc2Local'> failed
Nov 30 04:20:35 ip-10-0-20-176 dhclient[669]: Can't create /var/tmp/cloud-init/cloud-init-dhcp-hnatdvwi/dhclient.pid: No such file or directory

#### end syslog

A traceback when trying to read the temporary pid file that was created by our dhclient run during Ec2Local setup. Maybe we exited out of the dhcp run before we could read the pid file?

...
2017年11月30日 04:20:32,738 - util.py[DEBUG]: Running command ['ip', 'link', 'set', 'dev', 'eth0', 'up'] with allowed return codes [0] (shell=False, capture=True)
2017年11月30日 04:20:32,744 - util.py[DEBUG]: Running command ['/var/tmp/cloud-init/cloud-init-dhcp-hnatdvwi/dhclient', '-1', '-v', '-lf', '/var/tmp/cloud-init/cloud-init-dhcp-hnatdvwi/dhcp.leases', '-pf', '/var/tmp/cloud-init/cloud-init-dhcp-hnatdvwi/dhclient.pid', 'eth0', '-sf', '/bin/true'] with allowed return codes [0] (shell=False, capture=True)
2017年11月30日 04:20:32,768 - util.py[DEBUG]: Reading from /var/tmp/cloud-init/cloud-init-dhcp-hnatdvwi/dhclient.pid (quiet=False)
2017年11月30日 04:20:32,768 - handlers.py[DEBUG]: finish: init-local/search-Ec2Local: FAIL: no local data found from DataSourceEc2Local
2017年11月30日 04:20:32,768 - util.py[WARNING]: Getting data from <class 'cloudinit.sources.DataSourceEc2.DataSourceEc2Local'> failed
2017年11月30日 04:20:32,768 - util.py[DEBUG]: Getting data from <class 'cloudinit.sources.DataSourceEc2.DataSourceEc2Local'> failed
Traceback (most recent call last):
File "/usr/lib/python3/dist-packages/cloudinit/sources/__init__.py", line 332, in find_source
if s.get_data():
File "/usr/lib/python3/dist-packages/cloudinit/sources/DataSourceEc2.py", line 378, in get_data
return super(DataSourceEc2Local, self).get_data()
File "/usr/lib/python3/dist-packages/cloudinit/sources/DataSourceEc2.py", line 100, in get_data
self.fallback_interface)
File "/usr/lib/python3/dist-packages/cloudinit/net/dhcp.py", line 57, in maybe_perform_dhcp_discovery
return dhcp_discovery(dhclient_path, nic, tdir)
File "/usr/lib/python3/dist-packages/cloudinit/net/dhcp.py", line 124, in dhcp_discovery
pid = int(util.load_file(pid_file).strip())
File "/usr/lib/python3/dist-packages/cloudinit/util.py", line 1257, in load_file
with open(fname, 'rb') as ifh:
FileNotFoundError: [Errno 2] No such file or directory: '/var/tmp/cloud-init/cloud-init-dhcp-hnatdvwi/dhclient.pid'

cloud-init log from Ec2Local failure to read dhclient.pid file

More detail:
this also happens on previous 17.1.27, we just never tried to read that pidfile to act on it.

Nov 30 04:54:32 ip-10-0-20-176 dhclient[683]: Can't create /var/tmp/cloud-init/cloud-init-dhcp-zlfb5hsr/dhclient.pid: No such file or directory

Validated it doesn't happen on Artful. with 17.1.27 or 17.1.41

In further testing it is a timing thing with our tempdirectory being removed before dhclient attempts to write the actual pidfile.

sudo python3 -c 'from cloudinit.net.dhcp import maybe_perform_dhcp_discovery; maybe_perform_dhcp_discovery()'

This fails 100% of the time in zesty and artful emitting "Can't create dhclient[3296]: Can't create /var/tmp/cloud-init/.../dhclient.pid"

If I add a sleep(0.000001) in cloudinit/net/dhcp.py on line 123 just after the sandbox_dhclient_cmd, no pidfile write errors are produced by dhclient in /var/log/syslog.

Alternatively we could just have a busy wait there and only exit the tempdir context once we know we have a pid file and can clean ourselves up.

while not os.path.exists(pid_file):
pass

This affectively causes Ec2Local to fail and we fall back to Ec2 in the init-network stage. It slows down ec2 instance boots a bit, but cloud-init will still function on ec2.

OK. So dhclient is fun.

Background info
* we run dhclient like this:
-1 (try to get an ip address only once exit fail on fail).
-v (verbose)
-lf <tmpdir>/dhcp.leases
-pf <tmpdir>/pid
<interface>
-sf /bin/true
* dhclient.c source [1]

I'm pretty sure this is what is happening here.
1. when daemonizing, dhclient does not write its pidfile immediately (line 971). Instead it waits until it does "go_daemon" (line 4203). This does make some sense as it goes daemon by forking and the new process staying around.
2. on successful acquisition of address, cloud-init is removing the temp dir and looking for the pid before the fork()'ed process writes it.
2a. on failure, i think a pid is probably not written at all. I don't think we're handling the possible ProcessExecutionError that would be raised if dhclient returned non-zero.

Heres a suggestion for a fix
http://paste.ubuntu.com/26081537/

Another option would be for cloud-init to invoke dhclient with '-d' (do not background) which would avoid the background process entirely. The '-1' would allow it to exit on failure. Then on success we'd have to have the script file signal somehow that it was done or possibly just kill its parent.

The last option of course is to write a dhcp client in python :), which is looking more and more appealing.

[1] https://git.launchpad.net/~usd-import-team/ubuntu/+source/isc-dhcp/tree/client/dhclient.c

Interesting thing smoser is that dhclient doesn't actually return an error code where there are problems. Not the following when I hit selinux issues with /sbin/dhclient instead of our /tmp/dhclient

http://pastebin.ubuntu.com/26082502/ line 7 8 16 and 17 all point to busted dhclient, but supb wouldn't error for us in this case because retcode is 0

>>> from cloudinit.util import subp
>>> subp(['sudo', '/sbin/dhclient', '-1', '-v', '-lf', '/home/ubuntu/dhcp.leases', '-pf', '/home/ubuntu/dhclient.pid', 'eth0', '-sf', '/bin/true'])
('', "Internet Systems Consortium DHCP Client 4.3.3\nCopyright 2004-2015 Internet Systems Consortium.\nAll rights reserved.\nFor info, please visit https://www.isc.org/software/dhcp/\n\ncan't create /home/ubuntu/dhcp.leases: Permission denied\nexecve (/bin/true, ...): Permission denied\nListening on LPF/eth0/0a:42:9a:bd:dc:34\nSending on LPF/eth0/0a:42:9a:bd:dc:34\nSending on Socket/fallback\nDHCPDISCOVER on eth0 to 255.255.255.255 port 67 interval 3 (xid=0x9e09e019)\nDHCPREQUEST of 10.0.20.170 on eth0 to 255.255.255.255 port 67 (xid=0x19e0099e)\nDHCPOFFER of 10.0.20.170 from 10.0.20.1\nDHCPACK of 10.0.20.170 from 10.0.20.1\nexecve (/bin/true, ...): Permission denied\ncan't create /home/ubuntu/dhcp.leases: Permission denied\nbound to 10.0.20.170 -- renewal in 1636 seconds.\n")

Even parsing error output isn't an option (although we could catch SELinux type errors) because dhclient doesn't emit the 'Can't create pidfile' message until after the background process was forked.

So, I'll take part of your suggested patch, but I think us parsing or try/except handling of subp output is going to end up fruitless in this or other cases as dhclient doesn't really seem to exit in error upon the errors we care about.

This bug was fixed in the package cloud-init - 17.1-46-g7acc9e68-0ubuntu1

---------------
cloud-init (17.1-46-g7acc9e68-0ubuntu1) bionic; urgency=medium

* New upstream snapshot.
- ec2: Fix sandboxed dhclient background process cleanup.
[Chad Smith] (LP: #1735331)
- tests: NoCloudKVMImage do not modify the original local cache image.
- tests: Enable bionic in integration tests. [Joshua Powers]
- tests: Use apt-get to install a deb so that depends get resolved.
- sysconfig: Correctly render dns and dns search info.
[Ryan McCabe] (LP: #1705804)

-- Scott Moser <email address hidden> 2017年11月30日 21:59:55 -0500

An upload of cloud-init to artful-proposed has been rejected from the upload queue for the following reason: "to reupload with -v".

Hello Chad, or anyone else affected,

Accepted cloud-init into artful-proposed. The package will build now and be available at https://launchpad.net/ubuntu/+source/cloud-init/17.1-46-g7acc9e68-0ubuntu1~17.10.1 in a few hours, and then in the -proposed repository.

Please help us by testing this new package. See https://wiki.ubuntu.com/Testing/EnableProposed for documentation on how to enable and use -proposed.Your feedback will aid us getting this update out to other Ubuntu users.

If this package fixes the bug for you, please add a comment to this bug, mentioning the version of the package you tested and change the tag from verification-needed-artful to verification-done-artful. If it does not fix the bug for you, please add a comment stating that, and change the tag to verification-failed-artful. In either case, details of your testing will help us make a better decision.

Further information regarding the verification process can be found at https://wiki.ubuntu.com/QATeam/PerformingSRUVerification . Thank you in advance!

Hello Chad, or anyone else affected,

Accepted cloud-init into zesty-proposed. The package will build now and be available at https://launchpad.net/ubuntu/+source/cloud-init/17.1-46-g7acc9e68-0ubuntu1~17.04.1 in a few hours, and then in the -proposed repository.

Please help us by testing this new package. See https://wiki.ubuntu.com/Testing/EnableProposed for documentation on how to enable and use -proposed.Your feedback will aid us getting this update out to other Ubuntu users.

If this package fixes the bug for you, please add a comment to this bug, mentioning the version of the package you tested and change the tag from verification-needed-zesty to verification-done-zesty. If it does not fix the bug for you, please add a comment stating that, and change the tag to verification-failed-zesty. In either case, details of your testing will help us make a better decision.

Further information regarding the verification process can be found at https://wiki.ubuntu.com/QATeam/PerformingSRUVerification . Thank you in advance!

Thanks Steve. Attached are the verification logs for ec2 instance asserting that this bug is fixed.

# Launch instance under test
$ for release in xenial zesty artful; do
echo "Handling $release";
launch-ec2 --series $release;
ssh ubuntu@<ec2-address> cat /run/cloud-init/result.json;
ssh ubuntu@<ec2-address> grep Trace /var/log/cloud-init.log;
ssh ubuntu@<ec2-address> sudo sed 's/ $release / $release-proposed /' /etc/apt/sources.list;
ssh ubuntu@<ec2-address> sudo apt update;
ssh ubuntu@<ec2-address> sudo apt install cloud-init;
# Show upgrade without restart doesn't break
ssh ubuntu@<ec2-address> sudo cloud-init init;
# Show clean install doesn't break
ssh ubuntu@<ec2-address> 'sudo rm -rf /var/log/cloud-init* /var/lib/cloud; sudo reboot'
ssh ubuntu@<ec2-address> 'sudo cat /run/cloud-init/result.json
ssh ubuntu@<ec2-address> 'sudo grep Trace /var/log/cloud-init*';
# Asssert no intermittent tracebacks from dhcp_discovery and no leaked dhcpclients;
ssh ubuntu@<ec2-address> "sudo python3 -c 'from cloudinit.net.dhcp import maybe_perform_dhcp_discovery; maybe_perform_dhcp_discovery()";
sudo ps -afe |grep dhclient;

done

[Regression Potential]
Regression would still result in Tracebacks in DataSourceEc2Local which would cause cloud-init to fallback to DataSourceEc2 in init-network stage.

[Other Info]
Upstream commit at
https://git.launchpad.net/cloud-init/commit/?id=7acc9e68

=== End SRU Template ===

=== SRU Verification output ===

### EC2 Xenial upgrade and fresh install test
ubuntu@ip-10-0-20-54:~$ sudo vi /etc/apt/sources.list
ubuntu@ip-10-0-20-54:~$ sudo apt update
...
ubuntu@ip-10-0-20-54:~$ cat /run/cloud-init/result.json
{
"v1": {
"datasource": "DataSourceEc2Local",
"errors": []
}
}
ubuntu@ip-10-0-20-54:~$ grep Trace /var/log/cloud-init.log
ubuntu@ip-10-0-20-54:~$ sudo apt install cloud-init
Setting up cloud-init (17.1-46-g7acc9e68-0ubuntu1~16.04.1) ...
ubuntu@ip-10-0-20-54:~$ sudo cloud-init init
Cloud-init v. 17.1 running 'init' at 2017年12月02日 04:10:13 +0000. Up 167.09 seconds.
ci-info: ++++++++++++++++++++++++++++++++++++++++++++++Net device info++++++++++++++++++++++++++++++++++++++++++++++
ci-info: +--------+------+--------------------------------------------+---------------+--------+-------------------+
ci-info: | Device | Up | Address | Mask | Scope | Hw-Address |
ci-info: +--------+------+--------------------------------------------+---------------+--------+-------------------+
ci-info: | eth0 | True | 10.0.20.54 | 255.255.255.0 | . | 0a:a4:58:cb:62:8c |
ci-info: | eth0 | True | 2600:1f16:dc8:a120:73c6:9626:9c1d:2ecf/128 | . | global | 0a:a4:58:cb:62:8c |
ci-info: | lo | True | 127.0.0.1 | 255.0.0.0 | . | . |
ci-info: | lo | True | ::1/128 | . | host | . |
ci-info: +--------+------+--------------------------------------------+---------------+--------+-------------------+
ci-info: ++++++++++++++++++++++++++++Rou...

This bug was fixed in the package cloud-init - 17.1-46-g7acc9e68-0ubuntu1~16.04.1

---------------
cloud-init (17.1-46-g7acc9e68-0ubuntu1~16.04.1) xenial-proposed; urgency=medium

* New upstream snapshot.
- ec2: Fix sandboxed dhclient background process cleanup.
(LP: #1735331)
- tests: NoCloudKVMImage do not modify the original local cache image.
- tests: Enable bionic in integration tests. [Joshua Powers]
- tests: Use apt-get to install a deb so that depends get resolved.
- sysconfig: Correctly render dns and dns search info.
[Ryan McCabe]

cloud-init (17.1-41-g76243487-0ubuntu1~16.04.1) xenial-proposed; urgency=medium

* debian/cloud-init.templates: Fix capitilazation in 'AliYun'
(LP: #1728186)
* New upstream snapshot (LP: #1733653)
- integration test: replace curtin test ppa with cloud-init test ppa.
- EC2: Fix bug using fallback_nic and metadata when restoring from cache.
- EC2: Kill dhclient process used in sandbox dhclient.
- ntp: fix configuration template rendering for openSUSE and SLES
- centos: Provide the failed #include url in error messages
- Catch UrlError when #include'ing URLs [Andrew Jorgensen]
- hosts: Fix openSUSE and SLES setup for /etc/hosts and clarify docs.
[Robert Schweikert]
- rh_subscription: Perform null checks for enabled and disabled repos.
[Dave Mulford]
- Improve warning message when a template is not found.
[Robert Schweikert]
- Replace the temporary i9n.brickies.net with i9n.cloud-init.io.
- Azure: don't generate network configuration for SRIOV devices
- tests: address some minor feedback missed in last merge.
- tests: integration test cleanup and full pass of nocloud-kvm.
- Gentoo: chmod +x on all files in sysvinit/gentoo/
[Carlos Konstanski]

-- Chad Smith <email address hidden> 2017年12月01日 10:05:01 -0700

The verification of the Stable Release Update for cloud-init has completed successfully and the package has now been released to -updates. Subsequently, the Ubuntu Stable Release Updates Team is being unsubscribed and will not receive messages about this bug report. In the event that you encounter a regression using the package from -updates please report a new bug using ubuntu-bug and tag the bug report regression-update so we can easily find any regressions.

This bug was fixed in the package cloud-init - 17.1-46-g7acc9e68-0ubuntu1~17.04.1

---------------
cloud-init (17.1-46-g7acc9e68-0ubuntu1~17.04.1) zesty-proposed; urgency=medium

* New upstream snapshot.
- ec2: Fix sandboxed dhclient background process cleanup.
(LP: #1735331)
- tests: NoCloudKVMImage do not modify the original local cache image.
- tests: Enable bionic in integration tests. [Joshua Powers]
- tests: Use apt-get to install a deb so that depends get resolved.
- sysconfig: Correctly render dns and dns search info.
[Ryan McCabe]

cloud-init (17.1-41-g76243487-0ubuntu1~17.04.1) zesty-proposed; urgency=medium

* debian/cloud-init.templates: Fix capitilazation in 'AliYun'
(LP: #1728186)
* New upstream snapshot (LP: #1733653)
- integration test: replace curtin test ppa with cloud-init test ppa.
- EC2: Fix bug using fallback_nic and metadata when restoring from cache.
- EC2: Kill dhclient process used in sandbox dhclient.
- ntp: fix configuration template rendering for openSUSE and SLES
- centos: Provide the failed #include url in error messages
- Catch UrlError when #include'ing URLs [Andrew Jorgensen]
- hosts: Fix openSUSE and SLES setup for /etc/hosts and clarify docs.
[Robert Schweikert]
- rh_subscription: Perform null checks for enabled and disabled repos.
[Dave Mulford]
- Improve warning message when a template is not found.
[Robert Schweikert]
- Replace the temporary i9n.brickies.net with i9n.cloud-init.io.
- Azure: don't generate network configuration for SRIOV devices
- tests: address some minor feedback missed in last merge.
- tests: integration test cleanup and full pass of nocloud-kvm.
- Gentoo: chmod +x on all files in sysvinit/gentoo/
[Carlos Konstanski]

-- Chad Smith <email address hidden> 2017年12月01日 10:02:24 -0700

This bug was fixed in the package cloud-init - 17.1-46-g7acc9e68-0ubuntu1~17.10.1

---------------
cloud-init (17.1-46-g7acc9e68-0ubuntu1~17.10.1) artful-proposed; urgency=medium

* New upstream snapshot.
- ec2: Fix sandboxed dhclient background process cleanup.
(LP: #1735331)
- tests: NoCloudKVMImage do not modify the original local cache image.
- tests: Enable bionic in integration tests. [Joshua Powers]
- tests: Use apt-get to install a deb so that depends get resolved.
- sysconfig: Correctly render dns and dns search info.
[Ryan McCabe]

cloud-init (17.1-41-g76243487-0ubuntu1~17.10.1) artful-proposed; urgency=medium

* debian/cloud-init.templates: Fix capitilazation in 'AliYun'
(LP: #1728186)
* New upstream snapshot (LP: #1733653)
- integration test: replace curtin test ppa with cloud-init test ppa.
- EC2: Fix bug using fallback_nic and metadata when restoring from cache.
- EC2: Kill dhclient process used in sandbox dhclient.
- ntp: fix configuration template rendering for openSUSE and SLES
- centos: Provide the failed #include url in error messages
- Catch UrlError when #include'ing URLs [Andrew Jorgensen]
- hosts: Fix openSUSE and SLES setup for /etc/hosts and clarify docs.
[Robert Schweikert]
- rh_subscription: Perform null checks for enabled and disabled repos.
[Dave Mulford]
- Improve warning message when a template is not found.
[Robert Schweikert]
- Replace the temporary i9n.brickies.net with i9n.cloud-init.io.
- Azure: don't generate network configuration for SRIOV devices
- tests: address some minor feedback missed in last merge.
- tests: integration test cleanup and full pass of nocloud-kvm.
- Gentoo: chmod +x on all files in sysvinit/gentoo/
[Carlos Konstanski]

-- Chad Smith <email address hidden> 2017年12月01日 09:58:48 -0700

This bug is believed to be fixed in cloud-init in 1705804. If this is still a problem for you, please make a comment and set the state back to New

Thank you.

We are seeing errors very similar to this:

can't create /var/tmp/cloud-init/cloud-init-.../dhcp.leases: No such file or directory

The /var/tmp/cloud-init has been created, world writable.

Started seeing the errors a few days after the fix was released - around 5th December.

AWS EC2
ubuntu 16.04.1
cloud-init 17.1-46-g7acc9e68-0ubuntu1~16.04.1

Stretch, can you please attach /var/log/cloud-init.log ?
Better would be to attach output of 'cloud-init collect-logs'

Thanks.

Tracked in Github Issues as https://github.com/canonical/cloud-init/issues/3073