Willy Tarreau | baaee00 | 2006-06-26 02:48:02 +0200 | [diff] [blame] | 1 | /* |
| 2 | * General logging functions. |
| 3 | * |
| 4 | * Copyright 2000-2006 Willy Tarreau <w@1wt.eu> |
| 5 | * |
| 6 | * This program is free software; you can redistribute it and/or |
| 7 | * modify it under the terms of the GNU General Public License |
| 8 | * as published by the Free Software Foundation; either version |
| 9 | * 2 of the License, or (at your option) any later version. |
| 10 | * |
| 11 | */ |
| 12 | |
| 13 | #include <stdarg.h> |
| 14 | #include <stdio.h> |
| 15 | #include <stdlib.h> |
| 16 | #include <string.h> |
| 17 | #include <syslog.h> |
| 18 | #include <time.h> |
| 19 | #include <unistd.h> |
| 20 | |
| 21 | #include <sys/time.h> |
| 22 | |
Willy Tarreau | e3ba5f0 | 2006-06-29 18:54:54 +0200 | [diff] [blame] | 23 | #include <common/config.h> |
Willy Tarreau | 2dd0d47 | 2006-06-29 17:53:05 +0200 | [diff] [blame] | 24 | #include <common/standard.h> |
Willy Tarreau | baaee00 | 2006-06-26 02:48:02 +0200 | [diff] [blame] | 25 | |
| 26 | #include <types/backend.h> |
| 27 | #include <types/global.h> |
| 28 | #include <types/httperr.h> |
| 29 | #include <types/log.h> |
| 30 | #include <types/proxy.h> |
| 31 | #include <types/session.h> |
| 32 | |
| 33 | |
| 34 | const char *log_facilities[NB_LOG_FACILITIES] = { |
| 35 | "kern", "user", "mail", "daemon", |
| 36 | "auth", "syslog", "lpr", "news", |
| 37 | "uucp", "cron", "auth2", "ftp", |
| 38 | "ntp", "audit", "alert", "cron2", |
| 39 | "local0", "local1", "local2", "local3", |
| 40 | "local4", "local5", "local6", "local7" |
| 41 | }; |
| 42 | |
| 43 | |
| 44 | const char *log_levels[NB_LOG_LEVELS] = { |
| 45 | "emerg", "alert", "crit", "err", |
| 46 | "warning", "notice", "info", "debug" |
| 47 | }; |
| 48 | |
| 49 | const char *monthname[12] = { |
| 50 | "Jan", "Feb", "Mar", "Apr", "May", "Jun", |
| 51 | "Jul", "Aug", "Sep", "Oct", "Nov", "Dec" |
| 52 | }; |
| 53 | |
| 54 | const char sess_term_cond[8] = "-cCsSPRI"; /* normal, CliTo, CliErr, SrvTo, SrvErr, PxErr, Resource, Internal */ |
Willy Tarreau | b8750a8 | 2006-09-03 09:56:00 +0200 | [diff] [blame] | 55 | const char sess_fin_state[8] = "-RCHDLQT"; /* cliRequest, srvConnect, srvHeader, Data, Last, Queue, Tarpit */ |
Willy Tarreau | baaee00 | 2006-06-26 02:48:02 +0200 | [diff] [blame] | 56 | const char sess_cookie[4] = "NIDV"; /* No cookie, Invalid cookie, cookie for a Down server, Valid cookie */ |
| 57 | const char sess_set_cookie[8] = "N1I3PD5R"; /* No set-cookie, unknown, Set-Cookie Inserted, unknown, |
| 58 | Set-cookie seen and left unchanged (passive), Set-cookie Deleted, |
| 59 | unknown, Set-cookie Rewritten */ |
| 60 | void **pool_requri = NULL; |
| 61 | |
| 62 | |
| 63 | /* |
| 64 | * Displays the message on stderr with the date and pid. Overrides the quiet |
| 65 | * mode during startup. |
| 66 | */ |
Willy Tarreau | b17916e | 2006-10-15 15:17:57 +0200 | [diff] [blame^] | 67 | void Alert(const char *fmt, ...) |
Willy Tarreau | baaee00 | 2006-06-26 02:48:02 +0200 | [diff] [blame] | 68 | { |
| 69 | va_list argp; |
| 70 | struct timeval tv; |
| 71 | struct tm *tm; |
| 72 | |
| 73 | if (!(global.mode & MODE_QUIET) || (global.mode & (MODE_VERBOSE | MODE_STARTING))) { |
| 74 | va_start(argp, fmt); |
| 75 | |
| 76 | gettimeofday(&tv, NULL); |
| 77 | tm = localtime(&tv.tv_sec); |
| 78 | fprintf(stderr, "[ALERT] %03d/%02d%02d%02d (%d) : ", |
| 79 | tm->tm_yday, tm->tm_hour, tm->tm_min, tm->tm_sec, (int)getpid()); |
| 80 | vfprintf(stderr, fmt, argp); |
| 81 | fflush(stderr); |
| 82 | va_end(argp); |
| 83 | } |
| 84 | } |
| 85 | |
| 86 | |
| 87 | /* |
| 88 | * Displays the message on stderr with the date and pid. |
| 89 | */ |
Willy Tarreau | b17916e | 2006-10-15 15:17:57 +0200 | [diff] [blame^] | 90 | void Warning(const char *fmt, ...) |
Willy Tarreau | baaee00 | 2006-06-26 02:48:02 +0200 | [diff] [blame] | 91 | { |
| 92 | va_list argp; |
| 93 | struct timeval tv; |
| 94 | struct tm *tm; |
| 95 | |
| 96 | if (!(global.mode & MODE_QUIET) || (global.mode & MODE_VERBOSE)) { |
| 97 | va_start(argp, fmt); |
| 98 | |
| 99 | gettimeofday(&tv, NULL); |
| 100 | tm = localtime(&tv.tv_sec); |
| 101 | fprintf(stderr, "[WARNING] %03d/%02d%02d%02d (%d) : ", |
| 102 | tm->tm_yday, tm->tm_hour, tm->tm_min, tm->tm_sec, (int)getpid()); |
| 103 | vfprintf(stderr, fmt, argp); |
| 104 | fflush(stderr); |
| 105 | va_end(argp); |
| 106 | } |
| 107 | } |
| 108 | |
| 109 | /* |
| 110 | * Displays the message on <out> only if quiet mode is not set. |
| 111 | */ |
Willy Tarreau | b17916e | 2006-10-15 15:17:57 +0200 | [diff] [blame^] | 112 | void qfprintf(FILE *out, const char *fmt, ...) |
Willy Tarreau | baaee00 | 2006-06-26 02:48:02 +0200 | [diff] [blame] | 113 | { |
| 114 | va_list argp; |
| 115 | |
| 116 | if (!(global.mode & MODE_QUIET) || (global.mode & MODE_VERBOSE)) { |
| 117 | va_start(argp, fmt); |
| 118 | vfprintf(out, fmt, argp); |
| 119 | fflush(out); |
| 120 | va_end(argp); |
| 121 | } |
| 122 | } |
| 123 | |
| 124 | /* |
| 125 | * returns log level for <lev> or -1 if not found. |
| 126 | */ |
| 127 | int get_log_level(const char *lev) |
| 128 | { |
| 129 | int level; |
| 130 | |
| 131 | level = NB_LOG_LEVELS - 1; |
| 132 | while (level >= 0 && strcmp(log_levels[level], lev)) |
| 133 | level--; |
| 134 | |
| 135 | return level; |
| 136 | } |
| 137 | |
| 138 | |
| 139 | /* |
| 140 | * returns log facility for <fac> or -1 if not found. |
| 141 | */ |
| 142 | int get_log_facility(const char *fac) |
| 143 | { |
| 144 | int facility; |
| 145 | |
| 146 | facility = NB_LOG_FACILITIES - 1; |
| 147 | while (facility >= 0 && strcmp(log_facilities[facility], fac)) |
| 148 | facility--; |
| 149 | |
| 150 | return facility; |
| 151 | } |
| 152 | |
| 153 | |
| 154 | #define FD_SETS_ARE_BITFIELDS |
| 155 | #ifdef FD_SETS_ARE_BITFIELDS |
| 156 | /* |
| 157 | * This map is used with all the FD_* macros to check whether a particular bit |
| 158 | * is set or not. Each bit represents an ACSII code. FD_SET() sets those bytes |
| 159 | * which should be encoded. When FD_ISSET() returns non-zero, it means that the |
| 160 | * byte should be encoded. Be careful to always pass bytes from 0 to 255 |
| 161 | * exclusively to the macros. |
| 162 | */ |
| 163 | fd_set hdr_encode_map[(sizeof(fd_set) > (256/8)) ? 1 : ((256/8) / sizeof(fd_set))]; |
| 164 | fd_set url_encode_map[(sizeof(fd_set) > (256/8)) ? 1 : ((256/8) / sizeof(fd_set))]; |
| 165 | |
| 166 | #else |
| 167 | #error "Check if your OS uses bitfields for fd_sets" |
| 168 | #endif |
| 169 | |
| 170 | /* |
| 171 | * This function sends a syslog message to both log servers of a proxy, |
| 172 | * or to global log servers if the proxy is NULL. |
| 173 | * It also tries not to waste too much time computing the message header. |
| 174 | * It doesn't care about errors nor does it report them. |
| 175 | */ |
Willy Tarreau | b17916e | 2006-10-15 15:17:57 +0200 | [diff] [blame^] | 176 | void send_log(struct proxy *p, int level, const char *message, ...) |
Willy Tarreau | baaee00 | 2006-06-26 02:48:02 +0200 | [diff] [blame] | 177 | { |
| 178 | static int logfd = -1; /* syslog UDP socket */ |
| 179 | static long tvsec = -1; /* to force the string to be initialized */ |
| 180 | struct timeval tv; |
| 181 | va_list argp; |
| 182 | static char logmsg[MAX_SYSLOG_LEN]; |
| 183 | static char *dataptr = NULL; |
| 184 | int fac_level; |
| 185 | int hdr_len, data_len; |
| 186 | struct sockaddr_in *sa[2]; |
| 187 | int facilities[2], loglevel[2]; |
| 188 | int nbloggers = 0; |
| 189 | char *log_ptr; |
| 190 | |
| 191 | if (logfd < 0) { |
| 192 | if ((logfd = socket(AF_INET, SOCK_DGRAM, IPPROTO_UDP)) < 0) |
| 193 | return; |
| 194 | } |
| 195 | |
| 196 | if (level < 0 || progname == NULL || message == NULL) |
| 197 | return; |
| 198 | |
| 199 | gettimeofday(&tv, NULL); |
| 200 | if (tv.tv_sec != tvsec || dataptr == NULL) { |
| 201 | /* this string is rebuild only once a second */ |
| 202 | struct tm *tm = localtime(&tv.tv_sec); |
| 203 | tvsec = tv.tv_sec; |
| 204 | |
| 205 | hdr_len = snprintf(logmsg, sizeof(logmsg), |
| 206 | "<<<<>%s %2d %02d:%02d:%02d %s[%d]: ", |
| 207 | monthname[tm->tm_mon], |
| 208 | tm->tm_mday, tm->tm_hour, tm->tm_min, tm->tm_sec, |
| 209 | progname, pid); |
| 210 | /* WARNING: depending upon implementations, snprintf may return |
| 211 | * either -1 or the number of bytes that would be needed to store |
| 212 | * the total message. In both cases, we must adjust it. |
| 213 | */ |
| 214 | if (hdr_len < 0 || hdr_len > sizeof(logmsg)) |
| 215 | hdr_len = sizeof(logmsg); |
| 216 | |
| 217 | dataptr = logmsg + hdr_len; |
| 218 | } |
| 219 | |
| 220 | va_start(argp, message); |
| 221 | data_len = vsnprintf(dataptr, logmsg + sizeof(logmsg) - dataptr, message, argp); |
| 222 | if (data_len < 0 || data_len > (logmsg + sizeof(logmsg) - dataptr)) |
| 223 | data_len = logmsg + sizeof(logmsg) - dataptr; |
| 224 | va_end(argp); |
| 225 | dataptr[data_len - 1] = '\n'; /* force a break on ultra-long lines */ |
| 226 | |
| 227 | if (p == NULL) { |
| 228 | if (global.logfac1 >= 0) { |
| 229 | sa[nbloggers] = &global.logsrv1; |
| 230 | facilities[nbloggers] = global.logfac1; |
| 231 | loglevel[nbloggers] = global.loglev1; |
| 232 | nbloggers++; |
| 233 | } |
| 234 | if (global.logfac2 >= 0) { |
| 235 | sa[nbloggers] = &global.logsrv2; |
| 236 | facilities[nbloggers] = global.logfac2; |
| 237 | loglevel[nbloggers] = global.loglev2; |
| 238 | nbloggers++; |
| 239 | } |
| 240 | } else { |
| 241 | if (p->logfac1 >= 0) { |
| 242 | sa[nbloggers] = &p->logsrv1; |
| 243 | facilities[nbloggers] = p->logfac1; |
| 244 | loglevel[nbloggers] = p->loglev1; |
| 245 | nbloggers++; |
| 246 | } |
| 247 | if (p->logfac2 >= 0) { |
| 248 | sa[nbloggers] = &p->logsrv2; |
| 249 | facilities[nbloggers] = p->logfac2; |
| 250 | loglevel[nbloggers] = p->loglev2; |
| 251 | nbloggers++; |
| 252 | } |
| 253 | } |
| 254 | |
| 255 | while (nbloggers-- > 0) { |
| 256 | /* we can filter the level of the messages that are sent to each logger */ |
| 257 | if (level > loglevel[nbloggers]) |
| 258 | continue; |
| 259 | |
| 260 | /* For each target, we may have a different facility. |
| 261 | * We can also have a different log level for each message. |
| 262 | * This induces variations in the message header length. |
| 263 | * Since we don't want to recompute it each time, nor copy it every |
| 264 | * time, we only change the facility in the pre-computed header, |
| 265 | * and we change the pointer to the header accordingly. |
| 266 | */ |
| 267 | fac_level = (facilities[nbloggers] << 3) + level; |
| 268 | log_ptr = logmsg + 3; /* last digit of the log level */ |
| 269 | do { |
| 270 | *log_ptr = '0' + fac_level % 10; |
| 271 | fac_level /= 10; |
| 272 | log_ptr--; |
| 273 | } while (fac_level && log_ptr > logmsg); |
| 274 | *log_ptr = '<'; |
| 275 | |
| 276 | /* the total syslog message now starts at logptr, for dataptr+data_len-logptr */ |
| 277 | |
| 278 | #ifndef MSG_NOSIGNAL |
| 279 | sendto(logfd, log_ptr, dataptr + data_len - log_ptr, MSG_DONTWAIT, |
| 280 | (struct sockaddr *)sa[nbloggers], sizeof(**sa)); |
| 281 | #else |
| 282 | sendto(logfd, log_ptr, dataptr + data_len - log_ptr, MSG_DONTWAIT | MSG_NOSIGNAL, |
| 283 | (struct sockaddr *)sa[nbloggers], sizeof(**sa)); |
| 284 | #endif |
| 285 | } |
| 286 | } |
| 287 | |
| 288 | |
| 289 | /* |
| 290 | * send a log for the session when we have enough info about it |
| 291 | */ |
| 292 | void sess_log(struct session *s) |
| 293 | { |
| 294 | char pn[INET6_ADDRSTRLEN + strlen(":65535")]; |
| 295 | struct proxy *p = s->proxy; |
| 296 | int log; |
| 297 | char *uri; |
| 298 | char *pxid; |
| 299 | char *srv; |
| 300 | struct tm *tm; |
| 301 | |
| 302 | /* This is a first attempt at a better logging system. |
| 303 | * For now, we rely on send_log() to provide the date, although it obviously |
| 304 | * is the date of the log and not of the request, and most fields are not |
| 305 | * computed. |
| 306 | */ |
| 307 | |
| 308 | log = p->to_log & ~s->logs.logwait; |
| 309 | |
| 310 | if (s->cli_addr.ss_family == AF_INET) |
| 311 | inet_ntop(AF_INET, |
| 312 | (const void *)&((struct sockaddr_in *)&s->cli_addr)->sin_addr, |
| 313 | pn, sizeof(pn)); |
| 314 | else |
| 315 | inet_ntop(AF_INET6, |
| 316 | (const void *)&((struct sockaddr_in6 *)(&s->cli_addr))->sin6_addr, |
| 317 | pn, sizeof(pn)); |
| 318 | |
| 319 | uri = (log & LW_REQ) ? s->logs.uri ? s->logs.uri : "<BADREQ>" : ""; |
| 320 | pxid = p->id; |
| 321 | srv = (p->to_log & LW_SVID) ? |
| 322 | (s->data_source != DATA_SRC_STATS) ? |
| 323 | (s->srv != NULL) ? s->srv->id : "<NOSRV>" : "<STATS>" : "-"; |
| 324 | |
| 325 | tm = localtime(&s->logs.tv_accept.tv_sec); |
| 326 | if (p->to_log & LW_REQ) { |
| 327 | char tmpline[MAX_SYSLOG_LEN], *h; |
| 328 | int hdr; |
| 329 | |
| 330 | h = tmpline; |
| 331 | if (p->to_log & LW_REQHDR && (h < tmpline + sizeof(tmpline) - 10)) { |
| 332 | *(h++) = ' '; |
| 333 | *(h++) = '{'; |
| 334 | for (hdr = 0; hdr < p->nb_req_cap; hdr++) { |
| 335 | if (hdr) |
| 336 | *(h++) = '|'; |
| 337 | if (s->req_cap[hdr] != NULL) |
| 338 | h = encode_string(h, tmpline + sizeof(tmpline) - 7, |
| 339 | '#', hdr_encode_map, s->req_cap[hdr]); |
| 340 | } |
| 341 | *(h++) = '}'; |
| 342 | } |
| 343 | |
| 344 | if (p->to_log & LW_RSPHDR && (h < tmpline + sizeof(tmpline) - 7)) { |
| 345 | *(h++) = ' '; |
| 346 | *(h++) = '{'; |
| 347 | for (hdr = 0; hdr < p->nb_rsp_cap; hdr++) { |
| 348 | if (hdr) |
| 349 | *(h++) = '|'; |
| 350 | if (s->rsp_cap[hdr] != NULL) |
| 351 | h = encode_string(h, tmpline + sizeof(tmpline) - 4, |
| 352 | '#', hdr_encode_map, s->rsp_cap[hdr]); |
| 353 | } |
| 354 | *(h++) = '}'; |
| 355 | } |
| 356 | |
| 357 | if (h < tmpline + sizeof(tmpline) - 4) { |
| 358 | *(h++) = ' '; |
| 359 | *(h++) = '"'; |
| 360 | h = encode_string(h, tmpline + sizeof(tmpline) - 1, |
| 361 | '#', url_encode_map, uri); |
| 362 | *(h++) = '"'; |
| 363 | } |
| 364 | *h = '\0'; |
| 365 | |
| 366 | send_log(p, LOG_INFO, |
| 367 | "%s:%d [%02d/%s/%04d:%02d:%02d:%02d]" |
| 368 | " %s %s %d/%d/%d/%d/%s%d %d %s%lld" |
| 369 | " %s %s %c%c%c%c %d/%d/%d %d/%d%s\n", |
| 370 | pn, |
| 371 | (s->cli_addr.ss_family == AF_INET) ? |
| 372 | ntohs(((struct sockaddr_in *)&s->cli_addr)->sin_port) : |
| 373 | ntohs(((struct sockaddr_in6 *)&s->cli_addr)->sin6_port), |
| 374 | tm->tm_mday, monthname[tm->tm_mon], tm->tm_year+1900, |
| 375 | tm->tm_hour, tm->tm_min, tm->tm_sec, |
| 376 | pxid, srv, |
| 377 | s->logs.t_request, |
| 378 | (s->logs.t_queue >= 0) ? s->logs.t_queue - s->logs.t_request : -1, |
| 379 | (s->logs.t_connect >= 0) ? s->logs.t_connect - s->logs.t_queue : -1, |
| 380 | (s->logs.t_data >= 0) ? s->logs.t_data - s->logs.t_connect : -1, |
| 381 | (p->to_log & LW_BYTES) ? "" : "+", s->logs.t_close, |
| 382 | s->logs.status, |
| 383 | (p->to_log & LW_BYTES) ? "" : "+", s->logs.bytes, |
| 384 | s->logs.cli_cookie ? s->logs.cli_cookie : "-", |
| 385 | s->logs.srv_cookie ? s->logs.srv_cookie : "-", |
| 386 | sess_term_cond[(s->flags & SN_ERR_MASK) >> SN_ERR_SHIFT], |
| 387 | sess_fin_state[(s->flags & SN_FINST_MASK) >> SN_FINST_SHIFT], |
| 388 | (p->options & PR_O_COOK_ANY) ? sess_cookie[(s->flags & SN_CK_MASK) >> SN_CK_SHIFT] : '-', |
| 389 | (p->options & PR_O_COOK_ANY) ? sess_set_cookie[(s->flags & SN_SCK_MASK) >> SN_SCK_SHIFT] : '-', |
| 390 | s->srv ? s->srv->cur_sess : 0, p->nbconn, actconn, |
| 391 | s->logs.srv_queue_size, s->logs.prx_queue_size, tmpline); |
| 392 | } |
| 393 | else { |
| 394 | send_log(p, LOG_INFO, "%s:%d [%02d/%s/%04d:%02d:%02d:%02d]" |
| 395 | " %s %s %d/%d/%s%d %s%lld" |
| 396 | " %c%c %d/%d/%d %d/%d\n", |
| 397 | pn, |
| 398 | (s->cli_addr.ss_family == AF_INET) ? |
| 399 | ntohs(((struct sockaddr_in *)&s->cli_addr)->sin_port) : |
| 400 | ntohs(((struct sockaddr_in6 *)&s->cli_addr)->sin6_port), |
| 401 | tm->tm_mday, monthname[tm->tm_mon], tm->tm_year+1900, |
| 402 | tm->tm_hour, tm->tm_min, tm->tm_sec, |
| 403 | pxid, srv, |
| 404 | (s->logs.t_queue >= 0) ? s->logs.t_queue : -1, |
| 405 | (s->logs.t_connect >= 0) ? s->logs.t_connect - s->logs.t_queue : -1, |
| 406 | (p->to_log & LW_BYTES) ? "" : "+", s->logs.t_close, |
| 407 | (p->to_log & LW_BYTES) ? "" : "+", s->logs.bytes, |
| 408 | sess_term_cond[(s->flags & SN_ERR_MASK) >> SN_ERR_SHIFT], |
| 409 | sess_fin_state[(s->flags & SN_FINST_MASK) >> SN_FINST_SHIFT], |
| 410 | s->srv ? s->srv->cur_sess : 0, p->nbconn, actconn, |
| 411 | s->logs.srv_queue_size, s->logs.prx_queue_size); |
| 412 | } |
| 413 | |
| 414 | s->logs.logwait = 0; |
| 415 | } |
| 416 | |
| 417 | |
| 418 | /* |
| 419 | * Initializes some data needed later. |
| 420 | */ |
| 421 | void init_log() |
| 422 | { |
| 423 | int i; |
| 424 | char *tmp; |
| 425 | |
| 426 | /* initialize the log header encoding map : '{|}"#' should be encoded with |
| 427 | * '#' as prefix, as well as non-printable characters ( <32 or >= 127 ). |
| 428 | * URL encoding only requires '"', '#' to be encoded as well as non- |
| 429 | * printable characters above. |
| 430 | */ |
| 431 | memset(hdr_encode_map, 0, sizeof(hdr_encode_map)); |
| 432 | memset(url_encode_map, 0, sizeof(url_encode_map)); |
| 433 | for (i = 0; i < 32; i++) { |
| 434 | FD_SET(i, hdr_encode_map); |
| 435 | FD_SET(i, url_encode_map); |
| 436 | } |
| 437 | for (i = 127; i < 256; i++) { |
| 438 | FD_SET(i, hdr_encode_map); |
| 439 | FD_SET(i, url_encode_map); |
| 440 | } |
| 441 | |
| 442 | tmp = "\"#{|}"; |
| 443 | while (*tmp) { |
| 444 | FD_SET(*tmp, hdr_encode_map); |
| 445 | tmp++; |
| 446 | } |
| 447 | |
| 448 | tmp = "\"#"; |
| 449 | while (*tmp) { |
| 450 | FD_SET(*tmp, url_encode_map); |
| 451 | tmp++; |
| 452 | } |
| 453 | } |
| 454 | |
| 455 | /* |
| 456 | * Local variables: |
| 457 | * c-indent-level: 8 |
| 458 | * c-basic-offset: 8 |
| 459 | * End: |
| 460 | */ |