Mailing List Archive: Apache: Dev

requests possibly not reaching the log phase

Index | Next | Previous | View Threaded

john-perl at o-rourke

Dec 3, 2009, 12:43 AM

Post #1 of 8 (865 views)
Permalink

requests possibly not reaching the log phase

(apologies if this is a dupe, I originally sent from the wrong address)

Hi there,

I have an unusual problem - a large e-commerce site integrated with
Authorize.net for card payments which appears to be failing to log some
requests.

The Authorize.net system makes HTTP POST requests to our server, and
about 1 in every 500 transactions, the Authorize.net system reports a
timeout and there's no trace of the request in our logs. Authorize.net
won't investigate in any detail because their system is reporting that
the request simply timed out.

I'm using mod_perl but not hooking into the logging phase, and using a
mod_log CustomLog directive which outputs the usual stuff, plus request
time, connection state, and PID.

So for now, I'm assuming a request is being sent but the log handler
phase isn't running. The only way I can make this happen in a test
environment is by opening a TCP connection and then closing it without
sending any data. Are there any other reasons the log phase wouldn't be
run?

My next steps are to add simple request logging during the Trans phase,
and failing that, packet sniffing, but this is a live high-traffic
server so I'm trying to avoid that if possible.

cheers
John

minfrin at sharp

Dec 3, 2009, 2:09 AM

Post #2 of 8 (827 views)
Permalink

Re: requests possibly not reaching the log phase [In reply to]

John ORourke wrote:

> I have an unusual problem - a large e-commerce site integrated with
> Authorize.net for card payments which appears to be failing to log some
> requests.
>
> The Authorize.net system makes HTTP POST requests to our server, and
> about 1 in every 500 transactions, the Authorize.net system reports a
> timeout and there's no trace of the request in our logs. Authorize.net
> won't investigate in any detail because their system is reporting that
> the request simply timed out.

If httpd isn't logging anything, the most likely explanation is that the
request isn't reaching httpd at all.

How reliable is your network between their system and yours? Are there
any load balancing devices or other network magic in the way that could
potentially be misconfigured?

> My next steps are to add simple request logging during the Trans phase,
> and failing that, packet sniffing, but this is a live high-traffic
> server so I'm trying to avoid that if possible.

Packet sniffing will answer the question "was there any evidence of a
request", and would probably be the least invasive way of measuring
this. It's always useful to see what the network is actually doing,
rather than what you think it's doing.

Regards,
Graham
--

john-perl at o-rourke

Dec 3, 2009, 2:31 AM

Post #3 of 8 (830 views)
Permalink

Re: requests possibly not reaching the log phase [In reply to]

Graham Leggett wrote:
> If httpd isn't logging anything, the most likely explanation is that the
> request isn't reaching httpd at all.
>
> How reliable is your network between their system and yours? Are there
> any load balancing devices or other network magic in the way that could
> potentially be misconfigured?
>
That gives me a few new places to hunt down the issue, thanks.

> Packet sniffing will answer the question "was there any evidence of a
> request", and would probably be the least invasive way of measuring
> this. It's always useful to see what the network is actually doing,
> rather than what you think it's doing.
>

Definitely - I've decided to bite the bullet and run tshark in the
background, hopefully that will turn up some new information. Debugging
an error which happens at random a few times a month is an interesting
challenge!

cheers
John

sypek.pawel at gmail

Dec 3, 2009, 2:57 AM

Post #4 of 8 (828 views)
Permalink

Re: requests possibly not reaching the log phase [In reply to]

You might also take a look into global apache's error log. There are very
rare cases when PHP (or, probably, other modules) causes segmentation faults
in apache's child processes which prevents any request info to be written to
access log. The last time I had problems with this issue it was caused by
Oracle PHP extension (oci).

2009/12/3 John ORourke <john-perl [at] o-rourke>

> That gives me a few new places to hunt down the issue, thanks.
>

Regards,
Paul

nick at webthing

Dec 3, 2009, 3:30 AM

Post #5 of 8 (826 views)
Permalink

Re: requests possibly not reaching the log phase [In reply to]

On 3 Dec 2009, at 08:43, John ORourke wrote:

> So for now, I'm assuming a request is being sent but the log handler
> phase isn't running.

Seems improbable, though mod_perl adds an extra layer. Graham's
suggestion looks more plausible.

> My next steps are to add simple request logging during the Trans phase,

You can do that by adding a match-and-do-nothing RewriteRule and
setting RewriteLogLevel to log it. Or the third-party mod_security
will log a great deal more for you.

btw, this should be on the users@ list.

--
Nick Kew

poirier at pobox

Dec 3, 2009, 6:20 AM

Post #6 of 8 (832 views)
Permalink

Re: requests possibly not reaching the log phase [In reply to]

John ORourke <john-perl [at] o-rourke> writes:

> The Authorize.net system makes HTTP POST requests to our server, and
> about 1 in every 500 transactions, the Authorize.net system reports a
> timeout and there's no trace of the request in our logs. Authorize.net
> won't investigate in any detail because their system is reporting that
> the request simply timed out.

This could happen in Apache 2 if the web server timed out before reading
the complete request. (Apache 1.3 logs a 408; Apache 2 doesn't; Apache
trunk will log a 4xx of some sort depending on how much of the request
was read.)

If that's what's happening, it would indicate a problem outside of
Apache. You could confirm it by backporting the fix from
https://issues.apache.org/bugzilla/show_bug.cgi?id=39785 so logging
would occur. Then you might need to resort to packet tracing or
something like that to figure out exactly what's going on.

Dan

paul at querna

Dec 5, 2009, 9:50 AM

Post #7 of 8 (757 views)
Permalink

Re: requests possibly not reaching the log phase [In reply to]

On Thu, Dec 3, 2009 at 12:43 AM, John ORourke <john-perl [at] o-rourke> wrote:
> (apologies if this is a dupe, I originally sent from the wrong address)
>
> Hi there,
>
> I have an unusual problem - a large e-commerce site integrated with
> Authorize.net for card payments which appears to be failing to log some
> requests.
>
> The Authorize.net system makes HTTP POST requests to our server, and
> about 1 in every 500 transactions, the Authorize.net system reports a
> timeout and there's no trace of the request in our logs. Authorize.net
> won't investigate in any detail because their system is reporting that
> the request simply timed out.
>
> I'm using mod_perl but not hooking into the logging phase, and using a
> mod_log CustomLog directive which outputs the usual stuff, plus request
> time, connection state, and PID.
>
> So for now, I'm assuming a request is being sent but the log handler
> phase isn't running. The only way I can make this happen in a test
> environment is by opening a TCP connection and then closing it without
> sending any data. Are there any other reasons the log phase wouldn't be
> run?

mod_log_forensic was created for exactly this purpose:
<http://httpd.apache.org/docs/2.2/mod/mod_log_forensic.html>

hope that helps,

Paul

john-perl at o-rourke

Dec 5, 2009, 1:01 PM

Post #8 of 8 (757 views)
Permalink

Re: requests possibly not reaching the log phase [In reply to]

Many thanks for all the answers on this one folks - in summary the
suggestions were packet tracing, mod_security, RewriteLog, and
mod_log_forensic.

I went for packet tracing using tshark with a capture condition to
minimise the performance impact, which worked nicely. The requests in
question were completely missing, so the next possibility is an
occasional DNS lookup failure.

cheers
John

Paul Querna wrote:
>
> mod_log_forensic was created for exactly this purpose:
> <http://httpd.apache.org/docs/2.2/mod/mod_log_forensic.html>
>
> hope that helps,
>
> Paul
>
>

Index | Next | Previous | View Threaded

Interested in having your list archived? Contact Gossamer Threads