No log output seen if ignition hangs

[ashcrow]

Bug

Operating System Version

• RHCOS ~4392

Ignition Version

0.27.0-2.gitcc7ebe0.fc30

Environment

• libvirt
• openstack

What hardware/cloud provider/hypervisor is being used to run Ignition?

• libvirt
• openstack

Expected Behavior

If ignition is unable to honor the config the boot will fail with log output

Actual Behavior

If ignition is unable to honor the config the booting hangs with no log output.

Reproduction Steps

1. Provide an ignition config to RHCOS (example to be provided)
2. Booting hangs with no logs

Other Information

The following PRs addressed similar issues earlier on:

• cloud.ks: Add tty0 console output for ignition logging #158
• https://github.com/dustymabe/ignition-dracut/pull/13

This was reported by @eparis.

[dustymabe]

I've tried a few things to try to get the output from a systemd unit
that runs in the initrd to print to the kernel buffer (kmsg). Nothing
I do seems to work.

I've tried setting up the journal log to forward everything to kmsg:

https://github.com/dustymabe/ignition-dracut/blob/d664657cc2f733d8f54e9c0e69ba603babe55d92/dracut/99journald-conf/00-journal-log-forwarding.conf#L1-L3

and also added StandardOutput=kmsg+console to the systemd unit itself.
Regardless of what I do I can see the output in the journal but not from
dmesg.

[dustymabe]

so.. this was quite a rabbit hole. I've been in man pages all day long and finally figured out that what is happening is that the kernel is rate-limiting messages sent to /dev/kmsg from userspace (i.e. the journal) and will spit out a message like this:

[    4.690175] systemd-journal: 100 output lines suppressed due to ratelimiting                     
[    4.716922] systemd: 21 output lines suppressed due to ratelimiting

If I add printk.devkmsg=on to the kernel command line, which tells the kernel not to ratelimit, then I am able to see ignition output in dmesg (and thus any configured console= device)

still not sure what the optimal solution to this problem is, but I've got a smoking gun at least

[jlebon]

Actual Behavior

If ignition is unable to honor the config the booting hangs with no log output.

Should this say "with no log output on tty0."? Ignition logs do show up on ttyS0, right? So this is about having them show up on both tt0 and ttyS0?

the kernel is rate-limiting messages

Yeah, and Ignition is quite verbose too since it prints out the full config as well as everything it's doing during processing (which is nice). Do some messages pass through at least when it's an invalid config?

[eparis]

Yes, my VMs hang indefinitely with no output on tty0. (when I created a serial port I see there is, in my case, output on ttyS0.)

In my particular case I get the message (on ttyS0)

[31184.547195] ignition[692]: INFO     : GET http://test1-tnc.tt.testing:49500/config/etcd?etcd_index=0: attempt #5961
[31184.553312] ignition[692]: INFO     : GET error: Get http://test1-tnc.tt.testing:49500/config/etcd?etcd_index=0: dial tcp: lookup test1-tnc.tt.testing on 192.168.124.1:53: dial udp 192.168.124.1:53: connect: network is unreachable
[31189.548668] ignition[692]: INFO     : GET http://test1-tnc.tt.testing:49500/config/etcd?etcd_index=0: attempt #5962
[31189.554927] ignition[692]: INFO     : GET error: Get http://test1-tnc.tt.testing:49500/config/etcd?etcd_index=0: dial tcp: lookup test1-tnc.tt.testing on 192.168.124.1:53: dial udp 192.168.124.1:53: connect: network is unreachable
[31194.550630] ignition[692]: INFO     : GET http://test1-tnc.tt.testing:49500/config/etcd?etcd_index=0: attempt #5963
[31194.556454] ignition[692]: INFO     : GET error: Get http://test1-tnc.tt.testing:49500/config/etcd?etcd_index=0: dial tcp: lookup test1-tnc.tt.testing on 192.168.124.1:53: dial udp 192.168.124.1:53: connect: network is unreachable

Which are coming at the rate of 2 messages every 5 seconds. I am not getting rate limited...

[dustymabe]

Which are coming at the rate of 2 messages every 5 seconds. I am not getting rate limited...

you aren't getting rate limited on ttyS0 (the console), but I bet if you go back and look at tty0 (where only kmsgs are getting printed out) you'd see some messages about being rate limited.

[dustymabe]

FYI this should help: https://github.com/dustymabe/ignition-dracut/pull/14

[dustymabe]

related. I'd like to make a change like this globally in Fedora: https://lists.fedoraproject.org/archives/list/devel@lists.fedoraproject.org/thread/OI7BOWZSXDJM5W2KVDK3BBEN6S7ASLZC/

[dustymabe]

should be fixed in rhcos-4.0.4419. you should see ignition log statements on all console devices.