LKML Archive on lore.kernel.org
help / color / mirror / Atom feed
From: Sultan Alsawaf <sultanxda@gmail.com>
To: "Theodore Y. Ts'o" <tytso@mit.edu>,
	linux-kernel@vger.kernel.org, Jann Horn <jannh@google.com>
Subject: Re: Linux messages full of `random: get_random_u32 called from`
Date: Fri, 27 Apr 2018 15:59:10 -0700	[thread overview]
Message-ID: <450cdbd9-4eae-2f0f-e9d3-7603e5dbd655@gmail.com> (raw)
In-Reply-To: <20180427201036.GL5965@thunk.org>

> On Thu, Apr 26, 2018 at 10:20:44PM -0700, Sultan Alsawaf wrote:
>> I noted at least 20,000 mmc interrupts before I intervened in the boot process to provide entropy
>> myself. That's just for mmc, so I'm sure there were even more interrupts elsewhere. Is 20k+ interrupts
>> really not sufficient?
> How did you determine that there were 20,000 mmc interrupts before you
> had logged in?  Did you have access to the machine w/o having access
> to the login prompt?
>
> I can send a patch (see attached) that will spew large amounts of logs
> as each interrupt comes in and the entropy pool is getting intialized.
> That's how I test things on QEMU, and Jann did something similar on a
> (physical) test machine, so I'm pretty confident that if you were
> getting interrupts, it would result in them contributing into the
> pool.
>
> You will need a serial console, or build a kernel with a much larger
> dmesg buffer, since if you really are getting that many interrupts it
> will cause a lot of log spew.  
>> There are lots of other sources of entropy available as well, like
>> the ever-changing CPU frequencies reported by any recent Intel chip
>> (i.e., they report precision down to 1 kHz).
> That's something we could look at, but the problem is if there is some
> systemd unit during early boot that blocks waiting for the entropy
> pool to be initalized, the system will come to a dead halt, and even
> the CPU frequency shifts will probably not move much --- just as there
> weren't any interrupts while some system startup on the boot path
> wedges the system startup waiting for entropy.
>
> This is why ultimately, we do need to attack this problem from both
> ends, which means teaching userspace programs to only request
> cryptographic-grade randomness when it is really needed --- and most
> of the time, if the user has not logged in yet, you probably don't
> need cryptographic-grade randomness....
>
> 						- Ted
>
> diff --git a/drivers/char/random.c b/drivers/char/random.c
> index cd888d4ee605..69bd29f039e7 100644
> --- a/drivers/char/random.c
> +++ b/drivers/char/random.c
> @@ -916,6 +916,10 @@ static void crng_reseed(struct crng_state *crng, struct entropy_store *r)
>  		__u32	key[8];
>  	} buf;
>  
> +	if (crng == &primary_crng)
> +		pr_notice("random: crng_reseed primary from %px\n", r);
> +	else
> +		pr_notice("random: crng_reseed crng %px from %px\n", crng, r);
>  	if (r) {
>  		num = extract_entropy(r, &buf, 32, 16, 0);
>  		if (num == 0)
> @@ -1241,6 +1245,10 @@ void add_interrupt_randomness(int irq, int irq_flags)
>  	fast_pool->pool[2] ^= ip;
>  	fast_pool->pool[3] ^= (sizeof(ip) > 4) ? ip >> 32 :
>  		get_reg(fast_pool, regs);
> +	if (crng_init < 2)
> +		pr_notice("random: add_interrupt(cycles=0x%08llx, now=%ld, "
> +			  "irq=%d, ip=0x%08lx)\n",
> +			  cycles, now, irq, _RET_IP_);
>  
>  	fast_mix(fast_pool);
>  	add_interrupt_bench(cycles);
> @@ -1282,6 +1290,9 @@ void add_interrupt_randomness(int irq, int irq_flags)
>  
>  	/* award one bit for the contents of the fast pool */
>  	credit_entropy_bits(r, credit + 1);
> +	if (crng_init < 2)
> +		pr_notice("random: batched into pool in stage %d, bits now %d",
> +			  crng_init, ENTROPY_BITS(r));
>  }
>  EXPORT_SYMBOL_GPL(add_interrupt_randomness);

I dumped the contents of /proc/interrupts to dmesg using the attached patch I threw together,
and then waited a sufficient amount of time before introducing entropy myself in order to ensure
that the interrupt readings were not contaminated by user-provided interrupts.

Here is the interesting snippet from my dmesg:
[   30.689076] /proc/interrupts dump: 
               |            CPU0       CPU1       CPU2       CPU3       
                  0:          6          0          0          0   IO-APIC    2-edge      timer
                  8:          0          0          1          0   IO-APIC    8-edge      rtc0
                  9:          0        533          0          0   IO-APIC    9-fasteoi   acpi
                 10:          0          0          0          0   IO-APIC   10-edge      tpm0
                 29:          0          0          0          0   IO-APIC   29-fasteoi   intel_sst_driver
                 36:        203          0          0          0   IO-APIC   36-fasteoi   808622C1:04
                 37:          0        264          0          0   IO-APIC   37-fasteoi   808622C1:05
                 42:          0          0          0          0   IO-APIC   42-fasteoi   dw:dmac-1
                 43:          0          0          0          0   IO-APIC   43-fasteoi   dw:dmac-1
                 45:          0          0          0      11402   IO-APIC   45-fasteoi   mmc0
                168:          0          0          1          0  chv-gpio   95  rt5645
                182:          0          0          0          9  chv-gpio   17  i8042
                183:          0          0          0          0  chv-gpio   18  ELAN0000:00
                230:          0          0          0          0  chv-gpio   15  ACPI:Event
                310:          0          0          0          0   PCI-MSI 458752-edge      PCIe PME, pciehp
                311:          0          0          0          0   PCI-MSI 462848-edge      PCIe PME
                312:          0        520          0          0   PCI-MSI 327680-edge      xhci_hcd
                313:        940          0          0          0   PCI-MSI 32768-edge      i915
                314:          0        137          0          0   PCI-MSI 1048576-edge      iwlwifi
                315:          0          0          0         70   PCI-MSI 442368-edge      snd_hda_intel:card0
                NMI:          0          0          0          0   Non-maskable interrupts
                LOC:       4419       4014       4590       4564   Local timer interrupts
                SPU:          0          0          0          0   Spurious interrupts
                PMI:          0          0          0          0   Performance monitoring interrupts
                IWI:          1          0          0          0   IRQ work interrupts
                RTR:          0          0          0          0   APIC ICR read retries
                RES:       1562       1235       1647        796   Rescheduling interrupts
                CAL:       1220       1340       1466       1477   Function call interrupts
                TLB:         27         18         20         17   TLB shootdowns
                TRM:          0          0          0          0   Thermal event interrupts
                THR:          0          0          0          0   Threshold APIC interrupts
                MCE:          0          0          0          0   Machine check exceptions
                MCP:          1          1          1          1   Machine check polls
                ERR:          0
                MIS:          0
                PIN:          0          0          0          0   Posted-interrupt notification event
                NPI:          0          0          0          0   Nested posted-interrupt event
                PIW:          0          0          0          0   Posted-interrupt wakeup event
               |
[   81.698372] random: crng init done

Looks like there were 11,000 mmc interrupts 30 seconds into boot. When I measured 20,000, it was a few
minutes into boot, so that is why there is a disparity. Do also note that crng init completed 50 seconds
after the /proc/interrupts dump, so 11k+ interrupts clearly didn't do the trick. If you want, I can dump out
/proc/interrupts when the "random: crng init done" message is printed.

And here is the full dmesg: https://hastebin.com/isujicenev.vbs

Sultan

>From 79576697e3ca631c88ea784d837672ef34a24e42 Mon Sep 17 00:00:00 2001
From: Sultan Alsawaf <sultanxda@gmail.com>
Date: Fri, 27 Apr 2018 15:46:18 -0700
Subject: [PATCH] Print out /proc/interrupts to kmsg ~30s after boot

---
 fs/proc/Makefile           |  1 +
 fs/proc/interrupts_print.c | 42 ++++++++++++++++++++++++++++++++++++++++++
 kernel/printk/printk.c     |  2 +-
 3 files changed, 44 insertions(+), 1 deletion(-)
 create mode 100644 fs/proc/interrupts_print.c

diff --git a/fs/proc/Makefile b/fs/proc/Makefile
index ead487e80510..9bd462cec4ec 100644
--- a/fs/proc/Makefile
+++ b/fs/proc/Makefile
@@ -33,3 +33,4 @@ proc-$(CONFIG_PROC_KCORE)	+= kcore.o
 proc-$(CONFIG_PROC_VMCORE)	+= vmcore.o
 proc-$(CONFIG_PRINTK)	+= kmsg.o
 proc-$(CONFIG_PROC_PAGE_MONITOR)	+= page.o
+obj-y += interrupts_print.o
diff --git a/fs/proc/interrupts_print.c b/fs/proc/interrupts_print.c
new file mode 100644
index 000000000000..4981dca3b828
--- /dev/null
+++ b/fs/proc/interrupts_print.c
@@ -0,0 +1,42 @@
+#include <linux/slab.h>
+#include <linux/syscalls.h>
+#include <linux/workqueue.h>
+
+#define BUF_MAX_LEN (10000)
+
+static struct delayed_work intr_print_dwork;
+
+static void print_out_interrupts(struct work_struct *work)
+{
+	char *buf;
+	int fd, i;
+
+	buf = kzalloc(BUF_MAX_LEN, GFP_KERNEL);
+	if (!buf)
+		return;
+
+	fd = sys_open("/proc/interrupts", O_RDONLY, 0444);
+	if (fd < 0)
+		goto free_buf;
+
+	for (i = 0; i < BUF_MAX_LEN - 1; i++) {
+		if (sys_read(fd, buf + i, 1) != 1)
+			break;
+	}
+	sys_close(fd);
+
+	printk("/proc/interrupts dump: \n|%s|\n", buf);
+
+free_buf:
+	kfree(buf);
+}
+
+static int __init intr_print_init(void)
+{
+	INIT_DELAYED_WORK(&intr_print_dwork, print_out_interrupts);
+	schedule_delayed_work(&intr_print_dwork,
+		msecs_to_jiffies(30 * MSEC_PER_SEC));
+
+	return 0;
+}
+device_initcall(intr_print_init);
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index f274fbef821d..2d3151ce5f24 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -428,7 +428,7 @@ static u64 clear_seq;
 static u32 clear_idx;
 
 #define PREFIX_MAX		32
-#define LOG_LINE_MAX		(1024 - PREFIX_MAX)
+#define LOG_LINE_MAX		(10000)
 
 #define LOG_LEVEL(v)		((v) & 0x07)
 #define LOG_FACILITY(v)		((v) >> 3 & 0xff)
-- 
2.14.1

  reply	other threads:[~2018-04-27 22:59 UTC|newest]

Thread overview: 65+ messages / expand[flat|nested]  mbox.gz  Atom feed  top
2018-04-26  4:11 Sultan Alsawaf
2018-04-26  5:00 ` Theodore Y. Ts'o
2018-04-26  5:05   ` Sultan Alsawaf
2018-04-26  7:32     ` Theodore Y. Ts'o
2018-04-26 15:17       ` Sultan Alsawaf
2018-04-26 19:25         ` Theodore Y. Ts'o
2018-04-26 20:22           ` Sultan Alsawaf
2018-04-26 20:47             ` Christian Brauner
2018-04-27  0:00               ` Theodore Y. Ts'o
2018-04-27 15:38                 ` Jason A. Donenfeld
2018-04-27 19:14                   ` Theodore Y. Ts'o
2018-04-26 23:56             ` Theodore Y. Ts'o
2018-04-27  5:20               ` Sultan Alsawaf
2018-04-27 20:10                 ` Theodore Y. Ts'o
2018-04-27 22:59                   ` Sultan Alsawaf [this message]
2018-04-29 14:32                   ` Pavel Machek
2018-04-29 17:05                     ` Sultan Alsawaf
2018-04-29 18:41                       ` Pavel Machek
2018-04-29 20:20                         ` Sultan Alsawaf
2018-04-29 21:18                           ` Pavel Machek
2018-04-29 21:34                             ` Sultan Alsawaf
2018-04-29 22:05                           ` Theodore Y. Ts'o
2018-04-29 22:26                             ` Sultan Alsawaf
2018-04-29 22:43                               ` Jason A. Donenfeld
2018-04-29 22:49                                 ` Sultan Alsawaf
2018-04-30  0:11                                   ` Theodore Y. Ts'o
2018-04-30  4:34                                     ` Sultan Alsawaf
2018-04-30 16:11                                       ` Theodore Y. Ts'o
2018-05-01 19:53                                         ` Pavel Machek
2018-04-29 22:43                             ` Pavel Machek
2018-04-30  0:32                             ` Laura Abbott
2018-04-30 21:12                             ` Jeremy Cline
2018-05-01 11:52                               ` Justin Forbes
2018-05-01 12:55                                 ` Theodore Y. Ts'o
2018-05-01 22:35                                   ` Justin Forbes
2018-05-02  0:02                                     ` Theodore Y. Ts'o
2018-05-02 12:09                                       ` Justin Forbes
2018-05-02 16:26                                         ` Theodore Y. Ts'o
2018-05-02 17:49                                           ` Laura Abbott
2018-05-02 22:25                                             ` Theodore Y. Ts'o
2018-05-03  6:19                                               ` Pavel Machek
2018-05-03 12:23                                               ` Justin Forbes
2018-05-02  0:43                                     ` Sultan Alsawaf
2018-05-02  0:56                                       ` Theodore Y. Ts'o
2018-05-02  1:11                                         ` Sultan Alsawaf
2018-04-29 18:30                   ` Sultan Alsawaf
2018-04-29 20:08                     ` Theodore Y. Ts'o
2018-05-18  1:27                   ` Trent Piepho
2018-05-18  2:32                     ` Theodore Y. Ts'o
2018-05-18 22:56                       ` Trent Piepho
2018-05-18 23:22                         ` Theodore Y. Ts'o
2018-05-21 18:39                           ` Trent Piepho
2018-04-29 14:29               ` Pavel Machek
  -- strict thread matches above, loose matches on Subject: below --
2018-04-24 11:48 Paul Menzel
2018-04-24 13:56 ` Theodore Y. Ts'o
2018-04-24 14:30   ` Paul Menzel
2018-04-24 15:49   ` Theodore Y. Ts'o
2018-04-24 15:56     ` Paul Menzel
2018-04-25  7:41       ` Theodore Y. Ts'o
2018-04-26  3:48         ` Paul Menzel
2018-04-29 14:22           ` Pavel Machek
2018-04-29 23:02   ` Dave Jones
2018-04-29 23:07     ` Dave Jones
2018-04-30  0:21       ` Theodore Y. Ts'o
2018-04-26  5:51 ` Pavel Machek

Reply instructions:

You may reply publicly to this message via plain-text email
using any one of the following methods:

* Save the following mbox file, import it into your mail client,
  and reply-to-all from there: mbox

  Avoid top-posting and favor interleaved quoting:
  https://en.wikipedia.org/wiki/Posting_style#Interleaved_style

* Reply using the --to, --cc, and --in-reply-to
  switches of git-send-email(1):

  git send-email \
    --in-reply-to=450cdbd9-4eae-2f0f-e9d3-7603e5dbd655@gmail.com \
    --to=sultanxda@gmail.com \
    --cc=jannh@google.com \
    --cc=linux-kernel@vger.kernel.org \
    --cc=tytso@mit.edu \
    --subject='Re: Linux messages full of `random: get_random_u32 called from`' \
    /path/to/YOUR_REPLY

  https://kernel.org/pub/software/scm/git/docs/git-send-email.html

* If your mail client supports setting the In-Reply-To header
  via mailto: links, try the mailto: link

This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).