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