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 53f70f3..2fba250 100644 --- a/README.md +++ b/README.md @@ -108,5 +108,25 @@ REWARDS_ACCOUNTS=personal,spare docker compose run --rm rewards-farmer ``` `REWARDS_HEADLESS=1` is set in the image. It also works on the host if you want a run with no visible window; the pointer code needs an explicit window size in that mode, which `main.py` sets. +# 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..c621c8b --- /dev/null +++ b/src/log_utils.py @@ -0,0 +1,131 @@ +"""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 re +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") + +# 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" +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 ce56060..074a99c 100644 --- a/src/main.py +++ b/src/main.py @@ -1,6 +1,8 @@ +import logging import os import sys +import log_utils import accounts import rewards_tasks import mouse_trajectory @@ -10,6 +12,8 @@ from selenium.common.exceptions import SessionNotCreatedException HEADLESS = os.environ.get("REWARDS_HEADLESS", "").strip().lower() in ("1", "true", "yes") +logger = logging.getLogger(__name__) + def build_options(account: accounts.Account) -> webdriver.EdgeOptions: options = webdriver.EdgeOptions() @@ -41,11 +45,11 @@ def run_account(account: accounts.Account) -> bool: # is already open the driver's copy exits during startup, and selenium # reports it as the browser crashing with a message that names neither # the profile nor the other window. - print(f"[FAIL] {account.name}: could not start Edge with this profile.") - print(f" profile directory: {account.user_data_dir}") - print(" The usual cause is that this profile is already open in another") - print(" Edge window, including one left over from a previous run.") - print(f" driver said: {str(exc).strip().splitlines()[0]}") + logger.error("[FAIL] %s: could not start Edge with this profile.", account.name) + logger.error(" profile directory: %s", account.user_data_dir) + logger.error(" The usual cause is that this profile is already open in another") + logger.error(" Edge window, including one left over from a previous run.") + logger.error(" driver said: %s", log_utils.exception_summary(exc)) return False @@ -62,10 +66,12 @@ def run_account(account: accounts.Account) -> bool: def main() -> int: + log_utils.setup_logging() + try: configured = accounts.configured() except ValueError as exc: - print(f"[FAIL] {exc}") + logger.error("[FAIL] %s", exc) return 2 @@ -73,13 +79,13 @@ def main() -> int: for account in configured: if len(configured) > 1: - print(f"\n=== account: {account.name} ===") + logger.info("=== account: %s ===", account.name) if run_account(account): started += 1 if len(configured) > 1: - print(f"\n{started}/{len(configured)} accounts ran") + logger.info("%s/%s accounts ran", started, len(configured)) # Nothing is watching a container, and stdin is not a terminal there. if not HEADLESS: diff --git a/src/queries.py b/src/queries.py index 98dafad..6f166e7 100644 --- a/src/queries.py +++ b/src/queries.py @@ -11,6 +11,7 @@ The LLM's whole job in this project is producing short strings to type into Bing, and Bing's own autosuggest answers that question directly. """ +import logging import os import query_sources @@ -21,6 +22,8 @@ import query_sources # opposite of the point. A trends-only install, the Docker image for instance, # does not ship it. +logger = logging.getLogger(__name__) + LLM = "llm" TRENDS = "trends" @@ -46,7 +49,7 @@ def search_query_for_task(task_description: str) -> str: # Every feed was unreachable. The description still contains the topic, # so a trimmed version beats skipping the card entirely. - print("[WARNING] No query source reachable, using the task description as written.") + logger.warning("No query source reachable, using the task description as written.") return task_description.lower() @@ -63,7 +66,7 @@ def related_queries(count: int): if queries: return queries - print("[WARNING] No query source reachable, falling back to the wordlist.") + logger.warning("No query source reachable, falling back to the wordlist.") # nouns.txt is already in the repo for exactly this kind of seed. return query_sources.wordlist_queries(count) diff --git a/src/rewards_tasks.py b/src/rewards_tasks.py index b015b0e..1fe3a90 100644 --- a/src/rewards_tasks.py +++ b/src/rewards_tasks.py @@ -1,3 +1,5 @@ +import logging +import log_utils import os import random import time @@ -17,6 +19,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 +117,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 +161,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 +180,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 +194,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.""" @@ -228,7 +241,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/") @@ -242,7 +258,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 @@ -258,13 +274,19 @@ 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}") + logger.error( + "[FAIL] %s: %s: %s", name, type(exc).__name__, log_utils.exception_summary(exc), + 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..b6896a0 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.debug("Found ghost tab with handle %s and URL %s.", handle, self.driver.current_url) continue self.ensure_focus() @@ -47,17 +50,21 @@ 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.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() - print(f"[INFO] Closed tab with handle {handle} and URL {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: - 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