mirror of
https://github.com/CHOMPStation2/CHOMPStation2.git
synced 2025-12-12 19:22:56 +00:00
[MIRROR] JSON Logging Refactor (#11623)
Co-authored-by: Selis <12716288+ItsSelis@users.noreply.github.com> Co-authored-by: Kashargul <144968721+Kashargul@users.noreply.github.com>
This commit is contained in:
CHOMPStation2StaffMirrorBot
committed by
GitHub
GitHub
parent
272afa33c8
commit
5a62077f2c
@@ -1,135 +1,156 @@
|
||||
// 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
|
||||
GLOBAL_VAR_INIT(total_runtimes, 0)
|
||||
GLOBAL_VAR_INIT(total_runtimes, GLOB.total_runtimes || 0)
|
||||
GLOBAL_VAR_INIT(total_runtimes_skipped, 0)
|
||||
|
||||
#ifdef USE_CUSTOM_ERROR_HANDLER
|
||||
#define ERROR_USEFUL_LEN 2
|
||||
|
||||
// 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)
|
||||
GLOB.total_runtimes++ //CHOMPEdit just moving this here to start counting right away
|
||||
if(!istype(e)) // Something threw an unusual exception
|
||||
log_error("\[[time_stamp()]] Uncaught exception: [e]")
|
||||
/world/Error(exception/E, datum/e_src)
|
||||
GLOB.total_runtimes++
|
||||
|
||||
if(!istype(E)) //Something threw an unusual exception
|
||||
log_world("uncaught runtime error: [E]")
|
||||
return ..()
|
||||
|
||||
//CHOMP Edit Stealing this bit from TGStation to try to record OOM issues.
|
||||
//this is snowflake because of a byond bug (ID:2306577), do not attempt to call non-builtin procs in this if
|
||||
if(copytext(e.name,1,32) == "Maximum recursion level reached")
|
||||
if(copytext(E.name, 1, 32) == "Maximum recursion level reached")//32 == length() of that string + 1
|
||||
//log to world while intentionally triggering the byond bug.
|
||||
log_world("runtime error: [e.name]\n[e.desc]")
|
||||
log_world("runtime error: [E.name]\n[E.desc]")
|
||||
//if we got to here without silently ending, the byond bug has been fixed.
|
||||
log_world("The bug with recursion runtimes has been fixed. Please remove the snowflake check from world/Error in [__FILE__]:[__LINE__]")
|
||||
return //this will never happen.
|
||||
|
||||
else if(copytext(e.name,1,18) == "Out of resources!")
|
||||
log_world("BYOND out of memory.")
|
||||
log_game("BYOND out of memory.")
|
||||
return ..()
|
||||
//CHOMP Edit end
|
||||
else if(copytext(E.name, 1, 18) == "Out of resources!")//18 == length() of that string + 1
|
||||
log_world("BYOND out of memory. Restarting ([E?.file]:[E?.line])")
|
||||
TgsEndProcess()
|
||||
. = ..()
|
||||
Reboot(reason = 1)
|
||||
return
|
||||
|
||||
if(!GLOB.error_last_seen) // A runtime is occurring too early in start-up initialization
|
||||
var/static/regex/stack_workaround
|
||||
if(isnull(stack_workaround))
|
||||
stack_workaround = regex("[WORKAROUND_IDENTIFIER](.+?)[WORKAROUND_IDENTIFIER]")
|
||||
var/static/list/error_last_seen = list()
|
||||
var/static/list/error_cooldown = 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*/
|
||||
|
||||
if(!error_last_seen) // A runtime is occurring too early in start-up initialization
|
||||
return ..()
|
||||
|
||||
if(stack_workaround.Find(E.name))
|
||||
var/list/data = json_decode(stack_workaround.group[1])
|
||||
E.file = data[1]
|
||||
E.line = data[2]
|
||||
E.name = stack_workaround.Replace(E.name, "")
|
||||
|
||||
var/erroruid = "[e.file][e.line]"
|
||||
var/last_seen = GLOB.error_last_seen[erroruid]
|
||||
var/cooldown = GLOB.error_cooldown[erroruid] || 0
|
||||
if(last_seen == null) // A new error!
|
||||
GLOB.error_last_seen[erroruid] = world.time
|
||||
var/erroruid = "[E.file][E.line]"
|
||||
var/last_seen = error_last_seen[erroruid]
|
||||
var/cooldown = error_cooldown[erroruid] || 0
|
||||
|
||||
if(last_seen == null)
|
||||
error_last_seen[erroruid] = world.time
|
||||
last_seen = world.time
|
||||
if(cooldown < 0)
|
||||
GLOB.error_cooldown[erroruid]-- // Used to keep track of skip count for this error
|
||||
GLOB.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
|
||||
if(cooldown < 0)
|
||||
error_cooldown[erroruid]-- //Used to keep track of skip count for this error
|
||||
GLOB.total_runtimes_skipped++
|
||||
return //Error is currently silenced, skip handling it
|
||||
//Handle cooldowns and silencing spammy errors
|
||||
var/silencing = FALSE
|
||||
|
||||
// We can runtime before config is initialized because BYOND initialize objs/map before a bunch of other stuff happens.
|
||||
// This is a bunch of workaround code for that. Hooray!
|
||||
var/configured_error_cooldown
|
||||
var/configured_error_limit
|
||||
var/configured_error_silence_time
|
||||
if(config?.entries)
|
||||
configured_error_cooldown = CONFIG_GET(number/error_cooldown)
|
||||
configured_error_limit = CONFIG_GET(number/error_limit)
|
||||
configured_error_silence_time = CONFIG_GET(number/error_silence_time)
|
||||
else
|
||||
var/datum/config_entry/CE = /datum/config_entry/number/error_cooldown
|
||||
configured_error_cooldown = initial(CE.default)
|
||||
CE = /datum/config_entry/number/error_limit
|
||||
configured_error_limit = initial(CE.default)
|
||||
CE = /datum/config_entry/number/error_silence_time
|
||||
configured_error_silence_time = initial(CE.default)
|
||||
|
||||
|
||||
//Each occurence of a unique error adds to its cooldown time...
|
||||
cooldown = max(0, cooldown - (world.time - last_seen)) + configured_error_cooldown
|
||||
// ... which is used to silence an error if it occurs too often, too fast
|
||||
if(cooldown > ERROR_MAX_COOLDOWN)
|
||||
if(cooldown > configured_error_cooldown * configured_error_limit)
|
||||
cooldown = -1
|
||||
silencing = 1
|
||||
silencing = TRUE
|
||||
spawn(0)
|
||||
usr = null
|
||||
sleep(ERROR_SILENCE_TIME)
|
||||
var/skipcount = abs(GLOB.error_cooldown[erroruid]) - 1
|
||||
GLOB.error_cooldown[erroruid] = 0
|
||||
sleep(configured_error_silence_time)
|
||||
var/skipcount = abs(error_cooldown[erroruid]) - 1
|
||||
error_cooldown[erroruid] = 0
|
||||
if(skipcount > 0)
|
||||
log_error("\[[time_stamp()]] Skipped [skipcount] runtimes in [e.file],[e.line].")
|
||||
error_cache.logError(e, skipCount = skipcount)
|
||||
GLOB.error_last_seen[erroruid] = world.time
|
||||
GLOB.error_cooldown[erroruid] = cooldown
|
||||
SEND_TEXT(world.log, "\[[time_stamp()]] Skipped [skipcount] runtimes in [E.file],[E.line].")
|
||||
GLOB.error_cache.log_error(E, skip_count = 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)]")
|
||||
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.loc)
|
||||
usrinfo = list(" usr: [key_name(usr)]")
|
||||
locinfo = loc_name(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/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
|
||||
#ifndef DISABLE_DREAMLUAU
|
||||
var/list/state_stack = GLOB.lua_state_stack
|
||||
var/is_lua_call = length(state_stack)
|
||||
var/list/lua_stacks = list()
|
||||
if(is_lua_call)
|
||||
for(var/level in 1 to state_stack.len)
|
||||
lua_stacks += list(splittext(DREAMLUAU_GET_TRACEBACK(level), "\n"))
|
||||
#endif
|
||||
if(LAZYLEN(splitlines) > ERROR_USEFUL_LEN) // 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(LAZYLEN(line) < 3 || findtext(line, "source file:") || findtext(line, "usr.loc:"))
|
||||
continue
|
||||
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) != " ")
|
||||
if(copytext(line, 1, 3) != " ")//3 == length(" ") + 1
|
||||
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)
|
||||
if(usrinfo) //If this info isn't null, it hasn't been added yet
|
||||
desclines.Add(usrinfo)
|
||||
#ifndef DISABLE_DREAMLUAU
|
||||
if(is_lua_call)
|
||||
SSlua.log_involved_runtime(E, desclines, lua_stacks)
|
||||
#endif
|
||||
if(silencing)
|
||||
desclines += " (This error will now be silenced for [ERROR_SILENCE_TIME / 600] minutes)"
|
||||
desclines += " (This error will now be silenced for [DisplayTimeText(configured_error_silence_time)])"
|
||||
if(GLOB.error_cache)
|
||||
GLOB.error_cache.log_error(E, desclines)
|
||||
|
||||
// Now to actually output the error info...
|
||||
log_error("\[[time_stamp()]] Runtime in [e.file],[e.line]: [e]")
|
||||
var/main_line = "\[[time_stamp()]] Runtime in [E.file],[E.line]: [E]"
|
||||
SEND_TEXT(world.log, main_line)
|
||||
for(var/line in desclines)
|
||||
log_error(line)
|
||||
if(error_cache)
|
||||
error_cache.logError(e, desclines, e_src = e_src)
|
||||
SEND_TEXT(world.log, line)
|
||||
|
||||
#ifdef UNIT_TESTS
|
||||
if(GLOB.current_test)
|
||||
//good day, sir
|
||||
GLOB.current_test.Fail("[main_line]\n[desclines.Join("\n")]", file = E.file, line = E.line)
|
||||
#endif
|
||||
|
||||
/proc/log_runtime(exception/e, datum/e_src, extra_info)
|
||||
if(!istype(e))
|
||||
world.Error(e, e_src)
|
||||
return
|
||||
//if(Debugger?.enabled)
|
||||
// to_chat(world, span_alertwarning("[main_line]"), type = MESSAGE_TYPE_DEBUG)
|
||||
|
||||
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
|
||||
// This writes the regular format (unwrapping newlines and inserting timestamps as needed).
|
||||
log_runtime("runtime error: [E.name]\n[E.desc]")
|
||||
#endif
|
||||
|
||||
world.Error(e, e_src)
|
||||
#undef ERROR_USEFUL_LEN
|
||||
|
||||
Reference in New Issue
Block a user