Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Open
3 tasks done
rorydonohue opened this issue Feb 28, 2023 · 4 comments
Open
3 tasks done

Comments

@rorydonohue
Copy link

  • Used appropriate template for the issue type
  • Searched both open and closed issues for duplicates of this issue
  • 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

node-restify/lib/chain.js

Lines 188 to 198 in 39c1f6e

function resolve(value) {
if (value && req.log) {
// logs resolved value
req.log.warn(
{ value },
'Discarded returned value from async handler'
);
}
return next();
}

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
Copy link

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

@jdb5523
Copy link

jdb5523 commented Aug 15, 2023

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
Copy link

cgatian commented Dec 11, 2023

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
Copy link
Author

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.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

4 participants