%tS logformat code

This patch add the %tS logformat code to represent master transaction start time
in <seconds>.<milliseconds> format, similar to the existing access.log "current
time" field (%ts.%03tu).

Also allow formated values for adaptation_meta values.

This is a Measurement Factory project

diff --git a/src/AccessLogEntry.h b/src/AccessLogEntry.h
index 2263198cd7a510f096e7e2a07d2458a05af31091..b302c63bb8f7181468ac51fc41f7e04c98b370f8 100644 (file)
--- a/src/AccessLogEntry.h
+++ b/src/AccessLogEntry.h
@@ -176,6 +176,7 @@ public:
         int64_t highOffset;
         int64_t objectSize;
         LogTags code;
+        struct timeval start_time; ///< The time the master transaction started
         int msec;
         const char *rfc931;
         const char *extuser;

diff --git a/src/Notes.cc b/src/Notes.cc
index 9100e6cbfab5f98850c28e8f078c8387522e02f2..ad84e0ea6bff4af1ac28851f77e30cfabdd446dc 100644 (file)
--- a/src/Notes.cc
+++ b/src/Notes.cc
@@ -56,7 +56,7 @@ Note::addValue(const String &value)
 }
 
 const char *
-Note::match(HttpRequest *request, HttpReply *reply)
+Note::match(HttpRequest *request, HttpReply *reply, const AccessLogEntry::Pointer &al)
 {
 
     typedef Values::iterator VLI;
@@ -69,8 +69,15 @@ Note::match(HttpRequest *request, HttpReply *reply)
         const int ret= ch.fastCheck((*i)->aclList);
         debugs(93, 5, HERE << "Check for header name: " << key << ": " << (*i)->value
                <<", HttpRequest: " << request << " HttpReply: " << reply << " matched: " << ret);
-        if (ret == ACCESS_ALLOWED)
-            return (*i)->value.termedBuf();
+        if (ret == ACCESS_ALLOWED) {
+            if (al != NULL && (*i)->valueFormat != NULL) {
+                static MemBuf mb;
+                mb.reset();
+                (*i)->valueFormat->assemble(mb, al, 0);
+                return mb.content();
+            } else
+                return (*i)->value.termedBuf();
+        }
     }
     return NULL;
 }
@@ -93,7 +100,10 @@ Note::Pointer
 Notes::parse(ConfigParser &parser)
 {
     String key = ConfigParser::NextToken();
+    ConfigParser::EnableMacros();
     String value = ConfigParser::NextQuotedToken();
+    ConfigParser::DisableMacros();
+    bool valueWasQuoted = ConfigParser::LastTokenWasQuoted();
     Note::Pointer note = add(key);
     Note::Value::Pointer noteValue = note->addValue(value);
 
@@ -101,7 +111,10 @@ Notes::parse(ConfigParser &parser)
     label.append('=');
     label.append(value);
     aclParseAclList(parser, &noteValue->aclList, label.termedBuf());
-
+    if (formattedValues && valueWasQuoted) {
+        noteValue->valueFormat =  new Format::Format(descr ? descr : "Notes");
+        noteValue->valueFormat->parse(value.termedBuf());
+    }
     if (blacklisted) {
         for (int i = 0; blacklisted[i] != NULL; ++i) {
             if (note->key.caseCmp(blacklisted[i]) == 0) {

diff --git a/src/Notes.h b/src/Notes.h
index 8583da4e93f7c96b7a3d986f3026ab9ac1a265db..6edf828f16088008bfdbd69434b94f64793f9ba3 100644 (file)
--- a/src/Notes.h
+++ b/src/Notes.h
@@ -5,6 +5,7 @@
 #include "base/RefCount.h"
 #include "base/Vector.h"
 #include "CbDataList.h"
+#include "format/Format.h"
 #include "MemPool.h"
 #include "SquidString.h"
 #include "typedefs.h"
@@ -15,6 +16,7 @@
 
 class HttpRequest;
 class HttpReply;
+typedef RefCount<AccessLogEntry> AccessLogEntryPointer;
 
 /**
  * Used to store a note configuration. The notes are custom key:value
@@ -31,9 +33,11 @@ public:
     {
     public:
         typedef RefCount<Value> Pointer;
-        String value; ///< a note value
+        String value; ///< Configured annotation value, possibly with %macros
         ACLList *aclList; ///< The access list used to determine if this value is valid for a request
-        explicit Value(const String &aVal) : value(aVal), aclList(NULL) {}
+        /// Compiled annotation value format
+        Format::Format *valueFormat;
+        explicit Value(const String &aVal) : value(aVal), aclList(NULL), valueFormat(NULL) {}
         ~Value();
     };
     typedef Vector<Value::Pointer> Values;
@@ -50,8 +54,10 @@ public:
      * Walks through the  possible values list of the note and selects
      * the first value which matches the given HttpRequest and HttpReply
      * or NULL if none matches.
+     * If an AccessLogEntry given and Value::valueFormat is not null, the
+     * formatted value returned.
      */
-    const char *match(HttpRequest *request, HttpReply *reply);
+    const char *match(HttpRequest *request, HttpReply *reply, const AccessLogEntryPointer &al);
 
     String key; ///< The note key
     Values values; ///< The possible values list for the note
@@ -68,7 +74,7 @@ public:
     typedef NotesList::iterator iterator; ///< iterates over the notes list
     typedef NotesList::const_iterator const_iterator; ///< iterates over the notes list
 
-    Notes(const char *aDescr, const char **metasBlacklist): descr(aDescr), blacklisted(metasBlacklist) {}
+    Notes(const char *aDescr, const char **metasBlacklist, bool allowFormatted = false): descr(aDescr), blacklisted(metasBlacklist), formattedValues(allowFormatted) {}
     Notes(): descr(NULL), blacklisted(NULL) {}
     ~Notes() { notes.clean(); }
     /**
@@ -92,6 +98,7 @@ public:
     NotesList notes; ///< The Note::Pointer objects array list
     const char *descr; ///< A short description for notes list
     const char **blacklisted; ///< Null terminated list of blacklisted note keys
+    bool formattedValues; ///< Whether the formatted values are supported
 
 private:
     /**

diff --git a/src/Server.cc b/src/Server.cc
index 674caf71e972b4953a29230172566e8b61c70df6..9c7fe1e6a01cecee41f599fc7e6c9213719c4e35 100644 (file)
--- a/src/Server.cc
+++ b/src/Server.cc
@@ -561,7 +561,7 @@ ServerStateData::startAdaptation(const Adaptation::ServiceGroupPointer &group, H
     }
 
     adaptedHeadSource = initiateAdaptation(
-                            new Adaptation::Iterator(vrep, cause, group));
+                            new Adaptation::Iterator(vrep, cause, fwd->al, group));
     startedAdaptation = initiated(adaptedHeadSource);
     Must(startedAdaptation);
 }
@@ -924,7 +924,7 @@ ServerStateData::adaptOrFinalizeReply()
     // The callback can be called with a NULL service if adaptation is off.
     adaptationAccessCheckPending = Adaptation::AccessCheck::Start(
                                        Adaptation::methodRespmod, Adaptation::pointPreCache,
-                                       originalRequest(), virginReply(), this);
+                                       originalRequest(), virginReply(), fwd->al, this);
     debugs(11,5, HERE << "adaptationAccessCheckPending=" << adaptationAccessCheckPending);
     if (adaptationAccessCheckPending)
         return;

diff --git a/src/adaptation/AccessCheck.cc b/src/adaptation/AccessCheck.cc
index aaa8b97278f8df4b89df2c525deadcdc9ecd5e5a..fdda1c2336586dee3e675ee458a63d71ba6038c7 100644 (file)
--- a/src/adaptation/AccessCheck.cc
+++ b/src/adaptation/AccessCheck.cc
@@ -1,4 +1,5 @@
 #include "squid.h"
+#include "AccessLogEntry.h"
 #include "acl/FilledChecklist.h"
 #include "adaptation/AccessCheck.h"
 #include "adaptation/AccessRule.h"
@@ -19,13 +20,14 @@ cbdata_type Adaptation::AccessCheck::CBDATA_AccessCheck = CBDATA_UNKNOWN;
 
 bool
 Adaptation::AccessCheck::Start(Method method, VectPoint vp,
-                               HttpRequest *req, HttpReply *rep, Adaptation::Initiator *initiator)
+                               HttpRequest *req, HttpReply *rep,
+                               AccessLogEntry::Pointer &al, Adaptation::Initiator *initiator)
 {
 
     if (Config::Enabled) {
         // the new check will call the callback and delete self, eventually
         AsyncJob::Start(new AccessCheck( // we do not store so not a CbcPointer
-                            ServiceFilter(method, vp, req, rep), initiator));
+                            ServiceFilter(method, vp, req, rep, al), initiator));
         return true;
     }
 

diff --git a/src/adaptation/AccessCheck.h b/src/adaptation/AccessCheck.h
index cbcda89f8c13836e781d4136fbd65bd43f668327..13728e57d9b5578f501ff3d6e91369eb5e83d48b 100644 (file)
--- a/src/adaptation/AccessCheck.h
+++ b/src/adaptation/AccessCheck.h
@@ -2,6 +2,7 @@
 #define SQUID_ADAPTATION__ACCESS_CHECK_H
 
 #include "acl/Acl.h"
+#include "AccessLogEntry.h"
 #include "adaptation/Elements.h"
 #include "adaptation/forward.h"
 #include "adaptation/Initiator.h"
@@ -25,7 +26,7 @@ public:
 
     // use this to start async ACL checks; returns true if started
     static bool Start(Method method, VectPoint vp, HttpRequest *req,
-                      HttpReply *rep, Adaptation::Initiator *initiator);
+                      HttpReply *rep, AccessLogEntry::Pointer &al, Adaptation::Initiator *initiator);
 
 protected:
     // use Start to start adaptation checks

diff --git a/src/adaptation/Config.cc b/src/adaptation/Config.cc
index 18e6cbef08b2384b1713bd74fc6242abb0b47e3b..2794a4cdd22504196209cc7123ab1845c1327826 100644 (file)
--- a/src/adaptation/Config.cc
+++ b/src/adaptation/Config.cc
@@ -66,7 +66,7 @@ const char *metasBlacklist[] = {
     "Transfer-Complete",
     NULL
 };
-Notes Adaptation::Config::metaHeaders("ICAP header", metasBlacklist);
+Notes Adaptation::Config::metaHeaders("ICAP header", metasBlacklist, true);
 bool Adaptation::Config::needHistory = false;
 
 Adaptation::ServiceConfig*

diff --git a/src/adaptation/Iterator.cc b/src/adaptation/Iterator.cc
index 2d87460241ab1f66bd9ac311a2b30ebf5a81a10d..61f1413e66f0c5889a3e414cec34e77bd72711f1 100644 (file)
--- a/src/adaptation/Iterator.cc
+++ b/src/adaptation/Iterator.cc
@@ -16,12 +16,14 @@
 
 Adaptation::Iterator::Iterator(
     HttpMsg *aMsg, HttpRequest *aCause,
+    AccessLogEntry::Pointer &alp,
     const ServiceGroupPointer &aGroup):
         AsyncJob("Iterator"),
         Adaptation::Initiate("Iterator"),
         theGroup(aGroup),
         theMsg(aMsg),
         theCause(aCause),
+        al(alp),
         theLauncher(0),
         iterations(0),
         adapted(false)
@@ -99,7 +101,7 @@ void Adaptation::Iterator::step()
     }
 
     theLauncher = initiateAdaptation(
-                      service->makeXactLauncher(theMsg, theCause));
+                      service->makeXactLauncher(theMsg, theCause, al));
     Must(initiated(theLauncher));
     Must(!done());
 }
@@ -276,7 +278,7 @@ Adaptation::ServiceFilter Adaptation::Iterator::filter() const
         Must(false); // should not happen
     }
 
-    return ServiceFilter(method, theGroup->point, req, rep);
+    return ServiceFilter(method, theGroup->point, req, rep, al);
 }
 
 CBDATA_NAMESPACED_CLASS_INIT(Adaptation, Iterator);

diff --git a/src/adaptation/Iterator.h b/src/adaptation/Iterator.h
index fda39bb693cad5ec99634f4a3fdd36b9406b6c6a..191f1194d1b93b592b5a9d78edfcc7fac6c577d4 100644 (file)
--- a/src/adaptation/Iterator.h
+++ b/src/adaptation/Iterator.h
@@ -1,6 +1,7 @@
 #ifndef SQUID_ADAPTATION__ITERATOR_H
 #define SQUID_ADAPTATION__ITERATOR_H
 
+#include "AccessLogEntry.h"
 #include "adaptation/Initiate.h"
 #include "adaptation/Initiator.h"
 #include "adaptation/ServiceGroups.h"
@@ -25,6 +26,7 @@ class Iterator: public Initiate, public Initiator
 {
 public:
     Iterator(HttpMsg *virginHeader, HttpRequest *virginCause,
+             AccessLogEntry::Pointer &alp,
              const Adaptation::ServiceGroupPointer &aGroup);
     virtual ~Iterator();
 
@@ -57,6 +59,7 @@ protected:
     ServicePlan thePlan; ///< which services to use and in what order
     HttpMsg *theMsg; ///< the message being adapted (virgin for each step)
     HttpRequest *theCause; ///< the cause of the original virgin message
+    AccessLogEntry::Pointer al; ///< info for the future access.log entry
     CbcPointer<Adaptation::Initiate> theLauncher; ///< current transaction launcher
     int iterations; ///< number of steps initiated
     bool adapted; ///< whether the virgin message has been replaced

diff --git a/src/adaptation/Service.h b/src/adaptation/Service.h
index 1166f1c64b3c60afb7bed52b4c2675f022bffb08..f149ce1f2fff0887f173b9171e29960b9d05e2be 100644 (file)
--- a/src/adaptation/Service.h
+++ b/src/adaptation/Service.h
@@ -1,6 +1,7 @@
 #ifndef SQUID_ADAPTATION__SERVICE_H
 #define SQUID_ADAPTATION__SERVICE_H
 
+#include "AccessLogEntry.h"
 #include "adaptation/Elements.h"
 #include "adaptation/forward.h"
 #include "adaptation/ServiceConfig.h"
@@ -31,7 +32,7 @@ public:
     virtual bool broken() const;
     virtual bool up() const = 0; // see comments above
 
-    virtual Initiate *makeXactLauncher(HttpMsg *virginHeader, HttpRequest *virginCause) = 0;
+    virtual Initiate *makeXactLauncher(HttpMsg *virginHeader, HttpRequest *virginCause, AccessLogEntry::Pointer &alp) = 0;
 
     bool wants(const ServiceFilter &filter) const;
 

diff --git a/src/adaptation/ServiceFilter.cc b/src/adaptation/ServiceFilter.cc
index 25fbfac9f6a088eb6797bee47866876a15d7cbd8..90449d0fcb14faac93518cdfb5736e4171da9ef1 100644 (file)
--- a/src/adaptation/ServiceFilter.cc
+++ b/src/adaptation/ServiceFilter.cc
@@ -1,13 +1,15 @@
 #include "squid.h"
+#include "AccessLogEntry.h"
 #include "adaptation/ServiceFilter.h"
 #include "HttpReply.h"
 #include "HttpRequest.h"
 
-Adaptation::ServiceFilter::ServiceFilter(Method aMethod, VectPoint aPoint, HttpRequest *aReq, HttpReply *aRep):
+Adaptation::ServiceFilter::ServiceFilter(Method aMethod, VectPoint aPoint, HttpRequest *aReq, HttpReply *aRep, AccessLogEntry::Pointer const &alp):
         method(aMethod),
         point(aPoint),
         request(aReq),
-        reply(aRep)
+        reply(aRep),
+        al(alp)
 {
     if (reply)
         HTTPMSGLOCK(reply);
@@ -21,7 +23,8 @@ Adaptation::ServiceFilter::ServiceFilter(const ServiceFilter &f):
         method(f.method),
         point(f.point),
         request(f.request),
-        reply(f.reply)
+        reply(f.reply),
+        al(f.al)
 {
     if (request)
         HTTPMSGLOCK(request);

diff --git a/src/adaptation/ServiceFilter.h b/src/adaptation/ServiceFilter.h
index 0c9c8920c85a491fb6e336775756754481f5c12e..b88e96bc4cbf5a6f763193bf9df3dfa82109f95d 100644 (file)
--- a/src/adaptation/ServiceFilter.h
+++ b/src/adaptation/ServiceFilter.h
@@ -1,6 +1,7 @@
 #ifndef SQUID_ADAPTATION__SERVICE_FILTER_H
 #define SQUID_ADAPTATION__SERVICE_FILTER_H
 
+#include "AccessLogEntry.h"
 #include "adaptation/Elements.h"
 
 class HttpRequest;
@@ -13,7 +14,7 @@ namespace Adaptation
 class ServiceFilter
 {
 public:
-    ServiceFilter(Method, VectPoint, HttpRequest *, HttpReply *); // locks
+    ServiceFilter(Method, VectPoint, HttpRequest *, HttpReply *, AccessLogEntry::Pointer const &al); // locks
     ServiceFilter(const ServiceFilter &f);
     ~ServiceFilter(); // unlocks
 
@@ -24,6 +25,7 @@ public:
     VectPoint point; ///< adaptation location
     HttpRequest *request; ///< HTTP request being adapted or cause; may be nil
     HttpReply *reply; ///< HTTP response being adapted; may be nil
+    AccessLogEntry::Pointer al; ///< info for the future access.log entry
 };
 
 } // namespace Adaptation

diff --git a/src/adaptation/ecap/ServiceRep.cc b/src/adaptation/ecap/ServiceRep.cc
index 34e19ad6f4d2ce1215723f1b1e4e8b2e0a09dae3..9c78a45012435ff81916a32d9c526e8ea8b50a69 100644 (file)
--- a/src/adaptation/ecap/ServiceRep.cc
+++ b/src/adaptation/ecap/ServiceRep.cc
@@ -240,7 +240,7 @@ bool Adaptation::Ecap::ServiceRep::wantsUrl(const String &urlPath) const
 
 Adaptation::Initiate *
 Adaptation::Ecap::ServiceRep::makeXactLauncher(HttpMsg *virgin,
-        HttpRequest *cause)
+        HttpRequest *cause, AccessLogEntry::Pointer &alp)
 {
     Must(up());
 
@@ -253,7 +253,7 @@ Adaptation::Ecap::ServiceRep::makeXactLauncher(HttpMsg *virgin,
         debugs(93, 3, "asyncs: " << AsyncServices.size() << ' ' << TheEngine);
     }
 
-    XactionRep *rep = new XactionRep(virgin, cause, Pointer(this));
+    XactionRep *rep = new XactionRep(virgin, cause, alp, Pointer(this));
     XactionRep::AdapterXaction x(theService->makeXaction(rep));
     rep->master(x);
     return rep;

diff --git a/src/adaptation/ecap/ServiceRep.h b/src/adaptation/ecap/ServiceRep.h
index d3617c0290e818e4ab2b2adab46c15b71fcfca4c..19b166abcd4ba02872864ac6d06dc3fe0c1383e5 100644 (file)
--- a/src/adaptation/ecap/ServiceRep.h
+++ b/src/adaptation/ecap/ServiceRep.h
@@ -31,7 +31,7 @@ public:
     virtual void finalize();
     virtual bool probed() const;
     virtual bool up() const;
-    virtual Adaptation::Initiate *makeXactLauncher(HttpMsg *virginHeader, HttpRequest *virginCause);
+    virtual Adaptation::Initiate *makeXactLauncher(HttpMsg *virginHeader, HttpRequest *virginCause, AccessLogEntry::Pointer &alp);
     virtual bool wantsUrl(const String &urlPath) const;
     virtual void noteFailure();
     virtual const char *status() const;

diff --git a/src/adaptation/ecap/XactionRep.cc b/src/adaptation/ecap/XactionRep.cc
index 3938a76fb4fa180a2bbb791f385e2eeb92731d8c..30fb86cbd951c129c80d8d9e721443d7476c8b5c 100644 (file)
--- a/src/adaptation/ecap/XactionRep.cc
+++ b/src/adaptation/ecap/XactionRep.cc
@@ -13,6 +13,7 @@
 #include "adaptation/Initiator.h"
 #include "base/AsyncJobCalls.h"
 #include "base/TextException.h"
+#include "format/Format.h"
 #include "HttpReply.h"
 #include "HttpRequest.h"
 #include "SquidTime.h"
@@ -37,7 +38,7 @@ public:
 };
 
 Adaptation::Ecap::XactionRep::XactionRep(
-    HttpMsg *virginHeader, HttpRequest *virginCause,
+    HttpMsg *virginHeader, HttpRequest *virginCause, AccessLogEntry::Pointer &alp,
     const Adaptation::ServicePointer &aService):
         AsyncJob("Adaptation::Ecap::XactionRep"),
         Adaptation::Initiate("Adaptation::Ecap::XactionRep"),
@@ -46,7 +47,8 @@ Adaptation::Ecap::XactionRep::XactionRep(
         makingVb(opUndecided), proxyingAb(opUndecided),
         adaptHistoryId(-1),
         vbProductionFinished(false),
-        abProductionFinished(false), abProductionAtEnd(false)
+        abProductionFinished(false), abProductionAtEnd(false),
+        al(alp)
 {
     if (virginCause)
         theCauseRep = new MessageRep(virginCause);
@@ -181,7 +183,7 @@ Adaptation::Ecap::XactionRep::metaValue(const libecap::Name &name) const
         typedef Notes::iterator ACAMLI;
         for (ACAMLI i = Adaptation::Config::metaHeaders.begin(); i != Adaptation::Config::metaHeaders.end(); ++i) {
             if (name == (*i)->key.termedBuf()) {
-                if (const char *value = (*i)->match(request, reply))
+                if (const char *value = (*i)->match(request, reply, al))
                     return libecap::Area::FromTempString(value);
                 else
                     return libecap::Area();
@@ -202,7 +204,7 @@ Adaptation::Ecap::XactionRep::visitEachMetaHeader(libecap::NamedValueVisitor &vi
 
     typedef Notes::iterator ACAMLI;
     for (ACAMLI i = Adaptation::Config::metaHeaders.begin(); i != Adaptation::Config::metaHeaders.end(); ++i) {
-        const char *v = (*i)->match(request, reply);
+        const char *v = (*i)->match(request, reply, al);
         if (v) {
             const libecap::Name name((*i)->key.termedBuf());
             const libecap::Area value = libecap::Area::FromTempString(v);
@@ -231,7 +233,7 @@ Adaptation::Ecap::XactionRep::start()
         adaptHistoryId = ah->recordXactStart(service().cfg().key, current_time, false);
         typedef Notes::iterator ACAMLI;
         for (ACAMLI i = Adaptation::Config::metaHeaders.begin(); i != Adaptation::Config::metaHeaders.end(); ++i) {
-            const char *v = (*i)->match(request, reply);
+            const char *v = (*i)->match(request, reply, al);
             if (v) {
                 if (ah->metaHeaders == NULL)
                     ah->metaHeaders = new NotePairs();

diff --git a/src/adaptation/ecap/XactionRep.h b/src/adaptation/ecap/XactionRep.h
index 6723b1b7b0d7a726f16349dbaba2600f69e51ec1..a0a1548fd91cc11052c085b5989c1d90f8dc4254 100644 (file)
--- a/src/adaptation/ecap/XactionRep.h
+++ b/src/adaptation/ecap/XactionRep.h
@@ -27,7 +27,7 @@ class XactionRep : public Adaptation::Initiate, public libecap::host::Xaction,
         public BodyConsumer, public BodyProducer
 {
 public:
-    XactionRep(HttpMsg *virginHeader, HttpRequest *virginCause, const Adaptation::ServicePointer &service);
+    XactionRep(HttpMsg *virginHeader, HttpRequest *virginCause, AccessLogEntry::Pointer &alp, const Adaptation::ServicePointer &service);
     virtual ~XactionRep();
 
     typedef libecap::shared_ptr<libecap::adapter::Xaction> AdapterXaction;
@@ -114,6 +114,7 @@ private:
     bool vbProductionFinished; // whether there can be no more vb bytes
     bool abProductionFinished; // whether adapter has finished producing ab
     bool abProductionAtEnd;    // whether adapter produced a complete ab
+    AccessLogEntry::Pointer al; ///< Master transaction AccessLogEntry
 
     CBDATA_CLASS2(XactionRep);
 };

diff --git a/src/adaptation/icap/ModXact.cc b/src/adaptation/icap/ModXact.cc
index 74938c4df231044c7b7034499acf10b97a661146..ec793785629f514c0d19c0b8f88f82729c1d81c7 100644 (file)
--- a/src/adaptation/icap/ModXact.cc
+++ b/src/adaptation/icap/ModXact.cc
@@ -44,7 +44,7 @@ Adaptation::Icap::ModXact::State::State()
 }
 
 Adaptation::Icap::ModXact::ModXact(HttpMsg *virginHeader,
-                                   HttpRequest *virginCause, Adaptation::Icap::ServiceRep::Pointer &aService):
+                                   HttpRequest *virginCause, AccessLogEntry::Pointer &alp, Adaptation::Icap::ServiceRep::Pointer &aService):
         AsyncJob("Adaptation::Icap::ModXact"),
         Adaptation::Icap::Xaction("Adaptation::Icap::ModXact", aService),
         virginConsumed(0),
@@ -53,7 +53,8 @@ Adaptation::Icap::ModXact::ModXact(HttpMsg *virginHeader,
         protectGroupBypass(true),
         replyHttpHeaderSize(-1),
         replyHttpBodySize(-1),
-        adaptHistoryId(-1)
+        adaptHistoryId(-1),
+        alMaster(alp)
 {
     assert(virginHeader);
 
@@ -1437,7 +1438,7 @@ void Adaptation::Icap::ModXact::makeRequestHeaders(MemBuf &buf)
 
         HttpReply *reply = dynamic_cast<HttpReply*>(virgin.header);
 
-        if (const char *value = (*i)->match(r, reply)) {
+        if (const char *value = (*i)->match(r, reply, alMaster)) {
             buf.Printf("%s: %s\r\n", (*i)->key.termedBuf(), value);
             Adaptation::History::Pointer ah = request->adaptHistory(false);
             if (ah != NULL) {
@@ -1947,9 +1948,10 @@ void Adaptation::Icap::ModXact::clearError()
 
 /* Adaptation::Icap::ModXactLauncher */
 
-Adaptation::Icap::ModXactLauncher::ModXactLauncher(HttpMsg *virginHeader, HttpRequest *virginCause, Adaptation::ServicePointer aService):
+Adaptation::Icap::ModXactLauncher::ModXactLauncher(HttpMsg *virginHeader, HttpRequest *virginCause, AccessLogEntry::Pointer &alp, Adaptation::ServicePointer aService):
         AsyncJob("Adaptation::Icap::ModXactLauncher"),
-        Adaptation::Icap::Launcher("Adaptation::Icap::ModXactLauncher", aService)
+        Adaptation::Icap::Launcher("Adaptation::Icap::ModXactLauncher", aService),
+        al(alp)
 {
     virgin.setHeader(virginHeader);
     virgin.setCause(virginCause);
@@ -1961,7 +1963,7 @@ Adaptation::Icap::Xaction *Adaptation::Icap::ModXactLauncher::createXaction()
     Adaptation::Icap::ServiceRep::Pointer s =
         dynamic_cast<Adaptation::Icap::ServiceRep*>(theService.getRaw());
     Must(s != NULL);
-    return new Adaptation::Icap::ModXact(virgin.header, virgin.cause, s);
+    return new Adaptation::Icap::ModXact(virgin.header, virgin.cause, al, s);
 }
 
 void Adaptation::Icap::ModXactLauncher::swanSong()

diff --git a/src/adaptation/icap/ModXact.h b/src/adaptation/icap/ModXact.h
index 319aa72b217d7e7e0f6be37737db1cf5a52b4d48..8828d28de2bf687532e6ba08af3d5212a13b938f 100644 (file)
--- a/src/adaptation/icap/ModXact.h
+++ b/src/adaptation/icap/ModXact.h
@@ -32,6 +32,7 @@
 #ifndef SQUID_ICAPMODXACT_H
 #define SQUID_ICAPMODXACT_H
 
+#include "AccessLogEntry.h"
 #include "adaptation/icap/InOut.h"
 #include "adaptation/icap/Launcher.h"
 #include "adaptation/icap/Xaction.h"
@@ -132,7 +133,7 @@ class ModXact: public Xaction, public BodyProducer, public BodyConsumer
 {
 
 public:
-    ModXact(HttpMsg *virginHeader, HttpRequest *virginCause, ServiceRep::Pointer &s);
+    ModXact(HttpMsg *virginHeader, HttpRequest *virginCause, AccessLogEntry::Pointer &alp, ServiceRep::Pointer &s);
     virtual ~ModXact();
 
     // BodyProducer methods
@@ -337,6 +338,7 @@ private:
                      } sending;
     } state;
 
+    AccessLogEntry::Pointer alMaster; ///< Master transaction AccessLogEntry
     CBDATA_CLASS2(ModXact);
 };
 
@@ -345,7 +347,7 @@ private:
 class ModXactLauncher: public Launcher
 {
 public:
-    ModXactLauncher(HttpMsg *virginHeader, HttpRequest *virginCause, Adaptation::ServicePointer s);
+    ModXactLauncher(HttpMsg *virginHeader, HttpRequest *virginCause, AccessLogEntry::Pointer &alp, Adaptation::ServicePointer s);
 
 protected:
     virtual Xaction *createXaction();
@@ -357,6 +359,8 @@ protected:
 
     InOut virgin;
 
+    AccessLogEntry::Pointer al;
+
 private:
     CBDATA_CLASS2(ModXactLauncher);
 };

diff --git a/src/adaptation/icap/ServiceRep.cc b/src/adaptation/icap/ServiceRep.cc
index 6bc1e3032b1bc0f88e88bfb0b7738ad56fea6a5e..59502373a4e92770a05dfba8567d6f0b675506bc 100644 (file)
--- a/src/adaptation/icap/ServiceRep.cc
+++ b/src/adaptation/icap/ServiceRep.cc
@@ -653,9 +653,9 @@ Adaptation::Icap::ServiceRep::optionsFetchTime() const
 
 Adaptation::Initiate *
 Adaptation::Icap::ServiceRep::makeXactLauncher(HttpMsg *virgin,
-        HttpRequest *cause)
+        HttpRequest *cause, AccessLogEntry::Pointer &alp)
 {
-    return new Adaptation::Icap::ModXactLauncher(virgin, cause, this);
+    return new Adaptation::Icap::ModXactLauncher(virgin, cause, alp, this);
 }
 
 // returns a temporary string depicting service status, for debugging

diff --git a/src/adaptation/icap/ServiceRep.h b/src/adaptation/icap/ServiceRep.h
index 6e1a2b0079fb57768a8f08054341310cdb512d4b..7097198fc67d4b9d36e0f6411f5b1a2f78abeff0 100644 (file)
--- a/src/adaptation/icap/ServiceRep.h
+++ b/src/adaptation/icap/ServiceRep.h
@@ -97,7 +97,7 @@ public:
     bool availableForNew() const; ///< a new transaction may start communicating with the service
     bool availableForOld() const; ///< a transaction notified about connection slot availability may start communicating with the service
 
-    virtual Initiate *makeXactLauncher(HttpMsg *virginHeader, HttpRequest *virginCause);
+    virtual Initiate *makeXactLauncher(HttpMsg *virginHeader, HttpRequest *virginCause, AccessLogEntry::Pointer &alp);
 
     void callWhenAvailable(AsyncCall::Pointer &cb, bool priority = false);
     void callWhenReady(AsyncCall::Pointer &cb);

diff --git a/src/cf.data.pre b/src/cf.data.pre
index 5ab5ba86f106c4463b204144d0b3bc50cb9482d3..b0dbe9176b260224b324d17c2e72b44b6ddeac3d 100644 (file)
--- a/src/cf.data.pre
+++ b/src/cf.data.pre
@@ -3706,6 +3706,16 @@ DOC_START
                                default %d/%b/%Y:%H:%M:%S %z
                tr      Response time (milliseconds)
                dt      Total time spent making DNS lookups (milliseconds)
+               tS      Approximate master transaction start time in 
+                       <full seconds since epoch>.<fractional seconds> format.
+                       Currently, Squid considers the master transaction
+                       started when a complete HTTP request header initiating
+                       the transaction is received from the client. This is
+                       the same value that Squid uses to calculate transaction
+                       response time when logging %tr to access.log. Currently,
+                       Squid uses millisecond resolution for %tS values,
+                       similar to the default access.log "current time" field
+                       (%ts.%03tu).
 
        Access Control related format codes:
 

diff --git a/src/client_side.cc b/src/client_side.cc
index 5347b7f92fabbc74c8e832970b538e86f0c89a57..249e72a0b39c0b666fa89b79fb29fb1ee8daa51c 100644 (file)
--- a/src/client_side.cc
+++ b/src/client_side.cc
@@ -543,7 +543,7 @@ ClientHttpRequest::updateCounters()
         ++ statCounter.client_http.errors;
 
     clientUpdateStatHistCounters(logType,
-                                 tvSubMsec(start_time, current_time));
+                                 tvSubMsec(al->cache.start_time, current_time));
 
     clientUpdateHierCounters(&request->hier);
 }
@@ -649,7 +649,7 @@ ClientHttpRequest::logRequest()
 
     al->cache.code = logType;
 
-    al->cache.msec = tvSubMsec(start_time, current_time);
+    al->cache.msec = tvSubMsec(al->cache.start_time, current_time);
 
     if (request)
         prepareLogWithRequestDetails(request, al);
@@ -672,7 +672,7 @@ ClientHttpRequest::logRequest()
     (void)SyncNotes(*al, *request);
     typedef Notes::iterator ACAMLI;
     for (ACAMLI i = Config.notes.begin(); i != Config.notes.end(); ++i) {
-        if (const char *value = (*i)->match(request, al->reply)) {
+        if (const char *value = (*i)->match(request, al->reply, NULL)) {
             NotePairs &notes = SyncNotes(*al, *request);
             notes.add((*i)->key.termedBuf(), value);
             debugs(33, 3, HERE << (*i)->key.termedBuf() << " " << value);

diff --git a/src/client_side_request.cc b/src/client_side_request.cc
index f14c38510074ec035ca922ea261232f3b04ce5a7..e7df8a2515b36efddb3f45e1aa87973d3b1ccdc9 100644 (file)
--- a/src/client_side_request.cc
+++ b/src/client_side_request.cc
@@ -160,9 +160,9 @@ ClientHttpRequest::ClientHttpRequest(ConnStateData * aConn) :
 #endif
         loggingEntry_(NULL)
 {
-    start_time = current_time;
     setConn(aConn);
     al = new AccessLogEntry;
+    al->cache.start_time = current_time;
     al->tcpClient = clientConnection = aConn->clientConnection;
 #if USE_SSL
     if (aConn->clientConnection != NULL && aConn->clientConnection->isOpen()) {
@@ -322,7 +322,8 @@ clientBeginRequest(const HttpRequestMethod& method, char const *url, CSCB * stre
     ClientHttpRequest *http = new ClientHttpRequest(NULL);
     HttpRequest *request;
     StoreIOBuffer tempBuffer;
-    http->start_time = current_time;
+    if (http->al != NULL)
+        http->al->cache.start_time = current_time;
     /* this is only used to adjust the connection offset in client_side.c */
     http->req_sz = 0;
     tempBuffer.length = taillen;
@@ -1706,7 +1707,7 @@ ClientHttpRequest::doCallouts()
             calloutContext->adaptation_acl_check_done = true;
             if (Adaptation::AccessCheck::Start(
                         Adaptation::methodReqmod, Adaptation::pointPreCache,
-                        request, NULL, this))
+                        request, NULL, calloutContext->http->al, this))
                 return; // will call callback
         }
 #endif
@@ -1855,7 +1856,7 @@ ClientHttpRequest::startAdaptation(const Adaptation::ServiceGroupPointer &g)
     assert(!virginHeadSource);
     assert(!adaptedBodySource);
     virginHeadSource = initiateAdaptation(
-                           new Adaptation::Iterator(request, NULL, g));
+                           new Adaptation::Iterator(request, NULL, al, g));
 
     // we could try to guess whether we can bypass this adaptation
     // initiation failure, but it should not really happen

diff --git a/src/client_side_request.h b/src/client_side_request.h
index e4744ab8de660ed3439b06f0f66e448579ba3efc..e34a2c76ca7d7e870af3d1e4adec948ffd2bf677 100644 (file)
--- a/src/client_side_request.h
+++ b/src/client_side_request.h
@@ -105,7 +105,6 @@ public:
     // NP: still an enum so each stage altering it must take care when replacing it.
     LogTags logType;
 
-    struct timeval start_time;
     AccessLogEntry::Pointer al; ///< access.log entry
 
     struct {

diff --git a/src/format/ByteCode.h b/src/format/ByteCode.h
index d32227d6e4bef15f1bb07d9d18bb52b6fb301027..43bd5ea02ab08e7de6ea35cfae911d1380981acc 100644 (file)
--- a/src/format/ByteCode.h
+++ b/src/format/ByteCode.h
@@ -140,6 +140,7 @@ typedef enum {
     LFT_TIME_SUBSECOND,
     LFT_TIME_LOCALTIME,
     LFT_TIME_GMT,
+    LFT_TIME_START, // the time the master transaction started
 
     /* processing time details */
     LFT_TIME_TO_HANDLE_REQUEST,

diff --git a/src/format/Format.cc b/src/format/Format.cc
index 70c79aa62c4d9cd086b3a2b9f96100a68bfe2bf0..dcd64034d9be787a6cf6df97bda1d67c08e9e705 100644 (file)
--- a/src/format/Format.cc
+++ b/src/format/Format.cc
@@ -495,6 +495,13 @@ Format::Format::assemble(MemBuf &mb, const AccessLogEntry::Pointer &al, int logS
 
         break;
 
+        case LFT_TIME_START: {
+            int precision = fmt->widthMax >=0 ? fmt->widthMax : 3;
+            snprintf(tmp, sizeof(tmp), "%0*" PRId64 ".%0*d", fmt->zero && (fmt->widthMin - precision - 1 >= 0) ? fmt->widthMin - precision - 1 : 0, al->cache.start_time.tv_sec, precision, (int)(al->cache.start_time.tv_usec / fmt->divisor));
+            out = tmp;
+        }
+            break;
+
         case LFT_TIME_TO_HANDLE_REQUEST:
             outint = al->cache.msec;
             doint = 1;
@@ -1169,7 +1176,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;
+            const bool haveMaxWidth = fmt->widthMax >=0 && !doint && !dooff && !fmt->divisor;
             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 af80f95baa48c217ff173671e85eda92b04f7f81..e10cef5121a41b7c9d92c5d743a56159ad67eed8 100644 (file)
--- a/src/format/Token.cc
+++ b/src/format/Token.cc
@@ -51,6 +51,7 @@ static TokenTableEntry TokenTable2C[] = {
     {"tu", LFT_TIME_SUBSECOND},
     {"tl", LFT_TIME_LOCALTIME},
     {"tg", LFT_TIME_GMT},
+    {"tS", LFT_TIME_START},
     {"tr", LFT_TIME_TO_HANDLE_REQUEST},
 
     {"<pt", LFT_PEER_RESPONSE_TIME},
@@ -490,18 +491,18 @@ done:
         Config.onoff.log_fqdn = 1;
         break;
 
+    case LFT_TIME_START:
     case LFT_TIME_SUBSECOND:
         divisor = 1000;
 
         if (widthMax > 0) {
-            int i;
             divisor = 1000000;
 
-            for (i = widthMax; i > 1; --i)
+            for (int i = widthMax; i > 0; --i)
                 divisor /= 10;
 
             if (!divisor)
-                divisor = 0;
+                divisor = 1;
         }
         break;
 

diff --git a/src/stat.cc b/src/stat.cc
index 94e512cf5a33661db5c70c6839db89094a0e3e05..ffad2c2c03d512602959d575e3c9e69ce5c891c0 100644 (file)
--- a/src/stat.cc
+++ b/src/stat.cc
@@ -2042,9 +2042,9 @@ statClientRequests(StoreEntry * s)
         e = http->storeEntry();
         storeAppendPrintf(s, "entry %p/%s\n", e, e ? e->getMD5Text() : "N/A");
         storeAppendPrintf(s, "start %ld.%06d (%f seconds ago)\n",
-                          (long int) http->start_time.tv_sec,
-                          (int) http->start_time.tv_usec,
-                          tvSubDsec(http->start_time, current_time));
+                          (long int) http->al->cache.start_time.tv_sec,
+                          (int) http->al->cache.start_time.tv_usec,
+                          tvSubDsec(http->al->cache.start_time, current_time));
 #if USE_AUTH
         if (http->request->auth_user_request != NULL)
             p = http->request->auth_user_request->username();

diff --git a/src/tests/stub_libformat.cc b/src/tests/stub_libformat.cc
index 9278c69930aa67acd0cdfa87dccea98a15f95a0f..49ec2c66df799229d13950726e435c932ee04937 100644 (file)
--- a/src/tests/stub_libformat.cc
+++ b/src/tests/stub_libformat.cc
@@ -5,3 +5,6 @@
 #include "tests/STUB.h"
 
 void Format::Format::assemble(MemBuf &mb, const AccessLogEntryPointer &al, int logSequenceNumber) const STUB
+bool Format::Format::parse(char const*) STUB
+Format::Format::Format(char const*) STUB
+Format::Format::~Format() STUB