Log TOS and Netfilter marks set by Squid

This patch add new logformat codes to log TOS/DSCP values and netfilter marks
for client and server connections. If multiple outgoing connections were used,
the last used connection value logged.
The values printed in hexadecimal form.
The logformat codes are:
   %>qos    Client connection TOS/DSCP value set by Squid
   %<qos    Server connection TOS/DSCP value set by Squid
   %>nfmark Client connection netfilter mark set by Squid
   %<nfmark Server connection netfilter mark set by Squid

This patch also modify qos related code to set Comm::Connection::nfmark and 
Comm::Connection::tos members in Ip::Qos::setSockNfmark and Ip::Qos::setSockTos
methods. The Comm::Connection members are now set only if the tos and nfmark
set successfuly.

This is a Measurement Factory project

=== modified file 'src/FwdState.cc'
--- src/FwdState.cc	2013-06-18 22:30:39 +0000
+++ src/FwdState.cc	2013-07-15 07:14:08 +0000
@@ -1147,47 +1147,47 @@
     // Avoid pconns after races so that the same client does not suffer twice.
     // This does not increase the total number of connections because we just
     // closed the connection that failed the race. And re-pinning assumes this.
     if (pconnRace != raceHappened)
         temp = fwdPconnPool->pop(serverDestinations[0], host, checkRetriable());
 
     const bool openedPconn = Comm::IsConnOpen(temp);
     pconnRace = openedPconn ? racePossible : raceImpossible;
 
     // if we found an open persistent connection to use. use it.
     if (openedPconn) {
         serverConn = temp;
         flags.connected_okay = true;
         debugs(17, 3, HERE << "reusing pconn " << serverConnection());
         ++n_tries;
 
         comm_add_close_handler(serverConnection()->fd, fwdServerClosedWrapper, this);
 
         /* Update server side TOS and Netfilter mark on the connection. */
         if (Ip::Qos::TheConfig.isAclTosActive()) {
-            temp->tos = GetTosToServer(request);
-            Ip::Qos::setSockTos(temp, temp->tos);
+            const tos_t tos = GetTosToServer(request);
+            Ip::Qos::setSockTos(temp, tos);
         }
 #if SO_MARK
         if (Ip::Qos::TheConfig.isAclNfmarkActive()) {
-            temp->nfmark = GetNfmarkToServer(request);
-            Ip::Qos::setSockNfmark(temp, temp->nfmark);
+            const nfmark_t nfmark = GetNfmarkToServer(request);
+            Ip::Qos::setSockNfmark(temp, nfmark);
         }
 #endif
 
         dispatch();
         return;
     }
 
     // We will try to open a new connection, possibly to the same destination.
     // We reset serverDestinations[0] in case we are using it again because
     // ConnOpener modifies its destination argument.
     serverDestinations[0]->local.port(0);
     serverConn = NULL;
 
 #if URL_CHECKSUM_DEBUG
     entry->mem_obj->checkUrlChecksum();
 #endif
 
     /* Get the server side TOS and Netfilter mark to be set on the connection. */
     if (Ip::Qos::TheConfig.isAclTosActive()) {
         serverDestinations[0]->tos = GetTosToServer(request);

=== modified file 'src/cf.data.pre'
--- src/cf.data.pre	2013-06-18 06:22:13 +0000
+++ src/cf.data.pre	2013-07-15 07:18:27 +0000
@@ -3670,40 +3670,44 @@
 			adaptation_meta configuration parameter.
 			If no argument given all meta headers logged.
 
 	Connection related format codes:
 
 		>a	Client source IP address
 		>A	Client FQDN
 		>p	Client source port
 		>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
 
 		la	Local listening IP address the client connection was connected to.
 		lp	Local listening port number the client connection was connected to.
 
 		<a	Server IP address of the last server or peer connection
 		<A	Server FQDN or peer name
 		<p	Server port number of the last server or peer connection
 		<la	Local IP address of the last server or peer connection
 		<lp     Local port number of the last server or peer connection
+		>qos	Client connection TOS/DSCP value set by Squid
+		<qos	Server connection TOS/DSCP value set by Squid
+		>nfmark	Client connection netfilter mark set by Squid
+		<nfmark Server connection netfilter mark set by Squid
 
 	Time related format codes:
 
 		ts	Seconds since epoch
 		tu	subsecond time (milliseconds)
 		tl	Local time. Optional strftime format argument
 				default %d/%b/%Y:%H:%M:%S %z
 		tg	GMT time. Optional strftime format argument
 				default %d/%b/%Y:%H:%M:%S %z
 		tr	Response time (milliseconds)
 		dt	Total time spent making DNS lookups (milliseconds)
 
 	Access Control related format codes:
 
 		et	Tag returned by external acl
 		ea	Log string returned by external acl
 		un	User name (any available)
 		ul	User name from authentication
 		ue	User name from external acl helper
 		ui	User name from ident

=== modified file 'src/comm/Connection.cc'
--- src/comm/Connection.cc	2013-05-05 01:19:46 +0000
+++ src/comm/Connection.cc	2013-07-15 07:14:08 +0000
@@ -30,40 +30,41 @@
 Comm::Connection::~Connection()
 {
     if (fd >= 0) {
         debugs(5, 4, "BUG #3329: Orphan Comm::Connection: " << *this);
         debugs(5, 4, "NOTE: " << ++lost_conn << " Orphans since last started.");
         close();
     }
 
     cbdataReferenceDone(peer_);
 }
 
 Comm::ConnectionPointer
 Comm::Connection::copyDetails() const
 {
     ConnectionPointer c = new Comm::Connection;
 
     c->local = local;
     c->remote = remote;
     c->peerType = peerType;
     c->tos = tos;
+    c->nfmark = nfmark;
     c->flags = flags;
 
     // ensure FD is not open in the new copy.
     c->fd = -1;
 
     // ensure we have a cbdata reference to peer_ not a straight ptr copy.
     c->peer_ = cbdataReference(getPeer());
 
     return c;
 }
 
 void
 Comm::Connection::close()
 {
     if (isOpen()) {
         comm_close(fd);
         fd = -1;
         if (CachePeer *p=getPeer())
             -- p->stats.conn_open;
     }

=== modified file 'src/format/ByteCode.h'
--- src/format/ByteCode.h	2013-02-11 23:11:12 +0000
+++ src/format/ByteCode.h	2013-07-15 07:26:42 +0000
@@ -180,35 +180,39 @@
     LFT_ICAP_REQ_HEADER_ELEM,
     LFT_ICAP_REQ_ALL_HEADERS,
 
     LFT_ICAP_REP_HEADER,
     LFT_ICAP_REP_HEADER_ELEM,
     LFT_ICAP_REP_ALL_HEADERS,
 
     LFT_ICAP_TR_RESPONSE_TIME,
     LFT_ICAP_IO_TIME,
     LFT_ICAP_OUTCOME,
     LFT_ICAP_STATUS_CODE,
 #endif
 
 #if USE_SSL
     LFT_SSL_BUMP_MODE,
     LFT_SSL_USER_CERT_SUBJECT,
     LFT_SSL_USER_CERT_ISSUER,
 #endif
 
     LFT_NOTE,
+    LFT_CLIENT_LOCAL_TOS,
+    LFT_SERVER_LOCAL_TOS,
+    LFT_CLIENT_LOCAL_NFMARK,
+    LFT_SERVER_LOCAL_NFMARK,
     LFT_PERCENT			/* special string cases for escaped chars */
 } ByteCode_t;
 
 /// Quoting style for a format output.
 enum Quoting {
     LOG_QUOTE_NONE = 0,
     LOG_QUOTE_QUOTES,
     LOG_QUOTE_MIMEBLOB,
     LOG_QUOTE_URL,
     LOG_QUOTE_RAW
 };
 
 } // namespace Format
 
 #endif /* _SQUID_FMT_BYTECODE_H */

=== modified file 'src/format/Format.cc'
--- src/format/Format.cc	2013-06-11 09:25:07 +0000
+++ src/format/Format.cc	2013-07-15 07:28:57 +0000
@@ -1029,40 +1029,69 @@
         }
 
         case LFT_SSL_USER_CERT_SUBJECT:
             if (X509 *cert = al->cache.sslClientCert.get()) {
                 if (X509_NAME *subject = X509_get_subject_name(cert)) {
                     X509_NAME_oneline(subject, tmp, sizeof(tmp));
                     out = tmp;
                 }
             }
             break;
 
         case LFT_SSL_USER_CERT_ISSUER:
             if (X509 *cert = al->cache.sslClientCert.get()) {
                 if (X509_NAME *issuer = X509_get_issuer_name(cert)) {
                     X509_NAME_oneline(issuer, tmp, sizeof(tmp));
                     out = tmp;
                 }
             }
             break;
 #endif
+
+        case LFT_CLIENT_LOCAL_TOS:
+            if (al->tcpClient != NULL) {
+                snprintf(tmp, sizeof(tmp), "0x%x", (uint32_t)al->tcpClient->tos);
+                out = tmp;
+            }
+            break;
+
+        case LFT_SERVER_LOCAL_TOS:
+            if (al->hier.tcpServer != NULL) {
+                snprintf(tmp, sizeof(tmp), "0x%x", (uint32_t)al->hier.tcpServer->tos);
+                out = tmp;
+            }
+            break;
+
+        case LFT_CLIENT_LOCAL_NFMARK:
+            if (al->tcpClient != NULL) {
+                snprintf(tmp, sizeof(tmp), "0x%x", al->tcpClient->nfmark);
+                out = tmp;
+            }
+            break;
+
+        case LFT_SERVER_LOCAL_NFMARK:
+            if (al->hier.tcpServer != NULL) {
+                snprintf(tmp, sizeof(tmp), "0x%x", al->hier.tcpServer->nfmark);
+                out = tmp;
+            }
+            break;
+
         case LFT_NOTE:
             if (fmt->data.string) {
 #if USE_ADAPTATION
                 Adaptation::History::Pointer ah = al->request ? al->request->adaptHistory() : Adaptation::History::Pointer();
                 if (ah != NULL && ah->metaHeaders != NULL) {
                     if (const char *meta = ah->metaHeaders->find(fmt->data.string))
                         sb.append(meta);
                 }
 #endif
                 if (al->notes != NULL) {
                     if (const char *note = al->notes->find(fmt->data.string)) {
                         if (sb.size())
                             sb.append(", ");
                         sb.append(note);
                     }
                 }
                 out = sb.termedBuf();
                 quote = 1;
             } else {
 #if USE_ADAPTATION

=== modified file 'src/format/Token.cc'
--- src/format/Token.cc	2013-05-22 01:04:34 +0000
+++ src/format/Token.cc	2013-07-15 07:28:12 +0000
@@ -29,41 +29,40 @@
 
     {">v", LFT_REQUEST_VERSION_OLD_2X},
 
     {"%", LFT_PERCENT},
 
     {NULL, LFT_NONE}		/* this must be last */
 };
 
 /// 2-char tokens
 static TokenTableEntry TokenTable2C[] = {
 
     {">la", LFT_CLIENT_LOCAL_IP},
     {"la", LFT_LOCAL_LISTENING_IP},
     {">lp", LFT_CLIENT_LOCAL_PORT},
     {"lp", LFT_LOCAL_LISTENING_PORT},
     /*{ "lA", LFT_LOCAL_NAME }, */
 
     {"<la", LFT_SERVER_LOCAL_IP},
     {"oa", LFT_SERVER_LOCAL_IP_OLD_27},
     {"<lp", LFT_SERVER_LOCAL_PORT},
-    /* {"ot", LFT_PEER_OUTGOING_TOS}, */
 
     {"ts", LFT_TIME_SECONDS_SINCE_EPOCH},
     {"tu", LFT_TIME_SUBSECOND},
     {"tl", LFT_TIME_LOCALTIME},
     {"tg", LFT_TIME_GMT},
     {"tr", LFT_TIME_TO_HANDLE_REQUEST},
 
     {"<pt", LFT_PEER_RESPONSE_TIME},
     {"<tt", LFT_TOTAL_SERVER_SIDE_RESPONSE_TIME},
     {"dt", LFT_DNS_WAIT_TIME},
 
     {">ha", LFT_ADAPTED_REQUEST_HEADER},
     {">ha", LFT_ADAPTED_REQUEST_ALL_HEADERS},
 
     {"un", LFT_USER_NAME},
     {"ul", LFT_USER_LOGIN},
     /*{ "ur", LFT_USER_REALM }, */
     /*{ "us", LFT_USER_SCHEME }, */
     {"ui", LFT_USER_IDENT},
     {"ue", LFT_USER_EXTERNAL},
@@ -105,40 +104,44 @@
 
     {"<st", LFT_REPLY_SIZE_TOTAL},
     {"<sH", LFT_REPLY_HIGHOFFSET},
     {"<sS", LFT_REPLY_OBJECTSIZE},
     /*{ "<sl", LFT_REPLY_SIZE_LINE }, * /   / * the reply line (protocol, code, text) */
     {"<sh", LFT_REPLY_SIZE_HEADERS },
     /*{ "<sb", LFT_REPLY_SIZE_BODY }, */
     /*{ "<sB", LFT_REPLY_SIZE_BODY_NO_TE }, */
 
     {"et", LFT_TAG},
     {"st", LFT_IO_SIZE_TOTAL},
     {"ea", LFT_EXT_LOG},
     {"sn", LFT_SEQUENCE_NUMBER},
 
     {NULL, LFT_NONE}		/* this must be last */
 };
 
 /// Miscellaneous >2 byte tokens
 static TokenTableEntry TokenTableMisc[] = {
     {">eui", LFT_CLIENT_EUI},
+    {">qos", LFT_CLIENT_LOCAL_TOS},
+    {"<qos", LFT_SERVER_LOCAL_TOS},
+    {">nfmark", LFT_CLIENT_LOCAL_NFMARK},
+    {"<nfmark", LFT_SERVER_LOCAL_NFMARK},
     {"err_code", LFT_SQUID_ERROR },
     {"err_detail", LFT_SQUID_ERROR_DETAIL },
     {"note", LFT_NOTE },
     {NULL, LFT_NONE}		/* this must be last */
 };
 
 #if USE_ADAPTATION
 static TokenTableEntry TokenTableAdapt[] = {
     {"all_trs", LFT_ADAPTATION_ALL_XACT_TIMES},
     {"sum_trs", LFT_ADAPTATION_SUM_XACT_TIMES},
     {"<last_h", LFT_ADAPTATION_LAST_HEADER},
     {NULL, LFT_NONE}           /* this must be last */
 };
 #endif
 
 #if ICAP_CLIENT
 /// ICAP (icap::) tokens
 static TokenTableEntry TokenTableIcap[] = {
     {"tt", LFT_ICAP_TOTAL_TIME},
     {"<last_h", LFT_ADAPTATION_LAST_HEADER}, // deprecated

=== modified file 'src/ip/Qos.cci'
--- src/ip/Qos.cci	2013-01-08 23:51:02 +0000
+++ src/ip/Qos.cci	2013-07-15 07:14:08 +0000
@@ -1,50 +1,54 @@
 /* Inline QOS functions */
 #include "comm/Connection.h"
 #include "Debug.h"
 
 int
 Ip::Qos::setSockTos(const Comm::ConnectionPointer &conn, tos_t tos)
 {
 #if defined(IP_TOS)
     // Bug 3731: FreeBSD produces 'invalid option'
     // unless we pass it a 32-bit variable storing 8-bits of data.
     // NP: it is documented as 'int' for all systems, even those like Linux which accept 8-bit char
     //     so we convert to a int before setting.
     int bTos = tos;
     int x = setsockopt(conn->fd, IPPROTO_IP, IP_TOS, &bTos, sizeof(bTos));
     if (x < 0)
         debugs(50, 2, "Ip::Qos::setSockTos: setsockopt(IP_TOS) on " << conn << ": " << xstrerror());
+    else
+        conn->tos = tos;
     return x;
 #else
     debugs(50, DBG_IMPORTANT, "WARNING: setsockopt(IP_TOS) not supported on this platform");
     return -1;
 #endif
 }
 
 int
 Ip::Qos::setSockNfmark(const Comm::ConnectionPointer &conn, nfmark_t mark)
 {
 #if SO_MARK && USE_LIBCAP
     int x = setsockopt(conn->fd, SOL_SOCKET, SO_MARK, &mark, sizeof(nfmark_t));
     if (x < 0)
         debugs(50, 2, "setSockNfmark: setsockopt(SO_MARK) on " << conn << ": " << xstrerror());
+    else
+        conn->nfmark = mark;
     return x;
 #elif USE_LIBCAP
     debugs(50, DBG_IMPORTANT, "WARNING: setsockopt(SO_MARK) not supported on this platform");
     return -1;
 #else
     debugs(50, DBG_IMPORTANT, "WARNING: Netfilter marking disabled (netfilter marking requires build with LIBCAP)");
     return -1;
 #endif
 }
 
 bool
 Ip::Qos::Config::isHitTosActive() const
 {
     return (tosLocalHit || tosSiblingHit || tosParentHit || tosMiss || preserveMissTos);
 }
 
 bool
 Ip::Qos::Config::isHitNfmarkActive() const
 {
     return (markLocalHit || markSiblingHit || markParentHit || markMiss || preserveMissMark);