Retrievals hang at stage 'PaymentChannelSkip (Ongoing)'

[jacobheun]

@jcace reported this issue in #boost-help in filecoin slack.

Summary

Retrieval attempts to Boost leveraging lotus client retrieve will sometimes hang indefinitely or until the client times out. This may require a restart of the process to get it unstuck, but the issue can recur after restarts.

Initial reported versions:

lotus version 1.19.0+mainnet+git.64059ca87.dirty
boostd version 1.5.0+git.dbedffb

Issue is still being seen on 1.5.1-rc3

Note from the user

I have a very strange retrieval issue. Consider these two different retrieval commands:
a) lotus client retrieve --provider f01963614 QmfB9Sz8UYnTd8o8BVHrmGcrRcqDgu8jM8vFXUnFsTGbGE --car
b) lotus client retrieve --provider f01886797 QmaQpw28KgCjS8PRCDwSmn5jaoScYN4RYpqWxERtmqEsnE --car
a) works perfect, transfer starts right away, but b) just hangs at PaymentChannelSkip (Ongoing) and never progresses.
It will eventually time out.

What’s strange about this is I control both SP nodes. In fact, they are both physically
running on the same hardware. They are on the same internet connection.
They are storing files on the same physical disks.

Both CIDs are in a sector with an unsealed copy, and I’ve verified that it exists.
The only difference is that node b) currently has all my sealing workers connected
to it, whereas node a) does not - thus, unsealing is not possible. However, looking into the code
it would seem that the IsUnsealed
function should be able to find the sector just fine. The lotus-miner instance has the storage directly attached to it in both instances.

Boost/Miner configs between the two nodes are almost identical - did not modify anything to do with retrievals.
What could possibly cause this?

References:

• https://filecoinproject.slack.com/archives/C03CKDLEWG1/p1673319661213899
• https://filecoinproject.slack.com/archives/C03CKDLEWG1/p1673040967787369

Related #846
Related #1132

[jcace]

Thanks for creating this issue @jacobheun !!

[davidd8]

Triaging to the Tornado team ( @hannahhoward ) to prioritize and help debug this issue. This is a good cross-team bug as @jacobheun has been able to replicate some of the behavior in #1132. Once ready to investigate, let's loop in folks from Boost and Tornado to pair on it.

What's less clear to me is how many SPs are experiencing this issue, so let's keep an eye on that.

[jcace]

let me know if you need any troubleshooting/logging from my side, happy to help as I still have this issue in the wild now 👍

[jacobheun]

Adding another data point here, we had a similar report where retrievals were hanging, after shutting down boostd to restart deals the process logged the following:

"level":"info","ts":"2023-02-02T21:36:33.343-0800","logger":"dagstore","caller":"dagstore@v0.5.7/handlers.go:59","msg":"failure handler: stopping"}
{"level":"info","ts":"2023-02-02T21:36:33.345-0800","logger":"boost-provider","caller":"storagemarket/provider.go:497","msg":"storage provider: shutdown"}
{"level":"info","ts":"2023-02-02T21:36:33.867-0800","logger":"boost-provider","caller":"storagemarket/provider.go:509","msg":"storage provider: stop run loop"}
{"level":"info","ts":"2023-02-02T21:36:33.867-0800","logger":"boost-provider","caller":"storagemarket/provider_loop.go:370","msg":"provider run loop: complete"}
{"level":"info","ts":"2023-02-02T21:36:33.867-0800","logger":"boost-provider","caller":"storagemarket/provider.go:512","msg":"storage provider: shutdown complete"}
{"level":"info","ts":"2023-02-02T21:36:33.867-0800","logger":"modules","caller":"modules/retrieval.go:195","msg":"stopping libp2p protocol proxy"}
{"level":"info","ts":"2023-02-02T21:36:33.901-0800","logger":"dagstore","caller":"dagstore/wrapper.go:452","msg":"will close the dagstore"}
{"level":"info","ts":"2023-02-02T21:36:33.901-0800","logger":"dagstore","caller":"dagstore@v0.5.7/dagstore_control.go:50","msg":"dagstore closed"}
{"level":"info","ts":"2023-02-02T21:36:33.901-0800","logger":"dagstore","caller":"dagstore/wrapper.go:456","msg":"dagstore closed"}
{"level":"info","ts":"2023-02-02T21:36:33.901-0800","logger":"dagstore","caller":"dagstore/wrapper.go:459","msg":"waiting for dagstore background wrapper goroutines to exit"}
{"level":"info","ts":"2023-02-02T21:36:33.901-0800","logger":"dagstore","caller":"dagstore/wrapper.go:461","msg":"exited dagstore background wrapper goroutines"}
{"level":"error","ts":"2023-02-02T21:36:38.908-0800","logger":"dt_graphsync","caller":"graphsync/graphsync.go:866","msg":"failed to fire transport receive error stream reset: normal shutdown of state machine"}
{"level":"error","ts":"2023-02-02T21:36:38.908-0800","logger":"dt_graphsync","caller":"graphsync/graphsync.go:866","msg":"failed to fire transport receive error stream reset: normal shutdown of state machine"}
# The previous 2 lines occur 60 times
{"level":"error","ts":"2023-02-02T21:36:38.944-0800","logger":"builder","caller":"node/shutdown.go:41","msg":"shutting down boost failed: couldnt stop datatransfer.Manager in 5 seconds. forcing an App.Stop"}

Boost version: 1.5.1.rc4

Ref: filecoin slack

[hannahhoward]

hanging at PaymentChannelSkip is what will happen in Lotus client when the server side issue mentioned above by @jacobheun occurs. (#1125 (comment))

In Lassie, the same issue is a timeout on the client side. (which does send a correct cancel message, as opposed to Ctrl-C which @jacobheun correctly points out fails to get handled -- we will need to fix)

Re: the underlyng server issue, I have always said "must be sealed sectors" but I think the real culprit here is some kind of lock on the sealer getting stuck even for an unsealed sector. When the data transfer status is stuck in PauseResponder, that means from a retrieval standpoint we're waiting for the sealer to respond. To me, the fact that node B with all the sealers running is the stuck one is the tell. This also corresponds with results we got under high concurrency in HTTP load testing (@jacobhuen reach out to me for more information)

[jacobheun]

Casey has reported again that bitswap and http retrievals continue to function, so the stall is isolated to the graphsync retrieval code path.

Additionally, attempting to cancel the transfer boostd data-transfers cancel <id> hangs.

[web3-providers]

I do have a similar problem with boostd and was advised by @LexLuthr to comment here

It was running smooth for a while ( we have even moved to 1st place in the retrieval competition for 5 weeks ), but then it started to fail
After restart it goes as usual, starts serving retrieval deals, and at some point it starts failing and not serving more retrievals
We were running 1.5.11-rcsomething, and upgraded to 1.5.12

Everytime boostd stops serving new deals the last one is in state ResponderPaused and the last message has something to do with unsealing

2023-02-27 17:53:37.691 |   | DT:Open |   |  
-- | -- | -- | -- | --
2023-02-27 17:53:37.691 | 0ms | Open | New |  
2023-02-27 17:53:37.694 | 3ms | DT:NewVoucherResult |   |  
2023-02-27 17:53:37.695 | 1ms | DT:Accept |   |  
2023-02-27 17:53:37.696 | 1ms | DealAccepted | Unsealing |  
2023-02-27 17:53:37.697 | 1ms | DT:PauseResponder |   |  
2023-02-27 17:53:37.778 | 81ms | UnsealComplete | Unsealed

the last deals I have checked to have the unsealed sector in place

If i try to cancel the data-transfer it fails with

lotusmarkets@filecoin:~$ boostd data-transfers cancel 1677513182503132346
Error: unable to find matching data transfer

even though it's in state ResponderPaused in the boostd UI

Sorry if the info is not very useful, as I'm quite lost on the subject. I'm available in slack to provide whatever is needed and requested.

Currently the problem persist and I get to it in a couple of minutes after boostd restart

P.S.: slack handle j1v-f020378