diff --git a/.gitignore b/.gitignore index 3f805c1..2f85425 100644 --- a/.gitignore +++ b/.gitignore @@ -10,3 +10,7 @@ warnposeidon_main.txt xref-poseidon_main.html poseidon_controller_gui.cpython-36.pyc .txt + +# poseidon logging output +logs/ +*.log diff --git a/README.MD b/README.MD index 47ecd0b..edf1e6d 100644 --- a/README.MD +++ b/README.MD @@ -144,6 +144,14 @@ python3.5 poseidon_main.py If the sleds are not moving in the right direction simply rotate the relevant stepper motor plug (that connects to the CNC shield) 180 degrees and plug it back in. +## Logging +The controller mirrors everything it normally prints to the terminal into a rotating log file, so you have a record to look at when troubleshooting pump or serial-connection problems, even on a Raspberry Pi or with the packaged executable where no terminal is visible. The terminal output itself is unchanged. + +The log is written to `logs/poseidon.log` in the folder you launch from (rotated, capped at a few MB). Logging is **on by default**; to turn it off, set the environment variable `POSEIDON_LOG=0` before launching. + +To run the logging tests, from the `SOFTWARE/` folder run `python -m unittest test_poseidon_logging`. + + ## How does it work, and how to modify it. (Very easy!) The poseidon system was designed to be customizable. It uses the [Raspberry Pi](https://www.raspberrypi.org/) and [Arduino](https://www.arduino.cc/) electronics boards, which are supported by a strong ecosystem of open source hardware and software, facilitating the implementation of new functionalities. diff --git a/SOFTWARE/poseidon_logging.py b/SOFTWARE/poseidon_logging.py new file mode 100644 index 0000000..5be451d --- /dev/null +++ b/SOFTWARE/poseidon_logging.py @@ -0,0 +1,182 @@ +#!/usr/bin/env python +# -*- coding: utf-8 -*- + +# ############################################################################## +# POSEIDON LOGGING +# ############################################################################## +# Additive logging for the poseidon controller. +# +# This module mirrors everything written to stdout/stderr (all the existing +# print() calls and any tracebacks) into a rotating log file, while leaving the +# terminal output exactly as it was. +# Call setup_logging() once at startup. +# +# It is ON by default. To turn it off set the environment variable: +# POSEIDON_LOG=0 +# ############################################################################## + +import io +import os +import sys +import logging +import threading +from logging.handlers import RotatingFileHandler + +# Master switch. Logging to file is on unless POSEIDON_LOG is set to "0". +ENABLED = os.environ.get("POSEIDON_LOG", "1") != "0" + +# Where the log lives. Mirrors the ./images pattern used by save_image(). +LOG_DIR = "logs" +LOG_FILE = os.path.join(LOG_DIR, "poseidon.log") + +# 1 MB per file +MAX_BYTES = 1 * 1024 * 1024 + +# keep poseidon.log + 3 rotated copies +BACKUP_COUNT = 3 + + +class StreamToLogger: + """ + Captures print() (stdout) and tracebacks (stderr) into a logger + without touching any of the existing print() calls. + + Each thread keeps its own line buffer (threading.local), so concurrent + prints from worker threads never interleave and no lock is needed. + + fallback is the original stream, used by write()'s re-entrancy guard to + avoid recursion when a logging handler itself errors. + """ + + def __init__(self, logger, level, fallback=None): + self.logger = logger + self.level = level + self.fallback = fallback + self._local = threading.local() + + def write(self, message): + # Re-entrancy guard: a nested write() (logging reporting its own error) + # goes straight to the real stream, not back into the logger. + if getattr(self._local, "in_write", False): + if self.fallback is not None: + self.fallback.write(message) + return len(message) + self._local.in_write = True + try: + # print() emits text and \n separately; buffer until newline. Blank lines (poseidon's \n\n spacers) kept. + buffer = getattr(self._local, "buffer", "") + message + while "\n" in buffer: + line, buffer = buffer.split("\n", 1) + self.logger.log(self.level, line) + self._local.buffer = buffer + finally: + self._local.in_write = False + return len(message) + + def writelines(self, lines): + for line in lines: + self.write(line) + + def flush(self): + buffer = getattr(self._local, "buffer", "") + if buffer: + self.logger.log(self.level, buffer) + self._local.buffer = "" + + # --- file-like interface: delegate to the real stream, honest defaults --- + # Code and libraries (colorama, click, subprocess, ...) introspect the + # stream they're handed; a bare write/flush object would crash them. + + def isatty(self): + if self.fallback is not None and hasattr(self.fallback, "isatty"): + return self.fallback.isatty() + return False + + def fileno(self): + if self.fallback is not None and hasattr(self.fallback, "fileno"): + return self.fallback.fileno() + raise io.UnsupportedOperation("fileno") + + def writable(self): + return True + + def readable(self): + return False + + def seekable(self): + return False + + @property + def encoding(self): + return getattr(self.fallback, "encoding", None) or "utf-8" + + @property + def errors(self): + return getattr(self.fallback, "errors", None) or "strict" + + +class _BelowLevel(logging.Filter): + """Passes only records strictly below `level` (keeps ERROR off the stdout console).""" + + def __init__(self, level): + super().__init__() + self.level = level + + def filter(self, record): + return record.levelno < self.level + + +def setup_logging(): + """ + Send stdout and stderr to logs/poseidon.log keeping console output as-is. + Off when POSEIDON_LOG=0. + Does nothing if the log file can't be created. + """ + if not ENABLED: + return + + logger = logging.getLogger("poseidon") + if logger.handlers: + return + + # handlers must write here, not to the replaced sys.stdout + orig_stdout = sys.stdout + orig_stderr = sys.stderr + + try: + os.makedirs(LOG_DIR, exist_ok=True) + file_handler = RotatingFileHandler( + LOG_FILE, maxBytes=MAX_BYTES, backupCount=BACKUP_COUNT, + encoding="utf-8", + ) + except OSError as e: + # Can't write the log file: warn on the real console (if any) and + # leave stdout/stderr untouched so the app behaves exactly as before. + if orig_stderr is not None: + orig_stderr.write("poseidon_logging: file logging disabled (%s)\n" % e) + return + + file_handler.setFormatter(logging.Formatter( + "%(asctime)s %(levelname)s [%(threadName)s] %(message)s" + )) + + logger.setLevel(logging.DEBUG) + logger.propagate = False + logger.addHandler(file_handler) + + # Echo to the console with no prefix: INFO -> stdout, ERROR -> stderr (a None stream is skipped). + def add_console(stream, level, max_level=None): + if stream is None: + return + handler = logging.StreamHandler(stream) + handler.setFormatter(logging.Formatter("%(message)s")) + handler.setLevel(level) + if max_level is not None: + handler.addFilter(_BelowLevel(max_level)) + logger.addHandler(handler) + + add_console(orig_stdout, logging.INFO, max_level=logging.ERROR) + add_console(orig_stderr, logging.ERROR) + + sys.stdout = StreamToLogger(logger, logging.INFO, orig_stdout) + sys.stderr = StreamToLogger(logger, logging.ERROR, orig_stderr) diff --git a/SOFTWARE/poseidon_main.py b/SOFTWARE/poseidon_main.py index 7faac8c..9c30f79 100644 --- a/SOFTWARE/poseidon_main.py +++ b/SOFTWARE/poseidon_main.py @@ -21,6 +21,7 @@ from decimal import Decimal # This is our window from QtCreator import poseidon_controller_gui +import poseidon_logging import pdb import traceback, sys @@ -1476,6 +1477,9 @@ def closeEvent(self, event): # I feel better having one of these def main(): + # Mirror stdout/stderr to a rotating log file (see poseidon_logging). + # Additive: terminal output is unchanged. Disable with POSEIDON_LOG=0. + poseidon_logging.setup_logging() # a new app instance app = QtWidgets.QApplication(sys.argv) window = MainWindow() diff --git a/SOFTWARE/test_poseidon_logging.py b/SOFTWARE/test_poseidon_logging.py new file mode 100644 index 0000000..c0a0ae8 --- /dev/null +++ b/SOFTWARE/test_poseidon_logging.py @@ -0,0 +1,283 @@ +#!/usr/bin/env python +# -*- coding: utf-8 -*- + +# ############################################################################## +# TESTS : poseidon_logging +# ############################################################################## +# Standard-library unittest, no external dependencies. Run with: +# python -m unittest test_poseidon_logging +# +# Only poseidon_logging is tested: it is pure Python (no PyQt/serial/hardware), +# so it is the one part of the software that is cheap and deterministic to test. +# Each test isolates global state (sys.stdout/stderr, the "poseidon" logger and +# the log directory) and restores it afterwards. +# ############################################################################## + +import io +import os +import re +import sys +import shutil +import logging +import tempfile +import threading +import unittest +from unittest import mock + +import poseidon_logging + + +class PoseidonLoggingTest(unittest.TestCase): + + def setUp(self): + # Save anything setup_logging() may touch, to restore in tearDown. + self._stdout, self._stderr = sys.stdout, sys.stderr + self._enabled = poseidon_logging.ENABLED + self._log_dir = poseidon_logging.LOG_DIR + self._log_file = poseidon_logging.LOG_FILE + + # Point the log at a throwaway temp directory. + self.tmp = tempfile.mkdtemp() + poseidon_logging.ENABLED = True + poseidon_logging.LOG_DIR = os.path.join(self.tmp, "logs") + poseidon_logging.LOG_FILE = os.path.join(poseidon_logging.LOG_DIR, "poseidon.log") + + self.logger = logging.getLogger("poseidon") + self._reset_logger() + + def tearDown(self): + sys.stdout, sys.stderr = self._stdout, self._stderr + self._reset_logger() + poseidon_logging.ENABLED = self._enabled + poseidon_logging.LOG_DIR = self._log_dir + poseidon_logging.LOG_FILE = self._log_file + shutil.rmtree(self.tmp, ignore_errors=True) + + def _reset_logger(self): + for handler in self.logger.handlers[:]: + handler.close() + self.logger.removeHandler(handler) + # setup_logging() mutates this process-global logger; restore the + # pristine state so tests don't leak level/propagate into each other. + self.logger.setLevel(logging.NOTSET) + self.logger.propagate = True + + def _read_log(self): + for handler in self.logger.handlers: + handler.flush() + with open(poseidon_logging.LOG_FILE, encoding="utf-8") as f: + return f.read() + + # -------------------------------------------------------------------------- + + def test_disabled_is_a_clean_noop(self): + # POSEIDON_LOG=0 -> stdout untouched, no log directory created. + poseidon_logging.ENABLED = False + poseidon_logging.setup_logging() + self.assertIs(sys.stdout, self._stdout) + self.assertFalse(os.path.exists(poseidon_logging.LOG_DIR)) + + def test_print_is_written_to_file(self): + poseidon_logging.setup_logging() + print("RUN command sent.") + log = self._read_log() + self.assertIn("RUN command sent.", log) + self.assertIn("INFO", log) + + def test_stderr_is_captured_as_error(self): + poseidon_logging.setup_logging() + sys.stderr.write("ValueError: simulated serial failure\n") + log = self._read_log() + self.assertIn("ValueError: simulated serial failure", log) + self.assertIn("ERROR", log) + + def test_line_buffering_joins_split_writes(self): + # print() emits the text and the newline as separate writes, and + # multi-arg prints emit each piece separately; both must yield one line. + poseidon_logging.setup_logging() + sys.stdout.write("a") + sys.stdout.write(" ") + sys.stdout.write("b") + sys.stdout.write("\n") + log = self._read_log() + self.assertEqual(log.count("a b"), 1) + # No blank record produced by the trailing newline. re.MULTILINE so $ + # checks every line, not just the end of the whole log. + self.assertNotRegex(log, re.compile(r"INFO \[[^\]]*\]\s*$", re.MULTILINE)) + + def test_setup_is_idempotent(self): + poseidon_logging.setup_logging() + first_stdout = sys.stdout + poseidon_logging.setup_logging() # second call must do nothing + self.assertEqual(len(self.logger.handlers), 3) # file + stdout + stderr console + self.assertIs(sys.stdout, first_stdout) # not re-wrapped + print("UNIQUE_LINE") + self.assertEqual(self._read_log().count("UNIQUE_LINE"), 1) + + def test_survives_none_console(self): + # Frozen .exe / desktop-icon launch: stdout/stderr can be None. + sys.stdout = None + sys.stderr = None + poseidon_logging.setup_logging() # must not raise + print("line while console is None") + self.assertIn("line while console is None", self._read_log()) + + def test_file_failure_leaves_app_untouched(self): + # If the log file can't be created, the app behaves exactly as before. + sys.stderr = io_stderr = _Capture() + with mock.patch("poseidon_logging.os.makedirs", side_effect=OSError("nope")): + poseidon_logging.setup_logging() + self.assertIs(sys.stdout, self._stdout) # stdout not redirected + self.assertIn("file logging disabled", io_stderr.text) + + def test_concurrent_prints_are_not_corrupted(self): + poseidon_logging.setup_logging() + + def worker(n): + for i in range(50): + print("T%d-msg-%d" % (n, i)) + + threads = [threading.Thread(target=worker, args=(n,), name="W%d" % n) + for n in range(8)] + for t in threads: + t.start() + for t in threads: + t.join() + + log = self._read_log() + # Assert on WHOLE lines (end-anchored): a merged/interleaved line like + # "...] T0-msg-1T5-msg-2" would not match, so it would be excluded and + # the count would drop -- catching corruption a bare token scan misses. + msgs = re.findall(r"\] (T\d+-msg-\d+)$", log, re.MULTILINE) + self.assertEqual(len(msgs), 8 * 50) # nothing lost or corrupted + self.assertEqual(len(set(msgs)), 8 * 50) # nothing duplicated/merged + + def test_handler_error_does_not_recurse(self): + # A handler that fails on every emit mimics a Windows rollover rename + # under a file lock, or a console UnicodeEncodeError. Without the + # re-entrancy guard, handleError -> redirected stderr -> logger -> the + # same failing handler spirals into RecursionError on an ordinary + # print(). The guard must keep print() working and surface the logging + # error on the real stream instead. + fallback = _Capture() + sys.stderr = fallback # becomes orig_stderr / the guard's fallback + poseidon_logging.setup_logging() + + def make_failing_emit(handler): + def emit(record): + try: + raise OSError("simulated rollover/encode failure") + except Exception: + handler.handleError(record) + return emit + + for h in self.logger.handlers: + h.emit = make_failing_emit(h) + + try: + print("trigger") + except RecursionError: + self.fail("handler error spiralled into RecursionError") + + self.assertIn("simulated rollover/encode failure", fallback.text) + + def test_console_keeps_stdout_and_stderr_separate(self): + # stdout-origin lines must echo to the real stdout, stderr-origin lines + # to the real stderr -- not collapsed onto one stream. + cap_out, cap_err = _Capture(), _Capture() + sys.stdout, sys.stderr = cap_out, cap_err + poseidon_logging.setup_logging() + + print("normal line") + sys.stderr.write("error line\n") + + self.assertIn("normal line", cap_out.text) + self.assertNotIn("normal line", cap_err.text) + self.assertIn("error line", cap_err.text) + self.assertNotIn("error line", cap_out.text) + + def test_stream_is_file_like(self): + poseidon_logging.setup_logging() + out = sys.stdout + self.assertTrue(out.writable()) + self.assertFalse(out.readable()) + self.assertFalse(out.seekable()) + self.assertIsInstance(out.encoding, str) + self.assertTrue(out.encoding) + self.assertEqual(out.write("12345\n"), len("12345\n")) + + def test_isatty_delegates_to_fallback(self): + # isatty() reports whatever the real stream reports (or False if none). + # Driven against stubs so the result doesn't depend on the test runner. + SL = poseidon_logging.StreamToLogger + + class _Tty: + def __init__(self, value): + self.value = value + + def isatty(self): + return self.value + + self.assertTrue(SL(self.logger, logging.INFO, _Tty(True)).isatty()) + self.assertFalse(SL(self.logger, logging.INFO, _Tty(False)).isatty()) + self.assertFalse(SL(self.logger, logging.INFO, None).isatty()) + + def test_fileno_delegates_or_raises(self): + SL = poseidon_logging.StreamToLogger + # Delegates to a real fd when the fallback has one... + f = open(os.path.join(self.tmp, "fd.txt"), "w") + try: + self.assertIsInstance(SL(self.logger, logging.INFO, f).fileno(), int) + finally: + f.close() + # ...and raises the standard error when there is no console (frozen .exe). + with self.assertRaises(io.UnsupportedOperation): + SL(self.logger, logging.INFO, None).fileno() + + def test_filelike_defaults_when_no_console(self): + s = poseidon_logging.StreamToLogger(self.logger, logging.INFO, None) + self.assertEqual(s.encoding, "utf-8") + self.assertEqual(s.errors, "strict") + self.assertFalse(s.isatty()) + self.assertTrue(s.writable()) + self.assertFalse(s.seekable()) + + def test_writelines_logs_each_line(self): + poseidon_logging.setup_logging() + sys.stdout.writelines(["alpha\n", "beta\n"]) + log = self._read_log() + self.assertIn("alpha", log) + self.assertIn("beta", log) + + def test_warning_routes_to_stdout_console(self): + cap_out, cap_err = _Capture(), _Capture() + sys.stdout, sys.stderr = cap_out, cap_err + poseidon_logging.setup_logging() + logging.getLogger("poseidon").warning("a warning") + self.assertIn("a warning", cap_out.text) + self.assertNotIn("a warning", cap_err.text) + + def test_blank_lines_are_preserved(self): + # poseidon prints "\n\n" separators; those blank lines must survive. + poseidon_logging.setup_logging() + print("=====\n\n") + log = self._read_log() + # "=====" plus two blank record lines (empty message after the prefix). + self.assertIn("=====", log) + self.assertRegex(log, re.compile(r"INFO \[[^\]]*\]\s*$", re.MULTILINE)) + + +class _Capture: + '''Minimal writable stream used to capture the fallback warning.''' + def __init__(self): + self.text = "" + + def write(self, message): + self.text += message + + def flush(self): + pass + + +if __name__ == "__main__": + unittest.main()