fastify / fastify-reply-from

fastify plugin to forward the current http request to another server
MIT License
148 stars 76 forks source link

False response errored messages #338

Closed szegheo closed 8 months ago

szegheo commented 8 months ago

Prerequisites

Last working version

4.23.2

Stopped working in version

4.24.0

Node.js version

18

Operating system

Linux

Operating system version (i.e. 20.04, 11.3, 10)

Ubuntu 22.04.3 LTS

💥 Regression Report

In our Fastify server we forward all the API requests from the frontend to another micro-service with a global proxy handler routine. We have only one PUT endpoint, and starting from Fastify v4.24.0, every call to this PUT (204) endpoint raises a false "response errored" warning log. However, this proxied PUT request is processed fine on the target, and examining the Fastify logs it shows that everything went normal, except the last line here:

docker logs 4e2a955d0429 |grep "req-3i"
{"level":30,"time":1702909961244,"pid":1,"hostname":"4e2a955d0429","reqId":"req-3i","req":{"method":"PUT","url":"/api/foo-api/api/foo/lock/400003237","hostname":"localhost:5000","remoteAddress":"172.240.61.1","remotePort":41968},"msg":"incoming request"}
{"level":30,"time":1702909961246,"pid":1,"hostname":"4e2a955d0429","reqId":"req-3i","source":"/api/foo/lock/400003237","msg":"fetching from remote server"}
{"level":30,"time":1702909961312,"pid":1,"hostname":"4e2a955d0429","reqId":"req-3i","msg":"response received"}
{"level":30,"time":1702909961313,"pid":1,"hostname":"4e2a955d0429","reqId":"req-3i","res":{"statusCode":204},"responseTime":69.12243801355362,"msg":"request completed"}
{"level":40,"time":1702909967313,"pid":1,"hostname":"4e2a955d0429","reqId":"req-3i","err":{"type":"FastifyError","message":"HTTP request timed out","stack":"FastifyError: HTTP request timed out\n    at ClientRequest.<anonymous> (/home/app/node_modules/.pnpm/@fastify+reply-from@9.4.0/node_modules/@fastify/reply-from/lib/request.js:130:19)\n    at Object.onceWrapper (node:events:628:28)\n    at ClientRequest.emit (node:events:514:28)\n    at TLSSocket.emitRequestTimeout (node:_http_client:847:9)\n    at Object.onceWrapper (node:events:628:28)\n    at TLSSocket.emit (node:events:526:35)\n    at Socket._onTimeout (node:net:571:8)\n    at listOnTimeout (node:internal/timers:569:17)\n    at process.processTimers (node:internal/timers:512:7)","code":"FST_REPLY_FROM_HTTP_REQUEST_TIMEOUT","name":"FastifyError","statusCode":504},"msg":"response errored"}

All the other GETs and POSTs are working fine with the same preHandler logic, where we basically just decode a cookie and set an Authorization header:

request.headers['Authorization'] = `Bearer ${accessToken}`

I've spent a lot of time on this issue, but still don't know why it happens. On our side I see no reason, and it was fine with versions prior to 4.24.0 (so we've been reverted to 4.23.2). I've double checked that PUT endpoint, there's no response body and the response headers are fine (no content-length). Calling it directly from Postman also runs fine. I've tried to remove all our hooks and as much code as possible, but the warning is always there.

I'm trying to create a reproduction code (no luck as of now), but meanwhile I would kindly ask you to take a look on this. Maybe the changes made to the affected Fastify version will show you some connection. My suspect is this change. What do you think?

Thanks in advance!

Steps to Reproduce

I'm working on it... Unfortunately, my first attempts didn't triggered the issue. Please see my post below.

Expected Behavior

No "response errored" warns for PUT responses with code 204. As it was before 4.24.0.

szegheo commented 8 months ago

OK, finally I figured out, that it occurs when the client request arrives with Connection: keep-alive (default on HTTP/1.1 requests). Run the code below and wait ~3 sec:

const Fastify = require('fastify')
const fastifyHttpProxy = require('@fastify/http-proxy')

// PROXY TARGET
const fastifyProxyTarget = Fastify({
  logger: { level: 'debug' },
  disableRequestLogging: false,
}).put('/api', async (request, reply) => reply.code(204).send())

// CLIENT REQUESTS RECEIVER
const fastify = Fastify({
  logger: { level: 'debug' },
  disableRequestLogging: false,
});

fastify.register(fastifyHttpProxy, {
  upstream: 'http://localhost:3000/',
  prefix: '/proxytest',
  http2: false,
  http: {
    requestOptions: {
      timeout: 2000 //2sec
    }
  }
});

async function startTest() {
  await fastifyProxyTarget.listen({ port: 3000 });
  await fastify.listen({ port: 5000 });

  await fetch('http://localhost:5000/proxytest/api', {
    method: 'PUT',
    headers: {
      // 'Connection': 'close' // OK
      'Connection': 'keep-alive' // response errored
    }
  });
}

startTest()

The above code triggers the "response errored" warning with (current) v4.25.1, but not with 4.23.2

szegheo commented 8 months ago

Testing it further, it's now clear that it happens when the response code is 204 (method independent) and only with Node's http request (proxy options).

Eomm commented 8 months ago

Thanks for reporting!

Did you get the chance to debug it? I think the fastifyHttpProxy is waiting for the content-length IMHO, but I'm only guessing

szegheo commented 8 months ago

Thanks for reporting!

Did you get the chance to debug it? I think the fastifyHttpProxy is waiting for the content-length IMHO, but I'm only guessing

Ok, I'll try to look into it deeper, but unfortunately I'm not a Fastify expert (doing FE things mostly)

szegheo commented 8 months ago

From the side of Fastify, it seems quite clear, that this issue was brought in with this change. Currently, that new if block runs here because of the statusCode 204, and then it returns. When I skip that if block, the issue is gone. When I copy the next sendStream block into this new block, the issue is gone too.

Looking at the code of fastify-reply-from, the timeout error (that I reported) is created by handleHttp1Req, so maybe there should be some new check here to decide if the error should be forwarded or not.

The original timeout event is coming from Node's http module:

Emitted when the underlying socket times out from inactivity. This only notifies that the socket has been idle. The request must be destroyed manually.

Unfortunately, I do not have the necessary (deep) http knowledge to create a proper fix, but I hope at least these information will somehow useful. Honestly, I also wondering if the fix should be done here in reply-from or in Fastify (or both).

Thank you!