rcolebaugh / rpms / openssh

Forked from rpms/openssh 2 years ago
Clone
d1c05f
--- /dev/null
Michel Lind 1c324b
+++ b/slog.c
d1c05f
@@ -0,0 +1,619 @@
d1c05f
+/*
d1c05f
+ * Copyright 2004-present Facebook. All Rights Reserved.
d1c05f
+ */
d1c05f
+
d1c05f
+ /* When using slogctxt in any module perform a NULL pointer check */
d1c05f
+
d1c05f
+#include <sys/types.h>
d1c05f
+#include <stdlib.h>
d1c05f
+#include <unistd.h>
d1c05f
+#include <stdio.h>
d1c05f
+#include <string.h>
d1c05f
+#include <syslog.h>
d1c05f
+#include <pwd.h>
d1c05f
+#include <time.h>
d1c05f
+
d1c05f
+#include "includes.h"
d1c05f
+#include "slog.h"
d1c05f
+#include "log.h"
d1c05f
+#include "misc.h"
d1c05f
+#include "servconf.h"
d1c05f
+#include "xmalloc.h"
d1c05f
+
d1c05f
+typedef struct Structuredlogctxt Structuredlogctxt;
d1c05f
+
d1c05f
+struct Structuredlogctxt { /* items we care about logging */
d1c05f
+	char		server_ip[SLOG_SHORT_STRING_LEN];		// server_ip
d1c05f
+	int		server_port;		// server_port
d1c05f
+	char		remote_ip[SLOG_SHORT_STRING_LEN];		// remote_ip
d1c05f
+	int		remote_port;		// remote_port
d1c05f
+	pid_t		pam_process_pid;		// pam_pid
d1c05f
+	char		session_id[SLOG_STRING_LEN];		// session_id
d1c05f
+	char		method[SLOG_STRING_LEN];		// method
d1c05f
+	char		cert_id[SLOG_STRING_LEN];		// cert_id
d1c05f
+	unsigned long long		cert_serial;		// cert_serial
d1c05f
+	char		principal[SLOG_STRING_LEN];		// principal
d1c05f
+	char		user[SLOG_STRING_LEN];		// user
d1c05f
+	char		command[SLOG_LONG_STRING_LEN];		// command
d1c05f
+	SLOG_SESSION_STATE		session_state;		// session_state
d1c05f
+	SLOG_AUTHENTICATED		auth_successful;		// auth_successful
d1c05f
+	time_t		start_time;		// start_time
d1c05f
+	time_t		end_time;		// end_time
d1c05f
+	int		duration;		// duration
d1c05f
+	pid_t		main_pid;		// main_pid
d1c05f
+	char		auth_info[SLOG_MEDIUM_STRING_LEN];		// auth_info
d1c05f
+	char		client_version[SLOG_STRING_LEN];		// client_version
d1c05f
+};
d1c05f
+
d1c05f
+Structuredlogctxt *slogctxt;
d1c05f
+extern ServerOptions options;
d1c05f
+
d1c05f
+// Define token constants and default syntax format
d1c05f
+static const char *server_ip_token         = "server_ip";
d1c05f
+static const char *server_port_token       = "server_port";
d1c05f
+static const char *remote_ip_token         = "remote_ip";
d1c05f
+static const char *remote_port_token       = "remote_port";
d1c05f
+static const char *pam_pid_token           = "pam_pid";
d1c05f
+static const char *process_pid_token       = "pid";
d1c05f
+static const char *session_id_token        = "session_id";
d1c05f
+static const char *method_token            = "method";
d1c05f
+static const char *cert_id_token           = "cert_id";
d1c05f
+static const char *cert_serial_token       = "cert_serial";
d1c05f
+static const char *principal_token         = "principal";
d1c05f
+static const char *user_token              = "user";
d1c05f
+static const char *command_token           = "command";
d1c05f
+static const char *session_state_token     = "session_state";
d1c05f
+static const char *auth_successful_token   = "auth_successful";
d1c05f
+static const char *start_time_token        = "start_time";
d1c05f
+static const char *end_time_token          = "end_time";
d1c05f
+static const char *duration_token          = "duration";
d1c05f
+static const char *main_pid_token          = "main_pid";
d1c05f
+static const char *auth_info_token         = "auth_info";
d1c05f
+static const char *client_version          = "client_version";
d1c05f
+
d1c05f
+/* Example log format sshd_config
d1c05f
+ * LogFormatPrefix sshd_auth_msg:
d1c05f
+ * LogFormatKeys server_ip server_port remote_ip remote_port pid session_id /
d1c05f
+   method cert_id cert_serial principal user session_state auth_successful /
d1c05f
+   start_time command # NO LINE BREAKS
d1c05f
+ * LogFormatJson yes # no makes this output an json array vs json object
d1c05f
+ */
d1c05f
+
d1c05f
+// Set a arbitrary large size so we can feed a potentially
d1c05f
+// large json object to the logger
d1c05f
+#define SLOG_BUF_SIZE 8192
d1c05f
+#define SLOG_TRUNCATED_MESSAGE_JSON ", \"incomplete\": \"true\"}"
d1c05f
+#define SLOG_TRUNCATED_MESSAGE_ARRAY ", \"incomplete\"]"
d1c05f
+#define SLOG_TRUNCATED_SIZE 25
d1c05f
+/* size of format for JSON for quotes_colon_space around key and comma_space
d1c05f
+   after value or closure_null */
d1c05f
+#define SLOG_JSON_FORMAT_SIZE 6
d1c05f
+#define SLOG_BUF_CALC_SIZE  SLOG_BUF_SIZE - SLOG_TRUNCATED_SIZE
d1c05f
+
d1c05f
+/* private declarations */
d1c05f
+static void slog_log(void);
d1c05f
+static void slog_cleanup(void);
d1c05f
+static void slog_generate_auth_payload(char *);
d1c05f
+static void slog_escape_value(char *, char *, size_t);
d1c05f
+static void slog_get_safe_from_token(char *, const char *);
d1c05f
+static const char* slog_get_state_text(void);
d1c05f
+
d1c05f
+/* public functions */
d1c05f
+
d1c05f
+void
d1c05f
+slog_init(void)
d1c05f
+{
d1c05f
+	/* initialize only if we have log_format_keys */
d1c05f
+	if (options.num_log_format_keys != 0) {
d1c05f
+		slogctxt = xcalloc(1, sizeof(Structuredlogctxt));
d1c05f
+		if (slogctxt != NULL)
d1c05f
+			slog_cleanup();
d1c05f
+	}
d1c05f
+}
d1c05f
+
d1c05f
+void
d1c05f
+slog_pam_session_opened(void)
d1c05f
+{
d1c05f
+	if (slogctxt != NULL) {
d1c05f
+		slogctxt->session_state = SLOG_SESSION_OPEN;
d1c05f
+		slogctxt->pam_process_pid = getpid();
d1c05f
+	}
d1c05f
+}
d1c05f
+
d1c05f
+void
d1c05f
+slog_set_auth_data(int authenticated, const char *method, const char *user)
d1c05f
+{
d1c05f
+	if (slogctxt != NULL) {
d1c05f
+		slogctxt->auth_successful =
d1c05f
+		    authenticated ? SLOG_AUTHORIZED : SLOG_UNAUTHORIZED;
d1c05f
+		strlcpy(slogctxt->method, method, SLOG_SHORT_STRING_LEN);
d1c05f
+		strlcpy(slogctxt->user, user, SLOG_STRING_LEN);
d1c05f
+	}
d1c05f
+}
d1c05f
+
d1c05f
+void
d1c05f
+slog_set_cert_id(const char *id)
d1c05f
+{
d1c05f
+	if (slogctxt != NULL)
d1c05f
+		strlcpy(slogctxt->cert_id, id, SLOG_STRING_LEN);
d1c05f
+}
d1c05f
+
d1c05f
+
d1c05f
+void
d1c05f
+slog_set_cert_serial(unsigned long long serial)
d1c05f
+{
d1c05f
+	if (slogctxt != NULL)
d1c05f
+		slogctxt->cert_serial = serial;
d1c05f
+}
d1c05f
+
d1c05f
+void
d1c05f
+slog_set_connection(const char *remote_ip, int remote_port,
d1c05f
+    const char *server_ip, int server_port, const char *session)
d1c05f
+{
d1c05f
+	if (slogctxt != NULL) {
d1c05f
+		strlcpy(slogctxt->remote_ip, remote_ip, SLOG_SHORT_STRING_LEN);
d1c05f
+		slogctxt->remote_port = remote_port;
d1c05f
+		strlcpy(slogctxt->server_ip, server_ip, SLOG_SHORT_STRING_LEN);
d1c05f
+		slogctxt->server_port = server_port;
d1c05f
+		strlcpy(slogctxt->session_id, session, SLOG_STRING_LEN);
d1c05f
+		slogctxt->start_time = time(NULL);
d1c05f
+		slogctxt->main_pid = getpid();
d1c05f
+	}
d1c05f
+}
d1c05f
+
d1c05f
+void
d1c05f
+slog_set_client_version(const char *version)
d1c05f
+{
d1c05f
+	if (slogctxt != NULL) {
d1c05f
+		if (strlen(version) < SLOG_STRING_LEN)
d1c05f
+			strlcpy(slogctxt->client_version, version, SLOG_STRING_LEN);
d1c05f
+		else {
d1c05f
+			// version can be up to 256 bytes, truncate to 95 and add ' ...'
d1c05f
+			// which will fit in SLOG_STRING_LEN
d1c05f
+			snprintf(slogctxt->client_version, SLOG_STRING_LEN, "%.95s ...", version);
d1c05f
+		}
d1c05f
+	}
d1c05f
+}
d1c05f
+
d1c05f
+void
d1c05f
+slog_set_command(const char *command)
d1c05f
+{
d1c05f
+	if (slogctxt != NULL) {
d1c05f
+		if (strlen(command) < SLOG_LONG_STRING_LEN)
d1c05f
+			strlcpy(slogctxt->command, command, SLOG_LONG_STRING_LEN);
d1c05f
+		else {
d1c05f
+			// If command is longer than allowed we truncate it to
d1c05f
+			// 1995 (SLOG_LONG_STRING_LEN - 5) characters and add ' ...\0' to
d1c05f
+			// the end of the command.
d1c05f
+			snprintf(slogctxt->command, SLOG_LONG_STRING_LEN, "%.1995s ...", command);
d1c05f
+		}
d1c05f
+	}
d1c05f
+}
d1c05f
+
d1c05f
+void
d1c05f
+slog_set_principal(const char *principal)
d1c05f
+{
d1c05f
+	if (slogctxt != NULL)
d1c05f
+		strlcpy(slogctxt->principal, principal, SLOG_STRING_LEN);
d1c05f
+}
d1c05f
+
d1c05f
+void
d1c05f
+slog_set_user(const char *user)
d1c05f
+{
d1c05f
+	if (slogctxt != NULL)
d1c05f
+		strlcpy(slogctxt->user, user, SLOG_STRING_LEN);
d1c05f
+}
d1c05f
+
d1c05f
+void
d1c05f
+slog_set_auth_info(const char *auth_info)
d1c05f
+{
d1c05f
+	if (slogctxt != NULL)
d1c05f
+		strlcpy(slogctxt->auth_info, auth_info, SLOG_MEDIUM_STRING_LEN);
d1c05f
+}
d1c05f
+
d1c05f
+void
d1c05f
+slog_exit_handler(void)
d1c05f
+{
d1c05f
+	/* to prevent duplicate logging we only log based on the pid set */
d1c05f
+	if (slogctxt != NULL) {
d1c05f
+		if (slogctxt->server_ip[0] == 0)
d1c05f
+			return; // not initialized
d1c05f
+		if (slogctxt->main_pid != getpid())
d1c05f
+			return; // not main process
d1c05f
+		if (slogctxt->session_state == SLOG_SESSION_INIT)
d1c05f
+			slog_log();
d1c05f
+		else {
d1c05f
+			slogctxt->session_state = SLOG_SESSION_CLOSED;
d1c05f
+			slogctxt->end_time = time(NULL);
d1c05f
+			slogctxt->duration = slogctxt->end_time - slogctxt->start_time;
d1c05f
+			slog_log();
d1c05f
+			slog_cleanup();
d1c05f
+		}
d1c05f
+  }
d1c05f
+}
d1c05f
+
d1c05f
+void
d1c05f
+slog_log_session(void)
d1c05f
+{
d1c05f
+	if (slogctxt != NULL) {
d1c05f
+		slogctxt->session_state = SLOG_SESSION_OPEN;
d1c05f
+		slog_log();
d1c05f
+	}
d1c05f
+}
d1c05f
+
d1c05f
+/* private function scope begin */
d1c05f
+
d1c05f
+static void
d1c05f
+slog_log(void)
d1c05f
+{
d1c05f
+	char *buffer = xmalloc(SLOG_BUF_SIZE);
d1c05f
+
d1c05f
+	if (buffer == NULL)
d1c05f
+		return;
d1c05f
+
d1c05f
+	memset(buffer, 0, SLOG_BUF_SIZE);
d1c05f
+
d1c05f
+	if (options.num_log_format_keys > 0
d1c05f
+	    && slogctxt != NULL
d1c05f
+	    && slogctxt->server_ip[0] != 0
d1c05f
+	    && slogctxt->user[0] != 0) {
d1c05f
+		slog_generate_auth_payload(buffer);
d1c05f
+		do_log_slog_payload(buffer);
d1c05f
+	}
d1c05f
+
d1c05f
+	free(buffer);
d1c05f
+}
d1c05f
+
d1c05f
+static void
d1c05f
+slog_cleanup(void)
d1c05f
+{
d1c05f
+	// Reset the log context values
d1c05f
+	if (slogctxt != NULL) {
d1c05f
+		memset(slogctxt, 0, sizeof(Structuredlogctxt));
d1c05f
+		slogctxt->session_state = SLOG_SESSION_INIT;
d1c05f
+		slogctxt->auth_successful = SLOG_UNAUTHORIZED;
d1c05f
+	}
d1c05f
+}
d1c05f
+
d1c05f
+/* We use debug3 since the debug is very noisy */
d1c05f
+static void
d1c05f
+slog_generate_auth_payload(char *buf)
d1c05f
+{
d1c05f
+	if (buf == NULL)
d1c05f
+		return;
d1c05f
+
d1c05f
+	// Create large buffer so don't risk overflow
d1c05f
+	char *safe = xmalloc(SLOG_BUF_SIZE);
d1c05f
+	memset(safe, 0, SLOG_BUF_SIZE);
d1c05f
+
d1c05f
+	if (safe == NULL)
d1c05f
+		return;
d1c05f
+
d1c05f
+	int i;
d1c05f
+	size_t remaining;
d1c05f
+	int json = options.log_format_json;
d1c05f
+	int keys = options.num_log_format_keys;
d1c05f
+	int truncated = 0;
d1c05f
+	char *tmpbuf = buf;
d1c05f
+	char *key;
d1c05f
+
d1c05f
+	debug3("JSON format is %d with %d tokens.", json, keys);
d1c05f
+
d1c05f
+	if (options.log_format_prefix != NULL
d1c05f
+	    && strlen(options.log_format_prefix) < SLOG_BUF_CALC_SIZE-1) {
d1c05f
+		tmpbuf += snprintf(tmpbuf, SLOG_BUF_CALC_SIZE,
d1c05f
+	    "%s ", options.log_format_prefix);
d1c05f
+	}
d1c05f
+	*tmpbuf++ = (json) ? '{' : '[';
d1c05f
+	debug3("current buffer after prefix: %s", buf);
d1c05f
+
d1c05f
+	// Loop through the keys filling out the output string
d1c05f
+	for (i = 0; i < keys; i++) {
d1c05f
+		safe[0] = 0;  // clear safe string
d1c05f
+		key = options.log_format_keys[i];
d1c05f
+		remaining = SLOG_BUF_CALC_SIZE - (tmpbuf - buf);
d1c05f
+
d1c05f
+		if (key == NULL)
d1c05f
+			continue;  // Shouldn't happen but if null go to next key
d1c05f
+
d1c05f
+		slog_get_safe_from_token(safe, key);
d1c05f
+		debug3("token: %s, value: %s", key, safe);
d1c05f
+
d1c05f
+		if (json) {
d1c05f
+			if (*safe == '\0')
d1c05f
+				continue; // No value since we are using key pairs skip
d1c05f
+			if (remaining <= SLOG_JSON_FORMAT_SIZE + strlen(key) + strlen(safe)) {
d1c05f
+				debug("Log would exceed buffer size %u, %zu, %zu at key: %s",
d1c05f
+				    (unsigned int)remaining, strlen(key), strlen(safe), key);
d1c05f
+				truncated = 1;
d1c05f
+				break;
d1c05f
+			}
d1c05f
+			tmpbuf += snprintf(tmpbuf, remaining, "%s\"%s\": %s",
d1c05f
+			    i > 0 ? ", " : "", key, safe);
d1c05f
+		} else {
d1c05f
+			if (*safe == '\0')
d1c05f
+				strlcpy(safe, "\"\"", SLOG_SHORT_STRING_LEN);
d1c05f
+			if (remaining < SLOG_JSON_FORMAT_SIZE + strlen(safe)) {
d1c05f
+				debug("Log would exceed remaining buffer size %d, %zu, at key: %s",
d1c05f
+				    (unsigned int)remaining, strlen(safe), key);
d1c05f
+				truncated = 1;
d1c05f
+				break;
d1c05f
+			}
d1c05f
+			tmpbuf += snprintf(tmpbuf, remaining, "%s%s", i > 0 ? ", " : "", safe);
d1c05f
+		}
d1c05f
+		debug3("current buffer after token: %s", buf);
d1c05f
+		debug3("end of loop key: %s, %d out of %d keys", key, i + 1, keys);
d1c05f
+	}
d1c05f
+
d1c05f
+	// Close the log string. If truncated set truncated message and close string
d1c05f
+	if (truncated == 1)
d1c05f
+		strlcpy(tmpbuf, json ? SLOG_TRUNCATED_MESSAGE_JSON :
d1c05f
+		    SLOG_TRUNCATED_MESSAGE_ARRAY, SLOG_TRUNCATED_SIZE);
d1c05f
+	else {
d1c05f
+		*tmpbuf++ = (json) ? '}' : ']';
d1c05f
+	}
d1c05f
+
d1c05f
+	free(safe);
d1c05f
+}
d1c05f
+
d1c05f
+// buffer size is input string * 2 +1
d1c05f
+static void
d1c05f
+slog_escape_value(char *output, char *input, size_t buffer_size)
d1c05f
+{
d1c05f
+	int i;
d1c05f
+	buffer_size -= 2;
d1c05f
+	if (input != NULL) {
d1c05f
+		int input_size = strlen(input);
d1c05f
+		char *temp = output;
d1c05f
+		*temp++ = '"';
d1c05f
+		buffer_size--;
d1c05f
+		for (i = 0; i < input_size && buffer_size > 0; i++) {
d1c05f
+			switch(input[i]) {
d1c05f
+			// characters escaped are the same as folly::json::escapeString
d1c05f
+			case 27: // <escape> ascii control character
d1c05f
+				if (buffer_size > 6) {
d1c05f
+					*temp++ = '\\';
d1c05f
+					*temp++ = 'u';
d1c05f
+					*temp++ = '0';
d1c05f
+					*temp++ = '0';
d1c05f
+					*temp++ = '1';
d1c05f
+					*temp++ = 'b';
d1c05f
+					buffer_size -= 6;
d1c05f
+				}
d1c05f
+			case '\b':
d1c05f
+				if (buffer_size > 1) {
d1c05f
+					*temp++ = '\\';
d1c05f
+					*temp++ = 'b';
d1c05f
+					buffer_size -= 2;
d1c05f
+				}
d1c05f
+				break;
d1c05f
+			case '\f':
d1c05f
+				if (buffer_size > 1) {
d1c05f
+					*temp++ = '\\';
d1c05f
+					*temp++ = 'f';
d1c05f
+					buffer_size -= 2;
d1c05f
+				}
d1c05f
+				break;
d1c05f
+			case '\n':
d1c05f
+				if (buffer_size > 1) {
d1c05f
+					*temp++ = '\\';
d1c05f
+					*temp++ = 'n';
d1c05f
+					buffer_size -= 2;
d1c05f
+					}
d1c05f
+				break;
d1c05f
+			case '\r':
d1c05f
+				if (buffer_size > 1) {
d1c05f
+					*temp++ = '\\';
d1c05f
+					*temp++ = 'r';
d1c05f
+					buffer_size -= 2;
d1c05f
+				}
d1c05f
+				break;
d1c05f
+			case '\t':
d1c05f
+				if (buffer_size > 1) {
d1c05f
+					*temp++ = '\\';
d1c05f
+					*temp++ = 't';
d1c05f
+					buffer_size -= 2;
d1c05f
+				}
d1c05f
+				break;
d1c05f
+			case '\"':
d1c05f
+			case '\\':
d1c05f
+				if (buffer_size > 1) {
d1c05f
+					*temp++ = '\\';
d1c05f
+					buffer_size--;
d1c05f
+			}
d1c05f
+			default:  // Non-escape char
d1c05f
+				*temp++ = input[i];
d1c05f
+				buffer_size--;
d1c05f
+			}
d1c05f
+		}
d1c05f
+		*temp++ = '"';
d1c05f
+		*temp++ = '\0';
d1c05f
+	}
d1c05f
+}
d1c05f
+
d1c05f
+static void
d1c05f
+slog_get_safe_from_token(char *output, const char *token)
d1c05f
+{
d1c05f
+	if (output == NULL || token == NULL || slogctxt == NULL)
d1c05f
+		return;
d1c05f
+
d1c05f
+	if (strcmp(token, server_ip_token) == 0) {
d1c05f
+		if (slogctxt->server_ip[0] != 0) {
d1c05f
+			snprintf(output, SLOG_SHORT_STRING_LEN, "\"%s\"",
d1c05f
+			    slogctxt->server_ip);
d1c05f
+		}
d1c05f
+		return;
d1c05f
+	}
d1c05f
+
d1c05f
+	if (strcmp(token, server_port_token) == 0) {
d1c05f
+		if (slogctxt->server_port > 0) {
d1c05f
+			snprintf(output, SLOG_SHORT_STRING_LEN, "\"%d\"",
d1c05f
+			slogctxt->server_port);
d1c05f
+		}
d1c05f
+		return;
d1c05f
+	}
d1c05f
+
d1c05f
+	if (strcmp(token, remote_ip_token) == 0) {
d1c05f
+		if (slogctxt->remote_ip[0] != 0) {
d1c05f
+			snprintf(output, SLOG_SHORT_STRING_LEN, "\"%s\"",
d1c05f
+			    slogctxt->remote_ip);
d1c05f
+		}
d1c05f
+		return;
d1c05f
+	}
d1c05f
+
d1c05f
+	if (strcmp(token, remote_port_token) == 0) {
d1c05f
+		if (slogctxt->remote_port > 0) {
d1c05f
+			snprintf(output, SLOG_SHORT_STRING_LEN, "\"%d\"",
d1c05f
+			    slogctxt->remote_port);
d1c05f
+		}
d1c05f
+		return;
d1c05f
+	}
d1c05f
+
d1c05f
+	if (strcmp(token, pam_pid_token) == 0) {
d1c05f
+		if (slogctxt->pam_process_pid > 0) {
d1c05f
+			snprintf(output, SLOG_SHORT_STRING_LEN, "\"%ld\"",
d1c05f
+			    (long)slogctxt->pam_process_pid);
d1c05f
+		}
d1c05f
+		return;
d1c05f
+	}
d1c05f
+
d1c05f
+	if (strcmp(token, process_pid_token) == 0) {
d1c05f
+		snprintf(output, SLOG_SHORT_STRING_LEN, "\"%ld\"", (long)getpid());
d1c05f
+		return;
d1c05f
+	}
d1c05f
+
d1c05f
+	if (strcmp(token, session_id_token) == 0) {
d1c05f
+		if (slogctxt->session_id[0] != 0) {
d1c05f
+				snprintf(output, SLOG_STRING_LEN, "\"%s\"",
d1c05f
+				    slogctxt->session_id);
d1c05f
+		}
d1c05f
+		return;
d1c05f
+	}
d1c05f
+
d1c05f
+	if (strcmp(token, method_token) == 0) {
d1c05f
+		if (slogctxt->method[0] != 0) {
d1c05f
+				snprintf(output, SLOG_STRING_LEN, "\"%s\"",
d1c05f
+				    slogctxt->method);
d1c05f
+		}
d1c05f
+		return;
d1c05f
+	}
d1c05f
+
d1c05f
+	// Arbitrary input
d1c05f
+	if (strcmp(token, cert_id_token) == 0) {
d1c05f
+		if (slogctxt->cert_id[0] != 0 &&
d1c05f
+		    strcmp(slogctxt->method, "publickey") == 0) {
d1c05f
+				slog_escape_value(output, slogctxt->cert_id,
d1c05f
+				    SLOG_STRING_LEN * 2 + 1);
d1c05f
+		}
d1c05f
+		return;
d1c05f
+	}
d1c05f
+
d1c05f
+	if (strcmp(token, cert_serial_token) == 0) {
d1c05f
+		if (slogctxt->cert_serial > 0 &&
d1c05f
+		    strcmp(slogctxt->method, "publickey") == 0) {
d1c05f
+			snprintf(output, SLOG_SHORT_STRING_LEN, "\"%llu\"",
d1c05f
+			    slogctxt->cert_serial);
d1c05f
+		}
d1c05f
+		return;
d1c05f
+	}
d1c05f
+
d1c05f
+	// Arbitrary input
d1c05f
+	if (strcmp(token, principal_token) == 0) {
d1c05f
+		if (slogctxt->principal[0] != 0) {
d1c05f
+			slog_escape_value(output, slogctxt->principal,
d1c05f
+			    SLOG_STRING_LEN * 2 + 1);
d1c05f
+		}
d1c05f
+	return;
d1c05f
+	}
d1c05f
+
d1c05f
+	// Arbitrary input
d1c05f
+	if (strcmp(token, user_token) == 0) {
d1c05f
+		if (slogctxt->user[0] != 0) {
d1c05f
+			slog_escape_value(output, slogctxt->user,
d1c05f
+		    SLOG_STRING_LEN * 2 + 1);
d1c05f
+		}
d1c05f
+		return;
d1c05f
+	}
d1c05f
+
d1c05f
+	// Arbitrary input
d1c05f
+	if (strcmp(token, auth_info_token) == 0) {
d1c05f
+		if (slogctxt->auth_info[0] != 0) {
d1c05f
+			slog_escape_value(output, slogctxt->auth_info,
d1c05f
+			    SLOG_MEDIUM_STRING_LEN * 2 + 1);
d1c05f
+		}
d1c05f
+		return;
d1c05f
+	}
d1c05f
+
d1c05f
+	// Arbitrary input
d1c05f
+	if (strcmp(token, command_token) == 0) {
d1c05f
+		if (slogctxt->command[0] != 0) {
d1c05f
+			slog_escape_value(output, slogctxt->command,
d1c05f
+			    SLOG_LONG_STRING_LEN * 2 + 1);
d1c05f
+		}
d1c05f
+		return;
d1c05f
+	}
d1c05f
+
d1c05f
+	if (strcmp(token, auth_successful_token) == 0) {
d1c05f
+		snprintf(output, SLOG_SHORT_STRING_LEN, "\"%s\"",
d1c05f
+		    slogctxt->auth_successful == SLOG_AUTHORIZED ? "true" : "false");
d1c05f
+		return;
d1c05f
+	}
d1c05f
+
d1c05f
+	if (strcmp(token, session_state_token) == 0) {
d1c05f
+		snprintf(output, SLOG_SHORT_STRING_LEN, "\"%s\"",
d1c05f
+		    slog_get_state_text());
d1c05f
+		return;
d1c05f
+	}
d1c05f
+
d1c05f
+	if (strcmp(token, start_time_token) == 0) {
d1c05f
+		snprintf(output, SLOG_SHORT_STRING_LEN, "\"%d\"",
d1c05f
+		    (int)slogctxt->start_time);
d1c05f
+		return;
d1c05f
+	}
d1c05f
+
d1c05f
+	if (strcmp(token, end_time_token) == 0 && slogctxt->end_time > 0) {
d1c05f
+		snprintf(output, SLOG_SHORT_STRING_LEN, "\"%d\"",
d1c05f
+		    (int)slogctxt->end_time);
d1c05f
+		return;
d1c05f
+	}
d1c05f
+
d1c05f
+	if (strcmp(token, duration_token) == 0 && slogctxt->end_time > 0) {
d1c05f
+		snprintf(output, SLOG_SHORT_STRING_LEN, "\"%d\"", slogctxt->duration);
d1c05f
+		return;
d1c05f
+	}
d1c05f
+
d1c05f
+	if (strcmp(token, main_pid_token) == 0) {
d1c05f
+		if (slogctxt->main_pid > 0) {
d1c05f
+			snprintf(output, SLOG_SHORT_STRING_LEN, "\"%ld\"",
d1c05f
+			    (long)slogctxt->main_pid);
d1c05f
+		}
d1c05f
+		return;
d1c05f
+	}
d1c05f
+
d1c05f
+	// Arbitrary input
d1c05f
+	if (strncmp(token, client_version, strlen(client_version)) == 0) {
d1c05f
+		if (slogctxt->client_version[0] != 0) {
d1c05f
+			slog_escape_value(output, slogctxt->client_version,
d1c05f
+			    SLOG_STRING_LEN + 2);
d1c05f
+		}
d1c05f
+		return;
d1c05f
+	}
d1c05f
+}
d1c05f
+
d1c05f
+static const char *
d1c05f
+slog_get_state_text(void)
d1c05f
+{
d1c05f
+	if (slogctxt == NULL)
d1c05f
+		return "";
d1c05f
+
d1c05f
+	switch (slogctxt->session_state) {
d1c05f
+		case SLOG_SESSION_INIT:
d1c05f
+			return "Session failed";
d1c05f
+		case SLOG_SESSION_OPEN:
d1c05f
+			return "Session opened";
d1c05f
+		case SLOG_SESSION_CLOSED:
d1c05f
+			return "Session closed";
d1c05f
+		default:
d1c05f
+			return "Unknown session state";  // Should never happen
d1c05f
+	}
d1c05f
+}
Michel Lind 1c324b
--- a/servconf.c
Michel Lind 1c324b
+++ b/servconf.c
4c983d
@@ -205,6 +205,9 @@ initialize_server_options(ServerOptions
d1c05f
 	options->disable_forwarding = -1;
d1c05f
 	options->expose_userauth_info = -1;
4c983d
 	options->required_rsa_size = -1;
4c983d
+ 	options->log_format_prefix = NULL;
4c983d
+ 	options->num_log_format_keys = 0;
4c983d
+ 	options->log_format_json = -1;
d1c05f
 }
d1c05f
 
d1c05f
 /* Returns 1 if a string option is unset or set to "none" or 0 otherwise. */
4c983d
@@ -474,6 +477,8 @@ fill_default_server_options(ServerOption
d1c05f
 		options->sk_provider = xstrdup("internal");
4c983d
 	if (options->required_rsa_size == -1)
4c983d
 		options->required_rsa_size = SSH_RSA_MINIMUM_MODULUS_SIZE;
4c983d
+ 	if (options->log_format_json == -1)
4c983d
+ 		options->log_format_json = 0;
d1c05f
 
d1c05f
 	assemble_algorithms(options);
d1c05f
 
4c983d
@@ -554,6 +559,10 @@ typedef enum {
d1c05f
 	sAllowStreamLocalForwarding, sFingerprintHash, sDisableForwarding,
d1c05f
 	sExposeAuthInfo, sRDomain, sPubkeyAuthOptions, sSecurityKeyProvider,
4c983d
 	sRequiredRSASize,
4c983d
+ 	/* Structured Logging options.  Unless sLogFormatKeys is set,
4c983d
+ 	    structured logging is disabled */
4c983d
+ 	sLogFormatPrefix, sLogFormatKeys, sLogFormatJson,
d1c05f
+
d1c05f
 	sDeprecated, sIgnore, sUnsupported
d1c05f
 } ServerOpCodes;
d1c05f
 
4c983d
@@ -732,6 +741,9 @@ static struct {
d1c05f
 	{ "securitykeyprovider", sSecurityKeyProvider, SSHCFG_GLOBAL },
4c983d
 	{ "requiredrsasize", sRequiredRSASize, SSHCFG_ALL },
4c983d
 	{ "rsaminsize", sRequiredRSASize, SSHCFG_ALL }, /* alias */
4c983d
+ 	{ "logformatprefix", sLogFormatPrefix, SSHCFG_GLOBAL },
4c983d
+ 	{ "logformatkeys", sLogFormatKeys, SSHCFG_GLOBAL },
4c983d
+ 	{ "logformatjson", sLogFormatJson, SSHCFG_GLOBAL },
d1c05f
 	{ NULL, sBadOption, 0 }
d1c05f
 };
d1c05f
 
4c983d
@@ -2369,6 +2381,30 @@ process_server_config_line_depth(ServerO
d1c05f
 		}
d1c05f
 		break;
d1c05f
 
d1c05f
+	case sLogFormatPrefix:
f94360
+		arg = argv_next(&ac, &av;;
d1c05f
+		if (!arg || *arg == '\0') {
d1c05f
+			fatal("%.200s line %d: invalid log format prefix",
d1c05f
+			    filename, linenum);
d1c05f
+		}
d1c05f
+		options->log_format_prefix = xstrdup(arg);
d1c05f
+		break;
d1c05f
+
d1c05f
+	case sLogFormatKeys:
f94360
+		while ((arg = argv_next(&ac, &av)) && *arg != '\0') {
d1c05f
+			if (options->num_log_format_keys >= MAX_LOGFORMAT_KEYS)
d1c05f
+				fatal("%s line %d: too long format keys.",
d1c05f
+				    filename, linenum);
d1c05f
+			if (!*activep)
d1c05f
+				continue;
d1c05f
+			options->log_format_keys[options->num_log_format_keys++] = xstrdup(arg);
d1c05f
+		}
d1c05f
+		break;
d1c05f
+
d1c05f
+	case sLogFormatJson:
d1c05f
+		intptr = &options->log_format_json;
d1c05f
+		goto parse_flag;
d1c05f
+
d1c05f
 	case sIPQoS:
d1c05f
 		arg = argv_next(&ac, &av;;
d1c05f
 		if (!arg || *arg == '\0')
4c983d
@@ -3026,6 +3062,7 @@ dump_config(ServerOptions *o)
d1c05f
 	dump_cfg_fmtint(sStreamLocalBindUnlink, o->fwd_opts.streamlocal_bind_unlink);
d1c05f
 	dump_cfg_fmtint(sFingerprintHash, o->fingerprint_hash);
d1c05f
 	dump_cfg_fmtint(sExposeAuthInfo, o->expose_userauth_info);
d1c05f
+	dump_cfg_fmtint(sLogFormatJson, o->log_format_json);
d1c05f
 
d1c05f
 	/* string arguments */
d1c05f
 	dump_cfg_string(sPidFile, o->pid_file);
4c983d
@@ -3056,6 +3093,7 @@ dump_config(ServerOptions *o)
d1c05f
 #if defined(__OpenBSD__) || defined(HAVE_SYS_SET_PROCESS_RDOMAIN)
d1c05f
 	dump_cfg_string(sRDomain, o->routing_domain);
d1c05f
 #endif
d1c05f
+	dump_cfg_string(sLogFormatPrefix, o->log_format_prefix);
d1c05f
 
d1c05f
 	/* string arguments requiring a lookup */
d1c05f
 	dump_cfg_string(sLogLevel, log_level_name(o->log_level));
4c983d
@@ -3078,6 +3116,7 @@ dump_config(ServerOptions *o)
d1c05f
 	    o->num_auth_methods, o->auth_methods);
d1c05f
 	dump_cfg_strarray_oneline(sLogVerbose,
d1c05f
 	    o->num_log_verbose, o->log_verbose);
d1c05f
+	dump_cfg_strarray(sLogFormatKeys, o->num_log_format_keys, o->log_format_keys);
d1c05f
 
d1c05f
 	/* other arguments */
d1c05f
 	for (i = 0; i < o->num_subsystems; i++)
Michel Lind 1c324b
--- a/auth2-pubkey.c
Michel Lind 1c324b
+++ b/auth2-pubkey.c
d1c05f
@@ -66,6 +66,7 @@
d1c05f
 #include "monitor_wrap.h"
d1c05f
 #include "authfile.h"
d1c05f
 #include "match.h"
d1c05f
+#include "slog.h"
d1c05f
 #include "ssherr.h"
d1c05f
 #include "channels.h" /* XXX for session.h */
d1c05f
 #include "session.h" /* XXX for child_set_env(); refactor? */
4c983d
@@ -390,6 +391,7 @@ check_principals_line(struct ssh *ssh, c
d1c05f
 		debug3("%s: matched principal \"%.100s\"",
d1c05f
 		    loc, cert->principals[i]);
d1c05f
 		found = 1;
d1c05f
+		slog_set_principal(cp);
d1c05f
 	}
d1c05f
 	if (found && authoptsp != NULL) {
d1c05f
 		*authoptsp = opts;
4c983d
@@ -715,6 +717,7 @@ check_authkey_line(struct ssh *ssh, stru
d1c05f
 	    (unsigned long long)key->cert->serial,
d1c05f
 	    sshkey_type(found), fp, loc);
d1c05f
 
d1c05f
+	    slog_set_cert_serial(key->cert->serial);
d1c05f
  success:
d1c05f
 	if (finalopts == NULL)
d1c05f
 		fatal_f("internal error: missing options");
4c983d
@@ -865,6 +868,7 @@ user_cert_trusted_ca(struct ssh *ssh, st
d1c05f
 		*authoptsp = final_opts;
d1c05f
 		final_opts = NULL;
d1c05f
 	}
d1c05f
+	slog_set_cert_id(key->cert->key_id);
d1c05f
 	ret = 1;
d1c05f
  out:
d1c05f
 	sshauthopt_free(principals_opts);
Michel Lind 1c324b
--- a/regress/test-exec.sh
Michel Lind 1c324b
+++ b/regress/test-exec.sh
Michel Lind 1c324b
@@ -690,7 +690,7 @@ start_sshd ()
d1c05f
 
d1c05f
 	trace "wait for sshd"
d1c05f
 	i=0;
d1c05f
-	while [ ! -f $PIDFILE -a $i -lt 10 ]; do
d1c05f
+	while [ ! -f $PIDFILE -a $i -lt 3 ]; do
d1c05f
 		i=`expr $i + 1`
d1c05f
 		sleep $i
d1c05f
 	done
Michel Lind 1c324b
--- a/session.c
Michel Lind 1c324b
+++ b/session.c
d1c05f
@@ -96,6 +96,8 @@
d1c05f
 #include "monitor_wrap.h"
d1c05f
 #include "sftp.h"
d1c05f
 #include "atomicio.h"
d1c05f
+#include "slog.h"
d1c05f
+
d1c05f
 
d1c05f
 #if defined(KRB5) && defined(USE_AFS)
d1c05f
 #include <kafs.h>
d1c05f
@@ -753,6 +755,7 @@ do_exec(struct ssh *ssh, Session *s, con
d1c05f
 	    ssh_remote_ipaddr(ssh),
d1c05f
 	    ssh_remote_port(ssh),
d1c05f
 	    s->self);
d1c05f
+	    slog_log_session();
d1c05f
 
d1c05f
 #ifdef SSH_AUDIT_EVENTS
d1c05f
 	if (s->command != NULL || s->command_handle != -1)
Michel Lind 1c324b
@@ -1486,7 +1489,7 @@ do_setusercontext(struct passwd *pw)
d1c05f
 			perror("unable to set user context (setuser)");
d1c05f
 			exit(1);
d1c05f
 		}
d1c05f
-		/* 
d1c05f
+		/*
d1c05f
 		 * FreeBSD's setusercontext() will not apply the user's
d1c05f
 		 * own umask setting unless running with the user's UID.
d1c05f
 		 */
Michel Lind 1c324b
@@ -2163,6 +2166,7 @@ session_exec_req(struct ssh *ssh, Sessio
d1c05f
 	    (r = sshpkt_get_end(ssh)) != 0)
d1c05f
 		sshpkt_fatal(ssh, r, "%s: parse packet", __func__);
d1c05f
 
d1c05f
+	slog_set_command(command);
d1c05f
 	success = do_exec(ssh, s, command) == 0;
d1c05f
 	free(command);
d1c05f
 	return success;
Michel Lind 1c324b
@@ -2873,4 +2877,3 @@ session_get_remote_name_or_ip(struct ssh
d1c05f
 		remote = ssh_remote_ipaddr(ssh);
d1c05f
 	return remote;
d1c05f
 }
d1c05f
-
Michel Lind 1c324b
--- a/log.h
Michel Lind 1c324b
+++ b/log.h
d1c05f
@@ -133,4 +133,6 @@ void	 sshlogdirect(LogLevel, int, const
d1c05f
 #define logdie_fr(r, ...)	sshlogdie(__FILE__, __func__, __LINE__, 1, SYSLOG_LEVEL_ERROR, ssh_err(r), __VA_ARGS__)
d1c05f
 #define sigdie_fr(r, ...)	sshsigdie(__FILE__, __func__, __LINE__, 1, SYSLOG_LEVEL_ERROR, ssh_err(r), __VA_ARGS__)
d1c05f
 
d1c05f
+void     do_log_slog_payload(const char *);
d1c05f
+
d1c05f
 #endif
Michel Lind 1c324b
--- a/log.c
Michel Lind 1c324b
+++ b/log.c
Michel Lind 1c324b
@@ -531,3 +531,39 @@ sshlogdirect(LogLevel level, int forced,
d1c05f
 	do_log(level, forced, NULL, fmt, args);
d1c05f
 	va_end(args);
d1c05f
 }
d1c05f
+
d1c05f
+/* Custom function to log to syslog, to handle the session logging code
d1c05f
+ */
d1c05f
+void
d1c05f
+do_log_slog_payload(const char *payload)
d1c05f
+{
d1c05f
+#if defined(HAVE_OPENLOG_R) && defined(SYSLOG_DATA_INIT)
d1c05f
+	struct syslog_data sdata = SYSLOG_DATA_INIT;
d1c05f
+#endif
d1c05f
+	int pri = LOG_INFO;
d1c05f
+	int saved_errno = errno;
d1c05f
+	LogLevel level = SYSLOG_LEVEL_INFO;
d1c05f
+	log_handler_fn *tmp_handler;
d1c05f
+
d1c05f
+	if (log_handler != NULL) {
d1c05f
+		/* Avoid recursion */
d1c05f
+		tmp_handler = log_handler;
d1c05f
+		log_handler = NULL;
d1c05f
+		tmp_handler(level, 0, payload, log_handler_ctx);
d1c05f
+		log_handler = tmp_handler;
d1c05f
+	} else if (log_on_stderr) {
d1c05f
+		(void)write(log_stderr_fd, payload, strlen(payload));
d1c05f
+		(void)write(log_stderr_fd, "\r\n", 2);
d1c05f
+	} else {
d1c05f
+#if defined(HAVE_OPENLOG_R) && defined(SYSLOG_DATA_INIT)
d1c05f
+		openlog_r(argv0 ? argv0 : __progname, LOG_PID, log_facility, &sdata);
d1c05f
+		syslog_r(pri, &sdata, "%s", payload);
d1c05f
+		closelog_r(&sdata);
d1c05f
+#else
d1c05f
+		openlog(argv0 ? argv0 : __progname, LOG_PID, log_facility);
d1c05f
+		syslog(pri, "%s", payload);
d1c05f
+		closelog();
d1c05f
+#endif
d1c05f
+	}
d1c05f
+	errno = saved_errno;
d1c05f
+}
d1c05f
--- /dev/null
Michel Lind 1c324b
+++ b/slog.h
d1c05f
@@ -0,0 +1,41 @@
d1c05f
+/*
d1c05f
+ * Copyright 2004-present Facebook. All Rights Reserved.
d1c05f
+ */
d1c05f
+#ifndef USE_SLOG
d1c05f
+#define USE_SLOG
d1c05f
+
d1c05f
+#define SLOG_STRING_LEN        100
d1c05f
+#define SLOG_MEDIUM_STRING_LEN 1000
d1c05f
+#define SLOG_SHORT_STRING_LEN  50
d1c05f
+#define SLOG_LONG_STRING_LEN   2000
d1c05f
+
d1c05f
+typedef enum {
d1c05f
+	SLOG_SESSION_INIT,
d1c05f
+	SLOG_SESSION_OPEN,
d1c05f
+	SLOG_SESSION_CLOSED,
d1c05f
+} SLOG_SESSION_STATE;
d1c05f
+
d1c05f
+typedef enum {
d1c05f
+	SLOG_UNAUTHORIZED = 0,
d1c05f
+	SLOG_AUTHORIZED = 1
d1c05f
+} SLOG_AUTHENTICATED;
d1c05f
+
d1c05f
+void	slog_init(void);
d1c05f
+
d1c05f
+// setters
d1c05f
+void	slog_pam_session_opened(void);
d1c05f
+void	slog_set_auth_data(int , const char *, const char *);
d1c05f
+void	slog_set_cert_id(const char *);
d1c05f
+void	slog_set_cert_serial(unsigned long long );
d1c05f
+void	slog_set_connection(const char *, int, const char *, int, const char *);
d1c05f
+void	slog_set_command(const char *);
d1c05f
+void	slog_set_principal(const char *);
d1c05f
+void	slog_set_user(const char *);
d1c05f
+void	slog_set_auth_info(const char *);
d1c05f
+void	slog_set_client_version(const char *);
d1c05f
+
d1c05f
+// loggers
d1c05f
+void	slog_exit_handler(void);
d1c05f
+void	slog_log_session(void);
d1c05f
+
d1c05f
+#endif
Michel Lind 1c324b
--- a/sshd.c
Michel Lind 1c324b
+++ b/sshd.c
d1c05f
@@ -132,6 +132,8 @@
d1c05f
 #include "sk-api.h"
d1c05f
 #include "srclimit.h"
d1c05f
 #include "dh.h"
d1c05f
+#include "slog.h"
d1c05f
+#include <time.h>
d1c05f
 
d1c05f
 /* Re-exec fds */
d1c05f
 #define REEXEC_DEVCRYPTO_RESERVED_FD	(STDERR_FILENO + 1)
Michel Lind 1c324b
@@ -2177,6 +2179,7 @@ main(int ac, char **av)
d1c05f
 	}
d1c05f
 	/* Reinitialize the log (because of the fork above). */
d1c05f
 	log_init(__progname, options.log_level, options.log_facility, log_stderr);
d1c05f
+	slog_init();
d1c05f
 
d1c05f
 	if (FIPS_mode()) {
d1c05f
 		debug("FIPS mode initialized");
Michel Lind 1c324b
@@ -2346,8 +2349,15 @@ main(int ac, char **av)
d1c05f
 	    rdomain == NULL ? "" : " rdomain \"",
d1c05f
 	    rdomain == NULL ? "" : rdomain,
d1c05f
 	    rdomain == NULL ? "" : "\"");
d1c05f
-	free(laddr);
d1c05f
 
d1c05f
+
d1c05f
+	slog_set_connection(remote_ip,
d1c05f
+	    remote_port,
d1c05f
+	    laddr,
d1c05f
+	    ssh_local_port(ssh),
d1c05f
+	    get_log_session_id());
d1c05f
+
d1c05f
+	free(laddr);
d1c05f
 	/*
d1c05f
 	 * We don't want to listen forever unless the other side
d1c05f
 	 * successfully authenticates itself.  So we set up an alarm which is
Michel Lind 1c324b
@@ -2674,6 +2684,7 @@ cleanup_exit(int i)
d1c05f
 	if (in_cleanup)
d1c05f
 		_exit(i);
d1c05f
 	in_cleanup = 1;
d1c05f
+	slog_exit_handler();
d1c05f
 	if (the_active_state != NULL && the_authctxt != NULL) {
d1c05f
 		do_cleanup(the_active_state, the_authctxt);
d1c05f
 		if (use_privsep && privsep_is_preauth &&
Michel Lind 1c324b
--- a/sshd_config
Michel Lind 1c324b
+++ b/sshd_config
d1c05f
@@ -33,6 +33,15 @@ Include /etc/ssh/sshd_config.d/*.conf
d1c05f
 # Logging
d1c05f
 #SyslogFacility AUTH
d1c05f
 #LogLevel INFO
d1c05f
+# Structured logging
d1c05f
+# The default is no structured logging, to enable structured logging at least
d1c05f
+# one LogFormatKeys must be set.  LogFormatJson defaults to no (array) to keep
d1c05f
+# the log line size smaller, if keys are desired set LogFormatJson to yes
d1c05f
+LogFormatPrefix sshd_auth_msg:
d1c05f
+LogFormatKeys server_ip server_port remote_ip remote_port pid session_id method
d1c05f
+LogFormatKeys cert_id cert_serial principal user session_state auth_successful
d1c05f
+LogFormatKeys start_time command
d1c05f
+LogFormatJson yes
d1c05f
 
d1c05f
 # Authentication:
d1c05f
 
Michel Lind 1c324b
--- a/auth-pam.c
Michel Lind 1c324b
+++ b/auth-pam.c
d1c05f
@@ -94,6 +94,7 @@ extern char *__progname;
d1c05f
 #include "auth-pam.h"
d1c05f
 #include "canohost.h"
d1c05f
 #include "log.h"
d1c05f
+#include "slog.h"
d1c05f
 #include "msg.h"
d1c05f
 #include "packet.h"
d1c05f
 #include "misc.h"
Michel Lind 1c324b
@@ -1210,9 +1211,12 @@ do_pam_session(struct ssh *ssh)
d1c05f
 	if (sshpam_err != PAM_SUCCESS)
d1c05f
 		fatal("PAM: failed to set PAM_CONV: %s",
d1c05f
 		    pam_strerror(sshpam_handle, sshpam_err));
d1c05f
+
d1c05f
 	sshpam_err = pam_open_session(sshpam_handle, 0);
d1c05f
-	if (sshpam_err == PAM_SUCCESS)
d1c05f
+	if (sshpam_err == PAM_SUCCESS) {
d1c05f
+		slog_pam_session_opened();
d1c05f
 		sshpam_session_open = 1;
d1c05f
+	}
d1c05f
 	else {
d1c05f
 		sshpam_session_open = 0;
d1c05f
 		auth_restrict_session(ssh);
Michel Lind 1c324b
--- a/servconf.h
Michel Lind 1c324b
+++ b/servconf.h
d1c05f
@@ -22,6 +22,8 @@
d1c05f
 
d1c05f
 #define MAX_SUBSYSTEMS		256	/* Max # subsystems. */
d1c05f
 
d1c05f
+#define MAX_LOGFORMAT_KEYS      256     /* Max # LogFormatKeys */
d1c05f
+
d1c05f
 /* permit_root_login */
d1c05f
 #define	PERMIT_NOT_SET		-1
d1c05f
 #define	PERMIT_NO		0
d1c05f
@@ -239,6 +241,12 @@ typedef struct {
d1c05f
 	u_int64_t timing_secret;
d1c05f
 	char   *sk_provider;
4c983d
 	int	required_rsa_size;	/* minimum size of RSA keys */
d1c05f
+
4c983d
+ 	char   *log_format_prefix;
4c983d
+ 	u_int  num_log_format_keys;
4c983d
+ 	char   *log_format_keys[MAX_LOGFORMAT_KEYS];
4c983d
+ 	int log_format_json;	/* 1 to return "token": "token_val" in log format */
d1c05f
+
d1c05f
 }       ServerOptions;
d1c05f
 
d1c05f
 /* Information about the incoming connection as used by Match */
d1c05f
--- /dev/null
Michel Lind 1c324b
+++ b/regress/slog.sh
d1c05f
@@ -0,0 +1,59 @@
d1c05f
+tid='structured log'
d1c05f
+
d1c05f
+port="4242"
d1c05f
+log_prefix="sshd_auth_msg:"
d1c05f
+log_keys="server_ip server_port remote_ip remote_port pid session_id method cert_id cert_serial principal user session_state auth_successful _time command end_time duration auth_info client_version"
d1c05f
+do_log_json="yes"
d1c05f
+test_config="$OBJ/sshd2_config"
d1c05f
+old_config="$OBJ/sshd_config"
d1c05f
+PIDFILE=$OBJ/pidfile
d1c05f
+
d1c05f
+cat << EOF > $test_config
d1c05f
+	#*:
d1c05f
+	StrictModes             no
d1c05f
+	Port                    $port
d1c05f
+	AddressFamily           inet
d1c05f
+	ListenAddress           127.0.0.1
d1c05f
+	#ListenAddress          ::1
d1c05f
+	PidFile                 $PIDFILE
d1c05f
+	AuthorizedKeysFile      $OBJ/authorized_keys_%u
d1c05f
+	LogLevel                ERROR
d1c05f
+	AcceptEnv               _XXX_TEST_*
d1c05f
+	AcceptEnv               _XXX_TEST
d1c05f
+	HostKey $OBJ/host.ssh-ed25519
d1c05f
+	LogFormatPrefix $log_prefix
d1c05f
+	LogFormatJson $do_log_json
d1c05f
+	LogFormatKeys $log_keys
d1c05f
+EOF
d1c05f
+
d1c05f
+
d1c05f
+cp $test_config $old_config
d1c05f
+start_sshd
d1c05f
+
d1c05f
+${SSH} -F $OBJ/ssh_config somehost true
d1c05f
+if [ $? -ne 0 ]; then
d1c05f
+	fail "ssh connect with failed"
d1c05f
+fi
d1c05f
+
d1c05f
+test_log_counts() {
d1c05f
+	cnt=$(grep -c "$log_prefix" "$TEST_SSHD_LOGFILE")
d1c05f
+	if [ $cnt -ne 2 ]; then
d1c05f
+		fail "expected 2 structured logging lines, got $cnt"
d1c05f
+	fi
d1c05f
+}
d1c05f
+
d1c05f
+test_json_valid() {
d1c05f
+	which python &>/dev/null || echo 'python not found in path, skipping tests'
d1c05f
+
d1c05f
+	loglines=$(cat "$TEST_SSHD_LOGFILE" | grep "$log_prefix")
d1c05f
+	first=$(echo "$loglines" | head -n1)
d1c05f
+	last=$(echo "$loglines" | tail -n1)
d1c05f
+
d1c05f
+	echo ${first:$(expr length $log_prefix)} | python -m json.tool &>/dev/null \
d1c05f
+	    || fail "invalid json structure $first"
d1c05f
+	echo ${last:$(expr length $log_prefix)} | python -m json.tool &>/dev/null  \
d1c05f
+	    || fail "invalid json structure $last"
d1c05f
+}
d1c05f
+
d1c05f
+test_log_counts
d1c05f
+test_json_valid
Michel Lind 1c324b
--- a/Makefile.in
Michel Lind 1c324b
+++ b/Makefile.in
d1c05f
@@ -129,7 +129,7 @@ SSHDOBJS=sshd.o auth-rhosts.o auth-passw
d1c05f
 	monitor.o monitor_wrap.o auth-krb5.o \
d1c05f
 	auth2-gss.o gss-serv.o gss-serv-krb5.o kexgsss.o \
d1c05f
 	loginrec.o auth-pam.o auth-shadow.o auth-sia.o md5crypt.o \
d1c05f
-	srclimit.o sftp-server.o sftp-common.o \
d1c05f
+	srclimit.o sftp-server.o sftp-common.o sftp-realpath.o slog.o \
d1c05f
 	sandbox-null.o sandbox-rlimit.o sandbox-systrace.o sandbox-darwin.o \
d1c05f
 	sandbox-seccomp-filter.o sandbox-capsicum.o sandbox-pledge.o \
d1c05f
 	sandbox-solaris.o uidswap.o $(SKOBJS)
d1c05f
@@ -313,7 +313,7 @@ distclean:	regressclean
d1c05f
 	rm -f *.o *.a $(TARGETS) logintest config.cache config.log
d1c05f
 	rm -f *.out core opensshd.init openssh.xml
d1c05f
 	rm -f Makefile buildpkg.sh config.h config.status
d1c05f
-	rm -f survey.sh openbsd-compat/regress/Makefile *~ 
d1c05f
+	rm -f survey.sh openbsd-compat/regress/Makefile *~
d1c05f
 	rm -rf autom4te.cache
d1c05f
 	rm -f regress/check-perm
d1c05f
 	rm -f regress/mkdtemp
Michel Lind 1c324b
--- a/auth.c
Michel Lind 1c324b
+++ b/auth.c
d1c05f
@@ -76,6 +76,7 @@
d1c05f
 #include "ssherr.h"
d1c05f
 #include "compat.h"
d1c05f
 #include "channels.h"
d1c05f
+#include "slog.h"
d1c05f
 
d1c05f
 /* import */
d1c05f
 extern ServerOptions options;
d1c05f
@@ -351,6 +352,7 @@ auth_log(struct ssh *ssh, int authentica
d1c05f
 	    extra != NULL ? extra : "");
d1c05f
 
d1c05f
 	free(extra);
d1c05f
+	slog_set_auth_data(authenticated, method, authctxt->user);
d1c05f
 
d1c05f
 #if defined(CUSTOM_FAILED_LOGIN) || defined(SSH_AUDIT_EVENTS)
d1c05f
 	if (authenticated == 0 && !(authctxt->postponed || partial)) {
d1c05f
@@ -564,6 +566,7 @@ auth_openprincipals(const char *file, st
d1c05f
 struct passwd *
d1c05f
 getpwnamallow(struct ssh *ssh, const char *user)
d1c05f
 {
d1c05f
+	slog_set_user(user);
d1c05f
 #ifdef HAVE_LOGIN_CAP
d1c05f
 	extern login_cap_t *lc;
d1c05f
 #ifdef BSD_AUTH