[PATCH] Save current timestamp while moving oops message to nvram

[PATCH] Save current timestamp while moving oops message to nvram

[Ankit Kumar]

Currently on panic or Oops, kernel saves the last few bytes from dmesg
buffer to nvram. Usually kdump does capture kernel memory and provide
dmesg logs as well. But in some cases where kdump fails to capture
vmcore, the dmesg buffer stored in nvram/pstore turns out to be very
helpful in analyzing root cause.

But currently there is no way to figure out when the last dmesg was
captured on pstore. Hence enhance the pstore to also capture and save
current timestamp in human readable format as initial few bytes while
capturing dmesg buffer.

This patch enhances pstore write code to also capture and save current
timestamp in human readable format as initial few bytes while capturing
dmesg buffer.

It saves timestamp in UTC format following ISO-8601 standard. As per
ISO-8601 the 'Z' suffix to timestamp indicates UTC timeoffset.

Ref: https://en.wikipedia.org/wiki/ISO_8601#UTC

We can use date -d <PSTORE_LOGGED_TIME> command to print time according
to local time zone.

Partial pstore dump after applying this patch:
Oops#1 Part1 [2017-04-12T14:14:56Z]

Above time can be printed in current time zone using date -d command.
 #date -d 2017-04-12T14:14:56Z
   Wed Apr 12 19:44:56 IST 2017

Signed-off-by: Ankit Kumar <ankit@linux.vnet.ibm.com>
---

Changelog since v3:
 - Printed value in ISO 8601 standard.
 - Replaced sprintf with snprintf.
 - Reduced time buffer size to 32.

 fs/pstore/platform.c | 29 ++++++++++++++++++++++++++++-
 1 file changed, 28 insertions(+), 1 deletion(-)

diff --git a/fs/pstore/platform.c b/fs/pstore/platform.c
index efab7b6..f4017c5 100644
--- a/fs/pstore/platform.c
+++ b/fs/pstore/platform.c
@@ -44,6 +44,7 @@
 #include <linux/hardirq.h>
 #include <linux/jiffies.h>
 #include <linux/workqueue.h>
+#include <linux/time.h>
 
 #include "internal.h"
 
@@ -475,6 +476,28 @@ static size_t copy_kmsg_to_buffer(int hsize, size_t len)
 }
 
 /*
+ * description: It fills buffer with current time(in ISO 8601 standard)
+ * @param : buffer needs to be filled.
+ * @param : size of buffer.
+ * return : void
+ */
+static void get_curr_time(char *loc_time, int time_buf_size)
+{
+	struct timeval now;
+	struct tm tm_val;
+
+	if (!loc_time)
+		return;
+
+	do_gettimeofday(&now);
+	time_to_tm(now.tv_sec, 0, &tm_val);
+
+	snprintf(loc_time, time_buf_size - 1, "%.4d-%.2d-%.2dT%.2d:%.2d:%.2dZ",
+		(int)(1900 + tm_val.tm_year), tm_val.tm_mon + 1,
+		tm_val.tm_mday, tm_val.tm_hour, tm_val.tm_min, tm_val.tm_sec);
+}
+
+/*
  * callback from kmsg_dump. (s2,l2) has the most recently
  * written bytes, older bytes are in (s1,l1). Save as much
  * as we can from the end of the buffer.
@@ -489,6 +512,7 @@ static void pstore_dump(struct kmsg_dumper *dumper,
 	unsigned long	flags = 0;
 	int		is_locked;
 	int		ret;
+	char loc_time[32];
 
 	why = get_reason_str(reason);
 
@@ -521,7 +545,10 @@ static void pstore_dump(struct kmsg_dumper *dumper,
 			size = psinfo->bufsize;
 		}
 
-		hsize = sprintf(dst, "%s#%d Part%u\n", why, oopscount, part);
+		memset(loc_time, 0, sizeof(loc_time));
+		get_curr_time(loc_time, sizeof(loc_time));
+		hsize = sprintf(dst, "%s#%d Part%u [%s]\n", why, oopscount,
+				part, loc_time);
 		size -= hsize;
 
 		if (!kmsg_dump_get_buffer(dumper, true, dst + hsize,
-- 
2.7.4

Re: [PATCH] Save current timestamp while moving oops message to nvram

[Kees Cook]

On Wed, Apr 12, 2017 at 7:32 AM, Ankit Kumar <ankit@linux.vnet.ibm.com> wrote:
> Currently on panic or Oops, kernel saves the last few bytes from dmesg
> buffer to nvram. Usually kdump does capture kernel memory and provide
> dmesg logs as well. But in some cases where kdump fails to capture
> vmcore, the dmesg buffer stored in nvram/pstore turns out to be very
> helpful in analyzing root cause.
>
> But currently there is no way to figure out when the last dmesg was
> captured on pstore. Hence enhance the pstore to also capture and save
> current timestamp in human readable format as initial few bytes while
> capturing dmesg buffer.
>
> This patch enhances pstore write code to also capture and save current
> timestamp in human readable format as initial few bytes while capturing
> dmesg buffer.
>
> It saves timestamp in UTC format following ISO-8601 standard. As per
> ISO-8601 the 'Z' suffix to timestamp indicates UTC timeoffset.
>
> Ref: https://en.wikipedia.org/wiki/ISO_8601#UTC
>
> We can use date -d <PSTORE_LOGGED_TIME> command to print time according
> to local time zone.
>
> Partial pstore dump after applying this patch:
> Oops#1 Part1 [2017-04-12T14:14:56Z]
>
> Above time can be printed in current time zone using date -d command.
>  #date -d 2017-04-12T14:14:56Z
>    Wed Apr 12 19:44:56 IST 2017
>
> Signed-off-by: Ankit Kumar <ankit@linux.vnet.ibm.com>

Unfortunately, this isn't safe in the cases where time keeping hasn't
started yet. Additionally, this kind of thing is already collected by
the ram backend. See ramoops_write_kmsg_hdr(), which had to go through
a number of alterations to deal with time handling. Right now, the
filesystem should already reflect the time of the crash (if available)
and it should already be in the ramoops header as sec.nsec.

I wouldn't be opposed to lifting what ramoops does and moving it up
into the common pstore routines, though.

-Kees

> ---
>
> Changelog since v3:
>  - Printed value in ISO 8601 standard.
>  - Replaced sprintf with snprintf.
>  - Reduced time buffer size to 32.
>
>  fs/pstore/platform.c | 29 ++++++++++++++++++++++++++++-
>  1 file changed, 28 insertions(+), 1 deletion(-)
>
> diff --git a/fs/pstore/platform.c b/fs/pstore/platform.c
> index efab7b6..f4017c5 100644
> --- a/fs/pstore/platform.c
> +++ b/fs/pstore/platform.c
> @@ -44,6 +44,7 @@
>  #include <linux/hardirq.h>
>  #include <linux/jiffies.h>
>  #include <linux/workqueue.h>
> +#include <linux/time.h>
>
>  #include "internal.h"
>
> @@ -475,6 +476,28 @@ static size_t copy_kmsg_to_buffer(int hsize, size_t len)
>  }
>
>  /*
> + * description: It fills buffer with current time(in ISO 8601 standard)
> + * @param : buffer needs to be filled.
> + * @param : size of buffer.
> + * return : void
> + */
> +static void get_curr_time(char *loc_time, int time_buf_size)
> +{
> +       struct timeval now;
> +       struct tm tm_val;
> +
> +       if (!loc_time)
> +               return;
> +
> +       do_gettimeofday(&now);
> +       time_to_tm(now.tv_sec, 0, &tm_val);
> +
> +       snprintf(loc_time, time_buf_size - 1, "%.4d-%.2d-%.2dT%.2d:%.2d:%.2dZ",
> +               (int)(1900 + tm_val.tm_year), tm_val.tm_mon + 1,
> +               tm_val.tm_mday, tm_val.tm_hour, tm_val.tm_min, tm_val.tm_sec);
> +}
> +
> +/*
>   * callback from kmsg_dump. (s2,l2) has the most recently
>   * written bytes, older bytes are in (s1,l1). Save as much
>   * as we can from the end of the buffer.
> @@ -489,6 +512,7 @@ static void pstore_dump(struct kmsg_dumper *dumper,
>         unsigned long   flags = 0;
>         int             is_locked;
>         int             ret;
> +       char loc_time[32];
>
>         why = get_reason_str(reason);
>
> @@ -521,7 +545,10 @@ static void pstore_dump(struct kmsg_dumper *dumper,
>                         size = psinfo->bufsize;
>                 }
>
> -               hsize = sprintf(dst, "%s#%d Part%u\n", why, oopscount, part);
> +               memset(loc_time, 0, sizeof(loc_time));
> +               get_curr_time(loc_time, sizeof(loc_time));
> +               hsize = sprintf(dst, "%s#%d Part%u [%s]\n", why, oopscount,
> +                               part, loc_time);
>                 size -= hsize;
>
>                 if (!kmsg_dump_get_buffer(dumper, true, dst + hsize,
> --
> 2.7.4
>



-- 
Kees Cook
Pixel Security