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
🆑
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
/🆑

---------

Co-authored-by: Zephyr <12817816+ZephyrTFA@users.noreply.github.com>
This commit is contained in:
LemonInTheDark
2023-05-26 12:40:18 -06:00
committed by GitHub
co-authored by Zephyr
parent 08484b259f
commit b304b6523f
8 changed files with 57 additions and 27 deletions
+7 -1
View File
@@ -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
+2 -3
View File
@@ -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)
-1
View File
@@ -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)
+19 -15
View File
@@ -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
@@ -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
@@ -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
+5
View File
@@ -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,
)
+17 -3
View File
@@ -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()