Deal stuck in state StorageDealWaitingForData

[cryptowhizzard]

Describe the bug

Sector get stuck in state StorageDealWaitingForData

cat lotus.log | grep -a bafyreihtfwmp6kx4rvcmx7f5swf7xqqmgbgvjs2ngxwmqvvlvqwzcc3irm | more
2021-02-11T21:42:22.189+0100 INFO markets loggers/loggers.go:15 storage client event {"name": "ClientEventOpen", "proposal CID": "bafyreihtfwmp6kx4rvcmx7f5swf7xqqmg
bgvjs2ngxwmqvvlvqwzcc3irm", "state": "StorageDealReserveClientFunds", "message": ""}
2021-02-11T21:42:22.189+0100 INFO markets loggers/loggers.go:15 storage client event {"name": "ClientEventFundsReserved", "proposal CID": "bafyreihtfwmp6kx4rvcmx7f5
swf7xqqmgbgvjs2ngxwmqvvlvqwzcc3irm", "state": "StorageDealReserveClientFunds", "message": ""}
2021-02-11T21:42:22.189+0100 INFO markets loggers/loggers.go:15 storage client event {"name": "ClientEventFundingComplete", "proposal CID": "bafyreihtfwmp6kx4rvcmx7
f5swf7xqqmgbgvjs2ngxwmqvvlvqwzcc3irm", "state": "StorageDealFundsReserved", "message": ""}
2021-02-11T21:42:22.224+0100 INFO markets loggers/loggers.go:15 storage client event {"name": "ClientEventInitiateDataTransfer", "proposal CID": "bafyreihtfwmp6kx4r
vcmx7f5swf7xqqmgbgvjs2ngxwmqvvlvqwzcc3irm", "state": "StorageDealStartDataTransfer", "message": ""}
2021-02-11T21:42:22.224+0100 INFO storagemarket_impl clientstates/client_states.go:153 sending data for a deal bafyreihtfwmp6kx4rvcmx7f5swf7xqqmgbgvjs2ngxwmqv
vlvqwzcc3irm
2021-02-11T21:42:22.226+0100 INFO markets loggers/loggers.go:15 storage client event {"name": "ClientEventDataTransferInitiated", "proposal CID": "bafyreihtfwmp6kx4
rvcmx7f5swf7xqqmgbgvjs2ngxwmqvvlvqwzcc3irm", "state": "StorageDealTransferring", "message": ""}
2021-02-11T21:43:07.968+0100 INFO markets loggers/loggers.go:15 storage client event {"name": "ClientEventDataTransferComplete", "proposal CID": "bafyreihtfwmp6kx4r
vcmx7f5swf7xqqmgbgvjs2ngxwmqvvlvqwzcc3irm", "state": "StorageDealCheckForAcceptance", "message": ""}
2021-02-11T21:43:08.975+0100 INFO markets loggers/loggers.go:15 storage client event {"name": "ClientEventWaitForDealState", "proposal CID": "bafyreihtfwmp6kx4rvcmx
7f5swf7xqqmgbgvjs2ngxwmqvvlvqwzcc3irm", "state": "StorageDealCheckForAcceptance", "message": "Provider state: StorageDealWaitingForData"}
2021-02-11T21:43:09.985+0100 INFO markets loggers/loggers.go:15 storage client event {"name": "ClientEventWaitForDealState", "proposal CID": "bafyreihtfwmp6kx4rvcmx
7f5swf7xqqmgbgvjs2ngxwmqvvlvqwzcc3irm", "state": "StorageDealCheckForAcceptance", "message": "Provider state: StorageDealWaitingForData"}
2021-02-11T21:43:11.000+0100 INFO markets loggers/loggers.go:15 storage client event {"name": "ClientEventWaitForDealState", "proposal CID": "bafyreihtfwmp6kx4rvcmx
7f5swf7xqqmgbgvjs2ngxwmqvvlvqwzcc3irm", "state": "StorageDealCheckForAcceptance", "message": "Provider state: StorageDealWaitingForData"}
2021-02-11T21:43:12.007+0100 INFO markets loggers/loggers.go:15 storage client event {"name": "ClientEventWaitForDealState", "proposal CID": "bafyreihtfwmp6kx4rvcmx
7f5swf7xqqmgbgvjs2ngxwmqvvlvqwzcc3irm", "state": "StorageDealCheckForAcceptance", "message": "Provider state: StorageDealWaitingForData"}
2021-02-11T21:43:13.015+0100 INFO markets loggers/loggers.go:15 storage client event {"name": "ClientEventWaitForDealState", "proposal CID": "bafyreihtfwmp6kx4rvcmx
7f5swf7xqqmgbgvjs2ngxwmqvvlvqwzcc3irm", "state": "StorageDealCheckForAcceptance", "message": "Provider state: StorageDealWaitingForData"}
2021-02-11T21:43:14.023+0100 INFO markets loggers/loggers.go:15 storage client event {"name": "ClientEventWaitForDealState", "proposal CID": "bafyreihtfwmp6kx4rvcmx
7f5swf7xqqmgbgvjs2ngxwmqvvlvqwzcc3irm", "state": "StorageDealCheckForAcceptance", "message": "Provider state: StorageDealWaitingForData"}
2021-02-11T21:43:15.030+0100 INFO markets loggers/loggers.go:15 storage client event {"name": "ClientEventWaitForDealState", "proposal CID": "bafyreihtfwmp6kx4rvcmx
7f5swf7xqqmgbgvjs2ngxwmqvvlvqwzcc3irm", "state": "StorageDealCheckForAcceptance", "message": "Provider state: StorageDealWaitingForData"}
2021-02-11T21:43:16.046+0100 INFO markets loggers/loggers.go:15 storage client event {"name": "ClientEventWaitForDealState", "proposal CID": "bafyreihtfwmp6kx4rvcmx
7f5swf7xqqmgbgvjs2ngxwmqvvlvqwzcc3irm", "state": "StorageDealCheckForAcceptance", "message": "Provider state: StorageDealWaitingForData"}
2021-02-11T21:43:17.058+0100 INFO markets loggers/loggers.go:15 storage client event {"name": "ClientEventWaitForDealState", "proposal CID": "bafyreihtfwmp6kx4rvcmx
7f5swf7xqqmgbgvjs2ngxwmqvvlvqwzcc3irm", "state": "StorageDealCheckForAcceptance", "message": "Provider state: StorageDealWaitingForData"}
2021-02-11T21:43:18.072+0100 INFO markets loggers/loggers.go:15 storage client event {"name": "ClientEventWaitForDealState", "proposal CID": "bafyreihtfwmp6kx4rvcmx
7f5swf7xqqmgbgvjs2ngxwmqvvlvqwzcc3irm", "state": "StorageDealCheckForAcceptance", "message": "Provider state: StorageDealWaitingForData"}
2021-02-11T21:43:19.088+0100 INFO markets loggers/loggers.go:15 storage client event {"name": "ClientEventWaitForDealState", "proposal CID": "bafyreihtfwmp6kx4rv

lotus-miner storage-deals list --verbose | grep bafyreihtfwmp6kx4rvcmx7f5swf7xqqmgbgvjs2ngxwmqvvlvqwzcc3irm
Feb 11 21:42:22 true bafyreihtfwmp6kx4rvcmx7f5swf7xqqmgbgvjs2ngxwmqvvlvqwzcc3irm 0 StorageDealWaitingForData f3sbunigqcrdk2xkxcgvrm72wt73fb4km2kykuy3xvb5gexf66kryjoweno2zlz6kyjuzcket72xd2s7b3zhoq 32GiB 0 FIL

lotus client list-transfers --completed --verbose | grep bafyreihtfwmp6kx4rvcmx7f5swf7xqqmgbgvjs2ngxwmqvvlvqwzcc3irm
596 Completed 12D3KooWNHwmwNRkMEP6VqDCpjSZkqripoJgN7eWruvXXqC2kG9f bafykbzaced4qnbnzjza5ooo57ila3rpr7j3c5s4xcwn6ethsf4lfit2nsv7vs Y 16.66GiB {"Proposal":{"/":"bafyreihtfwmp6kx4rvcmx7f5swf7xqqmgbgvjs2ngxwmqvvlvqwzcc3irm"}}

To Reproduce
issue occurs random. All sectors after this are stuck also.

Version (run lotus version):
Latest master 12 februari 2021.

[ribasushi]

Latest master 12 februari 2021.
Please still run and supply lotus version - it will contain a git hash which tells us what is it you are actually running.

[cryptowhizzard]

Daemon: 1.4.1+mainnet+git.95e47cf99+api1.1.0
Local: lotus version 1.4.1+mainnet+git.95e47cf99

[dineshshenoy]

cc: @dirkmc

[cryptowhizzard]

I did some in depth research. The problem occurs when the miner is also pledging sectors. It looks the AP or whatever channel is full and everything else has to wait.

perhaps this is related?

[dirkmc]

The client proposes a deal, and when the provider accepts the deal proposal, the provider moves to StorageDealWaitingForData.

The client opens a data transfer channel, triggering a datatransfer.Open event on the provider side. In turn this should trigger the ProviderEventDataTransferInitiated event, which should move the provider into the StorageDealTransferring state.

Looking at the logs it seems that even though the client is able to transfer the whole file to the provider, for some reason the datatransfer.Open event never fires on the provider side.

@cryptowhizzard thanks for the bug report. I think it would help track down the problem if you could provide us with some more logs. Could you please set the following log subsystems to debug level using lotus log set-level and lotus-miner log set-level:

• markets
• dt-pushchanmon
• dt-impl
• data_transfer_network

[cryptowhizzard]

From my side this one can be closed. Since 1.6.0 i can make parallel deals ( client to miner ) without anything breaking. Good work !!