Not unique logIndex

[nikitosing]

Checklist

• This is not a security-related bug/issue. If it is, please follow please follow the security policy.
• I have searched on the issue tracker and the lotus forum, and there is no existing related issue or discussion.
• I am running the Latest release, the most recent RC(release canadiate) for the upcoming release or the dev branch(master), or have an issue updating to any of these.
• I did not make any code changes to lotus.

Lotus component

• lotus daemon - chain sync
• lotus fvm/fevm - Lotus FVM and FEVM interactions
• lotus miner/worker - sealing
• lotus miner - proving(WindowPoSt/WinningPoSt)
• lotus JSON-RPC API
• lotus message management (mpool)
• Other

Lotus Version

1.29.1+calibnet+git.3a3395dfe

Repro Steps

1. get transaction receipt on filecoin-testnet (calibnet, chain id: 314159): {"jsonrpc":"2.0","id":2,"method":"eth_getTransactionReceipt","params":["0x4A2C9D4AA7BF56EA34E9E5E751BEB577C45C93D38BA825AF2B95E34EF5635350"]}
2. See two different logs with logIndex: 0x2:

   {
    "address": "0x493cd7e48854582eb9aa3a303c06984d23f5a30e",
    "data": "0x000000000000000000000000000000000000000000000002fa12c7332fe0932d",
    "topics": [
     "0x9d228d69b5fdb8d273a2336f8fb8612d039631024ea9bf09c424a9503aa078f0",
     "0x000000000000000000000000f0e7d903ef892ac5fe7020f15c29ec1f6a10e9f3",
     "0x00000000000000000000000051e1f72b655528de2d4d88e70bd53774db8d0b0c"
    ],
    "removed": false,
    "logIndex": "0x2",
    "transactionIndex": "0x1",
    "transactionHash": "0x4a2c9d4aa7bf56ea34e9e5e751beb577c45c93d38ba825af2b95e34ef5635350",
    "blockHash": "0xbf3c2cbfb12cb7238741fa15b311a98e1158fcb19766c56547fb55ef77838407",
    "blockNumber": "0x1b18b4"
   }
   

   and

   {
    "address": "0x51e1f72b655528de2d4d88e70bd53774db8d0b0c",
    "data": "0x000000000000000000000000000000000000000000000002fb474098f67c0000000000000000000000000000000000000000000000000002fa12c7332fe0932d",
    "topics": [
     "0x90890809c654f11d6e72a28fa60149770a0d11ec6c92319d6ceb2bb0a4ea1a15",
     "0x000000000000000000000000f0e7d903ef892ac5fe7020f15c29ec1f6a10e9f3"
    ],
    "removed": false,
    "logIndex": "0x2",
    "transactionIndex": "0x1",
    "transactionHash": "0x4a2c9d4aa7bf56ea34e9e5e751beb577c45c93d38ba825af2b95e34ef5635350",
    "blockHash": "0xbf3c2cbfb12cb7238741fa15b311a98e1158fcb19766c56547fb55ef77838407",
    "blockNumber": "0x1b18b4"
   }
   

Describe the Bug

Expected behavior

logIndex should be unique per block and per transaction

Logging Information

full response on `{"jsonrpc":"2.0","id":2,"method":"eth_getTransactionReceipt","params":["0x4A2C9D4AA7BF56EA34E9E5E751BEB577C45C93D38BA825AF2B95E34EF5635350"]}`

{"id":2,"jsonrpc":"2.0","result":{"transactionHash":"0x4a2c9d4aa7bf56ea34e9e5e751beb577c45c93d38ba825af2b95e34ef5635350","transactionIndex":"0x1","blockHash":"0xbf3c2cbfb12cb7238741fa15b311a98e1158fcb19766c56547fb55ef77838407","blockNumber":"0x1b18b4","from":"0xf0e7d903ef892ac5fe7020f15c29ec1f6a10e9f3","to":"0x51e1f72b655528de2d4d88e70bd53774db8d0b0c","root":"0x0000000000000000000000000000000000000000000000000000000000000000","status":"0x1","contractAddress":null,"cumulativeGasUsed":"0x0","gasUsed":"0x4f2f712","effectiveGasPrice":"0x3ccfe","logsBloom":"0x00800080000000000000000000000000000000400400000000000000000000000000200000000110000000400000000008000000000100800000000400000000000000000000000000000008000000000000000200000000000000000000000000000000020000000000000000002800000000000000000000000010000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000002000000000000000000000000000000000000000000000000000020000000000000000000000004000000000100000000400040000000000000000000","logs":[{"address":"0x493cd7e48854582eb9aa3a303c06984d23f5a30e","data":"0x000000000000000000000000000000000000000000000002fa12c7332fe0932d","topics":["0xddf252ad1be2c89b69c2b068fc378daa952ba7f163c4a11628f55a4df523b3ef","0x0000000000000000000000000000000000000000000000000000000000000000","0x000000000000000000000000f0e7d903ef892ac5fe7020f15c29ec1f6a10e9f3"],"removed":false,"logIndex":"0x1","transactionIndex":"0x1","transactionHash":"0x4a2c9d4aa7bf56ea34e9e5e751beb577c45c93d38ba825af2b95e34ef5635350","blockHash":"0xbf3c2cbfb12cb7238741fa15b311a98e1158fcb19766c56547fb55ef77838407","blockNumber":"0x1b18b4"},{"address":"0x493cd7e48854582eb9aa3a303c06984d23f5a30e","data":"0x000000000000000000000000000000000000000000000002fa12c7332fe0932d","topics":["0x9d228d69b5fdb8d273a2336f8fb8612d039631024ea9bf09c424a9503aa078f0","0x000000000000000000000000f0e7d903ef892ac5fe7020f15c29ec1f6a10e9f3","0x00000000000000000000000051e1f72b655528de2d4d88e70bd53774db8d0b0c"],"removed":false,"logIndex":"0x2","transactionIndex":"0x1","transactionHash":"0x4a2c9d4aa7bf56ea34e9e5e751beb577c45c93d38ba825af2b95e34ef5635350","blockHash":"0xbf3c2cbfb12cb7238741fa15b311a98e1158fcb19766c56547fb55ef77838407","blockNumber":"0x1b18b4"},{"address":"0x51e1f72b655528de2d4d88e70bd53774db8d0b0c","data":"0x000000000000000000000000000000000000000000000002fb474098f67c0000000000000000000000000000000000000000000000000002fa12c7332fe0932d","topics":["0x90890809c654f11d6e72a28fa60149770a0d11ec6c92319d6ceb2bb0a4ea1a15","0x000000000000000000000000f0e7d903ef892ac5fe7020f15c29ec1f6a10e9f3"],"removed":false,"logIndex":"0x3","transactionIndex":"0x1","transactionHash":"0x4a2c9d4aa7bf56ea34e9e5e751beb577c45c93d38ba825af2b95e34ef5635350","blockHash":"0xbf3c2cbfb12cb7238741fa15b311a98e1158fcb19766c56547fb55ef77838407","blockNumber":"0x1b18b4"},{"address":"0x493cd7e48854582eb9aa3a303c06984d23f5a30e","data":"0x000000000000000000000000000000000000000000000002fa12c7332fe0932d","topics":["0xddf252ad1be2c89b69c2b068fc378daa952ba7f163c4a11628f55a4df523b3ef","0x0000000000000000000000000000000000000000000000000000000000000000","0x000000000000000000000000f0e7d903ef892ac5fe7020f15c29ec1f6a10e9f3"],"removed":false,"logIndex":"0x0","transactionIndex":"0x1","transactionHash":"0x4a2c9d4aa7bf56ea34e9e5e751beb577c45c93d38ba825af2b95e34ef5635350","blockHash":"0xbf3c2cbfb12cb7238741fa15b311a98e1158fcb19766c56547fb55ef77838407","blockNumber":"0x1b18b4"},{"address":"0x51e1f72b655528de2d4d88e70bd53774db8d0b0c","data":"0x000000000000000000000000000000000000000000000002fb474098f67c0000000000000000000000000000000000000000000000000002fa12c7332fe0932d","topics":["0x90890809c654f11d6e72a28fa60149770a0d11ec6c92319d6ceb2bb0a4ea1a15","0x000000000000000000000000f0e7d903ef892ac5fe7020f15c29ec1f6a10e9f3"],"removed":false,"logIndex":"0x2","transactionIndex":"0x1","transactionHash":"0x4a2c9d4aa7bf56ea34e9e5e751beb577c45c93d38ba825af2b95e34ef5635350","blockHash":"0xbf3c2cbfb12cb7238741fa15b311a98e1158fcb19766c56547fb55ef77838407","blockNumber":"0x1b18b4"}],"type":"0x2"}

[rvagg]

Response from my calibnet node:

[
    {
      "address": "0x493cd7e48854582eb9aa3a303c06984d23f5a30e",
      "data": "0x000000000000000000000000000000000000000000000002fa12c7332fe0932d",
      "topics": [
        "0xddf252ad1be2c89b69c2b068fc378daa952ba7f163c4a11628f55a4df523b3ef",
        "0x0000000000000000000000000000000000000000000000000000000000000000",
        "0x000000000000000000000000f0e7d903ef892ac5fe7020f15c29ec1f6a10e9f3"
      ],
      "removed": false,
      "logIndex": "0x1",
      "transactionIndex": "0x1",
      "transactionHash": "0x4a2c9d4aa7bf56ea34e9e5e751beb577c45c93d38ba825af2b95e34ef5635350",
      "blockHash": "0xbf3c2cbfb12cb7238741fa15b311a98e1158fcb19766c56547fb55ef77838407",
      "blockNumber": "0x1b18b4"
    },
    {
      "address": "0x493cd7e48854582eb9aa3a303c06984d23f5a30e",
      "data": "0x000000000000000000000000000000000000000000000002fa12c7332fe0932d",
      "topics": [
        "0x9d228d69b5fdb8d273a2336f8fb8612d039631024ea9bf09c424a9503aa078f0",
        "0x000000000000000000000000f0e7d903ef892ac5fe7020f15c29ec1f6a10e9f3",
        "0x00000000000000000000000051e1f72b655528de2d4d88e70bd53774db8d0b0c"
      ],
      "removed": false,
      "logIndex": "0x2",
      "transactionIndex": "0x1",
      "transactionHash": "0x4a2c9d4aa7bf56ea34e9e5e751beb577c45c93d38ba825af2b95e34ef5635350",
      "blockHash": "0xbf3c2cbfb12cb7238741fa15b311a98e1158fcb19766c56547fb55ef77838407",
      "blockNumber": "0x1b18b4"
    },
    {
      "address": "0x51e1f72b655528de2d4d88e70bd53774db8d0b0c",
      "data": "0x000000000000000000000000000000000000000000000002fb474098f67c0000000000000000000000000000000000000000000000000002fa12c7332fe0932d",
      "topics": [
        "0x90890809c654f11d6e72a28fa60149770a0d11ec6c92319d6ceb2bb0a4ea1a15",
        "0x000000000000000000000000f0e7d903ef892ac5fe7020f15c29ec1f6a10e9f3"
      ],
      "removed": false,
      "logIndex": "0x3",
      "transactionIndex": "0x1",
      "transactionHash": "0x4a2c9d4aa7bf56ea34e9e5e751beb577c45c93d38ba825af2b95e34ef5635350",
      "blockHash": "0xbf3c2cbfb12cb7238741fa15b311a98e1158fcb19766c56547fb55ef77838407",
      "blockNumber": "0x1b18b4"
    }
  ]

I can't see how we could end up with duplicate logIndex now. But the tipset for this case is https://calibration.filfox.info/en/tipset/1775796, which is July 10th. We fixed this event index bug back in #11952 which made it in to Lotus v1.27.1 which was released on June 24th, and it wasn't a mandatory upgrade.

I think what we're seeing here is pre-v1.27.1 behaviour being locked into the index, and because you're reaching back that far you're encountering the original bug that was filed for this @ #11630.

Is this a problem for you @nikitosing? We'd be able to come up with some suggestions for how you might correct this, but it'd either be some gnarly SQL to run on the database, or a delete and backfill of the impacted epochs, which is only going to work if you have the full historical state to rebuild the events from.

[nikitosing]

@rvagg Yes, I think that's the case.

but it'd either be some gnarly SQL to run on the database, or a delete and backfill of the impacted epochs, which is only going to work if you have the full historical state to rebuild the events from.

it's ok, we have the full historical state

[nikitosing]

@rvagg Could you please share your suggestions about workaround for the issue?

[rvagg]

@nikitosing can you run this, so we can see what we're dealing with? Given the path to your lotus repo dir, we want to run sqlite3 on the commandline to the sqlite/events.db file, so something like sqlite3 /path/to/lotus/sqlite/events.db. Then in the REPL that it gives you, run:

SELECT count(*)
FROM event e
JOIN (
    SELECT tipset_key_cid, event_index
    FROM event
    GROUP BY tipset_key_cid, event_index
    HAVING COUNT(*) > 1
) dup ON e.tipset_key_cid = dup.tipset_key_cid AND e.event_index = dup.event_index
ORDER BY e.tipset_key_cid, e.event_index;

And let me know what the number it comes back with is and we'll think about it from there.

The problem is, there was a migration in #11952 that was supposed to properly order all of these so you didn't have duplicates, so I'm actually not sure how you can end up with it in a bad state like this: https://github.com/filecoin-project/lotus/pull/11952/files#diff-fe5e47a357d5465c3a2b1002977a53ad7c0990f76da22137417723577b87b19eR382

[nikitosing]

@rvagg result is 87514

[rvagg]

@nikitosing that's a big number. Would you mind compiling lotus-shed for me, off master or the 1.29 branch, it shouldn't matter, and running lotus-shed indexes inspect-events --epochs 1652000 --log-good | tee inspect.log. If you're not running lotus with its standard repo location (~/.lotus) then you might need to start it with lotus-shed -repo /path/to/repo indexes .... It's going to start from the head and work backward comparing what it thinks should be in the events db to what is there and it'll print out any discrepancies it finds. There will likely be a lot, historically, that complain about "zero events epoch not in events_seen", but the main one I'm interested in is where it says that it expects X events but found Y in the database, where Y is greater than X. We've seen this elsewhere and don't know what's caused it, but it would be helpful to know if it's happening for you in this instance too. The 1652000 should take you back to when fevm started spitting out events, and hopefully it doesn't run too slowly on a calibnet node which doesn't have that many events.