mirrors/haproxy
1
0
Fork 0
mirror of https://git.haproxy.org/git/haproxy.git/ synced 2025-09-22 14:21:25 +02:00
Code Issues Projects Releases Wiki Activity

MEDIUM: log: Decompose %Tq in %Th %Ti %TR

Browse Source 
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 --------->:
This commit is contained in:
Thierry FOURNIER / OZON.IO 2016-07-28 17:19:45 +02:00 committed by Willy Tarreau
parent 70d604593d
commit 4cac359a39
6 changed files with 225 additions and 82 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

188
doc/configuration.txt
View File

@ -14634,10 +14634,10 @@ with a star ('*') after the field name below.
Field Format Extract from the example above Field Format Extract from the example above
1 process_name '[' pid ']:' haproxy[14389]: 1 process_name '[' pid ']:' haproxy[14389]:
2 client_ip ':' client_port 10.0.1.2:33317 2 client_ip ':' client_port 10.0.1.2:33317
3 '[' accept_date ']' [06/Feb/2009:12:14:14.655] 3 '[' request_date ']' [06/Feb/2009:12:14:14.655]
4 frontend_name http-in 4 frontend_name http-in
5 backend_name '/' server_name static/srv1 5 backend_name '/' server_name static/srv1
6 Tq '/' Tw '/' Tc '/' Tr '/' Tt* 10/0/30/69/109 6 TR '/' Tw '/' Tc '/' Tr '/' Ta* 10/0/30/69/109
7 status_code 200 7 status_code 200
8 bytes_read* 2750 8 bytes_read* 2750
9 captured_request_cookie - 9 captured_request_cookie -
@ -14663,11 +14663,8 @@ Detailed fields description :
replaced with the ID of the accepting socket, which is also reported in the replaced with the ID of the accepting socket, which is also reported in the
stats interface. stats interface.
- "accept_date" is the exact date when the TCP connection was received by - "request_date" is the exact date when the first byte of the HTTP request
haproxy (which might be very slightly different from the date observed on was received by haproxy (log field %tr).
the network if there was some queuing in the system's backlog). This is
usually the same date which may appear in any upstream firewall's log. This
does not depend on the fact that the client has sent the request or not.
- "frontend_name" is the name of the frontend (or listener) which received - "frontend_name" is the name of the frontend (or listener) which received
and processed the connection. and processed the connection.
@ -14683,12 +14680,13 @@ Detailed fields description :
server, "<NOSRV>" is indicated instead of a server name. If the request was server, "<NOSRV>" is indicated instead of a server name. If the request was
intercepted by the stats subsystem, "<STATS>" is indicated instead. intercepted by the stats subsystem, "<STATS>" is indicated instead.
- "Tq" is the total time in milliseconds spent waiting for the client to send - "TR" is the total time in milliseconds spent waiting for a full HTTP
a full HTTP request, not counting data. It can be "-1" if the connection request from the client (not counting body) after the first byte was
was aborted before a complete request could be received. It should always received. It can be "-1" if the connection was aborted before a complete
be very small because a request generally fits in one single packet. Large request could be received or the a bad request was received. It should
times here generally indicate network trouble between the client and always be very small because a request generally fits in one single packet.
haproxy. See "Timers" below for more details. Large times here generally indicate network issues between the client and
haproxy or requests being typed by hand. See "Timers" below for more details.
- "Tw" is the total time in milliseconds spent waiting in the various queues. - "Tw" is the total time in milliseconds spent waiting in the various queues.
It can be "-1" if the connection was aborted before reaching the queue. It can be "-1" if the connection was aborted before reaching the queue.
@ -14707,12 +14705,14 @@ Detailed fields description :
"GET" requests generally indicate an overloaded server. See "Timers" below "GET" requests generally indicate an overloaded server. See "Timers" below
for more details. for more details.
- "Tt" is the total time in milliseconds elapsed between the accept and the - "Ta" is the time the request remained active in haproxy, which is the total
last close. It covers all possible processing. There is one exception, if time in milliseconds elapsed between the first byte of the request was
"option logasap" was specified, then the time counting stops at the moment received and the last byte of response was sent. It covers all possible
the log is emitted. In this case, a '+' sign is prepended before the value, processing except the handshake (see Th) and idle time (see Ti). There is
indicating that the final one will be larger. See "Timers" below for more one exception, if "option logasap" was specified, then the time counting
details. stops at the moment the log is emitted. In this case, a '+' sign is
prepended before the value, indicating that the final one will be larger.
See "Timers" below for more details.
- "status_code" is the HTTP status code returned to the client. This status - "status_code" is the HTTP status code returned to the client. This status
is generally set by the server, but it might also be set by haproxy when is generally set by the server, but it might also be set by haproxy when
@ -14890,19 +14890,19 @@ Flags are :
At the moment, the default HTTP format is defined this way : At the moment, the default HTTP format is defined this way :
log-format %ci:%cp\ [%t]\ %ft\ %b/%s\ %Tq/%Tw/%Tc/%Tr/%Tt\ %ST\ %B\ %CC\ \ 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 %CS %tsc %ac/%fc/%bc/%sc/%rc %sq/%bq %hr %hs %{+Q}r"
the default CLF format is defined this way : the default CLF format is defined this way :
log-format %{+Q}o\ %{-Q}ci\ -\ -\ [%T]\ %r\ %ST\ %B\ \"\"\ \"\"\ %cp\ \ log-format "%{+Q}o %{-Q}ci - - [%trg] %r %ST %B \"\" \"\" %cp \
%ms\ %ft\ %b\ %s\ \%Tq\ %Tw\ %Tc\ %Tr\ %Tt\ %tsc\ %ac\ %fc\ \ %ms %ft %b %s %TR %Tw %Tc %Tr %Ta %tsc %ac %fc \
%bc\ %sc\ %rc\ %sq\ %bq\ %CC\ %CS\ \%hrl\ %hsl %bc %sc %rc %sq %bq %CC %CS %hrl %hsl"
and the default TCP format is defined this way : and the default TCP format is defined this way :
log-format %ci:%cp\ [%t]\ %ft\ %b/%s\ %Tw/%Tc/%Tt\ %B\ %ts\ \ log-format "%ci:%cp [%t] %ft %b/%s %Tw/%Tc/%Tt %B %ts \
%ac/%fc/%bc/%sc/%rc\ %sq/%bq %ac/%fc/%bc/%sc/%rc %sq/%bq"
Please refer to the table below for currently defined variables : Please refer to the table below for currently defined variables :
@ -14923,11 +14923,15 @@ Please refer to the table below for currently defined variables :
| | %ID | unique-id | string | | | %ID | unique-id | string |
| | %ST | status_code | numeric | | | %ST | status_code | numeric |
| | %T | gmt_date_time | date | | | %T | gmt_date_time | date |
| | %Ta | Active time of the request (from TR to end) | numeric |
| | %Tc | Tc | numeric | | | %Tc | Tc | numeric |
| | %Td | Td = Tt - (Tq + Tw + Tc + Tr) | numeric | | | %Td | Td = Tt - (Tq + Tw + Tc + Tr) | numeric |
| | %Tl | local_date_time | date | | | %Tl | local_date_time | date |
| H | %Tq | Tq | numeric | | | %Th | connection handshake time (SSL, PROXY proto) | numeric |
| H | %Tr | Tr | numeric | | H | %Ti | idle time before the HTTP request | numeric |
| H | %Tq | Th + Ti + TR | numeric |
| H | %TR | time to receive the full request from 1st byte| numeric |
| H | %Tr | Tr (response time) | numeric |
| | %Ts | timestamp | numeric | | | %Ts | timestamp | numeric |
| | %Tt | Tt | numeric | | | %Tt | Tt | numeric |
| | %Tw | Tw | numeric | | | %Tw | Tw | numeric |
@ -14963,6 +14967,9 @@ Please refer to the table below for currently defined variables :
| S | %sslc| ssl_ciphers (ex: AES-SHA) | string | | S | %sslc| ssl_ciphers (ex: AES-SHA) | string |
| S | %sslv| ssl_version (ex: TLSv1) | string | | S | %sslv| ssl_version (ex: TLSv1) | string |
| | %t | date_time (with millisecond resolution) | date | | | %t | date_time (with millisecond resolution) | date |
| H | %tr | date_time of HTTP request | date |
| H | %trg | gmt_date_time of start of HTTP request | date |
| H | %trl | locla_date_time of start of HTTP request | date |
| | %ts | termination_state | string | | | %ts | termination_state | string |
| H | %tsc | termination_state with cookie status | string | | H | %tsc | termination_state with cookie status | string |
+---+------+-----------------------------------------------+-------------+ +---+------+-----------------------------------------------+-------------+
@ -15082,13 +15089,41 @@ Timers provide a great help in troubleshooting network problems. All values are
reported in milliseconds (ms). These timers should be used in conjunction with reported in milliseconds (ms). These timers should be used in conjunction with
the session termination flags. In TCP mode with "option tcplog" set on the the session termination flags. In TCP mode with "option tcplog" set on the
frontend, 3 control points are reported under the form "Tw/Tc/Tt", and in HTTP frontend, 3 control points are reported under the form "Tw/Tc/Tt", and in HTTP
mode, 5 control points are reported under the form "Tq/Tw/Tc/Tr/Tt" : mode, 5 control points are reported under the form "TR/Tw/Tc/Tr/Ta". In
addition, three other measures are provided, "Th", "Ti", and "Tq".
- Tq: total time to get the client request (HTTP mode only). It's the time - Th: total time to accept tcp connection and execute handshakes for low level
elapsed between the moment the client connection was accepted and the protocols. Currently, these protocoles are proxy-protocol and SSL. This may
moment the proxy received the last HTTP header. The value "-1" indicates only happen once during the whole connection's lifetime. A large time here
that the end of headers (empty line) has never been seen. This happens when may indicate that the client only pre-established the connection without
the client closes prematurely or times out. speaking, that it is experiencing network issues preventing it from
completing a handshake in a reasonable time (eg: MTU issues), or that an
SSL handshake was very expensive to compute.
- Ti: is the idle time before the HTTP request (HTTP mode only). This timer
counts between the end of the handshakes and the first byte of the HTTP
request. When dealing with a second request in keep-alive mode, it starts
to count after the end of the transmission the previous response. Some
browsers pre-establish connections to a server in order to reduce the
latency of a future request, and keep them pending until they need it. This
delay will be reported as the idle time. A value of -1 indicates that
nothing was received on the connection.
- TR: total time to get the client request (HTTP mode only). It's the time
elapsed between the first bytes received and the moment the proxy received
the empty line marking the end of the HTTP headers. The value "-1"
indicates that the end of headers has never been seen. This happens when
the client closes prematurely or times out. This time is usually very short
since most requests fit in a single packet. A large time may indicate a
request typed by hand during a test.
- Tq: total time to get the client request from the accept date or since the
emission of the last byte of the previous response (HTTP mode only). It's
exactly equalt to Th + Ti + TR unless any of them is -1, in which case it
returns -1 as well. This timer used to be very useful before the arrival of
HTTP keep-alive and browsers' pre-connect feature. It's recommended to drop
it in favor of TR nowadays, as the idle time adds a lot of noise to the
reports.
- Tw: total time spent in the queues waiting for a connection slot. It - Tw: total time spent in the queues waiting for a connection slot. It
accounts for backend queue as well as the server queues, and depends on the accounts for backend queue as well as the server queues, and depends on the
@ -15114,38 +15149,50 @@ mode, 5 control points are reported under the form "Tq/Tw/Tc/Tr/Tt" :
header (empty line) was never seen, most likely because the server timeout header (empty line) was never seen, most likely because the server timeout
stroke before the server managed to process the request. stroke before the server managed to process the request.
- Ta: total active time for the HTTP request, between the moment the proxy
received the first byte of the request header and the emission of the last
byte of the response body. The exception is when the "logasap" option is
specified. In this case, it only equals (TR+Tw+Tc+Tr), and is prefixed with
a '+' sign. From this field, we can deduce "Td", the data transmission time,
by subtracting other timers when valid :
Td = Ta - (TR + Tw + Tc + Tr)
Timers with "-1" values have to be excluded from this equation. Note that
"Ta" can never be negative.
- Tt: total session duration time, between the moment the proxy accepted it - Tt: total session duration time, between the moment the proxy accepted it
and the moment both ends were closed. The exception is when the "logasap" and the moment both ends were closed. The exception is when the "logasap"
option is specified. In this case, it only equals (Tq+Tw+Tc+Tr), and is option is specified. In this case, it only equals (Th+Ti+TR+Tw+Tc+Tr), and
prefixed with a '+' sign. From this field, we can deduce "Td", the data is prefixed with a '+' sign. From this field, we can deduce "Td", the data
transmission time, by subtracting other timers when valid : transmission time, by subtracting other timers when valid :
Td = Tt - (Tq + Tw + Tc + Tr) Td = Tt - (Th + Ti + TR + Tw + Tc + Tr)
Timers with "-1" values have to be excluded from this equation. In TCP Timers with "-1" values have to be excluded from this equation. In TCP
mode, "Tq" and "Tr" have to be excluded too. Note that "Tt" can never be mode, "Ti", "Tq" and "Tr" have to be excluded too. Note that "Tt" can never
negative. be negative and that for HTTP, Tt is simply equal to (Th+Ti+Ta).
These timers provide precious indications on trouble causes. Since the TCP These timers provide precious indications on trouble causes. Since the TCP
protocol defines retransmit delays of 3, 6, 12... seconds, we know for sure protocol defines retransmit delays of 3, 6, 12... seconds, we know for sure
that timers close to multiples of 3s are nearly always related to lost packets that timers close to multiples of 3s are nearly always related to lost packets
due to network problems (wires, negotiation, congestion). Moreover, if "Tt" is due to network problems (wires, negotiation, congestion). Moreover, if "Ta" or
close to a timeout value specified in the configuration, it often means that a "Tt" is close to a timeout value specified in the configuration, it often means
session has been aborted on timeout. that a session has been aborted on timeout.
Most common cases : Most common cases :
- If "Tq" is close to 3000, a packet has probably been lost between the - If "Th" or "Ti" are close to 3000, a packet has probably been lost between
client and the proxy. This is very rare on local networks but might happen the client and the proxy. This is very rare on local networks but might
when clients are on far remote networks and send large requests. It may happen when clients are on far remote networks and send large requests. It
happen that values larger than usual appear here without any network cause. may happen that values larger than usual appear here without any network
Sometimes, during an attack or just after a resource starvation has ended, cause. Sometimes, during an attack or just after a resource starvation has
haproxy may accept thousands of connections in a few milliseconds. The time ended, haproxy may accept thousands of connections in a few milliseconds.
spent accepting these connections will inevitably slightly delay processing The time spent accepting these connections will inevitably slightly delay
of other connections, and it can happen that request times in the order of processing of other connections, and it can happen that request times in the
a few tens of milliseconds are measured after a few thousands of new order of a few tens of milliseconds are measured after a few thousands of
connections have been accepted at once. Using one of the keep-alive modes new connections have been accepted at once. Using one of the keep-alive
may display larger request times since "Tq" also measures the time spent modes may display larger idle times since "Ti" measures the time spent
waiting for additional requests. waiting for additional requests.
- If "Tc" is close to 3000, a packet has probably been lost between the - If "Tc" is close to 3000, a packet has probably been lost between the
@ -15157,42 +15204,41 @@ Most common cases :
to be the average majored by 3000, there are probably some packets lost to be the average majored by 3000, there are probably some packets lost
between the proxy and the server. between the proxy and the server.
- If "Tt" is large even for small byte counts, it generally is because - If "Ta" is large even for small byte counts, it generally is because
neither the client nor the server decides to close the connection, for neither the client nor the server decides to close the connection while
instance because both have agreed on a keep-alive connection mode. In order haproxy is running in tunnel mode and both have agreed on a keep-alive
to solve this issue, it will be needed to specify "option httpclose" on connection mode. In order to solve this issue, it will be needed to specify
either the frontend or the backend. If the problem persists, it means that one of the HTTP options to manipulate keep-alive or close options on either
the server ignores the "close" connection mode and expects the client to the frontend or the backend. Having the smallest possible 'Ta' or 'Tt' is
close. Then it will be required to use "option forceclose". Having the important when connection regulation is used with the "maxconn" option on
smallest possible 'Tt' is important when connection regulation is used with the servers, since no new connection will be sent to the server until
the "maxconn" option on the servers, since no new connection will be sent another one is released.
to the server until another one is released.
Other noticeable HTTP log cases ('xx' means any value to be ignored) : Other noticeable HTTP log cases ('xx' means any value to be ignored) :
Tq/Tw/Tc/Tr/+Tt The "option logasap" is present on the frontend and the log TR/Tw/Tc/Tr/+Ta The "option logasap" is present on the frontend and the log
was emitted before the data phase. All the timers are valid was emitted before the data phase. All the timers are valid
except "Tt" which is shorter than reality. except "Ta" which is shorter than reality.
-1/xx/xx/xx/Tt The client was not able to send a complete request in time -1/xx/xx/xx/Ta The client was not able to send a complete request in time
or it aborted too early. Check the session termination flags or it aborted too early. Check the session termination flags
then "timeout http-request" and "timeout client" settings. then "timeout http-request" and "timeout client" settings.
Tq/-1/xx/xx/Tt It was not possible to process the request, maybe because TR/-1/xx/xx/Ta It was not possible to process the request, maybe because
servers were out of order, because the request was invalid servers were out of order, because the request was invalid
or forbidden by ACL rules. Check the session termination or forbidden by ACL rules. Check the session termination
flags. flags.
Tq/Tw/-1/xx/Tt The connection could not establish on the server. Either it TR/Tw/-1/xx/Ta The connection could not establish on the server. Either it
actively refused it or it timed out after Tt-(Tq+Tw) ms. actively refused it or it timed out after Ta-(TR+Tw) ms.
Check the session termination flags, then check the Check the session termination flags, then check the
"timeout connect" setting. Note that the tarpit action might "timeout connect" setting. Note that the tarpit action might
return similar-looking patterns, with "Tw" equal to the time return similar-looking patterns, with "Tw" equal to the time
the client connection was maintained open. the client connection was maintained open.
Tq/Tw/Tc/-1/Tt The server has accepted the connection but did not return TR/Tw/Tc/-1/Ta The server has accepted the connection but did not return
a complete response in time, or it closed its connection a complete response in time, or it closed its connection
unexpectedly after Tt-(Tq+Tw+Tc) ms. Check the session unexpectedly after Ta-(TR+Tw+Tc) ms. Check the session
termination flags, then check the "timeout server" setting. termination flags, then check the "timeout server" setting.

7
include/types/log.h
View File

@ -77,9 +77,16 @@ enum {
LOG_FMT_BYTES, LOG_FMT_BYTES,
LOG_FMT_BYTES_UP, LOG_FMT_BYTES_UP,
LOG_FMT_T, LOG_FMT_T,
LOG_FMT_Ta,
LOG_FMT_Th,
LOG_FMT_Ti,
LOG_FMT_TQ, LOG_FMT_TQ,
LOG_FMT_TW, LOG_FMT_TW,
LOG_FMT_TC, LOG_FMT_TC,
LOG_FMT_Tr,
LOG_FMT_tr,
LOG_FMT_trg,
LOG_FMT_trl,
LOG_FMT_TR, LOG_FMT_TR,
LOG_FMT_TD, LOG_FMT_TD,
LOG_FMT_TT, LOG_FMT_TT,

2
include/types/stream.h
View File

@ -97,6 +97,8 @@ struct strm_logs {
int level; /* log level to force + 1 if > 0, -1 = no log */ int level; /* log level to force + 1 if > 0, -1 = no log */
struct timeval accept_date; /* date of the stream's accept() in user date */ struct timeval accept_date; /* date of the stream's accept() in user date */
struct timeval tv_accept; /* date of the stream's accept() in internal date (monotonic) */ struct timeval tv_accept; /* date of the stream's accept() in internal date (monotonic) */
long t_handshake; /* hanshake duration, -1 if never occurs */
long t_idle; /* idle duration, -1 if never occurs */
struct timeval tv_request; /* date the request arrives, {0,0} if never occurs */ struct timeval tv_request; /* date the request arrives, {0,0} if never occurs */
long t_queue; /* delay before the stream gets out of the connect queue, -1 if never occurs */ long t_queue; /* delay before the stream gets out of the connect queue, -1 if never occurs */
long t_connect; /* delay before the connect() to the server succeeds, -1 if never occurs */ long t_connect; /* delay before the connect() to the server succeeds, -1 if never occurs */

95
src/log.c
View File

@ -124,10 +124,14 @@ static const struct logformat_type logformat_keywords[] = {
{ "ID", LOG_FMT_UNIQUEID, PR_MODE_HTTP, LW_BYTES, NULL }, /* Unique ID */ { "ID", LOG_FMT_UNIQUEID, PR_MODE_HTTP, LW_BYTES, NULL }, /* Unique ID */
{ "ST", LOG_FMT_STATUS, PR_MODE_TCP, LW_RESP, NULL }, /* status code */ { "ST", LOG_FMT_STATUS, PR_MODE_TCP, LW_RESP, NULL }, /* status code */
{ "T", LOG_FMT_DATEGMT, PR_MODE_TCP, LW_INIT, NULL }, /* date GMT */ { "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 */ { "Tc", LOG_FMT_TC, PR_MODE_TCP, LW_BYTES, NULL }, /* Tc */
{ "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 */ { "Tl", LOG_FMT_DATELOCAL, PR_MODE_TCP, LW_INIT, NULL }, /* date local timezone */
{ "Tq", LOG_FMT_TQ, PR_MODE_HTTP, LW_BYTES, NULL }, /* Tq */ { "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 }, /* 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) */ { "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 */ { "Ts", LOG_FMT_TS, PR_MODE_TCP, LW_INIT, NULL }, /* timestamp GMT */
{ "Tt", LOG_FMT_TT, PR_MODE_TCP, LW_BYTES, NULL }, /* Tt */ { "Tt", LOG_FMT_TT, PR_MODE_TCP, LW_BYTES, NULL }, /* Tt */
@ -169,6 +173,9 @@ static const struct logformat_type logformat_keywords[] = {
{ "sslc", LOG_FMT_SSL_CIPHER, PR_MODE_TCP, LW_XPRT, NULL }, /* client-side SSL ciphers */ { "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 */ { "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 */ { "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 */ { "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 */ { "tsc", LOG_FMT_TERMSTATE_CK, PR_MODE_TCP, LW_INIT, NULL },/* termination state */
@ -187,8 +194,8 @@ static const struct logformat_type logformat_keywords[] = {
{ 0, 0, 0, 0, NULL } { 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 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 - - [%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 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 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; char *log_format = NULL;
@ -1305,6 +1312,7 @@ int build_logline(struct stream *s, char *dst, size_t maxsize, struct list *list
char *ret; char *ret;
int iret; int iret;
struct logformat_node *tmp; struct logformat_node *tmp;
struct timeval tv;
/* FIXME: let's limit ourselves to frontend logging for now. */ /* FIXME: let's limit ourselves to frontend logging for now. */
@ -1474,7 +1482,7 @@ int build_logline(struct stream *s, char *dst, size_t maxsize, struct list *list
last_isspace = 0; last_isspace = 0;
break; break;
case LOG_FMT_DATE: // %t case LOG_FMT_DATE: // %t = accept date
get_localtime(s->logs.accept_date.tv_sec, &tm); get_localtime(s->logs.accept_date.tv_sec, &tm);
ret = date2str_log(tmplog, &tm, &(s->logs.accept_date), ret = date2str_log(tmplog, &tm, &(s->logs.accept_date),
dst + maxsize - tmplog); dst + maxsize - tmplog);
@ -1484,7 +1492,18 @@ int build_logline(struct stream *s, char *dst, size_t maxsize, struct list *list
last_isspace = 0; last_isspace = 0;
break; 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); get_gmtime(s->logs.accept_date.tv_sec, &tm);
ret = gmt2str_log(tmplog, &tm, dst + maxsize - tmplog); ret = gmt2str_log(tmplog, &tm, dst + maxsize - tmplog);
if (ret == NULL) if (ret == NULL)
@ -1493,7 +1512,17 @@ int build_logline(struct stream *s, char *dst, size_t maxsize, struct list *list
last_isspace = 0; last_isspace = 0;
break; break;
case LOG_FMT_DATELOCAL: // %Tl 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 = accept date, local
get_localtime(s->logs.accept_date.tv_sec, &tm); get_localtime(s->logs.accept_date.tv_sec, &tm);
ret = localdate2str_log(tmplog, s->logs.accept_date.tv_sec, &tm, dst + maxsize - tmplog); ret = localdate2str_log(tmplog, s->logs.accept_date.tv_sec, &tm, dst + maxsize - tmplog);
if (ret == NULL) if (ret == NULL)
@ -1502,6 +1531,16 @@ int build_logline(struct stream *s, char *dst, size_t maxsize, struct list *list
last_isspace = 0; last_isspace = 0;
break; 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 case LOG_FMT_TS: // %Ts
get_gmtime(s->logs.accept_date.tv_sec, &tm); get_gmtime(s->logs.accept_date.tv_sec, &tm);
if (tmp->options & LOG_OPT_HEXA) { if (tmp->options & LOG_OPT_HEXA) {
@ -1620,7 +1659,32 @@ int build_logline(struct stream *s, char *dst, size_t maxsize, struct list *list
last_isspace = 0; last_isspace = 0;
break; 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); ret = ltoa_o(t_request, tmplog, dst + maxsize - tmplog);
if (ret == NULL) if (ret == NULL)
goto out; goto out;
@ -1646,7 +1710,7 @@ int build_logline(struct stream *s, char *dst, size_t maxsize, struct list *list
last_isspace = 0; last_isspace = 0;
break; 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, ret = ltoa_o((s->logs.t_data >= 0) ? s->logs.t_data - s->logs.t_connect : -1,
tmplog, dst + maxsize - tmplog); tmplog, dst + maxsize - tmplog);
if (ret == NULL) if (ret == NULL)
@ -1668,7 +1732,18 @@ int build_logline(struct stream *s, char *dst, size_t maxsize, struct list *list
last_isspace = 0; last_isspace = 0;
break; break;
case LOG_FMT_TT: // %Tt 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 = total time
if (!(fe->to_log & LW_BYTES)) if (!(fe->to_log & LW_BYTES))
LOGCHAR('+'); LOGCHAR('+');
ret = ltoa_o(s->logs.t_close, tmplog, dst + maxsize - tmplog); ret = ltoa_o(s->logs.t_close, tmplog, dst + maxsize - tmplog);

8
src/proto_http.c
View File

@ -2455,6 +2455,12 @@ int http_wait_for_request(struct stream *s, struct channel *req, int an_bit)
* data later, which is much more complicated. * data later, which is much more complicated.
*/ */
if (buffer_not_empty(req->buf) && msg->msg_state < HTTP_MSG_ERROR) { if (buffer_not_empty(req->buf) && msg->msg_state < HTTP_MSG_ERROR) {
/* This point is executed when some data is avalaible for analysis,
* so we log the end of the idle time. */
if (s->logs.t_idle == -1)
s->logs.t_idle = tv_ms_elapsed(&s->logs.tv_accept, &now) - s->logs.t_handshake;
if (txn->flags & TX_NOT_FIRST) { if (txn->flags & TX_NOT_FIRST) {
if (unlikely(!channel_is_rewritable(req))) { if (unlikely(!channel_is_rewritable(req))) {
if (req->flags & (CF_SHUTW|CF_SHUTW_NOW|CF_WRITE_ERROR|CF_WRITE_TIMEOUT)) if (req->flags & (CF_SHUTW|CF_SHUTW_NOW|CF_WRITE_ERROR|CF_WRITE_TIMEOUT))
@ -5026,6 +5032,8 @@ void http_end_txn_clean_session(struct stream *s)
s->logs.accept_date = date; /* user-visible date for logging */ s->logs.accept_date = date; /* user-visible date for logging */
s->logs.tv_accept = now; /* corrected date for internal use */ s->logs.tv_accept = now; /* corrected date for internal use */
s->logs.t_handshake = 0; /* There are no handshake in keep alive connection. */
s->logs.t_idle = -1;
tv_zero(&s->logs.tv_request); tv_zero(&s->logs.tv_request);
s->logs.t_queue = -1; s->logs.t_queue = -1;
s->logs.t_connect = -1; s->logs.t_connect = -1;

5
src/stream.c
View File

@ -93,6 +93,11 @@ struct stream *stream_new(struct session *sess, struct task *t, enum obj_type *o
s->logs.level = 0; s->logs.level = 0;
s->logs.accept_date = sess->accept_date; /* user-visible date for logging */ s->logs.accept_date = sess->accept_date; /* user-visible date for logging */
s->logs.tv_accept = sess->tv_accept; /* corrected date for internal use */ s->logs.tv_accept = sess->tv_accept; /* corrected date for internal use */
/* This function is called just after the handshake, so the handshake duration is
* between the accept time and now.
*/
s->logs.t_handshake = tv_ms_elapsed(&sess->tv_accept, &now);
s->logs.t_idle = -1;
tv_zero(&s->logs.tv_request); tv_zero(&s->logs.tv_request);
s->logs.t_queue = -1; s->logs.t_queue = -1;
s->logs.t_connect = -1; s->logs.t_connect = -1;