MEDIUM: log: Decompose %Tq in %Th %Ti %TR
Tq is the time between the instant the connection is accepted and a
complete valid request is received. This time includes the handshake
(SSL / Proxy-Protocol), the idle when the browser does preconnect and
the request reception.
This patch decomposes %Tq in 3 measurements names %Th, %Ti, and %TR
which returns respectively the handshake time, the idle time and the
duration of valid request reception. It also adds %Ta which reports
the request's active time, which is the total time without %Th nor %Ti.
It replaces %Tt as the total time, reporting accurate measurements for
HTTP persistent connections.
%Th is avalaible for TCP and HTTP sessions, %Ti, %TR and %Ta are only
avalaible for HTTP connections.
In addition to this, we have new timestamps %tr, %trg and %trl, which
log the date of start of receipt of the request, respectively in the
default format, in GMT time and in local time (by analogy with %t, %T
and %Tl). All of them are obviously only available for HTTP. These values
are more relevant as they more accurately represent the request date
without being skewed by a browser's preconnect nor a keep-alive idle
time.
The HTTP log format and the CLF log format have been modified to
use %tr, %TR, and %Ta respectively instead of %t, %Tq and %Tt. This
way the default log formats now produce the expected output for users
who don't want to manually fiddle with the log-format directive.
Example with the following log-format :
log-format "%ci:%cp [%tr] %ft %b/%s h=%Th/i=%Ti/R=%TR/w=%Tw/c=%Tc/r=%Tr/a=%Ta/t=%Tt %ST %B %CC %CS %tsc %ac/%fc/%bc/%sc/%rc %sq/%bq %hr %hs %{+Q}r"
The request was sent by hand using "openssl s_client -connect" :
Aug 23 14:43:20 haproxy[25446]: 127.0.0.1:45636 [23/Aug/2016:14:43:20.221] test~ test/test h=6/i=2375/R=261/w=0/c=1/r=0/a=262/t=2643 200 145 - - ---- 1/1/0/0/0 0/0 "GET / HTTP/1.1"
=> 6 ms of SSL handshake, 2375 waiting before sending the first char (in
fact the time to type the first line), 261 ms before the end of the request,
no time spent in queue, 1 ms spend connecting to the server, immediate
response, total active time for this request = 262ms. Total time from accept
to close : 2643 ms.
The timing now decomposes like this :
first request 2nd request
|<-------------------------------->|<-------------- ...
t tr t tr ...
---|----|----|----|----|----|----|----|----|--
: Th Ti TR Tw Tc Tr Td : Ti ...
:<---- Tq ---->: :
:<-------------- Tt -------------->:
:<--------- Ta --------->:
diff --git a/src/log.c b/src/log.c
index 4f4ede9..64c7922 100644
--- a/src/log.c
+++ b/src/log.c
@@ -124,10 +124,14 @@
{ "ID", LOG_FMT_UNIQUEID, PR_MODE_HTTP, LW_BYTES, NULL }, /* Unique ID */
{ "ST", LOG_FMT_STATUS, PR_MODE_TCP, LW_RESP, NULL }, /* status code */
{ "T", LOG_FMT_DATEGMT, PR_MODE_TCP, LW_INIT, NULL }, /* date GMT */
+ { "Ta", LOG_FMT_Ta, PR_MODE_HTTP, LW_BYTES, NULL }, /* Time active (tr to end) */
{ "Tc", LOG_FMT_TC, PR_MODE_TCP, LW_BYTES, NULL }, /* Tc */
- { "Tl", LOG_FMT_DATELOCAL, PR_MODE_TCP, LW_INIT, NULL }, /* date local timezone */
- { "Tq", LOG_FMT_TQ, PR_MODE_HTTP, LW_BYTES, NULL }, /* Tq */
- { "Tr", LOG_FMT_TR, PR_MODE_HTTP, LW_BYTES, NULL }, /* Tr */
+ { "Th", LOG_FMT_Th, PR_MODE_TCP, LW_BYTES, NULL }, /* Time handshake */
+ { "Ti", LOG_FMT_Ti, PR_MODE_HTTP, LW_BYTES, NULL }, /* Time idle */
+ { "Tl", LOG_FMT_DATELOCAL, PR_MODE_TCP, LW_INIT, NULL }, /* date local timezone */
+ { "Tq", LOG_FMT_TQ, PR_MODE_HTTP, LW_BYTES, NULL }, /* Tq=Th+Ti+TR */
+ { "Tr", LOG_FMT_Tr, PR_MODE_HTTP, LW_BYTES, NULL }, /* Tr */
+ { "TR", LOG_FMT_TR, PR_MODE_HTTP, LW_BYTES, NULL }, /* Time to receive a valid request */
{ "Td", LOG_FMT_TD, PR_MODE_TCP, LW_BYTES, NULL }, /* Td = Tt - (Tq + Tw + Tc + Tr) */
{ "Ts", LOG_FMT_TS, PR_MODE_TCP, LW_INIT, NULL }, /* timestamp GMT */
{ "Tt", LOG_FMT_TT, PR_MODE_TCP, LW_BYTES, NULL }, /* Tt */
@@ -169,6 +173,9 @@
{ "sslc", LOG_FMT_SSL_CIPHER, PR_MODE_TCP, LW_XPRT, NULL }, /* client-side SSL ciphers */
{ "sslv", LOG_FMT_SSL_VERSION, PR_MODE_TCP, LW_XPRT, NULL }, /* client-side SSL protocol version */
{ "t", LOG_FMT_DATE, PR_MODE_TCP, LW_INIT, NULL }, /* date */
+ { "tr", LOG_FMT_tr, PR_MODE_HTTP, LW_INIT, NULL }, /* date of start of request */
+ { "trg",LOG_FMT_trg, PR_MODE_HTTP, LW_INIT, NULL }, /* date of start of request, GMT */
+ { "trl",LOG_FMT_trl, PR_MODE_HTTP, LW_INIT, NULL }, /* date of start of request, local */
{ "ts", LOG_FMT_TERMSTATE, PR_MODE_TCP, LW_BYTES, NULL },/* termination state */
{ "tsc", LOG_FMT_TERMSTATE_CK, PR_MODE_TCP, LW_INIT, NULL },/* termination state */
@@ -187,8 +194,8 @@
{ 0, 0, 0, 0, NULL }
};
-char default_http_log_format[] = "%ci:%cp [%t] %ft %b/%s %Tq/%Tw/%Tc/%Tr/%Tt %ST %B %CC %CS %tsc %ac/%fc/%bc/%sc/%rc %sq/%bq %hr %hs %{+Q}r"; // default format
-char clf_http_log_format[] = "%{+Q}o %{-Q}ci - - [%T] %r %ST %B \"\" \"\" %cp %ms %ft %b %s %Tq %Tw %Tc %Tr %Tt %tsc %ac %fc %bc %sc %rc %sq %bq %CC %CS %hrl %hsl";
+char default_http_log_format[] = "%ci:%cp [%tr] %ft %b/%s %TR/%Tw/%Tc/%Tr/%Ta %ST %B %CC %CS %tsc %ac/%fc/%bc/%sc/%rc %sq/%bq %hr %hs %{+Q}r"; // default format
+char clf_http_log_format[] = "%{+Q}o %{-Q}ci - - [%trg] %r %ST %B \"\" \"\" %cp %ms %ft %b %s %TR %Tw %Tc %Tr %Ta %tsc %ac %fc %bc %sc %rc %sq %bq %CC %CS %hrl %hsl";
char default_tcp_log_format[] = "%ci:%cp [%t] %ft %b/%s %Tw/%Tc/%Tt %B %ts %ac/%fc/%bc/%sc/%rc %sq/%bq";
char *log_format = NULL;
@@ -1305,6 +1312,7 @@
char *ret;
int iret;
struct logformat_node *tmp;
+ struct timeval tv;
/* FIXME: let's limit ourselves to frontend logging for now. */
@@ -1474,7 +1482,7 @@
last_isspace = 0;
break;
- case LOG_FMT_DATE: // %t
+ case LOG_FMT_DATE: // %t = accept date
get_localtime(s->logs.accept_date.tv_sec, &tm);
ret = date2str_log(tmplog, &tm, &(s->logs.accept_date),
dst + maxsize - tmplog);
@@ -1484,7 +1492,18 @@
last_isspace = 0;
break;
- case LOG_FMT_DATEGMT: // %T
+ case LOG_FMT_tr: // %tr = start of request date
+ /* Note that the timers are valid if we get here */
+ tv_ms_add(&tv, &s->logs.accept_date, s->logs.t_idle >= 0 ? s->logs.t_idle + s->logs.t_handshake : 0);
+ get_localtime(tv.tv_sec, &tm);
+ ret = date2str_log(tmplog, &tm, &tv, dst + maxsize - tmplog);
+ if (ret == NULL)
+ goto out;
+ tmplog = ret;
+ last_isspace = 0;
+ break;
+
+ case LOG_FMT_DATEGMT: // %T = accept date, GMT
get_gmtime(s->logs.accept_date.tv_sec, &tm);
ret = gmt2str_log(tmplog, &tm, dst + maxsize - tmplog);
if (ret == NULL)
@@ -1493,7 +1512,17 @@
last_isspace = 0;
break;
+ case LOG_FMT_trg: // %trg = start of request date, GMT
+ tv_ms_add(&tv, &s->logs.accept_date, s->logs.t_idle >= 0 ? s->logs.t_idle + s->logs.t_handshake : 0);
+ get_gmtime(tv.tv_sec, &tm);
+ ret = gmt2str_log(tmplog, &tm, dst + maxsize - tmplog);
+ if (ret == NULL)
+ goto out;
+ tmplog = ret;
+ last_isspace = 0;
+ break;
+
- case LOG_FMT_DATELOCAL: // %Tl
+ case LOG_FMT_DATELOCAL: // %Tl = accept date, local
get_localtime(s->logs.accept_date.tv_sec, &tm);
ret = localdate2str_log(tmplog, s->logs.accept_date.tv_sec, &tm, dst + maxsize - tmplog);
if (ret == NULL)
@@ -1502,6 +1531,16 @@
last_isspace = 0;
break;
+ case LOG_FMT_trl: // %trl = start of request date, local
+ tv_ms_add(&tv, &s->logs.accept_date, s->logs.t_idle >= 0 ? s->logs.t_idle + s->logs.t_handshake : 0);
+ get_localtime(tv.tv_sec, &tm);
+ ret = localdate2str_log(tmplog, tv.tv_sec, &tm, dst + maxsize - tmplog);
+ if (ret == NULL)
+ goto out;
+ tmplog = ret;
+ last_isspace = 0;
+ break;
+
case LOG_FMT_TS: // %Ts
get_gmtime(s->logs.accept_date.tv_sec, &tm);
if (tmp->options & LOG_OPT_HEXA) {
@@ -1620,7 +1659,32 @@
last_isspace = 0;
break;
- case LOG_FMT_TQ: // %Tq
+ case LOG_FMT_Th: // %Th = handshake time
+ ret = ltoa_o(s->logs.t_handshake, tmplog, dst + maxsize - tmplog);
+ if (ret == NULL)
+ goto out;
+ tmplog = ret;
+ last_isspace = 0;
+ break;
+
+ case LOG_FMT_Ti: // %Ti = HTTP idle time
+ ret = ltoa_o(s->logs.t_idle, tmplog, dst + maxsize - tmplog);
+ if (ret == NULL)
+ goto out;
+ tmplog = ret;
+ last_isspace = 0;
+ break;
+
+ case LOG_FMT_TR: // %TR = HTTP request time
+ ret = ltoa_o((t_request >= 0) ? t_request - s->logs.t_idle - s->logs.t_handshake : -1,
+ tmplog, dst + maxsize - tmplog);
+ if (ret == NULL)
+ goto out;
+ tmplog = ret;
+ last_isspace = 0;
+ break;
+
+ case LOG_FMT_TQ: // %Tq = Th + Ti + TR
ret = ltoa_o(t_request, tmplog, dst + maxsize - tmplog);
if (ret == NULL)
goto out;
@@ -1646,7 +1710,7 @@
last_isspace = 0;
break;
- case LOG_FMT_TR: // %Tr
+ case LOG_FMT_Tr: // %Tr
ret = ltoa_o((s->logs.t_data >= 0) ? s->logs.t_data - s->logs.t_connect : -1,
tmplog, dst + maxsize - tmplog);
if (ret == NULL)
@@ -1668,7 +1732,18 @@
last_isspace = 0;
break;
+ case LOG_FMT_Ta: // %Ta = active time = Tt - Th - Ti
+ if (!(fe->to_log & LW_BYTES))
+ LOGCHAR('+');
+ ret = ltoa_o(s->logs.t_close - (s->logs.t_idle >= 0 ? s->logs.t_idle + s->logs.t_handshake : 0),
+ tmplog, dst + maxsize - tmplog);
+ if (ret == NULL)
+ goto out;
+ tmplog = ret;
+ last_isspace = 0;
+ break;
+
- case LOG_FMT_TT: // %Tt
+ case LOG_FMT_TT: // %Tt = total time
if (!(fe->to_log & LW_BYTES))
LOGCHAR('+');
ret = ltoa_o(s->logs.t_close, tmplog, dst + maxsize - tmplog);