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