From c2df97f57ce205935c37cd5a90cfeddb129cd92b Mon Sep 17 00:00:00 2001 From: Jeremy Allison Date: Thu, 5 Nov 2009 15:37:26 -0800 Subject: [PATCH] Fix up some of the timing constants for DELAYWRITE. Add some extra tests up test_delayed_write_update6 to investigate what happens to a sticky write handle after a second handle close. Jeremy. --- source4/torture/basic/delaywrite.c | 144 +++++++++++++++++++++++------ 1 file changed, 114 insertions(+), 30 deletions(-) diff --git a/source4/torture/basic/delaywrite.c b/source4/torture/basic/delaywrite.c index 71d8cc901fc..0c43c29cade 100644 --- a/source4/torture/basic/delaywrite.c +++ b/source4/torture/basic/delaywrite.c @@ -74,10 +74,6 @@ static bool test_delayed_write_update(struct torture_context *tctx, struct smbcl torture_comment(tctx, "Initial write time %s\n", nt_time_string(tctx, finfo1.basic_info.out.write_time)); - /* 3 second delay to ensure we get past any 2 second time - granularity (older systems may have that) */ - msleep(3 * msec); - written = smbcli_write(cli->tree, fnum1, 0, "x", 0, 1); if (written != 1) { @@ -101,7 +97,7 @@ static bool test_delayed_write_update(struct torture_context *tctx, struct smbcl nt_time_string(tctx, finfo2.basic_info.out.write_time)); if (finfo1.basic_info.out.write_time != finfo2.basic_info.out.write_time) { double diff = timeval_elapsed(&start); - if (diff < (TIMEDELAY_SECS * sec * 0.75)) { /* 0.75 to cope with vmware timing */ + if (diff < (TIMEDELAY_SECS * sec * 0.3)) { /* 0.3 to cope with vmware timing */ torture_comment(tctx, "Server updated write_time after %.2f seconds" "(1 sec == %.2f)(wrong!)\n", diff, sec); @@ -182,6 +178,10 @@ static bool test_delayed_write_update1(struct torture_context *tctx, struct smbc torture_comment(tctx, "Initial write time %s\n", nt_time_string(tctx, finfo1.all_info.out.write_time)); + /* 3 second delay to ensure we get past any 2 second time + granularity (older systems may have that) */ + msleep(3 * msec); + /* Do a zero length SMBwrite call to truncate. */ written = smbcli_smbwrite(cli->tree, fnum1, "x", 1024, 0); @@ -277,7 +277,7 @@ static bool test_delayed_write_update1(struct torture_context *tctx, struct smbc double diff = timeval_elapsed(&start); torture_comment(tctx, "server updated write_time after %.2f seconds" - "(1 sec == %.2f)(correct)\n", + "(1 sec == %.2f)(wrong)\n", diff, sec); break; } @@ -291,6 +291,9 @@ static bool test_delayed_write_update1(struct torture_context *tctx, struct smbc ret = false; } + fflush(stdout); + msleep(2 * msec); + /* the close should trigger an write time update */ smbcli_close(cli->tree, fnum1); fnum1 = -1; @@ -1170,7 +1173,7 @@ static bool test_delayed_write_update2(struct torture_context *tctx, struct smbc nt_time_string(tctx, finfo2.basic_info.out.write_time)); if (finfo1.basic_info.out.write_time != finfo2.basic_info.out.write_time) { double diff = timeval_elapsed(&start); - if (diff < (TIMEDELAY_SECS * sec * 0.75)) { /* 0.75 to cope with vmware timing */ + if (diff < (TIMEDELAY_SECS * sec * 0.3)) { /* 0.3 to cope with vmware timing */ torture_comment(tctx, "Server updated write_time after %.2f seconds" "(1sec == %.2f) (wrong!)\n", diff, sec); @@ -1415,6 +1418,19 @@ static bool test_finfo_after_write(struct torture_context *tctx, struct smbcli_s nt_time_string(tctx, finfo.basic_info.out.access_time), \ nt_time_string(tctx, finfo.basic_info.out.write_time)); \ } while (0) +#define GET_INFO_FILE2(finfo) do { \ + NTSTATUS _status; \ + _status = smb_raw_fileinfo(cli2->tree, tctx, &finfo); \ + if (!NT_STATUS_IS_OK(_status)) { \ + ret = false; \ + torture_result(tctx, TORTURE_FAIL, __location__": fileinfo failed: %s", \ + nt_errstr(_status)); \ + goto done; \ + } \ + 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)); \ +} while (0) #define GET_INFO_PATH(pinfo) do { \ NTSTATUS _status; \ _status = smb_raw_pathinfo(cli2->tree, tctx, &pinfo); \ @@ -1544,7 +1560,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 < (TIMEDELAY_SECS * sec * 0.75)) { /* 0.75 to cope with vmware timing */ + if (diff < (TIMEDELAY_SECS * sec * 0.3)) { /* 0.3 to cope with vmware timing */ torture_comment(tctx, "Server updated write_time after %.2f seconds " "(1sec == %.2f) (wrong!)\n", diff, sec); @@ -1710,7 +1726,7 @@ static bool test_delayed_write_update3a(struct torture_context *tctx, if (finfo1.basic_info.out.write_time > finfo0.basic_info.out.write_time) { double diff = timeval_elapsed(&start); - if (diff < (TIMEDELAY_SECS * sec * 0.75)) { /* 0.75 to cope with vmware timing */ + if (diff < (TIMEDELAY_SECS * sec * 0.3)) { /* 0.3 to cope with vmware timing */ torture_comment(tctx, "Server updated write_time after %.2f seconds " "(1sec == %.2f) (wrong!)\n", diff, sec); @@ -1729,12 +1745,14 @@ static bool test_delayed_write_update3a(struct torture_context *tctx, GET_INFO_BOTH(finfo1,pinfo1); COMPARE_WRITE_TIME_GREATER(pinfo1, pinfo0); + msleep(3 * msec); + /* * demonstrate that a truncate write always * updates the write time immediately */ for (i=0; i < 3; i++) { - msleep(1 * msec); + msleep(2 * msec); /* do a write */ torture_comment(tctx, "Do a truncate SMBwrite [%d] on the file handle\n", i); written = smbcli_smbwrite(cli->tree, fnum1, "x", 10240, 0); @@ -1749,6 +1767,8 @@ static bool test_delayed_write_update3a(struct torture_context *tctx, finfo1 = finfo2; } + msleep(3 * msec); + /* sure any further write doesn't update the write time */ start = timeval_current(); end = timeval_add(&start, 15 * sec, 0); @@ -1772,7 +1792,7 @@ static bool test_delayed_write_update3a(struct torture_context *tctx, ret = false; break; } - msleep(2 * msec); + msleep(1 * msec); } GET_INFO_BOTH(finfo2,pinfo2); @@ -1782,7 +1802,7 @@ static bool test_delayed_write_update3a(struct torture_context *tctx, } /* sleep */ - msleep(5 * msec); + msleep(3 * msec); /* get the initial times */ GET_INFO_BOTH(finfo1,pinfo1); @@ -1793,7 +1813,7 @@ static bool test_delayed_write_update3a(struct torture_context *tctx, * updates the write time immediately */ for (i=0; i < 3; i++) { - msleep(1 * msec); + msleep(2 * msec); /* do a write */ torture_comment(tctx, "Do a truncate SMBwrite [%d] on the file handle\n", i); written = smbcli_smbwrite(cli->tree, fnum1, "x", 512, 0); @@ -1809,7 +1829,7 @@ static bool test_delayed_write_update3a(struct torture_context *tctx, } /* sleep */ - msleep(5 * msec); + msleep(3 * msec); GET_INFO_BOTH(finfo3,pinfo3); COMPARE_WRITE_TIME_EQUAL(finfo3, finfo2); @@ -1921,7 +1941,7 @@ static bool test_delayed_write_update3b(struct torture_context *tctx, if (finfo1.basic_info.out.write_time > finfo0.basic_info.out.write_time) { double diff = timeval_elapsed(&start); - if (diff < (TIMEDELAY_SECS * sec * 0.75)) { /* 0.75 to cope with vmware timing */ + if (diff < (TIMEDELAY_SECS * sec * 0.3)) { /* 0.3 to cope with vmware timing */ torture_comment(tctx, "Server updated write_time after %.2f seconds " "(1sec == %.2f) (wrong!)\n", diff, sec); @@ -1963,7 +1983,7 @@ static bool test_delayed_write_update3b(struct torture_context *tctx, ret = false; break; } - msleep(2 * msec); + msleep(1 * msec); } GET_INFO_BOTH(finfo2,pinfo2); @@ -2073,7 +2093,7 @@ static bool test_delayed_write_update3c(struct torture_context *tctx, * updates the write time immediately */ for (i=0; i < 3; i++) { - msleep(1 * msec); + msleep(2 * msec); /* do a write */ torture_comment(tctx, "Do a truncate SMBwrite [%d] on the file handle\n", i); written = smbcli_smbwrite(cli->tree, fnum1, "x", 512, 0); @@ -2110,7 +2130,7 @@ static bool test_delayed_write_update3c(struct torture_context *tctx, ret = false; break; } - msleep(2 * msec); + msleep(1 * msec); } GET_INFO_BOTH(finfo2,pinfo2); @@ -2131,7 +2151,7 @@ static bool test_delayed_write_update3c(struct torture_context *tctx, * updates the write time immediately */ for (i=0; i < 3; i++) { - msleep(1 * msec); + msleep(2 * msec); /* do a write */ torture_comment(tctx, "Do a truncate write [%d] on the file handle\n", i); written = smbcli_smbwrite(cli->tree, fnum1, "x", 512, 0); @@ -2175,7 +2195,7 @@ static bool test_delayed_write_update3c(struct torture_context *tctx, ret = false; break; } - msleep(2 * msec); + msleep(1 * msec); } GET_INFO_BOTH(finfo2,pinfo2); @@ -2296,7 +2316,7 @@ static bool test_delayed_write_update4(struct torture_context *tctx, if (finfo1.basic_info.out.write_time > finfo0.basic_info.out.write_time) { double diff = timeval_elapsed(&start); - if (diff < (TIMEDELAY_SECS * sec * 0.75)) { /* 0.75 to cope with vmware timing */ + if (diff < (TIMEDELAY_SECS * sec * 0.3)) { /* 0.3 to cope with vmware timing */ torture_comment(tctx, "Server updated write_time after %.2f seconds " "(1sec == %.2f) (wrong!)\n", diff, sec); @@ -2338,7 +2358,7 @@ static bool test_delayed_write_update4(struct torture_context *tctx, ret = false; break; } - msleep(2 * msec); + msleep(1 * msec); } GET_INFO_BOTH(finfo2,pinfo2); @@ -2469,7 +2489,7 @@ static bool test_delayed_write_update5(struct torture_context *tctx, ret = false; break; } - msleep(2 * msec); + msleep(1 * msec); } GET_INFO_BOTH(finfo3,pinfo3); @@ -2501,7 +2521,7 @@ static bool test_delayed_write_update5(struct torture_context *tctx, ret = false; break; } - msleep(2 * msec); + msleep(1 * msec); } GET_INFO_BOTH(finfo4,pinfo4); @@ -2631,7 +2651,7 @@ static bool test_delayed_write_update5b(struct torture_context *tctx, ret = false; break; } - msleep(2 * msec); + msleep(1 * msec); } GET_INFO_BOTH(finfo3,pinfo3); @@ -2663,7 +2683,7 @@ static bool test_delayed_write_update5b(struct torture_context *tctx, ret = false; break; } - msleep(2 * msec); + msleep(1 * msec); } GET_INFO_BOTH(finfo4,pinfo4); @@ -2796,7 +2816,7 @@ again: /* make sure the 2 second delay from the first write are canceled */ start = timeval_current(); - end = timeval_add(&start, 15 * sec, 0); + end = timeval_add(&start, 10 * sec, 0); while (!timeval_expired(&end)) { /* get the times after the first write */ @@ -2810,7 +2830,7 @@ again: ret = false; break; } - msleep(2 * msec); + msleep(1 * msec); } GET_INFO_BOTH(finfo3,pinfo3); @@ -2821,7 +2841,7 @@ again: /* sure any further write doesn't update the write time */ start = timeval_current(); - end = timeval_add(&start, 15 * sec, 0); + end = timeval_add(&start, 10 * sec, 0); while (!timeval_expired(&end)) { /* do a write */ torture_comment(tctx, "Do a write on the file handle\n"); @@ -2842,7 +2862,7 @@ again: ret = false; break; } - msleep(2 * msec); + msleep(1 * msec); } GET_INFO_BOTH(finfo4,pinfo4); @@ -2872,6 +2892,70 @@ again: torture_comment(tctx, "Server updated the write_time on close (correct)\n"); } + /* See what the second write handle thinks the time is ? */ + finfo5.basic_info.in.file.fnum = fnum2; + GET_INFO_FILE2(finfo5); + COMPARE_WRITE_TIME_EQUAL(finfo5, pinfo6); + + /* See if we have lost the sticky write time on handle2 */ + msleep(3 * msec); + torture_comment(tctx, "Have we lost the sticky write time ?\n"); + + /* Make sure any further normal write doesn't update the write time */ + start = timeval_current(); + end = timeval_add(&start, 10 * sec, 0); + while (!timeval_expired(&end)) { + /* do a write */ + torture_comment(tctx, "Do a write on the second file handle\n"); + written = smbcli_write(cli2->tree, fnum2, 0, "x", 0, 1); + if (written != 1) { + torture_result(tctx, TORTURE_FAIL, __location__": written gave %d - should have been 1", (int)written); + ret = false; + goto done; + } + /* get the times after the write */ + GET_INFO_FILE2(finfo5); + GET_INFO_PATH(pinfo6); + + if (finfo5.basic_info.out.write_time > pinfo6.basic_info.out.write_time) { + double diff = timeval_elapsed(&start); + torture_comment(tctx, "Server updated write_time after %.2f seconds " + "(1sec == %.2f) (wrong!)\n", + diff, sec); + ret = false; + break; + } + msleep(1 * msec); + } + + /* What about a truncate write ? */ + start = timeval_current(); + end = timeval_add(&start, 10 * sec, 0); + while (!timeval_expired(&end)) { + /* do a write */ + torture_comment(tctx, "Do a truncate write on the second file handle\n"); + written = smbcli_write(cli2->tree, fnum2, 0, "x", 0, 0); + if (written != 0) { + torture_result(tctx, TORTURE_FAIL, __location__": written gave %d - should have been 1", (int)written); + ret = false; + goto done; + } + /* get the times after the write */ + GET_INFO_FILE2(finfo5); + GET_INFO_PATH(pinfo6); + + if (finfo5.basic_info.out.write_time > pinfo6.basic_info.out.write_time) { + double diff = timeval_elapsed(&start); + torture_comment(tctx, "Server updated write_time after %.2f seconds " + "(1sec == %.2f) (wrong!)\n", + diff, sec); + ret = false; + break; + } + msleep(1 * msec); + } + + /* keep the 2nd handle open and rerun tests */ if (first) { first = false; -- 2.34.1