Forum: NGINX Recently seeing a bunch of 400s

Announcement (2017-05-07): www.ruby-forum.com is now read-only since I unfortunately do not have the time to support and maintain the forum any more. Please see rubyonrails.org/community and ruby-lang.org/en/community for other Rails- und Ruby-related community platforms.
Ebd4c74ef7dcd6c4e0d44157e7efa49c?d=identicon&s=25 Neil Sheth (Guest)
on 2008-12-03 05:36
(Received via mailing list)
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!
Fda08117336cfde6562315df04b976e8?d=identicon&s=25 Dave Cheney (Guest)
on 2008-12-03 05:48
(Received via mailing list)
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
Ebd4c74ef7dcd6c4e0d44157e7efa49c?d=identicon&s=25 Neil Sheth (Guest)
on 2008-12-03 05:56
(Received via mailing list)
We're seeing a complaint from a user, pretty sure they aren't up to
anything nefarious!
Fda08117336cfde6562315df04b976e8?d=identicon&s=25 Dave Cheney (Guest)
on 2008-12-03 06:29
(Received via mailing list)
What is their complaint ?

What does your error.log say ?

Cheers

Dave

On Tue, 2 Dec 2008 20:49:10 -0800, Neil Sheth <nsheth@gmail.com> wrote:
>> could
>>> I'm seeing a bunch of entries like the following in my nginx access
log:
Ebd4c74ef7dcd6c4e0d44157e7efa49c?d=identicon&s=25 Neil Sheth (Guest)
on 2008-12-03 06:30
(Received via mailing list)
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).
Ebd4c74ef7dcd6c4e0d44157e7efa49c?d=identicon&s=25 Neil Sheth (Guest)
on 2008-12-03 06:39
(Received via mailing list)
They are saying they see a http 400 error page.  I don't see anything
of interest in the error log.
Fda08117336cfde6562315df04b976e8?d=identicon&s=25 Dave Cheney (Guest)
on 2008-12-03 06:41
(Received via mailing list)
On Tue, 2 Dec 2008 21:23:47 -0800, Neil Sheth <nsheth@gmail.com> 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
Ebd4c74ef7dcd6c4e0d44157e7efa49c?d=identicon&s=25 Neil Sheth (Guest)
on 2008-12-03 06:45
(Received via mailing list)
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.
Ebd4c74ef7dcd6c4e0d44157e7efa49c?d=identicon&s=25 Neil Sheth (Guest)
on 2008-12-03 06:57
(Received via mailing list)
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.
Ebd4c74ef7dcd6c4e0d44157e7efa49c?d=identicon&s=25 Neil Sheth (Guest)
on 2008-12-03 07:01
(Received via mailing list)
Likewise, not seeing anything with too many open files.
Fda08117336cfde6562315df04b976e8?d=identicon&s=25 Dave Cheney (Guest)
on 2008-12-03 10:36
(Received via mailing list)
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
B9340b8cfd6b4038536e58327ef648c9?d=identicon&s=25 Arvind Jayaprakash (Guest)
on 2008-12-03 18:31
(Received via mailing list)
Neil Sheth 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.
Ebd4c74ef7dcd6c4e0d44157e7efa49c?d=identicon&s=25 Neil Sheth (Guest)
on 2008-12-12 00:52
(Received via mailing list)
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?
Fda08117336cfde6562315df04b976e8?d=identicon&s=25 Dave Cheney (Guest)
on 2008-12-12 04:28
(Received via mailing list)
> 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
Ebd4c74ef7dcd6c4e0d44157e7efa49c?d=identicon&s=25 Neil Sheth (Guest)
on 2008-12-16 03:15
(Received via mailing list)
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.
Fda08117336cfde6562315df04b976e8?d=identicon&s=25 Dave Cheney (Guest)
on 2008-12-16 08:08
(Received via mailing list)
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().

<speculation>
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.
</speculation>

Cheers

Dave


On Mon, 15 Dec 2008 18:06:06 -0800, Neil Sheth <nsheth@gmail.com> 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
5640e332954fc0006aea97a155ce0afd?d=identicon&s=25 Igor Sysoev (Guest)
on 2008-12-16 09:40
(Received via mailing list)
On Tue, Dec 16, 2008 at 01:55:53AM -0500, Dave Cheney 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.
Fda08117336cfde6562315df04b976e8?d=identicon&s=25 Dave Cheney (Guest)
on 2008-12-16 10:08
(Received via mailing list)
Apologies, I stand corrected.

Cheers

Dave
This topic is locked and can not be replied to.