diff --git a/README.md b/README.md index 3b462d9..93126bb 100644 --- a/README.md +++ b/README.md @@ -1,8 +1,9 @@ # stern-event-agent A passive gameplay-event logger for Stern Spike 2 pinball, developed against -**King Kong LE 0.97**. It records the game's own events with millisecond -timestamps — the game is not modified, nothing scores, nothing blocks. +**King Kong LE 0.97**. It records the game's own events with RFC 3339 UTC +timestamps (millisecond precision) — the game is not modified, nothing scores, +nothing blocks. The logger is a PAD mode: a small shared object (`mode.so`) that the game process loads via `LD_PRELOAD`. It hooks function sites inside the game, and @@ -44,24 +45,24 @@ framework) and added to `ports/king_kong_le-0.97.port`. ### `/dump/mode.log` (deployed) -Append-only, millisecond stamps relative to the runtime loading, survives +Append-only, RFC 3339 UTC stamps with millisecond precision, survives reboots: ``` [pad] port ...: king_kong_le 0.97, 121 sites, 55 shots <- runtime armed (all hook words verified) -[GAMELOG] up: game king_kong_le 0.97, 55 named shots; event ids 77/37/52/40/200/198; extra_ball_award=13 -[GAMELOG] +2408751ms EV game_start - GAME START -[GAMELOG] +2408751ms EV ball_start player=1 ball=1 score=0 -[GAMELOG] +2424007ms SHOT X1 player=1 ball=1 score=7,349,830 <- all 55 named shots -[GAMELOG] +2644003ms EV ball_end player=1 ball=1 score=91,153,090 -[GAMELOG] +2644003ms EV bonus_end -[GAMELOG] +2644003ms SCORES P1=95,421,190 P2=0 P3=0 P4=0 -[GAMELOG] +...ms EV tilt_warning player=1 -[GAMELOG] +...ms EV tilt player=1 ball=2 -[pad] gamelog: MODE START 5 (Island Scene Escape the Swamp) player=1 score=... -[pad] gamelog: MODE END 5 (Island Scene Escape the Swamp) player=1 score=... mode_score=... dur=...ms -[GAMELOG] +...ms AWARD EXTRA BALL (id=13) player=1 <- next ball logs as "ball N (EXTRA BALL)" -[GAMELOG] +...ms AWARD id= player=1 score=... <- every award screen +[GAMELOG] 2026-10-12T20:45:12.123Z up: game king_kong_le 0.97, 55 named shots; event ids 77/37/52/40/200/198; extra_ball_award=13 +[GAMELOG] 2026-10-12T20:45:12.123Z EV game_start - GAME START +[GAMELOG] 2026-10-12T20:45:12.123Z EV ball_start player=1 ball=1 score=0 +[GAMELOG] 2026-10-12T20:45:12.123Z SHOT X1 player=1 ball=1 score=7,349,830 <- all 55 named shots +[GAMELOG] 2026-10-12T20:45:12.123Z EV ball_end player=1 ball=1 score=91,153,090 +[GAMELOG] 2026-10-12T20:45:12.123Z EV bonus_end +[GAMELOG] 2026-10-12T20:45:12.123Z SCORES P1=95,421,190 P2=0 P3=0 P4=0 +[GAMELOG] 2026-10-12T20:45:12.123Z EV tilt_warning player=1 +[GAMELOG] 2026-10-12T20:45:12.123Z EV tilt player=1 ball=2 +[pad] gamelog: 2026-10-12T20:45:12.123Z MODE START 5 (Island Scene Escape the Swamp) player=1 score=... +[pad] gamelog: 2026-10-12T20:45:12.123Z MODE END 5 (Island Scene Escape the Swamp) player=1 score=... mode_score=... dur=...ms +[GAMELOG] 2026-10-12T20:45:12.123Z AWARD EXTRA BALL (id=13) player=1 <- next ball logs as "ball N (EXTRA BALL)" +[GAMELOG] 2026-10-12T20:45:12.123Z AWARD id= player=1 score=... <- every award screen ``` Bus event ids (King Kong 0.97): `game_start`=0x4d, `ball_start`=0x25, @@ -86,18 +87,22 @@ flow exactly as stock (and are logged once), and the logger adds no scores of its own. Known cosmetic issue: the boot banner still prints the upstream "score reports stay on this machine" line — the later `passive gate` line is the truth. -### `/dump/switch.log` (implemented, not yet deployed) +### `/dump/switch.log` (deployed) -The runtime's switch-edge handler writes **every edge of every switch** to -`/dump/switch.log` — buttons included, attract included: +The runtime's switch-edge handler writes every edge of the human-activated +buttons to `/dump/switch.log` — the lockdown/action button (34), the start +button (36) and the two flipper buttons (62/63), attract included. Names are +quoted; the upper-flipper button switches (64/65) are wired in parallel with +the main flipper buttons on this cabinet, so they are left out: ``` - SW level=<0|1> hit=<0|1> game=<0|1> +2026-10-12T20:45:12.123Z SW "" level=<0|1> hit=<0|1> game=<0|1> ``` `level` is the switch's raw state after the edge, `hit` is the game's own -"counts as a hit" verdict, `game` whether a player is up. Names come from -`switch_names.inc`; an id not in the table logs `?`. +"counts as a hit" verdict, `game` whether a player is up. The logged ids are +the `gl_buttons[]` list in the runtime's switch-edge handler; names come from +`switch_names.inc`. ## Build diff --git a/gamelog.c b/gamelog.c index e28cf17..0b52a40 100644 --- a/gamelog.c +++ b/gamelog.c @@ -1,6 +1,6 @@ /* GAMELOG - a passive gameplay-event logger for Stern Spike 2. * - * Logs, with millisecond timestamps, to /dump/mode.log: + * Logs, with RFC 3339 UTC timestamps (millisecond precision), to /dump/mode.log: * EV - the game's bus events (game start, ball start/end, * bonus end, tilt warning, tilt), player, ball, score * SHOT - every shot the game dispatches while a ball is up @@ -19,28 +19,11 @@ #include "pad_mode.h" -/* -nostdlib: the few libc symbols resolve from the game's own libc at load, - * exactly as the runtime's and event_probe.c's do. */ -extern int clock_gettime(int, void *); - -/* the runtime patch exposes the award screens it sees */ +/* the runtime patch exposes the award screens it sees and the wall clock */ extern unsigned long gl_award_seq(void); extern unsigned gl_last_award_id(void); +extern void gl_rfc3339(char *buf, unsigned cap); -#define CLOCK_MONOTONIC 1 - -struct ts { - long sec, nsec; -}; - -static unsigned long ms(void) -{ - struct ts t; - clock_gettime(CLOCK_MONOTONIC, &t); - return (unsigned long)t.sec * 1000ul + (unsigned long)t.nsec / 1000000ul; -} - -static unsigned long t0; /* ms at .init, so stamps start near 0 */ static unsigned ball; /* ball in play, 1-based */ static unsigned extras_pending; /* extra balls awarded, not yet played */ static unsigned char in_game; @@ -57,22 +40,23 @@ static void score_str(char *out, unsigned cap, unsigned player) static void scores_line(const char *tag) { - char buf[128]; - char one[32]; + char tbuf[40], buf[128], one[32]; unsigned p, n = 0; + gl_rfc3339(tbuf, sizeof tbuf); buf[0] = 0; for (p = 1; p <= 4; p++) { score_str(one, sizeof one, p); n += (unsigned)pm_snprintf(buf + n, sizeof buf - n, "%sP%u=%s", n ? " " : "", p, one); } - pm_log("[GAMELOG] +%lums %s %s", ms() - t0, tag, buf); + pm_log("[GAMELOG] %s %s %s", tbuf, tag, buf); } static void on_init(void) { - t0 = ms(); + char tbuf[40]; + ball = 0; in_game = 0; extras_pending = 0; @@ -84,8 +68,9 @@ static void on_init(void) ev_bonus_end = pm_event("bonus_end"); ev_tilt_warn = pm_event("tilt_warning"); ev_tilt = pm_event("tilt"); - pm_log("[GAMELOG] up: game %s %s, %d named shots; event ids %d/%d/%d/%d/%d/%d; extra_ball_award=%u", - pm_game(), pm_version(), pm_shot_count(), + gl_rfc3339(tbuf, sizeof tbuf); + pm_log("[GAMELOG] %s up: game %s %s, %d named shots; event ids %d/%d/%d/%d/%d/%d; extra_ball_award=%u", + tbuf, pm_game(), pm_version(), pm_shot_count(), ev_game_start, ev_ball_start, ev_ball_end, ev_bonus_end, ev_tilt_warn, ev_tilt, extra_ball_award); } @@ -93,37 +78,38 @@ static void on_init(void) static void on_event(unsigned id) { const char *name = pm_event_name(id); - char one[32]; + char tbuf[40], one[32]; + gl_rfc3339(tbuf, sizeof tbuf); if (id == (unsigned)ev_game_start) { ball = 0; extras_pending = 0; in_game = 1; - pm_log("[GAMELOG] +%lums EV %s - GAME START", ms() - t0, + pm_log("[GAMELOG] %s EV %s - GAME START", tbuf, name ? name : "game_start"); } else if (id == (unsigned)ev_ball_start) { score_str(one, sizeof one, pm_player()); if (extras_pending) { extras_pending--; - pm_log("[GAMELOG] +%lums EV %s player=%u ball=%u (EXTRA BALL) score=%s", ms() - t0, + pm_log("[GAMELOG] %s EV %s player=%u ball=%u (EXTRA BALL) score=%s", tbuf, name ? name : "ball_start", pm_player(), ball, one); } else { ball++; - pm_log("[GAMELOG] +%lums EV %s player=%u ball=%u score=%s", ms() - t0, + pm_log("[GAMELOG] %s EV %s player=%u ball=%u score=%s", tbuf, name ? name : "ball_start", pm_player(), ball, one); } } else if (id == (unsigned)ev_ball_end) { score_str(one, sizeof one, pm_player()); - pm_log("[GAMELOG] +%lums EV %s player=%u ball=%u score=%s", ms() - t0, + pm_log("[GAMELOG] %s EV %s player=%u ball=%u score=%s", tbuf, name ? name : "ball_end", pm_player(), ball, one); } else if (id == (unsigned)ev_bonus_end) { - pm_log("[GAMELOG] +%lums EV %s", ms() - t0, name ? name : "bonus_end"); + pm_log("[GAMELOG] %s EV %s", tbuf, name ? name : "bonus_end"); scores_line("SCORES"); } else if (id == (unsigned)ev_tilt_warn) { - pm_log("[GAMELOG] +%lums EV %s player=%u", ms() - t0, + pm_log("[GAMELOG] %s EV %s player=%u", tbuf, name ? name : "tilt_warning", pm_player()); } else if (id == (unsigned)ev_tilt) { - pm_log("[GAMELOG] +%lums EV %s player=%u ball=%u", ms() - t0, + pm_log("[GAMELOG] %s EV %s player=%u ball=%u", tbuf, name ? name : "tilt", pm_player(), ball); } } @@ -131,17 +117,18 @@ static void on_event(unsigned id) static void on_shot(unsigned long long shot) { const char *name; - char one[32]; + char tbuf[40], one[32]; if (!in_game) /* attract-mode dispatches are noise */ return; + gl_rfc3339(tbuf, sizeof tbuf); name = pm_shot_name(shot); score_str(one, sizeof one, pm_player()); if (name) - pm_log("[GAMELOG] +%lums SHOT %s player=%u ball=%u score=%s", ms() - t0, + pm_log("[GAMELOG] %s SHOT %s player=%u ball=%u score=%s", tbuf, name, pm_player(), ball, one); else - pm_log("[GAMELOG] +%lums SHOT 0x%llx player=%u ball=%u score=%s", ms() - t0, + pm_log("[GAMELOG] %s SHOT 0x%llx player=%u ball=%u score=%s", tbuf, shot, pm_player(), ball, one); } @@ -149,15 +136,16 @@ static void on_tick(void) { /* award screens: the runtime hook counts them; log the new ones */ while (award_seq_seen != gl_award_seq()) { + char tbuf[40], one[32]; award_seq_seen++; + gl_rfc3339(tbuf, sizeof tbuf); if (gl_last_award_id() == extra_ball_award) { extras_pending++; - pm_log("[GAMELOG] +%lums AWARD EXTRA BALL (id=%u) player=%u", ms() - t0, + pm_log("[GAMELOG] %s AWARD EXTRA BALL (id=%u) player=%u", tbuf, gl_last_award_id(), pm_player()); } else { - char one[32]; score_str(one, sizeof one, pm_player()); - pm_log("[GAMELOG] +%lums AWARD id=%u player=%u score=%s", ms() - t0, + pm_log("[GAMELOG] %s AWARD id=%u player=%u score=%s", tbuf, gl_last_award_id(), pm_player(), one); } } diff --git a/pad_mode_runtime.c b/pad_mode_runtime.c index 8d273ee..7c2dd64 100644 --- a/pad_mode_runtime.c +++ b/pad_mode_runtime.c @@ -7936,20 +7936,50 @@ static unsigned long gl_award_n; unsigned long gl_award_seq(void) { return gl_award_n; } unsigned gl_last_award_id(void) { return gl_award_v; } +/* the wall clock as RFC 3339 UTC with milliseconds, e.g. 2026-10-12T20:45:12.123Z, into buf. + * The date is the civil-from-days algorithm (Hinnant); no libc time calls beyond clock_gettime. */ +struct gl_ts { long sec, nsec; }; +extern int clock_gettime(int, void *); +#define GL_CLOCK_REALTIME 0 + +void gl_rfc3339(char *buf, unsigned cap) +{ + struct gl_ts t; + long days, rem, era, doe, yoe, doy, mp, y, m, d; + if (clock_gettime(GL_CLOCK_REALTIME, &t) != 0) { + pm_snprintf(buf, cap, "0000-00-00T00:00:00.000Z"); + return; + } + days = t.sec / 86400; + rem = t.sec % 86400; + days += 719468; /* days since 1970-01-01 -> days since 0000-03-01 */ + era = (days >= 0 ? days : days - 146096) / 146097; + doe = days - era * 146097; /* [0, 146096] */ + yoe = (doe - doe / 1460 + doe / 36524 - doe / 146096) / 365; /* [0, 399] */ + doy = doe - (365 * yoe + yoe / 4 - yoe / 100); /* [0, 365] */ + mp = (5 * doy + 2) / 153; /* [0, 11] */ + d = doy - (153 * mp + 2) / 5 + 1; + m = mp + (mp < 10 ? 3 : -9); + y = yoe + era * 400 + (m <= 2 ? 1 : 0); + pm_snprintf(buf, cap, "%04ld-%02ld-%02ldT%02ld:%02ld:%02ld.%03ldZ", + y, m, d, rem / 3600, (rem / 60) % 60, rem % 60, t.nsec / 1000000); +} + static void gamelog_mode_log(const char *kind, unsigned id, unsigned player, unsigned long long score, unsigned long dur) { - char key[24]; + char key[24], tbuf[40]; const char *nm; pm_snprintf(key, sizeof key, "block_name_%u", id); nm = pm_port_text(key); + gl_rfc3339(tbuf, sizeof tbuf); if (dur) - say("gamelog: MODE %s %u (%s) player=%u score=%llu mode_score=%llu dur=%lums", - kind, id, nm ? nm : "?", player, score, + say("gamelog: %s MODE %s %u (%s) player=%u score=%llu mode_score=%llu dur=%lums", + tbuf, kind, id, nm ? nm : "?", player, score, score > gl_start_score[id] ? score - gl_start_score[id] : 0, dur); else - say("gamelog: MODE %s %u (%s) player=%u score=%llu", - kind, id, nm ? nm : "?", player, score); + say("gamelog: %s MODE %s %u (%s) player=%u score=%llu", + tbuf, kind, id, nm ? nm : "?", player, score); } static void gamelog_stock_tick(void) @@ -7985,9 +8015,12 @@ static void gamelog_stock_tick(void) /* the game's award screens (extra ball, special, replay...): logged, never refused */ static void on_award_screen(unsigned *r) { + char tbuf[40]; gl_award_v = r[0]; gl_award_n++; - say("gamelog: AWARD id=%u player=%u score=%llu", r[0], pm_player(), pm_score(pm_player())); + gl_rfc3339(tbuf, sizeof tbuf); + say("gamelog: %s AWARD id=%u player=%u score=%llu", tbuf, r[0], pm_player(), + pm_score(pm_player())); } static void gamelog_arm(void) @@ -8632,20 +8665,28 @@ static void on_switch_edge(unsigned *r) mask = edge.mode_mask ? *(const unsigned short *)(unsigned long)edge.mode_mask : 0u; hit = edge_is_hit(level, flags, pol, edge.mode_mask != 0, mask); playing = pm_in_game(); /* attract, a tilt: no player up for a mode to score */ - /* GAMELOG: every edge to /dump/switch.log (buttons included, attract included) */ + /* GAMELOG: the buttons a human presses, to /dump/switch.log (34 lockdown, 36 start, 62/63 the + * flipper buttons). The upper-flipper button switches (64/65) are wired in parallel with the + * main flipper buttons on this cabinet, so they are left out with every non-button switch. */ { + static const unsigned gl_buttons[] = { 34, 36, 62, 63 }; static const struct { unsigned id; const char *name; } gl_sw[] = { #include "switch_names.inc" }; unsigned k; - char nm[40] = "?", line[160]; - int fd, len; - for (k = 0; k < sizeof gl_sw / sizeof gl_sw[0]; k++) - if (gl_sw[k].id == id) { pm_snprintf(nm, sizeof nm, "%s", gl_sw[k].name); break; } - len = pm_snprintf(line, sizeof line, "%lu SW %u %s level=%u hit=%d game=%d\n", - pm_ms(), id, nm, level & 1u, hit, playing); - fd = open("/dump/switch.log", O_WRONLY | O_CREAT | O_APPEND, 0644); - if (fd >= 0) { write(fd, line, len); close(fd); } + char tbuf[40], nm[40] = "?", line[160]; + int fd, len, want = 0; + for (k = 0; k < sizeof gl_buttons / sizeof gl_buttons[0]; k++) + if (gl_buttons[k] == id) { want = 1; break; } + if (want) { + for (k = 0; k < sizeof gl_sw / sizeof gl_sw[0]; k++) + if (gl_sw[k].id == id) { pm_snprintf(nm, sizeof nm, "%s", gl_sw[k].name); break; } + gl_rfc3339(tbuf, sizeof tbuf); + len = pm_snprintf(line, sizeof line, "%s SW %u \"%s\" level=%u hit=%d game=%d\n", + tbuf, id, nm, level & 1u, hit, playing); + fd = open("/dump/switch.log", O_WRONLY | O_CREAT | O_APPEND, 0644); + if (fd >= 0) { write(fd, line, len); close(fd); } + } } if (edge_log_left > 0 && __sync_sub_and_fetch(&edge_log_left, 1) >= 0) say("edge: switch %u level %u (flags 0x%04x, polarity 0x%04x, mode mask 0x%04x, in game %d)%s", id, level & 1u,