[RFC PATCH 0/17] Introduce ckpt_error

[RFC PATCH 0/17] Introduce ckpt_error

[Serge Hallyn]

This patchset tweaks __ckpt_generate_fmt() to take one format with
%(X) enhancements.  It renames it ckpt_generate_fmt and makes it
non-static and introduces ckpt_error() as a user, which writes
information about why c/r failed to an optional user-provided
log fd.  If CONFIG_CHECKPOINT_DEBUG=y then these msgs are also
printk'd.

At the end of the patchset I introduce some callers of ckpt_error(),
but those are mainly for demonstration - those patches certainly
should not be applied as we want to be more systematic about both
when and how we output such information.

This patch is also available as branch oct27.writerr.ckpterr.6 of
http://git.kernel.org/gitweb.cgi?p=linux/kernel/git/sergeh/linux-cr.git;a=summary

-serge

[RFC PATCH 01/17] ckpt_write_err: use single format with %(T) style tokens

[Serge Hallyn]

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

Matt Helsley originally suggested this to avoid having two
format strings.  This is not bisect-safe and therefore not
even compile-tested.  Every call to ckpt_write_err must be
updated to use a single format.

Changelog: Oct 27: ensure %(T) has a closing paren

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

diff --git a/checkpoint/checkpoint.c b/checkpoint/checkpoint.c
index 6eb8f3b..404bf08 100644
--- a/checkpoint/checkpoint.c
+++ b/checkpoint/checkpoint.c
@@ -128,72 +128,80 @@ int ckpt_write_string(struct ckpt_ctx *ctx, char *str, int len)
  * 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 char *__ckpt_generate_fmt(struct ckpt_ctx *ctx, 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" },
-	};
+	int alloclen, len = 0;
+	int first = 1;
 
 	/*
 	 * 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);
+	alloclen = 37 + 8 * strlen(fmt);
+	format = kzalloc(alloclen, GFP_KERNEL);
 	if (!format)
 		return NULL;
 
-	format[len++] = '[';
-
-	if (fmt0[0] == 'T') {
-		if (ctx->tsk)
-			len = sprintf(format, "pid %d tsk %s ",
+	for (; *fmt; fmt++) {
+		BUG_ON(len > alloclen);
+		if (*fmt != '%' || fmt[1] != '(' || fmt[3] != ')') {
+			format[len++] = *fmt;
+			continue;
+		}
+		if (!first)
+			format[len++] = ' ';
+		else
+			first = 0;
+		switch(fmt[2]) {
+		case 'E':
+			len += sprintf(format+len, "[%s]", "err %d");
+			break;
+		case 'O':
+			len += sprintf(format+len, "[%s]", "obj %d");
+			break;
+		case 'P':
+			len += sprintf(format+len, "[%s]", "ptr %p");
+			break;
+		case 'V':
+			len += sprintf(format+len, "[%s]", "sym %pS");
+			break;
+		case 'S':
+			len += sprintf(format+len, "[%s]", "str %s");
+			break;
+		case 'T':
+			if (ctx->tsk)
+				len += sprintf(format+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(format+len, "[pid -1 tsk NULL]");
+			break;
+		default:
+			if (warn_prefmt++ < 5)
+				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);
+	format[len] = '\0';
 
 	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)
+static void __ckpt_generate_err(struct ckpt_ctx *ctx, char *fmt, va_list ap)
 {
 	va_list aq;
 	char *format;
 	char *str;
 	int len;
 
-	format = __ckpt_generate_fmt(ctx, fmt0, fmt);
+	format = __ckpt_generate_fmt(ctx, fmt);
 	va_copy(aq, ap);
 
 	/*
@@ -226,12 +234,12 @@ static void __ckpt_generate_err(struct ckpt_ctx *ctx, char *fmt0,
  * 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;
 
 	va_start(ap, fmt);
-	__ckpt_generate_err(ctx, fmt0, fmt, ap);
+	__ckpt_generate_err(ctx, fmt, ap);
 	va_end(ap);
 }
 
@@ -245,7 +253,7 @@ void __ckpt_write_err(struct ckpt_ctx *ctx, char *fmt0, char *fmt, ...)
  * 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;
 	char *str;
@@ -253,7 +261,7 @@ int ckpt_write_err(struct ckpt_ctx *ctx, char *fmt0, char *fmt, ...)
 
 	if (fmt) {
 		va_start(ap, fmt);
-		__ckpt_generate_err(ctx, fmt0, fmt, ap);
+		__ckpt_generate_err(ctx,  fmt, ap);
 		va_end(ap);
 	}
 
diff --git a/include/linux/checkpoint.h b/include/linux/checkpoint.h
index dfcb59b..224b494 100644
--- a/include/linux/checkpoint.h
+++ b/include/linux/checkpoint.h
@@ -70,12 +70,13 @@ 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 %(T) for checkpoint-specific arguments,
+ * which must come before non-checkpoint-specific ones.
+ * See checkpoint/checkpoint.c:__ckpt_generate_fmt() for details.
  */
-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);
-- 
1.6.1

[RFC PATCH 02/17] make ckpt_format_fmt non-static in checkpoint/sys.c

[Serge Hallyn]

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    |  103 +-------------------------------------------
 checkpoint/sys.c           |   95 ++++++++++++++++++++++++++++++++++++++++
 include/linux/checkpoint.h |    2 +
 3 files changed, 99 insertions(+), 101 deletions(-)

diff --git a/checkpoint/checkpoint.c b/checkpoint/checkpoint.c
index 404bf08..c6be4f9 100644
--- a/checkpoint/checkpoint.c
+++ b/checkpoint/checkpoint.c
@@ -96,104 +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);
 }
 
-/*
- * __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 *fmt)
-{
-	static int warn_prefmt = 0;
-	char *format;
-	int alloclen, len = 0;
-	int first = 1;
-
-	/*
-	 * 17 for "pid %d" (plus space)
-	 * 21 for "tsk %s" (tsk->comm)
-	 * up to 8 per varfmt entry
-	 */
-	alloclen = 37 + 8 * strlen(fmt);
-	format = kzalloc(alloclen, GFP_KERNEL);
-	if (!format)
-		return NULL;
-
-	for (; *fmt; fmt++) {
-		BUG_ON(len > alloclen);
-		if (*fmt != '%' || fmt[1] != '(' || fmt[3] != ')') {
-			format[len++] = *fmt;
-			continue;
-		}
-		if (!first)
-			format[len++] = ' ';
-		else
-			first = 0;
-		switch(fmt[2]) {
-		case 'E':
-			len += sprintf(format+len, "[%s]", "err %d");
-			break;
-		case 'O':
-			len += sprintf(format+len, "[%s]", "obj %d");
-			break;
-		case 'P':
-			len += sprintf(format+len, "[%s]", "ptr %p");
-			break;
-		case 'V':
-			len += sprintf(format+len, "[%s]", "sym %pS");
-			break;
-		case 'S':
-			len += sprintf(format+len, "[%s]", "str %s");
-			break;
-		case 'T':
-			if (ctx->tsk)
-				len += sprintf(format+len, "[pid %d tsk %s]",
-				      task_pid_vnr(ctx->tsk), ctx->tsk->comm);
-			else 
-				len += sprintf(format+len, "[pid -1 tsk NULL]");
-			break;
-		default:
-			if (warn_prefmt++ < 5)
-				printk(KERN_ERR
-					"c/r: bad format specifier %c\n",
-					fmt[2]);
-			BUG();
-		}
-
-		fmt += 3;
-	}
-	format[len] = '\0';
-
-	return format;
-}
-
-/* see _ckpt_generate_fmt for information on @fmt0 */
+/* see ckpt_generate_fmt for information on @fmt extensions */
 static void __ckpt_generate_err(struct ckpt_ctx *ctx, char *fmt, va_list ap)
 {
 	va_list aq;
@@ -201,7 +104,7 @@ static void __ckpt_generate_err(struct ckpt_ctx *ctx, char *fmt, va_list ap)
 	char *str;
 	int len;
 
-	format = __ckpt_generate_fmt(ctx, fmt);
+	format = ckpt_generate_fmt(ctx, fmt);
 	va_copy(aq, ap);
 
 	/*
@@ -231,7 +134,6 @@ static void __ckpt_generate_err(struct ckpt_ctx *ctx, char *fmt, va_list ap)
  * @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 *fmt, ...)
@@ -250,7 +152,6 @@ void __ckpt_write_err(struct ckpt_ctx *ctx, char *fmt, ...)
  * @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 *fmt, ...)
diff --git a/checkpoint/sys.c b/checkpoint/sys.c
index 260a1ee..38e65e4 100644
--- a/checkpoint/sys.c
+++ b/checkpoint/sys.c
@@ -339,6 +339,101 @@ int walk_task_subtree(struct task_struct *root,
 	return (ret < 0 ? ret : total);
 }
 
+/*
+ * ckpt_generate_fmt - generate standard checkpoint error message
+ * @ctx: checkpoint context
+ * @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 *fmt)
+{
+	static int warn_prefmt = 0;
+	char *format;
+	int alloclen, len = 0;
+	int first = 1;
+
+	/*
+	 * 17 for "pid %d" (plus space)
+	 * 21 for "tsk %s" (tsk->comm)
+	 * up to 8 per varfmt entry
+	 */
+	alloclen = 37 + 8 * strlen(fmt);
+	format = kzalloc(alloclen, GFP_KERNEL);
+	if (!format)
+		return NULL;
+
+	for (; *fmt; fmt++) {
+		BUG_ON(len > alloclen);
+		if (*fmt != '%' || fmt[1] != '(' || fmt[3] != ')') {
+			format[len++] = *fmt;
+			continue;
+		}
+		if (!first)
+			format[len++] = ' ';
+		else
+			first = 0;
+		switch(fmt[2]) {
+		case 'E':
+			len += sprintf(format+len, "[%s]", "err %d");
+			break;
+		case 'O':
+			len += sprintf(format+len, "[%s]", "obj %d");
+			break;
+		case 'P':
+			len += sprintf(format+len, "[%s]", "ptr %p");
+			break;
+		case 'V':
+			len += sprintf(format+len, "[%s]", "sym %pS");
+			break;
+		case 'S':
+			len += sprintf(format+len, "[%s]", "str %s");
+			break;
+		case 'T':
+			if (ctx->tsk)
+				len += sprintf(format+len, "[pid %d tsk %s]",
+				      task_pid_vnr(ctx->tsk), ctx->tsk->comm);
+			else 
+				len += sprintf(format+len, "[pid -1 tsk NULL]");
+			break;
+		default:
+			if (warn_prefmt++ < 5)
+				printk(KERN_ERR
+					"c/r: bad format specifier %c\n",
+					fmt[2]);
+			BUG();
+		}
+
+		fmt += 3;
+	}
+	format[len] = '\0';
+
+	return format;
+}
 
 /**
  * sys_checkpoint - checkpoint a container
diff --git a/include/linux/checkpoint.h b/include/linux/checkpoint.h
index 224b494..8a1eaa7 100644
--- a/include/linux/checkpoint.h
+++ b/include/linux/checkpoint.h
@@ -371,6 +371,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 *fmt);
+
 #endif /* CONFIG_CHECKPOINT */
 #endif /* __KERNEL__ */
 
-- 
1.6.1

[RFC PATCH 03/17] ckpt_write_err update arch/x86/mm/checkpoint.c

[Serge Hallyn]

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>
---
 arch/x86/mm/checkpoint.c |    4 ++--
 1 files changed, 2 insertions(+), 2 deletions(-)

diff --git a/arch/x86/mm/checkpoint.c b/arch/x86/mm/checkpoint.c
index 9dd8e12..3b0f514 100644
--- a/arch/x86/mm/checkpoint.c
+++ b/arch/x86/mm/checkpoint.c
@@ -116,11 +116,11 @@ static unsigned short decode_segment(__u16 seg)
 static int may_checkpoint_thread(struct ckpt_ctx *ctx, struct task_struct *t)
 {
 	if (t->thread.vm86_info) {
-		ckpt_write_err(ctx, "TE", "task in VM86 mode", -EBUSY);
+		ckpt_write_err(ctx, "%(T)%(E)task in VM86 mode", -EBUSY);
 		return -EBUSY;
 	}
 	if (task_thread_info(t)->flags & CKPT_X86_TIF_UNSUPPORTED) {
-		ckpt_write_err(ctx, "TE", "bad thread info flags %#lx", -EBUSY);
+		ckpt_write_err(ctx, "%(T)%(E)bad thread info flags %#lx", -EBUSY);
 		return -EBUSY;
 	}
 	return 0;
-- 
1.6.1

[RFC PATCH 04/17] ckpt_write_err update checkpoint/checkpoint.c

[Serge Hallyn]

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 |   28 ++++++++++++++--------------
 1 files changed, 14 insertions(+), 14 deletions(-)

diff --git a/checkpoint/checkpoint.c b/checkpoint/checkpoint.c
index c6be4f9..35fce15 100644
--- a/checkpoint/checkpoint.c
+++ b/checkpoint/checkpoint.c
@@ -319,12 +319,12 @@ static int may_checkpoint_task(struct ckpt_ctx *ctx, struct task_struct *t)
 	ckpt_debug("check %d\n", task_pid_nr_ns(t, ctx->root_nsproxy->pid_ns));
 
 	if (t->exit_state == EXIT_DEAD) {
-		__ckpt_write_err(ctx, "TE", "task state EXIT_DEAD\n", -EBUSY);
+		__ckpt_write_err(ctx, "%(T)%(E)task state EXIT_DEAD\n", -EBUSY);
 		return -EBUSY;
 	}
 
 	if (!ptrace_may_access(t, PTRACE_MODE_ATTACH)) {
-		__ckpt_write_err(ctx, "TE", "ptrace attach denied", -EPERM);
+		__ckpt_write_err(ctx, "%(T)%(E)ptrace attach denied", -EPERM);
 		return -EPERM;
 	}
 
@@ -334,13 +334,13 @@ static int may_checkpoint_task(struct ckpt_ctx *ctx, struct task_struct *t)
 
 	/* verify that all tasks belongs to same freezer cgroup */
 	if (t != current && !in_same_cgroup_freezer(t, ctx->root_freezer)) {
-		__ckpt_write_err(ctx, "TE", "unfrozen or wrong cgroup", -EBUSY);
+		__ckpt_write_err(ctx, "%(T)%(E)unfrozen or wrong cgroup", -EBUSY);
 		return -EBUSY;
 	}
 
 	/* FIX: add support for ptraced tasks */
 	if (task_ptrace(t)) {
-		__ckpt_write_err(ctx, "TE", "task is ptraced", -EBUSY);
+		__ckpt_write_err(ctx, "%(T)%(E)task is ptraced", -EBUSY);
 		return -EBUSY;
 	}
 
@@ -350,22 +350,22 @@ static int may_checkpoint_task(struct ckpt_ctx *ctx, struct task_struct *t)
 	 */
 	if (ctx->root_init && t != root &&
 	    t->real_parent == root->real_parent && t->tgid != root->tgid) {
-		__ckpt_write_err(ctx, "TE", "task is sibling of root", -EINVAL);
+		__ckpt_write_err(ctx, "%(T)%(E)task is sibling of root", -EINVAL);
 		return -EINVAL;
 	}
 
 	rcu_read_lock();
 	nsproxy = task_nsproxy(t);
 	if (nsproxy->mnt_ns != ctx->root_nsproxy->mnt_ns) {
-		__ckpt_write_err(ctx, "TE", "bad mnt_ns", -EPERM);
+		__ckpt_write_err(ctx, "%(T)%(E)bad mnt_ns", -EPERM);
 		ret = -EPERM;
 	}
 	if (nsproxy->pid_ns != ctx->root_nsproxy->pid_ns) {
-		__ckpt_write_err(ctx, "TE", "bad pid_ns", -EPERM);
+		__ckpt_write_err(ctx, "%(T)%(E)bad pid_ns", -EPERM);
 		ret = -EPERM;
 	}
 	if (nsproxy->net_ns != ctx->root_nsproxy->net_ns) {
-		__ckpt_write_err(ctx, "TE", "bad net_ns", -EPERM);
+		__ckpt_write_err(ctx, "%(T)%(E)bad net_ns", -EPERM);
 		ret = -EPERM;
 	}
 	rcu_read_unlock();
@@ -435,7 +435,7 @@ static int collect_objects(struct ckpt_ctx *ctx)
 		ret = ckpt_collect_task(ctx, ctx->tasks_arr[n]);
 		if (ret < 0) {
 			ctx->tsk = ctx->tasks_arr[n];
-			ckpt_write_err(ctx, "TE", "collect failed", ret);
+			ckpt_write_err(ctx, "%(T)%(E)collect failed", ret);
 			ctx->tsk = NULL;
 			break;
 		}
@@ -465,7 +465,7 @@ static int __tree_count_tasks(struct task_struct *task, void *data)
 
 	if (ctx->tasks_arr) {
 		if (d->nr == ctx->nr_tasks) {  /* unlikely... try again later */
-			__ckpt_write_err(ctx, "TE", "bad task count\n", -EBUSY);
+			__ckpt_write_err(ctx, "%(T)%(E)bad task count\n", -EBUSY);
 			ret = -EBUSY;
 			goto out;
 		}
@@ -476,7 +476,7 @@ static int __tree_count_tasks(struct task_struct *task, void *data)
 	ret = 1;
  out:
 	if (ret < 0)
-		ckpt_write_err(ctx, "", NULL);
+		ckpt_write_err(ctx, NULL);
 	ctx->tsk = NULL;
 	return ret;
 }
@@ -635,7 +635,7 @@ static int init_checkpoint_ctx(struct ckpt_ctx *ctx, pid_t pid)
 	ctx->root_init = is_container_init(task);
 
 	if (!(ctx->uflags & CHECKPOINT_SUBTREE) && !ctx->root_init) {
-		ckpt_write_err(ctx, "E", "not container init", -EINVAL);
+		ckpt_write_err(ctx, "%(E)not container init", -EINVAL);
 		return -EINVAL;  /* cleanup by ckpt_ctx_free() */
 	}
 
@@ -662,7 +662,7 @@ long do_checkpoint(struct ckpt_ctx *ctx, pid_t pid)
 	if (ctx->root_freezer) {
 		ret = cgroup_freezer_begin_checkpoint(ctx->root_freezer);
 		if (ret < 0) {
-			ckpt_write_err(ctx, "E", "freezer cgroup failed", ret);
+			ckpt_write_err(ctx, "%(E)freezer cgroup failed", ret);
 			return ret;
 		}
 	}
@@ -705,7 +705,7 @@ long do_checkpoint(struct ckpt_ctx *ctx, pid_t pid)
 
 	/* verify that all objects were indeed visited */
 	if (!ckpt_obj_visited(ctx)) {
-		ckpt_write_err(ctx, "E", "leak: unvisited", -EBUSY);
+		ckpt_write_err(ctx, "%(E)leak: unvisited", -EBUSY);
 		ret = -EBUSY;
 		goto out;
 	}
-- 
1.6.1

[RFC PATCH 05/17] ckpt_write_err update checkpoint/files.c

[Serge Hallyn]

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/files.c |   17 +++++++++--------
 1 files changed, 9 insertions(+), 8 deletions(-)

diff --git a/checkpoint/files.c b/checkpoint/files.c
index 440b7a9..1f2ab07 100644
--- a/checkpoint/files.c
+++ b/checkpoint/files.c
@@ -88,7 +88,7 @@ int checkpoint_fname(struct ckpt_ctx *ctx, struct path *path, struct path *root)
 					  CKPT_HDR_FILE_NAME);
 	} else {
 		ret = PTR_ERR(fname);
-		ckpt_write_err(ctx, "TEP", "obtain filename (file)", ret);
+		ckpt_write_err(ctx, "%(T)%(E)%(P)obtain filename (file)", ret);
 	}
 
 	kfree(buf);
@@ -204,20 +204,21 @@ int checkpoint_file(struct ckpt_ctx *ctx, void *ptr)
 	int ret;
 
 	if (!file->f_op || !file->f_op->checkpoint) {
-		ckpt_write_err(ctx, "TEPS", "f_op lacks checkpoint",
+		ckpt_write_err(ctx, "%(T)%(E)%(P)%(S)f_op lacks checkpoint",
 			       -EBADF, file, file->f_op);
 		ckpt_debug("f_op lacks checkpoint handler: %pS\n", file->f_op);
 		return -EBADF;
 	}
 	if (d_unlinked(file->f_dentry)) {
-		ckpt_write_err(ctx, "TEP", "unlinked file", -EBADF, file);
+		ckpt_write_err(ctx, "%(T)%(E)%(P)unlinked file", -EBADF, file);
 		ckpt_debug("unlinked files are unsupported\n");
 		return -EBADF;
 	}
 
 	ret = file->f_op->checkpoint(ctx, file);
 	if (ret < 0)
-		ckpt_write_err(ctx, "TEP", "file checkpoint failed", ret, file);
+		ckpt_write_err(ctx, "%(T)%(E)%(P)file checkpoint failed", ret,
+			       file);
 	return ret;
 }
 
@@ -257,7 +258,7 @@ static int checkpoint_file_desc(struct ckpt_ctx *ctx,
 	ret = -EBADF;
 	if (!file) {
 		pr_warning("c/r: file descriptor gone?");
-		ckpt_write_err(ctx, "TEP", "file gone? (%d)", ret, file, fd);
+		ckpt_write_err(ctx, "%(T)%(E)%(P)file gone? (%d)", ret, file, fd);
 		goto out;
 	}
 
@@ -360,7 +361,7 @@ int ckpt_collect_file(struct ckpt_ctx *ctx, struct file *file)
 	if (file->f_op->collect)
 		ret = file->f_op->collect(ctx, file);
 	if (ret < 0)
-		ckpt_write_err(ctx, "TEP", "file collect", ret, file);
+		ckpt_write_err(ctx, "%(T)%(E)%(P)file collect", ret, file);
 	return ret;
 }
 
@@ -379,7 +380,7 @@ static int collect_file_desc(struct ckpt_ctx *ctx,
 	rcu_read_unlock();
 
 	if (!file) {
-		ckpt_write_err(ctx, "TE", "file removed", -EBUSY, file);
+		ckpt_write_err(ctx, "%(T)%(E)file removed", -EBUSY, file);
 		return -EBUSY;
 	}
 
@@ -422,7 +423,7 @@ int ckpt_collect_file_table(struct ckpt_ctx *ctx, struct task_struct *t)
 
 	files = get_files_struct(t);
 	if (!files) {
-		ckpt_write_err(ctx, "TE", "files_struct missing", -EBUSY);
+		ckpt_write_err(ctx, "%(T)%(E)files_struct missing", -EBUSY);
 		return -EBUSY;
 	}
 	ret = collect_file_table(ctx, files);
-- 
1.6.1

[RFC PATCH 06/17] ckpt_write_err update checkpoint/memory.c

[Serge Hallyn]

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/memory.c |    8 ++++----
 1 files changed, 4 insertions(+), 4 deletions(-)

diff --git a/checkpoint/memory.c b/checkpoint/memory.c
index 656614c..c94a85e 100644
--- a/checkpoint/memory.c
+++ b/checkpoint/memory.c
@@ -679,7 +679,7 @@ static int checkpoint_vmas(struct ckpt_ctx *ctx, struct mm_struct *mm)
 			 vma->vm_start, vma->vm_end, vma->vm_flags);
 
 		if (vma->vm_flags & CKPT_VMA_NOT_SUPPORTED) {
-			ckpt_write_err(ctx, "TE", "vma: bad flags (%#lx)\n",
+			ckpt_write_err(ctx, "%(T)%(E)vma: bad flags (%#lx)\n",
 				       -ENOSYS, vma->vm_flags);
 			ret = -ENOSYS;
 			break;
@@ -692,7 +692,7 @@ static int checkpoint_vmas(struct ckpt_ctx *ctx, struct mm_struct *mm)
 		else
 			ret = -ENOSYS;
 		if (ret < 0) {
-			ckpt_write_err(ctx, "TE", "vma: failed", ret);
+			ckpt_write_err(ctx, "%(T)%(E)vma: failed", ret);
 			break;
 		}
 		/*
@@ -821,7 +821,7 @@ static int collect_mm(struct ckpt_ctx *ctx, struct mm_struct *mm)
 	if (mm->exe_file) {
 		ret = ckpt_collect_file(ctx, mm->exe_file);
 		if (ret < 0) {
-			ckpt_write_err(ctx, "TE", "mm: collect exe_file", ret);
+			ckpt_write_err(ctx, "%(T)%(E)mm: collect exe_file", ret);
 			goto out;
 		}
 	}
@@ -831,7 +831,7 @@ static int collect_mm(struct ckpt_ctx *ctx, struct mm_struct *mm)
 			continue;
 		ret = ckpt_collect_file(ctx, file);
 		if (ret < 0) {
-			ckpt_write_err(ctx, "TE", "mm: collect vm_file", ret);
+			ckpt_write_err(ctx, "%(T)%(E)mm: collect vm_file", ret);
 			break;
 		}
 	}
-- 
1.6.1

[RFC PATCH 07/17] ckpt_write_err update checkpoint/objhash.c

[Serge Hallyn]

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 |    8 ++++----
 1 files changed, 4 insertions(+), 4 deletions(-)

diff --git a/checkpoint/objhash.c b/checkpoint/objhash.c
index 730dd82..a152e69 100644
--- a/checkpoint/objhash.c
+++ b/checkpoint/objhash.c
@@ -657,7 +657,7 @@ static inline int obj_reverse_leak(struct ckpt_ctx *ctx, struct ckpt_obj *obj)
 	 * object while we were collecting, which we didn't catch.
 	 */
 	if (obj->ops->ref_users && !(ctx->uflags & CHECKPOINT_SUBTREE)) {
-		ckpt_write_err(ctx, "OP", "leak: reverse added late (%s)",
+		ckpt_write_err(ctx, "%(O)%(P)leak: reverse added late (%s)",
 			       obj->objref, obj->ptr, obj->ops->obj_name);
 		return -EBUSY;
 	}
@@ -774,7 +774,7 @@ int ckpt_obj_visit(struct ckpt_ctx *ctx, void *ptr, enum obj_type type)
 	if (!obj) {
 		if (!(ctx->uflags & CHECKPOINT_SUBTREE)) {
 			/* if not found report reverse leak (full container) */
-			ckpt_write_err(ctx, "OP", "leak: reverse unknown (%s)",
+			ckpt_write_err(ctx, "%(O)%(P)leak: reverse unknown (%s)",
 				       obj->objref, obj->ptr,
 				       obj->ops->obj_name);
 			return -EBUSY;
@@ -870,7 +870,7 @@ int ckpt_obj_contained(struct ckpt_ctx *ctx)
 
 		if (obj->ops->ref_users(obj->ptr) != obj->users) {
 			ckpt_debug("usage leak: %s\n", obj->ops->obj_name);
-			ckpt_write_err(ctx, "OP", "leak: usage (%d != %d (%s)",
+			ckpt_write_err(ctx, "%(O)%(P)leak: usage (%d != %d (%s)",
 				       obj->objref, obj->ptr,
 				       obj->ops->ref_users(obj->ptr),
 				       obj->users, obj->ops->obj_name);
@@ -896,7 +896,7 @@ int ckpt_obj_visited(struct ckpt_ctx *ctx)
 		if (!(obj->flags & CKPT_OBJ_VISITED)) {
 			ckpt_debug("reverse leak: %s (%d)\n",
 				   obj->ops->obj_name, obj->objref);
-			ckpt_write_err(ctx, "OP", "leak: not visited (%s)",
+			ckpt_write_err(ctx, "%(O)%(P)leak: not visited (%s)",
 				       obj->objref, obj->ptr,
 				       obj->ops->obj_name);
 			return 0;
-- 
1.6.1

[RFC PATCH 08/17] ckpt_write_err update checkpoint/process.c

[Serge Hallyn]

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/process.c |    8 ++++----
 1 files changed, 4 insertions(+), 4 deletions(-)

diff --git a/checkpoint/process.c b/checkpoint/process.c
index 8e4a823..e84683f 100644
--- a/checkpoint/process.c
+++ b/checkpoint/process.c
@@ -256,21 +256,21 @@ static int checkpoint_task_objs(struct ckpt_ctx *ctx, struct task_struct *t)
 	files_objref = checkpoint_obj_file_table(ctx, t);
 	ckpt_debug("files: objref %d\n", files_objref);
 	if (files_objref < 0) {
-		ckpt_write_err(ctx, "TE", "files_struct", files_objref);
+		ckpt_write_err(ctx, "%(T)%(E)files_struct", files_objref);
 		return files_objref;
 	}
 
 	mm_objref = checkpoint_obj_mm(ctx, t);
 	ckpt_debug("mm: objref %d\n", mm_objref);
 	if (mm_objref < 0) {
-		ckpt_write_err(ctx, "TE", "mm_struct", mm_objref);
+		ckpt_write_err(ctx, "%(T)%(E)mm_struct", mm_objref);
 		return mm_objref;
 	}
 
 	sighand_objref = checkpoint_obj_sighand(ctx, t);
 	ckpt_debug("sighand: objref %d\n", sighand_objref);
 	if (sighand_objref < 0) {
-		ckpt_write_err(ctx, "TE", "sighand_struct", sighand_objref);
+		ckpt_write_err(ctx, "%(T)%(E)sighand_struct", sighand_objref);
 		return sighand_objref;
 	}
 
@@ -303,7 +303,7 @@ static int checkpoint_task_objs(struct ckpt_ctx *ctx, struct task_struct *t)
 	if (first)
 		ret = checkpoint_obj_signal(ctx, t);
 	if (ret < 0)
-		ckpt_write_err(ctx, "TE", "signal_struct", ret);
+		ckpt_write_err(ctx, "%(T)%(E)signal_struct", ret);
 
 	return ret;
 }
-- 
1.6.1

[RFC PATCH 09/17] ckpt_write_err update checkpoint/signal.c

[Serge Hallyn]

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/signal.c |    9 +++++----
 1 files changed, 5 insertions(+), 4 deletions(-)

diff --git a/checkpoint/signal.c b/checkpoint/signal.c
index cdfb142..3eed685 100644
--- a/checkpoint/signal.c
+++ b/checkpoint/signal.c
@@ -287,7 +287,7 @@ static int checkpoint_sigpending(struct ckpt_ctx *ctx,
 	list_for_each_entry(q, &pending->list, list) {
 		/* TODO: remove after adding support for posix-timers */
 		if ((q->info.si_code & __SI_MASK) == __SI_TIMER) {
-			ckpt_write_err(ctx, "TE", "signal SI_TIMER", -ENOTSUPP);
+			ckpt_write_err(ctx, "%(T)%(E)signal SI_TIMER", -ENOTSUPP);
 			return -ENOTSUPP;
 		}
 		nr_pending++;
@@ -341,7 +341,8 @@ static int checkpoint_signal(struct ckpt_ctx *ctx, struct task_struct *t)
 
 	/* TODO: remove after adding support for posix-timers */
 	if (!list_empty(&signal->posix_timers)) {
-		ckpt_write_err(ctx, "TEP", "posix-timers\n", -ENOTSUPP, signal);
+		ckpt_write_err(ctx, "%(T)%(E)%(P)posix-timers\n", -ENOTSUPP,
+				signal);
 		unlock_task_sighand(t, &flags);
 		ret = -ENOTSUPP;
 		goto out;
@@ -653,7 +654,7 @@ int checkpoint_task_signal(struct ckpt_ctx *ctx, struct task_struct *t)
 
 	/* temporarily borrow signal queue - see chekcpoint_sigpending() */
 	if (!lock_task_sighand(t, &flags)) {
-		ckpt_write_err(ctx, "TE", "signand missing", -EBUSY);
+		ckpt_write_err(ctx, "%(T)%(E)signand missing", -EBUSY);
 		return -EBUSY;
 	}
 	list_splice_init(&t->pending.list, &pending.list);
@@ -664,7 +665,7 @@ int checkpoint_task_signal(struct ckpt_ctx *ctx, struct task_struct *t)
 
 	/* re-attach the borrowed queue */
 	if (!lock_task_sighand(t, &flags)) {
-		ckpt_write_err(ctx, "TE", "signand missing", -EBUSY);
+		ckpt_write_err(ctx, "%(T)%(E)sighand missing", -EBUSY);
 		return -EBUSY;
 	}
 	list_splice(&pending.list, &t->pending.list);
-- 
1.6.1

[RFC PATCH 10/17] ckpt_write_err update fs/eventpoll.c

[Serge Hallyn]

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>
---
 fs/eventpoll.c |    2 +-
 1 files changed, 1 insertions(+), 1 deletions(-)

diff --git a/fs/eventpoll.c b/fs/eventpoll.c
index e07de97..f21745b 100644
--- a/fs/eventpoll.c
+++ b/fs/eventpoll.c
@@ -1549,7 +1549,7 @@ unlock:
 	if (num_items != 0 || (num_items == 0 && rbp))
 		ret = -EBUSY; /* extra item(s) -- checkpoint obj leak */
 	if (ret)
-		ckpt_write_err(ctx, "E", " checkpointing epoll items.\n", ret);
+		ckpt_write_err(ctx, "%(E)checkpointing epoll items.\n", ret);
 	return ret;
 }
 
-- 
1.6.1

[RFC PATCH 11/17] define function to print error messages to user log

[Serge Hallyn]

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

Error messages are both sent to an optional user-provided logfile,
and, if CONFIG_CHECKPOINT_DEBUG=y, sent to syslog.

Changelog:
	Oct 27: add %(C) for ctx->total.
	Oct 26: Per Oren suggestion, return -EBADF for bad
		logfile in ckpt_ctx_alloc().

Signed-off-by: Serge E. Hallyn <serue-r/Jw6+rmf7HQT0dZR+AlfA@public.gmane.org>
---
 checkpoint/objhash.c             |    2 +
 checkpoint/sys.c                 |   67 +++++++++++++++++++++++++++++++++++---
 include/linux/checkpoint.h       |    5 +++
 include/linux/checkpoint_types.h |    1 +
 include/linux/syscalls.h         |    5 ++-
 5 files changed, 73 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 38e65e4..ab0f294 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;
@@ -254,6 +256,12 @@ static struct ckpt_ctx *ckpt_ctx_alloc(int fd, unsigned long uflags,
 	if (!ctx->file)
 		goto err;
 
+	if (logfd != -1) {
+		ctx->logfile = fget(logfd);
+		if (!ctx->logfile)
+			goto err;
+	}
+
 	err = -ENOMEM;
 	if (ckpt_obj_hash_alloc(ctx) < 0)
 		goto err;
@@ -401,6 +409,9 @@ char *ckpt_generate_fmt(struct ckpt_ctx *ctx, char *fmt)
 		case 'E':
 			len += sprintf(format+len, "[%s]", "err %d");
 			break;
+		case 'C': /* count of bytes read/written to checkpoint image */
+			len += sprintf(format+len, "[%s]", "pos %d");
+			break;
 		case 'O':
 			len += sprintf(format+len, "[%s]", "obj %d");
 			break;
@@ -435,6 +446,51 @@ char *ckpt_generate_fmt(struct ckpt_ctx *ctx, char *fmt)
 	return format;
 }
 
+void ckpt_log_error(struct ckpt_ctx *ctx, char *fmt, ...)
+{
+	mm_segment_t fs;
+	struct file *file;
+	int count;
+	va_list ap, aq, az;
+	char *format;
+	char buf[200], *bufp = buf;
+
+	if (!ctx || !ctx->logfile)
+		return;
+	file = ctx->logfile;
+
+	va_start(ap, fmt);
+	format = ckpt_generate_fmt(ctx, fmt);
+	va_copy(aq, ap);
+	va_copy(az, ap);
+	/* I'm not clear here - can I re-use aq, or do i need
+	 * a third copy? */
+	count = vsnprintf(bufp, 200, format ? : fmt, aq);
+	if (count > 200) {
+		bufp = kmalloc(count, GFP_KERNEL);
+		if (!bufp)
+		       goto out_free;
+		vsnprintf(bufp, count, format ? : fmt, az);
+	}
+
+	fs = get_fs();
+	set_fs(KERNEL_DS);
+	_ckpt_kwrite(file, bufp, count);
+	set_fs(fs);
+
+#ifdef CONFIG_CHECKPOINT_DEBUG
+	vprintk(format, aq);
+#endif
+
+out_free:
+	kfree(format);
+	va_end(aq);
+	va_end(ap);
+	va_end(az);
+	if (bufp != buf)
+		kfree(bufp);
+}
+
 /**
  * sys_checkpoint - checkpoint a container
  * @pid: pid of the container init(1) process
@@ -444,7 +500,8 @@ char *ckpt_generate_fmt(struct ckpt_ctx *ctx, char *fmt)
  * 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;
@@ -457,7 +514,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);
 
@@ -479,7 +536,7 @@ SYSCALL_DEFINE3(checkpoint, pid_t, pid, int, fd, unsigned long, flags)
  * 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;
@@ -492,7 +549,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.h b/include/linux/checkpoint.h
index 8a1eaa7..91e0066 100644
--- a/include/linux/checkpoint.h
+++ b/include/linux/checkpoint.h
@@ -372,6 +372,11 @@ static inline void restore_debug_free(struct ckpt_ctx *ctx) {}
 #endif /* CONFIG_CHECKPOINT_DEBUG */
 
 extern char *ckpt_generate_fmt(struct ckpt_ctx *ctx, char *fmt);
+extern void ckpt_log_error(struct ckpt_ctx *ctx, char *fmt, ...);
+
+#define ckpt_error(ctx, fmt, args...)					\
+	ckpt_log_error(ctx, "%s:%d %(C)" fmt, __func__, __LINE__,	\
+		       ctx ? ctx->total : -1, ## args);
 
 #endif /* CONFIG_CHECKPOINT */
 #endif /* __KERNEL__ */
diff --git a/include/linux/checkpoint_types.h b/include/linux/checkpoint_types.h
index 5cc11d9..c6dcd4f 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

[RFC PATCH 12/17] use ckpt_error in checkpoint/restart.c

[Serge Hallyn]

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

In cases where f(x) always returns 0 or <0, I felt free to
remove ckpt_debugs in favor of ckpt_error() only on error.

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

diff --git a/checkpoint/restart.c b/checkpoint/restart.c
index 9b75de8..540b7f7 100644
--- a/checkpoint/restart.c
+++ b/checkpoint/restart.c
@@ -64,7 +64,7 @@ static int restore_debug_task(struct ckpt_ctx *ctx, int flags)
 
 	s = kmalloc(sizeof(*s), GFP_KERNEL);
 	if (!s) {
-		ckpt_debug("no memory to register ?!\n");
+		ckpt_error(ctx, "no memory to register ?!\n");
 		return -ENOMEM;
 	}
 	s->pid = current->pid;
@@ -197,13 +197,13 @@ static int _ckpt_read_err(struct ckpt_ctx *ctx, struct ckpt_hdr *h)
 	len = h->len - sizeof(*h);
 	ptr = kzalloc(len + 1, GFP_KERNEL);
 	if (!ptr) {
-		ckpt_debug("insufficient memory to report image error\n");
+		ckpt_error(ctx, "insufficient memory to report image error\n");
 		return -ENOMEM;
 	}
 
 	ret = ckpt_kread(ctx, ptr, len);
 	if (ret >= 0) {
-		ckpt_debug("%s\n", &ptr[1]);
+		ckpt_error(ctx, "%s\n", &ptr[1]);
 		ret = -EIO;
 	}
 
@@ -715,7 +715,7 @@ static void _restore_notify_error(struct ckpt_ctx *ctx, int errno)
 {
 	/* first to fail: notify everyone (racy but harmless) */
 	if (!ckpt_test_ctx_error(ctx)) {
-		ckpt_debug("setting restart error %d\n", errno); \
+		ckpt_error(ctx, "setting restart error %d\n", errno);
 		ckpt_set_ctx_error(ctx, errno);
 		complete(&ctx->complete);
 		wake_up_all(&ctx->waitq);
@@ -729,7 +729,8 @@ static void _restore_notify_error(struct ckpt_ctx *ctx, int errno)
 */
 #define restore_notify_error(ctx, errno) \
 do { \
-	ckpt_debug("restart error %d, root pid %d\n", errno, ctx->root_pid); \
+	ckpt_error(ctx, "restart error %d, root pid %d\n", errno, \
+		   ctx->root_pid); \
 	_restore_notify_error(ctx, errno); \
 } while(0)
 
@@ -753,7 +754,8 @@ static int set_task_ctx(struct task_struct *task, struct ckpt_ctx *ctx)
 		task->checkpoint_ctx = ckpt_ctx_get(ctx);
 		ret = 0;
 	} else {
-		ckpt_debug("task %d has checkpoint_ctx\n", task_pid_vnr(task));
+		ckpt_error(ctx, "task %d has checkpoint_ctx\n",
+			   task_pid_vnr(task));
 		ret = 1;
 	}
 	task_unlock(task);
@@ -803,7 +805,7 @@ static int restore_activate_next(struct ckpt_ctx *ctx)
 		rcu_read_unlock();
 
 		if (!task) {
-			ckpt_debug("could not find task %d\n", pid);
+			ckpt_error(ctx, "could not find task %d\n", pid);
 			restore_notify_error(ctx, -ESRCH);
 			return -ESRCH;
 		}
@@ -958,29 +960,38 @@ static int do_restore_task(void)
 	current->flags |= PF_RESTARTING;
 
 	ret = wait_sync_threads();
-	if (ret < 0)
+	if (ret < 0) {
+		ckpt_error(ctx, "wait_sync_threads ret %d\n", ret);
 		goto out;
+	}
 
 	/* wait for our turn, do the restore, and tell next task in line */
 	ret = wait_task_active(ctx);
-	if (ret < 0)
+	if (ret < 0) {
+		ckpt_error(ctx, "wait_task_active ret %d\n", ret);
 		goto out;
+	}
 
 	restore_debug_running(ctx);
 
 	ret = pre_restore_task();
-	if (ret < 0)
+	if (ret < 0) {
+		ckpt_error(ctx, "pre_restore_task ret %d\n", ret);
 		goto out;
+	}
 
 	zombie = restore_task(ctx);
 	if (zombie < 0) {
+		ckpt_error(ctx, "restore_task ret %d\n", ret);
 		ret = zombie;
 		goto out;
 	}
 
 	ret = restore_activate_next(ctx);
-	if (ret < 0)
+	if (ret < 0) {
+		ckpt_error(ctx, "restore_activate_next ret %d\n", ret);
 		goto out;
+	}
 
 	/*
 	 * zombie: we're done here; do_exit() will notice the @ctx on
@@ -1021,12 +1032,12 @@ static int __prepare_descendants(struct task_struct *task, void *data)
 	ckpt_debug("consider task %d\n", task_pid_vnr(task));
 
 	if (!ptrace_may_access(task, PTRACE_MODE_ATTACH)) {
-		ckpt_debug("stranger task %d\n", task_pid_vnr(task));
+		ckpt_error(ctx, "stranger task %d\n", task_pid_vnr(task));
 		return -EPERM;
 	}
 
 	if (task_ptrace(task) & PT_PTRACED) {
-		ckpt_debug("ptraced task %d\n", task_pid_vnr(task));
+		ckpt_error(ctx, "ptraced task %d\n", task_pid_vnr(task));
 		return -EBUSY;
 	}
 
@@ -1182,24 +1193,31 @@ static int do_restore_coord(struct ckpt_ctx *ctx, pid_t pid)
 	restore_debug_running(ctx);
 
 	ret = restore_read_header(ctx);
-	ckpt_debug("restore header: %d\n", ret);
-	if (ret < 0)
+	if (ret < 0) {
+		ckpt_error(ctx, "restore header: %d\n", ret);
 		return ret;
+	}
 	ret = restore_container(ctx);
-	ckpt_debug("restore container: %d\n", ret);
-	if (ret < 0)
+	if (ret < 0) {
+		ckpt_error(ctx, "restore container: %d\n", ret);
 		return ret;
+	}
 	ret = restore_read_tree(ctx);
-	ckpt_debug("restore tree: %d\n", ret);
-	if (ret < 0)
+	if (ret < 0) {
+		ckpt_error(ctx, "restore tree: %d\n", ret);
 		return ret;
+	}
 
-	if ((ctx->uflags & RESTART_TASKSELF) && ctx->nr_pids != 1)
+	if ((ctx->uflags & RESTART_TASKSELF) && ctx->nr_pids != 1) {
+		ckpt_error(ctx, "self-restart but nr_pids=%d\n", ctx->nr_pids);
 		return -EINVAL;
+	}
 
 	ret = init_restart_ctx(ctx, pid);
-	if (ret < 0)
+	if (ret < 0) {
+		ckpt_error(ctx, "init_restart_ctx returned %d\n", ret);
 		return ret;
+	}
 
 	/*
 	 * Populate own ->checkpoint_ctx: if an ancestor attempts to
@@ -1212,7 +1230,7 @@ static int do_restore_coord(struct ckpt_ctx *ctx, pid_t pid)
 		 * We are a bad-behaving descendant: an ancestor must
 		 * have prepare_descendants() us as part of a restart.
 		 */
-		ckpt_debug("coord already has checkpoint_ctx\n");
+		ckpt_error(ctx, "coord already has checkpoint_ctx\n");
 		return -EBUSY;
 	}
 
@@ -1224,35 +1242,45 @@ static int do_restore_coord(struct ckpt_ctx *ctx, pid_t pid)
 
 	if (ctx->uflags & RESTART_TASKSELF) {
 		ret = pre_restore_task();
-		ckpt_debug("pre restore task: %d\n", ret);
-		if (ret < 0)
+		if (ret < 0) {
+			ckpt_error(ctx, "pre restore task: %d\n", ret);
 			goto out;
+		}
 		ret = restore_task(ctx);
 		ckpt_debug("restore task: %d\n", ret);
-		if (ret < 0)
+		if (ret < 0) {
+			ckpt_error(ctx, "restore task: %d\n", ret);
 			goto out;
+		}
 	} else {
 		/* prepare descendants' t->checkpoint_ctx point to coord */
 		ret = prepare_descendants(ctx, ctx->root_task);
 		ckpt_debug("restore prepare: %d\n", ret);
-		if (ret < 0)
+		if (ret < 0) {
+			ckpt_error(ctx, "restore prepare: %d\n", ret);
 			goto out;
+		}
 		/* wait for all other tasks to complete do_restore_task() */
 		ret = wait_all_tasks_finish(ctx);
 		ckpt_debug("restore finish: %d\n", ret);
-		if (ret < 0)
+		if (ret < 0) {
+			ckpt_error(ctx, "wait_all_tasks_finish: %d\n", ret);
 			goto out;
+		}
 	}
 
 	ret = deferqueue_run(ctx->deferqueue);  /* run deferred work */
 	ckpt_debug("restore deferqueue: %d\n", ret);
-	if (ret < 0)
+	if (ret < 0) {
+		ckpt_error(ctx, "restore deferqueue: %d\n", ret);
 		goto out;
+	}
 
 	ret = restore_read_tail(ctx);
-	ckpt_debug("restore tail: %d\n", ret);
-	if (ret < 0)
+	if (ret < 0) {
+		ckpt_error(ctx, "restore tail: %d\n", ret);
 		goto out;
+	}
 
 	if (ctx->uflags & RESTART_FROZEN) {
 		ret = cgroup_freezer_make_frozen(ctx->root_task);
@@ -1364,7 +1392,7 @@ long do_restart(struct ckpt_ctx *ctx, pid_t pid, unsigned long flags)
 	if (!ctx || (ctx->uflags & RESTART_TASKSELF)) {
 		if (ret < 0) {
 			/* partial restore is undefined: terminate */
-			ckpt_debug("restart err %ld, exiting\n", ret);
+			ckpt_error(ctx, "restart err %ld, exiting\n", ret);
 			force_sig(SIGKILL, current);
 		} else {
 			ret = restore_retval();
-- 
1.6.1

[RFC PATCH 13/17] ckpt_error in checkpoint/files.c

[Serge Hallyn]

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

Convert two ckpt_debugs to ckpt_errors - however, given that they
are merely doubling information available in ckpt_write_err(), should
they simply be removed?

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

diff --git a/checkpoint/files.c b/checkpoint/files.c
index 1f2ab07..e67a13f 100644
--- a/checkpoint/files.c
+++ b/checkpoint/files.c
@@ -206,12 +206,14 @@ int checkpoint_file(struct ckpt_ctx *ctx, void *ptr)
 	if (!file->f_op || !file->f_op->checkpoint) {
 		ckpt_write_err(ctx, "%(T)%(E)%(P)%(S)f_op lacks checkpoint",
 			       -EBADF, file, file->f_op);
-		ckpt_debug("f_op lacks checkpoint handler: %pS\n", file->f_op);
+		ckpt_error(ctx, "%(T)f_op lacks checkpoint handler: %pS\n",
+			   file->f_op);
 		return -EBADF;
 	}
 	if (d_unlinked(file->f_dentry)) {
 		ckpt_write_err(ctx, "%(T)%(E)%(P)unlinked file", -EBADF, file);
-		ckpt_debug("unlinked files are unsupported\n");
+		ckpt_error(ctx, "%(T)%(P)unlinked files are unsupported\n",
+			   file);
 		return -EBADF;
 	}
 
-- 
1.6.1

[RFC PATCH 14/17] ckpt_error in checkpoint/process.c

[Serge Hallyn]

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/process.c |   10 +++++-----
 1 files changed, 5 insertions(+), 5 deletions(-)

diff --git a/checkpoint/process.c b/checkpoint/process.c
index e84683f..9f46769 100644
--- a/checkpoint/process.c
+++ b/checkpoint/process.c
@@ -581,14 +581,14 @@ static int restore_task_creds(struct ckpt_ctx *ctx)
 
 	realcred = ckpt_obj_fetch(ctx, h->cred_ref, CKPT_OBJ_CRED);
 	if (IS_ERR(realcred)) {
-		ckpt_debug("Error %ld fetching realcred (ref %d)\n",
+		ckpt_error(ctx, "%(T)Error %ld fetching realcred (ref %(O))\n",
 			PTR_ERR(realcred), h->cred_ref);
 		ret = PTR_ERR(realcred);
 		goto out;
 	}
 	ecred = ckpt_obj_fetch(ctx, h->ecred_ref, CKPT_OBJ_CRED);
 	if (IS_ERR(ecred)) {
-		ckpt_debug("Error %ld fetching ecred (ref %d)\n",
+		ckpt_error(ctx, "%(T)Error %ld fetching ecred (ref %(O))\n",
 			PTR_ERR(ecred), h->ecred_ref);
 		ret = PTR_ERR(ecred);
 		goto out;
@@ -614,18 +614,18 @@ static int restore_task_objs(struct ckpt_ctx *ctx)
 	 */
 	ret = restore_task_creds(ctx);
 	if (ret < 0) {
-		ckpt_debug("restore_task_creds returned %d\n", ret);
+		ckpt_error(ctx, "%(T)restore_task_creds returned %d\n", ret);
 		return ret;
 	}
 	ret = restore_task_ns(ctx);
 	if (ret < 0) {
-		ckpt_debug("restore_task_ns returned %d\n", ret);
+		ckpt_error(ctx, "%(T)restore_task_ns returned %d\n", ret);
 		return ret;
 	}
 
 	h = ckpt_read_obj_type(ctx, sizeof(*h), CKPT_HDR_TASK_OBJS);
 	if (IS_ERR(h)) {
-		ckpt_debug("Error fetching task obj\n");
+		ckpt_error(ctx, "%(T)Error %d fetching task obj\n", PTR_ERR(h));
 		return PTR_ERR(h);
 	}
 
-- 
1.6.1

[RFC PATCH 15/17] ckpt_error in ipc/checkpoint_msg.c

[Serge Hallyn]

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>
---
 ipc/checkpoint_msg.c |    2 +-
 1 files changed, 1 insertions(+), 1 deletions(-)

diff --git a/ipc/checkpoint_msg.c b/ipc/checkpoint_msg.c
index b933c19..806fe74 100644
--- a/ipc/checkpoint_msg.c
+++ b/ipc/checkpoint_msg.c
@@ -352,7 +352,7 @@ int restore_ipc_msg(struct ckpt_ctx *ctx, struct ipc_namespace *ns)
 	ret = load_ipc_msg_hdr(ctx, h, msq);
 
 	if (ret < 0) {
-		ckpt_debug("msq: need to remove (%d)\n", ret);
+		ckpt_error(ctx, "%(T)msq: need to remove (%d)\n", ret);
 		freeque(ns, perms);
 	} else
 		ipc_unlock(perms);
-- 
1.6.1

[RFC PATCH 16/17] ckpt_error in ipc/checkpoint_sem.c

[Serge Hallyn]

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>
---
 ipc/checkpoint_sem.c |    2 +-
 1 files changed, 1 insertions(+), 1 deletions(-)

diff --git a/ipc/checkpoint_sem.c b/ipc/checkpoint_sem.c
index 76eb2b9..0b610ee 100644
--- a/ipc/checkpoint_sem.c
+++ b/ipc/checkpoint_sem.c
@@ -209,7 +209,7 @@ int restore_ipc_sem(struct ckpt_ctx *ctx, struct ipc_namespace *ns)
 
 	ret = load_ipc_sem_hdr(ctx, h, sem);
 	if (ret < 0) {
-		ckpt_debug("sem: need to remove (%d)\n", ret);
+		ckpt_error(ctx, "%(T)sem: need to remove (%d)\n", ret);
 		freeary(ns, perms);
 	} else
 		ipc_unlock(perms);
-- 
1.6.1

[RFC PATCH 17/17] ckpt_error in ipc/checkpoint_shm.c

[Serge Hallyn]

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>
---
 ipc/checkpoint_shm.c |    2 +-
 1 files changed, 1 insertions(+), 1 deletions(-)

diff --git a/ipc/checkpoint_shm.c b/ipc/checkpoint_shm.c
index 826e430..eb9dc50 100644
--- a/ipc/checkpoint_shm.c
+++ b/ipc/checkpoint_shm.c
@@ -266,7 +266,7 @@ int restore_ipc_shm(struct ckpt_ctx *ctx, struct ipc_namespace *ns)
  mutex:
 	fput(file);
 	if (ret < 0) {
-		ckpt_debug("shm: need to remove (%d)\n", ret);
+		ckpt_error(ctx, "%(T)shm: need to remove (%d)\n", ret);
 		do_shm_rmid(ns, perms);
 	} else
 		ipc_unlock(perms);
-- 
1.6.1

Re: [RFC PATCH 01/17] ckpt_write_err: use single format with %(T) style tokens

[Matt Helsley]

On Tue, Oct 27, 2009 at 05:46:11PM -0500, Serge Hallyn wrote:
> From: Serge E. Hallyn <serue-r/Jw6+rmf7HQT0dZR+AlfA@public.gmane.org>
> 
> Matt Helsley originally suggested this to avoid having two
> format strings.  This is not bisect-safe and therefore not
> even compile-tested.  Every call to ckpt_write_err must be
> updated to use a single format.
> 
> Changelog: Oct 27: ensure %(T) has a closing paren
> 
> Signed-off-by: Serge E. Hallyn <serue-r/Jw6+rmf7HQT0dZR+AlfA@public.gmane.org>

Looks better to me. Thanks for taking a crack at this.

Acked-by: Matt Helsley <matthltc-r/Jw6+rmf7HQT0dZR+AlfA@public.gmane.org>

Cheers,
	-Matt Helsley

Re: [RFC PATCH 02/17] make ckpt_format_fmt non-static in checkpoint/sys.c

[Matt Helsley]

On Tue, Oct 27, 2009 at 05:46:12PM -0500, Serge Hallyn 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>

nit: Would be nice to see a brief description along the lines
"Heads up: here's why I'm moving this and making it non-static"

(No Ack because I haven't gotten through the series yet)

Cheers,
	-Matt Helsley

Re: [RFC PATCH 02/17] make ckpt_format_fmt non-static in checkpoint/sys.c

[Serge E. Hallyn]

Quoting Matt Helsley (matthltc-r/Jw6+rmf7HQT0dZR+AlfA@public.gmane.org):
> On Tue, Oct 27, 2009 at 05:46:12PM -0500, Serge Hallyn 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>
> 
> nit: Would be nice to see a brief description along the lines
> "Heads up: here's why I'm moving this and making it non-static"

Crap - i wrote one, but it must have gotten lost in one of
my several rebases.

> (No Ack because I haven't gotten through the series yet)
> 
> Cheers,
> 	-Matt Helsley
> _______________________________________________
> Containers mailing list
> Containers-cunTk1MwBs9QetFLy7KEm3xJsTq8ys+cHZ5vskTnxNA@public.gmane.org
> https://lists.linux-foundation.org/mailman/listinfo/containers

Re: [RFC PATCH 11/17] define function to print error messages to user log

[Matt Helsley]

On Tue, Oct 27, 2009 at 05:46:21PM -0500, Serge Hallyn wrote:
> From: Serge E. Hallyn <serue-r/Jw6+rmf7HQT0dZR+AlfA@public.gmane.org>
> 
> Error messages are both sent to an optional user-provided logfile,
> and, if CONFIG_CHECKPOINT_DEBUG=y, sent to syslog.
> 
> Changelog:
> 	Oct 27: add %(C) for ctx->total.
> 	Oct 26: Per Oren suggestion, return -EBADF for bad
> 		logfile in ckpt_ctx_alloc().
> 
> Signed-off-by: Serge E. Hallyn <serue-r/Jw6+rmf7HQT0dZR+AlfA@public.gmane.org>

Reviewed-by: Matt Helsley <matthltc-r/Jw6+rmf7HQT0dZR+AlfA@public.gmane.org>

> ---
>  checkpoint/objhash.c             |    2 +
>  checkpoint/sys.c                 |   67 +++++++++++++++++++++++++++++++++++---
>  include/linux/checkpoint.h       |    5 +++
>  include/linux/checkpoint_types.h |    1 +
>  include/linux/syscalls.h         |    5 ++-
>  5 files changed, 73 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 38e65e4..ab0f294 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;
> @@ -254,6 +256,12 @@ static struct ckpt_ctx *ckpt_ctx_alloc(int fd, unsigned long uflags,
>  	if (!ctx->file)
>  		goto err;
> 
> +	if (logfd != -1) {
> +		ctx->logfile = fget(logfd);
> +		if (!ctx->logfile)
> +			goto err;
> +	}
> +
>  	err = -ENOMEM;
>  	if (ckpt_obj_hash_alloc(ctx) < 0)
>  		goto err;
> @@ -401,6 +409,9 @@ char *ckpt_generate_fmt(struct ckpt_ctx *ctx, char *fmt)
>  		case 'E':
>  			len += sprintf(format+len, "[%s]", "err %d");
>  			break;
> +		case 'C': /* count of bytes read/written to checkpoint image */
> +			len += sprintf(format+len, "[%s]", "pos %d");
> +			break;

Instead we could always output ckpt->total and then we wouldn't need %(C). I
suspect it's such a useful piece of information that it'll be repeated
in many/all format strings eventually.

>  		case 'O':
>  			len += sprintf(format+len, "[%s]", "obj %d");
>  			break;
> @@ -435,6 +446,51 @@ char *ckpt_generate_fmt(struct ckpt_ctx *ctx, char *fmt)
>  	return format;
>  }
> 
> +void ckpt_log_error(struct ckpt_ctx *ctx, char *fmt, ...)
> +{
> +	mm_segment_t fs;
> +	struct file *file;
> +	int count;
> +	va_list ap, aq, az;
> +	char *format;
> +	char buf[200], *bufp = buf;

I believe this buffer is too big for a kernel stack -- especially
for ckpt_log_error() which might be invoked "deep" in
the kernel stack.

> +
> +	if (!ctx || !ctx->logfile)
> +		return;
> +	file = ctx->logfile;
> +
> +	va_start(ap, fmt);
> +	format = ckpt_generate_fmt(ctx, fmt);
> +	va_copy(aq, ap);
> +	va_copy(az, ap);
> +	/* I'm not clear here - can I re-use aq, or do i need
> +	 * a third copy? */

I'm no varargs expert but I have re-read the man page and
seen a purported snippet of the standard. :)

I think you need a third copy operation but you may only need
two va_lists so long as you do a va_end before the next va_copy:

	va_copy(aq, ap);
	... <use aq> ...
	va_end(aq);
	va_copy(aq, ap);
	... <use aq> ...
	va_end(aq);
	...
	va_end(ap); 

Based on my reading it sounded like some arch/ABIs require space
proportional to the number of arguments for each un-va_end-ed copy.

> +	count = vsnprintf(bufp, 200, format ? : fmt, aq);

BTW -- I think you can use snprintf() without the buffer and length
arguments if you just need the length calculated. Perhaps the same
is possible with vsnprintf():

	count = vsnprintf(NULL, 0, format ? : fmt, aq);

If that works with vsnprintf() too then you could get rid of the
stack buf and always kmalloc the space..

Cheers,
	-Matt Helsley

Re: [RFC PATCH 02/17] make ckpt_format_fmt non-static in checkpoint/sys.c

[Serge E. Hallyn]

Quoting Serge E. Hallyn (serue-r/Jw6+rmf7HQT0dZR+AlfA@public.gmane.org):
> Quoting Matt Helsley (matthltc-r/Jw6+rmf7HQT0dZR+AlfA@public.gmane.org):
> > On Tue, Oct 27, 2009 at 05:46:12PM -0500, Serge Hallyn 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>
> > 
> > nit: Would be nice to see a brief description along the lines
> > "Heads up: here's why I'm moving this and making it non-static"
> 
> Crap - i wrote one, but it must have gotten lost in one of
> my several rebases.

Can't find it.  For now, the reason is:

	We will use ckpt_format_fmt in ckpt_error() which is used
	(and far more useful) in restart as well.  So move it out
	of checkpoint.c and into sys.c.

Re: [RFC PATCH 11/17] define function to print error messages to user log

[Serge E. Hallyn]

Quoting Matt Helsley (matthltc-r/Jw6+rmf7HQT0dZR+AlfA@public.gmane.org):
> > @@ -401,6 +409,9 @@ char *ckpt_generate_fmt(struct ckpt_ctx *ctx, char *fmt)
> >  		case 'E':
> >  			len += sprintf(format+len, "[%s]", "err %d");
> >  			break;
> > +		case 'C': /* count of bytes read/written to checkpoint image */
> > +			len += sprintf(format+len, "[%s]", "pos %d");
> > +			break;
> 
> Instead we could always output ckpt->total and then we wouldn't need %(C). I
> suspect it's such a useful piece of information that it'll be repeated
> in many/all format strings eventually.

Yes, likewise %(T).  If that's what we want to do.

Should we discuss here what we want an entry to look like?  For both
ckpt_write_err (to the checkpoint image) and ckpt_error()?

> >  		case 'O':
> >  			len += sprintf(format+len, "[%s]", "obj %d");
> >  			break;
> > @@ -435,6 +446,51 @@ char *ckpt_generate_fmt(struct ckpt_ctx *ctx, char *fmt)
> >  	return format;
> >  }
> > 
> > +void ckpt_log_error(struct ckpt_ctx *ctx, char *fmt, ...)
> > +{
> > +	mm_segment_t fs;
> > +	struct file *file;
> > +	int count;
> > +	va_list ap, aq, az;
> > +	char *format;
> > +	char buf[200], *bufp = buf;
> 
> I believe this buffer is too big for a kernel stack -- especially
> for ckpt_log_error() which might be invoked "deep" in
> the kernel stack.

200 bytes?  Well, I guess I can try with 50 which still may often be
enough.

> > +	if (!ctx || !ctx->logfile)
> > +		return;
> > +	file = ctx->logfile;
> > +
> > +	va_start(ap, fmt);
> > +	format = ckpt_generate_fmt(ctx, fmt);
> > +	va_copy(aq, ap);
> > +	va_copy(az, ap);
> > +	/* I'm not clear here - can I re-use aq, or do i need
> > +	 * a third copy? */
> 
> I'm no varargs expert but I have re-read the man page and
> seen a purported snippet of the standard. :)
> 
> I think you need a third copy operation but you may only need
> two va_lists so long as you do a va_end before the next va_copy:
> 
> 	va_copy(aq, ap);
> 	... <use aq> ...
> 	va_end(aq);
> 	va_copy(aq, ap);
> 	... <use aq> ...
> 	va_end(aq);
> 	...
> 	va_end(ap); 
> 
> Based on my reading it sounded like some arch/ABIs require space
> proportional to the number of arguments for each un-va_end-ed copy.

Ok, I'll do that, thanks.

> > +	count = vsnprintf(bufp, 200, format ? : fmt, aq);
> 
> BTW -- I think you can use snprintf() without the buffer and length
> arguments if you just need the length calculated. Perhaps the same
> is possible with vsnprintf():
> 
> 	count = vsnprintf(NULL, 0, format ? : fmt, aq);
> 
> If that works with vsnprintf() too then you could get rid of the
> stack buf and always kmalloc the space..

Hmm, yeah...  though i don't know that I *want* to always kmalloc
the space :)  It does look like it should work (though no comment
to that effect), but there is no speed advantage, save a bit of
memcpy (vs. always having a kmalloc).

-serge

Re: [RFC PATCH 11/17] define function to print error messages to user log

[Oren Laadan]

Serge E. Hallyn wrote:
> Quoting Matt Helsley (matthltc-r/Jw6+rmf7HQT0dZR+AlfA@public.gmane.org):
>>> @@ -401,6 +409,9 @@ char *ckpt_generate_fmt(struct ckpt_ctx *ctx, char *fmt)
>>>  		case 'E':
>>>  			len += sprintf(format+len, "[%s]", "err %d");
>>>  			break;
>>> +		case 'C': /* count of bytes read/written to checkpoint image */
>>> +			len += sprintf(format+len, "[%s]", "pos %d");
>>> +			break;
>> Instead we could always output ckpt->total and then we wouldn't need %(C). I
>> suspect it's such a useful piece of information that it'll be repeated
>> in many/all format strings eventually.
> 
> Yes, likewise %(T).  If that's what we want to do.

I agree. For the cases when there is not task, can put "none"

> 
> Should we discuss here what we want an entry to look like?  For both
> ckpt_write_err (to the checkpoint image) and ckpt_error()?
> 

Yes please !

>>>  		case 'O':
>>>  			len += sprintf(format+len, "[%s]", "obj %d");
>>>  			break;
>>> @@ -435,6 +446,51 @@ char *ckpt_generate_fmt(struct ckpt_ctx *ctx, char *fmt)
>>>  	return format;
>>>  }
>>>
>>> +void ckpt_log_error(struct ckpt_ctx *ctx, char *fmt, ...)
>>> +{
>>> +	mm_segment_t fs;
>>> +	struct file *file;
>>> +	int count;
>>> +	va_list ap, aq, az;
>>> +	char *format;
>>> +	char buf[200], *bufp = buf;
>> I believe this buffer is too big for a kernel stack -- especially
>> for ckpt_log_error() which might be invoked "deep" in
>> the kernel stack.
> 
> 200 bytes?  Well, I guess I can try with 50 which still may often be
> enough.

How about using a dedicated buffer on @ctx for that ?

> 
>>> +	if (!ctx || !ctx->logfile)
>>> +		return;
>>> +	file = ctx->logfile;
>>> +
>>> +	va_start(ap, fmt);
>>> +	format = ckpt_generate_fmt(ctx, fmt);
>>> +	va_copy(aq, ap);
>>> +	va_copy(az, ap);
>>> +	/* I'm not clear here - can I re-use aq, or do i need
>>> +	 * a third copy? */
>> I'm no varargs expert but I have re-read the man page and
>> seen a purported snippet of the standard. :)
>>
>> I think you need a third copy operation but you may only need
>> two va_lists so long as you do a va_end before the next va_copy:
>>
>> 	va_copy(aq, ap);
>> 	... <use aq> ...
>> 	va_end(aq);
>> 	va_copy(aq, ap);
>> 	... <use aq> ...
>> 	va_end(aq);
>> 	...
>> 	va_end(ap); 
>>
>> Based on my reading it sounded like some arch/ABIs require space
>> proportional to the number of arguments for each un-va_end-ed copy.
> 
> Ok, I'll do that, thanks.
> 
>>> +	count = vsnprintf(bufp, 200, format ? : fmt, aq);
>> BTW -- I think you can use snprintf() without the buffer and length
>> arguments if you just need the length calculated. Perhaps the same
>> is possible with vsnprintf():
>>
>> 	count = vsnprintf(NULL, 0, format ? : fmt, aq);
>>
>> If that works with vsnprintf() too then you could get rid of the
>> stack buf and always kmalloc the space..
> 
> Hmm, yeah...  though i don't know that I *want* to always kmalloc
> the space :)  It does look like it should work (though no comment
> to that effect), but there is no speed advantage, save a bit of
> memcpy (vs. always having a kmalloc).

Again, a dedicated buffer on @ctx will be helpful here.

Oren.

Re: [RFC PATCH 11/17] define function to print error messages to user log

[Serge E. Hallyn]

Quoting Oren Laadan (orenl-RdfvBDnrOixBDgjK7y7TUQ@public.gmane.org):
> 
> 
> Serge E. Hallyn wrote:
> > Quoting Matt Helsley (matthltc-r/Jw6+rmf7HQT0dZR+AlfA@public.gmane.org):
> >>> @@ -401,6 +409,9 @@ char *ckpt_generate_fmt(struct ckpt_ctx *ctx, char *fmt)
> >>>  		case 'E':
> >>>  			len += sprintf(format+len, "[%s]", "err %d");
> >>>  			break;
> >>> +		case 'C': /* count of bytes read/written to checkpoint image */
> >>> +			len += sprintf(format+len, "[%s]", "pos %d");
> >>> +			break;
> >> Instead we could always output ckpt->total and then we wouldn't need %(C). I
> >> suspect it's such a useful piece of information that it'll be repeated
> >> in many/all format strings eventually.
> > 
> > Yes, likewise %(T).  If that's what we want to do.
> 
> I agree. For the cases when there is not task, can put "none"
> 
> > 
> > Should we discuss here what we want an entry to look like?  For both
> > ckpt_write_err (to the checkpoint image) and ckpt_error()?
> > 
> 
> Yes please !

Actually %T isn't the current task, right, so it shouldn't always be prepended?
It actually is only meaningful during checkpoint_task(), collect_objs(), and
__tree_count_tasks?

Ok, so how about:

	1. ckpt_write_err() always also calls ckpt_error() (which in turn calls
		ckpt_debug).  Avoid duplication which exists in several places
		right now.
	2. We always prepend:

		[current->pid]:[ctx->root_pid]:[ctx->active_pid]:[ctx->errno][ctx->total]

	The %(X) expansions if specified come whereever they are in the fmt
	string (which is what's happening now with my patchset).

Kind of long, but again this is for ckpt_error and ckpt_write_err, not for all
ckpt_debugs().

> >>>  		case 'O':
> >>>  			len += sprintf(format+len, "[%s]", "obj %d");
> >>>  			break;
> >>> @@ -435,6 +446,51 @@ char *ckpt_generate_fmt(struct ckpt_ctx *ctx, char *fmt)
> >>>  	return format;
> >>>  }
> >>>
> >>> +void ckpt_log_error(struct ckpt_ctx *ctx, char *fmt, ...)
> >>> +{
> >>> +	mm_segment_t fs;
> >>> +	struct file *file;
> >>> +	int count;
> >>> +	va_list ap, aq, az;
> >>> +	char *format;
> >>> +	char buf[200], *bufp = buf;
> >> I believe this buffer is too big for a kernel stack -- especially
> >> for ckpt_log_error() which might be invoked "deep" in
> >> the kernel stack.
> > 
> > 200 bytes?  Well, I guess I can try with 50 which still may often be
> > enough.
> 
> How about using a dedicated buffer on @ctx for that ?

I was going to do that originally, but then thought back to your
comments about parallel checkpoint, and didn't feel like also adding
a spinlock.

Thoughts?

-serge

Re: [RFC PATCH 02/17] make ckpt_format_fmt non-static in checkpoint/sys.c

[Serge E. Hallyn]

Quoting Matt Helsley (matthltc-r/Jw6+rmf7HQT0dZR+AlfA@public.gmane.org):
> On Tue, Oct 27, 2009 at 05:46:12PM -0500, Serge Hallyn 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>
> 
> nit: Would be nice to see a brief description along the lines
> "Heads up: here's why I'm moving this and making it non-static"
> 
> (No Ack because I haven't gotten through the series yet)

Here is a slightly updated version with an actual (still terse)
description.  and with comment above ckpt_generate_fmt() fixed.

From 4f4200f7c12129049b1aafdbea3816e9ff53c1d4 Mon Sep 17 00:00:00 2001
From: Serge E. Hallyn <serue-r/Jw6+rmf7HQT0dZR+AlfA@public.gmane.org>
Date: Tue, 27 Oct 2009 10:39:49 -0400
Subject: [PATCH 02/17] make ckpt_generate_fmt non-static in checkpoint/sys.c

We will use ckpt_generate_fmt in ckpt_error(), which is also
used in restart, so checkpoint/checkpoint.h is not the right
place for it.

Changelog:
	Oct 28: also fix comment above ckpt_generate_fmt()

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

diff --git a/checkpoint/checkpoint.c b/checkpoint/checkpoint.c
index 404bf08..c6be4f9 100644
--- a/checkpoint/checkpoint.c
+++ b/checkpoint/checkpoint.c
@@ -96,104 +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);
 }
 
-/*
- * __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 *fmt)
-{
-	static int warn_prefmt = 0;
-	char *format;
-	int alloclen, len = 0;
-	int first = 1;
-
-	/*
-	 * 17 for "pid %d" (plus space)
-	 * 21 for "tsk %s" (tsk->comm)
-	 * up to 8 per varfmt entry
-	 */
-	alloclen = 37 + 8 * strlen(fmt);
-	format = kzalloc(alloclen, GFP_KERNEL);
-	if (!format)
-		return NULL;
-
-	for (; *fmt; fmt++) {
-		BUG_ON(len > alloclen);
-		if (*fmt != '%' || fmt[1] != '(' || fmt[3] != ')') {
-			format[len++] = *fmt;
-			continue;
-		}
-		if (!first)
-			format[len++] = ' ';
-		else
-			first = 0;
-		switch(fmt[2]) {
-		case 'E':
-			len += sprintf(format+len, "[%s]", "err %d");
-			break;
-		case 'O':
-			len += sprintf(format+len, "[%s]", "obj %d");
-			break;
-		case 'P':
-			len += sprintf(format+len, "[%s]", "ptr %p");
-			break;
-		case 'V':
-			len += sprintf(format+len, "[%s]", "sym %pS");
-			break;
-		case 'S':
-			len += sprintf(format+len, "[%s]", "str %s");
-			break;
-		case 'T':
-			if (ctx->tsk)
-				len += sprintf(format+len, "[pid %d tsk %s]",
-				      task_pid_vnr(ctx->tsk), ctx->tsk->comm);
-			else 
-				len += sprintf(format+len, "[pid -1 tsk NULL]");
-			break;
-		default:
-			if (warn_prefmt++ < 5)
-				printk(KERN_ERR
-					"c/r: bad format specifier %c\n",
-					fmt[2]);
-			BUG();
-		}
-
-		fmt += 3;
-	}
-	format[len] = '\0';
-
-	return format;
-}
-
-/* see _ckpt_generate_fmt for information on @fmt0 */
+/* see ckpt_generate_fmt for information on @fmt extensions */
 static void __ckpt_generate_err(struct ckpt_ctx *ctx, char *fmt, va_list ap)
 {
 	va_list aq;
@@ -201,7 +104,7 @@ static void __ckpt_generate_err(struct ckpt_ctx *ctx, char *fmt, va_list ap)
 	char *str;
 	int len;
 
-	format = __ckpt_generate_fmt(ctx, fmt);
+	format = ckpt_generate_fmt(ctx, fmt);
 	va_copy(aq, ap);
 
 	/*
@@ -231,7 +134,6 @@ static void __ckpt_generate_err(struct ckpt_ctx *ctx, char *fmt, va_list ap)
  * @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 *fmt, ...)
@@ -250,7 +152,6 @@ void __ckpt_write_err(struct ckpt_ctx *ctx, char *fmt, ...)
  * @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 *fmt, ...)
diff --git a/checkpoint/sys.c b/checkpoint/sys.c
index 260a1ee..a1c26e3 100644
--- a/checkpoint/sys.c
+++ b/checkpoint/sys.c
@@ -339,6 +339,104 @@ int walk_task_subtree(struct task_struct *root,
 	return (ret < 0 ? ret : total);
 }
 
+/*
+ * ckpt_generate_fmt - generate standard checkpoint error message
+ * @ctx: checkpoint context
+ * @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 @fmt by subtituting format snippets
+ * according to the contents of @fmt.  The format characters in
+ * @fmt can be %(E) (error), %(O) (objref), %(P) (pointer), %(S) (string),
+ * %(C) (bytes read/written out of checkpoint image so far), * and %(V)
+ * (variable/symbol). For example, %(E) will generate a "err %d"
+ * in PREFMT.
+ *
+ * If @fmt 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.
+ *
+ * XXX Do we want 'T' and 'C' to simply always be prepended?
+ */
+char *ckpt_generate_fmt(struct ckpt_ctx *ctx, char *fmt)
+{
+	static int warn_prefmt = 0;
+	char *format;
+	int alloclen, len = 0;
+	int first = 1;
+
+	/*
+	 * 17 for "pid %d" (plus space)
+	 * 21 for "tsk %s" (tsk->comm)
+	 * up to 8 per varfmt entry
+	 */
+	alloclen = 37 + 8 * strlen(fmt);
+	format = kzalloc(alloclen, GFP_KERNEL);
+	if (!format)
+		return NULL;
+
+	for (; *fmt; fmt++) {
+		BUG_ON(len > alloclen);
+		if (*fmt != '%' || fmt[1] != '(' || fmt[3] != ')') {
+			format[len++] = *fmt;
+			continue;
+		}
+		if (!first)
+			format[len++] = ' ';
+		else
+			first = 0;
+		switch(fmt[2]) {
+		case 'E':
+			len += sprintf(format+len, "[%s]", "err %d");
+			break;
+		case 'O':
+			len += sprintf(format+len, "[%s]", "obj %d");
+			break;
+		case 'P':
+			len += sprintf(format+len, "[%s]", "ptr %p");
+			break;
+		case 'V':
+			len += sprintf(format+len, "[%s]", "sym %pS");
+			break;
+		case 'S':
+			len += sprintf(format+len, "[%s]", "str %s");
+			break;
+		case 'T':
+			if (ctx->tsk)
+				len += sprintf(format+len, "[pid %d tsk %s]",
+				      task_pid_vnr(ctx->tsk), ctx->tsk->comm);
+			else 
+				len += sprintf(format+len, "[pid -1 tsk NULL]");
+			break;
+		default:
+			if (warn_prefmt++ < 5)
+				printk(KERN_ERR
+					"c/r: bad format specifier %c\n",
+					fmt[2]);
+			BUG();
+		}
+
+		fmt += 3;
+	}
+	format[len] = '\0';
+
+	return format;
+}
 
 /**
  * sys_checkpoint - checkpoint a container
diff --git a/include/linux/checkpoint.h b/include/linux/checkpoint.h
index 224b494..8a1eaa7 100644
--- a/include/linux/checkpoint.h
+++ b/include/linux/checkpoint.h
@@ -371,6 +371,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 *fmt);
+
 #endif /* CONFIG_CHECKPOINT */
 #endif /* __KERNEL__ */
 
-- 
1.6.1

Re: [RFC PATCH 11/17] define function to print error messages to user log

[Oren Laadan]

Serge E. Hallyn wrote:
> Quoting Oren Laadan (orenl-RdfvBDnrOixBDgjK7y7TUQ@public.gmane.org):
>>
>> Serge E. Hallyn wrote:
>>> Quoting Matt Helsley (matthltc-r/Jw6+rmf7HQT0dZR+AlfA@public.gmane.org):
>>>>> @@ -401,6 +409,9 @@ char *ckpt_generate_fmt(struct ckpt_ctx *ctx, char *fmt)
>>>>>  		case 'E':
>>>>>  			len += sprintf(format+len, "[%s]", "err %d");
>>>>>  			break;
>>>>> +		case 'C': /* count of bytes read/written to checkpoint image */
>>>>> +			len += sprintf(format+len, "[%s]", "pos %d");
>>>>> +			break;
>>>> Instead we could always output ckpt->total and then we wouldn't need %(C). I
>>>> suspect it's such a useful piece of information that it'll be repeated
>>>> in many/all format strings eventually.
>>> Yes, likewise %(T).  If that's what we want to do.
>> I agree. For the cases when there is not task, can put "none"
>>
>>> Should we discuss here what we want an entry to look like?  For both
>>> ckpt_write_err (to the checkpoint image) and ckpt_error()?
>>>
>> Yes please !
> 
> Actually %T isn't the current task, right, so it shouldn't always be prepended?
> It actually is only meaningful during checkpoint_task(), collect_objs(), and
> __tree_count_tasks?
> 
> Ok, so how about:
> 
> 	1. ckpt_write_err() always also calls ckpt_error() (which in turn calls
> 		ckpt_debug).  Avoid duplication which exists in several places
> 		right now.
> 	2. We always prepend:
> 
> 		[current->pid]:[ctx->root_pid]:[ctx->active_pid]:[ctx->errno][ctx->total]
> 
> 	The %(X) expansions if specified come whereever they are in the fmt
> 	string (which is what's happening now with my patchset).

So somewhere should set ctx->errno during a checkpoint.

I suppose active_pid is for restart, but it's redundant isn't it ?
(it's always active_pid) - is it the different between top-level pid-ns
and "current" pid-ns ?

Instead of writing root_pid repeatedly, why not write sometime at the
beginning some "global" info about the checkpoint/restart ?  (e.g.
the root_pid ...)

> 
> Kind of long, but again this is for ckpt_error and ckpt_write_err, not for all
> ckpt_debugs().
> 
>>>>>  		case 'O':
>>>>>  			len += sprintf(format+len, "[%s]", "obj %d");
>>>>>  			break;
>>>>> @@ -435,6 +446,51 @@ char *ckpt_generate_fmt(struct ckpt_ctx *ctx, char *fmt)
>>>>>  	return format;
>>>>>  }
>>>>>
>>>>> +void ckpt_log_error(struct ckpt_ctx *ctx, char *fmt, ...)
>>>>> +{
>>>>> +	mm_segment_t fs;
>>>>> +	struct file *file;
>>>>> +	int count;
>>>>> +	va_list ap, aq, az;
>>>>> +	char *format;
>>>>> +	char buf[200], *bufp = buf;
>>>> I believe this buffer is too big for a kernel stack -- especially
>>>> for ckpt_log_error() which might be invoked "deep" in
>>>> the kernel stack.
>>> 200 bytes?  Well, I guess I can try with 50 which still may often be
>>> enough.
>> How about using a dedicated buffer on @ctx for that ?
> 
> I was going to do that originally, but then thought back to your
> comments about parallel checkpoint, and didn't feel like also adding
> a spinlock.

We _will_ have some sort of locking when doing a parallel checkpoint.

So when we get there either use that lock, or (what I believe is more
likely) create a per-checkpointer sub-data structure (a-la per-cpu).

Oren.

Re: [RFC PATCH 11/17] define function to print error messages to user log

[Serge E. Hallyn]

Quoting Oren Laadan (orenl-RdfvBDnrOixBDgjK7y7TUQ@public.gmane.org):
> 
> 
> Serge E. Hallyn wrote:
> > Quoting Oren Laadan (orenl-RdfvBDnrOixBDgjK7y7TUQ@public.gmane.org):
> >>
> >> Serge E. Hallyn wrote:
> >>> Quoting Matt Helsley (matthltc-r/Jw6+rmf7HQT0dZR+AlfA@public.gmane.org):
> >>>>> @@ -401,6 +409,9 @@ char *ckpt_generate_fmt(struct ckpt_ctx *ctx, char *fmt)
> >>>>>  		case 'E':
> >>>>>  			len += sprintf(format+len, "[%s]", "err %d");
> >>>>>  			break;
> >>>>> +		case 'C': /* count of bytes read/written to checkpoint image */
> >>>>> +			len += sprintf(format+len, "[%s]", "pos %d");
> >>>>> +			break;
> >>>> Instead we could always output ckpt->total and then we wouldn't need %(C). I
> >>>> suspect it's such a useful piece of information that it'll be repeated
> >>>> in many/all format strings eventually.
> >>> Yes, likewise %(T).  If that's what we want to do.
> >> I agree. For the cases when there is not task, can put "none"
> >>
> >>> Should we discuss here what we want an entry to look like?  For both
> >>> ckpt_write_err (to the checkpoint image) and ckpt_error()?
> >>>
> >> Yes please !
> > 
> > Actually %T isn't the current task, right, so it shouldn't always be prepended?
> > It actually is only meaningful during checkpoint_task(), collect_objs(), and
> > __tree_count_tasks?
> > 
> > Ok, so how about:
> > 
> > 	1. ckpt_write_err() always also calls ckpt_error() (which in turn calls
> > 		ckpt_debug).  Avoid duplication which exists in several places
> > 		right now.
> > 	2. We always prepend:
> > 
> > 		[current->pid]:[ctx->root_pid]:[ctx->active_pid]:[ctx->errno][ctx->total]
> > 
> > 	The %(X) expansions if specified come whereever they are in the fmt
> > 	string (which is what's happening now with my patchset).
> 
> So somewhere should set ctx->errno during a checkpoint.
> 
> I suppose active_pid is for restart, but it's redundant isn't it ?
> (it's always active_pid) - is it the different between top-level pid-ns
> and "current" pid-ns ?

No, I figured it would be meaningful for instance in places like
wait_task_active().

> Instead of writing root_pid repeatedly, why not write sometime at the
> beginning some "global" info about the checkpoint/restart ?  (e.g.
> the root_pid ...)

Well it is written out (for restart) at the end, so I suppose I should
switch restore_debug_free() to using ckpt_error() instead of ckpt_debug().

> > Kind of long, but again this is for ckpt_error and ckpt_write_err, not for all
> > ckpt_debugs().
> > 
> >>>>>  		case 'O':
> >>>>>  			len += sprintf(format+len, "[%s]", "obj %d");
> >>>>>  			break;
> >>>>> @@ -435,6 +446,51 @@ char *ckpt_generate_fmt(struct ckpt_ctx *ctx, char *fmt)
> >>>>>  	return format;
> >>>>>  }
> >>>>>
> >>>>> +void ckpt_log_error(struct ckpt_ctx *ctx, char *fmt, ...)
> >>>>> +{
> >>>>> +	mm_segment_t fs;
> >>>>> +	struct file *file;
> >>>>> +	int count;
> >>>>> +	va_list ap, aq, az;
> >>>>> +	char *format;
> >>>>> +	char buf[200], *bufp = buf;
> >>>> I believe this buffer is too big for a kernel stack -- especially
> >>>> for ckpt_log_error() which might be invoked "deep" in
> >>>> the kernel stack.
> >>> 200 bytes?  Well, I guess I can try with 50 which still may often be
> >>> enough.
> >> How about using a dedicated buffer on @ctx for that ?
> > 
> > I was going to do that originally, but then thought back to your
> > comments about parallel checkpoint, and didn't feel like also adding
> > a spinlock.
> 
> We _will_ have some sort of locking when doing a parallel checkpoint.

Ok, so I'll set aside a big buffer and I'll just do a spinlock for now.

> So when we get there either use that lock, or (what I believe is more
> likely) create a per-checkpointer sub-data structure (a-la per-cpu).
> 
> Oren.

Re: [RFC PATCH 11/17] define function to print error messages to user log

[Oren Laadan]

Serge E. Hallyn wrote:
> Quoting Oren Laadan (orenl-RdfvBDnrOixBDgjK7y7TUQ@public.gmane.org):
>>
>> Serge E. Hallyn wrote:
>>> Quoting Oren Laadan (orenl-RdfvBDnrOixBDgjK7y7TUQ@public.gmane.org):
>>>> Serge E. Hallyn wrote:
>>>>> Quoting Matt Helsley (matthltc-r/Jw6+rmf7HQT0dZR+AlfA@public.gmane.org):
>>>>>>> @@ -401,6 +409,9 @@ char *ckpt_generate_fmt(struct ckpt_ctx *ctx, char *fmt)
>>>>>>>  		case 'E':
>>>>>>>  			len += sprintf(format+len, "[%s]", "err %d");
>>>>>>>  			break;
>>>>>>> +		case 'C': /* count of bytes read/written to checkpoint image */
>>>>>>> +			len += sprintf(format+len, "[%s]", "pos %d");
>>>>>>> +			break;
>>>>>> Instead we could always output ckpt->total and then we wouldn't need %(C). I
>>>>>> suspect it's such a useful piece of information that it'll be repeated
>>>>>> in many/all format strings eventually.
>>>>> Yes, likewise %(T).  If that's what we want to do.
>>>> I agree. For the cases when there is not task, can put "none"
>>>>
>>>>> Should we discuss here what we want an entry to look like?  For both
>>>>> ckpt_write_err (to the checkpoint image) and ckpt_error()?
>>>>>
>>>> Yes please !
>>> Actually %T isn't the current task, right, so it shouldn't always be prepended?
>>> It actually is only meaningful during checkpoint_task(), collect_objs(), and
>>> __tree_count_tasks?
>>>
>>> Ok, so how about:
>>>
>>> 	1. ckpt_write_err() always also calls ckpt_error() (which in turn calls
>>> 		ckpt_debug).  Avoid duplication which exists in several places
>>> 		right now.
>>> 	2. We always prepend:
>>>
>>> 		[current->pid]:[ctx->root_pid]:[ctx->active_pid]:[ctx->errno][ctx->total]
>>>
>>> 	The %(X) expansions if specified come whereever they are in the fmt
>>> 	string (which is what's happening now with my patchset).
>> So somewhere should set ctx->errno during a checkpoint.
>>
>> I suppose active_pid is for restart, but it's redundant isn't it ?
>> (it's always active_pid) - is it the different between top-level pid-ns
>> and "current" pid-ns ?
> 
> No, I figured it would be meaningful for instance in places like
> wait_task_active().

Perhaps then leave it out of the default printing, and have the
specific debug messages there write it explicitly.

> 
>> Instead of writing root_pid repeatedly, why not write sometime at the
>> beginning some "global" info about the checkpoint/restart ?  (e.g.
>> the root_pid ...)
> 
> Well it is written out (for restart) at the end, so I suppose I should
> switch restore_debug_free() to using ckpt_error() instead of ckpt_debug().

Yes, that will be helpful to reduce the noise :)

Oren.

Re: [RFC PATCH 11/17] define function to print error messages to user log

[Serge E. Hallyn]

Quoting Oren Laadan (orenl-RdfvBDnrOixBDgjK7y7TUQ@public.gmane.org):
> 
> 
> Serge E. Hallyn wrote:
> > Quoting Oren Laadan (orenl-RdfvBDnrOixBDgjK7y7TUQ@public.gmane.org):
> >>
> >> Serge E. Hallyn wrote:
> >>> Quoting Oren Laadan (orenl-RdfvBDnrOixBDgjK7y7TUQ@public.gmane.org):
> >>>> Serge E. Hallyn wrote:
> >>>>> Quoting Matt Helsley (matthltc-r/Jw6+rmf7HQT0dZR+AlfA@public.gmane.org):
> >>>>>>> @@ -401,6 +409,9 @@ char *ckpt_generate_fmt(struct ckpt_ctx *ctx, char *fmt)
> >>>>>>>  		case 'E':
> >>>>>>>  			len += sprintf(format+len, "[%s]", "err %d");
> >>>>>>>  			break;
> >>>>>>> +		case 'C': /* count of bytes read/written to checkpoint image */
> >>>>>>> +			len += sprintf(format+len, "[%s]", "pos %d");
> >>>>>>> +			break;
> >>>>>> Instead we could always output ckpt->total and then we wouldn't need %(C). I
> >>>>>> suspect it's such a useful piece of information that it'll be repeated
> >>>>>> in many/all format strings eventually.
> >>>>> Yes, likewise %(T).  If that's what we want to do.
> >>>> I agree. For the cases when there is not task, can put "none"
> >>>>
> >>>>> Should we discuss here what we want an entry to look like?  For both
> >>>>> ckpt_write_err (to the checkpoint image) and ckpt_error()?
> >>>>>
> >>>> Yes please !
> >>> Actually %T isn't the current task, right, so it shouldn't always be prepended?
> >>> It actually is only meaningful during checkpoint_task(), collect_objs(), and
> >>> __tree_count_tasks?
> >>>
> >>> Ok, so how about:
> >>>
> >>> 	1. ckpt_write_err() always also calls ckpt_error() (which in turn calls
> >>> 		ckpt_debug).  Avoid duplication which exists in several places
> >>> 		right now.
> >>> 	2. We always prepend:
> >>>
> >>> 		[current->pid]:[ctx->root_pid]:[ctx->active_pid]:[ctx->errno][ctx->total]
> >>>
> >>> 	The %(X) expansions if specified come whereever they are in the fmt
> >>> 	string (which is what's happening now with my patchset).
> >> So somewhere should set ctx->errno during a checkpoint.
> >>
> >> I suppose active_pid is for restart, but it's redundant isn't it ?
> >> (it's always active_pid) - is it the different between top-level pid-ns
> >> and "current" pid-ns ?
> > 
> > No, I figured it would be meaningful for instance in places like
> > wait_task_active().
> 
> Perhaps then leave it out of the default printing, and have the
> specific debug messages there write it explicitly.

Ok, so then current suggested format looks like:

[current->pid]:[ctx->errno]:[ctx->total]

Though is ctx->errno helpful even in restart?  Or should we assume we'll
figure that out through the msg in restore_notify_error()?

Maybe do:
[current->pid]=[task_pid_vnr(current)]:[ctx->total]

> >> Instead of writing root_pid repeatedly, why not write sometime at the
> >> beginning some "global" info about the checkpoint/restart ?  (e.g.
> >> the root_pid ...)
> > 
> > Well it is written out (for restart) at the end, so I suppose I should
> > switch restore_debug_free() to using ckpt_error() instead of ckpt_debug().
> 
> Yes, that will be helpful to reduce the noise :)

-serge

Re: [RFC PATCH 11/17] define function to print error messages to user log

[Oren Laadan]

Serge E. Hallyn wrote:
> Quoting Oren Laadan (orenl-RdfvBDnrOixBDgjK7y7TUQ@public.gmane.org):
>>
>> Serge E. Hallyn wrote:
>>> Quoting Oren Laadan (orenl-RdfvBDnrOixBDgjK7y7TUQ@public.gmane.org):
>>>> Serge E. Hallyn wrote:
>>>>> Quoting Oren Laadan (orenl-RdfvBDnrOixBDgjK7y7TUQ@public.gmane.org):
>>>>>> Serge E. Hallyn wrote:
>>>>>>> Quoting Matt Helsley (matthltc-r/Jw6+rmf7HQT0dZR+AlfA@public.gmane.org):
>>>>>>>>> @@ -401,6 +409,9 @@ char *ckpt_generate_fmt(struct ckpt_ctx *ctx, char *fmt)
>>>>>>>>>  		case 'E':
>>>>>>>>>  			len += sprintf(format+len, "[%s]", "err %d");
>>>>>>>>>  			break;
>>>>>>>>> +		case 'C': /* count of bytes read/written to checkpoint image */
>>>>>>>>> +			len += sprintf(format+len, "[%s]", "pos %d");
>>>>>>>>> +			break;
>>>>>>>> Instead we could always output ckpt->total and then we wouldn't need %(C). I
>>>>>>>> suspect it's such a useful piece of information that it'll be repeated
>>>>>>>> in many/all format strings eventually.
>>>>>>> Yes, likewise %(T).  If that's what we want to do.
>>>>>> I agree. For the cases when there is not task, can put "none"
>>>>>>
>>>>>>> Should we discuss here what we want an entry to look like?  For both
>>>>>>> ckpt_write_err (to the checkpoint image) and ckpt_error()?
>>>>>>>
>>>>>> Yes please !
>>>>> Actually %T isn't the current task, right, so it shouldn't always be prepended?
>>>>> It actually is only meaningful during checkpoint_task(), collect_objs(), and
>>>>> __tree_count_tasks?
>>>>>
>>>>> Ok, so how about:
>>>>>
>>>>> 	1. ckpt_write_err() always also calls ckpt_error() (which in turn calls
>>>>> 		ckpt_debug).  Avoid duplication which exists in several places
>>>>> 		right now.
>>>>> 	2. We always prepend:
>>>>>
>>>>> 		[current->pid]:[ctx->root_pid]:[ctx->active_pid]:[ctx->errno][ctx->total]
>>>>>
>>>>> 	The %(X) expansions if specified come whereever they are in the fmt
>>>>> 	string (which is what's happening now with my patchset).
>>>> So somewhere should set ctx->errno during a checkpoint.
>>>>
>>>> I suppose active_pid is for restart, but it's redundant isn't it ?
>>>> (it's always active_pid) - is it the different between top-level pid-ns
>>>> and "current" pid-ns ?
>>> No, I figured it would be meaningful for instance in places like
>>> wait_task_active().
>> Perhaps then leave it out of the default printing, and have the
>> specific debug messages there write it explicitly.
> 
> Ok, so then current suggested format looks like:
> 
> [current->pid]:[ctx->errno]:[ctx->total]
> 
> Though is ctx->errno helpful even in restart?  Or should we assume we'll
> figure that out through the msg in restore_notify_error()?
> 
> Maybe do:
> [current->pid]=[task_pid_vnr(current)]:[ctx->total]

I think errno is only helpful if an error occured.

So it should definitely be a part of the default msg given by
ckpt_error(), but not otherwise.

Oren.