NetBSD Problem Report #56797

From www@netbsd.org  Fri Apr 15 12:51:25 2022
Return-Path: <www@netbsd.org>
Received: from mail.netbsd.org (mail.netbsd.org [199.233.217.200])
	(using TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits))
	(Client CN "mail.NetBSD.org", Issuer "mail.NetBSD.org CA" (not verified))
	by mollari.NetBSD.org (Postfix) with ESMTPS id 36A9D1A921F
	for <gnats-bugs@gnats.NetBSD.org>; Fri, 15 Apr 2022 12:51:25 +0000 (UTC)
Message-Id: <20220415125123.7247C1A923B@mollari.NetBSD.org>
Date: Fri, 15 Apr 2022 12:51:23 +0000 (UTC)
From: uwe@stderr.spb.ru
Reply-To: uwe@stderr.spb.ru
To: gnats-bugs@NetBSD.org
Subject: timestamps messed up in quiet boot dmesg
X-Send-Pr-Version: www-1.0

>Number:         56797
>Category:       kern
>Synopsis:       timestamps messed up in quiet boot dmesg
>Confidential:   no
>Severity:       non-critical
>Priority:       low
>Responsible:    kern-bug-people
>State:          open
>Class:          sw-bug
>Submitter-Id:   net
>Arrival-Date:   Fri Apr 15 12:55:00 +0000 2022
>Last-Modified:  Tue Apr 19 13:25:01 +0000 2022
>Originator:     Valery Ushakov
>Release:        NetBSD-9.99.96
>Organization:
>Environment:
>Description:
When you boot quietly with -q the timestamps in the autoconf output
are all messed up.  Some of them are at the beginning of the line,
some are only after the "dev42 at bus666" part of the message, some
have no timestamp at all.  E.g. booting amd64 kernel with -q has in
the dmesg something like:

[     1.000003] timecounter: Timecounter "ACPI-Safe" frequency 3579545 Hz quality 900
pckbc1 at acpi0 (PS2K, PNP0303) (kbd port): io 0x60,0x64 irq 1
pckbc2 at acpi0 (PS2M, PNP0F03) (aux port): irq 12
attimer1 at acpi0 (TIMR, PNP0100): io 0x40-0x43,0x50-0x53
com0 at acpi0 (SRL0, PNP0501-1): io 0x3f8-0x3ff irq 4
[     1.030283] com0[   1.0302834] : ns16550a, 16-byte FIFO
[     1.030283] com0: console
acpivga0 at acpi0 (GFX0)[   1.0302834] : ACPI Display Adapter
acpiout0 at acpivga0 (VGA, 0x0100)[   1.0302834] : ACPI Display Output Device
[     1.030283] acpivga0: connected output devices:
[     1.030283] acpivga0:   0x0100 (acpiout0): VGA Analog Monitor, index 0, port 0, head 0
acpibat0 at acpi0 (BAT0, PNP0C0A-0)[   1.0302834] : ACPI Battery
acpiacad0 at acpi0 (AC, ACPI0003-0)[   1.0302834] : ACPI AC Adapter
pckbd0 at pckbc1 (kbd slot)
[     1.030283] pckbc1: using irq 1 for kbd slot
wskbd0 at pckbd0 mux 1
pms0 at pckbc1 (aux slot)
[     1.030283] pckbc1: using irq 12 for aux slot
wsmouse0 at pms0 mux 0
pci0 at mainbus0 bus 0: configuration mode 1
[     1.030283] pci0: MSI/MSI-X OK because VM guest.


The console output is mostly ok, but has a couple of gliches too, e.g.

[   1.0302834] Found vioif0 at virtio0
[   1.0302834] Found auich0 at pci0: Audio controller
[   1.0302834] Found ohci0 at pci0[   1.0302834] : USB Controller
...
[   1.0302834] Found ehci0 at pci0[   1.0302834] : USB controller

>How-To-Repeat:
Boot with -q, check console output and the dmesg.
>Fix:

>Audit-Trail:
From: Valery Ushakov <uwe@stderr.spb.ru>
To: gnats-bugs@netbsd.org
Cc: 
Subject: Re: kern/56797: timestamps messed up in quiet boot dmesg
Date: Tue, 19 Apr 2022 16:24:32 +0300

 From RTFS i think the issue is that the timestamp logic is in the
 wrong place.  The timestamp needs to be added at different points in
 the output to the console (naive) and to the log (normal+) but we use
 only one boolean needtstamp variable to track this state.

 Consider e.g. acpivga0 at acpi0 attachment.

 autoconf prints:

     aprint_naive("Found ");
     aprint_naive("%s at %s", ...);
     aprint_normal("%s at %s", ...);

 and then acpi_display.c driver prints:

     aprint_naive(": ACPI Display Adapter\n");
     aprint_normal(": ACPI Display Adapter\n");


 The result is that on the console we print:

   [   1.0310259] Found acpivga0 at acpi0: ACPI Display Adapter

 and in the log we print:

   acpivga0 at acpi0 (GFX0)[   1.0310259] : ACPI Display Adapter


 The following probably happens behind the scenes.

 naive("Found") is printed on the console and triggers printing of
 timestamp on the console, but not to the log.  naive("%s at %s") is
 printed on the console.  At this point needtstamp is false b/c we are
 in the middle of the line on the console.

 normal("%s at %s") is NOT printed on the cosole b/c we are quiet, but
 is sent to the the log.  But the same needtstamp variable is used and
 it is false, so no timestamp is added to the log.


 Then the driver prints naive(": ACPI Display Adapter\n") which is
 printed on the console and sets needtstamp to true b/c of the newline.

 Now the driver prints normal(": ACPI Display Adapter\n") that goes
 only to the log.  But the needtstamp is set, so the timestamp is added
 in the middle of the log line.

 -uwe

Home	PR Database Search