1

I have a python project where I use pytest for my unit testing.

Normally if I run the following command from my test folder:

pytest --collect-only

I will get all my tests:

...
40 tests collected
...

Now let's say I define a new class structlogconf.py (Based on this example)

import logging
import logging.config
import structlog


def configure() -> None:
    timestamper = structlog.processors.TimeStamper(fmt="%Y-%m-%d %H:%M:%S")
    pre_chain = [
        # Add the log level and a timestamp to the event_dict if the log entry
        # is not from structlog.
        structlog.stdlib.add_log_level,
        timestamper,
    ]

    logging.config.dictConfig(
        {
            "version": 1,
            "disable_existing_loggers": False,
            "formatters": {
                "plain": {
                    "()": structlog.stdlib.ProcessorFormatter,
                    "processor": structlog.dev.ConsoleRenderer(colors=False),
                    "foreign_pre_chain": pre_chain,
                },
                "colored": {
                    "()": structlog.stdlib.ProcessorFormatter,
                    "processor": structlog.dev.ConsoleRenderer(colors=True),
                    "foreign_pre_chain": pre_chain,
                },
            },
            "handlers": {
                "default": {
                    "level": "DEBUG",
                    "class": "logging.StreamHandler",
                    "formatter": "colored",
                },
                "file": {
                    "level": "DEBUG",
                    "class": "logging.handlers.WatchedFileHandler",
                    "filename": "test.log",
                    "formatter": "plain",
                },
            },
            "loggers": {
                "": {
                    "handlers": ["default", "file"],
                    "level": "DEBUG",
                    "propagate": True,
                },
            },
        }
    )
    structlog.configure(
        processors=[
            structlog.stdlib.add_log_level,
            structlog.stdlib.PositionalArgumentsFormatter(),
            timestamper,
            structlog.processors.StackInfoRenderer(),
            structlog.processors.format_exc_info,
            structlog.stdlib.ProcessorFormatter.wrap_for_formatter,
        ],
        logger_factory=structlog.stdlib.LoggerFactory(),
        wrapper_class=structlog.stdlib.BoundLogger,
        cache_logger_on_first_use=True,
    )

If now I run the pytest collect command again, pytest will not recover any test suite which import directly or indirectly the configure() function from the structlogconf.py. So I now obtain someting like:

...
5 tests collected
...

Is there anyone here which know how to use a struct log conf in a way that won't affect my pytest tests dicscovery?

FYI: Here is the stacktrace when running the collect in the problematic scenario:

... 
my remaining 5 tests which does not indirectly import my configure() function are showing here
...
================================================================== 5 tests collected in 1.03s ===================================================================
Traceback (most recent call last):
  File "C:\Users\MY_USER\.conda\envs\MY_ENV\lib\site-packages\_pytest\main.py", line 269, in wrap_session
    session.exitstatus = doit(config, session) or 0
  File "C:\Users\MY_USER\.conda\envs\MY_ENV\lib\site-packages\_pytest\main.py", line 322, in _main
    config.hook.pytest_collection(session=session)
  File "C:\Users\MY_USER\.conda\envs\MY_ENV\lib\site-packages\pluggy\_hooks.py", line 265, in __call__
    return self._hookexec(self.name, self.get_hookimpls(), kwargs, firstresult)
  File "C:\Users\MY_USER\.conda\envs\MY_ENV\lib\site-packages\pluggy\_manager.py", line 80, in _hookexec
    return self._inner_hookexec(hook_name, methods, kwargs, firstresult)
  File "C:\Users\MY_USER\.conda\envs\MY_ENV\lib\site-packages\pluggy\_callers.py", line 60, in _multicall
    return outcome.get_result()
  File "C:\Users\MY_USER\.conda\envs\MY_ENV\lib\site-packages\pluggy\_result.py", line 60, in get_result
    raise ex[1].with_traceback(ex[2])
  File "C:\Users\MY_USER\.conda\envs\MY_ENV\lib\site-packages\pluggy\_callers.py", line 39, in _multicall
    res = hook_impl.function(*args)
  File "C:\Users\MY_USER\.conda\envs\MY_ENV\lib\site-packages\_pytest\main.py", line 333, in pytest_collection
    session.perform_collect()
  File "C:\Users\MY_USER\.conda\envs\MY_ENV\lib\site-packages\_pytest\main.py", line 634, in perform_collect
    self.items.extend(self.genitems(node))
  File "C:\Users\MY_USER\.conda\envs\MY_ENV\lib\site-packages\_pytest\main.py", line 811, in genitems
    yield from self.genitems(subnode)
  File "C:\Users\MY_USER\.conda\envs\MY_ENV\lib\site-packages\_pytest\main.py", line 808, in genitems
    rep = collect_one_node(node)
  File "C:\Users\MY_USER\.conda\envs\MY_ENV\lib\site-packages\_pytest\runner.py", line 458, in collect_one_node
    rep: CollectReport = ihook.pytest_make_collect_report(collector=collector)
  File "C:\Users\MY_USER\.conda\envs\MY_ENV\lib\site-packages\pluggy\_hooks.py", line 265, in __call__
    return self._hookexec(self.name, self.get_hookimpls(), kwargs, firstresult)
  File "C:\Users\MY_USER\.conda\envs\MY_ENV\lib\site-packages\pluggy\_manager.py", line 80, in _hookexec
    return self._inner_hookexec(hook_name, methods, kwargs, firstresult)
  File "C:\Users\MY_USER\.conda\envs\MY_ENV\lib\site-packages\pluggy\_callers.py", line 55, in _multicall
    gen.send(outcome)
  File "C:\Users\MY_USER\.conda\envs\MY_ENV\lib\site-packages\_pytest\capture.py", line 796, in pytest_make_collect_report
    out, err = self.read_global_capture()
  File "C:\Users\MY_USER\.conda\envs\MY_ENV\lib\site-packages\_pytest\capture.py", line 718, in read_global_capture
    return self._global_capturing.readouterr()
  File "C:\Users\MY_USER\.conda\envs\MY_ENV\lib\site-packages\_pytest\capture.py", line 622, in readouterr
    err = self.err.snap()
  File "C:\Users\MY_USER\.conda\envs\MY_ENV\lib\site-packages\_pytest\capture.py", line 479, in snap
    self.tmpfile.seek(0)
ValueError: I/O operation on closed file.

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "C:\Users\MY_USER\.conda\envs\MY_ENV\lib\site-packages\_pytest\main.py", line 289, in wrap_session
    config.notify_exception(excinfo, config.option)
  File "C:\Users\MY_USER\.conda\envs\MY_ENV\lib\site-packages\_pytest\config\__init__.py", line 1037, in notify_exception
    res = self.hook.pytest_internalerror(excrepr=excrepr, excinfo=excinfo)
  File "C:\Users\MY_USER\.conda\envs\MY_ENV\lib\site-packages\pluggy\_hooks.py", line 265, in __call__
    return self._hookexec(self.name, self.get_hookimpls(), kwargs, firstresult)
  File "C:\Users\MY_USER\.conda\envs\MY_ENV\lib\site-packages\pluggy\_manager.py", line 80, in _hookexec
    return self._inner_hookexec(hook_name, methods, kwargs, firstresult)
  File "C:\Users\MY_USER\.conda\envs\MY_ENV\lib\site-packages\pluggy\_callers.py", line 60, in _multicall
    return outcome.get_result()
  File "C:\Users\MY_USER\.conda\envs\MY_ENV\lib\site-packages\pluggy\_result.py", line 60, in get_result
    raise ex[1].with_traceback(ex[2])
  File "C:\Users\MY_USER\.conda\envs\MY_ENV\lib\site-packages\pluggy\_callers.py", line 39, in _multicall
    res = hook_impl.function(*args)
  File "C:\Users\MY_USER\.conda\envs\MY_ENV\lib\site-packages\_pytest\capture.py", line 826, in pytest_internalerror
    self.stop_global_capturing()
  File "C:\Users\MY_USER\.conda\envs\MY_ENV\lib\site-packages\_pytest\capture.py", line 693, in stop_global_capturing
    self._global_capturing.pop_outerr_to_orig()
  File "C:\Users\MY_USER\.conda\envs\MY_ENV\lib\site-packages\_pytest\capture.py", line 573, in pop_outerr_to_orig
    out, err = self.readouterr()
  File "C:\Users\MY_USER\.conda\envs\MY_ENV\lib\site-packages\_pytest\capture.py", line 622, in readouterr
    err = self.err.snap()
  File "C:\Users\MY_USER\.conda\envs\MY_ENV\lib\site-packages\_pytest\capture.py", line 479, in snap
    self.tmpfile.seek(0)
ValueError: I/O operation on closed file.

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "C:\Users\MY_USER\.conda\envs\MY_ENV\lib\runpy.py", line 194, in _run_module_as_main
    return _run_code(code, main_globals, None,
  File "C:\Users\MY_USER\.conda\envs\MY_ENV\lib\runpy.py", line 87, in _run_code
    exec(code, run_globals)
  File "C:\Users\MY_USER\.conda\envs\MY_ENV\Scripts\pytest.exe\__main__.py", line 7, in <module>
  File "C:\Users\MY_USER\.conda\envs\MY_ENV\lib\site-packages\_pytest\config\__init__.py", line 185, in console_main
    code = main()
  File "C:\Users\MY_USER\.conda\envs\MY_ENV\lib\site-packages\_pytest\config\__init__.py", line 162, in main
    ret: Union[ExitCode, int] = config.hook.pytest_cmdline_main(
  File "C:\Users\MY_USER\.conda\envs\MY_ENV\lib\site-packages\pluggy\_hooks.py", line 265, in __call__
    return self._hookexec(self.name, self.get_hookimpls(), kwargs, firstresult)
  File "C:\Users\MY_USER\.conda\envs\MY_ENV\lib\site-packages\pluggy\_manager.py", line 80, in _hookexec
    return self._inner_hookexec(hook_name, methods, kwargs, firstresult)
  File "C:\Users\MY_USER\.conda\envs\MY_ENV\lib\site-packages\pluggy\_callers.py", line 60, in _multicall
    return outcome.get_result()
  File "C:\Users\MY_USER\.conda\envs\MY_ENV\lib\site-packages\pluggy\_result.py", line 60, in get_result
    raise ex[1].with_traceback(ex[2])
  File "C:\Users\MY_USER\.conda\envs\MY_ENV\lib\site-packages\pluggy\_callers.py", line 39, in _multicall
    res = hook_impl.function(*args)
  File "C:\Users\MY_USER\.conda\envs\MY_ENV\lib\site-packages\_pytest\main.py", line 316, in pytest_cmdline_main
    return wrap_session(config, _main)
  File "C:\Users\MY_USER\.conda\envs\MY_ENV\lib\site-packages\_pytest\main.py", line 311, in wrap_session
    config._ensure_unconfigure()
  File "C:\Users\MY_USER\.conda\envs\MY_ENV\lib\site-packages\_pytest\config\__init__.py", line 991, in _ensure_unconfigure
    fin()
  File "C:\Users\MY_USER\.conda\envs\MY_ENV\lib\site-packages\_pytest\capture.py", line 693, in stop_global_capturing
    self._global_capturing.pop_outerr_to_orig()
  File "C:\Users\MY_USER\.conda\envs\MY_ENV\lib\site-packages\_pytest\capture.py", line 573, in pop_outerr_to_orig
    out, err = self.readouterr()
  File "C:\Users\MY_USER\.conda\envs\MY_ENV\lib\site-packages\_pytest\capture.py", line 622, in readouterr
    err = self.err.snap()
  File "C:\Users\MY_USER\.conda\envs\MY_ENV\lib\site-packages\_pytest\capture.py", line 479, in snap
    self.tmpfile.seek(0)
ValueError: I/O operation on closed file.
Greg7000
  • 297
  • 3
  • 15
  • When you collect tests are you still in the same directory? – ujlbu4 Nov 23 '21 at 22:17
  • 1
    structlog does absolutely nothing that should affect pytest in any way. We'll need more details on what exactly you're doing there. Is pytest raising any errors or warnings? How are you calling the configure function? If you keep calling it but remove the structlog calls, does it start working? – hynek Nov 24 '21 at 11:36
  • ujlbu4, I am still in the same directory. – Greg7000 Nov 24 '21 at 13:59
  • hynek, I added the pytest stacktrace following the collect command. The configure() is called from let's say module A and module A is undertest in my pytest. When I comment code related to the configure(), everything works again. – Greg7000 Nov 24 '21 at 14:19

1 Answers1

1

This ain't the best solution but after trying to comment various sections from the configuration. I found out the issue originated from the "colored" section which is not critical for usability:

import logging
import logging.config
import structlog

def configure() -> None:
    timestamper = structlog.processors.TimeStamper(fmt="%Y-%m-%d %H:%M:%S")
    pre_chain = [
        # Add the log level and a timestamp to the event_dict if the log entry
        # is not from structlog.
        structlog.stdlib.add_log_level,
        timestamper,
    ]

    logging.config.dictConfig(
        {
            "version": 1,
            "disable_existing_loggers": False,
            "formatters": {
                "plain": {
                    "()": structlog.stdlib.ProcessorFormatter,
                    "processor": structlog.dev.ConsoleRenderer(colors=False),
                    "foreign_pre_chain": pre_chain,
                },
                # "colored": {
                #     "()": structlog.stdlib.ProcessorFormatter,
                #     "processor": structlog.dev.ConsoleRenderer(colors=True),
                #     "foreign_pre_chain": pre_chain,
                # },
            },
            "handlers": {
                "default": {
                    "level": "ERROR",
                    "class": "logging.StreamHandler",
                    "formatter": "plain", #               <---Change to "plain"
                },
                "file": {
                    "level": "ERROR",
                    "class": "logging.handlers.WatchedFileHandler",
                    "filename": "test.log",
                    "formatter": "plain",
                },
            },
            "loggers": {
                "": {
                    "handlers": ["default", "file"],
                    "level": "ERROR",
                    "propagate": True,
                },
            },
        }
    )
    structlog.configure(
        processors=[
            structlog.stdlib.add_log_level,
            structlog.stdlib.PositionalArgumentsFormatter(),
            timestamper,
            structlog.processors.StackInfoRenderer(),
            structlog.processors.format_exc_info,
            structlog.stdlib.ProcessorFormatter.wrap_for_formatter,
        ],
        logger_factory=structlog.stdlib.LoggerFactory(),
        wrapper_class=structlog.stdlib.BoundLogger,
        cache_logger_on_first_use=True,
    )

I must admit I would prefer a solution that allows me to keep the "colored" section...

Greg7000
  • 297
  • 3
  • 15