[Avocado-devel] Avocado not flushing output real time
Lukáš Doktor
ldoktor at redhat.com
Wed Aug 15 09:30:38 UTC 2018
Dne 15.8.2018 v 11:29 Lukáš Doktor napsal(a):
> Dne 9.8.2018 v 21:44 Alan Martinovic napsal(a):
>> 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
>>
>
> Hello Alan,
>
> python uses system default buffering, which for TTY devices is usually a line and fully buffered on non-tty (eg. pipe). That is why you see different behavior for `script.py | cat` vs. `script.py`.: https://docs.python.org/2/library/functions.html#open
>
> If you still need immediate response, you need to open the stdout unbuffered, or add `sys.stdout.flush()` after each write (note sys.stdout.flush() is not guaranteed to flush the output immediately so some delay might still happen, but in most cases it should suffice. Worst case you'll also have to run `os.fsync(sys.stdout.fileno)`).
>
> This change should work well in your example. You might see another issue if no new lines were to be generated, because Avocado does line buffering internally. So something like:
>
> for AAA in `seq 1 10`; do echo -n $AAA; done
>
> Would wait until newline (or exit), but there is realistically nothing we can do about this.
I mean we can, we do support writing right-away, it's just that we decided not to do for performance reasons, so you'd have to convince us pretty strongly to disable line-buffering.
Lukáš
>
> Regards,
> Lukáš
>
>>
>> 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 ]
>>
>
>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 488 bytes
Desc: OpenPGP digital signature
URL: <http://listman.redhat.com/archives/avocado-devel/attachments/20180815/172a4e4e/attachment.sig>
More information about the Avocado-devel
mailing list