From ebfbd22e59a58804f24acb08ea18015261571a59 Mon Sep 17 00:00:00 2001 From: Sara Golemon Date: Wed, 11 May 2005 05:11:31 +0000 Subject: [PATCH] Add debugging hooks for development diagnostics --- README | 2 + configure.in | 38 ++++++++++++++ include/libssh2_config.h.in | 21 ++++++++ include/libssh2_priv.h | 34 ++++++++++++ src/channel.c | 98 ++++++++++++++++++++++++++++++++-- src/kex.c | 93 +++++++++++++++++++++++++++++++-- src/misc.c | 26 ++++++++++ src/packet.c | 101 ++++++++++++++++++++++++++++++++++++ src/scp.c | 21 ++++++++ src/session.c | 41 +++++++++++++++ src/sftp.c | 73 ++++++++++++++++++++++++++ src/userauth.c | 37 ++++++++++++- 12 files changed, 577 insertions(+), 8 deletions(-) diff --git a/README b/README index 0cb9b75..6dd8ff2 100644 --- a/README +++ b/README @@ -4,6 +4,8 @@ libssh2 - SSH2 library Version 0.10 ------------ + Added developer debugging hooks. See --enable-debug-* options to ./configure + Ignore extended data in the SFTP layer. With no other mechanism to deal with that data it'd just fill up and get stuck. (Re)Fixed channel_write() to provide an opportunity for window space to become available again. diff --git a/configure.in b/configure.in index 518dfdc..d6eb772 100644 --- a/configure.in +++ b/configure.in @@ -169,6 +169,44 @@ if test "$GEX_NEW" != "no"; then AC_DEFINE(LIBSSH2_DH_GEX_NEW, 1, [Enable newer diffie-hellman-group-exchange-sha1 syntax]) fi +# +# Optional debugging -- Meant for developer maintenance only +# When enabled, the relevant debugging information will be written on stderr +# +AC_ARG_ENABLE(debug-transport, + AC_HELP_STRING([--enable-debug-transport],[Output transport layer debugging info to stderr]), + [AC_DEFINE(LIBSSH2_DEBUG_TRANSPORT, 1, [Output transport layer debugging info to stderr])]) +AC_ARG_ENABLE(debug-kex, + AC_HELP_STRING([--enable-debug-kex],[Output Key Exchange debugging info to stderr]), + [AC_DEFINE(LIBSSH2_DEBUG_KEX, 1, [Output Key Exchange debugging info to stderr])]) +AC_ARG_ENABLE(debug-userauth, + AC_HELP_STRING([--enable-debug-userauth],[Output userauth debugging info to stderr]), + [AC_DEFINE(LIBSSH2_DEBUG_USERAUTH, 1, [Output userauth layer debugging info to stderr])]) +AC_ARG_ENABLE(debug-channel, + AC_HELP_STRING([--enable-debug-connection],[Output connection layer debugging info to stderr]), + [AC_DEFINE(LIBSSH2_DEBUG_CONNECTION, 1, [Output connection layer debugging info to stderr])]) +AC_ARG_ENABLE(debug-scp, + AC_HELP_STRING([--enable-debug-scp],[Output scp subsystem debugging info to stderr]), + [AC_DEFINE(LIBSSH2_DEBUG_SCP, 1, [Output scp subsystem debugging info to stderr])]) +AC_ARG_ENABLE(debug-sftp, + AC_HELP_STRING([--enable-debug-sftp],[Output sftp subsystem debugging info to stderr]), + [AC_DEFINE(LIBSSH2_DEBUG_SFTP, 1, [Output sftp subsystem debugging info to stderr])]) +AC_ARG_ENABLE(debug-errors, + AC_HELP_STRING([--enable-debug-errors],[Output failure events to stderr]), + [AC_DEFINE(LIBSSH2_DEBUG_ERRORS, 1, [Output failure events to stderr])]) +AC_ARG_ENABLE(debug-all, + AC_HELP_STRING([--enable-debug-all],[Output debugging info for all layers to stderr]), + [ + AC_DEFINE(LIBSSH2_DEBUG_TRANSPORT, 1, [Output transport layer debugging info to stderr]) + AC_DEFINE(LIBSSH2_DEBUG_KEX, 1, [Output Key Exchange debugging info to stderr]) + AC_DEFINE(LIBSSH2_DEBUG_USERAUTH, 1, [Output userauth layer debugging info to stderr]) + AC_DEFINE(LIBSSH2_DEBUG_CONNECTION, 1, [Output connection layer debugging info to stderr]) + AC_DEFINE(LIBSSH2_DEBUG_SCP, 1, [Output scp subsystem debugging info to stderr]) + AC_DEFINE(LIBSSH2_DEBUG_SFTP, 1, [Output sftp subsystem debugging info to stderr]) + AC_DEFINE(LIBSSH2_DEBUG_ERRORS, 1, [Output failure events to stderr]) + ]) + + # Checks for header files. # AC_HEADER_STDC AC_CHECK_HEADERS([errno.h fcntl.h stdio.h stdlib.h unistd.h sys/uio.h sys/select.h]) diff --git a/include/libssh2_config.h.in b/include/libssh2_config.h.in index a7f8722..624eb1f 100644 --- a/include/libssh2_config.h.in +++ b/include/libssh2_config.h.in @@ -54,6 +54,27 @@ /* Enable "none" cipher -- NOT RECOMMENDED */ #undef LIBSSH2_CRYPT_NONE +/* Output connection layer debugging info to stderr */ +#undef LIBSSH2_DEBUG_CONNECTION + +/* Output failure events to stderr */ +#undef LIBSSH2_DEBUG_ERRORS + +/* Output Key Exchange debugging info to stderr */ +#undef LIBSSH2_DEBUG_KEX + +/* Output scp subsystem debugging info to stderr */ +#undef LIBSSH2_DEBUG_SCP + +/* Output sftp subsystem debugging info to stderr */ +#undef LIBSSH2_DEBUG_SFTP + +/* Output transport layer debugging info to stderr */ +#undef LIBSSH2_DEBUG_TRANSPORT + +/* Output userauth layer debugging info to stderr */ +#undef LIBSSH2_DEBUG_USERAUTH + /* Enable newer diffie-hellman-group-exchange-sha1 syntax */ #undef LIBSSH2_DH_GEX_NEW diff --git a/include/libssh2_priv.h b/include/libssh2_priv.h index 804dbbf..4f450d9 100644 --- a/include/libssh2_priv.h +++ b/include/libssh2_priv.h @@ -317,6 +317,37 @@ struct _LIBSSH2_MAC_METHOD { int (*dtor)(LIBSSH2_SESSION *session, void **abstract); }; +#if defined(LIBSSH2_DEBUG_TRANSPORT) || defined(LIBSSH2_DEBUG_KEX) || defined(LIBSSH2_DEBUG_USERAUTH) || defined(LIBSSH2_DEBUG_CONNECTION) || defined(LIBSSH2_DEBUG_SCP) || defined(LIBSSH2_DEBUG_SFTP) || defined(LIBSSH2_DEBUG_ERRORS) +#define LIBSSH2_DEBUG_ENABLED + +/* Internal debugging contexts -- Used with --enable-debug-* */ +#define LIBSSH2_DBG_TRANS 1 +#define LIBSSH2_DBG_KEX 2 +#define LIBSSH2_DBG_AUTH 3 +#define LIBSSH2_DBG_CONN 4 +#define LIBSSH2_DBG_SCP 5 +#define LIBSSH2_DBG_SFTP 6 +#define LIBSSH2_DBG_ERROR 7 + +void _libssh2_debug(LIBSSH2_SESSION *session, int context, const char *format, ...); + +#endif /* LIBSSH2_DEBUG_ENABLED */ + +#ifdef LIBSSH2_DEBUG_ERRORS +#define libssh2_error(session, errcode, errmsg, should_free) \ +{ \ + if (session->err_msg && session->err_should_free) { \ + LIBSSH2_FREE(session, session->err_msg); \ + } \ + session->err_msg = errmsg; \ + session->err_msglen = strlen(errmsg); \ + session->err_should_free = should_free; \ + session->err_code = errcode; \ + _libssh2_debug(session, LIBSSH2_DBG_ERROR, "%d - %s", session->err_code, session->err_msg); \ +} + +#else /* ! LIBSSH2_DEBUG_ERRORS */ + #define libssh2_error(session, errcode, errmsg, should_free) \ { \ if (session->err_msg && session->err_should_free) { \ @@ -328,6 +359,9 @@ struct _LIBSSH2_MAC_METHOD { session->err_code = errcode; \ } +#endif /* LIBSSH2_DEBUG_ENABLED */ + + #define LIBSSH2_SOCKET_UNKNOWN 1 #define LIBSSH2_SOCKET_CONNECTED 0 #define LIBSSH2_SOCKET_DISCONNECTED -1 diff --git a/src/channel.c b/src/channel.c index 5182599..c22922b 100644 --- a/src/channel.c +++ b/src/channel.c @@ -64,7 +64,9 @@ unsigned long libssh2_channel_nextid(LIBSSH2_SESSION *session) * Gets picked up by the new one.... Pretty unlikely all told... */ session->next_channel = id + 1; - +#ifdef LIBSSH2_DEBUG_CONNECTION + _libssh2_debug(session, LIBSSH2_DBG_CONN, "Allocated new channel ID#%lu", id); +#endif return id; } /* }}} */ @@ -115,6 +117,9 @@ LIBSSH2_API LIBSSH2_CHANNEL *libssh2_channel_open_ex(LIBSSH2_SESSION *session, c unsigned char *data = NULL; unsigned long data_len; +#ifdef LIBSSH2_DEBUG_CONNECTION + _libssh2_debug(session, LIBSSH2_DBG_CONN, "Opening Channel - win %d pack %d", window_size, packet_size); +#endif channel = LIBSSH2_ALLOC(session, sizeof(LIBSSH2_CHANNEL)); if (!channel) { libssh2_error(session, LIBSSH2_ERROR_ALLOC, "Unable to allocate space for channel data", 0); @@ -170,7 +175,12 @@ LIBSSH2_API LIBSSH2_CHANNEL *libssh2_channel_open_ex(LIBSSH2_SESSION *session, c channel->local.window_size = libssh2_ntohu32(data + 9); channel->local.window_size_initial = libssh2_ntohu32(data + 9); channel->local.packet_size = libssh2_ntohu32(data + 13); - +#ifdef LIBSSH2_DEBUG_CONNECTION + _libssh2_debug(session, LIBSSH2_DBG_CONN, "Connection Established - ID: %lu/%lu win: %lu/%lu pack: %lu/%lu", + channel->local.id, channel->remote.id, + channel->local.window_size, channel->remote.window_size, + channel->local.packet_size, channel->remote.packet_size); +#endif LIBSSH2_FREE(session, packet); LIBSSH2_FREE(session, data); @@ -230,6 +240,10 @@ LIBSSH2_API LIBSSH2_CHANNEL *libssh2_channel_direct_tcpip_ex(LIBSSH2_SESSION *se unsigned long host_len = strlen(host), shost_len = strlen(shost); unsigned long message_len = host_len + shost_len + 16; /* host_len(4) + port(4) + shost_len(4) + sport(4) */ +#ifdef LIBSSH2_DEBUG_CONNECTION + _libssh2_debug(session, LIBSSH2_DBG_CONN, "Requesting direct-tcpip session to from %s:%d to %s:%d", shost, sport, host, port); +#endif + s = message = LIBSSH2_ALLOC(session, message_len); if (!message) { libssh2_error(session, LIBSSH2_ERROR_ALLOC, "Unable to allocate memory for direct-tcpip connection", 0); @@ -261,6 +275,10 @@ LIBSSH2_API LIBSSH2_LISTENER *libssh2_channel_forward_listen_ex(LIBSSH2_SESSION unsigned long packet_len = host_len + (sizeof("tcpip-forward") - 1) + 14; /* packet_type(1) + request_len(4) + want_replay(1) + host_len(4) + port(4) */ +#ifdef LIBSSH2_DEBUG_CONNECTION + _libssh2_debug(session, LIBSSH2_DBG_CONN, "Requesting tcpip-forward session for %s:%d", host, port); +#endif + s = packet = LIBSSH2_ALLOC(session, packet_len); if (!packet) { libssh2_error(session, LIBSSH2_ERROR_ALLOC, "Unable to allocate memeory for setenv packet", 0); @@ -309,6 +327,9 @@ LIBSSH2_API LIBSSH2_LISTENER *libssh2_channel_forward_listen_ex(LIBSSH2_SESSION listener->host[host_len] = 0; if (data_len >= 5 && !port) { listener->port = libssh2_ntohu32(data + 1); +#ifdef LIBSSH2_DEBUG_CONNECTION + _libssh2_debug(session, LIBSSH2_DBG_CONN, "Dynamic tcpip-forward port allocated: %d", listener->port); +#endif } else { listener->port = port; } @@ -354,6 +375,10 @@ LIBSSH2_API int libssh2_channel_forward_cancel(LIBSSH2_LISTENER *listener) unsigned long packet_len = host_len + 14 + sizeof("cancel-tcpip-forward") - 1; /* packet_type(1) + request_len(4) + want_replay(1) + host_len(4) + port(4) */ +#ifdef LIBSSH2_DEBUG_CONNECTION + _libssh2_debug(session, LIBSSH2_DBG_CONN, "Cancelling tcpip-forward session for %s:%d", listener->host, listener->port); +#endif + s = packet = LIBSSH2_ALLOC(session, packet_len); if (!packet) { libssh2_error(session, LIBSSH2_ERROR_ALLOC, "Unable to allocate memeory for setenv packet", 0); @@ -446,6 +471,10 @@ LIBSSH2_API int libssh2_channel_setenv_ex(LIBSSH2_CHANNEL *channel, char *varnam unsigned long packet_len = varname_len + value_len + 21; /* packet_type(1) + channel_id(4) + request_len(4) + request(3)"env" + want_reply(1) + varname_len(4) + value_len(4) */ +#ifdef LIBSSH2_DEBUG_CONNECTION + _libssh2_debug(session, LIBSSH2_DBG_CONN, "Setting remote environment variable: %s=%s on channel %lu/%lu", varname, value, channel->local.id, channel->remote.id); +#endif + s = packet = LIBSSH2_ALLOC(session, packet_len); if (!packet) { libssh2_error(session, LIBSSH2_ERROR_ALLOC, "Unable to allocate memeory for setenv packet", 0); @@ -502,6 +531,10 @@ LIBSSH2_API int libssh2_channel_request_pty_ex(LIBSSH2_CHANNEL *channel, char *t unsigned long packet_len = term_len + modes_len + 41; /* packet_type(1) + channel(4) + pty_req_len(4) + "pty_req"(7) + want_reply(1) + term_len(4) + width(4) + height(4) + width_px(4) + height_px(4) + modes_len(4) */ +#ifdef LIBSSH2_DEBUG_CONNECTION + _libssh2_debug(session, LIBSSH2_DBG_CONN, "Allocating tty on channel %lu/%lu", channel->local.id, channel->remote.id); +#endif + s = packet = LIBSSH2_ALLOC(session, packet_len); if (!packet) { libssh2_error(session, LIBSSH2_ERROR_ALLOC, "Unable to allocate memory for pty-request", 0); @@ -568,6 +601,13 @@ LIBSSH2_API int libssh2_channel_x11_req_ex(LIBSSH2_CHANNEL *channel, int single_ unsigned long packet_len = proto_len + cookie_len + 41; /* packet_type(1) + channel(4) + x11_req_len(4) + "x11-req"(7) + want_reply(1) + single_cnx(4) + proto_len(4) + cookie_len(4) + screen_num(4) */ +#ifdef LIBSSH2_DEBUG_CONNECTION + _libssh2_debug(session, LIBSSH2_DBG_CONN, "Requesting x11-req for channel %lu/%lu: single=%d proto=%s cookie=%s screen=%d", + channel->local.id, channel->remote.id, single_connection, + auth_proto ? auth_proto : "MIT-MAGIC-COOKIE-1", + auth_cookie ? auth_cookie : "", screen_number); +#endif + s = packet = LIBSSH2_ALLOC(session, packet_len); if (!packet) { libssh2_error(session, LIBSSH2_ERROR_ALLOC, "Unable to allocate memory for pty-request", 0); @@ -635,6 +675,10 @@ LIBSSH2_API int libssh2_channel_process_startup(LIBSSH2_CHANNEL *channel, char * packet_len += message_len + 4; } +#ifdef LIBSSH2_DEBUG_CONNECTION + _libssh2_debug(session, LIBSSH2_DBG_CONN, "starting request(%s) on channel %lu/%lu, message=%s", request, channel->local.id, channel->remote.id, message); +#endif + s = packet = LIBSSH2_ALLOC(session, packet_len); if (!packet) { libssh2_error(session, LIBSSH2_ERROR_ALLOC, "Unable to allocate memory for channel-process request", 0); @@ -681,6 +725,9 @@ LIBSSH2_API int libssh2_channel_process_startup(LIBSSH2_CHANNEL *channel, char * */ LIBSSH2_API void libssh2_channel_set_blocking(LIBSSH2_CHANNEL *channel, int blocking) { +#ifdef LIBSSH2_DEBUG_CONNECTION + _libssh2_debug(channel->session, LIBSSH2_DBG_CONN, "Setting blocking mode on channel %lu/%lu to %d", channel->local.id, channel->remote.id, blocking); +#endif channel->blocking = blocking; } /* }}} */ @@ -701,13 +748,19 @@ LIBSSH2_API int libssh2_channel_flush_ex(LIBSSH2_CHANNEL *channel, int streamid) if (((packet_type == SSH_MSG_CHANNEL_DATA) || (packet_type == SSH_MSG_CHANNEL_EXTENDED_DATA)) && (libssh2_ntohu32(packet->data + 1) == channel->local.id)) { /* It's our channel at least */ + unsigned long packet_stream_id = (packet_type == SSH_MSG_CHANNEL_DATA) ? 0 : libssh2_ntohu32(packet->data + 5); if ((streamid == LIBSSH2_CHANNEL_FLUSH_ALL) || - ((packet_type == SSH_MSG_CHANNEL_EXTENDED_DATA) && ((streamid == LIBSSH2_CHANNEL_FLUSH_EXTENDED_DATA) || (streamid = libssh2_ntohu32(packet->data + 5)))) || + ((packet_type == SSH_MSG_CHANNEL_EXTENDED_DATA) && ((streamid == LIBSSH2_CHANNEL_FLUSH_EXTENDED_DATA) || (streamid == packet_stream_id))) || ((packet_type == SSH_MSG_CHANNEL_DATA) && (streamid == 0))) { + int bytes_to_flush = packet->data_len - packet->data_head; +#ifdef LIBSSH2_DEBUG_CONNECTION + _libssh2_debug(channel->session, LIBSSH2_DBG_CONN, "Flushing %d bytes of data from stream %lu on channel %lu/%lu", bytes_to_flush, + packet_stream_id, channel->local.id, channel->remote.id); +#endif /* It's one of the streams we wanted to flush */ refund_bytes += packet->data_len - 13; - flush_bytes += packet->data_len - packet->data_head; + flush_bytes += bytes_to_flush; LIBSSH2_FREE(channel->session, packet->data); if (packet->prev) { @@ -733,6 +786,9 @@ LIBSSH2_API int libssh2_channel_flush_ex(LIBSSH2_CHANNEL *channel, int streamid) adjust[0] = SSH_MSG_CHANNEL_WINDOW_ADJUST; libssh2_htonu32(adjust + 1, channel->remote.id); libssh2_htonu32(adjust + 5, refund_bytes); +#ifdef LIBSSH2_DEBUG_CONNECTION + _libssh2_debug(channel->session, LIBSSH2_DBG_CONN, "Adjusting window %lu bytes for data flushed from channel %lu/%lu", refund_bytes, channel->local.id, channel->remote.id); +#endif if (libssh2_packet_write(channel->session, adjust, 9)) { libssh2_error(channel->session, LIBSSH2_ERROR_SOCKET_SEND, "Unable to send transfer-window adjustment packet", 0); @@ -754,6 +810,9 @@ LIBSSH2_API int libssh2_channel_flush_ex(LIBSSH2_CHANNEL *channel, int streamid) */ LIBSSH2_API void libssh2_channel_handle_extended_data(LIBSSH2_CHANNEL *channel, int ignore_mode) { +#ifdef LIBSSH2_DEBUG_CONNECTION + _libssh2_debug(channel->session, LIBSSH2_DBG_CONN, "Setting channel %lu/%lu handle_extended_data mode to %d", channel->local.id, channel->remote.id, ignore_mode); +#endif channel->remote.extended_data_ignore_mode = ignore_mode; if (ignore_mode == LIBSSH2_CHANNEL_EXTENDED_DATA_IGNORE) { @@ -770,6 +829,9 @@ LIBSSH2_API int libssh2_channel_read_ex(LIBSSH2_CHANNEL *channel, int stream_id, LIBSSH2_SESSION *session = channel->session; int bytes_read = 0, blocking_read = 0; +#ifdef LIBSSH2_DEBUG_CONNECTION + _libssh2_debug(session, LIBSSH2_DBG_CONN, "Attempting to read %d bytes from channel %lu/%lu stream #%d", (int)buflen, channel->local.id, channel->remote.id, stream_id); +#endif do { LIBSSH2_PACKET *packet; @@ -796,6 +858,9 @@ LIBSSH2_API int libssh2_channel_read_ex(LIBSSH2_CHANNEL *channel, int stream_id, unlink_packet = 1; } +#ifdef LIBSSH2_DEBUG_CONNECTION + _libssh2_debug(session, LIBSSH2_DBG_CONN, "Reading %d of buffered data from %lu/%lu/%d", want, channel->local.id, channel->remote.id, stream_id); +#endif memcpy(buf + bytes_read, packet->data + packet->data_head, want); packet->data_head += want; bytes_read += want; @@ -815,6 +880,9 @@ LIBSSH2_API int libssh2_channel_read_ex(LIBSSH2_CHANNEL *channel, int stream_id, } LIBSSH2_FREE(session, packet->data); +#ifdef LIBSSH2_DEBUG_CONNECTION + _libssh2_debug(session, LIBSSH2_DBG_CONN, "Unlinking empty packet buffer from channel %lu/%lu sending window adjust for %d bytes", channel->local.id, channel->remote.id, (int)(packet->data_len - (stream_id ? 13 : 9))); +#endif /* Adjust the window based on the block we just freed */ adjust[0] = SSH_MSG_CHANNEL_WINDOW_ADJUST; libssh2_htonu32(adjust + 1, channel->remote.id); @@ -852,6 +920,9 @@ LIBSSH2_API int libssh2_channel_write_ex(LIBSSH2_CHANNEL *channel, int stream_id unsigned char *packet; unsigned long packet_len, bufwrote = 0; +#ifdef LIBSSH2_DEBUG_CONNECTION + _libssh2_debug(session, LIBSSH2_DBG_CONN, "Writing %d bytes on channel %lu/%lu, stream #%d", (int)buflen, channel->local.id, channel->remote.id, stream_id); +#endif if (channel->local.close) { libssh2_error(session, LIBSSH2_ERROR_CHANNEL_CLOSED, "We've already closed this channel", 0); return -1; @@ -895,14 +966,23 @@ LIBSSH2_API int libssh2_channel_write_ex(LIBSSH2_CHANNEL *channel, int stream_id /* Don't exceed the remote end's limits */ /* REMEMBER local means local as the SOURCE of the data */ if (bufwrite > channel->local.window_size) { +#ifdef LIBSSH2_DEBUG_CONNECTION + _libssh2_debug(session, LIBSSH2_DBG_CONN, "Splitting write block due to %lu byte window_size on %lu/%lu/%d", channel->local.window_size, channel->local.id, channel->remote.id, stream_id); +#endif bufwrite = channel->local.window_size; } if (bufwrite > channel->local.packet_size) { +#ifdef LIBSSH2_DEBUG_CONNECTION + _libssh2_debug(session, LIBSSH2_DBG_CONN, "Splitting write block due to %lu byte packet_size on %lu/%lu/%d", channel->local.packet_size, channel->local.id, channel->remote.id, stream_id); +#endif bufwrite = channel->local.packet_size; } libssh2_htonu32(s, bufwrite); s += 4; memcpy(s, buf, bufwrite); s += bufwrite; +#ifdef LIBSSH2_DEBUG_CONNECTION + _libssh2_debug(session, LIBSSH2_DBG_CONN, "Sending %d bytes on channel %lu/%lu, stream_id=%d", (int)bufwrite, channel->local.id, channel->remote.id, stream_id); +#endif if (libssh2_packet_write(session, packet, s - packet)) { libssh2_error(session, LIBSSH2_ERROR_SOCKET_SEND, "Unable to send channel data", 0); LIBSSH2_FREE(session, packet); @@ -935,6 +1015,9 @@ LIBSSH2_API int libssh2_channel_send_eof(LIBSSH2_CHANNEL *channel) LIBSSH2_SESSION *session = channel->session; unsigned char packet[5]; /* packet_type(1) + channelno(4) */ +#ifdef LIBSSH2_DEBUG_CONNECTION + _libssh2_debug(session, LIBSSH2_DBG_CONN, "Sending EOF on channel %lu/%lu",channel->local.id, channel->remote.id); +#endif packet[0] = SSH_MSG_CHANNEL_EOF; libssh2_htonu32(packet + 1, channel->remote.id); if (libssh2_packet_write(session, packet, 5)) { @@ -981,6 +1064,10 @@ LIBSSH2_API int libssh2_channel_close(LIBSSH2_CHANNEL *channel) return 0; } +#ifdef LIBSSH2_DEBUG_CONNECTION + _libssh2_debug(session, LIBSSH2_DBG_CONN, "Closing channel %lu/%lu", channel->local.id, channel->remote.id); +#endif + if (channel->close_cb) { LIBSSH2_CHANNEL_CLOSE(session, channel); } @@ -1008,6 +1095,9 @@ LIBSSH2_API int libssh2_channel_free(LIBSSH2_CHANNEL *channel) unsigned char channel_id[4], *data; unsigned long data_len; +#ifdef LIBSSH2_DEBUG_CONNECTION + _libssh2_debug(session, LIBSSH2_DBG_CONN, "Freeing channel %lu/%lu resources", channel->local.id, channel->remote.id); +#endif /* Allow channel freeing even when the socket has lost its connection */ if (!channel->local.close && (session->socket_state == LIBSSH2_SOCKET_CONNECTED) && libssh2_channel_close(channel)) { diff --git a/src/kex.c b/src/kex.c index f01fbca..d58b3f6 100644 --- a/src/kex.c +++ b/src/kex.c @@ -109,6 +109,9 @@ static int libssh2_kex_method_diffie_hellman_groupGP_sha1_key_exchange(LIBSSH2_S BN_bn2bin(e, e_packet + 6); } +#ifdef LIBSSH2_DEBUG_KEX + _libssh2_debug(session, LIBSSH2_DBG_KEX, "Sending KEX packet %d", (int)packet_type_init); +#endif if (libssh2_packet_write(session, e_packet, e_packet_len)) { libssh2_error(session, LIBSSH2_ERROR_SOCKET_SEND, "Unable to send KEX init message", 0); ret = -11; @@ -143,7 +146,18 @@ static int libssh2_kex_method_diffie_hellman_groupGP_sha1_key_exchange(LIBSSH2_S MD5_Update(&fingerprint_ctx, session->server_hostkey, session->server_hostkey_len); MD5_Final(session->server_hostkey_md5, &fingerprint_ctx); } -#endif +#ifdef LIBSSH2_DEBUG_KEX +{ + char fingerprint[50], *fprint = fingerprint; + int i; + for(i = 0; i < 16; i++, fprint += 3) { + snprintf(fprint, 4, "%02x:", session->server_hostkey_md5[i]); + } + *(--fprint) = '\0'; + _libssh2_debug(session, LIBSSH2_DBG_KEX, "Server's MD5 Fingerprint: %s", fingerprint); +} +#endif /* LIBSSH2_DEBUG_KEX */ +#endif /* ! OPENSSL_NO_MD5 */ #ifndef OPENSSL_NO_SHA { @@ -153,7 +167,18 @@ static int libssh2_kex_method_diffie_hellman_groupGP_sha1_key_exchange(LIBSSH2_S SHA1_Update(&fingerprint_ctx, session->server_hostkey, session->server_hostkey_len); SHA1_Final(session->server_hostkey_sha1, &fingerprint_ctx); } -#endif +#ifdef LIBSSH2_DEBUG_KEX +{ + char fingerprint[64], *fprint = fingerprint; + int i; + for(i = 0; i < 20; i++, fprint += 3) { + snprintf(fprint, 4, "%02x:", session->server_hostkey_sha1[i]); + } + *(--fprint) = '\0'; + _libssh2_debug(session, LIBSSH2_DBG_KEX, "Server's SHA1 Fingerprint: %s", fingerprint); +} +#endif /* LIBSSH2_DEBUG_KEX */ +#endif /* ! OPENSSL_NO_SHA */ if (session->hostkey->init(session, session->server_hostkey, session->server_hostkey_len, &session->server_hostkey_abstract)) { libssh2_error(session, LIBSSH2_ERROR_HOSTKEY_INIT, "Unable to initialize hostkey importer", 0); @@ -161,7 +186,6 @@ static int libssh2_kex_method_diffie_hellman_groupGP_sha1_key_exchange(LIBSSH2_S goto clean_exit; } - f_value_len = libssh2_ntohu32(s); s += 4; f_value = s; s += f_value_len; BN_bin2bn(f_value, f_value_len, f); @@ -250,6 +274,9 @@ static int libssh2_kex_method_diffie_hellman_groupGP_sha1_key_exchange(LIBSSH2_S goto clean_exit; } +#ifdef LIBSSH2_DEBUG_KEX + _libssh2_debug(session, LIBSSH2_DBG_KEX, "Sending NEWKEYS message"); +#endif c = SSH_MSG_NEWKEYS; if (libssh2_packet_write(session, &c, 1)) { libssh2_error(session, LIBSSH2_ERROR_SOCKET_SEND, "Unable to send NEWKEYS message", 0); @@ -264,6 +291,9 @@ static int libssh2_kex_method_diffie_hellman_groupGP_sha1_key_exchange(LIBSSH2_S } /* The first key exchange has been performed, switch to active crypt/comp/mac mode */ session->state |= LIBSSH2_STATE_NEWKEYS; +#ifdef LIBSSH2_DEBUG_KEX + _libssh2_debug(session, LIBSSH2_DBG_KEX, "Received NEWKEYS message"); +#endif /* This will actually end up being just packet_type(1) for this packet type anyway */ LIBSSH2_FREE(session, tmp); @@ -276,6 +306,9 @@ static int libssh2_kex_method_diffie_hellman_groupGP_sha1_key_exchange(LIBSSH2_S } memcpy(session->session_id, h_sig_comp, SHA_DIGEST_LENGTH); session->session_id_len = SHA_DIGEST_LENGTH; +#ifdef LIBSSH2_DEBUG_KEX + _libssh2_debug(session, LIBSSH2_DBG_KEX, "session_id calculated"); +#endif } /* Calculate IV/Secret/Key for each direction */ @@ -327,6 +360,9 @@ static int libssh2_kex_method_diffie_hellman_groupGP_sha1_key_exchange(LIBSSH2_S LIBSSH2_FREE(session, secret); } } +#ifdef LIBSSH2_DEBUG_KEX + _libssh2_debug(session, LIBSSH2_DBG_KEX, "Client to Server IV and Key calculated"); +#endif if (session->remote.crypt->flags & LIBSSH2_CRYPT_METHOD_FLAG_EVP) { if (session->remote.crypt_abstract) { @@ -376,6 +412,9 @@ static int libssh2_kex_method_diffie_hellman_groupGP_sha1_key_exchange(LIBSSH2_S LIBSSH2_FREE(session, secret); } } +#ifdef LIBSSH2_DEBUG_KEX + _libssh2_debug(session, LIBSSH2_DBG_KEX, "Server to Client IV and Key calculated"); +#endif if (session->local.mac->dtor) { session->local.mac->dtor(session, &session->local.mac_abstract); @@ -393,6 +432,9 @@ static int libssh2_kex_method_diffie_hellman_groupGP_sha1_key_exchange(LIBSSH2_S LIBSSH2_FREE(session, key); } } +#ifdef LIBSSH2_DEBUG_KEX + _libssh2_debug(session, LIBSSH2_DBG_KEX, "Client to Server HMAC Key calculated"); +#endif if (session->remote.mac->dtor) { session->remote.mac->dtor(session, &session->remote.mac_abstract); @@ -410,6 +452,9 @@ static int libssh2_kex_method_diffie_hellman_groupGP_sha1_key_exchange(LIBSSH2_S LIBSSH2_FREE(session, key); } } +#ifdef LIBSSH2_DEBUG_KEX + _libssh2_debug(session, LIBSSH2_DBG_KEX, "Server to Client HMAC Key calculated"); +#endif clean_exit: BN_clear_free(x); @@ -470,6 +515,9 @@ static int libssh2_kex_method_diffie_hellman_group1_sha1_key_exchange(LIBSSH2_SE BN_set_word(g, 2); BN_bin2bn(p_value, 128, p); +#ifdef LIBSSH2_DEBUG_KEX + _libssh2_debug(session, LIBSSH2_DBG_KEX, "Initiating Diffie-Hellman Group1 Key Exchange"); +#endif ret = libssh2_kex_method_diffie_hellman_groupGP_sha1_key_exchange(session, g, p, SSH_MSG_KEXDH_INIT, SSH_MSG_KEXDH_REPLY, NULL, 0); BN_clear_free(p); @@ -526,6 +574,9 @@ static int libssh2_kex_method_diffie_hellman_group14_sha1_key_exchange(LIBSSH2_S BN_set_word(g, 2); BN_bin2bn(p_value, 256, p); +#ifdef LIBSSH2_DEBUG_KEX + _libssh2_debug(session, LIBSSH2_DBG_KEX, "Initiating Diffie-Hellman Group14 Key Exchange"); +#endif ret = libssh2_kex_method_diffie_hellman_groupGP_sha1_key_exchange(session, g, p, SSH_MSG_KEXDH_INIT, SSH_MSG_KEXDH_REPLY, NULL, 0); BN_clear_free(p); @@ -554,10 +605,16 @@ static int libssh2_kex_method_diffie_hellman_group_exchange_sha1_key_exchange(LI libssh2_htonu32(request + 5, LIBSSH2_DH_GEX_OPTGROUP); libssh2_htonu32(request + 9, LIBSSH2_DH_GEX_MAXGROUP); request_len = 13; +#ifdef LIBSSH2_DEBUG_KEX + _libssh2_debug(session, LIBSSH2_DBG_KEX, "Initiating Diffie-Hellman Group-Exchange (New Method)"); +#endif #else request[0] = SSH_MSG_KEX_DH_GEX_REQUEST_OLD; libssh2_htonu32(request + 1, LIBSSH2_DH_GEX_OPTGROUP); request_len = 5; +#ifdef LIBSSH2_DEBUG_KEX + _libssh2_debug(session, LIBSSH2_DBG_KEX, "Initiating Diffie-Hellman Group-Exchange (Old Method)"); +#endif #endif if (libssh2_packet_write(session, request, request_len)) { @@ -746,6 +803,23 @@ static int libssh2_kexinit(LIBSSH2_SESSION *session) *(s++) = 0; *(s++) = 0; +#ifdef LIBSSH2_DEBUG_KEX +{ + /* Funnily enough, they'll all "appear" to be '\0' terminated */ + char *p = data + 21; /* type(1) + cookie(16) + len(4) */ + + _libssh2_debug(session, LIBSSH2_DBG_KEX, "Sent KEX: %s", p); p += kex_len + 4; + _libssh2_debug(session, LIBSSH2_DBG_KEX, "Sent HOSTKEY: %s", p); p += hostkey_len + 4; + _libssh2_debug(session, LIBSSH2_DBG_KEX, "Sent CRYPT_CS: %s", p); p += crypt_cs_len + 4; + _libssh2_debug(session, LIBSSH2_DBG_KEX, "Sent CRYPT_SC: %s", p); p += crypt_sc_len + 4; + _libssh2_debug(session, LIBSSH2_DBG_KEX, "Sent MAC_CS: %s", p); p += mac_cs_len + 4; + _libssh2_debug(session, LIBSSH2_DBG_KEX, "Sent MAC_SC: %s", p); p += mac_sc_len + 4; + _libssh2_debug(session, LIBSSH2_DBG_KEX, "Sent COMP_CS: %s", p); p += comp_cs_len + 4; + _libssh2_debug(session, LIBSSH2_DBG_KEX, "Sent COMP_SC: %s", p); p += comp_sc_len + 4; + _libssh2_debug(session, LIBSSH2_DBG_KEX, "Sent LANG_CS: %s", p); p += lang_cs_len + 4; + _libssh2_debug(session, LIBSSH2_DBG_KEX, "Sent LANG_SC: %s", p); p += lang_sc_len + 4; +} +#endif /* LIBSSH2_DEBUG_KEX */ if (libssh2_packet_write(session, data, data_len)) { LIBSSH2_FREE(session, data); libssh2_error(session, LIBSSH2_ERROR_SOCKET_SEND, "Unable to send KEXINIT packet to remote host", 0); @@ -1120,6 +1194,19 @@ static int libssh2_kex_agree_methods(LIBSSH2_SESSION *session, unsigned char *da return -1; } +#ifdef LIBSSH2_DEBUG_KEX + _libssh2_debug(session, LIBSSH2_DBG_KEX, "Agreed on KEX method: %s", session->kex->name); + _libssh2_debug(session, LIBSSH2_DBG_KEX, "Agreed on HOSTKEY method: %s", session->hostkey->name); + _libssh2_debug(session, LIBSSH2_DBG_KEX, "Agreed on CRYPT_CS method: %s", session->local.crypt->name); + _libssh2_debug(session, LIBSSH2_DBG_KEX, "Agreed on CRYPT_SC method: %s", session->remote.crypt->name); + _libssh2_debug(session, LIBSSH2_DBG_KEX, "Agreed on MAC_CS method: %s", session->local.mac->name); + _libssh2_debug(session, LIBSSH2_DBG_KEX, "Agreed on MAC_SC method: %s", session->remote.mac->name); + _libssh2_debug(session, LIBSSH2_DBG_KEX, "Agreed on COMP_CS method: %s", session->local.comp->name); + _libssh2_debug(session, LIBSSH2_DBG_KEX, "Agreed on COMP_SC method: %s", session->remote.comp->name); + _libssh2_debug(session, LIBSSH2_DBG_KEX, "Agreed on LANG_CS method:"); /* None yet */ + _libssh2_debug(session, LIBSSH2_DBG_KEX, "Agreed on LANG_SC method:"); /* None yet */ +#endif + /* Initialize compression layer */ if (session->local.comp && session->local.comp->init && session->local.comp->init(session, 1, &session->local.comp_abstract)) { diff --git a/src/misc.c b/src/misc.c index 4364c7d..c3b702d 100644 --- a/src/misc.c +++ b/src/misc.c @@ -169,3 +169,29 @@ LIBSSH2_API int libssh2_base64_decode(LIBSSH2_SESSION *session, char **data, int } /* }}} */ +#ifdef LIBSSH2_DEBUG_ENABLED +/* {{{ _libssh2_debug + * Internal debug logging facility + * Just writes to stderr until a good reason comes up to support anything else + */ +void _libssh2_debug(LIBSSH2_SESSION *session, int context, const char *format, ...) +{ + char buffer[1536]; + int len; + va_list vargs; + char *contexts[8] = { "Unknown", "Transport", "Key Exhange", "Userauth", "Connection", "scp", "SFTP", "Failure Event" }; + + if (context < 1 || context > 6) { + context = 0; + } + + len = snprintf(buffer, 1535, "[libssh2] %s: ", contexts[context]); + + va_start(vargs, format); + len += vsnprintf(buffer, 1535 - len, format, vargs); + buffer[len] = '\n'; + va_end(vargs); + write(2, buffer, len + 1); +} +/* }}} */ +#endif diff --git a/src/packet.c b/src/packet.c index 526ed9a..ba90da8 100644 --- a/src/packet.c +++ b/src/packet.c @@ -91,6 +91,9 @@ inline int libssh2_packet_queue_listener(LIBSSH2_SESSION *session, unsigned char shost = s; s += shost_len; sport = libssh2_ntohu32(s); s += 4; +#ifdef LIBSSH2_DEBUG_CONNECTION + _libssh2_debug(session, LIBSSH2_DBG_CONN, "Remote received connection from %s:%ld to %s:%ld", shost, sport, host, port); +#endif while (l) { if ((l->port == port) && (strlen(l->host) == host_len) && @@ -102,6 +105,9 @@ inline int libssh2_packet_queue_listener(LIBSSH2_SESSION *session, unsigned char (l->queue_maxsize <= l->queue_size)) { /* Queue is full */ failure_code = 4; /* SSH_OPEN_RESOURCE_SHORTAGE */ +#ifdef LIBSSH2_DEBUG_CONNECTION + _libssh2_debug(session, LIBSSH2_DBG_CONN, "Listener queue full, ignoring"); +#endif break; } @@ -134,6 +140,13 @@ inline int libssh2_packet_queue_listener(LIBSSH2_SESSION *session, unsigned char channel->local.window_size = initial_window_size; channel->local.packet_size = packet_size; +#ifdef LIBSSH2_DEBUG_CONNECTION + _libssh2_debug(session, LIBSSH2_DBG_CONN, "Connection queued: channel %ul/%ul win %ul/%ul packet %ul/%ul", + channel->local.id, channel->remote.id, + channel->local.window_size, channel->remote.window_size, + channel->local.packet_size, channel->remote.packet_size); +#endif + p = packet; *(p++) = SSH_MSG_CHANNEL_OPEN_CONFIRMATION; libssh2_htonu32(p, channel->remote.id); p += 4; @@ -208,6 +221,9 @@ inline int libssh2_packet_x11_open(LIBSSH2_SESSION *session, unsigned char *data shost = s; s += shost_len; sport = libssh2_ntohu32(s); s += 4; +#ifdef LIBSSH2_DEBUG_CONNECTION + _libssh2_debug(session, LIBSSH2_DBG_CONN, "X11 Connection Received from %s:%ld on channel %ul", shost, sport, sender_channel); +#endif if (session->x11) { channel = LIBSSH2_ALLOC(session, sizeof(LIBSSH2_CHANNEL)); if (!channel) { @@ -238,6 +254,12 @@ inline int libssh2_packet_x11_open(LIBSSH2_SESSION *session, unsigned char *data channel->local.window_size = initial_window_size; channel->local.packet_size = packet_size; +#ifdef LIBSSH2_DEBUG_CONNECTION + _libssh2_debug(session, LIBSSH2_DBG_CONN, "X11 Connection established: channel %ul/%ul win %ul/%ul packet %ul/%ul", + channel->local.id, channel->remote.id, + channel->local.window_size, channel->remote.window_size, + channel->local.packet_size, channel->remote.packet_size); +#endif p = packet; *(p++) = SSH_MSG_CHANNEL_OPEN_CONFIRMATION; libssh2_htonu32(p, channel->remote.id); p += 4; @@ -294,6 +316,9 @@ static int libssh2_packet_add(LIBSSH2_SESSION *session, unsigned char *data, siz LIBSSH2_PACKET *packet; unsigned long data_head = 0; +#ifdef LIBSSH2_DEBUG_TRANSPORT + _libssh2_debug(session, LIBSSH2_DBG_TRANS, "Packet type %d received, length=%d", (int)data[0], (int)datalen); +#endif if (macstate == LIBSSH2_MAC_INVALID) { if (session->macerror) { if (LIBSSH2_MACERROR(session, data, datalen) == 0) { @@ -342,6 +367,9 @@ static int libssh2_packet_add(LIBSSH2_SESSION *session, unsigned char *data, siz if (session->ssh_msg_disconnect) { LIBSSH2_DISCONNECT(session, reason, message, message_len, language, language_len); } +#ifdef LIBSSH2_DEBUG_TRANSPORT + _libssh2_debug(session, LIBSSH2_DBG_TRANS, "Disconnect(%d): %s(%s)", reason, message, language); +#endif LIBSSH2_FREE(session, data); session->socket_state = LIBSSH2_SOCKET_DISCONNECTED; return -1; @@ -382,6 +410,10 @@ static int libssh2_packet_add(LIBSSH2_SESSION *session, unsigned char *data, siz if (session->ssh_msg_debug) { LIBSSH2_DEBUG(session, always_display, message, message_len, language, language_len); } +#ifdef LIBSSH2_DEBUG_TRANSPORT + /* _libssh2_debug will actually truncate this for us so that it's not an inordinate about of data */ + _libssh2_debug(session, LIBSSH2_DBG_TRANS, "Debug Packet: %s", message); +#endif LIBSSH2_FREE(session, data); return 0; } @@ -398,6 +430,17 @@ static int libssh2_packet_add(LIBSSH2_SESSION *session, unsigned char *data, siz LIBSSH2_FREE(session, data); return 0; } +#ifdef LIBSSH2_DEBUG_CONNECTION +{ + unsigned long stream_id = 0; + + if (data[0] == SSH_MSG_CHANNEL_EXTENDED_DATA) { + stream_id = libssh2_ntohu32(data + 5); + } + + _libssh2_debug(session, LIBSSH2_DBG_CONN, "%d bytes received for channel %ul/%ul stream #%ul", (int)(datalen - data_head), channel->local.id, channel->remote.id, stream_id); +} +#endif if ((channel->remote.extended_data_ignore_mode == LIBSSH2_CHANNEL_EXTENDED_DATA_IGNORE) && (data[0] == SSH_MSG_CHANNEL_EXTENDED_DATA)) { /* Pretend we didn't receive this */ LIBSSH2_FREE(session, data); @@ -406,6 +449,9 @@ static int libssh2_packet_add(LIBSSH2_SESSION *session, unsigned char *data, siz /* Adjust the window based on the block we just freed */ unsigned char adjust[9]; +#ifdef LIBSSH2_DEBUG_CONNECTION + _libssh2_debug(session, LIBSSH2_DBG_CONN, "Ignoring extended data and refunding %d bytes", (int)(datalen - 13)); +#endif adjust[0] = SSH_MSG_CHANNEL_WINDOW_ADJUST; libssh2_htonu32(adjust + 1, channel->remote.id); libssh2_htonu32(adjust + 5, datalen - 13); @@ -451,6 +497,9 @@ static int libssh2_packet_add(LIBSSH2_SESSION *session, unsigned char *data, siz return 0; } +#ifdef LIBSSH2_DEBUG_CONNECTION + _libssh2_debug(session, LIBSSH2_DBG_CONN, "EOF received for channel %ul/%ul", channel->local.id, channel->remote.id); +#endif channel->remote.eof = 1; LIBSSH2_FREE(session, data); @@ -466,6 +515,9 @@ static int libssh2_packet_add(LIBSSH2_SESSION *session, unsigned char *data, siz LIBSSH2_FREE(session, data); return 0; } +#ifdef LIBSSH2_DEBUG_CONNECTION + _libssh2_debug(session, LIBSSH2_DBG_CONN, "Close received for channel %ul/%ul", channel->local.id, channel->remote.id); +#endif channel->remote.close = 1; /* TODO: Add a callback for this */ @@ -500,6 +552,9 @@ static int libssh2_packet_add(LIBSSH2_SESSION *session, unsigned char *data, siz if (channel && bytestoadd) { channel->local.window_size += bytestoadd; } +#ifdef LIBSSH2_DEBUG_CONNECTION + _libssh2_debug(session, LIBSSH2_DBG_CONN, "Window adjust received for channel %ul/%ul, adding %ul bytes, new window_size=%ul", channel->local.id, channel->remote.id, bytestoadd, channel->local.window_size); +#endif LIBSSH2_FREE(session, data); return 0; @@ -532,6 +587,9 @@ static int libssh2_packet_add(LIBSSH2_SESSION *session, unsigned char *data, siz * Well, it's already in the brigade, * let's just call back into ourselves */ +#ifdef LIBSSH2_DEBUG_TRANSPORT + _libssh2_debug(session, LIBSSH2_DBG_TRANS, "Renegotiating Keys"); +#endif libssh2_kex_exchange(session, 1); /* If there was a key reexchange failure, let's just hope we didn't send NEWKEYS yet, otherwise remote will drop us like a rock */ } @@ -559,6 +617,10 @@ static int libssh2_blocking_read(LIBSSH2_SESSION *session, unsigned char *buf, s } #endif +#ifdef LIBSSH2_DEBUG_TRANSPORT + _libssh2_debug(session, LIBSSH2_DBG_TRANS, "Blocking read: %d bytes", (int)count); +#endif + while (bytes_read < count) { int ret; @@ -617,6 +679,10 @@ static int libssh2_blocking_read(LIBSSH2_SESSION *session, unsigned char *buf, s bytes_read += ret; } +#ifdef LIBSSH2_DEBUG_TRANSPORT + _libssh2_debug(session, LIBSSH2_DBG_TRANS, "Blocking read: %d bytes actually read", (int)bytes_read); +#endif + return bytes_read; } /* }}} */ @@ -643,6 +709,10 @@ int libssh2_packet_read(LIBSSH2_SESSION *session, int should_block) ioctlsocket(session->socket_fd, FIONBIO, &non_block); } #endif + +#ifdef LIBSSH2_DEBUG_TRANSPORT + _libssh2_debug(session, LIBSSH2_DBG_TRANS, "Checking for packet: will%s block", should_block ? "" : " not"); +#endif if (session->state & LIBSSH2_STATE_NEWKEYS) { /* Temporary Buffer * The largest blocksize (currently) is 32, the largest MAC (currently) is 20 @@ -685,6 +755,9 @@ int libssh2_packet_read(LIBSSH2_SESSION *session, int should_block) packet_len = libssh2_ntohu32(block); padding_len = block[4]; +#ifdef LIBSSH2_DEBUG_TRANSPORT + _libssh2_debug(session, LIBSSH2_DBG_TRANS, "Processing packet %ul bytes long (with %ul bytes padding)", packet_len, padding_len); +#endif memcpy(tmp, block, 5); /* Use this for MAC later */ payload_len = packet_len - 1; /* padding_len(1) */ @@ -748,6 +821,9 @@ int libssh2_packet_read(LIBSSH2_SESSION *session, int should_block) LIBSSH2_FREE(session, payload); return -1; } +#ifdef LIBSSH2_DEBUG_TRANSPORT + _libssh2_debug(session, LIBSSH2_DBG_TRANS, "Payload decompressed: %ul bytes(compressed) to %ul bytes(uncompressed)", data_len, payload_len); +#endif if (free_payload) { LIBSSH2_FREE(session, payload); payload = data; @@ -800,6 +876,9 @@ int libssh2_packet_read(LIBSSH2_SESSION *session, int should_block) } packet_length = libssh2_ntohu32(buf); padding_length = buf[4]; +#ifdef LIBSSH2_DEBUG_TRANSPORT + _libssh2_debug(session, LIBSSH2_DBG_TRANS, "Processing plaintext packet %ul bytes long (with %ul bytes padding)", packet_length, padding_length); +#endif payload_len = packet_length - padding_length - 1; /* padding_length(1) */ payload = LIBSSH2_ALLOC(session, payload_len); @@ -840,6 +919,9 @@ int libssh2_packet_ask_ex(LIBSSH2_SESSION *session, unsigned char packet_type, u return -1; } } +#ifdef LIBSSH2_DEBUG_TRANSPORT + _libssh2_debug(session, LIBSSH2_DBG_TRANS, "Looking for packet of type: %d", (int)packet_type); +#endif while (packet) { if (packet->data[0] == packet_type && (packet->data_len >= (match_ofs + match_len)) && @@ -899,6 +981,9 @@ int libssh2_packet_require_ex(LIBSSH2_SESSION *session, unsigned char packet_typ return 0; } +#ifdef LIBSSH2_DEBUG_TRANSPORT + _libssh2_debug(session, LIBSSH2_DBG_TRANS, "Blocking until packet of type %d becomes available", (int)packet_type); +#endif while (session->socket_state == LIBSSH2_SOCKET_CONNECTED) { int ret = libssh2_packet_read(session, 1); if (ret < 0) { @@ -963,12 +1048,25 @@ int libssh2_packet_write(LIBSSH2_SESSION *session, unsigned char *data, unsigned int free_data = 0; unsigned char buf[246]; /* 6 byte header plus max padding size(240) */ +#ifdef LIBSSH2_DEBUG_TRANSPORT +{ + /* Show a hint of what's being sent */ + char excerpt[32]; + int ex_len = 0, db_ofs = 0; + + for (; ex_len < 24 && db_ofs < data_len; ex_len += 3, db_ofs++) snprintf(excerpt + ex_len, 4, "%02X ", data[db_ofs]); + _libssh2_debug(session, LIBSSH2_DBG_TRANS, "Sending packet type %d, length=%lu, %s", (int)data[0], data_len, excerpt); +} +#endif if ((session->state & LIBSSH2_STATE_NEWKEYS) && strcmp(session->local.comp->name, "none")) { if (session->local.comp->comp(session, 1, &data, &data_len, LIBSSH2_PACKET_MAXCOMP, &free_data, data, data_len, &session->local.comp_abstract)) { return -1; } +#ifdef LIBSSH2_DEBUG_TRANSPORT + _libssh2_debug(session, LIBSSH2_DBG_TRANS, "Compressed payload to %ul bytes", data_len); +#endif } #ifndef WIN32 @@ -990,6 +1088,9 @@ int libssh2_packet_write(LIBSSH2_SESSION *session, unsigned char *data, unsigned packet_length += padding_length; libssh2_htonu32(buf, packet_length); buf[4] = padding_length; +#ifdef LIBSSH2_DEBUG_TRANSPORT + _libssh2_debug(session, LIBSSH2_DBG_TRANS, "Sending packet with total length %ul (%ul bytes padding)", packet_length, padding_length); +#endif if (session->state & LIBSSH2_STATE_NEWKEYS) { /* Encryption is in effect */ diff --git a/src/scp.c b/src/scp.c index 0d4bb11..2ad264c 100644 --- a/src/scp.c +++ b/src/scp.c @@ -70,6 +70,9 @@ LIBSSH2_API LIBSSH2_CHANNEL *libssh2_scp_recv(LIBSSH2_SESSION *session, char *pa } command[command_len - 1] = '\0'; +#ifdef LIBSSH2_DEBUG_SCP + _libssh2_debug(session, LIBSSH2_DBG_SCP, "Opening channel for SCP receive"); +#endif /* Allocate a channel */ if ((channel = libssh2_channel_open_session(session)) == NULL) { LIBSSH2_FREE(session, command); @@ -86,6 +89,9 @@ LIBSSH2_API LIBSSH2_CHANNEL *libssh2_scp_recv(LIBSSH2_SESSION *session, char *pa } LIBSSH2_FREE(session, command); +#ifdef LIBSSH2_DEBUG_SCP + _libssh2_debug(session, LIBSSH2_DBG_SCP, "Sending initial wakeup"); +#endif /* SCP ACK */ response[0] = '\0'; if (libssh2_channel_write(channel, response, 1) != 1) { @@ -197,6 +203,9 @@ LIBSSH2_API LIBSSH2_CHANNEL *libssh2_scp_recv(LIBSSH2_SESSION *session, char *pa libssh2_channel_free(channel); return NULL; } +#ifdef LIBSSH2_DEBUG_SCP + _libssh2_debug(session, LIBSSH2_DBG_SCP, "mtime = %ld, atime = %ld", mtime, atime); +#endif /* We *should* check that atime.usec is valid, but why let that stop use? */ break; @@ -295,6 +304,9 @@ LIBSSH2_API LIBSSH2_CHANNEL *libssh2_scp_recv(LIBSSH2_SESSION *session, char *pa libssh2_channel_free(channel); return NULL; } +#ifdef LIBSSH2_DEBUG_SCP + _libssh2_debug(session, LIBSSH2_DBG_SCP, "mod = 0%lo size = %ld", mode, size); +#endif /* We *should* check that basename is valid, but why let that stop us? */ break; @@ -344,6 +356,9 @@ LIBSSH2_API LIBSSH2_CHANNEL *libssh2_scp_send_ex(LIBSSH2_SESSION *session, char } command[command_len - 1] = '\0'; +#ifdef LIBSSH2_DEBUG_SCP + _libssh2_debug(session, LIBSSH2_DBG_SCP, "Opening channel for SCP send"); +#endif /* Allocate a channel */ if ((channel = libssh2_channel_open_session(session)) == NULL) { /* previous call set libssh2_session_last_error(), pass it through */ @@ -372,6 +387,9 @@ LIBSSH2_API LIBSSH2_CHANNEL *libssh2_scp_send_ex(LIBSSH2_SESSION *session, char /* Send mtime and atime to be used for file */ if (mtime || atime) { response_len = snprintf(response, LIBSSH2_SCP_RESPONSE_BUFLEN, "T%ld 0 %ld 0\n", mtime, atime); +#ifdef LIBSSH2_DEBUG_SCP + _libssh2_debug(session, LIBSSH2_DBG_SCP, "Sent %s", response); +#endif if (libssh2_channel_write(channel, response, response_len) != response_len) { libssh2_error(session, LIBSSH2_ERROR_SOCKET_SEND, "Unable to send time data for SCP file", 0); libssh2_channel_free(channel); @@ -394,6 +412,9 @@ LIBSSH2_API LIBSSH2_CHANNEL *libssh2_scp_send_ex(LIBSSH2_SESSION *session, char } response_len = snprintf(response, LIBSSH2_SCP_RESPONSE_BUFLEN, "C0%o %lu %s\n", mode, (unsigned long)size, base); +#ifdef LIBSSH2_DEBUG_SCP + _libssh2_debug(session, LIBSSH2_DBG_SCP, "Sent %s", response); +#endif if (libssh2_channel_write(channel, response, response_len) != response_len) { libssh2_error(session, LIBSSH2_ERROR_SOCKET_SEND, "Unable to send core file data for SCP file", 0); libssh2_channel_free(channel); diff --git a/src/session.c b/src/session.c index e14a6ca..4294ccd 100644 --- a/src/session.c +++ b/src/session.c @@ -128,6 +128,9 @@ static int libssh2_banner_receive(LIBSSH2_SESSION *session) session->remote.banner = LIBSSH2_ALLOC(session, banner_len + 1); memcpy(session->remote.banner, banner, banner_len); session->remote.banner[banner_len] = '\0'; +#ifdef LIBSSH2_DEBUG_TRANSPORT + _libssh2_debug(session, LIBSSH2_DBG_TRANS, "Received Banner: %s", session->remote.banner); +#endif return 0; } /* }}} */ @@ -145,6 +148,22 @@ static int libssh2_banner_send(LIBSSH2_SESSION *session) banner_len = strlen(session->local.banner); banner = session->local.banner; } +#ifdef LIBSSH2_DEBUG_TRANSPORT +{ + /* Hack and slash to avoid sending CRLF in debug output */ + char banner_dup[256]; + + if (banner_len < 256) { + memcpy(banner_dup, banner, banner_len - 2); + banner_dup[banner_len - 2] = '\0'; + } else { + memcpy(banner_dup, banner, 255); + banner[255] = '\0'; + } + + _libssh2_debug(session, LIBSSH2_DBG_TRANS, "Sending Banner: %s", banner_dup); +} +#endif return (send(session->socket_fd, banner, banner_len, LIBSSH2_SOCKET_SEND_FLAGS(session)) == banner_len) ? 0 : 1; } @@ -173,6 +192,10 @@ LIBSSH2_API int libssh2_banner_set(LIBSSH2_SESSION *session, char *banner) } memcpy(session->local.banner, banner, banner_len); +#ifdef LIBSSH2_DEBUG_TRANSPORT + session->local.banner[banner_len] = '\0'; + _libssh2_debug(session, LIBSSH2_DBG_TRANS, "Setting local Banner: %s", session->local.banner); +#endif session->local.banner[banner_len++] = '\r'; session->local.banner[banner_len++] = '\n'; session->local.banner[banner_len++] = '\0'; @@ -208,6 +231,9 @@ LIBSSH2_API LIBSSH2_SESSION *libssh2_session_init_ex( session->free = local_free; session->realloc = local_realloc; session->abstract = abstract; +#ifdef LIBSSH2_DEBUG_TRANSPORT + _libssh2_debug(session, LIBSSH2_DBG_TRANS, "New session resource allocated"); +#endif return session; } @@ -248,6 +274,9 @@ LIBSSH2_API void* libssh2_session_callback_set(LIBSSH2_SESSION *session, int cbt return oldcb; break; } +#ifdef LIBSSH2_DEBUG_TRANSPORT + _libssh2_debug(session, LIBSSH2_DBG_TRANS, "Setting Callback %d", cbtype); +#endif return NULL; } @@ -266,6 +295,9 @@ LIBSSH2_API int libssh2_session_startup(LIBSSH2_SESSION *session, int socket) unsigned char service[sizeof("ssh-userauth") + 5 - 1]; unsigned long service_length; +#ifdef LIBSSH2_DEBUG_TRANSPORT + _libssh2_debug(session, LIBSSH2_DBG_TRANS, "session_startup for socket %d", socket); +#endif if (socket <= 0) { /* Did we forget something? */ libssh2_error(session, LIBSSH2_ERROR_SOCKET_NONE, "No socket provided", 0); @@ -291,6 +323,9 @@ LIBSSH2_API int libssh2_session_startup(LIBSSH2_SESSION *session, int socket) return LIBSSH2_ERROR_KEX_FAILURE; } +#ifdef LIBSSH2_DEBUG_TRANSPORT + _libssh2_debug(session, LIBSSH2_DBG_TRANS, "Requesting userauth service"); +#endif /* Request the userauth service */ service[0] = SSH_MSG_SERVICE_REQUEST; libssh2_htonu32(service + 1, sizeof("ssh-userauth") - 1); @@ -323,6 +358,9 @@ LIBSSH2_API int libssh2_session_startup(LIBSSH2_SESSION *session, int socket) */ LIBSSH2_API void libssh2_session_free(LIBSSH2_SESSION *session) { +#ifdef LIBSSH2_DEBUG_TRANSPORT + _libssh2_debug(session, LIBSSH2_DBG_TRANS, "Freeing session resource", session->remote.banner); +#endif while (session->channels.head) { LIBSSH2_CHANNEL *tmp = session->channels.head; @@ -464,6 +502,9 @@ LIBSSH2_API int libssh2_session_disconnect_ex(LIBSSH2_SESSION *session, int reas unsigned char *s, *data; unsigned long data_len, descr_len = 0, lang_len = 0; +#ifdef LIBSSH2_DEBUG_TRANSPORT + _libssh2_debug(session, LIBSSH2_DBG_TRANS, "Disconnecting: reason=%d, desc=%s, lang=%s", reason, description, lang); +#endif if (description) { descr_len = strlen(description); } diff --git a/src/sftp.c b/src/sftp.c index f5d7b0e..44baaf2 100644 --- a/src/sftp.c +++ b/src/sftp.c @@ -123,6 +123,9 @@ static int libssh2_sftp_packet_add(LIBSSH2_SFTP *sftp, unsigned char *data, unsi LIBSSH2_SESSION *session = sftp->channel->session; LIBSSH2_PACKET *packet; +#ifdef LIBSSH2_DEBUG_SFTP + _libssh2_debug(session, LIBSSH2_DBG_SFTP, "Received packet %d", (int)data[0]); +#endif packet = LIBSSH2_ALLOC(session, sizeof(LIBSSH2_PACKET)); if (!packet) { libssh2_error(session, LIBSSH2_ERROR_ALLOC, "Unable to allocate datablock for SFTP packet", 0); @@ -158,6 +161,9 @@ static int libssh2_sftp_packet_read(LIBSSH2_SFTP *sftp, int should_block) unsigned char *packet; unsigned long packet_len; +#ifdef LIBSSH2_DEBUG_SFTP + _libssh2_debug(session, LIBSSH2_DBG_SFTP, "Waiting for packet: %s block", should_block ? "will" : "willnot"); +#endif if (should_block) { libssh2_channel_set_blocking(channel, 1); if (4 != libssh2_channel_read(channel, buffer, 4)) { @@ -177,6 +183,9 @@ static int libssh2_sftp_packet_read(LIBSSH2_SFTP *sftp, int should_block) } } packet_len = libssh2_ntohu32(buffer); +#ifdef LIBSSH2_DEBUG_SFTP + _libssh2_debug(session, LIBSSH2_DBG_SFTP, "Data begin - Packet Length: %lu", packet_len); +#endif if (packet_len > LIBSSH2_SFTP_PACKET_MAXLEN) { libssh2_error(session, LIBSSH2_ERROR_CHANNEL_PACKET_EXCEEDED, "SFTP packet too large", 0); return -1; @@ -213,6 +222,9 @@ static int libssh2_sftp_packet_ask(LIBSSH2_SFTP *sftp, unsigned char packet_type unsigned char match_buf[5]; int match_len = 5; +#ifdef LIBSSH2_DEBUG_SFTP + _libssh2_debug(session, LIBSSH2_DBG_SFTP, "Asking for %d packet", (int)packet_type); +#endif if (poll_channel) { if (libssh2_sftp_packet_read(sftp, 0) < 0) { return -1; @@ -261,6 +273,9 @@ static int libssh2_sftp_packet_require(LIBSSH2_SFTP *sftp, unsigned char packet_ { LIBSSH2_SESSION *session = sftp->channel->session; +#ifdef LIBSSH2_DEBUG_SFTP + _libssh2_debug(session, LIBSSH2_DBG_SFTP, "Requiring %d packet", (int)packet_type); +#endif if (libssh2_sftp_packet_ask(sftp, packet_type, request_id, data, data_len, 0) == 0) { /* A packet was available in the packet brigade */ return 0; @@ -422,6 +437,9 @@ LIBSSH2_API LIBSSH2_SFTP *libssh2_sftp_init(LIBSSH2_SESSION *session) unsigned char *data, *s, buffer[9]; /* sftp_header(5){excludes request_id} + version_id(4) */ unsigned long data_len; +#ifdef LIBSSH2_DEBUG_SFTP + _libssh2_debug(session, LIBSSH2_DBG_SFTP, "Initializing SFTP subsystem"); +#endif channel = libssh2_channel_open_session(session); if (!channel) { libssh2_error(session, LIBSSH2_ERROR_CHANNEL_FAILURE, "Unable to startup channel", 0); @@ -451,6 +469,9 @@ LIBSSH2_API LIBSSH2_SFTP *libssh2_sftp_init(LIBSSH2_SESSION *session) buffer[4] = SSH_FXP_INIT; libssh2_htonu32(buffer + 5, LIBSSH2_SFTP_VERSION); +#ifdef LIBSSH2_DEBUG_SFTP + _libssh2_debug(session, LIBSSH2_DBG_SFTP, "Sending FXP_INIT packet advertising version %d support", (int)LIBSSH2_SFTP_VERSION); +#endif if (9 != libssh2_channel_write(channel, buffer, 9)) { libssh2_error(session, LIBSSH2_ERROR_SOCKET_SEND, "Unable to send SSH_FXP_INIT", 0); libssh2_channel_free(channel); @@ -474,8 +495,14 @@ LIBSSH2_API LIBSSH2_SFTP *libssh2_sftp_init(LIBSSH2_SESSION *session) s = data + 1; sftp->version = libssh2_ntohu32(s); s += 4; if (sftp->version > LIBSSH2_SFTP_VERSION) { +#ifdef LIBSSH2_DEBUG_SFTP + _libssh2_debug(session, LIBSSH2_DBG_SFTP, "Truncating remote SFTP version from %lu", sftp->version); +#endif sftp->version = LIBSSH2_SFTP_VERSION; } +#ifdef LIBSSH2_DEBUG_SFTP + _libssh2_debug(session, LIBSSH2_DBG_SFTP, "Enabling SFTP version %lu compatability", sftp->version); +#endif while (s < (data + data_len)) { char *extension_name, *extension_data; unsigned long extname_len, extdata_len; @@ -544,6 +571,9 @@ LIBSSH2_API LIBSSH2_SFTP_HANDLE *libssh2_sftp_open_ex(LIBSSH2_SFTP *sftp, char * s += libssh2_sftp_attr2bin(s, &attrs); } +#ifdef LIBSSH2_DEBUG_SFTP + _libssh2_debug(session, LIBSSH2_DBG_SFTP, "Sending %s open request", (open_type == LIBSSH2_SFTP_OPENFILE) ? "file" : "directory"); +#endif if (packet_len != libssh2_channel_write(channel, packet, packet_len)) { libssh2_error(session, LIBSSH2_ERROR_SOCKET_SEND, "Unable to send FXP_REMOVE command", 0); LIBSSH2_FREE(session, packet); @@ -596,6 +626,9 @@ LIBSSH2_API LIBSSH2_SFTP_HANDLE *libssh2_sftp_open_ex(LIBSSH2_SFTP *sftp, char * fp->u.file.offset = 0; +#ifdef LIBSSH2_DEBUG_SFTP + _libssh2_debug(session, LIBSSH2_DBG_SFTP, "Open command successful"); +#endif return fp; } /* }}} */ @@ -614,6 +647,9 @@ LIBSSH2_API size_t libssh2_sftp_read(LIBSSH2_SFTP_HANDLE *handle, char *buffer, unsigned char read_responses[2] = { SSH_FXP_DATA, SSH_FXP_STATUS }; size_t bytes_read = 0; +#ifdef LIBSSH2_DEBUG_SFTP + _libssh2_debug(session, LIBSSH2_DBG_SFTP, "Reading %lu bytes from SFTP handle", (unsigned long)buffer_maxlen); +#endif s = packet = LIBSSH2_ALLOC(session, packet_len); if (!packet) { libssh2_error(session, LIBSSH2_ERROR_ALLOC, "Unable to allocate memory for FXP_CLOSE packet", 0); @@ -652,6 +688,9 @@ LIBSSH2_API size_t libssh2_sftp_read(LIBSSH2_SFTP_HANDLE *handle, char *buffer, if (bytes_read > (data_len - 9)) { return -1; } +#ifdef LIBSSH2_DEBUG_SFTP + _libssh2_debug(session, LIBSSH2_DBG_SFTP, "%lu bytes returned", (unsigned long)bytes_read); +#endif memcpy(buffer, data + 9, bytes_read); handle->u.file.offset += bytes_read; LIBSSH2_FREE(session, data); @@ -718,6 +757,9 @@ LIBSSH2_API int libssh2_sftp_readdir(LIBSSH2_SFTP_HANDLE *handle, char *buffer, libssh2_htonu32(s, handle->handle_len); s += 4; memcpy(s, handle->handle, handle->handle_len); s += handle->handle_len; +#ifdef LIBSSH2_DEBUG_SFTP + _libssh2_debug(session, LIBSSH2_DBG_SFTP, "Reading entries from directory handle"); +#endif if (packet_len != libssh2_channel_write(channel, packet, packet_len)) { libssh2_error(session, LIBSSH2_ERROR_SOCKET_SEND, "Unable to send FXP_READ command", 0); LIBSSH2_FREE(session, packet); @@ -745,6 +787,9 @@ LIBSSH2_API int libssh2_sftp_readdir(LIBSSH2_SFTP_HANDLE *handle, char *buffer, } num_names = libssh2_ntohu32(data + 5); +#ifdef LIBSSH2_DEBUG_SFTP + _libssh2_debug(session, LIBSSH2_DBG_SFTP, "%lu entries returned", num_names); +#endif if (num_names <= 0) { LIBSSH2_FREE(session, data); return (num_names == 0) ? 0 : -1; @@ -789,6 +834,9 @@ LIBSSH2_API size_t libssh2_sftp_write(LIBSSH2_SFTP_HANDLE *handle, const char *b unsigned long packet_len = handle->handle_len + count + 25; /* packet_len(4) + packet_type(1) + request_id(4) + handle_len(4) + offset(8) + count(4) */ unsigned char *packet, *s, *data; +#ifdef LIBSSH2_DEBUG_SFTP + _libssh2_debug(session, LIBSSH2_DBG_SFTP, "Writing %lu bytes", (unsigned long)count); +#endif s = packet = LIBSSH2_ALLOC(session, packet_len); if (!packet) { libssh2_error(session, LIBSSH2_ERROR_ALLOC, "Unable to allocate memory for FXP_WRITE packet", 0); @@ -845,6 +893,9 @@ LIBSSH2_API int libssh2_sftp_fstat_ex(LIBSSH2_SFTP_HANDLE *handle, LIBSSH2_SFTP_ unsigned char *packet, *s, *data; unsigned char fstat_responses[2] = { SSH_FXP_ATTRS, SSH_FXP_STATUS }; +#ifdef LIBSSH2_DEBUG_SFTP + _libssh2_debug(session, LIBSSH2_DBG_SFTP, "Issuing %s command", setstat ? "set-stat" : "stat"); +#endif s = packet = LIBSSH2_ALLOC(session, packet_len); if (!packet) { libssh2_error(session, LIBSSH2_ERROR_ALLOC, "Unable to allocate memory for FSTAT/FSETSTAT packet", 0); @@ -925,6 +976,9 @@ LIBSSH2_API int libssh2_sftp_close_handle(LIBSSH2_SFTP_HANDLE *handle) unsigned long packet_len = handle->handle_len + 13; /* packet_len(4) + packet_type(1) + request_id(4) + handle_len(4) */ unsigned char *packet, *s, *data; +#ifdef LIBSSH2_DEBUG_SFTP + _libssh2_debug(session, LIBSSH2_DBG_SFTP, "Closing handle"); +#endif s = packet = LIBSSH2_ALLOC(session, packet_len); if (!packet) { libssh2_error(session, LIBSSH2_ERROR_ALLOC, "Unable to allocate memory for FXP_CLOSE packet", 0); @@ -993,6 +1047,9 @@ LIBSSH2_API int libssh2_sftp_unlink_ex(LIBSSH2_SFTP *sftp, char *filename, int f unsigned long packet_len = filename_len + 13; /* packet_len(4) + packet_type(1) + request_id(4) + filename_len(4) */ unsigned char *packet, *s, *data; +#ifdef LIBSSH2_DEBUG_SFTP + _libssh2_debug(session, LIBSSH2_DBG_SFTP, "Unlinking %s", filename); +#endif s = packet = LIBSSH2_ALLOC(session, packet_len); if (!packet) { libssh2_error(session, LIBSSH2_ERROR_ALLOC, "Unable to allocate memory for FXP_REMOVE packet", 0); @@ -1050,6 +1107,9 @@ LIBSSH2_API int libssh2_sftp_rename_ex(LIBSSH2_SFTP *sftp, char *source_filenam return -1; } +#ifdef LIBSSH2_DEBUG_SFTP + _libssh2_debug(session, LIBSSH2_DBG_SFTP, "Renaming %s to %s", source_filename, dest_filename); +#endif s = packet = LIBSSH2_ALLOC(session, packet_len); if (!packet) { libssh2_error(session, LIBSSH2_ERROR_ALLOC, "Unable to allocate memory for FXP_RENAME packet", 0); @@ -1118,6 +1178,9 @@ LIBSSH2_API int libssh2_sftp_mkdir_ex(LIBSSH2_SFTP *sftp, char *path, int path_l /* packet_len(4) + packet_type(1) + request_id(4) + path_len(4) */ unsigned char *packet, *s, *data; +#ifdef LIBSSH2_DEBUG_SFTP + _libssh2_debug(session, LIBSSH2_DBG_SFTP, "Creating directory %s with mode 0%lo", path, mode); +#endif s = packet = LIBSSH2_ALLOC(session, packet_len); if (!packet) { libssh2_error(session, LIBSSH2_ERROR_ALLOC, "Unable to allocate memory for FXP_MKDIR packet", 0); @@ -1170,6 +1233,9 @@ LIBSSH2_API int libssh2_sftp_rmdir_ex(LIBSSH2_SFTP *sftp, char *path, int path_l unsigned long packet_len = path_len + 13; /* packet_len(4) + packet_type(1) + request_id(4) + path_len(4) */ unsigned char *packet, *s, *data; +#ifdef LIBSSH2_DEBUG_SFTP + _libssh2_debug(session, LIBSSH2_DBG_SFTP, "Removing directory: %s", path); +#endif s = packet = LIBSSH2_ALLOC(session, packet_len); if (!packet) { libssh2_error(session, LIBSSH2_ERROR_ALLOC, "Unable to allocate memory for FXP_MKDIR packet", 0); @@ -1221,6 +1287,9 @@ LIBSSH2_API int libssh2_sftp_stat_ex(LIBSSH2_SFTP *sftp, char *path, int path_le unsigned char *packet, *s, *data; unsigned char stat_responses[2] = { SSH_FXP_ATTRS, SSH_FXP_STATUS }; +#ifdef LIBSSH2_DEBUG_SFTP + _libssh2_debug(session, LIBSSH2_DBG_SFTP, "%s %s", (stat_type == LIBSSH2_SFTP_SETSTAT) ? "Set-statting" : (stat_type == LIBSSH2_SFTP_LSTAT ? "LStatting" : "Statting"), path); +#endif s = packet = LIBSSH2_ALLOC(session, packet_len); if (!packet) { libssh2_error(session, LIBSSH2_ERROR_ALLOC, "Unable to allocate memory for FXP_MKDIR packet", 0); @@ -1306,6 +1375,10 @@ LIBSSH2_API int libssh2_sftp_symlink_ex(LIBSSH2_SFTP *sftp, const char *path, in return -1; } +#ifdef LIBSSH2_DEBUG_SFTP + _libssh2_debug(session, LIBSSH2_DBG_SFTP, "%s %s on %s", (link_type == LIBSSH2_SFTP_SYMLINK) ? "Creating" : "Reading", + (link_type == LIBSSH2_SFTP_REALPATH) ? "realpath" : "symlink", path); +#endif libssh2_htonu32(s, packet_len - 4); s += 4; switch (link_type) { case LIBSSH2_SFTP_REALPATH: diff --git a/src/userauth.c b/src/userauth.c index e896737..b9a24ba 100644 --- a/src/userauth.c +++ b/src/userauth.c @@ -96,7 +96,9 @@ LIBSSH2_API char *libssh2_userauth_list(LIBSSH2_SESSION *session, char *username methods_len = libssh2_ntohu32(data + 1); memcpy(data, data + 5, methods_len); data[methods_len] = '\0'; - +#ifdef LIBSSH2_DEBUG_USERAUTH + _libssh2_debug(session, LIBSSH2_DBG_AUTH, "Permitted auth methods: %s", data); +#endif return data; } /* }}} */ @@ -143,6 +145,9 @@ LIBSSH2_API int libssh2_userauth_password_ex(LIBSSH2_SESSION *session, char *use libssh2_htonu32(s, password_len); s += 4; memcpy(s, password, password_len); s += password_len; +#ifdef LIBSSH2_DEBUG_USERAUTH + _libssh2_debug(session, LIBSSH2_DBG_AUTH, "Attempting to login using password authentication"); +#endif if (libssh2_packet_write(session, data, data_len)) { libssh2_error(session, LIBSSH2_ERROR_SOCKET_SEND, "Unable to send userauth-password request", 0); LIBSSH2_FREE(session, data); @@ -156,6 +161,9 @@ LIBSSH2_API int libssh2_userauth_password_ex(LIBSSH2_SESSION *session, char *use } if (data[0] == SSH_MSG_USERAUTH_SUCCESS) { +#ifdef LIBSSH2_DEBUG_USERAUTH + _libssh2_debug(session, LIBSSH2_DBG_AUTH, "Password authentication successful"); +#endif LIBSSH2_FREE(session, data); session->state |= LIBSSH2_STATE_AUTHENTICATED; return 0; @@ -165,6 +173,9 @@ LIBSSH2_API int libssh2_userauth_password_ex(LIBSSH2_SESSION *session, char *use char *newpw = NULL; int newpw_len = 0; +#ifdef LIBSSH2_DEBUG_USERAUTH + _libssh2_debug(session, LIBSSH2_DBG_AUTH, "Password change required"); +#endif LIBSSH2_FREE(session, data); if (passwd_change_cb) { passwd_change_cb(session, &newpw, &newpw_len, &session->abstract); @@ -230,6 +241,9 @@ static int libssh2_file_read_publickey(LIBSSH2_SESSION *session, unsigned char * char *pubkey = NULL, c, *sp1, *sp2, *tmp; int pubkey_len = 0, tmp_len; +#ifdef LIBSSH2_DEBUG_USERAUTH + _libssh2_debug(session, LIBSSH2_DBG_AUTH, "Loading public key file: %s", pubkeyfile); +#endif /* Read Public Key */ fd = fopen(pubkeyfile, "r"); if (!fd) { @@ -305,6 +319,9 @@ static int libssh2_file_read_privatekey(LIBSSH2_SESSION *session, LIBSSH2_HOSTKE { LIBSSH2_HOSTKEY_METHOD **hostkey_methods_avail = libssh2_hostkey_methods(); +#ifdef LIBSSH2_DEBUG_USERAUTH + _libssh2_debug(session, LIBSSH2_DBG_AUTH, "Loading private key file: %s", privkeyfile); +#endif *hostkey_method = NULL; *hostkey_abstract = NULL; while (*hostkey_methods_avail && (*hostkey_methods_avail)->name) { @@ -429,6 +446,9 @@ LIBSSH2_API int libssh2_userauth_hostbased_fromfile_ex(LIBSSH2_SESSION *session, memcpy(s, sig, sig_len); s += sig_len; LIBSSH2_FREE(session, sig); +#ifdef LIBSSH2_DEBUG_USERAUTH + _libssh2_debug(session, LIBSSH2_DBG_AUTH, "Attempting hostbased authentication"); +#endif if (libssh2_packet_write(session, packet, s - packet)) { libssh2_error(session, LIBSSH2_ERROR_SOCKET_SEND, "Unable to send userauth-hostbased request", 0); LIBSSH2_FREE(session, packet); @@ -441,6 +461,9 @@ LIBSSH2_API int libssh2_userauth_hostbased_fromfile_ex(LIBSSH2_SESSION *session, } if (data[0] == SSH_MSG_USERAUTH_SUCCESS) { +#ifdef LIBSSH2_DEBUG_USERAUTH + _libssh2_debug(session, LIBSSH2_DBG_AUTH, "Hostbased authentication successful"); +#endif /* We are us and we've proved it. */ LIBSSH2_FREE(session, data); session->state |= LIBSSH2_STATE_AUTHENTICATED; @@ -500,6 +523,9 @@ LIBSSH2_API int libssh2_userauth_publickey_fromfile_ex(LIBSSH2_SESSION *session, libssh2_htonu32(s, pubkeydata_len); s += 4; memcpy(s, pubkeydata, pubkeydata_len); s += pubkeydata_len; +#ifdef LIBSSH2_DEBUG_USERAUTH + _libssh2_debug(session, LIBSSH2_DBG_AUTH, "Attempting publickey authentication"); +#endif if (libssh2_packet_write(session, packet, packet_len)) { libssh2_error(session, LIBSSH2_ERROR_SOCKET_SEND, "Unable to send userauth-publickey request", 0); LIBSSH2_FREE(session, packet); @@ -516,6 +542,9 @@ LIBSSH2_API int libssh2_userauth_publickey_fromfile_ex(LIBSSH2_SESSION *session, } if (data[0] == SSH_MSG_USERAUTH_SUCCESS) { +#ifdef LIBSSH2_DEBUG_USERAUTH + _libssh2_debug(session, LIBSSH2_DBG_AUTH, "Pubkey authentication prematurely successful"); +#endif /* God help any SSH server that allows an UNVERIFIED public key to validate the user */ LIBSSH2_FREE(session, data); LIBSSH2_FREE(session, packet); @@ -590,6 +619,9 @@ LIBSSH2_API int libssh2_userauth_publickey_fromfile_ex(LIBSSH2_SESSION *session, memcpy(s, sig, sig_len); s += sig_len; LIBSSH2_FREE(session, sig); +#ifdef LIBSSH2_DEBUG_USERAUTH + _libssh2_debug(session, LIBSSH2_DBG_AUTH, "Attempting publickey authentication -- phase 2"); +#endif if (libssh2_packet_write(session, packet, s - packet)) { libssh2_error(session, LIBSSH2_ERROR_SOCKET_SEND, "Unable to send userauth-publickey request", 0); LIBSSH2_FREE(session, packet); @@ -605,6 +637,9 @@ LIBSSH2_API int libssh2_userauth_publickey_fromfile_ex(LIBSSH2_SESSION *session, } if (data[0] == SSH_MSG_USERAUTH_SUCCESS) { +#ifdef LIBSSH2_DEBUG_USERAUTH + _libssh2_debug(session, LIBSSH2_DBG_AUTH, "Publickey authentication successful"); +#endif /* We are us and we've proved it. */ LIBSSH2_FREE(session, data); session->state |= LIBSSH2_STATE_AUTHENTICATED;