node-restify icon indicating copy to clipboard operation
node-restify copied to clipboard

Using return in Async handlers logs entire response object to stdout

Open rorydonohue opened this issue 1 year ago • 4 comments

  • [x] Used appropriate template for the issue type
  • [x] Searched both open and closed issues for duplicates of this issue
  • [x] Title adequately and concisely reflects the feature or the bug

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.

rorydonohue avatar Feb 28 '23 19:02 rorydonohue

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

dreaganluna avatar Jul 25 '23 13:07 dreaganluna

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.

jdb5523 avatar Aug 15 '23 20:08 jdb5523

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?

cgatian avatar Dec 11 '23 22:12 cgatian

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.

rorydonohue avatar Apr 11 '24 14:04 rorydonohue