Re: [linus:master] [of] 74df14cd30: WARNING:at_lib/refcount.c:#refcount_warn_saturate

From: Oliver Sang
Date: Thu Aug 24 2023 - 22:48:13 EST

Next message: Reka Norman: "[PATCH v2 0/9] media: cros-ec-cec: Add support for multiple ports"
Previous message: Google: "Re: [PATCH v3 1/1] tracing/kprobes: Return EADDRNOTAVAIL when func matches several symbols"
In reply to: Rob Herring: "Re: [linus:master] [of] 74df14cd30: WARNING:at_lib/refcount.c:#refcount_warn_saturate"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]

hi, Rob Herring,

On Thu, Aug 24, 2023 at 07:59:17AM -0500, Rob Herring wrote:
> On Thu, Aug 24, 2023 at 3:42 AM kernel test robot <oliver.sang@xxxxxxxxx> wrote:
> >
> >
> >
> > Hello,
> >
> > kernel test robot noticed "WARNING:at_lib/refcount.c:#refcount_warn_saturate" on:
> >
> > commit: 74df14cd301a1433947077e79ce2c610654a32e7 ("of: unittest: add node lifecycle tests")
>
> Perhaps that is the unittest which has a test to generate the WARN?
> Not enough context from the log. It should be preceded by EXPECT
> statements.

we supplied full dmesg as:
> > The kernel config and materials to reproduce are available at:
> > https://download.01.org/0day-ci/archive/20230824/202308241628.feb8dbbf-oliver.sang@xxxxxxxxx

from dmesg, before WARNING:
[ 70.409388][ T1] ### dt-test ### pass of_unittest_platform_populate():1264
[ 70.411108][ T1] ### dt-test ### EXPECT \ : platform testcase-data:testcase-device2: error -ENXIO: IRQ index 0 not found
[ 70.411126][ T1] platform testcase-data:testcase-device2: error -ENXIO: IRQ index 0 not found
[ 70.415857][ T1] ### dt-test ### EXPECT / : platform testcase-data:testcase-device2: error -ENXIO: IRQ index 0 not found
[ 70.415863][ T1] ### dt-test ### pass of_unittest_platform_populate():1275
[ 70.420244][ T1] ### dt-test ### pass of_unittest_platform_populate():1279
[ 70.422692][ T1] ### dt-test ### pass of_unittest_platform_populate():1285
[ 70.428237][ T1] ### dt-test ### pass of_unittest_platform_populate():1307
[ 70.430049][ T1] ### dt-test ### pass of_unittest_platform_populate():1307
[ 70.432540][ T1] ### dt-test ### pass of_unittest_platform_populate():1317
[ 70.434467][ T1] ### dt-test ### pass of_unittest_platform_populate():1317
[ 70.436416][ T1] ### dt-test ### pass of_unittest_lifecycle():3032
[ 70.438044][ T1] ### dt-test ### EXPECT \ : OF: ERROR: of_node_release() detected bad of_node_put() on /testcase-data/refcount-node
[ 70.438049][ T1] ### dt-test ### pass of_unittest_lifecycle():3057
[ 70.442557][ T1] ------------[ cut here ]------------
[ 70.443874][ T1] refcount_t: addition on 0; use-after-free.
[ 70.445250][ T1] WARNING: CPU: 1 PID: 1 at lib/refcount.c:25 refcount_warn_saturate+0x7a/0xd9

later:
[ 70.593100][ T1] ---[ end trace 0000000000000000 ]---
[ 70.685082][ T1] ### dt-test ### EXPECT / : OF: ERROR: of_node_release() detected bad of_node_put() on /testcase-data/refcount-node
[ 70.685088][ T1] ### dt-test ### EXPECT \ : ------------[ cut here ]------------
[ 70.687788][ T1] ### dt-test ### EXPECT \ : WARNING: <<all>>
[ 70.689644][ T1] ### dt-test ### EXPECT \ : refcount_t: underflow; use-after-free.
[ 70.691083][ T1] ### dt-test ### EXPECT \ : ---[ end trace <<int>> ]---
[ 70.693049][ T1] ### dt-test ### pass of_unittest_lifecycle():3077
[ 70.696236][ T1] ### dt-test ### EXPECT / : ---[ end trace <<int>> ]---
[ 70.696241][ T1] ### dt-test ### EXPECT / : refcount_t: underflow; use-after-free.
[ 70.697816][ T1] ### dt-test ### EXPECT / : WARNING: <<all>>
[ 70.699801][ T1] ### dt-test ### EXPECT / : ------------[ cut here ]------------
[ 70.701315][ T1] ### dt-test ### EXPECT_NOT \ : ------------[ cut here ]------------
[ 70.703176][ T1] ### dt-test ### EXPECT_NOT \ : WARNING: <<all>>
[ 70.705142][ T1] ### dt-test ### EXPECT_NOT \ : refcount_t: underflow; use-after-free.
[ 70.706679][ T1] ### dt-test ### EXPECT_NOT \ : ---[ end trace <<int>> ]---
[ 70.708730][ T1] ### dt-test ### pass of_unittest_lifecycle():3094
[ 70.712030][ T1] ### dt-test ### EXPECT_NOT / : ---[ end trace <<int>> ]---
[ 70.712035][ T1] ### dt-test ### EXPECT_NOT / : refcount_t: underflow; use-after-free.
[ 70.713786][ T1] ### dt-test ### EXPECT_NOT / : WARNING: <<all>>
[ 70.715744][ T1] ### dt-test ### EXPECT_NOT / : ------------[ cut here ]------------
[ 70.717285][ T1] ### dt-test ### pass of_unittest_lifecycle():3120
[ 70.720780][ T1] ### dt-test ### pass of_unittest_lifecycle():3121
[ 70.722425][ T1] ### dt-test ### pass of_unittest_check_tree_linkage():270
[ 70.724083][ T1] ### dt-test ### pass of_unittest_check_tree_linkage():273
[ 70.725918][ T1] ### dt-test ### end of unittest - 221 passed, 0 failed

not sure if they are helpful?

>
> > https://git.kernel.org/cgit/linux/kernel/git/torvalds/linux.git master
> >
> > [test failed on linux-next/master e3f80d3eae76c3557b3c9b5938ad01c0e6cf25ec]
> >
> > in testcase: boot
> >
> > compiler: gcc-7
> > test machine: qemu-system-i386 -enable-kvm -cpu SandyBridge -smp 2 -m 4G
> >
> > (please refer to attached dmesg/kmsg for entire log/backtrace)
> >
> >
> >
> > If you fix the issue in a separate patch/commit (i.e. not just a new version of
> > the same patch/commit), kindly add following tags
> > | Reported-by: kernel test robot <oliver.sang@xxxxxxxxx>
> > | Closes: https://lore.kernel.org/oe-lkp/202308241628.feb8dbbf-oliver.sang@xxxxxxxxx
> >
> >
> > [ 70.442557][ T1] ------------[ cut here ]------------
> > [ 70.443874][ T1] refcount_t: addition on 0; use-after-free.
> > [ 70.445250][ T1] WARNING: CPU: 1 PID: 1 at lib/refcount.c:25 refcount_warn_saturate (lib/refcount.c:25 (discriminator 3))
> > [ 70.447754][ T1] Modules linked in:
> > [ 70.448750][ T1] CPU: 1 PID: 1 Comm: swapper/0 Tainted: G TN 6.2.0-rc1-00057-g74df14cd301a #1 fcca16d7341229f468256f53411c1bbb3612d6fc
> > [ 70.451836][ T1] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.16.2-debian-1.16.2-1 04/01/2014
> > [ 70.454292][ T1] EIP: refcount_warn_saturate (lib/refcount.c:25 (discriminator 3))
> > [ 70.455655][ T1] Code: c6 05 3e 40 ed c3 01 e8 5d 62 97 ff 0f 0b eb 76 80 3d 3d 40 ed c3 00 75 6e 68 f0 5a 54 c3 c6 05 3d 40 ed c3 01 e8 3f 62 97 ff <0f> 0b eb 58 80 3d 3c 40 ed c3 00 75 50 68 1c 5b 54 c3 c6 05 3c 40
> > All code
> > ========
> > 0: c6 05 3e 40 ed c3 01 movb $0x1,-0x3c12bfc2(%rip) # 0xffffffffc3ed4045
> > 7: e8 5d 62 97 ff callq 0xffffffffff976269
> > c: 0f 0b ud2
> > e: eb 76 jmp 0x86
> > 10: 80 3d 3d 40 ed c3 00 cmpb $0x0,-0x3c12bfc3(%rip) # 0xffffffffc3ed4054
> > 17: 75 6e jne 0x87
> > 19: 68 f0 5a 54 c3 pushq $0xffffffffc3545af0
> > 1e: c6 05 3d 40 ed c3 01 movb $0x1,-0x3c12bfc3(%rip) # 0xffffffffc3ed4062
> > 25: e8 3f 62 97 ff callq 0xffffffffff976269
> > 2a:* 0f 0b ud2 <-- trapping instruction
> > 2c: eb 58 jmp 0x86
> > 2e: 80 3d 3c 40 ed c3 00 cmpb $0x0,-0x3c12bfc4(%rip) # 0xffffffffc3ed4071
> > 35: 75 50 jne 0x87
> > 37: 68 1c 5b 54 c3 pushq $0xffffffffc3545b1c
> > 3c: c6 .byte 0xc6
> > 3d: 05 .byte 0x5
> > 3e: 3c 40 cmp $0x40,%al
> >
> > Code starting with the faulting instruction
> > ===========================================
> > 0: 0f 0b ud2
> > 2: eb 58 jmp 0x5c
> > 4: 80 3d 3c 40 ed c3 00 cmpb $0x0,-0x3c12bfc4(%rip) # 0xffffffffc3ed4047
> > b: 75 50 jne 0x5d
> > d: 68 1c 5b 54 c3 pushq $0xffffffffc3545b1c
> > 12: c6 .byte 0xc6
> > 13: 05 .byte 0x5
> > 14: 3c 40 cmp $0x40,%al
> > [ 70.460090][ T1] EAX: 0000002a EBX: edf25dfc ECX: 00000000 EDX: 00000001
> > [ 70.461715][ T1] ESI: ffffffff EDI: edf20140 EBP: c5803c98 ESP: c5803c94
> > [ 70.463395][ T1] DS: 007b ES: 007b FS: 00d8 GS: 0000 SS: 0068 EFLAGS: 00010082
> > [ 70.465280][ T1] CR0: 80050033 CR2: 00000000 CR3: 04312000 CR4: 000406f0
> > [ 70.466949][ T1] DR0: 00000000 DR1: 00000000 DR2: 00000000 DR3: 00000000
> > [ 70.468627][ T1] DR6: fffe0ff0 DR7: 00000400
> > [ 70.469791][ T1] Call Trace:
> > [ 70.470624][ T1] kobject_get (lib/kobject.c:630)
> > [ 70.471657][ T1] of_node_get (drivers/of/dynamic.c:37)
> > [ 70.472723][ T1] of_fwnode_get (drivers/of/property.c:866 (discriminator 4))
> > [ 70.473833][ T1] fwnode_handle_get (drivers/base/property.c:822)
> > [ 70.475019][ T1] fwnode_get_nth_parent (drivers/base/property.c:686)
> > [ 70.476273][ T1] fwnode_full_name_string (lib/vsprintf.c:2091 (discriminator 3))
> > [ 70.477560][ T1] device_node_string (lib/vsprintf.c:2143)
> > [ 70.478752][ T1] ? sched_clock_cpu (kernel/sched/clock.c:364)
> > [ 70.479932][ T1] ? __lock_acquire (kernel/locking/lockdep.c:3746 kernel/locking/lockdep.c:3799 kernel/locking/lockdep.c:5055)
> > [ 70.481114][ T1] pointer (lib/vsprintf.c:2452)
> > [ 70.482112][ T1] vsnprintf (lib/vsprintf.c:2800)
> > [ 70.483212][ T1] vprintk_store (kernel/printk/printk.c:2241)
> > [ 70.484369][ T1] ? kvm_sched_clock_read (arch/x86/kernel/kvmclock.c:91)
> > [ 70.485663][ T1] ? sched_clock (arch/x86/kernel/tsc.c:254)
> > [ 70.486742][ T1] vprintk_emit (kernel/printk/printk.c:2338)
> > [ 70.487814][ T1] vprintk_default (kernel/printk/printk.c:2369)
> > [ 70.488983][ T1] vprintk (kernel/printk/printk_safe.c:51)
> > [ 70.489980][ T1] _printk (kernel/printk/printk.c:2382)
> > [ 70.490957][ T1] of_node_release (drivers/of/dynamic.c:343)
> > [ 70.492067][ T1] kobject_release (lib/kobject.c:677 lib/kobject.c:704)
> > [ 70.493179][ T1] kobject_put (include/linux/kref.h:65 lib/kobject.c:721)
> > [ 70.494272][ T1] of_node_put (drivers/of/dynamic.c:49)
> > [ 70.495302][ T1] of_unittest (drivers/of/unittest.c:3060 drivers/of/unittest.c:3650)
> > [ 70.496497][ T1] ? of_unittest_changeset (drivers/of/unittest.c:3605)
> > [ 70.497818][ T1] do_one_initcall (init/main.c:1306)
> > [ 70.498945][ T1] ? rcu_read_lock_sched_held (kernel/rcu/update.c:125)
> > [ 70.500257][ T1] ? trace_initcall_level (include/trace/events/initcall.h:10)
> > [ 70.501552][ T1] ? kernel_init_freeable (init/main.c:1378 init/main.c:1395 init/main.c:1414 init/main.c:1634)
> > [ 70.502817][ T1] kernel_init_freeable (init/main.c:1378 init/main.c:1395 init/main.c:1414 init/main.c:1634)
> > [ 70.504101][ T1] ? rest_init (init/main.c:1514)
> > [ 70.505225][ T1] kernel_init (init/main.c:1524)
> > [ 70.506294][ T1] ret_from_fork (arch/x86/entry/entry_32.S:770)
> > [ 70.507381][ T1] irq event stamp: 2968680
> > [ 70.508481][ T1] hardirqs last enabled at (2968679): kmem_cache_free (arch/x86/include/asm/irqflags.h:29 arch/x86/include/asm/irqflags.h:70 arch/x86/include/asm/irqflags.h:130 mm/slab.c:3581 mm/slab.c:3605)
> > [ 70.510605][ T1] hardirqs last disabled at (2968680): vprintk_store (arch/x86/include/asm/preempt.h:27 (discriminator 3) kernel/printk/printk.c:2061 (discriminator 3) kernel/printk/printk.c:2221 (discriminator 3))
> > [ 70.512664][ T1] softirqs last enabled at (2968660): __do_softirq (arch/x86/include/asm/preempt.h:27 kernel/softirq.c:415 kernel/softirq.c:600)
> > [ 70.514774][ T1] softirqs last disabled at (2968651): do_softirq_own_stack (arch/x86/kernel/irq_32.c:57 arch/x86/kernel/irq_32.c:147)
> > [ 70.516984][ T1] ---[ end trace 0000000000000000 ]---
> >
> >
> > The kernel config and materials to reproduce are available at:
> > https://download.01.org/0day-ci/archive/20230824/202308241628.feb8dbbf-oliver.sang@xxxxxxxxx
> >
> >
> >
> > --
> > 0-DAY CI Kernel Test Service
> > https://github.com/intel/lkp-tests/wiki
> >
>

Next message: Reka Norman: "[PATCH v2 0/9] media: cros-ec-cec: Add support for multiple ports"
Previous message: Google: "Re: [PATCH v3 1/1] tracing/kprobes: Return EADDRNOTAVAIL when func matches several symbols"
In reply to: Rob Herring: "Re: [linus:master] [of] 74df14cd30: WARNING:at_lib/refcount.c:#refcount_warn_saturate"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]