s4:torture: Produce more output to help debug smb2.multichannel.bugs.bug_15346

Print the time (as reckoned by tevent) at which each ‘negprot done’ and
‘echo done’ message is produced, and print another message if one of the
requests times out.

BUG: https://bugzilla.samba.org/show_bug.cgi?id=15498

Signed-off-by: Joseph Sutton <josephsutton@catalyst.net.nz>
Reviewed-by: Andreas Schneider <asn@samba.org>
Autobuild-User(master): Andreas Schneider <asn@cryptomilk.org>
Autobuild-Date(master): Tue Oct 24 15:51:40 UTC 2023 on atb-devel-224

diff --git a/source4/torture/smb2/multichannel.c b/source4/torture/smb2/multichannel.c
index cc1b5365164ca7e0f773cd9245cdfda36d60988e..a3616aea52d8c59e02f6951ac8bcaaef3b8f70c6 100644 (file)
--- a/source4/torture/smb2/multichannel.c
+++ b/source4/torture/smb2/multichannel.c
@@ -2378,6 +2378,11 @@ static void test_multichannel_bug_15346_ndone(struct tevent_req *subreq)
                tevent_req_callback_data_void(subreq);
        struct test_multichannel_bug_15346_state *state = conn->state;
        struct torture_context *tctx = state->tctx;
+       struct timeval current_time;
+       struct tm tm_buf;
+       struct tm *current_tm = NULL;
+       char time_str[sizeof "10000-01-01T00:00:00"];
+       size_t time_str_len;
        NTSTATUS status;
        bool ok = false;
 
@@ -2389,7 +2394,20 @@ static void test_multichannel_bug_15346_ndone(struct tevent_req *subreq)
        torture_assert_ntstatus_ok_goto(tctx, status, ok, asserted,
                                        "smbXcli_negprot_recv failed");
 
-       torture_comment(tctx, "conn[%zu]: negprot done\n", conn->idx);
+       current_time = tevent_timeval_current();
+       current_tm = gmtime_r(&current_time.tv_sec, &tm_buf);
+       torture_assert_not_null_goto(tctx, current_tm, ok, asserted,
+                                    "gmtime_r failed");
+
+       time_str_len = strftime(time_str, sizeof time_str, "%FT%T", current_tm);
+       torture_assert_size_not_equal_goto(tctx, time_str_len, 0, ok, asserted,
+                                          "strftime failed");
+
+       torture_comment(tctx,
+                       "%s.%ldZ: conn[%zu]: negprot done\n",
+                       time_str,
+                       (long)current_time.tv_usec,
+                       conn->idx);
 
        conn->ereq = smb2cli_echo_send(conn->smbXcli,
                                       tctx->ev,
@@ -2417,19 +2435,45 @@ static void test_multichannel_bug_15346_edone(struct tevent_req *subreq)
                tevent_req_callback_data_void(subreq);
        struct test_multichannel_bug_15346_state *state = conn->state;
        struct torture_context *tctx = state->tctx;
+       struct timeval current_time;
+       struct tm tm_buf;
+       struct tm *current_tm = NULL;
+       char time_str[sizeof "10000-01-01T00:00:00"];
+       size_t time_str_len;
+       const char *outcome = NULL;
        NTSTATUS status;
        bool ok = false;
 
        SMB_ASSERT(conn->ereq == subreq);
        conn->ereq = NULL;
 
+       current_time = tevent_timeval_current();
+       current_tm = gmtime_r(&current_time.tv_sec, &tm_buf);
+       torture_assert_not_null_goto(tctx, current_tm, ok, asserted,
+                                    "gmtime_r failed");
+
+       time_str_len = strftime(time_str, sizeof time_str, "%FT%T", current_tm);
+       torture_assert_size_not_equal_goto(tctx, time_str_len, 0, ok, asserted,
+                                          "strftime failed");
+
        status = smb2cli_echo_recv(subreq);
        TALLOC_FREE(subreq);
+       if (NT_STATUS_EQUAL(status, NT_STATUS_IO_TIMEOUT)) {
+               outcome = "timed out";
+       } else if (!NT_STATUS_IS_OK(status)) {
+               outcome = "failed";
+       } else {
+               outcome = "done";
+       }
+       torture_comment(tctx,
+                       "%s.%ldZ: conn[%zu]: echo %s\n",
+                       time_str,
+                       (long)current_time.tv_usec,
+                       conn->idx,
+                       outcome);
        torture_assert_ntstatus_ok_goto(tctx, status, ok, asserted,
                                        "smb2cli_echo_recv failed");
 
-       torture_comment(tctx, "conn[%zu]: echo done\n", conn->idx);
-
        state->num_ready += 1;
        if (state->num_ready < state->num_conns) {
                return;