Bug#1041524: logcheck: badly handles "rsyslog + journalctl" checking

[Thomas Parmelan]

Package: logcheck
Version: 1.4.3
Severity: normal
Tags: patch
X-Debbugs-Cc: tom+d...@ankh.fr.EU.org

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

-- System Information:
Debian Release: trixie/sid
APT prefers unstable
APT policy: (500, 'unstable')
Architecture: amd64 (x86_64)
Foreign Architectures: i386

Kernel: Linux 6.3.0-2-amd64 (SMP w/8 CPU threads; PREEMPT)
Kernel taint flags: TAINT_PROPRIETARY_MODULE, TAINT_OOT_MODULE, TAINT_UNSIGNED_MODULE
Locale: LANG=fr_FR.UTF-8, LC_CTYPE=fr_FR.UTF-8 (charmap=UTF-8), LANGUAGE not set
Shell: /bin/sh linked to /usr/bin/dash
Init: systemd (via /run/systemd/system)

Versions of packages logcheck depends on:
ii adduser 3.137
ii cron [cron-daemon] 3.0pl1-162
ii lockfile-progs 0.1.19
ii logtail 1.4.3
ii mime-construct 1.12+really1.11-1
ii postfix [mail-transport-agent] 3.8.1-2

Versions of packages logcheck recommends:
ii logcheck-database 1.4.3

Versions of packages logcheck suggests:
ii rsyslog [system-log-daemon] 8.2306.0-2

--
Thomas Parmelan

[Richard Lewis]

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

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

> 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.

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!

> 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

I think my question above is related to this bullet: a typical prefix
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?

> - join continuous lines (lines starting with whitespace) from
> journalctl output, as rsyslog only logs them as one line

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?

> - handle SORTUNIQ correctly even when using ISO_TIMESTAMPS

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?


-if [ "$SORTUNIQ" -eq 1 ];then
- SORT="sort -u"
-else
- SORT="sort -k 1,3 -s"
-fi

- $SORT "$TMPDIR/logoutput"/* | sed -e 's/[[:space:]]\+$//' >
"$TMPDIR/logoutput-sorted" \
+# Use "sort -u" or "sort ... | uniq"
+if [ "$SORTUNIQ" -eq 1 ];then
+ SORT_OPTS="-u"
+ sort $SORT_OPTS "$TMPDIR/logoutput"/* | sed -e 's/[[:space:]]\+$//'
> "$TMPDIR/logoutput-sorted" \
+ || 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

[Thomas Parmelan]

(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.le...@googlemail.com> :

> > 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.
>
> 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!

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.

> > - 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
>
> I think my question above is related to this bullet: a typical prefix
> 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?

The point of this manipulation is to have only one format of timestamp
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).

> > - join continuous lines (lines starting with whitespace) from
> > journalctl output, as rsyslog only logs them as one line
>
> 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 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 :)

> > - handle SORTUNIQ correctly even when using ISO_TIMESTAMPS
>
> 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?

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

--
Thomas Parmelan

[Richard Lewis]

On Fri, 21 Jul 2023 at 09:57, Thomas Parmelan <tom+d...@ankh.fr.eu.org> wrote:
>
> Le jeudi 20 juillet 2023 à 21:43, d'après
> Richard Lewis <richard.le...@googlemail.com> :

> 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".

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

> 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 also get multiple lines from sbuild (although i just wrote local
rules to match each fragment)

> > > - handle SORTUNIQ correctly even when using ISO_TIMESTAMPS
> >
> > 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?
>
> 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?).

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!)

[Thomas Parmelan]

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

> 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.

Yes, that's what I thought too.

> Personally, i would just tell rsyslog to use the less precise format,

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

> (or stop using rsyslog entirely).

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?

> 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.

[...]

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.

--
Thomas Parmelan

[Richard Lewis]

On Mon, 24 Jul 2023, 12:33 Thomas Parmelan, <tom+d...@ankh.fr.eu.org> wrote:

Le vendredi 21 juillet 2023 à 23:32, d'après

> (or stop using rsyslog entirely).

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?

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.

> 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.
[...]

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.

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

[Thomas Parmelan]

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

> 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.
>
> cool.  this does seem the way to go (there are other priorities, but consider
> it on the todo list!)

Great! Thanks.

--
Thomas Parmelan

[Stefan Froehlich]

Package: logcheck
Version: 1.4.2
Followup-For: Bug #1041524

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"




-- System Information:
Debian Release: 12.0
APT prefers stable-updates
APT policy: (500, 'stable-updates'), (500, 'stable-security'), (500, 'oldstable-updates'), (500, 'oldstable-security'), (500, 'stable'), (500, 'oldstable')
Architecture: amd64 (x86_64)

Kernel: Linux 6.1.0-10-amd64 (SMP w/8 CPU threads; PREEMPT)
Locale: LANG=de_AT.UTF-8, LC_CTYPE=de_AT.UTF-8 (charmap=UTF-8), LANGUAGE=en_US:en

Shell: /bin/sh linked to /usr/bin/dash
Init: systemd (via /run/systemd/system)

LSM: AppArmor: enabled

Versions of packages logcheck depends on:

ii adduser 3.134

ii cron [cron-daemon] 3.0pl1-162
ii lockfile-progs 0.1.19

ii logtail 1.4.2
ii mime-construct 1.12+really1.11-1
ii sendmail-bin [mail-transport-agent] 8.17.1.9-2

Versions of packages logcheck recommends:

ii logcheck-database 1.4.2

Versions of packages logcheck suggests:

ii rsyslog [system-log-daemon] 8.2302.0-1

-- Configuration Files:
/etc/logcheck/header.txt [Errno 13] Permission denied: '/etc/logcheck/header.txt'
/etc/logcheck/logcheck.conf [Errno 13] Permission denied: '/etc/logcheck/logcheck.conf'
/etc/logcheck/logcheck.logfiles [Errno 13] Permission denied: '/etc/logcheck/logcheck.logfiles'
/etc/logcheck/logcheck.logfiles.d/journal.logfiles [Errno 13] Permission denied: '/etc/logcheck/logcheck.logfiles.d/journal.logfiles'
/etc/logcheck/logcheck.logfiles.d/syslog.logfiles [Errno 13] Permission denied: '/etc/logcheck/logcheck.logfiles.d/syslog.logfiles'

-- no debconf information