Print time in shutdown logging

5 files changed, 43 insertions, 22 deletions

diff --git a/yt/yt/core/misc/hazard_ptr.cpp b/yt/yt/core/misc/hazard_ptr.cpp
index 35da3c4b78b..97f6da87e23 100644
--- a/yt/yt/core/misc/hazard_ptr.cpp
+++ b/yt/yt/core/misc/hazard_ptr.cpp
@@ -184,7 +184,8 @@ THazardPointerManager::THazardPointerManager()
 void THazardPointerManager::Shutdown()
 {
     if (auto* logFile = TryGetShutdownLogFile()) {
-        ::fprintf(logFile, "*** Hazard Pointer Manager shutdown started (ThreadCount: %d)\n",
+        ::fprintf(logFile, "%s\t*** Hazard Pointer Manager shutdown started (ThreadCount: %d)\n",
+            GetInstant().ToString().c_str(),
             ThreadCount_.load());
     }
 
@@ -195,7 +196,8 @@ void THazardPointerManager::Shutdown()
     });
 
     if (auto* logFile = TryGetShutdownLogFile()) {
-        ::fprintf(logFile, "*** Hazard Pointer Manager shutdown completed (DeletedPtrCount: %d)\n",
+        ::fprintf(logFile, "%s\t*** Hazard Pointer Manager shutdown completed (DeletedPtrCount: %d)\n",
+            GetInstant().ToString().c_str(),
             count);
     }
 }
@@ -282,7 +284,8 @@ THazardThreadState* THazardPointerManager::AllocateThreadState()
     }
 
     if (auto* logFile = TryGetShutdownLogFile()) {
-        ::fprintf(logFile, "*** Hazard Pointer Manager thread state allocated (ThreadId: %" PRISZT ")\n",
+        ::fprintf(logFile, "%s\t*** Hazard Pointer Manager thread state allocated (ThreadId: %" PRISZT ")\n",
+            GetInstant().ToString().c_str(),
             GetCurrentThreadId());
     }
 
@@ -374,7 +377,8 @@ void THazardPointerManager::DestroyThreadState(THazardThreadState* threadState)
     }
 
     if (auto* logFile = TryGetShutdownLogFile()) {
-        ::fprintf(logFile, "*** Hazard Pointer Manager thread state destroyed (ThreadId: %" PRISZT ", RetiredPtrCount: %d)\n",
+        ::fprintf(logFile, "%s\t*** Hazard Pointer Manager thread state destroyed (ThreadId: %" PRISZT ", RetiredPtrCount: %d)\n",
+            GetInstant().ToString().c_str(),
             GetCurrentThreadId(),
             count);
     }
diff --git a/yt/yt/core/misc/shutdown.cpp b/yt/yt/core/misc/shutdown.cpp
index 758980909be..3646df71505 100644
--- a/yt/yt/core/misc/shutdown.cpp
+++ b/yt/yt/core/misc/shutdown.cpp
@@ -37,7 +37,8 @@ public:
 
         if (ShutdownStarted_.load()) {
             if (auto* logFile = TryGetShutdownLogFile()) {
-                ::fprintf(logFile, "*** Attempt to register shutdown callback when shutdown is already in progress (Name: %s)\n",
+                ::fprintf(logFile, "%s\t*** Attempt to register shutdown callback when shutdown is already in progress (Name: %s)\n",
+                    GetInstant().ToString().c_str(),
                     name.c_str());
             }
             return nullptr;
@@ -50,7 +51,8 @@ public:
         InsertOrCrash(RegisteredCallbacks_, registeredCallback.Get());
 
         if (auto* logFile = TryGetShutdownLogFile()) {
-            ::fprintf(logFile, "*** Shutdown callback registered (Name: %s, Priority: %d)\n",
+            ::fprintf(logFile, "%s\t*** Shutdown callback registered (Name: %s, Priority: %d)\n",
+                GetInstant().ToString().c_str(),
                 registeredCallback->Name.c_str(),
                 registeredCallback->Priority);
         }
@@ -73,7 +75,8 @@ public:
             ShutdownThreadId_.store(GetCurrentThreadId());
 
             if (auto* logFile = TryGetShutdownLogFile()) {
-                ::fprintf(logFile, "*** Shutdown started (ThreadId: %" PRISZT ")\n",
+                ::fprintf(logFile, "%s\t*** Shutdown started (ThreadId: %" PRISZT ")\n",
+                    GetInstant().ToString().c_str(),
                     GetCurrentThreadId());
             }
 
@@ -108,7 +111,8 @@ public:
         for (auto it = registeredCallbacks.rbegin(); it != registeredCallbacks.rend(); it++) {
             const auto& registeredCallback = *it;
             if (auto* logFile = TryGetShutdownLogFile()) {
-                ::fprintf(logFile, "*** Running callback (Name: %s, Priority: %d)\n",
+                ::fprintf(logFile, "%s\t*** Running callback (Name: %s, Priority: %d)\n",
+                    GetInstant().ToString().c_str(),
                     registeredCallback.Name.c_str(),
                     registeredCallback.Priority);
             }
@@ -121,7 +125,8 @@ public:
     #endif
 
         if (auto* logFile = TryGetShutdownLogFile()) {
-            ::fprintf(logFile, "*** Shutdown completed\n");
+            ::fprintf(logFile, "%s\t*** Shutdown completed\n",
+                GetInstant().ToString().c_str());
         }
     }
 
@@ -209,7 +214,8 @@ private:
     {
         auto guard = Guard(Lock_);
         if (auto* logFile = TryGetShutdownLogFile()) {
-            ::fprintf(logFile, "*** Shutdown callback unregistered (Name: %s, Priority: %d)\n",
+            ::fprintf(logFile, "%s\t*** Shutdown callback unregistered (Name: %s, Priority: %d)\n",
+                GetInstant().ToString().c_str(),
                 registeredCallback->Name.c_str(),
                 registeredCallback->Priority);
         }
diff --git a/yt/yt/core/rpc/grpc/server.cpp b/yt/yt/core/rpc/grpc/server.cpp
index c845a3f0891..1b9909005d0 100644
--- a/yt/yt/core/rpc/grpc/server.cpp
+++ b/yt/yt/core/rpc/grpc/server.cpp
@@ -174,7 +174,8 @@ private:
             DoStop(graceful).Get().ThrowOnError();
         } catch (...) {
             if (auto* logFile = TryGetShutdownLogFile()) {
-                ::fprintf(logFile, "GRPC server shutdown failed: %s (ThreadId: %" PRISZT ")\n",
+                ::fprintf(logFile, "%s\tGRPC server shutdown failed: %s (ThreadId: %" PRISZT ")\n",
+                    GetInstant().ToString().c_str(),
                     CurrentExceptionMessage().c_str(),
                     GetCurrentThreadId());
             }
diff --git a/yt/yt/core/rpc/unittests/rpc_shutdown_ut.cpp b/yt/yt/core/rpc/unittests/rpc_shutdown_ut.cpp
index 8691dc4e9a5..5a2d043847b 100644
--- a/yt/yt/core/rpc/unittests/rpc_shutdown_ut.cpp
+++ b/yt/yt/core/rpc/unittests/rpc_shutdown_ut.cpp
@@ -48,7 +48,7 @@ void TestShutdown(const IChannelPtr& channel)
 
     while (shutdownLogInput.ReadLine(buffer)) {
         Cerr << buffer << Endl;
-        if (exitCode && buffer == "*** Shutdown completed") {
+        if (exitCode && buffer.Contains("*** Shutdown completed")) {
             exitCode = 0;
         }
     }
diff --git a/yt/yt/core/threading/thread.cpp b/yt/yt/core/threading/thread.cpp
index 57a7cbfdbc1..cc8f9cfae7d 100644
--- a/yt/yt/core/threading/thread.cpp
+++ b/yt/yt/core/threading/thread.cpp
@@ -72,7 +72,8 @@ bool TThread::StartSlow()
     }
 
     if (auto* logFile = TryGetShutdownLogFile()) {
-        ::fprintf(logFile, "*** Starting thread (ThreadName: %s)\n",
+        ::fprintf(logFile, "%s\t*** Starting thread (ThreadName: %s)\n",
+            GetInstant().ToString().c_str(),
             ThreadName_.c_str());
     }
 
@@ -81,7 +82,8 @@ bool TThread::StartSlow()
     try {
         UnderlyingThread_.Start();
     } catch (const std::exception& ex) {
-        fprintf(stderr, "*** Error starting thread (ThreadName: %s)\n*** %s\n",
+        fprintf(stderr, "%s\t*** Error starting thread (ThreadName: %s)\n*** %s\n",
+            GetInstant().ToString().c_str(),
             ThreadName_.c_str(),
             ex.what());
         YT_ABORT();
@@ -94,7 +96,8 @@ bool TThread::StartSlow()
     StartEpilogue();
 
     if (auto* logFile = TryGetShutdownLogFile()) {
-        ::fprintf(logFile, "*** Thread started (ThreadName: %s, ThreadId: %" PRISZT ")\n",
+        ::fprintf(logFile, "%s\t*** Thread started (ThreadName: %s, ThreadId: %" PRISZT ")\n",
+            GetInstant().ToString().c_str(),
             ThreadName_.c_str(),
             ThreadId_);
     }
@@ -122,7 +125,8 @@ void TThread::Stop()
             // Avoid deadlock.
             if (CanWaitForThreadShutdown()) {
                 if (auto* logFile = TryGetShutdownLogFile()) {
-                    ::fprintf(logFile, "*** Waiting for an already stopping thread to finish (ThreadName: %s, ThreadId: %" PRISZT ", WaiterThreadId: %" PRISZT ")\n",
+                    ::fprintf(logFile, "%s\t*** Waiting for an already stopping thread to finish (ThreadName: %s, ThreadId: %" PRISZT ", WaiterThreadId: %" PRISZT ")\n",
+                        GetInstant().ToString().c_str(),
                         ThreadName_.c_str(),
                         ThreadId_,
                         GetCurrentThreadId());
@@ -130,7 +134,8 @@ void TThread::Stop()
                 StoppedEvent_.Wait();
             } else {
                 if (auto* logFile = TryGetShutdownLogFile()) {
-                    ::fprintf(logFile, "*** Cannot wait for an already stopping thread to finish (ThreadName: %s, ThreadId: %" PRISZT ", WaiterThreadId: %" PRISZT ")\n",
+                    ::fprintf(logFile, "%s\t*** Cannot wait for an already stopping thread to finish (ThreadName: %s, ThreadId: %" PRISZT ", WaiterThreadId: %" PRISZT ")\n",
+                        GetInstant().ToString().c_str(),
                         ThreadName_.c_str(),
                         ThreadId_,
                         GetCurrentThreadId());
@@ -141,7 +146,8 @@ void TThread::Stop()
     }
 
     if (auto* logFile = TryGetShutdownLogFile()) {
-        ::fprintf(logFile, "*** Stopping thread (ThreadName: %s, ThreadId: %" PRISZT ", RequesterThreadId: %" PRISZT ")\n",
+        ::fprintf(logFile, "%s\t*** Stopping thread (ThreadName: %s, ThreadId: %" PRISZT ", RequesterThreadId: %" PRISZT ")\n",
+            GetInstant().ToString().c_str(),
             ThreadName_.c_str(),
             ThreadId_,
             GetCurrentThreadId());
@@ -152,7 +158,8 @@ void TThread::Stop()
     // Avoid deadlock.
     if (CanWaitForThreadShutdown()) {
         if (auto* logFile = TryGetShutdownLogFile()) {
-            ::fprintf(logFile, "*** Waiting for thread to stop (ThreadName: %s, ThreadId: %" PRISZT ", RequesterThreadId: %" PRISZT ")\n",
+            ::fprintf(logFile, "%s\t*** Waiting for thread to stop (ThreadName: %s, ThreadId: %" PRISZT ", RequesterThreadId: %" PRISZT ")\n",
+                GetInstant().ToString().c_str(),
                 ThreadName_.c_str(),
                 ThreadId_,
                 GetCurrentThreadId());
@@ -160,7 +167,8 @@ void TThread::Stop()
         UnderlyingThread_.Join();
     } else {
         if (auto* logFile = TryGetShutdownLogFile()) {
-            ::fprintf(logFile, "*** Cannot wait for thread to stop; detaching (ThreadName: %s, ThreadId: %" PRISZT ", RequesterThreadId: %" PRISZT ")\n",
+            ::fprintf(logFile, "%s\t*** Cannot wait for thread to stop; detaching (ThreadName: %s, ThreadId: %" PRISZT ", RequesterThreadId: %" PRISZT ")\n",
+                GetInstant().ToString().c_str(),
                 ThreadName_.c_str(),
                 ThreadId_,
                 GetCurrentThreadId());
@@ -171,7 +179,8 @@ void TThread::Stop()
     StopEpilogue();
 
     if (auto* logFile = TryGetShutdownLogFile()) {
-        ::fprintf(logFile, "*** Thread stopped (ThreadName: %s, ThreadId: %" PRISZT ", RequesterThreadId: %" PRISZT ")\n",
+        ::fprintf(logFile, "%s\t*** Thread stopped (ThreadName: %s, ThreadId: %" PRISZT ", RequesterThreadId: %" PRISZT ")\n",
+            GetInstant().ToString().c_str(),
             ThreadName_.c_str(),
             ThreadId_,
             GetCurrentThreadId());
@@ -204,7 +213,8 @@ void TThread::ThreadMainTrampoline()
         {
             if (Armed_ && !std::uncaught_exceptions()) {
                 if (auto* logFile = TryGetShutdownLogFile()) {
-                    ::fprintf(logFile, "Thread exit interceptor triggered (ThreadId: %" PRISZT ")\n",
+                    ::fprintf(logFile, "%s\tThread exit interceptor triggered (ThreadId: %" PRISZT ")\n",
+                        GetInstant().ToString().c_str(),
                         GetCurrentThreadId());
                 }
                 Shutdown();