[glib-networking] Add some log for a start

[Michael Catanzaro <mcatanzaro src gnome org>]

commit 5c20220fd1af698a867f1137e10c593767fbdab7
Author: Frederic Martinsons <frederic martinsons sigfox com>
Date:   Tue Nov 5 17:35:56 2019 +0100

    Add some log for a start
    
    Every claim_op() and yield_op(), including which op
    Every step in handshaking:
       g_tls_connection_base_handshake_async,
       do_implicit_handshake(),
       [async_]handshake_thread(),
       [sync/async]_handshake_thread_completed(),
       finish_handshake(),
       etc...
    When starting and completing read/write and close operations
    
    Signed-off-by: Frederic Martinsons <frederic martinsons sigfox com>

 tls/base/gtlsconnection-base.c | 146 +++++++++++++++++++++++++++++++----------
 1 file changed, 111 insertions(+), 35 deletions(-)
---
diff --git a/tls/base/gtlsconnection-base.c b/tls/base/gtlsconnection-base.c
index 6b6b6f2..2d092e4 100644
--- a/tls/base/gtlsconnection-base.c
+++ b/tls/base/gtlsconnection-base.c
@@ -29,6 +29,7 @@
 
 #include "gtlsconnection-base.h"
 #include "gtlsinputstream.h"
+#include "gtlslog.h"
 #include "gtlsoutputstream.h"
 
 #include <glib/gi18n-lib.h>
@@ -464,6 +465,48 @@ typedef enum {
   G_TLS_CONNECTION_BASE_OP_CLOSE_BOTH,
 } GTlsConnectionBaseOp;
 
+static const gchar *
+op_to_string (GTlsConnectionBaseOp op)
+{
+  switch (op)
+    {
+    case G_TLS_CONNECTION_BASE_OP_HANDSHAKE:
+      return "OP_HANDSHAKE";
+    case G_TLS_CONNECTION_BASE_OP_READ:
+      return "OP_READ";
+    case G_TLS_CONNECTION_BASE_OP_WRITE:
+      return "OP_WRITE";
+    case G_TLS_CONNECTION_BASE_OP_CLOSE_READ:
+      return "OP_CLOSE_READ";
+    case G_TLS_CONNECTION_BASE_OP_CLOSE_WRITE:
+      return "OP_CLOSE_WRITE";
+    case G_TLS_CONNECTION_BASE_OP_CLOSE_BOTH:
+      return "OP_CLOSE_BOTH";
+    }
+  g_assert_not_reached ();
+}
+
+static const gchar *
+status_to_string (GTlsConnectionBaseStatus st)
+{
+  switch (st)
+    {
+    case G_TLS_CONNECTION_BASE_OK:
+      return "BASE_OK";
+    case G_TLS_CONNECTION_BASE_WOULD_BLOCK:
+      return "WOULD_BLOCK";
+    case G_TLS_CONNECTION_BASE_TIMED_OUT:
+      return "TIMED_OUT";
+    case G_TLS_CONNECTION_BASE_REHANDSHAKE:
+      return "REHANDSHAKE";
+    case G_TLS_CONNECTION_BASE_TRY_AGAIN:
+      return "TRY_AGAIN";
+    case G_TLS_CONNECTION_BASE_ERROR:
+      return "ERROR";
+    }
+  g_assert_not_reached ();
+}
+
 static gboolean
 claim_op (GTlsConnectionBase    *tls,
           GTlsConnectionBaseOp   op,
@@ -473,9 +516,14 @@ claim_op (GTlsConnectionBase    *tls,
 {
   GTlsConnectionBasePrivate *priv = g_tls_connection_base_get_instance_private (tls);
 
+  g_tls_log_debug (tls, "claiming operation %s", op_to_string (op));
+
  try_again:
   if (g_cancellable_set_error_if_cancelled (cancellable, error))
-    return FALSE;
+    {
+      g_tls_log_debug (tls, "claim_op failed: cancelled");
+      return FALSE;
+    }
 
   g_mutex_lock (&priv->op_mutex);
 
@@ -489,6 +537,7 @@ claim_op (GTlsConnectionBase    *tls,
       g_set_error_literal (error, G_IO_ERROR, G_IO_ERROR_CLOSED,
                            _("Connection is closed"));
       g_mutex_unlock (&priv->op_mutex);
+      g_tls_log_debug (tls, "claim_op failed: connection is closed");
       return FALSE;
     }
 
@@ -500,6 +549,7 @@ claim_op (GTlsConnectionBase    *tls,
       if (error)
         *error = g_error_copy (priv->handshake_error);
       g_mutex_unlock (&priv->op_mutex);
+      g_tls_log_debug (tls, "claim_op failed: %s", error ? (*error)->message : "no error");
       return FALSE;
     }
 
@@ -514,6 +564,7 @@ claim_op (GTlsConnectionBase    *tls,
           if (!do_implicit_handshake (tls, timeout, cancellable, error))
             {
               g_mutex_unlock (&priv->op_mutex);
+              g_tls_log_debug (tls, "claim_op failed: do_implicit_handshake failed");
               return FALSE;
             }
         }
@@ -539,6 +590,7 @@ claim_op (GTlsConnectionBase    *tls,
             {
               g_propagate_error (error, my_error);
               g_mutex_unlock (&priv->op_mutex);
+              g_tls_log_debug (tls, "claim_op failed: finish_handshake failed or operation has been 
cancelled");
               return FALSE;
             }
 
@@ -559,6 +611,7 @@ claim_op (GTlsConnectionBase    *tls,
        */
       g_set_error_literal (error, G_IO_ERROR, G_IO_ERROR_FAILED, _("Cannot perform blocking operation during 
TLS handshake"));
       g_mutex_unlock (&priv->op_mutex);
+      g_tls_log_debug (tls, "claim_op failed: %s", (*error)->message);
       return FALSE;
     }
 
@@ -580,6 +633,7 @@ claim_op (GTlsConnectionBase    *tls,
           /* Intentionally not translated because this is not a fatal error to be
            * presented to the user, and to avoid this showing up in profiling. */
           g_set_error_literal (error, G_IO_ERROR, G_IO_ERROR_WOULD_BLOCK, "Operation would block");
+          g_tls_log_debug (tls, "claim_op failed: %s", (*error)->message);
           return FALSE;
         }
 
@@ -621,6 +675,7 @@ claim_op (GTlsConnectionBase    *tls,
         {
           g_set_error_literal (error, G_IO_ERROR, G_IO_ERROR_TIMED_OUT,
                                _("Socket I/O timed out"));
+          g_tls_log_debug (tls, "claim_op failed: %s", (*error)->message);
           return FALSE;
         }
 
@@ -642,6 +697,7 @@ claim_op (GTlsConnectionBase    *tls,
     priv->writing = TRUE;
 
   g_mutex_unlock (&priv->op_mutex);
+  g_tls_log_debug (tls, "claiming operation %s succeeded", op_to_string (op));
   return TRUE;
 }
 
@@ -652,6 +708,8 @@ yield_op (GTlsConnectionBase       *tls,
 {
   GTlsConnectionBasePrivate *priv = g_tls_connection_base_get_instance_private (tls);
 
+  g_tls_log_debug (tls, "yielding operation %s", op_to_string (op));
+
   g_mutex_lock (&priv->op_mutex);
 
   if (op == G_TLS_CONNECTION_BASE_OP_HANDSHAKE)
@@ -1206,8 +1264,7 @@ verify_peer_certificate (GTlsConnectionBase *tls,
                                              NULL, &error);
       if (error)
         {
-          g_warning ("failure verifying certificate chain: %s",
-                     error->message);
+          g_tls_log_warning (tls, "failure verifying certificate chain: %s", error->message);
           g_assert (errors != 0);
           g_clear_error (&error);
         }
@@ -1318,6 +1375,8 @@ g_tls_connection_base_handshake_thread_verify_certificate (GTlsConnectionBase *t
   GTlsConnectionBasePrivate *priv = g_tls_connection_base_get_instance_private (tls);
   gboolean accepted;
 
+  g_tls_log_debug (tls, "verifying peer certificate");
+
   g_mutex_lock (&priv->verify_certificate_mutex);
   priv->peer_certificate_examined = FALSE;
   priv->peer_certificate_accepted = FALSE;
@@ -1355,6 +1414,8 @@ handshake_thread (GTask        *task,
   gint64 start_time;
   gint64 timeout;
 
+  g_tls_log_debug (tls, "TLS handshake thread starts");
+
   /* A timeout, in microseconds, must be provided as a gint64* task_data. */
   g_assert (task_data);
   start_time = g_get_monotonic_time ();
@@ -1367,6 +1428,7 @@ handshake_thread (GTask        *task,
                  timeout, cancellable, &error))
     {
       g_task_return_error (task, error);
+      g_tls_log_debug (tls, "TLS handshake thread failed: claiming op failed");
       return;
     }
 
@@ -1381,6 +1443,7 @@ handshake_thread (GTask        *task,
         {
           g_task_return_new_error (task, G_TLS_ERROR, G_TLS_ERROR_MISC,
                                    _("Peer does not support safe renegotiation"));
+          g_tls_log_debug (tls, "TLS handshake thread failed: peer does not support safe renegotiation");
           return;
         }
 
@@ -1396,6 +1459,7 @@ handshake_thread (GTask        *task,
       if (status != G_TLS_CONNECTION_BASE_OK)
         {
           g_task_return_error (task, error);
+          g_tls_log_debug (tls, "TLS handshake thread failed: %s", error ? error->message : "no error");
           return;
         }
     }
@@ -1415,11 +1479,13 @@ handshake_thread (GTask        *task,
   if (error)
     {
       g_task_return_error (task, error);
+      g_tls_log_debug (tls, "TLS handshake thread failed: %s", error->message);
     }
   else
     {
       priv->ever_handshaked = TRUE;
       g_task_return_boolean (task, TRUE);
+      g_tls_log_debug (tls, "TLS handshake thread succeeded");
     }
 }
 
@@ -1432,6 +1498,8 @@ sync_handshake_thread_completed (GObject      *object,
   GTlsConnectionBasePrivate *priv = g_tls_connection_base_get_instance_private (tls);
   gpointer source_tag;
 
+  g_tls_log_debug (tls, "synchronous TLS handshake thread completed");
+
   source_tag = g_task_get_source_tag (G_TASK (result));
   g_assert (source_tag == do_implicit_handshake || source_tag == g_tls_connection_base_handshake);
   g_assert (g_task_is_valid (result, object));
@@ -1476,6 +1544,8 @@ finish_handshake (GTlsConnectionBase  *tls,
   gchar *original_negotiated_protocol;
   GError *my_error = NULL;
 
+  g_tls_log_debug (tls, "finishing TLS handshake");
+
   original_negotiated_protocol = g_steal_pointer (&priv->negotiated_protocol);
 
   if (g_task_propagate_boolean (task, &my_error))
@@ -1515,9 +1585,12 @@ finish_handshake (GTlsConnectionBase  *tls,
   if (my_error && priv->started_handshake)
     priv->handshake_error = g_error_copy (my_error);
 
-  if (!my_error)
+  if (!my_error) {
+    g_tls_log_debug (tls, "TLS handshake has finished successfully");
     return TRUE;
+  }
 
+  g_tls_log_debug (tls, "TLS handshake has finished with error: %s", my_error->message);
   g_propagate_error (error, my_error);
   return FALSE;
 }
@@ -1535,6 +1608,8 @@ g_tls_connection_base_handshake (GTlsConnection   *conn,
   gint64 *timeout = NULL;
   GError *my_error = NULL;
 
+  g_tls_log_debug (tls, "Starting synchronous TLS handshake");
+
   g_assert (!priv->handshake_context);
   priv->handshake_context = g_main_context_new ();
 
@@ -1595,6 +1670,8 @@ async_handshake_thread_completed (GObject      *object,
   GError *error = NULL;
   gboolean need_finish_handshake, success;
 
+  g_tls_log_debug (tls, "Asynchronous TLS handshake thread completed");
+
   g_assert (g_task_is_valid (result, object));
   g_assert (g_task_get_source_tag (G_TASK (result)) == g_tls_connection_base_handshake_async);
 
@@ -1634,6 +1711,8 @@ async_handshake_thread (GTask        *task,
   GTlsConnectionBase *tls = object;
   GTlsConnectionBasePrivate *priv = g_tls_connection_base_get_instance_private (tls);
 
+  g_tls_log_debug (tls, "Asynchronous TLS handshake thread starts");
+
   handshake_thread (task, object, task_data, cancellable);
 
   g_mutex_lock (&priv->op_mutex);
@@ -1662,6 +1741,8 @@ g_tls_connection_base_handshake_async (GTlsConnection      *conn,
   GTask *thread_task, *caller_task;
   gint64 *timeout = NULL;
 
+  g_tls_log_debug (tls, "Starting asynchronous TLS handshake");
+
   g_assert (!priv->handshake_context);
   priv->handshake_context = g_main_context_ref_thread_default ();
 
@@ -1727,6 +1808,8 @@ do_implicit_handshake (GTlsConnectionBase  *tls,
   GTlsConnectionBaseClass *tls_class = G_TLS_CONNECTION_BASE_GET_CLASS (tls);
   gint64 *thread_timeout = NULL;
 
+  g_tls_log_debug (tls, "Implcit TLS handshaking starts");
+
   /* We have op_mutex */
 
   g_assert (!priv->handshake_context);
@@ -1820,6 +1903,8 @@ g_tls_connection_base_read (GTlsConnectionBase  *tls,
   GTlsConnectionBaseStatus status;
   gssize nread;
 
+  g_tls_log_debug (tls, "starting to read data from TLS connection");
+
   do
     {
       if (!claim_op (tls, G_TLS_CONNECTION_BASE_OP_READ,
@@ -1849,9 +1934,11 @@ g_tls_connection_base_read (GTlsConnectionBase  *tls,
   if (status == G_TLS_CONNECTION_BASE_OK)
     {
       priv->successful_posthandshake_op = TRUE;
+      g_tls_log_debug (tls, "successfully read %" G_GSSIZE_FORMAT " bytes from TLS connection", nread);
       return nread;
     }
 
+  g_tls_log_debug (tls, "reading data from TLS connection has failed: %s", status_to_string (status));
   return -1;
 }
 
@@ -1867,6 +1954,8 @@ g_tls_connection_base_read_message (GTlsConnectionBase  *tls,
   GTlsConnectionBaseStatus status;
   gssize nread;
 
+  g_tls_log_debug (tls, "starting to read messages from TLS connection");
+
   do {
     if (!claim_op (tls, G_TLS_CONNECTION_BASE_OP_READ,
                    timeout, cancellable, error))
@@ -1906,9 +1995,11 @@ g_tls_connection_base_read_message (GTlsConnectionBase  *tls,
   if (status == G_TLS_CONNECTION_BASE_OK)
     {
       priv->successful_posthandshake_op = TRUE;
+      g_tls_log_debug (tls, "successfully read %" G_GSSIZE_FORMAT " bytes from TLS connection", nread);
       return nread;
     }
 
+  g_tls_log_debug (tls, "reading message from TLS connection has failed: %s", status_to_string (status));
   return -1;
 }
 
@@ -2001,6 +2092,8 @@ g_tls_connection_base_write (GTlsConnectionBase  *tls,
   GTlsConnectionBaseStatus status;
   gssize nwrote;
 
+  g_tls_log_debug (tls, "starting to write %" G_GSIZE_FORMAT " bytes to TLS connection", count);
+
   do
     {
       if (!claim_op (tls, G_TLS_CONNECTION_BASE_OP_WRITE,
@@ -2017,9 +2110,11 @@ g_tls_connection_base_write (GTlsConnectionBase  *tls,
   if (status == G_TLS_CONNECTION_BASE_OK)
     {
       priv->successful_posthandshake_op = TRUE;
+      g_tls_log_debug (tls, "successfully write %" G_GSSIZE_FORMAT " bytes to TLS connection", nwrote);
       return nwrote;
     }
 
+  g_tls_log_debug (tls, "writting data to TLS connection has failed: %s", status_to_string (status));
   return -1;
 }
 
@@ -2035,6 +2130,8 @@ g_tls_connection_base_write_message (GTlsConnectionBase  *tls,
   GTlsConnectionBaseStatus status;
   gssize nwrote;
 
+  g_tls_log_debug (tls, "starting to write messages to TLS connection");
+
   do {
     if (!claim_op (tls, G_TLS_CONNECTION_BASE_OP_WRITE,
                    timeout, cancellable, error))
@@ -2050,9 +2147,11 @@ g_tls_connection_base_write_message (GTlsConnectionBase  *tls,
   if (status == G_TLS_CONNECTION_BASE_OK)
     {
       priv->successful_posthandshake_op = TRUE;
+      g_tls_log_debug (tls, "successfully write %" G_GSSIZE_FORMAT " bytes to TLS connection", nwrote);
       return nwrote;
     }
 
+  g_tls_log_debug (tls, "writting messages to TLS connection has failed: %s", status_to_string (status));
   return -1;
 }
 
@@ -2153,6 +2252,8 @@ g_tls_connection_base_close_internal (GIOStream      *stream,
   gboolean success = TRUE;
   GError *close_error = NULL, *stream_error = NULL;
 
+  g_tls_log_debug (tls, "starting to close the TLS connection");
+
   /* This can be called from g_io_stream_close(), g_input_stream_close(),
    * g_output_stream_close(), or g_tls_connection_close(). In all cases, we only
    * do the close_fn() for writing. The difference is how we set the flags on
@@ -2217,14 +2318,20 @@ g_tls_connection_base_close_internal (GIOStream      *stream,
   /* Propagate errors. */
   if (status != G_TLS_CONNECTION_BASE_OK)
     {
+      g_tls_log_debug (tls, "error closing TLS connection: %s", close_error->message);
       g_propagate_error (error, close_error);
       g_clear_error (&stream_error);
     }
   else if (!success)
     {
+      g_tls_log_debug (tls, "error closing TLS connection: %s", stream_error->message);
       g_propagate_error (error, stream_error);
       g_clear_error (&close_error);
     }
+  else
+    {
+      g_tls_log_debug (tls, "the TLS connection has been closed successfully");
+    }
 
   return success && status == G_TLS_CONNECTION_BASE_OK;
 }
@@ -2584,34 +2691,3 @@ g_tls_connection_base_datagram_based_iface_init (GDatagramBasedInterface *iface)
   iface->condition_check = g_tls_connection_base_condition_check;
   iface->condition_wait = g_tls_connection_base_condition_wait;
 }
-
-void
-GTLS_DEBUG (gpointer    connection,
-            const char *message,
-            ...)
-{
-  char *result = NULL;
-  va_list args;
-  int ret;
-
-  g_assert (G_IS_TLS_CONNECTION (connection));
-
-  va_start (args, message);
-
-  ret = g_vasprintf (&result, message, args);
-  g_assert (ret > 0);
-
-  if (G_IS_TLS_CLIENT_CONNECTION (connection))
-    g_printf ("CLIENT %p: ", connection);
-  else if (G_IS_TLS_SERVER_CONNECTION (connection))
-    g_printf ("SERVER %p: ", connection);
-  else
-    g_assert_not_reached ();
-
-  g_printf ("%s\n", result);
-
-  fflush (stdout);
-
-  g_free (result);
-  va_end (args);
-}