Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Add Log handler for HTTP::Server #9034

Merged
merged 2 commits into from
Apr 11, 2020

Conversation

straight-shoota
Copy link
Member

Previously, errors while establishing a connection where just dumped out to STDERR.
Such errors are usually not very relevant but sometimes you might want to delve into details. The new Log system offers a great solution to bury these errors as debug messages, still making them available when logger level is low enough.

This creates a new dependency from HTTP::Server to Log that has not been there before. But I think that's okay. HTTP::Server is quite a high level API in stdlib terms and should often be used with a logging system anyways. And we would probably want to use the new Log system more often now in stdlib libraries.

In case you don't want that behaviour, overwriting handle_exception still allows inserting specific behaviour. But the default implementation should do a sane thing and not spill every failed SSL connection attempt to STDERR but still have a way to get access to these errors.

Previously, errors while establishing a connection where just dumped out to STDERR.
Such errors are usually not very relevant but sometimes you might want to delve
into details. The new Log system offers a great solution to bury these errors as
debug messages, still making them available when logger level is low enough.
Copy link
Contributor

@RX14 RX14 left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

❤️

This is what the Log system is for: allowing us to add advanced logging inside the stdlib! Next steps is probably adding more advanced debug logging to the stdlib.

private def handle_exception(e : Exception)
e.inspect_with_backtrace STDERR
STDERR.flush
Log.debug(exception: e) { "Error while connecting a new socket" }
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'd say this was more of an info-level or verbose warning personally.

I actually think the logger's default severity should be info or verbose, meaning we can add debug logging to the stdlib without it being on by default.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Actually I think this has to be an error. That's exactly what it is.
BTW, why is handled in a method? it's only used once 🙂

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The purpose of the method is that sublasses can override it and alter the behaviour.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yes, it's an error. But it has nowhere to go from here. It just bubbles up to the current fiber's root and is printed to stderr. That's not useful at all. Do you have any better idea than sending it to Log? IMO this is a perfect use case.

I don't mind changing the severity to info, @RX14

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Logging it as error it does not cause a bubbling. Since it’s a condition outside of what this method and class can control neither debug nor verbose are good fit I think.

If i were checking a server and something prevents connection to be accepted I think I would rather see it as an error than a debug.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Considering how to implement this, the difficult part is discerning which category an error belongs to. That's not trivial because everything related to TLS is just OpenSSL::SSL::Error. We plan on changing some things here anyway, such as a generic TLS API and change the integration with HTTP::Server to do the handshake inside the client fiber.
So it's probably best to postpone solving the log severity assignment. I'll go for everything being logged as error for now and we can refine it with/after the TLS/server refactor.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks @straight-shoota. I agree 100% now.
Probably we need to subclass OpenSSL::SSL::Error or maybe just make the OpenSSL::SSL::Socket::Server#accept method to not return until a connection was made or a fatal error occur, and just log client errors from there as info or debug but with a different source.

Maybe Apache sources can give us a hint about what errors to consider here: https://github.com/apache/httpd/blob/add4e2892b4c6b35be790843aac5713302dc1d2f/modules/ssl/ssl_engine_io.c#L1410-L1453.

Copy link
Member Author

@straight-shoota straight-shoota Apr 11, 2020

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think such errors should not be handled by SSL implementation but the calling code. For an HTTPS server, it's usually okay to essentially ignore client errors. In other use cases that might need to be handled differently.
As per #8108 (comment) SSL::Socket::Server needs to be removed from HTTP::Server implementation. Probably also entirely.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Well... the call to SSL_accept still has to happen somewhere, right? Aren't we just moving the problem somewhere else? But yes, having a SSL::ClientError subclass should be enough to be handled by servers, close everything and log as debug.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yes, we'd still have to sort out what's what. But it would prob be a bit easier when TCP accept and TSL accept don't happen in the same call.
(I was mainly commenting on your idea to make SSL::Server#accept block until it is successful and log every failure internally.)

private def handle_exception(e : Exception)
e.inspect_with_backtrace STDERR
STDERR.flush
Log.debug(exception: e) { "Error while connecting a new socket" }
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Actually I think this has to be an error. That's exactly what it is.
BTW, why is handled in a method? it's only used once 🙂

@bcardiff bcardiff requested review from waj and RX14 April 10, 2020 13:17
@waj waj merged commit 7217aad into crystal-lang:master Apr 11, 2020
@straight-shoota straight-shoota deleted the feature/http-server-log branch April 12, 2020 09:09
carlhoerberg pushed a commit to carlhoerberg/crystal that referenced this pull request Apr 29, 2020
* Add Log handler for HTTP::Server

Previously, errors while establishing a connection where just dumped out to STDERR.
Such errors are usually not very relevant but sometimes you might want to delve
into details. The new Log system offers a great solution to bury these errors as
debug messages, still making them available when logger level is low enough.

* Set log severity to error
@bcardiff bcardiff added this to the 0.35.0 milestone May 27, 2020
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

Successfully merging this pull request may close these issues.

None yet

5 participants