#include "HierarchyLogEntry.h"
#include "ip/IpAddress.h"
#include "HttpRequestMethod.h"
+#if ICAP_CLIENT
+#include "adaptation/icap/Elements.h"
+#endif
/* forward decls */
class HttpReply;
CacheDetails() : caddr(),
requestSize(0),
replySize(0),
+ requestHeadersSize(0),
+ replyHeadersSize(0),
highOffset(0),
objectSize(0),
code (LOG_TAG_NONE),
IpAddress caddr;
int64_t requestSize;
int64_t replySize;
+ int requestHeadersSize; ///< received, including request line
+ int replyHeadersSize; ///< sent, including status line
int64_t highOffset;
int64_t objectSize;
log_type code;
{
public:
- Headers() : request(NULL), reply(NULL) {}
+ Headers() : request(NULL),
+#if ICAP_CLIENT
+ icap(NULL),
+#endif
+ reply(NULL) {}
char *request;
+
+#if ICAP_CLIENT
+ char * icap; ///< last matching ICAP response header.
+#endif
char *reply;
} headers;
HierarchyLogEntry hier;
HttpReply *reply;
HttpRequest *request;
+
+#if ICAP_CLIENT
+ /** \brief This subclass holds log info for ICAP part of request
+ * \todo Inner class declarations should be moved outside
+ */
+ class IcapLogEntry {
+ public:
+ IcapLogEntry():request(NULL),reply(NULL),outcome(Adaptation::Icap::xoUnknown),trTime(0),ioTime(0),resStatus(HTTP_STATUS_NONE){}
+
+ IpAddress hostAddr; ///< ICAP server IP address
+ String serviceName; ///< ICAP service name
+ String reqUri; ///< ICAP Request-URI
+ Adaptation::Icap::ICAP::Method reqMethod; ///< ICAP request method
+ int64_t bytesSent; ///< number of bytes sent to ICAP server so far
+ int64_t bytesRead; ///< number of bytes read from ICAP server so far
+ HttpRequest* request; ///< ICAP request
+ HttpReply* reply; ///< ICAP reply
+
+ Adaptation::Icap::XactOutcome outcome; ///< final transaction status
+ /** \brief Transaction response time.
+ * The timer starts when the ICAP transaction
+ * is created and stops when the result of the transaction is logged
+ */
+ int trTime;
+ /** \brief Transaction I/O time.
+ * The timer starts when the first ICAP request
+ * byte is scheduled for sending and stops when the lastbyte of the
+ * ICAP response is received.
+ */
+ int ioTime;
+ http_status resStatus; ///< ICAP response status code
+ int processingTime; ///< total ICAP processing time in milliseconds
+ }
+ icap;
+#endif
};
class ACLChecklist;
class logformat_token;
/* Should be in 'AccessLog.h' as the driver */
+extern void accessLogLogTo(customlog* log, AccessLogEntry* al, ACLChecklist* checklist = NULL);
extern void accessLogLog(AccessLogEntry *, ACLChecklist * checklist);
extern void accessLogRotate(void);
extern void accessLogClose(void);
return true; // now we are in sync and can handle the call
}
+void
+CommConnectCbParams::print(std::ostream &os) const
+{
+ CommCommonCbParams::print(os);
+ os << ", " << dns;
+}
+
/* CommIoCbParams */
CommIoCbParams::CommIoCbParams(void *aData): CommCommonCbParams(aData),
void
CommConnectCbPtrFun::dial()
{
- handler(params.fd, params.flag, params.xerrno, params.data);
+ handler(params.fd, params.dns, params.flag, params.xerrno, params.data);
}
void
#include "comm.h"
#include "ConnectionDetail.h"
+#include "DnsLookupDetails.h"
#include "base/AsyncCall.h"
#include "base/AsyncJobCalls.h"
CommConnectCbParams(void *aData);
bool syncWithComm(); // see CommCommonCbParams::syncWithComm
+
+ void print(std::ostream &os) const;
+
+public:
+ DnsLookupDetails dns;
};
// read/write (I/O) parameters
--- /dev/null
+/*
+ * DEBUG: section 78 DNS lookups
+ */
+
+#include "config.h"
+#include "DnsLookupDetails.h"
+
+DnsLookupDetails::DnsLookupDetails(): wait(-1)
+{
+}
+
+DnsLookupDetails::DnsLookupDetails(const String &e, int w):
+ error(e), wait(w)
+{
+}
+
+std::ostream &
+DnsLookupDetails::print(std::ostream &os) const
+{
+ if (wait > 0)
+ os << "lookup_wait=" << wait;
+ if (error.size())
+ os << " lookup_err=" << error;
+ return os;
+}
--- /dev/null
+/*
+ * DEBUG: section 78 DNS lookups
+ */
+
+#ifndef SQUID_DNS_LOOKUP_DETAILS_H
+#define SQUID_DNS_LOOKUP_DETAILS_H
+
+#include "typedefs.h"
+#include "SquidString.h"
+
+/// encapsulates DNS lookup results
+class DnsLookupDetails
+{
+public:
+ DnsLookupDetails(); ///< no error, no lookup delay (i.e., no lookup)
+ DnsLookupDetails(const String &error, int wait);
+
+ std::ostream &print(std::ostream &os) const;
+
+public:
+ String error; ///< error message for unsuccessdul lookups; empty otherwise
+ int wait; ///< msecs spent waiting for the lookup (if any) or -1 (if none)
+};
+
+inline
+std::ostream &operator << (std::ostream &os, const DnsLookupDetails &dns)
+{
+ return dns.print(os);
+}
+
+#endif
struct timeval peer_select_start;
struct timeval store_complete_stop;
+
+ http_status peer_reply_status; ///< last HTTP status code received
+ timeval peer_http_request_sent; ///< last peer finished writing req
+ int64_t peer_response_time; ///< last peer response delay
+ timeval first_conn_start; ///< first connection use among all peers
+ int64_t total_response_time; ///< cumulative for all peers
};
extern void hierarchyNote(HierarchyLogEntry *, hier_code, const char *);
return -1;
}
+void
+HttpMsg::setContentLength(int64_t clen)
+{
+ header.delById(HDR_CONTENT_LENGTH); // if any
+ header.putInt64(HDR_CONTENT_LENGTH, clen);
+ content_length = clen;
+}
+
/* returns true if connection should be "persistent"
* after processing this message */
int
///< produce a message copy, except for a few connection-specific settings
virtual HttpMsg *clone() const = 0; ///< \todo rename: not a true copy?
+ /// [re]sets Content-Length header and cached value
+ void setContentLength(int64_t clen);
+
public:
HttpVersion http_ver;
};
/* Temporary parsing state; might turn into the replacement parser later on */
-struct _HttpParser {
+class HttpParser {
+public:
char state;
const char *buf;
int bufsiz;
int v_start, v_end;
int v_maj, v_min;
};
-typedef struct _HttpParser HttpParser;
extern void HttpParserInit(HttpParser *, const char *buf, int len);
extern int HttpParserParseReqLine(HttpParser *hp);
#include "HttpHeaderRange.h"
#include "MemBuf.h"
#include "Store.h"
+#if ICAP_CLIENT
+#include "adaptation/icap/icap_log.h"
+#endif
HttpRequest::HttpRequest() : HttpMsg(hoRequest)
{
my_addr.SetEmpty();
body_pipe = NULL;
// hier
+ dnsWait = -1;
errType = ERR_NONE;
peer_login = NULL; // not allocated/deallocated by this class
peer_domain = NULL; // not allocated/deallocated by this class
#if FOLLOW_X_FORWARDED_FOR
indirect_client_addr.SetEmpty();
#endif /* FOLLOW_X_FORWARDED_FOR */
+#if USE_ADAPTATION
+ adaptHistory_ = NULL;
+#endif
+#if ICAP_CLIENT
+ icapHistory_ = NULL;
+#endif
}
void
extacl_passwd.clean();
extacl_log.clean();
+
+#if USE_ADAPTATION
+ adaptHistory_ = NULL;
+#endif
+#if ICAP_CLIENT
+ icapHistory_ = NULL;
+#endif
}
void
strncpy(copy->host, host, sizeof(host)); // SQUIDHOSTNAMELEN
copy->host_addr = host_addr;
- if (auth_user_request) {
- copy->auth_user_request = auth_user_request;
- AUTHUSERREQUESTLOCK(copy->auth_user_request, "HttpRequest::clone");
- }
-
copy->port = port;
// urlPath handled in ctor
copy->canonical = canonical ? xstrdup(canonical) : NULL;
- // This may be too conservative for the 204 No Content case
- // may eventually need cloneNullAdaptationImmune() for that.
- copy->flags = flags.cloneAdaptationImmune();
-
copy->range = range ? new HttpHdrRange(*range) : NULL;
copy->ims = ims;
copy->imslen = imslen;
copy->max_forwards = max_forwards;
- copy->client_addr = client_addr;
- copy->my_addr = my_addr;
copy->hier = hier; // Is it safe to copy? Should we?
copy->errType = errType;
copy->extacl_passwd = extacl_passwd;
copy->extacl_log = extacl_log;
+ assert(copy->inheritProperties(this));
+
return copy;
}
reset_tcp = 0;
}
+#if ICAP_CLIENT
+Adaptation::Icap::History::Pointer
+HttpRequest::icapHistory() const
+{
+ if (!icapHistory_) {
+ if ((LogfileStatus == LOG_ENABLE && alLogformatHasIcapToken) ||
+ IcapLogfileStatus == LOG_ENABLE) {
+ icapHistory_ = new Adaptation::Icap::History();
+ debugs(93,4, HERE << "made " << icapHistory_ << " for " << this);
+ }
+ }
+
+ return icapHistory_;
+}
+#endif
+
+#if USE_ADAPTATION
+Adaptation::History::Pointer
+HttpRequest::adaptHistory() const
+{
+ if (!adaptHistory_) {
+ if (Adaptation::History::Enabled) {
+ adaptHistory_ = new Adaptation::History();
+ debugs(93,4, HERE << "made " << adaptHistory_ << " for " << this);
+ }
+ }
+
+ return adaptHistory_;
+}
+#endif
+
bool
HttpRequest::multipartRangeRequest() const
{
client_addr = aReq->client_addr;
my_addr = aReq->my_addr;
+ dnsWait = aReq->dnsWait;
+
+#if USE_ADAPTATION
+ adaptHistory_ = aReq->adaptHistory();
+#endif
+#if ICAP_CLIENT
+ icapHistory_ = aReq->icapHistory();
+#endif
+
// This may be too conservative for the 204 No Content case
// may eventually need cloneNullAdaptationImmune() for that.
flags = aReq->flags.cloneAdaptationImmune();
}
return true;
}
+
+void HttpRequest::recordLookup(const DnsLookupDetails &dns)
+{
+ if (dns.wait >= 0) { // known delay
+ if (dnsWait >= 0) // have recorded DNS wait before
+ dnsWait += dns.wait;
+ else
+ dnsWait = dns.wait;
+ }
+}
#include "client_side.h"
#include "HierarchyLogEntry.h"
#include "HttpRequestMethod.h"
+#if USE_ADAPTATION
+#include "adaptation/History.h"
+#endif
+#if ICAP_CLIENT
+#include "adaptation/icap/History.h"
+#endif
/* Http Request */
//DEAD?: extern int httpRequestHdrAllowedByName(http_hdr_type id);
extern void httpRequestPack(void *obj, Packer *p);
+// TODO: Move these three to access_log.h or AccessLogEntry.h
+#if USE_ADAPTATION
+extern bool alLogformatHasAdaptToken;
+#endif
+#if ICAP_CLIENT
+extern bool alLogformatHasIcapToken;
+#endif
+extern int LogfileStatus;
class HttpHdrRange;
+class DnsLookupDetails;
class HttpRequest: public HttpMsg
{
};
inline const char* GetHost(void) const { return host; };
+#if USE_ADAPTATION
+ /// Returns possibly nil history, creating it if adapt. logging is enabled
+ Adaptation::History::Pointer adaptHistory() const;
+#endif
+#if ICAP_CLIENT
+ /// Returns possibly nil history, creating it if icap logging is enabled
+ Adaptation::Icap::History::Pointer icapHistory() const;
+#endif
+
+ void recordLookup(const DnsLookupDetails &detail);
+
protected:
void clean();
*/
ConnStateData *pinned_connection;
+#if USE_ADAPTATION
+ mutable Adaptation::History::Pointer adaptHistory_; ///< per-HTTP transaction info
+#endif
+#if ICAP_CLIENT
+ mutable Adaptation::Icap::History::Pointer icapHistory_; ///< per-HTTP transaction info
+#endif
+
public:
IpAddress host_addr;
HierarchyLogEntry hier;
+ int dnsWait; ///< sum of DNS lookup delays in milliseconds, for %dt
+
err_type errType;
char *peer_login; /* Configured peer login:password */
DNSSERVER =
endif
+DNSSOURCE += \
+ DnsLookupDetails.h \
+ DnsLookupDetails.cc
+
SNMP_ALL_SOURCE = \
snmp_core.cc \
snmp_agent.cc
dns.cc \
dnsserver.cc \
dns_internal.cc \
+ DnsLookupDetails.cc \
+ DnsLookupDetails.h \
htcp.cc \
htcp.h \
ipc.cc \
#include "HttpReply.h"
#include "TextException.h"
#include "errorpage.h"
+#include "SquidTime.h"
#if USE_ADAPTATION
#include "adaptation/AccessCheck.h"
completed = true;
+ HttpRequest *r = originalRequest();
+ r->hier.total_response_time = r->hier.first_conn_start.tv_sec ?
+ tvSubMsec(r->hier.first_conn_start, current_time) : -1;
+
if (requestBodySource != NULL)
stopConsumingFrom(requestBodySource);
static void fvdbRegisterWithCacheManager();
#endif
-static int LogfileStatus = LOG_DISABLE;
+int LogfileStatus = LOG_DISABLE;
+
+#if USE_ADAPTATION
+bool alLogformatHasAdaptToken = false;
+#endif
+
+#if ICAP_CLIENT
+bool alLogformatHasIcapToken = false;
+#endif
+
#define LOG_BUF_SZ (MAX_URL<<2)
static const char c2x[] =
LFT_TIME_GMT,
LFT_TIME_TO_HANDLE_REQUEST,
+ LFT_PEER_RESPONSE_TIME,
+ LFT_TOTAL_SERVER_SIDE_RESPONSE_TIME,
+ LFT_DNS_WAIT_TIME,
+
LFT_REQUEST_HEADER,
LFT_REQUEST_HEADER_ELEM,
LFT_REQUEST_ALL_HEADERS,
/*LFT_USER_SCHEME, */
LFT_USER_EXTERNAL,
- LFT_HTTP_CODE,
+ LFT_HTTP_SENT_STATUS_CODE_OLD_30,
+ LFT_HTTP_SENT_STATUS_CODE,
+ LFT_HTTP_RECEIVED_STATUS_CODE,
/*LFT_HTTP_STATUS, */
LFT_SQUID_STATUS,
LFT_REQUEST_SIZE_TOTAL,
/*LFT_REQUEST_SIZE_LINE, */
- /*LFT_REQUEST_SIZE_HEADERS, */
+ LFT_REQUEST_SIZE_HEADERS,
/*LFT_REQUEST_SIZE_BODY, */
/*LFT_REQUEST_SIZE_BODY_NO_TE, */
LFT_REPLY_HIGHOFFSET,
LFT_REPLY_OBJECTSIZE,
/*LFT_REPLY_SIZE_LINE, */
- /*LFT_REPLY_SIZE_HEADERS, */
+ LFT_REPLY_SIZE_HEADERS,
/*LFT_REPLY_SIZE_BODY, */
/*LFT_REPLY_SIZE_BODY_NO_TE, */
LFT_IO_SIZE_TOTAL,
LFT_EXT_LOG,
+#if USE_ADAPTATION
+ LTF_ADAPTATION_SUM_XACT_TIMES,
+ LTF_ADAPTATION_ALL_XACT_TIMES,
+#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,
+ LFT_ICAP_REQUEST_URI,
+ LFT_ICAP_REQUEST_METHOD,
+ LFT_ICAP_BYTES_SENT,
+ LFT_ICAP_BYTES_READ,
+
+ LFT_ICAP_REQ_HEADER,
+ LFT_ICAP_REQ_HEADER_ELEM,
+ LFT_ICAP_REQ_ALL_HEADERS,
+
+ LFT_ICAP_REP_HEADER,
+ LFT_ICAP_REP_HEADER_ELEM,
+ LFT_ICAP_REP_ALL_HEADERS,
+
+ LFT_ICAP_TR_RESPONSE_TIME,
+ LFT_ICAP_IO_TIME,
+ LFT_ICAP_OUTCOME,
+ LFT_ICAP_STATUS_CODE,
+#endif
+
LFT_PERCENT /* special string cases for escaped chars */
} logformat_bcode_t;
{"tg", LFT_TIME_GMT},
{"tr", LFT_TIME_TO_HANDLE_REQUEST},
+ {"<pt", LFT_PEER_RESPONSE_TIME},
+ {"<tt", LFT_TOTAL_SERVER_SIDE_RESPONSE_TIME},
+ {"dt", LFT_DNS_WAIT_TIME},
+
{">h", LFT_REQUEST_HEADER},
{">h", LFT_REQUEST_ALL_HEADERS},
{"<h", LFT_REPLY_HEADER},
{"ui", LFT_USER_IDENT},
{"ue", LFT_USER_EXTERNAL},
- {"Hs", LFT_HTTP_CODE},
+ {"Hs", LFT_HTTP_SENT_STATUS_CODE_OLD_30},
+ {">Hs", LFT_HTTP_SENT_STATUS_CODE},
+ {"<Hs", LFT_HTTP_RECEIVED_STATUS_CODE},
/*{ "Ht", LFT_HTTP_STATUS }, */
{"Ss", LFT_SQUID_STATUS},
{ ">st", LFT_REQUEST_SIZE_TOTAL },
/*{ ">sl", LFT_REQUEST_SIZE_LINE }, * / / * the request line "GET ... " */
- /*{ ">sh", LFT_REQUEST_SIZE_HEADERS }, */
+ { ">sh", LFT_REQUEST_SIZE_HEADERS },
/*{ ">sb", LFT_REQUEST_SIZE_BODY }, */
/*{ ">sB", LFT_REQUEST_SIZE_BODY_NO_TE }, */
{"<sH", LFT_REPLY_HIGHOFFSET},
{"<sS", LFT_REPLY_OBJECTSIZE},
/*{ "<sl", LFT_REPLY_SIZE_LINE }, * / / * the reply line (protocol, code, text) */
- /*{ "<sh", LFT_REPLY_SIZE_HEADERS }, */
+ { "<sh", LFT_REPLY_SIZE_HEADERS },
/*{ "<sb", LFT_REPLY_SIZE_BODY }, */
/*{ "<sB", LFT_REPLY_SIZE_BODY_NO_TE }, */
{"%", LFT_PERCENT},
+#if USE_ADAPTATION
+ {"adapt::all_trs", LTF_ADAPTATION_ALL_XACT_TIMES},
+ {"adapt::sum_trs", LTF_ADAPTATION_SUM_XACT_TIMES},
+#endif
+
+#if ICAP_CLIENT
+ {"icap::tt", LFT_ICAP_TOTAL_TIME},
+ {"icap::<last_h", LFT_ICAP_LAST_MATCHED_HEADER},
+
+ {"icap::<A", LFT_ICAP_ADDR},
+ {"icap::<service_name", LFT_ICAP_SERV_NAME},
+ {"icap::ru", LFT_ICAP_REQUEST_URI},
+ {"icap::rm", LFT_ICAP_REQUEST_METHOD},
+ {"icap::>st", LFT_ICAP_BYTES_SENT},
+ {"icap::<st", LFT_ICAP_BYTES_READ},
+
+ {"icap::>h", LFT_ICAP_REQ_HEADER},
+ {"icap::<h", LFT_ICAP_REP_HEADER},
+
+ {"icap::tr", LFT_ICAP_TR_RESPONSE_TIME},
+ {"icap::tio", LFT_ICAP_IO_TIME},
+ {"icap::to", LFT_ICAP_OUTCOME},
+ {"icap::Hs", LFT_ICAP_STATUS_CODE},
+#endif
+
{NULL, LFT_NONE} /* this must be last */
};
break;
case LFT_CLIENT_IP_ADDRESS:
- if (!out) {
+ if (al->cache.caddr.IsNoAddr()) // e.g., ICAP OPTIONS lack client
+ out = "-";
+ else
out = al->cache.caddr.NtoA(tmp,1024);
- }
break;
case LFT_CLIENT_FQDN:
+ if (al->cache.caddr.IsAnyAddr()) // e.g., ICAP OPTIONS lack client
+ out = "-";
+ else
out = fqdncache_gethostbyaddr(al->cache.caddr, FQDN_LOOKUP_IF_MISS);
if (!out) {
out = al->cache.caddr.NtoA(tmp,1024);
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;
+ }
+ break;
+
+ case LFT_DNS_WAIT_TIME:
+ if (al->request && al->request->dnsWait >= 0) {
+ outint = al->request->dnsWait;
+ doint = 1;
+ }
+ break;
+
case LFT_REQUEST_HEADER:
if (al->request)
break;
+#if USE_ADAPTATION
+ case LTF_ADAPTATION_SUM_XACT_TIMES:
+ if (al->request) {
+ Adaptation::History::Pointer ah = al->request->adaptHistory();
+ if (ah != NULL)
+ ah->sumLogString(fmt->data.string, sb);
+ out = sb.termedBuf();
+ }
+ break;
+
+ case LTF_ADAPTATION_ALL_XACT_TIMES:
+ if (al->request) {
+ Adaptation::History::Pointer ah = al->request->adaptHistory();
+ if (ah != NULL)
+ ah->allLogString(fmt->data.string, sb);
+ out = sb.termedBuf();
+ }
+ break;
+#endif
+
+#if ICAP_CLIENT
+ case LFT_ICAP_LAST_MATCHED_HEADER:
+ if (al->request) {
+ Adaptation::Icap::History::Pointer ih = al->request->icapHistory();
+ if (ih != NULL)
+ sb = ih->mergeOfIcapHeaders.getByName(fmt->data.header.header);
+ }
+
+ out = sb.termedBuf();
+
+ quote = 1;
+
+ break;
+
+ case LFT_ICAP_LAST_MATCHED_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);
+ }
+
+ out = sb.termedBuf();
+
+ quote = 1;
+
+ break;
+
+ case LFT_ICAP_LAST_MATCHED_ALL_HEADERS:
+ out = al->headers.icap;
+
+ quote = 1;
+
+ break;
+
+ case LFT_ICAP_ADDR:
+ if (!out)
+ out = al->icap.hostAddr.NtoA(tmp,1024);
+ break;
+
+ case LFT_ICAP_SERV_NAME:
+ out = al->icap.serviceName.termedBuf();
+ break;
+
+ case LFT_ICAP_REQUEST_URI:
+ out = al->icap.reqUri.termedBuf();
+ break;
+
+ case LFT_ICAP_REQUEST_METHOD:
+ out = Adaptation::Icap::ICAP::methodStr(al->icap.reqMethod);
+ break;
+
+ case LFT_ICAP_BYTES_SENT:
+ outint = al->icap.bytesSent;
+ doint = 1;
+ break;
+
+ case LFT_ICAP_BYTES_READ:
+ outint = al->icap.bytesRead;
+ doint = 1;
+ break;
+
+ case LFT_ICAP_REQ_HEADER:
+ if (NULL != al->icap.request) {
+ sb = al->icap.request->header.getByName(fmt->data.header.header);
+ out = sb.termedBuf();
+ quote = 1;
+ }
+ break;
+
+ case LFT_ICAP_REQ_HEADER_ELEM:
+ if (al->request)
+ sb = al->icap.request->header.getByNameListMember(fmt->data.header.header, fmt->data.header.element, fmt->data.header.separator);
+
+ out = sb.termedBuf();
+
+ quote = 1;
+
+ break;
+
+ case LFT_ICAP_REQ_ALL_HEADERS:
+ if (al->icap.request) {
+ HttpHeaderPos pos = HttpHeaderInitPos;
+ while (const HttpHeaderEntry *e = al->icap.request->header.getEntry(&pos)) {
+ sb.append(e->name);
+ sb.append(": ");
+ sb.append(e->value);
+ sb.append("\r\n");
+ }
+ out = sb.termedBuf();
+ quote = 1;
+ }
+ break;
+
+ case LFT_ICAP_REP_HEADER:
+ if (NULL != al->icap.reply) {
+ sb = al->icap.reply->header.getByName(fmt->data.header.header);
+ out = sb.termedBuf();
+ quote = 1;
+ }
+ break;
+
+ case LFT_ICAP_REP_HEADER_ELEM:
+ if (NULL != al->icap.reply)
+ sb = al->icap.reply->header.getByNameListMember(fmt->data.header.header, fmt->data.header.element, fmt->data.header.separator);
+
+ out = sb.termedBuf();
+
+ quote = 1;
+
+ break;
+
+ case LFT_ICAP_REP_ALL_HEADERS:
+ if (al->icap.reply) {
+ HttpHeaderPos pos = HttpHeaderInitPos;
+ while (const HttpHeaderEntry *e = al->icap.reply->header.getEntry(&pos)) {
+ sb.append(e->name);
+ sb.append(": ");
+ sb.append(e->value);
+ sb.append("\r\n");
+ }
+ out = sb.termedBuf();
+ quote = 1;
+ }
+ break;
+
+ case LFT_ICAP_TR_RESPONSE_TIME:
+ outint = al->icap.trTime;
+ doint = 1;
+ break;
+
+ case LFT_ICAP_IO_TIME:
+ outint = al->icap.ioTime;
+ doint = 1;
+ break;
+
+ case LFT_ICAP_STATUS_CODE:
+ outint = al->icap.resStatus;
+ doint = 1;
+ break;
+
+ case LFT_ICAP_OUTCOME:
+ out = al->icap.outcome;
+ break;
+
+ case LFT_ICAP_TOTAL_TIME:
+ outint = al->icap.processingTime;
+ doint = 1;
+ break;
+#endif
case LFT_REQUEST_HEADER_ELEM:
if (al->request)
sb = al->request->header.getByNameListMember(fmt->data.header.header, fmt->data.header.element, fmt->data.header.separator);
/* case LFT_USER_REALM: */
/* case LFT_USER_SCHEME: */
- case LFT_HTTP_CODE:
+ // the fmt->type can not be LFT_HTTP_SENT_STATUS_CODE_OLD_30
+ // but compiler complains if ommited
+ case LFT_HTTP_SENT_STATUS_CODE_OLD_30:
+ case LFT_HTTP_SENT_STATUS_CODE:
outint = al->http.code;
doint = 1;
break;
+ case LFT_HTTP_RECEIVED_STATUS_CODE:
+ if(al->hier.peer_reply_status == HTTP_STATUS_NONE) {
+ out = "-";
+ }
+ else {
+ outint = al->hier.peer_reply_status;
+ doint = 1;
+ }
+ break;
/* case LFT_HTTP_STATUS:
* out = statusline->text;
* quote = 1;
break;
/*case LFT_REQUEST_SIZE_LINE: */
- /*case LFT_REQUEST_SIZE_HEADERS: */
+ case LFT_REQUEST_SIZE_HEADERS:
+ outoff = al->cache.requestHeadersSize;
+ dooff =1;
+ break;
/*case LFT_REQUEST_SIZE_BODY: */
/*case LFT_REQUEST_SIZE_BODY_NO_TE: */
break;
/*case LFT_REPLY_SIZE_LINE: */
- /*case LFT_REPLY_SIZE_HEADERS: */
+ case LFT_REPLY_SIZE_HEADERS:
+ outint = al->cache.replyHeadersSize;
+ doint = 1;
/*case LFT_REPLY_SIZE_BODY: */
/*case LFT_REPLY_SIZE_BODY_NO_TE: */
cur++;
}
+ // For upward compatibility, assume "http::" prefix as default prefix
+ // for all log access formating codes, except those starting
+ // from "icap::", "adapt::" and "%"
+ if (strncmp(cur,"http::", 6) == 0 &&
+ strncmp(cur+6, "icap::", 6) != 0 &&
+ strncmp(cur+6, "adapt::", 12) != 0 && *(cur+6) != '%' ) {
+ cur += 6;
+ }
+
lt->type = LFT_NONE;
for (lte = logformat_token_table; lte->config != NULL; lte++) {
switch (lt->type) {
+#if ICAP_CLIENT
+ case LFT_ICAP_LAST_MATCHED_HEADER:
+
+ case LFT_ICAP_REQ_HEADER:
+
+ case LFT_ICAP_REP_HEADER:
+#endif
+
case LFT_REQUEST_HEADER:
case LFT_REPLY_HEADER:
lt->data.header.element = cp;
- lt->type = (lt->type == LFT_REQUEST_HEADER) ?
- LFT_REQUEST_HEADER_ELEM :
- LFT_REPLY_HEADER_ELEM;
+ switch(lt->type) {
+ case LFT_REQUEST_HEADER: lt->type = LFT_REQUEST_HEADER_ELEM; break;
+ 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; break;
+ case LFT_ICAP_REQ_HEADER: lt->type = LFT_ICAP_REQ_HEADER_ELEM; break;
+ case LFT_ICAP_REP_HEADER: lt->type = LFT_ICAP_REP_HEADER_ELEM; break;
+#endif
+ default:break;
+ }
}
lt->data.header.header = header;
} else {
- lt->type = (lt->type == LFT_REQUEST_HEADER) ?
- LFT_REQUEST_ALL_HEADERS :
- LFT_REPLY_ALL_HEADERS;
+ switch(lt->type) {
+ case LFT_REQUEST_HEADER: lt->type = LFT_REQUEST_ALL_HEADERS; break;
+ 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; break;
+ case LFT_ICAP_REQ_HEADER: lt->type = LFT_ICAP_REQ_ALL_HEADERS; break;
+ case LFT_ICAP_REP_HEADER: lt->type = LFT_ICAP_REP_ALL_HEADERS; break;
+#endif
+ default:break;
+ }
Config.onoff.log_mime_hdrs = 1;
}
break;
+ case LFT_HTTP_SENT_STATUS_CODE_OLD_30:
+ debugs(46, 0, "WARNING: the \"Hs\" formating code is deprecated use the \">Hs\" instead");
+ lt->type = LFT_HTTP_SENT_STATUS_CODE;
+ break;
default:
break;
}
case LFT_STRING:
break;
-
+#if ICAP_CLIENT
+ case LFT_ICAP_LAST_MATCHED_HEADER_ELEM:
+ case LFT_ICAP_REQ_HEADER_ELEM:
+ case LFT_ICAP_REP_HEADER_ELEM:
+#endif
case LFT_REQUEST_HEADER_ELEM:
case LFT_REPLY_HEADER_ELEM:
arg = argbuf;
- type = (type == LFT_REQUEST_HEADER_ELEM) ?
- LFT_REQUEST_HEADER :
- LFT_REPLY_HEADER;
+ switch(type) {
+ case LFT_REQUEST_HEADER_ELEM: type = LFT_REQUEST_HEADER_ELEM; break;
+ case LFT_REPLY_HEADER_ELEM: type = LFT_REPLY_HEADER_ELEM; break;
+#if ICAP_CLIENT
+ case LFT_ICAP_LAST_MATCHED_HEADER_ELEM: type = LFT_ICAP_LAST_MATCHED_HEADER; break;
+ case LFT_ICAP_REQ_HEADER_ELEM: type = LFT_ICAP_REQ_HEADER; break;
+ case LFT_ICAP_REP_HEADER_ELEM: type = LFT_ICAP_REP_HEADER; break;
+#endif
+ default:break;
+ }
break;
case LFT_REPLY_ALL_HEADERS:
- type = (type == LFT_REQUEST_ALL_HEADERS) ?
- LFT_REQUEST_HEADER :
- LFT_REPLY_HEADER;
+#if ICAP_CLIENT
+ case LFT_ICAP_LAST_MATCHED_ALL_HEADERS:
+ case LFT_ICAP_REQ_ALL_HEADERS:
+ case LFT_ICAP_REP_ALL_HEADERS:
+#endif
+
+ switch(type) {
+ case LFT_REQUEST_ALL_HEADERS: type = LFT_REQUEST_HEADER; break;
+ 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; break;
+ case LFT_ICAP_REQ_ALL_HEADERS: type = LFT_ICAP_REQ_HEADER; break;
+ case LFT_ICAP_REP_ALL_HEADERS: type = LFT_ICAP_REP_HEADER; break;
+#endif
+ default:break;
+ }
break;
storeAppendPrintf(entry, "{%s}", arg);
for (te = logformat_token_table; te->config != NULL; te++) {
- if (te->token_type == t->type) {
+ if (te->token_type == type) {
storeAppendPrintf(entry, "%s", te->config);
break;
}
}
-void
-accessLogLog(AccessLogEntry * al, ACLChecklist * checklist)
+#if ICAP_CLIENT
+static void
+accessLogICAPSquid(AccessLogEntry * al, Logfile * logfile)
{
- customlog *log;
+ const char *client = NULL;
+ const char *user = NULL;
+ char tmp[MAX_IPSTRLEN], clientbuf[MAX_IPSTRLEN];
- if (LogfileStatus != LOG_ENABLE)
- return;
+ if (al->cache.caddr.IsAnyAddr()) { // ICAP OPTIONS xactions lack client
+ client = "-";
+ } else {
+ if (Config.onoff.log_fqdn)
+ client = fqdncache_gethostbyaddr(al->cache.caddr, FQDN_LOOKUP_IF_MISS);
+ if (!client)
+ client = al->cache.caddr.NtoA(clientbuf, MAX_IPSTRLEN);
+ }
+
+ user = accessLogFormatName(al->cache.authuser);
+
+ if (!user)
+ user = accessLogFormatName(al->cache.extuser);
+
+#if USE_SSL
+
+ if (!user)
+ user = accessLogFormatName(al->cache.ssluser);
+
+#endif
+
+ if (!user)
+ user = accessLogFormatName(al->cache.rfc931);
+
+ if (user && !*user)
+ safe_free(user);
+
+ logfilePrintf(logfile, "%9ld.%03d %6d %s -/%03d %"PRId64" %s %s %s -/%s -\n",
+ (long int) current_time.tv_sec,
+ (int) current_time.tv_usec / 1000,
+
+ al->icap.trTime,
+ client,
+
+ al->icap.resStatus,
+ al->icap.bytesRead,
+ Adaptation::Icap::ICAP::methodStr(al->icap.reqMethod),
+ al->icap.reqUri.termedBuf(),
+ user ? user : dash_str,
+ al->icap.hostAddr.NtoA(tmp, MAX_IPSTRLEN));
+ safe_free(user);
+}
+#endif
+
+void
+accessLogLogTo(customlog* log, AccessLogEntry * al, ACLChecklist * checklist)
+{
if (al->url == NULL)
al->url = dash_str;
if (al->hier.host[0] == '\0')
xstrncpy(al->hier.host, dash_str, SQUIDHOSTNAMELEN);
- for (log = Config.Log.accesslogs; log; log = log->next) {
+ for (; log; log = log->next) {
if (checklist && log->aclList && !checklist->matchAclListFast(log->aclList))
continue;
break;
+#if ICAP_CLIENT
+ case CLF_ICAP_SQUID:
+ accessLogICAPSquid(al, log->logfile);
+
+ break;
+#endif
+
case CLF_NONE:
goto last;
last:
(void)0; /* NULL statement for label */
+}
+void
+accessLogLog(AccessLogEntry * al, ACLChecklist * checklist)
+{
+ if (LogfileStatus != LOG_ENABLE)
+ return;
+
+ accessLogLogTo(Config.Log.accesslogs, al, checklist);
#if MULTICAST_MISS_STREAM
if (al->cache.code != LOG_TCP_MISS)
code(HIER_NONE),
cd_lookup(LOOKUP_NONE),
n_choices(0),
- n_ichoices(0)
+ n_ichoices(0),
+ peer_reply_status(HTTP_STATUS_NONE),
+ peer_response_time(-1),
+ total_response_time(-1)
{
memset(host, '\0', SQUIDHOSTNAMELEN);
memset(cd_host, '\0', SQUIDHOSTNAMELEN);
store_complete_stop.tv_sec =0;
store_complete_stop.tv_usec =0;
+
+ peer_http_request_sent.tv_sec = 0;
+ peer_http_request_sent.tv_usec = 0;
+
+ first_conn_start.tv_sec = 0;
+ first_conn_start.tv_usec = 0;
}
void
log->logfile = logfileOpen(log->filename, MAX_URL << 1, 1);
LogfileStatus = LOG_ENABLE;
+
+#if USE_ADAPTATION || ICAP_CLIENT
+ alLogformatHasAdaptToken = false;
+ alLogformatHasIcapToken = false;
+ for (logformat_token * curr_token = (log->logFormat?log->logFormat->format:NULL); curr_token; curr_token = curr_token->next)
+ {
+#if USE_ADAPTATION
+ if (curr_token->type == LTF_ADAPTATION_SUM_XACT_TIMES ||
+ curr_token->type == LTF_ADAPTATION_ALL_XACT_TIMES) {
+ 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)
+ {
+ alLogformatHasIcapToken = true;
+ }
+#endif
+ }
+#endif
}
#if HEADERS_LOG
accessLogFreeMemory(AccessLogEntry * aLogEntry)
{
safe_free(aLogEntry->headers.request);
+
+#if ICAP_CLIENT
+ safe_free(aLogEntry->headers.icap);
+#endif
+
safe_free(aLogEntry->headers.reply);
safe_free(aLogEntry->cache.authuser);
HTTPMSGUNLOCK(aLogEntry->reply);
HTTPMSGUNLOCK(aLogEntry->request);
+#if ICAP_CLIENT
+ HTTPMSGUNLOCK(aLogEntry->icap.reply);
+ HTTPMSGUNLOCK(aLogEntry->icap.request);
+#endif
}
int
}
void
-DestinationDomainLookup::LookupDone(const char *fqdn, void *data)
+DestinationDomainLookup::LookupDone(const char *fqdn, const DnsLookupDetails &details, void *data)
{
- ACLChecklist *checklist = (ACLChecklist *)data;
+ ACLFilledChecklist *checklist = Filled((ACLChecklist*)data);
assert (checklist->asyncState() == DestinationDomainLookup::Instance());
checklist->asyncInProgress(false);
checklist->changeState (ACLChecklist::NullState::Instance());
- Filled(checklist)->markDestinationDomainChecked();
+ checklist->markDestinationDomainChecked();
+ checklist->request->recordLookup(details);
checklist->check();
}
private:
static DestinationDomainLookup instance_;
- static void LookupDone(const char *, void *);
+ static void LookupDone(const char *, const DnsLookupDetails &, void *);
};
/// \ingroup ACLAPI
}
void
-DestinationIPLookup::LookupDone(const ipcache_addrs * ia, void *data)
+DestinationIPLookup::LookupDone(const ipcache_addrs *, const DnsLookupDetails &details, void *data)
{
- ACLChecklist *checklist = (ACLChecklist *)data;
+ ACLFilledChecklist *checklist = Filled((ACLChecklist*)data);
assert (checklist->asyncState() == DestinationIPLookup::Instance());
- Filled(checklist)->request->flags.destinationIPLookupCompleted();
+ checklist->request->flags.destinationIPLookupCompleted();
+ checklist->request->recordLookup(details);
checklist->asyncInProgress(false);
checklist->changeState (ACLChecklist::NullState::Instance());
checklist->check();
#include "acl/Checklist.h"
#include "acl/RegexData.h"
#include "acl/DomainData.h"
+#include "HttpRequest.h"
SourceDomainLookup SourceDomainLookup::instance_;
}
void
-SourceDomainLookup::LookupDone(const char *fqdn, void *data)
+SourceDomainLookup::LookupDone(const char *fqdn, const DnsLookupDetails &details, void *data)
{
- ACLChecklist *checklist = (ACLChecklist *)data;
+ ACLFilledChecklist *checklist = Filled((ACLChecklist*)data);
assert (checklist->asyncState() == SourceDomainLookup::Instance());
checklist->asyncInProgress(false);
checklist->changeState (ACLChecklist::NullState::Instance());
- Filled(checklist)->markSourceDomainChecked();
+ checklist->markSourceDomainChecked();
+ checklist->request->recordLookup(details);
checklist->check();
}
private:
static SourceDomainLookup instance_;
- static void LookupDone(const char *, void *);
+ static void LookupDone(const char *, const DnsLookupDetails &, void *);
};
class ACLSourceDomain
acl_checklist = NULL;
+#if ICAP_CLIENT
+ Adaptation::Icap::History::Pointer h = req->icapHistory();
+ if (h != NULL)
+ h->start("ACL");
+#endif
+
debugs(93, 5, HERE << "AccessCheck constructed for " << methodStr(method) << " " << vectPointStr(point));
}
Adaptation::AccessCheck::~AccessCheck()
{
+#if ICAP_CLIENT
+ Adaptation::Icap::History::Pointer h = req->icapHistory();
+ if (h != NULL)
+ h->stop("ACL");
+#endif
HTTPMSGUNLOCK(req);
HTTPMSGUNLOCK(rep);
if (callback_data)
#include "adaptation/Service.h"
#include "adaptation/AccessRule.h"
#include "adaptation/ServiceGroups.h"
+#include "adaptation/History.h"
bool Adaptation::Config::Enabled = false;
+char *Adaptation::Config::masterx_shared_name = NULL;
void
Adaptation::Config::parseService()
Enabled = enabled;
debugs(93,1, "Adaptation support is " << (Enabled ? "on" : "off."));
+ History::Configure();
FinalizeEach(AllServices(), "message adaptation services");
FinalizeEach(AllGroups(), "message adaptation service groups");
FinalizeEach(AllRules(), "message adaptation access rules");
public:
static bool Enabled; // true if at least one adaptation mechanism is
+ // these are global squid.conf options, documented elsewhere
+ static char *masterx_shared_name; // global TODO: do we need TheConfig?
+ // Options below are accessed via Icap::TheConfig or Ecap::TheConfig
+ // TODO: move ICAP-specific options to Icap::Config and add TheConfig
int onoff;
int send_client_ip;
int send_client_username;
--- /dev/null
+#include "config.h"
+#include "globals.h"
+#include "TextException.h"
+#include "SquidTime.h"
+#include "HttpRequest.h" /* for alLogformatHasAdaptToken */
+#include "adaptation/Config.h"
+#include "adaptation/History.h"
+
+Adaptation::History::Entry::Entry(const String &sid, const timeval &when):
+ service(sid), start(when), theRptm(-1), retried(false)
+{
+}
+
+Adaptation::History::Entry::Entry():
+ start(current_time), theRptm(-1), retried(false)
+{
+}
+
+void Adaptation::History::Entry::stop()
+{
+ // theRptm may already be set if the access log entry has already been made
+ (void)rptm(); // will cache result in theRptm if not set already
+}
+
+int Adaptation::History::Entry::rptm()
+{
+ if (theRptm < 0)
+ theRptm = tvSubMsec(start, current_time);
+ return theRptm;
+}
+
+
+int Adaptation::History::recordXactStart(const String &sid, const timeval &when, bool retrying)
+{
+ if (retrying) {
+ Must(!theEntries.empty()); // or there would be nothing to retry
+ theEntries.back().retried = true;
+ }
+ theEntries.push_back(Adaptation::History::Entry(sid, when));
+ return theEntries.size() - 1; // record position becomes history ID
+}
+
+void Adaptation::History::recordXactFinish(int hid)
+{
+ Must(0 <= hid && hid < static_cast<int>(theEntries.size()));
+ theEntries[hid].stop();
+}
+
+void Adaptation::History::allLogString(const char *serviceId, String &s)
+{
+ s="";
+ bool prevWasRetried = false;
+ // XXX: Fix Vector<> so that we can use const_iterator here
+ typedef Adaptation::History::Entries::iterator ECI;
+ for (ECI i = theEntries.begin(); i != theEntries.end(); ++i) {
+ // TODO: here and below, optimize service ID comparison?
+ if (!serviceId || i->service == serviceId) {
+ if (s.size() > 0) // not the first logged time, must delimit
+ s.append(prevWasRetried ? "+" : ",");
+
+ char buf[64];
+ snprintf(buf, sizeof(buf), "%d", i->rptm());
+ s.append(buf);
+
+ // continue; we may have two identical services (e.g., for retries)
+ }
+ prevWasRetried = i->retried;
+ }
+}
+
+void Adaptation::History::sumLogString(const char *serviceId, String &s)
+{
+ s="";
+ int retriedRptm = 0; // sum of rptm times of retried transactions
+ typedef Adaptation::History::Entries::iterator ECI;
+ for (ECI i = theEntries.begin(); i != theEntries.end(); ++i) {
+ if (i->retried) { // do not log retried xact but accumulate their time
+ retriedRptm += i->rptm();
+ } else
+ if (!serviceId || i->service == serviceId) {
+ if (s.size() > 0) // not the first logged time, must delimit
+ s.append(",");
+
+ char buf[64];
+ snprintf(buf, sizeof(buf), "%d", retriedRptm + i->rptm());
+ s.append(buf);
+
+ // continue; we may have two identical services (e.g., for retries)
+ }
+
+ if (!i->retried)
+ retriedRptm = 0;
+ }
+
+ // the last transaction is never retried or it would not be the last
+ Must(!retriedRptm);
+}
+
+void Adaptation::History::updateXxRecord(const char *name, const String &value)
+{
+ theXxName = name;
+ theXxValue = value;
+}
+
+bool Adaptation::History::getXxRecord(String &name, String &value) const
+{
+ if (theXxName.size() <= 0)
+ return false;
+
+ name = theXxName;
+ value = theXxValue;
+ return true;
+}
+
+
+bool Adaptation::History::Enabled = false;
+
+void Adaptation::History::Configure()
+{
+ const bool loggingNeedsUs = LogfileStatus == LOG_ENABLE &&
+ alLogformatHasAdaptToken;
+
+ Enabled = Adaptation::Config::Enabled &&
+ (loggingNeedsUs || Adaptation::Config::masterx_shared_name);
+
+ // TODO: should we disable unneeded _parts_ of the history?
+}
--- /dev/null
+#ifndef SQUID_ADAPT_HISTORY_H
+#define SQUID_ADAPT_HISTORY_H
+
+#include "RefCount.h"
+#include "Array.h"
+#include "SquidString.h"
+
+namespace Adaptation {
+
+
+/// collects information about adaptations related to a master transaction
+class History: public RefCountable {
+public:
+ typedef RefCount<Adaptation::History> Pointer;
+
+ /// record the start of a xact, return xact history ID
+ int recordXactStart(const String &serviceId, const timeval &when, bool retrying);
+
+ /// record the end of a xact identified by its history ID
+ void recordXactFinish(int hid);
+
+ /// dump individual xaction times to a string
+ void allLogString(const char *serviceId, String &buf);
+
+ /// dump xaction times, merging retried and retry times together
+ void sumLogString(const char *serviceId, String &buf);
+
+ /// sets or resets a cross-transactional database record
+ void updateXxRecord(const char *name, const String &value);
+
+ /// returns true and fills the record fields iff there is a db record
+ bool getXxRecord(String &name, String &value) const;
+
+ static bool Enabled; ///< whether some configuration options require it
+ static void Configure(); ///< determines whether the history is needed
+
+private:
+ /// single Xaction stats (i.e., a historical record entry)
+ class Entry {
+ public:
+ Entry(const String &serviceId, const timeval &when);
+ Entry(); // required by Vector<>
+
+ void stop(); ///< updates stats on transaction end
+ int rptm(); ///< returns response time [msec], calculates it if needed
+
+ String service; ///< adaptation service ID
+ timeval start; ///< when the xaction was started
+
+ private:
+ int theRptm; ///< calculated and cached response time value in msec
+
+ public:
+ bool retried; ///< whether the xaction was replaced by another
+ };
+
+ typedef Vector<Entry> Entries;
+ Entries theEntries; ///< historical record, in the order of xact starts
+
+ // theXx* will become a map<string,string>, but we only support one record
+ String theXxName; ///< name part of the cross-transactional database record
+ String theXxValue; ///< value part of the cross-xactional database record
+};
+
+} // namespace Adaptation
+
+#endif
bool isThere(); // we have a valid initiator pointer
Initiator *ptr(); // asserts isThere()
+ void *theCbdata() { return cbdata;}
private:
InitiatorHolder &operator =(const InitiatorHolder &anInitiator);
InitiatorHolder theInitiator;
ServicePointer theService;
+
+private:
+ Initiate(const Initiate &); // no definition
+ Initiate &operator =(const Initiate &); // no definition
};
} // namespace Adaptation
ServiceConfig.cc \
ServiceConfig.h \
ServiceGroups.cc \
- ServiceGroups.h
+ ServiceGroups.h \
+ History.cc \
+ History.h
# add libraries for specific adaptation schemes
libadaptation_la_LIBADD = @ECAP_LIBS@ @ECAPLIB@ @ICAP_LIBS@
#include "TextException.h"
#include "HttpRequest.h"
#include "HttpReply.h"
+#include "SquidTime.h"
#include "adaptation/ecap/XactionRep.h"
CBDATA_NAMESPACED_CLASS_INIT(Adaptation::Ecap::XactionRep, XactionRep);
AsyncJob("Adaptation::Ecap::XactionRep"),
Adaptation::Initiate("Adaptation::Ecap::XactionRep", anInitiator, aService),
theVirginRep(virginHeader), theCauseRep(NULL),
- proxyingVb(opUndecided), proxyingAb(opUndecided), canAccessVb(false),
+ proxyingVb(opUndecided), proxyingAb(opUndecided),
+ adaptHistoryId(-1),
+ canAccessVb(false),
abProductionFinished(false), abProductionAtEnd(false)
{
if (virginCause)
else
proxyingVb = opNever;
+ const HttpRequest *request = dynamic_cast<const HttpRequest*> (theCauseRep ?
+ theCauseRep->raw().header : theVirginRep.raw().header);
+ Must(request);
+ Adaptation::History::Pointer ah = request->adaptHistory();
+ if (ah != NULL) {
+ // retrying=false because ecap never retries transactions
+ adaptHistoryId = ah->recordXactStart(service().cfg().key, current_time, false);
+ }
+
theMaster->start();
}
}
terminateMaster();
+
+ const HttpRequest *request = dynamic_cast<const HttpRequest*>(theCauseRep ?
+ theCauseRep->raw().header : theVirginRep.raw().header);
+ Must(request);
+ Adaptation::History::Pointer ah = request->adaptHistory();
+ if (ah != NULL && adaptHistoryId >= 0)
+ ah->recordXactFinish(adaptHistoryId);
+
Adaptation::Initiate::swanSong();
}
typedef enum { opUndecided, opOn, opComplete, opNever } OperationState;
OperationState proxyingVb; // delivering virgin body from core to adapter
OperationState proxyingAb; // delivering adapted body from adapter to core
+ int adaptHistoryId; ///< adaptation history slot reservation
bool canAccessVb; // virgin BodyPipe content is accessible
bool abProductionFinished; // whether adapter has finished producing ab
bool abProductionAtEnd; // whether adapter produced a complete ab
Adaptation::Icap::Config::Config(): preview_enable(0), preview_size(0),
connect_timeout_raw(0), io_timeout_raw(0), reuse_connections(0),
- client_username_header(NULL), client_username_encode(0)
+ client_username_header(NULL), client_username_encode(0), repeat(NULL)
{
}
#include "adaptation/Config.h"
#include "adaptation/icap/ServiceRep.h"
+class acl_access;
namespace Adaptation
{
namespace Icap {
-class acl_access;
-
class ConfigParser;
class Config: public Adaptation::Config
int reuse_connections;
char* client_username_header;
int client_username_encode;
+ acl_access *repeat; ///< icap_retry ACL in squid.conf
+ int repeat_limit; ///< icap_retry_limit in squid.conf
Config();
~Config();
#include "adaptation/icap/Elements.h"
// TODO: remove this file?
+namespace Adaptation {
+namespace Icap {
+
+const XactOutcome xoUnknown = "ICAP_ERR_UNKNOWN";
+const XactOutcome xoError = "ICAP_ERR_OTHER";
+const XactOutcome xoOpt = "ICAP_OPT";
+const XactOutcome xoEcho = "ICAP_ECHO";
+const XactOutcome xoModified = "ICAP_MOD";
+const XactOutcome xoSatisfied = "ICAP_SAT";
+
+} // namespace Icap
+} // namespace Adaptation
{
namespace Icap {
+//TODO: remove the ICAP namespace
namespace ICAP {
using Adaptation::Method;
using Adaptation::methodNone;
using Adaptation::vectPointStr;
}
+typedef const char *XactOutcome; ///< transaction result for logging
+extern const XactOutcome xoUnknown; ///< initial value: outcome was not set
+extern const XactOutcome xoError; ///< all kinds of transaction errors
+extern const XactOutcome xoOpt; ///< OPTION transaction
+extern const XactOutcome xoEcho; ///< preserved virgin message (ICAP 204)
+extern const XactOutcome xoModified; ///< replaced virgin msg with adapted
+extern const XactOutcome xoSatisfied; ///< request satisfaction
} // namespace Icap
} // namespace Adaptation
--- /dev/null
+#include "adaptation/icap/History.h"
+#include "squid.h"
+#include "globals.h"
+#include "SquidTime.h"
+
+Adaptation::Icap::History::History(): mergeOfIcapHeaders(hoRequest),
+ lastIcapHeader(hoRequest), 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++)
+ currentStart = current_time;
+
+ debugs(93,4, HERE << "start " << context << " level=" << concurrencyLevel
+ << " time=" << pastTime << ' ' << this);
+}
+
+void Adaptation::Icap::History::stop(const char *context)
+{
+ if (!concurrencyLevel) {
+ debugs(93,1, HERE << "Internal error: poor history accounting " << this);
+ return;
+ }
+
+ const int current = currentTime();
+ debugs(93,4, HERE << "stop " << context << " level=" << concurrencyLevel <<
+ " time=" << pastTime << '+' << current << ' ' << this);
+
+ if (!--concurrencyLevel)
+ pastTime += current;
+}
+
+int Adaptation::Icap::History::processingTime() const
+{
+ const int total = pastTime + currentTime();
+ debugs(93,7, HERE << " current total: " << total << ' ' << this);
+ return total;
+}
+
+int Adaptation::Icap::History::currentTime() const
+{
+ return concurrencyLevel > 0 ?
+ max(0, tvSubMsec(currentStart, current_time)) : 0;
+}
--- /dev/null
+#ifndef SQUID_ICAPHISTORY_H
+#define SQUID_ICAPHISTORY_H
+
+#include "RefCount.h"
+#include "HttpHeader.h"
+#include "enums.h"
+
+namespace Adaptation {
+namespace Icap {
+
+/// collects information about ICAP processing related to an HTTP transaction
+class History: public RefCountable {
+public:
+ typedef RefCount<History> 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);
+ /// note the end of an ICAP processing interval
+ void stop(const char *context);
+
+ /// 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
+#endif
+ log_type logType; ///< the squid request status (TCP_MISS etc)
+
+ String log_uri; ///< the request uri
+ 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
+ int pastTime; ///< sum of closed processing interval durations
+ int concurrencyLevel; ///< number of concurrent processing threads
+};
+
+} // namespace Icap
+} // namespace Adaptation
+
+#endif /*SQUID_HISTORY_H*/
#include "squid.h"
#include "TextException.h"
+#include "HttpRequest.h"
+#include "HttpReply.h"
+#include "acl/FilledChecklist.h"
#include "HttpMsg.h"
#include "adaptation/icap/Launcher.h"
#include "adaptation/icap/Xaction.h"
#include "adaptation/icap/ServiceRep.h"
+#include "adaptation/icap/Config.h"
Adaptation::Icap::Launcher::Launcher(const char *aTypeName,
Adaptation::Initiate::start();
Must(theInitiator);
- launchXaction(false);
+ launchXaction("first");
}
-void Adaptation::Icap::Launcher::launchXaction(bool final)
+void Adaptation::Icap::Launcher::launchXaction(const char *xkind)
{
Must(!theXaction);
++theLaunches;
- debugs(93,4, HERE << "launching xaction #" << theLaunches);
+ debugs(93,4, HERE << "launching " << xkind << " xaction #" << theLaunches);
Adaptation::Icap::Xaction *x = createXaction();
- if (final)
+ x->attempts = theLaunches;
+ if (theLaunches > 1)
x->disableRetries();
+ if (theLaunches >= TheConfig.repeat_limit)
+ x->disableRepeats("over icap_retry_limit");
theXaction = initiateAdaptation(x);
Must(theXaction);
}
}
+// XXX: this call is unused by ICAPXaction in favor of ICAPLauncher::noteXactAbort
void Adaptation::Icap::Launcher::noteAdaptationQueryAbort(bool final)
{
+ debugs(93,5, HERE << "launches: " << theLaunches << "; final: " << final);
clearAdaptation(theXaction);
+
+ Must(done()); // swanSong will notify the initiator
+}
+
+void Adaptation::Icap::Launcher::noteXactAbort(XactAbortInfo &info)
+{
+ debugs(93,5, HERE << "theXaction:" << theXaction << " launches: " << theLaunches);
- // TODO: add more checks from FwdState::checkRetry()?
- if (!final && theLaunches < 2 && !shutting_down) {
- launchXaction(true);
+ // TODO: add more checks from FwdState::checkRetry()?
+ if (canRetry(info)) {
+ clearAdaptation(theXaction);
+ launchXaction("retry");
+ }
+ else if (canRepeat(info)) {
+ clearAdaptation(theXaction);
+ launchXaction("repeat");
} else {
- debugs(93,3, HERE << "cannot retry the failed ICAP xaction; tries: " <<
- theLaunches << "; final: " << final);
- Must(done()); // swanSong will notify the initiator
- }
+ debugs(93,3, HERE << "cannot retry or repeat a failed transaction");
+ clearAdaptation(theXaction);
+ Must(done()); // swanSong will notify the initiator
+ }
}
bool Adaptation::Icap::Launcher::doneAll() const
Adaptation::Initiate::swanSong();
}
+
+bool Adaptation::Icap::Launcher::canRetry(Adaptation::Icap::XactAbortInfo &info) const
+{
+ // We do not check and can exceed zero repeat limit when retrying.
+ // This is by design as the limit does not apply to pconn retrying.
+ return !shutting_down && info.isRetriable;
+}
+
+bool Adaptation::Icap::Launcher::canRepeat(Adaptation::Icap::XactAbortInfo &info) const
+{
+ debugs(93,9, HERE << shutting_down);
+ if (theLaunches >= TheConfig.repeat_limit || shutting_down)
+ return false;
+
+ debugs(93,9, HERE << info.isRepeatable); // TODO: update and use status()
+ if (!info.isRepeatable)
+ return false;
+
+ debugs(93,9, HERE << info.icapReply);
+ if (!info.icapReply) // did not get to read an ICAP reply; a timeout?
+ return true;
+
+ debugs(93,9, HERE << info.icapReply->sline.status);
+ if (!info.icapReply->sline.status) // failed to parse the reply; I/O err
+ return true;
+
+ ACLFilledChecklist *cl =
+ new ACLFilledChecklist(TheConfig.repeat, info.icapRequest, dash_str);
+ cl->reply = HTTPMSGLOCK(info.icapReply);
+
+ const bool result = cl->fastCheck();
+ delete cl;
+ return result;
+}
+
+/* ICAPXactAbortInfo */
+
+Adaptation::Icap::XactAbortInfo::XactAbortInfo(HttpRequest *anIcapRequest,
+ HttpReply *anIcapReply, bool beRetriable, bool beRepeatable):
+ icapRequest(anIcapRequest ? HTTPMSGLOCK(anIcapRequest) : NULL),
+ icapReply(anIcapReply ? HTTPMSGLOCK(anIcapReply) : NULL),
+ isRetriable(beRetriable), isRepeatable(beRepeatable)
+{
+}
+
+Adaptation::Icap::XactAbortInfo::XactAbortInfo(const Adaptation::Icap::XactAbortInfo &i):
+ icapRequest(i.icapRequest ? HTTPMSGLOCK(i.icapRequest) : NULL),
+ icapReply(i.icapReply ? HTTPMSGLOCK(i.icapReply) : NULL),
+ isRetriable(i.isRetriable), isRepeatable(i.isRepeatable)
+{
+}
+
+Adaptation::Icap::XactAbortInfo::~XactAbortInfo()
+{
+ HTTPMSGUNLOCK(icapRequest);
+ HTTPMSGUNLOCK(icapReply);
+}
namespace Icap {
class Xaction;
+class XactAbortInfo;
// Note: Initiate must be the first parent for cbdata to work. We use
// a temporary InitaitorHolder/toCbdata hacks and do not call cbdata
// Adaptation::Initiator: asynchronous communication with the current transaction
virtual void noteAdaptationAnswer(HttpMsg *message);
+ virtual void noteXactAbort(XactAbortInfo &info);
+
+private:
+ bool canRetry(XactAbortInfo &info) const; //< true if can retry in the case of persistent connection failures
+ bool canRepeat(XactAbortInfo &info) const; //< true if can repeat in the case of no or unsatisfactory response
virtual void noteAdaptationQueryAbort(bool final);
protected:
// creates the right ICAP transaction using stored configuration params
virtual Xaction *createXaction() = 0;
- void launchXaction(bool final);
+ void launchXaction(const char *xkind);
- Adaptation::Initiate *theXaction; // current ICAP transaction
+ Adaptation::Initiate *theXaction; ///< current ICAP transaction
int theLaunches; // the number of transaction launches
};
+/// helper class to pass information about aborted ICAP requests to
+/// the Adaptation::Icap::Launcher class
+class XactAbortInfo {
+public:
+ XactAbortInfo(HttpRequest *anIcapRequest, HttpReply *anIcapReply,
+ bool beRetriable, bool beRepeatable);
+ XactAbortInfo(const XactAbortInfo &);
+ ~XactAbortInfo();
+
+ HttpRequest *icapRequest;
+ HttpReply *icapReply;
+ bool isRetriable;
+ bool isRepeatable;
+
+private:
+ XactAbortInfo &operator =(const XactAbortInfo &); // undefined
+};
+
+/* required by UnaryMemFunT */
+inline std::ostream &operator << (std::ostream &os, Adaptation::Icap::XactAbortInfo info)
+{
+ // Nothing, it is unused
+ return os;
+}
+
+/// A Dialer class used to schedule the Adaptation::Icap::Launcher::noteXactAbort call
+class XactAbortCall: public UnaryMemFunT<Adaptation::Icap::Launcher, Adaptation::Icap::XactAbortInfo> {
+public:
+ typedef void (Adaptation::Icap::Launcher::*DialMethod)(Adaptation::Icap::XactAbortInfo &);
+ XactAbortCall(Adaptation::Icap::Launcher *launcer, DialMethod aMethod,
+ const Adaptation::Icap::XactAbortInfo &info):
+ UnaryMemFunT<Adaptation::Icap::Launcher, Adaptation::Icap::XactAbortInfo>(launcer, NULL, info),
+ dialMethod(aMethod)
+ {}
+ virtual void print(std::ostream &os) const { os << '(' << "retriable:" << arg1.isRetriable << ", repeatable:" << arg1.isRepeatable << ')'; }
+
+public:
+ DialMethod dialMethod;
+
+protected:
+ virtual void doDial() { (object->*dialMethod)(arg1); }
+};
} // namespace Icap
} // namespace Adaptation
+
#endif /* SQUID_ICAPLAUNCHER_H */
Xaction.cc \
Xaction.h \
ModXact.cc \
- ModXact.h
+ ModXact.h \
+ icap_log.cc \
+ icap_log.h \
+ History.cc \
+ History.h
#include "auth/UserRequest.h"
#include "adaptation/icap/Config.h"
#include "SquidTime.h"
+#include "AccessLogEntry.h"
+#include "adaptation/icap/History.h"
+#include "adaptation/History.h"
// flow and terminology:
// HTTP| --> receive --> encode --> write --> |network
HttpRequest *virginCause, Adaptation::Icap::ServiceRep::Pointer &aService):
AsyncJob("Adaptation::Icap::ModXact"),
Adaptation::Icap::Xaction("Adaptation::Icap::ModXact", anInitiator, aService),
- icapReply(NULL),
virginConsumed(0),
bodyParser(NULL),
- canStartBypass(false) // too early
+ canStartBypass(false), // too early
+ replyBodySize(0),
+ adaptHistoryId(-1)
{
assert(virginHeader);
// encoding
// nothing to do because we are using temporary buffers
- // parsing
- icapReply = new HttpReply;
+ // parsing; TODO: do not set until we parse, see ICAPOptXact
+ icapReply = HTTPMSGLOCK(new HttpReply);
icapReply->protoPrefix = "ICAP/"; // TODO: make an IcapReply class?
debugs(93,7, HERE << "initialized." << status());
{
Adaptation::Icap::Xaction::start();
+ // reserve an adaptation history slot (attempts are known at this time)
+ Adaptation::History::Pointer ah = virginRequest().adaptHistory();
+ if (ah != NULL)
+ adaptHistoryId = ah->recordXactStart(service().cfg().key, icap_tr_start, attempts > 1);
+
estimateVirginBody(); // before virgin disappears!
canStartBypass = service().cfg().bypass;
startWriting();
} else {
disableRetries();
+ disableRepeats("ICAP service is unusable");
throw TexcHere("ICAP service is unusable");
}
}
// write headers
state.writing = State::writingHeaders;
+ icap_tio_start = current_time;
scheduleWrite(requestBuf);
}
buf.append(ICAP::crlf, 2); // chunk-terminating CRLF
}
+const HttpRequest &Adaptation::Icap::ModXact::virginRequest() const
+{
+ const HttpRequest *request = virgin.cause ?
+ virgin.cause : dynamic_cast<const HttpRequest*>(virgin.header);
+ Must(request);
+ return *request;
+}
+
// did the activity reached the end of the virgin body?
bool Adaptation::Icap::ModXact::virginBodyEndReached(const Adaptation::Icap::VirginBodyAct &act) const
{
void Adaptation::Icap::ModXact::virginConsume()
{
- debugs(93, 9, HERE << "consumption guards: " << !virgin.body_pipe << isRetriable);
+ debugs(93, 9, HERE << "consumption guards: " << !virgin.body_pipe << isRetriable <<
+ isRepeatable << canStartBypass);
if (!virgin.body_pipe)
return; // nothing to consume
return; // do not consume if we may have to retry later
BodyPipe &bp = *virgin.body_pipe;
+ const bool wantToPostpone = isRepeatable || canStartBypass;
// Why > 2? HttpState does not use the last bytes in the buffer
// because delayAwareRead() is arguably broken. See
// HttpStateData::maybeReadVirginBody for more details.
- if (canStartBypass && bp.buf().spaceSize() > 2) {
+ if (wantToPostpone && bp.buf().spaceSize() > 2) {
// Postponing may increase memory footprint and slow the HTTP side
// down. Not postponing may increase the number of ICAP errors
// if the ICAP service fails. We may also use "potential" space to
bp.consume(size);
virginConsumed += size;
Must(!isRetriable); // or we should not be consuming
+ disableRepeats("consumed content");
disableBypass("consumed content");
}
}
void Adaptation::Icap::ModXact::handleCommRead(size_t)
{
Must(!state.doneParsing());
+ icap_tio_finish = current_time;
parseMore();
readMore();
}
" bytes");
virginBodySending.progress(size);
virginConsume();
+ disableRepeats("echoed content");
disableBypass("echoed content");
}
// stop (or do not start) sending adapted message body
void Adaptation::Icap::ModXact::stopSending(bool nicely)
{
+ debugs(93, 7, HERE << "Enter stop sending ");
if (doneSending())
return;
+ debugs(93, 7, HERE << "Proceed with stop sending ");
if (state.sending != State::sendingUndecided) {
debugs(93, 7, HERE << "will no longer send" << status());
disableBypass("already started to bypass");
Must(!isRetriable); // or we should not be bypassing
+ // TODO: should the same be enforced for isRepeatable? Check icap_repeat??
prepEchoing();
if (gotEncapsulated("res-hdr")) {
adapted.setHeader(new HttpReply);
+ setOutcome(service().cfg().method == ICAP::methodReqmod ?
+ xoSatisfied : xoModified);
} else if (gotEncapsulated("req-hdr")) {
adapted.setHeader(new HttpRequest);
+ setOutcome(xoModified);
} else
throw TexcHere("Neither res-hdr nor req-hdr in maybeAllocateHttpMsg()");
}
// called after parsing all headers or when bypassing an exception
void Adaptation::Icap::ModXact::startSending()
{
+ disableRepeats("sent headers");
disableBypass("sent headers");
sendAnswer(adapted.header);
break;
}
+ const HttpRequest *request = dynamic_cast<HttpRequest*>(adapted.header);
+ if (!request)
+ request = &virginRequest();
+
+ // 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();
+ if (ah != NULL) {
+ const String val = icapReply->header.getByName(xxName);
+ if (val.size() > 0) // XXX: HttpHeader lacks empty value detection
+ ah->updateXxRecord(xxName, val);
+ }
+ }
+
+ // We need to store received ICAP headers for <icapLastHeader logformat option.
+ // 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);
+ }
+
// handle100Continue() manages state.writing on its own.
// Non-100 status means the server needs no postPreview data from us.
if (state.writing == State::writingPaused)
// We actually start sending (echoig or not) in startSending.
void Adaptation::Icap::ModXact::prepEchoing()
{
+ disableRepeats("preparing to echo content");
disableBypass("preparing to echo content");
+ setOutcome(xoEcho);
// We want to clone the HTTP message, but we do not want
// to copy some non-HTTP state parts that HttpMsg kids carry in them.
debugs(93, 5, HERE << "have " << readBuf.contentSize() << " body bytes after " <<
"parse; parsed all: " << parsed);
+ replyBodySize += adapted.body_pipe->buf().contentSize();
// TODO: expose BodyPipe::putSize() to make this check simpler and clearer
- if (adapted.body_pipe->buf().contentSize() > 0) // parsed something sometime
+ // TODO: do we really need this if we disable when sending headers?
+ if (adapted.body_pipe->buf().contentSize() > 0) { // parsed something sometime
+ disableRepeats("sent adapted content");
disableBypass("sent adapted content");
+ }
if (parsed) {
stopParsing();
stopWriting(false);
stopSending(false);
- if (icapReply) {
- delete icapReply;
- icapReply = NULL;
- }
+ // update adaptation history if start was called and we reserved a slot
+ Adaptation::History::Pointer ah = virginRequest().adaptHistory();
+ if (ah != NULL && adaptHistoryId >= 0)
+ ah->recordXactFinish(adaptHistoryId);
Adaptation::Icap::Xaction::swanSong();
}
+void prepareLogWithRequestDetails(HttpRequest *, AccessLogEntry *);
+
+void Adaptation::Icap::ModXact::finalizeLogInfo()
+{
+ HttpRequest * request_ = NULL;
+ HttpReply * reply_ = NULL;
+ if(!(request_ = dynamic_cast<HttpRequest*>(adapted.header)))
+ {
+ request_ = (virgin.cause? virgin.cause: dynamic_cast<HttpRequest*>(virgin.header));
+ reply_ = dynamic_cast<HttpReply*>(adapted.header);
+ }
+
+ Adaptation::Icap::History::Pointer h = request_->icapHistory();
+ Must(h != NULL); // ICAPXaction::maybeLog calls only if there is a log
+ al.icp.opcode = ICP_INVALID;
+ al.url = h->log_uri.termedBuf();
+ const Adaptation::Icap::ServiceRep &s = service();
+ al.icap.reqMethod = s.cfg().method;
+
+ al.cache.caddr = request_->client_addr;
+
+ al.request = HTTPMSGLOCK(request_);
+ if(reply_)
+ al.reply = HTTPMSGLOCK(reply_);
+ else
+ al.reply = NULL;
+
+ if (h->rfc931.size())
+ al.cache.rfc931 = h->rfc931.termedBuf();
+
+#if USE_SSL
+ if (h->ssluser.size())
+ al.cache.ssluser = h->ssluser.termedBuf();
+#endif
+ al.cache.code = h->logType;
+ al.cache.requestSize = h->req_sz;
+ if (reply_) {
+ al.http.code = reply_->sline.status;
+ al.http.content_type = reply_->content_type.termedBuf();
+ al.cache.replySize = replyBodySize + reply_->hdr_sz;
+ al.cache.highOffset = replyBodySize;
+ //don't set al.cache.objectSize because it hasn't exist yet
+
+ Packer p;
+ MemBuf mb;
+
+ mb.init();
+ packerToMemInit(&p, &mb);
+
+ reply_->header.packInto(&p);
+ al.headers.reply = xstrdup(mb.buf);
+
+ packerClean(&p);
+ mb.clean();
+ }
+ prepareLogWithRequestDetails(request_, &al);
+ Xaction::finalizeLogInfo();
+}
+
+
void Adaptation::Icap::ModXact::makeRequestHeaders(MemBuf &buf)
{
char ntoabuf[MAX_IPSTRLEN];
buf.Printf("Proxy-Authorization: " SQUIDSTRINGPH "\r\n", SQUIDSTRINGPRINT(vh));
}
+ const HttpRequest *request = &virginRequest();
+
+ // share the cross-transactional database records if needed
+ if (Adaptation::Config::masterx_shared_name) {
+ Adaptation::History::Pointer ah = request->adaptHistory();
+ if (ah != NULL) {
+ String name, value;
+ if (ah->getXxRecord(name, value)) {
+ buf.Printf(SQUIDSTRINGPH ": " SQUIDSTRINGPH "\r\n",
+ SQUIDSTRINGPRINT(name), SQUIDSTRINGPRINT(value));
+ }
+ }
+ }
+
+
buf.Printf("Encapsulated: ");
MemBuf httpBuf;
// build HTTP request header, if any
ICAP::Method m = s.method;
- const HttpRequest *request = virgin.cause ?
- virgin.cause :
- dynamic_cast<const HttpRequest*>(virgin.header);
-
// to simplify, we could assume that request is always available
String urlPath;
// start ICAP request body with encapsulated HTTP headers
buf.append(httpBuf.content(), httpBuf.contentSize());
+ // TODO: write IcapRequest class?
+ icapRequest->parseHeader(buf.content(),buf.contentSize());
+
httpBuf.clean();
}
return;
}
- const HttpRequest *request = virgin.cause ?
- virgin.cause :
- dynamic_cast<const HttpRequest*>(virgin.header);
- const String urlPath = request ? request->urlpath : String();
+ const String urlPath = virginRequest().urlpath;
size_t wantedSize;
if (!service().wantsPreview(urlPath, wantedSize)) {
debugs(93, 5, HERE << "should not offer preview for " << urlPath);
{
virgin.setHeader(virginHeader);
virgin.setCause(virginCause);
+ updateHistory(true);
}
Adaptation::Icap::Xaction *Adaptation::Icap::ModXactLauncher::createXaction()
Must(s != NULL);
return new Adaptation::Icap::ModXact(this, virgin.header, virgin.cause, s);
}
+
+void Adaptation::Icap::ModXactLauncher::swanSong() {
+ debugs(93, 5, HERE << "swan sings");
+ updateHistory(false);
+ Adaptation::Icap::Launcher::swanSong();
+}
+
+void Adaptation::Icap::ModXactLauncher::updateHistory(bool start) {
+ HttpRequest *r = virgin.cause ?
+ virgin.cause : dynamic_cast<HttpRequest*>(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 (start)
+ h->start("ICAPModXactLauncher");
+ else
+ h->stop("ICAPModXactLauncher");
+ }
+ }
+}
private:
virtual void start();
+ /// locates the request, either as a cause or as a virgin message itself
+ const HttpRequest &virginRequest() const; // Must always be available
+
void estimateVirginBody();
void makeAdaptedBodyPipe(const char *what);
bool gotEncapsulated(const char *section) const;
void checkConsuming();
-
- HttpReply *icapReply;
+ virtual void finalizeLogInfo();
SizedEstimate virginBody;
VirginBodyAct virginBodyWriting; // virgin body writing state
bool canStartBypass; // enables bypass of transaction failures
+ uint64_t replyBodySize; ///< dechunked ICAP reply body size
+
+ int adaptHistoryId; ///< adaptation history slot reservation
+
class State
{
protected:
virtual Xaction *createXaction();
+ virtual void swanSong();
+
+ /// starts or stops transaction accounting in ICAP history
+ void updateHistory(bool start);
+
InOut virgin;
private:
#include "adaptation/icap/OptXact.h"
#include "adaptation/icap/Options.h"
#include "TextException.h"
+#include "SquidTime.h"
+#include "HttpRequest.h"
CBDATA_NAMESPACED_CLASS_INIT(Adaptation::Icap, OptXact);
CBDATA_NAMESPACED_CLASS_INIT(Adaptation::Icap, OptXactLauncher);
makeRequest(requestBuf);
debugs(93, 9, HERE << "request " << status() << ":\n" <<
(requestBuf.terminate(), requestBuf.content()));
-
+ icap_tio_start = current_time;
scheduleWrite(requestBuf);
}
const String host = s.cfg().host;
buf.Printf("Host: " SQUIDSTRINGPH ":%d\r\n", SQUIDSTRINGPRINT(host), s.cfg().port);
buf.append(ICAP::crlf, 2);
+
+ // XXX: HttpRequest cannot fully parse ICAP Request-Line
+ http_status status;
+ Must(icapRequest->parse(&buf, true, &status) > 0);
}
void Adaptation::Icap::OptXact::handleCommWrote(size_t size)
void Adaptation::Icap::OptXact::handleCommRead(size_t)
{
if (HttpMsg *r = parseResponse()) {
+ icap_tio_finish = current_time;
+ setOutcome(xoOpt);
sendAnswer(r);
+ icapReply = HTTPMSGLOCK(dynamic_cast<HttpReply*>(r));
Must(done()); // there should be nothing else to do
return;
}
status());
debugs(93, 5, HERE << "\n" << readBuf.content());
- HttpReply *r = new HttpReply;
+ HttpReply *r = HTTPMSGLOCK(new HttpReply);
r->protoPrefix = "ICAP/"; // TODO: make an IcapReply class?
if (!parseHttpMsg(r)) { // throws on errors
- delete r;
+ HTTPMSGUNLOCK(r);
return 0;
}
return r;
}
+void Adaptation::Icap::OptXact::swanSong()
+{
+ Adaptation::Icap::Xaction::swanSong();
+}
+
+void Adaptation::Icap::OptXact::finalizeLogInfo()
+{
+ // al.cache.caddr = 0;
+ al.icap.reqMethod = Adaptation::methodOptions;
+ Adaptation::Icap::Xaction::finalizeLogInfo();
+}
+
/* Adaptation::Icap::OptXactLauncher */
Adaptation::Icap::OptXactLauncher::OptXactLauncher(Adaptation::Initiator *anInitiator, Adaptation::ServicePointer aService):
void startReading();
+ virtual void swanSong();
+
private:
+ virtual void finalizeLogInfo();
CBDATA_CLASS2(OptXact);
};
#include "CommCalls.h"
#include "HttpMsg.h"
#include "adaptation/icap/Xaction.h"
+#include "adaptation/icap/Launcher.h"
#include "adaptation/icap/Config.h"
#include "TextException.h"
#include "pconn.h"
+#include "HttpRequest.h"
+#include "HttpReply.h"
+#include "acl/FilledChecklist.h"
+#include "icap_log.h"
#include "fde.h"
+#include "SquidTime.h"
static PconnPool *icapPconnPool = new PconnPool("ICAP Servers");
Adaptation::Icap::Xaction::Xaction(const char *aTypeName, Adaptation::Initiator *anInitiator, Adaptation::Icap::ServiceRep::Pointer &aService):
AsyncJob(aTypeName),
Adaptation::Initiate(aTypeName, anInitiator, aService.getRaw()),
+ icapRequest(NULL),
+ icapReply(NULL),
+ attempts(0),
connection(-1),
commBuf(NULL), commBufSize(0),
commEof(false),
reuseConnection(true),
isRetriable(true),
+ isRepeatable(true),
ignoreLastWrite(false),
connector(NULL), reader(NULL), writer(NULL), closer(NULL)
{
debugs(93,3, typeName << " constructed, this=" << this <<
" [icapx" << id << ']'); // we should not call virtual status() here
+ icapRequest = HTTPMSGLOCK(new HttpRequest);
+ icap_tr_start = current_time;
}
Adaptation::Icap::Xaction::~Xaction()
{
debugs(93,3, typeName << " destructed, this=" << this <<
" [icapx" << id << ']'); // we should not call virtual status() here
+ HTTPMSGUNLOCK(icapRequest);
+ HTTPMSGUNLOCK(icapReply);
}
Adaptation::Icap::ServiceRep &
void Adaptation::Icap::Xaction::disableRetries()
{
- debugs(93,5, typeName << (isRetriable ? " becomes" : " remains") <<
- " final" << status());
+ debugs(93,5, typeName << (isRetriable ? " from now on" : " still") <<
+ " cannot be retried " << status());
isRetriable = false;
}
+void Adaptation::Icap::Xaction::disableRepeats(const char *reason)
+{
+ debugs(93,5, typeName << (isRepeatable ? " from now on" : " still") <<
+ " cannot be repeated because " << reason << status());
+ isRepeatable = false;
+}
+
void Adaptation::Icap::Xaction::start()
{
Adaptation::Initiate::start();
debugs(93, 7, HERE << "ignoring last write; status: " << io.flag);
} else {
Must(io.flag == COMM_OK);
+ al.icap.bytesSent += io.size;
updateTimeout();
handleCommWrote(io.size);
}
mustStop("ICAP service connection externally closed");
}
+void Adaptation::Icap::Xaction::callException(const std::exception &e)
+{
+ setOutcome(xoError);
+ Adaptation::Initiate::callException(e);
+}
+
+
void Adaptation::Icap::Xaction::callEnd()
{
if (doneWithIo()) {
Must(io.flag == COMM_OK);
Must(io.size >= 0);
+ al.icap.bytesRead+=io.size;
+
updateTimeout();
debugs(93, 3, HERE << "read " << io.size << " bytes");
}
+void Adaptation::Icap::Xaction::setOutcome(const Adaptation::Icap::XactOutcome &xo)
+{
+ if (al.icap.outcome != xoUnknown) {
+ debugs(93, 3, HERE << "Warning: reseting outcome: from " <<
+ al.icap.outcome << " to " << xo);
+ } else {
+ debugs(93, 4, HERE << xo);
+ }
+ al.icap.outcome = xo;
+}
+
// This 'last chance' method is called before a 'done' transaction is deleted.
// It is wrong to call virtual methods from a destructor. Besides, this call
// indicates that the transaction will terminate as planned.
memFreeBuf(commBufSize, commBuf);
if (theInitiator)
- tellQueryAborted(!isRetriable);
+ tellQueryAborted();
+
+ maybeLog();
Adaptation::Initiate::swanSong();
}
+void Adaptation::Icap::Xaction::tellQueryAborted() {
+ Adaptation::Icap::Launcher *l = dynamic_cast<Adaptation::Icap::Launcher*>(theInitiator.ptr());
+ Adaptation::Icap::XactAbortInfo abortInfo(icapRequest, icapReply, retriable(), repeatable());
+ CallJob(91, 5, __FILE__, __LINE__,
+ "Adaptation::Icap::Launcher::noteXactAbort",
+ XactAbortCall(l, &Adaptation::Icap::Launcher::noteXactAbort, abortInfo) );
+ clearInitiator();
+}
+
+
+void Adaptation::Icap::Xaction::maybeLog() {
+ if(IcapLogfileStatus == LOG_ENABLE)
+ {
+ ACLChecklist *checklist = new ACLFilledChecklist(::Config.accessList.icap, al.request, dash_str);
+ if (!::Config.accessList.icap || checklist->fastCheck()) {
+ finalizeLogInfo();
+ icapLogLog(&al, checklist);
+ }
+ accessLogFreeMemory(&al);
+ delete checklist;
+ }
+}
+
+void Adaptation::Icap::Xaction::finalizeLogInfo()
+{
+ //prepare log data
+ al.icp.opcode = ICP_INVALID;
+
+ const Adaptation::Icap::ServiceRep &s = service();
+ al.icap.hostAddr = s.cfg().host.termedBuf();
+ al.icap.serviceName = s.cfg().key;
+ al.icap.reqUri = s.cfg().uri;
+
+ al.icap.ioTime = tvSubMsec(icap_tio_start, icap_tio_finish);
+ al.icap.trTime = tvSubMsec(icap_tr_start, current_time);
+
+ al.icap.request = HTTPMSGLOCK(icapRequest);
+ if (icapReply) {
+ al.icap.reply = HTTPMSGLOCK(icapReply);
+ al.icap.resStatus = icapReply->sline.status;
+ }
+}
+
// returns a temporary string depicting transaction status, for debugging
const char *Adaptation::Icap::Xaction::status() const
{
#include "MemBuf.h"
#include "adaptation/icap/ServiceRep.h"
#include "adaptation/Initiate.h"
+#include "AccessLogEntry.h"
class HttpMsg;
class CommConnectCbParams;
virtual ~Xaction();
void disableRetries();
+ void disableRepeats(const char *reason);
+ bool retriable() const { return isRetriable; }
+ bool repeatable() const { return isRepeatable; }
// comm handler wrappers, treat as private
void noteCommConnected(const CommConnectCbParams &io);
void noteCommTimedout(const CommTimeoutCbParams &io);
void noteCommClosed(const CommCloseCbParams &io);
+ // TODO: create these only when actually sending/receiving
+ HttpRequest *icapRequest; ///< sent (or at least created) ICAP request
+ HttpReply *icapReply; ///< received ICAP reply, if any
+
+ /// the number of times we tried to get to the service, including this time
+ int attempts;
+
protected:
virtual void start();
virtual void noteInitiatorAborted(); // TODO: move to Adaptation::Initiate
// useful for debugging
virtual bool fillVirginHttpHeader(MemBuf&) const;
- // custom end-of-call checks
+ // custom exception handling and end-of-call checks
+ virtual void callException(const std::exception &e);
virtual void callEnd();
+ // logging
+ void setOutcome(const XactOutcome &xo);
+ virtual void finalizeLogInfo();
+
ServiceRep &service();
+private:
+ void tellQueryAborted();
+ void maybeLog();
+
protected:
int connection; // FD of the ICAP server connection
size_t commBufSize;
bool commEof;
bool reuseConnection;
- bool isRetriable;
+ bool isRetriable; ///< can retry on persistent connection failures
+ bool isRepeatable; ///< can repeat if no or unsatisfactory response
bool ignoreLastWrite;
const char *stopReason;
AsyncCall::Pointer writer;
AsyncCall::Pointer closer;
+ AccessLogEntry al;
+
+ timeval icap_tr_start; /*time when the ICAP transaction was created */
+ timeval icap_tio_start; /*time when the first ICAP request byte was scheduled for sending*/
+ timeval icap_tio_finish; /*time when the last byte of the ICAP responsewas received*/
+
private:
//CBDATA_CLASS2(Xaction);
};
--- /dev/null
+#include "squid.h"
+#include "icap_log.h"
+#include "AccessLogEntry.h"
+
+int IcapLogfileStatus = LOG_DISABLE;
+
+void
+icapLogOpen()
+{
+ customlog *log;
+
+ for (log = Config.Log.icaplogs; log; log = log->next) {
+ if (log->type == CLF_NONE)
+ continue;
+
+ if (log->type == CLF_AUTO)
+ log->type = CLF_ICAP_SQUID;
+
+ log->logfile = logfileOpen(log->filename, MAX_URL << 1, 1);
+
+ IcapLogfileStatus = LOG_ENABLE;
+ }
+}
+
+void
+icapLogClose()
+{
+ customlog *log;
+
+ for (log = Config.Log.icaplogs; log; log = log->next) {
+ if (log->logfile) {
+ logfileClose(log->logfile);
+ log->logfile = NULL;
+ }
+ }
+}
+
+void
+icapLogRotate()
+{
+ for (customlog* log = Config.Log.icaplogs; log; log = log->next) {
+ if (log->logfile) {
+ logfileRotate(log->logfile);
+ }
+ }
+}
+
+void icapLogLog(AccessLogEntry *al, ACLChecklist * checklist)
+{
+ if (IcapLogfileStatus == LOG_ENABLE)
+ accessLogLogTo(Config.Log.icaplogs, al, checklist);
+}
--- /dev/null
+#ifndef ICAP_LOG_H_
+#define ICAP_LOG_H_
+
+class AccessLogEntry;
+class ACLChecklist;
+
+void icapLogClose();
+void icapLogOpen();
+void icapLogRotate();
+void icapLogLog(AccessLogEntry *al, ACLChecklist * checklist);
+
+extern int IcapLogfileStatus;
+
+#endif /*ICAP_LOG_H_*/
cl->type = CLF_SQUID;
} else if (strcmp(logdef_name, "common") == 0) {
cl->type = CLF_COMMON;
+#if ICAP_CLIENT
+ } else if (strcmp(logdef_name, "icap_squid") == 0) {
+ cl->type = CLF_ICAP_SQUID;
+#endif
} else {
debugs(3, 0, "Log format '" << logdef_name << "' is not defined");
self_destruct();
case CLF_COMMON:
storeAppendPrintf(entry, "%s squid", log->filename);
break;
-
+#if ICAP_CLIENT
+ case CLF_ICAP_SQUID:
+ storeAppendPrintf(entry, "%s icap_squid", log->filename);
+ break;
+#endif
case CLF_AUTO:
if (log->aclList)
Format codes:
+ % a literal % character
>a Client source IP address
>A Client FQDN
>p Client source port
ts Seconds since epoch
tu subsecond time (milliseconds)
tl Local time. Optional strftime format argument
- default %d/%b/%Y:%H:%M:%S %z
+ default %d/%b/%Y:%H:%M:%S %z
tg GMT time. Optional strftime format argument
- default %d/%b/%Y:%H:%M:%S %z
+ default %d/%b/%Y:%H:%M:%S %z
tr Response time (milliseconds)
- >h Request header. Optional header name argument
- on the format header[:[separator]element]
- <h Reply header. Optional header name argument
- as for >h
- un User name
- ul User name from authentication
- ui User name from ident
- us User name from SSL
- ue User name from external acl helper
- Hs HTTP status code
- Ss Squid request status (TCP_MISS etc)
- Sh Squid hierarchy status (DEFAULT_PARENT etc)
- mt MIME content type
- rm Request method (GET/POST etc)
- ru Request URL
- rp Request URL-Path excluding hostname
- rv Request protocol version
- et Tag returned by external acl
- ea Log string returned by external acl
- <st Reply size including HTTP headers
- >st Request size including HTTP headers
- st Request+Reply size including HTTP headers
- <sH Reply high offset sent
- <sS Upstream object size
- % a literal % character
+ dt Total time spent making DNS lookups (milliseconds)
+
+ HTTP cache related format codes:
+
+ [http::]>h Request header. Optional header name argument
+ on the format header[:[separator]element]
+ [http::]<h Reply header. Optional header name argument
+ as for >h
+ [http::]un User name
+ [http::]ul User name from authentication
+ [http::]ui User name from ident
+ [http::]us User name from SSL
+ [http::]ue User name from external acl helper
+ [http::]>Hs HTTP status code sent to the client
+ [http::]<Hs HTTP status code received from the next hop
+ [http::]Ss Squid request status (TCP_MISS etc)
+ [http::]Sh Squid hierarchy status (DEFAULT_PARENT etc)
+ [http::]mt MIME content type
+ [http::]rm Request method (GET/POST etc)
+ [http::]ru Request URL
+ [http::]rp Request URL-Path excluding hostname
+ [http::]rv Request protocol version
+ [http::]et Tag returned by external acl
+ [http::]ea Log string returned by external acl
+ [http::]<st Sent reply size including HTTP headers
+ [http::]>st Received request size including HTTP headers. In the
+ case of chunked requests the chunked encoding metadata
+ are not included
+ [http::]>sh Received HTTP request headers size
+ [http::]<sh Sent HTTP reply headers size
+ [http::]st Request+Reply size including HTTP headers
+ [http::]<sH Reply high offset sent
+ [http::]<sS Upstream object size
+ [http::]<pt Peer response time in milliseconds. The timer starts
+ when the last request byte is sent to the next hop
+ and stops when the last response byte is received.
+ [http::]<tt Total server-side time in milliseconds. The timer
+ starts with the first connect request (or write I/O)
+ 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
+ well as ICAP log codes documented with the icap_log option):
+
+ icap::tt Total ICAP processing time for the HTTP
+ transaction. The timer ticks when ICAP
+ ACLs are checked and when ICAP
+ transaction is in progress.
+
+ icap::<last_h The header of the last ICAP response
+ related to the HTTP transaction. Like
+ <h, accepts an optional header name
+ argument. Will not change semantics
+ when multiple ICAP transactions per HTTP
+ transaction are supported.
+
+ If adaptation is enabled the following two codes become available:
+
+ adapt::sum_trs Summed adaptation transaction response
+ times recorded as a comma-separated list in
+ the order of transaction start time. Each time
+ value is recorded as an integer number,
+ representing response time of one or more
+ adaptation (ICAP or eCAP) transaction in
+ milliseconds. When a failed transaction is
+ being retried or repeated, its time is not
+ logged individually but added to the
+ replacement (next) transaction. See also:
+ adapt::all_trs.
+
+ adapt::all_trs All adaptation transaction response times.
+ Same as adaptation_strs but response times of
+ individual transactions are never added
+ together. Instead, all transaction response
+ times are recorded individually.
+
+ You can prefix adapt::*_trs format codes with adaptation
+ service name in curly braces to record response time(s) specific
+ to that service. For example: %{my_service}adapt::sum_trs
The default formats available (which do not need re-defining) are:
-logformat squid %ts.%03tu %6tr %>a %Ss/%03Hs %<st %rm %ru %un %Sh/%<A %mt
-logformat squidmime %ts.%03tu %6tr %>a %Ss/%03Hs %<st %rm %ru %un %Sh/%<A %mt [%>h] [%<h]
-logformat common %>a %ui %un [%tl] "%rm %ru HTTP/%rv" %Hs %<st %Ss:%Sh
-logformat combined %>a %ui %un [%tl] "%rm %ru HTTP/%rv" %Hs %<st "%{Referer}>h" "%{User-Agent}>h" %Ss:%Sh
+logformat squid %ts.%03tu %6tr %>a %Ss/%03
>Hs %<st %rm %ru %un %Sh/%<A %mt
+logformat squidmime %ts.%03tu %6tr %>a %Ss/%03
>Hs %<st %rm %ru %un %Sh/%<A %mt [%>h] [%<h]
+logformat common %>a %ui %un [%tl] "%rm %ru HTTP/%rv" %>Hs %<st %Ss:%Sh
+logformat combined %>a %ui %un [%tl] "%rm %ru HTTP/%rv" %>Hs %<st "%{Referer}>h" "%{User-Agent}>h" %Ss:%Sh
DOC_END
NAME: access_log cache_access_log
access_log @DEFAULT_ACCESS_LOG@ squid
DOC_END
+NAME: icap_log
+TYPE: access_log
+IFDEF: ICAP_CLIENT
+LOC: Config.Log.icaplogs
+DEFAULT: none
+DOC_START
+ ICAP log files record ICAP transaction summaries, one line per
+ transaction.
+
+ The icap_log option format is:
+ icap_log <filepath> [<logformat name> [acl acl ...]]
+ icap_log none [acl acl ...]]
+
+ Please see access_log option documentation for details. The two
+ kinds of logs share the overall configuration approach and many
+ features.
+
+ ICAP processing of a single HTTP message or transaction may
+ require multiple ICAP transactions. In such cases, multiple
+ ICAP transaction log lines will correspond to a single access
+ log line.
+
+ ICAP log uses logformat codes that make sense for an ICAP
+ transaction. Header-related codes are applied to the HTTP header
+ embedded in an ICAP server response, with the following caveats:
+ For REQMOD, there is no HTTP response header unless the ICAP
+ server performed request satisfaction. For RESPMOD, the HTTP
+ request header is the header sent to the ICAP server. For
+ OPTIONS, there are no HTTP headers.
+
+ The following format codes are also available for ICAP logs:
+
+ icap::<A ICAP server IP address. Similar to <A.
+
+ icap::<service_name ICAP service name from the icap_service
+ option in Squid configuration file.
+
+ icap::ru ICAP Request-URI. Similar to ru.
+
+ icap::rm ICAP request method (REQMOD, RESPMOD, or
+ OPTIONS). Similar to existing rm.
+
+ icap::>st Bytes sent to the ICAP server (TCP payload
+ only; i.e., what Squid writes to the socket).
+
+ icap::<st Bytes received from the ICAP server (TCP
+ payload only; i.e., what Squid reads from
+ the socket).
+
+ icap::tr Transaction response time (in
+ milliseconds). The timer starts when
+ the ICAP transaction is created and
+ stops when the transaction is completed.
+ Similar to tr.
+
+ icap::tio Transaction I/O time (in milliseconds). The
+ timer starts when the first ICAP request
+ byte is scheduled for sending. The timers
+ stops when the last byte of the ICAP response
+ is received.
+
+ icap::to Transaction outcome: ICAP_ERR* for all
+ transaction errors, ICAP_OPT for OPTION
+ transactions, ICAP_ECHO for 204
+ responses, ICAP_MOD for message
+ modification, and ICAP_SAT for request
+ satisfaction. Similar to Ss.
+
+ icap::Hs ICAP response status code. Similar to Hs.
+
+ icap::>h ICAP request header(s). Similar to >h.
+
+ icap::<h ICAP response header(s). Similar to <h.
+
+ The default ICAP log format, which can be used without an explicit
+ definition, is called icap_squid:
+
+logformat icap_squid %ts.%03tu %6icap::tr %>a %icap::to/%03icap::Hs %icap::<size %icap::rm %icap::ru% %un -/%icap::<A -
+
+ See also: logformat, log_icap, and %icap::<last_h
+DOC_END
+
NAME: log_access
TYPE: acl_access
LOC: Config.accessList.log
logging will also not be accounted for in performance counters.
DOC_END
+NAME: log_icap
+TYPE: acl_access
+IFDEF: ICAP_CLIENT
+LOC: Config.accessList.icap
+DEFAULT: none
+DOC_START
+ This options allows you to control which requests get logged
+ to icap.log. See the icap_log directive for ICAP log details.
+DOC_END
+
NAME: cache_store_log
TYPE: string
DEFAULT: none
be no limit imposed.
DOC_END
+NAME: chunked_request_body_max_size
+COMMENT: (bytes)
+TYPE: b_int64_t
+DEFAULT: 64 KB
+LOC: Config.maxChunkedRequestBodySize
+DOC_START
+ A broken or confused HTTP/1.1 client may send a chunked HTTP
+ request to Squid. Squid does not have full support for that
+ feature yet. To cope with such requests, Squid buffers the
+ entire request and then dechunks request body to create a
+ plain HTTP/1.0 request with a known content length. The plain
+ request is then used by the rest of Squid code as usual.
+
+ The option value specifies the maximum size of the buffer used
+ to hold the request before the conversion. If the chunked
+ request size exceeds the specified limit, the conversion
+ fails, and the client receives an "unsupported request" error,
+ as if dechunking was disabled.
+
+ Dechunking is enabled by default. To disable conversion of
+ chunked requests, set the maximum to zero.
+
+ Request dechunking feature and this option in particular are a
+ temporary hack. When chunking requests and responses are fully
+ supported, there will be no need to buffer a chunked request.
+DOC_END
+
NAME: broken_posts
IFDEF: HTTP_VIOLATIONS
TYPE: acl_access
adaptation_access service_1 allow all
DOC_END
+NAME: adaptation_masterx_shared_names
+TYPE: string
+IFDEF: USE_ADAPTATION
+LOC: Adaptation::Config::masterx_shared_name
+DEFAULT: none
+DOC_START
+ For each master transaction (i.e., the HTTP request and response
+ sequence, including all related ICAP and eCAP exchanges), Squid
+ maintains a table of metadata. The table entries are (name, value)
+ pairs shared among eCAP and ICAP exchanges. The table is destroyed
+ with the master transaction.
+
+ This option specifies the table entry names that Squid must accept
+ from and forward to the adaptation transactions.
+
+ An ICAP REQMOD or RESPMOD transaction may set an entry in the
+ shared table by returning an ICAP header field with a name
+ specified in adaptation_masterx_shared_names. Squid will store
+ and forward that ICAP header field to subsequent ICAP
+ transactions within the same master transaction scope.
+
+ Only one shared entry name is supported at this time.
+
+Example:
+# share authentication information among ICAP services
+adaptation_masterx_shared_names X-Subscriber-ID
+DOC_END
+
+NAME: icap_retry
+TYPE: acl_access
+IFDEF: ICAP_CLIENT
+LOC: Adaptation::Icap::TheConfig.repeat
+DEFAULT: none
+DEFAULT_IF_NONE: deny all
+DOC_START
+ This ACL determines which retriable ICAP transactions are
+ retried. Transactions that received a complete ICAP response
+ and did not have to consume or produce HTTP bodies to receive
+ that response are usually retriable.
+
+ icap_retry allow|deny [!]aclname ...
+
+ Squid automatically retries some ICAP I/O timeouts and errors
+ due to persistent connection race conditions.
+
+ See also: icap_retry_limit
+DOC_END
+
+NAME: icap_retry_limit
+TYPE: int
+IFDEF: ICAP_CLIENT
+LOC: Adaptation::Icap::TheConfig.repeat_limit
+DEFAULT: 0
+DOC_START
+ Limits the number of retries allowed. When set to zero (default),
+ no retries are allowed.
+
+ Communication errors due to persistent connection race
+ conditions are unavoidable, automatically retried, and do not
+ count against this limit.
+
+ See also: icap_retry
+DOC_END
+
+
COMMENT_START
DNS OPTIONS
-----------------------------------------------------------------------------
#include "ClientRequestContext.h"
#include "MemBuf.h"
#include "SquidTime.h"
+#include "ChunkedCodingParser.h"
#if LINGERING_CLOSE
#define comm_close comm_lingering_close
static void clientUpdateStatCounters(log_type logType);
static void clientUpdateHierCounters(HierarchyLogEntry *);
static bool clientPingHasFinished(ping_data const *aPing);
-static void clientPrepareLogWithRequestDetails(HttpRequest *, AccessLogEntry *);
+void prepareLogWithRequestDetails(HttpRequest *, AccessLogEntry *);
#ifndef PURIFY
static int connIsUsable(ConnStateData * conn);
#endif
}
void
-clientPrepareLogWithRequestDetails(HttpRequest * request, AccessLogEntry * aLogEntry)
+prepareLogWithRequestDetails(HttpRequest * request, AccessLogEntry * aLogEntry)
{
assert(request);
assert(aLogEntry);
+#if ICAP_CLIENT
+ Adaptation::Icap::History::Pointer ih = request->icapHistory();
+#endif
if (Config.onoff.log_mime_hdrs) {
Packer p;
MemBuf mb;
packerToMemInit(&p, &mb);
request->header.packInto(&p);
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);
+#endif
+
packerClean(&p);
mb.clean();
}
+#if ICAP_CLIENT
+ if (ih != NULL)
+ aLogEntry->icap.processingTime = ih->processingTime();
+#endif
+
aLogEntry->http.method = request->method;
aLogEntry->http.version = request->http_ver;
aLogEntry->hier = request->hier;
- aLogEntry->cache.requestSize += request->content_length;
+ if (request->content_length > 0) // negative when no body or unknown length
+ aLogEntry->cache.requestSize += request->content_length;
aLogEntry->cache.extuser = request->extacl_user.termedBuf();
if (request->auth_user_request) {
if (getConn() != NULL) al.cache.caddr = getConn()->log_addr;
al.cache.requestSize = req_sz;
+ al.cache.requestHeadersSize = req_sz;
al.cache.replySize = out.size;
+ al.cache.replyHeadersSize = out.headers_sz;
al.cache.highOffset = out.offset;
al.cache.msec = tvSubMsec(start_time, current_time);
if (request)
- clientPrepareLogWithRequestDetails(request, &al);
+ prepareLogWithRequestDetails(request, &al);
if (getConn() != NULL && getConn()->rfc931[0])
al.cache.rfc931 = getConn()->rfc931;
}
}
+// Temporary hack helper: determine whether the request is chunked, expensive
+static bool
+isChunkedRequest(const HttpParser *hp) {
+ HttpRequest request;
+ if (!request.parseHeader(HttpParserHdrBuf(hp), HttpParserHdrSz(hp)))
+ return false;
+
+ return request.header.has(HDR_TRANSFER_ENCODING) &&
+ request.header.hasListMember(HDR_TRANSFER_ENCODING, "chunked", ',');
+}
+
+
/**
* parseHttpRequest()
*
static ClientSocketContext *
parseHttpRequest(ConnStateData *conn, HttpParser *hp, HttpRequestMethod * method_p, HttpVersion *http_ver)
{
- char *url = NULL;
char *req_hdr = NULL;
char *end;
size_t req_sz;
return parseHttpRequestAbort(conn, "error:unsupported-request-method");
}
- /* set url */
- /*
- * XXX this should eventually not use a malloc'ed buffer; the transformation code
- * below needs to be modified to not expect a mutable nul-terminated string.
- */
- url = (char *)xmalloc(hp->u_end - hp->u_start + 16);
-
- memcpy(url, hp->buf + hp->u_start, hp->u_end - hp->u_start + 1);
-
- url[hp->u_end - hp->u_start + 1] = '\0';
-
/*
* Process headers after request line
* TODO: Use httpRequestParse here.
*/
if ( squid_strnstr(req_hdr, "\r\r\n", req_sz) ) {
debugs(33, 1, "WARNING: suspicious HTTP request contains double CR");
- xfree(url);
return parseHttpRequestAbort(conn, "error:double-CR");
}
(int) HttpParserRequestLen(hp) << ", req_line_sz = " <<
HttpParserReqSz(hp));
+ // Temporary hack: We might receive a chunked body from a broken HTTP/1.1
+ // client that sends chunked requests to HTTP/1.0 Squid. If the request
+ // might have a chunked body, parse the headers early to look for the
+ // "Transfer-Encoding: chunked" header. If we find it, wait until the
+ // entire body is available so that we can set the content length and
+ // forward the request without chunks. The primary reason for this is
+ // to avoid forwarding a chunked request because the server side lacks
+ // logic to determine when it is valid to do so.
+ // FUTURE_CODE_TO_SUPPORT_CHUNKED_REQUESTS below will replace this hack.
+ if (hp->v_min == 1 && hp->v_maj == 1 && // broken client, may send chunks
+ Config.maxChunkedRequestBodySize > 0 && // configured to dechunk
+ (*method_p == METHOD_PUT || *method_p == METHOD_POST)) {
+
+ // check only once per request because isChunkedRequest is expensive
+ if (conn->in.dechunkingState == ConnStateData::chunkUnknown) {
+ if (isChunkedRequest(hp))
+ conn->startDechunkingRequest(hp);
+ else
+ conn->in.dechunkingState = ConnStateData::chunkNone;
+ }
+
+ if (conn->in.dechunkingState == ConnStateData::chunkParsing) {
+ if (conn->parseRequestChunks(hp)) // parses newly read chunks
+ return NULL; // wait for more data
+ debugs(33, 5, HERE << "Got complete chunked request or err.");
+ assert(conn->in.dechunkingState != ConnStateData::chunkParsing);
+ }
+ }
+
/* Ok, all headers are received */
http = new ClientHttpRequest(conn);
debugs(33, 5, "parseHttpRequest: Request Header is\n" <<(hp->buf) + hp->hdr_start);
+ /* set url */
+ /*
+ * XXX this should eventually not use a malloc'ed buffer; the transformation code
+ * below needs to be modified to not expect a mutable nul-terminated string.
+ */
+ char *url = (char *)xmalloc(hp->u_end - hp->u_start + 16);
+
+ memcpy(url, hp->buf + hp->u_start, hp->u_end - hp->u_start + 1);
+
+ url[hp->u_end - hp->u_start + 1] = '\0';
+
#if THIS_VIOLATES_HTTP_SPECS_ON_URL_TRANSFORMATION
if ((t = strchr(url, '#'))) /* remove HTML anchors */
int
connKeepReadingIncompleteRequest(ConnStateData * conn)
{
+ // when we read chunked requests, the entire body is buffered
+ // XXX: this check ignores header size and its limits.
+ if (conn->in.dechunkingState == ConnStateData::chunkParsing)
+ return conn->in.notYetUsed < Config.maxChunkedRequestBodySize;
+
return conn->in.notYetUsed >= Config.maxRequestHeaderSize ? 0 : 1;
}
ClientSocketContext *context = parseHttpRequestAbort(conn, "error:request-too-large");
clientStreamNode *node = context->getClientReplyContext();
assert(!connKeepReadingIncompleteRequest(conn));
- debugs(33, 1, "Request header is too large (" << conn->in.notYetUsed << " bytes)");
- debugs(33, 1, "Config 'request_header_max_size'= " << Config.maxRequestHeaderSize << " bytes.");
+ if (conn->in.dechunkingState == ConnStateData::chunkParsing) {
+ debugs(33, 1, "Chunked request is too large (" << conn->in.notYetUsed << " bytes)");
+ debugs(33, 1, "Config 'chunked_request_body_max_size'= " << Config.maxChunkedRequestBodySize << " bytes.");
+ } else {
+ debugs(33, 1, "Request header is too large (" << conn->in.notYetUsed << " bytes)");
+ debugs(33, 1, "Config 'request_header_max_size'= " << Config.maxRequestHeaderSize << " bytes.");
+ }
clientReplyContext *repContext = dynamic_cast<clientReplyContext *>(node->data.getRaw());
assert (repContext);
repContext->setReplyToError(ERR_TOO_BIG,
ClientHttpRequest *http = context->http;
HttpRequest *request = NULL;
bool notedUseOfBuffer = false;
+ bool tePresent = false;
+ bool deChunked = false;
+ bool unsupportedTe = false;
/* We have an initial client stream in place should it be needed */
/* setup our private context */
request->my_addr = conn->me;
request->http_ver = http_ver;
- if (!urlCheckRequest(request) ||
- request->header.has(HDR_TRANSFER_ENCODING)) {
+ tePresent = request->header.has(HDR_TRANSFER_ENCODING);
+ deChunked = conn->in.dechunkingState == ConnStateData::chunkReady;
+ if (deChunked) {
+ assert(tePresent);
+ request->setContentLength(conn->in.dechunked.contentSize());
+ request->header.delById(HDR_TRANSFER_ENCODING);
+ conn->finishDechunkingRequest(hp);
+ }
+
+ unsupportedTe = tePresent && !deChunked;
+ if (!urlCheckRequest(request) || unsupportedTe) {
clientStreamNode *node = context->getClientReplyContext();
clientReplyContext *repContext = dynamic_cast<clientReplyContext *>(node->data.getRaw());
assert (repContext);
{
assert(bodyPipe != NULL);
- if (const size_t putSize = bodyPipe->putMoreData(in.buf, in.notYetUsed))
- connNoteUseOfBuffer(this, putSize);
+ size_t putSize = 0;
+
+#if FUTURE_CODE_TO_SUPPORT_CHUNKED_REQUESTS
+ // The code below works, in principle, but we cannot do dechunking
+ // on-the-fly because that would mean sending chunked requests to
+ // the next hop. Squid lacks logic to determine which servers can
+ // receive chunk requests. Squid v3.0 code cannot even handle chunked
+ // responses which we may encourage by sending chunked requests.
+ // The error generation code probably needs more work.
+ if (in.bodyParser) { // chunked body
+ debugs(33,5, HERE << "handling chunked request body for FD " << fd);
+ bool malformedChunks = false;
+
+ MemBuf raw; // ChunkedCodingParser only works with MemBufs
+ raw.init(in.notYetUsed, in.notYetUsed);
+ raw.append(in.buf, in.notYetUsed);
+ try { // the parser will throw on errors
+ const mb_size_t wasContentSize = raw.contentSize();
+ BodyPipeCheckout bpc(*bodyPipe);
+ const bool parsed = in.bodyParser->parse(&raw, &bpc.buf);
+ bpc.checkIn();
+ putSize = wasContentSize - raw.contentSize();
+
+ if (parsed) {
+ stopProducingFor(bodyPipe, true); // this makes bodySize known
+ } else {
+ // parser needy state must imply body pipe needy state
+ if (in.bodyParser->needsMoreData() &&
+ !bodyPipe->mayNeedMoreData())
+ malformedChunks = true;
+ // XXX: if bodyParser->needsMoreSpace, how can we guarantee it?
+ }
+ } catch (...) { // XXX: be more specific
+ malformedChunks = true;
+ }
- if (!bodyPipe->mayNeedMoreData()) {
- // BodyPipe will clear us automagically when we produced everything
- bodyPipe = NULL;
+ if (malformedChunks) {
+ if (bodyPipe != NULL)
+ stopProducingFor(bodyPipe, false);
+
+ ClientSocketContext::Pointer context = getCurrentContext();
+ if (!context->http->out.offset) {
+ clientStreamNode *node = context->getClientReplyContext();
+ clientReplyContext *repContext = dynamic_cast<clientReplyContext *>(node->data.getRaw());
+ assert (repContext);
+ repContext->setReplyToError(ERR_INVALID_REQ, HTTP_BAD_REQUEST,
+ METHOD_NONE, NULL, &peer.sin_addr,
+ NULL, NULL, NULL);
+ context->pullData();
+ }
+ flags.readMoreRequests = false;
+ return; // XXX: is that sufficient to generate an error?
+ }
+ } else // identity encoding
+#endif
+ {
+ debugs(33,5, HERE << "handling plain request body for FD " << fd);
+ putSize = bodyPipe->putMoreData(in.buf, in.notYetUsed);
+ if (!bodyPipe->mayNeedMoreData()) {
+ // BodyPipe will clear us automagically when we produced everything
+ bodyPipe = NULL;
+ }
+ }
+
+ if (putSize > 0)
+ connNoteUseOfBuffer(this, putSize);
+ if (!bodyPipe) {
debugs(33,5, HERE << "produced entire request body for FD " << fd);
if (closing()) {
bodyPipe->enableAutoConsumption();
}
+// initialize dechunking state
+void
+ConnStateData::startDechunkingRequest(HttpParser *hp)
+{
+ debugs(33, 5, HERE << "start dechunking at " << HttpParserRequestLen(hp));
+ assert(in.dechunkingState == chunkUnknown);
+ assert(!in.bodyParser);
+ in.bodyParser = new ChunkedCodingParser;
+ in.chunkedSeen = HttpParserRequestLen(hp); // skip headers when dechunking
+ in.chunked.init(); // TODO: should we have a smaller-than-default limit?
+ in.dechunked.init();
+ in.dechunkingState = chunkParsing;
+}
+
+// put parsed content into input buffer and clean up
+void
+ConnStateData::finishDechunkingRequest(HttpParser *hp)
+{
+ debugs(33, 5, HERE << "finish dechunking; content: " << in.dechunked.contentSize());
+
+ assert(in.dechunkingState == chunkReady);
+ assert(in.bodyParser);
+ delete in.bodyParser;
+ in.bodyParser = NULL;
+
+ const mb_size_t headerSize = HttpParserRequestLen(hp);
+
+ // dechunking cannot make data bigger
+ assert(headerSize + in.dechunked.contentSize() + in.chunked.contentSize()
+ <= static_cast<mb_size_t>(in.notYetUsed));
+ assert(in.notYetUsed <= in.allocatedSize);
+
+ // copy dechunked content
+ char *end = in.buf + headerSize;
+ xmemmove(end, in.dechunked.content(), in.dechunked.contentSize());
+ end += in.dechunked.contentSize();
+
+ // copy post-chunks leftovers, if any, caused by request pipelining?
+ if (in.chunked.contentSize()) {
+ xmemmove(end, in.chunked.content(), in.chunked.contentSize());
+ end += in.chunked.contentSize();
+ }
+
+ in.notYetUsed = end - in.buf;
+
+ in.chunked.clean();
+ in.dechunked.clean();
+ in.dechunkingState = chunkUnknown;
+}
+
+// parse newly read request chunks and buffer them for finishDechunkingRequest
+// returns true iff needs more data
+bool
+ConnStateData::parseRequestChunks(HttpParser *)
+{
+ debugs(33,5, HERE << "parsing chunked request body at " <<
+ in.chunkedSeen << " < " << in.notYetUsed);
+ assert(in.bodyParser);
+ assert(in.dechunkingState == chunkParsing);
+
+ assert(in.chunkedSeen <= in.notYetUsed);
+ const mb_size_t fresh = in.notYetUsed - in.chunkedSeen;
+
+ // be safe: count some chunked coding metadata towards the total body size
+ if (fresh + in.dechunked.contentSize() > Config.maxChunkedRequestBodySize) {
+ debugs(33,3, HERE << "chunked body (" << fresh << " + " <<
+ in.dechunked.contentSize() << " may exceed " <<
+ "chunked_request_body_max_size=" <<
+ Config.maxChunkedRequestBodySize);
+ in.dechunkingState = chunkError;
+ return false;
+ }
+
+ if (fresh > in.chunked.potentialSpaceSize()) {
+ // should not happen if Config.maxChunkedRequestBodySize is reasonable
+ debugs(33,1, HERE << "request_body_max_size exceeds chunked buffer " <<
+ "size: " << fresh << " + " << in.chunked.contentSize() << " > " <<
+ in.chunked.potentialSpaceSize() << " with " <<
+ "chunked_request_body_max_size=" <<
+ Config.maxChunkedRequestBodySize);
+ in.dechunkingState = chunkError;
+ return false;
+ }
+ in.chunked.append(in.buf + in.chunkedSeen, fresh);
+ in.chunkedSeen += fresh;
+
+ try { // the parser will throw on errors
+ if (in.bodyParser->parse(&in.chunked, &in.dechunked))
+ in.dechunkingState = chunkReady; // successfully parsed all chunks
+ else
+ return true; // need more, keep the same state
+ } catch (...) {
+ debugs(33,3, HERE << "chunk parsing error");
+ in.dechunkingState = chunkError;
+ }
+ return false; // error, unsupported, or done
+}
+
char *
ConnStateData::In::addressToReadInto() const
{
return buf + notYetUsed;
}
-ConnStateData::In::In() : buf (NULL), notYetUsed (0), allocatedSize (0)
+ConnStateData::In::In() : bodyParser(NULL),
+ buf (NULL), notYetUsed (0), allocatedSize (0),
+ dechunkingState(ConnStateData::chunkUnknown)
{}
ConnStateData::In::~In()
{
if (allocatedSize)
memFreeBuf(allocatedSize, buf);
+ if (bodyParser)
+ delete bodyParser; // TODO: pool
}
/* This is a comm call normally scheduled by comm_close() */
class AuthUserRequest;
+class ChunkedCodingParser;
+class HttpParser;
+
template <class T>
class Range;
int fd;
+ /// chunk buffering and parsing algorithm state
+ typedef enum { chunkUnknown, chunkNone, chunkParsing, chunkReady, chunkError } DechunkingState;
+
struct In {
In();
~In();
char *addressToReadInto() const;
+
+ ChunkedCodingParser *bodyParser; ///< parses chunked request body
+ MemBuf chunked; ///< contains unparsed raw (chunked) body data
+ MemBuf dechunked; ///< accumulates parsed (dechunked) content
char *buf;
size_t notYetUsed;
size_t allocatedSize;
+ size_t chunkedSeen; ///< size of processed or ignored raw read data
+ DechunkingState dechunkingState; ///< request dechunking state
} in;
int64_t bodySizeLeft();
bool switchedToHttps() const { return false; }
#endif
+ void startDechunkingRequest(HttpParser *hp);
+ bool parseRequestChunks(HttpParser *hp);
+ void finishDechunkingRequest(HttpParser *hp);
+
private:
int connReadWasError(comm_err_t flag, int size, int xerrno);
int connFinishedWithConn(int size);
#include "SquidTime.h"
#include "wordlist.h"
#include "inet_pton.h"
+#include "fde.h"
#if USE_ADAPTATION
#include "adaptation/AccessCheck.h"
#include "adaptation/Service.h"
+#if ICAP_CLIENT
+#include "adaptation/icap/History.h"
+#endif
static void adaptationAclCheckDoneWrapper(Adaptation::ServicePointer service, void *data);
#endif
+
+
#if LINGERING_CLOSE
#define comm_close comm_lingering_close
#endif
debugs(93,3,HERE << this << " adaptationAclCheckDone called");
assert(http);
+#if ICAP_CLIENT
+ Adaptation::Icap::History::Pointer ih = http->request->icapHistory();
+ if(ih != NULL)
+ {
+ if (http->getConn() != NULL)
+ {
+ ih->rfc931 = http->getConn()->rfc931;
+#if USE_SSL
+ ih->ssluser = sslGetUserEmail(fd_table[http->getConn()->fd].ssl);
+#endif
+ }
+ ih->log_uri = http->log_uri;
+ ih->req_sz = http->req_sz;
+ }
+#endif
+
if (http->startAdaptation(service))
return;
debugs(83, 3, HERE << "calling processRequest()");
processRequest();
+
+#if ICAP_CLIENT
+ Adaptation::Icap::History::Pointer ih = request->icapHistory();
+ if (ih != NULL)
+ ih->logType = logType;
+#endif
}
#ifndef _USE_INLINE_
IpAddress default_addr;
// NP: CANNOT store the default addr:port together as it gets set/reset differently.
+ DnsLookupDetails dns; ///< host lookup details
IpAddress S;
AsyncCall::Pointer callback;
}
static void
-commConnectDnsHandle(const ipcache_addrs * ia, void *data)
+commConnectDnsHandle(const ipcache_addrs *ia, const DnsLookupDetails &details, void *data)
{
ConnectStateData *cs = (ConnectStateData *)data;
+ cs->dns = details;
if (ia == NULL) {
debugs(5, 3, "commConnectDnsHandle: Unknown host: " << cs->host);
-
- if (!dns_error_message) {
- dns_error_message = "Unknown DNS error";
- debugs(5, 1, "commConnectDnsHandle: Bad dns_error_message");
- }
-
- assert(dns_error_message != NULL);
cs->callCallback(COMM_ERR_DNS, 0);
return;
}
typedef CommConnectCbParams Params;
Params ¶ms = GetCommParams<Params>(callback);
params.fd = fd;
+ params.dns = dns;
params.flag = status;
params.xerrno = xerrno;
ScheduleCallHere(callback);
#endif
} comm_err_t;
-typedef void CNCB(int fd, comm_err_t status, int xerrno, void *data);
+class DnsLookupDetails;
+typedef void CNCB(int fd, const DnsLookupDetails &dns, comm_err_t status, int xerrno, void *data);
typedef void IOCB(int fd, char *, size_t size, comm_err_t flag, int xerrno, void *data);
}
static void
-idnsInitVCConnected(int fd, comm_err_t status, int xerrno, void *data)
+idnsInitVCConnected(int fd, const DnsLookupDetails &, comm_err_t status, int xerrno, void *data)
{
nsvc * vc = (nsvc *)data;
CLF_CUSTOM,
CLF_SQUID,
CLF_COMMON,
+#if ICAP_CLIENT
+ CLF_ICAP_SQUID,
+#endif
CLF_NONE
} customlog_type;
HTTPMSGUNLOCK(err->request);
safe_free(err->redirect_url);
safe_free(err->url);
- safe_free(err->dnsserver_msg);
safe_free(err->request_hdrs);
wordlistDestroy(&err->ftp.server_msg);
safe_free(err->ftp.request);
if (auth_user_request->denyMessage())
str.Printf("Auth ErrMsg: %s\r\n", auth_user_request->denyMessage());
- if (dnsserver_msg) {
- str.Printf("DNS Server ErrMsg: %s\r\n", dnsserver_msg);
- }
+ if (dnsError.size() > 0)
+ str.Printf("DNS ErrMsg: %s\r\n", dnsError.termedBuf());
/* - TimeStamp */
str.Printf("TimeStamp: %s\r\n\r\n", mkrfc1123(squid_curtime));
break;
case 'z':
- if (dnsserver_msg)
- p = dnsserver_msg;
+ if (dnsError.size() > 0)
+ p = dnsError.termedBuf();
else
p = "[unknown]";
char *url;
int xerrno;
u_short port;
- char *dnsserver_msg;
+ String dnsError; ///< DNS lookup error message
time_t ttl;
IpAddress src_addr;
#endif
static void
-fwdConnectDoneWrapper(int server_fd, comm_err_t status, int xerrno, void *data)
+fwdConnectDoneWrapper(int server_fd, const DnsLookupDetails &dns, comm_err_t status, int xerrno, void *data)
{
FwdState *fwd = (FwdState *) data;
- fwd->connectDone(server_fd, status, xerrno);
+ fwd->connectDone(server_fd, dns, status, xerrno);
}
static void
#endif
void
-FwdState::connectDone(int aServerFD, comm_err_t status, int xerrno)
+FwdState::connectDone(int aServerFD, const DnsLookupDetails &dns, comm_err_t status, int xerrno)
{
FwdServer *fs = servers;
assert(server_fd == aServerFD);
+ request->recordLookup(dns);
+
if (Config.onoff.log_ip_on_direct && status != COMM_ERR_DNS && fs->code == HIER_DIRECT)
updateHierarchyInfo();
ErrorState *anErr = errorCon(ERR_DNS_FAIL, HTTP_SERVICE_UNAVAILABLE, request);
- anErr->dnsserver_msg = xstrdup(dns_error_message_safe());
+ anErr->dnsError = dns.error;
fail(anErr);
assert(server_fd == -1);
debugs(17, 3, "fwdConnectStart: " << url);
+ if (n_tries == 0) // first attempt
+ request->hier.first_conn_start = current_time;
+
if (fs->_peer) {
ctimeout = fs->_peer->connect_timeout > 0 ? fs->_peer->connect_timeout
: Config.Timeout.peer_connect;
request->flags.auth = 1;
comm_add_close_handler(fd, fwdServerClosedWrapper, this);
updateHierarchyInfo();
- connectDone(fd, COMM_OK, 0);
+ connectDone(fd, DnsLookupDetails(), COMM_OK, 0);
return;
}
/* Failure. Fall back on next path */
bool reforwardableStatus(http_status s);
void serverClosed(int fd);
void connectStart();
- void connectDone(int server_fd, comm_err_t status, int xerrno);
+ void connectDone(int server_fd, const DnsLookupDetails &dns, comm_err_t status, int xerrno);
void connectTimeout(int fd);
void initiateSSL();
void negotiateSSL(int fd);
/// \ingroup FQDNCacheInternal
#define FQDN_HIGH_WATER 95
-/// \ingroup FQDNCacheAPI
-typedef struct _fqdncache_entry fqdncache_entry;
-
/**
\ingroup FQDNCacheAPI
* The data structure used for storing name-address mappings
* where structures of type fqdncache_entry whose most
* interesting members are:
*/
-struct _fqdncache_entry {
+class fqdncache_entry {
+public:
hash_link hash; /* must be first */
time_t lastref;
time_t expires;
unsigned int negcached:1;
unsigned int fromhosts:1;
} flags;
+
+ int age() const; ///< time passed since request_time or -1 if unknown
};
/// \ingroup FQDNCacheInternal
#endif
static void fqdncacheRelease(fqdncache_entry *);
static fqdncache_entry *fqdncacheCreateEntry(const char *name);
-static void fqdncacheCallback(fqdncache_entry *);
+static void fqdncacheCallback(fqdncache_entry *, int wait);
static fqdncache_entry *fqdncache_get(const char *);
static FQDNH dummy_handler;
static int fqdncacheExpiredEntry(const fqdncache_entry *);
/// \ingroup FQDNCacheInternal
static long fqdncache_high = 200;
+int
+fqdncache_entry::age() const
+{
+ return request_time.tv_sec ? tvSubMsec(request_time, current_time) : -1;
+}
+
+
/**
\ingroup FQDNCacheInternal
* Removes the given fqdncache entry
* Walks down the pending list, calling handlers
*/
static void
-fqdncacheCallback(fqdncache_entry * f)
+fqdncacheCallback(fqdncache_entry * f, int wait)
{
FQDNH *callback;
void *cbdata;
f->handler = NULL;
if (cbdataReferenceValidDone(f->handlerData, &cbdata)) {
- dns_error_message = f->error_message;
- callback(f->name_count ? f->names[0] : NULL, cbdata);
+ const DnsLookupDetails details(f->error_message, wait);
+ callback(f->name_count ? f->names[0] : NULL, details, cbdata);
}
fqdncacheUnlockEntry(f);
fqdncache_entry *f;
static_cast<generic_cbdata *>(data)->unwrap(&f);
n = ++FqdncacheStats.replies;
- statHistCount(&statCounter.dns.svc_time,
- tvSubMsec(f->request_time, current_time));
+ const int age = f->age();
+ statHistCount(&statCounter.dns.svc_time, age);
#if USE_DNSSERVERS
fqdncacheParse(f, reply);
fqdncacheAddEntry(f);
- fqdncacheCallback(f);
+ fqdncacheCallback(f, age);
}
/**
if (name[0] == '\0') {
debugs(35, 4, "fqdncache_nbgethostbyaddr: Invalid name!");
- dns_error_message = "Invalid hostname";
- handler(NULL, handlerData);
+ const DnsLookupDetails details("Invalid hostname", -1); // error, no lookup
+ handler(NULL, details, handlerData);
return;
}
f->handlerData = cbdataReference(handlerData);
- fqdncacheCallback(f);
+ fqdncacheCallback(f, -1); // no lookup
return;
}
f = NULL;
} else if (f->flags.negcached) {
FqdncacheStats.negative_hits++;
- dns_error_message = f->error_message;
+ // ignore f->error_message: the caller just checks FQDN cache presence
return NULL;
} else {
FqdncacheStats.hits++;
f->lastref = squid_curtime;
- dns_error_message = f->error_message;
+ // ignore f->error_message: the caller just checks FQDN cache presence
return f->names[0];
}
- dns_error_message = NULL;
+ /* no entry [any more] */
FqdncacheStats.misses++;
/// \ingroup FQDNCacheInternal
static void
-dummy_handler(const char *bufnotused, void *datanotused)
+dummy_handler(const char *, const DnsLookupDetails &, void *)
{
return;
}
}
#endif /*SQUID_SNMP */
-
-/// XXX: a hack to work around the missing DNS error info
-// see http://www.squid-cache.org/bugs/show_bug.cgi?id=2459
-const char *
-dns_error_message_safe()
-{
- if (dns_error_message)
- return dns_error_message;
- debugs(35,DBG_IMPORTANT, "Internal error: lost DNS error info");
- return "lost DNS error";
-}
}
void
-FtpStateData::ftpPasvCallback(int fd, comm_err_t status, int xerrno, void *data)
+FtpStateData::ftpPasvCallback(int fd, const DnsLookupDetails &dns, comm_err_t status, int xerrno, void *data)
{
FtpStateData *ftpState = (FtpStateData *)data;
debugs(9, 3, HERE);
+ ftpState->request->recordLookup(dns);
if (status != COMM_OK) {
debugs(9, 2, HERE << "Failed to connect. Retrying without PASV.");
//MOVED:structs.h extern SquidConfig2 Config2;
extern char *ConfigFile; /* NULL */
extern char *IcpOpcodeStr[];
- extern const char *dns_error_message; /* NULL */
extern const char *log_tags[];
extern char tmp_error_buf[ERROR_BUF_SZ];
extern char ThisCache[RFC2181_MAXHOSTNAMELEN << 1];
readBuf->init();
orig_request = HTTPMSGLOCK(fwd->request);
+ // reset peer response time stats for %<pt
+ orig_request->hier.peer_http_request_sent.tv_sec = 0;
+ orig_request->hier.peer_http_request_sent.tv_usec = 0;
+
if (fwd->servers)
_peer = fwd->servers->_peer; /* might be NULL */
* Parse the header and remove all referenced headers
*/
+ orig_request->hier.peer_reply_status = newrep->sline.status;
+
ctx_exit(ctx);
}
clen >>= 1;
IOStats.Http.read_hist[bin]++;
+
+ // update peer response time stats (%<pt)
+ const timeval &sent = orig_request->hier.peer_http_request_sent;
+ orig_request->hier.peer_response_time =
+ sent.tv_sec ? tvSubMsec(sent, current_time) : -1;
}
/** \par
commSetTimeout(fd, Config.Timeout.read, timeoutCall);
flags.request_sent = 1;
+
+ orig_request->hier.peer_http_request_sent = current_time;
}
// Close the HTTP server connection. Used by serverComplete().
}
static void
-netdbSendPing(const ipcache_addrs * ia, void *data)
+netdbSendPing(const ipcache_addrs *ia, const DnsLookupDetails &, void *data)
{
IpAddress addr;
char *hostname = NULL;
}
static void
-Ident::ConnectDone(int fd, comm_err_t status, int xerrno, void *data)
+Ident::ConnectDone(int fd, const DnsLookupDetails &, comm_err_t status, int xerrno, void *data)
{
IdentStateData *state = (IdentStateData *)data;
IdentClient *c;
* the ipcache_high threshold.
*/
-/// \ingroup IPCacheAPI
-typedef struct _ipcache_entry ipcache_entry;
-
/**
\ingroup IPCacheAPI
*
* where structures of type ipcache_entry whose most
* interesting members are:
*/
-struct _ipcache_entry {
+class ipcache_entry {
+public:
hash_link hash; /* must be first */
time_t lastref;
time_t expires;
unsigned int negcached:1;
unsigned int fromhosts:1;
} flags;
+
+ int age() const; ///< time passed since request_time or -1 if unknown
};
/// \ingroup IPCacheInternal
extern int _dns_ttl_;
#endif
+int
+ipcache_entry::age() const
+{
+ return request_time.tv_sec ? tvSubMsec(request_time, current_time) : -1;
+}
+
+
+
/**
\ingroup IPCacheInternal
*
* walks down the pending list, calling handlers
*/
static void
-ipcacheCallback(ipcache_entry * i)
+ipcacheCallback(ipcache_entry *i, int wait)
{
IPH *callback = i->handler;
void *cbdata = NULL;
i->handler = NULL;
if (cbdataReferenceValidDone(i->handlerData, &cbdata)) {
- dns_error_message = i->error_message;
- callback(i->addrs.count ? &i->addrs : NULL, cbdata);
+ const DnsLookupDetails details(i->error_message, wait);
+ callback((i->addrs.count ? &i->addrs : NULL), details, cbdata);
}
ipcacheUnlockEntry(i);
ipcache_entry *i;
static_cast<generic_cbdata *>(data)->unwrap(&i);
IpcacheStats.replies++;
- statHistCount(&statCounter.dns.svc_time,
- tvSubMsec(i->request_time, current_time));
+ const int age = i->age();
+ statHistCount(&statCounter.dns.svc_time, age);
+
#if USE_DNSSERVERS
done = ipcacheParse(i, reply);
{
ipcacheAddEntry(i);
- ipcacheCallback(i);
+ ipcacheCallback(i, age);
}
}
if (name == NULL || name[0] == '\0') {
debugs(14, 4, "ipcache_nbgethostbyname: Invalid name!");
IpcacheStats.invalid++;
- dns_error_message = "Invalid hostname";
- handler(NULL, handlerData);
+ const DnsLookupDetails details("Invalid hostname", -1); // error, no lookup
+ handler(NULL, details, handlerData);
return;
}
if ((addrs = ipcacheCheckNumeric(name))) {
debugs(14, 4, "ipcache_nbgethostbyname: BYPASS for '" << name << "' (already numeric)");
- dns_error_message = NULL;
IpcacheStats.numeric_hits++;
- handler(addrs, handlerData);
+ const DnsLookupDetails details(NULL, -1); // no error, no lookup
+ handler(addrs, details, handlerData);
return;
}
i->handlerData = cbdataReference(handlerData);
- ipcacheCallback(i);
+ ipcacheCallback(i, -1); // no lookup
return;
}
i = NULL;
} else if (i->flags.negcached) {
IpcacheStats.negative_hits++;
- dns_error_message = i->error_message;
+ // ignore i->error_message: the caller just checks IP cache presence
return NULL;
} else {
IpcacheStats.hits++;
i->lastref = squid_curtime;
- dns_error_message = i->error_message;
+ // ignore i->error_message: the caller just checks IP cache presence
return &i->addrs;
}
- dns_error_message = NULL;
+ /* no entry [any more] */
if ((addrs = ipcacheCheckNumeric(name))) {
IpcacheStats.numeric_hits++;
/// \ingroup IPCacheInternal
/// Callback.
static void
-ipcacheHandleCnameRecurse(const ipcache_addrs *addrs, void *cbdata)
+ipcacheHandleCnameRecurse(const ipcache_addrs *addrs, const DnsLookupDetails &, void *cbdata)
{
#if DNS_CNAME
ipcache_entry *i = NULL;
/* finish the lookup we were doing on parent when we got side-tracked for CNAME loop */
if (i->cname_wait == 0) {
ipcacheAddEntry(i);
- ipcacheCallback(i);
+ ipcacheCallback(i, i->age()); // age since i creation, includes CNAMEs
}
// else still more CNAME to be found.
#endif /* DNS_CNAME */
#include "squid.h"
#include "AccessLogEntry.h"
+#if ICAP_CLIENT
+#include "adaptation/icap/icap_log.h"
+#endif
#include "auth/Gadgets.h"
#include "ConfigParser.h"
#include "errorpage.h"
storeDirCloseSwapLogs();
storeLogClose();
accessLogClose();
+#if ICAP_CLIENT
+ icapLogClose();
+#endif
useragentLogClose();
refererCloseLog();
parseEtcHosts();
errorInitialize(); /* reload error pages */
accessLogInit();
+#if ICAP_CLIENT
+ icapLogOpen();
+#endif
storeLogOpen();
useragentOpenLog();
refererOpenLog();
accessLogRotate(); /* access.log */
useragentRotateLog(); /* useragent.log */
refererRotateLog(); /* referer.log */
+#if ICAP_CLIENT
+ icapLogRotate(); /*icap.log*/
+#endif
#if WIP_FWD_LOG
fwdLogRotate();
accessLogInit();
+#if ICAP_CLIENT
+ icapLogOpen();
+#endif
+
#if USE_IDENT
Ident::Init();
#endif
}
void
-mcastJoinGroups(const ipcache_addrs * ia, void *datanotused)
+mcastJoinGroups(const ipcache_addrs *ia, const DnsLookupDetails &, void *datanotused)
{
#ifdef IP_MULTICAST_TTL
int fd = theInIcpConnection;
}
static void
-peerDNSConfigure(const ipcache_addrs * ia, void *data)
+peerDNSConfigure(const ipcache_addrs *ia, const DnsLookupDetails &, void *data)
{
peer *p = (peer *)data;
}
static void
-peerProbeConnectDone(int fd, comm_err_t status, int xerrno, void *data)
+peerProbeConnectDone(int fd, const DnsLookupDetails &, comm_err_t status, int xerrno, void *data)
{
peer *p = (peer*)data;
SQUIDCEXTERN void dnsShutdown(void);
SQUIDCEXTERN void dnsInit(void);
SQUIDCEXTERN void dnsSubmit(const char *lookup, HLPCB * callback, void *data);
-/// XXX: a temporary hack to work around the missing DNS error info
-const char *dns_error_message_safe();
/* dns_internal.c */
SQUIDCEXTERN void idnsInit(void);
}
static void
-send_announce(const ipcache_addrs * ia, void *junk)
+send_announce(const ipcache_addrs *ia, const DnsLookupDetails &, void *junk)
{
LOCAL_ARRAY(char, tbuf, 256);
LOCAL_ARRAY(char, sndbuf, BUFSIZ);
} Timeout;
size_t maxRequestHeaderSize;
int64_t maxRequestBodySize;
+ int64_t maxChunkedRequestBodySize;
size_t maxReplyHeaderSize;
acl_size_t *ReplyBodySize;
customlog *accesslogs;
+#if ICAP_CLIENT
+ customlog *icaplogs;
+#endif
+
int rotateNumber;
} Log;
char *adminEmail;
acl_access *followXFF;
#endif /* FOLLOW_X_FORWARDED_FOR */
+#if ICAP_CLIENT
+ acl_access* icap;
+#endif
} accessList;
acl_deny_info_list *denyInfoList;
authConfig authConfiguration;
static void
-tunnelConnectDone(int fdnotused, comm_err_t status, int xerrno, void *data)
+tunnelConnectDone(int fdnotused, const DnsLookupDetails &dns, comm_err_t status, int xerrno, void *data)
{
TunnelStateData *tunnelState = (TunnelStateData *)data;
HttpRequest *request = tunnelState->request;
ErrorState *err = NULL;
+ request->recordLookup(dns);
+
if (tunnelState->servers->_peer)
hierarchyNote(&tunnelState->request->hier, tunnelState->servers->code,
tunnelState->servers->_peer->host);
debugs(26, 4, "tunnelConnect: Unknown host: " << tunnelState->host);
err = errorCon(ERR_DNS_FAIL, HTTP_NOT_FOUND, request);
*tunnelState->status_ptr = HTTP_NOT_FOUND;
- err->dnsserver_msg = xstrdup(dns_error_message_safe());
+ err->dnsError = dns.error;
err->callback = tunnelErrorComplete;
err->callback_data = tunnelState;
errorSend(tunnelState->client.fd(), err);
typedef void DUCB(int errflag, void *data); /* disk unlink CB */
typedef void DTCB(int errflag, void *data); /* disk trunc CB */
-typedef void FQDNH(const char *, void *);
+class DnsLookupDetails;
+typedef void FQDNH(const char *, const DnsLookupDetails &details, void *);
typedef void IDCB(const char *ident, void *data);
-typedef void IPH(const ipcache_addrs *, void *);
+typedef void IPH(const ipcache_addrs *, const DnsLookupDetails &details, void *);
typedef void IRCB(struct peer *, peer_t, protocol_t, void *, void *data);
class FwdServer;
projects / thirdparty / squid.git / commitdiff
