From nobody Fri Mar 11 15:57:33 2022 X-Original-To: current@mlmmj.nyi.freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2610:1c1:1:606c::19:1]) by mlmmj.nyi.freebsd.org (Postfix) with ESMTP id 209F21A11EED for ; Fri, 11 Mar 2022 15:57:53 +0000 (UTC) (envelope-from wlosh@bsdimp.com) Received: from mail-vs1-xe29.google.com (mail-vs1-xe29.google.com [IPv6:2607:f8b0:4864:20::e29]) (using TLSv1.3 with cipher TLS_AES_128_GCM_SHA256 (128/128 bits) key-exchange X25519 server-signature RSA-PSS (4096 bits) server-digest SHA256 client-signature RSA-PSS (2048 bits) client-digest SHA256) (Client CN "smtp.gmail.com", Issuer "GTS CA 1D4" (verified OK)) by mx1.freebsd.org (Postfix) with ESMTPS id 4KFVvN00YWz4TkN for ; Fri, 11 Mar 2022 15:57:51 +0000 (UTC) (envelope-from wlosh@bsdimp.com) Received: by mail-vs1-xe29.google.com with SMTP id g21so9940384vsp.6 for ; Fri, 11 Mar 2022 07:57:51 -0800 (PST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=bsdimp-com.20210112.gappssmtp.com; s=20210112; h=mime-version:references:in-reply-to:from:date:message-id:subject:to :cc; bh=7d4E251zW3L9IsIXeP7wuCsLY/w83UgSZMomz9t95Sw=; b=NLEJPnhdsF+v9I0X28OMP56mrk3pZzvOXWf0bPVRs/jGL40rxotSjyMk5/SKeempE6 FFTCRhEzbwMIyVrulD1VrtBZ9Q0PHfpi4VM+sCQPt0RdRp2XyV1QApIcBOVldenxgPFU JOHVuVBxDNv6xDuTin2zBfU59HMXeWIu3pFrjiW8PUSZjrwDn+1JoWmSzG997/90DckE BG6BGEl76wiByGZN7gDPKRbL3E2URaVFijP4BCcPg3zSXA93J7f0VSPmO/Oxr6BnIHzY sgqNR70c4DIT3Nw2NBx9Cfr2keC9YaiqZhHS0y5sLIEAdJbJPTuamdy/zt9FM/JijC38 Y7Lw== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20210112; h=x-gm-message-state:mime-version:references:in-reply-to:from:date :message-id:subject:to:cc; bh=7d4E251zW3L9IsIXeP7wuCsLY/w83UgSZMomz9t95Sw=; b=J5XgtZKT0h5otEwYu2KBe4U9DZob7ecC+gMzG32bwQh5PS4mmwno2ltdD3tSjpjXb9 jCQ/SmgWfiwwsEltjas3UbQ7Y/7H+wymI72uFBDsRe3AGFFO0uAtBWxzp0J0PIHFJtxD DTAywmBzF4sy3gM+XFklawOqGAyoWRqkHQkQ+VccY+CKQKkRNVRP1AlQm2qJIPe2yEEU Y8V/AfuUjxXrjB+qc6qpmczI2ZPbBDXoAuzQ6iJ/mttO4MRrXJPHzeBOVuQch+O4eWZB o/KT6nZ+aE6TyfxusOpZK4IxTskzpbZaiTBTSqsZQvEgpa2edfe/BR9hfix4PLOLZGXV 4BYQ== X-Gm-Message-State: AOAM532aFUXn2kgZpqnww1m3njwE0GbqwSQFXOm56MdXXXS3ee60P6Et cH9KsE5pq4kYSxxKrU7R6wUNJrJarBgfKRbbqHufDrswTnw= X-Google-Smtp-Source: ABdhPJyAWEaPVN9KWURW4u2g53RMzMjE/+7nh85DX5/R1IltciHJVC5+iNG51sb8W5J6xZeaE1jAgvtbvFbNYPL7Kqs= X-Received: by 2002:a05:6102:2139:b0:320:cf2a:4f3c with SMTP id f25-20020a056102213900b00320cf2a4f3cmr5334429vsg.13.1647014264876; Fri, 11 Mar 2022 07:57:44 -0800 (PST) List-Id: Discussions about the use of FreeBSD-current List-Archive: https://lists.freebsd.org/archives/freebsd-current List-Help: List-Post: List-Subscribe: List-Unsubscribe: Sender: owner-freebsd-current@freebsd.org MIME-Version: 1.0 References: <20220311105149.Horde.uO0yyQjwC3xmwZvuZWV1ADl@webmail.leidinger.net> In-Reply-To: <20220311105149.Horde.uO0yyQjwC3xmwZvuZWV1ADl@webmail.leidinger.net> From: Warner Losh Date: Fri, 11 Mar 2022 08:57:33 -0700 Message-ID: Subject: Re: What are the in-kernel functions to print human readable timestamps (bintime)? To: Alexander Leidinger Cc: FreeBSD Current Content-Type: multipart/alternative; boundary="00000000000032c60805d9f3648f" X-Rspamd-Queue-Id: 4KFVvN00YWz4TkN X-Spamd-Bar: - Authentication-Results: mx1.freebsd.org; dkim=pass header.d=bsdimp-com.20210112.gappssmtp.com header.s=20210112 header.b=NLEJPnhd; dmarc=none; spf=none (mx1.freebsd.org: domain of wlosh@bsdimp.com has no SPF policy when checking 2607:f8b0:4864:20::e29) smtp.mailfrom=wlosh@bsdimp.com X-Spamd-Result: default: False [-2.00 / 15.00]; RCVD_TLS_ALL(0.00)[]; ARC_NA(0.00)[]; R_DKIM_ALLOW(-0.20)[bsdimp-com.20210112.gappssmtp.com:s=20210112]; NEURAL_HAM_MEDIUM(-1.00)[-1.000]; FROM_HAS_DN(0.00)[]; NEURAL_HAM_LONG(-1.00)[-1.000]; MIME_GOOD(-0.10)[multipart/alternative,text/plain]; PREVIOUSLY_DELIVERED(0.00)[current@freebsd.org]; DMARC_NA(0.00)[bsdimp.com]; TO_MATCH_ENVRCPT_SOME(0.00)[]; TO_DN_ALL(0.00)[]; DKIM_TRACE(0.00)[bsdimp-com.20210112.gappssmtp.com:+]; RCPT_COUNT_TWO(0.00)[2]; RCVD_IN_DNSWL_NONE(0.00)[2607:f8b0:4864:20::e29:from]; NEURAL_HAM_SHORT(-1.00)[-1.000]; MLMMJ_DEST(0.00)[current]; FORGED_SENDER(0.30)[imp@bsdimp.com,wlosh@bsdimp.com]; R_SPF_NA(0.00)[no SPF record]; MIME_TRACE(0.00)[0:+,1:+,2:~]; SUBJECT_ENDS_QUESTION(1.00)[]; RCVD_COUNT_TWO(0.00)[2]; ASN(0.00)[asn:15169, ipnet:2607:f8b0::/32, country:US]; FROM_NEQ_ENVFROM(0.00)[imp@bsdimp.com,wlosh@bsdimp.com] X-ThisMailContainsUnwantedMimeParts: N --00000000000032c60805d9f3648f Content-Type: text/plain; charset="UTF-8" On Fri, Mar 11, 2022 at 2:52 AM Alexander Leidinger wrote: > Hi, > > I'm looking for a function to convert bintime to a human readable > format in the kernel... and what is the usual format we use? > Yes. We don't generally log it. > > The use case for this is: if something throws a log from the kernel > about a signal, I want to know when it happened, or in terms of code > see below (tabs are most probably messed up). > > Do we have some kind of policy in terms of kernel messages and > timestamps? Like "do not commit logging with timestamps"? Correct. The kernel doesn't know enough to properly render timestamps, nor should it. It's a lot more complicated than you'd expect, and the simple, naive implementation has too many flaws... > I have the > code below because I needed it at least once and think something like > this (in a human readably shape) would be beneficial to have in the > tree. > I really don't want to see code like that in the tree. Having it per-message in an ad-hoc manner strikes me as quite unwise, since how do you interpret it after the fact, especially in the face of adjustments to boottime for any time adjustments that happen after the event. Now, having said that, having good timestamps in the dmesg buffer is a desirable feature. 'Good' is subjective here, and there are times early in boot where it's simply not possible to get a time better than '0' until the timehands are ticking... But the dmesg buffer has more than what dmesg prints: it has syslog'd things (at least some of them) as well. There's also a priority that some lines have. <3>Foo, for example. It would be better, imho, to add a timestamp to the start of the lines (perhaps optionally since that might be expensive in $HUGE systems, or at times of extreme dmesg spew and the could be omitted in those cases). If you are interested in just the log messages, it wouldn't be terrible since we already add stuff to what's printed for the priority. We could say <3,seconds-since-boot.fracsec> instead of just <3> and hack dmesg to print the right thing. Warner > Code: > ---snip--- > diff --git a/sys/kern/kern_sig.c b/sys/kern/kern_sig.c > index 4a15bd45355..a83eebe0736 100644 > --- a/sys/kern/kern_sig.c > +++ b/sys/kern/kern_sig.c > @@ -80,6 +80,7 @@ __FBSDID("$FreeBSD$"); > #include > #include > #include > +#include > #include > #include > #include > @@ -3440,14 +3441,18 @@ sigexit(struct thread *td, int sig) > */ > if (coredump(td) == 0) > sig |= WCOREFLAG; > - if (kern_logsigexit) > + if (kern_logsigexit) { > + struct bintime now; > + > + getbintime(&now); > log(LOG_INFO, > - "pid %d (%s), jid %d, uid %d: exited on " > - "signal %d%s\n", p->p_pid, p->p_comm, > + "%zd: pid %d (%s), jid %d, uid %d: exited on " > + "signal %d%s\n", now.sec, p->p_pid, p->p_comm, > p->p_ucred->cr_prison->pr_id, > td->td_ucred->cr_uid, > sig &~ WCOREFLAG, > sig & WCOREFLAG ? " (core dumped)" : ""); > + } > } else > PROC_UNLOCK(p); > exit1(td, 0, sig); > ---snip--- > > Bye, > Alexander. > > -- > http://www.Leidinger.net Alexander@Leidinger.net: PGP 0x8F31830F9F2772BF > http://www.FreeBSD.org netchild@FreeBSD.org : PGP 0x8F31830F9F2772BF > --00000000000032c60805d9f3648f Content-Type: text/html; charset="UTF-8" Content-Transfer-Encoding: quoted-printable


=
On Fri, Mar 11, 2022 at 2:52 AM Alexa= nder Leidinger <Alexander@lei= dinger.net> wrote:
Hi,

I'm looking for a function to convert bintime to a human readable=C2=A0=
format in the kernel... and what is the usual format we use?

Yes. We don't generally log it.
=C2=A0<= /div>

The use case for this is: if something throws a log from the kernel=C2=A0 <= br> about a signal, I want to know when it happened, or in terms of code=C2=A0 =
see below (tabs are most probably messed up).

Do we have some kind of policy in terms of kernel messages and=C2=A0
timestamps? Like "do not commit logging with timestamps"?

Correct. The kernel=C2=A0doesn't=C2=A0know en= ough to properly render timestamps,
nor should it. It's a lot= more complicated than you'd expect, and the simple,
naive=C2= =A0implementation has too many flaws...
=C2=A0
I have the=C2=A0
code below because I needed it at least once and think something like=C2=A0=
this (in a human readably shape) would be beneficial to have in the=C2=A0 <= br> tree.

I really don't want to see co= de like that in the tree. Having it per-message
in an ad-hoc mann= er strikes me as quite unwise, since how do you interpret
it afte= r the fact, especially in the face of adjustments to boottime=C2=A0for any<= /div>
time adjustments that happen after the event.

Now, having said that, having good timestamps in the dmesg buffer is<= /div>
a desirable feature. 'Good' is subjective here, and there= are times early
in boot where it's simply not possible to ge= t a time better than '0' until
the timehands=C2=A0are tic= king...=C2=A0 But the dmesg buffer has more than what
dmesg print= s: it has syslog'd=C2=A0things (at least some of them) as well. There&#= 39;s
also a priority that some lines have. <3>Foo, for exam= ple. It would be better,
imho, to add a timestamp to the start of= the lines (perhaps optionally
since that might be expensive in $= HUGE systems, or at times of
extreme dmesg spew and the could be = omitted in those cases).
If you are interested in just the log me= ssages, it wouldn't be terrible
since we already add stuff to= what's printed for the priority. We could say
<3,seconds-= since-boot.fracsec> instead of just <3> and hack dmesg
t= o print the right thing.

Warner
=C2=A0
Code:
---snip---
diff --git a/sys/kern/kern_sig.c b/sys/kern/kern_sig.c
index 4a15bd45355..a83eebe0736 100644
--- a/sys/kern/kern_sig.c
+++ b/sys/kern/kern_sig.c
@@ -80,6 +80,7 @@ __FBSDID("$FreeBSD$");
=C2=A0 #include <sys/sysent.h>
=C2=A0 #include <sys/syslog.h>
=C2=A0 #include <sys/sysproto.h>
+#include <sys/time.h>
=C2=A0 #include <sys/timers.h>
=C2=A0 #include <sys/unistd.h>
=C2=A0 #include <sys/wait.h>
@@ -3440,14 +3441,18 @@ sigexit(struct thread *td, int sig)
=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 */
=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0if (coredump(= td) =3D=3D 0)
=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2= =A0 =C2=A0 =C2=A0sig |=3D WCOREFLAG;
-=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0if (kern_logsigexit= )
+=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0if (kern_logsigexit= ) {
+=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2= =A0 =C2=A0struct bintime now;
+
+=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2= =A0 =C2=A0getbintime(&now);
=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2= =A0 =C2=A0 =C2=A0log(LOG_INFO,
-=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2= =A0 =C2=A0 =C2=A0 =C2=A0"pid %d (%s), jid %d, uid %d: exited on "=
-=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2= =A0 =C2=A0 =C2=A0 =C2=A0"signal %d%s\n", p->p_pid, p->p_com= m,
+=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2= =A0 =C2=A0 =C2=A0 =C2=A0"%zd: pid %d (%s), jid %d, uid %d: exited on &= quot;
+=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2= =A0 =C2=A0 =C2=A0 =C2=A0"signal %d%s\n", now.sec, p->p_pid, p-= >p_comm,
=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2= =A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0p->p_ucred->cr_prison->pr_id,
=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2= =A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0td->td_ucred->cr_uid,
=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2= =A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0sig &~ WCOREFLAG,
=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2= =A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0sig & WCOREFLAG ? " (core dumped)&q= uot; : "");
+=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0}
=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0} else
=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0PROC_UNLOCK(p= );
=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0exit1(td, 0, sig);
---snip---

Bye,
Alexander.

--
h= ttp://www.Leidinger.net Alexander@Leidinger.net: PGP 0x8F31830F9F2772BF=
htt= p://www.FreeBSD.org=C2=A0 =C2=A0 netchild@FreeBSD.org=C2=A0 : PGP 0x8F3= 1830F9F2772BF
--00000000000032c60805d9f3648f--