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