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