Interpreting match listener logs¶

This is system context for an AI agent analyzing listener logs without prior knowledge of the application.

First read shared_context/listener_system.md.

Goal¶

Use listener logs to determine:

whether the stream and listener remained healthy;
which questions were issued and resolved;
which source event determined each result;
whether corrective events changed pending resolution data;
whether timing and execution mode matched the run's intent;
whether an absence of activity is expected or suspicious.

Do not infer database writes from a dry-run log.

Log structure¶

A typical line is:

LEVEL: MatchListener [<shortcode>]: <message>

Some entry-point logs may include a module segment such as MatchListener.__main__. Treat both forms as the same listener.

The bracketed value is the match shortcode ({sr_id[:8]}-{internal_match_id[:8]}), not the full Sportradar match id or internal match id. Other UUIDs in the message may identify:

a question definition;
a concrete question issuance;
a source event;
an internal match id (for example on Issuing … for match <…> lines).

Always distinguish these IDs before correlating lines.

Establish run context first¶

Before interpreting question behavior, find these lines or inspect the listener environment used by the run:

Subscribing to <URL>
**** DRY_RUN mode: no DB writes ****
**** Event processing is disabled ****
Writing events to `<path>`
Writing logs to `<path>`

Determine:

Match and league from the subscription URL.
Whether the source is live Sportradar or a local simulator.
Whether LISTENER_DRY_RUN is enabled.
Whether LISTENER_SKIP_PROCESSING_EVENTS disabled all processing.
Whether LISTENER_TIMING_SOURCE is realtime or ts.
Whether LISTENER_WRITE_LOGS_TO_FILE is enabled (console plus filesystem_container_data_dir/listener/{league}/{sr_id[:8]}-{match_id[:8]}.{listener_record_id[:8]}.log, or bare {shortcode}.log if no lifecycle row id).
Simulator playback settings, especially compressed/no-delay playback.

If the log came from a simulator with compressed playback, ts timing is usually intended. A realtime run against playback_speed=0 measures actual rapid execution, not simulated game time.

Stream and process health¶

Normal event line¶

Event received: <event type> event_id=<eid>

This means a non-heartbeat event was accepted for ordinary processing. When Sportradar provides payload.event.description, that text is appended after the type/id. It does not mean that the event issued or resolved a question.

At DEBUG level, the listener may log the complete normalized event instead of this compact line. After processing finishes, DEBUG also emits:

Event processed: <event type> event_id=<eid> (<N>ms)

The trailing (<N>ms) is real-time spent in question processing for that event.

Heartbeats¶

Consecutive heartbeats = <count>

Heartbeats show that the connection is alive but no match event reset the consecutive counter. The listener normally logs only selected counts, not every heartbeat.

Large counts are not automatically failures. Interpret them with:

the configured maximum consecutive heartbeat count;
whether Match.status is delayed (status checks reset the consecutive counter — see below);
whether the match has naturally gone quiet or ended;
whether a subsequent match event resets the count.

Match status checks¶

During idle heartbeats (every listener_match_status_check_heartbeats, default 50), the listener reloads the match and logs:

Match status check: status=<status> previous=<status|None> is_test=<bool>

Use these lines to see when Beat/schedule refresh moved the game to delayed, back to inprogress, or to a terminal status. Live non-test transitions may also log synthetic archive markers:

Synthetic game_delay_start recorded (status=delayed)
Synthetic game_delay_end recorded (status=inprogress)
Synthetic game_postponed recorded (status=postponed)

While status=delayed, each check resets the consecutive-heartbeat counter so rain-delay silence does not reach listener_max_consecutive_heartbeats (keep the idle max above the check interval). Before a max-heartbeat exit the listener refreshes status once more; if that check resets the counter, it does not shut down.

Normal shutdown¶

Match is no longer in progress (status=<status>); shutting down
Max heartbeats reached (<n>) - shutting down
Exiting game listener - end of program

The first is expected when database match state reaches a terminal status. A maximum-heartbeat shutdown may be expected after a stream goes quiet, but can also indicate stale match status or a feed issue.

Failure lines¶

Treat these as operational failures unless surrounding context proves otherwise:

Connection/Timeout error: ...
HTTP error: ...
JSON decode error: ...
Unexpected error: ...
Failed to parse event: ...
Failed to write event to filesystem: ...
Error in question processing: ...
Error processing question logic: ...
Error finalizing pending resolution <issuance UUID>: ...
Error finalizing pending issuance <definition UUID>: ...

Failed to write event to filesystem does not necessarily mean question processing stopped. Question-processing errors can leave questions missing or unresolved and require closer inspection.

Warnings such as invalid/missing Sportradar match ids indicate that question processing for that event did not proceed.

Corrective events¶

Detection¶

Skipping corrective event: <event type> event_id=<eid>

Processing corrective event: <event type> event_id=<eid>

The listener already observed that eid during the current process. That does not by itself prove that the payload changed.

Skipping — no in-memory pending resolution or pending issuance, and no open issuance / league definition that allows starting or retracting from a corrective (resolution_start_on_corrective / issuance_start_on_corrective / issuance_retract_on_corrective). Question logic does not run.
Processing — a pending exists, or a start-on-corrective flag allows opening resolve and/or issue from the corrective.

Pending-resolution update¶

Updated pending resolution for issuance <issuance UUID> from corrective event event_id=<eid>

This is the evidence that a corrective replaced the candidate event held for that issuance (refine path).

Pending-issuance update¶

Updated pending issuance for definition <definition UUID> group=<group>
('<name>') from corrective event event_id=<eid>; fields={<latest candidate>}

Same refine path for a deferred create: the corrective replaced the held issue candidate before Issuing / Created issuance. Compare fields to the earlier Deferring issuance line.

Starting resolve from a corrective¶

Starting resolution from corrective for issuance <issuance UUID> (resolution_start_on_corrective)
Deferring resolution for issuance <issuance UUID> ...

(or immediate Resolving / Resolved when the correction window is 0)

The definition had Start resolution on corrective on. The first delivery of this event never opened a pending; the feed correction newly matched resolve rules and opened defer/resolve. Correlate with later Resolving / Resolved for that issuance UUID.

Starting issue from a corrective¶

Starting issuance from corrective for definition <definition UUID> group=<group>
('<name>') (issuance_start_on_corrective)
Deferring issuance for definition <definition UUID> ...

(or immediate Issuing / Created issuance when the issuance correction window is 0)

The definition had Start issuance on corrective on. Correlate with later Issuing / Created issuance for that definition (then the new issuance UUID).

Correlate refine vs start:

The issuance UUID (resolve) or definition UUID (issue) with an earlier deferral (refine) or with this start line.
The event ID with the original candidate and corrective.
The later Resolving / Issuing line for the final candidate fields.

Multiple update lines for one pending are valid when the source reissues the same ID multiple times.

If corrective skip lines exist but no update/start lines exist, typical explanations are:

no question was pending for that event ID and resolution_start_on_corrective / issuance_start_on_corrective is off (or the corrective still does not match resolve/issue conditions);
the relevant question has correction window 0 and was never deferred;
the definition JSON was edited but not refreshed into the database;
the corrective arrived after the issuance resolved (resolve path) or after create finalized (issue path);
the listener restarted and lost its in-memory pending/seen-ID state.

Question issuance¶

Typical lines when a weighted pick runs and issues:

Issuance selection pool (N): 'At Bat Outcome' (a1b2c3d4)=1.0, 'Pitch Result' (e5f6g7h8)=0.5, ...

Issuance probability gate for '<definition name>' (<definition UUID>):
decision=<issue|skip|force_issue> probability=<0-100>
max_false_streak=<N> false_count_before=<N> false_count_after=<N>

Issuance weight decay for '<definition name>' (<definition UUID>):
count_before=N count_after=N+1 base_weight=W decay=D
effective_before=X effective_after=Y

Issuing '<definition name>' (<definition UUID>) group=<issuance_group>
for match <internal match id>; text='<rendered question>'; fields={<compact JSON>}

Created issuance <issuance UUID> group=<issuance_group> for '<definition name>';
text='<rendered question>'

In dry-run, these lines begin with DRY_RUN.

Interpretation:

Issuance selection pool lists every candidate that reached weighted selection (after triggers, group gates, and pivotal selection priority), with effective weights (post dynamic-weighting decay). Each entry is name + first 8 hex chars of the definition UUID. Empty pools are silent (no selection attempted).
Issuance probability gate is the final post-selection roll on the selected definition only (not once per candidate in the pool). decision=skip means the definition was selected but did not issue; the consecutive false count is in false_count_after. force_issue means the pity timer fired. Unlike most eligibility failures, skips are logged at INFO. A skip does not apply weight decay and does not re-pick another eligible definition.
Issuance weight decay appears only when the definition has dynamic weighting on and the probability gate passed. Counts are per listener session (in memory; reset on restart).
Issuing shows the selected definition, concurrency group, rendered user text, and trigger/state fields from the source event (only after a passing probability gate).
group= is the group's immutable slug (issuance snapshot), not a free string. Same group cannot have two opens; different groups can be open concurrently. Still at most one new issue per event. When a question is missing or delayed, load the league question_groups row (is_active, live issuance_min_interval, issuance_min_interval_after_groups, max_per_match, period_distribution).
Created issuance supplies the issuance UUID used for all later correlation.
fields.ts is the source stream timestamp, regardless of timing mode.
fields is a compact diagnostic snapshot, not the full event.

The fields object contains source paths referenced by issuance trigger/state expressions. Missing paths may appear as null; inspect the full recorded event before concluding the feed omitted data.

An Issuing line without Created issuance suggests an exception or interruption during creation/persistence.

Deferred issuance and corrective window¶

When issuance_correction_window_seconds > 0, create is held until the same eid settles (mirror of deferred resolution). Expected sequence:

Deferring issuance for definition <definition UUID> group=<issuance_group>
('<definition name>') text='<preview question>' on event type=<type> id=<eid>;
correction_window_seconds=<N>; fields={<initial candidate>}

Skipping corrective event: <type> event_id=<eid>
Updated pending issuance for definition <definition UUID> group=<group>
('<name>') from corrective event event_id=<eid>; fields={<latest candidate>}

Issuing '<definition name>' (<definition UUID>) group=<issuance_group> ...
fields={<final candidate>}

Created issuance <issuance UUID> group=<issuance_group> for '<definition name>';
text='<rendered question>'

Compare fields on Deferring issuance / Updated pending issuance / Issuing. Changed values prove the corrective affected what would be created. text= on defer is a best-effort preview from the candidate event (state extract + template); the authoritative rendered text is on Issuing / Created issuance after finalize.

Timing semantics¶

Same as deferred resolution: realtime waits N wall-clock seconds after the latest same-ID candidate; ts advances when stream ts moves by N. Matching correctives reset the window.

Dropped candidate¶

Dropped pending issuance for definition <definition UUID> group=<group>
('<name>'): <reason>

Typical reasons: triggers no longer match after a corrective, eligibility failed at finalize, or a newer pending superseded the hold. This is not the same as issuing then resolving “no” — no QuestionIssuance row was created.

Immediate resolution¶

For a zero correction window:

Resolving issuance <issuance UUID> group=<issuance_group> ('<definition name>')
text='<question>' on event type=<type> id=<eid>; fields={<compact JSON>}

Resolved issuance <issuance UUID> group=<issuance_group> ('<definition name>');
text='<question>'; correct=[<answer identifiers>];
resolution persisted

answer evaluation enqueued for issuance <issuance UUID>: <N> answer(s)

When no QuestionAnswer rows were committed yet at enqueue time:

answer evaluation skipped for issuance <issuance UUID>: no answers committed yet

Dry-run ends with:

answer evaluation skipped

Interpretation:

Resolving identifies the exact event payload used to calculate correctness.
fields.store_state is state captured when the question was issued.
Other fields values come from the resolution event.
correct=[...] lists answer-choice identifiers marked correct.
correct=[] is suspicious for a resolved multiple-choice question; inspect the answer conditions and event fields.
resolution persisted means the issuance row was committed with choice correctness. The following answer evaluation enqueued / skipped line is authoritative for whether Celery scoring tasks were dispatched (and for how many answers). An earlier design logged “enqueued” even when N was 0.

Deferred resolution and corrective window¶

Expected sequence:

Deferring resolution for issuance <issuance UUID> group=<issuance_group>
('<definition name>') ...
correction_window_seconds=<N>; fields={<initial candidate>}

Skipping corrective event: <type> event_id=<eid>
Updated pending resolution for issuance <issuance UUID>
from corrective event event_id=<eid>

Resolving issuance <issuance UUID> group=<issuance_group> ... id=<eid>;
fields={<latest candidate and store_state>}

Resolved issuance <issuance UUID> group=<issuance_group> ... correct=[...]

Compare the fields JSON on Deferring and Resolving. Changed values prove that the corrective payload affected the result. Do not compare only the final answer identifier.

Example, independent of sport:

Deferring ... fields={"event.result": "not_successful", ...}
Updated pending resolution ... event_id=abc
Resolving ... fields={"event.result": "successful", ...}
Resolved ... correct=["yes"]

Play under review (resolution hold)¶

The listener holds in-game resolve (not issuance) while a registered detector marks the play under review. Expected lines:

Holding pending resolution for issuance <issuance UUID> group=<group>
('<definition name>') event_id=<eid>: play under review; correction window paused

Still holding pending resolution for issuance <issuance UUID> event_id=<eid>:
play still under review

Skipping resolve start for issuance <issuance UUID> event_id=<eid>: play under review

Resuming correction window for pending resolution for issuance <issuance UUID>
event_id=<eid> after play review; correction_window_seconds=<N>

Resuming correction window for pending resolution for issuance <issuance UUID>
event_id=<eid> as call on the field; review hold expired; correction_window_seconds=<N>

Skipping retract of issuance <issuance UUID> event_id=<eid>: play under review

Interpretation:

Holding — first time this pending entered review hold. The correction window is paused (including a window of 0).
Still holding — a later same-event-id under-review update. Ticks that only skip expiry do not log this.
Skipping resolve start — a complementary event (different event id, same sport unit still in review) did not open resolve.
Resuming … after play review — the feed marked the play final; the configured window now runs from this instant.
Resuming … as call on the field — the review-hold cap elapsed while the play was still in the ledger. Finalize uses the last non-review payload.
Skipping retract — issuance_retract_on_corrective did not withdraw the open question because the corrective is still under review. Retract runs as usual after review ends.

Timing semantics¶

In realtime mode:

resolution should occur approximately N real seconds after the most recent same-ID candidate/update;
it does not require another stream event;
each matching corrective resets the timer.

In ts mode:

resolution occurs when a later processed event advances stream ts by N;
compressed replay can finish windows without waiting N real seconds;
a matching corrective updates the candidate timestamp and restarts the event-time window.

Dropped candidate¶

Dropped pending resolution for issuance <issuance UUID>:
candidate no longer resolvable after correction window

This is not the same as resolving “no.” The corrective invalidated the candidate's resolution condition, so the issuance remains open for a future resolution event.

What absence of logs means¶

Events but no questions¶

Possible causes:

no active definition trigger matched;
every matching definition's issuance_group already has an unresolved issuance (other groups can still issue);
maximum question count was reached (match-wide);
minimum interval since the last resolution in that group has not elapsed (max(match floor, live group interval, last issuance snapshot));
the group's period_distribution or max_per_match is exhausted (even = 1 per registered half when max_per_match is unset, else that integer even-split across registered keys; omitted explicit keys = uncapped; 0 = never in that period). Check the group map before the match period map when asking “why no second at-bat this half?”;
the group is inactive;
the current event's match period distribution cap was reached (period caps are independent of max count; periods / innings missing from the map skip this gate, so remaining questions can still issue up to max — see Period distribution vs max count);
every matching definition had issuance_weight of 0;
the selected definition’s issuance_probability gate rolled false (look for Issuance probability gate with decision=skip);
processing was disabled;
match lookup failed.

The listener does not log every negative eligibility/trigger decision at INFO, so absence alone does not identify which gate failed — except the probability gate, which always logs its decision.

When at least one definition trigger matched and nothing published, the listener also writes a compact blocked attempt row (question_issuance_denials). Operators browse those in Issuance Explorer (Blocked / All). Silent “no trigger matched” events are not stored. The listener logs one compact INFO line (DRY_RUN prefix in dry-run):

Blocked attempt group=halfinning step=group: Waited 97s of 300s since last resolve in group halfinning.

failed_step stays the parent gate (group, pivotal, match_max, …). The reason names the sub-check and numbers. Absence of this line still does not mean every eligibility miss was evaluated — only trigger-then-block passes are logged.

Correctives but no deferrals¶

Check whether any selected definitions have a nonzero resolution_correction_window_seconds or issuance_correction_window_seconds in the database.

Deferral without resolution / create¶

Check:

whether the process exited before a realtime timer fired;
whether ts mode received a sufficiently later timestamp;
whether repeated correctives kept resetting the window;
whether the play is still under review (Holding / Still holding / Skipping resolve start) so the window has not started;
whether an error occurred in timer finalization;
whether the candidate was dropped as no longer resolvable (resolve) or no longer eligible to issue (create).

Recommended analysis workflow¶

Search for ERROR, CRITICAL, WARNING, Traceback, and Exception.
Establish run mode, timing source, subscription URL, and simulator speed.
Count Created issuance and Resolved issuance.
Group question lines by issuance UUID (optionally also by group= when multiple concurrency lanes are open; use definition UUID for pre-create deferrals).
For each group, verify this lifecycle:
either immediate Issuing, or Deferring issuance then zero or more Updated pending issuance then Issuing
Created issuance
either immediate Resolving, or Deferring resolution then zero or more Updated pending resolution
Resolved, or an explained Dropped
Compare defer and finalize fields for corrected candidates (issue and resolve).
Count corrective skips separately from pending updates.
Inspect the final section for unresolved pendings or abrupt shutdown.
State conclusions with line evidence and separate confirmed facts from hypotheses.

Useful text searches:

DRY_RUN
Created issuance
group=
Deferring issuance
Updated pending issuance
Dropped pending issuance
Retracting issuance
Deferring resolution
Holding pending resolution
Still holding pending resolution
Skipping resolve start
Resuming correction window
Skipping retract of issuance
Updated pending resolution
Dropped pending resolution
Resolving issuance
Resolved issuance
Skipping corrective event
Blocked attempt
ERROR
WARNING

Reporting template¶

Use this compact structure when reporting findings:

Run context
- source:
- match:
- production/dry-run:
- timing source:

Health
- errors/warnings:
- shutdown reason:

Question lifecycle
- issued:
- resolved:
- deferred:
- dropped/unresolved:

Correctives
- duplicate/corrective skips:
- pending candidates updated:
- confirmed outcome changes:

Findings
- confirmed:
- suspicious:
- unknown / needs configuration or payload inspection:

Avoid sport-specific conclusions unless the corresponding question definition and source event fields were inspected.