Forum OpenACS Development: Re: Naviserver File download cancelled around 500k

2: Re: Naviserver File download cancelled around 500k (response to 1)

Posted by Gustaf Neumann on 03/03/15 08:00 AM

Hi Dave,

We have never seen such a scenario. Concerning the config file: the easiest option to test whether the config file is the culprit is to use the sample-config file for OpenACS that is shipped with naviserver. Per default, this is located in /usr/local/ns/conf/openacs-config.tcl

-g

3: Re: Naviserver File download cancelled around 500k (response to 2)

Posted by Dave Bauer on 03/11/15 06:15 PM

I did use the sample config to create my config file.

I am getting dropped connections for all kinds of things sometimes the request only takes 5-10 seconds. Slow but not anything that should timeout. I see nothing in the error logs.

4: Re: Naviserver File download cancelled around 500k (response to 3)

Posted by Gustaf Neumann on 03/12/15 03:43 AM

You say, this happens just for "downloads" via ns_return? does this happen as well with downloads form the file-storage? Do you have writer threads configured?

What version of NaviServer do you use?

In case of doubt, find out with "ns_info patchlevel" in ds/shell. If you have a recent version of NaviServer, you can turn on at runtime detailed logging from sockets with "ns_logctl severity Debug(ns:driver) on" via ds/shell. Find out about the available severities via "ns_logctl severities".

5: Re: Naviserver File download cancelled around 500k (response to 4)

Posted by Dave Bauer on 03/12/15 06:04 PM

Thanks.

I looked into this more.

There is an Amazon ECB in front of Naviserver. I don't have control over that. The requests get a 504 Gateway timeout when examined in Firefox Inspector after about 6 seconds.

Here is a quick sample of the log data. I have no idea what I am looking for. Is unable to read request a problem or might that be some sort of spam request?

[12/Mar/2015:10:02:00][6126.2aaab102f940][-driver:nssock-] Debug(ns:driver): SockError: Unable to read request (11: Resource temporarily unavailable), sock: 12, peer: 10.196.20.247:48602, request:
[12/Mar/2015:10:02:00][6126.2aaab102f940][-driver:nssock-] Debug(ns:driver): sockread returned read error; close socket
[12/Mar/2015:10:02:00][6126.2aaab102f940][-driver:nssock-] Debug(ns:driver): SockError: Unable to read request (11: Resource temporarily unavailable), sock: 11, peer: 10.196.20.247:48601, request:
[12/Mar/2015:10:02:01][6126.2aaab102f940][-driver:nssock-] Debug(ns:driver): sockread returned read error; close socket
[12/Mar/2015:10:02:01][6126.2aaab102f940][-driver:nssock-] Debug(ns:driver): SockError: Unable to read request (11: Resource temporarily unavailable), sock: 7, peer: 10.252.11.44:23749, request:
[12/Mar/2015:10:02:01][6126.2aaab102f940][-driver:nssock-] Debug(ns:driver): sockread returned read error; close socket
[12/Mar/2015:10:02:01][6126.2aaab102f940][-driver:nssock-] Debug(ns:driver): SockError: Unable to read request (11: Resource temporarily unavailable), sock: 15, peer: 10.252.11.44:23750, request:
[12/Mar/2015:10:02:04][6126.2aaab102f940][-driver:nssock-] Debug(ns:driver): sockread returned read error; close socket
[12/Mar/2015:10:02:04][6126.2aaab102f940][-driver:nssock-] Debug(ns:driver): SockError: Unable to read request (11: Resource temporarily unavailable), sock: 8, peer: 10.196.20.247:48598, request:
[12/Mar/2015:10:02:04][6126.2aaab102f940][-driver:nssock-] Debug(ns:driver): sockread returned read error; close socket
[12/Mar/2015:10:02:04][6126.2aaab102f940][-driver:nssock-] Debug(ns:driver): SockError: Unable to read request (11: Resource temporarily unavailable), sock: 16, peer: 10.196.20.247:48606, request:
[12/Mar/2015:10:02:04][6126.2aaab102f940][-driver:nssock-] Debug(ns:driver): sockread returned read error; close socket
[12/Mar/2015:10:02:04][6126.2aaab102f940][-driver:nssock-] Debug(ns:driver): SockError: Unable to read request (11: Resource temporarily unavailable), sock: 19, peer: 10.196.20.247:48607, request:
[12/Mar/2015:10:02:04][6126.2aaab102f940][-driver:nssock-] Notice: ... sockAccept accepted 2 connections

6: Re: Naviserver File download cancelled around 500k (response to 5)

Posted by Gustaf Neumann on 03/14/15 06:18 PM

Dear Dave,

i can help you more, when you answer my questions:

Does the truncation happen as well with downloads from the file-storage?
Do you have writer threads configured?
What version of NaviServer do you use?

From you reply is see just cases, where the debug output shows log lines from the input side (from different ip addresses). i would recommend to add ns_log entries before and after the ns_return statement when you send the CSV file.

What exactly is "an Amazon ECB"? I assume this is something like a reverse proxy. It the communication via SSL? How does your comment with the 504 error (usually this means "no response from upstream server") fit together with the partial result of the 500k. I can't believe you get a truncated result in the body the 504 error reply.

Do you see an entry for the request in the access.log?

7: Re: Naviserver File download cancelled around 500k (response to 6)

Posted by Dave Bauer on 03/22/15 09:56 PM

Thanks Gustaf,

It does appear the proxy is expecting a complete response within about 15 seconds and if the reply is not completed it responds with 504 to the client. I am trying to get the administrator of the proxy to give me information about what happens there.

8: Re: Naviserver File download cancelled around 500k (response to 7)

Posted by Gustaf Neumann on 03/24/15 12:04 PM

It seems, that there are more things to know to address the problem. If the result is sent via ns_return, then the problem will only appear when it takes the program more than 15 secs to generate the output. In this case, this has nothing to do with NaviServer.

Maybe it is an option for you to produce streaming output (via ns_write) as soon as you have partial results available. Most proxies send the "backend unresponsive" only when they receive no upstream output after the timeout.