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

scylla: Enable log feature in tracing #915

Closed
wants to merge 1 commit into from

Conversation

Lorak-mmk
Copy link
Collaborator

@Lorak-mmk Lorak-mmk commented Jan 15, 2024

This allows applications using log ecosystem to receive logs from the driver.
There shouldn't be a significant performance penalty, because log events are emitted only if there is not Subscriber active.

TODO:

Pre-review checklist

  • I have split my patch into logically separate commits.
  • All commit messages clearly explain what they change and why.
  • I added relevant tests for new features and bug fixes.
  • All commits compile, pass static checks and pass test.
  • PR description sums up the changes and reasons why they should be introduced.
  • I have provided docstrings for the public items that I want to introduce.
  • I have adjusted the documentation in ./docs/source/.
  • I added appropriate Fixes: annotations to PR description.

This allows applications using `log` ecosystem to
receive logs from the driver. There shouldn't be a significant
performance penalty, because `log` events are emitted
only if there is not `Subscriber` active.
@@ -38,7 +38,7 @@ thiserror = "1.0"
itertools = "0.11.0"
bigdecimal = "0.2.0"
num-bigint = "0.3"
tracing = "0.1.36"
tracing = { version = "0.1.36", features = ["log"] }
Copy link
Collaborator

Choose a reason for hiding this comment

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

I think it is wrong for us to unconditionally enable this feature. Our crate does not need it at all in order to function properly. The decision whether to enable the feature or not should be on the application developers (as it controls global behavior) - they can explicitly depend on tracing in their application and enable log feature.

Copy link
Collaborator Author

Choose a reason for hiding this comment

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

I'm not very familiar with how Cargo handles dependencies, resolves versions etc. I know it's possible to have 2 copies (2 versions) of the same dependency. What is user supposed to do if they want to enable log feature in tracing used by our driver and not include another tracing copy?
Is it possible for us to have a feature that enables log feature in tracing? I feel like this would be a bit easier to use.

Copy link
Collaborator

Choose a reason for hiding this comment

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

I'm not very familiar with how Cargo handles dependencies, resolves versions etc. I know it's possible to have 2 copies (2 versions) of the same dependency. What is user supposed to do if they want to enable log feature in tracing used by our driver and not include another tracing copy?

They need to specify a version constraint such that the cargo resolver will choose the same version. I don't know all the intricacies of the algorithm either, but I'm pretty sure that if you specify:

[dependencies]
tracing = { version = "0.1", features = ["log"] }

then, given that we have tracing = "0.1.36" in our depencencies, the resolver will choose the same version and instance of the tracing crate. Users can verify if they succeeded by looking at Cargo.lock.

Is it possible for us to have a feature that enables log feature in tracing? I feel like this would be a bit easier to use.

Yes, it is possible. However, I still think it's weird for us to add such a feature. If we were to add it, going further with that logic, all other library crates that use tracing internally should have such a feature as well - this does not scale. Users can easily enable the necessary feature in tracing for their application with the method I outlined.

Copy link
Contributor

@RoDmitry RoDmitry Jan 15, 2024

Choose a reason for hiding this comment

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

I'm not very familiar with how Cargo handles dependencies

I think it uses the crate with the most features enabled. Just a guess, because sometimes after removing a crate which enabled some features (for tokio for example), it required me to enable these features (for tokio) manually.

So if you require tracing with log manually (separately from scylla), it might use it.

@Lorak-mmk
Copy link
Collaborator Author

I looked at how is this feature implemented. See the following links:
https://github.com/tokio-rs/tracing/blob/a4217633e127e9f561b4e47ec1b42aa73d475afa/tracing/src/macros.rs#L20-L54
https://github.com/tokio-rs/tracing/blob/a4217633e127e9f561b4e47ec1b42aa73d475afa/tracing/src/macros.rs#L2459-L2477
https://github.com/tokio-rs/tracing/blob/d4ca988252211b12e3beccfa6b029064ede1d6dc/tracing-core/src/dispatch.rs#L368-L376

So basically it looks like the cost is one atomic relaxed load per log call. Considering that this atomic is only written to at most once iiuc the value should be cached and there should be no contention / other problems, so overhead should be negligible.
I'll try to add a feature to our crate that enables log in tracing.

After reading https://docs.rs/tracing/latest/tracing/#emitting-log-records and source code I think this could be in our default features - this will allow both apps using tracing and log ecosystems to consume the driver without any problems, improving usability of this crate. For users that want to avoid this marginal cost, they can disable the feature. This is also aligned with tracing docs recommendation that I linked - they recommend enabling the feature for libraries that want to be usable with both log and tracing.

@RoDmitry
Copy link
Contributor

It does not help actually. I will provide you with an example a bit later.

@Lorak-mmk
Copy link
Collaborator Author

I'll respond in the issue, so that discussion is there and not in a PR

@Lorak-mmk
Copy link
Collaborator Author

Turns out that most likely the original issue is not the fault of Scylla. I think adding the log feature still makes sense, just maybe not in default features. I'll update the PR shortly.

@Lorak-mmk
Copy link
Collaborator Author

Turns out enabling log integration is not that easy as just enabling log feature on tracing.
I added log feature to Scylla, created an example copied from logging.rs, but replaced tracing with env_logger.
When running it with RUST_LOG=trace, I get the info! from the example. I also get manually added logs, both from example and from inside the crate.
But I don't get any actual driver logs. I suspect that tracing's log integration doesn't play well with using with_current_subscriber() on futures passed to tokio::spawn.
So closing this for now. We should recommend users to use tracing for logs.

@Lorak-mmk Lorak-mmk closed this Jan 16, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

Logging in log is bugged, but tracing works
3 participants