src/log/access_log.cc

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