feat: add timestamped log output for better task duration tracking

This commit is contained in:
Nik Afiq 2026-08-06 23:23:41 +09:00
parent ff240cb104
commit e0744fc799
2 changed files with 60 additions and 0 deletions

View File

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

12
plan.md
View File

@ -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 <bogus>` 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