Hi,

I've been getting these regularly.

By changing http.c as follows:

        /* get the response */
        for(skip = 1; skip;) {
            if((headers = get_headers(be, cl)) == NULL) {
                //logmsg(LOG_WARNING, "response error read from %s:%hd:
%s",
                    inet_ntoa(srv->sin_addr), ntohs(srv->sin_port),
strerror(errno));
                err_reply(cl, h500, e500);
                clean_all();
                pthread_exit(NULL);
            }

To

        /* get the response */
        for(skip = 1; skip;) {
            if((headers = get_headers(be, cl)) == NULL) {
                logmsg(LOG_WARNING, "response error read from %s:%hd:
%s",
                    inet_ntoa(srv->sin_addr), ntohs(srv->sin_port),
strerror(errno));
                //err_reply(cl, h500, e500);
                clean_all();
                pthread_exit(NULL);
                return(NULL);
            }

Tho not very elegant, it does reduce the number of times I get a failed
request, as it seems most clients will simply retry the request when
getting a zero sized reply.

Of course, I now get tons of: 'response error read from ' messages in
the logs.

This happens most often on sites that use php on the backend.

Please help!


... John

On Tuesday 07 September 2004 00.44, John Hansen wrote:[...]

What is it you are trying to achieve with it? Perhaps if you explained the 
problem we could look together for a solution...[...]

> What is it you are trying to achieve with it? Perhaps if you [...]

I run a website with two backends with the horde/imp framework for webmail
access.
When accessing the webmail, users frequently get the 500 internal server error
returned by pound.

It appears to be something to do with bad headers, but must be pound related,
since if I bypass pound, everything works just fine.

By not returning the 500 page, it seems IE will retry, but every now and then
this fails too, and you just get IE's standard DNS or
Server error page.

... John

On Tuesday 07 September 2004 15.07, John Hansen wrote:[...]

So find out what the real problem is. Headers are unlikely - Pound just 
discards the bad ones, but the request goes through. More likely you may need 
to enable "unsafe" or WebDAV or similar. Going by your previous post it may 
also be a time-out issue - try playing with Client.[...]

> [...]

This is the error pound gives after my little change:
pound: response error read from 192.168.63.6:80: Success 
Or
pound: response error read from 192.168.63.7:80: Success


So, for some reason pound receives what it believes to be a bad response when
it tries to connect to the backend, and will without
the change return a 500 internal server error.

I have WebDAV enabled in pound and CheckURL 0

... John

On Tuesday 07 September 2004 23.07, John Hansen wrote:[...]

What version are you using? This looks like something quite ancient, certainly 
nothing like -current.

Timeouts for the back-end are controlled by the Server parameter - you may 
want to play with that, as I suggested in a previous post.

Disabling a valid response is not an acceptable solution.[...]

> What version are you using? This looks like something quite [...]

pound-current, as you updated it yesterday.
[...]

I've tried using values from 0 to 60, but all with the same result.
Also, I don't believe it's a timeout issue, since the e500 happens almost
immediately after clicking a link for example.
[...]

No, which is exactly why I posted this problem.

... John

On Wednesday 08 September 2004 15.14, John Hansen wrote:[...]

Pound-current would give you a clear indication of why the error occurred, 
such as "request URI too long" or "too many headers" or even "headers: out of 
memory" as the preceding message in the logs. Please check again - there 
simply is no way for your error to appear on its own (barring a bug I am not 
aware of).

Have you checked stuff like --enable-unsafe and/or --enable-msdav in the 
config?[...]

> Pound-current would give you a clear indication of why the [...]

Sep  8 23:31:54 james pound: response error read from 192.168.63.7:80: Success
This logmessage preceeds the e500 as the only pound message.

[...]

Configure command:

./configure --sysconfdir=/etc/pound --enable-msdav --enable-unsafe

Pound.cfg:
------------------------------
User            nobody
Group           nogroup

ExtendedHTTP    1
Loglevel        0
Alive           30
Client          10
Server          0

CheckURL        0
RewriteRedirect 0
WebDAV          1

ListenHTTP      192.168.63.1,80
ListenHTTPS     192.168.63.1,443 /etc/ssl/private/server.key
HTTPSHeaders    0 "Front-End-Https: on"

UrlGroup ".*"
HeadRequire Host "webmail\..*"
BackEnd 192.168.63.6,80,1
BackEnd 192.168.63.7,80,1
SESSION IP 3600
EndGroup

On Wednesday 08 September 2004 15.38, John Hansen wrote:[...]

What happens if I access your instance via an IP address rather than a 
symbolic host name (try going to http://192.168.63.1 for example)? All of a 
sudden I have no Host header, thus no UrlGroup matches, thus an Error 500. 
What if I get there via some DNS alias that does not start in webmail? Do you 
find that to be a Pound problem?

Are you really sure that your errors are really connected to back-end 
problems?[...]

> What happens if I access your instance via an IP address [...]

Actually that would give a 503, service not available
[...]

In the configuration posted I left out all other urlgroups, there is for
example a catch-all, but getting there using some other
alias would send you to www, not return e500.
[...]

I'm quite sure they are not backend problems, since as I said earlier, if I
turn pound off, and simply do SNAT to one of the
backends (I've tested both of them this way) the problem goes away.

Also note that when the e500 does happen, hitting the refresh button in the
browser, once or twice, reloads the page.

Problem is inconsistent, (intermittent).
For example, the webmail has a button that will refresh the Inbox. Hitting this
button sometimes gives an e500, with the 'response
error read from 192.168.63.7:80: Success' message in the logs, tho most the
time it reloads the page ok.

... John

We have been seeing intermittent 500 errors.  While I have not been able
to demonstrate it as of yet, it does appear to be Pound related.

On Thu, 9 Sep 2004, John Hansen wrote:
[...]

After playing around a little, I've found that by disabling keepalive on the
backend (Apache 1.3) this problem goes away.

However turning it off hurts performance under heavy load.

Does that help in tracking down the problem?

... John
[...]

I take that back.

It still happens.... :(

... John 
[...]

On Thursday 09 September 2004 12.28, John Hansen wrote:[...]

On looking at the code the only way you can get a 500 without a preceding log 
message if by having a time-out on the server. To test:

(http.c, lines 401 and on)

if(res <= 0) {
       /* this is expected to occur only on client reads */
       logmsg(LOG_WARNING, "headers: bad starting read");   <-- uncomment
here
       return NULL;
} else if(res >= (MAXBUF - 1)) {
       /* check for request length limit */
       logmsg(LOG_WARNING, "headers: request URI too long");
       err_reply(cl, h414, e414);
       return NULL;
}

This will tell you that you had a timeout. It will also appear very often on 
client time-outs, thus filling your logs, but for a test that should be
OK.[...]

> On looking at the code the only way you can get a 500 without [...]

Indeed, I now get 'headers: bad starting read' prior to 'response error read
from ...'
Now the question is, why does this happen only when pound is between the
browser and the backend.
If I access the backend directly, everything is fine, at least from the clients
perspective all pages load fine.

... John

On Thursday 09 September 2004 15.57, John Hansen wrote:[...]

...and the answer is "because your client's timeout is MUCH longer than 
Pound's". Most browsers have a very long timeout (a couple of minutes at 
least). As I already said try setting your Server value to some high value 
(120 would be a good start, but it's not a science, so you need a bit of 
trial and error here).

You may also want to look at your back-end servers and network setup to find 
out why it takes such a long time to get a response, but that's a separate 
question. Networking congestion/collisions and/or network buffer starvation 
on the Pound machine could explain a lot. You could also try tuning your 
networking parameters some.

Never forget that, while a client runs alone on its machine, Pound has a large 
number of connections all at once.[...]

> ...and the answer is "because your client's timeout is MUCH [...]

This doesn't makes sense. As I mentioned earlier, I get this error after
clicking on the inbox icon, and the error appears more or
less instantly, less than 1 second after I click.

Thus, it's definitely not a timeout issue.
[...]

As above, responses are instant, congestion on this network is minimal, the
512K connection is currently doing 6k/s.

This is the machine running pound: http://fw1.oztralis.com.au/phpsysinfo/
[...]


... John

On Thursday 09 September 2004 17.00, John Hansen wrote:[...]

Add the errno to your log messages - if you see EIO you have some other 
problem. Look at the bio_callback() function in http.c to see how it works. 
It may well be that you have network buffer starvation or something similar. 
In any case it is clear that Pound tries to read the response from the 
back-end and fails.[...]

> Add the errno to your log messages - if you see EIO you have [...]

Sep 10 01:19:21 fw1 pound: headers: bad starting read : Success
Sep 10 01:19:21 fw1 pound: response error read from 192.168.63.6:80: Success

Followed by the infamous e500.

... John

On Thursday 09 September 2004 17.20, John Hansen wrote:[...]

So it seems you got an EOF from the back-end (that's about the only way to get 
that message). To make sure change the code at http.c line 401 to 
differentiate between error (res < 0) and EOF (res == 0).

You may also want to put an instance of tcpwatch between Pound and the 
back-end to see exactly what the problem is.[...]

[...]

Sep 10 01:35:39 fw1 pound: headers: bad starting read : EOF
Sep 10 01:35:39 fw1 pound: response error read from 192.168.63.7:80: Success
[...]

This I wouldn't have a clue how to do, or what to look for...
Mind giving some hints?

... John

On Thursday 09 September 2004 17.37, John Hansen wrote:[...]

As expected.
[...]

Download and unpack tcpwatch from http://hathawaymix.org/Software/TCPWatch
on 
the same machine as Pound. Start tcpwatch listening on some port on the local 
machine and forwarding to the back-end

tcpwatch.py -L 127.0.0.1:20080:192.168.1.7:80

Change your Pound config so that the tcpwatch host and port (127.0.0.1 and 
20080) are defined as the back-end.

From now on requests to Pound are sent to tcpwatch, which in turn sends them 
to the real back-end. All the traffic is thus visible. Sit back, watch and 
enjoy. Try to understand why the back-end closes the connection. Let us know 
what you find out. Admire the setting sun.[...]

./tcpwatch.py -L 127.0.0.1:20080:192.168.63.7:80
Traceback (most recent call last):
  File "./tcpwatch.py", line 1485, in ?
    main(sys.argv[1:])
  File "./tcpwatch.py", line 1427, in main
    obs_factory, mainloop = setupTk(titlepart, config_info, colorized)
  File "./tcpwatch.py", line 475, in setupTk
    import Tkinter
ImportError: No module named Tkinter 


Ack.... I don't have X on any machine.... :(

Am Donnerstag, 9. September 2004 18:16 schrieb John Hansen:[...]

well, well, try tcpwatch.py --help

-s   Output to stdout instead of a Tkinter window

-r <path>  (synonyms: -R, --record-directory)
    Write recorded data to <path>.  By default, creates request and
    response files for each request, and writes a corresponding error
    file for any error detected by tcpwatch.


Cheers, Sascha
[...]

Ok,

This is the last of the TCPwatch output:
Attached the last 3 files from the watch folder.

It appears there is no indication why the backend closed the connection.

... John

[00:00.000 - client 127.0.0.1:57814 forwarded to 192.168.63.7:80]
==>GET /horde/imp/mailbox.php?mailbox=INBOX HTTP/1.0
==>Accept: image/gif, image/x-xbitmap, image/jpeg, image/pjpeg,
application/x-sh
ockwave-flash, application/vnd.ms-excel, application/vnd.ms-powerpoint,
applicat
ion/msword, */*
==>Referer: http://webmail.oztralis.net.au/horde/imp/mailbox.php?mailbox=INBOX
==>Accept-Language: en-au
==>Accept-Encoding: gzip, deflate
==>User-Agent: Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.1; SV1;
GeekNET;
.NET CLR 1.1.4322; Alexa Toolbar)
==>Cookie: Horde=1765a2596630e9eae01ab0294ae16837
==>Via: 1.1 nme-pow-pr2.tpgi.com.au:3128 (squid/2.5.STABLE3)
==>X-Forwarded-For: 220.244.63.182
==>Host: webmail.oztralis.net.au:80
==>Cache-Control: max-age=259200
==>Connection: keep-alive
==>X-Forwarded-For: 220.244.224.41
==>
[00:00.002 - server connected]
[00:00.504 - server closed]
TCPWatch finished.

On Thursday 09 September 2004 19.16, John Hansen wrote:[...]

So, Pound forwards the request correctly to your back-end. The back-end 
receives the request and immediately closes the connection. Pound observes 
this and replies with 500. Do you find that to be a problem, and if yes, why? 
What would you do different?

Why the back-end closes the connection rather than answering the request is 
left as an exercise.[...]

> So, Pound forwards the request correctly to your back-end. [...]

Obviously this should not happen, but it appears it does. Others have
experienced this too.
[...]

I would do what it seems most if not all browser do: retry the request, and
only after a set number of retries, abort with the e500.
[...]

Yes, that would be interresting to find out, but is beyond me unfortunately.

... John

On Friday 10 September 2004 16.02, John Hansen wrote:[...]

Yes, but nobody seems to know why...
[...]

That's something you can do in a browser, but can't really afford in a reverse 
proxy/load balancer. You'd run out of resources very fast.
[...]

It is however the very heart of the matter: the real problem is the way your 
back-end behaves, breaking just about every RFC I can think of. BTW, it's 
very unlikely that this is an Apache issue, as we would have seen it ages 
ago. Much more likely that you have a problem with your application.

If you want to try and look into it: the only differences between a browser 
request and what tcpwatch shows us are

- the Host header (port :80 appended)
- additional X-Forwarded-for header (the original would have had only one)

Have a look at how your application may be affected by those.[...]

> On Thursday 09 September 2004 19.16, John Hansen wrote:[...][...]

Maybe it's a problem with apache processes segfaulting. I had this problem
with squirrelmail, where the root of the problem seems to be in php,
somewhere in the regex code. The only solution I found was to start a new
apache process per request with
MaxRequestsPerChild 1
in the apache config. Since then it works without any problem.
Did you check the apache logs? Maybe you may want to give it a try.

Simon

> Maybe it's a problem with apache processes segfaulting. I had [...]

Yes, there is nothing in the logs to suggest this.