The logs are a valuable source of information about Squid workloads and performance. The logs record not only access information, but also system configuration errors and resource consumption (eg, memory, disk space). There are several log file maintained by Squid. Some have to be explicitely activated during compile time, others can safely be deactivated during run-time.
There are a few basic points common to all log files. The time stamps logged into the log files are usually UTC seconds unless stated otherwise. The initial time stamp usually contains a millisecond extension.
If you run your Squid from the RunCache script, a file squid.out contains the Squid startup times, and also all fatal errors, e.g. as produced by an assert() failure. If you are not using RunCache, you will not see such a file.
The cache.log file contains the debug and error messages that Squid generates. If you start your Squid using the default RunCache script, or start it with the -s command line option, a copy of certain messages will go into your syslog facilities. It is a matter of personal preferences to use a separate file for the squid log data.
From the area of automatic log file analysis, the cache.log file does not have much to offer. You will usually look into this file for automated error reports, when programming Squid, testing new features, or searching for reasons of a perceived misbehaviour, etc.
The user agent log file is only maintained, if
From the user agent log file you are able to find out about distributation of browsers of your clients. Using this option in conjunction with a loaded production squid might not be the best of all ideas.
The store.log file covers the objects currently kept on disk or removed ones. As a kind of transaction log it is ususally used for debugging purposes. A definitive statement, whether an object resides on your disks is only possible after analysing the complete log file. The release (deletion) of an object may be logged at a later time than the swap out (save to disk).
The store.log file may be of interest to log file analysis which looks into the objects on your disks and the time they spend there, or how many times a hot object was accessed. The latter may be covered by another log file, too. With knowledge of the cache_dir configuration option, this log file allows for a URL to filename mapping without recursing your cache disks. However, the Squid developers recommend to treat store.log primarily as a debug file, and so should you, unless you know what you are doing.
The print format for a store log entry (one line) consists of eleven space-separated columns, compare with the storeLog() function in file src/store_log.c:
"%9d.%03d %-7s %02d %08X %4d %9d %9d %9d %s %d/%d %s %s\n"
The timestamp when the line was logged in UTC with a millisecond fraction.
The action the object was sumitted to, compare with src/store_log.c:
The cache_dir number this object was stored into, starting at 0 for your first cache_dir line.
The file number for the object storage file. Please note that the path to this file is calculated according to your cache_dir configuration.
A file number of FFFFFFFF denominates "memory only" objects. Any action code for such a file number refers to an object which existed only in memory, not on disk. For instance, if a RELEASE code was logged with file number FFFFFFFF, the object existed only in memory, and was released from memory.
The HTTP reply status code.
The value of the HTTP "Date: " reply header.
The value of the HTTP "Last-Modified: " reply header.
The value of the HTTP "Expires: " reply header.
The HTTP "Content-Type" major value, or "unknown" if it cannot be determined.
This column consists of two slash separated fields:
If the advertised (or expected) length is missing, it will be set to zero. If the advertised length is not zero, but not equal to the real length, the object will be realeased from the cache.
The request method for the object, e.g. GET.
The key to the object, usually the URL.
The timestamp format for the columns Date to Expires are all expressed in UTC seconds. The actual values are parsed from the HTTP reply headers. An unparsable header is represented by a value of -1, and a missing header is represented by a value of -2.
The column key usually contains just the URL of the object. Some objects though will never become public. Thus the key is said to include a unique integer number and the request method in addition to the URL.
This logfile exists for Squid-1.0 only. The format is
[date] URL peerstatus peerhost
Most log file analysis program are based on the entries in access.log. Currently, there are two file formats possible for the log file, depending on your configuration for the emulate_httpd_log option. By default, Squid will log in its native log file format. If the above option is enabled, Squid will log in the common log file format as defined by the CERN web daemon.
The common log file format contains other information than the native log file, and less. The native format contains more information for the admin interested in cache evaluation.
The Common Logfile Format is used by numerous HTTP servers. This format consists of the following seven fields:
remotehost rfc931 authuser [date] "method URL" status bytes
It is parsable by a variety of tools. The common format contains different information than the native log file format. The HTTP version is logged, which is not logged in native log file format.
The native format is different for different major versions of Squid. For Squid-1.0 it is:
time elapsed remotehost code/status/peerstatus bytes method URL
For Squid-1.1, the information from the hierarchy.log was moved into access.log. The format is:
time elapsed remotehost code/status bytes method URL rfc931 peerstatus/peerhost type
For Squid-2 the columns stay the same, though the content within may change a little.
The native log file format logs more and different information than the common log file format: the request duration, some timeout information, the next upstream server address, and the content type.
There exist tools, which convert one file format into the other. Please mind that even though the log formats share most information, both formats contain information which is not part of the other format, and thus this part of the information is lost when converting. Especially converting back and forth is not possible without loss.
squid2common.pl is a conversion utility, which converts any of the squid log file formats into the old CERN proxy style output. There exist tools to analyse, evaluate and graph results from that format.
It is recommended though to use Squid's native log format due to its greater amount of information made available for later analysis. The print format line for native access.log entries looks like this:
"%9d.%03d %6d %s %s/%03d %d %s %s %s %s%s/%s %s"
Therefore, an access.log entry usually consists of (at least) 10 columns separated by one ore more spaces:
A Unix timestamp as UTC seconds with a millisecond resolution. You can convert Unix timestamps into something more human readable using this short perl script:
#! /usr/bin/perl -p
s/^\d+\.\d+/localtime $&/e;
The elapsed time considers how many milliseconds the transaction busied the cache. It differs in interpretation between TCP and UDP:
Please note that the entries are logged after the reply finished being sent, not during the lifetime of the transaction.
The IP address of the requesting instance, the client IP address. The client_netmask configuration option can distort the clients for data protection reasons, but it makes analysis more difficult. Often it is better to use one of the log file anonymizers.
Also, the log_fqdn configuration option may log the fully qualified domain name of the client instead of the dotted quad. The use of that option is discouraged due to its performance impact.
This column is made up of two entries separated by a slash. This column encodes the transaction result:
Several codes from older versions are no longer available, were renamed, or split. Especially the ERR_ codes do not seem to appear in the log file any more. Also refer to section Squid result codes for details on the codes no longer available in Squid-2.
The NOVM versions and Squid-2 also rely on the Unix buffer cache, thus you will see less TCP_MEM_HITs than with a Squid-1. Basically, the NOVM feature relies on read() to obtain an object, but due to the kernel buffer cache, no disk activity is needed. Only small objects (below 8KByte) are kept in Squid's part of main memory.
The size is the amount of data delivered to the client. Mind that this does not constitute the net object size, as headers are also counted. Also, failed requests may deliver an error page, the size of which is also logged here.
The request method to obtain an object. Please refer to section request-methods for available methods. If you turned off log_icp_queries in your configuration, you will not see (and thus unable to analyse) ICP exchanges. The PURGE method is only available, if you have an ACL for ``method purge'' enabled in your configuration file.
This column contains the URL requested. Please note that the log file may contain whitespaces for the URI. The default configuration for uri_whitespace denies whitespaces, though.
The eigth column may contain the ident lookups for the requesting client. Since ident lookups have performance impact, the default configuration turns ident_loookups off. If turned off, or no ident information is available, a ``-'' will be logged.
The hierarchy information consists of three items:
The content type of the object as seen in the HTTP reply header. Please note that ICP exchanges usually don't have any content type, and thus are logged ``-''. Also, some weird replies have content types ``:'' or even empty ones.
There may be two more columns in the access.log, if the (debug) option log_mime_headers is enabled In this case, the HTTP request headers are logged between a ``['' and a ``]'', and the HTTP reply headers are also logged between ``['' and ``]''. All control characters like CR and LF are URL-escaped, but spaces are not escaped! Parsers should watch out for this.
The TCP_ codes refer to requests on the HTTP port (usually 3128). The UDP_ codes refer to requests on the ICP port (usually 3130). If ICP logging was disabled using the log_icp_queries option, no ICP replies will be logged.
The following result codes were taken from a Squid-2, compare with the log_tags struct in src/access_log.c:
A valid copy of the requested object was in the cache.
The requested object was not in the cache.
The requested object was cached but STALE. The IMS query for the object resulted in "304 not modified".
The requested object was cached but STALE. The IMS query failed and the stale object was delivered.
The requested object was cached but STALE. The IMS query returned the new content.
The client issued a "no-cache" pragma, or some analogous cache control command along with the request. Thus, the cache has to refetch the object.
The client issued an IMS request for an object which was in the cache and fresh.
The object was believed to be in the cache, but could not be accessed.
Request for a negatively cached object, e.g. "404 not found", for which the cache believes to know that it is inaccessible. Also refer to the explainations for negative_ttl in your squid.conf file.
A valid copy of the requested object was in the cache and it was in memory, thus avoiding disk accesses.
Access was denied for this request.
The requested object was retrieved from the cache during offline mode. The offline mode never validates any object, see offline_mode in squid.conf file.
A valid copy of the requested object was in the cache.
The requested object is not in this cache.
Access was denied for this request.
An invalid request was received.
During "-Y" startup, or during frequent failures, a cache in hit only mode will return either UDP_HIT or this code. Neighbours will thus only fetch hits.
Seen with errors and cachemgr requests.
The following codes are no longer available in Squid-2:
Errors are now contained in the status code.
See: TCP_CLIENT_REFRESH_MISS.
See: TCP_SWAPFAIL_MISS.
Deleted, TCP_IMS_HIT used instead.
Hit objects are no longer available.
See: UDP_MISS_NOFETCH.
These are taken from RFC 2616 and verified for Squid. Squid-2 uses almost all codes except 307 (Temporary Redirect), 416 (Request Range Not Satisfiable), and 417 (Expectation Failed). Extra codes include 0 for a result code being unavailable, and 600 to signal an invalid header, a proxy error. Also, some definitions were added as for RFC 2518 (WebDAV). Yes, there are really two entries for status code 424, compare with http_status in src/enums.h:
000 Used mostly with UDP traffic. 100 Continue 101 Switching Protocols *102 Processing 200 OK 201 Created 202 Accepted 203 Non-Authoritative Information 204 No Content 205 Reset Content 206 Partial Content *207 Multi Status 300 Multiple Choices 301 Moved Permanently 302 Moved Temporarily 303 See Other 304 Not Modified 305 Use Proxy [307 Temporary Redirect] 400 Bad Request 401 Unauthorized 402 Payment Required 403 Forbidden 404 Not Found 405 Method Not Allowed 406 Not Acceptable 407 Proxy Authentication Required 408 Request Timeout 409 Conflict 410 Gone 411 Length Required 412 Precondition Failed 413 Request Entity Too Large 414 Request URI Too Large 415 Unsupported Media Type [416 Request Range Not Satisfiable] [417 Expectation Failed] *424 Locked *424 Failed Dependency *433 Unprocessable Entity 500 Internal Server Error 501 Not Implemented 502 Bad Gateway 503 Service Unavailable 504 Gateway Timeout 505 HTTP Version Not Supported *507 Insufficient Storage 600 Squid header parsing error
Squid recognizes several request methods as defined in RFC 2616. Newer versions of Squid (2.2.STABLE5 and above) also recognize RFC 2518 ``HTTP Extensions for Distributed Authoring -- WEBDAV'' extensions.
method defined cachabil. meaning --------- ---------- ---------- ------------------------------------------- GET HTTP/0.9 possibly object retrieval and simple searches. HEAD HTTP/1.0 possibly metadata retrieval. POST HTTP/1.0 CC or Exp. submit data (to a program). PUT HTTP/1.1 never upload data (e.g. to a file). DELETE HTTP/1.1 never remove resource (e.g. file). TRACE HTTP/1.1 never appl. layer trace of request route. OPTIONS HTTP/1.1 never request available comm. options. CONNECT HTTP/1.1r3 never tunnel SSL connection. ICP_QUERY Squid never used for ICP based exchanges. PURGE Squid never remove object from cache. PROPFIND rfc2518 ? retrieve properties of an object. PROPATCH rfc2518 ? change properties of an object. MKCOL rfc2518 never create a new collection. COPY rfc2518 never create a duplicate of src in dst. MOVE rfc2518 never atomically move src to dst. LOCK rfc2518 never lock an object against modifications. UNLOCK rfc2518 never unlock an object.
The following hierarchy codes are used with Squid-2:
For TCP HIT, TCP failures, cachemgr requests and all UDP requests, there is no hierarchy information.
The object was fetched from the origin server.
The object was fetched from a sibling cache which replied with UDP_HIT.
The object was requested from a parent cache which replied with UDP_HIT.
No ICP queries were sent. This parent was chosen because it was marked ``default'' in the config file.
The object was requested from the only parent appropriate for the given URL.
The object was fetched from the first parent in the list of parents.
The object was fetched from the origin server, because no parents existed for the given URL.
The object was fetched from the parent with the fastest (possibly weighted) round trip time.
This parent was chosen, because it included the the lowest RTT measurement to the origin server. See also the closests-only peer configuration option.
The parent selection was based on our own RTT measurements.
Our own RTT measurements returned a shorter time than any parent.
The object could not be requested because of a firewall configuration, see also never_direct and related material, and no parents were available.
The origin site was chosen, because the source ping arrived fastest.
No ICP replies were received from any parent. The parent was chosen, because it was marked for round robin in the config file and had the lowest usage count.
The peer was chosen, because the cache digest predicted a hit. This option was later replaced in order to distinguish between parents and siblings.
The parent was chosen, because the cache digest predicted a hit.
The sibling was chosen, because the cache digest predicted a hit.
This output seems to be unused?
The peer was selected by CARP.
part of src/peer_select.c:hier_strings[].
part of src/peer_select.c:hier_strings[].
Almost any of these may be preceded by 'TIMEOUT_' if the two-second (default) timeout occurs waiting for all ICP replies to arrive from neighbors, see also the icp_query_timeout configuration option.
The following hierarchy codes were removed from Squid-2:
code meaning -------------------- ------------------------------------------------- PARENT_UDP_HIT_OBJ hit objects are not longer available. SIBLING_UDP_HIT_OBJ hit objects are not longer available. SSL_PARENT_MISS SSL can now be handled by squid. FIREWALL_IP_DIRECT No special logging for hosts inside the firewall. LOCAL_IP_DIRECT No special logging for local networks.
This file has a rather unfortunate name. It also is often called the swap log. It is a record of every cache object written to disk. It is read when Squid starts up to ``reload'' the cache. If you remove this file when squid is NOT running, you will effectively wipe out your cache contents. If you remove this file while squid IS running, you can easily recreate it. The safest way is to simply shutdown the running process:
% squid -k shutdown
This will disrupt service, but at least you will have your swap log
back.
Alternatively, you can tell squid to rotate its log files. This also
causes a clean swap log to be written.
% squid -k rotate
For Squid-1.1, there are six fields:
In Squid-2, the swap log file is now called swap.state. This is a binary file that includes MD5 checksums, and StoreEntry fields. Please see the Programmers Guide for information on the contents and format of that file.
If you remove swap.state while Squid is running, simply send Squid the signal to rotate its log files:
% squid -k rotate
Alternatively, you can tell Squid to shutdown and it will
rewrite this file before it exits.
If you remove the swap.state while Squid is not running, you will not lose your entire cache. In this case, Squid will scan all of the cache directories and read each swap file to rebuild the cache. This can take a very long time, so you'll have to be patient.
By default the swap.state file is stored in the top-level of each cache_dir. You can move the logs to a different location with the cache_swap_log option.
You should never delete access.log, store.log, cache.log, or swap.state while Squid is running. With Unix, you can delete a file when a process has the file opened. However, the filesystem space is not reclaimed until the process closes the file.
If you accidentally delete swap.state while Squid is running, you can recover it by following the instructions in the previous questions. If you delete the others while Squid is running, you can not recover them.
The correct way to maintain your log files is with Squid's ``rotate'' feature. You should rotate your log files at least once per day. The current log files are closed and then renamed with numeric extensions (.0, .1, etc). If you want to, you can write your own scripts to archive or remove the old log files. If not, Squid will only keep up to logfile_rotate versions of each log file. The logfile rotation procedure also writes a clean swap.state file, but it does not leave numbered versions of the old files.
If you set logfile_rotate to 0, Squid simply closes and then re-opens the logs. This allows third-party logfile management systems, such as newsyslog, to maintain the log files.
To rotate Squid's logs, simple use this command:
squid -k rotate
For example, use this cron entry to rotate the logs at midnight:
0 0 * * * /usr/local/squid/bin/squid -k rotate
For Squid 2.4:
To disable access.log:
cache_access_log /dev/null
To disable store.log:
cache_store_log none
To disable cache.log:
cache_log /dev/null
For Squid 2.5:
To disable access.log:
cache_access_log none
To disable store.log:
cache_store_log none
To disable cache.log:
cache_log /dev/null
Note : It is a bad idea to disable the cache.log because this file contains many important status and debugging messages. However, if you really want to, you can.
Warning : If /dev/null is specified to any of the above log files, logfile rotate must also be set to 0 or else risk Squid rotating away /dev/null making it a plain log file.
Tip : Instead of disabling the log files, it is advisable to use a smaller value for logfile_rotate and properly rotating Squid's log files in your cron. That way, your log files are more controllable and self-maintained by your system.
You need to rotate your log files with a cron job. For example:
0 0 * * * /usr/local/squid/bin/squid -k rotate
If you set logfile_rotate to 0, Squid simply closes and then re-opens the logs. This allows third-party logfile management systems, such as newsyslog, to maintain the log files.
The preferred log file for analysis is the access.log file in native format. For long term evaluations, the log file should be obtained at regular intervals. Squid offers an easy to use API for rotating log files, in order that they may be moved (or removed) without disturbing the cache operations in progress. The procedures were described above.
Depending on the disk space allocated for log file storage, it is recommended to set up a cron job which rotates the log files every 24, 12, or 8 hour. You will need to set your logfile_rotate to a sufficiently large number. During a time of some idleness, you can safely transfer the log files to your analysis host in one burst.
Before transport, the log files can be compressed during off-peak time. On the analysis host, the log file are concatinated into one file, so one file for 24 hours is the yield. Also note that with log_icp_queries enabled, you might have around 1 GB of uncompressed log information per day and busy cache. Look into you cache manager info page to make an educated guess on the size of your log files.
The EU project DESIRE developed some some basic rules to obey when handling and processing log files:
This message means that the requested object was in ``Delete Behind'' mode and the user aborted the transfer. An object will go into ``Delete Behind'' mode if
This means that a timeout occurred while the object was being transferred. Most likely the retrieval of this object was very slow (or it stalled before finishing) and the user aborted the request. However, depending on your settings for quick_abort, Squid may have continued to try retrieving the object. Squid imposes a maximum amount of time on all open sockets, so after some amount of time the stalled request was aborted and logged win an ERR_LIFETIME_EXP message.
I've been asked to retrieve an object which was accidentally destroyed at the source for recovery. So, how do I figure out where the things are so I can copy them out and strip off the headers?
The following method applies only to the Squid-1.1 versions:
Use grep to find the named object (Url) in the cache/log file. The first field in this file is an integer file number.
Then, find the file fileno-to-pathname.pl from the ``scripts'' directory of the Squid source distribution. The usage is
perl fileno-to-pathname.pl [-c squid.conf]
file numbers are read on stdin, and pathnames are printed on
stdout.
Sort of. You can use store.log to find out if a particular response was cached.
Cached responses are logged with the SWAPOUT tag. Uncached responses are logged with the RELEASE tag.
However, your analysis must also consider that when a cached response is removed from the cache (for example due to cache replacement) it is also logged in store.log with the RELEASE tag. To differentiate these two, you can look at the filenumber (3rd) field. When an uncachable response is released, the filenumber is FFFFFFFF (-1). Any other filenumber indicates a cached response was released.