From cdb28b11ef3dbec6822d30688d9eaff844987b43 Mon Sep 17 00:00:00 2001
From: Christian Decker <decker.christian@gmail.com>
Date: Tue, 29 Sep 2020 11:26:25 +0200
Subject: [PATCH] pyln: Add logging handler that passes records to lightningd

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.
---
 contrib/pyln-client/pyln/client/plugin.py | 48 +++++++++++++++++++++++
 1 file changed, 48 insertions(+)

diff --git a/contrib/pyln-client/pyln/client/plugin.py b/contrib/pyln-client/pyln/client/plugin.py
index 78c1976d5ee9..e4bc8908c143 100644
--- a/contrib/pyln-client/pyln/client/plugin.py
+++ b/contrib/pyln-client/pyln/client/plugin.py
@@ -8,6 +8,7 @@
 import inspect
 import io
 import json
+import logging
 import math
 import os
 import re
@@ -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,
@@ -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