From: Sebastian Andrzej Siewior <bigeasy@linutronix.de>

Date: Tue, 30 May 2017 16:39:01 +0200

Subject: char/random: don't print that the init is done

Git-repo: git://git.kernel.org/pub/scm/linux/kernel/git/rt/linux-rt-devel.git

Git-commit: 4c441f8b036a13296cc41973523d6ed2bf3a7fe8

Patch-mainline: Queued in subsystem maintainer repository

References: SLE Realtime Extension

On RT we run into circular locking with pendingb_lock (workqueue),

port_lock_key (uart) and the primary_crng (random):

 ======================================================

 [ INFO: possible circular locking dependency detected ]

 -------------------------------------------------------

 irq/4-serial/512 is trying to acquire lock:

  ((pendingb_lock).lock){+.+...}, at: [<ffffffff8108d48d>] queue_work_on+0x5d/0x190

 but task is already holding lock:

  (&port_lock_key){+.+...}, at: [<ffffffff815b4bb6>] serial8250_handle_irq.part.27+0x16/0xb0

 which lock already depends on the new lock.

 the existing dependency chain (in reverse order) is:

 -> #3 (&port_lock_key){+.+...}:

        lock_acquire+0xac/0x240

        rt_spin_lock+0x46/0x50

        serial8250_console_write+0x211/0x220

        univ8250_console_write+0x1c/0x20

        console_unlock+0x563/0x5c0

        vprintk_emit+0x277/0x320

        vprintk_default+0x1a/0x20

        vprintk_func+0x20/0x80

        printk+0x3e/0x46

        crng_fast_load+0xde/0xe0

        add_interrupt_randomness+0x16c/0x1a0

        irq_thread+0x15c/0x1e0

        kthread+0x112/0x150

        ret_from_fork+0x31/0x40

 -> #2 (primary_crng.lock){+.+...}:

        lock_acquire+0xac/0x240

        rt_spin_lock+0x46/0x50

        _extract_crng+0x39/0xa0

        extract_crng+0x3a/0x40

        get_random_u32+0x120/0x190

        new_slab+0x1d6/0x7c0

        ___slab_alloc+0x30b/0x6f0

        __slab_alloc.isra.78+0x6c/0xc0

        __kmalloc+0x254/0x3a0

        pcpu_mem_zalloc+0x3a/0x70

        percpu_init_late+0x4f/0x8a

        start_kernel+0x1ec/0x3b8

        x86_64_start_reservations+0x2a/0x2c

        x86_64_start_kernel+0x13d/0x14c

        verify_cpu+0x0/0xfc

 -> #1 ((batched_entropy_u32_lock).lock){+.+...}:

        lock_acquire+0xac/0x240

        rt_spin_lock__no_mg+0x41/0x50

        get_random_u32+0x64/0x190

        new_slab+0x1d6/0x7c0

        ___slab_alloc+0x30b/0x6f0

        __slab_alloc.isra.78+0x6c/0xc0

        kmem_cache_alloc+0x26a/0x370

        __debug_object_init+0x325/0x460

        debug_object_activate+0x11c/0x1f0

        __queue_work+0x2c/0x770

        queue_work_on+0x12a/0x190

        serio_queue_event+0xd3/0x140

        __serio_register_port+0x17e/0x1a0

        i8042_probe+0x623/0x687

        platform_drv_probe+0x36/0x90

        driver_probe_device+0x1f8/0x2e0

        __driver_attach+0x96/0xa0

        bus_for_each_dev+0x5d/0x90

        driver_attach+0x19/0x20

        bus_add_driver+0x125/0x220

        driver_register+0x5b/0xd0

        __platform_driver_probe+0x5b/0x120

        __platform_create_bundle+0xaa/0xd0

        i8042_init+0x3f1/0x430

        do_one_initcall+0x3e/0x180

        kernel_init_freeable+0x212/0x295

        kernel_init+0x9/0x100

        ret_from_fork+0x31/0x40

 -> #0 ((pendingb_lock).lock){+.+...}:

        __lock_acquire+0x11b4/0x1320

        lock_acquire+0xac/0x240

        rt_spin_lock+0x46/0x50

        queue_work_on+0x5d/0x190

        tty_flip_buffer_push+0x26/0x30

        serial8250_rx_chars+0x120/0x1f0

        serial8250_handle_irq.part.27+0x58/0xb0

        serial8250_default_handle_irq+0x4b/0x60

        serial8250_interrupt+0x5f/0xd0

        irq_forced_thread_fn+0x1e/0x70

        irq_thread+0x137/0x1e0

        kthread+0x112/0x150

        ret_from_fork+0x31/0x40

 other info that might help us debug this:

 Chain exists of:

   (pendingb_lock).lock --> primary_crng.lock --> &port_lock_key

  Possible unsafe locking scenario:

        CPU0                    CPU1

        ----                    ----

   lock(&port_lock_key);

                                lock(primary_crng.lock);

                                lock(&port_lock_key);

   lock((pendingb_lock).lock);

  *** DEADLOCK ***

 2 locks held by irq/4-serial/512:

  #0:  (&i->lock){+.+...}, at: [<ffffffff815b0400>] serial8250_interrupt+0x30/0xd0

  #1:  (&port_lock_key){+.+...}, at: [<ffffffff815b4bb6>] serial8250_handle_irq.part.27+0x16/0xb0

 stack backtrace:

 CPU: 4 PID: 512 Comm: irq/4-serial Not tainted 4.11.3-rt0+ #101

 Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS 1.10.2-1 04/01/2014

 Call Trace:

  dump_stack+0x86/0xc1

  print_circular_bug+0x1be/0x210

  __lock_acquire+0x11b4/0x1320

  lock_acquire+0xac/0x240

  rt_spin_lock+0x46/0x50

  queue_work_on+0x5d/0x190

  tty_flip_buffer_push+0x26/0x30

  serial8250_rx_chars+0x120/0x1f0

  serial8250_handle_irq.part.27+0x58/0xb0

  serial8250_default_handle_irq+0x4b/0x60

  serial8250_interrupt+0x5f/0xd0

  irq_forced_thread_fn+0x1e/0x70

  irq_thread+0x137/0x1e0

  kthread+0x112/0x150

  ret_from_fork+0x31/0x40

It should work if we delay that printk after dropping the lock but we

also could skip it.

Signed-off-by: Sebastian Andrzej Siewior <bigeasy@linutronix.de>

Signed-off-by: Mike Galbraith <mgalbraith@suse.de>

---

 drivers/char/random.c |    2 --

 1 file changed, 2 deletions(-)

--- a/drivers/char/random.c

+++ b/drivers/char/random.c

@@ -864,7 +864,6 @@ static void crng_finalize_init(struct cr

 	crng_init = 2;

 	process_random_ready_list();

 	wake_up_interruptible(&crng_init_wait);

-	pr_notice("crng init done\n");

 	if (unseeded_warning.missed) {

 		pr_notice("%d get_random_xx warning(s) missed due to ratelimiting\n",

 			  unseeded_warning.missed);

@@ -901,7 +900,6 @@ static int crng_fast_load(const char *cp

 	if (crng_init_cnt >= CRNG_INIT_CNT_THRESH) {

 		crng_init = 1;

 		wake_up_interruptible(&crng_init_wait);

-		pr_notice("random: fast init done\n");

 	}

 	return 1;

 }