Add option -Z to syslogd(8) to use ISO 8601 timestamps

classic Classic list List threaded Threaded
7 messages Options
Reply | Threaded
Open this post in threaded view
|

Add option -Z to syslogd(8) to use ISO 8601 timestamps

Ben Woods
Hi everyone,

Please review my patch to add the -Z option to syslogd(8) to use ISO 8601
timestamps in UTC:
https://reviews.freebsd.org/D14918

This patch was taken from OpenBSD, and is the first of many features from
RFC5424 that we should be looking to add to syslogd(8) in FreeBSD.

BACKGROUND:
I have been centralising my logs lately, and found that they had different
timezones, but the RFC3164 syslog timestamp format does not include the
timezone. The servers had their timezones set to UTC, whilst the
workstations had their timezones set to the local timezone. This made it
difficult to correlate events across machines, as my log analysis tool had
simultaneous events entered with timestamps many hours apart.

I have added a few people to the review who last touched syslogd(8) - sorry
to those people, just trying to get reviewers :)

Regards,
Ben
--

--
From: Benjamin Woods
[hidden email]
_______________________________________________
[hidden email] mailing list
https://lists.freebsd.org/mailman/listinfo/freebsd-hackers
To unsubscribe, send any mail to "[hidden email]"
Reply | Threaded
Open this post in threaded view
|

Re: Add option -Z to syslogd(8) to use ISO 8601 timestamps

Julian Elischer-5
On 1/4/18 8:27 am, Ben Woods wrote:
> Hi everyone,
>
> Please review my patch to add the -Z option to syslogd(8) to use ISO 8601
> timestamps in UTC:

YES!
  I was just looking into doing this myself..

Just goes to show that if one procrastinates enough, someone else will
do the work!

is there a matching change for syslog(3) to actually generate new
timestamps?

The syslog protocol is unique that either end can be responsible for
the timestamp.

In the case of the new timestamp form you would have to strip off the
incoming old form timestamp and replace it.



_______________________________________________
[hidden email] mailing list
https://lists.freebsd.org/mailman/listinfo/freebsd-hackers
To unsubscribe, send any mail to "[hidden email]"
Reply | Threaded
Open this post in threaded view
|

Re: Add option -Z to syslogd(8) to use ISO 8601 timestamps

Ben Woods
On 1 April 2018 at 11:25, Julian Elischer <[hidden email]> wrote:

> is there a matching change for syslog(3) to actually generate new
> timestamps?
>
> The syslog protocol is unique that either end can be responsible for the
> timestamp.
>

The approach the OpenBSD team has taken has been to remove all timestamping
from syslog(3):

"Do not include a timestamp in the syslog message.  There is no need --
syslogd will fill it in immediately upon reception on the other side of
sendsyslog(2).  Our libc only talks to our syslogd, which will fix the
timestamp before forwarding.  syslog_r has done this for a long time
already.
ok tedu bluhm"

https://cvsweb.openbsd.org/cgi-bin/cvsweb/src/lib/libc/gen/syslog.c.diff?r1=1.32&r2=1.33&f=h
https://cvsweb.openbsd.org/cgi-bin/cvsweb/src/lib/libc/gen/syslog_r.c.diff?r1=1.9&r2=1.10&f=h

The FreeBSD syslog(3) code still adds a timestamp, so there is an option to
either remove this code from syslog(3) similar to OpenBSD, or update the
syslog(3) code to support either timestamp.
My testing shows that if syslogd(8) is not running at the time a message
comes in from syslog(3), the message is dropped (not buffered until syslogd
is once again running).
This means there would be no significant time delay issues causing
incorrect timestamps if syslogd(8) adds the timestamp instead of syslog(3).
https://svnweb.freebsd.org/base/head/lib/libc/gen/syslog.c?revision=326025&view=markup#l171

Note that when testing my patch with the logger(1) tool, which uses
syslog(3), I have found that the RFC3164 timestamp format applied by
syslog(3) is replaced with the RFC5424 timestamp format in syslogd(8), as
per the description below.


In the case of the new timestamp form you would have to strip off the
> incoming old form timestamp and replace it.
>

Indeed. This is handled by the changes in the parsemsg() function, which
effectively sets the -T option (RemoteAddDate = 1) if it detects the old
timestamp format when the -Z option has been set.
Note that my proposed implementation does not convert the old format to the
new format (and assume the current year), but instead simply strips the old
timestamp and applies a new one. This is as per OpenBSD's implementation.

Regards,
Ben
_______________________________________________
[hidden email] mailing list
https://lists.freebsd.org/mailman/listinfo/freebsd-hackers
To unsubscribe, send any mail to "[hidden email]"
Reply | Threaded
Open this post in threaded view
|

Re: Add option -Z to syslogd(8) to use ISO 8601 timestamps

Ian Lepore-3
On Sun, 2018-04-01 at 18:24 +0800, Ben Woods wrote:

> My testing shows that if syslogd(8) is not running at the time a
> message
> comes in from syslog(3), the message is dropped (not buffered until
> syslogd
> is once again running).
> This means there would be no significant time delay issues causing
> incorrect timestamps if syslogd(8) adds the timestamp instead of
> syslog(3).
> https://svnweb.freebsd.org/base/head/lib/libc/gen/syslog.c?revision=3
> 26025&view=markup#l171

The important issue with source-side timestamping doesn't have to do
with whether syslogd is running or not, it has to do with mutiple
threads and processes feeding data to syslogd at high speed and
accurately timestamping the events being logged. Mutexes are involved
in libc syslog(3) for multithreaded apps, and buffers are involved
which can lead to arbitrary ordering of messages generated by various
processes, and only source-side timestamps can make it clear in what
order things really happened.

In addition, milliseconds are not nearly fine-grained enough for
fractional seconds.  Even microseconds aren't really good enough on
modern hardware.

-- Ian
_______________________________________________
[hidden email] mailing list
https://lists.freebsd.org/mailman/listinfo/freebsd-hackers
To unsubscribe, send any mail to "[hidden email]"
Reply | Threaded
Open this post in threaded view
|

Re: Add option -Z to syslogd(8) to use ISO 8601 timestamps

Ed Schouten-6
In reply to this post by Ben Woods
Hi Ben,

2018-04-01 2:27 GMT+02:00 Ben Woods <[hidden email]>:

> Hi everyone,
>
> Please review my patch to add the -Z option to syslogd(8) to use ISO 8601
> timestamps in UTC:
> https://reviews.freebsd.org/D14918
>
> This patch was taken from OpenBSD, and is the first of many features from
> RFC5424 that we should be looking to add to syslogd(8) in FreeBSD.
>
> BACKGROUND:
> I have been centralising my logs lately, and found that they had different
> timezones, but the RFC3164 syslog timestamp format does not include the
> timezone. The servers had their timezones set to UTC, whilst the
> workstations had their timezones set to the local timezone. This made it
> difficult to correlate events across machines, as my log analysis tool had
> simultaneous events entered with timestamps many hours apart.
>
> I have added a few people to the review who last touched syslogd(8) - sorry
> to those people, just trying to get reviewers :)

Wow! That's a coincidence. I actually started working on something in
the same area a couple of days ago. One of our customers requires
sub-second precision of log entries, which is why I implemented RFC
5424 support for FreeBSD's syslogd a couple of days ago. I sent out a
pull request a couple of minutes ago and only noticed your email just
now.

https://reviews.freebsd.org/D14926

This patch doesn't change the output format of syslogd. It only adds
the RFC 5424 parsing and changes the internal model of syslogd to be
based on RFC 5424. Changing the output format to use ISO 8601
formatting was planned for a separate change.

What are your thoughts on my pull request? If you like it, maybe it
makes more sense to land my change first before applying yours?

--
Ed Schouten <[hidden email]>
Nuxi, 's-Hertogenbosch, the Netherlands
_______________________________________________
[hidden email] mailing list
https://lists.freebsd.org/mailman/listinfo/freebsd-hackers
To unsubscribe, send any mail to "[hidden email]"
Reply | Threaded
Open this post in threaded view
|

Re: Add option -Z to syslogd(8) to use ISO 8601 timestamps

Ben Woods
On 2 April 2018 at 03:33, Ed Schouten <[hidden email]> wrote:

> Wow! That's a coincidence. I actually started working on something in
> the same area a couple of days ago. One of our customers requires
> sub-second precision of log entries, which is why I implemented RFC
> 5424 support for FreeBSD's syslogd a couple of days ago. I sent out a
> pull request a couple of minutes ago and only noticed your email just
> now.
>
> https://reviews.freebsd.org/D14926
>
> This patch doesn't change the output format of syslogd. It only adds
> the RFC 5424 parsing and changes the internal model of syslogd to be
> based on RFC 5424. Changing the output format to use ISO 8601
> formatting was planned for a separate change.
>
> What are your thoughts on my pull request? If you like it, maybe it
> makes more sense to land my change first before applying yours?
>
> --
> Ed Schouten <[hidden email]>
> Nuxi, 's-Hertogenbosch, the Netherlands
>


Hi Ed,

That is a coincidence. Having looked through your code, I realise it is far
better than mine, and mine actually resulted in the syslogd output being
non-compliant with both RFC3164 and RFC5424 (by using the RFC5424 timestamp
format with the remainder of the log matching the RFC3164 format). I have
therefore abandoned my review in favour of yours.

My effort has not been wasted though, as it meant that I was recently
familiar with the syslogd.c code, and the contents of RFC3164 and RFC5424,
and therefore had a headstart in reviewing your patch. I have provided some
comments in phabricator for your consideration.

I think you have already handled the hard part of the migration to RFC5424,
which is the updated parsing logic. Whilst you have yet changed the log
output format to RFC5424, I suspect that will be the easy bit.
When it comes time to change the output format, it is worth noting that
NetBSD has provided the "-o" syslogd argument to allow the sysadmin to
select the output format:

 -o output_format
                  Select output message format.
                  bsd, rfc3164 traditional BSD Syslog format (default)
                  syslog, rfc5424 new syslog-protocol format

Regards,
Ben

--
From: Benjamin Woods
[hidden email]
_______________________________________________
[hidden email] mailing list
https://lists.freebsd.org/mailman/listinfo/freebsd-hackers
To unsubscribe, send any mail to "[hidden email]"
Reply | Threaded
Open this post in threaded view
|

Re: Add option -Z to syslogd(8) to use ISO 8601 timestamps

Ed Schouten-6
Hi Ben,

2018-04-02 12:22 GMT+02:00 Ben Woods <[hidden email]>:

> That is a coincidence. Having looked through your code, I realise it is far
> better than mine, and mine actually resulted in the syslogd output being
> non-compliant with both RFC3164 and RFC5424 (by using the RFC5424 timestamp
> format with the remainder of the log matching the RFC3164 format). I have
> therefore abandoned my review in favour of yours.
>
> My effort has not been wasted though, as it meant that I was recently
> familiar with the syslogd.c code, and the contents of RFC3164 and RFC5424,
> and therefore had a headstart in reviewing your patch. I have provided some
> comments in phabricator for your consideration.

Yes, exactly! Having someone who can review my changes thoroughly is
incredibly useful. Thanks a lot for your feedback so far! I'll take a
look at it later today and revise my patch where needed.

> I think you have already handled the hard part of the migration to RFC5424,
> which is the updated parsing logic. Whilst you have yet changed the log
> output format to RFC5424, I suspect that will be the easy bit.

Exactly. We do have to investigate whether we also want to use RFC
5424 to format console messages. It may be a bit too verbose,
especially for 80 column consoles. This is exactly why I left changing
the output format to another change.

> When it comes time to change the output format, it is worth noting that
> NetBSD has provided the "-o" syslogd argument to allow the sysadmin to
> select the output format:
>
>  -o output_format
>                   Select output message format.
>                   bsd, rfc3164 traditional BSD Syslog format (default)
>                   syslog, rfc5424 new syslog-protocol format

Yes! Being compatible with NetBSD here sounds like a good idea indeed.
No need to deviate unnecessarily.

Best regards,
--
Ed Schouten <[hidden email]>
Nuxi, 's-Hertogenbosch, the Netherlands
_______________________________________________
[hidden email] mailing list
https://lists.freebsd.org/mailman/listinfo/freebsd-hackers
To unsubscribe, send any mail to "[hidden email]"