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

[Henry S. Thompson]

Thanks for your patience with this, but still not quite getting it.

I thought there were two cases:

  1) Client drops the connection before the interaction is complete ==
     log shows HTTP result code 000, almost always size 0 as well;

  2) Interaction completed successfully == HTTP result code as from
     cache or remote, size as sent to client.

See below how I can't make that fit with your reply

Amos Jeffries writes:

>>>>  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.

So the simple story I added at the top is wrong, and I should instead
understand that

  1') Log shows size 0 means client dropped the connection before the
      interaction was complete (HTTP result code 000 vs. something else is
      just a question of when the drop was detected);

  2) Interaction completed successfully == HTTP result code as from
     cache or remote, size as sent to client.  0 size can _never_ mean
     all is well, server result was empty, because if all is well at
     least some header info will have been sent.

>>>>  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.

Sorry but I still don't see how two successive fetchs could result in a
decrement (w/o an NTP intervention).  

The negative numbers I'm seeing range up into the low 1000s (of msec,
right?  That's what the squid documentation says, IIRC).

Did you really mean "~100 _milliseconds_"?  My understanding was that
kernel time differences were typically accurate to ~100 _nanoseconds_.

If you can easily tell me where to look in the source, obviously that's
what I should do....

ht
-- 
       Henry S. Thompson, School of Informatics, University of Edinburgh
      10 Crichton Street, Edinburgh EH8 9AB, SCOTLAND -- (44) 131 650-4440
                Fax: (44) 131 650-4587, e-mail: ht at inf.ed.ac.uk
                       URL: http://www.ltg.ed.ac.uk/~ht/
 [mail from me _always_ has a .sig like this -- mail without it is forged spam]