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 <[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 ]
