From bc9e17aeb098a86c8839afde0f4bbe023a083521 Mon Sep 17 00:00:00 2001 From: Bram Matthys Date: Sun, 8 Aug 2021 12:04:41 +0200 Subject: [PATCH] Add multiline support to unreal_log() Any \n's will be expanded to multiple lines. * For JSON disk logging there is no change. * For text disk logging it will show as: [time] facility subsys.CODE+ [time] facility subsys.CODE+ [time] facility subsys.CODE So a plus sign is added if another message is to follow. * For notices to opers/snomasks exactly the same (plus sign if needed). Untested. More changes to follow eg to notice dropping the json in the followup msgs. This also changes the logging format for text disk to match the output on server notices, we no longer log as: [TS] facility subsystem event_code: msg.... But as: [TS] facility subsystem.event_code: msg.... --- include/h.h | 4 +-- src/api-efunctions.c | 2 +- src/log.c | 72 +++++++++++++++++++++++++++++--------------- src/modules/slog.c | 38 +++++++++++++++++------ 4 files changed, 79 insertions(+), 37 deletions(-) diff --git a/include/h.h b/include/h.h index 2c1e88a9a..a7b441044 100644 --- a/include/h.h +++ b/include/h.h @@ -777,7 +777,7 @@ extern MODVAR int (*watch_del_list)(Client *client, int flags); extern MODVAR Watch *(*watch_get)(char *nick); extern MODVAR int (*watch_check)(Client *client, int reply); extern MODVAR char *(*tkl_uhost)(TKL *tkl, char *buf, size_t buflen, int options); -extern MODVAR void (*do_unreal_log_remote_deliver)(LogLevel loglevel, char *subsystem, char *event_id, char *msg, char *json_serialized); +extern MODVAR void (*do_unreal_log_remote_deliver)(LogLevel loglevel, char *subsystem, char *event_id, MultiLine *msg, char *json_serialized); /* /Efuncs */ /* SSL/TLS functions */ @@ -1101,7 +1101,7 @@ extern char *log_type_valtostring(LogType v); #endif extern void do_unreal_log(LogLevel loglevel, char *subsystem, char *event_id, Client *client, char *msg, ...) __attribute__((format(printf,5,0))); extern void do_unreal_log_raw(LogLevel loglevel, char *subsystem, char *event_id, Client *client, char *msg, ...); -extern void do_unreal_log_internal_from_remote(LogLevel loglevel, char *subsystem, char *event_id, char *msgbuf, char *json_serialized); +extern void do_unreal_log_internal_from_remote(LogLevel loglevel, char *subsystem, char *event_id, MultiLine *msg, char *json_serialized); extern LogData *log_data_string(const char *key, const char *str); extern LogData *log_data_char(const char *key, const char c); extern LogData *log_data_integer(const char *key, int64_t integer); diff --git a/src/api-efunctions.c b/src/api-efunctions.c index 0f94b4084..f034f5265 100644 --- a/src/api-efunctions.c +++ b/src/api-efunctions.c @@ -128,7 +128,7 @@ int (*watch_del)(char *nick, Client *client, int flags); int (*watch_del_list)(Client *client, int flags); Watch *(*watch_get)(char *nick); int (*watch_check)(Client *client, int reply); -void (*do_unreal_log_remote_deliver)(LogLevel loglevel, char *subsystem, char *event_id, char *msg, char *json_serialized); +void (*do_unreal_log_remote_deliver)(LogLevel loglevel, char *subsystem, char *event_id, MultiLine *msg, char *json_serialized); Efunction *EfunctionAddMain(Module *module, EfunctionType eftype, int (*func)(), void (*vfunc)(), void *(*pvfunc)(), char *(*cfunc)()) { diff --git a/src/log.c b/src/log.c index f0ad32bb1..377715b13 100644 --- a/src/log.c +++ b/src/log.c @@ -913,29 +913,31 @@ literal: } /** Do the actual writing to log files */ -void do_unreal_log_disk(LogLevel loglevel, char *subsystem, char *event_id, char *msg, char *json_serialized) +void do_unreal_log_disk(LogLevel loglevel, char *subsystem, char *event_id, MultiLine *msg, char *json_serialized) { static int last_log_file_warning = 0; Log *l; - char text_buf[2048], timebuf[128]; + char timebuf[128]; struct stat fstats; int n; int write_error; long snomask; + MultiLine *m; snprintf(timebuf, sizeof(timebuf), "[%s] ", myctime(TStime())); - snprintf(text_buf, sizeof(text_buf), "%s %s %s: %s\n", - log_level_valtostring(loglevel), subsystem, event_id, msg); //RunHook3(HOOKTYPE_LOG, flags, timebuf, text_buf); // FIXME: call with more parameters and possibly not even 'text_buf' at all if (!loop.ircd_forked && (loglevel > ULOG_DEBUG)) { + for (m = msg; m; m = m->next) + { #ifdef _WIN32 - win_log("* %s", text_buf); + win_log("* %s %s.%s%s: %s\n", log_level_valtostring(loglevel), subsystem, event_id, m->next?"+":"", m->line); #else - fprintf(stderr, "%s", text_buf); + fprintf(stderr, "%s %s.%s%s: %s\n", log_level_valtostring(loglevel), subsystem, event_id, m->next?"+":"", m->line); #endif + } } /* In case of './unrealircd configtest': don't write to log file, only to stderr */ @@ -951,7 +953,8 @@ void do_unreal_log_disk(LogLevel loglevel, char *subsystem, char *event_id, char #ifdef HAVE_SYSLOG if (l->file && !strcasecmp(l->file, "syslog")) { - syslog(LOG_INFO, "%s", text_buf); + for (m = msg; m; m = m->next) + syslog(LOG_INFO, "%s %s.%s%s: %s", log_level_valtostring(loglevel), subsystem, event_id, m->next?"+":"", m->line); continue; } #endif @@ -1022,7 +1025,7 @@ void do_unreal_log_disk(LogLevel loglevel, char *subsystem, char *event_id, char if ((l->type == LOG_TYPE_JSON) && strcmp(subsystem, "traffic")) { n = write(l->logfd, json_serialized, strlen(json_serialized)); - if (n < strlen(text_buf)) + if (n < strlen(json_serialized)) write_error = 1; else write(l->logfd, "\n", 1); // FIXME: no.. we should do it this way..... and why do we use direct I/O at all? @@ -1035,9 +1038,17 @@ void do_unreal_log_disk(LogLevel loglevel, char *subsystem, char *event_id, char /* Let's ignore any write errors for this one. Next write() will catch it... */ ; } - n = write(l->logfd, text_buf, strlen(text_buf)); - if (n < strlen(text_buf)) - write_error = 1; + for (m = msg; m; m = m->next) + { + char text_buf[1024]; + snprintf(text_buf, sizeof(text_buf), "%s %s.%s%s: %s\n", log_level_valtostring(loglevel), subsystem, event_id, m->next?"+":"", m->line); + n = write(l->logfd, text_buf, strlen(text_buf)); + if (n < strlen(text_buf)) + { + write_error = 1; + break; + } + } } if (write_error) @@ -1099,7 +1110,7 @@ char *log_to_snomask(LogLevel loglevel, char *subsystem, char *event_id) #define COLOR_NONE "\xf" #define COLOR_DARKGREY "\00314" /** Do the actual writing to log files */ -void do_unreal_log_ircops(LogLevel loglevel, char *subsystem, char *event_id, char *msg, char *json_serialized) +void do_unreal_log_ircops(LogLevel loglevel, char *subsystem, char *event_id, MultiLine *msg, char *json_serialized) { Client *client; char *snomask_destinations; @@ -1107,6 +1118,7 @@ void do_unreal_log_ircops(LogLevel loglevel, char *subsystem, char *event_id, ch char *p; char found; MessageTag *mtags = NULL; + MultiLine *m; /* If not fully booted then we don't have a logging to snomask mapping so can't do much.. */ if (!loop.ircd_booted) @@ -1157,18 +1169,25 @@ void do_unreal_log_ircops(LogLevel loglevel, char *subsystem, char *event_id, ch log_level_color(loglevel), log_level_valtostring(loglevel), COLOR_NONE, COLOR_DARKGREY, subsystem, event_id, COLOR_NONE, msg);*/ - sendto_one(client, mtags, ":%s NOTICE %s :%s%s.%s%s %s[%s]%s %s", - me.name, client->name, - COLOR_DARKGREY, subsystem, event_id, COLOR_NONE, - log_level_color(loglevel), log_level_valtostring(loglevel), COLOR_NONE, - msg); + for (m = msg; m; m = m->next) + { + char subsystem_and_event_id[256]; + snprintf(subsystem_and_event_id, sizeof(subsystem_and_event_id), "%s%s.%s%s%s", + COLOR_DARKGREY, subsystem, event_id, COLOR_NONE, m->next?"+":""); + sendto_one(client, mtags, ":%s NOTICE %s :%s %s[%s]%s %s", + me.name, client->name, + subsystem_and_event_id, + log_level_color(loglevel), log_level_valtostring(loglevel), COLOR_NONE, + m->line); + // FIXME: only send json once ;) + } } if (mtags) free_message_tags(mtags); } -void do_unreal_log_remote(LogLevel loglevel, char *subsystem, char *event_id, char *msg, char *json_serialized) +void do_unreal_log_remote(LogLevel loglevel, char *subsystem, char *event_id, MultiLine *msg, char *json_serialized) { Log *l; int found = 0; @@ -1226,6 +1245,7 @@ void do_unreal_log_internal(LogLevel loglevel, char *subsystem, char *event_id, json_t *j_details = NULL; char msgbuf[1024]; char *loglevel_string = log_level_valtostring(loglevel); + MultiLine *mmsg; /* TODO: Enforcement: * - loglevel must be valid @@ -1299,34 +1319,38 @@ void do_unreal_log_internal(LogLevel loglevel, char *subsystem, char *event_id, /* Generate the JSON */ json_serialized = json_dumps(j, JSON_COMPACT); + /* Convert the message buffer to MultiLine */ + mmsg = line2multiline(msgbuf); + /* Now call the disk loggers */ - do_unreal_log_disk(loglevel, subsystem, event_id, msgbuf, json_serialized); + do_unreal_log_disk(loglevel, subsystem, event_id, mmsg, json_serialized); /* And the ircops stuff */ - do_unreal_log_ircops(loglevel, subsystem, event_id, msgbuf, json_serialized); + do_unreal_log_ircops(loglevel, subsystem, event_id, mmsg, json_serialized); - do_unreal_log_remote(loglevel, subsystem, event_id, msgbuf, json_serialized); + do_unreal_log_remote(loglevel, subsystem, event_id, mmsg, json_serialized); // NOTE: code duplication further down! /* Free everything */ safe_free(json_serialized); + safe_free_multiline(mmsg); json_decref(j_details); json_decref(j); } void do_unreal_log_internal_from_remote(LogLevel loglevel, char *subsystem, char *event_id, - char *msgbuf, char *json_serialized) + MultiLine *msg, char *json_serialized) { if (unreal_log_recursion_trap) return; unreal_log_recursion_trap = 1; /* Call the disk loggers */ - do_unreal_log_disk(loglevel, subsystem, event_id, msgbuf, json_serialized); + do_unreal_log_disk(loglevel, subsystem, event_id, msg, json_serialized); /* And the ircops stuff */ - do_unreal_log_ircops(loglevel, subsystem, event_id, msgbuf, json_serialized); + do_unreal_log_ircops(loglevel, subsystem, event_id, msg, json_serialized); unreal_log_recursion_trap = 0; } diff --git a/src/modules/slog.c b/src/modules/slog.c index 02178d57c..a492b82a2 100644 --- a/src/modules/slog.c +++ b/src/modules/slog.c @@ -33,7 +33,7 @@ ModuleHeader MOD_HEADER /* Forward declarations */ CMD_FUNC(cmd_slog); -void _do_unreal_log_remote_deliver(LogLevel loglevel, char *subsystem, char *event_id, char *msg, char *json_serialized); +void _do_unreal_log_remote_deliver(LogLevel loglevel, char *subsystem, char *event_id, MultiLine *msg, char *json_serialized); MOD_TEST() { @@ -70,6 +70,7 @@ CMD_FUNC(cmd_slog) char *json_incoming = NULL; char *json_serialized = NULL; MessageTag *m; + MultiLine *mmsg = NULL; json_t *j, *jt; json_error_t jerr; const char *original_timestamp; @@ -103,12 +104,23 @@ CMD_FUNC(cmd_slog) j = json_loads(json_incoming, JSON_REJECT_DUPLICATES, &jerr); if (!j) { - unreal_log(ULOG_INFO, "log", "REMOTE_LOG_INVALID_FORMAT", client, + unreal_log(ULOG_INFO, "log", "REMOTE_LOG_INVALID", client, "Received malformed JSON in server-to-server log message (SLOG) from $client", log_data_string("bad_json_serialized", json_incoming)); return; } + jt = json_object_get(j, "msg"); + if (!jt) + { + unreal_log(ULOG_INFO, "log", "REMOTE_LOG_INVALID", client, + "Missing 'msg' in JSON in server-to-server log message (SLOG) from $client", + log_data_string("bad_json_serialized", json_incoming)); + json_decref(j); + return; + } + mmsg = line2multiline(msg); + /* Set "timestamp", and save the original one in "original_timestamp" (if it existed) */ jt = json_object_get(j, "timestamp"); if (jt) @@ -124,28 +136,34 @@ CMD_FUNC(cmd_slog) json_serialized = json_dumps(j, JSON_COMPACT); if (json_serialized) - do_unreal_log_internal_from_remote(loglevel, subsystem, event_id, msg, json_serialized); + do_unreal_log_internal_from_remote(loglevel, subsystem, event_id, mmsg, json_serialized); - /* Free the JSON that we worked on */ - safe_free(json_serialized); - json_decref(j); - - /* And broadcast to the other servers */ + /* Broadcast to the other servers */ sendto_server(client, 0, 0, recv_mtags, ":%s SLOG %s %s %s :%s", client->id, parv[1], parv[2], parv[3], parv[4]); + + /* Free everything */ + safe_free(json_serialized); + json_decref(j); + safe_free_multiline(mmsg); } -void _do_unreal_log_remote_deliver(LogLevel loglevel, char *subsystem, char *event_id, char *msg, char *json_serialized) +void _do_unreal_log_remote_deliver(LogLevel loglevel, char *subsystem, char *event_id, MultiLine *msg, char *json_serialized) { MessageTag *mtags = safe_alloc(sizeof(MessageTag)); safe_strdup(mtags->name, "unrealircd.org/json-log"); safe_strdup(mtags->value, json_serialized); + /* Note that we only send the first line (msg->line), + * even for a multi-line event. + * If the recipient really wants to see everything then + * they can use the JSON data. + */ sendto_server(NULL, 0, 0, mtags, ":%s SLOG %s %s %s :%s", me.id, - log_level_valtostring(loglevel), subsystem, event_id, msg); + log_level_valtostring(loglevel), subsystem, event_id, msg->line); free_message_tags(mtags); }