Merge pull request #2464 from wiredtiger/wt-2356

WT-2356 Fix recovery bug in log_scan advancing.

5 files changed, 311 insertions, 27 deletions

diff --git a/src/log/log.c b/src/log/log.c
index 6e48bec8bea..ce2d7191491 100644
--- a/src/log/log.c
+++ b/src/log/log.c
@@ -1443,7 +1443,7 @@ __wt_log_scan(WT_SESSION_IMPL *session, WT_LSN *lsnp, uint32_t flags,
 	uint32_t cksum_calculate, cksum_tmp;
 	u_int i, logcount;
 	int firstrecord;
-	bool eol;
+	bool eol, partial_record;
 	char **logfiles;
 
 	conn = S2C(session);
@@ -1539,6 +1539,15 @@ __wt_log_scan(WT_SESSION_IMPL *session, WT_LSN *lsnp, uint32_t flags,
 	for (;;) {
 		if (rd_lsn.l.offset + allocsize > log_size) {
 advance:
+			if (rd_lsn.l.offset == log_size)
+				partial_record = false;
+			else
+				/*
+				 * See if there is anything non-zero at the
+				 * end of this log file.
+				 */
+				WT_ERR(__log_has_hole(session, log_fh,
+				    rd_lsn.l.offset, &partial_record));
 			/*
 			 * If we read the last record, go to the next file.
 			 */
@@ -1551,6 +1560,15 @@ advance:
 			if (LF_ISSET(WT_LOGSCAN_RECOVER))
 				WT_ERR(__log_truncate(session,
 				    &rd_lsn, WT_LOG_FILENAME, 1));
+			/*
+			 * If we had a partial record, we'll want to break
+			 * now after closing and truncating.  Although for now
+			 * log_truncate does not modify the LSN passed in,
+			 * this code does not assume it is unmodified after that
+			 * call which is why it uses the boolean set earlier.
+			 */
+			if (partial_record)
+				break;
 			WT_SET_LSN(&rd_lsn, rd_lsn.l.file + 1, 0);
 			/*
 			 * Avoid an error message when we reach end of log
@@ -1604,10 +1622,13 @@ advance:
 		if (reclen > allocsize) {
 			/*
 			 * The log file end could be the middle of this
-			 * log record.
+			 * log record.  If we have a partially written record
+			 * then this is considered the end of the log.
 			 */
-			if (rd_lsn.l.offset + rdup_len > log_size)
-				goto advance;
+			if (rd_lsn.l.offset + rdup_len > log_size) {
+				eol = true;
+				break;
+			}
 			/*
 			 * We need to round up and read in the full padded
 			 * record, especially for direct I/O.
diff --git a/test/recovery/Makefile.am b/test/recovery/Makefile.am
index 60f237dad10..35f8dd15823 100644
--- a/test/recovery/Makefile.am
+++ b/test/recovery/Makefile.am
@@ -1,14 +1,18 @@
 AM_CPPFLAGS = -I$(top_builddir) -I$(top_srcdir)/src/include \
     -I$(top_srcdir)/test/utility
 
-noinst_PROGRAMS = t
-t_SOURCES = recovery.c
-t_LDADD = $(top_builddir)/libwiredtiger.la
-t_LDFLAGS = -static
+noinst_PROGRAMS = random-abort truncated-log
+random_abort_SOURCES = random-abort.c
+random_abort_LDADD = $(top_builddir)/libwiredtiger.la
+random_abort_LDFLAGS = -static
+
+truncated_log_SOURCES = truncated-log.c
+truncated_log_LDADD = $(top_builddir)/libwiredtiger.la
+truncated_log_LDFLAGS = -static
 
 # Run this during a "make check" smoke test.
 TESTS = $(noinst_PROGRAMS)
 LOG_COMPILER = $(TEST_WRAPPER)
 
 clean-local:
-	rm -rf WiredTiger* *.core __*
+	rm -rf WT_TEST* *.core __*
diff --git a/test/recovery/recovery.c b/test/recovery/random-abort.c
index 5772865f030..ddcafbc80fd 100644
--- a/test/recovery/recovery.c
+++ b/test/recovery/random-abort.c
@@ -147,14 +147,14 @@ main(int argc, char *argv[])
 	uint32_t absent, count, timeout;
 	int ch, status, ret;
 	pid_t pid;
-	char *working_dir;
+	const char *working_dir;
 
 	if ((progname = strrchr(argv[0], DIR_DELIM)) == NULL)
 		progname = argv[0];
 	else
 		++progname;
 
-	working_dir = NULL;
+	working_dir = "WT_TEST.random-abort";
 	timeout = 10;
 	while ((ch = __wt_getopt(progname, argc, argv, "h:t:")) != EOF)
 		switch (ch) {
diff --git a/test/recovery/truncated-log.c b/test/recovery/truncated-log.c
new file mode 100644
index 00000000000..4add7a61f66
--- /dev/null
+++ b/test/recovery/truncated-log.c
@@ -0,0 +1,268 @@
+/*-
+ * Public Domain 2014-2016 MongoDB, Inc.
+ * Public Domain 2008-2014 WiredTiger, Inc.
+ *
+ * This is free and unencumbered software released into the public domain.
+ *
+ * Anyone is free to copy, modify, publish, use, compile, sell, or
+ * distribute this software, either in source code form or as a compiled
+ * binary, for any purpose, commercial or non-commercial, and by any
+ * means.
+ *
+ * In jurisdictions that recognize copyright laws, the author or authors
+ * of this software dedicate any and all copyright interest in the
+ * software to the public domain. We make this dedication for the benefit
+ * of the public at large and to the detriment of our heirs and
+ * successors. We intend this dedication to be an overt act of
+ * relinquishment in perpetuity of all present and future rights to this
+ * software under copyright law.
+ *
+ * THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND,
+ * EXPRESS OR IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF
+ * MERCHANTABILITY, FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT.
+ * IN NO EVENT SHALL THE AUTHORS BE LIABLE FOR ANY CLAIM, DAMAGES OR
+ * OTHER LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE,
+ * ARISING FROM, OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR
+ * OTHER DEALINGS IN THE SOFTWARE.
+ */
+
+#include <sys/wait.h>
+#include <errno.h>
+#include <signal.h>
+#include <stdio.h>
+#include <stdlib.h>
+#include <string.h>
+#ifndef _WIN32
+#include <unistd.h>
+#else
+/* snprintf is not supported on <= VS2013 */
+#define	snprintf _snprintf
+#endif
+
+#include <wiredtiger.h>
+
+#include "test_util.i"
+
+static char home[512];			/* Program working dir */
+static const char *progname;		/* Program name */
+static const char *uri = "table:main";
+
+#define	RECORDS_FILE "records"
+
+#define	ENV_CONFIG						\
+    "create,log=(file_max=100K,archive=false,enabled),"		\
+    "transaction_sync=(enabled,method=none)"
+#define	ENV_CONFIG_REC "log=(recover=on)"
+#define	LOG_FILE_1 "WiredTigerLog.0000000001"
+#define	MAX_VAL	4096
+
+#define	K_SIZE	16
+#define	V_SIZE	256
+
+static void
+usage(void)
+{
+	fprintf(stderr, "usage: %s [-h dir]\n", progname);
+	exit(EXIT_FAILURE);
+}
+
+/*
+ * Child process creates the database and table, and then writes data into
+ * the table until it is killed by the parent.
+ */
+static void
+fill_db(void)
+{
+	FILE *fp;
+	WT_CONNECTION *conn;
+	WT_CURSOR *cursor, *logc;
+	WT_LSN lsn, save_lsn;
+	WT_SESSION *session;
+	uint32_t i, max_key, min_key, units, unused;
+	int ret;
+	bool first;
+	char k[K_SIZE], v[V_SIZE];
+
+	/*
+	 * Run in the home directory so that the records file is in there too.
+	 */
+	chdir(home);
+	if ((ret = wiredtiger_open(NULL, NULL, ENV_CONFIG, &conn)) != 0)
+		testutil_die(ret, "wiredtiger_open");
+	if ((ret = conn->open_session(conn, NULL, NULL, &session)) != 0)
+		testutil_die(ret, "WT_CONNECTION:open_session");
+	if ((ret = session->create(session,
+	    uri, "key_format=S,value_format=S")) != 0)
+		testutil_die(ret, "WT_SESSION.create: %s", uri);
+	if ((ret =
+	    session->open_cursor(session, uri, NULL, NULL, &cursor)) != 0)
+		testutil_die(ret, "WT_SESSION.open_cursor: %s", uri);
+
+	/*
+	 * Keep a separate file with the records we wrote for checking.
+	 */
+	(void)unlink(RECORDS_FILE);
+	if ((fp = fopen(RECORDS_FILE, "w")) == NULL)
+		testutil_die(errno, "fopen");
+	/*
+	 * Set to no buffering.
+	 */
+	setvbuf(fp, NULL, _IONBF, 0);
+	save_lsn.l.file = 0;
+
+	/*
+	 * Write data into the table until we move to log file 2.
+	 * We do the calculation below so that we don't have to walk the
+	 * log for every record.
+	 *
+	 * Calculate about how many records should fit in the log file.
+	 * Subtract a bunch for metadata and file creation records.
+	 * Then subtract out a few more records to be conservative.
+	 */
+	units = (K_SIZE + V_SIZE) / 128 + 1;
+	min_key = 90000 / (units * 128) - 15;
+	max_key = min_key * 2;
+	first = true;
+	for (i = 0; i < max_key; ++i) {
+		snprintf(k, sizeof(k), "key%03d", (int)i);
+		snprintf(v, sizeof(v), "value%0*d",
+		    (int)(V_SIZE - strlen("value")), (int)i);
+		cursor->set_key(cursor, k);
+		cursor->set_value(cursor, v);
+		if ((ret = cursor->insert(cursor)) != 0)
+			testutil_die(ret, "WT_CURSOR.insert");
+
+		if (i > min_key) {
+			if ((ret = session->open_cursor(
+			    session, "log:", NULL, NULL, &logc)) != 0)
+				testutil_die(ret, "open_cursor: log");
+			if (save_lsn.l.file != 0) {
+				logc->set_key(logc,
+				    save_lsn.l.file, save_lsn.l.offset, 0);
+				if ((ret = logc->search(logc)) != 0)
+					testutil_die(errno, "search");
+			}
+			while ((ret = logc->next(logc)) == 0) {
+				if ((ret = logc->get_key(logc,
+				    &lsn.l.file, &lsn.l.offset, &unused)) != 0)
+					testutil_die(errno, "get_key");
+				if (lsn.l.file < 2)
+					save_lsn = lsn;
+				else {
+					if (first)
+						testutil_die(EINVAL,
+						    "min_key too high");
+					if (fprintf(fp,
+					    "%" PRIu32 " %" PRIu32 "\n",
+					    save_lsn.l.offset, i - 1) == -1)
+						testutil_die(errno, "fprintf");
+					fclose(fp);
+					abort();
+				}
+			}
+			first = false;
+		}
+	}
+}
+
+extern int __wt_optind;
+extern char *__wt_optarg;
+
+int
+main(int argc, char *argv[])
+{
+	FILE *fp;
+	WT_CONNECTION *conn;
+	WT_CURSOR *cursor;
+	WT_SESSION *session;
+	uint64_t new_offset, offset;
+	uint32_t count, max_key;
+	int ch, status, ret;
+	pid_t pid;
+	const char *working_dir;
+
+	if ((progname = strrchr(argv[0], DIR_DELIM)) == NULL)
+		progname = argv[0];
+	else
+		++progname;
+
+	working_dir = "WT_TEST.truncated-log";
+	while ((ch = __wt_getopt(progname, argc, argv, "h:")) != EOF)
+		switch (ch) {
+		case 'h':
+			working_dir = __wt_optarg;
+			break;
+		default:
+			usage();
+		}
+	argc -= __wt_optind;
+	argv += __wt_optind;
+	if (argc != 0)
+		usage();
+
+	testutil_work_dir_from_path(home, 512, working_dir);
+	testutil_make_work_dir(home);
+
+	/*
+	 * Fork a child to insert as many items.  We will then randomly
+	 * kill the child, run recovery and make sure all items we wrote
+	 * exist after recovery runs.
+	 */
+	if ((pid = fork()) < 0)
+		testutil_die(errno, "fork");
+
+	if (pid == 0) { /* child */
+		fill_db();
+		return (EXIT_SUCCESS);
+	}
+
+	/* parent */
+	/* Wait for child to kill itself. */
+	waitpid(pid, &status, 0);
+
+	/*
+	 * !!! If we wanted to take a copy of the directory before recovery,
+	 * this is the place to do it.
+	 */
+	chdir(home);
+	printf("Open database, run recovery and verify content\n");
+	if ((fp = fopen(RECORDS_FILE, "r")) == NULL)
+		testutil_die(errno, "fopen");
+	ret = fscanf(fp, "%" SCNu64 " %" SCNu32 "\n", &offset, &max_key);
+	fclose(fp);
+	if (ret != 2)
+		testutil_die(errno, "fscanf");
+	/*
+	 * The offset is the beginning of the last record.  Truncate to
+	 * the middle of that last record (i.e. ahead of that offset).
+	 */
+	new_offset = offset + V_SIZE;
+	printf("Parent: Truncate to %u\n", (uint32_t)new_offset);
+	if ((ret = truncate(LOG_FILE_1, (wt_off_t)new_offset)) != 0)
+		testutil_die(errno, "truncate");
+
+	if ((ret = wiredtiger_open(NULL, NULL, ENV_CONFIG_REC, &conn)) != 0)
+		testutil_die(ret, "wiredtiger_open");
+	if ((ret = conn->open_session(conn, NULL, NULL, &session)) != 0)
+		testutil_die(ret, "WT_CONNECTION:open_session");
+	if ((ret =
+	    session->open_cursor(session, uri, NULL, NULL, &cursor)) != 0)
+		testutil_die(ret, "WT_SESSION.open_cursor: %s", uri);
+
+	/*
+	 * For every key in the saved file, verify that the key exists
+	 * in the table after recovery.  Since we did write-no-sync, we
+	 * expect every key to have been recovered.
+	 */
+	count = 0;
+	while ((ret = cursor->next(cursor)) == 0)
+		++count;
+	if ((ret = conn->close(conn, NULL)) != 0)
+		testutil_die(ret, "WT_CONNECTION:close");
+	if (count > max_key) {
+		printf("expected %u records found %u\n", max_key, count);
+		return (EXIT_FAILURE);
+	}
+	printf("%u records verified\n", count);
+	return (EXIT_SUCCESS);
+}
diff --git a/test/utility/test_util.i b/test/utility/test_util.i
index 73141bc9be7..3b88d375381 100644
--- a/test/utility/test_util.i
+++ b/test/utility/test_util.i
@@ -66,26 +66,17 @@ testutil_die(int e, const char *fmt, ...)
  *	Creates the full intended work directory in buffer.
  */
 static inline void
-testutil_work_dir_from_path(char *buffer, size_t inputSize, char *dir)
+testutil_work_dir_from_path(char *buffer, size_t inputSize, const char *dir)
 {
 	/* If no directory is provided, use the default. */
-	if (dir == NULL) {
-		if (inputSize < sizeof(DEFAULT_DIR))
-			testutil_die(ENOMEM,
-			    "Not enough memory in buffer for directory %s%c%s",
-			    dir, DIR_DELIM, DEFAULT_DIR);
-
-		snprintf(buffer, inputSize, DEFAULT_DIR);
-		return;
-	}
-
-	/* Additional bytes for the directory and WT_TEST. */
-	if (inputSize < strlen(dir) + sizeof(DEFAULT_DIR) + sizeof(DIR_DELIM))
+	if (dir == NULL)
+		dir = DEFAULT_DIR;
+
+	if (inputSize < strlen(dir) + 1)
 		testutil_die(ENOMEM,
-		    "Not enough memory in buffer for directory %s%c%s",
-		    dir, DIR_DELIM, DEFAULT_DIR);
+		    "Not enough memory in buffer for directory %s", dir);
 
-	snprintf(buffer, inputSize, "%s%c%s", dir, DIR_DELIM, DEFAULT_DIR);
+	strcpy(buffer, dir);
 }
 
 /*