Don't log warnings about unsupported methods

[jroper]

If I make a request to an Akka HTTP server with an unsupported method, I get this:

$ curl http://localhost:9000 -X REMOTE -D -
HTTP/1.1 501 Not Implemented
Date: Thu, 14 Dec 2017 05:01:53 GMT
Connection: close
Content-Type: text/plain; charset=UTF-8
Content-Length: 23

Unsupported HTTP method

As you can see, that contains everything I need to know about the error. As the client, it's my responsibility to use only methods that the server understands, so that error only concerns me. So it therefore doesn't make sense for the server to also log an error, because it's not the servers problem, and there's nothing the server can do about it.

I run an internet facing website, and so far this month, about 90% of my logs have been polluted by Akka HTTP logging a warning about unsupported methods:

https://gist.github.com/jroper/e466351520c28b44cb402b9c95c1ffe9

Note that the 2017-12-07 16:44:05,352 [warn] a.a.ActorSystemImpl - Illegal request, responding with status '400 Bad Request': Request is missing required Hostheader: 'Host' header value of request towww.server110.com:443 doesn't match request target authority: Host header: Some(Host: www.server110.com:443) messages are actually caused by Akka HTTP not supporting CONNECT, but the wrong error message was logged (and this was fixed in #1315). I just upgraded to the latest Akka HTTP, and that error message has now been replaced with an error saying that CONNECT is not supported.

Generally, these requests come from bots scanning for vulnerable systems - they are beyond my control, and part of the ambient noise that all internet facing HTTP servers see. For Akka HTTP to tell the client what the problem is and log it as a warning is like catching an exception, logging it, and rethrowing it - it's an anti pattern.

These logs should be at debug level by default, or at very least, configurable to be logged at debug level, but I do think that since adequate feedback is provided to the client, the default should be debug.

[raboof]

I do think this depends on context: when running an 'internal' service I do think it would be good to log such errors, to make (possibly cross-team) debugging easier.

Indeed for an internet-facing endpoint it might also be good to be aware of such problems, but they should probably be aggregated as metrics rather than emitted as warning events.

Would setting akka.http.server.parsing.error-logging-verbosity to off make sense, or does that also turn off logging we really do want to see as events? If this is a good approach we should perhaps document it?

[jrudolph]

We once established the policy to log these kinds of errors with WARNING log level (see #30).

As @raboof, I also think that it very much depends on context how to log those. It's should be possible to configure your logging solution to turn certain kinds of messages down if that's necessary.

[jroper]

Would setting akka.http.server.parsing.error-logging-verbosity to off also suppress warnings generated by response headers? Because those are important to see.

[raboof]

Would setting akka.http.server.parsing.error-logging-verbosity to off also suppress warnings generated by response headers? Because those are important to see.

No, it's about parsing, so it would only affect incoming headers (so request headers for servers and response headers for clients)

[jroper]

When running an "internal" service, you will have many other mechanisms for diagnosing unsupported methods - not least to mention, you control the client there, so you can see the clients errors - and again, in 99% of scenarios, the error will be in the client and should be fixed in the client, so the appropriate place to notify is the client.

Of course, it does make sense that occasionally, you might want to see that in the server. This is the case for every single client error, sometimes it will be nice to see that error in the server. But definitely not by default, you would no more want to log client errors as you would want to log client successes - both you would only turn on when debugging.

If talking about policies, how about this policy? Log any message associated with a 1xx, 2xx, 3xx and 4xx status code at debug, since such a response is generated by the server when it's behaving as expected. However, if the server is behaving exceptionally, ie, messages associated with a 5xx error, then log it. Then, a configuration option could be added to tell Akka HTTP to log all messages associated with 4xx status codes at warning - this would be useful beyond just this use case, since it's not just unsupported methods that would be interesting in the internal case, but anything that doesn't match, whether it's unsupported media type or forbidden or not found or unauthenticated calls, all of those indicate a potential problem that if you wanted to help debug an internal client, logging in the server would make sense.