Debug Message Improvements

code/__DEFINES/chat.dm

@@ -18,19 +18,3 @@
 #define MESSAGE_TYPE_ADMINLOG "adminlog"
 #define MESSAGE_TYPE_ATTACKLOG "attacklog"
 #define MESSAGE_TYPE_DEBUG "debug"
-
-//debug printing macros (for development and testing)
-/// Used for debug messages to the world
-#define debug_world(msg) if (GLOB.Debug2) to_chat(world, \
-	type = MESSAGE_TYPE_DEBUG, \
-	text = "DEBUG: [msg]")
-/// Used for debug messages to the player
-#define debug_usr(msg) if (GLOB.Debug2&&usr) to_chat(usr, \
-	type = MESSAGE_TYPE_DEBUG, \
-	text = "DEBUG: [msg]")
-/// Used for debug messages to the admins
-#define debug_admins(msg) if (GLOB.Debug2) to_chat(GLOB.admins, \
-	type = MESSAGE_TYPE_DEBUG, \
-	text = "DEBUG: [msg]")
-/// Used for debug messages to the server
-#define debug_world_log(msg) if (GLOB.Debug2) log_world("DEBUG: [msg]")

code/__DEFINES/debug_messaging.dm

@@ -0,0 +1,8 @@
+#define DBG_TRACE "trace"
+#define DBG_INFO "info"
+#define DBG_WARN "warn"
+#define DBG_ERROR "error"
+
+#define DBG_LOG_WORLD (1 << 0)
+#define DBG_STACK_TRACE (1 << 1)
+#define DBG_ALWAYS (1 << 2)

code/__DEFINES/span.dm

@@ -39,7 +39,12 @@
 #define span_cultlarge(str) ("<span class='cultlarge'>" + str + "</span>")
 #define span_danger(str) ("<span class='danger'>" + str + "</span>")
 #define span_deadsay(str) ("<span class='deadsay'>" + str + "</span>")
-#define span_debug(str) ("<span class='debug'>" + str + "</span>")
+#define span_debug_legacy(str) ("<span class='debugLegacy'>" + str + "</span>")
+#define span_debug_basic(str) ("<span class='debug'>" + str + "</span>")
+#define span_debug_trace(str) ("<span class='debug debugTrace'>" + str + "</span>")
+#define span_debug_info(str) ("<span class='debug debugInfo'>" + str + "</span>")
+#define span_debug_warn(str) ("<span class='debug debugWarn'>" + str + "</span>")
+#define span_debug_error(str) ("<span class='debug debugError'>" + str + "</span>")
 #define span_deconversion_message(str) ("<span class='deconversion_message'>" + str + "</span>")
 #define span_drone(str) ("<span class='drone'>" + str + "</span>")
 #define span_engradio(str) ("<span class='engradio'>" + str + "</span>")

code/__HELPERS/debug_messaging.dm

@@ -0,0 +1,75 @@
+/* Helpers for Debug Messaging
+ *
+ * Log Levels conform to standard Unix expectations.
+ * All have the same argument set
+ *
+ * Messages are built as follows
+ * $PREFIX: $MESSAGE
+ *
+ * Messages are passed to chat only when the running server is in debug (is_debug_server), or live debugging has been enabled (GLOB.Debug2)
+ * Messages are passed globally on debug servers, otherwise Messages are passed to admins if live debugging is enabled.
+ * The single exception is TRACE level messages, which REQUIRE live debugging, this is to decrease general noise.
+ *
+ *  - level | Log level, controls the message border's color. Traces are only sent to chat when Live Debugging is enabled.
+ *   - DBG_TRACE: white | Spammy stuff, raw values of a calculation, etc.
+ *   - DBG_INFO: blue (default) | State changes, progress indications, Etc.
+ *   - DBG_WARN: orange | An issue has been handled cleanly, or something isn't right, but not enough to cause a problem for players.
+ *   - DBG_ERROR: red | Errors. Something has gone wrong and you're probably just about to bail out of the proc. Consider throwing a stack as well.
+
+ *
+ *  - prefix | Describes the sending system, Examples: Packets/IRPS, Jobs/AssignCaptain
+ *   - default: "DEBUG"
+ *
+ *  - message | The actual content of the message.
+ *   - Required.
+ *
+ *  - additional | Additional actions to take. Bitfield.
+ *   - DBG_LOG_WORLD (default) | call log_world with message.
+ *   - DBG_STACK_TRACE | Throw a stack trace.
+ *   - DBG_ALWAYS | Send regardless of debug status.
+ *
+ */
+
+/proc/message_debug(level = DBG_INFO, prefix = "DEBUG", message, additional = DBG_LOG_WORLD)
+	// If we're a trace message and debugging is not enabled, return immediately.
+	// or we aren't being forced to send regardless.
+	if(level == DBG_TRACE && !GLOB.Debug2 && !(additional & DBG_ALWAYS))
+		return
+	// No message, No Service.
+	if(!message)
+		CRASH("Debug message without message? Wack.")
+
+	/// Built message with prefix.
+	var/built_message = "[prefix]: [message]"
+
+	/// Severity span class to use.
+	var/severity_class
+	switch(level)
+		if(DBG_TRACE)
+			severity_class = "debugTrace"
+		if(DBG_INFO)
+			severity_class = "debugInfo"
+		if(DBG_WARN)
+			severity_class = "debugWarn"
+		if(DBG_ERROR)
+			severity_class = "debugError"
+		else
+			message_debug(DBG_ERROR, "DebugMessage/Severity", "Invalid severity level [level]. Setting to error.", DBG_STACK_TRACE)
+			level = DBG_ERROR
+			severity_class = "debugError"
+
+	// Check if we throw a stack trace.
+	if(additional & DBG_STACK_TRACE)
+		stack_trace("[level] | [built_message]")
+	// Log to world.
+	if(additional & DBG_LOG_WORLD)
+		log_world("[level] | [built_message]")
+
+	//Do we sent this, and to who?
+	//Trace requires Debug2 explicitly.
+	if((additional & DBG_ALWAYS) || GLOB.Debug2 || (GLOB.is_debug_server && (level != DBG_TRACE)))
+		to_chat(
+			target = (GLOB.is_debug_server ? world : GLOB.admins),
+			type = MESSAGE_TYPE_DEBUG,
+			html = "<div class='debug [severity_class]'>[built_message]</div>"
+			)

code/controllers/master.dm

@@ -199,7 +199,7 @@ GLOBAL_REAL(Master, /datum/controller/master) = new
 		current_runlevel = Master.current_runlevel
 		StartProcessing(10)
 	else
-		to_chat(world, span_boldannounce("The Master Controller is having some issues, we will need to re-initialize EVERYTHING"))
+		to_chat(world, span_debug_error("The Master Controller is having some issues, we will need to re-initialize EVERYTHING"))
 		Initialize(20, TRUE)
 
 
@@ -293,7 +293,7 @@ GLOBAL_REAL(Master, /datum/controller/master) = new
 	if(isnull(old_runlevel))
 		old_runlevel = "NULL"
 
-	testing("MC: Runlevel changed from [old_runlevel] to [new_runlevel]")
+	message_debug(DBG_INFO, "MC/Runlevel", "Runlevel changed from [old_runlevel] to [new_runlevel]")
 	current_runlevel = log(2, new_runlevel) + 1
 	if(current_runlevel < 1)
 		CRASH("Attempted to set invalid runlevel: [new_runlevel]")

code/controllers/subsystem.dm

@@ -277,7 +277,7 @@
 	var/time = (REALTIMEOFDAY - start_timeofday) / 10
 	var/msg = "Initialized [name] subsystem within [time] second[time == 1 ? "" : "s"]!"
 	if(GLOB.is_debug_server)
-		to_chat(world, span_debug("[msg]"))
+		to_chat(world, span_debug_legacy("[msg]"))
 	log_world(msg)
 	return time
 

code/controllers/subsystem/airmachines.dm

@@ -25,13 +25,13 @@ SUBSYSTEM_DEF(airmachines)
 
 /datum/controller/subsystem/airmachines/Initialize(timeofday)
 	var/starttime = REALTIMEOFDAY
-	to_chat(world, span_debug("Airmachines: Setting up atmospheric machinery..."))
+	to_chat(world, span_debug_legacy("Airmachines: Setting up atmospheric machinery..."))
 	setup_atmos_machinery()
-	to_chat(world, span_debug("Airmachines: Airmachine setup completed in [(REALTIMEOFDAY- starttime) / 10] seconds!"))
+	to_chat(world, span_debug_legacy("Airmachines: Airmachine setup completed in [(REALTIMEOFDAY- starttime) / 10] seconds!"))
 	starttime = REALTIMEOFDAY
-	to_chat(world, span_debug("Airmachines: Creating pipenets..."))
+	to_chat(world, span_debug_legacy("Airmachines: Creating pipenets..."))
 	setup_pipenets()
-	to_chat(world, span_debug("Airmachines: Pipenet creation completed in [(REALTIMEOFDAY- starttime) / 10] seconds!"))
+	to_chat(world, span_debug_legacy("Airmachines: Pipenet creation completed in [(REALTIMEOFDAY- starttime) / 10] seconds!"))
 	return ..()
 
 /datum/controller/subsystem/airmachines/stat_entry(msg)

code/controllers/subsystem/job.dm

@@ -119,7 +119,7 @@ SUBSYSTEM_DEF(job)
 		if(!job.config_check())
 			continue
 		if(!job.map_check()) //Even though we initialize before mapping, this is fine because the config is loaded at new
-			testing("Removed [job.type] due to map config")
+			message_debug(DBG_INFO, "SSJob/SetupOccupations", "Removed [job.type] due to map config.")
 			continue
 		new_all_occupations += job
 		name_occupations[job.title] = job

code/controllers/subsystem/mapping.dm

@@ -294,7 +294,7 @@ Used by the AI doomsday and the self-destruct nuke.
 	z_list = SSmapping.z_list
 	multiz_levels = SSmapping.multiz_levels
 
-#define INIT_ANNOUNCE(X) to_chat(world, span_debug("[X]")); log_world(X)
+#define INIT_ANNOUNCE(X) to_chat(world, span_debug_legacy("[X]")); log_world(X)
 /datum/controller/subsystem/mapping/proc/LoadGroup(list/errorList, name, path, files, list/traits, list/default_traits, silent = FALSE)
 	. = list()
 	var/start_time = REALTIMEOFDAY
@@ -319,7 +319,7 @@ Used by the AI doomsday and the self-destruct nuke.
 		for (var/i in 1 to total_z)
 			traits += list(default_traits)
 	else if (total_z != traits.len)  // mismatch
-		INIT_ANNOUNCE("WARNING: [traits.len] trait sets specified for [total_z] z-levels in [path]!")
+		message_debug(DBG_WARN, "SSMapping/LoadGroup", "[traits.len] trait sets specified for [total_z] z-levels in [path]!", DBG_ALWAYS | DBG_LOG_WORLD)
 		if (total_z < traits.len)  // ignore extra traits
 			traits.Cut(total_z + 1)
 		while (total_z > traits.len)  // fall back to defaults on extra levels

code/controllers/subsystem/ticker.dm

@@ -732,7 +732,7 @@ SUBSYSTEM_DEF(ticker)
 	///The full datum of the last song used.
 	var/datum/media/old_login_music
 
-	if(rustg_file_exists("data/last_round_lobby_music.txt")) //The define isn't truthy
+	if(rustg_file_exists("data/last_round_lobby_music.txt"))
 		old_login_music_t = rustg_file_read("data/last_round_lobby_music.txt")
 	var/list/music_tracks = title_music_data + rare_music_data
 	//Filter map-specific tracks
@@ -802,7 +802,7 @@ SUBSYSTEM_DEF(ticker)
 	if(!mode)
 		var/list/datum/game_mode/runnable_modes = draft_gamemodes()
 		if(!runnable_modes.len)
-			message_admins(world, "<B>No viable gamemodes to play.</B> Running Extended.")
+			message_debug(DBG_WARN, "Ticker/init_gamemode", "<u>No valid gamemodes.</u> Extended has been forced.", DBG_ALWAYS | DBG_LOG_WORLD)
 			mode = new /datum/game_mode/extended
 		else
 			mode = pick_weight(runnable_modes)
@@ -842,7 +842,10 @@ SUBSYSTEM_DEF(ticker)
 			SSjob.ResetOccupations()
 			return FALSE
 	else
-		message_admins(span_notice("DEBUG: Bypassing prestart checks..."))
+		if(can_continue)
+			message_debug(DBG_TRACE, "Ticker/init_gamemode", "Roundstart execution and occupation division were skipped, and would have passed anyways.")
+		else
+			message_debug(DBG_ERROR, "Ticker/init_gamemode", "Roundstart execution and occupation division were skipped, and at least one failed!")
 
 	log_game("Gamemode successfully initialized, chose: [mode.name]")
 	return TRUE

code/controllers/subsystem/zas.dm

@@ -170,7 +170,7 @@ SUBSYSTEM_DEF(zas)
 	settings = zas_settings
 	gas_data = xgm_gas_data
 
-	to_chat(world, span_debug("ZAS: Processing Geometry..."))
+	to_chat(world, span_debug_legacy("ZAS: Processing Geometry..."))
 
 	var/simulated_turf_count = 0
 
@@ -183,17 +183,17 @@ SUBSYSTEM_DEF(zas)
 
 		CHECK_TICK
 
-	to_chat(world, span_debug("ZAS:\n - Total Simulated Turfs: [simulated_turf_count]\n - Total Zones: [zones.len]\n - Total Edges: [edges.len]\n - Total Active Edges: [active_edges.len ? "<span class='danger'>[active_edges.len]</span>" : "None"]\n - Total Unsimulated Turfs: [world.maxx*world.maxy*world.maxz - simulated_turf_count]"))
+	to_chat(world, span_debug_legacy("ZAS:\n - Total Simulated Turfs: [simulated_turf_count]\n - Total Zones: [zones.len]\n - Total Edges: [edges.len]\n - Total Active Edges: [active_edges.len ? "<span class='danger'>[active_edges.len]</span>" : "None"]\n - Total Unsimulated Turfs: [world.maxx*world.maxy*world.maxz - simulated_turf_count]"))
 
-	to_chat(world, span_debug("ZAS: Geometry processing completed in [(REALTIMEOFDAY - starttime)/10] seconds!"))
+	to_chat(world, span_debug_legacy("ZAS: Geometry processing completed in [(REALTIMEOFDAY - starttime)/10] seconds!"))
 
 	if (simulate)
-		to_chat(world, span_debug("ZAS: Firing once..."))
+		to_chat(world, span_debug_legacy("ZAS: Firing once..."))
 
 		starttime = REALTIMEOFDAY
 		fire(FALSE, TRUE)
 
-		to_chat(world, span_debug("ZAS: Air settling completed in [(REALTIMEOFDAY - starttime)/10] seconds!"))
+		to_chat(world, span_debug_legacy("ZAS: Air settling completed in [(REALTIMEOFDAY - starttime)/10] seconds!"))
 
 	..(timeofday)
 

code/modules/admin/IsBanned.dm

@@ -7,7 +7,7 @@
 #define STICKYBAN_MAX_ADMIN_MATCHES 1
 
 /world/IsBanned(key, address, computer_id, type, real_bans_only=FALSE)
-	debug_world_log("isbanned(): '[args.Join("', '")]'")
+	message_debug(DBG_TRACE, "World/IsBanned", "[args.Join("', '")]", NONE)
 	if (!key || (!real_bans_only && (!address || !computer_id)))
 		if(real_bans_only)
 			return FALSE

code/modules/admin/admin_verbs.dm

@@ -853,7 +853,7 @@ GLOBAL_PROTECT(admin_verbs_hideable)
 						if (tile)
 							var/mob/living/carbon/human/hooman = new(tile)
 							hooman.equipOutfit(pick(subtypesof(/datum/outfit)))
-							testing("Spawned test mob at [COORD(tile)]")
+							message_debug(DBG_TRACE, "PopulateWorld", "Spawned test mob at [COORD(tile)]")
 			while (!area && --j > 0)
 
 /client/proc/toggle_AI_interact()

code/modules/admin/ipintel.dm

@@ -129,8 +129,4 @@
 		SSipintel.throttle = world.timeofday + (10 * 120 * SSipintel.errors)
 	else
 		error += " Attempting retry on [ip]."
-	log_ipintel(error)
-
-/proc/log_ipintel(text)
-	log_game("IPINTEL: [text]")
-	debug_admins("IPINTEL: [text]")
+	message_debug(DBG_ERROR, "IPIntel", error)

code/modules/admin/verbs/adminhelp.dm

@@ -888,7 +888,7 @@ GLOBAL_DATUM_INIT(admin_help_ui_handler, /datum/admin_help_ui_handler, new)
  */
 /proc/send2otherserver(source, msg, type = "Ahelp", target_servers, list/additional_data = list())
 	if(!CONFIG_GET(string/comms_key))
-		debug_world_log("Server cross-comms message not sent for lack of configured key")
+		message_debug(DBG_TRACE, "WorldComms/send2otherserver", "Server cross-comms message not sent for lack of configured key")
 		return
 
 	var/our_id = CONFIG_GET(string/cross_comms_name)
@@ -911,7 +911,7 @@ GLOBAL_DATUM_INIT(admin_help_ui_handler, /datum/admin_help_ui_handler, new)
 	if (auth)
 		var/comms_key = CONFIG_GET(string/comms_key)
 		if(!comms_key)
-			debug_world_log("Server cross-comms message not sent for lack of configured key")
+			message_debug(DBG_TRACE, "WorldComms/send_cross_comms", "Server cross-comms message not sent for lack of configured key")
 			return
 		message["key"] = comms_key
 	var/list/servers = CONFIG_GET(keyed_list/cross_server)

code/modules/food_and_drinks/kitchen_machinery/processor.dm

@@ -132,7 +132,7 @@
 	for(var/atom/movable/movable_input as anything in processor_contents)
 		var/datum/food_processor_process/recipe = PROCESSOR_SELECT_RECIPE(movable_input)
 		if (!recipe)
-			log_admin("DEBUG: [movable_input] in processor doesn't have a suitable recipe. How did it get in there? Please report it immediately!!!")
+			message_debug(DBG_ERROR, "FoodProcessor/interact", "[movable_input] in processor doesn't have a suitable recipe. Make a bug report.", DBG_ALWAYS | DBG_LOG_WORLD)
 			continue
 		total_time += recipe.time
 	var/offset = prob(50) ? -2 : 2
@@ -141,7 +141,7 @@
 	for(var/atom/movable/O in processor_contents)
 		var/datum/food_processor_process/P = PROCESSOR_SELECT_RECIPE(O)
 		if (!P)
-			log_admin("DEBUG: [O] in processor doesn't have a suitable recipe. How do you put it in?")
+			message_debug(DBG_ERROR, "FoodProcessor/interact", "[O] in processor doesn't have a suitable recipe. Make a bug report.", DBG_ALWAYS | DBG_LOG_WORLD)
 			continue
 		process_food(P, O)
 	pixel_x = base_pixel_x //return to its spot after shaking

code/modules/reagents/chemistry/recipes.dm

@@ -358,7 +358,7 @@
 	var/turf/target = locate(holder_turf.x + equilibrium.data["[id]_x"], holder_turf.y + equilibrium.data["[id]_y"], holder_turf.z)
 	//new /obj/effect/hotspot(target)
 	target.create_fire(1, 10)
-	debug_world("X: [equilibrium.data["[id]_x"]], Y: [equilibrium.data["[id]_x"]]")
+	message_debug(DBG_TRACE, "ChemReact/FireVortex", "X: [equilibrium.data["[id]_x"]], Y: [equilibrium.data["[id]_x"]]", NONE)
 
 /*
  * Creates a square of fire in a fire_range radius,

code/modules/shuttle/shuttle.dm

@@ -543,7 +543,7 @@
 //call the shuttle to destination S
 /obj/docking_port/mobile/proc/request(obj/docking_port/stationary/S)
 	if(!check_dock(S))
-		testing("check_dock failed on request for [src]")
+		message_debug(DBG_TRACE, "DockingPort/request", "check_dock failed on request for [src]")
 		return
 
 	if(mode == SHUTTLE_IGNITING && destination == S)

daedalus.dme

@@ -69,6 +69,7 @@
 #include "code\__DEFINES\credits.dm"
 #include "code\__DEFINES\cult.dm"
 #include "code\__DEFINES\database.dm"
+#include "code\__DEFINES\debug_messaging.dm"
 #include "code\__DEFINES\decal_defines.dm"
 #include "code\__DEFINES\devices.dm"
 #include "code\__DEFINES\direction_junctions.dm"
@@ -348,6 +349,7 @@
 #include "code\__HELPERS\construction.dm"
 #include "code\__HELPERS\dates.dm"
 #include "code\__HELPERS\datums.dm"
+#include "code\__HELPERS\debug_messaging.dm"
 #include "code\__HELPERS\dna.dm"
 #include "code\__HELPERS\files.dm"
 #include "code\__HELPERS\filters.dm"