From: William Lallemand Date: Mon, 27 Feb 2012 10:23:10 +0000 (+0100) Subject: MEDIUM: log: use log_format for mode tcplog X-Git-Tag: v1.5-dev8~12 X-Git-Url: http://git.ipfire.org/?a=commitdiff_plain;h=bddd4fd93b8d9e77aeeae19440f6343d7327c195;p=thirdparty%2Fhaproxy.git MEDIUM: log: use log_format for mode tcplog Merge http_sess_log() and tcp_sess_log() to sess_log() and move it to log.c A new field in logformat_type define if you can use a logformat variable in TCP or HTTP mode. doc: log-format in tcp mode Note that due to the way log buffer allocation currently works, trying to log an HTTP request without "option httplog" is still not possible. This will change in the near future. --- diff --git a/doc/configuration.txt b/doc/configuration.txt index 6ed736a624..70a25391e7 100644 --- a/doc/configuration.txt +++ b/doc/configuration.txt @@ -8741,8 +8741,8 @@ Detailed fields description : 8.2.4 Custom log format ----------------------- -The directive log-format allows you to custom the logs in http mode. It takes a -string as argument. +The directive log-format allows you to custom the logs in http mode and tcp +mode. It takes a string as argument. HAproxy understands some log format variables. % precedes log format variables. Variables can take arguments using braces ('{}'), and multiple arguments are @@ -8769,49 +8769,55 @@ At the moment, the default HTTP format is defined this way : log-format %Ci:%Cp\ [%t]\ %f\ %b/%s\ %Tq/%Tw/%Tc/%Tr/%Tt\ %st\ %B\ %cc\ \ %cs\ %ts\ %ac/%fc/%bc/%sc/%rc\ %sq/%bq\ %hr\ %hs\ %{+Q}r -And the default CLF format is defined this way : +the default CLF format is defined this way : log-format %{+Q}o\ %{-Q}Ci\ -\ -\ [%T]\ %r\ %st\ %B\ \"\"\ \"\"\ %Cp\ \ %ms\ %f\ %b\ %s\ \%Tq\ %Tw\ %Tc\ %Tr\ %Tt\ %ts\ %ac\ %fc\ \ %bc\ %sc\ %rc\ %sq\ %bq\ %cc\ %cs\ \%hrl\ %hsl -Please refer to the table below for currently defined variables : +and the default TCP format is defined this way : + + log-format %Ci:%Cp\ [%t]\ %f\ %b/%s\ %Tw/%Tc/%Tt\ %B\ %ts\ \ + %ac/%fc/%bc/%sc/%rc\ %sq/%bq - +------+-----------------------------------------------+-------------+ - | var | field name (8.2.2 and 8.2.3 for description) | type | - +------+-----------------------------------------------+-------------+ - | %o | special variable, apply flags on all next var | | - +------+-----------------------------------------------+-------------+ - | %B | bytes_read | numeric | - | %Ci | client_ip | string | - | %Cp | client_port | numeric | - | %Tc | Tc | numeric | - | %Tq | Tq | numeric | - | %Tr | Tr | numeric | - | %Tt | Tt | numeric | - | %Tw | Tw | numeric | - | %ac | actconn | numeric | - | %b | backend_name | string | - | %bc | beconn | numeric | - | %bq | backend_queue | numeric | - | %cc | captured_request_cookie | string | - | %cs | captured_response_cookie | string | - | %f | frontend_name | string | - | %fc | feconn | numeric | - | %hr | captured_request_headers default style | string | - | %hrl | captured_request_headers CLF style | string list | - | %hs | captured_response_headers default style | string | - | %hsl | captured_response_headers CLF style | string list | - | %ms | accept date milliseconds | numeric | - | %r | http_request | string | - | %rc | retries | numeric | - | %s | server_name | string | - | %sc | srv_conn | numeric | - | %sq | srv_queue | numeric | - | %st | status_code | numeric | - | %ts | termination_state | string | - +------+-----------------------------------------------+-------------+ +Please refer to the table below for currently defined variables : + +---+------+-----------------------------------------------+-------------+ + | H | var | field name (8.2.2 and 8.2.3 for description) | type | + +---+------+-----------------------------------------------+-------------+ + | | %o | special variable, apply flags on all next var | | + +---+------+-----------------------------------------------+-------------+ + | | %B | bytes_read | numeric | + | | %Ci | client_ip | string | + | | %Cp | client_port | numeric | + | | %Tc | Tc | numeric | + | * | %Tq | Tq | numeric | + | * | %Tr | Tr | numeric | + | | %Tt | Tt | numeric | + | | %Tw | Tw | numeric | + | | %ac | actconn | numeric | + | | %b | backend_name | string | + | | %bc | beconn | numeric | + | | %bq | backend_queue | numeric | + | * | %cc | captured_request_cookie | string | + | * | %cs | captured_response_cookie | string | + | | %f | frontend_name | string | + | | %fc | feconn | numeric | + | * | %hr | captured_request_headers default style | string | + | * | %hrl | captured_request_headers CLF style | string list | + | * | %hs | captured_response_headers default style | string | + | * | %hsl | captured_response_headers CLF style | string list | + | | %ms | accept date milliseconds | numeric | + | * | %r | http_request | string | + | | %rc | retries | numeric | + | | %s | server_name | string | + | | %sc | srv_conn | numeric | + | | %sq | srv_queue | numeric | + | * | %st | status_code | numeric | + | | %ts | termination_state | string | + +---+------+-----------------------------------------------+-------------+ + +*: mode httplog only 8.3. Advanced logging options ----------------------------- diff --git a/include/proto/log.h b/include/proto/log.h index 34d3813298..66fbe34df5 100644 --- a/include/proto/log.h +++ b/include/proto/log.h @@ -35,9 +35,17 @@ extern struct pool_head *pool2_requri; extern char *log_format; +extern char default_tcp_log_format[]; extern char default_http_log_format[]; extern char clf_http_log_format[]; + +/* + * send a log for the session when we have enough info about it. + * Will not log if the frontend has no log defined. + */ +void sess_log(struct session *s); + /* * Parse args in a logformat_var */ @@ -98,10 +106,6 @@ void send_log(struct proxy *p, int level, const char *format, ...) */ void __send_log(struct proxy *p, int level, char *message, size_t size); -/* - * send a log for the session when we have enough info about it - */ -void tcp_sess_log(struct session *s); /* * returns log level for or -1 if not found. diff --git a/src/cfgparse.c b/src/cfgparse.c index e01b90f76a..6f1df9c997 100644 --- a/src/cfgparse.c +++ b/src/cfgparse.c @@ -3313,9 +3313,13 @@ stats_error_parsing: } parse_logformat_string(logformat, curproxy); } - else if (!strcmp(args[1], "tcplog")) + else if (!strcmp(args[1], "tcplog")) { + char *logformat; /* generate a detailed TCP log */ curproxy->to_log |= LW_DATE | LW_CLIP | LW_SVID | LW_PXID | LW_BYTES; + logformat = default_tcp_log_format; + parse_logformat_string(logformat, curproxy); + } else if (!strcmp(args[1], "tcpka")) { /* enable TCP keep-alives on client and server sessions */ if (warnifnotcap(curproxy, PR_CAP_BE | PR_CAP_FE, file, linenum, args[1], NULL)) diff --git a/src/frontend.c b/src/frontend.c index f185f62c7b..12dc2c8a0e 100644 --- a/src/frontend.c +++ b/src/frontend.c @@ -78,10 +78,7 @@ int frontend_accept(struct session *s) /* FIXME: the logs are horribly complicated now, because they are * defined in

,

, and later and . */ - if (s->logs.logwait & LW_REQ) - s->do_log = http_sess_log; - else - s->do_log = tcp_sess_log; + s->do_log = sess_log; /* default error reporting function, may be changed by analysers */ s->srv_error = default_srv_error; diff --git a/src/log.c b/src/log.c index 0d13329356..3bcfaa56b9 100644 --- a/src/log.c +++ b/src/log.c @@ -56,46 +56,48 @@ const char sess_fin_state[8] = "-RCHDLQT"; /* cliRequest, srvConnect, srvHeader struct logformat_type { char *name; int type; + int mode; }; /* log_format variable names */ static const struct logformat_type logformat_keywords[] = { - { "o", LOG_GLOBAL }, /* global option */ - { "Ci", LOG_CLIENTIP }, /* client ip */ - { "Cp", LOG_CLIENTPORT }, /* client port */ - { "t", LOG_DATE }, /* date */ - { "T", LOG_DATEGMT }, /* date GMT */ - { "ms", LOG_MS }, /* accept date millisecond */ - { "f", LOG_FRONTEND }, /* frontend */ - { "b", LOG_BACKEND }, /* backend */ - { "s", LOG_SERVER }, /* server */ - { "B", LOG_BYTES }, /* bytes read */ - { "Tq", LOG_TQ }, /* Tq */ - { "Tw", LOG_TW }, /* Tw */ - { "Tc", LOG_TC }, /* Tc */ - { "Tr", LOG_TR }, /* Tr */ - { "Tt", LOG_TT }, /* Tt */ - { "st", LOG_STATUS }, /* status code */ - { "cc", LOG_CCLIENT }, /* client cookie */ - { "cs", LOG_CSERVER }, /* server cookie */ - { "ts", LOG_TERMSTATE },/* terminaison state */ - { "ac", LOG_ACTCONN }, /* actconn */ - { "fc", LOG_FECONN }, /* feconn */ - { "bc", LOG_BECONN }, /* beconn */ - { "sc", LOG_SRVCONN }, /* srv_conn */ - { "rc", LOG_RETRIES }, /* retries */ - { "sq", LOG_SRVQUEUE }, /* srv_queue */ - { "bq", LOG_BCKQUEUE }, /* backend_queue */ - { "hr", LOG_HDRREQUEST }, /* header request */ - { "hs", LOG_HDRRESPONS }, /* header response */ - { "hrl", LOG_HDRREQUESTLIST }, /* header request list */ - { "hsl", LOG_HDRRESPONSLIST }, /* header response list */ - { "r", LOG_REQ }, /* request */ + { "o", LOG_GLOBAL, PR_MODE_TCP }, /* global option */ + { "Ci", LOG_CLIENTIP, PR_MODE_TCP }, /* client ip */ + { "Cp", LOG_CLIENTPORT, PR_MODE_TCP }, /* client port */ + { "t", LOG_DATE, PR_MODE_TCP }, /* date */ + { "T", LOG_DATEGMT, PR_MODE_TCP }, /* date GMT */ + { "ms", LOG_MS, PR_MODE_TCP }, /* accept date millisecond */ + { "f", LOG_FRONTEND, PR_MODE_TCP }, /* frontend */ + { "b", LOG_BACKEND, PR_MODE_TCP }, /* backend */ + { "s", LOG_SERVER, PR_MODE_TCP }, /* server */ + { "B", LOG_BYTES, PR_MODE_TCP }, /* bytes read */ + { "Tq", LOG_TQ, PR_MODE_HTTP }, /* Tq */ + { "Tw", LOG_TW, PR_MODE_TCP }, /* Tw */ + { "Tc", LOG_TC, PR_MODE_TCP }, /* Tc */ + { "Tr", LOG_TR, PR_MODE_HTTP }, /* Tr */ + { "Tt", LOG_TT, PR_MODE_TCP }, /* Tt */ + { "st", LOG_STATUS, PR_MODE_HTTP }, /* status code */ + { "cc", LOG_CCLIENT, PR_MODE_HTTP }, /* client cookie */ + { "cs", LOG_CSERVER, PR_MODE_HTTP }, /* server cookie */ + { "ts", LOG_TERMSTATE, PR_MODE_TCP },/* terminaison state */ + { "ac", LOG_ACTCONN, PR_MODE_TCP }, /* actconn */ + { "fc", LOG_FECONN, PR_MODE_TCP }, /* feconn */ + { "bc", LOG_BECONN, PR_MODE_TCP }, /* beconn */ + { "sc", LOG_SRVCONN, PR_MODE_TCP }, /* srv_conn */ + { "rc", LOG_RETRIES, PR_MODE_TCP }, /* retries */ + { "sq", LOG_SRVQUEUE, PR_MODE_TCP }, /* srv_queue */ + { "bq", LOG_BCKQUEUE, PR_MODE_TCP }, /* backend_queue */ + { "hr", LOG_HDRREQUEST, PR_MODE_HTTP }, /* header request */ + { "hs", LOG_HDRRESPONS, PR_MODE_HTTP }, /* header response */ + { "hrl", LOG_HDRREQUESTLIST, PR_MODE_HTTP }, /* header request list */ + { "hsl", LOG_HDRRESPONSLIST, PR_MODE_HTTP }, /* header response list */ + { "r", LOG_REQ, PR_MODE_HTTP }, /* request */ { 0, 0 } }; char default_http_log_format[] = "%Ci:%Cp [%t] %f %b/%s %Tq/%Tw/%Tc/%Tr/%Tt %st %B %cc %cs %ts %ac/%fc/%bc/%sc/%rc %sq/%bq %hr %hs %{+Q}r"; // default format char clf_http_log_format[] = "%{+Q}o %{-Q}Ci - - [%T] %r %st %B \"\" \"\" %Cp %ms %f %b %s %Tq %Tw %Tc %Tr %Tt %ts %ac %fc %bc %sc %rc %sq %bq %cc %cs %hrl %hsl"; +char default_tcp_log_format[] = "%Ci:%Cp [%t] %f %b/%s %Tw/%Tc/%Tt %B %ts %ac/%fc/%bc/%sc/%rc %sq/%bq"; char *log_format = NULL; struct logformat_var_args { @@ -174,7 +176,6 @@ int parse_logformat_var(char *str, size_t len, struct proxy *curproxy) char varname[255] = { 0 }; // variable name int logformat_options = 0x00000000; - for (i = 1; i < len; i++) { // escape first char % if (!arg && str[i] == '{') { arg = str + i; @@ -190,18 +191,25 @@ int parse_logformat_var(char *str, size_t len, struct proxy *curproxy) varname[len - i] = '\0'; for (j = 0; logformat_keywords[j].name; j++) { // search a log type if (strcmp(varname, logformat_keywords[j].name) == 0) { - node = calloc(1, sizeof(struct logformat_node)); - node->type = logformat_keywords[j].type; - node->options = logformat_options; - node->arg = arg; - parse_logformat_var_args(node->arg, node); - if (node->type == LOG_GLOBAL) { - logformat_options = node->options; - free(node); + if (!((logformat_keywords[j].mode == PR_MODE_HTTP) && (curproxy->mode == PR_MODE_TCP))) { + node = calloc(1, sizeof(struct logformat_node)); + node->type = logformat_keywords[j].type; + node->options = logformat_options; + node->arg = arg; + parse_logformat_var_args(node->arg, node); + if (node->type == LOG_GLOBAL) { + logformat_options = node->options; + free(node); + } else { + LIST_ADDQ(&curproxy->logformat, &node->list); + } + return 0; } else { - LIST_ADDQ(&curproxy->logformat, &node->list); + Warning("Warning: No such variable name '%s' in this log mode\n", varname); + if (arg) + free(arg); + return -1; } - return 0; } } Warning("Warning: No such variable name '%s' in logformat\n", varname); @@ -438,50 +446,50 @@ int get_log_facility(const char *fac) */ char *logformat_write_string(char *dst, char *src, size_t size, struct logformat_node *node) { - char *orig = dst; - - if (src == NULL || *src == '\0') { - if (node->options & LOG_OPT_QUOTE) { - if (size > 2) { - *(dst++) = '"'; - *(dst++) = '"'; - *dst = '\0'; - node->options |= LOG_OPT_WRITTEN; - } else { - dst = NULL; - return dst; - } - } else { - if (size > 1) { - *(dst++) = '-'; - *dst = '\0'; - node->options |= LOG_OPT_WRITTEN; - } else { // error no space available - dst = NULL; - return dst; - } - } - } else { - if (node->options & LOG_OPT_QUOTE) { - if (size-- > 1 ) { - *(dst++) = '"'; - } else { - dst = NULL; - return NULL; - } - dst += strlcpy2(dst, src, size); - size -= orig - dst + 1; - if (size > 1) { - *(dst++) = '"'; - *dst = '\0'; - } else { - dst = NULL; - } - } else { - dst += strlcpy2(dst, src, size); - } - } - return dst; + char *orig = dst; + + if (src == NULL || *src == '\0') { + if (node->options & LOG_OPT_QUOTE) { + if (size > 2) { + *(dst++) = '"'; + *(dst++) = '"'; + *dst = '\0'; + node->options |= LOG_OPT_WRITTEN; + } else { + dst = NULL; + return dst; + } + } else { + if (size > 1) { + *(dst++) = '-'; + *dst = '\0'; + node->options |= LOG_OPT_WRITTEN; + } else { // error no space available + dst = NULL; + return dst; + } + } + } else { + if (node->options & LOG_OPT_QUOTE) { + if (size-- > 1 ) { + *(dst++) = '"'; + } else { + dst = NULL; + return NULL; + } + dst += strlcpy2(dst, src, size); + size -= orig - dst + 1; + if (size > 1) { + *(dst++) = '"'; + *dst = '\0'; + } else { + dst = NULL; + } + } else { + dst += strlcpy2(dst, src, size); + } + } + return dst; } /* generate the syslog header once a second */ @@ -618,7 +626,7 @@ void __send_log(struct proxy *p, int level, char *message, size_t size) /* we can filter the level of the messages that are sent to each logger */ if (level > logsrv->level) continue; - + /* 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. @@ -646,32 +654,60 @@ void __send_log(struct proxy *p, int level, char *message, size_t size) } } +extern fd_set hdr_encode_map[]; +extern fd_set url_encode_map[]; + + +const char sess_cookie[8] = "NIDVEO67"; /* No cookie, Invalid cookie, cookie for a Down server, Valid cookie, Expired cookie, Old cookie, unknown */ +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 */ + +#define LOGCHAR(x) do { \ + if (MAX_SYSLOG_LEN - (tmplog - logline) > 1) { \ + *(tmplog++) = (x); \ + } else { \ + goto out; \ + } \ + } while(0) /* - * send a log for the session when we have enough info about it + * send a log for the session when we have enough info about it. + * Will not log if the frontend has no log defined. */ -void tcp_sess_log(struct session *s) +void sess_log(struct session *s) { char pn[INET6_ADDRSTRLEN]; struct proxy *fe = s->fe; struct proxy *be = s->be; struct proxy *prx_log; + struct http_txn *txn = &s->txn; int tolog, level, err; - char *svid; + char *uri; + const char *svid; struct tm tm; + int t_request; + int hdr; + int last_isspace = 1; + static char logline[MAX_SYSLOG_LEN] = { 0 }; + static char *tmplog; + struct logformat_node *tmp; /* if we don't want to log normal traffic, return now */ - err = (s->flags & (SN_ERR_MASK | SN_REDISP)) || (s->req->cons->conn_retries != be->conn_retries); + err = (s->flags & (SN_ERR_MASK | SN_REDISP)) || + (s->req->cons->conn_retries != be->conn_retries) || + ((s->fe->mode == PR_MODE_HTTP) && txn->status >= 500); if (!err && (fe->options2 & PR_O2_NOLOGNORM)) return; - addr_to_str(&s->si[0].addr.from, pn, sizeof(pn)); - get_localtime(s->logs.tv_accept.tv_sec, &tm); - - if(LIST_ISEMPTY(&fe->logsrvs)) + if (LIST_ISEMPTY(&fe->logsrvs)) return; - prx_log = fe; + + if (addr_to_str(&s->req->prod->addr.from, pn, sizeof(pn)) == AF_UNIX) + snprintf(pn, sizeof(pn), "unix:%d", s->listener->luid); + + /* FIXME: let's limit ourselves to frontend logging for now. */ tolog = fe->to_log; if (!(tolog & LW_SVID)) @@ -688,33 +724,345 @@ void tcp_sess_log(struct session *s) break; } + t_request = -1; + if (tv_isge(&s->logs.tv_request, &s->logs.tv_accept)) + t_request = tv_ms_elapsed(&s->logs.tv_accept, &s->logs.tv_request); + level = LOG_INFO; if (err && (fe->options2 & PR_O2_LOGERRORS)) level = LOG_ERR; - send_log(prx_log, level, "%s:%d [%02d/%s/%04d:%02d:%02d:%02d.%03d]" - " %s %s/%s %ld/%ld/%s%ld %s%lld" - " %c%c %d/%d/%d/%d/%s%u %ld/%ld\n", - s->si[0].addr.from.ss_family == AF_UNIX ? "unix" : pn, - s->si[0].addr.from.ss_family == AF_UNIX ? s->listener->luid : get_host_port(&s->si[0].addr.from), - tm.tm_mday, monthname[tm.tm_mon], tm.tm_year+1900, - tm.tm_hour, tm.tm_min, tm.tm_sec, (int)s->logs.tv_accept.tv_usec/1000, - fe->id, be->id, svid, - (s->logs.t_queue >= 0) ? s->logs.t_queue : -1, - (s->logs.t_connect >= 0) ? s->logs.t_connect - s->logs.t_queue : -1, - (tolog & LW_BYTES) ? "" : "+", s->logs.t_close, - (tolog & LW_BYTES) ? "" : "+", s->logs.bytes_out, - sess_term_cond[(s->flags & SN_ERR_MASK) >> SN_ERR_SHIFT], - sess_fin_state[(s->flags & SN_FINST_MASK) >> SN_FINST_SHIFT], - actconn, fe->feconn, be->beconn, target_srv(&s->target) ? target_srv(&s->target)->cur_sess : 0, - (s->flags & SN_REDISP)?"+":"", - (s->req->cons->conn_retries>0)?(be->conn_retries - s->req->cons->conn_retries):be->conn_retries, - s->logs.srv_queue_size, s->logs.prx_queue_size); + /* fill logbuffer */ + + tmplog = logline; + tmplog = hdr_log(tmplog); + + list_for_each_entry(tmp, &fe->logformat, list) { + char *src = NULL; + switch (tmp->type) { + + case LOG_SEPARATOR: + if (!last_isspace) { + LOGCHAR(' '); + last_isspace = 1; + *tmplog = '\0'; + } + break; + + case LOG_TEXT: // text + src = tmp->arg; + tmplog += strlcpy2(tmplog, src, MAX_SYSLOG_LEN - (tmplog - logline)); + if (!tmplog) + goto out; + last_isspace = 0; + break; + + case LOG_CLIENTIP: // %Ci + src = (s->req->prod->addr.from.ss_family == AF_UNIX) ? "unix" : pn; + tmplog = logformat_write_string(tmplog, src, MAX_SYSLOG_LEN - (tmplog - logline), tmp); + + if (!tmplog) + goto out; + last_isspace = 0; + break; + + case LOG_CLIENTPORT: // %Cp + tmplog = ltoa_o((s->req->prod->addr.from.ss_family == AF_UNIX) ? s->listener->luid : get_host_port(&s->req->prod->addr.from), + tmplog, MAX_SYSLOG_LEN - (tmplog - logline)); + if (!tmplog) + goto out; + last_isspace = 0; + break; + + case LOG_DATE: // %t + get_localtime(s->logs.accept_date.tv_sec, &tm); + tmplog = date2str_log(tmplog, &tm, &(s->logs.accept_date), MAX_SYSLOG_LEN - (tmplog - logline)); + if (!tmplog) + goto out; + last_isspace = 0; + break; + + case LOG_DATEGMT: // %T + get_gmtime(s->logs.accept_date.tv_sec, &tm); + tmplog = gmt2str_log(tmplog, &tm, MAX_SYSLOG_LEN - (tmplog - logline)); + if (!tmplog) + goto out; + last_isspace = 0; + break; + + case LOG_MS: // %ms + if ((MAX_SYSLOG_LEN - (tmplog - logline)) < 4) { + tmplog = NULL; + goto out; + } + tmplog = utoa_pad((unsigned int)s->logs.accept_date.tv_usec/1000, + tmplog, 4); + last_isspace = 0; + + break; + + case LOG_FRONTEND: // %f + src = fe->id; + tmplog = logformat_write_string(tmplog, src, MAX_SYSLOG_LEN - (tmplog - logline), tmp); + if (!tmplog) + goto out; + last_isspace = 0 ; + break; + + case LOG_BACKEND: // %b + src = be->id; + tmplog = logformat_write_string(tmplog, src, MAX_SYSLOG_LEN - (tmplog - logline), tmp); + if (!tmplog) + goto out; + last_isspace = 0 ; + break; + + case LOG_SERVER: // %s + src = (char *)svid; + tmplog = logformat_write_string(tmplog, src, MAX_SYSLOG_LEN - (tmplog - logline), tmp); + if (!tmplog) + goto out; + last_isspace = 0; + break; + + case LOG_TQ: // %Tq + tmplog = ltoa_o(t_request, tmplog, MAX_SYSLOG_LEN - (tmplog - logline)); + if (!tmplog) + goto out; + last_isspace = 0; + break; + + case LOG_TW: // %Tw + tmplog = ltoa_o((s->logs.t_queue >= 0) ? s->logs.t_queue - t_request : -1, tmplog, MAX_SYSLOG_LEN - (tmplog - logline)); + if (!tmplog) + goto out; + last_isspace = 0; + break; + + case LOG_TC: // %Tc + tmplog = ltoa_o((s->logs.t_connect >= 0) ? s->logs.t_connect - s->logs.t_queue : -1, tmplog, MAX_SYSLOG_LEN - (tmplog - logline)); + if (!tmplog) + goto out; + last_isspace = 0; + break; + + case LOG_TR: // %Tr + tmplog = ltoa_o((s->logs.t_data >= 0) ? s->logs.t_data - s->logs.t_connect : -1, tmplog, MAX_SYSLOG_LEN - (tmplog - logline)); + if (!tmplog) + goto out; + last_isspace = 0; + break; + + case LOG_TT: // %Tt + if (!(tolog & LW_BYTES)) + *(tmplog++) = '+'; + tmplog = ltoa_o(s->logs.t_close, tmplog, MAX_SYSLOG_LEN - (tmplog - logline)); + if (!tmplog) + goto out; + last_isspace = 0; + break; + + case LOG_STATUS: // %st + tmplog = ultoa_o(txn->status, tmplog, MAX_SYSLOG_LEN - (tmplog - logline)); + if (!tmplog) + goto out; + last_isspace = 0; + break; + + case LOG_BYTES: // %B + if (!(tolog & LW_BYTES)) + *(tmplog++) = '+'; + tmplog = lltoa(s->logs.bytes_out, tmplog, MAX_SYSLOG_LEN - (tmplog - logline)); + if (!tmplog) + goto out; + last_isspace = 0; + break; + + case LOG_CCLIENT: // %cc + src = txn->cli_cookie; + tmplog = logformat_write_string(tmplog, src, MAX_SYSLOG_LEN - (tmplog - logline), tmp); + last_isspace = 0; + break; + + case LOG_CSERVER: // %cs + src = txn->srv_cookie; + tmplog = logformat_write_string(tmplog, src, MAX_SYSLOG_LEN - (tmplog - logline), tmp); + last_isspace = 0; + break; + + case LOG_TERMSTATE: // %ts + + LOGCHAR(sess_term_cond[(s->flags & SN_ERR_MASK) >> SN_ERR_SHIFT]); + LOGCHAR(sess_fin_state[(s->flags & SN_FINST_MASK) >> SN_FINST_SHIFT]); + if (fe->mode == PR_MODE_HTTP) { + LOGCHAR((be->options & PR_O_COOK_ANY) ? sess_cookie[(txn->flags & TX_CK_MASK) >> TX_CK_SHIFT] : '-'); + LOGCHAR((be->options & PR_O_COOK_ANY) ? sess_set_cookie[(txn->flags & TX_SCK_MASK) >> TX_SCK_SHIFT] : '-'); + } + *tmplog = '\0'; + last_isspace = 0; + break; + + case LOG_ACTCONN: // %ac + tmplog = ltoa_o(actconn, tmplog, MAX_SYSLOG_LEN - (tmplog - logline)); + if (!tmplog) + goto out; + last_isspace = 0; + break; + + case LOG_FECONN: // %fc + tmplog = ltoa_o(fe->feconn, tmplog, MAX_SYSLOG_LEN - (tmplog - logline)); + if (!tmplog) + goto out; + last_isspace = 0; + break; + + case LOG_BECONN: // %bc + tmplog = ltoa_o(be->beconn, tmplog, MAX_SYSLOG_LEN - (tmplog - logline)); + if (!tmplog) + goto out; + last_isspace = 0; + break; + + case LOG_SRVCONN: // %sc + tmplog = ultoa_o(target_srv(&s->target) ? target_srv(&s->target)->cur_sess : 0, tmplog, MAX_SYSLOG_LEN - (tmplog - logline)); + if (!tmplog) + goto out; + last_isspace = 0; + break; + + case LOG_RETRIES: // %rq + if (s->flags & SN_REDISP) + *(tmplog++) = '+'; + tmplog = ltoa_o((s->req->cons->conn_retries>0)?(be->conn_retries - s->req->cons->conn_retries):be->conn_retries, tmplog, MAX_SYSLOG_LEN - (tmplog - logline)); + last_isspace = 0; + break; + + case LOG_SRVQUEUE: // %sq + tmplog = ltoa_o(s->logs.srv_queue_size, tmplog, MAX_SYSLOG_LEN - (tmplog - logline)); + if (!tmplog) + goto out; + last_isspace = 0; + break; + + case LOG_BCKQUEUE: // %bq + tmplog = ltoa_o(s->logs.prx_queue_size, tmplog, MAX_SYSLOG_LEN - (tmplog - logline)); + if (!tmplog) + goto out; + last_isspace = 0; + break; + + case LOG_HDRREQUEST: // %hr + /* request header */ + if (fe->to_log & LW_REQHDR && txn->req.cap) { + if (tmp->options & LOG_OPT_QUOTE) + LOGCHAR('"'); + LOGCHAR('{'); + for (hdr = 0; hdr < fe->nb_req_cap; hdr++) { + if (hdr) + LOGCHAR('|'); + if (txn->req.cap[hdr] != NULL) + tmplog = encode_string(tmplog, logline + MAX_SYSLOG_LEN, + '#', hdr_encode_map, txn->req.cap[hdr]); + } + LOGCHAR('}'); + last_isspace = 0; + } + *tmplog = '\0'; + break; + + case LOG_HDRREQUESTLIST: // %hrl + /* request header list */ + if (fe->to_log & LW_REQHDR && txn->req.cap) { + for (hdr = 0; hdr < fe->nb_req_cap; hdr++) { + if (hdr > 0) + LOGCHAR(' '); + if (tmp->options & LOG_OPT_QUOTE) + LOGCHAR('"'); + if (txn->req.cap[hdr] != NULL) { + tmplog = encode_string(tmplog, logline + MAX_SYSLOG_LEN, + '#', hdr_encode_map, txn->req.cap[hdr]); + } else if (!(tmp->options & LOG_OPT_QUOTE)) + LOGCHAR('-'); + if (tmp->options & LOG_OPT_QUOTE) + LOGCHAR('"'); + *tmplog = '\0'; + last_isspace = 0; + } + } + break; + case LOG_HDRRESPONS: // %hs + /* response header */ + if (fe->to_log & LW_RSPHDR && + txn->rsp.cap) { + if (tmp->options & LOG_OPT_QUOTE) + LOGCHAR('"'); + LOGCHAR('{'); + for (hdr = 0; hdr < fe->nb_rsp_cap; hdr++) { + if (hdr) + LOGCHAR('|'); + if (txn->rsp.cap[hdr] != NULL) + tmplog = encode_string(tmplog, logline + MAX_SYSLOG_LEN, + '#', hdr_encode_map, txn->rsp.cap[hdr]); + } + LOGCHAR('}'); + last_isspace = 0; + if (tmp->options & LOG_OPT_QUOTE) + LOGCHAR('"'); + } + *tmplog = '\0'; + break; + + case LOG_HDRRESPONSLIST: // %hsl + /* response header list */ + if (fe->to_log & LW_RSPHDR && txn->rsp.cap) { + for (hdr = 0; hdr < fe->nb_rsp_cap; hdr++) { + if (hdr > 0) + LOGCHAR(' '); + if (tmp->options & LOG_OPT_QUOTE) + LOGCHAR('"'); + if (txn->rsp.cap[hdr] != NULL) { + tmplog = encode_string(tmplog, logline + MAX_SYSLOG_LEN, + '#', hdr_encode_map, txn->rsp.cap[hdr]); + } else if (!(tmp->options & LOG_OPT_QUOTE)) + LOGCHAR('-'); + if (tmp->options & LOG_OPT_QUOTE) + LOGCHAR('"'); + *tmplog = '\0'; + last_isspace = 0; + } + } + break; + + case LOG_REQ: // %r + /* Request */ + if (tmp->options & LOG_OPT_QUOTE) + LOGCHAR('"'); + uri = txn->uri ? txn->uri : ""; + tmplog = encode_string(tmplog, logline + MAX_SYSLOG_LEN, + '#', url_encode_map, uri); + if (tmp->options & LOG_OPT_QUOTE) + LOGCHAR('"'); + *tmplog = '\0'; + last_isspace = 0; + break; + } + } + +out: + + if (tmplog == NULL) // if previous error + tmplog = logline + MAX_SYSLOG_LEN - 1; + + __send_log(prx_log, level, logline, tmplog - logline + 1); s->logs.logwait = 0; + } + + + /* * Local variables: * c-indent-level: 8 diff --git a/src/proto_http.c b/src/proto_http.c index c71b839550..b3a1f98008 100644 --- a/src/proto_http.c +++ b/src/proto_http.c @@ -844,408 +844,9 @@ void http_return_srv_error(struct session *s, struct stream_interface *si) extern const char sess_term_cond[8]; extern const char sess_fin_state[8]; extern const char *monthname[12]; -const char sess_cookie[8] = "NIDVEO67"; /* No cookie, Invalid cookie, cookie for a Down server, Valid cookie, Expired cookie, Old cookie, unknown */ -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 */ struct pool_head *pool2_requri; struct pool_head *pool2_capture; -#define LOGCHAR(x) do { \ - if (MAX_SYSLOG_LEN - (tmplog - logline) > 1) { \ - *(tmplog++) = (x); \ - } else { \ - goto out; \ - } \ - } while(0) - -/* - * send a log for the session when we have enough info about it. - * Will not log if the frontend has no log defined. - */ -void http_sess_log(struct session *s) -{ - char pn[INET6_ADDRSTRLEN]; - struct proxy *fe = s->fe; - struct proxy *be = s->be; - struct proxy *prx_log; - struct http_txn *txn = &s->txn; - int tolog, level, err; - char *uri; - const char *svid; - struct tm tm; - int t_request; - int hdr; - int last_isspace = 1; - static char logline[MAX_SYSLOG_LEN] = { 0 }; - static char *tmplog; - struct logformat_node *tmp; - - /* if we don't want to log normal traffic, return now */ - err = (s->flags & (SN_ERR_MASK | SN_REDISP)) || - (s->req->cons->conn_retries != be->conn_retries) || - txn->status >= 500; - if (!err && (fe->options2 & PR_O2_NOLOGNORM)) - return; - - if (LIST_ISEMPTY(&fe->logsrvs)) - return; - prx_log = fe; - - if (addr_to_str(&s->req->prod->addr.from, pn, sizeof(pn)) == AF_UNIX) - snprintf(pn, sizeof(pn), "unix:%d", s->listener->luid); - - /* FIXME: let's limit ourselves to frontend logging for now. */ - tolog = fe->to_log; - - if (!(tolog & LW_SVID)) - svid = "-"; - else switch (s->target.type) { - case TARG_TYPE_SERVER: - svid = s->target.ptr.s->id; - break; - case TARG_TYPE_APPLET: - svid = s->target.ptr.a->name; - break; - default: - svid = ""; - break; - } - - t_request = -1; - if (tv_isge(&s->logs.tv_request, &s->logs.tv_accept)) - t_request = tv_ms_elapsed(&s->logs.tv_accept, &s->logs.tv_request); - - level = LOG_INFO; - if (err && (fe->options2 & PR_O2_LOGERRORS)) - level = LOG_ERR; - - /* fill logbuffer */ - - tmplog = logline; - tmplog = hdr_log(tmplog); - - list_for_each_entry(tmp, &fe->logformat, list) { - char *src = NULL; - switch (tmp->type) { - - case LOG_SEPARATOR: - if (!last_isspace) { - LOGCHAR(' '); - last_isspace = 1; - *tmplog = '\0'; - } - break; - - case LOG_TEXT: // text - src = tmp->arg; - tmplog += strlcpy2(tmplog, src, MAX_SYSLOG_LEN - (tmplog - logline)); - if (!tmplog) - goto out; - last_isspace = 0; - break; - - case LOG_CLIENTIP: // %Ci - src = (s->req->prod->addr.from.ss_family == AF_UNIX) ? "unix" : pn; - tmplog = logformat_write_string(tmplog, src, MAX_SYSLOG_LEN - (tmplog - logline), tmp); - - if (!tmplog) - goto out; - last_isspace = 0; - break; - - case LOG_CLIENTPORT: // %Cp - tmplog = ltoa_o((s->req->prod->addr.from.ss_family == AF_UNIX) ? s->listener->luid : get_host_port(&s->req->prod->addr.from), - tmplog, MAX_SYSLOG_LEN - (tmplog - logline)); - if (!tmplog) - goto out; - last_isspace = 0; - break; - - case LOG_DATE: // %t - get_localtime(s->logs.accept_date.tv_sec, &tm); - tmplog = date2str_log(tmplog, &tm, &(s->logs.accept_date), MAX_SYSLOG_LEN - (tmplog - logline)); - if (!tmplog) - goto out; - last_isspace = 0; - break; - - case LOG_DATEGMT: // %T - get_gmtime(s->logs.accept_date.tv_sec, &tm); - tmplog = gmt2str_log(tmplog, &tm, MAX_SYSLOG_LEN - (tmplog - logline)); - if (!tmplog) - goto out; - last_isspace = 0; - break; - - case LOG_MS: // %ms - if ((MAX_SYSLOG_LEN - (tmplog - logline)) < 4) { - tmplog = NULL; - goto out; - } - tmplog = utoa_pad((unsigned int)s->logs.accept_date.tv_usec/1000, - tmplog, 4); - last_isspace = 0; - - break; - - case LOG_FRONTEND: // %f - src = fe->id; - tmplog = logformat_write_string(tmplog, src, MAX_SYSLOG_LEN - (tmplog - logline), tmp); - if (!tmplog) - goto out; - last_isspace = 0 ; - break; - - case LOG_BACKEND: // %b - src = be->id; - tmplog = logformat_write_string(tmplog, src, MAX_SYSLOG_LEN - (tmplog - logline), tmp); - if (!tmplog) - goto out; - last_isspace = 0 ; - break; - - case LOG_SERVER: // %s - src = (char *)svid; - tmplog = logformat_write_string(tmplog, src, MAX_SYSLOG_LEN - (tmplog - logline), tmp); - if (!tmplog) - goto out; - last_isspace = 0; - break; - - case LOG_TQ: // %Tq - tmplog = ltoa_o(t_request, tmplog, MAX_SYSLOG_LEN - (tmplog - logline)); - if (!tmplog) - goto out; - last_isspace = 0; - break; - - case LOG_TW: // %Tw - tmplog = ltoa_o((s->logs.t_queue >= 0) ? s->logs.t_queue - t_request : -1, tmplog, MAX_SYSLOG_LEN - (tmplog - logline)); - if (!tmplog) - goto out; - last_isspace = 0; - break; - - case LOG_TC: // %Tc - tmplog = ltoa_o((s->logs.t_connect >= 0) ? s->logs.t_connect - s->logs.t_queue : -1, tmplog, MAX_SYSLOG_LEN - (tmplog - logline)); - if (!tmplog) - goto out; - last_isspace = 0; - break; - - case LOG_TR: // %Tr - tmplog = ltoa_o((s->logs.t_data >= 0) ? s->logs.t_data - s->logs.t_connect : -1, tmplog, MAX_SYSLOG_LEN - (tmplog - logline)); - if (!tmplog) - goto out; - last_isspace = 0; - break; - - case LOG_TT: // %Tt - if (!(tolog & LW_BYTES)) - *(tmplog++) = '+'; - tmplog = ltoa_o(s->logs.t_close, tmplog, MAX_SYSLOG_LEN - (tmplog - logline)); - if (!tmplog) - goto out; - last_isspace = 0; - break; - - case LOG_STATUS: // %st - tmplog = ultoa_o(txn->status, tmplog, MAX_SYSLOG_LEN - (tmplog - logline)); - if (!tmplog) - goto out; - last_isspace = 0; - break; - - case LOG_BYTES: // %B - if (!(tolog & LW_BYTES)) - *(tmplog++) = '+'; - tmplog = lltoa(s->logs.bytes_out, tmplog, MAX_SYSLOG_LEN - (tmplog - logline)); - if (!tmplog) - goto out; - last_isspace = 0; - break; - - case LOG_CCLIENT: // %cc - src = txn->cli_cookie; - tmplog = logformat_write_string(tmplog, src, MAX_SYSLOG_LEN - (tmplog - logline), tmp); - last_isspace = 0; - break; - - case LOG_CSERVER: // %cs - src = txn->srv_cookie; - tmplog = logformat_write_string(tmplog, src, MAX_SYSLOG_LEN - (tmplog - logline), tmp); - last_isspace = 0; - break; - - case LOG_TERMSTATE: // %ts - if (MAX_SYSLOG_LEN - (tmplog - logline) < 5) - goto out; - *(tmplog++) = sess_term_cond[(s->flags & SN_ERR_MASK) >> SN_ERR_SHIFT]; - *(tmplog++) = sess_fin_state[(s->flags & SN_FINST_MASK) >> SN_FINST_SHIFT]; - *(tmplog++) = (be->options & PR_O_COOK_ANY) ? sess_cookie[(txn->flags & TX_CK_MASK) >> TX_CK_SHIFT] : '-'; - *(tmplog++) = (be->options & PR_O_COOK_ANY) ? sess_set_cookie[(txn->flags & TX_SCK_MASK) >> TX_SCK_SHIFT] : '-'; - *tmplog = '\0'; - last_isspace = 0; - break; - - case LOG_ACTCONN: // %ac - tmplog = ltoa_o(actconn, tmplog, MAX_SYSLOG_LEN - (tmplog - logline)); - if (!tmplog) - goto out; - last_isspace = 0; - break; - - case LOG_FECONN: // %fc - tmplog = ltoa_o(fe->feconn, tmplog, MAX_SYSLOG_LEN - (tmplog - logline)); - if (!tmplog) - goto out; - last_isspace = 0; - break; - - case LOG_BECONN: // %bc - tmplog = ltoa_o(be->beconn, tmplog, MAX_SYSLOG_LEN - (tmplog - logline)); - if (!tmplog) - goto out; - last_isspace = 0; - break; - - case LOG_SRVCONN: // %sc - tmplog = ultoa_o(target_srv(&s->target) ? target_srv(&s->target)->cur_sess : 0, tmplog, MAX_SYSLOG_LEN - (tmplog - logline)); - if (!tmplog) - goto out; - last_isspace = 0; - break; - - case LOG_RETRIES: // %rq - if (s->flags & SN_REDISP) - *(tmplog++) = '+'; - tmplog = ltoa_o((s->req->cons->conn_retries>0)?(be->conn_retries - s->req->cons->conn_retries):be->conn_retries, tmplog, MAX_SYSLOG_LEN - (tmplog - logline)); - last_isspace = 0; - break; - - case LOG_SRVQUEUE: // %sq - tmplog = ltoa_o(s->logs.srv_queue_size, tmplog, MAX_SYSLOG_LEN - (tmplog - logline)); - if (!tmplog) - goto out; - last_isspace = 0; - break; - - case LOG_BCKQUEUE: // %bq - tmplog = ltoa_o(s->logs.prx_queue_size, tmplog, MAX_SYSLOG_LEN - (tmplog - logline)); - if (!tmplog) - goto out; - last_isspace = 0; - break; - - case LOG_HDRREQUEST: // %hr - /* request header */ - if (fe->to_log & LW_REQHDR && txn->req.cap) { - if (tmp->options & LOG_OPT_QUOTE) - LOGCHAR('"'); - LOGCHAR('{'); - for (hdr = 0; hdr < fe->nb_req_cap; hdr++) { - if (hdr) - LOGCHAR('|'); - if (txn->req.cap[hdr] != NULL) - tmplog = encode_string(tmplog, logline + MAX_SYSLOG_LEN, - '#', hdr_encode_map, txn->req.cap[hdr]); - } - LOGCHAR('}'); - last_isspace = 0; - } - *tmplog = '\0'; - break; - - case LOG_HDRREQUESTLIST: // %hrl - /* request header list */ - if (fe->to_log & LW_REQHDR && txn->req.cap) { - for (hdr = 0; hdr < fe->nb_req_cap; hdr++) { - if (hdr > 0) - LOGCHAR(' '); - if (tmp->options & LOG_OPT_QUOTE) - LOGCHAR('"'); - if (txn->req.cap[hdr] != NULL) { - tmplog = encode_string(tmplog, logline + MAX_SYSLOG_LEN, - '#', hdr_encode_map, txn->req.cap[hdr]); - } else if (!(tmp->options & LOG_OPT_QUOTE)) - LOGCHAR('-'); - if (tmp->options & LOG_OPT_QUOTE) - LOGCHAR('"'); - *tmplog = '\0'; - last_isspace = 0; - } - } - break; - - case LOG_HDRRESPONS: // %hs - /* response header */ - if (fe->to_log & LW_RSPHDR && - txn->rsp.cap) { - if (tmp->options & LOG_OPT_QUOTE) - LOGCHAR('"'); - LOGCHAR('{'); - for (hdr = 0; hdr < fe->nb_rsp_cap; hdr++) { - if (hdr) - LOGCHAR('|'); - if (txn->rsp.cap[hdr] != NULL) - tmplog = encode_string(tmplog, logline + MAX_SYSLOG_LEN, - '#', hdr_encode_map, txn->rsp.cap[hdr]); - } - LOGCHAR('}'); - last_isspace = 0; - if (tmp->options & LOG_OPT_QUOTE) - LOGCHAR('"'); - } - *tmplog = '\0'; - break; - - case LOG_HDRRESPONSLIST: // %hsl - /* response header list */ - if (fe->to_log & LW_RSPHDR && txn->rsp.cap) { - for (hdr = 0; hdr < fe->nb_rsp_cap; hdr++) { - if (hdr > 0) - LOGCHAR(' '); - if (tmp->options & LOG_OPT_QUOTE) - LOGCHAR('"'); - if (txn->rsp.cap[hdr] != NULL) { - tmplog = encode_string(tmplog, logline + MAX_SYSLOG_LEN, - '#', hdr_encode_map, txn->rsp.cap[hdr]); - } else if (!(tmp->options & LOG_OPT_QUOTE)) - LOGCHAR('-'); - if (tmp->options & LOG_OPT_QUOTE) - LOGCHAR('"'); - *tmplog = '\0'; - last_isspace = 0; - } - } - break; - - case LOG_REQ: // %r - /* Request */ - if (tmp->options & LOG_OPT_QUOTE) - LOGCHAR('"'); - uri = txn->uri ? txn->uri : ""; - tmplog = encode_string(tmplog, logline + MAX_SYSLOG_LEN, - '#', url_encode_map, uri); - if (tmp->options & LOG_OPT_QUOTE) - LOGCHAR('"'); - *tmplog = '\0'; - last_isspace = 0; - break; - } - } - -out: - - if (tmplog == NULL) // if previous error - tmplog = logline + MAX_SYSLOG_LEN - 1; - - __send_log(prx_log, level, logline, tmplog - logline + 1); - s->logs.logwait = 0; - -} - /* * Capture headers from message starting at according to header list * , and fill the structure appropriately.