[c++] Support option to set log level from environment#2972
Conversation
Codecov ReportAll modified and coverable lines are covered by tests ✅
Additional details and impacted files@@ Coverage Diff @@
## main #2972 +/- ##
==========================================
+ Coverage 89.84% 89.99% +0.14%
==========================================
Files 39 39
Lines 4057 4057
==========================================
+ Hits 3645 3651 +6
+ Misses 412 406 -6
Flags with carried forward coverage won't be shown. Click here to find out more.
|
| #endif | ||
| } | ||
| set_level("INFO"); | ||
| char* env_level = std::getenv("LIBTILEDBSOMA_LOGGING_LEVEL"); |
There was a problem hiding this comment.
There is a built-in activator for spdlog we could use too. I have been meaning to expose it in the R package as well. See https://github.com/eddelbuettel/spdlog#load-log-levels-from-env-variable-or-from-argv
I also find it convenient to turn on R and libtiledbsoma logging:
TileDB-SOMA/apis/r/src/rinterface.cpp
Lines 187 to 192 in 7cacee1
As an 'exported' Rcpp function this is available at the R prompt, and via the @export tag the generated R function is also in the NAMESPACE so it is directly callable.
There was a problem hiding this comment.
I also find it convenient to turn on R and libtiledbsoma logging:
Thanks @eddelbuettel . There's also tiledbsoma.pytiledbsoma.config_logging("debug") which is directly callable from Python. And spdl::set_log_level("DEBUG") which is directly callable from R. Knowing both of those things, I also do want the option to enable logging without editing source code -- in whichever language.
Thanks for the tip at https://github.com/eddelbuettel/spdlog#load-log-levels-from-env-variable-or-from-argv re spdlog::cfg::load_env_levels! TIL :). I do however want the option to set application-specific levels from the environment.
There was a problem hiding this comment.
Also keep in mind that there are different instances of spdlog involved which is why the C++-side-of-tiledbsoma-R has two enablers, one for C++ (in libtiledbsoma) and one for R + C++ in the R package.
I do however want the option to set application-specific levels from the environment.
That is exactly what it does. (Don't get distracted that the reference accidentally goes to my fork. It is a spdlog upstream feature.)
I used that very feature in the example code I posted on slack when I proposed header-only use of spdlog and fmt as potential fix to occassional build woes. Anyway ...
|
Is this something we should add to CMakeLists.txt too where we default it to OFF? Maybe for debug builds it could be INFO. |
|
It's is strictly run-time (once compiled in). As it has a marginal cost (of checking a run-time condition) you could tuck it inside #if .. #endif for debug mode. But if would loose the benefit of 'always being there' without mods to code which is, if I understand it correctly, @johnkerl is after here (and which I also find appealing). $ g++ -std=c++17 spdlog_ex_headeronly.cpp -o spdlog_ex_headeronly
$ ./spdlog_ex_headeronly # no setting
[14:26:53.559466] [my_demo] [I] [thread 2308290] Welcome to spdlog!
[14:26:53.559523] [my_demo] [E] [thread 2308290] Some error message with arg: 1
[14:26:53.559539] [my_demo] [I] [thread 2308290] Elapsed time: 6.8161e-05
[14:26:53.559548] [my_demo] [W] [thread 2308290] Easy padding in numbers like 00000012
[14:26:53.559584] [my_demo] [C] [thread 2308290] Support for int: 42; hex: 2a; oct: 52; bin: 101010
[14:26:53.559600] [my_demo] [I] [thread 2308290] Support for floats 1.23
[14:26:53.559612] [my_demo] [I] [thread 2308290] Positional args are supported too..
[14:26:53.559622] [my_demo] [I] [thread 2308290] left aligned
[14:26:53.559631] [my_demo] [I] [thread 2308290] Elapsed time: 0.000164105
$
$ SPDLOG_LEVEL=critical ./spdlog_ex_headeronly # critical only
[14:27:04.225658] [my_demo] [C] [thread 2308818] Support for int: 42; hex: 2a; oct: 52; bin: 101010
$
$ SPDLOG_LEVEL=error ./spdlog_ex_headeronly # error or higher
[14:27:15.571203] [my_demo] [E] [thread 2309374] Some error message with arg: 1
[14:27:15.571263] [my_demo] [C] [thread 2309374] Support for int: 42; hex: 2a; oct: 52; bin: 101010
$ It is activated by calling one line as demonstrated eg here and shown in the example I compiled and use here. Details#define FMT_HEADER_ONLY
#define SPDLOG_HEADER_ONLY
#include <spdlog/spdlog.h>
#include <spdlog/stopwatch.h>
#include <spdlog/sinks/stdout_color_sinks.h>
#include <spdlog/cfg/env.h>
int main(void) {
// this paragraph is entirely optional but related to something we do in RcppSpdlog
std::string logname = "my_demo"; // fix a name for this logger
auto sp = spdlog::get(logname); // retrieve existing one
if (sp == nullptr) sp = spdlog::stderr_color_mt(logname);// or create new one if needed
spdlog::set_default_logger(sp); // and set as default
// change log pattern (changed from [%H:%M:%S %z] [%n] [%^---%L---%$] )
spdlog::set_pattern("[%H:%M:%S.%f] [%n] [%^%L%$] [thread %t] %v");
// eg ./example SPDLOG_LEVEL=my_demo=warn
spdlog::cfg::load_env_levels();
// optional too but very cute in the tic-toc sense
spdlog::stopwatch sw; // instantiate a stop watch
spdlog::info("Welcome to spdlog!");
spdlog::error("Some error message with arg: {}", 1);
spdlog::info("Elapsed time: {}", sw);
spdlog::warn("Easy padding in numbers like {:08d}", 12);
spdlog::critical("Support for int: {0:d}; hex: {0:x}; oct: {0:o}; bin: {0:b}", 42);
spdlog::info("Support for floats {:03.2f}", 1.23456);
spdlog::info("Positional args are {1} {0}..", "too", "supported");
spdlog::info("{:<30}", "left aligned");
spdlog::info("Elapsed time: {}", sw);
} |
@nguyenv do you mind if I take this as a follow-on PR? |
|
I looked into this and there is a potentially simpler two-line solution because it is indeed covered upstream. This is should do: modified libtiledbsoma/src/utils/logger.cc
@@ -37,6 +37,7 @@
#include <spdlog/fmt/ostr.h>
#include <spdlog/sinks/basic_file_sink.h>
#include <spdlog/sinks/stdout_color_sinks.h>
+#include <spdlog/cfg/env.h>
namespace tiledbsoma {
@@ -72,6 +73,7 @@ Logger::Logger() {
#endif
}
set_level("INFO");
+ spdlog::cfg::load_env_levels(); // eg ./example SPDLOG_LEVEL=my_demo=warn
}
Logger::~Logger() {Demo, from R for ease of use, but note that this tickles use in R (I also looked into changing the R wrapper package, this is working via the same two-line trick but widely shipped) and then libtiledbsoma in the last two lines: $ SPDLOG_LEVEL="debug" Rscript -e 'library(tiledbsoma); sdf <- SOMADataFrameOpen("/tmp/tiledb/somadf_ts")'
[2024-09-09 17:35:28.930] [default] [Process: 3125929] [debug] [SOMADataFrameOpen] uri /tmp/tiledb/somadf_ts ts (now)
[2024-09-09 17:35:28.969] [default] [Process: 3125929] [debug] [TileDBObject] initialize SOMADataFrame with '/tmp/tiledb/somadf_ts' at (now)
[2024-09-09 17:35:28.969] [default] [Process: 3125929] [debug] [TileDBArray$open] Opening SOMADataFrame '/tmp/tiledb/somadf_ts' in READ mode
[2024-09-09 17:35:28.970] [default] [Process: 3125929] [debug] [tiledb_array] query is READ
[2024-09-09 17:35:28.975] [default] [Process: 3125929] [debug] [TileDBArray$update_metadata_cache] updating metadata cache for SOMADataFrame '/tmp/tiledb/somadf_ts' in READ
[2024-09-09 17:35:28.977] [tiledbsoma] [Process: 3125929] [Thread: 3125929] [debug] [SOMAArray] static method 'ctx' opening array '/tmp/tiledb/somadf_ts'
[2024-09-09 17:35:28.977] [tiledbsoma] [Process: 3125929] [Thread: 3125929] [debug] [SOMAArray] opening array '/tmp/tiledb/somadf_ts'
$ Without the env var nothing is shown or seen: $ Rscript -e 'library(tiledbsoma); sdf <- SOMADataFrameOpen("/tmp/tiledb/somadf_ts")'
$ |
|
@eddelbuettel kerl/libtiledbsoma-env-logging-level -- thank you! :) |
johnkerl
force-pushed
the
kerl/libtiledbsoma-env-logging-level
branch
from
d840372 to
16e7cdb
Compare
eddelbuettel
left a comment
eddelbuettel
left a comment
There was a problem hiding this comment.
Looks good to me -- I by now made a similar change in RcppSpdlog.
3 participants
I find this very useful, particularly on #2407 / [sc-51048]. If useful to other folks, great; if not, hopefully not too disruptive.