diff --git a/src/log_utils.py b/src/log_utils.py index 58b5b15..c621c8b 100644 --- a/src/log_utils.py +++ b/src/log_utils.py @@ -7,6 +7,7 @@ before this runs, so import order does not matter. import logging import os +import re import sys LEVEL_ENV_VAR = "REWARDS_FARMER_LOG_LEVEL" @@ -21,6 +22,36 @@ DEFAULT_LEVEL = "INFO" # default would make the output noisier than what it replaces. NOISY_LIBRARIES = ("httpx", "httpcore", "urllib3", "selenium") +# Longest a one-line exception summary may get before it is cut. Long enough +# for any real selenium message, short enough that a pathological one cannot +# push a whole screen of text into a single record. +MAX_SUMMARY_LENGTH = 300 + +_SESSION_INFO = re.compile(r"\s*\(Session info:[^)]*\)") + + +def exception_summary(exc: BaseException) -> str: + """One short line describing an exception, safe to put in a log record. + + str() on a selenium exception is multi-line: the message, then a session + info line, then the whole msedgedriver stacktrace. Only the first line is + worth showing in a per-task summary, and the full detail is still attached + as a traceback when the level is debug. + """ + text = str(exc).strip() + + if not text: + return "" + + text = _SESSION_INFO.sub("", text.splitlines()[0]).strip() + + if len(text) > MAX_SUMMARY_LENGTH: + # ASCII, because this can land on a Windows console whose encoding + # cannot represent an ellipsis character. + text = text[:MAX_SUMMARY_LENGTH - 3].rstrip() + "..." + + return text + # CRITICAL is the longest level name at 8 characters, so pad to that and the # message column stays aligned no matter what is being logged. LOG_FORMAT = "%(asctime)s %(levelname)-8s %(name)s: %(message)s" diff --git a/src/rewards_tasks.py b/src/rewards_tasks.py index bd44190..466106c 100644 --- a/src/rewards_tasks.py +++ b/src/rewards_tasks.py @@ -1,4 +1,5 @@ import logging +import log_utils import os import random import time @@ -284,12 +285,8 @@ class RewardsTaskUtils: except (NoSuchElementException, TimeoutException) as exc: logger.warning("[SKIP] %s: not available in this UI variant (%s)", name, type(exc).__name__) except Exception as exc: - # A selenium exception carries the whole msedgedriver stacktrace - # in str(), tens of lines of it, so keep the summary to the - # first line and let the traceback on debug hold the rest. - message = str(exc).strip().splitlines() logger.error( - "[FAIL] %s: %s: %s", name, type(exc).__name__, message[0] if message else "", + "[FAIL] %s: %s: %s", name, type(exc).__name__, log_utils.exception_summary(exc), exc_info=logger.isEnabledFor(logging.DEBUG) ) diff --git a/src/tab_utils.py b/src/tab_utils.py index b007147..b6896a0 100644 --- a/src/tab_utils.py +++ b/src/tab_utils.py @@ -33,7 +33,7 @@ document.dispatchEvent(new Event('visibilitychange')); self.driver.switch_to.window(handle) if self.driver.current_url in GHOST_TAB_URLS: - logger.info("Found ghost tab with handle %s and URL %s.", handle, self.driver.current_url) + logger.debug("Found ghost tab with handle %s and URL %s.", handle, self.driver.current_url) continue self.ensure_focus() @@ -50,14 +50,18 @@ document.dispatchEvent(new Event('visibilitychange')); self.driver.switch_to.window(handle) if self.driver.current_url in GHOST_TAB_URLS: - logger.info("Found ghost tab with handle %s and URL %s, not closing.", handle, self.driver.current_url) + logger.debug("Found ghost tab with handle %s and URL %s, not closing.", handle, self.driver.current_url) continue tab_url = self.driver.current_url try: self.driver.close() - logger.info("Closed tab with handle %s and URL %s.", handle, tab_url) + # Routine bookkeeping, one line per tab. At info it drowned + # the task summary: 19 of the 33 records in a full run were + # these. The warning below stays at warning, a tab that will + # not close is a real problem. + logger.debug("Closed tab with handle %s and URL %s.", handle, tab_url) except WebDriverException: logger.warning("Could not close tab with handle %s and URL %s.", handle, tab_url)