13.3 store.log

The store.log is a record of Squid's decisions to store and remove objects from the cache. Squid creates an entry for each object it stores in the cache, each uncachable object, and each object that is removed by the replacement policy. The log file covers both in-memory and on-disk caches.

The store.log provides the following you can't get from access.log :

• Whether or not a particular response was cached.

• The file number for cached objects. For UFS-based storage schemes, you can convert this to a pathname and examine the contents of the cache file.

• The response's content length: the Content-Length value, and the actual body length.

• Values for the Date , Last-Modified , and Expires headers.

• The response's cache key (i.e., MD5 hash value).

As you can see, this is mostly low-level information you won't need on a daily basis. Unless you do sophisticated analyses, or wish to debug a problem, you can probably get by without the store.log . You can disable it with a special setting:

 cache_store_log none 

As with other log files, Squid appends new store.log entries to the end of the file. A given URI may appear in the file more than once. For example, it gets cached, then released, then cached again. Only the most recent entry reflects the object's current status.

The store.log is text-based and looks something like this:

 1067299212.411 RELEASE -1 FFFFFFFF A5964B32245AC98592D83F9B6EA10B8D 206     1067299212 1064287906 -1 application/octet-stream 6840/6840     GET http://download.windowsupdate.com/msdownload/update/v3-19990518/cab... 1067299212.422 SWAPOUT 02 0005FD5F 6F34570785CACABC8DD01ABA5D73B392 200     1067299210 1057899600 -1 image/gif 1125/1125     GET http://forum.topsportsnet.com/shfimages/nav_members1.gif 1067299212.641 RELEASE -1 FFFFFFFF B0616CB4B7280F67672A40647DD08474 200     1067299212 -1 -1 text/html -1/67191     GET http://www.tlava.com/ 1067299212.671 RELEASE -1 FFFFFFFF 5ECD93934257594825659B596D9444BC 200     1067299023 1034873897 1067299023 image/jpeg 3386/3386     GET http://ebiz0.ipixmedia.com/abc/ebiz/_EBIZ_3922eabf57d44e2a4c3e7cd234a... 1067299212.786 RELEASE -1 FFFFFFFF B388F7B766B307ADEC044A4099946A21 200     1067297755 -1 -1 text/html -1/566     GET http://www.evenflowrocks.com/pages/100303pic15.cfm 1067299212.837 RELEASE -1 FFFFFFFF ABC862C7107F3B7E9FC2D7CA01C8E6A1 304     1067299212 -1 1067299212 unknown -1/0     GET http://ebiz0.ipixmedia.com/abc/ebiz/_EBIZ_3922eabf57d44e2a4c3e7cd234a... 1067299212.859 RELEASE -1 FFFFFFFF 5ED2726D4A3AD83CACC8A01CFDD6082B 304     1066940882 1065063803 -1 application/x-javascript -1/0     GET http://www.bellsouth.com/scripts/header_footer.js 

Each entry contains the following 13 fields:

1: timestamp

The timestamp when the event took place, expressed as seconds since the Unix epoch with millisecond resolution.

2: action

The action taken on the object. This field has three possible values: SWAPOUT , RELEASE , and SO_FAIL .

• A SWAPOUT occurs when Squid successfully completes saving the object data to disk. Some objects, such as those that are negatively cached, are kept in memory, but not on disk. Squid doesn't make a store.log entry for them.

• A SO_FAIL entry indicates that Squid could not completely save the object to disk. Most likely it means that the storage scheme implementation refused to open a new disk file for writing.

• A RELEASE occurs when Squid removes an object from the cache, or decides that the response isn't cachable in the first place.

3: directory number

The directory number is a 7-bit index to the list of cache directories that's written as a decimal number. For objects that aren't saved to disk, this field contains the value -1 .

4: file number

The file number is a 25-bit identifier used internally by Squid. It is written as an 8-character hexadecimal number. The UFS-based storage schemes have an algorithm for mapping file numbers to pathnames (see Section 13.3.1).

Objects that aren't saved to disk don't have a valid file number. For these, the file number field contains FFFFFFFF . This value appears only for RELEASE and SO_FAIL entries.

5: cache key

Squid uses MD5 hash values for the primary index to locate cached objects. The key is based on the request method, URI, and possibly other information.

You might be able to use the cache key to match up store.log entries. Note, however, that an object's cache key can change. This happens, for example, whenever Squid logs a TCP_REFRESH_MISS request in access.log . It looks like this:

 1065837334.045 SWAPOUT ... 554BACBD2CB2A0C38FF9BF4B2239A9E5 ... http://blah 1066031047.925 RELEASE ... 92AE17121926106EB12FA8054064CABA ... http://blah 1066031048.074 SWAPOUT ... 554BACBD2CB2A0C38FF9BF4B2239A9E5 ... http://blah 

So what's going on? The object is originally cached under one key ( 554B.. .). Some time later, Squid receives another request for the object and forwards a validation request to the origin server. When the response comes back with new content, Squid changes the cache key of the old object (to 92AE.. .) so that it can give the new object the correct key ( 554B.. .). The old object is then removed, and the new object is saved to disk.

6: status code

This field shows the HTTP status code of the response, just like access.log. See Table 13-1 for a list of status codes.

7: date

The value of the Date header in the HTTP response, expressed as seconds since the Unix epoch. The value -1 indicates an unparseable Date header, and -2 means the header was entirely absent.

8: last-modified

The value of the Last-Modified header in the HTTP response, expressed as seconds since the Unix epoch. The value -1 indicates an unparseable Last-Modified header, and -2 means the header was entirely absent.

9: expires

The value of the Expires header in the HTTP response, expressed as seconds since the Unix epoch. The value -1 indicates an unparseable Expires header, and -2 means the header was entirely absent.

10: content-type

The value of the Content-Type header in the HTTP response, excluding any media-type parameters. Squid inserts the value unknown if the Content-Type is missing.

11: content-length/ size

This field contains two numbers, separated by a slash. The first is the value of the Content-Length header. A -1 indicates the Content-Length header is absent. The second is the actual size of the HTTP message body. You can use these two numbers to identify partially received responses and origin servers that incorrectly calculate the content length. In most cases, the two numbers are the same.

12: method

The HTTP request method for the object, as in access.log .

13: URI

The final field is the requested URI, as in access.log . This field also has the whitespace problem mentioned in the previous section. However, it is less worrisome here because you can safely ignore any extra fields.

For many of the RELEASE entries, you'll see question marks ( ? ) for the last eight fields. This is because most of those field values come from what Squid calls the MemObject structure. This structure is present only for objects that have just been received, or are being stored entirely in memory. Most of the objects in Squid's cache don't have a MemObject because they exist only on disk. For these, Squid puts question marks in the fields with missing information.

13.3.1 Mapping File Numbers to Pathnames

If you find you need to examine a particular cache file, you can, with some effort, turn a file number into a pathname. You'll also need the directory number, and L1 and L2 values. In the Squid source code, the storeUfsDirFullPath( ) function does this. You can find it in the src/fs/ufs/store_dir_ufs.c file. This short Perl program mimics the current algorithm:

 #!/usr/bin/perl $L1 = 16; $L2 = 256; while (<>) {     $filn = hex($_);     printf("%02X/%02X/%08X\n",         (($filn / $L2) / $L2) % $L1,         ($filn / $L2) % $L2,         $filn); } 

And here's how you can use it:

 % echo 000DCD06  ./fileno-to-pathname.pl 0D/CD/000DCD06 

To find this file in the N th cache_dir , simply go to the corresponding directory and list or view the file:

 % cd /cache2 % ls -l 0D/CD/000DCD06 -rw-------  1 squid  squid  391 Jun  3 12:40 0D/CD/000DCD06 % less 0D/CD/000DCD06