Minor: Upgrade to 2.5.2: Default mark interval sometimes buggy

[opty77]

DISCLAIMER: Nothing fatal, just nice to become fixed if confirmed. :-)

Upgrade from 2.5.0:

2023-12-16T14:20:00.572539+01:00 qeporkak rc.syslog 9623 - - syslogd[821] v2.5.0: exiting on signal 15.
2023-12-16T14:20:00.585404+01:00 qeporkak syslogd 821 - - exiting on signal 15
2023-12-16T14:20:00.805136+01:00 qeporkak syslogd 9662 - - syslogd v2.5.2: restart.
2023-12-16T14:20:00.931679+01:00 qeporkak rc.syslog 9622 - - syslogd[9662] v2.5.2: restarted.
[...]
2023-12-16T14:28:35.463660+01:00 qeporkak sudo 9870 - -     opty : TTY=pts/3 ; PWD=/tmp ; USER=root ; COMMAND=/usr/bin/bash -c 'echo subseconds >> /dev/kmsg' ; EXIT=0
2023-12-16T14:40:00.826174+01:00 qeporkak syslogd 9662 - - -- MARK --
[...]
2023-12-16T15:47:01.653317+01:00 qeporkak crond 993 - - FILE /var/spool/cron/crontabs/root USER root PID 10299 /usr/bin/run-parts /etc/cron.hourly 1> /dev/null 
2023-12-16T15:48:30.899172+01:00 qeporkak syslogd 9662 - - -- MARK --

Upgrade from 2.3.0:

2023-12-16T17:08:51.091519+01:00 vodopnik syslogd 855 - - exiting on signal 15
2023-12-16T17:08:51.151878+01:00 vodopnik syslogd 20733 - - syslogd v2.5.2: restart.
2023-12-16T17:08:51.160532+01:00 vodopnik sudo 20725 - - pam_unix(sudo:session): session closed for user root
2023-12-16T17:08:51.160658+01:00 vodopnik sudo 20725 - -     opty : TTY=pts/1 ; PWD=/tmp ; USER=root ; COMMAND=/usr/bin/bash -c '/etc/rc.d/rc.syslog stop; timeout 1 pwait -U root -P 1 syslogd; /etc/rc.d/rc.syslog start' ; EXIT=0
2023-12-16T17:09:21.152714+01:00 vodopnik syslogd 20733 - - -- MARK --
[...]
2023-12-16T18:54:08.739143+01:00 vodopnik sudo 20876 - -     opty : TTY=pts/0 ; PWD=/home/opty ; USER=root ; COMMAND=/usr/bin/sort /var/log/messages /var/log/syslog /var/log/debug /var/log/secure /var/log/cron ; EXIT=0
2023-12-16T19:12:21.310191+01:00 vodopnik syslogd 20733 - - -- MARK --

Another upgrade from 2.3.0:

2023-12-16T17:30:00.426779+01:00 zeryk syslogd 717 - - exiting on signal 15
2023-12-16T17:30:00.539748+01:00 zeryk syslogd 12698 - - syslogd v2.5.2: restart.
2023-12-16T17:30:00.567819+01:00 zeryk sudo 12690 - - pam_unix(sudo:session): session closed for user root
2023-12-16T17:30:00.568191+01:00 zeryk sudo 12690 - -     opty : TTY=pts/1 ; PWD=/tmp ; USER=root ; COMMAND=/usr/bin/bash -c '/etc/rc.d/rc.syslog stop; timeout 1 pwait -U root -P 1 syslogd; /etc/rc.d/rc.syslog start' ; EXIT=0
2023-12-16T17:30:30.540190+01:00 zeryk syslogd 12698 - - -- MARK --
[...]
2023-12-16T18:02:45.756859+01:00 zeryk kernel - - - [IPTABLES DROP]: IN=eth1 OUT= MAC=<snip> SRC=<snip> DST=<snip> LEN=44 TOS=0x00 PREC=0x00 TTL=232 ID=54321 PROTO=TCP SPT=54455 DPT=16161 WINDOW=65535 RES=0x00 SYN URGP=0 
2023-12-16T18:04:30.557294+01:00 zeryk syslogd 12698 - - -- MARK --
[...]
2023-12-16T18:24:01.297942+01:00 zeryk crond 1030 - - FILE /var/spool/cron/crontabs/opty USER opty PID 12791 /home/opty/bin/ntpdrift 
2023-12-16T18:24:30.567278+01:00 zeryk syslogd 12698 - - -- MARK --

First and third -- MARK -- in the very last example may relate to

sysklogd/man/syslogd.8

Lines 627 to 641 in 3332c55

	The mark interval, as controlled by the
	.Fl m Ar INTV
	option, relies on an internal timer with 30 second granularity. Every
	30 seconds
	.Nm
	will attempt to log the text
	.Cd "-- MARK --"
	with (the internal) facility
	.Cd mark
	and priority
	.Cd info .
	Every log target is traversed, if at least
	.Ar INTV
	minutes have passed since the log target was written to, the mark is
	logged. Hence, it may be off by up to 30 seconds, this is by design.

?

[troglobit]

When filing an issue report. Please include in the description what you believe to be the issue. What may be obvious to you is maybe not obvious to others.

[opty77]

In the initial example the first -- MARK -- following daemon restart appears after about 11 minutes regarding previous message and the second one even after about one minute.

In the next example the first -- MARK -- appears almost right away after about 30 seconds regarding previous message and the second one after about 18 minutes. Oh well, quite close to 20 minutes of the default interval.

And in the final example the first -- MARK -- appears again almost right away after about 30 seconds regarding previous message, the second one after about 100 seconds and the third one after about 30 seconds.

I wouldn't expect such short actual intervals.

[opty77]

It seems that at least messages from sudo, crond and kernel don't reset the timer for -- MARK --.

I should have already mentioned that yesterday but those -- MARK --s almost right away following daemon restart made me doubt.

[troglobit]

Since I don't use MARK in my setups at all, the following is a speculative patch:

diff --git a/src/syslogd.c b/src/syslogd.c
index 68040fe..e0a637f 100644
--- a/src/syslogd.c
+++ b/src/syslogd.c
@@ -1679,8 +1679,22 @@ static void logmsg(struct buf_msg *buffer)
 
                /* don't output marks to recently written files */
                if (buffer->flags & MARK) {
-                       if (timer_now() - f->f_time < MarkInterval)
+                       switch (f->f_type) {
+                       case F_CONSOLE:
+                       case F_FILE:
+                       case F_FORW:
+                       case F_PIPE:
+                       case F_TTY:
+                       case F_USERS:
+                       case F_WALL:
+                               /* relevant log targets that set f->f_time */
+                               if ((timer_now() - f->f_time) < MarkInterval)
+                                       continue;
+                               break;
+                       default:
+                               /* skip --MARK-- for other log targets */
                                continue;
+                       }
                }
 
                /*

[opty77]

@troglobit: Thanks but unfortunately it didn't help:

2024-04-25T14:45:30.687912+02:00 vodopnik syslogd 1952 - - exiting on signal 15
2024-04-25T14:45:30.765371+02:00 vodopnik syslogd 26337 - - syslogd v2.5.2: restart.
2024-04-25T14:46:00.766331+02:00 vodopnik syslogd 26337 - - -- MARK --

[troglobit]

OK, that's unfortunate, because I cannot reproduce your issue at all. Is there anything special about your configuration you can think of?

[opty77]

Most probably just ;RFC5424 in /etc/syslog.conf so far.

[troglobit]

OK. So no pipes or alerting users pure similar odd stuff then. Alright.

And you're on Slackware, right, with a custom kernel?

[opty77]

Indeed.

[opty77]

Just for sure: Have you used any 32-bit system too when trying to reproduce?

[troglobit]

No. All 32-bit systems have aged out in all my environments.