Merge pull request #2360 from PolarisSS13/exceptionhandling

Fixes exception handling runtiming

code/_helpers/logging.dm

@@ -162,3 +162,24 @@
 
 /proc/key_name_admin(var/whom, var/include_name = 1)
 	return key_name(whom, 1, include_name)
+
+// Helper procs for building detailed log lines
+/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])"
+	else if(loc)
+		return "([loc]) (0,0,0) ([loc.type])"
+	else
+		return "(NULL) (0,0,0) (NULL)"
+
+/mob/log_info_line()
+	return "[..()] ([ckey])"
+
+/proc/log_info_line(var/datum/d)
+	if(!istype(d))
+		return
+	return d.log_info_line()

code/controllers/ProcessScheduler/core/process.dm

@@ -327,9 +327,7 @@
 
 /datum/controller/process/proc/catchException(var/exception/e, var/thrower)
 	if(istype(e)) // Real runtimes go to the real error handler
-		// There are two newlines here, because handling desc sucks
-		e.desc = "  Caught by process: [name]\n\n" + e.desc
-		world.Error(e, e_src = thrower)
+		log_runtime(e, thrower, "Caught by process: [name]")
 		return
 	var/etext = "[e]"
 	var/eid = "[e]" // Exception ID, for tracking repeated exceptions

code/modules/admin/admin_verbs.dm

@@ -162,7 +162,7 @@ var/list/admin_verbs_server = list(
 	/client/proc/nanomapgen_DumpImage
 	)
 var/list/admin_verbs_debug = list(
-        /client/proc/getruntimelog,                     //allows us to access runtime logs to somebody,
+	/client/proc/getruntimelog,                     //allows us to access runtime logs to somebody,
 	/client/proc/cmd_admin_list_open_jobs,
 	/client/proc/Debug2,
 	/client/proc/kill_air,
@@ -196,7 +196,8 @@ var/list/admin_verbs_debug = list(
 	/client/proc/jumptocoord,
 	/client/proc/dsay,
 	/client/proc/toggle_debug_logs,
-	/client/proc/admin_ghost			//allows us to ghost/reenter body at will,
+	/client/proc/admin_ghost,			//allows us to ghost/reenter body at will,
+	/datum/admins/proc/view_runtimes
 	)
 
 var/list/admin_verbs_paranoid_debug = list(

code/modules/admin/topic.dm

@@ -1176,6 +1176,18 @@
 		sleep(2)
 		C.jumptomob(M)
 
+	else if(href_list["adminplayerobservefollow"])
+		if(!check_rights(R_MENTOR|R_MOD|R_ADMIN|R_SERVER))
+			return
+
+		var/mob/M = locate(href_list["adminplayerobservefollow"])
+
+		var/client/C = usr.client
+		if(!isobserver(usr))	C.admin_ghost()
+		var/mob/observer/dead/G = C.mob
+		sleep(2)
+		G.ManualFollow(M)
+
 	else if(href_list["check_antagonist"])
 		check_antagonists()
 

code/modules/admin/verbs/debug.dm

@@ -959,3 +959,13 @@
 		log_admin("[key_name(src)] has toggled [M.key]'s [blockname] block [state]!")
 	else
 		alert("Invalid mob")
+
+/datum/admins/proc/view_runtimes()
+	set category = "Debug"
+	set name = "View Runtimes"
+	set desc = "Open the Runtime Viewer"
+
+	if(!check_rights(R_DEBUG))
+		return
+
+	error_cache.showTo(usr)

code/modules/error_handler/_defines.dm

@@ -0,0 +1,9 @@
+// Settings for the error handler and error viewer
+
+#define ERROR_COOLDOWN 600 // The "cooldown" time for each occurrence of a unique error
+#define ERROR_LIMIT 9 // How many occurrences before the next will silence them
+#define ERROR_MAX_COOLDOWN (ERROR_COOLDOWN * ERROR_LIMIT)
+#define ERROR_SILENCE_TIME 6000 // How long a unique error will be silenced for
+
+// How long to wait between messaging admins about occurrences of a unique error
+#define ERROR_MSG_DELAY 50

code/modules/error_handler/error_handler.dm

@@ -0,0 +1,118 @@
+var/list/error_last_seen = list()
+// error_cooldown items will either be positive (cooldown time) or negative (silenced error)
+//  If negative, starts at -1, and goes down by 1 each time that error gets skipped
+var/list/error_cooldown = list()
+var/total_runtimes = 0
+var/total_runtimes_skipped = 0
+// The ifdef needs to be down here, since the error viewer references total_runtimes
+#ifdef DEBUG
+/world/Error(var/exception/e, var/datum/e_src)
+	if(!istype(e)) // Something threw an unusual exception
+		log_to_dd("\[[time_stamp()]] Uncaught exception: [e]")
+		return ..()
+	if(!error_last_seen) // A runtime is occurring too early in start-up initialization
+		return ..()
+	total_runtimes++
+
+	var/erroruid = "[e.file][e.line]"
+	var/last_seen = error_last_seen[erroruid]
+	var/cooldown = error_cooldown[erroruid] || 0
+	if(last_seen == null) // A new error!
+		error_last_seen[erroruid] = world.time
+		last_seen = world.time
+	if(cooldown < 0)
+		error_cooldown[erroruid]-- // Used to keep track of skip count for this error
+		total_runtimes_skipped++
+		return // Error is currently silenced, skip handling it
+
+	// Handle cooldowns and silencing spammy errors
+	var/silencing = 0
+	// Each occurrence of a unique error adds to its "cooldown" time...
+	cooldown = max(0, cooldown - (world.time - last_seen)) + ERROR_COOLDOWN
+	// ... which is used to silence an error if it occurs too often, too fast
+	if(cooldown > ERROR_MAX_COOLDOWN)
+		cooldown = -1
+		silencing = 1
+		spawn(0)
+			usr = null
+			sleep(ERROR_SILENCE_TIME)
+			var/skipcount = abs(error_cooldown[erroruid]) - 1
+			error_cooldown[erroruid] = 0
+			if(skipcount > 0)
+				log_to_dd("\[[time_stamp()]] Skipped [skipcount] runtimes in [e.file],[e.line].")
+				error_cache.logError(e, skipCount = skipcount)
+	error_last_seen[erroruid] = world.time
+	error_cooldown[erroruid] = cooldown
+
+	// The detailed error info needs some tweaking to make it look nice
+	var/list/srcinfo = null
+	var/list/usrinfo = null
+	var/locinfo
+	// 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]"
+	if(istype(usr))
+		usrinfo = list("  usr: [log_info_line(usr)]")
+		locinfo = log_info_line(usr)
+		if(locinfo)
+			usrinfo += "  usr.loc: [locinfo]"
+	// The proceeding mess will almost definitely break if error messages are ever changed
+	// I apologize in advance
+	var/list/splitlines = splittext(e.desc, "\n")
+	var/list/desclines = list()
+	if(splitlines.len > 2) // If there aren't at least three lines, there's no info
+		for(var/line in splitlines)
+			if(length(line) < 3)
+				continue // Blank line, skip it
+			if(findtext(line, "source file:"))
+				continue // Redundant, skip it
+			if(findtext(line, "usr.loc:"))
+				continue // Our usr.loc is better, skip it
+			if(findtext(line, "usr:"))
+				if(usrinfo)
+					desclines.Add(usrinfo)
+					usrinfo = null
+				continue // Our usr info is better, replace it
+			if(srcinfo)
+				if(findtext(line, "src.loc:"))
+					continue
+				if(findtext(line, "src:"))
+					desclines.Add(srcinfo)
+					srcinfo = null
+					continue
+			if(copytext(line, 1, 3) != "  ")
+				desclines += ("  " + line) // Pad any unpadded lines, so they look pretty
+			else
+				desclines += line
+	if(srcinfo) // If these aren't null, they haven't been added yet
+		desclines.Add(srcinfo)
+	if(usrinfo)
+		desclines.Add(usrinfo)
+	if(silencing)
+		desclines += "  (This error will now be silenced for [ERROR_SILENCE_TIME / 600] minutes)"
+
+	// Now to actually output the error info...
+	log_to_dd("\[[time_stamp()]] Runtime in [e.file],[e.line]: [e]")
+	for(var/line in desclines)
+		log_to_dd(line)
+	if(error_cache)
+		error_cache.logError(e, desclines, e_src = e_src)
+
+#endif
+
+/proc/log_runtime(exception/e, datum/e_src, extra_info)
+	if(!istype(e))
+		world.Error(e, e_src)
+		return
+
+	if(extra_info)
+		// Adding extra info adds two newlines, because parsing runtimes is funky
+		if(islist(extra_info))
+			e.desc = "  [jointext(extra_info, "\n  ")]\n\n" + e.desc
+		else
+			e.desc = "  [extra_info]\n\n" + e.desc
+
+	world.Error(e, e_src)

code/modules/error_handler/error_viewer.dm

@@ -0,0 +1,206 @@
+// Error viewing datums, responsible for storing error info, notifying admins
+// when errors occur, and showing them to admins on demand.
+
+// There are 3 different types used here:
+//
+// - ErrorCache keeps track of all error sources, as well as all individually
+//   logged errors. Only one instance of this datum should ever exist, and it's
+//   right here:
+
+#ifdef DEBUG
+var/global/datum/ErrorViewer/ErrorCache/error_cache = new()
+#else
+// If debugging is disabled, there's nothing useful to log, so don't bother.
+var/global/datum/ErrorViewer/ErrorCache/error_cache = null
+#endif
+
+// - ErrorSource datums exist for each line (of code) that generates an error,
+//   and keep track of all errors generated by that line.
+//
+// - ErrorEntry datums exist for each logged error, and keep track of all
+//   relevant info about that error.
+
+// Common vars and procs are kept at the ErrorViewer level
+/datum/ErrorViewer/
+	var/name = ""
+
+/datum/ErrorViewer/proc/browseTo(var/user, var/html)
+	if(user)
+		var/datum/browser/popup = new(user, "error_viewer", "Runtime Viewer", 700, 500)
+		popup.add_head_content({"<style>
+			.runtime{
+				background-color: #171717;
+				border: solid 1px #202020;
+				font-family:'Courier New',monospace;
+				font-size:9pt;
+				color: #DDDDDD;
+			}
+			p.runtime_list{
+				font-family:'Courier New',monospace;
+				font-size:9pt;
+				margin: 0;
+				padding: 0;
+				text-indent:-13ch;
+				margin-left:13ch;
+			}
+			</style>"})
+		popup.set_content(html)
+		popup.open(0)
+
+/datum/ErrorViewer/proc/buildHeader(var/datum/ErrorViewer/back_to, var/linear, var/refreshable)
+	// Common starter HTML for showTo
+	var/html = ""
+
+	if(istype(back_to))
+		html += "[back_to.makeLink("<<<", null, linear)] "
+	if(refreshable)
+		html += "[makeLink("Refresh", null, linear)]"
+	if(html)
+		html += "<br><br>"
+	return html
+
+/datum/ErrorViewer/proc/showTo(var/user, var/datum/ErrorViewer/back_to, var/linear)
+	// Specific to each child type
+	return
+
+/datum/ErrorViewer/proc/makeLink(var/linktext, var/datum/ErrorViewer/back_to, var/linear)
+	var/back_to_param = ""
+	if(!linktext)
+		linktext = name
+	if(istype(back_to))
+		back_to_param = ";viewruntime_backto=\ref[back_to]"
+	if(linear)
+		back_to_param += ";viewruntime_linear=1"
+	return "<A HREF='?src=\ref[src];viewruntime=\ref[src][back_to_param]'>[html_encode(linktext)]</A>"
+
+/datum/ErrorViewer/Topic(href, href_list)
+	if(..())
+		return 1
+	if(href_list["viewruntime_backto"])
+		showTo(usr, locate(href_list["viewruntime_backto"]), href_list["viewruntime_linear"])
+	else
+		showTo(usr, null, href_list["viewruntime_linear"])
+
+/datum/ErrorViewer/ErrorCache
+	var/list/errors = list()
+	var/list/error_sources = list()
+	var/list/errors_silenced = list()
+
+/datum/ErrorViewer/ErrorCache/showTo(var/user, var/datum/ErrorViewer/back_to, var/linear)
+	var/html = buildHeader(null, linear, refreshable=1)
+	html += "[total_runtimes] runtimes, [total_runtimes_skipped] skipped<br><br>"
+	if(!linear)
+		html += "organized | [makeLink("linear", null, 1)]<hr>"
+		var/datum/ErrorViewer/ErrorSource/error_source
+		for(var/erroruid in error_sources)
+			error_source = error_sources[erroruid]
+			html += "<p class='runtime_list'>[error_source.makeLink(null, src)]<br></p>"
+	else
+		html += "[makeLink("organized", null)] | linear<hr>"
+		for(var/datum/ErrorViewer/ErrorEntry/error_entry in errors)
+			html += "<p class='runtime_list'>[error_entry.makeLink(null, src, 1)]<br></p>"
+	browseTo(user, html)
+
+/datum/ErrorViewer/ErrorCache/proc/logError(var/exception/e, var/list/desclines, var/skipCount, var/datum/e_src)
+	if(!istype(e))
+		return // Abnormal exception, don't even bother
+
+	var/erroruid = "[e.file][e.line]"
+	var/datum/ErrorViewer/ErrorSource/error_source = error_sources[erroruid]
+	if(!error_source)
+		error_source = new(e)
+		error_sources[erroruid] = error_source
+
+	var/datum/ErrorViewer/ErrorEntry/error_entry = new(e, desclines, skipCount, e_src)
+	error_entry.error_source = error_source
+	errors += error_entry
+	error_source.errors += error_entry
+	if(skipCount)
+		return // Skip notifying admins about skipped errors
+
+	// Show the error to admins with debug messages turned on, but only if one
+	//  from the same source hasn't been shown too recently
+	// (Also, make sure config is initialized, or log_debug will runtime)
+	if(config && error_source.next_message_at <= world.time)
+		var/const/viewtext = "\[view]" // Nesting these in other brackets went poorly
+		log_debug("Runtime in [e.file],[e.line]: [html_encode(e.name)] [error_entry.makeLink(viewtext)]")
+		error_source.next_message_at = world.time + ERROR_MSG_DELAY
+
+/datum/ErrorViewer/ErrorSource
+	var/list/errors = list()
+	var/next_message_at = 0
+
+/datum/ErrorViewer/ErrorSource/New(var/exception/e)
+	if(!istype(e))
+		name = "\[[time_stamp()]] Uncaught exceptions"
+		return
+	name = "\[[time_stamp()]] Runtime in [e.file],[e.line]: [e]"
+
+/datum/ErrorViewer/ErrorSource/showTo(var/user, var/datum/ErrorViewer/back_to, var/linear)
+	if(!istype(back_to))
+		back_to = error_cache
+	var/html = buildHeader(back_to, refreshable=1)
+	for(var/datum/ErrorViewer/ErrorEntry/error_entry in errors)
+		html += "<p class='runtime_list'>[error_entry.makeLink(null, src)]<br></p>"
+	browseTo(user, html)
+
+/datum/ErrorViewer/ErrorEntry
+	var/datum/ErrorViewer/ErrorSource/error_source
+	var/exception/exc
+	var/desc = ""
+	var/srcRef
+	var/srcType
+	var/turf/srcLoc
+	var/usrRef
+	var/turf/usrLoc
+	var/isSkipCount
+
+/datum/ErrorViewer/ErrorEntry/New(var/exception/e, var/list/desclines, var/skipCount, var/datum/e_src)
+	if(!istype(e))
+		name = "\[[time_stamp()]] Uncaught exception: [e]"
+		return
+	if(skipCount)
+		name = "\[[time_stamp()]] Skipped [skipCount] runtimes in [e.file],[e.line]."
+		isSkipCount = TRUE
+		return
+	name = "\[[time_stamp()]] Runtime in [e.file],[e.line]: [e]"
+	exc = e
+	if(istype(desclines))
+		for(var/line in desclines)
+			// There's probably a better way to do this than non-breaking spaces...
+			desc += "&nbsp;&nbsp;" + html_encode(line) + "<br>"
+	if(istype(e_src))
+		srcRef = "\ref[e_src]"
+		srcType = e_src.type
+		srcLoc = get_turf(e_src)
+	if(usr)
+		usrRef = "\ref[usr]"
+		usrLoc = get_turf(usr)
+
+/datum/ErrorViewer/ErrorEntry/showTo(var/user, var/datum/ErrorViewer/back_to, var/linear)
+	if(!istype(back_to))
+		back_to = error_source
+	var/html = buildHeader(back_to, linear)
+	html += "<div class='runtime'>[html_encode(name)]<br>[desc]</div>"
+	if(srcRef)
+		html += "<br>src: <a href='?_src_=vars;Vars=[srcRef]'>VV</a>"
+		if(ispath(srcType, /mob))
+			html += " <a href='?_src_=holder;adminplayeropts=[srcRef]'>PP</a>"
+			html += " <a href='?_src_=holder;adminplayerobservefollow=[srcRef]'>Follow</a>"
+		if(istype(srcLoc))
+			html += "<br>src.loc: <a href='?_src_=vars;Vars=\ref[srcLoc]'>VV</a>"
+			html += " <a href='?_src_=holder;adminplayerobservecoodjump=1;X=[srcLoc.x];Y=[srcLoc.y];Z=[srcLoc.z]'>JMP</a>"
+	if(usrRef)
+		html += "<br>usr: <a href='?_src_=vars;Vars=[usrRef]'>VV</a>"
+		html += " <a href='?_src_=holder;adminplayeropts=[usrRef]'>PP</a>"
+		html += " <a href='?_src_=holder;adminplayerobservefollow=[usrRef]'>Follow</a>"
+		if(istype(usrLoc))
+			html += "<br>usr.loc: <a href='?_src_=vars;Vars=\ref[usrLoc]'>VV</a>"
+			html += " <a href='?_src_=holder;adminplayerobservecoodjump=1;X=[usrLoc.x];Y=[usrLoc.y];Z=[usrLoc.z]'>JMP</a>"
+	browseTo(user, html)
+
+/datum/ErrorViewer/ErrorEntry/makeLink(var/linktext, var/datum/ErrorViewer/back_to, var/linear)
+	if(isSkipCount)
+		return html_encode(name)
+	else
+		return ..()

code/modules/error_handler/~defines.dm

@@ -0,0 +1,6 @@
+// Settings for the error handler and error viewer
+#undef ERROR_COOLDOWN
+#undef ERROR_LIMIT
+#undef ERROR_MAX_COOLDOWN
+#undef ERROR_SILENCE_TIME
+#undef ERROR_MSG_DELAY

polaris.dme

@@ -1274,6 +1274,10 @@
 #include "code\modules\economy\price_list.dm"
 #include "code\modules\economy\retail_scanner.dm"
 #include "code\modules\economy\TradeDestinations.dm"
+#include "code\modules\error_handler\_defines.dm"
+#include "code\modules\error_handler\error_handler.dm"
+#include "code\modules\error_handler\error_viewer.dm"
+#include "code\modules\error_handler\~defines.dm"
 #include "code\modules\events\apc_damage.dm"
 #include "code\modules\events\blob.dm"
 #include "code\modules\events\brand_intelligence.dm"