From 8652f8e715ea4fd25038e23fadaff4a114114efc Mon Sep 17 00:00:00 2001 From: Amos Jeffries Date: Sun, 21 Aug 2011 03:57:06 +1200 Subject: [PATCH] Bug 2279: Log Format options to log server source IP and port * Add %la and %lp to %>lp * polish log format tokens and documentation * de-duplicate tunnel.cc and forward.cc updateHierarchyInfo() code. This last is the only logic change. It involved creating hier.note() and shuffling bits of code around inside forward.cc to ensure connection setup had a single function, startConnectionOrFai(), which began the server connect process for all destination changes. --- doc/release-notes/release-3.2.sgml | 12 +++- src/cf.data.pre | 59 +++++++++++--------- src/format/Format.cc | 36 +++++++----- src/format/Tokens.cc | 41 +++++++++----- src/format/Tokens.h | 21 +++---- src/forward.cc | 90 ++++++++++-------------------- src/forward.h | 6 +- src/log/FormatSquidNative.cc | 15 +++-- src/log/access_log.cc | 6 +- src/structs.h | 1 - 10 files changed, 147 insertions(+), 140 deletions(-) diff --git a/doc/release-notes/release-3.2.sgml b/doc/release-notes/release-3.2.sgml index e67f54a51b..c7d722810e 100644 --- a/doc/release-notes/release-3.2.sgml +++ b/doc/release-notes/release-3.2.sgml @@ -546,14 +546,17 @@ This section gives a thorough account of those changes in three categories: which applies to both ICAP and eCAP.

logformat +

%<a Server or Peer IP address from the last server connection (next hop).

%>bs Number of HTTP-equivalent message body bytes received from the next hop.

icap::%>bs Number of message body bytes received from the ICAP server.

%sn Unique sequence number per log line. Ported from 2.7 -

%>eui EUI logging (EUI-48 / MAC address for IPv4, EUI-64 for IPv6) +

%>eui EUI logging (EUI-48 / MAC address for IPv4, EUI-64 for IPv6). Both EUI forms are logged in the same field. Type can be identified by length or byte delimiter. -

%err_code The ID of an error response served by Squid or - a similar internal error identifier +

%err_code The ID of an error response served by Squid or a similar internal error identifier

%err_detail Additional err_code-dependent error information. +

%>la Rename of %la to indicate being a client connection detail. +

%>lp Rename of %lp to indicate being a client connection detail. +

%<p Server or Peer port number from the last server connection (next hop). memory_pools_limit

Memory limits have been revised and corrected from 3.1.4 onwards. @@ -622,6 +625,9 @@ This section gives a thorough account of those changes in three categories: log_fqdn

Obsolete. Replaced by automatic detection of the %>A logformat tag. + log_ip_on_direct +

Obsolete. Use a custom log with %<A format tag to receive server FQDN or peer name. + maximum_single_addr_tries

The behaviour controlled by this directive is no longer possible. It has been replaced by connect_retries option which operates a little differently. diff --git a/src/cf.data.pre b/src/cf.data.pre index acbe43abca..f5fcdcaf87 100644 --- a/src/cf.data.pre +++ b/src/cf.data.pre @@ -2887,10 +2887,13 @@ DOC_START >a Client source IP address >A Client FQDN >p Client source port - >eui Client EUI (MAC address, EUI-48 or EUI-64 identifier) - eui Client source EUI (MAC address, EUI-48 or EUI-64 identifier) + >la Local IP address the client connected to + >lp Local port number the client connected to + + h Original request header. Optional header name argument on the format header[:[separator]element] @@ -2913,11 +2926,6 @@ DOC_START Optional header name argument as for >h [http::]h - [http::]un User name - [http::]ul User name from authentication - [http::]ui User name from ident - [http::]us User name from SSL - [http::]ue User name from external acl helper [http::]>Hs HTTP status code sent to the client [http::]rm Request method from client @@ -2940,8 +2946,6 @@ DOC_START [http::]rv Request protocol version [http::]>rv Request protocol version from client [http::]st Received request size including HTTP headers. In the case of chunked requests the chunked encoding metadata @@ -2959,6 +2963,11 @@ DOC_START sent to the first selected peer. The timer stops with the last I/O with the last peer. + Squid handling related format codes: + + Ss Squid request status (TCP_MISS etc) + Sh Squid hierarchy status (DEFAULT_PARENT etc) + If ICAP is enabled, the following code becomes available (as well as ICAP log codes documented with the icap_log option): @@ -2999,18 +3008,19 @@ DOC_START The default formats available (which do not need re-defining) are: -logformat squid %ts.%03tu %6tr %>a %Ss/%03>Hs %a %Ss/%03>Hs %a %ui %un [%tl] "%rm %ru HTTP/%rv" %>Hs %a %ui %un [%tl] "%rm %ru HTTP/%rv" %>Hs %h" "%{User-Agent}>h" %Ss:%Sh logformat referrer %ts.%03tu %>a %{Referer}>h %ru logformat useragent %>a [%tl] "%{User-Agent}>h" - When the log_mime_hdrs directive is set to ON. The squid, common and combined - formats have a safely encoded copy of the mime headers appended to each line - within a pair of brackets. + NOTE: When the log_mime_hdrs directive is set to ON. + The squid, common and combined formats have a safely encoded copy + of the mime headers appended to each line within a pair of brackets. + + NOTE: The common and combined formats are not quite true to the Apache definition. + The logs from Squid contain an extra status and hierarchy code appended. - The common and combined formats are not quite true to the Apache definition. - The logs from Squid contain an extra status and hierarchy code appended. DOC_END NAME: access_log cache_access_log @@ -3277,14 +3287,9 @@ DOC_START DOC_END NAME: log_ip_on_direct -COMMENT: on|off -TYPE: onoff -DEFAULT: on -LOC: Config.onoff.log_ip_on_direct +TYPE: obsolete DOC_START - Log the destination IP address in the hierarchy log tag when going - direct. Earlier Squid versions logged the hostname here. If you - prefer the old way set this to off. + Remove this option from your config. To log server or peer names use %request && al->request->clientConnectionManager.valid() && al->request->clientConnectionManager->clientConnection != NULL) { if (al->request->clientConnectionManager->clientConnection->remote.IsIPv4()) @@ -348,41 +348,51 @@ Format::Format::assemble(MemBuf &mb, AccessLogEntry *al, int logSequenceNumber) al->request->clientConnectionManager->clientConnection->remoteEui64.encode(tmp, 1024); out = tmp; } - break; +#else + out = "-"; #endif + break; - /* case LFT_SERVER_IP_ADDRESS: */ + case LFT_SERVER_IP_ADDRESS: + if (al->hier.tcpServer != NULL) { + out = al->hier.tcpServer->remote.NtoA(tmp,sizeof(tmp)); + } + break; - case LFT_SERVER_IP_OR_PEER_NAME: + case LFT_SERVER_FQDN_OR_PEER_NAME: out = al->hier.host; - break; - /* case LFT_SERVER_PORT: */ + case LFT_SERVER_PORT: + if (al->hier.tcpServer != NULL) { + outint = al->hier.tcpServer->remote.GetPort(); + doint = 1; + } + break; - case LFT_LOCAL_IP: + case LFT_CLIENT_LOCAL_IP_OLD_31: + case LFT_CLIENT_LOCAL_IP: if (al->tcpClient != NULL) { out = al->tcpClient->local.NtoA(tmp,sizeof(tmp)); } break; - case LFT_LOCAL_PORT: + case LFT_CLIENT_LOCAL_PORT_OLD_31: + case LFT_CLIENT_LOCAL_PORT: if (al->tcpClient != NULL) { outint = al->tcpClient->local.GetPort(); doint = 1; } break; - // the fmt->type can not be LFT_PEER_LOCAL_IP_OLD_27 - // but compiler complains if ommited - case LFT_PEER_LOCAL_IP_OLD_27: - case LFT_PEER_LOCAL_IP: + case LFT_SERVER_LOCAL_IP_OLD_27: + case LFT_SERVER_LOCAL_IP: if (al->hier.tcpServer != NULL) { out = al->hier.tcpServer->local.NtoA(tmp,sizeof(tmp)); } break; - case LFT_PEER_LOCAL_PORT: + case LFT_SERVER_LOCAL_PORT: if (al->hier.tcpServer != NULL) { outint = al->hier.tcpServer->local.GetPort(); doint = 1; diff --git a/src/format/Tokens.cc b/src/format/Tokens.cc index 9feed0efad..59a04c001e 100644 --- a/src/format/Tokens.cc +++ b/src/format/Tokens.cc @@ -35,21 +35,21 @@ struct Format::TokenTableEntry Format::TokenTable[] = { {">a", LFT_CLIENT_IP_ADDRESS}, {">p", LFT_CLIENT_PORT}, {">A", LFT_CLIENT_FQDN}, -#if USE_SQUID_EUI {">eui", LFT_CLIENT_EUI}, -#endif - /*{ "la", LFT_CLIENT_LOCAL_IP}, + {"la", LFT_CLIENT_LOCAL_IP_OLD_31}, + {">lp", LFT_CLIENT_LOCAL_PORT}, + {"lp", LFT_CLIENT_LOCAL_PORT_OLD_31}, /*{ "lA", LFT_LOCAL_NAME }, */ - {"la\" instead."); + type = LFT_CLIENT_LOCAL_IP; + break; + + case LFT_CLIENT_LOCAL_PORT_OLD_31: + debugs(46, 0, "WARNING: The \"lp\" formatting code is deprecated. Use the \">lp\" instead."); + type = LFT_CLIENT_LOCAL_PORT; + break; + + case LFT_SERVER_LOCAL_IP_OLD_27: debugs(46, 0, "WARNING: The \"oa\" formatting code is deprecated. Use the \"eui\" formatting code requires EUI features which are disabled in this Squid."); + break; +#endif + default: break; } diff --git a/src/format/Tokens.h b/src/format/Tokens.h index aef979551d..d79552c8e4 100644 --- a/src/format/Tokens.h +++ b/src/format/Tokens.h @@ -28,20 +28,21 @@ typedef enum { LFT_CLIENT_IP_ADDRESS, LFT_CLIENT_FQDN, LFT_CLIENT_PORT, -#if USE_SQUID_EUI LFT_CLIENT_EUI, -#endif - /*LFT_SERVER_IP_ADDRESS, */ - LFT_SERVER_IP_OR_PEER_NAME, - /*LFT_SERVER_PORT, */ + LFT_SERVER_IP_ADDRESS, + LFT_SERVER_FQDN_OR_PEER_NAME, + LFT_SERVER_PORT, - LFT_LOCAL_IP, - LFT_LOCAL_PORT, + LFT_CLIENT_LOCAL_IP, + LFT_CLIENT_LOCAL_IP_OLD_31, + LFT_CLIENT_LOCAL_PORT, + LFT_CLIENT_LOCAL_PORT_OLD_31, /*LFT_LOCAL_NAME, */ - LFT_PEER_LOCAL_IP, - LFT_PEER_LOCAL_IP_OLD_27, - LFT_PEER_LOCAL_PORT, + + LFT_SERVER_LOCAL_IP, + LFT_SERVER_LOCAL_IP_OLD_27, + LFT_SERVER_LOCAL_PORT, LFT_TIME_SECONDS_SINCE_EPOCH, LFT_TIME_SUBSECOND, diff --git a/src/forward.cc b/src/forward.cc index d258848878..15247665f6 100644 --- a/src/forward.cc +++ b/src/forward.cc @@ -285,14 +285,30 @@ FwdState::fwdStart(const Comm::ConnectionPointer &clientConn, StoreEntry *entry, void FwdState::startConnectionOrFail() { - debugs(17, 3, HERE << entry->url() ); + debugs(17, 3, HERE << entry->url()); if (serverDestinations.size() > 0) { + // Ditch error page if it was created before. + // A new one will be created if there's another problem + if (err) { + errorStateFree(err); + err = NULL; + } + + // Update the logging information about this new server connection. + // Done here before anything else so the errors get logged for + // this server link regardless of what happens when connecting to it. + // IF sucessfuly connected this top destination will become the serverConnection(). + request->hier.note(serverDestinations[0], request->GetHost()); + connectStart(); } else { - debugs(17, 3, HERE << entry->url() ); - ErrorState *anErr = errorCon(ERR_CANNOT_FORWARD, HTTP_SERVICE_UNAVAILABLE, request); - anErr->xerrno = errno; + debugs(17, 3, HERE << entry->url()); + ErrorState *anErr = NULL; + if (err) { + anErr = errorCon(ERR_CANNOT_FORWARD, HTTP_INTERNAL_SERVER_ERROR, request); + anErr->xerrno = errno; + } // else use actual error from last connection attempt fail(anErr); self = NULL; // refcounted } @@ -355,7 +371,6 @@ FwdState::complete() logReplyStatus(n_tries, entry->getReply()->sline.status); if (reforward()) { - assert(serverDestinations.size() > 0); debugs(17, 3, HERE << "re-forwarding " << entry->getReply()->sline.status << " " << entry->url()); if (Comm::IsConnOpen(serverConn)) @@ -363,10 +378,10 @@ FwdState::complete() entry->reset(); - /* the call to reforward() has already dropped the last path off the - * selection list. all we have now are the next path(s) to be tried. - */ - connectStart(); + // drop the last path off the selection list. try the next one. + serverDestinations.shift(); + startConnectionOrFail(); + } else { if (Comm::IsConnOpen(serverConn)) debugs(17, 3, HERE << "server FD " << serverConnection()->fd << " not re-forwarding status " << entry->getReply()->sline.status); @@ -523,27 +538,9 @@ FwdState::retryOrBail() { if (checkRetry()) { debugs(17, 3, HERE << "re-forwarding (" << n_tries << " tries, " << (squid_curtime - start_t) << " secs)"); - serverDestinations.shift(); // last one failed. try another. - - if (serverDestinations.size() > 0) { - /* Ditch error page if it was created before. - * A new one will be created if there's another problem */ - if (err) { - errorStateFree(err); - err = NULL; - } - - connectStart(); - return; - } - // else bail. no more serverDestinations possible to try. - - // produce cannot-forward error, but only if no more specific one exists - if (!err) { - ErrorState *anErr = errorCon(ERR_CANNOT_FORWARD, HTTP_INTERNAL_SERVER_ERROR, request); - errorAppendEntry(entry, anErr); - } + startConnectionOrFail(); + return; } // TODO: should we call completed() here and move doneWithRetries there? @@ -735,8 +732,6 @@ FwdState::connectDone(const Comm::ConnectionPointer &conn, comm_err_t status, in if (serverConnection()->getPeer()) peerConnectSucceded(serverConnection()->getPeer()); - updateHierarchyInfo(); - #if USE_SSL if ((serverConnection()->getPeer() && serverConnection()->getPeer()->use_ssl) || (!serverConnection()->getPeer() && request->protocol == AnyP::PROTO_HTTPS)) { @@ -756,9 +751,6 @@ FwdState::connectTimeout(int fd) assert(serverDestinations[0] != NULL); assert(fd == serverDestinations[0]->fd); - if (Config.onoff.log_ip_on_direct && serverDestinations[0]->peerType == HIER_DIRECT) - updateHierarchyInfo(); - if (entry->isEmpty()) { ErrorState *anErr = errorCon(ERR_CONNECT_FAIL, HTTP_GATEWAY_TIMEOUT, request); anErr->xerrno = ETIMEDOUT; @@ -830,7 +822,6 @@ FwdState::connectStart() request->flags.pinned = 1; if (pinned_connection->pinnedAuth()) request->flags.auth = 1; - updateHierarchyInfo(); dispatch(); return; } @@ -859,7 +850,6 @@ FwdState::connectStart() if (!serverConnection()->getPeer()) origin_tries++; - updateHierarchyInfo(); comm_add_close_handler(serverConnection()->fd, fwdServerClosedWrapper, this); /* Update server side TOS and Netfilter mark on the connection. */ @@ -1050,9 +1040,8 @@ FwdState::reforward() if (request->bodyNibbled()) return 0; - serverDestinations.shift(); - - if (serverDestinations.size() == 0) { + if (serverDestinations.size() <= 1) { + // NP: <= 1 since total count includes the recently failed one. debugs(17, 3, HERE << "No alternative forwarding paths left"); return 0; } @@ -1173,29 +1162,6 @@ FwdState::logReplyStatus(int tries, http_status status) FwdReplyCodes[tries][status]++; } -/** From Comment #5 by Henrik Nordstrom made at -http://www.squid-cache.org/bugs/show_bug.cgi?id=2391 on 2008-09-19 - -updateHierarchyInfo should be called each time a new path has been -selected or when more information about the path is available (i.e. the -server IP), and when it's called it needs to be given reasonable -arguments describing the now selected path.. - -It does not matter from a functional perspective if it gets called a few -times more than what is really needed, but calling it too often may -obviously hurt performance. -*/ -// updates HierarchyLogEntry, guessing nextHop and its format -void -FwdState::updateHierarchyInfo() -{ - assert(request); - assert(serverDestinations.size() > 0); - - request->hier.note(serverConnection(), request->GetHost()); -} - - /**** PRIVATE NON-MEMBER FUNCTIONS ********************************************/ /* diff --git a/src/forward.h b/src/forward.h index 19630e50c6..01cd931f21 100644 --- a/src/forward.h +++ b/src/forward.h @@ -33,7 +33,12 @@ public: static void initModule(); static void fwdStart(const Comm::ConnectionPointer &client, StoreEntry *, HttpRequest *); + + /// This is the real beginning of server connection. Call it whenever + /// the forwarding server destination has changed and a new one needs to be opened. + /// Produces the cannot-forward error on fail if no better error exists. void startConnectionOrFail(); + void fail(ErrorState *err); void unregister(Comm::ConnectionPointer &conn); void unregister(int fd); @@ -65,7 +70,6 @@ private: void start(Pointer aSelf); static void logReplyStatus(int tries, http_status status); - void updateHierarchyInfo(); void doneWithRetries(); void completed(); void retryOrBail(); diff --git a/src/log/FormatSquidNative.cc b/src/log/FormatSquidNative.cc index 8325eaad5a..55ac703cd5 100644 --- a/src/log/FormatSquidNative.cc +++ b/src/log/FormatSquidNative.cc @@ -43,10 +43,9 @@ void Log::Format::SquidNative(AccessLogEntry * al, Logfile * logfile) { - const char *user = NULL; - char clientip[MAX_IPSTRLEN]; + char hierHost[MAX_IPSTRLEN]; - user = ::Format::QuoteUrlEncodeUsername(al->cache.authuser); + const char *user = ::Format::QuoteUrlEncodeUsername(al->cache.authuser); if (!user) user = ::Format::QuoteUrlEncodeUsername(al->cache.extuser); @@ -62,11 +61,17 @@ Log::Format::SquidNative(AccessLogEntry * al, Logfile * logfile) if (user && !*user) safe_free(user); + char clientip[MAX_IPSTRLEN]; + if (al->tcpClient != NULL) + al->tcpClient->remote.NtoA(clientip, sizeof(clientip)); + else + al->cache.caddr.NtoA(clientip, sizeof(clientip)); + logfilePrintf(logfile, "%9ld.%03d %6d %s %s%s/%03d %"PRId64" %s %s %s %s%s/%s %s%s", (long int) current_time.tv_sec, (int) current_time.tv_usec / 1000, al->cache.msec, - al->cache.caddr.NtoA(clientip, MAX_IPSTRLEN), + clientip, ::Format::log_tags[al->cache.code], al->http.statusSfx(), al->http.code, @@ -76,7 +81,7 @@ Log::Format::SquidNative(AccessLogEntry * al, Logfile * logfile) user ? user : dash_str, al->hier.ping.timedout ? "TIMEOUT_" : "", hier_code_str[al->hier.code], - al->hier.host, + al->hier.tcpServer != NULL ? al->hier.tcpServer->remote.NtoA(hierHost, sizeof(hierHost)) : "-", al->http.content_type, (Config.onoff.log_mime_hdrs?"":"\n")); diff --git a/src/log/access_log.cc b/src/log/access_log.cc index 35cfbe955c..f3df330fc6 100644 --- a/src/log/access_log.cc +++ b/src/log/access_log.cc @@ -285,11 +285,7 @@ HierarchyLogEntry::note(const Comm::ConnectionPointer &server, const char *reque // went to peer, log peer host name xstrncpy(host, tcpServer->getPeer()->name, sizeof(host)); } else { - // went DIRECT, must honor log_ip_on_direct - if (!Config.onoff.log_ip_on_direct) - xstrncpy(host, requestedHost, sizeof(host)); - else - tcpServer->remote.NtoA(host, 256); + xstrncpy(host, requestedHost, sizeof(host)); } } } diff --git a/src/structs.h b/src/structs.h index 69d1a7ab0b..c485816841 100644 --- a/src/structs.h +++ b/src/structs.h @@ -407,7 +407,6 @@ struct SquidConfig { int digest_generation; #endif - int log_ip_on_direct; int ie_refresh; int vary_ignore_expire; int pipeline_prefetch; -- 2.47.3