mercredi 2 septembre 2020

Functional logger raises FileNotFoundError in Pytest

Intention

I want to make a python class that creates a log when it's initialized and add to the log when instances of the class do work. My code works in practice but when writing tests I get a FileNotFoundError.

Code

# code.py

""""A class that creates a logger during initialization"""

import datetime
import logging
import sys

from os import makedirs, path


class Worker(object):
    def __init__(self):
        job_name = path.splitext(sys.argv[0])[0]
        here = path.dirname(path.abspath(__file__))
        log_dir = ''.join([here, '/logs/jobs/', job_name])
        makedirs(log_dir, exist_ok=True)
        
        self.logger = logging.getLogger(.''.join(['jobs', job_name]))
        self.logger.setLevel(logging.DEBUG)
        
        log_formatter = logging.Formatter('%(name)s,%(levelname)-8s,%(asctime)s,%(message)s')
        stream_handler = logging.StreamHandler()
        stream_handler.setLevel(logging.WARN)
        stream_handler.setFormatter(log_formatter)
        self.logger.addHandler(stream_handler)
        
        now = datetime.datetime.now().strftime('%H%M%S')
        log_file = ''.join([log_dir, '/', job_name, '_', now, '.log'])
        file_handler = logging.FileHandler(log_file)
        file_handler.setLevel(logging.DEBUG)
        file_handler.setFormatter(log_formatter)
        self.logger.addHandler(file_handler)
        stream_handler.setLevel(logging.INFO)

    def do_something(self):
        """A job that needs to be done"""
        self.logger.info('I did something.')
        return True
# test_code.py
import unittest

from workers.code import Worker


class CodeTest(unittest.TestCase):
    def test__init__(self):
        worker = Worker()
        assert worker.logger.handlers  # this fails with FileNotFound Error

    def test_do_something(self):
        worker = Worker()  # this also fails even when delay=True on FileHandler
        assert worker.do_something()

Traceback

$ pytest
===================================== test session starts =====================================
platform linux -- Python 3.8.5, pytest-6.0.1, py-1.9.0, pluggy-0.13.1
rootdir: /home/laptop/Documents/Repositories/pytest-logging-test
collected 2 items                                                                             

tests/test_code.py FF                                                                   [100%]

========================================== FAILURES ===========================================
____________________________________ CodeTest.test__init__ ____________________________________

self = <tests.test_code.CodeTest testMethod=test__init__>

    def test__init__(self):
>       worker = Worker()

tests/test_code.py:8: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
workers/code.py:28: in __init__
    file_handler = logging.FileHandler(log_file)
/usr/lib/python3.8/logging/__init__.py:1143: in __init__
    StreamHandler.__init__(self, self._open())
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _

self = <[AttributeError("'FileHandler' object has no attribute 'level'") raised in repr()] FileHandler object at 0x7fc8ff05a820>

    def _open(self):
        """
        Open the current base file with the (original) mode and encoding.
        Return the resulting stream.
        """
>       return open(self.baseFilename, self.mode, encoding=self.encoding)
E       FileNotFoundError: [Errno 2] No such file or directory: '/home/laptop/Documents/Repositories/pytest-logging-test/workers/logs/jobs/home/laptop/Documents/Repositories/pytest-logging-test/venv/bin/pytest/home/laptop/Documents/Repositories/pytest-logging-test/venv/bin/pytest_172529.log'

/usr/lib/python3.8/logging/__init__.py:1172: FileNotFoundError
_________________________________ CodeTest.test_do_something __________________________________

self = <tests.test_code.CodeTest testMethod=test_do_something>

    def test_do_something(self):
>       worker = Worker()  # this also fails even when delay=True on FileHandler

tests/test_code.py:12: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
workers/code.py:28: in __init__
    file_handler = logging.FileHandler(log_file)
/usr/lib/python3.8/logging/__init__.py:1143: in __init__
    StreamHandler.__init__(self, self._open())
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _

self = <[AttributeError("'FileHandler' object has no attribute 'level'") raised in repr()] FileHandler object at 0x7fc8ff0140d0>

    def _open(self):
        """
        Open the current base file with the (original) mode and encoding.
        Return the resulting stream.
        """
>       return open(self.baseFilename, self.mode, encoding=self.encoding)
E       FileNotFoundError: [Errno 2] No such file or directory: '/home/laptop/Documents/Repositories/pytest-logging-test/workers/logs/jobs/home/laptop/Documents/Repositories/pytest-logging-test/venv/bin/pytest/home/laptop/Documents/Repositories/pytest-logging-test/venv/bin/pytest_172529.log'

/usr/lib/python3.8/logging/__init__.py:1172: FileNotFoundError
=================================== short test summary info ===================================
FAILED tests/test_code.py::CodeTest::test__init__ - FileNotFoundError: [Errno 2] No such fil...
FAILED tests/test_code.py::CodeTest::test_do_something - FileNotFoundError: [Errno 2] No suc...
====================================== 2 failed in 0.26s ======================================

Failed Solutions

It looks like pytest is trying to open the file before it's made. This code works in practice exactly as expected. I'm only getting this error when using pytest.

Also, in my tests directory, pytest creates a bunch of folders as is evident from /home/laptop/Documents/Repositories/pytest-logging-test/workers/logs/jobs/home/laptop/Documents/Repositories/pytest-logging-test/venv/bin/pytest/home/laptop/Documents/Repositories/pytest-logging-test/venv/bin/ in the traceback. I don't know why it doesn't make the file though.

When I set delay=True when calling FileHandler in the Worker class, test__init__ passes but test_do_something fails. Here is the traceback:

$ pytest
===================================== test session starts =====================================
platform linux -- Python 3.8.5, pytest-6.0.1, py-1.9.0, pluggy-0.13.1
rootdir: /home/laptop/Documents/Repositories/pytest-logging-test
collected 2 items                                                                             

tests/test_code.py .F                                                                   [100%]

========================================== FAILURES ===========================================
_________________________________ CodeTest.test_do_something __________________________________

self = <tests.test_code.CodeTest testMethod=test_do_something>

    def test_do_something(self):
        worker = Worker()  # this also fails even when delay=True on FileHandler
>       assert worker.do_something()

tests/test_code.py:13: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
workers/code.py:36: in do_something
    self.logger.info('I did something.')
/usr/lib/python3.8/logging/__init__.py:1434: in info
    self._log(INFO, msg, args, **kwargs)
/usr/lib/python3.8/logging/__init__.py:1577: in _log
    self.handle(record)
/usr/lib/python3.8/logging/__init__.py:1587: in handle
    self.callHandlers(record)
/usr/lib/python3.8/logging/__init__.py:1649: in callHandlers
    hdlr.handle(record)
/usr/lib/python3.8/logging/__init__.py:950: in handle
    self.emit(record)
/usr/lib/python3.8/logging/__init__.py:1182: in emit
    self.stream = self._open()
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _

self = <FileHandler /home/laptop/Documents/Repositories/pytest-logging-test/workers/logs/jobs/home/laptop/Documents/Repos...gging-test/venv/bin/pytest/home/laptop/Documents/Repositories/pytest-logging-test/venv/bin/pytest_172946.log (DEBUG)>

    def _open(self):
        """
        Open the current base file with the (original) mode and encoding.
        Return the resulting stream.
        """
>       return open(self.baseFilename, self.mode, encoding=self.encoding)
E       FileNotFoundError: [Errno 2] No such file or directory: '/home/laptopy/Documents/Repositories/pytest-logging-test/workers/logs/jobs/home/laptop/Documents/Repositories/pytest-logging-test/venv/bin/pytest/home/laptop/Documents/Repositories/pytest-logging-test/venv/bin/pytest_172946.log'

/usr/lib/python3.8/logging/__init__.py:1172: FileNotFoundError
------------------------------------ Captured stderr call -------------------------------------
jobs./home/laptop/Documents/Repositories/pytest-logging-test/venv/bin/pytest,INFO    ,2020-09-02 17:29:46,569,I did something.
=================================== short test summary info ===================================
FAILED tests/test_code.py::CodeTest::test_do_something - FileNotFoundError: [Errno 2] No suc...
================================= 1 failed, 1 passed in 0.28s =================================

In the python console the above code works exactly as expected:

>>> from workers.code import Worker
>>> w = Worker()
>>> w.do_something()
True

The approiate log files are made as well so this is a problem with pytest. The logger.info() call is being captured by pytest as evident in the traceback, but for some reason the file isn't being made. I can't figure out why this is happening. Can someone please shed some light?

Aucun commentaire:

Enregistrer un commentaire