Re: [Intel-wired-lan] 6.10; regression; bisected - commit 86167183a17e cause info msg "trying to register non-static key"

[Sasha Neftin <sasha.neftin@intel.com>]

On 18/05/2024 0:05, Vinicius Costa Gomes wrote:
> Hi,
> 
> + intel-wired-lan
> 
> Mikhail Gavrilov <mikhail.v.gavrilov@gmail.com> writes:
Hello Corinna,

Any thought? Revert?

Thanks,
Sasha
> 
>> Hi,
>> I am here to test unstable kernels.
>> Yesterday at Fedora Rawhide arrived the new kernel
>> 20240515git1b294a1f3561 and I spotter in kernel log new "red" message
>> with follow stacktrace:
>> [    8.471610] nvme nvme1: pci function 0000:0e:00.0
>> [    8.471616] nvme nvme0: pci function 0000:04:00.0
>> [    8.492638] nvme nvme1: 32/0/0 default/read/poll queues
>> [    8.496190] nvme nvme0: 31/0/0 default/read/poll queues
>> [    8.507051]  nvme0n1: p1 p2 p3
>> [    8.522270] INFO: trying to register non-static key.
>> [    8.522273] The code is fine but needs lockdep annotation, or maybe
>> [    8.522274] you didn't initialize this object before use?
>> [    8.522275] turning off the locking correctness validator.
>> [    8.522276] CPU: 31 PID: 683 Comm: (udev-worker) Not tainted
>> 6.10.0-0.rc0.20240515git1b294a1f3561.4.fc41.x86_64+debug #1
>> [    8.522278] Hardware name: ASUS System Product Name/ROG STRIX
>> B650E-I GAMING WIFI, BIOS 2611 04/07/2024
>> [    8.522280] Call Trace:
>> [    8.522281]  <TASK>
>> [    8.522282]  dump_stack_lvl+0x84/0xd0
>> [    8.522287]  register_lock_class+0xd84/0x1000
>> [    8.522291]  ? __pfx_register_lock_class+0x10/0x10
>> [    8.522293]  __lock_acquire+0x3d2/0x5c70
>> [    8.522295]  ? debug_object_free+0x298/0x550
>> [    8.522297]  ? __pfx_debug_object_free+0x10/0x10
>> [    8.522299]  ? __pfx_lock_release+0x10/0x10
>> [    8.522301]  ? __pfx___lock_acquire+0x10/0x10
>> [    8.522302]  ? hrtimer_try_to_cancel+0x22/0x460
>> [    8.522305]  lock_acquire+0x1ae/0x540
>> [    8.522307]  ? igc_ptp_clear_tx_tstamp+0x38/0x1b0 [igc]
>> [    8.522321]  ? __pfx_lock_acquire+0x10/0x10
>> [    8.522323]  ? seqcount_lockdep_reader_access.constprop.0+0xa5/0xb0
>> [    8.522325]  ? lockdep_hardirqs_on+0x7c/0x100
>> [    8.522326]  ? seqcount_lockdep_reader_access.constprop.0+0xa5/0xb0
>> [    8.522329]  _raw_spin_lock_irqsave+0x51/0xa0
>> [    8.522330]  ? igc_ptp_clear_tx_tstamp+0x38/0x1b0 [igc]
>> [    8.522337]  igc_ptp_clear_tx_tstamp+0x38/0x1b0 [igc]
>> [    8.522344]  igc_ptp_set_timestamp_mode+0x3cc/0x700 [igc]
>> [    8.522350]  ? igc_power_down_phy_copper+0xf1/0x140 [igc]
>> [    8.522358]  igc_ptp_reset+0x3b/0x5e0 [igc]
>> [    8.530693]  ? igc_set_eee_i225+0xfd/0x1e0 [igc]
>> [    8.530706]  igc_reset+0x2d9/0x3d0 [igc]
>> [    8.531707]  igc_probe+0x14ca/0x1e20 [igc]
>> [    8.531715]  ? _raw_spin_unlock_irqrestore+0x4f/0x80
>> [    8.531717]  ? __pfx_igc_probe+0x10/0x10 [igc]
>> [    8.531723]  local_pci_probe+0xdc/0x180
>> [    8.531727]  pci_device_probe+0x23c/0x810
>> [    8.531729]  ? kernfs_add_one+0x3ab/0x4a0
>> [    8.534068]  ? kernfs_new_node+0x13d/0x240
>> [    8.534070]  ? __pfx_pci_device_probe+0x10/0x10
>> [    8.534072]  ? kernfs_create_link+0x16e/0x240
>> [    8.534074]  ? kernfs_put+0x1c/0x40
>> [    8.534076]  ? sysfs_do_create_link_sd+0x8e/0x100
>> [    8.534078]  really_probe+0x1e0/0x8a0
>> [    8.536433]  __driver_probe_device+0x18c/0x370
>> [    8.536436]  driver_probe_device+0x4a/0x120
>> [    8.536438]  __driver_attach+0x194/0x4a0
>> [    8.536439]  ? __pfx___driver_attach+0x10/0x10
>> [    8.536441]  bus_for_each_dev+0x106/0x190
>> [    8.536443]  ? __pfx_bus_for_each_dev+0x10/0x10
>> [    8.536445]  bus_add_driver+0x2ff/0x530
>> [    8.536448]  driver_register+0x1a5/0x360
>> [    8.536449]  ? __pfx_igc_init_module+0x10/0x10 [igc]
>> [    8.536456]  do_one_initcall+0xd6/0x460
>> [    8.536459]  ? __pfx_do_one_initcall+0x10/0x10
>> [    8.536461]  ? kasan_unpoison+0x44/0x70
>> [    8.536464]  do_init_module+0x296/0x7c0
>> [    8.536466]  load_module+0x567b/0x74f0
>> [    8.536470]  ? __pfx_load_module+0x10/0x10
>> [    8.536473]  ? __might_fault+0x9d/0x120
>> [    8.536475]  ? local_clock_noinstr+0xd/0x100
>> [    8.536478]  ? __pfx___might_resched+0x10/0x10
>> [    8.536481]  ? __do_sys_init_module+0x1ef/0x220
>> [    8.536482]  __do_sys_init_module+0x1ef/0x220
>> [    8.536483]  ? __pfx___do_sys_init_module+0x10/0x10
>> [    8.536487]  do_syscall_64+0x97/0x190
>> [    8.536490]  ? lockdep_hardirqs_on_prepare+0x171/0x400
>> [    8.536492]  entry_SYSCALL_64_after_hwframe+0x76/0x7e
>> [    8.536494] RIP: 0033:0x7f29997265ae
>> [    8.536499] Code: 48 8b 0d 85 a8 0c 00 f7 d8 64 89 01 48 83 c8 ff
>> c3 66 2e 0f 1f 84 00 00 00 00 00 90 f3 0f 1e fa 49 89 ca b8 af 00 00
>> 00 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d 52 a8 0c 00 f7 d8 64 89
>> 01 48
> 
> It seems I have missed this following flow (in reverse):
> 
> + igc_ptp_clear_tx_tstamp
>    + igc_ptp_disable_tx_timestamp
>      + igc_ptp_set_timestamp_mode
>        + igc_ptp_reset
>          + igc_reset
>            + igc_probe
> 
> And that in igc_ptp_clear_tx_tstamp(), it uses ->ptp_tx_lock. So
> igc_ptp_init() needs to be called before igc_reset().
> 
> I think that is what this splat is telling us.
> 
> Don't know what's the best way forward, reverting the commit in question
> or trying to fix the initial problem some other way?
> 
>> [    8.536500] RSP: 002b:00007ffee505bff8 EFLAGS: 00000246 ORIG_RAX:
>> 00000000000000af
>> [    8.536502] RAX: ffffffffffffffda RBX: 000055eafe4a2ac0 RCX: 00007f29997265ae
>> [    8.536503] RDX: 00007f2998e6007d RSI: 00000000001067d6 RDI: 00007f299828c010
>> [    8.536504] RBP: 00007ffee505c0b0 R08: 000055eafe43a010 R09: 0000000000000007
>> [    8.536505] R10: 0000000000000007 R11: 0000000000000246 R12: 00007f2998e6007d
>> [    8.536506] R13: 0000000000020000 R14: 000055eafe476280 R15: 000055eafe4a25a0
>> [    8.536508]  </TASK>
>> [    8.542741] pps pps0: new PPS source ptp0
>> [    8.550932] igc 0000:0a:00.0 eth0: PHC added
>> [    8.550992] igc 0000:0a:00.0: 4.000 Gb/s available PCIe bandwidth
>> (5.0 GT/s PCIe x1 link)
>> [    8.550996] igc 0000:0a:00.0 eth0: MAC: e8:9c:25:6c:40:75
>> [    8.558160] igc 0000:0a:00.0 eno1: renamed from eth0
>>
>> Of course, I immediately wanted to find the first bad commit.
>> And now it has already been found:
>> 86167183a17e03ec77198897975e9fdfbd53cb0b is the first bad commit
>> commit 86167183a17e03ec77198897975e9fdfbd53cb0b (HEAD)
>> Author: Corinna Vinschen <vinschen@redhat.com>
>> Date:   Tue Apr 23 12:24:54 2024 +0200
>>
>>      igc: fix a log entry using uninitialized netdev
>>
>>      During successful probe, igc logs this:
>>
>>      [    5.133667] igc 0000:01:00.0 (unnamed net_device)
>> (uninitialized): PHC added
>>                                      ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
>>      The reason is that igc_ptp_init() is called very early, even before
>>      register_netdev() has been called. So the netdev_info() call works
>>      on a partially uninitialized netdev.
>>
>>      Fix this by calling igc_ptp_init() after register_netdev(), right
>>      after the media autosense check, just as in igb.  Add a comment,
>>      just as in igb.
>>
>>      Now the log message is fine:
>>
>>      [    5.200987] igc 0000:01:00.0 eth0: PHC added
>>
>>      Signed-off-by: Corinna Vinschen <vinschen@redhat.com>
>>      Reviewed-by: Hariprasad Kelam <hkelam@marvell.com>
>>      Acked-by: Vinicius Costa Gomes <vinicius.gomes@intel.com>
>>      Tested-by: Naama Meir <naamax.meir@linux.intel.com>
>>      Signed-off-by: Tony Nguyen <anthony.l.nguyen@intel.com>
>>
>>   drivers/net/ethernet/intel/igc/igc_main.c | 5 +++--
>>   1 file changed, 3 insertions(+), 2 deletions(-)
>>
>> The next step I was convinced that reverting the commit 86167183a17e
>> removed this info message.
> 
> Thank you for the effort.
> 
>>
>> I also attach here a full kernel log and build config.
>>
>> My hardware specs: https://linux-hardware.org/?probe=98ecbf3636
>>
>> I hope it helps.
>>
>> -- 
>> Best Regards,
>> Mike Gavrilov.
> 
> 
> Cheers,