[libsoup] timeout-test: fix on very slow machines

[Dan Winship <danw src gnome org>]

commit c3cc4a9d3d033c9a53ca83fa8b903d7be5dddeb5
Author: Dan Winship <danw gnome org>
Date:   Fri Aug 30 09:12:05 2013 -0400

    timeout-test: fix on very slow machines
    
    On slow old machines, the TLS handshake when making an https request
    can take longer than 1 second, which meant that even the "fast" https
    requests were hitting the 1-second timeout and failing.
    
    Fix this by making the timeouts longer. However, we don't want to do
    that unless absolutely necessary, since the test has to hit this
    timeout multiple times, and the test already takes 10 seconds to run
    with the 1-second timeout. So check how long it takes to make a single
    https request, and only slow down the rest of the tests if it looks
    like it will be needed.
    
    Also fix an unrelated bug, where the "session did/didn't close
    connection" check could fail if the same memory location got used for
    the first and second sockets.
    
    https://bugzilla.gnome.org/show_bug.cgi?id=660581

 tests/timeout-test.c |   53 ++++++++++++++++++++++++++++++++++++-------------
 1 files changed, 39 insertions(+), 14 deletions(-)
---
diff --git a/tests/timeout-test.c b/tests/timeout-test.c
index 27bcbff..405ec3c 100644
--- a/tests/timeout-test.c
+++ b/tests/timeout-test.c
@@ -26,7 +26,8 @@ do_message_to_session (SoupSession *session, const char *uri,
        SoupMessage *msg;
        gboolean finished = FALSE;
 
-       debug_printf (1, "    msg %s\n", comment);
+       if (comment)
+               debug_printf (1, "    msg %s\n", comment);
        msg = soup_message_new ("GET", uri);
 
        g_signal_connect (msg, "finished",
@@ -71,14 +72,14 @@ do_msg_tests_for_session (SoupSession *timeout_session,
                g_signal_connect (idle_session, "request-started",
                                  G_CALLBACK (request_started_cb), &ret);
                do_message_to_session (idle_session, fast_uri, "fast to idle", SOUP_STATUS_OK);
-               idle_first = ret;
+               idle_first = g_object_ref (ret);
        }
 
        if (plain_session) {
                g_signal_connect (plain_session, "request-started",
                                  G_CALLBACK (request_started_cb), &ret);
                do_message_to_session (plain_session, fast_uri, "fast to plain", SOUP_STATUS_OK);
-               plain_first = ret;
+               plain_first = g_object_ref (ret);
        }
 
        do_message_to_session (timeout_session, fast_uri, "fast to timeout", SOUP_STATUS_OK);
@@ -95,6 +96,7 @@ do_msg_tests_for_session (SoupSession *timeout_session,
                        debug_printf (1, "      ERROR: idle_session did not close first connection\n");
                        errors++;
                }
+               g_object_unref (idle_first);
        }
 
        if (plain_session) {
@@ -108,6 +110,7 @@ do_msg_tests_for_session (SoupSession *timeout_session,
                        debug_printf (1, "      ERROR: plain_session closed connection\n");
                        errors++;
                }
+               g_object_unref (plain_first);
        }
 }
 
@@ -148,7 +151,7 @@ do_request_to_session (SoupSession *session, const char *uri,
                soup_test_request_close_stream (req, stream, NULL, &error);
 
                if (error) {
-                       debug_printf (1, "      ERROR closing string: %s",
+                       debug_printf (1, "      ERROR closing stream: %s\n",
                                      error->message);
                        errors++;
                }
@@ -188,14 +191,14 @@ do_req_tests_for_session (SoupSession *timeout_session,
                g_signal_connect (idle_session, "request-started",
                                  G_CALLBACK (request_started_cb), &ret);
                do_request_to_session (idle_session, fast_uri, "fast to idle", FALSE);
-               idle_first = ret;
+               idle_first = g_object_ref (ret);
        }
 
        if (plain_session) {
                g_signal_connect (plain_session, "request-started",
                                  G_CALLBACK (request_started_cb), &ret);
                do_request_to_session (plain_session, fast_uri, "fast to plain", FALSE);
-               plain_first = ret;
+               plain_first = g_object_ref (ret);
        }
 
        do_request_to_session (timeout_session, fast_uri, "fast to timeout", FALSE);
@@ -212,6 +215,7 @@ do_req_tests_for_session (SoupSession *timeout_session,
                        debug_printf (1, "      ERROR: idle_session did not close first connection\n");
                        errors++;
                }
+               g_object_unref (idle_first);
        }
 
        if (plain_session) {
@@ -225,21 +229,22 @@ do_req_tests_for_session (SoupSession *timeout_session,
                        debug_printf (1, "      ERROR: plain_session closed connection\n");
                        errors++;
                }
+               g_object_unref (plain_first);
        }
 }
 
 static void
-do_timeout_tests (char *fast_uri, char *slow_uri)
+do_timeout_tests (char *fast_uri, char *slow_uri, gboolean extra_slow)
 {
        SoupSession *timeout_session, *idle_session, *plain_session;
 
        debug_printf (1, "  async\n");
        timeout_session = soup_test_session_new (SOUP_TYPE_SESSION_ASYNC,
-                                                SOUP_SESSION_TIMEOUT, 1,
+                                                SOUP_SESSION_TIMEOUT, extra_slow ? 3 : 1,
                                                 SOUP_SESSION_USE_THREAD_CONTEXT, TRUE,
                                                 NULL);
        idle_session = soup_test_session_new (SOUP_TYPE_SESSION_ASYNC,
-                                             SOUP_SESSION_IDLE_TIMEOUT, 1,
+                                             SOUP_SESSION_IDLE_TIMEOUT, extra_slow ? 2 : 1,
                                              SOUP_SESSION_USE_THREAD_CONTEXT, TRUE,
                                              NULL);
        /* The "plain" session also has an idle timeout, but it's longer
@@ -247,7 +252,7 @@ do_timeout_tests (char *fast_uri, char *slow_uri)
         * it has no timeout.
         */
        plain_session = soup_test_session_new (SOUP_TYPE_SESSION_ASYNC,
-                                              SOUP_SESSION_IDLE_TIMEOUT, 2,
+                                              SOUP_SESSION_IDLE_TIMEOUT, 20,
                                               SOUP_SESSION_USE_THREAD_CONTEXT, TRUE,
                                               NULL);
 
@@ -261,7 +266,7 @@ do_timeout_tests (char *fast_uri, char *slow_uri)
 
        debug_printf (1, "\n  sync\n");
        timeout_session = soup_test_session_new (SOUP_TYPE_SESSION_SYNC,
-                                                SOUP_SESSION_TIMEOUT, 1,
+                                                SOUP_SESSION_TIMEOUT, extra_slow ? 3 : 1,
                                                 NULL);
        /* SOUP_SESSION_TIMEOUT doesn't work with sync sessions */
        plain_session = soup_test_session_new (SOUP_TYPE_SESSION_SYNC,
@@ -298,7 +303,7 @@ server_handler (SoupServer        *server,
                soup_server_pause_message (server, msg);
                g_object_set_data (G_OBJECT (msg), "server", server);
                soup_add_timeout (soup_server_get_async_context (server),
-                                 1100, timeout_finish_message, msg);
+                                 4000, timeout_finish_message, msg);
        }
 }
 
@@ -317,12 +322,16 @@ main (int argc, char **argv)
                                    soup_server_get_port (server));
        slow_uri = g_strdup_printf ("http://127.0.0.1:%u/slow";,
                                    soup_server_get_port (server));
-       do_timeout_tests (fast_uri, slow_uri);
+       do_timeout_tests (fast_uri, slow_uri, FALSE);
        g_free (fast_uri);
        g_free (slow_uri);
        soup_test_server_quit_unref (server);
 
        if (tls_available) {
+               SoupSession *test_session;
+               gboolean extra_slow;
+               gint64 start, end;
+
                debug_printf (1, "\nhttps\n");
                server = soup_test_server_new_ssl (TRUE);
                soup_server_add_handler (server, NULL, server_handler, NULL, NULL);
@@ -330,7 +339,23 @@ main (int argc, char **argv)
                                            soup_server_get_port (server));
                slow_uri = g_strdup_printf ("https://127.0.0.1:%u/slow";,
                                            soup_server_get_port (server));
-               do_timeout_tests (fast_uri, slow_uri);
+
+               /* The 1-second timeouts are too fast for some machines... */
+               test_session = soup_test_session_new (SOUP_TYPE_SESSION, NULL);
+               start = g_get_monotonic_time ();
+               do_message_to_session (test_session, fast_uri, NULL, SOUP_STATUS_OK);
+               end = g_get_monotonic_time ();
+               soup_test_session_abort_unref (test_session);
+               debug_printf (2, "  (https request took %0.3fs)\n", (end - start) / 1000000.0);
+               if (end - start > 750000) {
+                       debug_printf (1, "  (using extra-slow mode)\n\n");
+                       extra_slow = TRUE;
+               } else {
+                       debug_printf (2, "\n");
+                       extra_slow = FALSE;
+               }
+
+               do_timeout_tests (fast_uri, slow_uri, extra_slow);
                g_free (fast_uri);
                g_free (slow_uri);
                soup_test_server_quit_unref (server);