Add support for JSON logging in sudo_logsrvd.

doc/sudo_logsrvd.conf.man.in

@@ -16,7 +16,7 @@
 .\" ACTION OF CONTRACT, NEGLIGENCE OR OTHER TORTIOUS ACTION, ARISING OUT OF
 .\" OR IN CONNECTION WITH THE USE OR PERFORMANCE OF THIS SOFTWARE.
 .\"
-.TH "SUDO_LOGSRVD.CONF" "@mansectform@" "January 23, 2020" "Sudo @PACKAGE_VERSION@" "File Formats Manual"
+.TH "SUDO_LOGSRVD.CONF" "@mansectform@" "February 15, 2020" "Sudo @PACKAGE_VERSION@" "File Formats Manual"
 .nh
 .if n .ad l
 .SH "NAME"
@@ -404,8 +404,13 @@ The default value is
 .TP 6n
 log_format = string
 The event log format.
-Currently, only sudo-style event logs are supported.
+Supported log formats are
-Other log formats may be added in the future.
+\(lqsudo\(rq
+for traditional sudo-style logs and
+\(lqjson\(rq
+for JSON-format logs.
+The JSON log entries contain the full contents of the accept, reject
+and alert messages.
 The default value is
 \fIsudo\fR.
 .SS "syslog"

doc/sudo_logsrvd.conf.mdoc.in

@@ -15,7 +15,7 @@
 .\" ACTION OF CONTRACT, NEGLIGENCE OR OTHER TORTIOUS ACTION, ARISING OUT OF
 .\" OR IN CONNECTION WITH THE USE OR PERFORMANCE OF THIS SOFTWARE.
 .\"
-.Dd January 23, 2020
+.Dd February 15, 2020
 .Dt SUDO_LOGSRVD.CONF @mansectform@
 .Os Sudo @PACKAGE_VERSION@
 .Sh NAME
@@ -355,8 +355,13 @@ The default value is
 .Em syslog .
 .It log_format = string
 The event log format.
-Currently, only sudo-style event logs are supported.
+Supported log formats are
-Other log formats may be added in the future.
+.Dq sudo
+for traditional sudo-style logs and
+.Dq json
+for JSON-format logs.
+The JSON log entries contain the full contents of the accept, reject
+and alert messages.
 The default value is
 .Em sudo .
 .El

examples/sudo_logsrvd.conf

@@ -114,7 +114,8 @@
 #log_type = syslog
 
 # Event log format.
-# Currently only sudo-style event logs are supported.
+# Supported log formats are "sudo" and "json"
+# Defaults to sudo
 #log_format = sudo
 
 [syslog]

logsrvd/eventlog.c

@@ -49,6 +49,7 @@
 #include "sudo_gettext.h"	/* must be included before sudo_compat.h */
 #include "sudo_compat.h"
 #include "sudo_fatal.h"
+#include "sudo_json.h"
 #include "sudo_queue.h"
 #include "sudo_debug.h"
 #include "sudo_util.h"
@@ -252,17 +253,20 @@ mysyslog(int pri, const char *fmt, ...)
  * Log a message to syslog, pre-pending the username and splitting the
  * message into parts if it is longer than syslog_maxlen.
  */
-static void
+static bool
-do_syslog(int pri, const struct iolog_details *details, char *msg)
+do_syslog(int pri, const char *reason, const struct iolog_details *details)
 {
     size_t len, maxlen;
-    char *p, *tmp, save;
+    char *logline, *p, *tmp, save;
     const char *fmt;
     debug_decl(do_syslog, SUDO_DEBUG_UTIL);
 
     /* A priority of -1 corresponds to "none". */
     if (pri == -1)
-	debug_return;
+	debug_return_bool(true);
+
+    if ((logline = new_logline(reason, NULL, details)) == NULL)
+	debug_return_bool(false);
 
     /*
      * Log the full line, breaking into multiple syslog(3) calls if necessary
@@ -270,7 +274,7 @@ do_syslog(int pri, const struct iolog_details *details, char *msg)
     fmt = _("%8s : %s");
     maxlen = logsrvd_conf_syslog_maxlen() -
 	(strlen(fmt) - 5 + strlen(details->submituser));
-    for (p = msg; *p != '\0'; ) {
+    for (p = logline; *p != '\0'; ) {
 	len = strlen(p);
 	if (len > maxlen) {
 	    /*
@@ -300,21 +304,25 @@ do_syslog(int pri, const struct iolog_details *details, char *msg)
 	maxlen = logsrvd_conf_syslog_maxlen() -
 	    (strlen(fmt) - 5 + strlen(details->submituser));
     }
+    free(logline);
 
-    debug_return;
+    debug_return_bool(true);
 }
 
 static bool
-do_logfile(const char *logfile, const struct iolog_details *details,
+do_logfile_sudo(const char *reason, const struct iolog_details *details)
-    const char *msg)
 {
     const char *timefmt = logsrvd_conf_logfile_time_format();
-    char timebuf[8192], *timestr = NULL;
+    const char *logfile = logsrvd_conf_logfile_path();
+    char *logline, timebuf[8192], *timestr = NULL;
     struct tm *timeptr;
     bool ret = false;
     mode_t oldmask;
     FILE *fp;
-    debug_decl(do_logfile, SUDO_DEBUG_UTIL);
+    debug_decl(do_logfile_sudo, SUDO_DEBUG_UTIL);
+
+    if ((logline = new_logline(reason, NULL, details)) == NULL)
+	debug_return_bool(false);
 
     oldmask = umask(S_IRWXG|S_IRWXO);
     fp = fopen(logfile, "a");
@@ -339,7 +347,7 @@ do_logfile(const char *logfile, const struct iolog_details *details,
 	}
     }
     (void)fprintf(fp, "%s : %s : %s", timestr ? timestr : "invalid date",
-	details->submituser, msg);
+	details->submituser, logline);
     (void)fflush(fp);
     if (ferror(fp)) {
 	sudo_debug_printf(SUDO_DEBUG_ERROR|SUDO_DEBUG_LINENO|SUDO_DEBUG_ERRNO,
@@ -351,14 +359,251 @@ do_logfile(const char *logfile, const struct iolog_details *details,
 done:
     if (fp != NULL)
 	(void) fclose(fp);
+    free(logline);
+    debug_return_bool(ret);
+}
+
+static bool
+json_add_timestamp(struct json_container *json, const char *name,
+    struct timespec *ts)
+{
+    const char *timefmt = logsrvd_conf_logfile_time_format();
+    struct json_value json_value;
+    time_t secs = ts->tv_sec;
+    char timebuf[1024];
+    struct tm *tm;
+    debug_decl(json_add_timestamp, SUDO_DEBUG_PLUGIN);
+
+    if ((tm = gmtime(&secs)) == NULL)
+	debug_return_bool(false);
+
+    if (!sudo_json_open_object(json, name))
+	goto oom;
+
+    json_value.type = JSON_NUMBER;
+    json_value.u.number = ts->tv_sec;
+    if (!sudo_json_add_value(json, "seconds", &json_value))
+	goto oom;
+
+    json_value.type = JSON_NUMBER;
+    json_value.u.number = ts->tv_nsec;
+    if (!sudo_json_add_value(json, "nanoseconds", &json_value))
+	goto oom;
+
+    strftime(timebuf, sizeof(timebuf), "%Y%m%d%H%M%SZ", tm);
+    json_value.type = JSON_STRING;
+    json_value.u.string = timebuf;
+    if (!sudo_json_add_value(json, "iso8601", &json_value))
+	goto oom;
+
+    strftime(timebuf, sizeof(timebuf), timefmt, tm);
+    json_value.type = JSON_STRING;
+    json_value.u.string = timebuf;
+    if (!sudo_json_add_value(json, "localtime", &json_value))
+	goto oom;
+
+    if (!sudo_json_close_object(json))
+	goto oom;
+
+    debug_return_bool(true);
+oom:
+    sudo_debug_printf(SUDO_DEBUG_ERROR|SUDO_DEBUG_ERRNO|SUDO_DEBUG_LINENO,
+	"%s: %s", __func__, "unable to allocate memory");
+    debug_return_bool(false);
+}
+
+static bool
+do_logfile_json(ClientMessage__TypeCase event_type, const char *reason,
+    TimeSpec *event_time, InfoMessage **info_msgs, size_t infolen)
+{
+    const char *logfile = logsrvd_conf_logfile_path();
+    const char *type_str;
+    const char *time_str;
+    struct json_container json;
+    struct json_value json_value;
+    struct timespec ts;
+    struct stat sb;
+    char **strvec;
+    mode_t oldmask;
+    FILE *fp = NULL;
+    int fd, ret = false;
+    size_t idx;
+    debug_decl(do_logfile_json, SUDO_DEBUG_UTIL);
+
+    if (sudo_gettime_real(&ts) == -1) {
+	sudo_debug_printf(SUDO_DEBUG_ERROR|SUDO_DEBUG_LINENO|SUDO_DEBUG_ERRNO,
+	    "unable to read the clock");
+	debug_return_bool(ret);
+    }
+
+    switch (event_type) {
+    case CLIENT_MESSAGE__TYPE_ACCEPT_MSG:
+	type_str = "accept";
+	time_str = "submit_time";
+	break;
+    case CLIENT_MESSAGE__TYPE_REJECT_MSG:
+	type_str = "reject";
+	time_str = "submit_time";
+	break;
+    case CLIENT_MESSAGE__TYPE_ALERT_MSG:
+	type_str = "alert";
+	time_str = "alert_time";
+	break;
+    default:
+	sudo_debug_printf(SUDO_DEBUG_ERROR|SUDO_DEBUG_LINENO,
+	    "unexpected event type %d", event_type);
+	debug_return_bool(ret);
+    }
+
+    if (!sudo_json_init(&json, 4, false, false))
+	goto done;
+    if (!sudo_json_open_object(&json, type_str))
+	goto done;
+
+    /* Reject and Alert events include a reason */
+    if (reason != NULL) {
+	json_value.type = JSON_STRING;
+	json_value.u.string = reason;
+	if (!sudo_json_add_value(&json, "reason", &json_value))
+	    goto done;
+    }
+
+    /* XXX - create and log uuid? */
+
+    /* Log event time on server (set earlier) */
+    if (!json_add_timestamp(&json, "server_time", &ts)) {
+	sudo_debug_printf(SUDO_DEBUG_ERROR|SUDO_DEBUG_ERRNO|SUDO_DEBUG_LINENO,
+	    "unable format timestamp");
+	goto done;
+    }
+
+    /* Log event time from client */
+    ts.tv_sec = event_time->tv_sec;
+    ts.tv_nsec = event_time->tv_nsec;
+    if (!json_add_timestamp(&json, time_str, &ts)) {
+	sudo_debug_printf(SUDO_DEBUG_ERROR|SUDO_DEBUG_ERRNO|SUDO_DEBUG_LINENO,
+	    "unable format timestamp");
+	goto done;
+    }
+
+    /* Dump details */
+    for (idx = 0; idx < infolen; idx++) {
+	InfoMessage *info = info_msgs[idx];
+
+	switch (info->value_case) {
+	case INFO_MESSAGE__VALUE_NUMVAL:
+	    json_value.type = JSON_NUMBER;
+	    json_value.u.number = info->numval;
+	    if (!sudo_json_add_value(&json, info->key, &json_value))
+		goto done;
+	    break;
+	case INFO_MESSAGE__VALUE_STRVAL:
+	    json_value.type = JSON_STRING;
+	    json_value.u.string = info->strval;
+	    if (!sudo_json_add_value(&json, info->key, &json_value))
+		goto done;
+	    break;
+	case INFO_MESSAGE__VALUE_STRLISTVAL:
+	    /* Must convert to NULL-terminated string vector. */
+	    strvec = strlist_copy(info->strlistval);
+	    if (strvec == NULL) {
+		sudo_debug_printf(SUDO_DEBUG_ERROR|SUDO_DEBUG_ERRNO|SUDO_DEBUG_LINENO,
+		    "%s: %s", __func__, "unable to allocate memory");
+		goto done;
+	    }
+	    json_value.type = JSON_ARRAY;
+	    json_value.u.array = strvec;
+	    if (!sudo_json_add_value(&json, info->key, &json_value))
+		goto done;
+	    free(strvec);
+	    break;
+	default:
+	    sudo_debug_printf(SUDO_DEBUG_ERROR|SUDO_DEBUG_LINENO,
+		"unexpected value case %d", info->value_case);
+	    goto done;
+	}
+    }
+
+    if (!sudo_json_close_object(&json))
+	goto done;
+
+    oldmask = umask(S_IRWXG|S_IRWXO);
+    fd = open(logfile, O_RDWR|O_CREAT, S_IRUSR|S_IWUSR);
+    (void)umask(oldmask);
+    if (fd == -1 || (fp = fdopen(fd, "w")) == NULL) {
+	sudo_debug_printf(SUDO_DEBUG_ERROR|SUDO_DEBUG_LINENO|SUDO_DEBUG_ERRNO,
+	    "unable to open log file %s", logfile);
+	if (fd != -1)
+	    close(fd);
+	goto done;
+    }
+    if (!sudo_lock_file(fileno(fp), SUDO_LOCK)) {
+	sudo_debug_printf(SUDO_DEBUG_ERROR|SUDO_DEBUG_LINENO|SUDO_DEBUG_ERRNO,
+	    "unable to lock log file %s", logfile);
+	goto done;
+    }
+
+    /* Note: assumes file ends in "\n}\n" */
+    if (fstat(fileno(fp), &sb) == -1) {
+	sudo_debug_printf(SUDO_DEBUG_ERROR|SUDO_DEBUG_ERRNO|SUDO_DEBUG_LINENO,
+	    "unable to stat %s", logfile);
+	goto done;
+    }
+    if (sb.st_size == 0) {
+	/* New file */
+	putc('{', fp);
+    } else if (fseeko(fp, -3, SEEK_END) == 0) {
+	/* Continue file, overwrite the final "\n}\n" */
+	putc(',', fp);
+    } else {
+	sudo_debug_printf(SUDO_DEBUG_ERROR|SUDO_DEBUG_ERRNO|SUDO_DEBUG_LINENO,
+	    "unable to seek %s", logfile);
+	goto done;
+    }
+    fputs(sudo_json_get_buf(&json), fp);
+    fputs("\n}\n", fp);			/* close JSON */
+    fclose(fp);
+    /* XXX - check for file error and recover */
+
+    ret = true;
+
+done:
+    sudo_json_free(&json);
+    if (fp != NULL)
+	fclose(fp);
+    debug_return_bool(ret);
+}
+
+static bool
+do_logfile(ClientMessage__TypeCase event_type, const char *reason,
+    const struct iolog_details *details, TimeSpec *event_time,
+    InfoMessage **info_msgs, size_t infolen)
+{
+    bool ret = false;
+    debug_decl(do_logfile, SUDO_DEBUG_UTIL);
+
+    switch (logsrvd_conf_eventlog_format()) {
+    case EVLOG_SUDO:
+	ret = do_logfile_sudo(reason, details);
+	break;
+    case EVLOG_JSON:
+	ret = do_logfile_json(event_type, reason, event_time,
+	    info_msgs, infolen);
+	break;
+    default:
+	sudo_debug_printf(SUDO_DEBUG_ERROR|SUDO_DEBUG_LINENO,
+	    "unexpected eventlog format %d", logsrvd_conf_eventlog_format());
+	break;
+    }
+
     debug_return_bool(ret);
 }
 
 bool
-log_accept(const struct iolog_details *details)
+log_accept(const struct iolog_details *details, TimeSpec *submit_time,
+    InfoMessage **info_msgs, size_t infolen)
 {
     const enum logsrvd_eventlog_type log_type = logsrvd_conf_eventlog_type();
-    char *logline;
     bool ret = true;
     int pri;
     debug_decl(log_accept, SUDO_DEBUG_UTIL);
@@ -366,33 +611,30 @@ log_accept(const struct iolog_details *details)
     if (log_type == EVLOG_NONE)
 	debug_return_bool(true);
 
-    if ((logline = new_logline(NULL, NULL, details)) == NULL)
-	debug_return_bool(false);
-
     switch (log_type) {
     case EVLOG_SYSLOG:
 	pri = logsrvd_conf_syslog_acceptpri();
 	if (pri != -1)
-	    do_syslog(pri, details, logline);
+	    ret = do_syslog(pri, NULL, details);
 	break;
     case EVLOG_FILE:
-	ret = do_logfile(logsrvd_conf_logfile_path(), details, logline);
+	ret = do_logfile(CLIENT_MESSAGE__TYPE_ACCEPT_MSG, NULL, details,
+	    submit_time, info_msgs, infolen);
 	break;
     default:
 	sudo_debug_printf(SUDO_DEBUG_ERROR|SUDO_DEBUG_LINENO,
 	    "unexpected eventlog type %d", log_type);
 	ret = false;
     }
-    free(logline);
 
     debug_return_bool(ret);
 }
 
 bool
-log_reject(const struct iolog_details *details, const char *reason)
+log_reject(const struct iolog_details *details, const char *reason,
+    TimeSpec *submit_time, InfoMessage **info_msgs, size_t infolen)
 {
     const enum logsrvd_eventlog_type log_type = logsrvd_conf_eventlog_type();
-    char *logline;
     bool ret = true;
     int pri;
     debug_decl(log_reject, SUDO_DEBUG_UTIL);
@@ -400,24 +642,21 @@ log_reject(const struct iolog_details *details, const char *reason)
     if (log_type == EVLOG_NONE)
 	debug_return_bool(true);
 
-    if ((logline = new_logline(reason, NULL, details)) == NULL)
-	debug_return_bool(false);
-
     switch (log_type) {
     case EVLOG_SYSLOG:
 	pri = logsrvd_conf_syslog_rejectpri();
 	if (pri != -1)
-	    do_syslog(pri, details, logline);
+	    do_syslog(pri, reason, details);
 	break;
     case EVLOG_FILE:
-	ret = do_logfile(logsrvd_conf_logfile_path(), details, logline);
+	ret = do_logfile(CLIENT_MESSAGE__TYPE_REJECT_MSG, reason, details,
+	    submit_time, info_msgs, infolen);
 	break;
     default:
 	sudo_debug_printf(SUDO_DEBUG_ERROR|SUDO_DEBUG_LINENO,
 	    "unexpected eventlog type %d", log_type);
 	ret = false;
     }
-    free(logline);
 
     debug_return_bool(ret);
 }
@@ -427,7 +666,6 @@ log_alert(const struct iolog_details *details, TimeSpec *alert_time,
     const char *reason)
 {
     const enum logsrvd_eventlog_type log_type = logsrvd_conf_eventlog_type();
-    char *logline;
     bool ret = true;
     int pri;
     debug_decl(log_alert, SUDO_DEBUG_UTIL);
@@ -435,25 +673,22 @@ log_alert(const struct iolog_details *details, TimeSpec *alert_time,
     if (log_type == EVLOG_NONE)
 	debug_return_bool(true);
 
-    if ((logline = new_logline(reason, NULL, details)) == NULL)
-	debug_return_bool(false);
-
     /* TODO: log alert_time */
     switch (log_type) {
     case EVLOG_SYSLOG:
 	pri = logsrvd_conf_syslog_alertpri();
 	if (pri != -1)
-	    do_syslog(pri, details, logline);
+	    do_syslog(pri, reason, details);
 	break;
     case EVLOG_FILE:
-	ret = do_logfile(logsrvd_conf_logfile_path(), details, logline);
+	ret = do_logfile(CLIENT_MESSAGE__TYPE_ALERT_MSG, reason, details,
+	    alert_time, NULL, 0);
 	break;
     default:
 	sudo_debug_printf(SUDO_DEBUG_ERROR|SUDO_DEBUG_LINENO,
 	    "unexpected eventlog type %d", log_type);
 	ret = false;
     }
-    free(logline);
 
     debug_return_bool(ret);
 }

logsrvd/iolog_writer.c

@@ -68,7 +68,7 @@ has_strlistval(InfoMessage *info)
  * The input string list need not be NULL-terminated.
  * Returns a NULL-terminated string vector.
  */
-static char **
+char **
 strlist_copy(InfoMessage__StringList *strlist)
 {
     char **dst, **src = strlist->strings;

logsrvd/logsrvd.c

@@ -260,7 +260,8 @@ handle_accept(AcceptMessage *msg, struct connection_closure *closure)
 	}
     }
 
-    if (!log_accept(&closure->details)) {
+    if (!log_accept(&closure->details, msg->submit_time, msg->info_msgs,
+	    msg->n_info_msgs)) {
 	closure->errstr = _("error logging accept event");
 	debug_return_bool(false);
     }
@@ -319,7 +320,8 @@ handle_reject(RejectMessage *msg, struct connection_closure *closure)
 	debug_return_bool(false);
     }
 
-    if (!log_reject(&closure->details, msg->reason)) {
+    if (!log_reject(&closure->details, msg->reason, msg->submit_time,
+	    msg->info_msgs, msg->n_info_msgs)) {
 	closure->errstr = _("error logging reject event");
 	debug_return_bool(false);
     }
@@ -512,7 +514,7 @@ handle_suspend(CommandSuspend *msg, struct connection_closure *closure)
     sudo_debug_printf(SUDO_DEBUG_INFO, "%s: received CommandSuspend",
 	__func__);
 
-    /* Store suspend siganl in log. */
+    /* Store suspend signal in log. */
     if (store_suspend(msg, closure) == -1) {
 	sudo_debug_printf(SUDO_DEBUG_ERROR|SUDO_DEBUG_LINENO,
 	    "failed to store CommandSuspend");

logsrvd/logsrvd.h

@@ -154,12 +154,13 @@ enum logsrvd_eventlog_type {
 
 /* Supported eventlog formats (currently just sudo) */
 enum logsrvd_eventlog_format {
-    EVLOG_SUDO
+    EVLOG_SUDO,
+    EVLOG_JSON
 };
 
 /* eventlog.c */
-bool log_accept(const struct iolog_details *details);
+bool log_accept(const struct iolog_details *details, TimeSpec *submit_time, InfoMessage **info_msgs, size_t infolen);
-bool log_reject(const struct iolog_details *details, const char *reason);
+bool log_reject(const struct iolog_details *details, const char *reason, TimeSpec *submit_time, InfoMessage **info_msgs, size_t infolen);
 bool log_alert(const struct iolog_details *details, TimeSpec *alert_time, const char *reason);
 
 /* iolog_writer.c */
@@ -171,6 +172,7 @@ int store_suspend(CommandSuspend *msg, struct connection_closure *closure);
 int store_winsize(ChangeWindowSize *msg, struct connection_closure *closure);
 void iolog_close_all(struct connection_closure *closure);
 void iolog_details_free(struct iolog_details *details);
+char ** strlist_copy(InfoMessage__StringList *strlist);
 
 /* logsrvd_conf.c */
 bool logsrvd_conf_read(const char *path);

logsrvd/logsrvd_conf.c

@@ -576,7 +576,9 @@ cb_eventlog_format(struct logsrvd_config *config, const char *str)
 {
     debug_decl(cb_eventlog_format, SUDO_DEBUG_UTIL);
 
-    if (strcmp(str, "sudo") == 0)
+    if (strcmp(str, "json") == 0)
+	config->eventlog.log_format = EVLOG_JSON;
+    else if (strcmp(str, "sudo") == 0)
 	config->eventlog.log_format = EVLOG_SUDO;
     else
 	debug_return_bool(false);
@@ -683,6 +685,7 @@ cb_logfile_path(struct logsrvd_config *config, const char *str)
 	debug_return_bool(false);
     }
 
+    /* TODO: open log file */
     free(config->logfile.path);
     config->logfile.path = copy;