regression: kernel log "flooded" with tpm tpm0: A TPM error (2306) occurred attempting to create NULL primary

regression: kernel log "flooded" with tpm tpm0: A TPM error (2306) occurred attempting to create NULL primary

[Christoph Anton Mitterer]

Hey.

Forwarding myself from:
https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=1087331

Since 6.11.7 (might have also happened with .6, which I've skipped, but
wasn't the case at least in 6.11.5).

I get:
Nov 11 17:50:20 heisenberg kernel: tpm tpm0: A TPM error (2306) occurred attempting to create NULL primary
Nov 11 17:50:30 heisenberg kernel: tpm tpm0: A TPM error (2306) occurred attempting to create NULL primary
Nov 11 17:50:41 heisenberg kernel: tpm tpm0: A TPM error (2306) occurred attempting to create NULL primary
Nov 11 17:50:51 heisenberg kernel: tpm tpm0: A TPM error (2306) occurred attempting to create NULL primary
Nov 11 17:51:01 heisenberg kernel: tpm tpm0: A TPM error (2306) occurred attempting to create NULL primary
Nov 11 17:51:11 heisenberg kernel: tpm tpm0: A TPM error (2306) occurred attempting to create NULL primary

every 10s.

It seems that this doesn't occur on a fresh boot, but only when I
resume from hibernation:

Nov 13 12:32:31 heisenberg kernel: Filesystems sync: 0.007 seconds
Nov 13 12:32:31 heisenberg kernel: Freezing user space processes
Nov 13 12:32:31 heisenberg kernel: sh (31294): drop_caches: 1
Nov 13 12:32:31 heisenberg kernel: Freezing user space processes completed (elapsed 0.326 seconds)
Nov 13 12:32:31 heisenberg kernel: OOM killer disabled.
Nov 13 12:32:31 heisenberg kernel: PM: hibernation: Marking nosave pages: [mem 0x00000000-0x00000fff]
Nov 13 12:32:31 heisenberg kernel: PM: hibernation: Marking nosave pages: [mem 0x000a0000-0x000fffff]
Nov 13 12:32:31 heisenberg kernel: PM: hibernation: Marking nosave pages: [mem 0x2f2a9000-0x310a8fff]
Nov 13 12:32:31 heisenberg kernel: PM: hibernation: Marking nosave pages: [mem 0x310be000-0x310befff]
Nov 13 12:32:31 heisenberg kernel: PM: hibernation: Marking nosave pages: [mem 0x34f53000-0x35046fff]
Nov 13 12:32:31 heisenberg kernel: PM: hibernation: Marking nosave pages: [mem 0x39cbf000-0x43afefff]
Nov 13 12:32:31 heisenberg kernel: PM: hibernation: Marking nosave pages: [mem 0x43b00000-0xffffffff]
Nov 13 12:32:31 heisenberg kernel: PM: hibernation: Basic memory bitmaps created
Nov 13 12:32:31 heisenberg kernel: PM: hibernation: Preallocating image memory
Nov 13 12:32:31 heisenberg kernel: PM: hibernation: Allocated 3676637 pages for snapshot
Nov 13 12:32:31 heisenberg kernel: PM: hibernation: Allocated 14706548 kbytes in 1.90 seconds (7740.28 MB/s)
Nov 13 12:32:31 heisenberg kernel: Freezing remaining freezable tasks
Nov 13 12:32:31 heisenberg kernel: Freezing remaining freezable tasks completed (elapsed 0.001 seconds)
Nov 13 12:32:31 heisenberg kernel: printk: Suspending console(s) (use no_console_suspend to debug)
Nov 13 12:32:31 heisenberg kernel: intel-hid INTC1070:00: failed to get button capability
Nov 13 12:32:31 heisenberg kernel: ACPI: EC: interrupt blocked
Nov 13 12:32:31 heisenberg kernel: Disabling non-boot CPUs ...
Nov 13 12:32:31 heisenberg kernel: smpboot: CPU 15 is now offline
Nov 13 12:32:31 heisenberg kernel: smpboot: CPU 14 is now offline
Nov 13 12:32:31 heisenberg kernel: smpboot: CPU 13 is now offline
Nov 13 12:32:31 heisenberg kernel: smpboot: CPU 12 is now offline
Nov 13 12:32:31 heisenberg kernel: smpboot: CPU 11 is now offline
Nov 13 12:32:31 heisenberg kernel: smpboot: CPU 10 is now offline
Nov 13 12:32:31 heisenberg kernel: smpboot: CPU 9 is now offline
Nov 13 12:32:31 heisenberg kernel: smpboot: CPU 8 is now offline
Nov 13 12:32:31 heisenberg kernel: smpboot: CPU 7 is now offline
Nov 13 12:32:31 heisenberg kernel: smpboot: CPU 6 is now offline
Nov 13 12:32:31 heisenberg kernel: smpboot: CPU 5 is now offline
Nov 13 12:32:31 heisenberg kernel: smpboot: CPU 4 is now offline
Nov 13 12:32:31 heisenberg kernel: smpboot: CPU 3 is now offline
Nov 13 12:32:31 heisenberg kernel: smpboot: CPU 2 is now offline
Nov 13 12:32:31 heisenberg kernel: smpboot: CPU 1 is now offline
Nov 13 12:32:31 heisenberg kernel: PM: hibernation: Creating image:
Nov 13 12:32:31 heisenberg kernel: PM: hibernation: Need to copy 3608962 pages
Nov 13 12:32:31 heisenberg kernel: PM: hibernation: Normal pages needed: 3608962 + 1024, available pages: 13065600
Nov 13 12:32:31 heisenberg kernel: Enabling non-boot CPUs ...
Nov 13 12:32:31 heisenberg kernel: smpboot: Booting Node 0 Processor 1 APIC 0x1
Nov 13 12:32:31 heisenberg kernel: CPU1 is up
Nov 13 12:32:31 heisenberg kernel: smpboot: Booting Node 0 Processor 2 APIC 0x8
Nov 13 12:32:31 heisenberg kernel: CPU2 is up
Nov 13 12:32:31 heisenberg kernel: smpboot: Booting Node 0 Processor 3 APIC 0x9
Nov 13 12:32:31 heisenberg kernel: CPU3 is up
Nov 13 12:32:31 heisenberg kernel: smpboot: Booting Node 0 Processor 4 APIC 0x10
Nov 13 12:32:31 heisenberg kernel: CPU4 is up
Nov 13 12:32:31 heisenberg kernel: smpboot: Booting Node 0 Processor 5 APIC 0x11
Nov 13 12:32:31 heisenberg kernel: CPU5 is up
Nov 13 12:32:31 heisenberg kernel: smpboot: Booting Node 0 Processor 6 APIC 0x18
Nov 13 12:32:31 heisenberg kernel: CPU6 is up
Nov 13 12:32:31 heisenberg kernel: smpboot: Booting Node 0 Processor 7 APIC 0x19
Nov 13 12:32:31 heisenberg kernel: CPU7 is up
Nov 13 12:32:31 heisenberg kernel: smpboot: Booting Node 0 Processor 8 APIC 0x20
Nov 13 12:32:31 heisenberg kernel: core: cpu_atom PMU driver: PEBS-via-PT 
Nov 13 12:32:31 heisenberg kernel: ... version:                5
Nov 13 12:32:31 heisenberg kernel: ... bit width:              48
Nov 13 12:32:31 heisenberg kernel: ... generic registers:      6
Nov 13 12:32:31 heisenberg kernel: ... value mask:             0000ffffffffffff
Nov 13 12:32:31 heisenberg kernel: ... max period:             00007fffffffffff
Nov 13 12:32:31 heisenberg kernel: ... fixed-purpose events:   3
Nov 13 12:32:31 heisenberg kernel: ... event mask:             000000070000003f
Nov 13 12:32:31 heisenberg kernel: CPU8 is up
Nov 13 12:32:31 heisenberg kernel: smpboot: Booting Node 0 Processor 9 APIC 0x22
Nov 13 12:32:31 heisenberg kernel: CPU9 is up
Nov 13 12:32:31 heisenberg kernel: smpboot: Booting Node 0 Processor 10 APIC 0x24
Nov 13 12:32:31 heisenberg kernel: CPU10 is up
Nov 13 12:32:31 heisenberg kernel: smpboot: Booting Node 0 Processor 11 APIC 0x26
Nov 13 12:32:31 heisenberg kernel: CPU11 is up
Nov 13 12:32:31 heisenberg kernel: smpboot: Booting Node 0 Processor 12 APIC 0x28
Nov 13 12:32:31 heisenberg kernel: CPU12 is up
Nov 13 12:32:31 heisenberg kernel: smpboot: Booting Node 0 Processor 13 APIC 0x2a
Nov 13 12:32:31 heisenberg kernel: CPU13 is up
Nov 13 12:32:31 heisenberg kernel: smpboot: Booting Node 0 Processor 14 APIC 0x2c
Nov 13 12:32:31 heisenberg kernel: CPU14 is up
Nov 13 12:32:31 heisenberg kernel: smpboot: Booting Node 0 Processor 15 APIC 0x2e
Nov 13 12:32:31 heisenberg kernel: CPU15 is up
Nov 13 12:32:31 heisenberg kernel: ACPI: EC: interrupt unblocked
Nov 13 12:32:31 heisenberg kernel: usb usb1: root hub lost power or was reset
Nov 13 12:32:31 heisenberg kernel: usb usb2: root hub lost power or was reset
Nov 13 12:32:31 heisenberg kernel: intel-hid INTC1070:00: failed to get button capability
Nov 13 12:32:31 heisenberg kernel: usb usb3: root hub lost power or was reset
Nov 13 12:32:31 heisenberg kernel: usb usb4: root hub lost power or was reset
Nov 13 12:32:31 heisenberg kernel: i915 0000:00:02.0: [drm] GT0: GuC firmware i915/adlp_guc_70.bin version 70.29.2
Nov 13 12:32:31 heisenberg kernel: i915 0000:00:02.0: [drm] GT0: HuC firmware i915/tgl_huc.bin version 7.9.3
Nov 13 12:32:31 heisenberg kernel: nvme nvme0: D3 entry latency set to 10 seconds
Nov 13 12:32:31 heisenberg kernel: nvme nvme0: 16/0/0 default/read/poll queues
Nov 13 12:32:31 heisenberg kernel: i915 0000:00:02.0: [drm] GT0: HuC: authenticated for all workloads
Nov 13 12:32:31 heisenberg kernel: i915 0000:00:02.0: [drm] GT0: GUC: submission enabled
Nov 13 12:32:31 heisenberg kernel: i915 0000:00:02.0: [drm] GT0: GUC: SLPC enabled
Nov 13 12:32:31 heisenberg kernel: i915 0000:00:02.0: [drm] GT0: GUC: RC enabled
Nov 13 12:32:31 heisenberg kernel: iwlwifi 0000:00:14.3: WFPM_UMAC_PD_NOTIFICATION: 0x20
Nov 13 12:32:31 heisenberg kernel: iwlwifi 0000:00:14.3: WFPM_LMAC2_PD_NOTIFICATION: 0x1f
Nov 13 12:32:31 heisenberg kernel: iwlwifi 0000:00:14.3: WFPM_AUTH_KEY_0: 0x90
Nov 13 12:32:31 heisenberg kernel: iwlwifi 0000:00:14.3: CNVI_SCU_SEQ_DATA_DW9: 0x0
Nov 13 12:32:31 heisenberg kernel: iwlwifi 0000:00:14.3: RFIm is deactivated, reason = 4
Nov 13 12:32:31 heisenberg kernel: usb 1-10: reset full-speed USB device number 6 using xhci_hcd
Nov 13 12:32:31 heisenberg kernel: usb 1-6: reset high-speed USB device number 3 using xhci_hcd
Nov 13 12:32:31 heisenberg kernel: usb 1-5: reset high-speed USB device number 2 using xhci_hcd
Nov 13 12:32:31 heisenberg kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: IMR restore failed, trying to cold boot
Nov 13 12:32:31 heisenberg kernel: PM: hibernation: Basic memory bitmaps freed
Nov 13 12:32:31 heisenberg kernel: mei_hdcp 0000:00:16.0-b638ab7e-94e2-4ea2-a552-d1c54b627f04: bound 0000:00:02.0 (ops i915_hdcp_ops [i915])
Nov 13 12:32:31 heisenberg kernel: OOM killer enabled.
Nov 13 12:32:31 heisenberg kernel: Restarting tasks ... 
Nov 13 12:32:31 heisenberg kernel: mei_pxp 0000:00:16.0-fbf6fcf1-96cf-4e2e-a6a6-1bab8cbe36b1: bound 0000:00:02.0 (ops i915_pxp_tee_component_ops [i915])
Nov 13 12:32:31 heisenberg kernel: done.
Nov 13 12:32:31 heisenberg kernel: usb 1-5.2: USB disconnect, device number 4
Nov 13 12:32:31 heisenberg kernel: usb 1-5.2: new full-speed USB device number 7 using xhci_hcd
Nov 13 12:32:31 heisenberg kernel: PM: hibernation: hibernation exit
Nov 13 12:32:31 heisenberg kernel: usb 1-5.2: New USB device found, idVendor=058f, idProduct=9540, bcdDevice= 1.20
Nov 13 12:32:31 heisenberg kernel: usb 1-5.2: New USB device strings: Mfr=1, Product=2, SerialNumber=0
Nov 13 12:32:31 heisenberg kernel: usb 1-5.2: Product: EMV Smartcard Reader
Nov 13 12:32:31 heisenberg kernel: usb 1-5.2: Manufacturer: Generic
Nov 13 12:32:31 heisenberg kernel: usb 1-5.2: Device is not authorized for usage
Nov 13 12:32:31 heisenberg kernel: usb 1-5.2: authorized to connect
Nov 13 12:32:31 heisenberg kernel: e1000e 0000:00:1f.6 eth0: NIC Link is Down
Nov 13 12:32:32 heisenberg kernel: iwlwifi 0000:00:14.3: WFPM_UMAC_PD_NOTIFICATION: 0x20
Nov 13 12:32:32 heisenberg kernel: iwlwifi 0000:00:14.3: WFPM_LMAC2_PD_NOTIFICATION: 0x1f
Nov 13 12:32:32 heisenberg kernel: iwlwifi 0000:00:14.3: WFPM_AUTH_KEY_0: 0x90
Nov 13 12:32:32 heisenberg kernel: iwlwifi 0000:00:14.3: CNVI_SCU_SEQ_DATA_DW9: 0x0
Nov 13 12:32:32 heisenberg kernel: iwlwifi 0000:00:14.3: RFIm is deactivated, reason = 4
Nov 13 12:33:06 heisenberg kernel: tpm tpm0: NULL Seed name comparison failed
Nov 13 12:33:16 heisenberg kernel: tpm tpm0: NULL Seed name comparison failed
Nov 13 12:33:26 heisenberg kernel: tpm tpm0: NULL Seed name comparison failed
Nov 13 12:33:30 heisenberg kernel: wlan0: authenticate with 40:e3:d6:51:2a:30 (local address=7c:b5:66:f7:a8:a5)
Nov 13 12:33:30 heisenberg kernel: wlan0: send auth to 40:e3:d6:51:2a:30 (try 1/3)
Nov 13 12:33:30 heisenberg kernel: wlan0: authenticated
Nov 13 12:33:30 heisenberg kernel: wlan0: associate with 40:e3:d6:51:2a:30 (try 1/3)
Nov 13 12:33:30 heisenberg kernel: wlan0: RX AssocResp from 40:e3:d6:51:2a:30 (capab=0x411 status=0 aid=8)
Nov 13 12:33:30 heisenberg kernel: wlan0: associated
Nov 13 12:33:30 heisenberg kernel: wlan0: Limiting TX power to 23 (23 - 0) dBm as advertised by 40:e3:d6:51:2a:30
Nov 13 12:33:31 heisenberg kernel: IPv4: martian source 255.255.255.255 from 10.183.63.252, on dev wlan0
Nov 13 12:33:31 heisenberg kernel: ll header: 00000000: 7c b5 66 f7 a8 a5 fc bd 67 c1 e2 ff 08 00
Nov 13 12:33:31 heisenberg kernel: IPv4: martian source 255.255.255.255 from 10.183.63.252, on dev wlan0
Nov 13 12:33:31 heisenberg kernel: ll header: 00000000: 7c b5 66 f7 a8 a5 fc bd 67 c1 e2 ff 08 00
Nov 13 12:33:31 heisenberg kernel: IPv4: martian source 255.255.255.255 from 10.183.63.253, on dev wlan0
Nov 13 12:33:31 heisenberg kernel: ll header: 00000000: 7c b5 66 f7 a8 a5 fc bd 67 16 62 33 08 00
Nov 13 12:33:31 heisenberg kernel: IPv4: martian source 255.255.255.255 from 10.183.63.253, on dev wlan0
Nov 13 12:33:31 heisenberg kernel: ll header: 00000000: 7c b5 66 f7 a8 a5 fc bd 67 16 62 33 08 00
Nov 13 12:33:36 heisenberg kernel: tpm tpm0: A TPM error (2306) occurred attempting to create NULL primary
Nov 13 12:33:46 heisenberg kernel: tpm tpm0: A TPM error (2306) occurred attempting to create NULL primary
Nov 13 12:33:57 heisenberg kernel: tpm tpm0: A TPM error (2306) occurred attempting to create NULL primary
Nov 13 12:34:07 heisenberg kernel: tpm tpm0: A TPM error (2306) occurred attempting to create NULL primary
Nov 13 12:34:17 heisenberg kernel: tpm tpm0: A TPM error (2306) occurred attempting to create NULL primary
Nov 13 12:34:27 heisenberg kernel: tpm tpm0: A TPM error (2306) occurred attempting to create NULL primary
Nov 13 12:34:38 heisenberg kernel: tpm tpm0: A TPM error (2306) occurred attempting to create NULL primary


Any ideas? :-)

Thanks,
Chris.

Re: regression: kernel log "flooded" with tpm tpm0: A TPM error (2306) occurred attempting to create NULL primary

[James Bottomley]

On Wed, 2024-11-13 at 15:44 +0100, Christoph Anton Mitterer wrote:
> Hey.
> 
> Forwarding myself from:
> https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=1087331
> 
> Since 6.11.7 (might have also happened with .6, which I've skipped,
> but
> wasn't the case at least in 6.11.5).
> 
> I get:
> Nov 11 17:50:20 heisenberg kernel: tpm tpm0: A TPM error (2306)
> occurred attempting to create NULL primary
> Nov 11 17:50:30 heisenberg kernel: tpm tpm0: A TPM error (2306)
> occurred attempting to create NULL primary
> Nov 11 17:50:41 heisenberg kernel: tpm tpm0: A TPM error (2306)
> occurred attempting to create NULL primary
> Nov 11 17:50:51 heisenberg kernel: tpm tpm0: A TPM error (2306)
> occurred attempting to create NULL primary
> Nov 11 17:51:01 heisenberg kernel: tpm tpm0: A TPM error (2306)
> occurred attempting to create NULL primary
> Nov 11 17:51:11 heisenberg kernel: tpm tpm0: A TPM error (2306)
> occurred attempting to create NULL primary

2306 is TPM_RC_OBJECT_MEMORY - out of memory for object contexts.  What
it's saying is that somewhere we're missing a context flush.  I'll take
a look.  Does this happen with the current upstream kernel?  It could
be a flush got lost as a result of a bad stable backport.

> It seems that this doesn't occur on a fresh boot, but only when I
> resume from hibernation:

That could be more significant, especially with this in the log:

> Nov 13 12:33:06 heisenberg kernel: tpm tpm0: NULL Seed name
> comparison failed
> Nov 13 12:33:16 heisenberg kernel: tpm tpm0: NULL Seed name
> comparison failed
> Nov 13 12:33:26 heisenberg kernel: tpm tpm0: NULL Seed name
> comparison failed

I think we might have to expect the NULL name to change on actual
hibernation because unlike suspend to ram it does power off the TPM.

However, the code that causes the above message was also in 6.10 ...
are you sure kernels 6.10 and beyond hibernate without producing this
message?

Regards,

James

Re: regression: kernel log "flooded" with tpm tpm0: A TPM error (2306) occurred attempting to create NULL primary

[James Bottomley]

On Wed, 2024-11-13 at 07:47 -0800, James Bottomley wrote:
> On Wed, 2024-11-13 at 15:44 +0100, Christoph Anton Mitterer wrote:
> > Hey.
> > 
> > Forwarding myself from:
> > https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=1087331
> > 
> > Since 6.11.7 (might have also happened with .6, which I've skipped,
> > but wasn't the case at least in 6.11.5).
> > 
> > I get:
> > Nov 11 17:50:20 heisenberg kernel: tpm tpm0: A TPM error (2306)
> > occurred attempting to create NULL primary
> > Nov 11 17:50:30 heisenberg kernel: tpm tpm0: A TPM error (2306)
> > occurred attempting to create NULL primary
> > Nov 11 17:50:41 heisenberg kernel: tpm tpm0: A TPM error (2306)
> > occurred attempting to create NULL primary
> > Nov 11 17:50:51 heisenberg kernel: tpm tpm0: A TPM error (2306)
> > occurred attempting to create NULL primary
> > Nov 11 17:51:01 heisenberg kernel: tpm tpm0: A TPM error (2306)
> > occurred attempting to create NULL primary
> > Nov 11 17:51:11 heisenberg kernel: tpm tpm0: A TPM error (2306)
> > occurred attempting to create NULL primary
> 
> 2306 is TPM_RC_OBJECT_MEMORY - out of memory for object contexts. 
> What it's saying is that somewhere we're missing a context flush. 
> I'll take a look.  Does this happen with the current upstream
> kernel?  It couldbe a flush got lost as a result of a bad stable
> backport.

OK, I found it; there's a bug in the handling of create primary on a
validation rather than a TPM error (it doesn't flush the handle). 
However, even when I fix that you're apparently going to get the below
message every 10s or so as the TPM tries to init

> 
> > It seems that this doesn't occur on a fresh boot, but only when I
> > resume from hibernation:
> 
> That could be more significant, especially with this in the log:
> 
> > Nov 13 12:33:06 heisenberg kernel: tpm tpm0: NULL Seed name
> > comparison failed
> > Nov 13 12:33:16 heisenberg kernel: tpm tpm0: NULL Seed name
> > comparison failed
> > Nov 13 12:33:26 heisenberg kernel: tpm tpm0: NULL Seed name
> > comparison failed
> 
> I think we might have to expect the NULL name to change on actual
> hibernation because unlike suspend to ram it does power off the TPM.

I checked the code: we're coming in on the correct path to renew the
null seed after hibernation, so it should all work.  The problem seems
to be that your TPM itself is doing something invalid because the name
we calculate for the primary key doesn't match what your TPM says it
should be.  Absent some form of attack or bus integrity problem, that
shouldn't ever happen, so I'm even more curious to know why it worked
in 6.11.5 and before and whether current upstream works.

I haven't found it yet, but I think the every 10s signature is because
the hibernation path is trying to restart the TPM device and won't take
no for an answer.

Re: regression: kernel log "flooded" with tpm tpm0: A TPM error (2306) occurred attempting to create NULL primary

[Jarkko Sakkinen]

On Wed Nov 13, 2024 at 4:44 PM EET, Christoph Anton Mitterer wrote:
> Hey.
>
> Forwarding myself from:
> https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=1087331
>
> Since 6.11.7 (might have also happened with .6, which I've skipped, but
> wasn't the case at least in 6.11.5).
>
> I get:
> Nov 11 17:50:20 heisenberg kernel: tpm tpm0: A TPM error (2306) occurred attempting to create NULL primary

Yep, I found the reason. My fix causes this. I sent a fix.

The problem still persists related to TPM bus encryption not working
with hibernate in 6.11.5 but the message was shown only once in the
log (and thus you did not notice it).

That can be worked around e.g. with kernel command-line flag that
would disable TPM bus encryption but it is out-of-scope as far as
I'm concerned.

Please test my fix and I can take it to PR.

BR, Jarkko

Re: regression: kernel log "flooded" with tpm tpm0: A TPM error (2306) occurred attempting to create NULL primary

[Jarkko Sakkinen]

On Wed Nov 13, 2024 at 8:49 PM EET, Jarkko Sakkinen wrote:
> On Wed Nov 13, 2024 at 4:44 PM EET, Christoph Anton Mitterer wrote:
> > Hey.
> >
> > Forwarding myself from:
> > https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=1087331
> >
> > Since 6.11.7 (might have also happened with .6, which I've skipped, but
> > wasn't the case at least in 6.11.5).
> >
> > I get:
> > Nov 11 17:50:20 heisenberg kernel: tpm tpm0: A TPM error (2306) occurred attempting to create NULL primary
>
> Yep, I found the reason. My fix causes this. I sent a fix.
>
> The problem still persists related to TPM bus encryption not working
> with hibernate in 6.11.5 but the message was shown only once in the
> log (and thus you did not notice it).
>
> That can be worked around e.g. with kernel command-line flag that
> would disable TPM bus encryption but it is out-of-scope as far as
> I'm concerned.
>
> Please test my fix and I can take it to PR.

https://lore.kernel.org/linux-integrity/20241113184449.477731-1-jarkko@kernel.org/T/#u

BR, Jarkko

Re: regression: kernel log "flooded" with tpm tpm0: A TPM error (2306) occurred attempting to create NULL primary

[Jarkko Sakkinen]

On Wed Nov 13, 2024 at 8:12 PM EET, James Bottomley wrote:
> > I think we might have to expect the NULL name to change on actual
> > hibernation because unlike suspend to ram it does power off the TPM.
>
> I checked the code: we're coming in on the correct path to renew the
> null seed after hibernation, so it should all work.  The problem seems
> to be that your TPM itself is doing something invalid because the name
> we calculate for the primary key doesn't match what your TPM says it
> should be.  Absent some form of attack or bus integrity problem, that
> shouldn't ever happen, so I'm even more curious to know why it worked
> in 6.11.5 and before and whether current upstream works.
>
> I haven't found it yet, but I think the every 10s signature is because
> the hibernation path is trying to restart the TPM device and won't take
> no for an answer.

My fix returned the behavior how it was before my earlier fix in this
corner case (i.e. disable TPM). The issue has gone unnoticed before
since it has emitted only a single klog entry.

On suspend this has not happened to me so obvious deduction is that
hibernate resets the null seed.

Hibernate needs an addition a fix to disable bus encryption from kernel
command-line completely, i.e. tpm.disable_integrity following the
convention from my earlier fix [1].

Fast-forward, in order to *enable* bus encryption with hibernate, a
feature patch would be needed to specify a NV key in the kernel
command-line. It probably cannot be resolved with a null key, at least
not based on these empirical results... I would not mind to be wrong in
this tho.

So to summarize:

1. Fix: tpm.disable_integrity
2. Feature:  tpm.integrity_key=<persistent handle>

I've never got hibernate working even after trying and without even 
having TPM in the configuration so pretty hard to test it beforehand...

[1] https://lore.kernel.org/linux-integrity/20241113184449.477731-1-jarkko@kernel.org/T/#u

BR, Jarkko

Re: regression: kernel log "flooded" with tpm tpm0: A TPM error (2306) occurred attempting to create NULL primary

[Jarkko Sakkinen]

On Thu Nov 14, 2024 at 12:34 AM EET, Jarkko Sakkinen wrote:
> I've never got hibernate working even after trying and without even 
> having TPM in the configuration so pretty hard to test it beforehand...

Hibernate really would need CI if there is even an aim to keep it
unbroken because I've actually never even met a first who has it
working, and neither any CI bot has complained me of hibernate not being
woring :-)

So I neither could give a promise that "this won't happen in future"
becaus there's no means/tools to guarantee that.

BR, Jarkko

Re: regression: kernel log "flooded" with tpm tpm0: A TPM error (2306) occurred attempting to create NULL primary

[Christoph Anton Mitterer]

On Wed, 2024-11-13 at 07:47 -0800, James Bottomley wrote:
> That could be more significant, especially with this in the log:
> 
> > Nov 13 12:33:06 heisenberg kernel: tpm tpm0: NULL Seed name
> > comparison failed
> > Nov 13 12:33:16 heisenberg kernel: tpm tpm0: NULL Seed name
> > comparison failed
> > Nov 13 12:33:26 heisenberg kernel: tpm tpm0: NULL Seed name
> > comparison failed
> 
> I think we might have to expect the NULL name to change on actual
> hibernation because unlike suspend to ram it does power off the TPM.
> 
> However, the code that causes the above message was also in 6.10 ...
> are you sure kernels 6.10 and beyond hibernate without producing this
> message?

Quite sure. At least the "flooding" wasn't the case, and `grep`ing some
older kernel logs (these should all be 6.11.5) I get:
$ zgrep tpm /var/log/kern.log.2.xz
2024-10-29T21:03:39.499295+01:00 heisenberg kernel: tpm_tis NTC0702:00: Ignoring error -5 while suspending
2024-10-30T14:23:34.460371+01:00 heisenberg kernel: tpm_tis NTC0702:00: Ignoring error -5 while suspending
2024-10-30T17:50:53.559651+01:00 heisenberg kernel: tpm_tis NTC0702:00: 2.0 TPM (device-id 0xFC, rev-id 1)
2024-10-31T14:28:10.449727+01:00 heisenberg kernel: tpm tpm0: NULL key integrity failure!
2024-10-31T14:28:10.529662+01:00 heisenberg kernel: tpm tpm0: NULL Seed name comparison failed
2024-10-31T14:28:10.529673+01:00 heisenberg kernel: tpm tpm0: NULL name has changed, disabling TPM due to interference
2024-10-31T19:52:23.385845+01:00 heisenberg kernel: tpm_tis NTC0702:00: Ignoring error -5 while suspending
2024-11-01T06:55:20.138812+01:00 heisenberg kernel: tpm_tis NTC0702:00: Ignoring error -5 while suspending
2024-11-01T15:41:22.428940+01:00 heisenberg kernel: tpm_tis NTC0702:00: Ignoring error -5 while suspending
2024-11-01T18:33:47.141633+01:00 heisenberg kernel: tpm_tis NTC0702:00: Ignoring error -5 while suspending
2024-11-01T22:28:13.469085+01:00 heisenberg kernel: tpm_tis NTC0702:00: Ignoring error -5 while suspending
2024-11-02T06:12:26.424367+01:00 heisenberg kernel: tpm_tis NTC0702:00: Ignoring error -5 while suspending

But this is probably anyway obsolete as Jarkko seems to have found the issue :-)


Cheers,
Chris.

Re: regression: kernel log "flooded" with tpm tpm0: A TPM error (2306) occurred attempting to create NULL primary

[Christoph Anton Mitterer]

On Wed, 2024-11-13 at 20:49 +0200, Jarkko Sakkinen wrote:
> The problem still persists related to TPM bus encryption not working
> with hibernate in 6.11.5 but the message was shown only once in the
> log (and thus you did not notice it).

At least my grep from before wouldn't have shown it even once.



> Please test my fix and I can take it to PR.

I've seen your PR was anyway already applied, so testing still needed?
I'd need to compile the whole Debian kernel which takes quite a while
O:-)


But other than that... and especially as I'm seeing these:
  2024-11-01T15:41:22.428940+01:00 heisenberg kernel: tpm_tis NTC0702:00: Ignoring error -5 while suspending
errors...

... I wondered whether that rings any bells on your side with respect
to: https://bugzilla.kernel.org/show_bug.cgi?id=216998

I short, ever since I got my current laptop, suspend2ram was broken,
that is per default I get:
# cat /sys/power/mem_sleep 
[s2idle] deep

and that "soft" suspend works (but there the CPU, keyboard, touchpad
and stuff is still on, drawing power and even the fan continues
running).

If I overwrite it to deep, I can go into suspend (or at least the
laptop actually does a real suspend2ram, but when I power on (here it
the really requires the power button, no longer only keyboard or
touchpad movement) the system immediately freezes and the screen
doesn't even light up.


Not a show stopper, but still quite annoying. Having looked around for
similar reports for quite a while I indeed found people indicating that
TPM might be the issue, but even with disabling TPM in the BIOS it
still fails.

So after all it might be just some broken Fujitsu firmware... but if
you'd have any idea what I could further try I'd be happy to hear about
it.


Thanks,
Chris.

PS: Thanks as well for the quick fix :-)

Re: regression: kernel log "flooded" with tpm tpm0: A TPM error (2306) occurred attempting to create NULL primary

[James Bottomley]

On Thu, 2024-11-14 at 00:56 +0100, Christoph Anton Mitterer wrote:
> On Wed, 2024-11-13 at 07:47 -0800, James Bottomley wrote:
> > That could be more significant, especially with this in the log:
> > 
> > > Nov 13 12:33:06 heisenberg kernel: tpm tpm0: NULL Seed name
> > > comparison failed
> > > Nov 13 12:33:16 heisenberg kernel: tpm tpm0: NULL Seed name
> > > comparison failed
> > > Nov 13 12:33:26 heisenberg kernel: tpm tpm0: NULL Seed name
> > > comparison failed
> > 
> > I think we might have to expect the NULL name to change on actual
> > hibernation because unlike suspend to ram it does power off the
> > TPM.
> > 
> > However, the code that causes the above message was also in 6.10
> > ...
> > are you sure kernels 6.10 and beyond hibernate without producing
> > this
> > message?
> 
> Quite sure. At least the "flooding" wasn't the case, and `grep`ing
> some
> older kernel logs (these should all be 6.11.5) I get:
> $ zgrep tpm /var/log/kern.log.2.xz
> 2024-10-29T21:03:39.499295+01:00 heisenberg kernel: tpm_tis
> NTC0702:00: Ignoring error -5 while suspending
> 2024-10-30T14:23:34.460371+01:00 heisenberg kernel: tpm_tis
> NTC0702:00: Ignoring error -5 while suspending
> 2024-10-30T17:50:53.559651+01:00 heisenberg kernel: tpm_tis
> NTC0702:00: 2.0 TPM (device-id 0xFC, rev-id 1)
> 2024-10-31T14:28:10.449727+01:00 heisenberg kernel: tpm tpm0: NULL
> key integrity failure!
> 2024-10-31T14:28:10.529662+01:00 heisenberg kernel: tpm tpm0: NULL
> Seed name comparison failed
> 2024-10-31T14:28:10.529673+01:00 heisenberg kernel: tpm tpm0: NULL
> name has changed, disabling TPM due to interference
> 2024-10-31T19:52:23.385845+01:00 heisenberg kernel: tpm_tis
> NTC0702:00: Ignoring error -5 while suspending
> 2024-11-01T06:55:20.138812+01:00 heisenberg kernel: tpm_tis
> NTC0702:00: Ignoring error -5 while suspending
> 2024-11-01T15:41:22.428940+01:00 heisenberg kernel: tpm_tis
> NTC0702:00: Ignoring error -5 while suspending
> 2024-11-01T18:33:47.141633+01:00 heisenberg kernel: tpm_tis
> NTC0702:00: Ignoring error -5 while suspending
> 2024-11-01T22:28:13.469085+01:00 heisenberg kernel: tpm_tis
> NTC0702:00: Ignoring error -5 while suspending
> 2024-11-02T06:12:26.424367+01:00 heisenberg kernel: tpm_tis
> NTC0702:00: Ignoring error -5 while suspending
> 
> But this is probably anyway obsolete as Jarkko seems to have found
> the issue :-)

Getting the TPM messages to quiet by disabling the chip fixes the
message spew, but it doesn't get you a working TPM chip back on resume.
I'll take a look at the hibernation path and see if I can see a hook we
can use to bring the TPM back.

Regards,

James
 

Re: regression: kernel log "flooded" with tpm tpm0: A TPM error (2306) occurred attempting to create NULL primary

[Christoph Anton Mitterer]

On Wed, 2024-11-13 at 18:06 -0800, James Bottomley wrote:
> 
> Getting the TPM messages to quiet by disabling the chip fixes the
> message spew, but it doesn't get you a working TPM chip back on
> resume.
> I'll take a look at the hibernation path and see if I can see a hook
> we
> can use to bring the TPM back.

Sure, but actually I don't use TPM anyway so for me the main point was
really just the nuisance of the repetitive log messages O:-)

Still, it would of course be nice if you get it properly running after
hibernation.

Thanks,
Chris

Re: regression: kernel log "flooded" with tpm tpm0: A TPM error (2306) occurred attempting to create NULL primary

[Jarkko Sakkinen]

On Thu Nov 14, 2024 at 2:04 AM EET, Christoph Anton Mitterer wrote:
> On Wed, 2024-11-13 at 20:49 +0200, Jarkko Sakkinen wrote:
> > The problem still persists related to TPM bus encryption not working
> > with hibernate in 6.11.5 but the message was shown only once in the
> > log (and thus you did not notice it).
>
> At least my grep from before wouldn't have shown it even once.
>
>
>
> > Please test my fix and I can take it to PR.
>
> I've seen your PR was anyway already applied, so testing still needed?
> I'd need to compile the whole Debian kernel which takes quite a while
> O:-)

It was too obvious and I wanted to bring that to 6.12 :-) It was
a mistake in my fix so was dead obvious.

>
>
> But other than that... and especially as I'm seeing these:
>   2024-11-01T15:41:22.428940+01:00 heisenberg kernel: tpm_tis NTC0702:00: Ignoring error -5 while suspending
> errors...
>
> ... I wondered whether that rings any bells on your side with respect
> to: https://bugzilla.kernel.org/show_bug.cgi?id=216998

So here's my proposal:

1. I added myself to the CC list.
2. Please add any additional comments from your response that might be
   missing as comment.

I look that as soon as I have time. First time I'm seeing this.

For anything TPM you can go ahead and CC me also in future... 

BR, Jarkko

Re: regression: kernel log "flooded" with tpm tpm0: A TPM error (2306) occurred attempting to create NULL primary

[Jarkko Sakkinen]

On Thu Nov 14, 2024 at 4:06 AM EET, James Bottomley wrote:
> Getting the TPM messages to quiet by disabling the chip fixes the
> message spew, but it doesn't get you a working TPM chip back on resume.
> I'll take a look at the hibernation path and see if I can see a hook we
> can use to bring the TPM back.

Fixing hibernate issue could not be done in the same patch as it is 
a different bug logically that I fixed. The hibernate bug pre-existed
in your original code.

So my fix was not about at all masking a bug, it was about fixing a
bug in my own previous fix. I.e. even you had a fix for hibernate, this
patch would have been needed separately.

BR, Jarkko

Re: regression: kernel log "flooded" with tpm tpm0: A TPM error (2306) occurred attempting to create NULL primary

[Jarkko Sakkinen]

On Thu Nov 14, 2024 at 4:17 AM EET, Christoph Anton Mitterer wrote:
> On Wed, 2024-11-13 at 18:06 -0800, James Bottomley wrote:
> > 
> > Getting the TPM messages to quiet by disabling the chip fixes the
> > message spew, but it doesn't get you a working TPM chip back on
> > resume.
> > I'll take a look at the hibernation path and see if I can see a hook
> > we
> > can use to bring the TPM back.
>
> Sure, but actually I don't use TPM anyway so for me the main point was
> really just the nuisance of the repetitive log messages O:-)
>
> Still, it would of course be nice if you get it properly running after
> hibernation.

Yeah, my point and fix was about denoting that there was actually
*logically* not one but two bugs, you can blame for the noise bug
:-)

Rare occasion but in this case it was for better that I caused the
noise bug so that we noticed hibernate having issue....

>
> Thanks,
> Chris

BR, Jarkko

Re: regression: kernel log "flooded" with tpm tpm0: A TPM error (2306) occurred attempting to create NULL primary

[Christoph Anton Mitterer]

Hey Jarkko.


On Thu, 2024-11-14 at 06:52 +0200, Jarkko Sakkinen wrote:
> It was too obvious and I wanted to bring that to 6.12 :-) It was
> a mistake in my fix so was dead obvious.

Since that is out anyway rather soonish, there's no need from my side
to get the fix into stable.

> > ... I wondered whether that rings any bells on your side with
> > respect
> > to: https://bugzilla.kernel.org/show_bug.cgi?id=216998
> 
> So here's my proposal:
> 
> 1. I added myself to the CC list.

:-)


> 2. Please add any additional comments from your response that might
> be
>    missing as comment.

Right now I don't really have any... mostly because I had no clue on
how to further debug it (the only thing that I could think of would be
having a look at any serial console output, but the laptop has no true
serial port anymore, so best I could do would be to attach some
USB/RS232 adapter, and whether that even loads before the system does
something is questionable)

If you have any ideas on what I can do to give more information, don't
hesitate to tell.

But as I've said... it might just be a bug/missing implementation in
the firmware and nothing from the kernel side.
Cause it really seems as if the display and CPU fan don't even power up
after resume.

So,... I'm happy if you have ideas... but don't waste too much of your
time on this! :-)

btw: Fujitsu support wasn't really helpful on this matter, once they
read Linux they basically said not-interested.


> I look that as soon as I have time. First time I'm seeing this.
> 
> For anything TPM you can go ahead and CC me also in future... 

Sure thanks :-)


Cheers,
Chris

Re: regression: kernel log "flooded" with tpm tpm0: A TPM error (2306) occurred attempting to create NULL primary

[Christoph Anton Mitterer]

Hey.

Just for confirmation:

The patch indeed fixed the repeated log messages after a resume from
hibernate :-)


Thanks again,
Chris.

Re: regression: kernel log "flooded" with tpm tpm0: A TPM error (2306) occurred attempting to create NULL primary

[Jarkko Sakkinen]

On Mon Nov 25, 2024 at 3:49 PM EET, Christoph Anton Mitterer wrote:
> Hey.
>
> Just for confirmation:
>
> The patch indeed fixed the repeated log messages after a resume from
> hibernate :-)
>
>
> Thanks again,
> Chris.

Awesome, thanks for informing!

BR, Jarkko