cache log sessionid (#297)

* implemented structured cache logging to be used as audit trail to help analyse potential cache pollution/corruption
* added common header to all known log targets
* made Oid::operator bool explicit to avoid logging/text format mishaps
* HttpClient::operator bool -> explicit
* changed cache logs to not rotate on start in order to retain more history
* added CacheRequestContext
* properly initialize request context
* log session id and request id on zencacehstore get/put
* changelog

1 files changed, 78 insertions, 50 deletions

diff --git a/src/zenserver/cache/structuredcachestore.cpp b/src/zenserver/cache/structuredcachestore.cpp
index bc4248a8a..1847c724d 100644
--- a/src/zenserver/cache/structuredcachestore.cpp
+++ b/src/zenserver/cache/structuredcachestore.cpp
@@ -16,6 +16,7 @@
 #include <zencore/timer.h>
 #include <zencore/trace.h>
 #include <zenstore/scrubcontext.h>
+#include <zenutil/cache/cache.h>
 
 #include <future>
 #include <limits>
@@ -218,7 +219,10 @@ ZEN_DEFINE_LOG_CATEGORY_STATIC(LogCacheActivity, "z$");
 
 static constinit std::string_view UE4DDCNamespaceName = "ue4.ddc";
 
-ZenCacheStore::ZenCacheStore(GcManager& Gc, const Configuration& Configuration) : m_Gc(Gc), m_Configuration(Configuration)
+ZenCacheStore::ZenCacheStore(GcManager& Gc, const Configuration& Configuration)
+: m_Log(logging::Get("z$"))
+, m_Gc(Gc)
+, m_Configuration(Configuration)
 {
 	CreateDirectories(m_Configuration.BasePath);
 
@@ -263,7 +267,11 @@ ZenCacheStore::~ZenCacheStore()
 }
 
 bool
-ZenCacheStore::Get(std::string_view Namespace, std::string_view Bucket, const IoHash& HashKey, ZenCacheValue& OutValue)
+ZenCacheStore::Get(const CacheRequestContext& Context,
+				   std::string_view			  Namespace,
+				   std::string_view			  Bucket,
+				   const IoHash&			  HashKey,
+				   ZenCacheValue&			  OutValue)
 {
 	if (ZenCacheNamespace* Store = GetNamespace(Namespace); Store)
 	{
@@ -279,7 +287,8 @@ ZenCacheStore::Get(std::string_view Namespace, std::string_view Bucket, const Io
 					const size_t ObjectSize = OutValue.Value.GetSize();
 
 					ZEN_LOG_INFO(LogCacheActivity,
-								 "GET HIT  {}/{}/{} -> {} {} {}",
+								 "GET HIT  [{}] {}/{}/{} -> {} {} {}",
+								 Context,
 								 Namespace,
 								 Bucket,
 								 HashKey,
@@ -290,7 +299,8 @@ ZenCacheStore::Get(std::string_view Namespace, std::string_view Bucket, const Io
 				else
 				{
 					ZEN_LOG_INFO(LogCacheActivity,
-								 "GET HIT  {}/{}/{} -> {} {} {}",
+								 "GET HIT  [{}] {}/{}/{} -> {} {} {}",
+								 Context,
 								 Namespace,
 								 Bucket,
 								 HashKey,
@@ -301,19 +311,27 @@ ZenCacheStore::Get(std::string_view Namespace, std::string_view Bucket, const Io
 			}
 			else
 			{
-				ZEN_LOG_INFO(LogCacheActivity, "GET MISS {}/{}/{}", Namespace, Bucket, HashKey);
+				ZEN_LOG_INFO(LogCacheActivity, "GET MISS [{}] {}/{}/{}", Context, Namespace, Bucket, HashKey);
 			}
 		}
 
 		return Result;
 	}
-	ZEN_WARN("request for unknown namespace '{}' in ZenCacheStore::Get, bucket '{}', key '{}'", Namespace, Bucket, HashKey.ToHexString());
+	ZEN_WARN("request for unknown namespace '{}' in ZenCacheStore::Get [{}], bucket '{}', key '{}'",
+			 Context,
+			 Namespace,
+			 Bucket,
+			 HashKey.ToHexString());
 
 	return false;
 }
 
 void
-ZenCacheStore::Put(std::string_view Namespace, std::string_view Bucket, const IoHash& HashKey, const ZenCacheValue& Value)
+ZenCacheStore::Put(const CacheRequestContext& Context,
+				   std::string_view			  Namespace,
+				   std::string_view			  Bucket,
+				   const IoHash&			  HashKey,
+				   const ZenCacheValue&		  Value)
 {
 	if (m_Configuration.EnableWriteLog)
 	{
@@ -323,7 +341,8 @@ ZenCacheStore::Put(std::string_view Namespace, std::string_view Bucket, const Io
 			const size_t ObjectSize = Value.Value.GetSize();
 
 			ZEN_LOG_INFO(LogCacheActivity,
-						 "PUT      {}/{}/{} -> {} {} {}",
+						 "PUT      [{}] {}/{}/{} -> {} {} {}",
+						 Context,
 						 Namespace,
 						 Bucket,
 						 HashKey,
@@ -334,7 +353,8 @@ ZenCacheStore::Put(std::string_view Namespace, std::string_view Bucket, const Io
 		else
 		{
 			ZEN_LOG_INFO(LogCacheActivity,
-						 "PUT      {}/{}/{} -> {} {} {}",
+						 "PUT      [{}] {}/{}/{} -> {} {} {}",
+						 Context,
 						 Namespace,
 						 Bucket,
 						 HashKey,
@@ -348,7 +368,11 @@ ZenCacheStore::Put(std::string_view Namespace, std::string_view Bucket, const Io
 	{
 		return Store->Put(Bucket, HashKey, Value);
 	}
-	ZEN_WARN("request for unknown namespace '{}' in ZenCacheStore::Put, bucket '{}', key '{}'", Namespace, Bucket, HashKey.ToHexString());
+	ZEN_WARN("request for unknown namespace '{}' in ZenCacheStore::Put [{}] bucket '{}', key '{}'",
+			 Context,
+			 Namespace,
+			 Bucket,
+			 HashKey.ToHexString());
 }
 
 bool
@@ -1128,8 +1152,9 @@ TEST_CASE("z$.namespaces")
 	ScopedTemporaryDirectory TempDir;
 	CreateDirectories(TempDir.Path());
 
-	IoHash Key1;
-	IoHash Key2;
+	const CacheRequestContext Context;
+	IoHash					  Key1;
+	IoHash					  Key2;
 	{
 		GcManager	  Gc;
 		ZenCacheStore Zcs(Gc, {.BasePath = TempDir.Path() / "cache", .AllowAutomaticCreationOfNamespaces = false});
@@ -1144,15 +1169,15 @@ TEST_CASE("z$.namespaces")
 		Buffer.SetContentType(ZenContentType::kCbObject);
 
 		ZenCacheValue PutValue = {.Value = Buffer};
-		Zcs.Put(ZenCacheStore::DefaultNamespace, Bucket, Key1, PutValue);
+		Zcs.Put(Context, ZenCacheStore::DefaultNamespace, Bucket, Key1, PutValue);
 
 		ZenCacheValue GetValue;
-		CHECK(Zcs.Get(ZenCacheStore::DefaultNamespace, Bucket, Key1, GetValue));
-		CHECK(!Zcs.Get(CustomNamespace, Bucket, Key1, GetValue));
+		CHECK(Zcs.Get(Context, ZenCacheStore::DefaultNamespace, Bucket, Key1, GetValue));
+		CHECK(!Zcs.Get(Context, CustomNamespace, Bucket, Key1, GetValue));
 
 		// This should just be dropped as we don't allow creating of namespaces on the fly
-		Zcs.Put(CustomNamespace, Bucket, Key1, PutValue);
-		CHECK(!Zcs.Get(CustomNamespace, Bucket, Key1, GetValue));
+		Zcs.Put(Context, CustomNamespace, Bucket, Key1, PutValue);
+		CHECK(!Zcs.Get(Context, CustomNamespace, Bucket, Key1, GetValue));
 	}
 
 	{
@@ -1167,13 +1192,13 @@ TEST_CASE("z$.namespaces")
 		IoBuffer Buffer2 = CacheValue2.GetBuffer().AsIoBuffer();
 		Buffer2.SetContentType(ZenContentType::kCbObject);
 		ZenCacheValue PutValue2 = {.Value = Buffer2};
-		Zcs.Put(CustomNamespace, Bucket, Key2, PutValue2);
+		Zcs.Put(Context, CustomNamespace, Bucket, Key2, PutValue2);
 
 		ZenCacheValue GetValue;
-		CHECK(!Zcs.Get(ZenCacheStore::DefaultNamespace, Bucket, Key2, GetValue));
-		CHECK(Zcs.Get(ZenCacheStore::DefaultNamespace, Bucket, Key1, GetValue));
-		CHECK(!Zcs.Get(CustomNamespace, Bucket, Key1, GetValue));
-		CHECK(Zcs.Get(CustomNamespace, Bucket, Key2, GetValue));
+		CHECK(!Zcs.Get(Context, ZenCacheStore::DefaultNamespace, Bucket, Key2, GetValue));
+		CHECK(Zcs.Get(Context, ZenCacheStore::DefaultNamespace, Bucket, Key1, GetValue));
+		CHECK(!Zcs.Get(Context, CustomNamespace, Bucket, Key1, GetValue));
+		CHECK(Zcs.Get(Context, CustomNamespace, Bucket, Key2, GetValue));
 	}
 }
 
@@ -1193,25 +1218,26 @@ TEST_CASE("z$.drop.bucket")
 	ScopedTemporaryDirectory TempDir;
 	CreateDirectories(TempDir.Path());
 
-	IoHash Key1;
-	IoHash Key2;
+	const CacheRequestContext Context;
+	IoHash					  Key1;
+	IoHash					  Key2;
 
-	auto PutValue =
-		[&CreateCacheValue](ZenCacheStore& Zcs, std::string_view Namespace, std::string_view Bucket, size_t KeyIndex, size_t Size) {
-			// Create a cache record
-			IoHash	 Key		= CreateKey(KeyIndex);
-			CbObject CacheValue = CreateCacheValue(Size);
+	auto PutValue = [&CreateCacheValue,
+					 &Context](ZenCacheStore& Zcs, std::string_view Namespace, std::string_view Bucket, size_t KeyIndex, size_t Size) {
+		// Create a cache record
+		IoHash	 Key		= CreateKey(KeyIndex);
+		CbObject CacheValue = CreateCacheValue(Size);
 
-			IoBuffer Buffer = CacheValue.GetBuffer().AsIoBuffer();
-			Buffer.SetContentType(ZenContentType::kCbObject);
+		IoBuffer Buffer = CacheValue.GetBuffer().AsIoBuffer();
+		Buffer.SetContentType(ZenContentType::kCbObject);
 
-			ZenCacheValue PutValue = {.Value = Buffer};
-			Zcs.Put(Namespace, Bucket, Key, PutValue);
-			return Key;
-		};
-	auto GetValue = [](ZenCacheStore& Zcs, std::string_view Namespace, std::string_view Bucket, const IoHash& Key) {
+		ZenCacheValue PutValue = {.Value = Buffer};
+		Zcs.Put(Context, Namespace, Bucket, Key, PutValue);
+		return Key;
+	};
+	auto GetValue = [&Context](ZenCacheStore& Zcs, std::string_view Namespace, std::string_view Bucket, const IoHash& Key) {
 		ZenCacheValue GetValue;
-		Zcs.Get(Namespace, Bucket, Key, GetValue);
+		Zcs.Get(Context, Namespace, Bucket, Key, GetValue);
 		return GetValue;
 	};
 	WorkerThreadPool Workers(1);
@@ -1253,6 +1279,8 @@ TEST_CASE("z$.drop.namespace")
 {
 	using namespace testutils;
 
+	const CacheRequestContext Context;
+
 	const auto CreateCacheValue = [](size_t Size) -> CbObject {
 		std::vector<uint8_t> Buf;
 		Buf.resize(Size);
@@ -1265,22 +1293,22 @@ TEST_CASE("z$.drop.namespace")
 	ScopedTemporaryDirectory TempDir;
 	CreateDirectories(TempDir.Path());
 
-	auto PutValue =
-		[&CreateCacheValue](ZenCacheStore& Zcs, std::string_view Namespace, std::string_view Bucket, size_t KeyIndex, size_t Size) {
-			// Create a cache record
-			IoHash	 Key		= CreateKey(KeyIndex);
-			CbObject CacheValue = CreateCacheValue(Size);
+	auto PutValue = [&CreateCacheValue,
+					 &Context](ZenCacheStore& Zcs, std::string_view Namespace, std::string_view Bucket, size_t KeyIndex, size_t Size) {
+		// Create a cache record
+		IoHash	 Key		= CreateKey(KeyIndex);
+		CbObject CacheValue = CreateCacheValue(Size);
 
-			IoBuffer Buffer = CacheValue.GetBuffer().AsIoBuffer();
-			Buffer.SetContentType(ZenContentType::kCbObject);
+		IoBuffer Buffer = CacheValue.GetBuffer().AsIoBuffer();
+		Buffer.SetContentType(ZenContentType::kCbObject);
 
-			ZenCacheValue PutValue = {.Value = Buffer};
-			Zcs.Put(Namespace, Bucket, Key, PutValue);
-			return Key;
-		};
-	auto GetValue = [](ZenCacheStore& Zcs, std::string_view Namespace, std::string_view Bucket, const IoHash& Key) {
+		ZenCacheValue PutValue = {.Value = Buffer};
+		Zcs.Put(Context, Namespace, Bucket, Key, PutValue);
+		return Key;
+	};
+	auto GetValue = [&Context](ZenCacheStore& Zcs, std::string_view Namespace, std::string_view Bucket, const IoHash& Key) {
 		ZenCacheValue GetValue;
-		Zcs.Get(Namespace, Bucket, Key, GetValue);
+		Zcs.Get(Context, Namespace, Bucket, Key, GetValue);
 		return GetValue;
 	};
 	WorkerThreadPool Workers(1);