Mailing List Archive: Apache self-destruct

Apache self-destruct

Nov 14, 1995, 2:47 PM

Post #1 of 11 (562 views)

Apache running at Cardiff went into self destruct mode again a few
moments ago.

I managed to catch it this time by having a cron job check the size of
the error_log every minute and do a sighup if it grew too big and send me
the last 100 lines of the log before it got zapped.

The problem this time originated from 155.207.1.25 (philippos.ccf.auth.gr)
for which the access log reports,

grep 155.207.1.25 access_log
155.207.1.25 - - [14/Nov/1995:20:59:18 +0000] "NULL" 200 225
155.207.1.25 - - [14/Nov/1995:20:59:35 +0000] "NULL" 200 225
155.207.1.25 - - [14/Nov/1995:20:59:50 +0000] "NULL" 200 225
155.207.1.25 - - [14/Nov/1995:21:00:00 +0000] "NULL" 200 225
155.207.1.25 - - [14/Nov/1995:21:00:10 +0000] "NULL" 200 225
155.207.1.25 - - [14/Nov/1995:21:00:22 +0000] "NULL" 200 225
155.207.1.25 - - [14/Nov/1995:21:00:38 +0000] "NULL" 200 225
155.207.1.25 - - [14/Nov/1995:21:01:20 +0000] "NULL" 200 225
155.207.1.25 - - [14/Nov/1995:21:01:31 +0000] "NULL" 200 225
155.207.1.25 - - [14/Nov/1995:21:01:59 +0000] "NULL" 200 225
155.207.1.25 - - [14/Nov/1995:21:02:17 +0000] "NULL" 200 225
155.207.1.25 - - [14/Nov/1995:21:02:29 +0000] "NULL" 200 225
155.207.1.25 - - [14/Nov/1995:21:05:46 +0000] "NULL" 200 225
155.207.1.25 - - [14/Nov/1995:21:06:09 +0000] "NULL" 200 53
155.207.1.25 - - [14/Nov/1995:21:06:58 +0000] "NULL" 200 225
155.207.1.25 - - [14/Nov/1995:21:07:21 +0000] "NULL" 200 225
155.207.1.25 - - [14/Nov/1995:21:07:34 +0000] "NULL" 200 225
155.207.1.25 - - [14/Nov/1995:21:07:44 +0000] "NULL" 200 225
155.207.1.25 - - [14/Nov/1995:21:08:04 +0000] "NULL" 200 225
155.207.1.25 - - [14/Nov/1995:21:08:10 +0000] "NULL" 200 225
155.207.1.25 - - [14/Nov/1995:21:09:48 +0000] "NULL" 200 225
155.207.1.25 - - [14/Nov/1995:21:09:58 +0000] "NULL" 200 3807
155.207.1.25 - - [14/Nov/1995:21:10:39 +0000] "NULL" 200 225
155.207.1.25 - - [14/Nov/1995:21:12:33 +0000] "NULL" 200 3153
155.207.1.25 - - [14/Nov/1995:21:24:22 +0000] "NULL" 200 871

Whether this is a cause or a symptom I don't know.
I've seen "NULL" in the logs before.

Could it be Apache reacting badly to an invalid request?

Anyone have any ideas?

rob

Re: Apache self-destruct [ In reply to ]

Nov 14, 1995, 3:49 PM

Post #2 of 11 (546 views)

> grep 155.207.1.25 access_log
> 155.207.1.25 - - [14/Nov/1995:20:59:18 +0000] "NULL" 200 225
> 155.207.1.25 - - [14/Nov/1995:20:59:35 +0000] "NULL" 200 225
> 155.207.1.25 - - [14/Nov/1995:20:59:50 +0000] "NULL" 200 225

Isn't it "impossible" to record a request of null and a response
of 255 bytes?

I had a look at the code and concluded that "NULL" was the result
of a client timeout, where the client sent no data (or at least
no "\n"), and at the point where that timeout is caught, bytes
sent has been set to -1.

Something is seriously wrong here, or is there a logical explanation?

rob

Re: Apache self-destruct [ In reply to ]

Nov 14, 1995, 4:59 PM

Post #3 of 11 (544 views)

> > grep 155.207.1.25 access_log
> > 155.207.1.25 - - [14/Nov/1995:20:59:18 +0000] "NULL" 200 225
> > 155.207.1.25 - - [14/Nov/1995:20:59:35 +0000] "NULL" 200 225
> > 155.207.1.25 - - [14/Nov/1995:20:59:50 +0000] "NULL" 200 225

I now think these are SSIes being processed when the script times
out or the client aborts.

So is there an oportunity for Apache to monumentally screw up
during interrupted SSI handling?

rob

Re: Apache self-destruct [ In reply to ]

Nov 14, 1995, 5:24 PM

Post #4 of 11 (550 views)

> I had a look at the code and concluded that "NULL" was the result
> of a client timeout, where the client sent no data (or at least
> no "\n"), and at the point where that timeout is caught, bytes
> sent has been set to -1.

A sampling from my logs:
intgate.raleigh.ibm.com - - [14/Nov/1995:11:30:19 -0800] "NULL" 200 8192
tdm76.el.utwente.nl - - [14/Nov/1995:12:04:03 -0800] "NULL" 200 8192
ix-wp2-19.ix.netcom.com - - [14/Nov/1995:12:46:52 -0800] "NULL" 200 8192
ppp014-sf2.sirius.com - - [14/Nov/1995:13:04:28 -0800] "NULL" 200 1772
dewey.disney.com - - [14/Nov/1995:13:42:08 -0800] "NULL" 200 8192
www.copyright.com - - [14/Nov/1995:14:10:36 -0800] "NULL" 200 8192

The majority of my NULL requests give a bytes sent of 8192,
but a few are less/more than that.

>
> Something is seriously wrong here, or is there a logical explanation?
>
> rob
>

--
sameer Voice: 510-601-9777
Community ConneXion FAX: 510-601-9734
The Internet Privacy Provider Dialin: 510-658-6376
http://www.c2.org/ (or login as "guest") sameer@c2.org

Re: Apache self-destruct [ In reply to ]

randy at zyzzyva

Nov 14, 1995, 7:09 PM

Post #5 of 11 (544 views)

>
> > > grep 155.207.1.25 access_log
> > > 155.207.1.25 - - [14/Nov/1995:20:59:18 +0000] "NULL" 200 225
> > > 155.207.1.25 - - [14/Nov/1995:20:59:35 +0000] "NULL" 200 225
> > > 155.207.1.25 - - [14/Nov/1995:20:59:50 +0000] "NULL" 200 225
>
> I now think these are SSIes being processed when the script times
> out or the client aborts.
>
> So is there an oportunity for Apache to monumentally screw up
> during interrupted SSI handling?
>
> rob

225 bytes is about the amount sent by "permission denied:" or
some such...

Re: Apache self-destruct [ In reply to ]

Nov 14, 1995, 7:16 PM

Post #6 of 11 (545 views)

>
> 225 bytes is about the amount sent by "permission denied:" or
> some such...
>

Well there were some permission denied messages in the error_log
but they were bogus (I'd mentioned these before). There's no
authorization protection on the server at all and the files that
were "denied" were accessible to everyone else before, during and
after the problem.

Apache got itself into a hole and couldn't get out.

Re: Apache self-destruct [ In reply to ]

randy at zyzzyva

Nov 14, 1995, 8:30 PM

Post #7 of 11 (544 views)

> >
> > 225 bytes is about the amount sent by "permission denied:" or
> > some such...
> >
>
> Well there were some permission denied messages in the error_log
> but they were bogus (I'd mentioned these before). There's no
> authorization protection on the server at all and the files that
> were "denied" were accessible to everyone else before, during and
> after the problem.
>
> Apache got itself into a hole and couldn't get out.
>
>

I wasn't necessarily suggesting "permission denied"... My
thought was that the server may be counting the bytes returned
from some shell related error like "cannot fork: no more processes"
or something. Knowing you do a lot of CGI at Cardiff, and you
mentioned SSI, perhaps it was related to an #exec include
somewhere... Just rambling...

Re: Apache self-destruct [ In reply to ]

Dirk.vanGulik at jrc

Nov 15, 1995, 5:18 AM

Post #8 of 11 (544 views)

> I had a look at the code and concluded that "NULL" was the result
> of a client timeout, where the client sent no data (or at least
> no "\n"), and at the point where that timeout is caught, bytes
> sent has been set to -1.

I could quite easily reproduce this; If you run out of memory during
the handling of a child process ( I tried an exec include) by making
it fork like hell *AND* you just allow the client to wait forever
to get its data; you get the "NULL" in the access log and an 'Unable
to fork new process' in the error log. The number of bytes send
varies though and I can see no relation with what happened.

We have seen something quite like it. We currently have a rather
virtual server; almost everything is created by perl scripts and
in combination with heavy mSQL queries it is easy to run out of mem.

Does this help ?

Dw.

--
http://me-www.jrc.it/~dirkx http://ewse.ceo.org
DWvGulik@Dialis.xs4all.nl Dirk.vanGulik@jrc.it
+39 332 78 1322 +39 332 78 9549
fax +39 332 78 9185

ISEI/ESBA; The Center For Earth Observation
Joint Research Centre of the European Communities, Ispra, Italy

Re: Apache self-destruct [ In reply to ]

Nov 15, 1995, 8:37 AM

Post #9 of 11 (546 views)

> >
> > Apache got itself into a hole and couldn't get out.
> >
> >
>
> I wasn't necessarily suggesting "permission denied"... My
> thought was that the server may be counting the bytes returned
> from some shell related error like "cannot fork: no more processes"
> or something. Knowing you do a lot of CGI at Cardiff, and you
> mentioned SSI, perhaps it was related to an #exec include
> somewhere... Just rambling...

All ramblings appreciated.

The error_log corn caught another one this morning...

[Wed Nov 15 08:01:01 1995] access to /mnt60/www/Movies/search.html failed for 194.166.19.10, reason: file permissions deny server access
[Wed Nov 15 08:01:01 1995] unable to include backlinks.html in parsed file /mnt60/www/Movies/search.html
[Wed Nov 15 08:01:01 1995] access to /mnt60/www/Movies/search.html failed for 194.166.19.10, reason: file permissions deny server access
[Wed Nov 15 08:01:01 1995] unable to include backlinks.html in parsed file /mnt60/www/Movies/search.html

There's a pile of these.. all bogus.

Re: Apache self-destruct [ In reply to ]

Nov 15, 1995, 8:52 AM

Post #10 of 11 (545 views)

So is there an oportunity for Apache to monumentally screw up
during interrupted SSI handling?

Ooooops... the timeout() function in http_main.c should search back
along the r->prev chain to find the original request before calling
log_transaction. Patch to come...

(... if no one's gotten there first).

rst

Re: Apache self-destruct [ In reply to ]

Nov 15, 1995, 8:57 AM

Post #11 of 11 (546 views)

> We have seen something quite like it. We currently have a rather
> virtual server; almost everything is created by perl scripts and
> in combination with heavy mSQL queries it is easy to run out of mem.

After a recent 32->64Mb upgrade, memory isn't too scarce a resource
at the moment, and there's always a ton of virtual memory waiting to
be used.

I have MaxClients set to 25, so there's a safety mechanism there to
stop too many processes being created. (Once the Sparc5 hits 25 apache's
it's sliding down a slope to self destruction, hence the safety limit)

rob