ethersphere / bee

Bee is a Swarm client implemented in Go. It’s the basic building block for the Swarm network: a private; decentralized; and self-sustaining network for permissionless publishing and access to your (application) data.
https://www.ethswarm.org
BSD 3-Clause "New" or "Revised" License
1.44k stars 337 forks source link

Parallel PushSync outside radius #4680

Open ldeffenb opened 1 month ago

ldeffenb commented 1 month ago

Context

bee 2.1.0 (also in 2.0.0, I suspect) on sepolia testnet

Summary

My sepolia testnet OSM uploader node is concurrently pushing chunks to nodes outside the target neighborhood even though it initiated a push to a node matching the chunk's desired neighborhood.

Expected behavior

If a chunk is being pushed to a node within its desired neighborhood, why push it to other peers outside the neighborhood? This amounts to concurrent parallel push paths that are unnecessary. It is also causing a lot of "shallow receipt depth" errors due to timing between in target and out of target radius peers.

Actual behavior

I added a bunch of logs to pushsync.go to determine that this was actually happening. The gist of these logs for chunk c4591c9eb98fe831670b459aef36029b0da80cdaa1a39771bfe9bcb55d69a09b are:

Chunk is originally put for upload
msg"="uploadTrace:uploadPutter.Put" "address"="c4591..."

And dequeued for sending by the Pusher
msg"="uploadTrace:IteratePending" "address"="c4591..." 

An initial entry is made to retryC in pushToClosest
msg"="pushTrace:pushToClosest:retry" "chunk"="c4591..." "why"="initial"

And the chunk is discovered to be going to the target neighborhood
msg"="pushTrace:pushToClosest:paralleling TRY" "chunk"="c4591..." "peer"="c802c4538..." "proximity"=4 "radius"=4 "parallels"=2

So 2 more entries are put into retryC
msg"="pushTrace:pushToClosest:retry" "chunk"="c4591..." "why"="parallelForwards(2)"
msg"="pushTrace:pushToClosest:retry" "chunk"="c4591..." "why"="parallelForwards(1)"

And the chunk is pushed to that "closest" in-target-neighborhood peer
msg"="pushTrace:pushToClosest:pushing" "chunk"="c4591..." "peer"="c802c4538..."
msg"="pushTrace:pushChunkToPeer" "chunk"="c4591..." "peer"="c802c4538..."

Ah, but the two "multiplexed" retries end up pushing OUTSIDE the target!
msg"="pushTrace:pushToClosest:pushing" "chunk"="c4591..." "peer"="deff932..."
msg"="pushTrace:pushToClosest:pushing" "chunk"="c4591..." "peer"="e8056b9..."
msg"="pushTrace:pushChunkToPeer" "chunk"="c4591..." "peer"="e8056b9..."
msg"="pushTrace:pushChunkToPeer" "chunk"="c4591..." "peer"="deff932..."

And all three of them report that chunkSent
msg"="uploadTrace:Report" "address"="c4591..."  "tag"=94 "state"="ChunkSent"
msg"="uploadTrace:Report" "address"="c4591..."  "tag"=94 "state"="ChunkSent"
msg"="uploadTrace:Report" "address"="c4591..."  "tag"=94 "state"="ChunkSent"

But the OUTSIDE OF TARGET peer actually finishes first!
msg"="pushTrace:push success" "chunk"="c4591..." "peer"="e8056b9..."
msg"="pushTrace:pushToClosest:result" "chunk"="c4591..." "peer"="e8056b9..."

And then the actual TARGET peer finishes, but too late...
msg"="pushTrace:push success" "chunk"="c4591..." "peer"="c802c4538..."

Because the pusher got the out of radius receipt and ends up retrying
msg"="pusher: failed checking receipt" "error"="pusher: shallow receipt depth 3, want at least 4, chunk_address c4591...: shallow recipt" "chunk_address"="c4591..."

And finally the THIRD push completes, but also too late
msg"="pushTrace:push success" "chunk"="c4591..." "peer"="deff932"

And then the retry does it all over again, but this time starting completely outside the target
msg"="pushTrace:pushToClosest:retry" "chunk"="c4591..." "why"="initial"
msg"="pushTrace:pushToClosest:pushing" "chunk"="c4591..." "peer"="ffc5e89"
msg"="pushTrace:pushChunkToPeer" "chunk"="c4591..." "peer"="ffc5e89"
msg"="uploadTrace:Report" "address"="c4591..."  "tag"=94 "state"="ChunkSent"
msg"="pushTrace:push success" "chunk"="c4591..." "peer"="ffc5e89"
msg"="pushTrace:pushToClosest:result" "chunk"="c4591..." "peer"="ffc5e89"

Which of course is too shallow, so it keeps retrying getting further and further away
msg"="pusher: failed checking receipt" "error"="pusher: shallow receipt depth 3, want at least 4, chunk_address c4591...: shallow receipt" "chunk_address"="c4591..."

msg"="pushTrace:pushToClosest:retry" "chunk"="c4591..." "why"="initial"
msg"="pushTrace:pushToClosest:pushing" "chunk"="c4591..." "peer"="8891df..."
msg"="pushTrace:pushChunkToPeer" "chunk"="c4591..." "peer"="8891df..."
msg"="pusher: failed checking receipt" "error"="pusher: shallow receipt depth 3, want at least 4, chunk_address c4591...: shallow receipt" "chunk_address"="c4591..."

msg"="pushTrace:pushToClosest:retry" "chunk"="c4591..." "why"="initial"
msg"="pushTrace:pushToClosest:pushing" "chunk"="c4591..." "peer"="8bea0e..."
msg"="pushTrace:pushChunkToPeer" "chunk"="c4591..." "peer"="8bea0e..."
msg"="uploadTrace:Report" "address"="c4591..."  "tag"=94 "state"="ChunkSent"
msg"="pushTrace:push success" "chunk"="c4591..." "peer"="8bea0e..."
msg"="pushTrace:pushToClosest:result" "chunk"="c4591..." "peer"="8bea0e..."
msg"="pusher: failed checking receipt" "error"="pusher: shallow receipt depth 3, want at least 4, chunk_address c4591...: shallow receipt" "chunk_address"="c4591..."

And here's the (un-filtered) raw logs:

"time"="2024-05-17 17:27:44.952070" "level"="debug" "logger"="node/storer" "msg"="uploadTrace:uploadPutter.Put" "address"="c4591c9eb98fe831670b459aef36029b0da80cdaa1a39771bfe9bcb55d69a09b" "batch"="cf5ab2db3f836eb8d78dcfc3f5e21ab510c15ee627e59d7bea357b0a12375d41"
"time"="2024-05-17 17:27:47.343372" "level"="debug" "logger"="node/pusher" "msg"="uploadTrace:IteratePending" "address"="c4591c9eb98fe831670b459aef36029b0da80cdaa1a39771bfe9bcb55d69a09b" "batch"="cf5ab2db3f836eb8d78dcfc3f5e21ab510c15ee627e59d7bea357b0a12375d41"
"time"="2024-05-17 17:27:47.343980" "level"="debug" "logger"="node/pushsync" "msg"="pushTrace:pushToClosest:retry" "chunk"="c4591c9eb98fe831670b459aef36029b0da80cdaa1a39771bfe9bcb55d69a09b" "why"="initial"
"time"="2024-05-17 17:27:47.345887" "level"="debug" "logger"="node/pushsync" "msg"="pushTrace:pushToClosest:paralleling TRY" "chunk"="c4591c9eb98fe831670b459aef36029b0da80cdaa1a39771bfe9bcb55d69a09b" "peer"="c802c453899cf40786257e3d84e593604352daba08419e6f019cf324434a6137" "proximity"=4 "radius"=4 "parallels"=2
"time"="2024-05-17 17:27:47.345912" "level"="debug" "logger"="node/pushsync" "msg"="pushTrace:pushToClosest:retry" "chunk"="c4591c9eb98fe831670b459aef36029b0da80cdaa1a39771bfe9bcb55d69a09b" "why"="parallelForwards(2)"
"time"="2024-05-17 17:27:47.345926" "level"="debug" "logger"="node/pushsync" "msg"="pushTrace:pushToClosest:retry" "chunk"="c4591c9eb98fe831670b459aef36029b0da80cdaa1a39771bfe9bcb55d69a09b" "why"="parallelForwards(1)"
"time"="2024-05-17 17:27:47.345948" "level"="debug" "logger"="node/pushsync" "msg"="pushTrace:pushToClosest:pushing" "chunk"="c4591c9eb98fe831670b459aef36029b0da80cdaa1a39771bfe9bcb55d69a09b" "peer"="c802c453899cf40786257e3d84e593604352daba08419e6f019cf324434a6137"
"time"="2024-05-17 17:27:47.345986" "level"="debug" "logger"="node/pushsync" "msg"="pushTrace:pushChunkToPeer" "chunk"="c4591c9eb98fe831670b459aef36029b0da80cdaa1a39771bfe9bcb55d69a09b" "peer"="c802c453899cf40786257e3d84e593604352daba08419e6f019cf324434a6137"
"time"="2024-05-17 17:27:47.345980" "level"="debug" "logger"="node/pushsync" "msg"="pushTrace:pushToClosest:pushing" "chunk"="c4591c9eb98fe831670b459aef36029b0da80cdaa1a39771bfe9bcb55d69a09b" "peer"="deff932ca047d29e9f6cef268de0f9f4d66f155016cd5cf6138d373e339f640c"
"time"="2024-05-17 17:27:47.348306" "level"="debug" "logger"="node/pushsync" "msg"="pushTrace:pushToClosest:pushing" "chunk"="c4591c9eb98fe831670b459aef36029b0da80cdaa1a39771bfe9bcb55d69a09b" "peer"="e8056b9ffdca31f834eaf0bc214a5db2141c71ec04108244f8ffeefd88572e19"
"time"="2024-05-17 17:27:47.348317" "level"="debug" "logger"="node/pushsync" "msg"="pushTrace:pushChunkToPeer" "chunk"="c4591c9eb98fe831670b459aef36029b0da80cdaa1a39771bfe9bcb55d69a09b" "peer"="e8056b9ffdca31f834eaf0bc214a5db2141c71ec04108244f8ffeefd88572e19"
"time"="2024-05-17 17:27:47.348901" "level"="debug" "logger"="node/pushsync" "msg"="pushTrace:pushChunkToPeer" "chunk"="c4591c9eb98fe831670b459aef36029b0da80cdaa1a39771bfe9bcb55d69a09b" "peer"="deff932ca047d29e9f6cef268de0f9f4d66f155016cd5cf6138d373e339f640c"
"time"="2024-05-17 17:27:47.352451" "level"="debug" "logger"="node/pushsync" "msg"="uploadTrace:Report" "address"="c4591c9eb98fe831670b459aef36029b0da80cdaa1a39771bfe9bcb55d69a09b" "batch"="cf5ab2db3f836eb8d78dcfc3f5e21ab510c15ee627e59d7bea357b0a12375d41" "tag"=94 "state"="ChunkSent"
"time"="2024-05-17 17:27:47.355388" "level"="debug" "logger"="node/pushsync" "msg"="uploadTrace:Report" "address"="c4591c9eb98fe831670b459aef36029b0da80cdaa1a39771bfe9bcb55d69a09b" "batch"="cf5ab2db3f836eb8d78dcfc3f5e21ab510c15ee627e59d7bea357b0a12375d41" "tag"=94 "state"="ChunkSent"
"time"="2024-05-17 17:27:47.366703" "level"="debug" "logger"="node/pushsync" "msg"="uploadTrace:Report" "address"="c4591c9eb98fe831670b459aef36029b0da80cdaa1a39771bfe9bcb55d69a09b" "batch"="cf5ab2db3f836eb8d78dcfc3f5e21ab510c15ee627e59d7bea357b0a12375d41" "tag"=94 "state"="ChunkSent"
"time"="2024-05-17 17:27:47.380237" "level"="debug" "logger"="node/pushsync" "msg"="pushTrace:push success" "chunk"="c4591c9eb98fe831670b459aef36029b0da80cdaa1a39771bfe9bcb55d69a09b" "peer"="e8056b9ffdca31f834eaf0bc214a5db2141c71ec04108244f8ffeefd88572e19"
"time"="2024-05-17 17:27:47.381899" "level"="debug" "logger"="node/pushsync" "msg"="pushTrace:pushToClosest:result" "chunk"="c4591c9eb98fe831670b459aef36029b0da80cdaa1a39771bfe9bcb55d69a09b" "peer"="e8056b9ffdca31f834eaf0bc214a5db2141c71ec04108244f8ffeefd88572e19"
"time"="2024-05-17 17:27:47.383814" "level"="debug" "logger"="node/pushsync" "msg"="pushTrace:push success" "chunk"="c4591c9eb98fe831670b459aef36029b0da80cdaa1a39771bfe9bcb55d69a09b" "peer"="c802c453899cf40786257e3d84e593604352daba08419e6f019cf324434a6137"
"time"="2024-05-17 17:27:47.382510" "level"="error" "logger"="node/pusher" "msg"="pusher: failed checking receipt" "error"="pusher: shallow receipt depth 3, want at least 4, chunk_address c4591c9eb98fe831670b459aef36029b0da80cdaa1a39771bfe9bcb55d69a09b: shallow recipt" "chunk_address"="c4591c9eb98fe831670b459aef36029b0da80cdaa1a39771bfe9bcb55d69a09b"
"time"="2024-05-17 17:27:47.384929" "level"="debug" "logger"="node/pushsync" "msg"="pushTrace:push success" "chunk"="c4591c9eb98fe831670b459aef36029b0da80cdaa1a39771bfe9bcb55d69a09b" "peer"="deff932ca047d29e9f6cef268de0f9f4d66f155016cd5cf6138d373e339f640c"

Note: my source code with all of these logs (and more) can be found in: https://github.com/ldeffenb/bee/blob/5ebc9b342f0a86532865a34769a09a67c1421a6c/pkg/pushsync/pushsync.go

Steps to reproduce

Do an upload in the sepolia testnet swarm which has some neighborhoods (at least, right now) with only a single node. This results in chunks multiplexing outside the neighborhood.

Possible solution

The issue is in pushsync where it attempts to multiplex pushes into a neighborhood that is within the storage radius. Specifically: https://github.com/ethersphere/bee/blob/92de2855d39c94cc1b7d78955c81463e1edcc72f/pkg/pushsync/pushsync.go#L403 The problem here is that parallelForwards retries are queued which each individually invoke closestPeer in the (false) hope that the next closest N peers will also be within the storage radius. Depending on the connected peers, this may or may not be the case.

In my observations, in the sparsely populated sepolia testnet swarm, only the closest peer is within the radius, and the next 2 (in the default configuration of maxMultiplexForwards = 2) peers are actually outside the radius. What this ends up doing is routing pushes through other peers which will then also deliver the pushed chunk into the proper neighborhood, multiplying the push overhead similar to a DDOS attack.

In addition, if one of the non-radius peers actually delivers the pushsync completion first, their receipt is returned to the pusher who concludes that it is a "shallow" receipt and attempts multiple retries, each of which picks up further and further away from the original "closest" peer. This can also cause extensive swap compensation load on the pushing node as each of the multiplexed pushsync's is charged against swap and can actually cause downstream cheques to be issued that are not covered by the original upstream pusher.

I tried a fix whereby I tried to get and check that the next closest peer was still within radius, but since the current peer has not yet been added to the skipList, the same in-radius peer is still returned by closestPeer. Somehow, a multiplexing retry should NOT push to a peer that is outside the radius, but other retries should try for any available peer. Not sure how to implement such a thing.

So, instead of fixing it, I the maxMultiplexForwards to 0 to disable the multiplexing and indeed, the shallow receipt depth errors and the out-of-radius pushsyncs completely stopped occurring.

Note that if you try setting this to zero, you also need to fix the following line to use max(1,parallelForwards) or pushing completely stops happening as the initial retry() doesn't queue anything into the zero length channel.

https://github.com/ethersphere/bee/blob/92de2855d39c94cc1b7d78955c81463e1edcc72f/pkg/pushsync/pushsync.go#L342

ldeffenb commented 1 month ago

If you need any additional examples, or my full log, just ask me for bee-2.1.0-rc2-6.out on 38's sepolianodes.

istae commented 1 month ago

1) One of the problems is that the shallow receipt check is done in the pusher. It should ideally be moved to pusync, which would allow us to add a peer to the skiplist ONLY on error. This means that pushsync only returns valid receipts, so that pusher does not have to retry again. this would also fix the issue you raised https://github.com/ethersphere/bee/issues/4683.

2) About the issue of "a multiplexing retry should NOT push to a peer that is outside the radius": multiplexing is an attempt to get multiple neighborhood nodes to store the same chunk to increase the probability that the chunk is syced within the neighborhood properly. The multiplexer should ideally only pick neighborhood peers but the multiplexer may very well be connected to a single node from the target neighborhood so we went with lesser restrictive approach of not checking the proximities. This has worked fine to my knowledge so far on mainnet which is a well populated network, but on testnet, it has backfired (albeit syncing is still working, but requires more work).

I'd prioritize tackling point 1 first.

ldeffenb commented 1 month ago

I'd prioritize tackling point 1 first.

I agree, but I think #2 is actually still critical in the mainnet. It is just harder to detect because there are more routes to get into the target neighborhood and more nodes in each neighborhood. Consider a chunk that has a different leading bit than the pusher. There is a small chance that one of the 20 peers connected in bin 0 is actually the correct neighborhood, but the other 2 (default configuration) are almost definitely NOT in the proper neighborhood, and I would go so far as to say likely that they're multiple-hops removed from a connection to that neighborhood. So there's still LOTS of redundant push traffic potentially being generated by the multiplexer not actually doing the proximity checks on the extra targets. The only advantage mainnet has, and likely the reason that it is less noticeable, is that the direct peer in the neighborhood has a good chance (presuming it is sufficiently performant) of delivering the push receipt before the routed requests, so the preferred connection won't be shallow, at least the first time the chunk is pushed (see also #4683 ).

But it's not as much of an issue since I've disabled multiplexing completely in my hack, and others willing to rebuild the code will also be able to do so if desired after #4682 is in place.