Add initial logging system implementation

4 files changed, 106 insertions, 13 deletions

diff --git a/doc/roadmap.rst b/doc/roadmap.rst
index b4517bb..8cc3670 100644
--- a/doc/roadmap.rst
+++ b/doc/roadmap.rst
@@ -22,6 +22,8 @@
 
 * [X] Respond to state requests
 
+* [ ] Handle per-module RPC requests
+
 
 The module management system will be the heart of ``ncserver``.  Similar to
 modules in Charybdis/Atheme or GlorIRCd.  Each module will provide a piece of
@@ -58,14 +60,14 @@ Resolved TBDs
 
 
 
-[ ] Logging system
+[/] Logging system
 ------------------
 
-* [ ] Output format
+* [X] Output format
 
-* [ ] Configuration
+* [X] Configuration
 
-* [ ] Event logging
+* [/] Event logging
 
   * [ ] auth
 
@@ -87,13 +89,13 @@ Resolved TBDs
 
     * [ ] RPC success
 
-  * [ ] config
+  * [/] config
 
     * [ ] Configuration editing
 
     * [ ] Configuration edited
 
-    * [ ] Configuration reading
+    * [X] Configuration reading
 
     * [ ] Configuration operation denied
 
@@ -111,16 +113,16 @@ This feature will require in-depth discussion.
 
 
 
-[ ] Service management module
+[/] Service management module
 -----------------------------
 
-* [ ] Design API
+* [X] Design API
 
-* [ ] Design YANG model
+* [X] Design YANG model
 
-* [ ] Implement module
+* [X] Implement module
 
-  * [ ] OpenRC
+  * [/] OpenRC
 
   * [ ] s6?
 
diff --git a/ncserver/base/log.py b/ncserver/base/log.py
new file mode 100644
index 0000000..053baec
--- /dev/null
+++ b/ncserver/base/log.py
@@ -0,0 +1,70 @@
+"""
+NETCONF for APK Distributions server:
+    Logging setup and routines.
+
+Copyright © 2020 Adélie Software in the Public Benefit, Inc.
+
+Released under the terms of the NCSA license.  See the LICENSE file included
+with this source distribution for more information.
+
+SPDX-License-Identifier: NCSA
+"""
+
+
+import logging
+
+from socket import gethostname
+from taillight import Signal
+
+
+HOSTNAME_CHANGED = Signal(('node_changed', 'sys:hostname'))
+"""The signal that will fire when the hostname is changed."""
+
+HANDLER = logging.StreamHandler()
+"""The root log handler."""
+
+LOG_AUTH = logging.getLogger('ncserver.auth')
+"""The authentication logger."""
+
+LOG_CONFIG = logging.getLogger('ncserver.config')
+"""The configuration logger."""
+
+LOG_OPERATIONAL = logging.getLogger('ncserver.operational')
+"""The operational logger."""
+
+
+def configure_format(hostname: str):
+    """Configure the formatter for the root log handler."""
+    fmt = logging.Formatter('%(asctime)s ' + hostname +
+                            ' %(name)s %(levelname)s: %(message)s',
+                            '%Y-%m-%dT%H:%M:%S')
+    HANDLER.setFormatter(fmt)
+
+
+def configure_logging(level: int):
+    """Configure the logging system."""
+    configure_format(gethostname())
+
+    root = logging.getLogger()
+
+    HANDLER.setLevel(level)
+    root.setLevel(level)
+
+    root.addHandler(HANDLER)
+
+
+
+HOSTNAME_CHANGED.add(configure_format)
+
+if not hasattr(logging, 'NOTICE'):
+    logging.addLevelName(25, 'NOTICE')
+    logging.NOTICE = 25
+
+    def log_notice(self, message, *args, **kwargs):
+        if self.isEnabledFor(25):
+            self._log(25, message, args, **kwargs)
+    logging.getLoggerClass().notice = log_notice
+
+    def root_notice(message, *args, **kwargs):
+        logging.log(25, message, *args, **kwargs)
+    logging.notice = root_notice
diff --git a/ncserver/base/util.py b/ncserver/base/util.py
index 5df4704..164e309 100644
--- a/ncserver/base/util.py
+++ b/ncserver/base/util.py
@@ -22,6 +22,11 @@ def _(the_string: str) -> str:
     return the_string
 
 
+def user_for_session(session) -> str:
+    """Determine the user for the specified session."""
+    return session.pkt_stream.stream.get_transport().get_username()
+
+
 def ensure_leaf(rpc, node):
     """Ensure that the node is a leaf (contains no child nodes)."""
     if len(node) > 0:
diff --git a/ncserver/server.py b/ncserver/server.py
index 0c56c2a..dd35b2d 100644
--- a/ncserver/server.py
+++ b/ncserver/server.py
@@ -17,13 +17,22 @@ from lxml import etree
 from netconf import error, util
 from netconf.server import NetconfSSHServer, SSHAuthorizedKeysController
 
+from ncserver.base.log import configure_logging, LOG_CONFIG
 from ncserver.base.modman import ModuleManager
+from ncserver.base.util import user_for_session
 from ncserver.config import ConfigManager
 
 
 QName = etree.QName  # pylint: disable=I1101
 
 
+def log_read(session, rpc):
+    """Log a configuration read."""
+    LOG_CONFIG.debug('%s on session %d is requesting configuration: %s',
+            user_for_session(session), session.session_id, etree.tostring(rpc)
+    )
+
+
 class Server:
     """The NETCONF server component."""
 
@@ -40,9 +49,14 @@ class Server:
 
         self.debug = self.config.get('server', 'debug')
         if self.debug:
-            logging.basicConfig(level=logging.DEBUG)
+            configure_logging(logging.DEBUG)
         else:
-            logging.basicConfig(level=logging.INFO)
+            loglevel = 'notice'
+            try:
+                loglevel = self.config.get('server', 'loglevel')
+            except KeyError:
+                pass
+            configure_logging(getattr(logging, loglevel.upper()))
 
         self.server = NetconfSSHServer(
             self.auth, self, port, self.config.get('server', 'host_key'),
@@ -71,6 +85,7 @@ class Server:
 
     def rpc_get(self, session, rpc, filter_or_none):  # pylint: disable=W0613
         """Handle the <get/> RPC."""
+        log_read(session, rpc)
         root = util.elm('nc:data')
         self.modman.collect_running(root)
         self.modman.collect_operational(root)
@@ -80,6 +95,7 @@ class Server:
     # pylint: disable=W0613
     def rpc_get_config(self, session, rpc, source, filter_or_none):
         """Handle the <get-config/> RPC."""
+        log_read(session, rpc)
         root = util.elm('nc:data')
         self.modman.collect_running(root)