Skip to content

main/postmarketos-initramfs: log to kernel ringbuffer

Caleb Connolly requested to merge caleb/initramfs-log-to-kmsg into master

Rework logging to always log the initramfs output to the kernel ringbuffer and deprecate PMOS_NO_OUTPUT_REDIRECT in favour of following the kernel loglevel.

I know it seems silly to use syslogd for this, but it's necessary to buffer writes to /dev/kmsg per-line if we want to correctly set the log level, and "tee" does not do this (it will write multiple lines at once, resulting in "<14>" prints in the ringbuffer). The main advantage to this is that we won't have kernel logs cut in half by initramfs logs anymore, everything will be nicely line buffered!

The previous logging solution of multiple "tail" commands would actually fail to log up to the last few lines before a crash due to how tail works (it polls the file and buffers lines).

I attempted something like this before, but I stopped after running into ratelimiting issues. These are now resolved by configuring the printk_devkmsg sysctl.


The general motivations behind PMOS_NO_OUTPUT_REDIRECT was to avoid cluttering up the console with initramfs logs when they aren't wanted; this is now handled instead by the kernels logging facility. We log to the ringbuffer at LOGLEVEL_INFO, so if "quiet" is specified on the cmdline (or the loglevel is otherwise set above info) then initramfs logs will also not be shown.

debug-shell changes

The debug-shell (and friends) generally relied on the script running in the context of a TTY. However the logging changes break this assumption (running sh -i no longer works). To fix this, the debug-shell is reworked to spawn a getty on the relevant consoles.

Additionally, the behaviour of the debug-shell is entirely reworked, removing the telnet feature. Instead it creates an ACM serial gadget which can be accessed via any normal terminal emulator (picocom, minicom, etc; or PuTTY on windows). Rather than just invoking sh, the debug-shell now creates a respawning getty on both the new virtual console and the active console (this will either be the UART console or tty0/1).

If fbkeyboard is available (it can be added by install postmarketos-mkinitfs-hook-console-shell) then it will be launched on tty0. A getty will also be launched on tty0 in this case even if it otherwise wouldn't be (if the active console was the serial port for example).

It is necessary to spawn these shells via getty since the logging rework means we can no longer assume that stdin/out/err reference a TTY.

In addition to the above, it is now possible to trigger a log dump by holding volume up during boot (if iskey is available). This can be useful for helping users debug their devices if the issue doesn't result in a failure that can be detected in the initramfs.

With these changes, the console-shell and debug-shell hook packages are reduced to only adding the additional tools/features. console-shell is still required for fbkeyboard, and debug-shell for the setup_usb_storage tool.

postmarketos-initramfs-tiny & postmarketos-initramfs-fullsize

To support the new "hold volume up to enter debug shell" feature, it was necessary to write a small program (iskey) to check if a key is being pressed. This is not very easy to do without libevdev, which adds >100k to the initramfs.

The deal with this, and the future inevitable expansion of the initramfs, without making postmarketOS unusable on devices with extremely limited space, the iskey program is made optional (the initramfs detects if it's available) and if it isn't then some fallback behaviour is used.

By default, the fullszie variant is used. Device maintainers should make their device explicitly depend on postmarketos-initramfs-tiny if they are space constrained. This will also allow us to keep track of which devices need this.

no telnet?!

Nop, however this shouldn't break any existing usecases. If you really want telnet then you can write your own hook, or start it up manually from an interactive shell in tty0, over your serial port, or via the USB serial gadget.

Example output when booting QEMU:

[    0.395851] Run /init as init process
[    0.413036] syslogd started: BusyBox v1.36.1
[    0.414202] [pmOS.rd]: ### postmarketOS initramfs ###
[    0.414534] [pmOS.rd]: Configuring kernel firmware image search path
[    0.446371] ACPI: \_SB_.LNKB: Enabled at IRQ 10
[    0.454461] ACPI: \_SB_.LNKC: Enabled at IRQ 11
[    0.462436] ACPI: \_SB_.LNKD: Enabled at IRQ 11
[    0.471239] ACPI: \_SB_.LNKA: Enabled at IRQ 10
[    0.497562] virtio_blk virtio4: 20/0/0 default/read/poll queues
[    0.504875] virtio_blk virtio4: [vda] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB)
[    0.507828]  vda: vda1 vda2
[    0.521189] ACPI: bus type drm_connector registered
[    0.529708] [drm] pci: virtio-vga detected at 0000:00:05.0
[    0.530082] virtio-pci 0000:00:05.0: vgaarb: deactivate vga console
[    0.534303] Console: switching to colour dummy device 80x25
[    0.534766] [drm] features: +virgl +edid -resource_blob -host_visible
[    0.534767] [drm] features: -context_init
[    0.537194] [drm] number of scanouts: 1
[    0.537436] [drm] number of cap sets: 2
[    0.544866] [drm] cap set 0: id 1, max-version 1, max-size 308
[    0.545347] [drm] cap set 1: id 2, max-version 2, max-size 1384
[    0.545926] [drm] Initialized virtio_gpu 0.1.0 0 for 0000:00:05.0 on minor 0
[    0.547536] fbcon: virtio_gpudrmfb (fb0) is primary device
[    0.549880] Console: switching to colour frame buffer device 128x48
[    0.566578] virtio-pci 0000:00:05.0: [drm] fb0: virtio_gpudrmfb frame buffer device
[    0.580967] input: QEMU Virtio Mouse as /devices/pci0000:00/0000:00:02.0/virtio0/input/input2
[    0.582771] input: QEMU Virtio Keyboard as /devices/pci0000:00/0000:00:03.0/virtio1/input/input3
[    0.595625] [pmOS.rd]: Setting framebuffer mode to: U:1024x768p-0
[    0.721585] [pmOS.rd]: Trying to mount subpartitions for 10 seconds...
[    0.733445] [pmOS.rd]: Setup usb network
[    0.733450] [pmOS.rd]:   /sys/class/android_usb does not exist, skipping android_usb
[    0.733453] [pmOS.rd]:   Setting up an USB gadget through configfs
[    0.735064] [pmOS.rd]: mkdir: can't create directory '/config/usb_gadget/g1/functions/ncm.usb0': No such file or directory
[    0.735112] [pmOS.rd]:   Couldn't create /config/usb_gadget/g1/functions/ncm.usb0
[    0.752391] [pmOS.rd]:   No USB Device Controller available
[    0.754641] [pmOS.rd]: NOTE: start of dhcpd is disabled (deviceinfo_disable_dhcpd)
[    0.762084] [pmOS.rd]: Mount boot partition (/dev/vda1) to /boot (read-only)
[    0.763526] FAT-fs (vda1): utf8 is not a recommended IO charset for FAT filesystems, filesystem will be case sensitive!
[    0.768314] [pmOS.rd]: Detected vfat filesystem
[    0.773958] [pmOS.rd]: Extract /boot/initramfs-extra
[    0.878840] [pmOS.rd]: 8543 blocks
[    0.893565] [pmOS.rd]: Not resizing root partition (/dev/vda2): no free space left
[    0.896701] [pmOS.rd]: Mount root partition (/dev/vda2) to /sysroot (read-only) with options 
[    0.897644] [pmOS.rd]: Detected ext4 filesystem
[    0.954973] EXT4-fs (vda2): INFO: recovery required on readonly filesystem
[    0.955442] EXT4-fs (vda2): write access will be enabled during recovery
[    1.015520] EXT4-fs (vda2): orphan cleanup on readonly fs
[    1.015955] EXT4-fs (vda2): recovery complete
[    1.020654] EXT4-fs (vda2): mounted filesystem 558e114c-eca3-4ab9-bc2d-2681b22f9679 ro with ordered data mode. Quota mode: none.
[    1.026171] [pmOS.rd]: Mount boot partition (/dev/vda1) to /sysroot/boot (read-write)
[    1.027319] [pmOS.rd]: Detected vfat filesystem
[    1.027473] FAT-fs (vda1): utf8 is not a recommended IO charset for FAT filesystems, filesystem will be case sensitive!
[    1.032092] FAT-fs (vda1): Volume was not properly unmounted. Some data may be corrupt. Please run fsck.
[    1.039899] syslogd exiting
OpenRC 0.53 is starting up Linux 6.8.3-0-edge (x86_64)

/proc is already mounted
/run/openrc: creating directory
/run/lock: creating directory
/run/lock: correcting owner
zram swap: activating with size: 738 MB
Caching service dependencies ... [ ok ]
Remounting devtmpfs on /dev ... [ ok ]
Mounting /dev/mqueue ... [ ok ]
Mounting /dev/shm ... [ ok ]
Mounting security filesystem ... [ ok ]
Mounting debug filesystem ... [ ok ]
Mounting config filesystem ... [ ok ]
Mounting persistent storage (pstore) filesystem ... [ ok ]
Starting udev ... [ ok ]
Generating a rule to create a /dev/root symlink ... [ ok ]
Populating /dev with existing devices through uevents ... [ ok ]
Waiting for uevents to be processed ... [ ok ]
Loading modules ... [ ok ]
Setting system clock using the hardware clock [UTC] ... [ ok ]
Checking local filesystems  ... [ ok ]
Remounting root filesystem read/write ... [ ok ]
Remounting filesystems ... [ ok ]
Mounting local filesystems ... [ ok ]
Configuring kernel parameters ... [ ok ]
Creating user login records ... [ ok ]
Cleaning /tmp directory ... [ ok ]
Setting hostname ... [ ok ]
Starting logbookd ...Cannot restore /var/log/logbookd.db
[ ok ]
Activating swap file ...Configured swap file size is 0, skipping creation.
[ ok ]
/run/dbus: creating directory
/run/dbus: correcting owner
Starting System Message Bus ... [ ok ]
Loading nftables rules and starting firewall ... [ ok ]
Starting haveged ... [ ok ]
Could not find a wireless interface
/var/run/wpa_supplicant: creating directory
Starting WPA Supplicant ... [ ok ]
Starting networkmanager ... [ ok ]
Starting chronyd ... [ ok ]
Starting kill-pbsplash ... [ ok ]
Restoring rfkill configuration ... [ ok ]
Starting sshd ... [ ok ]
Activating swap devices ... [ ok ]
zram swap: activating with size: 738 MB
Loading zram module...
[ ok ]
[ ok ]
Starting local ... [ ok ]

Welcome to postmarketOS

TODO before merging

  • Update relevant wiki pages to document the new debugging process (and drop references to PMOS_NO_OUTPUT_REDIRECT)
  • Add support for disabling the debug-shell feature? Let's deal with this once we have a better "first time setup" flow.
  • Update space constrained devices to depend on the postmarketos-initramfs-minimal
Edited by clayton craft

Merge request reports