Merge cd0b9f362b into b31ed6e325

syncoid: Add zstdmt compress options

findoid

@@ -25,6 +25,9 @@ if ($args{'path'} eq '') {
 	}
 }
 
+# resolve given path to a canonical one
+$args{'path'} = Cwd::realpath($args{'path'});
+
 my $dataset = getdataset($args{'path'});
 
 my %versions = getversions($args{'path'}, $dataset);

syncoid

@@ -498,7 +498,6 @@ sub syncdataset {
 
 		my $ret;
 		if (defined $origin) {
-			writelog('INFO', "Clone is recreated on target $targetfs based on $origin");
 			($ret, $stdout) = syncclone($sourcehost, $sourcefs, $origin, $targethost, $targetfs, $oldestsnap);
 			if ($ret) {
 				writelog('INFO', "clone creation failed, trying ordinary replication as fallback");
@@ -506,12 +505,6 @@ sub syncdataset {
 				return 0;
 			}
 		} else {
-			if (!defined ($args{'no-stream'}) ) {
-				writelog('INFO', "Sending oldest full snapshot $sourcefs\@$oldestsnap to new target filesystem:");
-			} else {
-				writelog('INFO', "--no-stream selected; sending newest full snapshot $sourcefs\@$oldestsnap to new target filesystem:");
-			}
-
 			($ret, $stdout) = syncfull($sourcehost, $sourcefs, $targethost, $targetfs, $oldestsnap);
 		}
 
@@ -532,8 +525,6 @@ sub syncdataset {
 			# $originaltargetreadonly = getzfsvalue($targethost,$targetfs,$targetisroot,'readonly');
 			# setzfsvalue($targethost,$targetfs,$targetisroot,'readonly','on');
 
-			writelog('INFO', "Updating new target filesystem with incremental $sourcefs\@$oldestsnap ... $newsyncsnap:");
-
 			(my $ret, $stdout) = syncincremental($sourcehost, $sourcefs, $targethost, $targetfs, $oldestsnap, $newsyncsnap, 0);
 
 			if ($ret != 0) {
@@ -865,6 +856,16 @@ sub syncdataset {
 		# those that exist on the source. Remaining are the snapshots
 		# that are only on the target. Then sort to remove the oldest
 		# snapshots first.
+
+		# regather snapshots on source and target
+		%snaps = getsnaps('source',$sourcehost,$sourcefs,$sourceisroot,0);
+
+		if ($targetexists) {
+		    my %targetsnaps = getsnaps('target',$targethost,$targetfs,$targetisroot,0);
+		    my %sourcesnaps = %snaps;
+		    %snaps = (%sourcesnaps, %targetsnaps);
+		}
+
 		my @to_delete = sort { sortsnapshots(\%snaps, $a, $b) } grep {!exists $snaps{'source'}{$_}} keys %{ $snaps{'target'} };
 		while (@to_delete) {
 			# Create batch of snapshots to remove
@@ -898,7 +899,6 @@ sub runsynccmd {
 	my $disp_pvsize = $pvsize == 0 ? 'UNKNOWN' : readablebytes($pvsize);
 	my $sendoptions;
 	if ($sendsource =~ / -t /) {
-		writelog('INFO', "Resuming interrupted zfs send/receive from $sourcefs to $targetfs (~ $disp_pvsize remaining):");
 		$sendoptions = getoptionsline(\@sendoptions, ('P','V','e','v'));
 	} elsif ($sendsource =~ /#/) {
 		$sendoptions = getoptionsline(\@sendoptions, ('L','V','c','e','w'));
@@ -934,12 +934,13 @@ sub runsynccmd {
 	my $recvcmd = "$targetsudocmd $zfscmd receive $recvoptions $targetfsescaped 2>&1";
 
 	my $synccmd = buildsynccmd($sendcmd,$recvcmd,$pvsize,$sourceisroot,$targetisroot);
-	writelog('INFO', "Sync size: ~$disp_pvsize");
+	writelog('DEBUG', "sync size: ~$disp_pvsize");
 	writelog('DEBUG', "$synccmd");
 
 	# make sure target is (still) not currently in receive.
 	if (iszfsbusy($targethost,$targetfs,$targetisroot)) {
-		writelog('WARN', "Cannot sync now: $targetfs is already target of a zfs receive process.");
+		my $targetname = buildnicename($targethost, $targetfs);
+		writelog('WARN', "Cannot sync now: $targetname is already target of a zfs receive process.");
 		return (1, '');
 	}
 
@@ -971,6 +972,16 @@ sub syncfull {
 	my $sendsource = "$sourcefsescaped\@$snapescaped";
 	my $pvsize = getsendsize($sourcehost,"$sourcefs\@$snapname",0,$sourceisroot);
 
+	my $srcname = buildnicename($sourcehost, $sourcefs, $snapname);
+	my $targetname = buildnicename($targethost, $targetfs);
+	my $disp_pvsize = $pvsize == 0 ? 'UNKNOWN' : readablebytes($pvsize);
+
+	if (!defined ($args{'no-stream'}) ) {
+		writelog('INFO', "Sending oldest full snapshot $srcname to new target filesystem $targetname (~ $disp_pvsize):");
+	} else {
+		writelog('INFO', "--no-stream selected; sending newest full snapshot $srcname to new target filesystem $targetname: (~ $disp_pvsize)");
+	}
+
 	return runsynccmd($sourcehost, $sourcefs, $sendsource, $targethost, $targetfs, $pvsize);
 } # end syncfull()
 
@@ -1011,8 +1022,11 @@ sub syncincremental {
 			foreach my $i (0..(scalar(@intsnaps) - 2)) {
 				my $snapa = $intsnaps[$i];
 				my $snapb = $intsnaps[$i + 1];
-				writelog('INFO', "Performing an incremental sync between '$snapa' and '$snapb'");
-				syncincremental($sourcehost, $sourcefs, $targethost, $targetfs, $snapa, $snapb, 1) == 0 or return $?;
+				(my $ret, my $stdout) = syncincremental($sourcehost, $sourcefs, $targethost, $targetfs, $snapa, $snapb, 1);
+
+				if ($ret != 0) {
+					return ($ret, $stdout);
+				}
 			}
 
 			# Return after finishing the -i syncs so that we don't try to do another -I
@@ -1026,6 +1040,12 @@ sub syncincremental {
 	my $sendsource = "$streamarg $sourcefsescaped\@$fromsnapescaped $sourcefsescaped\@$tosnapescaped";
 	my $pvsize = getsendsize($sourcehost,"$sourcefs\@$fromsnap","$sourcefs\@$tosnap",$sourceisroot);
 
+	my $srcname = buildnicename($sourcehost, $sourcefs, $fromsnap);
+	my $targetname = buildnicename($targethost, $targetfs);
+	my $disp_pvsize = $pvsize == 0 ? 'UNKNOWN' : readablebytes($pvsize);
+
+	writelog('INFO', "Sending incremental $srcname ... $tosnap to $targetname (~ $disp_pvsize):");
+
 	return runsynccmd($sourcehost, $sourcefs, $sendsource, $targethost, $targetfs, $pvsize);
 } # end syncincremental()
 
@@ -1038,6 +1058,12 @@ sub syncclone {
 	my $sendsource = "-i $originescaped $sourcefsescaped\@$tosnapescaped";
 	my $pvsize = getsendsize($sourcehost,$origin,"$sourcefs\@$tosnap",$sourceisroot);
 
+	my $srcname = buildnicename($sourcehost, $origin);
+	my $targetname = buildnicename($targethost, $targetfs);
+	my $disp_pvsize = $pvsize == 0 ? 'UNKNOWN' : readablebytes($pvsize);
+
+	writelog('INFO', "Clone is recreated on target $targetname based on $srcname (~ $disp_pvsize):");
+
 	return runsynccmd($sourcehost, $sourcefs, $sendsource, $targethost, $targetfs, $pvsize);
 } # end syncclone()
 
@@ -1047,6 +1073,12 @@ sub syncresume {
 	my $sendsource = "-t $receivetoken";
 	my $pvsize = getsendsize($sourcehost,"","",$sourceisroot,$receivetoken);
 
+	my $srcname = buildnicename($sourcehost, $sourcefs);
+	my $targetname = buildnicename($targethost, $targetfs);
+	my $disp_pvsize = $pvsize == 0 ? 'UNKNOWN' : readablebytes($pvsize);
+
+	writelog('INFO', "Resuming interrupted zfs send/receive from $srcname to $targetname (~ $disp_pvsize remaining):");
+
 	return runsynccmd($sourcehost, $sourcefs, $sendsource, $targethost, $targetfs, $pvsize);
 } # end syncresume()
 
@@ -1058,6 +1090,11 @@ sub syncbookmark {
 	my $tosnapescaped = escapeshellparam($tosnap);
 	my $sendsource = "-i $sourcefsescaped#$bookmarkescaped $sourcefsescaped\@$tosnapescaped";
 
+	my $srcname = buildnicename($sourcehost, $sourcefs, '', $bookmark);
+	my $targetname = buildnicename($targethost, $targetfs);
+
+	writelog('INFO', "Sending incremental $srcname ... $tosnap to $targetname:");
+
 	return runsynccmd($sourcehost, $sourcefs, $sendsource, $targethost, $targetfs, 0);
 } # end syncbookmark
 
@@ -1110,12 +1147,24 @@ sub compressargset {
 			decomrawcmd => 'zstd',
 			decomargs   => '-dc',
 		},
+		'zstdmt-fast' => {
+			rawcmd      => 'zstdmt',
+			args        => '-3',
+			decomrawcmd => 'zstdmt',
+			decomargs   => '-dc',
+		},
 		'zstd-slow' => {
 			rawcmd      => 'zstd',
 			args        => '-19',
 			decomrawcmd => 'zstd',
 			decomargs   => '-dc',
 		},
+		'zstdmt-slow' => {
+			rawcmd      => 'zstdmt',
+			args        => '-19',
+			decomrawcmd => 'zstdmt',
+			decomargs   => '-dc',
+		},
 		'xz' => {
 			rawcmd      => 'xz',
 			args        => '',
@@ -1138,7 +1187,7 @@ sub compressargset {
 
 	if ($value eq 'default') {
 		$value = $DEFAULT_COMPRESSION;
-	} elsif (!(grep $value eq $_, ('gzip', 'pigz-fast', 'pigz-slow', 'zstd-fast', 'zstd-slow', 'lz4', 'xz', 'lzo', 'default', 'none'))) {
+	} elsif (!(grep $value eq $_, ('gzip', 'pigz-fast', 'pigz-slow', 'zstd-fast', 'zstdmt-fast', 'zstd-slow', 'zstdmt-slow', 'lz4', 'xz', 'lzo', 'default', 'none'))) {
 		writelog('WARN', "Unrecognised compression value $value, defaulting to $DEFAULT_COMPRESSION");
 		$value = $DEFAULT_COMPRESSION;
 	}
@@ -1507,7 +1556,7 @@ sub getnewestsnapshot {
 	my $snaps = shift;
 	foreach my $snap (sort { sortsnapshots($snaps, $b, $a) } keys %{ $snaps{'source'} }) {
 		# return on first snap found - it's the newest
-		writelog('INFO', "NEWEST SNAPSHOT: $snap");
+		writelog('DEBUG', "NEWEST SNAPSHOT: $snap");
 		return $snap;
 	}
 	# must not have had any snapshots on source - looks like we'd better create one!
@@ -2233,6 +2282,26 @@ sub snapisincluded {
 	return 1;
 }
 
+sub buildnicename {
+	my ($host,$fs,$snapname,$bookmarkname) = @_;
+
+	my $name;
+	if ($host) {
+		$host =~ s/-S \/tmp\/syncoid[a-zA-Z0-9-@]+ //g;
+		$name = "$host:$fs";
+	} else {
+		$name = "$fs";
+	}
+
+	if ($snapname) {
+		$name = "$name\@$snapname";
+	} elsif ($bookmarkname) {
+		$name = "$name#$bookmarkname";
+	}
+
+	return $name;
+}
+
 __END__
 
 =head1 NAME
@@ -2251,7 +2320,7 @@ syncoid - ZFS snapshot replication tool
 
 Options:
 
-  --compress=FORMAT     Compresses data during transfer. Currently accepted options are gzip, pigz-fast, pigz-slow, zstd-fast, zstd-slow, lz4, xz, lzo (default) & none
+  --compress=FORMAT     Compresses data during transfer. Currently accepted options are gzip, pigz-fast, pigz-slow, zstd-fast, zstdmt-fast, zstd-slow, zstdmt-slow, lz4, xz, lzo (default) & none
   --identifier=EXTRA    Extra identifier which is included in the snapshot name. Can be used for replicating to multiple targets.
   --recursive|r         Also transfers child datasets
   --skip-parent         Skips syncing of the parent dataset. Does nothing without '--recursive' option.

tests/3_monitor_snapshots/run.sh

@@ -0,0 +1,18 @@
+#!/bin/bash
+set -x
+
+# this test will create pools in a number of states
+# and check the output text and return code of 
+# sanoid --monitor-snapshots
+
+. ../common/lib.sh
+
+# prepare
+setup
+checkEnvironment
+disableTimeSync
+
+# set timezone
+ln -sf /usr/share/zoneinfo/Europe/Vienna /etc/localtime
+
+python3 test_monitoring.py

tests/3_monitor_snapshots/sanoid.conf

@@ -0,0 +1,37 @@
+[sanoid-test-1]
+	use_template = production
+
+[sanoid-test-2]
+	use_template = demo
+
+[template_production]
+	hourly = 36
+	daily = 30
+	monthly = 3
+	yearly = 0
+	autosnap = yes
+	autoprune = no
+	hourly_warn = 90m
+	hourly_crit = 360m
+	daily_warn = 28h
+	daily_crit = 32h
+	weekly_warn = 0
+	weekly_crit = 0
+	monthly_warn = 32d
+	monthly_crit = 40d
+	yearly_warn = 0
+	yearly_crit = 0
+	
+
+[template_demo]
+	daily = 60
+	hourly_warn = 290m
+	hourly_crit = 360m
+	daily_warn = 28h
+	daily_crit = 48h
+	weekly_warn = 0
+	weekly_crit = 0
+	monthly_warn = 32d
+	monthly_crit = 40d
+	yearly_warn = 0
+	yearly_crit = 0

tests/3_monitor_snapshots/test_monitoring.py

@@ -0,0 +1,163 @@
+#!/usr/bin/env python3
+
+# this software is licensed for use under the Free Software Foundation's GPL v3.0 license, as retrieved
+# from http://www.gnu.org/licenses/gpl-3.0.html on 2014-11-17.  A copy should also be available in this
+# project's Git repository at https://github.com/jimsalterjrs/sanoid/blob/master/LICENSE.
+
+
+import os
+import subprocess
+import time
+import unittest
+
+
+sanoid_cmd = os.environ.get("SANOID")
+pool_disk_image1 = "/zpool1.img"
+pool_name1 = "sanoid-test-1"
+pool_disk_image2 = "/zpool2.img"
+pool_name2 = "sanoid-test-2"
+
+clk_id = time.CLOCK_REALTIME
+starting_time = time.clock_gettime(clk_id)
+
+
+def monitor_snapshots_command():
+    """Runs sanoid --monitor-snapshots and returns a CompletedProcess instance"""
+    return_info = subprocess.run([sanoid_cmd,  "--monitor-snapshots"], capture_output=True)
+    return return_info
+    
+def run_sanoid_cron_command():
+    """Runs sanoid and returns a CompletedProcess instance"""
+    return_info = subprocess.run([sanoid_cmd,  "--cron", "--verbose"], capture_output=True, check=True)
+    return return_info
+
+def advance_time(seconds):
+    """Advances the system clock by seconds"""
+    
+    # Get the current time
+    clk_id = time.CLOCK_REALTIME
+    time_seconds = time.clock_gettime(clk_id)
+    # print("Current unix time is", time_seconds, "or", time.asctime(time.gmtime(time_seconds)), "in GMT")
+    
+    # Set the clock to the current time plus seconds
+    time.clock_settime(clk_id, time_seconds + seconds)
+
+    # Print the new time
+    time_seconds = time.clock_gettime(clk_id)
+    # print("Current unix time is", time_seconds, "or", time.asctime(time.gmtime(time_seconds)), "in GMT")
+    return time_seconds
+
+
+class TestMonitoringOutput(unittest.TestCase):
+    def test_no_zpool(self):
+        """Test what happens if there is no zpool at all"""
+
+        return_info = monitor_snapshots_command()
+        self.assertEqual(return_info.stdout, b"CRIT: sanoid-test-1 has no daily snapshots at all!, CRIT: sanoid-test-1 has no hourly snapshots at all!, CRIT: sanoid-test-1 has no monthly snapshots at all!, CRIT: sanoid-test-2 has no daily snapshots at all!, CRIT: sanoid-test-2 has no hourly snapshots at all!, CRIT: sanoid-test-2 has no monthly snapshots at all!\n")
+        self.assertEqual(return_info.returncode, 2)
+
+class TestsWithZpool(unittest.TestCase):
+    """Tests that require a test zpool"""
+
+    def setUp(self):
+        """Set up the zpool"""
+        subprocess.run(["truncate", "-s", "512M", pool_disk_image1], check=True)
+        subprocess.run(["zpool", "create", "-f", pool_name1, pool_disk_image1], check=True)
+
+        subprocess.run(["truncate", "-s", "512M", pool_disk_image2], check=True)
+        subprocess.run(["zpool", "create", "-f", pool_name2, pool_disk_image2], check=True)
+
+        # Clear the snapshot cache in between
+        subprocess.run([sanoid_cmd, "--force-update"])
+
+    def tearDown(self):
+        """Clean up on either passed or failed tests"""
+        subprocess.run(["zpool", "export", pool_name1])
+        subprocess.run(["rm", "-f", pool_disk_image1])
+        subprocess.run(["zpool", "export", pool_name2])
+        subprocess.run(["rm", "-f", pool_disk_image2])
+        time.clock_settime(clk_id, starting_time)
+
+    def test_with_zpool_no_snapshots(self):
+        """Test what happens if there is a zpool, but with no snapshots"""
+
+        # Run sanoid --monitor-snapshots before doing anything else
+        return_info = monitor_snapshots_command()
+        self.assertEqual(return_info.stdout, b"CRIT: sanoid-test-1 has no daily snapshots at all!, CRIT: sanoid-test-1 has no hourly snapshots at all!, CRIT: sanoid-test-1 has no monthly snapshots at all!, CRIT: sanoid-test-2 has no daily snapshots at all!, CRIT: sanoid-test-2 has no hourly snapshots at all!, CRIT: sanoid-test-2 has no monthly snapshots at all!\n")
+        self.assertEqual(return_info.returncode, 2)
+
+    def test_immediately_after_running_sanoid(self):
+        """Test immediately after running sanoid --cron"""
+
+        run_sanoid_cron_command()
+        return_info = monitor_snapshots_command()
+        self.assertEqual(return_info.stdout, b"OK: all monitored datasets (sanoid-test-1, sanoid-test-2) have fresh snapshots\n")
+        self.assertEqual(return_info.returncode, 0)
+
+    def test_one_warning_hourly(self):
+        """Test one warning on hourly snapshots, no critical warnings, to check output and error status"""
+
+        run_sanoid_cron_command()
+        
+        # Advance 100 mins to trigger the hourly warning on sanoid-test-1 but nothing else
+        advance_time(100 * 60)
+        return_info = monitor_snapshots_command()
+        # Output should be something like: 
+        # WARN: sanoid-test-1 newest hourly snapshot is 1h 40m 0s old (should be < 1h 30m 0s)\n
+        # But we cannot be sure about the exact time as test execution could be different on
+        # different machines, so ignore the bits that may be different.
+        self.assertEqual(return_info.stdout[:49], b"WARN: sanoid-test-1 newest hourly snapshot is 1h ")
+        self.assertEqual(return_info.stdout[-30:], b"s old (should be < 1h 30m 0s)\n")
+        self.assertEqual(return_info.returncode, 1)
+
+    def test_two_criticals_hourly(self):
+        """Test two criticals (hourly), to check output and error status"""
+
+        run_sanoid_cron_command()
+        
+        # Advance 390 mins to trigger the hourly critical on both sanoid-test-1 and sanoid-test-2
+        advance_time(390 * 60)
+        return_info = monitor_snapshots_command()
+
+        # Output should be something like: 
+        # CRIT: sanoid-test-1 newest hourly snapshot is 6h 30m 1s old (should be < 6h 0m 0s), CRIT: sanoid-test-2 newest hourly snapshot is 6h 30m 1s old (should be < 6h 0m 0s)\n
+        # But we cannot be sure about the exact time as test execution could be different on
+        # different machines, so ignore the bits that may be different.
+        comma_location = return_info.stdout.find(b",")
+        self.assertEqual(return_info.stdout[:49], b"CRIT: sanoid-test-1 newest hourly snapshot is 6h ")
+        self.assertEqual(return_info.stdout[comma_location - 28:comma_location], b"s old (should be < 6h 0m 0s)")
+        self.assertEqual(return_info.stdout[comma_location:comma_location + 51], b", CRIT: sanoid-test-2 newest hourly snapshot is 6h ")
+        self.assertEqual(return_info.stdout[-29:], b"s old (should be < 6h 0m 0s)\n")
+        self.assertEqual(return_info.returncode, 2)
+
+    def test_two_criticals_hourly_two_warnings_daily(self):
+        """Test two criticals (hourly) and two warnings (daily), to check output and error status"""
+
+        run_sanoid_cron_command()
+        
+        # Advance more than 28 hours to trigger the daily warning on both sanoid-test-1 and sanoid-test-2
+        advance_time(29 * 60 * 60)
+        return_info = monitor_snapshots_command()
+
+        # Output should be something like: 
+        # CRIT: sanoid-test-1 newest hourly snapshot is 1d 5h 0m 0s old (should be < 6h 0m 0s), CRIT: sanoid-test-2 newest hourly snapshot is 1d 5h 0m 0s old (should be < 6h 0m 0s), WARN: sanoid-test-1 newest daily snapshot is 1d 5h 0m 0s old (should be < 1d 4h 0m 0s), WARN: sanoid-test-2 newest daily snapshot is 1d 5h 0m 0s old (should be < 1d 4h 0m 0s)\n
+        # But we cannot be sure about the exact time as test execution could be different on
+        # different machines, so ignore the bits that may be different.
+        print(return_info.stdout)
+        output_list = return_info.stdout.split(b", ")
+
+        self.assertEqual(output_list[0][:49], b"CRIT: sanoid-test-1 newest hourly snapshot is 1d ")
+        self.assertEqual(output_list[0][-28:], b"s old (should be < 6h 0m 0s)")
+        self.assertEqual(output_list[1][:49], b"CRIT: sanoid-test-2 newest hourly snapshot is 1d ")
+        self.assertEqual(output_list[1][-28:], b"s old (should be < 6h 0m 0s)")
+        
+        self.assertEqual(output_list[2][:48], b"WARN: sanoid-test-1 newest daily snapshot is 1d ")
+        self.assertEqual(output_list[2][-31:], b"s old (should be < 1d 4h 0m 0s)")
+        self.assertEqual(output_list[3][:48], b"WARN: sanoid-test-2 newest daily snapshot is 1d ")
+        self.assertEqual(output_list[3][-32:], b"s old (should be < 1d 4h 0m 0s)\n")
+
+        self.assertEqual(return_info.returncode, 2)
+
+
+if __name__ == '__main__':
+    unittest.main()

tests/4_monitor_snapshots_dont_warncrit/run.sh

@@ -0,0 +1,18 @@
+#!/bin/bash
+set -x
+
+# this test will create pools in a number of states
+# and check the output text and return code of 
+# sanoid --monitor-snapshots
+
+. ../common/lib.sh
+
+# prepare
+setup
+checkEnvironment
+disableTimeSync
+
+# set timezone
+ln -sf /usr/share/zoneinfo/Europe/Vienna /etc/localtime
+
+python3 test_monitoring.py

tests/4_monitor_snapshots_dont_warncrit/sanoid.conf

@@ -0,0 +1,41 @@
+[sanoid-test-1]
+	use_template = production
+
+[sanoid-test-2]
+	use_template = demo
+
+[template_production]
+	hourly = 36
+	daily = 30
+	monthly = 3
+	yearly = 0
+	autosnap = yes
+	autoprune = no
+	hourly_warn = 90m
+	hourly_crit = 360m
+	daily_warn = 28h
+	daily_crit = 32h
+	weekly_warn = 0
+	weekly_crit = 0
+	monthly_warn = 32d
+	monthly_crit = 40d
+	yearly_warn = 0
+	yearly_crit = 0
+	monitor_dont_warn = true
+	monitor_dont_crit = Yes
+	
+
+[template_demo]
+	daily = 60
+	hourly_warn = 290m
+	hourly_crit = 360m
+	daily_warn = 28h
+	daily_crit = 48h
+	weekly_warn = 0
+	weekly_crit = 0
+	monthly_warn = 32d
+	monthly_crit = 40d
+	yearly_warn = 0
+	yearly_crit = 0
+	monitor_dont_warn = ON
+	monitor_dont_crit = 1

tests/4_monitor_snapshots_dont_warncrit/test_monitoring.py

@@ -0,0 +1,163 @@
+#!/usr/bin/env python3
+
+# this software is licensed for use under the Free Software Foundation's GPL v3.0 license, as retrieved
+# from http://www.gnu.org/licenses/gpl-3.0.html on 2014-11-17.  A copy should also be available in this
+# project's Git repository at https://github.com/jimsalterjrs/sanoid/blob/master/LICENSE.
+
+
+import os
+import subprocess
+import time
+import unittest
+
+
+sanoid_cmd = os.environ.get("SANOID")
+pool_disk_image1 = "/zpool1.img"
+pool_name1 = "sanoid-test-1"
+pool_disk_image2 = "/zpool2.img"
+pool_name2 = "sanoid-test-2"
+
+clk_id = time.CLOCK_REALTIME
+starting_time = time.clock_gettime(clk_id)
+
+
+def monitor_snapshots_command():
+    """Runs sanoid --monitor-snapshots and returns a CompletedProcess instance"""
+    return_info = subprocess.run([sanoid_cmd,  "--monitor-snapshots"], capture_output=True)
+    return return_info
+    
+def run_sanoid_cron_command():
+    """Runs sanoid and returns a CompletedProcess instance"""
+    return_info = subprocess.run([sanoid_cmd,  "--cron", "--verbose"], capture_output=True, check=True)
+    return return_info
+
+def advance_time(seconds):
+    """Advances the system clock by seconds"""
+    
+    # Get the current time
+    clk_id = time.CLOCK_REALTIME
+    time_seconds = time.clock_gettime(clk_id)
+    # print("Current unix time is", time_seconds, "or", time.asctime(time.gmtime(time_seconds)), "in GMT")
+    
+    # Set the clock to the current time plus seconds
+    time.clock_settime(clk_id, time_seconds + seconds)
+
+    # Print the new time
+    time_seconds = time.clock_gettime(clk_id)
+    # print("Current unix time is", time_seconds, "or", time.asctime(time.gmtime(time_seconds)), "in GMT")
+    return time_seconds
+
+
+class TestMonitoringOutput(unittest.TestCase):
+    def test_no_zpool(self):
+        """Test what happens if there is no zpool at all"""
+
+        return_info = monitor_snapshots_command()
+        self.assertEqual(return_info.stdout, b"CRIT: sanoid-test-1 has no daily snapshots at all!, CRIT: sanoid-test-1 has no hourly snapshots at all!, CRIT: sanoid-test-1 has no monthly snapshots at all!, CRIT: sanoid-test-2 has no daily snapshots at all!, CRIT: sanoid-test-2 has no hourly snapshots at all!, CRIT: sanoid-test-2 has no monthly snapshots at all!\n")
+        self.assertEqual(return_info.returncode, 0)
+
+class TestsWithZpool(unittest.TestCase):
+    """Tests that require a test zpool"""
+
+    def setUp(self):
+        """Set up the zpool"""
+        subprocess.run(["truncate", "-s", "512M", pool_disk_image1], check=True)
+        subprocess.run(["zpool", "create", "-f", pool_name1, pool_disk_image1], check=True)
+
+        subprocess.run(["truncate", "-s", "512M", pool_disk_image2], check=True)
+        subprocess.run(["zpool", "create", "-f", pool_name2, pool_disk_image2], check=True)
+
+        # Clear the snapshot cache in between
+        subprocess.run([sanoid_cmd, "--force-update"])
+
+    def tearDown(self):
+        """Clean up on either passed or failed tests"""
+        subprocess.run(["zpool", "export", pool_name1])
+        subprocess.run(["rm", "-f", pool_disk_image1])
+        subprocess.run(["zpool", "export", pool_name2])
+        subprocess.run(["rm", "-f", pool_disk_image2])
+        time.clock_settime(clk_id, starting_time)
+
+    def test_with_zpool_no_snapshots(self):
+        """Test what happens if there is a zpool, but with no snapshots"""
+
+        # Run sanoid --monitor-snapshots before doing anything else
+        return_info = monitor_snapshots_command()
+        self.assertEqual(return_info.stdout, b"CRIT: sanoid-test-1 has no daily snapshots at all!, CRIT: sanoid-test-1 has no hourly snapshots at all!, CRIT: sanoid-test-1 has no monthly snapshots at all!, CRIT: sanoid-test-2 has no daily snapshots at all!, CRIT: sanoid-test-2 has no hourly snapshots at all!, CRIT: sanoid-test-2 has no monthly snapshots at all!\n")
+        self.assertEqual(return_info.returncode, 0)
+
+    def test_immediately_after_running_sanoid(self):
+        """Test immediately after running sanoid --cron"""
+
+        run_sanoid_cron_command()
+        return_info = monitor_snapshots_command()
+        self.assertEqual(return_info.stdout, b"OK: all monitored datasets (sanoid-test-1, sanoid-test-2) have fresh snapshots\n")
+        self.assertEqual(return_info.returncode, 0)
+
+    def test_one_warning_hourly(self):
+        """Test one warning on hourly snapshots, no critical warnings, to check output and error status"""
+
+        run_sanoid_cron_command()
+        
+        # Advance 100 mins to trigger the hourly warning on sanoid-test-1 but nothing else
+        advance_time(100 * 60)
+        return_info = monitor_snapshots_command()
+        # Output should be something like: 
+        # WARN: sanoid-test-1 newest hourly snapshot is 1h 40m 0s old (should be < 1h 30m 0s)\n
+        # But we cannot be sure about the exact time as test execution could be different on
+        # different machines, so ignore the bits that may be different.
+        self.assertEqual(return_info.stdout[:49], b"WARN: sanoid-test-1 newest hourly snapshot is 1h ")
+        self.assertEqual(return_info.stdout[-30:], b"s old (should be < 1h 30m 0s)\n")
+        self.assertEqual(return_info.returncode, 0)
+
+    def test_two_criticals_hourly(self):
+        """Test two criticals (hourly), to check output and error status"""
+
+        run_sanoid_cron_command()
+        
+        # Advance 390 mins to trigger the hourly critical on both sanoid-test-1 and sanoid-test-2
+        advance_time(390 * 60)
+        return_info = monitor_snapshots_command()
+
+        # Output should be something like: 
+        # CRIT: sanoid-test-1 newest hourly snapshot is 6h 30m 1s old (should be < 6h 0m 0s), CRIT: sanoid-test-2 newest hourly snapshot is 6h 30m 1s old (should be < 6h 0m 0s)\n
+        # But we cannot be sure about the exact time as test execution could be different on
+        # different machines, so ignore the bits that may be different.
+        comma_location = return_info.stdout.find(b",")
+        self.assertEqual(return_info.stdout[:49], b"CRIT: sanoid-test-1 newest hourly snapshot is 6h ")
+        self.assertEqual(return_info.stdout[comma_location - 28:comma_location], b"s old (should be < 6h 0m 0s)")
+        self.assertEqual(return_info.stdout[comma_location:comma_location + 51], b", CRIT: sanoid-test-2 newest hourly snapshot is 6h ")
+        self.assertEqual(return_info.stdout[-29:], b"s old (should be < 6h 0m 0s)\n")
+        self.assertEqual(return_info.returncode, 0)
+
+    def test_two_criticals_hourly_two_warnings_daily(self):
+        """Test two criticals (hourly) and two warnings (daily), to check output and error status"""
+
+        run_sanoid_cron_command()
+        
+        # Advance more than 28 hours to trigger the daily warning on both sanoid-test-1 and sanoid-test-2
+        advance_time(29 * 60 * 60)
+        return_info = monitor_snapshots_command()
+
+        # Output should be something like: 
+        # CRIT: sanoid-test-1 newest hourly snapshot is 1d 5h 0m 0s old (should be < 6h 0m 0s), CRIT: sanoid-test-2 newest hourly snapshot is 1d 5h 0m 0s old (should be < 6h 0m 0s), WARN: sanoid-test-1 newest daily snapshot is 1d 5h 0m 0s old (should be < 1d 4h 0m 0s), WARN: sanoid-test-2 newest daily snapshot is 1d 5h 0m 0s old (should be < 1d 4h 0m 0s)\n
+        # But we cannot be sure about the exact time as test execution could be different on
+        # different machines, so ignore the bits that may be different.
+        print(return_info.stdout)
+        output_list = return_info.stdout.split(b", ")
+
+        self.assertEqual(output_list[0][:49], b"CRIT: sanoid-test-1 newest hourly snapshot is 1d ")
+        self.assertEqual(output_list[0][-28:], b"s old (should be < 6h 0m 0s)")
+        self.assertEqual(output_list[1][:49], b"CRIT: sanoid-test-2 newest hourly snapshot is 1d ")
+        self.assertEqual(output_list[1][-28:], b"s old (should be < 6h 0m 0s)")
+        
+        self.assertEqual(output_list[2][:48], b"WARN: sanoid-test-1 newest daily snapshot is 1d ")
+        self.assertEqual(output_list[2][-31:], b"s old (should be < 1d 4h 0m 0s)")
+        self.assertEqual(output_list[3][:48], b"WARN: sanoid-test-2 newest daily snapshot is 1d ")
+        self.assertEqual(output_list[3][-32:], b"s old (should be < 1d 4h 0m 0s)\n")
+
+        self.assertEqual(return_info.returncode, 0)
+
+
+if __name__ == '__main__':
+    unittest.main()

tests/5_monitor_snapshots_warn_dont_crit/run.sh

@@ -0,0 +1,18 @@
+#!/bin/bash
+set -x
+
+# this test will create pools in a number of states
+# and check the output text and return code of 
+# sanoid --monitor-snapshots
+
+. ../common/lib.sh
+
+# prepare
+setup
+checkEnvironment
+disableTimeSync
+
+# set timezone
+ln -sf /usr/share/zoneinfo/Europe/Vienna /etc/localtime
+
+python3 test_monitoring.py

tests/5_monitor_snapshots_warn_dont_crit/sanoid.conf

@@ -0,0 +1,41 @@
+[sanoid-test-1]
+	use_template = production
+
+[sanoid-test-2]
+	use_template = demo
+
+[template_production]
+	hourly = 36
+	daily = 30
+	monthly = 3
+	yearly = 0
+	autosnap = yes
+	autoprune = no
+	hourly_warn = 90m
+	hourly_crit = 360m
+	daily_warn = 28h
+	daily_crit = 32h
+	weekly_warn = 0
+	weekly_crit = 0
+	monthly_warn = 32d
+	monthly_crit = 40d
+	yearly_warn = 0
+	yearly_crit = 0
+	monitor_dont_warn = FALSE
+	monitor_dont_crit = yes
+	
+
+[template_demo]
+	daily = 60
+	hourly_warn = 290m
+	hourly_crit = 360m
+	daily_warn = 28h
+	daily_crit = 48h
+	weekly_warn = 0
+	weekly_crit = 0
+	monthly_warn = 32d
+	monthly_crit = 40d
+	yearly_warn = 0
+	yearly_crit = 0
+	monitor_dont_warn = Off
+	monitor_dont_crit = On

tests/5_monitor_snapshots_warn_dont_crit/test_monitoring.py

@@ -0,0 +1,163 @@
+#!/usr/bin/env python3
+
+# this software is licensed for use under the Free Software Foundation's GPL v3.0 license, as retrieved
+# from http://www.gnu.org/licenses/gpl-3.0.html on 2014-11-17.  A copy should also be available in this
+# project's Git repository at https://github.com/jimsalterjrs/sanoid/blob/master/LICENSE.
+
+
+import os
+import subprocess
+import time
+import unittest
+
+
+sanoid_cmd = os.environ.get("SANOID")
+pool_disk_image1 = "/zpool1.img"
+pool_name1 = "sanoid-test-1"
+pool_disk_image2 = "/zpool2.img"
+pool_name2 = "sanoid-test-2"
+
+clk_id = time.CLOCK_REALTIME
+starting_time = time.clock_gettime(clk_id)
+
+
+def monitor_snapshots_command():
+    """Runs sanoid --monitor-snapshots and returns a CompletedProcess instance"""
+    return_info = subprocess.run([sanoid_cmd,  "--monitor-snapshots"], capture_output=True)
+    return return_info
+    
+def run_sanoid_cron_command():
+    """Runs sanoid and returns a CompletedProcess instance"""
+    return_info = subprocess.run([sanoid_cmd,  "--cron", "--verbose"], capture_output=True, check=True)
+    return return_info
+
+def advance_time(seconds):
+    """Advances the system clock by seconds"""
+    
+    # Get the current time
+    clk_id = time.CLOCK_REALTIME
+    time_seconds = time.clock_gettime(clk_id)
+    # print("Current unix time is", time_seconds, "or", time.asctime(time.gmtime(time_seconds)), "in GMT")
+    
+    # Set the clock to the current time plus seconds
+    time.clock_settime(clk_id, time_seconds + seconds)
+
+    # Print the new time
+    time_seconds = time.clock_gettime(clk_id)
+    # print("Current unix time is", time_seconds, "or", time.asctime(time.gmtime(time_seconds)), "in GMT")
+    return time_seconds
+
+
+class TestMonitoringOutput(unittest.TestCase):
+    def test_no_zpool(self):
+        """Test what happens if there is no zpool at all"""
+
+        return_info = monitor_snapshots_command()
+        self.assertEqual(return_info.stdout, b"CRIT: sanoid-test-1 has no daily snapshots at all!, CRIT: sanoid-test-1 has no hourly snapshots at all!, CRIT: sanoid-test-1 has no monthly snapshots at all!, CRIT: sanoid-test-2 has no daily snapshots at all!, CRIT: sanoid-test-2 has no hourly snapshots at all!, CRIT: sanoid-test-2 has no monthly snapshots at all!\n")
+        self.assertEqual(return_info.returncode, 0)
+
+class TestsWithZpool(unittest.TestCase):
+    """Tests that require a test zpool"""
+
+    def setUp(self):
+        """Set up the zpool"""
+        subprocess.run(["truncate", "-s", "512M", pool_disk_image1], check=True)
+        subprocess.run(["zpool", "create", "-f", pool_name1, pool_disk_image1], check=True)
+
+        subprocess.run(["truncate", "-s", "512M", pool_disk_image2], check=True)
+        subprocess.run(["zpool", "create", "-f", pool_name2, pool_disk_image2], check=True)
+
+        # Clear the snapshot cache in between
+        subprocess.run([sanoid_cmd, "--force-update"])
+
+    def tearDown(self):
+        """Clean up on either passed or failed tests"""
+        subprocess.run(["zpool", "export", pool_name1])
+        subprocess.run(["rm", "-f", pool_disk_image1])
+        subprocess.run(["zpool", "export", pool_name2])
+        subprocess.run(["rm", "-f", pool_disk_image2])
+        time.clock_settime(clk_id, starting_time)
+
+    def test_with_zpool_no_snapshots(self):
+        """Test what happens if there is a zpool, but with no snapshots"""
+
+        # Run sanoid --monitor-snapshots before doing anything else
+        return_info = monitor_snapshots_command()
+        self.assertEqual(return_info.stdout, b"CRIT: sanoid-test-1 has no daily snapshots at all!, CRIT: sanoid-test-1 has no hourly snapshots at all!, CRIT: sanoid-test-1 has no monthly snapshots at all!, CRIT: sanoid-test-2 has no daily snapshots at all!, CRIT: sanoid-test-2 has no hourly snapshots at all!, CRIT: sanoid-test-2 has no monthly snapshots at all!\n")
+        self.assertEqual(return_info.returncode, 0)
+
+    def test_immediately_after_running_sanoid(self):
+        """Test immediately after running sanoid --cron"""
+
+        run_sanoid_cron_command()
+        return_info = monitor_snapshots_command()
+        self.assertEqual(return_info.stdout, b"OK: all monitored datasets (sanoid-test-1, sanoid-test-2) have fresh snapshots\n")
+        self.assertEqual(return_info.returncode, 0)
+
+    def test_one_warning_hourly(self):
+        """Test one warning on hourly snapshots, no critical warnings, to check output and error status"""
+
+        run_sanoid_cron_command()
+        
+        # Advance 100 mins to trigger the hourly warning on sanoid-test-1 but nothing else
+        advance_time(100 * 60)
+        return_info = monitor_snapshots_command()
+        # Output should be something like: 
+        # WARN: sanoid-test-1 newest hourly snapshot is 1h 40m 0s old (should be < 1h 30m 0s)\n
+        # But we cannot be sure about the exact time as test execution could be different on
+        # different machines, so ignore the bits that may be different.
+        self.assertEqual(return_info.stdout[:49], b"WARN: sanoid-test-1 newest hourly snapshot is 1h ")
+        self.assertEqual(return_info.stdout[-30:], b"s old (should be < 1h 30m 0s)\n")
+        self.assertEqual(return_info.returncode, 1)
+
+    def test_two_criticals_hourly(self):
+        """Test two criticals (hourly), to check output and error status"""
+
+        run_sanoid_cron_command()
+        
+        # Advance 390 mins to trigger the hourly critical on both sanoid-test-1 and sanoid-test-2
+        advance_time(390 * 60)
+        return_info = monitor_snapshots_command()
+
+        # Output should be something like: 
+        # CRIT: sanoid-test-1 newest hourly snapshot is 6h 30m 1s old (should be < 6h 0m 0s), CRIT: sanoid-test-2 newest hourly snapshot is 6h 30m 1s old (should be < 6h 0m 0s)\n
+        # But we cannot be sure about the exact time as test execution could be different on
+        # different machines, so ignore the bits that may be different.
+        comma_location = return_info.stdout.find(b",")
+        self.assertEqual(return_info.stdout[:49], b"CRIT: sanoid-test-1 newest hourly snapshot is 6h ")
+        self.assertEqual(return_info.stdout[comma_location - 28:comma_location], b"s old (should be < 6h 0m 0s)")
+        self.assertEqual(return_info.stdout[comma_location:comma_location + 51], b", CRIT: sanoid-test-2 newest hourly snapshot is 6h ")
+        self.assertEqual(return_info.stdout[-29:], b"s old (should be < 6h 0m 0s)\n")
+        self.assertEqual(return_info.returncode, 0)
+
+    def test_two_criticals_hourly_two_warnings_daily(self):
+        """Test two criticals (hourly) and two warnings (daily), to check output and error status"""
+
+        run_sanoid_cron_command()
+        
+        # Advance more than 28 hours to trigger the daily warning on both sanoid-test-1 and sanoid-test-2
+        advance_time(29 * 60 * 60)
+        return_info = monitor_snapshots_command()
+
+        # Output should be something like: 
+        # CRIT: sanoid-test-1 newest hourly snapshot is 1d 5h 0m 0s old (should be < 6h 0m 0s), CRIT: sanoid-test-2 newest hourly snapshot is 1d 5h 0m 0s old (should be < 6h 0m 0s), WARN: sanoid-test-1 newest daily snapshot is 1d 5h 0m 0s old (should be < 1d 4h 0m 0s), WARN: sanoid-test-2 newest daily snapshot is 1d 5h 0m 0s old (should be < 1d 4h 0m 0s)\n
+        # But we cannot be sure about the exact time as test execution could be different on
+        # different machines, so ignore the bits that may be different.
+        print(return_info.stdout)
+        output_list = return_info.stdout.split(b", ")
+
+        self.assertEqual(output_list[0][:49], b"CRIT: sanoid-test-1 newest hourly snapshot is 1d ")
+        self.assertEqual(output_list[0][-28:], b"s old (should be < 6h 0m 0s)")
+        self.assertEqual(output_list[1][:49], b"CRIT: sanoid-test-2 newest hourly snapshot is 1d ")
+        self.assertEqual(output_list[1][-28:], b"s old (should be < 6h 0m 0s)")
+        
+        self.assertEqual(output_list[2][:48], b"WARN: sanoid-test-1 newest daily snapshot is 1d ")
+        self.assertEqual(output_list[2][-31:], b"s old (should be < 1d 4h 0m 0s)")
+        self.assertEqual(output_list[3][:48], b"WARN: sanoid-test-2 newest daily snapshot is 1d ")
+        self.assertEqual(output_list[3][-32:], b"s old (should be < 1d 4h 0m 0s)\n")
+
+        self.assertEqual(return_info.returncode, 1)
+
+
+if __name__ == '__main__':
+    unittest.main()

tests/README.md

@@ -0,0 +1,31 @@
+### Requirements ###
+Tests must be run inside a virtual machine. This is for your own safety, as the tests may create and destroy zpools etc.
+
+A VM with 35GB of storage and 8 cores running Ubuntu 20.04 completes the tests in about 5 hours.  
+
+#### Packages ####
+The tests require the following packages to be installed in the VM (Ubuntu 20.04 package names are used, translate as appropriate):
+```
+zfsutils-linux
+libconfig-inifiles-perl
+libcapture-tiny-perl
+```
+```
+apt install zfsutils-linux libconfig-inifiles-perl libcapture-tiny-perl
+```
+
+#### Install sanoid within the VM ####
+Install sanoid within the VM, for example
+```
+apt install git
+git clone https://github.com/jimsalterjrs/sanoid.git
+mkdir /etc/sanoid/
+cp sanoid/sanoid.defaults.conf /etc/sanoid/
+```
+
+### Run the tests ##
+This requires root/sudo privileges.
+```
+cd sanoid/tests/
+./run-tests.sh
+```

tests/common/lib.sh

@@ -10,7 +10,7 @@ function setup {
     export SANOID="../../sanoid"
 
     # make sure that there is no cache file
-    rm -f /var/cache/sanoidsnapshots.txt
+    rm -f /var/cache/sanoid/snapshots.txt
 
     # install needed sanoid configuration files
     [ -f sanoid.conf ] && cp sanoid.conf /etc/sanoid/sanoid.conf

tests/run-tests.sh

@@ -1,6 +1,6 @@
 #!/bin/bash
 
-# run's all the available tests
+# runs all the available tests
 
 for test in $(find . -mindepth 1 -maxdepth 1 -type d -printf "%P\n" | sort -g); do
     if [ ! -x "${test}/run.sh" ]; then
@@ -17,8 +17,11 @@ for test in $(find . -mindepth 1 -maxdepth 1 -type d -printf "%P\n" | sort -g);
     cd "${test}"
     echo -n y | bash run.sh > "${LOGFILE}" 2>&1
 
-    if [ $? -eq 0 ]; then
+    ret=$?
+    if [ $ret -eq 0 ]; then
         echo "[PASS]"
+    elif [ $ret -eq 130 ]; then
+        echo "[SKIPPED]"
     else
         echo "[FAILED] (see ${LOGFILE})"
     fi

tests/syncoid/005_reset_resume_state/run.sh

@@ -28,6 +28,8 @@ zfs create -o mountpoint="${MOUNT_TARGET}" "${POOL_NAME}"/src
 
 dd if=/dev/urandom of="${MOUNT_TARGET}"/big_file bs=1M count=200
 
+sleep 1
+
 ../../../syncoid --debug --compress=none --source-bwlimit=2m "${POOL_NAME}"/src "${POOL_NAME}"/dst &
 syncoid_pid=$!
 sleep 5

tests/syncoid/006_reset_resume_state2/run.sh

@@ -28,6 +28,8 @@ zfs create -o mountpoint="${MOUNT_TARGET}" "${POOL_NAME}"/src
 
 dd if=/dev/urandom of="${MOUNT_TARGET}"/big_file bs=1M count=200
 
+sleep 1
+
 zfs snapshot "${POOL_NAME}"/src@big
 ../../../syncoid --debug --no-sync-snap --compress=none --source-bwlimit=2m "${POOL_NAME}"/src "${POOL_NAME}"/dst &
 syncoid_pid=$!

tests/syncoid/011_sync_out-of-order_snapshots/run.sh

@@ -7,9 +7,13 @@ set -e
 
 . ../../common/lib.sh
 
-POOL_IMAGE="/tmp/jimsalterjrs_sanoid_815.img"
+if [ -z "$ALLOW_INVASIVE_TESTS" ]; then
+  exit 130
+fi
+
+POOL_IMAGE="/tmp/syncoid-test-11.zpool"
 POOL_SIZE="64M"
-POOL_NAME="jimsalterjrs_sanoid_815"
+POOL_NAME="syncoid-test-11"
 
 truncate -s "${POOL_SIZE}" "${POOL_IMAGE}"
 

tests/syncoid/run-tests.sh

@@ -17,8 +17,11 @@ for test in $(find . -mindepth 1 -maxdepth 1 -type d -printf "%P\n" | sort -g);
     cd "${test}"
     echo | bash run.sh > "${LOGFILE}" 2>&1
 
-    if [ $? -eq 0 ]; then
+    ret=$?
+    if [ $ret -eq 0 ]; then
         echo "[PASS]"
+    elif [ $ret -eq 130 ]; then
+        echo "[SKIPPED]"
     else
         echo "[FAILED] (see ${LOGFILE})"
     fi