Don't log error for HEAD requests which later match a GET route

[mcserv]

I get this warning in "production" environment, with log level set only to critical.

I'm not sure if it matters for this case, but it's running inside docker container with linux alpine, hosted on heroku, compiled with target x86_64-unknown-linux-musl.

I use latest rocket version (rocket = "0.4") and latest nightly (today's build). Same version for rocket_contrib.

I am also using Tera templating engine fairing, and routing to / like this:

use std::collections::HashMap;

use rocket_contrib::templates::Template;

#[rocket::get("/")]
pub(crate) fn index() -> Template {
    let context = HashMap::<String, String>::new();

    Template::render("index", context)
}

Of course, it's mounted like this:

.mount("/", rocket::routes![routes::website::index])

Accessing / using GET is alright, works as expected.

Rocket claims that it handles HEAD requests automatically if there would be matching GET anyway...

But every time I try to send HEAD request (using https://apitester.com/):

HEAD / HTTP/1.1
Host: sahsahae.herokuapp.com
Accept: */*
User-Agent: Mozilla/5.0 (compatible; Rigor/1.0.0; http://rigor.com)

I get this output:

HTTP/1.1 200 OK
Connection: keep-alive
Content-Length: 657
Content-Type: text/html; charset=utf-8
Date: Tue, 20 Aug 2019 21:52:16 GMT
Server: Rocket
Via: 1.1 vegur

And yet, it displays this error message every time I try to access it using HEAD?

For example, now I requested HEAD 5 times in a row:

2019-08-20T21:56:51.300655+00:00 app[web.1]: Error: No matching routes for HEAD /.
2019-08-20T21:56:51.307382+00:00 heroku[router]: at=info method=HEAD path="/" ... status=200 protocol=https
2019-08-20T21:56:52.291467+00:00 heroku[router]: at=info method=HEAD path="/" ... status=200 protocol=https
2019-08-20T21:56:52.284715+00:00 app[web.1]: Error: No matching routes for HEAD /.
2019-08-20T21:56:52.950319+00:00 app[web.1]: Error: No matching routes for HEAD /.
2019-08-20T21:56:52.957171+00:00 heroku[router]: at=info method=HEAD path="/" ... status=200 protocol=https
2019-08-20T21:56:54.248074+00:00 heroku[router]: at=info method=HEAD path="/" ... status=200 protocol=https
2019-08-20T21:56:54.241197+00:00 app[web.1]: Error: No matching routes for HEAD /.
2019-08-20T21:56:54.934550+00:00 app[web.1]: Error: No matching routes for HEAD /.
2019-08-20T21:56:54.941391+00:00 heroku[router]: at=info method=HEAD path="/" ... status=200 protocol=https

Each time it fails, but returns 200 OK.

What could be the issue?

[jebrosen]

I believe this or almost this was discussed in #606, which was moved to #21. If I remember correctly, the only problem here is the logging: You will get "ERROR: No matching routes for HEAD /" but not the following message that it will be handled anyway by trying the corresponding GET request and the successful response.

[mcserv]

I see, the duplication then seems to be related to the way log levels are handled?

In my opinion, such reroute notice should be debug level log, but for some reason, it also gets sent as a critical type of log, which is the only kind of logs my configuration is set to display.

I was mainly confused because heroku router would forward 200 OK even if rocket itself shows critical Error.

Thanks for clarification, hopefully this will be fixed :)

[SergioBenitez]

@sahsahae That's correct. Effectively, the router comes along and searches for something matching the HEAD request, just as it would any other request. If it fails to find something, it emits an error log indicating so, just like it would for any other request. Unlike any other request, however, the router then tries to find a GET request that otherwise matches, which succeeds (in your case), and the response is then returned. Of course, the error has already been logged at this point, even though it is effectively a false negative.

To provide better behavior here, we would need to hold off on logging the error message until we try a GET request first. If the GET request succeeds, we'd probably want to log a warning instead of an error. If it fails, we can log the error as today.

As the code stands today, I can't find an elegant way to accomplish this. I'll leave this issue open to keep it in mind. It's certainly something we should fix, irrespective of #21.

[shaoxp]

can we config a route with both GET and HEAD method ? this can also help to mitigate the issue here. currently, i am duplicating a route with HEAD to clear the error log.

[jblachly]

can we config a route with both GET and HEAD method ? this can also help to mitigate the issue here. currently, i am duplicating a route with HEAD to clear the error log.

Ideally, HEAD would be automatically generated from the GET route by introspecting on its (successful) return type, no? It should (could) be automatically generated.

[the10thWiz]

While certainly possible, this would require some significant changes to the routes macro, since it would need to mount two routes for every GET route. The current solution also extends to routes that don't take advantage of the codegen, while this solution wouldn't.

[jinakola]

To provide better behavior here, we would need to hold off on logging the error message until we try a GET request first. If the GET request succeeds, we'd probably want to log a warning instead of an error. If it fails, we can log the error as today.

Could this be implemented as always warning if no matching HEAD was found? This way if GET request succeeds we are left with one warning from HEAD and if it fails we are left with one warning from HEAD and one error from GET

[tessus]

@SergioBenitez

As the code stands today, I can't find an elegant way to accomplish this.

What I don't fully understand is why rocket would throw an error message for HEAD, when nobody created a HEAD route.

jjlin mentioned that rocket automatically implements a HEAD route when there's a matching GET route, but I don't understand why this is needed in the first place. If I wanted a HEAD route, I would add one. Why does rocket do this autmatically?

Either way, the solution to this problem is rather obvious. Do not let rocket create a HEAD route when I don't ask for it.

But maybe I am missing something crucial here.

[SergioBenitez]

@tessus There's no HEAD route being created. What's happening is that Rocket is automatically handling HEAD requests for you by checking/using the corresponding GET route. This is the whole point of HEAD requests, and since Rocket can do it automatically for you, it does, and it does so because otherwise you'd need to do it yourself to have a properly functioning web server.

The error message that Rocket emits when a HEAD request is automatically handled indicates that Rocket wasn't able to find a route that you registered that matches the HEAD request. It then proceeds with its automatic handling by calling the GET route and stripping the appropriate information to form a proper response.

Rocket isn't doing some weird or wrong, nor are the log messages wrong. In fact, they're too precise. In this case, we want to omit information, or at least change how we present it.

[tessus]

@SergioBenitez Thanks for the explanation. This makes sense!

[SergioBenitez]

Let's handle this when we handle #21.