Advanced logging capabilities

Avocado provides advanced logging capabilities at test run time. These can be combined with the standard Python library APIs on tests.

One common example is the need to follow specific progress on longer or more complex tests. Let’s look at a very simple test example, but one multiple clear stages on a single test:

import logging
import time

from avocado import Test


class Plant(Test):
    """Logs parts of the test progress in an specific logging stream."""

    def test_plant_organic(self):
        progress_log = logging.getLogger("avocado.test.progress")
        job_log = logging.getLogger("avocado.job")
        rows = int(self.params.get("rows", default=3))

        # Preparing soil
        for row in range(rows):
            progress_log.info("preparing soil on row %s", row)
        job_log.info("Soil has been prepared.")

        # Letting soil rest
        progress_log.info("letting soil rest before throwing seeds")
        time.sleep(1)

        # Throwing seeds
        for row in range(rows):
            progress_log.info("throwing seeds on row %s", row)

        job_log.info("Seeds have been palanted.")
        # Let them grow
        progress_log.info("waiting for Avocados to grow")
        time.sleep(2)

        # Harvest them
        for row in range(rows):
            progress_log.info("harvesting organic avocados on row %s", row)

        progress_log.error("Avocados are Gone")

Currently Avocado will store any log information that has been generated during job run into specific log files based on used logging namespace and process where the logs have been generated.

Avocado generate three types of log each of them with different purpose:

1. job.log

The job.log file is generated for each avocado job and it is stored directly in log_dir directory. This file contains only logs from avocado.job namespace and holds information about job configuration and test statuses which were run inside the job. The format of logs is:

<date> <time> avocado.job <log level> | <log>

2. full.log

The full.log file is generated for each avocado job and it is stored directly in log_dir directory. This file contains all logs which were generated during job run. It is very verbose, and it contains even avocado internal logs. If the parallel run is enabled (default behavior) the logs are not sorted and logs from multiple tests might be mixed together. Therefore, some post-processing of this file might be needed for full understanding of these logs. The format of logs is:

<date> <time> <namespace> <log level> | <testname>: <log>

3. debug.log

The debug.log file is generated for every test in avocado job and it is stored in {logs_dir}/test-results/{test-id} directory. This file contains all logs which were generated during one test run. (each test has its own debug.log file). This file is most important for debugging one specific test. The format of logs is:

<stream> <date> <time> <namespace> <log level> | <log>

Note

Avocado uses four main namespaces, each of them prints logs into different locations and you can use these namespaces in your tests if you want to adjust your logs:

avocado:

Main namespace for avocado logs.

avocado.test:

All logs under this namespace will be stored into {logs_dir}/test-results/{test-id}/debug.log

avocado.job:

All logs under this namespace will be stored into {logs_dir}/job.log

Showing custom log streams

Using –show

Alternatively, you can ask Avocado to show your logging stream, either exclusively or in addition to other builtin streams:

$ avocado --show app,avocado.test.progress run -- examples/tests/logging_streams.py

The outcome should be similar to:

JOB ID     : e236a04a03620aa73d5ce48e779ecbfd495bf940
JOB LOG    : /home/user/avocado/job-results/job-2023-04-19T11.50-e236a04/job.log
(1/1) examples/tests/logging_streams.py:Plant.test_plant_organic: STARTED
avocado.test.progress: 1-examples/tests/logging_streams.py:Plant.test_plant_organic: preparing soil on row 0
avocado.test.progress: 1-examples/tests/logging_streams.py:Plant.test_plant_organic: preparing soil on row 1
avocado.test.progress: 1-examples/tests/logging_streams.py:Plant.test_plant_organic: preparing soil on row 2
avocado.test.progress: 1-examples/tests/logging_streams.py:Plant.test_plant_organic: letting soil rest before throwing seeds
avocado.test.progress: 1-examples/tests/logging_streams.py:Plant.test_plant_organic: throwing seeds on row 0
avocado.test.progress: 1-examples/tests/logging_streams.py:Plant.test_plant_organic: throwing seeds on row 1
avocado.test.progress: 1-examples/tests/logging_streams.py:Plant.test_plant_organic: throwing seeds on row 2
avocado.test.progress: 1-examples/tests/logging_streams.py:Plant.test_plant_organic: waiting for Avocados to grow
avocado.test.progress: 1-examples/tests/logging_streams.py:Plant.test_plant_organic: harvesting organic avocados on row 0
avocado.test.progress: 1-examples/tests/logging_streams.py:Plant.test_plant_organic: harvesting organic avocados on row 1
avocado.test.progress: 1-examples/tests/logging_streams.py:Plant.test_plant_organic: harvesting organic avocados on row 2
1-examples/tests/logging_streams.py:Plant.test_plant_organic: Avocados have been harvested.
avocado.test.progress: 1-examples/tests/logging_streams.py:Plant.test_plant_organic: Avocados are Gone
(1/1) examples/tests/logging_streams.py:Plant.test_plant_organic: PASS (3.02 s)
RESULTS    : PASS 1 | ERROR 0 | FAIL 0 | SKIP 0 | WARN 0 | INTERRUPT 0 | CANCEL 0
JOB HTML   : /home/user/avocado/job-results/job-2023-04-19T11.50-e236a04/results.html
JOB TIME   : 4.34 s

Using –store-logging-stream

The custom avocado.test.progress stream is combined with the application output, which may or may not suit your needs or preferences. If you want the avocado.test.progress stream to be sent to a separate file, both for clarity and for persistence, you can run Avocado like this:

$ avocado run --store-logging-stream=avocado.test.progress -- examples/tests/logging_streams.py examples/tests/logging_streams.py

The result is that, besides all the other log files commonly generated, there will be created two log files named avocado.test.progress.log at the test results directory and in job log directory. In the test result directory the stream will be separated by test, but in the job log directory the logs will be combined from all tests.

During the test run, one could watch the progress with:

$ tail -f ~/avocado/job-results/latest/test-results/1-examples_tests_logging_streams.py_Plant.test_plant_organic/avocado.test.progress.log
2023-04-19 11:52:09,473 avocado.test.progress INFO | preparing soil on row 2
2023-04-19 11:52:09,473 avocado.test.progress INFO | letting soil rest before throwing seeds
2023-04-19 11:52:10,474 avocado.test.progress INFO | throwing seeds on row 0
2023-04-19 11:52:10,474 avocado.test.progress INFO | throwing seeds on row 1
2023-04-19 11:52:10,474 avocado.test.progress INFO | throwing seeds on row 2
2023-04-19 11:52:10,475 avocado.test.progress INFO | waiting for Avocados to grow
2023-04-19 11:52:12,476 avocado.test.progress INFO | harvesting organic avocados on row 0
2023-04-19 11:52:12,477 avocado.test.progress INFO | harvesting organic avocados on row 1
2023-04-19 11:52:12,478 avocado.test.progress INFO | harvesting organic avocados on row 2
2023-04-19 11:52:12,478 avocado.test.progress ERROR| Avocados are Gone

Or to see progress from all tests:

$ tail -f ~/avocado/job-results/latest/avocado.test.progress.log
2023-04-13 17:49:08,687 avocado.test.progress INFO | 1-examples/tests/logging_streams.py:Plant.test_plant_organic: preparing soil on row 0
2023-04-13 17:49:08,688 avocado.test.progress INFO | 1-examples/tests/logging_streams.py:Plant.test_plant_organic: preparing soil on row 1
2023-04-13 17:49:08,689 avocado.test.progress INFO | 2-examples/tests/logging_streams.py:Plant.test_plant_organic: preparing soil on row 0
2023-04-13 17:49:08,690 avocado.test.progress INFO | 2-examples/tests/logging_streams.py:Plant.test_plant_organic: preparing soil on row 1
2023-04-13 17:49:08,740 avocado.test.progress INFO | 1-examples/tests/logging_streams.py:Plant.test_plant_organic: preparing soil on row 2
2023-04-13 17:49:08,741 avocado.test.progress INFO | 1-examples/tests/logging_streams.py:Plant.test_plant_organic: letting soil rest before throwing seeds
2023-04-13 17:49:08,741 avocado.test.progress INFO | 2-examples/tests/logging_streams.py:Plant.test_plant_organic: preparing soil on row 2
2023-04-13 17:49:08,741 avocado.test.progress INFO | 2-examples/tests/logging_streams.py:Plant.test_plant_organic: letting soil rest before throwing seeds
2023-04-13 17:49:09,599 avocado.test.progress INFO | 1-examples/tests/logging_streams.py:Plant.test_plant_organic: throwing seeds on row 0
2023-04-13 17:49:09,600 avocado.test.progress INFO | 2-examples/tests/logging_streams.py:Plant.test_plant_organic: throwing seeds on row 0
2023-04-13 17:49:09,651 avocado.test.progress INFO | 1-examples/tests/logging_streams.py:Plant.test_plant_organic: throwing seeds on row 1
2023-04-13 17:49:09,651 avocado.test.progress INFO | 1-examples/tests/logging_streams.py:Plant.test_plant_organic: throwing seeds on row 2
2023-04-13 17:49:09,651 avocado.test.progress INFO | 1-examples/tests/logging_streams.py:Plant.test_plant_organic: waiting for Avocados to grow
2023-04-13 17:49:09,652 avocado.test.progress INFO | 2-examples/tests/logging_streams.py:Plant.test_plant_organic: throwing seeds on row 1
2023-04-13 17:49:09,652 avocado.test.progress INFO | 2-examples/tests/logging_streams.py:Plant.test_plant_organic: throwing seeds on row 2
2023-04-13 17:49:09,652 avocado.test.progress INFO | 2-examples/tests/logging_streams.py:Plant.test_plant_organic: waiting for Avocados to grow
2023-04-13 17:49:11,619 avocado.test.progress INFO | 1-examples/tests/logging_streams.py:Plant.test_plant_organic: harvesting organic avocados on row 0
2023-04-13 17:49:11,620 avocado.test.progress INFO | 1-examples/tests/logging_streams.py:Plant.test_plant_organic: harvesting organic avocados on row 1
2023-04-13 17:49:11,621 avocado.test.progress INFO | 2-examples/tests/logging_streams.py:Plant.test_plant_organic: harvesting organic avocados on row 0
2023-04-13 17:49:11,621 avocado.test.progress INFO | 2-examples/tests/logging_streams.py:Plant.test_plant_organic: harvesting organic avocados on row 1
2023-04-13 17:49:11,674 avocado.test.progress INFO | 1-examples/tests/logging_streams.py:Plant.test_plant_organic: harvesting organic avocados on row 2
2023-04-13 17:49:11,674 avocado.test.progress ERROR| 1-examples/tests/logging_streams.py:Plant.test_plant_organic: Avocados are Gone
2023-04-13 17:49:11,675 avocado.test.progress INFO | 2-examples/tests/logging_streams.py:Plant.test_plant_organic: harvesting organic avocados on row 2
2023-04-13 17:49:11,676 avocado.test.progress ERROR| 2-examples/tests/logging_streams.py:Plant.test_plant_organic: Avocados are Gone

The very same avocado.test.progress logger, could be used across multiple test methods and across multiple test modules.

By default avocado is creating full.log file in job_log directory with all avocado logs which were created during the job run:

$ avocado run examples/tests/logging_streams.py

Again you could watch the progress with:

$ tail -f ~/avocado/job-results/latest/test-results/full.log
2023-04-13 17:54:18,814 avocado.app INFO | JOB ID     : 14f66b17f7c79ba6765e4d0c6a7e77b8f7fa7308
2023-04-13 17:54:18,814 avocado.app INFO | JOB LOG    : /home/janrichter/avocado/job-results/job-2023-04-13T17.54-14f66b1/job.log
2023-04-13 17:54:18,814 avocado.sysinfo INFO | Commands configured by file: /home/janrichter/Avocado/avocado/avocado/etc/avocado/sysinfo/commands
2023-04-13 17:54:18,814 avocado.sysinfo INFO | Files configured by file: /home/janrichter/Avocado/avocado/avocado/etc/avocado/sysinfo/files
2023-04-13 17:54:18,814 avocado.sysinfo DEBUG| File /home/janrichter/Avocado/avocado/avocado/etc/avocado/sysinfo/fail_commands does not exist.
2023-04-13 17:54:18,814 avocado.sysinfo DEBUG| File /home/janrichter/Avocado/avocado/avocado/etc/avocado/sysinfo/fail_files does not exist.
2023-04-13 17:54:18,815 avocado.sysinfo INFO | Profilers configured by file: /home/janrichter/Avocado/avocado/avocado/etc/avocado/sysinfo/profilers
2023-04-13 17:54:18,815 avocado.sysinfo INFO | Profiler disabled
2023-04-13 17:54:18,875 avocado.sysinfo DEBUG| Not logging /proc/slabinfo (lack of permissions)
2023-04-13 17:54:18,901 avocado.sysinfo DEBUG| Not logging /sys/kernel/debug/sched_features (file not found)
2023-04-13 17:54:18,901 avocado.sysinfo DEBUG| Not logging /proc/pci (file not found)
2023-04-13 17:54:18,911 avocado.job INFO | Command line: /home/janrichter/.pyenv/versions/avocado/bin/avocado run --store-logging-stream=all -- examples/tests/logging_streams.py
2023-04-13 17:54:18,912 avocado.job INFO |
2023-04-13 17:54:18,914 avocado.job INFO | Avocado version: 101.0 (GIT commit bf7704ba)
2023-04-13 17:54:18,914 avocado.job INFO |
2023-04-13 17:54:18,914 avocado.job INFO | Avocado config:
2023-04-13 17:54:18,914 avocado.job INFO |
2023-04-13 17:54:18,915 avocado.job INFO | {'assets.fetch.ignore_errors': False,
2023-04-13 17:54:18,915 avocado.job INFO |  'assets.fetch.references': [],
2023-04-13 17:54:18,916 avocado.job INFO |  'assets.fetch.timeout': 300,
2023-04-13 17:54:18,916 avocado.job INFO |  'assets.list.days': None,
2023-04-13 17:54:18,916 avocado.job INFO |  'assets.list.overall_limit': None,
2023-04-13 17:54:18,916 avocado.job INFO |  'assets.list.size_filter': None,
2023-04-13 17:54:18,916 avocado.job INFO |  'assets.purge.days': None,
2023-04-13 17:54:18,916 avocado.job INFO |  'assets.purge.overall_limit': None,
2023-04-13 17:54:18,916 avocado.job INFO |  'assets.purge.size_filter': None,
2023-04-13 17:54:18,916 avocado.job INFO |  'assets.register.name': None,
2023-04-13 17:54:18,916 avocado.job INFO |  'assets.register.sha1_hash': None,
2023-04-13 17:54:18,916 avocado.job INFO |  'assets.register.url': None,
2023-04-13 17:54:18,916 avocado.job INFO |  'cache.clear': [],
2023-04-13 17:54:18,916 avocado.job INFO |  'cache.list': [],
2023-04-13 17:54:18,916 avocado.job INFO |  'config': None,
2023-04-13 17:54:18,916 avocado.job INFO |  'config.datadir': False,
2023-04-13 17:54:18,916 avocado.job INFO |  'core.paginator': False,
2023-04-13 17:54:18,916 avocado.job INFO |  'core.show': {'app'},
...

External logs

If your tests use some external logs which are not part of avocado.* namespace, avocado will still log these logs into the standard log files. Let’s see an example with Matplotlib external library:

import matplotlib.pyplot as plt

from avocado import Test


class MatplotlibTest(Test):
    def test(self):
        _, ax = plt.subplots()

        fruits = ["apple", "blueberry", "cherry", "orange"]
        counts = [40, 100, 30, 55]
        bar_labels = ["red", "blue", "_red", "orange"]
        bar_colors = ["tab:red", "tab:blue", "tab:red", "tab:orange"]

        ax.bar(fruits, counts, label=bar_labels, color=bar_colors)

        ax.set_ylabel("fruit supply")
        ax.set_title("Fruit supply by kind and color")
        ax.legend(title="Fruit color")

Avocado will add Matplotlib logs into the standard avocado logs:

$ avocado run examples/tests/external_logging_stream.py

You can check the logs by:

$ cat ~/avocado/job-results/latest/test-results/1-examples_tests_external_logging_stream.py_MatplotlibTest.test/debug.log
[stdlog] 2023-04-20 10:07:03,743 matplotlib DEBUG| matplotlib data path: /home/janrichter/.pyenv/versions/avocado/lib/python3.10/site-packages/matplotlib/mpl-data
[stdlog] 2023-04-20 10:07:03,748 matplotlib DEBUG| CONFIGDIR=/home/janrichter/.config/matplotlib
[stdlog] 2023-04-20 10:07:03,749 matplotlib DEBUG| interactive is False
[stdlog] 2023-04-20 10:07:03,749 matplotlib DEBUG| platform is linux
[stdlog] 2023-04-20 10:07:03,801 matplotlib DEBUG| CACHEDIR=/home/janrichter/.cache/matplotlib
[stdlog] 2023-04-20 10:07:03,802 matplotlib.font_manager DEBUG| Using fontManager instance from /home/janrichter/.cache/matplotlib/fontlist-v330.json
[stdlog] 2023-04-20 10:07:03,985 avocado.test INFO | INIT 1-examples/tests/external_logging_stream.py:MatplotlibTest.test
[stdlog] 2023-04-20 10:07:03,986 avocado.test DEBUG| PARAMS (key=timeout, path=*, default=None) => None
[stdlog] 2023-04-20 10:07:03,986 avocado.test DEBUG| Test metadata:
[stdlog] 2023-04-20 10:07:03,986 avocado.test DEBUG|   filename: /home/janrichter/Avocado/avocado/examples/tests/external_logging_stream.py
[stdlog] 2023-04-20 10:07:03,986 avocado.test DEBUG|   teststmpdir: /var/tmp/avocado_3b1c_sqy
[stdlog] 2023-04-20 10:07:03,987 avocado.test INFO | START 1-examples/tests/external_logging_stream.py:MatplotlibTest.test
[stdlog] 2023-04-20 10:07:03,995 matplotlib.pyplot DEBUG| Loaded backend agg version v2.2.
[stdlog] 2023-04-20 10:07:03,997 matplotlib.font_manager DEBUG| findfont: Matching sans\-serif:style=normal:variant=normal:weight=normal:stretch=normal:size=10.0.
[stdlog] 2023-04-20 10:07:03,997 matplotlib.font_manager DEBUG| findfont: score(FontEntry(fname='/home/janrichter/.pyenv/versions/avocado/lib/python3.10/site-packages/matplotlib/mpl-data/fonts/ttf/DejaVuSans-Bold.ttf', name='DejaVu Sans', style='normal', variant='normal', weight=700, stretch='normal', size='scalable')) = 0.33499999999999996
[stdlog] 2023-04-20 10:07:03,997 matplotlib.font_manager DEBUG| findfont: score(FontEntry(fname='/home/janrichter/.pyenv/versions/avocado/lib/python3.10/site-packages/matplotlib/mpl-data/fonts/ttf/DejaVuSansMono-BoldOblique.ttf', name='DejaVu Sans Mono', style='oblique', variant='normal', weight=700, stretch='normal', size='scalable')) = 11.335
[stdlog] 2023-04-20 10:07:03,997 matplotlib.font_manager DEBUG| findfont: score(FontEntry(fname='/home/janrichter/.pyenv/versions/avocado/lib/python3.10/site-packages/matplotlib/mpl-data/fonts/ttf/cmsy10.ttf', name='cmsy10', style='normal', variant='normal', weight=400, stretch='normal', size='scalable')) = 10.05
[stdlog] 2023-04-20 10:07:03,998 matplotlib.font_manager DEBUG| findfont: score(FontEntry(fname='/home/janrichter/.pyenv/versions/avocado/lib/python3.10/site-packages/matplotlib/mpl-data/fonts/ttf/STIXNonUni.ttf', name='STIXNonUnicode', style='normal', variant='normal', weight=400, stretch='normal', size='scalable')) = 10.05
[stdlog] 2023-04-20 10:07:03,998 matplotlib.font_manager DEBUG| findfont: score(FontEntry(fname='/home/janrichter/.pyenv/versions/avocado/lib/python3.10/site-packages/matplotlib/mpl-data/fonts/ttf/STIXGeneralBolIta.ttf', name='STIXGeneral', style='italic', variant='normal', weight=700, stretch='normal', size='scalable')) = 11.335
[stdlog] 2023-04-20 10:07:03,998 matplotlib.font_manager DEBUG| findfont: score(FontEntry(fname='/home/janrichter/.pyenv/versions/avocado/lib/python3.10/site-packages/matplotlib/mpl-data/fonts/ttf/DejaVuSansMono-Bold.ttf', name='DejaVu Sans Mono', style='normal', variant='normal', weight=700, stretch='normal', size='scalable')) = 10.335
[stdlog] 2023-04-20 10:07:03,998 matplotlib.font_manager DEBUG| findfont: score(FontEntry(fname='/home/janrichter/.pyenv/versions/avocado/lib/python3.10/site-packages/matplotlib/mpl-data/fonts/ttf/STIXNonUniBol.ttf', name='STIXNonUnicode', style='normal', variant='normal', weight=700, stretch='normal', size='scalable')) = 10.335
...