debcrafters-packages team mailing list archive
-
debcrafters-packages team
-
Mailing list archive
-
Message #03051
[Bug 2083700] Re: rsyslog FTBFS due to gzip different behavior with hw acceleration on s390x
# Noble verification
I checked the build logs[1] of rsyslog 8.2312.0-3ubuntu9.1/s390x[2] for
noble, and confirmed that:
a) it used this version of gzip from noble-proposed:
Get:17 http://ftpmaster.internal/ubuntu noble-proposed/main s390x gzip s390x 1.12-1ubuntu3.1 [106 kB]
b) The tests that were failing before now passed:
PASS: gzipwr_flushOnTXEnd.sh
PASS: gzipwr_flushInterval.sh
c) the rsyslog build itself succeeded.
Noble verification succeeded.
1. https://launchpadlibrarian.net/781814909/buildlog_ubuntu-noble-s390x.rsyslog_8.2312.0-3ubuntu9.1_BUILDING.txt.gz
2. https://launchpad.net/ubuntu/+source/rsyslog/8.2312.0-3ubuntu9.1/+build/30420829
** Tags removed: verification-needed-noble
** Tags added: verification-done-noble
--
You received this bug notification because you are a member of
Debcrafters packages, which is subscribed to gzip in Ubuntu.
https://bugs.launchpad.net/bugs/2083700
Title:
rsyslog FTBFS due to gzip different behavior with hw acceleration on
s390x
Status in Ubuntu on IBM z Systems:
Confirmed
Status in gzip package in Ubuntu:
Fix Released
Status in rsyslog package in Ubuntu:
Invalid
Status in zlib package in Ubuntu:
Incomplete
Status in gzip source package in Focal:
New
Status in rsyslog source package in Focal:
New
Status in zlib source package in Focal:
New
Status in gzip source package in Jammy:
Confirmed
Status in rsyslog source package in Jammy:
New
Status in zlib source package in Jammy:
New
Status in gzip source package in Noble:
Fix Committed
Status in rsyslog source package in Noble:
Invalid
Status in zlib source package in Noble:
Incomplete
Status in gzip source package in Oracular:
Fix Committed
Status in rsyslog source package in Oracular:
Invalid
Status in zlib source package in Oracular:
Incomplete
Status in gzip source package in Plucky:
Fix Released
Status in rsyslog source package in Plucky:
Invalid
Status in zlib source package in Plucky:
Incomplete
Bug description:
[ Impact ]
This affects s390x only, and causes an FTBFS in rsyslog in that
architecture.
For some time, the gzip package has been carrying a patch to use
s390x-specific hardware acceleration, if available. That was never the
case it seems, in the ubuntu s390x infrastructure.
At some point in the past year, the ubuntu s390x infrastructure got
upgraded and the new hardware had support for this code that was
dormant in gzip until then. This surfaced a difference in
implementation between the hardware-backed code, and the software-only
code, and was enough to trigger a test failure in the rsyslog package,
creating an FTBFS there on s390x.
[ Test Plan ]
The test plan consists in rebuilding rsyslog on s390x, and asserting
that its build-time tests pass.
Without the gzip fix, the rsyslog tests that fail are:
FAIL: gzipwr_flushInterval
FAIL: gzipwr_flushOnTXEnd
The full log can be seen in the original description of this bug.
With the gzip fix, the rsyslog tests all pass.
[ Where problems could occur ]
The fix is only affecting s390x-specific code, and only gets used on
s390x hardware that has support for the used functions. If there were
to be a regression, it would manifest itself on this specific
hardware, and could cause all sorts of problems, as the gzip tool is
used all over the place. Therefore, we also expect any regressions to
be quickly found. The gzip test suite of course still passes after
these changes.
[ Other Info ]
Due to the interdependency of this SRU with the rsyslog ones, the gzip package must be accepted and published before rsyslog. Specifically, these rsyslog bugs must only be accepted after gzip is accepted and published:
- https://bugs.launchpad.net/ubuntu/+source/rsyslog/+bug/2056768
- https://bugs.launchpad.net/ubuntu/+source/rsyslog/+bug/2073628
- https://bugs.launchpad.net/ubuntu/+source/rsyslog/+bug/2061726
If this is not observed, then rsyslog will fail to build on s390x,
until the new gzip package is in proposed and published.
Upstream gzip is still discussing[1] details of this bug, tests, RFCs,
and other places where the hardware implementation differs from the
software one. Depending on the outcome and impact, we may SRU follow-
up fixes down the road.
1. https://debbugs.gnu.org/cgi/bugreport.cgi?bug=75924
[ Original Description ]
During an archive rebuild, rsyslog FTBFS on s390x only:
https://launchpadlibrarian.net/751879056/buildlog_ubuntu-
oracular-s390x.rsyslog_8.2406.0-1ubuntu2_BUILDING.txt.gz
The build fails due to two tests:
FAIL: gzipwr_flushInterval
==========================
testbench: TZ env var not set, setting it to UTC
------------------------------------------------------------
08:47:04[0] Test: ./gzipwr_flushInterval.sh
------------------------------------------------------------
config rstb_216690_cea0d3b3Yo0x_.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_216690_cea0d3b3Yo0x.imdiag.port
9 $IMDiagServerRun 0
10 $IMDiagAbortTimeout 580
11
12 :syslogtag, contains, "rsyslogd" ./rstb_216690_cea0d3b3Yo0x.started
13 ###### end of testbench instrumentation part, test conf follows:
14
15 module(load="../plugins/imtcp/.libs/imtcp")
16 input(type="imtcp" port="0" listenPortFileName="rstb_216690_cea0d3b3Yo0x.tcpflood_port")
17
18 template(name="outfmt" type="string" string="%msg:F,58:2%\n")
19 :msg, contains, "msgnum:" action(type="omfile" template="outfmt"
20 zipLevel="6" ioBufferSize="256k"
21 flushOnTXEnd="off" flushInterval="1"
22 asyncWriting="on"
23 file="rstb_216690_cea0d3b3Yo0x.out.log.gz")
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 0x2aa0873c810 started
rsyslog debug: main Q:Reg: started with state 3, num workers now 1
08:47:04[0] rstb_216690_cea0d3b3Yo0x:.pid found, pid 158166
08:47:04[0] rsyslogd startup msg seen, pid 158166
waiting for file rstb_216690_cea0d3b3Yo0x.imdiag.port
imdiag port: 35391
waiting for file rstb_216690_cea0d3b3Yo0x.tcpflood_port
TCPFLOOD_PORT now: 32793
starting run 1
Sending 2500 messages.
00002500 messages sent
runtime: 0.005
End of tcpflood Run
gzip: rstb_216690_cea0d3b3Yo0x.out.log.gz: invalid compressed data--format violated
scanf error in index i=0
gzip: rstb_216690_cea0d3b3Yo0x.out.log.gz: invalid compressed data--format violated
sequence error detected in rstb_216690_cea0d3b3Yo0x.out.log.gz
number of lines in file: 0 rstb_216690_cea0d3b3Yo0x.out.log.gz
sorted data has been placed in error.log, first 10 lines are:
1 scanf error in index i=0
---last 10 lines are:
1 scanf error in index i=0
UNSORTED data, first 10 lines are:
1 scanf error in index i=0
---last 10 lines are:
1 scanf error in index i=0
not reporting failure as RSYSLOG_STATSURL is not set
rsyslog pid file still exists, trying to shutdown...
rsyslogd debug: info: trying to cooperatively stop input ../plugins/imdiag/.libs/imdiag, timeout 60000 ms
rsyslogd debug: info: trying to cooperatively stop input imtcp, timeout 60000 ms
rsyslog debug: main Q:Reg/w0: enter WrkrExecCleanup
rsyslog debug: 0x2aa0873c990: worker exiting
rsyslog debug: main Q:Reg/w0: thread joined
08:47:09[5] FAIL: Test ./gzipwr_flushInterval.sh (took 5 seconds)
FAIL gzipwr_flushInterval.sh (exit status: 1)
FAIL: gzipwr_flushOnTXEnd
=========================
testbench: TZ env var not set, setting it to UTC
------------------------------------------------------------
08:47:04[0] Test: ./gzipwr_flushOnTXEnd.sh
------------------------------------------------------------
config rstb_586738_b0a588ae30Do_.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_586738_b0a588ae30Do.imdiag.port
9 $IMDiagServerRun 0
10 $IMDiagAbortTimeout 580
11
12 :syslogtag, contains, "rsyslogd" ./rstb_586738_b0a588ae30Do.started
13 ###### end of testbench instrumentation part, test conf follows:
14
15 module(load="../plugins/imtcp/.libs/imtcp")
16 input(type="imtcp" port="0" listenPortFileName="rstb_586738_b0a588ae30Do.tcpflood_port")
17
18 template(name="outfmt" type="string" string="%msg:F,58:2%\n")
19 :msg, contains, "msgnum:" { action(type="omfile" template="outfmt"
20 zipLevel="6" ioBufferSize="256k"
21 flushOnTXEnd="on"
22 asyncWriting="on"
23 file="rstb_586738_b0a588ae30Do.out.log")
24 action(type="omfile" file="rstb_586738_b0a588ae30Do.countlog")
25 }
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 0x2aa18a89a50 started
rsyslog debug: main Q:Reg: started with state 3, num workers now 1
08:47:04[0] rstb_586738_b0a588ae30Do:.pid found, pid 158888
08:47:04[0] rsyslogd startup msg seen, pid 158888
waiting for file rstb_586738_b0a588ae30Do.imdiag.port
imdiag port: 35511
waiting for file rstb_586738_b0a588ae30Do.tcpflood_port
TCPFLOOD_PORT now: 39421
starting run 1
Sending 2500 messages.
00002500 messages sent
runtime: 0.001
End of tcpflood Run
imdiag: wait q_empty: qsize 1210 nempty 0
imdiag: wait q_empty: qsize 0 nempty 1
imdiag[35511]: mainqueue empty
test 1
wait_file_lines success, have 2500 lines, took 0 seconds, file rstb_586738_b0a588ae30Do.countlog
-rw-r--r-- 1 buildd buildd 4841 Sep 29 08:47 rstb_586738_b0a588ae30Do.out.log
gzip: stdin: invalid compressed data--format violated
chkseq: start 0, end 2499
scanf error in index i=0
sequence error detected
not reporting failure as RSYSLOG_STATSURL is not set
rsyslog pid file still exists, trying to shutdown...
rsyslogd debug: info: trying to cooperatively stop input ../plugins/imdiag/.libs/imdiag, timeout 60000 ms
rsyslogd debug: info: trying to cooperatively stop input imtcp, timeout 60000 ms
rsyslog debug: main Q:Reg/w0: enter WrkrExecCleanup
rsyslog debug: 0x2aa18a89bd0: worker exiting
rsyslog debug: main Q:Reg/w0: thread joined
08:47:05[1] FAIL: Test ./gzipwr_flushOnTXEnd.sh (took 1 seconds)
FAIL gzipwr_flushOnTXEnd.sh (exit status: 1)
--
Since these are both gzip related, I looked at zlib and noticed that
there are s390x-specific optimization patches for that package:
https://launchpad.net/ubuntu/+source/zlib/1:1.3.dfsg+really1.3.1-1ubuntu1.
In a PPA build, I re-built zlib without these s390x patches, and re-
built rsyslog against that version. In that case, the build succeeded:
https://launchpad.net/~enr0n/+archive/ubuntu/proposed-
migration/+build/29141297
Therefore, I believe the cause of this FTBFS is related the
s390x-specific patches in zlib. This needs investigating by someone
more familiar with s390x and/or these patches.
To manage notifications about this bug go to:
https://bugs.launchpad.net/ubuntu-z-systems/+bug/2083700/+subscriptions
