Initial Commit
This commit is contained in:
@@ -0,0 +1,280 @@
|
||||
"""A durable record of what one session actually did.
|
||||
|
||||
WHY THIS EXISTS
|
||||
|
||||
Everything needed to answer "did the agent open the app and look at it"
|
||||
was already being recorded - `_record()` has covered screenshot, click,
|
||||
key and type since they were written - and all of it was thrown away when
|
||||
the session ended. What survived was the tool result and Open WebUI's
|
||||
status history, and neither can answer the question:
|
||||
|
||||
* the report counts `run` and nothing else, so a session that claimed to
|
||||
click through a GUI and never called `click` reads exactly like one
|
||||
that did;
|
||||
* the status history is SAMPLED. The filter polls every two seconds and
|
||||
reads whatever the status happens to say, so a verb that returns
|
||||
quickly - a screenshot, a click - is usually overwritten before it is
|
||||
ever seen. Measured on a real session: 456 samples caught `launch_app`
|
||||
nine times, because it blocks for seconds, and caught not one of the
|
||||
screenshots that demonstrably happened.
|
||||
|
||||
So the question was being answered from the two records that cannot
|
||||
answer it, by a reader who had to guess which run they were even looking
|
||||
at. This writes the transcript to disk as it happens instead: every verb,
|
||||
in order, with the model's own words between them, one file per session,
|
||||
named so the newest is last.
|
||||
|
||||
NOTHING HERE MAY TAKE A SESSION DOWN. It is a record of the work, not
|
||||
part of it - the same rule the live view is held to, for the same reason.
|
||||
Every call is wrapped and a failure costs a line of the log, never a step
|
||||
of the session.
|
||||
"""
|
||||
|
||||
from __future__ import annotations
|
||||
|
||||
import json
|
||||
import os
|
||||
import sys
|
||||
import time
|
||||
|
||||
LOG_DIR = os.environ.get("OWUITOOLS_VM_LOG_DIR", "/var/lib/owuivm/sessions")
|
||||
# Roughly a fortnight of heavy use. These are small - a long session runs
|
||||
# to a few hundred KB - and the oldest is dropped when a new one opens.
|
||||
KEEP_SESSIONS = int(os.environ.get("OWUITOOLS_VM_LOG_KEEP", "60"))
|
||||
|
||||
# The model's words are the bulkiest thing in here and the least useful at
|
||||
# length; a couple of sentences is enough to see what it thought it was
|
||||
# doing before each call.
|
||||
NOTE_CHARS = 700
|
||||
|
||||
|
||||
class SessionLog:
|
||||
"""One file, appended to and flushed as the session runs.
|
||||
|
||||
Flushed on every line on purpose. A session that is killed - the step
|
||||
budget, a cancel, the machine dying - is exactly the session whose log
|
||||
someone will want, so the log must not be sitting in a buffer when it
|
||||
happens.
|
||||
"""
|
||||
|
||||
def __init__(self, path: str, started: float) -> None:
|
||||
self.path = path
|
||||
self.started = started
|
||||
self._handle = open(path, "a", encoding="utf-8")
|
||||
|
||||
def write(self, kind: str, **fields) -> None:
|
||||
try:
|
||||
record = {"at": round(time.time() - self.started, 2), "kind": kind}
|
||||
for key, value in fields.items():
|
||||
if value is not None:
|
||||
record[key] = value
|
||||
self._handle.write(json.dumps(record, default=str) + "\n")
|
||||
self._handle.flush()
|
||||
except Exception: # noqa: BLE001 - a log may never break the work
|
||||
pass
|
||||
|
||||
def close(self, **summary) -> None:
|
||||
try:
|
||||
self.write("end", **summary)
|
||||
self._handle.close()
|
||||
except Exception: # noqa: BLE001
|
||||
pass
|
||||
|
||||
|
||||
def open_log(session_id: str, **meta) -> SessionLog | None:
|
||||
"""Start a log for a session. Returns None if it cannot, never raises."""
|
||||
try:
|
||||
os.makedirs(LOG_DIR, mode=0o750, exist_ok=True)
|
||||
started = time.time()
|
||||
stamp = time.strftime("%Y%m%d-%H%M%S", time.localtime(started))
|
||||
path = os.path.join(LOG_DIR, f"{stamp}-{str(session_id)[:8]}.jsonl")
|
||||
log = SessionLog(path, started)
|
||||
os.chmod(path, 0o640)
|
||||
log.write("start", session=session_id,
|
||||
when=time.strftime("%Y-%m-%d %H:%M:%S", time.localtime(started)),
|
||||
**meta)
|
||||
_rotate()
|
||||
return log
|
||||
except Exception as exc: # noqa: BLE001
|
||||
# SILENT IS NOT THE SAME AS HARMLESS.
|
||||
#
|
||||
# A log may never break a session, so this returns None and the
|
||||
# work goes on. But the first version of this failed for every
|
||||
# session and looked exactly like a session that had nothing to
|
||||
# record: the daemon runs under ProtectSystem=strict and the log
|
||||
# directory was not in ReadWritePaths, so every write was denied
|
||||
# and swallowed. Saying so costs one line in the journal and is
|
||||
# the difference between a missing feature and a mystery.
|
||||
print(f"vmd: could not open the session log in {LOG_DIR}: {exc}",
|
||||
file=sys.stderr, flush=True)
|
||||
return None
|
||||
|
||||
|
||||
def _rotate() -> None:
|
||||
try:
|
||||
names = sorted(n for n in os.listdir(LOG_DIR) if n.endswith(".jsonl"))
|
||||
for name in names[:-KEEP_SESSIONS] if len(names) > KEEP_SESSIONS else []:
|
||||
os.unlink(os.path.join(LOG_DIR, name))
|
||||
except Exception: # noqa: BLE001
|
||||
pass
|
||||
|
||||
|
||||
# ---------------------------------------------------------------------
|
||||
# reading them back
|
||||
# ---------------------------------------------------------------------
|
||||
def load(path: str) -> list[dict]:
|
||||
records: list[dict] = []
|
||||
with open(path, encoding="utf-8", errors="replace") as handle:
|
||||
for line in handle:
|
||||
line = line.strip()
|
||||
if not line:
|
||||
continue
|
||||
try:
|
||||
records.append(json.loads(line))
|
||||
except ValueError:
|
||||
continue
|
||||
return records
|
||||
|
||||
|
||||
def sessions() -> list[dict]:
|
||||
"""Every log on disk, oldest first, with enough to choose between them."""
|
||||
out: list[dict] = []
|
||||
try:
|
||||
names = sorted(n for n in os.listdir(LOG_DIR) if n.endswith(".jsonl"))
|
||||
except OSError:
|
||||
return out
|
||||
for name in names:
|
||||
path = os.path.join(LOG_DIR, name)
|
||||
head: dict = {}
|
||||
tail: dict = {}
|
||||
try:
|
||||
records = load(path)
|
||||
except OSError:
|
||||
continue
|
||||
for record in records:
|
||||
if record.get("kind") == "start":
|
||||
head = record
|
||||
elif record.get("kind") == "end":
|
||||
tail = record
|
||||
out.append({
|
||||
"file": name, "path": path,
|
||||
"session": head.get("session", ""), "chat": head.get("chat", ""),
|
||||
"os": head.get("os", ""), "project": head.get("project", ""),
|
||||
"when": head.get("when", ""), "task": head.get("task", ""),
|
||||
"seconds": tail.get("at"), "outcome": tail.get("outcome", "(unfinished)"),
|
||||
"records": len(records),
|
||||
})
|
||||
return out
|
||||
|
||||
|
||||
def census(records: list[dict]) -> dict[str, int]:
|
||||
"""How many times each verb was actually called.
|
||||
|
||||
This is the line that answers "did it ever look at the screen", and it
|
||||
answers it with a number rather than with the agent's opinion of
|
||||
itself.
|
||||
"""
|
||||
counts: dict[str, int] = {}
|
||||
for record in records:
|
||||
kind = str(record.get("kind", ""))
|
||||
if kind in ("start", "end", "note"):
|
||||
continue
|
||||
counts[kind] = counts.get(kind, 0) + 1
|
||||
return dict(sorted(counts.items(), key=lambda kv: (-kv[1], kv[0])))
|
||||
|
||||
|
||||
def _clock(seconds: float) -> str:
|
||||
seconds = max(0.0, float(seconds or 0))
|
||||
return f"{int(seconds // 60):>3}:{seconds % 60:04.1f}"
|
||||
|
||||
|
||||
def _detail(record: dict) -> str:
|
||||
"""One line describing a verb, in the terms the verb was called in."""
|
||||
kind = record.get("kind", "")
|
||||
get = record.get
|
||||
match kind:
|
||||
case "run":
|
||||
code = get("exit_code")
|
||||
head = "timed out" if get("timed_out") else f"exit {code}"
|
||||
took = f" {get('seconds')}s" if get("seconds") is not None else ""
|
||||
return f"{head}{took} {str(get('command', ''))[:120]}"
|
||||
case "write_file" | "append_file":
|
||||
return f"{get('path', '')} ({get('bytes', 0)} bytes)"
|
||||
case "edit_file":
|
||||
return f"{get('path', '')} ({get('replaced', 0)} replaced)"
|
||||
case "read_file" | "list_dir":
|
||||
return str(get("path", ""))
|
||||
case "screenshot":
|
||||
return f"{get('width')}x{get('height')} ({int(get('bytes', 0) / 1024)} KB)"
|
||||
case "click" | "move" | "scroll":
|
||||
return f"({get('x')}, {get('y')})"
|
||||
case "key":
|
||||
return str(get("keys", ""))
|
||||
case "type":
|
||||
return f"{get('chars', 0)} characters"
|
||||
case "launch_app" | "open_page":
|
||||
return str(get("path") or get("url") or "")
|
||||
case "plan":
|
||||
return f"{get('count', 0)} tasks"
|
||||
case "task":
|
||||
return f"#{get('id')} -> {get('status')}"
|
||||
case "task_added":
|
||||
return str(get("text", ""))
|
||||
case "commit":
|
||||
return f"{get('sha') or '(nothing to commit)'} {str(get('message', ''))[:80]}"
|
||||
case "push" | "release":
|
||||
return str(get("url", ""))
|
||||
case "ready":
|
||||
return f"booted in {get('seconds', '?')}s"
|
||||
case "finish":
|
||||
return f"verified={get('verified')}"
|
||||
case "wait":
|
||||
return f"{get('seconds', '?')}s"
|
||||
case _:
|
||||
extra = {k: v for k, v in record.items() if k not in ("at", "kind")}
|
||||
return json.dumps(extra, default=str)[:160] if extra else ""
|
||||
|
||||
|
||||
def render(path: str) -> str:
|
||||
"""The whole session as something a person can read top to bottom."""
|
||||
records = load(path)
|
||||
head = next((r for r in records if r.get("kind") == "start"), {})
|
||||
tail = next((r for r in records if r.get("kind") == "end"), {})
|
||||
lines: list[str] = []
|
||||
|
||||
lines.append(f"session {head.get('session', '?')} {head.get('os', '?')}"
|
||||
+ (f" project {head['project']}" if head.get("project") else ""))
|
||||
if head.get("chat"):
|
||||
lines.append(f"chat {head['chat']}")
|
||||
when = head.get("when", "?")
|
||||
if tail.get("at") is not None:
|
||||
took = float(tail["at"])
|
||||
lines.append(f"ran {when} for {int(took // 60)}m {int(took % 60)}s"
|
||||
f" ({tail.get('outcome', '')})")
|
||||
else:
|
||||
lines.append(f"ran {when} (no end recorded - the session was cut short)")
|
||||
if head.get("task"):
|
||||
lines.append(f"asked {str(head['task'])[:300]}")
|
||||
lines.append("")
|
||||
|
||||
for record in records:
|
||||
kind = record.get("kind", "")
|
||||
if kind in ("start", "end"):
|
||||
continue
|
||||
stamp = _clock(record.get("at", 0))
|
||||
if kind == "note":
|
||||
text = " ".join(str(record.get("text", "")).split())
|
||||
if not text:
|
||||
continue
|
||||
lines.append(f"{stamp} · turn {record.get('turn', '?')}: {text[:NOTE_CHARS]}")
|
||||
continue
|
||||
lines.append(f"{stamp} {kind:<14} {_detail(record)}".rstrip())
|
||||
|
||||
counts = census(records)
|
||||
lines.append("")
|
||||
lines.append("what it actually did: "
|
||||
+ (", ".join(f"{v}x {k}" for k, v in counts.items()) or "nothing"))
|
||||
for verb in ("screenshot", "click", "type", "key"):
|
||||
if verb not in counts:
|
||||
lines.append(f" it never called {verb}")
|
||||
return "\n".join(lines)
|
||||
Reference in New Issue
Block a user