diff -u -r -N squid-3.1.0.10/ChangeLog squid-3.1.0.11/ChangeLog --- squid-3.1.0.10/ChangeLog 2009-07-18 16:16:09.000000000 +1200 +++ squid-3.1.0.11/ChangeLog 2009-07-19 17:11:05.000000000 +1200 @@ -1,3 +1,17 @@ +Changes to squid-3.1.0.11 (19 Jul 2009): + + - Bug 2087: Support adaptation sets and chains + - Bug 2459: dns error message broken when error handling delayed + - Support ICAP Retry + - Support ICAP retries based on the ICAP responses status code + - Support logging ICAP + - Support logging total DNS wait time + - Support logging response times of adaptation transactions + - General logging enhancements + - Dynamically form chains based on ICAP X-Next-Services header + - Support cross-transactional ICAP header exchange + - ... and much adaptation polish and improvements + Changes to squid-3.1.0.10 (18 Jul 2009): - Bug 2680: Regression Crash after rotate with no helpers running diff -u -r -N squid-3.1.0.10/configure squid-3.1.0.11/configure --- squid-3.1.0.10/configure 2009-07-18 16:17:06.000000000 +1200 +++ squid-3.1.0.11/configure 2009-07-19 17:11:50.000000000 +1200 @@ -1,7 +1,7 @@ #! /bin/sh # From configure.in Revision: 1.497 . # Guess values for system-dependent variables and create Makefiles. -# Generated by GNU Autoconf 2.62 for Squid Web Proxy 3.1.0.10. +# Generated by GNU Autoconf 2.62 for Squid Web Proxy 3.1.0.11. # # Report bugs to . # @@ -751,8 +751,8 @@ # Identity of this package. PACKAGE_NAME='Squid Web Proxy' PACKAGE_TARNAME='squid' -PACKAGE_VERSION='3.1.0.10' -PACKAGE_STRING='Squid Web Proxy 3.1.0.10' +PACKAGE_VERSION='3.1.0.11' +PACKAGE_STRING='Squid Web Proxy 3.1.0.11' PACKAGE_BUGREPORT='http://www.squid-cache.org/bugs/' ac_unique_file="src/main.cc" @@ -1678,7 +1678,7 @@ # Omit some internal or obsolete options to make the list less imposing. # This message is too long to be a string in the A/UX 3.1 sh. cat <<_ACEOF -\`configure' configures Squid Web Proxy 3.1.0.10 to adapt to many kinds of systems. +\`configure' configures Squid Web Proxy 3.1.0.11 to adapt to many kinds of systems. Usage: $0 [OPTION]... [VAR=VALUE]... @@ -1748,7 +1748,7 @@ if test -n "$ac_init_help"; then case $ac_init_help in - short | recursive ) echo "Configuration of Squid Web Proxy 3.1.0.10:";; + short | recursive ) echo "Configuration of Squid Web Proxy 3.1.0.11:";; esac cat <<\_ACEOF @@ -2079,7 +2079,7 @@ test -n "$ac_init_help" && exit $ac_status if $ac_init_version; then cat <<\_ACEOF -Squid Web Proxy configure 3.1.0.10 +Squid Web Proxy configure 3.1.0.11 generated by GNU Autoconf 2.62 Copyright (C) 1992, 1993, 1994, 1995, 1996, 1998, 1999, 2000, 2001, @@ -2093,7 +2093,7 @@ This file contains any messages produced by compilers while running configure, to aid debugging if configure makes a mistake. -It was created by Squid Web Proxy $as_me 3.1.0.10, which was +It was created by Squid Web Proxy $as_me 3.1.0.11, which was generated by GNU Autoconf 2.62. Invocation command line was $ $0 $@ @@ -2811,7 +2811,7 @@ # Define the identity of the package. PACKAGE='squid' - VERSION='3.1.0.10' + VERSION='3.1.0.11' cat >>confdefs.h <<_ACEOF @@ -49693,7 +49693,7 @@ # report actual input values of CONFIG_FILES etc. instead of their # values after options handling. ac_log=" -This file was extended by Squid Web Proxy $as_me 3.1.0.10, which was +This file was extended by Squid Web Proxy $as_me 3.1.0.11, which was generated by GNU Autoconf 2.62. Invocation command line was CONFIG_FILES = $CONFIG_FILES @@ -49746,7 +49746,7 @@ _ACEOF cat >>$CONFIG_STATUS <<_ACEOF || ac_write_fail=1 ac_cs_version="\\ -Squid Web Proxy config.status 3.1.0.10 +Squid Web Proxy config.status 3.1.0.11 configured by $0, generated by GNU Autoconf 2.62, with options \\"`$as_echo "$ac_configure_args" | sed 's/^ //; s/[\\""\`\$]/\\\\&/g'`\\" diff -u -r -N squid-3.1.0.10/configure.in squid-3.1.0.11/configure.in --- squid-3.1.0.10/configure.in 2009-07-18 16:17:06.000000000 +1200 +++ squid-3.1.0.11/configure.in 2009-07-19 17:11:50.000000000 +1200 @@ -2,7 +2,7 @@ dnl dnl $Id$ dnl -AC_INIT(Squid Web Proxy, 3.1.0.10, http://www.squid-cache.org/bugs/, squid) +AC_INIT(Squid Web Proxy, 3.1.0.11, http://www.squid-cache.org/bugs/, squid) AC_PREREQ(2.52) AM_CONFIG_HEADER(include/autoconf.h) AC_CONFIG_AUX_DIR(cfgaux) diff -u -r -N squid-3.1.0.10/include/Array.h squid-3.1.0.11/include/Array.h --- squid-3.1.0.10/include/Array.h 2009-07-18 16:16:12.000000000 +1200 +++ squid-3.1.0.11/include/Array.h 2009-07-19 17:11:08.000000000 +1200 @@ -109,6 +109,7 @@ iterator end(); const_iterator end () const; E& operator [] (unsigned i); + const E& operator [] (unsigned i) const; /* Do not change these, until the entry C struct is removed */ size_t capacity; @@ -346,6 +347,14 @@ return items[i]; } +template +const E & +Vector::operator [] (unsigned i) const +{ + assert (size() > i); + return items[i]; +} + template VectorIteratorBase::VectorIteratorBase() : pos(0), theVector(NULL) {} diff -u -r -N squid-3.1.0.10/include/version.h squid-3.1.0.11/include/version.h --- squid-3.1.0.10/include/version.h 2009-07-18 16:17:06.000000000 +1200 +++ squid-3.1.0.11/include/version.h 2009-07-19 17:11:50.000000000 +1200 @@ -9,7 +9,7 @@ */ #ifndef SQUID_RELEASE_TIME -#define SQUID_RELEASE_TIME 1247890568 +#define SQUID_RELEASE_TIME 1247980265 #endif #ifndef APP_SHORTNAME diff -u -r -N squid-3.1.0.10/src/access_log.cc squid-3.1.0.11/src/access_log.cc --- squid-3.1.0.10/src/access_log.cc 2009-07-18 16:16:22.000000000 +1200 +++ squid-3.1.0.11/src/access_log.cc 2009-07-19 17:11:12.000000000 +1200 @@ -106,7 +106,16 @@ 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[] = @@ -333,6 +342,10 @@ 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, @@ -348,7 +361,9 @@ /*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, @@ -365,7 +380,7 @@ 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, */ @@ -373,7 +388,7 @@ 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, */ @@ -381,6 +396,39 @@ 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; @@ -447,6 +495,10 @@ {"tg", LFT_TIME_GMT}, {"tr", LFT_TIME_TO_HANDLE_REQUEST}, + {"h", LFT_REQUEST_HEADER}, {">h", LFT_REQUEST_ALL_HEADERS}, {"Hs", LFT_HTTP_SENT_STATUS_CODE}, + {"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 }, */ @@ -485,7 +539,7 @@ {"st", LFT_ICAP_BYTES_SENT}, + {"icap::h", LFT_ICAP_REQ_HEADER}, + {"icap::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); @@ -620,6 +703,31 @@ 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) @@ -641,6 +749,175 @@ 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); @@ -719,13 +996,25 @@ /* 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; @@ -780,7 +1069,10 @@ 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: */ @@ -804,7 +1096,9 @@ 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: */ @@ -1022,6 +1316,15 @@ 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++) { @@ -1046,6 +1349,14 @@ 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: @@ -1064,16 +1375,30 @@ 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; } @@ -1099,6 +1424,10 @@ 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; } @@ -1160,7 +1489,11 @@ 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: @@ -1172,9 +1505,16 @@ 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; @@ -1182,9 +1522,22 @@ 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; @@ -1235,7 +1588,7 @@ 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; } @@ -1387,13 +1740,61 @@ } -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; @@ -1411,7 +1812,7 @@ 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; @@ -1441,6 +1842,13 @@ break; +#if ICAP_CLIENT + case CLF_ICAP_SQUID: + accessLogICAPSquid(al, log->logfile); + + break; +#endif + case CLF_NONE: goto last; @@ -1458,7 +1866,15 @@ 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) @@ -1534,7 +1950,10 @@ 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); @@ -1544,6 +1963,12 @@ 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 @@ -1580,6 +2005,28 @@ 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 @@ -1848,11 +2295,20 @@ 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 diff -u -r -N squid-3.1.0.10/src/AccessLogEntry.h squid-3.1.0.11/src/AccessLogEntry.h --- squid-3.1.0.10/src/AccessLogEntry.h 2009-07-18 16:16:15.000000000 +1200 +++ squid-3.1.0.11/src/AccessLogEntry.h 2009-07-19 17:11:08.000000000 +1200 @@ -35,6 +35,9 @@ #include "HierarchyLogEntry.h" #include "ip/IpAddress.h" #include "HttpRequestMethod.h" +#if ICAP_CLIENT +#include "adaptation/icap/Elements.h" +#endif /* forward decls */ class HttpReply; @@ -84,6 +87,8 @@ CacheDetails() : caddr(), requestSize(0), replySize(0), + requestHeadersSize(0), + replyHeadersSize(0), highOffset(0), objectSize(0), code (LOG_TAG_NONE), @@ -100,6 +105,8 @@ 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; @@ -118,9 +125,17 @@ { 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; @@ -137,6 +152,41 @@ 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; @@ -144,6 +194,7 @@ 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); diff -u -r -N squid-3.1.0.10/src/acl/DestinationDomain.cc squid-3.1.0.11/src/acl/DestinationDomain.cc --- squid-3.1.0.10/src/acl/DestinationDomain.cc 2009-07-18 16:16:22.000000000 +1200 +++ squid-3.1.0.11/src/acl/DestinationDomain.cc 2009-07-19 17:11:12.000000000 +1200 @@ -58,14 +58,15 @@ } 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(); } diff -u -r -N squid-3.1.0.10/src/acl/DestinationDomain.h squid-3.1.0.11/src/acl/DestinationDomain.h --- squid-3.1.0.10/src/acl/DestinationDomain.h 2009-07-18 16:16:22.000000000 +1200 +++ squid-3.1.0.11/src/acl/DestinationDomain.h 2009-07-19 17:11:12.000000000 +1200 @@ -73,7 +73,7 @@ private: static DestinationDomainLookup instance_; - static void LookupDone(const char *, void *); + static void LookupDone(const char *, const DnsLookupDetails &, void *); }; /// \ingroup ACLAPI diff -u -r -N squid-3.1.0.10/src/acl/DestinationIp.cc squid-3.1.0.11/src/acl/DestinationIp.cc --- squid-3.1.0.10/src/acl/DestinationIp.cc 2009-07-18 16:16:22.000000000 +1200 +++ squid-3.1.0.11/src/acl/DestinationIp.cc 2009-07-19 17:11:12.000000000 +1200 @@ -86,11 +86,12 @@ } 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(); diff -u -r -N squid-3.1.0.10/src/acl/SourceDomain.cc squid-3.1.0.11/src/acl/SourceDomain.cc --- squid-3.1.0.10/src/acl/SourceDomain.cc 2009-07-18 16:16:22.000000000 +1200 +++ squid-3.1.0.11/src/acl/SourceDomain.cc 2009-07-19 17:11:12.000000000 +1200 @@ -39,6 +39,7 @@ #include "acl/Checklist.h" #include "acl/RegexData.h" #include "acl/DomainData.h" +#include "HttpRequest.h" SourceDomainLookup SourceDomainLookup::instance_; @@ -56,14 +57,15 @@ } 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(); } diff -u -r -N squid-3.1.0.10/src/acl/SourceDomain.h squid-3.1.0.11/src/acl/SourceDomain.h --- squid-3.1.0.10/src/acl/SourceDomain.h 2009-07-18 16:16:22.000000000 +1200 +++ squid-3.1.0.11/src/acl/SourceDomain.h 2009-07-19 17:11:12.000000000 +1200 @@ -67,7 +67,7 @@ private: static SourceDomainLookup instance_; - static void LookupDone(const char *, void *); + static void LookupDone(const char *, const DnsLookupDetails &, void *); }; class ACLSourceDomain diff -u -r -N squid-3.1.0.10/src/adaptation/AccessCheck.cc squid-3.1.0.11/src/adaptation/AccessCheck.cc --- squid-3.1.0.10/src/adaptation/AccessCheck.cc 2009-07-18 16:16:22.000000000 +1200 +++ squid-3.1.0.11/src/adaptation/AccessCheck.cc 2009-07-19 17:11:12.000000000 +1200 @@ -23,51 +23,50 @@ if (Config::Enabled) { // the new check will call the callback and delete self, eventually - AccessCheck *check = new AccessCheck(method, vp, req, rep, cb, cbdata); - check->check(); - return true; + return AsyncStart(new AccessCheck( + ServiceFilter(method, vp, req, rep), cb, cbdata)); } debugs(83, 3, HERE << "adaptation off, skipping"); return false; } -Adaptation::AccessCheck::AccessCheck(Method aMethod, - VectPoint aPoint, - HttpRequest *aReq, - HttpReply *aRep, +Adaptation::AccessCheck::AccessCheck(const ServiceFilter &aFilter, AccessCheckCallback *aCallback, - void *aCallbackData): AsyncJob("AccessCheck"), done(FALSE) -{ - // TODO: assign these at creation time - - method = aMethod; - point = aPoint; - - req = HTTPMSGLOCK(aReq); - rep = aRep ? HTTPMSGLOCK(aRep) : NULL; - - callback = aCallback; - - callback_data = cbdataReference(aCallbackData); + void *aCallbackData): + AsyncJob("AccessCheck"), filter(aFilter), + callback(aCallback), + callback_data(cbdataReference(aCallbackData)), + acl_checklist(NULL) +{ +#if ICAP_CLIENT + Adaptation::Icap::History::Pointer h = filter.request->icapHistory(); + if (h != NULL) + h->start("ACL"); +#endif - acl_checklist = NULL; - - debugs(93, 5, HERE << "AccessCheck constructed for " << methodStr(method) << " " << vectPointStr(point)); + debugs(93, 5, HERE << "AccessCheck constructed for " << + methodStr(filter.method) << " " << vectPointStr(filter.point)); } Adaptation::AccessCheck::~AccessCheck() { - HTTPMSGUNLOCK(req); - HTTPMSGUNLOCK(rep); +#if ICAP_CLIENT + Adaptation::Icap::History::Pointer h = filter.request->icapHistory(); + if (h != NULL) + h->stop("ACL"); +#endif if (callback_data) cbdataReferenceDone(callback_data); } -/* - * Walk the access rules list and find all classes that have at least - * one service with matching method and vectoring point. - */ +void +Adaptation::AccessCheck::start() { + AsyncJob::start(); + check(); +} + +/// Walk the access rules list to find rules with applicable service groups void Adaptation::AccessCheck::check() { @@ -75,17 +74,9 @@ typedef AccessRules::iterator ARI; for (ARI i = AllRules().begin(); i != AllRules().end(); ++i) { - - /* - * We only find the first matching service because we only need - * one matching service to justify ACL-checking a class. We might - * use other services belonging to the class if the first service - * turns out to be unusable for some reason. - */ AccessRule *r = *i; - ServicePointer service = findBestService(*r, false); - if (service != NULL) { - debugs(93, 5, HERE << "check: rule '" << r->id << "' has candidate service '" << service->cfg().key << "'"); + if (isCandidate(*r)) { + debugs(93, 5, HERE << "check: rule '" << r->id << "' is a candidate"); candidates += r->id; } } @@ -107,8 +98,8 @@ if (AccessRule *r = FindRule(topCandidate())) { /* BUG 2526: what to do when r->acl is empty?? */ // XXX: we do not have access to conn->rfc931 here. - acl_checklist = new ACLFilledChecklist(r->acl, req, dash_str); - acl_checklist->reply = rep ? HTTPMSGLOCK(rep) : NULL; + acl_checklist = new ACLFilledChecklist(r->acl, filter.request, dash_str); + acl_checklist->reply = filter.reply ? HTTPMSGLOCK(filter.reply) : NULL; acl_checklist->nonBlockingCheck(AccessCheckCallbackWrapper, this); return; } @@ -116,9 +107,9 @@ candidates.shift(); // the rule apparently went away (reconfigure) } - // when there are no canidates, fake answer 1 debugs(93, 4, HERE << "NO candidates left"); - noteAnswer(1); + callBack(NULL); + Must(done()); } void @@ -134,130 +125,75 @@ ac->noteAnswer(answer==ACCESS_ALLOWED); } +/// process the results of the ACL check void Adaptation::AccessCheck::noteAnswer(int answer) { - debugs(93, 5, HERE << "AccessCheck::noteAnswer " << answer); - if (candidates.size()) - debugs(93, 5, HERE << "was checking rule" << topCandidate()); - - if (!answer) { - candidates.shift(); // the rule did not match - checkCandidates(); - return; + Must(!candidates.empty()); // the candidate we were checking must be there + debugs(93,5, HERE << topCandidate() << " answer=" << answer); + + if (answer) { // the rule matched + ServiceGroupPointer g = topGroup(); + if (g != NULL) { // the corresponding group found + callBack(g); + Must(done()); + return; + } } - /* - * We use an event here to break deep function call sequences - */ - // XXX: use AsyncCall for callback and remove - CallJobHere(93, 5, this, Adaptation::AccessCheck::do_callback); + // no match or the group disappeared during reconfiguration + candidates.shift(); + checkCandidates(); } +/// call back with a possibly nil group; the job ends here because all failures +/// at this point are fatal to the access check process void -Adaptation::AccessCheck::do_callback() +Adaptation::AccessCheck::callBack(const ServiceGroupPointer &g) { - debugs(93, 3, HERE); - - if (candidates.size()) - debugs(93, 3, HERE << "was checking rule" << topCandidate()); + debugs(93,3, HERE << g); void *validated_cbdata; - if (!cbdataReferenceValidDone(callback_data, &validated_cbdata)) { - debugs(93,3,HERE << "do_callback: callback_data became invalid, skipping"); - return; + if (cbdataReferenceValidDone(callback_data, &validated_cbdata)) { + callback(g, validated_cbdata); } + mustStop("done"); // called back or will never be able to call back +} - ServicePointer service = NULL; +Adaptation::ServiceGroupPointer +Adaptation::AccessCheck::topGroup() const +{ + ServiceGroupPointer g; if (candidates.size()) { if (AccessRule *r = FindRule(topCandidate())) { - service = findBestService(*r, true); - if (service != NULL) - debugs(93,3,HERE << "do_callback: with service " << service->cfg().uri); - else - debugs(93,3,HERE << "do_callback: no service for rule" << r->id); + g = FindGroup(r->groupId); + debugs(93,5, HERE << "top group for " << r->id << " is " << g); } else { - debugs(93,3,HERE << "do_callback: no rule" << topCandidate()); + debugs(93,5, HERE << "no rule for " << topCandidate()); } - candidates.shift(); // done with topCandidate() } else { - debugs(93,3,HERE << "do_callback: no candidate rules"); + debugs(93,5, HERE << "no candidates"); // should not happen } - callback(service, validated_cbdata); - done = TRUE; + return g; } -Adaptation::ServicePointer -Adaptation::AccessCheck::findBestService(AccessRule &r, bool preferUp) +/** Returns true iff the rule's service group will be used after ACL matches. + Used to detect rules worth ACl-checking. */ +bool +Adaptation::AccessCheck::isCandidate(AccessRule &r) { + debugs(93,7,HERE << "checking candidacy of " << r.id << ", group " << + r.groupId); - const char *what = preferUp ? "up " : ""; - debugs(93,7,HERE << "looking for the first matching " << - what << "service in group " << r.groupId); - - ServicePointer secondBest; - - ServiceGroup *g = FindGroup(r.groupId); + ServiceGroupPointer g = FindGroup(r.groupId); if (!g) { - debugs(93,5,HERE << "lost " << r.groupId << " group in rule" << r.id); - return ServicePointer(); - } - - ServiceGroup::Loop loop(g->initialServices()); - typedef ServiceGroup::iterator SGI; - for (SGI i = loop.begin; i != loop.end; ++i) { - - ServicePointer service = FindService(*i); - - if (!service) - continue; - - if (method != service->cfg().method) - continue; - - if (point != service->cfg().point) - continue; - - // sending a message to a broken service is likely to cause errors - if (service->cfg().bypass && service->broken()) - continue; - - if (service->up()) { - // sending a message to a service that does not want it is useless - // note that we cannot check wantsUrl for service that is not "up" - // note that even essential services are skipped on unwanted URLs! - if (!service->wantsUrl(req->urlpath)) - continue; - } else { - if (!secondBest) - secondBest = service; - if (preferUp) { - // the caller asked for an "up" service and we can bypass this one - if (service->cfg().bypass) - continue; - debugs(93,5,HERE << "cannot skip an essential down service"); - what = "down-but-essential "; - } - } - - debugs(93,5,HERE << "found first matching " << - what << "service for " << r.groupId << " group in rule" << r.id << - ": " << service->cfg().key); - - return service; - } - - if (secondBest != NULL) { - what = "down "; - debugs(93,5,HERE << "found first matching " << - what << "service for " << r.groupId << " group in rule" << r.id << - ": " << secondBest->cfg().key); - return secondBest; + debugs(93,7,HERE << "lost " << r.groupId << " group in rule" << r.id); + return false; } - debugs(93,5,HERE << "found no matching " << - what << "services for " << r.groupId << " group in rule" << r.id); - return ServicePointer(); + const bool wants = g->wants(filter); + debugs(93,7,HERE << r.groupId << (wants ? " wants" : " ignores")); + return wants; } diff -u -r -N squid-3.1.0.10/src/adaptation/AccessCheck.h squid-3.1.0.11/src/adaptation/AccessCheck.h --- squid-3.1.0.10/src/adaptation/AccessCheck.h 2009-07-18 16:16:22.000000000 +1200 +++ squid-3.1.0.11/src/adaptation/AccessCheck.h 2009-07-19 17:11:12.000000000 +1200 @@ -4,6 +4,7 @@ #include "base/AsyncJob.h" #include "adaptation/Elements.h" #include "adaptation/forward.h" +#include "adaptation/ServiceFilter.h" class HttpRequest; class HttpReply; @@ -18,7 +19,7 @@ class AccessCheck: public virtual AsyncJob { public: - typedef void AccessCheckCallback(ServicePointer match, void *data); + typedef void AccessCheckCallback(ServiceGroupPointer group, void *data); // use this to start async ACL checks; returns true if started static bool Start(Method method, VectPoint vp, HttpRequest *req, @@ -26,14 +27,11 @@ protected: // use Start to start adaptation checks - AccessCheck(Method, VectPoint, HttpRequest *, HttpReply *, AccessCheckCallback *, void *); + AccessCheck(const ServiceFilter &aFilter, AccessCheckCallback *, void *); ~AccessCheck(); private: - Method method; - VectPoint point; - HttpRequest *req; - HttpReply *rep; + const ServiceFilter filter; AccessCheckCallback *callback; void *callback_data; ACLFilledChecklist *acl_checklist; @@ -41,23 +39,23 @@ typedef int Candidate; typedef Vector Candidates; Candidates candidates; - Candidate topCandidate() { return *candidates.begin(); } + Candidate topCandidate() const { return *candidates.begin(); } + ServiceGroupPointer topGroup() const; // may return nil - void do_callback(); - ServicePointer findBestService(AccessRule &r, bool preferUp); - bool done; + void callBack(const ServiceGroupPointer &g); + bool isCandidate(AccessRule &r); public: - void check(); void checkCandidates(); static void AccessCheckCallbackWrapper(int, void*); -#if 0 - static EVH AccessCheckCallbackEvent; -#endif void noteAnswer(int answer); -//AsyncJob virtual methods - virtual bool doneAll() const { return AsyncJob::doneAll() && done;} +protected: + // AsyncJob API + virtual void start(); + virtual bool doneAll() const { return false; } /// not done until mustStop + + void check(); private: CBDATA_CLASS2(AccessCheck); diff -u -r -N squid-3.1.0.10/src/adaptation/AccessRule.cc squid-3.1.0.11/src/adaptation/AccessRule.cc --- squid-3.1.0.10/src/adaptation/AccessRule.cc 2009-07-18 16:16:22.000000000 +1200 +++ squid-3.1.0.11/src/adaptation/AccessRule.cc 2009-07-19 17:11:12.000000000 +1200 @@ -32,7 +32,7 @@ debugs(93,7, HERE << "no service group: " << groupId); // try to add a one-service group if (FindService(groupId) != NULL) { - ServiceGroup *g = new SingleService(groupId); + ServiceGroupPointer g = new SingleService(groupId); g->finalize(); // explicit groups were finalized before rules AllGroups().push_back(g); } @@ -44,7 +44,7 @@ } } -Adaptation::ServiceGroup * +Adaptation::ServiceGroupPointer Adaptation::AccessRule::group() { return FindGroup(groupId); diff -u -r -N squid-3.1.0.10/src/adaptation/AccessRule.h squid-3.1.0.11/src/adaptation/AccessRule.h --- squid-3.1.0.10/src/adaptation/AccessRule.h 2009-07-18 16:16:22.000000000 +1200 +++ squid-3.1.0.11/src/adaptation/AccessRule.h 2009-07-19 17:11:12.000000000 +1200 @@ -22,7 +22,7 @@ void finalize(); // service group consisting of one or more services - ServiceGroup *group(); + ServiceGroupPointer group(); public: typedef int Id; diff -u -r -N squid-3.1.0.10/src/adaptation/Config.cc squid-3.1.0.11/src/adaptation/Config.cc --- squid-3.1.0.10/src/adaptation/Config.cc 2009-07-18 16:16:22.000000000 +1200 +++ squid-3.1.0.11/src/adaptation/Config.cc 2009-07-19 17:11:12.000000000 +1200 @@ -41,15 +41,21 @@ #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; +int Adaptation::Config::service_iteration_limit = 16; void Adaptation::Config::parseService() { ServiceConfig *cfg = new ServiceConfig; - cfg->parse(); + if (!cfg->parse()) { + fatalf("%s:%d: malformed adaptation service configuration", + cfg_filename, config_lineno); + } serviceConfigs.push_back(cfg); } @@ -125,22 +131,34 @@ void Adaptation::Config::ParseServiceSet() { - ServiceSet *g = new ServiceSet(); + Adaptation::Config::ParseServiceGroup(new ServiceSet); +} + +void +Adaptation::Config::ParseServiceChain() +{ + Adaptation::Config::ParseServiceGroup(new ServiceChain); +} + +void +Adaptation::Config::ParseServiceGroup(ServiceGroupPointer g) +{ + assert(g != NULL); g->parse(); AllGroups().push_back(g); } void -Adaptation::Config::FreeServiceSet() +Adaptation::Config::FreeServiceGroups() { while (!AllGroups().empty()) { - delete AllGroups().back(); + // groups are refcounted so we do not explicitly delete them AllGroups().pop_back(); } } void -Adaptation::Config::DumpServiceSet(StoreEntry *entry, const char *name) +Adaptation::Config::DumpServiceGroups(StoreEntry *entry, const char *name) { typedef Groups::iterator GI; for (GI i = AllGroups().begin(); i != AllGroups().end(); ++i) @@ -191,7 +209,7 @@ Adaptation::Config::~Config() { FreeAccess(); - FreeServiceSet(); + FreeServiceGroups(); // invalidate each service so that it can be deleted when refcount=0 while (!AllServices().empty()) { diff -u -r -N squid-3.1.0.10/src/adaptation/Config.h squid-3.1.0.11/src/adaptation/Config.h --- squid-3.1.0.10/src/adaptation/Config.h 2009-07-18 16:16:22.000000000 +1200 +++ squid-3.1.0.11/src/adaptation/Config.h 2009-07-19 17:11:12.000000000 +1200 @@ -3,34 +3,22 @@ #include "event.h" #include "base/AsyncCall.h" +#include "adaptation/forward.h" #include "adaptation/Elements.h" class acl_access; class ConfigParser; -template -class RefCount; - namespace Adaptation { -class Service; -class ServiceConfig; -class Class; - -typedef RefCount ServicePointer; - -class ServiceGroup; -class AccessRule; - class Config { public: static void Finalize(bool enable); static void ParseServiceSet(void); - static void FreeServiceSet(void); - static void DumpServiceSet(StoreEntry *, const char *); + static void ParseServiceChain(void); static void ParseAccess(ConfigParser &parser); static void FreeAccess(void); @@ -41,6 +29,11 @@ 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? + static int service_iteration_limit; + // 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; @@ -56,7 +49,6 @@ void freeService(void); void dumpService(StoreEntry *, const char *) const; ServicePointer findService(const String&); - Class * findClass(const String& key); virtual void finalize(); @@ -65,6 +57,10 @@ Config &operator =(const Config &); // unsupported virtual ServicePointer createService(const ServiceConfig &cfg) = 0; + + static void ParseServiceGroup(ServiceGroupPointer group); + static void FreeServiceGroups(void); + static void DumpServiceGroups(StoreEntry *, const char *); }; } // namespace Adaptation diff -u -r -N squid-3.1.0.10/src/adaptation/ecap/XactionRep.cc squid-3.1.0.11/src/adaptation/ecap/XactionRep.cc --- squid-3.1.0.10/src/adaptation/ecap/XactionRep.cc 2009-07-18 16:16:23.000000000 +1200 +++ squid-3.1.0.11/src/adaptation/ecap/XactionRep.cc 2009-07-19 17:11:13.000000000 +1200 @@ -5,6 +5,7 @@ #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); @@ -14,9 +15,12 @@ HttpMsg *virginHeader, HttpRequest *virginCause, const Adaptation::ServicePointer &aService): AsyncJob("Adaptation::Ecap::XactionRep"), - Adaptation::Initiate("Adaptation::Ecap::XactionRep", anInitiator, aService), + Adaptation::Initiate("Adaptation::Ecap::XactionRep", anInitiator), + theService(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) @@ -38,6 +42,13 @@ theMaster = x; } +Adaptation::Service & +Adaptation::Ecap::XactionRep::service() +{ + Must(theService != NULL); + return *theService; +} + void Adaptation::Ecap::XactionRep::start() { @@ -48,6 +59,15 @@ else proxyingVb = opNever; + const HttpRequest *request = dynamic_cast (theCauseRep ? + theCauseRep->raw().header : theVirginRep.raw().header); + Must(request); + Adaptation::History::Pointer ah = request->adaptLogHistory(); + if (ah != NULL) { + // retrying=false because ecap never retries transactions + adaptHistoryId = ah->recordXactStart(service().cfg().key, current_time, false); + } + theMaster->start(); } @@ -74,6 +94,14 @@ } terminateMaster(); + + const HttpRequest *request = dynamic_cast(theCauseRep ? + theCauseRep->raw().header : theVirginRep.raw().header); + Must(request); + Adaptation::History::Pointer ah = request->adaptLogHistory(); + if (ah != NULL && adaptHistoryId >= 0) + ah->recordXactFinish(adaptHistoryId); + Adaptation::Initiate::swanSong(); } diff -u -r -N squid-3.1.0.10/src/adaptation/ecap/XactionRep.h squid-3.1.0.11/src/adaptation/ecap/XactionRep.h --- squid-3.1.0.10/src/adaptation/ecap/XactionRep.h 2009-07-18 16:16:23.000000000 +1200 +++ squid-3.1.0.11/src/adaptation/ecap/XactionRep.h 2009-07-19 17:11:13.000000000 +1200 @@ -8,9 +8,9 @@ #include "BodyPipe.h" #include "adaptation/Initiate.h" -#include "adaptation/Service.h" #include "adaptation/Message.h" #include "adaptation/ecap/MessageRep.h" +#include "adaptation/ecap/ServiceRep.h" #include #include #include @@ -72,6 +72,8 @@ virtual const char *status() const; protected: + Service &service(); + Adaptation::Message &answer(); void dropVirgin(const char *reason); @@ -82,6 +84,7 @@ private: AdapterXaction theMaster; // the actual adaptation xaction we represent + Adaptation::ServicePointer theService; ///< xaction's adaptation service MessageRep theVirginRep; MessageRep *theCauseRep; @@ -92,6 +95,7 @@ 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 diff -u -r -N squid-3.1.0.10/src/adaptation/forward.h squid-3.1.0.11/src/adaptation/forward.h --- squid-3.1.0.10/src/adaptation/forward.h 2009-07-18 16:16:23.000000000 +1200 +++ squid-3.1.0.11/src/adaptation/forward.h 2009-07-19 17:11:13.000000000 +1200 @@ -22,9 +22,12 @@ class AccessCheck; class AccessRule; class ServiceGroup; +class ServicePlan; +class ServiceFilter; class Message; typedef RefCount ServicePointer; +typedef RefCount ServiceGroupPointer; } // namespace Adaptation diff -u -r -N squid-3.1.0.10/src/adaptation/History.cc squid-3.1.0.11/src/adaptation/History.cc --- squid-3.1.0.10/src/adaptation/History.cc 1970-01-01 12:00:00.000000000 +1200 +++ squid-3.1.0.11/src/adaptation/History.cc 2009-07-19 17:11:12.000000000 +1200 @@ -0,0 +1,138 @@ +#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" + +/// impossible services value to identify unset theNextServices +const static String TheNullServices(",null,"); + +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; +} + + +Adaptation::History::History(): theNextServices(TheNullServices) { +} + +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(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; +} + +void Adaptation::History::updateNextServices(const String &services) +{ + if (theNextServices != TheNullServices) + debugs(93,3, HERE << "old services: " << theNextServices); + debugs(93,3, HERE << "new services: " << services); + Must(services != TheNullServices); + theNextServices = services; +} + +bool Adaptation::History::extractNextServices(String &value) +{ + if (theNextServices == TheNullServices) + return false; + + value = theNextServices; + theNextServices = TheNullServices; // prevents resetting the plan twice + return true; +} diff -u -r -N squid-3.1.0.10/src/adaptation/History.h squid-3.1.0.11/src/adaptation/History.h --- squid-3.1.0.10/src/adaptation/History.h 1970-01-01 12:00:00.000000000 +1200 +++ squid-3.1.0.11/src/adaptation/History.h 2009-07-19 17:11:12.000000000 +1200 @@ -0,0 +1,74 @@ +#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 Pointer; + + History(); + + /// 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; + + /// sets or resets next services for the Adaptation::Iterator to notice + void updateNextServices(const String &services); + + /// returns true, fills the value, and resets iff next services were set + bool extractNextServices(String &value); + +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 Entries; + Entries theEntries; ///< historical record, in the order of xact starts + + // theXx* will become a map, 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 + + String theNextServices; ///< services Adaptation::Iterator must use next +}; + +} // namespace Adaptation + +#endif diff -u -r -N squid-3.1.0.10/src/adaptation/icap/Config.cc squid-3.1.0.11/src/adaptation/icap/Config.cc --- squid-3.1.0.10/src/adaptation/icap/Config.cc 2009-07-18 16:16:23.000000000 +1200 +++ squid-3.1.0.11/src/adaptation/icap/Config.cc 2009-07-19 17:11:13.000000000 +1200 @@ -47,7 +47,7 @@ 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) { } diff -u -r -N squid-3.1.0.10/src/adaptation/icap/Config.h squid-3.1.0.11/src/adaptation/icap/Config.h --- squid-3.1.0.10/src/adaptation/icap/Config.h 2009-07-18 16:16:23.000000000 +1200 +++ squid-3.1.0.11/src/adaptation/icap/Config.h 2009-07-19 17:11:13.000000000 +1200 @@ -41,13 +41,12 @@ #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 @@ -62,6 +61,8 @@ 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(); diff -u -r -N squid-3.1.0.10/src/adaptation/icap/Elements.cc squid-3.1.0.11/src/adaptation/icap/Elements.cc --- squid-3.1.0.10/src/adaptation/icap/Elements.cc 2009-07-18 16:16:23.000000000 +1200 +++ squid-3.1.0.11/src/adaptation/icap/Elements.cc 2009-07-19 17:11:13.000000000 +1200 @@ -2,3 +2,15 @@ #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 diff -u -r -N squid-3.1.0.10/src/adaptation/icap/Elements.h squid-3.1.0.11/src/adaptation/icap/Elements.h --- squid-3.1.0.10/src/adaptation/icap/Elements.h 2009-07-18 16:16:23.000000000 +1200 +++ squid-3.1.0.11/src/adaptation/icap/Elements.h 2009-07-19 17:11:13.000000000 +1200 @@ -43,6 +43,7 @@ { namespace Icap { +//TODO: remove the ICAP namespace namespace ICAP { using Adaptation::Method; using Adaptation::methodNone; @@ -59,6 +60,13 @@ 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 diff -u -r -N squid-3.1.0.10/src/adaptation/icap/History.cc squid-3.1.0.11/src/adaptation/icap/History.cc --- squid-3.1.0.10/src/adaptation/icap/History.cc 1970-01-01 12:00:00.000000000 +1200 +++ squid-3.1.0.11/src/adaptation/icap/History.cc 2009-07-19 17:11:13.000000000 +1200 @@ -0,0 +1,103 @@ +#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; +} diff -u -r -N squid-3.1.0.10/src/adaptation/icap/History.h squid-3.1.0.11/src/adaptation/icap/History.h --- squid-3.1.0.10/src/adaptation/icap/History.h 1970-01-01 12:00:00.000000000 +1200 +++ squid-3.1.0.11/src/adaptation/icap/History.h 2009-07-19 17:11:13.000000000 +1200 @@ -0,0 +1,60 @@ +#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 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*/ diff -u -r -N squid-3.1.0.10/src/adaptation/icap/icap_log.cc squid-3.1.0.11/src/adaptation/icap/icap_log.cc --- squid-3.1.0.10/src/adaptation/icap/icap_log.cc 1970-01-01 12:00:00.000000000 +1200 +++ squid-3.1.0.11/src/adaptation/icap/icap_log.cc 2009-07-19 17:11:13.000000000 +1200 @@ -0,0 +1,52 @@ +#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); +} diff -u -r -N squid-3.1.0.10/src/adaptation/icap/icap_log.h squid-3.1.0.11/src/adaptation/icap/icap_log.h --- squid-3.1.0.10/src/adaptation/icap/icap_log.h 1970-01-01 12:00:00.000000000 +1200 +++ squid-3.1.0.11/src/adaptation/icap/icap_log.h 2009-07-19 17:11:13.000000000 +1200 @@ -0,0 +1,14 @@ +#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_*/ diff -u -r -N squid-3.1.0.10/src/adaptation/icap/Launcher.cc squid-3.1.0.11/src/adaptation/icap/Launcher.cc --- squid-3.1.0.10/src/adaptation/icap/Launcher.cc 2009-07-18 16:16:23.000000000 +1200 +++ squid-3.1.0.11/src/adaptation/icap/Launcher.cc 2009-07-19 17:11:13.000000000 +1200 @@ -4,17 +4,21 @@ #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::Initiator *anInitiator, Adaptation::ServicePointer &aService): AsyncJob(aTypeName), - Adaptation::Initiate(aTypeName, anInitiator, aService), - theXaction(0), theLaunches(0) + Adaptation::Initiate(aTypeName, anInitiator), + theService(aService), theXaction(0), theLaunches(0) { } @@ -28,17 +32,20 @@ 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); } @@ -60,19 +67,33 @@ } +// 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 +} - // TODO: add more checks from FwdState::checkRetry()? - if (!final && theLaunches < 2 && !shutting_down) { - launchXaction(true); - } else { - debugs(93,3, HERE << "cannot retry the failed ICAP xaction; tries: " << - theLaunches << "; final: " << final); - 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 (canRetry(info)) { + clearAdaptation(theXaction); + launchXaction("retry"); + } + else if (canRepeat(info)) { + clearAdaptation(theXaction); + launchXaction("repeat"); + } else { + debugs(93,3, HERE << "cannot retry or repeat a failed transaction"); + clearAdaptation(theXaction); + tellQueryAborted(false); // caller decides based on bypass, consumption + Must(done()); + } } bool Adaptation::Icap::Launcher::doneAll() const @@ -83,10 +104,67 @@ void Adaptation::Icap::Launcher::swanSong() { if (theInitiator) - tellQueryAborted(!service().cfg().bypass); + tellQueryAborted(true); // always final here because abnormal if (theXaction) clearAdaptation(theXaction); 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); +} diff -u -r -N squid-3.1.0.10/src/adaptation/icap/Launcher.h squid-3.1.0.11/src/adaptation/icap/Launcher.h --- squid-3.1.0.10/src/adaptation/icap/Launcher.h 2009-07-18 16:16:23.000000000 +1200 +++ squid-3.1.0.11/src/adaptation/icap/Launcher.h 2009-07-19 17:11:13.000000000 +1200 @@ -64,6 +64,7 @@ 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 @@ -79,6 +80,11 @@ // 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: @@ -90,14 +96,58 @@ // 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::ServicePointer theService; ///< ICAP service for all launches + 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 { +public: + typedef void (Adaptation::Icap::Launcher::*DialMethod)(Adaptation::Icap::XactAbortInfo &); + XactAbortCall(Adaptation::Icap::Launcher *launcer, DialMethod aMethod, + const Adaptation::Icap::XactAbortInfo &info): + UnaryMemFunT(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 */ diff -u -r -N squid-3.1.0.10/src/adaptation/icap/Makefile.am squid-3.1.0.11/src/adaptation/icap/Makefile.am --- squid-3.1.0.10/src/adaptation/icap/Makefile.am 2009-07-18 16:16:23.000000000 +1200 +++ squid-3.1.0.11/src/adaptation/icap/Makefile.am 2009-07-19 17:11:13.000000000 +1200 @@ -22,4 +22,8 @@ Xaction.cc \ Xaction.h \ ModXact.cc \ - ModXact.h + ModXact.h \ + icap_log.cc \ + icap_log.h \ + History.cc \ + History.h diff -u -r -N squid-3.1.0.10/src/adaptation/icap/Makefile.in squid-3.1.0.11/src/adaptation/icap/Makefile.in --- squid-3.1.0.10/src/adaptation/icap/Makefile.in 2009-07-18 16:16:48.000000000 +1200 +++ squid-3.1.0.11/src/adaptation/icap/Makefile.in 2009-07-19 17:11:34.000000000 +1200 @@ -47,7 +47,8 @@ LTLIBRARIES = $(noinst_LTLIBRARIES) libicap_la_LIBADD = am_libicap_la_OBJECTS = Client.lo Config.lo Elements.lo Options.lo \ - ServiceRep.lo Launcher.lo OptXact.lo Xaction.lo ModXact.lo + ServiceRep.lo Launcher.lo OptXact.lo Xaction.lo ModXact.lo \ + icap_log.lo History.lo libicap_la_OBJECTS = $(am_libicap_la_OBJECTS) DEFAULT_INCLUDES = depcomp = $(SHELL) $(top_srcdir)/cfgaux/depcomp @@ -279,7 +280,11 @@ Xaction.cc \ Xaction.h \ ModXact.cc \ - ModXact.h + ModXact.h \ + icap_log.cc \ + icap_log.h \ + History.cc \ + History.h all: all-am @@ -342,12 +347,14 @@ @AMDEP_TRUE@@am__include@ @am__quote@./$(DEPDIR)/Client.Plo@am__quote@ @AMDEP_TRUE@@am__include@ @am__quote@./$(DEPDIR)/Config.Plo@am__quote@ @AMDEP_TRUE@@am__include@ @am__quote@./$(DEPDIR)/Elements.Plo@am__quote@ +@AMDEP_TRUE@@am__include@ @am__quote@./$(DEPDIR)/History.Plo@am__quote@ @AMDEP_TRUE@@am__include@ @am__quote@./$(DEPDIR)/Launcher.Plo@am__quote@ @AMDEP_TRUE@@am__include@ @am__quote@./$(DEPDIR)/ModXact.Plo@am__quote@ @AMDEP_TRUE@@am__include@ @am__quote@./$(DEPDIR)/OptXact.Plo@am__quote@ @AMDEP_TRUE@@am__include@ @am__quote@./$(DEPDIR)/Options.Plo@am__quote@ @AMDEP_TRUE@@am__include@ @am__quote@./$(DEPDIR)/ServiceRep.Plo@am__quote@ @AMDEP_TRUE@@am__include@ @am__quote@./$(DEPDIR)/Xaction.Plo@am__quote@ +@AMDEP_TRUE@@am__include@ @am__quote@./$(DEPDIR)/icap_log.Plo@am__quote@ .cc.o: @am__fastdepCXX_TRUE@ $(CXXCOMPILE) -MT $@ -MD -MP -MF $(DEPDIR)/$*.Tpo -c -o $@ $< diff -u -r -N squid-3.1.0.10/src/adaptation/icap/ModXact.cc squid-3.1.0.11/src/adaptation/icap/ModXact.cc --- squid-3.1.0.10/src/adaptation/icap/ModXact.cc 2009-07-18 16:16:23.000000000 +1200 +++ squid-3.1.0.11/src/adaptation/icap/ModXact.cc 2009-07-19 17:11:13.000000000 +1200 @@ -17,6 +17,9 @@ #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 @@ -41,10 +44,12 @@ 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 + protectGroupBypass(true), + replyBodySize(0), + adaptHistoryId(-1) { assert(virginHeader); @@ -58,8 +63,8 @@ // 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()); @@ -70,6 +75,11 @@ { Adaptation::Icap::Xaction::start(); + // reserve an adaptation history slot (attempts are known at this time) + Adaptation::History::Pointer ah = virginRequest().adaptLogHistory(); + if (ah != NULL) + adaptHistoryId = ah->recordXactStart(service().cfg().key, icap_tr_start, attempts > 1); + estimateVirginBody(); // before virgin disappears! canStartBypass = service().cfg().bypass; @@ -101,6 +111,7 @@ startWriting(); } else { disableRetries(); + disableRepeats("ICAP service is unusable"); throw TexcHere("ICAP service is unusable"); } } @@ -131,6 +142,7 @@ // write headers state.writing = State::writingHeaders; + icap_tio_start = current_time; scheduleWrite(requestBuf); } @@ -304,6 +316,14 @@ buf.append(ICAP::crlf, 2); // chunk-terminating CRLF } +const HttpRequest &Adaptation::Icap::ModXact::virginRequest() const +{ + const HttpRequest *request = virgin.cause ? + virgin.cause : dynamic_cast(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 { @@ -336,7 +356,8 @@ 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 << protectGroupBypass); if (!virgin.body_pipe) return; // nothing to consume @@ -345,11 +366,12 @@ return; // do not consume if we may have to retry later BodyPipe &bp = *virgin.body_pipe; + const bool wantToPostpone = isRepeatable || canStartBypass || protectGroupBypass; // 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 @@ -381,7 +403,8 @@ bp.consume(size); virginConsumed += size; Must(!isRetriable); // or we should not be consuming - disableBypass("consumed content"); + disableRepeats("consumed content"); + disableBypass("consumed content", true); } } @@ -477,6 +500,7 @@ void Adaptation::Icap::ModXact::handleCommRead(size_t) { Must(!state.doneParsing()); + icap_tio_finish = current_time; parseMore(); readMore(); } @@ -498,8 +522,9 @@ debugs(93,5, HERE << "echoed " << size << " out of " << sizeMax << " bytes"); virginBodySending.progress(size); + disableRepeats("echoed content"); + disableBypass("echoed content", true); virginConsume(); - disableBypass("echoed content"); } if (virginBodyEndReached(virginBodySending)) { @@ -521,8 +546,10 @@ // 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()); @@ -584,9 +611,10 @@ void Adaptation::Icap::ModXact::bypassFailure() { - disableBypass("already started to bypass"); + disableBypass("already started to bypass", false); Must(!isRetriable); // or we should not be bypassing + // TODO: should the same be enforced for isRepeatable? Check icap_repeat?? prepEchoing(); @@ -605,12 +633,16 @@ } } -void Adaptation::Icap::ModXact::disableBypass(const char *reason) +void Adaptation::Icap::ModXact::disableBypass(const char *reason, bool includingGroupBypass) { if (canStartBypass) { debugs(93,7, HERE << "will never start bypass because " << reason); canStartBypass = false; } + if (protectGroupBypass && includingGroupBypass) { + debugs(93,7, HERE << "not protecting group bypass because " << reason); + protectGroupBypass = false; + } } @@ -623,8 +655,11 @@ 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()"); } @@ -654,7 +689,8 @@ // called after parsing all headers or when bypassing an exception void Adaptation::Icap::ModXact::startSending() { - disableBypass("sent headers"); + disableRepeats("sent headers"); + disableBypass("sent headers", true); sendAnswer(adapted.header); if (state.sending == State::sendingVirgin) @@ -700,6 +736,40 @@ break; } + const HttpRequest *request = dynamic_cast(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(true); + if (ah != NULL) { + const String val = icapReply->header.getByName(xxName); + if (val.size() > 0) // XXX: HttpHeader lacks empty value detection + ah->updateXxRecord(xxName, val); + } + } + + // update the adaptation plan if needed (all status codes!) + if (service().cfg().routing) { + String services; + if (icapReply->header.getList(HDR_X_NEXT_SERVICES, &services)) { + Adaptation::History::Pointer ah = request->adaptHistory(true); + if (ah != NULL) + ah->updateNextServices(services); + } + } // TODO: else warn (occasionally!) if we got HDR_X_NEXT_SERVICES + + // We need to store received ICAP headers for 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) @@ -762,12 +832,15 @@ // We actually start sending (echoig or not) in startSending. void Adaptation::Icap::ModXact::prepEchoing() { - disableBypass("preparing to echo content"); + disableRepeats("preparing to echo content"); + disableBypass("preparing to echo content", true); + 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. // Thus, we cannot use a smart pointer, copy constructor, or equivalent. // Instead, we simply write the HTTP message and "clone" it by parsing. + // TODO: use HttpMsg::clone()! HttpMsg *oldHead = virgin.header; debugs(93, 7, HERE << "cloning virgin message " << oldHead); @@ -781,8 +854,10 @@ // allocate the adapted message and copy metainfo Must(!adapted.header); HttpMsg *newHead = NULL; - if (dynamic_cast(oldHead)) { + if (const HttpRequest *oldR = dynamic_cast(oldHead)) { HttpRequest *newR = new HttpRequest; + newR->canonical = oldR->canonical ? + xstrdup(oldR->canonical) : NULL; // parse() does not set it newHead = newR; } else if (dynamic_cast(oldHead)) { HttpReply *newRep = new HttpReply; @@ -879,6 +954,9 @@ return false; } + if (HttpRequest *r = dynamic_cast(head)) + urlCanonical(r); // parse does not set HttpRequest::canonical + debugs(93, 5, HERE << "parse success, consume " << head->hdr_sz << " bytes, return true"); readBuf.consume(head->hdr_sz); return true; @@ -913,10 +991,14 @@ 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 - disableBypass("sent adapted content"); + // 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", true); + } if (parsed) { stopParsing(); @@ -1014,14 +1096,74 @@ 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().adaptLogHistory(); + 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(adapted.header))) + { + request_ = (virgin.cause? virgin.cause: dynamic_cast(virgin.header)); + reply_ = dynamic_cast(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]; @@ -1048,6 +1190,21 @@ 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(true); + 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; @@ -1057,10 +1214,6 @@ // build HTTP request header, if any ICAP::Method m = s.method; - const HttpRequest *request = virgin.cause ? - virgin.cause : - dynamic_cast(virgin.header); - // to simplify, we could assume that request is always available String urlPath; @@ -1113,6 +1266,9 @@ buf.append(ICAP::crlf, 2); // terminate ICAP header + // fill icapRequest for logging + Must(icapRequest->parseCharBuf(buf.content(), buf.contentSize())); + // start ICAP request body with encapsulated HTTP headers buf.append(httpBuf.content(), httpBuf.contentSize()); @@ -1141,7 +1297,8 @@ if (const HttpRequest* old_request = dynamic_cast(head)) { HttpRequest* new_request = new HttpRequest; - urlParse(old_request->method, old_request->canonical,new_request); + assert(old_request->canonical); + urlParse(old_request->method, old_request->canonical, new_request); new_request->http_ver = old_request->http_ver; headClone = new_request; } else if (const HttpReply *old_reply = dynamic_cast(head)) { @@ -1186,10 +1343,7 @@ return; } - const HttpRequest *request = virgin.cause ? - virgin.cause : - dynamic_cast(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); @@ -1309,6 +1463,9 @@ if (canStartBypass) buf.append("Y", 1); + + if (protectGroupBypass) + buf.append("G", 1); } void Adaptation::Icap::ModXact::fillDoneStatus(MemBuf &buf) const @@ -1531,6 +1688,7 @@ { virgin.setHeader(virginHeader); virgin.setCause(virginCause); + updateHistory(true); } Adaptation::Icap::Xaction *Adaptation::Icap::ModXactLauncher::createXaction() @@ -1540,3 +1698,25 @@ 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(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"); + } + } +} diff -u -r -N squid-3.1.0.10/src/adaptation/icap/ModXact.h squid-3.1.0.11/src/adaptation/icap/ModXact.h --- squid-3.1.0.10/src/adaptation/icap/ModXact.h 2009-07-18 16:16:23.000000000 +1200 +++ squid-3.1.0.11/src/adaptation/icap/ModXact.h 2009-07-19 17:11:13.000000000 +1200 @@ -167,6 +167,9 @@ 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); @@ -226,7 +229,7 @@ void bypassFailure(); void startSending(); - void disableBypass(const char *reason); + void disableBypass(const char *reason, bool includeGroupBypass); void prepEchoing(); void echoMore(); @@ -250,8 +253,7 @@ bool gotEncapsulated(const char *section) const; void checkConsuming(); - - HttpReply *icapReply; + virtual void finalizeLogInfo(); SizedEstimate virginBody; VirginBodyAct virginBodyWriting; // virgin body writing state @@ -262,6 +264,11 @@ ChunkedCodingParser *bodyParser; // ICAP response body parser bool canStartBypass; // enables bypass of transaction failures + bool protectGroupBypass; // protects ServiceGroup-wide bypass of failures + + uint64_t replyBodySize; ///< dechunked ICAP reply body size + + int adaptHistoryId; ///< adaptation history slot reservation class State { @@ -319,6 +326,11 @@ protected: virtual Xaction *createXaction(); + virtual void swanSong(); + + /// starts or stops transaction accounting in ICAP history + void updateHistory(bool start); + InOut virgin; private: diff -u -r -N squid-3.1.0.10/src/adaptation/icap/OptXact.cc squid-3.1.0.11/src/adaptation/icap/OptXact.cc --- squid-3.1.0.10/src/adaptation/icap/OptXact.cc 2009-07-18 16:16:23.000000000 +1200 +++ squid-3.1.0.11/src/adaptation/icap/OptXact.cc 2009-07-19 17:11:13.000000000 +1200 @@ -9,6 +9,8 @@ #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); @@ -36,7 +38,7 @@ makeRequest(requestBuf); debugs(93, 9, HERE << "request " << status() << ":\n" << (requestBuf.terminate(), requestBuf.content())); - + icap_tio_start = current_time; scheduleWrite(requestBuf); } @@ -48,6 +50,10 @@ 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) @@ -60,7 +66,10 @@ void Adaptation::Icap::OptXact::handleCommRead(size_t) { if (HttpMsg *r = parseResponse()) { + icap_tio_finish = current_time; + setOutcome(xoOpt); sendAnswer(r); + icapReply = HTTPMSGLOCK(dynamic_cast(r)); Must(done()); // there should be nothing else to do return; } @@ -74,11 +83,11 @@ 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; } @@ -88,6 +97,18 @@ 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): diff -u -r -N squid-3.1.0.10/src/adaptation/icap/OptXact.h squid-3.1.0.11/src/adaptation/icap/OptXact.h --- squid-3.1.0.10/src/adaptation/icap/OptXact.h 2009-07-18 16:16:23.000000000 +1200 +++ squid-3.1.0.11/src/adaptation/icap/OptXact.h 2009-07-19 17:11:13.000000000 +1200 @@ -63,7 +63,10 @@ void startReading(); + virtual void swanSong(); + private: + virtual void finalizeLogInfo(); CBDATA_CLASS2(OptXact); }; diff -u -r -N squid-3.1.0.10/src/adaptation/icap/Xaction.cc squid-3.1.0.11/src/adaptation/icap/Xaction.cc --- squid-3.1.0.10/src/adaptation/icap/Xaction.cc 2009-07-18 16:16:23.000000000 +1200 +++ squid-3.1.0.11/src/adaptation/icap/Xaction.cc 2009-07-19 17:11:13.000000000 +1200 @@ -7,10 +7,16 @@ #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"); @@ -19,40 +25,55 @@ Adaptation::Icap::Xaction::Xaction(const char *aTypeName, Adaptation::Initiator *anInitiator, Adaptation::Icap::ServiceRep::Pointer &aService): AsyncJob(aTypeName), - Adaptation::Initiate(aTypeName, anInitiator, aService.getRaw()), + Adaptation::Initiate(aTypeName, anInitiator), + icapRequest(NULL), + icapReply(NULL), + attempts(0), connection(-1), + theService(aService), 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 & Adaptation::Icap::Xaction::service() { - Adaptation::Icap::ServiceRep *s = dynamic_cast(&Initiate::service()); - Must(s); - return *s; + Must(theService != NULL); + return *theService; } 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(); @@ -220,6 +241,7 @@ 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); } @@ -256,6 +278,13 @@ 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()) { @@ -317,6 +346,8 @@ Must(io.flag == COMM_OK); Must(io.size >= 0); + al.icap.bytesRead+=io.size; + updateTimeout(); debugs(93, 3, HERE << "read " << io.size << " bytes"); @@ -397,6 +428,17 @@ } +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. @@ -413,11 +455,56 @@ memFreeBuf(commBufSize, commBuf); if (theInitiator) - tellQueryAborted(!isRetriable); + tellQueryAborted(); + + maybeLog(); Adaptation::Initiate::swanSong(); } +void Adaptation::Icap::Xaction::tellQueryAborted() { + Adaptation::Icap::Launcher *l = dynamic_cast(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 { diff -u -r -N squid-3.1.0.10/src/adaptation/icap/Xaction.h squid-3.1.0.11/src/adaptation/icap/Xaction.h --- squid-3.1.0.10/src/adaptation/icap/Xaction.h 2009-07-18 16:16:23.000000000 +1200 +++ squid-3.1.0.11/src/adaptation/icap/Xaction.h 2009-07-19 17:11:13.000000000 +1200 @@ -39,6 +39,7 @@ #include "MemBuf.h" #include "adaptation/icap/ServiceRep.h" #include "adaptation/Initiate.h" +#include "AccessLogEntry.h" class HttpMsg; class CommConnectCbParams; @@ -65,6 +66,9 @@ 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); @@ -73,6 +77,13 @@ 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 @@ -113,13 +124,23 @@ // 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 + Adaptation::Icap::ServiceRep::Pointer theService; /* * We have two read buffers. We would prefer to read directly @@ -137,7 +158,8 @@ 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; @@ -148,6 +170,12 @@ 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); }; diff -u -r -N squid-3.1.0.10/src/adaptation/Initiate.cc squid-3.1.0.11/src/adaptation/Initiate.cc --- squid-3.1.0.10/src/adaptation/Initiate.cc 2009-07-18 16:16:22.000000000 +1200 +++ squid-3.1.0.11/src/adaptation/Initiate.cc 2009-07-19 17:11:12.000000000 +1200 @@ -4,7 +4,6 @@ #include "squid.h" #include "HttpMsg.h" -#include "adaptation/Service.h" #include "adaptation/Initiator.h" #include "adaptation/Initiate.h" @@ -30,11 +29,9 @@ /* Initiate */ -Adaptation::Initiate::Initiate(const char *aTypeName, - Initiator *anInitiator, ServicePointer aService): - AsyncJob(aTypeName), theInitiator(anInitiator), theService(aService) +Adaptation::Initiate::Initiate(const char *aTypeName, Initiator *anInitiator): + AsyncJob(aTypeName), theInitiator(anInitiator) { - assert(theService != NULL); assert(theInitiator); } @@ -84,13 +81,6 @@ clearInitiator(); } -Adaptation::Service & -Adaptation::Initiate::service() -{ - assert(theService != NULL); - return *theService; -} - const char *Adaptation::Initiate::status() const { return AsyncJob::status(); // for now diff -u -r -N squid-3.1.0.10/src/adaptation/Initiate.h squid-3.1.0.11/src/adaptation/Initiate.h --- squid-3.1.0.10/src/adaptation/Initiate.h 2009-07-18 16:16:22.000000000 +1200 +++ squid-3.1.0.11/src/adaptation/Initiate.h 2009-07-19 17:11:12.000000000 +1200 @@ -32,6 +32,7 @@ bool isThere(); // we have a valid initiator pointer Initiator *ptr(); // asserts isThere() + void *theCbdata() { return cbdata;} private: InitiatorHolder &operator =(const InitiatorHolder &anInitiator); @@ -55,15 +56,13 @@ { public: - Initiate(const char *aTypeName, Initiator *anInitiator, ServicePointer aService); + Initiate(const char *aTypeName, Initiator *anInitiator); virtual ~Initiate(); // communication with the initiator virtual void noteInitiatorAborted() = 0; protected: - Service &service(); - void sendAnswer(HttpMsg *msg); // send to the initiator void tellQueryAborted(bool final); // tell initiator void clearInitiator(); // used by noteInitiatorAborted; TODO: make private @@ -73,7 +72,10 @@ virtual const char *status() const; // for debugging InitiatorHolder theInitiator; - ServicePointer theService; + +private: + Initiate(const Initiate &); // no definition + Initiate &operator =(const Initiate &); // no definition }; } // namespace Adaptation diff -u -r -N squid-3.1.0.10/src/adaptation/Iterator.cc squid-3.1.0.11/src/adaptation/Iterator.cc --- squid-3.1.0.10/src/adaptation/Iterator.cc 1970-01-01 12:00:00.000000000 +1200 +++ squid-3.1.0.11/src/adaptation/Iterator.cc 2009-07-19 17:11:12.000000000 +1200 @@ -0,0 +1,211 @@ +/* + * DEBUG: section 93 Adaptation + */ + +#include "squid.h" +#include "TextException.h" +#include "HttpRequest.h" +#include "HttpReply.h" +#include "HttpMsg.h" +#include "adaptation/Config.h" +#include "adaptation/Iterator.h" +#include "adaptation/Service.h" +#include "adaptation/ServiceFilter.h" +#include "adaptation/ServiceGroups.h" + + +Adaptation::Iterator::Iterator(Adaptation::Initiator *anInitiator, + HttpMsg *aMsg, HttpRequest *aCause, + const ServiceGroupPointer &aGroup): + AsyncJob("Iterator"), + Adaptation::Initiate("Iterator", anInitiator), + theGroup(aGroup), + theMsg(HTTPMSGLOCK(aMsg)), + theCause(aCause ? HTTPMSGLOCK(aCause) : NULL), + theLauncher(0), + iterations(0), + adapted(false) +{ +} + +Adaptation::Iterator::~Iterator() +{ + assert(!theLauncher); + HTTPMSGUNLOCK(theMsg); + HTTPMSGUNLOCK(theCause); +} + +void Adaptation::Iterator::start() +{ + Adaptation::Initiate::start(); + + thePlan = ServicePlan(theGroup, filter()); + step(); +} + +void Adaptation::Iterator::step() +{ + ++iterations; + debugs(93,5, HERE << '#' << iterations << " plan: " << thePlan); + + Must(!theLauncher); + + if (thePlan.exhausted()) { // nothing more to do + sendAnswer(theMsg); + Must(done()); + return; + } + + if (iterations > Adaptation::Config::service_iteration_limit) { + debugs(93,DBG_CRITICAL, "Adaptation iterations limit (" << + Adaptation::Config::service_iteration_limit << ") exceeded:\n" << + "\tPossible service loop with " << + theGroup->kind << " " << theGroup->id << ", plan=" << thePlan); + throw TexcHere("too many adaptations"); + } + + ServicePointer service = thePlan.current(); + Must(service != NULL); + debugs(93,5, HERE << "using adaptation service: " << service->cfg().key); + + theLauncher = initiateAdaptation( + service->makeXactLauncher(this, theMsg, theCause)); + Must(theLauncher); + Must(!done()); +} + +void Adaptation::Iterator::noteAdaptationAnswer(HttpMsg *aMsg) +{ + // set theCause if we switched to request satisfaction mode + if (!theCause) { // probably sent a request message + if (dynamic_cast(aMsg)) { // we got a response message + if (HttpRequest *cause = dynamic_cast(theMsg)) { + // definately sent request, now use it as the cause + theCause = cause; // moving the lock + theMsg = 0; + debugs(93,3, HERE << "in request satisfaction mode"); + } + } + } + + Must(aMsg); + HTTPMSGUNLOCK(theMsg); + theMsg = HTTPMSGLOCK(aMsg); + adapted = true; + + clearAdaptation(theLauncher); + if (!updatePlan(true)) // do not immediatelly advance the new plan + thePlan.next(filter()); + step(); +} + +void Adaptation::Iterator::noteInitiatorAborted() +{ + announceInitiatorAbort(theLauncher); // propogate to the transaction + clearInitiator(); + mustStop("initiator gone"); +} + +void Adaptation::Iterator::noteAdaptationQueryAbort(bool final) +{ + debugs(93,5, HERE << "final: " << final << " plan: " << thePlan); + clearAdaptation(theLauncher); + updatePlan(false); + + // can we replace the failed service (group-level bypass)? + const bool srcIntact = !theMsg->body_pipe || + !theMsg->body_pipe->consumedSize(); + // can we ignore the failure (compute while thePlan is not exhausted)? + Must(!thePlan.exhausted()); + const bool canIgnore = thePlan.current()->cfg().bypass; + debugs(85,5, HERE << "flags: " << srcIntact << canIgnore << adapted); + + if (srcIntact) { + if (thePlan.replacement(filter()) != NULL) { + debugs(93,3, HERE << "trying a replacement service"); + step(); + return; + } + } + + if (canIgnore && srcIntact && adapted) { + debugs(85,3, HERE << "responding with older adapted msg"); + sendAnswer(theMsg); + mustStop("sent older adapted msg"); + return; + } + + // caller may recover if we can ignore the error and virgin msg is intact + const bool useVirgin = canIgnore && !adapted && srcIntact; + tellQueryAborted(!useVirgin); + mustStop("group failure"); +} + +bool Adaptation::Iterator::doneAll() const +{ + return Adaptation::Initiate::doneAll() && thePlan.exhausted(); +} + +void Adaptation::Iterator::swanSong() +{ + if (theInitiator) + tellQueryAborted(true); // abnormal condition that should not happen + + if (theLauncher) + clearAdaptation(theLauncher); + + Adaptation::Initiate::swanSong(); +} + +bool Adaptation::Iterator::updatePlan(bool adopt) +{ + HttpRequest *r = theCause ? theCause : dynamic_cast(theMsg); + Must(r); + + Adaptation::History::Pointer ah = r->adaptHistory(); + if (!ah) + return false; // the feature is not enabled or is not triggered + + String services; + if (!ah->extractNextServices(services)) { // clears history + debugs(85,9, HERE << "no service-proposed plan received"); + return false; // the service did not provide a new plan + } + + if (!adopt) { + debugs(85,3, HERE << "rejecting service-proposed plan"); + return false; + } + + debugs(85,3, HERE << "retiring old plan: " << thePlan); + theGroup = new DynamicServiceChain(services, theGroup); // refcounted + thePlan = ServicePlan(theGroup, filter()); + debugs(85,3, HERE << "adopted service-proposed plan: " << thePlan); + return true; +} + +Adaptation::ServiceFilter Adaptation::Iterator::filter() const +{ + // the method may differ from theGroup->method due to request satisfaction + Method method = methodNone; + // temporary variables, no locking needed + HttpRequest *req = NULL; + HttpReply *rep = NULL; + + if (HttpRequest *r = dynamic_cast(theMsg)) { + method = methodReqmod; + req = r; + rep = NULL; + } else + if (HttpReply *r = dynamic_cast(theMsg)) { + method = methodRespmod; + req = theCause; + rep = r; + } else { + Must(false); // should not happen + } + + return ServiceFilter(method, theGroup->point, req, rep); +} + +CBDATA_NAMESPACED_CLASS_INIT(Adaptation, Iterator); diff -u -r -N squid-3.1.0.10/src/adaptation/Iterator.h squid-3.1.0.11/src/adaptation/Iterator.h --- squid-3.1.0.10/src/adaptation/Iterator.h 1970-01-01 12:00:00.000000000 +1200 +++ squid-3.1.0.11/src/adaptation/Iterator.h 2009-07-19 17:11:13.000000000 +1200 @@ -0,0 +1,65 @@ +#ifndef SQUID_ADAPTATION__ITERATOR_H +#define SQUID_ADAPTATION__ITERATOR_H + +#include "adaptation/Initiator.h" +#include "adaptation/Initiate.h" +#include "adaptation/ServiceGroups.h" + +namespace Adaptation +{ + +/* Iterator is started by client or server Initiators. It iterates services + in a given group, starting transaction launcher for each service, according + to the service plan. Service plans support adaptation sets and chains. + + Note: Initiate must be the first parent for cbdata to work. We use + a temporary InitiatorHolder/toCbdata hacks and do not call cbdata + operations on the initiator directly. +*/ + +/// iterates services in ServiceGroup, starting adaptation launchers +class Iterator: public Initiate, public Initiator +{ +public: + Iterator(Adaptation::Initiator *anInitiator, + HttpMsg *virginHeader, HttpRequest *virginCause, + const Adaptation::ServiceGroupPointer &aGroup); + virtual ~Iterator(); + + // Adaptation::Initiate: asynchronous communication with the initiator + void noteInitiatorAborted(); + + // Adaptation::Initiator: asynchronous communication with the current launcher + virtual void noteAdaptationAnswer(HttpMsg *message); + virtual void noteAdaptationQueryAbort(bool final); + +protected: + // Adaptation::Initiate API implementation + virtual void start(); + virtual bool doneAll() const; + virtual void swanSong(); + + /// launches adaptation for the service selected by the plan + void step(); + + /// replace the current group and plan with service-proposed ones if needed + bool updatePlan(bool adopt); // returns true iff the plan was replaced + + /// creates service filter for the current step + ServiceFilter filter() const; + + ServiceGroupPointer theGroup; ///< the service group we are iterating + ServicePlan thePlan; ///< which services to use and in what order + HttpMsg *theMsg; ///< the message being adapted (virgin for each step) + HttpRequest *theCause; ///< the cause of the original virgin message + Adaptation::Initiate *theLauncher; ///< current transaction launcher + int iterations; ///< number of steps initiated + bool adapted; ///< whether the virgin message has been replaced + + CBDATA_CLASS2(Iterator); +}; + +} // namespace Adaptation + + +#endif /* SQUID_ADAPTATION__ITERATOR_H */ diff -u -r -N squid-3.1.0.10/src/adaptation/Makefile.am squid-3.1.0.11/src/adaptation/Makefile.am --- squid-3.1.0.10/src/adaptation/Makefile.am 2009-07-18 16:16:22.000000000 +1200 +++ squid-3.1.0.11/src/adaptation/Makefile.am 2009-07-19 17:11:13.000000000 +1200 @@ -29,6 +29,8 @@ Initiate.h \ Initiator.cc \ Initiator.h \ + Iterator.cc \ + Iterator.h \ Message.cc \ Message.h \ Service.cc \ @@ -36,7 +38,11 @@ ServiceConfig.cc \ ServiceConfig.h \ ServiceGroups.cc \ - ServiceGroups.h + ServiceGroups.h \ + ServiceFilter.cc \ + ServiceFilter.h \ + History.cc \ + History.h # add libraries for specific adaptation schemes libadaptation_la_LIBADD = @ECAP_LIBS@ @ECAPLIB@ @ICAP_LIBS@ diff -u -r -N squid-3.1.0.10/src/adaptation/Makefile.in squid-3.1.0.11/src/adaptation/Makefile.in --- squid-3.1.0.10/src/adaptation/Makefile.in 2009-07-18 16:16:48.000000000 +1200 +++ squid-3.1.0.11/src/adaptation/Makefile.in 2009-07-19 17:11:34.000000000 +1200 @@ -48,8 +48,9 @@ CONFIG_CLEAN_FILES = LTLIBRARIES = $(noinst_LTLIBRARIES) am_libadaptation_la_OBJECTS = AccessCheck.lo AccessRule.lo Config.lo \ - Elements.lo Initiate.lo Initiator.lo Message.lo Service.lo \ - ServiceConfig.lo ServiceGroups.lo + Elements.lo Initiate.lo Initiator.lo Iterator.lo Message.lo \ + Service.lo ServiceConfig.lo ServiceGroups.lo ServiceFilter.lo \ + History.lo libadaptation_la_OBJECTS = $(am_libadaptation_la_OBJECTS) DEFAULT_INCLUDES = depcomp = $(SHELL) $(top_srcdir)/cfgaux/depcomp @@ -287,6 +288,8 @@ Initiate.h \ Initiator.cc \ Initiator.h \ + Iterator.cc \ + Iterator.h \ Message.cc \ Message.h \ Service.cc \ @@ -294,7 +297,11 @@ ServiceConfig.cc \ ServiceConfig.h \ ServiceGroups.cc \ - ServiceGroups.h + ServiceGroups.h \ + ServiceFilter.cc \ + ServiceFilter.h \ + History.cc \ + History.h # add libraries for specific adaptation schemes @@ -362,11 +369,14 @@ @AMDEP_TRUE@@am__include@ @am__quote@./$(DEPDIR)/AccessRule.Plo@am__quote@ @AMDEP_TRUE@@am__include@ @am__quote@./$(DEPDIR)/Config.Plo@am__quote@ @AMDEP_TRUE@@am__include@ @am__quote@./$(DEPDIR)/Elements.Plo@am__quote@ +@AMDEP_TRUE@@am__include@ @am__quote@./$(DEPDIR)/History.Plo@am__quote@ @AMDEP_TRUE@@am__include@ @am__quote@./$(DEPDIR)/Initiate.Plo@am__quote@ @AMDEP_TRUE@@am__include@ @am__quote@./$(DEPDIR)/Initiator.Plo@am__quote@ +@AMDEP_TRUE@@am__include@ @am__quote@./$(DEPDIR)/Iterator.Plo@am__quote@ @AMDEP_TRUE@@am__include@ @am__quote@./$(DEPDIR)/Message.Plo@am__quote@ @AMDEP_TRUE@@am__include@ @am__quote@./$(DEPDIR)/Service.Plo@am__quote@ @AMDEP_TRUE@@am__include@ @am__quote@./$(DEPDIR)/ServiceConfig.Plo@am__quote@ +@AMDEP_TRUE@@am__include@ @am__quote@./$(DEPDIR)/ServiceFilter.Plo@am__quote@ @AMDEP_TRUE@@am__include@ @am__quote@./$(DEPDIR)/ServiceGroups.Plo@am__quote@ .cc.o: diff -u -r -N squid-3.1.0.10/src/adaptation/Service.cc squid-3.1.0.11/src/adaptation/Service.cc --- squid-3.1.0.10/src/adaptation/Service.cc 2009-07-18 16:16:22.000000000 +1200 +++ squid-3.1.0.11/src/adaptation/Service.cc 2009-07-19 17:11:13.000000000 +1200 @@ -3,6 +3,8 @@ */ #include "squid.h" +#include "HttpRequest.h" +#include "adaptation/ServiceFilter.h" #include "adaptation/Service.h" Adaptation::Service::Service(const ServiceConfig &aConfig): theConfig(aConfig) @@ -23,6 +25,32 @@ return probed() && !up(); } +bool +Adaptation::Service::wants(const ServiceFilter &filter) const +{ + if (cfg().method != filter.method) + return false; + + if (cfg().point != filter.point) + return false; + + // sending a message to a broken service is likely to cause errors + if (cfg().bypass && broken()) + return false; + + if (up()) { + // Sending a message to a service that does not want it is useless. + // note that we cannot check wantsUrl for service that is not "up" + // note that even essential services are skipped on unwanted URLs! + return wantsUrl(filter.request->urlpath); + } + + // The service is down and is either not bypassable or not probed due + // to the bypass && broken() test above. Thus, we want to use it! + return true; +} + + Adaptation::Services & Adaptation::AllServices() { diff -u -r -N squid-3.1.0.10/src/adaptation/ServiceConfig.cc squid-3.1.0.11/src/adaptation/ServiceConfig.cc --- squid-3.1.0.10/src/adaptation/ServiceConfig.cc 2009-07-18 16:16:22.000000000 +1200 +++ squid-3.1.0.11/src/adaptation/ServiceConfig.cc 2009-07-19 17:11:13.000000000 +1200 @@ -7,7 +7,8 @@ #include "adaptation/ServiceConfig.h" Adaptation::ServiceConfig::ServiceConfig(): - port(-1), method(methodNone), point(pointNone), bypass(false) + port(-1), method(methodNone), point(pointNone), + bypass(false), routing(false) {} const char * @@ -59,23 +60,85 @@ ConfigParser::ParseString(&key); ConfigParser::ParseString(&method_point); - ConfigParser::ParseBool(&bypass); - ConfigParser::ParseString(&uri); - - debugs(3, 5, HERE << cfg_filename << ':' << config_lineno << ": " << - key << " " << method_point << " " << bypass); - method = parseMethod(method_point); point = parseVectPoint(method_point); - debugs(3, 5, HERE << cfg_filename << ':' << config_lineno << ": " << - "service_configConfig is " << methodStr() << "_" << vectPointStr()); + // reset optional parameters in case we are reconfiguring + bypass = routing = false; + + // handle optional service name=value parameters + const char *lastOption = NULL; + while (char *option = strtok(NULL, w_space)) { + if (strcmp(option, "0") == 0) { // backward compatibility + bypass = false; + continue; + } + if (strcmp(option, "1") == 0) { // backward compatibility + bypass = true; + continue; + } + + const char *name = option; + char *value = strstr(option, "="); + if (!value) { + lastOption = option; + break; + } + *value = '\0'; // terminate option name + ++value; // skip '=' + + // TODO: warn if option is set twice? + bool grokked = false; + if (strcmp(name, "bypass") == 0) + grokked = grokBool(bypass, name, value); + else + if (strcmp(name, "routing") == 0) + grokked = grokBool(routing, name, value); + else { + debugs(3, 0, cfg_filename << ':' << config_lineno << ": " << + "unknown adaptation service option: " << name << '=' << value); + } + if (!grokked) + return false; + } + + // what is left must be the service URI + if (!grokUri(lastOption)) + return false; + + // there should be nothing else left + if (const char *tail = strtok(NULL, w_space)) { + debugs(3, 0, cfg_filename << ':' << config_lineno << ": " << + "garbage after adaptation service URI: " << tail); + return false; + } + debugs(3,5, cfg_filename << ':' << config_lineno << ": " << + "adaptation_service " << key << ' ' << + methodStr() << "_" << vectPointStr() << ' ' << + bypass << routing << ' ' << + uri); + + return true; +} + +bool +Adaptation::ServiceConfig::grokUri(const char *value) +{ // TODO: find core code that parses URLs and extracts various parts + if (!value || !*value) { + debugs(3, 0, HERE << cfg_filename << ':' << config_lineno << ": " << + "empty adaptation service URI"); + return false; + } + + uri = value; + // extract scheme and use it as the service_configConfig protocol const char *schemeSuffix = "://"; - if (const String::size_type schemeEnd=uri.find(schemeSuffix)) + const String::size_type schemeEnd = uri.find(schemeSuffix); + if (schemeEnd != String::npos) protocol=uri.substr(0,schemeEnd); debugs(3, 5, HERE << cfg_filename << ':' << config_lineno << ": " << @@ -138,10 +201,22 @@ } resource.limitInit(s, len + 1); + return true; +} + - if ((bypass != 0) && (bypass != 1)) { +bool +Adaptation::ServiceConfig::grokBool(bool &var, const char *name, const char *value) +{ + if (!strcmp(value, "0") || !strcmp(value, "off")) + var = false; + else + if (!strcmp(value, "1") || !strcmp(value, "on")) + var = true; + else { debugs(3, 0, HERE << cfg_filename << ':' << config_lineno << ": " << - "wrong bypass value; 0 or 1 expected: " << bypass); + "wrong value for boolean " << name << "; " << + "'0', '1', 'on', or 'off' expected but got: " << value); return false; } diff -u -r -N squid-3.1.0.10/src/adaptation/ServiceConfig.h squid-3.1.0.11/src/adaptation/ServiceConfig.h --- squid-3.1.0.10/src/adaptation/ServiceConfig.h 2009-07-18 16:16:22.000000000 +1200 +++ squid-3.1.0.11/src/adaptation/ServiceConfig.h 2009-07-19 17:11:13.000000000 +1200 @@ -32,10 +32,15 @@ Method method; // what is being adapted (REQMOD vs RESPMOD) VectPoint point; // where the adaptation happens (pre- or post-cache) bool bypass; + bool routing; ///< whether this service may determine the next service(s) protected: Method parseMethod(const char *buf) const; VectPoint parseVectPoint(const char *buf) const; + + /// interpret parsed values + bool grokBool(bool &var, const char *name, const char *value); + bool grokUri(const char *value); }; } // namespace Adaptation diff -u -r -N squid-3.1.0.10/src/adaptation/ServiceFilter.cc squid-3.1.0.11/src/adaptation/ServiceFilter.cc --- squid-3.1.0.10/src/adaptation/ServiceFilter.cc 1970-01-01 12:00:00.000000000 +1200 +++ squid-3.1.0.11/src/adaptation/ServiceFilter.cc 2009-07-19 17:11:13.000000000 +1200 @@ -0,0 +1,40 @@ +#include "squid.h" +#include "HttpRequest.h" +#include "HttpReply.h" +#include "adaptation/ServiceFilter.h" + + +Adaptation::ServiceFilter::ServiceFilter(Method aMethod, VectPoint aPoint, +HttpRequest *aReq, HttpReply *aRep): method(aMethod), point(aPoint), + request(HTTPMSGLOCK(aReq)), + reply(aRep ? HTTPMSGLOCK(aRep) : NULL) +{ + // a lot of code assumes that there is always a virgin request or cause + assert(request); +} + +Adaptation::ServiceFilter::ServiceFilter(const ServiceFilter &f): + method(f.method), point(f.point), + request(HTTPMSGLOCK(f.request)), + reply(f.reply ? HTTPMSGLOCK(f.reply) : NULL) +{ +} + +Adaptation::ServiceFilter::~ServiceFilter() +{ + HTTPMSGUNLOCK(request); + HTTPMSGUNLOCK(reply); +} + +Adaptation::ServiceFilter &Adaptation::ServiceFilter::operator =(const ServiceFilter &f) +{ + if (this != &f) { + method = f.method; + point = f.point; + HTTPMSGUNLOCK(request); + HTTPMSGUNLOCK(reply); + request = HTTPMSGLOCK(f.request); + reply = f.reply ? HTTPMSGLOCK(f.reply) : NULL; + } + return *this; +} diff -u -r -N squid-3.1.0.10/src/adaptation/ServiceFilter.h squid-3.1.0.11/src/adaptation/ServiceFilter.h --- squid-3.1.0.10/src/adaptation/ServiceFilter.h 1970-01-01 12:00:00.000000000 +1200 +++ squid-3.1.0.11/src/adaptation/ServiceFilter.h 2009-07-19 17:11:13.000000000 +1200 @@ -0,0 +1,31 @@ +#ifndef SQUID_ADAPTATION__SERVICE_FILTER_H +#define SQUID_ADAPTATION__SERVICE_FILTER_H + +#include "adaptation/Elements.h" + +class HttpRequest; +class HttpReply; + +namespace Adaptation +{ + +/// information used to search for adaptation services +class ServiceFilter +{ +public: + ServiceFilter(Method, VectPoint, HttpRequest *, HttpReply *); // locks + ServiceFilter(const ServiceFilter &f); + ~ServiceFilter(); // unlocks + + ServiceFilter &operator =(const ServiceFilter &f); + +public: + Method method; ///< adaptation direction + VectPoint point; ///< adaptation location + HttpRequest *request; ///< HTTP request being adapted or cause; may be nil + HttpReply *reply; ///< HTTP response being adapted; may be nil +}; + +} // namespace Adaptation + +#endif /* SQUID_ADAPTATION__SERVICE_FILTER_H */ diff -u -r -N squid-3.1.0.10/src/adaptation/ServiceGroups.cc squid-3.1.0.11/src/adaptation/ServiceGroups.cc --- squid-3.1.0.10/src/adaptation/ServiceGroups.cc 2009-07-18 16:16:22.000000000 +1200 +++ squid-3.1.0.11/src/adaptation/ServiceGroups.cc 2009-07-19 17:11:13.000000000 +1200 @@ -5,10 +5,14 @@ #include "adaptation/Config.h" #include "adaptation/AccessRule.h" #include "adaptation/Service.h" +#include "adaptation/ServiceFilter.h" #include "adaptation/ServiceGroups.h" +#define ServiceGroup ServiceGroup -Adaptation::ServiceGroup::ServiceGroup(const String &aKind): kind(aKind) +Adaptation::ServiceGroup::ServiceGroup(const String &aKind, bool allSame): + kind(aKind), method(methodNone), point(pointNone), + allServicesSame(allSame) { } @@ -28,57 +32,252 @@ wordlistDestroy(&names); } +// Note: configuration code aside, this method is called by DynamicServiceChain void Adaptation::ServiceGroup::finalize() { - for (iterator i = services.begin(); i != services.end(); ++i) { - const String &id = *i; - // TODO: fail on failures - if (!FindService(id)) - debugs(93,0, "ERROR: Unknown adaptation name: " << id); + // 1) warn if services have different methods or vectoring point + // 2) warn if all-same services have different bypass status + // 3) warn if there are seemingly identical services in the group + // TODO: optimize by remembering ServicePointers rather than IDs + + String baselineKey; + bool baselineBypass = false; + for (Pos pos = 0; has(pos); ++pos) { + // TODO: quit on all errors + const String &sid = services[pos]; + ServicePointer service = at(pos); + if (service != NULL) { + if (method == methodNone) { + // optimization: cache values that should be the same + method = service->cfg().method; + point = service->cfg().point; + } else { + if (method != service->cfg().method) + finalizeMsg("Inconsistent service method for", sid, true); + if (point != service->cfg().point) + finalizeMsg("Inconsistent vectoring point for", sid, true); + } + + checkUniqueness(pos); + + if (allServicesSame) { + if (!baselineKey.size()) { + baselineKey = service->cfg().key; + baselineBypass = service->cfg().bypass; + } else + if (baselineBypass != service->cfg().bypass) { + debugs(93,0, "WARNING: Inconsistent bypass in " << kind << + ' ' << id << " may produce surprising results: " << + baselineKey << " vs. " << sid); + } + } + } else { + finalizeMsg("ERROR: Unknown adaptation name", sid, true); + } } debugs(93,7, HERE << "finalized " << kind << ": " << id); } -/* ServiceSet */ +/// checks that the service name or URI is not repeated later in the group +void +Adaptation::ServiceGroup::checkUniqueness(const Pos checkedPos) const +{ + ServicePointer checkedService = at(checkedPos); + if (!checkedService) // should not happen but be robust + return; + + for (Pos p = checkedPos + 1; has(p); ++p) { + ServicePointer s = at(p); + if (s != NULL && s->cfg().key == checkedService->cfg().key) + finalizeMsg("duplicate service name", s->cfg().key, false); + else + if (s != NULL && s->cfg().uri == checkedService->cfg().uri) + finalizeMsg("duplicate service URI", s->cfg().uri, false); + } +} -Adaptation::ServiceSet::ServiceSet(): ServiceGroup("adaptation set") +/// emits a formatted warning or error message at the appropriate dbg level +void +Adaptation::ServiceGroup::finalizeMsg(const char *msg, const String &culprit, + bool error) const { + const int level = error ? DBG_CRITICAL : DBG_IMPORTANT; + const char *pfx = error ? "ERROR: " : "WARNING: "; + debugs(93,level, pfx << msg << ' ' << culprit << " in " << kind << " '" << + id << "'"); +} + +Adaptation::ServicePointer Adaptation::ServiceGroup::at(const Pos pos) const { + return FindService(services[pos]); } -Adaptation::ServiceGroup::Loop Adaptation::ServiceSet::initialServices() +/// \todo: optimize to cut search short instead of looking for the best svc +bool +Adaptation::ServiceGroup::wants(const ServiceFilter &filter) const { - return Loop(services.begin(), services.end()); + Pos pos = 0; + return findService(filter, pos); } -#if FUTURE_OPTIMIZATION -void -Adaptation::ServiceSet::finalize() +bool +Adaptation::ServiceGroup::findService(const ServiceFilter &filter, Pos &pos) const { - ServiceGroup::finalize(); + if (method != filter.method || point != filter.point) { + debugs(93,5,HERE << id << " serves another location"); + return false; // assume other services have the same wrong location + } - for (wordlist *iter = service_names; iter; iter = iter->next) { - ServicePointer match = Config::FindService(iter->id); - if (match != NULL) - services += match; + // find the next interested service, skipping problematic ones if possible + bool foundEssential = false; + Pos essPos = 0; + for (; has(pos); ++pos) { + debugs(93,9,HERE << id << " checks service at " << pos); + ServicePointer service = at(pos); + + if (!service) + continue; // the service was lost due to reconfiguration + + if (!service->wants(filter)) + continue; // the service is not interested + + if (service->up() || !service->probed()) { + debugs(93,9,HERE << id << " has matching service at " << pos); + return true; + } + + if (service->cfg().bypass) { // we can safely ignore bypassable downers + debugs(93,9,HERE << id << " has bypassable service at " << pos); + continue; + } + + if (!allServicesSame) { // cannot skip (i.e., find best) service + debugs(93,9,HERE << id << " has essential service at " << pos); + return true; + } + + if (!foundEssential) { + debugs(93,9,HERE << id << " searches for best essential service from " << pos); + foundEssential = true; + essPos = pos; + } } + + if (foundEssential) { + debugs(93,9,HERE << id << " has best essential service at " << essPos); + pos = essPos; + return true; + } + + debugs(93,5,HERE << id << " has no matching services"); + return false; +} + +bool +Adaptation::ServiceGroup::findReplacement(const ServiceFilter &filter, Pos &pos) const +{ + return allServicesSame && findService(filter, pos); +} + +bool +Adaptation::ServiceGroup::findLink(const ServiceFilter &filter, Pos &pos) const +{ + return !allServicesSame && findService(filter, pos); +} + + +/* ServiceSet */ + +Adaptation::ServiceSet::ServiceSet(): ServiceGroup("adaptation set", true) +{ } -#endif /* SingleService */ Adaptation::SingleService::SingleService(const String &aServiceId): - ServiceGroup("single-service group") + ServiceGroup("single-service group", false) { id = aServiceId; services.push_back(aServiceId); } -Adaptation::ServiceGroup::Loop -Adaptation::SingleService::initialServices() + +/* ServiceChain */ + +Adaptation::ServiceChain::ServiceChain(): ServiceGroup("adaptation chain", false) +{ +} + + +/* ServiceChain */ + +Adaptation::DynamicServiceChain::DynamicServiceChain(const String &ids, + const ServiceGroupPointer prev) +{ + kind = "dynamic adaptation chain"; // TODO: optimize by using String const + id = ids; // use services ids as the dynamic group ID + + // initialize cache to improve consistency checks in finalize() + if (prev != NULL) { + method = prev->method; + point = prev->point; + } + + // populate services storage with supplied service ids + const char *item = NULL; + int ilen = 0; + const char *pos = NULL; + while (strListGetItem(&ids, ',', &item, &ilen, &pos)) + services.push_back(item); + + finalize(); // will report [dynamic] config errors +} + +/* ServicePlan */ + +Adaptation::ServicePlan::ServicePlan(): pos(0), atEof(true) { - return Loop(services.begin(), services.end()); // there should be only one +} + +Adaptation::ServicePlan::ServicePlan(const ServiceGroupPointer &g, + const ServiceFilter &filter): + group(g), pos(0), atEof(!g || !g->has(pos)) +{ + // this will find the first service because starting pos is zero + if (!atEof && !group->findService(filter, pos)) + atEof = true; +} + +Adaptation::ServicePointer +Adaptation::ServicePlan::current() const +{ + // may return NULL even if not atEof + return atEof ? Adaptation::ServicePointer() : group->at(pos); +} + +Adaptation::ServicePointer +Adaptation::ServicePlan::replacement(const ServiceFilter &filter) { + if (!atEof && !group->findReplacement(filter, ++pos)) + atEof = true; + return current(); +} + +Adaptation::ServicePointer +Adaptation::ServicePlan::next(const ServiceFilter &filter) { + if (!atEof && !group->findLink(filter, ++pos)) + atEof = true; + return current(); +} + +std::ostream & +Adaptation::ServicePlan::print(std::ostream &os) const +{ + if (!group) + return os << "[nil]"; + + return os << group->id << '[' << pos << ".." << group->services.size() << + (atEof ? ".]" : "]"); } @@ -91,7 +290,7 @@ return TheGroups; } -Adaptation::ServiceGroup * +Adaptation::ServiceGroupPointer Adaptation::FindGroup(const ServiceGroup::Id &id) { typedef Groups::iterator GI; diff -u -r -N squid-3.1.0.10/src/adaptation/ServiceGroups.h squid-3.1.0.11/src/adaptation/ServiceGroups.h --- squid-3.1.0.10/src/adaptation/ServiceGroups.h 2009-07-18 16:16:22.000000000 +1200 +++ squid-3.1.0.11/src/adaptation/ServiceGroups.h 2009-07-19 17:11:13.000000000 +1200 @@ -3,6 +3,8 @@ #include "SquidString.h" #include "Array.h" +#include "RefCount.h" +#include "adaptation/Elements.h" #include "adaptation/forward.h" namespace Adaptation @@ -10,36 +12,55 @@ // Interface for grouping adaptation services together. // Specific groups differ in how the first and the next services are selected -class ServiceGroup +class ServiceGroup: public RefCountable { public: + typedef RefCount Pointer; + typedef Vector Store; - typedef Store::iterator iterator; typedef String Id; - - // Information sufficient to iterate services stored in the group, - // grouped together to simplify initial/sequentialServices interfaces. - // The iterators point back to - struct Loop { - Loop(const iterator &b, const iterator &e): begin(b), end(e) {} - iterator begin; - iterator end; - }; + typedef unsigned int Pos; // Vector<>::poistion_type + friend class ServicePlan; public: - ServiceGroup(const String &aKind); + ServiceGroup(const String &aKind, bool areAllServicesSame); virtual ~ServiceGroup(); virtual void parse(); virtual void finalize(); // called after all are parsed - virtual Loop initialServices() = 0; - // TODO: virtual Loop sequentialServices() = 0; + bool wants(const ServiceFilter &filter) const; + +protected: + ///< whether this group has a service at the specified pos + bool has(const Pos pos) const { + // does not check that the service at pos still exists + return pos < services.size(); // unsigned pos is never negative + } + + /// these methods control group iteration; used by ServicePlan + + /// find next to try after failure, starting with pos + bool findReplacement(const ServiceFilter &filter, Pos &pos) const; + /// find next to link after success, starting with pos + bool findLink(const ServiceFilter &filter, Pos &pos) const; + +private: + ServicePointer at(const Pos pos) const; + bool findService(const ServiceFilter &filter, Pos &pos) const; + + void checkUniqueness(const Pos checkedPos) const; + void finalizeMsg(const char *msg, const String &culprit, bool error) const; public: String kind; Id id; Store services; + + Method method; /// based on the first added service + VectPoint point; /// based on the first added service + + const bool allServicesSame; // whether we can freely substitute services }; // a group of equivalent services; one service per set is usually used @@ -47,7 +68,10 @@ { public: ServiceSet(); - virtual Loop initialServices(); + +protected: + virtual bool replace(Pos &pos) const { return has(++pos); } + virtual bool advance(Pos &pos) const { return false; } }; // corner case: a group consisting of one service @@ -55,16 +79,66 @@ { public: SingleService(const String &aServiceKey); - virtual Loop initialServices(); + +protected: + virtual bool replace(Pos &pos) const { return false; } + virtual bool advance(Pos &pos) const { return false; } }; -// TODO: a group of services that must be used one after another -// class ServiceChain: public ServiceGroup +/// a group of services that must be used one after another +class ServiceChain: public ServiceGroup +{ +public: + ServiceChain(); + +protected: + virtual bool replace(Pos &pos) const { return false; } + virtual bool advance(Pos &pos) const { return has(++pos); } +}; +/// a temporary service chain built upon another service request +class DynamicServiceChain: public ServiceChain +{ +public: + DynamicServiceChain(const String &srvcs, const ServiceGroupPointer prev); +}; + + +/** iterates services stored in a group; iteration is not linear because we + need to both replace failed services and advance to the next chain link */ +class ServicePlan { +public: + typedef unsigned int Pos; // Vector<>::poistion_type + +public: + ServicePlan(); + explicit ServicePlan(const ServiceGroupPointer &g, const ServiceFilter &filter); + + ///< true iff there are no more services planned + bool exhausted() const { return atEof; } + + /// returns nil if the plan is complete + ServicePointer current() const; ///< current service + ServicePointer replacement(const ServiceFilter &filter); ///< next to try after failure + ServicePointer next(const ServiceFilter &filter); ///< next in chain after success + + std::ostream &print(std::ostream &os) const; + +private: + ServiceGroupPointer group; ///< the group we are iterating + Pos pos; ///< current service position within the group + bool atEof; ///< cached information for better performance +}; + +inline +std::ostream &operator <<(std::ostream &os, const ServicePlan &p) +{ + return p.print(os); +} -typedef Vector Groups; +typedef Vector Groups; extern Groups &AllGroups(); -extern ServiceGroup *FindGroup(const ServiceGroup::Id &id); +extern ServiceGroupPointer FindGroup(const ServiceGroup::Id &id); } // namespace Adaptation diff -u -r -N squid-3.1.0.10/src/adaptation/Service.h squid-3.1.0.11/src/adaptation/Service.h --- squid-3.1.0.10/src/adaptation/Service.h 2009-07-18 16:16:22.000000000 +1200 +++ squid-3.1.0.11/src/adaptation/Service.h 2009-07-19 17:11:13.000000000 +1200 @@ -39,6 +39,8 @@ typedef void Callback(void *data, Pointer &service); void callWhenReady(Callback *cb, void *data); + bool wants(const ServiceFilter &filter) const; + // the methods below can only be called on an up() service virtual bool wantsUrl(const String &urlPath) const = 0; diff -u -r -N squid-3.1.0.10/src/cache_cf.cc squid-3.1.0.11/src/cache_cf.cc --- squid-3.1.0.10/src/cache_cf.cc 2009-07-18 16:16:24.000000000 +1200 +++ squid-3.1.0.11/src/cache_cf.cc 2009-07-19 17:11:13.000000000 +1200 @@ -65,6 +65,7 @@ #include "adaptation/Config.h" static void parse_adaptation_service_set_type(); +static void parse_adaptation_service_chain_type(); static void parse_adaptation_access_type(); #endif @@ -3432,6 +3433,10 @@ 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(); @@ -3484,7 +3489,11 @@ 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) @@ -3545,6 +3554,12 @@ } static void +parse_adaptation_service_chain_type() +{ + Adaptation::Config::ParseServiceChain(); +} + +static void parse_adaptation_access_type() { Adaptation::Config::ParseAccess(LegacyParser); diff -u -r -N squid-3.1.0.10/src/cf.data.depend squid-3.1.0.11/src/cf.data.depend --- squid-3.1.0.10/src/cf.data.depend 2009-07-18 16:16:24.000000000 +1200 +++ squid-3.1.0.11/src/cf.data.depend 2009-07-19 17:11:13.000000000 +1200 @@ -25,8 +25,9 @@ http_header_replace http_port_list https_port_list -adaptation_access_type adaptation_service_set acl icap_service icap_class -adaptation_service_set_type icap_service +adaptation_access_type adaptation_service_set adaptation_service_chain acl icap_service icap_class +adaptation_service_set_type icap_service ecap_service +adaptation_service_chain_type icap_service ecap_service icap_access_type icap_class acl icap_class_type icap_service icap_service_type diff -u -r -N squid-3.1.0.10/src/cf.data.pre squid-3.1.0.11/src/cf.data.pre --- squid-3.1.0.10/src/cf.data.pre 2009-07-18 16:16:24.000000000 +1200 +++ squid-3.1.0.11/src/cf.data.pre 2009-07-19 17:11:13.000000000 +1200 @@ -2365,6 +2365,7 @@ Format codes: + % a literal % character >a Client source IP address >A Client FQDN >p Client source port @@ -2374,42 +2375,96 @@ 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 - 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 Request size including HTTP headers - st Request+Reply size including HTTP headers - h Request header. Optional header name argument + on the format header[:[separator]element] + [http::]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::]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::]a %Ss/%03Hs %a %Ss/%03Hs %h] [%a %ui %un [%tl] "%rm %ru HTTP/%rv" %Hs %a %ui %un [%tl] "%rm %ru HTTP/%rv" %Hs %h" "%{User-Agent}>h" %Ss:%Sh +logformat squid %ts.%03tu %6tr %>a %Ss/%03>Hs %a %Ss/%03>Hs %h] [%a %ui %un [%tl] "%rm %ru HTTP/%rv" %>Hs %a %ui %un [%tl] "%rm %ru HTTP/%rv" %>Hs %h" "%{User-Agent}>h" %Ss:%Sh DOC_END NAME: access_log cache_access_log @@ -2444,6 +2499,88 @@ 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 [ [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::st Bytes sent to the ICAP server (TCP payload + only; i.e., what Squid writes to the socket). + + icap::h ICAP request header(s). Similar to >h. + + icap::a %icap::to/%03icap::Hs %icap::icapHistory(); +#endif if (Config.onoff.log_mime_hdrs) { Packer p; MemBuf mb; @@ -456,14 +460,31 @@ 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) { @@ -502,8 +523,10 @@ 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; @@ -512,7 +535,7 @@ 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; @@ -1873,6 +1896,18 @@ } } +// 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() * @@ -1885,7 +1920,6 @@ 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; @@ -1952,17 +1986,6 @@ 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. @@ -1982,7 +2005,6 @@ */ 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"); } @@ -1990,6 +2012,35 @@ (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); @@ -2006,6 +2057,17 @@ 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 */ @@ -2157,6 +2219,11 @@ 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; } @@ -2166,8 +2233,13 @@ 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(node->data.getRaw()); assert (repContext); repContext->setReplyToError(ERR_TOO_BIG, @@ -2213,6 +2285,9 @@ 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 */ @@ -2313,8 +2388,17 @@ 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(node->data.getRaw()); assert (repContext); @@ -2648,13 +2732,74 @@ { assert(bodyPipe != NULL); - if (const size_t putSize = bodyPipe->putMoreData(in.buf, in.notYetUsed)) - connNoteUseOfBuffer(this, putSize); + size_t putSize = 0; - if (!bodyPipe->mayNeedMoreData()) { - // BodyPipe will clear us automagically when we produced everything - bodyPipe = NULL; +#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 (malformedChunks) { + if (bodyPipe != NULL) + stopProducingFor(bodyPipe, false); + + ClientSocketContext::Pointer context = getCurrentContext(); + if (!context->http->out.offset) { + clientStreamNode *node = context->getClientReplyContext(); + clientReplyContext *repContext = dynamic_cast(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()) { @@ -3435,19 +3580,121 @@ 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(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() */ diff -u -r -N squid-3.1.0.10/src/client_side.h squid-3.1.0.11/src/client_side.h --- squid-3.1.0.10/src/client_side.h 2009-07-18 16:16:24.000000000 +1200 +++ squid-3.1.0.11/src/client_side.h 2009-07-19 17:11:13.000000000 +1200 @@ -48,6 +48,9 @@ class AuthUserRequest; +class ChunkedCodingParser; +class HttpParser; + template class Range; @@ -144,13 +147,22 @@ 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(); @@ -253,6 +265,10 @@ 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); diff -u -r -N squid-3.1.0.10/src/client_side_request.cc squid-3.1.0.11/src/client_side_request.cc --- squid-3.1.0.10/src/client_side_request.cc 2009-07-18 16:16:24.000000000 +1200 +++ squid-3.1.0.11/src/client_side_request.cc 2009-07-19 17:11:13.000000000 +1200 @@ -59,12 +59,19 @@ #include "SquidTime.h" #include "wordlist.h" #include "inet_pton.h" +#include "fde.h" #if USE_ADAPTATION #include "adaptation/AccessCheck.h" +#include "adaptation/Iterator.h" #include "adaptation/Service.h" -static void adaptationAclCheckDoneWrapper(Adaptation::ServicePointer service, void *data); +#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 @@ -613,34 +620,45 @@ #if USE_ADAPTATION static void -adaptationAclCheckDoneWrapper(Adaptation::ServicePointer service, void *data) +adaptationAclCheckDoneWrapper(Adaptation::ServiceGroupPointer g, void *data) { ClientRequestContext *calloutContext = (ClientRequestContext *)data; if (!calloutContext->httpStateIsValid()) return; - calloutContext->adaptationAclCheckDone(service); + calloutContext->adaptationAclCheckDone(g); } void -ClientRequestContext::adaptationAclCheckDone(Adaptation::ServicePointer service) +ClientRequestContext::adaptationAclCheckDone(Adaptation::ServiceGroupPointer g) { debugs(93,3,HERE << this << " adaptationAclCheckDone called"); assert(http); - if (http->startAdaptation(service)) - return; +#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 (!service || service->cfg().bypass) { - // handle ICAP start failure when no service was selected - // or where the selected service was optional + if (!g) { + debugs(85,3, HERE << "no adaptation needed"); http->doCallouts(); return; } - // handle start failure for an essential ICAP service - http->handleAdaptationFailure(); + http->startAdaptation(g); } #endif @@ -1301,6 +1319,12 @@ 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_ @@ -1308,29 +1332,19 @@ #endif #if USE_ADAPTATION -/* - * Initiate an ICAP transaction. Return false on errors. - * The caller must handle errors. - */ -bool -ClientHttpRequest::startAdaptation(Adaptation::ServicePointer service) +/// Initiate an asynchronous adaptation transaction which will call us back. +void +ClientHttpRequest::startAdaptation(const Adaptation::ServiceGroupPointer &g) { - debugs(85, 3, HERE << this << " ClientHttpRequest::startAdaptation() called"); - if (!service) { - debugs(85, 3, "ClientHttpRequest::startAdaptation fails: lack of service"); - return false; - } - if (service->broken()) { - debugs(85, 3, "ClientHttpRequest::startAdaptation fails: broken service"); - return false; - } - + debugs(85, 3, HERE << "adaptation needed for " << this); assert(!virginHeadSource); assert(!adaptedBodySource); - virginHeadSource = initiateAdaptation(service->makeXactLauncher( - this, request, NULL)); + virginHeadSource = initiateAdaptation( + new Adaptation::Iterator(this, request, NULL, g)); - return virginHeadSource != NULL; + // we could try to guess whether we can bypass this adaptation + // initiation failure, but it should not really happen + assert(virginHeadSource != NULL); // Must, really } void diff -u -r -N squid-3.1.0.10/src/client_side_request.h squid-3.1.0.11/src/client_side_request.h --- squid-3.1.0.10/src/client_side_request.h 2009-07-18 16:16:24.000000000 +1200 +++ squid-3.1.0.11/src/client_side_request.h 2009-07-19 17:11:13.000000000 +1200 @@ -159,7 +159,7 @@ #if USE_ADAPTATION public: - bool startAdaptation(Adaptation::ServicePointer); + void startAdaptation(const Adaptation::ServiceGroupPointer &g); // private but exposed for ClientRequestContext void handleAdaptationFailure(bool bypassable = false); diff -u -r -N squid-3.1.0.10/src/CommCalls.cc squid-3.1.0.11/src/CommCalls.cc --- squid-3.1.0.10/src/CommCalls.cc 2009-07-18 16:16:15.000000000 +1200 +++ squid-3.1.0.11/src/CommCalls.cc 2009-07-19 17:11:08.000000000 +1200 @@ -67,6 +67,13 @@ 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), @@ -150,7 +157,7 @@ void CommConnectCbPtrFun::dial() { - handler(params.fd, params.flag, params.xerrno, params.data); + handler(params.fd, params.dns, params.flag, params.xerrno, params.data); } void diff -u -r -N squid-3.1.0.10/src/CommCalls.h squid-3.1.0.11/src/CommCalls.h --- squid-3.1.0.10/src/CommCalls.h 2009-07-18 16:16:15.000000000 +1200 +++ squid-3.1.0.11/src/CommCalls.h 2009-07-19 17:11:08.000000000 +1200 @@ -8,6 +8,7 @@ #include "comm.h" #include "ConnectionDetail.h" +#include "DnsLookupDetails.h" #include "base/AsyncCall.h" #include "base/AsyncJobCalls.h" @@ -79,6 +80,11 @@ CommConnectCbParams(void *aData); bool syncWithComm(); // see CommCommonCbParams::syncWithComm + + void print(std::ostream &os) const; + +public: + DnsLookupDetails dns; }; // read/write (I/O) parameters diff -u -r -N squid-3.1.0.10/src/comm.cc squid-3.1.0.11/src/comm.cc --- squid-3.1.0.10/src/comm.cc 2009-07-18 16:16:24.000000000 +1200 +++ squid-3.1.0.11/src/comm.cc 2009-07-19 17:11:13.000000000 +1200 @@ -209,6 +209,7 @@ 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; @@ -876,19 +877,13 @@ } 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; } @@ -918,6 +913,7 @@ typedef CommConnectCbParams Params; Params ¶ms = GetCommParams(callback); params.fd = fd; + params.dns = dns; params.flag = status; params.xerrno = xerrno; ScheduleCallHere(callback); diff -u -r -N squid-3.1.0.10/src/comm.h squid-3.1.0.11/src/comm.h --- squid-3.1.0.10/src/comm.h 2009-07-18 16:16:24.000000000 +1200 +++ squid-3.1.0.11/src/comm.h 2009-07-19 17:11:13.000000000 +1200 @@ -27,7 +27,8 @@ #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); diff -u -r -N squid-3.1.0.10/src/dns_internal.cc squid-3.1.0.11/src/dns_internal.cc --- squid-3.1.0.10/src/dns_internal.cc 2009-07-18 16:16:25.000000000 +1200 +++ squid-3.1.0.11/src/dns_internal.cc 2009-07-19 17:11:13.000000000 +1200 @@ -699,7 +699,7 @@ } 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; diff -u -r -N squid-3.1.0.10/src/DnsLookupDetails.cc squid-3.1.0.11/src/DnsLookupDetails.cc --- squid-3.1.0.10/src/DnsLookupDetails.cc 1970-01-01 12:00:00.000000000 +1200 +++ squid-3.1.0.11/src/DnsLookupDetails.cc 2009-07-19 17:11:09.000000000 +1200 @@ -0,0 +1,25 @@ +/* + * 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; +} diff -u -r -N squid-3.1.0.10/src/DnsLookupDetails.h squid-3.1.0.11/src/DnsLookupDetails.h --- squid-3.1.0.10/src/DnsLookupDetails.h 1970-01-01 12:00:00.000000000 +1200 +++ squid-3.1.0.11/src/DnsLookupDetails.h 2009-07-19 17:11:09.000000000 +1200 @@ -0,0 +1,31 @@ +/* + * 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 diff -u -r -N squid-3.1.0.10/src/enums.h squid-3.1.0.11/src/enums.h --- squid-3.1.0.10/src/enums.h 2009-07-18 16:16:25.000000000 +1200 +++ squid-3.1.0.11/src/enums.h 2009-07-19 17:11:13.000000000 +1200 @@ -533,6 +533,9 @@ CLF_CUSTOM, CLF_SQUID, CLF_COMMON, +#if ICAP_CLIENT + CLF_ICAP_SQUID, +#endif CLF_NONE } customlog_type; diff -u -r -N squid-3.1.0.10/src/errorpage.cc squid-3.1.0.11/src/errorpage.cc --- squid-3.1.0.10/src/errorpage.cc 2009-07-18 16:16:25.000000000 +1200 +++ squid-3.1.0.11/src/errorpage.cc 2009-07-19 17:11:13.000000000 +1200 @@ -496,7 +496,6 @@ 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); @@ -536,9 +535,8 @@ 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)); @@ -819,8 +817,8 @@ break; case 'z': - if (dnsserver_msg) - p = dnsserver_msg; + if (dnsError.size() > 0) + p = dnsError.termedBuf(); else p = "[unknown]"; diff -u -r -N squid-3.1.0.10/src/errorpage.h squid-3.1.0.11/src/errorpage.h --- squid-3.1.0.10/src/errorpage.h 2009-07-18 16:16:25.000000000 +1200 +++ squid-3.1.0.11/src/errorpage.h 2009-07-19 17:11:13.000000000 +1200 @@ -120,7 +120,7 @@ char *url; int xerrno; u_short port; - char *dnsserver_msg; + String dnsError; ///< DNS lookup error message time_t ttl; IpAddress src_addr; diff -u -r -N squid-3.1.0.10/src/forward.cc squid-3.1.0.11/src/forward.cc --- squid-3.1.0.10/src/forward.cc 2009-07-18 16:16:26.000000000 +1200 +++ squid-3.1.0.11/src/forward.cc 2009-07-19 17:11:14.000000000 +1200 @@ -375,10 +375,10 @@ #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 @@ -675,11 +675,13 @@ #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(); @@ -697,7 +699,7 @@ ErrorState *anErr = errorCon(ERR_DNS_FAIL, HTTP_SERVICE_UNAVAILABLE, request); - anErr->dnsserver_msg = xstrdup(dns_error_message_safe()); + anErr->dnsError = dns.error; fail(anErr); @@ -778,6 +780,9 @@ 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; @@ -813,7 +818,7 @@ 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 */ diff -u -r -N squid-3.1.0.10/src/forward.h squid-3.1.0.11/src/forward.h --- squid-3.1.0.10/src/forward.h 2009-07-18 16:16:26.000000000 +1200 +++ squid-3.1.0.11/src/forward.h 2009-07-19 17:11:14.000000000 +1200 @@ -37,7 +37,7 @@ 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); diff -u -r -N squid-3.1.0.10/src/fqdncache.cc squid-3.1.0.11/src/fqdncache.cc --- squid-3.1.0.10/src/fqdncache.cc 2009-07-18 16:16:26.000000000 +1200 +++ squid-3.1.0.11/src/fqdncache.cc 2009-07-19 17:11:14.000000000 +1200 @@ -83,9 +83,6 @@ /// \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 @@ -93,7 +90,8 @@ * 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; @@ -111,6 +109,8 @@ unsigned int negcached:1; unsigned int fromhosts:1; } flags; + + int age() const; ///< time passed since request_time or -1 if unknown }; /// \ingroup FQDNCacheInternal @@ -134,7 +134,7 @@ #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 *); @@ -152,6 +152,13 @@ /// \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 @@ -304,7 +311,7 @@ * Walks down the pending list, calling handlers */ static void -fqdncacheCallback(fqdncache_entry * f) +fqdncacheCallback(fqdncache_entry * f, int wait) { FQDNH *callback; void *cbdata; @@ -320,8 +327,8 @@ 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); @@ -490,8 +497,8 @@ fqdncache_entry *f; static_cast(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); @@ -502,7 +509,7 @@ fqdncacheAddEntry(f); - fqdncacheCallback(f); + fqdncacheCallback(f, age); } /** @@ -528,8 +535,8 @@ 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; } @@ -555,7 +562,7 @@ f->handlerData = cbdataReference(handlerData); - fqdncacheCallback(f); + fqdncacheCallback(f, -1); // no lookup return; } @@ -654,16 +661,16 @@ 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++; @@ -732,7 +739,7 @@ /// \ingroup FQDNCacheInternal static void -dummy_handler(const char *bufnotused, void *datanotused) +dummy_handler(const char *, const DnsLookupDetails &, void *) { return; } @@ -932,14 +939,3 @@ } #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"; -} diff -u -r -N squid-3.1.0.10/src/ftp.cc squid-3.1.0.11/src/ftp.cc --- squid-3.1.0.10/src/ftp.cc 2009-07-18 16:16:26.000000000 +1200 +++ squid-3.1.0.11/src/ftp.cc 2009-07-19 17:11:14.000000000 +1200 @@ -2787,10 +2787,11 @@ } 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."); diff -u -r -N squid-3.1.0.10/src/globals.h squid-3.1.0.11/src/globals.h --- squid-3.1.0.10/src/globals.h 2009-07-18 16:16:26.000000000 +1200 +++ squid-3.1.0.11/src/globals.h 2009-07-19 17:11:14.000000000 +1200 @@ -55,7 +55,6 @@ //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]; diff -u -r -N squid-3.1.0.10/src/HierarchyLogEntry.h squid-3.1.0.11/src/HierarchyLogEntry.h --- squid-3.1.0.10/src/HierarchyLogEntry.h 2009-07-18 16:16:17.000000000 +1200 +++ squid-3.1.0.11/src/HierarchyLogEntry.h 2009-07-19 17:11:09.000000000 +1200 @@ -56,6 +56,12 @@ 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 *); diff -u -r -N squid-3.1.0.10/src/http.cc squid-3.1.0.11/src/http.cc --- squid-3.1.0.10/src/http.cc 2009-07-18 16:16:27.000000000 +1200 +++ squid-3.1.0.11/src/http.cc 2009-07-19 17:11:14.000000000 +1200 @@ -87,6 +87,10 @@ readBuf->init(4096, SQUID_TCP_SO_RCVBUF); orig_request = HTTPMSGLOCK(fwd->request); + // reset peer response time stats for %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 */ @@ -732,6 +736,8 @@ * Parse the header and remove all referenced headers */ + orig_request->hier.peer_reply_status = newrep->sline.status; + ctx_exit(ctx); } @@ -1064,6 +1070,11 @@ clen >>= 1; IOStats.Http.read_hist[bin]++; + + // update peer response time stats (%hier.peer_http_request_sent; + orig_request->hier.peer_response_time = + sent.tv_sec ? tvSubMsec(sent, current_time) : -1; } /** \par @@ -1411,6 +1422,8 @@ 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(). diff -u -r -N squid-3.1.0.10/src/HttpHeader.cc squid-3.1.0.11/src/HttpHeader.cc --- squid-3.1.0.10/src/HttpHeader.cc 2009-07-18 16:16:18.000000000 +1200 +++ squid-3.1.0.11/src/HttpHeader.cc 2009-07-19 17:11:09.000000000 +1200 @@ -142,6 +142,9 @@ #if X_ACCELERATOR_VARY {"X-Accelerator-Vary", HDR_X_ACCELERATOR_VARY, ftStr}, #endif +#if USE_ADAPTATION + {"X-Next-Services", HDR_X_NEXT_SERVICES, ftStr}, +#endif {"Surrogate-Capability", HDR_SURROGATE_CAPABILITY, ftStr}, {"Surrogate-Control", HDR_SURROGATE_CONTROL, ftPSc}, {"Front-End-Https", HDR_FRONT_END_HTTPS, ftStr}, @@ -187,6 +190,9 @@ #if X_ACCELERATOR_VARY HDR_X_ACCELERATOR_VARY, #endif +#if USE_ADAPTATION + HDR_X_NEXT_SERVICES, +#endif HDR_SURROGATE_CAPABILITY, HDR_SURROGATE_CONTROL, HDR_X_FORWARDED_FOR @@ -222,6 +228,9 @@ #if X_ACCELERATOR_VARY HDR_X_ACCELERATOR_VARY, #endif +#if USE_ADAPTATION + HDR_X_NEXT_SERVICES, +#endif HDR_X_SQUID_ERROR, HDR_SURROGATE_CONTROL }; diff -u -r -N squid-3.1.0.10/src/HttpHeader.h squid-3.1.0.11/src/HttpHeader.h --- squid-3.1.0.10/src/HttpHeader.h 2009-07-18 16:16:18.000000000 +1200 +++ squid-3.1.0.11/src/HttpHeader.h 2009-07-19 17:11:09.000000000 +1200 @@ -123,6 +123,9 @@ #if X_ACCELERATOR_VARY HDR_X_ACCELERATOR_VARY, #endif +#if USE_ADAPTATION + HDR_X_NEXT_SERVICES, +#endif HDR_SURROGATE_CAPABILITY, HDR_SURROGATE_CONTROL, HDR_FRONT_END_HTTPS, diff -u -r -N squid-3.1.0.10/src/HttpMsg.cc squid-3.1.0.11/src/HttpMsg.cc --- squid-3.1.0.10/src/HttpMsg.cc 2009-07-18 16:16:18.000000000 +1200 +++ squid-3.1.0.11/src/HttpMsg.cc 2009-07-19 17:11:09.000000000 +1200 @@ -309,6 +309,14 @@ 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 diff -u -r -N squid-3.1.0.10/src/HttpMsg.h squid-3.1.0.11/src/HttpMsg.h --- squid-3.1.0.10/src/HttpMsg.h 2009-07-18 16:16:18.000000000 +1200 +++ squid-3.1.0.11/src/HttpMsg.h 2009-07-19 17:11:09.000000000 +1200 @@ -58,6 +58,9 @@ ///< 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; @@ -109,7 +112,8 @@ }; /* Temporary parsing state; might turn into the replacement parser later on */ -struct _HttpParser { +class HttpParser { +public: char state; const char *buf; int bufsiz; @@ -120,7 +124,6 @@ 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); diff -u -r -N squid-3.1.0.10/src/HttpRequest.cc squid-3.1.0.11/src/HttpRequest.cc --- squid-3.1.0.10/src/HttpRequest.cc 2009-07-18 16:16:18.000000000 +1200 +++ squid-3.1.0.11/src/HttpRequest.cc 2009-07-19 17:11:09.000000000 +1200 @@ -40,6 +40,9 @@ #include "HttpHeaderRange.h" #include "MemBuf.h" #include "Store.h" +#if ICAP_CLIENT +#include "adaptation/icap/icap_log.h" +#endif HttpRequest::HttpRequest() : HttpMsg(hoRequest) { @@ -87,6 +90,7 @@ 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 @@ -99,6 +103,12 @@ #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 @@ -138,6 +148,13 @@ extacl_passwd.clean(); extacl_log.clean(); + +#if USE_ADAPTATION + adaptHistory_ = NULL; +#endif +#if ICAP_CLIENT + icapHistory_ = NULL; +#endif } void @@ -163,25 +180,14 @@ 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; @@ -197,6 +203,8 @@ copy->extacl_passwd = extacl_passwd; copy->extacl_log = extacl_log; + assert(copy->inheritProperties(this)); + return copy; } @@ -356,6 +364,44 @@ 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(bool createIfNone) const +{ + if (!adaptHistory_ && createIfNone) { + adaptHistory_ = new Adaptation::History(); + debugs(93,4, HERE << "made " << adaptHistory_ << " for " << this); + } + + return adaptHistory_; +} + +Adaptation::History::Pointer +HttpRequest::adaptLogHistory() const +{ + const bool loggingNeedsHistory = (LogfileStatus == LOG_ENABLE) && + alLogformatHasAdaptToken; // TODO: make global to remove this method? + return HttpRequest::adaptHistory(loggingNeedsHistory); +} + +#endif + bool HttpRequest::multipartRangeRequest() const { @@ -509,6 +555,15 @@ 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(); @@ -523,3 +578,13 @@ } 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; + } +} diff -u -r -N squid-3.1.0.10/src/HttpRequest.h squid-3.1.0.11/src/HttpRequest.h --- squid-3.1.0.10/src/HttpRequest.h 2009-07-18 16:16:18.000000000 +1200 +++ squid-3.1.0.11/src/HttpRequest.h 2009-07-19 17:11:09.000000000 +1200 @@ -38,13 +38,28 @@ #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 { @@ -84,6 +99,19 @@ }; 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 adaptLogHistory() const; + /// Returns possibly nil history, creating it if requested + Adaptation::History::Pointer adaptHistory(bool createIfNone = false) 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(); @@ -103,6 +131,13 @@ */ 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; @@ -134,6 +169,8 @@ HierarchyLogEntry hier; + int dnsWait; ///< sum of DNS lookup delays in milliseconds, for %dt + err_type errType; char *peer_login; /* Configured peer login:password */ diff -u -r -N squid-3.1.0.10/src/icmp/net_db.cc squid-3.1.0.11/src/icmp/net_db.cc --- squid-3.1.0.10/src/icmp/net_db.cc 2009-07-18 16:16:27.000000000 +1200 +++ squid-3.1.0.11/src/icmp/net_db.cc 2009-07-19 17:11:14.000000000 +1200 @@ -271,7 +271,7 @@ } static void -netdbSendPing(const ipcache_addrs * ia, void *data) +netdbSendPing(const ipcache_addrs *ia, const DnsLookupDetails &, void *data) { IpAddress addr; char *hostname = NULL; diff -u -r -N squid-3.1.0.10/src/ident/Ident.cc squid-3.1.0.11/src/ident/Ident.cc --- squid-3.1.0.10/src/ident/Ident.cc 2009-07-18 16:16:27.000000000 +1200 +++ squid-3.1.0.11/src/ident/Ident.cc 2009-07-19 17:11:14.000000000 +1200 @@ -120,7 +120,7 @@ } 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; diff -u -r -N squid-3.1.0.10/src/ipcache.cc squid-3.1.0.11/src/ipcache.cc --- squid-3.1.0.10/src/ipcache.cc 2009-07-18 16:16:27.000000000 +1200 +++ squid-3.1.0.11/src/ipcache.cc 2009-07-19 17:11:14.000000000 +1200 @@ -77,9 +77,6 @@ * the ipcache_high threshold. */ -/// \ingroup IPCacheAPI -typedef struct _ipcache_entry ipcache_entry; - /** \ingroup IPCacheAPI * @@ -88,7 +85,8 @@ * 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; @@ -108,6 +106,8 @@ unsigned int negcached:1; unsigned int fromhosts:1; } flags; + + int age() const; ///< time passed since request_time or -1 if unknown }; /// \ingroup IPCacheInternal @@ -161,6 +161,14 @@ extern int _dns_ttl_; #endif +int +ipcache_entry::age() const +{ + return request_time.tv_sec ? tvSubMsec(request_time, current_time) : -1; +} + + + /** \ingroup IPCacheInternal * @@ -324,7 +332,7 @@ * 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; @@ -340,8 +348,8 @@ 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); @@ -646,8 +654,9 @@ ipcache_entry *i; static_cast(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); @@ -661,7 +670,7 @@ { ipcacheAddEntry(i); - ipcacheCallback(i); + ipcacheCallback(i, age); } } @@ -694,16 +703,16 @@ 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; } @@ -729,7 +738,7 @@ i->handlerData = cbdataReference(handlerData); - ipcacheCallback(i); + ipcacheCallback(i, -1); // no lookup return; } @@ -823,16 +832,16 @@ 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++; @@ -1064,7 +1073,7 @@ /// \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; @@ -1159,7 +1168,7 @@ /* 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 */ diff -u -r -N squid-3.1.0.10/src/main.cc squid-3.1.0.11/src/main.cc --- squid-3.1.0.10/src/main.cc 2009-07-18 16:16:27.000000000 +1200 +++ squid-3.1.0.11/src/main.cc 2009-07-19 17:11:14.000000000 +1200 @@ -34,6 +34,9 @@ #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" @@ -695,6 +698,9 @@ storeDirCloseSwapLogs(); storeLogClose(); accessLogClose(); +#if ICAP_CLIENT + icapLogClose(); +#endif useragentLogClose(); refererCloseLog(); @@ -726,6 +732,9 @@ parseEtcHosts(); errorInitialize(); /* reload error pages */ accessLogInit(); +#if ICAP_CLIENT + icapLogOpen(); +#endif storeLogOpen(); useragentOpenLog(); refererOpenLog(); @@ -790,6 +799,9 @@ accessLogRotate(); /* access.log */ useragentRotateLog(); /* useragent.log */ refererRotateLog(); /* referer.log */ +#if ICAP_CLIENT + icapLogRotate(); /*icap.log*/ +#endif #if WIP_FWD_LOG fwdLogRotate(); @@ -951,6 +963,10 @@ accessLogInit(); +#if ICAP_CLIENT + icapLogOpen(); +#endif + #if USE_IDENT Ident::Init(); #endif diff -u -r -N squid-3.1.0.10/src/Makefile.am squid-3.1.0.11/src/Makefile.am --- squid-3.1.0.10/src/Makefile.am 2009-07-18 16:16:18.000000000 +1200 +++ squid-3.1.0.11/src/Makefile.am 2009-07-19 17:11:09.000000000 +1200 @@ -15,6 +15,10 @@ DNSSERVER = endif +DNSSOURCE += \ + DnsLookupDetails.h \ + DnsLookupDetails.cc + SNMP_ALL_SOURCE = \ snmp_core.cc \ snmp_agent.cc @@ -233,6 +237,8 @@ dns.cc \ dnsserver.cc \ dns_internal.cc \ + DnsLookupDetails.cc \ + DnsLookupDetails.h \ htcp.cc \ htcp.h \ ipc.cc \ diff -u -r -N squid-3.1.0.10/src/Makefile.in squid-3.1.0.11/src/Makefile.in --- squid-3.1.0.10/src/Makefile.in 2009-07-18 16:16:47.000000000 +1200 +++ squid-3.1.0.11/src/Makefile.in 2009-07-19 17:11:33.000000000 +1200 @@ -179,17 +179,17 @@ DiskIO/ReadRequest.cc DiskIO/ReadRequest.h \ DiskIO/WriteRequest.cc DiskIO/WriteRequest.h DiskIO/DiskFile.h \ DiskIO/DiskIOStrategy.h DiskIO/IORequestor.h \ - DiskIO/DiskIOModule.h dlink.h dlink.cc dns_internal.cc dns.cc \ - enums.h errorpage.cc errorpage.h ETag.cc event.cc event.h \ - EventLoop.h EventLoop.cc external_acl.cc ExternalACL.h \ - ExternalACLEntry.cc ExternalACLEntry.h fd.cc fde.cc fde.h \ - filemap.cc forward.cc forward.h fqdncache.cc ftp.cc Generic.h \ - globals.h gopher.cc helper.cc helper.h HierarchyLogEntry.h \ - htcp.cc htcp.h http.cc http.h HttpStatusLine.cc \ - HttpStatusLine.h HttpHdrCc.cc HttpHdrRange.cc HttpHdrSc.cc \ - HttpHdrSc.h HttpHdrScTarget.cc HttpHdrScTarget.h \ - HttpHdrContRange.cc HttpHdrContRange.h HttpHeader.cc \ - HttpHeader.h HttpHeaderMask.h HttpHeaderRange.h \ + DiskIO/DiskIOModule.h dlink.h dlink.cc dns_internal.cc \ + DnsLookupDetails.h DnsLookupDetails.cc dns.cc enums.h \ + errorpage.cc errorpage.h ETag.cc event.cc event.h EventLoop.h \ + EventLoop.cc external_acl.cc ExternalACL.h ExternalACLEntry.cc \ + ExternalACLEntry.h fd.cc fde.cc fde.h filemap.cc forward.cc \ + forward.h fqdncache.cc ftp.cc Generic.h globals.h gopher.cc \ + helper.cc helper.h HierarchyLogEntry.h htcp.cc htcp.h http.cc \ + http.h HttpStatusLine.cc HttpStatusLine.h HttpHdrCc.cc \ + HttpHdrRange.cc HttpHdrSc.cc HttpHdrSc.h HttpHdrScTarget.cc \ + HttpHdrScTarget.h HttpHdrContRange.cc HttpHdrContRange.h \ + HttpHeader.cc HttpHeader.h HttpHeaderMask.h HttpHeaderRange.h \ HttpHeaderTools.cc HttpBody.cc HttpMsg.cc HttpMsg.h \ HttpReply.cc HttpReply.h HttpRequest.cc HttpRequest.h \ HttpRequestMethod.cc HttpRequestMethod.h HttpVersion.h ICP.h \ @@ -230,8 +230,10 @@ @USE_DELAY_POOLS_TRUE@am__objects_7 = $(am__objects_6) am__objects_8 = DiskIO/DiskIOModule.$(OBJEXT) \ DiskIO/ReadRequest.$(OBJEXT) DiskIO/WriteRequest.$(OBJEXT) -@USE_DNSSERVER_FALSE@am__objects_9 = dns_internal.$(OBJEXT) -@USE_DNSSERVER_TRUE@am__objects_9 = dns.$(OBJEXT) +@USE_DNSSERVER_FALSE@am__objects_9 = dns_internal.$(OBJEXT) \ +@USE_DNSSERVER_FALSE@ DnsLookupDetails.$(OBJEXT) +@USE_DNSSERVER_TRUE@am__objects_9 = dns.$(OBJEXT) \ +@USE_DNSSERVER_TRUE@ DnsLookupDetails.$(OBJEXT) @ENABLE_HTCP_TRUE@am__objects_10 = htcp.$(OBJEXT) @USE_IPC_WIN32_FALSE@am__objects_11 = ipc.$(OBJEXT) @USE_IPC_WIN32_TRUE@am__objects_11 = ipc_win32.$(OBJEXT) @@ -305,10 +307,11 @@ DelaySpec.cc DelaySpec.h DelayTagged.cc DelayTagged.h \ DelayUser.cc DelayUser.h DelayVector.cc DelayVector.h \ NullDelayId.cc NullDelayId.h dns.cc dnsserver.cc \ - dns_internal.cc htcp.cc htcp.h ipc.cc ipc_win32.cc \ - ProfStats.cc LeakFinder.cc LeakFinder.h snmp_core.cc \ - snmp_agent.cc unlinkd.cc ssl_support.cc ssl_support.h win32.cc \ - WinSvc.cc LoadableModule.h LoadableModule.cc LoadableModules.h \ + dns_internal.cc DnsLookupDetails.cc DnsLookupDetails.h htcp.cc \ + htcp.h ipc.cc ipc_win32.cc ProfStats.cc LeakFinder.cc \ + LeakFinder.h snmp_core.cc snmp_agent.cc unlinkd.cc \ + ssl_support.cc ssl_support.h win32.cc WinSvc.cc \ + LoadableModule.h LoadableModule.cc LoadableModules.h \ LoadableModules.cc DiskIO/DiskThreads/aiops.cc \ DiskIO/DiskThreads/aiops_win32.cc am__objects_23 = DiskIO/DiskIOModules_gen.$(OBJEXT) @@ -392,18 +395,18 @@ DelaySpec.cc DelaySpec.h DelayTagged.cc DelayTagged.h \ DelayUser.cc DelayUser.h DelayVector.cc DelayVector.h \ NullDelayId.cc NullDelayId.h disk.cc dlink.h dlink.cc \ - dns_internal.cc dns.cc errorpage.cc ETag.cc external_acl.cc \ - ExternalACLEntry.cc fd.cc fde.cc forward.cc fqdncache.cc \ - ftp.cc gopher.cc helper.cc htcp.cc htcp.h http.cc HttpBody.cc \ - HttpHeader.cc HttpHeaderTools.cc HttpHdrCc.cc \ - HttpHdrContRange.cc HttpHdrRange.cc HttpHdrSc.cc \ - HttpHdrScTarget.cc HttpMsg.cc HttpReply.cc HttpStatusLine.cc \ - icp_v2.cc icp_v3.cc ipc.cc ipc_win32.cc ipcache.cc int.cc \ - internal.cc list.cc logfile.cc multicast.cc mem_node.cc \ - MemBuf.cc MemObject.cc mime.cc neighbors.cc Packer.cc \ - Parsing.cc pconn.cc peer_digest.cc peer_select.cc \ - peer_sourcehash.cc peer_userhash.cc redirect.cc referer.cc \ - refresh.cc RemovalPolicy.cc Server.cc snmp_core.cc \ + dns_internal.cc DnsLookupDetails.h DnsLookupDetails.cc dns.cc \ + errorpage.cc ETag.cc external_acl.cc ExternalACLEntry.cc fd.cc \ + fde.cc forward.cc fqdncache.cc ftp.cc gopher.cc helper.cc \ + htcp.cc htcp.h http.cc HttpBody.cc HttpHeader.cc \ + HttpHeaderTools.cc HttpHdrCc.cc HttpHdrContRange.cc \ + HttpHdrRange.cc HttpHdrSc.cc HttpHdrScTarget.cc HttpMsg.cc \ + HttpReply.cc HttpStatusLine.cc icp_v2.cc icp_v3.cc ipc.cc \ + ipc_win32.cc ipcache.cc int.cc internal.cc list.cc logfile.cc \ + multicast.cc mem_node.cc MemBuf.cc MemObject.cc mime.cc \ + neighbors.cc Packer.cc Parsing.cc pconn.cc peer_digest.cc \ + peer_select.cc peer_sourcehash.cc peer_userhash.cc redirect.cc \ + referer.cc refresh.cc RemovalPolicy.cc Server.cc snmp_core.cc \ snmp_agent.cc ssl_support.cc ssl_support.h stat.cc StatHist.cc \ stmem.cc store.cc store_client.cc store_digest.cc store_dir.cc \ store_io.cc store_key_md5.cc store_log.cc store_rebuild.cc \ @@ -610,11 +613,12 @@ DelayPool.cc DelayPool.h DelayPools.h DelaySpec.cc DelaySpec.h \ DelayTagged.cc DelayTagged.h DelayUser.cc DelayUser.h \ DelayVector.cc DelayVector.h NullDelayId.cc NullDelayId.h \ - disk.cc dlink.h dlink.cc dns_internal.cc dns.cc errorpage.cc \ - ETag.cc external_acl.cc ExternalACLEntry.cc fd.cc fde.cc \ - forward.cc fqdncache.cc ftp.cc gopher.cc helper.cc htcp.cc \ - htcp.h http.cc HttpBody.cc HttpHeader.cc HttpHeaderTools.cc \ - HttpHdrCc.cc HttpHdrContRange.cc HttpHdrRange.cc HttpHdrSc.cc \ + disk.cc dlink.h dlink.cc dns_internal.cc DnsLookupDetails.h \ + DnsLookupDetails.cc dns.cc errorpage.cc ETag.cc \ + external_acl.cc ExternalACLEntry.cc fd.cc fde.cc forward.cc \ + fqdncache.cc ftp.cc gopher.cc helper.cc htcp.cc htcp.h http.cc \ + HttpBody.cc HttpHeader.cc HttpHeaderTools.cc HttpHdrCc.cc \ + HttpHdrContRange.cc HttpHdrRange.cc HttpHdrSc.cc \ HttpHdrScTarget.cc HttpMsg.cc HttpReply.cc HttpStatusLine.cc \ icp_v2.cc icp_v3.cc ipc.cc ipc_win32.cc ipcache.cc int.cc \ internal.cc list.cc logfile.cc multicast.cc mem_node.cc \ @@ -701,11 +705,12 @@ DelayPool.cc DelayPool.h DelayPools.h DelaySpec.cc DelaySpec.h \ DelayTagged.cc DelayTagged.h DelayUser.cc DelayUser.h \ DelayVector.cc DelayVector.h NullDelayId.cc NullDelayId.h \ - disk.cc dlink.h dlink.cc dns_internal.cc dns.cc errorpage.cc \ - ETag.cc external_acl.cc ExternalACLEntry.cc fd.cc fde.cc \ - forward.cc fqdncache.cc ftp.cc gopher.cc helper.cc htcp.cc \ - htcp.h http.cc HttpBody.cc HttpHeader.cc HttpHeaderTools.cc \ - HttpHdrCc.cc HttpHdrContRange.cc HttpHdrRange.cc HttpHdrSc.cc \ + disk.cc dlink.h dlink.cc dns_internal.cc DnsLookupDetails.h \ + DnsLookupDetails.cc dns.cc errorpage.cc ETag.cc \ + external_acl.cc ExternalACLEntry.cc fd.cc fde.cc forward.cc \ + fqdncache.cc ftp.cc gopher.cc helper.cc htcp.cc htcp.h http.cc \ + HttpBody.cc HttpHeader.cc HttpHeaderTools.cc HttpHdrCc.cc \ + HttpHdrContRange.cc HttpHdrRange.cc HttpHdrSc.cc \ HttpHdrScTarget.cc HttpMsg.cc HttpReply.cc HttpStatusLine.cc \ icp_v2.cc icp_v3.cc ipc.cc ipc_win32.cc ipcache.cc int.cc \ internal.cc list.cc logfile.cc multicast.cc mem_node.cc \ @@ -792,11 +797,12 @@ DelayPool.cc DelayPool.h DelayPools.h DelaySpec.cc DelaySpec.h \ DelayTagged.cc DelayTagged.h DelayUser.cc DelayUser.h \ DelayVector.cc DelayVector.h NullDelayId.cc NullDelayId.h \ - disk.cc dlink.h dlink.cc dns_internal.cc dns.cc errorpage.cc \ - ETag.cc external_acl.cc ExternalACLEntry.cc fd.cc fde.cc \ - forward.cc fqdncache.cc ftp.cc gopher.cc helper.cc htcp.cc \ - htcp.h http.cc HttpBody.cc HttpHeader.cc HttpHeaderTools.cc \ - HttpHdrCc.cc HttpHdrContRange.cc HttpHdrRange.cc HttpHdrSc.cc \ + disk.cc dlink.h dlink.cc dns_internal.cc DnsLookupDetails.h \ + DnsLookupDetails.cc dns.cc errorpage.cc ETag.cc \ + external_acl.cc ExternalACLEntry.cc fd.cc fde.cc forward.cc \ + fqdncache.cc ftp.cc gopher.cc helper.cc htcp.cc htcp.h http.cc \ + HttpBody.cc HttpHeader.cc HttpHeaderTools.cc HttpHdrCc.cc \ + HttpHdrContRange.cc HttpHdrRange.cc HttpHdrSc.cc \ HttpHdrScTarget.cc HttpMsg.cc HttpReply.cc HttpStatusLine.cc \ icp_v2.cc icp_v3.cc ipc.cc ipc_win32.cc ipcache.cc int.cc \ internal.cc list.cc logfile.cc multicast.cc mem_node.cc \ @@ -974,11 +980,12 @@ DelayPool.cc DelayPool.h DelayPools.h DelaySpec.cc DelaySpec.h \ DelayTagged.cc DelayTagged.h DelayUser.cc DelayUser.h \ DelayVector.cc DelayVector.h NullDelayId.cc NullDelayId.h \ - disk.cc dlink.h dlink.cc dns_internal.cc dns.cc errorpage.cc \ - ETag.cc external_acl.cc ExternalACLEntry.cc fd.cc fde.cc \ - forward.cc fqdncache.cc ftp.cc gopher.cc helper.cc htcp.cc \ - htcp.h http.cc HttpBody.cc HttpHeader.cc HttpHeaderTools.cc \ - HttpHdrCc.cc HttpHdrContRange.cc HttpHdrRange.cc HttpHdrSc.cc \ + disk.cc dlink.h dlink.cc dns_internal.cc DnsLookupDetails.h \ + DnsLookupDetails.cc dns.cc errorpage.cc ETag.cc \ + external_acl.cc ExternalACLEntry.cc fd.cc fde.cc forward.cc \ + fqdncache.cc ftp.cc gopher.cc helper.cc htcp.cc htcp.h http.cc \ + HttpBody.cc HttpHeader.cc HttpHeaderTools.cc HttpHdrCc.cc \ + HttpHdrContRange.cc HttpHdrRange.cc HttpHdrSc.cc \ HttpHdrScTarget.cc HttpMsg.cc HttpReply.cc HttpStatusLine.cc \ icp_v2.cc icp_v3.cc ipc.cc ipc_win32.cc ipcache.cc int.cc \ internal.cc list.cc logfile.cc multicast.cc mem_node.cc \ @@ -1106,11 +1113,12 @@ DelayPool.cc DelayPool.h DelayPools.h DelaySpec.cc DelaySpec.h \ DelayTagged.cc DelayTagged.h DelayUser.cc DelayUser.h \ DelayVector.cc DelayVector.h NullDelayId.cc NullDelayId.h \ - disk.cc dlink.h dlink.cc dns_internal.cc dns.cc errorpage.cc \ - ETag.cc external_acl.cc ExternalACLEntry.cc fd.cc fde.cc \ - forward.cc fqdncache.cc ftp.cc gopher.cc helper.cc htcp.cc \ - htcp.h http.cc HttpBody.cc HttpHdrCc.cc HttpHdrContRange.cc \ - HttpHdrRange.cc HttpHdrSc.cc HttpHdrScTarget.cc HttpHeader.cc \ + disk.cc dlink.h dlink.cc dns_internal.cc DnsLookupDetails.h \ + DnsLookupDetails.cc dns.cc errorpage.cc ETag.cc \ + external_acl.cc ExternalACLEntry.cc fd.cc fde.cc forward.cc \ + fqdncache.cc ftp.cc gopher.cc helper.cc htcp.cc htcp.h http.cc \ + HttpBody.cc HttpHdrCc.cc HttpHdrContRange.cc HttpHdrRange.cc \ + HttpHdrSc.cc HttpHdrScTarget.cc HttpHeader.cc \ HttpHeaderTools.cc HttpMsg.cc HttpReply.cc HttpRequest.cc \ HttpRequestMethod.cc HttpStatusLine.cc icp_v2.cc icp_v3.cc \ int.cc internal.cc ipc.cc ipc_win32.cc ipcache.cc list.cc \ @@ -1484,8 +1492,10 @@ -I$(top_builddir)/include @SQUID_CPPUNIT_INC@ \ -I$(top_srcdir)/lib -I$(top_builddir)/src AUTOMAKE_OPTIONS = subdir-objects -@USE_DNSSERVER_FALSE@DNSSOURCE = dns_internal.cc -@USE_DNSSERVER_TRUE@DNSSOURCE = dns.cc +@USE_DNSSERVER_FALSE@DNSSOURCE = dns_internal.cc DnsLookupDetails.h \ +@USE_DNSSERVER_FALSE@ DnsLookupDetails.cc +@USE_DNSSERVER_TRUE@DNSSOURCE = dns.cc DnsLookupDetails.h \ +@USE_DNSSERVER_TRUE@ DnsLookupDetails.cc @USE_DNSSERVER_FALSE@DNSSERVER = @USE_DNSSERVER_TRUE@DNSSERVER = dnsserver SNMP_ALL_SOURCE = \ @@ -1617,6 +1627,8 @@ dns.cc \ dnsserver.cc \ dns_internal.cc \ + DnsLookupDetails.cc \ + DnsLookupDetails.h \ htcp.cc \ htcp.h \ ipc.cc \ @@ -3647,6 +3659,7 @@ @AMDEP_TRUE@@am__include@ @am__quote@./$(DEPDIR)/DelayUser.Po@am__quote@ @AMDEP_TRUE@@am__include@ @am__quote@./$(DEPDIR)/DelayVector.Po@am__quote@ @AMDEP_TRUE@@am__include@ @am__quote@./$(DEPDIR)/DescriptorSet.Plo@am__quote@ +@AMDEP_TRUE@@am__include@ @am__quote@./$(DEPDIR)/DnsLookupDetails.Po@am__quote@ @AMDEP_TRUE@@am__include@ @am__quote@./$(DEPDIR)/ETag.Po@am__quote@ @AMDEP_TRUE@@am__include@ @am__quote@./$(DEPDIR)/EventLoop.Po@am__quote@ @AMDEP_TRUE@@am__include@ @am__quote@./$(DEPDIR)/ExternalACLEntry.Po@am__quote@ diff -u -r -N squid-3.1.0.10/src/multicast.cc squid-3.1.0.11/src/multicast.cc --- squid-3.1.0.10/src/multicast.cc 2009-07-18 16:16:27.000000000 +1200 +++ squid-3.1.0.11/src/multicast.cc 2009-07-19 17:11:14.000000000 +1200 @@ -50,7 +50,7 @@ } void -mcastJoinGroups(const ipcache_addrs * ia, void *datanotused) +mcastJoinGroups(const ipcache_addrs *ia, const DnsLookupDetails &, void *datanotused) { #ifdef IP_MULTICAST_TTL int fd = theInIcpConnection; diff -u -r -N squid-3.1.0.10/src/neighbors.cc squid-3.1.0.11/src/neighbors.cc --- squid-3.1.0.10/src/neighbors.cc 2009-07-18 16:16:27.000000000 +1200 +++ squid-3.1.0.11/src/neighbors.cc 2009-07-19 17:11:14.000000000 +1200 @@ -1230,7 +1230,7 @@ } static void -peerDNSConfigure(const ipcache_addrs * ia, void *data) +peerDNSConfigure(const ipcache_addrs *ia, const DnsLookupDetails &, void *data) { peer *p = (peer *)data; @@ -1399,7 +1399,7 @@ } 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; diff -u -r -N squid-3.1.0.10/src/protos.h squid-3.1.0.11/src/protos.h --- squid-3.1.0.10/src/protos.h 2009-07-18 16:16:27.000000000 +1200 +++ squid-3.1.0.11/src/protos.h 2009-07-19 17:11:14.000000000 +1200 @@ -127,8 +127,6 @@ 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); diff -u -r -N squid-3.1.0.10/src/send-announce.cc squid-3.1.0.11/src/send-announce.cc --- squid-3.1.0.10/src/send-announce.cc 2009-07-18 16:16:27.000000000 +1200 +++ squid-3.1.0.11/src/send-announce.cc 2009-07-19 17:11:14.000000000 +1200 @@ -55,7 +55,7 @@ } 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); diff -u -r -N squid-3.1.0.10/src/Server.cc squid-3.1.0.11/src/Server.cc --- squid-3.1.0.10/src/Server.cc 2009-07-18 16:16:18.000000000 +1200 +++ squid-3.1.0.11/src/Server.cc 2009-07-19 17:11:12.000000000 +1200 @@ -39,10 +39,11 @@ #include "HttpReply.h" #include "TextException.h" #include "errorpage.h" +#include "SquidTime.h" #if USE_ADAPTATION #include "adaptation/AccessCheck.h" -#include "adaptation/Service.h" +#include "adaptation/Iterator.h" #endif // implemented in client_side_reply.cc until sides have a common parent @@ -173,6 +174,10 @@ 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); @@ -503,24 +508,11 @@ } #if USE_ADAPTATION -/* - * Initiate an ICAP transaction. Return true on success. - * Caller will handle error condition by generating a Squid error message - * or take other action. - */ -bool -ServerStateData::startAdaptation(Adaptation::ServicePointer service, HttpRequest *cause) +/// Initiate an asynchronous adaptation transaction which will call us back. +void +ServerStateData::startAdaptation(const Adaptation::ServiceGroupPointer &group, HttpRequest *cause) { debugs(11, 5, "ServerStateData::startAdaptation() called"); - if (!service) { - debugs(11, 3, "ServerStateData::startAdaptation fails: lack of service"); - return false; - } - if (service->broken()) { - debugs(11, 3, "ServerStateData::startAdaptation fails: broken service"); - return false; - } - // check whether we should be sending a body as well // start body pipe to feed ICAP transaction if needed assert(!virginBodyDestination); @@ -536,9 +528,10 @@ virginBodyDestination->setBodySize(size); } - adaptedHeadSource = initiateAdaptation(service->makeXactLauncher( - this, vrep, cause)); - return adaptedHeadSource != NULL; + adaptedHeadSource = initiateAdaptation( + new Adaptation::Iterator(this, vrep, cause, group)); + startedAdaptation = adaptedHeadSource != NULL; + Must(startedAdaptation); } // properly cleans up ICAP-related state @@ -753,7 +746,7 @@ } void -ServerStateData::adaptationAclCheckDone(Adaptation::ServicePointer service) +ServerStateData::adaptationAclCheckDone(Adaptation::ServiceGroupPointer group) { adaptationAccessCheckPending = false; @@ -768,34 +761,22 @@ } // TODO: Should we check receivedBodyTooLarge on the server-side as well? - startedAdaptation = startAdaptation(service, originalRequest()); - - if (!startedAdaptation && (!service || service->cfg().bypass)) { - // handle ICAP start failure when no service was selected - // or where the selected service was optional + if (!group) { + debugs(11,3, HERE << "no adapation needed"); setFinalReply(virginReply()); processReplyBody(); return; } - if (!startedAdaptation) { - // handle start failure for an essential ICAP service - ErrorState *err = errorCon(ERR_ICAP_FAILURE, - HTTP_INTERNAL_SERVER_ERROR, originalRequest()); - err->xerrno = errno; - errorAppendEntry(entry, err); - abortTransaction("ICAP start failure"); - return; - } - + startAdaptation(group, originalRequest()); processReplyBody(); } void -ServerStateData::adaptationAclCheckDoneWrapper(Adaptation::ServicePointer service, void *data) +ServerStateData::adaptationAclCheckDoneWrapper(Adaptation::ServiceGroupPointer group, void *data) { ServerStateData *state = (ServerStateData *)data; - state->adaptationAclCheckDone(service); + state->adaptationAclCheckDone(group); } #endif diff -u -r -N squid-3.1.0.10/src/Server.h squid-3.1.0.11/src/Server.h --- squid-3.1.0.10/src/Server.h 2009-07-18 16:16:22.000000000 +1200 +++ squid-3.1.0.11/src/Server.h 2009-07-19 17:11:12.000000000 +1200 @@ -86,8 +86,8 @@ virtual HttpRequest *originalRequest(); #if USE_ADAPTATION - void adaptationAclCheckDone(Adaptation::ServicePointer service); - static void adaptationAclCheckDoneWrapper(Adaptation::ServicePointer service, void *data); + void adaptationAclCheckDone(Adaptation::ServiceGroupPointer group); + static void adaptationAclCheckDoneWrapper(Adaptation::ServiceGroupPointer group, void *data); // ICAPInitiator: start an ICAP transaction and receive adapted headers. virtual void noteAdaptationAnswer(HttpMsg *message); @@ -141,7 +141,7 @@ bool abortOnBadEntry(const char *abortReason); #if USE_ADAPTATION - bool startAdaptation(Adaptation::ServicePointer service, HttpRequest *cause); + void startAdaptation(const Adaptation::ServiceGroupPointer &group, HttpRequest *cause); void adaptVirginReplyBody(const char *buf, ssize_t len); void cleanAdaptation(); virtual bool doneWithAdaptation() const; /**< did we end ICAP communication? */ diff -u -r -N squid-3.1.0.10/src/structs.h squid-3.1.0.11/src/structs.h --- squid-3.1.0.10/src/structs.h 2009-07-18 16:16:27.000000000 +1200 +++ squid-3.1.0.11/src/structs.h 2009-07-19 17:11:15.000000000 +1200 @@ -183,6 +183,7 @@ } Timeout; size_t maxRequestHeaderSize; int64_t maxRequestBodySize; + int64_t maxChunkedRequestBodySize; size_t maxReplyHeaderSize; acl_size_t *ReplyBodySize; @@ -264,6 +265,10 @@ customlog *accesslogs; +#if ICAP_CLIENT + customlog *icaplogs; +#endif + int rotateNumber; } Log; char *adminEmail; @@ -479,6 +484,9 @@ acl_access *followXFF; #endif /* FOLLOW_X_FORWARDED_FOR */ +#if ICAP_CLIENT + acl_access* icap; +#endif } accessList; acl_deny_info_list *denyInfoList; authConfig authConfiguration; diff -u -r -N squid-3.1.0.10/src/tunnel.cc squid-3.1.0.11/src/tunnel.cc --- squid-3.1.0.10/src/tunnel.cc 2009-07-18 16:16:28.000000000 +1200 +++ squid-3.1.0.11/src/tunnel.cc 2009-07-19 17:11:15.000000000 +1200 @@ -553,12 +553,14 @@ 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); @@ -573,7 +575,7 @@ 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); diff -u -r -N squid-3.1.0.10/src/typedefs.h squid-3.1.0.11/src/typedefs.h --- squid-3.1.0.10/src/typedefs.h 2009-07-18 16:16:28.000000000 +1200 +++ squid-3.1.0.11/src/typedefs.h 2009-07-19 17:11:15.000000000 +1200 @@ -199,9 +199,10 @@ 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;