nvmeof: add comprehensive debug logging to monitor client initialization

Signed-off-by: Alexander Indenbaum <aindenba@redhat.com>

diff --git a/src/nvmeof/NVMeofGwMonitorClient.cc b/src/nvmeof/NVMeofGwMonitorClient.cc
index fc8595a34184b09f9417d2cde3623af4108238f3..9d5bc15a503289eb83e63345b67cab56eeb94f01 100644 (file)
--- a/src/nvmeof/NVMeofGwMonitorClient.cc
+++ b/src/nvmeof/NVMeofGwMonitorClient.cc
@@ -81,6 +81,7 @@ std::shared_ptr<grpc::ChannelCredentials> NVMeofGwMonitorClient::gw_creds()
 
 int NVMeofGwMonitorClient::init()
 {
+  dout(1) << "=== NVMeofGwMonitorClient::init() STARTED ===" << dendl;
   dout(10) << dendl;
   std::string val;
   auto args = argv_to_vec(orig_argc, orig_argv);
@@ -109,7 +110,7 @@ int NVMeofGwMonitorClient::init()
     }
   }
 
-  dout(10) << "gateway name: " << name <<
+  dout(1) << "Configuration parsed - gateway name: " << name <<
     " pool:" << pool <<
     " group:" << group <<
     " address: " << gateway_address << dendl;
@@ -119,28 +120,36 @@ int NVMeofGwMonitorClient::init()
   ceph_assert((server_cert.empty() == client_key.empty()) && (client_key.empty() == client_cert.empty()));
   init_gw_ssl_opts();
 
+  dout(1) << "About to initialize signal handlers" << dendl;
   init_async_signal_handler();
   register_async_signal_handler(SIGHUP, sighup_handler);
+  dout(1) << "Signal handlers initialized" << dendl;
 
   std::lock_guard l(lock);
+  dout(1) << "Acquired main lock, starting messenger initialization" << dendl;
 
   // Initialize Messenger
   client_messenger->add_dispatcher_tail(this);
   client_messenger->add_dispatcher_head(&objecter);
   client_messenger->start();
+  dout(1) << "Messenger started" << dendl;
 
   poolctx.start(2);
+  dout(1) << "Pool context started" << dendl;
 
   // Initialize MonClient
+  dout(1) << "About to build initial monmap" << dendl;
   if (monc.build_initial_monmap() < 0) {
     client_messenger->shutdown();
     client_messenger->wait();
     return -1;
   }
 
+  dout(1) << "Initial monmap built successfully" << dendl;
   monc.sub_want("NVMeofGw", 0, 0);
   monc.set_want_keys(CEPH_ENTITY_TYPE_MON|CEPH_ENTITY_TYPE_OSD);
   monc.set_messenger(client_messenger.get());
+  dout(1) << "MonClient configured" << dendl;
 
   // We must register our config callback before calling init(), so
   // that we see the initial configuration message
@@ -154,7 +163,9 @@ int NVMeofGwMonitorClient::init()
     });
   dout(4) << "nvmeof Registered monc callback" << dendl;
 
+  dout(1) << "About to call monc.init()" << dendl;
   int r = monc.init();
+  dout(1) << "monc.init() returned: " << r << dendl;
   if (r < 0) {
     monc.shutdown();
     client_messenger->shutdown();
@@ -163,7 +174,9 @@ int NVMeofGwMonitorClient::init()
   }
   dout(10) << "nvmeof Registered monc callback" << dendl;
 
+  dout(1) << "About to call monc.authenticate()" << dendl;
   r = monc.authenticate();
+  dout(1) << "monc.authenticate() returned: " << r << dendl;
   if (r < 0) {
     derr << "Authentication failed, did you specify an ID with a valid keyring?" << dendl;
     monc.shutdown();
@@ -171,7 +184,7 @@ int NVMeofGwMonitorClient::init()
     client_messenger->wait();
     return r;
   }
-  dout(10) << "monc.authentication done" << dendl;
+  dout(1) << "monc.authentication done" << dendl;
   monc.set_passthrough_monmap();
 
   client_t whoami = monc.get_global_id();
@@ -180,6 +193,7 @@ int NVMeofGwMonitorClient::init()
   objecter.init();
   objecter.enable_blocklist_events();
   objecter.start();
+  dout(1) << "Starting timer initialization" << dendl;
   timer.init();
 
   {
@@ -188,11 +202,13 @@ int NVMeofGwMonitorClient::init()
     next_tick_time = ceph::mono_clock::now();
     timer_active = true;
     auto tick_period = g_conf().get_val<std::chrono::seconds>("nvmeof_mon_client_tick_period");
-    dout(4) << "Initializing timer with period " << tick_period.count() << " seconds" << dendl;
-    schedule_next_tick();
+  dout(1) << "Initializing timer with period " << tick_period.count() << " seconds" << dendl;
+  dout(1) << "About to call schedule_next_tick()" << dendl;
+  schedule_next_tick();
+  dout(1) << "schedule_next_tick() completed" << dendl;
   }
 
-  dout(10) << "Complete." << dendl;
+  dout(1) << "Monitor client initialization completed successfully" << dendl;
   return 0;
 }
 
@@ -303,8 +319,10 @@ void NVMeofGwMonitorClient::tick()
 void NVMeofGwMonitorClient::schedule_next_tick()
 {
   ceph_assert(ceph_mutex_is_locked_by_me(beacon_lock));
-
+  dout(1) << "schedule_next_tick() called, timer_active=" << timer_active << dendl;
+  
   if (!timer_active) {
+    dout(1) << "Timer not active, returning from schedule_next_tick()" << dendl;
     return;
   }
 
@@ -330,11 +348,13 @@ void NVMeofGwMonitorClient::schedule_next_tick()
     }
   });
 
+  dout(1) << "About to call timer.add_event_at()" << dendl;
   timer.add_event_at(next_tick_time, cb);
+  dout(1) << "timer.add_event_at() completed successfully" << dendl;
   auto delay_ns = (next_tick_time - now).count();
-  dout(10) << "Rescheduled next tick at " << next_tick_time
-           << " (delay: " << delay_ns << " ns, "
-           << (delay_ns / 1000000.0) << " ms)" << dendl;
+  dout(1) << "Rescheduled next tick at " << next_tick_time
+          << " (delay: " << delay_ns << " ns, "
+          << (delay_ns / 1000000.0) << " ms)" << dendl;
 }
 
 void NVMeofGwMonitorClient::tick_callback()
@@ -342,12 +362,12 @@ void NVMeofGwMonitorClient::tick_callback()
   ceph_assert(ceph_mutex_is_locked_by_me(beacon_lock));
 
   if (!timer_active) {
-    dout(10) << "Timer fired but timer_active=false, ignoring" << dendl;
+    dout(5) << "Timer fired but timer_active=false, ignoring" << dendl;
     return;
   }
 
   auto start_time = ceph::mono_clock::now();
-  dout(10) << "Timer fired at " << start_time << dendl;
+  dout(5) << "Timer fired at " << start_time << dendl;
 
   // Perform the actual tick work
   connect_panic();
@@ -358,7 +378,7 @@ void NVMeofGwMonitorClient::tick_callback()
   auto end_time = ceph::mono_clock::now();
   auto duration = end_time - start_time;
   auto duration_ms = duration.count() / 1000000.0;
-  dout(10) << "Tick execution completed in " << duration.count() << " ns (" << duration_ms << " ms)" << dendl;
+  dout(5) << "Tick execution completed in " << duration.count() << " ns (" << duration_ms << " ms)" << dendl;
 
   // Warn if execution time is significant compared to tick period
   auto tick_period = g_conf().get_val<std::chrono::seconds>("nvmeof_mon_client_tick_period");