Build command tweaks (#301)

- Improvement: Don't chunk up .mp4 files as they generally won't benefit from deduplication or partial in-place-updates
- Improvement: Emit build name to console output when downloading a build
- Improvement: Added some debug logging
- Bugfix: Logging setup would previously not function correctly when not logging to file

7 files changed, 83 insertions, 59 deletions

diff --git a/src/zen/cmds/builds_cmd.cpp b/src/zen/cmds/builds_cmd.cpp
index 2c7a73fb3..56c3c3c4f 100644
--- a/src/zen/cmds/builds_cmd.cpp
+++ b/src/zen/cmds/builds_cmd.cpp
@@ -5,6 +5,7 @@
 #include <zencore/basicfile.h>
 #include <zencore/compactbinarybuilder.h>
 #include <zencore/compactbinaryfile.h>
+#include <zencore/compactbinaryfmt.h>
 #include <zencore/compress.h>
 #include <zencore/except.h>
 #include <zencore/filesystem.h>
@@ -5699,10 +5700,14 @@ namespace {
 			std::vector<std::pair<Oid, std::string>> AvailableParts;
 
 			CbObject BuildObject = Storage.GetBuild(BuildId);
-			ZEN_CONSOLE("GetBuild took {}. Payload size: {}",
+
+			ZEN_CONSOLE("GetBuild took {}. Name: '{}', Payload size: {}",
 						NiceTimeSpanMs(GetBuildTimer.GetElapsedTimeMs()),
+						BuildObject["BuildName"sv].AsString(),
 						NiceBytes(BuildObject.GetSize()));
 
+			ZEN_DEBUG("Build object: {}", BuildObject);
+
 			CbObjectView PartsObject = BuildObject["parts"sv].AsObjectView();
 			if (!PartsObject)
 			{
@@ -5782,11 +5787,13 @@ namespace {
 	{
 		ZEN_TRACE_CPU("GetRemoteContent");
 
-		Stopwatch GetBuildPartTimer;
-		CbObject  BuildPartManifest = Storage.GetBuildPart(BuildId, BuildParts[0].first);
+		Stopwatch			   GetBuildPartTimer;
+		const Oid			   BuildPartId		 = BuildParts[0].first;
+		const std::string_view BuildPartName	 = BuildParts[0].second;
+		CbObject			   BuildPartManifest = Storage.GetBuildPart(BuildId, BuildPartId);
 		ZEN_CONSOLE("GetBuildPart {} ('{}') took {}. Payload size: {}",
-					BuildParts[0].first,
-					BuildParts[0].second,
+					BuildPartId,
+					BuildPartName,
 					NiceTimeSpanMs(GetBuildPartTimer.GetElapsedTimeMs()),
 					NiceBytes(BuildPartManifest.GetSize()));
 
@@ -5915,7 +5922,7 @@ namespace {
 		OutPartContents.resize(1);
 		ParseBuildPartManifest(Storage,
 							   BuildId,
-							   BuildParts[0].first,
+							   BuildPartId,
 							   BuildPartManifest,
 							   OutPartContents[0],
 							   OutBlockDescriptions,
diff --git a/src/zen/zen.cpp b/src/zen/zen.cpp
index 713a0d66d..4e6161e86 100644
--- a/src/zen/zen.cpp
+++ b/src/zen/zen.cpp
@@ -33,6 +33,7 @@
 #include <zencore/string.h>
 #include <zencore/trace.h>
 #include <zenhttp/httpcommon.h>
+#include <zenutil/logging.h>
 #include <zenutil/zenserverprocess.h>
 
 #include <zencore/memory/fmalloc.h>
@@ -377,31 +378,6 @@ main(int argc, char** argv)
 	using namespace zen;
 	using namespace std::literals;
 
-	zen::logging::InitializeLogging();
-
-	// Set output mode to handle virtual terminal sequences
-	zen::logging::EnableVTMode();
-	std::set_terminate([]() {
-		void*			 Frames[8];
-		uint32_t		 FrameCount = GetCallstack(2, 8, Frames);
-		CallstackFrames* Callstack	= CreateCallstack(FrameCount, Frames);
-		ZEN_CRITICAL("Program exited abnormally via std::terminate()\n{}", CallstackToString(Callstack, "  "));
-		FreeCallstack(Callstack);
-	});
-
-	LoggerRef DefaultLogger = zen::logging::Default();
-	auto&	  Sinks			= DefaultLogger.SpdLogger->sinks();
-
-	Sinks.clear();
-	auto ConsoleSink = std::make_shared<spdlog::sinks::ansicolor_stdout_sink_mt>();
-	Sinks.push_back(ConsoleSink);
-
-	zen::MaximizeOpenFileCount();
-
-	//////////////////////////////////////////////////////////////////////////
-
-	auto _ = zen::MakeGuard([] { spdlog::shutdown(); });
-
 	AttachCommand			 AttachCmd;
 	BenchCommand			 BenchCmd;
 	BuildsCommand			 BuildsCmd;
@@ -674,14 +650,25 @@ main(int argc, char** argv)
 			exit(0);
 		}
 
-		if (GlobalOptions.IsDebug)
-		{
-			logging::SetLogLevel(logging::level::Debug);
-		}
-		if (GlobalOptions.IsVerbose)
-		{
-			logging::SetLogLevel(logging::level::Trace);
-		}
+		zen::LoggingOptions LogOptions;
+		LogOptions.IsDebug	  = GlobalOptions.IsDebug;
+		LogOptions.IsVerbose  = GlobalOptions.IsVerbose;
+		LogOptions.AllowAsync = false;
+		zen::InitializeLogging(LogOptions);
+
+		std::set_terminate([]() {
+			void*			 Frames[8];
+			uint32_t		 FrameCount = GetCallstack(2, 8, Frames);
+			CallstackFrames* Callstack	= CreateCallstack(FrameCount, Frames);
+			ZEN_CRITICAL("Program exited abnormally via std::terminate()\n{}", CallstackToString(Callstack, "  "));
+			FreeCallstack(Callstack);
+		});
+
+		zen::MaximizeOpenFileCount();
+
+		//////////////////////////////////////////////////////////////////////////
+
+		auto _ = zen::MakeGuard([] { zen::ShutdownLogging(); });
 
 #if ZEN_WITH_TRACE
 		if (TraceHost.size())
diff --git a/src/zencore/include/zencore/compactbinaryfmt.h b/src/zencore/include/zencore/compactbinaryfmt.h
new file mode 100644
index 000000000..ae0c3eb42
--- /dev/null
+++ b/src/zencore/include/zencore/compactbinaryfmt.h
@@ -0,0 +1,23 @@
+// Copyright Epic Games, Inc. All Rights Reserved.
+
+#pragma once
+
+#include <zencore/compactbinary.h>
+
+ZEN_THIRD_PARTY_INCLUDES_START
+#include <fmt/format.h>
+ZEN_THIRD_PARTY_INCLUDES_END
+
+#include <string_view>
+
+template<typename T>
+requires DerivedFrom<T, zen::CbObjectView>
+struct fmt::formatter<T> : fmt::formatter<std::string_view>
+{
+	auto format(const zen::CbObject& a, format_context& ctx) const
+	{
+		zen::ExtendableStringBuilder<1024> ObjStr;
+		zen::CompactBinaryToJson(a, ObjStr);
+		return fmt::formatter<std::string_view>::format(ObjStr.ToView(), ctx);
+	}
+};
diff --git a/src/zenhttp/include/zenhttp/formatters.h b/src/zenhttp/include/zenhttp/formatters.h
index 0fa5dc6da..74da9ab05 100644
--- a/src/zenhttp/include/zenhttp/formatters.h
+++ b/src/zenhttp/include/zenhttp/formatters.h
@@ -7,6 +7,7 @@
 #include <zencore/iobuffer.h>
 #include <zencore/string.h>
 #include <zenhttp/httpclient.h>
+#include <zenhttp/httpcommon.h>
 
 ZEN_THIRD_PARTY_INCLUDES_START
 #include <cpr/cpr.h>
@@ -67,15 +68,17 @@ struct fmt::formatter<cpr::Response>
 	{
 		using namespace std::literals;
 
-		if (Response.status_code == 200 || Response.status_code == 201)
+		zen::NiceTimeSpanMs NiceResponseTime(uint64_t(Response.elapsed * 1000));
+
+		if (zen::IsHttpSuccessCode(Response.status_code))
 		{
 			return fmt::format_to(Ctx.out(),
-								  "Url: {}, Status: {}, Bytes: {}/{} (Up/Down), Elapsed: {}s",
+								  "Url: {}, Status: {}, Bytes: {}/{} (Up/Down), Elapsed: {}",
 								  Response.url.str(),
 								  Response.status_code,
 								  Response.uploaded_bytes,
 								  Response.downloaded_bytes,
-								  Response.elapsed);
+								  NiceResponseTime.c_str());
 		}
 		else
 		{
@@ -90,12 +93,12 @@ struct fmt::formatter<cpr::Response>
 				std::string_view				  Json = Obj.ToJson(Sb).ToView();
 
 				return fmt::format_to(Ctx.out(),
-									  "Url: {}, Status: {}, Bytes: {}/{} (Up/Down), Elapsed: {}s, Response: '{}', Reason: '{}'",
+									  "Url: {}, Status: {}, Bytes: {}/{} (Up/Down), Elapsed: {}, Response: '{}', Reason: '{}'",
 									  Response.url.str(),
 									  Response.status_code,
 									  Response.uploaded_bytes,
 									  Response.downloaded_bytes,
-									  Response.elapsed,
+									  NiceResponseTime.c_str(),
 									  Json,
 									  Response.reason);
 			}
@@ -104,12 +107,12 @@ struct fmt::formatter<cpr::Response>
 				zen::BodyLogFormatter Body(Response.text);
 
 				return fmt::format_to(Ctx.out(),
-									  "Url: {}, Status: {}, Bytes: {}/{} (Up/Down), Elapsed: {}s, Reponse: '{}', Reason: '{}'",
+									  "Url: {}, Status: {}, Bytes: {}/{} (Up/Down), Elapsed: {}, Response: '{}', Reason: '{}'",
 									  Response.url.str(),
 									  Response.status_code,
 									  Response.uploaded_bytes,
 									  Response.downloaded_bytes,
-									  Response.elapsed,
+									  NiceResponseTime.c_str(),
 									  Body.GetText(),
 									  Response.reason);
 			}
diff --git a/src/zenutil/include/zenutil/chunkingcontroller.h b/src/zenutil/include/zenutil/chunkingcontroller.h
index ebc80e207..246f4498a 100644
--- a/src/zenutil/include/zenutil/chunkingcontroller.h
+++ b/src/zenutil/include/zenutil/chunkingcontroller.h
@@ -11,7 +11,7 @@
 
 namespace zen {
 
-const std::vector<std::string_view> DefaultChunkingExcludeExtensions = {".exe", ".dll", ".pdb", ".self"};
+const std::vector<std::string_view> DefaultChunkingExcludeExtensions = {".exe", ".dll", ".pdb", ".self", ".mp4"};
 
 const ChunkedParams DefaultChunkedParams = {.MinSize = ((8u * 1u) * 1024u) - 128u,
 											.MaxSize = 128u * 1024u,
diff --git a/src/zenutil/include/zenutil/logging.h b/src/zenutil/include/zenutil/logging.h
index ebf6372fc..d64eef207 100644
--- a/src/zenutil/include/zenutil/logging.h
+++ b/src/zenutil/include/zenutil/logging.h
@@ -32,6 +32,7 @@ struct LoggingOptions
 	bool				  IsDebug		  = false;
 	bool				  IsVerbose		  = false;
 	bool				  IsTest		  = false;
+	bool				  AllowAsync	  = true;
 	bool				  NoConsoleOutput = false;
 	std::filesystem::path AbsLogFile;  // Absolute path to main log file
 	std::string			  LogId;
diff --git a/src/zenutil/logging.cpp b/src/zenutil/logging.cpp
index 0444fa2c4..762b75a59 100644
--- a/src/zenutil/logging.cpp
+++ b/src/zenutil/logging.cpp
@@ -49,7 +49,7 @@ BeginInitializeLogging(const LoggingOptions& LogOptions)
 	zen::logging::InitializeLogging();
 	zen::logging::EnableVTMode();
 
-	bool IsAsync = true;
+	bool IsAsync = LogOptions.AllowAsync;
 
 	if (LogOptions.IsDebug)
 	{
@@ -181,7 +181,7 @@ FinishInitializeLogging(const LoggingOptions& LogOptions)
 		LogLevel = logging::level::Debug;
 	}
 
-	if (LogOptions.IsTest)
+	if (LogOptions.IsTest || LogOptions.IsVerbose)
 	{
 		LogLevel = logging::level::Trace;
 	}
@@ -194,18 +194,21 @@ FinishInitializeLogging(const LoggingOptions& LogOptions)
 	spdlog::set_formatter(
 		std::make_unique<logging::full_formatter>(LogOptions.LogId, std::chrono::system_clock::now()));	 // default to duration prefix
 
-	if (LogOptions.AbsLogFile.extension() == ".json")
-	{
-		g_FileSink->set_formatter(std::make_unique<logging::json_formatter>(LogOptions.LogId));
-	}
-	else
+	if (g_FileSink)
 	{
-		g_FileSink->set_formatter(std::make_unique<logging::full_formatter>(LogOptions.LogId));	 // this will have a date prefix
-	}
+		if (LogOptions.AbsLogFile.extension() == ".json")
+		{
+			g_FileSink->set_formatter(std::make_unique<logging::json_formatter>(LogOptions.LogId));
+		}
+		else
+		{
+			g_FileSink->set_formatter(std::make_unique<logging::full_formatter>(LogOptions.LogId));	 // this will have a date prefix
+		}
 
-	const std::string StartLogTime = zen::DateTime::Now().ToIso8601();
+		const std::string StartLogTime = zen::DateTime::Now().ToIso8601();
 
-	spdlog::apply_all([&](auto Logger) { Logger->info("log starting at {}", StartLogTime); });
+		spdlog::apply_all([&](auto Logger) { Logger->info("log starting at {}", StartLogTime); });
+	}
 
 	g_IsLoggingInitialized = true;
 }
@@ -213,7 +216,7 @@ FinishInitializeLogging(const LoggingOptions& LogOptions)
 void
 ShutdownLogging()
 {
-	if (g_IsLoggingInitialized)
+	if (g_IsLoggingInitialized && g_FileSink)
 	{
 		auto DefaultLogger = zen::logging::Default();
 		ZEN_LOG_INFO(DefaultLogger, "log ending at {}", zen::DateTime::Now().ToIso8601());