logging lots of error messages

[psFried]

I noticed that when logging is on at the info level, there seems to be an error message printed to the logs with every response.

INFO:rotor_http::server::parser: Error handing connection: end of stream reached

This message seems to get printed every time rotor writes out a response. This can be seen just by adding the log and env_logger crates to the HelloWorld example and running it with: RUST_LOG=info cargo run .... It doesn't seem like there's actually any problem with the response itself, so I wonder if that log statement should be removed or else logged at a finer level. Workaround at this point is just to filter out info messages from the parser, so not a huge deal.

[pyfisch]

I cannot reproduce. I am using the modified example and run it with: RUST_LOG=info cargo run --example hello_world_server. There are no log messages beside the one to test the logger. Is there anything wrong with how I set up the logger? If not what kind of system are you using?

[tailhook]

Maybe this happen if you enable log_errors feature which was recently fixed ?

Overall, error logging is not really well-defined in rotor ecosystem. On the one hand we shouldn't log clean connection termination on the other hand we must be able to log premature connection termination. And they are usually determined on the different protocol layers. Additionally it's too tempting to pass whatever socket error to the downstream without checking if that was just connection termination or any other socket error.

I'll try to find some time to investigate logging strategy in the next few weeks.

[psFried]

@pyfisch I'm using OSX. I tried your modified example and I couldn't get it to print the "Logger is running." test line. I don't know what's going on with that. As far as I can tell, it looks like everything is right in terms of logger initialization. I just created a minimal example using the latest crates.io version and copy/pasting the hello_world_server example into it and adding logging. Running that example always produces the log event with every request.

@tailhook I did not enable the log_errors feature. FWIW, I think logging it is actually ok, even if you can't necessarily determine if it's an error or not until it get's to the protocol layer. Maybe in this case it should just be logged at the debug or trace level and not label it as an error? I personally appreciate it when libraries have thorough logging because it's generally really easy to just suppress log messages that you don't want to see.

[tailhook]

Sure, moving it to a trace level is fine, as soon as we ensure that premature closes and protocol errors are covered on a higher logging level. Otherwise, it would be too hard to debug.

(sorry, I had no time to reproduce it myself, but you've said it's not huge deal, so I'll take a time and try to fix it in more comprehensive way)