From 2c91efcc68d9a6aff9163e81df7a5024703084d4 Mon Sep 17 00:00:00 2001 From: Andreas Schneider Date: Sun, 14 Jul 2013 12:36:59 +0200 Subject: [PATCH] log: Implment new logging functions. --- include/libssh/callbacks.h | 34 ++++++++++++ include/libssh/libssh.h | 6 +++ include/libssh/priv.h | 12 +++-- src/agent.c | 20 +++---- src/auth.c | 65 +++++++++++------------ src/bind.c | 2 +- src/log.c | 103 +++++++++++++++++++++++++++++-------- 7 files changed, 169 insertions(+), 73 deletions(-) diff --git a/include/libssh/callbacks.h b/include/libssh/callbacks.h index bc3eb79e..7525b73d 100644 --- a/include/libssh/callbacks.h +++ b/include/libssh/callbacks.h @@ -74,6 +74,24 @@ typedef int (*ssh_channel_callback_data) (ssh_channel channel, int code, void *d typedef void (*ssh_log_callback) (ssh_session session, int priority, const char *message, void *userdata); +/** + * @brief SSH log callback. + * + * All logging messages will go through this callback. + * + * @param priority Priority of the log, the smaller being the more important. + * + * @param function The function name calling the the logging fucntions. + * + * @param message The actual message + * + * @param userdata Userdata to be passed to the callback function. + */ +typedef void (*ssh_logging_callback) (int priority, + const char *function, + const char *buffer, + void *userdata); + /** * @brief SSH Connection status callback. * @param session Current session handler @@ -798,6 +816,22 @@ LIBSSH_API struct ssh_threads_callbacks_struct *ssh_threads_get_pthread(void); */ LIBSSH_API struct ssh_threads_callbacks_struct *ssh_threads_get_noop(void); +/** + * @brief Set the logging callback function. + * + * @param[in] cb The callback to set. + * + * @return 0 on success, < 0 on errror. + */ +LIBSSH_API int ssh_set_log_callback(ssh_logging_callback cb); + +/** + * @brief Get the pointer to the logging callback function. + * + * @return The pointer the the callback or NULL if none set. + */ +LIBSSH_API ssh_logging_callback ssh_get_log_callback(void); + /** @} */ #ifdef __cplusplus } diff --git a/include/libssh/libssh.h b/include/libssh/libssh.h index dd736322..ce21ca46 100644 --- a/include/libssh/libssh.h +++ b/include/libssh/libssh.h @@ -418,6 +418,12 @@ LIBSSH_API int ssh_is_blocking(ssh_session session); LIBSSH_API int ssh_is_connected(ssh_session session); LIBSSH_API int ssh_is_server_known(ssh_session session); +/* LOGGING */ +LIBSSH_API int ssh_set_log_level(int level); +LIBSSH_API int ssh_get_log_level(void); +LIBSSH_API void *ssh_get_log_userdata(void); +LIBSSH_API int ssh_set_log_userdata(void *data); + /* legacy */ LIBSSH_API void ssh_log(ssh_session session, int prioriry, diff --git a/include/libssh/priv.h b/include/libssh/priv.h index d7974026..35a6e4f3 100644 --- a/include/libssh/priv.h +++ b/include/libssh/priv.h @@ -152,15 +152,17 @@ struct ssh_kex_struct; int ssh_get_key_params(ssh_session session, ssh_key *privkey); /* LOGGING */ -#define SSH_LOG(session, priority, ...) \ - ssh_log_common(&session->common, priority, __FUNCTION__, __VA_ARGS__) +void _ssh_log(int verbosity, + const char *function, + const char *format, ...) PRINTF_ATTRIBUTE(3, 4); +#define SSH_LOG(priority, ...) \ + _ssh_log(priority, __FUNCTION__, __VA_ARGS__) + +/* LEGACY */ void ssh_log_common(struct ssh_common_struct *common, int verbosity, const char *function, const char *format, ...) PRINTF_ATTRIBUTE(4, 5); -void ssh_log_function(int verbosity, - const char *function, - const char *buffer); /* ERROR HANDLING */ diff --git a/src/agent.c b/src/agent.c index 9c62ea42..18b6bb78 100644 --- a/src/agent.c +++ b/src/agent.c @@ -257,19 +257,19 @@ static int agent_talk(struct ssh_session_struct *session, uint8_t payload[1024] = {0}; len = buffer_get_rest_len(request); - SSH_LOG(session, SSH_LOG_TRACE, "Request length: %u", len); + SSH_LOG(SSH_LOG_TRACE, "Request length: %u", len); agent_put_u32(payload, len); /* send length and then the request packet */ if (atomicio(session->agent, payload, 4, 0) == 4) { if (atomicio(session->agent, buffer_get_rest(request), len, 0) != len) { - SSH_LOG(session, SSH_LOG_WARN, "atomicio sending request failed: %s", + SSH_LOG(SSH_LOG_WARN, "atomicio sending request failed: %s", strerror(errno)); return -1; } } else { - SSH_LOG(session, SSH_LOG_WARN, + SSH_LOG(SSH_LOG_WARN, "atomicio sending request length failed: %s", strerror(errno)); return -1; @@ -277,7 +277,7 @@ static int agent_talk(struct ssh_session_struct *session, /* wait for response, read the length of the response packet */ if (atomicio(session->agent, payload, 4, 1) != 4) { - SSH_LOG(session, SSH_LOG_WARN, "atomicio read response length failed: %s", + SSH_LOG(SSH_LOG_WARN, "atomicio read response length failed: %s", strerror(errno)); return -1; } @@ -288,7 +288,7 @@ static int agent_talk(struct ssh_session_struct *session, "Authentication response too long: %u", len); return -1; } - SSH_LOG(session, SSH_LOG_TRACE, "Response length: %u", len); + SSH_LOG(SSH_LOG_TRACE, "Response length: %u", len); while (len > 0) { size_t n = len; @@ -296,12 +296,12 @@ static int agent_talk(struct ssh_session_struct *session, n = sizeof(payload); } if (atomicio(session->agent, payload, n, 1) != n) { - SSH_LOG(session, SSH_LOG_WARN, + SSH_LOG(SSH_LOG_WARN, "Error reading response from authentication socket."); return -1; } if (buffer_add_data(reply, payload, n) < 0) { - SSH_LOG(session, SSH_LOG_WARN, "Not enough space"); + SSH_LOG(SSH_LOG_WARN, "Not enough space"); return -1; } len -= n; @@ -366,7 +366,7 @@ int ssh_agent_get_ident_count(struct ssh_session_struct *session) { return -1; } - SSH_LOG(session, SSH_LOG_WARN, + SSH_LOG(SSH_LOG_WARN, "Answer type: %d, expected answer: %d", type, c2); @@ -382,7 +382,7 @@ int ssh_agent_get_ident_count(struct ssh_session_struct *session) { buffer_get_u32(reply, (uint32_t *) buf); session->agent->count = agent_get_u32(buf); - SSH_LOG(session, SSH_LOG_DEBUG, "Agent count: %d", + SSH_LOG(SSH_LOG_DEBUG, "Agent count: %d", session->agent->count); if (session->agent->count > 1024) { ssh_set_error(session, SSH_FATAL, @@ -557,7 +557,7 @@ ssh_string ssh_agent_sign_data(ssh_session session, } if (agent_failed(type)) { - SSH_LOG(session, SSH_LOG_WARN, "Agent reports failure in signing the key"); + SSH_LOG(SSH_LOG_WARN, "Agent reports failure in signing the key"); ssh_buffer_free(reply); return NULL; } else if (type != SSH2_AGENT_SIGN_RESPONSE) { diff --git a/src/auth.c b/src/auth.c index 07cbbd28..32059dfc 100644 --- a/src/auth.c +++ b/src/auth.c @@ -70,7 +70,7 @@ static int ssh_userauth_request_service(ssh_session session) { rc = ssh_service_request(session, "ssh-userauth"); if (rc != SSH_OK) { - SSH_LOG(session, SSH_LOG_WARN, + SSH_LOG(SSH_LOG_WARN, "Failed to request \"ssh-userauth\" service"); } @@ -162,10 +162,10 @@ SSH_PACKET_CALLBACK(ssh_packet_userauth_banner){ enter_function(); banner = buffer_get_ssh_string(packet); if (banner == NULL) { - SSH_LOG(session, SSH_LOG_WARN, + SSH_LOG(SSH_LOG_WARN, "Invalid SSH_USERAUTH_BANNER packet"); } else { - SSH_LOG(session, SSH_LOG_DEBUG, + SSH_LOG(SSH_LOG_DEBUG, "Received SSH_USERAUTH_BANNER packet"); if(session->banner != NULL) ssh_string_free(session->banner); @@ -206,12 +206,12 @@ SSH_PACKET_CALLBACK(ssh_packet_userauth_failure){ if (partial) { session->auth_state=SSH_AUTH_STATE_PARTIAL; - SSH_LOG(session, SSH_LOG_INFO, + SSH_LOG(SSH_LOG_INFO, "Partial success. Authentication that can continue: %s", auth_methods); } else { session->auth_state=SSH_AUTH_STATE_FAILED; - SSH_LOG(session, SSH_LOG_INFO, + SSH_LOG(SSH_LOG_INFO, "Access denied. Authentication that can continue: %s", auth_methods); ssh_set_error(session, SSH_REQUEST_DENIED, @@ -256,19 +256,19 @@ SSH_PACKET_CALLBACK(ssh_packet_userauth_success){ (void)type; (void)user; - SSH_LOG(session, SSH_LOG_DEBUG, "Authentication successful"); - SSH_LOG(session, SSH_LOG_TRACE, "Received SSH_USERAUTH_SUCCESS"); + SSH_LOG(SSH_LOG_DEBUG, "Authentication successful"); + SSH_LOG(SSH_LOG_TRACE, "Received SSH_USERAUTH_SUCCESS"); session->auth_state=SSH_AUTH_STATE_SUCCESS; session->session_state=SSH_SESSION_STATE_AUTHENTICATED; session->flags |= SSH_SESSION_FLAG_AUTHENTICATED; if(session->current_crypto && session->current_crypto->delayed_compress_out){ - SSH_LOG(session, SSH_LOG_DEBUG, "Enabling delayed compression OUT"); + SSH_LOG(SSH_LOG_DEBUG, "Enabling delayed compression OUT"); session->current_crypto->do_compress_out=1; } if(session->current_crypto && session->current_crypto->delayed_compress_in){ - SSH_LOG(session,SSH_LOG_DEBUG, "Enabling delayed compression IN"); + SSH_LOG(SSH_LOG_DEBUG, "Enabling delayed compression IN"); session->current_crypto->do_compress_in=1; } leave_function(); @@ -287,11 +287,11 @@ SSH_PACKET_CALLBACK(ssh_packet_userauth_pk_ok){ int rc; enter_function(); - SSH_LOG(session, SSH_LOG_TRACE, "Received SSH_USERAUTH_PK_OK/INFO_REQUEST/GSSAPI_RESPONSE"); + SSH_LOG(SSH_LOG_TRACE, "Received SSH_USERAUTH_PK_OK/INFO_REQUEST/GSSAPI_RESPONSE"); if(session->auth_state==SSH_AUTH_STATE_KBDINT_SENT){ /* Assuming we are in keyboard-interactive context */ - SSH_LOG(session, SSH_LOG_TRACE, + SSH_LOG(SSH_LOG_TRACE, "keyboard-interactive context, assuming SSH_USERAUTH_INFO_REQUEST"); rc=ssh_packet_userauth_info_request(session,type,packet,user); #if WITH_GSSAPI @@ -300,7 +300,7 @@ SSH_PACKET_CALLBACK(ssh_packet_userauth_pk_ok){ #endif } else { session->auth_state=SSH_AUTH_STATE_PK_OK; - SSH_LOG(session, SSH_LOG_TRACE, "Assuming SSH_USERAUTH_PK_OK"); + SSH_LOG(SSH_LOG_TRACE, "Assuming SSH_USERAUTH_PK_OK"); rc=SSH_PACKET_USED; } leave_function(); @@ -994,7 +994,7 @@ int ssh_userauth_agent(ssh_session session, state->pubkey = ssh_agent_get_first_ident(session, &state->comment); while (state->pubkey != NULL) { if(state->state == SSH_AGENT_STATE_NONE){ - SSH_LOG(session, SSH_LOG_DEBUG, + SSH_LOG(SSH_LOG_DEBUG, "Trying identity %s", state->comment); } if(state->state == SSH_AGENT_STATE_NONE || @@ -1009,7 +1009,7 @@ int ssh_userauth_agent(ssh_session session, state->state = SSH_AGENT_STATE_PUBKEY; return rc; } else if (rc != SSH_AUTH_SUCCESS) { - SSH_LOG(session, SSH_LOG_DEBUG, + SSH_LOG(SSH_LOG_DEBUG, "Public key of %s refused by server", state->comment); ssh_string_free_char(state->comment); ssh_key_free(state->pubkey); @@ -1018,7 +1018,7 @@ int ssh_userauth_agent(ssh_session session, continue; } - SSH_LOG(session, SSH_LOG_DEBUG, + SSH_LOG(SSH_LOG_DEBUG, "Public key of %s accepted by server", state->comment); state->state = SSH_AGENT_STATE_AUTH; } @@ -1032,7 +1032,7 @@ int ssh_userauth_agent(ssh_session session, SAFE_FREE(session->agent_state); return rc; } else if (rc != SSH_AUTH_SUCCESS) { - SSH_LOG(session, SSH_LOG_INFO, + SSH_LOG(SSH_LOG_INFO, "Server accepted public key but refused the signature"); state->pubkey = ssh_agent_get_next_ident(session, &state->comment); state->state = SSH_AGENT_STATE_NONE; @@ -1136,7 +1136,7 @@ int ssh_userauth_publickey_auto(ssh_session session, const char *privkey_file = state->it->data; char pubkey_file[1024] = {0}; if (state->state == SSH_AUTH_AUTO_STATE_PUBKEY){ - SSH_LOG(session, SSH_LOG_DEBUG, + SSH_LOG(SSH_LOG_DEBUG, "Trying to authenticate with %s", privkey_file); state->privkey = NULL; state->pubkey = NULL; @@ -1166,7 +1166,7 @@ int ssh_userauth_publickey_auto(ssh_session session, continue; } else if (rc == SSH_EOF) { /* If the file doesn't exist, continue */ - SSH_LOG(session, SSH_LOG_DEBUG, + SSH_LOG(SSH_LOG_DEBUG, "Private key %s doesn't exist.", privkey_file); state->it=state->it->next; @@ -1182,8 +1182,7 @@ int ssh_userauth_publickey_auto(ssh_session session, rc = ssh_pki_export_pubkey_file(state->pubkey, pubkey_file); if (rc == SSH_ERROR) { - SSH_LOG(session, - SSH_LOG_WARN, + SSH_LOG(SSH_LOG_WARN, "Could not write public key to file: %s", pubkey_file); } @@ -1193,8 +1192,7 @@ int ssh_userauth_publickey_auto(ssh_session session, if (state->state == SSH_AUTH_AUTO_STATE_KEY_IMPORTED){ rc = ssh_userauth_try_publickey(session, username, state->pubkey); if (rc == SSH_AUTH_ERROR) { - SSH_LOG(session, - SSH_LOG_WARN, + SSH_LOG(SSH_LOG_WARN, "Public key authentication error for %s", privkey_file); ssh_key_free(state->privkey); @@ -1204,8 +1202,7 @@ int ssh_userauth_publickey_auto(ssh_session session, } else if (rc == SSH_AUTH_AGAIN){ return rc; } else if (rc != SSH_AUTH_SUCCESS) { - SSH_LOG(session, - SSH_LOG_DEBUG, + SSH_LOG(SSH_LOG_DEBUG, "Public key for %s refused by server", privkey_file); ssh_key_free(state->privkey); @@ -1240,8 +1237,7 @@ int ssh_userauth_publickey_auto(ssh_session session, /* If the file doesn't exist, continue */ ssh_key_free(state->pubkey); state->pubkey=NULL; - SSH_LOG(session, - SSH_LOG_INFO, + SSH_LOG(SSH_LOG_INFO, "Private key %s doesn't exist.", privkey_file); state->it=state->it->next; @@ -1259,8 +1255,7 @@ int ssh_userauth_publickey_auto(ssh_session session, if (rc == SSH_AUTH_ERROR) { return rc; } else if (rc == SSH_AUTH_SUCCESS) { - SSH_LOG(session, - SSH_LOG_INFO, + SSH_LOG(SSH_LOG_INFO, "Successfully authenticated using %s", privkey_file); return rc; @@ -1268,16 +1263,14 @@ int ssh_userauth_publickey_auto(ssh_session session, return rc; } - SSH_LOG(session, - SSH_LOG_WARN, + SSH_LOG(SSH_LOG_WARN, "The server accepted the public key but refused the signature"); state->it=state->it->next; state->state=SSH_AUTH_AUTO_STATE_PUBKEY; /* continue */ } } - SSH_LOG(session, - SSH_LOG_INFO, + SSH_LOG(SSH_LOG_INFO, "Tried every public key, none matched"); SAFE_FREE(session->auth_auto_state); return SSH_AUTH_DENIED; @@ -1640,7 +1633,7 @@ static int ssh_userauth_kbdint_init(ssh_session session, session->auth_state = SSH_AUTH_STATE_KBDINT_SENT; session->pending_call_state = SSH_PENDING_CALL_AUTH_KBDINT_INIT; - SSH_LOG(session, SSH_LOG_DEBUG, + SSH_LOG(SSH_LOG_DEBUG, "Sending keyboard-interactive init request"); rc = packet_send(session); @@ -1714,7 +1707,7 @@ static int ssh_userauth_kbdint_send(ssh_session session) ssh_kbdint_free(session->kbdint); session->kbdint = NULL; - SSH_LOG(session, SSH_LOG_DEBUG, + SSH_LOG(SSH_LOG_DEBUG, "Sending keyboard-interactive response packet"); rc = packet_send(session); @@ -1800,7 +1793,7 @@ SSH_PACKET_CALLBACK(ssh_packet_userauth_info_request) { } nprompts = ntohl(nprompts); - SSH_LOG(session, SSH_LOG_DEBUG, + SSH_LOG(SSH_LOG_DEBUG, "%d keyboard-interactive prompts", nprompts); if (nprompts > KBDINT_MAX_PROMPT) { ssh_set_error(session, SSH_FATAL, @@ -2156,7 +2149,7 @@ int ssh_userauth_gssapi(ssh_session session) { } else if (rc == SSH_ERROR) { return SSH_AUTH_ERROR; } - ssh_log(session,SSH_LOG_PROTOCOL, "Authenticating with gssapi-with-mic"); + SSH_LOG(SSH_LOG_PROTOCOL, "Authenticating with gssapi-with-mic"); session->auth_state = SSH_AUTH_STATE_NONE; session->pending_call_state = SSH_PENDING_CALL_AUTH_GSSAPI_MIC; rc = ssh_gssapi_auth_mic(session); diff --git a/src/bind.c b/src/bind.c index 65a77797..e4c9327e 100644 --- a/src/bind.c +++ b/src/bind.c @@ -250,7 +250,7 @@ int ssh_bind_listen(ssh_bind sshbind) { return -1; } } else { - SSH_LOG(sshbind, SSH_LOG_INFO, "Using app-provided bind socket"); + SSH_LOG(SSH_LOG_INFO, "Using app-provided bind socket"); } return 0; } diff --git a/src/log.c b/src/log.c index 687afabc..ae546271 100644 --- a/src/log.c +++ b/src/log.c @@ -35,6 +35,10 @@ #include "libssh/misc.h" #include "libssh/session.h" +LIBSSH_THREAD int ssh_log_level; +LIBSSH_THREAD ssh_logging_callback ssh_log_cb; +LIBSSH_THREAD void *ssh_log_userdata; + /** * @defgroup libssh_log The SSH logging functions. * @ingroup libssh @@ -70,46 +74,60 @@ static int current_timestring(int hires, char *buf, size_t len) return 0; } -void ssh_log_function(int verbosity, - const char *function, - const char *buffer) +static void ssh_log_stderr(int verbosity, + const char *function, + const char *buffer) { char date[64] = {0}; int rc; rc = current_timestring(1, date, sizeof(date)); if (rc == 0) { - fprintf(stderr, "[%s, %d] %s", date, verbosity, function); + fprintf(stderr, "[%s, %d] %s:", date, verbosity, function); } else { fprintf(stderr, "[%d] %s", verbosity, function); } + fprintf(stderr, " %s\n", buffer); } -/** @internal - * @brief do the actual work of logging an event - */ - -static void do_ssh_log(struct ssh_common_struct *common, - int verbosity, - const char *function, - const char *buffer) { - if (common->callbacks && common->callbacks->log_function) { +static void ssh_log_function(int verbosity, + const char *function, + const char *buffer) +{ + ssh_logging_callback log_fn = ssh_get_log_callback(); + if (log_fn) { char buf[1024]; snprintf(buf, sizeof(buf), "%s: %s", function, buffer); - common->callbacks->log_function((ssh_session)common, - verbosity, - buf, - common->callbacks->userdata); + log_fn(verbosity, + function, + buf, + ssh_get_log_userdata()); return; } - ssh_log_function(verbosity, function, buffer); + ssh_log_stderr(verbosity, function, buffer); } -/* legacy function */ +void _ssh_log(int verbosity, + const char *function, + const char *format, ...) +{ + char buffer[1024]; + va_list va; + + if (verbosity <= ssh_get_log_level()) { + va_start(va, format); + vsnprintf(buffer, sizeof(buffer), format, va); + va_end(va); + ssh_log_function(verbosity, function, buffer); + } +} + +/* LEGACY */ + void ssh_log(ssh_session session, int verbosity, const char *format, ...) @@ -121,7 +139,7 @@ void ssh_log(ssh_session session, va_start(va, format); vsnprintf(buffer, sizeof(buffer), format, va); va_end(va); - do_ssh_log(&session->common, verbosity, "", buffer); + ssh_log_function(verbosity, "", buffer); } } @@ -143,10 +161,53 @@ void ssh_log_common(struct ssh_common_struct *common, va_start(va, format); vsnprintf(buffer, sizeof(buffer), format, va); va_end(va); - do_ssh_log(common, verbosity, function, buffer); + ssh_log_function(verbosity, function, buffer); } } + +/* PUBLIC */ + +int ssh_set_log_level(int level) { + if (level < 0) { + return -1; + } + + ssh_log_level = level; + + return 0; +} + +int ssh_get_log_level(void) { + return ssh_log_level; +} + +int ssh_set_log_callback(ssh_logging_callback cb) { + if (cb == NULL) { + return -1; + } + + ssh_log_cb = cb; + + return 0; +} + +ssh_logging_callback ssh_get_log_callback(void) { + return ssh_log_cb; +} + +void *ssh_get_log_userdata(void) +{ + return ssh_log_userdata; +} + +int ssh_set_log_userdata(void *data) +{ + ssh_log_userdata = data; + + return 0; +} + /** @} */ /* vim: set ts=4 sw=4 et cindent: */