Mailing List Archive: logging problems

I was trying to stay silent, but need to report some non-fatal
problems with logging...

If a client aborts a connection the logfiles *can* tell lies.

Access log might record everything as ok, error log can record nothing or
the wrong information.

I can see aborted CGI logged as 200 "OK" in access_log with
nothing in the error_log.

All aborted requests are incorrectly logged "send timed out" which is
what 0.6.5 and earlier did.

Unless there's a reason to keep logging in this way, a fix for
could be

in timeout()
sprintf(errstr,"%s timed out for %s",
timeout_name ? timeout_name : "request",
current_conn->remote_name);

becoming

if (sig == SIGPIPE)
sprintf(errstr,"%s. Connection with %s lost",
timeout_name ? timeout_name : "request",
current_conn->remote_name);
else
sprintf(errstr,"%s timed out for %s",
timeout_name ? timeout_name : "request",
current_conn->remote_name);

More worrying is that an aborted request can be logged as if nothing
was wrong, e.g. (note the varying byte counts which are understandable)

[Fri Jul 28 09:11:31 1995] send. Connection with ooo.lanl.gov lost
[Fri Jul 28 09:11:36 1995] send. Connection with ooo.lanl.gov lost

ooo.lanl.gov - - [28/Jul/1995:09:11:31 -0600] "GET /anim5.asis HTTP/1.0" 200 98304
ooo.lanl.gov - - [28/Jul/1995:09:11:36 -0600] "GET /anim5.asis HTTP/1.0" 200 81920

Maybe that's a desired effect; recording what was requested and how much
of it was sent before the problem occured, but it doesn't correspond with
<= 0.6.5 logging procedure. Earlier discussion about logging suggests there's
no clean way to add info to CLF to indicate that the request didn't complete
as expected.

fix/ignore/whatever.

rob

From: Rob Hartill <hartill@ooo.lanl.gov>
Date: Fri, 28 Jul 95 9:43:18 MDT

I was trying to stay silent, but need to report some non-fatal
problems with logging...

If a client aborts a connection the logfiles *can* tell lies.

Access log might record everything as ok, error log can record nothing or
the wrong information.

I believe it's at least consistent with the old Apache behavior (as
you note for one gripe out of two).

I can see aborted CGI logged as 200 "OK" in access_log with
nothing in the error_log.

All aborted requests are incorrectly logged "send timed out" which is
what 0.6.5 and earlier did.

Unless there's a reason to keep logging in this way, a fix for
could be... [snip]

Hmmm... this would have been better as a patch, if you can manage that,
but aside from the wording of an error log entry like

"send directory. Connection with foo.com lost"

it looks OK, and (unlike messing with the sub_request stuff) I can't
see how it could break anything. What the heck.

More worrying is that an aborted request can be logged as if nothing
was wrong, e.g. (note the varying byte counts which are understandable)

[Fri Jul 28 09:11:31 1995] send. Connection with ooo.lanl.gov lost
[Fri Jul 28 09:11:36 1995] send. Connection with ooo.lanl.gov lost

ooo.lanl.gov - - [28/Jul/1995:09:11:31 -0600] "GET /anim5.asis HTTP/1.0" 200 98304
ooo.lanl.gov - - [28/Jul/1995:09:11:36 -0600] "GET /anim5.asis HTTP/1.0" 200 81920

Maybe that's a desired effect; recording what was requested and how much
of it was sent before the problem occured, but it doesn't correspond with
<= 0.6.5 logging procedure.

Ummm... are you sure it doesn't? The usual SIGPIPE handler for Apache
0.6.x is the function send_fd_timed_out, which very definitely does
log the transaction, and I've seen at least one conversation on
c.i.w.s.u. which stated a preference for this behavior in preference
to what NetSite does (which is to log the transaction as if it had
run to completion whether it had or not --- Rob M. noted that the
actual bytes-written counts are not likely to be completely accurate
anyway, because of stuff left hanging in the kernel buffers; the other
guy said that even a ballpark estimate of bytes lost to aborts was
better than nothing).

rst