[ConradHughes]

The work here was pretty much all done by Claude Code (Fable 5.1), with prodding by me — I was seeing lots of failures-that-weren't-really-failures, and the root cause appears to be this tiny timing discrepancy, as documented below.

I've reproduced the bug and the before/after results myself on the stated versions and will answer follow-ups as best I can.

---

Environment

serverless-http 4.0.0 and master at ab1c416; Node v24.21.0 on Linux; the AWS provider with an API Gateway v1 event, though the provider is not involved. Seen in production on Lambda with Express 5.2.1 and pino-http 11.0.0, reproduced below with no framework and no logger.

Reproduction

The same handler on a real http.Server and under serverless-http, listening for finish and close on the response:

'use strict';
const http = require('http');
const serverless = require('serverless-http');

const app = (req, res) => {
  res.on('finish', () => console.log(`  finish: writableEnded=${res.writableEnded} writableFinished=${res.writableFinished}`));
  res.on('close', () => console.log(`  close:  writableEnded=${res.writableEnded} writableFinished=${res.writableFinished}`));
  res.writeHead(200, { 'content-type': 'text/plain' });
  res.end('ok');
};

(async () => {
  console.log('real http.Server:');
  const server = http.createServer(app);
  await new Promise((r) => server.listen(0, '127.0.0.1', r));
  await new Promise((r) => http.get({ port: server.address().port, host: '127.0.0.1' }, (res) => res.resume().on('end', r)));
  server.close();

  console.log('serverless-http:');
  const handler = serverless(app);
  const out = await handler({ httpMethod: 'GET', path: '/', headers: { host: 'x' }, body: null, isBase64Encoded: false, requestContext: {} }, {});
  console.log(`  handler returned ${out.statusCode} ${JSON.stringify(out.body)}`);
})();

Expected

finish sees writableEnded === true, as it does on a real server, and as Node's docs describe (writableEnded is "true after response.end() has been called").

Actual

real http.Server:
  finish: writableEnded=true writableFinished=true
  close:  writableEnded=true writableFinished=true
serverless-http:
  finish: writableEnded=false writableFinished=true
  close:  writableEnded=true writableFinished=true
  handler returned 200 "ok"

Under serverless-http, finish fires with writableEnded still false. writableFinished is already true at that point, which is backwards: Node sets writableFinished immediately before emitting finish, and writableEnded is meant to have been true since end() was called.

The consequence that found it: pino-http decides between its "request completed" and "request aborted" messages by reading res.writableEnded at the first of finish/close to fire (defaultSuccessfulRequestMessageProvider), so under serverless-http it labels successful responses "request aborted". Across a week of one production Lambda that was 2972 of 3269 request lines, every 304 and 404 and most 200s. The unanswered question at the end of #280 ("why pino logs request aborted instead of completed?") is this bug; #286 fixed the double logging that issue was opened for and does not touch this.

Mechanism

Node's OutgoingMessage.prototype.end() hands the final write to the socket with the finish callback attached, and only then sets this.finished, which is what the writableEnded getter returns (lib/_http_outgoing.js at v24.21.0: this._send('', 'latin1', finishCallback) at line 1207, this.finished = true at line 1221, outmsg.emit('finish') in onFinish at line 1140, the getter at line 886). That ordering is safe on a real socket because socket.write() never invokes its callback synchronously. The stub socket in lib/response.js does:

        if (typeof cb === 'function') {
          cb();
        }

so onFinish runs, and finish is emitted, from inside end() before line 1221 has executed. Anything that reads writableEnded on finish sees the pre-end() value.

Fix

Deferring that callback one tick is the obvious half, but on its own it is not enough. With only process.nextTick(cb) in response.js, the flag is right but the events move: lib/finish.js resolves immediately when item.finished is already set, which end() now does before finish has been emitted, so close is emitted and the handler returns before finish fires:

serverless-http (nextTick only):
  close:  writableEnded=true writableFinished=false
  handler returned 200 "ok"
  finish: writableEnded=true writableFinished=true

On Lambda a finish listener that runs after the handler has returned may not run at all before the environment is frozen, so that would be a regression for anyone logging on finish (which #197 recommended).

Making finish() wait for writableFinished as well keeps the order intact, so that's what I include here, along with a test that fails before the patch and passes afterwards.

Results at ab1c416: unpatched, 115 passing and the new test failing with expected [ [ 'finish', false ], … ] to deeply equal [ [ 'finish', true ], … ]; patched, 116 passing. The reproduction above then prints finish: writableEnded=true writableFinished=true and then close, before handler returned, and pino-http logs "request completed". item.writableFinished !== false rather than === true keeps the request side (IncomingMessage, which has no writableFinished) on the existing complete path.

Whether the wait in finish.js should instead key on writableFinished alone for responses, or whether the complete/finished short-circuit is relied on by a framework that ends synchronously without ever emitting finish, is I guess another question; this patch is the smallest change we could come up with that passes the existing suite.

[dougmoscrop]

Thanks, makes sense to me. While this a clear fix, I'm inclined to release this as semver-major in case of any accidental dependency on the broken behaviour.