status symlink non-atomicity traceback with status --wait

[ubuntu-server-builder]

This bug was originally filed in Launchpad as LP: #1962150

Launchpad details

affected_projects = []
assignee = adam-collard
assignee_name = Adam Collard
date_closed = 2023-03-23T20:18:11.072810+00:00
date_created = 2022-02-24T08:49:19.873990+00:00
date_fix_committed = 2022-04-08T20:41:43.544099+00:00
date_fix_released = 2023-03-23T20:18:11.072810+00:00
id = 1962150
importance = medium
is_complete = True
lp_url = https://bugs.launchpad.net/cloud-init/+bug/1962150
milestone = None
owner = adam-collard
owner_name = Adam Collard
private = False
status = fix_released
submitter = adam-collard
submitter_name = Adam Collard
tags = []
duplicates = []

Launchpad user Adam Collard(adam-collard) wrote on 2022-02-24T08:49:19.873990+00:00

MAAS run system-tests on a regular basis using LXD containers to set things up.

A recent run failed waiting for the LXD container to finish booting, with a traceback from cloud-init.

After launching the container, the script runs timeout 2000 cloud-init status --wait --long to ensure that the commands we pass through as user-data are complete.

Here's a redacted snippet from the logs

2022-02-23 17:21:00 INFO : Waiting for boot to finish...
2022-02-23 17:21:00 INFO timeout 2000 cloud-init status --wait --long
2022-02-23 17:21:04 INFO ..........
2022-02-23 17:21:04 INFO Traceback (most recent call last):
2022-02-23 17:21:04 INFO File "/usr/bin/cloud-init", line 11, in
2022-02-23 17:21:04 INFO load_entry_point('cloud-init==21.4', 'console_scripts', 'cloud-init')()
2022-02-23 17:21:04 INFO File "/usr/lib/python3/dist-packages/cloudinit/cmd/main.py", line 927, in main
2022-02-23 17:21:04 INFO retval = util.log_time(
2022-02-23 17:21:04 INFO File "/usr/lib/python3/dist-packages/cloudinit/util.py", line 2472, in log_time
2022-02-23 17:21:04 INFO ret = func(*args, **kwargs)
2022-02-23 17:21:04 INFO File "/usr/lib/python3/dist-packages/cloudinit/cmd/status.py", line 60, in handle_status_args
2022-02-23 17:21:04 INFO status, status_detail, time = _get_status_details(init.paths)
2022-02-23 17:21:04 INFO File "/usr/lib/python3/dist-packages/cloudinit/cmd/status.py", line 123, in _get_status_details
2022-02-23 17:21:04 INFO status_v1 = load_json(load_file(status_file)).get('v1', {})
2022-02-23 17:21:04 INFO File "/usr/lib/python3/dist-packages/cloudinit/util.py", line 1361, in load_file
2022-02-23 17:21:04 INFO with open(fname, 'rb') as ifh:
2022-02-23 17:21:04 INFO FileNotFoundError: [Errno 2] No such file or directory: '/run/cloud-init/status.json'

You can see from the ... that there are a few successful attempts to wait, but then it fails.

[ubuntu-server-builder]

Launchpad user Adam Collard(adam-collard) wrote on 2022-02-24T08:55:13.364254+00:00

Reading the code - https://github.com/canonical/cloud-init/blob/main/cloudinit/cmd/status.py#L141-L144 - , the status command tries to guard against the file not existing, but clearly this run slipped through - the file existed when we os.path.exists() it, but not when we open() it :|

Looking deeper, we can see that cmd.main.status_wrapper atomically writes JSON (yay!) to the 'data_d' (/var/lib/cloud/data) then symlinks that status file in the 'link_d' (/run/cloud-init). All seems reasonable, but let's look at how it does that symlinking:

https://github.com/canonical/cloud-init/blob/main/cloudinit/cmd/main.py#L755-L758

Note the force=True, and refer to the implementation of sym_link:

cloud-init/cloudinit/util.py

Lines 1887 to 1891 in 2837b83

	def sym_link(source, link, force=False):
	LOG.debug("Creating symbolic link from %r => %r", link, source)
	if force and os.path.exists(link):
	del_file(link)
	os.symlink(source, link)

.. which deletes the symlink, then re-creates it.

This is non-atomic and entirely possible for readers (such as --wait) to see the entry in the FS, before it gets deleted, the deletion to occur and then open it.

[ubuntu-server-builder]

Launchpad user Adam Collard(adam-collard) wrote on 2022-02-24T09:30:44.198720+00:00

#1298

[ubuntu-server-builder]

Launchpad user James Falcon(falcojr) wrote on 2022-02-25T16:01:56.113370+00:00

Good find! Thanks for providing a PR too.

[ubuntu-server-builder]

Launchpad user Chad Smith(chad.smith) wrote on 2022-02-26T03:28:03.948679+00:00

Reproducible with the following on a system with cloud-init:

echo > reproducer.py <<EOF
from cloudinit.util import sym_link, write_file

source_file = "/tmp/test"
link_file = "/run/cloud-init/status.json"
write_file(source_file, "{}")

while True:
sym_link(source_file, link_file, force=True)
EOF

terminal 1

python3 ./reproducer.py

terminal 2

cloud-init status --wait
.......
...
with open(fname, 'rb') as ifh:
FileNotFoundError: [Errno 2] No such file or directory: '/run/cloud-init/status.json'

[ubuntu-server-builder]

Launchpad user Chad Smith(chad.smith) wrote on 2022-04-08T20:41:39.255178+00:00

upstream commit 0450a1f landed that addresses this issue.