** Description changed: [ Impact ] - * An explanation of the effects of the bug on users and justification - for backporting the fix to the stable release. - - * In addition, it is helpful, but not required, to include an - explanation of how the upload fixes this bug. + This affects s390x only. + + 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 ] - * detailed instructions how to reproduce the bug - - * these should allow someone who is not familiar with the affected - package to reproduce the bug and verify that the updated package - fixes the problem. - - * if other testing is appropriate to perform before landing this - update, this should also be described here. + 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 ] - * Think about what the upload changes in the software. Imagine the - change is wrong or breaks something else: how would this show up? - - * It is assumed that any SRU candidate patch is well-tested before - upload and has a low overall risk of regression, but it's important - to make the effort to think about what ''could'' happen in the event - of a regression. - - * This must never be "None" or "Low", or entirely an argument as to why - your upload is low risk. - - * This both shows the SRU team that the risks have been considered, - and provides guidance to testers in regression-testing the SRU. + 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 ] - * Anything else you think is useful to include - - * Make sure to explain any deviation from the norm, to save the SRU - reviewer from having to infer your reasoning, possibly incorrectly. - This should also help reduce review iterations, particularly when the - reason for the deviation is not obvious. - - * Anticipate questions from users, SRU, +1 maintenance, security teams - and the Technical Board and address these questions in advance + 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 [ 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.
** Description changed: [ Impact ] This affects s390x only. 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. [ 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. ** Description changed: [ Impact ] - This affects s390x only. + 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. [ 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. ** Description changed: [ 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. -- You received this bug notification because you are a member of Ubuntu Bugs, which is subscribed to Ubuntu. https://bugs.launchpad.net/bugs/2083700 Title: rsyslog FTBFS due to gzip different behavior with hw acceleration on s390x To manage notifications about this bug go to: https://bugs.launchpad.net/ubuntu-z-systems/+bug/2083700/+subscriptions -- ubuntu-bugs mailing list ubuntu-bugs@lists.ubuntu.com https://lists.ubuntu.com/mailman/listinfo/ubuntu-bugs
