Repository: sdss/sdsstools

Issue:
Make colored_formatter a proper formatter
Somehow related to #8. `colored_formatter` should be a real `logging.Formatter` and only format the message, not emit it.

Discussion:
codecov-commenter: # [Codecov](https://codecov.io/gh/sdss/sdsstools/pull/11?src=pr&el=h1) Report
> Merging [#11](https://codecov.io/gh/sdss/sdsstools/pull/11?src=pr&el=desc) into [master](https://codecov.io/gh/sdss/sdsstools/commit/d7feba7b6153957c43e6e3124f987b5fd2837645&el=desc) will **increase** coverage by `14.43%`.
> The diff coverage is `86.21%`.

[![Impacted file tree graph](https://codecov.io/gh/sdss/sdsstools/pull/11/graphs/tree.svg?width=650&height=150&src=pr&token=RXDhA7SpXB)](https://codecov.io/gh/sdss/sdsstools/pull/11?src=pr&el=tree)

```diff
@@             Coverage Diff             @@
##           master      #11       +/-   ##
===========================================
+ Coverage   39.96%   54.38%   +14.43%     
===========================================
  Files           6        6               
  Lines         443      434        -9     
  Branches       79       76        -3     
===========================================
+ Hits          177      236       +59     
+ Misses        255      181       -74     
- Partials       11       17        +6     
```


| [Impacted Files](https://codecov.io/gh/sdss/sdsstools/pull/11?src=pr&el=tree) | Coverage Δ | |
|---|---|---|
| [src/sdsstools/logger.py](https://codecov.io/gh/sdss/sdsstools/pull/11/diff?src=pr&el=tree#diff-c3JjL3Nkc3N0b29scy9sb2dnZXIucHk=) | `90.33% <86.21%> (+48.22%)` | :arrow_up: |
| [src/sdsstools/color\_print.py](https://codecov.io/gh/sdss/sdsstools/pull/11/diff?src=pr&el=tree#diff-c3JjL3Nkc3N0b29scy9jb2xvcl9wcmludC5weQ==) | `24.72% <0.00%> (+3.38%)` | :arrow_up: |

------

[Continue to review full report at Codecov](https://codecov.io/gh/sdss/sdsstools/pull/11?src=pr&el=continue).
> **Legend** - [Click here to learn more](https://docs.codecov.io/docs/codecov-delta)
> `Δ = absolute <relative> (impact)`, `ø = not affected`, `? = missing data`
> Powered by [Codecov](https://codecov.io/gh/sdss/sdsstools/pull/11?src=pr&el=footer). Last update [d7feba7...d6a4c5e](https://codecov.io/gh/sdss/sdsstools/pull/11?src=pr&el=lastupdated). Read the [comment docs](https://docs.codecov.io/docs/pull-request-comments).


Patch:
diff --git a/poetry.lock b/poetry.lock
index 986a423..3acae0e 100644
--- a/poetry.lock
+++ b/poetry.lock
@@ -104,9 +104,6 @@ optional = false
 python-versions = ">=2.7, !=3.0.*, !=3.1.*, !=3.2.*, !=3.3.*, !=3.4.*, <4"
 version = "5.2.1"
 
-[package.dependencies]
-toml = {version = "*", optional = true, markers = "extra == \"toml\""}
-
 [package.extras]
 toml = ["toml"]
 
@@ -189,7 +186,7 @@ description = "iniconfig: brain-dead simple config-ini parsing"
 name = "iniconfig"
 optional = false
 python-versions = "*"
-version = "1.0.0"
+version = "1.0.1"
 
 [[package]]
 category = "main"
@@ -255,7 +252,7 @@ description = "A Python utility / library to sort Python imports."
 name = "isort"
 optional = false
 python-versions = ">=3.6,<4.0"
-version = "5.2.1"
+version = "5.2.2"
 
 [package.extras]
 colors = ["colorama (>=0.4.3,<0.5.0)"]
@@ -462,7 +459,7 @@ description = "pytest: simple powerful testing with Python"
 name = "pytest"
 optional = false
 python-versions = ">=3.5"
-version = "6.0.0"
+version = "6.0.1"
 
 [package.dependencies]
 attrs = ">=17.4.0"
@@ -727,7 +724,7 @@ testing = ["jaraco.itertools", "func-timeout"]
 dev = ["invoke", "twine", "wheel"]
 
 [metadata]
-content-hash = "10f54f50365c53c0fa96d23b7349f42bbd0ed71b332c4f9ce873d448dd7027c8"
+content-hash = "67414687f5a98bf82b347a8493648db8630a9b3964599184160cd55c07d7b321"
 lock-version = "1.1"
 python-versions = "^3.6"
 
@@ -877,7 +874,8 @@ importlib-metadata = [
     {file = "importlib_metadata-1.7.0.tar.gz", hash = "sha256:90bb658cdbbf6d1735b6341ce708fc7024a3e14e99ffdc5783edea9f9b077f83"},
 ]
 iniconfig = [
-    {file = "iniconfig-1.0.0.tar.gz", hash = "sha256:aa0b40f50a00e72323cb5d41302f9c6165728fd764ac8822aa3fff00a40d56b4"},
+    {file = "iniconfig-1.0.1-py3-none-any.whl", hash = "sha256:80cf40c597eb564e86346103f609d74efce0f6b4d4f30ec8ce9e2c26411ba437"},
+    {file = "iniconfig-1.0.1.tar.gz", hash = "sha256:e5f92f89355a67de0595932a6c6c02ab4afddc6fcdc0bfc5becd0d60884d3f69"},
 ]
 invoke = [
     {file = "invoke-1.4.1-py2-none-any.whl", hash = "sha256:93e12876d88130c8e0d7fd6618dd5387d6b36da55ad541481dfa5e001656f134"},
@@ -896,8 +894,8 @@ ipython-genutils = [
     {file = "ipython_genutils-0.2.0.tar.gz", hash = "sha256:eb2e116e75ecef9d4d228fdc66af54269afa26ab4463042e33785b887c628ba8"},
 ]
 isort = [
-    {file = "isort-5.2.1-py3-none-any.whl", hash = "sha256:a4401d357b0f7a9064781da345e6e2f075ebc09fbebf605740163140d5ac418c"},
-    {file = "isort-5.2.1.tar.gz", hash = "sha256:761a8f490d8bbcd3549b5618ed423468bbdece603cce44b290ee274c9a360893"},
+    {file = "isort-5.2.2-py3-none-any.whl", hash = "sha256:aea484023188ef1c38256dd24afa96e914adafe3a911a1786800a74e433006d1"},
+    {file = "isort-5.2.2.tar.gz", hash = "sha256:96b27045e3187b9bdde001143b79f9b10a462f372bff7062302818013b6c86f3"},
 ]
 jedi = [
     {file = "jedi-0.17.2-py2.py3-none-any.whl", hash = "sha256:98cc583fa0f2f8304968199b01b6b4b94f469a1f4a74c1560506ca2a211378b5"},
@@ -976,8 +974,8 @@ pyparsing = [
     {file = "pyparsing-2.4.7.tar.gz", hash = "sha256:c203ec8783bf771a155b207279b9bccb8dea02d8f0c9e5f8ead507bc3246ecc1"},
 ]
 pytest = [
-    {file = "pytest-6.0.0-py3-none-any.whl", hash = "sha256:869ec27f9b89964ccfe4fbdd5ccb8d3f285aaa3e9aa16a8491b9c8829148c230"},
-    {file = "pytest-6.0.0.tar.gz", hash = "sha256:a64d8fb4c15cdc70dae047352e980a197d855747cc885eb332cb73ddcc769168"},
+    {file = "pytest-6.0.1-py3-none-any.whl", hash = "sha256:8b6007800c53fdacd5a5c192203f4e531eb2a1540ad9c752e052ec0f7143dbad"},
+    {file = "pytest-6.0.1.tar.gz", hash = "sha256:85228d75db9f45e06e57ef9bf4429267f81ac7c0d742cc9ed63d09886a9fe6f4"},
 ]
 pytest-cov = [
     {file = "pytest-cov-2.10.0.tar.gz", hash = "sha256:1a629dc9f48e53512fcbfda6b07de490c374b0c83c55ff7a1720b3fccff0ac87"},
diff --git a/pyproject.toml b/pyproject.toml
index 5ebde51..5f41cdc 100644
--- a/pyproject.toml
+++ b/pyproject.toml
@@ -37,7 +37,6 @@ toml = "^0.10.0"
 pytest = "^6.0.0"
 pytest-sugar = "^0.9.4"
 pytest-cov = "^2.10.0"
-coverage = {version = "^5.2.1", extras = ["toml"]}
 codecov = "^2.1.8"
 
 [tool.poetry.extras]
@@ -59,7 +58,8 @@ use_parentheses = true
 skip_glob = ["*/_vendor"]
 
 [tool.pytest.ini_options]
-addopts = "--cov sdsstools --cov-report html --cov-report xml -W ignore"
+# Disable warnings system because it interferes with the logger warning capture.
+addopts = "--cov sdsstools --cov-report html --cov-report xml --cov-report term -p no:warnings"
 
 [tool.coverage.run]
 branch = true
@@ -72,6 +72,7 @@ omit = [
 
 [tool.coverage.report]
 exclude_lines = [
+    "def asyncio_exception_handler"
 ]
 
 [build-system]
diff --git a/src/sdsstools/logger.py b/src/sdsstools/logger.py
index 8bda20d..334d461 100644
--- a/src/sdsstools/logger.py
+++ b/src/sdsstools/logger.py
@@ -26,8 +26,7 @@ from .color_print import color_text
 __all__ = ['get_logger']
 
 
-# Base formatter for SH
-formatter = logging.Formatter()
+WARNING_RE = re.compile(r'^.*?\s*?(\w*?Warning): (.*)')
 
 
 def get_exception_formatted(tp, value, tb):
@@ -39,52 +38,48 @@ def get_exception_formatted(tp, value, tb):
     return highlight(tbtext, lexer, formatter)
 
 
-def colored_formatter(record):
-    """Prints log messages with colours."""
+class StreamFormatter(logging.Formatter):
+    """Custom `Formatter <logging.Formatter>` for the stream handler."""
 
-    colours = {'info': 'blue',
-               'debug': 'magenta',
-               'warning': 'yellow',
-               'critical': 'red',
-               'error': 'red'}
+    base_fmt = '%(message)s'
 
-    levelname = record.levelname.lower()
+    def __init__(self, fmt=base_fmt):
+        logging.Formatter.__init__(self, fmt)
 
-    if levelname.lower() in colours:
-        levelname_color = colours[levelname]
-        header = color_text('[{}]: '.format(levelname.upper()),
-                            levelname_color)
-    else:
-        header = f'[{levelname}]'
+    def format(self, record):
 
-    message = formatter.format(record)
+        colours = {'info': 'blue',
+                   'debug': 'magenta',
+                   'warning': 'yellow',
+                   'critical': 'red',
+                   'error': 'red'}
 
-    if levelname == 'warning':
-        warning_category_groups = re.match(r'^.*?\s*?(\w*?Warning): (.*)', message)
-        if warning_category_groups is not None:
-            warning_category, warning_text = warning_category_groups.groups()
+        record_cp = copy.copy(record)
 
-            # Temporary ignore warnings from pymodbus. The normal warnings.simplefilter
-            # does not work because pymodbus forces them to show.
-            if re.match('"@coroutine" decorator is deprecated.+', warning_text):
-                return
+        levelname = record_cp.levelname.lower()
+        message = record_cp.msg
 
-            warning_category_colour = color_text('({})'.format(warning_category), 'cyan')
-            message = '{} {}'.format(color_text(warning_text, ''), warning_category_colour)
+        if levelname.lower() in colours:
+            level_colour = colours[levelname]
+            header = color_text('[{}]: '.format(levelname.upper()), level_colour)
+        else:
+            return logging.Formatter.format(self, record)
 
-    if record.levelno >= logging.ERROR:
-        std = sys.__stderr__
-    else:
-        std = sys.__stdout__
+        record_cp.msg = '{}{}'.format(header, message)
 
-    std.write('{}{}\n'.format(header, message))
-    std.flush()
+        if levelname == 'warning' and len(record_cp.args) > 0:
+            warning_category_groups = WARNING_RE.match(record_cp.args[0])
+            if warning_category_groups is not None:
+                wcategory, wtext = warning_category_groups.groups()
+                wcategory_colour = color_text('({})'.format(wcategory), 'cyan')
+                message = '{} {}'.format(color_text(wtext, ''), wcategory_colour)
+                record_cp.args = tuple([message] + list(record_cp.args[1:]))
 
-    return
+        return logging.Formatter.format(self, record_cp)
 
 
-class SDSSFormatter(logging.Formatter):
-    """Custom `Formatter <logging.Formatter>`."""
+class FileFormatter(logging.Formatter):
+    """Custom `Formatter <logging.Formatter>` for the file handler."""
 
     base_fmt = '%(asctime)s - %(levelname)s - %(message)s'
     ansi_escape = re.compile(r'\x1b[^m]*m')
@@ -141,7 +136,7 @@ class SDSSLogger(logging.Logger):
 
         # Sets the console handler
         self.sh = logging.StreamHandler()
-        self.sh.emit = colored_formatter
+        self.sh.setFormatter(StreamFormatter())
         self.addHandler(self.sh)
         self.sh.setLevel(log_level)
 
@@ -203,7 +198,8 @@ class SDSSLogger(logging.Logger):
     def save_log(self, path):
         shutil.copyfile(self.log_filename, os.path.expanduser(path))
 
-    def start_file_logger(self, path, log_level=logging.DEBUG, mode='a', rotating=True):
+    def start_file_logger(self, path, log_level=logging.DEBUG,
+                          mode='a', rotating=True):
         """Start file logging."""
 
         log_file_path = os.path.expanduser(path)
@@ -230,7 +226,7 @@ class SDSSLogger(logging.Logger):
 
         else:
 
-            self.fh.setFormatter(SDSSFormatter())
+            self.fh.setFormatter(FileFormatter())
             self.addHandler(self.fh)
             self.fh.setLevel(log_level)
 
@@ -243,7 +239,8 @@ class SDSSLogger(logging.Logger):
         """Handles a record but first stores it."""
 
         if hasattr(self, 'header') and self.header is not None:
-            record.msg = self.header + record.msg
+            if not isinstance(record.msg, Exception):
+                record.msg = self.header + record.msg
 
         if record.levelno == logging.ERROR:
             self._last_error = record.getMessage()


Test patch:
diff --git a/test/conftest.py b/test/conftest.py
index 0a577b0..76d22ab 100644
--- a/test/conftest.py
+++ b/test/conftest.py
@@ -5,3 +5,11 @@
 # @Date: 2020-07-29
 # @Filename: conftest.py
 # @License: BSD 3-clause (http://www.opensource.org/licenses/BSD-3-Clause)
+
+from sdsstools import log
+
+
+# Disable sdsstools logging since it may interfere with the logger tests.
+log.warnings_logger.removeHandler(log.sh)
+log.removeHandler(log.sh)
+log.sh = None
diff --git a/test/test_logger.py b/test/test_logger.py
new file mode 100644
index 0000000..4c1598a
--- /dev/null
+++ b/test/test_logger.py
@@ -0,0 +1,138 @@
+#!/usr/bin/env python
+# -*- coding: utf-8 -*-
+#
+# @Author: José Sánchez-Gallego (gallegoj@uw.edu)
+# @Date: 2020-08-01
+# @Filename: test_logger.py
+# @License: BSD 3-clause (http://www.opensource.org/licenses/BSD-3-Clause)
+
+import logging
+import logging.handlers
+import os
+import uuid
+import warnings
+
+import pytest
+
+from sdsstools import get_logger
+from sdsstools.logger import get_exception_formatted
+
+
+@pytest.fixture
+def logger_no_fh():
+
+    _logger = get_logger(str(uuid.uuid4()))
+
+    yield _logger
+
+    handlers = _logger.warnings_logger.handlers
+    for handler in handlers:
+        _logger.warnings_logger.removeHandler(handler)
+
+
+@pytest.fixture
+def logger(tmp_path, logger_no_fh):
+
+    log_file = tmp_path / 'logs' / 'test_log.log'
+    logger_no_fh.start_file_logger(log_file)
+
+    yield logger_no_fh
+
+    handlers = logger_no_fh.warnings_logger.handlers
+    for handler in handlers:
+        logger_no_fh.warnings_logger.removeHandler(handler)
+
+
+def test_logger(logger, caplog):
+
+    assert len(logger.handlers) == 2
+
+    logger.debug('DEBUG')
+    logger.info('INFO')
+    logger.warning('WARNING')
+    logger.error('ERROR')
+
+    assert caplog.record_tuples == [(logger.name, logging.DEBUG, 'DEBUG'),
+                                    (logger.name, logging.INFO, 'INFO'),
+                                    (logger.name, logging.WARNING, 'WARNING'),
+                                    (logger.name, logging.ERROR, 'ERROR')]
+
+    assert logger.fh is not None
+    assert isinstance(logger.fh, logging.handlers.TimedRotatingFileHandler)
+    assert logger.log_filename is not None
+    assert len(open(str(logger.log_filename), 'r').read().splitlines()) == 4
+
+    assert len(logger.get_last_error()) is not None
+
+
+def test_set_level(caplog, logger):
+
+    logger.set_level(logging.ERROR)
+
+    with caplog.at_level(logging.ERROR):
+        logger.info('INFO')
+
+    assert len(caplog.records) == 0
+    assert len(open(str(logger.log_filename), 'r').read().splitlines()) == 0
+
+
+def test_warning_raised(logger):
+
+    with pytest.warns(UserWarning):
+        warnings.warn('A warning', UserWarning)
+
+
+def test_warning(logger, caplog):
+
+    warnings.warn('A warning', UserWarning)
+
+    assert len(logger.warnings_logger.handlers) == 2
+    assert logger.warnings_logger.handlers[0] == logger.handlers[0]
+
+    assert 'A warning' in caplog.messages[0]
+    assert len(open(str(logger.log_filename), 'r').read().splitlines()) == 1
+
+
+def test_exception_formatting(logger, caplog):
+
+    with pytest.raises(ValueError) as excinfo:
+        raise ValueError('An error')
+
+    exc_text = get_exception_formatted(excinfo.type, excinfo.value, excinfo.tb)
+
+    assert exc_text is not None
+    assert 'An error' in exc_text
+    assert '\x1b[91mValueError\x1b[39;49;00m' in exc_text
+
+
+def test_save_log(logger):
+
+    logger.info('INFO')
+
+    dest = os.path.dirname(logger.log_filename) + '/../copied_log.log'
+    logger.save_log(dest)
+
+    assert os.path.exists(dest)
+
+
+def test_get_logger_twice(logger):
+
+    logger2 = get_logger(logger.name)
+
+    assert logger == logger2
+
+
+def test_bad_fh_path(logger_no_fh, tmp_path):
+
+    bad_path = str(tmp_path)
+
+    with pytest.warns(RuntimeWarning):
+        logger_no_fh.start_file_logger(bad_path)
+
+    assert logger_no_fh.fh is None
+
+
+def test_fh_no_rotating(logger_no_fh, tmp_path):
+
+    logger_no_fh.start_file_logger(tmp_path / 'no_rotating.log', rotating=False)
+    assert isinstance(logger_no_fh.fh, logging.FileHandler)