Multiple Graphsync ReceiveError messages since 1.5.0 upgrade.

[TippyFlitsUK]

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]

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	[email protected]/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]

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]

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