[PATCH 00/17] Standardize c/r error reporting

[PATCH 00/17] Standardize c/r error reporting

[serue-r/Jw6+rmf7HQT0dZR+AlfA]

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

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

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

I'm sure we'll want another round if only to alter the format,
but I'm finding it very useful as is.

(As more callers are added I expect we'll want to add %(A) to
the format to indicate active_pid should be printed).

-serge

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

[serue-r/Jw6+rmf7HQT0dZR+AlfA]

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 29: merge with the next patch, moving ckpt_generate_fmt()
		into checkpoing/sys.c and making it non-static so that
		we can use it in ckpt_error().
	Oct 28: also fix comment above ckpt_generate_fmt()
	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    |  105 +++-----------------------------------------
 checkpoint/sys.c           |   95 +++++++++++++++++++++++++++++++++++++++
 include/linux/checkpoint.h |   13 +++--
 3 files changed, 110 insertions(+), 103 deletions(-)

diff --git a/checkpoint/checkpoint.c b/checkpoint/checkpoint.c
index 6eb8f3b..c6be4f9 100644
--- a/checkpoint/checkpoint.c
+++ b/checkpoint/checkpoint.c
@@ -96,104 +96,15 @@ int ckpt_write_string(struct ckpt_ctx *ctx, char *str, int len)
 	return ckpt_write_obj_type(ctx, str, len, CKPT_HDR_STRING);
 }
 
-/*
- * __ckpt_generate_fmt - generate standard checkpoint error message
- * @ctx: checkpoint context
- * @fmt0: c/r-format string
- * @fmt: message format
- *
- * This generates a unified format of checkpoint error messages, to
- * ease (after the failure) inspection by userspace tools. It converts
- * the (printf) message @fmt into a new format: "[PREFMT]: fmt".
- *
- * PREFMT is constructed from @fmt0 by subtituting format snippets
- * according to the contents of @fmt0.  The format characters in
- * @fmt0 can be E (error), O (objref), P (pointer), S (string) and
- * V (variable/symbol). For example, E will generate a "err %d" in
- * PREFMT (see prefmt_array below).
- *
- * If @fmt0 begins with T, PREFMT will begin with "pid %d tsk %s"
- * with the pid and the tsk->comm of the currently checkpointed task.
- * The latter is taken from ctx->tsk, and is it the responsbilility of
- * the caller to have a valid pointer there (in particular, functions
- * that iterate on the processes: collect_objects, checkpoint_task,
- * and tree_count_tasks).
- *
- * The caller of ckpt_write_err() and _ckpt_write_err() must provide
- * the additional variabes, in order, to match the @fmt0 (except for
- * the T key), e.g.:
- *
- *   ckpt_writ_err(ctx, "TEO", "FILE flags %d", err, objref, flags);
- *
- * Here, T is simply passed, E expects an integer (err), O expects an
- * integer (objref), and the last argument matches the format string.
- */
-static char *__ckpt_generate_fmt(struct ckpt_ctx *ctx, char *fmt0, char *fmt)
-{
-	static int warn_notask = 0;
-	static int warn_prefmt = 0;
-	char *format;
-	int i, j, len = 0;
-
-	static struct {
-		char key;
-		char *fmt;
-	} prefmt_array[] = {
-		{ 'E', "err %d" },
-		{ 'O', "obj %d" },
-		{ 'P', "ptr %p" },
-		{ 'V', "sym %pS" },
-		{ 'S', "str %s" },
-		{ 0, "??? %pS" },
-	};
-
-	/*
-	 * 17 for "pid %d" (plus space)
-	 * 21 for "tsk %s" (tsk->comm)
-	 * up to 8 per varfmt entry
-	 */
-	format = kzalloc(37 + 8 * strlen(fmt0) + strlen(fmt), GFP_KERNEL);
-	if (!format)
-		return NULL;
-
-	format[len++] = '[';
-
-	if (fmt0[0] == 'T') {
-		if (ctx->tsk)
-			len = sprintf(format, "pid %d tsk %s ",
-				      task_pid_vnr(ctx->tsk), ctx->tsk->comm);
-		else if (warn_notask++ < 5)
-			printk(KERN_ERR "c/r: no target task set\n");
-		fmt0++;
-	}
-
-	for (i = 0; i < strlen(fmt0); i++) {
-		for (j = 0; prefmt_array[j].key; j++)
-			if (prefmt_array[j].key == fmt0[i])
-				break;
-		if (!prefmt_array[j].key && warn_prefmt++ < 5)
-			printk(KERN_ERR "c/r: unknown prefmt %c\n", fmt0[i]);
-		len += sprintf(&format[len], "%s ", prefmt_array[j].fmt);
-	}
-
-	if (len > 1)
-		sprintf(&format[len-1], "]: %s", fmt);  /* erase last space */
-	else
-		sprintf(format, "%s", fmt);
-
-	return format;
-}
-
-/* see _ckpt_generate_fmt for information on @fmt0 */
-static void __ckpt_generate_err(struct ckpt_ctx *ctx, char *fmt0,
-				char *fmt, va_list ap)
+/* 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;
 	char *format;
 	char *str;
 	int len;
 
-	format = __ckpt_generate_fmt(ctx, fmt0, fmt);
+	format = ckpt_generate_fmt(ctx, fmt);
 	va_copy(aq, ap);
 
 	/*
@@ -223,15 +134,14 @@ static void __ckpt_generate_err(struct ckpt_ctx *ctx, char *fmt0,
  * @fmt: message format
  * @...: arguments
  *
- * See _ckpt_generate_fmt for information on @fmt0.
  * Use this during checkpoint to report while holding a spinlock
  */
-void __ckpt_write_err(struct ckpt_ctx *ctx, char *fmt0, char *fmt, ...)
+void __ckpt_write_err(struct ckpt_ctx *ctx, char *fmt, ...)
 {
 	va_list ap;
 
 	va_start(ap, fmt);
-	__ckpt_generate_err(ctx, fmt0, fmt, ap);
+	__ckpt_generate_err(ctx, fmt, ap);
 	va_end(ap);
 }
 
@@ -242,10 +152,9 @@ void __ckpt_write_err(struct ckpt_ctx *ctx, char *fmt0, 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 *fmt0, char *fmt, ...)
+int ckpt_write_err(struct ckpt_ctx *ctx, char *fmt, ...)
 {
 	va_list ap;
 	char *str;
@@ -253,7 +162,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/checkpoint/sys.c b/checkpoint/sys.c
index 260a1ee..9b2de18 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 @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)
+{
+	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:
+			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 dfcb59b..8a1eaa7 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);
@@ -370,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: [PATCH 01/17] ckpt_write_err: use single format with %(T) style tokens

[Oren Laadan]

serue-r/Jw6+rmf7HQT0dZR+AlfA@public.gmane.org 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 29: merge with the next patch, moving ckpt_generate_fmt()
> 		into checkpoing/sys.c and making it non-static so that
> 		we can use it in ckpt_error().
> 	Oct 28: also fix comment above ckpt_generate_fmt()
> 	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    |  105 +++-----------------------------------------
>  checkpoint/sys.c           |   95 +++++++++++++++++++++++++++++++++++++++
>  include/linux/checkpoint.h |   13 +++--
>  3 files changed, 110 insertions(+), 103 deletions(-)
> 
> diff --git a/checkpoint/checkpoint.c b/checkpoint/checkpoint.c
> index 6eb8f3b..c6be4f9 100644
> --- a/checkpoint/checkpoint.c
> +++ b/checkpoint/checkpoint.c
> @@ -96,104 +96,15 @@ int ckpt_write_string(struct ckpt_ctx *ctx, char *str, int len)
>  	return ckpt_write_obj_type(ctx, str, len, CKPT_HDR_STRING);
>  }
>  

[...]

> diff --git a/checkpoint/sys.c b/checkpoint/sys.c
> index 260a1ee..9b2de18 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);
>  }
>  

Some pieces of the comment below are obsolete...

> +/*
> + * 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
						typo  ^^^^^^^^^^^^^^^^^
> + * 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
		typo ^^^^^^^^			     ^^^^^^^
> + * the T key), e.g.:
      ^^^^^^^^^^  (obsolete)
> + *
> + *   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.

Rewrite example...

> + *
> + * XXX Do we want 'T' and 'C' to simply always be prepended?
> + */
> +char *ckpt_generate_fmt(struct ckpt_ctx *ctx, char *fmt)
> +{
> +	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);

This calculation assumed that @fmt had only format string...
At the very minimum you could take strlen(fmt)/3 (+1 to round up)

I thought you were going to use a @ctx->buffer or something ?

> +	format = kzalloc(alloclen, GFP_KERNEL);
> +	if (!format)
> +		return NULL;
> +
> +	for (; *fmt; fmt++) {
> +		BUG_ON(len > alloclen);
> +		if (*fmt != '%' || fmt[1] != '(' || fmt[3] != ')') {

This is still a bit risky .. how about adding
	|| fmt[2] == '\0'
between the 2nd and 3rd test ?

> +			format[len++] = *fmt;
> +			continue;
> +		}
> +		if (!first)
> +			format[len++] = ' ';
> +		else
> +			first = 0;

[...]

Oren.

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

[Serge E. Hallyn]

Quoting Oren Laadan (orenl-RdfvBDnrOixBDgjK7y7TUQ@public.gmane.org):
> 
> 
> serue-r/Jw6+rmf7HQT0dZR+AlfA@public.gmane.org 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 29: merge with the next patch, moving ckpt_generate_fmt()
> > 		into checkpoing/sys.c and making it non-static so that
> > 		we can use it in ckpt_error().
> > 	Oct 28: also fix comment above ckpt_generate_fmt()
> > 	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    |  105 +++-----------------------------------------
> >  checkpoint/sys.c           |   95 +++++++++++++++++++++++++++++++++++++++
> >  include/linux/checkpoint.h |   13 +++--
> >  3 files changed, 110 insertions(+), 103 deletions(-)
> > 
> > diff --git a/checkpoint/checkpoint.c b/checkpoint/checkpoint.c
> > index 6eb8f3b..c6be4f9 100644
> > --- a/checkpoint/checkpoint.c
> > +++ b/checkpoint/checkpoint.c
> > @@ -96,104 +96,15 @@ int ckpt_write_string(struct ckpt_ctx *ctx, char *str, int len)
> >  	return ckpt_write_obj_type(ctx, str, len, CKPT_HDR_STRING);
> >  }
> >  
> 
> [...]
> 
> > diff --git a/checkpoint/sys.c b/checkpoint/sys.c
> > index 260a1ee..9b2de18 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);
> >  }
> >  
> 
> Some pieces of the comment below are obsolete...
> 
> > +/*
> > + * 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
> 						typo  ^^^^^^^^^^^^^^^^^
> > + * 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
> 		typo ^^^^^^^^			     ^^^^^^^
> > + * the T key), e.g.:
>       ^^^^^^^^^^  (obsolete)
> > + *
> > + *   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.
> 
> Rewrite example...

Ok, thanks for pointing that out - I'll rewrite the whole thing.

> > + * XXX Do we want 'T' and 'C' to simply always be prepended?
> > + */
> > +char *ckpt_generate_fmt(struct ckpt_ctx *ctx, char *fmt)
> > +{
> > +	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);
> 
> This calculation assumed that @fmt had only format string...
> At the very minimum you could take strlen(fmt)/3 (+1 to round up)

Yeah, I didn't want to think about that in detail yet :)

> I thought you were going to use a @ctx->buffer or something ?

And I am, for my string.  We need one for the expanded fmt here,
and then one to snprintf the final string into so we can write it
out.

Shall I just add a @ctx->fmtbuf?

> > +	format = kzalloc(alloclen, GFP_KERNEL);
> > +	if (!format)
> > +		return NULL;
> > +
> > +	for (; *fmt; fmt++) {
> > +		BUG_ON(len > alloclen);
> > +		if (*fmt != '%' || fmt[1] != '(' || fmt[3] != ')') {
> 
> This is still a bit risky .. how about adding
> 	|| fmt[2] == '\0'
> between the 2nd and 3rd test ?

Well I can do that, but since we provide the fmt strings and there is
no risk for an information leak I didn't think it was worth making
the line even longer.  But ok, I'll add it...

thanks,
-serge

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

[Oren Laadan]

Serge E. Hallyn wrote:
> Quoting Oren Laadan (orenl-RdfvBDnrOixBDgjK7y7TUQ@public.gmane.org):
>>
>> serue-r/Jw6+rmf7HQT0dZR+AlfA@public.gmane.org wrote:
>>> From: Serge E. Hallyn <serue-r/Jw6+rmf7HQT0dZR+AlfA@public.gmane.org>

[...]
>>> +	 */
>>> +	alloclen = 37 + 8 * strlen(fmt);
>> This calculation assumed that @fmt had only format string...
>> At the very minimum you could take strlen(fmt)/3 (+1 to round up)
> 
> Yeah, I didn't want to think about that in detail yet :)
> 
>> I thought you were going to use a @ctx->buffer or something ?
> 
> And I am, for my string.  We need one for the expanded fmt here,
> and then one to snprintf the final string into so we can write it
> out.
> 
> Shall I just add a @ctx->fmtbuf?

Sure.

> 
>>> +	format = kzalloc(alloclen, GFP_KERNEL);
>>> +	if (!format)
>>> +		return NULL;
>>> +
>>> +	for (; *fmt; fmt++) {
>>> +		BUG_ON(len > alloclen);
>>> +		if (*fmt != '%' || fmt[1] != '(' || fmt[3] != ')') {
>> This is still a bit risky .. how about adding
>> 	|| fmt[2] == '\0'
>> between the 2nd and 3rd test ?
> 
> Well I can do that, but since we provide the fmt strings and there is
> no risk for an information leak I didn't think it was worth making
> the line even longer.  But ok, I'll add it...

Well, if a developer gives a string like "hello %(", then you
will potentially go past the end of the string and eventually
crash (or worse).

Oren.

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

[Sukadev Bhattiprolu]

serue-r/Jw6+rmf7HQT0dZR+AlfA@public.gmane.org [serue-r/Jw6+rmf7HQT0dZR+AlfA@public.gmane.org] 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.

It maybe easier to review this patch if this is broken up into smaller
patches:

	- move the code to new place
	- leave the fmt0 parameter to ckpt_generate_fmt() but ensure it
	  is unused.
	- finally remove the unused parameters from ckpt_generate_fmt()
	  and the callers. 

| 
| Changelog:
| 	Oct 29: merge with the next patch, moving ckpt_generate_fmt()
| 		into checkpoing/sys.c and making it non-static so that
| 		we can use it in ckpt_error().
| 	Oct 28: also fix comment above ckpt_generate_fmt()
| 	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    |  105 +++-----------------------------------------
|  checkpoint/sys.c           |   95 +++++++++++++++++++++++++++++++++++++++
|  include/linux/checkpoint.h |   13 +++--
|  3 files changed, 110 insertions(+), 103 deletions(-)
| 
| diff --git a/checkpoint/checkpoint.c b/checkpoint/checkpoint.c
| index 6eb8f3b..c6be4f9 100644
| --- a/checkpoint/checkpoint.c
| +++ b/checkpoint/checkpoint.c
| @@ -96,104 +96,15 @@ int ckpt_write_string(struct ckpt_ctx *ctx, char *str, int len)
|  	return ckpt_write_obj_type(ctx, str, len, CKPT_HDR_STRING);
|  }
| 
| -/*
| - * __ckpt_generate_fmt - generate standard checkpoint error message
| - * @ctx: checkpoint context
| - * @fmt0: c/r-format string
| - * @fmt: message format
| - *
| - * This generates a unified format of checkpoint error messages, to
| - * ease (after the failure) inspection by userspace tools. It converts
| - * the (printf) message @fmt into a new format: "[PREFMT]: fmt".
| - *
| - * PREFMT is constructed from @fmt0 by subtituting format snippets
| - * according to the contents of @fmt0.

| - * The format characters in
| - * @fmt0 can be E (error), O (objref), P (pointer), S (string) and
| - * V (variable/symbol). For example, E will generate a "err %d" in
| - * PREFMT (see prefmt_array below).
| - *
| - * If @fmt0 begins with T, PREFMT will begin with "pid %d tsk %s"
| - * with the pid and the tsk->comm of the currently checkpointed task.
| - * The latter is taken from ctx->tsk, and is it the responsbilility of
| - * the caller to have a valid pointer there (in particular, functions
| - * that iterate on the processes: collect_objects, checkpoint_task,
| - * and tree_count_tasks).
| - *
| - * The caller of ckpt_write_err() and _ckpt_write_err() must provide
| - * the additional variabes, in order, to match the @fmt0 (except for
| - * the T key), e.g.:
| - *
| - *   ckpt_writ_err(ctx, "TEO", "FILE flags %d", err, objref, flags);
| - *
| - * Here, T is simply passed, E expects an integer (err), O expects an
| - * integer (objref), and the last argument matches the format string.
| - */
| -static char *__ckpt_generate_fmt(struct ckpt_ctx *ctx, char *fmt0, char *fmt)
| -{
| -	static int warn_notask = 0;
| -	static int warn_prefmt = 0;
| -	char *format;
| -	int i, j, len = 0;
| -
| -	static struct {
| -		char key;
| -		char *fmt;
| -	} prefmt_array[] = {
| -		{ 'E', "err %d" },
| -		{ 'O', "obj %d" },
| -		{ 'P', "ptr %p" },
| -		{ 'V', "sym %pS" },
| -		{ 'S', "str %s" },
| -		{ 0, "??? %pS" },
| -	};
| -
| -	/*
| -	 * 17 for "pid %d" (plus space)
| -	 * 21 for "tsk %s" (tsk->comm)
| -	 * up to 8 per varfmt entry
| -	 */
| -	format = kzalloc(37 + 8 * strlen(fmt0) + strlen(fmt), GFP_KERNEL);
| -	if (!format)
| -		return NULL;
| -
| -	format[len++] = '[';
| -
| -	if (fmt0[0] == 'T') {
| -		if (ctx->tsk)
| -			len = sprintf(format, "pid %d tsk %s ",
| -				      task_pid_vnr(ctx->tsk), ctx->tsk->comm);
| -		else if (warn_notask++ < 5)
| -			printk(KERN_ERR "c/r: no target task set\n");
| -		fmt0++;
| -	}
| -
| -	for (i = 0; i < strlen(fmt0); i++) {
| -		for (j = 0; prefmt_array[j].key; j++)
| -			if (prefmt_array[j].key == fmt0[i])
| -				break;
| -		if (!prefmt_array[j].key && warn_prefmt++ < 5)
| -			printk(KERN_ERR "c/r: unknown prefmt %c\n", fmt0[i]);
| -		len += sprintf(&format[len], "%s ", prefmt_array[j].fmt);
| -	}
| -
| -	if (len > 1)
| -		sprintf(&format[len-1], "]: %s", fmt);  /* erase last space */
| -	else
| -		sprintf(format, "%s", fmt);
| -
| -	return format;
| -}
| -
| -/* see _ckpt_generate_fmt for information on @fmt0 */
| -static void __ckpt_generate_err(struct ckpt_ctx *ctx, char *fmt0,
| -				char *fmt, va_list ap)
| +/* 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;
|  	char *format;
|  	char *str;
|  	int len;
| 
| -	format = __ckpt_generate_fmt(ctx, fmt0, fmt);
| +	format = ckpt_generate_fmt(ctx, fmt);
|  	va_copy(aq, ap);
| 
|  	/*
| @@ -223,15 +134,14 @@ static void __ckpt_generate_err(struct ckpt_ctx *ctx, char *fmt0,
|   * @fmt: message format
|   * @...: arguments
|   *
| - * See _ckpt_generate_fmt for information on @fmt0.
|   * Use this during checkpoint to report while holding a spinlock
|   */
| -void __ckpt_write_err(struct ckpt_ctx *ctx, char *fmt0, char *fmt, ...)
| +void __ckpt_write_err(struct ckpt_ctx *ctx, char *fmt, ...)
|  {
|  	va_list ap;
| 
|  	va_start(ap, fmt);
| -	__ckpt_generate_err(ctx, fmt0, fmt, ap);
| +	__ckpt_generate_err(ctx, fmt, ap);
|  	va_end(ap);
|  }
| 
| @@ -242,10 +152,9 @@ void __ckpt_write_err(struct ckpt_ctx *ctx, char *fmt0, 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 *fmt0, char *fmt, ...)
| +int ckpt_write_err(struct ckpt_ctx *ctx, char *fmt, ...)
|  {
|  	va_list ap;
|  	char *str;
| @@ -253,7 +162,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/checkpoint/sys.c b/checkpoint/sys.c
| index 260a1ee..9b2de18 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 @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.

Its a little confusing on what PREFMT is and how it differs from @fmt0.
The [] with all upper case makes it look like the P, R, E etc are the
only valid characters for fmt0. Can we s/[PREFMT]/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);

s/writ/write/

| + *
| + * 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?

I think it would make sense to.

| + */
| +char *ckpt_generate_fmt(struct ckpt_ctx *ctx, char *fmt)
| +{
| +	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:
| +			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 dfcb59b..8a1eaa7 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);
| @@ -370,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
| 
| _______________________________________________
| Containers mailing list
| Containers-cunTk1MwBs9QetFLy7KEm3xJsTq8ys+cHZ5vskTnxNA@public.gmane.org
| https://lists.linux-foundation.org/mailman/listinfo/containers

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

[Serge E. Hallyn]

Quoting Sukadev Bhattiprolu (sukadev-23VcF4HTsmIX0ybBhKVfKdBPR1lH4CV8@public.gmane.org):
> serue-r/Jw6+rmf7HQT0dZR+AlfA@public.gmane.org [serue-r/Jw6+rmf7HQT0dZR+AlfA@public.gmane.org] 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.
> 
> It maybe easier to review this patch if this is broken up into smaller
> patches:
> 
> 	- move the code to new place
> 	- leave the fmt0 parameter to ckpt_generate_fmt() but ensure it
> 	  is unused.
> 	- finally remove the unused parameters from ckpt_generate_fmt()
> 	  and the callers. 

That's going a bit far...  I did leave the moving of the code in a separate
patch up until this last posting, but the new and old versions of
ckpt_generate_fmt() don't look alike enough to be able to compare side by
side anyway imo.

One thing which would help however imo would be if I keep a non-rebased
tagged tree alongside the rebased tree, so you can see what changes I'm
making over the last posting.  I'll do that as of today.

-serge

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

[serue-r/Jw6+rmf7HQT0dZR+AlfA]

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

Signed-off-by: Serge E. Hallyn <serue-r/Jw6+rmf7HQT0dZR+AlfA@public.gmane.org>
---
 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

[PATCH 03/17] ckpt_write_err update checkpoint/checkpoint.c

[serue-r/Jw6+rmf7HQT0dZR+AlfA]

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

Signed-off-by: Serge E. Hallyn <serue-r/Jw6+rmf7HQT0dZR+AlfA@public.gmane.org>
---
 checkpoint/checkpoint.c |   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

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

[serue-r/Jw6+rmf7HQT0dZR+AlfA]

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

Signed-off-by: Serge E. Hallyn <serue-r/Jw6+rmf7HQT0dZR+AlfA@public.gmane.org>
---
 checkpoint/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

[PATCH 05/17] ckpt_write_err update checkpoint/memory.c

[serue-r/Jw6+rmf7HQT0dZR+AlfA]

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

Signed-off-by: Serge E. Hallyn <serue-r/Jw6+rmf7HQT0dZR+AlfA@public.gmane.org>
---
 checkpoint/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

[PATCH 06/17] ckpt_write_err update checkpoint/objhash.c

[serue-r/Jw6+rmf7HQT0dZR+AlfA]

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

Signed-off-by: Serge E. Hallyn <serue-r/Jw6+rmf7HQT0dZR+AlfA@public.gmane.org>
---
 checkpoint/objhash.c |    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

[PATCH 07/17] ckpt_write_err update checkpoint/process.c

[serue-r/Jw6+rmf7HQT0dZR+AlfA]

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

Signed-off-by: Serge E. Hallyn <serue-r/Jw6+rmf7HQT0dZR+AlfA@public.gmane.org>
---
 checkpoint/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

[PATCH 08/17] ckpt_write_err update checkpoint/signal.c

[serue-r/Jw6+rmf7HQT0dZR+AlfA]

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

Signed-off-by: Serge E. Hallyn <serue-r/Jw6+rmf7HQT0dZR+AlfA@public.gmane.org>
---
 checkpoint/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

[PATCH 09/17] ckpt_write_err update fs/eventpoll.c

[serue-r/Jw6+rmf7HQT0dZR+AlfA]

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

Signed-off-by: Serge E. Hallyn <serue-r/Jw6+rmf7HQT0dZR+AlfA@public.gmane.org>
---
 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

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

[serue-r/Jw6+rmf7HQT0dZR+AlfA]

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 29: Split ckpt_log_error() into ckpt_log_error_v() and have
		ckpt_write_err() call it to duplicate the checkpoint
		error message into the optional user-provided log file and
		(if CONFIG_CHECKPOINT_DEBUG=y) syslog as well.
		Define a fn writing an error prefix (containing
		current->pid etc) for ckpt_error().
	Oct 28: Don't use a third va_args, and use smaller on-stack
		buffer (mhelsley comments).  It still might be cleaner
		to always kmalloc, but always using two kmallocs per
		ckpt_error is getting kinda gross...  (open to comments
		on that).
	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/checkpoint.c          |    8 +++-
 checkpoint/objhash.c             |    2 +
 checkpoint/sys.c                 |   91 ++++++++++++++++++++++++++++++++++----
 include/linux/checkpoint.h       |    5 ++
 include/linux/checkpoint_types.h |    5 ++
 include/linux/syscalls.h         |    5 +-
 6 files changed, 103 insertions(+), 13 deletions(-)

diff --git a/checkpoint/checkpoint.c b/checkpoint/checkpoint.c
index 35fce15..30ec622 100644
--- a/checkpoint/checkpoint.c
+++ b/checkpoint/checkpoint.c
@@ -123,8 +123,6 @@ static void __ckpt_generate_err(struct ckpt_ctx *ctx, char *fmt, va_list ap)
 
 	va_end(aq);
 	kfree(format);
-
-	ckpt_debug("c/r: checkpoint error: %s\n", str);
 }
 
 /**
@@ -140,9 +138,15 @@ void __ckpt_write_err(struct ckpt_ctx *ctx, char *fmt, ...)
 {
 	va_list ap;
 
+	/* write to checkpoint file */
 	va_start(ap, fmt);
 	__ckpt_generate_err(ctx, fmt, ap);
 	va_end(ap);
+
+	/* write to user log and syslog */
+	va_start(ap, fmt);
+	ckpt_log_error_v(ctx, fmt, ap);
+	va_end(ap);
 }
 
 /**
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 9b2de18..736606d 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);
@@ -220,12 +222,13 @@ static void ckpt_ctx_free(struct ckpt_ctx *ctx)
 		put_task_struct(ctx->root_freezer);
 
 	kfree(ctx->pids_arr);
+	kfree(ctx->error_buf);
 
 	kfree(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;
@@ -249,11 +252,23 @@ static struct ckpt_ctx *ckpt_ctx_alloc(int fd, unsigned long uflags,
 	spin_lock_init(&ctx->lock);
 #endif
 
+	err = -ENOMEM;
+	ctx->error_buf = kmalloc(CKPT_ERR_BUFSZ, GFP_KERNEL);
+	if (!ctx->error_buf)
+		goto err;
+	mutex_init(&ctx->error_buf_mutex);
+
 	err = -EBADF;
 	ctx->file = fget(fd);
 	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;
@@ -351,8 +366,7 @@ int walk_task_subtree(struct task_struct *root,
  * 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"
+ * 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"
@@ -370,8 +384,6 @@ int walk_task_subtree(struct task_struct *root,
  *
  * Here, T is simply passed, E expects an integer (err), O expects an
  * integer (objref), and the last argument matches the format string.
- *
- * XXX Do we want 'T' and 'C' to simply always be prepended?
  */
 char *ckpt_generate_fmt(struct ckpt_ctx *ctx, char *fmt)
 {
@@ -435,6 +447,66 @@ char *ckpt_generate_fmt(struct ckpt_ctx *ctx, char *fmt)
 	return format;
 }
 
+/*
+ * called only by ckpt_log_error_v() to write out a prefix, which
+ * looks like:
+ *	[current->pid]=[task_pid_vnr(current)]:[ctx->total]:[ctx->errno]
+ * the ctx->error_buf_mutex is held by caller, so we are free to
+ * write to ctx->error_buf_mutex.  We also can assume that ctx is valid.
+ * Returns the number of characters written (not including trailing \0).
+ */
+static int ckpt_write_error_prefix(struct ckpt_ctx *ctx)
+{
+	return snprintf(ctx->error_buf, CKPT_ERR_BUFSZ, "[%d]=[%d]:[%lld]:[%d] ",
+			 current->pid, task_pid_vnr(current), ctx->total,
+			 ctx->errno);
+}
+
+void ckpt_log_error_v(struct ckpt_ctx *ctx, char *fmt, va_list ap)
+{
+	mm_segment_t fs;
+	char *format;
+	struct file *file = ctx->logfile;
+	char *bufp;
+	va_list aq;
+	int count, len;
+
+	format = ckpt_generate_fmt(ctx, fmt);
+	mutex_lock(&ctx->error_buf_mutex);
+	bufp = ctx->error_buf;
+	len = ckpt_write_error_prefix(ctx);
+	va_copy(aq, ap);
+	count = vsnprintf(bufp+len, CKPT_ERR_BUFSZ-len, format ? : fmt, aq);
+	va_end(aq);
+	count += len;
+	if (count > CKPT_ERR_BUFSZ) {
+		printk(KERN_WARNING "%s:%s:%d error string too long (%d)\n",
+		       __FILE__, __func__, __LINE__, count);
+		bufp[CKPT_ERR_BUFSZ-1] = '\0';
+	}
+
+	fs = get_fs();
+	set_fs(KERNEL_DS);
+	_ckpt_kwrite(file, bufp, count);
+	set_fs(fs);
+
+	ckpt_debug("%s", bufp);
+	mutex_unlock(&ctx->error_buf_mutex);
+	kfree(format);
+}
+
+void ckpt_log_error(struct ckpt_ctx *ctx, char *fmt, ...)
+{
+	va_list ap;
+
+	if (!ctx || !ctx->logfile)
+		return;
+
+	va_start(ap, fmt);
+	ckpt_log_error_v(ctx, fmt, ap);
+	va_end(ap);
+}
+
 /**
  * sys_checkpoint - checkpoint a container
  * @pid: pid of the container init(1) process
@@ -444,7 +516,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 +530,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 +552,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 +565,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..d3348c5 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_v(struct ckpt_ctx *ctx, char *fmt, va_list ap);
+extern void ckpt_log_error(struct ckpt_ctx *ctx, char *fmt, ...);
+
+#define ckpt_error(ctx, fmt, args...)					\
+	ckpt_log_error(ctx, "%s:%d " fmt, __func__, __LINE__, ## args);
 
 #endif /* CONFIG_CHECKPOINT */
 #endif /* __KERNEL__ */
diff --git a/include/linux/checkpoint_types.h b/include/linux/checkpoint_types.h
index 5cc11d9..57fd524 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;
@@ -85,6 +86,10 @@ struct ckpt_ctx {
 	struct list_head task_status;   /* list of status for each task */
 	spinlock_t lock;
 #endif
+
+#define CKPT_ERR_BUFSZ 1024
+	char *error_buf;		/* used by ckpt_error() */
+	struct mutex error_buf_mutex;
 };
 
 #endif /* __KERNEL__ */
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

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

[Oren Laadan]

serue-r/Jw6+rmf7HQT0dZR+AlfA@public.gmane.org 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 29: Split ckpt_log_error() into ckpt_log_error_v() and have
> 		ckpt_write_err() call it to duplicate the checkpoint
> 		error message into the optional user-provided log file and
> 		(if CONFIG_CHECKPOINT_DEBUG=y) syslog as well.
> 		Define a fn writing an error prefix (containing
> 		current->pid etc) for ckpt_error().
> 	Oct 28: Don't use a third va_args, and use smaller on-stack
> 		buffer (mhelsley comments).  It still might be cleaner
> 		to always kmalloc, but always using two kmallocs per
> 		ckpt_error is getting kinda gross...  (open to comments
> 		on that).
> 	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/checkpoint.c          |    8 +++-
>  checkpoint/objhash.c             |    2 +
>  checkpoint/sys.c                 |   91 ++++++++++++++++++++++++++++++++++----
>  include/linux/checkpoint.h       |    5 ++
>  include/linux/checkpoint_types.h |    5 ++
>  include/linux/syscalls.h         |    5 +-
>  6 files changed, 103 insertions(+), 13 deletions(-)
> 
> diff --git a/checkpoint/checkpoint.c b/checkpoint/checkpoint.c
> index 35fce15..30ec622 100644
> --- a/checkpoint/checkpoint.c
> +++ b/checkpoint/checkpoint.c
> @@ -123,8 +123,6 @@ static void __ckpt_generate_err(struct ckpt_ctx *ctx, char *fmt, va_list ap)
>  
>  	va_end(aq);
>  	kfree(format);
> -
> -	ckpt_debug("c/r: checkpoint error: %s\n", str);
>  }
>  
>  /**
> @@ -140,9 +138,15 @@ void __ckpt_write_err(struct ckpt_ctx *ctx, char *fmt, ...)
>  {
>  	va_list ap;
>  
> +	/* write to checkpoint file */
>  	va_start(ap, fmt);
>  	__ckpt_generate_err(ctx, fmt, ap);
>  	va_end(ap);
> +
> +	/* write to user log and syslog */
> +	va_start(ap, fmt);
> +	ckpt_log_error_v(ctx, fmt, ap);
> +	va_end(ap);
>  }

__ckpt_write_err() can be called from spinlock context, so
it needs to remain as is.

Instead, call ckpt_log_error_v() from ckpt_write_err(), and if
the have ckpt_log_error_v() also avoid calling __ckpt_generate_err()
if the @fmt string is NULL, instead take from @ctx->err_string.

To be complete, we probably also need ckpt_log_{un,}lock(), that
are used in ckpt_log_error_v() and should also be used by whoever
uses _ckpt_write_err() directly.

Also, in light of my suggestion in the other email, maybe rename
ckpt_generate_err() to ckpt_generate_msg().

Oren.

[PATCH 11/17] have restore_debug_free use ckpt_error

[serue-r/Jw6+rmf7HQT0dZR+AlfA]

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

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

diff --git a/checkpoint/restart.c b/checkpoint/restart.c
index 9b75de8..3f23397 100644
--- a/checkpoint/restart.c
+++ b/checkpoint/restart.c
@@ -137,15 +137,16 @@ void restore_debug_free(struct ckpt_ctx *ctx)
 	 */
 	list_for_each_entry(s, &ctx->task_status, list)
 		count++;
-	ckpt_debug("%d tasks registered, nr_tasks was %d nr_total %d\n",
+	ckpt_error(ctx, "%d tasks registered, nr_tasks was %d nr_total %d\n",
 		   count, ctx->nr_tasks, atomic_read(&ctx->nr_total));
 
-	ckpt_debug("active pid was %d, ctx->errno %d\n", ctx->active_pid,
+	ckpt_error(ctx, "active pid was %d, ctx->errno %d\n", ctx->active_pid,
 		   ctx->errno);
-	ckpt_debug("kflags %lu uflags %lu oflags %lu", ctx->kflags,
+	ckpt_error(ctx, "kflags %lu uflags %lu oflags %lu", ctx->kflags,
 		   ctx->uflags, ctx->oflags);
 	for (i = 0; i < ctx->active_pid; i++)
-		ckpt_debug("task[%d] to run %d\n", i, ctx->pids_arr[i].vpid);
+		ckpt_error(ctx, "task[%d] to run %d\n", i,
+			   ctx->pids_arr[i].vpid);
 
 	list_for_each_entry_safe(s, p, &ctx->task_status, list) {
 		if (s->flags & RESTART_DBG_COORD)
@@ -170,7 +171,8 @@ void restore_debug_free(struct ckpt_ctx *ctx)
 			state = "Exited";
 		else
 			state = "??????";
-		ckpt_debug("pid %d type %s state %s\n", s->pid, which, state);
+		ckpt_error(ctx, "pid %d type %s state %s\n", s->pid, which,
+			   state);
 		list_del(&s->list);
 		kfree(s);
 	}
-- 
1.6.1

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

[serue-r/Jw6+rmf7HQT0dZR+AlfA]

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 3f23397..6eb5a70 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;
@@ -199,13 +199,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;
 	}
 
@@ -717,7 +717,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);
@@ -731,7 +731,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)
 
@@ -755,7 +756,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);
@@ -805,7 +807,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;
 		}
@@ -960,29 +962,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
@@ -1023,12 +1034,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;
 	}
 
@@ -1184,24 +1195,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
@@ -1214,7 +1232,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;
 	}
 
@@ -1226,35 +1244,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);
@@ -1366,7 +1394,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

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

[serue-r/Jw6+rmf7HQT0dZR+AlfA]

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

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

[serue-r/Jw6+rmf7HQT0dZR+AlfA]

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

Signed-off-by: Serge E. Hallyn <serue-r/Jw6+rmf7HQT0dZR+AlfA@public.gmane.org>
---
 checkpoint/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

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

[serue-r/Jw6+rmf7HQT0dZR+AlfA]

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

Signed-off-by: Serge E. Hallyn <serue-r/Jw6+rmf7HQT0dZR+AlfA@public.gmane.org>
---
 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

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

[serue-r/Jw6+rmf7HQT0dZR+AlfA]

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

Signed-off-by: Serge E. Hallyn <serue-r/Jw6+rmf7HQT0dZR+AlfA@public.gmane.org>
---
 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

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

[serue-r/Jw6+rmf7HQT0dZR+AlfA]

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

Signed-off-by: Serge E. Hallyn <serue-r/Jw6+rmf7HQT0dZR+AlfA@public.gmane.org>
---
 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: [PATCH 00/17] Standardize c/r error reporting

[Oren Laadan]

serue-r/Jw6+rmf7HQT0dZR+AlfA@public.gmane.org wrote:
> From: Serge E. Hallyn <serue-r/Jw6+rmf7HQT0dZR+AlfA@public.gmane.org>
> 
> This patchset
> 	1. defines ckpt_error() 
> 	2. allows users to pass a logfd into sys_checkpoint and
> 	   sys_restart
> 	3. Switches ckpt_write_err() to accepting a single enhanced
> 	   format string, instead of two separate formats.
> 	4. Has ckpt_write_err() call ckpt_error() to also log the
> 	   error in the user-provided logfile and syslog.
> 
> Every ckpt_error() message is prefixed by current's global pid,
> current's virtual pid, number of bytes read/written, and the
> ctx->errno.

Hmmm... I thought that we'd have:

ckpt_error() will be used _only_ when there is an error.
(will always print ctx->errno, which is assumed to be set)

ckpt_debug() will be used to report "log-able" debugging info
(will not print ctx->errno, because there wasn't any error)

_ckpt_debug() will be used to throw debugging info that isn't
logged (only goes to dmesg) and will not be compiled unless
CONFIG_CHECKPOINT_DEBUG is selected. This is useful for those
debug messages that are a pain to add remove, but that we
don't want to spit to users' logs.

Maybe rename ckpt_debug() to ckpt_log() and then _ckpt_debug()
to ckpt_debug()...

I think it's confusing for ckpt_error() to be used everywhere.

Oren.

> 
> I'm sure we'll want another round if only to alter the format,
> but I'm finding it very useful as is.
> 
> (As more callers are added I expect we'll want to add %(A) to
> the format to indicate active_pid should be printed).
> 
> -serge

Re: [PATCH 00/17] Standardize c/r error reporting

[Serge E. Hallyn]

Quoting Oren Laadan (orenl-RdfvBDnrOixBDgjK7y7TUQ@public.gmane.org):
> 
> 
> serue-r/Jw6+rmf7HQT0dZR+AlfA@public.gmane.org wrote:
> > From: Serge E. Hallyn <serue-r/Jw6+rmf7HQT0dZR+AlfA@public.gmane.org>
> > 
> > This patchset
> > 	1. defines ckpt_error() 
> > 	2. allows users to pass a logfd into sys_checkpoint and
> > 	   sys_restart
> > 	3. Switches ckpt_write_err() to accepting a single enhanced
> > 	   format string, instead of two separate formats.
> > 	4. Has ckpt_write_err() call ckpt_error() to also log the
> > 	   error in the user-provided logfile and syslog.
> > 
> > Every ckpt_error() message is prefixed by current's global pid,
> > current's virtual pid, number of bytes read/written, and the
> > ctx->errno.
> 
> Hmmm... I thought that we'd have:
> 
> ckpt_error() will be used _only_ when there is an error.
> (will always print ctx->errno, which is assumed to be set)
> 
> ckpt_debug() will be used to report "log-able" debugging info
> (will not print ctx->errno, because there wasn't any error)
> 
> _ckpt_debug() will be used to throw debugging info that isn't
> logged (only goes to dmesg) and will not be compiled unless
> CONFIG_CHECKPOINT_DEBUG is selected. This is useful for those
> debug messages that are a pain to add remove, but that we
> don't want to spit to users' logs.
> 
> Maybe rename ckpt_debug() to ckpt_log() and then _ckpt_debug()
> to ckpt_debug()...
> 
> I think it's confusing for ckpt_error() to be used everywhere.

Agreed, and I almost changed it today but didn't.  However note
that ckpt_error really is just for errors.  So I'll just rename
ckpt_log_error()->ckpt_log_msg() (and same with *_v).

-serge