Mayil-AI-Sandbox / loguru-Jan2023

MIT License
0 stars 0 forks source link

How can I get live logs with loguru and pytest? (hashtag611) #104

Closed vikramsubramanian closed 3 weeks ago

vikramsubramanian commented 3 weeks ago

I have tried many of the options like --log-cli-level, --log-level but I'm not able to run my tests seeing the output of the logs live.

vikramsubramanian commented 3 weeks ago

You should try with the --capture=no option.

vikramsubramanian commented 3 weeks ago

You should try with the --capture=no option.

Just tested it, but still does not work, this is the only output:

============================= test session starts =============================
platform win32 -- Python 3.10.1, pytest-6.2.5, py-1.11.0, pluggy-1.0.0 -- C:\xxxxxxxxxxxxxx\.venv\Scripts\python.exe
cachedir: .pytest_cache
metadata: {'Python': '3.10.1', 'Platform': 'Windows-10-10.0.19044-SP0', 'Packages': {'pytest': '6.2.5', 'py': '1.11.0', 'pluggy': '1.0.0'}, 'Plugins': {'html': '3.1.1', 'metadata': '1.11.0'}, 'JAVA_HOME': 'C:\\Program Files\\Java\\jre1.8.0_211'}
rootdir: XXXXXXXXXXXXXXXXXXXX, configfile: pytest.ini
plugins: html-3.1.1, metadata-1.11.0
collecting ... collected 3 items
vikramsubramanian commented 3 weeks ago

Can you please provide a reproducible example? It works fine when I test it.

vikramsubramanian commented 3 weeks ago

Can you please provide a reproducible example? It works fine when I test it.

Yes, I just prepared it: test.py:

"""
Test loguru error
"""
from loguru import logger
from subprocess import Popen, PIPE

def main():
    """
    Execute the tests
    """
    pytest_args = []

    report_path='./report.html'

    pytest_args.append(f'--html={report_path}')
    pytest_args.append(f'--self-contained-html')
    pytest_args.append(f'--capture=no')
    pytest_args.append('./t/')

    hashtag _retcode = pytest.main(pytest_args)

    with Popen(['pytest',
            *pytest_args,
            str(__file__)], shell=True, stdout=PIPE, stderr=PIPE, bufsize=1, close_fds=True,
            encoding='utf8',
            universal_newlines=True) as p:
        for line in p.stdout:
            print(line, end='') 

    logger.info('Tests finished')

if __name__ == '__main__':
    main()

t/my_test.py:

import time
from loguru import logger

def test_loguru(my_value):
    """
    test
    """
    logger.info(f'Testing value {my_value}...')
    logger.info(f'Testing value {my_value}...')
    logger.info(f'Testing value {my_value}...')
    time.sleep(5)
    assert my_value <= 4, "Test value."

conftest.py:


from loguru import logger
import pytest
from _pytest.logging import LogCaptureFixture

def caplog(caplog: LogCaptureFixture):
    """
    Make pytest work with loguru. See:

    """
    handler_id = logger.add(caplog.handler, format="{message}")
    yield caplog
    logger.remove(handler_id)

def my_value():
    """
    Some random value
    """
    return 5

requirements.txt

loguru==0.6.0
pylint==2.12.2
pytest==6.2.5
pytest-html==3.1.1
selenium==4.1.0

Output:

============================= test session starts =============================
platform win32 -- Python 3.10.1, pytest-6.2.5, py-1.11.0, pluggy-1.0.0
rootdir: C:\Users\HMG28\Desktop\delete_me_2
plugins: html-3.1.1, metadata-1.11.0
collected 1 item

t\my_test.py F

================================== FAILURES ===================================
_________________________________ test_loguru _________________________________

my_value = 5

    def test_loguru(my_value):
        """
        test
        """
        logger.info(f'Testing value {my_value}...')
        logger.info(f'Testing value {my_value}...')
        logger.info(f'Testing value {my_value}...')
        time.sleep(5)
>       assert my_value <= 4, "Test value."
E       AssertionError: Test value.
E       assert 5 <= 4

t\my_test.py:13: AssertionError
- generated html file: file://C:\Users\HMG28\Desktop\delete_me_2\report.html --
=========================== short test summary info ===========================
FAILED t/my_test.py::test_loguru - AssertionError: Test value.
============================== 1 failed in 5.13s ==============================
2022-03-04 18:44:33.605 | INFO     | __main__:main:39 - Tests finished
vikramsubramanian commented 3 weeks ago

Thanks for the snippets. How are you running the tests? If work fine for me both when using pytest or python test.py.

============================= test session starts ==============================
platform linux -- Python 3.10.2, pytest-6.2.5, py-1.11.0, pluggy-1.0.0
rootdir: /home/delgan/Programmation/loguru, configfile: tox.ini
plugins: freezegun-0.4.2, cov-3.0.0
collected 1 item

my_test.py F                                                             [100%]

=================================== FAILURES ===================================
_________________________________ test_loguru __________________________________

my_value = 5

    def test_loguru(my_value):
        """
        test
        """
        logger.info(f'Testing value {my_value}...')
        logger.info(f'Testing value {my_value}...')
        logger.info(f'Testing value {my_value}...')
        time.sleep(5)
>       assert my_value <= 4, "Test value."
E       AssertionError: Test value.
E       assert 5 <= 4

my_value   = 5

my_test.py:13: AssertionError
----------------------------- Captured stderr call -----------------------------
2022-03-04 22:07:39.685 | INFO     | my_test:test_loguru:9 - Testing value 5...
2022-03-04 22:07:39.685 | INFO     | my_test:test_loguru:10 - Testing value 5...
2022-03-04 22:07:39.685 | INFO     | my_test:test_loguru:11 - Testing value 5...
=========================== short test summary info ============================
FAILED my_test.py::test_loguru - AssertionError: Test value.
============================== 1 failed in 5.10s ===============================
2022-03-04 22:07:44.853 | INFO     | __main__:main:31 - Tests finished

This is maybe a problem specific to Windows.

vikramsubramanian commented 3 weeks ago

Hi, I'm running it with python test.py. I think your output is also not working, I'd expect to see after the line collected 1 item the 3 logger.info messages, as there is a delay of 5 seconds after them.

They do not appear live but at the end of the script when it has finished.

vikramsubramanian commented 3 weeks ago

These 3 lines are logged from within an external Process so there is no way to display them in live because they are redirected to the configured PIPE and later displayed with the for line in p.stdout loop.

vikramsubramanian commented 3 weeks ago

These 3 lines are logged from within an external Process so there is no way to display them in live because they are redirected to the configured PIPE and later displayed with the for line in p.stdout loop.

Thank you, but I don't understand why the rest of the lines are printed live, for example:

============================= test session starts ==============================
platform linux -- Python 3.10.2, pytest-6.2.5, py-1.11.0, pluggy-1.0.0
rootdir: /home/delgan/Programmation/loguru, configfile: tox.ini
plugins: freezegun-0.4.2, cov-3.0.0
collected 1 item

Then here the lines are not printed, and it continues until the subprocess finishes:


my_test.py F                                                             [100%]

=================================== FAILURES ===================================
_________________________________ test_loguru __________________________________

my_value = 5

    def test_loguru(my_value):
        """
        test
        """
        logger.info(f'Testing value {my_value}...')
        logger.info(f'Testing value {my_value}...')
        logger.info(f'Testing value {my_value}...')
        time.sleep(5)
>       assert my_value <= 4, "Test value."
E       AssertionError: Test value.
E       assert 5 <= 4

my_value   = 5

my_test.py:13: AssertionError
----------------------------- Captured stderr call -----------------------------
2022-03-04 22:07:39.685 | INFO     | my_test:test_loguru:9 - Testing value 5...
2022-03-04 22:07:39.685 | INFO     | my_test:test_loguru:10 - Testing value 5...
2022-03-04 22:07:39.685 | INFO     | my_test:test_loguru:11 - Testing value 5...
=========================== short test summary info ============================
FAILED my_test.py::test_loguru - AssertionError: Test value.
============================== 1 failed in 5.10s ===============================
2022-03-04 22:07:44.853 | INFO     | __main__:main:31 - Tests finished

Why is the rest of the lines of pytest printed but not the ones from loguru in the subprocess?

vikramsubramanian commented 3 weeks ago

One thing is that Loguru will be default write logs to stderr and not to stdout. This is one reason for which it's not appearing in live, I guess.

I also noticed that I had to set shell=False if you want Pytest not to capture the stderr output, but I don't know why. :confused:

vikramsubramanian commented 3 weeks ago

One thing is that Loguru will be default write logs to stderr and not to stdout. This is one reason for which it's not appearing in live, I guess.

I also noticed that I had to set shell=False if you want Pytest not to capture the stderr output, but I don't know why. 😕

I am using loguru, the output content is not utf8 encoded ![1648903144(1)](

vikramsubramanian commented 3 weeks ago

The encoding depends of the sink encoding. It might be a problem related to your terminal or pytest.

See also: [Resolving UnicodeEncodeError and other encoding issues](

vikramsubramanian commented 3 weeks ago

I'm closing this ticket as I guess it's solved.

vikramsubramanian commented 3 weeks ago

You should try with the --capture=no option.

I had a problem with loguru live logs when using PyCharm's test runner. Adding --capture=no in Additional Arguments of the runner configuration solved the problem.