Importance of Log capturing

Log capturing is very important when we run tests. It helps us to understand how the system behaves. More so in case of test failures, where we need to log certain files to understand why.

Sysinfo Collectibles on Avocado

The logging capabilities of avocado are quite extensive.

  • files - mainly sysfs files, and certain other files useful, captured before and after the test
  • commands - command output run before and after the test
  • profilers - runs these commands in background during the test

All of the above are captured into results folder. They are defined in avocado.conf, and can be customised.

# cd latest/test-results/2-examples_tests_failtest.py_FailTest.test/sysinfo/

# ls pre/

 cmdline              'df -mP'    'gcc --version'   interrupts      lscpu          modules                    partitions         slabinfo    version
 cpuinfo               dmesg       hostname        'ip link'       'lspci -vvnn'   mounts                     scaling_governor  'uname -a'
 current_clocksource  'fdisk -l'  'ifconfig -a'    'ld --version'   meminfo       'numactl --hardware show'   sched_features     uptime

# ls post/

 cmdline              'df -mP'    'gcc --version'   interrupts     'ld --version'   meminfo  'numactl --hardware show'   sched_features   uptime
 cpuinfo               dmesg       hostname        'ip link'        lscpu           modules   partitions                 slabinfo         version
 current_clocksource  'fdisk -l'  'ifconfig -a'     journalctl.gz  'lspci -vvnn'    mounts    scaling_governor          'uname -a'

They are defined in avocado.conf, and can be customised.

[sysinfo.collectibles]
# File with list of commands that will be executed and have their output collected
commands = etc/avocado/sysinfo/commands
# File with list of files that will be collected verbatim
files = etc/avocado/sysinfo/files
# File with list of commands that will run alongside the job/test
profilers = etc/avocado/sysinfo/profilers

# cat etc/avocado/sysinfo/files
/proc/cmdline
/proc/mounts
/proc/pci

More info at official Avocado Sysinfo documentation

Optimisation

The default behaviour is to log all the sysinfo collectibles in both pre and post.

There was a recent optimisation to the default behaviour, wherein we log only those changed files and commands in post.

If there are 25 files and commands, and 10 of them are unchanged during the test, then it is unnecessary to log them. Also, it is time consuming to locate which files changed, while debugging. So, we log only the 15 files and commands which are changed.

# avocado run a.sh
JOB ID     : ea5386a30e8c31f77d880294dcbecdaf2cb5d8e9
JOB LOG    : /root/avocado/job-results/job-2020-06-16T13.45-ea5386a/job.log
 (1/1) a.sh: PASS (5.14 s)
RESULTS    : PASS 1 | ERROR 0 | FAIL 0 | SKIP 0 | WARN 0 | INTERRUPT 0 | CANCEL 0
JOB TIME   : 5.19 s

# ls /root/avocado/job-results/latest/test-results/1-a.sh/sysinfo/pre/
 cmdline              'df -mP'    'gcc --version'   interrupts      lscpu          modules                    partitions      'uname -a'
 cpuinfo               dmesg       hostname        'ip link'       'lspci -vvnn'   mounts                     sched_features   uptime
 current_clocksource  'fdisk -l'  'ifconfig -a'    'ld --version'   meminfo       'numactl --hardware show'   slabinfo         version

# ls /root/avocado/job-results/latest/test-results/1-a.sh/sysinfo/post/
'df -mP'  'ifconfig -a'   interrupts   journalctl.gz   meminfo  'numactl --hardware show'   uptime

This behavior is controlled by a parameter in avocado.conf: sysinfo.collect.optimize

[sysinfo.collect]
# Optimize sysinfo collection by removing duplicates between pre and post
optimize = True

By this, we are looking atmost 35 % less disk space consumption in results folder per test, depending on the number of sysinfo collectibles configured, with less than 1s extra processing time.

Without this optimisation:

real	0m31.863s
user	0m25.546s
sys	0m1.458s

# du -sh /root/avocado/job-results/latest/
424K	/root/avocado/job-results/latest/

With this optimisation:

real	0m32.314s
user	0m25.800s
sys	0m1.303s

# du -sh /root/avocado/job-results/latest/
276K	/root/avocado/job-results/latest/

Sysinfo in case of only a test failure

There is also another feature which makes it possible to collect certain sysinfo logs only in case of test failure.

This feature gives us the option to collect data like sosreport and supportconfig, that too in case of test failure only. This helps running the test unattended and not worry about collecting logs as soon as a failure occurs.

We can configure them as commands (fail_commands) and files (fail_files) to be collected.

They are configured via avocado.conf:

[sysinfo.collectibles]
fail_commands = etc/avocado/sysinfo/fail_commands
fail_files = etc/avocado/sysinfo/fail_files

# cat etc/avocado/sysinfo/fail_files
sosreport --batch --tmp-dir $AVOCADO_SYSINFODIR
supportconfig -R $AVOCADO_SYSINFODIR

Notice the environment variable AVOCADO_SYSINFODIR. We can use it to place files generated on to the sysinfo folder.

# avocado run avocado/examples/tests/passtest.py avocado/examples/tests/failtest.py
JOB ID     : ac6e7400acbec69f079bd5ab446faa391e2758a9
JOB LOG    : /root/sim/tests/results/job-2020-07-11T14.03-ac6e740/job.log
 (1/2) avocado/examples/tests/passtest.py:PassTest.test: PASS (6.24 s)
 (2/2) avocado/examples/tests/failtest.py:FailTest.test: FAIL: This test is supposed to fail (110.23 s)
RESULTS    : PASS 1 | ERROR 0 | FAIL 1 | SKIP 0 | WARN 0 | INTERRUPT 0 | CANCEL 0
JOB TIME   : 122.93 s


# ls 1-avocado_examples_tests_passtest.py_PassTest.test/sysinfo/post/
'ifconfig -a'   journalctl.gz   'multipath -ll'

# ls 2-avocado_examples_tests_failtest.py_FailTest.test/sysinfo/post/
'ifconfig -a'   'multipath -ll'                                     sosreport-ltczzj3-lp2-2020-07-11-epsjncn.tar.xz
journalctl.gz   'sosreport --batch --tmp-dir $AVOCADO_SYSINFODIR'   sosreport-ltczzj3-lp2-2020-07-11-epsjncn.tar.xz.md5