This has so far only been observed on Azure.  It's not clear whether it's
impacted other cloud environments or not.

Cloud-init is not consistently being enabled during VM provisioning on
Microsoft Azure.  The external symptom is that the launch times out.  We can
see from the logs that the various systemd services associated with cloud-init
are never invoked at all:

Failed launch:

root@boot-failure:~# journalctl -b -1 | grep cloud-init | wc -l
0

Versus a successful launch:

root@boot-failure:~# journalctl -b 0 | grep cloud-init | wc -l
102
root@boot-failure:~# journalctl -b 0 | grep cloud-init | head -n1
Mar 12 18:12:01 localhost systemd[1]: Starting cloud-init-main.service - Cloud-init: Single Process...
root@boot-failure:~# journalctl -b 0 | grep cloud-init.target
Mar 12 18:12:12 boot-failure systemd[1]: Reached target cloud-init.target - Cloud-init target.

It may have something to do with cloud-init's systemd generator, which is
responsible for conditionally enabling cloud-init.target early in the boot
process.  On a failed launch it generates the following in
/run/cloud-init/cloud-init-generator.log:

/usr/lib/systemd/system-generators/cloud-init-generator normal=/run/systemd/generator early=/run/systemd/generator.early late=/run/systemd/generator.late
checking for datasource

While a successful launch specifically indicates that it's enabling
cloud-init.target:

/usr/lib/systemd/system-generators/cloud-init-generator normal=/run/systemd/generator early=/run/systemd/generator.early late=/run/systemd/generator.late
checking for datasource
ds-identify rc=0
enabled via /run/systemd/generator.early/multi-user.target.wants/cloud-init.target -> /lib/systemd/system/cloud-init.target

to the cloud-init-generator.  When running systemd with debug logging,
we see indications of successful completion of a number of generators in
a successful boot that ѕeem to disappear in an unsuccessful boot, with
no clear indication of why.

Success:
noahm@boot-failure1:~$ journalctl -b -1 -o short-monotonic | grep -F -- "system-generat"
[    3.772668] boot-failure1 (sd-exec-[274]: About to execute /usr/lib/systemd/system-generators/cloud-init-generator (null)
[    3.772690] boot-failure1 (sd-exec-[274]: About to execute /usr/lib/systemd/system-generators/netplan (null)
[    3.772709] boot-failure1 (sd-exec-[274]: About to execute /usr/lib/systemd/system-generators/systemd-debug-generator (null)
[    3.772731] boot-failure1 (sd-exec-[274]: About to execute /usr/lib/systemd/system-generators/systemd-fstab-generator (null)
[    3.772750] boot-failure1 (sd-exec-[274]: About to execute /usr/lib/systemd/system-generators/systemd-getty-generator (null)
[    3.772790] boot-failure1 (sd-exec-[274]: About to execute /usr/lib/systemd/system-generators/systemd-gpt-auto-generator (null)
[    3.772823] boot-failure1 (sd-exec-[274]: About to execute /usr/lib/systemd/system-generators/systemd-hibernate-resume-generator (null)
[    3.772897] boot-failure1 (sd-exec-[274]: About to execute /usr/lib/systemd/system-generators/systemd-rc-local-generator (null)
[    3.772916] boot-failure1 (sd-exec-[274]: About to execute /usr/lib/systemd/system-generators/systemd-run-generator (null)
[    3.772935] boot-failure1 (sd-exec-[274]: About to execute /usr/lib/systemd/system-generators/systemd-ssh-generator (null)
[    3.772968] boot-failure1 (sd-exec-[274]: About to execute /usr/lib/systemd/system-generators/systemd-system-update-generator (null)
[    3.772986] boot-failure1 (sd-exec-[274]: About to execute /usr/lib/systemd/system-generators/systemd-sysv-generator (null)
[    3.773004] boot-failure1 (sd-exec-[274]: About to execute /usr/lib/systemd/system-generators/systemd-tpm2-generator (null)
[    3.773065] boot-failure1 (sd-exec-[274]: /usr/lib/systemd/system-generators/systemd-rc-local-generator succeeded.
[    3.773494] boot-failure1 (sd-exec-[274]: /usr/lib/systemd/system-generators/systemd-ssh-generator succeeded.
[    3.774000] boot-failure1 (sd-exec-[274]: /usr/lib/systemd/system-generators/systemd-sysv-generator succeeded.
[    3.774010] boot-failure1 (sd-exec-[274]: /usr/lib/systemd/system-generators/systemd-debug-generator succeeded.
[    3.774020] boot-failure1 (sd-exec-[274]: /usr/lib/systemd/system-generators/systemd-fstab-generator succeeded.
[    3.774031] boot-failure1 (sd-exec-[274]: /usr/lib/systemd/system-generators/systemd-getty-generator succeeded.
[    3.774040] boot-failure1 (sd-exec-[274]: /usr/lib/systemd/system-generators/systemd-run-generator succeeded.
[    3.774051] boot-failure1 (sd-exec-[274]: /usr/lib/systemd/system-generators/systemd-hibernate-resume-generator succeeded.
[    3.774060] boot-failure1 (sd-exec-[274]: /usr/lib/systemd/system-generators/systemd-tpm2-generator succeeded.
[    3.774070] boot-failure1 (sd-exec-[274]: /usr/lib/systemd/system-generators/cloud-init-generator succeeded.
[    3.774082] boot-failure1 (sd-exec-[274]: /usr/lib/systemd/system-generators/systemd-gpt-auto-generator succeeded.
[    3.774092] boot-failure1 (sd-exec-[274]: /usr/lib/systemd/system-generators/systemd-system-update-generator succeeded.
[    3.774102] boot-failure1 (sd-exec-[274]: /usr/lib/systemd/system-generators/netplan terminated by signal ABRT.

Failure:
noahm@boot-failure1:~$ journalctl -b 0 -o short-monotonic | grep -F -- "system-generat"
[    3.398004] boot-failure1 (sd-exec-[272]: About to execute /usr/lib/systemd/system-generators/cloud-init-generator (null)
[    3.398026] boot-failure1 (sd-exec-[272]: About to execute /usr/lib/systemd/system-generators/netplan (null)
[    3.398044] boot-failure1 (sd-exec-[272]: About to execute /usr/lib/systemd/system-generators/systemd-debug-generator (null)
[    3.398065] boot-failure1 (sd-exec-[272]: About to execute /usr/lib/systemd/system-generators/systemd-fstab-generator (null)
[    3.398085] boot-failure1 (sd-exec-[272]: About to execute /usr/lib/systemd/system-generators/systemd-getty-generator (null)
[    3.398125] boot-failure1 (sd-exec-[272]: About to execute /usr/lib/systemd/system-generators/systemd-gpt-auto-generator (null)
[    3.398156] boot-failure1 (sd-exec-[272]: About to execute /usr/lib/systemd/system-generators/systemd-hibernate-resume-generator (null)
[    3.398207] boot-failure1 (sd-exec-[272]: About to execute /usr/lib/systemd/system-generators/systemd-rc-local-generator (null)
[    3.398275] boot-failure1 (sd-exec-[272]: About to execute /usr/lib/systemd/system-generators/systemd-run-generator (null)
[    3.398293] boot-failure1 (sd-exec-[272]: About to execute /usr/lib/systemd/system-generators/systemd-ssh-generator (null)
[    3.398312] boot-failure1 (sd-exec-[272]: About to execute /usr/lib/systemd/system-generators/systemd-system-update-generator (null)
[    3.398382] boot-failure1 (sd-exec-[272]: About to execute /usr/lib/systemd/system-generators/systemd-sysv-generator (null)
[    3.398418] boot-failure1 (sd-exec-[272]: About to execute /usr/lib/systemd/system-generators/systemd-tpm2-generator (null)
[    3.398486] boot-failure1 (sd-exec-[272]: /usr/lib/systemd/system-generators/systemd-debug-generator succeeded.
[    3.398635] boot-failure1 (sd-exec-[272]: /usr/lib/systemd/system-generators/systemd-fstab-generator succeeded.
[    3.398683] boot-failure1 (sd-exec-[272]: /usr/lib/systemd/system-generators/systemd-getty-generator succeeded.
[    3.398711] boot-failure1 (sd-exec-[272]: /usr/lib/systemd/system-generators/systemd-gpt-auto-generator succeeded.
[    3.398730] boot-failure1 (sd-exec-[272]: /usr/lib/systemd/system-generators/netplan terminated by signal ABRT.

The netplan ABRT log occurs in both cases, so I don't think it's
relevant, but maybe.

systemd indicates successful completion of the following generators in a
successful boot but not in a failed boot.  There's no clear indication
of what happened to them.

cloud-init-generator
systemd-hibernate-resume-generator
systemd-rc-local-generator
systemd-run-generator
systemd-ssh-generator
systemd-system-update-generator
systemd-sysv-generator
systemd-tpm2-generator

I've attached a full journalctl output for a failed boot for reference.

noah

I can confirm that systemd is sending a TERM to (at least) the
cloud-init-generator process.  However, I'm not yet sure why:

* The cloud-init-generator process typically runs in approximately 30ms,
  and is sometimes killed.

* I've been able to insert an artificial 2s pause in the middle of the
  script without appearing to impact the frequency of it being
  killed.

* Timing of this specific generator doesn't explain why several other
  generators are also apparently being killed.

The systemd docs
(https://manpages.debian.org/unstable/systemd/systemd.generator.7.en.html)
indicate that generators are executed synchronously during the boot
process and should thus take care to not "delay the entire boot if they
are slow".  However, there's no mention of a specific runtime
requirement.  Is the deadline dynamic in some way?

The default timeout is 90s, so it's far off.

I read a bit through systemd.  I don't see anything apart "alarm()" to
enforce a timeout.

"systemd.log_level=debug systemd.log_target=console" on the kernel
command line gives some more insight.  But this is a lot of output, so
requires serial console output.

Bastian

systemd.  Interestingly, it doesn't seem like systemd logs anything at
all when it sends a SIGTERM (at least to generators).

You mentioned on IRC that you've observed this on the generic images,
and I've now observed the same thing.  Note that it doesn't occur only
on first boot; it appears that it can happen on any reboot (or
presumably on daemon-reload, as generators are executed then as well).

One potentially interesting entry from the debug logs is:
[    3.398752] boot-failure1 (sd-gens)[271]: (sd-exec-strv) failed with exit status 1.

It does occur on a successful launch as well, but because the generators
all run in parallel, it's possible that whatever causes this does not
always lead to failure depending on how the events are ordered.

That mail did not make it to the list.  I also don't see any code path
that would do explicit SIGTERM.

Yes.  This code bails out on all and every error with exit(1).

Okay, found it:

wait_for_terminate_and_check:
| log_full(prio, "%s terminated by signal %s.", strna(name), signal_to_string(status.si_status));
| return -EPROTO;

do_execute:
| r = wait_for_terminate_and_check(…);
| if (r < 0) return r;

execute_strv:
| r = do_execute(…)
| _exit(r < 0 ? EXIT_FAILURE : r);

So the SIGABRT of netplan short circuits the error handling and kills
off all other generators.

Bastian

Control: block -1 by 1100418
Control: affects 1100418 + cloud.debian.org

I think the TERM comes from https://github.com/systemd/systemd/blob/main/src/shared/exec-util.c#L271

The mail is here and the log is at
https://bugs.debian.org/cgi-bin/bugreport.cgi?att=1;bug=1100338;filename=journal.fail;msg=10,
but I don't think that matters anymore.

Yep, that's basically the path I was on, too.  That explains the
intermittent nature of the failures, too, since it's possible for the
ABRT to happen after some generators have already completed
successfully.

I wonder what's going on with netplan-generator...

noah

systemd kills remaining generators in cleanup if one generator died with
a signal.  This might break booting.

Bastian