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