src/access_log.cc

   1
   2 /*
   3  * $Id: access_log.cc,v 1.66 2001/01/12 00:37:14 wessels Exp $
   4  *
   5  * DEBUG: section 46    Access Log
   6  * AUTHOR: Duane Wessels
   7  *
   8  * SQUID Web Proxy Cache          http://www.squid-cache.org/
   9  * ----------------------------------------------------------
  10  *
  11  *  Squid is the result of efforts by numerous individuals from
  12  *  the Internet community; see the CONTRIBUTORS file for full
  13  *  details.   Many organizations have provided support for Squid's
  14  *  development; see the SPONSORS file for full details.  Squid is
  15  *  Copyrighted (C) 2001 by the Regents of the University of
  16  *  California; see the COPYRIGHT file for full details.  Squid
  17  *  incorporates software developed and/or copyrighted by other
  18  *  sources; see the CREDITS file for full details.
  19  *
  20  *  This program is free software; you can redistribute it and/or modify
  21  *  it under the terms of the GNU General Public License as published by
  22  *  the Free Software Foundation; either version 2 of the License, or
  23  *  (at your option) any later version.
  24  *
  25  *  This program is distributed in the hope that it will be useful,
  26  *  but WITHOUT ANY WARRANTY; without even the implied warranty of
  27  *  MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
  28  *  GNU General Public License for more details.
  29  *
  30  *  You should have received a copy of the GNU General Public License
  31  *  along with this program; if not, write to the Free Software
  32  *  Foundation, Inc., 59 Temple Place, Suite 330, Boston, MA 02111, USA.
  33  *
  34  */
  35
  36
  37 #include "squid.h"
  38
  39 static void accessLogSquid(AccessLogEntry * al);
  40 static void accessLogCommon(AccessLogEntry * al);
  41 static Logfile *logfile = NULL;
  42 #if HEADERS_LOG
  43 static Logfile *headerslog = NULL;
  44 #endif
  45
  46 #if MULTICAST_MISS_STREAM
  47 static int mcast_miss_fd = -1;
  48 static struct sockaddr_in mcast_miss_to;
  49 static void mcast_encode(unsigned int *, size_t, const unsigned int *);
  50 #endif
  51
  52 const char *log_tags[] =
  53 {
  54     "NONE",
  55     "TCP_HIT",
  56     "TCP_MISS",
  57     "TCP_REFRESH_HIT",
  58     "TCP_REF_FAIL_HIT",
  59     "TCP_REFRESH_MISS",
  60     "TCP_CLIENT_REFRESH_MISS",
  61     "TCP_IMS_HIT",
  62     "TCP_SWAPFAIL_MISS",
  63     "TCP_NEGATIVE_HIT",
  64     "TCP_MEM_HIT",
  65     "TCP_DENIED",
  66     "TCP_OFFLINE_HIT",
  67 #if LOG_TCP_REDIRECTS
  68     "TCP_REDIRECT",
  69 #endif
  70     "UDP_HIT",
  71     "UDP_MISS",
  72     "UDP_DENIED",
  73     "UDP_INVALID",
  74     "UDP_MISS_NOFETCH",
  75     "ICP_QUERY",
  76     "LOG_TYPE_MAX"
  77 };
  78
  79 #if FORW_VIA_DB
  80 typedef struct {
  81     hash_link hash;
  82     int n;
  83 } fvdb_entry;
  84 static hash_table *via_table = NULL;
  85 static hash_table *forw_table = NULL;
  86 static void fvdbInit(void);
  87 static void fvdbDumpTable(StoreEntry * e, hash_table * hash);
  88 static void fvdbCount(hash_table * hash, const char *key);
  89 static OBJH fvdbDumpVia;
  90 static OBJH fvdbDumpForw;
  91 static FREE fvdbFreeEntry;
  92 static void fvdbClear(void);
  93 #endif
  94
  95 static int LogfileStatus = LOG_DISABLE;
  96 #define LOG_BUF_SZ (MAX_URL<<2)
  97
  98 static const char c2x[] =
  99 "000102030405060708090a0b0c0d0e0f"
 100 "101112131415161718191a1b1c1d1e1f"
 101 "202122232425262728292a2b2c2d2e2f"
 102 "303132333435363738393a3b3c3d3e3f"
 103 "404142434445464748494a4b4c4d4e4f"
 104 "505152535455565758595a5b5c5d5e5f"
 105 "606162636465666768696a6b6c6d6e6f"
 106 "707172737475767778797a7b7c7d7e7f"
 107 "808182838485868788898a8b8c8d8e8f"
 108 "909192939495969798999a9b9c9d9e9f"
 109 "a0a1a2a3a4a5a6a7a8a9aaabacadaeaf"
 110 "b0b1b2b3b4b5b6b7b8b9babbbcbdbebf"
 111 "c0c1c2c3c4c5c6c7c8c9cacbcccdcecf"
 112 "d0d1d2d3d4d5d6d7d8d9dadbdcdddedf"
 113 "e0e1e2e3e4e5e6e7e8e9eaebecedeeef"
 114 "f0f1f2f3f4f5f6f7f8f9fafbfcfdfeff";
 115
 116 /* log_quote -- URL-style encoding on MIME headers. */
 117
 118 char *
 119 log_quote(const char *header)
 120 {
 121     int c;
 122     int i;
 123     char *buf;
 124     char *buf_cursor;
 125     if (header == NULL) {
 126         buf = xcalloc(1, 1);
 127         *buf = '\0';
 128         return buf;
 129     }
 130     buf = xcalloc((strlen(header) * 3) + 1, 1);
 131     buf_cursor = buf;
 132     /*
 133      * We escape: \x00-\x1F"#%;<>?{}|\\\\^~`\[\]\x7F-\xFF
 134      * which is the default escape list for the CPAN Perl5 URI module
 135      * modulo the inclusion of space (x40) to make the raw logs a bit
 136      * more readable.
 137      */
 138     while ((c = *(const unsigned char *) header++) != '\0') {
 139 #if !OLD_LOG_MIME
 140         if (c == '\r') {
 141             *buf_cursor++ = '\\';
 142             *buf_cursor++ = 'r';
 143         } else if (c == '\n') {
 144             *buf_cursor++ = '\\';
 145             *buf_cursor++ = 'n';
 146         } else
 147 #endif
 148             if (c <= 0x1F
 149                 || c >= 0x7F
 150 #if OLD_LOG_MIME
 151                 || c == '"'
 152                 || c == '#'
 153                 || c == '%'
 154                 || c == ';'
 155                 || c == '<'
 156                 || c == '>'
 157                 || c == '?'
 158                 || c == '{'
 159                 || c == '}'
 160                 || c == '|'
 161                 || c == '\\'
 162                 || c == '^'
 163                 || c == '~'
 164                 || c == '`'
 165 #endif
 166                 || c == '['
 167             || c == ']') {
 168             *buf_cursor++ = '%';
 169             i = c * 2;
 170             *buf_cursor++ = c2x[i];
 171             *buf_cursor++ = c2x[i + 1];
 172 #if !OLD_LOG_MIME
 173         } else if (c == '\\') {
 174             *buf_cursor++ = '\\';
 175             *buf_cursor++ = '\\';
 176 #endif
 177         } else {
 178             *buf_cursor++ = (char) c;
 179         }
 180     }
 181     *buf_cursor = '\0';
 182     return buf;
 183 }
 184
 185 char *
 186 username_quote(const char *header)
 187 /* copy of log_quote. Bugs there will be found here */
 188 {
 189     int c;
 190     int i;
 191     char *buf;
 192     char *buf_cursor;
 193     if (header == NULL) {
 194         buf = xcalloc(1, 1);
 195         *buf = '\0';
 196         return buf;
 197     }
 198     buf = xcalloc((strlen(header) * 3) + 1, 1);
 199     buf_cursor = buf;
 200     /*
 201      * We escape: space \x00-\x1F and space (0x40) and \x7F-\xFF
 202      * to prevent garbage in the logs. CR and LF are also there just in case.
 203      */
 204     while ((c = *(const unsigned char *) header++) != '\0') {
 205         if (c == '\r') {
 206             *buf_cursor++ = '\\';
 207             *buf_cursor++ = 'r';
 208         } else if (c == '\n') {
 209             *buf_cursor++ = '\\';
 210             *buf_cursor++ = 'n';
 211         } else if (c <= 0x1F
 212                 || c >= 0x7F
 213             || c == ' ') {
 214             *buf_cursor++ = '%';
 215             i = c * 2;
 216             *buf_cursor++ = c2x[i];
 217             *buf_cursor++ = c2x[i + 1];
 218         } else {
 219             *buf_cursor++ = (char) c;
 220         }
 221     }
 222     *buf_cursor = '\0';
 223     return buf;
 224 }
 225
 226 char *
 227 accessLogFormatName(const char *name)
 228 {
 229     if (NULL == name)
 230         return xcalloc(strlen(dash_str) + 1, 1);
 231     return username_quote(name);
 232 }
 233
 234 static void
 235 accessLogSquid(AccessLogEntry * al)
 236 {
 237     const char *client = NULL;
 238     char *user = NULL;
 239     if (Config.onoff.log_fqdn)
 240         client = fqdncache_gethostbyaddr(al->cache.caddr, FQDN_LOOKUP_IF_MISS);
 241     if (client == NULL)
 242         client = inet_ntoa(al->cache.caddr);
 243     logfilePrintf(logfile, "%9d.%03d %6d %s %s/%03d %d %s %s %s %s%s/%s %s",
 244         (int) current_time.tv_sec,
 245         (int) current_time.tv_usec / 1000,
 246         al->cache.msec,
 247         client,
 248         log_tags[al->cache.code],
 249         al->http.code,
 250         al->cache.size,
 251         al->private.method_str,
 252         al->url,
 253         (user = accessLogFormatName(al->cache.authuser ?
 254                 al->cache.authuser : al->cache.rfc931)),
 255         al->hier.ping.timedout ? "TIMEOUT_" : "",
 256         hier_strings[al->hier.code],
 257         al->hier.host,
 258         al->http.content_type);
 259     safe_free(user);
 260 }
 261
 262 static void
 263 accessLogCommon(AccessLogEntry * al)
 264 {
 265     const char *client = NULL;
 266     char *user = NULL;
 267     if (Config.onoff.log_fqdn)
 268         client = fqdncache_gethostbyaddr(al->cache.caddr, 0);
 269     if (client == NULL)
 270         client = inet_ntoa(al->cache.caddr);
 271     logfilePrintf(logfile, "%s %s %s [%s] \"%s %s HTTP/%d.%d\" %d %d %s:%s",
 272         client,
 273         accessLogFormatName(al->cache.rfc931),
 274         (user = accessLogFormatName(al->cache.authuser)),
 275         mkhttpdlogtime(&squid_curtime),
 276         al->private.method_str,
 277         al->url,
 278         al->http.version.major, al->http.version.minor,
 279         al->http.code,
 280         al->cache.size,
 281         log_tags[al->cache.code],
 282         hier_strings[al->hier.code]);
 283     safe_free(user);
 284 }
 285
 286 void
 287 accessLogLog(AccessLogEntry * al)
 288 {
 289     if (LogfileStatus != LOG_ENABLE)
 290         return;
 291     if (al->url == NULL)
 292         al->url = dash_str;
 293     if (!al->http.content_type || *al->http.content_type == '\0')
 294         al->http.content_type = dash_str;
 295     if (al->icp.opcode)
 296         al->private.method_str = icp_opcode_str[al->icp.opcode];
 297     else
 298         al->private.method_str = RequestMethodStr[al->http.method];
 299     if (al->hier.host[0] == '\0')
 300         xstrncpy(al->hier.host, dash_str, SQUIDHOSTNAMELEN);
 301
 302     if (Config.onoff.common_log)
 303         accessLogCommon(al);
 304     else
 305         accessLogSquid(al);
 306     if (Config.onoff.log_mime_hdrs) {
 307         char *ereq = log_quote(al->headers.request);
 308         char *erep = log_quote(al->headers.reply);
 309         logfilePrintf(logfile, " [%s] [%s]\n", ereq, erep);
 310         safe_free(ereq);
 311         safe_free(erep);
 312     } else {
 313         logfilePrintf(logfile, "\n");
 314     }
 315     logfileFlush(logfile);
 316 #if MULTICAST_MISS_STREAM
 317     if (al->cache.code != LOG_TCP_MISS)
 318         (void) 0;
 319     else if (al->http.method != METHOD_GET)
 320         (void) 0;
 321     else if (mcast_miss_fd < 0)
 322         (void) 0;
 323     else {
 324         unsigned int ibuf[365];
 325         size_t isize;
 326         xstrncpy((char *) ibuf, al->url, 364 * sizeof(int));
 327         isize = ((strlen(al->url) + 8) / 8) * 2;
 328         if (isize > 364)
 329             isize = 364;
 330         mcast_encode((unsigned int *) ibuf, isize,
 331             (const unsigned int *) Config.mcast_miss.encode_key);
 332         comm_udp_sendto(mcast_miss_fd,
 333             &mcast_miss_to, sizeof(mcast_miss_to),
 334             ibuf, isize * sizeof(int));
 335     }
 336 #endif
 337 }
 338
 339 void
 340 accessLogRotate(void)
 341 {
 342 #if FORW_VIA_DB
 343     fvdbClear();
 344 #endif
 345     if (NULL == logfile)
 346         return;
 347     logfileRotate(logfile);
 348 #if HEADERS_LOG
 349     logfileRotate(headerslog);
 350 #endif
 351 }
 352
 353 void
 354 accessLogClose(void)
 355 {
 356     logfileClose(logfile);
 357     logfile = NULL;
 358 #if HEADERS_LOG
 359     logfileClose(headerslog);
 360     headerslog = NULL;
 361 #endif
 362 }
 363
 364 void
 365 hierarchyNote(HierarchyLogEntry * hl,
 366     hier_code code,
 367     const char *cache_peer)
 368 {
 369     assert(hl != NULL);
 370     hl->code = code;
 371     xstrncpy(hl->host, cache_peer, SQUIDHOSTNAMELEN);
 372 }
 373
 374 void
 375 accessLogInit(void)
 376 {
 377     assert(sizeof(log_tags) == (LOG_TYPE_MAX + 1) * sizeof(char *));
 378     if (strcasecmp(Config.Log.access, "none") == 0)
 379         return;
 380     logfile = logfileOpen(Config.Log.access, MAX_URL << 1, 1);
 381     LogfileStatus = LOG_ENABLE;
 382 #if HEADERS_LOG
 383     headerslog = logfileOpen("/usr/local/squid/logs/headers.log", 512);
 384     assert(NULL != headerslog);
 385 #endif
 386 #if FORW_VIA_DB
 387     fvdbInit();
 388 #endif
 389 #if MULTICAST_MISS_STREAM
 390     if (Config.mcast_miss.addr.s_addr != no_addr.s_addr) {
 391         memset(&mcast_miss_to, '\0', sizeof(mcast_miss_to));
 392         mcast_miss_to.sin_family = AF_INET;
 393         mcast_miss_to.sin_port = htons(Config.mcast_miss.port);
 394         mcast_miss_to.sin_addr.s_addr = Config.mcast_miss.addr.s_addr;
 395         mcast_miss_fd = comm_open(SOCK_DGRAM,
 396             0,
 397             Config.Addrs.udp_incoming,
 398             Config.mcast_miss.port,
 399             COMM_NONBLOCKING,
 400             "Multicast Miss Stream");
 401         if (mcast_miss_fd < 0)
 402             fatal("Cannot open Multicast Miss Stream Socket");
 403         debug(46, 1) ("Multicast Miss Stream Socket opened on FD %d\n",
 404             mcast_miss_fd);
 405         mcastSetTtl(mcast_miss_fd, Config.mcast_miss.ttl);
 406         if (strlen(Config.mcast_miss.encode_key) < 16)
 407             fatal("mcast_encode_key is too short, must be 16 characters");
 408     }
 409 #endif
 410 }
 411
 412 const char *
 413 accessLogTime(time_t t)
 414 {
 415     struct tm *tm;
 416     static char buf[128];
 417     static time_t last_t = 0;
 418     if (t != last_t) {
 419         tm = localtime(&t);
 420         strftime(buf, 127, "%Y/%m/%d %H:%M:%S", tm);
 421         last_t = t;
 422     }
 423     return buf;
 424 }
 425
 426
 427 #if FORW_VIA_DB
 428
 429 static void
 430 fvdbInit(void)
 431 {
 432     via_table = hash_create((HASHCMP *) strcmp, 977, hash4);
 433     forw_table = hash_create((HASHCMP *) strcmp, 977, hash4);
 434     cachemgrRegister("via_headers", "Via Request Headers", fvdbDumpVia, 0, 1);
 435     cachemgrRegister("forw_headers", "X-Forwarded-For Request Headers",
 436         fvdbDumpForw, 0, 1);
 437 }
 438
 439 static void
 440 fvdbCount(hash_table * hash, const char *key)
 441 {
 442     fvdb_entry *fv;
 443     if (NULL == hash)
 444         return;
 445     fv = hash_lookup(hash, key);
 446     if (NULL == fv) {
 447         fv = xcalloc(1, sizeof(fvdb_entry));
 448         fv->hash.key = xstrdup(key);
 449         hash_join(hash, &fv->hash);
 450     }
 451     fv->n++;
 452 }
 453
 454 void
 455 fvdbCountVia(const char *key)
 456 {
 457     fvdbCount(via_table, key);
 458 }
 459
 460 void
 461 fvdbCountForw(const char *key)
 462 {
 463     fvdbCount(forw_table, key);
 464 }
 465
 466 static void
 467 fvdbDumpTable(StoreEntry * e, hash_table * hash)
 468 {
 469     hash_link *h;
 470     fvdb_entry *fv;
 471     if (hash == NULL)
 472         return;
 473     hash_first(hash);
 474     while ((h = hash_next(hash))) {
 475         fv = (fvdb_entry *) h;
 476         storeAppendPrintf(e, "%9d %s\n", fv->n, hashKeyStr(&fv->hash));
 477     }
 478 }
 479
 480 static void
 481 fvdbDumpVia(StoreEntry * e)
 482 {
 483     fvdbDumpTable(e, via_table);
 484 }
 485
 486 static void
 487 fvdbDumpForw(StoreEntry * e)
 488 {
 489     fvdbDumpTable(e, forw_table);
 490 }
 491
 492 static
 493 void
 494 fvdbFreeEntry(void *data)
 495 {
 496     fvdb_entry *fv = data;
 497     xfree(fv->hash.key);
 498     xfree(fv);
 499 }
 500
 501 static void
 502 fvdbClear(void)
 503 {
 504     hashFreeItems(via_table, fvdbFreeEntry);
 505     hashFreeMemory(via_table);
 506     via_table = hash_create((HASHCMP *) strcmp, 977, hash4);
 507     hashFreeItems(forw_table, fvdbFreeEntry);
 508     hashFreeMemory(forw_table);
 509     forw_table = hash_create((HASHCMP *) strcmp, 977, hash4);
 510 }
 511
 512 #endif
 513
 514 #if MULTICAST_MISS_STREAM
 515 /*
 516  * From http://www.io.com/~paulhart/game/algorithms/tea.html
 517  *
 518  * size of 'ibuf' must be a multiple of 2.
 519  * size of 'key' must be 4.
 520  * 'ibuf' is modified in place, encrypted data is written in
 521  * network byte order.
 522  */
 523 static void
 524 mcast_encode(unsigned int *ibuf, size_t isize, const unsigned int *key)
 525 {
 526     unsigned int y;
 527     unsigned int z;
 528     unsigned int sum;
 529     const unsigned int delta = 0x9e3779b9;
 530     unsigned int n = 32;
 531     const unsigned int k0 = htonl(key[0]);
 532     const unsigned int k1 = htonl(key[1]);
 533     const unsigned int k2 = htonl(key[2]);
 534     const unsigned int k3 = htonl(key[3]);
 535     int i;
 536     for (i = 0; i < isize; i += 2) {
 537         y = htonl(ibuf[i]);
 538         z = htonl(ibuf[i + 1]);
 539         sum = 0;
 540         for (n = 32; n; n--) {
 541             sum += delta;
 542             y += (z << 4) + (k0 ^ z) + (sum ^ (z >> 5)) + k1;
 543             z += (y << 4) + (k2 ^ y) + (sum ^ (y >> 5)) + k3;
 544         }
 545         ibuf[i] = htonl(y);
 546         ibuf[i + 1] = htonl(z);
 547     }
 548 }
 549
 550 #endif
 551
 552 #if HEADERS_LOG
 553 void
 554 headersLog(int cs, int pq, method_t m, void *data)
 555 {
 556     HttpReply *rep;
 557     request_t *req;
 558     unsigned short magic = 0;
 559     unsigned char M = (unsigned char) m;
 560     unsigned short S;
 561     char *hmask;
 562     int ccmask = 0;
 563     if (0 == pq) {
 564         /* reply */
 565         rep = data;
 566         req = NULL;
 567         magic = 0x0050;
 568         hmask = rep->header.mask;
 569         if (rep->cache_control)
 570             ccmask = rep->cache_control->mask;
 571     } else {
 572         /* request */
 573         req = data;
 574         rep = NULL;
 575         magic = 0x0051;
 576         hmask = req->header.mask;
 577         if (req->cache_control)
 578             ccmask = req->cache_control->mask;
 579     }
 580     if (0 == cs) {
 581         /* client */
 582         magic |= 0x4300;
 583     } else {
 584         /* server */
 585         magic |= 0x5300;
 586     }
 587     magic = htons(magic);
 588     ccmask = htonl(ccmask);
 589     if (0 == pq)
 590         S = (unsigned short) rep->sline.status;
 591     else
 592         S = (unsigned short) HTTP_STATUS_NONE;
 593     logfileWrite(headerslog, &magic, sizeof(magic));
 594     logfileWrite(headerslog, &M, sizeof(M));
 595     logfileWrite(headerslog, &S, sizeof(S));
 596     logfileWrite(headerslog, hmask, sizeof(HttpHeaderMask));
 597     logfileWrite(headerslog, &ccmask, sizeof(int));
 598     logfileFlush(headerslog);
 599 }
 600
 601 #endif