Reverse-Proxy from Nginx to Node-RED does block Websocket communication

flobbi · 21 March 2019 10:03

Hello,

the problem existing is the following:

We have a Nginx Reverse Proxy which redirects to an OpenVPN connected Raspberry Pi running Node-RED. All static content is loaded correctly, just the Websocket connection via comms does not work.

On the nginx we run the following configuration for the Websocket part:

location ^~ /comms
    {
        access_log /var/log/nginx/comms_access.log;
        error_log /var/log/nginx/comms_error.log debug;

        proxy_pass https://##vpn_ip##:1880/comms;
        proxy_set_header Host $host;
	proxy_http_version 1.1;
        proxy_set_header Upgrade $http_upgrade;
        proxy_set_header Connection "upgrade";
    }

This leads to the following error (debug log nginx):

2019/03/21 09:41:17 [debug] 31802#0: *9592 http cleanup add: 0000000002861158
2019/03/21 09:41:17 [debug] 31802#0: *9592 get rr peer, try: 1
2019/03/21 09:41:17 [debug] 31802#0: *9592 stream socket 14
2019/03/21 09:41:17 [debug] 31802#0: *9592 epoll add connection: fd:14 ev:80002005
2019/03/21 09:41:17 [debug] 31802#0: *9592 connect to 10.0.12.28:1880, fd:14 #9634
2019/03/21 09:41:17 [debug] 31802#0: *9592 http upstream connect: -2
2019/03/21 09:41:17 [debug] 31802#0: *9592 posix_memalign: 0000000002806E70:128 @16
2019/03/21 09:41:17 [debug] 31802#0: *9592 event timer add: 14: 60000:1553157737896
2019/03/21 09:41:17 [debug] 31802#0: *9592 http finalize request: -4, "/comms?" a:1, c:2
2019/03/21 09:41:17 [debug] 31802#0: *9592 http request count:2 blk:0
2019/03/21 09:41:17 [debug] 31802#0: *9592 http run request: "/comms?"
2019/03/21 09:41:17 [debug] 31802#0: *9592 http upstream check client, write event:1, "/comms"
2019/03/21 09:41:17 [debug] 31802#0: *9592 http run request: "/comms?"
2019/03/21 09:41:17 [debug] 31802#0: *9592 http upstream check client, write event:1, "/comms"
2019/03/21 09:41:17 [debug] 31802#0: *9592 http upstream request: "/comms?"
2019/03/21 09:41:17 [debug] 31802#0: *9592 http upstream send request handler
2019/03/21 09:41:17 [debug] 31802#0: *9592 malloc: 0000000002809790:72
2019/03/21 09:41:17 [debug] 31802#0: *9592 set session: 00000000027F6D50
2019/03/21 09:41:17 [debug] 31802#0: *9592 tcp_nodelay
2019/03/21 09:41:17 [debug] 31802#0: *9592 SSL_do_handshake: -1
2019/03/21 09:41:17 [debug] 31802#0: *9592 SSL_get_error: 2
2019/03/21 09:41:17 [debug] 31802#0: *9592 SSL handshake handler: 0
2019/03/21 09:41:17 [debug] 31802#0: *9592 SSL_do_handshake: 1
2019/03/21 09:41:17 [debug] 31802#0: *9592 SSL: TLSv1.2, cipher: "ECDHE-RSA-AES128-GCM-SHA256 TLSv1.2 Kx=ECDH Au=RSA Enc=AESGCM(128) Mac=AEAD"
2019/03/21 09:41:17 [debug] 31802#0: *9592 SSL reused session
2019/03/21 09:41:17 [debug] 31802#0: *9592 http upstream ssl handshake: "/comms?"
2019/03/21 09:41:17 [debug] 31802#0: *9592 save session: 00000000027F6D50
2019/03/21 09:41:17 [debug] 31802#0: *9592 old session: 00000000027F6D50
2019/03/21 09:41:17 [debug] 31802#0: *9592 http upstream send request
2019/03/21 09:41:17 [debug] 31802#0: *9592 http upstream send request body
2019/03/21 09:41:17 [debug] 31802#0: *9592 chain writer buf fl:1 s:885
2019/03/21 09:41:17 [debug] 31802#0: *9592 chain writer in: 0000000002861198
2019/03/21 09:41:17 [debug] 31802#0: *9592 malloc: 0000000002806D70:80
2019/03/21 09:41:17 [debug] 31802#0: *9592 malloc: 00000000027F7710:16384
2019/03/21 09:41:17 [debug] 31802#0: *9592 SSL buf copy: 885
2019/03/21 09:41:17 [debug] 31802#0: *9592 SSL to write: 885
2019/03/21 09:41:17 [debug] 31802#0: *9592 SSL_write: 885
2019/03/21 09:41:17 [debug] 31802#0: *9592 chain writer out: 0000000000000000
2019/03/21 09:41:17 [debug] 31802#0: *9592 event timer del: 14: 1553157737896
2019/03/21 09:41:17 [debug] 31802#0: *9592 event timer add: 14: 60000:1553157737949
2019/03/21 09:41:17 [debug] 31802#0: *9592 http upstream process header
2019/03/21 09:41:17 [debug] 31802#0: *9592 malloc: 00000000027FB720:4096
2019/03/21 09:41:17 [debug] 31802#0: *9592 SSL_read: -1
2019/03/21 09:41:17 [debug] 31802#0: *9592 SSL_get_error: 2
2019/03/21 09:41:17 [debug] 31802#0: *9592 http upstream request: "/comms?"
2019/03/21 09:41:17 [debug] 31802#0: *9592 http upstream dummy handler
2019/03/21 09:41:17 [debug] 31802#0: *9592 http upstream request: "/comms?"
2019/03/21 09:41:17 [debug] 31802#0: *9592 http upstream process header
2019/03/21 09:41:17 [debug] 31802#0: *9592 SSL_read: 425
2019/03/21 09:41:17 [debug] 31802#0: *9592 SSL_read: -1
2019/03/21 09:41:17 [debug] 31802#0: *9592 SSL_get_error: 2
2019/03/21 09:41:17 [debug] 31802#0: *9592 http proxy status 404 "404 Not Found"
2019/03/21 09:41:17 [debug] 31802#0: *9592 http proxy header: "X-Powered-By: Express"
2019/03/21 09:41:17 [debug] 31802#0: *9592 http proxy header: "Access-Control-Allow-Origin: *"
2019/03/21 09:41:17 [debug] 31802#0: *9592 http proxy header: "Content-Security-Policy: default-src 'self'"
2019/03/21 09:41:17 [debug] 31802#0: *9592 http proxy header: "X-Content-Type-Options: nosniff"
2019/03/21 09:41:17 [debug] 31802#0: *9592 http proxy header: "Content-Type: text/html; charset=utf-8"
2019/03/21 09:41:17 [debug] 31802#0: *9592 posix_memalign: 00000000027D2E10:4096 @16
2019/03/21 09:41:17 [debug] 31802#0: *9592 http proxy header: "Content-Length: 144"
2019/03/21 09:41:17 [debug] 31802#0: *9592 http proxy header: "Date: Thu, 21 Mar 2019 08:41:17 GMT"
2019/03/21 09:41:17 [debug] 31802#0: *9592 http proxy header: "Connection: keep-alive"
2019/03/21 09:41:17 [debug] 31802#0: *9592 http proxy header done
2019/03/21 09:41:17 [debug] 31802#0: *9592 HTTP/1.1 404 Not Found
Server: nginx
Date: Thu, 21 Mar 2019 08:41:17 GMT
Content-Type: text/html; charset=utf-8
Transfer-Encoding: chunked
Connection: keep-alive
Vary: Accept-Encoding
X-Powered-By: Express
Access-Control-Allow-Origin: *
Content-Security-Policy: default-src 'self'
X-Content-Type-Options: nosniff
Content-Encoding: gzip

Debug log Node-RED/RaspberryPi:

Thu, 21 Mar 2019 09:26:21 GMT express:router dispatching GET /comms
Thu, 21 Mar 2019 09:26:21 GMT express:router query  : /comms
Thu, 21 Mar 2019 09:26:21 GMT express:router expressInit  : /comms
Thu, 21 Mar 2019 09:26:21 GMT express:router mounted_app  : /comms
Thu, 21 Mar 2019 09:26:21 GMT express:router dispatching GET /comms
Thu, 21 Mar 2019 09:26:21 GMT express:router query  : /comms
Thu, 21 Mar 2019 09:26:21 GMT express:router expressInit  : /comms
Thu, 21 Mar 2019 09:26:21 GMT express:router corsMiddleware  : /comms
Thu, 21 Mar 2019 09:26:21 GMT express:router jsonParser  : /comms
Thu, 21 Mar 2019 09:26:21 GMT express:router urlencodedParser  : /comms
Thu, 21 Mar 2019 09:26:21 GMT express:router mounted_app  : /comms
Thu, 21 Mar 2019 09:26:21 GMT express:router dispatching GET /comms
Thu, 21 Mar 2019 09:26:21 GMT express:router query  : /comms
Thu, 21 Mar 2019 09:26:21 GMT express:router expressInit  : /comms
Thu, 21 Mar 2019 09:26:21 GMT express:router <anonymous>  : /comms
Thu, 21 Mar 2019 09:26:21 GMT express:router serveStatic  : /comms
Thu, 21 Mar 2019 09:26:21 GMT express:router mounted_app  : /comms
Thu, 21 Mar 2019 09:26:21 GMT express:router dispatching GET /comms
Thu, 21 Mar 2019 09:26:21 GMT express:router query  : /comms
Thu, 21 Mar 2019 09:26:21 GMT express:router expressInit  : /comms
Thu, 21 Mar 2019 09:26:21 GMT express:router mounted_app  : /comms
Thu, 21 Mar 2019 09:26:21 GMT express:router dispatching GET /comms
Thu, 21 Mar 2019 09:26:21 GMT express:router query  : /comms
Thu, 21 Mar 2019 09:26:21 GMT express:router expressInit  : /comms
Thu, 21 Mar 2019 09:26:21 GMT express:router mounted_app  : /comms
Thu, 21 Mar 2019 09:26:21 GMT express:application no routes defined on app
Thu, 21 Mar 2019 09:26:21 GMT express:router serveStatic  : /comms

Does anybody know this problem?

realjax · 21 March 2019 11:39

Seems your nginx conf is ok. That is, I use the exact same and it works for me. Is the VPN connection maybe causing problems?

flobbi · 21 March 2019 12:07

Hello realjax,

the VPN connection is not causing the problem.
We have a different setup via VPN where the connection with Node-red works (Not the same setup but the same VPN connection).
Any other ideas what we can try?

realjax · 21 March 2019 12:24

Did you try http instead of https? I also use ssl but have it managed by Nginx

TotallyInformation · 21 March 2019 17:07

Certainly looks like an SSL issue. Are you using a self-signed cert?

flobbi · 22 March 2019 09:12

Thanks for your help so far.

We discovered an missing "Upgrade: websocket"-Header in the forwarded request to Node-RED. As we using $http_upgrade in our Nginx config, this variable is falsely empty.

Setting this manually to proxy_set_header Upgrade "websocket"; does the trick, but now we have another problem:

2019/03/22 09:41:30 [debug] 25212#0: *4112 http proxy status 101 "101 Switching Protocols"
2019/03/22 09:41:30 [debug] 25212#0: *4112 http proxy header: "Upgrade: websocket"
2019/03/22 09:41:30 [debug] 25212#0: *4112 http proxy header: "Connection: Upgrade"
2019/03/22 09:41:30 [debug] 25212#0: *4112 posix_memalign: 000000000298CA20:4096 @16
2019/03/22 09:41:30 [debug] 25212#0: *4112 http proxy header: "Sec-WebSocket-Accept: orjVAd/vZxRrDU4kXbdS96B/VBw="
2019/03/22 09:41:30 [debug] 25212#0: *4112 http proxy header: "Sec-WebSocket-Extensions: permessage-deflate"
2019/03/22 09:41:30 [debug] 25212#0: *4112 http proxy header done
2019/03/22 09:41:30 [debug] 25212#0: *4112 HTTP/1.1 101 Switching Protocols
Server: nginx
Date: Fri, 22 Mar 2019 08:41:30 GMT
Connection: upgrade
Upgrade: websocket
Sec-WebSocket-Accept: orjVAd/vZxRrDU4kXbdS96B/VBw=
Sec-WebSocket-Extensions: permessage-deflate

2019/03/22 09:41:30 [debug] 25212#0: *4112 write new buf t:1 f:0 000000000298CB20, pos 000000000298CB20, size: 227 file: 0, size: 0
2019/03/22 09:41:30 [debug] 25212#0: *4112 http write filter: l:0 f:0 s:227
2019/03/22 09:41:30 [debug] 25212#0: *4112 http cacheable: 0
2019/03/22 09:41:30 [debug] 25212#0: *4112 http proxy filter init s:101 h:0 c:0 l:-1
2019/03/22 09:41:30 [debug] 25212#0: *4112 http upstream process upstream
2019/03/22 09:41:30 [debug] 25212#0: *4112 pipe read upstream: 0
2019/03/22 09:41:30 [debug] 25212#0: *4112 pipe preread: 0
2019/03/22 09:41:30 [debug] 25212#0: *4112 pipe buf free s:0 t:1 f:0 0000000002807F70, pos 000000000280801F, size: 0 file: 0, size: 0
2019/03/22 09:41:30 [debug] 25212#0: *4112 pipe length: -1
2019/03/22 09:41:30 [debug] 25212#0: *4112 event timer: 14, old: 1553244150211, new: 1553244150244
2019/03/22 09:41:30 [debug] 25212#0: *4112 http upstream request: "/comms?"
2019/03/22 09:41:30 [debug] 25212#0: *4112 http upstream dummy handler
2019/03/22 09:42:30 [debug] 25212#0: *4112 event timer del: 14: 1553244150211
2019/03/22 09:42:30 [debug] 25212#0: *4112 http upstream request: "/comms?"
2019/03/22 09:42:30 [debug] 25212#0: *4112 http upstream process upstream
2019/03/22 09:42:30 [error] 25212#0: *4112 upstream timed out (110: Connection timed out) while reading upstream, client: 127.0.0.1, request: "GET /comms HTTP/1.1", upstream: "https://10.0.12.24:1880/comms"
2019/03/22 09:42:30 [debug] 25212#0: *4112 http upstream exit: 0000000000000000
2019/03/22 09:42:30 [debug] 25212#0: *4112 finalize http upstream request: 502
2019/03/22 09:42:30 [debug] 25212#0: *4112 finalize http proxy request
2019/03/22 09:42:30 [debug] 25212#0: *4112 free rr peer 1 0
2019/03/22 09:42:30 [debug] 25212#0: *4112 SSL_shutdown: 1
2019/03/22 09:42:30 [debug] 25212#0: *4112 close http upstream connection: 14

The response has the correct header 101 Switching Protocols, but then Node-RED times out:
2019/03/22 09:42:30 [error] 25212#0: *4112 upstream timed out (110: Connection timed out) while reading upstream, client: 127.0.0.1, request: "GET /comms HTTP/1.1", upstream: "https://10.0.12.24:1880/comms"

Anybody got any guesses?

realjax · 22 March 2019 09:49

Odd, I didnt need that. I see you are accessing node-red through https, have you tried a non-ssl connection as suggested?

flobbi · 22 March 2019 10:17

Sorry for ignoring you, @realjax
The Node-RED is running on https, which we can't change, therefore we have to go with an ssl connection. I also did a setup without ssl but it was the same result.

We're absolutely be at a loss where the header gets lost, too. But without setting it manually, the header will not be send although the browser is setting it.

realjax · 22 March 2019 10:36

no worries!
Well, I dunno what the problem is other then that from your latest log it seems that Nginx simply can't connect to https://10.0.12.24:1880/comms, it times out. Are you 100% sure that url is fine ?

flobbi · 22 March 2019 11:17

Yes, the url is fine. When I connect to the device an call it directly, everything is fine.

realjax · 22 March 2019 11:23

Looks like you are using a self signed certificate. That might very well be the reason nginx times out.

Topic		Replies	Views
WebSocket connection handshake 404 on /comms (nginx to Node-RED does block Websocket communication) General	5	6503	7 December 2021
NodeRED websockets and Nginx reverse proxy (subfolder) General nginx	10	1276	30 June 2022
Websocket comms error General	3	928	9 March 2021
Websocket with Node-RED and reverse proxy General	2	184	30 April 2024
Node red shows Lost connection to server, reconnecting.. beacuse of WebSocket connection to 'wss:// comms' api failed General	4	1457	18 June 2022

Reverse-Proxy from Nginx to Node-RED does block Websocket communication

Related topics