Message-ID: <CAHmME9pb9A4SN6TTjNvvxKqw1L3gXVOX7KKihfEH4AgKGNGZ2A@mail.gmail.com>
Date:   Thu, 27 Jan 2022 23:26:32 +0100
From:   "Jason A. Donenfeld" <Jason@...c4.com>
To:     Jonathan Neuschäfer <j.neuschaefer@....net>,
        Andy Lutomirski <luto@...capital.net>
Cc:     LKML <linux-kernel@...r.kernel.org>,
        "Theodore Ts'o" <tytso@....edu>,
        Sebastian Andrzej Siewior <bigeasy@...utronix.de>,
        Peter Zijlstra <peterz@...radead.org>,
        Ingo Molnar <mingo@...hat.com>, Will Deacon <will@...nel.org>,
        Waiman Long <longman@...hat.com>,
        Boqun Feng <boqun.feng@...il.com>
Subject: Re: "BUG: Invalid wait context" in invalidate_batched_entropy

Hi Jonathan,

Thanks for the report. I'll try to reproduce this and see what's going on.

I'm emailing back right away, though, so that I can CC in Andy
Lutomirski, who I know has been sitting on a stack of patches that fix
up (actually, remove) the locking, so this might be one path to fixing
this.

Thanks,
Jason

On Thu, Jan 27, 2022 at 11:21 PM Jonathan Neuschäfer
<j.neuschaefer@....net> wrote:
>
> Hi,
>
> when booting my ARM board with lockdep and CONFIG_PROVE_LOCKING, I get the following message:
>
> [    2.500000] =============================
> [    2.500000] [ BUG: Invalid wait context ]
> [    2.500000] 5.17.0-rc1 #563 Not tainted
> [    2.500000] -----------------------------
> [    2.500000] swapper/1 is trying to lock:
> [    2.500000] c0b0e9cc (batched_entropy_u32.lock){....}-{3:3}, at: invalidate_batched_entropy+0x18/0x4c
> [    2.500000] other info that might help us debug this:
> [    2.500000] context-{2:2}
> [    2.500000] 3 locks held by swapper/1:
> [    2.500000]  #0: c0ae86ac (event_mutex){+.+.}-{4:4}, at: event_trace_init+0x4c/0xd8
> [    2.500000]  #1: c0ae81b8 (trace_event_sem){+.+.}-{4:4}, at: event_trace_init+0x68/0xd8
> [    2.500000]  #2: c19b05cc (&sb->s_type->i_mutex_key#2){+.+.}-{4:4}, at: start_creating+0x40/0xc4
> [    2.500000] stack backtrace:
> [    2.500000] CPU: 0 PID: 1 Comm: swapper Not tainted 5.17.0-rc1 #563
> [    2.500000] Hardware name: WPCM450 chip
> [    2.500000] [<c00100a8>] (unwind_backtrace) from [<c000db2c>] (show_stack+0x10/0x14)
> [    2.500000] [<c000db2c>] (show_stack) from [<c0054eec>] (__lock_acquire+0x3f0/0x189c)
> [    2.500000] [<c0054eec>] (__lock_acquire) from [<c0054478>] (lock_acquire+0x2b8/0x354)
> [    2.500000] [<c0054478>] (lock_acquire) from [<c0568028>] (_raw_spin_lock_irqsave+0x60/0x74)
> [    2.500000] [<c0568028>] (_raw_spin_lock_irqsave) from [<c030b6f4>] (invalidate_batched_entropy+0x18/0x4c)
> [    2.500000] [<c030b6f4>] (invalidate_batched_entropy) from [<c030e7fc>] (crng_fast_load+0xf0/0x110)
> [    2.500000] [<c030e7fc>] (crng_fast_load) from [<c030e954>] (add_interrupt_randomness+0x138/0x200)
> [    2.500000] [<c030e954>] (add_interrupt_randomness) from [<c0061b34>] (handle_irq_event_percpu+0x18/0x38)
> [    2.500000] [<c0061b34>] (handle_irq_event_percpu) from [<c0061b8c>] (handle_irq_event+0x38/0x5c)
> [    2.500000] [<c0061b8c>] (handle_irq_event) from [<c0065b28>] (handle_fasteoi_irq+0x9c/0x114)
> [    2.500000] [<c0065b28>] (handle_fasteoi_irq) from [<c0061178>] (handle_irq_desc+0x24/0x34)
> [    2.500000] [<c0061178>] (handle_irq_desc) from [<c056214c>] (generic_handle_arch_irq+0x28/0x3c)
> [    2.500000] [<c056214c>] (generic_handle_arch_irq) from [<c0008eb4>] (__irq_svc+0x54/0x80)
> [    2.500000] Exception stack(0xc1485d48 to 0xc1485d90)
> [    2.500000] 5d40:                   9780e804 00000001 c09413d4 200000d3 60000053 c016af54
> [    2.500000] 5d60: 00000000 c0afa5b8 c14194e0 c19a1d48 c0789ce0 00000000 c1490480 c1485d98
> [    2.500000] 5d80: c0168970 c0168984 20000053 ffffffff
> [    2.500000] [<c0008eb4>] (__irq_svc) from [<c0168984>] (read_seqbegin.constprop.0+0x6c/0x90)
> [    2.500000] [<c0168984>] (read_seqbegin.constprop.0) from [<c016af54>] (d_lookup+0x14/0x40)
> [    2.500000] [<c016af54>] (d_lookup) from [<c015cecc>] (lookup_dcache+0x18/0x50)
> [    2.500000] [<c015cecc>] (lookup_dcache) from [<c015d868>] (lookup_one_len+0x90/0xe0)
> [    2.500000] [<c015d868>] (lookup_one_len) from [<c01e33e4>] (start_creating+0x68/0xc4)
> [    2.500000] [<c01e33e4>] (start_creating) from [<c01e398c>] (tracefs_create_file+0x30/0x11c)
> [    2.500000] [<c01e398c>] (tracefs_create_file) from [<c00c42f8>] (trace_create_file+0x14/0x38)
> [    2.500000] [<c00c42f8>] (trace_create_file) from [<c00cc854>] (event_create_dir+0x310/0x420)
> [    2.500000] [<c00cc854>] (event_create_dir) from [<c00cc9d8>] (__trace_early_add_event_dirs+0x28/0x50)
> [    2.500000] [<c00cc9d8>] (__trace_early_add_event_dirs) from [<c07c8d64>] (event_trace_init+0x70/0xd8)
> [    2.500000] [<c07c8d64>] (event_trace_init) from [<c07c8560>] (tracer_init_tracefs+0x14/0x284)
> [    2.500000] [<c07c8560>] (tracer_init_tracefs) from [<c000a330>] (do_one_initcall+0xdc/0x288)
> [    2.500000] [<c000a330>] (do_one_initcall) from [<c07bd1e8>] (kernel_init_freeable+0x1c4/0x20c)
> [    2.500000] [<c07bd1e8>] (kernel_init_freeable) from [<c05629c0>] (kernel_init+0x10/0x110)
> [    2.500000] [<c05629c0>] (kernel_init) from [<c00084f8>] (ret_from_fork+0x14/0x3c)
> [    2.500000] Exception stack(0xc1485fb0 to 0xc1485ff8)
> [    2.500000] 5fa0:                                     00000000 00000000 00000000 00000000
> [    2.500000] 5fc0: 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
> [    2.500000] 5fe0: 00000000 00000000 00000000 00000000 00000013 00000000
>
>
>
> I wasn't able to bisect it, but I can see it as far back as v5.13
> (I can't easily test earlier kernels). The lock in question was
> introduced with v5.2-rc1:
>
>
> commit b7d5dc21072cda7124d13eae2aefb7343ef94197
> Author: Sebastian Andrzej Siewior <bigeasy@...utronix.de>
> Date:   Sat Apr 20 00:09:51 2019 -0400
>
>     random: add a spinlock_t to struct batched_entropy
>
>     The per-CPU variable batched_entropy_uXX is protected by get_cpu_var().
>     This is just a preempt_disable() which ensures that the variable is only
>     from the local CPU. It does not protect against users on the same CPU
>     from another context. It is possible that a preemptible context reads
>     slot 0 and then an interrupt occurs and the same value is read again.
>
> [...]
>     Add a spinlock_t to the batched_entropy data structure and acquire the
>     lock while accessing it. Acquire the lock with disabled interrupts
>     because this function may be used from interrupt context.
>
>     Remove the batched_entropy_reset_lock lock. Now that we have a lock for
>     the data scructure, we can access it from a remote CPU.
>
>     Signed-off-by: Sebastian Andrzej Siewior <bigeasy@...utronix.de>
>     Signed-off-by: Theodore Ts'o <tytso@....edu>
>
>
> I'm not very familiar with the finer details of locking rules and
> lockdep, so any ideas (or patches) to fix this will be appreciated.
>
>
> Best regards,
> Jonathan Neuschäfer
> --
>
>
> In case it's relevant, here is my config:
>
> CONFIG_SYSVIPC=y
> CONFIG_NO_HZ=y
> CONFIG_HIGH_RES_TIMERS=y
> CONFIG_PREEMPT=y
> CONFIG_IKCONFIG=y
> CONFIG_IKCONFIG_PROC=y
> CONFIG_LOG_BUF_SHIFT=19
> CONFIG_CGROUPS=y
> CONFIG_NAMESPACES=y
> CONFIG_BLK_DEV_INITRD=y
> CONFIG_INITRAMFS_SOURCE="rootfs.cpio"
> CONFIG_CC_OPTIMIZE_FOR_SIZE=y
> CONFIG_EXPERT=y
> CONFIG_PROFILING=y
> # CONFIG_ARCH_MULTI_V7 is not set
> CONFIG_ARCH_NPCM=y
> CONFIG_ARCH_WPCM450=y
> CONFIG_CPU_DCACHE_WRITETHROUGH=y
> CONFIG_AEABI=y
> CONFIG_HIGHMEM=y
> CONFIG_UACCESS_WITH_MEMCPY=y
> CONFIG_ARM_APPENDED_DTB=y
> CONFIG_CMDLINE="earlyprintk debug console=ttyS0,115200 panic=-1"
> CONFIG_CMDLINE_EXTEND=y
> CONFIG_KEXEC=y
> # CONFIG_ATAGS_PROC is not set
> CONFIG_CPU_FREQ=y
> CONFIG_CPU_FREQ_STAT=y
> CONFIG_CPU_FREQ_DEFAULT_GOV_ONDEMAND=y
> CONFIG_CPU_IDLE=y
> CONFIG_KPROBES=y
> CONFIG_MODULES=y
> CONFIG_MODULE_UNLOAD=y
> CONFIG_ZSWAP=y
> CONFIG_ZSWAP_DEFAULT_ON=y
> CONFIG_Z3FOLD=y
> CONFIG_NET=y
> CONFIG_PACKET=y
> CONFIG_UNIX=y
> CONFIG_INET=y
> CONFIG_IP_MULTICAST=y
> CONFIG_IP_PNP=y
> CONFIG_IP_PNP_DHCP=y
> CONFIG_IP_PNP_BOOTP=y
> CONFIG_NET_DSA=y
> CONFIG_NET_DSA_TAG_DSA=y
> CONFIG_NET_DSA_TAG_EDSA=y
> CONFIG_NET_DSA_TAG_TRAILER=y
> CONFIG_NET_NCSI=y
> CONFIG_NCSI_OEM_CMD_GET_MAC=y
> CONFIG_NET_PKTGEN=m
> # CONFIG_WIRELESS is not set
> CONFIG_DEVTMPFS=y
> CONFIG_DEVTMPFS_MOUNT=y
> CONFIG_DEVTMPFS_SAFE=y
> CONFIG_MTD=y
> CONFIG_MTD_CMDLINE_PARTS=y
> CONFIG_MTD_BLOCK=y
> CONFIG_MTD_CFI=y
> CONFIG_MTD_JEDECPROBE=y
> CONFIG_MTD_CFI_ADV_OPTIONS=y
> CONFIG_MTD_CFI_GEOMETRY=y
> # CONFIG_MTD_MAP_BANK_WIDTH_4 is not set
> CONFIG_MTD_CFI_INTELEXT=y
> CONFIG_MTD_CFI_STAA=y
> CONFIG_MTD_PHYSMAP=y
> CONFIG_MTD_SPI_NOR=y
> CONFIG_BLK_DEV_LOOP=y
> CONFIG_SRAM=y
> CONFIG_EEPROM_AT24=y
> CONFIG_SCSI=y
> # CONFIG_SCSI_PROC_FS is not set
> # CONFIG_SCSI_LOWLEVEL is not set
> CONFIG_NETDEVICES=y
> # CONFIG_NET_VENDOR_ALACRITECH is not set
> # CONFIG_NET_VENDOR_AMAZON is not set
> # CONFIG_NET_VENDOR_AQUANTIA is not set
> # CONFIG_NET_VENDOR_ARC is not set
> # CONFIG_NET_VENDOR_BROADCOM is not set
> # CONFIG_NET_VENDOR_CADENCE is not set
> # CONFIG_NET_VENDOR_CAVIUM is not set
> # CONFIG_NET_VENDOR_CIRRUS is not set
> # CONFIG_NET_VENDOR_CORTINA is not set
> # CONFIG_NET_VENDOR_EZCHIP is not set
> # CONFIG_NET_VENDOR_FARADAY is not set
> # CONFIG_NET_VENDOR_GOOGLE is not set
> # CONFIG_NET_VENDOR_HISILICON is not set
> # CONFIG_NET_VENDOR_HUAWEI is not set
> # CONFIG_NET_VENDOR_INTEL is not set
> # CONFIG_NET_VENDOR_MICROSOFT is not set
> # CONFIG_NET_VENDOR_LITEX is not set
> # CONFIG_NET_VENDOR_MARVELL is not set
> # CONFIG_NET_VENDOR_MELLANOX is not set
> # CONFIG_NET_VENDOR_MICREL is not set
> # CONFIG_NET_VENDOR_MICROCHIP is not set
> # CONFIG_NET_VENDOR_MICROSEMI is not set
> # CONFIG_NET_VENDOR_NATSEMI is not set
> # CONFIG_NET_VENDOR_NETRONOME is not set
> # CONFIG_NET_VENDOR_NI is not set
> # CONFIG_NET_VENDOR_PENSANDO is not set
> # CONFIG_NET_VENDOR_QUALCOMM is not set
> # CONFIG_NET_VENDOR_RENESAS is not set
> # CONFIG_NET_VENDOR_ROCKER is not set
> # CONFIG_NET_VENDOR_SAMSUNG is not set
> # CONFIG_NET_VENDOR_SEEQ is not set
> # CONFIG_NET_VENDOR_SOLARFLARE is not set
> # CONFIG_NET_VENDOR_SMSC is not set
> # CONFIG_NET_VENDOR_SOCIONEXT is not set
> # CONFIG_NET_VENDOR_STMICRO is not set
> # CONFIG_NET_VENDOR_SYNOPSYS is not set
> # CONFIG_NET_VENDOR_VIA is not set
> # CONFIG_NET_VENDOR_WIZNET is not set
> # CONFIG_NET_VENDOR_XILINX is not set
> CONFIG_DAVICOM_PHY=y
> CONFIG_MARVELL_PHY=y
> CONFIG_MICREL_PHY=y
> CONFIG_REALTEK_PHY=y
> # CONFIG_WLAN is not set
> CONFIG_INPUT_EVDEV=y
> CONFIG_KEYBOARD_QT1070=m
> CONFIG_KEYBOARD_GPIO=y
> # CONFIG_INPUT_MOUSE is not set
> CONFIG_VT_HW_CONSOLE_BINDING=y
> CONFIG_LEGACY_PTY_COUNT=16
> CONFIG_SERIAL_8250=y
> CONFIG_SERIAL_8250_CONSOLE=y
> CONFIG_SERIAL_8250_NR_UARTS=6
> CONFIG_SERIAL_8250_RUNTIME_UARTS=6
> CONFIG_SERIAL_8250_EXTENDED=y
> CONFIG_SERIAL_8250_MANY_PORTS=y
> CONFIG_SERIAL_8250_ASPEED_VUART=m
> CONFIG_SERIAL_OF_PLATFORM=y
> CONFIG_HW_RANDOM=y
> CONFIG_I2C=y
> # CONFIG_I2C_COMPAT is not set
> CONFIG_I2C_CHARDEV=y
> CONFIG_I2C_MUX=y
> CONFIG_SPI=y
> CONFIG_SPI_BITBANG=y
> CONFIG_PINCTRL_SINGLE=y
> CONFIG_GPIOLIB=y
> CONFIG_DEBUG_GPIO=y
> CONFIG_GPIO_SYSFS=y
> CONFIG_GPIO_PCF857X=y
> CONFIG_POWER_RESET=y
> CONFIG_POWER_RESET_GPIO=y
> CONFIG_POWER_SUPPLY=y
> CONFIG_THERMAL=y
> CONFIG_WATCHDOG=y
> CONFIG_NPCM7XX_WATCHDOG=y
> CONFIG_MFD_ATMEL_HLCDC=y
> CONFIG_MFD_SYSCON=y
> CONFIG_REGULATOR=y
> CONFIG_REGULATOR_FIXED_VOLTAGE=y
> # CONFIG_DRM_DEBUG_MODESET_LOCK is not set
> CONFIG_FB=y
> CONFIG_FB_MODE_HELPERS=y
> CONFIG_HID_A4TECH=y
> CONFIG_HID_APPLE=y
> CONFIG_HID_BELKIN=y
> CONFIG_HID_CHERRY=y
> CONFIG_HID_CYPRESS=y
> CONFIG_HID_DRAGONRISE=y
> CONFIG_HID_EZKEY=y
> CONFIG_HID_GYRATION=y
> CONFIG_HID_ITE=y
> CONFIG_HID_TWINHAN=y
> CONFIG_HID_KENSINGTON=y
> CONFIG_HID_REDRAGON=y
> CONFIG_HID_MICROSOFT=y
> CONFIG_HID_MONTEREY=y
> CONFIG_HID_PANTHERLORD=y
> CONFIG_HID_PETALYNX=y
> CONFIG_HID_SUNPLUS=y
> CONFIG_HID_GREENASIA=y
> CONFIG_HID_SMARTJOYPLUS=y
> CONFIG_HID_TOPSEED=y
> CONFIG_HID_ZEROPLUS=y
> CONFIG_USB_CHIPIDEA=y
> CONFIG_USB_CHIPIDEA_UDC=y
> CONFIG_NOP_USB_XCEIV=y
> CONFIG_USB_GADGET=y
> CONFIG_U_SERIAL_CONSOLE=y
> CONFIG_USB_CONFIGFS=y
> CONFIG_USB_CONFIGFS_SERIAL=y
> CONFIG_USB_CONFIGFS_RNDIS=y
> CONFIG_USB_CONFIGFS_MASS_STORAGE=y
> CONFIG_USB_CONFIGFS_F_HID=y
> CONFIG_MMC=y
> CONFIG_SDIO_UART=y
> CONFIG_MMC_SDHCI=m
> CONFIG_MMC_SDHCI_PLTFM=m
> CONFIG_MMC_SDHCI_OF_ASPEED=m
> CONFIG_NEW_LEDS=y
> CONFIG_LEDS_CLASS=y
> CONFIG_LEDS_GPIO=y
> CONFIG_LEDS_TRIGGERS=y
> CONFIG_LEDS_TRIGGER_TIMER=y
> CONFIG_LEDS_TRIGGER_ONESHOT=y
> CONFIG_LEDS_TRIGGER_MTD=y
> CONFIG_LEDS_TRIGGER_HEARTBEAT=y
> CONFIG_LEDS_TRIGGER_CPU=y
> CONFIG_LEDS_TRIGGER_ACTIVITY=y
> CONFIG_LEDS_TRIGGER_DEFAULT_ON=y
> CONFIG_LEDS_TRIGGER_PANIC=y
> CONFIG_LEDS_TRIGGER_TTY=y
> CONFIG_RTC_CLASS=y
> CONFIG_RTC_DRV_RS5C372=y
> CONFIG_RTC_DRV_PCF8563=y
> CONFIG_RTC_DRV_S35390A=y
> CONFIG_RTC_DRV_RV3029C2=m
> CONFIG_DMADEVICES=y
> CONFIG_SYNC_FILE=y
> # CONFIG_DMABUF_DEBUG is not set
> # CONFIG_VIRTIO_MENU is not set
> # CONFIG_VHOST_MENU is not set
> CONFIG_STAGING=y
> # CONFIG_SURFACE_PLATFORMS is not set
> # CONFIG_IOMMU_SUPPORT is not set
> CONFIG_MEMORY=y
> CONFIG_PWM=y
> CONFIG_PWM_ATMEL_HLCDC_PWM=m
> CONFIG_GENERIC_PHY=y
> CONFIG_ISO9660_FS=m
> CONFIG_JOLIET=y
> CONFIG_UDF_FS=m
> CONFIG_MSDOS_FS=y
> CONFIG_VFAT_FS=y
> CONFIG_TMPFS=y
> # CONFIG_MISC_FILESYSTEMS is not set
> # CONFIG_NETWORK_FILESYSTEMS is not set
> CONFIG_NLS_CODEPAGE_437=y
> CONFIG_NLS_CODEPAGE_850=y
> CONFIG_NLS_ISO8859_1=y
> CONFIG_NLS_ISO8859_2=y
> CONFIG_NLS_UTF8=y
> CONFIG_KEYS=y
> CONFIG_LSM="lockdown,yama,loadpin,safesetid,integrity,bpf"
> CONFIG_CRYPTO_RSA=y
> CONFIG_CRYPTO_CCM=y
> CONFIG_CRYPTO_GCM=y
> CONFIG_CRYPTO_CMAC=y
> CONFIG_CRYPTO_SHA256=y
> CONFIG_CRYPTO_AES=y
> CONFIG_CRYPTO_DEFLATE=y
> CONFIG_CRYPTO_ZSTD=y
> CONFIG_ASYMMETRIC_KEY_TYPE=y
> CONFIG_ASYMMETRIC_PUBLIC_KEY_SUBTYPE=y
> CONFIG_X509_CERTIFICATE_PARSER=y
> CONFIG_PKCS7_MESSAGE_PARSER=y
> CONFIG_SYSTEM_TRUSTED_KEYRING=y
> CONFIG_CRC_CCITT=y
> CONFIG_CRC16=y
> CONFIG_LIBCRC32C=y
> CONFIG_DMA_API_DEBUG=y
> CONFIG_PRINTK_TIME=y
> CONFIG_DEBUG_INFO=y
> CONFIG_DEBUG_INFO_COMPRESSED=y
> CONFIG_MAGIC_SYSRQ=y
> CONFIG_DEBUG_FS=y
> # CONFIG_SCHED_DEBUG is not set
> # CONFIG_DEBUG_PREEMPT is not set
> CONFIG_PROVE_LOCKING=y
> CONFIG_PROVE_RAW_LOCK_NESTING=y
> CONFIG_DEBUG_LOCKDEP=y
> CONFIG_DEBUG_ATOMIC_SLEEP=y
> # CONFIG_FTRACE is not set
> CONFIG_BACKTRACE_VERBOSE=y
> CONFIG_DEBUG_USER=y
> CONFIG_DEBUG_LL=y
> CONFIG_DEBUG_LL_UART_8250=y
> CONFIG_DEBUG_UART_PHYS=0xb8000000
> CONFIG_DEBUG_UART_VIRT=0x0ff000000
> CONFIG_DEBUG_UART_8250_WORD=y
> CONFIG_EARLY_PRINTK=y

Powered by blists - more mailing lists