From ef2385fe86409ddf2a83a7056e12374bbf7bb9dd Mon Sep 17 00:00:00 2001 From: SkyratBot <59378654+SkyratBot@users.noreply.github.com> Date: Sun, 10 Dec 2023 03:59:23 +0100 Subject: [PATCH] [MIRROR] Logging fixes and catches [MDB IGNORE] (#25537) * Logging fixes and catches (#79621) THIS IS A REDO BECAUSE GITHUB SUCKS ASS ## About The Pull Request Hardens logging against sudden and unexpected cases where we try to log to a category that is not initialized or the file goes missing. ## Why It's Good For The Game Logging needs to be robust and bullet proof * Logging fixes and catches --------- Co-authored-by: Zephyr <12817816+ZephyrTFA@users.noreply.github.com> --- code/__DEFINES/_protect.dm | 4 ++ code/__DEFINES/logging.dm | 5 +- .../categories/log_category_internal.dm | 6 +++ code/modules/logging/log_category.dm | 7 ++- code/modules/logging/log_entry.dm | 24 ++++++++-- code/modules/logging/log_holder.dm | 47 ++++++++++++++++--- tgstation.dme | 1 + 7 files changed, 77 insertions(+), 17 deletions(-) create mode 100644 code/modules/logging/categories/log_category_internal.dm diff --git a/code/__DEFINES/_protect.dm b/code/__DEFINES/_protect.dm index 22fad2f6385..9152cfcb570 100644 --- a/code/__DEFINES/_protect.dm +++ b/code/__DEFINES/_protect.dm @@ -1,4 +1,5 @@ ///Protects a datum from being VV'd or spawned through admin manipulation +#ifndef TESTING #define GENERAL_PROTECT_DATUM(Path)\ ##Path/can_vv_get(var_name){\ return FALSE;\ @@ -15,3 +16,6 @@ ##Path/Write(savefile/savefile){\ return;\ } +#else +#define GENERAL_PROTECT_DATUM(Path) +#endif diff --git a/code/__DEFINES/logging.dm b/code/__DEFINES/logging.dm index daec53a76ec..a6102aa6e79 100644 --- a/code/__DEFINES/logging.dm +++ b/code/__DEFINES/logging.dm @@ -88,8 +88,9 @@ #define LOG_ENTRY_KEY_ID "id" #define LOG_ENTRY_KEY_SCHEMA_VERSION "s-ver" -// Category for invalid/missing categories -#define LOG_CATEGORY_NOT_FOUND "invalid-category" +// Internal categories +#define LOG_CATEGORY_INTERNAL_CATEGORY_NOT_FOUND "internal-category-not-found" +#define LOG_CATEGORY_INTERNAL_ERROR "internal-error" // Misc categories #define LOG_CATEGORY_ATTACK "attack" diff --git a/code/modules/logging/categories/log_category_internal.dm b/code/modules/logging/categories/log_category_internal.dm new file mode 100644 index 00000000000..d0b363e6365 --- /dev/null +++ b/code/modules/logging/categories/log_category_internal.dm @@ -0,0 +1,6 @@ +/datum/log_category/internal + category = LOG_CATEGORY_INTERNAL_ERROR + +/datum/log_category/internal_unknown_category + category = LOG_CATEGORY_INTERNAL_CATEGORY_NOT_FOUND + master_category = /datum/log_category/internal diff --git a/code/modules/logging/log_category.dm b/code/modules/logging/log_category.dm index 96849ff02c8..363fb5ad0be 100644 --- a/code/modules/logging/log_category.dm +++ b/code/modules/logging/log_category.dm @@ -20,6 +20,9 @@ /// Whether or not this log should not be publically visible var/secret = FALSE + /// The list of header information for this category. Used for log file re-initialization + var/list/category_header + /// Whether the readable version of the log message is formatted internally instead of by rustg /// IF YOU CHANGE THIS VERIFY LOGS ARE STILL PARSED CORRECTLY var/internal_formatting = FALSE @@ -32,10 +35,6 @@ GENERAL_PROTECT_DATUM(/datum/log_category) -/// Backup log category to catch attempts to log to a category that doesn't exist -/datum/log_category/backup_category_not_found - category = LOG_CATEGORY_NOT_FOUND - /// Add an entry to this category. It is very important that any data you provide doesn't hold references to anything! /datum/log_category/proc/create_entry(message, list/data, list/semver_store) var/datum/log_entry/entry = new( diff --git a/code/modules/logging/log_entry.dm b/code/modules/logging/log_entry.dm index 3de4e543d1a..8c9f6bd2cf0 100644 --- a/code/modules/logging/log_entry.dm +++ b/code/modules/logging/log_entry.dm @@ -95,19 +95,33 @@ GENERAL_PROTECT_DATUM(/datum/log_entry) #undef MANUAL_JSON_ENTRY +#define CHECK_AND_TRY_FILE_ERROR_RECOVERY(file) \ + var/static/in_error_recovery = FALSE; \ + if(!fexists(##file)) { \ + if(in_error_recovery) { \ + in_error_recovery = FALSE; \ + CRASH("Failed to error recover log file: [file]"); \ + }; \ + in_error_recovery = TRUE; \ + logger.Log(LOG_CATEGORY_INTERNAL_ERROR, "attempting to perform file error recovery: [file]"); \ + logger.init_category_file(logger.log_categories[category]); \ + call(src, __PROC__)(arglist(args)); \ + return; \ + }; \ + in_error_recovery = FALSE; + /// Writes the log entry to a file. /datum/log_entry/proc/write_entry_to_file(file) - if(!fexists(file)) - CRASH("Attempted to log to an uninitialized file: [file]") + CHECK_AND_TRY_FILE_ERROR_RECOVERY(file) WRITE_LOG_NO_FORMAT(file, "[to_json_text()]\n") /// Writes the log entry to a file as a human-readable string. /datum/log_entry/proc/write_readable_entry_to_file(file, format_internally = TRUE) - if(!fexists(file)) - CRASH("Attempted to log to an uninitialized file: [file]") - + CHECK_AND_TRY_FILE_ERROR_RECOVERY(file) // If it's being formatted internally we need to manually add a newline if(format_internally) WRITE_LOG_NO_FORMAT(file, "[to_readable_text(format = TRUE)]\n") else WRITE_LOG(file, "[to_readable_text(format = FALSE)]") + +#undef CHECK_AND_TRY_FILE_ERROR_RECOVERY diff --git a/code/modules/logging/log_holder.dm b/code/modules/logging/log_holder.dm index 1cea0e554be..b378e4b8ef3 100644 --- a/code/modules/logging/log_holder.dm +++ b/code/modules/logging/log_holder.dm @@ -107,7 +107,7 @@ GENERAL_PROTECT_DATUM(/datum/log_holder) return switch(action) - if("refresh") + if("re-render") cache_ui_data() SStgui.update_uis(src) return TRUE @@ -206,6 +206,42 @@ GENERAL_PROTECT_DATUM(/datum/log_holder) return category_tree +/// Log entry header used to mark a file is being reset +#define LOG_CATEGORY_RESET_FILE_MARKER "{\"LOG FILE RESET -- THIS IS AN ERROR\"}" +#define LOG_CATEGORY_RESET_FILE_MARKER_READABLE "LOG FILE RESET -- THIS IS AN ERROR" +/// Gets a recovery file for the given path. Caches the last known recovery path for each path. +/datum/log_holder/proc/get_recovery_file_for(path) + var/static/cache + if(isnull(cache)) + cache = list() + + var/count = cache[path] || 0 + while(fexists("[path].rec[count]")) + count++ + cache[path] = count + + return "[path].rec[count]" + +/// Sets up the given category's file and header. +/datum/log_holder/proc/init_category_file(datum/log_category/category) + var/file_path = category.get_output_file(null) + if(fexists(file_path)) // already exists? implant a reset marker + rustg_file_append(LOG_CATEGORY_RESET_FILE_MARKER, file_path) + fcopy(file_path, get_recovery_file_for(file_path)) + rustg_file_write("[json_encode(category.category_header)]\n", file_path) + + if(!human_readable_enabled) + return + + file_path = category.get_output_file(null, "log") + if(fexists(file_path)) + rustg_file_append(LOG_CATEGORY_RESET_FILE_MARKER_READABLE, file_path) + fcopy(file_path, get_recovery_file_for(file_path)) + rustg_file_write("\[[human_readable_timestamp()]\] Starting up round ID [round_id].\n - -------------------------\n", file_path) + +#undef LOG_CATEGORY_RESET_FILE_MARKER +#undef LOG_CATEGORY_RESET_FILE_MARKER_READABLE + /// Initializes the given log category and populates the list of contained categories based on the sub category list /datum/log_holder/proc/init_log_category(datum/log_category/category_type, list/datum/log_category/sub_categories) var/datum/log_category/category_instance = new category_type @@ -239,9 +275,8 @@ GENERAL_PROTECT_DATUM(/datum/log_holder) LOG_HEADER_CATEGORY = category_instance.category, ) - rustg_file_write("[json_encode(category_header)]\n", category_instance.get_output_file(null)) - if(human_readable_enabled) - rustg_file_write("\[[human_readable_timestamp()]\] Starting up round ID [round_id].\n - -------------------------\n", category_instance.get_output_file(null, "log")) + category_instance.category_header = category_header + init_category_file(category_instance, category_header) /datum/log_holder/proc/human_readable_timestamp(precision = 3) var/start = time2text(world.timeofday, "YYYY-MM-DD hh:mm:ss") @@ -270,7 +305,7 @@ GENERAL_PROTECT_DATUM(/datum/log_holder) stack_trace("Logging with a non-text message") if(!category) - category = LOG_CATEGORY_NOT_FOUND + category = LOG_CATEGORY_INTERNAL_CATEGORY_NOT_FOUND stack_trace("Logging with a null or empty category") if(data && !islist(data)) @@ -286,7 +321,7 @@ GENERAL_PROTECT_DATUM(/datum/log_holder) var/datum/log_category/log_category = log_categories[category] if(!log_category) - Log(LOG_CATEGORY_NOT_FOUND, message, data) + Log(LOG_CATEGORY_INTERNAL_CATEGORY_NOT_FOUND, message, data) CRASH("Attempted to log to a category that doesn't exist! [category]") var/list/semver_store = null diff --git a/tgstation.dme b/tgstation.dme index 5878df2e0ec..8df2465cd94 100644 --- a/tgstation.dme +++ b/tgstation.dme @@ -4357,6 +4357,7 @@ #include "code\modules\logging\categories\log_category_debug.dm" #include "code\modules\logging\categories\log_category_game.dm" #include "code\modules\logging\categories\log_category_href.dm" +#include "code\modules\logging\categories\log_category_internal.dm" #include "code\modules\logging\categories\log_category_misc.dm" #include "code\modules\logging\categories\log_category_pda.dm" #include "code\modules\logging\categories\log_category_silo.dm"