[Avocado-devel] Avocado not flushing output real time
Cleber Rosa
crosa at redhat.com
Thu Aug 9 19:34:32 UTC 2018
Hi Alan,
I can definitely reproduce your issue here. The interesting part is
that it (also) happens outside of Avocado. What I mean is:
$ /tmp/my-shell-script.sh | while read f; do echo "$f"; done;
Shows one line at a time. While:
$ /tmp/your-python-script.py | while read f; do echo "$f"; done;
Shows all of them at once. I need a bit more time to check the
differences here, and I'd appreciate if you could confirm that you get
the same behavior I'm describing here.
But, if at all possible, Avocado should also try print the lines as
they're printed on both cases.
Regards,
- Cleber.
On 08/09/2018 03:14 PM, Alan Martinovic wrote:
> Hi Cleber,
> thank you for the response.
>
> Yes it's a SIMPLE test.
> In the normal scenario it's a test run on the host to check the behavior of an
> embedded Linux device via uart.
>
> But the behavior is the same also with this dummy test code:
>
> ---
>
> #!/usr/bin/python3
>
> import time
> import sys
>
> print("Reading through boot record")
> for i in range(10):
> time.sleep(2)
> print(i)
>
> sys.exit(1)
>
>
> ---
>
> I run it as
> $ avocado --show=test run dummy_test
>
> For this example it block until the test is completed and then prints
> the output. Will mark the part where it blocks in the output below.
>
>
> ---
>
>
> alan at alan-N551JM:~/workspace/platform_tests$ avocado --show=test run dummy_test
> found extension EntryPoint.parse('human = avocado.plugins.human:HumanJob')
> found extension EntryPoint.parse('jobscripts =
> avocado.plugins.jobscripts:JobScripts')
> found extension EntryPoint.parse('teststmpdir =
> avocado.plugins.teststmpdir:TestsTmpDir')
> found extension EntryPoint.parse('json_variants =
> avocado.plugins.json_variants:JsonVariants')
> File /etc/avocado/sysinfo/commands does not exist.
> File /etc/avocado/sysinfo/files does not exist.
> File /etc/avocado/sysinfo/profilers does not exist.
> Command line: /home/alan/.local/bin/avocado --show=test run dummy_test
>
> Avocado version: 63.0
>
> Config files read (in order):
> /home/alan/.local/lib/python3.6/site-packages/avocado/etc/avocado/avocado.conf
> /home/alan/.local/lib/python3.6/site-packages/avocado/etc/avocado/conf.d/resultsdb.conf
> /home/alan/.local/lib/python3.6/site-packages/avocado/etc/avocado/conf.d/jobscripts.conf
> /home/alan/.local/lib/python3.6/site-packages/avocado/etc/avocado/conf.d/gdb.conf
> /home/alan/.local/lib/python3.6/site-packages/avocado/etc/avocado/conf.d/result_upload.conf
> /home/alan/.config/avocado/avocado.conf
>
> Avocado config:
> Section.Key Value
> datadir.paths.base_dir /var/lib/avocado
> datadir.paths.test_dir /usr/share/doc/avocado/tests
> datadir.paths.data_dir /var/lib/avocado/data
> datadir.paths.logs_dir ~/avocado/job-results
> sysinfo.collect.enabled True
> sysinfo.collect.commands_timeout -1
> sysinfo.collect.installed_packages False
> sysinfo.collect.profiler False
> sysinfo.collect.locale C
> sysinfo.collect.per_test False
> sysinfo.collectibles.commands /etc/avocado/sysinfo/commands
> sysinfo.collectibles.files /etc/avocado/sysinfo/files
> sysinfo.collectibles.profilers /etc/avocado/sysinfo/profilers
> runner.output.colored True
> runner.output.utf8
> remoter.behavior.reject_unknown_hosts False
> remoter.behavior.disable_known_hosts False
> job.output.loglevel debug
> restclient.connection.hostname localhost
> restclient.connection.port 9405
> restclient.connection.username
> restclient.connection.password
> plugins.disable []
> plugins.skip_broken_plugin_notification []
> plugins.loaders ['file', '@DEFAULT']
> plugins.jobscripts.pre /etc/avocado/scripts/job/pre.d/
> plugins.jobscripts.post /etc/avocado/scripts/job/post.d/
> plugins.jobscripts.warn_non_existing_dir False
> plugins.jobscripts.warn_non_zero_status True
> gdb.paths.gdb /usr/bin/gdb
> gdb.paths.gdbserver /usr/bin/gdbserver
>
> Avocado Data Directories:
>
> base /home/alan/avocado
> tests /home/alan/.local/lib/python3.6/site-packages/examples/tests
> data /home/alan/avocado/data
> logs /home/alan/avocado/job-results/job-2018-08-09T21.10-a9168c7
>
> No variants available, using defaults only
>
> Variant : /
> Temporary dir: /var/tmp/avocado_u50x75ah/avocado_job_n6_sbv95
>
> Job ID: a9168c7da524d621b56947bea7651004f58ab551
>
> File /etc/avocado/sysinfo/commands does not exist.
> File /etc/avocado/sysinfo/files does not exist.
> File /etc/avocado/sysinfo/profilers does not exist.
> INIT 1-dummy_test
> PARAMS (key=timeout, path=*, default=None) => None
> Test metadata:
> filename: /home/alan/workspace/platform_tests/dummy_test
> teststmpdir: /var/tmp/avocado_44fpdrzb
> workdir: /var/tmp/avocado_u50x75ah/avocado_job_n6_sbv95/1-dummy_test
> START 1-dummy_test
> DATA (filename=output.expected) => NOT FOUND (data sources: variant, file)
> Running '/home/alan/workspace/platform_tests/dummy_test'
>
> ######### WAITING HERE.... #################
> ######### WAITING HERE.... #################
> ######### WAITING HERE.... #################
>
> ######### EVERYTHING PRINTED AT ONCE #################
>
> [stdout] Reading through boot record
> [stdout] 0
> [stdout] 1
> [stdout] 2
> [stdout] 3
> [stdout] 4
> [stdout] 5
> [stdout] 6
> [stdout] 7
> [stdout] 8
> [stdout] 9
> Command '/home/alan/workspace/platform_tests/dummy_test' finished with
> 1 after 20.04673981666565s
> Exit status: 1
> Duration: 20.04673981666565
>
> Reproduced traceback from:
> /home/alan/.local/lib/python3.6/site-packages/avocado/core/test.py:831
> Traceback (most recent call last):
> File "/home/alan/.local/lib/python3.6/site-packages/avocado/core/test.py",
> line 1123, in _execute_cmd
> env=test_params, encoding=defaults.ENCODING)
> File "/home/alan/.local/lib/python3.6/site-packages/avocado/utils/process.py",
> line 1271, in run
> raise CmdError(cmd, sp.result)
> avocado.utils.process.CmdError:
> ('/home/alan/workspace/platform_tests/dummy_test',
> <avocado.utils.process.CmdResult object at 0x7f53000ceba8>)
>
> During handling of the above exception, another exception occurred:
>
> Traceback (most recent call last):
> File "/home/alan/.local/lib/python3.6/site-packages/avocado/core/test.py",
> line 1179, in test
> self._execute_cmd()
> File "/home/alan/.local/lib/python3.6/site-packages/avocado/core/test.py",
> line 1128, in _execute_cmd
> raise exceptions.TestFail(details)
> avocado.core.exceptions.TestFail:
> ('/home/alan/workspace/platform_tests/dummy_test',
> <avocado.utils.process.CmdResult object at 0x7f53000ceba8>)
>
> Local variables:
> -> self <class 'avocado.core.test.SimpleTest'>: 1-dummy_test
> DATA (filename=output.expected) => NOT FOUND (data sources: variant, file)
> DATA (filename=stdout.expected) => NOT FOUND (data sources: variant, file)
> DATA (filename=stderr.expected) => NOT FOUND (data sources: variant, file)
> FAIL 1-dummy_test -> TestFail:
> ('/home/alan/workspace/platform_tests/dummy_test',
> <avocado.utils.process.CmdResult object at 0x7f53000ceba8>)
>
> Test results available in
> /home/alan/avocado/job-results/job-2018-08-09T21.10-a9168c7
>
> ---
>
> On Thu, Aug 9, 2018 at 8:05 PM, Cleber Rosa <crosa at redhat.com> wrote:
>>
>>
>> On 08/09/2018 01:40 PM, Alan Martinovic wrote:
>>> Hi,
>>>
>>> I'm running a long test as a standalone script which prints statuses to sdtout.
>>> I've noticed that avocado doesn't print the output out before the test finishes
>>> completely.
>>>
>>> As if it isn't "flushing lines" (probably not the correct term, but it
>>> explains the behavior :) )
>>>
>>> Is this a known issue/expected behavior or something to do with my environment?
>>>
>>>
>>> Be Well,
>>> Alan
>>>
>>
>> Hi Alan,
>>
>> IIUC, you're running what Avocado calls a SIMPLE test (an executable,
>> that returns zero/non-zero), right?
>>
>> I created a sample script to test the behavior you describe:
>>
>> ---
>>
>> #!/bin/sh
>> for i in $(seq 1 30); do
>> echo "Step $i";
>> sleep 1;
>> done;
>>
>> ---
>>
>> And ran:
>>
>> $ avocado --show=test run /tmp/script.sh
>>
>> I get one line per second printed, which is the expected behavior (line
>> buffered output).
>>
>> The same happens when the test output is sent to the log files. Can you
>> describe the behavior of your test? Does it print multiple lines? Or a
>> continuous stream of characters that are not separated by newlines?
>>
>> Regards!
>>
>> --
>> Cleber Rosa
>> [ Sr Software Engineer - Virtualization Team - Red Hat ]
>> [ Avocado Test Framework - avocado-framework.github.io ]
>> [ 7ABB 96EB 8B46 B94D 5E0F E9BB 657E 8D33 A5F2 09F3 ]
--
Cleber Rosa
[ Sr Software Engineer - Virtualization Team - Red Hat ]
[ Avocado Test Framework - avocado-framework.github.io ]
[ 7ABB 96EB 8B46 B94D 5E0F E9BB 657E 8D33 A5F2 09F3 ]
More information about the Avocado-devel
mailing list