src/log/access_log.cc

   1 /*
   2  * DEBUG: section 46    Access Log
   3  * AUTHOR: Duane Wessels
   4  *
   5  * SQUID Web Proxy Cache          http://www.squid-cache.org/
   6  * ----------------------------------------------------------
   7  *
   8  *  Squid is the result of efforts by numerous individuals from
   9  *  the Internet community; see the CONTRIBUTORS file for full
  10  *  details.   Many organizations have provided support for Squid's
  11  *  development; see the SPONSORS file for full details.  Squid is
  12  *  Copyrighted (C) 2001 by the Regents of the University of
  13  *  California; see the COPYRIGHT file for full details.  Squid
  14  *  incorporates software developed and/or copyrighted by other
  15  *  sources; see the CREDITS file for full details.
  16  *
  17  *  This program is free software; you can redistribute it and/or modify
  18  *  it under the terms of the GNU General Public License as published by
  19  *  the Free Software Foundation; either version 2 of the License, or
  20  *  (at your option) any later version.
  21  *
  22  *  This program is distributed in the hope that it will be useful,
  23  *  but WITHOUT ANY WARRANTY; without even the implied warranty of
  24  *  MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
  25  *  GNU General Public License for more details.
  26  *
  27  *  You should have received a copy of the GNU General Public License
  28  *  along with this program; if not, write to the Free Software
  29  *  Foundation, Inc., 59 Temple Place, Suite 330, Boston, MA 02111, USA.
  30  *
  31  */
  32
  33 #include "squid.h"
  34 #include "AccessLogEntry.h"
  35 #include "acl/Checklist.h"
  36 #include "CachePeer.h"
  37 #include "err_detail_type.h"
  38 #include "errorpage.h"
  39 #include "errorpage.h"
  40 #include "format/Token.h"
  41 #include "globals.h"
  42 #include "hier_code.h"
  43 #include "HttpReply.h"
  44 #include "HttpRequest.h"
  45 #include "log/access_log.h"
  46 #include "log/Config.h"
  47 #include "log/File.h"
  48 #include "log/Formats.h"
  49 #include "MemBuf.h"
  50 #include "mgr/Registration.h"
  51 #include "rfc1738.h"
  52 #include "SquidConfig.h"
  53 #include "SquidTime.h"
  54 #include "Store.h"
  55
  56 #if USE_SQUID_EUI
  57 #include "eui/Eui48.h"
  58 #include "eui/Eui64.h"
  59 #endif
  60
  61 #if HEADERS_LOG
  62 static Logfile *headerslog = NULL;
  63 #endif
  64
  65 #if MULTICAST_MISS_STREAM
  66 static int mcast_miss_fd = -1;
  67
  68 static struct sockaddr_in mcast_miss_to;
  69 static void mcast_encode(unsigned int *, size_t, const unsigned int *);
  70 #endif
  71
  72 #if USE_FORW_VIA_DB
  73
  74 typedef struct {
  75     hash_link hash;
  76     int n;
  77 } fvdb_entry;
  78 static hash_table *via_table = NULL;
  79 static hash_table *forw_table = NULL;
  80 static void fvdbInit();
  81 static void fvdbDumpTable(StoreEntry * e, hash_table * hash);
  82 static void fvdbCount(hash_table * hash, const char *key);
  83 static OBJH fvdbDumpVia;
  84 static OBJH fvdbDumpForw;
  85 static FREE fvdbFreeEntry;
  86 static void fvdbClear(void);
  87 static void fvdbRegisterWithCacheManager();
  88 #endif
  89
  90 int LogfileStatus = LOG_DISABLE;
  91
  92 void
  93 accessLogLogTo(CustomLog* log, AccessLogEntry::Pointer &al, ACLChecklist * checklist)
  94 {
  95
  96     if (al->url == NULL)
  97         al->url = dash_str;
  98
  99     if (!al->http.content_type || *al->http.content_type == '\0')
 100         al->http.content_type = dash_str;
 101
 102     if (al->icp.opcode)
 103         al->_private.method_str = icp_opcode_str[al->icp.opcode];
 104     else if (al->htcp.opcode)
 105         al->_private.method_str = al->htcp.opcode;
 106     else
 107         al->_private.method_str = RequestMethodStr(al->http.method);
 108
 109     if (al->hier.host[0] == '\0')
 110         xstrncpy(al->hier.host, dash_str, SQUIDHOSTNAMELEN);
 111
 112     for (; log; log = log->next) {
 113         if (log->aclList && checklist && checklist->fastCheck(log->aclList) != ACCESS_ALLOWED)
 114             continue;
 115
 116         if (log->logfile) {
 117             logfileLineStart(log->logfile);
 118
 119             switch (log->type) {
 120
 121             case Log::Format::CLF_SQUID:
 122                 Log::Format::SquidNative(al, log->logfile);
 123                 break;
 124
 125             case Log::Format::CLF_COMBINED:
 126                 Log::Format::HttpdCombined(al, log->logfile);
 127                 break;
 128
 129             case Log::Format::CLF_COMMON:
 130                 Log::Format::HttpdCommon(al, log->logfile);
 131                 break;
 132
 133             case Log::Format::CLF_REFERER:
 134                 Log::Format::SquidReferer(al, log->logfile);
 135                 break;
 136
 137             case Log::Format::CLF_USERAGENT:
 138                 Log::Format::SquidUserAgent(al, log->logfile);
 139                 break;
 140
 141             case Log::Format::CLF_CUSTOM:
 142                 Log::Format::SquidCustom(al, log);
 143                 break;
 144
 145 #if ICAP_CLIENT
 146             case Log::Format::CLF_ICAP_SQUID:
 147                 Log::Format::SquidIcap(al, log->logfile);
 148                 break;
 149 #endif
 150
 151             case Log::Format::CLF_NONE:
 152                 return; // abort!
 153
 154             default:
 155                 fatalf("Unknown log format %d\n", log->type);
 156                 break;
 157             }
 158
 159             logfileLineEnd(log->logfile);
 160         }
 161
 162         // NP:  WTF?  if _any_ log line has no checklist ignore the following ones?
 163         if (!checklist)
 164             break;
 165     }
 166 }
 167
 168 void
 169 accessLogLog(AccessLogEntry::Pointer &al, ACLChecklist * checklist)
 170 {
 171     if (LogfileStatus != LOG_ENABLE)
 172         return;
 173
 174     accessLogLogTo(Config.Log.accesslogs, al, checklist);
 175 #if MULTICAST_MISS_STREAM
 176
 177     if (al->cache.code != LOG_TCP_MISS)
 178         (void) 0;
 179     else if (al->http.method != METHOD_GET)
 180         (void) 0;
 181     else if (mcast_miss_fd < 0)
 182         (void) 0;
 183     else {
 184         unsigned int ibuf[365];
 185         size_t isize;
 186         xstrncpy((char *) ibuf, al->url, 364 * sizeof(int));
 187         isize = ((strlen(al->url) + 8) / 8) * 2;
 188
 189         if (isize > 364)
 190             isize = 364;
 191
 192         mcast_encode((unsigned int *) ibuf, isize,
 193                      (const unsigned int *) Config.mcast_miss.encode_key);
 194
 195         comm_udp_sendto(mcast_miss_fd,
 196                         &mcast_miss_to, sizeof(mcast_miss_to),
 197                         ibuf, isize * sizeof(int));
 198     }
 199
 200 #endif
 201 }
 202
 203 void
 204 accessLogRotate(void)
 205 {
 206     CustomLog *log;
 207 #if USE_FORW_VIA_DB
 208
 209     fvdbClear();
 210 #endif
 211
 212     for (log = Config.Log.accesslogs; log; log = log->next) {
 213         if (log->logfile) {
 214             logfileRotate(log->logfile);
 215         }
 216     }
 217
 218 #if HEADERS_LOG
 219
 220     logfileRotate(headerslog);
 221
 222 #endif
 223 }
 224
 225 void
 226 accessLogClose(void)
 227 {
 228     CustomLog *log;
 229
 230     for (log = Config.Log.accesslogs; log; log = log->next) {
 231         if (log->logfile) {
 232             logfileClose(log->logfile);
 233             log->logfile = NULL;
 234         }
 235     }
 236
 237 #if HEADERS_LOG
 238
 239     logfileClose(headerslog);
 240
 241     headerslog = NULL;
 242
 243 #endif
 244 }
 245
 246 HierarchyLogEntry::HierarchyLogEntry() :
 247         code(HIER_NONE),
 248         cd_lookup(LOOKUP_NONE),
 249         n_choices(0),
 250         n_ichoices(0),
 251         peer_reply_status(HTTP_STATUS_NONE),
 252         peer_response_time(-1),
 253         total_response_time(-1),
 254         tcpServer(NULL),
 255         bodyBytesRead(-1)
 256 {
 257     memset(host, '\0', SQUIDHOSTNAMELEN);
 258     memset(cd_host, '\0', SQUIDHOSTNAMELEN);
 259
 260     peer_select_start.tv_sec =0;
 261     peer_select_start.tv_usec =0;
 262
 263     store_complete_stop.tv_sec =0;
 264     store_complete_stop.tv_usec =0;
 265
 266     peer_http_request_sent.tv_sec = 0;
 267     peer_http_request_sent.tv_usec = 0;
 268
 269     first_conn_start.tv_sec = 0;
 270     first_conn_start.tv_usec = 0;
 271 }
 272
 273 void
 274 HierarchyLogEntry::note(const Comm::ConnectionPointer &server, const char *requestedHost)
 275 {
 276     tcpServer = server;
 277     if (tcpServer == NULL) {
 278         code = HIER_NONE;
 279         xstrncpy(host, requestedHost, sizeof(host));
 280     } else {
 281         code = tcpServer->peerType;
 282
 283         if (tcpServer->getPeer()) {
 284             // went to peer, log peer host name
 285             xstrncpy(host, tcpServer->getPeer()->name, sizeof(host));
 286         } else {
 287             xstrncpy(host, requestedHost, sizeof(host));
 288         }
 289     }
 290 }
 291
 292 static void
 293 accessLogRegisterWithCacheManager(void)
 294 {
 295 #if USE_FORW_VIA_DB
 296     fvdbRegisterWithCacheManager();
 297 #endif
 298 }
 299
 300 void
 301 accessLogInit(void)
 302 {
 303     CustomLog *log;
 304
 305     accessLogRegisterWithCacheManager();
 306
 307 #if USE_ADAPTATION
 308     Log::TheConfig.hasAdaptToken = false;
 309 #endif
 310 #if ICAP_CLIENT
 311     Log::TheConfig.hasIcapToken = false;
 312 #endif
 313
 314     for (log = Config.Log.accesslogs; log; log = log->next) {
 315         if (log->type == Log::Format::CLF_NONE)
 316             continue;
 317
 318         log->logfile = logfileOpen(log->filename, MAX_URL << 2, 1);
 319
 320         LogfileStatus = LOG_ENABLE;
 321
 322 #if USE_ADAPTATION
 323         for (Format::Token * curr_token = (log->logFormat?log->logFormat->format:NULL); curr_token; curr_token = curr_token->next) {
 324             if (curr_token->type == Format::LFT_ADAPTATION_SUM_XACT_TIMES ||
 325                     curr_token->type == Format::LFT_ADAPTATION_ALL_XACT_TIMES ||
 326                     curr_token->type == Format::LFT_ADAPTATION_LAST_HEADER ||
 327                     curr_token->type == Format::LFT_ADAPTATION_LAST_HEADER_ELEM ||
 328                     curr_token->type == Format::LFT_ADAPTATION_LAST_ALL_HEADERS) {
 329                 Log::TheConfig.hasAdaptToken = true;
 330             }
 331 #if ICAP_CLIENT
 332             if (curr_token->type == Format::LFT_ICAP_TOTAL_TIME) {
 333                 Log::TheConfig.hasIcapToken = true;
 334             }
 335 #endif
 336         }
 337 #endif
 338     }
 339
 340 #if HEADERS_LOG
 341
 342     headerslog = logfileOpen("/usr/local/squid/logs/headers.log", 512);
 343
 344     assert(NULL != headerslog);
 345
 346 #endif
 347 #if MULTICAST_MISS_STREAM
 348
 349     if (Config.mcast_miss.addr.s_addr != no_addr.s_addr) {
 350         memset(&mcast_miss_to, '\0', sizeof(mcast_miss_to));
 351         mcast_miss_to.sin_family = AF_INET;
 352         mcast_miss_to.sin_port = htons(Config.mcast_miss.port);
 353         mcast_miss_to.sin_addr.s_addr = Config.mcast_miss.addr.s_addr;
 354         mcast_miss_fd = comm_open(SOCK_DGRAM,
 355                                   IPPROTO_UDP,
 356                                   Config.Addrs.udp_incoming,
 357                                   Config.mcast_miss.port,
 358                                   COMM_NONBLOCKING,
 359                                   "Multicast Miss Stream");
 360
 361         if (mcast_miss_fd < 0)
 362             fatal("Cannot open Multicast Miss Stream Socket");
 363
 364         debugs(46, DBG_IMPORTANT, "Multicast Miss Stream Socket opened on FD " << mcast_miss_fd);
 365
 366         mcastSetTtl(mcast_miss_fd, Config.mcast_miss.ttl);
 367
 368         if (strlen(Config.mcast_miss.encode_key) < 16)
 369             fatal("mcast_encode_key is too short, must be 16 characters");
 370     }
 371
 372 #endif
 373 #if USE_FORW_VIA_DB
 374
 375     fvdbInit();
 376
 377 #endif
 378 }
 379
 380 #if USE_FORW_VIA_DB
 381
 382 static void
 383 fvdbInit(void)
 384 {
 385     via_table = hash_create((HASHCMP *) strcmp, 977, hash4);
 386     forw_table = hash_create((HASHCMP *) strcmp, 977, hash4);
 387 }
 388
 389 static void
 390 fvdbRegisterWithCacheManager(void)
 391 {
 392     Mgr::RegisterAction("via_headers", "Via Request Headers", fvdbDumpVia, 0, 1);
 393     Mgr::RegisterAction("forw_headers", "X-Forwarded-For Request Headers",
 394                         fvdbDumpForw, 0, 1);
 395 }
 396
 397 static void
 398 fvdbCount(hash_table * hash, const char *key)
 399 {
 400     fvdb_entry *fv;
 401
 402     if (NULL == hash)
 403         return;
 404
 405     fv = (fvdb_entry *)hash_lookup(hash, key);
 406
 407     if (NULL == fv) {
 408         fv = static_cast <fvdb_entry *>(xcalloc(1, sizeof(fvdb_entry)));
 409         fv->hash.key = xstrdup(key);
 410         hash_join(hash, &fv->hash);
 411     }
 412
 413     ++ fv->n;
 414 }
 415
 416 void
 417 fvdbCountVia(const char *key)
 418 {
 419     fvdbCount(via_table, key);
 420 }
 421
 422 void
 423 fvdbCountForw(const char *key)
 424 {
 425     fvdbCount(forw_table, key);
 426 }
 427
 428 static void
 429 fvdbDumpTable(StoreEntry * e, hash_table * hash)
 430 {
 431     hash_link *h;
 432     fvdb_entry *fv;
 433
 434     if (hash == NULL)
 435         return;
 436
 437     hash_first(hash);
 438
 439     while ((h = hash_next(hash))) {
 440         fv = (fvdb_entry *) h;
 441         storeAppendPrintf(e, "%9d %s\n", fv->n, hashKeyStr(&fv->hash));
 442     }
 443 }
 444
 445 static void
 446 fvdbDumpVia(StoreEntry * e)
 447 {
 448     fvdbDumpTable(e, via_table);
 449 }
 450
 451 static void
 452 fvdbDumpForw(StoreEntry * e)
 453 {
 454     fvdbDumpTable(e, forw_table);
 455 }
 456
 457 static
 458 void
 459 fvdbFreeEntry(void *data)
 460 {
 461     fvdb_entry *fv = static_cast <fvdb_entry *>(data);
 462     xfree(fv->hash.key);
 463     xfree(fv);
 464 }
 465
 466 static void
 467 fvdbClear(void)
 468 {
 469     hashFreeItems(via_table, fvdbFreeEntry);
 470     hashFreeMemory(via_table);
 471     via_table = hash_create((HASHCMP *) strcmp, 977, hash4);
 472     hashFreeItems(forw_table, fvdbFreeEntry);
 473     hashFreeMemory(forw_table);
 474     forw_table = hash_create((HASHCMP *) strcmp, 977, hash4);
 475 }
 476
 477 #endif
 478
 479 #if MULTICAST_MISS_STREAM
 480 /*
 481  * From http://www.io.com/~paulhart/game/algorithms/tea.html
 482  *
 483  * size of 'ibuf' must be a multiple of 2.
 484  * size of 'key' must be 4.
 485  * 'ibuf' is modified in place, encrypted data is written in
 486  * network byte order.
 487  */
 488 static void
 489 mcast_encode(unsigned int *ibuf, size_t isize, const unsigned int *key)
 490 {
 491     unsigned int y;
 492     unsigned int z;
 493     unsigned int sum;
 494     const unsigned int delta = 0x9e3779b9;
 495     unsigned int n = 32;
 496     const unsigned int k0 = htonl(key[0]);
 497     const unsigned int k1 = htonl(key[1]);
 498     const unsigned int k2 = htonl(key[2]);
 499     const unsigned int k3 = htonl(key[3]);
 500     int i;
 501
 502     for (i = 0; i < isize; i += 2) {
 503         y = htonl(ibuf[i]);
 504         z = htonl(ibuf[i + 1]);
 505         sum = 0;
 506
 507         for (n = 32; n; --n) {
 508             sum += delta;
 509             y += (z << 4) + (k0 ^ z) + (sum ^ (z >> 5)) + k1;
 510             z += (y << 4) + (k2 ^ y) + (sum ^ (y >> 5)) + k3;
 511         }
 512
 513         ibuf[i] = htonl(y);
 514         ibuf[i + 1] = htonl(z);
 515     }
 516 }
 517
 518 #endif
 519
 520 #if HEADERS_LOG
 521 void
 522 headersLog(int cs, int pq, const HttpRequestMethod& method, void *data)
 523 {
 524     HttpReply *rep;
 525     HttpRequest *req;
 526     unsigned short magic = 0;
 527     unsigned char M = (unsigned char) m;
 528     unsigned short S;
 529     char *hmask;
 530     int ccmask = 0;
 531
 532     if (0 == pq) {
 533         /* reply */
 534         rep = data;
 535         req = NULL;
 536         magic = 0x0050;
 537         hmask = rep->header.mask;
 538
 539         if (rep->cache_control)
 540             ccmask = rep->cache_control->mask;
 541     } else {
 542         /* request */
 543         req = data;
 544         rep = NULL;
 545         magic = 0x0051;
 546         hmask = req->header.mask;
 547
 548         if (req->cache_control)
 549             ccmask = req->cache_control->mask;
 550     }
 551
 552     if (0 == cs) {
 553         /* client */
 554         magic |= 0x4300;
 555     } else {
 556         /* server */
 557         magic |= 0x5300;
 558     }
 559
 560     magic = htons(magic);
 561     ccmask = htonl(ccmask);
 562
 563     if (0 == pq)
 564         S = (unsigned short) rep->sline.status;
 565     else
 566         S = (unsigned short) HTTP_STATUS_NONE;
 567
 568     logfileWrite(headerslog, &magic, sizeof(magic));
 569     logfileWrite(headerslog, &M, sizeof(M));
 570     logfileWrite(headerslog, &S, sizeof(S));
 571     logfileWrite(headerslog, hmask, sizeof(HttpHeaderMask));
 572     logfileWrite(headerslog, &ccmask, sizeof(int));
 573 }
 574
 575 #endif
 576
 577 int
 578 logTypeIsATcpHit(log_type code)
 579 {
 580     /* this should be a bitmap for better optimization */
 581
 582     if (code == LOG_TCP_HIT)
 583         return 1;
 584
 585     if (code == LOG_TCP_IMS_HIT)
 586         return 1;
 587
 588     if (code == LOG_TCP_REFRESH_FAIL_OLD)
 589         return 1;
 590
 591     if (code == LOG_TCP_REFRESH_UNMODIFIED)
 592         return 1;
 593
 594     if (code == LOG_TCP_NEGATIVE_HIT)
 595         return 1;
 596
 597     if (code == LOG_TCP_MEM_HIT)
 598         return 1;
 599
 600     if (code == LOG_TCP_OFFLINE_HIT)
 601         return 1;
 602
 603     return 0;
 604 }