Forum OpenACS Q&A: NaviServer stops serving connections when slow external api calls pile up.

ad_try {
set result [ns_http run -method GET -headers $request_headers -expire $timeout $url]
} trap NONE {result options} {

} trap CHILDSTATUS {result options} {

} on error {result options} {

} finally {

}

However, the 'expire $timeout' option does not seem to work in all situations and then the thread gets stuck waiting for the ns_http return

Please notice, that all time periods passed to NaviServer are in seconds if not specified differently. Calling

ns_http ... -expire 500 ...

ns_http ... -expire 500ms ...
ns_http ... -expire 0.5s ...

Note, that there are many possible causes to endanger the liveliness of a system when depending on external services (which might take "forever", or "hang" or which might terminate on service restarts, or which might have a high variance in performance, etc.).

When you configure the HTTP client log [1] (introduced with 4.99.21) and you use a recent version of the nsstats module (checkout Bitbucket), you can get the statistics about the ns_http requests, similar to the access.log. With this you can identify certain potential bottlenecks.

When the HTTP-requests needed by your application are slow or unreliable, throwing in more cores or memory does not help. However, you can use a separate connection pool for such requests, or you have to use some background processing (like e.g. with ns_jobs).

[1] https://bitbucket.org/naviserver/naviserver/src/cdf5cb353b72e3b1560eaeb263d8dd898370634b/openacs-config.tcl#lines-640

Sorry about the confusion. When I typed in the set timeout 500 I inadvertently left off the ms. We are using 500ms as the value passed for the -expire argument.

With that information corrected our questions are still the same and any help you can give is greatly appreciated.

I have test cases where I set the -expire to 50ms and the expiration occurs as expected decoupling the target system from ours. The ssl error case is one that we cannot seem to manually reproduce and I am now wondering if the problem is rooted in the ssl connect failed problem. Is there a chance that the expiration timeout is not in affect while the ssl connection is being made? The symptoms we are seeing appear like the ssl connection has to be made before the timeout can cause a release of the call and return of control when the timeout is reached. Is this a possible issue and what can be done to fix it?

Thanks again for all of your help,

-Tony Kirkham

Thank you for your earlier responses. I have sifted through our earlier logs to gather more information to, hopefully, more precisely describe the issue we are seeing.

To restate: we are seeing issues where ns_http does not timeout and return after the specified expire value. We cannot seem to manually, intentionally reproduce the problem. When it happens, it seems that we are either having network issues or there is a problem with the target system but, we have not been able to identify these details during an incident. It is precisely these conditions under which we would want ns_http to be able to timeout and abandon the request, releasing the attempted connection to the target system, and returning to finish processing the current request to NaviServer.

Instead we experience ns_http not timing out with more and more requests stacking up and the system getting bogged down. The current fix when this occurs, since we have access, is to restart the target system. Once we do, NaviServer returns to its functioning state.

So, in short, the timeout works if all is well with the network and the target system. If the request just takes longer than desired, it will timeout. However, if there are "other problems", the timeout does not work.

After your last comment about the -expire and the -timeout arguments to ns_http, I have done a considerable amount of testing where I am able to verify that they both work as described in the documentation, under normal, functioning conditions. In my case, I have found the successful threshold using -timeout 134ms and -expire 152ms. Shortening either of these values by 1 or 2 ms will normally cause the call to timeout. So I know that the timeout does work under normal conditions.

With all of that said, here are some log entries that show the problem as we experienced it during the last event. There are several requests to the target system shown. There are timings reported and the response from the call. These are listed sequentially as they were logged. Any log entries that did not pertain to the call in question are replaced with ... (3 dots). The call to the target system is made inside a process that gathers and returns a bunch of information. The log includes a run_num: that is a unique, random string to identify the process run (this was added to try to debug this issue), a start run time: and end run time: which is the time from the start of the process to right before the call is made and right after the call returns, respectively, the call: being made, the error (if there was one), and the dur:, the duration of the call (which is the difference between the start and end times). There are comments added before each process instance indicating if it was successful or not and whether the result was expected or not. This shows that the system went from timing-out correctly to "ignoring" the timeout and not returning for up to 30 seconds.

I will dissect the first instance in an attempt to explain the information provided and to set the pattern that the others follow.

######  -- Correct timeout
[04/Jan/2023:05:07:43][1.7fb883fff700][-conn:east_intra:default:19:4500-] Notice: pkg-notices: in_box_notices; run_num: 03A965C1; start run time: 1537 ms; call: wt::jira::notice::get_notice

The above, first entry, indicates that the response was Correct and did actually timeout appropriately. It shows the time in the process right before the call is made: start run time: 1537 ms; (::get_notice contains the call to ns_http)

[04/Jan/2023:05:07:44][1.7fb883fff700][-conn:east_intra:default:19:4500-] Error: The request to Jira expired after the specified length: 500ms, for user: user1;
:     status:
:     result: http request timeout
:     error_info: http request timeout
:        while executing
:    "ns_http run -method GET -headers $request_headers -expire $timeout $url"
:        ("::try" body line 4)
[04/Jan/2023:05:07:44][1.7fb883fff700][-conn:east_intra:default:19:4500-] Notice: The request to Jira for approval notices did not contain a group element. error message: {The request to Jira expired}

The above few lines show the result of the call. This call did in fact timeout and the response contained the result error information about the http request timing out.

[04/Jan/2023:05:07:44][1.7fb883fff700][-conn:east_intra:default:19:4500-] Notice: pkg-notices: in_box_notices; run_num: 03A965C1; end   run time: 2071 ms; call: wt::jira::notice::get_notice; dur: 534 ms

The above line shows the time right after the call which indicates the end run time: 2071 ms which then has a corresponding duration of dur: 534 ms. To make sure that this "end" entry corresponds with the above "start" entry, the run_num: 03A965C1 identifies these entries as belonging to the same "process instance". Yes, this is slightly longer than the 500 ms for the timeout but, there is the surrounding call and return that can account for that additional time.

The following are additional log excerpts showing subsequent calls with their entries following the same pattern as this one just explained.

######  -- Correct timeout
[04/Jan/2023:10:28:12][1.7fb8cfc7e700][-conn:east_intra:default:4:64408-] Notice: pkg-notices: in_box_notices; run_num: D9D43629; start run time: 1630 ms; call: wt::jira::notice::get_notice
...
[04/Jan/2023:10:28:12][1.7fb8cfc7e700][-conn:east_intra:default:4:64408-] Error: The request to Jira expired after the specified length: 500ms, for user: user2;
:     status:
:     result: http request timeout
:     error_info: http request timeout
:        while executing
:    "ns_http run -method GET -headers $request_headers -expire $timeout $url"
:        ("::try" body line 4)
[04/Jan/2023:10:28:12][1.7fb8cfc7e700][-conn:east_intra:default:4:64408-] Notice: The request to Jira for approval notices did not contain a group element. error message: {The request to Jira expired}
[04/Jan/2023:10:28:12][1.7fb8cfc7e700][-conn:east_intra:default:4:64408-] Notice: pkg-notices: in_box_notices; run_num: D9D43629; end   run time: 2162 ms; call: wt::jira::notice::get_notice; dur: 532 ms

######  -- Successful run NO timeout
[04/Jan/2023:13:18:42][1.7fb8cdc7a700][-conn:east_intra:default:8:108041-] Notice: pkg-notices: in_box_notices; run_num: DDF11C73; start run time: 1606 ms; call: wt::jira::notice::get_notice
...
[04/Jan/2023:13:18:42][1.7fb8cdc7a700][-conn:east_intra:default:8:108041-] Notice: pkg-notices: in_box_notices; run_num: DDF11C73; end   run time: 2034 ms; call: wt::jira::notice::get_notice; dur: 428 ms

######  -- Bad run, does not appear to timeout but has a duration of longer than 500 ms and no timeout  It is possible that the http call timed out but, something else got stuck or that it did not log the error response correctly. Wat!
[04/Jan/2023:13:18:51][1.7fb8a6ffd700][-conn:east_intra:default:21:108096-] Notice: pkg-notices: in_box_notices; run_num: 4F6A7C4C; start run time: 1708 ms; call: wt::jira::notice::get_notice
...
[04/Jan/2023:13:18:55][1.7fb8a6ffd700][-conn:east_intra:default:21:108096-] Notice: pkg-notices: in_box_notices; run_num: 4F6A7C4C; end   run time: 5552 ms; call: wt::jira::notice::get_notice; dur: 3844 ms {{no timeout?}}

######  -- Bad run timed out but long after the 500 ms
[04/Jan/2023:13:19:45][1.7fb8cec7c700][-conn:east_intra:default:5:108393-] Notice: pkg-notices: in_box_notices; run_num: 2C241021; start run time: 1562 ms; call: wt::jira::notice::get_notice
...
[04/Jan/2023:13:19:55][1.7fb8cec7c700][-conn:east_intra:default:5:108393-] Error: The request to Jira expired after the specified length: 500ms, for user: user3;
:     status:
:     result: http request timeout
:     error_info: http request timeout
:        while executing
:    "ns_http run -method GET -headers $request_headers -expire $timeout $url"
:        ("::try" body line 4)
[04/Jan/2023:13:19:55][1.7fb8cec7c700][-conn:east_intra:default:5:108393-] Notice: The request to Jira for approval notices did not contain a group element. error message: {The request to Jira expired}
[04/Jan/2023:13:19:55][1.7fb8cec7c700][-conn:east_intra:default:5:108393-] Notice: pkg-notices: in_box_notices; run_num: 2C241021; end   run time: 11185 ms; call: wt::jira::notice::get_notice; dur: 9623 ms

######  -- Bad run timed out but long after the 500 ms
[04/Jan/2023:13:19:49][1.7fb8cdc7a700][-conn:east_intra:default:8:108439-] Notice: pkg-notices: in_box_notices; run_num: D9370223; start run time: 1648 ms; call: wt::jira::notice::get_notice
...
[04/Jan/2023:13:20:02][1.7fb8cdc7a700][-conn:east_intra:default:8:108439-] Error: The request to Jira expired after the specified length: 500ms, for user: user4;
:     status:
:     result: http request timeout
:     error_info: http request timeout
:        while executing
:    "ns_http run -method GET -headers $request_headers -expire $timeout $url"
:        ("::try" body line 4)
[04/Jan/2023:13:20:02][1.7fb8cdc7a700][-conn:east_intra:default:8:108439-] Notice: The request to Jira for approval notices did not contain a group element. error message: {The request to Jira expired}
[04/Jan/2023:13:20:02][1.7fb8cdc7a700][-conn:east_intra:default:8:108439-] Notice: pkg-notices: in_box_notices; run_num: D9370223; end   run time: 13709 ms; call: wt::jira::notice::get_notice; dur: 12061 ms

###### -- SSL connect failed and does not timeout for 30 seconds!
[04/Jan/2023:13:19:52][1.7fb8a7fff700][-conn:east_intra:default:11:108445-] Notice: pkg-notices: in_box_notices; run_num: B881E1A9; start run time: 1675 ms; call: wt::jira::notice::get_notice
...
[04/Jan/2023:13:20:23][1.7fb8a7fff700][-conn:east_intra:default:11:108445-] Error: The request to Jira appeared to succeed but, the result variable did not contain an http status.  Additional info follows:
:     status:
:     result: ssl connect failed: error:00000000:lib(0):func(0):reason(0)
:     error_info: ssl connect failed: error:00000000:lib(0):func(0):reason(0)
:        while executing
:    "ns_http run -method GET -headers $request_headers -expire $timeout $url"
:        ("::try" body line 4)
[04/Jan/2023:13:20:23][1.7fb8a7fff700][-conn:east_intra:default:11:108445-] Notice: The request to Jira for approval notices did not contain a group element. error message: {The request to Jira appeared to succeed but,}
[04/Jan/2023:13:20:23][1.7fb8a7fff700][-conn:east_intra:default:11:108445-] Notice: pkg-notices: in_box_notices; run_num: B881E1A9; end   run time: 32666 ms; call: wt::jira::notice::get_notice; dur: 30991 ms

######  -- Super bad run no ssl error, timeout but appears to be stuck for 4 minutes!
[04/Jan/2023:13:21:29][1.7fb8a7fff700][-conn:east_intra:default:11:108951-] Notice: pkg-notices: in_box_notices; run_num: E5E4A969; start run time: 1639 ms; call: wt::jira::notice::get_notice
...
[04/Jan/2023:13:25:30][1.7fb8a7fff700][-conn:east_intra:default:11:108951-] Error: The request to Jira expired after the specified length: 500ms, for user: user5;
:     status:
:     result: http request timeout
:     error_info: http request timeout
:        while executing
:    "ns_http run -method GET -headers $request_headers -expire $timeout $url"
:        ("::try" body line 4)
[04/Jan/2023:13:25:30][1.7fb8a7fff700][-conn:east_intra:default:11:108951-] Notice: The request to Jira for approval notices did not contain a group element. error message: {The request to Jira expired}
[04/Jan/2023:13:25:30][1.7fb8a7fff700][-conn:east_intra:default:11:108951-] Notice: pkg-notices: in_box_notices; run_num: E5E4A969; end   run time: 242778 ms; call: wt::jira::notice::get_notice; dur: 241139 ms

This last excerpt is from a recent run and shows what happens if the url being requested does not exist. This is another data point to show the behavior of ns_http under different conditions in an attempt to reproduce the problems we are seeing. This, as can be seen, returns with the error even before the timeout is reached, which is what I would expect it to do.

###### -- Different time completely but checking if the url cannot be resolved: using a non-existing url
[19/Jan/2023:04:51:40][1.7f1524b09700][-conn:tkirkham_intrapg14a:default:4:4660-] Notice: pkg-notices: in_box_notices; run_num: BA7BA78D; start run time: 1757 ms; call: wt::jira::notice::get_notice
[19/Jan/2023:04:51:40][1.7f1524b09700][-conn:tkirkham_intrapg14a:default:4:4660-] Warning: SockConnect could not resolve host jirabad.com
[19/Jan/2023:04:51:40][1.7f1524b09700][-conn:tkirkham_intrapg14a:default:4:4660-] Error: The request to Jira appeared to succeed but, had additional info. (run_num: BA7BA78D) The result variable did not contain an http s
tatus.  The request took: 3 ms, for user: user1;. Additional info follows:
:     status:
:     result: can't connect to jirabad.com port 443: reason unknown
:     error_info: can't connect to jirabad.com port 443: reason unknown
:        while executing
:    "ns_http run -method GET -headers $request_headers -timeout $timeout -expire $expire_after $url"
:        ("::try" body line 5)
[19/Jan/2023:04:51:40][1.7f1524b09700][-conn:tkirkham_intrapg14a:default:4:4660-] Notice: The request to Jira for approval notices did not contain a group element. error message: {The request to Jira appeared to succeed but, had additional info.}
[19/Jan/2023:04:51:40][1.7f1524b09700][-conn:tkirkham_intrapg14a:default:4:4660-] Notice: pkg-notices: in_box_notices; run_num: BA7BA78D; end   run time: 1765 ms; call: wt::jira::notice::get_notice; dur: 8 ms

As it can be seen from these log entries, there are times when the ns_http call does not appear to honor the specified -timeout or -expire. It is getting stuck somewhere. We are setting up the http logging capability to see if we can see any additional information but, we will be waiting for another event to occur to be able to get any additional data. Does this additional information give any new insight into what may be causing this and how to go about finding a solution?

Thank you very much for any help you can give.

-Tony

After finding out that we had turned on the http logging a while ago, I went through and pulled out all of the http_log entries that correspond to the error_log entries I posted earlier and have listed them here along side the error_log entries. When comparing these entries note that the timing in the error_log is reported in milliseconds and the timing in the http_log is in seconds.

A couple of things of interest.

• Among the entries that Marty posted above, most of them show that the request did time out but, long after the specified expire time of 500ms. This isn't expected behavior, is it?
• The requests that show as succeeding in the error_log show a status of ok in the http_log (even the one that took over 3 seconds, weird) and those that show a timeout in the error_log show a socktimeout in the http_log. So the two logs seem to match well.
• The request that errored-out with the ssl error did not have an entry in the http_log which makes sense if it is expected that the log entry occurs after a request completes, whether or not it was successful.

######  -- Correct timeout
## error_log
[04/Jan/2023:05:07:44][1.7fb883fff700][-conn:east_intra:default:19:4500-] Notice: pkg-notices: in_box_notices; run_num: 03A965C1; end   run time: 2071 ms; call: wt::jira::notice::get_notice; dur: 534 ms
## http_log
[04/Jan/2023:05:07:44 -0700] -conn:east_intra:default:19:4500- 408 GET https://target.site.url 0.518629 250 0 socktimeout

######  -- Correct timeout
## error_log
[04/Jan/2023:10:28:12][1.7fb8cfc7e700][-conn:east_intra:default:4:64408-] Notice: pkg-notices: in_box_notices; run_num: D9D43629; end   run time: 2162 ms; call: wt::jira::notice::get_notice; dur: 532 ms
## http_log
[04/Jan/2023:10:28:12 -0700] -conn:east_intra:default:4:64408- 408 GET https://target.site.url 0.515892 249 0 socktimeout

######  -- Successful run NO timeout
## error_log
[04/Jan/2023:13:18:42][1.7fb8cdc7a700][-conn:east_intra:default:8:108041-] Notice: pkg-notices: in_box_notices; run_num: DDF11C73; end   run time: 2034 ms; call: wt::jira::notice::get_notice; dur: 428 ms
## http_log
[04/Jan/2023:13:18:42 -0700] -conn:east_intra:default:8:108041- 200 GET https://target.site.url 0.412023 255 1022 ok

######  -- Bad run, does not appear to timeout but has a duration of longer than 500 ms and no timeout  It is possible that the http call timed out but, something else got stuck. Wat!
## error_log
[04/Jan/2023:13:18:55][1.7fb8a6ffd700][-conn:east_intra:default:21:108096-] Notice: pkg-notices: in_box_notices; run_num: 4F6A7C4C; end   run time: 5552 ms; call: wt::jira::notice::get_notice; dur: 3844 ms {{no timeout?}}
## http_log
[04/Jan/2023:13:18:55 -0700] -conn:east_intra:default:21:108096- 200 GET https://target.site.url 3.828102 251 796 ok

######  -- Bad run timed out but long after the 500 ms
## error_log
[04/Jan/2023:13:19:55][1.7fb8cec7c700][-conn:east_intra:default:5:108393-] Notice: pkg-notices: in_box_notices; run_num: 2C241021; end   run time: 11185 ms; call: wt::jira::notice::get_notice; dur: 9623 ms
## http_log
[04/Jan/2023:13:19:55 -0700] -conn:east_intra:default:5:108393- 408 GET https://target.site.url 9.607222 248 0 socktimeout

######  -- Bad run timed out but long after the 500 ms
## error_log
[04/Jan/2023:13:20:02][1.7fb8cdc7a700][-conn:east_intra:default:8:108439-] Notice: pkg-notices: in_box_notices; run_num: D9370223; end   run time: 13709 ms; call: wt::jira::notice::get_notice; dur: 12061 ms
## http_log
[04/Jan/2023:13:20:02 -0700] -conn:east_intra:default:8:108439- 408 GET https://target.site.url 12.045099 250 0 socktimeout

###### -- SSL connect failed and does not timeout for 30 seconds!
## error_log
[04/Jan/2023:13:20:23][1.7fb8a7fff700][-conn:east_intra:default:11:108445-] Notice: pkg-notices: in_box_notices; run_num: B881E1A9; end   run time: 32666 ms; call: wt::jira::notice::get_notice; dur: 30991 ms
## http_log
-- no entry was found in the http log to match with this request

######  -- Super bad run no ssl error, timeout but appears to be stuck for 4 minutes!
## error_log
[04/Jan/2023:13:25:30][1.7fb8a7fff700][-conn:east_intra:default:11:108951-] Notice: pkg-notices: in_box_notices; run_num: E5E4A969; end   run time: 242778 ms; call: wt::jira::notice::get_notice; dur: 241139 ms
## http_log
[04/Jan/2023:13:25:30 -0700] -conn:east_intra:default:11:108951- 408 GET https://target.site.url 241.122625 249 0 socktimeout

Sorry, if it feels like we are bombarding this thread with a bunch of information. We are just hoping that something we are finding can help make sense of what we are experiencing.

As always, thanks for your great help,

-Tony

Sorry for the confusion on the http log I posted. I was in a hurry and used a rather simple regex to remove the url from the log and in a few cases it truncated the time on the left of the decimal point on the time. So for example the following log entry obviously had it's time truncated because it is missing a digit to the left of the decimal point. (.695438)

httpclient.log.2023-01-04:[04/Jan/2023:13:22:52 -0700] -conn:east_intra:default:17:108483- 408 GET .695438 246 0 socktimeout

However, any times that have 2 or 3 digits to the left of the decimal point are accurate times. I guess, I figured this would be enough to show that we were going past the -expired time.

Also, the log entry times that Tony verified with his comparison between the http log and his debug statements in the error.log are accurate.

Looking back I really should have taken more time with that file. Sorry about that.

We can get you the full log with context times that returned "ok" and full length url. Also, I believe we still have some VM stats for that day at around the time of the event that we can get to you

What i read from this is:
- there are a substantial number of requests sent to the servers,
- a high number of the requests are perfectly fine, during a certain time window, there were troubles.

From the more detailed file analysis, i read:
- around 13:18:50, the response time of jira increased from to 2s, ... 8s.
- starting at 13:31:39, there are may 503 results from the jira, taking around 8 seconds.
- then (e.g. at 13:31:42, or 13:31:46), there are often 50 or more requests per second where some of these were very fast (<20ms) jira requests resulting in 503 from jira
- between 13:19:40 and 13:44:37, there were no HTTP client requests answered by jira with 200.

- also, when looking only at the successful requests, the runtime of these requests went up to 20s. (13:19:14: 19.6s, 13:19:40: 13s)

- The requests ending in 408 are distributed over the full day, but normally, these take ~500ms (the specified -expire time).
- Between 13:18:59 and 13:31:26, the reported timeout times are often substantially large (5s, 18s, up to 391s), although "-expire 500ms" was used.

So, one should probably concentrate first on figuring out, why the "-expire 500ms" flag was not honored in the successful requests, since this should be easier than trying to understand what happens with the timeout cases.

Do you have any information, what was the case with the jira system in this time window (hanging, overloaded, crashed)?
Talks NaviServer directly with jira, or is there a server between (e.g. a reverse proxy, or a load balancer).
What was the time window, when NaviServer hast stopped serving requests? Did it recover by itself, or did you restart it?

Here are suggestions how to proceed:

• The first measure to improve the situation is to remove the potential queuing in the default connection pool. The simplest thing is to create a connection pool "slow". When using a recent version of the request monitor (not more than 2 years old), and a "slow" pool exists, these requests are automatically moved to this connection pool. This has the advantage, that other requests are still served as usually, even when there is queuing in the "slow" pool. See for an example of t "slow" pool in [1], but don't forget to remove the comment character in the line defining this pool.

• As a second measure, I would recommend installing the NaviServer munin plugins, since these will provide among other things monitoring of the queuing times per pool.

• Third measure: get the tip version from NaviServer from Bitbucket. I have today fixed a problem of clearing the timeout status codes (which must have been in the code since quite a long time). I do not see the direct connection to reported symptoms, but I cannot exclude, that it might be related.

• Fourth measure: when compiling NaviServer, compile it with debugging enabled "using the -g flag" and make yourself familiar how to attach GDB at runtime to nsd and how to dump the stacks of all threads in the running server [3]. In case, you see this symptom again, dump all stacks ("thread apply all bt") and mail to output to me.

How often have you experienced this problem?
Depending on your urge, I would recommend to start with the first two measures. These will also help you get more insights about the runtime behavior and potential bottlenecks on potential load peaks over the day.

Let me know what your new insights are.
all the best
-g

[1] https://bitbucket.org/naviserver/naviserver/src/f3b5ad7dcb956d0ee9251e914e20e3d585f1c7b4/openacs-config.tcl#lines-526
[2] https://github.com/gustafn/munin-plugins-ns
[3] https://stackoverflow.com/questions/18391808/how-do-i-get-the-backtrace-for-all-the-threads-in-gdb