Boostd log error: "failed: looking for publish deal message"

[stuberman]

Checklist

• [X] This is not a question or a support request. If you have any boost related questions, please ask in the discussion forum.
• [X] This is not a new feature or enhancement request. If it is, please open a new idea discussion instead. New feature and enhancement requests would be entertained by the boost team after a thorough discussion only.
• [X] I have searched on the issue tracker and the discussion forum, and there is no existing related issue or discussion.
• [X] 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.
• [X] I did not make any code changes to boost.

Boost component

• [X] boost daemon - storage providers
• [ ] boost client
• [ ] boost UI
• [ ] boost data-transfer
• [ ] boost index-provider
• [ ] Other

Boost Version

boostd version 0.0.1+git.bc85712

Describe the Bug

Seeing error messages in Boostd log where it cannot find a publish deal message, although the deal is on chain and proving now.

This is for a deal renewal using Evergreen. A newer deal with the same piece was imported a few days ago as the logs show.

See the publish deal event on chain here: https://filfox.info/en/message/bafy2bzacedkxah7gesr7vn4dtmk7i6cxfftsgvkwiqxlfgslc4b7ssddqpokk

Logging Information

Log event
2022-05-30T19:30:23.608Z        ERROR   events  events/events_called.go:228     chain trigger (@H 1854399, triggered @ 1854405) failed: looking for publish deal message bafy2bzacedkxah7gesr7vn4dtmk7i6cxfftsgvkwiqxlfgslc4b7ssddqpokk: search msg failed: failed to load message: blockstore: block not found

Query Shard
boostd dagstore list-shards | grep baga6ea4seaqarrtrhcz754br24oq2dhp5dygslwkequonnfu3vnmvcw4jk6e4na
baga6ea4seaqarrtrhcz754br24oq2dhp5dygslwkequonnfu3vnmvcw4jk6e4na  Available 

Determined Piece CID for look up on chain
Piece CID baga6ea4seaqarrtrhcz754br24oq2dhp5dygslwkequonnfu3vnmvcw4jk6e4na

Result
https://filecoin.tools/baga6ea4seaqarrtrhcz754br24oq2dhp5dygslwkequonnfu3vnmvcw4jk6e4na

Deal Details
Details
Piece CID baga6ea4seaqarrtrhcz754br24oq2dhp5dygslwkequonnfu3vnmvcw4jk6e4na
Payload CID QmTweiMDiLbBebsDRXAJCskpzAqtyWGDu2qAuayuc1nDas
Deal ID 2045030
Miner ID f01278
Client f01037760
Client Address f3spci2tzjzhedgvxsoxg4hprrkyszdce5dacaxg4ndkvpshpuma2uf6c4fmk2lvvrobnz5bvr6j5hfeccpupq
Piece Size 34359738368
Verified Deal False
Start Deal 849434
End Deal 1917228
Price 320000000000
Miner Collateral 8390695415760894
Client Collateral 0
Status Active

Storage repo shows files exist for new deal and sector
ls -Alh /pool/storage/unsealed/s-t01278-4433
-rw-rw-r-- 1 stuart stuart 33G May 28 09:18 /pool/storage/unsealed/s-t01278-4433

ls -Alh /pool/storage/sealed/s-t01278-4433
-rw-rw-r-- 1 stuart stuart 32G May 28 09:14 /pool/storage/sealed/s-t01278-4433

ls -Alh /pool/storage/cache/s-t01278-4433
total 74M
-rw-rw-r-- 1 stuart stuart   64 May 28 09:14 p_aux
-rw-rw-r-- 1 stuart stuart 9.2M May 28 09:14 sc-02-data-tree-r-last-0.dat
-rw-rw-r-- 1 stuart stuart 9.2M May 28 09:14 sc-02-data-tree-r-last-1.dat
-rw-rw-r-- 1 stuart stuart 9.2M May 28 09:14 sc-02-data-tree-r-last-2.dat
-rw-rw-r-- 1 stuart stuart 9.2M May 28 09:14 sc-02-data-tree-r-last-3.dat
-rw-rw-r-- 1 stuart stuart 9.2M May 28 09:14 sc-02-data-tree-r-last-4.dat
-rw-rw-r-- 1 stuart stuart 9.2M May 28 09:14 sc-02-data-tree-r-last-5.dat
-rw-rw-r-- 1 stuart stuart 9.2M May 28 09:14 sc-02-data-tree-r-last-6.dat
-rw-rw-r-- 1 stuart stuart 9.2M May 28 09:14 sc-02-data-tree-r-last-7.dat
-rw-rw-r-- 1 stuart stuart 1020 May 28 09:14 t_aux

On chain log for this new sector 
lotus-miner sectors status --on-chain-info --log 4433
SectorID:   4433
Status:     Proving
CIDcommD:   baga6ea4seaqarrtrhcz754br24oq2dhp5dygslwkequonnfu3vnmvcw4jk6e4na
CIDcommR:   bagboea4b5abcbg6ozfbzng6xmvwir2gripyii7jttx6x4izvqbqb3kutfbqp7lqe
Ticket:     1737c3fa37ddffabcdbe98eb406296909db4bdd526e4a5ca19bd43a31033401d
TicketH:    1845913
Seed:       e27e7e466014f23381617d3d5cd75c28389fc4aabf694d7519820bfc7cfee13c
SeedH:      1847330
Precommit:  bafy2bzaceazbbcesjbblamn4rh3gdf5xmhv6d4pnpan66677s66zg3hdsttpc
Commit:     bafy2bzacea4lzppi7qo46geq5cdik6nqzn2dpr6el63khsefgkiteatrjxr6s
Deals:      [6545053]
Retries:    0

Sector On Chain Info
SealProof:      8
Activation:     1847431
Expiration:     3388908
DealWeight:     0
VerifiedDealWeight: 52739037298950144
InitialPledge:      1.679820936314084586 FIL

Expiration Info
OnTime:     3389088
Early:      0
--------
Event Log:
0.  2022-05-28 03:59:01 +0000 UTC:  [event;sealing.SectorStart] {"User":{"ID":4433,"SectorType":8}}
1.  2022-05-28 03:59:01 +0000 UTC:  [event;sealing.SectorAddPiece]  {"User":{}}
2.  2022-05-28 04:06:56 +0000 UTC:  [event;sealing.SectorPieceAdded]    {"User":{"NewPieces":[{"Piece":{"Size":34359738368,"PieceCID":{"/":"baga6ea4seaqarrtrhcz754br24oq2dhp5dygslwkequonnfu3vnmvcw4jk6e4na"}},"DealInfo":{"PublishCid":{"/":"bafy2bzacedkxah7gesr7vn4dtmk7i6cxfftsgvkwiqxlfgslc4b7ssddqpokk"},"DealID":6545053,"DealProposal":{"PieceCID":{"/":"baga6ea4seaqarrtrhcz754br24oq2dhp5dygslwkequonnfu3vnmvcw4jk6e4na"},"PieceSize":34359738368,"VerifiedDeal":true,"Client":"f1pkrmygbvweykpjcut36lf7ewgqdfhjklbhvepda","Provider":"f01278","Label":"QmTweiMDiLbBebsDRXAJCskpzAqtyWGDu2qAuayuc1nDas","StartEpoch":1854000,"EndEpoch":3388908,"StoragePricePerEpoch":"0","ProviderCollateral":"10284476142529728","ClientCollateral":"0"},"DealSchedule":{"StartEpoch":1854000,"EndEpoch":3388908},"KeepUnsealed":true}}]}}
3.  2022-05-28 04:06:56 +0000 UTC:  [event;sealing.SectorStartPacking]  {"User":{}}
4.  2022-05-28 04:06:56 +0000 UTC:  [event;sealing.SectorPacked]    {"User":{"FillerPieces":null}}
5.  2022-05-28 04:06:56 +0000 UTC:  [event;sealing.SectorTicket]    {"User":{"TicketValue":"FzfD+jfd/6vNvpjrQGKWkJ20vdUm5KXKGb1DoxAzQB0=","TicketEpoch":1845913}}
6.  2022-05-28 06:51:38 +0000 UTC:  [event;sealing.SectorPreCommit1]    {"User":{"PreCommit1Out":"eyJfbG90dXNfU2VhbFJhbmRvbW5lc3MiOiJGemZEK2pmZC82dk52cGpyUUdLV2tKMjB2ZFVtNUtYS0diMURveEF6UUIwPSIsImNvbW1fZCI6WzgsMTk4LDExMyw1NiwxNzksMjU0LDI0MCw0OSwyMTUsMjksMTMsMTIsMjM5LDIzMiwyNDAsMTA1LDQ2LDIwMiwzNiw0MCwyMzAsMTgwLDE4MCwyMjEsOTAsMjAyLDEzOCwyMjAsNzQsMTg4LDc4LDUyXSwiY29uZmlnIjp7ImlkIjoidHJlZS1kIiwicGF0aCI6Ii9zZWFsL3dvcmtlci9jYWNoZS9zLXQwMTI3OC00NDMzIiwicm93c190b19kaXNjYXJkIjo3LCJzaXplIjoyMTQ3NDgzNjQ3fSwibGFiZWxzIjp7IlN0YWNrZWREcmczMkdpQlYxIjp7Il9oIjpudWxsLCJsYWJlbHMiOlt7ImlkIjoibGF5ZXItMSIsInBhdGgiOiIvc2VhbC93b3JrZXIvY2FjaGUvcy10MDEyNzgtNDQzMyIsInJvd3NfdG9fZGlzY2FyZCI6Nywic2l6ZSI6MTA3Mzc0MTgyNH0seyJpZCI6ImxheWVyLTIiLCJwYXRoIjoiL3NlYWwvd29ya2VyL2NhY2hlL3MtdDAxMjc4LTQ0MzMiLCJyb3dzX3RvX2Rpc2NhcmQiOjcsInNpemUiOjEwNzM3NDE4MjR9LHsiaWQiOiJsYXllci0zIiwicGF0aCI6Ii9zZWFsL3dvcmtlci9jYWNoZS9zLXQwMTI3OC00NDMzIiwicm93c190b19kaXNjYXJkIjo3LCJzaXplIjoxMDczNzQxODI0fSx7ImlkIjoibGF5ZXItNCIsInBhdGgiOiIvc2VhbC93b3JrZXIvY2FjaGUvcy10MDEyNzgtNDQzMyIsInJvd3NfdG9fZGlzY2FyZCI6Nywic2l6ZSI6MTA3Mzc0MTgyNH0seyJpZCI6ImxheWVyLTUiLCJwYXRoIjoiL3NlYWwvd29ya2VyL2NhY2hlL3MtdDAxMjc4LTQ0MzMiLCJyb3dzX3RvX2Rpc2NhcmQiOjcsInNpemUiOjEwNzM3NDE4MjR9LHsiaWQiOiJsYXllci02IiwicGF0aCI6Ii9zZWFsL3dvcmtlci9jYWNoZS9zLXQwMTI3OC00NDMzIiwicm93c190b19kaXNjYXJkIjo3LCJzaXplIjoxMDczNzQxODI0fSx7ImlkIjoibGF5ZXItNyIsInBhdGgiOiIvc2VhbC93b3JrZXIvY2FjaGUvcy10MDEyNzgtNDQzMyIsInJvd3NfdG9fZGlzY2FyZCI6Nywic2l6ZSI6MTA3Mzc0MTgyNH0seyJpZCI6ImxheWVyLTgiLCJwYXRoIjoiL3NlYWwvd29ya2VyL2NhY2hlL3MtdDAxMjc4LTQ0MzMiLCJyb3dzX3RvX2Rpc2NhcmQiOjcsInNpemUiOjEwNzM3NDE4MjR9LHsiaWQiOiJsYXllci05IiwicGF0aCI6Ii9zZWFsL3dvcmtlci9jYWNoZS9zLXQwMTI3OC00NDMzIiwicm93c190b19kaXNjYXJkIjo3LCJzaXplIjoxMDczNzQxODI0fSx7ImlkIjoibGF5ZXItMTAiLCJwYXRoIjoiL3NlYWwvd29ya2VyL2NhY2hlL3MtdDAxMjc4LTQ0MzMiLCJyb3dzX3RvX2Rpc2NhcmQiOjcsInNpemUiOjEwNzM3NDE4MjR9LHsiaWQiOiJsYXllci0xMSIsInBhdGgiOiIvc2VhbC93b3JrZXIvY2FjaGUvcy10MDEyNzgtNDQzMyIsInJvd3NfdG9fZGlzY2FyZCI6Nywic2l6ZSI6MTA3Mzc0MTgyNH1dfX0sInJlZ2lzdGVyZWRfcHJvb2YiOiJTdGFja2VkRHJnMzJHaUJWMV8xIn0="}}
7.  2022-05-28 07:09:18 +0000 UTC:  [event;sealing.SectorPreCommit2]    {"User":{"Sealed":{"/":"bagboea4b5abcbg6ozfbzng6xmvwir2gripyii7jttx6x4izvqbqb3kutfbqp7lqe"},"Unsealed":{"/":"baga6ea4seaqarrtrhcz754br24oq2dhp5dygslwkequonnfu3vnmvcw4jk6e4na"}}}
8.  2022-05-28 07:09:20 +0000 UTC:  [event;sealing.SectorPreCommitted]  {"User":{"Message":{"/":"bafy2bzaceazbbcesjbblamn4rh3gdf5xmhv6d4pnpan66677s66zg3hdsttpc"},"PreCommitDeposit":"115066024855428017","PreCommitInfo":{"SealProof":8,"SectorNumber":4433,"SealedCID":{"/":"bagboea4b5abcbg6ozfbzng6xmvwir2gripyii7jttx6x4izvqbqb3kutfbqp7lqe"},"SealRandEpoch":1845913,"DealIDs":[6545053],"Expiration":3388908,"ReplaceCapacity":false,"ReplaceSectorDeadline":0,"ReplaceSectorPartition":0,"ReplaceSectorNumber":0}}}
9.  2022-05-28 07:13:00 +0000 UTC:  [event;sealing.SectorPreCommitLanded]   {"User":{"TipSet":"AXGg5AIggbhT7oxIJ/75FJkAIzO28K/HAxpdGztv/qr169zvfAgBcaDkAiDC9EpAXLjKUJVdF4vKu1ikHU3eEro1xBrqy7yrRILcRgFxoOQCIDjALfHn6QoT4P0jHWXpmEnIGNYHNc2fQbxf1n7U8nxYAXGg5AIgsNjh+7l9yyhgT8cs0dh80RWP7wEfN5E2ESvxg1vq6hMBcaDkAiBaUFLjkJXz2vxpmO6Io13PCHYpUiooOFPOXF21b1eTxAFxoOQCICB9TeWqM4cjZZ73Rrz0Rg24P4W7ZIXwdkB5JnH4JfJQ"}}
10. 2022-05-28 08:27:59 +0000 UTC:  [event;sealing.SectorSeedReady] {"User":{"SeedValue":"4n5+RmAU8jOBYX09XNdcKDifxKq/aU11GYIL/Hz+4Tw=","SeedEpoch":1847330}}
11. 2022-05-28 09:04:06 +0000 UTC:  [event;sealing.SectorProofReady]    {"User":{"Proof":"o6JDIqAPVcW9E/B4dvs1wktzgIM8lYf3nOlFPzcnqCwQizXRJXh4HTxw+/DFVQqXjTbmqld3E3csvwavbqncJ85lGfGXjVld7eQ2qow+P0aLlr4U3A4PUxL0Sl4BdXAlBQfte9USM827/Dez5fF8iOMbKGg6FLzwk58cTfDIP5EVauFF08muRNVAFW/LRBsji2EgCzcInWFaRGy+yRrABc+OQ5y9kTU3cUlz+MMD0BppcQ2Y+lxHcgeHvGNp8HccgtkrXBL1lo9P5B69hlLS53X6zttQ7TV0i4qeBf1Fc6T6q6vXVL98QXKtcJZM2b4Fsx6wl8VaVBJJk3xNLT6vGsa6/pGg53nuP01P3YvFW542GuhZx8vj1dzgz0W2oLDvEnav3U+sePkXNtHSxRJKKY69kfBF2dQ0UNZqHu0dMWE4qJPADgikjmYI6zisljOeqa+mjNULIc4jLqc5UBr5l5IR2BeiD5v7A6SXsj+v2DYLnmik0Ig4Zz7YAST8kLmwoD0WJMlABhkKQuY3BaJf127vX9f0U1EJuQCM9J+I3d4/2KY6B+OEvYBietJdEkAZrXHS/Ol1YtY3nhccPMXmwo7wPK6Uy4hzvgYYREwqDmRaXloUdCI3BjWWu3oYJVNcCYtDrtWbIDekCJj1A6hNm0dAnP/NwmflhyuMaVD5V1onSg2jCMlcyE1DR0a1hPbxgOH98uS6kPG3LKpIqLOypV6/QO/g85NipJlGZkpWCUk/Mk7WhhkMHa7iGYinLvV8oXxrCLWtsOawhjussAgeAgYKBq/NBvMJypbBD6EHDX3OOc5qjrwS8rTGplzoanDsuB4ec5Nd/HMmnG1W5ghKc5GpyFBWAnXwo/7oaReUkYmtqewAdgqb7iLhBOT9+SwcFnLAliic7DHCgFXBAM2/l1v02zpEp8AfN/rQS655KIiSigkbG4O3sbceCfn/CBKliLAytWz14m+QsqiPKSOIcgdUFfVBkm7efYuiKIduA35eWrP86LPTQ7OSrpral595s0VH0zSn9Q8gxCxd9FsI5/xNiwjx+hxQNkSCvuzQGF+cEzobHZ+9OHjBCYZXSd83lYXGSytbgRyXVpOk01fABBVzRgdDW0m30p//imsTg8CZXZpG9Q169gQ81cRfJF8qAO+jUjBs2cpL0mU7WgkMnKJsKzc3yl8/FTsLrGcb4m1fhDIJpmi3qJEApDOn+8jqofiotaeokRXxihAyts32kCZb1/0m8S9H3nhU298i6y765kgvtJ6HFb+W1Gqsm2XzkpwKmiuf8JvFBe4tv8q3gexg1IGHZVJOx5Z1juR1U6H8XZZgoM9XRF2VQzSlMD4Fj+31Hfrce0bcWuvfxv9s6zRbSPuMi/x+NwLgCJlQuksUT9X3gRHnFeUkAUqsNk8NCM0LmXd4qzUnoMi0zQAFrbAOdfYZn7Ni3BeltW5PM4CNN/1G7w4CZKOBERSPMIx9kAah1vJYDvjp+72LTvSfaeptafuWoUK4JstZrg7Ij/NwxI21dL4orV2iIbdnuOBbkf7KhIlo+DCBQUkaR0hPJAuXWL7heSBZV9woCeJcDmfYaIar8bGoIjrBeEu6X5g1kwGlQnsDRxypNT3LvkyiD6F9TwJ0qeFK9kYyOqPvzhrlCB5ZRy7Vbco30TTK/NjUASMw++ya0UjeRJSuWx8HrPbtdQG0MgwwjYRXAeI4liCsUbeSaGfT/ovXCMGoFpOoiOMCYPcxrPzy+j/MHR1oK783iFyLYhfw6bBdp4vm1f+vn/zGx/2yk5FPQjF3YJZsrUORNe5CoHS1MSpYU9dLa72Rpa5P1jjAuIQZJWbpwVYU9k/gSFi8WWJjmOVCn0hWidG/5aEWairDEGv7+M2H0bVVDm3PIoAkgIA/Kugxljuy6EO30dessPvtTCPmTU/NF/3YGcsN6EL6l21wzx9B5yIrKH7aaJpZ92TOfJkVJQ5p3+XRk02+5x9vN5jzJrqllaE+D9pqbSA27utTM3IPilzRV1sLQwgSv1zFsh/9MUdxgvM5ZQdipyVaxPgA2eRWiPO5fEzRDWm8kW9g31bDgCCobxTyzoNa5eh0tCUZ8Svg1a+IZXdNR+bb1Qrn+7DBhkUMkhTK0XL+X+7CkClm2TeMopzIm1lMSi9UIVQYKDzn5/Mj4+lEu+Nt64TVEe91CWiokagh0/mruY6KfdLOuazyZiKpIn42DciwQNXopchjc65mf4XDGTj6XH1vibVatvtg2ccl/E11WI0FJA415xfNTIvM4NOQDVN5v8PZS0bqjpcSFGek5wovP/NKIUQ9ocMHXQWN9HFnSbt/gGCHEjE49G97t1NdD5DgK79wca6z2jujq/GlG1Fg/VH3lvA8tYuRMy6Ll/ig80VtAaWimwhXd+nFkGmIeKIKVt27mW36443g+lBxzpUAgmQj2j9/FJ8Xssaa+Gpw4qF3Ma7PCikCM3QW6p2V4tsgWVy9M+eBsbVZ2QEQU1SNte7zsUrcs1UOcspMlI3QVRYVXKYDUP1EfyBC1gtCPGcT+muSSzNABfxdtefGggC19iNS2Ews"}}
12. 2022-05-28 09:14:53 +0000 UTC:  [event;sealing.SectorFinalized] {"User":{}}
13. 2022-05-28 09:14:54 +0000 UTC:  [event;sealing.SectorCommitSubmitted]   {"User":{"Message":{"/":"bafy2bzacea4lzppi7qo46geq5cdik6nqzn2dpr6el63khsefgkiteatrjxr6s"}}}
14. 2022-05-28 09:18:30 +0000 UTC:  [event;sealing.SectorProving]   {"User":{}}
15. 2022-05-28 09:18:30 +0000 UTC:  [event;sealing.SectorFinalized] {"User":{}}

Repo Steps

1. Run '...'
2. Do '...'
3. See error '...' ...

[dirkmc]

This log line indicates that lotus has tried to look up the publish deal message in the blockstore that contains chain messages, and hasn't been able to find the message.

2022-05-30T19:30:23.608Z        ERROR   events  events/events_called.go:228     chain trigger (@H 1854399, triggered @ 1854405) failed: looking for publish deal message bafy2bzacedkxah7gesr7vn4dtmk7i6cxfftsgvkwiqxlfgslc4b7ssddqpokk: search msg failed: failed to load message: blockstore: block not found

The only reason I can think of why that might happen is that the chain got out of sync.

I'd recommend asking the client to switch to use the v1.2.0 protocol. With deals made over the v1.2.0 protocol (and the latest RC of Boost) you can retry deals that fail at the publish stage.

[LexLuthr]

Please reopen if issue persists in Boost deals