Re: What are the in-kernel functions to print human readable timestamps (bintime)?
Warner Losh wrote: > 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. Isn't that what kern.msgbuf_show_timestamp does already? I use that, along with this script: 17:15 (40.0°C 400) [2] (49) "completions" root@thompson# cat /usr/common/bin/dmesg-uptime-to-date #!/bin/sh -efu set -efu boottime="$(sysctl -n kern.boottime | gawk '{printf "%d", gensub ("^.* sec = ([1-9][0-9]*), .*$", "\\1", 1)}')" [ -z "$(printf '%s' "$boottime" | egrep '^0$|^[1-9][0-9]*$')" ] && { printf 'Invalid boottime retrieved.\n' >& 2; exit 1; } dmesg "$@" | gawk -v boottime="$boottime" ' { uptime = gensub ("^\\[([1-9][0-9]*)\\] .*$", "\\1", 1) if (uptime == $0) realtime = "??? ?? ??:??;??" else realtime = strftime ("%b %d %T", uptime + boottime) print realtime " " $0 }' Mar 11 00:41:51 [3568757] Limiting closed port RST response from 313 to 200 packets/sec Mar 11 00:41:54 [3568760] Limiting closed port RST response from 308 to 200 packets/sec Mar 11 06:23:28 [3589254] icmp redirect from 183.196.23.176: 192.168.2.104 => 183.196.23.161 etc. Cheers, Jamie
Re: What are the in-kernel functions to format time?
On 3/11/22 12:20, Gary Jennejohn wrote: Do you mean the %zd? kvprintf() checks for a zflag and handles the argument as size_t or ssize_t, depending on whether the sign is positive or negative. Hi, Given that time is a 64-bit value, then probably "%llu", and (unsigned long long)bintime would do it, but then you need that cast. ./_types.h:typedef __int64_t __sbintime_t; I was tinking of a %XXX that divides the value somehow into something more readable, maybe suffixing "ns" or "ms" or "us" or something. --HPS
Re: What are the in-kernel functions to print human readable timestamps (bintime)?
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(); > 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 alexan...@leidinger.net: PGP 0x8F31830F9F2772BF > http://www.FreeBSD.orgnetch...@freebsd.org : PGP 0x8F31830F9F2772BF >
Re: What are the in-kernel functions to format time?
On Fri, 11 Mar 2022 11:01:03 +0100 Hans Petter Selasky wrote: > On 3/11/22 10:49, 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? > > > > > > 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"? 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. > > > > Hi, > > I think our kernel printer doesn't support this: > > sys/kern/subr_prf.c > Do you mean the %zd? kvprintf() checks for a zflag and handles the argument as size_t or ssize_t, depending on whether the sign is positive or negative. However, %n isn't supported. > If you need to extend the format, please check other OS'es too, like > OpenBSD, NetBSD and Linux, what they support, so there won't be any > obvious conflicts when moving code cross platforms! > -- Gary Jennejohn
Re: What are the in-kernel functions to format time?
On 3/11/22 10:49, 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? 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"? 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. Hi, I think our kernel printer doesn't support this: sys/kern/subr_prf.c If you need to extend the format, please check other OS'es too, like OpenBSD, NetBSD and Linux, what they support, so there won't be any obvious conflicts when moving code cross platforms! --HPS
What are the in-kernel functions to print human readable timestamps (bintime)?
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? 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"? 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. 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(); 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 alexan...@leidinger.net: PGP 0x8F31830F9F2772BF http://www.FreeBSD.orgnetch...@freebsd.org : PGP 0x8F31830F9F2772BF pgpG9ftB1Te63.pgp Description: Digitale PGP-Signatur
What are the in-kernel functions to format time?
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? 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"? 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. 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(); 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 alexan...@leidinger.net: PGP 0x8F31830F9F2772BF http://www.FreeBSD.orgnetch...@freebsd.org : PGP 0x8F31830F9F2772BF pgpiH30aWZMth.pgp Description: Digitale PGP-Signatur