Re: [OE-core] [PATCH 2/2] qemurunner: Impove handling of serial port output blocking
Richard Purdie writes: > On Wed, 2023-12-20 at 09:53 +0000, Alex Bennée wrote: >> Richard Purdie writes: >> >> > On Tue, 2023-12-19 at 16:44 +, Alex Bennée wrote: >> > > Richard Purdie writes: >> > > Yeah I'm only seeing A10/A11: >> > > >> > > o regression_1010.5 Invalid memory access 5 >> > > regression_1010.5 OK >> > > o regression_1010.6 Invalid memory access 6 >> > > >> > > WARNING: here A10 >> > > WARNING: here A11 >> > >> > How long does it take for the test data to "back up" and timeout? The >> > logging thread should take a maximum of 2s to notice data not being >> > read/handled on the serial port. >> >> I don't think it goes around the logging loop more than once. I only >> see: >> >> grep "got" >> build/tmp_trs-qemuarm64/work/trs_qemuarm64-trs-linux/trs-image/1.0/temp/log.do_testimage >> DEBUG: got [(12, 1)] >> >> from the poll. >> >> I'll keep digging. > > I've merged the patches into master since they are helping the stdout > issue and helped a number of issues others were seeing. > > In the final version of the patch I did fix an issue where the > exception handling from the thread was not working so well, it does at > least print a, exception/traceback properly now (in threadtarget()). > > One of the reasons I asked about the warnings was in case that was > showing an issue, previously it silently failed. > > I can believe there are other issues hiding in here :/. So the failure was due to an exception being thrown at: elif self.readsock.fileno() == event[1]: when my config hadn't triggered its opening. A bit of defensive coding and it works. See: Subject: [PATCH] qemurunner: more cleanups for output blocking Date: Wed, 20 Dec 2023 16:14:50 + Message-Id: <20231220161450.1422484-1-alex.ben...@linaro.org> > > Cheers, > > Richard -- Alex Bennée Virtualisation Tech Lead @ Linaro -=-=-=-=-=-=-=-=-=-=-=- Links: You receive all messages sent to this group. View/Reply Online (#192803): https://lists.openembedded.org/g/openembedded-core/message/192803 Mute This Topic: https://lists.openembedded.org/mt/103244415/21656 Group Owner: openembedded-core+ow...@lists.openembedded.org Unsubscribe: https://lists.openembedded.org/g/openembedded-core/unsub [arch...@mail-archive.com] -=-=-=-=-=-=-=-=-=-=-=-
[OE-core] [PATCH] qemurunner: more cleanups for output blocking
If we are only tracking stdout and are not using self.readsock we end
up throwing an exception blocking further action from the thread. Fix
this by checking self.readsock is not None first.
While we are at it split even into fd, event to make things clearer
and handle the fail path of stringify_event by echoing the hex value
of the unknown flag.
Signed-off-by: Alex Bennée
Cc: Mikko Rapeli
Cc: Richard Purdie
---
meta/lib/oeqa/utils/qemurunner.py | 20
1 file changed, 12 insertions(+), 8 deletions(-)
diff --git a/meta/lib/oeqa/utils/qemurunner.py
b/meta/lib/oeqa/utils/qemurunner.py
index 4a2246733f..7273bbc3db 100644
--- a/meta/lib/oeqa/utils/qemurunner.py
+++ b/meta/lib/oeqa/utils/qemurunner.py
@@ -785,19 +785,20 @@ class LoggingThread(threading.Thread):
self.logger.debug("Starting thread event loop")
while not breakout:
events = poll.poll(2)
-for event in events:
+for fd, event in events:
+
# An error occurred, bail out
-if event[1] & self.errorevents:
-raise Exception(self.stringify_event(event[1]))
+if event & self.errorevents:
+raise Exception(self.stringify_event(event))
# Event to stop the thread
-if self.readpipe == event[0]:
+if self.readpipe == fd:
self.logger.debug("Stop event received")
breakout = True
break
# A connection request was received
-elif self.serversock and self.serversock.fileno() == event[0]:
+elif self.serversock and self.serversock.fileno() == fd:
self.logger.debug("Connection request received")
self.readsock, _ = self.serversock.accept()
self.readsock.setblocking(0)
@@ -808,14 +809,14 @@ class LoggingThread(threading.Thread):
self.connection_established.set()
# Actual data to be logged
-elif self.readsock.fileno() == event[0]:
+elif self.readsock and self.readsock.fileno() == fd:
data = self.recv(1024, self.readsock)
self.logfunc(data)
-elif self.qemuoutput.fileno() == event[0]:
+elif self.qemuoutput.fileno() == fd:
data = self.qemuoutput.read()
self.logger.debug("Data received on qemu stdout %s" % data)
self.logfunc(data, ".stdout")
-elif self.serialsock and self.serialsock.fileno() == event[0]:
+elif self.serialsock and self.serialsock.fileno() == fd:
if self.serial_lock.acquire(blocking=False):
data = self.recv(1024, self.serialsock)
self.logger.debug("Data received serial thread %s" %
data.decode('utf-8', 'replace'))
@@ -864,6 +865,9 @@ class LoggingThread(threading.Thread):
val = 'POLLHUP'
elif select.POLLNVAL == event:
val = 'POLLNVAL'
+else:
+val = "0x%x" % (event)
+
return val
def close_socket(self, sock):
--
2.39.2
-=-=-=-=-=-=-=-=-=-=-=-
Links: You receive all messages sent to this group.
View/Reply Online (#192802):
https://lists.openembedded.org/g/openembedded-core/message/192802
Mute This Topic: https://lists.openembedded.org/mt/103283432/21656
Group Owner: openembedded-core+ow...@lists.openembedded.org
Unsubscribe: https://lists.openembedded.org/g/openembedded-core/unsub
[arch...@mail-archive.com]
-=-=-=-=-=-=-=-=-=-=-=-
Re: [OE-core] [PATCH 2/2] qemurunner: Impove handling of serial port output blocking
Richard Purdie writes: > On Tue, 2023-12-19 at 16:44 +0000, Alex Bennée wrote: >> Richard Purdie writes: >> >> > On Tue, 2023-12-19 at 15:10 +, Alex Bennée wrote: >> > > "Richard Purdie" writes: >> > > >> > > > Similar to stdout in the previous commit, we need to ensure serial >> > > > output >> > > > if written is read and put somewhere, else qemu might block on writes >> > > > to >> > > > the serial port leading to hangs in the kernel. Use our existing >> > > > logging >> > > > thread to log data when run_serial is not in use. >> > > > >> > > > Signed-off-by: Richard Purdie >> > > >> > > I'm still seeing hanging with my test case: >> > > >> > > o regression_1010.5 Invalid memory access 5 >> > > regression_1010.5 OK >> > > o regression_1010.6 Invalid memory access 6 >> > > >> > > Stdout: >> > > Tried to dump info from target but serial console failed >> > > Failed CMD: top -bn1 >> > > Tried to dump info from target but serial console failed >> > > Failed CMD: ps >> > > Tried to dump info from target but serial console failed >> > > Failed CMD: free >> > > >> > > NOTE: test_soafee (soafeetestsuite.SoafeeTestSuite.test_soafee) >> > > DEBUG: Checking if at least one of soafee-test-suite is installed >> > > DEBUG: Setting up a 400 second(s) timeout >> > > DEBUG: [Running]$ ssh -l root -o ServerAliveCountMax=2 -o >> > > ServerAliveInterval=30 -o UserKnownHostsFile=/dev/null -o >> > > StrictHostKeyChecking=no -o LogLevel=ERROR -p 127.0.0.1 export >> > > PATH=/usr/sbin:/sbin:/usr/bin:/bin; sudo -i -u trs soafee-test-suite run >> > > -r -t -T ; rm -rf /tmp/soafee-test-suite >> > > DEBUG: Waiting for process output: time: 1702998407.0291, endtime: >> > > 1702998707.0285847 >> > > DEBUG: Waiting for process output: time: 1702998412.0338314, endtime: >> > > 1702998707.0285847 >> > > DEBUG: Waiting for process output: time: 1702998417.0378022, endtime: >> > > 1702998707.0285847 >> > > DEBUG: Waiting for process output: time: 1702998422.0417945, endtime: >> > > 1702998707.0285847 >> > > >> > > >> > > The regression tests are hanging because that has triggered output on >> > > the serial port as the firmware attempted to service the test and the >> > > port isn't being drained. Then when that times out we start spinning >> > > waiting for more output. >> > >> > I don't really understand where it might be hanging unfortunately as in >> > my local tests it is draining stdout and the serial ports. Does it >> > login to the serial console correctly? Are there any WARNING messages? >> > >> > I did use this debug patch: >> > >> > https://git.yoctoproject.org/poky-contrib/commit/?h=rpurdie/t222=0d9029bad610736c114e0770d2433b53133fa620 >> > >> > to prove that it can interleave serial commands with left over output >> > successfully. A similar patch may help work out where your setup may be >> > hanging? >> >> Yeah I'm only seeing A10/A11: >> >> o regression_1010.5 Invalid memory access 5 >> regression_1010.5 OK >> o regression_1010.6 Invalid memory access 6 >> >> WARNING: here A10 >> WARNING: here A11 >> WARNING: here A10 >> WARNING: here A11 >> WARNING: here A10 >> WARNING: here A11 >> WARNING: here A10 >> WARNING: here A11 >> WARNING: here A10 >> WARNING: here A11 >> WARNING: here A10 >> WARNING: here A11 >> WARNING: here A10 >> WARNING: here A11 >> WARNING: here A10 >> WARNING: here A11 >> WARNING: here A10 >> WARNING: here A11 >> WARNING: here A10 >> WARNING: here A11 >> NOTE: ... FAIL >> DEBUG: Removed SIGALRM handler >> Traceback (most recent call last): >> File >> "/home/alex/lsrc/tests/trs/build/../poky/meta/lib/oeqa/core/decorator/__init__.py", >> line 35, in wrapped_f >> return func(*args, **kwargs) >> ^ >> File >> "/home/alex/lsrc/tests/trs/build/../poky/meta/lib/oeqa/core/decorator/__init__.py", >> line 35, in wrapped_f >> return func(*args, **
Re: [OE-core] [PATCH 2/2] qemurunner: Impove handling of serial port output blocking
Richard Purdie writes: > On Tue, 2023-12-19 at 15:10 +0000, Alex Bennée wrote: >> "Richard Purdie" writes: >> >> > Similar to stdout in the previous commit, we need to ensure serial output >> > if written is read and put somewhere, else qemu might block on writes to >> > the serial port leading to hangs in the kernel. Use our existing logging >> > thread to log data when run_serial is not in use. >> > >> > Signed-off-by: Richard Purdie >> >> I'm still seeing hanging with my test case: >> >> o regression_1010.5 Invalid memory access 5 >> regression_1010.5 OK >> o regression_1010.6 Invalid memory access 6 >> >> Stdout: >> Tried to dump info from target but serial console failed >> Failed CMD: top -bn1 >> Tried to dump info from target but serial console failed >> Failed CMD: ps >> Tried to dump info from target but serial console failed >> Failed CMD: free >> >> NOTE: test_soafee (soafeetestsuite.SoafeeTestSuite.test_soafee) >> DEBUG: Checking if at least one of soafee-test-suite is installed >> DEBUG: Setting up a 400 second(s) timeout >> DEBUG: [Running]$ ssh -l root -o ServerAliveCountMax=2 -o >> ServerAliveInterval=30 -o UserKnownHostsFile=/dev/null -o >> StrictHostKeyChecking=no -o LogLevel=ERROR -p 127.0.0.1 export >> PATH=/usr/sbin:/sbin:/usr/bin:/bin; sudo -i -u trs soafee-test-suite run -r >> -t -T ; rm -rf /tmp/soafee-test-suite >> DEBUG: Waiting for process output: time: 1702998407.0291, endtime: >> 1702998707.0285847 >> DEBUG: Waiting for process output: time: 1702998412.0338314, endtime: >> 1702998707.0285847 >> DEBUG: Waiting for process output: time: 1702998417.0378022, endtime: >> 1702998707.0285847 >> DEBUG: Waiting for process output: time: 1702998422.0417945, endtime: >> 1702998707.0285847 >> >> >> The regression tests are hanging because that has triggered output on >> the serial port as the firmware attempted to service the test and the >> port isn't being drained. Then when that times out we start spinning >> waiting for more output. > > I don't really understand where it might be hanging unfortunately as in > my local tests it is draining stdout and the serial ports. Does it > login to the serial console correctly? Are there any WARNING messages? > > I did use this debug patch: > > https://git.yoctoproject.org/poky-contrib/commit/?h=rpurdie/t222=0d9029bad610736c114e0770d2433b53133fa620 > > to prove that it can interleave serial commands with left over output > successfully. A similar patch may help work out where your setup may be > hanging? Yeah I'm only seeing A10/A11: o regression_1010.5 Invalid memory access 5 regression_1010.5 OK o regression_1010.6 Invalid memory access 6 WARNING: here A10 WARNING: here A11 WARNING: here A10 WARNING: here A11 WARNING: here A10 WARNING: here A11 WARNING: here A10 WARNING: here A11 WARNING: here A10 WARNING: here A11 WARNING: here A10 WARNING: here A11 WARNING: here A10 WARNING: here A11 WARNING: here A10 WARNING: here A11 WARNING: here A10 WARNING: here A11 WARNING: here A10 WARNING: here A11 NOTE: ... FAIL DEBUG: Removed SIGALRM handler Traceback (most recent call last): File "/home/alex/lsrc/tests/trs/build/../poky/meta/lib/oeqa/core/decorator/__init__.py", line 35, in wrapped_f return func(*args, **kwargs) ^ File "/home/alex/lsrc/tests/trs/build/../poky/meta/lib/oeqa/core/decorator/__init__.py", line 35, in wrapped_f return func(*args, **kwargs) ^ File "/home/alex/lsrc/tests/trs/meta-trs/lib/oeqa/runtime/cases/opteetest.py", line 27, in test_opteetest_xtest self.assertEqual(status, 0, msg='\n'.join([cmd, output])) AssertionError: 255 != 0 : xtest Run test suite with level=0 Those are the only two bits hit in the logging: grep "WARNING: here" build/tmp_trs-qemuarm64/work/trs_qemuarm64-trs-linux/trs-image/1.0/temp/log.do_testimage WARNING: here A10 WARNING: here A11 WARNING: here A10 WARNING: here A11 WARNING: here A10 WARNING: here A11 WARNING: here A10 WARNING: here A11 WARNING: here A10 WARNING: here A11 WARNING: here A10 WARNING: here A11 WARNING: here A10 WARNING: here A11 WARNING: here A10 WARNING: here A11 WARNING: here A10 WARNING: here A11 WARNING: here A10 WARNING: here A11 WARNING: here A10 WARNING: here A11 WARNING: here A10 WARNING: here A11 WARNING: here A10 WARNING: here A11 WARNING: here A10 WARNING: here A11 WARNING: here A10 WARNING: here A11
Re: [OE-core] [PATCH 1/2] qemurunner: Impove stdout logging handling
"Richard Purdie" writes:
> On Mon, 2023-12-18 at 10:07 -0800, Khem Raj wrote:
>> On Mon, Dec 18, 2023 at 9:58 AM Richard Purdie
>> wrote:
>> >
>> > On Mon, 2023-12-18 at 09:45 -0800, Khem Raj wrote:
>> > > I tried the two patches in this series. It did improve the situation
>> > > but I am still getting SSH timeouts. But this time its 13 tests
>> > > earlier it used to be 40+
>> > > btw. my images are using systemd. So it might be good to see if we see
>> > > this with poky-altcfg as well or not.
>> >
>> > Do you have the log.do_testimage and the ${WORKDIR}/testimage/ files?
>>
>> yes, further I ran the failing tests in loop one after another still
>> one test gzip fails with ssh timeouts
>>
>> https://busybox.net/~kraj/log.do_testimage.503
>> https://busybox.net/~kraj/testimage/
>>
>> there are two runs in the testimages folder. In one you see the RCU
>> stall and in second you do not
>> but it fails with same ssh timeout issue.
>>
>> >
>> > Did you still see rcu stalls in the logs?
>
> What is interesting is there is ~3MB of nulls in the .2 serial log. The
> rcu stall is also:
>
> [ 88.261687] serial8250_tx_chars+0xea/0x2b0
> [ 88.261689] serial8250_handle_irq+0x1e9/0x330
> [ 88.261691] serial8250_default_handle_irq+0x4a/0x90
> [ 88.261693] serial8250_interrupt+0x66/0xc0
> [ 88.261696] __handle_irq_event_percpu+0x54/0x1c0
> [ 88.261701] handle_irq_event+0x3d/0x80
>
> i.e. it is stalled in the serial TX path.
>
> The big question is why is there so many nulls on the serial port. I
> see a few on my local x86 test runs but only ~4kb, not megabytes of
> them. I hadn't worked out where/what they are from yet.
>
> I suspect something in the serial/kernel/qemu space isn't interacting
> correctly.
We generally don't model FIFOs in QEMU and also we will block the main
thread if we can't write data out.
>
> Find the cause of the nulls and we might make progress on this.
>
> Cheers,
>
> Richard
>
>
>
>
--
Alex Bennée
Virtualisation Tech Lead @ Linaro
-=-=-=-=-=-=-=-=-=-=-=-
Links: You receive all messages sent to this group.
View/Reply Online (#192750):
https://lists.openembedded.org/g/openembedded-core/message/192750
Mute This Topic: https://lists.openembedded.org/mt/103244414/21656
Group Owner: openembedded-core+ow...@lists.openembedded.org
Unsubscribe: https://lists.openembedded.org/g/openembedded-core/unsub
[arch...@mail-archive.com]
-=-=-=-=-=-=-=-=-=-=-=-
Re: [OE-core] [PATCH 2/2] qemurunner: Impove handling of serial port output blocking
"Richard Purdie" writes: > Similar to stdout in the previous commit, we need to ensure serial output > if written is read and put somewhere, else qemu might block on writes to > the serial port leading to hangs in the kernel. Use our existing logging > thread to log data when run_serial is not in use. > > Signed-off-by: Richard Purdie I'm still seeing hanging with my test case: o regression_1010.5 Invalid memory access 5 regression_1010.5 OK o regression_1010.6 Invalid memory access 6 Stdout: Tried to dump info from target but serial console failed Failed CMD: top -bn1 Tried to dump info from target but serial console failed Failed CMD: ps Tried to dump info from target but serial console failed Failed CMD: free NOTE: test_soafee (soafeetestsuite.SoafeeTestSuite.test_soafee) DEBUG: Checking if at least one of soafee-test-suite is installed DEBUG: Setting up a 400 second(s) timeout DEBUG: [Running]$ ssh -l root -o ServerAliveCountMax=2 -o ServerAliveInterval=30 -o UserKnownHostsFile=/dev/null -o StrictHostKeyChecking=no -o LogLevel=ERROR -p 127.0.0.1 export PATH=/usr/sbin:/sbin:/usr/bin:/bin; sudo -i -u trs soafee-test-suite run -r -t -T ; rm -rf /tmp/soafee-test-suite DEBUG: Waiting for process output: time: 1702998407.0291, endtime: 1702998707.0285847 DEBUG: Waiting for process output: time: 1702998412.0338314, endtime: 1702998707.0285847 DEBUG: Waiting for process output: time: 1702998417.0378022, endtime: 1702998707.0285847 DEBUG: Waiting for process output: time: 1702998422.0417945, endtime: 1702998707.0285847 The regression tests are hanging because that has triggered output on the serial port as the firmware attempted to service the test and the port isn't being drained. Then when that times out we start spinning waiting for more output. -- Alex Bennée Virtualisation Tech Lead @ Linaro -=-=-=-=-=-=-=-=-=-=-=- Links: You receive all messages sent to this group. View/Reply Online (#192747): https://lists.openembedded.org/g/openembedded-core/message/192747 Mute This Topic: https://lists.openembedded.org/mt/103244415/21656 Group Owner: openembedded-core+ow...@lists.openembedded.org Unsubscribe: https://lists.openembedded.org/g/openembedded-core/unsub [arch...@mail-archive.com] -=-=-=-=-=-=-=-=-=-=-=-
Re: [OE-core] [PATCH 1/2] qemurunner: Impove stdout logging handling
"Richard Purdie" writes:
> On Mon, 2023-12-18 at 09:45 -0800, Khem Raj wrote:
>> I tried the two patches in this series. It did improve the situation
>> but I am still getting SSH timeouts. But this time its 13 tests
>> earlier it used to be 40+
>> btw. my images are using systemd. So it might be good to see if we see
>> this with poky-altcfg as well or not.
>
> Do you have the log.do_testimage and the ${WORKDIR}/testimage/ files?
>
> Did you still see rcu stalls in the logs?
rcu stalls in the kernel is just a sign of QEMU's relative inefficiency
compared to real HW. However multiple -smp will help alleviate busy
vCPUs if you can. If you want guest time to be a bit more realistic you
can use icount but actual wall clock time will be longer as you can only
have one thread.
>
> Cheers,
>
> Richard
>
>
>
--
Alex Bennée
Virtualisation Tech Lead @ Linaro
-=-=-=-=-=-=-=-=-=-=-=-
Links: You receive all messages sent to this group.
View/Reply Online (#192679):
https://lists.openembedded.org/g/openembedded-core/message/192679
Mute This Topic: https://lists.openembedded.org/mt/103244414/21656
Group Owner: openembedded-core+ow...@lists.openembedded.org
Unsubscribe: https://lists.openembedded.org/g/openembedded-core/unsub
[arch...@mail-archive.com]
-=-=-=-=-=-=-=-=-=-=-=-
Re: [OE-core] [RFC PATCH v2] qemurunner.py: continue to drain stdout after login:
Khem Raj writes:
> I am on arch so no py-bt with gdb out of box but here is bt
>
> #0 0x7fa1e54ee367 in wait4 () from
> /mnt/b/yoe/master/build/tmp/sysroots-uninative/x86_64-linux/lib/libc.so.6
> #1 0x7fa1e5a858b9 in ?? () from
> /mnt/b/yoe/master/build/tmp/work/qemux86_64-yoe-linux/core-image-ptest-gstreamer1.0/1.0/recipe-sysroot-native/usr/bin/python3-native/../../lib/libpython3.11.so.1.0
> #2 0x7fa1e598e94a in ?? () from
> /mnt/b/yoe/master/build/tmp/work/qemux86_64-yoe-linux/core-image-ptest-gstreamer1.0/1.0/recipe-sysroot-native/usr/bin/python3-native/../../lib/libpython3.11.so.1.0
> #3 0x7fa1e594bf03 in PyObject_Vectorcall () from
> /mnt/b/yoe/master/build/tmp/work/qemux86_64-yoe-linux/core-image-ptest-gstreamer1.0/1.0/recipe-sysroot-native/usr/bin/python3-native/../../lib/libpython3.11.so.1.0
> #4 0x7fa1e5900063 in _PyEval_EvalFrameDefault () from
> /mnt/b/yoe/master/build/tmp/work/qemux86_64-yoe-linux/core-image-ptest-gstreamer1.0/1.0/recipe-sysroot-native/usr/bin/python3-native/../../lib/libpython3.11.so.1.0
> #5 0x7fa1e5a1da40 in ?? () from
> /mnt/b/yoe/master/build/tmp/work/qemux86_64-yoe-linux/core-image-ptest-gstreamer1.0/1.0/recipe-sysroot-native/usr/bin/python3-native/../../lib/libpython3.11.so.1.0
> #6 0x7fa1e5a1daf5 in PyEval_EvalCode () from
> /mnt/b/yoe/master/build/tmp/work/qemux86_64-yoe-linux/core-image-ptest-gstreamer1.0/1.0/recipe-sysroot-native/usr/bin/python3-native/../../lib/libpython3.11.so.1.0
> #7 0x7fa1e5a5deb3 in ?? () from
> /mnt/b/yoe/master/build/tmp/work/qemux86_64-yoe-linux/core-image-ptest-gstreamer1.0/1.0/recipe-sysroot-native/usr/bin/python3-native/../../lib/libpython3.11.so.1.0
> #8 0x7fa1e5a5e0d6 in ?? () from
> /mnt/b/yoe/master/build/tmp/work/qemux86_64-yoe-linux/core-image-ptest-gstreamer1.0/1.0/recipe-sysroot-native/usr/bin/python3-native/../../lib/libpython3.11.so.1.0
> #9 0x7fa1e5a5e1b0 in ?? () from
> /mnt/b/yoe/master/build/tmp/work/qemux86_64-yoe-linux/core-image-ptest-gstreamer1.0/1.0/recipe-sysroot-native/usr/bin/python3-native/../../lib/libpython3.11.so.1.0
> #10 0x7fa1e5a60b9b in _PyRun_SimpleFileObject () from
> /mnt/b/yoe/master/build/tmp/work/qemux86_64-yoe-linux/core-image-ptest-gstreamer1.0/1.0/recipe-sysroot-native/usr/bin/python3-native/../../lib/libpython3.11.so.1.0
> #11 0x7fa1e5a6111c in _PyRun_AnyFileObject () from
> /mnt/b/yoe/master/build/tmp/work/qemux86_64-yoe-linux/core-image-ptest-gstreamer1.0/1.0/recipe-sysroot-native/usr/bin/python3-native/../../lib/libpython3.11.so.1.0
> #12 0x7fa1e5a7ddf0 in Py_RunMain () from
> /mnt/b/yoe/master/build/tmp/work/qemux86_64-yoe-linux/core-image-ptest-gstreamer1.0/1.0/recipe-sysroot-native/usr/bin/python3-native/../../lib/libpython3.11.so.1.0
> #13 0x7fa1e5a7e32a in Py_BytesMain () from
> /mnt/b/yoe/master/build/tmp/work/qemux86_64-yoe-linux/core-image-ptest-gstreamer1.0/1.0/recipe-sysroot-native/usr/bin/python3-native/../../lib/libpython3.11.so.1.0
> #14 0x7fa1e5423efb in __libc_start_call_main () from
> /mnt/b/yoe/master/build/tmp/sysroots-uninative/x86_64-linux/lib/libc.so.6
> #15 0x7fa1e5423fb9 in __libc_start_main () from
> /mnt/b/yoe/master/build/tmp/sysroots-uninative/x86_64-linux/lib/libc.so.6
> #16 0x5581e2c53075 in _start ()
>
> since its using native libs and bins there is no debug info perhaps
> due to it being stripped and not kept around as well.
No - it won't work without debug symbols to poke around in pythons
runtime. Can you share the log?
Do you see anything from:
self.logger.warning('Extra log data read: %s\n' %
(data.decode('utf-8', errors='backslashreplace')))
except Exception as e:
self.logger.warning('Extra log data exception %s' % repr(e))
maybe we should have a: self.stop_thread() once we catch the exception?
--
Alex Bennée
Virtualisation Tech Lead @ Linaro
-=-=-=-=-=-=-=-=-=-=-=-
Links: You receive all messages sent to this group.
View/Reply Online (#192252):
https://lists.openembedded.org/g/openembedded-core/message/192252
Mute This Topic: https://lists.openembedded.org/mt/10335/21656
Group Owner: openembedded-core+ow...@lists.openembedded.org
Unsubscribe: https://lists.openembedded.org/g/openembedded-core/unsub
[arch...@mail-archive.com]
-=-=-=-=-=-=-=-=-=-=-=-
Re: [OE-core] [RFC PATCH v2] qemurunner.py: continue to drain stdout after login:
Khem Raj writes:
> this version hangs the run forever.
Do you have a reproducer? In my "make test" case it works fine.
Alternatively you could gdb attach to the hanging python and use py-bt
to generate a python backtrace.
>
> On Mon, Dec 11, 2023 at 7:57 AM Alex Bennée wrote:
>>
>> If qemurunner doesn't continuously drain stdout we will eventually
>> cause QEMU to block while trying to write to the pipe. This can
>> manifest itself if the guest has for example configured its serial
>> ports to output via stdio even if the test itself is using a TCP
>> console or SSH to run things.
>>
>> To do this:
>>
>> - always create a logging thread regardless of serial_ports
>> - use a semaphore between main and logging threads
>> - move the login detection into the logging thread
>> - wait until the second acquire before continuing
>>
>> This doesn't address a potential overflow of stderr although generally
>> stderr from QEMU will be a lot less likely to block due to the volume
>> of data.
>>
>> Signed-off-by: Alex Bennée
>> Cc: Mikko Rapeli
>> ---
>> meta/lib/oeqa/utils/qemurunner.py | 128 ++
>> 1 file changed, 78 insertions(+), 50 deletions(-)
>>
>> diff --git a/meta/lib/oeqa/utils/qemurunner.py
>> b/meta/lib/oeqa/utils/qemurunner.py
>> index 29fe271976..b768c08f04 100644
>> --- a/meta/lib/oeqa/utils/qemurunner.py
>> +++ b/meta/lib/oeqa/utils/qemurunner.py
>> @@ -207,8 +207,7 @@ class QemuRunner:
>> self.logger.info("QMP Available for connection at %s" % (qmp_port2))
>>
>> try:
>> -if self.serial_ports >= 2:
>> -self.threadsock, threadport = self.create_socket()
>> +self.threadsock, threadport = self.create_socket()
>> self.server_socket, self.serverport = self.create_socket()
>> except socket.error as msg:
>> self.logger.error("Failed to create listening socket: %s" %
>> msg[1])
>> @@ -243,6 +242,7 @@ class QemuRunner:
>> # to be a proper fix but this will suffice for now.
>> self.runqemu = subprocess.Popen(launch_cmd, shell=True,
>> stdout=subprocess.PIPE, stderr=subprocess.STDOUT, stdin=subprocess.PIPE,
>> preexec_fn=os.setpgrp, env=env, cwd=self.tmpdir)
>> output = self.runqemu.stdout
>> +output_drain = output
>> launch_time = time.time()
>>
>> #
>> @@ -431,21 +431,30 @@ class QemuRunner:
>> self.logger.debug("Target IP: %s" % self.ip)
>> self.logger.debug("Server IP: %s" % self.server_ip)
>>
>> -if self.serial_ports >= 2:
>> -self.thread = LoggingThread(self.log, self.threadsock,
>> self.logger)
>> -self.thread.start()
>> -if not self.thread.connection_established.wait(self.boottime):
>> -self.logger.error("Didn't receive a console connection from
>> qemu. "
>> - "Here is the qemu command line used:\n%s\nand "
>> - "output from runqemu:\n%s" % (cmdline, out))
>> -self.stop_thread()
>> -return False
>> +# Create and hold onto the login semaphore, this will block
>> +# the LoggingThread until we are ready
>> +login_semaphore = threading.Semaphore()
>> +login_semaphore.acquire()
>> +
>> +self.thread = LoggingThread(self.log, self.threadsock,
>> +self.runqemu.stdout,
>> self.boot_patterns['search_reached_prompt'],
>> +self.logger, login_semaphore)
>> +
>> +self.thread.start()
>> +login_semaphore.release()
>> +
>> +# if not self.thread.connection_established.wait(self.boottime):
>> +# self.logger.error("Didn't receive a console connection from
>> qemu. "
>> +# "Here is the qemu command line
>> used:\n%s\nand "
>> +# "output from runqemu:\n%s" % (cmdline, out))
>> +# self.stop_thread()
>> +# return False
>>
>> self.logger.debug("Output from runqemu:\n%s", out)
>> self.logger.debug("Waiting at most %d seconds for login banner
>> (%s)" %
>>(self.boottime, time.strftime("%D %H:%M:%S")))
>>
[OE-core] [RFC PATCH v2] qemurunner.py: continue to drain stdout after login:
If qemurunner doesn't continuously drain stdout we will eventually
cause QEMU to block while trying to write to the pipe. This can
manifest itself if the guest has for example configured its serial
ports to output via stdio even if the test itself is using a TCP
console or SSH to run things.
To do this:
- always create a logging thread regardless of serial_ports
- use a semaphore between main and logging threads
- move the login detection into the logging thread
- wait until the second acquire before continuing
This doesn't address a potential overflow of stderr although generally
stderr from QEMU will be a lot less likely to block due to the volume
of data.
Signed-off-by: Alex Bennée
Cc: Mikko Rapeli
---
meta/lib/oeqa/utils/qemurunner.py | 128 ++
1 file changed, 78 insertions(+), 50 deletions(-)
diff --git a/meta/lib/oeqa/utils/qemurunner.py
b/meta/lib/oeqa/utils/qemurunner.py
index 29fe271976..b768c08f04 100644
--- a/meta/lib/oeqa/utils/qemurunner.py
+++ b/meta/lib/oeqa/utils/qemurunner.py
@@ -207,8 +207,7 @@ class QemuRunner:
self.logger.info("QMP Available for connection at %s" % (qmp_port2))
try:
-if self.serial_ports >= 2:
-self.threadsock, threadport = self.create_socket()
+self.threadsock, threadport = self.create_socket()
self.server_socket, self.serverport = self.create_socket()
except socket.error as msg:
self.logger.error("Failed to create listening socket: %s" % msg[1])
@@ -243,6 +242,7 @@ class QemuRunner:
# to be a proper fix but this will suffice for now.
self.runqemu = subprocess.Popen(launch_cmd, shell=True,
stdout=subprocess.PIPE, stderr=subprocess.STDOUT, stdin=subprocess.PIPE,
preexec_fn=os.setpgrp, env=env, cwd=self.tmpdir)
output = self.runqemu.stdout
+output_drain = output
launch_time = time.time()
#
@@ -431,21 +431,30 @@ class QemuRunner:
self.logger.debug("Target IP: %s" % self.ip)
self.logger.debug("Server IP: %s" % self.server_ip)
-if self.serial_ports >= 2:
-self.thread = LoggingThread(self.log, self.threadsock, self.logger)
-self.thread.start()
-if not self.thread.connection_established.wait(self.boottime):
-self.logger.error("Didn't receive a console connection from
qemu. "
- "Here is the qemu command line used:\n%s\nand "
- "output from runqemu:\n%s" % (cmdline, out))
-self.stop_thread()
-return False
+# Create and hold onto the login semaphore, this will block
+# the LoggingThread until we are ready
+login_semaphore = threading.Semaphore()
+login_semaphore.acquire()
+
+self.thread = LoggingThread(self.log, self.threadsock,
+self.runqemu.stdout,
self.boot_patterns['search_reached_prompt'],
+self.logger, login_semaphore)
+
+self.thread.start()
+login_semaphore.release()
+
+# if not self.thread.connection_established.wait(self.boottime):
+# self.logger.error("Didn't receive a console connection from
qemu. "
+# "Here is the qemu command line used:\n%s\nand "
+# "output from runqemu:\n%s" % (cmdline, out))
+# self.stop_thread()
+# return False
self.logger.debug("Output from runqemu:\n%s", out)
self.logger.debug("Waiting at most %d seconds for login banner (%s)" %
(self.boottime, time.strftime("%D %H:%M:%S")))
endtime = time.time() + self.boottime
-filelist = [self.server_socket, self.runqemu.stdout]
+filelist = [self.server_socket]
reachedlogin = False
stopread = False
qemusock = None
@@ -464,46 +473,19 @@ class QemuRunner:
filelist.remove(self.server_socket)
self.logger.debug("Connection from %s:%s" % addr)
else:
-# try to avoid reading only a single character at a time
-time.sleep(0.1)
-if hasattr(file, 'read'):
-read = file.read(1024)
-elif hasattr(file, 'recv'):
-read = file.recv(1024)
-else:
-self.logger.error('Invalid file type: %s\n%s' % (file))
-read = b''
-
-self.logger.debug2('Partial boot log:\n%s' %
(read.decode('utf-8', errors='backslashreplace')))
-data = data + read
-if data:
-bootlog += data
-
Re: [OE-core] [RFC PATCH] qemurunner.py: ensure we drain stdout after boot prompt
Richard Purdie writes:
> On Wed, 2023-11-29 at 15:56 +0000, Alex Bennée wrote:
>> Richard Purdie writes:
>>
>> > On Wed, 2023-11-29 at 15:11 +0100, Erik Schilling wrote:
>> > > On Wed Nov 29, 2023 at 1:45 PM CET, Alex Bennée wrote:
>> > > > If qemurunner doesn't continuously drain stdout we will eventually
>> > > > cause QEMU to block while trying to write to the pipe. This can
>> > > > manifest itself if the guest has for example configured its serial
>> > > > ports to output via stdio even if the test itself is using a TCP
>> > > > console or SSH to run things.
>> > > >
>> > > > This doesn't address a potential overflow of stderr although generally
>> > > > stderr from QEMU will be a lot less likely to block due to the volume
>> > > > of data.
>> > > >
>> > > > Suggested-by: Erik Schilling
>> > > > Signed-off-by: Alex Bennée
>> > > > Cc: Mikko Rapeli
>> > > >
>> > > > ---
>> > > > AJB:
>> > > > As a QEMU developer I should note that we've had to solve a lot of
>> > > > similar problems within our own internal testing (e.g.
>> > > >
>> > > > https://gitlab.com/qemu-project/qemu/-/blob/master/python/qemu/machine/console_socket.py?ref_type=heads).
>> > > > Perhaps in the longer term it might make sense to consider using
>> > > > QEMU's own python tooling for configuring and launching QEMU?
>> > > > ---
>> > > > meta/lib/oeqa/utils/qemurunner.py | 12
>> > > > 1 file changed, 12 insertions(+)
>> > > >
>> > > > diff --git a/meta/lib/oeqa/utils/qemurunner.py
>> > > > b/meta/lib/oeqa/utils/qemurunner.py
>> > > > index 29fe271976..1ec472c49e 100644
>> > > > --- a/meta/lib/oeqa/utils/qemurunner.py
>> > > > +++ b/meta/lib/oeqa/utils/qemurunner.py
>> > > > @@ -243,6 +243,7 @@ class QemuRunner:
>> > > > # to be a proper fix but this will suffice for now.
>> > > > self.runqemu = subprocess.Popen(launch_cmd, shell=True,
>> > > > stdout=subprocess.PIPE, stderr=subprocess.STDOUT,
>> > > > stdin=subprocess.PIPE, preexec_fn=os.setpgrp, env=env, cwd=self.tmpdir)
>> > > > output = self.runqemu.stdout
>> > > > +output_drain = output
>> > > > launch_time = time.time()
>> > > >
>> > > > #
>> > > > @@ -539,6 +540,17 @@ class QemuRunner:
>> > > > self.logger.warning("The output:\n%s" % output)
>> > > > except:
>> > > > self.logger.warning("Serial console failed while trying
>> > > > to login")
>> > > > +
>> > > > +def drain_log():
>> > > > +while not output_drain.closed:
>> > > > +more_output = self.getOutput(output_drain)
>> > > > +if len(more_output) > 0:
>> > > > +self.logger.debug("Logs since boot: %s",
>> > > > more_output)
>> > > > +time.sleep(0.1)
>> > > > +
>> > > > +t = threading.Thread(target=drain_log)
>> > > > +t.start()
>> > > > +
>> > > > return True
>> > > >
>> > > > def stop(self):
>> > >
>> > > This is of course just a hack to demonstrate this was the problem. A
>> > > better solution would probably be to collect the logs through the
>> > > existing supervision process that gets forked off... That then also
>> > > solves the problem for the earlier code (and would transition nicely to
>> > > also drain stderr).
>> >
>> > I was wondering about that, this would ideally be handled by that
>> > existing log processing thread. Would you be willing to work out a
>> > patch to do that?
>>
>> Sure - but I'm a little unclear about how things are meant to work if
>> you can offer any pointers. I assume we can just allow the existing
>> logger to continue once we reach the login point?
>
> I was a little unsure about that when I recently worked on that code. I
> think you're right, we should keep the data flowing to the log files
> after login.
I'm having difficulty following the logic. I can see the main loop:
while time.time() < endtime and not stopread:
try:
sread, swrite, serror = select.select(filelist, [], [], 5)
except InterruptedError:
continue
but I guess we have to exit that for the tests to start running. Can
this be punted to the logging process? We'd need some sort of signal
from the logging bit that we'd reached the login point. What does python
use for that? mutex?
>
> Cheers,
>
> Richard
--
Alex Bennée
Virtualisation Tech Lead @ Linaro
-=-=-=-=-=-=-=-=-=-=-=-
Links: You receive all messages sent to this group.
View/Reply Online (#191494):
https://lists.openembedded.org/g/openembedded-core/message/191494
Mute This Topic: https://lists.openembedded.org/mt/102870835/21656
Group Owner: openembedded-core+ow...@lists.openembedded.org
Unsubscribe: https://lists.openembedded.org/g/openembedded-core/unsub
[arch...@mail-archive.com]
-=-=-=-=-=-=-=-=-=-=-=-
Re: [OE-core] [RFC PATCH] qemurunner.py: ensure we drain stdout after boot prompt
Richard Purdie writes:
> On Wed, 2023-11-29 at 15:11 +0100, Erik Schilling wrote:
>> On Wed Nov 29, 2023 at 1:45 PM CET, Alex Bennée wrote:
>> > If qemurunner doesn't continuously drain stdout we will eventually
>> > cause QEMU to block while trying to write to the pipe. This can
>> > manifest itself if the guest has for example configured its serial
>> > ports to output via stdio even if the test itself is using a TCP
>> > console or SSH to run things.
>> >
>> > This doesn't address a potential overflow of stderr although generally
>> > stderr from QEMU will be a lot less likely to block due to the volume
>> > of data.
>> >
>> > Suggested-by: Erik Schilling
>> > Signed-off-by: Alex Bennée
>> > Cc: Mikko Rapeli
>> >
>> > ---
>> > AJB:
>> > As a QEMU developer I should note that we've had to solve a lot of
>> > similar problems within our own internal testing (e.g.
>> >
>> > https://gitlab.com/qemu-project/qemu/-/blob/master/python/qemu/machine/console_socket.py?ref_type=heads).
>> > Perhaps in the longer term it might make sense to consider using
>> > QEMU's own python tooling for configuring and launching QEMU?
>> > ---
>> > meta/lib/oeqa/utils/qemurunner.py | 12
>> > 1 file changed, 12 insertions(+)
>> >
>> > diff --git a/meta/lib/oeqa/utils/qemurunner.py
>> > b/meta/lib/oeqa/utils/qemurunner.py
>> > index 29fe271976..1ec472c49e 100644
>> > --- a/meta/lib/oeqa/utils/qemurunner.py
>> > +++ b/meta/lib/oeqa/utils/qemurunner.py
>> > @@ -243,6 +243,7 @@ class QemuRunner:
>> > # to be a proper fix but this will suffice for now.
>> > self.runqemu = subprocess.Popen(launch_cmd, shell=True,
>> > stdout=subprocess.PIPE, stderr=subprocess.STDOUT, stdin=subprocess.PIPE,
>> > preexec_fn=os.setpgrp, env=env, cwd=self.tmpdir)
>> > output = self.runqemu.stdout
>> > +output_drain = output
>> > launch_time = time.time()
>> >
>> > #
>> > @@ -539,6 +540,17 @@ class QemuRunner:
>> > self.logger.warning("The output:\n%s" % output)
>> > except:
>> > self.logger.warning("Serial console failed while trying to
>> > login")
>> > +
>> > +def drain_log():
>> > +while not output_drain.closed:
>> > +more_output = self.getOutput(output_drain)
>> > +if len(more_output) > 0:
>> > +self.logger.debug("Logs since boot: %s", more_output)
>> > +time.sleep(0.1)
>> > +
>> > +t = threading.Thread(target=drain_log)
>> > +t.start()
>> > +
>> > return True
>> >
>> > def stop(self):
>>
>> This is of course just a hack to demonstrate this was the problem. A
>> better solution would probably be to collect the logs through the
>> existing supervision process that gets forked off... That then also
>> solves the problem for the earlier code (and would transition nicely to
>> also drain stderr).
>
> I was wondering about that, this would ideally be handled by that
> existing log processing thread. Would you be willing to work out a
> patch to do that?
Sure - but I'm a little unclear about how things are meant to work if
you can offer any pointers. I assume we can just allow the existing
logger to continue once we reach the login point?
--
Alex Bennée
Virtualisation Tech Lead @ Linaro
-=-=-=-=-=-=-=-=-=-=-=-
Links: You receive all messages sent to this group.
View/Reply Online (#191456):
https://lists.openembedded.org/g/openembedded-core/message/191456
Mute This Topic: https://lists.openembedded.org/mt/102870835/21656
Group Owner: openembedded-core+ow...@lists.openembedded.org
Unsubscribe: https://lists.openembedded.org/g/openembedded-core/unsub
[arch...@mail-archive.com]
-=-=-=-=-=-=-=-=-=-=-=-
[OE-core] [RFC PATCH] qemurunner.py: ensure we drain stdout after boot prompt
If qemurunner doesn't continuously drain stdout we will eventually
cause QEMU to block while trying to write to the pipe. This can
manifest itself if the guest has for example configured its serial
ports to output via stdio even if the test itself is using a TCP
console or SSH to run things.
This doesn't address a potential overflow of stderr although generally
stderr from QEMU will be a lot less likely to block due to the volume
of data.
Suggested-by: Erik Schilling
Signed-off-by: Alex Bennée
Cc: Mikko Rapeli
---
AJB:
As a QEMU developer I should note that we've had to solve a lot of
similar problems within our own internal testing (e.g.
https://gitlab.com/qemu-project/qemu/-/blob/master/python/qemu/machine/console_socket.py?ref_type=heads).
Perhaps in the longer term it might make sense to consider using
QEMU's own python tooling for configuring and launching QEMU?
---
meta/lib/oeqa/utils/qemurunner.py | 12
1 file changed, 12 insertions(+)
diff --git a/meta/lib/oeqa/utils/qemurunner.py
b/meta/lib/oeqa/utils/qemurunner.py
index 29fe271976..1ec472c49e 100644
--- a/meta/lib/oeqa/utils/qemurunner.py
+++ b/meta/lib/oeqa/utils/qemurunner.py
@@ -243,6 +243,7 @@ class QemuRunner:
# to be a proper fix but this will suffice for now.
self.runqemu = subprocess.Popen(launch_cmd, shell=True,
stdout=subprocess.PIPE, stderr=subprocess.STDOUT, stdin=subprocess.PIPE,
preexec_fn=os.setpgrp, env=env, cwd=self.tmpdir)
output = self.runqemu.stdout
+output_drain = output
launch_time = time.time()
#
@@ -539,6 +540,17 @@ class QemuRunner:
self.logger.warning("The output:\n%s" % output)
except:
self.logger.warning("Serial console failed while trying to login")
+
+def drain_log():
+while not output_drain.closed:
+more_output = self.getOutput(output_drain)
+if len(more_output) > 0:
+self.logger.debug("Logs since boot: %s", more_output)
+time.sleep(0.1)
+
+t = threading.Thread(target=drain_log)
+t.start()
+
return True
def stop(self):
--
2.39.2
-=-=-=-=-=-=-=-=-=-=-=-
Links: You receive all messages sent to this group.
View/Reply Online (#191449):
https://lists.openembedded.org/g/openembedded-core/message/191449
Mute This Topic: https://lists.openembedded.org/mt/102870835/21656
Group Owner: openembedded-core+ow...@lists.openembedded.org
Unsubscribe: https://lists.openembedded.org/g/openembedded-core/unsub
[arch...@mail-archive.com]
-=-=-=-=-=-=-=-=-=-=-=-
