From 5c475cab05fe5738388649b90281f7affb002082 Mon Sep 17 00:00:00 2001 From: Ethan Stoner Date: Wed, 26 Aug 2026 10:26:59 -0700 Subject: [PATCH 1/2] switch the bot runtime from print to logging Closes #14. The runtime modules now log through the stdlib logging module. A new log_utils.setup_logging is called once from main.py, and each module holds its own logging.getLogger(__name__) so every line says which module it came from. The [INFO] and [WARNING] prefixes are gone, since the level field carries that now. [OK], [SKIP] and [FAIL] stay in the message text: they are the per-task outcome summary from complete_all_tasks rather than severities, and folding them into the level would erase the run summary. They map to info, warning and error, which is the one thing print could not express, a real failure now sorts above a task the current UI variant simply does not ship. Two things fall out of having levels at all: - REWARDS_FARMER_LOG_LEVEL=DEBUG attaches the traceback to every [FAIL], which is the stack trace that bug reports keep having to be asked for. - REWARDS_FARMER_LOG_FILE writes the same output to a file, so an unattended run can be read after the fact. Both are off by default, so a normal run looks the same as before apart from the timestamp and level columns. The [FAIL] summary keeps only the first line of the exception message. A selenium exception carries the whole msedgedriver stacktrace inside str(), tens of lines of it, which would turn one task into one screenful and make the log file impossible to scan. The full detail is still there with the traceback on debug. The console stream is stdout rather than the StreamHandler default of stderr, so anyone already redirecting stdout keeps getting the output there, and its error handler is set to replace. Card descriptions are scraped from the page and are not ASCII outside the en-US market, and the Windows console encoding raises on them. check_selectors.py, fitts_law.py and analyze_keypresses.py are left on print. Their output is formatted report text, and prefixing every row of a diagnostic table with a timestamp and a level makes it harder to read. --- .gitignore | 1 + README.md | 21 +++++++++ src/llm_utils.py | 5 ++- src/log_utils.py | 100 +++++++++++++++++++++++++++++++++++++++++++ src/main.py | 3 ++ src/rewards_tasks.py | 49 +++++++++++++++------ src/tab_utils.py | 11 +++-- 7 files changed, 173 insertions(+), 17 deletions(-) create mode 100644 src/log_utils.py diff --git a/.gitignore b/.gitignore index 2cb64b9..a629200 100644 --- a/.gitignore +++ b/.gitignore @@ -1,5 +1,6 @@ *.png *.txt +*.log !nouns.txt Todo.md data-dir/ diff --git a/README.md b/README.md index ca3b02f..1107082 100644 --- a/README.md +++ b/README.md @@ -48,4 +48,25 @@ EU Users: you may have to accept a consent banner once on `rewards.bing.com` and Close all webdriver browser instances. Run `main.py` again; the automation should start working. +# Logging + +The script logs to the console. Two optional environment variables change that: + +| Variable | Default | Effect | +| --- | --- | --- | +| `REWARDS_FARMER_LOG_LEVEL` | `INFO` | Set to `DEBUG` to also attach the full stack trace to every `[FAIL]` line. | +| `REWARDS_FARMER_LOG_FILE` | unset | Path to also write the log to, useful for unattended runs. | + +Windows (PowerShell) +```sh +$env:REWARDS_FARMER_LOG_LEVEL="DEBUG"; $env:REWARDS_FARMER_LOG_FILE="run.log"; python src/main.py +``` + +*nix (Bash) +```sh +REWARDS_FARMER_LOG_LEVEL=DEBUG REWARDS_FARMER_LOG_FILE=run.log python src/main.py +``` + +If you are opening an issue about a crash, running with `REWARDS_FARMER_LOG_LEVEL=DEBUG` and attaching the log is the most useful thing you can include. + Please open up a GitHub issue if you run into any difficulties. \ No newline at end of file diff --git a/src/llm_utils.py b/src/llm_utils.py index 6dfa9f2..b3d6114 100644 --- a/src/llm_utils.py +++ b/src/llm_utils.py @@ -1,7 +1,10 @@ from typing import Generator +import logging import random import ollama +logger = logging.getLogger(__name__) + DEFAULT_SYSTEM_PROMPT_FOR_SEARCH_QUEST = ( "You are a helpful assistant tasked with creating a search query based on a directive. " "Output nothing but the search query you create, and do not include any additional commentary or explanation. " @@ -55,7 +58,7 @@ def get_nonempty_ollama_response(messages: list[dict[str, str]]) -> str: if response and response.strip(): return response - print(f"[WARNING] Empty LLM response, retry {attempt + 1}/{MAX_EMPTY_RETRIES}") + logger.warning("Empty LLM response, retry %s/%s", attempt + 1, MAX_EMPTY_RETRIES) raise RuntimeError(f"LLM returned nothing usable after {MAX_EMPTY_RETRIES} attempts") diff --git a/src/log_utils.py b/src/log_utils.py new file mode 100644 index 0000000..58b5b15 --- /dev/null +++ b/src/log_utils.py @@ -0,0 +1,100 @@ +"""Central logging configuration. + +`setup_logging` is called once from `main.py`. Every other module just does +`logger = logging.getLogger(__name__)` at import time, which is safe to do +before this runs, so import order does not matter. +""" + +import logging +import os +import sys + +LEVEL_ENV_VAR = "REWARDS_FARMER_LOG_LEVEL" +FILE_ENV_VAR = "REWARDS_FARMER_LOG_FILE" + +DEFAULT_LEVEL = "INFO" + +# Configuring the root logger switches on output for every library that logs, +# not just ours. httpx emits an info line per ollama call, which buries the +# task summary and puts the ollama endpoint in the log file. print never did +# this because it never touched logging at all, so leaving these at their +# default would make the output noisier than what it replaces. +NOISY_LIBRARIES = ("httpx", "httpcore", "urllib3", "selenium") + +# 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" +DATE_FORMAT = "%H:%M:%S" + +_configured = False + + +def _resolve_level(level: str | int | None) -> int: + """Turn a level name, a level number or None into a level number. + + An unusable value falls back to the default rather than raising. A typo in + an environment variable must not be able to take down an unattended run. + """ + if level is None: + level = os.environ.get(LEVEL_ENV_VAR, DEFAULT_LEVEL) + + if isinstance(level, int): + return level + + resolved = logging.getLevelNamesMapping().get(str(level).strip().upper()) + + if resolved is None: + logging.getLogger(__name__).warning( + "Unknown log level %r, falling back to %s", level, DEFAULT_LEVEL + ) + + return logging.getLevelNamesMapping()[DEFAULT_LEVEL] + + return resolved + + +def setup_logging(level: str | int | None = None, log_file: str | None = None) -> None: + """Configure the root logger. Calling this more than once is a no-op. + + `level` defaults to $REWARDS_FARMER_LOG_LEVEL, then to INFO. + `log_file` defaults to $REWARDS_FARMER_LOG_FILE, and no file is written + when neither is set. + """ + global _configured + + if _configured: + return + + root = logging.getLogger() + root.setLevel(_resolve_level(level)) + + formatter = logging.Formatter(LOG_FORMAT, datefmt=DATE_FORMAT) + + # Card descriptions are scraped from the page and are not ASCII outside the + # en-US market, which the Windows console encoding cannot represent. Replace + # those characters instead of letting the write raise. + if hasattr(sys.stdout, "reconfigure"): + sys.stdout.reconfigure(errors="replace") + + # stdout rather than the StreamHandler default of stderr, because this + # replaces print and anyone already redirecting stdout to a file should + # keep getting the same output there. + console = logging.StreamHandler(sys.stdout) + console.setFormatter(formatter) + root.addHandler(console) + + if log_file is None: + log_file = os.environ.get(FILE_ENV_VAR) + + if log_file: + # utf-8 explicitly. Card descriptions are scraped from the page and are + # not ASCII outside the en-US market, and the Windows default encoding + # would raise on them. + file_handler = logging.FileHandler(log_file, encoding="utf-8") + file_handler.setFormatter(formatter) + root.addHandler(file_handler) + + for name in NOISY_LIBRARIES: + logging.getLogger(name).setLevel(logging.WARNING) + + _configured = True diff --git a/src/main.py b/src/main.py index 2e18910..de5eb89 100644 --- a/src/main.py +++ b/src/main.py @@ -1,9 +1,12 @@ +import log_utils import rewards_tasks import mouse_trajectory import mimic_typing from selenium import webdriver from constants import USER_DATA_DIR, PROFILE_NAME +log_utils.setup_logging() + options = webdriver.EdgeOptions() options.add_experimental_option("excludeSwitches", ["enable-automation"]) diff --git a/src/rewards_tasks.py b/src/rewards_tasks.py index 55773db..bd44190 100644 --- a/src/rewards_tasks.py +++ b/src/rewards_tasks.py @@ -1,3 +1,4 @@ +import logging import os import random import time @@ -17,6 +18,8 @@ import element_selectors VISUAL_SEARCH_IMAGE_PATH = os.path.abspath("visual_search.jpg") +logger = logging.getLogger(__name__) + class RewardsTaskUtils: def __init__(self, driver: webdriver.Edge): self.driver = driver @@ -113,7 +116,10 @@ class RewardsTaskUtils: for card in explore_on_bing_links: if not self.elements.card_is_complete(card): - print(f"[WARNING] Explore on Bing Card [desc={self.elements.extract_card_descriptions(card)!r}] is not complete after searching. Please check manually.") + logger.warning( + "Explore on Bing Card [desc=%r] is not complete after searching. Please check manually.", + self.elements.extract_card_descriptions(card) + ) def complete_visual_search(self): self.switch_to_earn_page() @@ -154,7 +160,10 @@ class RewardsTaskUtils: for card in misc_cards: if not self.elements.card_is_complete(card) and self.elements.get_card_point_value(card) > 0: - print(f"[WARNING] Misc Card [desc={self.elements.extract_card_descriptions(card)!r}] is not complete after clicking. Please check manually.") + logger.warning( + "Misc Card [desc=%r] is not complete after clicking. Please check manually.", + self.elements.extract_card_descriptions(card) + ) self.tab_utils.close_all_other_tabs() @@ -170,7 +179,7 @@ class RewardsTaskUtils: # Measure, search, measure again. points_earned, max_pts = self.read_search_points() - print(f"[INFO] Search points before: {points_earned}/{max_pts}") + logger.info("Search points before: %s/%s", points_earned, max_pts) for round_number in range(1, max_rounds + 1): if points_earned >= max_pts: @@ -184,16 +193,19 @@ class RewardsTaskUtils: previous = points_earned points_earned, max_pts = self.read_search_points() - print(f"[INFO] Round {round_number}: {searches} searches -> {points_earned}/{max_pts}") + logger.info( + "Round %s: %s searches -> %s/%s", + round_number, searches, points_earned, max_pts + ) if points_earned <= previous: - print("[WARNING] Round produced no points, stopping instead of searching pointlessly.") + logger.warning("Round produced no points, stopping instead of searching pointlessly.") break if points_earned < max_pts: - print(f"[WARNING] Search quota not filled: {points_earned}/{max_pts}") + logger.warning("Search quota not filled: %s/%s", points_earned, max_pts) else: - print(f"Search quota complete: {points_earned}/{max_pts}") + logger.info("Search quota complete: %s/%s", points_earned, max_pts) def read_search_points(self): """Open the points breakdown, read the Bing search row, close it again.""" @@ -230,7 +242,10 @@ class RewardsTaskUtils: try: self.wait_for_then_click(self.elements.get_clear_bing_search_query_button) except StaleElementReferenceException: - print(f"[WARNING] StaleElementReferenceException when trying to click the clear button for query {i+1}. Trying again...") + logger.warning( + "StaleElementReferenceException when trying to click the clear button for query %s. Trying again...", + i + 1 + ) self.wait_for_then_click(self.elements.get_clear_bing_search_query_button) self.driver.get("https://rewards.bing.com/") @@ -244,7 +259,7 @@ class RewardsTaskUtils: try: self.wait_for_then_click(self.elements.get_claim_bonus_points_button) except TimeoutException: - print("[WARNING] Could not find the 'Claim Bonus Points' button. There are likely no bonus points to claim at this time.") + logger.warning("Could not find the 'Claim Bonus Points' button. There are likely no bonus points to claim at this time.") def complete_all_tasks(self): # Each task is run independently. The Rewards UI differs by market and @@ -260,13 +275,23 @@ class RewardsTaskUtils: ) for name, step in steps: + # The tags stay in the message rather than being folded into the + # level, they are the per-task outcome summary and reading a run + # means scanning for them. try: step() - print(f"[OK] {name}") + logger.info("[OK] %s", name) except (NoSuchElementException, TimeoutException) as exc: - print(f"[SKIP] {name}: not available in this UI variant ({type(exc).__name__})") + logger.warning("[SKIP] %s: not available in this UI variant (%s)", name, type(exc).__name__) except Exception as exc: - print(f"[FAIL] {name}: {type(exc).__name__}: {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 "", + exc_info=logger.isEnabledFor(logging.DEBUG) + ) # Leave a clean tab state behind for the next task. try: diff --git a/src/tab_utils.py b/src/tab_utils.py index a72012d..b007147 100644 --- a/src/tab_utils.py +++ b/src/tab_utils.py @@ -1,6 +1,9 @@ +import logging from selenium.common.exceptions import WebDriverException, JavascriptException from selenium import webdriver +logger = logging.getLogger(__name__) + GHOST_TAB_URLS = ( "https://ntp.msn.com/edge/ntp?locale=en-US&title=New%20tab&fre=1&dsp=1&sp=Bing&feed_dis=always&en_widget_reg=false&prerender=1&PC=U531", # has fre "https://ntp.msn.com/edge/ntp?locale=en-US&title=New%20tab&dsp=1&sp=Bing&feed_dis=always&en_widget_reg=false&prerender=1&PC=U531" # no fre @@ -30,7 +33,7 @@ document.dispatchEvent(new Event('visibilitychange')); self.driver.switch_to.window(handle) if self.driver.current_url in GHOST_TAB_URLS: - print(f"[INFO] Found ghost tab with handle {handle} and URL {self.driver.current_url}.") + logger.info("Found ghost tab with handle %s and URL %s.", handle, self.driver.current_url) continue self.ensure_focus() @@ -47,17 +50,17 @@ document.dispatchEvent(new Event('visibilitychange')); self.driver.switch_to.window(handle) if self.driver.current_url in GHOST_TAB_URLS: - print(f"[INFO] Found ghost tab with handle {handle} and URL {self.driver.current_url}, not closing.") + logger.info("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() - print(f"[INFO] Closed tab with handle {handle} and URL {tab_url}.") + logger.info("Closed tab with handle %s and URL %s.", handle, tab_url) except WebDriverException: - print(f"[WARNING] Could not close tab with handle {handle} and URL {tab_url}.") + logger.warning("Could not close tab with handle %s and URL %s.", handle, tab_url) self.problematic_tabs.add(handle) pass From 78a4aff5130f017546f245e96de8ccf0e5c2ccc9 Mon Sep 17 00:00:00 2001 From: Ethan Stoner Date: Wed, 26 Aug 2026 11:51:58 -0700 Subject: [PATCH 2/2] 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)