Package: guix;
To reply to this bug, email your comments to 78852 AT debbugs.gnu.org.
Toggle the display of automated, internal messages from the tracker.
View this report as an mbox folder, status mbox, maintainer mbox
bug-guix <at> gnu.org:bug#78852; Package guix.
(Sat, 21 Jun 2025 07:27:04 GMT) Full text and rfc822 format available.burban <at> opopop.net:bug-guix <at> gnu.org.
(Sat, 21 Jun 2025 07:27:04 GMT) Full text and rfc822 format available.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.