Re: [squid-users] More access.log questions

wh_at_msdrd.com wrote:
> Hello.
>
> Guys, sorry to post so many questions regarding access.log but, I'm
> trying to understand what is squid actually doing and if is working
> correctly. I don't understand what all the stuff in the access.log file
> are. I check the log everyday. I see something different every time I
> check. Below is the latest on access.log and I don't understand why the
> cache now is "DIRTY", what is assertion failed, 1 swapin MD5 mismatches,
> WARNING: newer swaplog entry for dirno 0, fileno 0000013B, and all those
> weird characters at the end of the log:
> 008.LMP%C2%BB%C2%A6%C2%AB_A.zip?Cache'
> Ì«* 2008 14:02:37 GMT}ARNING: suspicious CR characters in HTTP header
> {Date: Tue, 16 ð@
>
> Please help me understand what's going on.

Well for starters. The access.log does not contain that kind of info.
That stuff should be in the cache.log with the rest of the debug and
administration information.

The FAQ has a good detailed explanation of what the logs do and contain...
http://wiki.squid-cache.org/SquidFaq/SquidLogs

>
> Thanks in advanced.
>
>
>
> 2008/12/15 19:26:19| WARNING: 1 swapin MD5 mismatches

Some data received does not match a validity check that it should.
Probably corrupted data in the disk cache attempting to load.

> 2008/12/15 21:16:13| WARNING: HTTP header contains NULL characters

A client sent Squid an invalid HTTP request. It's being dropped.

> {Host: digdug.divxnetworks.com
> responseType: text/xml
> User-Agent: DivX Player 2.0
> Cookie:
> GUID=FFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFF}
> 2008/12/15 21:41:20| WARNING: 10 swapin MD5 mismatches

A total of 10 objects have now found to be corrupt.

> 2008/12/15 22:06:28| assertion failed: client_side.cc:2479:
> "conn->in.abortedSize == (size_t)conn->bodySizeLeft()"

Squid crashing with received data causing memory or state corruption
somewhere.

> 2008/12/15 22:06:31| Extension method 'NICK' added, enum=27
> 2008/12/15 22:06:31| Starting Squid Cache version 3.0.PRE5 for
> i486-pc-linux-gnu...
> 2008/12/15 22:06:31| Process ID 5075
> 2008/12/15 22:06:31| With 1024 file descriptors available
> 2008/12/15 22:06:31| DNS Socket created at 0.0.0.0, port 38826, FD 8
> 2008/12/15 22:06:31| Adding nameserver 200.42.213.11 from squid.conf
> 2008/12/15 22:06:31| Adding nameserver 200.42.213.21 from squid.conf
> 2008/12/15 22:06:31| Unlinkd pipe opened on FD 13
> 2008/12/15 22:06:31| Swap maxSize 102400000 KB, estimated 7876923
> objects
> 2008/12/15 22:06:31| Target number of buckets: 393846
> 2008/12/15 22:06:31| Using 524288 Store buckets
> 2008/12/15 22:06:31| Max Mem size: 102400 KB
> 2008/12/15 22:06:31| Max Swap size: 102400000 KB
> 2008/12/15 22:06:31| Rebuilding storage in /var/log/squid/cache (DIRTY)

Squid crashed earlier before completing its slow cache validation check.
That caused the swap.state journal to be out of sync with the cache,
corrupt or missing. Turning to paranoid and re-building indexes from a
full raw object scan.

> 2008/12/15 22:06:31| Using Least Load store dir selection
> 2008/12/15 22:06:31| Current Directory is /
> 2008/12/15 22:06:31| Loaded Icons.
> 2008/12/15 22:06:31| Accepting transparently proxied HTTP connections at
> 192.168.2.1, port 3128, FD 15.
> 2008/12/15 22:06:31| HTCP Disabled.
> 2008/12/15 22:06:31| WCCP Disabled.
> 2008/12/15 22:06:31| Ready to serve requests.
> 2008/12/15 22:06:32| Store rebuilding is 1.5% complete
> 2008/12/15 22:06:47| Store rebuilding is 30.2% complete
> 2008/12/15 22:06:50| WARNING: newer swaplog entry for dirno 0, fileno
> 00000062
> 2008/12/15 22:06:55| WARNING: newer swaplog entry for dirno 0, fileno
> 00000132
> 2008/12/15 22:06:55| WARNING: newer swaplog entry for dirno 0, fileno
> 00000135

3 files have been found to differ between the journal and whats actually
in cache.

> 2008/12/15 22:07:02| Store rebuilding is 74.0% complete
> 2008/12/15 22:07:13| Done reading /var/log/squid/cache swaplog (271062
> entries)
> 2008/12/15 22:07:13| Finished rebuilding storage from disk.
> 2008/12/15 22:07:13| 268975 Entries scanned
> 2008/12/15 22:07:13| 0 Invalid entries.
> 2008/12/15 22:07:13| 0 With invalid flags.
> 2008/12/15 22:07:13| 268719 Objects loaded.
> 2008/12/15 22:07:13| 0 Objects expired.
> 2008/12/15 22:07:13| 185 Objects cancelled.
> 2008/12/15 22:07:13| 1788 Duplicate URLs purged.
> 2008/12/15 22:07:13| 26 Swapfile clashes avoided.
> 2008/12/15 22:07:13| Took 41.2 seconds (6517.7 objects/sec).
> 2008/12/15 22:07:13| Beginning Validation Procedure
> 2008/12/15 22:07:13| 262144 Entries Validated so far.
> 2008/12/15 22:07:13| storeLateRelease: released 2 objects
> 2008/12/15 22:07:14| 524288 Entries Validated so far.
> 2008/12/15 22:07:14| Completed Validation Procedure
> 2008/12/15 22:07:14| Validated 533992 Entries
> 2008/12/15 22:07:14| store_swap_size = 15636412
> 2008/12/15 22:14:36| WARNING: 1 swapin MD5 mismatches
> 2008/12/15 22:18:39| ctx: enter level 0:
> 'http://74.125.93.104/translate_c?hl=es&sl=en&u=http://nov1.m.yahoo.net/nov0/Gftp6CpGg29dN5ckuR3PK
> Q__/1228216588/nov_ses_id033_tl5iz1xll0pimbet/www.kqzyfj.com/click-886648-2202641&prev=/search%3Fq%3Dwww.ebey.com%26hl%3Des%26lr%3D%26client
> %3Dfirefox-a%26channel%3Ds%26rls%3Dorg.mozilla:es-ES:official%26hs%3DTNk%26sa%3DG&usg=ALkJrhjCucbvExTxNxW7LnRua07fpKTBmg'
> 2008/12/15 22:18:39| ctx: enter level 1:
> 'http://74.125.93.104/translate_c?hl=es&sl=en&u=http://nov1.m.yahoo.net/nov0/Gftp6CpGg29dN5ckuR3PK
> Q__/1228216588/nov_ses_id033_tl5iz1xll0pimbet/www.kqzyfj.com/click-886648-2202641&prev=/search%3Fq%3Dwww.ebey.com%26hl%3Des%26lr%3D%26client
> %3Dfirefox-a%26channel%3Ds%26rls%3Dorg.mozilla:es-ES:official%26hs%3DTNk%26sa%3DG&usg=ALkJrhjCucbvExTxNxW7LnRua07fpKTBmg'
> 2008/12/15 22:18:39| HttpStateData::cacheableReply: unknown http status
> code in reply
> 2008/12/15 23:14:48| ctx: exit levels from 1 down to 0
> 2008/12/15 23:14:48| WARNING: 10 swapin MD5 mismatches
> 2008/12/15 23:14:58| assertion failed: client_side.cc:2479:
> "conn->in.abortedSize == (size_t)conn->bodySizeLeft()"

Squid crashes again on same invalid request received causing memory
corruption.

... and the cycle continues.

Amos

-- 
Please be using
   Current Stable Squid 2.7.STABLE5 or 3.0.STABLE10
   Current Beta Squid 3.1.0.3 or 3.0.STABLE11-RC1