make tt fails a test about bus1

[dvdhrm]

Closing this, lets keep the discussion in #18. Don't re-use old bugs, it will just annoy the people involved in the old bug.

[EduRam]

Next time please open a new report :)
Ok!

Which bus1 commit are you testing
This is my latest version:

; [e@dock bus1]$ git log -1
; commit 4261b7a
; Merge: 9e961d3 94c0b0d
; Author: Tom Gundersen [email protected]
; Date: Tue Aug 23 02:44:07 2016 +0200

This is the begining of the error messages

;Aug 23 17:30:57 dock kernel: BUG: unable to handle kernel paging request at 00007ffefdb66e60
;Aug 23 17:30:57 dock kernel: IP: [] bus1_node_destroy_by_id+0x1c/0x180 [bus1]
;Aug 23 17:30:57 dock kernel: PGD 69f5d067 PUD 66927067 PMD 66944067 PTE 80000000673d3867
;Aug 23 17:30:57 dock kernel: Oops: 0001 [#1] SMP
;Aug 23 17:30:57 dock kernel: Modules linked in: bus1(OE) ip6t_REJECT nf_reject_ipv6 xt_conntrack ip6t_rpfilter ip_set nfnetlink ebtable_broute bridge stp llc ebtable_nat ip6table_nat nf_co
nntrack_ipv6 nf_defrag_ipv6 nf_nat_ipv6 ip6table_security ip6table_mangle ip6table_raw iptable_nat nf_conntrack_ipv4 nf_defrag_ipv4 nf_nat_ipv4 nf_nat nf_conntrack iptable_security iptable
_mangle iptable_raw ebtable_filter ebtables ip6table_filter ip6_tables vmw_vsock_vmci_transport vsock btusb btrtl btbcm coretemp btintel bluetooth crct10dif_pclmul crc32_pclmul ppdev rfkil
l ghash_clmulni_intel vmw_balloon vmw_vmci snd_ens1371 gameport snd_rawmidi snd_seq_device joydev snd_ac97_codec ac97_bus snd_pcm snd_timer snd soundcore i2c_piix4 shpchp nfit parport_pc p
arport acpi_cpufreq tpm_tis tpm nfsd auth_rpcgss nfs_acl lockd grace sunrpc
;Aug 23 17:30:57 dock kernel: xfs libcrc32c vmwgfx drm_kms_helper ttm crc32c_intel drm mptspi scsi_transport_spi mptscsih e1000 mptbase serio_raw ata_generic pata_acpi fjes
;Aug 23 17:30:57 dock kernel: CPU: 0 PID: 1260 Comm: bus1-test Tainted: G OE 4.6.6-300.fc24.x86_64 #1
;Aug 23 17:30:57 dock kernel: Hardware name: VMware, Inc. VMware Virtual Platform/440BX Desktop Reference Platform, BIOS 6.00 07/02/2015

[teg]

This is due to pinning all the destinations simultaneously (taking an active reference) during the transaction. Currently, we allow the same message to be sent more than once to the same destination, and our tests send a lot of messages to itself causing itself to be pinned repeatedly, which lockdep sees as taking the same lock many times.

@dvdhrm mentioned wanting to disallow duplicate messages being sent to the same destination, which would solve this particular problem. Though, we probably anyway want to remove any restriction on how many references can be taken (actually, maybe not, doing that is probably a sign that something very strange is going on).

[teg]

Should be fixed now. Thanks for the report!

EDIT: nope, not fixed. I could not reproduce on 4.4.0-rc6, but now I can on 4.5.0-0.rc0.git1.1.fc24, so my patch did not do the trick.

[dvdhrm]

The real issue is that we provide lockdep annotations for bus1_active. While it is very handy for basic testing, it really doesn't scale well. I guess the right solution is to make those annotations optional.

[dvdhrm]

I pushed a fix now: 7350487

Not sure whether it really fixes the issue. I'll run some tests tomorrow. No time to compile a debug kernel now.

[teg]

[ 119.374028] ------------[ cut here ]------------
[ 119.374039] WARNING: CPU: 2 PID: 3063 at kernel/locking/lockdep.c:3444 lock_release+0x2c2/0x610()
[ 119.374042] DEBUG_LOCKS_WARN_ON(curr->lockdep_depth != depth - 1)
[ 119.374044] Modules linked in:
[ 119.374046] bus2(OE) fuse ccm snd_hda_codec_hdmi intel_rapl iosf_mbi x86_pkg_temp_thermal coretemp kvm irqbypass bridge crct10dif_pclmul crc32_pclmul stp llc arc4 iTCO_wdt iTCO_vendor_support iwlmvm uvcvideo mac80211 videobuf2_vmalloc videobuf2_memops videobuf2_v4l2 joydev videobuf2_core videodev btusb iwlwifi btrtl cdc_acm media btbcm btintel bluetooth cfg80211 snd_hda_codec_realtek i2c_i801 snd_hda_codec_generic i915 rtsx_pci_ms memstick snd_hda_intel snd_hda_codec snd_hda_core wmi snd_hwdep snd_seq thinkpad_acpi i2c_algo_bit snd_seq_device snd_pcm rfkill drm_kms_helper drm snd_timer snd video soundcore mei_me tpm_tis shpchp lpc_ich mei tpm binfmt_misc btrfs xor raid6_pq rtsx_pci_sdmmc mmc_core crc32c_intel e1000e rtsx_pci serio_raw ptp pps_core fjes cdc_mbim cdc_ncm usbnet cdc_wdm mii
[ 119.374134] CPU: 2 PID: 3063 Comm: b1-test Tainted: G W OE 4.5.0-0.rc0.git1.1.fc24.x86_64 #1
[ 119.374136] Hardware name: LENOVO 20AL007NGE/20AL007NGE, BIOS GIET66WW (2.16 ) 12/02/2013
[ 119.374139] 0000000000000000 00000000cf949e7d ffff8801b07fbbf0 ffffffff81429b09
[ 119.374144] ffff8801b07fbc38 ffff8801b07fbc28 ffffffff810ae092 ffff8801f0acc000
[ 119.374149] 0000000000000001 0000000000000000 0000000000000006 ffff8800a6dd0358
[ 119.374154] Call Trace:
[ 119.374159] [] dump_stack+0x4b/0x72
[ 119.374163] [] warn_slowpath_common+0x82/0xc0
[ 119.374167] [] warn_slowpath_fmt+0x5c/0x80
[ 119.374171] [] lock_release+0x2c2/0x610
[ 119.374177] [] ? bus1_peer_acquire_by_id+0x1c5/0x300 [bus2]
[ 119.374182] [] bus1_peer_acquire_by_id+0x156/0x300 [bus2]
[ 119.374185] [] ? bus1_peer_acquire_by_id+0x35/0x300 [bus2]
[ 119.374190] [] bus1_transaction_instantiate_for_id+0x27/0x180 [bus2]
[ 119.374194] [] bus1_peer_ioctl+0x70c/0x1d50 [bus2]
[ 119.374198] [] ? bus1_peer_ioctl+0x7c0/0x1d50 [bus2]
[ 119.374203] [] ? sched_clock+0x9/0x10
[ 119.374208] [] ? local_clock+0x1c/0x20
[ 119.374212] [] bus1_fs_bus_fop_ioctl_native+0x2e/0x40 [bus2]
[ 119.374216] [] do_vfs_ioctl+0x2f1/0x550
[ 119.374220] [] ? __audit_syscall_entry+0xab/0xf0
[ 119.374225] [] ? debug_lockdep_rcu_enabled+0x1d/0x20
[ 119.374228] [] SyS_ioctl+0x79/0x90
[ 119.374232] [] entry_SYSCALL_64_fastpath+0x12/0x76
[ 119.374235] ---[ end trace c619183c506dc16b ]---

[teg]

This should now have been fixed.

[EduRam]

Hi! I was browsing the source code and run command "sudo make tt" to see it working.
The following error messages appeared on "/var/log/messages".
I am not sure if it is known Issue, or something wrong on my linux environment!!!

...
Aug 22 14:43:32 dock kernel: BUG: unable to handle kernel paging request at 00007ffc086ada80
Aug 22 14:43:32 dock kernel: IP: [] bus1_node_destroy_by_id+0x1c/0x180 [bus1]
...
Aug 22 14:43:32 dock kernel: Call Trace:
Aug 22 14:43:32 dock kernel: [] bus1_peer_ioctl+0x4bc/0x760 [bus1]
Aug 22 14:43:32 dock kernel: [] bus1_fop_ioctl+0x37/0x80 [bus1]
Aug 22 14:43:32 dock kernel: [] do_vfs_ioctl+0xa2/0x5d0
Aug 22 14:43:32 dock kernel: [] SyS_ioctl+0x79/0x90
Aug 22 14:43:32 dock kernel: [] entry_SYSCALL_64_fastpath+0x1a/0xa4
Aug 22 14:43:32 dock kernel: Code: bf fa ff ff ff e9 66 ff ff ff 0f 1f 44 00 00 0f 1f 44 00 00 55 48 89 e5 41 57 41 56 41 55 41 54 49 89 f7 53 49 89 d6 48 83 ec 08 <48> 8b 36 4c 8b 67 30 40 f6 c6 02 74 3c 48 f7 c6 f8 ff ff ff 75
Aug 22 14:43:32 dock kernel: RIP [] bus1_node_destroy_by_id+0x1c/0x180 [bus1]
...

This is my Linux kernel version:

[e@dock ~]$ uname -a
Linux dock 4.6.6-300.fc24.x86_64 #1 SMP Wed Aug 10 21:07:35 UTC 2016 x86_64 x86_64 x86_64 GNU/Linux

[teg]

Which bus1 commit are you testing (and could you try the most recent one?) ? Next time please open a new report :)

[teg]

How reproducible is this? 100%? Also after a reboot?

[EduRam]

Hi!

I can reproduce it every time.
I send as attachement, the output of my build command, and dmesg.
(just after rebooting the VM)

make.txt
dmesg.txt

Update:
One of the test process is in this strange state:

[EduRam]

Ok ... Sorry for the confunsion!