%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 === modified file 'src/AccessLogEntry.h' --- src/AccessLogEntry.h 2013-11-11 12:09:44 +0000 +++ src/AccessLogEntry.h 2013-11-21 10:40:06 +0000 @@ -159,40 +159,41 @@ public: CacheDetails() : caddr(), highOffset(0), objectSize(0), code (LOG_TAG_NONE), msec(0), rfc931 (NULL), extuser(NULL), #if USE_SSL ssluser(NULL), #endif port(NULL) { ; } Ip::Address caddr; 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; #if USE_SSL const char *ssluser; Ssl::X509_Pointer sslClientCert; ///< cert received from the client #endif AnyP::PortCfg *port; } cache; /** \brief This subclass holds log info for various headers in raw format * \todo shuffle this to the relevant protocol section. */ class Headers { public: Headers() : request(NULL), === modified file 'src/Notes.cc' --- src/Notes.cc 2013-10-27 05:08:49 +0000 +++ src/Notes.cc 2013-11-21 11:39:31 +0000 @@ -39,86 +39,99 @@ #include "Store.h" #include "StrList.h" #include #include Note::Value::~Value() { aclDestroyAclList(&aclList); } Note::Value::Pointer Note::addValue(const String &value) { Value::Pointer v = new Value(value); values.push_back(v); return v; } const char * -Note::match(HttpRequest *request, HttpReply *reply) +Note::match(HttpRequest *request, HttpReply *reply, const AccessLogEntry::Pointer &al) { typedef Values::iterator VLI; ACLFilledChecklist ch(NULL, request, NULL); ch.reply = reply; if (reply) HTTPMSGLOCK(ch.reply); for (VLI i = values.begin(); i != values.end(); ++i ) { 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; } Note::Pointer Notes::add(const String ¬eKey) { typedef Notes::NotesList::iterator AMLI; for (AMLI i = notes.begin(); i != notes.end(); ++i) { if ((*i)->key == noteKey) return (*i); } Note::Pointer note = new Note(noteKey); notes.push_back(note); return note; } 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); String label(key); 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) { fatalf("%s:%d: meta key \"%s\" is a reserved %s name", cfg_filename, config_lineno, note->key.termedBuf(), descr ? descr : ""); } } } return note; } void Notes::dump(StoreEntry *entry, const char *key) { typedef Notes::NotesList::iterator AMLI; for (AMLI m = notes.begin(); m != notes.end(); ++m) { typedef Note::Values::iterator VLI; for (VLI v =(*m)->values.begin(); v != (*m)->values.end(); ++v ) { === modified file 'src/Notes.h' --- src/Notes.h 2013-10-27 05:08:49 +0000 +++ src/Notes.h 2013-11-21 12:03:44 +0000 @@ -1,114 +1,121 @@ #ifndef SQUID_NOTES_H #define SQUID_NOTES_H #include "acl/forward.h" #include "base/RefCount.h" #include "base/Vector.h" #include "CbDataList.h" +#include "format/Format.h" #include "MemPool.h" #include "SquidString.h" #include "typedefs.h" #if HAVE_STRING #include #endif class HttpRequest; class HttpReply; +typedef RefCount AccessLogEntryPointer; /** * Used to store a note configuration. The notes are custom key:value * pairs ICAP request headers or ECAP options used to pass * custom transaction-state related meta information to squid * internal subsystems or to adaptation services. */ class Note: public RefCountable { public: typedef RefCount Pointer; /// Stores a value for the note. class Value: public RefCountable { 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; explicit Note(const String &aKey): key(aKey) {} /** * Adds a value to the note and returns a pointer to the * related Value object. */ Value::Pointer addValue(const String &value); /** * 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 }; class ConfigParser; /** * Used to store a notes configuration list. */ class Notes { public: typedef Vector NotesList; 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(); } /** * Parse a notes line and returns a pointer to the * parsed Note object. */ Note::Pointer parse(ConfigParser &parser); /** * Dump the notes list to the given StoreEntry object. */ void dump(StoreEntry *entry, const char *name); void clean(); /// clean the notes list /// points to the first argument iterator begin() { return notes.begin(); } /// points to the end of list iterator end() { return notes.end(); } /// return true if the notes list is empty bool empty() { return notes.empty(); } 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: /** * Adds a note to the notes list and returns a pointer to the * related Note object. If the note key already exists in list, * returns a pointer to the existing object. */ Note::Pointer add(const String ¬eKey); }; /** * Used to store list of notes */ class NotePairs: public RefCountable { public: typedef RefCount Pointer; /** * Used to store a note key/value pair. === modified file 'src/Server.cc' --- src/Server.cc 2013-10-25 00:13:46 +0000 +++ src/Server.cc 2013-11-19 16:48:36 +0000 @@ -538,41 +538,41 @@ void ServerStateData::startAdaptation(const Adaptation::ServiceGroupPointer &group, HttpRequest *cause) { debugs(11, 5, "ServerStateData::startAdaptation() called"); // check whether we should be sending a body as well // start body pipe to feed ICAP transaction if needed assert(!virginBodyDestination); HttpReply *vrep = virginReply(); assert(!vrep->body_pipe); int64_t size = 0; if (vrep->expectingBody(cause->method, size) && size) { virginBodyDestination = new BodyPipe(this); vrep->body_pipe = virginBodyDestination; debugs(93, 6, HERE << "will send virgin reply body to " << virginBodyDestination << "; size: " << size); if (size > 0) virginBodyDestination->setBodySize(size); } adaptedHeadSource = initiateAdaptation( - new Adaptation::Iterator(vrep, cause, group)); + new Adaptation::Iterator(vrep, cause, fwd->al, group)); startedAdaptation = initiated(adaptedHeadSource); Must(startedAdaptation); } // properly cleans up ICAP-related state // may be called multiple times void ServerStateData::cleanAdaptation() { debugs(11,5, HERE << "cleaning ICAP; ACL: " << adaptationAccessCheckPending); if (virginBodyDestination != NULL) stopProducingFor(virginBodyDestination, false); announceInitiatorAbort(adaptedHeadSource); if (adaptedBodySource != NULL) stopConsumingFrom(adaptedBodySource); if (!adaptationAccessCheckPending) // we cannot cancel a pending callback assert(doneWithAdaptation()); // make sure the two methods are in sync @@ -901,41 +901,41 @@ void ServerStateData::sendBodyIsTooLargeError() { ErrorState *err = new ErrorState(ERR_TOO_BIG, Http::scForbidden, request); fwd->fail(err); fwd->dontRetry(true); abortTransaction("Virgin body too large."); } // TODO: when HttpStateData sends all errors to ICAP, // we should be able to move this at the end of setVirginReply(). void ServerStateData::adaptOrFinalizeReply() { #if USE_ADAPTATION // TODO: merge with client side and return void to hide the on/off logic? // 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; #endif setFinalReply(virginReply()); } /// initializes bodyBytesRead stats if needed and applies delta void ServerStateData::adjustBodyBytesRead(const int64_t delta) { int64_t &bodyBytesRead = originalRequest()->hier.bodyBytesRead; // if we got here, do not log a dash even if we got nothing from the server if (bodyBytesRead < 0) bodyBytesRead = 0; bodyBytesRead += delta; // supports negative and zero deltas === modified file 'src/adaptation/AccessCheck.cc' --- src/adaptation/AccessCheck.cc 2013-02-16 17:05:36 +0000 +++ src/adaptation/AccessCheck.cc 2013-11-19 16:44:40 +0000 @@ -1,48 +1,50 @@ #include "squid.h" +#include "AccessLogEntry.h" #include "acl/FilledChecklist.h" #include "adaptation/AccessCheck.h" #include "adaptation/AccessRule.h" #include "adaptation/Config.h" #include "adaptation/Initiator.h" #include "adaptation/Service.h" #include "adaptation/ServiceGroups.h" #include "base/AsyncJobCalls.h" #include "base/TextException.h" #include "ConfigParser.h" #include "globals.h" #include "HttpReply.h" #include "HttpRequest.h" /** \cond AUTODOCS-IGNORE */ cbdata_type Adaptation::AccessCheck::CBDATA_AccessCheck = CBDATA_UNKNOWN; /** \endcond */ 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; } debugs(83, 3, HERE << "adaptation off, skipping"); return false; } Adaptation::AccessCheck::AccessCheck(const ServiceFilter &aFilter, Adaptation::Initiator *initiator): AsyncJob("AccessCheck"), filter(aFilter), theInitiator(initiator), acl_checklist(NULL) { #if ICAP_CLIENT Adaptation::Icap::History::Pointer h = filter.request->icapHistory(); if (h != NULL) h->start("ACL"); #endif debugs(93, 5, HERE << "AccessCheck constructed for " << === modified file 'src/adaptation/AccessCheck.h' --- src/adaptation/AccessCheck.h 2013-10-25 00:13:46 +0000 +++ src/adaptation/AccessCheck.h 2013-11-19 16:44:40 +0000 @@ -1,48 +1,49 @@ #ifndef SQUID_ADAPTATION__ACCESS_CHECK_H #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" #include "adaptation/ServiceFilter.h" #include "base/AsyncJob.h" class HttpRequest; class HttpReply; class ACLFilledChecklist; namespace Adaptation { class AccessRule; // checks adaptation_access rules to find a matching adaptation service class AccessCheck: public virtual AsyncJob { public: typedef void AccessCheckCallback(ServiceGroupPointer group, void *data); // 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 AccessCheck(const ServiceFilter &aFilter, Adaptation::Initiator *); ~AccessCheck(); private: const ServiceFilter filter; CbcPointer theInitiator; ///< the job which ordered this access check ACLFilledChecklist *acl_checklist; typedef int Candidate; typedef Vector Candidates; Candidates candidates; Candidate topCandidate() const { return *candidates.begin(); } ServiceGroupPointer topGroup() const; // may return nil void callBack(const ServiceGroupPointer &g); bool isCandidate(AccessRule &r); === modified file 'src/adaptation/Config.cc' --- src/adaptation/Config.cc 2013-11-12 14:48:50 +0000 +++ src/adaptation/Config.cc 2013-11-20 14:10:16 +0000 @@ -49,41 +49,41 @@ int Adaptation::Config::send_client_ip = false; int Adaptation::Config::send_username = false; int Adaptation::Config::use_indirect_client = true; const char *metasBlacklist[] = { "Methods", "Service", "ISTag", "Encapsulated", "Opt-body-type", "Max-Connections", "Options-TTL", "Date", "Service-ID", "Allow", "Preview", "Transfer-Preview", "Transfer-Ignore", "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* Adaptation::Config::newServiceConfig() const { return new ServiceConfig(); } void Adaptation::Config::removeService(const String& service) { removeRule(service); const Groups& groups = AllGroups(); for (unsigned int i = 0; i < groups.size(); ) { const ServiceGroupPointer group = groups[i]; const ServiceGroup::Store& services = group->services; typedef ServiceGroup::Store::const_iterator SGSI; for (SGSI it = services.begin(); it != services.end(); ++it) { if (*it == service) { group->removedServices.push_back(service); === modified file 'src/adaptation/Iterator.cc' --- src/adaptation/Iterator.cc 2013-11-12 14:48:50 +0000 +++ src/adaptation/Iterator.cc 2013-11-21 11:41:26 +0000 @@ -1,44 +1,46 @@ /* * DEBUG: section 93 Adaptation */ #include "squid.h" #include "adaptation/Answer.h" #include "adaptation/Config.h" #include "adaptation/Iterator.h" #include "adaptation/Service.h" #include "adaptation/ServiceFilter.h" #include "adaptation/ServiceGroups.h" #include "base/TextException.h" #include "HttpMsg.h" #include "HttpReply.h" #include "HttpRequest.h" 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) { if (theCause != NULL) HTTPMSGLOCK(theCause); if (theMsg != NULL) HTTPMSGLOCK(theMsg); } Adaptation::Iterator::~Iterator() { assert(!theLauncher); HTTPMSGUNLOCK(theMsg); HTTPMSGUNLOCK(theCause); } void Adaptation::Iterator::start() { @@ -82,41 +84,41 @@ if (iterations > Adaptation::Config::service_iteration_limit) { debugs(93,DBG_CRITICAL, "Adaptation iterations limit (" << Adaptation::Config::service_iteration_limit << ") exceeded:\n" << "\tPossible service loop with " << theGroup->kind << " " << theGroup->id << ", plan=" << thePlan); throw TexcHere("too many adaptations"); } ServicePointer service = thePlan.current(); Must(service != NULL); debugs(93,5, HERE << "using adaptation service: " << service->cfg().key); if (Adaptation::Config::needHistory) { Adaptation::History::Pointer ah = request->adaptHistory(true); SBuf uid(thePlan.current()->cfg().key); ah->recordAdaptationService(uid); } theLauncher = initiateAdaptation( - service->makeXactLauncher(theMsg, theCause)); + service->makeXactLauncher(theMsg, theCause, al)); Must(initiated(theLauncher)); Must(!done()); } void Adaptation::Iterator::noteAdaptationAnswer(const Answer &answer) { switch (answer.kind) { case Answer::akForward: handleAdaptedHeader(const_cast(answer.message.getRaw())); break; case Answer::akBlock: handleAdaptationBlock(answer); break; case Answer::akError: handleAdaptationError(answer.final); break; } @@ -259,24 +261,24 @@ Adaptation::ServiceFilter Adaptation::Iterator::filter() const { // the method may differ from theGroup->method due to request satisfaction Method method = methodNone; // temporary variables, no locking needed HttpRequest *req = NULL; HttpReply *rep = NULL; if (HttpRequest *r = dynamic_cast(theMsg)) { method = methodReqmod; req = r; rep = NULL; } else if (HttpReply *theReply = dynamic_cast(theMsg)) { method = methodRespmod; req = theCause; rep = theReply; } else { 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-11-19 16:44:40 +0000 @@ -1,69 +1,72 @@ #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" class HttpMsg; class HttpRequest; namespace Adaptation { /* Iterator is started by client or server Initiators. It iterates services in a given group, starting transaction launcher for each service, according to the service plan. Service plans support adaptation sets and chains. Note: Initiate must be the first parent for cbdata to work. We use a temporary InitiatorHolder/toCbdata hacks and do not call cbdata operations on the initiator directly. */ /// iterates services in ServiceGroup, starting adaptation launchers class Iterator: public Initiate, public Initiator { public: Iterator(HttpMsg *virginHeader, HttpRequest *virginCause, + AccessLogEntry::Pointer &alp, const Adaptation::ServiceGroupPointer &aGroup); virtual ~Iterator(); // Adaptation::Initiate: asynchronous communication with the initiator void noteInitiatorAborted(); // Adaptation::Initiator: asynchronous communication with the current launcher virtual void noteAdaptationAnswer(const Answer &answer); protected: // Adaptation::Initiate API implementation virtual void start(); virtual bool doneAll() const; virtual void swanSong(); /// launches adaptation for the service selected by the plan void step(); /// replace the current group and plan with service-proposed ones if needed bool updatePlan(bool adopt); // returns true iff the plan was replaced /// creates service filter for the current step ServiceFilter filter() const; void handleAdaptedHeader(HttpMsg *msg); void handleAdaptationBlock(const Answer &answer); void handleAdaptationError(bool final); ServiceGroupPointer theGroup; ///< the service group we are iterating 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 CBDATA_CLASS2(Iterator); }; } // namespace Adaptation #endif /* SQUID_ADAPTATION__ITERATOR_H */ === modified file 'src/adaptation/Service.h' --- src/adaptation/Service.h 2013-10-25 00:13:46 +0000 +++ src/adaptation/Service.h 2013-11-19 17:42:22 +0000 @@ -1,54 +1,55 @@ #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" #include "base/RefCount.h" #include "SquidString.h" // TODO: Move src/ICAP/ICAPServiceRep.h API comments here and update them class HttpMsg; class HttpRequest; namespace Adaptation { // manages adaptation service configuration in squid.conf // specific adaptation mechanisms extend this class class Service: public RefCountable { public: typedef RefCount Pointer; typedef String Id; public: explicit Service(const ServiceConfigPointer &aConfig); virtual ~Service(); virtual bool probed() const = 0; // see comments above 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; // the methods below can only be called on an up() service virtual bool wantsUrl(const String &urlPath) const = 0; // called by transactions to report service failure virtual void noteFailure() = 0; const ServiceConfig &cfg() const { return *theConfig; } virtual void finalize(); // called after creation /// called when removed from the config; the service will be /// auto-destroyed when the last refcounting user leaves virtual void detach() = 0; /// whether detached() was called virtual bool detached() const = 0; protected: === modified file 'src/adaptation/ServiceFilter.cc' --- src/adaptation/ServiceFilter.cc 2013-10-25 00:13:46 +0000 +++ src/adaptation/ServiceFilter.cc 2013-11-19 16:44:40 +0000 @@ -1,44 +1,47 @@ #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); // a lot of code assumes that there is always a virgin request or cause assert(request); HTTPMSGLOCK(request); } 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); if (reply) HTTPMSGLOCK(reply); } Adaptation::ServiceFilter::~ServiceFilter() { HTTPMSGUNLOCK(request); HTTPMSGUNLOCK(reply); } Adaptation::ServiceFilter &Adaptation::ServiceFilter::operator =(const ServiceFilter &f) { if (this != &f) { method = f.method; point = f.point; HTTPMSGUNLOCK(request); === modified file 'src/adaptation/ServiceFilter.h' --- src/adaptation/ServiceFilter.h 2009-07-13 01:20:26 +0000 +++ src/adaptation/ServiceFilter.h 2013-11-19 16:44:40 +0000 @@ -1,31 +1,33 @@ #ifndef SQUID_ADAPTATION__SERVICE_FILTER_H #define SQUID_ADAPTATION__SERVICE_FILTER_H +#include "AccessLogEntry.h" #include "adaptation/Elements.h" class HttpRequest; class HttpReply; namespace Adaptation { /// information used to search for adaptation services 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 ServiceFilter &operator =(const ServiceFilter &f); public: Method method; ///< adaptation direction 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 #endif /* SQUID_ADAPTATION__SERVICE_FILTER_H */ === modified file 'src/adaptation/ecap/ServiceRep.cc' --- src/adaptation/ecap/ServiceRep.cc 2012-08-28 13:00:30 +0000 +++ src/adaptation/ecap/ServiceRep.cc 2013-11-20 11:01:10 +0000 @@ -148,44 +148,44 @@ } bool Adaptation::Ecap::ServiceRep::probed() const { return true; // we "probe" the adapter in finalize(). } bool Adaptation::Ecap::ServiceRep::up() const { return theService != NULL; } bool Adaptation::Ecap::ServiceRep::wantsUrl(const String &urlPath) const { Must(up()); return theService->wantsUrl(urlPath.termedBuf()); } Adaptation::Initiate * Adaptation::Ecap::ServiceRep::makeXactLauncher(HttpMsg *virgin, - HttpRequest *cause) + HttpRequest *cause, AccessLogEntry::Pointer &alp) { Must(up()); - 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; } // returns a temporary string depicting service status, for debugging const char *Adaptation::Ecap::ServiceRep::status() const { // TODO: move generic stuff from eCAP and ICAP to Adaptation static MemBuf buf; buf.reset(); buf.append("[", 1); if (up()) buf.append("up", 2); else buf.append("down", 4); if (detached()) === 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-11-19 17:42:58 +0000 @@ -14,41 +14,41 @@ { namespace Ecap { /* The eCAP service representative maintains information about a single eCAP service that Squid communicates with. One eCAP module may register many eCAP services. */ class ServiceRep : public Adaptation::Service { public: explicit ServiceRep(const ServiceConfigPointer &aConfig); virtual ~ServiceRep(); typedef libecap::shared_ptr AdapterService; /* Adaptation::Service API */ 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; virtual void detach(); virtual bool detached() const; protected: void tryConfigureAndStart(); bool handleFinalizeFailure(const char *error); private: AdapterService theService; // the actual adaptation service we represent bool isDetached; }; /// register loaded eCAP module service void RegisterAdapterService(const ServiceRep::AdapterService& adapterService); /// unregister loaded eCAP module service by service uri void UnregisterAdapterService(const String& serviceUri); === modified file 'src/adaptation/ecap/XactionRep.cc' --- src/adaptation/ecap/XactionRep.cc 2013-10-25 00:13:46 +0000 +++ src/adaptation/ecap/XactionRep.cc 2013-11-20 17:19:14 +0000 @@ -1,68 +1,70 @@ /* * DEBUG: section 93 eCAP Interface */ #include "squid.h" #include #include #include #include #include #include "adaptation/Answer.h" #include "adaptation/ecap/Config.h" #include "adaptation/ecap/XactionRep.h" #include "adaptation/Initiator.h" #include "base/TextException.h" +#include "format/Format.h" #include "HttpReply.h" #include "HttpRequest.h" #include "SquidTime.h" CBDATA_NAMESPACED_CLASS_INIT(Adaptation::Ecap::XactionRep, XactionRep); /// a libecap Visitor for converting adapter transaction options to HttpHeader class OptionsExtractor: public libecap::NamedValueVisitor { public: typedef libecap::Name Name; typedef libecap::Area Area; OptionsExtractor(HttpHeader &aMeta): meta(aMeta) {} // libecap::NamedValueVisitor API virtual void visit(const Name &name, const Area &value) { meta.putExt(name.image().c_str(), value.toString().c_str()); } HttpHeader &meta; ///< where to put extracted options }; 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"), theService(aService), theVirginRep(virginHeader), theCauseRep(NULL), makingVb(opUndecided), proxyingAb(opUndecided), adaptHistoryId(-1), vbProductionFinished(false), - abProductionFinished(false), abProductionAtEnd(false) + abProductionFinished(false), abProductionAtEnd(false), + al(alp) { if (virginCause) theCauseRep = new MessageRep(virginCause); } Adaptation::Ecap::XactionRep::~XactionRep() { assert(!theMaster); delete theCauseRep; theAnswerRep.reset(); } void Adaptation::Ecap::XactionRep::master(const AdapterXaction &x) { Must(!theMaster); Must(x != NULL); theMaster = x; } @@ -163,91 +165,91 @@ String name, value; if (ah->getXxRecord(name, value)) return libecap::Area::FromTempBuffer(value.rawBuf(), value.size()); } } return libecap::Area(); } const libecap::Area Adaptation::Ecap::XactionRep::metaValue(const libecap::Name &name) const { HttpRequest *request = dynamic_cast(theCauseRep ? theCauseRep->raw().header : theVirginRep.raw().header); Must(request); HttpReply *reply = dynamic_cast(theVirginRep.raw().header); if (name.known()) { // must check to avoid empty names matching unset cfg 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(); } } } return libecap::Area(); } void Adaptation::Ecap::XactionRep::visitEachMetaHeader(libecap::NamedValueVisitor &visitor) const { HttpRequest *request = dynamic_cast(theCauseRep ? theCauseRep->raw().header : theVirginRep.raw().header); Must(request); HttpReply *reply = dynamic_cast(theVirginRep.raw().header); 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); visitor.visit(name, value); } } } void Adaptation::Ecap::XactionRep::start() { Must(theMaster); if (!theVirginRep.raw().body_pipe) makingVb = opNever; // there is nothing to deliver HttpRequest *request = dynamic_cast (theCauseRep ? theCauseRep->raw().header : theVirginRep.raw().header); Must(request); HttpReply *reply = dynamic_cast(theVirginRep.raw().header); Adaptation::History::Pointer ah = request->adaptLogHistory(); if (ah != NULL) { // retrying=false because ecap never retries transactions 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(); if (!ah->metaHeaders->hasPair((*i)->key.termedBuf(), v)) ah->metaHeaders->add((*i)->key.termedBuf(), v); } } } theMaster->start(); } void Adaptation::Ecap::XactionRep::swanSong() { // clear body_pipes, if any // this code does not maintain proxying* and canAccessVb states; should it? if (theAnswerRep != NULL) { BodyPipe::Pointer body_pipe = answer().body_pipe; === modified file 'src/adaptation/ecap/XactionRep.h' --- src/adaptation/ecap/XactionRep.h 2013-10-25 00:13:46 +0000 +++ src/adaptation/ecap/XactionRep.h 2013-11-20 11:02:11 +0000 @@ -10,41 +10,41 @@ #include "adaptation/Initiate.h" #include "adaptation/Message.h" #include "BodyPipe.h" #include #include #include #include namespace Adaptation { namespace Ecap { /* The eCAP xaction representative maintains information about a single eCAP xaction that Squid communicates with. One eCAP module may register many eCAP xactions. */ 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 AdapterXaction; void master(const AdapterXaction &aMaster); // establish a link // libecap::host::Xaction API virtual const libecap::Area option(const libecap::Name &name) const; virtual void visitEachOption(libecap::NamedValueVisitor &visitor) const; virtual libecap::Message &virgin(); virtual const libecap::Message &cause(); virtual libecap::Message &adapted(); virtual void useVirgin(); virtual void useAdapted(const libecap::shared_ptr &msg); virtual void blockVirgin(); virtual void adaptationDelayed(const libecap::Delay &); virtual void adaptationAborted(); virtual void vbDiscard(); virtual void vbMake(); virtual void vbStopMaking(); virtual void vbMakeMore(); @@ -97,28 +97,29 @@ /// Return the adaptation meta headers and their values void visitEachMetaHeader(libecap::NamedValueVisitor &visitor) const; private: AdapterXaction theMaster; // the actual adaptation xaction we represent Adaptation::ServicePointer theService; ///< xaction's adaptation service MessageRep theVirginRep; MessageRep *theCauseRep; typedef libecap::shared_ptr MessagePtr; MessagePtr theAnswerRep; typedef enum { opUndecided, opOn, opComplete, opNever } OperationState; OperationState makingVb; //< delivering virgin body from pipe to adapter OperationState proxyingAb; // delivering adapted body from adapter to core int adaptHistoryId; ///< adaptation history slot reservation 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); }; } // namespace Ecap } // namespace Adaptation #endif /* SQUID_ECAP_XACTION_REP_H */ === modified file 'src/adaptation/icap/ModXact.cc' --- src/adaptation/icap/ModXact.cc 2013-11-11 12:09:44 +0000 +++ src/adaptation/icap/ModXact.cc 2013-11-20 14:54:57 +0000 @@ -27,50 +27,51 @@ #include "SquidTime.h" #include "URL.h" // flow and terminology: // HTTP| --> receive --> encode --> write --> |network // end | <-- send <-- parse <-- read <-- |end // TODO: replace gotEncapsulated() with something faster; we call it often CBDATA_NAMESPACED_CLASS_INIT(Adaptation::Icap, ModXact); CBDATA_NAMESPACED_CLASS_INIT(Adaptation::Icap, ModXactLauncher); static const size_t TheBackupLimit = BodyPipe::MaxCapacity; Adaptation::Icap::ModXact::State::State() { memset(this, 0, sizeof(*this)); } 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), bodyParser(NULL), canStartBypass(false), // too early protectGroupBypass(true), replyHttpHeaderSize(-1), replyHttpBodySize(-1), - adaptHistoryId(-1) + adaptHistoryId(-1), + alMaster(alp) { assert(virginHeader); virgin.setHeader(virginHeader); // sets virgin.body_pipe if needed virgin.setCause(virginCause); // may be NULL // adapted header and body are initialized when we parse them // writing and reading ends are handled by Adaptation::Icap::Xaction // encoding // nothing to do because we are using temporary buffers // parsing; TODO: do not set until we parse, see ICAPOptXact icapReply = new HttpReply; icapReply->protoPrefix = "ICAP/"; // TODO: make an IcapReply class? debugs(93,7, HERE << "initialized." << status()); } @@ -1420,41 +1421,41 @@ client_addr = request->indirect_client_addr; } else #endif client_addr = request->client_addr; if (!client_addr.isAnyAddr() && !client_addr.isNoAddr()) buf.Printf("X-Client-IP: %s\r\n", client_addr.toStr(ntoabuf,MAX_IPSTRLEN)); } if (TheConfig.send_username && request) makeUsernameHeader(request, buf); // Adaptation::Config::metaHeaders typedef Notes::iterator ACAMLI; for (ACAMLI i = Adaptation::Config::metaHeaders.begin(); i != Adaptation::Config::metaHeaders.end(); ++i) { HttpRequest *r = virgin.cause ? virgin.cause : dynamic_cast(virgin.header); Must(r); 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) { if (ah->metaHeaders == NULL) ah->metaHeaders = new NotePairs; if (!ah->metaHeaders->hasPair((*i)->key.termedBuf(), value)) ah->metaHeaders->add((*i)->key.termedBuf(), value); } } } // fprintf(stderr, "%s\n", buf.content()); buf.append(ICAP::crlf, 2); // terminate ICAP header // fill icapRequest for logging Must(icapRequest->parseCharBuf(buf.content(), buf.contentSize())); // start ICAP request body with encapsulated HTTP headers buf.append(httpBuf.content(), httpBuf.contentSize()); @@ -1930,55 +1931,56 @@ if (!request) request = const_cast(&virginRequest()); if (request) request->detailError(ERR_ICAP_FAILURE, errDetail); } void Adaptation::Icap::ModXact::clearError() { HttpRequest *request = dynamic_cast(adapted.header); // if no adapted request, update virgin (and inherit its properties later) if (!request) request = const_cast(&virginRequest()); if (request) request->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); updateHistory(true); } Adaptation::Icap::Xaction *Adaptation::Icap::ModXactLauncher::createXaction() { 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() { debugs(93, 5, HERE << "swan sings"); updateHistory(false); Adaptation::Icap::Launcher::swanSong(); } void Adaptation::Icap::ModXactLauncher::updateHistory(bool doStart) { HttpRequest *r = virgin.cause ? virgin.cause : dynamic_cast(virgin.header); // r should never be NULL but we play safe; TODO: add Should() if (r) { Adaptation::Icap::History::Pointer h = r->icapHistory(); if (h != NULL) { if (doStart) h->start("ICAPModXactLauncher"); === 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-11-20 17:21:01 +0000 @@ -15,40 +15,41 @@ * * This program is free software; you can redistribute it and/or modify * it under the terms of the GNU General Public License as published by * the Free Software Foundation; either version 2 of the License, or * (at your option) any later version. * * This program is distributed in the hope that it will be useful, * but WITHOUT ANY WARRANTY; without even the implied warranty of * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the * GNU General Public License for more details. * * You should have received a copy of the GNU General Public License * along with this program; if not, write to the Free Software * Foundation, Inc., 59 Temple Place, Suite 330, Boston, MA 02111, USA. * */ #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" #include "BodyPipe.h" /* * ICAPModXact implements ICAP REQMOD and RESPMOD transaction using * ICAPXaction as the base. The ICAPModXact receives a virgin HTTP message * from an ICAP vecoring point, (a.k.a., initiator), communicates with the * ICAP server, and sends the adapted HTTP message headers back. * Virgin/adapted HTTP message body is reveived/sent using BodyPipe * interface. The initiator (or its associate) is expected to send and/or * receive the HTTP body. */ class ChunkedCodingParser; namespace Adaptation { namespace Icap @@ -115,41 +116,41 @@ /* other members can be accessed iff enabled() */ size_t ad() const; // advertised preview size size_t debt() const; // remains to write bool done() const; // wrote everything bool ieof() const; // premature EOF void wrote(size_t size, bool wroteEof); private: size_t theWritten; size_t theAd; enum State { stDisabled, stWriting, stIeof, stDone } theState; }; 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 virtual void noteMoreBodySpaceAvailable(BodyPipe::Pointer); virtual void noteBodyConsumerAborted(BodyPipe::Pointer); // BodyConsumer methods virtual void noteMoreBodyDataAvailable(BodyPipe::Pointer); virtual void noteBodyProductionEnded(BodyPipe::Pointer); virtual void noteBodyProducerAborted(BodyPipe::Pointer); // comm handlers virtual void handleCommConnected(); virtual void handleCommWrote(size_t size); virtual void handleCommRead(size_t size); void handleCommWroteHeaders(); void handleCommWroteBody(); // service waiting void noteServiceReady(); @@ -320,48 +321,51 @@ // is parsing ICAP or HTTP headers read from the ICAP server bool parsingHeaders() const { return parsing == psIcapHeader || parsing == psHttpHeader; } enum Parsing { psIcapHeader, psHttpHeader, psBody, psDone } parsing; // measures ICAP request writing progress enum Writing { writingInit, writingConnect, writingHeaders, writingPreview, writingPaused, writingPrime, writingAlmostDone, // waiting for the last write() call to finish writingReallyDone } writing; enum Sending { sendingUndecided, sendingVirgin, sendingAdapted, sendingDone } sending; } state; + AccessLogEntry::Pointer alMaster; ///< Master transaction AccessLogEntry CBDATA_CLASS2(ModXact); }; // An Launcher that stores ModXact construction info and // creates ModXact when needed 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(); virtual void swanSong(); /// starts or stops transaction accounting in ICAP history void updateHistory(bool start); InOut virgin; + AccessLogEntry::Pointer al; + private: CBDATA_CLASS2(ModXactLauncher); }; } // namespace Icap } // namespace Adaptation #endif /* SQUID_ICAPMOD_XACT_H */ === 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-11-19 17:40:01 +0000 @@ -636,43 +636,43 @@ // conservative estimate of how long the OPTIONS transaction will take // XXX: move hard-coded constants from here to Adaptation::Icap::TheConfig const int expectedWait = 20; // seconds // Unknown or invalid (too small) expiration times should not happen. // Adaptation::Icap::Options should use the default TTL, and ICAP servers should not // send invalid TTLs, but bugs and attacks happen. if (expire < expectedWait) return squid_curtime; else return expire - expectedWait; // before the current options expire } // use revival delay as "expiration" time for a service w/o valid options return squid_curtime + TheConfig.service_revival_delay; } 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 const char *Adaptation::Icap::ServiceRep::status() const { static MemBuf buf; buf.reset(); buf.append("[", 1); if (up()) buf.append("up", 2); else { buf.append("down", 4); if (isSuspended) buf.append(",susp", 5); if (!theOptions) buf.append(",!opt", 5); else if (!theOptions->valid()) === 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-11-19 17:40:50 +0000 @@ -80,41 +80,41 @@ */ class ServiceRep : public RefCountable, public Adaptation::Service, public Adaptation::Initiator { public: typedef RefCount Pointer; public: explicit ServiceRep(const ServiceConfigPointer &aConfig); virtual ~ServiceRep(); virtual void finalize(); virtual bool probed() const; // see comments above virtual bool up() const; // see comments above 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); // the methods below can only be called on an up() service bool wantsUrl(const String &urlPath) const; bool wantsPreview(const String &urlPath, size_t &wantedSize) const; bool allows204() const; bool allows206() const; Comm::ConnectionPointer getConnection(bool isRetriable, bool &isReused); void putConnection(const Comm::ConnectionPointer &conn, bool isReusable, bool sendReset, const char *comment); void noteConnectionUse(const Comm::ConnectionPointer &conn); void noteConnectionFailed(const char *comment); void noteFailure(); // called by transactions to report service failure void noteNewWaiter() {theAllWaiters++;} ///< New xaction waiting for service to be up or available void noteGoneWaiter(); ///< An xaction is not waiting any more for service to be available bool existWaiters() const {return (theAllWaiters > 0);} ///< if there are xactions waiting for the service to be available === modified file 'src/cf.data.pre' --- src/cf.data.pre 2013-11-12 14:48:50 +0000 +++ src/cf.data.pre 2013-11-19 15:54:31 +0000 @@ -3689,40 +3689,50 @@ lp Local listening port number the client connection was connected to. . 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: 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 us User name from SSL HTTP related format codes: REQUEST [http::]rm Request method (GET/POST etc) [http::]>rm Request method from client [http::]ru Request URL from client === modified file 'src/client_side.cc' --- src/client_side.cc 2013-11-11 12:09:44 +0000 +++ src/client_side.cc 2013-11-20 14:41:47 +0000 @@ -526,41 +526,41 @@ case CLOSEST_DIRECT: ++ statCounter.netdb.times_used; break; default: break; } } void ClientHttpRequest::updateCounters() { clientUpdateStatCounters(logType); if (request->errType != ERR_NONE) ++ statCounter.client_http.errors; clientUpdateStatHistCounters(logType, - tvSubMsec(start_time, current_time)); + tvSubMsec(al->cache.start_time, current_time)); clientUpdateHierCounters(&request->hier); } void prepareLogWithRequestDetails(HttpRequest * request, AccessLogEntry::Pointer &aLogEntry) { assert(request); assert(aLogEntry != NULL); if (Config.onoff.log_mime_hdrs) { Packer p; MemBuf mb; mb.init(); packerToMemInit(&p, &mb); request->header.packInto(&p); //This is the request after adaptation or redirection aLogEntry->headers.adapted_request = xstrdup(mb.buf); // the virgin request is saved to aLogEntry->request @@ -632,64 +632,64 @@ if (loggingEntry() && loggingEntry()->mem_obj) al->cache.objectSize = loggingEntry()->contentLen(); // payload duplicate ?? with or without TE ? al->cache.caddr.setNoAddr(); if (getConn() != NULL) { al->cache.caddr = getConn()->log_addr; al->cache.port = cbdataReference(getConn()->port); } al->http.clientRequestSz.header = req_sz; al->http.clientReplySz.header = out.headers_sz; // XXX: calculate without payload encoding or headers !! al->http.clientReplySz.payloadData = out.size - out.headers_sz; // pretend its all un-encoded data for now. al->cache.highOffset = out.offset; 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); if (getConn() != NULL && getConn()->clientConnection != NULL && getConn()->clientConnection->rfc931[0]) al->cache.rfc931 = getConn()->clientConnection->rfc931; #if USE_SSL && 0 /* This is broken. Fails if the connection has been closed. Needs * to snarf the ssl details some place earlier.. */ if (getConn() != NULL) al->cache.ssluser = sslGetUserEmail(fd_table[getConn()->fd].ssl); #endif /*Add notes*/ // The al->notes and request->notes must point to the same object. (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); } } ACLFilledChecklist checklist(NULL, request, NULL); if (al->reply) { checklist.reply = al->reply; HTTPMSGLOCK(checklist.reply); } if (request) { al->adapted_request = request; HTTPMSGLOCK(al->adapted_request); } accessLogLog(al, &checklist); bool updatePerformanceCounters = true; if (Config.accessList.stats_collection) { === modified file 'src/client_side_request.cc' --- src/client_side_request.cc 2013-10-25 00:13:46 +0000 +++ src/client_side_request.cc 2013-11-19 16:47:03 +0000 @@ -143,43 +143,43 @@ redirect_done = false; redirect_fail_count = 0; store_id_done = false; store_id_fail_count = 0; no_cache_done = false; interpreted_req_hdrs = false; #if USE_SSL sslBumpCheckDone = false; #endif debugs(85,3, HERE << this << " ClientRequestContext constructed"); } CBDATA_CLASS_INIT(ClientHttpRequest); ClientHttpRequest::ClientHttpRequest(ConnStateData * aConn) : #if USE_ADAPTATION AsyncJob("ClientHttpRequest"), #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()) { if (SSL *ssl = fd_table[aConn->clientConnection->fd].ssl) al->cache.sslClientCert.reset(SSL_get_peer_certificate(ssl)); } #endif dlinkAdd(this, &active, &ClientActiveRequests); #if USE_ADAPTATION request_satisfaction_mode = false; #endif #if USE_SSL sslBumpNeed_ = Ssl::bumpEnd; #endif } /* * returns true if client specified that the object must come from the cache * without contacting origin server */ @@ -305,41 +305,42 @@ } /** * Create a request and kick it off * * \retval 0 success * \retval -1 failure * * TODO: Pass in the buffers to be used in the inital Read request, as they are * determined by the user */ int clientBeginRequest(const HttpRequestMethod& method, char const *url, CSCB * streamcallback, CSD * streamdetach, ClientStreamData streamdata, HttpHeader const *header, char *tailbuf, size_t taillen) { size_t url_sz; 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; tempBuffer.data = tailbuf; /* client stream setup */ clientStreamInit(&http->client_stream, clientGetMoreData, clientReplyDetach, clientReplyStatus, new clientReplyContext(http), streamcallback, streamdetach, streamdata, tempBuffer); /* make it visible in the 'current acctive requests list' */ /* Set flags */ /* internal requests only makes sense in an * accelerator today. TODO: accept flags ? */ http->flags.accel = true; /* allow size for url rewriting */ url_sz = strlen(url) + Config.appendDomainLen + 5; http->uri = (char *)xcalloc(url_sz, 1); strcpy(http->uri, url); if ((request = HttpRequest::CreateFromUrlAndMethod(http->uri, method)) == NULL) { debugs(85, 5, "Invalid URL: " << http->uri); @@ -1689,41 +1690,41 @@ // CVE-2009-0801: verify the Host: header is consistent with other known details. if (!calloutContext->host_header_verify_done) { debugs(83, 3, HERE << "Doing calloutContext->hostHeaderVerify()"); calloutContext->host_header_verify_done = true; calloutContext->hostHeaderVerify(); return; } if (!calloutContext->http_access_done) { debugs(83, 3, HERE << "Doing calloutContext->clientAccessCheck()"); calloutContext->http_access_done = true; calloutContext->clientAccessCheck(); return; } #if USE_ADAPTATION if (!calloutContext->adaptation_acl_check_done) { 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 if (!calloutContext->redirect_done) { calloutContext->redirect_done = true; assert(calloutContext->redirect_state == REDIRECT_NONE); if (Config.Program.redirect) { debugs(83, 3, HERE << "Doing calloutContext->clientRedirectStart()"); calloutContext->redirect_state = REDIRECT_PENDING; calloutContext->clientRedirectStart(); return; } } if (!calloutContext->adapted_http_access_done) { debugs(83, 3, HERE << "Doing calloutContext->clientAccessCheck2()"); calloutContext->adapted_http_access_done = true; calloutContext->clientAccessCheck2(); @@ -1838,41 +1839,41 @@ #if ICAP_CLIENT Adaptation::Icap::History::Pointer ih = request->icapHistory(); if (ih != NULL) ih->logType = logType; #endif } #if !_USE_INLINE_ #include "client_side_request.cci" #endif #if USE_ADAPTATION /// Initiate an asynchronous adaptation transaction which will call us back. void ClientHttpRequest::startAdaptation(const Adaptation::ServiceGroupPointer &g) { debugs(85, 3, HERE << "adaptation needed for " << this); 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 Must(initiated(virginHeadSource)); } void ClientHttpRequest::noteAdaptationAnswer(const Adaptation::Answer &answer) { assert(cbdataReferenceValid(this)); // indicates bug clearAdaptation(virginHeadSource); assert(!adaptedBodySource); switch (answer.kind) { case Adaptation::Answer::akForward: handleAdaptedHeader(const_cast(answer.message.getRaw())); break; case Adaptation::Answer::akBlock: handleAdaptationBlock(answer); === 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-11-19 14:52:02 +0000 @@ -88,41 +88,40 @@ Comm::ConnectionPointer clientConnection; HttpRequest *request; /* Parsed URL ... */ char *uri; char *log_uri; String store_id; /* StoreID for transactions where the request member is nil */ struct { int64_t offset; int64_t size; size_t headers_sz; } out; HttpHdrRangeIter range_iter; /* data for iterating thru range specs */ size_t req_sz; /* raw request size on input, not current request size */ /// the processing tags associated with this request transaction. // 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 { bool accel; //bool intercepted; //XXX: it's apparently never used. //bool spoof_client_ip; //XXX: it's apparently never used. bool internal; bool done_copying; bool purging; } flags; struct { Http::StatusCode status; char *location; } redirect; dlink_node active; dlink_list client_stream; int mRangeCLen(); === modified file 'src/format/ByteCode.h' --- src/format/ByteCode.h 2013-10-29 02:24:29 +0000 +++ src/format/ByteCode.h 2013-11-19 15:06:55 +0000 @@ -123,40 +123,41 @@ LFT_ADAPTED_REPLY_SIZE_HEADERS, /*LFT_REPLY_SIZE_BODY, */ /*LFT_REPLY_SIZE_BODY_NO_TE, */ LFT_CLIENT_IO_SIZE_TOTAL, /* client credentials */ LFT_USER_NAME, /* any source will do */ LFT_USER_LOGIN, LFT_USER_IDENT, /*LFT_USER_REALM, */ /*LFT_USER_SCHEME, */ LFT_USER_EXTERNAL, /* LFT_USER_SSL_CERT, */ /* global time details */ LFT_TIME_SECONDS_SINCE_EPOCH, 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, LFT_PEER_RESPONSE_TIME, LFT_TOTAL_SERVER_SIDE_RESPONSE_TIME, LFT_DNS_WAIT_TIME, /* Squid internal processing details */ LFT_SQUID_STATUS, LFT_SQUID_ERROR, LFT_SQUID_ERROR_DETAIL, LFT_SQUID_HIERARCHY, LFT_MIME_TYPE, LFT_TAG, LFT_EXT_LOG, LFT_SEQUENCE_NUMBER, #if USE_ADAPTATION === modified file 'src/format/Format.cc' --- src/format/Format.cc 2013-11-11 12:09:44 +0000 +++ src/format/Format.cc 2013-11-20 20:30:29 +0000 @@ -478,40 +478,47 @@ spec = fmt->data.timespec; if (fmt->type == LFT_TIME_LOCALTIME) { if (!spec) spec = "%d/%b/%Y:%H:%M:%S %z"; t = localtime(&squid_curtime); } else { if (!spec) spec = "%d/%b/%Y:%H:%M:%S"; t = gmtime(&squid_curtime); } strftime(tmp, sizeof(tmp), spec, t); out = tmp; } 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; break; case LFT_PEER_RESPONSE_TIME: if (al->hier.peer_response_time < 0) { out = "-"; } else { outoff = al->hier.peer_response_time; dooff = 1; } break; case LFT_TOTAL_SERVER_SIDE_RESPONSE_TIME: if (al->hier.total_response_time < 0) { out = "-"; } else { outoff = al->hier.total_response_time; dooff = 1; @@ -1152,41 +1159,41 @@ case LOG_QUOTE_URL: newout = rfc1738_escape(out); break; case LOG_QUOTE_RAW: break; } if (newout) { if (dofree) safe_free(out); out = newout; dofree = newfree; } } // 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; const int maxWidth = haveMaxWidth ? fmt->widthMax : strlen(out); if (fmt->left) mb.Printf("%-*.*s", minWidth, maxWidth, out); else mb.Printf("%*.*s", minWidth, maxWidth, out); } else mb.append(out, strlen(out)); } else { mb.append("-", 1); } if (fmt->space) mb.append(" ", 1); sb.clean(); === modified file 'src/format/Token.cc' --- src/format/Token.cc 2013-10-29 02:24:29 +0000 +++ src/format/Token.cc 2013-11-21 11:48:12 +0000 @@ -34,40 +34,41 @@ {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 }, */ {"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}, {"Hs", LFT_HTTP_SENT_STATUS_CODE_OLD_30}, {">Hs", LFT_HTTP_SENT_STATUS_CODE}, {" 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; case LFT_HTTP_SENT_STATUS_CODE_OLD_30: debugs(46, DBG_PARSE_NOTE(DBG_IMPORTANT), "WARNING: The \"Hs\" formatting code is deprecated. Use the \">Hs\" instead."); type = LFT_HTTP_SENT_STATUS_CODE; break; case LFT_SERVER_LOCAL_IP_OLD_27: debugs(46, DBG_PARSE_NOTE(DBG_IMPORTANT), "WARNING: The \"oa\" formatting code is deprecated. Use the \"rp\" instead."); type = LFT_CLIENT_REQ_URLPATH; break; case LFT_REQUEST_VERSION_OLD_2X: debugs(46, DBG_PARSE_NOTE(DBG_IMPORTANT), "WARNING: The \">v\" formatting code is deprecated. Use the \">rv\" instead."); === modified file 'src/stat.cc' --- src/stat.cc 2013-10-25 00:13:46 +0000 +++ src/stat.cc 2013-11-19 14:59:24 +0000 @@ -2025,43 +2025,43 @@ fd_table[fd].bytes_read, fd_table[fd].bytes_written); storeAppendPrintf(s, "\tFD desc: %s\n", fd_table[fd].desc); storeAppendPrintf(s, "\tin: buf %p, offset %ld, size %ld\n", conn->in.buf, (long int) conn->in.notYetUsed, (long int) conn->in.allocatedSize); storeAppendPrintf(s, "\tremote: %s\n", conn->clientConnection->remote.toUrl(buf,MAX_IPSTRLEN)); storeAppendPrintf(s, "\tlocal: %s\n", conn->clientConnection->local.toUrl(buf,MAX_IPSTRLEN)); storeAppendPrintf(s, "\tnrequests: %d\n", conn->nrequests); } storeAppendPrintf(s, "uri %s\n", http->uri); storeAppendPrintf(s, "logType %s\n", LogTags_str[http->logType]); storeAppendPrintf(s, "out.offset %ld, out.size %lu\n", (long int) http->out.offset, (unsigned long int) http->out.size); storeAppendPrintf(s, "req_sz %ld\n", (long int) http->req_sz); 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(); else #endif if (http->request->extacl_user.defined()) { p = http->request->extacl_user.termedBuf(); } if (!p && conn != NULL && conn->clientConnection->rfc931[0]) p = conn->clientConnection->rfc931; #if USE_SSL if (!p && conn != NULL && Comm::IsConnOpen(conn->clientConnection)) p = sslGetUserEmail(fd_table[conn->clientConnection->fd].ssl); #endif if (!p)