node.jsapachenginx-reverse-proxyfastifyfastify-multipart

When FastifyJS send a response to client, Apache doesn't send it to him


I currently host an API made with FastifyJS and going through a reverse proxy made with Apache. Everything works if I directly make my requests to my node server, however, with Apache (I also tried nginx) it seems that the response isn't sent to my client. After checking Apache access logs and Fastify verbose mode logs, it looks like my proxy isn't receiving the response from FastifyJS.

Logs from FastifyJS (verbose):

{"level":30,"time":1706742990703,"pid":1358,"hostname":"debian","reqId":"req-2","req":{"method":"POST","url":"/files/create","hostname":"127.0.0.1:3500","remoteAddress":"127.0.0.1","remotePort":35272},"msg":"incoming request"}
{"level":30,"time":1706742990925,"pid":1358,"hostname":"debian","reqId":"req-2","res":{"statusCode":200},"responseTime":222.1608750000014,"msg":"request completed"}
{"level":30,"time":1706742990964,"pid":1358,"hostname":"debian","reqId":"req-3","req":{"method":"PUT","url":"/files/uploadChunk?transferkey=azezaqsdcdsq&chunk=0","hostname":"127.0.0.1:3500","remoteAddress":"127.0.0.1","remotePort":35272},"msg":"incoming request"}
Uploaded chunk (transferKey: azezaqsdcdsq, chunk: 0): chunkPos: 0
{"level":30,"time":1706742999872,"pid":1358,"hostname":"debian","reqId":"req-3","res":{"statusCode":201},"responseTime":8908.116479000004,"msg":"request completed"}
{"level":30,"time":1706742999908,"pid":1358,"hostname":"debian","reqId":"req-4","req":{"method":"PUT","url":"/files/uploadChunk?transferkey=azezaqsdcdsq&chunk=1","hostname":"127.0.0.1:3500","remoteAddress":"127.0.0.1","remotePort":36536},"msg":"incoming request"}
Uploaded chunk (transferKey: azezaqsdcdsq, chunk: 1): chunkPos: 1
{"level":30,"time":1706743001925,"pid":1358,"hostname":"debian","reqId":"req-4","res":{"statusCode":201},"responseTime":2017.0185090000014,"msg":"request completed"}

Logs from Apache access:

192.168.1.* - - [01/Feb/2024:00:16:30 +0100] "POST /files/create HTTP/1.1" 200 654 "-" "Stend CLI/1.0.1"
192.168.1.* - - [01/Feb/2024:00:16:30 +0100] "PUT /files/uploadChunk?transferkey=azezaqsdcdsq&chunk=0 HTTP/1.1" 201 163 "-" "-"
192.168.1.* - - [01/Feb/2024:00:16:39 +0100] "PUT /files/uploadChunk?transferkey=azezaqsdcdsq&chunk=1 HTTP/1.1" 408 485 "-" "-"

Note: the last request that fail with 408 shows up somes minutes after the other one that success with HTTP 201.

Logs from Apache errors (debug):

[Thu Feb 01 00:16:30.702276 2024] [authz_core:debug] [pid 1147:tid 140211841373888] mod_authz_core.c(843): [client 192.168.1.254:50962] AH01628: authorization result: granted (no directives)
[Thu Feb 01 00:16:30.702364 2024] [proxy:debug] [pid 1147:tid 140211841373888] mod_proxy.c(1511): [client 192.168.1.254:50962] AH01143: Running scheme http handler (attempt 0)
[Thu Feb 01 00:16:30.702373 2024] [proxy:debug] [pid 1147:tid 140211841373888] proxy_util.c(2568): AH00942: http: has acquired connection for (127.0.0.1:3500)
[Thu Feb 01 00:16:30.702382 2024] [proxy:debug] [pid 1147:tid 140211841373888] proxy_util.c(2626): [client 192.168.1.254:50962] AH00944: connecting http://127.0.0.1:3500/files/create to 127.
0.0.1:3500
[Thu Feb 01 00:16:30.702389 2024] [proxy:debug] [pid 1147:tid 140211841373888] proxy_util.c(2849): [client 192.168.1.254:50962] AH00947: connected /files/create to 127.0.0.1:3500
[Thu Feb 01 00:16:30.925265 2024] [proxy:debug] [pid 1147:tid 140211841373888] proxy_util.c(2584): AH00943: http: has released connection for (127.0.0.1:3500)
[Thu Feb 01 00:16:30.942604 2024] [authz_core:debug] [pid 1147:tid 140211832981184] mod_authz_core.c(843): [client 192.168.1.254:50967] AH01628: authorization result: granted (no directives)
[Thu Feb 01 00:16:30.942659 2024] [proxy:debug] [pid 1147:tid 140211832981184] mod_proxy.c(1511): [client 192.168.1.254:50967] AH01143: Running scheme http handler (attempt 0)
[Thu Feb 01 00:16:30.942667 2024] [proxy:debug] [pid 1147:tid 140211832981184] proxy_util.c(2568): AH00942: http: has acquired connection for (127.0.0.1:3500)
[Thu Feb 01 00:16:30.942676 2024] [proxy:debug] [pid 1147:tid 140211832981184] proxy_util.c(2626): [client 192.168.1.254:50967] AH00944: connecting http://127.0.0.1:3500/files/uploadChunk?tr
ansferkey=azezaqsdcdsq&chunk=0 to 127.0.0.1:3500
[Thu Feb 01 00:16:30.942686 2024] [proxy:debug] [pid 1147:tid 140211832981184] proxy_util.c(2849): [client 192.168.1.254:50967] AH00947: connected /files/uploadChunk?transferkey=azezaqsdcdsq
&chunk=0 to 127.0.0.1:3500
[Thu Feb 01 00:16:39.872914 2024] [proxy:debug] [pid 1147:tid 140211832981184] proxy_util.c(2584): AH00943: http: has released connection for (127.0.0.1:3500)
[Thu Feb 01 00:16:39.899225 2024] [authz_core:debug] [pid 1148:tid 140212025947840] mod_authz_core.c(843): [client 192.168.1.254:50973] AH01628: authorization result: granted (no directives)
[Thu Feb 01 00:16:39.899319 2024] [proxy:debug] [pid 1148:tid 140212025947840] mod_proxy.c(1511): [client 192.168.1.254:50973] AH01143: Running scheme http handler (attempt 0)
[Thu Feb 01 00:16:39.899351 2024] [proxy:debug] [pid 1148:tid 140212025947840] proxy_util.c(2568): AH00942: http: has acquired connection for (127.0.0.1:3500)
[Thu Feb 01 00:16:39.899363 2024] [proxy:debug] [pid 1148:tid 140212025947840] proxy_util.c(2626): [client 192.168.1.254:50973] AH00944: connecting http://127.0.0.1:3500/files/uploadChunk?tr
ansferkey=azezaqsdcdsq&chunk=1 to 127.0.0.1:3500
[Thu Feb 01 00:16:39.899472 2024] [proxy:debug] [pid 1148:tid 140212025947840] proxy_util.c(2849): [client 192.168.1.254:50973] AH00947: connected /files/uploadChunk?transferkey=azezaqsdcdsq
&chunk=1 to 127.0.0.1:3500
[Thu Feb 01 00:16:39.906992 2024] [proxy:debug] [pid 1148:tid 140212025947840] proxy_util.c(3321): AH02824: http: connection established with 127.0.0.1:3500 (127.0.0.1:3500)
[Thu Feb 01 00:16:39.907053 2024] [proxy:debug] [pid 1148:tid 140212025947840] proxy_util.c(3510): AH00962: http: connection complete to 127.0.0.1:3500 (127.0.0.1)
[Thu Feb 01 00:21:42.000262 2024] [proxy:error] [pid 1148:tid 140212025947840] (70007)The timeout specified has expired: [client 192.168.1.254:50973] AH02608: read request body failed to 127
.0.0.1:3500 (127.0.0.1) from 192.168.1.254 ()
[Thu Feb 01 00:21:42.000332 2024] [proxy_http:error] [pid 1148:tid 140212025947840] [client 192.168.1.254:50973] AH01097: pass request body failed to 127.0.0.1:3500 (127.0.0.1) from 192.168.
1.254 ()
[Thu Feb 01 00:21:42.000341 2024] [proxy:debug] [pid 1148:tid 140212025947840] proxy_util.c(2584): AH00943: http: has released connection for (127.0.0.1:3500)

I also tried using Nginx but the problem is kinda similar. Using Cloudflare directly results on a "branded" HTTP Bad Gateway error:

Cloudflare bad gateway

Edit: forgot to say that the issue appears when using Node to send the requests to the server using Axios and/or Superagent. I doesn't have this issue on Postman and on browser using the same Axios code (however, Axios seems to be really slow to upload file).


Solution

  • Not suite sure if I managed to fix it, but there was an issue with the code of my client that sended an invalid FormData body to the server.