rework interrupt-resume autotesting

instead of doing two runs for each journal entry, do one run for each
"write" operation, be it a journal entry or a writing driver call. this
saves runs between which no visible change occurred, which yields a 33%
improvement in runtime.

we now also exclude the final entry purge from the test, as it's really
kinda pointless, and we'd have to jump through additional hoops
(simulate an atomic commit of the state) to make it reliable in all
cases.

note that this also adds a few steps, which actually uncovered a bug in
the expunge sequencing.

amends efd72b85.

src/common.h

@@ -124,7 +124,7 @@ BIT_ENUM(
 // Global options
 extern int Verbosity;
 extern int DFlags;
-extern int JLimit;
+extern int JLimit, JCount;
 extern int UseFSync;
 
 // Global constants (inited by main())
@@ -132,6 +132,7 @@ extern int Pid;
 extern char Hostname[256];
 extern const char *Home;
 
+void countStep( void );
 void stats( void );
 
 /* util.c */

src/drv_proxy.c

@@ -212,6 +212,7 @@ proxy_@name@_cb( @decl_cb_args@void *aux )
 	@name@_cmd_t *cmd = (@name@_cmd_t *)aux;
 	proxy_store_t *ctx = cmd->ctx;
 
+	@count_step@
 	@print_cb_args_tpl@
 	cmd->callback( @pass_cb_args@cmd->callback_aux );
 	debug( "%s[% 2d] Callback leave @name@\n", ctx->label, cmd->tag );
@@ -251,6 +252,10 @@ static @type@proxy_@name@( store_t *gctx@decl_args@, void (*cb)( @decl_cb_args@v
 		debug( "  %s\n", box->string );
 //# END
 
+//# DEFINE create_box_counted 1
+
+//# DEFINE delete_box_counted 1
+
 //# DEFINE prepare_load_box_print_fmt_args , opts=%s
 //# DEFINE prepare_load_box_print_pass_args , fmt_opts( opts ).str
 //# DEFINE prepare_load_box_print_fmt_ret %s
@@ -313,13 +318,18 @@ static @type@proxy_@name@( store_t *gctx@decl_args@, void (*cb)( @decl_cb_args@v
 		fflush( stdout );
 	}
 //# END
+//# DEFINE store_msg_counted 1
 
 //# DEFINE set_msg_flags_checked 1
 //# DEFINE set_msg_flags_print_fmt_args , uid=%u, add=%s, del=%s
 //# DEFINE set_msg_flags_print_pass_args , cmd->uid, fmt_flags( cmd->add ).str, fmt_flags( cmd->del ).str
+//# DEFINE set_msg_flags_counted 1
 
 //# DEFINE trash_msg_print_fmt_args , uid=%u
 //# DEFINE trash_msg_print_pass_args , cmd->msg->uid
+//# DEFINE trash_msg_counted 1
+
+//# DEFINE close_box_counted 1
 
 //# DEFINE commit_cmds_print_args
 	proxy_flush_checked_cmds( ctx );

src/drv_proxy_gen.pl

@@ -176,7 +176,13 @@ for (@ptypes) {
 		$replace{'print_fmt_args'} = make_format($cmd_args);
 	}
 	for (keys %defines) {
-		$replace{$1} = delete $defines{$_} if (/^${cmd_name}_(.*)$/);
+		next if (!/^${cmd_name}_(.*)$/);
+		my ($key, $val) = ($1, delete $defines{$_});
+		if ($key eq 'counted') {
+			$replace{count_step} = "countStep();\n";
+		} else {
+			$replace{$key} = $val;
+		}
 	}
 	my %used;
 	my $text = $templates{$template};

src/main.c

@@ -132,6 +132,13 @@ crashHandler( int n )
 }
 #endif
 
+void
+countStep( void )
+{
+	if (!--JLimit)
+		exit( 100 );
+}
+
 int
 main( int argc, char **argv )
 {

src/run-tests.pl

@@ -783,10 +783,19 @@ sub test_impl($$$$)
 		exit 1;
 	}
 
-	my ($nj, $njl) = (undef, 0);
+	my ($nj, $njl, $nje) = (undef, 0, 0);
 	if ($$rtx{state} != $$sx{state}) {
 		$nj = readfile("near/.mbsyncstate.journal");
-		$njl = (@$nj - 1) * 2;
+		STEPS: {
+			for (reverse @$ret) {
+				if (/^### (\d+) steps, (\d+) entries ###$/) {
+					$njl = int($1) - 1;
+					$nje = int($2);
+					last STEPS;
+				}
+			}
+			die("Cannot extract step count.\n");
+		}
 
 		my ($jxc, $jret) = runsync($async, "-0 --no-expunge", "2-replay.log");
 		my $jrcs = readstate() if (!$jxc);
@@ -835,13 +844,15 @@ sub test_impl($$$$)
 		mkchan($sx);
 
 		my ($nxc, $nret) = runsync($async, "-Ts$l", "4-interrupt.log");
-		if ($nxc != (100 + ($l & 1)) << 8) {
+		if ($nxc != 100 << 8) {
 			print "Interrupting at step $l/$njl failed.\n";
 			print "Debug output:\n";
 			print @$nret;
 			exit 1;
 		}
 
+		my $pnnj = readfile("near/.mbsyncstate.journal");
+
 		($nxc, $nret) = runsync($async, "-Tj", "5-resume.log");
 		my $nrtx = readchan($$sx{state}) if (!$nxc);
 		if ($nxc || cmpchan($nrtx, $tx)) {
@@ -851,9 +862,9 @@ sub test_impl($$$$)
 			print "Options:\n";
 			print " [ ".join(", ", map('"'.qm($_).'"', @$sfx))." ]\n";
 			my $nnj = readfile("near/.mbsyncstate.journal");
-			my $ln = int($l / 2);
+			my $ln = $#$pnnj;
 			print "Journal:\n".join("", @$nnj[0..$ln])."-------\n".join("", @$nnj[($ln + 1)..$#$nnj])."\n";
-			print "Full journal:\n".join("", @$nj)."\n";
+			print "Full journal:\n".join("", @$nj[0..$nje])."=======\n".join("", @$nj[($nje + 1)..$#$nj])."\n";
 			if (!$nxc) {
 				print "Expected result:\n";
 				printchan($tx);

src/sync.c

@@ -1719,9 +1719,15 @@ box_closed_p2( sync_vars_t *svars, int t )
 	if (!(svars->state[t^1] & ST_CLOSED))
 		return;
 
-	// All the journalling done in this function is merely for the autotest -
-	// the operations are idempotent, and we're about to commit the new state
-	// right afterwards anyway.
+	// All logging done in this function is merely for the journal replay
+	// autotest - the operations are idempotent, and we're about to commit
+	// the new state right afterwards anyway. Therefore, it would also
+	// make no sense to cover it by the interrupt-resume autotest (which
+	// would also add unreasonable complexity, as the maxuid bumps and entry
+	// purge must be consistent).
+
+	if (DFlags & KEEPJOURNAL)
+		printf( "### %d steps, %d entries ###\n", -JLimit, JCount );
 
 	for (t = 0; t < 2; t++) {
 		// Committing maxuid is delayed until all messages were propagated, to

src/sync_state.c

@@ -439,8 +439,6 @@ jFprintf( sync_vars_t *svars, const char *msg, ... )
 {
 	va_list va;
 
-	if (JLimit && !--JLimit)
-		exit( 101 );
 	if (!svars->jfp) {
 		create_state( svars );
 		if (!(svars->jfp = fopen( svars->jname, svars->replayed ? "a" : "w" ))) {
@@ -454,8 +452,8 @@ jFprintf( sync_vars_t *svars, const char *msg, ... )
 	va_start( va, msg );
 	vFprintf( svars->jfp, msg, va );
 	va_end( va );
-	if (JLimit && !--JLimit)
-		exit( 100 );
+	countStep();
+	JCount++;
 }
 
 void

src/util.c

@@ -15,7 +15,7 @@
 
 int Verbosity = TERSE;
 int DFlags;
-int JLimit;
+int JLimit, JCount;
 int UseFSync = 1;
 
 int Pid;