src/log/access_log.cc

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