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

Collapse
4: Re: How to correctly configure the reverse proxy. (response to 1)
Posted by Tony Kirkham on 01/31/21 01:50 AM

I'm just getting back to this problem. We have been limping along with only the ability to upload smaller files. I wanted to thank you very much for your reply a couple of months ago. I believe we have the changes you are referring to because we are running NaviServer/4.99.18 and from the link to the commit you indicated it appears that those changes were included in this version. Also I am running revproxy version 0.12.

I appreciate the suggestions (and directions) to increase the logging level and I am including the results below. I added validation and backend reply call backs that make a simple ns_log call so I could see just where they are called in the process. The uploads that succeed contain files Here is the call that I am currently making which includes some timeouts where I am trying to make sure that there is plenty of time to upload the files before timing out. This has not helped.

lappend upstream_args -timeout 10
lappend upstream_args -sendtimeout 60
lappend upstream_args -receivetimeout 60
lappend upstream_args -url_rewrite_callback pmd::rewrite_url
lappend upstream_args -validation_callback pmd::val_call
lappend upstream_args -exception_callback pmd::exc_call
lappend upstream_args -backend_reply_callback pmd::rep_call

ns_register_filter \
    postauth * http://server_name_path/pmd/* \
    ::revproxy::upstream {*}$upstream_args

This segment of the log is a successful attempt where the file is uploaded and stored correctly. The file size is ~ 40 kB. I have had files up to ~ 170 kB succeed.

[29/Jan/2021:22:39:45][1.7f570aacf700][-conn:server_name:1:8-] Notice: Inside validation call back pmd::val_call
[29/Jan/2021:22:39:45][1.7f570aacf700][-conn:server_name:1:8-] Notice: PROXY: upstream: send max 16000 bytes from string to conn0 (length 38094)
[29/Jan/2021:22:39:45][1.7f570aacf700][-conn:server_name:1:8-] Notice: PROXY: upstream: send max 16000 bytes from string to conn0 (length 38094)
[29/Jan/2021:22:39:45][1.7f570aacf700][-conn:server_name:1:8-] Notice: PROXY: upstream: send max 16000 bytes from string to conn0 (length 38094)
[29/Jan/2021:22:39:45][1.7f570aacf700][-conn:server_name:1:8-] Notice: PROXY: backendChan conn0 frontendChan conn1 method POST version 1.0 http://server_name_path/pmd/api/program/25689/logo?user_id=1234
[29/Jan/2021:22:39:45][1.7f56f1ffb700][-socks-] Notice: socks: starting
[29/Jan/2021:22:39:46][1.7f56f1ffb700][-socks-] Notice: update interpreter to epoch 1, trace none, time 0.216013 secs
[29/Jan/2021:22:39:46][1.7f56f1ffb700][-socks-] Notice: PROXY: backendReply: send 223 bytes from conn0 to conn1 (http://server_name_path/pmd/api/program/25689/logo?user_id=1234)
[29/Jan/2021:22:39:46][1.7f56f1ffb700][-socks-] Notice: PROXY: backendReply: first <HTTP/1.1 200 OK> HEAD <X-Powered-By: Express
Content-Type: application/json; charset=utf-8
Content-Length: 16
ETag: W/"10-oV4hJxRVSENxc/wX8+mA4/Pe4tA"
Date: Fri, 29 Jan 2021 22:39:46 GMT
Connection: close>
[29/Jan/2021:22:39:46][1.7f56f1ffb700][-socks-] Notice: Inside backend reply callback call back pmd::rep_call
[29/Jan/2021:22:39:46][1.7f56f1ffb700][-socks-] Notice: PROXY: backendReply: from http://server_name_path/pmd/api/program/25689/logo?user_id=1234
HTTP/1.1 200 OK
X-Powered-By: Express
Content-Type: application/json; charset=utf-8
Content-Length: 16
ETag: W/"10-oV4hJxRVSENxc/wX8+mA4/Pe4tA"
Date: Fri, 29 Jan 2021 22:39:46 GMT
Connection: close

[29/Jan/2021:22:39:46][1.7f56f1ffb700][-socks-] Notice: PROXY: backendReply: from conn0 to conn1 towrite 223 written 223 spooled(conn1) 16
[29/Jan/2021:22:39:46][1.7f56f1ffb700][-socks-] Notice: PROXY: spool from conn0 (exists 1) to conn1 (exists 1): condition r
[29/Jan/2021:22:39:46][1.7f56f1ffb700][-socks-] Notice: PROXY: ... auto closing conn0 manual conn1: http://server_name_path/pmd/api/program/25689/logo?user_id=1234 (suspended 0)
[29/Jan/2021:22:39:46][1.7f56f1ffb700][-socks-] Notice: PROXY: cleanup channel conn1, spooled 16 bytes (to spool 16)

This next segment is where the upload failed. The file size is : 789 kB (The upload also fails with a file size of 453 kB.)

[29/Jan/2021:22:39:46][1.7f56f1ffb700][-socks-] Notice: PROXY: cleanup channel conn5, spooled 37844 bytes (to spool 37844)
[29/Jan/2021:22:42:49][1.7f570aacf700][-conn:server_name:1:11-] Notice: Inside validation call back pmd::val_call
[29/Jan/2021:22:42:49][1.7f570aacf700][-conn:server_name:1:11-] Notice: PROXY: upstream: send max 16000 bytes from string to conn6 (length 808993)
[29/Jan/2021:22:42:49][1.7f570aacf700][-conn:server_name:1:11-] Notice: PROXY: upstream: send max 16000 bytes from string to conn6 (length 808993)
... There are 51 of these lines here in total.  I have eliminated them here for brevety ...
[29/Jan/2021:22:42:49][1.7f570aacf700][-conn:server_name:1:11-] Notice: PROXY: upstream: send max 16000 bytes from string to conn6 (length 808993)
[29/Jan/2021:22:42:49][1.7f570aacf700][-conn:server_name:1:11-] Notice: PROXY: upstream: send max 16000 bytes from string to conn6 (length 808993)
[29/Jan/2021:22:42:49][1.7f570aacf700][-conn:server_name:1:11-] Notice: PROXY: backendChan conn6 frontendChan conn7 method POST version 1.0 http://server_name_path/pmd/api/program/25689/logo?user_id=1234
[29/Jan/2021:22:42:59][1.7f56f1ffb700][-socks-] Notice: PROXY: spool from conn7 (exists 1) to conn6 (exists 1): condition t
[29/Jan/2021:22:42:59][1.7f56f1ffb700][-socks-] Notice: PROXY: timeout occurred while spooling conn7 to conn6
[29/Jan/2021:22:42:59][1.7f56f1ffb700][-socks-] Notice: PROXY: ... auto closing conn7 manual conn6: client (suspended 0)
[29/Jan/2021:22:42:59][1.7f56f1ffb700][-socks-] Notice: PROXY: cleanup channel conn6, spooled 0 bytes (to spool ???)

Here is the last part of another run that started the same but ended slightly differently after the 51 "send max ..." lines with the following ...

...
[29/Jan/2021:17:28:03][1.7fe179e74700][-conn:server_name:1:6-] Notice: PROXY: upstream: send max 16000 bytes from string to conn12 (length 808991)
[29/Jan/2021:17:28:03][1.7fe179e74700][-conn:server_name:1:6-] Notice: PROXY: backendChan conn12 frontendChan conn13 method POST version 1.0 http://server_name_path/pmd/api/program/25689/logo?user_id=1234
[29/Jan/2021:17:28:13][1.7fe1697fa700][-socks-] Notice: PROXY: timeout occurred while waiting for backend reply conn12 to conn13
[29/Jan/2021:17:28:13][1.7fe1697fa700][-socks-] Notice: PROXY: backendReply: ... auto closing conn12 http://server_name_path/pmd/api/program/25689/logo?user_id=1234

I am not sure which side is timing out, but I believe it is the Node side given the more verbose logging. You can see, in the first failed output that there is 10 seconds between the Notice: PROXY: backendChan... and the next line with a condition t. When I set the three timeout params to 60 seconds the time difference extends to 60 seconds. So all of the upstream: send max... lines happen immediately and then things just stop until the timeout time is passed and then the other lines get logged. However, if I make a request to upload the file directly from the client browser to the Node server, there is not a timeout and the upload succeeds on the files that fail going through NaviServer as the reverse proxy. Also, your link to the updated code you mention is an update to ns_http run|queue. I am not sure how that applies. Is it something that is used automatically when using the revproxy or is it something that I have the ability to manipulate from withing the ::revproxy::upstream call?

From this information does it appear that I have configured the revproxy correctly and the problem is with the upstream server or have I misconfigured the revproxy in some way?

Thank you very much for any help you can give.

-Tony