From e0744fc799610645657bdeedf115f6bbae008265 Mon Sep 17 00:00:00 2001 From: Nik Afiq Date: Thu, 6 Aug 2026 23:23:41 +0900 Subject: [PATCH] feat: add timestamped log output for better task duration tracking --- ba_daily.py | 48 ++++++++++++++++++++++++++++++++++++++++++++++++ plan.md | 12 ++++++++++++ 2 files changed, 60 insertions(+) diff --git a/ba_daily.py b/ba_daily.py index 1420520..744f433 100644 --- a/ba_daily.py +++ b/ba_daily.py @@ -2,10 +2,53 @@ """Python CLI entry point: ba_dailies.sh -> ba_daily.py -> ba_auto/tasks/*.py""" import os import sys +from datetime import datetime from ba_auto import config, driver, navigation from ba_auto.tasks import arena, battle_pass, bounty, cafe, circle, event_sweep, exit_game, gem_shop, lesson, login, mailbox, scrimmage, shop_common, shop_tactical, stamina, story_sweep, story_sweep_hard + +class _TimestampedStream: + """Wraps a stream so every printed line gets a '[YYYY-MM-DD HH:MM:SS]' + prefix. Installed once on sys.stdout/sys.stderr at process start (see + the __main__ guard at the bottom of this file) so every task module's + existing print() call -- ~300 call sites across ba_daily.py and + ba_auto/ -- gains a timestamp for free, without touching any of them + individually. This is what lets the per-preset cron logs in + ~/ba_logs/ show how long each task/step within a run actually took, + not just the run's own start/finish (which ba_cron_run.sh already + timestamps on its own bracketing lines). + + Buffers partial writes until a newline so a single print() call (which + itself may issue more than one underlying write()) still produces one + timestamped line rather than one timestamp per fragment. + """ + + def __init__(self, stream): + self._stream = stream + self._buffer = "" + + def write(self, data): + self._buffer += data + while "\n" in self._buffer: + line, self._buffer = self._buffer.split("\n", 1) + timestamp = datetime.now().strftime("%Y-%m-%d %H:%M:%S") + self._stream.write(f"[{timestamp}] {line}\n") + self._stream.flush() + return len(data) + + def flush(self): + self._stream.flush() + + def isatty(self): + return self._stream.isatty() + + +def _install_timestamped_output(): + sys.stdout = _TimestampedStream(sys.stdout) + sys.stderr = _TimestampedStream(sys.stderr) + + TASKS = { "login": login.run, "mailbox": mailbox.run, @@ -283,4 +326,9 @@ def main(argv): if __name__ == "__main__": + # Skipped for --list-commands: that output is consumed verbatim by + # completions/ba_dailies.bash as a plain space-separated list, and a + # timestamp prefix would break its parsing. + if not (len(sys.argv) > 1 and sys.argv[1] == "--list-commands"): + _install_timestamped_output() sys.exit(main(sys.argv)) diff --git a/plan.md b/plan.md index 13d5e00..94306fa 100644 --- a/plan.md +++ b/plan.md @@ -1249,6 +1249,18 @@ Confirmed live that Enter -- this flow's established generic fallback for every **Confirmed live end-to-end twice the same day.** First via direct `xdotool`/`scrot` calibration (not through the actual code path). Then, after deploying, a real `./ba_dailies.sh login` run hit an unrelated stuck-loading-buffer timeout, killed and relaunched the game itself, and the still-pending update notice reappeared on that fresh relaunch -- the log shows `[login] update/download notice detected -- clicking OK` immediately followed by `[login] reached home`, and a follow-up screenshot confirmed a genuine, fully-interactive home screen (full HUD: AP 60/240, credits, gems, nav bar). Both the OCR detection and the button click fired correctly on their first real, un-rehearsed encounter through the normal dispatch path, not just the manual calibration walkthrough. +### Phase 29: Timestamped log output (2026-08-06) + +User request: add a timestamp to each log line, to be able to see the time period each process/task takes within a run. + +No reference equivalent -- this is purely local logging plumbing, not game-automation logic. Every task module already prints `[taskname] ...` progress lines (~300 `print()` call sites across `ba_daily.py` and `ba_auto/`), but none of them carried a timestamp; `ba_cron_run.sh` only timestamps its own bracketing start/finish/skip lines around the whole `daily`/`q4h` run, not each task inside it, so a slow or hung step couldn't be pinpointed from the log alone. + +Rather than touch ~300 call sites individually, `ba_daily.py` now installs a `_TimestampedStream` wrapper on both `sys.stdout` and `sys.stderr` once at process start (in the `__main__` guard). It buffers writes until a newline (so one `print()` call, which can issue more than one underlying `write()`, still yields exactly one timestamped line) and prefixes each completed line with `[YYYY-MM-DD HH:MM:SS]`. Every existing `print()` across every task module gets this for free with no per-call-site changes. + +One carve-out: `--list-commands` (the machine-readable list `completions/ba_dailies.bash` parses verbatim for tab completion) skips installing the wrapper entirely, so its output stays a plain space-separated list. + +`bash -n`/`py_compile` passed locally; a standalone probe (`scratchpad/`, deleted after) confirmed the buffering-until-newline behavior against a fake stream, including a `print()` with multiple args and a raw multi-part `write()` sequence with no trailing newline until the last call, both collapsing to one timestamped line each. Deployed via the standard `rsync` push and confirmed live on nik-gpu: `./ba_dailies.sh pause_status`/`./ba_dailies.sh ` both show real `[2026-08-06 HH:MM:SS]`-prefixed output (including the stderr "Unknown phase" path), while `python3 ba_daily.py --list-commands` still returns the plain unprefixed command list the completion script expects. + ## Prerequisites ### OCR