From 5850ec9434fa08d0152cd38b00a4b1b11c147ba9 Mon Sep 17 00:00:00 2001 From: Bram Matthys Date: Wed, 10 Jun 2026 19:27:20 +0200 Subject: [PATCH] Show TKL IDs (and related spamfilter TKL ID, if any) in TKL_ADD, TKL_DEL, TKL_EXPIRE and SPAMFILTER_MATCH messages. This uses the newly added functions log_data_optional_string() and log_data_optional_name_value(). The first shows the optional string like "abc" and the second expands to "[name: value]". What's also new is that both of these will swallow a preceding space if there is no value. This so you can just use "Something. $optional_string" and it will expand to "Something." if $optional_string is empty. This makes things less hacky and more human readable :) --- doc/RELEASE-NOTES.md | 4 +- include/h.h | 2 + include/struct.h | 3 ++ src/log.c | 98 +++++++++++++++++++++++++++++++++++++++++--- src/modules/tkl.c | 73 ++++++++++++++++++++------------- 5 files changed, 146 insertions(+), 34 deletions(-) diff --git a/doc/RELEASE-NOTES.md b/doc/RELEASE-NOTES.md index 288e55cd8..959e760ce 100644 --- a/doc/RELEASE-NOTES.md +++ b/doc/RELEASE-NOTES.md @@ -17,9 +17,11 @@ This is work in progress and may not always be a stable version. with e.g. `STATS gline +i G7K2MP9WQX3`. * Spamfilters also have an ID, and we already had something similar that could be used for `SPAMFILTER del ` that was only local-server. - For new spamfilters this is now a network wide ID as well. + For new spamfilters this is now a network wide ID. * When a server ban was placed by a spamfilter, `STATS gline` shows the originating spamfilter's ID, so it can be traced back. + * The TKL ID and related Spamfilter ID (if any), also appear in log + messages `TKL_ADD`, `TKL_DEL`, `TKL_EXPIRE` and `SPAMFILTER_MATCH`. * The `STATS gline` and other TKL stats changed format, see *Developers and protocol* if you use scripts or your client depends on the exact numeric format. diff --git a/include/h.h b/include/h.h index 7b99d4cab..47e99c050 100644 --- a/include/h.h +++ b/include/h.h @@ -1455,6 +1455,8 @@ extern void do_unreal_log(LogLevel loglevel, const char *subsystem, const char * extern void do_unreal_log_raw(LogLevel loglevel, const char *subsystem, const char *event_id, Client *client, const char *msg, ...); extern void do_unreal_log_internal_from_remote(LogLevel loglevel, const char *subsystem, const char *event_id, MultiLine *msg, json_t *json, const char *json_serialized, Client *from_server); extern LogData *log_data_string(const char *key, const char *str); +extern LogData *log_data_optional_name_value(const char *key, const char *label, const char *value); +extern LogData *log_data_optional_string(const char *key, const char *value); extern LogData *log_data_char(const char *key, const char c); extern LogData *log_data_integer(const char *key, int64_t integer); extern LogData *log_data_timestamp(const char *key, time_t ts); diff --git a/include/struct.h b/include/struct.h index 9cb8be391..dbe65bb2c 100644 --- a/include/struct.h +++ b/include/struct.h @@ -228,6 +228,8 @@ typedef OperPermission (*OperClassEntryEvalCallback)(OperClassACLEntryVar* varia typedef enum LogFieldType { LOG_FIELD_INTEGER, // and unsigned? LOG_FIELD_STRING, + LOG_FIELD_OPTIONAL_NAME_VALUE, + LOG_FIELD_OPTIONAL_STRING, LOG_FIELD_CLIENT, LOG_FIELD_CHANNEL, LOG_FIELD_OBJECT, @@ -237,6 +239,7 @@ typedef enum LogFieldType { typedef struct LogData { LogFieldType type; char *key; + char *label; /**< Display label for LOG_FIELD_OPTIONAL_NAME_VALUE, NULL otherwise */ union { int64_t integer; char *string; diff --git a/src/log.c b/src/log.c index 079988b18..8b9bc63a1 100644 --- a/src/log.c +++ b/src/log.c @@ -587,6 +587,39 @@ LogData *log_data_string(const char *key, const char *str) return d; } +/** Like log_data_string(), the JSON is identical, but in buildlogstring() + * if the value is empty the string will be empty plus one preceding space + * character is "eaten". This way you can write things like + * "blablabla. $optionalstring" and both the space and the $optionalstring + * will not appear in the output. + */ +LogData *log_data_optional_string(const char *key, const char *value) +{ + LogData *d = safe_alloc(sizeof(LogData)); + + d->type = LOG_FIELD_OPTIONAL_STRING; + safe_strdup(d->key, key); + safe_strdup(d->value.string, value); + return d; +} + +/** Optional "[label: value]" field. In the JSON the value is stored raw, exactly + * like log_data_string() (so consumers get a clean value, not display text); in + * the text buildlogstring() shows it as "[label: value]". If the value is empty + * the whole thing is left out of the text and one preceding space is consumed, so + * "blablabla. $field" collapses cleanly when $field is empty. + */ +LogData *log_data_optional_name_value(const char *key, const char *label, const char *value) +{ + LogData *d = safe_alloc(sizeof(LogData)); + + d->type = LOG_FIELD_OPTIONAL_NAME_VALUE; + safe_strdup(d->key, key); + safe_strdup(d->label, label); + safe_strdup(d->value.string, value); + return d; +} + LogData *log_data_char(const char *key, const char c) { LogData *d = safe_alloc(sizeof(LogData)); @@ -783,11 +816,13 @@ LogData *log_data_textanalysis(const char *key, TextAnalysis *ta) void log_data_free(LogData *d) { - if (d->type == LOG_FIELD_STRING) + if ((d->type == LOG_FIELD_STRING) || (d->type == LOG_FIELD_OPTIONAL_NAME_VALUE) || + (d->type == LOG_FIELD_OPTIONAL_STRING)) safe_free(d->value.string); else if (((d->type == LOG_FIELD_OBJECT) || (d->type == LOG_FIELD_OBJECT_NOFREE)) && d->value.object) json_decref(d->value.object); + safe_free(d->label); safe_free(d->key); safe_free(d); } @@ -899,14 +934,26 @@ int valid_subsystem(const char *s) * @param name Array of variables names * @param value Array of variable values */ -void buildlogstring(const char *inbuf, char *outbuf, size_t len, json_t *details) +/* Eat one space immediately before the current output position, if any. + * Used when an optional log field outputs nothing. */ +static void buildlogstring_eat_space(char **o, char *outbuf, int *left) +{ + if ((*o > outbuf) && ((*o)[-1] == ' ')) + { + (*o)--; + (*left)++; + } +} + +void buildlogstring(const char *inbuf, char *outbuf, size_t len, json_t *details, json_t *optional_keys) { const char *i, *p; char *o; int left = len - 1; int cnt, found; char varname[256], *varp, *varpp; - json_t *t; + char buf[BUFSIZE]; + json_t *t, *opt; #ifdef DEBUGMODE if (len <= 0) @@ -973,13 +1020,30 @@ void buildlogstring(const char *inbuf, char *outbuf, size_t len, json_t *details { output = json_get_value(t); } - if (output) + /* optional_keys maps each optional field's key to its label (a + * json string) for log_data_optional_name_value, or to json null + * for log_data_optional_string. A non-NULL lookup means "optional". + */ + opt = json_object_get(optional_keys, varname); + if (output && *output) { + if (opt && json_is_string(opt)) + { + /* name:value field: show it as "[label: value]" (the JSON keeps the raw value) */ + ircsnprintf(buf, sizeof(buf), "[%s: %s]", json_string_value(opt), output); + output = buf; + } strlcpy(o, output, left); left -= strlen(output); /* may become <0 */ if (left <= 0) return; /* return - don't write \0 to 'o'. ensured by strlcpy already */ o += strlen(output); /* value entirely written */ + } else + if (opt) + { + /* Optional field that is empty: show nothing and eat a + * preceding space. */ + buildlogstring_eat_space(&o, outbuf, &left); } } else { @@ -1801,6 +1865,7 @@ void do_unreal_log_internal(LogLevel loglevel, const char *subsystem, const char const char *str; json_t *j = NULL; json_t *j_details = NULL; + json_t *optional_keys = NULL; json_t *t; char msgbuf[MAXLOGLENGTH]; const char *loglevel_string = log_level_valtostring(loglevel); @@ -1842,6 +1907,7 @@ void do_unreal_log_internal(LogLevel loglevel, const char *subsystem, const char j = json_object(); j_details = json_object(); + optional_keys = json_object(); json_object_set_new(j, "timestamp", json_string_unreal(timestamp_iso8601_now())); json_object_set_new(j, "level", json_string_unreal(loglevel_string)); @@ -1869,6 +1935,27 @@ void do_unreal_log_internal(LogLevel loglevel, const char *subsystem, const char else json_object_set_new(j_details, d->key, json_null()); break; + case LOG_FIELD_OPTIONAL_NAME_VALUE: + /* Optional: raw value in the JSON (or null), exactly like + * LOG_FIELD_STRING; buildlogstring() shows it as "[label: value]" + * in the text and eats a preceding space when empty. The label is + * stored as this key's value in optional_keys. */ + json_object_set_new(optional_keys, d->key, json_string_unreal(d->label)); + if (d->value.string) + json_object_set_new(j_details, d->key, json_string_unreal(d->value.string)); + else + json_object_set_new(j_details, d->key, json_null()); + break; + case LOG_FIELD_OPTIONAL_STRING: + /* Same JSON as LOG_FIELD_STRING (value as-is, null only when + * NULL); the optional_keys entry (value null = no label) is what + * makes buildlogstring() eat a preceding space when empty. */ + json_object_set_new(optional_keys, d->key, json_null()); + if (d->value.string) + json_object_set_new(j_details, d->key, json_string_unreal(d->value.string)); + else + json_object_set_new(j_details, d->key, json_null()); + break; case LOG_FIELD_CLIENT: json_expand_client(j_details, d->key, d->value.client, 3); break; @@ -1897,9 +1984,10 @@ void do_unreal_log_internal(LogLevel loglevel, const char *subsystem, const char } if (expand_msg) - buildlogstring(msg, msgbuf, sizeof(msgbuf), j_details); + buildlogstring(msg, msgbuf, sizeof(msgbuf), j_details, optional_keys); else strlcpy(msgbuf, msg, sizeof(msgbuf)); + json_decref(optional_keys); json_object_set_new(j, "msg", json_string_unreal(msgbuf)); diff --git a/src/modules/tkl.c b/src/modules/tkl.c index 8f4832a79..bb90d563e 100644 --- a/src/modules/tkl.c +++ b/src/modules/tkl.c @@ -3916,23 +3916,27 @@ void tkl_expire_entry(TKL *tkl) if (TKLIsServerBan(tkl)) { unreal_log(ULOG_INFO, "tkl", "TKL_EXPIRE", NULL, - "Expiring $tkl.type_string '$tkl' [reason: $tkl.reason] [by: $tkl.set_by] [duration: $tkl.duration_string]", - log_data_tkl("tkl", tkl)); + "Expiring $tkl.type_string '$tkl' [reason: $tkl.reason] [by: $tkl.set_by] [duration: $tkl.duration_string] $id $spamfilter_id", + log_data_tkl("tkl", tkl), + log_data_optional_name_value("id", "id", tkl->id), + log_data_optional_name_value("spamfilter_id", "spamfilter-id", tkl->spamfilter_id)); } else if (TKLIsNameBan(tkl)) { if (!tkl->ptr.nameban->hold) { unreal_log(ULOG_INFO, "tkl", "TKL_EXPIRE", NULL, - "Expiring $tkl.type_string '$tkl' [reason: $tkl.reason] [by: $tkl.set_by] [duration: $tkl.duration_string]", - log_data_tkl("tkl", tkl)); + "Expiring $tkl.type_string '$tkl' [reason: $tkl.reason] [by: $tkl.set_by] [duration: $tkl.duration_string] $id", + log_data_tkl("tkl", tkl), + log_data_optional_name_value("id", "id", tkl->id)); } } else if (TKLIsBanException(tkl)) { unreal_log(ULOG_INFO, "tkl", "TKL_EXPIRE", NULL, - "Expiring $tkl.type_string '$tkl' [type: $tkl.exception_types] [reason: $tkl.reason] [by: $tkl.set_by] [duration: $tkl.duration_string]", - log_data_tkl("tkl", tkl)); + "Expiring $tkl.type_string '$tkl' [type: $tkl.exception_types] [reason: $tkl.reason] [by: $tkl.set_by] [duration: $tkl.duration_string] $id", + log_data_tkl("tkl", tkl), + log_data_optional_name_value("id", "id", tkl->id)); } // FIXME: so.. this isn't logged? or what? @@ -4294,10 +4298,11 @@ int spamfilter_check_users(TKL *tkl) /* matched! */ unreal_log(ULOG_INFO, "tkl", "SPAMFILTER_MATCH", client, - "[Spamfilter] $client.details matches filter '$tkl': [cmd: $command: '$str'] [reason: $tkl.reason] [action: $tkl.ban_action]", + "[Spamfilter] $client.details matches filter '$tkl': [cmd: $command: '$str'] [reason: $tkl.reason] [action: $tkl.ban_action] $spamfilter_id", log_data_tkl("tkl", tkl), log_data_string("command", "USER"), - log_data_string("str", spamfilter_user)); + log_data_string("str", spamfilter_user), + log_data_optional_name_value("spamfilter_id", "spamfilter-id", tkl->id)); RunHook(HOOKTYPE_LOCAL_SPAMFILTER, client, spamfilter_user, spamfilter_user, SPAMF_USER, NULL, tkl); matches++; @@ -4988,27 +4993,32 @@ void _sendnotice_tkl_add(TKL *tkl) if (TKLIsServerBan(tkl)) { unreal_log(ULOG_INFO, "tkl", "TKL_ADD", NULL, - "$tkl.type_string added: '$tkl' [reason: $tkl.reason] [by: $tkl.set_by] [duration: $tkl.duration_string]", - log_data_tkl("tkl", tkl)); + "$tkl.type_string added: '$tkl' [reason: $tkl.reason] [by: $tkl.set_by] [duration: $tkl.duration_string] $id $spamfilter_id", + log_data_tkl("tkl", tkl), + log_data_optional_name_value("id", "id", tkl->id), + log_data_optional_name_value("spamfilter_id", "spamfilter-id", tkl->spamfilter_id)); } else if (TKLIsNameBan(tkl)) { unreal_log(ULOG_INFO, "tkl", "TKL_ADD", NULL, - "$tkl.type_string added: '$tkl' [reason: $tkl.reason] [by: $tkl.set_by] [duration: $tkl.duration_string]", - log_data_tkl("tkl", tkl)); + "$tkl.type_string added: '$tkl' [reason: $tkl.reason] [by: $tkl.set_by] [duration: $tkl.duration_string] $id", + log_data_tkl("tkl", tkl), + log_data_optional_name_value("id", "id", tkl->id)); } else if (TKLIsSpamfilter(tkl)) { unreal_log(ULOG_INFO, "tkl", "TKL_ADD", NULL, "Spamfilter added: '$tkl' [type: $tkl.match_type] [targets: $tkl.spamfilter_targets] " - "[action: $tkl.ban_action] [reason: $tkl.reason] [by: $tkl.set_by]", - log_data_tkl("tkl", tkl)); + "[action: $tkl.ban_action] [reason: $tkl.reason] [by: $tkl.set_by] $id", + log_data_tkl("tkl", tkl), + log_data_optional_name_value("id", "id", tkl->id)); } else if (TKLIsBanException(tkl)) { unreal_log(ULOG_INFO, "tkl", "TKL_ADD", NULL, - "$tkl.type_string added: '$tkl' [types: $tkl.exception_types] [by: $tkl.set_by] [duration: $tkl.duration_string]", - log_data_tkl("tkl", tkl)); + "$tkl.type_string added: '$tkl' [types: $tkl.exception_types] [by: $tkl.set_by] [duration: $tkl.duration_string] $id", + log_data_tkl("tkl", tkl), + log_data_optional_name_value("id", "id", tkl->id)); } else { unreal_log(ULOG_ERROR, "tkl", "BUG_UNKNOWN_TKL", NULL, @@ -5026,31 +5036,36 @@ void _sendnotice_tkl_del(const char *removed_by, TKL *tkl) if (TKLIsServerBan(tkl)) { unreal_log(ULOG_INFO, "tkl", "TKL_DEL", NULL, - "$tkl.type_string removed: '$tkl' [reason: $tkl.reason] [by: $removed_by] [set at: $tkl.set_at_string]", + "$tkl.type_string removed: '$tkl' [reason: $tkl.reason] [by: $removed_by] [set at: $tkl.set_at_string] $id $spamfilter_id", log_data_tkl("tkl", tkl), - log_data_string("removed_by", removed_by)); + log_data_string("removed_by", removed_by), + log_data_optional_name_value("id", "id", tkl->id), + log_data_optional_name_value("spamfilter_id", "spamfilter-id", tkl->spamfilter_id)); } else if (TKLIsNameBan(tkl)) { unreal_log(ULOG_INFO, "tkl", "TKL_DEL", NULL, - "$tkl.type_string removed: '$tkl' [reason: $tkl.reason] [by: $removed_by] [set at: $tkl.set_at_string]", + "$tkl.type_string removed: '$tkl' [reason: $tkl.reason] [by: $removed_by] [set at: $tkl.set_at_string] $id", log_data_tkl("tkl", tkl), - log_data_string("removed_by", removed_by)); + log_data_string("removed_by", removed_by), + log_data_optional_name_value("id", "id", tkl->id)); } else if (TKLIsSpamfilter(tkl)) { unreal_log(ULOG_INFO, "tkl", "TKL_DEL", NULL, "Spamfilter removed: '$tkl' [type: $tkl.match_type] [targets: $tkl.spamfilter_targets] " - "[action: $tkl.ban_action] [reason: $tkl.reason] [by: $removed_by] [set at: $tkl.set_at_string]", + "[action: $tkl.ban_action] [reason: $tkl.reason] [by: $removed_by] [set at: $tkl.set_at_string] $id", log_data_tkl("tkl", tkl), - log_data_string("removed_by", removed_by)); + log_data_string("removed_by", removed_by), + log_data_optional_name_value("id", "id", tkl->id)); } else if (TKLIsBanException(tkl)) { unreal_log(ULOG_INFO, "tkl", "TKL_DEL", NULL, - "$tkl.type_string removed: '$tkl' [types: $tkl.exception_types] [by: $removed_by] [set at: $tkl.set_at_string]", + "$tkl.type_string removed: '$tkl' [types: $tkl.exception_types] [by: $removed_by] [set at: $tkl.set_at_string] $id", log_data_tkl("tkl", tkl), - log_data_string("removed_by", removed_by)); + log_data_string("removed_by", removed_by), + log_data_optional_name_value("id", "id", tkl->id)); } else { unreal_log(ULOG_ERROR, "tkl", "BUG_UNKNOWN_TKL", NULL, @@ -6017,24 +6032,26 @@ static void match_spamfilter_hit(Client *client, const char *str_in, const char if (hide_content || (target == SPAMF_RAW)) { unreal_log(ULOG_INFO, "tkl", "SPAMFILTER_MATCH", client, - "[Spamfilter] $client.details matches filter '$tkl': [cmd: $command$_space$destination] [reason: $tkl.reason] [action: $tkl.ban_action]", + "[Spamfilter] $client.details matches filter '$tkl': [cmd: $command$_space$destination] [reason: $tkl.reason] [action: $tkl.ban_action] $spamfilter_id", log_data_tkl("tkl", tkl), log_data_string("command", cmd), log_data_string("_space", destination ? " " : ""), - log_data_string("destination", destination ? destination : "")); + log_data_string("destination", destination ? destination : ""), + log_data_optional_name_value("spamfilter_id", "spamfilter-id", tkl->id)); } else { // Yeah we are re-running the text analysis. TextAnalysis textanalysis; memset(&textanalysis, 0, sizeof(textanalysis)); RunHook(HOOKTYPE_ANALYZE_TEXT, client, str, &textanalysis); unreal_log(ULOG_INFO, "tkl", "SPAMFILTER_MATCH", client, - "[Spamfilter] $client.details matches filter '$tkl': [cmd: $command$_space$destination: '$str'] [reason: $tkl.reason] [action: $tkl.ban_action]", + "[Spamfilter] $client.details matches filter '$tkl': [cmd: $command$_space$destination: '$str'] [reason: $tkl.reason] [action: $tkl.ban_action] $spamfilter_id", log_data_tkl("tkl", tkl), log_data_string("command", cmd), log_data_string("_space", destination ? " " : ""), log_data_string("destination", destination ? destination : ""), log_data_string("str", str), - log_data_textanalysis("text_analysis", &textanalysis)); + log_data_textanalysis("text_analysis", &textanalysis), + log_data_optional_name_value("spamfilter_id", "spamfilter-id", tkl->id)); *content_revealed = 1; }