Why is res.send being called twice?

Question

I'm working on creating a middleware for an express router that will execute some code for every request and response. Intercepting a request is easy and there are plenty of examples, but I have not found anything for an elegant approach to intercepting a response. After some research, the best I have come up with is to replace the send function of the response object, shown in the following snippet:

const express = require('express');
const app = express();
var router = express.Router();
var port = process.env.PORT || 3000;

router.get('/test', function(req, res) {
    res.send({
        message: "testing"
    });
});

app.use(function(req, res, next){
    console.log("INTERCEPT-REQUEST");
    const orig_send = res.send;
    res.send = function(arg) {
        console.log("INTERCEPT-RESPONSE");
        orig_send.call(res, arg);
    };
    next();
});

app.use("/api", router);
app.listen(process.env.PORT || 3000) && console.log("Running");

There's a problem with this approach: for some reason "INTERCEPT-RESPONSE" is printed in the console twice, meaning res.send is being called twice...

I can set a flag on res.locals the first time it's called to avoid processing the response twice, but I am wondering why res.send is being called twice?

Answer 1

To solve this issue use res.json()

Because the json(...) function convert JSON object to stringify and thus res.send or res.json function does not have to be called again

https://github.com/expressjs/express/blob/master/lib/response.js#L250-L271

Answer 2

Better example

Try this code to see what are the arguments passed to res.send:

const express = require('express');
const app = express();
var router = express.Router();
var port = process.env.PORT || 3000;

router.get('/test', function(req, res) {
    console.log('ACTUAL RESPONSE');
    res.send({
        message: "testing"
    });
});

app.use(function(req, res, next){
    console.log("INTERCEPT-REQUEST");
    const orig_send = res.send;
    res.send = function(arg) {
        console.log("INTERCEPT-RESPONSE", JSON.stringify(arg));
        orig_send.call(res, arg);
    };
    next();
});

app.use("/api", router);
app.listen(process.env.PORT || 3000, function () {
    console.log("Running");
});

(I also changed the printing of "Running" to print it when the server is actually listening - your code && was printed before the server was listening - but that's not that important here).

Now after running:

curl http://localhost:3000/api/test

the output on the server console is:

Running
INTERCEPT-REQUEST
ACTUAL RESPONSE
INTERCEPT-RESPONSE {"0":{"message":"testing"}}
INTERCEPT-RESPONSE {"0":"{\"message\":\"testing\"}"}

What happens

As you can see your handler is actually called once by your code, with an object as the first (and only) argument. But then it is called once again with an object serialized to JSON. This is how res.send internally works - see below for details. Since you put your intercepting function on the actual response object then I guess it is calling itself with JSON argument and it doesn't even know that it calls your function in the meantime.

How to avoid it

Try it with the object serialized to JSON by yourself:

const express = require('express');
const app = express();
var router = express.Router();
var port = process.env.PORT || 3000;

router.get('/test', function(req, res) {
    console.log('ACTUAL RESPONSE');
    res.send(JSON.stringify({
        message: "testing"
    }));
});

app.use(function(req, res, next){
    console.log("INTERCEPT-REQUEST");
    const orig_send = res.send;
    res.send = function(arg) {
        console.log("INTERCEPT-RESPONSE", JSON.stringify(arg));
        orig_send.call(res, arg);
    };
    next();
});

app.use("/api", router);
app.listen(process.env.PORT || 3000, function () {
    console.log("Running");
});

Now it prints:

Running
INTERCEPT-REQUEST
ACTUAL RESPONSE
INTERCEPT-RESPONSE {"0":"{\"message\":\"testing\"}"}

Calling the res.send only once.

Explanation

Now, this is the code that handles object arguments to res.json:

  if (chunk === null) {
    chunk = '';
  } else if (Buffer.isBuffer(chunk)) {
    if (!this.get('Content-Type')) {
      this.type('bin');
    }
  } else {
    return this.json(chunk);
  }

See: https://github.com/expressjs/express/blob/master/lib/response.js#L144-L154

You get the else branch and it calls this.json() (which is res.json() really) with your argument.

But guess what - res.json() calls res.send() in this line:

return this.send(body);

See: https://github.com/expressjs/express/blob/master/lib/response.js#L250

Which calls your intercepting function (for the second time) before running the real res.send().

So, mystery solved. :)

Answer 3

@rsp 's explanation was too good.

After making the modification Postman was taking response as HTML format,

So I found a different way to handle it.

I'm just pasting the middleware part here. Please modify it according to your use case.

import { NextFunction, Request, Response } from "express";

const logActivity = (req: Request, res: Response, next: NextFunction): void => {
    const originalSend = res.send.bind(res) as typeof res.send;
    const originalJson = res.json.bind(res) as typeof res.json;

    // Override the default send function
    res.send = function (body): Response {
        // Call the original send function and return its result
        return originalSend(body);
    };

    // Override the default json function
    res.json = function (body): Response {
        // Log the HTTP status code and response body
        console.log('HTTP Status Code:', res.statusCode);
        console.log('Response Body:', body);

        // Call the original json function and return its result
        return originalJson(body);
    };

    next();
};

export default logActivity;