Error when walking vm_messages

[davidgasquez]

The task vm_messages is returning some errors when running lily job walk on some archival snapshots.

Steps to Reproduce:

1. Obtain the Archival Snapshot: aws s3 cp "s3://sentinel-backfill/historical-exports/snapshot_2880_5762_1666948097.car.zst" .
2. Extract it: unzstd snapshot_2880_5762_1666948097.car.zst -o /tmp/snapshot.car
3. Initialize Lily: lily init --config=config.toml --import-snapshot /tmp/snapshot.car
4. Start Lily Daemon: nohup lily daemon --config=config.toml --bootstrap=false &> lily.log &
5. Run a walk that goes through 4987: lily job run --storage=CSV walk --from 4950 --to 5000
6. Check Visor Processing Reports: cat visor_processing_reports.csv | grep ERROR

This is the config.toml file:

[Storage]
    [Storage.File]
        [Storage.File.CSV]
            Format = "CSV"
            Path = "/tmp/data"
            OmitHeader = false
            FilePattern = "{table}.csv"

The visor_processing_reports.csv has the following error:

4987,bafy2bzacebhsu3zb4ozi2ivvmpccl2uvcbnbx2u7di7iulztcjwibzplzrpcq,walk_1668532240,vm_messages,2022-11-15T17:10:47.347Z,2022-11-15T17:10:48.187Z,ERROR,,"[{""Cid"":{""/"":""bafy2bzacebrgpkrvsditem5hn7qw2vtvilc7owhmp2wdjexspzyth2qd5mzus""},""Error"":""failed to get to actor code for message: bafy2bzacecqe37bhu4scycqotm4l3ymkedweaunhjuxbyhghkvmwj3z7z6czu to address f09312""}]"

And the lily.log file has these lines:

{
  "level": "error",
  "ts": "2022-11-15T17:13:42.562Z",
  "logger": "lily/tasks/vmmsg",
  "caller": "vm/task.go:106",
  "msg": "parsing VM message",
  "source_cid": "bafy2bzacebrgpkrvsditem5hn7qw2vtvilc7owhmp2wdjexspzyth2qd5mzus",
  "source_receipt": {
    "ExitCode": 6,
    "Return": null,
    "GasUsed": 1750648,
    "ActorErr": {},
    "ExecutionTrace": {
      "Msg": {
        "Version": 0,
        "To": "f1pslsa42aigwifvztckhhmymjjodqu7nliybkpja",
        "From": "f1sfp3lmtoon3geb4hdkvmlgv4n2gahp3pdt5ihca",
        "Nonce": 3,
        "Value": "99999999741668065300",
        "GasLimit": 5342681,
        "GasFeeCap": "161181",
        "GasPremium": "160854",
        "Method": 0,
        "Params": null,
        "CID": {
          "/": "bafy2bzacedccpjl25ob6qsm2pe6i67gw7iudllck3ykp4xniw3ycept5qdeou"
        }
      },
      "MsgRct": {
        "ExitCode": 6,
        "Return": null,
        "GasUsed": 1750648
      },
      "Error": "failed to transfer funds (RetCode=6): transfer failed when deducting funds (99.9999997416680653 FIL): not enough funds (RetCode=6)",
      "Duration": 316271,
      "GasCharges": null,
      "Subcalls": [
        {
          "Msg": {
            "Version": 0,
            "To": "f09312",
            "From": "f00",
            "Nonce": 0,
            "Value": "0",
            "GasLimit": 5342681,
            "GasFeeCap": "0",
            "GasPremium": "0",
            "Method": 1,
            "Params": "VQF8lyBzQEGsgtczEo52YYlLhwp9qw==",
            "CID": {
              "/": "bafy2bzacecqe37bhu4scycqotm4l3ymkedweaunhjuxbyhghkvmwj3z7z6czu"
            }
          },
          "MsgRct": {
            "ExitCode": 0,
            "Return": null,
            "GasUsed": 1534243
          },
          "Error": "",
          "Duration": 30560,
          "GasCharges": null,
          "Subcalls": null
        }
      ]
    },
    "Duration": 398131,
    "GasCosts": {
      "BaseFeeBurn": "768534472",
      "OverEstimationBurn": "1576902487",
      "MinerPenalty": "0",
      "MinerTip": "858793229302",
      "Refund": "0",
      "GasRefund": 0,
      "GasBurned": 3592033
    }
  },
  "child_cid": "bafy2bzacecqe37bhu4scycqotm4l3ymkedweaunhjuxbyhghkvmwj3z7z6czu",
  "child_receipt": {
    "ExitCode": 0,
    "Return": null,
    "GasUsed": 1534243
  }
}

{
  "level": "info",
  "ts": "2022-11-15T17:13:42.574Z",
  "logger": "lily/index/processor",
  "caller": "processor/state.go:276",
  "msg": "processor ended",
  "task": "vm_messages",
  "height": "4987",
  "reporter": "walk_1668532412",
  "duration": 0.196460052
}

{
  "level": "warn",
  "ts": "2022-11-15T17:10:48.187Z",
  "logger": "lily/index/manager",
  "caller": "integrated/manager.go:122",
  "msg": "task failed",
  "height": "4987",
  "reporter": "walk_1668532240",
  "task": "vm_messages",
  "status": "ERROR",
  "errors": [
    {
      "Cid": {
        "/": "bafy2bzacebrgpkrvsditem5hn7qw2vtvilc7owhmp2wdjexspzyth2qd5mzus"
      },
      "Error": "failed to get to actor code for message: bafy2bzacecqe37bhu4scycqotm4l3ymkedweaunhjuxbyhghkvmwj3z7z6czu to address f09312"
    }
  ]
}

Lily Version: v0.12.0+6-g8d3c4b7

[davidgasquez]

Heya @frrist! Spotted this error again:

{
  "level":"info",
  "ts":"2022-12-14T16:42:55.270Z",
  "msg":"error found for height 2243044: [{\"Cid\":{\"/\":\"bafy2bzaceb2ywpipkptpxop72i5uhvf45j3rwjpexef4loexgiocuavkfexpk\"},\"Error\":\"failed to get to actor code for message: bafy2bzacecnfhqvpcljsdbxvwohnocdthy5mub5zgdirtce45ocpopudonow6 to address f1jeautnpgr6js6uqtm4aa6mf6dvhn3unbdcvpbpy\"}]",
  "task":"vm_messages"
}

This was when walking the snapshot_2240640_2243522_1667419218.car.zst Archival Snapshot around epoch 2243044.

[davidgasquez]

Same happening at height 2323717.

[frrist]

@davidgasquez this looks like it may be a duplicate of: #1110

[frrist]

via #1112