Data Transfer Stall

[Stebalien]

Update (May 28th): We have deployed #8082 to monitor BS with the latest fix ipfs/go-bitswap#477. We are still running into the 'this request was not processed in time' error but this is likely a false positive due to an incorrect timeout setting in the monitoring tool that we should calibrate for a GW node in production. We need to make this setting a normal IPFS config that can be modified through the standard CLI to avoid restarting the node and better calibrate the timeout. (There's a tribute issue about it that might be picked up next week: #8157.)

---

Version information:

go-ipfs v0.8.0

Description:

We saw a bitswap stall on some of the preload nodes where they were unable to download any content, even from connected nodes (ipfs/js-ipfs#3577).

This looks related to #5183 but that issue was mostly about specific content. That is, a specific request would fail, and we'd get into a stuck state where we couldn't download that specific content.

The preload nodes did not appear to be spinning, stuck, etc. but restarting them fixed the issue.

Possible causes:

• Deadlock somewhere.
• Full wantlist? Maybe we have some cases where wants are getting stuck in the wantlist and never clearing, building up over time?

[BigLep]

@aschmahmann is going to provide more context/info.

[aschmahmann]

There was a report that a node was not sending data over bitswap despite having the data locally. The user was able to run ipfs block stat --offline <cid> and get a result, and yet the data seemed not to transfer over Bitswap.

I investigated further using vole https://github.com/aschmahmann/vole to directly send the node a Bitswap request such as:

vole.exe bitswap check <cid> <peer-multiaddr> and got the response {"Found":false,"Responded":false,"Error":null}, which means we did not get a response or an error on whether we received the other peer has the data or not. IIRC the peer was still able to respond to requests from other peers about other CIDs, but I don't recall at the moment what other types of probing I tried from my machine 😟.

[Stebalien]

Matt noted that disabling QUIC seemed to help. This issue could be related to libp2p/go-libp2p-quic-transport#57 (where we could be failing to timeout somewhere in bitswap, backing everything up).

[schomatis]

Although I have a vague understanding of the high level issue I don't find enough information to translate this into any actionable item.

• Is the idea (at least for the moment) to make a speculative static analysis based on the limited information or are there tests or dynamic analysis where I could get more information?
  • Static: I don't have much experience with bitswap code so I'm going to need some pointers to a couple of entry places if the analysis should go that way.
  • Dynamic: can I test this locally?
    • If yes, can I run a single ipfs daemon node or do I need to set up a more involved local network?
    • If no, do I need access to the gateways?

[aschmahmann]

Dynamic: can I test this locally?

I do not know of a way to reproduce this issue. My recollection from some comments @gmasgras made are that the situation we saw was.

• Gateway A fetches CID X from the network (or our cluster, I forget)
• Gateway B is peered to A
• B tries to fetch X and fails even though A has the data
  • Running ipfs block stat --offline X would give us the data
  • Running vole bitswap check X Aaddress gives {"Found":false,"Responded":false,"Error":null}

It might be that simulating this situation + check on the gateway once every 30 min would at least let us know if this continues to happen and could enable more live debugging on the node. cc @coryschwartz who's started on some scripts that might help here.

Static: I don't have much experience with bitswap code so I'm going to need some pointers to a couple of entry places if the analysis should go that way.

Ya, this is harder. The place I'd investigate is tracking how an inbound message gets put into a queue and gets dropped, stuck forever or for a very long time, etc. (IIRC I've waited over 30 minutes on a response). This means starting with the message handling code and tracing how it enters and leaves the queue.

[coryschwartz]

Adding some content to an IPFS node and trying to read it through the gateways, some of the content would throw a HTTP 504 after several minutes.

I setup a second IPFS node with the routing disabled and peered it only to the gateways.

What I found is that some of the gateways responded with an error some of the time. Using vole, and a list of CIDs I had added earlier, I could check the status for each gateway. Sometimes, running this test results in successes for all CIDS on all gateways. Other times, a gateway will stall for several minutes before finally throwing an error.

Running this rudementary script to check each gateway against a set of CIDS

GATEWAYS=(
        "/dns/gateway-bank1-am6.dwebops.net/tcp/4001/p2p/12D3KooWEfQkss14RPkFoGCby5ZRo5F2UYEMEfSAbYUdjeAE6Dk3"
        "/dns/gateway-bank1-ams1.dwebops.net/tcp/4001/p2p/QmXAdzKCUZTg9SLLRK6nrfyhJmK1S43n2y5EBeGQ7zqhfW"
        "/dns/gateway-bank1-dc13.dwebops.net/tcp/4001/p2p/12D3KooWJfq7u5cYc65HAZT3mE3irDH5KYSUdFxXTdf2KTB7FQgf"
        "/dns/gateway-bank1-mrs1.dwebops.net/tcp/4001/p2p/QmYZmw1PQXtKVeAjRfn8TnKYAurSdezRd1kdDjenzxTF6y"
        "/dns/gateway-bank1-nrt1.dwebops.net/tcp/4001/p2p/QmQ41LAQUdH6JQCeSR1qMT8qdPAkZ9XgkvqYHs9HiAdh5Z"
        "/dns/gateway-bank1-ny5.dwebops.net/tcp/4001/p2p/12D3KooWDUGVYVaJKmGR3eJCbgihEYgYAfpnZqJYzhzeaJrLxq6j"
        "/dns/gateway-bank1-sg1.dwebops.net/tcp/4001/p2p/12D3KooWGoaeFe2h4uhTEAhaN6yTccUMn5uizxvyRaWkd2x8ZYHP"
        "/dns/gateway-bank1-sjc1.dwebops.net/tcp/4001/p2p/QmXYHU1M8t86gRKvUmE42smybPKXqTPEUPDUaCVtLmS6Bw"
        "/dns/gateway-bank2-ams1.dwebops.net/tcp/4001/p2p/QmRzfM4kLwk6AjnZVmFra9RdMguWyjU4j8tctNz6dzxjxc"
        "/dns/gateway-bank2-dc13.dwebops.net/tcp/4001/p2p/12D3KooWAAW7p19cyLb39w5V5AuvX4c5gTPtQv8RuZo2tCKeFpZ7"
        "/dns/gateway-bank2-mrs1.dwebops.net/tcp/4001/p2p/QmSPz3WfZ1xCq6PCFQj3xFHAPBRUudbogcDPSMtwkQzxGC"
        "/dns/gateway-bank2-nrt1.dwebops.net/tcp/4001/p2p/QmXygeCqKjpcbT9E7jgSbAvcDnPaJp9gQDzEVFZ6zzjVc2"
        "/dns/gateway-bank2-ny5.dwebops.net/tcp/4001/p2p/12D3KooWDBprpmGqQay9f513WvQ9cZfXAtW1TiqPP2fpuEGnZsqh"
        "/dns/gateway-bank2-sg1.dwebops.net/tcp/4001/p2p/12D3KooWDK1MAZuySwEv49Zmm7JVgsUgjGwZVB8Kdzdwr7mLcNL2"
        "/dns/gateway-bank2-sjc1.dwebops.net/tcp/4001/p2p/QmVLb8bi8oAmLwrTdjGurtVGN7FaJvhXP5UM3s56uyqfxL"
)

for gw in "${GATEWAYS[@]}"
do
        (
        echo "---------------"
        echo checking $gw
        for cid in $(cat pinned.txt)
        do
                echo -n "${cid} "
                ./vole bitswap check $cid $gw 2>&1
                echo "return status: $?"
        done
        ) | tee $(sed 's/\//_/g'<<<"${gw}.tst") &
done

wait

The problem doesn't seem to persist. If I have trouble htting a CID from one of the gateways once, and then try again later the problem has resolved itself.

This might not always be the case, but when I ran this, only saw errors on one specific gateway node, and I captured a profile of the node running there in case it's useful.

https://gist.github.com/coryschwartz/3eaae387933f16ee7b455ffd3eb6d122

one server gateway does take on more load than the rest, and it is not uncommon for the nginx response time to exhaust the full 10 minute timeout. For all gateways, the P99 response time for nginx 10 minutes (the nginx timeout). location:nginx_http_response_time_ms:99p

load averages for gateways

of course load follows with other metrics, throughput, etc.

I still need to look farther to understand exactly what's going on here, but I wonder if just adding some load shedding to the gateways would make the service more performent for users. Nginx could be configured to try locally, and after a short timeout, try another node.

[schomatis]

@coryschwartz I need more information to reproduce this, could you please expand on:

I setup a second IPFS node with the routing disabled and peered it only to the gateways.

and the file pinned.txt from your script.

[schomatis]

@aschmahmann I need more precision as to what a 'bitswap stall' means. Is it the {"Found":false,"Responded":false,"Error":null} response? Meaning we are connected to the peer, receiving messages but no message reports either having or not having the requested CID (which I assume is expected by bitswap upcoming spec, although I would want to know within which time window that is).

In that case I can consistently get that response from GW gateway-bank1-sjc1.dwebops.net with "hello world" CID:

(with ipshipyard/vole#1)

vole bitswap check QmQPeNsJPyVWPFDVHb77w8G42Fvo15z4bG2X8D2GhfbSXc /dns/gateway-bank1-sjc1.dwebops.net/tcp/4001/p2p/QmXYHU1M8t86gRKvUmE42smybPKXqTPEUPDUaCVtLmS6Bw