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 <[email protected]> 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@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 <[email protected]> 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 ] >> > >
signature.asc
Description: OpenPGP digital signature
