Write panic errors to logs (kaspanet#445) (kaspanet#446)

* Write panic errors to logs (kaspanet#445)

* Remove the comment as it doesn't need to be addressed

Reason: Waiting here will block the thread, and as the thread is locked
and we wait for the logger system to be initiated that would wait for
the thread to be released itself, making the waiting pointless

* Add column to the log message for the panic error

* Move panic setup after the logger init in all places

* Add the thread name to the panic error

* default hook invoke position + minor style changes

core/src/panic.rs

@@ -1,13 +1,31 @@
-use std::{panic, process};
+use kaspa_core::error;
+use std::{panic, process, thread};
 
 /// Configures the panic hook to exit the program on every panic
 pub fn configure_panic() {
     let default_hook = panic::take_hook();
     panic::set_hook(Box::new(move |panic_info| {
-        // Invoke the default hook and exit the process
+        // Get the panic location details
+        let (file, line, column) = match panic_info.location() {
+            Some(location) => (location.file(), location.line(), location.column()),
+            None => ("unknown", 0, 0),
+        };
+
+        let message = match panic_info.payload().downcast_ref::<&str>() {
+            Some(s) => *s,
+            None => match panic_info.payload().downcast_ref::<String>() {
+                Some(s) => &s[..],
+                None => "Box<dyn Any>",
+            },
+        };
+        // Get the thread name
+        let current_thread = thread::current();
+        let thread_name = current_thread.name().unwrap_or("<unnamed>");
+        // Log the panic
+        error!("thread '{}' panicked at {}:{}:{}: {}", thread_name, file, line, column, message);
+        // Invoke the default hook as well, since it might include additional info such as the full backtrace
         default_hook(panic_info);
         println!("Exiting...");
-        // TODO: setup a wait time and fold the log system properly
         process::exit(1);
     }));
 }

kaspad/src/daemon.rs

@@ -158,14 +158,15 @@ pub fn get_log_dir(args: &Args) -> Option<String> {
 
 impl Runtime {
     pub fn from_args(args: &Args) -> Self {
-        // Configure the panic behavior
-        kaspa_core::panic::configure_panic();
-
         let log_dir = get_log_dir(args);
 
         // Initialize the logger
         kaspa_core::log::init_logger(log_dir.as_deref(), &args.log_level);
 
+        // Configure the panic behavior
+        // As we log the panic, we want to set it up after the logger
+        kaspa_core::panic::configure_panic();
+
         Self { log_dir: log_dir.map(|log_dir| log_dir.to_owned()) }
     }
 }
@@ -248,7 +249,7 @@ pub fn create_core_with_runtime(runtime: &Runtime, args: &Args, fd_total_budget:
 
     // Reset Condition: User explicitly requested a reset
     if is_db_reset_needed && db_dir.exists() {
-        let msg = "Reset DB was requested -- this means the current databases will be fully deleted, 
+        let msg = "Reset DB was requested -- this means the current databases will be fully deleted,
 do you confirm? (answer y/n or pass --yes to the Kaspad command line to confirm all interactive questions)";
         get_user_approval_or_exit(msg, args.yes);
         info!("Deleting databases");

simpa/src/main.rs

@@ -136,6 +136,7 @@ fn main() {
     kaspa_core::log::init_logger(None, &args.log_level);
 
     // Configure the panic behavior
+    // As we log the panic, we want to set it up after the logger
     kaspa_core::panic::configure_panic();
 
     // Print package name and version
@@ -170,7 +171,7 @@ fn main_impl(mut args: Args) {
 
     if args.miners > 1 {
         warn!(
-            "Warning: number of miners was configured to {}. Currently each miner added doubles the simulation 
+            "Warning: number of miners was configured to {}. Currently each miner added doubles the simulation
         memory and runtime footprint, while a single miner is sufficient for most simulation purposes (delay is simulated anyway).",
             args.miners
         );
@@ -441,8 +442,9 @@ mod tests {
         args.tpb = 1;
         args.test_pruning = true;
 
-        kaspa_core::panic::configure_panic();
         kaspa_core::log::try_init_logger(&args.log_level);
+        // As we log the panic, we want to set it up after the logger
+        kaspa_core::panic::configure_panic();
         main_impl(args);
     }
 }

testing/integration/src/mempool_benchmarks.rs

@@ -39,8 +39,9 @@ use tokio::join;
 #[tokio::test]
 #[ignore = "bmk"]
 async fn bench_bbt_latency() {
-    kaspa_core::panic::configure_panic();
     kaspa_core::log::try_init_logger("info,kaspa_core::time=debug,kaspa_mining::monitor=debug");
+    // As we log the panic, we want to set it up after the logger
+    kaspa_core::panic::configure_panic();
 
     // Constants
     const BLOCK_COUNT: usize = usize::MAX;
@@ -286,8 +287,9 @@ async fn bench_bbt_latency() {
 #[tokio::test]
 #[ignore = "bmk"]
 async fn bench_bbt_latency_2() {
-    kaspa_core::panic::configure_panic();
     kaspa_core::log::try_init_logger("info,kaspa_core::time=debug,kaspa_mining::monitor=debug");
+    // As we log the panic, we want to set it up after the logger
+    kaspa_core::panic::configure_panic();
 
     // Constants
     const BLOCK_COUNT: usize = usize::MAX;

testing/integration/src/rpc_tests.rs

@@ -39,8 +39,9 @@ macro_rules! tst {
 /// `cargo test --release --package kaspa-testing-integration --lib -- rpc_tests::sanity_test`
 #[tokio::test]
 async fn sanity_test() {
-    kaspa_core::panic::configure_panic();
     kaspa_core::log::try_init_logger("info");
+    // As we log the panic, we want to set it up after the logger
+    kaspa_core::panic::configure_panic();
 
     let args = Args {
         simnet: true,

testing/integration/src/subscribe_benchmarks.rs

@@ -75,10 +75,11 @@ fn create_client_addresses(index: usize, network_id: &NetworkId) -> Vec<Address>
 #[ignore = "bmk"]
 async fn utxos_changed_subscriptions_sanity_check() {
     init_allocator_with_default_settings();
-    kaspa_core::panic::configure_panic();
     kaspa_core::log::try_init_logger(
-        "INFO, kaspa_core::time=debug, kaspa_rpc_core=debug, kaspa_grpc_client=debug, kaspa_notify=info, kaspa_notify::address::tracker=debug, kaspa_notify::listener=debug, kaspa_notify::subscription::single=debug, kaspa_mining::monitor=debug, kaspa_testing_integration::subscribe_benchmarks=trace", 
+        "INFO, kaspa_core::time=debug, kaspa_rpc_core=debug, kaspa_grpc_client=debug, kaspa_notify=info, kaspa_notify::address::tracker=debug, kaspa_notify::listener=debug, kaspa_notify::subscription::single=debug, kaspa_mining::monitor=debug, kaspa_testing_integration::subscribe_benchmarks=trace",
     );
+    // As we log the panic, we want to set it up after the logger
+    kaspa_core::panic::configure_panic();
 
     let (prealloc_sk, _) = secp256k1::generate_keypair(&mut thread_rng());
     let args = ArgsBuilder::simnet(TX_LEVEL_WIDTH as u64 * CONTRACT_FACTOR, PREALLOC_AMOUNT)
@@ -131,10 +132,11 @@ async fn utxos_changed_subscriptions_sanity_check() {
 #[ignore = "bmk"]
 async fn bench_utxos_changed_subscriptions_daemon() {
     init_allocator_with_default_settings();
-    kaspa_core::panic::configure_panic();
     kaspa_core::log::try_init_logger(
-        "INFO, kaspa_core::core=trace, kaspa_core::time=debug, kaspa_rpc_core=debug, kaspa_grpc_client=debug, kaspa_notify=info, kaspa_notify::address::tracker=debug, kaspa_notify::listener=debug, kaspa_notify::subscription::single=debug, kaspa_mining::monitor=debug, kaspa_testing_integration::subscribe_benchmarks=trace", 
+        "INFO, kaspa_core::core=trace, kaspa_core::time=debug, kaspa_rpc_core=debug, kaspa_grpc_client=debug, kaspa_notify=info, kaspa_notify::address::tracker=debug, kaspa_notify::listener=debug, kaspa_notify::subscription::single=debug, kaspa_mining::monitor=debug, kaspa_testing_integration::subscribe_benchmarks=trace",
     );
+    // As we log the panic, we want to set it up after the logger
+    kaspa_core::panic::configure_panic();
 
     let daemon_args = DaemonArgs::from_env_args();
     let args = ArgsBuilder::simnet(TX_LEVEL_WIDTH as u64 * CONTRACT_FACTOR, PREALLOC_AMOUNT).apply_daemon_args(&daemon_args).build();
@@ -157,10 +159,11 @@ async fn bench_utxos_changed_subscriptions_daemon() {
 
 async fn utxos_changed_subscriptions_client(address_cycle_seconds: u64, address_max_cycles: usize) {
     init_allocator_with_default_settings();
-    kaspa_core::panic::configure_panic();
     kaspa_core::log::try_init_logger(
-        "INFO, kaspa_core::time=debug, kaspa_rpc_core=debug, kaspa_grpc_client=debug, kaspa_notify=info, kaspa_notify::address::tracker=debug, kaspa_notify::listener=debug, kaspa_notify::subscription::single=debug, kaspa_mining::monitor=debug, kaspa_testing_integration::subscribe_benchmarks=trace", 
+        "INFO, kaspa_core::time=debug, kaspa_rpc_core=debug, kaspa_grpc_client=debug, kaspa_notify=info, kaspa_notify::address::tracker=debug, kaspa_notify::listener=debug, kaspa_notify::subscription::single=debug, kaspa_mining::monitor=debug, kaspa_testing_integration::subscribe_benchmarks=trace",
     );
+    // As we log the panic, we want to set it up after the logger
+    kaspa_core::panic::configure_panic();
 
     assert!(address_cycle_seconds >= 60);
     if TX_COUNT < TX_LEVEL_WIDTH {