imfile-logrotate-async.sh failure on 32bit arm

[markhindley]

Hello,

When building the Devuan fork of Debian's rsyslog, we are encountering failures of the imfile-logrotate-async.sh test on both 32bit arm (armel and armhf).

Version v8.2212.0

The build is the same as Debian, but without systemd and journal support. Sources are available here

FAIL: imfile-logrotate-async

============================

[inotify mode]
testbench: TZ env var not set, setting it to UTC

14:36:09[0] Test: ./imfile-logrotate-async.sh

/usr/sbin/logrotate
config rstb_738081_2ca568c9pIEA_.conf is:
1 module(load="../plugins/imdiag/.libs/imdiag")
2 global(inputs.timeout.shutdown="60000"
3 default.action.queue.timeoutshutdown="20000"
4 default.action.queue.timeoutEnqueue="20000")
5 # use legacy-style for the following settings so that we can override if needed
6 $MainmsgQueueTimeoutEnqueue 20000
7 $MainmsgQueueTimeoutShutdown 10000
8 $IMDiagListenPortFileName rstb_738081_2ca568c9pIEA.imdiag.port
9 $IMDiagServerRun 0
10 $IMDiagAbortTimeout 580
11
12 :syslogtag, contains, "rsyslogd" ./rstb_738081_2ca568c9pIEA.started
13 ###### end of testbench instrumentation part, test conf follows:
14
15 $WorkDirectory rstb_738081_2ca568c9pIEA.spool
16
17 global( debug.whitelist="on"
18 debug.files=["imfile.c", "stream.c"]
19 )
20
21 module(load="../plugins/imfile/.libs/imfile" mode="inotify" PollingInterval="2")
22
23 input(type="imfile" File="./rstb_738081_2ca568c9pIEA.input*.log" Tag="file:"
24 Severity="error" Facility="local7" addMetadata="on" reopenOnTruncate="on")
25
26 $template outfmt,"%msg:F,58:2%\n"
27 if $msg contains "msgnum:" then
28 action(type="omfile" file="rstb_738081_2ca568c9pIEA.out.log" template="outfmt")
rsyslogd: NOTE: RSYSLOG_DEBUG_TIMEOUTS_TO_STDERR activated
main Q:Reg: worker start requested, num workers currently 0
main Q:Reg: wrkr start initiated with state 0, num workers now 1
rsyslog debug: main Q:Reg: worker 0x1c6ac58 started
rsyslog debug: main Q:Reg: started with state 3, num workers now 1
14:36:10[1] rstb_738081_2ca568c9pIEA:.pid found, pid 2617
14:36:10[1] rsyslogd startup msg seen, pid 2617
waiting for file rstb_738081_2ca568c9pIEA.imdiag.port
imdiag port: 34381
inputfilegen: had hup, sig 1
inputfilegen: rstb_738081_2ca568c9pIEA.input.log reopened
inputfilegen: current message number 3231
======================:
ROTATE 1 INPUT FILES:
15606776 -rw-r--r-- 1 pbuilder pbuilder 12288 Dec 19 14:36 rstb_738081_2ca568c9pIEA.input.log
15606774 -rw-r--r-- 1 pbuilder pbuilder 54927 Dec 19 14:36 rstb_738081_2ca568c9pIEA.input.log.1
15606773 -rw-r--r-- 1 pbuilder pbuilder 5 Dec 19 14:36 rstb_738081_2ca568c9pIEA.inputfilegen_pid
inputfilegen: had hup, sig 1
inputfilegen: rstb_738081_2ca568c9pIEA.input.log reopened
inputfilegen: current message number 6867
======================:
ROTATE 2 INPUT FILES:
15606621 -rw-r--r-- 1 pbuilder pbuilder 12288 Dec 19 14:36 rstb_738081_2ca568c9pIEA.input.log
15606776 -rw-r--r-- 1 pbuilder pbuilder 61812 Dec 19 14:36 rstb_738081_2ca568c9pIEA.input.log.1
15606774 -rw-r--r-- 1 pbuilder pbuilder 54927 Dec 19 14:36 rstb_738081_2ca568c9pIEA.input.log.2
15606773 -rw-r--r-- 1 pbuilder pbuilder 5 Dec 19 14:36 rstb_738081_2ca568c9pIEA.inputfilegen_pid
rsyslogd: imfile: poll_tree cannot stat file '/build/rsyslog-8.2212.0/tests/rstb_738081_2ca568c9pIEA.input.log' - ignored: No such file or directory [v8.2212.0]
inputfilegen: had hup, sig 1
inputfilegen: last message number was 10000
======================:
ROTATE 3 INPUT FILES:
15606512 -rw-r--r-- 1 pbuilder pbuilder 0 Dec 19 14:36 rstb_738081_2ca568c9pIEA.input.log
15606621 -rw-r--r-- 1 pbuilder pbuilder 53248 Dec 19 14:36 rstb_738081_2ca568c9pIEA.input.log.1
15606776 -rw-r--r-- 1 pbuilder pbuilder 61812 Dec 19 14:36 rstb_738081_2ca568c9pIEA.input.log.2
15606774 -rw-r--r-- 1 pbuilder pbuilder 54927 Dec 19 14:36 rstb_738081_2ca568c9pIEA.input.log.3
15606773 -rw-r--r-- 1 pbuilder pbuilder 5 Dec 19 14:36 rstb_738081_2ca568c9pIEA.inputfilegen_pid
======================:
ls rstb_738081_2ca568c9pIEA.spool:
total 4
15729697 -rw------- 1 pbuilder pbuilder 140 Dec 19 14:36 imfile-state:15606621:a4aec819b6fce2c4
======================:
FINAL INPUT FILES:
15606512 -rw-r--r-- 1 pbuilder pbuilder 0 Dec 19 14:36 rstb_738081_2ca568c9pIEA.input.log
15606621 -rw-r--r-- 1 pbuilder pbuilder 53248 Dec 19 14:36 rstb_738081_2ca568c9pIEA.input.log.1
15606776 -rw-r--r-- 1 pbuilder pbuilder 61812 Dec 19 14:36 rstb_738081_2ca568c9pIEA.input.log.2
15606774 -rw-r--r-- 1 pbuilder pbuilder 54927 Dec 19 14:36 rstb_738081_2ca568c9pIEA.input.log.3
15606773 -rw-r--r-- 1 pbuilder pbuilder 5 Dec 19 14:36 rstb_738081_2ca568c9pIEA.inputfilegen_pid
======================:
LINES: 0 rstb_738081_2ca568c9pIEA.input.log
TAIL rstb_738081_2ca568c9pIEA.input.log:

LINES: 3133 rstb_738081_2ca568c9pIEA.input.log.1
TAIL rstb_738081_2ca568c9pIEA.input.log.1:
msgnum:00009990:
msgnum:00009991:
msgnum:00009992:
msgnum:00009993:
msgnum:00009994:
msgnum:00009995:
msgnum:00009996:
msgnum:00009997:
msgnum:00009998:
msgnum:00009999:

LINES: 3636 rstb_738081_2ca568c9pIEA.input.log.2
TAIL rstb_738081_2ca568c9pIEA.input.log.2:
msgnum:00006857:
msgnum:00006858:
msgnum:00006859:
msgnum:00006860:
msgnum:00006861:
msgnum:00006862:
msgnum:00006863:
msgnum:00006864:
msgnum:00006865:
msgnum:00006866:

wc: rstb_738081_2ca568c9pIEA.inpt.log.3: No such file or directory
LINES:
TAIL rstb_738081_2ca568c9pIEA.input.log.3:
msgnum:00003221:
msgnum:00003222:
msgnum:00003223:
msgnum:00003224:
msgnum:00003225:
msgnum:00003226:
msgnum:00003227:
msgnum:00003228:
msgnum:00003229:
msgnum:00003230:

14:36:12 wait_file_lines waiting, expected 10000, current 9999 lines
14:36:12 wait_file_lines waiting, expected 10000, current 9999 lines
14:36:12 wait_file_lines waiting, expected 10000, current 9999 lines
14:36:12 wait_file_lines waiting, expected 10000, current 9999 lines
[...]
14:37:41 wait_file_lines waiting, expected 10000, current 9999 lines
wait_file_lines failed, expected 10000 got 9999 after 1671460662 retries, took 90 seconds

i386 and all 64bit builds pass.

I saw the timing of that test was recently adjusted, but I am unclear if that is a related issue.

Thanks for any advice on debugging or fixing.

Mark

[rgerhards]

The timing change indeed seems to be the root cause of the failure.

[markhindley]

Let me know if there is anything I can contribute to help fix the test timing.