Access Log help!!!

[allworknoplay]

Hi guys! I didn't know who else to go to so I decided to sign up here and give it a shot....

 

I have your typical LAMP setup. I have an application that runs on windows that access's our API

running on apache so there is no user-end interface.

 

What I am seeing is that at the end of the access log, usually the last number tells you how many

KB's were sent back to the client. Sometimes I don't always get that though, it seems to be very random.

 

So I would ALWAYS get a 200 status code, but right next to it, sometimes I get a "-" symbol.

 

According to apache, it means that nothing was sent back to the client, and this is bad because I always

send back an "OK" message so that my application knows it was successful.

 

There are no errors in my apache access log, nor are there any errors in my php log....

 

I just cannot seem to figure out why I am getting this!!

 

Can anyone help shed some light on this?

 

Thanks...

 

Kim

 

[madmax]

Sure these aren't HEAD requests? (200 response)

 

Have you remapped other responses somehow (say 304?)

 

I'd guess that only headers are being sent with no content byte count

[allworknoplay]

I always get 200, I've never seen any other status code, so I guess that's a good thing right? hehehe...

 

I forgot to mention that this only occurs during a POST method. We use GET also but for something else

and it always gets sent back some kind of response. Here's an example of what I am seeing...perhaps it might

jog someone's memory??

 

[17/Jan/2008:23:39:31 -0500] "POST /api_program.php HTTP/1.1" 200 -

 

But then a minute later when our program reports in again it works!!

 

[17/Jan/2008:24:20:11 -0500] "POST /api_program.php HTTP/1.1" 200 211

 

It almost kinda seems a hit or miss deal which makes it VERY difficult for me to replicate and figure out.

 

 

[allworknoplay]

I found this on linuxsupport.com....

 

 

4. I get loads of entries such as "GET / HTTP/1.0" 200 1179 "-" "Apache/2.2.3 (Unix) (internal dummy connection)" in my access logs.

 

This is a way for Apache to signal its children that it's time to die. You probably want to check the MinSpareServers, MaxSpareServers and MacRequestsPerChild settings in the httpd.conf file. The following settings are recommended for a reasonably busy server on the internet.

 

StartServers    16

MinSpareServers  8

MaxSpareServers  64

MaxClients        256

MaxRequestsPerChild  4000

 

 

 

Eventhough I'm not using Apache 2.0, I am using 1.3...I am wondering if my MinSpareServers etc are wrong maybe??

This is what I have....

 

 

 

Timeout 100

 

KeepAlive On

 

MaxKeepAliveRequests 200

 

KeepAliveTimeout 2

 

MinSpareServers 15

MaxSpareServers 35

 

StartServers 25

 

MaxClients 256

 

MaxRequestsPerChild 0

 

 

 

 

[allworknoplay]

This is what the document says about the last column after the status code...

 

 

 

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.

[madmax]

The linuxsupport info might be valid but mishandling POST returns seems a wacky way to terminate child processes.

 

I think it would be pretty easy to set up simulated logging from your PHP app to confirm if Apache has inconsistent behavour

 

Can't recall ever seeing this behaviour as I rarely use PHP POST - but I wonder if it might be a PHP bug?

I only found http://bugs.php.net/bug.php?id=22427 - (unfortunately this appears to relate to Win32)

 

Does this only relate to PHP or does other CGI POST code exhibit the same behaviour? Might be worth setting up a few small tests.  You could set up a sequence of repeated PHP POSTs and see if it is "toggling" on/off or if it really is acting at random. Perhaps there might be another trend such as gradual thread death?

 

If it is a feature of child process behaviour then surely it would exhibit the same trends using other forms of CGI?

 

Is the PHP post_max_size set correctly?. Perhaps it might exhibit strange behaviour if not set right?

 

[Daniel0]

The 200 status code means everything is ok.

[allworknoplay]

The linuxsupport info might be valid but mishandling POST returns seems a wacky way to terminate child processes.

 

I think it would be pretty easy to set up simulated logging from your PHP app to confirm if Apache has inconsistent behavour

 

Can't recall ever seeing this behaviour as I rarely use PHP POST - but I wonder if it might be a PHP bug?

I only found http://bugs.php.net/bug.php?id=22427 - (unfortunately this appears to relate to Win32)

 

Does this only relate to PHP or does other CGI POST code exhibit the same behaviour? Might be worth setting up a few small tests.  You could set up a sequence of repeated PHP POSTs and see if it is "toggling" on/off or if it really is acting at random. Perhaps there might be another trend such as gradual thread death?

 

If it is a feature of child process behaviour then surely it would exhibit the same trends using other forms of CGI?

 

Is the PHP post_max_size set correctly?. Perhaps it might exhibit strange behaviour if not set right?

 

 

It's running on a P4 with 2gigs of ram. It's dedicated to nothing but PHP/apache so what I did was totally gave php a ton of memory. I gave the  post size and upload size around 128 megs.

 

What happened was I noticed this on one server and thought perhaps the server was getting hammered too much.

So I went ahead and put in my load balancer that i purchased awhile back. so now i have 2 dedicated apache servers built exactly the same way and BOTH have the same issue!!

 

I built a test box and tried to hammer it and I couldn't get it to say "200 -" but I don't think i hammered it the way

it truly is from my application.

 

I fear this is an issue that I just won't be able to figure out unless I actually get a consultant that can learn how my application works and sits there with me to brainstorm and troubleshoot...

 

=(

 

it's one of those needle in a haystack issues....

 

As for the CGI, we don't use CGI at all...all the apache is doing is serving up our PHP code.

The requests are either POSTS or GETS.

 

It's also pretty recent PHP version as well.....i hate these kind of issues!!!!!!!!!!!!!!

 

Since I gave PHP a ton of memory, I don't think it's a memory issue. What I also did was gave it almost NO memory

and when you do that, you end up getting  a 500 status code....

 

 

 

[allworknoplay]

The 200 status code means everything is ok.

 

hi, the issue isn't the status code, it's the returned bytes column next to it, I'm trying to figure out

why sometimes it's "-" and not bytes...

[madmax]

As for the CGI, we don't use CGI at all...all the apache is doing is serving up our PHP code.

The requests are either POSTS or GETS.

 

No, I probably didn't explain myself properly. IF and only IF using CGI already THEN does CGI trigger the same problem in Apache. ELSEIF NOT using CGI THEN have you tried setting up a CGI based test which might simulate the demands and trigger the same bug?

 

The reason for suggesting this is to try to eliminate PHP from the equation. If you can do this then finding the needle might be easier.

 

I think you're only hope is to worth through using some logical process of elimination and hope you get lucky. If you found, say that CGI under heavy loads can trigger the same problem then you can focus on Apache.

 

Same sort of divide-and-conquer methods might work if looking at PHP perhaps?

Divide and conquer can often work when you really don't have much information about what you're dealing with.

[allworknoplay]

As for the CGI, we don't use CGI at all...all the apache is doing is serving up our PHP code.

The requests are either POSTS or GETS.

 

No, I probably didn't explain myself properly. IF and only IF using CGI already THEN does CGI trigger the same problem in Apache. ELSEIF NOT using CGI THEN have you tried setting up a CGI based test which might simulate the demands and trigger the same bug?

 

The reason for suggesting this is to try to eliminate PHP from the equation. If you can do this then finding the needle might be easier.

 

I think you're only hope is to worth through using some logical process of elimination and hope you get lucky. If you found, say that CGI under heavy loads can trigger the same problem then you can focus on Apache.

 

Same sort of divide-and-conquer methods might work if looking at PHP perhaps?

Divide and conquer can often work when you really don't have much information about what you're dealing with.

 

 

 

OHHHH!! That is a good idea....when you say CGI, does that pretty much mean re-rewriting my code in PERL?

I'm all for trying anything out even if it takes a lot of time, I think a lot of users here are the same in that when something

doesn't work quite right, it bothers you until you figure it out!!!

 

I was hoping the load balancer would help rule things out but it didn't....

I thought it was a bandwidth issue so I upgraded my entire infrastructure to 1GIG....bought a Cisco 2960 since all my

servers already have 1GIG NIC's...

 

But I'm beginning to beleive that it is either PHP(bug), or APACHE(bug), or APACHE(mis-configuration) that is the isssue...

 

[allworknoplay]

I wanted to post my PHP config so you can get an idea....

 

upload_max_filesize = 20M ; Max upload file size

post_max_size = 35M ; Max post size

 

display_errors = Off ; Do not show errors on screen

log_errors = On ; Log errors to log file

error_log = /usr/local/apache/logs/php_errors.log

 

max_execution_time = 75    ; Maximum execution time of each script, in seconds

max_input_time = 75    ; Maximum amount of time each script may spend parsing request data

memory_limit = 64M      ; Maximum amount of memory a script may consume

 

 

I'm thinking maybe trying to bump up all the categories and give everyone 30% more memory to see if

it resolves the issue before I start having to write code in CGI...

 

 

 

[madmax]

OHHHH!! That is a good idea....when you say CGI, does that pretty much mean re-rewriting my code in PERL?

 

Depends on how complex you want your test app to be and this may depend really on how close you want it to mirror what your app is doing. You can knock up a very simple CGI app in seconds which you could loop to throw a few million requests at the server to see if it falls over. I don't know much PERL - I write my CGI apps in Win32/C. I once installed PERL and it came with a wodge of useful CGI test scripts.

 

There is also the apache test util (Apache Bench/AB) which you might prefer to use as a diagnostic.

http://www.debianhelp.co.uk/apacheab.htm  (Win32 AB.EXE if I recall right)

 

Whether that will stress all Apache-side (non PHP) aspects of your system is a moot point however.

I suggest it only as a means of doing a comparative test which *MIGHT* eliminate the need to look at PHP IF you get very lucky!

 

Looking at PHP first is really a scattergun approach to problem solving (or shooting arrows in the dark into a pretty large pool). You may well get lucky but then again you may not. Since PHP is a pretty *big* haystack I'd be inclined to look at the "cheaper" options (in terms of time). As always, binary-chop/divide+conquer is a powerful weapon when you don't have a clue where to look. Unfortunately there is always a tendency to get fixated on something you believe strongly is the the cause, waste many hours and perhaps even give up. (I plead guilty occasionally lol!).

 

Try to eliminate as much of the simple and obvious as possible and leave the "painful" and complex stuff till last

 

[allworknoplay]

Wow Madmax, thank you so much for your thoughts the last few days on both this thread and the new one I just made on keepalives!!!

 

I totally agree, sometimes you almost FEEL you know what the issue is so you must keep banging at it and it may very well

not even be the issue!! I am going to try a few easy methods first like bumping up RAM, or playing with how many httpd servers to create....

 

I just don't want to buy another server and keep buying more hardware to throw at the issue because my instincts tells me

that it's not so much the hardware but either an Apache/PHP configuration, or just bad code somewhere...

 

I am using software called DebugView, I think that is what TCPView is, but I will take a look....

 

 

[allworknoplay]

I gave PHP a lot of memory as well as gave Apache a bunch of extra Min/Max spare servers etc..

 

I basically boosted everything and saw pretty much no difference!!

 

What is interesting though is when I restart apache, I don't see the "-" value for about 10 minutes, then it starts coming

in again, I don't know if that is really useful though...

 

Here's something interesting though. I created a blank file and then accessed that file through firefox.

 

In the access log I got this ........"200 5"

 

So basically I got the OK status with probably 5 bytes header returned....

 

 

So now I am wondering that at random times my API program doesn't even FINISH running? Because that's the

only thing I can think of that would get me the "-" status....

 

 

I wish there was more documentation as to what apache thinks is going on when it gives "200 -". Instead of just

simply saying no bytes returned...I mean...ok, now I know that no bytes are returned but now how do I figure

out why??

 

 

BTW: I modified my blank page and put the command "exit" to try to see if I can make the blank page not finish executing

and I still got the "200 5" status...

 

 

 

 

[allworknoplay]

I found an article that talks about parsing the log file. IT's funny, in the example, he has the "-" behind the 200 status code!

I just wish there was someone who was an authoritative on that darn "-" behind the 200 code....

 

Basic grep and cut commands

Now that you've got the log files onto a machine where you can parse them, it's time to try and locate information in there. Assuming you used the CustomLog format I described in my previous article, a line from your Apache log file will look something like this:

[16/Oct/2003:09:58:15 -0700] "GET /html/rex.html HTTP/1.1" 200 "-" 330

 

Now one task you might do is to check what percentage of your log lines were successful, i.e., returned an HTTP code of 200. In the line above the HTTP return code is the number that appears right before the "-". So your first instinct is probably to just do this to find out the total number of lines in your log file:

 

 

BTW: In debugview, what happens is, in my application, it expects our API to return the status "OK".

So in debugview, if my application doesn't get it, it will say ERROR: cannot communicate with server.

 

When I watch this as my application reports data in, randomly I will get this error....so it seems to coincide with when

the "-" shows up in the access log because if the API isn't returning back the OK status, then the application will give out

the error...

 

 

[allworknoplay]

Hey Madmax!! I think I am beginning to figure something out...

 

As I was watching debugview, I noticed something....

 

I TURNED off my application after it said it tried to POST data right? But after watching the LIVE access log

I saw no attempts to hit the apache server?? So that's why I turned off the application..

 

Then about 1 minute later, I then saw the attempt!! But my application was already turned off!!

 

And there it was! The status code with....... "200 -"

 

 

So there seems to be delay?? Now my only conclusion to that is the apache server is swamped so it puts the attempted access

in queue but perhaps by the time it is ready to take the queue, the data is either lost, dead or just blank...which leads to accessing

the API file but no return....

 

 

This also kinda makes sense because as I said before, when I would restart the apache server, I don't get the "200 -" code until about 10 minutes later....

 

 

So what do you think?? I think I'm close!!!

 

 

[allworknoplay]

Ok here's the latest update...

 

I don't think it is the apache server being "hammered" that is causing the problem anymore.

 

I setup a standalone server built exactly the same way with no other traffic other than my one application.

 

No one knows about this server but me.

 

Upon turning my application on and off, I can actually replicate the "200 -" status. It's success seems to be random.

 

The data is sent via a POST method and the size is roughly 86K....

 

I will keep doing more tests to see why the return status is random.

 

BTW: When it is successful, I get a returned code of "200 14"

 

The 14 number is pretty much the size of my API sending back the "OK" status to my application. Debugview shows success...

 

[trq]

Just a thought, but could this be happening when the client closes there browser / hits stop?

[allworknoplay]

Just a thought, but could this be happening when the client closes there browser / hits stop?

 

 

Yeah I thought of that but you would actually get an error in apache when that happens.

 

Plus my application doesn't involve a browser at all, it's a custom software application that talks to apache/php

behind the scenes...

[allworknoplay]

Ok, I think I have stumbled upon something..

 

My API uses a lot of shell_exec's (it's a function in PHP that let's me basically do linux command line through PHP)

just for kicks, I commented out all the shell_exec's and my application worked!!!

 

(what I mean by worked is, I ALWAYS get a status code back of "200 14". When I uncommented the shell_exec's again,

it went back to "200 -"

 

 

There are only 11 calls to shell_exec but that's a little misleading because based on the data, it can actually loop through

that 100's of times!!

 

So either my application is taking TOO long to run or there is an issue with shell_exec's taking too long to execute...

 

PHP by default is set to 30 seconds execution time but I forgot to enable the error for this so let me see what I get

when I enable this log...

 

 

[allworknoplay]

I replaced my shell_exec's with...fopen function in PHP...

 

My initial test shows back "200 14"....

 

So that's a good thing, I need to have my application run for a couple hours before I know the data

is actually written to the file and not just dropped....

[allworknoplay]

No dice....

 

It seemed to work for awhile and now it's back to "200 -" again...

 

I just don't get it!!!

[madmax]

Debugview won't really be of much use. You need TCPView

 

Throwing memory at it might result in a "lucky shot" but it doesn't divide the "problem field" in half

Reducing by halves is REALLY effective and quick. You have to use stuff like this if you get paid

to do support and accept the reality that for a lot of the time you may not know everything about

a certain product.

 

I doubt seriously if throwing hardware at the problem will fix it. More to the point it may have fixed

it accidentally which is the worst possible situation since you won't actually know what was wrong

in the first place and it is quite likely that after all that time and effort the problem could arise again!.

(eek!).

 

I would tend to trust Apache and if it returns "-" then it is genuinely telling you that for one reason

or another it returned "no content" back. It may not be able. That child/thread may have been

unable to complete the back end transaction but may have successfully returned some sort of response

(perhaps just headers).

 

"-" *should* mean content returned, but headers only (don't quote me on that tho')

 

This would make sense if you don't get it to start with but the problem accelerates. Symptoms of

a bottleneck somewhere or running out of physical resources. Both should be monitorable.

 

This might be running out of resources at the server back end. It may be a chain-interaction say thru

an SQL server or some other bottleneck. Unless you find some way to test selective areas and divide

the problem searching the entire back end really would be needle+haystack stuff.

 

Have you tried turning Apache logs to "debug" level on a very short term basis and watching them in

real time to see if any other errors pop up?? (error.log)

 

I would also check the inbound response from your client-end API to see if, for some reason, it gets

it's knickers in a twist after time and starts sending out "wrong" requests to the server. Also ought to be

loggable if you wrote the client end API

 

Check the obvious, Log stuff, get things pinned down rather than taking random shots.

 

 

[madmax]

Debugview won't really be of much use. You need TCPView

EDIT - oops didn't see page 2!. Now see you are using Debugview on your API so ignore above

 

I am guessing that Shell-exec on a heavily hammered webserver would lead to potential resource issues. Particularly if you get a stuck or delayed thread elsewhere at the O/S level due to other componentry involved with the exec'd program. Once you exec synching events must be a pain since you have minimal or no control over those child processes unless you're very careful how they're excec'd. Are you monitoring or producing any graphs of spawned procs active on the server at any given moment? Might be illuminating.

 

I know ppl use it a lot and get no probems with very simple shell calls but my instinct would be to avoid it if poss. esp when called from a script language which may already have interaction issues and complex heirarchies of dependencies to track/trace/debug.  Can you not get PHP to do the job?