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 +#include +#include +#include +#include +#include +#include +#include + +#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: // 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 @@ -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 /* 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