#168 nslog: bytes sent in access log wildly incorrect sometimes

[Rusty Brooks]

I was looking at an analysis page for some of my access
logs, when I noticed that the total traffic on some
pages was very large, as in, more than 1000 times
larger than it should be.

When I started tracking down, I found lots of entries
like this in my access.logs:

67.72.101.6 - - [01/Oct/2003:07:47:42 -0500] "HEAD /
HTTP/1.0" 200 4294967160 "" ""

They're not all HEAD requests, but seem to run the gamut.

This is actually against AOLServer 4 beta 10, which I
did not see on the list above.

If people have trouble reproducing this I'll see if I
can set up some kind of test bed.

[Rusty Brooks]

Logged In: YES
user_id=878147

I took a further look. I have a registered procedure that
handles all HEAD requests, and it may be the culprit.
Although, I can't see why what I have would be a problem.

ns_register_proc HEAD /* HEAD_handler ""
proc HEAD_handler { args } {
ns_return 200 [ns_guesstype [ns_conn url]] ""
}

I made a HEAD handler for a reason, largely because some
browsers send a HEAD request before downloading a file, and
some of the file-download urls on my site are dynamically
created, and can take a long time. It does not make much
sense to generate the content to fulfil a head request,
which, as far as I know, browsers use to figure out what the
content-type is going to be.

[Tim Moss]

Logged In: YES
user_id=664829

Interesting that the erroneous size reported is just a few
bytes short of MAXINT (i.e. 2^32 on a 32 bit machine).

Its almost as if the variable containing the content length is
not being initialized or something.

[Rusty Brooks]

Logged In: YES
user_id=878147

Tim,

I agree, that does seem to indicate something, particularly
since I'm returning a 0 length string. Although, of course, the
server does send back a couple hundred bytes of headers and
what not.

Also, the erroneous size varies. Perhaps I could do some
testing to find out, but I have a hunch that the reported size
is a function of MAXINT and the number of bytes actually
returned to the browser.

Can anyone reproduce this? What happens to you (even on
other verisons of AOLServer) when you use my registered
proc for a HEAD (and send a head request)?

[Mark Page]

Logged In: YES
user_id=605103

Your original description states that you are using 4beta10.
This looks very much like a problem which was fixed in
4beta12. You should grab a more recent beta version (12 or
better), and see if you still get this same result.

[Rusty Brooks]

Logged In: YES
user_id=878147

I don't see 4beta12 available for download (the latest I see
is 10). Where can one get it?

[Dossy Shiobara]

Logged In: YES
user_id=21885

Do you have a registered proc or trace filter that handles
the "/" URL?

I'm not sure what the problem is, but I see it in my nslog
access logs now and then as well -- I'm guessing here, but I
think I might know what the common culprit is.

Of course, I'm running CVS HEAD and Mark indicates this was
fixed by 4.0 GM, so it doesn't seem the fix he's referring to
has made the problem go away entirely.

[Jamie Rasmussen]

Logged In: YES
user_id=522678

I also see this in AOLserver 4 on Win32 (custom build, but
approx. 4.05). The problem does not seem to be resolved by
the fix to bug #990439.

[Dossy Shiobara]

Logged In: YES
user_id=21885

As of 4.0.8a, I have not been able to find these incorrect
log entries in any of my access logs. Is anyone else
running either 4.0.7 or 4.0.8a still seeing this issue in
their logs?

I'm going to look at the CVS diffs to see what change went
in that might have fixed this bug.

[Jamie Rasmussen]

Logged In: YES
user_id=522678

This is an important bug for us because we have monthly
transfer limits for customers, and need to be able to
accurately charge them for overage.

I managed to catch this happening on my dev machine, running
AOLserver 4.1 HEAD - I was using the nsadmin EvalTcl page,
which is a registered proc that calls ns_returnnotice after
it has eval'ed your arbitrary code. When it happened, the
page was eval'ing a proc that takes a couple of minutes to run.

The ns_returnnotice eventually causes ReturnCharData
(return.c) to get called. The headers are created and
queued, and their length is subtracted from
connPtr->nContentSent, which is zero at that point, yielding
a negative number. ReturnCharData then calls Ns_WriteConn.
This failed, possibly because of a timeout somewhere, so
nContentSent wasn't increased.

When LogTrace (nslog.c) gets called by RunTraces later,
nContentSent is still negative. It is sprintf'ed as a %u,
which is why the number in the logs is so large.

It appears that in AOLserver 3.3 the headers were written
immediately after creation. I'm not certain where the best
place to fix this in 4 is, the easiest fix might be to just
make Ns_ConnContentSent return 0 if nContentSent < 0.

[Dossy Shiobara]

Logged In: YES
user_id=21885

This sounded like such a great and plausible explanation --
totally made sense. But, I can't reproduce it on either my
latest HEAD build or the latest aolserver_v40_bp build.

Here's the ADP page I'm using as my test case:

<%
ns_sleep 5
ns_returnnotice 200 "test" "this is a test"
%>

I make the HTTP request and immediately disconnect the
socket, causing the Ns_ConnWrite() to (presumably) fail.

Are you using [ns_adp_stream] in the page? How many bytes
is the message (3rd arg) to ns_returnnotice? Perhaps the
problem only manifests when the connection is dropped WHILE
the ns_returnnotice is writing the response message?

Are you running the latest 4.1.0a from HEAD? If you can
still reproduce it with the latest HEAD build, then if you
can narrow down a reproducible test case, I'd really
appreciate it.

[Dossy Shiobara]

Logged In: YES
user_id=21885

Some notes --

The "bytes" column in the logfile, according to Common
Logfile Format in Apache docs, refers to the size of
the "object" returned to the client, not including the
headers.

See: http://httpd.apache.org/docs/logs.html#common

> The last entry indicates the size of the object
> returned to the client, not including the response
> headers. If no content was returned to the client,
> this value will be "-". To log "0" for no content,
> use %B instead.

This explains why we are decrementing
connPtr->nContentSent by the size of the HTTP response
headers in nsd/return.c Ns_ConnQueueHeaders(). (TODO:
What happens when we roll our own headers with
[ns_write] or the C API? Headers are being counted and
logged as part of the bytes ... should document this.)

[Sean Redmond]

Logged In: YES
user_id=43372

This just started happening to me after installing a new
server, in this case with 4.0.7. I thought I'd mention it
since it was asked a couple of months ago if this was the
case. I'm not sure from reading this whether or not it might
be fixed in 4.0.8, or. 9.

[Joe Oldak]

Logged In: YES
user_id=554486

I still occasionally see this in 4.0.10.

It mostly happens when a request processor filter function
returns a not found error, resulting in a 404. (though
happens with code 200 sometimes too)

I notice that connPtr.nContentSent is a signed int, but is
logged as an unsigned. Clearly this int is getting negative
somewhere during the request.

In Ns_ConnQueueHeaders, nContentSent is subtracted from.
Perhaps there's some condition whereby even if no content is
served the length of the header is still subtracted. I've
not followed this through it's just conjecture based on the
evidence I've seen.

Perhaps the simplest fix would be for the nslog module to
check that the int isn't negative before printing?