Mocked sectorbuilder with 512Mib sector hangs on retrieval

[jsign]

This is a continuation of this problem.

I setup again the test showing the problem on v0.5.3. Now the deal can be made, which is nice, but the retrieval hangs. Looking at the logs there's an error:

2020-08-25T11:51:46.093-0300    WARN    graphsync_network       network/libp2p_impl.go:80       error resetting deadline: set pipe: deadline not supported
2020-08-25T11:51:46.097-0300    INFO    markets loggers/loggers.go:24   retrieval event {"name": "ClientEventBlocksReceived", "deal ID": "0", "state": "DealStatusOngoing", "message": ""}
2020-08-25T11:51:46.097-0300    WARN    graphsync_network       network/libp2p_impl.go:66       error setting deadline: set pipe: deadline not supported
2020-08-25T11:51:46.097-0300    INFO    markets loggers/loggers.go:29   retrieval event {"name": "ProviderEventBlockSent", "deal ID": "0", "receiver": "12D3KooWLBKfBterQPuw9rQLp5sGPK8MvDXetbPjcCbDE3vnHSMe", "state": "DealStatusOngoing", "message": ""}
2020-08-25T11:51:46.100-0300    WARN    graphsync_network       network/libp2p_impl.go:80       error resetting deadline: set pipe: deadline not supported
2020-08-25T11:51:46.104-0300    INFO    markets loggers/loggers.go:29   retrieval event {"name": "ProviderEventPaymentRequested", "deal ID": "0", "receiver": "12D3KooWLBKfBterQPuw9rQLp5sGPK8MvDXetbPjcCbDE3vnHSMe", "state": "DealStatusFundsNeeded", "message": ""}
2020-08-25T11:51:46.104-0300    INFO    markets loggers/loggers.go:24   retrieval event {"name": "ClientEventBlocksReceived", "deal ID": "0", "state": "DealStatusOngoing", "message": ""}
2020-08-25T11:51:46.104-0300    WARN    graphsync_network       network/libp2p_impl.go:66       error setting deadline: set pipe: deadline not supported
2020-08-25T11:51:46.106-0300    WARN    graphsync_network       network/libp2p_impl.go:80       error resetting deadline: set pipe: deadline not supported
2020-08-25T11:51:46.108-0300    INFO    markets loggers/loggers.go:24   retrieval event {"name": "ClientEventPaymentRequested", "deal ID": "0", "state": "DealStatusFundsNeeded", "message": ""}
2020-08-25T11:51:46.109-0300    INFO    markets loggers/loggers.go:24   retrieval event {"name": "ClientEventBlocksReceived", "deal ID": "0", "state": "DealStatusFundsNeeded", "message": ""}
2020-08-25T11:51:46.110-0300    INFO    markets loggers/loggers.go:24   retrieval event {"name": "ClientEventSendFunds", "deal ID": "0", "state": "DealStatusSendFunds", "message": ""}
2020-08-25T11:51:46.146-0300    WARN    data_transfer_network   network/libp2p_impl.go:66       error setting deadline: set pipe: deadline not supported
2020-08-25T11:51:46.147-0300    WARN    data_transfer_network   network/libp2p_impl.go:80       error resetting deadline: set pipe: deadline not supported
2020-08-25T11:51:46.147-0300    ERROR   fsm     fsm/fsm.go:92   Executing event planner failed: Invalid transition in queue, state `11`, event `15`:
    github.com/filecoin-project/go-statemachine/fsm.eventProcessor.Apply
        /Users/ignaciohagopian/go/pkg/mod/github.com/filecoin-project/go-statemachine@v0.0.0-20200813232949-df9b130df370/fsm/eventprocessor.go:137
2020-08-25T11:51:46.167-0300    WARN    paych   paychmgr/paych.go:244   AddVoucher: voucher re-added with matching proof
2020-08-25T11:51:46.167-0300    INFO    markets loggers/loggers.go:24   retrieval event {"name": "ClientEventPaymentSent", "deal ID": "0", "state": "DealStatusOngoing", "message": ""}
2020-08-25T11:51:46.167-0300    INFO    markets loggers/loggers.go:29   retrieval event {"name": "ProviderEventPaymentReceived", "deal ID": "0", "receiver": "12D3KooWLBKfBterQPuw9rQLp5sGPK8MvDXetbPjcCbDE3vnHSMe", "state": "DealStatusOngoing", "message": ""}
2020-08-25T11:51:46.168-0300    WARN    graphsync_network       network/libp2p_impl.go:66       error setting deadline: set pipe: deadline not supported
2020-08-25T11:51:46.168-0300    WARN    graphsync_network       network/libp2p_impl.go:80       error resetting deadline: set pipe: deadline not supported
2020-08-25T11:51:46.168-0300    INFO    markets loggers/loggers.go:29   retrieval event {"name": "ProviderEventBlocksCompleted", "deal ID": "0", "receiver": "12D3KooWLBKfBterQPuw9rQLp5sGPK8MvDXetbPjcCbDE3vnHSMe", "state": "DealStatusBlocksComplete", "message": ""}
2020-08-25T11:51:46.168-0300    INFO    markets loggers/loggers.go:29   retrieval event {"name": "ProviderEventPaymentRequested", "deal ID": "0", "receiver": "12D3KooWLBKfBterQPuw9rQLp5sGPK8MvDXetbPjcCbDE3vnHSMe", "state": "DealStatusFundsNeededLastPayment", "message": ""}
2020-08-25T11:51:46.168-0300    WARN    data_transfer_network   network/libp2p_impl.go:66       error setting deadline: set pipe: deadline not supported
2020-08-25T11:51:46.168-0300    WARN    data_transfer_network   network/libp2p_impl.go:80       error resetting deadline: set pipe: deadline not supported
2020-08-25T11:51:46.169-0300    INFO    markets loggers/loggers.go:24   retrieval event {"name": "ClientEventLastPaymentRequested", "deal ID": "0", "state": "DealStatusFundsNeededLastPayment", "message": ""}

To reproduce:

• Checkout this
• Run go test ./node -run TestAPIDealFlow$/TestDealFlow -v

cc @arajasek @hannahhoward

[hannahhoward]

Follow-up:

Good news and bad news.

Good news for @jsign is if you change your data size in makedeal from 10x1024x1024 to 11x1024x1024 it will work. That should give you a quick workaround so you can use the 512MB mock sector builder.

Bad news for all is the bug here is quite unfortunate. In retrieval deals, you have a payment interval, and a set increase to that inverval as payments are made. Normally since we deal with data in irregular block sizes and over all data size, we assume that the last payment will always be a "left over" -- i.e. something less than overall payment interval. However, if you happen to hit the exact boundary of a payment interval on the last block in your data, it appears we are failing.

The reason the data size change fixes it is the default payment interval & payment interval increase for a retrieval provider, left unchanged is 1024x1024. (i.e. 1MB)

So in this setup the payment intervals are:
1MB
2MB (1MB + 1MB)
3MB (2MB + 1MB)
4MB (3MB + 1MB)

---

= payment at 10MB the total data size.

Eek. Am working on more permaneant fix.

[hannahhoward]

So it's clear, the failure has nothing to do with the change in the sector builder size, only that the new data size you set happened to reveal a new bug.

[hannahhoward]

FYI: filecoin-project/go-fil-markets#388 -- actual fix incoming when it makes it through the chain

[jsign]

So it's clear, the failure has nothing to do with the change in the sector builder size, only that the new data size you set happened to reveal a new bug.

Oh, I see. I tried with 15MiB and it failed as expected (considering your logic). With 14MiB or 16Mib works correctly.

Thanks for taking a look, happy we caught this one.

[jsign]

This was solved in v0.5.10.