JSON Logging Take Two (#73604)

## About The Pull Request

Converts all logging, excluding perf and investigate, to json.
I focused on making the system as easy to use and as easy to add new
categories as possible.

Due to issues related to logging to world at global creation logger is
now a byond real, which is created directly before Master

Log categories support versioning, secret flagging, and sub-category
filtering. Although all of this is entirely optional for coders.
If you ever want to add a new category and use it, all you need to do is
make the barebones category datum and the define.
I've kept existing procs such as log_game, and simply turned them into a
wrapper for Logger.Log(xxx, ...)
## Why It's Good For The Game

Makes processing and filtering logs much easier in the future, while
only minimally downgrading log crawling experience.
I am also working on a log viewer frontend for admin usage however that
will take a little bit longer to finish up.
Also makes special logging and data tracking much easier thanks to a
data list processing implementation and handling
## Changelog
🆑
server: All logs are now formatted in json, excluding perf and
investigations
/🆑

---------

Signed-off-by: GitHub <noreply@github.com>
Co-authored-by: tattle <66640614+dragomagol@users.noreply.github.com>
Co-authored-by: Kyle Spier-Swenson <kyleshome@gmail.com>
Co-authored-by: GoldenAlpharex <58045821+GoldenAlpharex@users.noreply.github.com>
This commit is contained in:
Zephyr
2023-05-21 22:51:00 -04:00
committed by GitHub
parent 3df5d3b42b
commit fbec9c14e9
49 changed files with 1055 additions and 353 deletions
@@ -0,0 +1,26 @@
/datum/log_category/admin
category = LOG_CATEGORY_ADMIN
config_flag = /datum/config_entry/flag/log_admin
/datum/log_category/admin_dsay
category = LOG_CATEGORY_ADMIN_DSAY
master_category = /datum/log_category/admin
config_flag = /datum/config_entry/flag/log_admin
/datum/log_category/admin_circuit
category = LOG_CATEGORY_ADMIN_CIRCUIT
master_category = /datum/log_category/admin
config_flag = /datum/config_entry/flag/log_admin
// private categories //
/datum/log_category/admin_private
category = LOG_CATEGORY_ADMIN_PRIVATE
config_flag = /datum/config_entry/flag/log_admin
secret = TRUE
/datum/log_category/admin_asay
category = LOG_CATEGORY_ADMIN_PRIVATE_ASAY
master_category = /datum/log_category/admin_private
config_flag = /datum/config_entry/flag/log_adminchat
secret = TRUE
@@ -0,0 +1,7 @@
/datum/log_category/game_compat
category = LOG_CATEGORY_COMPAT_GAME
master_category = /datum/log_category/game
config_flag = /datum/config_entry/flag/logging_compat_adminprivate
/datum/config_entry/flag/logging_compat_adminprivate
default = FALSE
@@ -0,0 +1,45 @@
/datum/log_category/debug
category = LOG_CATEGORY_DEBUG
/datum/log_category/debug_tgui
category = LOG_CATEGORY_DEBUG_TGUI
master_category = /datum/log_category/debug
/datum/log_category/debug_sql
category = LOG_CATEGORY_DEBUG_SQL
master_category = /datum/log_category/debug
/datum/log_category/debug_lua
category = LOG_CATEGORY_DEBUG_LUA
master_category = /datum/log_category/debug
/datum/log_category/debug_href
category = LOG_CATEGORY_DEBUG_HREF
master_category = /datum/log_category/debug
// This is not in the debug master category on purpose, do not add it
/datum/log_category/debug_runtime
category = LOG_CATEGORY_RUNTIME
internal_formatting = FALSE
/datum/log_category/debug_mapping
category = LOG_CATEGORY_DEBUG_MAPPING
master_category = /datum/log_category/debug
/datum/log_category/debug_job
category = LOG_CATEGORY_DEBUG_JOB
config_flag = /datum/config_entry/flag/log_job_debug
master_category = /datum/log_category/debug
/datum/log_category/debug_mobtag
category = LOG_CATEGORY_DEBUG_MOBTAG
master_category = /datum/log_category/debug
/datum/log_category/debug_asset
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
@@ -0,0 +1,58 @@
/datum/log_category/game
category = LOG_CATEGORY_GAME
config_flag = /datum/config_entry/flag/log_game
/datum/log_category/game_vote
category = LOG_CATEGORY_GAME_VOTE
config_flag = /datum/config_entry/flag/log_vote
master_category = /datum/log_category/game
/datum/log_category/game_emote
category = LOG_CATEGORY_GAME_EMOTE
config_flag = /datum/config_entry/flag/log_emote
master_category = /datum/log_category/game
/datum/log_category/game_internet_request
category = LOG_CATEGORY_GAME_INTERNET_REQUEST
config_flag = /datum/config_entry/flag/log_internet_request
master_category = /datum/log_category/game
/datum/log_category/game_radio_emote
category = LOG_CATEGORY_GAME_RADIO_EMOTE
config_flag = /datum/config_entry/flag/log_emote
master_category = /datum/log_category/game
/datum/log_category/game_traitor
category = LOG_CATEGORY_GAME_TRAITOR
config_flag = /datum/config_entry/flag/log_traitor
master_category = /datum/log_category/game
/datum/log_category/game_topic
category = LOG_CATEGORY_GAME_TOPIC
config_flag = /datum/config_entry/flag/log_world_topic
master_category = /datum/log_category/game
/datum/log_category/game_say
category = LOG_CATEGORY_GAME_SAY
config_flag = /datum/config_entry/flag/log_say
master_category = /datum/log_category/game
/datum/log_category/game_whisper
category = LOG_CATEGORY_GAME_WHISPER
config_flag = /datum/config_entry/flag/log_whisper
master_category = /datum/log_category/game
/datum/log_category/game_ooc
category = LOG_CATEGORY_GAME_OOC
config_flag = /datum/config_entry/flag/log_ooc
master_category = /datum/log_category/game
/datum/log_category/game_prayer
category = LOG_CATEGORY_GAME_PRAYER
config_flag = /datum/config_entry/flag/log_prayer
master_category = /datum/log_category/game
/datum/log_category/game_access
category = LOG_CATEGORY_GAME_ACCESS
config_flag = /datum/config_entry/flag/log_access
master_category = /datum/log_category/game
@@ -0,0 +1,58 @@
/datum/log_category/virus
category = LOG_CATEGORY_VIRUS
config_flag = /datum/config_entry/flag/log_virus
/datum/log_category/tool
category = LOG_CATEGORY_TOOL
config_flag = /datum/config_entry/flag/log_tools
/datum/log_category/mecha
category = LOG_CATEGORY_MECHA
config_flag = /datum/config_entry/flag/log_mecha
/datum/log_category/silicon
category = LOG_CATEGORY_SILICON
config_flag = /datum/config_entry/flag/log_silicon
/datum/log_category/paper
category = LOG_CATEGORY_PAPER
/datum/log_category/attack
category = LOG_CATEGORY_ATTACK
config_flag = /datum/config_entry/flag/log_attack
/datum/log_category/economy
category = LOG_CATEGORY_ECONOMY
config_flag = /datum/config_entry/flag/log_econ
/datum/log_category/manifest
category = LOG_CATEGORY_MANIFEST
config_flag = /datum/config_entry/flag/log_manifest
/datum/log_category/shuttle
category = LOG_CATEGORY_SHUTTLE
config_flag = /datum/config_entry/flag/log_shuttle
/datum/log_category/supicious_login
category = LOG_CATEGORY_SUSPICIOUS_LOGIN
config_flag = /datum/config_entry/flag/log_suspicious_login
/datum/log_category/config
category = LOG_CATEGORY_CONFIG
/datum/log_category/filter
category = LOG_CATEGORY_FILTER
/datum/log_category/signal
category = LOG_CATEGORY_SIGNAL
/datum/log_category/dynamic
category = LOG_CATEGORY_DYNAMIC
/datum/log_category/telecomms
category = LOG_CATEGORY_TELECOMMS
config_flag = /datum/config_entry/flag/log_telecomms
/datum/log_category/speech_indicator
category = LOG_CATEGORY_SPEECH_INDICATOR
config_flag = /datum/config_entry/flag/log_speech_indicators
@@ -0,0 +1,11 @@
/datum/log_category/pda
category = LOG_CATEGORY_PDA
config_flag = /datum/config_entry/flag/log_pda
/datum/log_category/pda_chat
category = LOG_CATEGORY_PDA_CHAT
master_category = /datum/log_category/pda
/datum/log_category/pda_comment
category = LOG_CATEGORY_PDA_COMMENT
master_category = /datum/log_category/pda
@@ -0,0 +1,23 @@
/datum/log_category/uplink
category = LOG_CATEGORY_UPLINK
config_flag = /datum/config_entry/flag/log_uplink
/datum/log_category/uplink_malf
category = LOG_CATEGORY_UPLINK_MALF
config_flag = /datum/config_entry/flag/log_uplink
master_category = /datum/log_category/uplink
/datum/log_category/uplink_heretic
category = LOG_CATEGORY_UPLINK_HERETIC
config_flag = /datum/config_entry/flag/log_uplink
master_category = /datum/log_category/uplink
/datum/log_category/uplink_changeling
category = LOG_CATEGORY_UPLINK_CHANGELING
config_flag = /datum/config_entry/flag/log_uplink
master_category = /datum/log_category/uplink
/datum/log_category/uplink_spell
category = LOG_CATEGORY_UPLINK_SPELL
config_flag = /datum/config_entry/flag/log_uplink
master_category = /datum/log_category/uplink
+39 -15
View File
@@ -1,32 +1,56 @@
/// The main datum that contains all log entries for a category
/datum/log_category
/// The category this datum contains
/// The category name
var/category
/// The schema version of this log category.
/// Expected format of "Major.Minor.Patch"
var/schema_version = LOG_CATEGORY_SCHEMA_VERSION_NOT_SET
/// The master category that contains this category
var/datum/log_category/master_category
/// If set this config flag is checked to enable this log category
var/config_flag
/// List of all entries, in chronological order of when they were added
var/list/entries = list()
/// Whether or not this log should not be publically visible
var/secret = FALSE
/// Whether the readable version of the log message is formatted internally instead of by rustg
var/internal_formatting = TRUE
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/add_entry(message, list/data)
var/list/entry = list(
LOG_ENTRY_MESSAGE = message,
LOG_ENTRY_TIMESTAMP = big_number_to_text(rustg_unix_timestamp()),
/datum/log_category/proc/create_entry(message, list/data, list/semver_store)
var/datum/log_entry/entry = new(
// world state contains raw timestamp
timestamp = logger.human_readable_timestamp(),
category = category,
message = message,
data = data,
semver_store = semver_store,
)
if(data)
entry[LOG_ENTRY_DATA] = data
entries += list(entry)
write_entry(entry)
/// Allows for category specific file splitting. Needs to accept a null entry for the default file.
/datum/log_category/proc/get_output_file(list/entry)
return "[GLOB.log_directory]/[category].json"
/// If master_category it will always return the output of master_category.get_output_file(entry)
/datum/log_category/proc/get_output_file(list/entry, extension = "log.json")
if(master_category)
return master_category.get_output_file(entry, extension)
if(secret)
return "[GLOB.log_directory]/secret/[category].[extension]"
return "[GLOB.log_directory]/[category].[extension]"
/// Writes an entry to the output file for the category
/datum/log_category/proc/write_entry(list/entry)
rustg_file_append("[json_encode(entry)]\n", get_output_file(entry))
/// Writes an entry to the output file(s) for the category
/datum/log_category/proc/write_entry(datum/log_entry/entry)
// config isn't loaded? assume we want human readable logs
if(isnull(config) || CONFIG_GET(flag/log_as_human_readable))
entry.write_readable_entry_to_file(get_output_file(entry, "log"), format_internally = internal_formatting)
entry.write_entry_to_file(get_output_file(entry))
+114
View File
@@ -0,0 +1,114 @@
// Schema version must always be the very last element in the array.
// Current Schema: 1.0.0
// [timestamp, category, message, data, world_state, semver_store, id, schema_version]
/// A datum which contains log information.
/datum/log_entry
/// Next id to assign to a log entry.
var/static/next_id = 0
/// Unique id of the log entry.
var/id
/// Schema version of the log entry.
var/schema_version = "1.0.0"
/// Unix timestamp of the log entry.
var/timestamp
/// Category of the log entry.
var/category
/// Message of the log entry.
var/message
/// Data of the log entry; optional.
var/list/data
/// Semver store of the log entry, used to store the schema of data entries
var/list/semver_store
GENERAL_PROTECT_DATUM(/datum/log_entry)
/datum/log_entry/New(timestamp, category, message, list/data, list/semver_store)
..()
src.id = next_id++
src.timestamp = timestamp
src.category = category
src.message = message
with_data(data)
with_semver_store(semver_store)
/datum/log_entry/proc/with_data(list/data)
if(!isnull(data))
if(!islist(data))
src.data = list("data" = data)
stack_trace("Log entry data was not a list, it was [data.type].")
else
src.data = data
return src
/datum/log_entry/proc/with_semver_store(list/semver_store)
if(isnull(semver_store))
return
if(!islist(semver_store))
stack_trace("Log entry semver store was not a list, it was [semver_store.type]. We cannot reliably convert it to a list.")
else
src.semver_store = semver_store
return src
/// Converts the log entry to a human-readable string.
/datum/log_entry/proc/to_readable_text(format = TRUE)
if(format)
return "\[[timestamp]\] [uppertext(category)]: [message]"
else
return "[message]"
/// Converts the log entry to a JSON string.
/datum/log_entry/proc/to_json_text()
// I do not trust byond's json encoder, so we're doing it manually
var/list/json_strings = list()
json_strings += json_encode(timestamp)
json_strings += json_encode(category)
json_strings += json_encode(message)
if(length(data))
json_strings += json_encode(data)
else
json_strings += "null"
json_strings += json_encode(world.get_world_state_for_logging())
if(length(semver_store))
json_strings += json_encode(semver_store)
else
json_strings += "null"
json_strings += "[id]"
json_strings += json_encode(schema_version)
return "\[[json_strings.Join(",")]\]"
/// 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]")
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]")
// 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)]")
+197 -25
View File
@@ -1,6 +1,5 @@
GLOBAL_DATUM_INIT(logger, /datum/log_holder, new)
GLOBAL_PROTECT(logger)
GLOBAL_REAL(logger, /datum/log_holder)
/**
* Main datum to manage logging actions
*/
@@ -14,40 +13,58 @@ GLOBAL_PROTECT(logger)
var/list/datum/log_category/log_categories
/// typecache list for categories that exist but are disabled
var/list/disabled_categories
/// category nesting tree for ui purposes
var/list/category_group_tree
/// list of Log args waiting for processing pending log initialization
var/list/waiting_log_calls
/// Whether or not logging as human readable text is enabled
var/human_readable_enabled = FALSE
var/initialized = FALSE
var/shutdown = FALSE
GENERAL_PROTECT_DATUM(/datum/log_holder)
/// Assembles basic information for logging, creating the log category datums and checking for config flags as required
/datum/log_holder/proc/init_logging()
if(initialized)
CRASH("Attempted to call init_logging twice!")
initialized = TRUE
round_id = GLOB.round_id
logging_start_timestamp = rustg_unix_timestamp()
logging_start_timestamp = unix_timestamp_string()
log_categories = list()
disabled_categories = list()
for(var/datum/log_category/category_type as anything in subtypesof(/datum/log_category))
var/category = initial(category_type.category)
if(!category)
continue
if(category in log_categories)
stack_trace("Found two identical log category type definitions! [category_type]")
continue
human_readable_enabled = CONFIG_GET(flag/log_as_human_readable)
var/config_flag = initial(category_type.config_flag)
category_group_tree = assemble_log_category_tree()
var/config_flag
for(var/datum/log_category/master_category as anything in category_group_tree)
var/list/sub_categories = category_group_tree[master_category]
sub_categories = sub_categories.Copy()
for(var/datum/log_category/sub_category as anything in sub_categories)
config_flag = initial(sub_category.config_flag)
if(config_flag && !config.Get(config_flag))
disabled_categories[initial(sub_category.category)] = TRUE
sub_categories -= sub_category
continue
config_flag = initial(master_category.config_flag)
if(config_flag && !config.Get(config_flag))
disabled_categories[category] = TRUE
continue
category_type = log_categories[category] = new category_type
var/list/log_start_entry = list(
LOG_HEADER_CATEGORY = category,
LOG_HEADER_INIT_TIMESTAMP = big_number_to_text(logging_start_timestamp),
LOG_HEADER_ROUND_ID = big_number_to_text(GLOB.round_id),
)
rustg_file_write("[json_encode(log_start_entry)]\n", category_type.get_output_file(null))
disabled_categories[initial(master_category.category)] = TRUE
if(!length(sub_categories))
continue
// enabled, or any of the sub categories are enabled
init_log_category(master_category, sub_categories)
initialized = TRUE
// process any waiting log calls and then cut the list
for(var/list/arg_list as anything in waiting_log_calls)
Log(arglist(arg_list))
waiting_log_calls?.Cut()
if(fexists(GLOB.config_error_log))
fcopy(GLOB.config_error_log, "[GLOB.log_directory]/config_error.log")
@@ -61,10 +78,120 @@ GLOBAL_PROTECT(logger)
CRASH("Attempted to call shutdown_logging twice!")
shutdown = TRUE
/// This is Log because log is a byond internal proc
/// Iterates over all log category types to assemble them into a tree of main category -> (sub category)[] while also checking for loops and sanity errors
/datum/log_holder/proc/assemble_log_category_tree()
var/static/list/category_tree
if(category_tree)
return category_tree
category_tree = list()
var/list/all_types = subtypesof(/datum/log_category)
var/list/known_categories = list()
var/list/sub_categories = list()
// Assemble the master categories
for(var/datum/log_category/category_type as anything in all_types)
var/category = initial(category_type.category)
if(category in known_categories)
stack_trace("log category type '[category_type]' has duplicate category '[category]', skipping")
continue
if(!initial(category_type.schema_version))
stack_trace("log category type '[category_type]' does not have a valid schema version, skipping")
continue
var/master_category = initial(category_type.master_category)
if(master_category)
sub_categories[master_category] += list(category_type)
continue
category_tree[category_type] = list()
// Sort the sub categories
for(var/datum/log_category/master as anything in sub_categories)
if(!(master in category_tree))
stack_trace("log category [master] is an invalid master category as it's a sub category")
continue
for(var/datum/log_category/sub_category as anything in sub_categories[master])
if(initial(sub_category.secret) != initial(master.secret))
stack_trace("log category [sub_category] has a secret status that differs from its master category [master]")
category_tree[master] += list(sub_category)
return category_tree
/// 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
var/list/contained_categories = list()
for(var/datum/log_category/sub_category as anything in sub_categories)
sub_category = new sub_category
var/sub_category_actual = sub_category.category
sub_category.master_category = category_instance
log_categories[sub_category_actual] = sub_category
if(!semver_to_list(sub_category.schema_version))
stack_trace("log category [sub_category_actual] has an invalid schema version '[sub_category.schema_version]'")
sub_category.schema_version = LOG_CATEGORY_SCHEMA_VERSION_NOT_SET
contained_categories += sub_category_actual
log_categories[category_instance.category] = category_instance
if(!semver_to_list(category_instance.schema_version))
stack_trace("log category [category_instance.category] has an invalid schema version '[category_instance.schema_version]'")
category_instance.schema_version = LOG_CATEGORY_SCHEMA_VERSION_NOT_SET
contained_categories += category_instance.category
var/list/category_header = list(
LOG_HEADER_INIT_TIMESTAMP = logging_start_timestamp,
LOG_HEADER_ROUND_ID = big_number_to_text(GLOB.round_id),
LOG_HEADER_SECRET = category_instance.secret,
LOG_HEADER_CATEGORY_LIST = contained_categories,
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"))
/datum/log_holder/proc/unix_timestamp_string() // pending change to rust-g
return RUSTG_CALL(RUST_G, "unix_timestamp")()
/datum/log_holder/proc/human_readable_timestamp(precision = 3)
var/start = time2text(world.timeofday, "YYYY-MM-DD hh:mm:ss")
// now we grab the millis from the rustg timestamp
var/list/timestamp = splittext(unix_timestamp_string(), ".")
var/millis = timestamp[2]
if(length(millis) > precision)
millis = copytext(millis, 1, precision + 1)
return "[start].[millis]"
/// Adds an entry to the given category, if the category is disabled it will not be logged.
/// If the category does not exist, we will CRASH and log to the error category.
/// the data list is optional and will be recursively json serialized.
/datum/log_holder/proc/Log(category, message, list/data)
if(!initialized || shutdown)
CRASH("Attempted to perform logging before initializion or after shutdown!")
// This is Log because log is a byond internal proc
if(shutdown)
stack_trace("Performing logging after shutdown! This might not be functional in the future!")
// but for right now it's fine
// do not include the message because these go into the runtime log and we might be secret!
if(!istext(message))
message = "[message]"
stack_trace("Logging with a non-text message")
if(!category)
category = LOG_CATEGORY_NOT_FOUND
stack_trace("Logging with a null or empty category")
if(data && !islist(data))
data = list("data" = data)
stack_trace("Logging with data this is not a list, it will be converted to a list with a single key 'data'")
if(!initialized) // we are initialized during /world/proc/SetupLogging which is called in /world/New
waiting_log_calls += list(list(category, message, data))
return
if(disabled_categories[category])
return
@@ -73,4 +200,49 @@ GLOBAL_PROTECT(logger)
if(!log_category)
Log(LOG_CATEGORY_NOT_FOUND, message, data)
CRASH("Attempted to log to a category that doesn't exist! [category]")
log_category.add_entry(message, data)
var/list/semver_store = null
if(length(data))
semver_store = list()
data = recursive_jsonify(data, semver_store)
log_category.create_entry(message, data, semver_store)
/// Recursively converts an associative list of datums into their jsonified(list) form
/datum/log_holder/proc/recursive_jsonify(list/data_list, list/semvers)
if(isnull(data_list))
return null
var/list/jsonified_list = list()
for(var/key in data_list)
var/datum/data = data_list[key]
if(isnull(data))
// do nothing - nulls are allowed
else if(islist(data))
data = recursive_jsonify(data, semvers)
else if(isdatum(data))
var/list/options_list = list(
SCHEMA_VERSION = LOG_CATEGORY_SCHEMA_VERSION_NOT_SET,
)
var/list/serialization_data = data.serialize_list(options_list, semvers)
var/current_semver = semvers[data.type]
if(!semver_to_list(current_semver))
stack_trace("serialization of data had an invalid semver")
semvers[data.type] = LOG_CATEGORY_SCHEMA_VERSION_NOT_SET
if(!length(serialization_data)) // serialize_list wasn't implemented, and errored
stack_trace("serialization data was empty")
continue
data = recursive_jsonify(serialization_data, semvers)
if(islist(data) && !length(data))
stack_trace("recursive_jsonify got an empty list after serialization")
continue
jsonified_list[key] = data
return jsonified_list