search

filecoin-project / boost

Boost is a tool for Filecoin storage providers to manage data storage and retrievals on Filecoin.
Other
111 stars 71 forks source link

flaky TestMultipleDealsConcurrent #905

Open dirkmc opened 2 years ago

dirkmc commented 2 years ago

https://app.circleci.com/pipelines/github/filecoin-project/boost/2470/workflows/fc0e1c49-b324-4c8e-ac3d-0bb18f692b49/jobs/21387/parallel-runs/0/steps/0-114

2022-10-18T14:54:30.059Z    ERROR   boost-storage-deal  logs/log.go:53  deal failed {"id": "08e86119-d83b-4298-8eeb-1e50700462c6", "err": "failed to verify CommP: commP mismatch, expected=baga6ea4seaqd5zcgjmj4oeonxknvhf2wpfbgtoojntqf4mumiydk7wvhyg3qoli, actual=baga6ea4seaqke7qzenku5qlf4xwci4rrriyie72ea5lpw7ct2tvf5pwnd2gdscy"}
2022-10-18T14:54:30.125Z    ERROR   boost-storage-deal  logs/log.go:53  deal failed {"id": "07162fac-d6c4-4e0f-a8d4-d735cb1d1700", "err": "failed to verify CommP: commP mismatch, expected=baga6ea4seaqj2y2swvi6vssdogmklh3llnkrrpkw45xles5ghoj4kb5jm3ldimy, actual=baga6ea4seaqd5zcgjmj4oeonxknvhf2wpfbgtoojntqf4mumiydk7wvhyg3qoli"}
2022-10-18T14:54:30.170Z    ERROR   boost-storage-deal  logs/log.go:53  deal failed {"id": "f6a2dead-9d3e-4471-85ae-6d8e72bf4b30", "err": "failed to verify CommP: commP mismatch, expected=baga6ea4seaqke7qzenku5qlf4xwci4rrriyie72ea5lpw7ct2tvf5pwnd2gdscy, actual=baga6ea4seaqj2y2swvi6vssdogmklh3llnkrrpkw45xles5ghoj4kb5jm3ldimy"}
    provider_test.go:1048: 
            Error Trace:    /home/circleci/project/storagemarket/provider_test.go:1048
                                        /home/circleci/project/storagemarket/provider_test.go:151
            Error:          Received unexpected error:
                            failed to verify CommP: commP mismatch, expected=baga6ea4seaqd5zcgjmj4oeonxknvhf2wpfbgtoojntqf4mumiydk7wvhyg3qoli, actual=baga6ea4seaqke7qzenku5qlf4xwci4rrriyie72ea5lpw7ct2tvf5pwnd2gdscy
            Test:           TestMultipleDealsConcurrent
2022-10-18T14:54:30.202Z    ERROR   boost-storage-deal  logs/log.go:53  failed to untag funds   {"id": "f6a2dead-9d3e-4471-85ae-6d8e72bf4b30", "err": "persisting untag funds log to DB: inserting funds log: sql: database is closed"}
2022-10-18T14:54:30.202Z    ERROR   boost-storage-deal  logs/log.go:53  failed to untag storage {"id": "f6a2dead-9d3e-4471-85ae-6d8e72bf4b30", "err": "persisting untag storage for deal to DB: getting untagged amount: sql: database is closed"}
2022-10-18T14:54:30.202Z    ERROR   boost-storage-deal  logs/log.go:53  failed to untag storage space   {"id": "56981315-5cfa-4ba2-bec7-7b1069d6a9c4", "err": "persisting untag storage for deal to DB: getting untagged amount: sql: database is closed"}
    controller.go:269: missing call(s) to *mock_types.MockChainDealManager.WaitForPublishDeals(is anything, is equal to QmXenrv93GUvaqpqdcKEXVz8SJJgLbbqqw9JCdRrA4Cm5J (cid.Cid), is equal to {baga6ea4seaqke7qzenku5qlf4xwci4rrriyie72ea5lpw7ct2tvf5pwnd2gdscy 4194304 false t01014 t01011 {[] false} 50000 800000 1 1 1} (market.DealProposal)) /home/circleci/project/storagemarket/smtestutil/mocks.go:217
    controller.go:269: missing call(s) to *mock_types.MockChainDealManager.WaitForPublishDeals(is anything, is equal to QmVaPTddRyjLjMoZnYufWc5M5CjyGNPmFEpp5HtPKEqZFG (cid.Cid), is equal to {baga6ea4seaqd5zcgjmj4oeonxknvhf2wpfbgtoojntqf4mumiydk7wvhyg3qoli 4194304 false t01014 t01011 {[] false} 50000 800000 1 1 1} (market.DealProposal)) /home/circleci/project/storagemarket/smtestutil/mocks.go:217
    controller.go:269: missing call(s) to *mock_types.MockChainDealManager.WaitForPublishDeals(is anything, is equal to QmTbEvXabndtyFm6zYZBvYg82jy9Po9bX8dXbyPAEWYh1f (cid.Cid), is equal to {baga6ea4seaqj2y2swvi6vssdogmklh3llnkrrpkw45xles5ghoj4kb5jm3ldimy 4194304 false t01014 t01011 {[] false} 50000 800000 1 1 1} (market.DealProposal)) /home/circleci/project/storagemarket/smtestutil/mocks.go:217
    controller.go:269: missing call(s) to *mock_types.MockPieceAdder.AddPiece(is anything, is equal to 4161536 (abi.UnpaddedPieceSize), is anything, is equal to {QmUo6yRfuCzKY9tJDCLEH8ytTh3Y9jbCG5RbbYgnt1JFWQ 34 0xc000902d98 {50000 800000} true} (api.PieceDealInfo)) /home/circleci/project/storagemarket/smtestutil/mocks.go:269
    controller.go:269: missing call(s) to *mock_types.MockPieceAdder.AddPiece(is anything, is equal to 4161536 (abi.UnpaddedPieceSize), is anything, is equal to {QmcdyB29uHtqMRZy47MrhaqFqHpHuPr7eUxWWPJbGpSRxg 59 0xc000902eb8 {50000 800000} true} (api.PieceDealInfo)) /home/circleci/project/storagemarket/smtestutil/mocks.go:269
    controller.go:269: missing call(s) to *mock_types.MockPieceAdder.AddPiece(is anything, is equal to 4161536 (abi.UnpaddedPieceSize), is anything, is equal to {QmTPwmaQtBLq9RXbvNyfj46X65YShYzMzn62FFbNYcieEm 68 0xc000902fd8 {50000 800000} true} (api.PieceDealInfo)) /home/circleci/project/storagemarket/smtestutil/mocks.go:269
    controller.go:269: missing call(s) to *mock_types.MockDealPublisher.Publish(is anything, is equal to {{baga6ea4seaqke7qzenku5qlf4xwci4rrriyie72ea5lpw7ct2tvf5pwnd2gdscy 4194304 false t01014 t01011 {[] false} 50000 800000 1 1 1} {2 [115 105 103]}} (market.ClientDealProposal)) /home/circleci/project/storagemarket/smtestutil/mocks.go:180
    controller.go:269: missing call(s) to *mock_types.MockDealPublisher.Publish(is anything, is equal to {{baga6ea4seaqd5zcgjmj4oeonxknvhf2wpfbgtoojntqf4mumiydk7wvhyg3qoli 4194304 false t01014 t01011 {[] false} 50000 800000 1 1 1} {2 [115 105 103]}} (market.ClientDealProposal)) /home/circleci/project/storagemarket/smtestutil/mocks.go:180
    controller.go:269: missing call(s) to *mock_types.MockDealPublisher.Publish(is anything, is equal to {{baga6ea4seaqj2y2swvi6vssdogmklh3llnkrrpkw45xles5ghoj4kb5jm3ldimy 4194304 false t01014 t01011 {[] false} 50000 800000 1 1 1} {2 [115 105 103]}} (market.ClientDealProposal)) /home/circleci/project/storagemarket/smtestutil/mocks.go:180
    controller.go:269: aborting test due to missing call(s)
2022-10-18T14:54:30.203Z    ERROR   boost-storage-deal  logs/log.go:53  deal failed {"id": "56981315-5cfa-4ba2-bec7-7b1069d6a9c4", "err": "failed to add index and announce deal: failed to persist deal state: sql: database is closed"}
2022-10-18T14:54:30.203Z    ERROR   boost-storage-deal  logs/log.go:53  failed to update deal state in DB   {"id": "56981315-5cfa-4ba2-bec7-7b1069d6a9c4", "err": "sql: database is closed"}
2022-10-18T14:54:30.203Z    ERROR   boost-storage-deal  logs/log.go:53  failed to untag funds   {"id": "56981315-5cfa-4ba2-bec7-7b1069d6a9c4", "err": "persisting untag funds for deal to DB: getting untagged amount: sql: database is closed"}
2022-10-18T14:54:30.203Z    ERROR   boost-storage-deal  logs/log.go:53  failed to untag storage {"id": "56981315-5cfa-4ba2-bec7-7b1069d6a9c4", "err": "persisting untag storage for deal to DB: getting untagged amount: sql: database is closed"}
--- FAIL: TestMultipleDealsConcurrent (2.56s)
jacobheun commented 1 year ago

Started looking into this a bit more as it's been popping up pretty frequently. The interesting bit here is that the commp mismatches are showing expected and actual commp from the other deals, so it's not an incorrect computation. I expect that the wires are getting crossed in the test somewhere and we're seeing some collision in data prep.