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

Amos.

Thanks for replying. After reviewing this access.log file section, is
sqid working correctly or are there any adjustments I need to make to
make run more smoothly?

Amos Jeffries wrote:
> 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

-- 
*Wilson Hernandez*
Presidente
829.848.9595
809.766.0441
www.msdrd.com <http://www.msdrd.com>
Conservando el medio ambiente