From 78a4aff5130f017546f245e96de8ccf0e5c2ccc9 Mon Sep 17 00:00:00 2001 From: Ethan Stoner Date: Wed, 26 Aug 2026 11:51:58 -0700 Subject: [PATCH] quieten routine tab logging and harden the failure summary Follow-ups from running the conversion against a live account. Tab open/close bookkeeping moves from info to debug. It was 19 of the 33 records in a full run, so the six task outcomes that are the point of the summary were outnumbered three to one by tab handles and query strings. The "could not close" case stays at warning, a tab that will not close is a real problem rather than bookkeeping. The [FAIL] summary moves into log_utils.exception_summary, which takes the first line, drops the "(Session info: ...)" fragment and caps the result. A selenium exception embeds the whole msedgedriver stacktrace in str(), and the cap means a pathological message cannot push a screenful of text into one record. The cut marker is ASCII because this can land on a Windows console whose encoding cannot represent an ellipsis. The suppressed-library list was checked rather than guessed: with the root logger wide open, a real browser session plus one ollama call produced records from httpx, httpcore, urllib3 and selenium only, and nothing else. That set is already pinned. Worth noting selenium alone emits 45 records for a single page load, so without the pinning the debug mode this PR recommends for bug reports would be unusable. --- src/log_utils.py | 31 +++++++++++++++++++++++++++++++ src/rewards_tasks.py | 7 ++----- src/tab_utils.py | 10 +++++++--- 3 files changed, 40 insertions(+), 8 deletions(-) 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)