WT-2706 Fix lost log writes when switching files (#2803)

Fix a path that incorrectly returning success from log_write without writing a log record.

4 files changed, 46 insertions, 12 deletions

diff --git a/src/conn/conn_log.c b/src/conn/conn_log.c
index 5397962bc4f..1ae370ef2fa 100644
--- a/src/conn/conn_log.c
+++ b/src/conn/conn_log.c
@@ -544,8 +544,6 @@ restart:
 	while (i < WT_SLOT_POOL) {
 		save_i = i;
 		slot = &log->slot_pool[i++];
-		WT_ASSERT(session, slot->slot_state != 0 ||
-		    slot->slot_release_lsn.l.file >= log->write_lsn.l.file);
 		if (slot->slot_state != WT_LOG_SLOT_WRITTEN)
 			continue;
 		written[written_i].slot_index = save_i;
diff --git a/src/include/log.h b/src/include/log.h
index 11cbfbb3639..870c046252c 100644
--- a/src/include/log.h
+++ b/src/include/log.h
@@ -256,6 +256,8 @@ struct __wt_log {
 #ifdef HAVE_DIAGNOSTIC
 	uint64_t	 write_calls;		/* Calls to log_write */
 #endif
+#define	WT_LOG_OPENED	0x01		/* Log subsystem successfully open */
+	uint32_t	flags;
 };
 
 struct __wt_log_record {
diff --git a/src/log/log.c b/src/log/log.c
index 364447b874b..bf83c280d8d 100644
--- a/src/log/log.c
+++ b/src/log/log.c
@@ -790,6 +790,7 @@ __log_newfile(WT_SESSION_IMPL *session, bool conn_open, bool *created)
 {
 	WT_CONNECTION_IMPL *conn;
 	WT_DECL_RET;
+	WT_FH *log_fh;
 	WT_LOG *log;
 	WT_LSN end_lsn;
 	int yield_cnt;
@@ -862,8 +863,15 @@ __log_newfile(WT_SESSION_IMPL *session, bool conn_open, bool *created)
 		WT_RET(__wt_log_allocfile(
 		    session, log->fileid, WT_LOG_FILENAME));
 	}
+	/*
+	 * Since the file system clears the output file handle pointer before
+	 * searching the handle list and filling in the new file handle,
+	 * we must pass in a local file handle.  Otherwise there is a wide
+	 * window where another thread could see a NULL log file handle.
+	 */
 	WT_RET(__log_openfile(session,
-	    false, &log->log_fh, WT_LOG_FILENAME, log->fileid));
+	    false, &log_fh, WT_LOG_FILENAME, log->fileid));
+	WT_PUBLISH(log->log_fh, log_fh);
 	/*
 	 * We need to setup the LSNs.  Set the end LSN and alloc LSN to
 	 * the end of the header.
@@ -1176,6 +1184,8 @@ __wt_log_open(WT_SESSION_IMPL *session)
 	}
 
 err:	WT_TRET(__wt_fs_directory_list_free(session, &logfiles, logcount));
+	if (ret == 0)
+		F_SET(log, WT_LOG_OPENED);
 	return (ret);
 }
 
@@ -1215,6 +1225,7 @@ __wt_log_close(WT_SESSION_IMPL *session)
 		WT_RET(__wt_close(session, &log->log_dir_fh));
 		log->log_dir_fh = NULL;
 	}
+	F_CLR(log, WT_LOG_OPENED);
 	return (0);
 }
 
@@ -1855,9 +1866,10 @@ __wt_log_write(WT_SESSION_IMPL *session, WT_ITEM *record, WT_LSN *lsnp,
 	/*
 	 * An error during opening the logging subsystem can result in it
 	 * being enabled, but without an open log file.  In that case,
-	 * just return.
+	 * just return.  We can also have logging opened for reading in a
+	 * read-only database and attempt to write a record on close.
 	 */
-	if (log->log_fh == NULL)
+	if (!F_ISSET(log, WT_LOG_OPENED) || F_ISSET(conn, WT_CONN_READONLY))
 		return (0);
 	ip = record;
 	if ((compressor = conn->log_compressor) != NULL &&
diff --git a/test/recovery/random-abort.c b/test/recovery/random-abort.c
index 637e8cce168..a2fa940b1db 100644
--- a/test/recovery/random-abort.c
+++ b/test/recovery/random-abort.c
@@ -35,7 +35,10 @@ static char home[512];			/* Program working dir */
 static const char *progname;		/* Program name */
 static const char * const uri = "table:main";
 
-#define	NTHREADS	5
+#define	MAX_TH	12
+#define	MIN_TH	5
+#define	MAX_TIME	40
+#define	MIN_TIME	10
 #define	RECORDS_FILE	"records-%u"
 
 #define	ENV_CONFIG						\
@@ -147,6 +150,7 @@ fill_db(uint32_t nth)
 	if ((ret = session->close(session, NULL)) != 0)
 		testutil_die(ret, "WT_SESSION:close");
 
+	printf("Create %" PRIu32 " writer threads\n", nth);
 	for (i = 0; i < nth; ++i) {
 		td[i].conn = conn;
 		td[i].start = (UINT64_MAX / nth) * i;
@@ -188,6 +192,7 @@ main(int argc, char *argv[])
 	uint32_t absent, count, i, nth, timeout;
 	int ch, status, ret;
 	pid_t pid;
+	bool rand_th, rand_time;
 	const char *working_dir;
 	char fname[64], kname[64];
 
@@ -196,18 +201,22 @@ main(int argc, char *argv[])
 	else
 		++progname;
 
-	working_dir = "WT_TEST.random-abort-many";
-	timeout = 10;
-	nth = NTHREADS;
+	nth = MIN_TH;
+	rand_th = rand_time = true;
+	timeout = MIN_TIME;
+	working_dir = "WT_TEST.random-abort";
+
 	while ((ch = __wt_getopt(progname, argc, argv, "h:T:t:")) != EOF)
 		switch (ch) {
 		case 'h':
 			working_dir = __wt_optarg;
 			break;
 		case 'T':
+			rand_th = false;
 			nth = (uint32_t)atoi(__wt_optarg);
 			break;
 		case 't':
+			rand_time = false;
 			timeout = (uint32_t)atoi(__wt_optarg);
 			break;
 		default:
@@ -221,6 +230,19 @@ main(int argc, char *argv[])
 	testutil_work_dir_from_path(home, 512, working_dir);
 	testutil_make_work_dir(home);
 
+	__wt_random_init_seed(NULL, &rnd);
+	if (rand_time) {
+		timeout = __wt_random(&rnd) % MAX_TIME;
+		if (timeout < MIN_TIME)
+			timeout = MIN_TIME;
+	}
+	if (rand_th) {
+		nth = __wt_random(&rnd) % MAX_TH;
+		if (nth < MIN_TH)
+			nth = MIN_TH;
+	}
+	printf("Parent: Create %u threads; sleep %" PRIu32 " seconds\n",
+	    nth, timeout);
 	/*
 	 * Fork a child to insert as many items.  We will then randomly
 	 * kill the child, run recovery and make sure all items we wrote
@@ -235,9 +257,7 @@ main(int argc, char *argv[])
 	}
 
 	/* parent */
-	__wt_random_init(&rnd);
 	/* Sleep for the configured amount of time before killing the child. */
-	printf("Parent: sleep %" PRIu32 " seconds, then kill child\n", timeout);
 	sleep(timeout);
 
 	/*
@@ -268,8 +288,10 @@ main(int argc, char *argv[])
 	absent = count = 0;
 	for (i = 0; i < nth; ++i) {
 		snprintf(fname, sizeof(fname), RECORDS_FILE, i);
-		if ((fp = fopen(fname, "r")) == NULL)
+		if ((fp = fopen(fname, "r")) == NULL) {
+			fprintf(stderr, "Failed to open %s. i %u\n", fname, i);
 			testutil_die(errno, "fopen");
+		}
 
 		/*
 		 * For every key in the saved file, verify that the key exists