syslog(2) change

syslog(2) change

[BurnZeZ]

[-- Attachment #1: Type: text/plain, Size: 757 bytes --]

Currently, syslog() prints sysname, date/time, and fmt.
Check out the diff and tell me if I'm just being dumb.

Sample before/after lines...

cirno Feb  9 20:38:55 Hung up on 8.8.8.8; claimed to be fbi.gov
1455068335 cirno Hung up on 8.8.8.8; claimed to be fbi.gov


Nobody wants this stupid crap where you have to try to recall which
timezone(s) a machine is/was in.  Also, with this change it's easy to
plot out occurrences of some log string over time, as you don't have
to do any date string conversions (useful when trying to track down
bugs that don't present themselves frequently).

The only con I can think of is that you'll need to use date(1)
to convert the timestamp if you want your date string, but hey,
at least the timestamp isn't ambiguous.

[-- Attachment #2: Type: text/plain, Size: 1057 bytes --]

diff -r 94c649383b95 sys/man/2/perror
--- a/sys/man/2/perror	Tue Feb 09 16:24:41 2016 -0500
+++ b/sys/man/2/perror	Tue Feb 09 19:54:00 2016 -0500
@@ -36,8 +36,8 @@
 .I Logname
 must contain no slashes.
 The message is a line with several fields:
+seconds since the epoch;
 the name of the machine writing the message;
-the date and time;
 the message specified by the
 .IR print (2)
 format
diff -r 94c649383b95 sys/src/libc/9sys/syslog.c
--- a/sys/src/libc/9sys/syslog.c	Tue Feb 09 16:24:41 2016 -0500
+++ b/sys/src/libc/9sys/syslog.c	Tue Feb 09 19:54:00 2016 -0500
@@ -43,7 +43,7 @@
 syslog(int cons, char *logname, char *fmt, ...)
 {
 	char buf[1024];
-	char *ctim, *p;
+	char *p;
 	va_list arg;
 	int n;
 	Dir *d;
@@ -92,11 +92,7 @@
 		return;
 	}
 
-	ctim = ctime(time(0));
-	p = buf + snprint(buf, sizeof(buf)-1, "%s ", sysname());
-	strncpy(p, ctim+4, 15);
-	p += 15;
-	*p++ = ' ';
+	p = buf + snprint(buf, sizeof(buf)-1, "%ld %s ", time(0), sysname());
 	errstr(err, sizeof err);
 	va_start(arg, fmt);
 	p = vseprint(p, buf+sizeof(buf)-1, fmt, arg);

Re: [9front] syslog(2) change

[Devon H. O'Dell]

go for the gusto and implement 5424

2016-02-09 21:03 GMT-08:00  <BurnZeZ@feline.systems>:
> Currently, syslog() prints sysname, date/time, and fmt.
> Check out the diff and tell me if I'm just being dumb.
>
> Sample before/after lines...
>
> cirno Feb  9 20:38:55 Hung up on 8.8.8.8; claimed to be fbi.gov
> 1455068335 cirno Hung up on 8.8.8.8; claimed to be fbi.gov
>
>
> Nobody wants this stupid crap where you have to try to recall which
> timezone(s) a machine is/was in.  Also, with this change it's easy to
> plot out occurrences of some log string over time, as you don't have
> to do any date string conversions (useful when trying to track down
> bugs that don't present themselves frequently).
>
> The only con I can think of is that you'll need to use date(1)
> to convert the timestamp if you want your date string, but hey,
> at least the timestamp isn't ambiguous.
> diff -r 94c649383b95 sys/man/2/perror
> --- a/sys/man/2/perror  Tue Feb 09 16:24:41 2016 -0500
> +++ b/sys/man/2/perror  Tue Feb 09 19:54:00 2016 -0500
> @@ -36,8 +36,8 @@
>  .I Logname
>  must contain no slashes.
>  The message is a line with several fields:
> +seconds since the epoch;
>  the name of the machine writing the message;
> -the date and time;
>  the message specified by the
>  .IR print (2)
>  format
> diff -r 94c649383b95 sys/src/libc/9sys/syslog.c
> --- a/sys/src/libc/9sys/syslog.c        Tue Feb 09 16:24:41 2016 -0500
> +++ b/sys/src/libc/9sys/syslog.c        Tue Feb 09 19:54:00 2016 -0500
> @@ -43,7 +43,7 @@
>  syslog(int cons, char *logname, char *fmt, ...)
>  {
>         char buf[1024];
> -       char *ctim, *p;
> +       char *p;
>         va_list arg;
>         int n;
>         Dir *d;
> @@ -92,11 +92,7 @@
>                 return;
>         }
>
> -       ctim = ctime(time(0));
> -       p = buf + snprint(buf, sizeof(buf)-1, "%s ", sysname());
> -       strncpy(p, ctim+4, 15);
> -       p += 15;
> -       *p++ = ' ';
> +       p = buf + snprint(buf, sizeof(buf)-1, "%ld %s ", time(0), sysname());
>         errstr(err, sizeof err);
>         va_start(arg, fmt);
>         p = vseprint(p, buf+sizeof(buf)-1, fmt, arg);

Re: [9front] syslog(2) change

[arisawa]

Hi,

I also hate current date/time format of /sys/log.
that makes log analysis very difficult.
I prefer
cirno 2016-02-01 20:38:55 Hung up on 8.8.8.8; claimed to be fbi.gov
instead of
cirno Feb  9 20:38:55 Hung up on 8.8.8.8; claimed to be fbi.gov

your
1455068335 cirno Hung up on 8.8.8.8; claimed to be fbi.gov
is too radical, I think.

I also prefer "2016-02-01 20:38:55” style for ls -l to compare with /sys/log.


> 2016/02/10 14:03、BurnZeZ@feline.systems のメール：
> 
> Currently, syslog() prints sysname, date/time, and fmt.
> Check out the diff and tell me if I'm just being dumb.
> 
> Sample before/after lines...
> 
> cirno Feb  9 20:38:55 Hung up on 8.8.8.8; claimed to be fbi.gov
> 1455068335 cirno Hung up on 8.8.8.8; claimed to be fbi.gov
> 
> 
> Nobody wants this stupid crap where you have to try to recall which
> timezone(s) a machine is/was in.  Also, with this change it's easy to
> plot out occurrences of some log string over time, as you don't have
> to do any date string conversions (useful when trying to track down
> bugs that don't present themselves frequently).
> 
> The only con I can think of is that you'll need to use date(1)
> to convert the timestamp if you want your date string, but hey,
> at least the timestamp isn't ambiguous.diff -r 94c649383b95 sys/man/2/perror
> --- a/sys/man/2/perror	Tue Feb 09 16:24:41 2016 -0500
> +++ b/sys/man/2/perror	Tue Feb 09 19:54:00 2016 -0500
> @@ -36,8 +36,8 @@
> .I Logname
> must contain no slashes.
> The message is a line with several fields:
> +seconds since the epoch;
> the name of the machine writing the message;
> -the date and time;
> the message specified by the
> .IR print (2)
> format
> diff -r 94c649383b95 sys/src/libc/9sys/syslog.c
> --- a/sys/src/libc/9sys/syslog.c	Tue Feb 09 16:24:41 2016 -0500
> +++ b/sys/src/libc/9sys/syslog.c	Tue Feb 09 19:54:00 2016 -0500
> @@ -43,7 +43,7 @@
> syslog(int cons, char *logname, char *fmt, ...)
> {
> 	char buf[1024];
> -	char *ctim, *p;
> +	char *p;
> 	va_list arg;
> 	int n;
> 	Dir *d;
> @@ -92,11 +92,7 @@
> 		return;
> 	}
> 
> -	ctim = ctime(time(0));
> -	p = buf + snprint(buf, sizeof(buf)-1, "%s ", sysname());
> -	strncpy(p, ctim+4, 15);
> -	p += 15;
> -	*p++ = ' ';
> +	p = buf + snprint(buf, sizeof(buf)-1, "%ld %s ", time(0), sysname());
> 	errstr(err, sizeof err);
> 	va_start(arg, fmt);
> 	p = vseprint(p, buf+sizeof(buf)-1, fmt, arg);

Re: [9front] syslog(2) change

[BurnZeZ]

> I prefer
> cirno 2016-02-01 20:38:55 Hung up on 8.8.8.8; claimed to be fbi.gov
> instead of
> cirno Feb  9 20:38:55 Hung up on 8.8.8.8; claimed to be fbi.gov

This doesn't address the timezone problem, which is arguably the
biggest concern.  The first thing I thought of was simply including
the timezone, but that really just means more crap on each line

Another way is to just imply GMT and exclude specifying it in the
date/time, but then the logs don't appear different, so it's not easy
to tell when the behavior was corrected if you're looking back at your
logs in the future.


> your
> 1455068335 cirno Hung up on 8.8.8.8; claimed to be fbi.gov
> is too radical, I think.

Perhaps, but it seems to me like the simplest fix.

Re: [9front] syslog(2) change

[arisawa]

I don’t understand what real problems you want to resolve.
are your log files shard among cpu servers that are located in different time zone?

> 2016/02/10 21:14、BurnZeZ@feline.systems のメール：
> 
>> I prefer
>> cirno 2016-02-01 20:38:55 Hung up on 8.8.8.8; claimed to be fbi.gov
>> instead of
>> cirno Feb  9 20:38:55 Hung up on 8.8.8.8; claimed to be fbi.gov
> 
> This doesn't address the timezone problem, which is arguably the
> biggest concern.  The first thing I thought of was simply including
> the timezone, but that really just means more crap on each line
> 
> Another way is to just imply GMT and exclude specifying it in the
> date/time, but then the logs don't appear different, so it's not easy
> to tell when the behavior was corrected if you're looking back at your
> logs in the future.
> 
> 
>> your
>> 1455068335 cirno Hung up on 8.8.8.8; claimed to be fbi.gov
>> is too radical, I think.
> 
> Perhaps, but it seems to me like the simplest fix.

Re: [9front] syslog(2) change

[stanley lieber]

[-- Attachment #1: Type: text/plain, Size: 198 bytes --]

> are your log files shard among cpu servers that are
> located in different time zone?

This seems like the obvious question upon which all of this hinges. This is
almost certainly a rare case.

sl

[-- Attachment #2: Type: text/html, Size: 264 bytes --]

Re: [9front] syslog(2) change

[BurnZeZ]

> > are your log files shard among cpu servers that are
> > located in different time zone?

No, but this came up as I was preparing to do so.
Note that terminals also write to the files in /sys/log.
(The first example I can think of is cpu(1))


> This seems like the obvious question upon which all of this hinges. This is
> almost certainly a rare case.

I didn't consider this a strange thing to do.  Running a bunch of
nodes from a single install means only maintaining one filesystem.
Nonetheless, netbooted terminals in a different timezone will have
the same issue.

Re: [9front] syslog(2) change

[sl]

>> This seems like the obvious question upon which all of this hinges. This is
>> almost certainly a rare case.
> 
> I didn't consider this a strange thing to do.  Running a bunch of
> nodes from a single install means only maintaining one filesystem.
> Nonetheless, netbooted terminals in a different timezone will have
> the same issue.

Systems in different timezones sharing an fs is precisely the "rare
case" I was describing. Can you guess why this case is rare?

sl

Re: [9front] syslog(2) change

[Julius Schmidt]

I'm in favour of putting timezones in log files. I know it may seem
pedantic, but imagine a program parsing log files that needs to convert
into unix timestamp.  It seems silly to require such a program to be
able to map hosts to timezones.  Adding a timezone identifier to log
files seems like a trivial change that would remove any ambiguity about
the exact UTC time of a log entry.

I do much prefer something like yyyy-mm-dd... over burnzez' suggestion.

aiju

On Wed, 10 Feb 2016, sl@stanleylieber.com wrote:

>>> This seems like the obvious question upon which all of this hinges. This is
>>> almost certainly a rare case.
>>
>> I didn't consider this a strange thing to do.  Running a bunch of
>> nodes from a single install means only maintaining one filesystem.
>> Nonetheless, netbooted terminals in a different timezone will have
>> the same issue.
>
> Systems in different timezones sharing an fs is precisely the "rare
> case" I was describing. Can you guess why this case is rare?
>
> sl
>

Re: [9front] syslog(2) change

[sl]

> I'm in favour of putting timezones in log files. I know it may seem
> pedantic, but imagine a program parsing log files that needs to convert
> into unix timestamp.  It seems silly to require such a program to be
> able to map hosts to timezones.  Adding a timezone identifier to log
> files seems like a trivial change that would remove any ambiguity about
> the exact UTC time of a log entry.

Wait, this approaches a rationale.

sl

Re: [9front] syslog(2) change

[Kurt H Maier]

On Wed, Feb 10, 2016 at 09:57:36PM +0100, Julius Schmidt wrote:
> I do much prefer something like yyyy-mm-dd... over burnzez' suggestion.

If you're going to put timezones in the logfiles, you pretty much have
to use ISO-8601 date formats, and resolve to stick to numeric offsets.
As we're discovering on irc, trying to convert from abbreviations to
meaningul data is a fool's game.  Switching to YYYY-MM-DDTHH:MM:SS+HH:MM
is the only sane option.

khm

Re: [9front] syslog(2) change

[Devon H. O'Dell]

2016-02-10 13:08 GMT-08:00 Kurt H Maier <khm@sciops.net>:
> On Wed, Feb 10, 2016 at 09:57:36PM +0100, Julius Schmidt wrote:
>> I do much prefer something like yyyy-mm-dd... over burnzez' suggestion.
>
> If you're going to put timezones in the logfiles, you pretty much have
> to use ISO-8601 date formats, and resolve to stick to numeric offsets.
> As we're discovering on irc, trying to convert from abbreviations to
> meaningul data is a fool's game.  Switching to YYYY-MM-DDTHH:MM:SS+HH:MM
> is the only sane option.

NB 8601 is specified as what is used in syslog format per 5424, not
that anyone cares about RFCs.

> khm

Re: [9front] syslog(2) change

[sl]

I don't get it. Everyone knows all the machines are
located at Murray Hill.

sl

Re: [9front] syslog(2) change

[BurnZeZ]

On Wed Feb 10 15:28:40 EST 2016, sl@stanleylieber.com wrote:
> >> This seems like the obvious question upon which all of this hinges. This is
> >> almost certainly a rare case.
> > 
> > I didn't consider this a strange thing to do.  Running a bunch of
> > nodes from a single install means only maintaining one filesystem.
> > Nonetheless, netbooted terminals in a different timezone will have
> > the same issue.
> 
> Systems in different timezones sharing an fs is precisely the "rare
> case" I was describing. Can you guess why this case is rare?
> 
> sl
> 

I assume latency is the primary reason not to.  If you're running a
bunch of scripts that are accessing files all over the place, you
might have a problem.  One useful example I can think of would be
having some remote machine that is primarily used as a remote gateway.

You're right though, I can see why someone might avoid doing this.



On Wed Feb 10 16:08:12 EST 2016, khm@sciops.net wrote:
> On Wed, Feb 10, 2016 at 09:57:36PM +0100, Julius Schmidt wrote:
> > I do much prefer something like yyyy-mm-dd... over burnzez' suggestion.
> 
> If you're going to put timezones in the logfiles, you pretty much have
> to use ISO-8601 date formats, and resolve to stick to numeric offsets.
> As we're discovering on irc, trying to convert from abbreviations to
> meaningul data is a fool's game.  Switching to YYYY-MM-DDTHH:MM:SS+HH:MM
> is the only sane option.
> 
> khm
> 

cirno Feb  9 20:38:55 Hung up on 8.8.8.8; claimed to be fbi.gov
cirno 1455068335 Hung up on 8.8.8.8; claimed to be fbi.gov
cirno 2016-02-09T20:38:55-0500 Hung up on 8.8.8.8; claimed to be fbi.gov

I still prefer the terseness of seconds since the epoch, but ISO-8601 is
at least machine readable.

Re: [9front] syslog(2) change

[arisawa]

however syslog need to be human readable.

> 2016/02/11 7:41、BurnZeZ@feline.systems のメール：
> 
> 
> cirno Feb  9 20:38:55 Hung up on 8.8.8.8; claimed to be fbi.gov
> cirno 1455068335 Hung up on 8.8.8.8; claimed to be fbi.gov
> cirno 2016-02-09T20:38:55-0500 Hung up on 8.8.8.8; claimed to be fbi.gov
> 
> I still prefer the terseness of seconds since the epoch, but ISO-8601 is
> at least machine readable.

Re: [9front] syslog(2) change

[Kurt H Maier]

On Wed, Feb 10, 2016 at 07:14:05AM -0500, BurnZeZ@feline.systems wrote:
> 
> This doesn't address the timezone problem, which is arguably the
> biggest concern.  The first thing I thought of was simply including
> the timezone, but that really just means more crap on each line
> 

It's not a concern at all, because (unless you ruin your logging) you
have the hostname in the first spot, and you can just look up its
timezone.  I'm always in support of using epoch time in place of
human-readable strings -- or at least ISO-8601 format; either one is
sortable.  But worrying about timezones is a waste of the actual time.

> Another way is to just imply GMT and exclude specifying it in the
> date/time, but then the logs don't appear different, so it's not easy
> to tell when the behavior was corrected if you're looking back at your
> logs in the future.

This is trivially solvable by correcting previous logs when you change the
damn timezone.  You can make all kinds of assumptions about data if you
exert the smallest amount of effort into curating it.

I also don't know why you want to play three-card-monte with the
ordering of the information; the hostname needs to stay first.  This
makes tools like xcat's xcoll much easier to port and maintain.

khm

Re: [9front] syslog(2) change

[BurnZeZ]

> I also don't know why you want to play three-card-monte with the
> ordering of the information; the hostname needs to stay first.  This
> makes tools like xcat's xcoll much easier to port and maintain.

If the order is significant in some way, it doesn't need to be
changed.  I meant to say this in my first mail (I had to rewrite that
mail after a surgical mb2→paste destroyed it).  The only reason reason
I placed the timestamp first was so that timestamps would be aligned
when you're skimming through the logs.