restify / node-restify

The future of Node.js REST development
http://restify.com
MIT License
10.71k stars 984 forks source link

Using return in Async handlers logs entire response object to stdout #1946

Open rorydonohue opened 1 year ago

rorydonohue commented 1 year ago

Restify Version: 11.1.0 Node.js Version: 19.7.0

Expected behaviour

We are upgrading from Restify 8.6.1 -> 11.1.0. In version 8.6.1, we were able to use a return before res.send in an async handler to end the request there and then:

server.get("/endpoint", async function get(req, res) {
  return res.send({ }); 
});

This is especially useful in complex handlers to protect against accidental code running after a sent response.

However doing this in version 11.1.0 adds a very large console log to stdout with what looks like a response object.

I understand that calling next is not allowed when using async functions so the return value is being passed onto the handler chain, however I would expect using a return here would not perform this console log. The log does not happen when using a normal function handler, so I would expect an async handler to behave the same.

End the request and not perform a console log.

Actual behaviour

Logs a response object to stdout.

Screenshot 2023-02-28 at 18 54 34

This message JSON ends with: "msg": "Discarded returned value from async handler"

Logging this amount of data for each request would obviously add considerable load onto our logging systems.

Repro case

import * as restify from "restify";
const api = restify.createServer({
  name: "API",
});

// ASYNC function results in a console log
api.get("/endpoint", async function get(req, res) {
  return res.send({ });
});

// Normal function returns WITHOUT a console log as expected
api.get("/endpoint2", function get(req, res, next) {
  return res.send({ });
});

// If not in test mode, start the server
api.listen(8080, function () {
  console.log("ready on %s", api.url);
});

Cause

https://github.com/restify/node-restify/blob/39c1f6ed124f1b90ab9a00364b261e5343456d89/lib/chain.js#L188-L198

Are you willing and able to fix this?

Willing to help with guidance, but this probably needs someone who intimately understands the restify handler chain.

dreaganluna commented 1 year ago

Is there any news on this issue? I'm considering downgrading again because of this.. :/ I think this dump was introduced in v9.

jdb5523 commented 1 year ago

I'm experiencing the same issue. Two possible workarounds are:

  1. Explicitly setting req.log = null in the handler. This is obviously not ideal if you actually want to use the logging plugin for the request.
  2. Moving the empty return onto a separate line after the res.send() call. Obviously not ideal either if you actually want to pass a value into the next handler in the chain.
cgatian commented 9 months ago

Is it a reasonable change to test if value is an instanceOf ServerResponse? If it is, don't include it in the log. Or perhaps don't log value?

rorydonohue commented 5 months ago

I'm experiencing the same issue. Two possible workarounds are:

  1. Explicitly setting req.log = null in the handler. This is obviously not ideal if you actually want to use the logging plugin for the request.
  2. Moving the empty return onto a separate line after the res.send() call. Obviously not ideal either if you actually want to pass a value into the next handler in the chain.

On #1 here, I ran into an issue where the in-build Restify throttle uses req.log.trace and throws an error, obviously not ideal to be removing something that is expected to be there. I've restored to #2 which is not ideal.