[squid-users] Seeking insight into zeros, negative values in log: 2.6.STABLE18

[Amos Jeffries]

On 4/08/2016 9:52 p.m., Henry S. Thompson wrote:
> Amos Jeffries writes:
> 
>> On 4/08/2016 2:36 a.m., Henry S. Thompson wrote:
>>> I'm trying to do some summary statistics based on log files from our
>>> 2.6.STABLE18 setup.
>>
>> Please upgrade. The current 3.5.20 release can do everything that
>> Squid-2.6 could do, and a lot more useful stuff besides.
> 
> I'd love to, but it's out of my hands, much higher up :-(.
> 
> Thanks for your help below.
> 
>>>  2) Leaving aside those cases, I see a modest handful (1 in 7000) of 0
>>>     values in the size field, e.g.
>>>
>>>     1402741879.726 114 ... TCP_MISS/200 0 GET http://... DIRECT/... image/gif
>>>     1402771557.693 176 ... TCP_HIT/200 0 GET http://... NONE/- image/gif
>>>
>>>     How should these be understood?
>>
>> A response with no body payload. It happens. Usually with "web bug" type
>> images used for tracking.
>> Or maybe the image was something like a captcha and the script producing
>> it crashed with no data sent.
> 
> But documentation claims size field includes headers, and clearly
> (image/gif) at least a Content-type header was sent...

Nope. The reply message header (maybe more, or not) was received from
the server but not sent to the client. The second case it only got as
far as loading from disk and not yet sending.

At the lowest level it was likely the attempt to write(2) those reply
details to the client that detected the connection was closed/aborted
already by the other end.

> 
>>>  3) I'm seeing very small numbers (1 in 100000) of negative durations, e.g.
>>>
>>>     1402744620.389 -70 ... TCP_MISS/200 1882 GET http://... DIRECT/... text/xml
>>>     
>>>     How should these be understood?
>>
>> The system clock on your machine went backwards between the request
>> arriving and the response being completely sent. Check for issues in
>> your NTP setup.
> 
> 1000s of times a day?  Seems . . . unlikely.  But I'll try to get the
> sys admin people responsible to investigate.

Squid's simply doing a time fetch from the kernel and subtracting
Start-time from End-time to get a negative.
Note that its on the scale of ~100 milliseconds.

Amos