Journal log entries while installing an ISO image
Hi, Yesterday I prepared an USB stick with the recent version of the Arch Linux installation medium (Release 2025-04-01). This is about some error entries in the system journal, which I encountered during copying this ISO image over. The respective transcripts are provided inline, as well as attached in the form of plain text files. I used initially $ sudo cp <ISO> /dev/sda. After having finished that process, I spotted some error log entries in the system journal: Apr 20 15:30:25 T470p sudo[21475]: friedrich : TTY=pts/2 ; PWD=/home/friedrich/(...) ; USER=root ; COMMAND=/usr/bin/cp archlinux-2025.04.01-x86_64.iso /dev/sda Apr 20 15:30:25 T470p sudo[21475]: pam_unix(sudo:session): session opened for user root(uid=0) by friedrich(uid=1000) Apr 20 15:33:10 T470p systemd[1]: systemd-udevd.service: Watchdog timeout (limit 3min)! Apr 20 15:33:10 T470p systemd[1]: systemd-udevd.service: Killing process 359 (systemd-udevd) with signal SIGABRT. Apr 20 15:34:40 T470p systemd[1]: systemd-udevd.service: State 'stop-watchdog' timed out. Killing. Apr 20 15:34:40 T470p systemd[1]: systemd-udevd.service: Killing process 359 (systemd-udevd) with signal SIGKILL. Apr 20 15:36:10 T470p systemd[1]: systemd-udevd.service: Processes still around after SIGKILL. Ignoring. Apr 20 15:37:38 T470p kernel: sda: sda1 sda2 Apr 20 15:37:38 T470p sudo[21475]: pam_unix(sudo:session): session closed for user root Apr 20 15:37:38 T470p systemd[1]: systemd-udevd.service: Main process exited, code=killed, status=9/KILL Apr 20 15:37:38 T470p systemd[1]: systemd-udevd.service: Failed with result 'watchdog'. Apr 20 15:37:38 T470p systemd[1]: systemd-udevd.service: Consumed 4.845s CPU time, 51.6M memory peak. Apr 20 15:37:38 T470p systemd[1]: systemd-udevd.service: Scheduled restart job, restart counter is at 1. Apr 20 15:37:38 T470p systemd[1]: Starting Rule-based Manager for Device Events and Files... Apr 20 15:37:39 T470p systemd-udevd[21582]: Using default interface naming scheme 'v257'. Apr 20 15:37:39 T470p systemd[1]: Started Rule-based Manager for Device Events and Files. Apr 20 15:38:19 T470p kernel: usb 1-1: USB disconnect, device number 7 Because I had doubts about the integrity of the thus prepared USB stick, I repeated the process, this time using $ su - and # dd if=<ISO> of=/dev/sda bs=8M. Here, I encountered similar logs: Apr 20 15:38:53 T470p kernel: sda: sda1 sda2 Apr 20 15:38:53 T470p kernel: sd 0:0:0:0: [sda] Attached SCSI removable disk Apr 20 15:39:07 T470p su[21650]: (to root) friedrich on pts/2 Apr 20 15:39:07 T470p su[21650]: pam_unix(su:session): session opened for user root(uid=0) by friedrich(uid=1000) Apr 20 15:44:05 T470p systemd[1]: systemd-udevd.service: Watchdog timeout (limit 3min)! Apr 20 15:44:05 T470p systemd[1]: systemd-udevd.service: Killing process 21582 (systemd-udevd) with signal SIGABRT. Apr 20 15:45:35 T470p systemd[1]: systemd-udevd.service: State 'stop-watchdog' timed out. Killing. Apr 20 15:45:35 T470p systemd[1]: systemd-udevd.service: Killing process 21582 (systemd-udevd) with signal SIGKILL. Apr 20 15:47:05 T470p systemd[1]: systemd-udevd.service: Processes still around after SIGKILL. Ignoring. Apr 20 15:48:35 T470p systemd[1]: systemd-udevd.service: State 'final-sigterm' timed out. Killing. Apr 20 15:48:35 T470p systemd[1]: systemd-udevd.service: Killing process 21582 (systemd-udevd) with signal SIGKILL. Apr 20 15:48:56 T470p kernel: sda: sda1 sda2 Apr 20 15:48:56 T470p systemd[1]: systemd-udevd.service: Main process exited, code=killed, status=9/KILL Apr 20 15:48:56 T470p systemd[1]: systemd-udevd.service: Failed with result 'watchdog'. Apr 20 15:48:56 T470p systemd[1]: systemd-udevd.service: Consumed 1.101s CPU time, 7.4M memory peak. Apr 20 15:48:56 T470p systemd[1]: systemd-udevd.service: Scheduled restart job, restart counter is at 2. Apr 20 15:48:56 T470p systemd[1]: Starting Rule-based Manager for Device Events and Files... Apr 20 15:48:56 T470p systemd-udevd[21808]: Using default interface naming scheme 'v257'. Apr 20 15:48:56 T470p systemd[1]: Started Rule-based Manager for Device Events and Files. Apr 20 15:49:13 T470p kernel: usb 1-1: USB disconnect, device number 8 In the second run, where I kept an eye on the journal, I noticed that the error entries were logged a few minutes *before* the copying process completed. There were no errors reported by both of these directly. The pen drive is booting and working just fine. However, I felt this behaviour being worth it to be reported. Maybe someone else can make sense of it. Best, Friedrich
(…) This is about some error entries in the system journal, which I encountered during copying this ISO image over. The respective transcripts are provided inline, as well as attached in the form of plain text files. (…) I believe this is unrelated to the copying process. udevd stopped responding for `WatchdogSec` seconds,⁽¹⁾ systemd restarted it. This kind of reports are usually associated with some specific piece of hardware leading to udevd lock-up, and no less often the bug is resolved in later kernel releases.
You may try passing `udev.log_level=debug` to kernel command-line during boot. See if that produces any useful info, but also note that this log level is very spammy. Cheers ____ ⁽¹⁾ See `man systemd.service`
Hi mpan, Am Mo., 21. Apr. 2025 um 23:51 Uhr schrieb mpan <archml-y1vf3axu@mpan.pl>:
(…) This is about some error entries in the system journal, which I encountered during copying this ISO image over. The respective transcripts are provided inline, as well as attached in the form of plain text files. (…) I believe this is unrelated to the copying process.
Actually, I am certain that the behaviour was triggered *by the copying process*, as the log journal entries were reproducible by repeating the installation for a second time.
udevd stopped responding for `WatchdogSec` seconds,⁽¹⁾ systemd restarted it. This kind of reports are usually associated with some specific piece of hardware leading to udevd lock-up, and no less often the bug is resolved in later kernel releases.
The logs indicate some *failed attempts* to SIGABRT and then SIGKILL. Shortly after the completion of the operation (when the kernel emits sda: sda1 sda2), a log: systemd-udevd.service: Main process exited, code=killed, status=9/KILL can be spotted. Thus it is rather clear that the error is truly related to the ISO image installation to sda. Possibly the USB stick leads to such a kind of lock-up as you mentioned, while the copying process is underway? The actual *copying procedure* completed successfully. You may try passing `udev.log_level=debug` to kernel command-line
during boot. See if that produces any useful info, but also note that this log level is very spammy.
Hm, what should I look for? Best, Friedrich
Hi Friedrich, while you're likely much better versed in your goals than what I likely know how to do I couldn't help but ponder what exactly you're trying to accomplish by copying the ISO to the seemingly unpartitioned hard disk /dev/sda, if I've followed along correctly. *> which I encountered during copying this ISO image over.* If you were trying to write the ISO as-is for bootable reuse wouldn't you use DD to write the image as it stands? Otherwise if keeping the ISO as an ISO was your goal wouldn't you need to create a basic partition table, mount the partition (ie /dev/sda1 to /mnt) then *cp archlinux.iso /mnt* ? Apologies if I've misread, you've sparked my genuine curiosity with the path you've chosen. Thanks, Sean On Tue, Apr 22, 2025 at 12:24 PM Friedrich Romstedt < friedrichromstedt@gmail.com> wrote:
Hi mpan,
Am Mo., 21. Apr. 2025 um 23:51 Uhr schrieb mpan <archml-y1vf3axu@mpan.pl>:
(…) This is about some error entries in the system journal, which I
encountered
during copying this ISO image over. The respective transcripts are provided inline, as well as attached in the form of plain text files. (…) I believe this is unrelated to the copying process.
Actually, I am certain that the behaviour was triggered by the copying process, as the log journal entries were reproducible by repeating the installation for a second time.
udevd stopped responding for `WatchdogSec` seconds,⁽¹⁾ systemd restarted it. This kind of reports are usually associated with some specific piece of hardware leading to udevd lock-up, and no less often the bug is resolved in later kernel releases.
The logs indicate some failed attempts to SIGABRT and then SIGKILL. Shortly after the completion of the operation (when the kernel emits sda: sda1 sda2), a log:
systemd-udevd.service: Main process exited, code=killed, status=9/KILL
can be spotted. Thus it is rather clear that the error is truly related to the ISO image installation to sda.
Possibly the USB stick leads to such a kind of lock-up as you mentioned, while the copying process is underway? The actual copying procedure completed successfully.
You may try passing `udev.log_level=debug` to kernel command-line during boot. See if that produces any useful info, but also note that this log level is very spammy.
Hm, what should I look for?
Best, Friedrich
Am Di., 22. Apr. 2025 um 19:17 Uhr schrieb Sean Snell <ssnell@lakecs.net>:
*> which I encountered during copying this ISO image over.*
If you were trying to write the ISO as-is for bootable reuse wouldn't you use DD to write the image as it stands? Otherwise if keeping the ISO as an ISO was your goal wouldn't you need to create a basic partition table, mount the partition (ie /dev/sda1 to /mnt) then *cp archlinux.iso /mnt* ?
I was providing an USB pen drive with the current version of the Arch Linux bootable ISO image. cp archlinux.iso /mnt/ would be pretty useless, as it would just copy the ISO file into the directory /mnt. Instead, I copied over the ISO "in raw" directly to the special device file /dev/sda, s.t. it becomes the content of the corresponding device (the pen drive here) directly, so it can be booted later on. In fact, it doesn't matter which program opens that device file /dev/sda. All the translation to the raw memory of the device is done by the kernel. So it doesn't matter if dd or cp is used. In this respect, the *work is not done by* dd. It is not even much faster. For both programs, /dev/sda is used as a file lying around in /dev/, which is opened in writing mode, and whose content is overwritten.
Apologies if I've misread, you've sparked my genuine curiosity with the path you've chosen.
At this point, the ingenuity of "device files" becomes apparent. I always find it a pretty genious way of exposing devices in a filesystem tree. Best, Friedrich
Hi Friedrich, while you're likely much better versed in your goals than what I likely know how to do I couldn't help but ponder what exactly you're trying to accomplish by copying the ISO to the seemingly unpartitioned hard disk /dev/sda, if I've followed along correctly.
*> which I encountered during copying this ISO image over.*
If you were trying to write the ISO as-is for bootable reuse wouldn't you use DD to write the image as it stands? Otherwise if keeping the ISO as an ISO was your goal wouldn't you need to create a basic partition table, mount the partition (ie /dev/sda1 to /mnt) then *cp archlinux.iso /mnt* ? Hello,
What Friedrich does is not only perfectly valid, but this is the suggested method.⁽¹⁾ Nothing should be mounted, the file should be simply copied to another file. `dd` is still listed in Arch Wiki, because anybody caring got tired of reverting that or correcting yet another “improvement” somebody adds. Dealing with aftermath of using `dd` seems much more efficient than going on a pointless crusade. Cheers ____ ⁽¹⁾ https://wiki.archlinux.org/title/USB_flash_installation_medium#Using_basic_c...
I believe this is unrelated to the copying process.
Actually, I am certain that the behaviour was triggered *by the copying process*, as the log journal entries were reproducible by repeating the installation for a second time.
I misunderstood your report then. From now on I’ll assume we eliminated the possibility, that this is something happening regardless of copying.
The logs indicate some *failed attempts* to SIGABRT and then SIGKILL. Shortly after the completion of the operation (when the kernel emits sda: sda1 sda2), a log:
systemd-udevd.service: Main process exited, code=killed, status=9/KILL
can be spotted. Thus it is rather clear that the error is truly related to the ISO image installation to sda.
Possibly the USB stick leads to such a kind of lock-up as you mentioned, while the copying process is underway? The actual *copying procedure* completed successfully. (…)
If either udevd or a program invoked by udevd try to read from the USB stick at the same time writing happens, I suppose this could happen. Hypothetically. I never encountered blocking like that. At least some reads should be scheduled between writes. I also searched the web for possibly relevant issues and can’t see such mentions. This explanation would be good, though. It would only indicate a benign failure, not affecting the data.
You may try passing `udev.log_level=debug` to kernel command-line
during boot. See if that produces any useful info, but also note that this log level is very spammy. Hm, what should I look for?
Everything around the same time the error is triggered. I didn’t think of that earlier, but `udevadm monitor` run in another console may be less spammy. Observe it during the situation. Again, anything pointing to what udev activity happens would be useful for debugging.
Am Montag, dem 21.04.2025 um 13:57 +0200 schrieb Friedrich Romstedt:
Hi,
Yesterday I prepared an USB stick with the recent version of the Arch Linux installation medium (Release 2025-04-01).
This is about some error entries in the system journal, which I encountered during copying this ISO image over. The respective transcripts are provided inline, as well as attached in the form of plain text files.
See https://github.com/systemd/systemd/issues/36624 and https://github.com/systemd/systemd/pull/36685 It appears that current udevd synchronously probes partition table of USB device. Your device seems to be too slow to answer in time while under write load, so udevd stalls in the ioctl syscall and fails to respond to the watchdog in time. As a consequence, systemd then kills the procees. It look as if this issue was fixed in March (see above), but that fix hasn't found its way into a release yet. Cheers, Basti
I used initially $ sudo cp <ISO> /dev/sda. After having finished that process, I spotted some error log entries in the system journal:
Apr 20 15:30:25 T470p sudo[21475]: friedrich : TTY=pts/2 ; PWD=/home/friedrich/(...) ; USER=root ; COMMAND=/usr/bin/cp archlinux-2025.04.01-x86_64.iso /dev/sda Apr 20 15:30:25 T470p sudo[21475]: pam_unix(sudo:session): session opened for user root(uid=0) by friedrich(uid=1000) Apr 20 15:33:10 T470p systemd[1]: systemd-udevd.service: Watchdog timeout (limit 3min)! Apr 20 15:33:10 T470p systemd[1]: systemd-udevd.service: Killing process 359 (systemd-udevd) with signal SIGABRT. Apr 20 15:34:40 T470p systemd[1]: systemd-udevd.service: State 'stop- watchdog' timed out. Killing. Apr 20 15:34:40 T470p systemd[1]: systemd-udevd.service: Killing process 359 (systemd-udevd) with signal SIGKILL. Apr 20 15:36:10 T470p systemd[1]: systemd-udevd.service: Processes still around after SIGKILL. Ignoring. Apr 20 15:37:38 T470p kernel: sda: sda1 sda2 Apr 20 15:37:38 T470p sudo[21475]: pam_unix(sudo:session): session closed for user root Apr 20 15:37:38 T470p systemd[1]: systemd-udevd.service: Main process exited, code=killed, status=9/KILL Apr 20 15:37:38 T470p systemd[1]: systemd-udevd.service: Failed with result 'watchdog'. Apr 20 15:37:38 T470p systemd[1]: systemd-udevd.service: Consumed 4.845s CPU time, 51.6M memory peak. Apr 20 15:37:38 T470p systemd[1]: systemd-udevd.service: Scheduled restart job, restart counter is at 1. Apr 20 15:37:38 T470p systemd[1]: Starting Rule-based Manager for Device Events and Files... Apr 20 15:37:39 T470p systemd-udevd[21582]: Using default interface naming scheme 'v257'. Apr 20 15:37:39 T470p systemd[1]: Started Rule-based Manager for Device Events and Files. Apr 20 15:38:19 T470p kernel: usb 1-1: USB disconnect, device number 7
Because I had doubts about the integrity of the thus prepared USB stick, I repeated the process, this time using $ su - and # dd if=<ISO> of=/dev/sda bs=8M. Here, I encountered similar logs:
Apr 20 15:38:53 T470p kernel: sda: sda1 sda2 Apr 20 15:38:53 T470p kernel: sd 0:0:0:0: [sda] Attached SCSI removable disk Apr 20 15:39:07 T470p su[21650]: (to root) friedrich on pts/2 Apr 20 15:39:07 T470p su[21650]: pam_unix(su:session): session opened for user root(uid=0) by friedrich(uid=1000) Apr 20 15:44:05 T470p systemd[1]: systemd-udevd.service: Watchdog timeout (limit 3min)! Apr 20 15:44:05 T470p systemd[1]: systemd-udevd.service: Killing process 21582 (systemd-udevd) with signal SIGABRT. Apr 20 15:45:35 T470p systemd[1]: systemd-udevd.service: State 'stop- watchdog' timed out. Killing. Apr 20 15:45:35 T470p systemd[1]: systemd-udevd.service: Killing process 21582 (systemd-udevd) with signal SIGKILL. Apr 20 15:47:05 T470p systemd[1]: systemd-udevd.service: Processes still around after SIGKILL. Ignoring. Apr 20 15:48:35 T470p systemd[1]: systemd-udevd.service: State 'final-sigterm' timed out. Killing. Apr 20 15:48:35 T470p systemd[1]: systemd-udevd.service: Killing process 21582 (systemd-udevd) with signal SIGKILL. Apr 20 15:48:56 T470p kernel: sda: sda1 sda2 Apr 20 15:48:56 T470p systemd[1]: systemd-udevd.service: Main process exited, code=killed, status=9/KILL Apr 20 15:48:56 T470p systemd[1]: systemd-udevd.service: Failed with result 'watchdog'. Apr 20 15:48:56 T470p systemd[1]: systemd-udevd.service: Consumed 1.101s CPU time, 7.4M memory peak. Apr 20 15:48:56 T470p systemd[1]: systemd-udevd.service: Scheduled restart job, restart counter is at 2. Apr 20 15:48:56 T470p systemd[1]: Starting Rule-based Manager for Device Events and Files... Apr 20 15:48:56 T470p systemd-udevd[21808]: Using default interface naming scheme 'v257'. Apr 20 15:48:56 T470p systemd[1]: Started Rule-based Manager for Device Events and Files. Apr 20 15:49:13 T470p kernel: usb 1-1: USB disconnect, device number 8
In the second run, where I kept an eye on the journal, I noticed that the error entries were logged a few minutes before the copying process completed. There were no errors reported by both of these directly.
The pen drive is booting and working just fine. However, I felt this behaviour being worth it to be reported. Maybe someone else can make sense of it.
Best, Friedrich
participants (4)
-
Friedrich Romstedt
-
mpan
-
Sean Snell
-
Sebastian Wiesner