[PATCH 00/22] Standardize c/r error reporting (v2)

[PATCH 00/22] Standardize c/r error reporting (v2)

[serue-r/Jw6+rmf7HQT0dZR+AlfA]

From: Serge E. Hallyn <serue-r/Jw6+rmf7HQT0dZR+AlfA@public.gmane.org>

This patchset does the following:
        1. defines ckpt_error()
        2. allows users to pass a logfd into sys_checkpoint and
           sys_restart
        3. Switches ckpt_write_err() to accepting a single enhanced
           format string, instead of two separate formats.
        4. Has ckpt_write_err() call ckpt_error() to also log the
           error in the user-provided logfile and syslog.

Every ckpt_error() message is prefixed by current's global pid, current's
virtual pid, number of bytes read/written, and the ctx->errno.

I'm sending just the meaningful patches this time:

	0001-Make-__ckpt_generate_fmt-public.patch
	0002-Add-format-and-message-buffers-to-ctx-and-make-err_s.patch
	0003-switch-ckpt_generate_err-to-use-ctx-fields.patch
	0004-Change-to-the-new-enhanced-error-string-format.patch
	0013-add-logfd-to-c-r-api.patch
	0014-define-ckpt_error-and-implement-ckpt_do_write_msg.patch
	0015-explain-locking-for-write_err_msg.patch

The full rebased, re-split patchset can be seen at:
	http://git.kernel.org/gitweb.cgi?p=linux/kernel/git/sergeh/linux-cr.git;a=shortlog;h=refs/heads/debuglog-clean
The patches which I am not sending are all just changing the the callers of
ckpt_write_err() or ckpt_debug().

You can see all the changes relative to the patchset I sent yesterday by
looking at the non-rebased branch at:
	http://git.kernel.org/gitweb.cgi?p=linux/kernel/git/sergeh/linux-cr.git;a=shortlog;h=refs/heads/debuglog-nonrebased

-serge

[PATCH 01/22] Make __ckpt_generate_fmt public

[serue-r/Jw6+rmf7HQT0dZR+AlfA]

From: Serge E. Hallyn <serue-r/Jw6+rmf7HQT0dZR+AlfA@public.gmane.org>

Move it to checkpoint/sys.c, call it ckpt_generate_fmt, make it
non-static.  It will be used later by ckpt_error, which is used
during restart as well as checkpoint.

Signed-off-by: Serge E. Hallyn <serue-r/Jw6+rmf7HQT0dZR+AlfA@public.gmane.org>
---
 checkpoint/checkpoint.c    |   90 +-------------------------------------------
 checkpoint/sys.c           |   87 ++++++++++++++++++++++++++++++++++++++++++
 include/linux/checkpoint.h |    2 +
 3 files changed, 90 insertions(+), 89 deletions(-)

diff --git a/checkpoint/checkpoint.c b/checkpoint/checkpoint.c
index 6eb8f3b..d0ffd0d 100644
--- a/checkpoint/checkpoint.c
+++ b/checkpoint/checkpoint.c
@@ -96,94 +96,6 @@ int ckpt_write_string(struct ckpt_ctx *ctx, char *str, int len)
 	return ckpt_write_obj_type(ctx, str, len, CKPT_HDR_STRING);
 }
 
-/*
- * __ckpt_generate_fmt - generate standard checkpoint error message
- * @ctx: checkpoint context
- * @fmt0: c/r-format string
- * @fmt: message format
- *
- * This generates a unified format of checkpoint error messages, to
- * ease (after the failure) inspection by userspace tools. It converts
- * the (printf) message @fmt into a new format: "[PREFMT]: fmt".
- *
- * PREFMT is constructed from @fmt0 by subtituting format snippets
- * according to the contents of @fmt0.  The format characters in
- * @fmt0 can be E (error), O (objref), P (pointer), S (string) and
- * V (variable/symbol). For example, E will generate a "err %d" in
- * PREFMT (see prefmt_array below).
- *
- * If @fmt0 begins with T, PREFMT will begin with "pid %d tsk %s"
- * with the pid and the tsk->comm of the currently checkpointed task.
- * The latter is taken from ctx->tsk, and is it the responsbilility of
- * the caller to have a valid pointer there (in particular, functions
- * that iterate on the processes: collect_objects, checkpoint_task,
- * and tree_count_tasks).
- *
- * The caller of ckpt_write_err() and _ckpt_write_err() must provide
- * the additional variabes, in order, to match the @fmt0 (except for
- * the T key), e.g.:
- *
- *   ckpt_writ_err(ctx, "TEO", "FILE flags %d", err, objref, flags);
- *
- * Here, T is simply passed, E expects an integer (err), O expects an
- * integer (objref), and the last argument matches the format string.
- */
-static char *__ckpt_generate_fmt(struct ckpt_ctx *ctx, char *fmt0, char *fmt)
-{
-	static int warn_notask = 0;
-	static int warn_prefmt = 0;
-	char *format;
-	int i, j, len = 0;
-
-	static struct {
-		char key;
-		char *fmt;
-	} prefmt_array[] = {
-		{ 'E', "err %d" },
-		{ 'O', "obj %d" },
-		{ 'P', "ptr %p" },
-		{ 'V', "sym %pS" },
-		{ 'S', "str %s" },
-		{ 0, "??? %pS" },
-	};
-
-	/*
-	 * 17 for "pid %d" (plus space)
-	 * 21 for "tsk %s" (tsk->comm)
-	 * up to 8 per varfmt entry
-	 */
-	format = kzalloc(37 + 8 * strlen(fmt0) + strlen(fmt), GFP_KERNEL);
-	if (!format)
-		return NULL;
-
-	format[len++] = '[';
-
-	if (fmt0[0] == 'T') {
-		if (ctx->tsk)
-			len = sprintf(format, "pid %d tsk %s ",
-				      task_pid_vnr(ctx->tsk), ctx->tsk->comm);
-		else if (warn_notask++ < 5)
-			printk(KERN_ERR "c/r: no target task set\n");
-		fmt0++;
-	}
-
-	for (i = 0; i < strlen(fmt0); i++) {
-		for (j = 0; prefmt_array[j].key; j++)
-			if (prefmt_array[j].key == fmt0[i])
-				break;
-		if (!prefmt_array[j].key && warn_prefmt++ < 5)
-			printk(KERN_ERR "c/r: unknown prefmt %c\n", fmt0[i]);
-		len += sprintf(&format[len], "%s ", prefmt_array[j].fmt);
-	}
-
-	if (len > 1)
-		sprintf(&format[len-1], "]: %s", fmt);  /* erase last space */
-	else
-		sprintf(format, "%s", fmt);
-
-	return format;
-}
-
 /* see _ckpt_generate_fmt for information on @fmt0 */
 static void __ckpt_generate_err(struct ckpt_ctx *ctx, char *fmt0,
 				char *fmt, va_list ap)
@@ -193,7 +105,7 @@ static void __ckpt_generate_err(struct ckpt_ctx *ctx, char *fmt0,
 	char *str;
 	int len;
 
-	format = __ckpt_generate_fmt(ctx, fmt0, fmt);
+	format = ckpt_generate_fmt(ctx, fmt0, fmt);
 	va_copy(aq, ap);
 
 	/*
diff --git a/checkpoint/sys.c b/checkpoint/sys.c
index 260a1ee..c888a12 100644
--- a/checkpoint/sys.c
+++ b/checkpoint/sys.c
@@ -339,6 +339,93 @@ int walk_task_subtree(struct task_struct *root,
 	return (ret < 0 ? ret : total);
 }
 
+/*
+ * ckpt_generate_fmt - generate standard checkpoint error message
+ * @ctx: checkpoint context
+ * @fmt0: c/r-format string
+ * @fmt: message format
+ *
+ * This generates a unified format of checkpoint error messages, to
+ * ease (after the failure) inspection by userspace tools. It converts
+ * the (printf) message @fmt into a new format: "[PREFMT]: fmt".
+ *
+ * PREFMT is constructed from @fmt0 by subtituting format snippets
+ * according to the contents of @fmt0.  The format characters in
+ * @fmt0 can be E (error), O (objref), P (pointer), S (string) and
+ * V (variable/symbol). For example, E will generate a "err %d" in
+ * PREFMT (see prefmt_array below).
+ *
+ * If @fmt0 begins with T, PREFMT will begin with "pid %d tsk %s"
+ * with the pid and the tsk->comm of the currently checkpointed task.
+ * The latter is taken from ctx->tsk, and is it the responsbilility of
+ * the caller to have a valid pointer there (in particular, functions
+ * that iterate on the processes: collect_objects, checkpoint_task,
+ * and tree_count_tasks).
+ *
+ * The caller of ckpt_write_err() and _ckpt_write_err() must provide
+ * the additional variabes, in order, to match the @fmt0 (except for
+ * the T key), e.g.:
+ *
+ *   ckpt_writ_err(ctx, "TEO", "FILE flags %d", err, objref, flags);
+ *
+ * Here, T is simply passed, E expects an integer (err), O expects an
+ * integer (objref), and the last argument matches the format string.
+ */
+char *ckpt_generate_fmt(struct ckpt_ctx *ctx, char *fmt0, char *fmt)
+{
+	static int warn_notask = 0;
+	static int warn_prefmt = 0;
+	char *format;
+	int i, j, len = 0;
+
+	static struct {
+		char key;
+		char *fmt;
+	} prefmt_array[] = {
+		{ 'E', "err %d" },
+		{ 'O', "obj %d" },
+		{ 'P', "ptr %p" },
+		{ 'V', "sym %pS" },
+		{ 'S', "str %s" },
+		{ 0, "??? %pS" },
+	};
+
+	/*
+	 * 17 for "pid %d" (plus space)
+	 * 21 for "tsk %s" (tsk->comm)
+	 * up to 8 per varfmt entry
+	 */
+	format = kzalloc(37 + 8 * strlen(fmt0) + strlen(fmt), GFP_KERNEL);
+	if (!format)
+		return NULL;
+
+	format[len++] = '[';
+
+	if (fmt0[0] == 'T') {
+		if (ctx->tsk)
+			len = sprintf(format, "pid %d tsk %s ",
+				      task_pid_vnr(ctx->tsk), ctx->tsk->comm);
+		else if (warn_notask++ < 5)
+			printk(KERN_ERR "c/r: no target task set\n");
+		fmt0++;
+	}
+
+	for (i = 0; i < strlen(fmt0); i++) {
+		for (j = 0; prefmt_array[j].key; j++)
+			if (prefmt_array[j].key == fmt0[i])
+				break;
+		if (!prefmt_array[j].key && warn_prefmt++ < 5)
+			printk(KERN_ERR "c/r: unknown prefmt %c\n", fmt0[i]);
+		len += sprintf(&format[len], "%s ", prefmt_array[j].fmt);
+	}
+
+	if (len > 1)
+		sprintf(&format[len-1], "]: %s", fmt);  /* erase last space */
+	else
+		sprintf(format, "%s", fmt);
+
+	return format;
+}
 
 /**
  * sys_checkpoint - checkpoint a container
diff --git a/include/linux/checkpoint.h b/include/linux/checkpoint.h
index dfcb59b..541bfa8 100644
--- a/include/linux/checkpoint.h
+++ b/include/linux/checkpoint.h
@@ -370,6 +370,8 @@ static inline void restore_debug_free(struct ckpt_ctx *ctx) {}
 
 #endif /* CONFIG_CHECKPOINT_DEBUG */
 
+extern char *ckpt_generate_fmt(struct ckpt_ctx *ctx, char *fmt0, char *fmt);
+
 #endif /* CONFIG_CHECKPOINT */
 #endif /* __KERNEL__ */
 
-- 
1.6.1

[PATCH 02/22] Add format and message buffers to ctx and make err_str bigger

[serue-r/Jw6+rmf7HQT0dZR+AlfA]

From: Serge E. Hallyn <serue-r/Jw6+rmf7HQT0dZR+AlfA@public.gmane.org>

Signed-off-by: Serge E. Hallyn <serue-r/Jw6+rmf7HQT0dZR+AlfA@public.gmane.org>
---
 checkpoint/sys.c                 |    5 +++++
 include/linux/checkpoint_types.h |   18 +++++++++++++++++-
 2 files changed, 22 insertions(+), 1 deletions(-)

diff --git a/checkpoint/sys.c b/checkpoint/sys.c
index c888a12..0a486f0 100644
--- a/checkpoint/sys.c
+++ b/checkpoint/sys.c
@@ -249,6 +249,11 @@ static struct ckpt_ctx *ckpt_ctx_alloc(int fd, unsigned long uflags,
 	spin_lock_init(&ctx->lock);
 #endif
 
+	mutex_init(&ctx->msg_buf_mutex);
+	spin_lock_init(&ctx->err_string_lock);
+	spin_lock_init(&ctx->fmt_buf_lock);
+	ctx->err_string_len = 0;
+
 	err = -EBADF;
 	ctx->file = fget(fd);
 	if (!ctx->file)
diff --git a/include/linux/checkpoint_types.h b/include/linux/checkpoint_types.h
index 5cc11d9..46c58fb 100644
--- a/include/linux/checkpoint_types.h
+++ b/include/linux/checkpoint_types.h
@@ -59,7 +59,6 @@ struct ckpt_ctx {
 	struct path fs_mnt;     /* container root (FIXME) */
 
 	struct task_struct *tsk;/* checkpoint: current target task */
-	char err_string[256];	/* checkpoint: error string */
 	int errno;		/* restart: errno that caused failure */
 
 	struct list_head pgarr_list;	/* page array to dump VMA contents */
@@ -85,6 +84,23 @@ struct ckpt_ctx {
 	struct list_head task_status;   /* list of status for each task */
 	spinlock_t lock;
 #endif
+
+#define CKPT_MSG_BUFSZ 1024
+	/* err_string holds specific checkpoint error strings which may
+	 * be crafted in a context where we can't write it out yet */
+	char err_string[CKPT_MSG_BUFSZ];
+	spinlock_t err_string_lock;
+	int err_string_len;
+
+	/* fmt_buf holds the result of processing an enhanced format
+	 * string for use in crafting msg_buf */
+	char fmt_buf[CKPT_MSG_BUFSZ];
+	spinlock_t fmt_buf_lock;
+
+	/* msg_buf holds messages for writing to user log and syslog */
+	char msg_buf[CKPT_MSG_BUFSZ];
+	int msg_buf_len;
+	struct mutex msg_buf_mutex;
 };
 
 #endif /* __KERNEL__ */
-- 
1.6.1

[PATCH 03/22] switch ckpt_generate_err to use ctx fields

[serue-r/Jw6+rmf7HQT0dZR+AlfA]

From: Serge E. Hallyn <serue-r/Jw6+rmf7HQT0dZR+AlfA@public.gmane.org>

ckpt_generate_fmt() now places the format in ctx->fmt_buf.
ckpt_fill_err_string() calls ckpt_generate_fmt() under
ctx->fmt_buf_lock, and writes its own error (under
ctx->err_string_lock) to ctx->err_string.

Signed-off-by: Serge E. Hallyn <serue-r/Jw6+rmf7HQT0dZR+AlfA@public.gmane.org>
---
 checkpoint/checkpoint.c    |   76 ++++++++++++++++++++++++++++++--------------
 checkpoint/sys.c           |   16 ++-------
 include/linux/checkpoint.h |    3 +-
 3 files changed, 58 insertions(+), 37 deletions(-)

diff --git a/checkpoint/checkpoint.c b/checkpoint/checkpoint.c
index d0ffd0d..49f6e9d 100644
--- a/checkpoint/checkpoint.c
+++ b/checkpoint/checkpoint.c
@@ -96,36 +96,52 @@ int ckpt_write_string(struct ckpt_ctx *ctx, char *str, int len)
 	return ckpt_write_obj_type(ctx, str, len, CKPT_HDR_STRING);
 }
 
-/* see _ckpt_generate_fmt for information on @fmt0 */
-static void __ckpt_generate_err(struct ckpt_ctx *ctx, char *fmt0,
+static void ckpt_fill_err_string(struct ckpt_ctx *ctx, char *fmt0,
 				char *fmt, va_list ap)
 {
 	va_list aq;
-	char *format;
-	char *str;
 	int len;
+	unsigned long flags;
 
-	format = ckpt_generate_fmt(ctx, fmt0, fmt);
+	spin_lock_irqsave(&ctx->err_string_lock, flags);
+	spin_lock(&ctx->fmt_buf_lock);
+	ckpt_generate_fmt(ctx, fmt0, fmt);
 	va_copy(aq, ap);
 
+	if (ctx->err_string_len == CKPT_MSG_BUFSZ)
+		goto out_unlock;
+
 	/*
 	 * prefix the error string with a '\0' to facilitate easy
 	 * backtrace to the beginning of the error message without
 	 * needing to parse the entire checkpoint image.
 	 */
-	ctx->err_string[0] = '\0';
-	str = &ctx->err_string[1];
-	len = vsnprintf(str, 255, format ? : fmt, ap) + 2;
+	if (ctx->err_string_len == 0) {
+		ctx->err_string[0] = '\0';
+		ctx->err_string_len = 1;
+	}
 
-	if (len > 256) {
+	len = vsnprintf(ctx->err_string + ctx->err_string_len,
+			CKPT_MSG_BUFSZ - ctx->err_string_len,
+			ctx->fmt_buf, ap);
+
+	if (len >= CKPT_MSG_BUFSZ - ctx->err_string_len) {
 		printk(KERN_NOTICE "c/r: error string truncated: ");
 		vprintk(fmt, aq);
-	}
+		ctx->err_string[CKPT_MSG_BUFSZ-1] = '\0';
+		ctx->err_string_len = CKPT_MSG_BUFSZ;
+	} else
+		/* vscnprintf did add a \0 but didn't count
+		 * it toward the len.  We want it to count
+		 * toward the len so we keep a \0 between each
+		 * error msg */
+		ctx->err_string_len += len + 1;
 
 	va_end(aq);
-	kfree(format);
 
-	ckpt_debug("c/r: checkpoint error: %s\n", str);
+out_unlock:
+	spin_unlock(&ctx->fmt_buf_lock);
+	spin_unlock_irqrestore(&ctx->err_string_lock, flags);
 }
 
 /**
@@ -143,7 +159,7 @@ void __ckpt_write_err(struct ckpt_ctx *ctx, char *fmt0, char *fmt, ...)
 	va_list ap;
 
 	va_start(ap, fmt);
-	__ckpt_generate_err(ctx, fmt0, fmt, ap);
+	ckpt_fill_err_string(ctx, fmt, ap);
 	va_end(ap);
 }
 
@@ -160,29 +176,41 @@ void __ckpt_write_err(struct ckpt_ctx *ctx, char *fmt0, char *fmt, ...)
 int ckpt_write_err(struct ckpt_ctx *ctx, char *fmt0, char *fmt, ...)
 {
 	va_list ap;
-	char *str;
-	int len, ret = 0;
+	int i, len, ret = 0;
 
 	if (fmt) {
 		va_start(ap, fmt);
-		__ckpt_generate_err(ctx, fmt0, fmt, ap);
+		ckpt_fill_err_string(ctx,  fmt, ap);
 		va_end(ap);
 	}
 
-	str = ctx->err_string;
-	len = strlen(str + 1);
-	if (len == 0)	/* empty error string */
-		return 0;
+	mutex_lock(&ctx->msg_buf_mutex);
+	spin_lock(&ctx->err_string_lock);
+	len = ctx->err_string_len;
+	memcpy(ctx->msg_buf, ctx->err_string, len);
+	ctx->err_string_len = 0;
+	spin_unlock(&ctx->err_string_lock);
+
+	if (len == 0)
+		goto out_unlock;
 
-	len += 2; 	/* leading and trailing '\0' */
+	ctx->msg_buf_len = len;
+	/* write to the checkpoint image */
 	ret = ckpt_write_obj_type(ctx, NULL, 0, CKPT_HDR_ERROR);
 	if (!ret)
-		ret = ckpt_write_string(ctx, str, len);
+		ret = ckpt_write_string(ctx, ctx->msg_buf, ctx->msg_buf_len);
 	if (ret < 0)
 		printk(KERN_NOTICE "c/r: error string unsaved (%d): %s\n",
-		       ret, str + 1);
+		       ret, ctx->msg_buf);
+
+	/* duplicate to user log file and syslog */
+	for (i = 0; i < len-1; i++)
+		if (ctx->msg_buf[i] == '\0')
+			ctx->msg_buf[i] = '\n';
+	ckpt_do_write_msg(ctx);
 
-	str[1] = '\0';
+out_unlock:
+	mutex_unlock(&ctx->msg_buf_mutex);
 	return ret;
 }
 
diff --git a/checkpoint/sys.c b/checkpoint/sys.c
index 0a486f0..8810576 100644
--- a/checkpoint/sys.c
+++ b/checkpoint/sys.c
@@ -375,12 +375,13 @@ int walk_task_subtree(struct task_struct *root,
  *
  * Here, T is simply passed, E expects an integer (err), O expects an
  * integer (objref), and the last argument matches the format string.
+ *
+ * Must be called with ctx->fmt_buf_lock held.  The expanded format
+ * will be placed in ctx->fmt_buf.
  */
 char *ckpt_generate_fmt(struct ckpt_ctx *ctx, char *fmt0, char *fmt)
 {
-	static int warn_notask = 0;
-	static int warn_prefmt = 0;
-	char *format;
+	char *format = ctx->fmt_buf;
 	int i, j, len = 0;
 
 	static struct {
@@ -395,15 +396,6 @@ char *ckpt_generate_fmt(struct ckpt_ctx *ctx, char *fmt0, char *fmt)
 		{ 0, "??? %pS" },
 	};
 
-	/*
-	 * 17 for "pid %d" (plus space)
-	 * 21 for "tsk %s" (tsk->comm)
-	 * up to 8 per varfmt entry
-	 */
-	format = kzalloc(37 + 8 * strlen(fmt0) + strlen(fmt), GFP_KERNEL);
-	if (!format)
-		return NULL;
-
 	format[len++] = '[';
 
 	if (fmt0[0] == 'T') {
diff --git a/include/linux/checkpoint.h b/include/linux/checkpoint.h
index 541bfa8..4cfd44b 100644
--- a/include/linux/checkpoint.h
+++ b/include/linux/checkpoint.h
@@ -370,7 +370,8 @@ static inline void restore_debug_free(struct ckpt_ctx *ctx) {}
 
 #endif /* CONFIG_CHECKPOINT_DEBUG */
 
-extern char *ckpt_generate_fmt(struct ckpt_ctx *ctx, char *fmt0, char *fmt);
+extern void ckpt_generate_fmt(struct ckpt_ctx *ctx, char *fmt0, char *fmt);
+static inline void ckpt_do_write_msg(struct ckpt_ctx *ctx) { }
 
 #endif /* CONFIG_CHECKPOINT */
 #endif /* __KERNEL__ */
-- 
1.6.1

[PATCH 04/22] Change to the new enhanced error string format

[serue-r/Jw6+rmf7HQT0dZR+AlfA]

From: Serge E. Hallyn <serue-r/Jw6+rmf7HQT0dZR+AlfA@public.gmane.org>

Signed-off-by: Serge E. Hallyn <serue-r/Jw6+rmf7HQT0dZR+AlfA@public.gmane.org>
---
 checkpoint/checkpoint.c    |   15 ++----
 checkpoint/sys.c           |  122 ++++++++++++++++++++++----------------------
 include/linux/checkpoint.h |   12 ++--
 3 files changed, 72 insertions(+), 77 deletions(-)

diff --git a/checkpoint/checkpoint.c b/checkpoint/checkpoint.c
index 49f6e9d..c835d82 100644
--- a/checkpoint/checkpoint.c
+++ b/checkpoint/checkpoint.c
@@ -96,8 +96,7 @@ int ckpt_write_string(struct ckpt_ctx *ctx, char *str, int len)
 	return ckpt_write_obj_type(ctx, str, len, CKPT_HDR_STRING);
 }
 
-static void ckpt_fill_err_string(struct ckpt_ctx *ctx, char *fmt0,
-				char *fmt, va_list ap)
+static void ckpt_fill_err_string(struct ckpt_ctx *ctx, char *fmt, va_list ap)
 {
 	va_list aq;
 	int len;
@@ -105,7 +104,7 @@ static void ckpt_fill_err_string(struct ckpt_ctx *ctx, char *fmt0,
 
 	spin_lock_irqsave(&ctx->err_string_lock, flags);
 	spin_lock(&ctx->fmt_buf_lock);
-	ckpt_generate_fmt(ctx, fmt0, fmt);
+	ckpt_generate_fmt(ctx, fmt);
 	va_copy(aq, ap);
 
 	if (ctx->err_string_len == CKPT_MSG_BUFSZ)
@@ -147,14 +146,12 @@ out_unlock:
 /**
  * __ckpt_write_err - save an error string on the ctx->err_string
  * @ctx: checkpoint context
- * @fmt0: error pre-format
  * @fmt: message format
  * @...: arguments
  *
- * See _ckpt_generate_fmt for information on @fmt0.
  * Use this during checkpoint to report while holding a spinlock
  */
-void __ckpt_write_err(struct ckpt_ctx *ctx, char *fmt0, char *fmt, ...)
+void __ckpt_write_err(struct ckpt_ctx *ctx, char *fmt, ...)
 {
 	va_list ap;
 
@@ -166,21 +163,19 @@ void __ckpt_write_err(struct ckpt_ctx *ctx, char *fmt0, char *fmt, ...)
 /**
  * ckpt_write_err - write an object describing an error
  * @ctx: checkpoint context
- * @pre: string pre-format
  * @fmt: error string format
  * @...: error string arguments
  *
- * See _ckpt_generate_fmt for information on @fmt0.
  * If @fmt is null, the string in the ctx->err_string will be used (and freed)
  */
-int ckpt_write_err(struct ckpt_ctx *ctx, char *fmt0, char *fmt, ...)
+int ckpt_write_err(struct ckpt_ctx *ctx, char *fmt, ...)
 {
 	va_list ap;
 	int i, len, ret = 0;
 
 	if (fmt) {
 		va_start(ap, fmt);
-		ckpt_fill_err_string(ctx,  fmt, ap);
+		ckpt_fill_err_string(ctx, fmt, ap);
 		va_end(ap);
 	}
 
diff --git a/checkpoint/sys.c b/checkpoint/sys.c
index 8810576..e2c01df 100644
--- a/checkpoint/sys.c
+++ b/checkpoint/sys.c
@@ -345,83 +345,83 @@ int walk_task_subtree(struct task_struct *root,
 }
 
 /*
- * ckpt_generate_fmt - generate standard checkpoint error message
+ * ckpt_generate_fmt - handle the special flags in the enhanced format
+ * strings used by checkpoint/restart error messages.
  * @ctx: checkpoint context
- * @fmt0: c/r-format string
  * @fmt: message format
  *
- * This generates a unified format of checkpoint error messages, to
- * ease (after the failure) inspection by userspace tools. It converts
- * the (printf) message @fmt into a new format: "[PREFMT]: fmt".
+ * The special flags are surrounded by %() to help them visually stand
+ * out.  For instance, %(O) means an objref.  The following special
+ * flags are recognized:
+ *	E: error
+ *	O: objref
+ *	P: pointer
+ *	T: task
+ *	S: string
+ *	V: variable
  *
- * PREFMT is constructed from @fmt0 by subtituting format snippets
- * according to the contents of @fmt0.  The format characters in
- * @fmt0 can be E (error), O (objref), P (pointer), S (string) and
- * V (variable/symbol). For example, E will generate a "err %d" in
- * PREFMT (see prefmt_array below).
- *
- * If @fmt0 begins with T, PREFMT will begin with "pid %d tsk %s"
- * with the pid and the tsk->comm of the currently checkpointed task.
- * The latter is taken from ctx->tsk, and is it the responsbilility of
- * the caller to have a valid pointer there (in particular, functions
- * that iterate on the processes: collect_objects, checkpoint_task,
- * and tree_count_tasks).
+ * %(E) will be expanded to "[err %d]".  Likewise O, P, S, and V, will
+ * also expand to format flags requiring an argument to the subsequent
+ * sprintf or printk.  T will be expanded to a string with no flags,
+ * requiring no further arguments.
  *
  * The caller of ckpt_write_err() and _ckpt_write_err() must provide
- * the additional variabes, in order, to match the @fmt0 (except for
+ * the additional variabes, in order, to match the @fmt (except for
  * the T key), e.g.:
  *
- *   ckpt_writ_err(ctx, "TEO", "FILE flags %d", err, objref, flags);
- *
- * Here, T is simply passed, E expects an integer (err), O expects an
- * integer (objref), and the last argument matches the format string.
+ *	ckpt_write_err(ctx, "%(T)FILE flags %d %O %E\n", flags, objref, err);
  *
  * Must be called with ctx->fmt_buf_lock held.  The expanded format
  * will be placed in ctx->fmt_buf.
  */
-char *ckpt_generate_fmt(struct ckpt_ctx *ctx, char *fmt0, char *fmt)
+void ckpt_generate_fmt(struct ckpt_ctx *ctx, char *fmt)
 {
-	char *format = ctx->fmt_buf;
-	int i, j, len = 0;
-
-	static struct {
-		char key;
-		char *fmt;
-	} prefmt_array[] = {
-		{ 'E', "err %d" },
-		{ 'O', "obj %d" },
-		{ 'P', "ptr %p" },
-		{ 'V', "sym %pS" },
-		{ 'S', "str %s" },
-		{ 0, "??? %pS" },
-	};
-
-	format[len++] = '[';
-
-	if (fmt0[0] == 'T') {
-		if (ctx->tsk)
-			len = sprintf(format, "pid %d tsk %s ",
+	char *s = ctx->fmt_buf;
+	int len = 0;
+	int first = 1;
+
+	for (; *fmt && len < CKPT_MSG_BUFSZ; fmt++) {
+		if (*fmt != '%' || fmt[1] != '(' || fmt[2] == '\0' ||
+							fmt[3] != ')') {
+			s[len++] = *fmt;
+			continue;
+		}
+		if (!first)
+			s[len++] = ' ';
+		else
+			first = 0;
+		switch (fmt[2]) {
+		case 'E':
+			len += sprintf(s+len, "[%s]", "err %d");
+			break;
+		case 'O':
+			len += sprintf(s+len, "[%s]", "obj %d");
+			break;
+		case 'P':
+			len += sprintf(s+len, "[%s]", "ptr %p");
+			break;
+		case 'V':
+			len += sprintf(s+len, "[%s]", "sym %pS");
+			break;
+		case 'S':
+			len += sprintf(s+len, "[%s]", "str %s");
+			break;
+		case 'T':
+			if (ctx->tsk)
+				len += sprintf(s+len, "[pid %d tsk %s]",
 				      task_pid_vnr(ctx->tsk), ctx->tsk->comm);
-		else if (warn_notask++ < 5)
-			printk(KERN_ERR "c/r: no target task set\n");
-		fmt0++;
-	}
+			else
+				len += sprintf(s+len, "[pid -1 tsk NULL]");
+			break;
+		default:
+			printk(KERN_ERR "c/r: bad format specifier %c\n",
+					fmt[2]);
+			BUG();
+		}
 
-	for (i = 0; i < strlen(fmt0); i++) {
-		for (j = 0; prefmt_array[j].key; j++)
-			if (prefmt_array[j].key == fmt0[i])
-				break;
-		if (!prefmt_array[j].key && warn_prefmt++ < 5)
-			printk(KERN_ERR "c/r: unknown prefmt %c\n", fmt0[i]);
-		len += sprintf(&format[len], "%s ", prefmt_array[j].fmt);
+		fmt += 3;
 	}
-
-	if (len > 1)
-		sprintf(&format[len-1], "]: %s", fmt);  /* erase last space */
-	else
-		sprintf(format, "%s", fmt);
-
-	return format;
+	s[len] = '\0';
 }
 
 /**
diff --git a/include/linux/checkpoint.h b/include/linux/checkpoint.h
index 4cfd44b..6464851 100644
--- a/include/linux/checkpoint.h
+++ b/include/linux/checkpoint.h
@@ -70,12 +70,12 @@ extern int ckpt_write_buffer(struct ckpt_ctx *ctx, void *ptr, int len);
 extern int ckpt_write_string(struct ckpt_ctx *ctx, char *str, int len);
 
 /*
- * Generate a checkpoint error message with unified format, of the
- * form: "[PREFMT]: @fmt", where PREFMT is constructed from @fmt0. See
- * checkpoint/checkpoint.c:__ckpt_generate_fmt() for details.
+ * Generate a checkpoint error message with unified format.  Format
+ * can include tokens like %(E) for checkpoint-specific arguments,
+ * which must come before non-checkpoint-specific ones.
  */
-extern void __ckpt_write_err(struct ckpt_ctx *ctx, char *fmt0, char *fmt, ...);
-extern int ckpt_write_err(struct ckpt_ctx *ctx, char *fmt0, char *fmt, ...);
+extern void __ckpt_write_err(struct ckpt_ctx *ctx,  char *fmt, ...);
+extern int ckpt_write_err(struct ckpt_ctx *ctx,  char *fmt, ...);
 
 extern int _ckpt_read_obj_type(struct ckpt_ctx *ctx,
 			       void *ptr, int len, int type);
@@ -370,7 +370,7 @@ static inline void restore_debug_free(struct ckpt_ctx *ctx) {}
 
 #endif /* CONFIG_CHECKPOINT_DEBUG */
 
-extern void ckpt_generate_fmt(struct ckpt_ctx *ctx, char *fmt0, char *fmt);
+extern void ckpt_generate_fmt(struct ckpt_ctx *ctx, char *fmt);
 static inline void ckpt_do_write_msg(struct ckpt_ctx *ctx) { }
 
 #endif /* CONFIG_CHECKPOINT */
-- 
1.6.1

[PATCH 13/22] add logfd to c/r api

[serue-r/Jw6+rmf7HQT0dZR+AlfA]

From: Serge E. Hallyn <serue-r/Jw6+rmf7HQT0dZR+AlfA@public.gmane.org>

Signed-off-by: Serge E. Hallyn <serue-r/Jw6+rmf7HQT0dZR+AlfA@public.gmane.org>
---
 checkpoint/objhash.c             |    2 ++
 checkpoint/sys.c                 |   22 +++++++++++++++++-----
 include/linux/checkpoint_types.h |    1 +
 include/linux/syscalls.h         |    5 +++--
 4 files changed, 23 insertions(+), 7 deletions(-)

diff --git a/checkpoint/objhash.c b/checkpoint/objhash.c
index a152e69..25b9c10 100644
--- a/checkpoint/objhash.c
+++ b/checkpoint/objhash.c
@@ -858,6 +858,8 @@ int ckpt_obj_contained(struct ckpt_ctx *ctx)
 
 	/* account for ctx->file reference (if in the table already) */
 	ckpt_obj_users_inc(ctx, ctx->file, 1);
+	if (ctx->logfile)
+		ckpt_obj_users_inc(ctx, ctx->logfile, 1);
 	/* account for ctx->root_nsproxy reference (if in the table already) */
 	ckpt_obj_users_inc(ctx, ctx->root_nsproxy, 1);
 
diff --git a/checkpoint/sys.c b/checkpoint/sys.c
index e2c01df..b959b27 100644
--- a/checkpoint/sys.c
+++ b/checkpoint/sys.c
@@ -204,6 +204,8 @@ static void ckpt_ctx_free(struct ckpt_ctx *ctx)
 
 	if (ctx->file)
 		fput(ctx->file);
+	if (ctx->logfile)
+		fput(ctx->logfile);
 
 	ckpt_obj_hash_free(ctx);
 	path_put(&ctx->fs_mnt);
@@ -225,7 +227,7 @@ static void ckpt_ctx_free(struct ckpt_ctx *ctx)
 }
 
 static struct ckpt_ctx *ckpt_ctx_alloc(int fd, unsigned long uflags,
-				       unsigned long kflags)
+				       unsigned long kflags, int logfd)
 {
 	struct ckpt_ctx *ctx;
 	int err;
@@ -259,6 +261,13 @@ static struct ckpt_ctx *ckpt_ctx_alloc(int fd, unsigned long uflags,
 	if (!ctx->file)
 		goto err;
 
+	if (logfd == -1)
+		goto skiplogfd;
+	ctx->logfile = fget(logfd);
+	if (!ctx->logfile)
+		goto err;
+
+skiplogfd:
 	err = -ENOMEM;
 	if (ckpt_obj_hash_alloc(ctx) < 0)
 		goto err;
@@ -429,11 +438,13 @@ void ckpt_generate_fmt(struct ckpt_ctx *ctx, char *fmt)
  * @pid: pid of the container init(1) process
  * @fd: file to which dump the checkpoint image
  * @flags: checkpoint operation flags
+ * @logfd: fd to which to dump debug and error messages
  *
  * Returns positive identifier on success, 0 when returning from restart
  * or negative value on error
  */
-SYSCALL_DEFINE3(checkpoint, pid_t, pid, int, fd, unsigned long, flags)
+SYSCALL_DEFINE4(checkpoint, pid_t, pid, int, fd, unsigned long, flags,
+		int, logfd)
 {
 	struct ckpt_ctx *ctx;
 	long ret;
@@ -446,7 +457,7 @@ SYSCALL_DEFINE3(checkpoint, pid_t, pid, int, fd, unsigned long, flags)
 
 	if (pid == 0)
 		pid = task_pid_vnr(current);
-	ctx = ckpt_ctx_alloc(fd, flags, CKPT_CTX_CHECKPOINT);
+	ctx = ckpt_ctx_alloc(fd, flags, CKPT_CTX_CHECKPOINT, logfd);
 	if (IS_ERR(ctx))
 		return PTR_ERR(ctx);
 
@@ -464,11 +475,12 @@ SYSCALL_DEFINE3(checkpoint, pid_t, pid, int, fd, unsigned long, flags)
  * @pid: pid of task root (in coordinator's namespace), or 0
  * @fd: file from which read the checkpoint image
  * @flags: restart operation flags
+ * @logfd: fd to which to dump debug and error messages
  *
  * Returns negative value on error, or otherwise returns in the realm
  * of the original checkpoint
  */
-SYSCALL_DEFINE3(restart, pid_t, pid, int, fd, unsigned long, flags)
+SYSCALL_DEFINE4(restart, pid_t, pid, int, fd, unsigned long, flags, int, logfd)
 {
 	struct ckpt_ctx *ctx = NULL;
 	long ret;
@@ -481,7 +493,7 @@ SYSCALL_DEFINE3(restart, pid_t, pid, int, fd, unsigned long, flags)
 		return -EPERM;
 
 	if (pid)
-		ctx = ckpt_ctx_alloc(fd, flags, CKPT_CTX_RESTART);
+		ctx = ckpt_ctx_alloc(fd, flags, CKPT_CTX_RESTART, logfd);
 	if (IS_ERR(ctx))
 		return PTR_ERR(ctx);
 
diff --git a/include/linux/checkpoint_types.h b/include/linux/checkpoint_types.h
index 46c58fb..d0b47f2 100644
--- a/include/linux/checkpoint_types.h
+++ b/include/linux/checkpoint_types.h
@@ -48,6 +48,7 @@ struct ckpt_ctx {
 	unsigned long oflags;	/* restart: uflags from checkpoint */
 
 	struct file *file;	/* input/output file */
+	struct file *logfile;	/* debug log file */
 	loff_t total;		/* total read/written */
 
 	atomic_t refcount;
diff --git a/include/linux/syscalls.h b/include/linux/syscalls.h
index 33bce6e..4fce331 100644
--- a/include/linux/syscalls.h
+++ b/include/linux/syscalls.h
@@ -754,8 +754,9 @@ asmlinkage long sys_pselect6(int, fd_set __user *, fd_set __user *,
 asmlinkage long sys_ppoll(struct pollfd __user *, unsigned int,
 			  struct timespec __user *, const sigset_t __user *,
 			  size_t);
-asmlinkage long sys_checkpoint(pid_t pid, int fd, unsigned long flags);
-asmlinkage long sys_restart(pid_t pid, int fd, unsigned long flags);
+asmlinkage long sys_checkpoint(pid_t pid, int fd, unsigned long flags,
+			       int logfd);
+asmlinkage long sys_restart(pid_t pid, int fd, unsigned long flags, int logfd);
 
 int kernel_execve(const char *filename, char *const argv[], char *const envp[]);
 
-- 
1.6.1

[PATCH 14/22] define ckpt_error and implement ckpt_do_write_msg

[serue-r/Jw6+rmf7HQT0dZR+AlfA]

From: Serge E. Hallyn <serue-r/Jw6+rmf7HQT0dZR+AlfA@public.gmane.org>

Signed-off-by: Serge E. Hallyn <serue-r/Jw6+rmf7HQT0dZR+AlfA@public.gmane.org>
---
 checkpoint/sys.c           |   64 ++++++++++++++++++++++++++++++++++++++++++++
 include/linux/checkpoint.h |    6 +++-
 2 files changed, 69 insertions(+), 1 deletions(-)

diff --git a/checkpoint/sys.c b/checkpoint/sys.c
index b959b27..94cbe57 100644
--- a/checkpoint/sys.c
+++ b/checkpoint/sys.c
@@ -433,6 +433,70 @@ void ckpt_generate_fmt(struct ckpt_ctx *ctx, char *fmt)
 	s[len] = '\0';
 }
 
+/*
+ * Write ctx->msg_buf to user-provided log and to syslog
+ * Called under ctx->msg_buf_mutex.
+ */
+void ckpt_do_write_msg(struct ckpt_ctx *ctx)
+{
+	struct file *file = ctx->logfile;
+	mm_segment_t fs;
+
+	fs = get_fs();
+	set_fs(KERNEL_DS);
+	_ckpt_kwrite(file, ctx->msg_buf, ctx->msg_buf_len);
+	set_fs(fs);
+
+	ckpt_debug("%s", ctx->msg_buf);
+}
+
+static void ckpt_log_msg_v(struct ckpt_ctx *ctx, char *fmt, va_list ap)
+{
+	char *msgbuf;
+	va_list aq;
+	int count, len;
+
+	mutex_lock(&ctx->msg_buf_mutex);
+	/* expand the format into ctx->fmt_buf */
+	spin_lock(&ctx->fmt_buf_lock);
+	ckpt_generate_fmt(ctx, fmt);
+	msgbuf = ctx->msg_buf;
+
+	/* write the prefix */
+	len = snprintf(msgbuf, CKPT_MSG_BUFSZ, "[%d]=[%d]:[%lld]:[%d] ",
+			 current->pid, task_pid_vnr(current), ctx->total,
+			 ctx->errno);
+	/* fill in the message */
+	va_copy(aq, ap);
+	count = vsnprintf(msgbuf+len, CKPT_MSG_BUFSZ-len, ctx->fmt_buf, aq);
+	va_end(aq);
+
+	spin_unlock(&ctx->fmt_buf_lock);
+
+	count += len;
+	if (count > CKPT_MSG_BUFSZ) {
+		printk(KERN_WARNING "%s:%s:%d error string too long (%d)\n",
+		       __FILE__, __func__, __LINE__, count);
+		msgbuf[CKPT_MSG_BUFSZ-1] = '\0';
+	}
+
+	ctx->msg_buf_len = count;
+	ckpt_do_write_msg(ctx);
+	mutex_unlock(&ctx->msg_buf_mutex);
+}
+
+void ckpt_log_msg(struct ckpt_ctx *ctx, char *fmt, ...)
+{
+	va_list ap;
+
+	if (!ctx || !ctx->logfile)
+		return;
+
+	va_start(ap, fmt);
+	ckpt_log_msg_v(ctx, fmt, ap);
+	va_end(ap);
+}
+
 /**
  * sys_checkpoint - checkpoint a container
  * @pid: pid of the container init(1) process
diff --git a/include/linux/checkpoint.h b/include/linux/checkpoint.h
index 6464851..0c2bb56 100644
--- a/include/linux/checkpoint.h
+++ b/include/linux/checkpoint.h
@@ -371,7 +371,11 @@ static inline void restore_debug_free(struct ckpt_ctx *ctx) {}
 #endif /* CONFIG_CHECKPOINT_DEBUG */
 
 extern void ckpt_generate_fmt(struct ckpt_ctx *ctx, char *fmt);
-static inline void ckpt_do_write_msg(struct ckpt_ctx *ctx) { }
+extern void ckpt_do_write_msg(struct ckpt_ctx *ctx);
+extern void ckpt_log_msg(struct ckpt_ctx *ctx, char *fmt, ...);
+
+#define ckpt_error(ctx, fmt, args...)					\
+	ckpt_log_msg(ctx, "%s:%d " fmt, __func__, __LINE__, ## args);
 
 #endif /* CONFIG_CHECKPOINT */
 #endif /* __KERNEL__ */
-- 
1.6.1

[PATCH 15/22] explain locking for write_err_msg

[serue-r/Jw6+rmf7HQT0dZR+AlfA]

From: Serge E. Hallyn <serue-r/Jw6+rmf7HQT0dZR+AlfA@public.gmane.org>

Signed-off-by: Serge E. Hallyn <serue-r/Jw6+rmf7HQT0dZR+AlfA@public.gmane.org>
---
 checkpoint/checkpoint.c |   21 +++++++++++++++++++++
 1 files changed, 21 insertions(+), 0 deletions(-)

diff --git a/checkpoint/checkpoint.c b/checkpoint/checkpoint.c
index 71340de..f057c7a 100644
--- a/checkpoint/checkpoint.c
+++ b/checkpoint/checkpoint.c
@@ -96,6 +96,13 @@ int ckpt_write_string(struct ckpt_ctx *ctx, char *str, int len)
 	return ckpt_write_obj_type(ctx, str, len, CKPT_HDR_STRING);
 }
 
+/*
+ * ckpt_fill_err_string() can be called under spinlock and therefore
+ * must not sleep.  So we protect ctx->err_string and ->err_string_len
+ * with ctx->err_string_lock which is a spinlock.
+ * We must also take the ctx->fmt_buf_lock (also a spin_lock) for the
+ * whole time that we are writing to and reading from ctx->fmt_buf.
+ */
 static void ckpt_fill_err_string(struct ckpt_ctx *ctx, char *fmt, va_list ap)
 {
 	va_list aq;
@@ -166,6 +173,20 @@ void __ckpt_write_err(struct ckpt_ctx *ctx, char *fmt, ...)
  * @fmt: error string format
  * @...: error string arguments
  *
+ * Here is the locking rationale:
+ * __ckpt_write_err() (which can be called from spinlock context)
+ * writes to ctx->err_string under ctx->err_string_lock.
+ *
+ * ckpt_write_err() in turn copies ctx->err_string to ctx->msg_buf
+ * under both ctx->msg_buf_mutex and ctx->err_string_lock, and clears
+ * out ctx->err_sring (so theoretically it can be written to again).
+ * It then drops ctx->err_string_lock (which is a spinlock) and keeps
+ * the ctx->msg_buf_mutex.
+ *
+ * It then can leisurely write out msg_buf under mutex ( by calling
+ * ckpt_do_write_msg() ), while another task could be writing new
+ * messages to ctx->err_string.
+ *
  * If @fmt is null, the string in the ctx->err_string will be used (and freed)
  */
 int ckpt_write_err(struct ckpt_ctx *ctx, char *fmt, ...)
-- 
1.6.1

Re: [PATCH 04/22] Change to the new enhanced error string format

[Matt Helsley]

On Fri, Oct 30, 2009 at 06:00:26PM -0500, serue-r/Jw6+rmf7HQT0dZR+AlfA@public.gmane.org wrote:
> From: Serge E. Hallyn <serue-r/Jw6+rmf7HQT0dZR+AlfA@public.gmane.org>
> 
> Signed-off-by: Serge E. Hallyn <serue-r/Jw6+rmf7HQT0dZR+AlfA@public.gmane.org>
> ---

<snip>

> - * This generates a unified format of checkpoint error messages, to
> - * ease (after the failure) inspection by userspace tools. It converts
> - * the (printf) message @fmt into a new format: "[PREFMT]: fmt".
> + * The special flags are surrounded by %() to help them visually stand
> + * out.  For instance, %(O) means an objref.  The following special
> + * flags are recognized:
> + *	E: error
> + *	O: objref
> + *	P: pointer
> + *	T: task
> + *	S: string
> + *	V: variable
>   *

Something for the future: It might be good to have "F: File" as well. It
may sometimes be useful to print out a file name instead of just the struct
file pointer. It'd be useful for epoll, file checkpoint ops in general, and
file-backed VMAs.

<snip>

> -char *ckpt_generate_fmt(struct ckpt_ctx *ctx, char *fmt0, char *fmt)
> +void ckpt_generate_fmt(struct ckpt_ctx *ctx, char *fmt)
>  {
> -	char *format = ctx->fmt_buf;
> -	int i, j, len = 0;
> -
> -	static struct {
> -		char key;
> -		char *fmt;
> -	} prefmt_array[] = {
> -		{ 'E', "err %d" },
> -		{ 'O', "obj %d" },
> -		{ 'P', "ptr %p" },
> -		{ 'V', "sym %pS" },
> -		{ 'S', "str %s" },
> -		{ 0, "??? %pS" },
> -	};
> -
> -	format[len++] = '[';
> -
> -	if (fmt0[0] == 'T') {
> -		if (ctx->tsk)
> -			len = sprintf(format, "pid %d tsk %s ",
> +	char *s = ctx->fmt_buf;
> +	int len = 0;
> +	int first = 1;
> +
> +	for (; *fmt && len < CKPT_MSG_BUFSZ; fmt++) {
> +		if (*fmt != '%' || fmt[1] != '(' || fmt[2] == '\0' ||
> +							fmt[3] != ')') {
> +			s[len++] = *fmt;
> +			continue;
> +		}
> +		if (!first)
> +			s[len++] = ' ';
> +		else
> +			first = 0;
> +		switch (fmt[2]) {
> +		case 'E':
> +			len += sprintf(s+len, "[%s]", "err %d");

Why not use snprintf ? Maybe I'm misunderstanding the length check in
the for-loop but it doesn't look sufficient to avoid overrunning the
fmt_buf. Suppose len == CKPT_MSG_BUFSZ - 1 and fmt[2] is non-NUL. Then 
we're writing 8-9 more non-NUL bytes to fmt_buf ("[err %d]" in this
case).

You could avoid snprintf() by doing:

	for (; *fmt && len < (CKPT_MSG_BUFSZ - 9); fmt++) {

which won't allow you to completely fill fmt_buf but will ensure
you never run off the end. But I still think snprintf may be necessary
to handle the default case (below).

> +			break;
> +		case 'O':
> +			len += sprintf(s+len, "[%s]", "obj %d");
> +			break;
> +		case 'P':
> +			len += sprintf(s+len, "[%s]", "ptr %p");
> +			break;
> +		case 'V':
> +			len += sprintf(s+len, "[%s]", "sym %pS");
> +			break;
> +		case 'S':
> +			len += sprintf(s+len, "[%s]", "str %s");
> +			break;
> +		case 'T':
> +			if (ctx->tsk)
> +				len += sprintf(s+len, "[pid %d tsk %s]",
>  				      task_pid_vnr(ctx->tsk), ctx->tsk->comm);
> -		else if (warn_notask++ < 5)
> -			printk(KERN_ERR "c/r: no target task set\n");
> -		fmt0++;
> -	}
> +			else
> +				len += sprintf(s+len, "[pid -1 tsk NULL]");
> +			break;
> +		default:
> +			printk(KERN_ERR "c/r: bad format specifier %c\n",
> +					fmt[2]);
> +			BUG();

Perhaps BUG() isn't such a good idea since this will be used in
error-recovery paths. The printk looks fine. Perhaps just skip to the ')':

			while (*fmt && *fmt != ')')
				fmt++;

The problem is this breaks walking the valist because an argument has been
provided which won't be consumed. To fix this seems necessary to insert
strings indicating which arguments to use with each subsequent conversion
specifier:

	arg_num = 1; /* valist index starts at one. see man snprintf */
	for (...) {
		...
		case 'S':
			len += snprintf(s+len, CKPT_MSG_BUFSZ - len,
					"[str %%*%d$s]", arg_num);
			/* sample output:[str %*3$s]" */
			arg_num++;
			break;
		...
		default:
			printk(KERN_ERR "c/r: bad format specifier %c\n", fmt[2]);
			while (*fmt && *fmt != ')')
				fmt++;
			arg_num++;
			break;

which all but requires the use snprintf instead of sprintf.

Cheers,
	-Matt Helsley

Re: [PATCH 04/22] Change to the new enhanced error string format

[Serge E. Hallyn]

Quoting Matt Helsley (matthltc-r/Jw6+rmf7HQT0dZR+AlfA@public.gmane.org):
> On Fri, Oct 30, 2009 at 06:00:26PM -0500, serue-r/Jw6+rmf7HQT0dZR+AlfA@public.gmane.org wrote:
> > From: Serge E. Hallyn <serue-r/Jw6+rmf7HQT0dZR+AlfA@public.gmane.org>
> > 
> > Signed-off-by: Serge E. Hallyn <serue-r/Jw6+rmf7HQT0dZR+AlfA@public.gmane.org>
> > ---
> 
> <snip>
> 
> > - * This generates a unified format of checkpoint error messages, to
> > - * ease (after the failure) inspection by userspace tools. It converts
> > - * the (printf) message @fmt into a new format: "[PREFMT]: fmt".
> > + * The special flags are surrounded by %() to help them visually stand
> > + * out.  For instance, %(O) means an objref.  The following special
> > + * flags are recognized:
> > + *	E: error
> > + *	O: objref
> > + *	P: pointer
> > + *	T: task
> > + *	S: string
> > + *	V: variable
> >   *
> 
> Something for the future: It might be good to have "F: File" as well. It
> may sometimes be useful to print out a file name instead of just the struct
> file pointer. It'd be useful for epoll, file checkpoint ops in general, and
> file-backed VMAs.

Sure...  As callers want it, we can add it - I also expect %A for
ctx->active_pid (which won't take an argument) to be added.

...

> > +	for (; *fmt && len < CKPT_MSG_BUFSZ; fmt++) {
> > +		if (*fmt != '%' || fmt[1] != '(' || fmt[2] == '\0' ||
> > +							fmt[3] != ')') {
> > +			s[len++] = *fmt;
> > +			continue;
> > +		}
> > +		if (!first)
> > +			s[len++] = ' ';
> > +		else
> > +			first = 0;
> > +		switch (fmt[2]) {
> > +		case 'E':
> > +			len += sprintf(s+len, "[%s]", "err %d");
> 
> Why not use snprintf ?

Yup, thanks for keeping me honest - just switched my new patchset
to do that.

...

> > +		default:
> > +			printk(KERN_ERR "c/r: bad format specifier %c\n",
> > +					fmt[2]);
> > +			BUG();
> 
> Perhaps BUG() isn't such a good idea since this will be used in

I disagree - this fmt is passed in by the kernel, so if we get a flag
we don't understand, then it is a bug in our c/r code.

-serge

Re: [PATCH 04/22] Change to the new enhanced error string format

[Matt Helsley]

On Mon, Nov 02, 2009 at 10:52:20AM -0600, Serge E. Hallyn wrote:
> Quoting Matt Helsley (matthltc-r/Jw6+rmf7HQT0dZR+AlfA@public.gmane.org):
> > On Fri, Oct 30, 2009 at 06:00:26PM -0500, serue-r/Jw6+rmf7HQT0dZR+AlfA@public.gmane.org wrote:
> > > From: Serge E. Hallyn <serue-r/Jw6+rmf7HQT0dZR+AlfA@public.gmane.org>
> > > 
> > > Signed-off-by: Serge E. Hallyn <serue-r/Jw6+rmf7HQT0dZR+AlfA@public.gmane.org>
> > > ---

<snip>

> ...
> 
> > > +		default:
> > > +			printk(KERN_ERR "c/r: bad format specifier %c\n",
> > > +					fmt[2]);
> > > +			BUG();
> > 
> > Perhaps BUG() isn't such a good idea since this will be used in
> 
> I disagree - this fmt is passed in by the kernel, so if we get a flag
> we don't understand, then it is a bug in our c/r code.

OK, you've convinced me.

Cheers,
	-Matt Helsley

Re: [PATCH 04/22] Change to the new enhanced error string format

[Matt Helsley]

On Fri, Oct 30, 2009 at 06:00:26PM -0500, serue-r/Jw6+rmf7HQT0dZR+AlfA@public.gmane.org wrote:
> From: Serge E. Hallyn <serue-r/Jw6+rmf7HQT0dZR+AlfA@public.gmane.org>
> 
> Signed-off-by: Serge E. Hallyn <serue-r/Jw6+rmf7HQT0dZR+AlfA@public.gmane.org>
> ---

<snip>

> diff --git a/checkpoint/sys.c b/checkpoint/sys.c
> index 8810576..e2c01df 100644
> --- a/checkpoint/sys.c
> +++ b/checkpoint/sys.c
> @@ -345,83 +345,83 @@ int walk_task_subtree(struct task_struct *root,
>  }
> 
>  /*
> - * ckpt_generate_fmt - generate standard checkpoint error message
> + * ckpt_generate_fmt - handle the special flags in the enhanced format
> + * strings used by checkpoint/restart error messages.
>   * @ctx: checkpoint context
> - * @fmt0: c/r-format string
>   * @fmt: message format
>   *
> - * This generates a unified format of checkpoint error messages, to
> - * ease (after the failure) inspection by userspace tools. It converts
> - * the (printf) message @fmt into a new format: "[PREFMT]: fmt".
> + * The special flags are surrounded by %() to help them visually stand
> + * out.  For instance, %(O) means an objref.  The following special
> + * flags are recognized:
> + *	E: error
> + *	O: objref
> + *	P: pointer
> + *	T: task
> + *	S: string
> + *	V: variable
>   *
> - * PREFMT is constructed from @fmt0 by subtituting format snippets
> - * according to the contents of @fmt0.  The format characters in
> - * @fmt0 can be E (error), O (objref), P (pointer), S (string) and
> - * V (variable/symbol). For example, E will generate a "err %d" in
> - * PREFMT (see prefmt_array below).
> - *
> - * If @fmt0 begins with T, PREFMT will begin with "pid %d tsk %s"
> - * with the pid and the tsk->comm of the currently checkpointed task.
> - * The latter is taken from ctx->tsk, and is it the responsbilility of
> - * the caller to have a valid pointer there (in particular, functions
> - * that iterate on the processes: collect_objects, checkpoint_task,
> - * and tree_count_tasks).
> + * %(E) will be expanded to "[err %d]".  Likewise O, P, S, and V, will
> + * also expand to format flags requiring an argument to the subsequent
> + * sprintf or printk.  T will be expanded to a string with no flags,
> + * requiring no further arguments.
>   *
>   * The caller of ckpt_write_err() and _ckpt_write_err() must provide
> - * the additional variabes, in order, to match the @fmt0 (except for
> + * the additional variabes, in order, to match the @fmt (except for
>   * the T key), e.g.:
>   *
> - *   ckpt_writ_err(ctx, "TEO", "FILE flags %d", err, objref, flags);
> - *
> - * Here, T is simply passed, E expects an integer (err), O expects an
> - * integer (objref), and the last argument matches the format string.
> + *	ckpt_write_err(ctx, "%(T)FILE flags %d %O %E\n", flags, objref, err);
>   *
>   * Must be called with ctx->fmt_buf_lock held.  The expanded format
>   * will be placed in ctx->fmt_buf.

It might also be good to note that, unlike normal conversion
specifications, these do not allow any flags, minimum field width,
precision, length modifiers, or argument numbers ("%*" or "%*m$").
This keeps these portions of the log(s) somewhat uniform and also
simplifies the code.

<snip>

Cheers,
	-Matt Helsley