From d0b525c00328c40c1c2b15baf534aeba701b4537 Mon Sep 17 00:00:00 2001 From: Lee Richardson Date: Mon, 15 Aug 2022 16:03:28 -0400 Subject: [PATCH 1/9] Better error logging during ballot decryption --- src/electionguard_gui/services/ballot_upload_service.py | 9 +++++++-- 1 file changed, 7 insertions(+), 2 deletions(-) diff --git a/src/electionguard_gui/services/ballot_upload_service.py b/src/electionguard_gui/services/ballot_upload_service.py index aae7e87d..f3be5afa 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) + try: + ballot = from_raw(SubmittedBallot, ballot_str) + except Exception as e: + self._log.info(f"error deserializing ballot: {ballot_obj}") + self._log.error(e) + raise ballots.append(ballot) return ballots From 92b7b03e5cc7383380d8083ce6bbc00de2428cca Mon Sep 17 00:00:00 2001 From: Lee Richardson Date: Tue, 16 Aug 2022 08:14:24 -0400 Subject: [PATCH 2/9] # per RC 8/15/22 log errors and continue processing even if it makes numbers incorrect --- src/electionguard_gui/services/ballot_upload_service.py | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/src/electionguard_gui/services/ballot_upload_service.py b/src/electionguard_gui/services/ballot_upload_service.py index f3be5afa..20612c2b 100644 --- a/src/electionguard_gui/services/ballot_upload_service.py +++ b/src/electionguard_gui/services/ballot_upload_service.py @@ -68,9 +68,9 @@ def get_ballots(self, db: Database, election_id: str) -> list[SubmittedBallot]: ballot_str = ballot_obj["file_contents"] try: ballot = from_raw(SubmittedBallot, ballot_str) + # pylint: disable=broad-except except Exception as e: - self._log.info(f"error deserializing ballot: {ballot_obj}") - self._log.error(e) - raise + 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 ballots.append(ballot) return ballots From 78e0820cd8d079d7e8a48d8caa05028e418a8d45 Mon Sep 17 00:00:00 2001 From: Lee Richardson Date: Tue, 16 Aug 2022 08:48:27 -0400 Subject: [PATCH 3/9] Ability to set the log level in logger for the stream handler --- src/electionguard/logs.py | 18 +++++++++++++++--- tests/unit/electionguard/test_logs.py | 3 ++- 2 files changed, 17 insertions(+), 4 deletions(-) diff --git a/src/electionguard/logs.py b/src/electionguard/logs.py index 09132d53..7a250c23 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,12 +105,12 @@ 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 diff --git a/tests/unit/electionguard/test_logs.py b/tests/unit/electionguard/test_logs.py index 4640ec4f..46ce6864 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 From dcd0b9fb3f04f22414c2b1dda76f5ac7d5c4fe1b Mon Sep 17 00:00:00 2001 From: Lee Richardson Date: Tue, 16 Aug 2022 09:29:11 -0400 Subject: [PATCH 4/9] Combine EG logging with eel logging --- .../components/component_base.py | 2 +- .../key_ceremony_details_component.py | 2 +- .../components/view_decryption_component.py | 2 +- src/electionguard_gui/containers.py | 2 +- src/electionguard_gui/main_app.py | 2 +- .../services/eel_log_service.py | 43 ++++++++++++------- 6 files changed, 33 insertions(+), 20 deletions(-) diff --git a/src/electionguard_gui/components/component_base.py b/src/electionguard_gui/components/component_base.py index 29b92d04..2f97dc63 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 c4f7fcff..a9befd9f 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 5b705d8b..cf6debbf 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 4e7cefdf..d0b040c6 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: Factory[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 aa7981f8..80bef36f 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/eel_log_service.py b/src/electionguard_gui/services/eel_log_service.py index 75e7fcdc..3bd762e3 100644 --- a/src/electionguard_gui/services/eel_log_service.py +++ b/src/electionguard_gui/services/eel_log_service.py @@ -1,4 +1,13 @@ -from datetime import datetime +import logging +from typing import Any +from electionguard.logs import ( + log_critical, + log_debug, + log_error, + log_info, + log_warning, + LOG, +) from electionguard_gui.services.service_base import ServiceBase @@ -6,24 +15,28 @@ 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) - 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, *args: Any, **kwargs: Any) -> None: + log_error(message, *args, **kwargs) - def fatal(self, message: str) -> None: - self._log("FATAL", message) + # pylint: disable=no-self-use + def fatal(self, message: str, *args: Any, **kwargs: Any) -> None: + log_critical(message, *args, **kwargs) From c94126e088167dbbb55e35852628366987f7980e Mon Sep 17 00:00:00 2001 From: Lee Richardson Date: Tue, 16 Aug 2022 09:29:29 -0400 Subject: [PATCH 5/9] cache clean in dockerfile --- src/electionguard_gui/Dockerfile | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/src/electionguard_gui/Dockerfile b/src/electionguard_gui/Dockerfile index a5e51060..a7efa8a2 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 From db7a7693e2557dde42920f81a3a843b8b0501609 Mon Sep 17 00:00:00 2001 From: Lee Richardson Date: Tue, 16 Aug 2022 09:30:24 -0400 Subject: [PATCH 6/9] fix issue with recovering during ballot parsing errors --- src/electionguard_gui/services/ballot_upload_service.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/electionguard_gui/services/ballot_upload_service.py b/src/electionguard_gui/services/ballot_upload_service.py index 20612c2b..0161a800 100644 --- a/src/electionguard_gui/services/ballot_upload_service.py +++ b/src/electionguard_gui/services/ballot_upload_service.py @@ -68,9 +68,9 @@ def get_ballots(self, db: Database, election_id: str) -> list[SubmittedBallot]: ballot_str = ballot_obj["file_contents"] 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 - ballots.append(ballot) return ballots From e08117a84a356ae15f744ea0b0cc3112f64a3036 Mon Sep 17 00:00:00 2001 From: Lee Richardson Date: Tue, 16 Aug 2022 10:43:22 -0400 Subject: [PATCH 7/9] log to file --- src/electionguard/logs.py | 6 +++--- src/electionguard_gui/services/eel_log_service.py | 7 +++++++ 2 files changed, 10 insertions(+), 3 deletions(-) diff --git a/src/electionguard/logs.py b/src/electionguard/logs.py index 7a250c23..f4adc0f6 100644 --- a/src/electionguard/logs.py +++ b/src/electionguard/logs.py @@ -115,7 +115,7 @@ def get_stream_handler(log_level: int) -> logging.StreamHandler: 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 @@ -125,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/services/eel_log_service.py b/src/electionguard_gui/services/eel_log_service.py index 3bd762e3..62b2cab7 100644 --- a/src/electionguard_gui/services/eel_log_service.py +++ b/src/electionguard_gui/services/eel_log_service.py @@ -1,6 +1,8 @@ import logging +from os import path, makedirs from typing import Any from electionguard.logs import ( + get_file_handler, log_critical, log_debug, log_error, @@ -8,6 +10,7 @@ log_warning, LOG, ) +from electionguard_gui.services.directory_service import get_data_dir from electionguard_gui.services.service_base import ServiceBase @@ -17,6 +20,10 @@ class EelLogService(ServiceBase): 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) + file_name = path.join(file_dir, "electionguard.log") + LOG.add_handler(get_file_handler(logging.DEBUG, file_name)) def trace(self, message: str, *args: Any, **kwargs: Any) -> None: pass From 287c8ba9d27e4ded5c2801b981f050ed80cdf6dd Mon Sep 17 00:00:00 2001 From: Lee Richardson Date: Tue, 16 Aug 2022 10:54:47 -0400 Subject: [PATCH 8/9] Use date in file name so that when run on single machine containers don't conflict --- src/electionguard_gui/containers.py | 2 +- src/electionguard_gui/services/eel_log_service.py | 4 +++- 2 files changed, 4 insertions(+), 2 deletions(-) diff --git a/src/electionguard_gui/containers.py b/src/electionguard_gui/containers.py index d0b040c6..fbf09b85 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.Singleton(EelLogService) + log_service: Singleton[EelLogService] = providers.Singleton(EelLogService) config_service: Factory[ConfigurationService] = providers.Factory( ConfigurationService ) diff --git a/src/electionguard_gui/services/eel_log_service.py b/src/electionguard_gui/services/eel_log_service.py index 62b2cab7..f0a523b5 100644 --- a/src/electionguard_gui/services/eel_log_service.py +++ b/src/electionguard_gui/services/eel_log_service.py @@ -1,3 +1,4 @@ +from datetime import datetime import logging from os import path, makedirs from typing import Any @@ -22,7 +23,8 @@ 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) - file_name = path.join(file_dir, "electionguard.log") + 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, *args: Any, **kwargs: Any) -> None: From 101daf0b186520ec504048dd80dc68517c497f33 Mon Sep 17 00:00:00 2001 From: Lee Richardson Date: Tue, 16 Aug 2022 12:45:32 -0400 Subject: [PATCH 9/9] Log stack traces --- .../services/eel_log_service.py | 16 ++++++++++++---- 1 file changed, 12 insertions(+), 4 deletions(-) diff --git a/src/electionguard_gui/services/eel_log_service.py b/src/electionguard_gui/services/eel_log_service.py index f0a523b5..5109870f 100644 --- a/src/electionguard_gui/services/eel_log_service.py +++ b/src/electionguard_gui/services/eel_log_service.py @@ -43,9 +43,17 @@ def warn(self, message: str, *args: Any, **kwargs: Any) -> None: log_warning(message, *args, **kwargs) # pylint: disable=no-self-use - def error(self, message: str, *args: Any, **kwargs: Any) -> None: - log_error(message, *args, **kwargs) + def error(self, message: str, exception: Exception) -> None: + log_error( + f"{message} '{exception}'", + exc_info=1, + extra={"exception": exception}, + ) # pylint: disable=no-self-use - def fatal(self, message: str, *args: Any, **kwargs: Any) -> None: - log_critical(message, *args, **kwargs) + def fatal(self, message: str, exception: Exception) -> None: + log_critical( + f"{message} '{str(exception)}'", + exc_info=1, + extra={"exception": exception}, + )