capture zenserver output on error (#51)

* capture spawned server output and output on launch error
* fix logging and launch validation in tests

7 files changed, 112 insertions, 30 deletions

diff --git a/CHANGELOG.md b/CHANGELOG.md
index 456150f6b..197cf53ef 100644
--- a/CHANGELOG.md
+++ b/CHANGELOG.md
@@ -24,6 +24,7 @@
 - Imrpovement: Make sure zenserver detaches itself as a child process at startup to avoid zombie process if parent process does not wait for zenserver child process
 - Improvement: Trying to load a compact binary object from an empty file no longer causes access violation
 - Improvement: When importing oplogs we now import all attachments first and (optionally clean) write the oplog on success to avoid invalid import results
+- Improvement: Capture launched zenserver output to display to user if launch fails
 
 ## 5.4.4
 - Bugfix: Get raw size for compressed chunks correctly for `/prj/{project}/oplog/{log}/chunkinfos`
diff --git a/src/zen/cmds/up_cmd.cpp b/src/zen/cmds/up_cmd.cpp
index 3095211b6..0db5afb3b 100644
--- a/src/zen/cmds/up_cmd.cpp
+++ b/src/zen/cmds/up_cmd.cpp
@@ -86,14 +86,20 @@ UpCommand::Run(const ZenCliOptions& GlobalOptions, int argc, char** argv)
 
 	if (!Server.WaitUntilReady(Timeout))
 	{
-		ZEN_ERROR("zen server launch failed (timed out)");
-		return 1;
+		if (Server.IsRunning())
+		{
+			ZEN_ERROR("zen server launch failed (timed out), terminating");
+			Server.Terminate();
+			return 111;
+		}
+		int ReturnCode = Server.Shutdown();
+		ZEN_CONSOLE("{}", Server.GetLogOutput());
+		return ReturnCode;
 	}
 	else
 	{
 		ZEN_CONSOLE("zen server up");
 	}
-
 	return 0;
 }
 
diff --git a/src/zencore/include/zencore/process.h b/src/zencore/include/zencore/process.h
index dbf5837e2..48a2eb0d7 100644
--- a/src/zencore/include/zencore/process.h
+++ b/src/zencore/include/zencore/process.h
@@ -28,6 +28,7 @@ public:
 	ZENCORE_API [[nodiscard]] bool IsValid() const;
 	ZENCORE_API bool			   Wait(int TimeoutMs = -1);
 	ZENCORE_API int				   WaitExitCode();
+	ZENCORE_API int				   GetExitCode();
 	ZENCORE_API bool			   Terminate(int ExitCode);
 	ZENCORE_API void			   Reset();
 	[[nodiscard]] inline int	   Pid() const { return m_Pid; }
diff --git a/src/zencore/process.cpp b/src/zencore/process.cpp
index 8fddc9562..88eb8af0d 100644
--- a/src/zencore/process.cpp
+++ b/src/zencore/process.cpp
@@ -277,10 +277,8 @@ ProcessHandle::Wait(int TimeoutMs)
 }
 
 int
-ProcessHandle::WaitExitCode()
+ProcessHandle::GetExitCode()
 {
-	Wait(-1);
-
 #if ZEN_PLATFORM_WINDOWS
 	DWORD ExitCode = 0;
 	GetExitCodeProcess(m_ProcessHandle, &ExitCode);
@@ -297,6 +295,13 @@ ProcessHandle::WaitExitCode()
 #endif
 }
 
+int
+ProcessHandle::WaitExitCode()
+{
+	Wait(-1);
+	return GetExitCode();
+}
+
 //////////////////////////////////////////////////////////////////////////
 
 #if !ZEN_PLATFORM_WINDOWS || ZEN_WITH_TESTS
diff --git a/src/zenserver-test/zenserver-test.cpp b/src/zenserver-test/zenserver-test.cpp
index aa711ab7c..4d2c507fe 100644
--- a/src/zenserver-test/zenserver-test.cpp
+++ b/src/zenserver-test/zenserver-test.cpp
@@ -234,7 +234,9 @@ TEST_CASE("multi.basic")
 	ZEN_INFO("Waiting...");
 
 	const uint16_t PortNum1 = Instance1.WaitUntilReady();
+	CHECK_MESSAGE(PortNum1 != 0, Instance1.GetLogOutput());
 	const uint16_t PortNum2 = Instance2.WaitUntilReady();
+	CHECK_MESSAGE(PortNum2 != 0, Instance1.GetLogOutput());
 
 	std::atomic<uint64_t> RequestCount{0};
 	std::atomic<uint64_t> BatchCounter{0};
@@ -478,6 +480,7 @@ namespace utils {
 			Inst.SetTestDir(DataDir);
 			Inst.SpawnServer(Port, Args);
 			const uint16_t InstancePort = Inst.WaitUntilReady();
+			CHECK_MESSAGE(InstancePort != 0, Inst.GetLogOutput());
 
 			if (Port != InstancePort)
 				ZEN_DEBUG("relocation detected from {} to {}", Port, InstancePort);
@@ -738,6 +741,7 @@ TEST_CASE("zcache.cbpackage")
 		LocalInstance.SpawnServer(TestEnv.GetNewPortNumber(),
 								  fmt::format("--upstream-thread-count=0 --upstream-zen-url=http://localhost:{}", RemotePortNumber));
 		const uint16_t LocalPortNumber = LocalInstance.WaitUntilReady();
+		CHECK_MESSAGE(LocalPortNumber != 0, LocalInstance.GetLogOutput());
 
 		const auto LocalBaseUri	 = fmt::format("http://localhost:{}/z$", LocalPortNumber);
 		const auto RemoteBaseUri = fmt::format("http://localhost:{}/z$", RemotePortNumber);
@@ -798,6 +802,7 @@ TEST_CASE("zcache.cbpackage")
 		LocalInstance.SpawnServer(TestEnv.GetNewPortNumber(),
 								  fmt::format("--upstream-thread-count=0 --upstream-zen-url=http://localhost:{}", RemotePortNumber));
 		const uint16_t LocalPortNumber = LocalInstance.WaitUntilReady();
+		CHECK_MESSAGE(LocalPortNumber != 0, LocalInstance.GetLogOutput());
 
 		const auto LocalBaseUri	 = fmt::format("http://localhost:{}/z$", LocalPortNumber);
 		const auto RemoteBaseUri = fmt::format("http://localhost:{}/z$", RemotePortNumber);
@@ -2563,7 +2568,8 @@ public:
 		{
 			auto& Instance = m_Instances[i];
 
-			Instance->WaitUntilReady();
+			uint16_t PortNumber = Instance->WaitUntilReady();
+			CHECK_MESSAGE(PortNumber != 0, Instance->GetLogOutput());
 		}
 	}
 
diff --git a/src/zenutil/include/zenutil/zenserverprocess.h b/src/zenutil/include/zenutil/zenserverprocess.h
index af5125471..1bd00acb7 100644
--- a/src/zenutil/include/zenutil/zenserverprocess.h
+++ b/src/zenutil/include/zenutil/zenserverprocess.h
@@ -66,7 +66,7 @@ struct ZenServerInstance
 	ZenServerInstance(ZenServerEnvironment& TestEnvironment);
 	~ZenServerInstance();
 
-	void			   Shutdown();
+	int				   Shutdown();
 	void			   SignalShutdown();
 	uint16_t		   WaitUntilReady();
 	[[nodiscard]] bool WaitUntilReady(int Timeout);
@@ -77,6 +77,7 @@ struct ZenServerInstance
 	inline void		   SetOwnerPid(int Pid) { m_OwnerPid = Pid; }
 	bool			   IsRunning();
 	bool			   Terminate();
+	std::string		   GetLogOutput() const;
 
 	void SetTestDir(std::filesystem::path TestDir);
 
@@ -116,6 +117,7 @@ private:
 	uint16_t			  m_BasePort = 0;
 	std::optional<int>	  m_OwnerPid;
 	std::string			  m_Name;
+	std::filesystem::path m_OutputCapturePath;
 
 	void CreateShutdownEvent(int BasePort);
 	void SpawnServer(int BasePort, std::string_view AdditionalServerArgs, int WaitTimeoutMs);
diff --git a/src/zenutil/zenserverprocess.cpp b/src/zenutil/zenserverprocess.cpp
index 9a2ec9774..f5bc088a5 100644
--- a/src/zenutil/zenserverprocess.cpp
+++ b/src/zenutil/zenserverprocess.cpp
@@ -12,6 +12,7 @@
 #include <zencore/string.h>
 #include <zencore/thread.h>
 #include <zencore/timer.h>
+#include <zenutil/basicfile.h>
 
 #include <atomic>
 
@@ -534,6 +535,8 @@ ZenServerInstance::~ZenServerInstance()
 	try
 	{
 		Shutdown();
+		std::error_code DummyEc;
+		std::filesystem::remove(std::filesystem::temp_directory_path() / ("zenserver_" + m_Name + ".log"), DummyEc);
 	}
 	catch (const std::exception& Err)
 	{
@@ -547,7 +550,7 @@ ZenServerInstance::SignalShutdown()
 	m_ShutdownEvent.Set();
 }
 
-void
+int
 ZenServerInstance::Shutdown()
 {
 	if (m_Process.IsValid())
@@ -557,28 +560,44 @@ ZenServerInstance::Shutdown()
 			if (m_Terminate)
 			{
 				ZEN_INFO("Terminating zenserver process {}", m_Name);
-				m_Process.Terminate(111);
+				int ExitCode = 111;
+				m_Process.Terminate(ExitCode);
 				m_Process.Reset();
 				ZEN_DEBUG("zenserver process {} ({}) terminated", m_Name, m_Process.Pid());
+				return ExitCode;
 			}
 			else
 			{
-				ZEN_DEBUG("Requesting zenserver process {} ({}) to shut down", m_Name, m_Process.Pid());
-				SignalShutdown();
-				ZEN_DEBUG("Waiting for zenserver process {} ({}) to shut down", m_Name, m_Process.Pid());
-				while (!m_Process.Wait(5000))
+				if (m_Process.IsRunning())
 				{
-					ZEN_WARN("Waiting for zenserver process {} ({}) timed out", m_Name, m_Process.Pid());
+					ZEN_DEBUG("Requesting zenserver process {} ({}) to shut down", m_Name, m_Process.Pid());
+					SignalShutdown();
+					ZEN_DEBUG("Waiting for zenserver process {} ({}) to shut down", m_Name, m_Process.Pid());
+					while (!m_Process.Wait(5000))
+					{
+						ZEN_WARN("Waiting for zenserver process {} ({}) timed out", m_Name, m_Process.Pid());
+					}
 				}
+				ZEN_DEBUG("zenserver process {} ({}) exited", m_Name, m_Process.Pid());
+				int ExitCode = m_Process.GetExitCode();
 				m_Process.Reset();
+				return ExitCode;
 			}
-			ZEN_DEBUG("zenserver process {} ({}) exited", m_Name, m_Process.Pid());
 		}
 		else
 		{
+			if (m_Process.Wait(0))
+			{
+				int ExitCode = m_Process.GetExitCode();
+				ZEN_DEBUG("zenserver process {} ({}) exited", m_Name, m_Process.Pid());
+				m_Process.Reset();
+				return ExitCode;
+			}
 			ZEN_DEBUG("Detached from zenserver process {} ({})", m_Name, m_Process.Pid());
+			return 0;
 		}
 	}
+	return -1;
 }
 
 void
@@ -654,11 +673,9 @@ ZenServerInstance::SpawnServer(int BasePort, std::string_view AdditionalServerAr
 
 	const std::filesystem::path BaseDir		  = m_Env.ProgramBaseDir();
 	const std::filesystem::path Executable	  = BaseDir / "zenserver" ZEN_EXE_SUFFIX_LITERAL;
-	CreateProcOptions			CreateOptions = {
-				  .WorkingDirectory = &CurrentDirectory,
-				  .Flags			= CreationFlags,
-	  };
-	CreateProcResult ChildPid = CreateProc(Executable, CommandLine.ToView(), CreateOptions);
+	const std::filesystem::path OutputPath	  = std::filesystem::temp_directory_path() / ("zenserver_" + m_Name + ".log");
+	CreateProcOptions			CreateOptions = {.WorkingDirectory = &CurrentDirectory, .Flags = CreationFlags, .StdoutFile = OutputPath};
+	CreateProcResult			ChildPid	  = CreateProc(Executable, CommandLine.ToView(), CreateOptions);
 #if ZEN_PLATFORM_WINDOWS
 	if (!ChildPid && ::GetLastError() == ERROR_ELEVATION_REQUIRED)
 	{
@@ -688,7 +705,11 @@ ZenServerInstance::SpawnServer(int BasePort, std::string_view AdditionalServerAr
 	{
 		if (!WaitUntilReady(WaitTimeoutMs))
 		{
-			throw std::runtime_error(fmt::format("server start of {} timeout after {}", m_Name, NiceTimeSpanMs(WaitTimeoutMs)));
+			throw std::runtime_error(fmt::format("server start of {} {} after {}: {}",
+												 m_Name,
+												 m_Process.IsRunning() ? "timeout" : "crash",
+												 NiceTimeSpanMs(WaitTimeoutMs),
+												 GetLogOutput()));
 		}
 	}
 }
@@ -762,10 +783,14 @@ ZenServerInstance::WaitUntilReady()
 {
 	while (m_ReadyEvent.Wait(100) == false)
 	{
-		if (!m_Process.IsRunning() || !m_Process.IsValid())
+		if (!m_Process.IsValid())
 		{
-			ZEN_WARN("Wait abandoned by invalid process (running={})", m_Process.IsRunning());
-
+			ZEN_WARN("Wait abandoned by invalid process");
+			return 0;
+		}
+		if (!m_Process.IsRunning())
+		{
+			ZEN_WARN("Wait abandoned by exited process");
 			return 0;
 		}
 	}
@@ -778,14 +803,30 @@ ZenServerInstance::WaitUntilReady()
 bool
 ZenServerInstance::WaitUntilReady(int Timeout)
 {
-	if (m_ReadyEvent.Wait(Timeout))
+	int TimeoutLeftMS = Timeout;
+	while (m_ReadyEvent.Wait(100) == false)
 	{
-		OnServerReady();
-
-		return true;
+		if (!m_Process.IsValid())
+		{
+			ZEN_WARN("Wait abandoned by invalid process");
+			return false;
+		}
+		if (!m_Process.IsRunning())
+		{
+			ZEN_WARN("Wait abandoned by exited process");
+			return false;
+		}
+		TimeoutLeftMS -= 100;
+		if ((TimeoutLeftMS <= 0))
+		{
+			ZEN_WARN("Wait abandoned due to timeout");
+			return false;
+		}
 	}
 
-	return false;
+	OnServerReady();
+
+	return true;
 }
 
 void
@@ -851,6 +892,26 @@ ZenServerInstance::IsRunning()
 	return m_Process.IsRunning();
 }
 
+std::string
+ZenServerInstance::GetLogOutput() const
+{
+	std::filesystem::path OutputPath = std::filesystem::temp_directory_path() / ("zenserver_" + m_Name + ".log");
+	if (std::filesystem::is_regular_file(OutputPath))
+	{
+		FileContents Contents = ReadFile(OutputPath);
+		if (!Contents.ErrorCode)
+		{
+			IoBuffer Content = Contents.Flatten();
+			if (Content)
+			{
+				std::string Log((const char*)Content.Data(), Content.Size());
+				return Log;
+			}
+		}
+	}
+	return {};
+}
+
 bool
 ZenServerInstance::Terminate()
 {