[PATCH 1/2]pstore: Move timestamp collection code to common pstore place

[PATCH 1/2]pstore: Move timestamp collection code to common pstore place

[Ankit Kumar]

Current pstore code(ram.c) gets dump timestamp and make it part of header.
Different diffent architecture uses different header format and hence it
won't be good idea to make ramoops_write_kmsg_hdr/ramoops_read_kmsg_hdr
part of generic pstore code.

ramoops_write_kmsg_hdr calls __getnstimeofday to get timestamp and also
takes care of condition if timekeeping has not resumed.

This patch moves code for retrieving timestamp to common place and hence
can be used by other functions as well.

Signed-off-by: Ankit Kumar <ankit@linux.vnet.ibm.com>
---
 fs/pstore/internal.h |  1 +
 fs/pstore/platform.c | 13 +++++++++++++
 fs/pstore/ram.c      |  9 ++++-----
 3 files changed, 18 insertions(+), 5 deletions(-)

diff --git a/fs/pstore/internal.h b/fs/pstore/internal.h
index c416e65..339dcdc 100644
--- a/fs/pstore/internal.h
+++ b/fs/pstore/internal.h
@@ -22,6 +22,7 @@ static inline void pstore_unregister_pmsg(void) {}
 #endif
 
 extern struct pstore_info *psinfo;
+void pstore_get_timestamp(struct timespec *timestamp);
 
 extern void	pstore_set_kmsg_bytes(int);
 extern void	pstore_get_records(int);
diff --git a/fs/pstore/platform.c b/fs/pstore/platform.c
index d468eec..5cb25b0 100644
--- a/fs/pstore/platform.c
+++ b/fs/pstore/platform.c
@@ -474,6 +474,19 @@ static size_t copy_kmsg_to_buffer(int hsize, size_t len)
 	return total_len;
 }
 
+void pstore_get_timestamp(struct timespec *timestamp)
+{
+	if (!timestamp)
+		return;
+
+	/* Report zeroed timestamp if called before timekeeping has resumed. */
+	if (__getnstimeofday(timestamp)) {
+		timestamp->tv_sec = 0;
+		timestamp->tv_nsec = 0;
+	}
+}
+EXPORT_SYMBOL_GPL(pstore_get_timestamp);
+
 /*
  * callback from kmsg_dump. (s2,l2) has the most recently
  * written bytes, older bytes are in (s1,l1). Save as much
diff --git a/fs/pstore/ram.c b/fs/pstore/ram.c
index 5cb022c..e39297d 100644
--- a/fs/pstore/ram.c
+++ b/fs/pstore/ram.c
@@ -37,6 +37,8 @@
 #include <linux/of.h>
 #include <linux/of_address.h>
 
+#include "internal.h"
+
 #define RAMOOPS_KERNMSG_HDR "===="
 #define MIN_MEM_SIZE 4096UL
 
@@ -362,11 +364,8 @@ static size_t ramoops_write_kmsg_hdr(struct persistent_ram_zone *prz,
 	struct timespec timestamp;
 	size_t len;
 
-	/* Report zeroed timestamp if called before timekeeping has resumed. */
-	if (__getnstimeofday(&timestamp)) {
-		timestamp.tv_sec = 0;
-		timestamp.tv_nsec = 0;
-	}
+	pstore_get_timestamp(&timestamp);
+
 	hdr = kasprintf(GFP_ATOMIC, RAMOOPS_KERNMSG_HDR "%lu.%lu-%c\n",
 		(long)timestamp.tv_sec, (long)(timestamp.tv_nsec / 1000),
 		compressed ? 'C' : 'D');
-- 
2.7.4

[PATCH 2/2] Save current timestamp part of dmesg while writing oops message to pstore

[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.

Present code creates pstore dump file(/sys/fs/pstore/dmesg-***) based on
timestamp(retrieved from header). Current pstore code creates dump file
(/sys/fs/pstore/dmesg-***) with that timestamp. Dump file can be analyzed
based on file creation time and we can make out whether dump file has latest
data or not.

But when we transfer pstore dump file(/sys/fs/pstore/dmesg-***) to other
machine or collect file using some utilities(sosreport/supportconfig) then file
timestamp gets changed and hence by looking at device file (dmesg-***) we won't
be able to identify whether dump has latest data or not.

Above issue can be fixed if we also have timestamp(dump creation time) as
initial few bytes while capturing dmesg buffer to pstore dump file
(/sys/fs/pstore/dmesg-***).


This patch enhances pstore write code to also write timestamp as part of data.

Here is sample log of dump file:(/sys/fs/pstore/dmesg-***)
Oops#1 Part1 [timestamp:1494939359.590463]


Above timestamp can be converted to current zone using date command.
 #date -d @1494939359.590463
 # Tue May 16 18:25:59 IST 2017

Signed-off-by: Ankit Kumar <ankit@linux.vnet.ibm.com>
---
 fs/pstore/platform.c | 7 +++++--
 1 file changed, 5 insertions(+), 2 deletions(-)

diff --git a/fs/pstore/platform.c b/fs/pstore/platform.c
index 4fedf83..f65000e 100644
--- a/fs/pstore/platform.c
+++ b/fs/pstore/platform.c
@@ -501,6 +501,7 @@ static void pstore_dump(struct kmsg_dumper *dumper,
 	unsigned long	flags = 0;
 	int		is_locked;
 	int		ret;
+	struct timespec timestamp;
 
 	why = get_reason_str(reason);
 
@@ -540,9 +541,11 @@ static void pstore_dump(struct kmsg_dumper *dumper,
 			dst_size = psinfo->bufsize;
 		}
 
+		pstore_get_timestamp(&timestamp);
 		/* Write dump header. */
-		header_size = snprintf(dst, dst_size, "%s#%d Part%u\n", why,
-				 oopscount, part);
+		header_size = snprintf(dst, dst_size, "%s#%d Part%u [timestamp:%lu.%lu]\n",
+				why, oopscount, part, (long)timestamp.tv_sec,
+				(long)(timestamp.tv_nsec / 1000));
 		dst_size -= header_size;
 
 		/* Write dump contents. */
-- 
2.7.4

Re: [PATCH 1/2]pstore: Move timestamp collection code to common pstore place

[Kees Cook]

On Mon, May 22, 2017 at 3:20 AM, Ankit Kumar <ankit@linux.vnet.ibm.com> wrote:
> Current pstore code(ram.c) gets dump timestamp and make it part of header.
> Different diffent architecture uses different header format and hence it
> won't be good idea to make ramoops_write_kmsg_hdr/ramoops_read_kmsg_hdr
> part of generic pstore code.
>
> ramoops_write_kmsg_hdr calls __getnstimeofday to get timestamp and also
> takes care of condition if timekeeping has not resumed.
>
> This patch moves code for retrieving timestamp to common place and hence
> can be used by other functions as well.

Ah! Heh, funny, I had just done a version of this while working on EFI
pstore fixes. Here's what I did instead:

https://git.kernel.org/pub/scm/linux/kernel/git/kees/linux.git/commit/?h=pstore/fixes&id=ea209b760f104daf0cf62953090b66c5628b0842

This makes it so the time field is prepopulated for all backend
writes, which should simplify things (no need to have the backends
call out).

-Kees

>
> Signed-off-by: Ankit Kumar <ankit@linux.vnet.ibm.com>
> ---
>  fs/pstore/internal.h |  1 +
>  fs/pstore/platform.c | 13 +++++++++++++
>  fs/pstore/ram.c      |  9 ++++-----
>  3 files changed, 18 insertions(+), 5 deletions(-)
>
> diff --git a/fs/pstore/internal.h b/fs/pstore/internal.h
> index c416e65..339dcdc 100644
> --- a/fs/pstore/internal.h
> +++ b/fs/pstore/internal.h
> @@ -22,6 +22,7 @@ static inline void pstore_unregister_pmsg(void) {}
>  #endif
>
>  extern struct pstore_info *psinfo;
> +void pstore_get_timestamp(struct timespec *timestamp);
>
>  extern void    pstore_set_kmsg_bytes(int);
>  extern void    pstore_get_records(int);
> diff --git a/fs/pstore/platform.c b/fs/pstore/platform.c
> index d468eec..5cb25b0 100644
> --- a/fs/pstore/platform.c
> +++ b/fs/pstore/platform.c
> @@ -474,6 +474,19 @@ static size_t copy_kmsg_to_buffer(int hsize, size_t len)
>         return total_len;
>  }
>
> +void pstore_get_timestamp(struct timespec *timestamp)
> +{
> +       if (!timestamp)
> +               return;
> +
> +       /* Report zeroed timestamp if called before timekeeping has resumed. */
> +       if (__getnstimeofday(timestamp)) {
> +               timestamp->tv_sec = 0;
> +               timestamp->tv_nsec = 0;
> +       }
> +}
> +EXPORT_SYMBOL_GPL(pstore_get_timestamp);
> +
>  /*
>   * callback from kmsg_dump. (s2,l2) has the most recently
>   * written bytes, older bytes are in (s1,l1). Save as much
> diff --git a/fs/pstore/ram.c b/fs/pstore/ram.c
> index 5cb022c..e39297d 100644
> --- a/fs/pstore/ram.c
> +++ b/fs/pstore/ram.c
> @@ -37,6 +37,8 @@
>  #include <linux/of.h>
>  #include <linux/of_address.h>
>
> +#include "internal.h"
> +
>  #define RAMOOPS_KERNMSG_HDR "===="
>  #define MIN_MEM_SIZE 4096UL
>
> @@ -362,11 +364,8 @@ static size_t ramoops_write_kmsg_hdr(struct persistent_ram_zone *prz,
>         struct timespec timestamp;
>         size_t len;
>
> -       /* Report zeroed timestamp if called before timekeeping has resumed. */
> -       if (__getnstimeofday(&timestamp)) {
> -               timestamp.tv_sec = 0;
> -               timestamp.tv_nsec = 0;
> -       }
> +       pstore_get_timestamp(&timestamp);
> +
>         hdr = kasprintf(GFP_ATOMIC, RAMOOPS_KERNMSG_HDR "%lu.%lu-%c\n",
>                 (long)timestamp.tv_sec, (long)(timestamp.tv_nsec / 1000),
>                 compressed ? 'C' : 'D');
> --
> 2.7.4
>



-- 
Kees Cook
Pixel Security

Re: [PATCH 2/2] Save current timestamp part of dmesg while writing oops message to pstore

[Kees Cook]

On Mon, May 22, 2017 at 3:20 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.
>
> Present code creates pstore dump file(/sys/fs/pstore/dmesg-***) based on
> timestamp(retrieved from header). Current pstore code creates dump file
> (/sys/fs/pstore/dmesg-***) with that timestamp. Dump file can be analyzed
> based on file creation time and we can make out whether dump file has latest
> data or not.
>
> But when we transfer pstore dump file(/sys/fs/pstore/dmesg-***) to other
> machine or collect file using some utilities(sosreport/supportconfig) then file
> timestamp gets changed and hence by looking at device file (dmesg-***) we won't
> be able to identify whether dump has latest data or not.
>
> Above issue can be fixed if we also have timestamp(dump creation time) as
> initial few bytes while capturing dmesg buffer to pstore dump file
> (/sys/fs/pstore/dmesg-***).
>
>
> This patch enhances pstore write code to also write timestamp as part of data.
>
> Here is sample log of dump file:(/sys/fs/pstore/dmesg-***)
> Oops#1 Part1 [timestamp:1494939359.590463]

While I understand your rationale about possibly losing file timestamp
information in userspace, I think this is a solvable problem on the
collection side. If an additional header is needed, perhaps copy the
dmesg files like this:

for i in dmesg-*; do
    (stat --format=%y /sys/fs/pstore/$i; \
     cat /sys/fs/pstore/$i) > $collect_dir/$i
done

One of the primary concerns for pstore is the stored dump size, even
to the point of adding compression to the routines to squeeze out
every last bit of space. I'd really rather avoid adding the timestamp
to the stored data like this. It's up to the backends already to
efficiently store this, and it's exposed via the file timestamp, so I
really can't justify adding redundant data.

-Kees

-- 
Kees Cook
Pixel Security

Re: [PATCH 1/2]pstore: Move timestamp collection code to common pstore place

[Ankit Kumar]

Hi Kees,

Thank you so much for your response.



On Tuesday 23 May 2017 05:07 AM, Kees Cook wrote:
> On Mon, May 22, 2017 at 3:20 AM, Ankit Kumar <ankit@linux.vnet.ibm.com> wrote:
>> Current pstore code(ram.c) gets dump timestamp and make it part of header.
>> Different diffent architecture uses different header format and hence it
>> won't be good idea to make ramoops_write_kmsg_hdr/ramoops_read_kmsg_hdr
>> part of generic pstore code.
>>
>> ramoops_write_kmsg_hdr calls __getnstimeofday to get timestamp and also
>> takes care of condition if timekeeping has not resumed.
>>
>> This patch moves code for retrieving timestamp to common place and hence
>> can be used by other functions as well.
> Ah! Heh, funny, I had just done a version of this while working on EFI
> pstore fixes. Here's what I did instead:
>
> https://git.kernel.org/pub/scm/linux/kernel/git/kees/linux.git/commit/?h=pstore/fixes&id=ea209b760f104daf0cf62953090b66c5628b0842
>
> This makes it so the time field is prepopulated for all backend
> writes, which should simplify things (no need to have the backends
> call out).


Above mentioned patch moves code to common place and also simplifies things.
I agree, My patch is not required anymore.

Thank you;

~Ankit




> -Kees
>
>> Signed-off-by: Ankit Kumar <ankit@linux.vnet.ibm.com>
>> ---
>>   fs/pstore/internal.h |  1 +
>>   fs/pstore/platform.c | 13 +++++++++++++
>>   fs/pstore/ram.c      |  9 ++++-----
>>   3 files changed, 18 insertions(+), 5 deletions(-)
>>
>> diff --git a/fs/pstore/internal.h b/fs/pstore/internal.h
>> index c416e65..339dcdc 100644
>> --- a/fs/pstore/internal.h
>> +++ b/fs/pstore/internal.h
>> @@ -22,6 +22,7 @@ static inline void pstore_unregister_pmsg(void) {}
>>   #endif
>>
>>   extern struct pstore_info *psinfo;
>> +void pstore_get_timestamp(struct timespec *timestamp);
>>
>>   extern void    pstore_set_kmsg_bytes(int);
>>   extern void    pstore_get_records(int);
>> diff --git a/fs/pstore/platform.c b/fs/pstore/platform.c
>> index d468eec..5cb25b0 100644
>> --- a/fs/pstore/platform.c
>> +++ b/fs/pstore/platform.c
>> @@ -474,6 +474,19 @@ static size_t copy_kmsg_to_buffer(int hsize, size_t len)
>>          return total_len;
>>   }
>>
>> +void pstore_get_timestamp(struct timespec *timestamp)
>> +{
>> +       if (!timestamp)
>> +               return;
>> +
>> +       /* Report zeroed timestamp if called before timekeeping has resumed. */
>> +       if (__getnstimeofday(timestamp)) {
>> +               timestamp->tv_sec = 0;
>> +               timestamp->tv_nsec = 0;
>> +       }
>> +}
>> +EXPORT_SYMBOL_GPL(pstore_get_timestamp);
>> +
>>   /*
>>    * callback from kmsg_dump. (s2,l2) has the most recently
>>    * written bytes, older bytes are in (s1,l1). Save as much
>> diff --git a/fs/pstore/ram.c b/fs/pstore/ram.c
>> index 5cb022c..e39297d 100644
>> --- a/fs/pstore/ram.c
>> +++ b/fs/pstore/ram.c
>> @@ -37,6 +37,8 @@
>>   #include <linux/of.h>
>>   #include <linux/of_address.h>
>>
>> +#include "internal.h"
>> +
>>   #define RAMOOPS_KERNMSG_HDR "===="
>>   #define MIN_MEM_SIZE 4096UL
>>
>> @@ -362,11 +364,8 @@ static size_t ramoops_write_kmsg_hdr(struct persistent_ram_zone *prz,
>>          struct timespec timestamp;
>>          size_t len;
>>
>> -       /* Report zeroed timestamp if called before timekeeping has resumed. */
>> -       if (__getnstimeofday(&timestamp)) {
>> -               timestamp.tv_sec = 0;
>> -               timestamp.tv_nsec = 0;
>> -       }
>> +       pstore_get_timestamp(&timestamp);
>> +
>>          hdr = kasprintf(GFP_ATOMIC, RAMOOPS_KERNMSG_HDR "%lu.%lu-%c\n",
>>                  (long)timestamp.tv_sec, (long)(timestamp.tv_nsec / 1000),
>>                  compressed ? 'C' : 'D');
>> --
>> 2.7.4
>>
>
>

Re: [PATCH 2/2] Save current timestamp part of dmesg while writing oops message to pstore

[Ankit Kumar]

Hi Kees,



On Tuesday 23 May 2017 05:21 AM, Kees Cook wrote:
> On Mon, May 22, 2017 at 3:20 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.
>>
>> Present code creates pstore dump file(/sys/fs/pstore/dmesg-***) based on
>> timestamp(retrieved from header). Current pstore code creates dump file
>> (/sys/fs/pstore/dmesg-***) with that timestamp. Dump file can be analyzed
>> based on file creation time and we can make out whether dump file has latest
>> data or not.
>>
>> But when we transfer pstore dump file(/sys/fs/pstore/dmesg-***) to other
>> machine or collect file using some utilities(sosreport/supportconfig) then file
>> timestamp gets changed and hence by looking at device file (dmesg-***) we won't
>> be able to identify whether dump has latest data or not.
>>
>> Above issue can be fixed if we also have timestamp(dump creation time) as
>> initial few bytes while capturing dmesg buffer to pstore dump file
>> (/sys/fs/pstore/dmesg-***).
>>
>>
>> This patch enhances pstore write code to also write timestamp as part of data.
>>
>> Here is sample log of dump file:(/sys/fs/pstore/dmesg-***)
>> Oops#1 Part1 [timestamp:1494939359.590463]
> While I understand your rationale about possibly losing file timestamp
> information in userspace, I think this is a solvable problem on the
> collection side. If an additional header is needed, perhaps copy the
> dmesg files like this:
>
> for i in dmesg-*; do
>      (stat --format=%y /sys/fs/pstore/$i; \
>       cat /sys/fs/pstore/$i) > $collect_dir/$i
> done

Yes. We can handle this in userspace. But we wanted to see if we can add 
this as part of pstore
log itself.


> One of the primary concerns for pstore is the stored dump size,

I understand. How about adding timestamp to file name itself? Something 
like below

index 792a4e5..0837365 100644
--- a/fs/pstore/inode.c
+++ b/fs/pstore/inode.c
@@ -349,9 +349,10 @@ int pstore_mkfile(struct dentry *root, struct 
pstore_record *record)

         switch (record->type) {
         case PSTORE_TYPE_DMESG:
-               scnprintf(name, sizeof(name), "dmesg-%s-%lld%s",
+               scnprintf(name, sizeof(name), "dmesg-%s-%lld%s-%lu.%lu",
                           record->psi->name, record->id,
-                         record->compressed ? ".enc.z" : "");
+                         record->compressed ? ".enc.z" : "",
+                         record->time.tv_sec, record->time.tv_nsec / 1000);
                 break;
         case PSTORE_TYPE_CONSOLE:


~Ankit

Re: [PATCH 2/2] Save current timestamp part of dmesg while writing oops message to pstore

[Ankit Kumar]

Hi Kees,



On Tuesday 23 May 2017 02:19 PM, Ankit Kumar wrote:
> Hi Kees,
>
>
>
> On Tuesday 23 May 2017 05:21 AM, Kees Cook wrote:
>> On Mon, May 22, 2017 at 3:20 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.
>>>
>>> Present code creates pstore dump file(/sys/fs/pstore/dmesg-***) 
>>> based on
>>> timestamp(retrieved from header). Current pstore code creates dump file
>>> (/sys/fs/pstore/dmesg-***) with that timestamp. Dump file can be 
>>> analyzed
>>> based on file creation time and we can make out whether dump file 
>>> has latest
>>> data or not.
>>>
>>> But when we transfer pstore dump file(/sys/fs/pstore/dmesg-***) to 
>>> other
>>> machine or collect file using some 
>>> utilities(sosreport/supportconfig) then file
>>> timestamp gets changed and hence by looking at device file 
>>> (dmesg-***) we won't
>>> be able to identify whether dump has latest data or not.
>>>
>>> Above issue can be fixed if we also have timestamp(dump creation 
>>> time) as
>>> initial few bytes while capturing dmesg buffer to pstore dump file
>>> (/sys/fs/pstore/dmesg-***).
>>>
>>>
>>> This patch enhances pstore write code to also write timestamp as 
>>> part of data.
>>>
>>> Here is sample log of dump file:(/sys/fs/pstore/dmesg-***)
>>> Oops#1 Part1 [timestamp:1494939359.590463]
>> While I understand your rationale about possibly losing file timestamp
>> information in userspace, I think this is a solvable problem on the
>> collection side. If an additional header is needed, perhaps copy the
>> dmesg files like this:
>>
>> for i in dmesg-*; do
>>      (stat --format=%y /sys/fs/pstore/$i; \
>>       cat /sys/fs/pstore/$i) > $collect_dir/$i
>> done
>
> Yes. We can handle this in userspace. But we wanted to see if we can 
> add this as part of pstore
> log itself.
>
>
>> One of the primary concerns for pstore is the stored dump size,
>
> I understand. How about adding timestamp to file name itself? 
> Something like below


How about appending time as part of file name itself. ?
Did you get time to look at above approach.
Code can be something like below piece.

~Ankit
>
> index 792a4e5..0837365 100644
> --- a/fs/pstore/inode.c
> +++ b/fs/pstore/inode.c
> @@ -349,9 +349,10 @@ int pstore_mkfile(struct dentry *root, struct 
> pstore_record *record)
>
>         switch (record->type) {
>         case PSTORE_TYPE_DMESG:
> -               scnprintf(name, sizeof(name), "dmesg-%s-%lld%s",
> +               scnprintf(name, sizeof(name), "dmesg-%s-%lld%s-%lu.%lu",
>                           record->psi->name, record->id,
> -                         record->compressed ? ".enc.z" : "");
> +                         record->compressed ? ".enc.z" : "",
> +                         record->time.tv_sec, record->time.tv_nsec / 
> 1000);
>                 break;
>         case PSTORE_TYPE_CONSOLE:
>
>
> ~Ankit