2

So far I managed to get the kernel & systemd to output the first log messages from booting on the system’s serial port. Further, after the boot process is (nearly) completed, journald continues to log all of its stuff to the serial as well (e.g. when any service logs something). However, there is short time window where I get no output on the serial console. It happens always precisely after systemd starts the unit dev-mqueue.mount and the logging eventually continues with the message Console: switching to colour frame buffer device 240x67. So the serial console misses ca. 5 seconds of crucial log messages. It was exact this way on all of my retries. I’m unsure why the logging continues at exact this point.

My question is: How can I achieve that in those 5 seconds something continues logging to the serial console?

System Infos: (in case it is a system specific problem):

  • System: Raspberry Pi 4B (4 GB RAM)
  • OS: Debian GNU/Linux (image of 2023.11.09 from here)
    • further apt update && apt upgrade
    • kernel: Linux rpi4-20231108 6.1.0-17-arm64 #1 SMP Debian 6.1.69-1 (2023-12-30) aarch64 GNU/Linux
    • booting from SD card
  • using native serial output of RPi4 via GPIO pins
  • adapter for serial input: CP2101 (set to 3,3 V mode) via USB using picocom on a Debian desktop system

Current Configuration: (maybe also helpful to others which just need logs over serial after successful boot)

So that the native serial console of a RPi is enabled, enable_uart=1 must be set in /boot/firmware/config.txt (default on most images). Further, the kernel needs to know that it should use the serial port as its console. On a RPi4, one is called /dev/ttyS1 which is available via Pins 8 & 10 (see here). Further, systemd & journald need to know that as well. So I did the following:

In /etc/default/raspi-config I set CONSOLES="tty0 ttyS1,115200" to instruct the kernel. In /etc/default/raspi-extra-cmdline I added the configs systemd.journald.forward_to_console=1 to instruct journald from initramfs. After a long update-initramfs -u -k all, /boot/firmware/cmdline.txt contains now: console=tty0 console=ttyS1,115200 systemd.journald.forward_to_console=1 root=LABEL=RASPIROOT rw fsck.repair=yes net.ifnames=0 rootwait.

I created the file /etc/systemd/journald.conf.d/forwardto-ttyS1.conf for journald post-initramfs with the content:

[Journal]
ForwardToConsole=yes
TTYPath=/dev/ttyS1
MaxLevelConsole=info

At last, to avoid getty to show a login prompt on serial, I disabled it for this specific tty by running systemctl mask [email protected].

What I tried so far:

  • adding systemd.log_target=console and loglevel=7 to cmdline: did change nothing
  • adding systemd.log_target=kmsg to cmdline: did change nothing
  • changing the baudrate from 115200 to 9600: slows down booting, but still nothing is logged for 5 seconds

Full serial output (asciinema recordings, also here for 115200 and 9600) & journal logs from a 115200 & 9600 baudrate run are posted here (caution: high CPU usage possible, read here for meta).

Context: I want this log output because a custom-designed Debian image of mine crashes while booting before it can mount its drive in read-write to eventually save log files to it. The refresh rate of the screen output is too slow to show the last crucial messages which might explain why it crashes. Those messages shortly before it crashes also don‘t get logged to the serial, making it nearly impossible to debug it.

1 Answer 1

1

By replaying the asciinema recording in a browser, I discovered that the issue was not on the record. This was a "display issue" caused by tmux. When viewing the asciinema (or connecting to the serial) outside of a tmux session, the log just continued and seems complete. But in tmux, even with the default config, it breaks. (just in case: I tested with&without tmux in xterm & KDE’s Konsole and bash & zsh)

Sorry for the potential disturbance here. Just in case, I will keep my question up in case anyone else hits the same issue and is helped by my answer, even if I think that is nearly impossible …

more explanation for super nerds

The issue happens because of this line being printed unescaped (that’s how the line was saved by asciinema, with spaces at the start truncated):

Mounting \u001b[0;1;39mdev-mqueue.mount\u001b…POSIX Message Queue File System...\r\n

The escape character \u001b is sent to invoke actions in the terminal emulator (called ANSI escape sequences. To summarize, e.g. \u001b[0;1;39m says "reset" (0), "toggle bold / increased intensity" (1) and "default foreground color" (39). The code afterwards should reset everything again, however systemd-journald asserted the original line as too long, so it truncated the original line by replacing the middle part with an ellipse () (this is explained here), leaving a single escape character alone.

While most terminal emulators (including Linux virtual tty) seem to be able to handle this mostly fine (at max a few characters are not printed), tmux continues parsing the escape code, resulting in 5 seconds where nothing is printed by tmux.

You must log in to answer this question.

Not the answer you're looking for? Browse other questions tagged .