In my daily report, I always have a lot of stuff in the "Unknown
entries" section:

Unknown entries from news log file:
First 50 / 3351 lines (1.5%)
2023-07-23T04:15:01.882775+00:00 localhost innd: ctlinnd command E
2023-07-23T04:15:01.882898+00:00 localhost innd: SERVER servermode paused
2023-07-23T04:15:01.889064+00:00 localhost innfeed[3010274]:
news.quux.org:0
checkpoint seconds 86397 offered 1869 accepted 0 refused 1867 rejected 0 accsize 0 rejsize 0

I'm running rsyslog, with the following log files configured in /etc/rsyslog.d/news.conf:

news.crit /var/log/news/news.crit
news.err /var/log/news/news.err
news.notice /var/log/news/news.notice
news.debug /var/log/news/news.debug

Otherwise, rsyslog.conf is unmodified aside from adding news.none to the
/var/log/syslog rule.

It sort of looks like the contents of news.notice are also ending up in
/var/log/news/news, but I'm not sure why or how to change that. Any
suggestions?

This is Debian 12, if that's helpful.

john

Hi John,

> In my daily report, I always have a lot of stuff in the "Unknown
> entries" section:
>
> Unknown entries from news log file:
> First 50 / 3351 lines (1.5%)
> 2023-07-23T04:15:01.882775+00:00 localhost innd: ctlinnd command E

Timestamps in my news log files look like:

[news.notice]
Jul 29 04:15:01 news innd[3334925]: ctlinnd command E

[news]
Jul 29 04:35:01.632 + feed.usenet-fr.net [...]

I've just checked, and it seems that the innreport script only handles
lines with a format like the above ones:

($day, $hour, $prog, $left)
=~ m/^(\S+\s+\S+) (\S+) \S+ (\S+): (.*)$/o;

It is the low-precision timestamp used by syslog.

> This is Debian 12, if that's helpful.
https://www.debian.org/releases/bookworm/amd64/release-notes/ch-information.en.html#rsyslog-timestamp-change-affects-logcheck

rsyslog now defaults to “high precision timestamps” which may affect
other programs that analyze the system logs.

Oh, this is an unexpected change which unfortunately breaks daily Usenet
reports as innreport does not cope with that new setting :-/

I bet inn2 is not the only package which broke with that change...
It's probably worthwhile a fix in Debian stable (12) as innreport is
broken. I'll send a mail to Marco (the inn2 package maintainer) as I am
unsure he reads us here.

FWIW, the high-precision timestamp is enabled with a line like this one
in rsyslog.conf:
$ActionFileDefaultTemplate RSYSLOG_FileFormat
instead of RSYSLOG_TraditionalFileFormat (low-precision).

Anyway, innreport should really support high-precision timestamps.
Could you please try the following patch and tell me whether it works
for your next daily reports?

I've tested it with a test file on my system, and innreport correctly
recognizes "2023-07-23T04:15:01.882775+00:00" with it:

Control commands to INND:
Command Number
logmode 1

TOTAL: 1 1

--- scripts/innreport.in
+++ scripts/innreport.in
@@ -95,6 +95,7 @@
use strict;
use Carp qw( cluck confess );
use Time::Local;
+use Time::Piece;

## Default display configuration file (parameter added in INN 2.7.0).
my $DISPLAY_FILE = 'innreport-display.conf';
@@ -452,6 +453,18 @@ while (!eof()) {
my ($res, $day, $hour, $prog, $left);
DECODE:
{
+ # Convert a high-precision timestamp like
+ # 2023-07-23T04:15:01.882775+02:00
+ # to the low-precision timestamp used by innreport.
+ if ($_ =~
/^(\d+-\d+-\d+T\d+:\d+:\d+)(\.\d+)?([+-]\d+):?(\d+)/) {
+ my $t = Time::Piece->strptime(
+ "$1 $3$4",
+ "%Y-%m-%dT%T %z"
+ );
+ my $newdate = $t->monname . " " . $t->mday . " " . $t->hms;
+ $_ =~ s/^\S+/$newdate/;
+ }
+ ($day, $hour, $prog, $left)
= $_ =~ m/^(\S+\s+\S+) (\S+) \S+ (\S+): \[ID \d+ \S+\]
(.*)$/o;
if ($day) { last DECODE; }

I've used Time::Piece as it is a Perl core module.

> It sort of looks like the contents of news.notice are also ending up in
> /var/log/news/news, but I'm not sure why or how to change that. Any
> suggestions?

Are you really sure "2023-07-23T04:15:01.882775+00:00 localhost innd:
ctlinnd command E" appears in /var/log/news/news? (and not only in
/var/log/news/news.notice?)
Your rsyslog rules explicitly mention news.notice.

--
Julien ÉLIE

« Tempora si fuerint nubila, solus eris. » (Ovide)

Adding to my previous message:

>> This is Debian 12, if that's helpful.
>
> https://www.debian.org/releases/bookworm/amd64/release-notes/ch-information.en.html#rsyslog-timestamp-change-affects-logcheck
>
>   rsyslog now defaults to “high precision timestamps” which may affect
>   other programs that analyze the system logs.
>
>
> Oh, this is an unexpected change which unfortunately breaks daily Usenet
> reports as innreport does not cope with that new setting :-/
>
> I bet inn2 is not the only package which broke with that change...
> It's probably worthwhile a fix in Debian stable (12) as innreport is
> broken.  I'll send a mail to Marco (the inn2 package maintainer) as I am
> unsure he reads us here.

Mail sent.
You may also want to open a Debian bug report for the inn2 package if
you wish (so that other people see that issue).

> +            # Convert a high-precision timestamp like
> +            #   2023-07-23T04:15:01.882775+02:00
> +            # to the low-precision timestamp used by innreport.
> +            if ($_ =~
> /^(\d+-\d+-\d+T\d+:\d+:\d+)(\.\d+)?([+-]\d+):?(\d+)/) {
> +                my $t = Time::Piece->strptime(
> +                    "$1 $3$4",
> +                    "%Y-%m-%dT%T %z"
> +                );

I've adapted the patch to actually use the local time zone, and not UTC.
It indeed seems like rsyslog uses UTC by default, so if the time zone is
"+00:00" in the logs, innreport tries to get the local time zone, and
use it.

2023-07-23T04:15:01.882775+00:00 in France with an actual +0200 timezone
will mean 2h15 and not 4h15.

--- a/scripts/innreport.in
+++ b/scripts/innreport.in
@@ -95,6 +95,7 @@
use strict;
use Carp qw( cluck confess );
use Time::Local;
+use Time::Piece;

## Default display configuration file (parameter added in INN 2.7.0).
my $DISPLAY_FILE = 'innreport-display.conf';
@@ -452,6 +453,26 @@ while (!eof()) {
my ($res, $day, $hour, $prog, $left);
DECODE:
{
+ # Convert a high-precision timestamp like
+ # 2023-07-23T04:15:01.882775+02:00
+ # to the low-precision timestamp used by innreport.
+ if ($_ =~
/^(\d+-\d+-\d+T\d+:\d+:\d+)(\.\d+)?([+-]\d+):?(\d+)/) {
+ my $tzone = "$3$4";
+ my $t;
+ + # Retrieve the local time zone, if logging is in UTC.
+ if ("$tzone" eq "+0000") {
+ my $localt = localtime;
+ $tzone = $localt->strftime("%z");
+ $t = Time::Piece->strptime("$1 $tzone",
"%Y-%m-%dT%T %z");
+ } else {
+ $t = Time::Piece->strptime("$1", "%Y-%m-%dT%T");
+ }
+ + my $newdate = $t->monname . " " . $t->mday . " " . $t->hms;
+ $_ =~ s/^\S+/$newdate/;
+ }
+ ($day, $hour, $prog, $left)
= $_ =~ m/^(\S+\s+\S+) (\S+) \S+ (\S+): \[ID \d+ \S+\]
(.*)$/o;
if ($day) { last DECODE; }

--
Julien ÉLIE

« Tempora si fuerint nubila, solus eris. » (Ovide)

Julien ÉLIE <iulius@nom-de-mon-site.com.invalid> writes:
> https://www.debian.org/releases/bookworm/amd64/release-notes/ch-information.en.html#rsyslog-timestamp-change-affects-logcheck
>
> rsyslog now defaults to “high precision timestamps” which may affect
> other programs that analyze the system logs.
>
>
> Oh, this is an unexpected change which unfortunately breaks daily
> Usenet reports as innreport does not cope with that new setting :-/
>

Ah, I see... the high-precision timestamps are actually pretty nice
because syslog's old year-less timestamps were a constant source of pain
to me, but of course it's breaking stuff...

>
> FWIW, the high-precision timestamp is enabled with a line like this
> one in rsyslog.conf:
> $ActionFileDefaultTemplate RSYSLOG_FileFormat
> instead of RSYSLOG_TraditionalFileFormat (low-precision).
>
>
> Anyway, innreport should really support high-precision
> timestamps. Could you please try the following patch and tell me
> whether it works for your next daily reports?
>

I applied the patch to innreport; I assume it'll get blown away with the
next time the Debian package updates, but maybe by then we'll have an
official fix in.

Ran news.daily manually and the report looks good, no more unknown
entries section!

Thank you,

john

Hi John,

>> rsyslog now defaults to “high precision timestamps” which may affect
>> other programs that analyze the system logs.
>>
>> Oh, this is an unexpected change which unfortunately breaks daily
>> Usenet reports as innreport does not cope with that new setting :-/
>
> Ah, I see... the high-precision timestamps are actually pretty nice
> because syslog's old year-less timestamps were a constant source of pain
> to me, but of course it's breaking stuff...

Sure, I agree the high-precision timestamps are better.
They should have been supported by innreport sooner!
At least, that's now done :)

> I applied the patch to innreport; I assume it'll get blown away with the
> next time the Debian package updates, but maybe by then we'll have an
> official fix in.

The next package update will very probably have this patch.
I'll commit it tomorrow to the 2.7 branch (slightly improved for only
computing the local timezone once, and not for every log line parsed).

> Ran news.daily manually and the report looks good, no more unknown
> entries section!

Thanks for having tested. I'm glad it fixes the issue.

And naturally, many thanks for having reported the issue!

--
Julien ÉLIE

« A killfile on Usenet can get you peace and quiet. A killfile in the
real world can get you twenty years to life. » (Nils Nieuwjaar)