From b304b6523fa1f497800c8ba3818e4d2c01d4eaf4 Mon Sep 17 00:00:00 2001 From: LemonInTheDark <58055496+LemonInTheDark@users.noreply.github.com> Date: Fri, 26 May 2023 11:40:18 -0700 Subject: [PATCH] Converts del logging to proper json, using json objects instead of building a text file (#75636) ## About The Pull Request It's easier to parse, and makes more sense when you read it. This way I'll never have to add yet another case to my parser for someone changing where a space goes or something. Moves qdel into its own category cause the old name looked ugly (yell if this is dumb) Added a bitfield to entries pulled from categories, adds a new flag that enables pretty printing json lists. ## Why It's Good For The Game IMPROVES my workflow ## Changelog :cl: server: del logging is now done by outputting to a json file again, but this time we're using ACTUAL json and not just a big text string with newlines and shit /:cl: --------- Co-authored-by: Zephyr <12817816+ZephyrTFA@users.noreply.github.com> --- code/__DEFINES/logging.dm | 8 ++++- code/__HELPERS/logging/debug.dm | 5 ++- code/_globalvars/logging.dm | 1 - code/controllers/subsystem/garbage.dm | 34 +++++++++++-------- .../logging/categories/log_category_debug.dm | 4 --- .../logging/categories/log_category_misc.dm | 7 ++++ code/modules/logging/log_category.dm | 5 +++ code/modules/logging/log_entry.dm | 20 +++++++++-- 8 files changed, 57 insertions(+), 27 deletions(-) diff --git a/code/__DEFINES/logging.dm b/code/__DEFINES/logging.dm index 9cfe197c0ca..0883e7e5cbc 100644 --- a/code/__DEFINES/logging.dm +++ b/code/__DEFINES/logging.dm @@ -89,6 +89,7 @@ #define LOG_CATEGORY_TELECOMMS "telecomms" #define LOG_CATEGORY_TOOL "tool" #define LOG_CATEGORY_VIRUS "virus" +#define LOG_CATEGORY_QDEL "qdel" // Admin categories #define LOG_CATEGORY_ADMIN "admin" @@ -107,7 +108,6 @@ #define LOG_CATEGORY_DEBUG_LUA "debug-lua" #define LOG_CATEGORY_DEBUG_MAPPING "debug-mapping" #define LOG_CATEGORY_DEBUG_MOBTAG "debug-mobtag" -#define LOG_CATEGORY_DEBUG_QDEL "debug-qdel" #define LOG_CATEGORY_DEBUG_SQL "debug-sql" #define LOG_CATEGORY_DEBUG_TGUI "debug-tgui" @@ -140,6 +140,12 @@ #define LOG_CATEGORY_PDA_CHAT "pda-chat" #define LOG_CATEGORY_PDA_COMMENT "pda-comment" +// Flags that apply to the entry_flags var on logging categories +// These effect how entry datums process the inputs passed into them +/// Enables data list usage for readable log entries +/// You'll likely want to disable internal formatting to make this work properly +#define ENTRY_USE_DATA_W_READABLE (1<<0) + #define SCHEMA_VERSION "schema-version" // Default log schema version diff --git a/code/__HELPERS/logging/debug.dm b/code/__HELPERS/logging/debug.dm index 1a2685e0092..c4ed2f1086f 100644 --- a/code/__HELPERS/logging/debug.dm +++ b/code/__HELPERS/logging/debug.dm @@ -35,9 +35,8 @@ WRITE_LOG_NO_FORMAT(GLOB.perf_log, .) /// Logging for hard deletes -/// Done once, at roundend. Really just a text file -/proc/log_qdel(text) - WRITE_LOG(GLOB.world_qdel_log, "QDEL: [text]") +/proc/log_qdel(text, list/data) + logger.Log(LOG_CATEGORY_QDEL, text, data) /* Log to the logfile only. */ /proc/log_runtime(text, list/data) diff --git a/code/_globalvars/logging.dm b/code/_globalvars/logging.dm index 52ea9067421..4d0b0698679 100644 --- a/code/_globalvars/logging.dm +++ b/code/_globalvars/logging.dm @@ -32,7 +32,6 @@ GLOBAL_PROTECT(##log_var_name);\ // These should be used where the log category cannot easily be a json log file. DECLARE_LOG(config_error_log, DONT_START_LOG) DECLARE_LOG(perf_log, DONT_START_LOG) // Declared here but name is set in time_track subsystem -DECLARE_LOG_NAMED(world_qdel_log, "qdel", START_LOG) #ifdef REFERENCE_DOING_IT_LIVE DECLARE_LOG_NAMED(harddel_log, "harddels", START_LOG) diff --git a/code/controllers/subsystem/garbage.dm b/code/controllers/subsystem/garbage.dm index 6d297998fef..086fcd760c5 100644 --- a/code/controllers/subsystem/garbage.dm +++ b/code/controllers/subsystem/garbage.dm @@ -82,32 +82,36 @@ SUBSYSTEM_DEF(garbage) /datum/controller/subsystem/garbage/Shutdown() //Adds the del() log to the qdel log file - var/list/dellog = list() + var/list/del_log = list() //sort by how long it's wasted hard deleting sortTim(items, cmp=/proc/cmp_qdel_item_time, associative = TRUE) for(var/path in items) var/datum/qdel_item/I = items[path] - dellog += "Path: [path]" + var/list/entry = list() + del_log[path] = entry + if (I.qdel_flags & QDEL_ITEM_SUSPENDED_FOR_LAG) - dellog += "\tSUSPENDED FOR LAG" + entry["SUSPENDED FOR LAG"] = TRUE if (I.failures) - dellog += "\tFailures: [I.failures]" - dellog += "\tqdel() Count: [I.qdels]" - dellog += "\tDestroy() Cost: [I.destroy_time]ms" + entry["Failures"] = I.failures + entry["qdel() Count"] = I.qdels + entry["Destroy() Cost (ms)"] = I.destroy_time + if (I.hard_deletes) - dellog += "\tTotal Hard Deletes: [I.hard_deletes]" - dellog += "\tTime Spent Hard Deleting: [I.hard_delete_time]ms" - dellog += "\tHighest Time Spent Hard Deleting: [I.hard_delete_max]ms" + entry["Total Hard Deletes"] = I.hard_deletes + entry["Time Spend Hard Deleting (ms)"] = I.hard_delete_time + entry["Highest Time Spend Hard Deleting (ms)"] = I.hard_delete_max if (I.hard_deletes_over_threshold) - dellog += "\tHard Deletes Over Threshold: [I.hard_deletes_over_threshold]" + entry["Hard Deletes Over Threshold"] = I.hard_deletes_over_threshold if (I.slept_destroy) - dellog += "\tSleeps: [I.slept_destroy]" + entry["Total Sleeps"] = I.slept_destroy if (I.no_respect_force) - dellog += "\tIgnored force: [I.no_respect_force] times" + entry["Total Ignored Force"] = I.no_respect_force if (I.no_hint) - dellog += "\tNo hint: [I.no_hint] times" - log_qdel(dellog.Join("\n")) + entry["Total No Hint"] = I.no_hint + + log_qdel("", del_log) /datum/controller/subsystem/garbage/fire() //the fact that this resets its processing each fire (rather then resume where it left off) is intentional. @@ -278,7 +282,7 @@ SUBSYSTEM_DEF(garbage) #endif if (D.gc_destroyed <= 0) D.gc_destroyed = queue_time - + var/list/queue = queues[level] queue[++queue.len] = list(queue_time, refid, D.gc_destroyed) // not += for byond reasons diff --git a/code/modules/logging/categories/log_category_debug.dm b/code/modules/logging/categories/log_category_debug.dm index 417a56773d6..03b7d519547 100644 --- a/code/modules/logging/categories/log_category_debug.dm +++ b/code/modules/logging/categories/log_category_debug.dm @@ -39,7 +39,3 @@ category = LOG_CATEGORY_DEBUG_ASSET config_flag = /datum/config_entry/flag/log_asset master_category = /datum/log_category/debug - -/datum/log_category/debug_qdel - category = LOG_CATEGORY_DEBUG_QDEL - master_category = /datum/log_category/debug diff --git a/code/modules/logging/categories/log_category_misc.dm b/code/modules/logging/categories/log_category_misc.dm index 5cc77fed203..b24d13e94ec 100644 --- a/code/modules/logging/categories/log_category_misc.dm +++ b/code/modules/logging/categories/log_category_misc.dm @@ -56,3 +56,10 @@ /datum/log_category/speech_indicator category = LOG_CATEGORY_SPEECH_INDICATOR config_flag = /datum/config_entry/flag/log_speech_indicators + +// Logs seperately, printed into on server shutdown to store hard deletes and such +/datum/log_category/debug_qdel + category = LOG_CATEGORY_QDEL + // We want this human readable so it's easy to see at a glance + entry_flags = ENTRY_USE_DATA_W_READABLE + internal_formatting = FALSE diff --git a/code/modules/logging/log_category.dm b/code/modules/logging/log_category.dm index 82dcc57d0fe..fe86491b902 100644 --- a/code/modules/logging/log_category.dm +++ b/code/modules/logging/log_category.dm @@ -10,6 +10,10 @@ /// The master category that contains this category var/datum/log_category/master_category + /// Flags to apply to our /datum/log_entry's + /// See code/__DEFINES/logging/dm + var/entry_flags = NONE + /// If set this config flag is checked to enable this log category var/config_flag @@ -32,6 +36,7 @@ GENERAL_PROTECT_DATUM(/datum/log_category) timestamp = logger.human_readable_timestamp(), category = category, message = message, + flags = entry_flags, data = data, semver_store = semver_store, ) diff --git a/code/modules/logging/log_entry.dm b/code/modules/logging/log_entry.dm index 0f47cef6796..4b5bf19775b 100644 --- a/code/modules/logging/log_entry.dm +++ b/code/modules/logging/log_entry.dm @@ -24,6 +24,10 @@ /// Message of the log entry. var/message + /// Bitfield that describes how exactly to log stuff exactly + /// See code/__DEFINES/logging/dm + var/flags = NONE + /// Data of the log entry; optional. var/list/data @@ -32,12 +36,13 @@ GENERAL_PROTECT_DATUM(/datum/log_entry) -/datum/log_entry/New(timestamp, category, message, list/data, list/semver_store) +/datum/log_entry/New(timestamp, category, message, flags, list/data, list/semver_store) ..() src.id = next_id++ src.timestamp = timestamp src.category = category + src.flags = flags src.message = message with_data(data) with_semver_store(semver_store) @@ -62,10 +67,19 @@ GENERAL_PROTECT_DATUM(/datum/log_entry) /// Converts the log entry to a human-readable string. /datum/log_entry/proc/to_readable_text(format = TRUE) + var/output = "" if(format) - return "\[[timestamp]\] [uppertext(category)]: [message]" + output += "\[[timestamp]\] [uppertext(category)]: [message]" else - return "[message]" + output += "[message]" + + if(flags & ENTRY_USE_DATA_W_READABLE) +#if DM_VERSION >= 515 + output += json_encode(data, JSON_PRETTY_PRINT) +#else + output += json_encode(data) +#endif + return output /// Converts the log entry to a JSON string. /datum/log_entry/proc/to_json_text()