400 Bad Request/request failed: error reading the headers details

Forum Moderators: phranque

Message Too Old, No Replies

400 Bad Request/request failed: error reading the headers details

see details for 400 Bad Request

freizz

7:07 pm on Jan 30, 2008 (gmt 0)

Hi,

I see "request failed: error reading the headers" in my error_log. I see it about 10 times per hour on a server that has about 2m ist per hour. It's not much, but enough to be a problem. The client gets a 400 Bad Request then that happens.

My question is:

How can I see what was sent to apache to cause it to disregard it as a bad request?

Thanx in advance
FreiZz

coopster

7:22 pm on Jan 30, 2008 (gmt 0)

Look for the same timestamp from the same IP address in your

access_log

freizz

7:40 pm on Jan 30, 2008 (gmt 0)

Good Idea, but the records don't seem to match

** I'm using
/usr/sbin/rotatelogs /var/log/httpd/log.web 1800
/usr/sbin/rotatelogs /var/log/httpd/log.error 3600

[root@minime httpd]# grep 400 log.web.1201719600
minime.semethingelse.com 192.168.15.12 - - [30/Jan/2008:14:03:02 -0500] "POST /scr/show.php HTTP/1.0" 400 312 "-" "-"
minime. semethingelse.com 192.168.15.12 - - [30/Jan/2008:14:03:21 -0500] "POST /scr/show.php HTTP/1.0" 400 312 "-" "-"
minime.semethingelse.com 192.168.15.12 - - [30/Jan/2008:14:06:09 -0500] "POST /scr/show.php HTTP/1.0" 400 312 "-" "-"
minime.semethingelse.com 192.168.15.10 - - [30/Jan/2008:14:13:36 -0500] "POST /scr/show.php HTTP/1.0" 400 312 "-" "-"
minime.semethingelse.com 192.168.15.10 - - [30/Jan/2008:14:16:28 -0500] "POST /scr/show.php HTTP/1.0" 400 312 "-" "-"
minime.semethingelse.com 192.168.15.10 - - [30/Jan/2008:14:20:07 -0500] "POST /scr/show.php HTTP/1.0" 400 312 "-" "-"
[root@minime httpd]# cat log.error.1201719600
[Wed Jan 30 14:05:02 2008] [error] [client 192.168.15.12] request failed: error reading the headers
[Wed Jan 30 14:05:21 2008] [error] [client 192.168.15.12] request failed: error reading the headers
[Wed Jan 30 14:08:27 2008] [error] [client 192.168.15.12] request failed: error reading the headers
[Wed Jan 30 14:15:36 2008] [error] [client 192.168.15.10] request failed: error reading the headers
[Wed Jan 30 14:18:28 2008] [error] [client 192.168.15.10] request failed: error reading the headers
[Wed Jan 30 14:22:07 2008] [error] [client 192.168.15.10] request failed: error reading the headers
[Wed Jan 30 14:33:07 2008] [error] [client 192.168.15.12] request failed: error reading the headers
[root@minime httpd]#

freizz

7:42 pm on Jan 30, 2008 (gmt 0)

and /scr/show.php is called millions of times per day... the exact same way

phranque

12:51 am on Jan 31, 2008 (gmt 0)

it's probably a maliciously crafted HTTP POST request designed to execute arbitrary code on the server by causing a heap overflow in php.
a server limit has been exceeded such as number or length of request header field(s).

freizz

12:28 pm on Jan 31, 2008 (gmt 0)

Well most of them are.

But the ones I am investigating are legit. Clients that are making these requests day in and day out are complaining that sometimes they get a 400 error and they garanty that they send the request the same way they always do.

Since they are POST i don't see the full content in the log file.

Is there a way I could see it?

FreiZz

phranque

1:27 pm on Jan 31, 2008 (gmt 0)

try (temporarily) adding %{error-notes}n to your log format string.

this could be helpful:
[httpd.apache.org...]

freizz

4:30 pm on Feb 4, 2008 (gmt 0)

Hi Phranque!

%{error-notes}n did not help much, but it did hint me to something else. I played with dumpio to log everything and see what I would get the error.

Turns out, one second is a realllllly long time.

Seriously, what happened was that I got the POST command then i would just not get anything else. 120 seconds later the 400 Error pour be generated because it timedout.

Turns out the problem was a faulty switch that would drop packets. Connected the machine on another healthy switch... problem solved.

Thank you all for your help

FreiZz