bot event delivery can permanently skip events: non-monotonic robotEvent scores + exclusive cursor

[an9xyz]

Summary

POST /v1/bot/events paginates the authoritative queue with an exclusive lower
bound (ZRANGEBYSCORE key (cursor +inf, modules/bot_api/events.go:251), while the
scores written into robotEvent:{robotID} come from octo-lib GenSeq — a
per-process HiLo block allocator (config/seq.go: seqStep = 1000, blocks cached
in a package-level seqMap, guarded only by a process-local mutex, and min_seq
written back with an unconditional ON DUPLICATE KEY UPDATE).

With more than one replica, several 1000-wide blocks are live simultaneously, so
event_id order and real enqueue order are decoupled. Once a consumer's cursor
advances into a higher block, every event subsequently enqueued from a lower live
block becomes permanently unreachable: the exclusive Min excludes it, and nothing
ever re-delivers below the cursor.

events.go:182-213 already records the adjacent assumption ("uniqueness is assumed
and unverified", PR #685 review P2-3), but scoped the consequence to score
collisions. Ordering inversion alone is sufficient — no collision required — and
that is what we measured in production.

Evidence (production, read-only measurement)

One bot event queue, 644 members:

• 19 adjacent ordering inversions, every one landing exactly on a 1000-block
  boundary (…X007 → …(X+1)001)
• maximum time regression 6.7 days (a higher event_id carrying a strictly older
  event than its predecessor)
• the deployment runs 3 replicas

Collisions are also already happening, not just inversions

The measured queue above has unique scores, so it demonstrates the inversion path in
isolation. A full read-only sweep of 1948 non-trivial queues found 3 with
duplicate scores:

members	distinct scores	duplicates
70565	70395	170
25136	23932	1204
16588	15526	1062

The duplicate counts clustering near multiples of seqStep is the signature of a whole
block being handed out twice. The mechanism is addOrUpdateSeq:

insert into `seq`(`key`,min_seq,step) values(?,?,?) ON DUPLICATE KEY UPDATE min_seq=VALUES(min_seq)

The written-back min_seq is computed from process-local seq.CurSeq + seqStep
and the update is unconditional, so a replica whose block is behind can move
min_seq backwards. A replica that cold-starts afterwards reads an already-issued
range and re-issues it.

Collisions add a second, worse loss path on top of the skip. ackEvent /
eventAck delete by ZRemRangeByScore(key, id, id) (events.go:160, :324), which
removes every member sharing that score — so acking one delivered event silently
destroys an event that was never delivered to anyone. events.go:182-213 predicted
exactly this and recorded it as assumed-not-happening; it is happening.

Restricted to card_action events, where acted_at is a server-side time.Now()
(modules/message/api_card_action.go:253) and therefore directly comparable:

event_id (suffix)	acted_at
…4007	T+0s
…4012	T+560s
…4013	T+590s
…5009	T−29s ← older event, ~1000 higher score
…5010	T+672s

Two blocks (…4xxx, …5xxx) were demonstrably issuing concurrently. A consumer that
polled at any point after …5009 landed holds a cursor ≥ …5009, so …4012 and
…4013 can never be delivered to it.

This is not a consumer-side misuse

The server advances the cursor by max observed event_id inside its own long-poll
hold:

for _, r := range raw {
    if r.EventID > page.cursor { page.cursor = r.EventID }   // events.go:235
}

A single hold that reads a high-block event and then receives a low-block enqueue
skips it server-side, regardless of how the bot manages its cursor.

Impact

Silent, permanent loss of bot events, including card_action. The user-visible
symptom is that clicking an interactive card does nothing — and specifically that it
works for some users on the same card while silently failing for others, depending on
which block their click landed in.

The loss is not self-healing. The D4 idempotency claim keys on
(message_id, action_id, operator_uid) with a TTL of Robot.MessageExpire
(default 7 days) and deliberately excludes inputs, so a user whose event was skipped
receives {"accepted":true,"replay":true} on every retry within that window. The D8
assumption that "a re-tap after timeout heals it" does not hold here: the retry is
absorbed by the dedupe key and the skipped event is never re-enqueued.

Proposed fix

1. Strictly monotonic score source for robotEvent — Redis INCR, or the
   transactional per-key DB sequence pattern already built in internal/msgextraseq
   for the same class of GenSeq defect on message_extra.version. This is the
   actual fix.
2. Re-delivery window below the cursor — read from cursor - margin and have
   consumers dedupe on event_id. Cheaper, but only narrows the window instead of
   closing it; acceptable only as an interim mitigation.

Either way, the exclusive-cursor contract in events.go should state that it requires
a monotonic score, and the invariant should get a test that fails under concurrent
block allocation rather than a comment saying it is assumed.

Note that the five ZADD producer sites into robotEvent:{robotID} (enumerated in
modules/robot/api.go:224-235) must all move to the new allocator together; a partial
cutover reintroduces exactly the two-live-block condition this issue is about.

Related

Same root-cause family as the message_extra.version work tracked in #627, which
replaced GenSeq with a transactional per-channel sequence — but only for
message_extra writers (pinned_message.version is in that scope via
seqStore.ReserveTx). The robotEvent score was never covered, and activating that
cutover has no effect on this path. The ordering assumption was first written down in
PR #685.

Two further instances of the same defect are covered by neither #627 nor this
issue, and should be triaged separately:

• conversation_extra.version — GenSeq(common.SyncConversationExtraKey)
  (modules/message/api_conversation.go:195), read back with
  Where("uid=? and version>?") (db_conversation_extra.go:29)
• reminders.version — GenSeq(common.RemindersKey)
  (modules/message/api_reminders.go:172), read back with reminders.version>?
  (db_reminders.go:93-102)

Both are exclusive-cursor delta sync over a GenSeq-allocated version, and both use a
single global seq key (no uid/channel suffix), so one non-monotonic allocation is
shared by every user of that feature — a wider blast radius than the per-bot queue this
issue is about. Symptom would be silently missing reminders / conversation-extra state
rather than missing bot events.

---

Acceptance — narrowed, and what closing this requires

This section narrows the scope of this issue. It is not a claim that the defect
is fixed; it is a statement of which of the failures described above this issue is
accountable for, so that it has a reachable completion condition.

In scope — closing this issue requires all three

1. No new colliding scores. botevent-seq -action preflight duplicate count stops
   increasing. It will not drop to zero: existing duplicates are deliberately left
   alone, because an ack deletes every member sharing a score and there is no record
   of which of a pair was ever delivered.
2. No block-driven inversions. The allocator no longer hands out ids from
   per-process blocks, so the 19 inversions with a 6.7 day maximum regression measured
   here cannot recur.
3. Observed effect after activation. Track whether reports of "clicked the card,
   nothing happened" go away:
   • gone → the residual below does not matter in practice, and closing here is
     accurate
   • sharply down but not gone → the remainder is the reordering residual, which
     gives the follow-up a real priority instead of a guess
   • unchanged → the diagnosis in this issue is wrong and it should stay open

Out of scope — tracked separately

Allocation and publication are two operations. A producer can allocate N, stall
on marshalling or a GC pause, while another allocates N+1, publishes, and rings the
doorbell; the consumer wakes on that ZADD, advances its cursor past N, and the first
producer's publish then lands below it. Monotonic ids do not close that window — it
needs the allocation and the ZADD to be one atomic operation, or a re-delivery window
below the cursor, which is what modules/bot_api/events.go:186-199 calls the other
half of the fix.

A follow-up issue will track it. Two things make it a separate piece of work rather
than an omission here:

• It requires resolving a conflict with modules/bot_mention, which atomically
  commits an idempotency claim together with the queue write and needs the event id
  before publishing — the opposite of assigning the id inside the publish. That is
  a cross-module design decision about which atomicity boundary wins.
• Its severity is different in kind, not just in degree. Block inversion was
  systemic and self-worsening: once a cursor entered a high block, every subsequent
  event from a replica holding a lower block was invisible, and each restart opened
  another block. The reordering window loses one event and does not move the
  cursor relative to later ones, so it does not accumulate. The staged symptom
  reported here — works at first, then some users, then nothing — is the block
  behaviour, and that part goes away.

Honest caveat: the reordering window is not quantified. There are production
numbers for collisions and block inversions; there are none for this. It is also not
purely theoretical — this cluster has known pod GC / CPU throttling that can stall a
producer for hundreds of milliseconds, and the long-poll doorbell wakes consumers in
milliseconds. And it is not self-healing either: the D4 idempotency claim
(7 days, keyed without inputs) turns a user's retry into a replay.

Note on closing

Do not close this from a merge. PR #702 is behaviour-neutral on merge — the
allocator stays on the legacy path until an operator activates it. Close only after
activation plus the three checks above.

[an9xyz]

Reproduced locally — all three loss paths confirmed

Reproduced against local containers (MySQL 8.0.33 + Redis 7) using the real
config.Context.GenSeq (no reimplementation) and the real read/ack shapes from
modules/bot_api/events.go. Driver committed at tools/genseq-repro/.

go build -o /tmp/repro ./tools/genseq-repro && /tmp/repro

Two child processes are used deliberately: seqMap / seqLock are package-level in
octo-lib, so a single process cannot hold two independent block states. Each child
cold-starts and waits on a shared wall-clock barrier so both read seq.min_seq before
either writes it back — which is exactly the concurrent-cold-start condition a rolling
restart of N replicas produces.

1. Collision is deterministic, not a race you have to be unlucky to hit

seeded seq:reproRobotEvent min_seq=5000 step=1000

replica-A issued: [5001 5002 5003 5004 5005 5006 5007 5008 5009 5010 5011 5012]
replica-B issued: [5001 5002 5003 5004 5005 5006 5007 5008 5009 5010 5011 5012]

COLLISION: 12 ids issued by BOTH replicas: [5001 … 5012]
seq.min_seq after both replicas: 6000 (unconditional ON DUPLICATE KEY UPDATE)

Both replicas read min_seq=5000, both wrote back 6000, both then issued from
5001. The overlap is total, not partial: any two replicas whose cold-start reads
both precede either write-back issue the same ids. This is the mechanism behind the
production duplicate counts clustering near multiples of seqStep.

2a. Skip when a page boundary lands on a shared score

queue has 3 members; consumed with limit=1, cursor ended at 5002
delivered 2:
    {"event_id":5001,"from":"replica-A"}
    {"event_id":5002,"from":"replica-A"}
  SKIPPED FOREVER: {"event_id":5001,"from":"replica-B"}

No time inversion needed. The page ends on the first member of score 5001; the next
read's exclusive (5001 excludes the second one forever. getEvents uses
limit 20..100, so on a queue with >1000 duplicate scores this is routine, not exotic.

2b. Skip when a lower block enqueues late (the shape measured in production)

bot polls: delivered 2, cursor=6002
replica-A then enqueues [5013 5014] (later in time, lower score)
bot polls again from (6002: got 0 events
  SKIPPED FOREVER: [5013 5014] — born below the cursor, never deliverable

These events are born below the cursor. No amount of polling reaches them.

3. Ack destroys events that were never delivered

score 5001 held 2 members before ack: [{…"replica-A"} {…"replica-B"}]
after ZRemRangeByScore(5001,5001): 0 remain
ACK DESTROYED 1 event(s) while acking 1

Why this stayed latent

The first scenario in the run — read the whole collided queue in one page — loses
nothing. Loss requires either a page boundary on a shared score or a late lower-block
enqueue. That is consistent with the reported symptom being intermittent and
per-user on the same card, rather than a clean total outage that would have been
noticed immediately.

[an9xyz]

Follow-up: the collisions are still accumulating, and the fingerprint is exact

Re-measured the three affected queues about an hour after the first sweep:

queue	dup members (1st sweep)	dup members (2nd sweep)	duplicate score range
A	1204	1204	1065001 – 1072236
B	1062	1062	1016001 – 1018302
C (botfather)	170	358	1252001 – 1283228

Two things this pins down:

1. This is ongoing, not a historical artifact. Queue C more than doubled its
duplicate count within the hour. The replicas had been up ~5h at the time, so the
collisions are not confined to the cold-start window — addOrUpdateSeq is
unconditional on the extend path too (min_seq = CurSeq + seqStep from
process-local state), so two replicas extending their blocks overwrite each other the
same way they do on cold start.

2. The fingerprint matches the reproduction exactly. Every duplicated score holds
exactly 2 members — never 3 — across all 2624 duplicates, and every duplicate range
begins at …X001, i.e. min_seq + 1, a block start. That is precisely the shape the
local reproduction produced: two replicas reading the same min_seq and both issuing
from min_seq + 1. Exactly-2 rather than 3 is consistent with 3 replicas where two
happen to overlap a given block.

No member payloads were read or exported for this measurement — counts, score ranges
and per-score cardinality only.