[PATCH] Enhanced access logging, added ICAP logging, chunked requests, bug #2495 fix.

Hello,

    Please consider the following changes for Squid3 trunk inclusion.
Most of them have been accumulating on the 3p0-plus lp branch and have
been tested in production. All have been tested in the lab. I compressed
the 150KB patch, but the attached text file shows squid.conf
documentation describing most of the features listed below.

Many thanks to Christos Tsantilas for help with coding and testing.

If approved, I will try to do a "bzr merge" instead of a raw patch,
provided Robert helps me with convincing bzr to obey :-).

Thank you,

Alex.
------------------
Enhanced access logging, added ICAP logging, chunked requests, bug #2495
fix:

Ported features accumulated on 3p0-plus branch as of r8937:

  - A hack to support chunked requests
    (see chunked_request_body_max_size in squid.conf).

  - Enhanced access logging
    (<Hs, <sh, >sh, <pt, <tt, icap_total_time, and <icap_last_h)

  - ICAP logging
    (see icap_log and log_icap in squid.conf as well as
    http://wiki.squid-cache.org/Features/AdaptationLog).

  - ICAP retries based on the ICAP responses status code
    (see icap_retry and icap_retry_limit in squid.conf).

New v3.1-only changes:

  - Support logging resp. times of adaptation transactions to access.log
    (%adaptation_sum_trs and %adaptation_all_trs)

  - Support logging of total DNS wait time to access.log
    (%dt)

  - Bug #2495 fix

Squid v3.1.0.9-based
  Contains official Squid v3.1 branch changes up to r9605.

=== modified file 'src/cf.data.pre'
--- src/cf.data.pre 2009-06-25 13:32:03 +0000
+++ src/cf.data.pre 2009-06-26 20:46:49 +0000
@@ -2320,6 +2320,7 @@
                 tg GMT time. Optional strftime format argument
                         default %d/%b/%Y:%H:%M:%S %z
                 tr Response time (milliseconds)
+ dt Total time spent making DNS lookups (milliseconds)
>h Request header. Optional header name argument
                         on the format header[:[separator]element]
                 <h Reply header. Optional header name argument
@@ -2329,7 +2330,8 @@
                 ui User name from ident
                 us User name from SSL
                 ue User name from external acl helper
- Hs HTTP status code
+ Hs HTTP status code sent to the client
+ <Hs HTTP status code received from the next hop
                 Ss Squid request status (TCP_MISS etc)
                 Sh Squid hierarchy status (DEFAULT_PARENT etc)
                 mt MIME content type
@@ -2339,13 +2341,63 @@
                 rv Request protocol version
                 et Tag returned by external acl
                 ea Log string returned by external acl
- <st Reply size including HTTP headers
- >st Request size including HTTP headers
+ <st Sent reply size including HTTP headers
+ >st Received request size including HTTP headers. In the
+ case of chunked requests the chunked encoding metadata
+ are not included
+ >sh Received HTTP request headers size
+ <sh Sent HTTP reply headers size
                 st Request+Reply size including HTTP headers
                 <sH Reply high offset sent
                 <sS Upstream object size
+ <pt Peer response time in milliseconds. The timer starts
+ when the last request byte is sent to the next hop
+ and stops when the last response byte is received.
+ <tt Total server-side time in milliseconds. The timer
+ starts with the first connect request (or write I/O)
+ sent to the first selected peer. The timer stops
+ with the last I/O with the last peer.
                 % a literal % character
 
+ If ICAP is enabled, the following two codes become available (as
+ well as ICAP log codes documented with the icap_log option):
+
+ icap_total_time Total ICAP processing time for the HTTP
+ transaction. The timer ticks when ICAP
+ ACLs are checked and when ICAP
+ transaction is in progress.
+
+ <icap_last_h The header of the last ICAP response
+ related to the HTTP transaction. Like
+ <h, accepts an optional header name
+ argument. Will not change semantics
+ when multiple ICAP transactions per HTTP
+ transaction are supported.
+
+ If adaptation is enabled the following two codes become available:
+
+ adaptation_sum_trs Summed adaptation transaction response
+ times recorded as a comma-separated list in
+ the order of transaction start time. Each time
+ value is recorded as an integer number,
+ representing response time of one or more
+ adaptation (ICAP or eCAP) transaction in
+ milliseconds. When a failed transaction is
+ being retried or repeated, its time is not
+ logged individually but added to the
+ replacement (next) transaction. See also:
+ adaptation_all_trs.
+
+ adaptation_all_trs All adaptation transaction response times.
+ Same as adaptation_strs but response times of
+ individual transactions are never added
+ together. Instead, all transaction response
+ times are recorded individually.
+
+ You can prefix adaptation_*_trs format codes with adaptation
+ service name in curly braces to record response time(s) specific
+ to that service. For example: %{my_service}adaptation_sum_trs
+
         The default formats available (which do not need re-defining) are:
 
 logformat squid %ts.%03tu %6tr %>a %Ss/%03Hs %<st %rm %ru %un %Sh/%<A %mt
@@ -2386,6 +2438,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 <filepath> [<logformat name> [acl acl ...]]
+ icap_log none [acl acl ...]]
+
+ Please see access_log option documentation for details. The two
+ kinds of logs share the overall configuration approach and many
+ features.
+
+ ICAP processing of a single HTTP message or transaction may
+ require multiple ICAP transactions. In such cases, multiple
+ ICAP transaction log lines will correspond to a single access
+ log line.
+
+ ICAP log uses logformat codes that make sense for an ICAP
+ transaction. Header-related codes are applied to the HTTP header
+ embedded in an ICAP server response, with the following caveats:
+ For REQMOD, there is no HTTP response header unless the ICAP
+ server performed request satisfaction. For RESPMOD, the HTTP
+ request header is the header sent to the ICAP server. For
+ OPTIONS, there are no HTTP headers.
+
+ The following format codes are also available for ICAP logs:
+
+ <icap_A ICAP server IP address. Similar to <A.
+
+ <icap_service_name ICAP service name from the icap_service
+ option in Squid configuration file.
+
+ icap_ru ICAP Request-URI. Similar to ru.
+
+ icap_rm ICAP request method (REQMOD, RESPMOD, or
+ OPTIONS). Similar to existing rm.
+
+ >icap_size Bytes sent to the ICAP server (TCP payload
+ only; i.e., what Squid writes to the socket).
+
+ <icap_size Bytes received from the ICAP server (TCP
+ payload only; i.e., what Squid reads from
+ the socket).
+
+ icap_tr Transaction response time (in
+ milliseconds). The timer starts when
+ the ICAP transaction is created and
+ stops when the transaction is completed.
+ Similar to tr.
+
+ icap_tio Transaction I/O time (in milliseconds). The
+ timer starts when the first ICAP request
+ byte is scheduled for sending. The timers
+ stops when the last byte of the ICAP response
+ is received.
+
+ icap_to Transaction outcome: ICAP_ERR* for all
+ transaction errors, ICAP_OPT for OPTION
+ transactions, ICAP_ECHO for 204
+ responses, ICAP_MOD for message
+ modification, and ICAP_SAT for request
+ satisfaction. Similar to Ss.
+
+ icap_Hs ICAP response status code. Similar to Hs.
+
+ >icap_h ICAP request header(s). Similar to >h.
+
+ <icap_h ICAP response header(s). Similar to <h.
+
+ The default ICAP log format, which can be used without an explicit
+ definition, is called icap_squid:
+
+logformat icap_squid %ts.%03tu %6icap_tr %>a %icap_to/%03icap_Hs %<icap_size %icap_rm %icap_ru% %un -/%<icap_A -
+
+ See also: logformat, log_icap, and %<icapLastHeader
+DOC_END
+
 NAME: log_access
 TYPE: acl_access
 LOC: Config.accessList.log
@@ -2397,6 +2531,16 @@
         logging will also not be accounted for in performance counters.
 DOC_END
 
+NAME: log_icap
+TYPE: acl_access
+IFDEF: ICAP_CLIENT
+LOC: Config.accessList.icap
+DEFAULT: none
+DOC_START
+ This options allows you to control which requests get logged
+ to icap.log. See the icap_log directive for ICAP log details.
+DOC_END
+
 NAME: cache_store_log
 TYPE: string
 DEFAULT: none
@@ -3260,6 +3404,33 @@
         be no limit imposed.
 DOC_END
 
+NAME: chunked_request_body_max_size
+COMMENT: (bytes)
+TYPE: b_int64_t
+DEFAULT: 64 KB
+LOC: Config.maxChunkedRequestBodySize
+DOC_START
+ A broken or confused HTTP/1.1 client may send a chunked HTTP
+ request to Squid. Squid does not have full support for that
+ feature yet. To cope with such requests, Squid buffers the
+ entire request and then dechunks request body to create a
+ plain HTTP/1.0 request with a known content length. The plain
+ request is then used by the rest of Squid code as usual.
+
+ The option value specifies the maximum size of the buffer used
+ to hold the request before the conversion. If the chunked
+ request size exceeds the specified limit, the conversion
+ fails, and the client receives an "unsupported request" error,
+ as if dechunking was disabled.
+
+ Dechunking is enabled by default. To disable conversion of
+ chunked requests, set the maximum to zero.
+
+ Request dechunking feature and this option in particular are a
+ temporary hack. When chunking requests and responses are fully
+ supported, there will be no need to buffer a chunked request.
+DOC_END
+
 NAME: broken_posts
 IFDEF: HTTP_VIOLATIONS
 TYPE: acl_access
@@ -5555,6 +5726,71 @@
 adaptation_access service_1 allow all
 DOC_END
 
+NAME: adaptation_masterx_shared_names
+TYPE: string
+IFDEF: USE_ADAPTATION
+LOC: Adaptation::Config::masterx_shared_name
+DEFAULT: none
+DOC_START
+ For each master transaction (i.e., the HTTP request and response
+ sequence, including all related ICAP and eCAP exchanges), Squid
+ maintains a table of metadata. The table entries are (name, value)
+ pairs shared among eCAP and ICAP exchanges. The table is destroyed
+ with the master transaction.
+
+ This option specifies the table entry names that Squid must accept
+ from and forward to the adaptation transactions.
+
+ An ICAP REQMOD or RESPMOD transaction may set an entry in the
+ shared table by returning an ICAP header field with a name
+ specified in adaptation_masterx_shared_names. Squid will store
+ and forward that ICAP header field to subsequent ICAP
+ transactions within the same master transaction scope.
+
+ Only one shared entry name is supported at this time.
+
+Example:
+# share authentication information among ICAP services
+adaptation_masterx_shared_names X-Subscriber-ID
+DOC_END
+
+NAME: icap_retry
+TYPE: acl_access
+IFDEF: ICAP_CLIENT
+LOC: Adaptation::Icap::TheConfig.repeat
+DEFAULT: none
+DEFAULT_IF_NONE: deny all
+DOC_START
+ This ACL determines which retriable ICAP transactions are
+ retried. Transactions that received a complete ICAP response
+ and did not have to consume or produce HTTP bodies to receive
+ that response are usually retriable.
+
+ icap_retry allow|deny [!]aclname ...
+
+ Squid automatically retries some ICAP I/O timeouts and errors
+ due to persistent connection race conditions.
+
+ See also: icap_retry_limit
+DOC_END
+
+NAME: icap_retry_limit
+TYPE: int
+IFDEF: ICAP_CLIENT
+LOC: Adaptation::Icap::TheConfig.repeat_limit
+DEFAULT: 0
+DOC_START
+ Limits the number of retries allowed. When set to zero (default),
+ no retries are allowed.
+
+ Communication errors due to persistent connection race
+ conditions are unavoidable, automatically retried, and do not
+ count against this limit.
+
+ See also: icap_retry
+DOC_END
+
+
 COMMENT_START
  DNS OPTIONS
  -----------------------------------------------------------------------------