feat: opt-in Swarm.ResourceMgr (go-libp2p v0.18)

[marten-seemann]

Part of #8761

• go-libp2p v0.18.0 completes the deprecation of ipfs/go-log@v1 and migrates all remaining repos to ipfs/go-log@v2
• Adds commands and configuration for libp2p Network Resource Manager
  • ipfs swarm limit --help
  • ipfs swarm stats --help
• Adds config at Swarm.ResourceMgr
  • Swarm.ResourceMgr.Enabled is a flag, disabled by default

Closes #8722
Closes #1482 🧙‍♂️

• remove the log/tail command go-ipfs-api#263.
• Decide where to put these commands
  • done in feat(core): add libp2p resource manager #8735 which got merged into this PR
• Make command reading config from a file work over HTTP RPC
• final cleanup by @lidel – see feat: opt-in Swarm.ResourceMgr (go-libp2p v0.18) #8680 (comment)
  • Add opt-in env or config flag to control resource manager instantiation, until we are comfortable with production testing to enable by default (similar to improve resource manager integration filecoin-project/lotus#8318)
  • Decide where is the limit.json config file going to live: hardcoded in the repo root or configured through go-ipfs-config.

[guseggert]

Do you have plans to publish metrics when a RM req is rejected due to exceeded scope limits? That would be very useful operationally to help know when to scale gateway fleets.

[marten-seemann]

The resource manager has a tracer integration (see https://github.com/libp2p/go-libp2p-resource-manager/blob/master/trace.go), so it would be possible to hook this up with Prometheus in one way or the other.

[vyzo]

travis asked for the same thing so i will add metrics support to the reource manager.

…

On Fri, Feb 11, 2022, 14:50 Marten Seemann ***@***.***> wrote: The resource manager has a tracer integration (see https://github.com/libp2p/go-libp2p-resource-manager/blob/master/trace.go), so it would be possible to hook this up with Prometheus in one way or the other. — Reply to this email directly, view it on GitHub <#8680 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AAAI4SREFOVU7UPT2MVGGMTU2UA2XANCNFSM5MBCYZ7Q> . You are receiving this because you are subscribed to this thread.Message ID: ***@***.***>

[lidel]

"exchange files" → "cat file" interop test always gets stuck after go -> go2: 8.39 MB (125ms)
(was able to reproduce locally with this PRs binary)

Quick way to reproduce/debug is to run specific test with:
export IPFS_GO_EXEC=/path/to/ipfs-binary-from-libp2p-v018-branch/ipfs
npx ipfs-interop -- -t node --grep "go -> go2: 8.39 MB → works
npx ipfs-interop -- -t node --grep "go -> go2: 67.1 MB" → hangs

Given this PR adds resource manager, I guess some limit is hit?

Update: set DEBUG="ipfsd-ctl:daemon*" IPFS_LOGGING="INFO" in env to see go-ipfs daemon logs.

[lidel]

DEBUG="ipfsd-ctl:daemon*" IPFS_LOGGING="DEBUG"  npx ipfs-interop -- -t node --grep "go -> go2: 67.1 MB"

Revealed connection being dropped by go-libp2p-resource-manager:

2022-02-24T02:49:11.848+0100    DEBUG   rcmgr   go-libp2p-resource-manager@v0.1.3/scope.go:239  blocked memory reservation      {"scope": "peer:12D3KooWReFVRYtypujVVXkvictuB8PyaZnSraLEDvwQPGSDxMaL", "size": 258126, "priority": 128, "error": "resource limit exceeded"}
2022-02-24T02:49:11.849+0100    DEBUG   dht     net/message_manager.go:303      error reading message   {"error": "stream reset", "retrying": true}
2022-02-24T02:49:11.849+0100    DEBUG   swarm2  go-libp2p-swarm@v0.10.2/swarm.go:336    [12D3KooWKyDk1EymJbcr59vVjJeJUvwe6vdAUKXnRtbNVt63pvow] opening stream to peer [12D3KooWReFVRYtypujVVXkvictuB8PyaZnSraLEDvwQPGSDxMaL]
2022-02-24T02:49:11.849+0100    DEBUG   swarm2  go-libp2p-swarm@v0.10.2/swarm_dial.go:241       dialing peer    {"from": "12D3KooWKyDk1EymJbcr59vVjJeJUvwe6vdAUKXnRtbNVt63pvow", "to": "12D3KooWReFVRYtypujVVXkvictuB8PyaZnSraLEDvwQPGSDxMaL"}
2022-02-24T02:49:11.849+0100    DEBUG   swarm2  go-libp2p-swarm@v0.10.2/limiter.go:193  [limiter] adding a dial job through limiter: /ip4/127.0.0.1/tcp/44017
2022-02-24T02:49:11.849+0100    DEBUG   swarm2  go-libp2p-swarm@v0.10.2/limiter.go:161  [limiter] taking FD token: peer: 12D3KooWReFVRYtypujVVXkvictuB8PyaZnSraLEDvwQPGSDxMaL; addr: /ip4/127.0.0.1/tcp/44017; prev consuming: 0
2022-02-24T02:49:11.849+0100    DEBUG   swarm2  go-libp2p-swarm@v0.10.2/limiter.go:167  [limiter] executing dial; peer: 12D3KooWReFVRYtypujVVXkvictuB8PyaZnSraLEDvwQPGSDxMaL; addr: /ip4/127.0.0.1/tcp/44017; FD consuming: 1; waiting: 0
2022-02-24T02:49:11.849+0100    DEBUG   swarm2  go-libp2p-swarm@v0.10.2/swarm_dial.go:386       12D3KooWKyDk1EymJbcr59vVjJeJUvwe6vdAUKXnRtbNVt63pvow swarm dialing 12D3KooWReFVRYtypujVVXkvictuB8PyaZnSraLEDvwQPGSDxMaL /ip4/127.0.0.1/tcp/44017
2022-02-24T02:49:11.849+0100    INFO    bitswap go-bitswap@v0.5.1/bitswap.go:638        Bitswap ReceiveError: stream reset
2022-02-24T02:49:11.849+0100    DEBUG   bitswap_network network/ipfs_impl.go:413        bitswap net handleNewStream from 12D3KooWReFVRYtypujVVXkvictuB8PyaZnSraLEDvwQPGSDxMaL error: stream reset
2022-02-24T02:49:11.849+0100    INFO    bitswap go-bitswap@v0.5.1/bitswap.go:638        Bitswap ReceiveError: stream reset
2022-02-24T02:49:11.849+0100    DEBUG   bitswap_network network/ipfs_impl.go:413        bitswap net handleNewStream from 12D3KooWReFVRYtypujVVXkvictuB8PyaZnSraLEDvwQPGSDxMaL error: stream reset
2022-02-24T02:49:11.849+0100    INFO    connmgr connmgr/connmgr.go:546  tried to remove tag from untracked peer: 12D3KooWReFVRYtypujVVXkvictuB8PyaZnSraLEDvwQPGSDxMaL
2022-02-24T02:49:11.849+0100    DEBUG   bs:sprmgr       sessionpeermanager/sessionpeermanager.go:98     Bitswap: removed peer from session      {"session": 1, "peer": "12D3KooWReFVRYtypujVVXkvictuB8PyaZnSraLEDvwQPGSDxMaL", "peerCount": 0}

[marten-seemann]

Revealed connection being dropped by go-libp2p-resource-manager

There's no connection being dropped. The resource manager is blocking a memory with prio 128, which is probably a yamux stream window increase: https://github.com/libp2p/go-yamux/blob/cd22a37b789cf6e1fe4f2c2cff6da5df7a49dfac/stream.go#L229. This won't cause any problems.

Do we have logs from the other node?

[lidel]

These logs ipfsd-ctl:daemon are from both ends, which make it difficult to debug.

I decided to remove ipfs-interop from the picture and was still able to replicate the issue without it, using two nodes on same machine.

👉 ipfs cat of 65MB file gets stuck

With this setup you can tweak IPFS_LOGGING level for each node independently, and see logs on each end:

Node A (source)

One terminal:

$ export IPFS_PATH=/tmp/node-a
$ ipfs daemon --init --init-profile server,randomports,test

Second terminal:

$ ipfs id | jq '.Addresses[0]' 
{addrA}
$ ipfs swarm connect  {addrB}
$ head -c 65M /dev/urandom | ipfs add -Q
{cid-OK}
$ head -c 8M /dev/urandom | ipfs add -Q
{cid-FAIL}

Node B (destination)

One terminal:

$ export IPFS_PATH=/tmp/node-b
$ ipfs daemon --init --init-profile server,randomports,test

Second terminal:

$ ipfs id | jq '.Addresses[0]' 
{addrB}
$ ipfs swarm connect  {addrA}
$ ipfs cat {cid-OK} > /tmp/8M # finished instantly
$ ipfs cat {cid-FAIL} > /tmp/65M # stops in the middle (around 20-50%)
30.50 MiB / 65.00 MiB [==================================>--------------------------------------]  46.92%

[aschmahmann]

@marten-seemann @lidel I'm not totally sure, but am wondering if we're running into a combination of go-bitswap not gracefully handling the lack of streams and go-bitswap using more streams than it should (ipfs/boxo#80).

[vyzo]

or yamux not handling properly the refusal yo increase the window from the other side, that also a possibility.

…

On Thu, Feb 24, 2022, 16:17 Adin Schmahmann ***@***.***> wrote: @marten-seemann <https://github.com/marten-seemann> @lidel <https://github.com/lidel> I'm not totally sure, but am wondering if we're running into a combination of go-bitswap not gracefully handling the lack of streams and go-bitswap using more streams than it should ( ipfs/boxo#80 <ipfs/boxo#80>). — Reply to this email directly, view it on GitHub <#8680 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AAAI4SXHGGPWMEJAWSY2AHLU4Y4ZBANCNFSM5MBCYZ7Q> . You are receiving this because you commented.Message ID: ***@***.***>

[BigLep]

2022-03-03 conversation:

1. @BigLep : create issue for the overall user story to link to
2. Making config changes without recompiling will likely be key here, even for the initial gateway testing for validating go-libp2p 0.18.

[lidel]

Applied changes based on feedback from stewards sync:

• core/node/libp2p/rcmgr_defaults.go vendors all implicit default limits from go-libp2p
  • the number of hardcoded numbers is scary 🙈
  • adjustedDefaultLimits is tweaking default limits based on external factors, such as values in existing Swarm.ConnMgr.HighWater config (ported fix from improve resource manager integration filecoin-project/lotus#8318)
• Ended up keeping limit.json parser and hiding Swarm.ResourceMgr.Limits for now.
  • The way defaults are handled and initialized by go-libp2p is bit complex, there are at least two layers of indirection using different structs.
  • Coming up with Swarm.ResourceMgr.Limits that acts as persistence for ipfs swarm limit -s and is compatible with limit.json will improve UX, but that is additional work which should not block go-libp2p 0.18 from being merged.

Before this is merged, we should make a decision if we are ok with

• hardcoding all these default limits
  • DECISION: remove, and keep only the adjustedDefaultLimits logic (this is in separate PR feat: detect default limit changes in go-libp2p-resource-manager #8857)
• not having Swarm.ResourceMgr.Limits in our config and using standalone limit.json for now
  • I vote merging as-is, just so we land new go-libp2p. Wiring up Swarm.ResourceMgr.Limits can happen in a future PR.
  • Remaining UX improvements extracted to ResourceMgr UX improvements #8858