Dear maintainers,

The systemd journal is checked by default, in addition to rsyslog files,
starting with logcheck version 1.4.1. But the format of timestamps are
different by default for journal (uses the old-school format: "Jul 20
11:51:03") and rsyslog >= 8.2210.0-3 (uses an RFC3339-compatible format:
"2023-07-20T11:51:03.046581+0200"). So logcheck cannot compare them
correctly.

Also, journalctl can emit multi-line logs, whereas rsyslog cannot.

The attached patch adds a new ISO_TIMESTAMPS config variable to the logcheck
script, allowing logcheck to:
  - call journalctl with "-o short-iso-precise" in order to get a
    nearly-RFC3339-compatible timestamp
  - add the missing ':' between the timezone hours and minutes to convert the
    journalctl shot-iso-precise timestamp to the exact RFC3339 timestamp
    format used by rsyslog
  - join continuous lines (lines starting with whitespace) from
    journalctl output, as rsyslog only logs them as one line
  - handle SORTUNIQ correctly even when using ISO_TIMESTAMPS

I have been using this locally since early March.

(NB in https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=1032197 I also
suggested to make journalctl use the "correct" timestamp format; if/when
this actually gets done, the "second sed action" in my logcheck patch
can be dropped)

Regards,
Tom

On Thu, 20 Jul 2023 12:15:25 +0200 Thomas Parmelan <tom+debian@ankh.fr.eu.org> wrote:

Some interesting ideas in here - i think i am missing something though:

I understand until the word "compare" here - are you saying that rules
don't match entries from rsyslog or from systemd? because both seem to
be matched fine for me!
in the logcheck-database of rules is

^(\w{3} [ :0-9]{11}|[0-9T:.+-]{32})

which should match both rules without needing to change the format,
and includes a : wherever it occurs.... have we got something wrong in
this, and if so, what?

this part i understand (although i didnt check the sed logic closely)
and agree it would be worth doing: is it definitely correct that a
blank line is always a continuation line like this?

i didnt understand this bit of the patch (copied below):- it seems to
have a lot of repetition, and introduce a call to 'uniq', but only
sometimes:

(i also wonder why anything is better than just 'sort -u' regardless
of timestamp format): can you explain what the issue is that is being
solved?


+   || error "Could not save sorted log content to
$TMPDIR/logoutput-sorted"
+else
+ if [ "$ISO_TIMESTAMPS" -eq 1 ]; then
+     SORT_OPTS="-k 1 -s"
+ else
+     SORT_OPTS="-k 1,3 -s"
+ fi
+ sort $SORT_OPTS "$TMPDIR/logoutput"/* | sed -e 's/[[:space:]]\+$//'
| uniq > "$TMPDIR/logoutput-sorted" \
    || error "Could not save sorted log content to
$TMPDIR/logoutput-sorted"
+fi

(Note: it seems you forgot to Cc me - I extracted your mail from the BTS
web interface to make this answer. However I now am subscribed to this
bug report so that should not matter anymore!)

Le jeudi 20 juillet 2023 à 21:43, d'après
Richard Lewis <richard.lewis.debian@googlemail.com> :

Sorry, bad explanation on my part. What I started to see in logcheck
reports was: two times the same event, one with the rsyslog timestamp
and one with the journalctl timestamp. So I started to search why this
was happening and tried to make it so that each event would be reported
only once, like it was before the journal-checking was enabled. But that
does not seem to be really possible, more on that below.
in the mail report, so that it can be easier (both for sort and for a
human) to read and compare.

Let's take a single sample event, getting logged both by rsylog and
journald.

With the default configuration and without my patch I get this in the
report, which is really not easy to read because of the huge difference
in timestamp formatting (and also, there's no way this can be sorted
correctly):

2023-07-20T21:10:16.791208+02:00 silk fetchmail[2839]: mailbox selection failed
Jul 20 21:10:16 silk fetchmail[2839]: mailbox selection failed

With my patch to use "journalctl -o short-iso-precise", I get this
(a little better):

2023-07-20T21:10:16.790956+0200 silk fetchmail[2839]: mailbox selection failed
2023-07-20T21:10:16.791208+02:00 silk fetchmail[2839]: mailbox selection failed

And when adding the missing ':' I get this:

2023-07-20T21:10:16.790956+02:00 silk fetchmail[2839]: mailbox selection failed
2023-07-20T21:10:16.791208+02:00 silk fetchmail[2839]: mailbox selection failed

I initially thought that it would also enable me, by using SORTUNIQ=1,
to only have one report instead of a double report for each event (one
from rsyslog and one from journalctl), but in fact I now think that is
not possible because as you can see above, both rsyslog and journal
appear to use their own timestamp values which are slightly different,
so even with the same formatting they are different and cannot be
treated by "sort -u".

I don't know what to do about that. This doesn't solve my inital problem
(duplicate events in the report), but at least they have a similar
timestamp format that 1) makes it really easier to "compare" them by eye
and 2) allows logcheck to sort them).

I think each line starts either with a timestamp, or with whitespace as
indentation. This is done in the print_multiline() function in
src/shared/logs-show.c in the systemd source, from what I understand.

One sample of it that I recall was an error event in a Perl program that
led it to log several lines of Perl code (in the same log message). Once
it had passed through logcheck's sort treatment it was obviously
unusable :)

I think i tried at the time (this was a few months ago) to use
SORTUNIQ=1 (it it set to 0 by default), I don't recall exactly, but you
are right, this is not correct. The logic was initially to use 'sort -u'
or only 'sort' and I wrongly transformed it to 'sort -u' or 'sort |
uniq' which I agree is total nonsense. Sorry about that.

The sort key selection probably still needs to be adjusted though. When
using ISO_TIMESTAMPS, the whole timestamp is in the first field so '-k
1' should be used. If not using ISO_TIMESTAMPS, the original behaviour
of "-k 1,3" is used (I don't understand it though: that would be the
month and then the hh:mm::ss parts?).

Regards,
Tom

Thank-you, i understand now.

I suppose the timestamp difference is because the journal 'gets' the
message, and then forwards it to rsyslog which then creates its own
timestamp,
so even if systemd and rsyslog would agree a common format, this will
always be an issue.

Personally, i would just tell rsyslog to use the less precise format,
(or stop using rsyslog entirely).

Instead of changing journal lines to add the colon you could perhaps
try and delete all the decimals after the . , which would (usually?)
make them identical to the journal timestamps.

This might be overkill, but we could make the pre-processing of log
files be more customisable, so the user could choose whatever mangling
of timestamps, whitespace and/or sorting they want.

ie make it so that in logcheck.conf there are variables
PRE_PROCESS_LOG_ENTRIES="sed -e s/[[:space:]]$g/ -e ...."
POST_PROCESS_LOG_ENTRIES="sort -k1,3 -u"
# and/or set JOURNALCTL_OPTS=(-o iso-whatever)

and then logcheck could use eval,
eval $PRE_PROCESS_LOG_ENTRIES logoutput > logputput.1
eval $POST_PROCESS_LOG_ENTRIES logoutput > logputput.1

then people can do arbitrary mangling of timestamps or whatever. This
would avoid over-complicating the logic in logcheck at the expense of
requiring the user to write the sed/sort lines

i also get multiple lines from sbuild (although i just wrote local
rules to match each fragment)

It's sorting on fields one to three which are the 'Mmm DD HH:MM:SS'
bit in the old-style timestamp:
so (except for around midnight!) this sorts in date order, but not
change the order of messages.

(i dont know  -u is not included!)

Le vendredi 21 juillet 2023 à 23:32, d'après
Richard Lewis <richard.lewis.debian@googlemail.com> :

Yes, that's what I thought too.

The more precise format has been the default in rsyslog for quite some
time.

I quite like my old habits wrt to /var/log/* :p

But I now understand that all that is logged via rsyslog comes from
systemd-journald anyway, so there's actually no point for logcheck to
check both rsyslog files and the journal! I instructed logcheck to only
look at the journal, and I therefore no longer have my "duplicates"
problem. Maybe that should be the new default for the logcheck package,
or at least having some explicit documentation about it?
[...]

The possibility of setting JOURNALCTL_OPTS would be great! I think the
pre/post-processing customisation is a good idea too, to move all that
logic from the code to the configuration.

i think that might be premature to chamge the default - it would require
people using rsyslog to change a conffile, whereas the current default
should work for everyone.

But agree the docs need a regresh. a quick win would be to add a comment to
say how to disable checking of syslog.

cool.  this does seem the way to go (there are other priorities, but
consider it on the todo list!)

Le jeudi 27 juillet 2023 à 18:44, d'après
Richard Lewis <richard.lewis.debian@googlemail.com> :

Great! Thanks.

Dear Maintainer,

I also had the problem of duplicated journalctl/rsyslogd messages with
different time formatting, but otherwise than suggested in this bug I'd
like to move to the precision format - and thus came up with a patch to
specify journalctl options before I even found this bug.

So perhaps you'd like to use (or adapt) my simple path which allowes to
add this to the configuration, if desired:

JOURNALCTL_OPTS="-oshort-iso-precise"