Merge pull request #7055 from VOREStation/vplk-debug-master

Debug Master Controller

code/_helpers/logging.dm

@@ -259,20 +259,28 @@
 	return key_name(whom, 1, include_name)
 
 // Helper procs for building detailed log lines
+//
+// These procs must not fail under ANY CIRCUMSTANCES!
+//
+
 /datum/proc/log_info_line()
 	return "[src] ([type])"
 
 /atom/log_info_line()
+	. = ..()
 	var/turf/t = get_turf(src)
 	if(istype(t))
-		return "([t]) ([t.x],[t.y],[t.z]) ([t.type])"
+		return "[.] @ [t.log_info_line()]"
 	else if(loc)
-		return "([loc]) (0,0,0) ([loc.type])"
+		return "[.] @ ([loc]) (0,0,0) ([loc.type])"
 	else
-		return "(NULL) (0,0,0) (NULL)"
+		return "[.] @ (NULL) (0,0,0) (NULL)"
+
+/turf/log_info_line()
+	return "([src]) ([x],[y],[z]) ([type])"
 
 /mob/log_info_line()
-	return "[..()] ([ckey])"
+	return "[..()] (ckey=[ckey])"
 
 /proc/log_info_line(var/datum/d)
 	if(!d)

code/controllers/failsafe.dm

@@ -52,6 +52,7 @@ var/datum/controller/failsafe/Failsafe
 			if(Master.processing && Master.iteration)
 				// Check if processing is done yet.
 				if(Master.iteration == master_iteration)
+					log_debug("DEFCON [defcon]: Master.iteration=[Master.iteration] Master.last_run=[Master.last_run] world.time=[world.time]")
 					switch(defcon)
 						if(4,5)
 							--defcon
@@ -71,7 +72,7 @@ var/datum/controller/failsafe/Failsafe
 								master_iteration = 0
 								to_chat(admins, "<span class='adminnotice'>MC restarted successfully</span>")
 							else if(rtn < 0)
-								log_game("FailSafe: Could not restart MC, runtime encountered. Entering defcon 0")
+								log_world("FailSafe: Could not restart MC, runtime encountered. Entering defcon 0")
 								to_chat(admins, "<span class='boldannounce'>ERROR: DEFCON [defcon_pretty()]. Could not restart MC, runtime encountered. I will silently keep retrying.</span>")
 							//if the return number was 0, it just means the mc was restarted too recently, and it just needs some time before we try again
 							//no need to handle that specially when defcon 0 can handle it

code/controllers/master.dm

@@ -50,6 +50,8 @@ GLOBAL_REAL(Master, /datum/controller/master) = new
 
 	var/current_runlevel	//for scheduling different subsystems for different stages of the round
 
+	var/dbg_is_running_subsystem = FALSE  // TEMPORARY DEBUGGING - true only while we are actually waiting on a subsystem
+
 	var/static/restart_clear = 0
 	var/static/restart_timeout = 0
 	var/static/restart_count = 0
@@ -221,10 +223,12 @@ GLOBAL_REAL(Master, /datum/controller/master) = new
 	//loop ended, restart the mc
 	log_game("MC crashed or runtimed, restarting")
 	message_admins("MC crashed or runtimed, restarting")
+	log_world("MC crashed or runtimed, restarting")
 	var/rtn2 = Recreate_MC()
 	if (rtn2 <= 0)
 		log_game("Failed to recreate MC (Error code: [rtn2]), it's up to the failsafe now")
 		message_admins("Failed to recreate MC (Error code: [rtn2]), it's up to the failsafe now")
+		log_world("Failed to recreate MC (Error code: [rtn2]), it's up to the failsafe now")
 		Failsafe.defcon = 2
 
 // Main loop.
@@ -336,6 +340,7 @@ GLOBAL_REAL(Master, /datum/controller/master) = new
 			subsystems_to_check = tickersubsystems
 
 		if (CheckQueue(subsystems_to_check) <= 0)
+			log_world("MC: CheckQueue(subsystems_to_check) exited uncleanly, SoftReset (error_level=[error_level]")
 			if (!SoftReset(tickersubsystems, runlevel_sorted_subsystems))
 				log_world("MC: SoftReset() failed, crashing")
 				return
@@ -348,6 +353,7 @@ GLOBAL_REAL(Master, /datum/controller/master) = new
 
 		if (queue_head)
 			if (RunQueue() <= 0)
+				log_world("MC: RunQueue() exited uncleanly, running SoftReset (error_level=[error_level]")
 				if (!SoftReset(tickersubsystems, runlevel_sorted_subsystems))
 					log_world("MC: SoftReset() failed, crashing")
 					return
@@ -470,9 +476,11 @@ GLOBAL_REAL(Master, /datum/controller/master) = new
 
 			queue_node.state = SS_RUNNING
 
+			dbg_is_running_subsystem = TRUE // TEMPORARY DEBUGGING
 			tick_usage = TICK_USAGE
 			var/state = queue_node.ignite(queue_node_paused)
 			tick_usage = TICK_USAGE - tick_usage
+			dbg_is_running_subsystem = FALSE // TEMPORARY DEBUGGING
 
 			if (state == SS_RUNNING)
 				state = SS_IDLE

code/modules/error_handler/error_handler.dm

@@ -51,12 +51,12 @@ GLOBAL_VAR_INIT(total_runtimes_skipped, 0)
 	// First, try to make better src/usr info lines
 	if(istype(e_src))
 		srcinfo = list("  src: [log_info_line(e_src)]")
-		locinfo = log_info_line(e_src)
-		if(locinfo)
-			srcinfo += "  src.loc: [locinfo]"
+		var/atom/atom_e_src = e_src
+		if(istype(atom_e_src))
+			srcinfo += "  src.loc: [log_info_line(atom_e_src.loc)]"
 	if(istype(usr))
 		usrinfo = list("  usr: [log_info_line(usr)]")
-		locinfo = log_info_line(usr)
+		locinfo = log_info_line(usr.loc)
 		if(locinfo)
 			usrinfo += "  usr.loc: [locinfo]"
 	// The proceeding mess will almost definitely break if error messages are ever changed

code/modules/vore/trycatch_vr.dm

@@ -25,6 +25,7 @@ The proc you're attemping should return nonzero values on success.
 	catch(var/exception/e)
 		error("attempt_vr runtimed when calling [procname] on [callon].")
 		error("attempt_vr catch: [e] on [e.file]:[e.line]")
+		log_runtime(e)
 		return 0
 
 /*