Odd timeouts reading requests despite successful serving of requests

[ltning]

New day, new issue.

Consider these requests from a browser (private window for a "clean" access):

Mar 12 01:29:24 wii pound[27891]: 84.214.145.66 GET /ltning/p/1773014130.033156 HTTP/1.1 - HTTP/1.1 200 OK
Mar 12 01:29:24 wii pound[27891]: 84.214.145.66 GET /ltning/s/header-2afc7c64cee85f82e9f47e383efa6829.jpg HTTP/1.1 - HTTP/1.1 200 OK
Mar 12 01:29:24 wii pound[27891]: 84.214.145.66 GET /ltning/s/avatar-1122131a322ac7a58db83a2ce72c763b.png HTTP/1.1 - HTTP/1.1 200 OK
Mar 12 01:29:24 wii pound[27891]: 84.214.145.66 GET /ltning/s/post-9b83fa97cc906336a536800f4e344948.png HTTP/1.1 - HTTP/1.1 200 OK
Mar 12 01:29:24 wii pound[27891]: 84.214.145.66 GET /favicon.ico HTTP/1.1 - HTTP/1.1 200 OK

Then 10 seconds later, presumably after the Client timeout has fired, the following log entries show up:

Mar 12 01:29:34 wii pound[27891]: (fc868000) read error
Mar 12 01:29:34 wii pound[27891]: (fc868000) e500: 84.214.145.66: error reading request: Operation timed out
Mar 12 01:29:34 wii pound[27891]: 84.214.145.66  - HTTP/1.0 500 Internal Server Error
Mar 12 01:29:34 wii pound[27891]: (fc86aa00) read error
Mar 12 01:29:34 wii pound[27891]: (fc86aa00) e500: 84.214.145.66: error reading request: Operation timed out
Mar 12 01:29:34 wii pound[27891]: 84.214.145.66  - HTTP/1.0 500 Internal Server Error
Mar 12 01:29:34 wii pound[27891]: (fc869c00) read error
Mar 12 01:29:34 wii pound[27891]: (fc869c00) e500: 84.214.145.66: error reading request: Operation timed out
Mar 12 01:29:34 wii pound[27891]: 84.214.145.66  - HTTP/1.0 500 Internal Server Error

I do not see this from all inbound requests, but it is entirely reproducible from my Firefox. It is also interesting to see that the browser console reports no issues. A packet capture (attached) shows that 10 seconds after the request, a series of FIN+ACK comes from the server to the client, indicating that the browser is keeping a keepalive session which the server is shutting down, however it is mis-interpreting this as a failure to read the client request.

Is there a way to tune the keepalive settings in pound? This does not feel like something that should be logged as an error.

wiicafe.pcap.zip

[graygnuorg]

This is normal behavior. Being a proxy, pound cannot keep connections indefinitely: this would create too wide a surface for ddos. Instead, its behavior is controlled by a set of timeouts. The time to wait for the next request from the client is defined by Client setting and is 10 seconds by default. You can tune it to your liking, if the default does not suit you.

[ltning]

Yeah the behaviour is correct (although it would be useful with a separate "KeepAlive" timeout, so the timeout for waiting for a client request and the time to keep a connection alive could be configured differently). My question is about the logging: It is emitted as if it were an error, and a HTTP 500 at that (across two log lines); is this really necessary?

[graygnuorg]

You are right, this is spurious. I'll revise the log messages.

[graygnuorg]

Fixed in commit e37b286. Additionally, commit c9fac59 forces metric agents to close connection, thereby avoiding another spurious 'Connection timed out' message.