pdp: proving period init bad state investigation

[Kubuxu]

I'm investingating proving period init failing but resulting in curio node trying to prove in any case

+----+------------------------------+---------------------------+--------------------------------------------------------------------+----------------+------------------+----------------+------------+-------------------------------------->
| id | prev_challenge_request_epoch | challenge_request_task_id | challenge_request_msg_hash                                         | proving_period | challenge_window | prove_at_epoch | init_ready | create_message_hash                  >
|----+------------------------------+---------------------------+--------------------------------------------------------------------+----------------+------------------+----------------+------------+-------------------------------------->
| 3  | <null>                       | <null>                    | <null>                                                             | 240            | 20               | <null>         | False      | 0x8fa368ad45a42e7e54d91e759eafdfab071>
| 9  | <null>                       | <null>                    | <null>                                                             | 240            | 20               | <null>         | False      | 0xb647d99f1a7cdfef3533ee416c23a840699>
| 5  | <null>                       | <null>                    | <null>                                                             | 240            | 20               | <null>         | False      | 0xf4c1b6d46624933b0abe6769cafc45bda54>
| 10 | <null>                       | <null>                    | <null>                                                             | 240            | 20               | <null>         | False      | 0x5fddd19bfdc25ae0d42b74721cdf4aa16e8>
| 7  | 3147129                      | <null>                    | 0x36c0dcafa31fc827c2dd725cced1de458a1ba31fd79e10476e5f10823128ef7c | 240            | 20               | 3147349        | True       | 0xe469e7f815256e7423b1015e10ab41b4da1>
| 4  | 3145106                      | <null>                    | <null>                                                             | 240            | 20               | 3145318        | True       | 0x955df1442a90a51ccc359616ec6ccb5d79a>
| 2  | <null>                       | <null>                    | <null>                                                             | 240            | 20               | <null>         | False      | 0x9fce1742cabfe813a0c9495ac526b916d83>
| 8  | <null>                       | <null>                    | <null>                                                             | 240            | 20               | <null>         | False      | 0x845dd0eb3e878169b3d4672044b41bb811c>
| 6  | <null>                       | <null>                    | <null>                                                             | 240            | 20               | <null>         | False      | 0xf4d0ac475a0b5c95f34ad92ce9d0c531b81>
| 1  | 3147246                      | <null>                    | 0x8c779523410b30ea1ed6f17d6e21ed62e13c4d9b60781253f1d7c464e65e8c29 | 240            | 20               | 3147466        | True       | 0x22c1cee8bfb104cdf0fdd345e981823fab3>
+----+------------------------------+---------------------------+--------------------------------------------------------------------+----------------+------------------+----------------+------------+--------------------------------------```

[Kubuxu]

ID 4 is in a weird state where it has prev_challenge_request_epoch and challenge_request_msg_hash is null, but the contract returns ProvingPeriodNotInitialized(uint256) when it tries to query NextPDPChallengeWindowStart

[jennijuju]

curio logs that could be related

{
  "caller": "harmonytask/task_type_handler.go:237",
  "dt": "2025-10-29T05:46:00.057+0800",
  "error": "failed to get next challenge window start: message execution failed (exit=[33], revert reason=[message failed with backtrace:\n00: f0169801 (method 3844450837) -- contract reverted at 3917 (33)\n (RetCode=33)], vm error=[0x999010d50000000000000000000000000000000000000000000000000000000000000322])",
  "errorVerbose": "failed to get next challenge window start:\n    github.com/filecoin-project/curio/tasks/pdp.(*NextProvingPeriodTask).Do\n        /root/workspace/curio/tasks/pdp/task_next_pp.go:128\n  - message execution failed (exit=[33], revert reason=[message failed with backtrace:\n00: f0169801 (method 3844450837) -- contract reverted at 3917 (33)\n (RetCode=33)], vm error=[0x999010d50000000000000000000000000000000000000000000000000000000000000322])",
  "id": "391920",
  "level": "error",
  "logger": "harmonytask",
  "msg": "Do() returned error",
  "platform": "Curio PDP",
  "type": "PDPProvingPeriod"

[Kubuxu]

That is ProvingPeriodNotInitialized, unfortunately, if anything was in logs, it was way earlier.

[Kubuxu]

After adding additional error return:

{"level":"error","ts":"2025-10-29T15:33:32.984+0100","logger":"harmonytask","caller":"harmonytask/task_type_handler.go:237","msg":"Do() returned error","type":"PDPInitPP","id":"88540","error":"data set 4 has no leaves","errorVerbose":"data set 4 has no leaves:\n    github.com/filecoin-project/curio/tasks/pdp.(*InitProvingPeriodTask).Do\n        /home/kubuxu/curio/tasks/pdp/task_init_pp.go:127"}

not sure how we got into the previous state

[Kubuxu]

I think I found the root cause, piece was deleted from that dataset, which then cause failure in removal:

error: failed to cleanup deleted pieces: failed to cleanup deleted pieces: failed to delete parked piece ref 401: ERROR: null value in column "pdp_pieceref" of relation "pdp_data_set_pieces" violates not-null constraint (SQLSTATE 23502)

error: failed to send transaction: failed to estimate gas: failed to estimate gas: message execution failed: exit 33, reason: message failed with backtrace: 00: f0176630 (method 3844450837) -- contract reverted at 75 (33) 01: f0176630 (method 6) -- contract reverted at 2720 (33) 02: f0176641 (method 3844450837) -- contract reverted at 75 (33) 03: f0176641 (method 6) -- contract reverted at 11291 (33) (RetCode=33)

The removal failure description:
So we are going:

• delete in curio.parked_piece_refs triggers -> TABLE "curio.pdp_piecerefs" CONSTRAINT "pdp_piecerefs_piece_ref_fkey" FOREIGN KEY (piece_ref) REFERENCES curio.parked_piece_refs(ref_id) ON DELETE CASCADE
• delete in curio.pdp_piecerefs triggers TABLE "curio.pdp_data_set_pieces" CONSTRAINT "pdp_proofset_roots_pdp_pieceref_fkey" FOREIGN KEY (pdp_pieceref) REFERENCES curio.pdp_piecerefs(id) ON DELETE SET NULL and TABLE "curio.pdp_data_set_piece_adds" CONSTRAINT "pdp_proofset_root_adds_pdp_pieceref_fkey" FOREIGN KEY (pdp_pieceref) REFERENCES curio.pdp_piecerefs(id) ON DELETE SET NULL
• in both of these tables pdp_pieceref is not null

This was also the last piece in that dataset, so I'm not certain what other consequences it might have, but it is causing initPP to fail due to an explicit check that was returning a non-specific error: #753

[Kubuxu]

But there seems to be another issue where some datasets ever get init_ready set to true (or fail init). I'm investigating.

[Kubuxu]

Performing normal create then add:

{"level":"info","ts":"2025-10-29T16:03:30.938+0100","logger":"harmonytask","caller":"harmonytask/task_type_handler.go:195","msg":"Beginning work on Task","id":90691,"from":"poller","name":"PDPInitPP","sector":null}
{"level":"error","ts":"2025-10-29T16:03:30.941+0100","logger":"harmonytask","caller":"harmonytask/task_type_handler.go:237","msg":"Do() returned error","type":"PDPInitPP","id":"90691","error":"data set 11 has no leaves","errorVerbose":"data set 11 has no leaves:\n    github.com/filecoin-project/curio/tasks/pdp.(*InitProvingPeriodTask).Do\n        /home/kubuxu/curio/tasks/pdp/task_init_pp.go:127"}
{"level":"info","ts":"2025-10-29T16:03:31.080+0100","logger":"harmonytask","caller":"harmonytask/task_type_handler.go:195","msg":"Beginning work on Task","id":90691,"from":"poller","name":"PDPInitPP","sector":null}
{"level":"error","ts":"2025-10-29T16:03:31.084+0100","logger":"harmonytask","caller":"harmonytask/task_type_handler.go:237","msg":"Do() returned error","type":"PDPInitPP","id":"90691","error":"data set 11 has no leaves","errorVerbose":"data set 11 has no leaves:\n    github.com/filecoin-project/curio/tasks/pdp.(*InitProvingPeriodTask).Do\n        /home/kubuxu/curio/tasks/pdp/task_init_pp.go:127"}
{"level":"info","ts":"2025-10-29T16:03:31.223+0100","logger":"harmonytask","caller":"harmonytask/task_type_handler.go:195","msg":"Beginning work on Task","id":90691,"from":"poller","name":"PDPInitPP","sector":null}
{"level":"error","ts":"2025-10-29T16:03:31.226+0100","logger":"harmonytask","caller":"harmonytask/task_type_handler.go:237","msg":"Do() returned error","type":"PDPInitPP","id":"90691","error":"data set 11 has no leaves","errorVerbose":"data set 11 has no leaves:\n    github.com/filecoin-project/curio/tasks/pdp.(*InitProvingPeriodTask).Do\n        /home/kubuxu/curio/tasks/pdp/task_init_pp.go:127"}
{"level":"info","ts":"2025-10-29T16:04:00.063+0100","logger":"curio/message","caller":"message/watch_eth.go:226","msg":"Updating transaction to confirmed","txHash":"0xab20645f975ecd766b24ed1bcd8234575a537a8ea9a7f36e1ad355c9c8832987","success":true,"blockNumber":"3147461","confirmations":"1"}
{"level":"info","ts":"2025-10-29T16:04:00.068+0100","logger":"curio/message","caller":"message/watch_eth.go:250","msg":"Successfully confirmed transaction","txHash":"0xab20645f975ecd766b24ed1bcd8234575a537a8ea9a7f36e1ad355c9c8832987"}
{"level":"info","ts":"2025-10-29T16:04:00.068+0100","logger":"curio/message","caller":"message/watch_eth.go:261","msg":"MessageWatcherEth update completed","confirmed":1,"stillPending":0,"waitingConfirmations":0,"errors":0,"total":1,"duration":0.009457389}
{"level":"info","ts":"2025-10-29T16:04:01.930+0100","logger":"harmonytask","caller":"harmonytask/task_type_handler.go:195","msg":"Beginning work on Task","id":90909,"from":"poller","name":"PDPInitPP","sector":null}
{"level":"info","ts":"2025-10-29T16:04:05.121+0100","logger":"harmonytask","caller":"harmonytask/task_type_handler.go:195","msg":"Beginning work on Task","id":90913,"from":"poller","name":"SendTransaction","sector":null}
{"level":"info","ts":"2025-10-29T16:04:05.496+0100","logger":"curio/message","caller":"message/sender_eth.go:405","msg":"sent transaction","hash":"0x7927a65c0e6aeb515e9e72c5520dd00e98b8ccdb230d81e3ec917c8fb574a3bf","task_id":90913,"send_error":null,"poll_loops":6}

PPInit seems to execute early, fails a few times and then catches itself.
The state seems correct after the fact.

[Kubuxu]

but create-and-add fails to enable initPP task for the dataset:

{"level":"info","ts":"2025-10-29T16:07:39.522+0100","logger":"pdp","caller":"pdp/handlers_create.go:108","msg":"PDP CreateDataSet: Inserting transaction tracking","txHash":"0xcfaff73dc8fc40c6148625cad5f049796a3b51240d1c3b708b39d668bb3d81e8","service":"public","recordKeeper":"0x02925630df557F957f70E112bA06e50965417CA0"}
{"level":"info","ts":"2025-10-29T16:07:39.525+0100","logger":"pdp","caller":"pdp/handlers_create.go:307","msg":"Successfully inserted transaction tracking records","txHash":"0xcfaff73dc8fc40c6148625cad5f049796a3b51240d1c3b708b39d668bb3d81e8","service":"public"}
{"level":"info","ts":"2025-10-29T16:07:42.698+0100","logger":"harmonytask","caller":"harmonytask/task_type_handler.go:195","msg":"Beginning work on Task","id":90790,"from":"poller","name":"PDPNotify","sector":null}
{"level":"info","ts":"2025-10-29T16:07:42.699+0100","logger":"pdp","caller":"pdp/notify_task.go:59","msg":"PDP notify","upload":{"id":"558aa4df-db30-428a-bd48-e107a2662fad","service":"public","piece_cid":"baga6ea4seaqey7t7krihcdnnrubbtd3ioczelvilpovlopeiv6fvnipwvsnkojq","notify_url":"","piece_ref":1001,"check_hash_codec":"sha2-256-trunc254-padded","check_hash":"TH5/VFBxDa2NAhmPaHCyRdULe6q3PIivi1ah9qyapyY="},"task_id":90790}
{"level":"info","ts":"2025-10-29T16:07:42.707+0100","logger":"pdp","caller":"pdp/notify_task.go:91","msg":"Successfully processed PDP notify task 90790 for upload ID 558aa4df-db30-428a-bd48-e107a2662fad"}
{"level":"info","ts":"2025-10-29T16:08:00.056+0100","logger":"curio/message","caller":"message/watch_eth.go:114","msg":"Assigned orphaned pending transactions","count":1,"machineID":1}
{"level":"info","ts":"2025-10-29T16:08:00.057+0100","logger":"curio/message","caller":"message/watch_eth.go:261","msg":"MessageWatcherEth update completed","confirmed":0,"stillPending":1,"waitingConfirmations":0,"errors":0,"total":1,"duration":0.000816902}
{"level":"info","ts":"2025-10-29T16:08:30.054+0100","logger":"curio/message","caller":"message/watch_eth.go:226","msg":"Updating transaction to confirmed","txHash":"0xcfaff73dc8fc40c6148625cad5f049796a3b51240d1c3b708b39d668bb3d81e8","success":true,"blockNumber":"3147470","confirmations":"1"}
{"level":"info","ts":"2025-10-29T16:08:30.061+0100","logger":"curio/message","caller":"message/watch_eth.go:250","msg":"Successfully confirmed transaction","txHash":"0xcfaff73dc8fc40c6148625cad5f049796a3b51240d1c3b708b39d668bb3d81e8"}
{"level":"info","ts":"2025-10-29T16:08:30.061+0100","logger":"curio/message","caller":"message/watch_eth.go:261","msg":"MessageWatcherEth update completed","confirmed":1,"stillPending":0,"waitingConfirmations":0,"errors":0,"total":1,"duration":0.01024353}
{"level":"info","ts":"2025-10-29T16:09:00.117+0100","logger":"pdp","caller":"pdp/proofset_create_watch.go:43","msg":"DataSetCreate watcher has pending data sets","count":1}
{"level":"info","ts":"2025-10-29T16:09:00.117+0100","logger":"pdp","caller":"pdp/proofset_create_watch.go:47","msg":"Processing data set create","txHash":"0xcfaff73dc8fc40c6148625cad5f049796a3b51240d1c3b708b39d668bb3d81e8","service":"public"}
{"level":"info","ts":"2025-10-29T16:09:00.118+0100","logger":"pdp","caller":"pdp/proofset_create_watch.go:88","msg":"Extracted dataSetId from receipt","txHash":"0xcfaff73dc8fc40c6148625cad5f049796a3b51240d1c3b708b39d668bb3d81e8","dataSetId":12}
{"level":"info","ts":"2025-10-29T16:09:00.134+0100","logger":"pdp","caller":"pdp/proofset_create_watch.go:55","msg":"Successfully processed data set create","txHash":"0xcfaff73dc8fc40c6148625cad5f049796a3b51240d1c3b708b39d668bb3d81e8"}
{"level":"info","ts":"2025-10-29T16:09:00.134+0100","logger":"pdp","caller":"pdp/proofset_addroot_watch.go:59","msg":"Processing piece add","dataSet":{"Int64":0,"Valid":false},"addMessageHash":"0xcfaff73dc8fc40c6148625cad5f049796a3b51240d1c3b708b39d668bb3d81e8"}

SELECT init_ready FROM curio.pdp_data_sets where id = 12
+------------+
| init_ready |
|------------|
| False      |
+------------+

[Kubuxu]

This makes sense as the dataset doesn't exist at the point in time when, in normal add flow, this is done.
It should resolve itself if I add another piece through a normal flow to this dataset.