Skip to content

Commit

Permalink
pyln: Add logging handler that passes records to lightningd
Browse files Browse the repository at this point in the history
It is often pretty usefuk to use the builtin logging module to debug things,
including libraries that a plugin may use. This adds a simple
`PluginLogHandler` that maps the python logging levels to the `lightningd`
logging levels, and formats the record in a way that it doesn't clutter up the
`lightningd` logs (no duplicate timestamps and levels).

This allow us to tweak the log level that is reported to `lightningd` simply
using the following

```python3
import logging
logging.basicConfig(level=logging.DEBUG)
```

Notice that in order for the logs to be displayed on the terminal or the
logfile, both the logging level in the plugin _and_ the `--log-level`
`lightningd` is running need to be adjusted (the python logging level only
controls which messages get forwarded to `lightningd`, it does not have the
power to overrule `lightningd` about what to actually display).

I chose `logging.INFO` as the default, since libraries have a tendency to spew
out everything in `logging.DEBUG` mode

Changelog-Added: pyln: Plugins have been integrated with the `logging` module for easier debugging and error reporting.
  • Loading branch information
cdecker committed Oct 13, 2020
1 parent a297c1b commit cdb28b1
Showing 1 changed file with 48 additions and 0 deletions.
48 changes: 48 additions & 0 deletions contrib/pyln-client/pyln/client/plugin.py
Original file line number Diff line number Diff line change
Expand Up @@ -8,6 +8,7 @@
import inspect
import io
import json
import logging
import math
import os
import re
Expand Down Expand Up @@ -210,6 +211,13 @@ def convert_featurebits(

self.write_lock = RLock()

# Initialize the logging system with a handler that passes the logs to
# lightning for display.
log_handler = PluginLogHandler(self)
formatter = logging.Formatter('%(name)-12s: %(message)s')
log_handler.setFormatter(formatter)
logging.getLogger('').addHandler(log_handler)

def add_method(self, name: str, func: Callable[..., Any],
background: bool = False,
category: Optional[str] = None,
Expand Down Expand Up @@ -790,3 +798,43 @@ def monkey_patch(plugin: Plugin, stdout: bool = True,
setattr(sys, "stdout", PluginStream(plugin, level="info"))
if stderr:
setattr(sys, "stderr", PluginStream(plugin, level="warn"))


class PluginLogHandler(logging.StreamHandler):
def __init__(self, plugin: Plugin) -> None:
logging.StreamHandler.__init__(self, stream=None)
self.plugin = plugin

# Map the numeric levels to the string levels lightningd understands.
self.levels = {
logging.CRITICAL: 'error',
logging.ERROR: 'error',
logging.WARNING: 'info',
logging.INFO: 'info',
logging.DEBUG: 'debug',
logging.NOTSET: 'debug',
}

def emit(self, record: logging.LogRecord) -> None:
"""Emit a record.
If a formatter is specified, it is used to format the record. Numeric
levels are translated into strings that lightningd understands. If
exception information is present, it is formatted using
traceback.print_exception and appended to the stream.
"""
try:
msg = self.format(record)
level = self.levels.get(record.levelno, 'info')
self.plugin.log(msg, level=level)
except RecursionError: # See issue https://bugs.python.org/issue36272
raise
except Exception:
self.handleError(record) # Writes errors in logging system to stderr
pass

def flush(self) -> None:
"""Flushing is a no-op since each message is written as it comes in.
"""
pass

0 comments on commit cdb28b1

Please sign in to comment.