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
47static Logfile *headerslog = NULL;
48#endif
49
50#if MULTICAST_MISS_STREAM
51static int mcast_miss_fd = -1;
52
53static struct sockaddr_in mcast_miss_to;
54static void mcast_encode(unsigned int *, size_t, const unsigned int *);
55#endif
56
57#if USE_FORW_VIA_DB
58
59using HeaderValueCountsElement = std::pair<const SBuf, uint64_t>;
61using HeaderValueCounts = std::unordered_map<SBuf, uint64_t, std::hash<SBuf>, std::equal_to<SBuf>, PoolingAllocator<HeaderValueCountsElement> >;
62
64static HeaderValueCounts TheViaCounts;
66static HeaderValueCounts TheForwardedCounts;
67
68static OBJH fvdbDumpVia;
69static OBJH fvdbDumpForwarded;
70static void fvdbClear(void);
71static void fvdbRegisterWithCacheManager();
72#endif
73
75
76void
78{
79
80 if (al->url.isEmpty())
81 al->url = Format::Dash;
82
83 if (!al->http.content_type || *al->http.content_type == '\0')
85
86 if (al->hier.host[0] == '\0')
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
146void
148{
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
175 ibuf, isize * sizeof(int));
176 }
177
178#endif
179}
180
181void
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
197
198#endif
199}
200
201void
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 = nullptr;
210 }
211 }
212
213#if HEADERS_LOG
214
215 logfileClose(headerslog);
216
217 headerslog = NULL;
218
219#endif
220}
221
224 cd_lookup(LOOKUP_NONE),
225 n_choices(0),
226 n_ichoices(0),
227 peer_reply_status(Http::scNone),
228 tcpServer(nullptr),
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
241
242 totalResponseTime_.tv_sec = -1;
243 totalResponseTime_.tv_usec = 0;
244
245 firstConnStart_.tv_sec = 0;
246 firstConnStart_.tv_usec = 0;
247}
248
249void
251{
253
255 if (tcpServer == nullptr) {
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
271void
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
283void
285{
287}
288
289void
291{
293}
294
295void
297{
298 if (!firstConnStart_.tv_sec)
300}
301
302void
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
315bool
316HierarchyLogEntry::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
342bool
343HierarchyLogEntry::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
355static void
357{
358#if USE_FORW_VIA_DB
359 fvdbRegisterWithCacheManager();
360#endif
361}
362
363void
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:nullptr); 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
441static void
442fvdbRegisterWithCacheManager(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
449void
450fvdbCountVia(const SBuf &headerValue)
451{
452 ++TheViaCounts[headerValue];
453}
454
455void
456fvdbCountForwarded(const SBuf &key)
457{
458 ++TheForwardedCounts[key];
459}
460
461static void
462fvdbDumpCounts(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
469static void
470fvdbDumpVia(StoreEntry * e)
471{
472 assert(e);
473 fvdbDumpCounts(*e, TheViaCounts);
474}
475
476static void
477fvdbDumpForwarded(StoreEntry * e)
478{
479 assert(e);
480 fvdbDumpCounts(*e, TheForwardedCounts);
481}
482
483static void
484fvdbClear(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 */
501static void
502mcast_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
534void
535headersLog(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
#define COMM_NONBLOCKING
Definition: Connection.h:46
char HttpHeaderMask[12]
@ LOG_TCP_MISS
Definition: LogTags.h:40
class SquidConfig Config
Definition: SquidConfig.cc:12
void accessLogInit(void)
Definition: access_log.cc:364
void accessLogLog(const AccessLogEntryPointer &al, ACLChecklist *checklist)
Definition: access_log.cc:147
void accessLogClose(void)
Definition: access_log.cc:202
static int mcast_miss_fd
Definition: access_log.cc:51
void accessLogLogTo(CustomLog *log, const AccessLogEntryPointer &al, ACLChecklist *checklist)
Definition: access_log.cc:77
static void accessLogRegisterWithCacheManager(void)
Definition: access_log.cc:356
int LogfileStatus
Definition: access_log.cc:74
void accessLogRotate(void)
Definition: access_log.cc:182
static struct sockaddr_in mcast_miss_to
Definition: access_log.cc:53
static void mcast_encode(unsigned int *, size_t, const unsigned int *)
Definition: access_log.cc:502
void fvdbCountVia(const SBuf &)
void fvdbCountForwarded(const SBuf &)
count occurrences of the given X-Forwarded-For header value
void log(char *format,...)
#define assert(EX)
Definition: assert.h:19
static char server[MAXLINE]
Acl::Answer const & fastCheck()
Definition: Checklist.cc:332
HttpRequestMethod method
class AccessLogEntry::CacheDetails cache
HierarchyLogEntry hier
class AccessLogEntry::HttpDetails http
bool allowed() const
Definition: Acl.h:150
static Notes metaHeaders
The list of configured meta headers.
Definition: Config.h:58
char * name
Definition: CachePeer.h:39
hier_code peerType
Definition: Connection.h:152
CachePeer * getPeer() const
Definition: Connection.cc:124
Token * next
Definition: Token.h:71
char host[SQUIDHOSTNAMELEN]
struct timeval peer_select_start
void clearPeerNotes()
forget previous notePeerRead() and notePeerWrite() calls (if any)
Definition: access_log.cc:272
struct timeval peer_last_write_
time of the last write to the last peer
bool totalResponseTime(struct timeval &responseTime)
Definition: access_log.cc:343
struct timeval store_complete_stop
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.
timeval firstConnStart_
first connection use among all peers
char cd_host[SQUIDHOSTNAMELEN]
bool peerResponseTime(struct timeval &responseTime)
Definition: access_log.cc:316
struct timeval totalResponseTime_
cumulative for all peers
struct timeval peer_last_read_
time of the last read from the last peer
void startPeerClock()
Start recording total time spent communicating with peers.
Definition: access_log.cc:296
void stopPeerClock(const bool force)
Definition: access_log.cc:303
void resetPeerNotes(const Comm::ConnectionPointer &server, const char *requestedHost)
Definition: access_log.cc:250
int32_t mask
Definition: HttpHdrCc.h:173
HttpHeaderMask mask
Definition: HttpHeader.h:170
Http::StatusLine sline
Definition: HttpReply.h:56
HttpHeader header
Definition: Message.h:74
HttpHdrCc * cache_control
Definition: Message.h:76
Http::StatusCode status() const
retrieve the status code for this status line
Definition: StatusLine.h:45
bool hasIcapToken
Definition: Config.h:53
bool hasAdaptToken
Definition: Config.h:49
Definition: File.h:39
bool empty() const
Definition: Notes.h:139
STL Allocator that uses Squid memory pools for memory management.
Definition: SBuf.h:94
const char * c_str()
Definition: SBuf.cc:516
size_type length() const
Returns the number of bytes stored in SBuf.
Definition: SBuf.h:415
bool isEmpty() const
Definition: SBuf.h:431
CustomLog * accesslogs
Definition: SquidConfig.h:184
Ip::Address addr
Definition: SquidConfig.h:461
struct SquidConfig::@106 Addrs
Ip::Address udp_incoming
Definition: SquidConfig.h:233
struct SquidConfig::@118 mcast_miss
char * encode_key
Definition: SquidConfig.h:464
unsigned short port
Definition: SquidConfig.h:463
struct SquidConfig::@103 Log
int rotateNumber
Definition: SquidConfig.h:189
int comm_udp_sendto(int fd, const Ip::Address &to_addr, const void *buf, int len)
Definition: comm.cc:916
int comm_open(int sock_type, int proto, Ip::Address &addr, int flags, const char *note)
Definition: comm.cc:241
#define DBG_IMPORTANT
Definition: Stream.h:41
#define debugs(SECTION, LEVEL, CONTENT)
Definition: Stream.h:196
#define LOG_DISABLE
Definition: defines.h:63
#define LOG_ENABLE
Definition: defines.h:62
void fatal(const char *message)
Definition: fatal.cc:28
void fatalf(const char *fmt,...)
Definition: fatal.cc:68
const char * dash_str
@ HIER_NONE
Definition: hier_code.h:13
unsigned char code
Definition: html_quote.c:20
void logfileLineEnd(Logfile *lf)
Definition: File.cc:132
void logfileWrite(Logfile *lf, const char *buf, size_t len)
Definition: File.cc:108
void logfileRotate(Logfile *lf, int16_t rotateCount)
Definition: File.cc:101
void logfileLineStart(Logfile *lf)
Definition: File.cc:126
void logfileClose(Logfile *lf)
Definition: File.cc:92
Logfile * logfileOpen(const char *path, size_t bufsz, int fatal_flag)
Definition: File.cc:40
@ LOOKUP_NONE
Definition: lookup_t.h:13
void OBJH(StoreEntry *)
Definition: forward.h:44
int mcastSetTtl(int fd, int mcast_ttl)
Definition: multicast.cc:20
const SBuf Dash
@ LFT_ICAP_TOTAL_TIME
Definition: ByteCode.h:192
@ LFT_NOTE
Definition: ByteCode.h:236
@ LFT_ADAPTATION_SUM_XACT_TIMES
Definition: ByteCode.h:183
@ LFT_ADAPTATION_LAST_HEADER
Definition: ByteCode.h:185
@ LFT_ADAPTATION_LAST_ALL_HEADERS
Definition: ByteCode.h:187
@ LFT_ADAPTATION_LAST_HEADER_ELEM
Definition: ByteCode.h:186
@ LFT_ADAPTATION_ALL_XACT_TIMES
Definition: ByteCode.h:184
Definition: forward.h:22
@ scNone
Definition: StatusCode.h:21
@ METHOD_GET
Definition: MethodType.h:25
void HttpdCombined(const AccessLogEntryPointer &al, Logfile *logfile)
Log with Apache httpd combined format.
void SquidCustom(const AccessLogEntryPointer &al, CustomLog *log)
Log with a local custom format.
void SquidIcap(const AccessLogEntryPointer &al, Logfile *logfile)
Display log details in Squid ICAP format.
void SquidUserAgent(const AccessLogEntryPointer &al, Logfile *logfile)
Display log details in useragent format.
@ CLF_COMBINED
Definition: Formats.h:28
@ CLF_ICAP_SQUID
Definition: Formats.h:32
@ CLF_COMMON
Definition: Formats.h:29
@ CLF_USERAGENT
Definition: Formats.h:36
@ CLF_SQUID
Definition: Formats.h:35
@ CLF_REFERER
Definition: Formats.h:34
@ CLF_NONE
Definition: Formats.h:37
@ CLF_CUSTOM
Definition: Formats.h:30
void HttpdCommon(const AccessLogEntryPointer &al, Logfile *logfile)
Log with Apache httpd common format.
void SquidNative(const AccessLogEntryPointer &al, Logfile *logfile)
Native Squid Format Display.
void SquidReferer(const AccessLogEntryPointer &al, Logfile *logfile)
Display log details in Squid old refererlog format.
LogConfig TheConfig
Definition: Config.cc:15
void RegisterAction(char const *action, char const *desc, OBJH *handler, int pw_req_flag, int atomic)
Definition: Registration.cc:16
#define SQUIDHOSTNAMELEN
Definition: rfc2181.h:30
static StoreRebuildData counts
void tvSub(struct timeval &res, struct timeval const &t1, struct timeval const &t2)
Definition: gadgets.cc:58
struct timeval current_time
the current UNIX time in timeval {seconds, microseconds} format
Definition: gadgets.cc:17
#define NULL
Definition: types.h:166
char * xstrncpy(char *dst, const char *src, size_t n)
Definition: xstring.cc:37

 

Introduction

Documentation

Support

Miscellaneous

Web Site Translations

Mirrors