First draft of logging functionality.

First draft of logging functionality.

[david]

The patches following this message are my first attempt at
implementing atomic logging for notmuch.  The idea is that such logs
could be useful in synchronizing notmuch instances.

Feedback of any kind is welcome. I'm particularly interested in
comments about the log format and performance.

In my tests, logging adds about a 10% speed penalty (tagging ~3700
messages) if enabled. I'd be curious if people for whom tagging is
slow could tell me if they take a bigger hit. If you want to test, add
a stanza like

[log]
tags = /path/to/logfile

to your notmuch config.

About the format, I am currently using

seconds-since-epoch json-quoted-message-id json-quoted-plus-minus-tag

I know some of you will not be thrilled with the quoting format; I'm
open to other ideas, but this is what was already existing in notmuch
code.  At the moment I wanted to push the quoting fairly far down the
stack and use the same for all potential logging, but perhaps this is
too much "design by convenient implementation".

Canadian-Thanksgiving-Greetings,

David

[PATCH 1/3] Initial implementation of low level logging routines.

[david]

[-- Warning: decoded text below may be mangled, UTF-8 assumed --]
[-- Attachment #1: Type: text/plain, Size: 4540 bytes --]

From: David Bremner <bremner@unb.ca>

notmuch_log_open: open a log file; just a wrapper around open(2)
notmuch_log_append: atomically append a buffer (character array) to a log file

Based on per-write file locking, performance will have to be tested.
---
 Makefile.local   |    1 +
 notmuch-client.h |   10 +++++
 notmuch-config.c |   15 ++++++++
 notmuch-log.c    |  102 ++++++++++++++++++++++++++++++++++++++++++++++++++++++
 4 files changed, 128 insertions(+), 0 deletions(-)
 create mode 100644 notmuch-log.c

diff --git a/Makefile.local b/Makefile.local
index ade8412..8dbda15 100644
--- a/Makefile.local
+++ b/Makefile.local
@@ -240,6 +240,7 @@ notmuch_client_srcs =		\
 	notmuch-config.c	\
 	notmuch-count.c		\
 	notmuch-dump.c		\
+	notmuch-log.c		\
 	notmuch-new.c		\
 	notmuch-reply.c		\
 	notmuch-restore.c	\
diff --git a/notmuch-client.h b/notmuch-client.h
index 20be43b..0422b1c 100644
--- a/notmuch-client.h
+++ b/notmuch-client.h
@@ -191,6 +191,16 @@ notmuch_config_set_new_tags (notmuch_config_t *config,
 			     const char *new_tags[],
 			     size_t length);
 
+const char *
+notmuch_config_get_log_path (notmuch_config_t *config,
+			     const char *name);
+
+int
+notmuch_log_open (const char *path);
+
+notmuch_status_t
+notmuch_log_append (int file_desc, const char *buffer, size_t len);
+
 notmuch_bool_t
 debugger_is_active (void);
 
diff --git a/notmuch-config.c b/notmuch-config.c
index cf30603..c01e8f4 100644
--- a/notmuch-config.c
+++ b/notmuch-config.c
@@ -562,3 +562,18 @@ notmuch_config_set_new_tags (notmuch_config_t *config,
     config->new_tags = NULL;
 }
 
+const char *
+notmuch_config_get_log_path (notmuch_config_t *config, const char *name)
+{
+    char *path, *rpath;
+
+    path= g_key_file_get_string (config->key_file,
+				 "log", name, NULL);
+    if (path != NULL) {
+	rpath = talloc_strdup (config, path);
+	free (path);
+	return rpath;
+    } else {
+	return NULL;
+    }
+}
diff --git a/notmuch-log.c b/notmuch-log.c
new file mode 100644
index 0000000..c4ddcd3
--- /dev/null
+++ b/notmuch-log.c
@@ -0,0 +1,102 @@
+
+/* notmuch - Not much of an email program, (just index and search)
+ *
+ * Copyright © 2010 David Bremner
+ *
+ * This program is free software: you can redistribute it and/or modify
+ * it under the terms of the GNU General Public License as published by
+ * the Free Software Foundation, either version 3 of the License, or
+ * (at your option) any later version.
+ *
+ * This program is distributed in the hope that it will be useful,
+ * but WITHOUT ANY WARRANTY; without even the implied warranty of
+ * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+ * GNU General Public License for more details.
+ *
+ * You should have received a copy of the GNU General Public License
+ * along with this program.  If not, see http://www.gnu.org/licenses/ .
+ *
+ * Author: David Bremner <david@tethera.net>
+ */
+
+#include <sys/types.h>
+#include <sys/stat.h>
+#include <fcntl.h>
+#include <unistd.h>
+
+#include "notmuch-client.h"
+/*
+   Look a key up in the config file; open the corresponding file as a
+   log.
+
+   Return a file descriptor to the open log file, or -1 if an error
+   occurs.
+  */
+
+int
+notmuch_log_open (const char *path)
+{
+    int fd;
+
+    fd = open (path, O_CREAT|O_WRONLY|O_APPEND);
+    if (fd < 0) {
+	fprintf (stderr, "Failed to open %s: %s\n",
+		 path, strerror (errno));
+    }
+
+    return fd;
+}
+
+notmuch_status_t
+notmuch_log_append (int file_desc, const char *buffer, size_t len){
+
+    struct flock lock;
+
+    lock.l_type = F_WRLCK;
+    lock.l_whence = SEEK_SET;
+    lock.l_start = 0;
+    lock.l_len = 0;
+
+    if (fcntl (file_desc, F_SETLKW, &lock) != 0) {
+	fprintf (stderr, "Failed to lock  %s\n",
+		 strerror (errno));
+
+	return NOTMUCH_STATUS_FILE_ERROR;
+    }
+
+    while (len > 0)
+    {
+	int written;
+
+	written = write(file_desc, buffer, len);
+	if (written < 0 || (written == 0 && errno !=0))
+	{
+	    fprintf (stderr, "Failed to write %zd characters: %s\n",
+		     len, strerror (errno));
+
+	    return NOTMUCH_STATUS_FILE_ERROR;
+	}
+
+	len -= written;
+	buffer += written;
+
+    }
+
+    if (fdatasync (file_desc) != 0) {
+	fprintf (stderr, "Failed to sync:  %s\n",
+		 strerror (errno));
+
+	return NOTMUCH_STATUS_FILE_ERROR;
+    }
+
+    lock.l_type=F_UNLCK;
+
+    if (fcntl (file_desc, F_SETLK, &lock) != 0) {
+	fprintf (stderr, "Failed to unlock:  %s\n",
+		 strerror (errno));
+
+	return NOTMUCH_STATUS_FILE_ERROR;
+    }
+
+    return NOTMUCH_STATUS_SUCCESS;
+}
-- 
1.7.1

[PATCH 2/3] notmuch-log.c: Add a function to log a pair of strings with a timestamp.

[david]

From: David Bremner <bremner@unb.ca>

Since the function is supposed to work for any pair of strings, this
means some form of quoting seems necessary. I decided to re-use the
json quoting routines for convenience.
---
 notmuch-client.h |    4 ++++
 notmuch-log.c    |   18 ++++++++++++++++++
 2 files changed, 22 insertions(+), 0 deletions(-)

diff --git a/notmuch-client.h b/notmuch-client.h
index 0422b1c..a849e21 100644
--- a/notmuch-client.h
+++ b/notmuch-client.h
@@ -201,6 +201,10 @@ notmuch_log_open (const char *path);
 notmuch_status_t
 notmuch_log_append (int file_desc, const char *buffer, size_t len);
 
+notmuch_status_t
+notmuch_log_string_pair (void *ctx, int file_desc,
+			 const char *str1, const char *str2);
+
 notmuch_bool_t
 debugger_is_active (void);
 
diff --git a/notmuch-log.c b/notmuch-log.c
index c4ddcd3..b0aca95 100644
--- a/notmuch-log.c
+++ b/notmuch-log.c
@@ -23,6 +23,8 @@
 #include <sys/stat.h>
 #include <fcntl.h>
 #include <unistd.h>
+#include <time.h>
+#include <talloc.h>
 
 #include "notmuch-client.h"
 /*
@@ -100,3 +102,19 @@ notmuch_log_append (int file_desc, const char *buffer, size_t len){
 
     return NOTMUCH_STATUS_SUCCESS;
 }
+
+notmuch_status_t
+notmuch_log_string_pair(void *ctx, int log_fd,
+			const char *string1, const char *string2){
+
+    char *quoted1, *quoted2, *buffer;
+
+    quoted1 = json_quote_str (ctx, string1);
+    quoted2 = json_quote_str (ctx, string2);
+
+    buffer = talloc_asprintf (ctx, "%ld %s %s\n",
+			      (long)time(NULL),
+			      quoted1, quoted2);
+
+    return notmuch_log_append (log_fd, buffer, strlen(buffer));
+}
-- 
1.7.1

[PATCH 3/3] notmuch-tag.c: Add tag logging.

[david]

From: David Bremner <bremner@unb.ca>

logging of tags is enabled by adding a stanza like

[log]
tags = /some/path/you/can/write/to

to your notmuch config.

Note that we intentionally do the logging after the database
transaction is finished.
---
 notmuch-tag.c |   31 +++++++++++++++++++++++++++++++
 1 files changed, 31 insertions(+), 0 deletions(-)

diff --git a/notmuch-tag.c b/notmuch-tag.c
index fd54bc7..f24d1e4 100644
--- a/notmuch-tag.c
+++ b/notmuch-tag.c
@@ -46,6 +46,9 @@ notmuch_tag_command (void *ctx, unused (int argc), unused (char *argv[]))
     notmuch_message_t *message;
     struct sigaction action;
     int i;
+    int log_fd = -1;
+    notmuch_bool_t enable_log = FALSE;
+    const char *log_path;
 
     /* Setup our handler for SIGINT */
     memset (&action, 0, sizeof (struct sigaction));
@@ -96,6 +99,17 @@ notmuch_tag_command (void *ctx, unused (int argc), unused (char *argv[]))
     if (config == NULL)
 	return 1;
 
+    log_path = notmuch_config_get_log_path (config, "tags");
+
+    if (log_path != NULL) {
+      enable_log = TRUE;
+
+      log_fd = notmuch_log_open(log_path);
+
+      if (log_fd < 0)
+	return 1;
+    }
+
     notmuch = notmuch_database_open (notmuch_config_get_database_path (config),
 				     NOTMUCH_DATABASE_MODE_READ_WRITE);
     if (notmuch == NULL)
@@ -114,10 +128,15 @@ notmuch_tag_command (void *ctx, unused (int argc), unused (char *argv[]))
 	 notmuch_messages_valid (messages) && !interrupted;
 	 notmuch_messages_move_to_next (messages))
     {
+	const char *message_id = NULL;
 	message = notmuch_messages_get (messages);
 
 	notmuch_message_freeze (message);
 
+	if (enable_log)
+	    message_id = talloc_strdup (ctx,
+					notmuch_message_get_message_id (message));
+
 	for (i = 0; i < remove_tags_count; i++)
 	    notmuch_message_remove_tag (message,
 					argv[remove_tags[i]] + 1);
@@ -128,6 +147,18 @@ notmuch_tag_command (void *ctx, unused (int argc), unused (char *argv[]))
 	notmuch_message_thaw (message);
 
 	notmuch_message_destroy (message);
+
+	if (enable_log) {
+	    for (i = 0; i < remove_tags_count; i++)
+		notmuch_log_string_pair (ctx, log_fd,
+					 message_id,
+					 argv[remove_tags[i]]);
+
+	    for (i = 0; i < add_tags_count; i++)
+		notmuch_log_string_pair (ctx, log_fd,
+					 message_id,
+					 argv[add_tags[i]]);
+	}
     }
 
     notmuch_query_destroy (query);
-- 
1.7.1

Re: First draft of logging functionality.

[Michal Sojka]

On Mon, 11 Oct 2010, david@tethera.net wrote:
> The patches following this message are my first attempt at
> implementing atomic logging for notmuch.  The idea is that such logs
> could be useful in synchronizing notmuch instances.
> 
> Feedback of any kind is welcome. I'm particularly interested in
> comments about the log format and performance.

Hi David,

I'm not sure whether implementing logging facility outside of notmuch
library is a good thing. If somebody will use a third-party tool (such
as python bindings) to manipulate his tags, they won't appear in the
log.

-Michal

Re: First draft of logging functionality.

[David Bremner]

On Tue, 12 Oct 2010 11:06:17 +0200, Michal Sojka <sojkam1@fel.cvut.cz> wrote:

> I'm not sure whether implementing logging facility outside of notmuch
> library is a good thing. If somebody will use a third-party tool (such
> as python bindings) to manipulate his tags, they won't appear in the
> log.

Yeah, thanks for that. I had been worrying about the same thing, but
your message helped clarify things for me.

I guess log files should be opened in notmuch_database_open, and the
actual logging in this case could happen from notmuch_message_add_tag.

From an atomicity point of view it might make more sense to store up a
list of log lines, and dump them all from _notmuch_message_sync.
One could attach a log buffer to a message, and flush that atomically
when syncing the message back to the database. In this context, it is a
little more tedious to have more than one log file. 

d

Re: First draft of logging functionality.

[Michal Sojka]

On Tue, 12 Oct 2010, David Bremner wrote:
> On Tue, 12 Oct 2010 11:06:17 +0200, Michal Sojka <sojkam1@fel.cvut.cz> wrote:
> 
> > I'm not sure whether implementing logging facility outside of notmuch
> > library is a good thing. If somebody will use a third-party tool (such
> > as python bindings) to manipulate his tags, they won't appear in the
> > log.
> 
> Yeah, thanks for that. I had been worrying about the same thing, but
> your message helped clarify things for me.
> 
> I guess log files should be opened in notmuch_database_open, and the
> actual logging in this case could happen from notmuch_message_add_tag.
> 
> From an atomicity point of view it might make more sense to store up a
> list of log lines, and dump them all from _notmuch_message_sync.
> One could attach a log buffer to a message, and flush that atomically
> when syncing the message back to the database.

Yes, the above sounds good to me.

> In this context, it is a little more tedious to have more than one log
> file.

Why multiple log files? You may have the buffers for message logs in
memory, right?

Another thing to keep in mind is how it will behave with 'notmuch
restore'. If do dump followed by resore you will have a very long log
with no useful information in it. Some optimization may be employed here.

Bye
-Michal

Re: First draft of logging functionality.

[David Bremner]

On Tue, 12 Oct 2010 13:38:42 +0200, Michal Sojka <sojkam1@fel.cvut.cz> wrote:
> 
> Why multiple log files? You may have the buffers for message logs in
> memory, right?

Well, maybe one log for tag operations, one for adding messages, etc... 
But it is easy enough to mark log entries by what they are.

> 
> Another thing to keep in mind is how it will behave with 'notmuch
> restore'. If do dump followed by resore you will have a very long log
> with no useful information in it. Some optimization may be employed here.
> 

Yes. This seems hard to optimize internally, but I was thinking of some
"log compression" function that comes up with a minimal equivalent set
of operations. I had in mind that this could be used to sync:
concatenate all the logs, and then compress to a minimal set of
operations.  This is still not completely thought out...
Another issue is that the buffer could get rather big during a restore,
but this is presumably fixable by flushing it if it gets too large.

All the best,

David

Re: First draft of logging functionality.

[Rob Browning]

david@tethera.net writes:

> The patches following this message are my first attempt at
> implementing atomic logging for notmuch.  The idea is that such logs
> could be useful in synchronizing notmuch instances.

For this to be completely safe, I suspect it may need to be adjusted to
do write ahead logging or something similar.  Otherwise operations could
be lost.

i.e. notmuch would atomically and safely write the intended (tag)
operation to the log, then perform the tag.  On startup, notmuch would
need to scan the log to detect and apply operations that hadn't been
fully completed (presumably due to a crash).

More generally, while thinking about sync/logging a few days ago, I
wondered about using sqlite.  That would help with atomicity, rollback,
synchronizing multiple readers/writers, etc.  It might also make
operations more efficient once we implement all the features we want.

For example, with the log information in sqlite, a separate notmuch sync
to another machine could be reading from the log (and with limitations,
writing) in parallel with normal notmuch operations.  Depending on how
we decide to handle sync with multiple peers, the log may also need to
track which peers have seen what, prune appropriately, etc.

Of course sqlite may not be appropriate, and would require performance
testing, etc., but we should probably think about the features we'll
eventually want, and consider how much work they're likely to require
with any given approach, regardless.

Hope this helps
-- 
Rob Browning
rlb @defaultvalue.org and @debian.org
GPG as of 2002-11-03 14DD 432F AE39 534D B592 F9A0 25C8 D377 8C7E 73A4

Second draft of logging patches

[david]

Here is my second try at logging, taking into account the feedback I
got from Rob and Michal.  There is definitely some tidying to do; in
particular I know the protoypes in public headers need
documentation. Also, I should add a configuration option to
enable configuration by command or something like that.

It does do write-ahead logging for tag changes, based on calls to
notmuch_message_(freeze|thaw).

It is more or less hardcoded to output to .notmuch/log

At the moment the buffering is line by line, but in principle this
just needs to be changed in one place (the call to notmuch_log_open).

Currently logging is disabled by default, unless a call to
notmuch_database_open_log is made. In the long run, if we keep this
code, then maybe the API of notmuch_database_open should be
modified to optionally enable logging.

[PATCH 1/4] Initial implementation of low level logging routines.

[david]

[-- Warning: decoded text below may be mangled, UTF-8 assumed --]
[-- Attachment #1: Type: text/plain, Size: 11451 bytes --]

From: David Bremner <bremner@unb.ca>

notmuch_log_open: open a log file; return an opaque "log descriptor"

notmuch_log_words: log words, escaping spaces and newlines, and appending a newline.

Log format is space delimited, and line oriented.  Escaping log text
is currently based on a slightly simplified version of
json_quote_chararray in ../json.c. This is probably overkill.

notmuch_log_transaction_(start|finish): log a transaction identifier
and depth.

Nested transactions are supported, so that this aligns with
notmuch_message_(freeze|thaw).  The are not too well tested though,
since I don't know when they arise.
---
 lib/Makefile.local |    1 +
 lib/log-private.h  |   13 +++
 lib/log.c          |  289 ++++++++++++++++++++++++++++++++++++++++++++++++++++
 lib/notmuch.h      |   23 ++++
 notmuch-client.h   |    4 +
 notmuch-config.c   |   15 +++
 6 files changed, 345 insertions(+), 0 deletions(-)
 create mode 100644 lib/log-private.h
 create mode 100644 lib/log.c

diff --git a/lib/Makefile.local b/lib/Makefile.local
index a60ef98..d7e8f41 100644
--- a/lib/Makefile.local
+++ b/lib/Makefile.local
@@ -46,6 +46,7 @@ extra_cflags += -I$(dir) -fPIC
 libnotmuch_c_srcs =		\
 	$(notmuch_compat_srcs)	\
 	$(dir)/libsha1.c	\
+	$(dir)/log.c		\
 	$(dir)/message-file.c	\
 	$(dir)/messages.c	\
 	$(dir)/sha1.c		\
diff --git a/lib/log-private.h b/lib/log-private.h
new file mode 100644
index 0000000..1af05dd
--- /dev/null
+++ b/lib/log-private.h
@@ -0,0 +1,13 @@
+
+#ifndef NOTMUCH_LOG_PRIVATE_H
+#define NOTMUCH_LOG_PRIVATE_H
+#include "notmuch.h"
+struct _notmuch_log {
+  int file_desc;
+  char *buffer;
+  char *txn_id;
+  int txn_depth;
+  notmuch_log_buffering_t buffering;
+};
+
+#endif
diff --git a/lib/log.c b/lib/log.c
new file mode 100644
index 0000000..31f1e62
--- /dev/null
+++ b/lib/log.c
@@ -0,0 +1,289 @@
+
+/* notmuch - Not much of an email program, (just index and search)
+ *
+ * Copyright © 2010 David Bremner
+ *
+ * This program is free software: you can redistribute it and/or modify
+ * it under the terms of the GNU General Public License as published by
+ * the Free Software Foundation, either version 3 of the License, or
+ * (at your option) any later version.
+ *
+ * This program is distributed in the hope that it will be useful,
+ * but WITHOUT ANY WARRANTY; without even the implied warranty of
+ * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+ * GNU General Public License for more details.
+ *
+ * You should have received a copy of the GNU General Public License
+ * along with this program.  If not, see http://www.gnu.org/licenses/ .
+ *
+ * Author: David Bremner <david@tethera.net>
+ */
+
+#include <sys/types.h>
+#include <sys/stat.h>
+#include <fcntl.h>
+#include <unistd.h>
+#include <errno.h>
+#include <string.h>
+#include <talloc.h>
+#include <stdarg.h>
+
+#include "log-private.h"
+#include "notmuch.h"
+
+/*
+ * Return a file descriptor to the open log file, or -1 if an error
+ * occurs.
+ *
+ */
+
+notmuch_log_t *
+notmuch_log_open (void *ctx,const char *path, notmuch_log_buffering_t buffering)
+{
+    int fd;
+    notmuch_log_t *log;
+
+    log=talloc (ctx, notmuch_log_t);
+    if (log==NULL)
+	return NULL;
+
+    fd = open (path, O_CREAT|O_WRONLY|O_APPEND, S_IRUSR|S_IWUSR|S_IRGRP|S_IROTH);
+    if (fd < 0) {
+	fprintf (stderr, "Failed to open %s: %s\n",
+		 path, strerror (errno));
+	return NULL;
+    }
+
+    log->file_desc = fd;
+    log->buffer = NULL;
+    log->txn_id = NULL;
+    log->txn_depth = 0;
+    log->buffering = buffering;
+    return log;
+}
+
+static notmuch_status_t
+_log_write (int file_desc, const char *buffer, size_t len){
+
+    struct flock lock;
+
+    lock.l_type = F_WRLCK;
+    lock.l_whence = SEEK_SET;
+    lock.l_start = 0;
+    lock.l_len = 0;
+
+    if (fcntl (file_desc, F_SETLKW, &lock) != 0) {
+	fprintf (stderr, "Failed to lock  %s\n",
+		 strerror (errno));
+
+	return NOTMUCH_STATUS_FILE_ERROR;
+    }
+
+    while (len > 0)
+    {
+	int written;
+
+	written = write(file_desc, buffer, len);
+	if (written < 0 || (written == 0 && errno !=0))
+	{
+	    fprintf (stderr, "Failed to write %zd characters: %s\n",
+		     len, strerror (errno));
+
+	    return NOTMUCH_STATUS_FILE_ERROR;
+	}
+
+	len -= written;
+	buffer += written;
+
+    }
+
+    if (fdatasync (file_desc) != 0) {
+	fprintf (stderr, "Failed to sync:  %s\n",
+		 strerror (errno));
+
+	return NOTMUCH_STATUS_FILE_ERROR;
+    }
+
+    lock.l_type=F_UNLCK;
+
+    if (fcntl (file_desc, F_SETLK, &lock) != 0) {
+	fprintf (stderr, "Failed to unlock:  %s\n",
+		 strerror (errno));
+
+	return NOTMUCH_STATUS_FILE_ERROR;
+    }
+
+    return NOTMUCH_STATUS_SUCCESS;
+}
+
+void
+notmuch_log_sync (notmuch_log_t *log)
+{
+    if (log->buffer) {
+	_log_write(log->file_desc, log->buffer, strlen (log->buffer));
+	talloc_free(log->buffer);
+	log->buffer=NULL;
+    }
+
+};
+
+
+/* This function was derived from the print_string_ptr function of
+ * cJSON (http://cjson.sourceforge.net/) and is used by permission of
+ * the following license:
+ *
+ * Copyright (c) 2009 Dave Gamble
+ *
+ * Permission is hereby granted, free of charge, to any person obtaining a copy
+ * of this software and associated documentation files (the "Software"), to deal
+ * in the Software without restriction, including without limitation the rights
+ * to use, copy, modify, merge, publish, distribute, sublicense, and/or sell
+ * copies of the Software, and to permit persons to whom the Software is
+ * furnished to do so, subject to the following conditions:
+ *
+ * The above copyright notice and this permission notice shall be included in
+ * all copies or substantial portions of the Software.
+ *
+ * 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 OR COPYRIGHT HOLDERS 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.
+ */
+
+static char *
+_log_escape_chararray(const void *ctx, const char *str, const size_t len)
+{
+    const char *ptr;
+    char *ptr2;
+    char *out;
+    size_t loop;
+    size_t required;
+
+    for (loop = 0, required = 0, ptr = str;
+	 loop < len;
+	 loop++, required++, ptr++) {
+	if ((unsigned char)(*ptr) <= ' ')
+	    required++;
+    }
+
+    /*
+     * + 1 for trailing NULL.
+     */
+    out = talloc_array (ctx, char, required + 1);
+
+    ptr = str;
+    ptr2 = out;
+
+    for (loop = 0; loop < len; loop++) {
+	if ((unsigned char)(*ptr) > 32 && *ptr != '\"' && *ptr != '\\') {
+		*ptr2++ = *ptr++;
+	    } else {
+		*ptr2++ = '\\';
+		switch (*ptr++) {
+		    case ' ':   *ptr2++ = ' ';	break;
+		    case '\\':	*ptr2++ = '\\';	break;
+		    case '\b':	*ptr2++ = 'b';	break;
+		    case '\f':	*ptr2++ = 'f';	break;
+		    case '\n':	*ptr2++ = 'n';	break;
+		    case '\r':	*ptr2++ = 'r';	break;
+		    case '\t':	*ptr2++ = 't';	break;
+		    default:	 ptr2--;	break;
+		}
+	    }
+    }
+    *ptr2++ = '\0';
+
+    return out;
+}
+
+static char*
+_log_escape_string (void *ctx, const char *str)
+{
+    return _log_escape_chararray (ctx, str, strlen(str));
+}
+
+/*
+ * Log a series of strings as a space delimited line.  Spaces and
+ * backslashes will be escaped by adding a backslash in front.
+ */
+
+static notmuch_status_t
+_log_append_string (notmuch_log_t *log, const char *str)
+{
+    if (log->buffer == NULL) {
+	log->buffer = talloc_strdup (log, str);
+    } else {
+	log->buffer = talloc_strdup_append (log->buffer, str);
+    }
+
+    if (log->buffer == NULL){
+	return NOTMUCH_STATUS_OUT_OF_MEMORY;
+    }
+
+    if (log->buffering == NOTMUCH_LOG_BUFFER_NONE)
+	notmuch_log_sync(log);
+
+    return NOTMUCH_STATUS_SUCCESS;
+}
+
+
+/*
+ *  Log a null terminated list of strings as a single space delimited log line.
+ *  spaces and newlines are escaped.
+ */
+
+void
+notmuch_log_words (notmuch_log_t *log, const char *word, ...)
+{
+    va_list args;
+    const char *str;
+    char *timestamp;
+
+    timestamp = talloc_asprintf (log, "%ld", (long)time(NULL));
+    _log_append_string(log,timestamp);
+    talloc_free(timestamp);
+
+    va_start (args, word);
+
+    for (str = word; str != NULL; str = va_arg (args, const char *)) {
+	_log_append_string (log, " ");
+	_log_append_string(log, _log_escape_string (log, str));
+    }
+
+    va_end(args);
+
+    _log_append_string(log, "\n");
+    if (log->buffering <= NOTMUCH_LOG_BUFFER_LINE)
+	notmuch_log_sync(log);
+
+};
+
+void
+notmuch_log_start_transaction (notmuch_log_t *log)
+{
+    /* XXX This should probably be something like a uuid */
+    if (log->txn_depth == 0) {
+	log->txn_id = talloc_asprintf (log, "%ld", random());
+    }
+    log->txn_depth++;
+
+    notmuch_log_words(log,"TX_START",
+		      talloc_asprintf (log, "%s.%d", log->txn_id, log->txn_depth));
+};
+
+void
+notmuch_log_finish_transaction (notmuch_log_t *log)
+{
+    notmuch_log_words(log,"TX_END",
+		      talloc_asprintf (log, "%s.%d", log->txn_id, log->txn_depth));
+
+    log->txn_depth--;
+
+    if (log->txn_depth == 0){
+	talloc_free (log->txn_id);
+	log->txn_id = NULL;
+    }
+};
diff --git a/lib/notmuch.h b/lib/notmuch.h
index 505ad19..1da84aa 100644
--- a/lib/notmuch.h
+++ b/lib/notmuch.h
@@ -119,6 +119,7 @@ typedef struct _notmuch_message notmuch_message_t;
 typedef struct _notmuch_tags notmuch_tags_t;
 typedef struct _notmuch_directory notmuch_directory_t;
 typedef struct _notmuch_filenames notmuch_filenames_t;
+typedef struct _notmuch_log notmuch_log_t;
 
 /* Create a new, empty notmuch database located at 'path'.
  *
@@ -1123,6 +1124,28 @@ notmuch_filenames_move_to_next (notmuch_filenames_t *filenames);
 void
 notmuch_filenames_destroy (notmuch_filenames_t *filenames);
 
+
+typedef enum _notmuch_log_buffer {
+  NOTMUCH_LOG_BUFFER_NONE = 0,
+  NOTMUCH_LOG_BUFFER_LINE = 1,
+  NOTMUCH_LOG_BUFFER_USER = 2
+} notmuch_log_buffering_t;
+
+notmuch_log_t *
+notmuch_log_open (void *ctx, const char *path, notmuch_log_buffering_t buffering);
+
+
+void
+notmuch_log_sync (notmuch_log_t *log);
+
+void
+notmuch_log_words (notmuch_log_t *log, const char *word, ...);
+void
+notmuch_log_start_transaction (notmuch_log_t *log);
+
+void
+notmuch_log_finish_transaction (notmuch_log_t *log);
+
 NOTMUCH_END_DECLS
 
 #endif
diff --git a/notmuch-client.h b/notmuch-client.h
index 20be43b..0be679d 100644
--- a/notmuch-client.h
+++ b/notmuch-client.h
@@ -191,6 +191,10 @@ notmuch_config_set_new_tags (notmuch_config_t *config,
 			     const char *new_tags[],
 			     size_t length);
 
+const char *
+notmuch_config_get_log_path (notmuch_config_t *config,
+			     const char *name);
+
 notmuch_bool_t
 debugger_is_active (void);
 
diff --git a/notmuch-config.c b/notmuch-config.c
index cf30603..c01e8f4 100644
--- a/notmuch-config.c
+++ b/notmuch-config.c
@@ -562,3 +562,18 @@ notmuch_config_set_new_tags (notmuch_config_t *config,
     config->new_tags = NULL;
 }
 
+const char *
+notmuch_config_get_log_path (notmuch_config_t *config, const char *name)
+{
+    char *path, *rpath;
+
+    path= g_key_file_get_string (config->key_file,
+				 "log", name, NULL);
+    if (path != NULL) {
+	rpath = talloc_strdup (config, path);
+	free (path);
+	return rpath;
+    } else {
+	return NULL;
+    }
+}
-- 
1.7.1

[PATCH 2/4] Add log component to database struct.

[david]

From: David Bremner <bremner@unb.ca>

- add accessor required because the notmuch database struct is opaque

- add a function notmuch_database_open_log to open a log file and
associate it with an open database.  The reasoning is that this is
preferable to breaking the notmuch_database_open API at this point.
---
 lib/database-private.h |    4 +++-
 lib/database.cc        |   36 ++++++++++++++++++++++++++++++++++++
 lib/notmuch.h          |   12 ++++++++++++
 3 files changed, 51 insertions(+), 1 deletions(-)

diff --git a/lib/database-private.h b/lib/database-private.h
index bd72f67..da4a72c 100644
--- a/lib/database-private.h
+++ b/lib/database-private.h
@@ -31,7 +31,7 @@
 #include <inttypes.h>
 
 #include "notmuch-private.h"
-
+#include "log-private.h"
 #include <xapian.h>
 
 struct _notmuch_database {
@@ -39,6 +39,8 @@ struct _notmuch_database {
 
     char *path;
 
+    notmuch_log_t *log;
+
     notmuch_bool_t needs_upgrade;
     notmuch_database_mode_t mode;
     Xapian::Database *xapian_db;
diff --git a/lib/database.cc b/lib/database.cc
index e4ac970..d453a0f 100644
--- a/lib/database.cc
+++ b/lib/database.cc
@@ -683,6 +683,10 @@ notmuch_database_open (const char *path,
 	    prefix_t *prefix = &PROBABILISTIC_PREFIX[i];
 	    notmuch->query_parser->add_prefix (prefix->name, prefix->prefix);
 	}
+
+	/* by default, logging is disabled */
+	notmuch->log = NULL;
+
     } catch (const Xapian::Error &error) {
 	fprintf (stderr, "A Xapian exception occurred opening database: %s\n",
 		 error.get_msg().c_str());
@@ -718,12 +722,44 @@ notmuch_database_close (notmuch_database_t *notmuch)
     talloc_free (notmuch);
 }
 
+/* Attempt to open a log file in the same location as the xapian
+ * database.
+ *
+ * Caller should pass an open notmuch database to it.
+ */
+
+notmuch_status_t
+notmuch_database_open_log (notmuch_database_t *notmuch)
+{
+
+    char *log_path;
+
+    log_path = talloc_asprintf(notmuch, "%s/.notmuch/log",
+			       notmuch_database_get_path (notmuch));
+
+    if (log_path == NULL)
+	return NOTMUCH_STATUS_OUT_OF_MEMORY;
+
+    notmuch->log =  notmuch_log_open (notmuch, log_path, NOTMUCH_LOG_BUFFER_LINE);
+    if (notmuch->log == NULL)
+	return NOTMUCH_STATUS_FILE_ERROR;
+
+    talloc_free(log_path);
+    return NOTMUCH_STATUS_SUCCESS;
+}
+
 const char *
 notmuch_database_get_path (notmuch_database_t *notmuch)
 {
     return notmuch->path;
 }
 
+notmuch_log_t *
+notmuch_database_get_log (notmuch_database_t *notmuch)
+{
+    return notmuch->log;
+}
+
 unsigned int
 notmuch_database_get_version (notmuch_database_t *notmuch)
 {
diff --git a/lib/notmuch.h b/lib/notmuch.h
index 1da84aa..54d839a 100644
--- a/lib/notmuch.h
+++ b/lib/notmuch.h
@@ -171,6 +171,14 @@ typedef enum {
 notmuch_database_t *
 notmuch_database_open (const char *path,
 		       notmuch_database_mode_t mode);
+/*
+ * Open the log file associated with a database.
+ *
+ * Caller should pass an open database.
+ */
+
+notmuch_status_t
+notmuch_database_open_log (notmuch_database_t *notmuch);
 
 /* Close the given notmuch database, freeing all associated
  * resources. See notmuch_database_open. */
@@ -188,6 +196,10 @@ notmuch_database_get_path (notmuch_database_t *database);
 unsigned int
 notmuch_database_get_version (notmuch_database_t *database);
 
+/* Return the log descriptor of the current database; NULL if no log is open */
+notmuch_log_t *
+notmuch_database_get_log (notmuch_database_t *database);
+
 /* Does this database need to be upgraded before writing to it?
  *
  * If this function returns TRUE then no functions that modify the
-- 
1.7.1

[PATCH 3/4] Add logging to low level message handling routines.

[david]

From: David Bremner <bremner@unb.ca>

This might not be ideal from the point of view of "atomic"
transactions, but it is transparent to the caller of the library.
---
 lib/message.cc |   30 ++++++++++++++++++++++++++++++
 1 files changed, 30 insertions(+), 0 deletions(-)

diff --git a/lib/message.cc b/lib/message.cc
index 71f5619..0385e68 100644
--- a/lib/message.cc
+++ b/lib/message.cc
@@ -600,12 +600,17 @@ void
 _notmuch_message_sync (notmuch_message_t *message)
 {
     Xapian::WritableDatabase *db;
+    notmuch_log_t *log;
 
     if (message->notmuch->mode == NOTMUCH_DATABASE_MODE_READ_ONLY)
 	return;
 
     db = static_cast <Xapian::WritableDatabase *> (message->notmuch->xapian_db);
     db->replace_document (message->doc_id, message->doc);
+
+    log = notmuch_database_get_log(message->notmuch);
+    if (log)
+	notmuch_log_sync (log);
 }
 
 /* Ensure that 'message' is not holding any file object open. Future
@@ -635,10 +640,16 @@ _notmuch_message_add_term (notmuch_message_t *message,
 {
 
     char *term;
+    notmuch_log_t *log;
 
     if (value == NULL)
 	return NOTMUCH_PRIVATE_STATUS_NULL_POINTER;
 
+    log=notmuch_database_get_log(message->notmuch);
+    if (log)
+	notmuch_log_words (log,"+", prefix_name, value,
+			   notmuch_message_get_message_id (message), NULL);
+
     term = talloc_asprintf (message, "%s%s",
 			    _find_prefix (prefix_name), value);
 
@@ -691,10 +702,16 @@ _notmuch_message_remove_term (notmuch_message_t *message,
 			      const char *value)
 {
     char *term;
+    notmuch_log_t *log;
 
     if (value == NULL)
 	return NOTMUCH_PRIVATE_STATUS_NULL_POINTER;
 
+    log=notmuch_database_get_log(message->notmuch);
+    if (log)
+	notmuch_log_words (log,"-", prefix_name, value,
+			   notmuch_message_get_message_id (message), NULL);
+
     term = talloc_asprintf (message, "%s%s",
 			    _find_prefix (prefix_name), value);
 
@@ -806,6 +823,7 @@ notmuch_status_t
 notmuch_message_freeze (notmuch_message_t *message)
 {
     notmuch_status_t status;
+    notmuch_log_t* log;
 
     status = _notmuch_database_ensure_writable (message->notmuch);
     if (status)
@@ -813,6 +831,10 @@ notmuch_message_freeze (notmuch_message_t *message)
 
     message->frozen++;
 
+    log = notmuch_database_get_log (message->notmuch);
+    if (log)
+      notmuch_log_start_transaction (log);
+
     return NOTMUCH_STATUS_SUCCESS;
 }
 
@@ -820,6 +842,7 @@ notmuch_status_t
 notmuch_message_thaw (notmuch_message_t *message)
 {
     notmuch_status_t status;
+    notmuch_log_t* log;
 
     status = _notmuch_database_ensure_writable (message->notmuch);
     if (status)
@@ -827,12 +850,19 @@ notmuch_message_thaw (notmuch_message_t *message)
 
     if (message->frozen > 0) {
 	message->frozen--;
+
+	log = notmuch_database_get_log (message->notmuch);
+	if (log)
+	    notmuch_log_finish_transaction (log);
+
 	if (message->frozen == 0)
 	    _notmuch_message_sync (message);
+
 	return NOTMUCH_STATUS_SUCCESS;
     } else {
 	return NOTMUCH_STATUS_UNBALANCED_FREEZE_THAW;
     }
+
 }
 
 void
-- 
1.7.1

[PATCH 4/4] Enable logging in notmuch-tag.c

[david]

From: David Bremner <bremner@unb.ca>

Currently a separate function must be called to enable logging; this API is subject to change.
---
 notmuch-tag.c |    5 +++++
 1 files changed, 5 insertions(+), 0 deletions(-)

diff --git a/notmuch-tag.c b/notmuch-tag.c
index fd54bc7..bd7bfbc 100644
--- a/notmuch-tag.c
+++ b/notmuch-tag.c
@@ -101,6 +101,11 @@ notmuch_tag_command (void *ctx, unused (int argc), unused (char *argv[]))
     if (notmuch == NULL)
 	return 1;
 
+    if (notmuch_database_open_log(notmuch) != NOTMUCH_STATUS_SUCCESS){
+	fprintf (stderr, "Failed to open log\n");
+	return 1;
+    }
+
     query = notmuch_query_create (notmuch, query_string);
     if (query == NULL) {
 	fprintf (stderr, "Out of memory.\n");
-- 
1.7.1

Re: Second draft of logging patches

[David Bremner]

On Sun, 24 Oct 2010 18:01:02 -0300, david@tethera.net wrote:
> Here is my second try at logging, taking into account the feedback I
> got from Rob and Michal.  There is definitely some tidying to do; in
> particular I know the protoypes in public headers need
> documentation. Also, I should add a configuration option to
> enable configuration by command or something like that.

I had a thought of a possibly interesting application of the (yet to be
written) log playback code. It could be use to implement a simple
queuing system where commands are only logged but not actually run on
the database. I'm not sure about the performance implications, but it
could be interesting because it eliminates the need to have a server
running in order to eliminate write contention for the tag database.
The "queue runner" could be as simple as a cron job, or it could be
something spawned by one of the queue operations; the point would be
that queueing could continue while the snapshot of the queue was run.

d

Re: Second draft of logging patches

[Michal Sojka]

On Wed, 10 Nov 2010, David Bremner wrote:
> On Sun, 24 Oct 2010 18:01:02 -0300, david@tethera.net wrote:
> > Here is my second try at logging, taking into account the feedback I
> > got from Rob and Michal.  There is definitely some tidying to do; in
> > particular I know the protoypes in public headers need
> > documentation. Also, I should add a configuration option to
> > enable configuration by command or something like that.
> 
> I had a thought of a possibly interesting application of the (yet to be
> written) log playback code. It could be use to implement a simple
> queuing system where commands are only logged but not actually run on
> the database. I'm not sure about the performance implications, but it
> could be interesting because it eliminates the need to have a server
> running in order to eliminate write contention for the tag database.
> The "queue runner" could be as simple as a cron job, or it could be
> something spawned by one of the queue operations; the point would be
> that queueing could continue while the snapshot of the queue was run.

Hi, I think this could be very interesting and that it could make the
tagging operation asynchronous and thus faster as was suggested by
Sebastian in id:"87k4l5whwe.fsf@SSpaeth.de".

In this case, however, the queuing should happen in the client, not in
the library.

-Michal

Re: Second draft of logging patches

[David Bremner]

On Sat, 13 Nov 2010 06:25:57 +0100, Michal Sojka <sojkam1@fel.cvut.cz> wrote:
> On Wed, 10 Nov 2010, David Bremner wrote:
> > I had a thought of a possibly interesting application of the (yet to be
> > written) log playback code. It could be use to implement a simple
> > queuing system where commands are only logged but not actually run on
> > the database. 

> Hi, I think this could be very interesting and that it could make the
> tagging operation asynchronous and thus faster as was suggested by
> Sebastian in id:"87k4l5whwe.fsf@SSpaeth.de".
> 
> In this case, however, the queuing should happen in the client, not in
> the library.

Agreed. The current implementation of automagically logging things in
the library would be undesirable here. That specific thing shouldn't be
too hard to change. Also worth thinking about is (optionally) using the
Maildir to log most tag changes; Maildirs are designed (imperfectly, but
still) to support simulataneous writes.  The database could then catch
up by reading the Maildir.

d