Merge branch 'ajaus/additional-command-logging' into 'main'

[REMIX-2821] Add additional command logging to both the bridge server and client.

See merge request lightspeedrtx/bridge-remix-nv!74

bridge.conf

@@ -229,7 +229,6 @@
 # it can sometimes be helpful to check state values and verify that the
 # content being read matches on both the bridge client and server. By
 # toggling this setting we also send read-only calls to the server.
-# Default is false.
 #
 # Supported values: True, False
 
@@ -238,7 +237,6 @@
 # In a Debug or DebugOptimized build of the bridge, setting LogApiCalls
 # to True will write each call to a D3D9 API function through the bridge
 # client to to the the client log file ("d3d9.log").
-# Default is false.
 #
 # Supported values: True, False
 
@@ -251,22 +249,29 @@
 # the call will be logged. This includes clientside internal calls to 
 # D3D9API functions. Additionally, each nested internal call to a 
 # public D3D9 API function will be offset by an additional tab.
-# Default is false.
 #
 # Supported values: True, False
 
 # logAllCalls = False
 
+# In a Debug or DebugOptimized build of the bridge, setting LogAllCommands
+# will log Command object creation, commands being pushed to the command buffer,
+# and waitForCommand calls to the respective Bridge server or client log files.
+# Additionally, it will enable logging of Bridge Server Module and Device
+# processing, the same as setting logServerCommands to True
+
+# Supported values: True, False
+
+# logAllCommands = False
+
 # In a Debug or DebugOptimized build of the bridge, setting LogServerCommands
-# to True will write each command sent to the server to the server log file
-# ("NvRemixBridge.log")
-# Default is false.
-#
+# or LogAllCommands to True will write each command sent to the server to the server 
+# log file ("NvRemixBridge.log")
+
 # Supported values: True, False
 
 # logServerCommands = False
 
-
 # The bridge client and server inter-process communication (IPC) relies
 # on sending a lot of commands and data from the client to the server
 # constantly. During normal operation this works fine and as expected,

src/server/main.cpp

@@ -281,7 +281,7 @@ void ProcessDeviceCommandQueue() {
  PULL_U(currentUID);
 #if defined(_DEBUG) || defined(DEBUGOPT)
  if (GlobalOptions::getLogServerCommands()) {
- Logger::info(toString(rpcHeader.command));
+ Logger::info("Device Processing: " + toString(rpcHeader.command) + " UID: " + std::to_string(currentUID));
  }
 #endif
  std::unique_lock<std::mutex> lock(gLock);

src/server/module_processing.cpp

@@ -88,7 +88,7 @@ void processModuleCommandQueue(std::atomic<bool>* const pbSignalEnd) {
  PULL_U(currentUID);
 #if defined(_DEBUG) || defined(DEBUGOPT)
  if (GlobalOptions::getLogServerCommands()) {
- Logger::info(toString(rpcHeader.command));
+ Logger::info("Module Processing: " + toString(rpcHeader.command) + " UID: " + std::to_string(currentUID));
  }
 #endif
  std::unique_lock<std::mutex> lock(gLock);

src/util/config/global_options.h

@@ -114,8 +114,12 @@ class GlobalOptions {
  return get().logApiCalls;
  }
 
+ static bool getLogAllCommands() {
+ return get().logAllCommands;
+ }
+
  static bool getLogServerCommands() {
- return get().logServerCommands;
+ return get().logServerCommands || get().logAllCommands;
  }
 
  static uint32_t getCommandTimeout() {
@@ -315,9 +319,17 @@ class GlobalOptions {
  // public D3D9 API function will be offset by an additional tab.
  logAllCalls = bridge_util::Config::getOption<bool>("logAllCalls", false);
 
+ // In a Debug or DebugOptimized build of the bridge, setting LogAllCommands
+ // will log Command object creation, commands being pushed to the command buffer,
+ // and waitForCommand calls to the respective Bridge server or client log files.
+ // Additionally, it will enable logging of Bridge Server Module and Device
+ // processing, the same as setting logServerCommands to True
+
+ logAllCommands = bridge_util::Config::getOption<bool>("logAllCommands", false);
+
  // In a Debug or DebugOptimized build of the bridge, setting LogServerCommands
- // to True will write each command sent to the server to the server log file
- // ("NvRemixBridge.log")
+ // or LogAllCommands to True will write each command sent to the server to the server 
+ // log file ("NvRemixBridge.log")
 
  logServerCommands = bridge_util::Config::getOption<bool>("logServerCommands", false);
 
@@ -426,6 +438,7 @@ class GlobalOptions {
  bool sendCreateFunctionServerResponses;
  bool logAllCalls;
  bool logApiCalls;
+ bool logAllCommands;
  bool logServerCommands;
  uint32_t commandTimeout;
  uint32_t startupTimeout;

src/util/util_bridgecommand.cpp

@@ -157,6 +157,11 @@ DECL_BRIDGE_FUNC(bridge_util::Result, waitForCommand, const Commands::D3D9Comman
  if (command != Commands::Any) {
  Logger::trace(format_string("Waiting for command %s for %d ms up to %d times...", Commands::toString(command).c_str(), peekTimeoutMS, maxAttempts));
  }
+#endif
+#if defined(_DEBUG) || defined(DEBUGOPT)
+ if (GlobalOptions::getLogAllCommands()) {
+ Logger::info("waitForCommand Command:" + toString(command) + (verifyUID ? " UID: " + std::to_string(uidToVerify) : ""));
+ }
 #endif
  bool infiniteRetries = false;
  bool bEarlyOut = false;
@@ -183,8 +188,12 @@ DECL_BRIDGE_FUNC(bridge_util::Result, waitForCommand, const Commands::D3D9Comman
 #endif
  return Result::Success;
  } else {
- Logger::debug(format_string("Different instance of a command detected: %s with UID: %s , Expected: %s with UID: %s. ", Commands::toString(header.command).c_str(), std::to_string(header.pHandle).c_str(),
- Commands::toString(command).c_str(), std::to_string(uidToVerify).c_str()));
+#if defined(_DEBUG) || defined(DEBUGOPT)
+ if (GlobalOptions::getLogAllCommands()) {
+ Logger::info(format_string("Different instance of a command detected: %s with UID: %s , Expected: %s with UID: %s. ", Commands::toString(header.command).c_str(), std::to_string(header.pHandle).c_str(),
+ Commands::toString(command).c_str(), std::to_string(uidToVerify).c_str()));
+ }
+#endif
  // If we see the incorrect command, we want to give the other side of
  // the bridge ample time to make an attempt to process it first
  Sleep(peekTimeoutMS);
@@ -253,6 +262,16 @@ DECL_COMMAND_FUNC(,Command,const Commands::D3D9Command command,
  // this issue I recommend enclosing the Command object in its own scope block, and make
  // sure there is no command nesting happening either.
 
+#if defined(_DEBUG) || defined(DEBUGOPT)
+ if (GlobalOptions::getLogAllCommands()) {
+#ifdef REMIX_BRIDGE_CLIENT
+ Logger::info("Requesting: " +toString(command) + " UID: " + std::to_string(s_cmdUID));
+#else
+ Logger::info("Responding: " + toString(command) + " UID: " + std::to_string(pHandle));
+#endif
+ }
+#endif
+
 #ifdef REMIX_BRIDGE_CLIENT
  s_pWriterChannel->m_mutex.lock();
 #endif
@@ -274,6 +293,11 @@ DECL_COMMAND_FUNC(,Command,const Commands::D3D9Command command,
 #ifdef REMIX_BRIDGE_CLIENT
  syncDataQueue(1, false);
  const auto result = s_pWriterChannel->data->push((UINT)s_cmdUID);
+#if defined(_DEBUG) || defined(DEBUGOPT)
+ if (GlobalOptions::getLogAllCommands()) {
+ Logger::info("Pushed UID: " + std::to_string(s_cmdUID));
+ }
+#endif
  if (RESULT_FAILURE(result)) {
  // For now just log when things go wrong, but could use some robustness improvements
  Logger::err("DataQueue send_data: Failed to send data!");
@@ -293,6 +317,11 @@ DECL_COMMAND_FUNC(,~Command) {
  // was disabled externally by the server process exit callback.
  do {
  result = s_pWriterChannel->commands->push({ m_command, m_commandFlags, (uint32_t) s_pWriterChannel->data->get_pos(), m_handle });
+#if defined(_DEBUG) || defined(DEBUGOPT)
+ if (GlobalOptions::getLogAllCommands()) {
+ Logger::info("Pushed: " + toString(m_command));
+ }
+#endif
  } while (
  RESULT_FAILURE(result)
  && numRetries++ < GlobalOptions::getCommandRetries()