Forum OpenACS Q&A: Re: How to correctly configure the reverse proxy.

Collapse
9: Re: How to correctly configure the reverse proxy. (response to 1)
Posted by Tony Kirkham on 05/04/21 12:23 PM

I now have a NaviServer 4.99.20 running and, unfortunately, I am seeing the same result; a 36.9 KB file uploads without a problem, but a 789 KB file does not.

Here is what I am now seeing in the logs for the failed upload. I have removed several of the repetitive lines.

[03/May/2021:17:03:32][1.7fc60f646700][-conn:servern_pmd:default:0:216-] Notice: Inside validation call back pmd::val_call
[03/May/2021:17:03:32][1.7fc60f646700][-conn:servern_pmd:default:0:216-] Debug(connchan): ns_connchan open http://servern-pmd-pm-dashboard/pm-dashboard/api/program/25875/logo?user_id=2936 => conn304
[03/May/2021:17:03:32][1.7fc60f646700][-conn:servern_pmd:default:0:216-] Debug(connchan): conn304 ConnchanDriverSend try to send [0] 63 bytes (total 1331)
[03/May/2021:17:03:32][1.7fc60f646700][-conn:servern_pmd:default:0:216-] Debug(connchan): conn304 ConnchanDriverSend NsDriverSend returned result 1331 errorState 0 --- operation now in progress
[03/May/2021:17:03:32][1.7fc60f646700][-conn:servern_pmd:default:0:216-] Debug(connchan): conn304 ConnchanDriverSend check partialResult 1331 nSent 1331 toSend 0 partial ? 0
[03/May/2021:17:03:32][1.7fc60f646700][-conn:servern_pmd:default:0:216-] Debug(connchan): conn304 ### check result 1331 == -1 || 1331 == 1331 (partial 0 && ok 1) => try again 0
[03/May/2021:17:03:32][1.7fc60f646700][-conn:servern_pmd:default:0:216-] Debug(connchan): conn304 ConnchanDriverSend sent 1331 bytes state Operation now in progress
[03/May/2021:17:03:32][1.7fc60f646700][-conn:servern_pmd:default:0:216-] Debug(connchan): ns_connchan open http://servern-pmd-pm-dashboard/pm-dashboard/api/program/25875/logo?user_id=2936 returns 0
[03/May/2021:17:03:32][1.7fc60f646700][-conn:servern_pmd:default:0:216-] Notice: PROXY: upstream: send max 16000 bytes from string to conn304 (length 808993)
[03/May/2021:17:03:32][1.7fc60f646700][-conn:servern_pmd:default:0:216-] Debug(connchan): WS: send msgLen toSend 16000
[03/May/2021:17:03:32][1.7fc60f646700][-conn:servern_pmd:default:0:216-] Debug(connchan): conn304 ConnchanDriverSend try to send [0] 16000 bytes (total 16000)
[03/May/2021:17:03:32][1.7fc60f646700][-conn:servern_pmd:default:0:216-] Debug(connchan): conn304 ConnchanDriverSend NsDriverSend returned result 16000 errorState 0 --- operation now in progress
[03/May/2021:17:03:32][1.7fc60f646700][-conn:servern_pmd:default:0:216-] Debug(connchan): conn304 ConnchanDriverSend check partialResult 16000 nSent 16000 toSend 0 partial ? 0
[03/May/2021:17:03:32][1.7fc60f646700][-conn:servern_pmd:default:0:216-] Debug(connchan): conn304 ### check result 16000 == -1 || 16000 == 16000 (partial 0 && ok 1) => try again 0
[03/May/2021:17:03:32][1.7fc60f646700][-conn:servern_pmd:default:0:216-] Debug(connchan): conn304 ns_connchan write returns 0
[03/May/2021:17:03:32][1.7fc60f646700][-conn:servern_pmd:default:0:216-] Notice: PROXY: upstream: send max 16000 bytes from string to conn304 (length 808993)
... removed lines ...
[03/May/2021:17:03:32][1.7fc60f646700][-conn:servern_pmd:default:0:216-] Debug(connchan): WS: send msgLen toSend 16000
[03/May/2021:17:03:32][1.7fc60f646700][-conn:servern_pmd:default:0:216-] Debug(connchan): conn304 ConnchanDriverSend try to send [0] 16000 bytes (total 16000)
[03/May/2021:17:03:32][1.7fc60f646700][-conn:servern_pmd:default:0:216-] Debug(connchan): conn304 ConnchanDriverSend NsDriverSend returned result 16000 errorState 0 --- operation now in progress
[03/May/2021:17:03:32][1.7fc60f646700][-conn:servern_pmd:default:0:216-] Debug(connchan): conn304 ConnchanDriverSend check partialResult 16000 nSent 16000 toSend 0 partial ? 0
[03/May/2021:17:03:32][1.7fc60f646700][-conn:servern_pmd:default:0:216-] Debug(connchan): conn304 ### check result 16000 == -1 || 16000 == 16000 (partial 0 && ok 1) => try again 0
[03/May/2021:17:03:32][1.7fc60f646700][-conn:servern_pmd:default:0:216-] Debug(connchan): conn304 ns_connchan write returns 0
[03/May/2021:17:03:32][1.7fc60f646700][-conn:servern_pmd:default:0:216-] Notice: PROXY: upstream: send max 16000 bytes from string to conn304 (length 808993)
[03/May/2021:17:03:32][1.7fc60f646700][-conn:servern_pmd:default:0:216-] Debug(connchan): WS: send msgLen toSend 16000
[03/May/2021:17:03:32][1.7fc60f646700][-conn:servern_pmd:default:0:216-] Debug(connchan): conn304 ConnchanDriverSend try to send [0] 16000 bytes (total 16000)
[03/May/2021:17:03:32][1.7fc60f646700][-conn:servern_pmd:default:0:216-] Debug(connchan): conn304 ConnchanDriverSend NsDriverSend returned result 12744 errorState 0 --- operation now in progress
[03/May/2021:17:03:32][1.7fc60f646700][-conn:servern_pmd:default:0:216-] Debug(connchan): conn304 ConnchanDriverSend check partialResult 12744 nSent 12744 toSend 3256 partial ? 1
[03/May/2021:17:03:32][1.7fc60f646700][-conn:servern_pmd:default:0:216-] Notice: conn304 ConnchanDriverSend partial write operation, sent 12744 (so far 12744) remaining 3256 bytes, full length 16000
[03/May/2021:17:03:32][1.7fc60f646700][-conn:servern_pmd:default:0:216-] Debug(connchan): conn304 ### check result 12744 == -1 || 16000 == 12744 (partial 1 && ok 1) => try again 1
[03/May/2021:17:03:32][1.7fc60f646700][-conn:servern_pmd:default:0:216-] Debug(connchan): conn304 ConnchanDriverSend try to send [0] 3256 bytes (total 3256)
[03/May/2021:17:03:32][1.7fc60f646700][-conn:servern_pmd:default:0:216-] Debug(connchan): conn304 ConnchanDriverSend NsDriverSend returned result 0 errorState 0 --- resource temporarily unavailable
[03/May/2021:17:03:32][1.7fc60f646700][-conn:servern_pmd:default:0:216-] Debug(connchan): conn304 ConnchanDriverSend would block, no timeout configured, origLength 16000 still to send 16000 already sent 12744
[03/May/2021:17:03:32][1.7fc60f646700][-conn:servern_pmd:default:0:216-] Notice: ... partial write: to send 16000 sent 12744 remaining 3256
[03/May/2021:17:03:32][1.7fc60f646700][-conn:servern_pmd:default:0:216-] Debug(connchan): conn304 ns_connchan write returns 0
[03/May/2021:17:03:32][1.7fc60f646700][-conn:servern_pmd:default:0:216-] Notice: PROXY: upstream: send max 16000 bytes from string to conn304 (length 808993)
[03/May/2021:17:03:32][1.7fc60f646700][-conn:servern_pmd:default:0:216-] Debug(connchan): WS: send msgLen toSend 16000
[03/May/2021:17:03:32][1.7fc60f646700][-conn:servern_pmd:default:0:216-] Debug(connchan): conn304 ConnchanDriverSend try to send [0] 16000 bytes (total 16000)
[03/May/2021:17:03:32][1.7fc60f646700][-conn:servern_pmd:default:0:216-] Debug(connchan): conn304 ConnchanDriverSend NsDriverSend returned result 0 errorState 0 --- resource temporarily unavailable
[03/May/2021:17:03:32][1.7fc60f646700][-conn:servern_pmd:default:0:216-] Debug(connchan): conn304 ConnchanDriverSend would block, no timeout configured, origLength 16000 still to send 16000 already sent 0
[03/May/2021:17:03:32][1.7fc60f646700][-conn:servern_pmd:default:0:216-] Notice: ... partial write: to send 16000 sent 0 remaining 16000
[03/May/2021:17:03:32][1.7fc60f646700][-conn:servern_pmd:default:0:216-] Debug(connchan): conn304 ns_connchan write returns 0
[03/May/2021:17:03:32][1.7fc60f646700][-conn:servern_pmd:default:0:216-] Notice: PROXY: upstream: send max 16000 bytes from string to conn304 (length 808993)
... removed lines ...
[03/May/2021:17:03:32][1.7fc60f646700][-conn:servern_pmd:default:0:216-] Debug(connchan): WS: send msgLen toSend 16000
[03/May/2021:17:03:32][1.7fc60f646700][-conn:servern_pmd:default:0:216-] Debug(connchan): conn304 ConnchanDriverSend try to send [0] 16000 bytes (total 16000)
[03/May/2021:17:03:32][1.7fc60f646700][-conn:servern_pmd:default:0:216-] Debug(connchan): conn304 ConnchanDriverSend NsDriverSend returned result 0 errorState 0 --- resource temporarily unavailable
[03/May/2021:17:03:32][1.7fc60f646700][-conn:servern_pmd:default:0:216-] Debug(connchan): conn304 ConnchanDriverSend would block, no timeout configured, origLength 16000 still to send 16000 already sent 0
[03/May/2021:17:03:32][1.7fc60f646700][-conn:servern_pmd:default:0:216-] Notice: ... partial write: to send 16000 sent 0 remaining 16000
[03/May/2021:17:03:32][1.7fc60f646700][-conn:servern_pmd:default:0:216-] Debug(connchan): conn304 ns_connchan write returns 0
[03/May/2021:17:03:32][1.7fc60f646700][-conn:servern_pmd:default:0:216-] Notice: PROXY: upstream: send max 16000 bytes from string to conn304 (length 808993)
[03/May/2021:17:03:32][1.7fc60f646700][-conn:servern_pmd:default:0:216-] Debug(connchan): WS: send msgLen toSend 8993
[03/May/2021:17:03:32][1.7fc60f646700][-conn:servern_pmd:default:0:216-] Debug(connchan): conn304 ConnchanDriverSend try to send [0] 8993 bytes (total 8993)
[03/May/2021:17:03:32][1.7fc60f646700][-conn:servern_pmd:default:0:216-] Debug(connchan): conn304 ConnchanDriverSend NsDriverSend returned result 0 errorState 0 --- resource temporarily unavailable
[03/May/2021:17:03:32][1.7fc60f646700][-conn:servern_pmd:default:0:216-] Debug(connchan): conn304 ConnchanDriverSend would block, no timeout configured, origLength 8993 still to send 8993 already sent 0
[03/May/2021:17:03:32][1.7fc60f646700][-conn:servern_pmd:default:0:216-] Notice: ... partial write: to send 8993 sent 0 remaining 8993
[03/May/2021:17:03:32][1.7fc60f646700][-conn:servern_pmd:default:0:216-] Debug(connchan): conn304 ns_connchan write returns 0
[03/May/2021:17:03:32][1.7fc60f646700][-conn:servern_pmd:default:0:216-] Debug(connchan): conn305 ConnChanDetachObjCmd sock 4
[03/May/2021:17:03:32][1.7fc60f646700][-conn:servern_pmd:default:0:216-] Debug(connchan): conn305 ns_connchan detach returns 0
[03/May/2021:17:03:32][1.7fc60f646700][-conn:servern_pmd:default:0:216-] Notice: PROXY: backendChan conn304 frontendChan conn305 method POST version 1.0 http://servern-pmd-pm-dashboard/pm-dashboard/api/program/25875/logo?user_id=2936
[03/May/2021:17:03:32][1.7fc60f646700][-conn:servern_pmd:default:0:216-] Debug(connchan): conn305 ns_connchan callback returns 0
[03/May/2021:17:03:32][1.7fc60f646700][-conn:servern_pmd:default:0:216-] Debug(connchan): conn304 ns_connchan callback returns 0
[03/May/2021:17:03:42][1.7fc5f4ff9700][-socks-] Debug(connchan): conn304 NsTclConnChanProc why  (64)
[03/May/2021:17:03:42][1.7fc5f4ff9700][-socks-] Notice: PROXY: timeout occurred while waiting for backend reply conn304 to conn305
[03/May/2021:17:03:42][1.7fc5f4ff9700][-socks-] Debug(connchan): WS: send msgLen toSend 32
[03/May/2021:17:03:42][1.7fc5f4ff9700][-socks-] Debug(connchan): conn305 ConnchanDriverSend try to send [0] 32 bytes (total 32)
[03/May/2021:17:03:42][1.7fc5f4ff9700][-socks-] Debug(connchan): conn305 ConnchanDriverSend NsDriverSend returned result 32 errorState 1 --- Success
[03/May/2021:17:03:42][1.7fc5f4ff9700][-socks-] Debug(connchan): conn305 ConnchanDriverSend check partialResult 32 nSent 32 toSend 0 partial ? 0
[03/May/2021:17:03:42][1.7fc5f4ff9700][-socks-] Debug(connchan): conn305 ### check result 32 == -1 || 32 == 32 (partial 0 && ok 1) => try again 0
[03/May/2021:17:03:42][1.7fc5f4ff9700][-socks-] Debug(connchan): conn305 ns_connchan write returns 0
[03/May/2021:17:03:42][1.7fc5f4ff9700][-socks-] Notice: PROXY: backendReply: ... auto closing conn304 http://servern-pmd-pm-dashboard/pm-dashboard/api/program/25875/logo?user_id=2936
[03/May/2021:17:03:42][1.7fc5f4ff9700][-socks-] Debug(connchan): conn305 ns_connchan close connChanPtr 0x7fc609287ca0
[03/May/2021:17:03:42][1.7fc5f4ff9700][-socks-] Debug(connchan): conn305 connchan: CancelCallback 0x7fc60a862700
[03/May/2021:17:03:42][1.7fc5f4ff9700][-socks-] Debug(connchan): conn305 ns_connchan close returns 0
[03/May/2021:17:03:42][1.7fc5f4ff9700][-socks-] Debug(connchan): conn304 NsTclConnChanProc Tcl eval <::revproxy::backendReply> returned <0>
[03/May/2021:17:03:42][1.7fc5f4ff9700][-socks-] Debug(connchan): NsTclConnChanProc <::revproxy::backendReply -callback pmd::rep_call conn304 conn305 http://servern-pmd-pm-dashboard/pm-dashboard/api/program/25875/logo?user_id=2936 {-timeout 10 -sendtimeout 60 -receivetimeout 60} 0 t> numeric result 0
[03/May/2021:17:03:42][1.7fc5f4ff9700][-socks-] Debug(connchan): conn304 NsTclConnChanProc free channel
[03/May/2021:17:03:42][1.7fc5f4ff9700][-socks-] Debug(connchan): conn304 connchan: CancelCallback 0x7fc5e8fd6200
[03/May/2021:17:03:42][1.7fc5f4ff9700][-socks-] Debug(connchan): NsTclConnChanProc called on a probably deleted callback 0x7fc60a862700
[03/May/2021:17:03:42][1.7fc5f4ff9700][-socks-] Debug(connchan): connchan: callbackCallbackFree cbPtr 0x7fc60a862700 why 32
[03/May/2021:17:03:42][1.7fc5f4ff9700][-socks-] Debug(connchan): connchan: callbackCallbackFree cbPtr 0x7fc5e8fd6200 why 32

Here are the corresponding lines from the Node/Express logs, which do not appear deep enough to be of much use.

Mon, 03 May 2021 23:03:32 GMT express:router dispatching POST /pm-dashboard/api/program/25875/logo?user_id=2936
Mon, 03 May 2021 23:03:32 GMT express:router query  : /pm-dashboard/api/program/25875/logo?user_id=2936
Mon, 03 May 2021 23:03:32 GMT express:router expressInit  : /pm-dashboard/api/program/25875/logo?user_id=2936
Mon, 03 May 2021 23:03:32 GMT express:router logger  : /pm-dashboard/api/program/25875/logo?user_id=2936
Mon, 03 May 2021 23:03:32 GMT express:router logger  : /pm-dashboard/api/program/25875/logo?user_id=2936
Mon, 03 May 2021 23:03:32 GMT express:router jsonParser  : /pm-dashboard/api/program/25875/logo?user_id=2936
Mon, 03 May 2021 23:03:32 GMT express:router urlencodedParser  : /pm-dashboard/api/program/25875/logo?user_id=2936
Mon, 03 May 2021 23:03:32 GMT express:router cookieParser  : /pm-dashboard/api/program/25875/logo?user_id=2936
Mon, 03 May 2021 23:03:32 GMT express:router trim prefix (/pm-dashboard) from url /pm-dashboard/api/program/25875/logo?user_id=2936
Mon, 03 May 2021 23:03:32 GMT express:router serveStatic /pm-dashboard : /pm-dashboard/api/program/25875/logo?user_id=2936
Mon, 03 May 2021 23:03:32 GMT express:router trim prefix (/pm-dashboard) from url /pm-dashboard/api/program/25875/logo?user_id=2936
Mon, 03 May 2021 23:03:32 GMT express:router serveStatic /pm-dashboard : /pm-dashboard/api/program/25875/logo?user_id=2936
Mon, 03 May 2021 23:03:32 GMT express:router <anonymous>  : /pm-dashboard/api/program/25875/logo?user_id=2936
Mon, 03 May 2021 23:03:32 GMT express:router trim prefix (/pm-dashboard/api) from url /pm-dashboard/api/program/25875/logo?user_id=2936
Mon, 03 May 2021 23:03:32 GMT express:router router /pm-dashboard/api : /pm-dashboard/api/program/25875/logo?user_id=2936
Mon, 03 May 2021 23:03:32 GMT express:router dispatching POST /program/25875/logo?user_id=2936
Mon, 03 May 2021 23:03:32 GMT express:router trim prefix (/program) from url /program/25875/logo?user_id=2936
Mon, 03 May 2021 23:03:32 GMT express:router router /program : /pm-dashboard/api/program/25875/logo?user_id=2936
Mon, 03 May 2021 23:03:32 GMT express:router dispatching POST /25875/logo?user_id=2936

The upload starts off just fine and then about half-way through a partial send happens and all further sends fail. Everything happens in the first second of the request and is not affected by the 10 second timeout I have tried to set in the least. It does now report that "resource temporarily unavailable" along with the "would block, no timeout configured".

Another part of this puzzle, that I did not mention before, is that I am running Naviserver and Node in separate Docker containers. As I mentioned above, if I change the upload code to bypass NaviServer as the reverse proxy and go directly to the Node server all of the files upload without a problem. So it does not seem to be a size limit problem for Node or Naviserver individually, but only in the transfer between them.

Does this give any more insight into this problem?

I really appreciate all the help,

-Tony