Canceling a retrieval deal on the client can cause data transfer to get stuck in 'Ongoing' on the server side

[jacobheun]

Problem

Terminating a graphsync data transfer via the client aborting (ctrl+c) can result in the transfer not being properly terminated on Boosts end. This can eventually lead to timeouts on the client side for subsequent requests.

Info

Transport: Graphsync via Lassie

In the below screenshot, I ran 4 retrievals using https://github.com/filecoin-project/lassie and canceled all of them mid download. 3 of the 4 retrievals got stuck in the 'Ongoing' state.

lassie fetch --progress bafy...

The terminated data transfer event logs look like:

2023-01-26 15:50:01.443 |   | DT:Open | 
2023-01-26 15:50:01.443 | 0ms | Open | New |  
2023-01-26 15:50:01.446 | 3ms | DT:NewVoucherResult |   |  
2023-01-26 15:50:01.447 | 1ms | DT:Accept |   |  
2023-01-26 15:50:01.449 | 2ms | DealAccepted | Unsealing |  
2023-01-26 15:50:01.450 | 1ms | DT:PauseResponder |   |  
2023-01-26 15:50:01.807 | 357ms | DT:ResumeResponder |   |  
2023-01-26 15:50:01.807 | 0ms | UnsealComplete | Unsealed |  
2023-01-26 15:50:03.048 | 1s | DT:DataSent |   |  
2023-01-26 15:50:03.605 | 557ms | DT:DataSent |   |  
2023-01-26 15:50:04.899 | 1s | DT:DataSent


... (more data sent)
2023-01-26 15:52:28.445	655ms	DT:DataSent		
2023-01-26 15:52:29.114	669ms	DT:DataSent		
2023-01-26 15:52:29.321	207ms	DT:ReceiveDataError		stream reset
2023-01-26 15:52:29.324	3ms	DT:SendDataError		queue shutdown

The data transfer that was fully canceled, was actually a timeout termination by lassie because data was not sent for ~20s. The full event logs look like this:

2023-01-26 15:52:40.133		DT:Open		
2023-01-26 15:52:40.133	0ms	Open	New	
2023-01-26 15:52:40.136	3ms	DT:NewVoucherResult		
2023-01-26 15:52:40.137	1ms	DT:Accept		
2023-01-26 15:52:40.139	2ms	DealAccepted	Unsealing	
2023-01-26 15:52:40.140	1ms	DT:PauseResponder		
2023-01-26 15:52:40.536	396ms	DT:ResumeResponder		
2023-01-26 15:52:40.536	0ms	UnsealComplete	Unsealed	
2023-01-26 15:52:58.208	18s	DT:Cancel		
2023-01-26 15:52:58.211	3ms	ClientCancelled	Cancelling	Client cancelled retrieval
2023-01-26 15:52:58.212	1ms	DT:CleanupComplete		
2023-01-26 15:52:58.215	3ms	CancelComplete	Cancelled	Client cancelled retrieval

Refs

• Possibly related to Retrievals hang at stage 'PaymentChannelSkip (Ongoing)' #1125
• Possibly related to Retrievals stopped working (stuck on DealProposed (WaitForAcceptance)) #846

[jacobheun]

I was able to get this replicated consistently locally, at least for the Ongoing hang but havent reproduced the timeout side yet.

Using #1143 I added TC to the docker setup to slow retrieval so that 8MB requests would take several seconds. Leveraging a modified version of lassie (thanks @masih !) I was then able to cancel requests mid flight to get the Ongoing hang

It might be worth noting, that prior to going through Boost, when I interrupted requests to lotus I eventually got the following error:

failed to load blockstore for piece baga6ea4seaqnu565elcclgmhv7nvypneacwjq3t4ahudduqyhrvdsdtu6jjamjq: failed to acquire shard for piece CID baga6ea4seaqnu565elcclgmhv7nvypneacwjq3t4ahudduqyhrvdsdtu6jjamjq: shard is in errored state; err: failed to acquire reader of mount on initialization: failed to unseal deal 4: RPCConnectionError

Requests would get outright refused until I restarted Boost, so there may be some connection there. This could be a red herring, but I'll need to investigate more to determine if that's the case.

[jacobheun]

I still haven't been able to replicate transfers completely hanging from the clients perspective. My assumption is there is either a concurrency limit we're hitting due to other failed transfers being in progress, or that the whole state machine is just getting locked up for some reason.

I'm not familiar with the go-data-transfer state machine, but the problem appears to be in there for this Ongoing hanging issue. Quickly looking at the go-data-transfer v1.15.3 code, it doesn't appear that certain states, such as DT:SendDataError are resulting in fsm transitions. As an example if the channel no longer exists (I assume this is the case when the client resets the connect) it looks like the error is propagated up to https://github.com/filecoin-project/go-data-transfer/blob/v1.15.3/transport/graphsync/graphsync.go#L849 but no FSM change is triggered.

[davidd8]

Triaged to Tornado team, as it relates to #1125

[hannahhoward]

@jacobheun so, essentially, I believe the reason SendDataError doesn't terminate the state machine is that it may be a temporarily cut stream and we expect the client might reconnect and restart. What is not present however is a timer (say 10 minutes) that pushes the state into Failed if there is no restart. The whole conversion of SendDataError to not an immediate fail was done while I wasn't maintaining this state machine, and it seems reasonable, given restart functionality.... except for the obvious failure to ever move out of the state if the client does not restart.

[jacobheun]

Workaround included via #1233 to cancel any stalled retrievals, so marking this as closed for now. There is some longer term improvements that we are planning to resolve the underlying problem with stalls.