From 4541c53f9b6f6f882f0e735fe63a48de870545c4 Mon Sep 17 00:00:00 2001 From: Graeme Seaton Date: Sat, 17 Jul 2021 17:35:52 +0100 Subject: [PATCH 01/11] Cleanup plot log / send disk_space to separate log --- src/plotman/archive.py | 2 +- src/plotman/configuration.py | 9 ++++++++- src/plotman/plotman.py | 29 ++++++++++++++++++++++------- 3 files changed, 31 insertions(+), 9 deletions(-) diff --git a/src/plotman/archive.py b/src/plotman/archive.py index 136f2bab..453088aa 100644 --- a/src/plotman/archive.py +++ b/src/plotman/archive.py @@ -18,7 +18,7 @@ from plotman import configuration, job, manager, plot_util -logger = logging.getLogger(__name__) +logger = logging.getLogger("disk_space") _WINDOWS = sys.platform == 'win32' diff --git a/src/plotman/configuration.py b/src/plotman/configuration.py index df03e143..f7e7a831 100644 --- a/src/plotman/configuration.py +++ b/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(':', '_') diff --git a/src/plotman/plotman.py b/src/plotman/plotman.py index 5312b78c..eaaed198 100755 --- a/src/plotman/plotman.py +++ b/src/plotman/plotman.py @@ -170,29 +170,44 @@ 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') + disk_space_logger = logging.getLogger("disk_space") + 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('abc') + # # 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)) time.sleep(cfg.scheduling.polling_time_s) From 523960e0809ba985939fffa8b192700fffb33be7 Mon Sep 17 00:00:00 2001 From: Graeme Seaton Date: Sun, 18 Jul 2021 10:21:36 +0100 Subject: [PATCH 02/11] Log cli to root log --- src/plotman/archive.py | 12 ++++++------ src/plotman/plotman.py | 15 +++++++++++---- 2 files changed, 17 insertions(+), 10 deletions(-) diff --git a/src/plotman/archive.py b/src/plotman/archive.py index 453088aa..0101651a 100644 --- a/src/plotman/archive.py +++ b/src/plotman/archive.py @@ -18,7 +18,7 @@ from plotman import configuration, job, manager, plot_util -logger = logging.getLogger("disk_space") +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 diff --git a/src/plotman/plotman.py b/src/plotman/plotman.py index eaaed198..db83c6d8 100755 --- a/src/plotman/plotman.py +++ b/src/plotman/plotman.py @@ -180,7 +180,7 @@ def main() -> None: 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_handler = logging.handlers.RotatingFileHandler( @@ -193,7 +193,7 @@ def main() -> None: disk_space_handler.setFormatter(disk_space_formatter) disk_space_logger.addHandler(disk_space_handler) disk_space_logger.setLevel(logging.INFO) - disk_space_logger.info('abc') + disk_space_logger.info('Start disk space logger') # # Stay alive, spawning plot jobs @@ -206,8 +206,10 @@ def main() -> None: # TODO: report this via a channel that can be polled on demand, so we don't spam the console if started: print('%s' % (msg)) + root_logger.info(msg) else: print('...sleeping %d s: %s' % (cfg.scheduling.polling_time_s, msg)) + root_logger.info('...sleeping' + cfg.scheduling.polling_time_s + 's: ' + msg) time.sleep(cfg.scheduling.polling_time_s) @@ -266,11 +268,15 @@ def main() -> None: if cfg.archiving is None: print('archiving not configured but is required for this command') else: - print('...starting archive loop') + start_msg = '...starting archive loop' + print(start_msg) + root_logger.info(start_msg) firstit = True while True: if not firstit: - print('Sleeping 60s until next iteration...') + sleeping_msg = 'Sleeping 60s until next iteration...' + print(sleeping_msg) + root_logger.info(sleeping_msg) time.sleep(60) jobs = Job.get_running_jobs(cfg.logging.plots) firstit = False @@ -278,6 +284,7 @@ def main() -> None: archiving_status, log_messages = archive.spawn_archive_process(cfg.directories, cfg.archiving, cfg.logging, jobs) for log_message in log_messages: print(log_message) + root_logger.info(log_message) # Debugging: show the destination drive usage schedule From feae5e62e72c6c2235ddc2645885325bda262747 Mon Sep 17 00:00:00 2001 From: Graeme Seaton Date: Sun, 18 Jul 2021 10:28:37 +0100 Subject: [PATCH 03/11] str int --- src/plotman/plotman.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/plotman/plotman.py b/src/plotman/plotman.py index db83c6d8..2313445b 100755 --- a/src/plotman/plotman.py +++ b/src/plotman/plotman.py @@ -209,7 +209,7 @@ def main() -> None: root_logger.info(msg) else: print('...sleeping %d s: %s' % (cfg.scheduling.polling_time_s, msg)) - root_logger.info('...sleeping' + cfg.scheduling.polling_time_s + 's: ' + msg) + root_logger.info('...sleeping' + str(cfg.scheduling.polling_time_s) + 's: ' + msg) time.sleep(cfg.scheduling.polling_time_s) From f75faf1cc93f83e2a4270772a64762fadaa4bf82 Mon Sep 17 00:00:00 2001 From: Graeme Seaton Date: Sun, 18 Jul 2021 11:22:55 +0100 Subject: [PATCH 04/11] Disable disk space propagation --- src/plotman/plotman.py | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/src/plotman/plotman.py b/src/plotman/plotman.py index 2313445b..7247f4c1 100755 --- a/src/plotman/plotman.py +++ b/src/plotman/plotman.py @@ -183,6 +183,7 @@ def main() -> None: 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', @@ -209,7 +210,7 @@ def main() -> None: root_logger.info(msg) else: print('...sleeping %d s: %s' % (cfg.scheduling.polling_time_s, msg)) - root_logger.info('...sleeping' + str(cfg.scheduling.polling_time_s) + 's: ' + msg) + root_logger.info('...sleeping %d s: %s', cfg.scheduling.polling_time_s, msg) time.sleep(cfg.scheduling.polling_time_s) From f8bfec6d4988745f6902d7f77f7bb4b97907a6e2 Mon Sep 17 00:00:00 2001 From: Graeme Seaton Date: Sun, 18 Jul 2021 11:46:40 +0100 Subject: [PATCH 05/11] Log plot progress to root log --- src/plotman/interactive.py | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/src/plotman/interactive.py b/src/plotman/interactive.py index 82ea89a8..47ae7e8c 100644 --- a/src/plotman/interactive.py +++ b/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,6 +142,7 @@ 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(plotting_status) if cfg.archiving is not None: if archiving_active: From 3434083d1a8d280c2cd2c45ca85b7000c820aad8 Mon Sep 17 00:00:00 2001 From: Graeme Seaton Date: Sun, 18 Jul 2021 12:35:28 +0100 Subject: [PATCH 06/11] Add function prefix --- src/plotman/interactive.py | 3 ++- src/plotman/plotman.py | 13 ++++++------- 2 files changed, 8 insertions(+), 8 deletions(-) diff --git a/src/plotman/interactive.py b/src/plotman/interactive.py index 47ae7e8c..7be1890f 100644 --- a/src/plotman/interactive.py +++ b/src/plotman/interactive.py @@ -142,13 +142,14 @@ 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(plotting_status) + 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) + root_logger.info('[archive] %s', archiving_status) archdir_freebytes, log_messages = archive.get_archdir_freebytes(cfg.archiving) for log_message in log_messages: diff --git a/src/plotman/plotman.py b/src/plotman/plotman.py index 7247f4c1..d60cd2bd 100755 --- a/src/plotman/plotman.py +++ b/src/plotman/plotman.py @@ -207,10 +207,9 @@ def main() -> None: # TODO: report this via a channel that can be polled on demand, so we don't spam the console if started: print('%s' % (msg)) - root_logger.info(msg) else: print('...sleeping %d s: %s' % (cfg.scheduling.polling_time_s, msg)) - root_logger.info('...sleeping %d s: %s', cfg.scheduling.polling_time_s, msg) + root_logger.info('[plot] %s', msg) time.sleep(cfg.scheduling.polling_time_s) @@ -267,17 +266,18 @@ 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: start_msg = '...starting archive loop' print(start_msg) - root_logger.info(start_msg) + root_logger.info('[archive] %s', start_msg) firstit = True while True: if not firstit: sleeping_msg = 'Sleeping 60s until next iteration...' print(sleeping_msg) - root_logger.info(sleeping_msg) time.sleep(60) jobs = Job.get_running_jobs(cfg.logging.plots) firstit = False @@ -285,8 +285,7 @@ def main() -> None: archiving_status, log_messages = archive.spawn_archive_process(cfg.directories, cfg.archiving, cfg.logging, jobs) for log_message in log_messages: print(log_message) - root_logger.info(log_message) - + root_logger.info('[archive] %s', archiving_status) # Debugging: show the destination drive usage schedule elif args.cmd == 'dsched': From 3860aff06590655767ec408d6c8663c0334407e3 Mon Sep 17 00:00:00 2001 From: Graeme Seaton Date: Sun, 18 Jul 2021 13:29:40 +0100 Subject: [PATCH 07/11] Track archiving more effectively --- src/plotman/interactive.py | 9 ++++++--- src/plotman/plotman.py | 9 ++++++--- 2 files changed, 12 insertions(+), 6 deletions(-) diff --git a/src/plotman/interactive.py b/src/plotman/interactive.py index 7be1890f..70ba7c56 100644 --- a/src/plotman/interactive.py +++ b/src/plotman/interactive.py @@ -147,9 +147,12 @@ def curses_main(stdscr: typing.Any, cmd_autostart_plotting: typing.Optional[bool 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) - root_logger.info('[archive] %s', archiving_status) + 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: diff --git a/src/plotman/plotman.py b/src/plotman/plotman.py index d60cd2bd..d9bc8ce0 100755 --- a/src/plotman/plotman.py +++ b/src/plotman/plotman.py @@ -283,9 +283,12 @@ def main() -> None: 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) - root_logger.info('[archive] %s', archiving_status) + 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) # Debugging: show the destination drive usage schedule elif args.cmd == 'dsched': From 01b71c9a7b3c3bc9bb283eb76ef8ad9974c8d55e Mon Sep 17 00:00:00 2001 From: Graeme Seaton Date: Sun, 18 Jul 2021 14:10:39 +0100 Subject: [PATCH 08/11] Change archive daemon polling to system setting --- src/plotman/plotman.py | 5 ++--- 1 file changed, 2 insertions(+), 3 deletions(-) diff --git a/src/plotman/plotman.py b/src/plotman/plotman.py index d9bc8ce0..bbe8924b 100755 --- a/src/plotman/plotman.py +++ b/src/plotman/plotman.py @@ -276,9 +276,8 @@ def main() -> None: firstit = True while True: if not firstit: - sleeping_msg = 'Sleeping 60s until next iteration...' - print(sleeping_msg) - 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 From 128a0c45ff660d347f3a87f21fc8a9f847a22037 Mon Sep 17 00:00:00 2001 From: Graeme Seaton Date: Sun, 18 Jul 2021 14:30:16 +0100 Subject: [PATCH 09/11] Fix archive log --- src/plotman/plotman.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/plotman/plotman.py b/src/plotman/plotman.py index bbe8924b..469fc079 100755 --- a/src/plotman/plotman.py +++ b/src/plotman/plotman.py @@ -284,7 +284,7 @@ def main() -> None: archiving_status, log_messages = archive.spawn_archive_process(cfg.directories, cfg.archiving, cfg.logging, jobs) if log_messages: for log_message in log_messages: - log.log(log_message) + print(log_message) root_logger.info('[archive] %s', log_message) else: root_logger.info('[archive] %s', archiving_status) From 23cbc3507382245fe34f879c9f35c375fb54c094 Mon Sep 17 00:00:00 2001 From: Graeme Seaton Date: Sun, 18 Jul 2021 14:54:12 +0100 Subject: [PATCH 10/11] Add Changelog entry --- CHANGELOG.md | 1 + 1 file changed, 1 insertion(+) diff --git a/CHANGELOG.md b/CHANGELOG.md index aacf943c..87edf217 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -8,6 +8,7 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ## [unreleased] ### Fixed ### Added +- Output same entries to plotman.log from 'plotman interactive' and ' plotman plot/archive' "daemons" ## [0.5.1] - 2021-07-15 ### Fixed From ecbb472f582a96a3c2a70e3628834d3109cb3550 Mon Sep 17 00:00:00 2001 From: Kyle Altendorf Date: Sat, 28 Aug 2021 20:02:27 -0400 Subject: [PATCH 11/11] Update CHANGELOG.md --- CHANGELOG.md | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 56ec2a36..bd0bd942 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -16,7 +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" +- 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