POST -> Premature close?

[lmeyerov]

Describe the bug

• Node.js version: 14.14
• OS & version: Ubuntu 18 LTS

We aren't really sure where to start on this one, including with a tighter reproduction, so any pointers on how to proceed / what it might be would be appreciated.

We suspect it is somehow in how we're connecting got <> fastify over a stream, and while we finally got it reproducible, currently on a large test + deep in our app.

Some clues:

• This seems to appear for bigger buffers, vs smaller, but unclear. Normally I wouldn't file this coarse of an issue, but it's a weird one for us to dig into.

• On the fastify side, the closest related we saw is Sporadic ERR_STREAM_PREMATURE_CLOSE fastify/fastify-static#116

• We've had to iterate with eos handling this year as that has been changing in various engine/libs, though not in the last ~2 months

Actual behavior

See trace on below got request, including auto-retry also failing (deterministic re-fail is promising..):

        // Call got in promise mode so it automatically retries these requests
        // The GPU worker socket is volatile, likes to throw `EAGAIN` errors
        // when you request things of it while simulating.
        // Use timeouts as canaries
        const fullNodeCPUTable = readFullNodeCPUTable(sessionId, {timeout: 4042, retry: 10}).then((o) => {
            return o.body;
        });
        let preshapedNodes = Table.from(fullNodeCPUTable);

=>

const gotTable = ({ id, name, tableKind = '', headers = {}, ...rest }) => (got.extend({
    method: 'POST',
    responseType: 'buffer',
    searchParams: { id },
    headers: {
        'Accept': 'application/octet-stream',
        'Content-Type':'application/x-www-form-urlencoded',
        ...headers
    },
    ...rest
})(`${basePath}/${Path.join(...[name, tableKind].filter(Boolean))}`))

And on the fastify service side, we're going through https://github.com/apache/arrow/blob/fbb781bcdd15d54c52c71881c5c53d0c68069be6/js/src/ipc/reader.ts#L521 :

=>

const pump = require('stream').pipeline;
const { AsyncIterable } = require('ix');
const { RecordBatchStreamWriter } = require('apache-arrow');
const eos = require('util').promisify(require('stream').finished);

                compress = true;
                layoutOptions && graph.setLayoutOptions(layoutOptions).commit();
                readers = AsyncIterable.as(readEverything(graph, { filtered }));

            const stream = pump(
                readers.concatAll().toNodeStream({ objectMode: true }),
                RecordBatchStreamWriter.throughNode({ autoDestroy: false }),
                (error) => error && req.log.error(error)
            );

                reply.type('application/octet-stream').compress(stream);

            await eos(stream);

=> Session logs:

streamgl-viz_1         | 2020-12-16T01:19:04.737456537Z {"level":20,"time":1608081544737,"pid":37,"hostname":"c8902bb4fd5f","filename":"/opt/graphistry/apps/lib/instrumentation/got.js","msg":"making got request: POST http://nginx/streamgl/read/edge?id=5a8c492f27f14ce78643763697bf546d"}
streamgl-gpu_1         | 2020-12-16T01:19:04.756894359Z {"level":20,"time":1608081544755,"pid":45,"hostname":"eb60848f7d23","filename":"/opt/graphistry/apps/streamgl/gpu-worker/services/read.js","msg":"@worker /read handler"}
streamgl-gpu_1         | 2020-12-16T01:19:04.777813111Z {"level":20,"time":1608081544776,"pid":45,"hostname":"eb60848f7d23","filename":"/opt/graphistry/apps/streamgl/gpu-worker/services/read.js","msg":"@worker /read handler"}
streamgl-gpu_1         | 2020-12-16T01:19:04.876936627Z {"level":50,"time":1608081543975,"pid":45,"hostname":"eb60848f7d23","filename":"/opt/graphistry/apps/streamgl/gpu-worker/index.js","reqId":5,"payload":{"type":"NodeError","message":"Premature close","stack":"Error: Premature close\n    at Duplexify.onclose (/opt/graphistry/node_modules/fastify/node_modules/readable-stream/lib/internal/streams/end-of-stream.js:62:73)\n    at Duplexify.emit (events.js:327:22)\n    at Duplexify.EventEmitter.emit (domain.js:486:12)\n    at Duplexify._destroy (/opt/graphistry/node_modules/duplexify/index.js:199:8)\n    at /opt/graphistry/node_modules/duplexify/index.js:182:10\n    at processTicksAndRejections (internal/process/task_queues.js:75:11)","name":"Error","code":"ERR_STREAM_PREMATURE_CLOSE"}}
streamgl-gpu_1         | 2020-12-16T01:19:04.877394780Z {"level":50,"time":1608081543976,"pid":45,"hostname":"eb60848f7d23","filename":"/opt/graphistry/apps/streamgl/gpu-worker/index.js","reqId":5,"payload":{"id":5,"err":{"type":"Error","message":"Something went wrong","stack":"Error: Something went wrong\n    at Object.<anonymous> (/opt/graphistry/node_modules/fastify-sensible/index.js:49:20)\n    at handleError (/opt/graphistry/node_modules/fastify/lib/reply.js:525:18)\n    at onErrorHook (/opt/graphistry/node_modules/fastify/lib/reply.js:496:5)\n    at Duplexify.<anonymous> (/opt/graphistry/node_modules/fastify/lib/reply.js:444:9)\n    at Duplexify.<anonymous> (/opt/graphistry/node_modules/fastify/node_modules/readable-stream/lib/internal/streams/end-of-stream.js:17:14)\n    at Duplexify.onclose (/opt/graphistry/node_modules/fastify/node_modules/readable-stream/lib/internal/streams/end-of-stream.js:63:23)\n    at Duplexify.emit (events.js:327:22)\n    at Duplexify.EventEmitter.emit (domain.js:486:12)\n    at Duplexify._destroy (/opt/graphistry/node_modules/duplexify/index.js:199:8)\n    at /opt/graphistry/node_modules/duplexify/index.js:182:10\n    at processTicksAndRejections (internal/process/task_queues.js:75:11)"},"req":{"method":"POST","url":"/read/edge?id=5a8c492f27f14ce78643763697bf546d","headers":{"x-forwarded-host":"streamgl-gpu","x-forwarded-proto":"http","x-forwarded-port":"80","x-forwarded-for":"::ffff:172.21.0.15","accept-encoding":"gzip, deflate, br","content-type":"application/x-www-form-urlencoded","accept":"application/octet-stream","user-agent":"@graphistry/viz::@streamgl/gpu-worker","content-length":"55","host":"streamgl-gpu","connection":"close"}},"res":{"statusCode":500,"headers":{"content-security-policy":"default-src 'self';base-uri 'self';block-all-mixed-content;font-src 'self' https: data:;frame-ancestors 'self';img-src 'self' data:;object-src 'none';script-src 'self';script-src-attr 'none';style-src 'self' https: 'unsafe-inline';upgrade-insecure-requests","x-dns-prefetch-control":"off","expect-ct":"max-age=0","x-frame-options":"SAMEORIGIN","strict-transport-security":"max-age=15552000; includeSubDomains","x-download-options":"noopen","x-content-type-options":"nosniff","x-permitted-cross-domain-policies":"none","referrer-policy":"no-referrer","x-xss-protection":"0","vary":["Origin","accept-encoding"],"access-control-allow-origin":"","content-type":"application/octet-stream","content-encoding":"br","x-response-time":"24.67"}}},"msg":"Uncaught error in fastify route"}
streamgl-viz_1         | 2020-12-16T01:19:06.045835231Z {"level":20,"time":1608081546045,"pid":37,"hostname":"c8902bb4fd5f","filename":"/opt/graphistry/apps/lib/instrumentation/got.js","msg":"got response 200 :: undefined from http://nginx/streamgl/read/node?id=5a8c492f27f14ce78643763697bf546d"}
streamgl-gpu_1         | 2020-12-16T01:19:08.768667002Z {"level":50,"time":1608081548767,"pid":45,"hostname":"eb60848f7d23","filename":"/opt/graphistry/apps/streamgl/gpu-worker/graph.js","payload":{"err":{"type":"NodeError","message":"Premature close","stack":"Error [ERR_STREAM_PREMATURE_CLOSE]: Premature close\n    at RecordBatchWriterDuplex.onclose (internal/streams/end-of-stream.js:117:38)\n    at RecordBatchWriterDuplex.emit (events.js:327:22)\n    at RecordBatchWriterDuplex.EventEmitter.emit (domain.js:486:12)\n    at emitCloseNT (internal/streams/destroy.js:87:10)\n    at processTicksAndRejections (internal/process/task_queues.js:79:21)","code":"ERR_STREAM_PREMATURE_CLOSE"},"id":"5a8c492f27f14ce78643763697bf546d"},"msg":"graph transaction exn"}
streamgl-viz_1         | 2020-12-16T01:19:09.815851381Z {"level":20,"time":1608081549815,"pid":37,"hostname":"c8902bb4fd5f","filename":"/opt/graphistry/apps/lib/instrumentation/got.js","payload":{},"msg":"retry"}
streamgl-viz_1         | 2020-12-16T01:19:09.816972435Z {"level":20,"time":1608081549816,"pid":37,"hostname":"c8902bb4fd5f","filename":"/opt/graphistry/apps/lib/instrumentation/got.js","msg":"making got request: POST http://nginx/streamgl/read/edge?id=5a8c492f27f14ce78643763697bf546d"}
streamgl-gpu_1         | 2020-12-16T01:19:09.829828453Z {"level":20,"time":1608081549828,"pid":45,"hostname":"eb60848f7d23","filename":"/opt/graphistry/apps/streamgl/gpu-worker/services/read.js","msg":"@worker /read handler"}
streamgl-gpu_1         | 2020-12-16T01:19:10.137158606Z {"level":50,"time":1608081548757,"pid":45,"hostname":"eb60848f7d23","filename":"/opt/graphistry/apps/streamgl/gpu-worker/index.js","reqId":7,"payload":{"type":"NodeError","message":"Premature close","stack":"Error: Premature close\n    at Duplexify.onclose (/opt/graphistry/node_modules/fastify/node_modules/readable-stream/lib/internal/streams/end-of-stream.js:62:73)\n    at Duplexify.emit (events.js:327:22)\n    at Duplexify.EventEmitter.emit (domain.js:486:12)\n    at Duplexify._destroy (/opt/graphistry/node_modules/duplexify/index.js:199:8)\n    at /opt/graphistry/node_modules/duplexify/index.js:182:10\n    at processTicksAndRejections (internal/process/task_queues.js:75:11)","name":"Error","code":"ERR_STREAM_PREMATURE_CLOSE"}}

Checklist

• [x ] I have read the documentation.
• I have tried my code with the latest version of Node.js and Got.

[szmarczak]

=> Session logs:

Can you please provide the actual stack trace and not raw logs from your application?

[szmarczak]

Can you please use native Node.js HTTP server instead of fastify? Your example is strictly tied to duplexify, readable-stream and fastify.

Unless you can provide an actual reproducible code, there is nothing we can help with.

[lmeyerov]

Thanks -- will do on both accounts

[lmeyerov]

Slowly getting there. An update on the interplay @ fastify/fastify#2739 . There seems to be something about eos stream <> compression that got times out on and fastify reports back. Still whittling down to a repro.

[szmarczak]

Heads up! Have you figured out what part in your code is responsible for the fail?

[lmeyerov]

I think we're good to close. We got it sorted to a few things from upgrades to our web networking stack. May be of interest, e.g., docs:

• NodeJS 14/15 duplex streams regressed @ stream: regression in v14, this.push(null) in Transform doesn't emit end nodejs/node#35926 , and recently fixed by stream: fix regression on duplex end nodejs/node#35941 . We were using for our custom compressor, + some regular stream logic . Not seeing duplex errors after upgrading again.

• Some reason fastify-compress is picking br over gzip despite serverside prioritization, and default fastify-compress br is level 9 , which is incredibly slow. This in turn triggered timeout/retries by got, which kept failing, and got us further off the beaten path. Worked around by using Allow tuning of Brotli compression level fastify/fastify-compress#106 / Support passing zlibOptions and brotliOptions fastify/fastify-compress#113 . TBD what is going on with br being picked over gzip, which we had properly tuned + preferred, while br wasn't. There may be a bug around why br is getting picked wrt Chrome's accept encodings.

• We switched to using streams as got body args after seeing the multiple issues/discussions around get http response when using stream API to upload file #1514 :

                const writer = new RecordBatchStreamWriter({autodestroy: true});
                const writerStream = writer._getNodeStream();
                const responseFut = ourGotWrapper(sessionId, {retry: 0, timeout: 5455, body: writerStream});
                writer.writeAll(table);
                const response = await responseFut;

We'll be watching activity over the next month. Two things still bug us:

• The mismatching finish acks might not be explained by get http response when using stream API to upload file #1514 , so we'll be passively watching for that .

• We want to figure out what's going on w/ br being picked over gzip, and we'll probably be more proactive here as it's a useful perf knob for us