Js-ipfs: Slow response on new files AND Seeing "already piped" errors

[mitra42]

Version: 0.27.4
On OSX
I'm using files.cat to retrieve a file that has only a moment ago been pushed to the IPFS by our gateway server (so I'm expecting a relatively slow response).
But ... I'm seeing "Error already piped" dweb_transport_ipfs_bundled.js:122318 Uncaught Error: already piped
at sink (dweb_transport_ipfs_bundled.js:122318)
at consume (dweb_transport_ipfs_bundled.js:121847)
at Connection.consume (dweb_transport_ipfs_bundled.js:121847)
at pull (dweb_transport_ipfs_bundled.js:123000)
at Dialer.handle (dweb_transport_ipfs_bundled.js:109125)
at attemptMuxerUpgrade (dweb_transport_ipfs_bundled.js:70145)
at gotWarmedUpConn (dweb_transport_ipfs_bundled.js:70035)
at Swarm.dial (dweb_transport_ipfs_bundled.js:70022)
at _getPeerInfo (dweb_transport_ipfs_bundled.js:72065)
at setImmediate (dweb_transport_ipfs_bundled.js:72124)

I realize the linenumbers aren't that helpful, so if the trace isn't easy to find I can try and generate more info.

Of course we are used to seeing the ubiquitous "Stream ended prematurely" and "Invalid MAC" errors, so I'm wondering if this is another that can be safely ignored or is an indication of a problem.

What I'm seeing is that IPFS.files.cat is often never returning.
Sometimes this accompanied by the piping error.
If I reload then and do the exact same thing (the file already having been pushed to the IPFS gateway) t
or could be why I'm not seeing ipfs.files.get ever return .

If I reload and go back to the same file, it works - so I'm pretty sure the issue is in IPFS's response to not finding the file immediately.

Also ... if I load the file from the ipfs.io gateway in a different tab then the files.cat returns.

I'm pretty sure that I've seen that behavior in a different situation, where the act of looking for the file on ipfs.io speeds up the file coming back.

[mitra42]

I'm trying to narrow this down ... there is definitely the new "already piped" error, but it doesn't seem to be the cause of the slow response. I was wrong about files.get, its dag.get that doesn't return. (In my code, I do a dag.get and then call files.cat if its a DAGNode.)

dag.get is - for the new files - not returning at all (can wait 10's of minutes), for files pushed earlier, it works fine. The multihash (as returned by the HTTP API on the gateway server) is: QmZ5TBouUQrZrfUFxARh2RNUPEPgoRRk4QMesvkTaJSXNL
cid reports: CID {codec: "dag-pb", version: 0, multihash: Uint8Array(34)}

I start this process up on the browser, then in another tab go to
https://ipfs.io/ipfs/QmZ5TBouUQrZrfUFxARh2RNUPEPgoRRk4QMesvkTaJSXNL

The file displays happily in that tab AND importantly the dag.get (that was previously sitting there doing nothing) now returns correctly and gets the file.

This is a weird interaction between what should be independent processes. I don't know what is happening under the hood, but it seems like the http retrieval on the ipfs.io server is somehow priming the DHT so the browser call works ?

[mitra42]

I've confirmed some of that assumption by hacking the HTTP gateway so that after pushing the file to the local IPFS gateway, it queries ipfs.io before telling the client the ipfs hash ... Sounds confusing so let me draw out ...

*

1. Client does a metadata request: http://gateway.dweb.me/metadata/archiveid/xxx
2. gateway.dweb.me finds the metadata from inside archive.org, this represents a small set of files (e.g. image, thumbnail, torrent etc)
3. gateway.dweb.me fetches each file from archive server.
4. gateway.dweb.me pushes each file to ipfs.dweb.me running on same server and obtains multihash
5. gateway.dweb.me requests https://ipfs.io/ipfs/ for each file - ignores the result.
6. gateway.dweb.me returns multihash to client with rest of metadata
7. client fetches file through JS-IPFS

This repeatably works.
WIthout step 5 it repeatable fails (dag.get never returns).
I've left gateway.dweb.me with this step enabled, and will be offline for most of the next

(NOTE - gateway.dweb.me is still experimental and its behavior is highly likely to change ! )
Clients are running js-ipfs v0.27.4 (and I'm testing in Chrome)
Server is reports:
{"Version":"0.4.11","Commit":"","Repo":"6","System":"amd64/linux","Golang":"go1.9"}

[mitra42]

More testing .... going a "HEAD https://ipfs.io/ipfs/" is sufficient to unblock the client,
@diasdavid Any idea what could be happening this seems bizarre behavior ?

[daviddias]

That behavior happens flawlessly because Relay hasn't been integrated (aka set to default) and so the Browser node isn't dialing to your local node directly.

It's coming :) https://github.com/ipfs/js-ipfs#project-status

[mitra42]

Ok - I can leave the hack in place for now (of doing a "Head" to ipfs.io) but trying to understanad what it means about DHT not being integrated, how is content being found if not via the DHT, and why does pinging ipfs.io make it suddenly get found. (Note the IPFS server where the content is being "added" is a Go server that Kyle set up).

[mitra42]

I think https://discuss.ipfs.io/t/ipfs-ls-cat-hash-halts-while-gateway-ipfs-shows-the-file-right-away/1853 is the same issue. As the poster says there "the whole point of P2P network is that a path between the node is found, am I wrong?"

[thiagodelgado111]

Not sure but probably related, from time to time I get this error log on the browser console: Uncaught Error: already piped

Details

Uncaught Error: already piped
    at sink (index.js:11)
    at consume (sink.js:7)
    at Connection.consume (sink.js:7)
    at pull (pull.js:43)
    at Dialer.handle (index.js:47)
    at attemptMuxerUpgrade (dial.js:157)
    at gotWarmedUpConn (dial.js:54)
    at Swarm.dial (dial.js:40)
    at _getPeerInfo (index.js:279)
    at setImmediate (index.js:342)
    at setImmediate.js:27
    at run (setImmediate.js:40)
    at runIfPresent (setImmediate.js:69)
    at onGlobalMessage (setImmediate.js:109)
sink @ index.js:11
consume @ sink.js:7
consume @ sink.js:7
pull @ pull.js:43
handle @ index.js:47
attemptMuxerUpgrade @ dial.js:157
gotWarmedUpConn @ dial.js:54
(anonymous) @ dial.js:40
_getPeerInfo @ index.js:279
setImmediate @ index.js:342
(anonymous) @ setImmediate.js:27
run @ setImmediate.js:40
runIfPresent @ setImmediate.js:69
onGlobalMessage @ setImmediate.js:109
postMessage (async)
registerImmediate @ setImmediate.js:120
setImmediate @ setImmediate.js:27
(anonymous) @ setImmediate.js:26
_getPeerInfo @ index.js:342
dial @ index.js:274
dial @ libp2p.js:39
self._libp2pNode.on @ libp2p.js:42
./node_modules/events/events.js.EventEmitter.emit @ events.js:81
discovery.on @ index.js:75
./node_modules/events/events.js.EventEmitter.emit @ events.js:81
_peerDiscovered @ index.js:130
./node_modules/events/events.js.EventEmitter.emit @ events.js:81
proto.addRequest @ listener.js:67
(anonymous) @ utils.js:78
./node_modules/component-emitter/index.js.Emitter.emit @ index.js:133
./node_modules/socket.io-client/lib/socket.js.Socket.onevent @ socket.js:270
./node_modules/socket.io-client/lib/socket.js.Socket.onpacket @ socket.js:228
(anonymous) @ index.js:21
./node_modules/component-emitter/index.js.Emitter.emit @ index.js:133
./node_modules/socket.io-client/lib/manager.js.Manager.ondecoded @ manager.js:345
(anonymous) @ index.js:21
./node_modules/component-emitter/index.js.Emitter.emit @ index.js:133
./node_modules/socket.io-parser/index.js.Decoder.add @ index.js:241
./node_modules/socket.io-client/lib/manager.js.Manager.ondata @ manager.js:335
(anonymous) @ index.js:21
./node_modules/component-emitter/index.js.Emitter.emit @ index.js:133
./node_modules/engine.io-client/lib/socket.js.Socket.onPacket @ socket.js:456
(anonymous) @ socket.js:273
./node_modules/component-emitter/index.js.Emitter.emit @ index.js:133
./node_modules/engine.io-client/lib/transport.js.Transport.onPacket @ transport.js:145
./node_modules/engine.io-client/lib/transport.js.Transport.onData @ transport.js:137
ws.onmessage @ websocket.js:147

[ztl8702]

I am getting a similar issue as @thiagodelgado111 when running js-ipfs in custom Node.js code.

Trace

/home/../orbit-play/node_modules/pull-pair/index.js:11
      throw new Error('already piped')
      ^

Error: already piped
    at sink (/home/../orbit-play/node_modules/pull-pair/index.js:11:13)
    at consume (/home/../orbit-play/node_modules/pull-defer/sink.js:7:17)
    at consume (/home/../orbit-play/node_modules/pull-defer/sink.js:7:17)
    at Connection.consume (/home/../orbit-play/node_modules/pull-defer/sink.js:7:17)
    at pull (/home/../orbit-play/node_modules/pull-stream/pull.js:43:9)
    at Dialer.handle (/home/../orbit-play/node_modules/multistream-select/src/dialer/index.js:47:5)
    at protocolHandshake (/home/../orbit-play/node_modules/libp2p-switch/src/dial.js:208:10)
    at attemptMuxerUpgrade (/home/../orbit-play/node_modules/libp2p-switch/src/dial.js:64:11)
    at ms.select (/home/../orbit-play/node_modules/libp2p-switch/src/dial.js:170:15)
    at f (/home/../orbit-play/node_modules/once/once.js:25:25)

---

I am wondering: as a workaround, can we somehow restart libp2p whenever it gets an uncaught exception?

[olizilla]

WIP to fix "already piped" error in https://github.com/libp2p/js-libp2p-switch/pull/262

See also

• #1366
• https://github.com/libp2p/js-libp2p-switch/issues/235

[daviddias]

Woot, awesome work @olizilla ❤️ Closing this one. @mitra42 let us know if you see that error again :)