Repository: radiocosmology/alpenhorn

Issue:
Port log file handling code from alpenhorn1
Alpenhorn-1 uses https://pypi.org/project/concurrent-log-handler/ to handle log files, which is very helpful for us on the clusters where we can't use logrotate to handle log files.

We should re-implement this as an optional feature, configured via the config file (instead of the `ALPENHORN_LOG_FILE` environmental variable).  e.g.:
```
logging:
    level: DEBUG
    file:
        name: ~/alpenspool/alpenhorn.log
        rotate: yes
        max-size: 4G
        file-count: 100
```

Discussion:
ketiltrout: This PR introduces a dependency on `concurrent-log-handler`, which provides a version of the standard `RotatingFileHanlder` which allows multiple processes to write to the same log file.  This is done via a lock file.

This dependency was in alpenhorn1, which is why I've added it here, but I don't think it's necessary.  It's not clear to me why we would have multiple things writing to alpenhorn's log file at the same time.

Should I remove it?

The only thing I can think is that maybe we had it in alpenhorn1 due to the old HPSS callback script which used to be executed on another machine on scinet?  Even that is no longer done: the main alpenhorn process takes care of everything now for HPSS.

Patch:
diff --git a/alpenhorn/config.py b/alpenhorn/config.py
index 2186b61..1c37221 100644
--- a/alpenhorn/config.py
+++ b/alpenhorn/config.py
@@ -31,9 +31,9 @@ Example config:
         - alpenhorn_chime
         - chimedb.core.alpenhorn
 
-    # Logging configuration
+    # Logging configuration.  By default, alpenhorn sends all log message to
+    # standard error.
     logging:
-
         # Set the overall logging level
         level: debug
 
@@ -41,6 +41,68 @@ Example config:
         module_levels:
             alpenhorn.db: info
 
+        # Alpenhorn can be configured to send log output to syslog and/or
+        # a file.  This is _in addition_ to the log sent to standard error,
+        # which is always enabled.
+
+        # Syslog logging.
+        syslog:
+            # If true, enable logging to syslog.  Note: if the "syslog" section
+            # is present in the logging config, then the default value
+            # of this key is true.  As a result, this key need only be specified if
+            # none of the other syslog configuration parameters are provided
+            # in the config.
+            enable: true
+
+            # The network address to send syslog message to.
+            #
+            # May also be a Unix domain socket (like "/dev/log").  In that case,
+            # set `port`, below, to zero to indicate this.
+            #
+            # Defaults to "localhost".
+            address: localhost
+
+            # The network port to send syslog messages to.  If this is zero,
+            # then the port is ignored and `address` is taken to be a Unix domain
+            # socket.  Defaults to 514, the standard syslog port.
+            port: 514
+
+            # The syslog facility to use.  If given, should be the name of one of
+            # the syslog facilities, disregarding case ("user", "local0", ...)
+            # Defaults to "user".
+            facility: user
+
+            # Set to True to use TCP, instead of UDP, to send messages to the syslog server.
+            # Ignored if using a Unix domain socket (i.e. `port` is zero).  Default is False.
+            use_tcp: false
+
+        # File logging.
+        file:
+            name: /path/to/file.log
+
+            # If a third-party (like logrotate) is rotating the alpenhorn log
+            # file, set this to "true" to tell alpenhorn to watch for log-file
+            # rotation.
+            watch: false
+
+            # Alternately, alpenhorn can manage log file rotation itself.  Set
+            # "rotate" to true to enable.  At most one of "watch" and "rotate"
+            # may be true.
+            rotate: true
+
+            # The following two settings affect alpenhorn-managed log rotation
+            # and are ignored if "rotate" is not true.
+
+            # Maximum number of rotated files to keep.  Must be at least one
+            # Rotated files append an integer to the name specified (e.g.
+            # "file.log.1", "file.log.2" etc.).
+            backup_count: 100
+
+            # Size, in bytes, at which log file rotation occurs.  May include a suffix:
+            # k, M, or G.
+            max_bytes: 4G
+
+
     # Configure the operation of the local service
     service:
         # Default number of worker threads
diff --git a/alpenhorn/logger.py b/alpenhorn/logger.py
index 99df44f..6130425 100644
--- a/alpenhorn/logger.py
+++ b/alpenhorn/logger.py
@@ -1,51 +1,385 @@
-"""Setup logging for alpenhorn.
+"""Set up logging for alpenhorn.
+
+This module provides two important functions:
+
+* `init_logging()` should be called as soon as possible after program start
+    to turn on logging to standard error.  Any log messages produced before
+    this call are discarded.
+
+* `configure_logging()` should be called immediately after the alpenhorn
+    config has been loaded.  It will re-configure the alpenhorn logger
+    based on the alpenhorn configuration, including starting file or syslog-
+    based logging, if requested.
+
+alpenhorn buffers log messages emitted between these two calls and will flush
+them to any additonal log destinations started by `configure_logging` so that
+these messages are not lost.  (This is in addiiton to the messages being sent
+immediately to standard error, which always happens.)
+
+Note also that between the two calls, the log level of the root logger is
+set to DEBUG.
 """
 
+import socket
 import logging
+import pathlib
+import logging.handlers
 
 from . import config
 
-root_logger = logging.getLogger()
-
-log_stream = logging.StreamHandler()
+try:
+    from concurrent_log_handler import (
+        ConcurrentRotatingFileHandler as RotatingFileHandler,
+    )
+except ImportError:
+    RotatingFileHandler = logging.handlers.RotatingFileHandler
 
+# The log format.  Used by the stderr log and any other log destinations
 log_fmt = logging.Formatter(
     "%(asctime)s %(levelname)s >> [%(threadName)s] %(message)s", "%b %d %H:%M:%S"
 )
 
-log_stream.setFormatter(log_fmt)
+# initialised by init_logging
+log_buffer = None
 
-root_logger.setLevel(logging.DEBUG)
-root_logger.addHandler(log_stream)
 
+class StartupHandler(logging.handlers.BufferingHandler):
+    """Start-up logging handler for alpenhorn.
 
-def start_logging():
-    """From the config, setup logging."""
+    A logging hander similar to logging.handlers.MemoryHandler, except:
+    * it can flush to potentially multiple target handlers
+    * it never automatically flushes.
+    * once the buffer is full, further messages are silently discarded
 
-    # TODO: apply different settings for the client
+    Parameters
+    ----------
+    capacity
+        The maximum number of log messages to buffer.
+    """
+
+    def __init__(self, capacity: int) -> None:
+        super().__init__(capacity)
+        self.targets = list()
+
+    def addTarget(self, handler: logging.Handler) -> None:
+        """Add `handler` to the list of targets."""
+        self.targets.append(handler)
+
+    def shouldFlush(self, record) -> bool:
+        """Returns false to disable autoflushing."""
+        return False
+
+    def emit(self, record) -> None:
+        """Buffer `record` if not full."""
+        self.acquire()
+        try:
+            if len(self.buffer) < self.capacity:
+                self.buffer.append(record)
+        finally:
+            self.release()
+
+    def flush(self) -> None:
+        """Flush to all targets.
+
+        After flushing, the buffer is cleared.
+        """
+        self.acquire()
+        try:
+            for target in self.targets:
+                for record in self.buffer:
+                    target.handle(record)
+            self.buffer.clear()
+        finally:
+            self.release()
+
+    def close(self) -> None:
+        """Discard all targets and drop the buffer."""
+        self.acquire()
+        try:
+            self.targets = list()
+            super().close()
+        finally:
+            self.release()
+
+
+def init_logging() -> None:
+    """Initialise the logger.
+
+    This function is called before the config is read.  It sets up logging to
+    standard error and also starts a log buffer where messages accumulate
+    before the logging facilities defined by the configuration are started.
+    """
+
+    # This is the stderr logger.  It is always present, regardless of logging config
+    log_stream = logging.StreamHandler()
+    log_stream.setFormatter(log_fmt)
+
+    # This is the start-up logger.  It buffers messages in memory until configure_logging()
+    # is called, at which point the buffered messages are flushed to a file, if one was
+    # opened, so that messages logged before the start of file logging are recorded,
+    # and then this handler is shut down.
+    global log_buffer
+    log_buffer = StartupHandler(10000)
+
+    # Set up initial logging
+    root_logger = logging.getLogger()
+    root_logger.setLevel(logging.DEBUG)
+    root_logger.addHandler(log_buffer)
+    root_logger.addHandler(log_stream)
+
+    root_logger.info("Alpenhorn start.")
+
+
+def _max_bytes_from_config(max_bytes: str | float | int) -> int:
+    """Convert logging.file.max_bytes to bytes.
+
+    Parameters
+    ----------
+    max_bytes
+        The value of logging.file.max_bytes.
+
+    Returns
+    -------
+    max_bytes
+        The max size converted to bytes
+
+    Raises
+    ------
+    ValueError
+        max_bytes was invalid
+    """
+
+    exponent = 0
+
+    # Look for a suffix
+    if isinstance(max_bytes, str):
+        if max_bytes.endswith("k"):
+            max_bytes = max_bytes[:-1]
+            exponent = 1
+        elif max_bytes.endswith("M"):
+            max_bytes = max_bytes[:-1]
+            exponent = 2
+        elif max_bytes.endswith("G"):
+            max_bytes = max_bytes[:-1]
+            exponent = 3
+
+    try:
+        result = int(float(max_bytes) * (1024**exponent))
+    except ValueError:
+        raise ValueError("bad size for logging.file.max_bytes")
+
+    if result <= 0:
+        raise ValueError("bad size for logging.file.max_bytes")
+
+    return result
+
+
+def configure_sys_logging(syslog_config: dict) -> logging.handlers.SysLogHandler | None:
+    """Configure a syslog logging handler based on the config.
+
+    Parameters
+    ----------
+    syslog_config
+        The contents of the `logging.syslog` section of the
+        alpenhorn config.
+
+    Returns
+    -------
+    syslog_handler
+        The configured syslog handler
+    """
 
-    # TODO: add in a way of taking completely custom logging parameters from the
-    # config using logging.dictConfig
+    enable = syslog_config.get("enable", True)
+    if enable is not True and enable is not False:
+        raise ValueError("logging.syslog.enable in config must be boolean")
 
-    # TODO: while I'm mostly buying into the philosophy that logs should
-    # generally just be sent to stdout and then be left to the system to deal
-    # with, on SciNet it's probably useful to specify file locations, so we
-    # should bring that back
+    if not enable:
+        return None  # Explicitly disabled
 
-    def _check_level(level):
+    # Configuration parameters
+    address = syslog_config.get("address", "localhost")
+    port = int(syslog_config.get("port", 514))
+
+    # If port is zero, then address is a local socket.
+    if port:
+        address = (address, port)
+
+    use_tcp = syslog_config.get("use_tcp", False)
+    if use_tcp is not True and use_tcp is not False:
+        raise ValueError("logging.syslog.use_tcp in config must be boolean")
+
+    # Get facility
+    facname = syslog_config.get("facility", "user").lower()
+    try:
+        facility = logging.handlers.SysLogHandler.facility_names[facname]
+    except KeyError:
+        raise ValueError("unknown facility in logging.syslog.facility")
+
+    handler = logging.handlers.SysLogHandler(
+        address=address,
+        facility=facility,
+        socktype=socket.SOCK_STREAM if use_tcp else socket.SOCK_DGRAM,
+    )
+
+    # Format handler
+    global log_fmt
+    handler.setFormatter(log_fmt)
+
+    # Log the start of syslogging to the alpenhorn logger.
+    # We do this _before_ adding the file handler to prevent
+    # duplicating this message (via both the syslog handler and
+    # the start-up handler).
+    alpen_logger = logging.getLogger("alpenhorn")
+    if port:
+        alpen_logger.info(
+            f"Logging to syslog at {address}:{port} via "
+            + ("TCP" if use_tcp else "UDP")
+            + f" as facility {facname}"
+        )
+    else:
+        alpen_logger.info(f"Logging to syslog socket {address} as facility {facname}")
+
+    return handler
+
+
+def configure_file_logging(file_config: dict) -> logging.Handler:
+    """Configure a file logging handler based on the config.
+
+    Paramters
+    ---------
+    file_config
+        The contents of the `logging.file` section of the
+        alpenhorn config.
+
+    Returns
+    -------
+    file_handler
+        The configured file handler
+
+    Raises
+    ------
+    KeyError
+        no `logging.file.name` was specified in the config
+    ValueError
+        a bad value was encountered in the logging config
+    """
+
+    if "name" not in file_config:
+        raise KeyError("No logging.file.name in config")
+
+    name = pathlib.Path(file_config["name"]).expanduser()
+
+    watch = file_config.get("watch", False)
+    if watch is not True and watch is not False:
+        raise ValueError("logging.file.watch in config must be boolean")
+
+    rotate = file_config.get("rotate", False)
+    if rotate is not True and rotate is not False:
+        raise ValueError("logging.file.rotate in config must be boolean")
+
+    # Choose handler
+    if rotate and watch:
+        raise ValueError(
+            "logging.file.rotate and logging.file.watch both true in config"
+        )
+    elif rotate:
+        # Alpenhorn is rotating the log
+        try:
+            backup_count = int(file_config.get("backup_count", 100))
+        except ValueError:
+            raise ValueError("Bad value for logging.file.backup_count")
+
+        if backup_count <= 0:
+            raise ValueError("Bad value for logging.file.backup_count")
+
+        max_bytes = _max_bytes_from_config(file_config.get("max_bytes", "4G"))
+        handler = RotatingFileHandler(
+            name, maxBytes=max_bytes, backupCount=backup_count
+        )
+        how = " [rotating]"
+    elif watch:
+        # Someone else is rotating the log
+        handler = logging.handlers.WatchedFileHandler(name)
+        how = " [watching]"
+    else:
+        # No one is rotating the log
+        handler = logging.FileHandler(name)
+        how = ""
+
+    # Format handler
+    global log_fmt
+    handler.setFormatter(log_fmt)
+
+    # Log the start of file logging to the alpenhorn logger.
+    # We do this _before_ adding the file handler to prevent
+    # duplicating this message (via both the file handler and
+    # the start-up handler).
+    alpen_logger = logging.getLogger("alpenhorn")
+    alpen_logger.info(f"Logging to{how} {name}")
+
+    return handler
+
+
+def configure_logging() -> None:
+    """Configure the logger from from the config, and start logging.
+
+    This will flush any log messages accumulated from program start until now
+    to the log after it has been started.
+
+    Raises
+    ------
+    KeyError
+        A required key was missing from the logging config.
+    ValueError
+        An invalid value was found in the logging config.
+    """
+
+    # TODO: apply different settings for the client
+
+    def _check_level(level, source):
         if level not in ["DEBUG", "INFO", "WARNING", "ERROR", "CRITICAL"]:
-            raise RuntimeError("Log level %s is not valid" % level)
+            raise ValueError(f"Log level {level} defined by {source} is not valid")
+
+    logger_config = config.config.get("logging", dict())
 
     # Set the overall level
-    level = config.config["logging"]["level"].upper()
-    _check_level(level)
+    level = logger_config["level"].upper()
+    _check_level(level, "logging.level")
 
+    root_logger = logging.getLogger()
     root_logger.setLevel(level)
 
     # Apply any module specific logging levels
-    for name, level in config.config["logging"]["module_levels"].items():
+    for name, level in logger_config["module_levels"].items():
         logger = logging.getLogger(name)
         level = level.upper()
 
-        _check_level(level)
+        _check_level(level, f"logging.module_levels.{name}")
         logger.setLevel(level)
+
+    # Configure syslog logging, maybe
+    if "syslog" in logger_config:
+        syslog_handler = configure_sys_logging(logger_config["syslog"])
+    else:
+        syslog_handler = None
+
+    # Configure file logging, maybe
+    if "file" in logger_config:
+        file_handler = configure_file_logging(logger_config["file"])
+    else:
+        file_handler = None
+
+    # Start logging to the configured loggers
+    global log_buffer
+    for handler in [syslog_handler, file_handler]:
+        if handler:
+            root_logger.addHandler(handler)
+            log_buffer.addTarget(handler)
+
+    # Flush the start-up buffer to all targets
+    log_buffer.flush()
+
+    # Shut down and delete the start-up handler
+    root_logger.removeHandler(log_buffer)
+    log_buffer.close()
+    log_buffer = None
diff --git a/alpenhorn/service.py b/alpenhorn/service.py
index 7b2d940..ecd179e 100755
--- a/alpenhorn/service.py
+++ b/alpenhorn/service.py
@@ -33,11 +33,14 @@ sys.excepthook = log_exception
 def cli():
     """Alpenhorn data management service."""
 
+    # Initialise logging
+    logger.init_logging()
+
     # Load the configuration for alpenhorn
     config.load_config()
 
-    # Set up logging
-    logger.start_logging()
+    # Set up logging based on config
+    logger.configure_logging()
 
     # Load alpenhorn extensions
     extensions.load_extensions()
diff --git a/requirements.txt b/requirements.txt
index d14d8cb..2cc1441 100644
--- a/requirements.txt
+++ b/requirements.txt
@@ -1,4 +1,5 @@
 Click >= 6.0
+concurrent-log-handler
 peewee ~= 3.0
 PyYAML
 tabulate


Test patch:
diff --git a/tests/conftest.py b/tests/conftest.py
index d687bc5..1485968 100644
--- a/tests/conftest.py
+++ b/tests/conftest.py
@@ -2,8 +2,10 @@
 import os
 import pytest
 import shutil
+import logging
 from unittest.mock import patch, MagicMock
 
+import alpenhorn.logger
 from alpenhorn import config, db, extensions
 from alpenhorn.queue import FairMultiFIFOQueue
 from alpenhorn.storage import StorageGroup, StorageNode
@@ -51,7 +53,29 @@ def pytest_configure(config):
 
 
 @pytest.fixture
-def set_config(request):
+def logger():
+    """Set up for log testing
+
+    Yields alpenhorn.logger.
+    """
+
+    alpenhorn.logger.init_logging()
+
+    yield alpenhorn.logger
+
+    # Teardown
+    root = logging.getLogger()
+
+    # Remove all handlers from the root logger
+    handlers = root.handlers
+    for handler in handlers:
+        root.removeHandler(handler)
+
+    alpenhorn.logger.log_buffer = None
+
+
+@pytest.fixture
+def set_config(request, logger):
     """Set alpenhorn.config.config for testing.
 
     Any value given in the alpenhorn_config mark is merged into the
diff --git a/tests/test_logger.py b/tests/test_logger.py
new file mode 100644
index 0000000..206f6e5
--- /dev/null
+++ b/tests/test_logger.py
@@ -0,0 +1,292 @@
+"""Test alpenhorn.logger"""
+import pytest
+import socket
+import logging
+import pathlib
+import alpenhorn.logger
+from unittest.mock import patch, MagicMock
+
+
+def test_max_bytes_from_config():
+    """Test throwing things at _max_bytes_from_config"""
+
+    assert alpenhorn.logger._max_bytes_from_config("1") == 1
+    assert alpenhorn.logger._max_bytes_from_config(12) == 12
+    assert alpenhorn.logger._max_bytes_from_config("1k") == 1024
+    assert alpenhorn.logger._max_bytes_from_config("1M") == 1024 * 1024
+    assert alpenhorn.logger._max_bytes_from_config("1G") == 1024 * 1024 * 1024
+    assert alpenhorn.logger._max_bytes_from_config("3.3") == 3
+    assert alpenhorn.logger._max_bytes_from_config(3.3) == 3
+    assert alpenhorn.logger._max_bytes_from_config("3.3k") == int(3.3 * 1024)
+    assert alpenhorn.logger._max_bytes_from_config("3.3M") == int(3.3 * 1024 * 1024)
+
+    for string in ["", 0, -1, "3.3T", "words"]:
+        with pytest.raises(ValueError):
+            alpenhorn.logger._max_bytes_from_config(string)
+
+
+def test_log_buffer_gone(set_config, logger):
+    """configure_logging() deletes logger.log_buffer"""
+
+    assert logger.log_buffer is not None
+    logger.configure_logging()
+    assert logger.log_buffer is None
+
+
+@pytest.mark.alpenhorn_config({"logging": {"syslog": {"test": True}}})
+def test_config_sys_logging(set_config, logger):
+    """Check that configure_logging calls configure_sys_logging() when a
+    "logging.syslog" section is present."""
+
+    with patch("alpenhorn.logger.configure_sys_logging") as mock:
+        logger.configure_logging()
+
+    mock.assert_called_once_with({"test": True})
+
+
+@pytest.mark.alpenhorn_config({"logging": {"syslog": {"enable": 1}}})
+def test_syslog_bad_enable(set_config, logger):
+    """Test non-bool syslog.enable."""
+
+    with pytest.raises(ValueError):
+        logger.configure_logging()
+
+
+@pytest.mark.alpenhorn_config({"logging": {"syslog": {"facility": "invalid"}}})
+def test_syslog_bad_facility(set_config, logger):
+    """Test invalid syslog.facility."""
+
+    with pytest.raises(ValueError):
+        logger.configure_logging()
+
+
+@pytest.mark.alpenhorn_config({"logging": {"syslog": {"enable": False}}})
+def test_syslog_disabled(set_config, logger):
+    """Test explicit disable of syslog."""
+
+    with patch("logging.handlers.SysLogHandler") as mock:
+        logger.configure_logging()
+
+    mock.assert_not_called()
+
+
+@pytest.mark.alpenhorn_config({"logging": {"syslog": {"enable": True}}})
+def test_syslog_default(set_config, logger):
+    """Test default syslog config."""
+
+    mock = MagicMock()
+    mock.facility_names = {"user": 123}
+
+    with patch("logging.handlers.SysLogHandler", mock):
+        logger.configure_logging()
+
+    mock.assert_called_with(
+        address=("localhost", 514), facility=123, socktype=socket.SOCK_DGRAM
+    )
+
+
+@pytest.mark.alpenhorn_config(
+    {
+        "logging": {
+            "syslog": {
+                "address": "addr",
+                "port": 12,
+                "facility": "SOMETHING",
+                "use_tcp": True,
+            }
+        }
+    }
+)
+def test_syslog_params(set_config, logger):
+    """Test syslog config params."""
+
+    mock = MagicMock()
+    mock.facility_names = {"user": 123, "something": 45}
+
+    with patch("logging.handlers.SysLogHandler", mock):
+        logger.configure_logging()
+
+    mock.assert_called_with(
+        address=("addr", 12), facility=45, socktype=socket.SOCK_STREAM
+    )
+
+
+@pytest.mark.alpenhorn_config({"logging": {"syslog": {"address": "sock", "port": 0}}})
+def test_syslog_domain_socket(set_config, logger):
+    """Test syslog domain socket config."""
+
+    mock = MagicMock()
+    mock.facility_names = {"user": 123}
+
+    with patch("logging.handlers.SysLogHandler", mock):
+        logger.configure_logging()
+
+    mock.assert_called_with(address="sock", facility=123, socktype=socket.SOCK_DGRAM)
+
+
+@pytest.mark.alpenhorn_config({"logging": {"syslog": {"use_tcp": "sometimes"}}})
+def test_syslog_bad_use_tcp(set_config, logger):
+    """Test non-bool syslog.use_tcp."""
+
+    with pytest.raises(ValueError):
+        logger.configure_logging()
+
+
+@pytest.mark.alpenhorn_config({"logging": {"file": {"test": True}}})
+def test_config_file_logging(set_config, logger):
+    """Check that configure_logging calls configure_file_logging() when a
+    "logging.file" section is present."""
+
+    with patch("alpenhorn.logger.configure_file_logging") as mock:
+        logger.configure_logging()
+
+    mock.assert_called_once_with({"test": True})
+
+
+@pytest.mark.alpenhorn_config({"logging": {"file": {"watch": True}}})
+def test_file_no_name(set_config, logger):
+    """Can't have logger.file without logger.file.name."""
+
+    with pytest.raises(KeyError):
+        logger.configure_logging()
+
+
+@pytest.mark.alpenhorn_config({"logging": {"file": {"name": "/log", "watch": "sure"}}})
+def test_file_bad_watch(set_config, logger):
+    """Test non-bool file.watch."""
+
+    with pytest.raises(ValueError):
+        logger.configure_logging()
+
+
+@pytest.mark.alpenhorn_config(
+    {"logging": {"file": {"name": "/log", "rotate": "maybe"}}}
+)
+def test_file_bad_rotate(set_config, logger):
+    """Test non-bool file.rotate."""
+
+    with pytest.raises(ValueError):
+        logger.configure_logging()
+
+
+@pytest.mark.alpenhorn_config(
+    {"logging": {"file": {"name": "/log", "watch": True, "rotate": True}}}
+)
+def test_file_watch_rotate(set_config, logger):
+    """Can't set both file.watch and file.rotate to True."""
+
+    with pytest.raises(ValueError):
+        logger.configure_logging()
+
+
+@pytest.mark.alpenhorn_config({"logging": {"file": {"name": "/log"}}})
+def test_file_logging(set_config, logger, xfs):
+    """Test file logging.
+
+    Also tests that log messages emitted before configurin_logging()
+    do end up in the resultant logs.
+    """
+
+    log = logging.getLogger()
+
+    log.warning("PRE-START")
+    logger.configure_logging()
+    log.warning("POST-START")
+
+    with open("/log") as f:
+        whole_log = f.read()
+
+    assert "PRE-START" in whole_log
+    assert "POST-START" in whole_log
+
+
+@pytest.mark.alpenhorn_config({"logging": {"file": {"name": "/log", "watch": True}}})
+def test_watchfile_logging(set_config, logger, xfs):
+    """Test file logging and watching."""
+
+    with patch("logging.handlers.WatchedFileHandler") as mock:
+        logger.configure_logging()
+
+    mock.assert_called_with(pathlib.Path("/log"))
+
+
+@pytest.mark.alpenhorn_config(
+    {"logging": {"file": {"name": "/log", "backup_count": "0", "rotate": True}}}
+)
+def test_rotate_bad_count(set_config, logger, xfs):
+    """Test a bad backup_count while rotating."""
+
+    with pytest.raises(ValueError):
+        logger.configure_logging()
+
+
+@pytest.mark.alpenhorn_config(
+    {"logging": {"file": {"name": "/log", "max_bytes": "Pi", "rotate": True}}}
+)
+def test_rotate_bad_size(set_config, logger, xfs):
+    """Test a bad max_bytes while rotating."""
+
+    with pytest.raises(ValueError):
+        logger.configure_logging()
+
+
+@pytest.mark.alpenhorn_config(
+    {
+        "logging": {
+            "file": {
+                "name": "/log",
+                "max_bytes": 1234,
+                "backup_count": 567,
+                "rotate": True,
+            }
+        }
+    }
+)
+def test_rotatefile_logging(set_config, logger, xfs):
+    """Test file logging and rotating."""
+
+    mock = MagicMock()
+
+    with patch("alpenhorn.logger.RotatingFileHandler") as mock:
+        logger.configure_logging()
+
+    mock.assert_called_with(pathlib.Path("/log"), maxBytes=1234, backupCount=567)
+
+
+@pytest.mark.alpenhorn_config(
+    {
+        "logging": {
+            "level": "WARNING",
+            "module_levels": {"mod1": "INFO", "mod2": "DEBUG"},
+        }
+    }
+)
+def test_logger_levels(set_config, logger):
+    """Test setting logging levels."""
+
+    logger.configure_logging()
+
+    root = logging.getLogger()
+    assert root.getEffectiveLevel() == logging.WARNING
+
+    log = logging.getLogger("mod1")
+    assert log.getEffectiveLevel() == logging.INFO
+
+    log = logging.getLogger("mod2")
+    assert log.getEffectiveLevel() == logging.DEBUG
+
+
+@pytest.mark.alpenhorn_config({"logging": {"level": "INVALID"}})
+def test_logger_bad_level(set_config, logger):
+    """Test bad logging levels."""
+
+    with pytest.raises(ValueError):
+        logger.configure_logging()
+
+
+@pytest.mark.alpenhorn_config({"logging": {"module_levels": {"alpenhorn": "INVALID"}}})
+def test_logger_bad_module_levels(set_config, logger):
+    """Test bad logging levels."""
+
+    with pytest.raises(ValueError):
+        logger.configure_logging()