access_log.cc
Go to the documentation of this file.
1 /*
2  * Copyright (C) 1996-2022 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 "Store.h"
38 
39 #if USE_SQUID_EUI
40 #include "eui/Eui48.h"
41 #include "eui/Eui64.h"
42 #endif
43 
44 #include <unordered_map>
45 
46 #if HEADERS_LOG
47 static Logfile *headerslog = NULL;
48 #endif
49 
50 #if MULTICAST_MISS_STREAM
51 static int mcast_miss_fd = -1;
52 
53 static struct sockaddr_in mcast_miss_to;
54 static void mcast_encode(unsigned int *, size_t, const unsigned int *);
55 #endif
56 
57 #if USE_FORW_VIA_DB
58 
59 using HeaderValueCountsElement = std::pair<const SBuf, uint64_t>;
61 using HeaderValueCounts = std::unordered_map<SBuf, uint64_t, std::hash<SBuf>, std::equal_to<SBuf>, PoolingAllocator<HeaderValueCountsElement> >;
62 
64 static HeaderValueCounts TheViaCounts;
66 static HeaderValueCounts TheForwardedCounts;
67 
68 static OBJH fvdbDumpVia;
69 static OBJH fvdbDumpForwarded;
70 static void fvdbClear(void);
71 static void fvdbRegisterWithCacheManager();
72 #endif
73 
75 
76 void
78 {
79 
80  if (al->url.isEmpty())
81  al->url = Format::Dash;
82 
83  if (!al->http.content_type || *al->http.content_type == '\0')
84  al->http.content_type = dash_str;
85 
86  if (al->hier.host[0] == '\0')
87  xstrncpy(al->hier.host, dash_str, SQUIDHOSTNAMELEN);
88 
89  for (; log; log = log->next) {
90  if (log->aclList && checklist && !checklist->fastCheck(log->aclList).allowed())
91  continue;
92 
93  // The special-case "none" type has no logfile object set
94  if (log->type == Log::Format::CLF_NONE)
95  return;
96 
97  if (log->logfile) {
98  logfileLineStart(log->logfile);
99 
100  switch (log->type) {
101 
103  Log::Format::SquidNative(al, log->logfile);
104  break;
105 
107  Log::Format::HttpdCombined(al, log->logfile);
108  break;
109 
111  Log::Format::HttpdCommon(al, log->logfile);
112  break;
113 
115  Log::Format::SquidReferer(al, log->logfile);
116  break;
117 
119  Log::Format::SquidUserAgent(al, log->logfile);
120  break;
121 
124  break;
125 
126 #if ICAP_CLIENT
128  Log::Format::SquidIcap(al, log->logfile);
129  break;
130 #endif
131 
132  default:
133  fatalf("Unknown log format %d\n", log->type);
134  break;
135  }
136 
137  logfileLineEnd(log->logfile);
138  }
139 
140  // NP: WTF? if _any_ log line has no checklist ignore the following ones?
141  if (!checklist)
142  break;
143  }
144 }
145 
146 void
148 {
149  if (LogfileStatus != LOG_ENABLE)
150  return;
151 
152  accessLogLogTo(Config.Log.accesslogs, al, checklist);
153 #if MULTICAST_MISS_STREAM
154 
155  if (al->cache.code != LOG_TCP_MISS)
156  (void) 0;
157  else if (al->http.method != METHOD_GET)
158  (void) 0;
159  else if (mcast_miss_fd < 0)
160  (void) 0;
161  else {
162  unsigned int ibuf[365];
163  size_t isize;
164  xstrncpy((char *) ibuf, al->url.c_str(), 364 * sizeof(int));
165  isize = ((al->url.length() + 8) / 8) * 2;
166 
167  if (isize > 364)
168  isize = 364;
169 
170  mcast_encode((unsigned int *) ibuf, isize,
171  (const unsigned int *) Config.mcast_miss.encode_key);
172 
174  &mcast_miss_to, sizeof(mcast_miss_to),
175  ibuf, isize * sizeof(int));
176  }
177 
178 #endif
179 }
180 
181 void
183 {
184  CustomLog *log;
185 #if USE_FORW_VIA_DB
186 
187  fvdbClear();
188 #endif
189 
190  for (log = Config.Log.accesslogs; log; log = log->next) {
191  log->rotate();
192  }
193 
194 #if HEADERS_LOG
195 
196  logfileRotate(headerslog, Config.Log.rotateNumber);
197 
198 #endif
199 }
200 
201 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 
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  clearPeerNotes();
241 
242  totalResponseTime_.tv_sec = -1;
243  totalResponseTime_.tv_usec = 0;
244 
245  firstConnStart_.tv_sec = 0;
246  firstConnStart_.tv_usec = 0;
247 }
248 
249 void
251 {
252  clearPeerNotes();
253 
254  tcpServer = server;
255  if (tcpServer == NULL) {
256  code = HIER_NONE;
257  xstrncpy(host, requestedHost, sizeof(host));
258  } else {
260 
261  if (tcpServer->getPeer()) {
262  // went to peer, log peer host name
263  xstrncpy(host, tcpServer->getPeer()->name, sizeof(host));
264  } else {
265  xstrncpy(host, requestedHost, sizeof(host));
266  }
267  }
268 }
269 
271 void
273 {
274  peer_last_read_.tv_sec = 0;
275  peer_last_read_.tv_usec = 0;
276 
277  peer_last_write_.tv_sec = 0;
278  peer_last_write_.tv_usec = 0;
279 
280  bodyBytesRead = -1;
281 }
282 
283 void
285 {
287 }
288 
289 void
291 {
293 }
294 
295 void
297 {
298  if (!firstConnStart_.tv_sec)
300 }
301 
302 void
304 {
305  debugs(46, 5, "First connection started: " << firstConnStart_ <<
306  ", current total response time value: " << (totalResponseTime_.tv_sec * 1000 + totalResponseTime_.tv_usec/1000) <<
307  (force ? ", force fixing" : ""));
308  if (!force && totalResponseTime_.tv_sec != -1)
309  return;
310 
311  if (firstConnStart_.tv_sec)
313 }
314 
315 bool
316 HierarchyLogEntry::peerResponseTime(struct timeval &responseTime)
317 {
318  // no I/O whatsoever
319  if (peer_last_write_.tv_sec <= 0 && peer_last_read_.tv_sec <= 0)
320  return false;
321 
322  // accommodate read without (completed) write
323  const auto last_write = peer_last_write_.tv_sec > 0 ?
325 
326  // accommodate write without (completed) read
327  const auto last_read = peer_last_read_.tv_sec > 0 ?
329 
330  tvSub(responseTime, last_write, last_read);
331  // The peer response time (%<pt) stopwatch is currently defined to start
332  // when we wrote the entire request. Thus, if we wrote something after the
333  // last read, report zero peer response time.
334  if (responseTime.tv_sec < 0) {
335  responseTime.tv_sec = 0;
336  responseTime.tv_usec = 0;
337  }
338 
339  return true;
340 }
341 
342 bool
343 HierarchyLogEntry::totalResponseTime(struct timeval &responseTime)
344 {
345  // This should not really happen, but there may be rare code
346  // paths that lead to FwdState discarded (or transaction logged)
347  // without (or before) a stopPeerClock() call.
348  if (firstConnStart_.tv_sec && totalResponseTime_.tv_sec == -1)
349  stopPeerClock(false);
350 
351  responseTime = totalResponseTime_;
352  return responseTime.tv_sec >= 0 && responseTime.tv_usec >= 0;
353 }
354 
355 static void
357 {
358 #if USE_FORW_VIA_DB
359  fvdbRegisterWithCacheManager();
360 #endif
361 }
362 
363 void
365 {
366  CustomLog *log;
367 
369 
370 #if USE_ADAPTATION
372 #endif
373 #if ICAP_CLIENT
375 #endif
376 
377  for (log = Config.Log.accesslogs; log; log = log->next) {
378  if (log->type == Log::Format::CLF_NONE)
379  continue;
380 
381  log->logfile = logfileOpen(log->filename, log->bufferSize, log->fatal);
382 
384 
385 #if USE_ADAPTATION
386  for (Format::Token * curr_token = (log->logFormat?log->logFormat->format:NULL); curr_token; curr_token = curr_token->next) {
387  if (curr_token->type == Format::LFT_ADAPTATION_SUM_XACT_TIMES ||
388  curr_token->type == Format::LFT_ADAPTATION_ALL_XACT_TIMES ||
389  curr_token->type == Format::LFT_ADAPTATION_LAST_HEADER ||
390  curr_token->type == Format::LFT_ADAPTATION_LAST_HEADER_ELEM ||
391  curr_token->type == Format::LFT_ADAPTATION_LAST_ALL_HEADERS||
392  (curr_token->type == Format::LFT_NOTE && !Adaptation::Config::metaHeaders.empty())) {
394  }
395 #if ICAP_CLIENT
396  if (curr_token->type == Format::LFT_ICAP_TOTAL_TIME) {
398  }
399 #endif
400  }
401 #endif
402  }
403 
404 #if HEADERS_LOG
405 
406  headerslog = logfileOpen("/usr/local/squid/logs/headers.log", 512);
407 
408  assert(NULL != headerslog);
409 
410 #endif
411 #if MULTICAST_MISS_STREAM
412 
413  if (Config.mcast_miss.addr.s_addr != no_addr.s_addr) {
414  memset(&mcast_miss_to, '\0', sizeof(mcast_miss_to));
415  mcast_miss_to.sin_family = AF_INET;
416  mcast_miss_to.sin_port = htons(Config.mcast_miss.port);
417  mcast_miss_to.sin_addr.s_addr = Config.mcast_miss.addr.s_addr;
418  mcast_miss_fd = comm_open(SOCK_DGRAM,
419  IPPROTO_UDP,
423  "Multicast Miss Stream");
424 
425  if (mcast_miss_fd < 0)
426  fatal("Cannot open Multicast Miss Stream Socket");
427 
428  debugs(46, DBG_IMPORTANT, "Multicast Miss Stream Socket opened on FD " << mcast_miss_fd);
429 
431 
432  if (strlen(Config.mcast_miss.encode_key) < 16)
433  fatal("mcast_encode_key is too short, must be 16 characters");
434  }
435 
436 #endif
437 }
438 
439 #if USE_FORW_VIA_DB
440 
441 static void
442 fvdbRegisterWithCacheManager(void)
443 {
444  Mgr::RegisterAction("via_headers", "Via Request Headers", fvdbDumpVia, 0, 1);
445  Mgr::RegisterAction("forw_headers", "X-Forwarded-For Request Headers",
446  fvdbDumpForwarded, 0, 1);
447 }
448 
449 void
450 fvdbCountVia(const SBuf &headerValue)
451 {
452  ++TheViaCounts[headerValue];
453 }
454 
455 void
456 fvdbCountForwarded(const SBuf &key)
457 {
458  ++TheForwardedCounts[key];
459 }
460 
461 static void
462 fvdbDumpCounts(StoreEntry &e, const HeaderValueCounts &counts)
463 {
464  PackableStream os(e);
465  for (const auto &i : counts)
466  os << std::setw(9) << i.second << ' ' << i.first << "\n";
467 }
468 
469 static void
470 fvdbDumpVia(StoreEntry * e)
471 {
472  assert(e);
473  fvdbDumpCounts(*e, TheViaCounts);
474 }
475 
476 static void
477 fvdbDumpForwarded(StoreEntry * e)
478 {
479  assert(e);
480  fvdbDumpCounts(*e, TheForwardedCounts);
481 }
482 
483 static void
484 fvdbClear(void)
485 {
486  TheViaCounts.clear();
487  TheForwardedCounts.clear();
488 }
489 
490 #endif
491 
492 #if MULTICAST_MISS_STREAM
493 /*
494  * From http://www.io.com/~paulhart/game/algorithms/tea.html
495  *
496  * size of 'ibuf' must be a multiple of 2.
497  * size of 'key' must be 4.
498  * 'ibuf' is modified in place, encrypted data is written in
499  * network byte order.
500  */
501 static void
502 mcast_encode(unsigned int *ibuf, size_t isize, const unsigned int *key)
503 {
504  unsigned int y;
505  unsigned int z;
506  unsigned int sum;
507  const unsigned int delta = 0x9e3779b9;
508  unsigned int n = 32;
509  const unsigned int k0 = htonl(key[0]);
510  const unsigned int k1 = htonl(key[1]);
511  const unsigned int k2 = htonl(key[2]);
512  const unsigned int k3 = htonl(key[3]);
513  int i;
514 
515  for (i = 0; i < isize; i += 2) {
516  y = htonl(ibuf[i]);
517  z = htonl(ibuf[i + 1]);
518  sum = 0;
519 
520  for (n = 32; n; --n) {
521  sum += delta;
522  y += (z << 4) + (k0 ^ z) + (sum ^ (z >> 5)) + k1;
523  z += (y << 4) + (k2 ^ y) + (sum ^ (y >> 5)) + k3;
524  }
525 
526  ibuf[i] = htonl(y);
527  ibuf[i + 1] = htonl(z);
528  }
529 }
530 
531 #endif
532 
533 #if HEADERS_LOG
534 void
535 headersLog(int cs, int pq, const HttpRequestMethod& method, void *data)
536 {
537  HttpReply *rep;
538  HttpRequest *req;
539  unsigned short magic = 0;
540  unsigned char M = (unsigned char) m;
541  char *hmask;
542  int ccmask = 0;
543 
544  if (0 == pq) {
545  /* reply */
546  rep = data;
547  req = NULL;
548  magic = 0x0050;
549  hmask = rep->header.mask;
550 
551  if (rep->cache_control)
552  ccmask = rep->cache_control->mask;
553  } else {
554  /* request */
555  req = data;
556  rep = NULL;
557  magic = 0x0051;
558  hmask = req->header.mask;
559 
560  if (req->cache_control)
561  ccmask = req->cache_control->mask;
562  }
563 
564  if (0 == cs) {
565  /* client */
566  magic |= 0x4300;
567  } else {
568  /* server */
569  magic |= 0x5300;
570  }
571 
572  magic = htons(magic);
573  ccmask = htonl(ccmask);
574 
575  unsigned short S = 0;
576  if (0 == pq)
577  S = static_cast<unsigned short>(rep->sline.status());
578 
579  logfileWrite(headerslog, &magic, sizeof(magic));
580  logfileWrite(headerslog, &M, sizeof(M));
581  logfileWrite(headerslog, &S, sizeof(S));
582  logfileWrite(headerslog, hmask, sizeof(HttpHeaderMask));
583  logfileWrite(headerslog, &ccmask, sizeof(int));
584 }
585 
586 #endif
587 
void fatal(const char *message)
Definition: fatal.cc:28
void accessLogLogTo(CustomLog *log, const AccessLogEntryPointer &al, ACLChecklist *checklist)
Definition: access_log.cc:77
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:51
struct SquidConfig::@101 Log
@ 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:303
@ scNone
Definition: StatusCode.h:21
HttpHeader header
Definition: Message.h:75
static void accessLogRegisterWithCacheManager(void)
Definition: access_log.cc:356
void log(char *format,...)
HttpHeaderMask mask
Definition: HttpHeader.h:172
struct SquidConfig::@105 Addrs
static struct sockaddr_in mcast_miss_to
Definition: access_log.cc:53
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:890
@ CLF_COMBINED
Definition: Formats.h:28
Definition: SBuf.h:87
#define LOG_DISABLE
Definition: defines.h:63
void accessLogClose(void)
Definition: access_log.cc:202
CustomLog * accesslogs
Definition: SquidConfig.h:184
Ip::Address addr
Definition: SquidConfig.h:469
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:74
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:147
@ LFT_ICAP_TOTAL_TIME
Definition: ByteCode.h:192
char * name
Definition: CachePeer.h:39
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:472
struct timeval totalResponseTime_
cumulative for all peers
void clearPeerNotes()
forget previous notePeerRead() and notePeerWrite() calls (if any)
Definition: access_log.cc:272
@ CLF_ICAP_SQUID
Definition: Formats.h:32
bool hasIcapToken
Definition: Config.h:53
struct timeval current_time
the current UNIX time in timeval {seconds, microseconds} format
Definition: gadgets.cc:17
@ CLF_SQUID
Definition: Formats.h:35
char cd_host[SQUIDHOSTNAMELEN]
struct timeval store_complete_stop
void OBJH(StoreEntry *)
Definition: forward.h:44
#define NULL
Definition: types.h:166
@ CLF_REFERER
Definition: Formats.h:34
@ 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
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:316
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:296
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
int comm_open(int sock_type, int proto, Ip::Address &addr, int flags, const char *note)
Definition: comm.cc:223
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
bool allowed() const
Definition: Acl.h:149
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.
#define DBG_IMPORTANT
Definition: Stream.h:41
static void mcast_encode(unsigned int *, size_t, const unsigned int *)
Definition: access_log.cc:502
void resetPeerNotes(const Comm::ConnectionPointer &server, const char *requestedHost)
Definition: access_log.cc:250
char host[SQUIDHOSTNAMELEN]
bool totalResponseTime(struct timeval &responseTime)
Definition: access_log.cc:343
void logfileLineEnd(Logfile *lf)
Definition: File.cc:132
@ LFT_NOTE
Definition: ByteCode.h:236
void accessLogInit(void)
Definition: access_log.cc:364
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:182
#define debugs(SECTION, LEVEL, CONTENT)
Definition: Stream.h:196
const SBuf Dash
#define SQUIDHOSTNAMELEN
Definition: rfc2181.h:30
void tvSub(struct timeval &res, struct timeval const &t1, struct timeval const &t2)
Definition: gadgets.cc:58
class SquidConfig Config
Definition: SquidConfig.cc:12
struct SquidConfig::@117 mcast_miss
void SquidUserAgent(const AccessLogEntryPointer &al, Logfile *logfile)
Display log details in useragent format.

 

Introduction

Documentation

Support

Miscellaneous

Web Site Translations

Mirrors