avocado.test.progress logging stream setup via API #6080

marioaag · 2024-12-09T22:42:34Z

marioaag
Dec 9, 2024

I'm trying to send some progress messages to the terminal using the documentation in: https://avocado-framework.readthedocs.io/en/latest/guides/writer/chapters/logging.html#showing-custom-log-streams

And setting the core.show through the job_config parameters

JOB_CONFIG = {'core.show': {'app', 'avocado.test.progress'}}

    test_suite_obj = TestSuite(name=name,
                               tests=runnables,
                               job_config=JOB_CONFIG,
                               config=JOB_CONFIG)

I can see how it gets set in the job.log file:

2024-12-09 16:29:45,145 avocado.job job              L0309 I    | Avocado version: 108.0
2024-12-09 16:29:45,145 avocado.job job              L0310 I    |
2024-12-09 16:29:45,145 avocado.job job              L0288 I    | Avocado config:
2024-12-09 16:29:45,145 avocado.job job              L0289 I    |
2024-12-09 16:29:45,146 avocado.job job              L0291 I    | {'core.show': {'app', 'avocado.test.progress'},      <<<<<------ GETS SET
2024-12-09 16:29:45,146 avocado.job job              L0291 I    |  'datadir.paths.base_dir': '/Users/mario/avocado',
2024-12-09 16:29:45,146 avocado.job job              L0291 I    |  'datadir.paths.cache_dirs': ['/Users/mario/avocado/data/cache'],
2024-12-09 16:29:45,146 avocado.job job              L0291 I    |  'datadir.paths.data_dir': '/Users/mario/avocado/data',
2024-12-09 16:29:45,146 avocado.job job              L0291 I    |  'datadir.paths.logs_dir': '/tmp/iLAB_LOGS/AVOCADO_LOGs/241209-162936961428',
2024-12-09 16:29:45,146 avocado.job job              L0291 I    |  'datadir.paths.test_dir': '/usr/share/doc/avocado/tests',
2024-12-09 16:29:45,146 avocado.job job              L0291 I    |  'human_ui.omit.statuses': [],
2024-12-09 16:29:45,146 avocado.job job              L0291 I    |  'job.output.loglevel': 'INFO',
2024-12-09 16:29:45,146 avocado.job job              L0291 I    |  'job.output.testlogs.logfiles': ['debug.log'],
2024-12-09 16:29:45,146 avocado.job job              L0291 I    |  'job.output.testlogs.statuses': [],
2024-12-09 16:29:45,146 avocado.job job              L0291 I    |  'job.output.testlogs.summary_statuses': ['ERROR', 'FAIL', 'INTERRUPTED'],
2024-12-09 16:29:45,146 avocado.job job              L0291 I    |  'job.run.logging_buffer_size': 0,
2024-12-09 16:29:45,146 avocado.job job              L0291 I    |  'job.run.result.json.enabled': True,
2024-12-09 16:29:45,146 avocado.job job              L0291 I    |  'job.run.result.json.output': None,
2024-12-09 16:29:45,146 avocado.job job              L0291 I    |  'job.run.result.tap.enabled': True,
2024-12-09 16:29:45,146 avocado.job job              L0291 I    |  'job.run.result.tap.include_logs': False,
2024-12-09 16:29:45,146 avocado.job job              L0291 I    |  'job.run.result.tap.output': None,
2024-12-09 16:29:45,146 avocado.job job              L0291 I    |  'job.run.result.xunit.enabled': True,
2024-12-09 16:29:45,146 avocado.job job              L0291 I    |  'job.run.result.xunit.job_name': None,
2024-12-09 16:29:45,146 avocado.job job              L0291 I    |  'job.run.result.xunit.max_test_log_chars': 100000,
2024-12-09 16:29:45,146 avocado.job job              L0291 I    |  'job.run.result.xunit.output': None,
2024-12-09 16:29:45,146 avocado.job job              L0291 I    |  'job.run.store_logging_stream': [],
2024-12-09 16:29:45,146 avocado.job job              L0291 I    |  'job.run.timeout': 0,
2024-12-09 16:29:45,146 avocado.job job              L0291 I    |  'json.variants.load': None,
2024-12-09 16:29:45,146 avocado.job job              L0291 I    |  'plugins.cache.order': [],
2024-12-09 16:29:45,146 avocado.job job              L0291 I    |  'plugins.cli.cmd.order': [],
2024-12-09 16:29:45,146 avocado.job job              L0291 I    |  'plugins.cli.order': [],
2024-12-09 16:29:45,146 avocado.job job              L0291 I    |  'plugins.disable': [],
2024-12-09 16:29:45,146 avocado.job job              L0291 I    |  'plugins.init.order': [],
2024-12-09 16:29:45,146 avocado.job job              L0291 I    |  'plugins.job.prepost.order': [],
2024-12-09 16:29:45,146 avocado.job job              L0291 I    |  'plugins.jobscripts.post': '/etc/avocado/scripts/job/post.d/',

And I can see how the message is logged in the debug.log

[stderr] I:avocado.test.progress:TEST TEST TEST TEST

But not see it in the terminal output:

JOB ID     : 2ad72d337dd9dd3b1bf600ea79c775e2edebacd9
JOB LOG    : /tmp/iLAB_LOGS/AVOCADO_LOGs/241209-162936961428/job-2024-12-09T16.29-2ad72d3/job.log
 (241209-162938905847.CHS-3/30) git/iLabConfig/test/avocado/testcases/CheckHostStatus/CheckHostStatus.py:CheckHostStatus.filesystem_check: STARTED
 (241209-162938905847.CHS-2/30) git/iLabConfig/test/avocado/testcases/CheckHostStatus/CheckHostStatus.py:CheckHostStatus.up_time: STARTED
 (241209-162938905847.CHS-5/30) git/iLabConfig/test/avocado/testcases/CheckHostStatus/CheckHostStatus.py:CheckHostStatus.test_kdump: STARTED
 (241209-162938905847.CHS-1/30) git/iLabConfig/test/avocado/testcases/CheckHostStatus/CheckHostStatus.py:CheckHostStatus.os_info: STARTED
 (241209-162938905847.CHS-7/30) git/iLabConfig/test/avocado/testcases/CheckHostStatus/CheckHostStatus.py:CheckHostStatus.file_system_capacity_check: STARTED
 (241209-162938905847.CHS-9/30) git/iLabConfig/test/avocado/testcases/CheckHostStatus/CheckHostStatus.py:CheckHostStatus.ntp_check: STARTED
 (241209-162938905847.CHS-6/30) git/iLabConfig/test/avocado/testcases/CheckHostStatus/CheckHostStatus.py:CheckHostStatus.memory_check: STARTED
 (241209-162938905847.CHS-10/30) git/iLabConfig/test/avocado/testcases/CheckHostStatus/CheckHostStatus.py:CheckHostStatus.msdi_check: STARTED
 (241209-162938905847.CHS-4/30) git/iLabConfig/test/avocado/testcases/CheckHostStatus/CheckHostStatus.py:CheckHostStatus.core_dump_check: STARTED
 (241209-162938905847.CHS-8/30) git/iLabConfig/test/avocado/testcases/CheckHostStatus/CheckHostStatus.py:CheckHostStatus.syslog_test: STARTED
 (241209-162938905847.CHS-5/30) git/iLabConfig/test/avocado/testcases/CheckHostStatus/CheckHostStatus.py:CheckHostStatus.test_kdump: ERROR: name 'sys' is not defined (0.40 s)
 (241209-162938905847.CHS-3/30) git/iLabConfig/test/avocado/testcases/CheckHostStatus/CheckHostStatus.py:CheckHostStatus.filesystem_check: ERROR: name 'sys' is not defined (0.43 s)
 (241209-162938905847.CHS-2/30) git/iLabConfig/test/avocado/testcases/CheckHostStatus/CheckHostStatus.py:CheckHostStatus.up_time: ERROR: name 'sys' is not defined (0.42 s)
 (241209-162938905847.CHS-1/30) git/iLabConfig/test/avocado/testcases/CheckHostStatus/CheckHostStatus.py:CheckHostStatus.os_info: ERROR: name 'sys' is not defined (0.45 s)
 (241209-162938905847.CHS-7/30) git/iLabConfig/test/avocado/testcases/CheckHostStatus/CheckHostStatus.py:CheckHostStatus.file_system_capacity_check: ERROR: name 'sys' is not defined (0.41 s)
 (241209-162938905847.CHS-9/30) git/iLabConfig/test/avocado/testcases/CheckHostStatus/CheckHostStatus.py:CheckHostStatus.ntp_check: ERROR: name 'sys' is not defined (0.38 s)
 (241209-162938905847.CHS-4/30) git/iLabConfig/test/avocado/testcases/CheckHostStatus/CheckHostStatus.py:CheckHostStatus.core_dump_check: ERROR: name 'sys' is not defined (0.37 s)
 (241209-162938905847.CHS-10/30) git/iLabConfig/test/avocado/testcases/CheckHostStatus/CheckHostStatus.py:CheckHostStatus.msdi_check: ERROR: name 'sys' is not defined (0.39 s)
 (241209-162938905847.CHS-6/30) git/iLabConfig/test/avocado/testcases/CheckHostStatus/CheckHostStatus.py:CheckHostStatus.memory_check: ERROR: name 'sys' is not defined (0.41 s)
 (241209-162938905847.CHS-8/30) git/iLabConfig/test/avocado/testcases/CheckHostStatus/CheckHostStatus.py:CheckHostStatus.syslog_test: ERROR: name 'sys' is not defined (0.39 s)
 (241209-162938905847.CHS-13/30) git/iLabConfig/test/avocado/testcases/PathsCheck/PathsCheck.py:PathsCheck.fcp_paths_check: STARTED
 (241209-162938905847.CHS-12/30) git/iLabConfig/test/avocado/testcases/PathsCheck/PathsCheck.py:PathsCheck.fcp_luns_check: STARTED
 (241209-162938905847.CHS-11/30) git/iLabConfig/test/avocado/testcases/CheckHostStatus/CheckHostStatus.py:CheckHostStatus.disk_data_retrieve: STARTED
 (241209-162938905847.CHS-14/30) git/iLabConfig/test/avocado/testcases/PathsCheck/PathsCheck.py:PathsCheck.iscsi_luns_check: STARTED
 (241209-162938905847.CHS-16/30) git/iLabConfig/test/avocado/testcases/PathsCheck/PathsCheck.py:PathsCheck.eckd_luns_check: STARTED
 (241209-162938905847.CHS-15/30) git/iLabConfig/test/avocado/testcases/PathsCheck/PathsCheck.py:PathsCheck.iscsi_paths_check: STARTED
 (241209-162938905847.CHS-17/30) git/iLabConfig/test/avocado/testcases/PathsCheck/PathsCheck.py:PathsCheck.eckd_paths_check: STARTED
 (241209-162938905847.CHS-18/30) git/iLabConfig/test/avocado/testcases/PathsCheck/PathsCheck.py:PathsCheck.fba_luns_check: STARTED
 (241209-162938905847.CHS-19/30) git/iLabConfig/test/avocado/testcases/PathsCheck/PathsCheck.py:PathsCheck.fba_paths_check: STARTED
 (241209-162938905847.CHS-20/30) git/iLabConfig/test/avocado/testcases/CheckHostStatus/CheckHostStatus.py:CheckHostStatus.zvm_userid_check: STARTED
 (241209-162938905847.CHS-11/30) git/iLabConfig/test/avocado/testcases/CheckHostStatus/CheckHostStatus.py:CheckHostStatus.disk_data_retrieve: ERROR: name 'sys' is not defined (0.45 s)
 (241209-162938905847.CHS-20/30) git/iLabConfig/test/avocado/testcases/CheckHostStatus/CheckHostStatus.py:CheckHostStatus.zvm_userid_check: ERROR: name 'sys' is not defined (0.39 s)
 (241209-162938905847.CHS-21/30) git/iLabConfig/test/avocado/testcases/CheckHostStatus/CheckHostStatus.py:CheckHostStatus.zvm_fcp_devices_check: STARTED
 (241209-162938905847.CHS-22/30) git/iLabConfig/test/avocado/testcases/CheckHostStatus/CheckHostStatus.py:CheckHostStatus.zvm_info: STARTED
 (241209-162938905847.CHS-21/30) git/iLabConfig/test/avocado/testcases/CheckHostStatus/CheckHostStatus.py:CheckHostStatus.zvm_fcp_devices_check: ERROR: name 'sys' is not defined (0.25 s)
 (241209-162938905847.CHS-22/30) git/iLabConfig/test/avocado/testcases/CheckHostStatus/CheckHostStatus.py:CheckHostStatus.zvm_info: ERROR: name 'sys' is not defined (0.24 s)
 (241209-162938905847.CHS-23/30) git/iLabConfig/test/avocado/testcases/CheckHostStatus/CheckHostStatus.py:CheckHostStatus.eckd_devices_check: STARTED
 (241209-162938905847.CHS-24/30) git/iLabConfig/test/avocado/testcases/CheckHostStatus/CheckHostStatus.py:CheckHostStatus.fba_devices_check: STARTED
 (241209-162938905847.CHS-23/30) git/iLabConfig/test/avocado/testcases/CheckHostStatus/CheckHostStatus.py:CheckHostStatus.eckd_devices_check: ERROR: name 'sys' is not defined (0.25 s)
 (241209-162938905847.CHS-24/30) git/iLabConfig/test/avocado/testcases/CheckHostStatus/CheckHostStatus.py:CheckHostStatus.fba_devices_check: ERROR: name 'sys' is not defined (0.24 s)
 (241209-162938905847.CHS-25/30) git/iLabConfig/test/avocado/testcases/CheckHostStatus/CheckHostStatus.py:CheckHostStatus.disktest_io_running_check: STARTED
 (241209-162938905847.CHS-26/30) git/iLabConfig/test/avocado/testcases/CheckHostStatus/CheckHostStatus.py:CheckHostStatus.io_devices_check: STARTED
 (241209-162938905847.CHS-16/30) git/iLabConfig/test/avocado/testcases/PathsCheck/PathsCheck.py:PathsCheck.eckd_luns_check: PASS (3.36 s)
 (241209-162938905847.CHS-25/30) git/iLabConfig/test/avocado/testcases/CheckHostStatus/CheckHostStatus.py:CheckHostStatus.disktest_io_running_check: ERROR: name 'sys' is not defined (0.25 s)
 (241209-162938905847.CHS-27/30) git/iLabConfig/test/avocado/testcases/CheckHostStatus/CheckHostStatus.py:CheckHostStatus.syslog_rotate_check: STARTED
 (241209-162938905847.CHS-26/30) git/iLabConfig/test/avocado/testcases/CheckHostStatus/CheckHostStatus.py:CheckHostStatus.io_devices_check: ERROR: name 'sys' is not defined (0.24 s)
 (241209-162938905847.CHS-28/30) git/iLabConfig/test/avocado/testcases/CheckHostStatus/CheckHostStatus.py:CheckHostStatus.udev_rules_check: STARTED
 (241209-162938905847.CHS-29/30) git/iLabConfig/test/avocado/testcases/CheckHostStatus/CheckHostStatus.py:CheckHostStatus.multipath_check: STARTED
 (241209-162938905847.CHS-12/30) git/iLabConfig/test/avocado/testcases/PathsCheck/PathsCheck.py:PathsCheck.fcp_luns_check: PASS (4.28 s)
 (241209-162938905847.CHS-30/30) git/iLabConfig/test/avocado/testcases/CheckHostStatus/CheckHostStatus.py:CheckHostStatus.get_hba_data: STARTED
 (241209-162938905847.CHS-27/30) git/iLabConfig/test/avocado/testcases/CheckHostStatus/CheckHostStatus.py:CheckHostStatus.syslog_rotate_check: ERROR: name 'sys' is not defined (0.26 s)
 (241209-162938905847.CHS-28/30) git/iLabConfig/test/avocado/testcases/CheckHostStatus/CheckHostStatus.py:CheckHostStatus.udev_rules_check: ERROR: name 'sys' is not defined (0.25 s)
 (241209-162938905847.CHS-29/30) git/iLabConfig/test/avocado/testcases/CheckHostStatus/CheckHostStatus.py:CheckHostStatus.multipath_check: ERROR: name 'sys' is not defined (0.25 s)
 (241209-162938905847.CHS-18/30) git/iLabConfig/test/avocado/testcases/PathsCheck/PathsCheck.py:PathsCheck.fba_luns_check: FAIL: FBA LUNs don't match the expected in: ilabg14 (3.46 s)
 (241209-162938905847.CHS-30/30) git/iLabConfig/test/avocado/testcases/CheckHostStatus/CheckHostStatus.py:CheckHostStatus.get_hba_data: ERROR: name 'sys' is not defined (0.25 s)
 (241209-162938905847.CHS-14/30) git/iLabConfig/test/avocado/testcases/PathsCheck/PathsCheck.py:PathsCheck.iscsi_luns_check: PASS (4.68 s)
 (241209-162938905847.CHS-17/30) git/iLabConfig/test/avocado/testcases/PathsCheck/PathsCheck.py:PathsCheck.eckd_paths_check: FAIL: Actual number of paths per lun doesn't match the expected on ilabg14 (10.32 s)
 (241209-162938905847.CHS-15/30) git/iLabConfig/test/avocado/testcases/PathsCheck/PathsCheck.py:PathsCheck.iscsi_paths_check: PASS (9.83 s)
 (241209-162938905847.CHS-19/30) git/iLabConfig/test/avocado/testcases/PathsCheck/PathsCheck.py:PathsCheck.fba_paths_check: FAIL: FBA LUNs Paths don't match the expected in: ilabg14 (19.66 s)
 (241209-162938905847.CHS-13/30) git/iLabConfig/test/avocado/testcases/PathsCheck/PathsCheck.py:PathsCheck.fcp_paths_check: PASS (28.25 s)
RESULTS    : PASS 5 | ERROR 22 | FAIL 3 | SKIP 0 | WARN 0 | INTERRUPT 0 | CANCEL 0
JOB TIME   : 32.97 s

The test that I'm running is avocado instrumented:

progress_log = logging.getLogger("avocado.test.progress")
progress_log.info("TEST TEST TEST TEST")

Do I missing something else that should be done to get it printing to the terminal?

I reported something similar in the pass and a fix was reported as implemented but looks like we still have a problem using the API.

Old ticket -> #5626

Answered by richtja

May 2, 2025

Hi @marioaag, sorry for the late reply, I missed this question. Can you please provide more info about how you create the runnables, because I am not able to reproduce this behaviour? This is what I did:

Test file:

import logging
from avocado import Test


class PassTest(Test):
    """
    Example test that passes.

    :avocado: tags=fast
    """

    def test(self):
        """
        A test simply doesn't have to fail in order to pass
        """
        progress_log = logging.getLogger("avocado.test.progress")
        progress_log.info("TEST TEST TEST TEST")

Command run

$ avocado --show=app,avocado.test.progress run examples/tests/passtest.py
JOB ID     : b501f708207e4d8b9c0f913cad…

View full answer

marioaag · 2025-05-01T01:01:23Z

marioaag
May 1, 2025
Author

@richtja, could you take a look to this one? it is something that looks like didn't get resolved as expected with the latest logger changes

0 replies

richtja · 2025-05-02T07:59:03Z

richtja
May 2, 2025
Maintainer

Hi @marioaag, sorry for the late reply, I missed this question. Can you please provide more info about how you create the runnables, because I am not able to reproduce this behaviour? This is what I did:

Test file:

import logging
from avocado import Test


class PassTest(Test):
    """
    Example test that passes.

    :avocado: tags=fast
    """

    def test(self):
        """
        A test simply doesn't have to fail in order to pass
        """
        progress_log = logging.getLogger("avocado.test.progress")
        progress_log.info("TEST TEST TEST TEST")

Command run

$ avocado --show=app,avocado.test.progress run examples/tests/passtest.py
JOB ID     : b501f708207e4d8b9c0f913cad83bbce237e06bd
JOB LOG    : /home/janrichter/avocado/job-results/job-2025-05-02T09.44-b501f70/job.log
 (1/1) examples/tests/passtest.py:PassTest.test: STARTED
avocado.test.progress: 1-examples/tests/passtest.py:PassTest.test: 2025-05-02 09:44:46,147 avocado.test.progress passtest         L0017 INFO | TEST TEST TEST TEST
 (1/1) examples/tests/passtest.py:PassTest.test: PASS (0.01 s)
RESULTS    : PASS 1 | ERROR 0 | FAIL 0 | SKIP 0 | WARN 0 | INTERRUPT 0 | CANCEL 0
JOB HTML   : /home/janrichter/avocado/job-results/job-2025-05-02T09.44-b501f70/results.html
JOB TIME   : 1.47 s

Job API script

#!/usr/bin/env python3

from avocado.core.job import Job
from avocado.core.suite import TestSuite
from avocado.core.nrunner.runnable import Runnable

JOB_CONFIG = {'core.show': {'app', 'avocado.test.progress'},"resolver.references": ["examples/tests/passtest.py:PassTest.test"],}

suite = TestSuite.from_config(JOB_CONFIG)
with Job(JOB_CONFIG, test_suites=[suite]) as job:
    result = job.run()

Job API script output

python ../testing/test_job.py
JOB ID     : 77627465dc9927636dc5228aef41dac4066fbfa3
JOB LOG    : /home/janrichter/avocado/job-results/job-2025-05-02T09.48-7762746/job.log
 (6bbceacc-e7aa-484d-b756-5ca0dadfcdf6-1/1) examples/tests/passtest.py:PassTest.test: STARTED
avocado.test.progress: 6bbceacc-e7aa-484d-b756-5ca0dadfcdf6-1-examples/tests/passtest.py:PassTest.test: 2025-05-02 09:48:40,484 avocado.test.progress passtest         L0017 INFO | TEST TEST TEST TEST
 (6bbceacc-e7aa-484d-b756-5ca0dadfcdf6-1/1) examples/tests/passtest.py:PassTest.test: PASS (0.01 s)
RESULTS    : PASS 1 | ERROR 0 | FAIL 0 | SKIP 0 | WARN 0 | INTERRUPT 0 | CANCEL 0
JOB HTML   : /home/janrichter/avocado/job-results/job-2025-05-02T09.48-7762746/results.html
JOB TIME   : 1.39 s

Job API script with Runnable

#!/usr/bin/env python3

from avocado.core.job import Job
from avocado.core.suite import TestSuite
from avocado.core.nrunner.runnable import Runnable

JOB_CONFIG = {'core.show': {'app', 'avocado.test.progress'}}

suite = TestSuite(name="suite", tests=[Runnable("avocado-instrumented", "examples/tests/passtest.py:PassTest.test", config=JOB_CONFIG)], config=JOB_CONFIG)
with Job(JOB_CONFIG, test_suites=[suite]) as job:
    result = job.run()

Job API script with Runnable output

 python ../testing/test_job.py
JOB ID     : c8cdbca47b82c488658533be0366d5f0c5e75b87
JOB LOG    : /home/janrichter/avocado/job-results/job-2025-05-02T09.56-c8cdbca/job.log
 (suite-1/1) examples/tests/passtest.py:PassTest.test: STARTED
avocado.test.progress: suite-1-examples/tests/passtest.py:PassTest.test: 2025-05-02 09:56:37,057 avocado.test.progress passtest         L0017 INFO | TEST TEST TEST TEST
 (suite-1/1) examples/tests/passtest.py:PassTest.test: PASS (0.01 s)
RESULTS    : PASS 1 | ERROR 0 | FAIL 0 | SKIP 0 | WARN 0 | INTERRUPT 0 | CANCEL 0
JOB HTML   : /home/janrichter/avocado/job-results/job-2025-05-02T09.56-c8cdbca/results.html
JOB TIME   : 1.41 s

0 replies

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

avocado.test.progress logging stream setup via API #6080

Uh oh!

{{title}}

Uh oh!

Uh oh!

{{editor}}'s edit

{{editor}}'s edit

Uh oh!

Replies: 2 comments

Uh oh!

{{title}}

Uh oh!

Uh oh!

{{title}}

Uh oh!

Select a reply

Uh oh!

avocado.test.progress logging stream setup via API #6080

Uh oh!

Uh oh!

marioaag Dec 9, 2024

Replies: 2 comments

Uh oh!

marioaag May 1, 2025 Author

Uh oh!

richtja May 2, 2025 Maintainer

marioaag
Dec 9, 2024

marioaag
May 1, 2025
Author

richtja
May 2, 2025
Maintainer