diff --git a/src/electionguard/logs.py b/src/electionguard/logs.py index 09132d538..f4adc0f66 100644 --- a/src/electionguard/logs.py +++ b/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 diff --git a/src/electionguard_gui/Dockerfile b/src/electionguard_gui/Dockerfile index a5e510602..a7efa8a2c 100644 --- a/src/electionguard_gui/Dockerfile +++ b/src/electionguard_gui/Dockerfile @@ -59,6 +59,10 @@ 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 @@ -66,10 +70,6 @@ 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 diff --git a/src/electionguard_gui/components/component_base.py b/src/electionguard_gui/components/component_base.py index 29b92d042..2f97dc630 100644 --- a/src/electionguard_gui/components/component_base.py +++ b/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)) diff --git a/src/electionguard_gui/components/key_ceremony_details_component.py b/src/electionguard_gui/components/key_ceremony_details_component.py index c4f7fcff6..a9befd9f1 100644 --- a/src/electionguard_gui/components/key_ceremony_details_component.py +++ b/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))) diff --git a/src/electionguard_gui/components/view_decryption_component.py b/src/electionguard_gui/components/view_decryption_component.py index 5b705d8b5..cf6debbf4 100644 --- a/src/electionguard_gui/components/view_decryption_component.py +++ b/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))) diff --git a/src/electionguard_gui/containers.py b/src/electionguard_gui/containers.py index 4e7cefdf5..fbf09b85f 100644 --- a/src/electionguard_gui/containers.py +++ b/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 ) diff --git a/src/electionguard_gui/main_app.py b/src/electionguard_gui/main_app.py index aa7981f83..80bef36f3 100644 --- a/src/electionguard_gui/main_app.py +++ b/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 diff --git a/src/electionguard_gui/services/ballot_upload_service.py b/src/electionguard_gui/services/ballot_upload_service.py index aae7e87d7..0161a800d 100644 --- a/src/electionguard_gui/services/ballot_upload_service.py +++ b/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 diff --git a/src/electionguard_gui/services/eel_log_service.py b/src/electionguard_gui/services/eel_log_service.py index 75e7fcdcc..5109870f4 100644 --- a/src/electionguard_gui/services/eel_log_service.py +++ b/src/electionguard_gui/services/eel_log_service.py @@ -1,4 +1,17 @@ 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 @@ -6,24 +19,41 @@ 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}, + ) diff --git a/tests/unit/electionguard/test_logs.py b/tests/unit/electionguard/test_logs.py index 4640ec4fb..46ce68647 100644 --- a/tests/unit/electionguard/test_logs.py +++ b/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