Hello,
I’m seeing a bunch of entries like the following in my nginx access log:
88.147.21.24 - - [02/Dec/2008:04:16:43 -0600] “-” 400 0 “-” “-”
72.14.204.136 - - [02/Dec/2008:04:16:43 -0600] “-” 400 0 “-” “-”
88.147.21.24 - - [02/Dec/2008:04:16:46 -0600] “-” 400 0 “-” “-”
88.147.21.24 - - [02/Dec/2008:04:16:48 -0600] “-” 400 0 “-” “-”
88.147.21.24 - - [02/Dec/2008:04:16:51 -0600] “-” 400 0 “-” “-”
72.39.110.147 - - [02/Dec/2008:04:16:53 -0600] “-” 400 0 “-” “-”
88.147.21.24 - - [02/Dec/2008:04:16:54 -0600] “-” 400 0 “-” “-”
67.165.72.106 - - [02/Dec/2008:04:16:56 -0600] “-” 400 0 “-” “-”
88.147.21.24 - - [02/Dec/2008:04:16:57 -0600] “-” 400 0 “-” “-”
82.37.232.219 - - [02/Dec/2008:04:17:00 -0600] “-” 400 0 “-” “-”
220.255.7.179 - - [02/Dec/2008:04:17:39 -0600] “-” 400 0 “-” “-”
220.255.7.218 - - [02/Dec/2008:04:17:39 -0600] “-” 400 0 “-” “-”
72.21.243.194 - - [02/Dec/2008:04:17:41 -0600] “-” 400 0 “-” “-”
220.255.7.141 - - [02/Dec/2008:04:17:41 -0600] “-” 400 0 “-” “-”
220.255.7.162 - - [02/Dec/2008:04:17:42 -0600] “-” 400 0 “-” “-”
220.255.7.184 - - [02/Dec/2008:04:17:42 -0600] “-” 400 0 “-” “-”
and so on . . .
I’m running 0.6.32. A bit of a loss as to where to start looking -
any suggestions?
Thanks!
They are most likely bots probing port 80 on your server, then closing
the
connection without sending a request.
Whois and host suggest that those are home ip’s on cable modems. You
could
try running P0f or tcpdumping the traffic to see what they are doing.
Cheers
Dave
We’re seeing a complaint from a user, pretty sure they aren’t up to
anything nefarious!
What is their complaint ?
What does your error.log say ?
Cheers
Dave
On Tue, 2 Dec 2008 20:49:10 -0800, Neil S. [email protected] wrote:
could
I’m seeing a bunch of entries like the following in my nginx access
log:
They are saying they see a http 400 error page. I don’t see anything
of interest in the error log.
Even seeing it in the log from one of Google’s ips. I’ll look into
p0f / tcpdump (not familiar with either). Anything else suggested?
Not sure where the request is getting malformed (if that’s what’s
going on).
On Tue, 2 Dec 2008 21:23:47 -0800, Neil S. [email protected] wrote:
Even seeing it in the log from one of Google’s ips. I’ll look into
p0f / tcpdump (not familiar with either). Anything else suggested?
Not sure where the request is getting malformed (if that’s what’s
going on).
Check your error.log, lsof your nginx workers, you may be out of file
descriptors. Check dmesg and your syslog, your machine may be limiting
connections.
(just some guesses)
Cheers
Dave
Sorry - anything in particular I’m looking for to indicate a
connections limit? I’ve seen that in the past, but received
appropriate messages in the nginx error log. Not seeing anything
relevant in the error log this time.
The majority of requests seem to be getting through - looking at the
log files for the past 2 days, looks like I’m seeing about 20k of
these 400 entries a day. For some of those IP addresses, some of the
requests “get through” but others return the 400. I checked the
access logs on my backend apache servers, and it doesn’t look like
these requests ever get there. We are serving our images directly
from nginx, but it’s difficult to see what request is causing this
error.
Likewise, not seeing anything with too many open files.
Hmmm,
How regularly does the line show up in your logs ? If its every minute
or so, then you could try tcpdumping the packets for a minute or so
then filter through for the IP that was recorded as the problem to
figure out exactly what they requested.
Cheers
Dave
Neil S. wrote:
88.147.21.24 - - [02/Dec/2008:04:16:54 -0600] “-” 400 0 “-” “-”
67.165.72.106 - - [02/Dec/2008:04:16:56 -0600] “-” 400 0 “-” “-”
88.147.21.24 - - [02/Dec/2008:04:16:57 -0600] “-” 400 0 “-” “-”
82.37.232.219 - - [02/Dec/2008:04:17:00 -0600] “-” 400 0 “-” “-”
220.255.7.179 - - [02/Dec/2008:04:17:39 -0600] “-” 400 0 “-” “-”
220.255.7.218 - - [02/Dec/2008:04:17:39 -0600] “-” 400 0 “-” “-”
72.21.243.194 - - [02/Dec/2008:04:17:41 -0600] “-” 400 0 “-” “-”
220.255.7.141 - - [02/Dec/2008:04:17:41 -0600] “-” 400 0 “-” “-”
220.255.7.162 - - [02/Dec/2008:04:17:42 -0600] “-” 400 0 “-” “-”
220.255.7.184 - - [02/Dec/2008:04:17:42 -0600] “-” 400 0 “-” “-”
The first dash indicates that the server did not receive a legal http
request. So there was a network connection to the port, but no http
request was sent on it.
You would need a network dump to figure out what bytes are being sent if
any for these connections. This is almost certainly not a problem with
this instance of nginx; the problem should be elsewhere.
Just an update -
Looking at a tcpdump for a specific case, figuring that basically a
first packet comes, but our server didn’t expect it (could be due to
the fact that there was no original handshake to establish the
connection or our server closed the connection but the remote machine
didn’t get the packet to realize it was closed), that’s why our host
replies with RST flag, saying that the packet was unexpected and that
the record of the connection should be closed on the other side. And
it records it with the 400 error in the access file, logging that some
garbage came, and that it correctly reset the connection.
Not sure what’s causing that. I happened to get one of our users on
the phone, who’s experiencing this. If she connects directly to one
of our backend webservers, the request is successful. Connecting to
our front-end nginx box, however, gives nothing but 400s and the
following error message in her browser:
he connection to the server was reset while the page was loading
the network link was interrupted while negotiating a connection
Any additional thoughts? Could be a problem with networking or routing?
I’m not fully knowledgeable about the network layer, so my explanation
may have been incorrect. I asked our hosting provider to look at it,
thinking it could be something they could help with, this was their
response:
From looking over packet dumps I have collected, this appears to be a
client-side issue and not something caused by the server.
The requests resulting in 400 error codes appear to correspond to the
client opening and then closing the connection. In the packet dump, I
see the clients initiate the connection with a SYN and then immediate
close it with FIN, ACK or RST, ACK. Similar behavior exists for 499
errors except the client sends a HTTP request before closing the
connection.
The clients appear to be aborting the connection and then momentarily
later retrying it. Maybe they think the page isn’t loading and retry
it.
I see another ongoing thread about 400s with firefox, perhaps I’m
experiencing the same issue.
Looking at a tcpdump for a specific case, figuring that basically a
first packet comes, but our server didn’t expect it (could be due to
the fact that there was no original handshake to establish the
connection or our server closed the connection but the remote machine
didn’t get the packet to realize it was closed), that’s why our host
replies with RST flag, saying that the packet was unexpected and that
the record of the connection should be closed on the other side. And
it records it with the 400 error in the access file, logging that some
garbage came, and that it correctly reset the connection.
That doesn’t make sense. If you send a packet to a port without
establishing a connection you’ll get a RST, but that comes from the tcp
stack, the application waiting on select() or accept() will be
completely
unaware of the failed connection attempt. Unless, of course, there is a
bug
in your OS’s TCP stack.
Cheers
Dave
499 is nginx’s error code for ‘client closed connection without
receiving
the whole body’, that is, they pressed the stop button on their browser,
or
navigated away. It’s generally harmless
If you see this pattern
client → SYN → nginx
client ← SYN/ACK ← nginx
client → SYN/ACK → nginx
client → FIN → nginx
then nginx will have accepted the connection and you will get a 400 in
the
access log
however this
client → SYN → nginx
client ← SYN/ACK → nginx
client → RST → nginx
is not a complete TCP connection, and nginx will not return from
accept().
Browsers open several TCP connections to request resources from a page,
it
could be that the browser is proactively opening secondary connections
as
it sends the intial request. This request is returned with a 400 error
code
because of the cookie error, and so the browser closes any outstanding
secondary TCP connections.
Cheers
Dave
On Mon, 15 Dec 2008 18:06:06 -0800, Neil S. [email protected] wrote:
client opening and then closing the connection. In the packet dump, I
didn’t get the packet to realize it was closed), that’s why our host
replies with RST flag, saying that the packet was unexpected and that
the record of the connection should be closed on the other side. And
it records it with the 400 error in the access file, logging that some
garbage came, and that it correctly reset the connection.
That doesn’t make sense. If you send a packet to a port without
establishing a connection you’ll get a RST, but that comes from the tcp
stack, the application waiting on select() or accept() will be
completely
Apologies, I stand corrected.
Cheers
Dave
On Tue, Dec 16, 2008 at 01:55:53AM -0500, Dave C. wrote:
client --> FIN --> nginx
then nginx will have accepted the connection and you will get a 400 in the
access log
No, according to src/http/ngx_http_request.h:
/*
- HTTP does not define the code for the case when a client closed
- the connection while we are processing its request so we introduce
- own code to log such situation when a client has closed the
connection
- before we even try to send the HTTP header to it
*/
#define NGX_HTTP_CLIENT_CLOSED_REQUEST 499
So, the above pattern will result in 400, if nginx has catched to
accept()
before FIN has been received or in this error: “accept() failed (53:
Software
caused connection abort) while accepting new connection on 0.0.0.0:80”,
if nginx has called accept after FIN has been received.
499 means that nginx has got a whole request, but did not send anything
to client.