Package: guix;
Message #5 received at submit <at> debbugs.gnu.org (full text, mbox):
From: burban <at> opopop.net To: bug-guix <at> gnu.org Subject: shepherd: internal syslog records not in chronological order Date: Fri, 20 Jun 2025 19:01:44 +0000
Hi,
I tried to replace package rsyslog by using shepherd internal logging
service. If everything is directed to say /var/log/shepherd, some lines
are out of sequence, below an example with 1.0.3 on Debian Trixie (the
--- lines are my comments and enclose deleted lines of no direct interest)
======================================
2025-06-19 23:56:11 localhost shepherd[1]: Stopping service mountall-bootclean...
2025-06-19 23:56:11 localhost shepherd[1]: Service mountall-bootclean stopped.
2025-06-19 23:56:11 localhost shepherd[1]: Service mountall-bootclean is now stopped.
... Above, the last recorded lines before shepĥerd syslog is stopped because we have to unmount /var before shutdown
2025-06-20 16:59:44 localhost linux: [ 0.000000] Linux version 6.1.0-21-amd64 (debian-kernel <at> lists.debian.org) (gcc-12 (Debian 12.2.0-14) 12.2.0, GNU ld (GNU Binutils for Debian) 2.40) #1 SMP PREEMPT_DYNAMIC Debian 6.1.90-1 (2024-05-03)
... /dev/kmsg and shepherd messages interleaved, but obviously not in chronological order
2025-06-20 16:59:44 localhost shepherd[1]: Service mountall running with value #t.
2025-06-20 16:59:44 localhost shepherd[1]: Starting service rsyslogd...
2025-06-20 16:59:44 localhost shepherd[1]: Service rsyslogd has been started.
2025-06-20 16:59:44 localhost shepherd[1]: Service rsyslogd started.
2025-06-20 16:59:44 localhost linux: [ 0.000000] Command line: BOOT_IMAGE=/boot/vmlinuz-6.1.0-21-amd64 root=UUID=b5539695-8658-493c-9197-a59078c20f65 ro init=/bin/shepherd quiet
2025-06-20 16:59:44 localhost shepherd[1]: Service rsyslogd running with value #<system-log 7fcf42806d00>.
2025-06-20 16:59:44 localhost shepherd[1]: Starting service mountall-bootclean...
2025-06-20 16:59:44 localhost shepherd[1]: Service mountall-bootclean started.
2025-06-20 16:59:44 localhost shepherd[1]: Service mountall-bootclean running with value #t.
2025-06-20 16:59:44 localhost linux: [ 0.000000] BIOS-provided physical RAM map:
2025-06-20 16:59:44 localhost shepherd[1]: Service mountall-bootclean has been started.
2025-06-20 16:59:44 localhost shepherd[1]: Starting service kernel-variables-setup...
2025-06-20 16:59:44 localhost linux: [ 0.000000] BIOS-e820: [mem 0x0000000000000000-0x000000000009fbff] usable
2025-06-20 16:59:44 localhost linux: [ 0.000000] BIOS-e820: [mem 0x000000000009fc00-0x000000000009ffff] reserved
2025-06-20 16:59:44 localhost linux: [ 0.000000] BIOS-e820: [mem 0x00000000000f0000-0x00000000000fffff] reserved
2025-06-20 16:59:44 localhost linux: [ 0.000000] BIOS-e820: [mem 0x0000000000100000-0x000000005dbdffff] usable
2025-06-20 16:59:44 localhost linux: [ 0.000000] BIOS-e820: [mem 0x000000005dbe0000-0x000000005dbfffff] reserved
...
2025-06-20 16:59:44 localhost linux: [ 0.038751] ACPI: INT_SRC_OVR (bus 0 bus_irq 11 global_irq 11 high level)
2025-06-20 16:59:44 localhost linux: [ 0.038755] ACPI: Using ACPI (MADT) for SMP configuration information
2025-06-20 16:59:44 localhost linux: [ 0.038756] ACPI: HPET id: 0x8086a201 base: 0xfed00000
2025-06-20 16:59:44 localhost linux: [ 0.038763] smpboot: Allowing 1 CPUs, 0 hotplug CPUs
2025-06-20 16:59:44 localhost shepherd[1]: Service kernel-variables-setup has been started.
2025-06-20 16:59:44 localhost linux: [ 0.038787] PM: hibernation: Registered nosave memory: [mem 0x00000000-0x00000fff]
2025-06-20 16:59:44 localhost shepherd[1]: Service kernel-variables-setup started.
2025-06-20 16:59:44 localhost shepherd[1]: Service kernel-variables-setup running with value #t.
2025-06-20 16:59:44 localhost shepherd[1]: Starting service random-generator-setup...
2025-06-20 16:59:44 localhost linux: [ 0.038788] PM: hibernation: Registered nosave memory: [mem 0x0009f000-0x0009ffff]
2025-06-20 16:59:44 localhost linux: [ 0.038789] PM: hibernation: Registered nosave memory: [mem 0x000a0000-0x000effff]
2025-06-20 16:59:44 localhost linux: [ 0.038790] PM: hibernation: Registered nosave memory: [mem 0x000f0000-0x000fffff]
2025-06-20 16:59:44 localhost linux: [ 0.038791] [mem 0x5dc00000-0xfeffbfff] available for PCI devices
2025-06-20 16:59:44 localhost linux: [ 0.038793] Booting paravirtualized kernel on KVM
2025-06-20 16:59:44 localhost linux: [ 0.038795] clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 7645519600211568 ns
...
2025-06-20 16:59:44 localhost linux: [ 0.236295] cblist_init_generic: Setting adjustable number of callback queues.
2025-06-20 16:59:44 localhost linux: [ 0.236295] cblist_init_generic: Setting shift to 0 and lim to 1.
2025-06-20 16:59:44 localhost linux: [ 0.236307] Performance Events: AMD PMU driver.
2025-06-20 16:59:44 localhost linux: [ 0.236319] ... version: 0
2025-06-20 16:59:44 localhost linux: [ 0.236320] ... bit width: 48
2025-06-20 16:59:44 localhost shepherd[1]: Registering new logger for random-generator-setup.
2025-06-20 16:59:44 localhost linux: [ 0.236321] ... generic registers: 4
2025-06-20 16:59:44 localhost linux: [ 0.236321] ... value mask: 0000ffffffffffff
...
2025-06-20 16:59:44 localhost linux: [ 0.268918] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177]
2025-06-20 16:59:44 localhost linux: [ 0.268919] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376]
2025-06-20 16:59:44 localhost linux: [ 0.269065] pci 0000:00:01.3: [8086:7113] type 00 class 0x068000
2025-06-20 16:59:44 localhost linux: [ 0.269392] pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI
2025-06-20 16:59:44 localhost shepherd[1]: Service random-generator-setup has been started.
2025-06-20 16:59:44 localhost shepherd[1]: Service random-generator-setup started.
2025-06-20 16:59:44 localhost shepherd[1]: Service random-generator-setup running with value #t.
2025-06-20 16:59:44 localhost linux: [ 0.269400] pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB
2025-06-20 16:59:44 localhost linux: [ 0.269557] pci 0000:00:02.0: [1b36:0100] type 00 class 0x030000
2025-06-20 16:59:44 localhost shepherd[1]: Starting service networking...
2025-06-20 16:59:44 localhost linux: [ 0.274591] pci 0000:00:02.0: reg 0x10: [mem 0xf4000000-0xf7ffffff]
2025-06-20 16:59:44 localhost linux: [ 0.275865] pci 0000:00:02.0: reg 0x14: [mem 0xf8000000-0xfbffffff]
2025-06-20 16:59:44 localhost linux: [ 0.276995] pci 0000:00:02.0: reg 0x18: [mem 0xfc070000-0xfc071fff]
...
2025-06-20 16:59:44 localhost linux: [ 1.365623] e1000 0000:00:03.0 eth0: Intel(R) PRO/1000 Network Connection
2025-06-20 16:59:44 localhost linux: [ 1.370623] e1000 0000:00:03.0 ens3: renamed from eth0
2025-06-20 16:59:44 localhost linux: [ 1.732827] EXT4-fs (sda1): mounted filesystem with ordered data mode. Quota mode: none.
2025-06-20 16:59:44 localhost linux: [ 2.722732] random: crng init done
... Here it becomes chronological
2025-06-20 16:59:44 localhost [ 3.030500] shepherd[1]: GNU Shepherd 1.0.3 (Guile 3.0.10, x86_64-pc-linux-gnu)
2025-06-20 16:59:44 localhost [ 3.030562] shepherd[1]: Starting service root...
2025-06-20 16:59:44 localhost [ 3.030809] shepherd[1]: Service root started.
2025-06-20 16:59:44 localhost [ 3.030863] shepherd[1]: Service root running with value #<<process> id: 1 command: #f>.
2025-06-20 16:59:44 localhost [ 3.031057] shepherd[1]: Service root has been started.
2025-06-20 16:59:44 localhost [ 3.034142] shepherd[1]: Starting service hostname-setup...
2025-06-20 16:59:44 localhost [ 3.034197] shepherd[1]: Service hostname-setup started.
2025-06-20 16:59:44 localhost [ 3.034461] shepherd[1]: Service hostname-setup running with value #t.
2025-06-20 16:59:44 localhost [ 3.034518] shepherd[1]: Service hostname-setup has been started.
2025-06-20 16:59:44 localhost [ 3.035999] shepherd[1]: Starting service mount-in-memory-fs...
2025-06-20 16:59:44 localhost [ 3.036057] shepherd[1]: Service mount-in-memory-fs started.
2025-06-20 16:59:44 localhost [ 3.036388] shepherd[1]: Service mount-in-memory-fs running with value #t.
2025-06-20 16:59:44 localhost [ 3.036447] shepherd[1]: Service mount-in-memory-fs has been started.
2025-06-20 16:59:44 localhost [ 3.054568] shepherd[1]: Starting service udev...
2025-06-20 16:59:44 localhost [ 3.093498] shepherd[1]: Registering new logger for udev.
2025-06-20 16:59:44 localhost [ 3.116002] shepherd[1]: Registering new logger for udev.
2025-06-20 16:59:44 localhost [ 3.187339] shepherd[1]: Registering new logger for udev.
2025-06-20 16:59:44 localhost linux: [ 3.215368] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input4
2025-06-20 16:59:44 localhost linux: [ 3.232540] ACPI: button: Power Button [PWRF]
2025-06-20 16:59:44 localhost linux: [ 3.246655] sd 0:0:0:0: Attached scsi generic sg0 type 0
2025-06-20 16:59:44 localhost linux: [ 3.247738] sr 1:0:0:0: Attached scsi generic sg1 type 5
2025-06-20 16:59:44 localhost linux: [ 3.251667] input: PC Speaker as /devices/platform/pcspkr/input/input5
2025-06-20 16:59:44 localhost linux: [ 3.281398] parport_pc 00:03: reported by Plug and Play ACPI
2025-06-20 16:59:44 localhost linux: [ 3.281518] parport0: PC-style at 0x378, irq 7 [PCSPP,TRISTATE]
2025-06-20 16:59:44 localhost linux: [ 3.301153] powernow_k8: Power state transitions not supported
2025-06-20 16:59:44 localhost linux: [ 3.378137] ACPI: bus type drm_connector registered
2025-06-20 16:59:44 localhost linux: [ 3.404776] ppdev: user-space parallel port driver
2025-06-20 16:59:44 localhost linux: [ 3.486541] ACPI: \_SB_.LNKB: Enabled at IRQ 10
2025-06-20 16:59:44 localhost linux: [ 3.492591] qxl 0000:00:02.0: vgaarb: deactivate vga console
2025-06-20 16:59:44 localhost linux: [ 3.494655] Console: switching to colour dummy device 80x25
2025-06-20 16:59:44 localhost linux: [ 3.495068] [drm] Device Version 0.0
2025-06-20 16:59:44 localhost linux: [ 3.495070] [drm] Compression level 0 log level 0
2025-06-20 16:59:44 localhost linux: [ 3.495072] [drm] 12286 io pages at offset 0x1000000
2025-06-20 16:59:44 localhost linux: [ 3.495073] [drm] 16777216 byte draw area at offset 0x0
2025-06-20 16:59:44 localhost linux: [ 3.495074] [drm] RAM header offset: 0x3ffe000
2025-06-20 16:59:44 localhost linux: [ 3.495091] [drm] qxl: 16M of VRAM memory size
2025-06-20 16:59:44 localhost linux: [ 3.495092] [drm] qxl: 63M of IO pages memory ready (VRAM domain)
2025-06-20 16:59:44 localhost linux: [ 3.495092] [drm] qxl: 64M of Surface memory size
2025-06-20 16:59:44 localhost linux: [ 3.498461] [drm] slot 0 (main): base 0xf4000000, size 0x03ffe000
2025-06-20 16:59:44 localhost linux: [ 3.498698] [drm] slot 1 (surfaces): base 0xf8000000, size 0x04000000
2025-06-20 16:59:44 localhost linux: [ 3.500535] [drm] Initialized qxl 0.1.0 20120117 for 0000:00:02.0 on minor 0
2025-06-20 16:59:44 localhost linux: [ 3.502612] fbcon: qxldrmfb (fb0) is primary device
2025-06-20 16:59:44 localhost linux: [ 3.514985] Console: switching to colour frame buffer device 128x48
2025-06-20 16:59:44 localhost linux: [ 3.534724] qxl 0000:00:02.0: [drm] fb0: qxldrmfb frame buffer device
2025-06-20 16:59:44 localhost [ 3.643887] shepherd[1]: Service udev has been started.
2025-06-20 16:59:44 localhost [ 3.643958] shepherd[1]: Service udev started.
2025-06-20 16:59:44 localhost [ 3.646046] shepherd[1]: Service udev running with value #t.
2025-06-20 16:59:44 localhost [ 3.646148] shepherd[1]: Starting service keyboard-setup...
2025-06-20 16:59:44 localhost [ 3.750186] shepherd[1]: Service keyboard-setup has been started.
2025-06-20 16:59:44 localhost [ 3.750248] shepherd[1]: Service keyboard-setup started.
2025-06-20 16:59:44 localhost [ 3.751417] shepherd[1]: Service keyboard-setup running with value #t.
2025-06-20 16:59:44 localhost [ 3.751506] shepherd[1]: Starting service mount-in-memory-fs-step2...
2025-06-20 16:59:44 localhost [ 3.751807] shepherd[1]: Service mount-in-memory-fs-step2 started.
2025-06-20 16:59:44 localhost [ 3.751878] shepherd[1]: Service mount-in-memory-fs-step2 running with value #t.
2025-06-20 16:59:44 localhost [ 3.753542] shepherd[1]: Service mount-in-memory-fs-step2 has been started.
2025-06-20 16:59:44 localhost [ 3.753654] shepherd[1]: Starting service clock-setup...
2025-06-20 16:59:44 localhost linux: [ 3.791255] e1000: ens3 NIC Link is Up 1000 Mbps Full Duplex, Flow Control: RX
2025-06-20 16:59:44 localhost linux: [ 3.791588] IPv6: ADDRCONF(NETDEV_CHANGE): ens3: link becomes ready
2025-06-20 16:59:44 localhost [ 4.469090] shepherd[1]: Service clock-setup has been started.
2025-06-20 16:59:44 localhost [ 4.469215] shepherd[1]: Service clock-setup started.
2025-06-20 16:59:44 localhost [ 4.470516] shepherd[1]: Service clock-setup running with value #t.
2025-06-20 16:59:44 localhost [ 4.470640] shepherd[1]: Starting service lvm2...
2025-06-20 16:59:44 localhost [ 4.471648] shepherd[1]: Service lvm2 started.
2025-06-20 16:59:44 localhost [ 4.471947] shepherd[1]: Service lvm2 running with value #t.
2025-06-20 16:59:44 localhost [ 4.474070] shepherd[1]: Service lvm2 has been started.
2025-06-20 16:59:44 localhost [ 4.474255] shepherd[1]: Starting service checkroot...
2025-06-20 16:59:44 localhost [ 4.493280] shepherd[1]: Registering new logger for checkroot.
2025-06-20 16:59:44 localhost [ 4.499054] shepherd[1]: [sh] fsck from util-linux 2.41
2025-06-20 16:59:44 localhost [ 4.512264] shepherd[1]: [sh] /dev/sda1: clean, 98380/327680 files, 1045202/1310464 blocks
2025-06-20 16:59:44 localhost [ 4.524805] shepherd[1]: Registering new logger for checkroot.
2025-06-20 16:59:44 localhost linux: [ 4.535819] EXT4-fs (sda1): re-mounted. Quota mode: none.
2025-06-20 16:59:44 localhost [ 4.538460] shepherd[1]: Service checkroot has been started.
2025-06-20 16:59:44 localhost [ 4.538603] shepherd[1]: Service checkroot started.
2025-06-20 16:59:44 localhost [ 4.540942] shepherd[1]: Service checkroot running with value #t.
2025-06-20 16:59:44 localhost [ 4.541119] shepherd[1]: Starting service checkfs...
2025-06-20 16:59:44 localhost [ 4.545450] shepherd[1]: [fsck] fsck from util-linux 2.41
2025-06-20 16:59:44 localhost [ 4.546057] shepherd[1]: [fsck] Checking all file systems.
2025-06-20 16:59:44 localhost [ 4.548674] shepherd[1]: Service checkfs has been started.
2025-06-20 16:59:44 localhost [ 4.548840] shepherd[1]: Service checkfs started.
2025-06-20 16:59:44 localhost [ 4.556793] shepherd[1]: Service checkfs running with value #t.
2025-06-20 16:59:44 localhost [ 4.556939] shepherd[1]: Starting service checkroot-bootclean...
2025-06-20 16:59:44 localhost [ 4.557313] shepherd[1]: Service checkroot-bootclean started.
2025-06-20 16:59:44 localhost [ 4.557382] shepherd[1]: Service checkroot-bootclean running with value #t.
2025-06-20 16:59:44 localhost [ 4.565002] shepherd[1]: Service checkroot-bootclean has been started.
2025-06-20 16:59:44 localhost [ 4.565070] shepherd[1]: Starting service load-kernel-modules...
2025-06-20 16:59:44 localhost [ 4.565415] shepherd[1]: Service load-kernel-modules started.
2025-06-20 16:59:44 localhost [ 4.565484] shepherd[1]: Service load-kernel-modules running with value #t.
2025-06-20 16:59:44 localhost [ 4.567805] shepherd[1]: Service load-kernel-modules has been started.
2025-06-20 16:59:44 localhost [ 4.567882] shepherd[1]: Starting service mountall...
2025-06-20 16:59:44 localhost [ 4.571050] shepherd[1]: Service mountall has been started.
2025-06-20 16:59:44 localhost [ 4.571110] shepherd[1]: Service mountall started.
... Remember that we had message "Service mountall running with value
#t." followed by messages about services mountall-bootclean, kernel-variables-setup,
random-generator-setup, networking at he top of the file.
The dependencies order is: load-kernel-modules, mountall (to mount /var), rsyslogd (shepherd syslog),
mountall-bootclean, kernel-variables-setup, random-generator-setup, networking
Below, the formatting changes as shepherd syslog has kicked in
2025-06-20 16:59:44 localhost shepherd[1]: Registering new logger for networking.
2025-06-20 16:59:44 localhost shepherd[1]: Service networking has been started.
2025-06-20 16:59:44 localhost shepherd[1]: Service networking started.
2025-06-20 16:59:44 localhost shepherd[1]: Service networking running with value #t.
2025-06-20 16:59:44 localhost shepherd[1]: Starting service console-setup...
2025-06-20 16:59:44 localhost shepherd[1]: Service console-setup has been started.
2025-06-20 16:59:44 localhost shepherd[1]: Service console-setup started.
2025-06-20 16:59:44 localhost shepherd[1]: Service console-setup running with value #t.
2025-06-20 16:59:44 localhost shepherd[1]: Starting service login-helper...
2025-06-20 16:59:44 localhost shepherd[1]: Service login-helper started.
2025-06-20 16:59:44 localhost shepherd[1]: Service login-helper running with value #t.
2025-06-20 16:59:44 localhost shepherd[1]: Service login-helper has been started.
2025-06-20 16:59:44 localhost shepherd[1]: Starting service X11-common...
2025-06-20 16:59:44 localhost shepherd[1]: Service X11-common started.
...
===============================================
This can be misleading as to what happens in the system. Is there a way to
avoid that behaviour?
Sincerely.
--
Bernard
GNU bug tracking system
Copyright (C) 1999 Darren O. Benham,
1997,2003 nCipher Corporation Ltd,
1994-97 Ian Jackson.