From debbugs-submit-bounces@debbugs.gnu.org Sat Jun 21 03:26:22 2025 Received: (at submit) by debbugs.gnu.org; 21 Jun 2025 07:26:22 +0000 Received: from localhost ([127.0.0.1]:60632 helo=debbugs.gnu.org) by debbugs.gnu.org with esmtp (Exim 4.84_2) (envelope-from ) id 1uSscF-00077d-7l for submit@debbugs.gnu.org; Sat, 21 Jun 2025 03:26:22 -0400 Received: from lists.gnu.org ([2001:470:142::17]:43590) by debbugs.gnu.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.84_2) (envelope-from ) id 1uSh09-0001aZ-0r for submit@debbugs.gnu.org; Fri, 20 Jun 2025 15:02:14 -0400 Received: from eggs.gnu.org ([2001:470:142:3::10]) by lists.gnu.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.90_1) (envelope-from ) id 1uSh02-0001Ml-Mm for bug-guix@gnu.org; Fri, 20 Jun 2025 15:02:07 -0400 Received: from [2a03:9da0:11:108::2] (helo=hagen2.opopop.net) by eggs.gnu.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.90_1) (envelope-from ) id 1uSgzx-0001Va-VT for bug-guix@gnu.org; Fri, 20 Jun 2025 15:02:06 -0400 DKIM-Signature: v=1; a=rsa-sha256; q=dns/txt; c=relaxed/relaxed; d=opopop.net; s=202504; h=Content-Transfer-Encoding:Content-Type:MIME-Version:Message-ID: Date:Subject:To:From:Sender:Reply-To:Cc:Content-ID:Content-Description: Resent-Date:Resent-From:Resent-Sender:Resent-To:Resent-Cc:Resent-Message-ID: In-Reply-To:References:List-Id:List-Help:List-Unsubscribe:List-Subscribe: List-Post:List-Owner:List-Archive; bh=X1n7/p+IxmWmg+Vg/b/w4v2g8ySNCUild4E+KMVhZaE=; b=d41ypdPGygIJCQQnYgL9WXSzAW /o3xvbEbnTylWkLl6gcFfdnHWyFX41VO9Wcwj8Nq/CSflrgFamhea9uisT5B/0CbwLF+N9A6ac0Tf f1mcAlwlyzWoTrRzKq62zbiqEVCvyEvZASVsfHrkdDfdnskNXKYsnFuybaJ7m6BmkbttsLTl73CLC p00ePZWXVrTxT6HkUd16lTXkIkSlPP81T4HECDSorRnyMD09l5FRmvBWIT91p0Utcr1yvEmZZ26du cjJpm3L4kg6qgbli3ew/pWSWFB66aT/6gPzYV/Q2gWxK37AlLGK+psjTBgdwLBrNBUeiCUcjObAX7 5Ju044sg==; Received: from localhost ([127.0.0.1] helo=hagen2) by hagen2 with esmtps (TLS1.3) tls TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384 (Exim 4.96) (envelope-from ) id 1uSgzj-000I4j-2Y for bug-guix@gnu.org; Fri, 20 Jun 2025 19:01:48 +0000 From: burban@opopop.net To: bug-guix@gnu.org Subject: shepherd: internal syslog records not in chronological order Date: Fri, 20 Jun 2025 19:01:44 +0000 Message-ID: <87o6uifd9j.fsf@opopop.net> User-Agent: Gnus/5.13 (Gnus v5.13) Emacs/28.2 (gnu/linux) MIME-Version: 1.0 Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: quoted-printable X-Host-Lookup-Failed: Reverse DNS lookup failed for 2a03:9da0:11:108::2 (failed) Received-SPF: pass client-ip=2a03:9da0:11:108::2; envelope-from=burban@opopop.net; helo=hagen2.opopop.net X-Spam_score_int: -12 X-Spam_score: -1.3 X-Spam_bar: - X-Spam_report: (-1.3 / 5.0 requ) BAYES_00=-1.9, DKIM_SIGNED=0.1, DKIM_VALID=-0.1, DKIM_VALID_AU=-0.1, DKIM_VALID_EF=-0.1, RDNS_NONE=0.793, SPF_HELO_NONE=0.001, SPF_PASS=-0.001 autolearn=no autolearn_force=no X-Spam_action: no action X-Spam-Score: 0.9 (/) X-Debbugs-Envelope-To: submit X-Mailman-Approved-At: Sat, 21 Jun 2025 03:26:17 -0400 X-BeenThere: debbugs-submit@debbugs.gnu.org X-Mailman-Version: 2.1.18 Precedence: list List-Id: List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , Errors-To: debbugs-submit-bounces@debbugs.gnu.org Sender: "Debbugs-submit" X-Spam-Score: -0.1 (/) 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)= =20 =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D= =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D 2025-06-19 23:56:11 localhost shepherd[1]: Stopping service mountall-bootcl= ean... 2025-06-19 23:56:11 localhost shepherd[1]: Service mountall-bootclean stopp= ed. 2025-06-19 23:56:11 localhost shepherd[1]: Service mountall-bootclean is no= w stopped. ... Above, the last recorded lines before shep=C4=A5erd syslog is stopped b= ecause 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@lists.debian.org) (gcc-12 (Debian 12.2.0-14) 12.2.0, G= NU 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 chron= ological order 2025-06-20 16:59:44 localhost shepherd[1]: Service mountall running with va= lue #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 starte= d. 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_IMAG= E=3D/boot/vmlinuz-6.1.0-21-amd64 root=3DUUID=3Db5539695-8658-493c-9197-a590= 78c20f65 ro init=3D/bin/shepherd quiet 2025-06-20 16:59:44 localhost shepherd[1]: Service rsyslogd running with va= lue #. 2025-06-20 16:59:44 localhost shepherd[1]: Starting service mountall-bootcl= ean... 2025-06-20 16:59:44 localhost shepherd[1]: Service mountall-bootclean start= ed. 2025-06-20 16:59:44 localhost shepherd[1]: Service mountall-bootclean runni= ng 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 b= een started. 2025-06-20 16:59:44 localhost shepherd[1]: Starting service kernel-variable= s-setup... 2025-06-20 16:59:44 localhost linux: [ 0.000000] BIOS-e820: [mem 0x00000= 00000000000-0x000000000009fbff] usable 2025-06-20 16:59:44 localhost linux: [ 0.000000] BIOS-e820: [mem 0x00000= 0000009fc00-0x000000000009ffff] reserved 2025-06-20 16:59:44 localhost linux: [ 0.000000] BIOS-e820: [mem 0x00000= 000000f0000-0x00000000000fffff] reserved 2025-06-20 16:59:44 localhost linux: [ 0.000000] BIOS-e820: [mem 0x00000= 00000100000-0x000000005dbdffff] usable 2025-06-20 16:59:44 localhost linux: [ 0.000000] BIOS-e820: [mem 0x00000= 0005dbe0000-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: 0x8086a2= 01 base: 0xfed00000 2025-06-20 16:59:44 localhost linux: [ 0.038763] smpboot: Allowing 1 CPU= s, 0 hotplug CPUs 2025-06-20 16:59:44 localhost shepherd[1]: Service kernel-variables-setup h= as been started. 2025-06-20 16:59:44 localhost linux: [ 0.038787] PM: hibernation: Regist= ered nosave memory: [mem 0x00000000-0x00000fff] 2025-06-20 16:59:44 localhost shepherd[1]: Service kernel-variables-setup s= tarted. 2025-06-20 16:59:44 localhost shepherd[1]: Service kernel-variables-setup r= unning with value #t. 2025-06-20 16:59:44 localhost shepherd[1]: Starting service random-generato= r-setup... 2025-06-20 16:59:44 localhost linux: [ 0.038788] PM: hibernation: Regist= ered nosave memory: [mem 0x0009f000-0x0009ffff] 2025-06-20 16:59:44 localhost linux: [ 0.038789] PM: hibernation: Regist= ered nosave memory: [mem 0x000a0000-0x000effff] 2025-06-20 16:59:44 localhost linux: [ 0.038790] PM: hibernation: Regist= ered nosave memory: [mem 0x000f0000-0x000fffff] 2025-06-20 16:59:44 localhost linux: [ 0.038791] [mem 0x5dc00000-0xfeffb= fff] 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-ji= ffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 76455196002115= 68 ns ... 2025-06-20 16:59:44 localhost linux: [ 0.236295] cblist_init_generic: Se= tting adjustable number of callback queues. 2025-06-20 16:59:44 localhost linux: [ 0.236295] cblist_init_generic: Se= tting 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 rando= m-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: legac= y IDE quirk: reg 0x18: [io 0x0170-0x0177] 2025-06-20 16:59:44 localhost linux: [ 0.268919] pci 0000:00:01.1: legac= y 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 h= as been started. 2025-06-20 16:59:44 localhost shepherd[1]: Service random-generator-setup s= tarted. 2025-06-20 16:59:44 localhost shepherd[1]: Service random-generator-setup r= unning 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 0= x10: [mem 0xf4000000-0xf7ffffff] 2025-06-20 16:59:44 localhost linux: [ 0.275865] pci 0000:00:02.0: reg 0= x14: [mem 0xf8000000-0xfbffffff] 2025-06-20 16:59:44 localhost linux: [ 0.276995] pci 0000:00:02.0: reg 0= x18: [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 star= ted. 2025-06-20 16:59:44 localhost [ 3.030863] shepherd[1]: Service root runn= ing with value #< 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 l= ogger for udev. 2025-06-20 16:59:44 localhost [ 3.116002] shepherd[1]: Registering new l= ogger for udev. 2025-06-20 16:59:44 localhost [ 3.187339] shepherd[1]: Registering new l= ogger 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 But= ton [PWRF] 2025-06-20 16:59:44 localhost linux: [ 3.246655] sd 0:0:0:0: Attached sc= si generic sg0 type 0 2025-06-20 16:59:44 localhost linux: [ 3.247738] sr 1:0:0:0: Attached sc= si generic sg1 type 5 2025-06-20 16:59:44 localhost linux: [ 3.251667] input: PC Speaker as /d= evices/platform/pcspkr/input/input5 2025-06-20 16:59:44 localhost linux: [ 3.281398] parport_pc 00:03: repor= ted by Plug and Play ACPI 2025-06-20 16:59:44 localhost linux: [ 3.281518] parport0: PC-style at 0= x378, irq 7 [PCSPP,TRISTATE] 2025-06-20 16:59:44 localhost linux: [ 3.301153] powernow_k8: Power stat= e transitions not supported 2025-06-20 16:59:44 localhost linux: [ 3.378137] ACPI: bus type drm_conn= ector registered 2025-06-20 16:59:44 localhost linux: [ 3.404776] ppdev: user-space paral= lel port driver 2025-06-20 16:59:44 localhost linux: [ 3.486541] ACPI: \_SB_.LNKB: Enabl= ed at IRQ 10 2025-06-20 16:59:44 localhost linux: [ 3.492591] qxl 0000:00:02.0: vgaar= b: deactivate vga console 2025-06-20 16:59:44 localhost linux: [ 3.494655] Console: switching to c= olour 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 dra= w 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 pa= ges memory ready (VRAM domain) 2025-06-20 16:59:44 localhost linux: [ 3.495092] [drm] qxl: 64M of Surfa= ce memory size 2025-06-20 16:59:44 localhost linux: [ 3.498461] [drm] slot 0 (main): ba= se 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) i= s primary device 2025-06-20 16:59:44 localhost linux: [ 3.514985] Console: switching to c= olour 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 star= ted. 2025-06-20 16:59:44 localhost [ 3.646046] shepherd[1]: Service udev runn= ing 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_C= HANGE): ens3: link becomes ready 2025-06-20 16:59:44 localhost [ 4.469090] shepherd[1]: Service clock-set= up has been started. 2025-06-20 16:59:44 localhost [ 4.469215] shepherd[1]: Service clock-set= up started. 2025-06-20 16:59:44 localhost [ 4.470516] shepherd[1]: Service clock-set= up 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 star= ted. 2025-06-20 16:59:44 localhost [ 4.471947] shepherd[1]: Service lvm2 runn= ing 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 l= ogger for checkroot. 2025-06-20 16:59:44 localhost [ 4.499054] shepherd[1]: [sh] fsck from ut= il-linux 2.41 2025-06-20 16:59:44 localhost [ 4.512264] shepherd[1]: [sh] /dev/sda1: c= lean, 98380/327680 files, 1045202/1310464 blocks 2025-06-20 16:59:44 localhost [ 4.524805] shepherd[1]: Registering new l= ogger for checkroot. 2025-06-20 16:59:44 localhost linux: [ 4.535819] EXT4-fs (sda1): re-moun= ted. 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 a= ll file systems. 2025-06-20 16:59:44 localhost [ 4.548674] shepherd[1]: Service checkfs h= as been started. 2025-06-20 16:59:44 localhost [ 4.548840] shepherd[1]: Service checkfs s= tarted. 2025-06-20 16:59:44 localhost [ 4.556793] shepherd[1]: Service checkfs r= unning 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-kern= el-modules started. 2025-06-20 16:59:44 localhost [ 4.565484] shepherd[1]: Service load-kern= el-modules running with value #t. 2025-06-20 16:59:44 localhost [ 4.567805] shepherd[1]: Service load-kern= el-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-va= riables-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, net= working Below, the formatting changes as shepherd syslog has kicked in 2025-06-20 16:59:44 localhost shepherd[1]: Registering new logger for netwo= rking. 2025-06-20 16:59:44 localhost shepherd[1]: Service networking has been star= ted. 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 s= tarted. 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 wi= th 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 wit= h value #t. 2025-06-20 16:59:44 localhost shepherd[1]: Service login-helper has been st= arted. 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. ... =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D= =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D This can be misleading as to what happens in the system. Is there a way to avoid that behaviour? Sincerely. --=20 Bernard From debbugs-submit-bounces@debbugs.gnu.org Sun Jun 29 06:21:13 2025 Received: (at 78852) by debbugs.gnu.org; 29 Jun 2025 10:21:13 +0000 Received: from localhost ([127.0.0.1]:55070 helo=debbugs.gnu.org) by debbugs.gnu.org with esmtp (Exim 4.84_2) (envelope-from ) id 1uVp9s-00033W-O8 for submit@debbugs.gnu.org; Sun, 29 Jun 2025 06:21:13 -0400 Received: from eggs.gnu.org ([2001:470:142:3::10]:38602) by debbugs.gnu.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.84_2) (envelope-from ) id 1uVp9g-000305-33 for 78852@debbugs.gnu.org; Sun, 29 Jun 2025 06:21:00 -0400 Received: from fencepost.gnu.org ([2001:470:142:3::e]) by eggs.gnu.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.90_1) (envelope-from ) id 1uVp9a-0007wX-Dw; Sun, 29 Jun 2025 06:20:54 -0400 DKIM-Signature: v=1; a=rsa-sha256; q=dns/txt; c=relaxed/relaxed; d=gnu.org; s=fencepost-gnu-org; h=MIME-Version:Date:References:In-Reply-To:Subject:To: From; bh=aOu9DGH6Ozyec8fWdq0RiBz+8/s5wfxFr5iGFLtz2AA=; b=dd81BIvgkaw7krrTDidl LfSbG/Xk8tjCDZN7lcpA7XqVTd82dqzwL5J41gJuTMSjvnLLtFfiRRJRVogLZj3QsIS0T5ok4KfoR +QHTOD20623wg/HnTZnLVqKqpClMprmBvF3VARPdWHMgToVJDw620zF+S6oh3LxCOEEt42wNSCqoB va5X4q34r5UpwMRmBghtVuFKNAVto00+rmFGl1GJEUW4Cvd8URAgSSwGcimfEmVR7XPvJWZ0qZVFY DtBvMBk208gitdgKdogsA0Tw26T+c98FJEWcxmCT0YovlIWipnMOn8/ivyW/IZWudty9uT8XWqMat 4mjQJnMN4M0DUQ==; From: =?utf-8?Q?Ludovic_Court=C3=A8s?= To: burban@opopop.net Subject: Re: bug#78852: shepherd: internal syslog records not in chronological order In-Reply-To: <87o6uifd9j.fsf@opopop.net> (burban@opopop.net's message of "Fri, 20 Jun 2025 19:01:44 +0000") References: <87o6uifd9j.fsf@opopop.net> Date: Sun, 29 Jun 2025 12:19:49 +0200 Message-ID: <87ecv2u9x6.fsf@inria.fr> User-Agent: Gnus/5.13 (Gnus v5.13) MIME-Version: 1.0 Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: quoted-printable X-Spam-Score: -2.3 (--) X-Debbugs-Envelope-To: 78852 Cc: 78852@debbugs.gnu.org X-BeenThere: debbugs-submit@debbugs.gnu.org X-Mailman-Version: 2.1.18 Precedence: list List-Id: List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , Errors-To: debbugs-submit-bounces@debbugs.gnu.org Sender: "Debbugs-submit" X-Spam-Score: -3.3 (---) Hi, burban@opopop.net writes: > ... /dev/kmsg and shepherd messages interleaved, but obviously not in chr= onological 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 star= ted. > 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=3D/boot/vmlinuz-6.1.0-21-amd64 > root=3DUUID=3Db5539695-8658-493c-9197-a59078c20f65 ro init=3D/bin/shepherd > quiet > 2025-06-20 16:59:44 localhost shepherd[1]: Service rsyslogd running with = value #. > 2025-06-20 16:59:44 localhost shepherd[1]: Starting service mountall-boot= clean... > 2025-06-20 16:59:44 localhost shepherd[1]: Service mountall-bootclean sta= rted. > 2025-06-20 16:59:44 localhost shepherd[1]: Service mountall-bootclean run= ning with value #t. > 2025-06-20 16:59:44 localhost linux: [ 0.000000] BIOS-provided physica= l RAM map: /dev/kmsg is read when =E2=80=98system-log=E2=80=99 starts, and it already = contains lots of lines. These lines are dumped concurrently with logging output coming from shepherd services, hence this behavior. The problem is that /dev/kmsg doesn=E2=80=99t associate a proper timestamp = with each line (only the elapsed time since boot in square brackets). Thus I=E2=80=99m not sure what can be done here. If you have ideas from other such systems, please share! Thanks, Ludo=E2=80=99. From debbugs-submit-bounces@debbugs.gnu.org Wed Jul 02 20:34:51 2025 Received: (at 78852) by debbugs.gnu.org; 3 Jul 2025 00:34:52 +0000 Received: from localhost ([127.0.0.1]:40723 helo=debbugs.gnu.org) by debbugs.gnu.org with esmtp (Exim 4.84_2) (envelope-from ) id 1uX7uc-0006V1-7D for submit@debbugs.gnu.org; Wed, 02 Jul 2025 20:34:51 -0400 Received: from [2a03:9da0:11:108::2] (port=58364 helo=hagen2.opopop.net) by debbugs.gnu.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.84_2) (envelope-from ) id 1uX6S8-000173-6H for 78852@debbugs.gnu.org; Wed, 02 Jul 2025 19:01:21 -0400 DKIM-Signature: v=1; a=rsa-sha256; q=dns/txt; c=relaxed/relaxed; d=opopop.net; s=202506; h=Content-Transfer-Encoding:Content-Type:MIME-Version:Message-ID: In-Reply-To:Date:References:Subject:Cc:To:From:Sender:Reply-To:Content-ID: Content-Description:Resent-Date:Resent-From:Resent-Sender:Resent-To:Resent-Cc :Resent-Message-ID:List-Id:List-Help:List-Unsubscribe:List-Subscribe: List-Post:List-Owner:List-Archive; bh=CVWzqS2GSbT13qD4iX9ZyPu0IKL2spMoSOatpCfynWs=; b=tgrpDqgUzON+0nAkmAtdsYRK/M tjoVEq2sl1/6VsbrPPdBvXWSIZRzqVgKLVPEL9GuatDvS4gHMly7b3do4lxOu8AvlsP5xKqcfzNdF iqid/xykKOXnoON7NHLtZDKaRM9WJTlyKQ9iXR5nauf67aAcdHoNomb7oDihjcbEvG/e4vZ26iC94 ImVXhTEYHXIT0TwRPEAr9/80F78cRZ/UmOh9vmQdgnH1pxXNG4PDkBeepBJJ1RSXO2M0QioetHGDB QnDRuNAS4ipbK72SZXOLDuJ4yEnq4rh63I4q7KUrYKKxW6H3G4TfufkAJmlGrlo6oL3F6pcOR3S2l LjJQ0/Yw==; Received: from localhost ([127.0.0.1] helo=hagen2) by hagen2.opopop.net with esmtps (TLS1.3) tls TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384 (Exim 4.96) (envelope-from ) id 1uX6S1-000Lm3-2Y; Wed, 02 Jul 2025 23:01:13 +0000 From: burban@opopop.net To: Ludovic =?utf-8?Q?Court=C3=A8s?= Subject: Re: bug#78852: shepherd: internal syslog records not in chronological order References: <87o6uifd9j.fsf@opopop.net> <87ecv2u9x6.fsf@inria.fr> Date: Wed, 02 Jul 2025 23:01:13 +0000 In-Reply-To: <87ecv2u9x6.fsf@inria.fr> ("Ludovic =?utf-8?Q?Court=C3=A8s=22?= =?utf-8?Q?'s?= message of "Sun, 29 Jun 2025 12:19:49 +0200") Message-ID: <871pqy5hae.fsf@opopop.net> User-Agent: Gnus/5.13 (Gnus v5.13) Emacs/28.2 (gnu/linux) MIME-Version: 1.0 Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: quoted-printable X-Spam-Score: 1.3 (+) X-Spam-Report: Spam detection software, running on the system "debbugs.gnu.org", has NOT identified this incoming email as spam. The original message has been attached to this so you can view it or label similar future email. If you have any questions, see the administrator of that system for details. Content preview: Hello, That the lines from /dev/kmsg are dumped concurrently with these from shepherd services is to be expected of course. But when ‘system-log’ starts, it would be logical to flush first /proc/kmesg while keeping on hold it's own messaging until that is done. Content analysis details: (1.3 points, 10.0 required) pts rule name description ---- ---------------------- -------------------------------------------------- -0.0 SPF_PASS SPF: sender matches SPF record 0.0 SPF_HELO_NONE SPF: HELO does not publish an SPF Record 1.3 RDNS_NONE Delivered to internal network by a host with no rDNS X-Debbugs-Envelope-To: 78852 X-Mailman-Approved-At: Wed, 02 Jul 2025 20:34:48 -0400 Cc: 78852@debbugs.gnu.org X-BeenThere: debbugs-submit@debbugs.gnu.org X-Mailman-Version: 2.1.18 Precedence: list List-Id: List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , Errors-To: debbugs-submit-bounces@debbugs.gnu.org Sender: "Debbugs-submit" X-Spam-Score: 0.3 (/) Hello, That the lines from /dev/kmsg are dumped concurrently with these from shepherd services is to be expected of course. But when =E2=80=98system-log=E2=80=99 starts, it would be logical to flush = first /proc/kmesg while keeping on hold it's own messaging until that is done. I don't know how hard that would be to implement, my hope was that the syslog service is already a bit special (it's generated with hard coded start and stop for instance). And yes, timestamps in the boot process logs are bogus also with traditional logging systems before they start, but the ordering is at least ok. Ludovic Court=C3=A8s writes: > Hi, > > burban@opopop.net writes: > >> ... /dev/kmsg and shepherd messages interleaved, but obviously not in ch= ronological 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 sta= rted. >> 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=3D/boot/vmlinuz-6.1.0-21-amd64 >> root=3DUUID=3Db5539695-8658-493c-9197-a59078c20f65 ro init=3D/bin/shephe= rd >> quiet >> 2025-06-20 16:59:44 localhost shepherd[1]: Service rsyslogd running with= value #. >> 2025-06-20 16:59:44 localhost shepherd[1]: Starting service mountall-boo= tclean... >> 2025-06-20 16:59:44 localhost shepherd[1]: Service mountall-bootclean st= arted. >> 2025-06-20 16:59:44 localhost shepherd[1]: Service mountall-bootclean ru= nning with value #t. >> 2025-06-20 16:59:44 localhost linux: [ 0.000000] BIOS-provided physic= al RAM map: > > /dev/kmsg is read when =E2=80=98system-log=E2=80=99 starts, and it alread= y contains lots > of lines. These lines are dumped concurrently with logging output > coming from shepherd services, hence this behavior. > > The problem is that /dev/kmsg doesn=E2=80=99t associate a proper timestam= p with > each line (only the elapsed time since boot in square brackets). Thus > I=E2=80=99m not sure what can be done here. > > If you have ideas from other such systems, please share! > > Thanks, > Ludo=E2=80=99. Sincerely. --=20 Bernard From debbugs-submit-bounces@debbugs.gnu.org Thu Jul 03 03:45:30 2025 Received: (at 78852) by debbugs.gnu.org; 3 Jul 2025 07:45:30 +0000 Received: from localhost ([127.0.0.1]:42387 helo=debbugs.gnu.org) by debbugs.gnu.org with esmtp (Exim 4.84_2) (envelope-from ) id 1uXEdM-0004AG-Ux for submit@debbugs.gnu.org; Thu, 03 Jul 2025 03:45:29 -0400 Received: from eggs.gnu.org ([2001:470:142:3::10]:44806) by debbugs.gnu.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.84_2) (envelope-from ) id 1uXEdH-000482-T9 for 78852@debbugs.gnu.org; Thu, 03 Jul 2025 03:45:24 -0400 Received: from fencepost.gnu.org ([2001:470:142:3::e]) by eggs.gnu.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.90_1) (envelope-from ) id 1uXEdB-000580-H3; Thu, 03 Jul 2025 03:45:17 -0400 DKIM-Signature: v=1; a=rsa-sha256; q=dns/txt; c=relaxed/relaxed; d=gnu.org; s=fencepost-gnu-org; h=MIME-Version:Date:References:In-Reply-To:Subject:To: From; bh=rbEGfZwh5BlfcxqN96FWAp8ICqKdqGRxCoKWR9+18AI=; b=OzJb/AHW4xqKnnYbVl0v WRVmp8cx+LQTsyn+CNindjX6h/RXmjSyCjmcOpXtct2nCSN6KG5mFo5NzTcOymAdszGKvvBNzardJ kfTdyIfWJbnU6x+4BdobZ3UQ1gvxu1MWYrQdKZEOTHxNQxGuiPZG0LLir71qftCYNP8IscXbAqYSH saIlQEaPOiT74lgJJ5kLgfFCVysYcGXPgq/ScY4CITVcM0dpv4xzFpMD/WdB6zhE1qo2f9x6RYZwN zLgSQaNu7PnZu/QNDLMybvnb0LHmH3t6MYW/ix7XOCGTOIEY4hXfCC7WNwNw7WJXn+9hs53Q+KfvC vvvKNbitXMNE7Q==; From: =?utf-8?Q?Ludovic_Court=C3=A8s?= To: burban@opopop.net Subject: Re: bug#78852: shepherd: internal syslog records not in chronological order In-Reply-To: <871pqy5hae.fsf@opopop.net> (burban@opopop.net's message of "Wed, 02 Jul 2025 23:01:13 +0000") References: <87o6uifd9j.fsf@opopop.net> <87ecv2u9x6.fsf@inria.fr> <871pqy5hae.fsf@opopop.net> User-Agent: mu4e 1.12.11; emacs 30.1 X-URL: https://people.bordeaux.inria.fr/lcourtes/ X-PGP-Fingerprint: 3CE4 6455 8A84 FDC6 9DB4 0CFB 090B 1199 3D9A EBB5 X-OS: x86_64-pc-linux-gnu X-Revolutionary-Date: Quintidi 15 Messidor an 233 de la =?utf-8?Q?R=C3=A9v?= =?utf-8?Q?olution=2C?= jour du Chamois Date: Thu, 03 Jul 2025 09:43:46 +0200 Message-ID: <87plehvhvx.fsf@gnu.org> MIME-Version: 1.0 Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: quoted-printable X-Spam-Score: -2.3 (--) X-Debbugs-Envelope-To: 78852 Cc: 78852@debbugs.gnu.org X-BeenThere: debbugs-submit@debbugs.gnu.org X-Mailman-Version: 2.1.18 Precedence: list List-Id: List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , Errors-To: debbugs-submit-bounces@debbugs.gnu.org Sender: "Debbugs-submit" X-Spam-Score: -3.3 (---) Hi, burban@opopop.net writes: > But when =E2=80=98system-log=E2=80=99 starts, it would be logical to flus= h first > /proc/kmesg while keeping on hold it's own messaging until that is > done. OK. As it stands, flushing /dev/kmsg before the other messages get written is hard to implement: /dev/kmsg is considered as just one of several sources of =E2=80=98system-log=E2=80=99, which just logs every line= of every source as soon as it=E2=80=99s available=E2=80=94hence the interleaving. It needs more thought though, maybe we can find a way to do that. Thanks, Ludo=E2=80=99.