[BUG] Retrieval deal fails with "deal data transfer failed: incomplete response" - Client Side #5829

ethanwu155 · 2021-03-17T07:30:11Z

Describe the bug
Client cannot get stored file on FileCoin from miner. Stored file has StorageDealActive Status.

Version (run lotus version):
lotus version 1.5.0+mainnet+git.191a05da4

To Reproduce
Steps to reproduce the behavior:

Run lotus client retrieve --miner <minerID> <data CID> <output file>
Get the following error:

ERROR: retrieval failed: Retrieve: Retrieval Error: error generated by data transfer: deal │ data transfer failed: incomplete response

Expected behavior
Expect to be able to retrieve stored file.

Logs

$ lotus client retrieve --miner f066596 bafyaa6qsgafcmalqudsaeiekkmiypfxq6vgdwepdafg6jyacye46gurjichuapbzxwqhoywq7yjaagelucbyabasgafcmalqudsaeif3e6tsyc7c3anlmobix3744duq7cyasjsmrsmbkdn4besizu5ffyjaagf6zcc36aykcqeaeghh3sbl6bzaqcaibaaeedt5zav7am output.mp4                                                                                       
> Recv: 0 B, Paid 0 FIL, ClientEventOpen (DealStatusNew)                                  
> Recv: 0 B, Paid 0 FIL, ClientEventDealProposed (DealStatusWaitForAcceptance)            
> Recv: 122 B, Paid 0 FIL, ClientEventBlocksReceived (DealStatusWaitForAcceptance)        
> Recv: 122 B, Paid 0 FIL, ClientEventDealAccepted (DealStatusAccepted)                   
> Recv: 122 B, Paid 0 FIL, ClientEventPaymentChannelAddingFunds (DealStatusPaymentChannelAllocatingLane)                                                                            
> Recv: 122 B, Paid 0 FIL, ClientEventLaneAllocated (DealStatusOngoing)                   
> Recv: 122 B, Paid 0 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

Screenshots
See attachment

Additional context
None

The text was updated successfully, but these errors were encountered:

kernelogic · 2021-03-17T19:13:02Z

This is caused by two things:
#5821
#5409

The miner you tested have set unseal price to be non-zero. So it just go back to non-fast-retrieval, and unsealing failed.

flyworker · 2021-03-17T19:36:17Z

we tested both on 1.5.0 and 1.5.3 both have similar issue.

bq1024 · 2021-03-17T19:54:19Z

This is caused by two things:
#5821
#5409

The miner you tested have set unseal price to be non-zero. So it just go back to non-fast-retrieval, and unsealing failed.

We have set unseal price to zero but failed.

bq1024 · 2021-03-17T19:59:26Z

We have exactly the same issue.

Client Side:

$ lotus client retrieve  --miner f019104 --pieceCid=baga6ea4seaqn6mlouekcaghi574xvkshq4kdkk57yboy5focxatabfio4iytwii mAXCg5AIgcSJzsW/ogYWKQQaYZruCwaGaqGmWMSNKDOKbR3W5x5s test-retrieval
> 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: 0 B, Paid 0 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

Miner Side:

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"}

pooja · 2021-03-18T18:55:02Z

Some related miner logs:

ethanwu155 · 2021-03-19T13:34:01Z

I upgraded lotus to 1.5.3rc and tried to run the retrieval again and the result is the same.

Daemon Logs:

dirkmc · 2021-03-22T09:26:26Z

It seems that the error is getting lost somewhere in the unsealing code.
First step is to have better error logging on unseal failure: #5851

dirkmc · 2021-03-22T09:33:00Z

We need to bubble up the fix for a better message than "incomplete response" from filecoin-project/go-data-transfer#145
I made a release of go-data-transfer with this fix in v1.2.9: filecoin-project/go-data-transfer#167

dirkmc · 2021-03-22T09:46:28Z

In go-fil-markets close the reader after unsealing completes, and check the result of the close to see if it returns an error: filecoin-project/go-fil-markets#507

dirkmc · 2021-03-22T10:53:36Z

Release markets v1.2.0: filecoin-project/go-fil-markets#509
Next we need to bubble up to lotus and test out the release manually: #5853

pooja · 2021-03-22T16:36:50Z

Hey team, adding a couple other details:

The storage deal was made with an offline data transfer
The miner was storing an unsealed copy of the data. Not sure if an unseal was triggered. Have asked the team to chime in here!

kernelogic · 2021-03-22T16:55:37Z

@dirkmc it's pretty easy to reproduce - let me know if there's a release that can be tested with I'll be happy to do it.

dirkmc · 2021-03-22T17:14:10Z

Thanks, that would be great - we're testing out the release and once it's ready we'd love for you to test it.
I'm not sure that the change I've made will fix the bug, as it may be on the unsealing side. But it should at least give more information in the logs.

jamerduhgamer · 2021-03-22T22:20:23Z

Looks like unsealing did occur even though we had an unsealed copy of the data. Pictures of the log from the miner below.

jamerduhgamer · 2021-03-22T23:45:37Z

This is the corresponding journal entry for the retrieval deal above.
Lotus Journal for DealID 4.txt

jennijuju · 2021-03-24T21:39:40Z

assigned as blocked b/c according to #5829 (comment) May be fixed the new market release

kernelogic · 2021-03-29T06:45:29Z

@f8-ptrk stored a deal from me with fast-retrieval, he also set the unsealing price to 1 FIL.
When I do the retrieval with him, guess what, it immediately failed with the "incomplete response" message and he obtained 1 FIL from me.

@dirkmc if you think it is just a confusing message, no unsealing happened, I don't know how to explain the fee then

lotus client retrieve --miner f062353 bafykbzacebcilfo3sfu4o6re5lz7zh66xdz6la74nmp7y7idcofeysuvnb7p2 /mnt/ipfs/CC-MAIN-2018-47-index.tar.05

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 FIL, ClientEventVoucherShortfall (DealStatusCheckFunds)
Recv: 0 B, Paid 0 FIL, ClientEventPaymentChannelAddingFunds (DealStatusPaymentChannelAddingFunds)
Recv: 0 B, Paid 0 FIL, ClientEventPaymentChannelReady (DealStatusOngoing)
Recv: 0 B, Paid 0 FIL, ClientEventPaymentRequested (DealStatusFundsNeeded)
Recv: 0 B, Paid 0 FIL, ClientEventSendFunds (DealStatusSendFunds)
Recv: 0 B, Paid 1 FIL, ClientEventPaymentSent (DealStatusOngoing)
Recv: 0 B, Paid 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

https://filfox.info/en/message/bafy2bzaced7csrimf3r5kds6cmz3zw6o5pdaal6qw6gxtpa5bnhhktdimwerw

kernelogic · 2021-03-30T06:19:20Z

Re-tested retrieval on my own miner for both unseal price is zero (successful) and non-zero (failed). In the log there's some weirdness about unsealing (shouldn't even happen, deal is fast-retreival), also some weirdness about cancel-transfer saying channel not found.

lotus -v
lotus version 1.5.3+mainnet+git.358773e2b

unsealprice_nonzero_failure.txt
unsealprice_zero_success.txt

dirkmc · 2021-03-31T15:25:41Z

Likely root cause: filecoin-project/go-fil-markets#528

ethanwu155 added hint/needs-triaging kind/bug Kind: Bug labels Mar 17, 2021

dirkmc mentioned this issue Mar 22, 2021

better logging when unsealing fails #5851

Merged

dirkmc mentioned this issue Mar 22, 2021

close the reader after unsealing into blockstore filecoin-project/go-fil-markets#507

Merged

jennijuju removed the hint/needs-triaging label Mar 22, 2021

jennijuju added the status/blocked label Mar 24, 2021

dirkmc mentioned this issue Mar 25, 2021

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

Closed

This was referenced Mar 31, 2021

Create integration tests for retrieval with > 0 unseal price filecoin-project/go-fil-markets#527

Closed

When retrieval unsealing price > 0, provider tries to start sending blocks before unsealing is complete filecoin-project/go-fil-markets#528

Closed

dirkmc mentioned this issue Mar 31, 2021

Retrieval deal fails with "deal data transfer failed: incomplete response" - miner side view #5530

Closed

dirkmc mentioned this issue Apr 2, 2021

Update to go-fil-markets-v1.2.5 #5941

Merged

12 tasks

jennijuju mentioned this issue Apr 6, 2021

[Deal Making Issue] Retrieval Deals Error: deal data transfer failed: incomplete response #5954

Closed

pooja mentioned this issue Apr 6, 2021

[Deal Making Issue] #5980

Closed

magik6k closed this as completed in #5941 Apr 9, 2021

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[BUG] Retrieval deal fails with "deal data transfer failed: incomplete response" - Client Side #5829

[BUG] Retrieval deal fails with "deal data transfer failed: incomplete response" - Client Side #5829

ethanwu155 commented Mar 17, 2021

kernelogic commented Mar 17, 2021

flyworker commented Mar 17, 2021

bq1024 commented Mar 17, 2021

bq1024 commented Mar 17, 2021

pooja commented Mar 18, 2021

ethanwu155 commented Mar 19, 2021 •

edited

Loading

dirkmc commented Mar 22, 2021

dirkmc commented Mar 22, 2021 •

edited

Loading

dirkmc commented Mar 22, 2021

dirkmc commented Mar 22, 2021 •

edited

Loading

pooja commented Mar 22, 2021

kernelogic commented Mar 22, 2021

dirkmc commented Mar 22, 2021

jamerduhgamer commented Mar 22, 2021

jamerduhgamer commented Mar 22, 2021

jennijuju commented Mar 24, 2021

kernelogic commented Mar 29, 2021

kernelogic commented Mar 30, 2021

dirkmc commented Mar 31, 2021

[BUG] Retrieval deal fails with "deal data transfer failed: incomplete response" - Client Side #5829

[BUG] Retrieval deal fails with "deal data transfer failed: incomplete response" - Client Side #5829

Comments

ethanwu155 commented Mar 17, 2021

kernelogic commented Mar 17, 2021

flyworker commented Mar 17, 2021

bq1024 commented Mar 17, 2021

bq1024 commented Mar 17, 2021

pooja commented Mar 18, 2021

ethanwu155 commented Mar 19, 2021 • edited Loading

dirkmc commented Mar 22, 2021

dirkmc commented Mar 22, 2021 • edited Loading

dirkmc commented Mar 22, 2021

dirkmc commented Mar 22, 2021 • edited Loading

pooja commented Mar 22, 2021

kernelogic commented Mar 22, 2021

dirkmc commented Mar 22, 2021

jamerduhgamer commented Mar 22, 2021

jamerduhgamer commented Mar 22, 2021

jennijuju commented Mar 24, 2021

kernelogic commented Mar 29, 2021

kernelogic commented Mar 30, 2021

dirkmc commented Mar 31, 2021

ethanwu155 commented Mar 19, 2021 •

edited

Loading

dirkmc commented Mar 22, 2021 •

edited

Loading

dirkmc commented Mar 22, 2021 •

edited

Loading