From 118c669d6a34ac64a3a4f042e98f5fea25c10589 Mon Sep 17 00:00:00 2001 From: Leshana Date: Mon, 30 Mar 2020 16:48:18 -0400 Subject: [PATCH 1/5] Enhanced logging of Master and Failsafe controllers. --- code/controllers/failsafe.dm | 3 ++- code/controllers/master.dm | 4 ++++ 2 files changed, 6 insertions(+), 1 deletion(-) diff --git a/code/controllers/failsafe.dm b/code/controllers/failsafe.dm index 0589d5fa7ff..254472a2c8b 100644 --- a/code/controllers/failsafe.dm +++ b/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, "MC restarted successfully") 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, "ERROR: DEFCON [defcon_pretty()]. Could not restart MC, runtime encountered. I will silently keep retrying.") //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 diff --git a/code/controllers/master.dm b/code/controllers/master.dm index 644ab8d2f0d..07cf0712461 100644 --- a/code/controllers/master.dm +++ b/code/controllers/master.dm @@ -221,10 +221,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 +338,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 +351,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 From 2e114ede5c27671db958d324016938a1baa6c94b Mon Sep 17 00:00:00 2001 From: Leshana Date: Mon, 30 Mar 2020 16:49:22 -0400 Subject: [PATCH 2/5] Fix error handler printing bogus src.loc and usr.loc info --- code/_helpers/logging.dm | 16 ++++++++++++---- code/modules/error_handler/error_handler.dm | 8 ++++---- 2 files changed, 16 insertions(+), 8 deletions(-) diff --git a/code/_helpers/logging.dm b/code/_helpers/logging.dm index 7f3393ccc99..18cede2ea4b 100644 --- a/code/_helpers/logging.dm +++ b/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) diff --git a/code/modules/error_handler/error_handler.dm b/code/modules/error_handler/error_handler.dm index 098ea614b5e..edae4c42ea7 100644 --- a/code/modules/error_handler/error_handler.dm +++ b/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 From 771c09ad2f224a403d68611d9b2da74f186d6055 Mon Sep 17 00:00:00 2001 From: Leshana Date: Mon, 30 Mar 2020 16:49:46 -0400 Subject: [PATCH 3/5] Make attempt_vr print more complete debugging info/stack trace. --- code/modules/vore/trycatch_vr.dm | 1 + 1 file changed, 1 insertion(+) diff --git a/code/modules/vore/trycatch_vr.dm b/code/modules/vore/trycatch_vr.dm index 78e91e91ebe..396352aadc6 100644 --- a/code/modules/vore/trycatch_vr.dm +++ b/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 /* From 48ee61f636ec2969b776af7d0edf67c48d65e976 Mon Sep 17 00:00:00 2001 From: Leshana Date: Mon, 30 Mar 2020 20:28:10 -0400 Subject: [PATCH 4/5] Avoid potential situation where log_debug calls to_chat which calls vchat_exec_update which calls log_debug. --- code/modules/vchat/vchat_db.dm | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/code/modules/vchat/vchat_db.dm b/code/modules/vchat/vchat_db.dm index 8f9ba13e92c..38b5173ac68 100644 --- a/code/modules/vchat/vchat_db.dm +++ b/code/modules/vchat/vchat_db.dm @@ -24,7 +24,7 @@ GLOBAL_DATUM(vchatdb, /database) //For INSERT/CREATE/DELETE, etc that return a RowsAffected. /proc/vchat_exec_update(var/query) if(!check_vchat()) - log_debug("There's no vchat database open but you tried to query it with: [query]") + log_world("There's no vchat database open but you tried to query it with: [query]") return FALSE //Solidify our query @@ -35,7 +35,7 @@ GLOBAL_DATUM(vchatdb, /database) //Handle errors if(q.Error()) - log_debug("Query \"[islist(query)?query[1]:query]\" ended in error [q.ErrorMsg()]") + log_world("Query \"[islist(query)?query[1]:query]\" ended in error [q.ErrorMsg()]") return FALSE return q.RowsAffected() From 3e9c17c1c0c194ce7e67d0edb1c6821f5ca2bbae Mon Sep 17 00:00:00 2001 From: Leshana Date: Mon, 30 Mar 2020 16:48:42 -0400 Subject: [PATCH 5/5] Debugging code to determine if Master failures actually happen while firing a subsystem. --- code/controllers/master.dm | 4 ++++ 1 file changed, 4 insertions(+) diff --git a/code/controllers/master.dm b/code/controllers/master.dm index 07cf0712461..cc6b224b5bf 100644 --- a/code/controllers/master.dm +++ b/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 @@ -474,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