Debug logging for DMAPI to hunt the dd topic issue

src/DMAPI/tgs/core/_definitions.dm

@@ -4,3 +4,7 @@
 
 #define TGS_UNIMPLEMENTED "___unimplemented"
 #define TGS_VERSION_PARAMETER "server_service_version"
+
+#ifndef TGS_DEBUG_LOG
+#define TGS_DEBUG_LOG(message)
+#endif

src/DMAPI/tgs/v5/api.dm

@@ -22,12 +22,17 @@
 
 	var/detached = FALSE
 
+/datum/tgs_api/v5/New()
+	. = ..()
+	TGS_DEBUG_LOG("V5 API created")
+
 /datum/tgs_api/v5/ApiVersion()
 	return new /datum/tgs_version(
 		#include "__interop_version.dm"
 	)
 
 /datum/tgs_api/v5/OnWorldNew(minimum_required_security_level)
+	TGS_DEBUG_LOG("OnWorldNew()")
 	server_port = world.params[DMAPI5_PARAM_SERVER_PORT]
 	access_identifier = world.params[DMAPI5_PARAM_ACCESS_IDENTIFIER]
 
@@ -96,17 +101,28 @@
 	return TRUE
 
 /datum/tgs_api/v5/proc/RequireInitialBridgeResponse()
+	TGS_DEBUG_LOG("RequireInitialBridgeResponse()")
+	var/logged = FALSE
 	while(!version)
+		if(!logged)
+			TGS_DEBUG_LOG("RequireInitialBridgeResponse: Starting sleep")
+			logged = TRUE
+
 		sleep(1)
 
+	TGS_DEBUG_LOG("RequireInitialBridgeResponse: Passed")
+
 /datum/tgs_api/v5/OnInitializationComplete()
 	Bridge(DMAPI5_BRIDGE_COMMAND_PRIME)
 
 /datum/tgs_api/v5/OnTopic(T)
+	TGS_DEBUG_LOG("OnTopic()")
 	RequireInitialBridgeResponse()
+	TGS_DEBUG_LOG("OnTopic passed bridge request gate")
 	var/list/params = params2list(T)
 	var/json = params[DMAPI5_TOPIC_DATA]
 	if(!json)
+		TGS_DEBUG_LOG("No \"[DMAPI5_TOPIC_DATA]\" entry found, ignoring...")
 		return FALSE // continue to /world/Topic
 
 	if(!initialized)
@@ -211,6 +227,7 @@
 	return chat_channels.Copy()
 
 /datum/tgs_api/v5/proc/DecodeChannels(chat_update_json)
+	TGS_DEBUG_LOG("DecodeChannels()")
 	var/list/chat_channels_json = chat_update_json[DMAPI5_CHAT_UPDATE_CHANNELS]
 	if(istype(chat_channels_json))
 		chat_channels.Cut()

src/DMAPI/tgs/v5/topic.dm

@@ -5,6 +5,7 @@
 	return response
 
 /datum/tgs_api/v5/proc/ProcessTopicJson(json, check_access_identifier)
+	TGS_DEBUG_LOG("ProcessTopicJson(..., [check_access_identifier])")
 	var/list/result = ProcessRawTopic(json, check_access_identifier)
 	if(!result)
 		result = TopicResponse("Runtime error!")
@@ -25,16 +26,20 @@
 	return response_json
 
 /datum/tgs_api/v5/proc/ProcessRawTopic(json, check_access_identifier)
+	TGS_DEBUG_LOG("ProcessRawTopic(..., [check_access_identifier])")
 	var/list/topic_parameters = json_decode(json)
 	if(!topic_parameters)
+		TGS_DEBUG_LOG("ProcessRawTopic: json_decode failed")
 		return TopicResponse("Invalid topic parameters json: [json]!");
 
 	var/their_sCK = topic_parameters[DMAPI5_PARAMETER_ACCESS_IDENTIFIER]
 	if(check_access_identifier && their_sCK != access_identifier)
-		return TopicResponse("Failed to decode [DMAPI5_PARAMETER_ACCESS_IDENTIFIER]!")
+		TGS_DEBUG_LOG("ProcessRawTopic: access identifier check failed")
+		return TopicResponse("Failed to decode [DMAPI5_PARAMETER_ACCESS_IDENTIFIER] or it does not match!")
 
 	var/command = topic_parameters[DMAPI5_TOPIC_PARAMETER_COMMAND_TYPE]
 	if(!isnum(command))
+		TGS_DEBUG_LOG("ProcessRawTopic: command type check failed")
 		return TopicResponse("Failed to decode [DMAPI5_TOPIC_PARAMETER_COMMAND_TYPE]!")
 
 	return ProcessTopicCommand(command, topic_parameters)
@@ -43,6 +48,7 @@
 	return "response[payload_id]"
 
 /datum/tgs_api/v5/proc/ProcessTopicCommand(command, list/topic_parameters)
+	TGS_DEBUG_LOG("ProcessTopicCommand([command], ...)")
 	switch(command)
 
 		if(DMAPI5_TOPIC_COMMAND_CHAT_COMMAND)
@@ -121,8 +127,10 @@
 			return TopicResponse()
 
 		if(DMAPI5_TOPIC_COMMAND_CHAT_CHANNELS_UPDATE)
+			TGS_DEBUG_LOG("ProcessTopicCommand: It's a chat update")
 			var/list/chat_update_json = topic_parameters[DMAPI5_TOPIC_PARAMETER_CHAT_UPDATE]
 			if(!istype(chat_update_json))
+				TGS_DEBUG_LOG("ProcessTopicCommand: failed \"[DMAPI5_TOPIC_PARAMETER_CHAT_UPDATE]\" check")
 				return TopicResponse("Invalid or missing [DMAPI5_TOPIC_PARAMETER_CHAT_UPDATE]!")
 
 			DecodeChannels(chat_update_json)

tests/DMAPI/LongRunning/Config.dm

@@ -9,3 +9,4 @@
 #define TGS_ERROR_LOG(message) TgsError(##message)
 #define TGS_NOTIFY_ADMINS(event)
 #define TGS_CLIENT_COUNT 0
+#define TGS_DEBUG_LOG(message) world.log << "TGS DEBUG: [##message]"