Bug #2412
closed%T in accesslog.format doesn't work as expected
Description
I am using the following configuration:
accesslog.format = "%h l %u %t \"%r\" %>s %b %Ts \"{Referer}i\" \"%{User-Agent}i\""
the differenc to the default formatting is the %Ts which is according to doc: time used in seconds
expected:
it should show the real time the request took.
what it does:
I do requests at /foo/bar.php with an average response time of 200ms.
At some of the requests it show the time since the last request. Not the processing time.
It appears, that it only occurs at requests from a high level browser. Not with java library or wget.
The interesting thing is the wrong line in the log file is immediately (0-2s) after the request written even if it says 15s in the log.
log:
X.X.X.X - - [17/Apr/2012:13:40:03 +0200] "POST /foo/bar.php HTTP/1.0" 200 833 0s "-" "Axis/1.4"
X.X.X.X - - [17/Apr/2012:13:40:16 +0200] "POST /foo/bar.php HTTP/1.0" 200 833 2s "-" "Axis/1.4"
X.X.X.X - - [17/Apr/2012:13:40:21 +0200] "POST /foo/bar.php HTTP/1.0" 200 833 0s "-" "Axis/1.4"
X.X.X.X - - [17/Apr/2012:13:40:33 +0200] "POST /foo/bar.php HTTP/1.0" 200 833 1s "-" "Axis/1.4"
X.X.X.X - - [17/Apr/2012:13:40:38 +0200] "GET /foo/bar.php HTTP/1.0" 200 228 0s "-" "check_http/v1.4.15 (nagios-plugins 1.4.15)"
X.X.X.X - - [17/Apr/2012:13:40:38 +0200] "POST /foo/bar.php HTTP/1.0" 200 634 0s "-" "Axis/1.4"
X.X.X.X - - [17/Apr/2012:13:40:39 +0200] "POST /foo/bar.php HTTP/1.0" 200 718 1s "-" "Axis/1.4"
X.X.X.X - - [17/Apr/2012:13:41:03 +0200] "GET /foo/bar.php HTTP/1.1" 200 181 1s "-" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/535.19 (KHTML, like Gecko) Chrome/18.0.1025.162 Safari/535.19"
X.X.X.X - - [17/Apr/2012:13:41:10 +0200] "POST /foo/bar.php HTTP/1.0" 200 833 1s "-" "Axis/1.4"
X.X.X.X - - [17/Apr/2012:13:41:16 +0200] "POST /foo/bar.php HTTP/1.0" 200 833 1s "-" "Axis/1.4"
X.X.X.X - - [17/Apr/2012:13:41:22 +0200] "GET /foo/bar.php HTTP/1.1" 200 181 19s "-" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/535.19 (KHTML, like Gecko) Chrome/18.0.1025.162 Safari/535.19"
X.X.X.X - - [17/Apr/2012:13:41:30 +0200] "POST /foo/bar.php HTTP/1.0" 200 833 1s "-" "Axis/1.4"
X.X.X.X - - [17/Apr/2012:13:41:33 +0200] "GET /foo/bar.php HTTP/1.1" 200 181 11s "-" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/535.19 (KHTML, like Gecko) Chrome/18.0.1025.162 Safari/535.19"
X.X.X.X - - [17/Apr/2012:13:41:37 +0200] "GET /foo/bar.php HTTP/1.1" 200 181 4s "-" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/535.19 (KHTML, like Gecko) Chrome/18.0.1025.162 Safari/535.19"
X.X.X.X - - [17/Apr/2012:13:41:38 +0200] "GET /foo/bar.php HTTP/1.0" 200 228 1s "-" "check_http/v1.4.15 (nagios-plugins 1.4.15)"
X.X.X.X - - [17/Apr/2012:13:41:40 +0200] "GET /foo/bar.php HTTP/1.1" 200 181 3s "-" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/535.19 (KHTML, like Gecko) Chrome/18.0.1025.162 Safari/535.19"
X.X.X.X - - [17/Apr/2012:13:41:40 +0200] "GET /foo/bar.php HTTP/1.1" 200 181 0s "-" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/535.19 (KHTML, like Gecko) Chrome/18.0.1025.162 Safari/535.19"
X.X.X.X - - [17/Apr/2012:13:41:41 +0200] "GET /foo/bar.php HTTP/1.1" 200 181 1s "-" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/535.19 (KHTML, like Gecko) Chrome/18.0.1025.162 Safari/535.19"
X.X.X.X - - [17/Apr/2012:13:41:51 +0200] "POST /foo/bar.php HTTP/1.0" 200 833 1s "-" "Axis/1.4"
X.X.X.X - - [17/Apr/2012:13:44:27 +0200] "GET /foo/bar.php HTTP/1.0" 200 228 0s "-" "Wget/1.12 (linux-gnu)"
X.X.X.X - - [17/Apr/2012:13:44:30 +0200] "GET /foo/bar.php HTTP/1.0" 200 228 1s "-" "Wget/1.12 (linux-gnu)"
X.X.X.X - - [17/Apr/2012:13:44:34 +0200] "GET /foo/bar.php HTTP/1.0" 200 228 1s "-" "Wget/1.12 (linux-gnu)"
Updated by jensj about 12 years ago
i forgot to mention, that it seems to be the time, since the last request with the same browser.
Updated by stbuehler about 12 years ago
- Target version set to 1.4.x
I don't see an easy fix to this as 1.4.x doesn't have an extra state for keep-alive, and this means that after the previous request ended it "starts" the next one immediately (which is what the start timestamps is referring to).
Updated by stbuehler about 9 years ago
- Has duplicate Bug #2608: Request response time in lighttpd access log added
Updated by gstrauss about 8 years ago
How about we update con->request_start when the first byte of the next request is received for subsequent requests on keep-alive connections?
diff --git a/src/connections.c b/src/connections.c
index f01d698..2175f07 100644
--- a/src/connections.c
+++ b/src/connections.c
@@ -891,6 +891,7 @@ static int connection_handle_read_state(server *srv, connection *con) {
chunkqueue *cq = con->read_queue;
chunkqueue *dst_cq = con->request_content_queue;
int is_closed = 0; /* the connection got closed, if we don't have a complete header, -> error */
+ int is_request_start = chunkqueue_is_empty(cq); /*(and if con->state is CON_STATE_READ)*/
if (con->is_readable) {
con->read_idle_ts = srv->cur_ts;
@@ -913,6 +914,11 @@ static int connection_handle_read_state(server *srv, connection *con) {
switch(ostate) {
case CON_STATE_READ:
+ /* update request_start timestamp when first byte of
+ * next request is received on a keep-alive connection */
+ if (con->request_count > 1 && is_request_start)
+ con->request_start = srv->cur_ts;
+
/* if there is a \r\n\r\n in the chunkqueue
*
* scan the chunk-queue twice
Updated by stbuehler about 8 years ago
- Target version changed from 1.4.x to 1.4.40
Updated by stbuehler about 8 years ago
- Status changed from New to Fixed
- % Done changed from 0 to 100
Applied in changeset r3111.
Also available in: Atom