Project

General

Profile

Bug #2412

%T in accesslog.format doesn't work as expected

Added by jensj about 5 years ago. Updated about 1 year ago.

Status:
Fixed
Priority:
Normal
Assignee:
-
Category:
mod_accesslog
Target version:
Start date:
2012-04-17
Due date:
% Done:

100%

Missing in 1.5.x:
No

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)"


Related issues

Duplicated by Bug #2608: Request response time in lighttpd access log Duplicate 2015-01-13

Associated revisions

Revision 3111 (diff)
Added by stbuehler about 1 year ago

[core] fix request_start in keep-alive requests to mark time when received first byte (fixes #2412)

From: Stefan Bühler <>

Revision 6f89a8bb (diff)
Added by stbuehler about 1 year ago

[core] fix request_start in keep-alive requests to mark time when received first byte (fixes #2412)

From: Stefan Bühler <>

git-svn-id: svn://svn.lighttpd.net/lighttpd/branches/lighttpd-1.4.x@3111 152afb58-edef-0310-8abb-c4023f1b3aa9

History

#1 Updated by jensj about 5 years ago

i forgot to mention, that it seems to be the time, since the last request with the same browser.

#2 Updated by stbuehler about 5 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).

#3 Updated by stbuehler about 5 years ago

  • Category set to mod_accesslog

#4 Updated by stbuehler about 2 years ago

  • Duplicated by Bug #2608: Request response time in lighttpd access log added

#5 Updated by gstrauss about 1 year 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

#6 Updated by stbuehler about 1 year ago

  • Target version changed from 1.4.x to 1.4.40

#7 Updated by stbuehler about 1 year ago

  • Status changed from New to Fixed
  • % Done changed from 0 to 100

Applied in changeset r3111.

Also available in: Atom