[Avocado-devel] Avocado not flushing output real time
Alan Martinovic
alan.martinovic at senic.com
Thu Aug 9 19:44:55 UTC 2018
Hey Cleber,
yup, got the same behavior. Nice find :)
These two behave the same:
$ /tmp/my-shell-script.sh | while read f; do echo "$f"; done;
$ /tmp/my-shell-script.sh
And these two behave differently:
$ /tmp/your-python-script.py # Prints line at a time
$ /tmp/your-python-script.py | while read f; do echo "$f"; done; #
Prints at once
Be Well,
Alan
On Thu, Aug 9, 2018 at 9:34 PM, Cleber Rosa <crosa at redhat.com> wrote:
> 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