BlockPut context canceled

[mikeshultz]

Additional information:

• OS: Linux
• IPFS Cluster version: 0.13.0+git6b25d6fd3ed2348f8e8460ae1dcc0ee0ce4a255d
• Installation method: official docker images (ipfs/ipfs-cluster:v0.13.0)

Describe the bug:

Using the ipfs-deploy package, I'm trying to add a directory of files, which appears to call /add with all the files. This appears to fail during a call to the ipfs daemon at /aip/v0/block/put but has no useful information about the error that occurred, even with debug logging.

Furthest I got investigating the source of the error was to this line which appears to be the source of the context canceled message in the ipfs-cluster code:

https://github.com/ipfs/ipfs-cluster/blob/d2a83e45f1ad5f84a3eae70b46fb9b521b90ab03/adder/util.go#L58

It doesn't seem to happen with the first call either. Here's an example of debug log output during this request:

2020-07-15T18:43:47.934Z    DEBUG   adder   adder/adder.go:84   adding from multipart with params: &{PinOptions:{ReplicationFactorMin:0 ReplicationFactorMax:0 Name:mikes-swag Mode:recursive ShardSize:0 UserAllocations:[] ExpireAt:0001-01-01 00:00:00 +0000 UTC Metadata:map[] PinUpdate:b} Local:false Recursive:true Layout: Chunker:size-262144 RawLeaves:false Hidden:false Wrap:false Shard:false Progress:false CidVersion:0 HashFun:sha2-256 StreamChannels:true NoCopy:false}
2020-07-15T18:43:47.934Z    DEBUG   adder   adder/adder.go:97   adding from files
2020-07-15T18:43:47.935Z    DEBUG   adder   adder/adder.go:164  ipfsAdder AddFile(public)
2020-07-15T18:43:47.936Z    DEBUG   adder   adder/util.go:44    block put QmWKFE4HMRaBNQt6NDn2afr8gaWi6pRckwa9E2E8a2Qz66 to [12D3KooWMdb9phVShHQz6FBGzy2LtPEdvBh8mndQeBSrzTuoqqj7 QmQX5HVjn9HJ6yKhATYtHmKXrMAEUCYvXhZEkpTirbWFEm]
2020-07-15T18:43:47.937Z    DEBUG   ipfshttp    ipfshttp/ipfshttp.go:849    putting block to IPFS: QmWKFE4HMRaBNQt6NDn2afr8gaWi6pRckwa9E2E8a2Qz66
2020-07-15T18:43:47.937Z    DEBUG   ipfshttp    ipfshttp/ipfshttp.go:549    posting block/put?format=v0&mhlen=32&mhtype=sha2-256
2020-07-15T18:43:47.942Z    DEBUG   ipfshttp    ipfshttp/ipfshttp.go:899    block/put response CIDQmWKFE4HMRaBNQt6NDn2afr8gaWi6pRckwa9E2E8a2Qz66
2020-07-15T18:43:47.949Z    DEBUG   adder   adder/util.go:44    block put QmWKFE4HMRaBNQt6NDn2afr8gaWi6pRckwa9E2E8a2Qz66 to [12D3KooWMdb9phVShHQz6FBGzy2LtPEdvBh8mndQeBSrzTuoqqj7 QmQX5HVjn9HJ6yKhATYtHmKXrMAEUCYvXhZEkpTirbWFEm]
2020-07-15T18:43:47.949Z    DEBUG   ipfshttp    ipfshttp/ipfshttp.go:849    putting block to IPFS: QmWKFE4HMRaBNQt6NDn2afr8gaWi6pRckwa9E2E8a2Qz66
2020-07-15T18:43:47.949Z    DEBUG   ipfshttp    ipfshttp/ipfshttp.go:549    posting block/put?format=v0&mhlen=32&mhtype=sha2-256
2020-07-15T18:43:47.951Z    DEBUG   ipfshttp    ipfshttp/ipfshttp.go:899    block/put response CIDQmWKFE4HMRaBNQt6NDn2afr8gaWi6pRckwa9E2E8a2Qz66
2020-07-15T18:43:47.960Z    DEBUG   adder   adder/util.go:44    block put QmRJLjMa3SF6D2EMURsnBKuu5AoUBrVpdQJ9Y2E5isUcTG to [12D3KooWMdb9phVShHQz6FBGzy2LtPEdvBh8mndQeBSrzTuoqqj7 QmQX5HVjn9HJ6yKhATYtHmKXrMAEUCYvXhZEkpTirbWFEm]
2020-07-15T18:43:47.960Z    DEBUG   ipfshttp    ipfshttp/ipfshttp.go:849    putting block to IPFS: QmRJLjMa3SF6D2EMURsnBKuu5AoUBrVpdQJ9Y2E5isUcTG
2020-07-15T18:43:47.960Z    DEBUG   ipfshttp    ipfshttp/ipfshttp.go:549    posting block/put?format=v0&mhlen=32&mhtype=sha2-256
2020-07-15T18:43:47.963Z    DEBUG   ipfshttp    ipfshttp/ipfshttp.go:899    block/put response CIDQmRJLjMa3SF6D2EMURsnBKuu5AoUBrVpdQJ9Y2E5isUcTG
2020-07-15T18:43:47.965Z    DEBUG   adder   adder/util.go:44    block put QmRJLjMa3SF6D2EMURsnBKuu5AoUBrVpdQJ9Y2E5isUcTG to [12D3KooWMdb9phVShHQz6FBGzy2LtPEdvBh8mndQeBSrzTuoqqj7 QmQX5HVjn9HJ6yKhATYtHmKXrMAEUCYvXhZEkpTirbWFEm]
2020-07-15T18:43:47.965Z    DEBUG   ipfshttp    ipfshttp/ipfshttp.go:849    putting block to IPFS: QmRJLjMa3SF6D2EMURsnBKuu5AoUBrVpdQJ9Y2E5isUcTG
2020-07-15T18:43:47.965Z    ERROR   p2p-gorpc   go-libp2p-gorpc@v0.1.0/call.go:64   context canceled
2020-07-15T18:43:47.965Z    DEBUG   ipfshttp    ipfshttp/ipfshttp.go:549    posting block/put?format=v0&mhlen=32&mhtype=sha2-256
2020-07-15T18:43:47.965Z    ERROR   ipfshttp    ipfshttp/ipfshttp.go:561    error posting to IPFS:Post "http://127.0.0.1:5001/api/v0/block/put?format=v0&mhlen=32&mhtype=sha2-256": context canceled
2020-07-15T18:43:47.965Z    ERROR   p2p-gorpc   go-libp2p-gorpc@v0.1.0/call.go:64   Post "http://127.0.0.1:5001/api/v0/block/put?format=v0&mhlen=32&mhtype=sha2-256": context canceled
2020-07-15T18:43:47.965Z    ERROR   adder   adder/util.go:58    BlockPut on 12D3KooWMdb9phVShHQz6FBGzy2LtPEdvBh8mndQeBSrzTuoqqj7: Post "http://127.0.0.1:5001/api/v0/block/put?format=v0&mhlen=32&mhtype=sha2-256": context canceled
2020-07-15T18:43:47.965Z    ERROR   adder   adder/util.go:58    BlockPut on QmQX5HVjn9HJ6yKhATYtHmKXrMAEUCYvXhZEkpTirbWFEm: context canceled
2020-07-15T18:43:47.965Z    ERROR   adder   adder/adder.go:168  error adding to cluster: failed to put block on all destinations
2020-07-15T18:43:47.965Z    ERROR   adder   adderutils/adderutils.go:107    failed to put block on all destinations
2020-07-15T18:43:47.966Z    INFO    restapilog  rest/restapi.go:113 10.8.3.21 - - [15/Jul/2020:18:43:47 +0000] "POST /add?name=mikes-swag&recursive=true&stream-channels=true HTTP/1.1" 200 100

Connectivity seems fine between ipfs-cluster and the ipfs daemon (different containers, same kube pod). The error occurs whether or not HTTP basic auth is enabled. This may be an error on my cluster configuration, but I'm having trouble narrowing down the cause of this. Any ideas?

[welcome]

Thank you for submitting your first issue to this repository! A maintainer will be here shortly to triage and review.
In the meantime, please double-check that you have provided all the necessary information to make this process easy! Any information that can help save additional round trips is useful! We currently aim to give initial feedback within two business days. If this does not happen, feel free to leave a comment.
Please keep an eye on how this issue will be labeled, as labels give an overview of priorities, assignments and additional actions requested by the maintainers:

• "Priority" labels will show how urgent this is for the team.
• "Status" labels will show if this is ready to be worked on, blocked, or in progress.
• "Need" labels will indicate if additional input or analysis is required.

Finally, remember to use https://discuss.ipfs.io if you just need general support.

[hsanjuan]

Weird... this looks like the request gets cancelled very soon after starting.

As far as I can tell, the context getting cancelled comes all the way from the HTTP request, so I am suspecting something is not right with ipfs-deploy (or the ipfs-cluster-api library that it uses, since that has been giving people problems before (ipfs-cluster/js-cluster-client#3)).

Is there any chance you can inspect the /add request and the JS console when adding (developer tools?)? Even a tcpdump might be useful to see exactly what is getting posted, without any other info.. but I suspect it's the js-cluster-client library. Does it work with a single file?

[mikeshultz]

Thanks for quick response and the input! Can you shed any light onto what exactly "context canceled" means? Is the connection getting reset, or is there something else to it? I couldn't find a lot of information on this except that it probably comes from net/http.

I didn't really suspect the client on this, assuming it was happening between ipfs-cluster and the ipfs daemon. I'm trying to narrow it down with a bare-minimum script to repro. I'll make sure to try with ipfs-cluster-client separately too.

I can't currently inspect the request since it's being done server-side(nodejs) but when I get this repro script working I'll figure something out to get the raw HTTP request.

[hsanjuan]

The http request that we handle has a "context" associated. If the request dies or is interrupted the context is "cancelled".

That context is passed along as cluster does his things (like triggering other requests). When it comes to trigger a blockPut request it realizes that the context it's trying to use was cancelled, so it errors and interrupts the whole process. It is basically aborting things because the things it's trying to do are linked to a request that somehow stopped.

We use ipfs-cluster-ctl to add content in several places and haven't observed this, that is why I'm suspecting a bug in the client library.

[mikeshultz]

It wasn't the client cancelling it, but an nginx reverse proxy sitting in front of ipfs-cluster.

If anyone stumbles across this issue with a similar issue, I turned off proxy request buffering. That way, nginx doesn't read the entire file being added into memory before sending it along to ipfs-cluster. Still not sure if it was a timeout issue or buffer exhaustion, but turning that off cleared up this issue.

Thanks, @hsanjuan for the background information. That was a lot of help.

[hsanjuan]

Might be related to ipfs/kubo#6402 .

nginx is broken for anything that streams a response without having read the full request. If it works now it might just be because of timing (so essentially getting lucky).