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

@@ -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 <id>` 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.

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);

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;

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));
 

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]",
+		           "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_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]",
+			           "Expiring $tkl.type_string '$tkl' [reason: $tkl.reason] [by: $tkl.set_by] [duration: $tkl.duration_string] $id",
-				   log_data_tkl("tkl", tkl));
+				   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]",
+			   "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_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]",
+			   "$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_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]",
+			   "$tkl.type_string added: '$tkl' [reason: $tkl.reason] [by: $tkl.set_by] [duration: $tkl.duration_string] $id",
-			   log_data_tkl("tkl", tkl));
+			   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]",
+			   "[action: $tkl.ban_action] [reason: $tkl.reason] [by: $tkl.set_by] $id",
-			   log_data_tkl("tkl", tkl));
+			   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]",
+			   "$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_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;
 			}