2006-06-25 20:48:02 -04:00
/*
* General logging functions .
*
2008-06-22 11:18:02 -04:00
* Copyright 2000 - 2008 Willy Tarreau < w @ 1 wt . eu >
2006-06-25 20:48:02 -04:00
*
* This program is free software ; you can redistribute it and / or
* modify it under the terms of the GNU General Public License
* as published by the Free Software Foundation ; either version
* 2 of the License , or ( at your option ) any later version .
*
*/
2012-12-20 15:23:42 -05:00
# include <ctype.h>
2007-11-30 12:38:35 -05:00
# include <fcntl.h>
2006-06-25 20:48:02 -04:00
# include <stdarg.h>
# include <stdio.h>
# include <stdlib.h>
# include <string.h>
# include <syslog.h>
# include <time.h>
# include <unistd.h>
2007-12-05 04:47:29 -05:00
# include <errno.h>
2006-06-25 20:48:02 -04:00
# include <sys/time.h>
2016-08-10 12:30:56 -04:00
# include <sys/uio.h>
2006-06-25 20:48:02 -04:00
2006-06-29 12:54:54 -04:00
# include <common/config.h>
2009-08-19 05:22:33 -04:00
# include <common/compat.h>
2018-11-25 13:14:37 -05:00
# include <common/initcall.h>
2006-06-29 11:53:05 -04:00
# include <common/standard.h>
2006-10-15 09:38:50 -04:00
# include <common/time.h>
2006-06-25 20:48:02 -04:00
2017-10-24 06:00:51 -04:00
# include <types/cli.h>
2006-06-25 20:48:02 -04:00
# include <types/global.h>
2012-02-08 10:37:49 -05:00
# include <types/log.h>
2008-07-14 18:22:45 -04:00
2017-10-24 06:00:51 -04:00
# include <proto/applet.h>
# include <proto/cli.h>
2012-04-05 12:02:55 -04:00
# include <proto/frontend.h>
2008-07-14 18:22:45 -04:00
# include <proto/log.h>
2012-12-20 18:09:23 -05:00
# include <proto/sample.h>
2015-04-03 08:46:27 -04:00
# include <proto/stream.h>
2011-03-10 10:55:02 -05:00
# include <proto/stream_interface.h>
2012-10-12 08:56:11 -04:00
# ifdef USE_OPENSSL
# include <proto/ssl_sock.h>
# endif
2006-06-25 20:48:02 -04:00
2015-10-01 07:18:13 -04:00
struct log_fmt {
char * name ;
struct {
2018-07-13 05:56:34 -04:00
struct buffer sep1 ; /* first pid separator */
struct buffer sep2 ; /* second pid separator */
2015-10-01 07:18:13 -04:00
} pid ;
} ;
static const struct log_fmt log_formats [ LOG_FORMATS ] = {
[ LOG_FORMAT_RFC3164 ] = {
. name = " rfc3164 " ,
. pid = {
2018-07-13 04:54:26 -04:00
. sep1 = { . area = " [ " , . data = 1 } ,
. sep2 = { . area = " ]: " , . data = 3 }
2015-10-01 07:18:13 -04:00
}
} ,
[ LOG_FORMAT_RFC5424 ] = {
. name = " rfc5424 " ,
. pid = {
2018-07-13 04:54:26 -04:00
. sep1 = { . area = " " , . data = 1 } ,
. sep2 = { . area = " - " , . data = 3 }
2015-10-01 07:18:13 -04:00
}
2018-11-12 02:45:00 -05:00
} ,
[ LOG_FORMAT_SHORT ] = {
. name = " short " ,
. pid = {
. sep1 = { . area = " " , . data = 0 } ,
. sep2 = { . area = " " , . data = 1 } ,
}
} ,
2018-11-12 05:57:56 -05:00
[ LOG_FORMAT_RAW ] = {
. name = " raw " ,
. pid = {
. sep1 = { . area = " " , . data = 0 } ,
. sep2 = { . area = " " , . data = 0 } ,
}
} ,
2015-09-22 10:05:32 -04:00
} ;
2016-02-12 07:23:03 -05:00
# define FD_SETS_ARE_BITFIELDS
# ifdef FD_SETS_ARE_BITFIELDS
/*
* This map is used with all the FD_ * macros to check whether a particular bit
* is set or not . Each bit represents an ACSII code . FD_SET ( ) sets those bytes
* which should be escaped . When FD_ISSET ( ) returns non - zero , it means that the
* byte should be escaped . Be careful to always pass bytes from 0 to 255
* exclusively to the macros .
*/
fd_set rfc5424_escape_map [ ( sizeof ( fd_set ) > ( 256 / 8 ) ) ? 1 : ( ( 256 / 8 ) / sizeof ( fd_set ) ) ] ;
2018-09-10 12:16:53 -04:00
fd_set hdr_encode_map [ ( sizeof ( fd_set ) > ( 256 / 8 ) ) ? 1 : ( ( 256 / 8 ) / sizeof ( fd_set ) ) ] ;
fd_set url_encode_map [ ( sizeof ( fd_set ) > ( 256 / 8 ) ) ? 1 : ( ( 256 / 8 ) / sizeof ( fd_set ) ) ] ;
fd_set http_encode_map [ ( sizeof ( fd_set ) > ( 256 / 8 ) ) ? 1 : ( ( 256 / 8 ) / sizeof ( fd_set ) ) ] ;
2016-02-12 07:23:03 -05:00
# else
# error "Check if your OS uses bitfields for fd_sets"
# endif
2006-06-25 20:48:02 -04:00
const char * log_facilities [ NB_LOG_FACILITIES ] = {
" kern " , " user " , " mail " , " daemon " ,
" auth " , " syslog " , " lpr " , " news " ,
" uucp " , " cron " , " auth2 " , " ftp " ,
" ntp " , " audit " , " alert " , " cron2 " ,
" local0 " , " local1 " , " local2 " , " local3 " ,
" local4 " , " local5 " , " local6 " , " local7 "
} ;
const char * log_levels [ NB_LOG_LEVELS ] = {
" emerg " , " alert " , " crit " , " err " ,
" warning " , " notice " , " info " , " debug "
} ;
2013-06-10 10:42:09 -04:00
const char sess_term_cond [ 16 ] = " -LcCsSPRIDKUIIII " ; /* normal, Local, CliTo, CliErr, SrvTo, SrvErr, PxErr, Resource, Internal, Down, Killed, Up, -- */
2006-09-03 03:56:00 -04:00
const char sess_fin_state [ 8 ] = " -RCHDLQT " ; /* cliRequest, srvConnect, srvHeader, Data, Last, Queue, Tarpit */
2006-06-25 20:48:02 -04:00
2012-02-08 10:37:49 -05:00
/* log_format */
struct logformat_type {
char * name ;
int type ;
2012-02-27 05:23:10 -05:00
int mode ;
2012-04-02 10:22:10 -04:00
int lw ; /* logwait bitsfield */
2012-03-02 08:35:21 -05:00
int ( * config_callback ) ( struct logformat_node * node , struct proxy * curproxy ) ;
2012-12-20 11:22:52 -05:00
const char * replace_by ; /* new option to use instead of old one */
2012-02-08 10:37:49 -05:00
} ;
2012-03-02 08:35:21 -05:00
int prepare_addrsource ( struct logformat_node * node , struct proxy * curproxy ) ;
2012-02-08 10:37:49 -05:00
/* log_format variable names */
static const struct logformat_type logformat_keywords [ ] = {
2012-04-02 10:22:10 -04:00
{ " o " , LOG_FMT_GLOBAL , PR_MODE_TCP , 0 , NULL } , /* global option */
2012-12-20 11:22:52 -05:00
/* please keep these lines sorted ! */
{ " B " , LOG_FMT_BYTES , PR_MODE_TCP , LW_BYTES , NULL } , /* bytes from server to client */
{ " CC " , LOG_FMT_CCLIENT , PR_MODE_HTTP , LW_REQHDR , NULL } , /* client cookie */
{ " CS " , LOG_FMT_CSERVER , PR_MODE_HTTP , LW_RSPHDR , NULL } , /* server cookie */
{ " H " , LOG_FMT_HOSTNAME , PR_MODE_TCP , LW_INIT , NULL } , /* Hostname */
{ " ID " , LOG_FMT_UNIQUEID , PR_MODE_HTTP , LW_BYTES , NULL } , /* Unique ID */
2014-06-13 06:21:40 -04:00
{ " ST " , LOG_FMT_STATUS , PR_MODE_TCP , LW_RESP , NULL } , /* status code */
2012-04-02 10:22:10 -04:00
{ " T " , LOG_FMT_DATEGMT , PR_MODE_TCP , LW_INIT , NULL } , /* date GMT */
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 --------->:
2016-07-28 11:19:45 -04:00
{ " Ta " , LOG_FMT_Ta , PR_MODE_HTTP , LW_BYTES , NULL } , /* Time active (tr to end) */
2012-12-20 11:22:52 -05:00
{ " Tc " , LOG_FMT_TC , PR_MODE_TCP , LW_BYTES , NULL } , /* Tc */
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 --------->:
2016-07-28 11:19:45 -04:00
{ " 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 */
2016-05-17 11:55:27 -04:00
{ " Td " , LOG_FMT_TD , PR_MODE_TCP , LW_BYTES , NULL } , /* Td = Tt - (Tq + Tw + Tc + Tr) */
2012-12-20 11:22:52 -05:00
{ " Ts " , LOG_FMT_TS , PR_MODE_TCP , LW_INIT , NULL } , /* timestamp GMT */
2012-04-02 10:22:10 -04:00
{ " Tt " , LOG_FMT_TT , PR_MODE_TCP , LW_BYTES , NULL } , /* Tt */
2012-12-20 11:22:52 -05:00
{ " Tw " , LOG_FMT_TW , PR_MODE_TCP , LW_BYTES , NULL } , /* Tw */
{ " U " , LOG_FMT_BYTES_UP , PR_MODE_TCP , LW_BYTES , NULL } , /* bytes from client to server */
2012-04-02 10:22:10 -04:00
{ " ac " , LOG_FMT_ACTCONN , PR_MODE_TCP , LW_BYTES , NULL } , /* actconn */
2012-12-20 11:22:52 -05:00
{ " b " , LOG_FMT_BACKEND , PR_MODE_TCP , LW_INIT , NULL } , /* backend */
2012-04-02 10:22:10 -04:00
{ " bc " , LOG_FMT_BECONN , PR_MODE_TCP , LW_BYTES , NULL } , /* beconn */
2012-12-20 11:22:52 -05:00
{ " bi " , LOG_FMT_BACKENDIP , PR_MODE_TCP , LW_BCKIP , prepare_addrsource } , /* backend source ip */
{ " bp " , LOG_FMT_BACKENDPORT , PR_MODE_TCP , LW_BCKIP , prepare_addrsource } , /* backend source port */
2012-04-02 10:22:10 -04:00
{ " bq " , LOG_FMT_BCKQUEUE , PR_MODE_TCP , LW_BYTES , NULL } , /* backend_queue */
2017-06-23 05:23:43 -04:00
{ " ci " , LOG_FMT_CLIENTIP , PR_MODE_TCP , LW_CLIP | LW_XPRT , NULL } , /* client ip */
{ " cp " , LOG_FMT_CLIENTPORT , PR_MODE_TCP , LW_CLIP | LW_XPRT , NULL } , /* client port */
2012-12-20 11:22:52 -05:00
{ " f " , LOG_FMT_FRONTEND , PR_MODE_TCP , LW_INIT , NULL } , /* frontend */
{ " fc " , LOG_FMT_FECONN , PR_MODE_TCP , LW_BYTES , NULL } , /* feconn */
2017-06-23 05:23:43 -04:00
{ " fi " , LOG_FMT_FRONTENDIP , PR_MODE_TCP , LW_FRTIP | LW_XPRT , NULL } , /* frontend ip */
{ " fp " , LOG_FMT_FRONTENDPORT , PR_MODE_TCP , LW_FRTIP | LW_XPRT , NULL } , /* frontend port */
2012-12-20 11:22:52 -05:00
{ " ft " , LOG_FMT_FRONTEND_XPRT , PR_MODE_TCP , LW_INIT , NULL } , /* frontend with transport mode */
2014-06-13 06:23:06 -04:00
{ " hr " , LOG_FMT_HDRREQUEST , PR_MODE_TCP , LW_REQHDR , NULL } , /* header request */
{ " hrl " , LOG_FMT_HDRREQUESTLIST , PR_MODE_TCP , LW_REQHDR , NULL } , /* header request list */
{ " hs " , LOG_FMT_HDRRESPONS , PR_MODE_TCP , LW_RSPHDR , NULL } , /* header response */
{ " hsl " , LOG_FMT_HDRRESPONSLIST , PR_MODE_TCP , LW_RSPHDR , NULL } , /* header response list */
2015-04-27 17:37:03 -04:00
{ " HM " , LOG_FMT_HTTP_METHOD , PR_MODE_HTTP , LW_REQ , NULL } , /* HTTP method */
{ " HP " , LOG_FMT_HTTP_PATH , PR_MODE_HTTP , LW_REQ , NULL } , /* HTTP path */
2015-07-31 12:14:16 -04:00
{ " HQ " , LOG_FMT_HTTP_QUERY , PR_MODE_HTTP , LW_REQ , NULL } , /* HTTP query */
2015-04-27 17:37:03 -04:00
{ " HU " , LOG_FMT_HTTP_URI , PR_MODE_HTTP , LW_REQ , NULL } , /* HTTP full URI */
{ " HV " , LOG_FMT_HTTP_VERSION , PR_MODE_HTTP , LW_REQ , NULL } , /* HTTP version */
2014-08-28 09:03:15 -04:00
{ " lc " , LOG_FMT_LOGCNT , PR_MODE_TCP , LW_INIT , NULL } , /* log counter */
2012-12-20 11:22:52 -05:00
{ " ms " , LOG_FMT_MS , PR_MODE_TCP , LW_INIT , NULL } , /* accept date millisecond */
2012-04-02 10:22:10 -04:00
{ " pid " , LOG_FMT_PID , PR_MODE_TCP , LW_INIT , NULL } , /* log pid */
2012-12-20 11:22:52 -05:00
{ " r " , LOG_FMT_REQ , PR_MODE_HTTP , LW_REQ , NULL } , /* request */
{ " rc " , LOG_FMT_RETRIES , PR_MODE_TCP , LW_BYTES , NULL } , /* retries */
2014-01-25 05:01:50 -05:00
{ " rt " , LOG_FMT_COUNTER , PR_MODE_TCP , LW_REQ , NULL } , /* request counter (HTTP or TCP session) */
2012-12-20 11:22:52 -05:00
{ " s " , LOG_FMT_SERVER , PR_MODE_TCP , LW_SVID , NULL } , /* server */
{ " sc " , LOG_FMT_SRVCONN , PR_MODE_TCP , LW_BYTES , NULL } , /* srv_conn */
{ " si " , LOG_FMT_SERVERIP , PR_MODE_TCP , LW_SVIP , NULL } , /* server destination ip */
{ " sp " , LOG_FMT_SERVERPORT , PR_MODE_TCP , LW_SVIP , NULL } , /* server destination port */
{ " sq " , LOG_FMT_SRVQUEUE , PR_MODE_TCP , LW_BYTES , NULL } , /* srv_queue */
2012-10-12 14:17:54 -04:00
{ " 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 */
2012-12-20 11:22:52 -05:00
{ " t " , LOG_FMT_DATE , PR_MODE_TCP , LW_INIT , NULL } , /* date */
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 --------->:
2016-07-28 11:19:45 -04:00
{ " 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 */
2012-12-20 11:22:52 -05:00
{ " 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 */
/* The following tags are deprecated and will be removed soon */
{ " Bi " , LOG_FMT_BACKENDIP , PR_MODE_TCP , LW_BCKIP , prepare_addrsource , " bi " } , /* backend source ip */
{ " Bp " , LOG_FMT_BACKENDPORT , PR_MODE_TCP , LW_BCKIP , prepare_addrsource , " bp " } , /* backend source port */
2017-06-23 05:23:43 -04:00
{ " Ci " , LOG_FMT_CLIENTIP , PR_MODE_TCP , LW_CLIP | LW_XPRT , NULL , " ci " } , /* client ip */
{ " Cp " , LOG_FMT_CLIENTPORT , PR_MODE_TCP , LW_CLIP | LW_XPRT , NULL , " cp " } , /* client port */
{ " Fi " , LOG_FMT_FRONTENDIP , PR_MODE_TCP , LW_FRTIP | LW_XPRT , NULL , " fi " } , /* frontend ip */
{ " Fp " , LOG_FMT_FRONTENDPORT , PR_MODE_TCP , LW_FRTIP | LW_XPRT , NULL , " fp " } , /* frontend port */
2012-12-20 11:22:52 -05:00
{ " Si " , LOG_FMT_SERVERIP , PR_MODE_TCP , LW_SVIP , NULL , " si " } , /* server destination ip */
{ " Sp " , LOG_FMT_SERVERPORT , PR_MODE_TCP , LW_SVIP , NULL , " sp " } , /* server destination port */
{ " cc " , LOG_FMT_CCLIENT , PR_MODE_HTTP , LW_REQHDR , NULL , " CC " } , /* client cookie */
{ " cs " , LOG_FMT_CSERVER , PR_MODE_HTTP , LW_RSPHDR , NULL , " CS " } , /* server cookie */
{ " st " , LOG_FMT_STATUS , PR_MODE_HTTP , LW_RESP , NULL , " ST " } , /* status code */
2012-04-02 10:22:10 -04:00
{ 0 , 0 , 0 , 0 , NULL }
2012-02-08 10:37:49 -05:00
} ;
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 --------->:
2016-07-28 11:19:45 -04:00
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 " ;
2012-12-20 11:22:52 -05:00
char default_tcp_log_format [ ] = " %ci:%cp [%t] %ft %b/%s %Tw/%Tc/%Tt %B %ts %ac/%fc/%bc/%sc/%rc %sq/%bq " ;
2012-02-08 10:37:49 -05:00
char * log_format = NULL ;
2015-09-25 13:17:44 -04:00
/* Default string used for structured-data part in RFC5424 formatted
* syslog messages .
*/
char default_rfc5424_sd_log_format [ ] = " - " ;
2015-09-22 10:05:32 -04:00
2018-11-12 01:25:28 -05:00
/* total number of dropped logs */
unsigned int dropped_logs = 0 ;
2015-09-22 10:05:32 -04:00
/* This is a global syslog header, common to all outgoing messages in
* RFC3164 format . It begins with time - based part and is updated by
* update_log_hdr ( ) .
2015-09-19 16:09:02 -04:00
*/
2017-06-02 10:20:16 -04:00
THREAD_LOCAL char * logheader = NULL ;
2015-09-19 16:09:02 -04:00
2015-09-22 10:05:32 -04:00
/* This is a global syslog header for messages in RFC5424 format. It is
* updated by update_log_hdr_rfc5424 ( ) .
*/
2017-06-02 10:20:16 -04:00
THREAD_LOCAL char * logheader_rfc5424 = NULL ;
2015-09-22 10:05:32 -04:00
2015-09-19 16:09:02 -04:00
/* This is a global syslog message buffer, common to all outgoing
* messages . It contains only the data part .
2012-03-19 11:51:53 -04:00
*/
2017-06-02 10:20:16 -04:00
THREAD_LOCAL char * logline = NULL ;
2012-03-19 11:51:53 -04:00
2015-09-25 13:17:44 -04:00
/* A global syslog message buffer, common to all RFC5424 syslog messages.
* Currently , it is used for generating the structured - data part .
*/
2017-06-02 10:20:16 -04:00
THREAD_LOCAL char * logline_rfc5424 = NULL ;
2015-09-25 13:17:44 -04:00
2017-10-24 05:44:05 -04:00
/* A global buffer used to store all startup alerts/warnings. It will then be
* retrieve on the CLI . */
2018-12-15 10:55:36 -05:00
static char * startup_logs = NULL ;
2017-10-24 05:44:05 -04:00
2012-02-08 10:37:49 -05:00
struct logformat_var_args {
char * name ;
int mask ;
} ;
struct logformat_var_args var_args_list [ ] = {
// global
{ " M " , LOG_OPT_MANDATORY } ,
{ " Q " , LOG_OPT_QUOTE } ,
2012-04-05 12:02:55 -04:00
{ " X " , LOG_OPT_HEXA } ,
2016-02-12 07:23:03 -05:00
{ " E " , LOG_OPT_ESC } ,
2012-02-08 10:37:49 -05:00
{ 0 , 0 }
} ;
2013-04-12 12:30:32 -04:00
/* return the name of the directive used in the current proxy for which we're
* currently parsing a header , when it is known .
*/
static inline const char * fmt_directive ( const struct proxy * curproxy )
{
2013-12-02 06:24:54 -05:00
switch ( curproxy - > conf . args . ctx ) {
2015-07-09 05:20:00 -04:00
case ARGC_ACL :
return " acl " ;
case ARGC_STK :
return " stick " ;
case ARGC_TRK :
return " track-sc " ;
case ARGC_LOG :
return " log-format " ;
2015-09-25 13:17:44 -04:00
case ARGC_LOGSD :
return " log-format-sd " ;
2013-12-02 06:24:54 -05:00
case ARGC_HRQ :
2013-11-20 09:09:52 -05:00
return " http-request " ;
2013-12-02 06:24:54 -05:00
case ARGC_HRS :
2013-11-20 09:09:52 -05:00
return " http-response " ;
2015-07-09 05:20:00 -04:00
case ARGC_UIF :
return " unique-id-format " ;
2013-11-29 06:15:45 -05:00
case ARGC_RDR :
2015-07-09 05:20:00 -04:00
return " redirect " ;
case ARGC_CAP :
return " capture " ;
2015-07-09 05:39:33 -04:00
case ARGC_SRV :
return " server " ;
MAJOR: spoe: Add an experimental Stream Processing Offload Engine
SPOE makes possible the communication with external components to retrieve some
info using an in-house binary protocol, the Stream Processing Offload Protocol
(SPOP). In the long term, its aim is to allow any kind of offloading on the
streams. This first version, besides being experimental, won't do lot of
things. The most important today is to validate the protocol design and lay the
foundations of what will, one day, be a full offload engine for the stream
processing.
So, for now, the SPOE can offload the stream processing before "tcp-request
content", "tcp-response content", "http-request" and "http-response" rules. And
it only supports variables creation/suppression. But, in spite of these limited
features, we can easily imagine to implement a SSO solution, an ip reputation
service or an ip geolocation service.
Internally, the SPOE is implemented as a filter. So, to use it, you must use
following line in a proxy proxy section:
frontend my-front
...
filter spoe [engine <name>] config <file>
...
It uses its own configuration file to keep the HAProxy configuration clean. It
is also a easy way to disable it by commenting out the filter line.
See "doc/SPOE.txt" for all details about the SPOE configuration.
2016-10-27 16:29:49 -04:00
case ARGC_SPOE :
return " spoe-message " ;
2016-11-24 17:57:54 -05:00
case ARGC_UBK :
return " use_backend " ;
2013-12-02 06:24:54 -05:00
default :
2015-07-09 05:20:00 -04:00
return " undefined(please report this bug) " ; /* must never happen */
2013-12-02 06:24:54 -05:00
}
2013-04-12 12:30:32 -04:00
}
2012-03-02 08:35:21 -05:00
/*
* callback used to configure addr source retrieval
*/
int prepare_addrsource ( struct logformat_node * node , struct proxy * curproxy )
{
curproxy - > options2 | = PR_O2_SRC_ADDR ;
return 0 ;
}
2012-02-08 10:37:49 -05:00
/*
2016-11-22 17:13:04 -05:00
* Parse args in a logformat_var . Returns 0 in error
* case , otherwise , it returns 1.
2012-02-08 10:37:49 -05:00
*/
2016-11-22 18:41:28 -05:00
int parse_logformat_var_args ( char * args , struct logformat_node * node , char * * err )
2012-02-08 10:37:49 -05:00
{
int i = 0 ;
int end = 0 ;
int flags = 0 ; // 1 = + 2 = -
char * sp = NULL ; // start pointer
2016-11-22 18:41:28 -05:00
if ( args = = NULL ) {
memprintf ( err , " internal error: parse_logformat_var_args() expects non null 'args' " ) ;
2016-11-22 17:13:04 -05:00
return 0 ;
2016-11-22 18:41:28 -05:00
}
2012-02-08 10:37:49 -05:00
while ( 1 ) {
if ( * args = = ' \0 ' )
end = 1 ;
if ( * args = = ' + ' ) {
// add flag
sp = args + 1 ;
flags = 1 ;
}
if ( * args = = ' - ' ) {
// delete flag
sp = args + 1 ;
flags = 2 ;
}
if ( * args = = ' \0 ' | | * args = = ' , ' ) {
* args = ' \0 ' ;
2012-12-20 12:19:26 -05:00
for ( i = 0 ; sp & & var_args_list [ i ] . name ; i + + ) {
2012-02-08 10:37:49 -05:00
if ( strcmp ( sp , var_args_list [ i ] . name ) = = 0 ) {
if ( flags = = 1 ) {
node - > options | = var_args_list [ i ] . mask ;
break ;
} else if ( flags = = 2 ) {
node - > options & = ~ var_args_list [ i ] . mask ;
break ;
}
}
}
sp = NULL ;
if ( end )
break ;
}
2012-12-20 12:19:26 -05:00
args + + ;
2012-02-08 10:37:49 -05:00
}
2016-11-22 17:13:04 -05:00
return 1 ;
2012-02-08 10:37:49 -05:00
}
/*
2012-12-20 15:23:42 -05:00
* Parse a variable ' % varname ' or ' % { args } varname ' in log - format . The caller
* must pass the args part in the < arg > pointer with its length in < arg_len > ,
* and varname with its length in < var > and < var_len > respectively . < arg > is
* ignored when arg_len is 0. Neither < var > nor < var_len > may be null .
2016-11-22 16:06:04 -05:00
* Returns false in error case and err is filled , otherwise returns true .
2012-02-08 10:37:49 -05:00
*/
2016-11-22 18:41:28 -05:00
int parse_logformat_var ( char * arg , int arg_len , char * var , int var_len , struct proxy * curproxy , struct list * list_format , int * defoptions , char * * err )
2012-02-08 10:37:49 -05:00
{
2012-12-20 15:23:42 -05:00
int j ;
struct logformat_node * node ;
for ( j = 0 ; logformat_keywords [ j ] . name ; j + + ) { // search a log type
if ( strlen ( logformat_keywords [ j ] . name ) = = var_len & &
strncmp ( var , logformat_keywords [ j ] . name , var_len ) = = 0 ) {
if ( logformat_keywords [ j ] . mode ! = PR_MODE_HTTP | | curproxy - > mode = = PR_MODE_HTTP ) {
2016-04-03 07:48:43 -04:00
node = calloc ( 1 , sizeof ( * node ) ) ;
2016-11-22 17:24:10 -05:00
if ( ! node ) {
2016-11-22 18:41:28 -05:00
memprintf ( err , " out of memory error " ) ;
2016-11-22 17:24:10 -05:00
return 0 ;
}
2012-12-20 15:23:42 -05:00
node - > type = logformat_keywords [ j ] . type ;
node - > options = * defoptions ;
if ( arg_len ) {
node - > arg = my_strndup ( arg , arg_len ) ;
2016-11-22 18:41:28 -05:00
if ( ! parse_logformat_var_args ( node - > arg , node , err ) )
2016-11-22 17:11:21 -05:00
return 0 ;
2012-12-20 15:23:42 -05:00
}
if ( node - > type = = LOG_FMT_GLOBAL ) {
* defoptions = node - > options ;
free ( node - > arg ) ;
free ( node ) ;
} else {
if ( logformat_keywords [ j ] . config_callback & &
logformat_keywords [ j ] . config_callback ( node , curproxy ) ! = 0 ) {
2016-11-22 16:06:04 -05:00
return 0 ;
2012-02-08 10:37:49 -05:00
}
2012-12-20 15:23:42 -05:00
curproxy - > to_log | = logformat_keywords [ j ] . lw ;
LIST_ADDQ ( list_format , & node - > list ) ;
2012-02-08 10:37:49 -05:00
}
2012-12-20 15:23:42 -05:00
if ( logformat_keywords [ j ] . replace_by )
2017-11-24 10:50:31 -05:00
ha_warning ( " parsing [%s:%d] : deprecated variable '%s' in '%s', please replace it with '%s'. \n " ,
curproxy - > conf . args . file , curproxy - > conf . args . line ,
logformat_keywords [ j ] . name , fmt_directive ( curproxy ) , logformat_keywords [ j ] . replace_by ) ;
2016-11-22 16:06:04 -05:00
return 1 ;
2012-12-20 15:23:42 -05:00
} else {
2016-11-22 18:41:28 -05:00
memprintf ( err , " format variable '%s' is reserved for HTTP mode " ,
logformat_keywords [ j ] . name ) ;
2016-11-22 16:06:04 -05:00
return 0 ;
2012-02-08 10:37:49 -05:00
}
}
}
2012-12-20 15:23:42 -05:00
j = var [ var_len ] ;
var [ var_len ] = 0 ;
2016-11-22 18:41:28 -05:00
memprintf ( err , " no such format variable '%s'. If you wanted to emit the '%%' character verbatim, you need to use '%%%%' " , var ) ;
2012-12-20 15:23:42 -05:00
var [ var_len ] = j ;
2016-11-22 16:06:04 -05:00
return 0 ;
2012-02-08 10:37:49 -05:00
}
/*
* push to the logformat linked list
*
* start : start pointer
* end : end text pointer
* type : string type
2012-03-12 07:46:41 -04:00
* list_format : destination list
2012-02-08 10:37:49 -05:00
*
* LOG_TEXT : copy chars from start to end excluding end .
*
*/
2016-11-22 18:41:28 -05:00
int add_to_logformat_list ( char * start , char * end , int type , struct list * list_format , char * * err )
2012-02-08 10:37:49 -05:00
{
char * str ;
2012-12-20 15:59:12 -05:00
if ( type = = LF_TEXT ) { /* type text */
2016-04-03 07:48:43 -04:00
struct logformat_node * node = calloc ( 1 , sizeof ( * node ) ) ;
2016-11-22 17:24:10 -05:00
if ( ! node ) {
2016-11-22 18:41:28 -05:00
memprintf ( err , " out of memory error " ) ;
2016-11-22 17:24:10 -05:00
return 0 ;
}
2016-04-03 07:48:43 -04:00
str = calloc ( 1 , end - start + 1 ) ;
2012-02-08 10:37:49 -05:00
strncpy ( str , start , end - start ) ;
str [ end - start ] = ' \0 ' ;
node - > arg = str ;
2012-03-12 07:46:41 -04:00
node - > type = LOG_FMT_TEXT ; // type string
LIST_ADDQ ( list_format , & node - > list ) ;
2012-12-20 15:59:12 -05:00
} else if ( type = = LF_SEPARATOR ) {
2016-04-03 07:48:43 -04:00
struct logformat_node * node = calloc ( 1 , sizeof ( * node ) ) ;
2016-11-22 17:24:10 -05:00
if ( ! node ) {
2016-11-22 18:41:28 -05:00
memprintf ( err , " out of memory error " ) ;
2016-11-22 17:24:10 -05:00
return 0 ;
}
2012-03-12 07:46:41 -04:00
node - > type = LOG_FMT_SEPARATOR ;
LIST_ADDQ ( list_format , & node - > list ) ;
2012-02-08 10:37:49 -05:00
}
2016-11-22 17:11:21 -05:00
return 1 ;
2012-02-08 10:37:49 -05:00
}
2012-12-20 18:09:23 -05:00
/*
* Parse the sample fetch expression < text > and add a node to < list_format > upon
* success . At the moment , sample converters are not yet supported but fetch arguments
MAJOR: sample: maintain a per-proxy list of the fetch args to resolve
While ACL args were resolved after all the config was parsed, it was not the
case with sample fetch args because they're almost everywhere now.
The issue is that ACLs now solely rely on sample fetches, so their args
resolving doesn't work anymore. And many fetches involving a server, a
proxy or a userlist don't work at all.
The real issue is that at the bottom layers we have no information about
proxies, line numbers, even ACLs in order to report understandable errors,
and that at the top layers we have no visibility over the locations where
fetches are referenced (think log node).
After failing multiple unsatisfying solutions attempts, we now have a new
concept of args list. The principle is that every proxy has a list head
which contains a number of indications such as the config keyword, the
context where it's used, the file and line number, etc... and a list of
arguments. This list head is of the same type as the elements, so it
serves as a template for adding new elements. This way, it is filled from
top to bottom by the callers with the information they have (eg: line
numbers, ACL name, ...) and the lower layers just have to duplicate it and
add an element when they face an argument they cannot resolve yet.
Then at the end of the configuration parsing, a loop passes over each
proxy's list and resolves all the args in sequence. And this way there is
all necessary information to report verbose errors.
The first immediate benefit is that for the first time we got very precise
location of issues (arg number in a keyword in its context, ...). Second,
in order to do this we had to parse log-format and unique-id-format a bit
earlier, so that was a great opportunity for doing so when the directives
are encountered (unless it's a default section). This way, the recorded
line numbers for these args are the ones of the place where the log format
is declared, not the end of the file.
Userlists report slightly more information now. They're the only remaining
ones in the ACL resolving function.
2013-04-02 10:34:32 -04:00
* should work . The curpx - > conf . args . ctx must be set by the caller .
2016-11-22 17:11:21 -05:00
*
* In error case , the function returns 0 , otherwise it returns 1.
2012-12-20 18:09:23 -05:00
*/
2016-11-22 18:41:28 -05:00
int add_sample_to_logformat_list ( char * text , char * arg , int arg_len , struct proxy * curpx , struct list * list_format , int options , int cap , char * * err )
2012-12-20 18:09:23 -05:00
{
char * cmd [ 2 ] ;
struct sample_expr * expr ;
struct logformat_node * node ;
int cmd_arg ;
cmd [ 0 ] = text ;
cmd [ 1 ] = " " ;
cmd_arg = 0 ;
2016-11-22 18:41:28 -05:00
expr = sample_parse_expr ( cmd , & cmd_arg , curpx - > conf . args . file , curpx - > conf . args . line , err , & curpx - > conf . args ) ;
2012-12-20 18:09:23 -05:00
if ( ! expr ) {
2016-11-22 18:41:28 -05:00
memprintf ( err , " failed to parse sample expression <%s> : %s " , text , * err ) ;
2016-11-22 17:11:21 -05:00
return 0 ;
2012-12-20 18:09:23 -05:00
}
2016-04-03 07:48:43 -04:00
node = calloc ( 1 , sizeof ( * node ) ) ;
2016-11-22 17:24:10 -05:00
if ( ! node ) {
2016-11-22 18:41:28 -05:00
memprintf ( err , " out of memory error " ) ;
2016-11-22 17:24:10 -05:00
return 0 ;
}
2012-12-20 18:09:23 -05:00
node - > type = LOG_FMT_EXPR ;
node - > expr = expr ;
node - > options = options ;
if ( arg_len ) {
node - > arg = my_strndup ( arg , arg_len ) ;
2016-11-22 18:41:28 -05:00
if ( ! parse_logformat_var_args ( node - > arg , node , err ) )
2016-11-22 17:11:21 -05:00
return 0 ;
2012-12-20 18:09:23 -05:00
}
2013-01-07 19:10:24 -05:00
if ( expr - > fetch - > val & cap & SMP_VAL_REQUEST )
2012-12-20 18:09:23 -05:00
node - > options | = LOG_OPT_REQ_CAP ; /* fetch method is request-compatible */
2013-01-07 19:10:24 -05:00
if ( expr - > fetch - > val & cap & SMP_VAL_RESPONSE )
2012-12-20 18:09:23 -05:00
node - > options | = LOG_OPT_RES_CAP ; /* fetch method is response-compatible */
2016-11-22 17:11:21 -05:00
if ( ! ( expr - > fetch - > val & cap ) ) {
2017-09-21 10:36:43 -04:00
free ( node ) ;
node = NULL ;
2016-11-22 18:41:28 -05:00
memprintf ( err , " sample fetch <%s> may not be reliably used here because it needs '%s' which is not available here " ,
text , sample_src_names ( expr - > fetch - > use ) ) ;
2016-11-22 17:11:21 -05:00
return 0 ;
}
2013-01-07 19:10:24 -05:00
2012-12-20 18:09:23 -05:00
/* check if we need to allocate an hdr_idx struct for HTTP parsing */
/* Note, we may also need to set curpx->to_log with certain fetches */
2013-03-24 02:22:08 -04:00
curpx - > http_needed | = ! ! ( expr - > fetch - > use & SMP_USE_HTTP_ANY ) ;
2012-12-20 18:09:23 -05:00
2014-01-31 09:08:02 -05:00
/* FIXME: temporary workaround for missing LW_XPRT and LW_REQ flags
* needed with some sample fetches ( eg : ssl * ) . We always set it for
* now on , but this will leave with sample capabilities soon .
2013-01-10 10:22:27 -05:00
*/
curpx - > to_log | = LW_XPRT ;
2014-01-31 09:08:02 -05:00
curpx - > to_log | = LW_REQ ;
2012-12-20 18:09:23 -05:00
LIST_ADDQ ( list_format , & node - > list ) ;
2016-11-22 17:11:21 -05:00
return 1 ;
2012-12-20 18:09:23 -05:00
}
2012-02-08 10:37:49 -05:00
/*
* Parse the log_format string and fill a linked list .
* Variable name are preceded by % and composed by characters [ a - zA - Z0 - 9 ] * : % varname
MAJOR: sample: maintain a per-proxy list of the fetch args to resolve
While ACL args were resolved after all the config was parsed, it was not the
case with sample fetch args because they're almost everywhere now.
The issue is that ACLs now solely rely on sample fetches, so their args
resolving doesn't work anymore. And many fetches involving a server, a
proxy or a userlist don't work at all.
The real issue is that at the bottom layers we have no information about
proxies, line numbers, even ACLs in order to report understandable errors,
and that at the top layers we have no visibility over the locations where
fetches are referenced (think log node).
After failing multiple unsatisfying solutions attempts, we now have a new
concept of args list. The principle is that every proxy has a list head
which contains a number of indications such as the config keyword, the
context where it's used, the file and line number, etc... and a list of
arguments. This list head is of the same type as the elements, so it
serves as a template for adding new elements. This way, it is filled from
top to bottom by the callers with the information they have (eg: line
numbers, ACL name, ...) and the lower layers just have to duplicate it and
add an element when they face an argument they cannot resolve yet.
Then at the end of the configuration parsing, a loop passes over each
proxy's list and resolves all the args in sequence. And this way there is
all necessary information to report verbose errors.
The first immediate benefit is that for the first time we got very precise
location of issues (arg number in a keyword in its context, ...). Second,
in order to do this we had to parse log-format and unique-id-format a bit
earlier, so that was a great opportunity for doing so when the directives
are encountered (unless it's a default section). This way, the recorded
line numbers for these args are the ones of the place where the log format
is declared, not the end of the file.
Userlists report slightly more information now. They're the only remaining
ones in the ACL resolving function.
2013-04-02 10:34:32 -04:00
* You can set arguments using { } : % { many arguments } varname .
* The curproxy - > conf . args . ctx must be set by the caller .
2012-03-12 07:46:41 -04:00
*
* str : the string to parse
* curproxy : the proxy affected
* list_format : the destination list
2013-02-05 12:52:25 -05:00
* options : LOG_OPT_ * to force on every node
2013-01-07 19:10:24 -05:00
* cap : all SMP_VAL_ * flags supported by the consumer
2016-11-22 17:11:21 -05:00
*
2016-11-22 18:41:28 -05:00
* The function returns 1 in success case , otherwise , it returns 0 and err is filled .
2012-02-08 10:37:49 -05:00
*/
2016-11-22 18:41:28 -05:00
int parse_logformat_string ( const char * fmt , struct proxy * curproxy , struct list * list_format , int options , int cap , char * * err )
2012-02-08 10:37:49 -05:00
{
2012-12-24 06:36:33 -05:00
char * sp , * str , * backfmt ; /* start pointer for text parts */
2012-12-20 15:23:42 -05:00
char * arg = NULL ; /* start pointer for args */
char * var = NULL ; /* start pointer for vars */
int arg_len = 0 ;
int var_len = 0 ;
int cformat ; /* current token format */
int pformat ; /* previous token format */
2012-02-08 10:37:49 -05:00
struct logformat_node * tmplf , * back ;
2012-12-24 06:36:33 -05:00
sp = str = backfmt = strdup ( fmt ) ;
2016-11-22 17:24:10 -05:00
if ( ! str ) {
2016-11-22 18:41:28 -05:00
memprintf ( err , " out of memory error " ) ;
2016-11-22 17:24:10 -05:00
return 0 ;
}
2012-08-09 10:41:35 -04:00
curproxy - > to_log | = LW_INIT ;
2012-04-02 10:22:10 -04:00
2012-02-08 10:37:49 -05:00
/* flush the list first. */
2012-03-12 07:46:41 -04:00
list_for_each_entry_safe ( tmplf , back , list_format , list ) {
2012-02-08 10:37:49 -05:00
LIST_DEL ( & tmplf - > list ) ;
free ( tmplf ) ;
}
2012-12-20 15:23:42 -05:00
for ( cformat = LF_INIT ; cformat ! = LF_END ; str + + ) {
2012-02-08 10:37:49 -05:00
pformat = cformat ;
2012-12-20 15:23:42 -05:00
if ( ! * str )
cformat = LF_END ; // preset it to save all states from doing this
2018-11-15 15:10:04 -05:00
/* The principle of the two-step state machine below is to first detect a change, and
2012-12-20 15:23:42 -05:00
* second have all common paths processed at one place . The common paths are the ones
* encountered in text areas ( LF_INIT , LF_TEXT , LF_SEPARATOR ) and at the end ( LF_END ) .
* We use the common LF_INIT state to dispatch to the different final states .
*/
switch ( pformat ) {
case LF_STARTVAR : // text immediately following a '%'
2012-12-20 18:09:23 -05:00
arg = NULL ; var = NULL ;
2012-12-20 15:23:42 -05:00
arg_len = var_len = 0 ;
if ( * str = = ' { ' ) { // optional argument
cformat = LF_STARG ;
arg = str + 1 ;
2012-02-08 10:37:49 -05:00
}
2012-12-20 18:09:23 -05:00
else if ( * str = = ' [ ' ) {
cformat = LF_STEXPR ;
var = str + 1 ; // store expr in variable name
}
2013-12-15 19:38:33 -05:00
else if ( isalpha ( ( unsigned char ) * str ) ) { // variable name
2012-02-08 10:37:49 -05:00
cformat = LF_VAR ;
2012-12-20 15:23:42 -05:00
var = str ;
2012-02-08 10:37:49 -05:00
}
2012-12-20 15:23:42 -05:00
else if ( * str = = ' % ' )
cformat = LF_TEXT ; // convert this character to a litteral (useful for '%')
2013-12-15 19:38:33 -05:00
else if ( isdigit ( ( unsigned char ) * str ) | | * str = = ' ' | | * str = = ' \t ' ) {
2013-12-02 11:45:48 -05:00
/* single '%' followed by blank or digit, send them both */
cformat = LF_TEXT ;
pformat = LF_TEXT ; /* finally we include the previous char as well */
sp = str - 1 ; /* send both the '%' and the current char */
2017-04-15 10:01:59 -04:00
memprintf ( err , " unexpected variable name near '%c' at position %d line : '%s'. Maybe you want to write a single '%%', use the syntax '%%%%' " ,
2016-11-22 18:41:28 -05:00
* str , ( int ) ( str - backfmt ) , fmt ) ;
2016-11-22 17:11:21 -05:00
return 0 ;
2013-12-02 11:45:48 -05:00
}
2012-12-20 15:23:42 -05:00
else
cformat = LF_INIT ; // handle other cases of litterals
break ;
case LF_STARG : // text immediately following '%{'
if ( * str = = ' } ' ) { // end of arg
2012-02-08 10:37:49 -05:00
cformat = LF_EDARG ;
2012-12-20 15:23:42 -05:00
arg_len = str - arg ;
* str = 0 ; // used for reporting errors
2012-02-08 10:37:49 -05:00
}
2012-12-20 15:23:42 -05:00
break ;
case LF_EDARG : // text immediately following '%{arg}'
2012-12-20 18:09:23 -05:00
if ( * str = = ' [ ' ) {
cformat = LF_STEXPR ;
var = str + 1 ; // store expr in variable name
break ;
}
2013-12-15 19:38:33 -05:00
else if ( isalnum ( ( unsigned char ) * str ) ) { // variable name
2012-02-08 10:37:49 -05:00
cformat = LF_VAR ;
2012-12-20 15:23:42 -05:00
var = str ;
break ;
}
2016-11-22 18:41:28 -05:00
memprintf ( err , " parse argument modifier without variable name near '%%{%s}' " , arg ) ;
2016-11-22 17:11:21 -05:00
return 0 ;
2012-12-20 15:23:42 -05:00
2012-12-20 18:09:23 -05:00
case LF_STEXPR : // text immediately following '%['
if ( * str = = ' ] ' ) { // end of arg
cformat = LF_EDEXPR ;
var_len = str - var ;
* str = 0 ; // needed for parsing the expression
}
break ;
2012-12-20 15:23:42 -05:00
case LF_VAR : // text part of a variable name
var_len = str - var ;
2013-12-15 19:38:33 -05:00
if ( ! isalnum ( ( unsigned char ) * str ) )
2012-12-20 15:23:42 -05:00
cformat = LF_INIT ; // not variable name anymore
break ;
2012-12-20 18:09:23 -05:00
default : // LF_INIT, LF_TEXT, LF_SEPARATOR, LF_END, LF_EDEXPR
2012-12-20 15:23:42 -05:00
cformat = LF_INIT ;
}
if ( cformat = = LF_INIT ) { /* resynchronize state to text/sep/startvar */
switch ( * str ) {
case ' % ' : cformat = LF_STARTVAR ; break ;
case ' ' : cformat = LF_SEPARATOR ; break ;
case 0 : cformat = LF_END ; break ;
default : cformat = LF_TEXT ; break ;
2012-02-08 10:37:49 -05:00
}
}
2012-12-20 15:23:42 -05:00
if ( cformat ! = pformat | | pformat = = LF_SEPARATOR ) {
switch ( pformat ) {
case LF_VAR :
2016-11-22 18:41:28 -05:00
if ( ! parse_logformat_var ( arg , arg_len , var , var_len , curproxy , list_format , & options , err ) )
2016-11-22 17:11:21 -05:00
return 0 ;
2012-12-20 15:23:42 -05:00
break ;
2012-12-20 18:09:23 -05:00
case LF_STEXPR :
2016-11-22 18:41:28 -05:00
if ( ! add_sample_to_logformat_list ( var , arg , arg_len , curproxy , list_format , options , cap , err ) )
2016-11-22 17:11:21 -05:00
return 0 ;
2012-12-20 18:09:23 -05:00
break ;
2012-12-20 15:23:42 -05:00
case LF_TEXT :
case LF_SEPARATOR :
2016-11-22 18:41:28 -05:00
if ( ! add_to_logformat_list ( sp , str , pformat , list_format , err ) )
2016-11-22 17:11:21 -05:00
return 0 ;
2012-12-20 15:23:42 -05:00
break ;
}
sp = str ; /* new start of text at every state switch and at every separator */
2012-02-08 10:37:49 -05:00
}
}
2012-12-20 15:23:42 -05:00
2016-11-22 17:11:21 -05:00
if ( pformat = = LF_STARTVAR | | pformat = = LF_STARG | | pformat = = LF_STEXPR ) {
2016-11-22 18:41:28 -05:00
memprintf ( err , " truncated line after '%s' " , var ? var : arg ? arg : " % " ) ;
2016-11-22 17:11:21 -05:00
return 0 ;
}
2012-12-24 06:36:33 -05:00
free ( backfmt ) ;
2016-11-22 17:11:21 -05:00
return 1 ;
2012-02-08 10:37:49 -05:00
}
2018-03-26 09:54:32 -04:00
/*
* Parse " log " keyword and update < logsrvs > list accordingly .
*
* When < do_del > is set , it means the " no log " line was parsed , so all log
* servers in < logsrvs > are released .
*
* Otherwise , we try to parse the " log " line . First of all , when the list is not
* the global one , we look for the parameter " global " . If we find it ,
* global . logsrvs is copied . Else we parse each arguments .
*
* The function returns 1 in success case , otherwise , it returns 0 and err is
* filled .
*/
int parse_logsrv ( char * * args , struct list * logsrvs , int do_del , char * * err )
{
struct sockaddr_storage * sk ;
struct logsrv * logsrv = NULL ;
int port1 , port2 ;
int cur_arg ;
/*
* " no log " : delete previous herited or defined syslog
* servers .
*/
if ( do_del ) {
struct logsrv * back ;
if ( * ( args [ 1 ] ) ! = 0 ) {
memprintf ( err , " 'no log' does not expect arguments " ) ;
goto error ;
}
list_for_each_entry_safe ( logsrv , back , logsrvs , list ) {
LIST_DEL ( & logsrv - > list ) ;
free ( logsrv ) ;
}
return 1 ;
}
/*
* " log global " : copy global . logrsvs linked list to the end of logsrvs
* list . But first , we check ( logsrvs ! = global . logsrvs ) .
*/
if ( * ( args [ 1 ] ) & & * ( args [ 2 ] ) = = 0 & & ! strcmp ( args [ 1 ] , " global " ) ) {
if ( logsrvs = = & global . logsrvs ) {
memprintf ( err , " 'global' is not supported for a global syslog server " ) ;
goto error ;
}
list_for_each_entry ( logsrv , & global . logsrvs , list ) {
2018-03-26 10:09:19 -04:00
struct logsrv * node ;
list_for_each_entry ( node , logsrvs , list ) {
if ( node - > ref = = logsrv )
goto skip_logsrv ;
}
node = malloc ( sizeof ( * node ) ) ;
2018-03-26 09:54:32 -04:00
memcpy ( node , logsrv , sizeof ( struct logsrv ) ) ;
2018-03-26 10:09:19 -04:00
node - > ref = logsrv ;
2018-03-26 09:54:32 -04:00
LIST_INIT ( & node - > list ) ;
LIST_ADDQ ( logsrvs , & node - > list ) ;
2018-03-26 10:09:19 -04:00
skip_logsrv :
continue ;
2018-03-26 09:54:32 -04:00
}
return 1 ;
}
/*
* " log <address> ...: parse a syslog server line
*/
if ( * ( args [ 1 ] ) = = 0 | | * ( args [ 2 ] ) = = 0 ) {
memprintf ( err , " expects <address> and <facility> %s as arguments " ,
( ( logsrvs = = & global . logsrvs ) ? " " : " or global " ) ) ;
goto error ;
}
2018-11-12 01:34:59 -05:00
/* take care of "stdout" and "stderr" as regular aliases for fd@1 / fd@2 */
if ( strcmp ( args [ 1 ] , " stdout " ) = = 0 )
args [ 1 ] = " fd@1 " ;
else if ( strcmp ( args [ 1 ] , " stderr " ) = = 0 )
args [ 1 ] = " fd@2 " ;
2018-03-26 09:54:32 -04:00
logsrv = calloc ( 1 , sizeof ( * logsrv ) ) ;
if ( ! logsrv ) {
memprintf ( err , " out of memory " ) ;
goto error ;
}
/* skip address for now, it will be parsed at the end */
cur_arg = 2 ;
/* just after the address, a length may be specified */
logsrv - > maxlen = MAX_SYSLOG_LEN ;
if ( strcmp ( args [ cur_arg ] , " len " ) = = 0 ) {
int len = atoi ( args [ cur_arg + 1 ] ) ;
if ( len < 80 | | len > 65535 ) {
memprintf ( err , " invalid log length '%s', must be between 80 and 65535 " ,
args [ cur_arg + 1 ] ) ;
goto error ;
}
logsrv - > maxlen = len ;
cur_arg + = 2 ;
}
if ( logsrv - > maxlen > global . max_syslog_len )
global . max_syslog_len = logsrv - > maxlen ;
/* after the length, a format may be specified */
if ( strcmp ( args [ cur_arg ] , " format " ) = = 0 ) {
logsrv - > format = get_log_format ( args [ cur_arg + 1 ] ) ;
if ( logsrv - > format < 0 ) {
memprintf ( err , " unknown log format '%s' " , args [ cur_arg + 1 ] ) ;
goto error ;
}
cur_arg + = 2 ;
}
/* parse the facility */
logsrv - > facility = get_log_facility ( args [ cur_arg ] ) ;
if ( logsrv - > facility < 0 ) {
memprintf ( err , " unknown log facility '%s' " , args [ cur_arg ] ) ;
goto error ;
}
cur_arg + + ;
/* parse the max syslog level (default: debug) */
logsrv - > level = 7 ;
if ( * ( args [ cur_arg ] ) ) {
logsrv - > level = get_log_level ( args [ cur_arg ] ) ;
if ( logsrv - > level < 0 ) {
memprintf ( err , " unknown optional log level '%s' " , args [ cur_arg ] ) ;
goto error ;
}
cur_arg + + ;
}
/* parse the limit syslog level (default: emerg) */
logsrv - > minlvl = 0 ;
if ( * ( args [ cur_arg ] ) ) {
logsrv - > minlvl = get_log_level ( args [ cur_arg ] ) ;
if ( logsrv - > minlvl < 0 ) {
memprintf ( err , " unknown optional minimum log level '%s' " , args [ cur_arg ] ) ;
goto error ;
}
cur_arg + + ;
}
/* Too many args */
if ( * ( args [ cur_arg ] ) ) {
memprintf ( err , " cannot handle unexpected argument '%s' " , args [ cur_arg ] ) ;
goto error ;
}
/* now, back to the address */
sk = str2sa_range ( args [ 1 ] , NULL , & port1 , & port2 , err , NULL , NULL , 1 ) ;
if ( ! sk )
goto error ;
logsrv - > addr = * sk ;
if ( sk - > ss_family = = AF_INET | | sk - > ss_family = = AF_INET6 ) {
if ( port1 ! = port2 ) {
memprintf ( err , " port ranges and offsets are not allowed in '%s' " , args [ 1 ] ) ;
goto error ;
}
logsrv - > addr = * sk ;
if ( ! port1 )
set_host_port ( & logsrv - > addr , SYSLOG_PORT ) ;
}
LIST_ADDQ ( logsrvs , & logsrv - > list ) ;
return 1 ;
error :
free ( logsrv ) ;
return 0 ;
}
2017-10-24 05:44:05 -04:00
/* Generic function to display messages prefixed by a label */
static void print_message ( const char * label , const char * fmt , va_list argp )
{
struct tm tm ;
char * head , * msg ;
head = msg = NULL ;
get_localtime ( date . tv_sec , & tm ) ;
memprintf ( & head , " [%s] %03d/%02d%02d%02d (%d) : " ,
label , tm . tm_yday , tm . tm_hour , tm . tm_min , tm . tm_sec , ( int ) getpid ( ) ) ;
memvprintf ( & msg , fmt , argp ) ;
if ( global . mode & MODE_STARTING )
memprintf ( & startup_logs , " %s%s%s " , ( startup_logs ? startup_logs : " " ) , head , msg ) ;
fprintf ( stderr , " %s%s " , head , msg ) ;
fflush ( stderr ) ;
free ( head ) ;
free ( msg ) ;
}
2006-06-25 20:48:02 -04:00
/*
* Displays the message on stderr with the date and pid . Overrides the quiet
* mode during startup .
*/
2017-11-24 10:50:31 -05:00
void ha_alert ( const char * fmt , . . . )
2006-06-25 20:48:02 -04:00
{
va_list argp ;
if ( ! ( global . mode & MODE_QUIET ) | | ( global . mode & ( MODE_VERBOSE | MODE_STARTING ) ) ) {
va_start ( argp , fmt ) ;
2017-10-24 05:44:05 -04:00
print_message ( " ALERT " , fmt , argp ) ;
2006-06-25 20:48:02 -04:00
va_end ( argp ) ;
}
}
/*
* Displays the message on stderr with the date and pid .
*/
2017-11-24 10:50:31 -05:00
void ha_warning ( const char * fmt , . . . )
2006-06-25 20:48:02 -04:00
{
va_list argp ;
if ( ! ( global . mode & MODE_QUIET ) | | ( global . mode & MODE_VERBOSE ) ) {
va_start ( argp , fmt ) ;
2017-10-24 05:44:05 -04:00
print_message ( " WARNING " , fmt , argp ) ;
2006-06-25 20:48:02 -04:00
va_end ( argp ) ;
}
}
2018-11-21 12:04:52 -05:00
/*
* Displays the message on stderr with the date and pid .
*/
void ha_notice ( const char * fmt , . . . )
{
va_list argp ;
if ( ! ( global . mode & MODE_QUIET ) | | ( global . mode & MODE_VERBOSE ) ) {
va_start ( argp , fmt ) ;
print_message ( " NOTICE " , fmt , argp ) ;
va_end ( argp ) ;
}
}
2006-06-25 20:48:02 -04:00
/*
* Displays the message on < out > only if quiet mode is not set .
*/
2006-10-15 09:17:57 -04:00
void qfprintf ( FILE * out , const char * fmt , . . . )
2006-06-25 20:48:02 -04:00
{
va_list argp ;
if ( ! ( global . mode & MODE_QUIET ) | | ( global . mode & MODE_VERBOSE ) ) {
va_start ( argp , fmt ) ;
vfprintf ( out , fmt , argp ) ;
fflush ( out ) ;
va_end ( argp ) ;
}
}
2015-09-22 10:05:32 -04:00
/*
* returns log format for < fmt > or - 1 if not found .
*/
int get_log_format ( const char * fmt )
{
int format ;
format = LOG_FORMATS - 1 ;
2015-10-01 07:18:13 -04:00
while ( format > = 0 & & strcmp ( log_formats [ format ] . name , fmt ) )
2015-09-22 10:05:32 -04:00
format - - ;
return format ;
}
2006-06-25 20:48:02 -04:00
/*
* returns log level for < lev > or - 1 if not found .
*/
int get_log_level ( const char * lev )
{
int level ;
level = NB_LOG_LEVELS - 1 ;
while ( level > = 0 & & strcmp ( log_levels [ level ] , lev ) )
level - - ;
return level ;
}
/*
* returns log facility for < fac > or - 1 if not found .
*/
int get_log_facility ( const char * fac )
{
int facility ;
facility = NB_LOG_FACILITIES - 1 ;
while ( facility > = 0 & & strcmp ( log_facilities [ facility ] , fac ) )
facility - - ;
2012-02-06 10:00:33 -05:00
2006-06-25 20:48:02 -04:00
return facility ;
}
2016-02-12 07:23:03 -05:00
/*
* Encode the string .
*
* When using the + E log format option , it will try to escape ' " \ ]'
* characters with ' \ ' as prefix . The same prefix should not be used as
* < escape > .
*/
static char * lf_encode_string ( char * start , char * stop ,
const char escape , const fd_set * map ,
const char * string ,
struct logformat_node * node )
{
if ( node - > options & LOG_OPT_ESC ) {
if ( start < stop ) {
stop - - ; /* reserve one byte for the final '\0' */
while ( start < stop & & * string ! = ' \0 ' ) {
if ( ! FD_ISSET ( ( unsigned char ) ( * string ) , map ) ) {
if ( ! FD_ISSET ( ( unsigned char ) ( * string ) , rfc5424_escape_map ) )
* start + + = * string ;
else {
if ( start + 2 > = stop )
break ;
* start + + = ' \\ ' ;
* start + + = * string ;
}
}
else {
if ( start + 3 > = stop )
break ;
* start + + = escape ;
* start + + = hextab [ ( * string > > 4 ) & 15 ] ;
* start + + = hextab [ * string & 15 ] ;
}
string + + ;
}
* start = ' \0 ' ;
}
}
else {
return encode_string ( start , stop , escape , map , string ) ;
}
return start ;
}
/*
* Encode the chunk .
*
* When using the + E log format option , it will try to escape ' " \ ]'
* characters with ' \ ' as prefix . The same prefix should not be used as
* < escape > .
*/
static char * lf_encode_chunk ( char * start , char * stop ,
const char escape , const fd_set * map ,
2018-07-13 05:56:34 -04:00
const struct buffer * chunk ,
2016-02-12 07:23:03 -05:00
struct logformat_node * node )
{
char * str , * end ;
if ( node - > options & LOG_OPT_ESC ) {
if ( start < stop ) {
2018-07-13 04:54:26 -04:00
str = chunk - > area ;
end = chunk - > area + chunk - > data ;
2016-02-12 07:23:03 -05:00
stop - - ; /* reserve one byte for the final '\0' */
while ( start < stop & & str < end ) {
if ( ! FD_ISSET ( ( unsigned char ) ( * str ) , map ) ) {
if ( ! FD_ISSET ( ( unsigned char ) ( * str ) , rfc5424_escape_map ) )
* start + + = * str ;
else {
if ( start + 2 > = stop )
break ;
* start + + = ' \\ ' ;
* start + + = * str ;
}
}
else {
if ( start + 3 > = stop )
break ;
* start + + = escape ;
* start + + = hextab [ ( * str > > 4 ) & 15 ] ;
* start + + = hextab [ * str & 15 ] ;
}
str + + ;
}
* start = ' \0 ' ;
}
}
else {
return encode_chunk ( start , stop , escape , map , chunk ) ;
}
return start ;
}
2012-02-08 10:38:44 -05:00
/*
* Write a string in the log string
2016-02-12 07:23:03 -05:00
* Take cares of quote and escape options
2012-02-08 10:38:44 -05:00
*
2018-11-15 15:10:04 -05:00
* Return the address of the \ 0 character , or NULL on error
2012-02-08 10:38:44 -05:00
*/
2018-09-05 09:23:10 -04:00
char * lf_text_len ( char * dst , const char * src , size_t len , size_t size , const struct logformat_node * node )
2012-02-08 10:38:44 -05:00
{
2012-12-21 13:23:44 -05:00
if ( size < 2 )
return NULL ;
if ( node - > options & LOG_OPT_QUOTE ) {
* ( dst + + ) = ' " ' ;
size - - ;
2012-02-27 05:23:10 -05:00
}
2012-12-21 13:23:44 -05:00
2013-02-05 12:52:25 -05:00
if ( src & & len ) {
2016-07-25 05:35:02 -04:00
if ( + + len > size )
len = size ;
2016-02-12 07:23:03 -05:00
if ( node - > options & LOG_OPT_ESC ) {
char * ret ;
2016-07-25 05:35:02 -04:00
ret = escape_string ( dst , dst + len , ' \\ ' , rfc5424_escape_map , src ) ;
2016-02-12 07:23:03 -05:00
if ( ret = = NULL | | * ret ! = ' \0 ' )
return NULL ;
len = ret - dst ;
}
else {
len = strlcpy2 ( dst , src , len ) ;
}
2012-12-21 13:23:44 -05:00
size - = len ;
dst + = len ;
}
2013-02-05 12:52:25 -05:00
else if ( ( node - > options & ( LOG_OPT_QUOTE | LOG_OPT_MANDATORY ) ) = = LOG_OPT_MANDATORY ) {
if ( size < 2 )
return NULL ;
* ( dst + + ) = ' - ' ;
}
2012-12-21 13:23:44 -05:00
if ( node - > options & LOG_OPT_QUOTE ) {
if ( size < 2 )
return NULL ;
* ( dst + + ) = ' " ' ;
}
* dst = ' \0 ' ;
2012-02-27 05:23:10 -05:00
return dst ;
2012-02-08 10:38:44 -05:00
}
2018-09-05 09:23:10 -04:00
static inline char * lf_text ( char * dst , const char * src , size_t size , const struct logformat_node * node )
2012-12-21 13:23:44 -05:00
{
return lf_text_len ( dst , src , size , size , node ) ;
}
2012-04-05 12:02:55 -04:00
/*
2018-11-15 15:10:04 -05:00
* Write a IP address to the log string
2012-04-05 12:02:55 -04:00
* + X option write in hexadecimal notation , most signifant byte on the left
*/
2018-09-05 09:23:10 -04:00
char * lf_ip ( char * dst , const struct sockaddr * sockaddr , size_t size , const struct logformat_node * node )
2012-04-05 12:02:55 -04:00
{
char * ret = dst ;
int iret ;
char pn [ INET6_ADDRSTRLEN ] ;
if ( node - > options & LOG_OPT_HEXA ) {
const unsigned char * addr = ( const unsigned char * ) & ( ( struct sockaddr_in * ) sockaddr ) - > sin_addr . s_addr ;
iret = snprintf ( dst , size , " %02X%02X%02X%02X " , addr [ 0 ] , addr [ 1 ] , addr [ 2 ] , addr [ 3 ] ) ;
if ( iret < 0 | | iret > size )
return NULL ;
ret + = iret ;
} else {
addr_to_str ( ( struct sockaddr_storage * ) sockaddr , pn , sizeof ( pn ) ) ;
ret = lf_text ( dst , pn , size , node ) ;
if ( ret = = NULL )
return NULL ;
}
return ret ;
}
/*
* Write a port to the log
* + X option write in hexadecimal notation , most signifant byte on the left
*/
2018-09-05 09:23:10 -04:00
char * lf_port ( char * dst , const struct sockaddr * sockaddr , size_t size , const struct logformat_node * node )
2012-04-05 12:02:55 -04:00
{
char * ret = dst ;
int iret ;
if ( node - > options & LOG_OPT_HEXA ) {
const unsigned char * port = ( const unsigned char * ) & ( ( struct sockaddr_in * ) sockaddr ) - > sin_port ;
iret = snprintf ( dst , size , " %02X%02X " , port [ 0 ] , port [ 1 ] ) ;
if ( iret < 0 | | iret > size )
return NULL ;
ret + = iret ;
} else {
ret = ltoa_o ( get_host_port ( ( struct sockaddr_storage * ) sockaddr ) , dst , size ) ;
if ( ret = = NULL )
return NULL ;
}
return ret ;
}
2015-09-22 10:05:32 -04:00
/* Re-generate time-based part of the syslog header in RFC3164 format at
* the beginning of logheader once a second and return the pointer to the
* first character after it .
2012-03-19 11:51:53 -04:00
*/
2015-09-25 13:17:44 -04:00
static char * update_log_hdr ( const time_t time )
2006-06-25 20:48:02 -04:00
{
2017-06-02 10:20:16 -04:00
static THREAD_LOCAL long tvsec ;
static THREAD_LOCAL char * dataptr = NULL ; /* backup of last end of header, NULL first time */
2018-07-13 05:56:34 -04:00
static THREAD_LOCAL struct buffer host = { } ;
2017-06-02 10:20:16 -04:00
static THREAD_LOCAL int sep = 0 ;
2006-06-25 20:48:02 -04:00
2015-09-25 13:17:44 -04:00
if ( unlikely ( time ! = tvsec | | dataptr = = NULL ) ) {
2006-06-25 20:48:02 -04:00
/* this string is rebuild only once a second */
2007-10-25 04:34:16 -04:00
struct tm tm ;
2012-03-19 11:51:53 -04:00
int hdr_len ;
2007-10-25 04:34:16 -04:00
2015-09-25 13:17:44 -04:00
tvsec = time ;
2007-10-25 04:34:16 -04:00
get_localtime ( tvsec , & tm ) ;
2006-06-25 20:48:02 -04:00
2018-07-13 04:54:26 -04:00
if ( unlikely ( global . log_send_hostname ! = host . area ) ) {
host . area = global . log_send_hostname ;
host . data = host . area ? strlen ( host . area ) : 0 ;
sep = host . data ? 1 : 0 ;
2015-10-01 07:18:13 -04:00
}
2015-09-19 16:09:02 -04:00
hdr_len = snprintf ( logheader , global . max_syslog_len ,
2015-10-01 07:18:13 -04:00
" <<<<>%s %2d %02d:%02d:%02d %.*s%*s " ,
2007-10-25 04:34:16 -04:00
monthname [ tm . tm_mon ] ,
2015-10-01 07:18:13 -04:00
tm . tm_mday , tm . tm_hour , tm . tm_min , tm . tm_sec ,
2018-07-13 04:54:26 -04:00
( int ) host . data , host . area , sep , " " ) ;
2006-06-25 20:48:02 -04:00
/* WARNING: depending upon implementations, snprintf may return
* either - 1 or the number of bytes that would be needed to store
* the total message . In both cases , we must adjust it .
*/
2014-06-27 12:10:07 -04:00
if ( hdr_len < 0 | | hdr_len > global . max_syslog_len )
hdr_len = global . max_syslog_len ;
2006-06-25 20:48:02 -04:00
2015-09-19 16:09:02 -04:00
dataptr = logheader + hdr_len ;
2006-06-25 20:48:02 -04:00
}
2015-01-07 09:03:42 -05:00
dataptr [ 0 ] = 0 ; // ensure we get rid of any previous attempt
2015-09-19 16:35:44 -04:00
return dataptr ;
2012-02-06 10:00:33 -05:00
}
2015-09-22 10:05:32 -04:00
/* Re-generate time-based part of the syslog header in RFC5424 format at
* the beginning of logheader_rfc5424 once a second and return the pointer
* to the first character after it .
*/
2015-09-25 13:17:44 -04:00
static char * update_log_hdr_rfc5424 ( const time_t time )
2015-09-22 10:05:32 -04:00
{
2017-06-02 10:20:16 -04:00
static THREAD_LOCAL long tvsec ;
static THREAD_LOCAL char * dataptr = NULL ; /* backup of last end of header, NULL first time */
2016-03-27 05:08:03 -04:00
const char * gmt_offset ;
2015-09-22 10:05:32 -04:00
2015-09-25 13:17:44 -04:00
if ( unlikely ( time ! = tvsec | | dataptr = = NULL ) ) {
2015-09-22 10:05:32 -04:00
/* this string is rebuild only once a second */
struct tm tm ;
int hdr_len ;
2015-09-25 13:17:44 -04:00
tvsec = time ;
2015-09-22 10:05:32 -04:00
get_localtime ( tvsec , & tm ) ;
2016-03-26 21:04:16 -04:00
gmt_offset = get_gmt_offset ( time , & tm ) ;
2015-09-22 10:05:32 -04:00
hdr_len = snprintf ( logheader_rfc5424 , global . max_syslog_len ,
2015-10-09 15:31:43 -04:00
" <<<<>1 %4d-%02d-%02dT%02d:%02d:%02d%.3s:%.2s %s " ,
2015-09-22 10:05:32 -04:00
tm . tm_year + 1900 , tm . tm_mon + 1 , tm . tm_mday ,
2015-10-09 15:31:43 -04:00
tm . tm_hour , tm . tm_min , tm . tm_sec ,
2016-03-27 05:08:03 -04:00
gmt_offset , gmt_offset + 3 ,
2015-10-01 07:18:13 -04:00
global . log_send_hostname ? global . log_send_hostname : hostname ) ;
2015-09-22 10:05:32 -04:00
/* WARNING: depending upon implementations, snprintf may return
* either - 1 or the number of bytes that would be needed to store
* the total message . In both cases , we must adjust it .
*/
if ( hdr_len < 0 | | hdr_len > global . max_syslog_len )
hdr_len = global . max_syslog_len ;
dataptr = logheader_rfc5424 + hdr_len ;
}
dataptr [ 0 ] = 0 ; // ensure we get rid of any previous attempt
return dataptr ;
}
2012-02-06 10:00:33 -05:00
/*
2015-09-19 16:09:02 -04:00
* This function sends the syslog message using a printf format string . It
* expects an LF - terminated message .
2012-02-06 10:00:33 -05:00
*/
void send_log ( struct proxy * p , int level , const char * format , . . . )
{
va_list argp ;
2012-03-19 11:51:53 -04:00
int data_len ;
2012-02-06 10:00:33 -05:00
2015-01-15 10:29:53 -05:00
if ( level < 0 | | format = = NULL | | logline = = NULL )
2012-02-06 10:00:33 -05:00
return ;
va_start ( argp , format ) ;
2015-09-19 16:09:02 -04:00
data_len = vsnprintf ( logline , global . max_syslog_len , format , argp ) ;
2014-06-27 12:10:07 -04:00
if ( data_len < 0 | | data_len > global . max_syslog_len )
data_len = global . max_syslog_len ;
2006-06-25 20:48:02 -04:00
va_end ( argp ) ;
2012-02-06 10:00:33 -05:00
2015-09-25 13:17:44 -04:00
__send_log ( p , level , logline , data_len , default_rfc5424_sd_log_format , 2 ) ;
2012-02-06 10:00:33 -05:00
}
/*
* This function sends a syslog message .
* It doesn ' t care about errors nor does it report them .
2015-09-25 13:17:44 -04:00
* It overrides the last byte of the message vector with an LF character .
* The arguments < sd > and < sd_size > are used for the structured - data part
* in RFC5424 formatted syslog messages .
2012-02-06 10:00:33 -05:00
*/
2015-09-25 13:17:44 -04:00
void __send_log ( struct proxy * p , int level , char * message , size_t size , char * sd , size_t sd_size )
2012-02-06 10:00:33 -05:00
{
2017-06-02 10:20:16 -04:00
static THREAD_LOCAL struct iovec iovec [ NB_MSG_IOVEC_ELEMENTS ] = { } ;
static THREAD_LOCAL struct msghdr msghdr = {
//.msg_iov = iovec,
2015-09-16 12:25:42 -04:00
. msg_iovlen = NB_MSG_IOVEC_ELEMENTS
} ;
2017-06-02 10:20:16 -04:00
static THREAD_LOCAL int logfdunix = - 1 ; /* syslog to AF_UNIX socket */
static THREAD_LOCAL int logfdinet = - 1 ; /* syslog to AF_INET socket */
static THREAD_LOCAL char * dataptr = NULL ;
2012-02-06 10:00:33 -05:00
int fac_level ;
struct list * logsrvs = NULL ;
struct logsrv * tmp = NULL ;
int nblogger ;
2015-09-22 10:05:32 -04:00
char * hdr , * hdr_ptr ;
2015-09-19 16:09:02 -04:00
size_t hdr_size ;
2015-09-25 13:17:44 -04:00
time_t time = date . tv_sec ;
2018-07-13 05:56:34 -04:00
struct buffer * tag = & global . log_tag ;
2017-06-02 10:20:16 -04:00
static THREAD_LOCAL int curr_pid ;
static THREAD_LOCAL char pidstr [ 100 ] ;
2018-07-13 05:56:34 -04:00
static THREAD_LOCAL struct buffer pid ;
2017-06-02 10:20:16 -04:00
msghdr . msg_iov = iovec ;
2012-02-06 10:00:33 -05:00
dataptr = message ;
2006-06-25 20:48:02 -04:00
if ( p = = NULL ) {
2011-10-12 11:50:54 -04:00
if ( ! LIST_ISEMPTY ( & global . logsrvs ) ) {
logsrvs = & global . logsrvs ;
2006-06-25 20:48:02 -04:00
}
} else {
2011-10-12 11:50:54 -04:00
if ( ! LIST_ISEMPTY ( & p - > logsrvs ) ) {
logsrvs = & p - > logsrvs ;
2006-06-25 20:48:02 -04:00
}
2018-07-13 04:54:26 -04:00
if ( p - > log_tag . area ) {
2015-10-01 07:18:13 -04:00
tag = & p - > log_tag ;
}
2006-06-25 20:48:02 -04:00
}
2011-10-12 11:50:54 -04:00
if ( ! logsrvs )
return ;
2015-10-01 07:18:13 -04:00
if ( unlikely ( curr_pid ! = getpid ( ) ) ) {
curr_pid = getpid ( ) ;
ltoa_o ( curr_pid , pidstr , sizeof ( pidstr ) ) ;
chunk_initstr ( & pid , pidstr ) ;
}
2007-12-05 04:47:29 -05:00
/* Send log messages to syslog server. */
2011-10-12 11:50:54 -04:00
nblogger = 0 ;
list_for_each_entry ( tmp , logsrvs , list ) {
const struct logsrv * logsrv = tmp ;
2018-12-15 09:48:48 -05:00
int * plogfd ;
2018-11-12 02:45:00 -05:00
char * pid_sep1 = " " , * pid_sep2 = " " ;
char logheader_short [ 3 ] ;
2007-12-05 04:47:29 -05:00
int sent ;
2015-09-19 16:35:44 -04:00
int maxlen ;
2015-09-19 16:09:02 -04:00
int hdr_max = 0 ;
2015-10-01 07:18:13 -04:00
int tag_max = 0 ;
int pid_sep1_max = 0 ;
int pid_max = 0 ;
int pid_sep2_max = 0 ;
2015-09-25 13:17:44 -04:00
int sd_max = 0 ;
2015-09-28 10:01:03 -04:00
int max = 0 ;
2007-12-05 04:47:29 -05:00
2014-06-23 12:07:15 -04:00
nblogger + + ;
2006-06-25 20:48:02 -04:00
/* we can filter the level of the messages that are sent to each logger */
2011-10-12 11:50:54 -04:00
if ( level > logsrv - > level )
2006-06-25 20:48:02 -04:00
continue ;
2012-02-27 05:23:10 -05:00
2018-12-15 09:48:48 -05:00
if ( logsrv - > addr . ss_family = = AF_UNSPEC ) {
/* the socket's address is a file descriptor */
plogfd = ( int * ) & ( ( struct sockaddr_in * ) & logsrv - > addr ) - > sin_addr . s_addr ;
if ( unlikely ( ! ( ( struct sockaddr_in * ) & logsrv - > addr ) - > sin_port ) ) {
2019-01-02 14:09:33 -05:00
/* FD not yet initialized to non-blocking mode.
* DON ' T DO IT ON A TERMINAL !
*/
if ( ! isatty ( * plogfd ) )
fcntl ( * plogfd , F_SETFL , O_NONBLOCK ) ;
2018-12-15 09:48:48 -05:00
( ( struct sockaddr_in * ) & logsrv - > addr ) - > sin_port = 1 ;
2018-11-12 01:34:59 -05:00
}
2018-12-15 09:48:48 -05:00
}
else if ( logsrv - > addr . ss_family = = AF_UNIX )
plogfd = & logfdunix ;
else
plogfd = & logfdinet ;
if ( unlikely ( * plogfd < 0 ) ) {
/* socket not successfully initialized yet */
if ( ( * plogfd = socket ( logsrv - > addr . ss_family , SOCK_DGRAM ,
( logsrv - > addr . ss_family = = AF_UNIX ) ? 0 : IPPROTO_UDP ) ) < 0 ) {
2018-03-20 06:17:29 -04:00
static char once ;
if ( ! once ) {
once = 1 ; /* note: no need for atomic ops here */
2018-11-12 01:00:11 -05:00
ha_alert ( " socket() failed in logger #%d: %s (errno=%d) \n " ,
2018-03-20 06:17:29 -04:00
nblogger , strerror ( errno ) , errno ) ;
}
2014-06-23 12:07:15 -04:00
continue ;
2018-11-13 12:30:12 -05:00
} else {
/* we don't want to receive anything on this socket */
setsockopt ( * plogfd , SOL_SOCKET , SO_RCVBUF , & zero , sizeof ( zero ) ) ;
/* does nothing under Linux, maybe needed for others */
shutdown ( * plogfd , SHUT_RD ) ;
fcntl ( * plogfd , F_SETFD , fcntl ( * plogfd , F_GETFD , FD_CLOEXEC ) | FD_CLOEXEC ) ;
2014-06-23 12:07:15 -04:00
}
}
2015-09-22 10:05:32 -04:00
switch ( logsrv - > format ) {
case LOG_FORMAT_RFC3164 :
hdr = logheader ;
2015-09-25 13:17:44 -04:00
hdr_ptr = update_log_hdr ( time ) ;
2015-09-22 10:05:32 -04:00
break ;
case LOG_FORMAT_RFC5424 :
hdr = logheader_rfc5424 ;
2015-09-25 13:17:44 -04:00
hdr_ptr = update_log_hdr_rfc5424 ( time ) ;
sd_max = sd_size ; /* the SD part allowed only in RFC5424 */
2015-09-22 10:05:32 -04:00
break ;
2018-11-12 02:45:00 -05:00
case LOG_FORMAT_SHORT :
/* all fields are known, skip the header generation */
hdr = logheader_short ;
hdr [ 0 ] = ' < ' ;
hdr [ 1 ] = ' 0 ' + MAX ( level , logsrv - > minlvl ) ;
hdr [ 2 ] = ' > ' ;
hdr_ptr = hdr ;
hdr_max = 3 ;
maxlen = logsrv - > maxlen - hdr_max ;
max = MIN ( size , maxlen ) - 1 ;
goto send ;
2018-11-12 05:57:56 -05:00
case LOG_FORMAT_RAW :
/* all fields are known, skip the header generation */
hdr_ptr = hdr = " " ;
hdr_max = 0 ;
maxlen = logsrv - > maxlen ;
max = MIN ( size , maxlen ) - 1 ;
goto send ;
2015-09-22 10:05:32 -04:00
default :
continue ; /* must never happen */
}
hdr_size = hdr_ptr - hdr ;
2006-06-25 20:48:02 -04:00
/* For each target, we may have a different facility.
* We can also have a different log level for each message .
* This induces variations in the message header length .
* Since we don ' t want to recompute it each time , nor copy it every
* time , we only change the facility in the pre - computed header ,
* and we change the pointer to the header accordingly .
*/
2011-10-12 11:50:54 -04:00
fac_level = ( logsrv - > facility < < 3 ) + MAX ( level , logsrv - > minlvl ) ;
2015-09-22 10:05:32 -04:00
hdr_ptr = hdr + 3 ; /* last digit of the log level */
2006-06-25 20:48:02 -04:00
do {
2015-09-19 16:09:02 -04:00
* hdr_ptr = ' 0 ' + fac_level % 10 ;
2006-06-25 20:48:02 -04:00
fac_level / = 10 ;
2015-09-19 16:09:02 -04:00
hdr_ptr - - ;
2015-09-22 10:05:32 -04:00
} while ( fac_level & & hdr_ptr > hdr ) ;
2015-09-19 16:09:02 -04:00
* hdr_ptr = ' < ' ;
2015-09-22 10:05:32 -04:00
hdr_max = hdr_size - ( hdr_ptr - hdr ) ;
2014-06-27 12:10:07 -04:00
2015-10-01 07:18:13 -04:00
/* time-based header */
2015-09-19 16:09:02 -04:00
if ( unlikely ( hdr_size > = logsrv - > maxlen ) ) {
hdr_max = MIN ( hdr_max , logsrv - > maxlen ) - 1 ;
2015-09-25 13:17:44 -04:00
sd_max = 0 ;
2015-09-19 16:09:02 -04:00
goto send ;
}
2015-09-19 16:35:44 -04:00
maxlen = logsrv - > maxlen - hdr_max ;
2015-10-01 07:18:13 -04:00
/* tag */
2018-07-13 04:54:26 -04:00
tag_max = tag - > data ;
2015-10-01 07:18:13 -04:00
if ( unlikely ( tag_max > = maxlen ) ) {
tag_max = maxlen - 1 ;
sd_max = 0 ;
goto send ;
}
maxlen - = tag_max ;
/* first pid separator */
2018-07-13 04:54:26 -04:00
pid_sep1_max = log_formats [ logsrv - > format ] . pid . sep1 . data ;
2015-10-01 07:18:13 -04:00
if ( unlikely ( pid_sep1_max > = maxlen ) ) {
pid_sep1_max = maxlen - 1 ;
sd_max = 0 ;
goto send ;
}
2018-07-13 04:54:26 -04:00
pid_sep1 = log_formats [ logsrv - > format ] . pid . sep1 . area ;
2015-10-01 07:18:13 -04:00
maxlen - = pid_sep1_max ;
/* pid */
2018-07-13 04:54:26 -04:00
pid_max = pid . data ;
2015-10-01 07:18:13 -04:00
if ( unlikely ( pid_max > = maxlen ) ) {
pid_max = maxlen - 1 ;
sd_max = 0 ;
goto send ;
}
maxlen - = pid_max ;
/* second pid separator */
2018-07-13 04:54:26 -04:00
pid_sep2_max = log_formats [ logsrv - > format ] . pid . sep2 . data ;
2015-10-01 07:18:13 -04:00
if ( unlikely ( pid_sep2_max > = maxlen ) ) {
pid_sep2_max = maxlen - 1 ;
2015-09-25 13:17:44 -04:00
sd_max = 0 ;
2015-09-19 16:35:44 -04:00
goto send ;
}
2018-07-13 04:54:26 -04:00
pid_sep2 = log_formats [ logsrv - > format ] . pid . sep2 . area ;
2015-10-01 07:18:13 -04:00
maxlen - = pid_sep2_max ;
2015-09-19 16:09:02 -04:00
2015-10-01 07:18:13 -04:00
/* structured-data */
2015-09-25 13:17:44 -04:00
if ( sd_max > = maxlen ) {
sd_max = maxlen - 1 ;
goto send ;
}
2015-09-19 16:09:02 -04:00
2015-09-28 10:01:03 -04:00
max = MIN ( size , maxlen - sd_max ) - 1 ;
2015-09-19 16:09:02 -04:00
send :
iovec [ 0 ] . iov_base = hdr_ptr ;
2015-10-01 07:18:13 -04:00
iovec [ 0 ] . iov_len = hdr_max ;
2018-07-13 04:54:26 -04:00
iovec [ 1 ] . iov_base = tag - > area ;
2015-10-01 07:18:13 -04:00
iovec [ 1 ] . iov_len = tag_max ;
iovec [ 2 ] . iov_base = pid_sep1 ;
iovec [ 2 ] . iov_len = pid_sep1_max ;
2018-07-13 04:54:26 -04:00
iovec [ 3 ] . iov_base = pid . area ;
2015-10-01 07:18:13 -04:00
iovec [ 3 ] . iov_len = pid_max ;
iovec [ 4 ] . iov_base = pid_sep2 ;
iovec [ 4 ] . iov_len = pid_sep2_max ;
iovec [ 5 ] . iov_base = sd ;
iovec [ 5 ] . iov_len = sd_max ;
iovec [ 6 ] . iov_base = dataptr ;
iovec [ 6 ] . iov_len = max ;
iovec [ 7 ] . iov_base = " \n " ; /* insert a \n at the end of the message */
iovec [ 7 ] . iov_len = 1 ;
2015-09-16 12:25:42 -04:00
2018-11-12 01:34:59 -05:00
if ( logsrv - > addr . ss_family = = AF_UNSPEC ) {
/* the target is a direct file descriptor */
sent = writev ( * plogfd , iovec , 8 ) ;
}
else {
msghdr . msg_name = ( struct sockaddr * ) & logsrv - > addr ;
msghdr . msg_namelen = get_addr_len ( & logsrv - > addr ) ;
2015-09-16 12:25:42 -04:00
2018-11-12 01:34:59 -05:00
sent = sendmsg ( * plogfd , & msghdr , MSG_DONTWAIT | MSG_NOSIGNAL ) ;
}
2014-06-27 12:10:07 -04:00
2007-12-05 04:47:29 -05:00
if ( sent < 0 ) {
2018-03-20 06:17:29 -04:00
static char once ;
2018-11-12 01:25:28 -05:00
if ( errno = = EAGAIN )
2019-03-08 12:53:21 -05:00
_HA_ATOMIC_ADD ( & dropped_logs , 1 ) ;
2018-11-12 01:25:28 -05:00
else if ( ! once ) {
2018-03-20 06:17:29 -04:00
once = 1 ; /* note: no need for atomic ops here */
2018-11-12 01:34:59 -05:00
ha_alert ( " sendmsg()/writev() failed in logger #%d: %s (errno=%d) \n " ,
2018-03-20 06:17:29 -04:00
nblogger , strerror ( errno ) , errno ) ;
}
2007-12-05 04:47:29 -05:00
}
2006-06-25 20:48:02 -04:00
}
}
2012-02-27 05:23:10 -05:00
extern fd_set hdr_encode_map [ ] ;
extern fd_set url_encode_map [ ] ;
2014-03-13 11:46:18 -04:00
extern fd_set http_encode_map [ ] ;
2012-02-27 05:23:10 -05:00
2012-04-05 15:18:22 -04:00
const char sess_cookie [ 8 ] = " NIDVEOU7 " ; /* No cookie, Invalid cookie, cookie for a Down server, Valid cookie, Expired cookie, Old cookie, Unused, unknown */
2012-02-27 05:23:10 -05:00
const char sess_set_cookie [ 8 ] = " NPDIRU67 " ; /* No set-cookie, Set-cookie found and left unchanged (passive),
Set - cookie Deleted , Set - Cookie Inserted , Set - cookie Rewritten ,
Set - cookie Updated , unknown , unknown */
2012-03-12 07:46:41 -04:00
/*
* try to write a character if there is enough space , or goto out
*/
2012-02-27 05:23:10 -05:00
# define LOGCHAR(x) do { \
2012-03-12 07:46:41 -04:00
if ( tmplog < dst + maxsize - 1 ) { \
2012-02-27 05:23:10 -05:00
* ( tmplog + + ) = ( x ) ; \
} else { \
goto out ; \
} \
} while ( 0 )
2006-06-25 20:48:02 -04:00
2012-03-12 07:46:41 -04:00
2018-11-26 10:31:20 -05:00
/* Initializes some log data at boot */
static void init_log ( )
2016-02-12 07:23:03 -05:00
{
char * tmp ;
2018-09-10 12:16:53 -04:00
int i ;
2016-02-12 07:23:03 -05:00
/* Initialize the escape map for the RFC5424 structured-data : '"\]'
* inside PARAM - VALUE should be escaped with ' \ ' as prefix .
* See https : //tools.ietf.org/html/rfc5424#section-6.3.3 for more
* details .
*/
memset ( rfc5424_escape_map , 0 , sizeof ( rfc5424_escape_map ) ) ;
tmp = " \" \\ ] " ;
while ( * tmp ) {
FD_SET ( * tmp , rfc5424_escape_map ) ;
tmp + + ;
}
2018-09-10 12:16:53 -04:00
/* initialize the log header encoding map : '{|}"#' should be encoded with
* ' # ' as prefix , as well as non - printable characters ( < 32 or > = 127 ) .
* URL encoding only requires ' " ' , ' # ' to be encoded as well as non -
* printable characters above .
*/
memset ( hdr_encode_map , 0 , sizeof ( hdr_encode_map ) ) ;
memset ( url_encode_map , 0 , sizeof ( url_encode_map ) ) ;
for ( i = 0 ; i < 32 ; i + + ) {
FD_SET ( i , hdr_encode_map ) ;
FD_SET ( i , url_encode_map ) ;
}
for ( i = 127 ; i < 256 ; i + + ) {
FD_SET ( i , hdr_encode_map ) ;
FD_SET ( i , url_encode_map ) ;
}
tmp = " \" #{|} " ;
while ( * tmp ) {
FD_SET ( * tmp , hdr_encode_map ) ;
tmp + + ;
}
tmp = " \" # " ;
while ( * tmp ) {
FD_SET ( * tmp , url_encode_map ) ;
tmp + + ;
}
/* initialize the http header encoding map. The draft httpbis define the
* header content as :
*
* HTTP - message = start - line
* * ( header - field CRLF )
* CRLF
* [ message - body ]
* header - field = field - name " : " OWS field - value OWS
* field - value = * ( field - content / obs - fold )
* field - content = field - vchar [ 1 * ( SP / HTAB ) field - vchar ]
* obs - fold = CRLF 1 * ( SP / HTAB )
* field - vchar = VCHAR / obs - text
* VCHAR = % x21 - 7 E
* obs - text = % x80 - FF
*
* All the chars are encoded except " VCHAR " , " obs-text " , SP and HTAB .
* The encoded chars are form 0x00 to 0x08 , 0x0a to 0x1f and 0x7f . The
2018-11-15 15:10:04 -05:00
* " obs-fold " is voluntarily forgotten because haproxy remove this .
2018-09-10 12:16:53 -04:00
*/
memset ( http_encode_map , 0 , sizeof ( http_encode_map ) ) ;
for ( i = 0x00 ; i < = 0x08 ; i + + )
FD_SET ( i , http_encode_map ) ;
for ( i = 0x0a ; i < = 0x1f ; i + + )
FD_SET ( i , http_encode_map ) ;
FD_SET ( 0x7f , http_encode_map ) ;
2016-02-12 07:23:03 -05:00
}
2018-11-26 10:31:20 -05:00
INITCALL0 ( STG_PREPARE , init_log ) ;
2017-10-27 07:53:47 -04:00
static int init_log_buffers_per_thread ( )
{
return init_log_buffers ( ) ;
}
static void deinit_log_buffers_per_thread ( )
{
deinit_log_buffers ( ) ;
}
2017-07-26 09:33:35 -04:00
/* Initialize log buffers used for syslog messages */
int init_log_buffers ( )
{
logheader = my_realloc2 ( logheader , global . max_syslog_len + 1 ) ;
logheader_rfc5424 = my_realloc2 ( logheader_rfc5424 , global . max_syslog_len + 1 ) ;
logline = my_realloc2 ( logline , global . max_syslog_len + 1 ) ;
logline_rfc5424 = my_realloc2 ( logline_rfc5424 , global . max_syslog_len + 1 ) ;
if ( ! logheader | | ! logline_rfc5424 | | ! logline | | ! logline_rfc5424 )
return 0 ;
return 1 ;
}
/* Deinitialize log buffers used for syslog messages */
void deinit_log_buffers ( )
{
2019-03-07 08:19:24 -05:00
void * tmp_startup_logs ;
2017-07-26 09:33:35 -04:00
free ( logheader ) ;
free ( logheader_rfc5424 ) ;
free ( logline ) ;
free ( logline_rfc5424 ) ;
2019-03-08 12:53:21 -05:00
tmp_startup_logs = _HA_ATOMIC_XCHG ( & startup_logs , NULL ) ;
2019-03-07 08:19:24 -05:00
free ( tmp_startup_logs ) ;
2017-07-26 09:33:35 -04:00
logheader = NULL ;
logheader_rfc5424 = NULL ;
logline = NULL ;
logline_rfc5424 = NULL ;
2017-10-24 05:44:05 -04:00
startup_logs = NULL ;
2017-07-26 09:33:35 -04:00
}
2012-12-27 20:44:01 -05:00
/* Builds a log line in <dst> based on <list_format>, and stops before reaching
* < maxsize > characters . Returns the size of the output string in characters ,
* not counting the trailing zero which is always added if the resulting size
2018-09-05 10:55:15 -04:00
* is not zero . It requires a valid session and optionally a stream . If the
* stream is NULL , default values will be assumed for the stream part .
2012-12-27 20:44:01 -05:00
*/
2018-09-05 08:58:15 -04:00
int sess_build_logline ( struct session * sess , struct stream * s , char * dst , size_t maxsize , struct list * list_format )
2006-06-25 20:48:02 -04:00
{
2015-04-03 09:40:56 -04:00
struct proxy * fe = sess - > fe ;
2018-09-05 10:55:15 -04:00
struct proxy * be ;
struct http_txn * txn ;
const struct strm_logs * logs ;
const struct connection * be_conn ;
unsigned int s_flags ;
unsigned int uniq_id ;
2018-07-13 05:56:34 -04:00
struct buffer chunk ;
2012-02-27 05:23:10 -05:00
char * uri ;
2015-04-27 17:37:03 -04:00
char * spc ;
2015-07-31 12:14:16 -04:00
char * qmark ;
2015-04-27 17:37:03 -04:00
char * end ;
2007-10-25 04:34:16 -04:00
struct tm tm ;
2012-02-27 05:23:10 -05:00
int t_request ;
int hdr ;
int last_isspace = 1 ;
2015-04-27 17:37:03 -04:00
int nspaces = 0 ;
2012-03-19 11:51:53 -04:00
char * tmplog ;
2012-03-12 07:46:41 -04:00
char * ret ;
int iret ;
2012-02-27 05:23:10 -05:00
struct logformat_node * tmp ;
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 --------->:
2016-07-28 11:19:45 -04:00
struct timeval tv ;
2018-09-05 10:55:15 -04:00
struct strm_logs tmp_strm_log ;
2006-06-25 20:48:02 -04:00
2012-02-27 05:23:10 -05:00
/* FIXME: let's limit ourselves to frontend logging for now. */
2007-03-31 19:30:43 -04:00
2018-09-05 10:55:15 -04:00
if ( likely ( s ) ) {
be = s - > be ;
txn = s - > txn ;
be_conn = cs_conn ( objt_cs ( s - > si [ 1 ] . end ) ) ;
s_flags = s - > flags ;
uniq_id = s - > uniq_id ;
logs = & s - > logs ;
} else {
/* we have no stream so we first need to initialize a few
* things that are needed later . We do increment the request
* ID so that it ' s uniquely assigned to this request just as
* if the request had reached the point of being processed .
* A request error is reported as it ' s the only element we have
* here and which justifies emitting such a log .
*/
be = fe ;
txn = NULL ;
be_conn = NULL ;
s_flags = SF_ERR_PRXCOND | SF_FINST_R ;
2019-03-08 12:53:21 -05:00
uniq_id = _HA_ATOMIC_XADD ( & global . req_count , 1 ) ;
2018-09-05 10:55:15 -04:00
/* prepare a valid log structure */
tmp_strm_log . tv_accept = sess - > tv_accept ;
tmp_strm_log . accept_date = sess - > accept_date ;
tmp_strm_log . t_handshake = sess - > t_handshake ;
tmp_strm_log . t_idle = tv_ms_elapsed ( & sess - > tv_accept , & now ) - sess - > t_handshake ;
tv_zero ( & tmp_strm_log . tv_request ) ;
tmp_strm_log . t_queue = - 1 ;
tmp_strm_log . t_connect = - 1 ;
tmp_strm_log . t_data = - 1 ;
tmp_strm_log . t_close = tv_ms_elapsed ( & sess - > tv_accept , & now ) ;
tmp_strm_log . bytes_in = 0 ;
tmp_strm_log . bytes_out = 0 ;
tmp_strm_log . prx_queue_pos = 0 ;
tmp_strm_log . srv_queue_pos = 0 ;
logs = & tmp_strm_log ;
}
2012-02-27 05:23:10 -05:00
t_request = - 1 ;
2018-09-05 09:16:23 -04:00
if ( tv_isge ( & logs - > tv_request , & logs - > tv_accept ) )
t_request = tv_ms_elapsed ( & logs - > tv_accept , & logs - > tv_request ) ;
2012-02-27 05:23:10 -05:00
2012-03-12 07:46:41 -04:00
tmplog = dst ;
2009-05-10 05:57:02 -04:00
2012-02-27 05:23:10 -05:00
/* fill logbuffer */
2012-03-12 07:46:41 -04:00
if ( LIST_ISEMPTY ( list_format ) )
return 0 ;
2012-02-27 05:23:10 -05:00
2012-03-12 07:46:41 -04:00
list_for_each_entry ( tmp , list_format , list ) {
2013-10-01 04:45:07 -04:00
struct connection * conn ;
2012-10-12 13:48:16 -04:00
const char * src = NULL ;
2012-12-20 18:09:23 -05:00
struct sample * key ;
2018-07-13 05:56:34 -04:00
const struct buffer empty = { } ;
2012-02-27 05:23:10 -05:00
2012-12-20 18:09:23 -05:00
switch ( tmp - > type ) {
2012-03-12 07:46:41 -04:00
case LOG_FMT_SEPARATOR :
2012-02-27 05:23:10 -05:00
if ( ! last_isspace ) {
LOGCHAR ( ' ' ) ;
last_isspace = 1 ;
}
break ;
2012-03-12 07:46:41 -04:00
case LOG_FMT_TEXT : // text
2012-02-27 05:23:10 -05:00
src = tmp - > arg ;
2012-04-05 12:02:55 -04:00
iret = strlcpy2 ( tmplog , src , dst + maxsize - tmplog ) ;
2012-03-12 07:46:41 -04:00
if ( iret = = 0 )
2012-02-27 05:23:10 -05:00
goto out ;
2012-03-12 07:46:41 -04:00
tmplog + = iret ;
2012-02-27 05:23:10 -05:00
last_isspace = 0 ;
break ;
2012-12-20 18:09:23 -05:00
case LOG_FMT_EXPR : // sample expression, may be request or response
key = NULL ;
2018-12-15 08:00:06 -05:00
if ( tmp - > options & LOG_OPT_REQ_CAP & & s )
2015-07-06 09:41:02 -04:00
key = sample_fetch_as_type ( be , sess , s , SMP_OPT_DIR_REQ | SMP_OPT_FINAL , tmp - > expr , SMP_T_STR ) ;
2018-12-15 08:00:06 -05:00
if ( ! key & & ( tmp - > options & LOG_OPT_RES_CAP ) & & s )
2015-07-06 09:41:02 -04:00
key = sample_fetch_as_type ( be , sess , s , SMP_OPT_DIR_RES | SMP_OPT_FINAL , tmp - > expr , SMP_T_STR ) ;
2014-03-13 11:46:18 -04:00
if ( tmp - > options & LOG_OPT_HTTP )
2016-02-12 07:23:03 -05:00
ret = lf_encode_chunk ( tmplog , dst + maxsize ,
' % ' , http_encode_map , key ? & key - > data . u . str : & empty , tmp ) ;
2014-03-13 11:46:18 -04:00
else
2018-07-13 04:54:26 -04:00
ret = lf_text_len ( tmplog ,
key ? key - > data . u . str . area : NULL ,
key ? key - > data . u . str . data : 0 ,
dst + maxsize - tmplog ,
tmp ) ;
2012-12-20 18:09:23 -05:00
if ( ret = = 0 )
goto out ;
tmplog = ret ;
last_isspace = 0 ;
break ;
2012-12-20 11:22:52 -05:00
case LOG_FMT_CLIENTIP : // %ci
2015-04-03 13:19:59 -04:00
conn = objt_conn ( sess - > origin ) ;
2013-10-01 04:45:07 -04:00
if ( conn )
ret = lf_ip ( tmplog , ( struct sockaddr * ) & conn - > addr . from , dst + maxsize - tmplog , tmp ) ;
else
ret = lf_text_len ( tmplog , NULL , 0 , dst + maxsize - tmplog , tmp ) ;
2012-03-12 07:46:41 -04:00
if ( ret = = NULL )
2012-02-27 05:23:10 -05:00
goto out ;
2012-03-12 07:46:41 -04:00
tmplog = ret ;
2012-02-27 05:23:10 -05:00
last_isspace = 0 ;
break ;
2012-12-20 11:22:52 -05:00
case LOG_FMT_CLIENTPORT : // %cp
2015-04-03 13:19:59 -04:00
conn = objt_conn ( sess - > origin ) ;
2013-10-01 04:45:07 -04:00
if ( conn ) {
if ( conn - > addr . from . ss_family = = AF_UNIX ) {
2015-04-03 08:46:27 -04:00
ret = ltoa_o ( sess - > listener - > luid , tmplog , dst + maxsize - tmplog ) ;
2013-10-01 04:45:07 -04:00
} else {
ret = lf_port ( tmplog , ( struct sockaddr * ) & conn - > addr . from ,
dst + maxsize - tmplog , tmp ) ;
}
2012-04-05 12:02:55 -04:00
}
2013-10-01 04:45:07 -04:00
else
ret = lf_text_len ( tmplog , NULL , 0 , dst + maxsize - tmplog , tmp ) ;
2012-04-05 12:02:55 -04:00
if ( ret = = NULL )
goto out ;
tmplog = ret ;
last_isspace = 0 ;
break ;
2012-12-20 11:22:52 -05:00
case LOG_FMT_FRONTENDIP : // %fi
2015-04-03 13:19:59 -04:00
conn = objt_conn ( sess - > origin ) ;
2013-10-01 04:45:07 -04:00
if ( conn ) {
conn_get_to_addr ( conn ) ;
ret = lf_ip ( tmplog , ( struct sockaddr * ) & conn - > addr . to , dst + maxsize - tmplog , tmp ) ;
}
else
ret = lf_text_len ( tmplog , NULL , 0 , dst + maxsize - tmplog , tmp ) ;
2012-04-05 12:02:55 -04:00
if ( ret = = NULL )
goto out ;
tmplog = ret ;
last_isspace = 0 ;
break ;
2012-12-20 11:22:52 -05:00
case LOG_FMT_FRONTENDPORT : // %fp
2015-04-03 13:19:59 -04:00
conn = objt_conn ( sess - > origin ) ;
2013-10-01 04:45:07 -04:00
if ( conn ) {
conn_get_to_addr ( conn ) ;
if ( conn - > addr . to . ss_family = = AF_UNIX )
2015-04-03 08:46:27 -04:00
ret = ltoa_o ( sess - > listener - > luid , tmplog , dst + maxsize - tmplog ) ;
2013-10-01 04:45:07 -04:00
else
ret = lf_port ( tmplog , ( struct sockaddr * ) & conn - > addr . to , dst + maxsize - tmplog , tmp ) ;
2012-04-05 12:02:55 -04:00
}
2013-10-01 04:45:07 -04:00
else
ret = lf_text_len ( tmplog , NULL , 0 , dst + maxsize - tmplog , tmp ) ;
2012-03-12 07:46:41 -04:00
if ( ret = = NULL )
2012-02-27 05:23:10 -05:00
goto out ;
2012-03-12 07:46:41 -04:00
tmplog = ret ;
2012-02-27 05:23:10 -05:00
last_isspace = 0 ;
break ;
2012-12-20 11:22:52 -05:00
case LOG_FMT_BACKENDIP : // %bi
2018-09-05 09:24:56 -04:00
if ( be_conn )
ret = lf_ip ( tmplog , ( const struct sockaddr * ) & be_conn - > addr . from , dst + maxsize - tmplog , tmp ) ;
2013-10-01 04:45:07 -04:00
else
ret = lf_text_len ( tmplog , NULL , 0 , dst + maxsize - tmplog , tmp ) ;
2012-03-12 07:46:41 -04:00
if ( ret = = NULL )
2012-03-02 08:35:21 -05:00
goto out ;
2012-03-12 07:46:41 -04:00
tmplog = ret ;
2012-03-02 08:35:21 -05:00
last_isspace = 0 ;
break ;
2012-12-20 11:22:52 -05:00
case LOG_FMT_BACKENDPORT : // %bp
2018-09-05 09:24:56 -04:00
if ( be_conn )
ret = lf_port ( tmplog , ( struct sockaddr * ) & be_conn - > addr . from , dst + maxsize - tmplog , tmp ) ;
2013-10-01 04:45:07 -04:00
else
ret = lf_text_len ( tmplog , NULL , 0 , dst + maxsize - tmplog , tmp ) ;
2012-04-05 12:02:55 -04:00
if ( ret = = NULL )
goto out ;
tmplog = ret ;
last_isspace = 0 ;
break ;
2012-12-20 11:22:52 -05:00
case LOG_FMT_SERVERIP : // %si
2018-09-05 09:24:56 -04:00
if ( be_conn )
ret = lf_ip ( tmplog , ( struct sockaddr * ) & be_conn - > addr . to , dst + maxsize - tmplog , tmp ) ;
2013-10-01 04:45:07 -04:00
else
ret = lf_text_len ( tmplog , NULL , 0 , dst + maxsize - tmplog , tmp ) ;
2012-04-05 12:02:55 -04:00
if ( ret = = NULL )
goto out ;
tmplog = ret ;
last_isspace = 0 ;
break ;
2012-12-20 11:22:52 -05:00
case LOG_FMT_SERVERPORT : // %sp
2018-09-05 09:24:56 -04:00
if ( be_conn )
ret = lf_port ( tmplog , ( struct sockaddr * ) & be_conn - > addr . to , dst + maxsize - tmplog , tmp ) ;
2013-10-01 04:45:07 -04:00
else
ret = lf_text_len ( tmplog , NULL , 0 , dst + maxsize - tmplog , tmp ) ;
2012-03-12 07:46:41 -04:00
if ( ret = = NULL )
2012-03-02 08:35:21 -05:00
goto out ;
2012-03-12 07:46:41 -04:00
tmplog = ret ;
2012-03-02 08:35:21 -05:00
last_isspace = 0 ;
break ;
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 --------->:
2016-07-28 11:19:45 -04:00
case LOG_FMT_DATE : // %t = accept date
2018-09-05 09:16:23 -04:00
get_localtime ( logs - > accept_date . tv_sec , & tm ) ;
ret = date2str_log ( tmplog , & tm , & logs - > accept_date , dst + maxsize - tmplog ) ;
2012-03-12 07:46:41 -04:00
if ( ret = = NULL )
2012-02-27 05:23:10 -05:00
goto out ;
2012-03-12 07:46:41 -04:00
tmplog = ret ;
2012-02-27 05:23:10 -05:00
last_isspace = 0 ;
break ;
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 --------->:
2016-07-28 11:19:45 -04:00
case LOG_FMT_tr : // %tr = start of request date
/* Note that the timers are valid if we get here */
2018-09-05 09:16:23 -04:00
tv_ms_add ( & tv , & logs - > accept_date , logs - > t_idle > = 0 ? logs - > t_idle + logs - > t_handshake : 0 ) ;
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 --------->:
2016-07-28 11:19:45 -04:00
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
2018-09-05 09:16:23 -04:00
get_gmtime ( logs - > accept_date . tv_sec , & tm ) ;
2012-04-05 12:02:55 -04:00
ret = gmt2str_log ( tmplog , & tm , dst + maxsize - tmplog ) ;
2012-03-12 07:46:41 -04:00
if ( ret = = NULL )
2012-02-27 05:23:10 -05:00
goto out ;
2012-03-12 07:46:41 -04:00
tmplog = ret ;
2012-02-27 05:23:10 -05:00
last_isspace = 0 ;
2012-10-18 22:36:09 -04:00
break ;
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 --------->:
2016-07-28 11:19:45 -04:00
case LOG_FMT_trg : // %trg = start of request date, GMT
2018-09-05 09:16:23 -04:00
tv_ms_add ( & tv , & logs - > accept_date , logs - > t_idle > = 0 ? logs - > t_idle + logs - > t_handshake : 0 ) ;
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 --------->:
2016-07-28 11:19:45 -04:00
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
2018-09-05 09:16:23 -04:00
get_localtime ( logs - > accept_date . tv_sec , & tm ) ;
ret = localdate2str_log ( tmplog , logs - > accept_date . tv_sec , & tm , dst + maxsize - tmplog ) ;
2012-10-18 22:36:09 -04:00
if ( ret = = NULL )
goto out ;
tmplog = ret ;
last_isspace = 0 ;
2012-02-27 05:23:10 -05:00
break ;
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 --------->:
2016-07-28 11:19:45 -04:00
case LOG_FMT_trl : // %trl = start of request date, local
2018-09-05 09:16:23 -04:00
tv_ms_add ( & tv , & logs - > accept_date , logs - > t_idle > = 0 ? logs - > t_idle + logs - > t_handshake : 0 ) ;
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 --------->:
2016-07-28 11:19:45 -04:00
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 ;
2012-04-05 12:02:55 -04:00
case LOG_FMT_TS : // %Ts
2018-09-05 09:16:23 -04:00
get_gmtime ( logs - > accept_date . tv_sec , & tm ) ;
2012-04-05 12:02:55 -04:00
if ( tmp - > options & LOG_OPT_HEXA ) {
2018-09-05 09:16:23 -04:00
iret = snprintf ( tmplog , dst + maxsize - tmplog , " %04X " , ( unsigned int ) logs - > accept_date . tv_sec ) ;
2012-04-05 12:02:55 -04:00
if ( iret < 0 | | iret > dst + maxsize - tmplog )
goto out ;
last_isspace = 0 ;
tmplog + = iret ;
} else {
2018-09-05 09:16:23 -04:00
ret = ltoa_o ( logs - > accept_date . tv_sec , tmplog , dst + maxsize - tmplog ) ;
2012-04-05 12:02:55 -04:00
if ( ret = = NULL )
goto out ;
tmplog = ret ;
last_isspace = 0 ;
}
break ;
2012-03-12 07:46:41 -04:00
case LOG_FMT_MS : // %ms
2012-04-05 12:02:55 -04:00
if ( tmp - > options & LOG_OPT_HEXA ) {
2018-09-05 09:16:23 -04:00
iret = snprintf ( tmplog , dst + maxsize - tmplog , " %02X " , ( unsigned int ) logs - > accept_date . tv_usec / 1000 ) ;
2012-04-05 12:02:55 -04:00
if ( iret < 0 | | iret > dst + maxsize - tmplog )
goto out ;
last_isspace = 0 ;
tmplog + = iret ;
} else {
if ( ( dst + maxsize - tmplog ) < 4 )
2012-02-27 05:23:10 -05:00
goto out ;
2018-09-05 09:16:23 -04:00
ret = utoa_pad ( ( unsigned int ) logs - > accept_date . tv_usec / 1000 ,
2013-01-23 19:18:16 -05:00
tmplog , 4 ) ;
if ( ret = = NULL )
2012-03-26 11:52:55 -04:00
goto out ;
2013-01-23 19:18:16 -05:00
tmplog = ret ;
2012-02-27 05:23:10 -05:00
last_isspace = 0 ;
2012-04-05 12:02:55 -04:00
}
break ;
2012-02-27 05:23:10 -05:00
2012-03-12 07:46:41 -04:00
case LOG_FMT_FRONTEND : // %f
2012-02-27 05:23:10 -05:00
src = fe - > id ;
2012-04-05 12:02:55 -04:00
ret = lf_text ( tmplog , src , dst + maxsize - tmplog , tmp ) ;
2012-03-12 07:46:41 -04:00
if ( ret = = NULL )
2012-02-27 05:23:10 -05:00
goto out ;
2012-03-12 07:46:41 -04:00
tmplog = ret ;
2012-03-26 11:52:55 -04:00
last_isspace = 0 ;
2012-02-27 05:23:10 -05:00
break ;
2012-10-12 08:56:11 -04:00
case LOG_FMT_FRONTEND_XPRT : // %ft
src = fe - > id ;
if ( tmp - > options & LOG_OPT_QUOTE )
LOGCHAR ( ' " ' ) ;
iret = strlcpy2 ( tmplog , src , dst + maxsize - tmplog ) ;
if ( iret = = 0 )
goto out ;
tmplog + = iret ;
2016-12-22 14:44:00 -05:00
if ( sess - > listener - > bind_conf - > xprt = = xprt_get ( XPRT_SSL ) )
2012-10-12 08:56:11 -04:00
LOGCHAR ( ' ~ ' ) ;
if ( tmp - > options & LOG_OPT_QUOTE )
LOGCHAR ( ' " ' ) ;
last_isspace = 0 ;
break ;
2012-10-12 14:17:54 -04:00
# ifdef USE_OPENSSL
case LOG_FMT_SSL_CIPHER : // %sslc
src = NULL ;
2015-04-03 13:19:59 -04:00
conn = objt_conn ( sess - > origin ) ;
2013-10-01 04:45:07 -04:00
if ( conn ) {
2017-10-13 10:59:49 -04:00
src = ssl_sock_get_cipher_name ( conn ) ;
2013-10-01 04:45:07 -04:00
}
2012-10-12 14:17:54 -04:00
ret = lf_text ( tmplog , src , dst + maxsize - tmplog , tmp ) ;
if ( ret = = NULL )
goto out ;
tmplog = ret ;
last_isspace = 0 ;
break ;
2012-10-12 08:56:11 -04:00
2012-10-12 14:17:54 -04:00
case LOG_FMT_SSL_VERSION : // %sslv
src = NULL ;
2015-04-03 13:19:59 -04:00
conn = objt_conn ( sess - > origin ) ;
2013-10-01 04:45:07 -04:00
if ( conn ) {
2017-10-13 10:59:49 -04:00
src = ssl_sock_get_proto_version ( conn ) ;
2013-10-01 04:45:07 -04:00
}
2012-10-12 14:17:54 -04:00
ret = lf_text ( tmplog , src , dst + maxsize - tmplog , tmp ) ;
if ( ret = = NULL )
goto out ;
tmplog = ret ;
last_isspace = 0 ;
break ;
# endif
2012-03-12 07:46:41 -04:00
case LOG_FMT_BACKEND : // %b
2012-02-27 05:23:10 -05:00
src = be - > id ;
2012-04-05 12:02:55 -04:00
ret = lf_text ( tmplog , src , dst + maxsize - tmplog , tmp ) ;
2012-03-12 07:46:41 -04:00
if ( ret = = NULL )
2012-02-27 05:23:10 -05:00
goto out ;
2012-03-12 07:46:41 -04:00
tmplog = ret ;
2012-03-26 11:52:55 -04:00
last_isspace = 0 ;
2012-02-27 05:23:10 -05:00
break ;
2012-03-12 07:46:41 -04:00
case LOG_FMT_SERVER : // %s
2018-09-05 09:30:16 -04:00
switch ( obj_type ( s ? s - > target : NULL ) ) {
BUG/MINOR: log: make log-format, unique-id-format and add-header more independant
It happens that all of them call parse_logformat_line() which sets
proxy->to_log with a number of flags affecting the line format for
all three users. For example, having a unique-id specified disables
the default log-format since fe->to_log is tested when the session
is established.
Similarly, having "option logasap" will cause "+" to be inserted in
unique-id or headers referencing some of the fields depending on
LW_BYTES.
This patch first removes most of the dependency on fe->to_log whenever
possible. The first possible cleanup is to stop checking fe->to_log
for being null, considering that it always contains at least LW_INIT
when any such usage is made of the log-format!
Also, some checks are wrong. s->logs.logwait cannot be nulled by
"logwait &= ~LW_*" since LW_INIT is always there. This results in
getting the wrong log at the end of a request or session when a
unique-id or add-header is set, because logwait is still not null
but the log-format is not checked.
Further cleanups are required. Most LW_* flags should be removed or at
least replaced with what they really mean (eg: depend on client-side
connection, depend on server-side connection, etc...) and this should
only affect logging, not other mechanisms.
This patch fixes the default log-format and tries to limit interferences
between the log formats, but does not pretend to do more for the moment,
since it's the most visible breakage.
2012-12-28 03:40:16 -05:00
case OBJ_TYPE_SERVER :
2018-09-20 05:13:58 -04:00
src = __objt_server ( s - > target ) - > id ;
BUG/MINOR: log: make log-format, unique-id-format and add-header more independant
It happens that all of them call parse_logformat_line() which sets
proxy->to_log with a number of flags affecting the line format for
all three users. For example, having a unique-id specified disables
the default log-format since fe->to_log is tested when the session
is established.
Similarly, having "option logasap" will cause "+" to be inserted in
unique-id or headers referencing some of the fields depending on
LW_BYTES.
This patch first removes most of the dependency on fe->to_log whenever
possible. The first possible cleanup is to stop checking fe->to_log
for being null, considering that it always contains at least LW_INIT
when any such usage is made of the log-format!
Also, some checks are wrong. s->logs.logwait cannot be nulled by
"logwait &= ~LW_*" since LW_INIT is always there. This results in
getting the wrong log at the end of a request or session when a
unique-id or add-header is set, because logwait is still not null
but the log-format is not checked.
Further cleanups are required. Most LW_* flags should be removed or at
least replaced with what they really mean (eg: depend on client-side
connection, depend on server-side connection, etc...) and this should
only affect logging, not other mechanisms.
This patch fixes the default log-format and tries to limit interferences
between the log formats, but does not pretend to do more for the moment,
since it's the most visible breakage.
2012-12-28 03:40:16 -05:00
break ;
case OBJ_TYPE_APPLET :
2018-09-20 05:13:58 -04:00
src = __objt_applet ( s - > target ) - > name ;
BUG/MINOR: log: make log-format, unique-id-format and add-header more independant
It happens that all of them call parse_logformat_line() which sets
proxy->to_log with a number of flags affecting the line format for
all three users. For example, having a unique-id specified disables
the default log-format since fe->to_log is tested when the session
is established.
Similarly, having "option logasap" will cause "+" to be inserted in
unique-id or headers referencing some of the fields depending on
LW_BYTES.
This patch first removes most of the dependency on fe->to_log whenever
possible. The first possible cleanup is to stop checking fe->to_log
for being null, considering that it always contains at least LW_INIT
when any such usage is made of the log-format!
Also, some checks are wrong. s->logs.logwait cannot be nulled by
"logwait &= ~LW_*" since LW_INIT is always there. This results in
getting the wrong log at the end of a request or session when a
unique-id or add-header is set, because logwait is still not null
but the log-format is not checked.
Further cleanups are required. Most LW_* flags should be removed or at
least replaced with what they really mean (eg: depend on client-side
connection, depend on server-side connection, etc...) and this should
only affect logging, not other mechanisms.
This patch fixes the default log-format and tries to limit interferences
between the log formats, but does not pretend to do more for the moment,
since it's the most visible breakage.
2012-12-28 03:40:16 -05:00
break ;
default :
src = " <NOSRV> " ;
break ;
}
2012-04-05 12:02:55 -04:00
ret = lf_text ( tmplog , src , dst + maxsize - tmplog , tmp ) ;
2012-03-12 07:46:41 -04:00
if ( ret = = NULL )
2012-02-27 05:23:10 -05:00
goto out ;
2012-03-12 07:46:41 -04:00
tmplog = ret ;
2012-02-27 05:23:10 -05:00
last_isspace = 0 ;
break ;
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 --------->:
2016-07-28 11:19:45 -04:00
case LOG_FMT_Th : // %Th = handshake time
2018-09-05 09:16:23 -04:00
ret = ltoa_o ( logs - > t_handshake , tmplog , dst + maxsize - tmplog ) ;
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 --------->:
2016-07-28 11:19:45 -04:00
if ( ret = = NULL )
goto out ;
tmplog = ret ;
last_isspace = 0 ;
break ;
case LOG_FMT_Ti : // %Ti = HTTP idle time
2018-09-05 09:16:23 -04:00
ret = ltoa_o ( logs - > t_idle , tmplog , dst + maxsize - tmplog ) ;
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 --------->:
2016-07-28 11:19:45 -04:00
if ( ret = = NULL )
goto out ;
tmplog = ret ;
last_isspace = 0 ;
break ;
case LOG_FMT_TR : // %TR = HTTP request time
2018-09-05 09:16:23 -04:00
ret = ltoa_o ( ( t_request > = 0 ) ? t_request - logs - > t_idle - logs - > t_handshake : - 1 ,
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 --------->:
2016-07-28 11:19:45 -04:00
tmplog , dst + maxsize - tmplog ) ;
if ( ret = = NULL )
goto out ;
tmplog = ret ;
last_isspace = 0 ;
break ;
case LOG_FMT_TQ : // %Tq = Th + Ti + TR
2012-04-05 12:02:55 -04:00
ret = ltoa_o ( t_request , tmplog , dst + maxsize - tmplog ) ;
2012-03-12 07:46:41 -04:00
if ( ret = = NULL )
2012-02-27 05:23:10 -05:00
goto out ;
2012-03-12 07:46:41 -04:00
tmplog = ret ;
2012-02-27 05:23:10 -05:00
last_isspace = 0 ;
break ;
2012-03-12 07:46:41 -04:00
case LOG_FMT_TW : // %Tw
2018-09-05 09:16:23 -04:00
ret = ltoa_o ( ( logs - > t_queue > = 0 ) ? logs - > t_queue - t_request : - 1 ,
2012-04-05 12:02:55 -04:00
tmplog , dst + maxsize - tmplog ) ;
2012-03-12 07:46:41 -04:00
if ( ret = = NULL )
2012-02-27 05:23:10 -05:00
goto out ;
2012-03-12 07:46:41 -04:00
tmplog = ret ;
2012-02-27 05:23:10 -05:00
last_isspace = 0 ;
break ;
2012-03-12 07:46:41 -04:00
case LOG_FMT_TC : // %Tc
2018-09-05 09:16:23 -04:00
ret = ltoa_o ( ( logs - > t_connect > = 0 ) ? logs - > t_connect - logs - > t_queue : - 1 ,
2012-04-05 12:02:55 -04:00
tmplog , dst + maxsize - tmplog ) ;
2012-03-12 07:46:41 -04:00
if ( ret = = NULL )
2012-02-27 05:23:10 -05:00
goto out ;
2012-03-12 07:46:41 -04:00
tmplog = ret ;
2012-02-27 05:23:10 -05:00
last_isspace = 0 ;
break ;
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 --------->:
2016-07-28 11:19:45 -04:00
case LOG_FMT_Tr : // %Tr
2018-09-05 09:16:23 -04:00
ret = ltoa_o ( ( logs - > t_data > = 0 ) ? logs - > t_data - logs - > t_connect : - 1 ,
2012-04-05 12:02:55 -04:00
tmplog , dst + maxsize - tmplog ) ;
2012-03-12 07:46:41 -04:00
if ( ret = = NULL )
2012-02-27 05:23:10 -05:00
goto out ;
2012-03-12 07:46:41 -04:00
tmplog = ret ;
2012-02-27 05:23:10 -05:00
last_isspace = 0 ;
break ;
2016-05-17 11:55:27 -04:00
case LOG_FMT_TD : // %Td
2018-09-05 09:07:15 -04:00
if ( be - > mode = = PR_MODE_HTTP )
2018-09-05 09:16:23 -04:00
ret = ltoa_o ( ( logs - > t_data > = 0 ) ? logs - > t_close - logs - > t_data : - 1 ,
2016-05-17 11:55:27 -04:00
tmplog , dst + maxsize - tmplog ) ;
else
2018-09-05 09:16:23 -04:00
ret = ltoa_o ( ( logs - > t_connect > = 0 ) ? logs - > t_close - logs - > t_connect : - 1 ,
2016-05-17 11:55:27 -04:00
tmplog , dst + maxsize - tmplog ) ;
if ( ret = = NULL )
goto out ;
tmplog = ret ;
last_isspace = 0 ;
break ;
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 --------->:
2016-07-28 11:19:45 -04:00
case LOG_FMT_Ta : // %Ta = active time = Tt - Th - Ti
if ( ! ( fe - > to_log & LW_BYTES ) )
LOGCHAR ( ' + ' ) ;
2018-09-05 09:16:23 -04:00
ret = ltoa_o ( logs - > t_close - ( logs - > t_idle > = 0 ? logs - > t_idle + logs - > t_handshake : 0 ) ,
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 --------->:
2016-07-28 11:19:45 -04:00
tmplog , dst + maxsize - tmplog ) ;
if ( ret = = NULL )
goto out ;
tmplog = ret ;
last_isspace = 0 ;
break ;
case LOG_FMT_TT : // %Tt = total time
BUG/MINOR: log: make log-format, unique-id-format and add-header more independant
It happens that all of them call parse_logformat_line() which sets
proxy->to_log with a number of flags affecting the line format for
all three users. For example, having a unique-id specified disables
the default log-format since fe->to_log is tested when the session
is established.
Similarly, having "option logasap" will cause "+" to be inserted in
unique-id or headers referencing some of the fields depending on
LW_BYTES.
This patch first removes most of the dependency on fe->to_log whenever
possible. The first possible cleanup is to stop checking fe->to_log
for being null, considering that it always contains at least LW_INIT
when any such usage is made of the log-format!
Also, some checks are wrong. s->logs.logwait cannot be nulled by
"logwait &= ~LW_*" since LW_INIT is always there. This results in
getting the wrong log at the end of a request or session when a
unique-id or add-header is set, because logwait is still not null
but the log-format is not checked.
Further cleanups are required. Most LW_* flags should be removed or at
least replaced with what they really mean (eg: depend on client-side
connection, depend on server-side connection, etc...) and this should
only affect logging, not other mechanisms.
This patch fixes the default log-format and tries to limit interferences
between the log formats, but does not pretend to do more for the moment,
since it's the most visible breakage.
2012-12-28 03:40:16 -05:00
if ( ! ( fe - > to_log & LW_BYTES ) )
2012-03-12 07:46:41 -04:00
LOGCHAR ( ' + ' ) ;
2018-09-05 09:16:23 -04:00
ret = ltoa_o ( logs - > t_close , tmplog , dst + maxsize - tmplog ) ;
2012-03-12 07:46:41 -04:00
if ( ret = = NULL )
2012-02-27 05:23:10 -05:00
goto out ;
2012-03-12 07:46:41 -04:00
tmplog = ret ;
2012-02-27 05:23:10 -05:00
last_isspace = 0 ;
break ;
2012-12-20 11:22:52 -05:00
case LOG_FMT_STATUS : // %ST
2016-04-25 11:09:40 -04:00
ret = ltoa_o ( txn ? txn - > status : 0 , tmplog , dst + maxsize - tmplog ) ;
2012-03-12 07:46:41 -04:00
if ( ret = = NULL )
2012-02-27 05:23:10 -05:00
goto out ;
2012-03-12 07:46:41 -04:00
tmplog = ret ;
2012-02-27 05:23:10 -05:00
last_isspace = 0 ;
break ;
2012-03-12 07:46:41 -04:00
case LOG_FMT_BYTES : // %B
BUG/MINOR: log: make log-format, unique-id-format and add-header more independant
It happens that all of them call parse_logformat_line() which sets
proxy->to_log with a number of flags affecting the line format for
all three users. For example, having a unique-id specified disables
the default log-format since fe->to_log is tested when the session
is established.
Similarly, having "option logasap" will cause "+" to be inserted in
unique-id or headers referencing some of the fields depending on
LW_BYTES.
This patch first removes most of the dependency on fe->to_log whenever
possible. The first possible cleanup is to stop checking fe->to_log
for being null, considering that it always contains at least LW_INIT
when any such usage is made of the log-format!
Also, some checks are wrong. s->logs.logwait cannot be nulled by
"logwait &= ~LW_*" since LW_INIT is always there. This results in
getting the wrong log at the end of a request or session when a
unique-id or add-header is set, because logwait is still not null
but the log-format is not checked.
Further cleanups are required. Most LW_* flags should be removed or at
least replaced with what they really mean (eg: depend on client-side
connection, depend on server-side connection, etc...) and this should
only affect logging, not other mechanisms.
This patch fixes the default log-format and tries to limit interferences
between the log formats, but does not pretend to do more for the moment,
since it's the most visible breakage.
2012-12-28 03:40:16 -05:00
if ( ! ( fe - > to_log & LW_BYTES ) )
2012-03-12 07:46:41 -04:00
LOGCHAR ( ' + ' ) ;
2018-09-05 09:16:23 -04:00
ret = lltoa ( logs - > bytes_out , tmplog , dst + maxsize - tmplog ) ;
2012-12-20 09:38:04 -05:00
if ( ret = = NULL )
goto out ;
tmplog = ret ;
last_isspace = 0 ;
break ;
case LOG_FMT_BYTES_UP : // %U
2018-09-05 09:16:23 -04:00
ret = lltoa ( logs - > bytes_in , tmplog , dst + maxsize - tmplog ) ;
2012-03-12 07:46:41 -04:00
if ( ret = = NULL )
2012-02-27 05:23:10 -05:00
goto out ;
2012-03-12 07:46:41 -04:00
tmplog = ret ;
2012-02-27 05:23:10 -05:00
last_isspace = 0 ;
break ;
2012-12-20 11:22:52 -05:00
case LOG_FMT_CCLIENT : // %CC
2016-04-25 11:09:40 -04:00
src = txn ? txn - > cli_cookie : NULL ;
2012-04-05 12:02:55 -04:00
ret = lf_text ( tmplog , src , dst + maxsize - tmplog , tmp ) ;
2012-03-12 07:46:41 -04:00
if ( ret = = NULL )
2012-03-26 11:52:55 -04:00
goto out ;
2012-03-12 07:46:41 -04:00
tmplog = ret ;
2012-02-27 05:23:10 -05:00
last_isspace = 0 ;
break ;
2012-12-20 11:22:52 -05:00
case LOG_FMT_CSERVER : // %CS
2016-04-25 11:09:40 -04:00
src = txn ? txn - > srv_cookie : NULL ;
2012-04-05 12:02:55 -04:00
ret = lf_text ( tmplog , src , dst + maxsize - tmplog , tmp ) ;
2012-03-12 07:46:41 -04:00
if ( ret = = NULL )
2012-03-26 11:52:55 -04:00
goto out ;
2012-03-12 07:46:41 -04:00
tmplog = ret ;
2012-02-27 05:23:10 -05:00
last_isspace = 0 ;
break ;
2012-03-12 07:46:41 -04:00
case LOG_FMT_TERMSTATE : // %ts
2018-09-05 09:51:28 -04:00
LOGCHAR ( sess_term_cond [ ( s_flags & SF_ERR_MASK ) > > SF_ERR_SHIFT ] ) ;
LOGCHAR ( sess_fin_state [ ( s_flags & SF_FINST_MASK ) > > SF_FINST_SHIFT ] ) ;
2012-03-12 10:09:42 -04:00
* tmplog = ' \0 ' ;
last_isspace = 0 ;
break ;
2012-02-27 05:23:10 -05:00
2012-03-12 07:46:41 -04:00
case LOG_FMT_TERMSTATE_CK : // %tsc, same as TS with cookie state (for mode HTTP)
2018-09-05 09:51:28 -04:00
LOGCHAR ( sess_term_cond [ ( s_flags & SF_ERR_MASK ) > > SF_ERR_SHIFT ] ) ;
LOGCHAR ( sess_fin_state [ ( s_flags & SF_FINST_MASK ) > > SF_FINST_SHIFT ] ) ;
2016-04-25 11:09:40 -04:00
LOGCHAR ( ( txn & & ( be - > ck_opts & PR_CK_ANY ) ) ? sess_cookie [ ( txn - > flags & TX_CK_MASK ) > > TX_CK_SHIFT ] : ' - ' ) ;
LOGCHAR ( ( txn & & ( be - > ck_opts & PR_CK_ANY ) ) ? sess_set_cookie [ ( txn - > flags & TX_SCK_MASK ) > > TX_SCK_SHIFT ] : ' - ' ) ;
2012-02-27 05:23:10 -05:00
last_isspace = 0 ;
break ;
2012-03-12 07:46:41 -04:00
case LOG_FMT_ACTCONN : // %ac
2012-04-05 12:02:55 -04:00
ret = ltoa_o ( actconn , tmplog , dst + maxsize - tmplog ) ;
2012-03-12 07:46:41 -04:00
if ( ret = = NULL )
2012-02-27 05:23:10 -05:00
goto out ;
2012-03-12 07:46:41 -04:00
tmplog = ret ;
2012-02-27 05:23:10 -05:00
last_isspace = 0 ;
break ;
2012-03-12 07:46:41 -04:00
case LOG_FMT_FECONN : // %fc
2012-04-05 12:02:55 -04:00
ret = ltoa_o ( fe - > feconn , tmplog , dst + maxsize - tmplog ) ;
2012-03-12 07:46:41 -04:00
if ( ret = = NULL )
2012-02-27 05:23:10 -05:00
goto out ;
2012-03-12 07:46:41 -04:00
tmplog = ret ;
2012-02-27 05:23:10 -05:00
last_isspace = 0 ;
break ;
2012-03-12 07:46:41 -04:00
case LOG_FMT_BECONN : // %bc
2012-04-05 12:02:55 -04:00
ret = ltoa_o ( be - > beconn , tmplog , dst + maxsize - tmplog ) ;
2012-03-12 07:46:41 -04:00
if ( ret = = NULL )
2012-02-27 05:23:10 -05:00
goto out ;
2012-03-12 07:46:41 -04:00
tmplog = ret ;
2012-02-27 05:23:10 -05:00
last_isspace = 0 ;
break ;
2012-03-12 07:46:41 -04:00
case LOG_FMT_SRVCONN : // %sc
2018-09-05 09:30:16 -04:00
ret = ultoa_o ( objt_server ( s ? s - > target : NULL ) ?
2012-11-11 18:42:33 -05:00
objt_server ( s - > target ) - > cur_sess :
2012-04-05 12:02:55 -04:00
0 , tmplog , dst + maxsize - tmplog ) ;
2012-03-12 07:46:41 -04:00
if ( ret = = NULL )
2012-02-27 05:23:10 -05:00
goto out ;
2012-03-12 07:46:41 -04:00
tmplog = ret ;
2012-02-27 05:23:10 -05:00
last_isspace = 0 ;
break ;
2012-03-12 07:46:41 -04:00
case LOG_FMT_RETRIES : // %rq
2018-09-05 09:51:28 -04:00
if ( s_flags & SF_REDISP )
2012-03-12 07:46:41 -04:00
LOGCHAR ( ' + ' ) ;
2018-09-04 13:21:44 -04:00
ret = ltoa_o ( ( s & & s - > si [ 1 ] . conn_retries > 0 ) ?
2014-11-28 08:42:25 -05:00
( be - > conn_retries - s - > si [ 1 ] . conn_retries ) :
2012-04-05 12:02:55 -04:00
be - > conn_retries , tmplog , dst + maxsize - tmplog ) ;
2012-03-12 07:46:41 -04:00
if ( ret = = NULL )
2012-03-26 11:52:55 -04:00
goto out ;
2012-03-12 07:46:41 -04:00
tmplog = ret ;
2012-02-27 05:23:10 -05:00
last_isspace = 0 ;
break ;
2012-03-12 07:46:41 -04:00
case LOG_FMT_SRVQUEUE : // %sq
2018-09-05 09:16:23 -04:00
ret = ltoa_o ( logs - > srv_queue_pos , tmplog , dst + maxsize - tmplog ) ;
2012-03-12 07:46:41 -04:00
if ( ret = = NULL )
2012-02-27 05:23:10 -05:00
goto out ;
2012-03-12 07:46:41 -04:00
tmplog = ret ;
2012-02-27 05:23:10 -05:00
last_isspace = 0 ;
break ;
2012-03-12 07:46:41 -04:00
case LOG_FMT_BCKQUEUE : // %bq
2018-09-05 09:16:23 -04:00
ret = ltoa_o ( logs - > prx_queue_pos , tmplog , dst + maxsize - tmplog ) ;
2012-03-12 07:46:41 -04:00
if ( ret = = NULL )
2012-02-27 05:23:10 -05:00
goto out ;
2012-03-12 07:46:41 -04:00
tmplog = ret ;
2012-02-27 05:23:10 -05:00
last_isspace = 0 ;
break ;
2012-03-12 07:46:41 -04:00
case LOG_FMT_HDRREQUEST : // %hr
2012-02-27 05:23:10 -05:00
/* request header */
2018-09-05 09:28:07 -04:00
if ( fe - > nb_req_cap & & s & & s - > req_cap ) {
2012-02-27 05:23:10 -05:00
if ( tmp - > options & LOG_OPT_QUOTE )
LOGCHAR ( ' " ' ) ;
LOGCHAR ( ' { ' ) ;
for ( hdr = 0 ; hdr < fe - > nb_req_cap ; hdr + + ) {
if ( hdr )
LOGCHAR ( ' | ' ) ;
2015-04-03 16:16:32 -04:00
if ( s - > req_cap [ hdr ] ! = NULL ) {
2016-02-12 07:23:03 -05:00
ret = lf_encode_string ( tmplog , dst + maxsize ,
' # ' , hdr_encode_map , s - > req_cap [ hdr ] , tmp ) ;
2012-03-12 07:46:41 -04:00
if ( ret = = NULL | | * ret ! = ' \0 ' )
2012-03-26 11:52:55 -04:00
goto out ;
2012-03-12 07:46:41 -04:00
tmplog = ret ;
2012-03-26 11:52:55 -04:00
}
2012-02-27 05:23:10 -05:00
}
LOGCHAR ( ' } ' ) ;
2012-03-26 11:52:55 -04:00
if ( tmp - > options & LOG_OPT_QUOTE )
LOGCHAR ( ' " ' ) ;
2012-02-27 05:23:10 -05:00
last_isspace = 0 ;
}
break ;
2012-03-12 07:46:41 -04:00
case LOG_FMT_HDRREQUESTLIST : // %hrl
2012-02-27 05:23:10 -05:00
/* request header list */
2018-09-05 09:28:07 -04:00
if ( fe - > nb_req_cap & & s & & s - > req_cap ) {
2012-02-27 05:23:10 -05:00
for ( hdr = 0 ; hdr < fe - > nb_req_cap ; hdr + + ) {
if ( hdr > 0 )
LOGCHAR ( ' ' ) ;
if ( tmp - > options & LOG_OPT_QUOTE )
LOGCHAR ( ' " ' ) ;
2015-04-03 16:16:32 -04:00
if ( s - > req_cap [ hdr ] ! = NULL ) {
2016-02-12 07:23:03 -05:00
ret = lf_encode_string ( tmplog , dst + maxsize ,
' # ' , hdr_encode_map , s - > req_cap [ hdr ] , tmp ) ;
2012-03-12 07:46:41 -04:00
if ( ret = = NULL | | * ret ! = ' \0 ' )
2012-03-26 11:52:55 -04:00
goto out ;
2012-03-12 07:46:41 -04:00
tmplog = ret ;
2012-02-27 05:23:10 -05:00
} else if ( ! ( tmp - > options & LOG_OPT_QUOTE ) )
LOGCHAR ( ' - ' ) ;
if ( tmp - > options & LOG_OPT_QUOTE )
LOGCHAR ( ' " ' ) ;
last_isspace = 0 ;
}
}
break ;
2006-06-25 20:48:02 -04:00
2012-03-12 07:46:41 -04:00
case LOG_FMT_HDRRESPONS : // %hs
2012-02-27 05:23:10 -05:00
/* response header */
2018-09-05 09:28:07 -04:00
if ( fe - > nb_rsp_cap & & s & & s - > res_cap ) {
2012-02-27 05:23:10 -05:00
if ( tmp - > options & LOG_OPT_QUOTE )
LOGCHAR ( ' " ' ) ;
LOGCHAR ( ' { ' ) ;
for ( hdr = 0 ; hdr < fe - > nb_rsp_cap ; hdr + + ) {
if ( hdr )
LOGCHAR ( ' | ' ) ;
2015-04-03 16:16:32 -04:00
if ( s - > res_cap [ hdr ] ! = NULL ) {
2016-02-12 07:23:03 -05:00
ret = lf_encode_string ( tmplog , dst + maxsize ,
' # ' , hdr_encode_map , s - > res_cap [ hdr ] , tmp ) ;
2012-03-12 07:46:41 -04:00
if ( ret = = NULL | | * ret ! = ' \0 ' )
2012-03-26 11:52:55 -04:00
goto out ;
2012-03-12 07:46:41 -04:00
tmplog = ret ;
2012-03-26 11:52:55 -04:00
}
2012-02-27 05:23:10 -05:00
}
LOGCHAR ( ' } ' ) ;
last_isspace = 0 ;
if ( tmp - > options & LOG_OPT_QUOTE )
LOGCHAR ( ' " ' ) ;
}
break ;
2012-03-12 07:46:41 -04:00
case LOG_FMT_HDRRESPONSLIST : // %hsl
2012-02-27 05:23:10 -05:00
/* response header list */
2018-09-05 09:28:07 -04:00
if ( fe - > nb_rsp_cap & & s & & s - > res_cap ) {
2012-02-27 05:23:10 -05:00
for ( hdr = 0 ; hdr < fe - > nb_rsp_cap ; hdr + + ) {
if ( hdr > 0 )
LOGCHAR ( ' ' ) ;
if ( tmp - > options & LOG_OPT_QUOTE )
LOGCHAR ( ' " ' ) ;
2015-04-03 16:16:32 -04:00
if ( s - > res_cap [ hdr ] ! = NULL ) {
2016-02-12 07:23:03 -05:00
ret = lf_encode_string ( tmplog , dst + maxsize ,
' # ' , hdr_encode_map , s - > res_cap [ hdr ] , tmp ) ;
2012-03-12 07:46:41 -04:00
if ( ret = = NULL | | * ret ! = ' \0 ' )
2012-03-26 11:52:55 -04:00
goto out ;
2012-03-12 07:46:41 -04:00
tmplog = ret ;
2012-02-27 05:23:10 -05:00
} else if ( ! ( tmp - > options & LOG_OPT_QUOTE ) )
LOGCHAR ( ' - ' ) ;
if ( tmp - > options & LOG_OPT_QUOTE )
LOGCHAR ( ' " ' ) ;
last_isspace = 0 ;
}
}
break ;
2012-03-12 07:46:41 -04:00
case LOG_FMT_REQ : // %r
2012-02-27 05:23:10 -05:00
/* Request */
if ( tmp - > options & LOG_OPT_QUOTE )
LOGCHAR ( ' " ' ) ;
2016-04-25 11:09:40 -04:00
uri = txn & & txn - > uri ? txn - > uri : " <BADREQ> " ;
2016-02-12 07:23:03 -05:00
ret = lf_encode_string ( tmplog , dst + maxsize ,
' # ' , url_encode_map , uri , tmp ) ;
2012-03-12 07:46:41 -04:00
if ( ret = = NULL | | * ret ! = ' \0 ' )
2012-03-26 11:52:55 -04:00
goto out ;
2012-03-12 07:46:41 -04:00
tmplog = ret ;
2012-02-27 05:23:10 -05:00
if ( tmp - > options & LOG_OPT_QUOTE )
LOGCHAR ( ' " ' ) ;
last_isspace = 0 ;
break ;
2012-04-05 12:02:55 -04:00
2015-04-27 17:37:03 -04:00
case LOG_FMT_HTTP_PATH : // %HP
2016-04-25 11:09:40 -04:00
uri = txn & & txn - > uri ? txn - > uri : " <BADREQ> " ;
2015-04-27 17:37:03 -04:00
2015-06-17 13:58:02 -04:00
if ( tmp - > options & LOG_OPT_QUOTE )
2015-04-27 17:37:03 -04:00
LOGCHAR ( ' " ' ) ;
end = uri + strlen ( uri ) ;
// look for the first whitespace character
while ( uri < end & & ! HTTP_IS_SPHT ( * uri ) )
uri + + ;
// keep advancing past multiple spaces
while ( uri < end & & HTTP_IS_SPHT ( * uri ) ) {
uri + + ; nspaces + + ;
}
// look for first space or question mark after url
spc = uri ;
while ( spc < end & & * spc ! = ' ? ' & & ! HTTP_IS_SPHT ( * spc ) )
spc + + ;
2016-04-25 19:39:02 -04:00
if ( ! txn | | ! txn - > uri | | nspaces = = 0 ) {
2018-07-13 04:54:26 -04:00
chunk . area = " <BADREQ> " ;
chunk . data = strlen ( " <BADREQ> " ) ;
2015-04-27 17:37:03 -04:00
} else {
2018-07-13 04:54:26 -04:00
chunk . area = uri ;
chunk . data = spc - uri ;
2015-04-27 17:37:03 -04:00
}
2016-02-12 07:23:03 -05:00
ret = lf_encode_chunk ( tmplog , dst + maxsize , ' # ' , url_encode_map , & chunk , tmp ) ;
2015-04-27 17:37:03 -04:00
if ( ret = = NULL | | * ret ! = ' \0 ' )
goto out ;
tmplog = ret ;
2015-06-17 13:58:02 -04:00
if ( tmp - > options & LOG_OPT_QUOTE )
2015-04-27 17:37:03 -04:00
LOGCHAR ( ' " ' ) ;
last_isspace = 0 ;
break ;
2015-07-31 12:14:16 -04:00
case LOG_FMT_HTTP_QUERY : // %HQ
if ( tmp - > options & LOG_OPT_QUOTE )
LOGCHAR ( ' " ' ) ;
2016-04-25 11:09:40 -04:00
if ( ! txn | | ! txn - > uri ) {
2018-07-13 04:54:26 -04:00
chunk . area = " <BADREQ> " ;
chunk . data = strlen ( " <BADREQ> " ) ;
2015-07-31 12:14:16 -04:00
} else {
uri = txn - > uri ;
end = uri + strlen ( uri ) ;
// look for the first question mark
while ( uri < end & & * uri ! = ' ? ' )
uri + + ;
qmark = uri ;
// look for first space or question mark after url
while ( uri < end & & ! HTTP_IS_SPHT ( * uri ) )
uri + + ;
2018-07-13 04:54:26 -04:00
chunk . area = qmark ;
chunk . data = uri - qmark ;
2015-07-31 12:14:16 -04:00
}
2016-02-12 07:23:03 -05:00
ret = lf_encode_chunk ( tmplog , dst + maxsize , ' # ' , url_encode_map , & chunk , tmp ) ;
2015-07-31 12:14:16 -04:00
if ( ret = = NULL | | * ret ! = ' \0 ' )
goto out ;
tmplog = ret ;
if ( tmp - > options & LOG_OPT_QUOTE )
LOGCHAR ( ' " ' ) ;
last_isspace = 0 ;
break ;
2015-04-27 17:37:03 -04:00
case LOG_FMT_HTTP_URI : // %HU
2016-04-25 11:09:40 -04:00
uri = txn & & txn - > uri ? txn - > uri : " <BADREQ> " ;
2015-04-27 17:37:03 -04:00
2015-06-17 13:58:02 -04:00
if ( tmp - > options & LOG_OPT_QUOTE )
2015-04-27 17:37:03 -04:00
LOGCHAR ( ' " ' ) ;
end = uri + strlen ( uri ) ;
// look for the first whitespace character
while ( uri < end & & ! HTTP_IS_SPHT ( * uri ) )
uri + + ;
// keep advancing past multiple spaces
while ( uri < end & & HTTP_IS_SPHT ( * uri ) ) {
uri + + ; nspaces + + ;
}
// look for first space after url
spc = uri ;
while ( spc < end & & ! HTTP_IS_SPHT ( * spc ) )
spc + + ;
2016-04-25 11:09:40 -04:00
if ( ! txn | | ! txn - > uri | | nspaces = = 0 ) {
2018-07-13 04:54:26 -04:00
chunk . area = " <BADREQ> " ;
chunk . data = strlen ( " <BADREQ> " ) ;
2015-04-27 17:37:03 -04:00
} else {
2018-07-13 04:54:26 -04:00
chunk . area = uri ;
chunk . data = spc - uri ;
2015-04-27 17:37:03 -04:00
}
2016-02-12 07:23:03 -05:00
ret = lf_encode_chunk ( tmplog , dst + maxsize , ' # ' , url_encode_map , & chunk , tmp ) ;
2015-04-27 17:37:03 -04:00
if ( ret = = NULL | | * ret ! = ' \0 ' )
goto out ;
tmplog = ret ;
2015-06-17 13:58:02 -04:00
if ( tmp - > options & LOG_OPT_QUOTE )
2015-04-27 17:37:03 -04:00
LOGCHAR ( ' " ' ) ;
last_isspace = 0 ;
break ;
case LOG_FMT_HTTP_METHOD : // %HM
2016-04-25 11:09:40 -04:00
uri = txn & & txn - > uri ? txn - > uri : " <BADREQ> " ;
2015-06-17 13:58:02 -04:00
if ( tmp - > options & LOG_OPT_QUOTE )
2015-04-27 17:37:03 -04:00
LOGCHAR ( ' " ' ) ;
end = uri + strlen ( uri ) ;
// look for the first whitespace character
spc = uri ;
while ( spc < end & & ! HTTP_IS_SPHT ( * spc ) )
spc + + ;
if ( spc = = end ) { // odd case, we have txn->uri, but we only got a verb
2018-07-13 04:54:26 -04:00
chunk . area = " <BADREQ> " ;
chunk . data = strlen ( " <BADREQ> " ) ;
2015-04-27 17:37:03 -04:00
} else {
2018-07-13 04:54:26 -04:00
chunk . area = uri ;
chunk . data = spc - uri ;
2015-04-27 17:37:03 -04:00
}
2016-02-12 07:23:03 -05:00
ret = lf_encode_chunk ( tmplog , dst + maxsize , ' # ' , url_encode_map , & chunk , tmp ) ;
2015-04-27 17:37:03 -04:00
if ( ret = = NULL | | * ret ! = ' \0 ' )
goto out ;
tmplog = ret ;
2015-06-17 13:58:02 -04:00
if ( tmp - > options & LOG_OPT_QUOTE )
2015-04-27 17:37:03 -04:00
LOGCHAR ( ' " ' ) ;
last_isspace = 0 ;
break ;
case LOG_FMT_HTTP_VERSION : // %HV
2016-04-25 11:09:40 -04:00
uri = txn & & txn - > uri ? txn - > uri : " <BADREQ> " ;
2015-06-17 13:58:02 -04:00
if ( tmp - > options & LOG_OPT_QUOTE )
2015-04-27 17:37:03 -04:00
LOGCHAR ( ' " ' ) ;
end = uri + strlen ( uri ) ;
// look for the first whitespace character
while ( uri < end & & ! HTTP_IS_SPHT ( * uri ) )
uri + + ;
// keep advancing past multiple spaces
while ( uri < end & & HTTP_IS_SPHT ( * uri ) ) {
uri + + ; nspaces + + ;
}
// look for the next whitespace character
while ( uri < end & & ! HTTP_IS_SPHT ( * uri ) )
uri + + ;
// keep advancing past multiple spaces
while ( uri < end & & HTTP_IS_SPHT ( * uri ) )
uri + + ;
2016-04-25 11:09:40 -04:00
if ( ! txn | | ! txn - > uri | | nspaces = = 0 ) {
2018-07-13 04:54:26 -04:00
chunk . area = " <BADREQ> " ;
chunk . data = strlen ( " <BADREQ> " ) ;
2015-04-27 17:37:03 -04:00
} else if ( uri = = end ) {
2018-07-13 04:54:26 -04:00
chunk . area = " HTTP/0.9 " ;
chunk . data = strlen ( " HTTP/0.9 " ) ;
2015-04-27 17:37:03 -04:00
} else {
2018-07-13 04:54:26 -04:00
chunk . area = uri ;
chunk . data = end - uri ;
2015-04-27 17:37:03 -04:00
}
2016-02-12 07:23:03 -05:00
ret = lf_encode_chunk ( tmplog , dst + maxsize , ' # ' , url_encode_map , & chunk , tmp ) ;
2015-04-27 17:37:03 -04:00
if ( ret = = NULL | | * ret ! = ' \0 ' )
goto out ;
tmplog = ret ;
2015-06-17 13:58:02 -04:00
if ( tmp - > options & LOG_OPT_QUOTE )
2015-04-27 17:37:03 -04:00
LOGCHAR ( ' " ' ) ;
last_isspace = 0 ;
break ;
2012-04-05 12:02:55 -04:00
case LOG_FMT_COUNTER : // %rt
if ( tmp - > options & LOG_OPT_HEXA ) {
2018-09-05 09:52:59 -04:00
iret = snprintf ( tmplog , dst + maxsize - tmplog , " %04X " , uniq_id ) ;
2012-04-05 12:02:55 -04:00
if ( iret < 0 | | iret > dst + maxsize - tmplog )
goto out ;
last_isspace = 0 ;
tmplog + = iret ;
} else {
2018-09-05 09:52:59 -04:00
ret = ltoa_o ( uniq_id , tmplog , dst + maxsize - tmplog ) ;
2012-04-05 12:02:55 -04:00
if ( ret = = NULL )
goto out ;
tmplog = ret ;
last_isspace = 0 ;
}
break ;
2014-08-28 09:03:15 -04:00
case LOG_FMT_LOGCNT : // %lc
if ( tmp - > options & LOG_OPT_HEXA ) {
2015-04-03 09:40:56 -04:00
iret = snprintf ( tmplog , dst + maxsize - tmplog , " %04X " , fe - > log_count ) ;
2014-08-28 09:03:15 -04:00
if ( iret < 0 | | iret > dst + maxsize - tmplog )
goto out ;
last_isspace = 0 ;
tmplog + = iret ;
} else {
2015-04-03 09:40:56 -04:00
ret = ultoa_o ( fe - > log_count , tmplog , dst + maxsize - tmplog ) ;
2014-08-28 09:03:15 -04:00
if ( ret = = NULL )
goto out ;
tmplog = ret ;
last_isspace = 0 ;
}
break ;
2012-04-05 12:02:55 -04:00
case LOG_FMT_HOSTNAME : // %H
src = hostname ;
ret = lf_text ( tmplog , src , dst + maxsize - tmplog , tmp ) ;
if ( ret = = NULL )
goto out ;
tmplog = ret ;
last_isspace = 0 ;
break ;
case LOG_FMT_PID : // %pid
if ( tmp - > options & LOG_OPT_HEXA ) {
iret = snprintf ( tmplog , dst + maxsize - tmplog , " %04X " , pid ) ;
if ( iret < 0 | | iret > dst + maxsize - tmplog )
goto out ;
last_isspace = 0 ;
tmplog + = iret ;
} else {
ret = ltoa_o ( pid , tmplog , dst + maxsize - tmplog ) ;
if ( ret = = NULL )
goto out ;
tmplog = ret ;
last_isspace = 0 ;
}
break ;
2012-03-12 07:48:57 -04:00
case LOG_FMT_UNIQUEID : // %ID
2013-08-28 09:44:19 -04:00
ret = NULL ;
2018-09-05 09:49:01 -04:00
src = s ? s - > unique_id : NULL ;
2014-04-14 19:38:48 -04:00
ret = lf_text ( tmplog , src , maxsize - ( tmplog - dst ) , tmp ) ;
2012-03-12 07:48:57 -04:00
if ( ret = = NULL )
goto out ;
tmplog = ret ;
last_isspace = 0 ;
break ;
2012-02-27 05:23:10 -05:00
}
}
out :
2012-03-12 07:46:41 -04:00
/* *tmplog is a unused character */
* tmplog = ' \0 ' ;
2012-12-27 20:44:01 -05:00
return tmplog - dst ;
2012-02-27 05:23:10 -05:00
2006-06-25 20:48:02 -04:00
}
2012-03-12 07:46:41 -04:00
/*
REORG/MAJOR: session: rename the "session" entity to "stream"
With HTTP/2, we'll have to support multiplexed streams. A stream is in
fact the largest part of what we currently call a session, it has buffers,
logs, etc.
In order to catch any error, this commit removes any reference to the
struct session and tries to rename most "session" occurrences in function
names to "stream" and "sess" to "strm" when that's related to a session.
The files stream.{c,h} were added and session.{c,h} removed.
The session will be reintroduced later and a few parts of the stream
will progressively be moved overthere. It will more or less contain
only what we need in an embryonic session.
Sample fetch functions and converters will have to change a bit so
that they'll use an L5 (session) instead of what's currently called
"L4" which is in fact L6 for now.
Once all changes are completed, we should see approximately this :
L7 - http_txn
L6 - stream
L5 - session
L4 - connection | applet
There will be at most one http_txn per stream, and a same session will
possibly be referenced by multiple streams. A connection will point to
a session and to a stream. The session will hold all the information
we need to keep even when we don't yet have a stream.
Some more cleanup is needed because some code was already far from
being clean. The server queue management still refers to sessions at
many places while comments talk about connections. This will have to
be cleaned up once we have a server-side connection pool manager.
Stream flags "SN_*" still need to be renamed, it doesn't seem like
any of them will need to move to the session.
2015-04-02 18:22:06 -04:00
* send a log for the stream when we have enough info about it .
2012-03-12 07:46:41 -04:00
* Will not log if the frontend has no log defined .
*/
REORG/MAJOR: session: rename the "session" entity to "stream"
With HTTP/2, we'll have to support multiplexed streams. A stream is in
fact the largest part of what we currently call a session, it has buffers,
logs, etc.
In order to catch any error, this commit removes any reference to the
struct session and tries to rename most "session" occurrences in function
names to "stream" and "sess" to "strm" when that's related to a session.
The files stream.{c,h} were added and session.{c,h} removed.
The session will be reintroduced later and a few parts of the stream
will progressively be moved overthere. It will more or less contain
only what we need in an embryonic session.
Sample fetch functions and converters will have to change a bit so
that they'll use an L5 (session) instead of what's currently called
"L4" which is in fact L6 for now.
Once all changes are completed, we should see approximately this :
L7 - http_txn
L6 - stream
L5 - session
L4 - connection | applet
There will be at most one http_txn per stream, and a same session will
possibly be referenced by multiple streams. A connection will point to
a session and to a stream. The session will hold all the information
we need to keep even when we don't yet have a stream.
Some more cleanup is needed because some code was already far from
being clean. The server queue management still refers to sessions at
many places while comments talk about connections. This will have to
be cleaned up once we have a server-side connection pool manager.
Stream flags "SN_*" still need to be renamed, it doesn't seem like
any of them will need to move to the session.
2015-04-02 18:22:06 -04:00
void strm_log ( struct stream * s )
2012-03-12 07:46:41 -04:00
{
2015-04-03 09:40:56 -04:00
struct session * sess = s - > sess ;
2012-03-12 07:46:41 -04:00
int size , err , level ;
2015-09-25 13:17:44 -04:00
int sd_size = 0 ;
2012-03-12 07:46:41 -04:00
/* if we don't want to log normal traffic, return now */
2015-04-02 19:14:29 -04:00
err = ( s - > flags & SF_REDISP ) | |
( ( s - > flags & SF_ERR_MASK ) > SF_ERR_LOCAL ) | |
( ( ( s - > flags & SF_ERR_MASK ) = = SF_ERR_NONE ) & &
2014-11-28 08:42:25 -05:00
( s - > si [ 1 ] . conn_retries ! = s - > be - > conn_retries ) ) | |
2015-04-03 17:46:31 -04:00
( ( sess - > fe - > mode = = PR_MODE_HTTP ) & & s - > txn & & s - > txn - > status > = 500 ) ;
2006-06-25 20:48:02 -04:00
2015-04-03 09:40:56 -04:00
if ( ! err & & ( sess - > fe - > options2 & PR_O2_NOLOGNORM ) )
2012-03-12 07:46:41 -04:00
return ;
2012-02-27 05:23:10 -05:00
2015-04-03 09:40:56 -04:00
if ( LIST_ISEMPTY ( & sess - > fe - > logsrvs ) )
2012-03-12 07:46:41 -04:00
return ;
2012-02-27 05:23:10 -05:00
2013-06-11 11:18:02 -04:00
if ( s - > logs . level ) { /* loglevel was overridden */
if ( s - > logs . level = = - 1 ) {
s - > logs . logwait = 0 ; /* logs disabled */
return ;
}
level = s - > logs . level - 1 ;
}
else {
level = LOG_INFO ;
2015-04-03 09:40:56 -04:00
if ( err & & ( sess - > fe - > options2 & PR_O2_LOGERRORS ) )
2013-06-11 11:18:02 -04:00
level = LOG_ERR ;
}
2012-03-12 07:46:41 -04:00
2013-08-28 09:44:19 -04:00
/* if unique-id was not generated */
2015-04-03 09:40:56 -04:00
if ( ! s - > unique_id & & ! LIST_ISEMPTY ( & sess - > fe - > format_unique_id ) ) {
2017-11-24 11:34:44 -05:00
if ( ( s - > unique_id = pool_alloc ( pool_head_uniqueid ) ) ! = NULL )
2015-04-03 09:40:56 -04:00
build_logline ( s , s - > unique_id , UNIQUEID_LEN , & sess - > fe - > format_unique_id ) ;
2013-08-28 09:44:19 -04:00
}
2015-09-25 13:17:44 -04:00
if ( ! LIST_ISEMPTY ( & sess - > fe - > logformat_sd ) ) {
sd_size = build_logline ( s , logline_rfc5424 , global . max_syslog_len ,
& sess - > fe - > logformat_sd ) ;
}
2015-09-19 16:09:02 -04:00
size = build_logline ( s , logline , global . max_syslog_len , & sess - > fe - > logformat ) ;
2012-03-12 07:46:41 -04:00
if ( size > 0 ) {
2019-03-08 12:53:21 -05:00
_HA_ATOMIC_ADD ( & sess - > fe - > log_count , 1 ) ;
2015-09-25 13:17:44 -04:00
__send_log ( sess - > fe , level , logline , size + 1 , logline_rfc5424 , sd_size ) ;
2012-03-12 07:46:41 -04:00
s - > logs . logwait = 0 ;
}
}
2012-02-27 05:23:10 -05:00
2018-09-05 13:51:10 -04:00
/*
* send a minimalist log for the session . Will not log if the frontend has no
* log defined . It is assumed that this is only used to report anomalies that
* cannot lead to the creation of a regular stream . Because of this the log
* level is LOG_INFO or LOG_ERR depending on the " log-separate-error " setting
* in the frontend . The caller must simply know that it should not call this
2018-10-05 04:22:27 -04:00
* function to report unimportant events . It is safe to call this function with
* sess = = NULL ( will not do anything ) .
2018-09-05 13:51:10 -04:00
*/
void sess_log ( struct session * sess )
{
int size , level ;
int sd_size = 0 ;
2018-10-05 04:22:27 -04:00
if ( ! sess )
return ;
2018-09-05 13:51:10 -04:00
if ( LIST_ISEMPTY ( & sess - > fe - > logsrvs ) )
return ;
level = LOG_INFO ;
if ( sess - > fe - > options2 & PR_O2_LOGERRORS )
level = LOG_ERR ;
if ( ! LIST_ISEMPTY ( & sess - > fe - > logformat_sd ) ) {
sd_size = sess_build_logline ( sess , NULL ,
logline_rfc5424 , global . max_syslog_len ,
& sess - > fe - > logformat_sd ) ;
}
size = sess_build_logline ( sess , NULL , logline , global . max_syslog_len , & sess - > fe - > logformat ) ;
if ( size > 0 ) {
2019-03-08 12:53:21 -05:00
_HA_ATOMIC_ADD ( & sess - > fe - > log_count , 1 ) ;
2018-09-05 13:51:10 -04:00
__send_log ( sess - > fe , level , logline , size + 1 , logline_rfc5424 , sd_size ) ;
}
}
2017-10-24 06:00:51 -04:00
static int cli_io_handler_show_startup_logs ( struct appctx * appctx )
{
struct stream_interface * si = appctx - > owner ;
const char * msg = ( startup_logs ? startup_logs : " No startup alerts/warnings. \n " ) ;
if ( ci_putstr ( si_ic ( si ) , msg ) = = - 1 ) {
2018-11-15 05:08:52 -05:00
si_rx_room_blk ( si ) ;
2017-10-24 06:00:51 -04:00
return 0 ;
}
return 1 ;
}
/* register cli keywords */
static struct cli_kw_list cli_kws = { { } , {
{ { " show " , " startup-logs " , NULL } ,
" show startup-logs : report logs emitted during HAProxy startup " ,
NULL , cli_io_handler_show_startup_logs } ,
{ { } , }
} } ;
2018-11-25 13:14:37 -05:00
INITCALL1 ( STG_REGISTER , cli_register_kw , & cli_kws ) ;
2018-11-26 05:21:50 -05:00
REGISTER_PER_THREAD_INIT ( init_log_buffers_per_thread ) ;
REGISTER_PER_THREAD_DEINIT ( deinit_log_buffers_per_thread ) ;
2006-06-25 20:48:02 -04:00
/*
* Local variables :
* c - indent - level : 8
* c - basic - offset : 8
* End :
*/