------------------------------------------------------------ revno: 13170 revision-id: chtsanti@users.sourceforge.net-20131205110445-gv1h47u6pv8sjgi9 parent: squid3@treenet.co.nz-20131204005734-ecd56l6nfyow0go1 committer: Christos Tsantilas branch nick: trunk timestamp: Thu 2013-12-05 13:04:45 +0200 message: %tS logformat code This patch add the %tS logformat code to represent master transaction start time in . 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 ------------------------------------------------------------ # Bazaar merge directive format 2 (Bazaar 0.90) # revision_id: chtsanti@users.sourceforge.net-20131205110445-\ # gv1h47u6pv8sjgi9 # target_branch: http://bzr.squid-cache.org/bzr/squid3/trunk/ # testament_sha1: ae47fa4252a4dcf3c61f56ea3a065566135f3d3f # timestamp: 2013-12-05 11:54:03 +0000 # source_branch: http://bzr.squid-cache.org/bzr/squid3/trunk/ # base_revision_id: squid3@treenet.co.nz-20131204005734-\ # ecd56l6nfyow0go1 # # Begin patch === modified file 'src/AccessLogEntry.h' --- src/AccessLogEntry.h 2013-11-11 12:09:44 +0000 +++ src/AccessLogEntry.h 2013-12-05 11:04:45 +0000 @@ -176,6 +176,7 @@ 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; === modified file 'src/Notes.cc' --- src/Notes.cc 2013-10-27 05:08:49 +0000 +++ src/Notes.cc 2013-12-05 11:04:45 +0000 @@ -56,7 +56,7 @@ } 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 @@ 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 @@ 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 @@ label.append('='); label.append(value); aclParseAclList(parser, ¬eValue->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) { === modified file 'src/Notes.h' --- src/Notes.h 2013-10-27 05:08:49 +0000 +++ src/Notes.h 2013-12-05 11:04:45 +0000 @@ -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 AccessLogEntryPointer; /** * Used to store a note configuration. The notes are custom key:value @@ -31,9 +33,11 @@ { public: typedef RefCount 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 Values; @@ -50,8 +54,10 @@ * 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 @@ 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 @@ 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: /** === modified file 'src/Server.cc' --- src/Server.cc 2013-11-18 15:55:05 +0000 +++ src/Server.cc 2013-12-05 11:04:45 +0000 @@ -561,7 +561,7 @@ } 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 @@ // 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; === modified file 'src/adaptation/AccessCheck.cc' --- src/adaptation/AccessCheck.cc 2013-02-16 17:05:36 +0000 +++ src/adaptation/AccessCheck.cc 2013-12-05 11:04:45 +0000 @@ -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 @@ 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; } === modified file 'src/adaptation/AccessCheck.h' --- src/adaptation/AccessCheck.h 2013-10-25 00:13:46 +0000 +++ src/adaptation/AccessCheck.h 2013-12-05 11:04:45 +0000 @@ -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 @@ // 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 === modified file 'src/adaptation/Config.cc' --- src/adaptation/Config.cc 2013-11-12 14:48:50 +0000 +++ src/adaptation/Config.cc 2013-12-05 11:04:45 +0000 @@ -66,7 +66,7 @@ "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* === modified file 'src/adaptation/Iterator.cc' --- src/adaptation/Iterator.cc 2013-11-12 14:48:50 +0000 +++ src/adaptation/Iterator.cc 2013-12-05 11:04:45 +0000 @@ -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 @@ } theLauncher = initiateAdaptation( - service->makeXactLauncher(theMsg, theCause)); + service->makeXactLauncher(theMsg, theCause, al)); Must(initiated(theLauncher)); Must(!done()); } @@ -276,7 +278,7 @@ 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); === modified file 'src/adaptation/Iterator.h' --- src/adaptation/Iterator.h 2013-10-25 00:13:46 +0000 +++ src/adaptation/Iterator.h 2013-12-05 11:04:45 +0000 @@ -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 @@ { public: Iterator(HttpMsg *virginHeader, HttpRequest *virginCause, + AccessLogEntry::Pointer &alp, const Adaptation::ServiceGroupPointer &aGroup); virtual ~Iterator(); @@ -57,6 +59,7 @@ 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 theLauncher; ///< current transaction launcher int iterations; ///< number of steps initiated bool adapted; ///< whether the virgin message has been replaced === modified file 'src/adaptation/Service.h' --- src/adaptation/Service.h 2013-10-25 00:13:46 +0000 +++ src/adaptation/Service.h 2013-12-05 11:04:45 +0000 @@ -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 @@ 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; === modified file 'src/adaptation/ServiceFilter.cc' --- src/adaptation/ServiceFilter.cc 2013-10-25 00:13:46 +0000 +++ src/adaptation/ServiceFilter.cc 2013-12-05 11:04:45 +0000 @@ -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 @@ method(f.method), point(f.point), request(f.request), - reply(f.reply) + reply(f.reply), + al(f.al) { if (request) HTTPMSGLOCK(request); === modified file 'src/adaptation/ServiceFilter.h' --- src/adaptation/ServiceFilter.h 2009-07-13 01:20:26 +0000 +++ src/adaptation/ServiceFilter.h 2013-12-05 11:04:45 +0000 @@ -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 @@ 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 @@ 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 === modified file 'src/adaptation/ecap/ServiceRep.cc' --- src/adaptation/ecap/ServiceRep.cc 2013-11-29 19:47:54 +0000 +++ src/adaptation/ecap/ServiceRep.cc 2013-12-05 11:04:45 +0000 @@ -240,7 +240,7 @@ Adaptation::Initiate * Adaptation::Ecap::ServiceRep::makeXactLauncher(HttpMsg *virgin, - HttpRequest *cause) + HttpRequest *cause, AccessLogEntry::Pointer &alp) { Must(up()); @@ -253,7 +253,7 @@ 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; === modified file 'src/adaptation/ecap/ServiceRep.h' --- src/adaptation/ecap/ServiceRep.h 2013-10-25 00:13:46 +0000 +++ src/adaptation/ecap/ServiceRep.h 2013-12-05 11:04:45 +0000 @@ -31,7 +31,7 @@ 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; === modified file 'src/adaptation/ecap/XactionRep.cc' --- src/adaptation/ecap/XactionRep.cc 2013-11-29 19:47:54 +0000 +++ src/adaptation/ecap/XactionRep.cc 2013-12-05 11:04:45 +0000 @@ -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 @@ }; 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 @@ 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 @@ 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 @@ 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 @@ 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(); === modified file 'src/adaptation/ecap/XactionRep.h' --- src/adaptation/ecap/XactionRep.h 2013-11-29 19:47:54 +0000 +++ src/adaptation/ecap/XactionRep.h 2013-12-05 11:04:45 +0000 @@ -27,7 +27,7 @@ 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 AdapterXaction; @@ -114,6 +114,7 @@ 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); }; === modified file 'src/adaptation/icap/ModXact.cc' --- src/adaptation/icap/ModXact.cc 2013-11-23 00:58:42 +0000 +++ src/adaptation/icap/ModXact.cc 2013-12-05 11:04:45 +0000 @@ -44,7 +44,7 @@ } 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 @@ protectGroupBypass(true), replyHttpHeaderSize(-1), replyHttpBodySize(-1), - adaptHistoryId(-1) + adaptHistoryId(-1), + alMaster(alp) { assert(virginHeader); @@ -1437,7 +1438,7 @@ HttpReply *reply = dynamic_cast(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 @@ /* 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::ServiceRep::Pointer s = dynamic_cast(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() === modified file 'src/adaptation/icap/ModXact.h' --- src/adaptation/icap/ModXact.h 2013-10-25 00:13:46 +0000 +++ src/adaptation/icap/ModXact.h 2013-12-05 11:04:45 +0000 @@ -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 @@ { 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 @@ } sending; } state; + AccessLogEntry::Pointer alMaster; ///< Master transaction AccessLogEntry CBDATA_CLASS2(ModXact); }; @@ -345,7 +347,7 @@ 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 @@ InOut virgin; + AccessLogEntry::Pointer al; + private: CBDATA_CLASS2(ModXactLauncher); }; === modified file 'src/adaptation/icap/ServiceRep.cc' --- src/adaptation/icap/ServiceRep.cc 2013-02-12 11:34:35 +0000 +++ src/adaptation/icap/ServiceRep.cc 2013-12-05 11:04:45 +0000 @@ -653,9 +653,9 @@ 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 === modified file 'src/adaptation/icap/ServiceRep.h' --- src/adaptation/icap/ServiceRep.h 2013-10-25 00:13:46 +0000 +++ src/adaptation/icap/ServiceRep.h 2013-12-05 11:04:45 +0000 @@ -97,7 +97,7 @@ 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); === modified file 'src/cf.data.pre' --- src/cf.data.pre 2013-11-12 14:48:50 +0000 +++ src/cf.data.pre 2013-12-05 11:04:45 +0000 @@ -3706,6 +3706,16 @@ 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 + . 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: === modified file 'src/client_side.cc' --- src/client_side.cc 2013-11-23 00:58:42 +0000 +++ src/client_side.cc 2013-12-05 11:04:45 +0000 @@ -543,7 +543,7 @@ ++ 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 @@ 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 @@ (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 ¬es = SyncNotes(*al, *request); notes.add((*i)->key.termedBuf(), value); debugs(33, 3, HERE << (*i)->key.termedBuf() << " " << value); === modified file 'src/client_side_request.cc' --- src/client_side_request.cc 2013-12-04 00:57:34 +0000 +++ src/client_side_request.cc 2013-12-05 11:04:45 +0000 @@ -160,9 +160,9 @@ #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 @@ 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 @@ 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 @@ 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 === modified file 'src/client_side_request.h' --- src/client_side_request.h 2013-10-25 00:13:46 +0000 +++ src/client_side_request.h 2013-12-05 11:04:45 +0000 @@ -105,7 +105,6 @@ // 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 { === modified file 'src/format/ByteCode.h' --- src/format/ByteCode.h 2013-10-29 02:24:29 +0000 +++ src/format/ByteCode.h 2013-12-05 11:04:45 +0000 @@ -140,6 +140,7 @@ 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, === modified file 'src/format/Format.cc' --- src/format/Format.cc 2013-11-11 12:09:44 +0000 +++ src/format/Format.cc 2013-12-05 11:04:45 +0000 @@ -495,6 +495,13 @@ 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 @@ } // 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; === modified file 'src/format/Token.cc' --- src/format/Token.cc 2013-10-29 02:24:29 +0000 +++ src/format/Token.cc 2013-12-05 11:04:45 +0000 @@ -51,6 +51,7 @@ {"tu", LFT_TIME_SUBSECOND}, {"tl", LFT_TIME_LOCALTIME}, {"tg", LFT_TIME_GMT}, + {"tS", LFT_TIME_START}, {"tr", LFT_TIME_TO_HANDLE_REQUEST}, {" 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; === modified file 'src/stat.cc' --- src/stat.cc 2013-11-23 00:58:42 +0000 +++ src/stat.cc 2013-12-05 11:04:45 +0000 @@ -2042,9 +2042,9 @@ 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(); === modified file 'src/tests/stub_libformat.cc' --- src/tests/stub_libformat.cc 2012-08-28 13:00:30 +0000 +++ src/tests/stub_libformat.cc 2013-12-05 11:04:45 +0000 @@ -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