Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Failed retrieval deal v1.13.2-rc4 #7763

Closed
8 of 18 tasks
stuberman opened this issue Dec 11, 2021 · 5 comments
Closed
8 of 18 tasks

Failed retrieval deal v1.13.2-rc4 #7763

stuberman opened this issue Dec 11, 2021 · 5 comments
Labels
area/markets/retrieval area/markets Area: Markets area/sealing kind/bug Kind: Bug LM-tech-debt need/analysis Hint: Needs Analysis
Milestone
LM-Tech-Debt-Lega...

Comments

@stuberman
Copy link

Checklist

  • This is not a security-related bug/issue. If it is, please follow please follow the security policy.
  • This is not a question or a support request. If you have any lotus related questions, please ask in the lotus forum.
  • This is not a new feature request. If it is, please file a feature request instead.
  • This is not an enhancement request. If it is, please file a improvement suggestion instead.
  • I have searched on the issue tracker and the lotus forum, and there is no existing related issue or discussion.
  • I am running the Latest release, or the most recent RC(release canadiate) for the upcoming release or the dev branch(master), or have an issue updating to any of these.
  • I did not make any code changes to lotus.

Lotus component

  • lotus daemon - chain sync
  • lotus miner - mining and block production
  • lotus miner/worker - sealing
  • lotus miner - proving(WindowPoSt)
  • lotus miner/market - storage deal
  • lotus miner/market - retrieval deal
  • lotus miner/market - data transfer
  • lotus client
  • lotus JSON-RPC API
  • lotus message management (mpool)
  • Other

Lotus Version

lotus-miner --call-on-markets version
Daemon:  1.13.2-rc4+mainnet+git.e05fdf892+api1.2.0
Local: lotus-miner version 1.13.2-rc4+mainnet+git.e05fdf892


lotus-miner version
Daemon:  1.13.2-rc4+mainnet+git.e05fdf892+api1.2.0
Local: lotus-miner version 1.13.2-rc4+mainnet+git.e05fdf892

Config.toml
[Storage]
  ParallelFetchLimit = 5
  AllowAddPiece = false
  AllowPreCommit1 = false
  AllowPreCommit2 = false
  AllowCommit = false
  AllowUnseal = false
  ResourceFiltering = "hardware"

lotus-worker info
Worker version:  1.5.0
CLI version: lotus-worker version 1.13.2-rc4+mainnet+git.e05fdf892

Session: d61a757f-8257-4502-8e40-b52129dbc0a7
Enabled: true
Hostname: sealer
CPUs: 128; GPUs: [GeForce RTX 3090]
RAM: 46.06 GiB/251.6 GiB; Swap: 275.8 MiB/526 GiB
Task types: FIN GET UNS C1 C2 PC2 PC1 AP 

536385c7-a3d1-479f-affc-9961eb10c052:
	Weight: 10; Use: Seal 
	Local: /seal2/worker
c45a6c01-b823-4813-92b9-fa2841ea3523:
	Weight: 10; Use: Seal 
	Local: /seal/worker

Describe the Bug

Markets node received request for retrieval
No unsealed version (sector 1318) so lotus-miner sends sealed and cache to worker
Worker fetches sealed an cache and ready to start unseal
But lotus-miner errors out and sealed sector and fetched data remain on worker.

Why is retrieval process looking in markets node for a path that only exists on miner and worker nodes?
Why does a failed deal leave behind data in worker?

Logging Information

lotus-miner retrieval-deals list

12D3KooWR78XjWcJqq73VjBPwTVv5QrjGFHVVeeADcG4qcr3c17n  1629254447593549851  ...x52cgwqe  DealStatusErrored            0         0            failed to load blockstore for piece baga6ea4seaqdjvcltqt3fwsb3z7ihaakwa3mkjmmb5knkhjsiallbk4lutrwiiy: failed to acquire shard for piece CID baga6ea4seaqdjvcltqt3fwsb3z7ihaakwa3mkjmmb5knkhjsiallbk4lutrwiiy: mount fetch failed: failed to fetch and copy underlying mount to transient file: failed to fetch from underlying mount: failed to fetch unsealed piece baga6ea4seaqdjvcltqt3fwsb3z7ihaakwa3mkjmmb5knkhjsiallbk4lutrwiiy: failed to unseal deal 2081795: failed to unseal piece from sector 1318: opening partial file: openning partial file '/market/storage/unsealed/s-t01278-1318': open /market/storage/unsealed/s-t01278-1318: no such file or directory

12D3KooWRN2uv65m1F6eU5t8VDqMUKgapx5HJTnP3YiFWY9dA7Tn  1629985948889462501  ...x52cgwqe  DealStatusErrored            0         0            failed to load blockstore for piece baga6ea4seaqdjvcltqt3fwsb3z7ihaakwa3mkjmmb5knkhjsiallbk4lutrwiiy: failed to acquire shard for piece CID baga6ea4seaqdjvcltqt3fwsb3z7ihaakwa3mkjmmb5knkhjsiallbk4lutrwiiy: failed to acquire shard: failed to acquire reader of mount on initialization: mount fetch failed: failed to fetch and copy underlying mount to transient file: failed to fetch from underlying mount: failed to fetch unsealed piece baga6ea4seaqdjvcltqt3fwsb3z7ihaakwa3mkjmmb5knkhjsiallbk4lutrwiiy: failed to unseal deal 2081795: failed to unseal piece from sector 1318: opening partial file: openning partial file '/market/storage/unsealed/s-t01278-1318': open /market/storage/unsealed/s-t01278-1318: no such file or directory

12D3KooWPfmmk2vz5fmS4i8n1kW21mGjFjWUHiV5pNCpFL2hiLfm  1629446210819135001  ...x52cgwqe  DealStatusErrored            0         0            failed to load blockstore for piece baga6ea4seaqdjvcltqt3fwsb3z7ihaakwa3mkjmmb5knkhjsiallbk4lutrwiiy: failed to acquire shard for piece CID baga6ea4seaqdjvcltqt3fwsb3z7ihaakwa3mkjmmb5knkhjsiallbk4lutrwiiy: failed to acquire shard: failed to acquire reader of mount on initialization: mount fetch failed: failed to fetch and copy underlying mount to transient file: failed to fetch from underlying mount: failed to fetch unsealed piece baga6ea4seaqdjvcltqt3fwsb3z7ihaakwa3mkjmmb5knkhjsiallbk4lutrwiiy: failed to unseal deal 2081795: failed to unseal piece from sector 1318: opening partial file: openning partial file '/market/storage/unsealed/s-t01278-1318': open /market/storage/unsealed/s-t01278-1318: no such file or directory

Markets node logs:

2021-12-11T20:06:30.879Z	WARN	rpc	go-jsonrpc@v0.1.5/client.go:362	rpc output message buffer	{"n": 11}
2021-12-11T20:09:06.375Z	INFO	dt_graphsync	graphsync/graphsync.go:552	12D3KooWB7VnSBe4asxdJKSy767p9QYoEm5cLcaqYE3DsCCMs386-12D3KooWSsaFCtzDJUEhLQYDdwoFtdCMqqfk562UMvccFz12kYxU-1639251766039379435, pull request queued, req=&{BCid:bafykbzacecgvrremltlsb3m7jvdvuwfba2m6hhv5j35h6mf7eybwtx52cgwqe Type:0 Paus:false Part:false Pull:true Stor:0xc0224cd080 Vouch:0xc0224cd0b0 VTyp:RetrievalDealProposal/1 XferID:1639251766039379435 RestartChannel:--0}
2021-12-11T20:09:06.375Z	INFO	dt-impl	impl/events.go:314	channel 12D3KooWB7VnSBe4asxdJKSy767p9QYoEm5cLcaqYE3DsCCMs386-12D3KooWSsaFCtzDJUEhLQYDdwoFtdCMqqfk562UMvccFz12kYxU-1639251766039379435: received new channel request from 12D3KooWB7VnSBe4asxdJKSy767p9QYoEm5cLcaqYE3DsCCMs386
2021-12-11T20:09:06.391Z	INFO	dt-impl	impl/events.go:393	data-transfer request validated, will create & start tracking channel	{"channelID": "12D3KooWB7VnSBe4asxdJKSy767p9QYoEm5cLcaqYE3DsCCMs386-12D3KooWSsaFCtzDJUEhLQYDdwoFtdCMqqfk562UMvccFz12kYxU-1639251766039379435", "payloadCid": "bafykbzacecgvrremltlsb3m7jvdvuwfba2m6hhv5j35h6mf7eybwtx52cgwqe"}
2021-12-11T20:09:06.391Z	INFO	markets	loggers/loggers.go:30	retrieval provider event	{"name": "ProviderEventOpen", "deal ID": "1639251766264102770", "receiver": "12D3KooWB7VnSBe4asxdJKSy767p9QYoEm5cLcaqYE3DsCCMs386", "state": "DealStatusNew", "message": ""}
2021-12-11T20:09:06.396Z	INFO	markets	loggers/loggers.go:30	retrieval provider event	{"name": "ProviderEventDealAccepted", "deal ID": "1639251766264102770", "receiver": "12D3KooWB7VnSBe4asxdJKSy767p9QYoEm5cLcaqYE3DsCCMs386", "state": "DealStatusUnsealing", "message": ""}
2021-12-11T20:09:06.397Z	INFO	dt_graphsync	graphsync/graphsync.go:1060	incoming graphsync request	{"peer": "12D3KooWB7VnSBe4asxdJKSy767p9QYoEm5cLcaqYE3DsCCMs386", "graphsync request id": 0, "data transfer channel id": "12D3KooWB7VnSBe4asxdJKSy767p9QYoEm5cLcaqYE3DsCCMs386-12D3KooWSsaFCtzDJUEhLQYDdwoFtdCMqqfk562UMvccFz12kYxU-1639251766039379435"}
2021-12-11T20:09:06.397Z	INFO	gs-queryexecutor	queryexecutor/queryexecutor.go:103	Empty task on peer request stack
2021-12-11T20:09:06.405Z	DEBUG	advmgr	sector-storage/piece_provider.go:89	did not get storage reader;sector={Miner:1278 Number:1318}, err:failed to read sector {{1278 1318} 8} from remote(1): sector not found
2021-12-11T20:09:06.405Z	DEBUG	advmgr	sector-storage/piece_provider.go:169	result of first tryReadUnsealedPiece: r=<nil>, err=failed to read sector {{1278 1318} 8} from remote(1): sector not found
2021-12-11T20:09:06.405Z	DEBUG	advmgr	sector-storage/piece_provider.go:172	no unsealed sector file with unsealed piece, sector={ID:{Miner:1278 Number:1318} ProofType:8}, pieceOffset=0, size=8522825728
2021-12-11T20:11:31.009Z	WARN	rpc	go-jsonrpc@v0.1.5/client.go:362	rpc output message buffer	{"n": 11}
2021-12-11T20:12:00.944Z	WARN	rpc	go-jsonrpc@v0.1.5/client.go:362	rpc output message buffer	{"n": 11}
2021-12-11T20:12:02.680Z	WARN	rpc	go-jsonrpc@v0.1.5/client.go:362	rpc output message buffer	{"n": 11}
2021-12-11T20:12:03.372Z	WARN	rpc	go-jsonrpc@v0.1.5/client.go:362	rpc output message buffer	{"n": 12}
2021-12-11T20:12:30.677Z	WARN	rpc	go-jsonrpc@v0.1.5/client.go:362	rpc output message buffer	{"n": 11}
2021-12-11T20:12:30.689Z	WARN	rpc	go-jsonrpc@v0.1.5/client.go:362	rpc output message buffer	{"n": 12}
2021-12-11T20:12:30.699Z	WARN	rpc	go-jsonrpc@v0.1.5/client.go:362	rpc output message buffer	{"n": 13}
2021-12-11T20:12:30.777Z	WARN	rpc	go-jsonrpc@v0.1.5/client.go:362	rpc output message buffer	{"n": 14}
2021-12-11T20:12:30.899Z	WARN	rpc	go-jsonrpc@v0.1.5/client.go:362	rpc output message buffer	{"n": 15}
2021-12-11T20:12:33.895Z	WARN	rpc	go-jsonrpc@v0.1.5/client.go:362	rpc output message buffer	{"n": 16}
2021-12-11T20:13:00.398Z	WARN	rpc	go-jsonrpc@v0.1.5/client.go:362	rpc output message buffer	{"n": 13}
2021-12-11T20:13:00.428Z	WARN	rpc	go-jsonrpc@v0.1.5/client.go:362	rpc output message buffer	{"n": 14}
2021-12-11T20:13:00.576Z	WARN	rpc	go-jsonrpc@v0.1.5/client.go:362	rpc output message buffer	{"n": 15}
2021-12-11T20:13:00.584Z	WARN	rpc	go-jsonrpc@v0.1.5/client.go:362	rpc output message buffer	{"n": 16}
2021-12-11T20:13:00.879Z	WARN	rpc	go-jsonrpc@v0.1.5/client.go:362	rpc output message buffer	{"n": 17}
2021-12-11T20:13:00.900Z	WARN	rpc	go-jsonrpc@v0.1.5/client.go:362	rpc output message buffer	{"n": 18}
2021-12-11T20:13:01.078Z	WARN	rpc	go-jsonrpc@v0.1.5/client.go:362	rpc output message buffer	{"n": 19}
2021-12-11T20:13:01.529Z	WARN	rpc	go-jsonrpc@v0.1.5/client.go:362	rpc output message buffer	{"n": 20}
2021-12-11T20:13:29.780Z	WARN	rpc	go-jsonrpc@v0.1.5/client.go:362	rpc output message buffer	{"n": 17}
2021-12-11T20:13:30.434Z	WARN	rpc	go-jsonrpc@v0.1.5/client.go:362	rpc output message buffer	{"n": 18}
2021-12-11T20:13:30.459Z	WARN	rpc	go-jsonrpc@v0.1.5/client.go:362	rpc output message buffer	{"n": 19}
2021-12-11T20:13:30.481Z	WARN	rpc	go-jsonrpc@v0.1.5/client.go:362	rpc output message buffer	{"n": 20}
2021-12-11T20:13:30.508Z	WARN	rpc	go-jsonrpc@v0.1.5/client.go:362	rpc output message buffer	{"n": 21}
2021-12-11T20:13:30.880Z	WARN	rpc	go-jsonrpc@v0.1.5/client.go:362	rpc output message buffer	{"n": 22}
2021-12-11T20:13:31.675Z	WARN	rpc	go-jsonrpc@v0.1.5/client.go:362	rpc output message buffer	{"n": 23}
2021-12-11T20:13:31.787Z	WARN	rpc	go-jsonrpc@v0.1.5/client.go:362	rpc output message buffer	{"n": 24}
2021-12-11T20:13:59.892Z	WARN	rpc	go-jsonrpc@v0.1.5/client.go:362	rpc output message buffer	{"n": 21}
2021-12-11T20:14:00.536Z	WARN	rpc	go-jsonrpc@v0.1.5/client.go:362	rpc output message buffer	{"n": 22}
2021-12-11T20:14:04.219Z	ERROR	advmgr	sector-storage/piece_provider.go:192	failed to SectorsUnsealPiece: worker UnsealPiece call: storage call error 0: unsealing sector: acquire unsealed sector path (existing): allocate local sector for fetching: couldn't find a suitable path for a sector
2021-12-11T20:14:04.219Z	WARN	dagstore	dagstore/miner_api.go:164	failed to unseal deal 2081795: failed to unseal piece from sector 1318: unsealing piece: worker UnsealPiece call: storage call error 0: unsealing sector: acquire unsealed sector path (existing): allocate local sector for fetching: couldn't find a suitable path for a sector
2021-12-11T20:14:04.219Z	WARN	dagstore	dagstore@v0.4.3/dagstore_async.go:37	acquire: failed to fetch from mount upgrader	{"shard": "baga6ea4seaqdjvcltqt3fwsb3z7ihaakwa3mkjmmb5knkhjsiallbk4lutrwiiy", "error": "failed to unseal deal 2081795: failed to unseal piece from sector 1318: unsealing piece: worker UnsealPiece call: storage call error 0: unsealing sector: acquire unsealed sector path (existing): allocate local sector for fetching: couldn't find a suitable path for a sector", "errorVerbose": "failed to unseal deal 2081795:\n    github.com/filecoin-project/lotus/markets/dagstore.(*minerAPI).FetchUnsealedPiece\n        /home/stuart/lotus/markets/dagstore/miner_api.go:163\n  - failed to unseal piece from sector 1318:\n    github.com/filecoin-project/lotus/markets/sectoraccessor.(*sectorAccessor).UnsealSectorAt\n        /home/stuart/lotus/markets/sectoraccessor/sectoraccessor.go:75\n  - unsealing piece:\n    github.com/filecoin-project/lotus/extern/sector-storage.(*pieceProvider).ReadPiece\n        /home/stuart/lotus/extern/sector-storage/piece_provider.go:193\n  - worker UnsealPiece call: storage call error 0: unsealing sector: acquire unsealed sector path (existing): allocate local sector for fetching: couldn't find a suitable path for a sector"}
2021-12-11T20:14:04.219Z	INFO	markets	loggers/loggers.go:30	retrieval provider event	{"name": "ProviderEventUnsealError", "deal ID": "1639251766264102770", "receiver": "12D3KooWB7VnSBe4asxdJKSy767p9QYoEm5cLcaqYE3DsCCMs386", "state": "DealStatusFailing", "message": "failed to load blockstore for piece baga6ea4seaqdjvcltqt3fwsb3z7ihaakwa3mkjmmb5knkhjsiallbk4lutrwiiy: failed to acquire shard for piece CID baga6ea4seaqdjvcltqt3fwsb3z7ihaakwa3mkjmmb5knkhjsiallbk4lutrwiiy: failed to unseal deal 2081795: failed to unseal piece from sector 1318: unsealing piece: worker UnsealPiece call: storage call error 0: unsealing sector: acquire unsealed sector path (existing): allocate local sector for fetching: couldn't find a suitable path for a sector"}
2021-12-11T20:14:04.224Z	INFO	dt-impl	impl/impl.go:286	close channel 12D3KooWB7VnSBe4asxdJKSy767p9QYoEm5cLcaqYE3DsCCMs386-12D3KooWSsaFCtzDJUEhLQYDdwoFtdCMqqfk562UMvccFz12kYxU-1639251766039379435
2021-12-11T20:14:04.224Z	INFO	dagstore	dagstore@v0.4.3/handlers.go:36	failure handler: recovering shard	{"key": "baga6ea4seaqdjvcltqt3fwsb3z7ihaakwa3mkjmmb5knkhjsiallbk4lutrwiiy", "from_error": "failed to acquire reader of mount so we can return the accessor: failed to unseal deal 2081795: failed to unseal piece from sector 1318: unsealing piece: worker UnsealPiece call: storage call error 0: unsealing sector: acquire unsealed sector path (existing): allocate local sector for fetching: couldn't find a suitable path for a sector", "attempt": 0}
2021-12-11T20:14:04.225Z	INFO	dt-impl	impl/impl.go:303	12D3KooWSsaFCtzDJUEhLQYDdwoFtdCMqqfk562UMvccFz12kYxU: sending cancel channel to 12D3KooWB7VnSBe4asxdJKSy767p9QYoEm5cLcaqYE3DsCCMs386 for channel 12D3KooWB7VnSBe4asxdJKSy767p9QYoEm5cLcaqYE3DsCCMs386-12D3KooWSsaFCtzDJUEhLQYDdwoFtdCMqqfk562UMvccFz12kYxU-1639251766039379435
2021-12-11T20:14:04.225Z	INFO	markets	loggers/loggers.go:30	retrieval provider event	{"name": "ProviderEventCancelComplete", "deal ID": "1639251766264102770", "receiver": "12D3KooWB7VnSBe4asxdJKSy767p9QYoEm5cLcaqYE3DsCCMs386", "state": "DealStatusErrored", "message": "failed to load blockstore for piece baga6ea4seaqdjvcltqt3fwsb3z7ihaakwa3mkjmmb5knkhjsiallbk4lutrwiiy: failed to acquire shard for piece CID baga6ea4seaqdjvcltqt3fwsb3z7ihaakwa3mkjmmb5knkhjsiallbk4lutrwiiy: failed to unseal deal 2081795: failed to unseal piece from sector 1318: unsealing piece: worker UnsealPiece call: storage call error 0: unsealing sector: acquire unsealed sector path (existing): allocate local sector for fetching: couldn't find a suitable path for a sector"}
2021-12-11T20:14:04.226Z	ERROR	retrievalmarket_impl	dtutils/dtutils.go:74	processing dt event: normal shutdown of state machine
2021-12-11T20:14:04.260Z	DEBUG	advmgr	sector-storage/piece_provider.go:89	did not get storage reader;sector={Miner:1278 Number:1318}, err:failed to read sector {{1278 1318} 8} from remote(1): sector not found
2021-12-11T20:14:04.260Z	DEBUG	advmgr	sector-storage/piece_provider.go:169	result of first tryReadUnsealedPiece: r=<nil>, err=failed to read sector {{1278 1318} 8} from remote(1): sector not found
2021-12-11T20:14:04.260Z	DEBUG	advmgr	sector-storage/piece_provider.go:172	no unsealed sector file with unsealed piece, sector={ID:{Miner:1278 Number:1318} ProofType:8}, pieceOffset=0, size=8522825728
2021-12-11T20:14:04.275Z	ERROR	advmgr	sector-storage/piece_provider.go:192	failed to SectorsUnsealPiece: worker UnsealPiece call: storage call error 0: unsealing sector: acquire unsealed sector path (existing): allocate local sector for fetching: couldn't find a suitable path for a sector
2021-12-11T20:14:04.275Z	WARN	dagstore	dagstore/miner_api.go:164	failed to unseal deal 2081795: failed to unseal piece from sector 1318: unsealing piece: worker UnsealPiece call: storage call error 0: unsealing sector: acquire unsealed sector path (existing): allocate local sector for fetching: couldn't find a suitable path for a sector
2021-12-11T20:14:04.275Z	WARN	dagstore	dagstore@v0.4.3/dagstore_async.go:107	initialize: failed to fetch from mount upgrader	{"shard": "baga6ea4seaqdjvcltqt3fwsb3z7ihaakwa3mkjmmb5knkhjsiallbk4lutrwiiy", "error": "failed to unseal deal 2081795: failed to unseal piece from sector 1318: unsealing piece: worker UnsealPiece call: storage call error 0: unsealing sector: acquire unsealed sector path (existing): allocate local sector for fetching: couldn't find a suitable path for a sector", "errorVerbose": "failed to unseal deal 2081795:\n    github.com/filecoin-project/lotus/markets/dagstore.(*minerAPI).FetchUnsealedPiece\n        /home/stuart/lotus/markets/dagstore/miner_api.go:163\n  - failed to unseal piece from sector 1318:\n    github.com/filecoin-project/lotus/markets/sectoraccessor.(*sectorAccessor).UnsealSectorAt\n        /home/stuart/lotus/markets/sectoraccessor/sectoraccessor.go:75\n  - unsealing piece:\n    github.com/filecoin-project/lotus/extern/sector-storage.(*pieceProvider).ReadPiece\n        /home/stuart/lotus/extern/sector-storage/piece_provider.go:193\n  - worker UnsealPiece call: storage call error 0: unsealing sector: acquire unsealed sector path (existing): allocate local sector for fetching: couldn't find a suitable path for a sector"}
2021-12-11T20:14:04.276Z	WARN	dagstore	dagstore@v0.4.3/handlers.go:54	failure handler: failed to recover shard	{"key": "baga6ea4seaqdjvcltqt3fwsb3z7ihaakwa3mkjmmb5knkhjsiallbk4lutrwiiy", "attempt": 1}
2021-12-11T20:14:04.276Z	INFO	dagstore	dagstore@v0.4.3/handlers.go:32	failure handler: max attempts exceeded; skipping recovery	{"key": "baga6ea4seaqdjvcltqt3fwsb3z7ihaakwa3mkjmmb5knkhjsiallbk4lutrwiiy", "from_error": "failed to acquire reader of mount on initialization: failed to unseal deal 2081795: failed to unseal piece from sector 1318: unsealing piece: worker UnsealPiece call: storage call error 0: unsealing sector: acquire unsealed sector path (existing): allocate local sector for fetching: couldn't find a suitable path for a sector", "attempt": 1}
2021-12-11T20:14:04.616Z	INFO	dt-impl	impl/events.go:142	channel 12D3KooWB7VnSBe4asxdJKSy767p9QYoEm5cLcaqYE3DsCCMs386-12D3KooWSsaFCtzDJUEhLQYDdwoFtdCMqqfk562UMvccFz12kYxU-1639251766039379435: received cancel request, cleaning up channel
2021-12-11T20:15:41.076Z	INFO	dt_graphsync	graphsync/graphsync.go:552	12D3KooWB7VnSBe4asxdJKSy767p9QYoEm5cLcaqYE3DsCCMs386-12D3KooWSsaFCtzDJUEhLQYDdwoFtdCMqqfk562UMvccFz12kYxU-1639251766039379436, pull request queued, req=&{BCid:bafykbzacecgvrremltlsb3m7jvdvuwfba2m6hhv5j35h6mf7eybwtx52cgwqe Type:0 Paus:false Part:false Pull:true Stor:0xc02d68e108 Vouch:0xc02d68e138 VTyp:RetrievalDealProposal/1 XferID:1639251766039379436 RestartChannel:--0}
2021-12-11T20:15:41.076Z	INFO	dt-impl	impl/events.go:314	channel 12D3KooWB7VnSBe4asxdJKSy767p9QYoEm5cLcaqYE3DsCCMs386-12D3KooWSsaFCtzDJUEhLQYDdwoFtdCMqqfk562UMvccFz12kYxU-1639251766039379436: received new channel request from 12D3KooWB7VnSBe4asxdJKSy767p9QYoEm5cLcaqYE3DsCCMs386
2021-12-11T20:15:41.109Z	INFO	dt-impl	impl/events.go:393	data-transfer request validated, will create & start tracking channel	{"channelID": "12D3KooWB7VnSBe4asxdJKSy767p9QYoEm5cLcaqYE3DsCCMs386-12D3KooWSsaFCtzDJUEhLQYDdwoFtdCMqqfk562UMvccFz12kYxU-1639251766039379436", "payloadCid": "bafykbzacecgvrremltlsb3m7jvdvuwfba2m6hhv5j35h6mf7eybwtx52cgwqe"}
2021-12-11T20:15:41.109Z	INFO	markets	loggers/loggers.go:30	retrieval provider event	{"name": "ProviderEventOpen", "deal ID": "1639251766264102771", "receiver": "12D3KooWB7VnSBe4asxdJKSy767p9QYoEm5cLcaqYE3DsCCMs386", "state": "DealStatusNew", "message": ""}
2021-12-11T20:15:41.113Z	INFO	markets	loggers/loggers.go:30	retrieval provider event	{"name": "ProviderEventDealAccepted", "deal ID": "1639251766264102771", "receiver": "12D3KooWB7VnSBe4asxdJKSy767p9QYoEm5cLcaqYE3DsCCMs386", "state": "DealStatusUnsealing", "message": ""}
2021-12-11T20:15:41.115Z	INFO	dt_graphsync	graphsync/graphsync.go:1060	incoming graphsync request	{"peer": "12D3KooWB7VnSBe4asxdJKSy767p9QYoEm5cLcaqYE3DsCCMs386", "graphsync request id": 1, "data transfer channel id": "12D3KooWB7VnSBe4asxdJKSy767p9QYoEm5cLcaqYE3DsCCMs386-12D3KooWSsaFCtzDJUEhLQYDdwoFtdCMqqfk562UMvccFz12kYxU-1639251766039379436"}
2021-12-11T20:15:41.116Z	INFO	gs-queryexecutor	queryexecutor/queryexecutor.go:103	Empty task on peer request stack
2021-12-11T20:15:41.117Z	INFO	markets	loggers/loggers.go:30	retrieval provider event	{"name": "ProviderEventUnsealError", "deal ID": "1639251766264102771", "receiver": "12D3KooWB7VnSBe4asxdJKSy767p9QYoEm5cLcaqYE3DsCCMs386", "state": "DealStatusFailing", "message": "failed to load blockstore for piece baga6ea4seaqdjvcltqt3fwsb3z7ihaakwa3mkjmmb5knkhjsiallbk4lutrwiiy: failed to acquire shard for piece CID baga6ea4seaqdjvcltqt3fwsb3z7ihaakwa3mkjmmb5knkhjsiallbk4lutrwiiy: shard is in errored state; err: failed to acquire reader of mount on initialization: failed to unseal deal 2081795: failed to unseal piece from sector 1318: unsealing piece: worker UnsealPiece call: storage call error 0: unsealing sector: acquire unsealed sector path (existing): allocate local sector for fetching: couldn't find a suitable path for a sector"}
2021-12-11T20:15:41.121Z	INFO	dt-impl	impl/impl.go:286	close channel 12D3KooWB7VnSBe4asxdJKSy767p9QYoEm5cLcaqYE3DsCCMs386-12D3KooWSsaFCtzDJUEhLQYDdwoFtdCMqqfk562UMvccFz12kYxU-1639251766039379436
2021-12-11T20:15:41.121Z	INFO	dt-impl	impl/impl.go:303	12D3KooWSsaFCtzDJUEhLQYDdwoFtdCMqqfk562UMvccFz12kYxU: sending cancel channel to 12D3KooWB7VnSBe4asxdJKSy767p9QYoEm5cLcaqYE3DsCCMs386 for channel 12D3KooWB7VnSBe4asxdJKSy767p9QYoEm5cLcaqYE3DsCCMs386-12D3KooWSsaFCtzDJUEhLQYDdwoFtdCMqqfk562UMvccFz12kYxU-1639251766039379436
2021-12-11T20:15:41.121Z	INFO	markets	loggers/loggers.go:30	retrieval provider event	{"name": "ProviderEventCancelComplete", "deal ID": "1639251766264102771", "receiver": "12D3KooWB7VnSBe4asxdJKSy767p9QYoEm5cLcaqYE3DsCCMs386", "state": "DealStatusErrored", "message": "failed to load blockstore for piece baga6ea4seaqdjvcltqt3fwsb3z7ihaakwa3mkjmmb5knkhjsiallbk4lutrwiiy: failed to acquire shard for piece CID baga6ea4seaqdjvcltqt3fwsb3z7ihaakwa3mkjmmb5knkhjsiallbk4lutrwiiy: shard is in errored state; err: failed to acquire reader of mount on initialization: failed to unseal deal 2081795: failed to unseal piece from sector 1318: unsealing piece: worker UnsealPiece call: storage call error 0: unsealing sector: acquire unsealed sector path (existing): allocate local sector for fetching: couldn't find a suitable path for a sector"}
2021-12-11T20:15:41.123Z	ERROR	retrievalmarket_impl	dtutils/dtutils.go:74	processing dt event: normal shutdown of state machine
2021-12-11T20:15:41.489Z	INFO	dt-impl	impl/events.go:142	channel 12D3KooWB7VnSBe4asxdJKSy767p9QYoEm5cLcaqYE3DsCCMs386-12D3KooWSsaFCtzDJUEhLQYDdwoFtdCMqqfk562UMvccFz12kYxU-1639251766039379436: received cancel request, cleaning up channel
2021-12-11T20:17:32.889Z	ERROR	storageadapter	storageadapter/provider.go:380	timed out waiting for deal expiry
2021-12-11T20:21:14.252Z	INFO	graphsync	impl/graphsync.go:468	Graphsync ReceiveError from 12D3KooWB7VnSBe4asxdJKSy767p9QYoEm5cLcaqYE3DsCCMs386: stream reset

Lotus-miner logs:

2021-12-11T20:14:04.198Z	DEBUG	advmgr	sector-storage/sched_worker.go:280	task done	{"workerid": "d61a757f-8257-4502-8e40-b52129dbc0a7"}
2021-12-11T20:14:04.198Z	DEBUG	advmgr	sector-storage/manager.go:259	calling unseal sector on worker, sectoID={1278 1318}
2021-12-11T20:14:04.199Z	DEBUG	advmgr	sector-storage/sched.go:356	SCHED 0 queued; 4 open windows
2021-12-11T20:14:04.216Z	DEBUG	advmgr	sector-storage/manager.go:263	completed unseal sector {1278 1318}
2021-12-11T20:14:04.217Z	WARN	rpc	go-jsonrpc@v0.1.5/handler.go:279	error in RPC call to 'Filecoin.SectorsUnsealPiece': worker UnsealPiece call:
    github.com/filecoin-project/lotus/extern/sector-storage.(*Manager).SectorsUnsealPiece
        /home/stuart/lotus/extern/sector-storage/manager.go:267
  - storage call error 0: unsealing sector: acquire unsealed sector path (existing): allocate local sector for fetching: couldn't find a suitable path for a sector
2021-12-11T20:14:04.258Z	DEBUG	advmgr	sector-storage/manager.go:223	acquire unseal sector lock for sector {1278 1318}
2021-12-11T20:14:04.258Z	DEBUG	advmgr	sector-storage/manager.go:252	will schedule unseal for sector {1278 1318}
2021-12-11T20:14:04.258Z	DEBUG	advmgr	sector-storage/sched.go:356	SCHED 1 queued; 4 open windows
2021-12-11T20:14:04.263Z	DEBUG	advmgr	sector-storage/sched.go:452	SCHED windows: [{allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:0 cpuUse:0 cond:<nil> waiting:0} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:0 cpuUse:0 cond:<nil> waiting:0} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:0 cpuUse:0 cond:<nil> waiting:0} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:0 cpuUse:0 cond:<nil> waiting:0} todo:[]}]
2021-12-11T20:14:04.263Z	DEBUG	advmgr	sector-storage/sched.go:453	SCHED Acceptable win: [[2 3]]
2021-12-11T20:14:04.263Z	DEBUG	advmgr	sector-storage/sched.go:467	SCHED try assign sqi:0 sector 1318 to window 2
2021-12-11T20:14:04.263Z	DEBUG	advmgr	sector-storage/sched.go:476	SCHED ASSIGNED sqi:0 sector 1318 task seal/v0/unseal to window 2
2021-12-11T20:14:04.263Z	DEBUG	advmgr	sector-storage/sched_worker.go:375	assign worker sector 1318
2021-12-11T20:14:04.263Z	DEBUG	advmgr	sector-storage/sched.go:356	SCHED 0 queued; 4 open windows
2021-12-11T20:14:04.263Z	DEBUG	advmgr	sector-storage/manager.go:231	copy sealed/cache sector data for sector {1278 1318}
2021-12-11T20:14:04.267Z	DEBUG	advmgr	sector-storage/sched_worker.go:280	task done	{"workerid": "d61a757f-8257-4502-8e40-b52129dbc0a7"}
2021-12-11T20:14:04.267Z	DEBUG	advmgr	sector-storage/manager.go:259	calling unseal sector on worker, sectoID={1278 1318}
2021-12-11T20:14:04.267Z	DEBUG	advmgr	sector-storage/sched.go:356	SCHED 0 queued; 4 open windows
2021-12-11T20:14:04.273Z	DEBUG	advmgr	sector-storage/manager.go:263	completed unseal sector {1278 1318}
2021-12-11T20:14:04.273Z	WARN	rpc	go-jsonrpc@v0.1.5/handler.go:279	error in RPC call to 'Filecoin.SectorsUnsealPiece': worker UnsealPiece call:
    github.com/filecoin-project/lotus/extern/sector-storage.(*Manager).SectorsUnsealPiece
        /home/stuart/lotus/extern/sector-storage/manager.go:267
  - storage call error 0: unsealing sector: acquire unsealed sector path (existing): allocate local sector for fetching: couldn't find a suitable path for a sector


Lotus-worker logs:

2021-12-11T20:09:06.430Z	INFO	stores	stores/remote.go:229	Fetch http://192.168.1.95:2345/remote/sealed/s-t01278-1318 -> /seal/worker/sealed/fetching/s-t01278-1318
2021-12-11T20:14:03.171Z	DEBUG	stores	stores/util_unix.go:30	move sector data	{"from": "/seal/worker/sealed/fetching/s-t01278-1318", "to": "/seal/worker/sealed/s-t01278-1318"}
2021-12-11T20:14:03.182Z	INFO	stores	stores/remote.go:229	Fetch http://192.168.1.95:2345/remote/cache/s-t01278-1318 -> /seal/worker/cache/fetching/s-t01278-1318
2021-12-11T20:14:04.198Z	DEBUG	stores	stores/util_unix.go:30	move sector data	{"from": "/seal/worker/cache/fetching/s-t01278-1318", "to": "/seal/worker/cache/s-t01278-1318"}
2021-12-11T20:14:04.200Z	DEBUG	advmgr	sector-storage/worker_local.go:140	acquired sector {{1278 1318} 8} (e:6; a:0): {{0 0}  /seal/worker/sealed/s-t01278-1318 /seal/worker/cache/s-t01278-1318}
2021-12-11T20:14:04.213Z	DEBUG	advmgr	sector-storage/worker_local.go:442	worker will unseal piece now, sector={Miner:1278 Number:1318}
2021-12-11T20:14:04.269Z	DEBUG	advmgr	sector-storage/worker_local.go:140	acquired sector {{1278 1318} 8} (e:6; a:0): {{0 0}  /seal/worker/sealed/s-t01278-1318 /seal/worker/cache/s-t01278-1318}
2021-12-11T20:14:04.273Z	DEBUG	advmgr	sector-storage/worker_local.go:442	worker will unseal piece now, sector={Miner:1278 Number:1318}


Lotus-worker sealing paths:

ls -Alh /seal/worker/sealed
total 33G
drwxr-xr-x 2 stuart stuart 4.0K Dec 11 20:14 fetching
-rw-rw-r-- 1 stuart stuart  32G Dec 11 20:14 s-t01278-1318

ls -Alh /seal/worker/sealed/fetching
total 0

ls -Alh /seal/worker/cache/fetching
total 0

ls -Alh /seal/worker/cache
total 8.0K
drwxr-xr-x 2 stuart stuart 4.0K Dec 11 20:14 fetching
drwxr-xr-x 2 stuart stuart 4.0K Dec 11 20:14 s-t01278-1318

ls -Alh /seal/worker/cache/s-t01278-1318
total 74M
-rw-rw-r-- 1 stuart stuart   64 Dec 11 20:14 p_aux
-rw-rw-r-- 1 stuart stuart 9.2M Dec 11 20:14 sc-02-data-tree-r-last-0.dat
-rw-rw-r-- 1 stuart stuart 9.2M Dec 11 20:14 sc-02-data-tree-r-last-1.dat
-rw-rw-r-- 1 stuart stuart 9.2M Dec 11 20:14 sc-02-data-tree-r-last-2.dat
-rw-rw-r-- 1 stuart stuart 9.2M Dec 11 20:14 sc-02-data-tree-r-last-3.dat
-rw-rw-r-- 1 stuart stuart 9.2M Dec 11 20:14 sc-02-data-tree-r-last-4.dat
-rw-rw-r-- 1 stuart stuart 9.2M Dec 11 20:14 sc-02-data-tree-r-last-5.dat
-rw-rw-r-- 1 stuart stuart 9.2M Dec 11 20:14 sc-02-data-tree-r-last-6.dat
-rw-rw-r-- 1 stuart stuart 9.2M Dec 11 20:14 sc-02-data-tree-r-last-7.dat
-rw-rw-r-- 1 stuart stuart 1.1K Dec 11 20:14 t_aux

ls -Alh /seal/worker/cache/fetching
total 0

Repo Steps

  1. Run '...'
  2. Do '...'
  3. See error '...'
    ...
@benjaminh83 benjaminh83 mentioned this issue Dec 15, 2021
Closed
14 tasks
@benjaminh83 benjaminh83 mentioned this issue Jan 6, 2022
Closed
18 tasks
@jennijuju jennijuju added area/sealing need/analysis Hint: Needs Analysis and removed need/triage labels Jan 10, 2022
@jennijuju
Copy link
Member

might be somewhat related to #7938

@jennijuju
Copy link
Member

We should look into how the UNS job is schedule and find the sector data and start the job.
If anyone has thoughts or Q, find @magik6k in #fil-lotus-dev

@beck-8
Copy link
Contributor

beck-8 commented Mar 1, 2022

Describe the Bug

failed to load blockstore for piece baga6ea4seaqd4yfmzsdzozlpiafowmc6z6mh64wfl7tcney5rohvsabgviwc2mi: invalid header: malformed stream: invalid appearance of int token; expected start of map

Please see my steps, 100% reproducible @jennijuju @magik6k

version：lotus-miner version 1.14.2+2k+git.6347daf84

Logging Information

root@ubuntu:~# lotus-miner storage-deals list
ProposalCid  DealId  State              Client                                                                                  Size  Price          Duration
...spcrbwbu  2       StorageDealActive  t3setqboohk7dj4rhyifgmuernjotbdrxzzr35wjjuqaoitw5uamtmruiixnoa6nlqycywnuzfrxi3etsx3bvq  512B  0.0002594 FIL  518800
root@ubuntu:~# lotus-miner retrieval-deals list
Receiver                                              DealID               Payload      State              PricePerByte  BytesSent  Message
12D3KooWEJNLRCY8MPYjttH31tKH9Ww93UnmzTMDuAPEXVYD2JQb  1646120577260757912  ...aa5gwlhc  DealStatusErrored  0             0          failed to load blockstore for piece baga6ea4seaqd4yfmzsdzozlpiafowmc6z6mh64wfl7tcney5rohvsabgviwc2mi: invalid header: malformed stream: invalid appearance of int token; expected start of map
root@ubuntu:~# lotus-miner data-transfers list --show-failed
Sending Channels

ID                   Status     Sending To   Root Cid     Initiated?  Transferred  Voucher
1646120577259778241  Cancelled  ...XVYD2JQb  ...aa5gwlhc  N           0B           ...lIncrease":1048576,"UnsealPrice":"0"}

Receiving Channels

miner log

2022-03-01T03:43:00.200-0500    INFO    dt-impl impl/events.go:314      channel 12D3KooWEJNLRCY8MPYjttH31tKH9Ww93UnmzTMDuAPEXVYD2JQb-12D3KooWKWZMaYTCda54yC1MLqi5unqEXeuyWfdSpoW4R1BRHo61-1646120577259778241: received new channel request from 12D3KooWEJNLRCY8MPYjttH31tKH9Ww
93UnmzTMDuAPEXVYD2JQb
2022-03-01T03:43:00.209-0500    INFO    dt-impl impl/events.go:393      data-transfer request validated, will create & start tracking channel   {"channelID": "12D3KooWEJNLRCY8MPYjttH31tKH9Ww93UnmzTMDuAPEXVYD2JQb-12D3KooWKWZMaYTCda54yC1MLqi5unqEXeuyWfdSpoW4R1BRHo61-1646120
577259778241", "payloadCid": "bafk2bzacebtltydsplrijykspygstp6usex5x3ghlrddgimmleqlzaa5gwlhc"}
2022-03-01T03:43:00.209-0500    INFO    markets loggers/loggers.go:30   retrieval provider event        {"name": "ProviderEventOpen", "deal ID": "1646120577260757912", "receiver": "12D3KooWEJNLRCY8MPYjttH31tKH9Ww93UnmzTMDuAPEXVYD2JQb", "state": "DealStatusNew", "message":
 ""}
2022-03-01T03:43:00.211-0500    INFO    dt_graphsync    graphsync/graphsync.go:1060     incoming graphsync request      {"peer": "12D3KooWEJNLRCY8MPYjttH31tKH9Ww93UnmzTMDuAPEXVYD2JQb", "graphsync request id": 0, "data transfer channel id": "12D3KooWEJNLRCY8MPYjttH31tKH9Ww
93UnmzTMDuAPEXVYD2JQb-12D3KooWKWZMaYTCda54yC1MLqi5unqEXeuyWfdSpoW4R1BRHo61-1646120577259778241"}
2022-03-01T03:43:00.211-0500    INFO    gs-queryexecutor        queryexecutor/queryexecutor.go:103      Empty task on peer request stack
2022-03-01T03:43:00.213-0500    INFO    markets loggers/loggers.go:30   retrieval provider event        {"name": "ProviderEventDealAccepted", "deal ID": "1646120577260757912", "receiver": "12D3KooWEJNLRCY8MPYjttH31tKH9Ww93UnmzTMDuAPEXVYD2JQb", "state": "DealStatusUnsealin
g", "message": ""}
2022-03-01T03:43:00.219-0500    DEBUG   advmgr  sector-storage/piece_provider.go:89     did not get storage reader;sector={Miner:1000 Number:86}, err:failed to read sector {{1000 86} 5} from remote(1): sector not found
2022-03-01T03:43:00.219-0500    DEBUG   advmgr  sector-storage/piece_provider.go:169    result of first tryReadUnsealedPiece: r=<nil>, err=failed to read sector {{1000 86} 5} from remote(1): sector not found
2022-03-01T03:43:00.219-0500    DEBUG   advmgr  sector-storage/piece_provider.go:172    no unsealed sector file with unsealed piece, sector={ID:{Miner:1000 Number:86} ProofType:5}, pieceOffset=0, size=508
2022-03-01T03:43:00.219-0500    DEBUG   advmgr  sector-storage/manager.go:235   acquire unseal sector lock for sector {1000 86}
2022-03-01T03:43:00.219-0500    DEBUG   advmgr  sector-storage/manager.go:264   will schedule unseal for sector {1000 86}
2022-03-01T03:43:00.219-0500    DEBUG   advmgr  sector-storage/sched.go:356     SCHED 1 queued; 2 open windows
2022-03-01T03:43:00.220-0500    DEBUG   advmgr  sector-storage/sched.go:452     SCHED windows: [{allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:0 cpuUse:0 cond:<nil> waiting:0} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:0 cpuUse:0 cond:<nil> waiting:0} todo:[]}]
2022-03-01T03:43:00.220-0500    DEBUG   advmgr  sector-storage/sched.go:453     SCHED Acceptable win: [[0 1]]
2022-03-01T03:43:00.220-0500    DEBUG   advmgr  sector-storage/sched.go:467     SCHED try assign sqi:0 sector 86 to window 0
2022-03-01T03:43:00.220-0500    DEBUG   advmgr  sector-storage/sched.go:476     SCHED ASSIGNED sqi:0 sector 86 task seal/v0/unseal to window 0
2022-03-01T03:43:00.220-0500    DEBUG   advmgr  sector-storage/sched_worker.go:375      assign worker sector 86
2022-03-01T03:43:00.220-0500    DEBUG   advmgr  sector-storage/sched.go:356     SCHED 0 queued; 2 open windows
2022-03-01T03:43:00.220-0500    DEBUG   advmgr  sector-storage/manager.go:243   copy sealed/cache sector data for sector {1000 86}
2022-03-01T03:43:00.221-0500    DEBUG   advmgr  sector-storage/worker_local.go:140      acquired sector {{1000 86} 5} (e:6; a:0): {{0 0}  /root/.lotusminer/sealed/s-t01000-86 /root/.lotusminer/cache/s-t01000-86  }
2022-03-01T03:43:00.221-0500    DEBUG   advmgr  sector-storage/sched_worker.go:280      task done       {"workerid": "c5cc877c-d604-4fe2-a286-b3878b123b0b"}
2022-03-01T03:43:00.221-0500    DEBUG   advmgr  sector-storage/sched.go:356     SCHED 0 queued; 2 open windows
2022-03-01T03:43:00.221-0500    DEBUG   advmgr  sector-storage/manager.go:271   calling unseal sector on worker, sectoID={1000 86}
2022-03-01T03:43:00.223-0500    DEBUG   advmgr  sector-storage/worker_local.go:515      worker will unseal piece now, sector={Miner:1000 Number:86}
2022-03-01T03:43:00.223-0500    DEBUG   advmgr  sector-storage/worker_local.go:140      acquired sector {{1000 86} 5} (e:0; a:1): {{0 0} /root/.lotusminer/unsealed/s-t01000-86    }
2022-03-01T03:43:00.223-0500    DEBUG   advmgr  sector-storage/worker_local.go:140      acquired sector {{1000 86} 5} (e:14; a:0): {{0 0}  /root/.lotusminer/sealed/s-t01000-86 /root/.lotusminer/cache/s-t01000-86 /root/.lotusminer/update/s-t01000-86 }
2022-03-01T03:43:00.223 INFO filcrypto::proofs::api > fil_empty_sector_update_decode_from: start
2022-03-01T03:43:00.223 INFO filecoin_proofs::api::update > decode_from:start
2022-03-01T03:43:00.223 INFO storage_proofs_update::vanilla > out data path "/root/.lotusminer/unsealed/s-t01000-86", len 2052
2022-03-01T03:43:00.223 INFO storage_proofs_update::vanilla > replica path "/root/.lotusminer/update/s-t01000-86", len 2048
2022-03-01T03:43:00.223 INFO storage_proofs_update::vanilla > sector key path "/root/.lotusminer/sealed/s-t01000-86", len 2048
2022-03-01T03:43:00.225 INFO filecoin_proofs::api::update > decode_from:finish
2022-03-01T03:43:00.225 INFO filcrypto::proofs::api > fil_empty_sector_update_decode_from: finish
2022-03-01T03:43:00.225-0500    WARN    stores  stores/local.go:607     RemoveCopies: no primary copies of sector {1000 86} (sealed), not removing anything
2022-03-01T03:43:00.225-0500    WARN    stores  stores/local.go:607     RemoveCopies: no primary copies of sector {1000 86} (cache), not removing anything
2022-03-01T03:43:00.225-0500    DEBUG   advmgr  sector-storage/worker_local.go:528      worker has unsealed piece, sector={Miner:1000 Number:86}
2022-03-01T03:43:00.225-0500    DEBUG   advmgr  sector-storage/manager.go:275   completed unseal sector {1000 86}
2022-03-01T03:43:00.226-0500    DEBUG   advmgr  sector-storage/piece_provider.go:196    unsealed a sector file to read the piece, sector={ID:{Miner:1000 Number:86} ProofType:5}, pieceOffset=0, size=508
2022-03-01T03:43:00.226-0500    DEBUG   stores  stores/remote.go:602    Check local /root/.lotusminer/unsealed/s-t01000-86 (+0,512)
2022-03-01T03:43:00.226-0500    DEBUG   stores  stores/remote.go:607    fetched sector size /root/.lotusminer/unsealed/s-t01000-86 (+0,512)
2022-03-01T03:43:00.226-0500    DEBUG   stores  stores/remote.go:614    local partial file opened /root/.lotusminer/unsealed/s-t01000-86 (+0,512)
2022-03-01T03:43:00.226-0500    DEBUG   stores  stores/remote.go:622    check if partial file is allocated /root/.lotusminer/unsealed/s-t01000-86 (+0,512)
2022-03-01T03:43:00.226-0500    INFO    stores  stores/remote.go:625    returning piece reader for local unsealed piece sector={Miner:1000 Number:86}, (offset=0, size=512)
2022-03-01T03:43:00.226-0500    DEBUG   advmgr  sector-storage/piece_provider.go:207    got a reader to read unsealed piece, sector={ID:{Miner:1000 Number:86} ProofType:5}, pieceOffset=0, size=508
2022-03-01T03:43:00.226-0500    DEBUG   advmgr  sector-storage/piece_provider.go:212    returning reader to read unsealed piece, sector={ID:{Miner:1000 Number:86} ProofType:5}, pieceOffset=0, size=508
2022-03-01T03:43:00.227-0500    INFO    markets loggers/loggers.go:30   retrieval provider event        {"name": "ProviderEventUnsealError", "deal ID": "1646120577260757912", "receiver": "12D3KooWEJNLRCY8MPYjttH31tKH9Ww93UnmzTMDuAPEXVYD2JQb", "state": "DealStatusFailing",
 "message": "failed to load blockstore for piece baga6ea4seaqd4yfmzsdzozlpiafowmc6z6mh64wfl7tcney5rohvsabgviwc2mi: invalid header: malformed stream: invalid appearance of int token; expected start of map"}
2022-03-01T03:43:00.228-0500    INFO    dt-impl impl/impl.go:286        close channel 12D3KooWEJNLRCY8MPYjttH31tKH9Ww93UnmzTMDuAPEXVYD2JQb-12D3KooWKWZMaYTCda54yC1MLqi5unqEXeuyWfdSpoW4R1BRHo61-1646120577259778241
2022-03-01T03:43:00.228-0500    INFO    dt-impl impl/impl.go:303        12D3KooWKWZMaYTCda54yC1MLqi5unqEXeuyWfdSpoW4R1BRHo61: sending cancel channel to 12D3KooWEJNLRCY8MPYjttH31tKH9Ww93UnmzTMDuAPEXVYD2JQb for channel 12D3KooWEJNLRCY8MPYjttH31tKH9Ww93UnmzTMDuAPEXVYD2JQb-12
D3KooWKWZMaYTCda54yC1MLqi5unqEXeuyWfdSpoW4R1BRHo61-1646120577259778241
2022-03-01T03:43:00.228-0500    INFO    markets loggers/loggers.go:30   retrieval provider event        {"name": "ProviderEventCancelComplete", "deal ID": "1646120577260757912", "receiver": "12D3KooWEJNLRCY8MPYjttH31tKH9Ww93UnmzTMDuAPEXVYD2JQb", "state": "DealStatusErrore
d", "message": "failed to load blockstore for piece baga6ea4seaqd4yfmzsdzozlpiafowmc6z6mh64wfl7tcney5rohvsabgviwc2mi: invalid header: malformed stream: invalid appearance of int token; expected start of map"}
2022-03-01T03:43:00.229-0500    ERROR   retrievalmarket_impl    dtutils/dtutils.go:74   processing dt event: normal shutdown of state machine

Repo Steps

  • run localnet(lotus,lotus-miner|lotus,lotus-miner,lotus-worker always recurrent)
  • lotus-miner sectors pledge
  • waiting sectors active
  • closed miner config keepunsealed
  • lotus-miner sectors snap-up xx
  • lotus client deal --fast-retrieval=false bafk2bzacebtltydsplrijykspygstp6usex5x3ghlrddgimmleqlzaa5gwlhc t01000 0.0000000005 518400
  • lotus-miner storage-deals pending-publish --publish-now && lotus-miner sectors seal xx && waitting UpdateActivating
  • lotus client retrieve dataCid outputPath
  • error will occur

keepunsealed=false + snapdeal It will cause the data to not be retrieved after the height of 900, but this is not the problem now.

@RobQuistNL RobQuistNL mentioned this issue May 9, 2022
Open
18 tasks
@rjan90 rjan90 added this to the LM-Tech-Debt-Legacy-Markets milestone Mar 24, 2023
@TippyFlitsUK
Copy link
Contributor

Ongoing unsealing enhancements referenced here - #10316

@rjan90
Copy link
Contributor

rjan90 commented Jun 3, 2024

Closing this ticket as the Legacy Lotus/Lotus-Miner Markets sub-system reached EOL at the end of the 31st January 2023, and is being completely removed from the code here:

@rjan90 rjan90 closed this as completed Jun 3, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
area/markets/retrieval area/markets Area: Markets area/sealing kind/bug Kind: Bug LM-tech-debt need/analysis Hint: Needs Analysis
Projects
Lotus+Actors Board
Status: Closed
Lotus-Miner-V2
Status: 👀 In Review
Milestone
LM-Tech-Debt-Legacy-Markets
Development

No branches or pull requests
7 participants
@TippyFlitsUK @ZenGround0 @rjan90 @beck-8 @jennijuju @stuberman @Reiers