merge the logging work into the feature branch

Both change main.py and README.md, and three separate pull requests touching
the same entry point is worse for review than one. Resolved by keeping every
section of the README and folding the logging setup into the new multi-account
main, so the profile-in-use message from #35 is now a logger.error and uses
log_utils.exception_summary rather than repeating the truncation inline.

queries.py moves to logging with the rest of the runtime.

.gitignore

@@ -1,5 +1,6 @@
 *.png
 *.txt
+*.log
 !nouns.txt
 Todo.md
 data-dir/

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.

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")
 

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

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.")
+		logger.error("[FAIL] %s: could not start Edge with this profile.", account.name)
-		print(f"       profile directory: {account.user_data_dir}")
+		logger.error("       profile directory: %s", account.user_data_dir)
-		print("       The usual cause is that this profile is already open in another")
+		logger.error("       The usual cause is that this profile is already open in another")
-		print("       Edge window, including one left over from a previous run.")
+		logger.error("       Edge window, including one left over from a previous run.")
-		print(f"       driver said: {str(exc).strip().splitlines()[0]}")
+		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:

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)

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:

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