Merge branch 'logging-fix' into ver/0.8.5

Fix #134

slivka/conf/logging.py

@@ -19,46 +19,31 @@ def __init__(self, address, ctx: zmq.Context = None):
         socket.connect(address)
         super().__init__(socket)
 
-    def emit(self, record):
-        message = self.format(record)
-        msg = record.__dict__.copy()
-        msg.update(
-            message=message,
-            msg=message,
-            args=None,
-            exc_info=None,
-            exc_text=None
-        )
-        self.queue.send_json(msg)
+    def enqueue(self, record):
+        self.queue.send_json(record.__dict__)
+
+    def close(self):
+        super().close()
+        self.queue.close()
 
 
 class ZMQQueueListener(logging.handlers.QueueListener):
     def __init__(self, address, handlers=(), ctx: zmq.Context = None):
         self._address = address
-        ctx = ctx or _context
-        self._ctx = ctx
-        socket = ctx.socket(zmq.PULL)
+        self._ctx = ctx or _context
+        socket = self._ctx.socket(zmq.PULL)
         socket.bind(address)
         super().__init__(socket, *handlers, respect_handler_level=False)
-        self.handlers = list(self.handlers)
 
     def __enter__(self):
         self.start()
 
     def __exit__(self, exc_type, exc_val, exc_tb):
         self.stop()
-        self.cleanup()
-
-    def add_handler(self, handler):
-        self.handlers.append(handler)
-
-    def remove_handler(self, handler):
-        self.handlers.remove(handler)
 
     def dequeue(self, block):
         msg = self.queue.recv_json()
         if msg == self._sentinel:
-            self.queue.close(0)
             return msg
         else:
             return logging.makeLogRecord(msg)
@@ -71,8 +56,6 @@ def enqueue_sentinel(self):
     def stop(self):
         super().stop()
         self.queue.close(0)
-
-    def cleanup(self):
         if self._address.startswith('ipc://'):
             os.unlink(self._address[6:])
 
@@ -87,42 +70,25 @@ def get_logging_sock():
     return path
 
 
-def _get_default_logging_config():
-    return {
-        'version': 1,
-        'disable_existing_loggers': False,
-        'formatters': {
-            'full': {
-                'format': "%(asctime)s %(levelname)-10s %(name)s %(message)s",
-                'datefmt': "%d/%m/%y %H:%M:%S"
-            },
-            'minimal': {
-                'format': '%(levelname)s %(message)s'
-            }
-        },
-        'handlers': {
-            'slivka.logging_queue': {
-                'class': 'slivka.conf.logging.ZMQQueueHandler',
-                'formatter': 'full',
-                'level': 'DEBUG',
-                'address': get_logging_sock()
-            },
-            'console': {
-                'class': 'logging.StreamHandler',
-                'formatter': 'minimal',
-                'level': 'DEBUG'
-            }
-        },
-        'loggers': {
-            'slivka': {
-                'level': 'DEBUG',
-                'propagate': False,
-                'handlers': ['slivka.logging_queue', 'console']
-            }
-        }
-    }
-
-
-def configure_logging(config=None):
-    config = config or _get_default_logging_config()
-    logging.config.dictConfig(config)
+def configure_logging(level=logging.DEBUG):
+    if isinstance(level, str):
+        level = logging.getLevelName(level)
+
+    zmq_handler = ZMQQueueHandler(get_logging_sock())
+    zmq_handler.setLevel(level)
+    full_formatter = logging.Formatter(
+        fmt="%(asctime)s %(levelname)-8s %(name)s %(message)s",
+        datefmt="%Y-%m-%d %H:%M:%S"
+    )
+    zmq_handler.setFormatter(full_formatter)
+
+    console_handler = logging.StreamHandler()
+    console_handler.setLevel(logging.WARNING)
+    minimal_formatter = logging.Formatter(fmt="%(levelname)-8s %(message)s")
+    console_handler.setFormatter(minimal_formatter)
+
+    logger = logging.getLogger("slivka")
+    logger.propagate = False
+    logger.setLevel(level)
+    logger.addHandler(zmq_handler)
+    logger.addHandler(console_handler)

test/conf/zmq_logging.py

@@ -0,0 +1,80 @@
+import logging
+import logging.handlers
+import unittest
+
+import pytest
+import slivka.conf.logging
+import zmq
+from hamcrest import assert_that, has_entries, has_properties
+from slivka.conf.logging import ZMQQueueHandler, ZMQQueueListener
+
+
+@pytest.fixture(scope="module")
+def address():
+    return "tcp://localhost:13231"
+
+
+@pytest.fixture()
+def logger():
+    return logging.Logger("test.logging", level=logging.DEBUG)
+
+
+@pytest.fixture()
+def pull_socket(address):
+    ctx = zmq.Context.instance()
+    socket: zmq.Socket = ctx.socket(zmq.PULL)
+    socket.bind(address)
+    yield socket
+    socket.close(0)
+
+
+@pytest.fixture()
+def mock_handler():
+    handler = logging.Handler()
+    with unittest.mock.patch.object(handler, "emit"):
+        yield handler
+
+
+def test_handler_record_sent(address, logger, pull_socket):
+    handler = ZMQQueueHandler(address)
+    logger.addHandler(handler)
+    logger.error("Error message")
+    data = pull_socket.recv_json()
+    # noinspection PyTypeChecker
+    assert_that(
+        data,
+        has_entries(
+            name="test.logging",
+            msg="Error message",
+            levelname="ERROR",
+            levelno=logging.ERROR,
+        ),
+    )
+
+
+def test_listener_record_received(logger, address, mock_handler):
+    logger.addHandler(ZMQQueueHandler(address))
+    listener = ZMQQueueListener(address, handlers=(mock_handler,))
+    logger.info("info message")
+    record = listener.dequeue(True)
+    assert_that(
+        record,
+        has_properties(
+            "name", "test.logging",
+            "msg", "info message",
+            "levelname", "INFO",
+            "levelno", logging.INFO,
+            "exc_info", None,
+            "exc_text", None,
+        ),
+    )
+
+
+def test_configure_logging(minimal_project, mock_handler):
+    slivka.conf.logging.configure_logging()
+    addr = slivka.conf.logging.get_logging_sock()
+    listener = ZMQQueueListener(addr, handlers=(mock_handler,))
+    logger = logging.getLogger("slivka")
+    logger.info("info message")
+    record = listener.dequeue(True)
+    assert record.name == "slivka"

test/conftest.py

@@ -1,4 +1,5 @@
 import os
+import shutil
 import tempfile
 from functools import partial
 from unittest import mock
@@ -7,6 +8,7 @@
 import pytest
 
 import slivka.db
+from slivka.compat.resources import open_binary
 
 
 @pytest.fixture(scope="package")
@@ -43,3 +45,10 @@ def job_directory(slivka_home):
 def job_directory_factory(slivka_home):
     (slivka_home / "jobs").mkdir(exist_ok=True)
     yield partial(tempfile.mkdtemp, dir=slivka_home / "jobs")
+
+
+@pytest.fixture(scope="function")
+def minimal_project(slivka_home):
+    in_stream = open_binary("test", "resources/minimal_project/settings.yaml")
+    with open(slivka_home / "settings.yaml", "wb") as out_file:
+        shutil.copyfileobj(in_stream, out_file)

test/resources/minimal_project/settings.yaml

@@ -0,0 +1,14 @@
+version: "0.8"
+directory.uploads: ./uploads
+directory.jobs: ./jobs
+directory.logs: ./log
+directory.services: ./
+
+server.host: 127.0.0.1:4040
+server.uploads-path: /media/uploads
+server.jobs-path: /media/jobs
+
+local-queue.host: tcp://127.0.0.1:4041
+
+mongodb.host: 127.0.0.1:27017
+mongodb.database: testdb