linux-kernel - Re: [PATCH v3] printk: Add boottime and real timestamps

lists.openwall.net		lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC
Open Source and information security mailing list archives

Hash Suite: Windows password security audit tool. GUI, reports in PDF.

[<prev] [next>] [<thread-prev] [thread-next>] [day] [month] [year] [list]

Date:   Wed, 9 Aug 2017 20:24:33 +0200
From:   "Luis R. Rodriguez" <mcgrof@...nel.org>
To:     Prarit Bhargava <prarit@...hat.com>
Cc:     "Luis R. Rodriguez" <mcgrof@...nel.org>,
        linux-kernel@...r.kernel.org, Mark Salyzyn <salyzyn@...roid.com>,
        Jonathan Corbet <corbet@....net>,
        Petr Mladek <pmladek@...e.com>,
        Sergey Senozhatsky <sergey.senozhatsky@...il.com>,
        Steven Rostedt <rostedt@...dmis.org>,
        John Stultz <john.stultz@...aro.org>,
        Thomas Gleixner <tglx@...utronix.de>,
        Stephen Boyd <sboyd@...eaurora.org>,
        Andrew Morton <akpm@...ux-foundation.org>,
        Greg Kroah-Hartman <gregkh@...uxfoundation.org>,
        "Paul E. McKenney" <paulmck@...ux.vnet.ibm.com>,
        Christoffer Dall <cdall@...aro.org>,
        Deepa Dinamani <deepa.kernel@...il.com>,
        Ingo Molnar <mingo@...nel.org>,
        Joel Fernandes <joelaf@...gle.com>,
        Kees Cook <keescook@...omium.org>,
        Peter Zijlstra <peterz@...radead.org>,
        Geert Uytterhoeven <geert+renesas@...der.be>,
        Nicholas Piggin <npiggin@...il.com>,
        "Jason A. Donenfeld" <Jason@...c4.com>,
        Olof Johansson <olof@...om.net>,
        Josh Poimboeuf <jpoimboe@...hat.com>, linux-doc@...r.kernel.org
Subject: Re: [PATCH v3] printk: Add boottime and real timestamps

On Mon, Aug 07, 2017 at 02:17:33PM -0400, Prarit Bhargava wrote:
> 
> 
> On 08/07/2017 01:14 PM, Luis R. Rodriguez wrote:
> 
> > 
> > Note printk_late_init() is a late_initcall(). This means if the
> > printk_time_setting was disabled it will take a while to enable it. Enabling it
> > is done at the device_initcall(), so if printk setting is disabled but a user
> > enables it with a toggle of the module param there is a period of time during
> > which time resolution would be different. 
> 
> I'm not sure I follow your comment.  Could you elaborate with an example of
> what you think is going wrong or might be confusing?

Sure let's consider this:

+static u64 printk_get_ts(void)
+{
+	u64 mono, offset_real;
+
+	if (printk_time <= PRINTK_TIME_LOCAL)
+		return local_clock();
+
+	if (printk_time == PRINTK_TIME_BOOT)
+		return ktime_get_boot_log_ts();
+
+	mono = ktime_get_real_log_ts(&offset_real);
+
+	if (printk_time == PRINTK_TIME_MONO)
+		return mono;
+
+	return mono + offset_real;
+}

So even if printk_time was flipped in the end the backend routines used will be
local_clock(), ,ktime_get_boot_log_ts() or ktime_get_real_log_ts().

This is used here;
 
@@ -1643,7 +1756,7 @@ static bool cont_add(int facility, int level, enum log_flags flags, const char *
 		cont.facility = facility;
 		cont.level = level;
 		cont.owner = current;
-		cont.ts_nsec = local_clock();
+		cont.ts_nsec = printk_get_ts();
 		cont.flags = flags;
 	}


But lets inspect these new calls:
 
diff --git a/kernel/time/timekeeping.c b/kernel/time/timekeeping.c
@@ -477,6 +479,24 @@ u64 notrace ktime_get_boot_fast_ns(void)
 }
 EXPORT_SYMBOL_GPL(ktime_get_boot_fast_ns);
 
+u64 ktime_get_real_log_ts(u64 *offset_real)
+{
+	*offset_real = ktime_to_ns(tk_core.timekeeper.offs_real);
+
+	if (timekeeping_active)
+		return ktime_get_mono_fast_ns();
+	else
+		return local_clock();
+}
+
+u64 ktime_get_boot_log_ts(void)
+{
+	if (timekeeping_active)
+		return ktime_get_boot_fast_ns();
+	else
+		return local_clock();
+}
+

So they are really only effectively calling something other than
what lock_clock() returns *iff* timekeeping_active is true. But
this is only set later at the respective device_initcall() in this
file:

@@ -1530,6 +1550,8 @@ void __init timekeeping_init(void)
 
 	write_seqcount_end(&tk_core.seq);
 	raw_spin_unlock_irqrestore(&timekeeper_lock, flags);
+
+	timekeeping_active = 1;
 }
 

So when the boot param is processed and prints out that it has
changed someone inspecting any time setting after that print
may assume its using after that ktime_get_mono_fast_ns() or
time_get_boot_fast_ns() but this is not accurate, it will use
local_clock() until *after* device_initcall().

So in between boot and this particular device_initcall() time
resolution can only be local_time(). Seems worth documenting
that.

  Luis