Re: requests possibly not reaching the log phase
On Thu, Dec 3, 2009 at 12:43 AM, John ORourke john-p...@o-rourke.org 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
Re: requests possibly not reaching the log phase
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
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
Re: requests possibly not reaching the log phase
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 --
Re: requests possibly not reaching the log phase
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
Re: requests possibly not reaching the log phase
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-p...@o-rourke.org That gives me a few new places to hunt down the issue, thanks. Regards, Paul
Re: requests possibly not reaching the log phase
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
Re: requests possibly not reaching the log phase
John ORourke john-p...@o-rourke.org 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
