Standardise logging for interactive and plot/archive 'daemons'

CHANGELOG.md

@@ -16,6 +16,8 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0
   ([#885](https://github.com/ericaltendorf/plotman/pull/885))
 - `supervisord` now used in Docker image.
   ([#898](https://github.com/ericaltendorf/plotman/pull/898))
+- Output same entries to plotman.log from 'plotman interactive' and ' plotman plot/archive' "daemons".
+  ([#878](https://github.com/ericaltendorf/plotman/pull/878))
 
 ## [0.5.1] - 2021-07-15
 ### Fixed

src/plotman/archive.py

@@ -18,7 +18,7 @@
 from plotman import configuration, job, manager, plot_util
 
 
-logger = logging.getLogger(__name__)
+disk_space_logger = logging.getLogger("disk_space")
 
 _WINDOWS = sys.platform == 'win32'
 
@@ -164,15 +164,15 @@ def get_archdir_freebytes(arch_cfg: configuration.Archiving) -> typing.Tuple[typ
             archdir_freebytes[archdir.strip()] = freebytes
 
     for line in log_messages:
-        logger.info(line)
+        disk_space_logger.info(line)
 
-    logger.info('stdout from disk space script:')
+    disk_space_logger.info('stdout from disk space script:')
     for line in stdout.splitlines():
-        logger.info(f'    {line}')
+        disk_space_logger.info(f'    {line}')
 
-    logger.info('stderr from disk space script:')
+    disk_space_logger.info('stderr from disk space script:')
     for line in stderr.splitlines():
-        logger.info(f'    {line}')
+        disk_space_logger.info(f'    {line}')
 
     return archdir_freebytes, log_messages
 

src/plotman/configuration.py

@@ -268,7 +268,8 @@ class Logging:
     plots: str = os.path.join(appdirs.user_data_dir("plotman"), 'plots')
     transfers: str = os.path.join(appdirs.user_data_dir("plotman"), 'transfers')
     application: str = os.path.join(appdirs.user_log_dir("plotman"), 'plotman.log')
-
+    disk_spaces: str = os.path.join(appdirs.user_log_dir("plotman"), 'plotman-disk_spaces.log')
+
     def setup(self) -> None:
         os.makedirs(self.plots, exist_ok=True)
         os.makedirs(self.transfers, exist_ok=True)
@@ -287,6 +288,12 @@ def create_transfer_log_path(self, time: pendulum.DateTime) -> str:
             directory=self.transfers,
             group='transfer',
         )
+    def create_tdisk_space_log_path(self, time: pendulum.DateTime) -> str:
+        return self._create_log_path(
+            time=time,
+            directory=self.disk_spaces,
+            group='disk_space',
+        )
 
     def _create_log_path(self, time: pendulum.DateTime, directory: str, group: str) -> str:
         timestamp = time.isoformat(timespec='microseconds').replace(':', '_')

src/plotman/interactive.py

@@ -6,11 +6,12 @@
 import subprocess
 import sys
 import typing
+import logging
 
 from plotman import archive, configuration, manager, reporting
 from plotman.job import Job
 
-
+root_logger = logging.getLogger()
 class TerminalTooSmallError(Exception):
     pass
 
@@ -141,12 +142,17 @@ def curses_main(stdscr: typing.Any, cmd_autostart_plotting: typing.Optional[bool
                     if msg.find("stagger") < 0:
                         aging_reason = msg
                     plotting_status = msg
+                root_logger.info('[plot] %s', msg)
 
             if cfg.archiving is not None:
                 if archiving_active:
                     archiving_status, log_messages = archive.spawn_archive_process(cfg.directories, cfg.archiving, cfg.logging, jobs)
-                    for log_message in log_messages:
-                        log.log(log_message)
+                    if log_messages:
+                        for log_message in log_messages:
+                            log.log(log_message)
+                            root_logger.info('[archive] %s', log_message)
+                    else:
+                        root_logger.info('[archive] %s', archiving_status)
 
                 archdir_freebytes, log_messages = archive.get_archdir_freebytes(cfg.archiving)
                 for log_message in log_messages:

src/plotman/plotman.py

@@ -170,29 +170,46 @@ def main() -> None:
 
     with cfg.setup():
         root_logger = logging.getLogger()
-        handler = logging.handlers.RotatingFileHandler(
+        root_handler = logging.handlers.RotatingFileHandler(
             backupCount=10,
             encoding='utf-8',
             filename=cfg.logging.application,
             maxBytes=10_000_000,
         )
-        formatter = Iso8601Formatter(fmt='%(asctime)s: %(message)s')
-        handler.setFormatter(formatter)
-        root_logger.addHandler(handler)
+        root_formatter = Iso8601Formatter(fmt='%(asctime)s: %(message)s')
+        root_handler.setFormatter(root_formatter)
+        root_logger.addHandler(root_handler)
         root_logger.setLevel(logging.INFO)
-        root_logger.info('abc')
+        root_logger.info('Start root logger')
+
+        disk_space_logger = logging.getLogger("disk_space")
+        disk_space_logger.propagate = False
+        disk_space_handler = logging.handlers.RotatingFileHandler(
+            backupCount=10,
+            encoding='utf-8',
+            filename=cfg.logging.disk_spaces,
+            maxBytes=10_000_000,
+        )
+        disk_space_formatter = Iso8601Formatter(fmt='%(asctime)s: %(message)s')
+        disk_space_handler.setFormatter(disk_space_formatter)
+        disk_space_logger.addHandler(disk_space_handler)
+        disk_space_logger.setLevel(logging.INFO)
+        disk_space_logger.info('Start disk space logger')
 
         #
         # Stay alive, spawning plot jobs
         #
         if args.cmd == 'plot':
             print('...starting plot loop')
             while True:
-                wait_reason = manager.maybe_start_new_plot(cfg.directories, cfg.scheduling, cfg.plotting, cfg.logging)
+                (started, msg) = manager.maybe_start_new_plot(cfg.directories, cfg.scheduling, cfg.plotting, cfg.logging)
 
                 # TODO: report this via a channel that can be polled on demand, so we don't spam the console
-                if wait_reason:
-                    print('...sleeping %d s: %s' % (cfg.scheduling.polling_time_s, wait_reason))
+                if started:
+                    print('%s' % (msg))
+                else:
+                    print('...sleeping %d s: %s' % (cfg.scheduling.polling_time_s, msg))
+                root_logger.info('[plot] %s', msg)
 
                 time.sleep(cfg.scheduling.polling_time_s)
 
@@ -249,21 +266,28 @@ def main() -> None:
             # Start running archival
             elif args.cmd == 'archive':
                 if cfg.archiving is None:
-                    print('archiving not configured but is required for this command')
+                    start_msg = 'archiving not configured but is required for this command'
+                    print(start_msg)
+                    root_logger.info('[archive] %s', start_msg)
                 else:
-                    print('...starting archive loop')
+                    start_msg = '...starting archive loop'
+                    print(start_msg)
+                    root_logger.info('[archive] %s', start_msg)
                     firstit = True
                     while True:
                         if not firstit:
-                            print('Sleeping 60s until next iteration...')
-                            time.sleep(60)
+                            print('Sleeping %d s until next iteration...' % (cfg.scheduling.polling_time_s))
+                            time.sleep(cfg.scheduling.polling_time_s)
                             jobs = Job.get_running_jobs(cfg.logging.plots)
                         firstit = False
 
                         archiving_status, log_messages = archive.spawn_archive_process(cfg.directories, cfg.archiving, cfg.logging, jobs)
-                        for log_message in log_messages:
-                            print(log_message)
-
+                        if log_messages:
+                            for log_message in log_messages:
+                                print(log_message)
+                                root_logger.info('[archive] %s', log_message)
+                        else:
+                            root_logger.info('[archive] %s', archiving_status)
 
             # Debugging: show the destination drive usage schedule
             elif args.cmd == 'dsched':