NodeJs+Express Application issue (linux related)

Ghost-Order · 08-24-2021, 07:50 PM

Hello, I have a problem with a very basic ecommerce app develop with Nodejs+express that only occurs in linux, in windows this issue doesn't appear.

I have 3 post handlers that:
1. Write information to the hard drive (for example in the case of new admin user creation).
2. And then redirects the user to another endpoint.

In this case for example, the post handler for the creation of a new admin user writes to the hard drive the new user information and then redirects him to /admin/products

Code:

router.post('/signup',
  async (req, res) => {
    const {email, password, passwordConfirmation} = req.body;
    const user = await usersRepo.create({ email, password });
    req.session.userId = user.id;
    res.redirect('/admin/products');
  })

The post handler works just fine, it even redirects the user to the correct endpoint as you can see in this image https://i.imgur.com/Ypvzw8M.png, the problem is that the get function that handle that request (for /admin/products) is not working, is not even being called.

Code:

router.get('/admin/products',
  requireAuth,
  async (req, res) => {
    const products = await productsRepo.getAll();
    res.send(productIndexTemplate({products}))
});

However the get handler itself works just fine when I type manually the url in the browser, the issue only occurs when the get handler is invoked from a post handler (through a redirection) that writes to the hard drive. I reach to this conclusion because when the post handler doesn't write any information to the hard drive (for example the sign in post handler) the redirected endpoint loads just fine.

Now as I said this only happens in linux, when I tested on windows this whole issue doesn't appear, so I'm guessing my problem is more related to linux itself than to the application. Have you ever experienced this issue?

boughtonp · 08-25-2021, 09:07 AM

Don't give us screenshots, provide the relevant requests and responses - preferably using curl with at least -i option. (You can obtain curl commands from browser dev tools network tab, but if so it should be trimmed to the minimum needed to display the issue.)

The problem is unlikely to be with Linux - though I wouldn't rule out a bug in NodeJS that happens to be Linux-specific - and more likely to be a browser-related one.

(e.g. Wouldn't surprise me if something is returning a HTTP 307 when it should be using 303, and there's a difference in how the browsers involve are behaving.)

Ghost-Order · 08-25-2021, 08:22 PM

Quote:

Originally Posted by boughtonp

Don't give us screenshots, provide the relevant requests and responses - preferably using curl with at least -i option. (You can obtain curl commands from browser dev tools network tab, but if so it should be trimmed to the minimum needed to display the issue.)

The problem is unlikely to be with Linux - though I wouldn't rule out a bug in NodeJS that happens to be Linux-specific - and more likely to be a browser-related one.

(e.g. Wouldn't surprise me if something is returning a HTTP 307 when it should be using 303, and there's a difference in how the browsers involve are behaving.)

Sorry for the late response, the content of the GET headers are the same either when I access the endpoint(/admin/products) typing the URL manually or when I am redirected to the endpoint, the only difference is that when I access the endpoint manually I get both the response and request headers, but when I access the endpoint through a redirection(from /signup) I only get the request header, there is no response header and the status code is empty.

About the POST headers of /signup, in the response one I can see the correct redirection to /admin/products and the correct status code 302.

Code:

HTTP/1.1 302 Found
Location: /admin/products
Content-Type: text/html; charset=utf-8

I have the same issue both in firefox and chrome, but in chrome at least when it occurs(which is almost always) it refreshes itself automatically resulting in the endpoint(/admin/products) loading correctly.

boughtonp · 08-26-2021, 12:43 PM

Quote:

Originally Posted by Ghost-Order

Sorry for the late response, the content of the GET headers are the same either when I access the endpoint(/admin/products) typing the URL manually or when I am redirected to the endpoint, the only difference is that when I access the endpoint manually I get both the response and request headers, but when I access the endpoint through a redirection(from /signup) I only get the request header, there is no response header and the status code is empty.

That's not how HTTP works - a response MUST start with at least a status line (made up of the version, status code, and explanation), and almost always includes headers, even if there's no response body.

If you are seeing an empty status code, you are not viewing the HTTP response.

Without seeing the actual HTTP request and response messages involved, there's not much anyone here can say.

i.e. Based on what you've said, you should be running four curl commands, a POST /signup and GET /admin/products when running on Windows and the same ones when running on Linux, and sharing the output.

If you've confirmed the HTML involved is irrelevant (i.e. contains no meta redirects, JS location.href changes, etc), then the response body can be ditched with a redirect, e.g: "curl -visSL 'http://google.com' > /dev/null" (use Git Bash and that'll work on Windows).

If the requests and responses are identical on Windows and Linux but the behaviour still differs then you need to identify what parts are different and come up with methods to rule each of them out.

Ghost-Order · 08-27-2021, 03:56 PM

Quote:

Originally Posted by boughtonp

That's not how HTTP works - a response MUST start with at least a status line (made up of the version, status code, and explanation), and almost always includes headers, even if there's no response body.

If you are seeing an empty status code, you are not viewing the HTTP response.

Without seeing the actual HTTP request and response messages involved, there's not much anyone here can say.

i.e. Based on what you've said, you should be running four curl commands, a POST /signup and GET /admin/products when running on Windows and the same ones when running on Linux, and sharing the output.

If you've confirmed the HTML involved is irrelevant (i.e. contains no meta redirects, JS location.href changes, etc), then the response body can be ditched with a redirect, e.g: "curl -visSL 'http://google.com' > /dev/null" (use Git Bash and that'll work on Windows).

If the requests and responses are identical on Windows and Linux but the behaviour still differs then you need to identify what parts are different and come up with methods to rule each of them out.

I did the tests both in Linux and Windows. As you will see, the only difference is in the last header of POST request, the one that should be the response header for /admin/products, in Windows I get it, in Linux I don't (although sometimes it works as I mentioned before but is like 1 out of 20 times and is very random).

POST request to localhost:3000/signup for Windows

Code:

curl localhost:3000/signup --data-raw "email=user1@user.com&password=pwd&passwordConfirmation=pwd" -siSvL > /dev/null
* Trying 127.0.0.1:3000...
* Connected to localhost (127.0.0.1) port 3000 (#0)
> POST /signup HTTP/1.1
> Host: localhost:3000
> User-Agent: curl/7.78.0
> Accept: */*
> Content-Length: 58
> Content-Type: application/x-www-form-urlencoded
>
* Mark bundle as not supporting multiuse
< HTTP/1.1 302 Found
< X-Powered-By: Express
< Location: /admin/products
< Vary: Accept
< Content-Type: text/plain; charset=utf-8
< Content-Length: 37
< Set-Cookie: express:sess=eyJ1c2VySWQiOiI3NmQzZjI3OCJ9; path=/; httponly
< Set-Cookie: express:sess.sig=HYP537f7J75Ifibysl24DyBXppc; path=/; httponly
< Date: Fri, 27 Aug 2021 20:12:31 GMT
< Connection: keep-alive
< Keep-Alive: timeout=5
<
* Ignoring the response-body
* Connection #0 to host localhost left intact
* Issue another request to this URL: 'http://localhost:3000/admin/products'
* Switch from POST to GET
* Found bundle for host localhost: 0x25524ff8250 [serially]
* Can not multiplex, even if we wanted to!
* Re-using existing connection! (#0) with host localhost
* Connected to localhost (127.0.0.1) port 3000 (#0)
> GET /admin/products HTTP/1.1
> Host: localhost:3000
> User-Agent: curl/7.78.0
> Accept: */*
>
* Mark bundle as not supporting multiuse
< HTTP/1.1 200 OK
< X-Powered-By: Express
< Content-Type: text/html; charset=utf-8
< Content-Length: 2339
< ETag: W/"923-MGVv1CkwYiaapOPrLeQqyI2S8XA"
< Date: Fri, 27 Aug 2021 20:12:31 GMT
< Connection: keep-alive
< Keep-Alive: timeout=5
<
* Connection #0 to host localhost left intact

POST request to localhost:3000/signup for Linux

Code:

curl localhost:3000/signup --data-raw "email=user1@user.com&password=pwd&passwordConfirmation=pwd" -siSvL > /dev/null
* Trying 127.0.0.1:3000...
* Connected to localhost (127.0.0.1) port 3000 (#0)
> POST /signup HTTP/1.1
> Host: localhost:3000
> User-Agent: curl/7.78.0
> Accept: */*
> Content-Length: 58
> Content-Type: application/x-www-form-urlencoded
> 
} [58 bytes data]
* Mark bundle as not supporting multiuse
< HTTP/1.1 302 Found
< X-Powered-By: Express
< Location: /admin/products
< Vary: Accept
< Content-Type: text/plain; charset=utf-8
< Content-Length: 37
< Set-Cookie: express:sess=eyJ1c2VySWQiOiJjODM0OWExOCJ9; path=/; httponly
< Set-Cookie: express:sess.sig=b770trUOiy4UwuR60ldBTbN_DtQ; path=/; httponly
< Date: Fri, 27 Aug 2021 19:47:30 GMT
< Connection: keep-alive
< Keep-Alive: timeout=5
< 
* Ignoring the response-body
{ [37 bytes data]
* Connection #0 to host localhost left intact
* Issue another request to this URL: 'http://localhost:3000/admin/products'
* Switch from POST to GET
* Found bundle for host localhost: 0x55bc0d551960 [serially]
* Can not multiplex, even if we wanted to!
* Re-using existing connection! (#0) with host localhost
* Connected to localhost (127.0.0.1) port 3000 (#0)
> GET /admin/products HTTP/1.1
> Host: localhost:3000
> User-Agent: curl/7.78.0
> Accept: */*
> 
* Connection died, retrying a fresh connect (retry count: 1)
* Closing connection 0
* Issue another request to this URL: 'http://localhost:3000/admin/products'
* Hostname localhost was found in DNS cache
*   Trying 127.0.0.1:3000...
* connect to 127.0.0.1 port 3000 failed: Connection refused
*   Trying ::1:3000...
* connect to ::1 port 3000 failed: Connection refused
* Failed to connect to localhost port 3000 after 0 ms: Connection refused
* Closing connection 1
curl: (7) Failed to connect to localhost port 3000 after 0 ms: Connection refused

GET request to localhost:3000/admin/products for Windows

Code:

curl localhost:3000/admin/products -visS > /dev/null
* Trying 127.0.0.1:3000...
* Connected to localhost (127.0.0.1) port 3000 (#0)
> GET /admin/products HTTP/1.1
> Host: localhost:3000
> User-Agent: curl/7.78.0
> Accept: */*
>
* Mark bundle as not supporting multiuse
< HTTP/1.1 200 OK
< X-Powered-By: Express
< Content-Type: text/html; charset=utf-8
< Content-Length: 2339
< ETag: W/"923-MGVv1CkwYiaapOPrLeQqyI2S8XA"
< Date: Fri, 27 Aug 2021 20:14:41 GMT
< Connection: keep-alive
< Keep-Alive: timeout=5
<
* Connection #0 to host localhost left intact

GET request to localhost:3000/admin/products for Linux

Code:

curl localhost:3000/admin/products -visSL > /dev/null
* Trying 127.0.0.1:3000...
* Connected to localhost (127.0.0.1) port 3000 (#0)
> GET /admin/products HTTP/1.1
> Host: localhost:3000
> User-Agent: curl/7.78.0
> Accept: */*
>
* Mark bundle as not supporting multiuse
< HTTP/1.1 200 OK
< X-Powered-By: Express
< Content-Type: text/html; charset=utf-8
< Content-Length: 2331
< ETag: W/"91b-TyOhurjPfeHHMY7hPdci2qMIg8k"
< Date: Fri, 27 Aug 2021 19:52:20 GMT
< Connection: keep-alive
< Keep-Alive: timeout=5
<
{ [2331 bytes data]
* Connection #0 to host localhost left intact

boughtonp · 08-27-2021, 04:50 PM

Ok, so it's actually closing/refusing the connection. Odd.

Have you got any logging in place for Node/Express? Maybe something is causing it to crash and auto-restart?

If it randomly works some times, that suggests a threading/race condition. I can't remember what sort of logging Express has, but either enable full debugging/verbosity and/or insert a console.log at the earliest point in the GET handler (to see if the second request is actually reaching Express or not). Also, if you can sleep it at the end of the POST (immediately before it returns the redirect), in case there's some async process that's only quick enough to finish some of the time (though I'd expect a 500 error in that situation).

If that didn't reveal anything, I'd probably copy the relevant functionality into a new application, verify it still had the problem, then start removing as much code as possible until its the simplest example that still demonstrates the issue - often that process will highlight the issue, but if it doesn't it gives you something that can be used to report a bug with.

I assume you've already checked that you're on the latest stable versions of Node and Express on both OSes...

Ghost-Order · 08-28-2021, 08:29 PM

Quote:

Originally Posted by boughtonp

Ok, so it's actually closing/refusing the connection. Odd.

Have you got any logging in place for Node/Express? Maybe something is causing it to crash and auto-restart?

If it randomly works some times, that suggests a threading/race condition. I can't remember what sort of logging Express has, but either enable full debugging/verbosity and/or insert a console.log at the earliest point in the GET handler (to see if the second request is actually reaching Express or not). Also, if you can sleep it at the end of the POST (immediately before it returns the redirect), in case there's some async process that's only quick enough to finish some of the time (though I'd expect a 500 error in that situation).

If that didn't reveal anything, I'd probably copy the relevant functionality into a new application, verify it still had the problem, then start removing as much code as possible until its the simplest example that still demonstrates the issue - often that process will highlight the issue, but if it doesn't it gives you something that can be used to report a bug with.

I assume you've already checked that you're on the latest stable versions of Node and Express on both OSes...

Yeah, as I said in the OP, the GET handler is not even being called, or rather it is being called as the header suggest but the GET handler isn't actually handling that request, I just tested logging at the earliest point of the GET handler again just in case but it's the same, the log doesn't appear in the console.

On the other hand, I tried with sleep functions of 100, 300, 1000 ms and it causes an empty reply from the server, however the new user is still being created:

Code:

* Trying 127.0.0.1:3000...
* Connected to localhost (127.0.0.1) port 3000 (#0)
> POST /signup HTTP/1.1
> Host: localhost:3000
> User-Agent: curl/7.78.0
> Accept: */*
> Content-Length: 58
> Content-Type: application/x-www-form-urlencoded
> 
} [58 bytes data]
* Empty reply from server
* Closing connection 0
curl: (52) Empty reply from server