mattlqx/stern-event-agent
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

feat: RFC 3339 timestamps, quoted switch names, buttons-only switch log

Browse Source 
All GAMELOG lines (EV/SHOT/SCORES/AWARD in mode.log, the runtime's MODE
START/END and AWARD lines) and every switch.log line now carry the wall
clock as RFC 3339 UTC with millisecond precision; the +Nms stamps relative
to runtime load are gone (dur= on MODE END stays: it is a duration). The
timestamp comes from a new gl_rfc3339() in the runtime: clock_gettime
(CLOCK_REALTIME) plus the civil-from-days algorithm, no libc time calls.

switch.log now logs only the human-activated buttons (34 lockdown, 36
start, 62/63 flippers) with quoted names. The upper-flipper button
switches (64/65) fire in parallel with the main flipper buttons on this
cabinet and are left out with every non-button switch.

Deployed and verified on the machine: the boot banner reads
2026-10-13T01:39:39.640Z against the machine's own UTC clock.

Co-Authored-By: Claude Code <noreply@anthropic.com>
This commit is contained in:
mattlqx
2026-10-12 21:42:42 -04:00
co-authored by Claude Code
parent 18ab285e22
commit e8f812ba4a
3 changed files with 111 additions and 77 deletions
Download Patch File Download Diff File Expand all files Collapse all files
README.md
+27 -22
View File
@@ -1,8 +1,9 @@
# stern-event-agent # stern-event-agent
A passive gameplay-event logger for Stern Spike 2 pinball, developed against 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 **King Kong LE 0.97**. It records the game's own events with RFC 3339 UTC
timestamps — the game is not modified, nothing scores, nothing blocks. 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 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 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) ### `/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: reboots:
``` ```
[pad] port ...: king_kong_le 0.97, 121 sites, 55 shots <- runtime armed (all hook words verified) [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] 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] +2408751ms EV game_start - GAME START [GAMELOG] 2026-10-12T20:45:12.123Z EV game_start - GAME START
[GAMELOG] +2408751ms EV ball_start player=1 ball=1 score=0 [GAMELOG] 2026-10-12T20:45:12.123Z 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] 2026-10-12T20:45:12.123Z 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] 2026-10-12T20:45:12.123Z EV ball_end player=1 ball=1 score=91,153,090
[GAMELOG] +2644003ms EV bonus_end [GAMELOG] 2026-10-12T20:45:12.123Z EV bonus_end
[GAMELOG] +2644003ms SCORES P1=95,421,190 P2=0 P3=0 P4=0 [GAMELOG] 2026-10-12T20:45:12.123Z SCORES P1=95,421,190 P2=0 P3=0 P4=0
[GAMELOG] +...ms EV tilt_warning player=1 [GAMELOG] 2026-10-12T20:45:12.123Z EV tilt_warning player=1
[GAMELOG] +...ms EV tilt player=1 ball=2 [GAMELOG] 2026-10-12T20:45:12.123Z EV tilt player=1 ball=2
[pad] gamelog: MODE START 5 (Island Scene Escape the Swamp) player=1 score=... [pad] gamelog: 2026-10-12T20:45:12.123Z 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 [pad] gamelog: 2026-10-12T20:45:12.123Z 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] 2026-10-12T20:45:12.123Z AWARD EXTRA BALL (id=13) player=1 <- next ball logs as "ball N (EXTRA BALL)"
[GAMELOG] +...ms AWARD id=<n> player=1 score=... <- every award screen [GAMELOG] 2026-10-12T20:45:12.123Z AWARD id=<n> player=1 score=... <- every award screen
``` ```
Bus event ids (King Kong 0.97): `game_start`=0x4d, `ball_start`=0x25, 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 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. 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 The runtime's switch-edge handler writes every edge of the human-activated
`/dump/switch.log` — buttons included, attract included: 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:
``` ```
<ms> SW <id> <NAME> level=<0|1> hit=<0|1> game=<0|1> 2026-10-12T20:45:12.123Z SW <id> "<NAME>" 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 `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 "counts as a hit" verdict, `game` whether a player is up. The logged ids are
`switch_names.inc`; an id not in the table logs `?`. the `gl_buttons[]` list in the runtime's switch-edge handler; names come from
`switch_names.inc`.
## Build ## Build
gamelog.c
+28 -40
View File
@@ -1,6 +1,6 @@
/* GAMELOG - a passive gameplay-event logger for Stern Spike 2. /* 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 <event name> - the game's bus events (game start, ball start/end, * EV <event name> - the game's bus events (game start, ball start/end,
* bonus end, tilt warning, tilt), player, ball, score * bonus end, tilt warning, tilt), player, ball, score
* SHOT <shot name> - every shot the game dispatches while a ball is up * SHOT <shot name> - every shot the game dispatches while a ball is up
@@ -19,28 +19,11 @@
#include "pad_mode.h" #include "pad_mode.h"
/* -nostdlib: the few libc symbols resolve from the game's own libc at load, /* the runtime patch exposes the award screens it sees and the wall clock */
* 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 */
extern unsigned long gl_award_seq(void); extern unsigned long gl_award_seq(void);
extern unsigned gl_last_award_id(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 ball; /* ball in play, 1-based */
static unsigned extras_pending; /* extra balls awarded, not yet played */ static unsigned extras_pending; /* extra balls awarded, not yet played */
static unsigned char in_game; 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) static void scores_line(const char *tag)
{ {
char buf[128]; char tbuf[40], buf[128], one[32];
char one[32];
unsigned p, n = 0; unsigned p, n = 0;
gl_rfc3339(tbuf, sizeof tbuf);
buf[0] = 0; buf[0] = 0;
for (p = 1; p <= 4; p++) { for (p = 1; p <= 4; p++) {
score_str(one, sizeof one, p); score_str(one, sizeof one, p);
n += (unsigned)pm_snprintf(buf + n, sizeof buf - n, "%sP%u=%s", n += (unsigned)pm_snprintf(buf + n, sizeof buf - n, "%sP%u=%s",
n ? " " : "", p, one); 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) static void on_init(void)
{ {
t0 = ms(); char tbuf[40];
ball = 0; ball = 0;
in_game = 0; in_game = 0;
extras_pending = 0; extras_pending = 0;
@@ -84,8 +68,9 @@ static void on_init(void)
ev_bonus_end = pm_event("bonus_end"); ev_bonus_end = pm_event("bonus_end");
ev_tilt_warn = pm_event("tilt_warning"); ev_tilt_warn = pm_event("tilt_warning");
ev_tilt = pm_event("tilt"); 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", gl_rfc3339(tbuf, sizeof tbuf);
pm_game(), pm_version(), pm_shot_count(), 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_game_start, ev_ball_start, ev_ball_end,
ev_bonus_end, ev_tilt_warn, ev_tilt, extra_ball_award); 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) static void on_event(unsigned id)
{ {
const char *name = pm_event_name(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) { if (id == (unsigned)ev_game_start) {
ball = 0; ball = 0;
extras_pending = 0; extras_pending = 0;
in_game = 1; 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"); name ? name : "game_start");
} else if (id == (unsigned)ev_ball_start) { } else if (id == (unsigned)ev_ball_start) {
score_str(one, sizeof one, pm_player()); score_str(one, sizeof one, pm_player());
if (extras_pending) { if (extras_pending) {
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); name ? name : "ball_start", pm_player(), ball, one);
} else { } else {
ball++; 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); name ? name : "ball_start", pm_player(), ball, one);
} }
} else if (id == (unsigned)ev_ball_end) { } else if (id == (unsigned)ev_ball_end) {
score_str(one, sizeof one, pm_player()); 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); name ? name : "ball_end", pm_player(), ball, one);
} else if (id == (unsigned)ev_bonus_end) { } 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"); scores_line("SCORES");
} else if (id == (unsigned)ev_tilt_warn) { } 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()); name ? name : "tilt_warning", pm_player());
} else if (id == (unsigned)ev_tilt) { } 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); name ? name : "tilt", pm_player(), ball);
} }
} }
@@ -131,17 +117,18 @@ static void on_event(unsigned id)
static void on_shot(unsigned long long shot) static void on_shot(unsigned long long shot)
{ {
const char *name; const char *name;
char one[32]; char tbuf[40], one[32];
if (!in_game) /* attract-mode dispatches are noise */ if (!in_game) /* attract-mode dispatches are noise */
return; return;
gl_rfc3339(tbuf, sizeof tbuf);
name = pm_shot_name(shot); name = pm_shot_name(shot);
score_str(one, sizeof one, pm_player()); score_str(one, sizeof one, pm_player());
if (name) 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); name, pm_player(), ball, one);
else 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); 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 */ /* award screens: the runtime hook counts them; log the new ones */
while (award_seq_seen != gl_award_seq()) { while (award_seq_seen != gl_award_seq()) {
char tbuf[40], one[32];
award_seq_seen++; award_seq_seen++;
gl_rfc3339(tbuf, sizeof tbuf);
if (gl_last_award_id() == extra_ball_award) { if (gl_last_award_id() == extra_ball_award) {
extras_pending++; 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()); gl_last_award_id(), pm_player());
} else { } else {
char one[32];
score_str(one, sizeof one, pm_player()); 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); gl_last_award_id(), pm_player(), one);
} }
} }
pad_mode_runtime.c
+56 -15
View File
@@ -7936,20 +7936,50 @@ static unsigned long gl_award_n;
unsigned long gl_award_seq(void) { return gl_award_n; } unsigned long gl_award_seq(void) { return gl_award_n; }
unsigned gl_last_award_id(void) { return gl_award_v; } 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, static void gamelog_mode_log(const char *kind, unsigned id, unsigned player,
unsigned long long score, unsigned long dur) unsigned long long score, unsigned long dur)
{ {
char key[24]; char key[24], tbuf[40];
const char *nm; const char *nm;
pm_snprintf(key, sizeof key, "block_name_%u", id); pm_snprintf(key, sizeof key, "block_name_%u", id);
nm = pm_port_text(key); nm = pm_port_text(key);
gl_rfc3339(tbuf, sizeof tbuf);
if (dur) if (dur)
say("gamelog: MODE %s %u (%s) player=%u score=%llu mode_score=%llu dur=%lums", say("gamelog: %s MODE %s %u (%s) player=%u score=%llu mode_score=%llu dur=%lums",
kind, id, nm ? nm : "?", player, score, tbuf, kind, id, nm ? nm : "?", player, score,
score > gl_start_score[id] ? score - gl_start_score[id] : 0, dur); score > gl_start_score[id] ? score - gl_start_score[id] : 0, dur);
else else
say("gamelog: MODE %s %u (%s) player=%u score=%llu", say("gamelog: %s MODE %s %u (%s) player=%u score=%llu",
kind, id, nm ? nm : "?", player, score); tbuf, kind, id, nm ? nm : "?", player, score);
} }
static void gamelog_stock_tick(void) 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 */ /* the game's award screens (extra ball, special, replay...): logged, never refused */
static void on_award_screen(unsigned *r) static void on_award_screen(unsigned *r)
{ {
char tbuf[40];
gl_award_v = r[0]; gl_award_v = r[0];
gl_award_n++; 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) 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; 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); 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 */ 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[] = { static const struct { unsigned id; const char *name; } gl_sw[] = {
#include "switch_names.inc" #include "switch_names.inc"
}; };
unsigned k; unsigned k;
char nm[40] = "?", line[160]; char tbuf[40], nm[40] = "?", line[160];
int fd, len; int fd, len, want = 0;
for (k = 0; k < sizeof gl_sw / sizeof gl_sw[0]; k++) for (k = 0; k < sizeof gl_buttons / sizeof gl_buttons[0]; k++)
if (gl_sw[k].id == id) { pm_snprintf(nm, sizeof nm, "%s", gl_sw[k].name); break; } if (gl_buttons[k] == id) { want = 1; break; }
len = pm_snprintf(line, sizeof line, "%lu SW %u %s level=%u hit=%d game=%d\n", if (want) {
pm_ms(), id, nm, level & 1u, hit, playing); for (k = 0; k < sizeof gl_sw / sizeof gl_sw[0]; k++)
fd = open("/dump/switch.log", O_WRONLY | O_CREAT | O_APPEND, 0644); if (gl_sw[k].id == id) { pm_snprintf(nm, sizeof nm, "%s", gl_sw[k].name); break; }
if (fd >= 0) { write(fd, line, len); close(fd); } 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) 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, say("edge: switch %u level %u (flags 0x%04x, polarity 0x%04x, mode mask 0x%04x, in game %d)%s", id, level & 1u,