From: Alex Rousskov Date: Fri, 18 Feb 2011 19:39:05 +0000 (-0700) Subject: libecap v0.2.0 options support: accept/update/log eCAP transaction meta-info X-Git-Tag: take03~1 X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=5038f9d8c3dc4352098b16cb8665a4f89d5de70a;p=thirdparty%2Fsquid.git libecap v0.2.0 options support: accept/update/log eCAP transaction meta-info Adapter transaction options are now extracted and can be logged in HTTP transaction log (access.log): Moved ICAP-specific logging-related adaptation history features to the general adaptation history class and used them in eCAP code. Support adaptation_masterx_shared_names option for eCAP transactions. eCAP transactions can now forward meta information to subsequent ICAP or eCAP transactions (within the same master transaction scope). Allow a routing eCAP service to determine the list of adaptation services to be applied next to the same master transaction (same as the X-Next-Services ICAP extension). Identified a couple of %adapt::(theCauseRep ? + theCauseRep->raw().header : theVirginRep.raw().header); + Must(request); + if (name.known()) { // must check to avoid empty names matching unset cfg + Adaptation::History::Pointer ah = request->adaptHistory(false); + if (ah != NULL) { + String name, value; + if (ah->getXxRecord(name, value)) + return libecap::Area::FromTempBuffer(value.rawBuf(), value.size()); + } + } + return libecap::Area(); +} + void Adaptation::Ecap::XactionRep::start() { @@ -271,6 +314,7 @@ Adaptation::Ecap::XactionRep::useVirgin() // check that clone() copies the pipe so that we do not have to Must(!theVirginRep.raw().header->body_pipe == !clone->body_pipe); + updateHistory(); sendAnswer(Answer::Forward(clone)); Must(done()); } @@ -286,6 +330,7 @@ Adaptation::Ecap::XactionRep::useAdapted(const libecap::shared_ptrbody()) { // final, bodyless answer proxyingAb = opNever; + updateHistory(); sendAnswer(Answer::Forward(msg)); } else { // got answer headers but need to handle body proxyingAb = opOn; @@ -295,6 +340,7 @@ Adaptation::Ecap::XactionRep::useAdapted(const libecap::shared_ptrtieBody(this); // sets us as a producer Must(msg->body_pipe != NULL); // check tieBody + updateHistory(); sendAnswer(Answer::Forward(msg)); debugs(93,4, HERE << "adapter will produce body" << status()); @@ -311,10 +357,59 @@ Adaptation::Ecap::XactionRep::blockVirgin() sinkVb("blockVirgin"); + updateHistory(); sendAnswer(Answer::Block(service().cfg().key)); Must(done()); } +/// Called just before sendAnswer() to record adapter meta-information +/// which may affect answer processing and may be needed for logging. +void +Adaptation::Ecap::XactionRep::updateHistory() +{ + if (!theMaster) // all updates rely on being able to query the adapter + return; + + const HttpRequest *request = dynamic_cast(theCauseRep ? + theCauseRep->raw().header : theVirginRep.raw().header); + Must(request); + + // TODO: move common ICAP/eCAP logic to Adaptation::Xaction or similar + // TODO: optimize Area-to-String conversion + + // update the cross-transactional database if needed + if (const char *xxNameStr = Adaptation::Config::masterx_shared_name) { + Adaptation::History::Pointer ah = request->adaptHistory(true); + if (ah != NULL) { + libecap::Name xxName(xxNameStr); // TODO: optimize? + if (const libecap::Area val = theMaster->option(xxName)) + ah->updateXxRecord(xxNameStr, val.toString().c_str()); + } + } + + // update the adaptation plan if needed + if (service().cfg().routing) { + String services; + if (const libecap::Area services = theMaster->option(libecap::metaNextServices)) { + Adaptation::History::Pointer ah = request->adaptHistory(true); + if (ah != NULL) + ah->updateNextServices(services.toString().c_str()); + } + } // TODO: else warn (occasionally!) if we got libecap::metaNextServices + + // Store received meta headers for adapt::adaptLogHistory(); + if (ah != NULL) { + HttpHeader meta(hoReply); + OptionsExtractor extractor(meta); + theMaster->visitEachOption(extractor); + ah->recordMeta(&meta); + } +} + + void Adaptation::Ecap::XactionRep::vbDiscard() { diff --git a/src/adaptation/ecap/XactionRep.h b/src/adaptation/ecap/XactionRep.h index 61163ee772..d0552f1017 100644 --- a/src/adaptation/ecap/XactionRep.h +++ b/src/adaptation/ecap/XactionRep.h @@ -86,11 +86,13 @@ protected: void moveAbContent(); + void updateHistory(); void terminateMaster(); void scheduleStop(const char *reason); const libecap::Area clientIpValue() const; const libecap::Area usernameValue() const; + const libecap::Area masterxSharedValue(const libecap::Name &name) const; private: AdapterXaction theMaster; // the actual adaptation xaction we represent diff --git a/src/adaptation/icap/History.cc b/src/adaptation/icap/History.cc index 92da86c3f8..dbc2666492 100644 --- a/src/adaptation/icap/History.cc +++ b/src/adaptation/icap/History.cc @@ -3,68 +3,12 @@ #include "globals.h" #include "SquidTime.h" -Adaptation::Icap::History::History(): mergeOfIcapHeaders(hoRequest), - lastIcapHeader(hoRequest), logType(LOG_TAG_NONE), req_sz(0), +Adaptation::Icap::History::History(): + logType(LOG_TAG_NONE), req_sz(0), pastTime(0), concurrencyLevel(0) { } -Adaptation::Icap::History::History(const Adaptation::Icap::History& ih) -{ - assign(ih); -} - -Adaptation::Icap::History::~History() -{ - mergeOfIcapHeaders.clean(); - lastIcapHeader.clean(); - rfc931.clean(); -#if USE_SSL - ssluser.clean(); -#endif - log_uri.clean(); -} - -void Adaptation::Icap::History::assign(const Adaptation::Icap::History& ih) -{ - mergeOfIcapHeaders.clean(); - mergeOfIcapHeaders.update(&ih.mergeOfIcapHeaders, NULL); - lastIcapHeader.clean(); - lastIcapHeader.update(&ih.lastIcapHeader, NULL); - rfc931 = ih.rfc931; - -#if USE_SSL - ssluser = ih.ssluser; -#endif - - logType = ih.logType; - log_uri = ih.log_uri; - req_sz = ih.req_sz; - pastTime = ih.pastTime; - currentStart = ih.currentStart; - concurrencyLevel = ih.concurrencyLevel; - debugs(93,7, HERE << this << " = " << &ih); -} - -Adaptation::Icap::History& Adaptation::Icap::History::operator=(const History& ih) -{ - if (this != &ih) - assign(ih); - return *this; -} - -void Adaptation::Icap::History::setIcapLastHeader(const HttpHeader * lih) -{ - lastIcapHeader.clean(); - lastIcapHeader.update(lih, NULL); -} - -void Adaptation::Icap::History::mergeIcapHeaders(const HttpHeader * lih) -{ - mergeOfIcapHeaders.update(lih, NULL); - mergeOfIcapHeaders.compact(); -} - void Adaptation::Icap::History::start(const char *context) { if (!concurrencyLevel++) diff --git a/src/adaptation/icap/History.h b/src/adaptation/icap/History.h index e4cbd25799..2fb08343b5 100644 --- a/src/adaptation/icap/History.h +++ b/src/adaptation/icap/History.h @@ -2,7 +2,6 @@ #define SQUID_ICAPHISTORY_H #include "RefCount.h" -#include "HttpHeader.h" #include "enums.h" namespace Adaptation @@ -17,16 +16,6 @@ public: typedef RefCount Pointer; History(); - History(const History& ih); - - ~History(); - - History& operator=(const History& ih); - - ///store the last reply header from ICAP server - void setIcapLastHeader(const HttpHeader * lih); - ///merge new header and stored one - void mergeIcapHeaders(const HttpHeader * lih); /// record the start of an ICAP processing interval void start(const char *context); @@ -36,8 +25,6 @@ public: /// returns the total time of all ICAP processing intervals int processingTime() const; - HttpHeader mergeOfIcapHeaders; ///< Merge of REQMOD and RESPMOD responses. If both responses contain the header, the one from the last response will be used - HttpHeader lastIcapHeader; ///< Last received reply from ICAP server String rfc931; ///< the username from ident #if USE_SSL String ssluser; ///< the username from SSL @@ -48,8 +35,6 @@ public: size_t req_sz; ///< the request size private: - void assign(const History &); - int currentTime() const; ///< time since current start or zero timeval currentStart; ///< when the current processing interval started diff --git a/src/adaptation/icap/ModXact.cc b/src/adaptation/icap/ModXact.cc index ae54334c4a..5f0b25fd2b 100644 --- a/src/adaptation/icap/ModXact.cc +++ b/src/adaptation/icap/ModXact.cc @@ -770,7 +770,7 @@ void Adaptation::Icap::ModXact::parseIcapHead() // update the cross-transactional database if needed (all status codes!) if (const char *xxName = Adaptation::Config::masterx_shared_name) { Adaptation::History::Pointer ah = request->adaptHistory(true); - if (ah != NULL) { + if (ah != NULL) { // TODO: reorder checks to avoid creating history const String val = icapReply->header.getByName(xxName); if (val.size() > 0) // XXX: HttpHeader lacks empty value detection ah->updateXxRecord(xxName, val); @@ -791,11 +791,9 @@ void Adaptation::Icap::ModXact::parseIcapHead() // If we already have stored headers from previous ICAP transaction related to this // request, old headers will be replaced with the new one. - Adaptation::Icap::History::Pointer h = request->icapHistory(); - if (h != NULL) { - h->mergeIcapHeaders(&icapReply->header); - h->setIcapLastHeader(&icapReply->header); - } + Adaptation::History::Pointer ah = request->adaptLogHistory(); + if (ah != NULL) + ah->recordMeta(&icapReply->header); // handle100Continue() manages state.writing on its own. // Non-100 status means the server needs no postPreview data from us. @@ -1302,6 +1300,7 @@ void Adaptation::Icap::ModXact::makeRequestHeaders(MemBuf &buf) // share the cross-transactional database records if needed if (Adaptation::Config::masterx_shared_name) { + // XXX: do not create history here: there can be no values in empty ah Adaptation::History::Pointer ah = request->adaptHistory(true); if (ah != NULL) { String name, value; diff --git a/src/cf.data.pre b/src/cf.data.pre index 321b8c1707..a5ef97ca74 100644 --- a/src/cf.data.pre +++ b/src/cf.data.pre @@ -2921,7 +2921,7 @@ DOC_START sent to the first selected peer. The timer stops with the last I/O with the last peer. - If ICAP is enabled, the following two codes become available (as + If ICAP is enabled, the following code becomes available (as well as ICAP log codes documented with the icap_log option): icap::tt Total ICAP processing time for the HTTP @@ -2929,14 +2929,13 @@ DOC_START ACLs are checked and when ICAP transaction is in progress. - icap::a %icap::to/%03icap::Hs %icap::icapHistory(); -#endif if (Config.onoff.log_mime_hdrs) { Packer p; MemBuf mb; @@ -572,14 +569,15 @@ prepareLogWithRequestDetails(HttpRequest * request, AccessLogEntry * aLogEntry) aLogEntry->headers.request = xstrdup(mb.buf); } -#if ICAP_CLIENT - packerClean(&p); - mb.reset(); - packerToMemInit(&p, &mb); - - if (ih != NULL) - ih->lastIcapHeader.packInto(&p); - aLogEntry->headers.icap = xstrdup(mb.buf); +#if USE_ADAPTATION + const Adaptation::History::Pointer ah = request->adaptLogHistory(); + if (ah != NULL) { + packerClean(&p); + mb.reset(); + packerToMemInit(&p, &mb); + ah->lastMeta.packInto(&p); + aLogEntry->headers.adapt_last = xstrdup(mb.buf); + } #endif packerClean(&p); @@ -587,6 +585,7 @@ prepareLogWithRequestDetails(HttpRequest * request, AccessLogEntry * aLogEntry) } #if ICAP_CLIENT + const Adaptation::Icap::History::Pointer ih = request->icapHistory(); if (ih != NULL) aLogEntry->icap.processingTime = ih->processingTime(); #endif diff --git a/src/log/access_log.cc b/src/log/access_log.cc index da729f6a0b..16a00f718f 100644 --- a/src/log/access_log.cc +++ b/src/log/access_log.cc @@ -421,14 +421,14 @@ typedef enum { #if USE_ADAPTATION LTF_ADAPTATION_SUM_XACT_TIMES, LTF_ADAPTATION_ALL_XACT_TIMES, + LFT_ADAPTATION_LAST_HEADER, + LFT_ADAPTATION_LAST_HEADER_ELEM, + LFT_ADAPTATION_LAST_ALL_HEADERS, #endif #if ICAP_CLIENT LFT_ICAP_TOTAL_TIME, - LFT_ICAP_LAST_MATCHED_HEADER, - LFT_ICAP_LAST_MATCHED_HEADER_ELEM, - LFT_ICAP_LAST_MATCHED_ALL_HEADERS, LFT_ICAP_ADDR, LFT_ICAP_SERV_NAME, @@ -583,11 +583,12 @@ struct logformat_token_table_entry logformat_token_table[] = { #if USE_ADAPTATION {"adapt::all_trs", LTF_ADAPTATION_ALL_XACT_TIMES}, {"adapt::sum_trs", LTF_ADAPTATION_SUM_XACT_TIMES}, + {"adapt::request) { - Adaptation::Icap::History::Pointer ih = al->request->icapHistory(); - if (ih != NULL) - sb = ih->mergeOfIcapHeaders.getByName(fmt->data.header.header); + const Adaptation::History::Pointer ah = al->request->adaptHistory(); + if (ah != NULL) // XXX: add adapt::allMeta.getByName(fmt->data.header.header); } + // XXX: here and elsewhere: move such code inside the if guard out = sb.termedBuf(); quote = 1; break; - case LFT_ICAP_LAST_MATCHED_HEADER_ELEM: + case LFT_ADAPTATION_LAST_HEADER_ELEM: if (al->request) { - Adaptation::Icap::History::Pointer ih = al->request->icapHistory(); - if (ih != NULL) - sb = ih->mergeOfIcapHeaders.getByNameListMember(fmt->data.header.header, fmt->data.header.element, fmt->data.header.separator); + const Adaptation::History::Pointer ah = al->request->adaptHistory(); + if (ah != NULL) // XXX: add adapt::allMeta.getByNameListMember(fmt->data.header.header, fmt->data.header.element, fmt->data.header.separator); } out = sb.termedBuf(); @@ -859,13 +859,15 @@ accessLogCustom(AccessLogEntry * al, customlog * log) break; - case LFT_ICAP_LAST_MATCHED_ALL_HEADERS: - out = al->headers.icap; + case LFT_ADAPTATION_LAST_ALL_HEADERS: + out = al->headers.adapt_last; quote = 1; break; +#endif +#if ICAP_CLIENT case LFT_ICAP_ADDR: if (!out) out = al->icap.hostAddr.NtoA(tmp,1024); @@ -1478,9 +1480,11 @@ done: switch (lt->type) { -#if ICAP_CLIENT - case LFT_ICAP_LAST_MATCHED_HEADER: +#if USE_ADAPTATION + case LFT_ADAPTATION_LAST_HEADER: +#endif +#if ICAP_CLIENT case LFT_ICAP_REQ_HEADER: case LFT_ICAP_REP_HEADER: @@ -1518,10 +1522,12 @@ done: case LFT_REPLY_HEADER: lt->type = LFT_REPLY_HEADER_ELEM; break; -#if ICAP_CLIENT - case LFT_ICAP_LAST_MATCHED_HEADER: - lt->type = LFT_ICAP_LAST_MATCHED_HEADER_ELEM; +#if USE_ADAPTATION + case LFT_ADAPTATION_LAST_HEADER: + lt->type = LFT_ADAPTATION_LAST_HEADER_ELEM; break; +#endif +#if ICAP_CLIENT case LFT_ICAP_REQ_HEADER: lt->type = LFT_ICAP_REQ_HEADER_ELEM; break; @@ -1548,10 +1554,12 @@ done: case LFT_REPLY_HEADER: lt->type = LFT_REPLY_ALL_HEADERS; break; -#if ICAP_CLIENT - case LFT_ICAP_LAST_MATCHED_HEADER: - lt->type = LFT_ICAP_LAST_MATCHED_ALL_HEADERS; +#if USE_ADAPTATION + case LFT_ADAPTATION_LAST_HEADER: + lt->type = LFT_ADAPTATION_LAST_ALL_HEADERS; break; +#endif +#if ICAP_CLIENT case LFT_ICAP_REQ_HEADER: lt->type = LFT_ICAP_REQ_ALL_HEADERS; break; @@ -1652,8 +1660,10 @@ accessLogDumpLogFormat(StoreEntry * entry, const char *name, logformat * definit case LFT_STRING: break; +#if USE_ADAPTATION + case LFT_ADAPTATION_LAST_HEADER_ELEM: +#endif #if ICAP_CLIENT - case LFT_ICAP_LAST_MATCHED_HEADER_ELEM: case LFT_ICAP_REQ_HEADER_ELEM: case LFT_ICAP_REP_HEADER_ELEM: #endif @@ -1670,18 +1680,20 @@ accessLogDumpLogFormat(StoreEntry * entry, const char *name, logformat * definit switch (type) { case LFT_REQUEST_HEADER_ELEM: - type = LFT_REQUEST_HEADER_ELEM; + type = LFT_REQUEST_HEADER; break; case LFT_ADAPTED_REQUEST_HEADER_ELEM: - type = LFT_ADAPTED_REQUEST_HEADER_ELEM; + type = LFT_ADAPTED_REQUEST_HEADER; break; case LFT_REPLY_HEADER_ELEM: - type = LFT_REPLY_HEADER_ELEM; + type = LFT_REPLY_HEADER; break; -#if ICAP_CLIENT - case LFT_ICAP_LAST_MATCHED_HEADER_ELEM: - type = LFT_ICAP_LAST_MATCHED_HEADER; +#if USE_ADAPTATION + case LFT_ADAPTATION_LAST_HEADER_ELEM: + type = LFT_ADAPTATION_LAST_HEADER; break; +#endif +#if ICAP_CLIENT case LFT_ICAP_REQ_HEADER_ELEM: type = LFT_ICAP_REQ_HEADER; break; @@ -1699,8 +1711,10 @@ accessLogDumpLogFormat(StoreEntry * entry, const char *name, logformat * definit case LFT_ADAPTED_REQUEST_ALL_HEADERS: case LFT_REPLY_ALL_HEADERS: +#if USE_ADAPTATION + case LFT_ADAPTATION_LAST_ALL_HEADERS: +#endif #if ICAP_CLIENT - case LFT_ICAP_LAST_MATCHED_ALL_HEADERS: case LFT_ICAP_REQ_ALL_HEADERS: case LFT_ICAP_REP_ALL_HEADERS: #endif @@ -1715,10 +1729,12 @@ accessLogDumpLogFormat(StoreEntry * entry, const char *name, logformat * definit case LFT_REPLY_ALL_HEADERS: type = LFT_REPLY_HEADER; break; -#if ICAP_CLIENT - case LFT_ICAP_LAST_MATCHED_ALL_HEADERS: - type = LFT_ICAP_LAST_MATCHED_HEADER; +#if USE_ADAPTATION + case LFT_ADAPTATION_LAST_ALL_HEADERS: + type = LFT_ADAPTATION_LAST_HEADER; break; +#endif +#if ICAP_CLIENT case LFT_ICAP_REQ_ALL_HEADERS: type = LFT_ICAP_REQ_HEADER; break; @@ -2202,18 +2218,17 @@ accessLogInit(void) LogfileStatus = LOG_ENABLE; -#if USE_ADAPTATION || ICAP_CLIENT - for (logformat_token * curr_token = (log->logFormat?log->logFormat->format:NULL); curr_token; curr_token = curr_token->next) { #if USE_ADAPTATION + for (logformat_token * curr_token = (log->logFormat?log->logFormat->format:NULL); curr_token; curr_token = curr_token->next) { if (curr_token->type == LTF_ADAPTATION_SUM_XACT_TIMES || - curr_token->type == LTF_ADAPTATION_ALL_XACT_TIMES) { + curr_token->type == LTF_ADAPTATION_ALL_XACT_TIMES || + curr_token->type == LFT_ADAPTATION_LAST_HEADER || + curr_token->type == LFT_ADAPTATION_LAST_HEADER_ELEM || + curr_token->type == LFT_ADAPTATION_LAST_ALL_HEADERS) { alLogformatHasAdaptToken = true; } -#endif #if ICAP_CLIENT - if (curr_token->type == LFT_ICAP_LAST_MATCHED_HEADER || - curr_token->type == LFT_ICAP_LAST_MATCHED_HEADER_ELEM || - curr_token->type == LFT_ICAP_LAST_MATCHED_ALL_HEADERS) { + if (curr_token->type == LFT_ICAP_TOTAL_TIME) { alLogformatHasIcapToken = true; } #endif @@ -2482,7 +2497,7 @@ accessLogFreeMemory(AccessLogEntry * aLogEntry) safe_free(aLogEntry->headers.request); #if ICAP_CLIENT - safe_free(aLogEntry->headers.icap); + safe_free(aLogEntry->headers.adapt_last); #endif safe_free(aLogEntry->headers.reply);