increase sleep time in cache test and flush test output (#935)

* increase timeout

Account for possible coarse resolution of `bson_get_monotonic_time` on Windows

* add `TEST_PRINTF` and `TEST_STDERR_PRINTF` macros

To flush stderr and stdout to avoid mixed output in logs.

kms-message/test/test_kmip_reader_writer.c

@@ -42,11 +42,11 @@ kms_kmip_writer_test_evaluate (kmip_writer_t *writer,
    actual_hex = data_to_hex (actual_buf, actual_len);
 
    if (0 != strcmp (expected_hex, actual_hex)) {
-      fprintf (stderr,
-               "expected '%s' but got '%s' for test description: %s\n",
-               expected_hex,
-               actual_hex,
-               desc);
+      TEST_STDERR_PRINTF (
+         "expected '%s' but got '%s' for test description: %s\n",
+         expected_hex,
+         actual_hex,
+         desc);
       abort ();
    }
 

kms-message/test/test_kms_assert.h

@@ -23,14 +23,31 @@
 #include <stdio.h>
 #include <string.h>
 
-#define TEST_ERROR(...)                                                        \
-   do {                                                                        \
-      fprintf (                                                                \
-         stderr, "test error %s:%d %s(): ", __FILE__, __LINE__, __FUNCTION__); \
-      fprintf (stderr, __VA_ARGS__);                                           \
-      fprintf (stderr, "\n");                                                  \
-      fflush (stderr);                                                         \
-      abort ();                                                                \
+// TEST_PRINTF ensures stdout and stderr are flushed.
+#define TEST_PRINTF(...)             \
+   if (1) {                          \
+      fflush (stderr);               \
+      fprintf (stdout, __VA_ARGS__); \
+      fflush (stdout);               \
+   } else                            \
+      ((void) 0)
+
+// TEST_STDERR_PRINTF ensures stdout and stderr are flushed.
+#define TEST_STDERR_PRINTF(...)      \
+   if (1) {                          \
+      fflush (stdout);               \
+      fprintf (stderr, __VA_ARGS__); \
+      fflush (stderr);               \
+   } else                            \
+      ((void) 0)
+
+#define TEST_ERROR(...)                                                \
+   do {                                                                \
+      TEST_STDERR_PRINTF (                                             \
+         "test error %s:%d %s(): ", __FILE__, __LINE__, __FUNCTION__); \
+      TEST_STDERR_PRINTF (__VA_ARGS__);                                \
+      TEST_STDERR_PRINTF ("\n");                                       \
+      abort ();                                                        \
    } while (0)
 
 #define ASSERT(stmt)                             \

kms-message/test/test_kms_azure_online.c

@@ -56,8 +56,8 @@ test_getenv (const char *key)
 {
    char *value = getenv (key);
    if (!value) {
-      fprintf (
-         stderr, "Environment variable: %s not set (@@ctest-skip@@)", key);
+      TEST_STDERR_PRINTF ("Environment variable: %s not set (@@ctest-skip@@)\n",
+                          key);
       exit (2);
    }
    TEST_TRACE ("Env: %s = %s", key, value);

kms-message/test/test_kms_gcp_online.c

@@ -56,8 +56,8 @@ test_getenv (const char *key)
 {
    char *value = getenv (key);
    if (!value) {
-      fprintf (
-         stderr, "Environment variable: %s not set (@@ctest-skip@@)", key);
+      TEST_STDERR_PRINTF ("Environment variable: %s not set (@@ctest-skip@@)\n",
+                          key);
       exit (2);
    }
    TEST_TRACE ("Env: %s = %s", key, value);
@@ -185,7 +185,7 @@ test_gcp (void)
                                       opt);
    ASSERT (req);
    if (kms_request_get_error (req)) {
-      printf ("error: %s\n", kms_request_get_error (req));
+      TEST_STDERR_PRINTF ("error: %s\n", kms_request_get_error (req));
       ASSERT (false);
    }
    req_str = kms_request_to_string (req);

kms-message/test/test_kms_request.c

@@ -383,7 +383,7 @@ all_aws_sig_v4_tests (const char *path, const char *selected)
    }
 
    if (skip_aws_test (test_name) && !selected) {
-      printf ("SKIP: %s\n", test_name);
+      TEST_PRINTF ("SKIP: %s\n", test_name);
       goto done;
    }
 
@@ -407,7 +407,7 @@ all_aws_sig_v4_tests (const char *path, const char *selected)
          continue;
       }
 
-      printf ("%s\n", path);
+      TEST_PRINTF ("%s\n", path);
       aws_sig_v4_test (path);
       ran_tests = true;
    }
@@ -903,7 +903,7 @@ parser_testcase_run (parser_testcase_t *testcase)
       size_t ret = fread (buf, 1, (size_t) bytes_to_read, response_file);
 
       if (!kms_response_parser_feed (parser, buf, (int) ret)) {
-         printf ("feed error: %s\n", parser->error);
+         TEST_PRINTF ("feed error: %s\n", parser->error);
          ASSERT (false);
       }
    }
@@ -945,7 +945,7 @@ kms_response_parser_files (void)
    size_t i;
 
    for (i = 0; i < sizeof (tests) / sizeof (tests[0]); i++) {
-      printf (" parser testcase: %d\n", (int) i);
+      TEST_PRINTF (" parser testcase: %d\n", (int) i);
       parser_testcase_run (tests + i);
    }
 }
@@ -1081,8 +1081,8 @@ kms_signature_test (void)
    signature_b64 = kms_message_raw_to_b64 (signature_raw, 256);
 
    if (0 != strcmp (signature_b64, expected_signature)) {
-      printf ("generated signature: %s\n", signature_b64);
-      printf ("but expected signature: %s\n", expected_signature);
+      TEST_PRINTF ("generated signature: %s\n", signature_b64);
+      TEST_PRINTF ("but expected signature: %s\n", expected_signature);
       abort ();
    }
 
@@ -1197,7 +1197,7 @@ test_request_newlines (void)
 #define RUN_TEST(_func)                                          \
    do {                                                          \
       if (!selector || 0 == kms_strcasecmp (#_func, selector)) { \
-         printf ("%s\n", #_func);                                \
+         TEST_PRINTF ("%s\n", #_func);                           \
          _func ();                                               \
          ran_tests = true;                                       \
       }                                                          \
@@ -1232,15 +1232,15 @@ main (int argc, char *argv[])
    help = "Usage: test_kms_request [TEST_NAME]";
 
    if (argc > 2) {
-      fprintf (stderr, "%s\n", help);
+      TEST_STDERR_PRINTF ("%s\n", help);
       abort ();
    } else if (argc == 2) {
       selector = argv[1];
    }
 
    int ret = kms_message_init ();
    if (ret != 0) {
-      printf ("kms_message_init failed: 0x%x\n", ret);
+      TEST_PRINTF ("kms_message_init failed: 0x%x\n", ret);
       abort ();
    }
 
@@ -1292,7 +1292,7 @@ main (int argc, char *argv[])
 
    if (!ran_tests) {
       KMS_ASSERT (argc == 2);
-      fprintf (stderr, "No such test: \"%s\"\n", argv[1]);
+      TEST_STDERR_PRINTF ("No such test: \"%s\"\n", argv[1]);
       abort ();
    }
 

test/test-mc-fle2-payload-iev-v2.c

@@ -379,7 +379,7 @@ static void _mc_fle2_iev_v2_validate(_mongocrypt_tester_t *tester, _mc_fle2_iev_
 }
 
 static void test_fle2_iev_v2_test(_mongocrypt_tester_t *tester, const char *path) {
-    printf("Loading test from %s...\n", path);
+    TEST_PRINTF("Loading test from %s...\n", path);
 
     mongocrypt_binary_t *test_bin = TEST_FILE(path);
     if (!test_bin) {
@@ -405,7 +405,7 @@ static void test_fle2_iev_v2_test(_mongocrypt_tester_t *tester, const char *path
 
 static void test_fle2_iev_v2(_mongocrypt_tester_t *tester) {
     if (!_aes_ctr_is_supported_by_os) {
-        printf("Common Crypto with no CTR support detected. Skipping.");
+        TEST_PRINTF("Common Crypto with no CTR support detected. Skipping.");
         return;
     }
 

test/test-mc-fle2-payload-iev.c

@@ -171,7 +171,7 @@ static void test_FLE2IndexedEqualityEncryptedValue_decrypt(_mongocrypt_tester_t
     mongocrypt_t *crypt;
 
     if (!_aes_ctr_is_supported_by_os) {
-        printf("Common Crypto with no CTR support detected. Skipping.");
+        TEST_PRINTF("Common Crypto with no CTR support detected. Skipping.");
         return;
     }
 

test/test-mc-fle2-payload-iup-v2.c

@@ -107,7 +107,7 @@ static void _test_mc_FLE2InsertUpdatePayloadV2_decrypt(_mongocrypt_tester_t *tes
     mongocrypt_t *crypt;
 
     if (!_aes_ctr_is_supported_by_os) {
-        printf("Common Crypto with no CTR support detected. Skipping.");
+        TEST_PRINTF("Common Crypto with no CTR support detected. Skipping.");
         return;
     }
 

test/test-mc-fle2-payload-iup.c

@@ -100,7 +100,7 @@ static void test_FLE2InsertUpdatePayload_decrypt(_mongocrypt_tester_t *tester) {
     mongocrypt_t *crypt;
 
     if (!_aes_ctr_is_supported_by_os) {
-        printf("Common Crypto with no CTR support detected. Skipping.");
+        TEST_PRINTF("Common Crypto with no CTR support detected. Skipping.");
         return;
     }
 

test/test-mc-fle2-payload-uev.c

@@ -125,7 +125,7 @@ static void test_FLE2UnindexedEncryptedValue_decrypt(_mongocrypt_tester_t *teste
     mongocrypt_t *crypt;
 
     if (!_aes_ctr_is_supported_by_os) {
-        printf("Common Crypto with no CTR support detected. Skipping.");
+        TEST_PRINTF("Common Crypto with no CTR support detected. Skipping.");
         return;
     }
 
@@ -201,7 +201,7 @@ static void test_FLE2UnindexedEncryptedValue_decrypt(_mongocrypt_tester_t *teste
 
 static void test_FLE2UnindexedEncryptedValue_encrypt(_mongocrypt_tester_t *tester) {
     if (!_aes_ctr_is_supported_by_os) {
-        printf("Common Crypto with no CTR support detected. Skipping.");
+        TEST_PRINTF("Common Crypto with no CTR support detected. Skipping.");
         return;
     }
 

test/test-mc-fle2-rfds.c

@@ -92,7 +92,7 @@ static void test_mc_FLE2RangeFindDriverSpec_parse(_mongocrypt_tester_t *tester)
         testcase *test = tests + i;
         mongocrypt_status_t *status = mongocrypt_status_new();
         mc_FLE2RangeFindDriverSpec_t rfds;
-        printf("running subtest: %s\n", test->desc);
+        TEST_PRINTF("running subtest: %s\n", test->desc);
         bool ret = mc_FLE2RangeFindDriverSpec_parse(&rfds, TMP_BSON(test->in), status);
         if (!test->expectError) {
             ASSERT_OK_STATUS(ret, status);
@@ -329,7 +329,7 @@ static void test_mc_FLE2RangeFindDriverSpec_to_placeholders(_mongocrypt_tester_t
 
     for (size_t i = 0; i < sizeof(tests) / sizeof(tests[0]); i++) {
         testcase_t *test = tests + i;
-        printf("running subtest: %s : %s\n", test->desc, test->in);
+        TEST_PRINTF("running subtest: %s : %s\n", test->desc, test->in);
         ASSERT_OK_STATUS(mc_FLE2RangeFindDriverSpec_parse(&spec, TMP_BSON(test->in), status), status);
 
         // Create the expected document.

test/test-mc-range-edge-generation.c

@@ -38,20 +38,19 @@ typedef struct {
 #undef MAX_INT32_EDGES
 
 static void print_edges_compared(mc_edges_t *edgesGot, const char *const *edgesExpected) {
-    fflush(stdout); // Avoid incomplete stdout output from prior tests on error
-    fprintf(stderr, "edges got ... begin\n");
+    TEST_STDERR_PRINTF("edges got ... begin\n");
     for (size_t i = 0; i < mc_edges_len(edgesGot); i++) {
-        fprintf(stderr, "  %s\n", mc_edges_get(edgesGot, i));
+        TEST_STDERR_PRINTF("  %s\n", mc_edges_get(edgesGot, i));
     }
-    fprintf(stderr, "edges got ... end\n");
+    TEST_STDERR_PRINTF("edges got ... end\n");
 
-    fprintf(stderr, "edges expected ... begin\n");
+    TEST_STDERR_PRINTF("edges expected ... begin\n");
     const char *const *iter = edgesExpected;
     while (*iter != NULL) {
-        fprintf(stderr, "  %s\n", *iter);
+        TEST_STDERR_PRINTF("  %s\n", *iter);
         iter++;
     }
-    fprintf(stderr, "edges expected ... end\n");
+    TEST_STDERR_PRINTF("edges expected ... end\n");
 }
 
 static void _test_getEdgesInt32(_mongocrypt_tester_t *tester) {