Experienced via Lassie's CI suite which has suddenly become flaky with some new …workloads. Using the [testing/sws-logging](https://github.com/ipfs/boxo/tree/testing/sws-logging) branch here (started by @hannahhoward, continued by me) to diagnose with additional debug printing. It evidences in an inability to communicate with a peer that we know has the block, and bitswap has been told has the block.
See logs below, which come from [here](https://github.com/filecoin-project/lassie/actions/runs/5865827197/job/15903479085?pr=371) using 715365a23d36ccd0fe2c9cf95ec16afa0d50f39b on the [testing/sws-logging](https://github.com/ipfs/boxo/tree/testing/sws-logging) branch. Here's what I believe happens:
* `session#findMorePeers` -> `ProviderQueryManager#FindProvidersAsync`
* `ProviderQueryManager#findProviderWorker` does its thing, processing the queue of providers to connect to, performs a `pqm.network.ConnectTo()` which is goes through (bitswap/network/ipfs_impl.go) `bsnet#ConnectTo()` to just do a basic `host.Connect()`
* We get a `Connected()` notification which is received by (bitswap/network/ipfs_impl.go) `connectEventManager#Connected()` and it does a `c.setState(p, stateResponsive)` on that peer.
* Meanwhile, the `ProviderQueryManager#FindProvidersAsync` has returned, the `Connect()` returned, we even got a `Connected()`, so the `Session` invokes `sessionWantSender#Update(peer, nil, have, nil)`, i.e. the `peer` has the cid `have`, this is a "change".
* In `sessionWantSender` we go from `onChange()` to `processUpdates()` to `updateWantBlockPresence()` to `wantInfo#setPeerBlockPresence()` to `wantInfo#calculateBestPeer()` - we see these in the logs
* After the call to `processUpdates()`, `sessionWantSender` moves on to `sendNextWants()`, which compiles them and calls `sendWants()` which in turn calls `PeerManager#SendWants()`.
* **BUT** it turns out that `PeerManager` doesn't have a `peerQueues` entry for this peer .. yet ..
* Back in `connectEventManager`, the `worker()` (goroutine) loop finally picks up a change, and sees that `p` is now `stateResponsive` so it ends up calling `Bitswap#PeerConnected()` which calls `Client#PeerConnected()` which calls `PeerManager#Connected()` which calls `PeerManager#getOrCreate()` that finally sets up a `peerQueues` entry for that peer; so it's now ready to talk (_"hey, what'd I miss?"_).
I'm a bit fuzzy on what the logs show beyond here and why it doesn't manage to rectify the situation with retries; I guess because it had one chance to take the peer from `FindProvidersAsync` and ask it for the block, and it failed that one chance and there isn't really another.
The async disconnect in `connectEventManager` seems to be the main problem here, perhaps a call to `Connected()` shouldn't return until the state change has been fully propagated.
<details>
<summary>Relevant logs</summary>
```
2023-08-15T09:52:43.126Z DEBUG bs:sess session/session.go:361 FindMorePeers {"session": 1, "cid": "bafybeifrrglx2issn2had5rtstn3xltla6vxmpjfwfz7o3hapvkynh4zoq", "pending": 1}
2023-08-15T09:52:43.126Z DEBUG bitswap providerquerymanager/providerquerymanager.go:332 New Provider Query on cid: bafybeifrrglx2issn2had5rtstn3xltla6vxmpjfwfz7o3hapvkynh4zoq
2023-08-15T09:52:43.126Z DEBUG bitswap providerquerymanager/providerquerymanager.go:234 Beginning Find Provider Request for cid: bafybeifrrglx2issn2had5rtstn3xltla6vxmpjfwfz7o3hapvkynh4zoq
2023-08-15T09:52:43.126Z DEBUG lassie/bitswap bitswaphelpers/indexerrouting.go:86 provider records requested from bitswap, sending back indexer results {"providerCount": 1}
2023-08-15T09:52:43.126Z DEBUG bitswap providerquerymanager/providerquerymanager.go:244 Connecting to provider 1WRsHVY1dhNKpD...
2023-08-15T09:52:43.126Z DEBUG basichost basic/basic_host.go:737 host QmRR8VvuQf4Fvr2ptGJj2qjJkmqREJXbF4jv8KkSRLsMj1 dialing 1WRsHVY1dhNKpD
2023-08-15T09:52:43.126Z DEBUG mocknet mock/mock_peernet.go:119 QmRR8VvuQf4Fvr2ptGJj2qjJkmqREJXbF4jv8KkSRLsMj1 (newly) dialing 1WRsHVY1dhNKpD
2023-08-15T09:52:43.126Z DEBUG mocknet mock/mock_peernet.go:132 QmRR8VvuQf4Fvr2ptGJj2qjJkmqREJXbF4jv8KkSRLsMj1 dialing 1WRsHVY1dhNKpD openingConn
2023-08-15T09:52:43.126Z DEBUG mocknet mock/mock_peernet.go:140 QmRR8VvuQf4Fvr2ptGJj2qjJkmqREJXbF4jv8KkSRLsMj1 opening connection to 1WRsHVY1dhNKpD
2023-08-15T09:52:43.126Z DEBUG mocknet mock/mock_peernet.go:183 1WRsHVY1dhNKpD accepting connection from QmRR8VvuQf4Fvr2ptGJj2qjJkmqREJXbF4jv8KkSRLsMj1
2023-08-15T09:52:43.126Z DEBUG bitswap_network network/connecteventmanager.go:159 connectEventManager connected to peer, setting responsive {"peer": "QmRR8VvuQf4Fvr2ptGJj2qjJkmqREJXbF4jv8KkSRLsMj1"}
2023-08-15T09:52:43.126Z DEBUG bitswap_network network/connecteventmanager.go:140 connectEventManager detected peer connectivity {"peer": "QmRR8VvuQf4Fvr2ptGJj2qjJkmqREJXbF4jv8KkSRLsMj1"}
2023-08-15T09:52:43.126Z DEBUG mocknet mock/mock_conn.go:148 Conn.NewStreamWithProtocol: QmRR8VvuQf4Fvr2ptGJj2qjJkmqREJXbF4jv8KkSRLsMj1 --> 1WRsHVY1dhNKpD
2023-08-15T09:52:43.126Z DEBUG bitswap_network network/connecteventmanager.go:159 connectEventManager connected to peer, setting responsive {"peer": "1WRsHVY1dhNKpD"}
2023-08-15T09:52:43.126Z DEBUG mocknet mock/mock_conn.go:148 Conn.NewStreamWithProtocol: 1WRsHVY1dhNKpD --> QmRR8VvuQf4Fvr2ptGJj2qjJkmqREJXbF4jv8KkSRLsMj1
2023-08-15T09:52:43.127Z DEBUG basichost basic/basic_host.go:433 negotiated: /ipfs/id/1.0.0 (took 25.701µs)
2023-08-15T09:52:43.127Z DEBUG net/identify identify/id.go:463 sending snapshot {"seq": 2, "protocols": ["/fil/datatransfer/1.2.0","/ipfs/bitswap","/ipfs/bitswap/1.0.0","/ipfs/bitswap/1.1.0","/ipfs/bitswap/1.2.0","/ipfs/graphsync/2.0.0","/ipfs/id/1.0.0","/ipfs/id/push/1.0.0"], "addrs": ["/ip6/100::2438:fce9:9d50:c714/tcp/4242"]}
2023-08-15T09:52:43.127Z DEBUG net/identify identify/id.go:468 /ipfs/id/1.0.0 sending message to 1WRsHVY1dhNKpD /ip4/127.0.0.1/tcp/15381
2023-08-15T09:52:43.127Z DEBUG net/identify identify/id.go:519 /ipfs/id/1.0.0 received message from QmRR8VvuQf4Fvr2ptGJj2qjJkmqREJXbF4jv8KkSRLsMj1 /ip6/100::2438:fce9:9d50:c714/tcp/4242
2023-08-15T09:52:43.127Z DEBUG net/identify identify/id.go:787 1WRsHVY1dhNKpD received listen addrs for QmRR8VvuQf4Fvr2ptGJj2qjJkmqREJXbF4jv8KkSRLsMj1: [/ip6/100::2438:fce9:9d50:c714/tcp/4242]
2023-08-15T09:52:43.127Z DEBUG basichost basic/basic_host.go:433 negotiated: /ipfs/id/1.0.0 (took 398.503µs)
2023-08-15T09:52:43.127Z DEBUG net/identify identify/id.go:463 sending snapshot {"seq": 2, "protocols": ["/ipfs/bitswap","/ipfs/bitswap/1.0.0","/ipfs/bitswap/1.1.0","/ipfs/bitswap/1.2.0","/ipfs/id/1.0.0","/ipfs/id/push/1.0.0"], "addrs": ["/ip4/127.0.0.1/tcp/15381"]}
2023-08-15T09:52:43.127Z DEBUG net/identify identify/id.go:468 /ipfs/id/1.0.0 sending message to QmRR8VvuQf4Fvr2ptGJj2qjJkmqREJXbF4jv8KkSRLsMj1 /ip6/100::2438:fce9:9d50:c714/tcp/4242
2023-08-15T09:52:43.127Z DEBUG net/identify identify/id.go:519 /ipfs/id/1.0.0 received message from 1WRsHVY1dhNKpD /ip4/127.0.0.1/tcp/15381
2023-08-15T09:52:43.127Z DEBUG net/identify identify/id.go:787 QmRR8VvuQf4Fvr2ptGJj2qjJkmqREJXbF4jv8KkSRLsMj1 received listen addrs for 1WRsHVY1dhNKpD: [/ip4/127.0.0.1/tcp/15381]
2023-08-15T09:52:43.127Z WARN net/identify identify/id.go:811 QmRR8VvuQf4Fvr2ptGJj2qjJkmqREJXbF4jv8KkSRLsMj1 cannot unmarshal key from remote peer: 1WRsHVY1dhNKpD, asn1: structure error: tags don't match (16 vs {class:3 tag:27 length:52 isCompound:false}) {optional:false explicit:false application:false private:false defaultValue:<nil> tag:<nil> stringType:0 timeType:0 set:false omitEmpty:false} publicKeyInfo @2
2023-08-15T09:52:43.127Z DEBUG basichost basic/basic_host.go:754 host QmRR8VvuQf4Fvr2ptGJj2qjJkmqREJXbF4jv8KkSRLsMj1 finished dialing 1WRsHVY1dhNKpD
2023-08-15T09:52:43.127Z DEBUG bitswap providerquerymanager/providerquerymanager.go:250 Connected to provider 1WRsHVY1dhNKpD
2023-08-15T09:52:43.127Z DEBUG bitswap providerquerymanager/providerquerymanager.go:264 Found 0 providers for cid: bafybeifrrglx2issn2had5rtstn3xltla6vxmpjfwfz7o3hapvkynh4zoq
2023-08-15T09:52:43.127Z DEBUG net/identify identify/obsaddr.go:442 added own observed listen addr {"observed": "/ip6/100::2438:fce9:9d50:c714/tcp/4242"}
2023-08-15T09:52:43.127Z DEBUG bitswap providerquerymanager/providerquerymanager.go:332 Received provider (1WRsHVY1dhNKpD) for cid (bafybeifrrglx2issn2had5rtstn3xltla6vxmpjfwfz7o3hapvkynh4zoq)
2023-08-15T09:52:43.127Z DEBUG bitswap providerquerymanager/providerquerymanager.go:332 Finished Provider Query on cid: bafybeifrrglx2issn2had5rtstn3xltla6vxmpjfwfz7o3hapvkynh4zoq
2023-08-15T09:52:43.127Z DEBUG bs:peermgr peermanager/peermanager.go:214 pm RegisterSession {"peer": "1WRsHVY1dhNKpD", "session": 1}
2023-08-15T09:52:43.127Z DEBUG bs:sprmgr sessionpeermanager/sessionpeermanager.go:68 Bitswap: Added peer to session {"session": 1, "peer": "1WRsHVY1dhNKpD", "peerCount": 1}
2023-08-15T09:52:43.127Z DEBUG bs:sess session/sessionwantsender.go:[65](https://github.com/filecoin-project/lassie/actions/runs/5865827197/job/15903479085?pr=371#step:63:67)7 sws update want block presence {"cid": "bafybeifrrglx2issn2had5rtstn3xltla6vxmpjfwfz7o3hapvkynh4zoq", "peerID": "1WRsHVY1dhNKpD"}
2023-08-15T09:52:43.127Z DEBUG bs:sess session/sessionwantsender.go:764 sws new best peer {"peerID": "1WRsHVY1dhNKpD"}
2023-08-15T09:52:43.127Z DEBUG bs:sess session/sessionwantsender.go:657 sws update want block presence {"cid": "bafybeifrrglx2issn2had5rtstn3xltla6vxmpjfwfz7o3hapvkynh4zoq", "peerID": "1WRsHVY1dhNKpD"}
2023-08-15T09:52:43.127Z DEBUG bs:sess session/sessionwantsender.go:764 sws new best peer {"peerID": "1WRsHVY1dhNKpD"}
2023-08-15T09:52:43.127Z DEBUG bs:sess session/sessionwantsender.go:535 sws send next wants {"newly available": ["1WRsHVY1dhNKpD"]}
2023-08-15T09:52:43.127Z DEBUG bs:sess session/sessionwantsender.go:558 sws send new want block {"cid": "bafybeifrrglx2issn2had5rtstn3xltla6vxmpjfwfz7o3hapvkynh4zoq", "peerID": "1WRsHVY1dhNKpD"}
2023-08-15T09:52:43.127Z DEBUG bs:sess session/sessionwantsender.go:580 sws sending wants {"sends": 1}
2023-08-15T09:52:43.127Z DEBUG bs:peermgr peermanager/peermanager.go:155 pm SendWants {"peer": "1WRsHVY1dhNKpD", "wantBlocks": 1, "wantHaves": 1}
2023-08-15T09:52:43.127Z DEBUG bs:peermgr peermanager/peermanager.go:159 pm SendWants no peerQueue for {"peer": "1WRsHVY1dhNKpD"}
2023-08-15T09:52:43.127Z DEBUG bitswap_network network/connecteventmanager.go:140 connectEventManager detected peer connectivity {"peer": "1WRsHVY1dhNKpD"}
2023-08-15T09:52:43.127Z DEBUG bs:peermgr peermanager/peermanager.go:91 pm Connected {"peer": "1WRsHVY1dhNKpD"}
2023-08-15T09:52:43.127Z DEBUG bs:peermgr peermanager/peermanager.go:203 pm getOrCreate new peer {"peer": "1WRsHVY1dhNKpD"}
2023-08-15T09:52:43.127Z DEBUG bitswap messagequeue/messagequeue.go:280 mq: add want have from broadcast {"cid": "bafybeifrrglx2issn2had5rtstn3xltla6vxmpjfwfz7o3hapvkynh4zoq", "peerID": "1WRsHVY1dhNKpD"}
2023-08-15T09:52:43.127Z DEBUG bs:sess session/sessionwantsender.go:535 sws send next wants {"newly available": null}
2023-08-15T09:52:43.127Z DEBUG bs:sess session/sessionwantsender.go:546 sws want block in process, no new want block sent {"cid": "bafybeifrrglx2issn2had5rtstn3xltla6vxmpjfwfz7o3hapvkynh4zoq"}
2023-08-15T09:52:43.127Z DEBUG bs:sess session/sessionwantsender.go:580 sws sending wants {"sends": 0}
2023-08-15T09:52:43.129Z DEBUG mocknet mock/mock_conn.go:148 Conn.NewStreamWithProtocol: QmRR8VvuQf4Fvr2ptGJj2qjJkmqREJXbF4jv8KkSRLsMj1 --> 1WRsHVY1dhNKpD
2023-08-15T09:52:43.129Z DEBUG bitswap messagequeue/messagequeue.go:[66](https://github.com/filecoin-project/lassie/actions/runs/5865827197/job/15903479085?pr=371#step:63:68)6 sent message {"type": "WANT_HAVE", "cid": "bafybeifrrglx2issn2had5rtstn3xltla6vxmpjfwfz7o3hapvkynh4zoq", "local": "QmRR8VvuQf4Fvr2ptGJj2qjJkmqREJXbF4jv8KkSRLsMj1", "to": "1WRsHVY1dhNKpD"}
2023-08-15T09:52:43.129Z WARN bitswap_network network/ipfs_impl.go:245 error setting deadline: set pipe: deadline not supported
2023-08-15T09:52:43.130Z DEBUG mocknet mock/mock_conn.go:148 Conn.NewStreamWithProtocol: QmRR8VvuQf4Fvr2ptGJj2qjJkmqREJXbF4jv8KkSRLsMj1 --> 1WRsHVY1dhNKpD
2023-08-15T09:52:43.130Z WARN bitswap_network network/ipfs_impl.go:269 error resetting deadline: set pipe: deadline not supported
2023-08-15T09:52:43.130Z DEBUG bs:sess session/session.go:4[67](https://github.com/filecoin-project/lassie/actions/runs/5865827197/job/15903479085?pr=371#step:63:69) broadcastWantHaves {"session": 1, "cids": [{"/":"bafybeifrrglx2issn2had5rtstn3xltla6vxmpjfwfz7o3hapvkynh4zoq"}]}
2023-08-15T09:52:43.130Z DEBUG basichost basic/basic_host.go:433 negotiated: /ipfs/bitswap/1.2.0 (took 800.106µs)
2023-08-15T09:52:43.131Z DEBUG bitswap_network network/ipfs_impl.go:427 bitswap net handleNewStream from QmRR8VvuQf4Fvr2ptGJj2qjJkmqREJXbF4jv8KkSRLsMj1
2023-08-15T09:52:43.131Z DEBUG engine decision/engine.go:634 Bitswap engine <- msg {"local": "1WRsHVY1dhNKpD", "from": "QmRR8VvuQf4Fvr2ptGJj2qjJkmqREJXbF4jv8KkSRLsMj1", "entryCount": 1}
2023-08-15T09:52:43.131Z DEBUG engine decision/engine.go:638 Bitswap engine <- want-have {"local": "1WRsHVY1dhNKpD", "from": "QmRR8VvuQf4Fvr2ptGJj2qjJkmqREJXbF4jv8KkSRLsMj1", "cid": "bafybeifrrglx2issn2had5rtstn3xltla6vxmpjfwfz7o3hapvkynh4zoq"}
LinkSystemBlockstore.GetSize bafybeifrrglx2issn2had5rtstn3xltla6vxmpjfwfz7o3hapvkynh4zoq
LinkSystemBlockstore.GetSize= bafybeifrrglx2issn2had5rtstn3xltla6vxmpjfwfz7o3hapvkynh4zoq 1332
2023-08-15T09:52:43.132Z DEBUG engine decision/engine.go:779 Bitswap engine: block found {"local": "1WRsHVY1dhNKpD", "from": "QmRR8VvuQf4Fvr2ptGJj2qjJkmqREJXbF4jv8KkSRLsMj1", "cid": "bafybeifrrglx2issn2had5rtstn3xltla6vxmpjfwfz7o3hapvkynh4zoq", "isWantBlock": false}
2023-08-15T09:52:43.132Z DEBUG engine decision/engine.go:545 Bitswap process tasks {"local": "1WRsHVY1dhNKpD", "taskCount": 1}
2023-08-15T09:52:43.132Z DEBUG engine decision/engine.go:598 Bitswap engine -> msg {"local": "1WRsHVY1dhNKpD", "to": "QmRR8VvuQf4Fvr2ptGJj2qjJkmqREJXbF4jv8KkSRLsMj1", "blockCount": 0, "presenceCount": 1, "size": 38}
2023-08-15T09:52:43.133Z DEBUG mocknet mock/mock_conn.go:148 Conn.NewStreamWithProtocol: 1WRsHVY1dhNKpD --> QmRR8VvuQf4Fvr2ptGJj2qjJkmqREJXbF4jv8KkSRLsMj1
2023-08-15T09:52:43.133Z WARN bitswap_network network/ipfs_impl.go:245 error setting deadline: set pipe: deadline not supported
2023-08-15T09:52:43.133Z DEBUG basichost basic/basic_host.go:413 protocol mux failed: stream reset (took 2.485821ms)
2023-08-15T09:52:43.133Z WARN bitswap_network network/ipfs_impl.go:2[69](https://github.com/filecoin-project/lassie/actions/runs/5865827197/job/15903479085?pr=371#step:63:71) error resetting deadline: set pipe: deadline not supported
2023-08-15T09:52:43.133Z DEBUG basichost basic/basic_host.go:433 negotiated: /ipfs/bitswap/1.2.0 (took 321.[70](https://github.com/filecoin-project/lassie/actions/runs/5865827197/job/15903479085?pr=371#step:63:72)3µs)
2023-08-15T09:52:43.134Z DEBUG bitswap_network network/ipfs_impl.go:427 bitswap net handleNewStream from 1WRsHVY1dhNKpD
2023-08-15T09:52:43.134Z DEBUG bs:sess session/session.go:221 Bitswap <- HAVE {"local": "QmRR8VvuQf4Fvr2ptGJj2qjJkmqREJXbF4jv8KkSRLsMj1", "from": "1WRsHVY1dhNKpD", "cid": "bafybeifrrglx2issn2had5rtstn3xltla6vxmpjfwfz7o3hapvkynh4zoq", "session": 1}
2023-08-15T09:52:43.134Z DEBUG bs:peermgr peermanager/peermanager.go:214 pm RegisterSession {"peer": "1WRsHVY1dhNKpD", "session": 1}
2023-08-15T09:52:43.134Z DEBUG bs:sess session/sessionwantsender.go:657 sws update want block presence {"cid": "bafybeifrrglx2issn2had5rtstn3xltla6vxmpjfwfz7o3hapvkynh4zoq", "peerID": "1WRsHVY1dhNKpD"}
2023-08-15T09:52:43.134Z DEBUG bs:sess session/sessionwantsender.go:[76](https://github.com/filecoin-project/lassie/actions/runs/5865827197/job/15903479085?pr=371#step:63:78)4 sws new best peer {"peerID": "1WRsHVY1dhNKpD"}
2023-08-15T09:52:43.134Z DEBUG bs:sess session/sessionwantsender.go:535 sws send next wants {"newly available": null}
2023-08-15T09:52:43.134Z DEBUG bs:sess session/sessionwantsender.go:546 sws want block in process, no new want block sent {"cid": "bafybeifrrglx2issn2had5rtstn3xltla6vxmpjfwfz7o3hapvkynh4zoq"}
2023-08-15T09:52:43.134Z DEBUG bs:sess session/sessionwantsender.go:580 sws sending wants {"sends": 0}
2023-08-15T09:52:43.134Z DEBUG bitswap-server server/server.go:325 sent message {"type": "HAVE", "cid": "bafybeifrrglx2issn2had5rtstn3xltla6vxmpjfwfz7o3hapvkynh4zoq", "local": "1WRsHVY1dhNKpD", "to": "QmRR8VvuQf4Fvr2ptGJj2qjJkmqREJXbF4jv8KkSRLsMj1"}
2023-08-15T09:52:43.135Z DEBUG bitswap-server server/server.go:3[79](https://github.com/filecoin-project/lassie/actions/runs/5865827197/job/15903479085?pr=371#step:63:81) sent message {"peer": "QmRR8VvuQf4Fvr2ptGJj2qjJkmqREJXbF4jv8KkSRLsMj1"}
2023-08-15T09:52:43.135Z DEBUG bitswap-server server/server.go:2[82](https://github.com/filecoin-project/lassie/actions/runs/5865827197/job/15903479085?pr=371#step:63:84) Bitswap.TaskWorker.Loop {"ID": 0}
2023-08-15T09:52:43.[139](https://github.com/filecoin-project/lassie/actions/runs/5865827197/job/15903479085?pr=371#step:63:141)Z DEBUG bs:sess session/session.go:467 broadcastWantHaves {"session": 1, "cids": [{"/":"bafybeifrrglx2issn2had5rtstn3xltla6vxmpjfwfz7o3hapvkynh4zoq"}]}
2023-08-15T09:52:43.151Z DEBUG bs:sess session/session.go:467 broadcastWantHaves {"session": 1, "cids": [{"/":"bafybeifrrglx2issn2had5rtstn3xltla6vxmpjfwfz7o3hapvkynh4zoq"}]}
```
</details>