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>
next in thread | previous in thread | raw e-mail | index | archive | help
This message is in MIME format and has been PGP signed.
--=_cY8l_FQJmHsikIO5P-QFghT
Content-Type: text/plain; charset=utf-8; format=flowed; DelSp=Yes
Content-Disposition: inline
Content-Transfer-Encoding: quoted-printable
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=20=20
change=20for me)?
I have to check out the kern.msgbuf_show_timestamp part in this=20=20
thread,=20which 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=20=20
implementation=20which 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-mess=
age
> in an ad-hoc manner strikes me as quite unwise, since how do you interpre=
t
> 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=20=20
to=20commit this code like it is. I was looking for stuff which could=20=20
print=20something human readable, like "2022-12-03 14:23:22.45=20=20
'kernel-time'"=20(just as an example). I don't want to push the TZ into=20=
=20
the=20kernel, or the knowledge if the cmos clock is set to localtime or=20=
=20
UTC.=20I want to provide an admin with a way to determine when such a=20=20
message=20may have printed. Currently there is no way to know at which=20=
=20
time=20it was printed. The admin needs to know if the clock is set in=20=20
UTC=20or localtime, and how to calculate the wall-clock time from this,=20=
=20
which=20is less heavy on the implementation and provides a mean to=20=20
correlate=20the 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' unti=
l
> 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 s=
ay
> <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=20=20
kern.msgbuf_show_timestamp=20is what you describe here?
And it looks like kern.msgbuf_show_timestamp is not the same as=20=20
printing=20a timestamp to the console... (it looks like the timestamp is=20=
=20
printed=20in the dmesg, but not to the console, which is what I have in=20=
=20
mind=20for this particular message... respectively could be added log()=20=
=20
with=20a 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) =3D=3D 0)
>> sig |=3D 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_com=
m,
>> 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
>>
--=20
http://www.Leidinger.net=20Alexander@Leidinger.net: PGP 0x8F31830F9F2772BF
http://www.FreeBSD.org netchild@FreeBSD.org : PGP 0x8F31830F9F2772BF
--=_cY8l_FQJmHsikIO5P-QFghT
Content-Type: application/pgp-signature
Content-Description: Digitale PGP-Signatur
Content-Disposition: inline
-----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-----
--=_cY8l_FQJmHsikIO5P-QFghT--
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?20220312184407.Horde.T5lVaVvzo9-ulIE4UZaKY1H>