[Avocado-devel] option --output-check-record behavior
Lucas Meneghel Rodrigues
lookkas at gmail.com
Fri Sep 9 21:25:33 UTC 2016
On Fri, Sep 9, 2016 at 8:14 AM Marcos E. Matsunaga <
Marcos.Matsunaga at oracle.com> wrote:
> Hi guys,
>
> First of all, thanks again for your help. I really appreciate it.
>
> I found an interesting behavior. If I set loglevel=info in
> /etc/avocado/avocado.conf, it will not produce any content in
> stderr.expected and stdout.expected. If I set loglevel=debug, then it will
> work as it should. I don't mind running in debug mode, but I am not sure
> the behavior should be affected by loglevel.
>
> Anyway, the question I have is about using --output-check-record when
> multiplexing. I notice that the files stdout.expected and stderr.expected
> get overwritten on each variant. I will assume there is a way to save each
> of the variant results and then use them to check. The problem is that I
> went through the documentation and didn't find anything that talks about it.
>
> Thanks again.
>
> BTW, is the whole development team Brazilian?
>
No, we also have Lukas, from Czech republic, and also contributors in China
and India.
> On 09/08/2016 08:05 PM, Lucas Meneghel Rodrigues wrote:
>
> Yep, that was the problem. The pipe won't work if shell=False (default).
>
> Now, on the rationale why shell=False is the default, basically, it's
> unsafe, see:
>
> https://docs.python.org/2/library/subprocess.html
>
> With shell=True, the expected standard output starts to appear.
>
> On Thu, Sep 8, 2016 at 4:01 PM Lucas Meneghel Rodrigues <lookkas at gmail.com>
> wrote:
>
>> By the way, you *must* set shell=True to use pipes (which I did forget).
>> Otherwise the pipes won't work.
>>
>> On Thu, Sep 8, 2016 at 4:00 PM Lucas Meneghel Rodrigues <
>> lookkas at gmail.com> wrote:
>>
>>> I think you guys are missing the point here. I just tried Marcos's test
>>> here and that's what I get with Avocado LTS 36.2:
>>>
>>> $ avocado run xentest.py --output-check-record all
>>> JOB ID : c44d95698bc6a20329691a9c10370c3b63c8944f
>>> JOB LOG :
>>> /home/lmr/avocado/job-results/job-2016-09-08T15.54-c44d956/job.log
>>> TESTS : 1
>>> (1/1) xentest.py:xentest.test_xen_start_stop: ERROR (0.01 s)
>>> RESULTS : PASS 0 | ERROR 1 | FAIL 0 | SKIP 0 | WARN 0 | INTERRUPT 0
>>> JOB HTML :
>>> /home/lmr/avocado/job-results/job-2016-09-08T15.54-c44d956/html/results.html
>>> TESTS TIME : 0.01 s
>>> $ ls
>>> xentest.py xentest.pyc xentest.py.data
>>> $ cat xentest.py.data/stdout.expected
>>> $ cat xentest.py.data/stderr.expected
>>> xc: error: Could not obtain handle on privileged command interface (2 =
>>> No such file or directory): Internal error
>>> libxl: error: libxl.c:116:libxl_ctx_alloc: cannot open libxc handle: No
>>> such file or directory
>>> cannot init xl context
>>>
>>> Keep in mind that I have installed only the basic xen packages, so my
>>> 'xl' doesn't work. Avocado does its job and creates xentest.py.data, with
>>> the expected outputs.
>>>
>>> So no, you don't need to avoid the pipes, and everything should work.
>>> The caveat is that avocado creates xentest.py.data with the recorded files
>>> in the same dir of your test file. You have to test that with your version
>>> of avocado and verify if the directory/files are created or not. If not,
>>> it's a bug, although I think we have a functional test to avoid such a bug.
>>>
>>> So for me here, everything is worked as designed. I modified xentest.py
>>> to use avocado libs:
>>>
>>> #!/usr/bin/env python
>>> # vim: tabstop=8 expandtab shiftwidth=4 softtabstop=4
>>>
>>> import os
>>> import sys
>>> import string
>>> import logging
>>> import commands
>>> import time
>>>
>>> from avocado import Test
>>> from avocado import main
>>> from avocado.utils import process
>>> from autotest.client import utils
>>> from autotest.client import xen
>>>
>>> progress_log = logging.getLogger("progress")
>>>
>>> class xentest(Test):
>>> """
>>> Test
>>> """
>>> def exec_xl(self):
>>> """
>>> Start xen Guest
>>> """
>>> sleeptime = self.params.get('sleep_time')
>>> guestdef = self.params.get('guest_cfg')
>>> runaction = self.params.get('run_action')
>>> domname = self.params.get('domain_name')
>>> progress_log.info('%s: Running action %s', self.name, runaction)
>>> time.sleep(sleeptime)
>>> if runaction == 'create':
>>> cmd = ('/usr/sbin/xl %s %s' % (runaction, guestdef))
>>> if process.system(cmd, ignore_status=False) == "0":
>>> pass
>>> else:
>>> return False
>>> else:
>>> cmd = ('/usr/sbin/xl %s %s' % (runaction, domname))
>>> if process.system(cmd, ignore_status=False) == "0":
>>> pass
>>> else:
>>> return False
>>>
>>> def test_xen_start_stop(self):
>>> """
>>> Get Xen version
>>> """
>>> fd = open('/tmp/xenver.log', 'w')
>>> fd.write('### %s\n' % time.time())
>>> cmd = "xl info|grep xen_version| awk '{print $3}'"
>>> xenversion = process.system_output(cmd, ignore_status=False)
>>> process.system('ls -la /usr/share/avocado/tests 2>&1')
>>> print('Xen Version = %s.\n' % xenversion)
>>> fd.write('Xen Version = %s.\n' % xenversion)
>>> fd.write('### %s\n' % time.time())
>>> if self.exec_xl() == "0":
>>> pass
>>> else:
>>> return False
>>> fd.close()
>>>
>>> if __name__ == "__main__":
>>> main()
>>>
>>> I hope this helps,
>>>
>>> Lucas
>>>
>>> On Thu, Sep 8, 2016 at 3:55 PM Marcos E. Matsunaga <
>>> Marcos.Matsunaga at oracle.com> wrote:
>>>
>>>> Thanks Amador,
>>>>
>>>> I assumed it would have the same behavior as utils.system and
>>>> completely ignored the pipe.
>>>>
>>>>
>>>>
>>>> On 09/08/2016 07:39 PM, Amador Segundo wrote:
>>>>
>>>> On Sep 8, 2016 8:19 PM, "Marcos E. Matsunaga" <
>>>> Marcos.Matsunaga at oracle.com> wrote:
>>>> >
>>>> > Hi Cleber,
>>>> >
>>>> > Sorry for being a pain. I've tried to use process.system to execute
>>>> commands, but I got an error, that's why I kept the autotest libraries (I
>>>> actually copied from one of the files in io-github-autotest-libvirt).
>>>> >
>>>> > The error I'm getting is:
>>>> >
>>>> > 2016-09-08 13:49:25,844 sysinfo L0371 INFO | Profiler
>>>> disabled
>>>> > 2016-09-08 13:49:25,845 test L0214 INFO | START
>>>> 1-/root/avocado-vt/io-fs-autotest-xen/xen/tests/xentest.py:xentest.test_xen_start_stop;1
>>>> > 2016-09-08 13:49:25,846 process L0334 INFO | Running 'xl
>>>> info|grep xen_version| awk '{print $3}''
>>>> > 2016-09-08 13:49:25,863 process L0435 INFO | Command 'xl
>>>> info|grep xen_version| awk '{print $3}'' finished with 1 after
>>>> 0.00377798080444s
>>>>
>>>> The problem here is the pipe. You can collect the output and parse it
>>>> inside the python code. Something.like:
>>>>
>>>> output = process.system_output("xl info")
>>>> for line in output.splitlines():
>>>> if 'xen_version' in line:
>>>> var = line.split()[3]
>>>> break
>>>> ...
>>>>
>>>> > 2016-09-08 13:49:25,863 stacktrace L0038 ERROR|
>>>> > 2016-09-08 13:49:25,863 stacktrace L0041 ERROR| Reproduced
>>>> traceback from: /usr/lib/python2.7/site-packages/avocado/core/test.py:448
>>>> > 2016-09-08 13:49:25,864 stacktrace L0044 ERROR| Traceback (most
>>>> recent call last):
>>>> > 2016-09-08 13:49:25,864 stacktrace L0044 ERROR| File
>>>> "/root/avocado-vt/io-fs-autotest-xen/xen/tests/xentest.py", line 52, in
>>>> test_xen_start_stop
>>>> > 2016-09-08 13:49:25,864 stacktrace L0044 ERROR| xenversion =
>>>> process.system_output(cmd, ignore_status=False)
>>>> > 2016-09-08 13:49:25,864 stacktrace L0044 ERROR| File
>>>> "/usr/lib/python2.7/site-packages/avocado/utils/process.py", line 1139, in
>>>> system_output
>>>> > 2016-09-08 13:49:25,864 stacktrace L0044 ERROR| sudo=sudo)
>>>> > 2016-09-08 13:49:25,864 stacktrace L0044 ERROR| File
>>>> "/usr/lib/python2.7/site-packages/avocado/utils/process.py", line 1046, in
>>>> run
>>>> > 2016-09-08 13:49:25,864 stacktrace L0044 ERROR| raise
>>>> CmdError(cmd, sp.result)
>>>> > 2016-09-08 13:49:25,864 stacktrace L0044 ERROR| CmdError:
>>>> Command 'xl info|grep xen_version| awk '{print $3}'' failed (rc=1)
>>>> > 2016-09-08 13:49:25,864 stacktrace L0045 ERROR|
>>>> > 2016-09-08 13:49:25,865 test L0563 ERROR| Traceback (most
>>>> recent call last):
>>>> >
>>>> > 2016-09-08 13:49:25,865 test L0563 ERROR| File
>>>> "/usr/lib/python2.7/site-packages/avocado/core/test.py", line 503, in
>>>> _run_avocado
>>>> > raise test_exception
>>>> >
>>>> > 2016-09-08 13:49:25,865 test L0563 ERROR| CmdError:
>>>> Command 'xl info|grep xen_version| awk '{print $3}'' failed (rc=1)
>>>> >
>>>> > I looked at
>>>> "/usr/lib/python2.7/site-packages/avocado/utils/process.py", line 1139 and
>>>> didn't see anything that could be causing the problem. I even tried to add
>>>> "sudo=False" argument in process.system, but I get the same error.
>>>> >
>>>> > Thanks again.
>>>> >
>>>> >
>>>> > On 09/08/2016 06:36 PM, Cleber Rosa wrote:
>>>> >>
>>>> >> On 09/08/2016 01:50 PM, Marcos E. Matsunaga wrote:
>>>> >>>
>>>> >>> On 09/08/2016 05:44 PM, Cleber Rosa wrote:
>>>> >>>>
>>>> >>>> On 09/08/2016 11:34 AM, Marcos E. Matsunaga wrote:
>>>> >>>>>
>>>> >>>>> Hi Cleber,
>>>> >>>>>
>>>> >>>>> Thanks for your quick reply. That's exactly what I understood,
>>>> but here
>>>> >>>>> is what is happening
>>>> >>>>>
>>>> >>>>> I have a directory ~/avocado/xen/tests where I have the xentest.py
>>>> >>>>> script. When I execute it, it does create the directory
>>>> >>>>> ~/avocado/xen/tests/xentest.py.data with stderr.expected and
>>>> >>>>> stdout.expected (empty). It also creates the two files (stdout and
>>>> >>>>> stderr) in the job-results/latest directory, but also empty.
>>>> >>>>>
>>>> >>>>> The weird thing is that instead of saving, it reports to the
>>>> job.log as
>>>> >>>>> an error "L0151 ERROR| [stderr] Parsing config from /VM/guest1/
>>>> vm.cf".
>>>> >>>>>
>>>> >>>>> That's why I think I am missing something.
>>>> >>>>
>>>> >>>> Can you post the full test code and the resulting `job.log` file?
>>>> >>>
>>>> >>> Sure.. It is attached.
>>>> >>> And the multiplex file I am using is:
>>>> >>>
>>>> >>> xentest:
>>>> >>> guest1:
>>>> >>> action: !mux
>>>> >>> start:
>>>> >>> run_action: "create"
>>>> >>> domain_name: "perf1"
>>>> >>> sleep_time: 1
>>>> >>> stop:
>>>> >>> run_action: "shutdown"
>>>> >>> domain_name: "perf1"
>>>> >>> sleep_time: 60
>>>> >>> guest_cfg: /Repo/VM/perf1/vm.cfg
>>>> >>>
>>>> >>>>> Thanks again for your help.
>>>> >>>>>
>>>> >>>>> On 09/08/2016 02:59 PM, Cleber Rosa wrote:
>>>> >>>>>>
>>>> >>>>>> On 09/08/2016 10:25 AM, Marcos E. Matsunaga wrote:
>>>> >>>>>>>
>>>> >>>>>>> Hi All,
>>>> >>>>>>>
>>>> >>>>>>> I am new to avocado and have just started to look into it.
>>>> >>>>>>>
>>>> >>>>>>> I have been playing with avocado on Fedora 24 for a few weeks. I
>>>> >>>>>>> wrote a
>>>> >>>>>>> small script to run commands and was exploring the option
>>>> >>>>>>> "--output-check-record", but it never populate the files
>>>> >>>>>>> stderr.expected
>>>> >>>>>>> and stdout.expected. Instead, it prints an error with
>>>> "[stderr]" in
>>>> >>>>>>> the
>>>> >>>>>>> job.log file. My understanding is that the output (stderr and
>>>> stdout)
>>>> >>>>>>> of commands/scripts executed by avocado would be captured and
>>>> saved on
>>>> >>>>>>> those files (like on synctest.py example), but it doesn't. I
>>>> want to
>>>> >>>>>>> know if I am doing something wrong or it is a bug.
>>>> >>>>>>>
>>>> >>>>>> Hi Marcos,
>>>> >>>>>>
>>>> >>>>>> Avocado creates the `stdout` and `stderr` files in the test
>>>> result
>>>> >>>>>> directory. In the synctest example, for instance, my contains:
>>>> >>>>>>
>>>> >>>>>> $ avocado run examples/tests/synctest.py
>>>> >>>>>> $ cat
>>>> >>>>>>
>>>> ~/avocado/job-results/latest/test-results/1-examples_tests_synctest.py\:SyncTest.test/stdout
>>>> >>>>>>
>>>> >>>>>>
>>>> >>>>>>
>>>> >>>>>> PAR : waiting
>>>> >>>>>> PASS : sync interrupted
>>>> >>>>>>
>>>> >>>>>> `stderr` is actually empty for that test:
>>>> >>>>>>
>>>> >>>>>> $ wc -l
>>>> >>>>>>
>>>> ~/avocado/job-results/latest/test-results/1-examples_tests_synctest.py\:SyncTest.test/stderr
>>>> >>>>>>
>>>> >>>>>>
>>>> >>>>>> 0
>>>> >>>>>>
>>>> /home/cleber/avocado/job-results/latest/test-results/1-examples_tests_synctest.py:SyncTest.test/stderr
>>>> >>>>>>
>>>> >>>>>>
>>>> >>>>>>
>>>> >>>>>> What you have to do is, once you're satisfied with those
>>>> outputs, and
>>>> >>>>>> they're considered "the gold standard", you'd move those to the
>>>> test
>>>> >>>>>> *data directory*.
>>>> >>>>>>
>>>> >>>>>> So, if you test is hosted at, `/tests/xl.py`, you'd created the
>>>> >>>>>> `/tests/xl.py.data`, and put those files there, named
>>>> `stdout.expected`
>>>> >>>>>> and `stderr.expected`.
>>>> >>>>>>
>>>> >>>>>> Whenever you run `avocado run --output-check-record all
>>>> /tests/xl.py`,
>>>> >>>>>> those files will be used and the output of the *current* test
>>>> execution
>>>> >>>>>> will be compared to those "gold standards".
>>>> >>>>>>
>>>> >>>>>>> The script is very simple and the way I execute the command is:
>>>> >>>>>>>
>>>> >>>>>>> cmd = ('/usr/sbin/xl create /VM/guest1/vm.cfg')
>>>> >>>>>>> if utils.system(cmd) == "0":
>>>> >>
>>>> >> The issue seems to be related to the fact that you're using old
>>>> autotest
>>>> >> libraries to execute your external commands.
>>>> >>
>>>> >> The output record/check support is built into Avocado's libraries,
>>>> >> namely `avocado.utils.process`.
>>>> >>
>>>> >> Try to replace your code with:
>>>> >>
>>>> >> from avocado.utils import process
>>>> >> ...
>>>> >> process.system(cmd)
>>>> >>
>>>> >> Also, mixing and matching autotest and avocado libraries in the same
>>>> >> test code is not something I'd recommend. Not that it's guaranteed
>>>> to
>>>> >> break. I'd recomend to (try to) move to avocado libraries, or keep an
>>>> >> eye on strange behavior like this.
>>>> >>
>>>> >>>>>>> pass
>>>> >>>>>>> else:
>>>> >>>>>>> return False
>>>> >>>>>>>
>>>> >>>>>>> The command send to stdout:
>>>> >>>>>>>
>>>> >>>>>>> Parsing config from /VM/guest1/vm.cfg
>>>> >>>>>>>
>>>> >>>>>>> I run the test as:
>>>> >>>>>>>
>>>> >>>>>>> avocado run --output-check-record all xentest.py
>>>> >>>>>>>
>>>> >>>>>>> The job.log file contains:
>>>> >>>>>>>
>>>> >>>>>>> 2016-09-07 13:04:48,015 test L0214 INFO | START
>>>> >>>>>>>
>>>> 1-/root/avocado-vt/io-fs-autotest-xen/xen/tests/xentest.py:xentest.test_xen_start_stop;1
>>>> >>>>>>>
>>>> >>>>>>>
>>>> >>>>>>>
>>>> >>>>>>> 2016-09-07 13:04:48,051 xentest L0033 INFO |
>>>> >>>>>>>
>>>> 1-/root/avocado-vt/io-fs-autotest-xen/xen/tests/xentest.py:xentest.test_xen_start_stop;1:
>>>> >>>>>>>
>>>> >>>>>>>
>>>> >>>>>>> Running action create
>>>> >>>>>>> 2016-09-07 13:04:49,067 utils L0151 ERROR| [stderr]
>>>> Parsing
>>>> >>>>>>> config from /VM/guest1/vm.cfg
>>>> >>>>>>> 2016-09-07 13:04:49,523 test L0586 INFO | PASS
>>>> >>>>>>>
>>>> 1-/root/avocado-vt/io-fs-autotest-xen/xen/tests/xentest.py:xentest.test_xen_start_stop;1
>>>> >>>>>>>
>>>> >>>>>>>
>>>> >>>>>>>
>>>> >>>>>>>
>>>> >>>>>>> Thanks for your time and help.
>>>> >>>>>>
>>>> >>>>>> Let me know if it's clear now! And thanks for trying Avocado out!
>>>> >>>>>>
>>>> >
>>>> > --
>>>> >
>>>> > Regards,
>>>> >
>>>> > Marcos Eduardo Matsunaga
>>>> >
>>>> > Oracle USA
>>>> > Linux Engineering
>>>> >
>>>> > “The statements and opinions expressed here are my own and do not
>>>> > necessarily represent those of Oracle Corporation.”
>>>> >
>>>>
>>>>
>>>> --
>>>>
>>>> Regards,
>>>>
>>>> Marcos Eduardo Matsunaga
>>>>
>>>> Oracle USA
>>>> Linux Engineering
>>>>
>>>> “The statements and opinions expressed here are my own and do not
>>>> necessarily represent those of Oracle Corporation.”
>>>>
>>>>
> --
>
> Regards,
>
> Marcos Eduardo Matsunaga
>
> Oracle USA
> Linux Engineering
>
> “The statements and opinions expressed here are my own and do not
> necessarily represent those of Oracle Corporation.”
>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://listman.redhat.com/archives/avocado-devel/attachments/20160909/362d12fa/attachment.htm>
More information about the Avocado-devel
mailing list