access_log.cc
Go to the documentation of this file.
1 /*
2  * Copyright (C) 1996-2021 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 #include "sbuf/Algorithms.h"
15 #if USE_ADAPTATION
16 #include "adaptation/Config.h"
17 #endif
18 #include "base/PackableStream.h"
19 #include "CachePeer.h"
20 #include "error/Detail.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 "sbuf/SBuf.h"
36 #include "SquidConfig.h"
37 #include "SquidTime.h"
38 #include "Store.h"
39 
40 #if USE_SQUID_EUI
41 #include "eui/Eui48.h"
42 #include "eui/Eui64.h"
43 #endif
44 
45 #include <unordered_map>
46 
47 #if HEADERS_LOG
48 static Logfile *headerslog = NULL;
49 #endif
50 
51 #if MULTICAST_MISS_STREAM
52 static int mcast_miss_fd = -1;
53 
54 static struct sockaddr_in mcast_miss_to;
55 static void mcast_encode(unsigned int *, size_t, const unsigned int *);
56 #endif
57 
58 #if USE_FORW_VIA_DB
59 
60 using HeaderValueCountsElement = std::pair<const SBuf, uint64_t>;
62 using HeaderValueCounts = std::unordered_map<SBuf, uint64_t, std::hash<SBuf>, std::equal_to<SBuf>, PoolingAllocator<HeaderValueCountsElement> >;
63 
65 static HeaderValueCounts TheViaCounts;
67 static HeaderValueCounts TheForwardedCounts;
68 
69 static OBJH fvdbDumpVia;
70 static OBJH fvdbDumpForwarded;
71 static void fvdbClear(void);
72 static void fvdbRegisterWithCacheManager();
73 #endif
74 
76 
77 void
79 {
80 
81  if (al->url.isEmpty())
82  al->url = Format::Dash;
83 
84  if (!al->http.content_type || *al->http.content_type == '\0')
85  al->http.content_type = dash_str;
86 
87  if (al->hier.host[0] == '\0')
88  xstrncpy(al->hier.host, dash_str, SQUIDHOSTNAMELEN);
89 
90  for (; log; log = log->next) {
91  if (log->aclList && checklist && !checklist->fastCheck(log->aclList).allowed())
92  continue;
93 
94  // The special-case "none" type has no logfile object set
95  if (log->type == Log::Format::CLF_NONE)
96  return;
97 
98  if (log->logfile) {
99  logfileLineStart(log->logfile);
100 
101  switch (log->type) {
102 
104  Log::Format::SquidNative(al, log->logfile);
105  break;
106 
108  Log::Format::HttpdCombined(al, log->logfile);
109  break;
110 
112  Log::Format::HttpdCommon(al, log->logfile);
113  break;
114 
116  Log::Format::SquidReferer(al, log->logfile);
117  break;
118 
120  Log::Format::SquidUserAgent(al, log->logfile);
121  break;
122 
125  break;
126 
127 #if ICAP_CLIENT
129  Log::Format::SquidIcap(al, log->logfile);
130  break;
131 #endif
132 
133  default:
134  fatalf("Unknown log format %d\n", log->type);
135  break;
136  }
137 
138  logfileLineEnd(log->logfile);
139  }
140 
141  // NP: WTF? if _any_ log line has no checklist ignore the following ones?
142  if (!checklist)
143  break;
144  }
145 }
146 
147 void
149 {
150  if (LogfileStatus != LOG_ENABLE)
151  return;
152 
153  accessLogLogTo(Config.Log.accesslogs, al, checklist);
154 #if MULTICAST_MISS_STREAM
155 
156  if (al->cache.code != LOG_TCP_MISS)
157  (void) 0;
158  else if (al->http.method != METHOD_GET)
159  (void) 0;
160  else if (mcast_miss_fd < 0)
161  (void) 0;
162  else {
163  unsigned int ibuf[365];
164  size_t isize;
165  xstrncpy((char *) ibuf, al->url.c_str(), 364 * sizeof(int));
166  isize = ((al->url.length() + 8) / 8) * 2;
167 
168  if (isize > 364)
169  isize = 364;
170 
171  mcast_encode((unsigned int *) ibuf, isize,
172  (const unsigned int *) Config.mcast_miss.encode_key);
173 
175  &mcast_miss_to, sizeof(mcast_miss_to),
176  ibuf, isize * sizeof(int));
177  }
178 
179 #endif
180 }
181 
182 void
184 {
185  CustomLog *log;
186 #if USE_FORW_VIA_DB
187 
188  fvdbClear();
189 #endif
190 
191  for (log = Config.Log.accesslogs; log; log = log->next) {
192  log->rotate();
193  }
194 
195 #if HEADERS_LOG
196 
197  logfileRotate(headerslog, Config.Log.rotateNumber);
198 
199 #endif
200 }
201 
202 void
204 {
205  CustomLog *log;
206 
207  for (log = Config.Log.accesslogs; log; log = log->next) {
208  if (log->logfile) {
209  logfileClose(log->logfile);
210  log->logfile = NULL;
211  }
212  }
213 
214 #if HEADERS_LOG
215 
216  logfileClose(headerslog);
217 
218  headerslog = NULL;
219 
220 #endif
221 }
222 
224  code(HIER_NONE),
225  cd_lookup(LOOKUP_NONE),
226  n_choices(0),
227  n_ichoices(0),
228  peer_reply_status(Http::scNone),
229  tcpServer(NULL),
230  bodyBytesRead(-1)
231 {
232  memset(host, '\0', SQUIDHOSTNAMELEN);
233  memset(cd_host, '\0', SQUIDHOSTNAMELEN);
234 
235  peer_select_start.tv_sec =0;
236  peer_select_start.tv_usec =0;
237 
238  store_complete_stop.tv_sec =0;
239  store_complete_stop.tv_usec =0;
240 
241  clearPeerNotes();
242 
243  totalResponseTime_.tv_sec = -1;
244  totalResponseTime_.tv_usec = 0;
245 
246  firstConnStart_.tv_sec = 0;
247  firstConnStart_.tv_usec = 0;
248 }
249 
250 void
252 {
253  clearPeerNotes();
254 
255  tcpServer = server;
256  if (tcpServer == NULL) {
257  code = HIER_NONE;
258  xstrncpy(host, requestedHost, sizeof(host));
259  } else {
261 
262  if (tcpServer->getPeer()) {
263  // went to peer, log peer host name
264  xstrncpy(host, tcpServer->getPeer()->name, sizeof(host));
265  } else {
266  xstrncpy(host, requestedHost, sizeof(host));
267  }
268  }
269 }
270 
272 void
274 {
275  peer_last_read_.tv_sec = 0;
276  peer_last_read_.tv_usec = 0;
277 
278  peer_last_write_.tv_sec = 0;
279  peer_last_write_.tv_usec = 0;
280 
281  bodyBytesRead = -1;
282 }
283 
284 void
286 {
288 }
289 
290 void
292 {
294 }
295 
296 void
298 {
299  if (!firstConnStart_.tv_sec)
301 }
302 
303 void
305 {
306  debugs(46, 5, "First connection started: " << firstConnStart_ <<
307  ", current total response time value: " << (totalResponseTime_.tv_sec * 1000 + totalResponseTime_.tv_usec/1000) <<
308  (force ? ", force fixing" : ""));
309  if (!force && totalResponseTime_.tv_sec != -1)
310  return;
311 
312  if (firstConnStart_.tv_sec)
314 }
315 
316 bool
317 HierarchyLogEntry::peerResponseTime(struct timeval &responseTime)
318 {
319  // no I/O whatsoever
320  if (peer_last_write_.tv_sec <= 0 && peer_last_read_.tv_sec <= 0)
321  return false;
322 
323  // accommodate read without (completed) write
324  const auto last_write = peer_last_write_.tv_sec > 0 ?
326 
327  // accommodate write without (completed) read
328  const auto last_read = peer_last_read_.tv_sec > 0 ?
330 
331  tvSub(responseTime, last_write, last_read);
332  // The peer response time (%<pt) stopwatch is currently defined to start
333  // when we wrote the entire request. Thus, if we wrote something after the
334  // last read, report zero peer response time.
335  if (responseTime.tv_sec < 0) {
336  responseTime.tv_sec = 0;
337  responseTime.tv_usec = 0;
338  }
339 
340  return true;
341 }
342 
343 bool
344 HierarchyLogEntry::totalResponseTime(struct timeval &responseTime)
345 {
346  // This should not really happen, but there may be rare code
347  // paths that lead to FwdState discarded (or transaction logged)
348  // without (or before) a stopPeerClock() call.
349  if (firstConnStart_.tv_sec && totalResponseTime_.tv_sec == -1)
350  stopPeerClock(false);
351 
352  responseTime = totalResponseTime_;
353  return responseTime.tv_sec >= 0 && responseTime.tv_usec >= 0;
354 }
355 
356 static void
358 {
359 #if USE_FORW_VIA_DB
360  fvdbRegisterWithCacheManager();
361 #endif
362 }
363 
364 void
366 {
367  CustomLog *log;
368 
370 
371 #if USE_ADAPTATION
373 #endif
374 #if ICAP_CLIENT
376 #endif
377 
378  for (log = Config.Log.accesslogs; log; log = log->next) {
379  if (log->type == Log::Format::CLF_NONE)
380  continue;
381 
382  log->logfile = logfileOpen(log->filename, log->bufferSize, log->fatal);
383 
385 
386 #if USE_ADAPTATION
387  for (Format::Token * curr_token = (log->logFormat?log->logFormat->format:NULL); curr_token; curr_token = curr_token->next) {
388  if (curr_token->type == Format::LFT_ADAPTATION_SUM_XACT_TIMES ||
389  curr_token->type == Format::LFT_ADAPTATION_ALL_XACT_TIMES ||
390  curr_token->type == Format::LFT_ADAPTATION_LAST_HEADER ||
391  curr_token->type == Format::LFT_ADAPTATION_LAST_HEADER_ELEM ||
392  curr_token->type == Format::LFT_ADAPTATION_LAST_ALL_HEADERS||
393  (curr_token->type == Format::LFT_NOTE && !Adaptation::Config::metaHeaders.empty())) {
395  }
396 #if ICAP_CLIENT
397  if (curr_token->type == Format::LFT_ICAP_TOTAL_TIME) {
399  }
400 #endif
401  }
402 #endif
403  }
404 
405 #if HEADERS_LOG
406 
407  headerslog = logfileOpen("/usr/local/squid/logs/headers.log", 512);
408 
409  assert(NULL != headerslog);
410 
411 #endif
412 #if MULTICAST_MISS_STREAM
413 
414  if (Config.mcast_miss.addr.s_addr != no_addr.s_addr) {
415  memset(&mcast_miss_to, '\0', sizeof(mcast_miss_to));
416  mcast_miss_to.sin_family = AF_INET;
417  mcast_miss_to.sin_port = htons(Config.mcast_miss.port);
418  mcast_miss_to.sin_addr.s_addr = Config.mcast_miss.addr.s_addr;
419  mcast_miss_fd = comm_open(SOCK_DGRAM,
420  IPPROTO_UDP,
424  "Multicast Miss Stream");
425 
426  if (mcast_miss_fd < 0)
427  fatal("Cannot open Multicast Miss Stream Socket");
428 
429  debugs(46, DBG_IMPORTANT, "Multicast Miss Stream Socket opened on FD " << mcast_miss_fd);
430 
432 
433  if (strlen(Config.mcast_miss.encode_key) < 16)
434  fatal("mcast_encode_key is too short, must be 16 characters");
435  }
436 
437 #endif
438 }
439 
440 #if USE_FORW_VIA_DB
441 
442 static void
443 fvdbRegisterWithCacheManager(void)
444 {
445  Mgr::RegisterAction("via_headers", "Via Request Headers", fvdbDumpVia, 0, 1);
446  Mgr::RegisterAction("forw_headers", "X-Forwarded-For Request Headers",
447  fvdbDumpForwarded, 0, 1);
448 }
449 
450 void
451 fvdbCountVia(const SBuf &headerValue)
452 {
453  ++TheViaCounts[headerValue];
454 }
455 
456 void
457 fvdbCountForwarded(const SBuf &key)
458 {
459  ++TheForwardedCounts[key];
460 }
461 
462 static void
463 fvdbDumpCounts(StoreEntry &e, const HeaderValueCounts &counts)
464 {
465  PackableStream os(e);
466  for (const auto &i : counts)
467  os << std::setw(9) << i.second << ' ' << i.first << "\n";
468 }
469 
470 static void
471 fvdbDumpVia(StoreEntry * e)
472 {
473  assert(e);
474  fvdbDumpCounts(*e, TheViaCounts);
475 }
476 
477 static void
478 fvdbDumpForwarded(StoreEntry * e)
479 {
480  assert(e);
481  fvdbDumpCounts(*e, TheForwardedCounts);
482 }
483 
484 static void
485 fvdbClear(void)
486 {
487  TheViaCounts.clear();
488  TheForwardedCounts.clear();
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 
void fatal(const char *message)
Definition: fatal.cc:28
void accessLogLogTo(CustomLog *log, const AccessLogEntryPointer &al, ACLChecklist *checklist)
Definition: access_log.cc:78
Token * next
Definition: Token.h:71
hier_code peerType
Definition: Connection.h:150
struct timeval peer_last_write_
time of the last write to the last peer
void HttpdCombined(const AccessLogEntryPointer &al, Logfile *logfile)
Log with Apache httpd combined format.
static int mcast_miss_fd
Definition: access_log.cc:52
@ LOOKUP_NONE
Definition: lookup_t.h:13
@ LFT_ADAPTATION_LAST_ALL_HEADERS
Definition: ByteCode.h:187
void SquidIcap(const AccessLogEntryPointer &al, Logfile *logfile)
Display log details in Squid ICAP format.
void logfileClose(Logfile *lf)
Definition: File.cc:92
@ CLF_COMMON
Definition: Formats.h:29
@ LFT_ADAPTATION_LAST_HEADER
Definition: ByteCode.h:185
Ip::Address udp_incoming
Definition: SquidConfig.h:240
void stopPeerClock(const bool force)
Definition: access_log.cc:304
@ scNone
Definition: StatusCode.h:21
HttpHeader header
Definition: Message.h:75
static void accessLogRegisterWithCacheManager(void)
Definition: access_log.cc:357
void log(char *format,...)
HttpHeaderMask mask
Definition: HttpHeader.h:172
static struct sockaddr_in mcast_miss_to
Definition: access_log.cc:54
void logfileWrite(Logfile *lf, const char *buf, size_t len)
Definition: File.cc:108
int comm_udp_sendto(int fd, const Ip::Address &to_addr, const void *buf, int len)
Definition: comm.cc:891
@ CLF_COMBINED
Definition: Formats.h:28
Definition: SBuf.h:87
#define LOG_DISABLE
Definition: defines.h:63
void accessLogClose(void)
Definition: access_log.cc:203
CustomLog * accesslogs
Definition: SquidConfig.h:184
Ip::Address addr
Definition: SquidConfig.h:470
LogConfig TheConfig
Definition: Config.cc:15
#define LOG_ENABLE
Definition: defines.h:62
void HttpdCommon(const AccessLogEntryPointer &al, Logfile *logfile)
Log with Apache httpd common format.
int LogfileStatus
Definition: access_log.cc:75
char * xstrncpy(char *dst, const char *src, size_t n)
Definition: xstring.cc:37
Acl::Answer const & fastCheck()
Definition: Checklist.cc:332
Http::StatusLine sline
Definition: HttpReply.h:56
int rotateNumber
Definition: SquidConfig.h:189
Definition: forward.h:22
@ CLF_CUSTOM
Definition: Formats.h:30
void accessLogLog(const AccessLogEntryPointer &al, ACLChecklist *checklist)
Definition: access_log.cc:148
@ LFT_ICAP_TOTAL_TIME
Definition: ByteCode.h:192
char * name
Definition: CachePeer.h:39
#define DBG_IMPORTANT
Definition: Debug.h:41
int32_t mask
Definition: HttpHdrCc.h:173
@ LOG_TCP_MISS
Definition: LogTags.h:40
#define COMM_NONBLOCKING
Definition: Connection.h:46
void fvdbCountVia(const SBuf &)
bool empty() const
Definition: Notes.h:139
@ LFT_ADAPTATION_LAST_HEADER_ELEM
Definition: ByteCode.h:186
char * encode_key
Definition: SquidConfig.h:473
struct timeval totalResponseTime_
cumulative for all peers
void clearPeerNotes()
forget previous notePeerRead() and notePeerWrite() calls (if any)
Definition: access_log.cc:273
@ CLF_ICAP_SQUID
Definition: Formats.h:32
bool hasIcapToken
Definition: Config.h:53
@ CLF_SQUID
Definition: Formats.h:35
char cd_host[SQUIDHOSTNAMELEN]
struct timeval store_complete_stop
struct SquidConfig::@106 Addrs
void OBJH(StoreEntry *)
Definition: forward.h:44
#define NULL
Definition: types.h:166
@ CLF_REFERER
Definition: Formats.h:34
#define debugs(SECTION, LEVEL, CONTENT)
Definition: Debug.h:123
@ LFT_ADAPTATION_ALL_XACT_TIMES
Definition: ByteCode.h:184
timeval firstConnStart_
first connection use among all peers
struct timeval peer_select_start
Http::StatusCode status() const
retrieve the status code for this status line
Definition: StatusLine.h:45
@ HIER_NONE
Definition: hier_code.h:13
void logfileLineStart(Logfile *lf)
Definition: File.cc:126
char HttpHeaderMask[12]
void SquidNative(const AccessLogEntryPointer &al, Logfile *logfile)
Native Squid Format Display.
CachePeer * getPeer() const
Definition: Connection.cc:124
unsigned char code
Definition: html_quote.c:20
struct SquidConfig::@102 Log
bool hasAdaptToken
Definition: Config.h:49
struct timeval peer_last_read_
time of the last read from the last peer
bool peerResponseTime(struct timeval &responseTime)
Definition: access_log.cc:317
Logfile * logfileOpen(const char *path, size_t bufsz, int fatal_flag)
Definition: File.cc:40
const char * dash_str
#define assert(EX)
Definition: assert.h:19
void startPeerClock()
Start recording total time spent communicating with peers.
Definition: access_log.cc:297
HttpHdrCc * cache_control
Definition: Message.h:77
void fatalf(const char *fmt,...)
Definition: fatal.cc:68
void logfileRotate(Logfile *lf, int16_t rotateCount)
Definition: File.cc:101
struct SquidConfig::@118 mcast_miss
int comm_open(int sock_type, int proto, Ip::Address &addr, int flags, const char *note)
Definition: comm.cc:224
static Notes metaHeaders
The list of configured meta headers.
Definition: Config.h:58
@ LFT_ADAPTATION_SUM_XACT_TIMES
Definition: ByteCode.h:183
Definition: File.h:39
unsigned short port
Definition: SquidConfig.h:235
@ CLF_USERAGENT
Definition: Formats.h:36
int64_t bodyBytesRead
number of body bytes received from the next hop or -1
Comm::ConnectionPointer tcpServer
TCP/IP level details of the last peer/server connection.
void fvdbCountForwarded(const SBuf &)
count occurrences of the given X-Forwarded-For header value
struct timeval current_time
Definition: stub_time.cc:15
bool allowed() const
Definition: Acl.h:143
void SquidCustom(const AccessLogEntryPointer &al, CustomLog *log)
Log with a local custom format.
int mcastSetTtl(int fd, int mcast_ttl)
Definition: multicast.cc:20
void SquidReferer(const AccessLogEntryPointer &al, Logfile *logfile)
Display log details in Squid old refererlog format.
static char server[MAXLINE]
static StoreRebuildData counts
STL Allocator that uses Squid memory pools for memory management.
static void mcast_encode(unsigned int *, size_t, const unsigned int *)
Definition: access_log.cc:503
void resetPeerNotes(const Comm::ConnectionPointer &server, const char *requestedHost)
Definition: access_log.cc:251
void tvSub(struct timeval &res, struct timeval const &t1, struct timeval const &t2)
Definition: time.cc:44
char host[SQUIDHOSTNAMELEN]
bool totalResponseTime(struct timeval &responseTime)
Definition: access_log.cc:344
void logfileLineEnd(Logfile *lf)
Definition: File.cc:132
@ LFT_NOTE
Definition: ByteCode.h:236
void accessLogInit(void)
Definition: access_log.cc:365
void RegisterAction(char const *action, char const *desc, OBJH *handler, int pw_req_flag, int atomic)
Definition: Registration.cc:16
@ METHOD_GET
Definition: MethodType.h:25
@ CLF_NONE
Definition: Formats.h:37
void accessLogRotate(void)
Definition: access_log.cc:183
const SBuf Dash
#define SQUIDHOSTNAMELEN
Definition: rfc2181.h:30
class SquidConfig Config
Definition: SquidConfig.cc:12
void SquidUserAgent(const AccessLogEntryPointer &al, Logfile *logfile)
Display log details in useragent format.

 

Introduction

Documentation

Support

Miscellaneous

Web Site Translations

Mirrors