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

I have been using the reverse proxy module to have NaviServer/OACS perform authentication and serve some of the URL space from a Node instance. My configuration has been working fairly well, but we have run into a problem with uploading some files. Most files upload fine, but with some we receive 504 Gateway Timeout responses. These responses seem to be size related. I am trying to figure out if this is an issue with the Naviserver reverse proxy configuration or limits set in the Node instance.

Focusing specifically on the ::revproxy::upstream call, I have configured and understand the -url_rewrite_callback arg (see here) and I can see that there are options for three timeouts: -timeout, -sendtimeout, -receivetimeout as well as other args.

What do each of these timeouts affect and where can I go to understand better the other arguments in this call?

Thanks,

-Tony

Collapse
Posted by Tony Kirkham on

I can't seem to figure out how to edit my question so I will respond to it. I have some more details that I would like to add.

I have attempted to set the -timeout and -sendtimeout args to 60 and 120 seconds and it just spins for the specified amount of time and then closes with the error. By setting the -timeout to 1 second I can make most of the uploads fail, so I know that it is affecting the request. The files that upload without a problem are on the order of 30 KB where as the file that has never succeeded is on the order of 740 KB.

Collapse
Posted by Gustaf Neumann on
Which version of NaviServer are you using? There was a change in timeout semantics this year, making the behavior more useful.

How does backend behave? Does it send data incrementally or long time nothing and all data together?

For answering these questions, you can use in revproxy-procs the "verbose" flag, and "ns_logctl severity Debug(connchan) on" (e.g. in ds/shell) to get low-level debug information.

[1] https://bitbucket.org/naviserver/naviserver/commits/177e4e66a54810ed0bf4434ed0e60510584e3b90

Collapse
Posted by Tony Kirkham on

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

Collapse
Posted by Gustaf Neumann on

First of all, i would recommend to upgrade to NaviServer 4.99.20, since there are many changes in the code, also affecting low-level I/O, connchan handling, etc. This will be much more robust also in connection with partial reads/writes and addresses changes in the behavior of newer versions of OpenSSL.

Anyhow, what i can read from your lines above is the following:

  1. setting "-timeout 10"
  2. start of request "29/Jan/2021:22:42:49"
  3. timeout" 29/Jan/2021:22:42:59" while spooling from conn7 to conn6

Well, between (2) and (3) there are 10 seconds, the timeout value. Since it spools some data to conn6, i would assume that conn6 is the client (browser) and conn7 is the backend (node) . Since there is no reply from conn7 within this time span, the timeout occurs.

One question is, what happens on the node side? Maybe there are some entries in the log-file?

You can intensify the logging by turning on more log levels on the NaviServer side, especially on connchan. When you add for example the following line to the begin of the revproxy-procs, then you get more detailed information (be careful, if this is a busy site, you might get too much). One can certainly turn more detailed logging dynamically (maybe per revproxy PUT requests, but you have to add activation/deactivation yourself to the proc).


ns_logctl severity Debug(connchan) on