[libsoup] io-http2: fix message time metrics

[Carlos Garcia Campos <carlosgc src gnome org>]

commit 93f66d4253d2bd42fe60e4ba0f1ec070d943b36d
Author: Carlos Garcia Campos <cgarcia igalia com>
Date:   Tue May 25 16:31:52 2021 +0200

    io-http2: fix message time metrics
    
    We awere not setting response start/end for HTTP/2

 libsoup/http2/soup-client-message-io-http2.c |  19 +++-
 tests/http2-test.c                           | 152 ++++++++++++++++++++++++++-
 2 files changed, 166 insertions(+), 5 deletions(-)
---
diff --git a/libsoup/http2/soup-client-message-io-http2.c b/libsoup/http2/soup-client-message-io-http2.c
index e4e6fca8..924fb556 100644
--- a/libsoup/http2/soup-client-message-io-http2.c
+++ b/libsoup/http2/soup-client-message-io-http2.c
@@ -335,8 +335,10 @@ on_begin_frame_callback (nghttp2_session        *session,
 
         switch (hd->type) {
         case NGHTTP2_HEADERS:
-                if (data->state < STATE_READ_HEADERS)
+                if (data->state < STATE_READ_HEADERS) {
+                        soup_message_set_metrics_timestamp (data->item->msg, 
SOUP_MESSAGE_METRICS_RESPONSE_START);
                         advance_state_from (data, STATE_WRITE_DONE, STATE_READ_HEADERS);
+                }
                 break;
         case NGHTTP2_DATA:
                 if (data->state < STATE_READ_DATA_START) {
@@ -1055,6 +1057,7 @@ client_stream_eof (SoupClientInputStream *stream,
 
         SoupHTTP2MessageData *data = get_data_for_message (io, msg);
         h2_debug (io, data, "Client stream EOF");
+        soup_message_set_metrics_timestamp (msg, SOUP_MESSAGE_METRICS_RESPONSE_END);
         advance_state_from (data, STATE_READ_DATA, STATE_READ_DONE);
         g_signal_handlers_disconnect_by_func (stream, client_stream_eof, msg);
         soup_message_got_body (data->msg);
@@ -1243,7 +1246,17 @@ soup_client_message_io_http2_run_until_read (SoupClientMessageIO  *iface,
 {
         SoupClientMessageIOHTTP2 *io = (SoupClientMessageIOHTTP2 *)iface;
 
-        return io_run_until (io, msg, TRUE, STATE_READ_DATA, cancellable, error);
+        if (io_run_until (io, msg, TRUE, STATE_READ_DATA, cancellable, error))
+                return TRUE;
+
+        soup_message_set_metrics_timestamp (msg, SOUP_MESSAGE_METRICS_RESPONSE_END);
+
+        if (get_io_data (msg) == io)
+                soup_client_message_io_http2_finished (iface, msg);
+        else
+                g_warn_if_reached ();
+
+        return FALSE;
 }
 
 static gboolean
@@ -1322,6 +1335,8 @@ io_run_until_read_async (SoupMessage *msg,
                 return;
         }
 
+        soup_message_set_metrics_timestamp (msg, SOUP_MESSAGE_METRICS_RESPONSE_END);
+
         if (get_io_data (msg) == io)
                 soup_client_message_io_http2_finished ((SoupClientMessageIO *)io, msg);
         else
diff --git a/tests/http2-test.c b/tests/http2-test.c
index dd3214a6..071ef332 100644
--- a/tests/http2-test.c
+++ b/tests/http2-test.c
@@ -521,7 +521,7 @@ do_logging_test (Test *test, gconstpointer data)
 }
 
 static void
-do_metrics_test (Test *test, gconstpointer data)
+do_metrics_size_test (Test *test, gconstpointer data)
 {
         GBytes *bytes = g_bytes_new_static ("Test", sizeof ("Test"));
         test->msg = soup_message_new (SOUP_METHOD_POST, "https://127.0.0.1:5000/echo_post";);
@@ -550,6 +550,148 @@ do_metrics_test (Test *test, gconstpointer data)
         g_object_unref (test->msg);
 }
 
+static void
+metrics_test_network_event_cb (SoupMessage       *msg,
+                               GSocketClientEvent event,
+                               GIOStream         *connection,
+                               guint             *network_event_called)
+{
+        SoupMessageMetrics *metrics = soup_message_get_metrics (msg);
+
+        g_assert_cmpuint (soup_message_metrics_get_fetch_start (metrics), >, 0);
+
+        switch (event) {
+        case G_SOCKET_CLIENT_RESOLVING:
+                g_assert_cmpuint (soup_message_metrics_get_dns_start (metrics), >, 0);
+                break;
+        case G_SOCKET_CLIENT_RESOLVED:
+                g_assert_cmpuint (soup_message_metrics_get_dns_end (metrics), >, 0);
+                g_assert_cmpuint (soup_message_metrics_get_dns_end (metrics), >=, 
soup_message_metrics_get_dns_start (metrics));
+                break;
+        case G_SOCKET_CLIENT_CONNECTING:
+                g_assert_cmpuint (soup_message_metrics_get_connect_start (metrics), >, 0);
+                g_assert_cmpuint (soup_message_metrics_get_connect_start (metrics), >=, 
soup_message_metrics_get_dns_end (metrics));
+                break;
+        case G_SOCKET_CLIENT_TLS_HANDSHAKING:
+                g_assert_cmpuint (soup_message_metrics_get_tls_start (metrics), >, 0);
+                g_assert_cmpuint (soup_message_metrics_get_tls_start (metrics), >=, 
soup_message_metrics_get_connect_start (metrics));
+                break;
+        case G_SOCKET_CLIENT_COMPLETE:
+                g_assert_cmpuint (soup_message_metrics_get_connect_end (metrics), >, 0);
+                g_assert_cmpuint (soup_message_metrics_get_connect_end (metrics), >=, 
soup_message_metrics_get_connect_start (metrics));
+                g_assert_cmpuint (soup_message_metrics_get_connect_end (metrics), >=, 
soup_message_metrics_get_tls_start (metrics));
+                break;
+        default:
+                return;
+        }
+
+        *network_event_called += 1;
+}
+
+static void
+metrics_test_message_starting_cb (SoupMessage *msg,
+                                  gboolean    *starting_called)
+{
+        SoupMessageMetrics *metrics = soup_message_get_metrics (msg);
+
+        g_assert_cmpuint (soup_message_metrics_get_request_start (metrics), >, 0);
+        g_assert_cmpuint (soup_message_metrics_get_request_start (metrics), >=, 
soup_message_metrics_get_fetch_start (metrics));
+
+        *starting_called = TRUE;
+}
+
+static void
+metrics_test_status_changed_cb (SoupMessage *msg,
+                                GParamSpec  *pspec,
+                                gboolean    *status_changed_called)
+{
+        SoupMessageMetrics *metrics = soup_message_get_metrics (msg);
+
+        g_assert_cmpuint (soup_message_metrics_get_response_start (metrics), >, 0);
+        g_assert_cmpuint (soup_message_metrics_get_response_start (metrics), >=, 
soup_message_metrics_get_request_start (metrics));
+
+        *status_changed_called = TRUE;
+}
+
+static void
+metrics_test_got_body_cb (SoupMessage *msg,
+                          gboolean    *got_body_called)
+{
+        SoupMessageMetrics *metrics = soup_message_get_metrics (msg);
+
+        g_assert_cmpuint (soup_message_metrics_get_response_end (metrics), >, 0);
+        g_assert_cmpuint (soup_message_metrics_get_response_end (metrics), >=, 
soup_message_metrics_get_response_start (metrics));
+
+        *got_body_called = TRUE;
+}
+
+static void
+do_one_metrics_time_test (SoupSession *session,
+                          gboolean     is_new_connection)
+{
+        SoupMessage *msg;
+        GBytes *body;
+        SoupMessageMetrics *metrics;
+        gboolean starting_called = FALSE;
+        gboolean status_changed_called = FALSE;
+        gboolean got_body_called = FALSE;
+        guint network_event_called = 0;
+
+        msg = soup_message_new (SOUP_METHOD_GET, "https://127.0.0.1:5000/";);
+        soup_message_add_flags (msg, SOUP_MESSAGE_COLLECT_METRICS);
+        g_signal_connect (msg, "starting",
+                          G_CALLBACK (metrics_test_message_starting_cb),
+                          &starting_called);
+        g_signal_connect (msg, "notify::status-code",
+                          G_CALLBACK (metrics_test_status_changed_cb),
+                          &status_changed_called);
+        g_signal_connect (msg, "got-body",
+                          G_CALLBACK (metrics_test_got_body_cb),
+                          &got_body_called);
+        g_signal_connect (msg, "network-event",
+                          G_CALLBACK (metrics_test_network_event_cb),
+                          &network_event_called);
+        body = soup_session_send_and_read (session, msg, NULL, NULL);
+        soup_test_assert_message_status (msg, SOUP_STATUS_OK);
+        g_bytes_unref (body);
+
+        g_assert_true (starting_called);
+        g_assert_true (status_changed_called);
+        g_assert_true (got_body_called);
+        if (is_new_connection)
+                g_assert_cmpuint (network_event_called, ==, 5);
+        else
+                g_assert_cmpuint (network_event_called, ==, 0);
+
+        metrics = soup_message_get_metrics (msg);
+        g_assert_nonnull (metrics);
+        g_assert_cmpuint (soup_message_metrics_get_fetch_start (metrics), >, 0);
+        if (is_new_connection) {
+                g_assert_cmpuint (soup_message_metrics_get_dns_start (metrics), >, 0);
+                g_assert_cmpuint (soup_message_metrics_get_dns_end (metrics), >, 0);
+                g_assert_cmpuint (soup_message_metrics_get_connect_start (metrics), >, 0);
+                g_assert_cmpuint (soup_message_metrics_get_tls_start (metrics), >, 0);
+                g_assert_cmpuint (soup_message_metrics_get_connect_end (metrics), >, 0);
+        } else {
+                g_assert_cmpuint (soup_message_metrics_get_dns_start (metrics), ==, 0);
+                g_assert_cmpuint (soup_message_metrics_get_dns_end (metrics), ==, 0);
+                g_assert_cmpuint (soup_message_metrics_get_connect_start (metrics), ==, 0);
+                g_assert_cmpuint (soup_message_metrics_get_tls_start (metrics), ==, 0);
+                g_assert_cmpuint (soup_message_metrics_get_connect_end (metrics), ==, 0);
+        }
+        g_assert_cmpuint (soup_message_metrics_get_request_start (metrics), >, 0);
+        g_assert_cmpuint (soup_message_metrics_get_response_start (metrics), >, 0);
+        g_assert_cmpuint (soup_message_metrics_get_response_end (metrics), >, 0);
+        g_object_unref (msg);
+}
+
+static void
+do_metrics_time_test (Test *test, gconstpointer data)
+{
+        do_one_metrics_time_test (test->session, TRUE);
+        do_one_metrics_time_test (test->session, FALSE);
+}
+
 static void
 on_preconnect_ready (SoupSession     *session,
                      GAsyncResult    *result,
@@ -795,9 +937,13 @@ main (int argc, char **argv)
                     setup_session,
                     do_logging_test,
                     teardown_session);
-        g_test_add ("/http2/metrics", Test, NULL,
+        g_test_add ("/http2/metrics/size", Test, NULL,
+                    setup_session,
+                    do_metrics_size_test,
+                    teardown_session);
+        g_test_add ("/http2/metrics/time", Test, NULL,
                     setup_session,
-                    do_metrics_test,
+                    do_metrics_time_test,
                     teardown_session);
         g_test_add ("/http2/preconnect", Test, NULL,
                     setup_session,