log, email_server: Don't use syslog instead of journald

- Syslog is not used on FreedomBox machines. Logging to syslog instead of
journald looses a lot of information fields that are otherwise available.

- Drop logging additional information. Most of the information is already
present in full journald records. Access using journalctl -o json.

- Use the same formatting for console as the primary daemon.

- When logging for actions, capture warnings too.

- Always log to stderr so that UI can capture the traceback and show UI error
messages. stderr is never used for returning data.

Tests:

- Run action script using command line with a error 'sudo actions/email_server
home mk a b'. See the traceback message printed on stderr (not stdout). Message
is printed with full field information in journalctl -o json.

- Main daemon writes to stderr and to journal with same formatting as before.

- Adding a warning in action code or main daemon results in printing of the
warning with desired formatting. import warnings; warnings.warn('Foo warning')

Signed-off-by: Sunil Mohan Adapa <sunil@medhas.org>
Reviewed-by: James Valleroy <jvalleroy@mailbox.org>

actions/email_server

@@ -15,13 +15,12 @@ from plinth.modules.email_server import audit
 EXIT_SYNTAX = 10
 EXIT_PERM = 20
 
-logger = logging.getLogger(os.path.basename(__file__))
+logger = logging.getLogger(__file__)
 
 
 def main():
     """Parse arguments."""
-    # Set up logging
-    plinth.log.pipe_to_syslog(to_stderr='tty')
+    plinth.log.action_init()
 
     parser = argparse.ArgumentParser()
     parser.add_argument('module', help='Module to trigger action in')
@@ -34,7 +33,6 @@ def main():
         _call(args.module, args.action, args.arguments)
     except Exception as exception:
         logger.exception(exception)
-        _log_additional_info()
         sys.exit(1)
 
 
@@ -59,18 +57,5 @@ def _call(module_name, action_name, arguments):
     action(*arguments)
 
 
-def _log_additional_info():
-    """Log additional debugging information."""
-    import grp
-    import pwd
-    resu = ','.join(pwd.getpwuid(uid).pw_name for uid in os.getresuid())
-    resg = ','.join(grp.getgrgid(gid).gr_name for gid in os.getresgid())
-    pyver = sys.version.replace('\n', ' ')
-    logger.error('--- Additional Information ---')
-    logger.error('resuid=%s, resgid=%s', resu, resg)
-    logger.error('argv=%r, cwd=%r', sys.argv, os.getcwd())
-    logger.error('pyver=%s (%s)', pyver, os.uname().machine)
-
-
 if __name__ == '__main__':
     main()

plinth/log.py

@@ -5,12 +5,9 @@ Setup logging for the application.
 
 import importlib
 import logging
-import logging.handlers
-import sys
+import logging.config
 import warnings
 
-import cherrypy
-
 from . import cfg
 
 default_level = None
@@ -63,13 +60,8 @@ class ColoredFormatter(logging.Formatter):
         return super().format(record)
 
 
-def init():
-    """Setup the logging framework."""
-    # Remove default handlers and let the log message propagate to root logger.
-    for cherrypy_logger in [cherrypy.log.error_log, cherrypy.log.access_log]:
-        for handler in list(cherrypy_logger.handlers):
-            cherrypy_logger.removeHandler(handler)
-
+def _capture_warnings():
+    """Capture all warnings include deprecation warnings."""
     # Capture all Python warnings such as deprecation warnings
     logging.captureWarnings(True)
 
@@ -80,6 +72,25 @@ def init():
         warnings.filterwarnings('default', '', ImportWarning)
 
 
+def action_init():
+    """Initialize logging for action scripts."""
+    _capture_warnings()
+
+    logging.config.dictConfig(get_configuration())
+
+
+def init():
+    """Setup the logging framework."""
+    import cherrypy
+
+    # Remove default handlers and let the log message propagate to root logger.
+    for cherrypy_logger in [cherrypy.log.error_log, cherrypy.log.access_log]:
+        for handler in list(cherrypy_logger.handlers):
+            cherrypy_logger.removeHandler(handler)
+
+    _capture_warnings()
+
+
 def setup_cherrypy_static_directory(app):
     """Hush output from cherrypy static file request logging.
 
@@ -129,24 +140,3 @@ def get_configuration():
         configuration['root']['handlers'].append('journal')
 
     return configuration
-
-
-def pipe_to_syslog(level=logging.INFO, to_stderr=True):
-    """Make the root logger write to syslog and stderr. Useful in actions"""
-    logger = logging.getLogger()
-    logger.setLevel(level)
-
-    fmt = '/freedombox/%(name)s[%(process)d]: %(levelname)s: %(message)s'
-    formatter = logging.Formatter(fmt=fmt)
-
-    # Using syslog in Python: https://stackoverflow.com/q/3968669
-    syslog_handler = logging.handlers.SysLogHandler(address='/dev/log')
-    syslog_handler.setFormatter(formatter)
-    logger.addHandler(syslog_handler)
-
-    if to_stderr == 'tty' and sys.stdin.isatty():
-        to_stderr = True
-    if to_stderr is True:
-        stderr_handler = logging.StreamHandler()
-        stderr_handler.setFormatter(formatter)
-        logger.addHandler(stderr_handler)