[BUG] Unsealing is always needed if miner has set the unsealing price to non-zero

[xinaxu]

Describe the bug
Unsealing is always needed if the miner has set the unseal price to non-zero.
This happens even when fast-retrieval is enabled and the miner keeps the unsealed copy.

Version (run lotus version):
1.5.0+mainnet+git.55b85f314.dirty+api1.1.0

To Reproduce
Steps to reproduce the behavior:

1. Set your miner with unseal price 0.1
2. Make a storage deal with default parameter (which enables fast retrieval)
3. Make a retrieval deal with default parameter
4. The miner will ask for unsealing and the unsealing will fail due to this bug Cannot perform any retrieval for 32GB files #5409

Expected behavior
Unseal should not be needed and the retrieval should succeed

Logs
When the unseal price is set to 0.1

> Recv: 0 B, Paid 0 FIL, ClientEventOpen (DealStatusNew)
> Recv: 0 B, Paid 0 FIL, ClientEventDealProposed (DealStatusWaitForAcceptance)
> Recv: 0 B, Paid 0 FIL, ClientEventUnsealPaymentRequested (DealStatusAccepted)
> Recv: 0 B, Paid 0 FIL, ClientEventPaymentChannelAddingFunds (DealStatusPaymentChannelAllocatingLane)
> Recv: 0 B, Paid 0 FIL, ClientEventLaneAllocated (DealStatusOngoing)
> Recv: 0 B, Paid 0 FIL, ClientEventPaymentRequested (DealStatusFundsNeeded)
> Recv: 0 B, Paid 0 FIL, ClientEventSendFunds (DealStatusSendFunds)
> Recv: 0 B, Paid 0.1 FIL, ClientEventPaymentSent (DealStatusOngoing)
> Recv: 0 B, Paid 0.1 FIL, ClientEventDataTransferError (DealStatusErrored)
> Recv: 0 B, Paid 0 FIL, ClientEventOpen (DealStatusNew)
ERROR: retrieval failed: Retrieve: Retrieval Error: error generated by data transfer: deal data transfer failed: incomplete response

When the unseal price is set to 0

> Recv: 0 B, Paid 0 FIL, ClientEventOpen (DealStatusNew)
> Recv: 0 B, Paid 0 FIL, ClientEventDealProposed (DealStatusWaitForAcceptance)
> Recv: 0 B, Paid 0 FIL, ClientEventDealAccepted (DealStatusAccepted)
> Recv: 0 B, Paid 0 FIL, ClientEventPaymentChannelAddingFunds (DealStatusPaymentChannelAllocatingLane)
> Recv: 0 B, Paid 0 FIL, ClientEventLaneAllocated (DealStatusOngoing)
> Recv: 1.049 KiB, Paid 0 FIL, ClientEventBlocksReceived (DealStatusOngoing)
> Recv: 53.06 KiB, Paid 0 FIL, ClientEventBlocksReceived (DealStatusOngoing)
> Recv: 53.06 KiB, Paid 0 FIL, ClientEventPaymentRequested (DealStatusFundsNeeded)
> Recv: 1.052 MiB, Paid 0 FIL, ClientEventBlocksReceived (DealStatusFundsNeeded)
> Recv: 1.052 MiB, Paid 0 FIL, ClientEventSendFunds (DealStatusSendFunds)
> Recv: 1.052 MiB, Paid 0.000010271639671525 FIL, ClientEventPaymentSent (DealStatusOngoing)
> Recv: 2.052 MiB, Paid 0.000010271639671525 FIL, ClientEventBlocksReceived (DealStatusOngoing)

[arajasek]

@xinaxu Thanks for the issue! Were you running the miner for this retrieval effort too? If so, can you please share the deal logs from the provider side too?

[xinaxu]

Mar 16 05:59:59 lotus lotus-miner[1071729]: 2021-03-16T05:59:59.306Z        INFO        dt-impl        impl/events.go:338        received new channel request from 12D3KooWJesyZarYF6WQiSPNUvbfEvjKGpaLs4kPCH8HsMPPyZxp
Mar 16 05:59:59 lotus lotus-miner[1071729]: 2021-03-16T05:59:59.675Z        INFO        markets        loggers/loggers.go:30        retrieval provider event        {"name": "ProviderEventPaymentRequested", "deal ID": "8", "receiver": "12D3KooWJesyZarYF6WQiSPNUvbfEvjKGpaLs4kPCH8HsMPPyZxp", "state": "DealStatusFundsNeededUnseal", "message": ""}
Mar 16 06:00:00 lotus lotus-miner[1071729]: 2021-03-16T06:00:00.402Z        INFO        markets        loggers/loggers.go:30        retrieval provider event        {"name": "ProviderEventDealAccepted", "deal ID": "8", "receiver": "12D3KooWJesyZarYF6WQiSPNUvbfEvjKGpaLs4kPCH8HsMPPyZxp", "state": "DealStatusFundsNeededUnseal", "message": ""}
Mar 16 06:03:30 lotus lotus-miner[1071729]: 2021-03-16T06:03:30.591Z        INFO        markets        loggers/loggers.go:30        retrieval provider event        {"name": "ProviderEventPaymentReceived", "deal ID": "8", "receiver": "12D3KooWJesyZarYF6WQiSPNUvbfEvjKGpaLs4kPCH8HsMPPyZxp", "state": "DealStatusUnsealing", "message": ""}
Mar 16 06:07:37 lotus lotus-miner[1071729]: 2021-03-16T06:07:37.311Z        INFO        dt-impl        impl/events.go:338        received new channel request from 12D3KooWJesyZarYF6WQiSPNUvbfEvjKGpaLs4kPCH8HsMPPyZxp
Mar 16 06:07:37 lotus lotus-miner[1071729]: 2021-03-16T06:07:37.807Z        INFO        markets        loggers/loggers.go:30        retrieval provider event        {"name": "ProviderEventPaymentRequested", "deal ID": "9", "receiver": "12D3KooWJesyZarYF6WQiSPNUvbfEvjKGpaLs4kPCH8HsMPPyZxp", "state": "DealStatusFundsNeededUnseal", "message": ""}
Mar 16 06:07:38 lotus lotus-miner[1071729]: 2021-03-16T06:07:38.761Z        INFO        markets        loggers/loggers.go:30        retrieval provider event        {"name": "ProviderEventDealAccepted", "deal ID": "9", "receiver": "12D3KooWJesyZarYF6WQiSPNUvbfEvjKGpaLs4kPCH8HsMPPyZxp", "state": "DealStatusFundsNeededUnseal", "message": ""}
Mar 16 06:07:56 lotus lotus-miner[1071729]: 2021-03-16T06:07:56.124Z        INFO        markets        loggers/loggers.go:30        retrieval provider event        {"name": "ProviderEventPaymentReceived", "deal ID": "9", "receiver": "12D3KooWJesyZarYF6WQiSPNUvbfEvjKGpaLs4kPCH8HsMPPyZxp", "state": "DealStatusUnsealing", "message": ""}
Mar 16 06:16:17 lotus lotus-miner[1071729]: 2021-03-16T06:16:17.738Z        INFO        markets        loggers/loggers.go:30        retrieval provider event        {"name": "ProviderEventDataTransferError", "deal ID": "8", "receiver": "12D3KooWJesyZarYF6WQiSPNUvbfEvjKGpaLs4kPCH8HsMPPyZxp", "state": "DealStatusErrored", "message": "deal data transfer failed: incomplete response"}
Mar 16 06:20:56 lotus lotus-miner[1071729]: 2021-03-16T06:20:56.814Z        INFO        markets        loggers/loggers.go:30        retrieval provider event        {"name": "ProviderEventDataTransferError", "deal ID": "9", "receiver": "12D3KooWJesyZarYF6WQiSPNUvbfEvjKGpaLs4kPCH8HsMPPyZxp", "state": "DealStatusErrored", "message": "deal data transfer failed: incomplete response"}
Mar 16 06:24:16 lotus lotus-miner[1071729]: 2021-03-16T06:24:16.167Z        INFO        dt-impl        impl/events.go:338        received new channel request from 12D3KooWJesyZarYF6WQiSPNUvbfEvjKGpaLs4kPCH8HsMPPyZxp
Mar 16 06:24:16 lotus lotus-miner[1071729]: 2021-03-16T06:24:16.554Z        INFO        markets        loggers/loggers.go:30        retrieval provider event        {"name": "ProviderEventPaymentRequested", "deal ID": "12", "receiver": "12D3KooWJesyZarYF6WQiSPNUvbfEvjKGpaLs4kPCH8HsMPPyZxp", "state": "DealStatusFundsNeededUnseal", "message": ""}
Mar 16 06:24:17 lotus lotus-miner[1071729]: 2021-03-16T06:24:17.802Z        INFO        markets        loggers/loggers.go:30        retrieval provider event        {"name": "ProviderEventDealAccepted", "deal ID": "12", "receiver": "12D3KooWJesyZarYF6WQiSPNUvbfEvjKGpaLs4kPCH8HsMPPyZxp", "state": "DealStatusFundsNeededUnseal", "message": ""}
Mar 16 06:24:19 lotus lotus-miner[1071729]: 2021-03-16T06:24:19.390Z        INFO        markets        loggers/loggers.go:30        retrieval provider event        {"name": "ProviderEventDataTransferError", "deal ID": "12", "receiver": "12D3KooWJesyZarYF6WQiSPNUvbfEvjKGpaLs4kPCH8HsMPPyZxp", "state": "DealStatusErrored", "message": "deal data transfer failed: incomplete response"}
Mar 16 06:24:58 lotus lotus-miner[1071729]: 2021-03-16T06:24:58.278Z        INFO        dt-impl        impl/events.go:338        received new channel request from 12D3KooWJesyZarYF6WQiSPNUvbfEvjKGpaLs4kPCH8HsMPPyZxp
Mar 16 06:24:58 lotus lotus-miner[1071729]: 2021-03-16T06:24:58.635Z        INFO        markets        loggers/loggers.go:30        retrieval provider event        {"name": "ProviderEventPaymentRequested", "deal ID": "13", "receiver": "12D3KooWJesyZarYF6WQiSPNUvbfEvjKGpaLs4kPCH8HsMPPyZxp", "state": "DealStatusFundsNeededUnseal", "message": ""}
Mar 16 06:24:59 lotus lotus-miner[1071729]: 2021-03-16T06:24:59.768Z        INFO        markets        loggers/loggers.go:30        retrieval provider event        {"name": "ProviderEventDealAccepted", "deal ID": "13", "receiver": "12D3KooWJesyZarYF6WQiSPNUvbfEvjKGpaLs4kPCH8HsMPPyZxp", "state": "DealStatusFundsNeededUnseal", "message": ""}
Mar 16 06:26:14 lotus lotus-miner[1071729]: 2021-03-16T06:26:14.064Z        INFO        dt-impl        impl/events.go:338        received new channel request from 12D3KooWJesyZarYF6WQiSPNUvbfEvjKGpaLs4kPCH8HsMPPyZxp
Mar 16 06:26:14 lotus lotus-miner[1071729]: 2021-03-16T06:26:14.084Z        INFO        markets        loggers/loggers.go:30        retrieval provider event        {"name": "ProviderEventOpen", "deal ID": "14", "receiver": "12D3KooWJesyZarYF6WQiSPNUvbfEvjKGpaLs4kPCH8HsMPPyZxp", "state": "DealStatusNew", "message": ""}
Mar 16 06:26:14 lotus lotus-miner[1071729]: 2021-03-16T06:26:14.134Z        INFO        markets        loggers/loggers.go:30        retrieval provider event        {"name": "ProviderEventDealAccepted", "deal ID": "14", "receiver": "12D3KooWJesyZarYF6WQiSPNUvbfEvjKGpaLs4kPCH8HsMPPyZxp", "state": "DealStatusUnsealing", "message": ""}

While the client is waiting, I can see jobs of type "RD" from lotus-miner sealing jobs
@arajasek if you need more detailed log, let me know how to turn them on.

[flyworker]

with 1.5.3

Mar 17 17:38:36 miner4 lotus-miner[14143]: 2021-03-17T17:38:36.041Z INFO markets loggers/loggers.go:30 retrieval provider event {"name": "ProviderEventOpen", "deal ID": "15", "receiver": "12D3KooWLb3vya3V3ZU39jZRfVsTEY6KB93czht8AdVAF3pMCgqA", "state": "DealStatusNew", "message": ""}
Mar 17 17:38:36 miner4 lotus-miner[14143]: 2021-03-17T17:38:36.069Z INFO markets loggers/loggers.go:30 retrieval provider event {"name": "ProviderEventDealAccepted", "deal ID": "15", "receiver": "12D3KooWLb3vya3V3ZU39jZRfVsTEY6KB93czht8AdVAF3pMCgqA", "state": "DealStatusUnsealing", "message": ""}
Mar 17 17:40:34 miner4 lotus-miner[14143]: 2021-03-17T17:40:34.586Z INFO markets loggers/loggers.go:30 retrieval provider event {"name": "ProviderEventUnsealComplete", "deal ID": "15", "receiver": "12D3KooWLb3vya3V3ZU39jZRfVsTEY6KB93czht8AdVAF3pMCgqA", "state": "DealStatusUnsealed", "message": ""}
Mar 17 17:40:34 miner4 lotus-miner[14143]: 2021-03-17T17:40:34.597Z INFO dt-impl impl/impl.go:370 resume channel 12D3KooWLb3vya3V3ZU39jZRfVsTEY6KB93czht8AdVAF3pMCgqA-12D3KooWH5PDdPxQsPSegABD8FUkSvcg7czGYWwWsj666aEAhyDx-15
Mar 17 17:40:34 miner4 lotus-miner[14143]: 2021-03-17T17:40:34.598Z INFO graphsync responsemanager/responsemanager.go:481 response failed: %!w(traversal.SkipMe={})
Mar 17 17:40:34 miner4 lotus-miner[14143]: 2021-03-17T17:40:34.608Z INFO markets loggers/loggers.go:30 retrieval provider event {"name": "ProviderEventDataTransferError", "deal ID": "15", "receiver": "12D3KooWLb3vya3V3ZU39jZRfVsTEY6KB93czht8AdVAF3pMCgqA", "state": "DealStatusErrored", "message": "deal data transfer failed: incomplete response"}

[dirkmc]

Closing as it seems this has the same root cause as #5829: The underlying issue is the error deal data transfer failed: incomplete response

Note that the names of the states here are a little confusing: DealStatusUnsealing means that the data for the deal is being retrieved from a sector and put into the blockstore.
If the sector has not yet been unsealed, it will be unsealed, which takes some time.
If the sector has already been unsealed it won't be unsealed a second time.

Looking at the logs that @flyworker posted, the time between DealStatusUnsealing and DealStatusUnsealed is only 2 seconds, so I don't think it unsealed a sector, most likely the data was already available on disk.