Re: [Xen-devel] vTPM ownership problem

["Xu, Quan" <quan.xu@xxxxxxxxx>]

A tricky issue..

 

- CC vTPM maintainer.

- Go through your new log, and it looks correct.

- Check /sys/class/misc/tpm0/device/owned status.

- Check tss status

- Check __auto_start__ start service (i.e. Attestation) may take ownership, but the passwd is different from your input..

 

 

Quan

 

 

 

From: Zhenyang Feng [mailto:fengzhenyang2014@xxxxxxxxx]
Sent: Wednesday, September 23, 2015 7:01 AM
To: Xu, Quan
Cc: xen-devel@xxxxxxxxxxxxxxxxxxxx
Subject: Re: [Xen-devel] vTPM ownership problem

 

I cleared TPM hardware, resetted it and upgraded xen to 4.5.0. But the same problem still exists.

~# tpm_takeownership

Enter owner password: 

Confirm password: 

Enter SRK password: 

Confirm password: 

Tspi_TPM_TakeOwnership failed: 0x00002004 - layer=tcs, code=0004 (4), Internal software error

 

 

Here is my vtpmmgr / vtpm instance log.

 

 

vtpmmgr:

Xen Minimal OS!

  start_info: 0xea000(VA)

    nr_pages: 0x8000

  shared_inf: 0xdb49c000(MA)

     pt_base: 0xed000(VA)

nr_pt_frames: 0x5

    mfn_list: 0xaa000(VA)

   mod_start: 0x0(VA)

     mod_len: 0

       flags: 0x0

    cmd_line: 

       stack: 0x68d00-0x88d00

MM: Init

      _text: 0x0(VA)

     _etext: 0x44133(VA)

   _erodata: 0x50000(VA)

     _edata: 0x53380(VA)

stack start: 0x68d00(VA)

       _end: 0xa9340(VA)

  start_pfn: f5

    max_pfn: 8000

Mapping memory range 0x400000 - 0x8000000

setting 0x0-0x50000 readonly

skipped 0x1000

MM: Initialise page allocator for 133000(133000)-8000000(8000000)

MM: done

Demand map pfns at 8001000-2008001000.

Heap resides at 2008002000-4008002000.

Initialising timer interface

Initialising console ... done.

gnttab_table mapped at 0x8001000.

Initialising scheduler

Thread "Idle": pointer: 0x2008002050, stack: 0x180000

Thread "xenstore": pointer: 0x2008002800, stack: 0x190000

xenbus initialised on irq 1 mfn 0x122f20

Thread "shutdown": pointer: 0x2008002fb0, stack: 0x1a0000

main.c: dummy main: start_info=0x88e00

Thread "main": pointer: 0x2008003760, stack: 0x1b0000

"main" 

INFO[VTPM]: Starting vTPM manager domain

INFO[VTPM]: Option: Using tpm_tis driver

******************* BLKFRONT for device/vbd/768 **********

 

 

backend at /local/domain/0/backend/qdisk/1/768

Failed to read /local/domain/0/backend/qdisk/1/768/feature-barrier.

524288 sectors of 512 bytes

**************************

blk_open(device/vbd/768) -> 3

============= Init TPM BACK ================

Thread "tpmback-listener": pointer: 0x20080044b0, stack: 0x1c0000

============= Init TPM TIS Driver ==============

IOMEM Machine Base Address: FED40000

Enabled Localities: 0 

1.2 TPM (device-id=0x0 vendor-id = 104A rev-id = 4E)

TPM interface capabilities (0x15):

   Interrupt Level Low

   Locality Change Int Support

   Data Avail Int Support

Timeout b was adjusted to standard value.

tpm_tis_open() -> 4

INFO[TPM]: TPM_GetCapability

INFO[VTPM]: Hardware TPM:

INFO[VTPM]:  version: 1 2 8 8

INFO[VTPM]:  specLevel: 2

INFO[VTPM]:  errataRev: 2

INFO[VTPM]:  vendorID: STM 

INFO[VTPM]:  vendorSpecificSize: 0

INFO[VTPM]:  vendorSpecific: 

INFO[TPM]: TPM_GetCapability

INFO[TPM]: TPM_GetCapability

INFO[VTPM]: Flushing 1 handle(s) of type 2

INFO[TPM]: TPM_FlushSpecific

INFO[TPM]: TPM_GetCapability

INFO[TPM]: TPM_GetCapability

INFO[TPM]: TPM_GetCapability

INFO[TPM]: TPM_GetCapability

INFO[TPM]: TPM_GetRandom

INFO[TPM]: TPM_GetRandom

INFO[TPM]: TPM_OIAP

INFO[TPM]: Auth Session: 0x44c0f7 opened by TPM_OIAP.

INFO[TPM]: TPM_PCR_Read

INFO[TPM]: TPM_PCR_Read

INFO[TPM]: TPM_PCR_Read

INFO[TPM]: TPM_PCR_Read

INFO[TPM]: TPM_PCR_Read

INFO[TPM]: TPM_PCR_Read

INFO[TPM]: TPM_PCR_Read

INFO[TPM]: TPM_PCR_Read

INFO[TPM]: TPM_PCR_Read

INFO[TPM]: TPM_PCR_Read

INFO[TPM]: TPM_PCR_Read

INFO[TPM]: TPM_PCR_Read

INFO[TPM]: TPM_PCR_Read

INFO[TPM]: TPM_PCR_Read

INFO[TPM]: TPM_PCR_Read

INFO[TPM]: TPM_PCR_Read

INFO[TPM]: TPM_PCR_Read

INFO[TPM]: TPM_PCR_Read

INFO[TPM]: TPM_PCR_Read

INFO[TPM]: TPM_PCR_Read

INFO[TPM]: TPM_PCR_Read

INFO[TPM]: TPM_PCR_Read

INFO[TPM]: TPM_PCR_Read

INFO[TPM]: TPM_PCR_Read

TPM Manager - disk format 0

 root seal: 84; sector of 13: 3924

 root: 3200 v=528

 itree: 36; sector of 112: 4032

 group: 3560 v=3472 id=816 md=280

 group seal: 72; 5 in parent: 1860; sector of 13: 3904

 vtpm: 20+64; sector of 48: 4048

INFO[VTPM]: disk_read_sector 0

INFO[VTPM]: disk_read_sector 1

load_root_pre: n/n

INFO[VTPM]: Failed to read manager file. Assuming first time initialization.

INFO[TPM]: TPM_ReadPubek

INFO[TPM]: TPM_TakeOwnership

INFO[TPM]: TPM_DisablePubekRead

INFO[TPM]: TPM_OSAP

INFO[TPM]: Auth Session: 0xabc128 opened by TPM_OSAP.

INFO[TPM]: TPM_SaveState

INFO[VTPM]: Finished initialized new VTPM manager

INFO[TPM]: TPM_TerminateHandle

INFO[TPM]: Auth Session: 0xabc128 closed by TPM_TerminateHandle

INFO[VTPM]: Waiting for commands from vTPM's:

Tpmback:Info Frontend 2/0 connected

INFO[VTPM]: Passthrough: TPM_GetRandom

INFO[VTPM]: Waiting for commands from vTPM's:

INFO[VTPM]: Passthrough: TPM_GetRandom

INFO[VTPM]: Waiting for commands from vTPM's:

INFO[VTPM]: vtpmmgr_LoadHashKey

INFO[VTPM]: Waiting for commands from vTPM's:

INFO[VTPM]: vtpmmgr_SaveHashKey

SaveHashKey with unknown UUID=7740b63c-f6e3-4db2-a94c-9c5332609ad6 - creating in auth0 (f=1)

INFO[VTPM]: Waiting for commands from vTPM's:

INFO[VTPM]: vtpmmgr_SaveHashKey

INFO[VTPM]: Waiting for commands from vTPM's:

INFO[VTPM]: vtpmmgr_SaveHashKey

INFO[VTPM]: Waiting for commands from vTPM's:

INFO[VTPM]: vtpmmgr_SaveHashKey

INFO[VTPM]: Waiting for commands from vTPM's:

INFO[VTPM]: vtpmmgr_SaveHashKey

INFO[VTPM]: Waiting for commands from vTPM's:

INFO[VTPM]: vtpmmgr_SaveHashKey

INFO[VTPM]: Waiting for commands from vTPM's:

INFO[VTPM]: vtpmmgr_SaveHashKey

INFO[VTPM]: Waiting for commands from vTPM's:

INFO[VTPM]: vtpmmgr_SaveHashKey

INFO[VTPM]: Waiting for commands from vTPM's:

INFO[VTPM]: vtpmmgr_SaveHashKey

INFO[VTPM]: Waiting for commands from vTPM's:

INFO[VTPM]: vtpmmgr_SaveHashKey

INFO[VTPM]: Waiting for commands from vTPM's:

INFO[VTPM]: vtpmmgr_SaveHashKey

INFO[VTPM]: Waiting for commands from vTPM's:

INFO[VTPM]: vtpmmgr_SaveHashKey

INFO[VTPM]: Waiting for commands from vTPM's:

INFO[VTPM]: vtpmmgr_SaveHashKey

INFO[VTPM]: Waiting for commands from vTPM's:

INFO[VTPM]: vtpmmgr_SaveHashKey

INFO[VTPM]: Waiting for commands from vTPM's:

INFO[VTPM]: vtpmmgr_SaveHashKey

INFO[VTPM]: Waiting for commands from vTPM's:

INFO[VTPM]: vtpmmgr_SaveHashKey

INFO[VTPM]: Waiting for commands from vTPM's:

INFO[VTPM]: vtpmmgr_SaveHashKey

INFO[VTPM]: Waiting for commands from vTPM's:

INFO[VTPM]: vtpmmgr_SaveHashKey

INFO[VTPM]: Waiting for commands from vTPM's:

INFO[VTPM]: vtpmmgr_SaveHashKey

INFO[VTPM]: Waiting for commands from vTPM's:

INFO[VTPM]: vtpmmgr_SaveHashKey

INFO[VTPM]: Waiting for commands from vTPM's:

INFO[VTPM]: vtpmmgr_SaveHashKey

INFO[VTPM]: Waiting for commands from vTPM's:

INFO[VTPM]: vtpmmgr_SaveHashKey

INFO[VTPM]: Waiting for commands from vTPM's:

 

 

vtpm:

Xen Minimal OS!

  start_info: 0xf2000(VA)

    nr_pages: 0x800

  shared_inf: 0xdb49a000(MA)

     pt_base: 0xf5000(VA)

nr_pt_frames: 0x5

    mfn_list: 0xee000(VA)

   mod_start: 0x0(VA)

     mod_len: 0

       flags: 0x0

    cmd_line: 

       stack: 0xad540-0xcd540

MM: Init

      _text: 0x0(VA)

     _etext: 0x7f3c3(VA)

   _erodata: 0x95000(VA)

     _edata: 0x97bc0(VA)

stack start: 0xad540(VA)

       _end: 0xedb80(VA)

  start_pfn: fd

    max_pfn: 800

Mapping memory range 0x400000 - 0x800000

setting 0x0-0x95000 readonly

skipped 0x1000

MM: Initialise page allocator for ff000(ff000)-800000(800000)

MM: done

Demand map pfns at 801000-2000801000.

Heap resides at 2000802000-4000802000.

Initialising timer interface

Initialising console ... done.

gnttab_table mapped at 0x801000.

Initialising scheduler

Thread "Idle": pointer: 0x2000802050, stack: 0x110000

Thread "xenstore": pointer: 0x2000802800, stack: 0x120000

xenbus initialised on irq 1 mfn 0x1e0567

Thread "shutdown": pointer: 0x2000802fb0, stack: 0x130000

main.c: dummy main: start_info=0xcd640

Thread "main": pointer: 0x2000803760, stack: 0x140000

"main" 

vtpm.c:463: Info: starting TPM Emulator (1.2.0.7-475)

vtpm.c:395: Info: Startup mode is `clear'

vtpm.c:425: Info: All PCRs initialized to default values

vtpm.c:429: Info: TPM Maintenance Commands disabled

vtpm.c:439: Info: Log level set to (null)

============= Init TPM BACK ================

Thread "tpmback-listener": pointer: 0x2000804380, stack: 0x150000

============= Init TPM Front ================

Tpmfront:Info Waiting for backend connection..

Tpmfront:Info Backend Connected

Tpmfront:Info Initialization Completed successfully

vtpmblk.c:34: Info: Initializing persistent NVM storage

 

******************* BLKFRONT for device/vbd/768 **********

 

 

backend at /local/domain/0/backend/qdisk/2/768

Failed to read /local/domain/0/backend/qdisk/2/768/feature-barrier.

32768 sectors of 512 bytes

**************************

blk_open(device/vbd/768) -> 3

vtpm.c:210: Info: VTPM Initializing

 

tpm_cmd_handler.c:4187: Debug: tpm_emulator_init(1, 0x00000007)

vtpm_cmd.c:155: Info: Requesting Encryption key from backend

vtpm_cmd.c:164: Error: VTPM_LoadHashKey() failed with error code (3)

vtpm_cmd.c:175: Error: VTPM_LoadHashKey failed

tpm_data.c:122: Info: initializing TPM data to default values

tpm_startup.c:29: Info: TPM_Init()

tpm_testing.c:243: Info: TPM_SelfTestFull()

tpm_testing.c:39: Debug: tpm_test_prng()

tpm_testing.c:69: Debug: Monobit: 9962

tpm_testing.c:70: Debug: Poker:   13.6

tpm_testing.c:71: Debug: run_1:   2504, 2485

tpm_testing.c:72: Debug: run_2:   1217, 1274

tpm_testing.c:73: Debug: run_3:   643, 614

tpm_testing.c:74: Debug: run_4:   328, 336

tpm_testing.c:75: Debug: run_5:   165, 147

tpm_testing.c:76: Debug: run_6+:  146, 146

tpm_testing.c:77: Debug: run_34:  0

tpm_testing.c:111: Debug: tpm_test_sha1()

tpm_testing.c:157: Debug: tpm_test_hmac()

tpm_testing.c:184: Debug: tpm_test_rsa_EK()

tpm_testing.c:186: Debug: tpm_rsa_generate_key()

tpm_testing.c:191: Debug: testing endorsement key

tpm_testing.c:197: Debug: tpm_rsa_sign(RSA_SSA_PKCS1_SHA1)

tpm_testing.c:200: Debug: tpm_rsa_verify(RSA_SSA_PKCS1_SHA1)

tpm_testing.c:203: Debug: tpm_rsa_sign(RSA_SSA_PKCS1_DER)

tpm_testing.c:206: Debug: tpm_rsa_verify(RSA_SSA_PKCS1_DER)

tpm_testing.c:210: Debug: tpm_rsa_encrypt(RSA_ES_PKCSV15)

tpm_testing.c:214: Debug: tpm_rsa_decrypt(RSA_ES_PKCSV15)

tpm_testing.c:218: Debug: verify plain text

tpm_testing.c:221: Debug: tpm_rsa_encrypt(RSA_ES_OAEP_SHA1)

tpm_testing.c:225: Debug: tpm_rsa_decrypt(RSA_ES_OAEP_SHA1)

tpm_testing.c:229: Debug: verify plain text

tpm_testing.c:261: Info: Self-Test succeeded

tpm_startup.c:43: Info: TPM_Startup(1)

tpm_cmd_handler.c:4217: Debug: tpm_handle_command(0)

tpm_cmd_handler.c:3514: Debug: [TPM_TAG_RQU_COMMAND]

tpm_cmd_handler.c:3630: Debug: [TPM_ORD_GetCapability]

tpm_capability.c:697: Info: TPM_GetCapability()

tpm_capability.c:717: Debug: [TPM_CAP_PROPERTY]

tpm_capability.c:148: Debug: [TPM_CAP_PROP_TIS_TIMEOUT]

tpm_cmd_handler.c:4158: Info: TPM command succeeded

tpm_data.c:209: Debug: size of permanent data: 6963

vtpmblk.c:69: Debug: Begin Write data="" len=6992 slot=0 ssize=8388608

Tpmback:Info Frontend 3/0 connected

vtpmblk.c:88: Info: Wrote 6992 bytes to NVM persistent storage

vtpm_cmd.c:201: Info: Sending encryption key to backend

tpm_cmd_handler.c:4217: Debug: tpm_handle_command(0)

tpm_cmd_handler.c:3514: Debug: [TPM_TAG_RQU_COMMAND]

tpm_cmd_handler.c:3630: Debug: [TPM_ORD_GetCapability]

tpm_capability.c:697: Info: TPM_GetCapability()

tpm_capability.c:717: Debug: [TPM_CAP_PROPERTY]

tpm_capability.c:199: Debug: [TPM_CAP_PROP_DURATION]

tpm_cmd_handler.c:4158: Info: TPM command succeeded

tpm_data.c:209: Debug: size of permanent data: 6963

vtpmblk.c:69: Debug: Begin Write data="" len=6992 slot=1 ssize=8388608

vtpmblk.c:88: Info: Wrote 6992 bytes to NVM persistent storage

vtpm_cmd.c:201: Info: Sending encryption key to backend

tpm_cmd_handler.c:4217: Debug: tpm_handle_command(0)

tpm_cmd_handler.c:3514: Debug: [TPM_TAG_RQU_COMMAND]

tpm_cmd_handler.c:3880: Debug: [TPM_ORD_PCRRead]

tpm_integrity.c:58: Info: TPM_PCRRead()

tpm_cmd_handler.c:4158: Info: TPM command succeeded

tpm_data.c:209: Debug: size of permanent data: 6963

vtpmblk.c:69: Debug: Begin Write data="" len=6992 slot=0 ssize=8388608

vtpmblk.c:88: Info: Wrote 6992 bytes to NVM persistent storage

vtpm_cmd.c:201: Info: Sending encryption key to backend

tpm_cmd_handler.c:4217: Debug: tpm_handle_command(0)

tpm_cmd_handler.c:3514: Debug: [TPM_TAG_RQU_COMMAND]

tpm_cmd_handler.c:3880: Debug: [TPM_ORD_PCRRead]

tpm_integrity.c:58: Info: TPM_PCRRead()

tpm_cmd_handler.c:4158: Info: TPM command succeeded

tpm_data.c:209: Debug: size of permanent data: 6963

vtpmblk.c:69: Debug: Begin Write data="" len=6992 slot=1 ssize=8388608

vtpmblk.c:88: Info: Wrote 6992 bytes to NVM persistent storage

vtpm_cmd.c:201: Info: Sending encryption key to backend

tpm_cmd_handler.c:4217: Debug: tpm_handle_command(0)

tpm_cmd_handler.c:3514: Debug: [TPM_TAG_RQU_COMMAND]

tpm_cmd_handler.c:3880: Debug: [TPM_ORD_PCRRead]

tpm_integrity.c:58: Info: TPM_PCRRead()

tpm_cmd_handler.c:4158: Info: TPM command succeeded

tpm_data.c:209: Debug: size of permanent data: 6963

vtpmblk.c:69: Debug: Begin Write data="" len=6992 slot=0 ssize=8388608

vtpmblk.c:88: Info: Wrote 6992 bytes to NVM persistent storage

vtpm_cmd.c:201: Info: Sending encryption key to backend

tpm_cmd_handler.c:4217: Debug: tpm_handle_command(0)

tpm_cmd_handler.c:3514: Debug: [TPM_TAG_RQU_COMMAND]

tpm_cmd_handler.c:3880: Debug: [TPM_ORD_PCRRead]

tpm_integrity.c:58: Info: TPM_PCRRead()

tpm_cmd_handler.c:4158: Info: TPM command succeeded

tpm_data.c:209: Debug: size of permanent data: 6963

vtpmblk.c:69: Debug: Begin Write data="" len=6992 slot=1 ssize=8388608

vtpmblk.c:88: Info: Wrote 6992 bytes to NVM persistent storage

vtpm_cmd.c:201: Info: Sending encryption key to backend

tpm_cmd_handler.c:4217: Debug: tpm_handle_command(0)

tpm_cmd_handler.c:3514: Debug: [TPM_TAG_RQU_COMMAND]

tpm_cmd_handler.c:3880: Debug: [TPM_ORD_PCRRead]

tpm_integrity.c:58: Info: TPM_PCRRead()

tpm_cmd_handler.c:4158: Info: TPM command succeeded

tpm_data.c:209: Debug: size of permanent data: 6963

vtpmblk.c:69: Debug: Begin Write data="" len=6992 slot=0 ssize=8388608

vtpmblk.c:88: Info: Wrote 6992 bytes to NVM persistent storage

vtpm_cmd.c:201: Info: Sending encryption key to backend

tpm_cmd_handler.c:4217: Debug: tpm_handle_command(0)

tpm_cmd_handler.c:3514: Debug: [TPM_TAG_RQU_COMMAND]

tpm_cmd_handler.c:3880: Debug: [TPM_ORD_PCRRead]

tpm_integrity.c:58: Info: TPM_PCRRead()

tpm_cmd_handler.c:4158: Info: TPM command succeeded

tpm_data.c:209: Debug: size of permanent data: 6963

vtpmblk.c:69: Debug: Begin Write data="" len=6992 slot=1 ssize=8388608

vtpmblk.c:88: Info: Wrote 6992 bytes to NVM persistent storage

vtpm_cmd.c:201: Info: Sending encryption key to backend

tpm_cmd_handler.c:4217: Debug: tpm_handle_command(0)

tpm_cmd_handler.c:3514: Debug: [TPM_TAG_RQU_COMMAND]

tpm_cmd_handler.c:3880: Debug: [TPM_ORD_PCRRead]

tpm_integrity.c:58: Info: TPM_PCRRead()

tpm_cmd_handler.c:4158: Info: TPM command succeeded

tpm_data.c:209: Debug: size of permanent data: 6963

vtpmblk.c:69: Debug: Begin Write data="" len=6992 slot=0 ssize=8388608

vtpmblk.c:88: Info: Wrote 6992 bytes to NVM persistent storage

vtpm_cmd.c:201: Info: Sending encryption key to backend

tpm_cmd_handler.c:4217: Debug: tpm_handle_command(0)

tpm_cmd_handler.c:3514: Debug: [TPM_TAG_RQU_COMMAND]

tpm_cmd_handler.c:3880: Debug: [TPM_ORD_PCRRead]

tpm_integrity.c:58: Info: TPM_PCRRead()

tpm_cmd_handler.c:4158: Info: TPM command succeeded

tpm_data.c:209: Debug: size of permanent data: 6963

vtpmblk.c:69: Debug: Begin Write data="" len=6992 slot=1 ssize=8388608

vtpmblk.c:88: Info: Wrote 6992 bytes to NVM persistent storage

vtpm_cmd.c:201: Info: Sending encryption key to backend

tpm_cmd_handler.c:4217: Debug: tpm_handle_command(0)

tpm_cmd_handler.c:3514: Debug: [TPM_TAG_RQU_COMMAND]

tpm_cmd_handler.c:3880: Debug: [TPM_ORD_PCRRead]

tpm_integrity.c:58: Info: TPM_PCRRead()

tpm_cmd_handler.c:4158: Info: TPM command succeeded

tpm_data.c:209: Debug: size of permanent data: 6963

vtpmblk.c:69: Debug: Begin Write data="" len=6992 slot=0 ssize=8388608

vtpmblk.c:88: Info: Wrote 6992 bytes to NVM persistent storage

vtpm_cmd.c:201: Info: Sending encryption key to backend

tpm_cmd_handler.c:4217: Debug: tpm_handle_command(0)

tpm_cmd_handler.c:3514: Debug: [TPM_TAG_RQU_COMMAND]

tpm_cmd_handler.c:3875: Debug: [TPM_ORD_Extend]

tpm_integrity.c:39: Info: TPM_Extend()

tpm_cmd_handler.c:4158: Info: TPM command succeeded

tpm_data.c:209: Debug: size of permanent data: 6963

vtpmblk.c:69: Debug: Begin Write data="" len=6992 slot=1 ssize=8388608

vtpmblk.c:88: Info: Wrote 6992 bytes to NVM persistent storage

vtpm_cmd.c:201: Info: Sending encryption key to backend

tpm_cmd_handler.c:4217: Debug: tpm_handle_command(0)

tpm_cmd_handler.c:3514: Debug: [TPM_TAG_RQU_COMMAND]

tpm_cmd_handler.c:3630: Debug: [TPM_ORD_GetCapability]

tpm_capability.c:697: Info: TPM_GetCapability()

tpm_capability.c:778: Debug: [TPM_CAP_VERSION_VAL]

tpm_cmd_handler.c:4158: Info: TPM command succeeded

tpm_data.c:209: Debug: size of permanent data: 6963

vtpmblk.c:69: Debug: Begin Write data="" len=6992 slot=0 ssize=8388608

vtpmblk.c:88: Info: Wrote 6992 bytes to NVM persistent storage

vtpm_cmd.c:201: Info: Sending encryption key to backend

tpm_cmd_handler.c:4217: Debug: tpm_handle_command(0)

tpm_cmd_handler.c:3514: Debug: [TPM_TAG_RQU_COMMAND]

tpm_cmd_handler.c:3630: Debug: [TPM_ORD_GetCapability]

tpm_capability.c:697: Info: TPM_GetCapability()

tpm_capability.c:701: Debug: [TPM_CAP_ORD]

tpm_cmd_handler.c:4158: Info: TPM command succeeded

tpm_data.c:209: Debug: size of permanent data: 6963

vtpmblk.c:69: Debug: Begin Write data="" len=6992 slot=1 ssize=8388608

vtpmblk.c:88: Info: Wrote 6992 bytes to NVM persistent storage

vtpm_cmd.c:201: Info: Sending encryption key to backend

tpm_cmd_handler.c:4217: Debug: tpm_handle_command(0)

tpm_cmd_handler.c:3514: Debug: [TPM_TAG_RQU_COMMAND]

tpm_cmd_handler.c:3630: Debug: [TPM_ORD_GetCapability]

tpm_capability.c:697: Info: TPM_GetCapability()

tpm_capability.c:701: Debug: [TPM_CAP_ORD]

tpm_cmd_handler.c:4158: Info: TPM command succeeded

tpm_data.c:209: Debug: size of permanent data: 6963

vtpmblk.c:69: Debug: Begin Write data="" len=6992 slot=0 ssize=8388608

vtpmblk.c:88: Info: Wrote 6992 bytes to NVM persistent storage

vtpm_cmd.c:201: Info: Sending encryption key to backend

tpm_cmd_handler.c:4217: Debug: tpm_handle_command(0)

tpm_cmd_handler.c:3514: Debug: [TPM_TAG_RQU_COMMAND]

tpm_cmd_handler.c:3630: Debug: [TPM_ORD_GetCapability]

tpm_capability.c:697: Info: TPM_GetCapability()

tpm_capability.c:717: Debug: [TPM_CAP_PROPERTY]

tpm_capability.c:74: Debug: [TPM_CAP_PROP_PCR]

tpm_cmd_handler.c:4158: Info: TPM command succeeded

tpm_data.c:209: Debug: size of permanent data: 6963

vtpmblk.c:69: Debug: Begin Write data="" len=6992 slot=1 ssize=8388608

vtpmblk.c:88: Info: Wrote 6992 bytes to NVM persistent storage

vtpm_cmd.c:201: Info: Sending encryption key to backend

tpm_cmd_handler.c:4217: Debug: tpm_handle_command(0)

tpm_cmd_handler.c:3514: Debug: [TPM_TAG_RQU_COMMAND]

tpm_cmd_handler.c:3630: Debug: [TPM_ORD_GetCapability]

tpm_capability.c:697: Info: TPM_GetCapability()

tpm_capability.c:717: Debug: [TPM_CAP_PROPERTY]

tpm_capability.c:78: Debug: [TPM_CAP_PROP_DIR]

tpm_cmd_handler.c:4158: Info: TPM command succeeded

tpm_data.c:209: Debug: size of permanent data: 6963

vtpmblk.c:69: Debug: Begin Write data="" len=6992 slot=0 ssize=8388608

vtpmblk.c:88: Info: Wrote 6992 bytes to NVM persistent storage

vtpm_cmd.c:201: Info: Sending encryption key to backend

tpm_cmd_handler.c:4217: Debug: tpm_handle_command(0)

tpm_cmd_handler.c:3514: Debug: [TPM_TAG_RQU_COMMAND]

tpm_cmd_handler.c:3630: Debug: [TPM_ORD_GetCapability]

tpm_capability.c:697: Info: TPM_GetCapability()

tpm_capability.c:717: Debug: [TPM_CAP_PROPERTY]

tpm_capability.c:86: Debug: [TPM_CAP_PROP_KEYS]

tpm_cmd_handler.c:4158: Info: TPM command succeeded

tpm_data.c:209: Debug: size of permanent data: 6963

vtpmblk.c:69: Debug: Begin Write data="" len=6992 slot=1 ssize=8388608

vtpmblk.c:88: Info: Wrote 6992 bytes to NVM persistent storage

vtpm_cmd.c:201: Info: Sending encryption key to backend

tpm_cmd_handler.c:4217: Debug: tpm_handle_command(0)

tpm_cmd_handler.c:3514: Debug: [TPM_TAG_RQU_COMMAND]

tpm_cmd_handler.c:3630: Debug: [TPM_ORD_GetCapability]

tpm_capability.c:697: Info: TPM_GetCapability()

tpm_capability.c:717: Debug: [TPM_CAP_PROPERTY]

tpm_capability.c:82: Debug: [TPM_CAP_PROP_MANUFACTURER]

tpm_cmd_handler.c:4158: Info: TPM command succeeded

tpm_data.c:209: Debug: size of permanent data: 6963

vtpmblk.c:69: Debug: Begin Write data="" len=6992 slot=0 ssize=8388608

vtpmblk.c:88: Info: Wrote 6992 bytes to NVM persistent storage

vtpm_cmd.c:201: Info: Sending encryption key to backend

tpm_cmd_handler.c:4217: Debug: tpm_handle_command(0)

tpm_cmd_handler.c:3514: Debug: [TPM_TAG_RQU_COMMAND]

tpm_cmd_handler.c:3630: Debug: [TPM_ORD_GetCapability]

tpm_capability.c:697: Info: TPM_GetCapability()

tpm_capability.c:717: Debug: [TPM_CAP_PROPERTY]

tpm_capability.c:114: Debug: [TPM_CAP_PROP_MAX_AUTHSESS]

tpm_cmd_handler.c:4158: Info: TPM command succeeded

tpm_data.c:209: Debug: size of permanent data: 6963

vtpmblk.c:69: Debug: Begin Write data="" len=6992 slot=1 ssize=8388608

vtpmblk.c:88: Info: Wrote 6992 bytes to NVM persistent storage

vtpm_cmd.c:201: Info: Sending encryption key to backend

tpm_cmd_handler.c:4217: Debug: tpm_handle_command(0)

tpm_cmd_handler.c:3514: Debug: [TPM_TAG_RQU_COMMAND]

tpm_cmd_handler.c:3630: Debug: [TPM_ORD_GetCapability]

tpm_capability.c:697: Info: TPM_GetCapability()

tpm_capability.c:725: Debug: [TPM_CAP_KEY_HANDLE]

tpm_capability.c:319: Debug: [TPM_RT_KEY]

tpm_cmd_handler.c:4158: Info: TPM command succeeded

tpm_data.c:209: Debug: size of permanent data: 6963

vtpmblk.c:69: Debug: Begin Write data="" len=6992 slot=0 ssize=8388608

vtpmblk.c:88: Info: Wrote 6992 bytes to NVM persistent storage

vtpm_cmd.c:201: Info: Sending encryption key to backend

tpm_cmd_handler.c:4217: Debug: tpm_handle_command(0)

tpm_cmd_handler.c:3514: Debug: [TPM_TAG_RQU_COMMAND]

tpm_cmd_handler.c:3850: Debug: [TPM_ORD_ReadPubek]

tpm_credentials.c:130: Info: TPM_ReadPubek()

tpm_cmd_handler.c:4158: Info: TPM command succeeded

tpm_data.c:209: Debug: size of permanent data: 6963

vtpmblk.c:69: Debug: Begin Write data="" len=6992 slot=1 ssize=8388608

vtpmblk.c:88: Info: Wrote 6992 bytes to NVM persistent storage

vtpm_cmd.c:201: Info: Sending encryption key to backend

 

 

2015-09-21 16:42 GMT+02:00 Xu, Quan <quan.xu@xxxxxxxxx>:

There are 2 error information:

1. The following is misleading, but correct. So ignore it.
    ERROR[VTPM]: LoadKey failure: Unrecognized uuid! 405ffc60-6b15-48e0-921a-d6645db0be03
    ERROR[VTPM]: Failed to load key

2. This is maybe the problem:
ERROR[VTPM]: LoadKey failure: Unrecognized uuid! 405ffc60-6b15-48e0-921a-d6645db0be03
ERROR[VTPM]: Failed to load key
ERROR in vtpmmgr_LoadHashKey at vtpm_cmd_handler.c:78 code: TPM_BAD_PARAMETER.

....

Share 2 working cfg..

[vtpmmgr]
kernel="/usr/lib/xen/boot/vtpmmgr-stubdom.gz"
memory=128
disk=["file:/var/scale/vdisk/vmgr,hda,w"]
name="vtpmmgr"
iomem=["fed40,5"]


[Vtpm]
kernel="/usr/lib/xen/boot/vtpm-stubdom.gz"
memory=8
disk=["file:/var/scale/vdisk/vtpm0,hda,w"]
name="vtpm0"
vtpm=["backend=vtpmmgr,uuid=6bf5cf32-6c23-4cc7-98e5-398a645a0925"]



you can also clear TPM 1.2 hardware and reset it.
also you can upgrade to  xen 4.5.0,  which is much better than 4.3.0.




Quan






















From: Zhenyang Feng [mailto:fengzhenyang2014@xxxxxxxxx]
Sent: Sunday, September 20, 2015 7:41 PM
To: Xu, Quan
Cc: xen-devel@xxxxxxxxxxxxxxxxxxxx
Subject: Re: [Xen-devel] vTPM ownership problem

Hi Quan,

Thank you in advance. 

I have set  XSM_ENABLE ?=y in xen-4.3.0/Config.mk before install XEN. 

I remove the vtpmmgr / vtpm disk and build it again. But the problem still exists.

Here is vtpmmgr  / vtpm  instance log.  (Including executing tpm_takeownership in domU)


vtpmmgr:
Parsing config from /var/vtpmmgr.cfg
Daemon running with PID 2922
Xen Minimal OS!
  start_info: 0xa3000(VA)
    nr_pages: 0x1000
  shared_inf: 0xdb48d000(MA)
     pt_base: 0xa6000(VA)
nr_pt_frames: 0x5
    mfn_list: 0x9b000(VA)
   mod_start: 0x0(VA)
     mod_len: 0
       flags: 0x0
    cmd_line: 
  stack:      0x5a800-0x7a800
MM: Init
      _text: 0x0(VA)
     _etext: 0x3a284(VA)
   _erodata: 0x46000(VA)
     _edata: 0x48c60(VA)
stack start: 0x5a800(VA)
       _end: 0x9ae20(VA)
  start_pfn: ae
    max_pfn: 1000
Mapping memory range 0x400000 - 0x1000000
setting 0x0-0x46000 readonly
skipped 0x1000
MM: Initialise page allocator for b4000(b4000)-1000000(1000000)
MM: done
Demand map pfns at 1001000-2001001000.
Heap resides at 2001002000-4001002000.
Initialising timer interface
Initialising console ... done.
gnttab_table mapped at 0x1001000.
Initialising scheduler
Thread "Idle": pointer: 0x2001002050, stack: 0xd0000
Thread "xenstore": pointer: 0x2001002800, stack: 0xe0000
xenbus initialised on irq 1 mfn 0x1d0c98
Thread "shutdown": pointer: 0x2001002fb0, stack: 0xf0000
Dummy main: start_info=0x7a900
Thread "main": pointer: 0x2001003760, stack: 0x100000
"main" 
Shutting down ()
Shutdown requested: 3
Thread "shutdown" exited.
INFO[VTPM]: Starting vTPM manager domain
INFO[VTPM]: Option: Using tpm_tis driver
******************* BLKFRONT for device/vbd/768 **********


backend at /local/domain/0/backend/vbd/1/768
32768 sectors of 512 bytes
**************************
blk_open(device/vbd/768) -> 3
============= Init TPM BACK ================
Thread "tpmback-listener": pointer: 0x20010043f0, stack: 0xf0000
============= Init TPM TIS Driver ==============
IOMEM Machine Base Address: FED40000
Enabled Localities: 0 
1.2 TPM (device-id=0x0 vendor-id = 104A rev-id = 4E)
TPM interface capabilities (0x15):
        Interrupt Level Low
        Locality Change Int Support
        Data Avail Int Support
tpm_tis_open() -> 4
INFO[TPM]: TPM_GetCapability
INFO[VTPM]: Hardware TPM:
INFO[VTPM]:  version: 1 2 8 8
INFO[VTPM]:  specLevel: 2
INFO[VTPM]:  errataRev: 2
INFO[VTPM]:  vendorID: STM 
INFO[VTPM]:  vendorSpecificSize: 0
INFO[VTPM]:  vendorSpecific: 
INFO[TPM]: TPM_GetCapability
INFO[TPM]: TPM_GetCapability
INFO[VTPM]: Flushing 1 handle(s) of type 2
INFO[TPM]: TPM_FlushSpecific
INFO[TPM]: TPM_GetCapability
INFO[TPM]: TPM_GetCapability
INFO[TPM]: TPM_GetCapability
INFO[TPM]: TPM_GetCapability
INFO[TPM]: TPM_GetRandom
INFO[TPM]: TPM_GetRandom
INFO[TPM]: TPM_OIAP
INFO[TPM]: Auth Session: 0x1639a6 opened by TPM_OIAP.
INFO[VTPM]: Loading disk image header
ERROR[VTPM]: Invalid ID string in disk image!
ERROR[VTPM]: Failed to load manager data!
INFO[VTPM]: Failed to read manager file. Assuming first time initialization.
INFO[TPM]: TPM_ReadPubek
INFO[TPM]: TPM_TakeOwnership
INFO[TPM]: TPM_DisablePubekRead
INFO[TPM]: TPM_OSAP
INFO[TPM]: Auth Session: 0xb311d2 opened by TPM_OSAP.
INFO[TPM]: TPM_CreateWrapKey
INFO[TPM]: Auth Session: 0xb311d2 closed by TPM
INFO[TPM]: TPM_LoadKey
INFO[TPM]: Key Handle: 0x963a83 opened by TPM_LoadKey
INFO[TPM]: TPM_SaveState
INFO[VTPM]: Creating new disk image header
INFO[VTPM]: Saving root storage key..
INFO[VTPM]: Binding uuid table symmetric key..
INFO[TPM]: TPM_Bind
INFO[VTPM]: Saved new manager disk header.
INFO[VTPM]: Finished initialized new VTPM manager
INFO[VTPM]: Waiting for commands from vTPM's:
Tpmback:Info Frontend 2/0 connected
INFO[VTPM]: Passthrough: TPM_GetRandom
INFO[VTPM]: Waiting for commands from vTPM's:
INFO[VTPM]: Passthrough: TPM_GetRandom
INFO[VTPM]: Waiting for commands from vTPM's:
ERROR[VTPM]: LoadKey failure: Unrecognized uuid! 405ffc60-6b15-48e0-921a-d6645db0be03
ERROR[VTPM]: Failed to load key
ERROR in vtpmmgr_LoadHashKey at vtpm_cmd_handler.c:78 code: TPM_BAD_PARAMETER.
INFO[VTPM]: Waiting for commands from vTPM's:
INFO[VTPM]: Registered vtpm 405ffc60-6b15-48e0-921a-d6645db0be03
INFO[VTPM]: Generating a new symmetric key
INFO[VTPM]: Binding encrypted key
INFO[TPM]: TPM_Bind
INFO[VTPM]: Encrypting the uuid table
INFO[TPM]: TPM_Bind
INFO[VTPM]: Saved hash and key for vtpm 405ffc60-6b15-48e0-921a-d6645db0be03
INFO[VTPM]: Waiting for commands from vTPM's:
INFO[TPM]: TPM_Bind
INFO[VTPM]: Saved hash and key for vtpm 405ffc60-6b15-48e0-921a-d6645db0be03
INFO[VTPM]: Waiting for commands from vTPM's:
INFO[TPM]: TPM_Bind
INFO[VTPM]: Saved hash and key for vtpm 405ffc60-6b15-48e0-921a-d6645db0be03
INFO[VTPM]: Waiting for commands from vTPM's:
INFO[TPM]: TPM_Bind
INFO[VTPM]: Saved hash and key for vtpm 405ffc60-6b15-48e0-921a-d6645db0be03
INFO[VTPM]: Waiting for commands from vTPM's:
INFO[TPM]: TPM_Bind
INFO[VTPM]: Saved hash and key for vtpm 405ffc60-6b15-48e0-921a-d6645db0be03
INFO[VTPM]: Waiting for commands from vTPM's:
INFO[TPM]: TPM_Bind
INFO[VTPM]: Saved hash and key for vtpm 405ffc60-6b15-48e0-921a-d6645db0be03
INFO[VTPM]: Waiting for commands from vTPM's:
INFO[TPM]: TPM_Bind
INFO[VTPM]: Saved hash and key for vtpm 405ffc60-6b15-48e0-921a-d6645db0be03
INFO[VTPM]: Waiting for commands from vTPM's:
INFO[TPM]: TPM_Bind
INFO[VTPM]: Saved hash and key for vtpm 405ffc60-6b15-48e0-921a-d6645db0be03
INFO[VTPM]: Waiting for commands from vTPM's:
INFO[TPM]: TPM_Bind
INFO[VTPM]: Saved hash and key for vtpm 405ffc60-6b15-48e0-921a-d6645db0be03
INFO[VTPM]: Waiting for commands from vTPM's:
INFO[TPM]: TPM_Bind
INFO[VTPM]: Saved hash and key for vtpm 405ffc60-6b15-48e0-921a-d6645db0be03
INFO[VTPM]: Waiting for commands from vTPM's:
INFO[TPM]: TPM_Bind
INFO[VTPM]: Saved hash and key for vtpm 405ffc60-6b15-48e0-921a-d6645db0be03
INFO[VTPM]: Waiting for commands from vTPM's:
INFO[TPM]: TPM_Bind
INFO[VTPM]: Saved hash and key for vtpm 405ffc60-6b15-48e0-921a-d6645db0be03
INFO[VTPM]: Waiting for commands from vTPM's:
INFO[TPM]: TPM_Bind
INFO[VTPM]: Saved hash and key for vtpm 405ffc60-6b15-48e0-921a-d6645db0be03
INFO[VTPM]: Waiting for commands from vTPM's:
INFO[TPM]: TPM_Bind
INFO[VTPM]: Saved hash and key for vtpm 405ffc60-6b15-48e0-921a-d6645db0be03
INFO[VTPM]: Waiting for commands from vTPM's:
INFO[TPM]: TPM_Bind
INFO[VTPM]: Saved hash and key for vtpm 405ffc60-6b15-48e0-921a-d6645db0be03
INFO[VTPM]: Waiting for commands from vTPM's:
INFO[TPM]: TPM_Bind
INFO[VTPM]: Saved hash and key for vtpm 405ffc60-6b15-48e0-921a-d6645db0be03
INFO[VTPM]: Waiting for commands from vTPM's:
INFO[TPM]: TPM_Bind
INFO[VTPM]: Saved hash and key for vtpm 405ffc60-6b15-48e0-921a-d6645db0be03
INFO[VTPM]: Waiting for commands from vTPM's:
INFO[TPM]: TPM_Bind
INFO[VTPM]: Saved hash and key for vtpm 405ffc60-6b15-48e0-921a-d6645db0be03
INFO[VTPM]: Waiting for commands from vTPM's:
INFO[TPM]: TPM_Bind
INFO[VTPM]: Saved hash and key for vtpm 405ffc60-6b15-48e0-921a-d6645db0be03
INFO[VTPM]: Waiting for commands from vTPM's:
INFO[TPM]: TPM_Bind
INFO[VTPM]: Saved hash and key for vtpm 405ffc60-6b15-48e0-921a-d6645db0be03
INFO[VTPM]: Waiting for commands from vTPM's:
INFO[TPM]: TPM_Bind
INFO[VTPM]: Saved hash and key for vtpm 405ffc60-6b15-48e0-921a-d6645db0be03
INFO[VTPM]: Waiting for commands from vTPM's:
INFO[TPM]: TPM_Bind
INFO[VTPM]: Saved hash and key for vtpm 405ffc60-6b15-48e0-921a-d6645db0be03
INFO[VTPM]: Waiting for commands from vTPM's:



vtpm:
Daemon running with PID 3648
Xen Minimal OS!
  start_info: 0xf2000(VA)
    nr_pages: 0x800
  shared_inf: 0xdb48b000(MA)
     pt_base: 0xf5000(VA)
nr_pt_frames: 0x5
    mfn_list: 0xee000(VA)
   mod_start: 0x0(VA)
     mod_len: 0
       flags: 0x0
    cmd_line: 
  stack:      0xad220-0xcd220
MM: Init
      _text: 0x0(VA)
     _etext: 0x7f974(VA)
   _erodata: 0x95000(VA)
     _edata: 0x97aa0(VA)
stack start: 0xad220(VA)
       _end: 0xed840(VA)
  start_pfn: fd
    max_pfn: 800
Mapping memory range 0x400000 - 0x800000
setting 0x0-0x95000 readonly
skipped 0x1000
MM: Initialise page allocator for ff000(ff000)-800000(800000)
MM: done
Demand map pfns at 801000-2000801000.
Heap resides at 2000802000-4000802000.
Initialising timer interface
Initialising console ... done.
gnttab_table mapped at 0x801000.
Initialising scheduler
Thread "Idle": pointer: 0x2000802050, stack: 0x110000
Thread "xenstore": pointer: 0x2000802800, stack: 0x120000
xenbus initialised on irq 1 mfn 0x1f7b8c
Thread "shutdown": pointer: 0x2000802fb0, stack: 0x130000
Dummy main: start_info=0xcd320
Thread "main": pointer: 0x2000803760, stack: 0x140000
"main" 
Shutting down ()
Shutdown requested: 3
Thread "shutdown" exited.
vtpm.c:425: Info: starting TPM Emulator (1.2.0.7-475)
vtpm.c:357: Info: Startup mode is `clear'
vtpm.c:387: Info: All PCRs initialized to default values
vtpm.c:391: Info: TPM Maintenance Commands disabled
vtpm.c:401: Info: Log level set to (null)
============= Init TPM BACK ================
Thread "tpmback-listener": pointer: 0x2000802fb0, stack: 0x130000
============= Init TPM Front ================
Tpmfront:Info Waiting for backend connection..
Tpmfront:Info Backend Connected
Tpmfront:Info Initialization Completed successfully
vtpmblk.c:34: Info: Initializing persistent NVM storage

******************* BLKFRONT for device/vbd/768 **********


backend at /local/domain/0/backend/vbd/2/768
16384 sectors of 512 bytes
**************************
blk_open(device/vbd/768) -> 3
vtpm.c:175: Info: VTPM Initializing

tpm_cmd_handler.c:4113: Debug: tpm_emulator_init(1, 0x00000007)
vtpm_cmd.c:155: Info: Requesting Encryption key from backend
vtpm_cmd.c:164: Error: VTPM_LoadHashKey() failed with error code (3)
vtpm_cmd.c:175: Error: VTPM_LoadHashKey failed
tpm_data.c:120: Info: initializing TPM data to default values
tpm_startup.c:29: Info: TPM_Init()
tpm_testing.c:243: Info: TPM_SelfTestFull()
tpm_testing.c:39: Debug: tpm_test_prng()
tpm_testing.c:69: Debug: Monobit: 9994
tpm_testing.c:70: Debug: Poker:   19.3
tpm_testing.c:71: Debug: run_1:   2590, 2574
tpm_testing.c:72: Debug: run_2:   1227, 1206
tpm_testing.c:73: Debug: run_3:   599, 629
tpm_testing.c:74: Debug: run_4:   307, 339
tpm_testing.c:75: Debug: run_5:   167, 154
tpm_testing.c:76: Debug: run_6+:  157, 146
tpm_testing.c:77: Debug: run_34:  0
tpm_testing.c:111: Debug: tpm_test_sha1()
tpm_testing.c:157: Debug: tpm_test_hmac()
tpm_testing.c:184: Debug: tpm_test_rsa_EK()
tpm_testing.c:186: Debug: tpm_rsa_generate_key()
tpm_testing.c:191: Debug: testing endorsement key
tpm_testing.c:197: Debug: tpm_rsa_sign(RSA_SSA_PKCS1_SHA1)
tpm_testing.c:200: Debug: tpm_rsa_verify(RSA_SSA_PKCS1_SHA1)
tpm_testing.c:203: Debug: tpm_rsa_sign(RSA_SSA_PKCS1_DER)
tpm_testing.c:206: Debug: tpm_rsa_verify(RSA_SSA_PKCS1_DER)
tpm_testing.c:210: Debug: tpm_rsa_encrypt(RSA_ES_PKCSV15)
tpm_testing.c:214: Debug: tpm_rsa_decrypt(RSA_ES_PKCSV15)
tpm_testing.c:218: Debug: verify plain text
tpm_testing.c:221: Debug: tpm_rsa_encrypt(RSA_ES_OAEP_SHA1)
tpm_testing.c:225: Debug: tpm_rsa_decrypt(RSA_ES_OAEP_SHA1)
tpm_testing.c:229: Debug: verify plain text
tpm_testing.c:261: Info: Self-Test succeeded
tpm_startup.c:43: Info: TPM_Startup(1)
tpm_cmd_handler.c:4143: Debug: tpm_handle_command(0)
tpm_cmd_handler.c:3450: Debug: [TPM_TAG_RQU_COMMAND]
tpm_cmd_handler.c:3566: Debug: [TPM_ORD_GetCapability]
tpm_capability.c:697: Info: TPM_GetCapability()
tpm_capability.c:717: Debug: [TPM_CAP_PROPERTY]
tpm_capability.c:148: Debug: [TPM_CAP_PROP_TIS_TIMEOUT]
tpm_cmd_handler.c:4084: Info: TPM command succeeded
tpm_data.c:206: Debug: size of permanent data: 6963
vtpmblk.c:69: Debug: Begin Write data="" len=6992 slot=0 ssize=4194304
Tpmback:Info Frontend 3/0 connected
vtpmblk.c:88: Info: Wrote 6992 bytes to NVM persistent storage
vtpm_cmd.c:201: Info: Sending encryption key to backend
tpm_cmd_handler.c:4143: Debug: tpm_handle_command(0)
tpm_cmd_handler.c:3450: Debug: [TPM_TAG_RQU_COMMAND]
tpm_cmd_handler.c:3566: Debug: [TPM_ORD_GetCapability]
tpm_capability.c:697: Info: TPM_GetCapability()
tpm_capability.c:717: Debug: [TPM_CAP_PROPERTY]
tpm_capability.c:199: Debug: [TPM_CAP_PROP_DURATION]
tpm_cmd_handler.c:4084: Info: TPM command succeeded
tpm_data.c:206: Debug: size of permanent data: 6963
vtpmblk.c:69: Debug: Begin Write data="" len=6992 slot=1 ssize=4194304
vtpmblk.c:88: Info: Wrote 6992 bytes to NVM persistent storage
vtpm_cmd.c:201: Info: Sending encryption key to backend
tpm_cmd_handler.c:4143: Debug: tpm_handle_command(0)
tpm_cmd_handler.c:3450: Debug: [TPM_TAG_RQU_COMMAND]
tpm_cmd_handler.c:3816: Debug: [TPM_ORD_PCRRead]
tpm_integrity.c:58: Info: TPM_PCRRead()
tpm_cmd_handler.c:4084: Info: TPM command succeeded
tpm_data.c:206: Debug: size of permanent data: 6963
vtpmblk.c:69: Debug: Begin Write data="" len=6992 slot=0 ssize=4194304
vtpmblk.c:88: Info: Wrote 6992 bytes to NVM persistent storage
vtpm_cmd.c:201: Info: Sending encryption key to backend
tpm_cmd_handler.c:4143: Debug: tpm_handle_command(0)
tpm_cmd_handler.c:3450: Debug: [TPM_TAG_RQU_COMMAND]
tpm_cmd_handler.c:3816: Debug: [TPM_ORD_PCRRead]
tpm_integrity.c:58: Info: TPM_PCRRead()
tpm_cmd_handler.c:4084: Info: TPM command succeeded
tpm_data.c:206: Debug: size of permanent data: 6963
vtpmblk.c:69: Debug: Begin Write data="" len=6992 slot=1 ssize=4194304
vtpmblk.c:88: Info: Wrote 6992 bytes to NVM persistent storage
vtpm_cmd.c:201: Info: Sending encryption key to backend
tpm_cmd_handler.c:4143: Debug: tpm_handle_command(0)
tpm_cmd_handler.c:3450: Debug: [TPM_TAG_RQU_COMMAND]
tpm_cmd_handler.c:3816: Debug: [TPM_ORD_PCRRead]
tpm_integrity.c:58: Info: TPM_PCRRead()
tpm_cmd_handler.c:4084: Info: TPM command succeeded
tpm_data.c:206: Debug: size of permanent data: 6963
vtpmblk.c:69: Debug: Begin Write data="" len=6992 slot=0 ssize=4194304
vtpmblk.c:88: Info: Wrote 6992 bytes to NVM persistent storage
vtpm_cmd.c:201: Info: Sending encryption key to backend
tpm_cmd_handler.c:4143: Debug: tpm_handle_command(0)
tpm_cmd_handler.c:3450: Debug: [TPM_TAG_RQU_COMMAND]
tpm_cmd_handler.c:3816: Debug: [TPM_ORD_PCRRead]
tpm_integrity.c:58: Info: TPM_PCRRead()
tpm_cmd_handler.c:4084: Info: TPM command succeeded
tpm_data.c:206: Debug: size of permanent data: 6963
vtpmblk.c:69: Debug: Begin Write data="" len=6992 slot=1 ssize=4194304
vtpmblk.c:88: Info: Wrote 6992 bytes to NVM persistent storage
vtpm_cmd.c:201: Info: Sending encryption key to backend
tpm_cmd_handler.c:4143: Debug: tpm_handle_command(0)
tpm_cmd_handler.c:3450: Debug: [TPM_TAG_RQU_COMMAND]
tpm_cmd_handler.c:3816: Debug: [TPM_ORD_PCRRead]
tpm_integrity.c:58: Info: TPM_PCRRead()
tpm_cmd_handler.c:4084: Info: TPM command succeeded
tpm_data.c:206: Debug: size of permanent data: 6963
vtpmblk.c:69: Debug: Begin Write data="" len=6992 slot=0 ssize=4194304
vtpmblk.c:88: Info: Wrote 6992 bytes to NVM persistent storage
vtpm_cmd.c:201: Info: Sending encryption key to backend
tpm_cmd_handler.c:4143: Debug: tpm_handle_command(0)
tpm_cmd_handler.c:3450: Debug: [TPM_TAG_RQU_COMMAND]
tpm_cmd_handler.c:3816: Debug: [TPM_ORD_PCRRead]
tpm_integrity.c:58: Info: TPM_PCRRead()
tpm_cmd_handler.c:4084: Info: TPM command succeeded
tpm_data.c:206: Debug: size of permanent data: 6963
vtpmblk.c:69: Debug: Begin Write data="" len=6992 slot=1 ssize=4194304
vtpmblk.c:88: Info: Wrote 6992 bytes to NVM persistent storage
vtpm_cmd.c:201: Info: Sending encryption key to backend
tpm_cmd_handler.c:4143: Debug: tpm_handle_command(0)
tpm_cmd_handler.c:3450: Debug: [TPM_TAG_RQU_COMMAND]
tpm_cmd_handler.c:3816: Debug: [TPM_ORD_PCRRead]
tpm_integrity.c:58: Info: TPM_PCRRead()
tpm_cmd_handler.c:4084: Info: TPM command succeeded
tpm_data.c:206: Debug: size of permanent data: 6963
vtpmblk.c:69: Debug: Begin Write data="" len=6992 slot=0 ssize=4194304
vtpmblk.c:88: Info: Wrote 6992 bytes to NVM persistent storage
vtpm_cmd.c:201: Info: Sending encryption key to backend
tpm_cmd_handler.c:4143: Debug: tpm_handle_command(0)
tpm_cmd_handler.c:3450: Debug: [TPM_TAG_RQU_COMMAND]
tpm_cmd_handler.c:3816: Debug: [TPM_ORD_PCRRead]
tpm_integrity.c:58: Info: TPM_PCRRead()
tpm_cmd_handler.c:4084: Info: TPM command succeeded
tpm_data.c:206: Debug: size of permanent data: 6963
vtpmblk.c:69: Debug: Begin Write data="" len=6992 slot=1 ssize=4194304
vtpmblk.c:88: Info: Wrote 6992 bytes to NVM persistent storage
vtpm_cmd.c:201: Info: Sending encryption key to backend
tpm_cmd_handler.c:4143: Debug: tpm_handle_command(0)
tpm_cmd_handler.c:3450: Debug: [TPM_TAG_RQU_COMMAND]
tpm_cmd_handler.c:3816: Debug: [TPM_ORD_PCRRead]
tpm_integrity.c:58: Info: TPM_PCRRead()
tpm_cmd_handler.c:4084: Info: TPM command succeeded
tpm_data.c:206: Debug: size of permanent data: 6963
vtpmblk.c:69: Debug: Begin Write data="" len=6992 slot=0 ssize=4194304
vtpmblk.c:88: Info: Wrote 6992 bytes to NVM persistent storage
vtpm_cmd.c:201: Info: Sending encryption key to backend
tpm_cmd_handler.c:4143: Debug: tpm_handle_command(0)
tpm_cmd_handler.c:3450: Debug: [TPM_TAG_RQU_COMMAND]
tpm_cmd_handler.c:3811: Debug: [TPM_ORD_Extend]
tpm_integrity.c:39: Info: TPM_Extend()
tpm_cmd_handler.c:4084: Info: TPM command succeeded
tpm_data.c:206: Debug: size of permanent data: 6963
vtpmblk.c:69: Debug: Begin Write data="" len=6992 slot=1 ssize=4194304
vtpmblk.c:88: Info: Wrote 6992 bytes to NVM persistent storage
vtpm_cmd.c:201: Info: Sending encryption key to backend
tpm_cmd_handler.c:4143: Debug: tpm_handle_command(0)
tpm_cmd_handler.c:3450: Debug: [TPM_TAG_RQU_COMMAND]
tpm_cmd_handler.c:3566: Debug: [TPM_ORD_GetCapability]
tpm_capability.c:697: Info: TPM_GetCapability()
tpm_capability.c:778: Debug: [TPM_CAP_VERSION_VAL]
tpm_cmd_handler.c:4084: Info: TPM command succeeded
tpm_data.c:206: Debug: size of permanent data: 6963
vtpmblk.c:69: Debug: Begin Write data="" len=6992 slot=0 ssize=4194304
vtpmblk.c:88: Info: Wrote 6992 bytes to NVM persistent storage
vtpm_cmd.c:201: Info: Sending encryption key to backend
tpm_cmd_handler.c:4143: Debug: tpm_handle_command(0)
tpm_cmd_handler.c:3450: Debug: [TPM_TAG_RQU_COMMAND]
tpm_cmd_handler.c:3566: Debug: [TPM_ORD_GetCapability]
tpm_capability.c:697: Info: TPM_GetCapability()
tpm_capability.c:701: Debug: [TPM_CAP_ORD]
tpm_cmd_handler.c:4084: Info: TPM command succeeded
tpm_data.c:206: Debug: size of permanent data: 6963
vtpmblk.c:69: Debug: Begin Write data="" len=6992 slot=1 ssize=4194304
vtpmblk.c:88: Info: Wrote 6992 bytes to NVM persistent storage
vtpm_cmd.c:201: Info: Sending encryption key to backend
tpm_cmd_handler.c:4143: Debug: tpm_handle_command(0)
tpm_cmd_handler.c:3450: Debug: [TPM_TAG_RQU_COMMAND]
tpm_cmd_handler.c:3566: Debug: [TPM_ORD_GetCapability]
tpm_capability.c:697: Info: TPM_GetCapability()
tpm_capability.c:701: Debug: [TPM_CAP_ORD]
tpm_cmd_handler.c:4084: Info: TPM command succeeded
tpm_data.c:206: Debug: size of permanent data: 6963
vtpmblk.c:69: Debug: Begin Write data="" len=6992 slot=0 ssize=4194304
vtpmblk.c:88: Info: Wrote 6992 bytes to NVM persistent storage
vtpm_cmd.c:201: Info: Sending encryption key to backend
tpm_cmd_handler.c:4143: Debug: tpm_handle_command(0)
tpm_cmd_handler.c:3450: Debug: [TPM_TAG_RQU_COMMAND]
tpm_cmd_handler.c:3566: Debug: [TPM_ORD_GetCapability]
tpm_capability.c:697: Info: TPM_GetCapability()
tpm_capability.c:717: Debug: [TPM_CAP_PROPERTY]
tpm_capability.c:74: Debug: [TPM_CAP_PROP_PCR]
tpm_cmd_handler.c:4084: Info: TPM command succeeded
tpm_data.c:206: Debug: size of permanent data: 6963
vtpmblk.c:69: Debug: Begin Write data="" len=6992 slot=1 ssize=4194304
vtpmblk.c:88: Info: Wrote 6992 bytes to NVM persistent storage
vtpm_cmd.c:201: Info: Sending encryption key to backend
tpm_cmd_handler.c:4143: Debug: tpm_handle_command(0)
tpm_cmd_handler.c:3450: Debug: [TPM_TAG_RQU_COMMAND]
tpm_cmd_handler.c:3566: Debug: [TPM_ORD_GetCapability]
tpm_capability.c:697: Info: TPM_GetCapability()
tpm_capability.c:717: Debug: [TPM_CAP_PROPERTY]
tpm_capability.c:78: Debug: [TPM_CAP_PROP_DIR]
tpm_cmd_handler.c:4084: Info: TPM command succeeded
tpm_data.c:206: Debug: size of permanent data: 6963
vtpmblk.c:69: Debug: Begin Write data="" len=6992 slot=0 ssize=4194304
vtpmblk.c:88: Info: Wrote 6992 bytes to NVM persistent storage
vtpm_cmd.c:201: Info: Sending encryption key to backend
tpm_cmd_handler.c:4143: Debug: tpm_handle_command(0)
tpm_cmd_handler.c:3450: Debug: [TPM_TAG_RQU_COMMAND]
tpm_cmd_handler.c:3566: Debug: [TPM_ORD_GetCapability]
tpm_capability.c:697: Info: TPM_GetCapability()
tpm_capability.c:717: Debug: [TPM_CAP_PROPERTY]
tpm_capability.c:86: Debug: [TPM_CAP_PROP_KEYS]
tpm_cmd_handler.c:4084: Info: TPM command succeeded
tpm_data.c:206: Debug: size of permanent data: 6963
vtpmblk.c:69: Debug: Begin Write data="" len=6992 slot=1 ssize=4194304
vtpmblk.c:88: Info: Wrote 6992 bytes to NVM persistent storage
vtpm_cmd.c:201: Info: Sending encryption key to backend
tpm_cmd_handler.c:4143: Debug: tpm_handle_command(0)
tpm_cmd_handler.c:3450: Debug: [TPM_TAG_RQU_COMMAND]
tpm_cmd_handler.c:3566: Debug: [TPM_ORD_GetCapability]
tpm_capability.c:697: Info: TPM_GetCapability()
tpm_capability.c:717: Debug: [TPM_CAP_PROPERTY]
tpm_capability.c:82: Debug: [TPM_CAP_PROP_MANUFACTURER]
tpm_cmd_handler.c:4084: Info: TPM command succeeded
tpm_data.c:206: Debug: size of permanent data: 6963
vtpmblk.c:69: Debug: Begin Write data="" len=6992 slot=0 ssize=4194304
vtpmblk.c:88: Info: Wrote 6992 bytes to NVM persistent storage
vtpm_cmd.c:201: Info: Sending encryption key to backend
tpm_cmd_handler.c:4143: Debug: tpm_handle_command(0)
tpm_cmd_handler.c:3450: Debug: [TPM_TAG_RQU_COMMAND]
tpm_cmd_handler.c:3566: Debug: [TPM_ORD_GetCapability]
tpm_capability.c:697: Info: TPM_GetCapability()
tpm_capability.c:717: Debug: [TPM_CAP_PROPERTY]
tpm_capability.c:114: Debug: [TPM_CAP_PROP_MAX_AUTHSESS]
tpm_cmd_handler.c:4084: Info: TPM command succeeded
tpm_data.c:206: Debug: size of permanent data: 6963
vtpmblk.c:69: Debug: Begin Write data="" len=6992 slot=1 ssize=4194304
vtpmblk.c:88: Info: Wrote 6992 bytes to NVM persistent storage
vtpm_cmd.c:201: Info: Sending encryption key to backend
tpm_cmd_handler.c:4143: Debug: tpm_handle_command(0)
tpm_cmd_handler.c:3450: Debug: [TPM_TAG_RQU_COMMAND]
tpm_cmd_handler.c:3566: Debug: [TPM_ORD_GetCapability]
tpm_capability.c:697: Info: TPM_GetCapability()
tpm_capability.c:725: Debug: [TPM_CAP_KEY_HANDLE]
tpm_capability.c:319: Debug: [TPM_RT_KEY]
tpm_cmd_handler.c:4084: Info: TPM command succeeded
tpm_data.c:206: Debug: size of permanent data: 6963
vtpmblk.c:69: Debug: Begin Write data="" len=6992 slot=0 ssize=4194304
vtpmblk.c:88: Info: Wrote 6992 bytes to NVM persistent storage
vtpm_cmd.c:201: Info: Sending encryption key to backend
tpm_cmd_handler.c:4143: Debug: tpm_handle_command(0)
tpm_cmd_handler.c:3450: Debug: [TPM_TAG_RQU_COMMAND]
tpm_cmd_handler.c:3786: Debug: [TPM_ORD_ReadPubek]
tpm_credentials.c:130: Info: TPM_ReadPubek()
tpm_cmd_handler.c:4084: Info: TPM command succeeded
tpm_data.c:206: Debug: size of permanent data: 6963
vtpmblk.c:69: Debug: Begin Write data="" len=6992 slot=1 ssize=4194304
vtpmblk.c:88: Info: Wrote 6992 bytes to NVM persistent storage
vtpm_cmd.c:201: Info: Sending encryption key to backend

Best,
DearFuture

2015-09-16 8:15 GMT+02:00 Xu, Quan <quan.xu@xxxxxxxxx>:
1. For xen 4.3.0, youâd better enable XSM security module.
2. share your vtpmmgr  / vtpm  instance log.
3. Clear vtpm / vtpmmgr disk, do it again.
 
 
Quan
 
 
 
From: xen-devel-bounces@xxxxxxxxxxxxx [mailto:xen-devel-bounces@xxxxxxxxxxxxx] On Behalf Of Zhenyang Feng
Sent: Wednesday, September 09, 2015 4:40 AM
To: xen-devel@xxxxxxxxxxxxxxxxxxxx
Subject: [Xen-devel] vTPM ownership problem
 
Hello everyone, I need to use vTPM to finish a project but I encounter the same problem as http://lists.xenproject.org/archives/html/xen-devel/2015-06/msg03930.html
 
I followed the steps explained in https://mhsamsal.wordpress.com/2013/12/05/configuring-virtual-tpm-vtpm-for-xen-4-3-guest-virtual-machines/.
 
I'm running Ubuntu 14.04 as Dom0 on Dell. I compiled Xen 4.3.0 from source. After creating vtpmmgr and vtpm stubdoms, and DomU, I can invoke tpm_version as well as cat /sys/class/misc/tpm0/device/pcrs from DomU:
 
However, I cannot take ownership of vTPM and thus I fail to execute the commands required ownership of vTPM. When I invoke takeownership(I set SRK password to null) I get the following error:
 
 
root@tpm-guest:~# tpm_takeownership
Enter owner password: 
Confirm password: 
Enter SRK password: 
Confirm password: 
Tspi_TPM_TakeOwnership failed: 0x00002004 - layer=tcs, code=0004 (4), Internal software error
 
 
root@tpm-guest:~# tpm_takeownership -z -y -l debug
Tspi_Context_Create success
Tspi_Context_Connect success
Tspi_Context_GetTpmObject success
Tspi_GetPolicyObject success
Tspi_Policy_SetSecret success
Tspi_Context_CreateObject success
Tspi_GetPolicyObject success
Tspi_Policy_SetSecret success
Tspi_TPM_TakeOwnership failed: 0x00002004 - layer=tcs, code=0004 (4), Internal software error
Tspi_Context_CloseObject success
Tspi_Context_FreeMemory success
Tspi_Context_Close success
 
I have just upgraded to Ubuntu 15.04 as the reply said but get the same error again. Could you help me handle it? Thank you very much.
 
Best,
DearFuture
 
 

 

_______________________________________________
Xen-devel mailing list
Xen-devel@xxxxxxxxxxxxx
http://lists.xen.org/xen-devel