feat(log): constant town timeline — every maintenance step start/ok/skip/fail

Town maintenance was only traceable by piecing together scattered messages, and a step
that silently did nothing was indistinguishable from one that never ran. Every step now
emits the same stable, machine-readable line:

    grep "TOWN>" log/log.txt

    TOWN> g2 r2 | maintenance      | start | at a5_town_start
    TOWN> g2 r2 | town_heal        | start
    TOWN> g2 r2 | inspect_inventory | ok    | in pack=0 keep=0 sell=0 gold_full=False
    TOWN> g2 r2 | buy_consumables  | start | needs id=0 tp=0 hp=4 mana=0 rejuv=0 | sell_pending=0
    TOWN> g2 r2 | buy_consumables  | ok    | at a4_jamella | after: Consumables(...)
    TOWN> g2 r2 | stash_items      | skip  | nothing kept and gold not full
    TOWN> g2 r2 | repair           | skip  | no repair due and nothing to sell
    TOWN> g2 r2 | resurrect_merc   | start
    TOWN> g2 r2 | gamble           | skip  | stash not full / gambling not configured
    TOWN> g2 r2 | maintenance      | ok    | done in 21s | at a4_jamella

Covers shop, id, stash, repair, sell, resurrect and gamble. status is start|ok|skip|fail,
and skip states the reason. Steps carry useful detail: consumable needs before and after
buying, pack contents and keep/sell counts, repair trigger, items left in the pack after
stashing, and total maintenance duration.

Individual item transfers mirror into the same stream from transfer_items() as
item_sell / item_stash / item_drop, so vendoring a rare or stashing a rune appears inline
with the steps around it.

_step() also sets _maintenance_step, so the existing failure-reporting path is unchanged.
The ">" in the prefix is deliberate: a bare "TOWN" collides with template names such as
A5_TOWN_0.

Immediately useful — the first two games after this landed showed "done in 225s" with
buy_consumables failing against "done in 21s" with it succeeding.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
This commit is contained in:
alexpolo1
2026-08-27 17:38:33 +02:00
parent e976749910
commit f01610e53f
3 changed files with 98 additions and 9 deletions

View File

@@ -659,6 +659,42 @@ paths; don't unify them.
---
## The town timeline — `grep "TOWN>"`
Every town-maintenance step reports start and outcome in one stable, machine-readable
shape, so a whole town visit reads as a sequence:
```bash
grep "TOWN>" log/log.txt
```
```
TOWN> g2 r2 | maintenance | start | at a5_town_start
TOWN> g2 r2 | town_heal | start
TOWN> g2 r2 | inspect_inventory | ok | in pack=0 keep=0 sell=0 gold_full=False
TOWN> g2 r2 | buy_consumables | start | needs id=0 tp=0 hp=4 mana=0 rejuv=0 | sell_pending=0
TOWN> g2 r2 | buy_consumables | ok | at a4_jamella | after: Consumables(...)
TOWN> g2 r2 | stash_items | skip | nothing kept and gold not full
TOWN> g2 r2 | repair | skip | no repair due and nothing to sell
TOWN> g2 r2 | resurrect_merc | start
TOWN> g2 r2 | gamble | skip | stash not full / gambling not configured
TOWN> g2 r2 | maintenance | ok | done in 21s | at a4_jamella
```
- `status` is one of **start | ok | skip | fail**. `skip` says *why* it was skipped, so a
step that silently did nothing is now distinguishable from one that never ran.
- Individual item transfers mirror into the same stream from
`inventory/personal.py::transfer_items` as `item_sell` / `item_stash` / `item_drop`, so
vendoring a rare and stashing a rune appear inline with the steps around them.
- The `maintenance ok` line carries total duration — the fastest way to spot a slow town
visit. Example from the first run after this landed: `done in 225s` with
`buy_consumables | fail` versus `done in 21s` with `ok` the next game.
Emitted by `_step()` inside `Bot.on_maintenance` (`src/bot.py`). **Keep the format stable** —
it is meant to be grepped, not read as prose. The `>` in the prefix matters: a bare `TOWN`
also matches template names like `A5_TOWN_0`.
---
## Verifying a boss run actually worked
Learned the hard way (Bug 24). Log lines and `failed:false` are **not** proof of a kill.

View File

@@ -463,6 +463,25 @@ class Bot:
return True
return False
def _step(step: str, status: str = "start", detail: str = "") -> None:
"""Emit one line of the town-maintenance timeline.
Every step reports start and outcome in the same shape so a whole town visit
can be read (or grepped) as a sequence:
grep "TOWN>" log/log.txt
status is one of: start | ok | skip | fail. Keep the format stable — it is
meant to be machine-readable, not prose.
"""
if status == "start":
self._maintenance_step = step
gs = self._game_stats
head = f"TOWN> g{getattr(gs, '_game_counter', 0)} r{getattr(gs, '_run_counter', 0)} | {step:<16} | {status:<5}"
line = f"{head} | {detail}" if detail else head
(Logger.warning if status == "fail" else Logger.info)(line)
self._step_fn = _step
_step("maintenance", "start", f"at {self._curr_loc}")
# Dismiss skill/quest/help/stats icon if they are on screen
if not view.dismiss_skills_icon():
view.return_to_play()
@@ -473,7 +492,7 @@ class Bot:
# Drinks health first (cheaper), then rejuv as fallback if health is unavailable.
# Happens before update_pot_needs so the reduced belt is accurately counted
# and the buy step will restock whatever was drunk.
self._maintenance_step = "town_heal"
_step("town_heal")
_town_heal_threshold = 0.95
_town_heal_max_drinks = 5
for _drink_attempt in range(_town_heal_max_drinks):
@@ -501,7 +520,7 @@ class Bot:
Logger.info(f"We are running trav and have full rejuvs so skipping {skipped_run}")
# Inspect inventory
self._maintenance_step = "inspect_inventory"
_step("inspect_inventory")
items = None
need_inspect = self._picked_up_items or self._previous_run_failed
if Config().char["runs_per_stash"]:
@@ -535,21 +554,26 @@ class Bot:
if any([item.need_id for item in items]):
if _maint_timed_out("identify_items"): return
Logger.info("ID items at cain")
self._maintenance_step = "identify_items"
_step("identify_items", "start", f"items needing id={sum(1 for i in items if getattr(i, 'need_id', False))}")
self._curr_loc = self._town_manager.identify(self._curr_loc)
if self._curr_loc is True:
Logger.warning("identify() returned True (unexpected location) — re-detecting town act")
self._curr_loc = self._verify_town_location()
if not self._curr_loc:
_step("identify_items", "fail", "Cain not available — continuing unidentified")
Logger.warning("Could not identify items (Cain not available). Continuing without ID.")
self._curr_loc = self._verify_town_location()
else:
# recheck inventory
items = personal.inspect_items(game_stats=self._game_stats)
_step("identify_items", "ok", f"at {self._curr_loc}")
keep_items = any([item.keep for item in items]) if items else None
sell_items = any([item.sell for item in items]) if items else None
sell_count = sum(1 for item in items if item.sell) if items else 0
stash_gold = personal.get_inventory_gold_full()
_step("inspect_inventory", "ok",
f"in pack={len(items) if items else 0} keep={sum(1 for i in items if i.keep) if items else 0} "
f"sell={sell_count} gold_full={bool(stash_gold)}")
# Check if should need some healing
img = grab()
@@ -573,7 +597,10 @@ class Bot:
if need_refill or sell_count >= 3:
if _maint_timed_out("buy_consumables"): return
Logger.info("Buy consumables and/or sell items")
self._maintenance_step = "buy_consumables"
_step("buy_consumables", "start",
f"needs id={consumables.get_needs('id')} tp={consumables.get_needs('tp')} "
f"hp={consumables.get_needs('health')} mana={consumables.get_needs('mana')} "
f"rejuv={consumables.get_needs('rejuv')} | sell_pending={sell_count}")
prev_buy_loc = self._curr_loc
# A5 Malah is unreliable in the current patch (wandering NPC, stale body
# templates — fails most games). Buy at A4 Jamella instead when in A5.
@@ -592,6 +619,7 @@ class Bot:
items = result_items
sell_items = any([item.sell for item in items]) if items else None
Logger.debug(f"Needs: {consumables.get_needs()}")
_step("buy_consumables", "ok", f"at {self._curr_loc} | after: {consumables.get_needs()}")
else:
Logger.warning("Buy consumables failed, retrying in current act")
wait(0.5, 0.6)
@@ -622,12 +650,13 @@ class Bot:
# here — that skips the stash step and strands picked-up runes/items
# in inventory forever. Re-anchor and fall through to stash.
reason = "Buy consumables failed (vendor not found) — continuing to stash without buying"
_step("buy_consumables", "fail", "vendor not found after retries — continuing to stash")
Logger.warning(reason)
self._save_error_screenshot("maintenance", reason)
self._curr_loc = self._verify_town_location(prev_buy_loc)
elif meters.get_health(img) <= Config().char["take_rejuv_potion_health"] or meters.get_mana(img) <= Config().char["take_rejuv_potion_mana"]:
Logger.info("Healing at next possible Vendor")
self._maintenance_step = "heal"
_step("heal")
prev_heal_loc = self._curr_loc
self._curr_loc = self._town_manager.heal(self._curr_loc)
if not self._curr_loc:
@@ -635,6 +664,7 @@ class Bot:
wait(0.5, 0.6)
self._curr_loc = self._town_manager.heal(self._verify_town_location(prev_heal_loc))
if not self._curr_loc:
_step("heal", "fail", "healer not reachable")
Logger.warning("Heal failed after retry, continuing without heal")
self._curr_loc = self._verify_town_location(prev_heal_loc)
@@ -646,10 +676,12 @@ class Bot:
belt.update_pot_needs()
# Stash stuff
if not (keep_items or stash_gold):
_step("stash_items", "skip", "nothing kept and gold not full")
if keep_items or stash_gold:
if _maint_timed_out("stash_items"): return
Logger.info("Stashing items")
self._maintenance_step = "stash_items"
_step("stash_items", "start", f"keep_items={bool(keep_items)} gold_full={bool(stash_gold)}")
prev_loc = self._curr_loc
self._curr_loc, result_items = self._town_manager.stash(self._curr_loc, items=items, game_stats=self._game_stats)
if not self._curr_loc:
@@ -659,6 +691,7 @@ class Bot:
self._curr_loc, result_items = self._town_manager.stash(self._verify_town_location(prev_loc), items=items, game_stats=self._game_stats)
if not self._curr_loc:
reason = "Maintenance failed [step: stash_items] — stash NPC not found after retry"
_step("stash_items", "fail", "stash not found after retry — ending game")
Logger.error(reason)
self._save_error_screenshot("maintenance", reason)
if not self._game_stats.get_failure_reason():
@@ -666,6 +699,7 @@ class Bot:
self.trigger_or_stop("end_game", failed=True)
return
sell_items = any([item.sell for item in result_items]) if result_items else None
_step("stash_items", "ok", f"at {self._curr_loc} | left in pack={len(result_items) if result_items else 0}")
#Acquire mutex to prevent controller from killing thread during transmutes
self._stash_mutex.acquire()
Logger.info("Running transmutes")
@@ -704,6 +738,8 @@ class Bot:
need_repair = is_visible(ScreenObjects.NeedRepair)
need_routine_repair = False if not Config().char["runs_per_repair"] else self._game_stats._run_counter % Config().char["runs_per_repair"] == 0
need_refill_teleport = self._char.capabilities.can_teleport_with_charges and (not self._char.select_tp() or self._char.is_low_on_teleport_charges())
if not (need_repair or need_routine_repair or need_refill_teleport or sell_items):
_step("repair", "skip", "no repair due and nothing to sell")
if need_repair or need_routine_repair or need_refill_teleport or sell_items:
if _maint_timed_out("repair"): return
if need_repair:
@@ -714,7 +750,10 @@ class Bot:
Logger.info("Teleport charges ran out. Need to repair")
elif sell_items:
Logger.info("Selling items at repair vendor")
self._maintenance_step = "repair"
_reason = ("gear about to break" if need_repair else
"routine" if need_routine_repair else
"tp charges" if need_refill_teleport else "sell items")
_step("repair", "start", f"reason={_reason} sell_pending={bool(sell_items)}")
prev_repair_loc = self._curr_loc
self._curr_loc, result_items = self._town_manager.repair(self._curr_loc, items)
if not self._curr_loc:
@@ -723,7 +762,9 @@ class Bot:
self._curr_loc, result_items = self._town_manager.repair(self._verify_town_location(prev_repair_loc), items)
if self._curr_loc:
items = result_items
_step("repair", "ok", f"at {self._curr_loc}")
if not self._curr_loc:
_step("repair", "fail", "vendor not found — non-fatal, continuing")
# Keep maintenance best-effort for stability: avoid killing runs on flaky NPC/vendor detection.
# IMPORTANT: re-detect the act — a failed repair trip may have left us in A4,
# and assuming A5 here poisons the next run's waypoint pathing AND the act
@@ -738,7 +779,7 @@ class Bot:
# Check if merc needs to be revived
if _maint_timed_out("resurrect_merc"): return
self._maintenance_step = "resurrect_merc"
_step("resurrect_merc")
if Config().char["use_merc"]:
merc_visible = False
try:
@@ -764,6 +805,7 @@ class Bot:
f"Skipping merc resurrect until game {skip_until} "
f"(resurrect NPC unreachable {getattr(gs, '_merc_resurrect_fail_streak', 0)}x in a row)"
)
_step("resurrect_merc", "skip", f"breaker active until game {skip_until}")
merc_visible = True # suppress this game's attempt without touching state
if not merc_visible and not self._game_stats._merc_resurrect_failed:
Logger.info("Resurrect merc")
@@ -779,6 +821,7 @@ class Bot:
Logger.warning("Resurrect failed — skipping the retry, this NPC has been unreachable")
if new_loc is False:
# Failed to resurrect (can't afford or other error) - don't log death, just continue
_step("resurrect_merc", "fail", "NPC not reachable — continuing mercless")
Logger.warning("Failed to resurrect merc after retry, continuing without merc")
self._game_stats._merc_resurrect_failed = True
gs._merc_resurrect_fail_streak = getattr(gs, "_merc_resurrect_fail_streak", 0) + 1
@@ -799,6 +842,7 @@ class Bot:
Logger.warning("Resurrect returned None, continuing at current location")
pass
else:
_step("resurrect_merc", "ok", f"at {new_loc}")
self._game_stats.log_merc_death()
self._curr_loc = new_loc
# It worked — clear the breaker so a transient failure never
@@ -808,11 +852,15 @@ class Bot:
# Gamble if needed
if _maint_timed_out("gamble"): return
self._maintenance_step = "gamble"
if not (vendor.get_gamble_status() and Config().char["gamble_items"]):
_step("gamble", "skip", "stash not full / gambling not configured")
else:
_step("gamble")
while vendor.get_gamble_status() and Config().char["gamble_items"]:
Logger.debug("Head to gamble")
self._curr_loc = self._town_manager.gamble(self._curr_loc)
if not self._curr_loc:
_step("gamble", "fail", "gamble vendor not reachable")
Logger.warning("Gamble failed, skipping gamble")
self._curr_loc = self._verify_town_location()
break
@@ -825,6 +873,8 @@ class Bot:
self._curr_loc = self._verify_town_location()
break
_step("maintenance", "ok", f"done in {time.time() - _maint_start:.0f}s | at {self._curr_loc}")
# Start a new run
started_run = False
self._previous_run_failed = False

View File

@@ -541,6 +541,9 @@ def transfer_items(items: list, action: str = "drop", img: np.ndarray = None) ->
# item successfully transferred, delete from list
item_label = f" '{item.name}'" if item.name else ""
Logger.debug(f"Confirmed {action}{item_label} at position {item.pos}")
# Mirror into the TOWN timeline so sells/stashes/drops of individual items
# appear in the same greppable sequence as the maintenance steps.
Logger.info(f"TOWN> | item_{action:<11} | ok | {item.name or '?'} @ {item.pos}")
for cnt, o_item in enumerate(items):
if o_item.pos == item.pos:
items.pop(cnt)