| Summary: | AB-INT PTEST: openssh banner test failure | ||||||||||
|---|---|---|---|---|---|---|---|---|---|---|---|
| Product: | [QA/Testing] Package Testing (ptest) | Reporter: | Alexandre Belloni <alexandre.belloni> | ||||||||
| Component: | ptest | Assignee: | Steve Sakoman <steve> | ||||||||
| Status: | RESOLVED FIXED | QA Contact: | |||||||||
| Severity: | normal | ||||||||||
| Priority: | Medium | CC: | alexandre.belloni, joaomarcos.costa, luca.ceresoli, mikko.rapeli, randy.macleod | ||||||||
| Version: | unspecified | ||||||||||
| Target Milestone: | 4.0.20 | ||||||||||
| Hardware: | x86 | ||||||||||
| OS: | Multiple | ||||||||||
| Whiteboard: | AB-INT | ||||||||||
| OS type for building Yocto: | --- | Type of Regression: | --- | ||||||||
| Verified: | Documentation change: | No (bug/feature does not impact docs) | |||||||||
| Attachments: |
|
||||||||||
|
Description
Alexandre Belloni
2023-08-02 14:32:35 UTC
May be related to: https://bugzilla.yoctoproject.org/show_bug.cgi?id=15179 https://autobuilder.yoctoproject.org/typhoon/#/builders/82/builds/5244/steps/13/logs/stdio qemuarm64-ptest ubuntu1804-arm-1 https://autobuilder.yoctoproject.org/typhoon/#/builders/82/builds/5251/steps/13/logs/stdio ubuntu1804-arm-1 1691401916 https://autobuilder.yoctoproject.org/typhoon/#/builders/81/builds/5454/steps/12/logs/stdio qemux86-64-ptest rocky9-ty-1 Hit this failure on x86_64 build host, x86_64 build target, conf/local.conf modifications on top of standard poky master branch: IMAGE_CLASSES += "testimage" TEST_RUNQEMUPARAMS += "slirp" PREFERRED_VERSION_linux-yocto = "" SANITY_TESTED_DISTROS = "" Build command: $ bitbake -c testimage core-image-ptest-all Build host: Ubuntu 22.04.3 LTS Manually started "runqemu slirp nographic novga core-image-ptest-openssh" and ran "ptest-runner" but this time the test passed. Manually reviewed /usr/lib/openssh/ptest/run-ptest and /usr/lib/openssh/ptest/regress/Makefile and can't see obvious faults in them. Modified /usr/lib/openssh/ptest/regress/Makefile to only run "banner" test and looping that now to see if I can introduce a failure this way. Connected over ssh to the target too and monitoring /var/log/messages. sudo invovations form the tests are visible there. The log wrapper scripts from each test execution leave logs to /usr/lib/openssh/ptest/regress/log/ directory and symlinks to /usr/lib/openssh/ptest/regress/ssh.log and /usr/lib/openssh/ptest/regress/sshd.log Sadly these are wiped every time the wrappers execute. Looping with " while true; do ptest-runner openssh || break; done" hopefully leaves the logs from last failing command in place. Lets hope this reproduces. No reproduction after 12 hours of looping the banner test on a low load build machine. https://autobuilder.yoctoproject.org/typhoon/#/builders/81/builds/5510/steps/12/logs/stdio qemux86-64-ptest on fedora38-ty-4 Created attachment 4969 [details]
ptest log fetched from fedora38-ty-4
Ran 200 core-image-ptest-openssh test runs with patch https://lists.openembedded.org/g/openembedded-core/message/187315 but failed to reproduce this bug. https://autobuilder.yoctoproject.org/typhoon/#/builders/81/builds/5545/steps/12/logs/stdio qemux86-64-ptest rocky9-ty-1 https://autobuilder.yoctoproject.org/typhoon/#/builders/82/builds/5364/steps/12/logs/stdio qemuarm64-ptest ubuntu2204-arm-1 Is there a way to get to the do_testimage task logs from https://autobuilder.yoctoproject.org/typhoon/#/builders/82/builds/5364/steps/12/logs/stdio ? Created attachment 4973 [details] detailed failure log Log file from http://autobuilder.yocto.io/pub/non-release/20230907-29/testresults/qemux86-64-ptest/openssh.log attached Trying to get help from upstream to debug this issue via discussion in https://github.com/openssh/openssh-portable/pull/437 where the logging patch was sadly rejected as the test execution scripts used by upstream already do similar things. Test run output from the failure:
run test banner.sh ...
test banner: missing banner file
test banner: size 0
cmp: EOF on /usr/lib/openssh/ptest/regress/banner.in
banner size 0 mismatch
test banner: size 10
test banner: size 100
cmp: EOF on /usr/lib/openssh/ptest/regress/banner.in
banner size 100 mismatch
test banner: size 1000
test banner: size 10000
test banner: size 100000
test banner: suppress banner (-q)
FAIL: banner
return value: 1
busybox cmp complains about EOF if first file contains less new lines than second file, thus if banner.in is empty and banner.out contains one or more new lines, then output will be "cmp: EOF on banner.in". Same if banner.in contains a single new line and banner.out more than two.
$ /bin/busybox printf "foo" > foo
$ /bin/busybox printf "foo\n" > bar
$ /bin/busybox cmp foo bar
cmp: EOF on foo
$ /bin/busybox printf "foo\n" > foo
$ /bin/busybox printf "foo\n\n" > bar
$ /bin/busybox cmp foo bar
cmp: EOF on foo
Thus banner.out must contain more new lines than banner.in when this bug hits.
banner.out is created by capturing full stderr of the ssh client command:
${SSH} -F $OBJ/ssh_proxy otherhost true 2>$OBJ/banner.out
Since this bug is intermittend, there must be some other errors printed by the ssh command. These could be timeouts or other non-critical warnings which happend during ssh connection setup. It makes sense to log the output of banner.out and to check if it's possible to reduce the stderr logging from the ssh command line. In the worst case this test needs to be mitted completely since capturing only banner and nothing else from ssh output may be tricky.
Another similar looking instance of openssh stderr based test failing because the ssh stderr output has extra lines which were not expected: http://autobuilder.yocto.io/pub/non-release/20230913-11/testresults/qemuarm64-ptest/openssh.log run test stderr-data.sh ... test stderr data transfer: () test stderr data transfer: (-n) cmp: EOF on /usr/lib/openssh/ptest/regress/data stderr corrupt FAIL: stderr data transfer return value: 1 Executing: ssh -Q key-plain log /usr/lib/openssh/ptest/regress/log/20230913T125725.351040.ssh.5888.log Executing: ssh -Q key-plain log /usr/lib/openssh/ptest/regress/log/20230913T125725.362707.ssh.5895.log trace: using cached key type ssh-ed25519 trace: using cached key type sk-ssh-ed25519@openssh.com trace: using cached key type ecdsa-sha2-nistp256 trace: using cached key type ecdsa-sha2-nistp384 trace: using cached key type ecdsa-sha2-nistp521 trace: using cached key type sk-ecdsa-sha2-nistp256@openssh.com trace: using cached key type ssh-dss trace: using cached key type ssh-rsa trace: test stderr data transfer: () Executing: ssh -F /usr/lib/openssh/ptest/regress/ssh_proxy otherhost exec sh -c 'exec > /dev/null; sleep 3; cat /usr/lib/openssh/ptest/regress/data 1>&2 ' log /usr/lib/openssh/ptest/regress/log/20230913T125725.498447.ssh.5954.log Executing: /usr/sbin/sshd -i -f /usr/lib/openssh/ptest/regress/sshd_proxy log /usr/lib/openssh/ptest/regress/log/20230913T125725.515129.sshd.5960.log Executing: ssh -F /usr/lib/openssh/ptest/regress/ssh_proxy otherhost exec sh -c 'echo a; exec > /dev/null; sleep 3; cat /usr/lib/openssh/ptest/regress/data 1>&2 ' log /usr/lib/openssh/ptest/regress/log/20230913T125728.807994.ssh.5968.log Executing: /usr/sbin/sshd -i -f /usr/lib/openssh/ptest/regress/sshd_proxy log /usr/lib/openssh/ptest/regress/log/20230913T125728.824618.sshd.5974.log trace: test stderr data transfer: (-n) Executing: ssh -n -F /usr/lib/openssh/ptest/regress/ssh_proxy otherhost exec sh -c 'exec > /dev/null; sleep 3; cat /usr/lib/openssh/ptest/regress/data 1>&2 ' log /usr/lib/openssh/ptest/regress/log/20230913T125732.117532.ssh.5983.log Executing: /usr/sbin/sshd -i -f /usr/lib/openssh/ptest/regress/sshd_proxy log /usr/lib/openssh/ptest/regress/log/20230913T125732.134057.sshd.5989.log FAIL: stderr corrupt Saving debug logs to /usr/lib/openssh/ptest/regress/failed-stderr_data_transfer-logs.tar Sadly this failed-stderr_data_transfer-logs.tar wasn't captured from the test run and this specific test was not istrumented to capture more logs. Created attachment 4976 [details] openssh test log with debug output Latest openssh failure with debug logs from http://autobuilder.yocto.io/pub/non-release/20230917-2/testresults/qemuarm64-ptest/openssh.log Latest log file shows: run test banner.sh ... test banner: missing banner file test banner: size 0 cmp: EOF on /usr/lib/openssh/ptest/regress/banner.in Contents of /usr/lib/openssh/ptest/regress/banner.in: Contents of /usr/lib/openssh/ptest/regress/banner.out: sudo: unable to execute /usr/bin/env: Broken pipe banner size 0 mismatch So it looks like ssh test command stderr includes unexpected line "sudo: unable to execute /usr/bin/env: Broken pipe" which fails the test when comparison banner.in has an empty file. sudo was updated in poky last time August 14 2023, and before that July 30th 2023. I suspect problems started to appear since those updates. https://autobuilder.yoctoproject.org/typhoon/#/builders/81/builds/5473/steps/12/logs/stdio qemux86-64-ptest fedora38-ty-2 https://autobuilder.yoctoproject.org/typhoon/#/builders/82/builds/5344/steps/13/logs/stdio qemuarm64-ptest ubuntu1804-arm-1 https://autobuilder.yoctoproject.org/typhoon/#/builders/81/builds/5581/steps/12/logs/stdio qemux86-64-ptest rocky9-ty-1 https://autobuilder.yoctoproject.org/typhoon/#/builders/82/builds/5448/steps/13/logs/stdio qemuarm64-ptest ubuntu1804-arm-1 https://autobuilder.yoctoproject.org/typhoon/#/builders/82/builds/5293/steps/13/logs/stdio qemuarm64-ptest ubuntu1804-arm-1 https://autobuilder.yoctoproject.org/typhoon/#/builders/82/builds/5413/steps/13/logs/stdio qemuarm64-ptest ubuntu1804-arm-1 https://autobuilder.yoctoproject.org/typhoon/#/builders/82/builds/5509/steps/12/logs/stdio qemuarm64-ptest ubuntu2204-arm-1 Since the extra data in ssh/sshd stderr seem to come from sudo, I proposed https://lists.openembedded.org/g/openembedded-core/message/188775 to remove sudo usage from openssh ptest since tests also pass without sudo. The workaround of removing sudo depenendecy from openssh ptest test execution has been applied few weeks ago: commit 3cba2dfd43a3b89083d453ee3f84bf3f9358c415 Author: Mikko Rapeli <mikko.rapeli@linaro.org> AuthorDate: Fri Oct 6 18:05:02 2023 +0300 Commit: Richard Purdie <richard.purdie@linuxfoundation.org> CommitDate: Mon Oct 9 15:51:13 2023 +0100 openssh: drop sudo from ptest dependencies Has this bug been hit since then? AFAIK this issues was affecting autobuilder test runs on a weekly basis before. Build move to 5.0 -- ../Randy https://autobuilder.yoctoproject.org/typhoon/#/builders/81/builds/5965/steps/12/logs/stdio qemux86-64-ptest alma9-ty-2 https://autobuilder.yoctoproject.org/typhoon/#/builders/82/builds/5752/steps/12/logs/stdio qemuarm64-ptest ubuntu1804-arm-1 https://autobuilder.yoctoproject.org/typhoon/#/builders/81/builds/5527/steps/12/logs/stdio qemux86-64-ptest fedora38-ty-3 https://autobuilder.yoctoproject.org/typhoon/#/builders/82/builds/5360/steps/12/logs/stdio qemuarm64-ptest ubuntu2204-arm-1 No failure in November but back in December. To understand what is going on, at least do_testimage logs of the failure are needed. Is someone able to capture those? I don't know how to go from https://autobuilder.yoctoproject.org/typhoon/#/builders/81/builds/5581/steps/12/logs/stdio to the logs of the failed task. The latest occurrence is this one: https://autobuilder.yocto.io/pub/non-release/20231129-22/testresults/qemux86-64-ptest/openssh.log The one you pointed out is from 3 month ago that I'm triaging just now. (In reply to Alexandre Belloni from comment #34) > The latest occurrence is this one: > > https://autobuilder.yocto.io/pub/non-release/20231129-22/testresults/qemux86- > 64-ptest/openssh.log This shows errors like sudo: unable to execute /usr/bin/env: Broken pipe which means that sudo was on the image. This is likely the cause of the failure. When did sudo come back and what added that dependency? It was removed from direct openssh ptest dependencies. > The one you pointed out is from 3 month ago that I'm triaging just now. Ok, understood. It didn't come back, this failure is from kirkstone so I guess it needs to be fixed there too. *** Bug 15179 has been marked as a duplicate of this bug. *** https://autobuilder.yoctoproject.org/typhoon/#/builders/81/builds/5499/steps/12/logs/stdio qemux86-64-ptest fedora37-ty-2 *** Bug 15347 has been marked as a duplicate of this bug. *** https://autobuilder.yoctoproject.org/typhoon/#/builders/82/builds/5320/steps/13/logs/stdio qemuarm64-ptest ubuntu1804-arm-1 https://autobuilder.yoctoproject.org/typhoon/#/builders/81/builds/5645/steps/12/logs/stdio qemux86-64-ptest alma9-ty-2 https://autobuilder.yoctoproject.org/typhoon/#/builders/82/builds/5462/steps/13/logs/stdio qemuarm64-ptest ubuntu1804-arm-1 |