#739 Logging (#749)

* Better error logging during ballot decryption

* # per RC 8/15/22 log errors and continue processing even if it makes numbers incorrect

* Ability to set the log level in logger for the stream handler

* Combine EG logging with eel logging

* cache clean in dockerfile

* fix issue with recovering during ballot parsing errors

* log to file

* Use date in file name so that when run on single machine containers don't conflict

* Log stack traces

Author: lprichar

src/electionguard/logs.py

@@ -16,12 +16,17 @@ class ElectionGuardLog(Singleton):
     """
 
     __logger: logging.Logger
+    __stream_handler: logging.StreamHandler
 
     def __init__(self) -> None:
         super().__init__()
 
         self.__logger = logging.getLogger("electionguard")
-        self.__logger.addHandler(get_stream_handler())
+        # Pythong's logger will use the most restrictive of the logger level and the handler level,
+        #   so set the logger to the lowest level the handler ever might log at
+        self.__logger.setLevel(logging.DEBUG)
+        self.__stream_handler = get_stream_handler(logging.INFO)
+        self.__logger.addHandler(self.__stream_handler)
 
     @staticmethod
     def __get_call_info() -> Tuple[str, str, int]:
@@ -44,6 +49,13 @@ def __formatted_message(self, message: str) -> str:
         message = f"{os.path.basename(filename)}.{funcname}:#L{line}: {message}"
         return message
 
+    def set_stream_log_level(self, Level: int) -> None:
+        """
+        Sets the stream log level
+        """
+        self.remove_handler(self.__stream_handler)
+        self.add_handler(get_stream_handler(Level))
+
     def add_handler(self, handler: logging.Handler) -> None:
         """
         Adds a logger handler
@@ -93,17 +105,17 @@ def critical(self, message: str, *args: Any, **kwargs: Any) -> None:
         self.__logger.critical(self.__formatted_message(message), *args, **kwargs)
 
 
-def get_stream_handler() -> logging.StreamHandler:
+def get_stream_handler(log_level: int) -> logging.StreamHandler:
     """
     Get a Stream Handler, sends only warnings and errors to stdout.
     """
     stream_handler = logging.StreamHandler(sys.stdout)
-    stream_handler.setLevel(logging.INFO)
+    stream_handler.setLevel(log_level)
     stream_handler.setFormatter(logging.Formatter(FORMAT))
     return stream_handler
 
 
-def get_file_handler() -> logging.FileHandler:
+def get_file_handler(log_level: int, filename: str) -> logging.FileHandler:
     """
     Get a File System Handler, sends verbose logging to a file, `electionguard.log`.
     When that file gets too large, the logs will rotate, creating files with names
@@ -113,9 +125,9 @@ def get_file_handler() -> logging.FileHandler:
     # TODO: add file compression, save a bunch of space.
     #   https://medium.com/@rahulraghu94/overriding-pythons-timedrotatingfilehandler-to-compress-your-log-files-iot-c766a4ace240 # pylint: disable=line-too-long
     file_handler = RotatingFileHandler(
-        "electionguard.log", "a", maxBytes=10_000_000, backupCount=10
+        filename, "a", maxBytes=10_000_000, backupCount=10
     )
-    file_handler.setLevel(logging.DEBUG)
+    file_handler.setLevel(log_level)
     file_handler.setFormatter(logging.Formatter(FORMAT))
     return file_handler
 

src/electionguard_gui/Dockerfile

@@ -59,17 +59,17 @@ RUN poetry config virtualenvs.in-project true && \
 # Get Source
 ##################################################################################
 
+# cleanup first, the next layer will get invalidated easiliy
+RUN apt-get clean && \
+    rm -rf /var/lib/apt/lists/*
+
 COPY ./src ./src
 RUN rm src/electionguard_gui/__init__.py
 
 ##################################################################################
 # Run EGUI
 ##################################################################################
 
-# cleanup
-RUN apt-get clean && \
-    rm -rf /var/lib/apt/lists/*
-
 # the final poetry install runs fast, it activates the virtualenv and initializes the modules
 RUN poetry install
 

src/electionguard_gui/components/component_base.py

@@ -27,6 +27,6 @@ def expose(self) -> None:
         fact that method names exposed must be globally unique."""
 
     def handle_error(self, error: Exception) -> dict[str, Any]:
-        self._log.error(error)
+        self._log.error("error in component_base", error)
         traceback.print_exc()
         return eel_fail(str(error))

src/electionguard_gui/components/key_ceremony_details_component.py

@@ -109,7 +109,7 @@ def on_key_ceremony_changed(self, _: str, key_ceremony_id: str) -> None:
             eel.refresh_key_ceremony(eel_success(result))
         # pylint: disable=broad-except
         except Exception as e:
-            self._log.error(e)
+            self._log.error("error on key ceremony changed", e)
             traceback.print_exc()
             # pylint: disable=no-member
             eel.refresh_key_ceremony(eel_fail(str(e)))

src/electionguard_gui/components/view_decryption_component.py

@@ -65,7 +65,7 @@ def on_decryption_changed(self, _: str, decryption_id: str) -> None:
             refresh_decryption(eel_success())
         # pylint: disable=broad-except
         except Exception as e:
-            self._log.error(e)
+            self._log.error("error in on decryption changed", e)
             traceback.print_exc()
             refresh_decryption(eel_fail(str(e)))
 

src/electionguard_gui/containers.py

@@ -54,7 +54,7 @@ class Container(containers.DeclarativeContainer):
     """Responsible for dependency injection and how components are wired together"""
 
     # services
-    log_service: Factory[EelLogService] = providers.Factory(EelLogService)
+    log_service: Singleton[EelLogService] = providers.Singleton(EelLogService)
     config_service: Factory[ConfigurationService] = providers.Factory(
         ConfigurationService
     )

src/electionguard_gui/main_app.py

@@ -103,6 +103,6 @@ def start(self) -> None:
             self.log_service.debug(f"Starting eel port={port} mode={mode} host={host}")
             eel.start("index.html", size=(1024, 768), port=port, mode=mode, host=host)
         except Exception as e:
-            self.log_service.error(e)
+            self.log_service.error("error in main app start", e)
             traceback.print_exc()
             raise e

src/electionguard_gui/services/ballot_upload_service.py

@@ -59,13 +59,18 @@ def add_ballot(
         )
 
     def get_ballots(self, db: Database, election_id: str) -> list[SubmittedBallot]:
-        self._log.trace(f"getting ballots for {election_id}")
+        self._log.debug(f"getting ballots for {election_id}")
         ballot_uploads = db.ballot_uploads.find(
             {"election_id": election_id, "file_contents": {"$exists": True}}
         )
         ballots = []
         for ballot_obj in ballot_uploads:
             ballot_str = ballot_obj["file_contents"]
-            ballot = from_raw(SubmittedBallot, ballot_str)
-            ballots.append(ballot)
+            try:
+                ballot = from_raw(SubmittedBallot, ballot_str)
+                ballots.append(ballot)
+            # pylint: disable=broad-except
+            except Exception as e:
+                self._log.error("error deserializing ballot: {ballot_obj}", e)
+                # per RC 8/15/22 log errors and continue processing even if it makes numbers incorrect
         return ballots

src/electionguard_gui/services/eel_log_service.py

@@ -1,29 +1,59 @@
 from datetime import datetime
+import logging
+from os import path, makedirs
+from typing import Any
+from electionguard.logs import (
+    get_file_handler,
+    log_critical,
+    log_debug,
+    log_error,
+    log_info,
+    log_warning,
+    LOG,
+)
+from electionguard_gui.services.directory_service import get_data_dir
 from electionguard_gui.services.service_base import ServiceBase
 
 
 class EelLogService(ServiceBase):
     """A facade for logging. Currently this simply writes to the console without using log levels, but
     this may eventually be used to log to a file or database."""
 
-    # pylint: disable=no-self-use
-    def _log(self, level: str, message: str) -> None:
-        print(f"{datetime.now()} {level} {message}")
+    def __init__(self) -> None:
+        LOG.set_stream_log_level(logging.DEBUG)
+        file_dir = path.join(get_data_dir(), "logs")
+        makedirs(file_dir, exist_ok=True)
+        now = datetime.now().strftime("%Y-%m-%d-%H-%M-%S-%f")
+        file_name = path.join(file_dir, f"electionguard-{now}.log")
+        LOG.add_handler(get_file_handler(logging.DEBUG, file_name))
 
-    def trace(self, message: str) -> None:
+    def trace(self, message: str, *args: Any, **kwargs: Any) -> None:
         pass
 
-    def debug(self, message: str) -> None:
-        self._log("DEBUG", message)
+    # pylint: disable=no-self-use
+    def debug(self, message: str, *args: Any, **kwargs: Any) -> None:
+        log_debug(message, *args, **kwargs)
 
-    def info(self, message: str) -> None:
-        self._log("INFO ", message)
+    # pylint: disable=no-self-use
+    def info(self, message: str, *args: Any, **kwargs: Any) -> None:
+        log_info(message, *args, **kwargs)
 
-    def warn(self, message: str) -> None:
-        self._log("WARN ", message)
+    # pylint: disable=no-self-use
+    def warn(self, message: str, *args: Any, **kwargs: Any) -> None:
+        log_warning(message, *args, **kwargs)
 
-    def error(self, e: Exception) -> None:
-        self._log("ERROR", str(e))
+    # pylint: disable=no-self-use
+    def error(self, message: str, exception: Exception) -> None:
+        log_error(
+            f"{message} '{exception}'",
+            exc_info=1,
+            extra={"exception": exception},
+        )
 
-    def fatal(self, message: str) -> None:
-        self._log("FATAL", message)
+    # pylint: disable=no-self-use
+    def fatal(self, message: str, exception: Exception) -> None:
+        log_critical(
+            f"{message} '{str(exception)}'",
+            exc_info=1,
+            extra={"exception": exception},
+        )

tests/unit/electionguard/test_logs.py

@@ -1,3 +1,4 @@
+import logging
 from tests.base_test_case import BaseTestCase
 
 from electionguard.logs import (
@@ -45,7 +46,7 @@ def test_log_handlers(self):
         self.assertEqual(len(empty_handlers), 0)
 
         # Act
-        log_add_handler(get_stream_handler())
+        log_add_handler(get_stream_handler(logging.INFO))
         added_handlers = log_handlers()
 
         # Assert