Re: unicorn log attack?

Re: unicorn log attack?

[Eric Wong]

Lawrence Pit <lawrencepit@icloud.com> wrote:
> Hi Eric,
> 
> I'm writing to you directly instead of to the unicorn-public list.

Which got your HTML email tarpitted in my spam folder instead of
being bounced back right away so you could fix it :)

> I noticed yesterday our unicorn.log files, which are usually tiny,
> were gigantic in size. Fortunately, this was caused by a friendly
> attack, but had they persisted I think we would've run out of
> diskspace (of which we would've been warned in advance, so we
> could've dealt with the situation I suppose had it happened)
> 
> Upon inspection it seems requests were received as shown below (
> I've cut out the middle part of the value that was part of the form
> body that was posted )
> 
> The log statement is printed out by unicorn.rb method +log_error+.
> 
> I'm not sure this is a unicorn issue, and thinking more an issue of
> how we developers should deal with repeatedly receiving the same
> sort of (sometimes very large) exceptions? Any advice?

Right, not a unicorn issue :)

Use logrotate or similar, compress your logs frequently, be
mindful of what you dump from your app; and watch your disk
usage (which you seem to be doing already), but that includes
emails :)

In ancient times (perhaps it was the Mongrel days), the server
itself would dump the contents of bad HTTP requests for
debugging; but given the amount of probes/scans I saw: it wasn't
worth it.  We don't even log things like aborted/dropped
connections.

Since the backtrace below clearly shows the error happened from
something your application was doing; I don't consider it the
responsibility of the app server to sanitize it.

> ps. if you want to reply via the list that's fine by me.

Done :) but I've shortened the backtrace for readability

> E, [2016-01-26T11:23:49.499928 srv23 28932] unicorn: app error:
> invalid %-encoding (stri%26%23%30%30%32%

<snip>

> [ CUT VERY LARGE VALUE ]

<snip :>

> (ArgumentError)
> /usr/local/lib/ruby/2.2.0/uri/common.rb:382:in
> `decode_www_form_component'
> /rack-1.5.5/lib/rack/utils.rb:42:in
> `unescape'
> /rack-1.5.5/lib/rack/utils.rb:105:in
> `block (2 levels) in parse_nested_query'

<snip>  These definitely aren't called from code in unicorn itself.

> /rack-1.5.5/lib/rack/urlmap.rb:50:in
> `each'
> /rack-1.5.5/lib/rack/urlmap.rb:50:in
> `call'
> /unicorn-5.0.1/lib/unicorn/http_server.rb:562:in
> `process_client'
> /unicorn-5.0.1/lib/unicorn/oob_gc.rb:70:in
> `process_client'
> /unicorn-5.0.1/lib/unicorn/http_server.rb:658:in
> `worker_loop'

Re: unicorn log attack?

[Lawrence Pit]

Hi Eric,

> but that includes emails :)

Yeah, sorry about the email format :[  Hope this time it's as expected.

> Since the backtrace below clearly shows the error happened from
> something your application was doing;

.. if you count ruby MRI and rack as my application. ;) All this
happens way before it touches what I would call my application. But
yes, I could insert my own middleware before the first rack middleware
and deal with it.

> I don't consider it the responsibility of the app server to sanitize it.

fwiw, I agree :) ... similarly, why consider it the responsibility of
the app server to log it?  it is an application level error, not a
unicorn error.

Rack's spec doesn't state how to deal with exceptions in return to
@app.call. Python's PEP 0333 says a bit more, along the lines of that
applications should try to trap their own, internal errors. I'll go
for that then.


PS.

> In ancient times (perhaps it was the Mongrel days), the server
> itself would dump the contents of bad HTTP requests for
> debugging; but given the amount of probes/scans I saw: it wasn't
> worth it.  We don't even log things like aborted/dropped
> connections.

Yes, nice. :)

The request I'm seeing is also a bad HTTP request (invalid
%-encoding). To illustrate:

curl -v -X POST "http://localhost:8080/?foo=bar%0abaz%xx"

will have unicorn responds with a 400 Bad Request, handling
Unicorn::HttpParserError. The request doesn't enter @app.call(...).
And indeed unicorn doesn't even bother logging anything about this
request.

When sending the same thing as form data:

curl -v -X POST -d "foo=bar%0abaz%xx" "http://localhost:8080/"

then this will result in a 500 error and unicorn will log the posted
value and stacktrace (provided Rack::Request.new(env).POST is called
anywhere and @app doesn't trap its own errors):

app error: invalid %-encoding (bar%0abaz%xx)
(Rack::Utils::InvalidParameterError)


Cheers,
Lawrence

Re: unicorn log attack?

[Eric Wong]

Lawrence Pit <lawrence.pit@gmail.com> wrote:
> Hi Eric,
> 
> > but that includes emails :)
> 
> Yeah, sorry about the email format :[  Hope this time it's as expected.

Yep, you can check for deliverability of any message by
checking: bogomips.org/unicorn-public/$MESSAGE_ID/
(or just look near the top of http://bogomips.org/unicorn-public/)

Nothing hits the list until it hits the archives.

I also suggest always Bcc:-ing yourself instead of having your
mail client save to a "Sent" folder so you can:

a) test deliverability (including the Message-ID: in headers
   if it's added by the server and not your client)

b) get proper threading with any reply-to-all lists you're not
   subscribed to.

> > I don't consider it the responsibility of the app server to sanitize it.
> 
> fwiw, I agree :) ... similarly, why consider it the responsibility of
> the app server to log it?  it is an application level error, not a
> unicorn error.

I'm not entirely sure why unicorn logs it, either.  I think it
was already expected in 2009 for application servers to log
that (thin/mongrel/...?)

Similarly, I don't like the "timeout" feature of unicorn
anymore, either since it encourages hiding bugs.

There's no chance of removing either feature, of course.