Cowboy throws "400 Bad Request" but nothing logged in logger

[hubertlepicki]

So one of my employees stumbled upon this issue:
https://groups.google.com/forum/#!msg/elixir-lang-core/Iz0PFye8iXs/6Lzzq8ZgEwAJ

Basically we have some large cookies that exceeded the configured request headers size set in Cowboy. The workaround in the discussion helped.

But the issue I want o report is that there was nothing logged onto Phoenix console. I have been poking around, and I think it's because the response status was 400, while Plug's cowboy "translator" kicks in only for 500+ responses. Specifically this is this code:

https://github.com/elixir-lang/plug/blob/master/lib/plug/adapters/translator.ex#L28

Is this expected behavior? I have found it confusing, and it led to some wasted time - if I saw the error on the console I would sort it out sooner.

I'm happy to submit PR with a fix if we should also log "400 Bad request".

[josevalim]

@hubertlepicki I don't think we are ignoring those requests because plug is not involved. But I may be wrong. I would love if you could further investigate this.

[hubertlepicki]

ok that may be the case too that plug does not even kick in while cowboy crashes. Let me add logging for everything and see what the result is, if we can catch those 400s at all here

[hubertlepicki]

.Yeah you are right, Plug does not even kick in and cannot catch this exception. However, I found a way to catch it:

 config :my_app, MyApp.Endpoint,                                                                                                                  
   http: [port: 4000, protocol_options: [                                                                                                                    
     onresponse: fn(arg1, arg2, arg3, arg4) ->                                                                                                               
       if arg1 == 400 do                                                                                                                                     
         IO.puts "BANG";                                                                                                                                     
       end                                                                                                                                                   
       arg4                                                                                                                                                  
     end                                                                                                                                                     
     ]                                                                                                                                                       
   ]

It looks like Cowboy's onresponse handler is the only way that exceptions that happen in Cowboy can be caught.

Maybe we should provide a default onresponse handler and ship it with Phoenix (or Plug or both independently) so that we can log those?

[hubertlepicki]

@josevalim @chrismccord what do you guys think of above? It sort of feels weird to me that we do not log that cowboy crashed, returning 400, while at the same Phoenix is responsible about starting Cowboy.

[josevalim]

I am not sure yet. One alternative is to open up a discussion on Cowboy and see if they could log on such cases as well.

[hubertlepicki]

So as above in ninenines/cowboy#962 onresponse handler is the only way to do it, apparently :(.

I think the philosophy behind Cowboy's approach is that it's really up to you how and why you log stuff. It's embeddable web server, so it's developer's responsibility to maintain configuration and implement logging. In our case, I think whatever code sets up Cowboy should attempt to log the requests, error statuses and error messages intercepted from Cowboy, and to some extent this is happening. But that's not true if the request never hits elixir app.

[hubertlepicki]

If this is rather not worth further investigation or solution, we'd be prob better closing it?

[josevalim]

I think on_response is probably a good way to handle this but I do not have cycles to put on Plug lately. So I will be able to get back at this just in a month or two, sorry. :)

[josevalim]

Sorry for the delay. @hubertlepicki how can we improve this? I am not sure if we can detect that particular event from Cowboy to log, if so, we should maybe do that? Btw, there are other cases where Cowboy will also just refuse the request, like if you send too many headers or long header names, although those are usually for security reasons.

[josevalim]

So I was taking a look at this and apparently there is no way to know why onresponse is being called. So we can't really say it is about exceeding a maximum header size.

[pezra]

@hubertlepicki's config suggestion works great in development mode but it fails for an exrm production build. For example:

Cannot add file sys.config to tar file - [{error,{31,erl_parse,["syntax error before: ",["Fun"]]}}]

Is there a way of setting onresponse of cowboy outside of configuration that needs to be compiled into sys.config?

[pezra]

I found an approach that works for my application: https://github.com/pezra/phoenix_cowboy_logging

Comments or suggestions welcome.

[sb8244]

Thanks for closing this via commit. I ran into the issue and look forward to upgrading to get the logging in the future.

Feedback: it may be worth documenting this problem somewhere on Phoenix docs, before the error occurs. It would be surprising to run into this error without knowing about it previously, and you'll really only see it in production usually, especially if on a subdomain based organization.