Messages in this thread Patch in this message | | | Subject | Re: Linux messages full of `random: get_random_u32 called from` | From | Sultan Alsawaf <> | Date | Fri, 27 Apr 2018 15:59:10 -0700 |
| |
> 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
| |