Intermitent fork issue

[guilledk]

Something we found on the translator is only on certain forks, the reader processes each new block as it where a fork, this is likely caused by a bug in the TimedSet datastructure.

Examples of logs:

[2023-11-30T17:07:50.770][READER][DEBUG] [decodeShipData]:
[2023-11-30T17:07:50.770][READER][DEBUG] prev: #312799312 - 12a4f050781449d3cf2bf190bb8fd9d1f88e3ec1c99a29fd1f95d56b4e8aee2d
[2023-11-30T17:07:50.770][READER][DEBUG] this: #312799313 - 12a4f051547e9c5eb47797c29f33c8456f104ce4f5521b667e52e9b3d296ea67
2023-11-30T17:07:50.786Z [PID:114163] [info] : drained 2 operations.
2023-11-30T17:07:50.786Z [PID:114163] [info] : broadcasting 1 blocks...
2023-11-30T17:07:50.786Z [PID:114163] [info] : done.
2023-11-30T17:07:51.174Z [PID:114163] [info] : 312799313 pushed, at 1.998002142671022 blocks/sec
[2023-11-30T17:07:51.274][READER][DEBUG] [decodeShipData]:
[2023-11-30T17:07:51.274][READER][DEBUG] prev: #312799313 - 12a4f051547e9c5eb47797c29f33c8456f104ce4f5521b667e52e9b3d296ea67
[2023-11-30T17:07:51.274][READER][DEBUG] this: #312799314 - 12a4f052bf82795da35c2d23f7b226e7bddaa77daa218e556813ca0905e43709
2023-11-30T17:07:51.295Z [PID:114163] [info] : drained 2 operations.
2023-11-30T17:07:51.295Z [PID:114163] [info] : broadcasting 1 blocks...
2023-11-30T17:07:51.295Z [PID:114163] [info] : done.
[2023-11-30T17:07:51.774][READER][DEBUG] [decodeShipData]:
[2023-11-30T17:07:51.774][READER][DEBUG] prev: #312799314 - 12a4f052bf82795da35c2d23f7b226e7bddaa77daa218e556813ca0905e43709
[2023-11-30T17:07:51.774][READER][DEBUG] this: #312799315 - 12a4f0538212f48f40ea4d7525ae37603ddd2ae1f6aa973081caa6d0ee7f07a9
2023-11-30T17:07:51.817Z [PID:114163] [info] : drained 2 operations.
2023-11-30T17:07:51.817Z [PID:114163] [info] : broadcasting 1 blocks...
2023-11-30T17:07:51.817Z [PID:114163] [info] : done.
2023-11-30T17:07:52.174Z [PID:114163] [info] : 312799315 pushed, at 2 blocks/sec
[2023-11-30T17:07:52.274][READER][DEBUG] [decodeShipData]:
[2023-11-30T17:07:52.274][READER][DEBUG] prev: #312799315 - 12a4f0538212f48f40ea4d7525ae37603ddd2ae1f6aa973081caa6d0ee7f07a9
[2023-11-30T17:07:52.274][READER][DEBUG] this: #312799316 - 12a4f0548f9b99345efb23dae1a64dbc4b29c0b6864f2dd80b0ca74263e6afa8
2023-11-30T17:07:52.316Z [PID:114163] [info] : drained 2 operations.
2023-11-30T17:07:52.316Z [PID:114163] [info] : broadcasting 1 blocks...
2023-11-30T17:07:52.316Z [PID:114163] [info] : done.
[2023-11-30T17:07:52.775][READER][DEBUG] [decodeShipData]:
[2023-11-30T17:07:52.775][READER][DEBUG] prev: #312799316 - 12a4f0548f9b99345efb23dae1a64dbc4b29c0b6864f2dd80b0ca74263e6afa8
[2023-11-30T17:07:52.775][READER][DEBUG] this: #312799317 - 12a4f055c9829bdfd937a4125aa15ac7c9b66ee7aaa036e33d2d05f31465ba08
2023-11-30T17:07:52.821Z [PID:114163] [info] : drained 2 operations.
2023-11-30T17:07:52.821Z [PID:114163] [info] : broadcasting 1 blocks...
2023-11-30T17:07:52.821Z [PID:114163] [info] : done.
[2023-11-30T17:07:53.124][READER][DEBUG] [decodeShipData]:
[2023-11-30T17:07:53.124][READER][DEBUG] prev: #312799317 - 12a4f055c9829bdfd937a4125aa15ac7c9b66ee7aaa036e33d2d05f31465ba08
[2023-11-30T17:07:53.124][READER][DEBUG] this: #312799318 - 12a4f0560cd4092bf11314b2d8e2d0bb4856c2b71ee34cb1215a99046f3c5e2f
2023-11-30T17:07:53.171Z [PID:114163] [info] : drained 2 operations.
2023-11-30T17:07:53.171Z [PID:114163] [info] : broadcasting 1 blocks...
2023-11-30T17:07:53.171Z [PID:114163] [info] : done.
2023-11-30T17:07:53.174Z [PID:114163] [info] : 312799318 pushed, at 3 blocks/sec
2023-11-30T17:07:54.174Z [PID:114163] [info] : 312799318 pushed, at 0 blocks/sec
2023-11-30T17:07:55.175Z [PID:114163] [info] : 312799318 pushed, at 0 blocks/sec
[2023-11-30T17:07:55.487][READER][DEBUG] [decodeShipData]:
[2023-11-30T17:07:55.487][READER][DEBUG] prev: #312799313 - 12a4f051547e9c5eb47797c29f33c8456f104ce4f5521b667e52e9b3d296ea67
[2023-11-30T17:07:55.487][READER][DEBUG] this: #312799314 - 12a4f05267faf81b3148a9f69be41619d48c3a7c4b72fb05f3ae5846b5d461c9
[2023-11-30T17:07:55.487][READER][DEBUG] FORK detected!
[2023-11-30T17:07:55.487][READER][DEBUG] blockHistory last 40 values before handling:
[2023-11-30T17:07:55.487][READER][DEBUG] [
  312799279, 312799280, 312799281, 312799282,
  312799283, 312799284, 312799285, 312799286,
  312799287, 312799288, 312799289, 312799290,
  312799291, 312799292, 312799293, 312799294,
  312799295, 312799296, 312799297, 312799298,
  312799299, 312799300, 312799301, 312799302,
  312799303, 312799304, 312799305, 312799306,
  312799307, 312799308, 312799309, 312799310,
  312799311, 312799312, 312799313, 312799314,
  312799315, 312799316, 312799317, 312799318
]
[2023-11-30T17:07:55.490][READER][DEBUG] purging block collector from 312799314
[2023-11-30T17:07:55.490][READER][DEBUG] done, purged up to 312799314
[2023-11-30T17:07:55.490][READER][DEBUG] purging block history from 312799314
[2023-11-30T17:07:55.490][READER][DEBUG] blockHistory last 40 values after handling:
[2023-11-30T17:07:55.490][READER][DEBUG] [
  312799279, 312799280, 312799281, 312799282,
  312799283, 312799284, 312799285, 312799286,
  312799287, 312799288, 312799289, 312799290,
  312799291, 312799292, 312799293, 312799294,
  312799295, 312799296, 312799297, 312799298,
  312799299, 312799300, 312799301, 312799302,
  312799303, 312799304, 312799305, 312799306,
  312799307, 312799308, 312799309, 312799310,
  312799311, 312799312, 312799313, 312799314,
  312799315, 312799316, 312799317, 312799318
]
[2023-11-30T17:07:55.490][READER][DEBUG] blockHistory has #312799314? true
[2023-11-30T17:07:55.490][READER][DEBUG] done.
[2023-11-30T17:07:55.494][READER][DEBUG] [decodeShipData]:
[2023-11-30T17:07:55.495][READER][DEBUG] prev: #312799314 - 12a4f05267faf81b3148a9f69be41619d48c3a7c4b72fb05f3ae5846b5d461c9
[2023-11-30T17:07:55.495][READER][DEBUG] this: #312799315 - 12a4f053ad952c8b2609d5959ef37e0282d378c6c00cab7044deeaeaf7d687b4
[2023-11-30T17:07:55.495][READER][DEBUG] FORK detected!
[2023-11-30T17:07:55.495][READER][DEBUG] blockHistory last 40 values before handling:
[2023-11-30T17:07:55.495][READER][DEBUG] [
  312799280, 312799281, 312799282, 312799283,
  312799284, 312799285, 312799286, 312799287,
  312799288, 312799289, 312799290, 312799291,
  312799292, 312799293, 312799294, 312799295,
  312799296, 312799297, 312799298, 312799299,
  312799300, 312799301, 312799302, 312799303,
  312799304, 312799305, 312799306, 312799307,
  312799308, 312799309, 312799310, 312799311,
  312799312, 312799313, 312799314, 312799315,
  312799316, 312799317, 312799318, 312799314
]
[2023-11-30T17:07:55.495][READER][DEBUG] purging block collector from 312799315
[2023-11-30T17:07:55.495][READER][DEBUG] done, purged up to 312799315
[2023-11-30T17:07:55.495][READER][DEBUG] purging block history from 312799315
[2023-11-30T17:07:55.495][READER][DEBUG] blockHistory last 40 values after handling:
[2023-11-30T17:07:55.495][READER][DEBUG] [
  312799280, 312799281, 312799282, 312799283,
  312799284, 312799285, 312799286, 312799287,
  312799288, 312799289, 312799290, 312799291,
  312799292, 312799293, 312799294, 312799295,
  312799296, 312799297, 312799298, 312799299,
  312799300, 312799301, 312799302, 312799303,
  312799304, 312799305, 312799306, 312799307,
  312799308, 312799309, 312799310, 312799311,
  312799312, 312799313, 312799314, 312799315,
  312799316, 312799317, 312799318, 312799314
]
[2023-11-30T17:07:55.495][READER][DEBUG] blockHistory has #312799315? true
[2023-11-30T17:07:55.495][READER][DEBUG] done.
2023-11-30T17:07:55.499Z [PID:114163] [info] : got 312799314 and expected 312799319, chain fork detected. reverse all blocks which were affected
2023-11-30T17:07:55.499Z [PID:114163] [info] : purging indices in db from block 312799314...
[2023-11-30T17:07:55.501][READER][DEBUG] [decodeShipData]:
[2023-11-30T17:07:55.501][READER][DEBUG] prev: #312799315 - 12a4f053ad952c8b2609d5959ef37e0282d378c6c00cab7044deeaeaf7d687b4
[2023-11-30T17:07:55.501][READER][DEBUG] this: #312799316 - 12a4f054207d229f79aaa47546463f53aa253b57b1034fd8a4618f36ad3f76f1
[2023-11-30T17:07:55.501][READER][DEBUG] FORK detected!
[2023-11-30T17:07:55.501][READER][DEBUG] blockHistory last 40 values before handling:
[2023-11-30T17:07:55.501][READER][DEBUG] [
  312799281, 312799282, 312799283, 312799284,
  312799285, 312799286, 312799287, 312799288,
  312799289, 312799290, 312799291, 312799292,
  312799293, 312799294, 312799295, 312799296,
  312799297, 312799298, 312799299, 312799300,
  312799301, 312799302, 312799303, 312799304,
  312799305, 312799306, 312799307, 312799308,
  312799309, 312799310, 312799311, 312799312,
  312799313, 312799314, 312799315, 312799316,
  312799317, 312799318, 312799314, 312799315
]
[2023-11-30T17:07:55.501][READER][DEBUG] purging block collector from 312799316
[2023-11-30T17:07:55.501][READER][DEBUG] done, purged up to 312799316
[2023-11-30T17:07:55.501][READER][DEBUG] purging block history from 312799316
[2023-11-30T17:07:55.501][READER][DEBUG] blockHistory last 40 values after handling:
[2023-11-30T17:07:55.501][READER][DEBUG] [
  312799281, 312799282, 312799283, 312799284,
  312799285, 312799286, 312799287, 312799288,
  312799289, 312799290, 312799291, 312799292,
  312799293, 312799294, 312799295, 312799296,
  312799297, 312799298, 312799299, 312799300,
  312799301, 312799302, 312799303, 312799304,
  312799305, 312799306, 312799307, 312799308,
  312799309, 312799310, 312799311, 312799312,
  312799313, 312799314, 312799315, 312799316,
  312799317, 312799318, 312799314, 312799315
]
[2023-11-30T17:07:55.502][READER][DEBUG] blockHistory has #312799316? true
[2023-11-30T17:07:55.502][READER][DEBUG] done.
2023-11-30T17:07:55.507Z [PID:114163] [info] : got 312799315 and expected 312799319, chain fork detected. reverse all blocks which were affected
2023-11-30T17:07:55.507Z [PID:114163] [info] : purging indices in db from block 312799315...
2023-11-30T17:07:55.545Z [PID:114163] [debug] : getLastIndexedBlock:
{
    "@timestamp": "2023-11-30T17:07:53Z",
    "block_num": 312799318,
    "@global": {
        "block_num": 312799282
    },
    "@blockHash": "12a4f0560cd4092bf11314b2d8e2d0bb4856c2b71ee34cb1215a99046f3c5e2f",
    "@evmBlockHash": "de6cd57b0a56801c0d04baeb7166a8934ee618038442f219381d305e0937c691",
    "@evmPrevBlockHash": "ad0d9076c5ac8b0a586e7e28e5615f07d0e548fe596f276733831fb97d5f57f0",
    "@receiptsRootHash": "56e81f171bcc55a6ff8345e692c0f86e5b48e01b996cadc001622fb5e363b421",
    "@transactionsRoot": "56e81f171bcc55a6ff8345e692c0f86e5b48e01b996cadc001622fb5e363b421",
    "gasUsed": "0",
    "gasLimit": "0",
    "size": "0",
    "code": "eosio",
    "table": "global"
}
2023-11-30T17:07:55.545Z [PID:114163] [debug] : getLastIndexedBlock:
{
    "@timestamp": "2023-11-30T17:07:53Z",
    "block_num": 312799318,
    "@global": {
        "block_num": 312799282
    },
    "@blockHash": "12a4f0560cd4092bf11314b2d8e2d0bb4856c2b71ee34cb1215a99046f3c5e2f",
    "@evmBlockHash": "de6cd57b0a56801c0d04baeb7166a8934ee618038442f219381d305e0937c691",
    "@evmPrevBlockHash": "ad0d9076c5ac8b0a586e7e28e5615f07d0e548fe596f276733831fb97d5f57f0",
    "@receiptsRootHash": "56e81f171bcc55a6ff8345e692c0f86e5b48e01b996cadc001622fb5e363b421",
    "@transactionsRoot": "56e81f171bcc55a6ff8345e692c0f86e5b48e01b996cadc001622fb5e363b421",
    "gasUsed": "0",
    "gasLimit": "0",
    "size": "0",
    "code": "eosio",
    "table": "global"
}
2023-11-30T17:07:55.549Z [PID:114163] [debug] : telos-mainnet-delta-v1.5-00000031 delete result: {
    "took": 2,
    "timed_out": false,
    "total": 4,
    "deleted": 0,
    "batches": 1,
    "version_conflicts": 4,
    "noops": 0,
    "retries": {
        "bulk": 0,
        "search": 0
    },
    "throttled_millis": 0,
    "requests_per_second": -1,
    "throttled_until_millis": 0,
    "failures": []
}
2023-11-30T17:07:55.551Z [PID:114163] [debug] : telos-mainnet-action-v1.5-00000031 delete result: {
    "took": 1,
    "timed_out": false,
    "total": 0,
    "deleted": 0,
    "batches": 0,
    "version_conflicts": 0,
    "noops": 0,
    "retries": {
        "bulk": 0,
        "search": 0
    },
    "throttled_millis": 0,
    "requests_per_second": -1,
    "throttled_until_millis": 0,
    "failures": []
}
2023-11-30T17:07:55.551Z [PID:114163] [info] : deleted blocks from 312799315 to 312799318, remaining: 0
2023-11-30T17:07:55.551Z [PID:114163] [debug] : purged db of blocks newer than 312799314, continue...
2023-11-30T17:07:55.572Z [PID:114163] [debug] : telos-mainnet-delta-v1.5-00000031 delete result: {
    "took": 26,
    "timed_out": false,
    "total": 5,
    "deleted": 5,
    "batches": 1,
    "version_conflicts": 0,
    "noops": 0,
    "retries": {
        "bulk": 0,
        "search": 0
    },
    "throttled_millis": 0,
    "requests_per_second": -1,
    "throttled_until_millis": 0,
    "failures": []
}
2023-11-30T17:07:55.574Z [PID:114163] [debug] : telos-mainnet-action-v1.5-00000031 delete result: {
    "took": 1,
    "timed_out": false,
    "total": 0,
    "deleted": 0,
    "batches": 0,
    "version_conflicts": 0,
    "noops": 0,
    "retries": {
        "bulk": 0,
        "search": 0
    },
    "throttled_millis": 0,
    "requests_per_second": -1,
    "throttled_until_millis": 0,
    "failures": []
}
2023-11-30T17:07:55.574Z [PID:114163] [info] : deleted blocks from 312799314 to 312799318, remaining: 0
2023-11-30T17:07:55.574Z [PID:114163] [debug] : purged db of blocks newer than 312799313, continue...
2023-11-30T17:07:55.575Z [PID:114163] [info] : drained 4 operations.
2023-11-30T17:07:55.575Z [PID:114163] [info] : broadcasting 1 blocks...
2023-11-30T17:07:55.575Z [PID:114163] [info] : done.
2023-11-30T17:07:55.590Z [PID:114163] [info] : drained 2 operations.
2023-11-30T17:07:55.590Z [PID:114163] [info] : broadcasting 1 blocks...
2023-11-30T17:07:55.590Z [PID:114163] [info] : done.
2023-11-30T17:07:55.591Z [PID:114163] [info] : drained 4 operations.
2023-11-30T17:07:55.591Z [PID:114163] [info] : broadcasting 1 blocks...
2023-11-30T17:07:55.591Z [PID:114163] [info] : done.
[2023-11-30T17:07:55.608][READER][DEBUG] [decodeShipData]:
[2023-11-30T17:07:55.608][READER][DEBUG] prev: #312799316 - 12a4f054207d229f79aaa47546463f53aa253b57b1034fd8a4618f36ad3f76f1
[2023-11-30T17:07:55.608][READER][DEBUG] this: #312799317 - 12a4f0559cb7e64f9379c8d24be0ed1fb0a550aeeae145129302f32ca8bd1c30
[2023-11-30T17:07:55.608][READER][DEBUG] FORK detected!
[2023-11-30T17:07:55.608][READER][DEBUG] blockHistory last 40 values before handling:
[2023-11-30T17:07:55.608][READER][DEBUG] [
  312799282, 312799283, 312799284, 312799285,
  312799286, 312799287, 312799288, 312799289,
  312799290, 312799291, 312799292, 312799293,
  312799294, 312799295, 312799296, 312799297,
  312799298, 312799299, 312799300, 312799301,
  312799302, 312799303, 312799304, 312799305,
  312799306, 312799307, 312799308, 312799309,
  312799310, 312799311, 312799312, 312799313,
  312799314, 312799315, 312799316, 312799317,
  312799318, 312799314, 312799315, 312799316
]
[2023-11-30T17:07:55.608][READER][DEBUG] purging block collector from 312799317
[2023-11-30T17:07:55.608][READER][DEBUG] done, purged up to 312799317
[2023-11-30T17:07:55.608][READER][DEBUG] purging block history from 312799317
[2023-11-30T17:07:55.608][READER][DEBUG] blockHistory last 40 values after handling:
[2023-11-30T17:07:55.608][READER][DEBUG] [
  312799282, 312799283, 312799284, 312799285,
  312799286, 312799287, 312799288, 312799289,
  312799290, 312799291, 312799292, 312799293,
  312799294, 312799295, 312799296, 312799297,
  312799298, 312799299, 312799300, 312799301,
  312799302, 312799303, 312799304, 312799305,
  312799306, 312799307, 312799308, 312799309,
  312799310, 312799311, 312799312, 312799313,
  312799314, 312799315, 312799316, 312799317,
  312799318, 312799314, 312799315, 312799316
]
[2023-11-30T17:07:55.608][READER][DEBUG] blockHistory has #312799317? true
[2023-11-30T17:07:55.608][READER][DEBUG] done.
2023-11-30T17:07:55.609Z [PID:114163] [error] : Unhandled Rejection
2023-11-30T17:07:55.610Z [PID:114163] [error] : {}
2023-11-30T17:07:55.610Z [PID:114163] [error] : Expected block 312799315 and got 312799317, gap on reader?
2023-11-30T17:07:55.611Z [PID:114163] [error] : Error: Expected block 312799315 and got 312799317, gap on reader?
    at TEVMIndexer.processBlock (file:///home/guille/telosevm-translator/build/indexer.js:210:19)
    at EventEmitter.emit (node:events:513:28)
    at HyperionSequentialReader.checkBlock (file:///home/guille/telosevm-translator/node_modules/@eosrio/hyperion-sequential-reader/lib/esm/reader.js:571:29)
    at HyperionSequentialReader.collectDelta (file:///home/guille/telosevm-translator/node_modules/@eosrio/hyperion-sequential-reader/lib/esm/reader.js:553:14)
    at HyperionSequentialReader.handleWorkerMessage (file:///home/guille/telosevm-translator/node_modules/@eosrio/hyperion-sequential-reader/lib/esm/reader.js:491:22)
    at Worker.<anonymous> (file:///home/guille/telosevm-translator/node_modules/@eosrio/hyperion-sequential-reader/lib/esm/reader.js:471:22)
    at Worker.emit (node:events:513:28)
    at MessagePort.<anonymous> (node:internal/worker:233:53)
    at MessagePort.[nodejs.internal.kHybridDispatch] (node:internal/event_target:694:20)
    at MessagePort.exports.emitMessage (node:internal/per_context/messageport:23:28)

2023-11-30T17:07:53.734Z [PID:593361] [info] : 312799318 pushed, at 2 blocks/sec
2023-11-30T17:07:54.734Z [PID:593361] [info] : 312799318 pushed, at 0 blocks/sec
2023-11-30T17:07:55.470Z [PID:593361] [info] : got 312799314 and expected 312799319, chain fork detected. reverse all blocks which were affected
2023-11-30T17:07:55.470Z [PID:593361] [info] : purging indices in db from block 312799314...
2023-11-30T17:07:55.471Z [PID:593361] [info] : got 312799315 and expected 312799319, chain fork detected. reverse all blocks which were affected
2023-11-30T17:07:55.471Z [PID:593361] [info] : purging indices in db from block 312799315...
2023-11-30T17:07:55.477Z [PID:593361] [info] : got 312799316 and expected 312799319, chain fork detected. reverse all blocks which were affected
2023-11-30T17:07:55.477Z [PID:593361] [info] : purging indices in db from block 312799316...
2023-11-30T17:07:55.607Z [PID:593361] [info] : drained 4 operations.
2023-11-30T17:07:55.607Z [PID:593361] [info] : broadcasting 1 blocks...
2023-11-30T17:07:55.607Z [PID:593361] [info] : done.
2023-11-30T17:07:55.641Z [PID:593361] [error] : Unhandled Rejection
2023-11-30T17:07:55.642Z [PID:593361] [error] : {
2023-11-30T17:07:55.642Z [PID:593361] [error] : The first argument must be of type string or an instance of Buffer, ArrayBuffer, or Array or an Array-like Object. Received undefined
2023-11-30T17:07:55.642Z [PID:593361] [error] : TypeError: The first argument must be of type string or an instance of Buffer, ArrayBuffer, or Array or an Array-like Object. Received undefined
2023-11-30T17:07:55.922Z [PID:594266] [info] : Telos EVM Indexer 1.5
2023-11-30T17:07:55.923Z [PID:594266] [info] : Blocks will be shown in the following format: [native block num|evm block num]
2023-11-30T17:07:55.923Z [PID:594266] [info] : Happy indexing!

other: https://pastebin.com/bwL9Fi72 https://pastebin.com/yqE2bn6Q