[Box Backup-commit] COMMIT r2496 - in box/trunk: lib/common test/backupstorepatch test/bbackupd

boxbackup-dev at boxbackup.org boxbackup-dev at boxbackup.org
Thu Apr 9 23:45:01 BST 2009


Author: chris
Date: 2009-04-09 23:44:58 +0100 (Thu, 09 Apr 2009)
New Revision: 2496

Modified:
   box/trunk/lib/common/Test.cpp
   box/trunk/lib/common/Test.h
   box/trunk/test/backupstorepatch/testbackupstorepatch.cpp
   box/trunk/test/bbackupd/testbbackupd.cpp
Log:
Show reasons for waiting during bbackupd and backupstorepatch tests,
to help with interpreting test output.

When running at Trace level, where extra output from bbackupd etc. is
common, log a single line at the start of waiting, instead of progress
dots, to help with interpreting output.

Show number of seconds waited for on Windows as well as Unixes.


Modified: box/trunk/lib/common/Test.cpp
===================================================================
--- box/trunk/lib/common/Test.cpp	2009-04-04 14:05:14 UTC (rev 2495)
+++ box/trunk/lib/common/Test.cpp	2009-04-09 22:44:58 UTC (rev 2496)
@@ -229,7 +229,14 @@
 	#endif
 
 	// time for it to start up
-	::fprintf(stdout, "Waiting for server to start: ");
+	if (Logging::GetGlobalLevel() >= Log::TRACE)
+	{
+		BOX_TRACE("Waiting for server to start");
+	}
+	else
+	{
+		::fprintf(stdout, "Waiting for server to start: ");
+	}
 
 	for (int i = 0; i < 15; i++)
 	{
@@ -243,8 +250,12 @@
 			break;
 		}
 
-		::fprintf(stdout, ".");
-		::fflush(stdout);
+		if (Logging::GetGlobalLevel() < Log::TRACE)
+		{
+			::fprintf(stdout, ".");
+			::fflush(stdout);
+		}
+
 		::sleep(1);
 	}
 
@@ -253,19 +264,42 @@
 
 	if (pidIfKnown && !ServerIsAlive(pidIfKnown))
 	{
-		::fprintf(stdout, " server died!\n");
+		if (Logging::GetGlobalLevel() >= Log::TRACE)
+		{
+			BOX_ERROR("server died!");
+		}
+		else
+		{
+			::fprintf(stdout, " server died!\n");
+		}
+
 		TEST_FAIL_WITH_MESSAGE("Server died!");	
 		return -1;
 	}
 
 	if (!TestFileNotEmpty(pidFile))
 	{
-		::fprintf(stdout, " timed out!\n");
+		if (Logging::GetGlobalLevel() >= Log::TRACE)
+		{
+			BOX_ERROR("timed out!");
+		}
+		else
+		{
+			::fprintf(stdout, " timed out!\n");
+		}
+
 		TEST_FAIL_WITH_MESSAGE("Server didn't save PID file");	
 		return -1;
 	}
 
-	::fprintf(stdout, " done.\n");
+	if (Logging::GetGlobalLevel() >= Log::TRACE)
+	{
+		BOX_TRACE("Server started");
+	}
+	else
+	{
+		::fprintf(stdout, " done.\n");
+	}
 
 	// wait a second for the pid to be written to the file
 	::sleep(1);
@@ -278,8 +312,9 @@
 
 	if (pidIfKnown && pid != pidIfKnown)
 	{
-		printf("Server wrote wrong pid to file (%s): expected %d "
-			"but found %d\n", pidFile, pidIfKnown, pid);
+		BOX_ERROR("Server wrote wrong pid to file (" << pidFile <<
+			"): expected " << pidIfKnown << " but found " <<
+			pid);
 		TEST_FAIL_WITH_MESSAGE("Server wrote wrong pid to file");	
 		return -1;
 	}
@@ -381,22 +416,43 @@
 
 
 // Wait a given number of seconds for something to complete
-void wait_for_operation(int seconds)
+void wait_for_operation(int seconds, char* message)
 {
-	printf("Waiting: ");
-	fflush(stdout);
+	if (Logging::GetGlobalLevel() >= Log::TRACE)
+	{
+		BOX_TRACE("Waiting " << seconds << " seconds for " << message);
+	}
+	else
+	{
+		printf("Waiting for %s: ", message);
+		fflush(stdout);
+	}
+
 	for(int l = 0; l < seconds; ++l)
 	{
 		sleep(1);
-		printf(".");
+		if (Logging::GetGlobalLevel() < Log::TRACE)
+		{
+			printf(".");
+			fflush(stdout);
+		}
+	}
+
+	if (Logging::GetGlobalLevel() >= Log::TRACE)
+	{
+		BOX_TRACE("Finished waiting for " << message);
+	}
+	else
+	{
+		printf(" done.\n");
 		fflush(stdout);
 	}
-	printf(" done.\n");
-	fflush(stdout);
 }
 
 void safe_sleep(int seconds)
 {
+	BOX_TRACE("sleeping for " << seconds << " seconds");
+
 #ifdef WIN32
 	Sleep(seconds * 1000);
 #else
@@ -404,7 +460,6 @@
 	memset(&ts, 0, sizeof(ts));
 	ts.tv_sec  = seconds;
 	ts.tv_nsec = 0;
-	BOX_TRACE("sleeping for " << seconds << " seconds");
 	while (nanosleep(&ts, &ts) == -1 && errno == EINTR)
 	{
 		BOX_TRACE("safe_sleep interrupted with " <<
@@ -415,4 +470,3 @@
 #endif
 }
 
-

Modified: box/trunk/lib/common/Test.h
===================================================================
--- box/trunk/lib/common/Test.h	2009-04-04 14:05:14 UTC (rev 2495)
+++ box/trunk/lib/common/Test.h	2009-04-09 22:44:58 UTC (rev 2496)
@@ -158,7 +158,7 @@
 void terminate_bbackupd(int pid);
 
 // Wait a given number of seconds for something to complete
-void wait_for_operation(int seconds);
+void wait_for_operation(int seconds, char* message);
 void safe_sleep(int seconds);
 
 #endif // TEST__H

Modified: box/trunk/test/backupstorepatch/testbackupstorepatch.cpp
===================================================================
--- box/trunk/test/backupstorepatch/testbackupstorepatch.cpp	2009-04-04 14:05:14 UTC (rev 2495)
+++ box/trunk/test/backupstorepatch/testbackupstorepatch.cpp	2009-04-09 22:44:58 UTC (rev 2496)
@@ -578,7 +578,7 @@
 #ifdef WIN32
 			// Cannot signal bbstored to do housekeeping now,
 			// so just wait until we're sure it's done
-			wait_for_operation(12);
+			wait_for_operation(12, "housekeeping to run");
 #else
 			// Send the server a restart signal, so it does 
 			// housekeeping immediately, and wait for it to happen

Modified: box/trunk/test/bbackupd/testbbackupd.cpp
===================================================================
--- box/trunk/test/bbackupd/testbbackupd.cpp	2009-04-04 14:05:14 UTC (rev 2495)
+++ box/trunk/test/bbackupd/testbbackupd.cpp	2009-04-09 22:44:58 UTC (rev 2496)
@@ -87,9 +87,9 @@
 // two cycles and a bit
 #define TIME_TO_WAIT_FOR_BACKUP_OPERATION	12
 
-void wait_for_backup_operation(int seconds = TIME_TO_WAIT_FOR_BACKUP_OPERATION)
+void wait_for_backup_operation(char* message)
 {
-	wait_for_operation(seconds);
+	wait_for_operation(TIME_TO_WAIT_FOR_BACKUP_OPERATION, message);
 }
 
 int bbstored_pid = 0;
@@ -889,7 +889,7 @@
 		TEST_THAT(close(fd) == 0);
 		
 		int pid = start_internal_daemon();
-		wait_for_backup_operation();
+		wait_for_backup_operation("internal daemon to run a sync");
 		TEST_THAT(stop_internal_daemon(pid));
 
 		// two-second delay on the first read() of f1
@@ -910,7 +910,8 @@
 			"Buffer write");
 		TEST_THAT(close(fd) == 0);	
 
-		wait_for_backup_operation();
+		wait_for_backup_operation("internal daemon to sync "
+			"spacetest/f1");
 		// can't test whether intercept was triggered, because
 		// it's in a different process.
 		// TEST_THAT(intercept_triggered());
@@ -985,7 +986,8 @@
 			"Buffer write");
 		TEST_THAT(close(fd) == 0);	
 
-		wait_for_backup_operation();
+		wait_for_backup_operation("internal daemon to sync "
+			"spacetest/f1 again");
 		// can't test whether intercept was triggered, because
 		// it's in a different process.
 		// TEST_THAT(intercept_triggered());
@@ -1050,7 +1052,8 @@
 			"Buffer write");
 		TEST_THAT(close(fd) == 0);	
 
-		wait_for_backup_operation();
+		wait_for_backup_operation("internal daemon to sync "
+			"spacetest/f1 again");
 		// can't test whether intercept was triggered, because
 		// it's in a different process.
 		// TEST_THAT(intercept_triggered());
@@ -1139,7 +1142,8 @@
 			"Buffer write");
 		TEST_THAT(close(fd) == 0);	
 
-		wait_for_backup_operation();
+		wait_for_backup_operation("internal dameon to scan "
+			"spacetest/d1");
 		// can't test whether intercept was triggered, because
 		// it's in a different process.
 		// TEST_THAT(intercept_triggered());
@@ -1284,10 +1288,10 @@
 		// housekeeping deleted them, the backup cannot complete
 		// if the limit is 20 blocks.
 
-		BOX_TRACE("Waiting for bbackupd to notice that the "
+		BOX_TRACE("Waiting for sync for bbackupd to notice that the "
 			"store is full");
 		wait_for_sync_end();
-		BOX_TRACE("done.");
+		BOX_TRACE("Sync finished.");
 
 		BOX_TRACE("Compare to check that there are differences");
 		int compareReturnValue = ::system(BBACKUPQUERY " "
@@ -1297,7 +1301,7 @@
 		TEST_RETURN(compareReturnValue,
 			BackupQueries::ReturnCode::Compare_Different);
 		TestRemoteProcessMemLeaks("bbackupquery.memleaks");
-		BOX_TRACE("done.");
+		BOX_TRACE("Compare finished.");
 
 		// Check that the notify script was run
 		TEST_THAT(TestFileExists("testfiles/notifyran.store-full.1"));
@@ -1307,9 +1311,8 @@
 		// Kill the daemon
 		terminate_bbackupd(bbackupd_pid);
 
-		BOX_TRACE("Wait for housekeeping to remove the deleted files");
-		wait_for_backup_operation(5);
-		BOX_TRACE("done.");
+		wait_for_operation(5, "housekeeping to remove the "
+			"deleted files");
 
 		// This removes f1 and d7, which were previously marked
 		// as deleted, so total usage drops by 4 blocks to 24.
@@ -1470,9 +1473,8 @@
 			return 1;
 		}
 
-		BOX_TRACE("Wait for housekeeping to remove the deleted files");
-		wait_for_backup_operation(5);
-		BOX_TRACE("done.");
+		wait_for_operation(5, "housekeeping to remove the "
+			"deleted files");
 
 		BOX_TRACE("Check that the files were removed");
 		{
@@ -1606,9 +1608,7 @@
 				"| ( cd testfiles && tar xf - )") == 0);
 		#endif
 
-		BOX_TRACE("Wait for bbackupd to upload more files");
-		wait_for_backup_operation();
-		BOX_TRACE("done.");
+		wait_for_backup_operation("bbackupd to upload more files");
 		
 		// Check that the contents of the store are the same 
 		// as the contents of the disc 
@@ -1803,8 +1803,8 @@
 		// also test symlink-to-self loop does not break restore
 		TEST_THAT(symlink("self", SYM_DIR "/self") == 0);
 
-		::wait_for_operation(4);
-		::sync_and_wait();
+		wait_for_operation(4, "symlinks to be old enough");
+		sync_and_wait();
 
 		// Check that the backup was successful, i.e. no differences
 		int compareReturnValue = ::system(BBACKUPQUERY " "
@@ -2207,7 +2207,8 @@
 			fs.Close();
 		}
 
-		wait_for_backup_operation();
+		wait_for_backup_operation("upload of file with unicode name");
+
 		// Compare to check that the file was uploaded
 		compareReturnValue = ::system(BBACKUPQUERY " -Wwarning "
 			"-c testfiles/bbackupd.conf \"compare -acQ\" quit");
@@ -2541,7 +2542,8 @@
 		}
 
 		// wait for backup daemon to do it's stuff, and compare again
-		wait_for_backup_operation();
+		wait_for_backup_operation("bbackupd to sync the changes");
+
 		compareReturnValue = ::system(BBACKUPQUERY " -Wwarning "
 			"-c testfiles/bbackupd.conf "
 			"-l testfiles/query2.log "
@@ -2586,7 +2588,8 @@
 			TEST_THAT(close(fd1) == 0);
 		}
 
-		wait_for_backup_operation(4);
+		wait_for_operation(4, "bbackupd to try to access the store");
+
 		// Check that an error was reported just once
 		TEST_THAT(TestFileExists("testfiles/notifyran.backup-error.1"));
 		TEST_THAT(!TestFileExists("testfiles/notifyran.backup-error.2"));
@@ -2644,9 +2647,11 @@
 			TEST_THAT(close(fd1) == 0);
 		}
 
-		// bbackupd should pause for about 90 seconds from store_fixed_time,
-		// so check that it hasn't run after 85 seconds from store_fixed_time
-		wait_for_backup_operation(85 - time(NULL) + store_fixed_time);
+		// bbackupd should pause for about 90 seconds from
+		// store_fixed_time, so check that it hasn't run after
+		// 85 seconds after store_fixed_time
+		wait_for_operation(85 - time(NULL) + store_fixed_time,
+			"just before bbackupd recovers");
 		TEST_THAT(!TestFileExists("testfiles/"
 			"notifyran.backup-start.wait-snapshot.1"));
 
@@ -2660,7 +2665,7 @@
 		TestRemoteProcessMemLeaks("bbackupquery.memleaks");		
 
 		// wait another 10 seconds, bbackup should have run
-		wait_for_backup_operation(10);
+		wait_for_operation(10, "bbackupd to recover");
 		TEST_THAT(TestFileExists("testfiles/"
 			"notifyran.backup-start.wait-snapshot.1"));
 	
@@ -2742,9 +2747,11 @@
 			TEST_THAT(close(fd1) == 0);
 		}
 
-		// bbackupd should pause for about 90 seconds from store_fixed_time,
-		// so check that it hasn't run after 85 seconds from store_fixed_time
-		wait_for_backup_operation(85 - time(NULL) + store_fixed_time);
+		// bbackupd should pause for about 90 seconds from
+		// store_fixed_time, so check that it hasn't run after
+		// 85 seconds from store_fixed_time
+		wait_for_operation(85 - time(NULL) + store_fixed_time,
+			"just before bbackupd recovers");
 		TEST_THAT(!TestFileExists("testfiles/"
 			"notifyran.backup-start.wait-automatic.1"));
 
@@ -2758,7 +2765,7 @@
 		TestRemoteProcessMemLeaks("bbackupquery.memleaks");		
 
 		// wait another 10 seconds, bbackup should have run
-		wait_for_backup_operation(10);
+		wait_for_operation(10, "bbackupd to recover");
 		TEST_THAT(TestFileExists("testfiles/"
 			"notifyran.backup-start.wait-automatic.1"));
 	
@@ -2801,7 +2808,7 @@
 				== 0);
 		#endif
 
-		wait_for_backup_operation();
+		wait_for_backup_operation("bbackupd to sync the changes");
 		compareReturnValue = ::system(BBACKUPQUERY " "
 			"-c testfiles/bbackupd.conf "
 			"-l testfiles/query3c.log "
@@ -2830,7 +2837,8 @@
 				"testfiles/TestDir1/x1/dir-to-file") == 0);
 		#endif
 
-		wait_for_backup_operation();
+		wait_for_backup_operation("bbackupd to sync the changes");
+
 		compareReturnValue = ::system(BBACKUPQUERY " "
 			"-c testfiles/bbackupd.conf "
 			"-l testfiles/query3d.log "
@@ -2862,7 +2870,8 @@
 				== 0);
 		#endif
 
-		wait_for_backup_operation();
+		wait_for_backup_operation("bbackupd to sync the changes");
+
 		compareReturnValue = ::system(BBACKUPQUERY " "
 			"-c testfiles/bbackupd.conf "
 			"-l testfiles/query3e.log "
@@ -2894,7 +2903,8 @@
 				"testfiles/TestDir1/x1/dir-to-file") == 0);
 		#endif
 
-		wait_for_backup_operation();
+		wait_for_backup_operation("bbackupd to sync the changes");
+
 		compareReturnValue = ::system(BBACKUPQUERY " "
 			"-c testfiles/bbackupd.conf "
 			"-l testfiles/query3f.log "
@@ -2924,9 +2934,12 @@
 		TEST_THAT(close(fd2) == 0);
 		TEST_THAT(TestFileExists("testfiles/TestDir1/untracked-1"));
 		TEST_THAT(TestFileExists("testfiles/TestDir1/untracked-2"));
-		wait_for_operation(5);
+
 		// back up both files
-		wait_for_backup_operation();
+		wait_for_operation(5, "untracked files to be old enough");
+		wait_for_backup_operation("bbackupd to sync the "
+			"untracked files");
+
 		compareReturnValue = ::system(BBACKUPQUERY " "
 			"-c testfiles/bbackupd.conf "
 			"-l testfiles/query3g.log "
@@ -2944,7 +2957,10 @@
 			"testfiles/TestDir1/untracked-2") == 0);
 		TEST_THAT(!TestFileExists("testfiles/TestDir1/untracked-1"));
 		TEST_THAT( TestFileExists("testfiles/TestDir1/untracked-2"));
-		wait_for_backup_operation();
+
+		wait_for_backup_operation("bbackupd to sync the untracked "
+			"files again");
+
 		compareReturnValue = ::system(BBACKUPQUERY " "
 			"-c testfiles/bbackupd.conf "
 			"-l testfiles/query3g.log "
@@ -2977,9 +2993,11 @@
 		TEST_THAT(close(fd2) == 0);
 		TEST_THAT(TestFileExists("testfiles/TestDir1/tracked-1"));
 		TEST_THAT(TestFileExists("testfiles/TestDir1/tracked-2"));
-		wait_for_operation(5);
+
 		// back up both files
-		wait_for_backup_operation();
+		wait_for_operation(5, "tracked files to be old enough");
+		wait_for_backup_operation("bbackupd to sync the tracked files");
+
 		compareReturnValue = ::system(BBACKUPQUERY " "
 			"-c testfiles/bbackupd.conf "
 			"-l testfiles/query3h.log "
@@ -2997,7 +3015,10 @@
 			"testfiles/TestDir1/tracked-2") == 0);
 		TEST_THAT(!TestFileExists("testfiles/TestDir1/tracked-1"));
 		TEST_THAT( TestFileExists("testfiles/TestDir1/tracked-2"));
-		wait_for_backup_operation();
+
+		wait_for_backup_operation("bbackupd to sync the tracked "
+			"files again");
+
 		compareReturnValue = ::system(BBACKUPQUERY " "
 			"-c testfiles/bbackupd.conf "
 			"-l testfiles/query3i.log "
@@ -3018,7 +3039,8 @@
 		TEST_THAT(::rename("testfiles/TestDir1/df9834.dsf", 
 			"testfiles/TestDir1/x1/dsfdsfs98.fd") == 0);
 		
-		wait_for_backup_operation();
+		wait_for_backup_operation("bbackupd to sync");
+
 		compareReturnValue = ::system(BBACKUPQUERY " "
 			"-c testfiles/bbackupd.conf "
 			"-l testfiles/query3j.log "
@@ -3056,7 +3078,8 @@
 		#endif
 		
 		// Wait and test
-		wait_for_backup_operation();
+		wait_for_backup_operation("bbackupd to sync old files");
+
 		compareReturnValue = ::system(BBACKUPQUERY " "
 			"-c testfiles/bbackupd.conf "
 			"-l testfiles/query3k.log "
@@ -3239,7 +3262,8 @@
 			}
 
 			// Wait and test...
-			wait_for_backup_operation();
+			wait_for_backup_operation("bbackupd to try to sync "
+				"unreadable file");
 			compareReturnValue = ::system(BBACKUPQUERY " "
 				"-c testfiles/bbackupd.conf "
 				"-l testfiles/query3o.log "
@@ -3343,7 +3367,9 @@
 		::chmod("testfiles/TestDir1/df9834.dsf", 0423);
 		
 		// Wait and test
-		wait_for_backup_operation();
+		wait_for_backup_operation("bbackupd to sync deletion "
+			"of directory");
+
 		compareReturnValue = ::system(BBACKUPQUERY " "
 			"-c testfiles/bbackupd.conf "
 			"-l testfiles/query4.log "
@@ -3544,7 +3570,8 @@
 		#endif
 		
 		// Wait and test
-		wait_for_backup_operation();
+		wait_for_backup_operation("bbackupd to sync new files");
+
 		compareReturnValue = ::system(BBACKUPQUERY " "
 			"-c testfiles/bbackupd.conf "
 			"-l testfiles/query5.log "
@@ -3562,7 +3589,9 @@
 		printf("\n==== Rename directory\n");
 		TEST_THAT(rename("testfiles/TestDir1/sub23/dhsfdss", 
 			"testfiles/TestDir1/renamed-dir") == 0);
-		wait_for_backup_operation();
+
+		wait_for_backup_operation("bbackupd to sync renamed directory");
+
 		compareReturnValue = ::system(BBACKUPQUERY " "
 			"-c testfiles/bbackupd.conf "
 			"-l testfiles/query6.log "
@@ -3588,7 +3617,9 @@
 			"testfiles/TestDir1/df324-ren") == 0);
 		TEST_THAT(rename("testfiles/TestDir1/sub23/find2perl", 
 			"testfiles/TestDir1/find2perl-ren") == 0);
-		wait_for_backup_operation();
+
+		wait_for_backup_operation("bbackupd to sync renamed files");
+
 		compareReturnValue = ::system(BBACKUPQUERY " "
 			"-c testfiles/bbackupd.conf "
 			"-l testfiles/query6.log "
@@ -3631,7 +3662,7 @@
 		}
 
 		// Wait and test
-		wait_for_backup_operation();
+		wait_for_backup_operation("bbackup to sync future file");
 		compareReturnValue = ::system(BBACKUPQUERY " "
 			"-c testfiles/bbackupd.conf "
 			"-l testfiles/query3e.log "
@@ -3698,9 +3729,11 @@
 			::fclose(f);
 		}
 
-		// Wait and test that there *are* differences
-		wait_for_backup_operation((TIME_TO_WAIT_FOR_BACKUP_OPERATION * 
-			3) / 2); // little bit longer than usual
+		// Wait a little bit longer than usual
+		wait_for_operation((TIME_TO_WAIT_FOR_BACKUP_OPERATION * 
+			3) / 2, "bbackupd to detect changed store marker");
+
+		// Test that there *are* differences
 		compareReturnValue = ::system(BBACKUPQUERY " "
 			"-c testfiles/bbackupd.conf "
 			"-l testfiles/query6.log "
@@ -3714,9 +3747,8 @@
 		if (!ServerIsAlive(bbackupd_pid)) return 1;
 		if (!ServerIsAlive(bbstored_pid)) return 1;
 
-		printf("\n==== Waiting for bbackupd to recover\n");
 		// 100 seconds - (12*3/2)
-		wait_for_operation(82);
+		wait_for_operation(82, "bbackupd to recover");
 
 		TEST_THAT(ServerIsAlive(bbackupd_pid));
 		TEST_THAT(ServerIsAlive(bbstored_pid));
@@ -3947,8 +3979,9 @@
 		if(bbackupd_pid != -1 && bbackupd_pid != 0)
 		{
 			// Wait and compare (a little bit longer than usual)
-			wait_for_backup_operation(
-				(TIME_TO_WAIT_FOR_BACKUP_OPERATION*3) / 2); 
+			wait_for_operation(
+				(TIME_TO_WAIT_FOR_BACKUP_OPERATION*3) / 2,
+				"bbackupd to sync everything"); 
 			compareReturnValue = ::system(BBACKUPQUERY " "
 				"-c testfiles/bbackupd.conf "
 				"-l testfiles/query4a.log "




More information about the Boxbackup-commit mailing list