Bug 32981

Description of problem:

For the past 4 days, started on "mar 14 21:12:17", I'm seeing the following message in the logs:

"""
kernel: tpm tpm0: tpm_try_transmit: send(): error -62
"""

This message is repeated every 12.5 seconds, for a total 24622 times.

This system's logs go back to the 22 of February and the only other tpm relevant mentions are:

"""
fev 22 09:55:44 marte kernel: tpm_tis 00:09: 1.2 TPM (device-id 0xB, rev-id 16)
mar 03 08:39:43 marte kernel: tpm_tis 00:09: 1.2 TPM (device-id 0xB, rev-id 16)
"""

I looked in the logs to see what had changed prior to the first tpm error message but did not find any clues.

This system has been up since "mar 03 08:39:42", that is over 15 days, so a new kernel is (probably) not the issue and I had not installed any packages or updates in the days prior.

After trying to debug the problem and searching the interwebs for help, nothing relevant come up.

So today I had some free time and decided to do some poking and see what would break.

I stopped all services one by one to see if the messages would stop but they continued so I turned to the kernel modules and removed the modules "tpm_infineon" and "tpm_tis" and the tpm error messages stopped but I got the following kernel warning and backtrace:

"""
[1298151.494104] ------------[ cut here ]------------
[1298151.494747] WARNING: CPU: 1 PID: 109117 at kernel/workqueue.c:3397 __flush_work.isra.0+0x291/0x2b0
[1298151.495462] Modules linked in: nfnetlink_queue bluetooth ecdh_generic ecc binfmt_misc xsk_diag udp_diag raw_diag unix_diag af_packet_diag netlink_diag exfat tls xt_recent ipt_IFWLOG ipt_psd xt_set ip_set_hash_ip ip_set ipt_REJECT n
f_reject_ipv4 xt_multiport xt_hashlimit xt_conntrack xt_addrtype xt_mark iptable_mangle iptable_nat xt_CT xt_tcpudp iptable_raw xt_NFLOG nfnetlink_log xt_LOG nf_log_syslog nf_nat_tftp nf_nat_snmp_basic nf_conntrack_snmp nf_nat_sip nf_nat_pptp nf_nat_irc nf_nat_h323 nf_nat_ftp nf_nat_amanda ts_kmp nf_conntrack_amanda nf_nat nf_conntrack_sane nf_conntrack_tftp nf_conntrack_sip nf_conntrack_pptp nf_conntrack_netlink nfnetlink nf_conntrack_netbios_ns nf_conntrack_broadcast nf_conntrack_irc nf_conntrack_h323 nf_conntrack_ftp nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 iptable_filter overlay af_packet nls_utf8 nls_cp437 vfat fat snd_hda_codec_realtek snd_hda_codec_generic ledtrig_audio snd_hda_codec_hdmi snd_hda_intel snd_intel_dspcfg snd_intel_sdw_acpi spi_nor snd_hda_codec mei_hdcp intel_rapl_msr
[1298151.495538]  mtd mei_pxp snd_hda_core intel_rapl_common e1000e x86_pkg_temp_thermal mei_wdt intel_powerclamp snd_hwdep coretemp spi_intel_platform spi_intel snd_pcm iTCO_wdt wireguard intel_pmc_bxt curve25519_x86_64 libchacha20poly1305 chacha_x86_64 poly1305_x86_64 iTCO_vendor_support libcurve25519_generic libchacha ip6_udp_tunnel rapl udp_tunnel snd_timer hp_wmi intel_cstate snd bridge input_leds intel_uncore joydev mei_me sparse_keymap tpm_tis(-) ptp soundcore stp platform_profile llc i2c_i801 tpm_tis_core pps_core psmouse mei wmi_bmof lpc_ich evdev i2c_smbus cfg80211 rfkill zram msr loop fuse configfs efivarfs dmi_sysfs ip_tables x_tables ipv6 crc_ccitt dm_thin_pool dm_persistent_data dm_bio_prison dm_bufio uas usb_storage dm_crypt trusted asn1_encoder tee tpm crc32_pclmul crc32c_intel polyval_clmulni polyval_generic gf128mul ghash_clmulni_intel sha512_ssse3 atkbd sha256_ssse3 sha1_ssse3 sha1_generic aesni_intel crypto_simd vivaldi_fmap cryptd serio_raw xhci_pci xhci_pci_renesas i915 i2c_algo_bit drm_buddy ttm
[1298151.499869]  drm_display_helper drm_kms_helper video drm wmi cec rc_core dm_mirror dm_region_hash dm_log dm_mod [last unloaded: tpm_infineon]
[1298151.510455] CPU: 1 PID: 109117 Comm: modprobe Not tainted 6.6.18-desktop-1.mga9 #1
[1298151.511725] Hardware name: Hewlett-Packard HP EliteDesk 800 G1 SFF/1998, BIOS L01 v02.65 07/13/2015
[1298151.512729] RIP: 0010:__flush_work.isra.0+0x291/0x2b0
[1298151.513737] Code: 8b 04 25 c0 ed 02 00 48 89 44 24 40 48 8b 53 40 8b 43 30 e9 b3 fe ff ff 40 30 f6 4c 8b 36 e9 f2 fd ff ff 0f 0b e9 3b ff ff ff <0f> 0b e9 34 ff ff ff 0f 0b e9 d8 fe ff ff 0f 0b e9 a9 fe ff ff e8
[1298151.517288] RSP: 0018:ffffc9000b493d88 EFLAGS: 00010246
[1298151.518946] RAX: 0000000000000000 RBX: ffff88813e5e6328 RCX: ffffc9000b493e14
[1298151.520588] RDX: 0000000000000004 RSI: ffffc90000ab0008 RDI: ffff88813e5e6368
[1298151.522393] RBP: ffff88813e5e6368 R08: 0000000000000002 R09: 0000000000000000
[1298151.523952] R10: ffff888147d03b78 R11: ffffc9000b493de0 R12: 0000000000000001
[1298151.525342] R13: ffff888100ae1c80 R14: ffffffff9796df10 R15: 0000000000000000
[1298151.526982] FS:  00007fd8108f4400(0000) GS:ffff88840fa80000(0000) knlGS:0000000000000000
[1298151.528695] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[1298151.530213] CR2: 00007fd8102708b0 CR3: 0000000112126003 CR4: 00000000001706e0
[1298151.531884] Call Trace:
[1298151.533542]  <TASK>
[1298151.535066]  ? __flush_work.isra.0+0x291/0x2b0
[1298151.536671]  ? __warn+0x7d/0x130
[1298151.538451]  ? __flush_work.isra.0+0x291/0x2b0
[1298151.540120]  ? report_bug+0x16d/0x1a0
[1298151.541746]  ? handle_bug+0x41/0x70
[1298151.543358]  ? exc_invalid_op+0x13/0x60
[1298151.544959]  ? asm_exc_invalid_op+0x16/0x20
[1298151.546575]  ? __flush_work.isra.0+0x291/0x2b0
[1298151.548198]  ? cleanup_glue_dir+0x71/0xa0
[1298151.549983]  ? device_del+0x295/0x3e0
[1298151.551758]  tpm_tis_remove+0x9d/0xf0 [tpm_tis_core]
[1298151.553190]  pnp_device_remove+0x24/0x80
[1298151.554697]  device_release_driver_internal+0x19b/0x200
[1298151.556467]  driver_detach+0x44/0x90
[1298151.558220]  bus_remove_driver+0x69/0xf0
[1298151.559836]  cleanup_tis+0xc/0x9f0 [tpm_tis]
[1298151.561292]  __do_sys_delete_module+0x1a9/0x2f0
[1298151.563047]  ? do_syscall_64+0x67/0x80
[1298151.564680]  ? exit_to_user_mode_prepare+0x40/0x1e0
[1298151.566131]  do_syscall_64+0x5b/0x80
[1298151.567866]  entry_SYSCALL_64_after_hwframe+0x6e/0xd8
[1298151.569594] RIP: 0033:0x7fd81032d8a7
[1298151.571076] Code: 73 01 c3 48 8b 0d 69 35 0c 00 f7 d8 64 89 01 48 83 c8 ff c3 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 44 00 00 b8 b0 00 00 00 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d 39 35 0c 00 f7 d8 64 89 01 48
[1298151.574556] RSP: 002b:00007ffca60024b8 EFLAGS: 00000206 ORIG_RAX: 00000000000000b0
[1298151.576433] RAX: ffffffffffffffda RBX: 000000000205bf90 RCX: 00007fd81032d8a7
[1298151.577938] RDX: 0000000000000000 RSI: 0000000000000800 RDI: 000000000205bff8
[1298151.579396] RBP: 0000000000000000 R08: 1999999999999999 R09: 0000000000000000
[1298151.581117] R10: 00007fd81039da80 R11: 0000000000000206 R12: 000000000205bf90
[1298151.582828] R13: 0000000000000000 R14: 0000000000000000 R15: 000000000205bff8
[1298151.584543]  </TASK>
[1298151.586242] ---[ end trace 0000000000000000 ]---

Partitions are LUKS encrypted and the "dm_crypt" is the module keeping the "tpm" module loaded but I don't think that is the cause of the issue.

There is a bug somewhere causing this issue, probably in the kernel TPM modules, but at the moment the system seems stable and I see no ill effects so I'm making this report for future reference just in case other people encounter the same issue.



Version-Release number of selected component (if applicable):

# rpm -qa | grep 6.6.18 | sort
cpupower-6.6.18-1.mga9
kernel-desktop-6.6.18-1.mga9
kernel-desktop-latest-6.6.18-1.mga9
kernel-userspace-headers-6.6.18-1.mga9
lib64bpf1-6.6.18-1.mga9
perf-6.6.18-1.mga9



How reproducible:

Only happened one time so far.



Steps to Reproduce:

Unknown.



Extra information:

# uptime
 09:23:35 up 15 days, 44 min,  1 user,  load average: 0,40, 0,28, 0,38
# uname -a
Linux marte 6.6.18-desktop-1.mga9 #1 SMP PREEMPT_DYNAMIC Sat Feb 24 02:17:35 UTC 2024 x86_64 GNU/Linux
# lsmod | grep -E '(trusted|tpm|dm-crypt)'
trusted                45056  1 dm_crypt
asn1_encoder           12288  1 trusted
tee                    45056  1 trusted
tpm                   102400  1 trusted