Logging: set event subscriber globally for all threads

[Gor027]

Pre-review checklist

The previous attempt for adding logging support in the driver was to set a custom event subscriber with an option to replace it with a new subscriber if the logging configuration is changed during the program's runtime. The tracing::subscriber::set_default function was used to set a scoped subscriber and be able to drop it gracefully. However, the documentation of the function fails to mention that the default subscriber is set only for the current thread hence making it unsuitable for the needs of multi-threaded applications. So, as of now, the tracing::subscriber::set_global_default is the only reliable way to set a default subscriber available for all threads within an application. However, it can be set only once and cannot be gracefully dropped later, so multiple attempts to set a global default subscriber will fail. This PR replaces set_default with set_global_default, which implies that cass_log_set_level must be called only once and later attempts to modify the logging configuration will be ignored. For informational purposes, a logging section is added to the README to explain the details of the implementation and usage. Additionally, the test logs from build and cassandra jobs will be uploaded as an artifact in order to help in some debugging processes in the future.

Fixes #110

• [x] I have split my patch into logically separate commits.
• [x] All commit messages clearly explain what they change and why.
• [x] PR description sums up the changes and reasons why they should be introduced.
• [ ] I have enabled appropriate tests in .github/workflows/build.yml in gtest_filter.
• [ ] I have enabled appropriate tests in .github/workflows/cassandra.yml in gtest_filter.

[Lorak-mmk]

I'm not that familiar with tracing crate, but can't we do the same thing as in rust driver did in https://github.com/scylladb/scylla-rust-driver/pull/668? I mean using .with_current_subscriber() on each future that is passed to tokio::spawn(). The restriction that cass_log_set_level can be called only once is quite restrictive, I don't think cpp-driver has such limitation.

[piodul]

I'm not that familiar with tracing crate, but can't we do the same thing as in rust driver did in scylladb/scylla-rust-driver#668? I mean using .with_current_subscriber() on each future that is passed to tokio::spawn(). The restriction that cass_log_set_level can be called only once is quite restrictive, I don't think cpp-driver has such limitation.

Yes, this sounds better - however, this approach requires rust driver 0.8.0 to work properly.

[Lorak-mmk]

So in order to do that we need to merge https://github.com/scylladb/cpp-rust-driver/pull/107 first, right?

[piodul]

So in order to do that we need to merge #107 first, right?

Probably. Or, if a PR that just migrates to the new rust driver version is extracted out of that, then merge that first. I guess it's up to @wprzytula.

[Gor027]

I'm not that familiar with tracing crate, but can't we do the same thing as in rust driver did in scylladb/scylla-rust-driver#668? I mean using .with_current_subscriber() on each future that is passed to tokio::spawn(). The restriction that cass_log_set_level can be called only once is quite restrictive, I don't think cpp-driver has such limitation.

Yes, this sounds better - however, this approach requires rust driver 0.8.0 to work properly.

IIUC, this implies having a scoped logger for each future, so logs outside of futures will not be recorded and modified as C++ logs as there is no global default subscriber.

[Gor027]

As I see, what is necessary to properly support logging is not yet supported in the tracing crate: https://github.com/tokio-rs/tracing/issues/1517

[Lorak-mmk]

I'm not that familiar with tracing crate, but can't we do the same thing as in rust driver did in scylladb/scylla-rust-driver#668? I mean using .with_current_subscriber() on each future that is passed to tokio::spawn(). The restriction that cass_log_set_level can be called only once is quite restrictive, I don't think cpp-driver has such limitation.

Yes, this sounds better - however, this approach requires rust driver 0.8.0 to work properly.

IIUC, this implies having a scoped logger for each future, so logs outside of futures will not be recorded and modified as C++ logs as there is no global default subscriber.

What are logs outside of futures? Do you mean logs that are logged in cass_* functions directly? If so, how many places where such logs are possible do we have? Is it possible to use scoped logger in those places?

[Gor027]

I'm not that familiar with tracing crate, but can't we do the same thing as in rust driver did in scylladb/scylla-rust-driver#668? I mean using .with_current_subscriber() on each future that is passed to tokio::spawn(). The restriction that cass_log_set_level can be called only once is quite restrictive, I don't think cpp-driver has such limitation.

Yes, this sounds better - however, this approach requires rust driver 0.8.0 to work properly.

IIUC, this implies having a scoped logger for each future, so logs outside of futures will not be recorded and modified as C++ logs as there is no global default subscriber.

What are logs outside of futures? Do you mean logs that are logged in cass_* functions directly? If so, how many places where such logs are possible do we have? Is it possible to use scoped logger in those places?

Yes, for example, logs that may appear in some setters. It is hard to guess where these logs are possible and we should always make sure that a newly added log in the Rust driver also appears in the bindings, so we should add a scoped subscriber to the appropriate function.

[Lorak-mmk]

One solution to that could be a proc macro wrapping whole function body in a scoped subscriber. This macro would be placed on any function that calls Rust driver or does the logging itself.

[wprzytula]

One solution to that could be a proc macro wrapping whole function body in a scoped subscriber. This macro would be placed on any function that calls Rust driver or does the logging itself.

This is an interesting idea, could you write a PoC for this?

[wprzytula]

@Gor027 Using this PR's code, I'm still unable to get any logs from the Rust driver. I'm using the prepared example, modified by adding these lines at the main() beginning:

cass_log_set_level(CASS_LOG_TRACE);
cass_log_set_callback(callback, NULL);

with callback defined as:

void callback(CassLogMessage const* msg, void *data) {
  printf("%s::%s:%i: %s\n", msg->file, msg->function, msg->line, msg->message);
}

There's no difference whether I call cass_log_set_callback() or not.

[Gor027]

I tested with the modifications you mentioned and it worked for me:

1686564005967 [DEBUG] (scylla_cpp_driver::logging:169) message: Log level is set to TRACE
scylla::transport::connection_pool:::631: message: [127.0.0.1:9042] Started asynchronous pool worker
scylla::transport::connection_pool:::739: message: [127.0.0.1:9042] Will open the first connection to the node
scylla::transport::connection_pool:::680: pool_state: "[(0, [])]"
scylla::transport::connection_pool:::823: message: [127.0.0.1:9042] Failed to open connection to the non-shard-aware port: IoError(Os { code: 111, kind: ConnectionRefused, message: "Connection refused" })
scylla::transport::connection_pool:::680: pool_state: "[(0, [])]"
scylla::transport::connection_pool:::692: message: [127.0.0.1:9042] Scheduling next refill in 100 ms
scylla::transport::connection_pool:::275: message: Selecting random connection
scylla::transport::topology:::438: message: Known peers: ContactPoint(ContactPoint { address: 127.0.0.1:9042, datacenter: None })
scylla::transport::topology:::491: message: Could not fetch metadata, error: IO Error: No connections in the pool; last connection failed with: IO Error: Connection refused (os error 111)
Error: IO Error: No connections in the pool; last connection failed with: IO Error: Connection refused (os error 111)

Did you make sure that you link an updated version of libscylla_cpp_driver.so while building the example?

[Gor027]

One solution to that could be a proc macro wrapping whole function body in a scoped subscriber. This macro would be placed on any function that calls Rust driver or does the logging itself.

The problem is that with_current_subscriber returns a future that needs to be awaited, so what about logging in non-async functions?

[wprzytula]

Did you make sure that you link an updated version of libscylla_cpp_driver.so while building the example?

Apparently not... Now, my output is the same as yours. Great!

[Gor027]

@Lorak-mmk @piodul what do you think?

[Lorak-mmk]

If we were to merge it with current limitations:

1. This PR needs to document those limitations:
   • Being able to call cass_set_log_level only once
   • That this library ignores warning in set_global_default documentation https://docs.rs/tracing/latest/tracing/subscriber/fn.set_global_default.html "Note: Libraries should NOT call set_global_default()! That will cause conflicts when executables try to set them later." - so if you're using it from Rust application, you won't be able to set global default subscriber.
2. Issue needs to be open after merge. You can also put my idea for a solution in the issue (Creating macro that uses https://docs.rs/tracing/latest/tracing/subscriber/fn.with_default.html + adding .with_current_subscriber() to futures passed to tokio::spawn)

[Gor027]

1. This PR needs to document those limitations:

Details about the logging limitations are documented in the README.

• That this library ignores warning in set_global_default documentation https://docs.rs/tracing/latest/tracing/subscriber/fn.set_global_default.html "Note: Libraries should NOT call set_global_default()! That will cause conflicts when executables try to set them later." - so if you're using it from Rust application, you won't be able to set global default subscriber.

Do we plan to release the bindings as a library so that other crates can depend on it?

[wprzytula]

• That this library ignores warning in set_global_default documentation https://docs.rs/tracing/latest/tracing/subscriber/fn.set_global_default.html "Note: Libraries should NOT call set_global_default()! That will cause conflicts when executables try to set them later." - so if you're using it from Rust application, you won't be able to set global default subscriber.

Do we plan to release the bindings as a library so that other crates can depend on it?

IIUC, the problem stated by @Lorak-mmk is about an (IMO) unlikely situation when someone uses the C library (driven by the bindings) using FFI in another Rust crate. But... why would anyone do that?

[Lorak-mmk]

One possible scenario is using our library underneath something like https://github.com/Metaswitch/cassandra-rs

[Gor027]

Ping. I have updated README about logging limitations.

[piodul]

One solution to that could be a proc macro wrapping whole function body in a scoped subscriber. This macro would be placed on any function that calls Rust driver or does the logging itself.

The CPP driver API is large and it sounds very easy to make a mistake and forget about some functions that need it. I don't see how we could test something like that, I think we need something which doesn't require per-function action.

One idea that comes to my mind is a per-file attribute macro which automatically annotates extern "C" functions whose names start with cass_.

One possible scenario is using our library underneath something like https://github.com/Metaswitch/cassandra-rs

Maybe there is no problem? Rust libraries are linked statically, so our bindings will contain a copy of the tracing library, including the symbol for the global subscriber. If you have an application which uses tracing itself and links to our bindings, then perhaps there will be two separate instances of tracing. This is just a hypothesis, but I think it's worth checking out - perhaps there is no problem at all with the current solution.

[wprzytula]

One solution to that could be a proc macro wrapping whole function body in a scoped subscriber. This macro would be placed on any function that calls Rust driver or does the logging itself.

The CPP driver API is large and it sounds very easy to make a mistake and forget about some functions that need it. I don't see how we could test something like that, I think we need something which doesn't require per-function action.

One idea that comes to my mind is a per-file attribute macro which automatically annotates extern "C" functions whose names start with cass_.

One possible scenario is using our library underneath something like https://github.com/Metaswitch/cassandra-rs

Maybe there is no problem? Rust libraries are linked statically, so our bindings will contain a copy of the tracing library, including the symbol for the global subscriber. If you have an application which uses tracing itself and links to our bindings, then perhaps there will be two separate instances of tracing. This is just a hypothesis, but I think it's worth checking out - perhaps there is no problem at all with the current solution.

This is definitely promising. Are you going to check the hypothesis out?