search

filecoin-project / lotus

Reference implementation of the Filecoin protocol, written in Go
https://lotus.filecoin.io/
Other
2.85k stars 1.27k forks source link

Multiple Graphsync ReceiveError messages since 1.5.0 upgrade. #5722

Closed TippyFlitsUK closed 3 years ago

TippyFlitsUK commented 3 years ago

I am seeing multiple deal failures and Graphysync ReceiveError messages since the 1.5.0 upgrade. I have included a log snippet below.

I am not sure if this is a general issue or as a result of an individual error with a specific client. I have only received deals from one client since the upgrade so am currently unable to make a simple comparison. The client ID is f3qpseg3qlpckug75qqas6jsce4up6kg5bo4yaefwnxo4fwx2n5f7jpkkrzy37jxnshkd6mazxso2rxfoaxska

This appears to be very similar to #4593 and #4856

2021-03-04T21:31:38.053Z    INFO    storagemarket_impl  impl/provider.go:211    Handling storage deal proposal!
2021-03-04T21:31:38.055Z    INFO    markets loggers/loggers.go:20   storage provider event  {"name": "ProviderEventOpen", "proposal CID": "bafyreihyrwd2ysd4afrijl4pzfpkrbs6s6os4xvg24d3jikzaxey6rfjdq", "state": "StorageDealValidating", "message": ""}
2021-03-04T21:31:38.067Z    INFO    markets loggers/loggers.go:20   storage provider event  {"name": "ProviderEventDealDeciding", "proposal CID": "bafyreihyrwd2ysd4afrijl4pzfpkrbs6s6os4xvg24d3jikzaxey6rfjdq", "state": "StorageDealAcceptWait", "message": ""}
2021-03-04T21:31:38.096Z    INFO    markets loggers/loggers.go:20   storage provider event  {"name": "ProviderEventDataRequested", "proposal CID": "bafyreihyrwd2ysd4afrijl4pzfpkrbs6s6os4xvg24d3jikzaxey6rfjdq", "state": "StorageDealWaitingForData", "message": ""}
2021-03-04T21:31:38.536Z    INFO    dt-impl impl/events.go:338  received new channel request from 12D3KooWQzMJbLno5cudsqTUEsrycN1U3gHVtayRj4dZjRnEvrfc
2021-03-04T21:31:38.538Z    INFO    dt-impl impl/events.go:21   channel 12D3KooWQzMJbLno5cudsqTUEsrycN1U3gHVtayRj4dZjRnEvrfc-12D3KooWKG9mQfyAAyCc3huFVMMzpKCdbgLhED6PYFhwM7q8Ab3W-113: opened
2021-03-04T21:31:38.538Z    INFO    markets loggers/loggers.go:20   storage provider event  {"name": "ProviderEventDataTransferInitiated", "proposal CID": "bafyreihyrwd2ysd4afrijl4pzfpkrbs6s6os4xvg24d3jikzaxey6rfjdq", "state": "StorageDealTransferring", "message": ""}
2021-03-04T21:32:06.159Z    INFO    miner   miner/miner.go:383  Time delta between now and our mining base: 6s (nulls: 0)
2021-03-04T21:32:36.059Z    INFO    miner   miner/miner.go:383  Time delta between now and our mining base: 6s (nulls: 0)
2021-03-04T21:33:06.076Z    INFO    miner   miner/miner.go:383  Time delta between now and our mining base: 6s (nulls: 0)
2021-03-04T21:33:36.478Z    INFO    miner   miner/miner.go:383  Time delta between now and our mining base: 6s (nulls: 0)
2021-03-04T21:34:06.495Z    INFO    miner   miner/miner.go:383  Time delta between now and our mining base: 6s (nulls: 0)
2021-03-04T21:34:36.511Z    INFO    miner   miner/miner.go:383  Time delta between now and our mining base: 6s (nulls: 0)
2021-03-04T21:35:06.156Z    INFO    miner   miner/miner.go:383  Time delta between now and our mining base: 6s (nulls: 0)
2021-03-04T21:35:18.338Z    INFO    graphsync   impl/graphsync.go:299   Graphsync ReceiveError: stream reset
2021-03-04T21:35:21.421Z    INFO    graphsync   impl/graphsync.go:299   Graphsync ReceiveError: message too large
2021-03-04T21:35:36.061Z    INFO    miner   miner/miner.go:383  Time delta between now and our mining base: 6s (nulls: 0)
2021-03-04T21:36:05.426Z    INFO    graphsync   impl/graphsync.go:299   Graphsync ReceiveError: message too large
2021-03-04T21:36:06.135Z    INFO    miner   miner/miner.go:383  Time delta between now and our mining base: 6s (nulls: 0)
2021-03-04T21:36:07.596Z    ERROR   dt-impl impl/receiver.go:110    received error message on data transfer: unmarshaling t.Request pointer: stream reset
2021-03-04T21:36:07.604Z    ERROR   dt-impl impl/receiver.go:110    received error message on data transfer: stream reset
2021-03-04T21:36:36.481Z    INFO    miner   miner/miner.go:383  Time delta between now and our mining base: 6s (nulls: 0)
2021-03-04T21:36:44.849Z    INFO    graphsync   impl/graphsync.go:299   Graphsync ReceiveError: message too large
2021-03-04T21:37:06.078Z    INFO    miner   miner/miner.go:383  Time delta between now and our mining base: 6s (nulls: 0)
2021-03-04T21:37:26.438Z    INFO    graphsync   impl/graphsync.go:299   Graphsync ReceiveError: message too large
2021-03-04T21:37:36.314Z    INFO    miner   miner/miner.go:383  Time delta between now and our mining base: 6s (nulls: 0)
2021-03-04T21:38:06.080Z    INFO    miner   miner/miner.go:383  Time delta between now and our mining base: 6s (nulls: 0)
2021-03-04T21:38:06.842Z    INFO    graphsync   impl/graphsync.go:299   Graphsync ReceiveError: message too large
2021-03-04T21:38:36.055Z    INFO    miner   miner/miner.go:383  Time delta between now and our mining base: 6s (nulls: 0)
2021-03-04T21:38:39.707Z    INFO    graphsync   impl/graphsync.go:299   Graphsync ReceiveError: message too large
2021-03-04T21:39:06.363Z    INFO    miner   miner/miner.go:383  Time delta between now and our mining base: 6s (nulls: 0)
2021-03-04T21:39:11.018Z    INFO    graphsync   impl/graphsync.go:299   Graphsync ReceiveError: message too large
2021-03-04T21:39:36.046Z    INFO    miner   miner/miner.go:383  Time delta between now and our mining base: 6s (nulls: 0)
2021-03-04T21:39:45.380Z    INFO    graphsync   impl/graphsync.go:299   Graphsync ReceiveError: message too large
2021-03-04T21:40:06.153Z    INFO    miner   miner/miner.go:383  Time delta between now and our mining base: 6s (nulls: 0)
2021-03-04T21:40:19.105Z    INFO    graphsync   impl/graphsync.go:299   Graphsync ReceiveError: message too large
2021-03-04T21:40:36.029Z    INFO    miner   miner/miner.go:383  Time delta between now and our mining base: 6s (nulls: 0)
2021-03-04T21:41:02.863Z    INFO    graphsync   impl/graphsync.go:299   Graphsync ReceiveError: message too large
2021-03-04T22:12:03.547Z    INFO    storagemarket_impl  impl/provider.go:211    Handling storage deal proposal!
2021-03-04T22:12:03.552Z    INFO    markets loggers/loggers.go:20   storage provider event  {"name": "ProviderEventOpen", "proposal CID": "bafyreigqkyqa5xn2iyhcp5sverqsqkgqjr6u4jcg7kzcbtqoyry2isxygy", "state": "StorageDealValidating", "message": ""}
2021-03-04T22:12:03.560Z    INFO    markets loggers/loggers.go:20   storage provider event  {"name": "ProviderEventDealDeciding", "proposal CID": "bafyreigqkyqa5xn2iyhcp5sverqsqkgqjr6u4jcg7kzcbtqoyry2isxygy", "state": "StorageDealAcceptWait", "message": ""}
2021-03-04T22:12:03.599Z    INFO    markets loggers/loggers.go:20   storage provider event  {"name": "ProviderEventDataRequested", "proposal CID": "bafyreigqkyqa5xn2iyhcp5sverqsqkgqjr6u4jcg7kzcbtqoyry2isxygy", "state": "StorageDealWaitingForData", "message": ""}
2021-03-04T22:12:04.567Z    INFO    dt-impl impl/events.go:338  received new channel request from 12D3KooWQzMJbLno5cudsqTUEsrycN1U3gHVtayRj4dZjRnEvrfc
2021-03-04T22:12:04.568Z    INFO    dt-impl impl/events.go:21   channel 12D3KooWQzMJbLno5cudsqTUEsrycN1U3gHVtayRj4dZjRnEvrfc-12D3KooWKG9mQfyAAyCc3huFVMMzpKCdbgLhED6PYFhwM7q8Ab3W-121: opened
2021-03-04T22:12:04.568Z    INFO    markets loggers/loggers.go:20   storage provider event  {"name": "ProviderEventDataTransferInitiated", "proposal CID": "bafyreigqkyqa5xn2iyhcp5sverqsqkgqjr6u4jcg7kzcbtqoyry2isxygy", "state": "StorageDealTransferring", "message": ""}
2021-03-04T22:12:06.049Z    INFO    miner   miner/miner.go:383  Time delta between now and our mining base: 6s (nulls: 0)
2021-03-04T22:12:36.384Z    INFO    miner   miner/miner.go:383  Time delta between now and our mining base: 6s (nulls: 0)
2021-03-04T22:13:02.517Z    INFO    graphsync   impl/graphsync.go:299   Graphsync ReceiveError: stream reset
2021-03-04T22:13:05.480Z    INFO    graphsync   impl/graphsync.go:299   Graphsync ReceiveError: message too large
2021-03-04T22:13:06.130Z    INFO    miner   miner/miner.go:383  Time delta between now and our mining base: 6s (nulls: 0)
2021-03-04T22:13:36.387Z    INFO    miner   miner/miner.go:383  Time delta between now and our mining base: 6s (nulls: 0)
2021-03-04T22:13:48.269Z    INFO    graphsync   impl/graphsync.go:299   Graphsync ReceiveError: message too large
2021-03-04T22:13:48.897Z    ERROR   dt-impl impl/receiver.go:110    received error message on data transfer: unmarshaling t.Request pointer: failed to read deferred field: stream reset
2021-03-04T22:13:48.899Z    INFO    dt-impl impl/events.go:126  channel 12D3KooWQzMJbLno5cudsqTUEsrycN1U3gHVtayRj4dZjRnEvrfc-12D3KooWKG9mQfyAAyCc3huFVMMzpKCdbgLhED6PYFhwM7q8Ab3W-121: received cancel request, cleaning up channel
2021-03-04T22:13:48.899Z    ERROR   dt_graphsync    graphsync/graphsync.go:559  cannot unregister while requests are in progress
2021-03-04T22:13:48.899Z    INFO    markets loggers/loggers.go:20   storage provider event  {"name": "ProviderEventDataTransferCancelled", "proposal CID": "bafyreigqkyqa5xn2iyhcp5sverqsqkgqjr6u4jcg7kzcbtqoyry2isxygy", "state": "StorageDealFailing", "message": "data transfer cancelled"}
2021-03-04T22:13:48.900Z    WARN    providerstates  providerstates/provider_states.go:536   deal bafyreigqkyqa5xn2iyhcp5sverqsqkgqjr6u4jcg7kzcbtqoyry2isxygy failed: data transfer cancelled
2021-03-04T22:13:48.901Z    INFO    markets loggers/loggers.go:20   storage provider event  {"name": "ProviderEventFailed", "proposal CID": "bafyreigqkyqa5xn2iyhcp5sverqsqkgqjr6u4jcg7kzcbtqoyry2isxygy", "state": "StorageDealError", "message": "data transfer cancelled"}
2021-03-04T22:14:06.039Z    INFO    miner   miner/miner.go:383  Time delta between now and our mining base: 6s (nulls: 0)
2021-03-04T22:14:07.119Z    INFO    graphsync   impl/graphsync.go:299   Graphsync ReceiveError: message too large
Reiers commented 3 years ago

Miner is stable, pledging away and in sync.

Same problem and, client ID: f3qpseg3qlpckug75qqas6jsce4up6kg5bo4yaefwnxo4fwx2n5f7jpkkrzy37jxnshkd6mazxso2rxfoaxska

2021-03-04T22:35:12.874+0100    INFO    graphsync   impl/graphsync.go:299   Graphsync ReceiveError: message too large
2021-03-04T22:35:16.187+0100    ERROR   dt-impl impl/receiver.go:110    received error message on data transfer: stream reset
2021-03-04T22:35:36.058+0100    INFO    miner   miner/miner.go:383  Time delta between now and our mining base: 6s (nulls: 0)
2021-03-04T22:36:01.556+0100    INFO    graphsync   impl/graphsync.go:299   Graphsync ReceiveError: message too large
2021-03-04T22:36:06.141+0100    INFO    miner   miner/miner.go:383  Time delta between now and our mining base: 6s (nulls: 0)
2021-03-04T22:36:36.066+0100    INFO    miner   miner/miner.go:383  Time delta between now and our mining base: 6s (nulls: 0)
2021-03-04T22:36:47.981+0100    INFO    graphsync   impl/graphsync.go:299   Graphsync ReceiveError: message too large
2021-03-04T22:36:50.391+0100    ERROR   dt-impl impl/receiver.go:110    received error message on data transfer: unmarshaling t.Request pointer: failed to read cid field t.BCid: stream reset
2021-03-04T22:36:59.211+0100    WARN    storagemarket_impl  impl/provider.go:517    failed to write deal status response: stream reset
2021-03-04T22:37:06.421+0100    WARN    net/identify    go-log@v1.0.4/log.go:175    error reading identify message: stream reset
2021-03-04T22:37:06.425+0100    WARN    storagemarket_impl  impl/provider.go:517    failed to write deal status response: stream reset
2021-03-04T22:37:06.542+0100    INFO    miner   miner/miner.go:383  Time delta between now and our mining base: 6s (nulls: 0)
2021-03-04T22:37:30.506+0100    INFO    sectors storage-sealing/states_sealing.go:315   precommit message landed on chain: 4516
2021-03-04T22:37:35.070+0100    INFO    graphsync   impl/graphsync.go:299   Graphsync ReceiveError: message too large

Lotus Version Daemon: 1.5.0+mainnet+git.55b85f314+api1.1.0 Local: lotus version 1.5.0+mainnet+git.55b85f314

cwhiggins commented 3 years ago

I have four 512mib deals from this client that completed and are currently in process, PC1. https://filfox.info/en/message/bafy2bzacebveo5klyavp3eiroecrupamzos4dwa5yennmlbqumjoqb56nz7pi, 4 deals in one msg

lotus version
Daemon:  1.5.0+mainnet+git.55b85f314+api1.1.0
Local: lotus version 1.5.0+mainnet+git.55b85f314

but I have also had this error popping up

2021-03-05T13:24:15.824-0500   ERROR  data-transfer   channels/channel_state.go:101unexpected EOF
raulk commented 3 years ago

Lots of data transfer fixes have landed in 1.11.0 and above. Please reopen if still reproduceable on those versions.