Turn off database log spam

[rkfg]

I have log_filters = "ERROR" in the config and yet electrs produces enormous amount of useless database logs (in db/bitcoin/LOG file) like this:

2022/02/06-14:04:52.920247 7f96d12040 [db/db_impl/db_impl_compaction_flush.cc:1389] [txid] Manual flush finished, status: OK
2022/02/06-14:04:52.920252 7f96d12040 [db/db_impl/db_impl_compaction_flush.cc:1379] [funding] Manual flush start.
2022/02/06-14:04:52.920258 7f96d12040 [db/db_impl/db_impl_compaction_flush.cc:1389] [funding] Manual flush finished, status: OK
2022/02/06-14:04:52.920262 7f96d12040 [db/db_impl/db_impl_compaction_flush.cc:1379] [spending] Manual flush start.
2022/02/06-14:04:52.920268 7f96d12040 [db/db_impl/db_impl_compaction_flush.cc:1389] [spending] Manual flush finished, status: OK
2022/02/06-14:05:02.938064 7f96d12040 [db/db_impl/db_impl_compaction_flush.cc:1379] [config] Manual flush start.
2022/02/06-14:05:02.938215 7f96d12040 [db/db_impl/db_impl_compaction_flush.cc:1389] [config] Manual flush finished, status: OK
2022/02/06-14:05:02.938225 7f96d12040 [db/db_impl/db_impl_compaction_flush.cc:1379] [headers] Manual flush start.
2022/02/06-14:05:02.938231 7f96d12040 [db/db_impl/db_impl_compaction_flush.cc:1389] [headers] Manual flush finished, status: OK
2022/02/06-14:05:02.938237 7f96d12040 [db/db_impl/db_impl_compaction_flush.cc:1379] [txid] Manual flush start.
2022/02/06-14:05:02.938243 7f96d12040 [db/db_impl/db_impl_compaction_flush.cc:1389] [txid] Manual flush finished, status: OK
2022/02/06-14:05:02.938248 7f96d12040 [db/db_impl/db_impl_compaction_flush.cc:1379] [funding] Manual flush start.
2022/02/06-14:05:02.938253 7f96d12040 [db/db_impl/db_impl_compaction_flush.cc:1389] [funding] Manual flush finished, status: OK
2022/02/06-14:05:02.938258 7f96d12040 [db/db_impl/db_impl_compaction_flush.cc:1379] [spending] Manual flush start.
2022/02/06-14:05:02.938263 7f96d12040 [db/db_impl/db_impl_compaction_flush.cc:1389] [spending] Manual flush finished, status: OK
2022/02/06-14:05:10.460750 7f96d12040 [db/db_impl/db_impl_compaction_flush.cc:1379] [config] Manual flush start.
2022/02/06-14:05:10.460870 7f96d12040 [db/db_impl/db_impl_compaction_flush.cc:1389] [config] Manual flush finished, status: OK
2022/02/06-14:05:10.460879 7f96d12040 [db/db_impl/db_impl_compaction_flush.cc:1379] [headers] Manual flush start.
2022/02/06-14:05:10.460886 7f96d12040 [db/db_impl/db_impl_compaction_flush.cc:1389] [headers] Manual flush finished, status: OK
2022/02/06-14:05:10.460891 7f96d12040 [db/db_impl/db_impl_compaction_flush.cc:1379] [txid] Manual flush start.
2022/02/06-14:05:10.460898 7f96d12040 [db/db_impl/db_impl_compaction_flush.cc:1389] [txid] Manual flush finished, status: OK
2022/02/06-14:05:10.460902 7f96d12040 [db/db_impl/db_impl_compaction_flush.cc:1379] [funding] Manual flush start.
2022/02/06-14:05:10.460908 7f96d12040 [db/db_impl/db_impl_compaction_flush.cc:1389] [funding] Manual flush finished, status: OK
2022/02/06-14:05:10.460913 7f96d12040 [db/db_impl/db_impl_compaction_flush.cc:1379] [spending] Manual flush start.
2022/02/06-14:05:10.460918 7f96d12040 [db/db_impl/db_impl_compaction_flush.cc:1389] [spending] Manual flush finished, status: OK
2022/02/06-14:05:10.521469 7f96d12040 [db/db_impl/db_impl_compaction_flush.cc:1379] [config] Manual flush start.
2022/02/06-14:05:10.521509 7f96d12040 [db/db_impl/db_impl_compaction_flush.cc:1389] [config] Manual flush finished, status: OK
2022/02/06-14:05:10.521515 7f96d12040 [db/db_impl/db_impl_compaction_flush.cc:1379] [headers] Manual flush start.
2022/02/06-14:05:10.521521 7f96d12040 [db/db_impl/db_impl_compaction_flush.cc:1389] [headers] Manual flush finished, status: OK
2022/02/06-14:05:10.521527 7f96d12040 [db/db_impl/db_impl_compaction_flush.cc:1379] [txid] Manual flush start.
2022/02/06-14:05:10.521533 7f96d12040 [db/db_impl/db_impl_compaction_flush.cc:1389] [txid] Manual flush finished, status: OK
2022/02/06-14:05:10.521538 7f96d12040 [db/db_impl/db_impl_compaction_flush.cc:1379] [funding] Manual flush start.
2022/02/06-14:05:10.521543 7f96d12040 [db/db_impl/db_impl_compaction_flush.cc:1389] [funding] Manual flush finished, status: OK
2022/02/06-14:05:10.521548 7f96d12040 [db/db_impl/db_impl_compaction_flush.cc:1379] [spending] Manual flush start.
2022/02/06-14:05:10.521554 7f96d12040 [db/db_impl/db_impl_compaction_flush.cc:1389] [spending] Manual flush finished, status: OK
2022/02/06-14:05:10.659286 7f96d12040 [db/db_impl/db_impl_compaction_flush.cc:1379] [config] Manual flush start.
2022/02/06-14:05:10.659327 7f96d12040 [db/db_impl/db_impl_compaction_flush.cc:1389] [config] Manual flush finished, status: OK
2022/02/06-14:05:10.659334 7f96d12040 [db/db_impl/db_impl_compaction_flush.cc:1379] [headers] Manual flush start.
2022/02/06-14:05:10.659340 7f96d12040 [db/db_impl/db_impl_compaction_flush.cc:1389] [headers] Manual flush finished, status: OK
2022/02/06-14:05:10.659345 7f96d12040 [db/db_impl/db_impl_compaction_flush.cc:1379] [txid] Manual flush start.
2022/02/06-14:05:10.659351 7f96d12040 [db/db_impl/db_impl_compaction_flush.cc:1389] [txid] Manual flush finished, status: OK
2022/02/06-14:05:10.659356 7f96d12040 [db/db_impl/db_impl_compaction_flush.cc:1379] [funding] Manual flush start.
2022/02/06-14:05:10.659362 7f96d12040 [db/db_impl/db_impl_compaction_flush.cc:1389] [funding] Manual flush finished, status: OK
2022/02/06-14:05:10.659367 7f96d12040 [db/db_impl/db_impl_compaction_flush.cc:1379] [spending] Manual flush start.
2022/02/06-14:05:10.659372 7f96d12040 [db/db_impl/db_impl_compaction_flush.cc:1389] [spending] Manual flush finished, status: OK
2022/02/06-14:05:10.748050 7f96d12040 [db/db_impl/db_impl_compaction_flush.cc:1379] [config] Manual flush start.
2022/02/06-14:05:10.748088 7f96d12040 [db/db_impl/db_impl_compaction_flush.cc:1389] [config] Manual flush finished, status: OK
2022/02/06-14:05:10.748095 7f96d12040 [db/db_impl/db_impl_compaction_flush.cc:1379] [headers] Manual flush start.
2022/02/06-14:05:10.748101 7f96d12040 [db/db_impl/db_impl_compaction_flush.cc:1389] [headers] Manual flush finished, status: OK
2022/02/06-14:05:10.748107 7f96d12040 [db/db_impl/db_impl_compaction_flush.cc:1379] [txid] Manual flush start.

I looked around and found that there's a function to set log level in the rust-rocksdb upstream but not in the fork used for electrs. Is it possible to turn all of this off? The LOG file grows up to 800 Mb and those are really useless writes for my SSD.

Electrs built from master for aarch64 using BINDGEN_EXTRA_CLANG_ARGS="-target gcc-aarch64-linux-gnu" RUSTFLAGS="-C linker=aarch64-linux-gnu-gcc" cargo build --locked --release --target aarch64-unknown-linux-gnu, run on RPi 4.

[Kixunil]

This is a different kind of logging and I do agree it'd be good to have it configurable. I'm not sure if it's a good idea to mix it in log filters because of being different but it also feels strange from user perspective to have two options seemingly controlling the "same" thing.

Orthogonal issue: would be nice if we could change location of the db log file. I like to put logs into /var/log to adhere to FHS.

[rkfg]

LevelDB also stores its LOG file with the rest of the data so it's kind of a tradition already... but I personally don't have a strong opinion about it. The fork that electrs uses hasn't been updated for more than a year and some options don't even exist there (like LogLevel enum). Updating such a core dependency just to fix this issue might not be very practical. Maybe patching out just those two lines would do? They're added every 5-10 seconds, it's a major waste. Another, better option would be binding rocksdb_options_set_info_log_level properly and using it accordingly (if I understand its purpose right), this function is present in the fork but only in the C interface.

[rkfg]

Any progress on this? I have to support my own fork of rust-rocksdb with a one-line patch because of this, think about all the SSD wear...

[romanz]

Latest electrs versions (0.10.x) are using https://github.com/romanz/rust-rocksdb/commits/2023-10/electrs-build (based on RocksDB 7.8.3, which is provided by current Debian stable - https://packages.debian.org/stable/librocksdb-dev). Could you please test if the issue persists?

[romanz]

I have to support my own fork of rust-rocksdb with a one-line patch because of this, think about all the SSD wear...

Could you please share the relevant patch?

[romanz]

@rkfg Can we use https://github.com/rust-rocksdb/rust-rocksdb/blame/c1314a3d5942cf19975a3e1058cd2fa418bb1837/src/db_options.rs#L1565?

[rkfg]

I built the current master and yes, the issue is there. Do you not get this constant spam in the LOG file? Hopefully setting the log level explicitly should fix it. My patch is like this:

diff --git a/db/db_impl/db_impl_compaction_flush.cc b/db/db_impl/db_impl_compaction_flush.cc
index f93d70551..7303b5dd8 100644
--- a/db/db_impl/db_impl_compaction_flush.cc
+++ b/db/db_impl/db_impl_compaction_flush.cc
@@ -1376,8 +1376,6 @@ int DBImpl::Level0StopWriteTrigger(ColumnFamilyHandle* column_family) {
 Status DBImpl::Flush(const FlushOptions& flush_options,
                      ColumnFamilyHandle* column_family) {
   auto cfh = reinterpret_cast<ColumnFamilyHandleImpl*>(column_family);
-  ROCKS_LOG_INFO(immutable_db_options_.info_log, "[%s] Manual flush start.",
-                 cfh->GetName().c_str());
   Status s;
   if (immutable_db_options_.atomic_flush) {
     s = AtomicFlushMemTables({cfh->cfd()}, flush_options,
@@ -1386,9 +1384,6 @@ Status DBImpl::Flush(const FlushOptions& flush_options,
     s = FlushMemTable(cfh->cfd(), flush_options, FlushReason::kManualFlush);
   }
 
-  ROCKS_LOG_INFO(immutable_db_options_.info_log,
-                 "[%s] Manual flush finished, status: %s\n",
-                 cfh->GetName().c_str(), s.ToString().c_str());
   return s;
 }
 

But it's for your fork and now I can't build it (rocksdb) due to a cryptic error:

  thread 'main' panicked at /home/rkfg/.cargo/registry/src/index.crates.io-6f17d22bba15001f/proc-macro2-1.0.69/src/fallback.rs:817:9:
  "enum_(unnamed_at_rocksdb/include/rocksdb/c_h_722_1)" is not a valid Ident

From what I googled it's related to clang 16 but I really don't want to mess with this all if it can be solved without any rocksdb patches.

[romanz]

Maybe we can use https://docs.rs/electrs-rocksdb/0.19.0-e3/electrs_rocksdb/struct.Options.html#method.set_db_log_dir to move the logs into another directory? (as suggested in https://github.com/romanz/electrs/issues/680#issuecomment-1030848627)

[rkfg]

I'd prefer to turn this off completely. What's the purpose of the same messages repeated every 10 seconds and taking up hundreds of megabytes?

[romanz]

Actually, the log is caused by an unneeded flush() call on every sync iteration (even if no blocks were found): https://github.com/romanz/electrs/blob/a01d58c35d2f6aaea7a479eb508404e7ff3affdf/src/index.rs#L182 @rkfg Good catch, and sorry for missing it!

[romanz]

Could you please try https://github.com/romanz/electrs/commit/deb40bc280c07ca8d8ce303b09b44f56939976a3 to see if it resolves this issue?

[rkfg]

Yes, this seems to have fixed it, thanks!

[Kixunil]

I'd still love to see the dir configurable but from the doc I'm confused what it really does. (Says something about prefixes.) I will have to check myself later (or anyone else can check for me what happens if you set /var/log/electrs-mainnet/db and have the datadir in /var/lib/electrs-mainnet)

[romanz]

@Kixunil it seems that using db_log_dir creates a LOG file with a "custom" prefix (using the DB path, with some characters being replaced by underscores - https://github.com/facebook/rocksdb/blob/f6fd4b9dbd15dba36f7e5ad23de407b5c26b1460/file/filename.cc#L37 or https://github.com/facebook/rocksdb/blob/f6fd4b9dbd15dba36f7e5ad23de407b5c26b1460/tools/advisor/advisor/bench_runner.py#L22 for an example).

[Kixunil]

Uh, that's horrible, thanks for finding it! Given what it does I'm not sure if I want to do it as it'd produce weird, long name. (I mean, I'm probably not motivated to send a PR because I wouldn't use it anyway but wouldn't oppose anyone implementing the feature.)