Bug: QueueListener doesn't work

[Goldziher]

Hi there,

The the QueueListener doesn't work as expected. I added a PR with a failing test to illustrate this #89 .

[aminalaee]

I might be wrong but I think this test doesn't work with standard logging module either:

logger = Logger("test", INFO)
stream = io.StringIO()
stream_handler = StreamHandler(stream)
q = queue.Queue()
listener = handlers.QueueListener(q, stream_handler)
listener.start()
handler = handlers.QueueHandler(q)
logger.addHandler(handler)


@pytest.mark.xfail(reason="https://github.com/microsoft/picologging/issues/90")
def test_queue_listener_handler(caplog: Any) -> None:
    with caplog.at_level("INFO"):
        logger.info("Testing now!")
        assert "Testing now!" in caplog.text

First I think you are checking the caplog in the end, but nothing is sent to the standard output to be captured, you should check the stream.getvalue() instead:

assert "Testing now!" == stream.getvalue()

And another issue is the timing, which I think the assert is checked before the QueueListener thread can dequeue. If you add a delay between the assert it works fine. Or you can do listener.stop() to stop the thread and process records in queue.

There's a similar test, so modifying your test works ok:

logger = Logger("test", INFO)
stream = io.StringIO()
stream_handler = StreamHandler(stream)
q = queue.Queue()
listener = handlers.QueueListener(q, stream_handler)
listener.start()
handler = handlers.QueueHandler(q)
logger.addHandler(handler)


@pytest.mark.xfail(reason="https://github.com/microsoft/picologging/issues/90")
def test_queue_listener_handler() -> None:
    logger.info("Testing now!")
    listener.stop()
    assert "Testing now!" in stream.getvalue()

[Goldziher]

I might be wrong but I think this test doesn't work with standard logging module either:

logger = Logger("test", INFO)
stream = io.StringIO()
stream_handler = StreamHandler(stream)
q = queue.Queue()
listener = handlers.QueueListener(q, stream_handler)
listener.start()
handler = handlers.QueueHandler(q)
logger.addHandler(handler)


@pytest.mark.xfail(reason="https://github.com/microsoft/picologging/issues/90")
def test_queue_listener_handler(caplog: Any) -> None:
    with caplog.at_level("INFO"):
        logger.info("Testing now!")
        assert "Testing now!" in caplog.text

First I think you are checking the caplog in the end, but nothing is sent to the standard output to be captured, you should check the stream.getvalue() instead:

assert "Testing now!" == stream.getvalue()

And another issue is the timing, which I think the assert is checked before the QueueListener thread can dequeue. If you add a delay between the assert it works fine. Or you can do listener.stop() to stop the thread and process records in queue.

There's a similar test, so modifying your test works ok:

logger = Logger("test", INFO)
stream = io.StringIO()
stream_handler = StreamHandler(stream)
q = queue.Queue()
listener = handlers.QueueListener(q, stream_handler)
listener.start()
handler = handlers.QueueHandler(q)
logger.addHandler(handler)


@pytest.mark.xfail(reason="https://github.com/microsoft/picologging/issues/90")
def test_queue_listener_handler() -> None:
    logger.info("Testing now!")
    listener.stop()
    assert "Testing now!" in stream.getvalue()

You're wrong I'm afraid.

See this test and the one immediately below it with xfail in starlite:

https://github.com/starlite-api/starlite/blob/main/tests/logging_config/test_logging_config.py#L76

[pamelafox]

I am checking this out on my machine (Python 3.10, picologging @ HEAD).

When I run the proposed test_queue_listener_handler test for picologging, it fails.
However, it also fails if I change all the imports to the standard logging module.

I also ran the same code in Python console and saw ‘Testing now!’ In stream.getvalue() but not in standard out.

>>> import io
>>> import queue
>>> from logging import INFO, Logger, StreamHandler, handlers
>>> 
>>> logger = Logger("test", INFO)
>>> stream = io.StringIO()
>>> stream_handler = StreamHandler(stream)
>>> q = queue.Queue()
>>> listener = handlers.QueueListener(q, stream_handler)
>>> listener.start()
>>> handler = handlers.QueueHandler(q)
>>> logger.addHandler(handler)
>>> logger.info('Testing now!')
>>> 
>>> stream.getvalue()
'Testing now!\n'

@Goldziher, does the test_queue_listener_handler test pass for you with the logging module on your system?

I see the referenced Starlite test, but I think something must be a bit different about that setup, since that seems to show a test which passes with logging but fails with picologging.

[Goldziher]

Thanks for checking.

I'll update the tests with a full reproduction mirroring starlite after work today.

[Goldziher]

ok @pamelafox @aminalaee - please see my PR - i updated it with an implementation similar to starlite's, which i think conclusively demonstrates that there is indeed an issue.

[aminalaee]

@Goldziher Since I involved myself in the conversation(!) I should comment, I think the starlite test you added makes more sense now.
With the previous test as I said you could use stream.getvalue() instead of caplog and it would work.

But with the new test I see your usage probably doesn't allow it. My guess is that the pytest caplog doesn't work with picologging but works with logging. I ran your tests and the queue is emptied and everything works as expected on picologging side, it's only that caplog can't capture the logs. Maybe a new fixture/plugin is needed for picologging like: https://github.com/pytest-dev/pytest/blob/59b8ec3ce11f8e94d924dc97bc1e14f380824b54/src/_pytest/logging.py#L537

So I think it's a limitation of caplog rather than a bug with QueuListener.

[Goldziher]

Thanks for checking @aminalaee. I suspected as much as well. Either way, its an issue - although not the same issue.

[tonybaloney]

Is this now fixed in 0.9.0? Since #122 was merged

[pamelafox]

I personally believe that the underlying issues found from that test have now been fixed. A higher-level issue is that pytest caplog doesn't work with picologging, and that's filed as #125, but I don't think we need this additional test since I added a simplified version in the recent PR. @Goldziher, do you agree?

[Goldziher]

I personally believe that the underlying issues found from that test have now been fixed. A higher-level issue is that pytest caplog doesn't work with picologging, and that's filed as #125, but I don't think we need this additional test since I added a simplified version in the recent PR. @Goldziher, do you agree?

Sure