HTTP request is sent twice in Node app

[b1nks]

I'm using unit:node Docker image and I encountered double sending of http requests.

Looks like a bug, but I'm not qualified enough to dive deeper into the problem.

The situation can be repeated on the simplest configuration:

• Use a pure image unit:node, basic Unit configuration and copy there a .js file with sending an http request from anywhere

const http = require("unit-http");

const options = {
  hostname: "<your hostname>",
  port: 80,
  path: "/<your path>",
  method: "GET",
};

const req = http.request(options, (res) => {
  let responseData = "";

  res.on("data", (chunk) => {
    responseData += chunk;
  });

  res.on("end", () => {
    console.log("Response:", responseData);
  });
});

req.on("error", (error) => {
  console.error("Error:", error);
});

req.end();

const server = http.createServer();

server.listen();

• When we launch the container we will see one line in the logs, but when we look at the logs of the target server we will actually see two requests

[hongzhidao]

Hi @b1nks,

When we launch the container we will see one line in the logs, but when we look at the logs of the target server we will actually see two requests

What do the two request logs in the target server look like?

[b1nks]

I initially encountered this problem when sending a message via the Telegram API. I received two messages instead of one sent.

But this situation is easily repeated, for example, by sending a request to webhook.site. The screenshots show that the code I provided above recorded the success message once, but on the site we see two incoming requests.

[hongzhidao]

I tried your code to send to the local server running nginx.
Here's my configuration.

# conf.json
{
   "listeners": {
      "*:8080": {
          "pass": "applications/node"
      }
  },
  "applications": {
      "node": {
          "type": "external",
          "executable": "/usr/bin/node",
          "arguments": ["/tmp/app.js"]
      }
  }
}

# app.js
const options = {
  hostname: "test.com",
  port: 8082,
  path: "/index.html",
  method: "GET",
};

But I only see one access log in nginx. Could you try it with a local server like nginx?
Btw, I didn't use Docker.

[b1nks]

I started another container with nginx:latest and sent a request to it. The result is exactly the same.

Later I will try to do the same test without using Docker, however, we cannot ignore the fact that the Docker image does not work correctly, because this behavior occurs even with the most basic configuration

[b1nks]

I ran this config without Docker and everything is fine, no double request sending occurs

[b1nks]

Hello. Is there any news on this issue?

[javorszky]

Hello. Is there any news on this issue?

Hi! Apologies, we've been busy releasing version 1.33 and some associated tasks. I am going to look at this this week and should have an update for you soon.

[javorszky]

Additional details for others to replicate this that was needed to look into this:

1. go to https://webhook.site. That will give you a unique URL that you can use to plug into the options object in the example code. Mine looks like this:

const options = {
  hostname: "webhook.site",
  port: 80,
  path: "/21d0ae48-4210-4c87-b4a5-a81649357386",
  method: "GET",
};

2. in the code the http.createServer() call does not pass an option and handler function. It defaults to an empty object for the options (which is fine as we're not propagating the options to node's http constructor), but more importantly the request handler function is undefined, which means even though the node app runs and the server listens, when an incoming request is received there's nothing to do anything with it, which means the request will time out. A fix for that is below. That way when we send a request to Unit, we get a response.

const server = http.createServer({}, (req, res) => {
  res.writeHead(200, {"Content-Type": "text/plain"});
  res.end("Hello, Node.js on Unit!")
});

3. The way the example code is written will make the app immediately send a request to the host+/path that's in the options object once per boot up without making a request to Unit, but subsequent requests to Unit, and therefore the app, will mean there will be no additional requests sent to webhook.site.

@b1nks do you have a more functional code you can paste here where you can reproduce the issue that when you send 1 request to Unit, it results in 2 requests to webhook.site?

[b1nks]

I initially got this problem when I added a handler for a Mongo data change event to my app.
I experimented with the code and configuration and found that the error could be reproduced with the most basic configuration, which I provided in the first message.

My app is a fairly simple configuration with express.js and of course I use a more complete initialization from the documentation.
I have several handler functions and when they work I do not observe double sending of the request.
Below is a more accurate example of my configuration

Dockerfile

FROM unit:node

COPY src/ /www/
COPY unit-config.json /docker-entrypoint.d/

RUN cd /www/ && npm install && npm link unit-http

unit-config.json

{
  "listeners": {
    "*:8080": {
      "pass": "routes"
    }
  },

  "routes": [
    {
      "action": {
        "pass": "applications/express"
      }
    }
  ],

  "applications": {
    "express": {
      "type": "external",
      "working_directory": "/www/",
      "executable": "/usr/bin/env",

      "arguments": [
        "node",
        "--loader",
        "unit-http/loader.mjs",
        "--require",
        "unit-http/loader",
        "index.js"
      ]
    }
  }
}

index.js

import http from "http";
import mongoose from "mongoose";
import express from "express";
import { User, Group } from "./models.js";
import { handlers } from "./handlers.js";

await mongoose.connect(...)

// Here is the problem
User.watch(
  [
    {
      $match: {
        operationType: "update",
        "updateDescription.updatedFields.active": { $exists: true },
      },
    },
  ],
  { fullDocument: "updateLookup" }
).on("change", async (data) => {
  console.log(data);

  await handlers.handleChangeActive(data.fullDocument);
});

const app = express();

app.get(...);

const server = http.createServer(app);

server.listen(PORT, HOST, () => {...});

handleChangeActive can have any implementation, including sending a request to webhook.site. This is always a double send.

[javorszky]

Thank you for this. To make sure I understand your flow correctly:

1. given the above code you send 1 (one) request to the Unit application
2. that request results in the User model being updated
3. that update kicks off a call to handleChangeActive
4. that is always a double send

As I don't have the actual application (I'm missing the models and handlers.js as well as the package.json) and I don't know enough about nodejs and mongoose here to fill in the blanks, and even then it would be different, could you double check something for me?

I'm curious, how many times is User.watch.on("change") getting called?

The question I'm trying to find out is whether the double call happens because the model has a double update, but each update correctly sends a single call to handleActiveChange, or it's an issue in Unit itself.

If you run this application on your host machine outside of Unit, does the issue get resolved?

[b1nks]

Thanks for this clarifying question, it helped me to discover some facts that I hadn't noticed before.
Apparently User.watch.on("change") is indeed called twice, although only one entry is always written to the container logs.
I discovered this by adding a call to write to the database in handleChangeActive, which was not there before.
The write happens twice.

However, I don't think that mongoose itself can be involved in this behavior, because I tried sending the request in other ways without the participation of any third-party libraries, including using a simple implementation of event emitter.
And I always got the same effect.

Unfortunately, I can't run my application on the host machine, but I will try to make a similar configuration and make sure that it works correctly.

[javorszky]

Can you link me to the event emitter example, or paste in a fully working code that I can copy paste as-is? It would help a lot if you had a minimum reproduction example we can look at so we can remove as much of the possibility of a user application doing unexpected things and hone in on Unit sending a double request.

[b1nks]

Sorry for the long absence.

Dockerfile

FROM unit:node

COPY index.js /www/
COPY unit-config.json /docker-entrypoint.d/

RUN cd /www/ && npm link unit-http

index.js

const http = require("http");
const EventEmitter = require("events");

const myEmitter = new EventEmitter();

myEmitter.on("event", () => {
  const options = {
    hostname: "webhook.site",
    port: 80,
    path: "/dec14dea-3b30-4276-9e36-9974b8cf7fe5",
    method: "GET",
  };

  const req = http.request(options, (res) => {
    console.log(res.statusCode);
  });

  req.end();
});

myEmitter.emit("event");

http.createServer((req, res) => {
  res.writeHead(200, { "Content-Type": "text/plain" });
  res.end("Hello, Node.js on Unit!");
});

unit-config.json

{
  "listeners": {
    "*:8080": {
      "pass": "applications/node"
    }
  },

  "applications": {
    "node": {
      "type": "external",
      "working_directory": "/www/",
      "executable": "/usr/bin/env",

      "arguments": [
        "node",
        "--loader",
        "unit-http/loader.mjs",
        "--require",
        "unit-http/loader",
        "index.js"
      ]
    }
  }
}

[javorszky]

Hey @b1nks,

Thank you for this. I copy-pasted this code to check what's happening, created my own webhook.site.

Here's what's happening:

• When you first start the docker service with the given configuration, Unit will check whether it has a statefile, and if it doesn't, it creates one, shuts down, and starts again. The second time it makes use of the statefile
• every time the node app starts, the code dispatches an event: myEmitter.emit on line 21 dispatches it, the listener on line 6 picks it up, within that you create a request on line 14, and send it on line 18. That request gets sent once to webhook.site
• that event is not hooked up to the http server, which means once Unit is up and running, I can send a request to Unit as many times as I want, the only effect that's going to have is a response of 200 with "Hello, Node.js on Unit!" message. The event will not be emitted, and the webhook.site will not be called. For the purposes of the double request to webook.site, the http server isn't needed
• If you restarted the application itself, that would also send one request to webhook.site

My assumption is that Unit's start-stop-start in Docker is tripping you up and that's what you're seeing as a weird double request. That is by design. We're working on making that more seamless as we've bumped into issues with the start-stop-start from others as well.

Let me know if you're experiencing something different. If this is what's the original issue, then Unit is behaving as designed. I do admit that the start-stop-start isn't spelled out explicitly in the documentation: https://unit.nginx.org/installation/#initial-configuration