Fwd: Optimization of log levels - libSSH

[Gangadhar Sandrani <gangadhar.sandrani@xxxxxxxxx>]

Hi All,



We have registered callbacks for fetching the debug/trace from libssh in
our server side interface code, and for configuring the log level we use
the API ssh_set_log_level(SSH_LOG_LEVEL).



When the log level is set to 1 and 2 we observe all the warnings and
protocol information would be displayed. But we observe that lot of trace
messages are being logged from libSSH stack even for a simple SSH session
login and immediate exit and also for execution of commands in SSH session.



In order to restrict lot of trace messages from being logged for log levels
1 and 2, I have identified few and unimportant trace messages in the libSSH
code and moved them to higher log level i.e., 3 which usually logs packet
level information.



Please find attached patch "libssh_log_optimization_patch" and please let
me know whether the changes are fine and can be accepted.



Please find comparison between the no of trace messages logged for log
levels 1 and 2 for a simple SSH session login and immediate exit i.e.,
before and after applying the patch which is clearly shown in
"libsshlogging-before_applying_patch" and
"libsshlogging-after_applying_patch".


Regards,

Gangadhar S


When SSH_LOG_LEVEL is set to SSH_LOG_WARNING(1), Below are the debug traces from libSSH stack during simple SSH login and immediate exit of the session.


1970-01-01 00:01:43.021 ssh_analyze_banner: Analyzing banner: SSH-2.0-OpenSSH_5.3
1970-01-01 00:01:43.021 ssh_analyze_banner: We are talking to an OpenSSH client version: 5.3 (50300)
1970-01-01 00:01:45.921 channel_write_common: channel_write wrote 60 bytes
1970-01-01 00:01:46.635 channel_default_bufferize: placing 1 bytes into channel buffer (stderr=0)
1970-01-01 00:01:46.748 channel_default_bufferize: placing 1 bytes into channel buffer (stderr=0)
1970-01-01 00:01:46.749 channel_write_common: channel_write wrote 1 bytes
1970-01-01 00:01:46.971 channel_default_bufferize: placing 1 bytes into channel buffer (stderr=0)
1970-01-01 00:01:46.972 channel_write_common: channel_write wrote 1 bytes
1970-01-01 00:01:47.163 channel_default_bufferize: placing 1 bytes into channel buffer (stderr=0)
1970-01-01 00:01:47.164 channel_write_common: channel_write wrote 1 bytes
1970-01-01 00:01:47.415 channel_write_common: channel_write wrote 1 bytes
1970-01-01 00:01:47.566 channel_default_bufferize: placing 1 bytes into channel buffer (stderr=0)
1970-01-01 00:01:47.567 channel_write_common: channel_write wrote 20 bytes



When SSH_LOG_LEVEL is set to SSH_LOG_PROTOCOL(2), Below are the debug traces from libSSH stack during an SSH login and immediate exit of the session.

1970-01-01 00:01:08.552 ssh_server_connection_callback: SSH client banner: SSH-2.0-OpenSSH_5.3
1970-01-01 00:01:08.553 ssh_analyze_banner: Analyzing banner: SSH-2.0-OpenSSH_5.3
1970-01-01 00:01:08.553 ssh_analyze_banner: We are talking to an OpenSSH client version: 5.3 (50300)
1970-01-01 00:01:08.835 ssh_packet_newkeys: Received SSH_MSG_NEWKEYS
1970-01-01 00:01:09.378 ssh_channel_read_timeout: Read (1) buffered : 0 bytes. Window: 32000
1970-01-01 00:01:09.630 grow_window: growing window (channel 43:0) to 1280000 bytes
1970-01-01 00:01:09.631 channel_write_common: channel_write wrote 60 bytes
1970-01-01 00:01:09.631 ssh_channel_read_timeout: Read (1) buffered : 0 bytes. Window: 1280000
1970-01-01 00:01:09.883 ssh_channel_read_timeout: Read (1) buffered : 0 bytes. Window: 1280000
1970-01-01 00:01:10.079 channel_rcv_data: Channel receiving 1 bytes data in 0 (local win=1280000 remote win=10
1970-01-01 00:01:10.080 channel_default_bufferize: placing 1 bytes into channel buffer (stderr=0)
1970-01-01 00:01:10.080 channel_rcv_data: Channel windows are now (local win=1279999 remote win=1048516)
1970-01-01 00:01:10.080 ssh_channel_read_timeout: Read (1) buffered : 0 bytes. Window: 1279999
1970-01-01 00:01:10.191 channel_rcv_data: Channel receiving 1 bytes data in 0 (local win=1279999 remote win=10
1970-01-01 00:01:10.192 channel_default_bufferize: placing 1 bytes into channel buffer (stderr=0)
1970-01-01 00:01:10.192 channel_rcv_data: Channel windows are now (local win=1279998 remote win=1048516)
1970-01-01 00:01:10.193 channel_write_common: channel_write wrote 1 bytes
1970-01-01 00:01:10.193 ssh_channel_read_timeout: Read (1) buffered : 0 bytes. Window: 1279998
1970-01-01 00:01:10.444 channel_write_common: channel_write wrote 1 bytes
1970-01-01 00:01:10.445 ssh_channel_read_timeout: Read (1) buffered : 0 bytes. Window: 1279998
1970-01-01 00:01:10.543 channel_rcv_data: Channel receiving 1 bytes data in 0 (local win=1279998 remote win=10
1970-01-01 00:01:10.543 channel_default_bufferize: placing 1 bytes into channel buffer (stderr=0)
1970-01-01 00:01:10.544 channel_rcv_data: Channel windows are now (local win=1279997 remote win=1048514)
1970-01-01 00:01:10.544 ssh_channel_read_timeout: Read (1) buffered : 0 bytes. Window: 1279997
1970-01-01 00:01:10.687 channel_rcv_data: Channel receiving 1 bytes data in 0 (local win=1279997 remote win=10
1970-01-01 00:01:10.688 channel_default_bufferize: placing 1 bytes into channel buffer (stderr=0)
1970-01-01 00:01:10.688 channel_rcv_data: Channel windows are now (local win=1279996 remote win=1048514)
1970-01-01 00:01:10.689 channel_write_common: channel_write wrote 1 bytes
1970-01-01 00:01:10.689 ssh_channel_read_timeout: Read (1) buffered : 0 bytes. Window: 1279996
1970-01-01 00:01:10.940 channel_write_common: channel_write wrote 1 bytes
1970-01-01 00:01:10.941 ssh_channel_read_timeout: Read (1) buffered : 0 bytes. Window: 1279996
1970-01-01 00:01:10.944 channel_rcv_data: Channel receiving 1 bytes data in 0 (local win=1279996 remote win=10
1970-01-01 00:01:10.944 channel_default_bufferize: placing 1 bytes into channel buffer (stderr=0)
1970-01-01 00:01:10.944 channel_rcv_data: Channel windows are now (local win=1279995 remote win=1048512)
1970-01-01 00:01:10.945 channel_write_common: channel_write wrote 20 bytes

diff --git a/libssh-libssh-0.6.1/src/channels.c b/libssh-libssh-0.6.1/src/channels.c
index 51e96fe..a222b1c 100644
--- a/libssh-libssh-0.6.1/src/channels.c
+++ b/libssh-libssh-0.6.1/src/channels.c
@@ -507,7 +507,7 @@ SSH_PACKET_CALLBACK(channel_rcv_data){
   }
   len = ssh_string_len(str);

-  SSH_LOG(SSH_LOG_PROTOCOL,
+  SSH_LOG(SSH_LOG_PACKET,
       "Channel receiving %" PRIdS " bytes data in %d (local win=%d remote win=%d)",
       len,
       is_stderr,
@@ -535,7 +535,7 @@ SSH_PACKET_CALLBACK(channel_rcv_data){
     channel->local_window = 0; /* buggy remote */
   }

-  SSH_LOG(SSH_LOG_PROTOCOL,
+  SSH_LOG(SSH_LOG_PACKET,
       "Channel windows are now (local win=%d remote win=%d)",
       channel->local_window,
       channel->remote_window);
@@ -867,7 +867,7 @@ int channel_default_bufferize(ssh_channel channel, void *data, int len,
       return -1;
   }

-  SSH_LOG(SSH_LOG_RARE,
+  SSH_LOG(SSH_LOG_PACKET,
       "placing %d bytes into channel buffer (stderr=%d)", len, is_stderr);
   if (is_stderr == 0) {
     /* stdout */
@@ -1378,7 +1378,7 @@ int channel_write_common(ssh_channel channel, const void *data,
       return SSH_ERROR;
     }

-    SSH_LOG(SSH_LOG_RARE,
+    SSH_LOG(SSH_LOG_PACKET,
         "channel_write wrote %ld bytes", (long int) effectivelen);

     channel->remote_window -= effectivelen;
@@ -2775,7 +2775,7 @@ int ssh_channel_read_timeout(ssh_channel channel,
    * We may have problem if the window is too small to accept as much data
    * as asked
    */
-  SSH_LOG(SSH_LOG_PROTOCOL,
+  SSH_LOG(SSH_LOG_PACKET,
       "Read (%d) buffered : %d bytes. Window: %d",
       count,
       buffer_get_rest_len(stdbuf),
diff --git a/libssh-libssh-0.6.1/src/client.c b/libssh-libssh-0.6.1/src/client.c
index cb41f1c..2355dd5 100644
--- a/libssh-libssh-0.6.1/src/client.c
+++ b/libssh-libssh-0.6.1/src/client.c
@@ -503,7 +503,7 @@ int ssh_connect(ssh_session session) {
       ssh_set_error(session, SSH_FATAL, "Couldn't apply options");
       return SSH_ERROR;
   }
-  SSH_LOG(SSH_LOG_RARE,"libssh %s, using threading %s", ssh_copyright(), ssh_threads_get_type());
+  SSH_LOG(SSH_LOG_PROTOCOL,"libssh %s, using threading %s", ssh_copyright(), ssh_threads_get_type());
   session->ssh_connection_callback = ssh_client_connection_callback;
   session->session_state=SSH_SESSION_STATE_CONNECTING;
   ssh_socket_set_callbacks(session->socket,&session->socket_callbacks);
diff --git a/libssh-libssh-0.6.1/src/config.c b/libssh-libssh-0.6.1/src/config.c
index 3d8dd41..4c966ed 100644
--- a/libssh-libssh-0.6.1/src/config.c
+++ b/libssh-libssh-0.6.1/src/config.c
@@ -383,7 +383,7 @@ int ssh_config_parse_file(ssh_session session, const char *filename) {
     return 0;
   }

-  SSH_LOG(SSH_LOG_RARE, "Reading configuration data from %s", filename);
+  SSH_LOG(SSH_LOG_PACKET, "Reading configuration data from %s", filename);

   parsing = 1;
   while (fgets(line, sizeof(line), f)) {
diff --git a/libssh-libssh-0.6.1/src/packet.c b/libssh-libssh-0.6.1/src/packet.c
index 96f6d10..2923210 100644
--- a/libssh-libssh-0.6.1/src/packet.c
+++ b/libssh-libssh-0.6.1/src/packet.c
@@ -339,7 +339,7 @@ int ssh_packet_socket_callback(const void *data, size_t receivedlen, void *user)

             return processed;
         case PACKET_STATE_PROCESSING:
-            SSH_LOG(SSH_LOG_RARE, "Nested packet processing. Delaying.");
+            SSH_LOG(SSH_LOG_PACKET, "Nested packet processing. Delaying.");
             return 0;
     }

diff --git a/libssh-libssh-0.6.1/src/packet1.c b/libssh-libssh-0.6.1/src/packet1.c
index 127bb77..96691b9 100644
--- a/libssh-libssh-0.6.1/src/packet1.c
+++ b/libssh-libssh-0.6.1/src/packet1.c
@@ -241,7 +241,7 @@ int ssh_packet_socket_callback1(const void *data, size_t receivedlen, void *user

       return processed;
     case PACKET_STATE_PROCESSING:
-      SSH_LOG(SSH_LOG_RARE, "Nested packet processing. Delaying.");
+      SSH_LOG(SSH_LOG_PACKET, "Nested packet processing. Delaying.");
       return 0;
   }


When SSH_LOG_LEVEL is set to SSH_LOG_WARNING(1), Below are the debug traces from libSSH stack during simple SSH login and immediate exit of the session.

1970-01-01 00:27:24.213 ssh_server_connection_callback: SSH client banner: SSH-2.0-OpenSSH_5.3
1970-01-01 00:27:24.213 ssh_analyze_banner: Analyzing banner: SSH-2.0-OpenSSH_5.3
1970-01-01 00:27:24.213 ssh_analyze_banner: We are talking to an OpenSSH client version: 5.3 (50300)


When SSH_LOG_LEVEL is set to SSH_LOG_PROTOCOL(2), Below are the debug traces from libSSH stack during an SSH login and immediate exit of the session.

1970-01-01 00:29:06.554 ssh_server_connection_callback: SSH client banner: SSH-2.0-OpenSSH_5.3
1970-01-01 00:29:06.555 ssh_analyze_banner: Analyzing banner: SSH-2.0-OpenSSH_5.3
1970-01-01 00:29:06.555 ssh_analyze_banner: We are talking to an OpenSSH client version: 5.3 (50300)
1970-01-01 00:29:06.834 ssh_packet_newkeys: Received SSH_MSG_NEWKEYS
1970-01-01 00:29:07.668 grow_window: growing window (channel 43:0) to 1280000 bytes