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

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

(cherry picked from commit 36d657ccc67ce0fb5dd1881458ffc8a748b8aa44)

4 files changed, 46 insertions, 13 deletions

diff --git a/src/conn/conn_log.c b/src/conn/conn_log.c
index 6cb8ba3d0f9..f83430735ef 100644
--- a/src/conn/conn_log.c
+++ b/src/conn/conn_log.c
@@ -545,8 +545,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 0e676d47b66..f84b147cb70 100644
--- a/src/include/log.h
+++ b/src/include/log.h
@@ -255,7 +255,8 @@ struct __wt_log {
 	uint64_t	 write_calls;		/* Calls to log_write */
 #endif
 
-	uint32_t	 flags;
+#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 b11cd55844d..8591818b5a3 100644
--- a/src/log/log.c
+++ b/src/log/log.c
@@ -775,6 +775,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;
@@ -847,8 +848,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.
@@ -1165,6 +1173,8 @@ __wt_log_open(WT_SESSION_IMPL *session)
 
 err:	if (logfiles != NULL)
 		__wt_log_files_free(session, logfiles, logcount);
+	if (ret == 0)
+		F_SET(log, WT_LOG_OPENED);
 	return (ret);
 }
 
@@ -1205,6 +1215,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);
 }
 
@@ -1818,9 +1829,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 2454aa6056b..92f65c540cf 100644
--- a/test/recovery/random-abort.c
+++ b/test/recovery/random-abort.c
@@ -44,7 +44,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						\
@@ -158,6 +161,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;
@@ -199,6 +203,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];
 
@@ -207,18 +212,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:
@@ -232,6 +241,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
@@ -246,9 +268,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);
 
 	/*
@@ -279,8 +299,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