logging

apps/RenderCadenceCompositor/README.md

@@ -44,6 +44,7 @@ Included now:
 - render-thread-only GL commit once the artifact is ready
 - manifest-driven stateless single-pass shader packages
 - default float, vec2, color, boolean, enum, and trigger parameters
+- background logging with `log`, `warning`, and `error` levels
 - compact telemetry
 - non-GL frame-exchange tests
 
@@ -100,6 +101,10 @@ Use `--no-shader` to keep the simple motion fallback only.
 
 ## Expected Telemetry
 
+Startup, shutdown, shader-build, and render-thread event messages are written through the app logger. Telemetry is intentionally separate and remains a compact once-per-second cadence line.
+
+The logger writes to the console, `OutputDebugStringA`, and `logs/render-cadence-compositor.log` by default. Render-thread log calls use the non-blocking path so diagnostics do not become cadence blockers.
+
 The app prints one line per second:
 
 ```text

apps/RenderCadenceCompositor/RenderCadenceCompositor.cpp

@@ -1,12 +1,14 @@
 #include "app/AppConfig.h"
 #include "app/RenderCadenceApp.h"
 #include "frames/SystemFrameExchange.h"
+#include "logging/Logger.h"
 #include "render/RenderThread.h"
 #include "VideoIOFormat.h"
 
 #include <windows.h>
 
 #include <iostream>
+#include <sstream>
 #include <string>
 
 namespace
@@ -38,17 +40,22 @@ private:
 
 int main(int argc, char** argv)
 {
+	RenderCadenceCompositor::AppConfig appConfig = RenderCadenceCompositor::DefaultAppConfig();
+	RenderCadenceCompositor::Logger::Instance().Start(appConfig.logging);
+	RenderCadenceCompositor::Log(
+		"app",
+		"RenderCadenceCompositor starting. Starts render cadence, system-memory exchange, DeckLink scheduled output, and telemetry. Press Enter to stop.");
+
 	ComInitGuard com;
 	if (!com.Initialize())
 	{
-		std::cerr << "COM initialization failed: 0x" << std::hex << com.Result() << std::dec << "\n";
+		std::ostringstream message;
+		message << "COM initialization failed: 0x" << std::hex << com.Result();
+		RenderCadenceCompositor::LogError("app", message.str());
+		RenderCadenceCompositor::Logger::Instance().Stop();
 		return 1;
 	}
 
-	std::cout << "RenderCadenceCompositor\n"
-		<< "  Starts render cadence, system-memory exchange, DeckLink scheduled output, and telemetry.\n"
-		<< "  Press Enter to stop.\n";
-
 	SystemFrameExchangeConfig frameExchangeConfig;
 	frameExchangeConfig.width = 1920;
 	frameExchangeConfig.height = 1080;
@@ -66,7 +73,6 @@ int main(int argc, char** argv)
 
 	RenderThread renderThread(frameExchange, renderConfig);
 
-	RenderCadenceCompositor::AppConfig appConfig = RenderCadenceCompositor::DefaultAppConfig();
 	for (int index = 1; index < argc; ++index)
 	{
 		const std::string argument = argv[index];
@@ -87,12 +93,15 @@ int main(int argc, char** argv)
 	std::string error;
 	if (!app.Start(error))
 	{
-		std::cerr << "RenderCadenceCompositor start failed: " << error << "\n";
+		RenderCadenceCompositor::LogError("app", "RenderCadenceCompositor start failed: " + error);
+		RenderCadenceCompositor::Logger::Instance().Stop();
 		return 1;
 	}
 
 	std::string line;
 	std::getline(std::cin, line);
 	app.Stop();
+	RenderCadenceCompositor::Log("app", "RenderCadenceCompositor stopped.");
+	RenderCadenceCompositor::Logger::Instance().Stop();
 	return 0;
 }

apps/RenderCadenceCompositor/app/AppConfig.cpp

@@ -9,6 +9,12 @@ AppConfig DefaultAppConfig()
 	config.deckLink.outputAlphaRequired = false;
 	config.outputThread.targetBufferedFrames = 4;
 	config.telemetry.interval = std::chrono::seconds(1);
+	config.logging.minimumLevel = LogLevel::Log;
+	config.logging.writeToConsole = true;
+	config.logging.writeToDebugOutput = true;
+	config.logging.writeToFile = true;
+	config.logging.filePath = "logs/render-cadence-compositor.log";
+	config.logging.maxQueuedMessages = 1024;
 	config.warmupCompletedFrames = 4;
 	config.warmupTimeout = std::chrono::seconds(3);
 	config.prerollTimeout = std::chrono::seconds(3);

apps/RenderCadenceCompositor/app/AppConfig.h

@@ -1,5 +1,6 @@
 #pragma once
 
+#include "../logging/Logger.h"
 #include "../telemetry/TelemetryPrinter.h"
 #include "../video/DeckLinkOutput.h"
 #include "../video/DeckLinkOutputThread.h"
@@ -15,6 +16,7 @@ struct AppConfig
 	DeckLinkOutputConfig deckLink;
 	DeckLinkOutputThreadConfig outputThread;
 	TelemetryPrinterConfig telemetry;
+	LoggerConfig logging;
 	std::size_t warmupCompletedFrames = 4;
 	std::chrono::milliseconds warmupTimeout = std::chrono::seconds(3);
 	std::chrono::milliseconds prerollTimeout = std::chrono::seconds(3);

apps/RenderCadenceCompositor/app/RenderCadenceApp.h

@@ -1,13 +1,13 @@
 #pragma once
 
 #include "AppConfig.h"
+#include "../logging/Logger.h"
 #include "../runtime/RuntimeShaderBridge.h"
 #include "../telemetry/TelemetryPrinter.h"
 #include "../video/DeckLinkOutput.h"
 #include "../video/DeckLinkOutputThread.h"
 
 #include <chrono>
-#include <iostream>
 #include <string>
 #include <thread>
 #include <type_traits>
@@ -65,6 +65,7 @@ public:
 
 	bool Start(std::string& error)
 	{
+		Log("app", "Initializing DeckLink output.");
 		if (!mOutput.Initialize(
 			mConfig.deckLink,
 			[this](const VideoIOCompletion& completion) {
@@ -72,44 +73,56 @@ public:
 			},
 			error))
 		{
+			LogError("app", "DeckLink output initialization failed: " + error);
 			return false;
 		}
 
+		Log("app", "Starting render thread.");
 		if (!detail::StartRenderThread(mRenderThread, error, 0))
 		{
+			LogError("app", "Render thread start failed: " + error);
 			Stop();
 			return false;
 		}
 		StartRuntimeShaderBuild();
 
+		Log("app", "Waiting for rendered warmup frames.");
 		if (!mFrameExchange.WaitForCompletedDepth(mConfig.warmupCompletedFrames, mConfig.warmupTimeout))
 		{
 			error = "Timed out waiting for rendered warmup frames.";
+			LogError("app", error);
 			Stop();
 			return false;
 		}
 
+		Log("app", "Starting DeckLink output thread.");
 		if (!mOutputThread.Start())
 		{
 			error = "DeckLink output thread failed to start.";
+			LogError("app", error);
 			Stop();
 			return false;
 		}
 
+		Log("app", "Waiting for DeckLink preroll frames.");
 		if (!WaitForPreroll())
 		{
 			error = "Timed out waiting for DeckLink preroll frames.";
+			LogError("app", error);
 			Stop();
 			return false;
 		}
 
+		Log("app", "Starting DeckLink scheduled playback.");
 		if (!mOutput.StartScheduledPlayback(error))
 		{
+			LogError("app", "DeckLink scheduled playback failed: " + error);
 			Stop();
 			return false;
 		}
 
 		mTelemetry.Start(mFrameExchange, mOutput, mOutputThread, mRenderThread);
+		Log("app", "RenderCadenceCompositor started.");
 		mStarted = true;
 		return true;
 	}
@@ -122,6 +135,8 @@ public:
 		StopRuntimeShaderBuild();
 		mRenderThread.Stop();
 		mOutput.ReleaseResources();
+		if (mStarted)
+			Log("app", "RenderCadenceCompositor shutdown complete.");
 		mStarted = false;
 	}
 
@@ -143,13 +158,20 @@ private:
 
 	void StartRuntimeShaderBuild()
 	{
+		if (mConfig.runtimeShaderId.empty())
+		{
+			Log("runtime-shader", "Runtime shader build disabled.");
+			return;
+		}
+
+		Log("runtime-shader", "Starting background Slang build for shader '" + mConfig.runtimeShaderId + "'.");
 		mShaderBridge.Start(
 			mConfig.runtimeShaderId,
 			[this](const RuntimeShaderArtifact& artifact) {
 				mRenderThread.SubmitRuntimeShaderArtifact(artifact);
 			},
 			[](const std::string& message) {
-				std::cout << "Runtime Slang build failed: " << message << "\n";
+				LogError("runtime-shader", "Runtime Slang build failed: " + message);
 			});
 	}
 

apps/RenderCadenceCompositor/logging/Logger.cpp

@@ -0,0 +1,283 @@
+#include "Logger.h"
+
+#include <windows.h>
+
+#include <iomanip>
+#include <iostream>
+#include <sstream>
+#include <ctime>
+#include <filesystem>
+
+namespace RenderCadenceCompositor
+{
+namespace
+{
+int Rank(LogLevel level)
+{
+	switch (level)
+	{
+	case LogLevel::Log:
+		return 0;
+	case LogLevel::Warning:
+		return 1;
+	case LogLevel::Error:
+		return 2;
+	default:
+		return 0;
+	}
+}
+
+std::string FormatTimestamp(std::chrono::system_clock::time_point timestamp)
+{
+	const std::time_t time = std::chrono::system_clock::to_time_t(timestamp);
+	std::tm localTime = {};
+	localtime_s(&localTime, &time);
+
+	std::ostringstream stream;
+	stream << std::put_time(&localTime, "%Y-%m-%d %H:%M:%S");
+	return stream.str();
+}
+
+std::string FormatRecord(const Logger::Record& record)
+{
+	std::ostringstream stream;
+	stream << FormatTimestamp(record.timestamp)
+		<< " [" << LogLevelName(record.level) << "]"
+		<< " [" << record.subsystem << "] "
+		<< record.message;
+	return stream.str();
+}
+}
+
+const char* LogLevelName(LogLevel level)
+{
+	switch (level)
+	{
+	case LogLevel::Log:
+		return "log";
+	case LogLevel::Warning:
+		return "warning";
+	case LogLevel::Error:
+		return "error";
+	default:
+		return "log";
+	}
+}
+
+Logger& Logger::Instance()
+{
+	static Logger logger;
+	return logger;
+}
+
+Logger::~Logger()
+{
+	Stop();
+}
+
+void Logger::Start(LoggerConfig config)
+{
+	std::lock_guard<std::mutex> lock(mMutex);
+	if (mRunning)
+		return;
+
+	mConfig = config;
+	mStopping = false;
+	mRunning = true;
+	OpenFileSink();
+	{
+		std::lock_guard<std::mutex> countersLock(mCountersMutex);
+		mCounters = LoggerCounters();
+	}
+	mThread = std::thread([this]() { ThreadMain(); });
+}
+
+void Logger::Stop()
+{
+	{
+		std::lock_guard<std::mutex> lock(mMutex);
+		if (!mRunning && !mThread.joinable())
+			return;
+		mStopping = true;
+	}
+	mCondition.notify_all();
+
+	if (mThread.joinable())
+		mThread.join();
+
+	std::lock_guard<std::mutex> lock(mMutex);
+	CloseFileSink();
+	mRunning = false;
+}
+
+void Logger::Write(LogLevel level, const std::string& subsystem, const std::string& message)
+{
+	Enqueue(Record{ std::chrono::system_clock::now(), std::this_thread::get_id(), level, subsystem, message }, true);
+}
+
+bool Logger::TryWrite(LogLevel level, const std::string& subsystem, const std::string& message)
+{
+	return Enqueue(Record{ std::chrono::system_clock::now(), std::this_thread::get_id(), level, subsystem, message }, false);
+}
+
+void Logger::Log(const std::string& subsystem, const std::string& message)
+{
+	Write(LogLevel::Log, subsystem, message);
+}
+
+void Logger::Warning(const std::string& subsystem, const std::string& message)
+{
+	Write(LogLevel::Warning, subsystem, message);
+}
+
+void Logger::Error(const std::string& subsystem, const std::string& message)
+{
+	Write(LogLevel::Error, subsystem, message);
+}
+
+LoggerCounters Logger::Counters() const
+{
+	std::lock_guard<std::mutex> lock(mCountersMutex);
+	return mCounters;
+}
+
+bool Logger::IsRunning() const
+{
+	std::lock_guard<std::mutex> lock(mMutex);
+	return mRunning;
+}
+
+bool Logger::ShouldWrite(LogLevel level) const
+{
+	return Rank(level) >= Rank(mConfig.minimumLevel);
+}
+
+bool Logger::Enqueue(Record record, bool block)
+{
+	if (!ShouldWrite(record.level))
+		return true;
+
+	std::unique_lock<std::mutex> lock(mMutex, std::defer_lock);
+	if (block)
+	{
+		lock.lock();
+	}
+	else if (!lock.try_lock())
+	{
+		std::lock_guard<std::mutex> countersLock(mCountersMutex);
+		++mCounters.dropped;
+		return false;
+	}
+
+	if (!mRunning)
+	{
+		lock.unlock();
+		WriteRecord(record);
+		return true;
+	}
+
+	if (mQueue.size() >= mConfig.maxQueuedMessages)
+	{
+		std::lock_guard<std::mutex> countersLock(mCountersMutex);
+		++mCounters.dropped;
+		return false;
+	}
+
+	mQueue.push_back(std::move(record));
+	{
+		std::lock_guard<std::mutex> countersLock(mCountersMutex);
+		++mCounters.queued;
+	}
+	lock.unlock();
+	mCondition.notify_one();
+	return true;
+}
+
+void Logger::ThreadMain()
+{
+	for (;;)
+	{
+		Record record;
+		{
+			std::unique_lock<std::mutex> lock(mMutex);
+			mCondition.wait(lock, [this]() {
+				return mStopping || !mQueue.empty();
+			});
+
+			if (mQueue.empty())
+			{
+				if (mStopping)
+					return;
+				continue;
+			}
+
+			record = std::move(mQueue.front());
+			mQueue.pop_front();
+		}
+		WriteRecord(record);
+	}
+}
+
+void Logger::WriteRecord(const Record& record)
+{
+	const std::string line = FormatRecord(record);
+
+	if (mConfig.writeToDebugOutput)
+		OutputDebugStringA((line + "\n").c_str());
+
+	if (mConfig.writeToConsole)
+	{
+		if (record.level == LogLevel::Error)
+			std::cerr << line << "\n";
+		else
+			std::cout << line << "\n";
+	}
+	if (mFile.is_open())
+	{
+		mFile << line << "\n";
+		mFile.flush();
+	}
+
+	std::lock_guard<std::mutex> lock(mCountersMutex);
+	++mCounters.written;
+}
+
+void Logger::OpenFileSink()
+{
+	CloseFileSink();
+	if (!mConfig.writeToFile || mConfig.filePath.empty())
+		return;
+
+	std::error_code error;
+	const std::filesystem::path logPath(mConfig.filePath);
+	if (logPath.has_parent_path())
+		std::filesystem::create_directories(logPath.parent_path(), error);
+	mFile.open(logPath, std::ios::out | std::ios::app);
+}
+
+void Logger::CloseFileSink()
+{
+	if (mFile.is_open())
+		mFile.close();
+}
+
+bool TryLog(LogLevel level, const std::string& subsystem, const std::string& message)
+{
+	return Logger::Instance().TryWrite(level, subsystem, message);
+}
+
+void Log(const std::string& subsystem, const std::string& message)
+{
+	Logger::Instance().Log(subsystem, message);
+}
+
+void LogWarning(const std::string& subsystem, const std::string& message)
+{
+	Logger::Instance().Warning(subsystem, message);
+}
+
+void LogError(const std::string& subsystem, const std::string& message)
+{
+	Logger::Instance().Error(subsystem, message);
+}
+}

apps/RenderCadenceCompositor/logging/Logger.h

@@ -0,0 +1,101 @@
+#pragma once
+
+#include <atomic>
+#include <chrono>
+#include <condition_variable>
+#include <cstddef>
+#include <cstdint>
+#include <deque>
+#include <fstream>
+#include <mutex>
+#include <string>
+#include <thread>
+
+namespace RenderCadenceCompositor
+{
+enum class LogLevel
+{
+	Log,
+	Warning,
+	Error
+};
+
+struct LoggerConfig
+{
+	LogLevel minimumLevel = LogLevel::Log;
+	bool writeToConsole = true;
+	bool writeToDebugOutput = true;
+	bool writeToFile = true;
+	std::string filePath = "logs/render-cadence-compositor.log";
+	std::size_t maxQueuedMessages = 1024;
+};
+
+struct LoggerCounters
+{
+	uint64_t queued = 0;
+	uint64_t written = 0;
+	uint64_t dropped = 0;
+};
+
+const char* LogLevelName(LogLevel level);
+
+class Logger
+{
+public:
+	struct Record
+	{
+		std::chrono::system_clock::time_point timestamp;
+		std::thread::id threadId;
+		LogLevel level = LogLevel::Log;
+		std::string subsystem;
+		std::string message;
+	};
+
+	static Logger& Instance();
+
+	Logger(const Logger&) = delete;
+	Logger& operator=(const Logger&) = delete;
+
+	~Logger();
+
+	void Start(LoggerConfig config = LoggerConfig());
+	void Stop();
+
+	void Write(LogLevel level, const std::string& subsystem, const std::string& message);
+	bool TryWrite(LogLevel level, const std::string& subsystem, const std::string& message);
+
+	void Log(const std::string& subsystem, const std::string& message);
+	void Warning(const std::string& subsystem, const std::string& message);
+	void Error(const std::string& subsystem, const std::string& message);
+
+	LoggerCounters Counters() const;
+	bool IsRunning() const;
+
+private:
+	Logger() = default;
+
+	bool ShouldWrite(LogLevel level) const;
+	bool Enqueue(Record record, bool block);
+	void ThreadMain();
+	void WriteRecord(const Record& record);
+	void OpenFileSink();
+	void CloseFileSink();
+
+	LoggerConfig mConfig;
+	std::ofstream mFile;
+	std::thread mThread;
+	mutable std::mutex mMutex;
+	std::condition_variable mCondition;
+	std::deque<Record> mQueue;
+	bool mStopping = false;
+	bool mRunning = false;
+
+	mutable std::mutex mCountersMutex;
+	LoggerCounters mCounters;
+};
+
+bool TryLog(LogLevel level, const std::string& subsystem, const std::string& message);
+void Log(const std::string& subsystem, const std::string& message);
+void LogWarning(const std::string& subsystem, const std::string& message);
+void LogError(const std::string& subsystem, const std::string& message);
+}

apps/RenderCadenceCompositor/render/RenderThread.cpp

@@ -2,6 +2,7 @@
 
 #include "../frames/SystemFrameExchange.h"
 #include "../frames/SystemFrameTypes.h"
+#include "../logging/Logger.h"
 #include "../platform/HiddenGlWindow.h"
 #include "Bgra8ReadbackPipeline.h"
 #include "GLExtensions.h"
@@ -10,7 +11,6 @@
 
 #include <algorithm>
 #include <thread>
-#include <windows.h>
 
 RenderThread::RenderThread(SystemFrameExchange& frameExchange, Config config) :
 	mFrameExchange(frameExchange),
@@ -71,6 +71,7 @@ RenderThread::Metrics RenderThread::GetMetrics() const
 
 void RenderThread::ThreadMain()
 {
+	RenderCadenceCompositor::TryLog(RenderCadenceCompositor::LogLevel::Log, "render-thread", "Render thread starting.");
 	HiddenGlWindow window;
 	std::string error;
 	if (!window.Create(mConfig.width, mConfig.height, error) || !window.MakeCurrent())
@@ -156,6 +157,7 @@ void RenderThread::ThreadMain()
 	renderer.ShutdownGl();
 	window.ClearCurrent();
 	mRunning.store(false, std::memory_order_release);
+	RenderCadenceCompositor::TryLog(RenderCadenceCompositor::LogLevel::Log, "render-thread", "Render thread stopped.");
 }
 
 void RenderThread::SignalStarted()
@@ -167,6 +169,7 @@ void RenderThread::SignalStarted()
 
 void RenderThread::SignalStartupFailure(const std::string& error)
 {
+	RenderCadenceCompositor::TryLog(RenderCadenceCompositor::LogLevel::Error, "render-thread", error);
 	std::lock_guard<std::mutex> lock(mStartupMutex);
 	mStartupError = error;
 	mStartupCondition.notify_all();
@@ -221,13 +224,19 @@ void RenderThread::TryCommitReadyRuntimeShader(RuntimeShaderRenderer& runtimeSha
 	std::string commitError;
 	if (!runtimeShaderRenderer.CommitShaderArtifact(artifact, commitError))
 	{
-		OutputDebugStringA(("Runtime shader GL commit failed: " + commitError + "\n").c_str());
+		RenderCadenceCompositor::TryLog(
+			RenderCadenceCompositor::LogLevel::Error,
+			"render-thread",
+			"Runtime shader GL commit failed: " + commitError);
 		std::lock_guard<std::mutex> lock(mMetricsMutex);
 		++mMetrics.shaderBuildFailures;
 		return;
 	}
 
-	OutputDebugStringA(("Runtime shader committed: " + artifact.shaderId + ". " + artifact.message + "\n").c_str());
+	RenderCadenceCompositor::TryLog(
+		RenderCadenceCompositor::LogLevel::Log,
+		"render-thread",
+		"Runtime shader committed: " + artifact.shaderId + ". " + artifact.message);
 	std::lock_guard<std::mutex> lock(mMetricsMutex);
 	++mMetrics.shaderBuildsCommitted;
 }