Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Loading the kernel module floods journalctl with call traces #257

Closed
MikkoMMM opened this issue Feb 21, 2020 · 6 comments
Closed

Loading the kernel module floods journalctl with call traces #257

MikkoMMM opened this issue Feb 21, 2020 · 6 comments

Comments

@MikkoMMM
Copy link

These are the commands I do to get this to happen:

git pull origin master
make clean && make && sudo make install
sudo depmod -a
sudo modprobe v4l2loopback video_nr=8,9 card_label="DSLR direct","OBS Cam" exclusive_caps=1,1,1,1,1,1,1,1

Then journalctl -b first shows the list of kernel modules and something like these lines twice:

Feb 21 14:04:11 localhost kernel: CPU: 4 PID: 9082 Comm: v4l_id Tainted: P           OE     5.5.4-arch1-1 #1
Feb 21 14:04:11 localhost kernel:  jbd2 hid_generic usbhid
Feb 21 14:04:11 localhost kernel: Hardware name: System manufacturer System Product Name/TUF Z390-PLUS GAMING, BIOS 0805 09/21/2018
Feb 21 14:04:11 localhost kernel:  hid uas usb_storage
Feb 21 14:04:11 localhost kernel: RIP: 0010:v4l_querycap+0x82/0xa0 [videodev]
Feb 21 14:04:11 localhost kernel:  sr_mod cdrom sd_mod ahci
Feb 21 14:04:11 localhost kernel: Code: 8b 73 54 81 ca 00 00 00 80 48 b9 00 00 20 00 00 00 20 00 48 0b 4b 54 21 d6 39 f2 75 11 48 89 4b 54 5b 5d 41 5c 41 5d 41 5e c3 <0f> 0b eb d2 0f 0b 48 89 4b 54 5b 5d 41 5c 41 5d 41 5e c3 66 66 2e
Feb 21 14:04:11 localhost kernel:  libahci libata xhci_pci
Feb 21 14:04:11 localhost kernel: RSP: 0018:ffff9f1a84373cb8 EFLAGS: 00010297
Feb 21 14:04:11 localhost kernel:  xhci_hcd crc32c_intel
Feb 21 14:04:11 localhost kernel:  scsi_mod vfio_pci irqbypass
Feb 21 14:04:11 localhost kernel: RAX: 0000000000000000 RBX: ffff9f1a84373db0 RCX: 0000000000000001
Feb 21 14:04:11 localhost kernel:  vfio_virqfd vfio_iommu_type1 vfio
Feb 21 14:04:11 localhost kernel: RDX: 0000000085008003 RSI: 0000000000000000 RDI: 0000000000000000
Feb 21 14:04:11 localhost kernel: RBP: ffff963b2e990000 R08: ffff9f1a84373df9 R09: 0000000000000000
Feb 21 14:04:11 localhost kernel: CPU: 2 PID: 9083 Comm: v4l_id Tainted: P           OE     5.5.4-arch1-1 #1
Feb 21 14:04:11 localhost kernel: Hardware name: System manufacturer System Product Name/TUF Z390-PLUS GAMING, BIOS 0805 09/21/2018
Feb 21 14:04:11 localhost kernel: R10: ffff963b2fd6a440 R11: ffff9f1a84373df9 R12: ffff963b2e1dad00
Feb 21 14:04:11 localhost kernel: R13: ffff963b2fd6a440 R14: ffffffffc275b340 R15: 0000000000000000
Feb 21 14:04:11 localhost kernel: RIP: 0010:v4l_querycap+0x82/0xa0 [videodev]
Feb 21 14:04:11 localhost kernel: Code: 8b 73 54 81 ca 00 00 00 80 48 b9 00 00 20 00 00 00 20 00 48 0b 4b 54 21 d6 39 f2 75 11 48 89 4b 54 5b 5d 41 5c 41 5d 41 5e c3 <0f> 0b eb d2 0f 0b 48 89 4b 54 5b 5d 41 5c 41 5d 41 5e c3 66 66 2e
Feb 21 14:04:11 localhost kernel: FS:  00007fea2711b840(0000) GS:ffff963c5dd00000(0000) knlGS:0000000000000000
Feb 21 14:04:11 localhost kernel: RSP: 0018:ffff9f1a8677bcb8 EFLAGS: 00010297
Feb 21 14:04:11 localhost kernel: CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
Feb 21 14:04:11 localhost kernel: RAX: 0000000000000000 RBX: ffff9f1a8677bdb0 RCX: 0000000000000001
Feb 21 14:04:11 localhost kernel: RDX: 0000000085008003 RSI: 0000000000000000 RDI: 0000000000000000
Feb 21 14:04:11 localhost kernel: CR2: 00007fea27f97068 CR3: 000000033083e004 CR4: 00000000003606e0
Feb 21 14:04:11 localhost kernel: RBP: ffff963b2e994000 R08: ffff9f1a8677bdf9 R09: 0000000000000000
Feb 21 14:04:11 localhost kernel: DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
Feb 21 14:04:11 localhost kernel: DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
Feb 21 14:04:11 localhost kernel: R10: ffff963b7c0de6c0 R11: ffff9f1a8677bdf9 R12: ffff963c571e5500
Feb 21 14:04:11 localhost kernel: R13: ffff963b7c0de6c0 R14: ffffffffc275b340 R15: 0000000000000000
Feb 21 14:04:11 localhost kernel: Call Trace:
Feb 21 14:04:11 localhost kernel: FS:  00007fd2d4e5f840(0000) GS:ffff963c5dc80000(0000) knlGS:0000000000000000
Feb 21 14:04:11 localhost kernel: CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
Feb 21 14:04:11 localhost kernel: CR2: 00007fd2d5cdb068 CR3: 00000003a57c0004 CR4: 00000000003606e0
Feb 21 14:04:11 localhost kernel: DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
Feb 21 14:04:11 localhost kernel: DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
Feb 21 14:04:11 localhost kernel: Call Trace:
Feb 21 14:04:11 localhost kernel:  __video_do_ioctl+0x1c6/0x410 [videodev]
Feb 21 14:04:11 localhost kernel:  __video_do_ioctl+0x1c6/0x410 [videodev]
Feb 21 14:04:11 localhost kernel:  ? v4l_s_fmt+0x5d0/0x5d0 [videodev]
Feb 21 14:04:11 localhost kernel:  ? v4l_s_fmt+0x5d0/0x5d0 [videodev]
Feb 21 14:04:11 localhost kernel:  video_usercopy+0x2a0/0x620 [videodev]
Feb 21 14:04:11 localhost kernel:  video_usercopy+0x2a0/0x620 [videodev]
Feb 21 14:04:11 localhost kernel:  v4l2_ioctl+0x48/0x50 [videodev]
Feb 21 14:04:11 localhost kernel:  v4l2_ioctl+0x48/0x50 [videodev]
Feb 21 14:04:11 localhost kernel:  do_vfs_ioctl+0x4b7/0x730
Feb 21 14:04:11 localhost kernel:  do_vfs_ioctl+0x4b7/0x730
Feb 21 14:04:11 localhost kernel:  ? syscall_trace_enter+0x19c/0x2e0
Feb 21 14:04:11 localhost kernel:  ? syscall_trace_enter+0x19c/0x2e0
Feb 21 14:04:11 localhost kernel:  ksys_ioctl+0x5e/0x90
Feb 21 14:04:11 localhost kernel:  ksys_ioctl+0x5e/0x90
Feb 21 14:04:11 localhost kernel:  __x64_sys_ioctl+0x16/0x20
Feb 21 14:04:11 localhost kernel:  __x64_sys_ioctl+0x16/0x20
Feb 21 14:04:11 localhost kernel:  do_syscall_64+0x4e/0x150
Feb 21 14:04:11 localhost kernel:  do_syscall_64+0x4e/0x150
Feb 21 14:04:11 localhost kernel:  entry_SYSCALL_64_after_hwframe+0x44/0xa9
Feb 21 14:04:11 localhost kernel:  entry_SYSCALL_64_after_hwframe+0x44/0xa9
Feb 21 14:04:11 localhost kernel: RIP: 0033:0x7fd2d5c0c2eb
Feb 21 14:04:11 localhost kernel: RIP: 0033:0x7fea27ec82eb
Feb 21 14:04:11 localhost kernel: Code: 0f 1e fa 48 8b 05 a5 8b 0c 00 64 c7 00 26 00 00 00 48 c7 c0 ff ff ff ff c3 66 0f 1f 44 00 00 f3 0f 1e fa b8 10 00 00 00 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d 75 8b 0c 00 f7 d8 64 89 01 48
Feb 21 14:04:11 localhost kernel: Code: 0f 1e fa 48 8b 05 a5 8b 0c 00 64 c7 00 26 00 00 00 48 c7 c0 ff ff ff ff c3 66 0f 1f 44 00 00 f3 0f 1e fa b8 10 00 00 00 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d 75 8b 0c 00 f7 d8 64 89 01 48
Feb 21 14:04:11 localhost kernel: RSP: 002b:00007ffc6c758958 EFLAGS: 00000246
Feb 21 14:04:11 localhost kernel: RSP: 002b:00007ffe65465878 EFLAGS: 00000246
Feb 21 14:04:11 localhost kernel:  ORIG_RAX: 0000000000000010
Feb 21 14:04:11 localhost kernel: RAX: ffffffffffffffda RBX: 00007ffc6c758ad8 RCX: 00007fd2d5c0c2eb
Feb 21 14:04:11 localhost kernel:  ORIG_RAX: 0000000000000010
Feb 21 14:04:11 localhost kernel: RAX: ffffffffffffffda RBX: 00007ffe654659f8 RCX: 00007fea27ec82eb
Feb 21 14:04:11 localhost kernel: RDX: 00007ffc6c758960 RSI: 0000000080685600 RDI: 0000000000000003
Feb 21 14:04:11 localhost kernel: RDX: 00007ffe65465880 RSI: 0000000080685600 RDI: 0000000000000003
Feb 21 14:04:11 localhost kernel: RBP: 0000000000000003 R08: 0000000000000000 R09: 0000000000000000
Feb 21 14:04:11 localhost kernel: RBP: 0000000000000003 R08: 0000000000000000 R09: 0000000000000000
Feb 21 14:04:11 localhost kernel: R10: 0000000000000000 R11: 0000000000000246 R12: 0000555db59ed260
Feb 21 14:04:11 localhost kernel: R10: 0000000000000000 R11: 0000000000000246 R12: 0000558e8b687260
Feb 21 14:04:11 localhost kernel: R13: 00007ffc6c758ad0 R14: 0000000000000000 R15: 0000000000000000
Feb 21 14:04:11 localhost kernel: R13: 00007ffe654659f0 R14: 0000000000000000 R15: 0000000000000000
Feb 21 14:04:11 localhost kernel: ---[ end trace a9eadff44cf9eb4e ]---
Feb 21 14:04:11 localhost kernel: ---[ end trace a9eadff44cf9eb4f ]---

After that, it starts repeating these lines around four times a second:

Feb 21 14:04:11 localhost kernel: ------------[ cut here ]------------
Feb 21 14:04:11 localhost kernel: WARNING: CPU: 3 PID: 3709 at drivers/media/v4l2-core/v4l2-ioctl.c:1079 v4l_querycap+0x86/0xa0 [videodev]
Feb 21 14:04:11 localhost kernel: Modules linked in: v4l2loopback(OE) nvidia_uvm(OE) fuse xt_MASQUERADE nf_conntrack_netlink nfnetlink xfrm_user xfrm_algo xt_addrtype iptable_nat nf_nat br_netfilter bridge cfg80211 xt_owner 8021q ipt_REJECT nf_reject_i>
Feb 21 14:04:11 localhost kernel:  snd_pcm_dmaengine snd_hda_codec_generic aesni_intel ledtrig_audio crypto_simd cryptd glue_helper intel_cstate intel_uncore snd_hda_intel dm_mod intel_rapl_perf snd_intel_dspcfg drm_kms_helper ofpart snd_hda_codec pcsp>
Feb 21 14:04:11 localhost kernel: CPU: 3 PID: 3709 Comm: AudioThread Tainted: P        W  OE     5.5.4-arch1-1 #1
Feb 21 14:04:11 localhost kernel: Hardware name: System manufacturer System Product Name/TUF Z390-PLUS GAMING, BIOS 0805 09/21/2018
Feb 21 14:04:11 localhost kernel: RIP: 0010:v4l_querycap+0x86/0xa0 [videodev]
Feb 21 14:04:11 localhost kernel: Code: ca 00 00 00 80 48 b9 00 00 20 00 00 00 20 00 48 0b 4b 54 21 d6 39 f2 75 11 48 89 4b 54 5b 5d 41 5c 41 5d 41 5e c3 0f 0b eb d2 <0f> 0b 48 89 4b 54 5b 5d 41 5c 41 5d 41 5e c3 66 66 2e 0f 1f 84 00
Feb 21 14:04:11 localhost kernel: RSP: 0018:ffff9f1a84db7cb8 EFLAGS: 00010202
Feb 21 14:04:11 localhost kernel: RAX: 0000000000000000 RBX: ffff9f1a84db7db0 RCX: 8520800285208002
Feb 21 14:04:11 localhost kernel: RDX: 0000000085008003 RSI: 0000000085008002 RDI: 0000000000000000
Feb 21 14:04:11 localhost kernel: RBP: ffff963b2e990000 R08: ffff9f1a84db7df9 R09: 0000000000000000
Feb 21 14:04:11 localhost kernel: R10: ffff963c217e3ec0 R11: ffff9f1a84db7df9 R12: ffff963b4eaefb00
Feb 21 14:04:11 localhost kernel: R13: ffff963c217e3ec0 R14: ffffffffc275b340 R15: 0000000000000000
Feb 21 14:04:11 localhost kernel: FS:  00007f880ae2e700(0000) GS:ffff963c5dcc0000(0000) knlGS:0000000000000000
Feb 21 14:04:11 localhost kernel: CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
Feb 21 14:04:11 localhost kernel: CR2: 00000b691548d008 CR3: 00000003f1364004 CR4: 00000000003606e0
Feb 21 14:04:11 localhost kernel: DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
Feb 21 14:04:11 localhost kernel: DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
Feb 21 14:04:11 localhost kernel: Call Trace:
Feb 21 14:04:11 localhost kernel:  __video_do_ioctl+0x1c6/0x410 [videodev]
Feb 21 14:04:11 localhost kernel:  ? v4l_s_fmt+0x5d0/0x5d0 [videodev]
Feb 21 14:04:11 localhost kernel:  video_usercopy+0x2a0/0x620 [videodev]
Feb 21 14:04:11 localhost kernel:  v4l2_ioctl+0x48/0x50 [videodev]
Feb 21 14:04:11 localhost kernel:  do_vfs_ioctl+0x4b7/0x730
Feb 21 14:04:11 localhost kernel:  ksys_ioctl+0x5e/0x90
Feb 21 14:04:11 localhost kernel:  __x64_sys_ioctl+0x16/0x20
Feb 21 14:04:11 localhost kernel:  do_syscall_64+0x4e/0x150
Feb 21 14:04:11 localhost kernel:  entry_SYSCALL_64_after_hwframe+0x44/0xa9
Feb 21 14:04:11 localhost kernel: RIP: 0033:0x7f881a61a2eb
Feb 21 14:04:11 localhost kernel: Code: 0f 1e fa 48 8b 05 a5 8b 0c 00 64 c7 00 26 00 00 00 48 c7 c0 ff ff ff ff c3 66 0f 1f 44 00 00 f3 0f 1e fa b8 10 00 00 00 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d 75 8b 0c 00 f7 d8 64 89 01 48
Feb 21 14:04:11 localhost kernel: RSP: 002b:00007f880ae2d468 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
Feb 21 14:04:11 localhost kernel: RAX: ffffffffffffffda RBX: 00000b691467c0c0 RCX: 00007f881a61a2eb
Feb 21 14:04:11 localhost kernel: RDX: 00007f880ae2d4e8 RSI: ffffffff80685600 RDI: 000000000000004f
Feb 21 14:04:11 localhost kernel: RBP: 00007f880ae2d580 R08: 0000000000000000 R09: 0000000000000013
Feb 21 14:04:11 localhost kernel: R10: 0000000000000000 R11: 0000000000000246 R12: 000000000000004f
Feb 21 14:04:11 localhost kernel: R13: 00007f880ae2d4e8 R14: 00000b691467c0c1 R15: 00000b6914529e70
Feb 21 14:04:11 localhost kernel: ---[ end trace a9eadff44cf9eb53 ]---
Feb 21 14:04:11 localhost kernel: ------------[ cut here ]------------

System information:

[mikko@localhost v4l2loopback]$ dmesg  | grep -i v4l2loopback
[  689.184137] Modules linked in: v4l2loopback(OE) nvidia_uvm(OE) fuse xt_MASQUERADE nf_conntrack_netlink nfnetlink xfrm_user xfrm_algo xt_addrtype iptable_nat nf_nat br_netfilter bridge cfg80211 xt_owner 8021q ipt_REJECT nf_reject_ipv4 garp mrp xt_tcpudp stp llc xt_conntrack nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 hwmon_vid iptable_filter btrfs blake2b_generic xor raid6_pq libcrc32c dm_crypt nls_iso8859_1 nls_cp437 vfat fat eeepc_wmi mei_hdcp asus_wmi intel_rapl_msr intel_rapl_common nvidia_drm(POE) snd_hda_codec_hdmi nvidia_modeset(POE) snd_sof_pci x86_pkg_temp_thermal snd_sof_intel_byt intel_powerclamp snd_sof_intel_ipc coretemp kvm_intel snd_sof_xtensa_dsp snd_sof_intel_hda_common battery sparse_keymap iTCO_wdt rfkill snd_soc_hdac_hda iTCO_vendor_support mxm_wmi nvidia(POE) kvm snd_sof_intel_hda snd_sof snd_hda_ext_core snd_soc_acpi_intel_match snd_soc_acpi wmi_bmof snd_soc_core crct10dif_pclmul crc32_pclmul snd_compress ghash_clmulni_intel snd_hda_codec_realtek ac97_bus

[mikko@localhost v4l2loopback]$ uname -a
Linux localhost 5.5.4-arch1-1 #1 SMP PREEMPT Sat, 15 Feb 2020 00:36:29 +0000 x86_64 GNU/Linux

[mikko@localhost v4l2loopback]$ lsb_release -a
LSB Version:    1.4
Distributor ID: Arch
Description:    Arch Linux
Release:        rolling
Codename:       n/a
@umlaeute
Copy link
Owner

which exact version of v4l2loopback is this?

@MikkoMMM
Copy link
Author

It should still be the latest on master, e1ca7ad

I don't even use the releases these days since they seem to come too late for everything to stay in working shape sometimes.

@MikkoMMM
Copy link
Author

Just a regular sudo modprobe v4l2loopback isn't enough to trigger this, by the way. But I figured I'd make it easier for you developers and found out this is enough to trigger the call trace flood:
sudo modprobe v4l2loopback exclusive_caps=1,1,1,1,1,1,1,1

@derneue
Copy link

derneue commented Apr 9, 2020

Same issue here. You can trigger it just by adding the exclusive_caps option. v4l_querycap() WARNs you if the driver change the device_caps. Maybe the issue could be solved without WARN but I do not know how. I am not deep into the v4l thing.

Read v4l_querycap() line 1074:
https://elixir.bootlin.com/linux/latest/source/drivers/media/v4l2-core/v4l2-ioctl.c#L1057

@derneue
Copy link

derneue commented Apr 9, 2020

Maybe the exclusive_caps (V4L2_CAP_VIDEO_CAPTURE/V4L2_CAP_VIDEO_OUTPUT) should be set earlier in init_vdev(), so then there should be no warn again because the v4l_querycap() assertion should not hit. The information is then already in the file descriptor read out here:
https://elixir.bootlin.com/linux/latest/source/drivers/media/v4l2-core/v4l2-ioctl.c#L1061

@derneue derneue mentioned this issue Apr 9, 2020
Closed
@marcusmueller
Copy link

marcusmueller commented Apr 13, 2020 •
edited

Can replicate (current master, i.e. v0.12.4, on Linux 5.5.15-200.fc31.x86_64 SMP) with just insmod v4l2loopback.ko exclusive_caps=1; because I don't think having full dmesg output in-discussion helps, here's a link:
dmesg.txt

@umlaeute umlaeute mentioned this issue Apr 26, 2020
Closed
@jakobrs jakobrs mentioned this issue Apr 28, 2020
Merged
10 tasks
@umlaeute umlaeute mentioned this issue Jun 1, 2020
Closed
@umlaeute umlaeute mentioned this issue Aug 9, 2020
Closed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
4 participants
@umlaeute @marcusmueller @MikkoMMM @derneue