IMA fails to see TPM chip (rpi3, linaro optee)

IMA fails to see TPM chip (rpi3, linaro optee)

[Markku Savela]

[-- Attachment #1: Type: text/plain, Size: 976 bytes --]

Hi,

I'm experimenting with optee (linaro) on rpi3 and trying to use TPM chip 
(Letstrust/Infineon) with IMA. I seem to run into issue mentioned in

  https://www.spinics.net/lists/linux-integrity/msg01018.html

e.g., spi is not intialized early enough

[    4.007959] ima: No TPM chip found, activating TPM-bypass! (rc=-19)
[    5.240738] tpm_tis_spi spi0.1: 2.0 TPM (device-id 0x1B, rev-id 22)

However, after boot, tpm works just fine, it's just IMA not picking it 
up. Has this issue been solved (but not yet present in linaro kernel):

Linux 4.14.56-v8 #3 SMP PREEMPT Wed Feb 13 14:40:29 EET 2019 aarch64 
GNU/Linux.

Seeking hints how to proceed? Would picking tpm/spi or some other driver 
source from some newer kernel and drop into linaro source? Any hope of 
that helping?

I'm booting with config.txt:

enable_uart=1
dtparam=spi=on
dtoverlay=spi-bcm2835
dtoverlay=tpm-slb9670
kernel_address=0x02000000
device_tree_address=0x01000000

... attached the dmesg output.

[-- Attachment #2: dmesg.txt --]
[-- Type: text/plain, Size: 16545 bytes --]

[    0.000000] Booting Linux on physical CPU 0x0
[    0.000000] Linux version 4.14.56-v8 (msa@kone2) (gcc version 8.2.1 20180802 (GNU Toolchain for the A-profile Architecture 8.2-2018-08 (arm-rel-8.23))) #3 SMP PREEMPT Wed Feb 13 14:40:29 EET 2019
[    0.000000] Boot CPU: AArch64 Processor [410fd034]
[    0.000000] Machine model: Raspberry Pi 3 Model B Rev 1.2
[    0.000000] debug: ignoring loglevel setting.
[    0.000000] efi: Getting EFI parameters from FDT:
[    0.000000] efi: UEFI not found.
[    0.000000] cma: Reserved 8 MiB at 0x000000003a000000
[    0.000000] On node 0 totalpages: 241664
[    0.000000]   DMA zone: 3776 pages used for memmap
[    0.000000]   DMA zone: 0 pages reserved
[    0.000000]   DMA zone: 241664 pages, LIFO batch:31
[    0.000000] psci: probing for conduit method from DT.
[    0.000000] psci: PSCIv1.1 detected in firmware.
[    0.000000] psci: Using standard PSCI v0.2 function IDs
[    0.000000] psci: Trusted OS migration not required
[    0.000000] psci: SMC Calling Convention v1.1
[    0.000000] percpu: Embedded 22 pages/cpu @ffffffe13af78000 s50456 r8192 d31464 u90112
[    0.000000] pcpu-alloc: s50456 r8192 d31464 u90112 alloc=22*4096
[    0.000000] pcpu-alloc: [0] 0 [0] 1 [0] 2 [0] 3 
[    0.000000] Detected VIPT I-cache on CPU0
[    0.000000] CPU features: enabling workaround for ARM erratum 845719
[    0.000000] Built 1 zonelists, mobility grouping on.  Total pages: 237888
[    0.000000] Kernel command line: console=tty0 console=ttyS0,115200 root=/dev/nfs rw rootfstype=nfs nfsroot=192.168.1.5:/srv/nfs/rpi3,udp,vers=3 ip=192.168.1.100 smsc95xx.macaddr=b8:27:eb:c3:4e:dc ignore_loglevel dma.dmachans=0x7f35 rootwait 8250.nr_uarts=1 elevator=deadline fsck.repair=yes bcm2708_fb.fbwidth=1920 bcm2708_fb.fbheight=1080 vc_mem.mem_base=0x3ec00000 vc_mem.mem_size=0x40000000 dwc_otg.fiq_enable=0 dwc_otg.fiq_fsm_enable=0 dwc_otg.nak_holdoff=0
[    0.000000] PID hash table entries: 4096 (order: 3, 32768 bytes)
[    0.000000] Dentry cache hash table entries: 131072 (order: 8, 1048576 bytes)
[    0.000000] Inode-cache hash table entries: 65536 (order: 7, 524288 bytes)
[    0.000000] Memory: 891540K/966656K available (7100K kernel code, 898K rwdata, 4136K rodata, 2752K init, 690K bss, 66924K reserved, 8192K cma-reserved)
[    0.000000] Virtual kernel memory layout:
[    0.000000]     modules : 0xffffff8000000000 - 0xffffff8008000000   (   128 MB)
[    0.000000]     vmalloc : 0xffffff8008000000 - 0xffffffbebfff0000   (   250 GB)
[    0.000000]       .text : 0xffffff83fee80000 - 0xffffff83ff570000   (  7104 KB)
[    0.000000]     .rodata : 0xffffff83ff570000 - 0xffffff83ff980000   (  4160 KB)
[    0.000000]       .init : 0xffffff83ff980000 - 0xffffff83ffc30000   (  2752 KB)
[    0.000000]       .data : 0xffffff83ffc30000 - 0xffffff83ffd10a00   (   899 KB)
[    0.000000]        .bss : 0xffffff83ffd10a00 - 0xffffff83ffdbd5e8   (   691 KB)
[    0.000000]     fixed   : 0xffffffbefe7fb000 - 0xffffffbefec00000   (  4116 KB)
[    0.000000]     PCI I/O : 0xffffffbefee00000 - 0xffffffbeffe00000   (    16 MB)
[    0.000000]     vmemmap : 0xffffffbf00000000 - 0xffffffc000000000   (     4 GB maximum)
[    0.000000]               0xffffffbf84000000 - 0xffffffbf84ec0000   (    14 MB actual)
[    0.000000]     memory  : 0xffffffe100000000 - 0xffffffe13b000000   (   944 MB)
[    0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1
[    0.000000] ftrace: allocating 25847 entries in 101 pages
[    0.000000] Preemptible hierarchical RCU implementation.
[    0.000000] 	Tasks RCU enabled.
[    0.000000] NR_IRQS: 64, nr_irqs: 64, preallocated irqs: 0
[    0.000000] arch_timer: cp15 timer(s) running at 19.20MHz (phys).
[    0.000000] clocksource: arch_sys_counter: mask: 0xffffffffffffff max_cycles: 0x46d987e47, max_idle_ns: 440795202767 ns
[    0.000007] sched_clock: 56 bits at 19MHz, resolution 52ns, wraps every 4398046511078ns
[    0.000229] Console: colour dummy device 80x25
[    0.001270] console [tty0] enabled
[    0.001313] Calibrating delay loop (skipped), value calculated using timer frequency.. 38.40 BogoMIPS (lpj=19200)
[    0.001358] pid_max: default: 32768 minimum: 301
[    0.001511] Security Framework initialized
[    0.001745] Mount-cache hash table entries: 2048 (order: 2, 16384 bytes)
[    0.001791] Mountpoint-cache hash table entries: 2048 (order: 2, 16384 bytes)
[    0.002835] Disabling memory control group subsystem
[    0.007075] ASID allocator initialised with 32768 entries
[    0.009073] Hierarchical SRCU implementation.
[    0.011324] EFI services will not be available.
[    0.013139] smp: Bringing up secondary CPUs ...
[    1.065299] CPU1: failed to come online
[    1.065327] CPU1: failed in unknown state : 0x0
[    2.098311] CPU2: failed to come online
[    2.098339] CPU2: failed in unknown state : 0x0
[    3.131243] CPU3: failed to come online
[    3.131271] CPU3: failed in unknown state : 0x0
[    3.131337] smp: Brought up 1 node, 1 CPU
[    3.131361] SMP: Total of 1 processors activated.
[    3.131393] CPU features: detected feature: 32-bit EL0 Support
[    3.131421] CPU features: detected feature: Kernel page table isolation (KPTI)
[    3.133969] CPU: All CPU(s) started at EL2
[    3.134008] alternatives: patching kernel code
[    3.135012] devtmpfs: initialized
[    3.147738] random: get_random_u32 called from bucket_table_alloc+0x108/0x270 with crng_init=0
[    3.149318] Enabled cp15_barrier support
[    3.149352] Enabled setend support
[    3.149722] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns
[    3.149776] futex hash table entries: 1024 (order: 5, 131072 bytes)
[    3.150595] pinctrl core: initialized pinctrl subsystem
[    3.150812] DMI not present or invalid.
[    3.151182] NET: Registered protocol family 16
[    3.156102] cpuidle: using governor menu
[    3.156604] vdso: 2 pages (1 code @ ffffff83ff577000, 1 data @ ffffff83ffc34000)
[    3.156654] hw-breakpoint: found 6 breakpoint and 4 watchpoint registers.
[    3.158260] DMA: preallocated 256 KiB pool for atomic allocations
[    3.158400] Serial: AMBA PL011 UART driver
[    3.160935] bcm2835-mbox 3f00b880.mailbox: mailbox enabled
[    3.161603] uart-pl011 3f201000.serial: could not find pctldev for node /soc/gpio@7e200000/uart0_pins, deferring probe
[    3.199041] bcm2835-dma 3f007000.dma: DMA legacy API manager at ffffff800801d000, dmachans=0x1
[    3.200884] SCSI subsystem initialized
[    3.201156] usbcore: registered new interface driver usbfs
[    3.201246] usbcore: registered new interface driver hub
[    3.201438] usbcore: registered new device driver usb
[    3.201704] dmi: Firmware registration failed.
[    3.202657] raspberrypi-firmware soc:firmware: Attached to firmware from 2017-02-15 17:14
[    3.203705] raspberrypi-firmware soc:firmware: Get Throttled mailbox call failed
[    3.205245] clocksource: Switched to clocksource arch_sys_counter
[    3.303830] VFS: Disk quotas dquot_6.6.0
[    3.303959] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes)
[    3.304200] FS-Cache: Loaded
[    3.304466] CacheFiles: Loaded
[    3.314327] NET: Registered protocol family 2
[    3.315102] TCP established hash table entries: 8192 (order: 4, 65536 bytes)
[    3.315265] TCP bind hash table entries: 8192 (order: 5, 131072 bytes)
[    3.315491] TCP: Hash tables configured (established 8192 bind 8192)
[    3.315733] UDP hash table entries: 512 (order: 2, 16384 bytes)
[    3.315802] UDP-Lite hash table entries: 512 (order: 2, 16384 bytes)
[    3.316105] NET: Registered protocol family 1
[    3.318835] RPC: Registered named UNIX socket transport module.
[    3.318865] RPC: Registered udp transport module.
[    3.318887] RPC: Registered tcp transport module.
[    3.318909] RPC: Registered tcp NFSv4.1 backchannel transport module.
[    3.321740] hw perfevents: enabled with armv8_pmuv3 PMU driver, 7 counters available
[    3.323758] workingset: timestamp_bits=46 max_order=18 bucket_order=0
[    3.334692] FS-Cache: Netfs 'nfs' registered for caching
[    3.336521] NFS: Registering the id_resolver key type
[    3.336581] Key type id_resolver registered
[    3.336605] Key type id_legacy registered
[    3.339825] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 249)
[    3.341111] io scheduler noop registered
[    3.341140] io scheduler deadline registered (default)
[    3.341538] io scheduler cfq registered
[    3.341567] io scheduler mq-deadline registered
[    3.341593] io scheduler kyber registered
[    3.344793] BCM2708FB: allocated DMA memory fa050000
[    3.344852] BCM2708FB: allocated DMA channel 0 @ ffffff800801d000
[    3.389594] Console: switching to colour frame buffer device 240x67
[    3.411374] Serial: 8250/16550 driver, 1 ports, IRQ sharing enabled
[    3.413167] bcm2835-rng 3f104000.rng: hwrng registered
[    3.413528] vc-mem: phys_addr:0x00000000 mem_base=0x3ec00000 mem_size:0x40000000(1024 MiB)
[    3.414517] gpiomem-bcm2835 3f200000.gpiomem: Initialised: Registers at 0x3f200000
[    3.414842] cacheinfo: Unable to detect cache hierarchy for CPU 0
[    3.427738] brd: module loaded
[    3.439741] loop: module loaded
[    3.439849] Loading iSCSI transport class v2.0-870.
[    3.441983] spi-bcm2835 3f204000.spi: could not get clk: -517
[    3.442577] libphy: Fixed MDIO Bus: probed
[    3.442792] usbcore: registered new interface driver lan78xx
[    3.442974] usbcore: registered new interface driver smsc95xx
[    3.443107] dwc_otg: version 3.00a 10-AUG-2012 (platform bus)
[    3.443548] dwc_otg 3f980000.usb: base=0x08280000
[    3.644900] Core Release: 2.80a
[    3.644985] Setting default values for core params
[    3.645110] Finished setting default values for core params
[    3.845511] Using Buffer DMA mode
[    3.845592] Periodic Transfer Interrupt Enhancement - disabled
[    3.845710] Multiprocessor Interrupt Enhancement - disabled
[    3.845824] OTG VER PARAM: 0, OTG VER FLAG: 0
[    3.845926] Dedicated Tx FIFOs mode
[    3.846294] dwc_otg: Microframe scheduler enabled
[    3.846511] dwc_otg 3f980000.usb: DWC OTG Controller
[    3.846647] dwc_otg 3f980000.usb: new USB bus registered, assigned bus number 1
[    3.846828] dwc_otg 3f980000.usb: irq 41, io mem 0x00000000
[    3.846988] Init: Port Power? op_state=1
[    3.847076] Init: Power Port (0)
[    3.847424] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002
[    3.847566] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    3.847716] usb usb1: Product: DWC OTG Controller
[    3.847820] usb usb1: Manufacturer: Linux 4.14.56-v8 dwc_otg_hcd
[    3.847944] usb usb1: SerialNumber: 3f980000.usb
[    3.848775] hub 1-0:1.0: USB hub found
[    3.848907] hub 1-0:1.0: 1 port detected
[    3.849677] dwc_otg: FIQ disabled
[    3.849760] dwc_otg: NAK holdoff disabled
[    3.854312] dwc_otg: FIQ split-transaction FSM disabled
[    3.858934] Module dwc_common_port init
[    3.865118] usbcore: registered new interface driver usb-storage
[    3.869734] IR NEC protocol handler initialized
[    3.874277] IR RC5(x/sz) protocol handler initialized
[    3.878869] IR RC6 protocol handler initialized
[    3.883480] IR JVC protocol handler initialized
[    3.887945] IR Sony protocol handler initialized
[    3.892500] IR SANYO protocol handler initialized
[    3.897000] IR Sharp protocol handler initialized
[    3.901367] IR MCE Keyboard/mouse protocol handler initialized
[    3.905706] IR XMP protocol handler initialized
[    3.911017] bcm2835-wdt 3f100000.watchdog: Broadcom BCM2835 watchdog timer
[    3.915817] bcm2835-cpufreq: min=600000 max=1200000
[    3.920632] sdhci: Secure Digital Host Controller Interface driver
[    3.925120] sdhci: Copyright(c) Pierre Ossman
[    3.929951] mmc-bcm2835 3f300000.mmc: could not get clk, deferring probe
[    3.934771] sdhost-bcm2835 3f202000.mmc: could not get clk, deferring probe
[    3.939374] Error: Driver 'sdhost-bcm2835' is already registered, aborting...
[    3.943983] sdhci-pltfm: SDHCI platform and OF driver helper
[    3.955900] ledtrig-cpu: registered to indicate activity on CPUs
[    3.960784] hidraw: raw HID events driver (C) Jiri Kosina
[    3.965645] usbcore: registered new interface driver usbhid
[    3.970282] usbhid: USB HID core driver
[    3.974956] optee: probing for conduit method from DT.
[    3.983648] optee: initialized driver
[    3.988535] Initializing XFRM netlink socket
[    3.993143] NET: Registered protocol family 17
[    3.997787] Key type dns_resolver registered
[    4.003427] registered taskstats version 1
[    4.007959] ima: No TPM chip found, activating TPM-bypass! (rc=-19)
[    4.012534] ima: Allocated hash algorithm: sha1
[    4.025488] uart-pl011 3f201000.serial: cts_event_workaround enabled
[    4.030295] 3f201000.serial: ttyAMA0 at MMIO 0x3f201000 (irq = 72, base_baud = 0) is a PL011 rev2
[    4.036748] console [ttyS0] disabled
[    4.041456] 3f215040.serial: ttyS0 at MMIO 0x0 (irq = 151, base_baud = 31250000) is a 16550
[    5.213338] console [ttyS0] enabled
[    5.224692] Indeed it is in host mode hprt0 = 00021501
[    5.240738] tpm_tis_spi spi0.1: 2.0 TPM (device-id 0x1B, rev-id 22)
[    5.321486] mmc-bcm2835 3f300000.mmc: mmc_debug:0 mmc_debug2:0
[    5.332293] mmc-bcm2835 3f300000.mmc: DMA channel allocated
[    5.368298] sdhost: log_buf @ ffffff80080bd000 (fa044000)
[    5.398273] mmc1: queuing unknown CIS tuple 0x80 (2 bytes)
[    5.411451] mmc1: queuing unknown CIS tuple 0x80 (3 bytes)
[    5.423275] mmc1: queuing unknown CIS tuple 0x80 (3 bytes)
[    5.433552] usb 1-1: new high-speed USB device number 2 using dwc_otg
[    5.433709] mmc0: sdhost-bcm2835 loaded - DMA enabled (>1)
[    5.435556] of_cfs_init
[    5.435665] of_cfs_init: OK
[    5.435874] Indeed it is in host mode hprt0 = 00001101
[    5.535748] mmc1: queuing unknown CIS tuple 0x80 (7 bytes)
[    5.616321] mmc0: host does not support reading read-only switch, assuming write-enable
[    5.631216] mmc0: new high speed SDHC card at address 0001
[    5.642014] bounce: isa pool size: 16 pages
[    5.651306] mmcblk0: mmc0:0001 EB1QT 29.8 GiB
[    5.662334]  mmcblk0: p1 p2
[    5.669932] random: fast init done
[    5.681600] usb 1-1: New USB device found, idVendor=0424, idProduct=9514
[    5.693254] usb 1-1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[    5.705995] hub 1-1:1.0: USB hub found
[    5.714756] hub 1-1:1.0: 5 ports detected
[    5.762390] mmc1: new high speed SDIO card at address 0001
[    6.010274] usb 1-1.1: new high-speed USB device number 3 using dwc_otg
[    6.109698] usb 1-1.1: New USB device found, idVendor=0424, idProduct=ec00
[    6.121503] usb 1-1.1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[    6.136598] smsc95xx v1.0.6
[    6.190655] smsc95xx 1-1.1:1.0 eth0: register 'smsc95xx' at usb-3f980000.usb-1.1, smsc95xx USB 2.0 Ethernet, b8:27:eb:c3:4e:dc
[    6.506964] smsc95xx 1-1.1:1.0 eth0: hardware isn't capable of remote wakeup
[    7.552523] random: crng init done
[    8.090192] smsc95xx 1-1.1:1.0 eth0: link up, 100Mbps, full-duplex, lpa 0xC1E1
[    8.114275] IP-Config: Guessing netmask 255.255.255.0
[    8.124560] IP-Config: Complete:
[    8.133084]      device=eth0, hwaddr=b8:27:eb:c3:4e:dc, ipaddr=192.168.1.100, mask=255.255.255.0, gw=255.255.255.255
[    8.149199]      host=192.168.1.100, domain=, nis-domain=(none)
[    8.160506]      bootserver=255.255.255.255, rootserver=192.168.1.5, rootpath=
[    9.223898] VFS: Mounted root (nfs filesystem) on device 0:16.
[    9.236189] devtmpfs: mounted
[    9.250405] Freeing unused kernel memory: 2752K
[   10.612055] systemd[1]: System time before build time, advancing clock.
[   11.327120] NET: Registered protocol family 10
[   11.340597] Segment Routing with IPv6
[   11.377635] ip_tables: (C) 2000-2006 Netfilter Core Team
[   14.835459] systemd-journald[89]: Received request to flush runtime journal from PID 1
[   17.114963] vchiq: module is from the staging directory, the quality is unknown, you have been warned.
[   18.187428] vchiq: vchiq_init_state: slot_zero = ffffff8008772000, is_master = 0
[   21.101112] brcmfmac: brcmf_fw_map_chip_to_name: using brcm/brcmfmac43430-sdio.bin for chip 0x00a9a6(43430) rev 0x000001
[   21.122880] usbcore: registered new interface driver brcmfmac
[   21.154470] brcmfmac mmc1:0001:1: Direct firmware load for brcm/brcmfmac43430-sdio.bin failed with error -2
[   22.186565] brcmfmac: brcmf_sdio_htclk: HT Avail timeout (1000000): clkctl 0x50
[   23.212844] brcmfmac: brcmf_sdio_htclk: HT Avail timeout (1000000): clkctl 0x50

Re: IMA fails to see TPM chip (rpi3, linaro optee)

[Markku Savela]

On 18/02/2019 11:36, Markku Savela wrote:

>   https://www.spinics.net/lists/linux-integrity/msg01018.html
> 
> e.g., spi is not intialized early enough
> 
> [    4.007959] ima: No TPM chip found, activating TPM-bypass! (rc=-19)
> [    5.240738] tpm_tis_spi spi0.1: 2.0 TPM (device-id 0x1B, rev-id 22)

Oh, and I already have the self test disabled (in above), no effect...


diff --git a/drivers/char/tpm/tpm2-cmd.c b/drivers/char/tpm/tpm2-cmd.c
index 44a3d1623..7e61fc243 100644
--- a/drivers/char/tpm/tpm2-cmd.c
+++ b/drivers/char/tpm/tpm2-cmd.c
@@ -890,7 +890,7 @@ static int tpm2_do_selftest(struct tpm_chip *chip)

         loops = jiffies_to_msecs(duration) / delay_msec;

-       rc = tpm2_start_selftest(chip, true);
+       rc = tpm2_start_selftest(chip, false);
         if (rc)
                 return rc;

Re: IMA fails to see TPM chip (rpi3, linaro optee)

[Markku Savela]

No hints how to solve? Anybody?


> In addition to disabling the full selftest, I had to revert
> commit b76c8d5 ("clk-bcm2835: Read max core clock from firmware") in
> order for the TPM to initialize prior to IMA.

..also, cannot find above mentioned commit from (Torvalds) linux tree 
either. Something in in the integrity only?

Re: IMA fails to see TPM chip (rpi3, linaro optee)

[Markku Savela]

On 20/02/2019 10:14, Markku Savela wrote:
> No hints how to solve? Anybody?

I changed IMA to just ignore the tpm test in hope that TPM would be 
ready by the time IMA needs it -- no such luck, the "tpm2_probe", which 
triggers the manual start just comes too late. I could just force the 
manual startup earlier in boot, if I could figure out a proper place to 
put the function call...


[    4.008322] ima: Allocated hash algorithm: sha1
[    4.012820] ima: Error Communicating to TPM chip
[    4.017302] ima: Error Communicating to TPM chip
[    4.021763] ima: Error Communicating to TPM chip
[    4.026004] ima: Error Communicating to TPM chip
[    4.030295] ima: Error Communicating to TPM chip
[    4.034558] ima: Error Communicating to TPM chip
[    4.038766] ima: Error Communicating to TPM chip
[    4.042805] ima: Error Communicating to TPM chip
[    4.046951] ima: Error Communicating to TPM chip, result: -19
[    4.059431] uart-pl011 3f201000.serial: cts_event_workaround enabled
[    4.063766] 3f201000.serial: ttyAMA0 at MMIO 0x3f201000 (irq = 72, 
base_baud = 0) is a PL011 rev2
[    4.069963] console [ttyS0] disabled
[    4.074178] 3f215040.serial: ttyS0 at MMIO 0x0 (irq = 151, base_baud 
= 31250000) is a 16550
[    5.282479] console [ttyS0] enabled
[    5.293360] Indeed it is in host mode hprt0 = 00021501
[    5.308808] tpm2_probe cmd rc=256
[    5.322282] tpm_tis_spi spi0.1: 2.0 TPM (device-id 0x1B, rev-id 22)
[    5.358842] tpm tpm0: A TPM error (256) occurred continue selftest
[    5.378137] tpm tpm0: starting up the TPM manually


Earlier in boot there this "spi-bcm2835" notice. Is this the reason the 
probe gets delayed?

[    3.440240] Loading iSCSI transport class v2.0-870.
[    3.442267] spi-bcm2835 3f204000.spi: could not get clk: -517
[    3.442804] libphy: Fixed MDIO Bus: probed
[    3.443019] usbcore: registered new interface driver lan78xx
[

Re: IMA fails to see TPM chip (rpi3, linaro optee)

[Mimi Zohar]

[ Cc'ing Peter ]

On Thu, 2019-02-21 at 11:08 +0200, Markku Savela wrote:
> On 20/02/2019 10:14, Markku Savela wrote:
> > No hints how to solve? Anybody?
> 
> I changed IMA to just ignore the tpm test in hope that TPM would be 
> ready by the time IMA needs it -- no such luck, the "tpm2_probe", which 
> triggers the manual start just comes too late. I could just force the 
> manual startup earlier in boot, if I could figure out a proper place to 
> put the function call...
> 
> 
> [    4.008322] ima: Allocated hash algorithm: sha1
> [    4.012820] ima: Error Communicating to TPM chip
> [    4.017302] ima: Error Communicating to TPM chip
> [    4.021763] ima: Error Communicating to TPM chip
> [    4.026004] ima: Error Communicating to TPM chip
> [    4.030295] ima: Error Communicating to TPM chip
> [    4.034558] ima: Error Communicating to TPM chip
> [    4.038766] ima: Error Communicating to TPM chip
> [    4.042805] ima: Error Communicating to TPM chip
> [    4.046951] ima: Error Communicating to TPM chip, result: -19
> [    4.059431] uart-pl011 3f201000.serial: cts_event_workaround enabled
> [    4.063766] 3f201000.serial: ttyAMA0 at MMIO 0x3f201000 (irq = 72, 
> base_baud = 0) is a PL011 rev2
> [    4.069963] console [ttyS0] disabled
> [    4.074178] 3f215040.serial: ttyS0 at MMIO 0x0 (irq = 151, base_baud 
> = 31250000) is a 16550
> [    5.282479] console [ttyS0] enabled
> [    5.293360] Indeed it is in host mode hprt0 = 00021501
> [    5.308808] tpm2_probe cmd rc=256
> [    5.322282] tpm_tis_spi spi0.1: 2.0 TPM (device-id 0x1B, rev-id 22)
> [    5.358842] tpm tpm0: A TPM error (256) occurred continue selftest
> [    5.378137] tpm tpm0: starting up the TPM manually
> 
> 
> Earlier in boot there this "spi-bcm2835" notice. Is this the reason the 
> probe gets delayed?
> 
> [    3.440240] Loading iSCSI transport class v2.0-870.
> [    3.442267] spi-bcm2835 3f204000.spi: could not get clk: -517
> [    3.442804] libphy: Fixed MDIO Bus: probed
> [    3.443019] usbcore: registered new interface driver lan78xx
> [
> 

This problem was previously discussed here -
https://lore.kernel.org/linux-integrity/trinity-3e6c2430-417d-4eef-b06
7-e30d68592b4d-1506716047790@3c-app-gmx-bs69/

Mimi

Re: IMA fails to see TPM chip (rpi3, linaro optee)

[Markku Savela]

On 21/02/2019 14:49, Mimi Zohar wrote:
> This problem was previously discussed here -
> https://lore.kernel.org/linux-integrity/trinity-3e6c2430-417d-4eef-b06
> 7-e30d68592b4d-1506716047790@3c-app-gmx-bs69/

Yes, I've been reading that thread, but as git novice

> Right, for rpi-4.14.y kernel, reverting commit acddd39 ("clk-bcm2835:
> Read max core clock from firmware") allows the TPM to be initialized
> prior to IMA, but is probably not the right solution.

.. I'm not able to find this commit from linaro git (I don't know what 
command to use...).

Re: IMA fails to see TPM chip (rpi3, linaro optee)

[Markku Savela]

On 21/02/2019 15:17, Markku Savela wrote:
> 
>> Right, for rpi-4.14.y kernel, reverting commit acddd39 ("clk-bcm2835:
>> Read max core clock from firmware") allows the TPM to be initialized
>> prior to IMA, but is probably not the right solution.
> 
> .. I'm not able to find this commit from linaro git (I don't know what 
> command to use...).

...that is, the "obvious" one fails to produce anything usefull...


git show acddd39
fatal: ambiguous argument 'acddd39': unknown revision or path not in the 
working tree.
Use '--' to separate paths from revisions, like this:
'git <command> [<revision>...] -- [<file>...]'

...and have no idea how to fix it.

Re: IMA fails to see TPM chip (rpi3, linaro optee)

[Markku Savela]

[-- Attachment #1: Type: text/plain, Size: 1249 bytes --]

In case anyone is interested, I got IMA to accept TPM chip in my special 
case (linaro optee kernel) by changing

   clk-bcm2835.c: core_initcall -> susbsys_initcall
   raspberrypi.c: subsys_initcall -> core_initcall

At first check, the system seems to be ok. Maybe some combination of 
initcalls could work, but this is enough for me.

diff --git a/drivers/clk/bcm/clk-bcm2835.c b/drivers/clk/bcm/clk-bcm2835.c
index d6caac9c3..7cdd597f1 100644
--- a/drivers/clk/bcm/clk-bcm2835.c
+++ b/drivers/clk/bcm/clk-bcm2835.c
@@ -2330,7 +2330,7 @@ static int __init __bcm2835_clk_driver_init(void)
  {
         return platform_driver_register(&bcm2835_clk_driver);
  }
-core_initcall(__bcm2835_clk_driver_init);
+subsys_initcall(__bcm2835_clk_driver_init);

  MODULE_AUTHOR("Eric Anholt <eric@anholt.net>");
  MODULE_DESCRIPTION("BCM2835 clock driver");
diff --git a/drivers/firmware/raspberrypi.c b/drivers/firmware/raspberrypi.c
index a82819a78..dfa362e1c 100644
--- a/drivers/firmware/raspberrypi.c
+++ b/drivers/firmware/raspberrypi.c
@@ -457,7 +457,7 @@ static int __init rpi_firmware_init(void)
  out1:
         return ret;
  }
-subsys_initcall(rpi_firmware_init);
+core_initcall(rpi_firmware_init);

  static void __init rpi_firmware_exit(void)
  {

[-- Attachment #2: dmesg.txt --]
[-- Type: text/plain, Size: 16379 bytes --]

[    0.000000] Booting Linux on physical CPU 0x0
[    0.000000] Linux version 4.14.56-v8 (msa@kone2) (gcc version 8.2.1 20180802 (GNU Toolchain for the A-profile Architecture 8.2-2018-08 (arm-rel-8.23))) #34 SMP PREEMPT Tue Feb 26 09:59:46 EET 2019
[    0.000000] Boot CPU: AArch64 Processor [410fd034]
[    0.000000] Machine model: Raspberry Pi 3 Model B Rev 1.2
[    0.000000] debug: ignoring loglevel setting.
[    0.000000] efi: Getting EFI parameters from FDT:
[    0.000000] efi: UEFI not found.
[    0.000000] cma: Reserved 8 MiB at 0x000000003a000000
[    0.000000] On node 0 totalpages: 241664
[    0.000000]   DMA zone: 3776 pages used for memmap
[    0.000000]   DMA zone: 0 pages reserved
[    0.000000]   DMA zone: 241664 pages, LIFO batch:31
[    0.000000] psci: probing for conduit method from DT.
[    0.000000] psci: PSCIv1.1 detected in firmware.
[    0.000000] psci: Using standard PSCI v0.2 function IDs
[    0.000000] psci: Trusted OS migration not required
[    0.000000] psci: SMC Calling Convention v1.1
[    0.000000] percpu: Embedded 22 pages/cpu @ffffffdafaf78000 s50456 r8192 d31464 u90112
[    0.000000] pcpu-alloc: s50456 r8192 d31464 u90112 alloc=22*4096
[    0.000000] pcpu-alloc: [0] 0 [0] 1 [0] 2 [0] 3 
[    0.000000] Detected VIPT I-cache on CPU0
[    0.000000] CPU features: enabling workaround for ARM erratum 845719
[    0.000000] Built 1 zonelists, mobility grouping on.  Total pages: 237888
[    0.000000] Kernel command line: console=tty0 console=ttyS0,115200 root=/dev/nfs rw rootfstype=nfs nfsroot=192.168.1.5:/srv/nfs/rpi3,udp,vers=3 ip=192.168.1.100 smsc95xx.macaddr=b8:27:eb:c3:4e:dc ignore_loglevel dma.dmachans=0x7f35 rootwait 8250.nr_uarts=1 elevator=deadline fsck.repair=yes bcm2708_fb.fbwidth=1920 bcm2708_fb.fbheight=1080 vc_mem.mem_base=0x3ec00000 vc_mem.mem_size=0x40000000 dwc_otg.fiq_enable=0 dwc_otg.fiq_fsm_enable=0 dwc_otg.nak_holdoff=0
[    0.000000] PID hash table entries: 4096 (order: 3, 32768 bytes)
[    0.000000] Dentry cache hash table entries: 131072 (order: 8, 1048576 bytes)
[    0.000000] Inode-cache hash table entries: 65536 (order: 7, 524288 bytes)
[    0.000000] Memory: 891540K/966656K available (7100K kernel code, 898K rwdata, 4136K rodata, 2752K init, 690K bss, 66924K reserved, 8192K cma-reserved)
[    0.000000] Virtual kernel memory layout:
[    0.000000]     modules : 0xffffff8000000000 - 0xffffff8008000000   (   128 MB)
[    0.000000]     vmalloc : 0xffffff8008000000 - 0xffffffbebfff0000   (   250 GB)
[    0.000000]       .text : 0xffffff873c080000 - 0xffffff873c770000   (  7104 KB)
[    0.000000]     .rodata : 0xffffff873c770000 - 0xffffff873cb80000   (  4160 KB)
[    0.000000]       .init : 0xffffff873cb80000 - 0xffffff873ce30000   (  2752 KB)
[    0.000000]       .data : 0xffffff873ce30000 - 0xffffff873cf10a00   (   899 KB)
[    0.000000]        .bss : 0xffffff873cf10a00 - 0xffffff873cfbd5e8   (   691 KB)
[    0.000000]     fixed   : 0xffffffbefe7fb000 - 0xffffffbefec00000   (  4116 KB)
[    0.000000]     PCI I/O : 0xffffffbefee00000 - 0xffffffbeffe00000   (    16 MB)
[    0.000000]     vmemmap : 0xffffffbf00000000 - 0xffffffc000000000   (     4 GB maximum)
[    0.000000]               0xffffffbf6b000000 - 0xffffffbf6bec0000   (    14 MB actual)
[    0.000000]     memory  : 0xffffffdac0000000 - 0xffffffdafb000000   (   944 MB)
[    0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1
[    0.000000] ftrace: allocating 25847 entries in 101 pages
[    0.000000] Preemptible hierarchical RCU implementation.
[    0.000000] 	Tasks RCU enabled.
[    0.000000] NR_IRQS: 64, nr_irqs: 64, preallocated irqs: 0
[    0.000000] arch_timer: cp15 timer(s) running at 19.20MHz (phys).
[    0.000000] clocksource: arch_sys_counter: mask: 0xffffffffffffff max_cycles: 0x46d987e47, max_idle_ns: 440795202767 ns
[    0.000006] sched_clock: 56 bits at 19MHz, resolution 52ns, wraps every 4398046511078ns
[    0.000230] Console: colour dummy device 80x25
[    0.001273] console [tty0] enabled
[    0.001314] Calibrating delay loop (skipped), value calculated using timer frequency.. 38.40 BogoMIPS (lpj=19200)
[    0.001359] pid_max: default: 32768 minimum: 301
[    0.001509] Security Framework initialized
[    0.001742] Mount-cache hash table entries: 2048 (order: 2, 16384 bytes)
[    0.001788] Mountpoint-cache hash table entries: 2048 (order: 2, 16384 bytes)
[    0.002828] Disabling memory control group subsystem
[    0.007080] ASID allocator initialised with 32768 entries
[    0.009076] Hierarchical SRCU implementation.
[    0.011328] EFI services will not be available.
[    0.013142] smp: Bringing up secondary CPUs ...
[    1.065346] CPU1: failed to come online
[    1.065375] CPU1: failed in unknown state : 0x0
[    2.098358] CPU2: failed to come online
[    2.098385] CPU2: failed in unknown state : 0x0
[    3.131299] CPU3: failed to come online
[    3.131326] CPU3: failed in unknown state : 0x0
[    3.131393] smp: Brought up 1 node, 1 CPU
[    3.131417] SMP: Total of 1 processors activated.
[    3.131450] CPU features: detected feature: 32-bit EL0 Support
[    3.131478] CPU features: detected feature: Kernel page table isolation (KPTI)
[    3.133992] CPU: All CPU(s) started at EL2
[    3.134031] alternatives: patching kernel code
[    3.135051] devtmpfs: initialized
[    3.147773] random: get_random_u32 called from bucket_table_alloc+0x108/0x270 with crng_init=0
[    3.149355] Enabled cp15_barrier support
[    3.149388] Enabled setend support
[    3.149753] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns
[    3.149807] futex hash table entries: 1024 (order: 5, 131072 bytes)
[    3.150616] pinctrl core: initialized pinctrl subsystem
[    3.150843] DMI not present or invalid.
[    3.151212] NET: Registered protocol family 16
[    3.156129] cpuidle: using governor menu
[    3.156632] vdso: 2 pages (1 code @ ffffff873c777000, 1 data @ ffffff873ce34000)
[    3.156682] hw-breakpoint: found 6 breakpoint and 4 watchpoint registers.
[    3.158291] DMA: preallocated 256 KiB pool for atomic allocations
[    3.158432] Serial: AMBA PL011 UART driver
[    3.160824] bcm2835-mbox 3f00b880.mailbox: mailbox enabled
[    3.161505] uart-pl011 3f201000.serial: could not find pctldev for node /soc/gpio@7e200000/uart0_pins, deferring probe
[    3.164127] raspberrypi-firmware soc:firmware: Attached to firmware from 2017-02-15 17:14
[    3.165142] raspberrypi-firmware soc:firmware: Get Throttled mailbox call failed
[    3.202106] bcm2835-dma 3f007000.dma: DMA legacy API manager at ffffff800801d000, dmachans=0x1
[    3.203951] SCSI subsystem initialized
[    3.204221] usbcore: registered new interface driver usbfs
[    3.204305] usbcore: registered new interface driver hub
[    3.204505] usbcore: registered new device driver usb
[    3.204764] dmi: Firmware registration failed.
[    3.206300] clocksource: Switched to clocksource arch_sys_counter
[    3.304846] VFS: Disk quotas dquot_6.6.0
[    3.304973] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes)
[    3.305213] FS-Cache: Loaded
[    3.305480] CacheFiles: Loaded
[    3.315358] NET: Registered protocol family 2
[    3.316124] TCP established hash table entries: 8192 (order: 4, 65536 bytes)
[    3.316264] TCP bind hash table entries: 8192 (order: 5, 131072 bytes)
[    3.316501] TCP: Hash tables configured (established 8192 bind 8192)
[    3.316745] UDP hash table entries: 512 (order: 2, 16384 bytes)
[    3.316813] UDP-Lite hash table entries: 512 (order: 2, 16384 bytes)
[    3.317113] NET: Registered protocol family 1
[    3.319838] RPC: Registered named UNIX socket transport module.
[    3.319867] RPC: Registered udp transport module.
[    3.319890] RPC: Registered tcp transport module.
[    3.319912] RPC: Registered tcp NFSv4.1 backchannel transport module.
[    3.322756] hw perfevents: enabled with armv8_pmuv3 PMU driver, 7 counters available
[    3.324765] workingset: timestamp_bits=46 max_order=18 bucket_order=0
[    3.335738] FS-Cache: Netfs 'nfs' registered for caching
[    3.337574] NFS: Registering the id_resolver key type
[    3.337632] Key type id_resolver registered
[    3.337657] Key type id_legacy registered
[    3.340874] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 249)
[    3.342162] io scheduler noop registered
[    3.342191] io scheduler deadline registered (default)
[    3.342592] io scheduler cfq registered
[    3.342620] io scheduler mq-deadline registered
[    3.342647] io scheduler kyber registered
[    3.345835] BCM2708FB: allocated DMA memory fa050000
[    3.345896] BCM2708FB: allocated DMA channel 0 @ ffffff800801d000
[    3.390715] Console: switching to colour frame buffer device 240x67
[    3.413102] Serial: 8250/16550 driver, 1 ports, IRQ sharing enabled
[    3.414253] console [ttyS0] disabled
[    3.414460] 3f215040.serial: ttyS0 at MMIO 0x0 (irq = 151, base_baud = 31250000) is a 16550
[    4.216411] console [ttyS0] enabled
[    4.221282] bcm2835-rng 3f104000.rng: hwrng registered
[    4.226888] vc-mem: phys_addr:0x00000000 mem_base=0x3ec00000 mem_size:0x40000000(1024 MiB)
[    4.236214] gpiomem-bcm2835 3f200000.gpiomem: Initialised: Registers at 0x3f200000
[    4.244229] cacheinfo: Unable to detect cache hierarchy for CPU 0
[    4.263396] brd: module loaded
[    4.278387] loop: module loaded
[    4.281699] Loading iSCSI transport class v2.0-870.
[    4.301401] tpm_tis_spi spi0.1: 2.0 TPM (device-id 0x1B, rev-id 22)
[    4.320239] tpm tpm0: A TPM error (256) occurred continue selftest
[    4.326658] tpm tpm0: starting up the TPM manually
[    4.968311] libphy: Fixed MDIO Bus: probed
[    4.972698] usbcore: registered new interface driver lan78xx
[    4.978632] usbcore: registered new interface driver smsc95xx
[    4.984599] dwc_otg: version 3.00a 10-AUG-2012 (platform bus)
[    4.990843] dwc_otg 3f980000.usb: base=0x08290000
[    5.196990] Core Release: 2.80a
[    5.200313] Setting default values for core params
[    5.205337] Finished setting default values for core params
[    5.411399] Using Buffer DMA mode
[    5.414851] Periodic Transfer Interrupt Enhancement - disabled
[    5.420894] Multiprocessor Interrupt Enhancement - disabled
[    5.426675] OTG VER PARAM: 0, OTG VER FLAG: 0
[    5.431210] Dedicated Tx FIFOs mode
[    5.435110] dwc_otg: Microframe scheduler enabled
[    5.440112] dwc_otg 3f980000.usb: DWC OTG Controller
[    5.445313] dwc_otg 3f980000.usb: new USB bus registered, assigned bus number 1
[    5.452912] dwc_otg 3f980000.usb: irq 41, io mem 0x00000000
[    5.458769] Init: Port Power? op_state=1
[    5.462848] Init: Power Port (0)
[    5.466490] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002
[    5.473535] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    5.481025] usb usb1: Product: DWC OTG Controller
[    5.485907] usb usb1: Manufacturer: Linux 4.14.56-v8 dwc_otg_hcd
[    5.496956] usb usb1: SerialNumber: 3f980000.usb
[    5.507098] hub 1-0:1.0: USB hub found
[    5.515799] hub 1-0:1.0: 1 port detected
[    5.525149] dwc_otg: FIQ disabled
[    5.533270] dwc_otg: NAK holdoff disabled
[    5.542048] dwc_otg: FIQ split-transaction FSM disabled
[    5.552100] Module dwc_common_port init
[    5.562434] usbcore: registered new interface driver usb-storage
[    5.573412] IR NEC protocol handler initialized
[    5.582746] IR RC5(x/sz) protocol handler initialized
[    5.592566] IR RC6 protocol handler initialized
[    5.601793] IR JVC protocol handler initialized
[    5.611016] IR Sony protocol handler initialized
[    5.620208] IR SANYO protocol handler initialized
[    5.629628] IR Sharp protocol handler initialized
[    5.638942] IR MCE Keyboard/mouse protocol handler initialized
[    5.649400] IR XMP protocol handler initialized
[    5.659521] bcm2835-wdt 3f100000.watchdog: Broadcom BCM2835 watchdog timer
[    5.671363] bcm2835-cpufreq: min=600000 max=1200000
[    5.681428] sdhci: Secure Digital Host Controller Interface driver
[    5.692381] sdhci: Copyright(c) Pierre Ossman
[    5.701946] mmc-bcm2835 3f300000.mmc: mmc_debug:0 mmc_debug2:0
[    5.712619] mmc-bcm2835 3f300000.mmc: DMA channel allocated
[    5.742432] Indeed it is in host mode hprt0 = 00021501
[    5.816960] sdhost: log_buf @ ffffff8008095000 (fa044000)
[    5.844329] mmc1: queuing unknown CIS tuple 0x80 (2 bytes)
[    5.859370] mmc1: queuing unknown CIS tuple 0x80 (3 bytes)
[    5.871114] mmc1: queuing unknown CIS tuple 0x80 (3 bytes)
[    5.881328] mmc0: sdhost-bcm2835 loaded - DMA enabled (>1)
[    5.881513] Error: Driver 'sdhost-bcm2835' is already registered, aborting...
[    5.881519] sdhci-pltfm: SDHCI platform and OF driver helper
[    5.892356] ledtrig-cpu: registered to indicate activity on CPUs
[    5.892473] hidraw: raw HID events driver (C) Jiri Kosina
[    5.892641] usbcore: registered new interface driver usbhid
[    5.892645] usbhid: USB HID core driver
[    5.892686] optee: probing for conduit method from DT.
[    5.908487] optee: initialized driver
[    5.908817] Initializing XFRM netlink socket
[    5.908852] NET: Registered protocol family 17
[    5.908990] Key type dns_resolver registered
[    5.910209] registered taskstats version 1
[    5.932358] ima: Allocated hash algorithm: sha1
[    5.942857] usb 1-1: new high-speed USB device number 2 using dwc_otg
[    5.943024] Indeed it is in host mode hprt0 = 00001101
[    6.136012] mmc1: queuing unknown CIS tuple 0x80 (7 bytes)
[    6.146795] uart-pl011 3f201000.serial: cts_event_workaround enabled
[    6.157922] 3f201000.serial: ttyAMA0 at MMIO 0x3f201000 (irq = 72, base_baud = 0) is a PL011 rev2
[    6.173806] of_cfs_init
[    6.181027] of_cfs_init: OK
[    6.200598] usb 1-1: New USB device found, idVendor=0424, idProduct=9514
[    6.212067] usb 1-1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[    6.225277] hub 1-1:1.0: USB hub found
[    6.233775] hub 1-1:1.0: 5 ports detected
[    6.249428] mmc0: host does not support reading read-only switch, assuming write-enable
[    6.264155] mmc0: new high speed SDHC card at address 0001
[    6.274809] bounce: isa pool size: 16 pages
[    6.283907] mmcblk0: mmc0:0001 EB1QT 29.8 GiB
[    6.294645]  mmcblk0: p1 p2
[    6.315804] random: fast init done
[    6.378731] mmc1: new high speed SDIO card at address 0001
[    6.530324] usb 1-1.1: new high-speed USB device number 3 using dwc_otg
[    6.629734] usb 1-1.1: New USB device found, idVendor=0424, idProduct=ec00
[    6.641251] usb 1-1.1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[    6.656028] smsc95xx v1.0.6
[    6.709687] smsc95xx 1-1.1:1.0 eth0: register 'smsc95xx' at usb-3f980000.usb-1.1, smsc95xx USB 2.0 Ethernet, b8:27:eb:c3:4e:dc
[    7.274992] smsc95xx 1-1.1:1.0 eth0: hardware isn't capable of remote wakeup
[    8.070929] random: crng init done
[   11.482101] smsc95xx 1-1.1:1.0 eth0: link up, 100Mbps, full-duplex, lpa 0xC1E1
[   11.494322] IP-Config: Guessing netmask 255.255.255.0
[   11.494326] IP-Config: Complete:
[   11.494336]      device=eth0, hwaddr=b8:27:eb:c3:4e:dc, ipaddr=192.168.1.100, mask=255.255.255.0, gw=255.255.255.255
[   11.494344]      host=192.168.1.100, domain=, nis-domain=(none)
[   11.494350]      bootserver=255.255.255.255, rootserver=192.168.1.5, rootpath=
[   12.616961] VFS: Mounted root (nfs filesystem) on device 0:16.
[   12.628965] devtmpfs: mounted
[   12.643071] Freeing unused kernel memory: 2752K
[   13.703933] systemd[1]: System time before build time, advancing clock.
[   14.422920] NET: Registered protocol family 10
[   14.436185] Segment Routing with IPv6
[   14.473361] ip_tables: (C) 2000-2006 Netfilter Core Team
[   17.788411] systemd-journald[91]: Received request to flush runtime journal from PID 1
[   20.237446] vchiq: module is from the staging directory, the quality is unknown, you have been warned.
[   21.216994] vchiq: vchiq_init_state: slot_zero = ffffff80086a9000, is_master = 0
[   25.058521] brcmfmac: brcmf_fw_map_chip_to_name: using brcm/brcmfmac43430-sdio.bin for chip 0x00a9a6(43430) rev 0x000001
[   25.080017] usbcore: registered new interface driver brcmfmac
[   25.120788] brcmfmac mmc1:0001:1: Direct firmware load for brcm/brcmfmac43430-sdio.bin failed with error -2
[   26.207876] brcmfmac: brcmf_sdio_htclk: HT Avail timeout (1000000): clkctl 0x50
[   27.230516] brcmfmac: brcmf_sdio_htclk: HT Avail timeout (1000000): clkctl 0x50

Re: IMA fails to see TPM chip (rpi3, linaro optee)

[Mimi Zohar]

On Tue, 2019-02-26 at 10:12 +0200, Markku Savela wrote:
> In case anyone is interested, I got IMA to accept TPM chip in my special 
> case (linaro optee kernel) by changing
> 
>    clk-bcm2835.c: core_initcall -> susbsys_initcall
>    raspberrypi.c: subsys_initcall -> core_initcall
> 
> At first check, the system seems to be ok. Maybe some combination of 
> initcalls could work, but this is enough for me.

Thank you for sharing this!

Mimi

> 
> diff --git a/drivers/clk/bcm/clk-bcm2835.c b/drivers/clk/bcm/clk-bcm2835.c
> index d6caac9c3..7cdd597f1 100644
> --- a/drivers/clk/bcm/clk-bcm2835.c
> +++ b/drivers/clk/bcm/clk-bcm2835.c
> @@ -2330,7 +2330,7 @@ static int __init __bcm2835_clk_driver_init(void)
>   {
>          return platform_driver_register(&bcm2835_clk_driver);
>   }
> -core_initcall(__bcm2835_clk_driver_init);
> +subsys_initcall(__bcm2835_clk_driver_init);
> 
>   MODULE_AUTHOR("Eric Anholt <eric@anholt.net>");
>   MODULE_DESCRIPTION("BCM2835 clock driver");
> diff --git a/drivers/firmware/raspberrypi.c b/drivers/firmware/raspberrypi.c
> index a82819a78..dfa362e1c 100644
> --- a/drivers/firmware/raspberrypi.c
> +++ b/drivers/firmware/raspberrypi.c
> @@ -457,7 +457,7 @@ static int __init rpi_firmware_init(void)
>   out1:
>          return ret;
>   }
> -subsys_initcall(rpi_firmware_init);
> +core_initcall(rpi_firmware_init);
> 
>   static void __init rpi_firmware_exit(void)
>   {

Re: IMA fails to see TPM chip (rpi3, linaro optee)

[Ard Biesheuvel]

On Tue, 26 Feb 2019 at 13:14, Mimi Zohar <zohar@linux.ibm.com> wrote:
>
> On Tue, 2019-02-26 at 10:12 +0200, Markku Savela wrote:
> > In case anyone is interested, I got IMA to accept TPM chip in my special
> > case (linaro optee kernel) by changing
> >
> >    clk-bcm2835.c: core_initcall -> susbsys_initcall
> >    raspberrypi.c: subsys_initcall -> core_initcall
> >
> > At first check, the system seems to be ok. Maybe some combination of
> > initcalls could work, but this is enough for me.
>
> Thank you for sharing this!
>
> Mimi
>

Hi Mimi, Markku,

I am not sure why I am being cc'ed on this thread, or if there is
anything particular you would like my opinion on.

In general, having to juggle initcall ordering like this is horrid, so
while useful as a data point, I'd prefer fixing it properly instead.
I.e., if the firmware driver relies on a clock having been enabled,
this should be reflected in the DT, and supported in the firmware
driver by deferring the probe until the clock becomes available.



> >
> > diff --git a/drivers/clk/bcm/clk-bcm2835.c b/drivers/clk/bcm/clk-bcm2835.c
> > index d6caac9c3..7cdd597f1 100644
> > --- a/drivers/clk/bcm/clk-bcm2835.c
> > +++ b/drivers/clk/bcm/clk-bcm2835.c
> > @@ -2330,7 +2330,7 @@ static int __init __bcm2835_clk_driver_init(void)
> >   {
> >          return platform_driver_register(&bcm2835_clk_driver);
> >   }
> > -core_initcall(__bcm2835_clk_driver_init);
> > +subsys_initcall(__bcm2835_clk_driver_init);
> >
> >   MODULE_AUTHOR("Eric Anholt <eric@anholt.net>");
> >   MODULE_DESCRIPTION("BCM2835 clock driver");
> > diff --git a/drivers/firmware/raspberrypi.c b/drivers/firmware/raspberrypi.c
> > index a82819a78..dfa362e1c 100644
> > --- a/drivers/firmware/raspberrypi.c
> > +++ b/drivers/firmware/raspberrypi.c
> > @@ -457,7 +457,7 @@ static int __init rpi_firmware_init(void)
> >   out1:
> >          return ret;
> >   }
> > -subsys_initcall(rpi_firmware_init);
> > +core_initcall(rpi_firmware_init);
> >
> >   static void __init rpi_firmware_exit(void)
> >   {
>

Re: IMA fails to see TPM chip (rpi3, linaro optee)

[Mimi Zohar]

[Cc'ing Jarkko]

On Tue, 2019-02-26 at 13:38 +0100, Ard Biesheuvel wrote:
> On Tue, 26 Feb 2019 at 13:14, Mimi Zohar <zohar@linux.ibm.com> wrote:
> >
> > On Tue, 2019-02-26 at 10:12 +0200, Markku Savela wrote:
> > > In case anyone is interested, I got IMA to accept TPM chip in my special
> > > case (linaro optee kernel) by changing
> > >
> > >    clk-bcm2835.c: core_initcall -> susbsys_initcall
> > >    raspberrypi.c: subsys_initcall -> core_initcall
> > >
> > > At first check, the system seems to be ok. Maybe some combination of
> > > initcalls could work, but this is enough for me.
> >
> > Thank you for sharing this!
> >
> > Mimi
> >
> 
> Hi Mimi, Markku,
> 
> I am not sure why I am being cc'ed on this thread, or if there is
> anything particular you would like my opinion on.

Hi Ard, thank you for responding.  The clk not being initialized early
enough has been a problem for years.  Because of the clk not being
initialized, the TPM initialization is deferred, causing IMA to go
into TPM-bypass mode.

> 
> In general, having to juggle initcall ordering like this is horrid, so
> while useful as a data point, I'd prefer fixing it properly instead.
> I.e., if the firmware driver relies on a clock having been enabled,
> this should be reflected in the DT, and supported in the firmware
> driver by deferring the probe until the clock becomes available.

If a DT change could resolve this problem, that would be wonderful.

Mimi

> 
> 
> > >
> > > diff --git a/drivers/clk/bcm/clk-bcm2835.c b/drivers/clk/bcm/clk-bcm2835.c
> > > index d6caac9c3..7cdd597f1 100644
> > > --- a/drivers/clk/bcm/clk-bcm2835.c
> > > +++ b/drivers/clk/bcm/clk-bcm2835.c
> > > @@ -2330,7 +2330,7 @@ static int __init __bcm2835_clk_driver_init(void)
> > >   {
> > >          return platform_driver_register(&bcm2835_clk_driver);
> > >   }
> > > -core_initcall(__bcm2835_clk_driver_init);
> > > +subsys_initcall(__bcm2835_clk_driver_init);
> > >
> > >   MODULE_AUTHOR("Eric Anholt <eric@anholt.net>");
> > >   MODULE_DESCRIPTION("BCM2835 clock driver");
> > > diff --git a/drivers/firmware/raspberrypi.c b/drivers/firmware/raspberrypi.c
> > > index a82819a78..dfa362e1c 100644
> > > --- a/drivers/firmware/raspberrypi.c
> > > +++ b/drivers/firmware/raspberrypi.c
> > > @@ -457,7 +457,7 @@ static int __init rpi_firmware_init(void)
> > >   out1:
> > >          return ret;
> > >   }
> > > -subsys_initcall(rpi_firmware_init);
> > > +core_initcall(rpi_firmware_init);
> > >
> > >   static void __init rpi_firmware_exit(void)
> > >   {
> >
> 

Re: IMA fails to see TPM chip (rpi3, linaro optee)

[Jarkko Sakkinen]

On Tue, Feb 26, 2019 at 09:04:38AM -0500, Mimi Zohar wrote:
> Hi Ard, thank you for responding.  The clk not being initialized early
> enough has been a problem for years.  Because of the clk not being
> initialized, the TPM initialization is deferred, causing IMA to go
> into TPM-bypass mode.

I'd guess this is an SPI issue and not really something that TPM could
resolve? Please correct me if I'm wrong. I.e. SPI gets initialized after
IMA.

/Jarkko

Re: IMA fails to see TPM chip (rpi3, linaro optee)

[Mimi Zohar]

On Tue, 2019-02-26 at 20:09 +0200, Jarkko Sakkinen wrote:
> On Tue, Feb 26, 2019 at 09:04:38AM -0500, Mimi Zohar wrote:
> > Hi Ard, thank you for responding.  The clk not being initialized early
> > enough has been a problem for years.  Because of the clk not being
> > initialized, the TPM initialization is deferred, causing IMA to go
> > into TPM-bypass mode.
> 
> I'd guess this is an SPI issue and not really something that TPM could
> resolve? Please correct me if I'm wrong. I.e. SPI gets initialized after
> IMA.
> 

Peter's original post with some debugging is here:
https://lore.kernel.org/linux-integrity/trinity-3e6c2430-417d-4eef-b067-e30d68592b4d-1506716047790@3c-app-gmx-bs69/

Re: IMA fails to see TPM chip (rpi3, linaro optee)

[James Bottomley]

On Tue, 2019-02-26 at 07:14 -0500, Mimi Zohar wrote:
> On Tue, 2019-02-26 at 10:12 +0200, Markku Savela wrote:
> > In case anyone is interested, I got IMA to accept TPM chip in my
> > special 
> > case (linaro optee kernel) by changing
> > 
> >    clk-bcm2835.c: core_initcall -> susbsys_initcall
> >    raspberrypi.c: subsys_initcall -> core_initcall
> > 
> > At first check, the system seems to be ok. Maybe some combination
> > of initcalls could work, but this is enough for me.
> 
> Thank you for sharing this!

I've just had one of these on x86: a Dell Inspiron 7000 that I got for
my wife.  This is the dmesg:

cottony:~ # dmesg|grep -i tpm
[    0.000000] ACPI: TPM2 0x000000008A595160 000034 (v03 DELL   CBX3     00000001 AMI  00000000)
[    1.628559] ima: No TPM chip found, activating TPM-bypass! (rc=-19)

I haven't investigated what type of TPM this is yet, but I suspect the
bus is attaching after IMA activates.  The TPM works normally after
this.

James