[Avocado-devel] Avocado not flushing output real time
Alan Martinovic
alan.martinovic at senic.com
Thu Aug 9 19:14:10 UTC 2018
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 ]
More information about the Avocado-devel
mailing list