[BUG] Online storage finished transfer but is stuck in "StorageDealTransferring"

[rjan90]

Basic Information
I'm a miner, and I got a storage deal that has finished transferring, but is stuck in StorageDealTransferring-state on my miner:

lotus-miner storage-deals list
...5up7jpjq  0        StorageDealTransferring                  f3rab4mhsr7f2gdg6ozgj44mtny6bhcy3rvlftc5xyki6t4hvhdkaji3ahfaid6fh2o3wff4yfrzag4lge2r2q  32GiB   0 FIL                     519033

And when I grep after the deal on the deal-transfer, it says that it has completed:

lotus-miner data-transfers list --completed | grep jpjq
1847   Completed  ...Powtfgsa     ...R6cy1eDL  N           28.01GiB     ...77zdyciciy5bgu2mhs3dwafzv45up7jpjq"}}  

@jsign was the client sending out the deal, so he might have some information on how it is looking at the client side.

Version
Daemon: 1.5.3-rc2+mainnet+git.9afb5ff94+api1.1.0
Local: lotus version 1.5.3-rc2+mainnet+git.9afb5ff94

Setup
Lotus-miner & Lotus-daemon server:
EPYC 7302
256GB RAM
SSD-disks

Lotus daemon and miner logs
Miner logs:

tail -30000 ~/lotusminer.log | grep jpjq
2021-03-17T20:45:18.761+0100	INFO	markets	loggers/loggers.go:20	storage provider event	{"name": "ProviderEventOpen", "proposal CID": "bafyreihb5mzfu5ktbgxvpkkv77zdyciciy5bgu2mhs3dwafzv45up7jpjq", "state": "StorageDealValidating", "message": ""}
2021-03-17T20:45:18.778+0100	INFO	markets	loggers/loggers.go:20	storage provider event	{"name": "ProviderEventDealDeciding", "proposal CID": "bafyreihb5mzfu5ktbgxvpkkv77zdyciciy5bgu2mhs3dwafzv45up7jpjq", "state": "StorageDealAcceptWait", "message": ""}
2021-03-17T20:45:18.792+0100	INFO	markets	loggers/loggers.go:20	storage provider event	{"name": "ProviderEventDataRequested", "proposal CID": "bafyreihb5mzfu5ktbgxvpkkv77zdyciciy5bgu2mhs3dwafzv45up7jpjq", "state": "StorageDealWaitingForData", "message": ""}
2021-03-17T20:45:19.157+0100	INFO	markets	loggers/loggers.go:20	storage provider event	{"name": "ProviderEventDataTransferInitiated", "proposal CID": "bafyreihb5mzfu5ktbgxvpkkv77zdyciciy5bgu2mhs3dwafzv45up7jpjq", "state": "StorageDealTransferring", "message": ""}

[rjan90]

Update:
The deal is now in StorageDealVerifyData-state

lotus-miner storage-deals list
...5up7jpjq  0        StorageDealVerifyData                    f3rab4mhsr7f2gdg6ozgj44mtny6bhcy3rvlftc5xyki6t4hvhdkaji3ahfaid6fh2o3wff4yfrzag4lge2r2q  32GiB   0 FIL                     519033

But it took an awfully long time from when it finished transferring, until it went to verifing:

2021-03-17T20:45:19.157+0100	INFO	markets	loggers/loggers.go:20	storage provider event	{"name": "ProviderEventDataTransferInitiated", "proposal CID": "bafyreihb5mzfu5ktbgxvpkkv77zdyciciy5bgu2mhs3dwafzv45up7jpjq", "state": "StorageDealTransferring", "message": ""}
2021-03-18T10:36:43.303+0100	INFO	markets	loggers/loggers.go:20	storage provider event	{"name": "ProviderEventDataTransferCompleted", "proposal CID": "bafyreihb5mzfu5ktbgxvpkkv77zdyciciy5bgu2mhs3dwafzv45up7jpjq", "state": "StorageDealVerifyData", "message": ""}

[rjan90]

As I had more incoming transfers I have closely monitored when they finished the transfer, and how long it takes before they changed their state from StorageDealTransferring to StorageDealVerifyData, and it's over 1-2+ hours at least, and some are not changing their state at all.

I know @jsign is currently sending out a lot of deals, and that his client is probably quite busy in terms of resources and disk-io! I don't know the technical details about when deal/transfers changes states, so this is just my intuition/guessing: but it seems like the state-changes are delayed on my miner, because it can't contact the busy client sending the deal, and thus can't close the transfer-channel and send the deal to StorageDealVerifyData-state?

[jsign]

The POV of me (client) for your miner is:

Mar 17 19:45:18  bafyreihb5mzfu5ktbgxvpkkv77zdyciciy5bgu2mhs3dwafzv45up7jpjq  1612363  f023467   StorageDealAwaitingPreCommit      N                 N            baga6ea4seaqakgvkgk2gsjxbmerjeoqr4u7wfwi3x6siyxwaebvlcmlrdouk2hq  31.75 GiB  0 FIL                     519033    12D3KooWHAN67HgLoqrygQnouFF5uVhwM4kP7zurpR65Powtfgsa-12D3KooWMpuRzgVuRS6m285cucGgnXWwTnsNtGzjsMJeEqS7UtJw-1847  Completed       true      
Mar 17 21:32:18  bafyreif5fvk4iw5jrctbylpuzk3ezoxhyliz6f2ikuhate4dgq5tffiszq  0        f023467   StorageDealTransferring           N                 N            baga6ea4seaqc4d2nfjjgg7e6vonfoztwu5lrvr7sggzi3uc3xu6hl6b7ozx3yia  31.75 GiB  0 FIL                     518819    12D3KooWHAN67HgLoqrygQnouFF5uVhwM4kP7zurpR65Powtfgsa-12D3KooWMpuRzgVuRS6m285cucGgnXWwTnsNtGzjsMJeEqS7UtJw-1858  Ongoing         true      
Mar 17 23:09:23  bafyreianqksz4lhqubbrgdxjwnjk5wgvfqh5xbs3zstkcz7dhfw56uash4  0        f023467   StorageDealCheckForAcceptance     N                 N            baga6ea4seaqeszmjk3zrmk5eiitesvwyia2x333i3fpkl7hyvlgj5vjzyr5xsgy  31.75 GiB  0 FIL                     521505    12D3KooWHAN67HgLoqrygQnouFF5uVhwM4kP7zurpR65Powtfgsa-12D3KooWMpuRzgVuRS6m285cucGgnXWwTnsNtGzjsMJeEqS7UtJw-1861  Completed       true      Provider state: StorageDealTransferring
Mar 17 23:10:14  bafyreidrxjfwf2qjv7gr6rsmvv4g54fibb57kbhdiqaqqfczbu6pr7pzze  0        f023467   StorageDealTransferring           N                 N            baga6ea4seaqese77w4yswa4bdd2ke345ii7bwunwvc6iozxlxjq4byuadq5z6pa  31.75 GiB  0 FIL                     521503    12D3KooWHAN67HgLoqrygQnouFF5uVhwM4kP7zurpR65Powtfgsa-12D3KooWMpuRzgVuRS6m285cucGgnXWwTnsNtGzjsMJeEqS7UtJw-1865  Ongoing         true      
Mar 18 00:51:08  bafyreidxnzm6rtu7oerpzo5wnmltvyozr4jk4oqrfzh76lab4vkjgqu4q4  0        f023467   StorageDealCheckForAcceptance     N                 N            baga6ea4seaqlomd657xeg53n6xhb4j6libyckoqmjvdfr73xe23yejahwhxr4bq  31.75 GiB  0 FIL                     521301    12D3KooWHAN67HgLoqrygQnouFF5uVhwM4kP7zurpR65Powtfgsa-12D3KooWMpuRzgVuRS6m285cucGgnXWwTnsNtGzjsMJeEqS7UtJw-1872  Completed       true      Provider state: StorageDealTransferring

[rjan90]

So the deals that are currently in StorageDealCheckForAcceptance on your side is actually finished transferring:

lotus-miner data-transfers list --completed | grep ash4
1861   Completed  ...Powtfgsa     ...qRDNzEa3  N           28.01GiB     ...wnjk5wgvfqh5xbs3zstkcz7dhfw56uash4"}}  

lotus-miner data-transfers list --completed | grep u4q4
1872   Completed  ...Powtfgsa     ...wKkxi6Vt  N           29.13GiB     ...nmltvyozr4jk4oqrfzh76lab4vkjgqu4q4"}}  

And here is how they look in my storage-deal list:

...w56uash4  0        StorageDealTransferring                  f3rab4mhsr7f2gdg6ozgj44mtny6bhcy3rvlftc5xyki6t4hvhdkaji3ahfaid6fh2o3wff4yfrzag4lge2r2q  32GiB   0 FIL                     521505
...kjgqu4q4  0        StorageDealTransferring                  f3rab4mhsr7f2gdg6ozgj44mtny6bhcy3rvlftc5xyki6t4hvhdkaji3ahfaid6fh2o3wff4yfrzag4lge2r2q  32GiB   0 FIL                     521301

And the miner-logs for the deals:
**deal ...ash4**

tail -30000 ~/lotusminer.log | grep ash4
2021-03-18T00:09:23.951+0100	INFO	markets	loggers/loggers.go:20	storage provider event	{"name": "ProviderEventOpen", "proposal CID": "bafyreianqksz4lhqubbrgdxjwnjk5wgvfqh5xbs3zstkcz7dhfw56uash4", "state": "StorageDealValidating", "message": ""}
2021-03-18T00:09:23.965+0100	INFO	markets	loggers/loggers.go:20	storage provider event	{"name": "ProviderEventDealDeciding", "proposal CID": "bafyreianqksz4lhqubbrgdxjwnjk5wgvfqh5xbs3zstkcz7dhfw56uash4", "state": "StorageDealAcceptWait", "message": ""}
2021-03-18T00:09:23.980+0100	INFO	markets	loggers/loggers.go:20	storage provider event	{"name": "ProviderEventDataRequested", "proposal CID": "bafyreianqksz4lhqubbrgdxjwnjk5wgvfqh5xbs3zstkcz7dhfw56uash4", "state": "StorageDealWaitingForData", "message": ""}
2021-03-18T04:12:16.514+0100	INFO	markets	loggers/loggers.go:20	storage provider event	{"name": "ProviderEventDataTransferInitiated", "proposal CID": "bafyreianqksz4lhqubbrgdxjwnjk5wgvfqh5xbs3zstkcz7dhfw56uash4", "state": "StorageDealTransferring", "message": ""}

**deal ...u4q4**

tail -30000 ~/lotusminer.log | grep u4q4
2021-03-18T01:51:08.623+0100	INFO	markets	loggers/loggers.go:20	storage provider event	{"name": "ProviderEventOpen", "proposal CID": "bafyreidxnzm6rtu7oerpzo5wnmltvyozr4jk4oqrfzh76lab4vkjgqu4q4", "state": "StorageDealValidating", "message": ""}
2021-03-18T01:51:08.636+0100	INFO	markets	loggers/loggers.go:20	storage provider event	{"name": "ProviderEventDealDeciding", "proposal CID": "bafyreidxnzm6rtu7oerpzo5wnmltvyozr4jk4oqrfzh76lab4vkjgqu4q4", "state": "StorageDealAcceptWait", "message": ""}
2021-03-18T01:51:08.648+0100	INFO	markets	loggers/loggers.go:20	storage provider event	{"name": "ProviderEventDataRequested", "proposal CID": "bafyreidxnzm6rtu7oerpzo5wnmltvyozr4jk4oqrfzh76lab4vkjgqu4q4", "state": "StorageDealWaitingForData", "message": ""}
2021-03-18T11:18:26.940+0100	INFO	markets	loggers/loggers.go:20	storage provider event	{"name": "ProviderEventDataTransferInitiated", "proposal CID": "bafyreidxnzm6rtu7oerpzo5wnmltvyozr4jk4oqrfzh76lab4vkjgqu4q4", "state": "StorageDealTransferring", "message": ""}

[jennijuju]

Re-visit after the new market release is in.

[neondragon]

(Slack @NeonixAF f019551)

I am seeing this issue on lotus-miner 1.9.0+mainnet with a deal from Estuary.

lotus-miner storage-deals list
...lvp2i4yq  0        StorageDealTransferring                  f3vnq2cmwig3qjisnx5hobxvsd4drn4f54xfxnv4tciw6vnjdsf5xipgafreprh5riwmgtcirpcdmi3urbg36a  16GiB     0 FIL                     1000000

lotus-miner data-transfers list --completed | grep i4yq
1621972176083952066  Completed  ...MTqHYBjw     ...opDgnZTM  N           14.2GiB      ...yhfalvv4lorcaarodc57qtibfolvp2i4yq"}}

tail -300000 /var/log/lotus/miner.log | grep i4yq
{"level":"info","ts":"2021-05-25T22:00:04.202Z","logger":"markets","caller":"loggers/loggers.go:20","msg":"storage provider event","name":"ProviderEventOpen","proposal CID":"bafyreiesoluhouf5nidqrtxcyhfalvv4lorcaarodc57qtibfolvp2i4yq","state":"StorageDealValidating","message":""}
{"level":"info","ts":"2021-05-25T22:00:04.220Z","logger":"markets","caller":"loggers/loggers.go:20","msg":"storage provider event","name":"ProviderEventDealDeciding","proposal CID":"bafyreiesoluhouf5nidqrtxcyhfalvv4lorcaarodc57qtibfolvp2i4yq","state":"StorageDealAcceptWait","message":""}
{"level":"info","ts":"2021-05-25T22:00:04.264Z","logger":"markets","caller":"loggers/loggers.go:20","msg":"storage provider event","name":"ProviderEventDataRequested","proposal CID":"bafyreiesoluhouf5nidqrtxcyhfalvv4lorcaarodc57qtibfolvp2i4yq","state":"StorageDealWaitingForData","message":""}
{"level":"info","ts":"2021-05-25T22:00:06.181Z","logger":"markets","caller":"loggers/loggers.go:20","msg":"storage provider event","name":"ProviderEventDataTransferInitiated","proposal CID":"bafyreiesoluhouf5nidqrtxcyhfalvv4lorcaarodc57qtibfolvp2i4yq","state":"StorageDealTransferring","message":""}
{"level":"info","ts":"2021-05-26T05:34:16.875Z","logger":"markets","caller":"loggers/loggers.go:20","msg":"storage provider event","name":"ProviderEventDataTransferRestarted","proposal CID":"bafyreiesoluhouf5nidqrtxcyhfalvv4lorcaarodc57qtibfolvp2i4yq","state":"StorageDealTransferring","message":""}
{"level":"info","ts":"2021-05-27T05:57:51.733Z","logger":"markets","caller":"loggers/loggers.go:20","msg":"storage provider event","name":"ProviderEventDataTransferRestarted","proposal CID":"bafyreiesoluhouf5nidqrtxcyhfalvv4lorcaarodc57qtibfolvp2i4yq","state":"StorageDealTransferring","message":""}