Date: Sat, 12 Mar 2022 18:44:07 +0100 From: Alexander Leidinger <Alexander@leidinger.net> To: Warner Losh <imp@bsdimp.com> Cc: FreeBSD Current <current@freebsd.org> Subject: Re: What are the in-kernel functions to print human readable timestamps (bintime)? Message-ID: <20220312184407.Horde.T5lVaVvzo9-ulIE4UZaKY1H@webmail.leidinger.net> In-Reply-To: <CANCZdfoEOY6%2BokeVJLDwTF5qXxwYs-Wupn6o6JvH-OAO3oj=JQ@mail.gmail.com> References: <20220311105149.Horde.uO0yyQjwC3xmwZvuZWV1ADl@webmail.leidinger.net> <CANCZdfoEOY6%2BokeVJLDwTF5qXxwYs-Wupn6o6JvH-OAO3oj=JQ@mail.gmail.com>
index | next in thread | previous in thread | raw e-mail
[-- Attachment #1 --]
Quoting Warner Losh <imp@bsdimp.com> (from Fri, 11 Mar 2022 08:57:33 -0700):
> On Fri, Mar 11, 2022 at 2:52 AM Alexander Leidinger <Alexander@leidinger.net>
> 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.
Would it be acceptable in this particular case (or should I keep this
change for me)?
I have to check out the kern.msgbuf_show_timestamp part in this
thread, which looks interesting. It may fit my needs here.
>> 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'm aware that it is complicated. IMO too complicated for a full
implementation which will satisfy all needs.
>> 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.
Sorry, I was not verbose enough in my mail it seems. I do _not_ want
to commit this code like it is. I was looking for stuff which could
print something human readable, like "2022-12-03 14:23:22.45
'kernel-time'" (just as an example). I don't want to push the TZ into
the kernel, or the knowledge if the cmos clock is set to localtime or
UTC. I want to provide an admin with a way to determine when such a
message may have printed. Currently there is no way to know at which
time it was printed. The admin needs to know if the clock is set in
UTC or localtime, and how to calculate the wall-clock time from this,
which is less heavy on the implementation and provides a mean to
correlate the mesage with some action on the machine.
> 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.
From the other message in the thread it looks like
kern.msgbuf_show_timestamp is what you describe here?
And it looks like kern.msgbuf_show_timestamp is not the same as
printing a timestamp to the console... (it looks like the timestamp is
printed in the dmesg, but not to the console, which is what I have in
mind for this particular message... respectively could be added log()
with a sysctl to activate it or not).
Bye,
Alexander.
> 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 <sys/sysent.h>
>> #include <sys/syslog.h>
>> #include <sys/sysproto.h>
>> +#include <sys/time.h>
>> #include <sys/timers.h>
>> #include <sys/unistd.h>
>> #include <sys/wait.h>
>> @@ -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
>>
--
http://www.Leidinger.net Alexander@Leidinger.net: PGP 0x8F31830F9F2772BF
http://www.FreeBSD.org netchild@FreeBSD.org : PGP 0x8F31830F9F2772BF
[-- Attachment #2 --]
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v2
iQIzBAABCAAdFiEER9UlYXp1PSd08nWXEg2wmwP42IYFAmIs2+YACgkQEg2wmwP4
2IYCyw//a5EQ6l4QVfwxXUXGOrRKRkBmL+QkfLvaGFLExi8V1i17/QGsRpOCf4Pl
WKv5e1vVI9okZiiGeBwuL51lh4wzc9vRwOq2z2UvxRPaP9u+HfgOSOJYNJMW/+mf
y/73d/NvCGLsELUDyYr08wKYTChURqrliPWeHvzn7UsgW8TPzht8hnOqOdr8vM1G
JW7Kdk2FvgrXIvG8eE4FUwOtPBXhRNlViyr4cDBUhsTPiAlpIwH7OhxpnkNDEMkN
bJZkBzfGAxxunfFNPaaUVkKuiGIcZ3FiKRn3Oa/arTsMO4vpjKLUzY8KWyqh5kCF
GdIAbaZdXAov46A/7Zw67j272PA7vd9/Gw/6td8BZwVlTSC6KH/DLVCXLGm9k2LK
ThDmxbjzrqBxZC9oV21df55Nj5E8A0X1gx6pYu43VVEWTWuw7a6GlDVcdGZ094Ky
xA1kSlM19bPA1siK5n7laeI5zg2V67cYKnCUgVhtqP9cNAmWaicVPdP/ppumG2OI
2iKg+iK2LLwm+73AdYChCtGhQ8AcUMlZZTs83vu1Hhl66nWnoAq4LxyVH6euGfvb
PnSlPaZPP3ECjc+Hh1iSkX6duGnTn0v7zh/akwMrdtbyjqPhTFcXJmLiPDcLy/Cy
JvYS2opoYGibBTdavxkCf/zMEI9ObZdysvxdx2Vw9gqa9J4WBOs=
=O5pL
-----END PGP SIGNATURE-----
help
Want to link to this message? Use this
URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?20220312184407.Horde.T5lVaVvzo9-ulIE4UZaKY1H>