• Unknown entries from news log file

    From John@21:1/5 to All on Mon Jul 24 21:37:08 2023
    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

    --- SoupGate-Win32 v1.05
    * Origin: fsxNet Usenet Gateway (21:1/5)
  • From =?UTF-8?Q?Julien_=c3=89LIE?=@21:1/5 to All on Sat Jul 29 11:01:39 2023
    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
  • From =?UTF-8?Q?Julien_=c3=89LIE?=@21:1/5 to All on Sat Jul 29 12:04:02 2023
    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");
  • From John@21:1/5 to iulius@nom-de-mon-site.com.invalid on Sat Jul 29 17:09:53 2023
    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

    --- SoupGate-Win32 v1.05
    * Origin: fsxNet Usenet Gateway (21:1/5)
  • From =?UTF-8?Q?Julien_=c3=89LIE?=@21:1/5 to All on Sat Jul 29 23:32:38 2023
    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)

    --- SoupGate-Win32 v1.05
    * Origin: fsxNet Usenet Gateway (21:1/5)