Add %master_xaction logformat code (#471)

Currently, knowing master transaction ID can be very helpful in triage,
especially when dealing with flash crowds on busy proxies. Upcoming
changes will also tie many current "anonymous" level-0/1 messages to
logged transactions via this ID.

diff --git a/src/MasterXaction.cc b/src/MasterXaction.cc
index 20107c97022deefc9986eecf28830e8b538bbe16..9aeaea5fa84bce0d2f3c9a699a38f1d0ed4b71d1 100644 (file)
--- a/src/MasterXaction.cc
+++ b/src/MasterXaction.cc
@@ -9,5 +9,5 @@
 #include "squid.h"
 #include "MasterXaction.h"
 
-InstanceIdDefinitions(MasterXaction, "MXID_");
+InstanceIdDefinitions(MasterXaction, "master", uint64_t);
 

diff --git a/src/MasterXaction.h b/src/MasterXaction.h
index f1d16df887bb23b188e889c52bca69af25278b6f..9991f7e8e6f53a9e1d6137d4b172196d1aee60ea 100644 (file)
--- a/src/MasterXaction.h
+++ b/src/MasterXaction.h
@@ -44,7 +44,7 @@ public:
     explicit MasterXaction(const XactionInitiator anInitiator) : initiator(anInitiator) {};
 
     /// transaction ID.
-    InstanceId<MasterXaction> id;
+    InstanceId<MasterXaction, uint64_t> id;
 
     /// the listening port which originated this transaction
     AnyP::PortCfgPointer squidPort;

diff --git a/src/base/InstanceId.h b/src/base/InstanceId.h
index 52a96d77c9d8b4865584fad38c9e50a21494cb88..3dae7f280ddbe7babdae0c484debadaef3a46292 100644 (file)
--- a/src/base/InstanceId.h
+++ b/src/base/InstanceId.h
@@ -11,19 +11,19 @@
 
 #include <iosfwd>
 
+typedef unsigned int InstanceIdDefaultValueType;
 /** Identifier for class instances
  *   - unique IDs for a large number of concurrent instances, but may wrap;
  *   - useful for debugging and insecure request/response matching;
  *   - sequential IDs within a class except when wrapping;
  *   - always positive IDs.
- *  \todo: add storage type parameter to support configurable Value types?
  *  \todo: add creation/destruction debugging?
  */
-template <class Class>
+template <class Class, class ValueType = InstanceIdDefaultValueType>
 class InstanceId
 {
 public:
-    typedef unsigned int Value; ///< id storage type; \todo: parameterize?
+    typedef ValueType Value; ///< id storage type
 
     InstanceId() {change();}
 
@@ -39,33 +39,36 @@ public:
     const char * prefix() const;
 
 public:
-    Value value = 0; ///< instance identifier
+    Value value = Value(); ///< instance identifier
 
 private:
     InstanceId(const InstanceId &); ///< not implemented; IDs are unique
     InstanceId& operator=(const InstanceId &); ///< not implemented
 };
 
-/// convenience macro to instantiate Class-specific stuff in .cc files
-#define InstanceIdDefinitions(Class, pfx) \
+/// An InstanceIdDefinitions() helper. Avoid direct use.
+#define InstanceIdDefinitions3(Class, pfx, ValueType, ...) \
     template<> const char * \
-    InstanceId<Class>::prefix() const { \
+    InstanceId<Class, ValueType>::prefix() const { \
         return pfx; \
     } \
     template<> std::ostream & \
-    InstanceId<Class>::print(std::ostream &os) const { \
+    InstanceId<Class, ValueType>::print(std::ostream &os) const { \
         return os << pfx << value; \
     } \
     template<> void \
-    InstanceId<Class>::change() { \
-        static InstanceId<Class>::Value Last = 0; \
+    InstanceId<Class, ValueType>::change() { \
+        static auto Last = Value(); \
         value = ++Last ? Last : ++Last; \
     }
 
+/// convenience macro to instantiate Class-specific stuff in .cc files
+#define InstanceIdDefinitions(...) InstanceIdDefinitions3(__VA_ARGS__, InstanceIdDefaultValueType)
+
 /// print the id
-template <class Class>
+template <class Class, class ValueType>
 inline
-std::ostream &operator <<(std::ostream &os, const InstanceId<Class> &id)
+std::ostream &operator <<(std::ostream &os, const InstanceId<Class, ValueType> &id)
 {
     return id.print(os);
 }

diff --git a/src/cf.data.pre b/src/cf.data.pre
index 56bcac5bd50da90acdf564135463981252228f68..1e797ba8a38a910d2e67b1bafb8a13032b48e4e2 100644 (file)
--- a/src/cf.data.pre
+++ b/src/cf.data.pre
@@ -4533,6 +4533,14 @@ DOC_START
                        individual notes. There is currently no way to
                        specify both value and notes separators when logging
                        all notes with %note.
+               master_xaction  The master transaction identifier is an unsigned
+                       integer. These IDs are guaranteed to monotonically
+                       increase within a single worker process lifetime, with
+                       higher values corresponding to transactions that were
+                       accepted or initiated later. Due to current implementation
+                       deficiencies, some IDs are skipped (i.e. never logged).
+                       Concurrent workers and restarted workers use similar,
+                       overlapping sequences of master transaction IDs.
 
        Connection related format codes:
 

diff --git a/src/format/ByteCode.h b/src/format/ByteCode.h
index f12c9fd02010b3357f7b1415eec9f6b1fba67bb9..66fd08bb74cd1721fedd4f37179202bcaa5777e5 100644 (file)
--- a/src/format/ByteCode.h
+++ b/src/format/ByteCode.h
@@ -233,6 +233,7 @@ typedef enum {
 
     LFT_NOTE,
     LFT_PERCENT,            /* special string cases for escaped chars */
+    LFT_MASTER_XACTION,
 
     // TODO assign better bytecode names and Token strings for these
 #if USE_OPENSSL

diff --git a/src/format/Format.cc b/src/format/Format.cc
index f4754310c3f50be3d5069b18f61bc6ed4e46236e..3bb426895eae27a76c1a8ec0422dc76aa63359e9 100644 (file)
--- a/src/format/Format.cc
+++ b/src/format/Format.cc
@@ -23,6 +23,7 @@
 #include "MemBuf.h"
 #include "proxyp/Header.h"
 #include "rfc1738.h"
+#include "sbuf/Stream.h"
 #include "sbuf/StringConvert.h"
 #include "security/CertError.h"
 #include "security/NegotiationHistory.h"
@@ -398,6 +399,8 @@ Format::Format::assemble(MemBuf &mb, const AccessLogEntry::Pointer &al, int logS
         struct timeval outtv = {0, 0};
         int doMsec = 0;
         int doSec = 0;
+        bool doUint64 = false;
+        uint64_t outUint64 = 0;
 
         switch (fmt->type) {
 
@@ -1442,6 +1445,13 @@ Format::Format::assemble(MemBuf &mb, const AccessLogEntry::Pointer &al, int logS
             if (!al->lastAclData.isEmpty())
                 out = al->lastAclData.c_str();
             break;
+
+        case LFT_MASTER_XACTION:
+            if (al->request) {
+                doUint64 = true;
+                outUint64 = static_cast<uint64_t>(al->request->masterXaction->id.value);
+                break;
+            }
         }
 
         if (dooff) {
@@ -1451,6 +1461,9 @@ Format::Format::assemble(MemBuf &mb, const AccessLogEntry::Pointer &al, int logS
         } else if (doint) {
             sb.appendf("%0*ld", fmt->zero && fmt->widthMin >= 0 ? fmt->widthMin : 0, outint);
             out = sb.c_str();
+        } else if (doUint64) {
+            sb.appendf("%0*" PRIu64, fmt->zero && fmt->widthMin >= 0 ? fmt->widthMin : 0, outUint64);
+            out = sb.c_str();
         } else if (doMsec) {
             if (fmt->widthMax < 0) {
                 sb.appendf("%0*ld", fmt->zero && fmt->widthMin >= 0 ? fmt->widthMin : 0, tvToMsec(outtv));
@@ -1526,7 +1539,7 @@ Format::Format::assemble(MemBuf &mb, const AccessLogEntry::Pointer &al, int logS
             }
 
             // enforce width limits if configured
-            const bool haveMaxWidth = fmt->widthMax >=0 && !doint && !dooff && !doMsec && !doSec;
+            const bool haveMaxWidth = fmt->widthMax >=0 && !doint && !dooff && !doMsec && !doSec && !doUint64;
             if (haveMaxWidth || fmt->widthMin) {
                 const int minWidth = fmt->widthMin >= 0 ?
                                      fmt->widthMin :0;

diff --git a/src/format/Token.cc b/src/format/Token.cc
index edb4ce51754f041c9501bcc4a05c14647fcd689f..130ee375fc1b952b87b9a46e275c19d887dea50c 100644 (file)
--- a/src/format/Token.cc
+++ b/src/format/Token.cc
@@ -148,6 +148,7 @@ static TokenTableEntry TokenTableMisc[] = {
     TokenTableEntry("err_detail", LFT_SQUID_ERROR_DETAIL ),
     TokenTableEntry("note", LFT_NOTE ),
     TokenTableEntry("credentials", LFT_CREDENTIALS),
+    TokenTableEntry("master_xaction", LFT_MASTER_XACTION),
     /*
      * Legacy external_acl_type format tokens
      */