`PositionExecution` events do not appear in indexer

[hdevalence]

Describe the bug

The DEX is supposed to emit PositionExecution events as it executes. However, these events don't appear in the indexer.

To Reproduce

On deimos-5, I created a liquidity position plpid1cr5cxr7dt8qwwjx8lmgfjnxea3fmxn7kzlw46pnk4pt5c384nw6qajqzr0 that was intentionally mispriced. Its initial reserves were 232.897367penumbra, 0test_usd. Creation transaction is here: https://cuiloa.testnet.penumbra.zone/transaction/360cf15d5fedf532f1c2dfc2d3245354780ef3ba8218eb8b46a9c10ecf0dfede

In block 64883, this was submitted against and then arb'd to have reserves 700.935094560192616373test_usd

The ProtoJSON for that LPID is {"inner":"wOmDD81ZwOdIx/7QmUzZ7FOzT9YX3V0GdqhXTET1m7Q="}.

After closing and withdrawing, I saw

penumbra=# SELECT *
FROM events
WHERE events.rowid IN (
  SELECT event_id
  FROM attributes
  WHERE value = '{"inner":"wOmDD81ZwOdIx/7QmUzZ7FOzT9YX3V0GdqhXTET1m7Q="}'
);
 rowid | block_id | tx_id |                         type
-------+----------+-------+------------------------------------------------------
 17255 |     3576 |   400 | penumbra.core.component.dex.v1.EventPositionOpen
 24719 |     5322 |   528 | penumbra.core.component.dex.v1.EventPositionWithdraw
 24695 |     5316 |   527 | penumbra.core.component.dex.v1.EventPositionClose
(3 rows)

in the events DB. showing that there were other events but not EventPositionExecution. None of those seem to appear in the DB:

penumbra=# select * from events where type = 'penumbra.core.component.dex.v1.EventPositionExecution';
 rowid | block_id | tx_id | type
-------+----------+-------+------
(0 rows)

Looking for block-scoped events, we see

penumbra=# SELECT e.*
FROM events e
JOIN blocks b ON e.block_id = b.rowid
WHERE b.height = 64883 AND e.tx_id IS NULL;
 rowid | block_id | tx_id |                       type
-------+----------+-------+--------------------------------------------------
 17220 |     3576 |       | block
 17221 |     3576 |       | penumbra.core.component.dex.v1.EventArbExecution
 17222 |     3576 |       | penumbra.core.component.sct.v1.EventAnchor
 17223 |     3576 |       | penumbra.core.component.sct.v1.EventBlockRoot
(4 rows)

so while we see the EventArbExecution we don't see any EventPositionExecution.

The events are supposed to be emitted here: https://github.com/penumbra-zone/penumbra/blob/main/crates/core/component/dex/src/component/router/fill_route.rs#L410

Expected behavior

The emitted events should appear in the event database. Where are they being dropped?

Additional context

Blocks progress on the dex explorer

[hdevalence]

It would be useful to pull up logs scoped to block 64883 from a single validator to try to find out where the events are getting dropped.

[conorsch]

Voila: https://gist.github.com/conorsch/79a799270fb8d5e27c0dc57034adc950

[conorsch]

We see several ABCI events emitted in the logs, matching the db contents above:

❯ rg 'event\{[^\}]+\}' val-logs.txt -o --no-line-number | sort | uniq -c
      2 event{kind="penumbra.core.component.dex.v1.EventArbExecution"}
      2 event{kind="penumbra.core.component.sct.v1.EventAnchor"}
      2 event{kind="penumbra.core.component.sct.v1.EventBlockRoot"}

But nowhere do we see an EventPositionClose, as we'd expect. Why not?

[conorsch]

Zooming out from specifically block 64883, I do see EventPositionClose events:

2024-03-12T04:26:10.563034Z  INFO abci:DeliverTx{txid="6724c368a0c9d8f27b31aa1590f73fe834981f43b7481b2961ca90df837e582c"}:event{kind="penumbra.core.component.dex.v1.EventPositionClose"}: penumbra_app::server::consensus: k="positionId" v="{\"inner\":\"wOmDD81ZwOdIx/7QmUzZ7FOzT9YX3V0GdqhXTET1m7Q=\"}"
2024-03-12T04:26:10.565676Z  INFO abci:DeliverTx{txid="6724c368a0c9d8f27b31aa1590f73fe834981f43b7481b2961ca90df837e582c"}:event{kind="penumbra.core.component.dex.v1.EventPositionClose"}: penumbra_app::server::consensus: k="positionId" v="{\"inner\":\"wOmDD81ZwOdIx/7QmUzZ7FOzT9YX3V0GdqhXTET1m7Q=\"}"

So we know those events are at least sometimes emitted and ingested as we'd expect, which is encouraging.

[hdevalence]

Note: we're not looking for EventPositionClose, we're looking for EventPositionExecution, the comment above links to the place in the source code where that event is emitted. We expect to not see any position close events since the position wasn't closed in that block.

[conorsch]

Ah, right, my mistake. Searching for EventPositionExecution shows zero results over the past week. Will need to tinker on a local devnet to try to coax an event out.

[conorsch]

After merge of #4016, I'm able to observe EventPositionExecution on preview:

❯ psql "$DATABASE_URL" -c 'SELECT e.* FROM events e JOIN blocks b ON e.block_id = b.rowid ;' | rg Event | perl -lanE 'print $F[-1]' | sort | uniq -c
      5 penumbra.core.component.dex.v1.EventBatchSwap
      1 penumbra.core.component.dex.v1.EventPositionExecution
     30 penumbra.core.component.dex.v1.EventPositionOpen
      5 penumbra.core.component.dex.v1.EventSwap
      5 penumbra.core.component.dex.v1.EventSwapClaim
   1286 penumbra.core.component.sct.v1.EventAnchor
   1286 penumbra.core.component.sct.v1.EventBlockRoot
     74 penumbra.core.component.sct.v1.EventCommitment
      1 penumbra.core.component.sct.v1.EventEpochRoot
     47 penumbra.core.component.shielded_pool.v1.EventOutput
     14 penumbra.core.component.shielded_pool.v1.EventSpend

The setup steps were:

• on wallet 1, run cargo run -r -q --bin pcli -- --home ~/.local/share/pcli-preview tx lp replicate xyk penumbra:gm 500penumbra --current-price 1
• on wallet 2, which has sufficient funds, run cargo run -r -q --bin pcli -- --home /tmp/preview-wallet-2 tx swap 5gm --into penumbra

After the swap was processed and auto-claimed, the execution event shows up in the indexing db.