RDFLib / pySHACL

A Python validator for SHACL
Apache License 2.0
249 stars 63 forks source link

validate in pyshacl>0.26.0 breaks logging #271

Open frank-fzi opened 3 hours ago

frank-fzi commented 3 hours ago

In pySHACL 0.26.0, handlers are removed from pyshacl logger only:

https://github.com/RDFLib/pySHACL/blob/8420fcb8713471e62ada554c8a69a5dae31ee943/pyshacl/validate.py#L55

Starting from pySHACL 0.27.0, the root logger is returned and all handlers are removed:

https://github.com/RDFLib/pySHACL/blob/f7c47a2bb3e4df788a01360e969f81602c469a05/pyshacl/entrypoints.py#L232

This breaks any logging outside pyshacl.

Steps to reproduce:

import logging

from pyshacl import validate
from rdflib import Graph

BEFORE_VALIDATE = "before validate"
AFTER_VALIDATE = "after validate"

def test_validate(caplog):
    logger = logging.getLogger("test_validate")
    logger.setLevel(logging.INFO)
    logger.info(BEFORE_VALIDATE)
    validate(Graph())
    logger.info(AFTER_VALIDATE)

    assert BEFORE_VALIDATE in caplog.messages
    assert AFTER_VALIDATE in caplog.messages

With pyshacl 0.26.0, both log messages are contained in caplog.messages and the test is successful. Starting from pyshacl 0.27.0, only the first message is contained in caplog.messages and assert AFTER_VALIDATE in caplog.messages fails.

ashleysommer commented 2 hours ago

@frank-fzi Thanks for pointing that out.

That small change was made while refactoring the PySHACL runner configurations. I remember making that change to switch from __main__ to "root" logger, but I don't remember the reasoning behind why I made the change, and it is not mentioned in the changelog.

This will be why my test suite logging has not been working too.

I believe it will be relatively simple to fix, by either switching back to using the __main__ file logger, or by moving to a "pyshacl" named logger.

ashleysommer commented 2 hours ago

Update: Actually, just looking at the code, I see this is a bug. The new make_default_logger helper that was introduced in v0.27.0 is supposed to create the logger using the given name variable. However due to a copy/paste error and a testing oversight, this was not implemented correctly. Its odd that the ruff linter did not complain about an unused variable in the function signature.

I will release a quick v0.28.1 update with this fix.

ashleysommer commented 1 hour ago

@frank-fzi I've just pushed out v0.28.1, can you please test it and let me know if it resolves this issue for you.

frank-fzi commented 1 hour ago

Hi @ashleysommer, I've just tested with v0.28.1 and the logging which was broken since v0.27.0 now works again as expected 🎉

Thanks a lot for the very quick fix 🚀