HACK source4/torture/basic/delaywrite.c
[metze/samba/wip.git] / source4 / torture / basic / delaywrite.c
index 05183d9e6cc7c5e109559673c5c3cd23f35013f0..dd261d86d09630200148b55b240cd8176c785ffa 100644 (file)
@@ -30,6 +30,7 @@
 #include "libcli/libcli.h"
 #include "torture/util.h"
 #include "torture/basic/proto.h"
+#include "lib/util/time_basic.h"
 
 #define BASEDIR "\\delaywrite"
 
@@ -129,16 +130,16 @@ static bool test_delayed_write_update1(struct torture_context *tctx, struct smbc
        double sec = ((double)used_delay) / ((double)normal_delay);
        int msec = 1000 * sec;
        char buf[2048];
+       bool first;
+       bool updated;
 
        torture_comment(tctx, "\nRunning test_delayed_write_update1\n");
 
        torture_assert(tctx, torture_setup_dir(cli, BASEDIR), "Failed to setup up test directory: " BASEDIR);
 
        fnum1 = smbcli_open(cli->tree, fname, O_RDWR|O_CREAT, DENY_NONE);
-       if (fnum1 == -1) {
-               torture_result(tctx, TORTURE_FAIL, "Failed to open %s", fname);
-               return false;
-       }
+       torture_assert_int_not_equal(tctx, fnum1, -1, talloc_asprintf(tctx,
+                                    "Failed to open %s", fname));
 
        memset(buf, 'x', 2048);
        written =  smbcli_write(cli->tree, fnum1, 0, buf, 0, 2048);
@@ -158,6 +159,9 @@ static bool test_delayed_write_update1(struct torture_context *tctx, struct smbc
 
        torture_assert_ntstatus_ok(tctx, status, "fileinfo failed");
 
+       torture_assert_u64_equal(tctx, finfo1.all_info.out.size, 2048,
+                                "file size not as expected after write(2048)");
+
        torture_comment(tctx, "Initial write time %s\n",
                        nt_time_string(tctx, finfo1.all_info.out.write_time));
 
@@ -167,112 +171,82 @@ static bool test_delayed_write_update1(struct torture_context *tctx, struct smbc
 
        /* Do a zero length SMBwrite call to truncate. */
        written = smbcli_smbwrite(cli->tree, fnum1, "x", 1024, 0);
-
-       if (written != 0) {
-               torture_result(tctx, TORTURE_FAIL, 
-                                          "write failed - wrote %d bytes (%s)\n",
-                                          (int)written, __location__);
-               return false;
-       }
+       torture_assert_int_equal(tctx, written, 0,
+                                "unexpected number of bytes written");
 
        start = timeval_current();
        end = timeval_add(&start, (120 * sec), 0);
+       first = true;
+       updated = false;
        while (!timeval_expired(&end)) {
                status = smb_raw_fileinfo(cli->tree, tctx, &finfo2);
 
-               if (!NT_STATUS_IS_OK(status)) {
-                       DEBUG(0, ("fileinfo failed: %s\n", nt_errstr(status)));
-                       ret = false;
-                       break;
-               }
+               torture_assert_ntstatus_ok(tctx, status, "fileinfo failed");
 
-               if (finfo2.all_info.out.size != 1024) {
-                       torture_result(tctx, TORTURE_FAIL, 
-                                                  "file not truncated, size = %u (should be 1024)",
-                               (unsigned int)finfo2.all_info.out.size);
-                       ret = false;
-                       break;
-               }
+               torture_assert_u64_equal(tctx, finfo2.all_info.out.size, 1024,
+                                        "file not truncated to expected size "
+                                        "(1024)");
 
                torture_comment(tctx, "write time %s\n",
                        nt_time_string(tctx, finfo2.all_info.out.write_time));
-               if (finfo1.all_info.out.write_time != finfo2.all_info.out.write_time) {
-                       double diff = timeval_elapsed(&start);
-                       if (diff > (0.25 * (used_delay / (double)1000000))) {
-                               torture_result(tctx, TORTURE_FAIL, "After SMBwrite truncate "
-                                       "server updated write_time after %.2f seconds"
-                                       "(write time update dealy == %.2f)(wrong!)\n",
-                                              diff, used_delay / (double)1000000);
-                               ret = false;
-                               break;
-                       }
 
-                       torture_comment(tctx, "After SMBwrite truncate "
-                                       "server updated write_time after %.2f seconds"
-                                       "(1 sec == %.2f)(correct)\n",
-                                       diff, used_delay / (double)1000000);
+               if (finfo1.all_info.out.write_time !=
+                   finfo2.all_info.out.write_time)
+               {
+                       updated = true;
                        break;
                }
+
                fflush(stdout);
                smb_msleep(1 * msec);
+               first = false;
        }
 
-       if (finfo1.all_info.out.write_time == finfo2.all_info.out.write_time) {
-               torture_result(tctx, TORTURE_FAIL, 
-                                          "Server did not update write time (wrong!)");
-               ret = false;
-       }
+       torture_assert(tctx, updated,
+                      "Server did not update write time within 120 seconds");
+
+       torture_assert(tctx, first, talloc_asprintf(tctx,
+                      "Server did not update write time immediately but only "
+                      "after %.2f seconds!", timeval_elapsed(&start)));
+
+       torture_comment(tctx, "Server updated write time immediately. Good!\n");
 
        fflush(stdout);
        smb_msleep(2 * msec);
 
        /* Do a non-zero length SMBwrite and make sure it doesn't update the write time. */
        written = smbcli_smbwrite(cli->tree, fnum1, "x", 0, 1);
-
-       if (written != 1) {
-               torture_result(tctx, TORTURE_FAIL, 
-                                          "write failed - wrote %d bytes (%s)",
-                                          (int)written, __location__);
-               return false;
-       }
+       torture_assert_int_equal(tctx, written, 1,
+                                "unexpected number of bytes written");
 
        start = timeval_current();
        end = timeval_add(&start, (10*sec), 0);
        while (!timeval_expired(&end)) {
                status = smb_raw_fileinfo(cli->tree, tctx, &finfo3);
 
-               if (!NT_STATUS_IS_OK(status)) {
-                       DEBUG(0, ("fileinfo failed: %s\n", nt_errstr(status)));
-                       ret = false;
-                       break;
-               }
+               torture_assert_ntstatus_ok(tctx, status, "fileinfo failed");
 
-               if (finfo3.all_info.out.size != 1024) {
-                       DEBUG(0, ("file not truncated, size = %u (should be 1024)\n",
-                               (unsigned int)finfo3.all_info.out.size));
-                       ret = false;
-                       break;
-               }
+               torture_assert_u64_equal(tctx, finfo3.all_info.out.size, 1024,
+                                        "file not truncated to expected size "
+                                        "(1024)");
 
                torture_comment(tctx, "write time %s\n",
                        nt_time_string(tctx, finfo3.all_info.out.write_time));
-               if (finfo2.all_info.out.write_time != finfo3.all_info.out.write_time) {
-                       double diff = timeval_elapsed(&start);
 
-                       torture_comment(tctx, "server updated write_time after %.2f seconds"
-                                       "(wrong)\n",
-                                       diff);
-                       break;
-               }
+               torture_assert_u64_equal(tctx,
+                                        finfo3.all_info.out.write_time,
+                                        finfo2.all_info.out.write_time,
+                                        talloc_asprintf(tctx,
+                                               "Server updated write time "
+                                               "after %.2f seconds (wrong!)",
+                                               timeval_elapsed(&start)));
+
                fflush(stdout);
                smb_msleep(1 * msec);
        }
 
-       if (finfo2.all_info.out.write_time != finfo3.all_info.out.write_time) {
-               torture_result(tctx, TORTURE_FAIL, 
-                                          "Server updated write time (wrong!)");
-               ret = false;
-       }
+       torture_comment(tctx, "Server did not update write time within 10 "
+                       "seconds. Good!\n");
 
        fflush(stdout);
        smb_msleep(2 * msec);
@@ -284,13 +258,17 @@ static bool test_delayed_write_update1(struct torture_context *tctx, struct smbc
        status = smb_raw_pathinfo(cli->tree, tctx, &pinfo4);
        torture_assert_ntstatus_ok(tctx, status, "pathinfo failed");
 
-       if (finfo3.all_info.out.write_time == pinfo4.all_info.out.write_time) {
-               torture_result(tctx, TORTURE_FAIL,
-                                          "Server did not update write time on close (wrong!)");
-               ret = false;
-       } else if (finfo3.all_info.out.write_time < pinfo4.all_info.out.write_time) {
-               torture_comment(tctx, "Server updated write time on close (correct)\n");
-       }
+       torture_assert_u64_not_equal(tctx,
+                                    pinfo4.all_info.out.write_time,
+                                    finfo3.all_info.out.write_time,
+                                    "Server did not update write time on "
+                                    "close (wrong!)");
+       torture_assert(tctx,
+               pinfo4.all_info.out.write_time > finfo3.all_info.out.write_time,
+               "Server updated write time on close, but to an earlier point "
+               "in time");
+
+       torture_comment(tctx, "Server updated write time on close (correct)\n");
 
        if (fnum1 != -1)
                smbcli_close(cli->tree, fnum1);
@@ -318,16 +296,16 @@ static bool test_delayed_write_update1a(struct torture_context *tctx, struct smb
        double sec = ((double)used_delay) / ((double)normal_delay);
        int msec = 1000 * sec;
        char buf[2048];
+       bool first;
+       bool updated;
 
        torture_comment(tctx, "\nRunning test_delayed_write_update1a\n");
 
        torture_assert(tctx, torture_setup_dir(cli, BASEDIR), "Failed to setup up test directory: " BASEDIR);
 
        fnum1 = smbcli_open(cli->tree, fname, O_RDWR|O_CREAT, DENY_NONE);
-       if (fnum1 == -1) {
-               torture_result(tctx, TORTURE_FAIL, "Failed to open %s", fname);
-               return false;
-       }
+       torture_assert_int_not_equal(tctx, fnum1, -1, talloc_asprintf(tctx,
+                                    "Failed to open %s", fname));
 
        memset(buf, 'x', 2048);
        written =  smbcli_write(cli->tree, fnum1, 0, buf, 0, 2048);
@@ -347,66 +325,54 @@ static bool test_delayed_write_update1a(struct torture_context *tctx, struct smb
 
        torture_assert_ntstatus_ok(tctx, status, "fileinfo failed");
 
-       torture_comment(tctx, "Initial write time %s\n", 
-              nt_time_string(tctx, finfo1.all_info.out.write_time));
+       torture_assert_u64_equal(tctx, finfo1.all_info.out.size, 2048,
+                                "file size not as expected after write(2048)");
+
+       torture_comment(tctx, "Initial write time %s\n",
+                       nt_time_string(tctx, finfo1.all_info.out.write_time));
 
        /* Do a zero length SMBwrite call to truncate. */
        written = smbcli_smbwrite(cli->tree, fnum1, "x", 10240, 0);
 
-       if (written != 0) {
-               torture_result(tctx, TORTURE_FAIL, "write failed - wrote %d bytes (%s)",
-                      (int)written, __location__);
-               return false;
-       }
+       torture_assert_int_equal(tctx, written, 0,
+                                "unexpected number of bytes written");
 
        start = timeval_current();
        end = timeval_add(&start, (120*sec), 0);
+       first = true;
+       updated = false;
        while (!timeval_expired(&end)) {
                status = smb_raw_fileinfo(cli->tree, tctx, &finfo2);
 
-               if (!NT_STATUS_IS_OK(status)) {
-                       torture_result(tctx, TORTURE_FAIL, "fileinfo failed: %s", 
-                                                  nt_errstr(status));
-                       ret = false;
-                       break;
-               }
+               torture_assert_ntstatus_ok(tctx, status, "fileinfo failed");
 
-               if (finfo2.all_info.out.size != 10240) {
-                       torture_result(tctx, TORTURE_FAIL, 
-                                                  "file not truncated, size = %u (should be 10240)",
-                               (unsigned int)finfo2.all_info.out.size);
-                       ret = false;
-                       break;
-               }
+               torture_assert_u64_equal(tctx, finfo2.all_info.out.size, 10240,
+                                        "file not truncated to expected size "
+                                        "(10240)");
 
                torture_comment(tctx, "write time %s\n",
-                      nt_time_string(tctx, finfo2.all_info.out.write_time));
-               if (finfo1.all_info.out.write_time != finfo2.all_info.out.write_time) {
-                       double diff = timeval_elapsed(&start);
-                       if (diff > (0.25 * (used_delay / (double)1000000))) {
-                               torture_result(tctx, TORTURE_FAIL, "After SMBwrite truncate "
-                                       "server updated write_time after %.2f seconds"
-                                       "(write time update delay == %.2f)(wrong!)\n",
-                                       diff, used_delay / (double)1000000);
-                               ret = false;
-                               break;
-                       }
+                       nt_time_string(tctx, finfo2.all_info.out.write_time));
 
-                       torture_comment(tctx, "After SMBwrite truncate "
-                                       "server updated write_time after %.2f seconds"
-                                       "(write time update delay == %.2f)(correct)\n",
-                                       diff, used_delay / (double)1000000);
+               if (finfo1.all_info.out.write_time !=
+                   finfo2.all_info.out.write_time)
+               {
+                       updated = true;
                        break;
                }
+
                fflush(stdout);
                smb_msleep(1 * msec);
+               first = false;
        }
 
-       if (finfo1.all_info.out.write_time == finfo2.all_info.out.write_time) {
-               torture_result(tctx, TORTURE_FAIL, 
-                                          "Server did not update write time (wrong!)");
-               ret = false;
-       }
+       torture_assert(tctx, updated,
+                      "Server did not update write time within 120 seconds");
+
+       torture_assert(tctx, first, talloc_asprintf(tctx,
+                      "Server did not update write time immediately but only "
+                      "after %.2f seconds!", timeval_elapsed(&start)));
+
+       torture_comment(tctx, "Server updated write time immediately. Good!\n");
 
        fflush(stdout);
        smb_msleep(2 * msec);
@@ -414,48 +380,37 @@ static bool test_delayed_write_update1a(struct torture_context *tctx, struct smb
        /* Do a non-zero length SMBwrite and make sure it doesn't update the write time. */
        written = smbcli_smbwrite(cli->tree, fnum1, "x", 0, 1);
 
-       torture_assert_int_equal(tctx, written, 1, 
-                                                        "unexpected number of bytes written");
+       torture_assert_int_equal(tctx, written, 1,
+                                "unexpected number of bytes written");
 
        start = timeval_current();
        end = timeval_add(&start, (10*sec), 0);
        while (!timeval_expired(&end)) {
                status = smb_raw_fileinfo(cli->tree, tctx, &finfo3);
 
-               if (!NT_STATUS_IS_OK(status)) {
-                       torture_result(tctx, TORTURE_FAIL, "fileinfo failed: %s\n", 
-                                                  nt_errstr(status));
-                       ret = false;
-                       break;
-               }
+               torture_assert_ntstatus_ok(tctx, status, "fileinfo failed");
 
-               if (finfo3.all_info.out.size != 10240) {
-                       torture_result(tctx, TORTURE_FAIL, 
-                                                  "file not truncated, size = %u (should be 10240)",
-                                                  (unsigned int)finfo3.all_info.out.size);
-                       ret = false;
-                       break;
-               }
+               torture_assert_u64_equal(tctx, finfo3.all_info.out.size, 10240,
+                                        "file not truncated to expected size "
+                                        "(10240)");
 
                torture_comment(tctx, "write time %s\n",
-                      nt_time_string(tctx, finfo3.all_info.out.write_time));
-               if (finfo2.all_info.out.write_time != finfo3.all_info.out.write_time) {
-                       double diff = timeval_elapsed(&start);
+                       nt_time_string(tctx, finfo3.all_info.out.write_time));
+
+               torture_assert_u64_equal(tctx,
+                                        finfo3.all_info.out.write_time,
+                                        finfo2.all_info.out.write_time,
+                                        talloc_asprintf(tctx,
+                                               "Server updated write time "
+                                               "after %.2f seconds (wrong!)",
+                                               timeval_elapsed(&start)));
 
-                       torture_result(tctx, TORTURE_FAIL, "server updated write_time after %.2f seconds"
-                                       "(write time update delay == %.2f)(correct)\n",
-                                       diff, used_delay / (double)1000000);
-                       break;
-               }
                fflush(stdout);
                smb_msleep(1 * msec);
        }
 
-       if (finfo2.all_info.out.write_time != finfo3.all_info.out.write_time) {
-               torture_result(tctx, TORTURE_FAIL, 
-                                          "Server updated write time (wrong!)");
-               ret = false;
-       }
+       torture_comment(tctx, "Server did not update write time within 10 "
+                       "seconds. Good!\n");
 
        /* the close should trigger an write time update */
        smbcli_close(cli->tree, fnum1);
@@ -464,13 +419,17 @@ static bool test_delayed_write_update1a(struct torture_context *tctx, struct smb
        status = smb_raw_pathinfo(cli->tree, tctx, &pinfo4);
        torture_assert_ntstatus_ok(tctx, status, "pathinfo failed");
 
-       if (finfo3.all_info.out.write_time == pinfo4.all_info.out.write_time) {
-               torture_result(tctx, TORTURE_FAIL, 
-                                          "Server did not update write time on close (wrong!)");
-               ret = false;
-       } else if (finfo3.all_info.out.write_time < pinfo4.all_info.out.write_time) {
-               torture_comment(tctx, "Server updated write time on close (correct)\n");
-       }
+       torture_assert_u64_not_equal(tctx,
+                                    pinfo4.all_info.out.write_time,
+                                    finfo3.all_info.out.write_time,
+                                    "Server did not update write time on "
+                                    "close (wrong!)");
+       torture_assert(tctx,
+               pinfo4.all_info.out.write_time > finfo3.all_info.out.write_time,
+               "Server updated write time on close, but to an earlier point "
+               "in time");
+
+       torture_comment(tctx, "Server updated write time on close (correct)\n");
 
        if (fnum1 != -1)
                smbcli_close(cli->tree, fnum1);
@@ -498,16 +457,16 @@ static bool test_delayed_write_update1b(struct torture_context *tctx, struct smb
        double sec = ((double)used_delay) / ((double)normal_delay);
        int msec = 1000 * sec;
        char buf[2048];
+       bool first;
+       bool updated;
 
        torture_comment(tctx, "\nRunning test_delayed_write_update1b\n");
 
        torture_assert(tctx, torture_setup_dir(cli, BASEDIR), "Failed to setup up test directory: " BASEDIR);
 
        fnum1 = smbcli_open(cli->tree, fname, O_RDWR|O_CREAT, DENY_NONE);
-       if (fnum1 == -1) {
-               torture_result(tctx, TORTURE_FAIL, "Failed to open %s", fname);
-               return false;
-       }
+       torture_assert_int_not_equal(tctx, fnum1, -1, talloc_asprintf(tctx,
+                                    "Failed to open %s", fname));
 
        memset(buf, 'x', 2048);
        written =  smbcli_write(cli->tree, fnum1, 0, buf, 0, 2048);
@@ -527,8 +486,11 @@ static bool test_delayed_write_update1b(struct torture_context *tctx, struct smb
 
        torture_assert_ntstatus_ok(tctx, status, "fileinfo failed");
 
+       torture_assert_u64_equal(tctx, finfo1.all_info.out.size, 2048,
+                                "file size not as expected after write(2048)");
+
        torture_comment(tctx, "Initial write time %s\n",
-              nt_time_string(tctx, finfo1.all_info.out.write_time));
+               nt_time_string(tctx, finfo1.all_info.out.write_time));
 
        /* Do a SET_END_OF_FILE_INFO call to truncate. */
        status = smbcli_ftruncate(cli->tree, fnum1, (uint64_t)10240);
@@ -537,52 +499,40 @@ static bool test_delayed_write_update1b(struct torture_context *tctx, struct smb
 
        start = timeval_current();
        end = timeval_add(&start, (120*sec), 0);
+       first = true;
+       updated = false;
        while (!timeval_expired(&end)) {
                status = smb_raw_fileinfo(cli->tree, tctx, &finfo2);
 
-               if (!NT_STATUS_IS_OK(status)) {
-                       DEBUG(0, ("fileinfo failed: %s\n", nt_errstr(status)));
-                       ret = false;
-                       break;
-               }
+               torture_assert_ntstatus_ok(tctx, status, "fileinfo failed");
 
-               if (finfo2.all_info.out.size != 10240) {
-                       torture_result(tctx, TORTURE_FAIL,
-                                                  "file not truncated (size = %u, should be 10240)",
-                                                  (unsigned int)finfo2.all_info.out.size );
-                       ret = false;
-                       break;
-               }
+               torture_assert_u64_equal(tctx, finfo2.all_info.out.size, 10240,
+                                        "file not truncated to expected size "
+                                        "(10240)");
 
                torture_comment(tctx, "write time %s\n",
-                      nt_time_string(tctx, finfo2.all_info.out.write_time));
-               if (finfo1.all_info.out.write_time != finfo2.all_info.out.write_time) {
-                       double diff = timeval_elapsed(&start);
-                       if (diff > (0.25 * (used_delay / (double)1000000))) {
-                               torture_result(tctx, TORTURE_FAIL, 
-                                       "After SET_END_OF_FILE truncate "
-                                       "server updated write_time after %.2f seconds"
-                                       "(write time update delay == %.2f)(wrong!)",
-                                       diff, used_delay / (double)1000000);
-                               ret = false;
-                               break;
-                       }
+                       nt_time_string(tctx, finfo2.all_info.out.write_time));
 
-                       torture_comment(tctx, "After SET_END_OF_FILE truncate "
-                                       "server updated write_time after %.2f seconds"
-                                       "(write time update delay == %.2f)(correct)\n",
-                                       diff, used_delay / (double)1000000);
+               if (finfo1.all_info.out.write_time !=
+                   finfo2.all_info.out.write_time)
+               {
+                       updated = true;
                        break;
                }
+
                fflush(stdout);
                smb_msleep(1 * msec);
+               first = false;
        }
 
-       if (finfo1.all_info.out.write_time == finfo2.all_info.out.write_time) {
-               torture_result(tctx, TORTURE_FAIL,
-                                          "Server did not update write time (wrong!)");
-               ret = false;
-       }
+       torture_assert(tctx, updated,
+                      "Server did not update write time within 120 seconds");
+
+       torture_assert(tctx, first, talloc_asprintf(tctx,
+                      "Server did not update write time immediately but only "
+                      "after %.2f seconds!", timeval_elapsed(&start)));
+
+       torture_comment(tctx, "Server updated write time immediately. Good!\n");
 
        fflush(stdout);
        smb_msleep(2 * msec);
@@ -590,46 +540,37 @@ static bool test_delayed_write_update1b(struct torture_context *tctx, struct smb
        /* Do a non-zero length SMBwrite and make sure it doesn't update the write time. */
        written = smbcli_smbwrite(cli->tree, fnum1, "x", 0, 1);
 
-       torture_assert_int_equal(tctx, written, 1, 
-                                                        "unexpected number of bytes written");
+       torture_assert_int_equal(tctx, written, 1,
+                                "unexpected number of bytes written");
 
        start = timeval_current();
        end = timeval_add(&start, (10*sec), 0);
        while (!timeval_expired(&end)) {
                status = smb_raw_fileinfo(cli->tree, tctx, &finfo3);
 
-               if (!NT_STATUS_IS_OK(status)) {
-                       torture_result(tctx, TORTURE_FAIL,
-                                                  "fileinfo failed: %s", nt_errstr(status));
-                       ret = false;
-                       break;
-               }
+               torture_assert_ntstatus_ok(tctx, status, "fileinfo failed");
 
-               if (finfo3.all_info.out.size != 10240) {
-                       DEBUG(0, ("file not truncated (size = %u, should be 10240)\n",
-                               (unsigned int)finfo3.all_info.out.size ));
-                       ret = false;
-                       break;
-               }
+               torture_assert_u64_equal(tctx, finfo3.all_info.out.size, 10240,
+                                        "file not truncated to expected size "
+                                        "(10240)");
 
                torture_comment(tctx, "write time %s\n",
-                      nt_time_string(tctx, finfo3.all_info.out.write_time));
-               if (finfo2.all_info.out.write_time != finfo3.all_info.out.write_time) {
-                       double diff = timeval_elapsed(&start);
+                       nt_time_string(tctx, finfo3.all_info.out.write_time));
+
+               torture_assert_u64_equal(tctx,
+                                        finfo3.all_info.out.write_time,
+                                        finfo2.all_info.out.write_time,
+                                        talloc_asprintf(tctx,
+                                               "Server updated write time "
+                                               "after %.2f seconds (wrong!)",
+                                               timeval_elapsed(&start)));
 
-                       torture_comment(tctx, "server updated write_time after %.2f seconds"
-                                       "(write time update delay == %.2f)(correct)\n",
-                                       diff, used_delay / (double)1000000);
-                       break;
-               }
                fflush(stdout);
                smb_msleep(1 * msec);
        }
 
-       if (finfo2.all_info.out.write_time != finfo3.all_info.out.write_time) {
-               torture_result(tctx, TORTURE_FAIL, "Server updated write time (wrong!)\n");
-               ret = false;
-       }
+       torture_comment(tctx, "Server did not update write time within 10 "
+                       "seconds. Good!\n");
 
        /* the close should trigger an write time update */
        smbcli_close(cli->tree, fnum1);
@@ -638,12 +579,17 @@ static bool test_delayed_write_update1b(struct torture_context *tctx, struct smb
        status = smb_raw_pathinfo(cli->tree, tctx, &pinfo4);
        torture_assert_ntstatus_ok(tctx, status, "pathinfo failed");
 
-       if (finfo3.all_info.out.write_time == pinfo4.all_info.out.write_time) {
-               torture_result(tctx, TORTURE_FAIL, "Server did not update write time on close (wrong!)\n");
-               ret = false;
-       } else if (finfo3.all_info.out.write_time < pinfo4.all_info.out.write_time) {
-               torture_comment(tctx, "Server updated write time on close (correct)\n");
-       }
+       torture_assert_u64_not_equal(tctx,
+                                    pinfo4.all_info.out.write_time,
+                                    finfo3.all_info.out.write_time,
+                                    "Server did not update write time on "
+                                    "close (wrong!)");
+       torture_assert(tctx,
+               pinfo4.all_info.out.write_time > finfo3.all_info.out.write_time,
+               "Server updated write time on close, but to an earlier point "
+               "in time");
+
+       torture_comment(tctx, "Server updated write time on close (correct)\n");
 
        if (fnum1 != -1)
                smbcli_close(cli->tree, fnum1);
@@ -671,16 +617,16 @@ static bool test_delayed_write_update1c(struct torture_context *tctx, struct smb
        double sec = ((double)used_delay) / ((double)normal_delay);
        int msec = 1000 * sec;
        char buf[2048];
+       bool first;
+       bool updated;
 
        torture_comment(tctx, "\nRunning test_delayed_write_update1c\n");
 
        torture_assert(tctx, torture_setup_dir(cli, BASEDIR), "Failed to setup up test directory: " BASEDIR);
 
        fnum1 = smbcli_open(cli->tree, fname, O_RDWR|O_CREAT, DENY_NONE);
-       if (fnum1 == -1) {
-               torture_result(tctx, TORTURE_FAIL, "Failed to open %s", fname);
-               return false;
-       }
+       torture_assert_int_not_equal(tctx, fnum1, -1, talloc_asprintf(tctx,
+                                    "Failed to open %s", fname));
 
        memset(buf, 'x', 2048);
        written =  smbcli_write(cli->tree, fnum1, 0, buf, 0, 2048);
@@ -700,8 +646,11 @@ static bool test_delayed_write_update1c(struct torture_context *tctx, struct smb
 
        torture_assert_ntstatus_ok(tctx, status, "fileinfo failed");
 
+       torture_assert_u64_equal(tctx, finfo1.all_info.out.size, 2048,
+                                "file size not as expected after write(2048)");
+
        torture_comment(tctx, "Initial write time %s\n",
-              nt_time_string(tctx, finfo1.all_info.out.write_time));
+               nt_time_string(tctx, finfo1.all_info.out.write_time));
 
        /* Do a SET_ALLOCATION_SIZE call to truncate. */
        parms.allocation_info.level = RAW_SFILEINFO_ALLOCATION_INFO;
@@ -710,103 +659,81 @@ static bool test_delayed_write_update1c(struct torture_context *tctx, struct smb
 
        status = smb_raw_setfileinfo(cli->tree, &parms);
 
-       torture_assert_ntstatus_ok(tctx, status, 
-                                                          "RAW_SFILEINFO_ALLOCATION_INFO failed");
+       torture_assert_ntstatus_ok(tctx, status,
+                                  "RAW_SFILEINFO_ALLOCATION_INFO failed");
 
        start = timeval_current();
        end = timeval_add(&start, (120*sec), 0);
+       first = true;
+       updated = false;
        while (!timeval_expired(&end)) {
                status = smb_raw_fileinfo(cli->tree, tctx, &finfo2);
 
-               if (!NT_STATUS_IS_OK(status)) {
-                       torture_result(tctx, TORTURE_FAIL, "fileinfo failed: %s", 
-                                                  nt_errstr(status));
-                       ret = false;
-                       break;
-               }
+               torture_assert_ntstatus_ok(tctx, status, "fileinfo failed");
 
-               if (finfo2.all_info.out.size != 0) {
-                       torture_result(tctx, TORTURE_FAIL, 
-                                                  "file not truncated (size = %u, should be 10240)",
-                               (unsigned int)finfo2.all_info.out.size);
-                       ret = false;
-                       break;
-               }
+               torture_assert_u64_equal(tctx, finfo2.all_info.out.size, 0,
+                                        "file not truncated to expected size "
+                                        "(0)");
 
                torture_comment(tctx, "write time %s\n",
-                      nt_time_string(tctx, finfo2.all_info.out.write_time));
-               if (finfo1.all_info.out.write_time != finfo2.all_info.out.write_time) {
-                       double diff = timeval_elapsed(&start);
-                       if (diff > (0.25 * (used_delay / (double)1000000))) {
-                               torture_result(tctx, TORTURE_FAIL, "After SET_ALLOCATION_INFO truncate "
-                                       "server updated write_time after %.2f seconds"
-                                       "(write time update delay == %.2f)(wrong!)\n",
-                                       diff, used_delay / (double)1000000);
-                               ret = false;
-                               break;
-                       }
+                       nt_time_string(tctx, finfo2.all_info.out.write_time));
 
-                       torture_comment(tctx, "After SET_ALLOCATION_INFO truncate "
-                                       "server updated write_time after %.2f seconds"
-                                       "(write time update delay == %.2f)(correct)\n",
-                                       diff, used_delay / (double)1000000);
+               if (finfo1.all_info.out.write_time !=
+                   finfo2.all_info.out.write_time)
+               {
+                       updated = true;
                        break;
                }
+
                fflush(stdout);
                smb_msleep(1 * msec);
+               first = false;
        }
 
-       if (finfo1.all_info.out.write_time == finfo2.all_info.out.write_time) {
-               torture_result(tctx, TORTURE_FAIL, 
-                                          "Server did not update write time (wrong!)");
-               ret = false;
-       }
+       torture_assert(tctx, updated,
+                      "Server did not update write time within 120 seconds");
+
+       torture_assert(tctx, first, talloc_asprintf(tctx,
+                      "Server did not update write time immediately but only "
+                      "after %.2f seconds!", timeval_elapsed(&start)));
+
+       torture_comment(tctx, "Server updated write time immediately. Good!\n");
 
        fflush(stdout);
        smb_msleep(2 * msec);
 
        /* Do a non-zero length SMBwrite and make sure it doesn't update the write time. */
        written = smbcli_smbwrite(cli->tree, fnum1, "x", 0, 1);
-       torture_assert_int_equal(tctx, written, 1, 
-                                                        "Unexpected number of bytes written");
+       torture_assert_int_equal(tctx, written, 1,
+                                "Unexpected number of bytes written");
 
        start = timeval_current();
        end = timeval_add(&start, (10*sec), 0);
        while (!timeval_expired(&end)) {
                status = smb_raw_fileinfo(cli->tree, tctx, &finfo3);
 
-               if (!NT_STATUS_IS_OK(status)) {
-                       torture_result(tctx, TORTURE_FAIL, "fileinfo failed: %s", 
-                                                  nt_errstr(status));
-                       ret = false;
-                       break;
-               }
+               torture_assert_ntstatus_ok(tctx, status, "fileinfo failed");
 
-               if (finfo3.all_info.out.size != 1) {
-                       torture_result(tctx, TORTURE_FAIL, "file not expanded");
-                       ret = false;
-                       break;
-               }
+               torture_assert_u64_equal(tctx, finfo3.all_info.out.size, 1,
+                                        "file not expaneded");
 
                torture_comment(tctx, "write time %s\n",
-                      nt_time_string(tctx, finfo3.all_info.out.write_time));
-               if (finfo2.all_info.out.write_time != finfo3.all_info.out.write_time) {
-                       double diff = timeval_elapsed(&start);
+                       nt_time_string(tctx, finfo3.all_info.out.write_time));
+
+               torture_assert_u64_equal(tctx,
+                                        finfo3.all_info.out.write_time,
+                                        finfo2.all_info.out.write_time,
+                                        talloc_asprintf(tctx,
+                                               "Server updated write time "
+                                               "after %.2f seconds (wrong!)",
+                                               timeval_elapsed(&start)));
 
-                       torture_comment(tctx, "server updated write_time after %.2f seconds"
-                                       "(write time update delay == %.2f)(wrong)\n",
-                                       diff, used_delay / (double)1000000);
-                       break;
-               }
                fflush(stdout);
                smb_msleep(1 * msec);
        }
 
-       if (finfo2.all_info.out.write_time != finfo3.all_info.out.write_time) {
-               torture_result(tctx, TORTURE_FAIL, 
-                                          "Server updated write time (wrong!)");
-               ret = false;
-       }
+       torture_comment(tctx, "Server did not update write time within 10 "
+                       "seconds. Good!\n");
 
        /* the close should trigger an write time update */
        smbcli_close(cli->tree, fnum1);
@@ -815,12 +742,15 @@ static bool test_delayed_write_update1c(struct torture_context *tctx, struct smb
        status = smb_raw_pathinfo(cli->tree, tctx, &pinfo4);
        torture_assert_ntstatus_ok(tctx, status, "pathinfo failed");
 
-       if (finfo3.all_info.out.write_time == pinfo4.all_info.out.write_time) {
-               torture_result(tctx, TORTURE_FAIL, "Server did not update write time on close (wrong!)\n");
-               ret = false;
-       } else if (finfo3.all_info.out.write_time < pinfo4.all_info.out.write_time) {
-               torture_comment(tctx, "Server updated write time on close (correct)\n");
-       }
+       torture_assert_u64_not_equal(tctx,
+                                    pinfo4.all_info.out.write_time,
+                                    finfo3.all_info.out.write_time,
+                                    "Server did not update write time on "
+                                    "close (wrong!)");
+       torture_assert(tctx,
+               pinfo4.all_info.out.write_time > finfo3.all_info.out.write_time,
+               "Server updated write time on close, but to an earlier point "
+               "in time");
 
        if (fnum1 != -1)
                smbcli_close(cli->tree, fnum1);
@@ -1379,6 +1309,10 @@ static bool test_finfo_after_write(struct torture_context *tctx, struct smbcli_s
 } while (0)
 
 #define GET_INFO_FILE(finfo) do { \
+       struct timeval atv; \
+       struct timeval wtv; \
+       struct timeval_buf atvb; \
+       struct timeval_buf wtvb; \
        NTSTATUS _status; \
        _status = smb_raw_fileinfo(cli->tree, tctx, &finfo); \
        if (!NT_STATUS_IS_OK(_status)) { \
@@ -1387,9 +1321,11 @@ static bool test_finfo_after_write(struct torture_context *tctx, struct smbcli_s
                               nt_errstr(_status)); \
                goto done; \
        } \
+       nttime_to_timeval(&atv, finfo.basic_info.out.access_time); \
+       nttime_to_timeval(&wtv, finfo.basic_info.out.write_time); \
        torture_comment(tctx, "fileinfo: Access(%s) Write(%s)\n", \
-                       nt_time_string(tctx, finfo.basic_info.out.access_time), \
-                       nt_time_string(tctx, finfo.basic_info.out.write_time)); \
+                       timeval_str_buf(&atv, false, true, &atvb), \
+                       timeval_str_buf(&wtv, false, true, &wtvb)); \
 } while (0)
 #define GET_INFO_FILE2(finfo) do { \
        NTSTATUS _status; \
@@ -1477,6 +1413,8 @@ static bool test_delayed_write_update3(struct torture_context *tctx,
        struct timeval start;
        struct timeval end;
        double used_delay = torture_setting_int(tctx, "writetimeupdatedelay", 2000000);
+       //double used_delay = torture_setting_int(tctx, "writetimeupdatedelay", 1000000);
+       //int normal_delay = 1000000;
        int normal_delay = 2000000;
        double sec = ((double)used_delay) / ((double)normal_delay);
        int msec = 1000 * sec;
@@ -1530,7 +1468,7 @@ static bool test_delayed_write_update3(struct torture_context *tctx,
                if (finfo1.basic_info.out.write_time > finfo0.basic_info.out.write_time) {
                        double diff = timeval_elapsed(&start);
                        if (diff < (used_delay / (double)1000000)) {
-                               torture_result(tctx, TORTURE_FAIL, "Server updated write_time after %.2f seconds "
+                               torture_result(tctx, TORTURE_FAIL, "111Server updated write_time after %.2f seconds "
                                                "(write time update delay == %.2f) (wrong!)\n",
                                                diff, used_delay / (double)1000000);
                                ret = false;
@@ -2995,7 +2933,7 @@ static bool test_delayed_write_update7(struct torture_context *tctx, struct smbc
 
        if (finfo2.basic_info.out.write_time != finfo3.basic_info.out.write_time) {
                torture_result(tctx, TORTURE_FAIL, 
-                       "qpathinfo time doens't match fileinfo time");
+                       "qpathinfo time doesn't match fileinfo time");
                ret = false;
        }
 
@@ -3139,9 +3077,9 @@ static bool test_directory_update8(struct torture_context *tctx, struct smbcli_s
 /*
    testing of delayed update of write_time
 */
-struct torture_suite *torture_delay_write(void)
+struct torture_suite *torture_delay_write(TALLOC_CTX *ctx)
 {
-       struct torture_suite *suite = torture_suite_create(talloc_autofree_context(), "delaywrite");
+       struct torture_suite *suite = torture_suite_create(ctx, "delaywrite");
 
        torture_suite_add_2smb_test(suite, "finfo update on close", test_finfo_after_write);
        torture_suite_add_1smb_test(suite, "delayed update of write time", test_delayed_write_update);
@@ -3159,7 +3097,6 @@ struct torture_suite *torture_delay_write(void)
        torture_suite_add_2smb_test(suite, "delayed update of write time 5b", test_delayed_write_update5b);
        torture_suite_add_2smb_test(suite, "delayed update of write time 6", test_delayed_write_update6);
        torture_suite_add_1smb_test(suite, "timestamp resolution test", test_delayed_write_update7);
-       torture_suite_add_1smb_test(suite, "timestamp resolution test", test_delayed_write_update7);
        torture_suite_add_1smb_test(suite, "directory timestamp update test", test_directory_update8);
 
        return suite;