How to log malformed requests which cause cowboy to terminate request?

Phoenix Forum Questions / Help
,
1

Hi!

I’ve got an app which periodically puts into log “Cowboy returned 400 because it was unable to parse the request headers…”. And no any details. After upgrading the app to phoenix 1.5.x messages disappear at all which is even worse than before (but requests still terminate before any Plug). If I start a newly created phoenix app in dev mode:

mix phx.new test_app --no-ecto
....
cd test_app
iex -S mix phx.server

and do a malformed request like curl -H 'Host:' 'http://localhost:4000/' then I got nothing in console and 400 in curl; and if a bad header removed then I got an answer:

 ~/P/G/tmp  curl -v -H 'Host:' 'http://localhost:4000/'                                       Чт 26 ноя 2020 00:41:44
*   Trying 127.0.0.1:4000...
* TCP_NODELAY set
* Connected to localhost (127.0.0.1) port 4000 (#0)
> GET / HTTP/1.1
> User-Agent: curl/7.68.0
> Accept: */*
> 
* Mark bundle as not supporting multiuse
< HTTP/1.1 400 Bad Request
< connection: close
< content-length: 0
< 
* Closing connection 0

# nothing in the app console

 ~/P/G/tmp  curl -v 'http://localhost:4000/'                                                  Чт 26 ноя 2020 00:41:58
*   Trying 127.0.0.1:4000...
* TCP_NODELAY set
* Connected to localhost (127.0.0.1) port 4000 (#0)
> GET / HTTP/1.1
> Host: localhost:4000
> User-Agent: curl/7.68.0
> Accept: */*
> 
* Mark bundle as not supporting multiuse
< HTTP/1.1 200 OK
< cache-control: max-age=0, no-cache, no-store, must-revalidate, post-check=0, pre-check=0
< content-length: 3374
< content-type: text/html; charset=utf-8
< cross-origin-window-policy: deny
< date: Wed, 25 Nov 2020 19:42:01 GMT
< server: Cowboy
< vary: x-requested-with
< x-content-type-options: nosniff
< x-download-options: noopen
< x-frame-options: SAMEORIGIN
< x-permitted-cross-domain-policies: none
< x-request-id: FkrXpUERSlgSUqUAAAFj
< x-xss-protection: 1; mode=block
< set-cookie: _tmp_key=SFMyNTY.g3QAAAABbQAAAAtfY3NyZl90b2tlbm0AAAAYZW9aR0xrMkJsRklSa1huWTFTb0N4MkF5.fiHc1F-YXuaVnX-tyB2dy8ClRUuz7FRluGquVrOcNGg; path=/; HttpOnly
< 
<!DOCTYPE html>
<html lang="en">
  <head>
...
</html>

# normal debug messages in console

The same situation with too big headers, the only change is error “431 Request Header Fields Too Large” but still nothing in console\logs.

So the question: is it possible to catch such initial raw requests somehow? It would be very useful for analysis.

Thanks!

2

So answering to my own question:

I don’t know why Plug.Cowboy doesn’t show 431 via Logger as it should in handle_event/4 but if I manually attach a telemetry handler to the [:cowboy, :request, :early_error] event then I can get logs. Even though they not the logs I need (I would prefer to have the full initial request to analyze what exactly cowboy didn’t like) but better than total silence.

So just make put a handler somewhere:

defmodule MyAppWeb.CowboyLogger do
  @moduledoc false

  require Logger

  def init do
    :telemetry.attach(
      :my_app_cowboy_logger,
      [:cowboy, :request, :early_error],
      &handle_event/4,
      nil
    )
  end

  def handle_event(
        [:cowboy, :request, :early_error],
        _,
        req,
        _
      ) do
    Logger.error("cowboy error: #{inspect(req)}")
  end
end

and then just call somewhere MyAppWeb.CowboyLogger.init(), for example, from MyAppWeb.Telemetry.init/1.

But actually its pretty weird that Plug.Cowboy.handle_event/4 doesn’t work and no errors are shown.

2 Likes