Bug 2171376 - tpm2_activatecredential fails with Error decrypting AIK
Summary: tpm2_activatecredential fails with Error decrypting AIK
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Fedora
Classification: Fedora
Component: tpm2-tools
Version: 38
Hardware: Unspecified
OS: Unspecified
unspecified
high
Target Milestone: ---
Assignee: Peter Robinson
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2023-02-20 08:33 UTC by Karel Srot
Modified: 2023-04-22 00:48 UTC (History)
5 users (show)

Fixed In Version: tpm2-tools-5.5-3.fc39 tpm2-tools-5.5-3.fc38
Clone Of:
Environment:
Last Closed: 2023-04-19 18:16:05 UTC
Type: Bug
Embargoed:


Attachments (Terms of Use)

Description Karel Srot 2023-02-20 08:33:43 UTC
Description of problem:

With tpm2-tools-5.5-1.fc38 keylime agent fails to run tpm2_activatecredential:

systemd[1]: Started keylime_agent.service - The Keylime compute agent.
keylime_agent[15085]: INFO:keylime.config:Reading configuration from ['/etc/keylime/logging.conf']
keylime_agent[15085]: 2023-02-19 19:00:12.692 - keylime.keylime.cmd_exec - DEBUG - Executing command "tpm2_startup --version"
keylime_agent[15085]: 2023-02-19 19:00:12.704 - keylime.tpm - INFO - TPM2-TOOLS Version: 5.5
keylime_agent[15085]: 2023-02-19 19:00:12.705 - keylime.cloudagent - WARNING - IMPORTANT: The Python agent is deprecated and will be removed with the next major release (7.0.0)!
keylime_agent[15085]: 2023-02-19 19:00:12.705 - keylime.cloudagent - WARNING -            Please migrate to the Rust based agent: https://github.com/keylime/rust-keylime/
keylime_agent[15085]: 2023-02-19 19:00:12.705 - keylime.cloudagent - WARNING - The configuration upgrade templates path /usr/share/keylime/templates does not exist
keylime_agent[15085]: 2023-02-19 19:00:12.705 - keylime.cloudagent - WARNING - Measurement list path /sys/kernel/security/tpm0/binary_bios_measurements not accessible by agent. Any attempt to instruct it to access this path - via "keylime_tenant" CLI - will result in agent process dying
keylime_agent[15085]: 2023-02-19 19:00:12.706 - keylime.config - INFO - Reading configuration from ['/etc/keylime/agent.conf']
keylime_agent[15085]: 2023-02-19 19:00:12.707 - keylime.config - INFO - Applied configuration snippets from /etc/keylime/agent.conf.d
keylime_agent[15085]: 2023-02-19 19:00:12.707 - keylime.secure_mount - DEBUG - Secure storage location /var/lib/keylime/secure already mounted on tmpfs
keylime_agent[15085]: 2023-02-19 19:00:12.710 - keylime.cloudagent - INFO - Dropped privileges to keylime:tss
keylime_agent[15085]: 2023-02-19 19:00:12.710 - keylime.keylime.cmd_exec - DEBUG - Executing command "tpm2_getcap properties-fixed"
keylime_agent[15085]: 2023-02-19 19:00:12.730 - keylime.tpm - WARNING - INSECURE: Keylime is using a software TPM emulator rather than a real hardware TPM.
keylime_agent[15085]: 2023-02-19 19:00:12.730 - keylime.tpm - WARNING - INSECURE: The security of Keylime is currently NOT linked to a hardware root of trust.
keylime_agent[15085]: 2023-02-19 19:00:12.730 - keylime.tpm - WARNING - INSECURE: Only use Keylime in this mode for testing or debugging purposes.
keylime_agent[15085]: 2023-02-19 19:00:12.730 - keylime.keylime.cmd_exec - DEBUG - Executing command "tpm2_startup -c"
keylime_agent[15085]: 2023-02-19 19:00:12.747 - keylime.keylime.cmd_exec - DEBUG - Executing command "tpm2_getcap algorithms"
keylime_agent[15085]: 2023-02-19 19:00:12.769 - keylime.keylime.cmd_exec - DEBUG - Executing command "tpm2_getcap pcrs"
keylime_agent[15085]: 2023-02-19 19:00:12.787 - keylime.tpm - INFO - Taking ownership with config provided TPM owner password
keylime_agent[15085]: 2023-02-19 19:00:12.787 - keylime.tpm - DEBUG - Removing all saved sessions from TPM
keylime_agent[15085]: 2023-02-19 19:00:12.787 - keylime.keylime.cmd_exec - DEBUG - Executing command "tpm2_flushcontext -s"
keylime_agent[15085]: 2023-02-19 19:00:12.803 - keylime.keylime.cmd_exec - DEBUG - Executing command "tpm2_changeauth -c o keylime"
keylime_agent[15085]: 2023-02-19 19:00:12.837 - keylime.keylime.cmd_exec - DEBUG - Executing command "tpm2_changeauth -c e keylime"
keylime_agent[15085]: 2023-02-19 19:00:12.870 - keylime.tpm - INFO - TPM Owner password confirmed: keylime
keylime_agent[15085]: 2023-02-19 19:00:12.870 - keylime.tpm - INFO - Flushing old ek handle: 0x81000000
keylime_agent[15085]: 2023-02-19 19:00:12.870 - keylime.keylime.cmd_exec - DEBUG - Executing command "tpm2_getcap handles-persistent"
keylime_agent[15085]: 2023-02-19 19:00:12.887 - keylime.keylime.cmd_exec - DEBUG - Executing command "tpm2_createek -c - -G rsa -u /tmp/tmp6rjo4m00 -w keylime -P keylime"
keylime_agent[15085]: 2023-02-19 19:00:13.014 - keylime.keylime.cmd_exec - DEBUG - Executing command "tpm2_flushcontext -t"
keylime_agent[15085]: 2023-02-19 19:00:13.030 - keylime.keylime.cmd_exec - DEBUG - Executing command "tpm2_readpublic -c 0x81000000 -o /tmp/tmpz93b6eua"
keylime_agent[15085]: 2023-02-19 19:00:13.044 - keylime.keylime.cmd_exec - DEBUG - Executing command "t p m 2 _ n v r e a d p u b l i c"
keylime_agent[15085]: 2023-02-19 19:00:13.064 - keylime.keylime.cmd_exec - DEBUG - Executing command "tpm2_nvread 0x1c00002 -s 1016 -o /tmp/tmpvh7u39_r"
keylime_agent[15085]: 2023-02-19 19:00:13.086 - keylime.tpm - INFO - Flushing old ak handle: /var/lib/keylime/secure/tmpnf5vq5tb
keylime_agent[15085]: 2023-02-19 19:00:13.086 - keylime.keylime.cmd_exec - DEBUG - Executing command "tpm2_getcap handles-persistent"
keylime_agent[15085]: 2023-02-19 19:00:13.099 - keylime.keylime.cmd_exec - DEBUG - Executing command "tpm2_evictcontrol -C o -c /var/lib/keylime/secure/tmpnf5vq5tb -P keylime"
keylime_agent[15085]: 2023-02-19 19:00:13.115 - keylime.tpm - INFO - Failed to flush old ak handle: /var/lib/keylime/secure/tmpnf5vq5tb.  Code 1: [b'WARNING:esys:src/tss2-esys/api/Esys_ContextLoad.c:279:Esys_ContextLoad_Finish() Received TPM Error \n', b'ERROR:esys:src/tss2-esys/api/Esys_ContextLoad.c:93:Esys_ContextLoad() Esys Finish ErrorCode (0x000001df) \n', b'ERROR: Esys_ContextLoad(0x1DF) - tpm:parameter(1):integrity check failed\n', b'ERROR: Incorrect handle value, got: "/var/lib/keylime/secure/tmpnf5vq5tb", expected expected [o|p|e|n|l] or a handle number\n', b'ERROR: Unable to read PEM from provided BIO/file\n', b'ERROR: Unable to fetch public/private portions of TSS PRIVKEY\n', b'ERROR: Cannot make sense of object context "/var/lib/keylime/secure/tmpnf5vq5tb"\n', b'ERROR: Unable to run tpm2_evictcontrol\n']
keylime_agent[15085]: 2023-02-19 19:00:13.115 - keylime.tpm - DEBUG - Creating a new AIK identity
keylime_agent[15085]: 2023-02-19 19:00:13.116 - keylime.secure_mount - DEBUG - Secure storage location /var/lib/keylime/secure already mounted on tmpfs
keylime_agent[15085]: 2023-02-19 19:00:13.116 - keylime.keylime.cmd_exec - DEBUG - Executing command "tpm2_createak -C 0x81000000 -c /var/lib/keylime/secure/tmpddd8az7b -G rsa -g sha256 -s rsassa -u /tmp/tmp9h7n6k9b -p vvtqk3cilH1pntdGAEPz -P keylime"
keylime_agent[15085]: 2023-02-19 19:00:13.286 - keylime.keylime.cmd_exec - DEBUG - Executing command "tpm2_flushcontext -t"
keylime_agent[15085]: 2023-02-19 19:00:13.301 - keylime.cloudagent - INFO - Agent UUID: d432fbb3-d2f1-4a97-9ef7-75bd81c00000
keylime_agent[15085]: 2023-02-19 19:00:13.301 - keylime.secure_mount - DEBUG - Secure storage location /var/lib/keylime/secure already mounted on tmpfs
keylime_agent[15085]: 2023-02-19 19:00:13.301 - keylime.cloudagent - INFO - No value provided in server_key_password option for agent, assuming the key is unencrypted
keylime_agent[15085]: 2023-02-19 19:00:13.301 - keylime.cloudagent - INFO - Key for U/V transport and mTLS certificate not found, generating a new one
keylime_agent[15085]: 2023-02-19 19:00:13.584 - keylime.cloudagent - INFO - No mTLS certificate found, generating a new one
keylime_agent[15085]: 2023-02-19 19:00:13.586 - keylime.keylime.cmd_exec - DEBUG - Executing command "tpm2_nvread 0x1500018 -C 0x40000001 -s 32 -P keylime"
keylime_agent[15085]: 2023-02-19 19:00:13.603 - keylime.tpm - DEBUG - No stored U in TPM NVRAM
keylime_agent[15085]: 2023-02-19 19:00:13.607 - urllib3.connectionpool - DEBUG - Starting new HTTP connection (1): 127.0.0.1:8890
keylime_agent[15085]: 2023-02-19 19:00:13.687 - urllib3.connectionpool - DEBUG - http://127.0.0.1:8890 "POST /v2.1/agents/d432fbb3-d2f1-4a97-9ef7-75bd81c00000 HTTP/1.1" 200 None
keylime_agent[15085]: 2023-02-19 19:00:13.688 - keylime.registrar_client - INFO - Agent registration requested for d432fbb3-d2f1-4a97-9ef7-75bd81c00000
keylime_agent[15085]: 2023-02-19 19:00:13.688 - keylime.secure_mount - DEBUG - Secure storage location /var/lib/keylime/secure already mounted on tmpfs
keylime_agent[15085]: 2023-02-19 19:00:13.688 - keylime.keylime.cmd_exec - DEBUG - Executing command "tpm2_startauthsession --policy-session -S /var/lib/keylime/secure/tmpdw4q_2pu"
keylime_agent[15085]: 2023-02-19 19:00:13.703 - keylime.keylime.cmd_exec - DEBUG - Executing command "tpm2_policysecret -S /var/lib/keylime/secure/tmpdw4q_2pu -c 0x4000000B keylime"
keylime_agent[15085]: 2023-02-19 19:00:13.725 - keylime.keylime.cmd_exec - DEBUG - Executing command "tpm2_activatecredential -c /var/lib/keylime/secure/tmpddd8az7b -C 0x81000000 -i /tmp/tmpp88lwea0 -o /var/lib/keylime/secure/tmppopjbbc6 -p vvtqk3cilH1pntdGAEPz -P session:/var/lib/keylime/secure/tmpdw4q_2pu"
keylime_agent[15085]: 2023-02-19 19:00:13.763 - keylime.tpm - ERROR - Error decrypting AIK: Command: ['tpm2_activatecredential', '-c', '/var/lib/keylime/secure/tmpddd8az7b', '-C', '0x81000000', '-i', '/tmp/tmpp88lwea0', '-o', '/var/lib/keylime/secure/tmppopjbbc6', '-p', 'vvtqk3cilH1pntdGAEPz', '-P', 'session:/var/lib/keylime/secure/tmpdw4q_2pu'] returned 1, expected 0, output [], stderr [b'WARNING:esys:src/tss2-esys/api/Esys_ActivateCredential.c:321:Esys_ActivateCredential_Finish() Received TPM Error \n', b'ERROR:esys:src/tss2-esys/api/Esys_ActivateCredential.c:105:Esys_ActivateCredential() Esys Finish ErrorCode (0x000001df) \n', b'ERROR: Esys_ActivateCredential(0x1DF) - tpm:parameter(1):integrity check failed\n', b'ERROR: Unable to run tpm2_activatecredential\n']
keylime_agent[15085]: 2023-02-19 19:00:13.763 - keylime.tpm - ERROR - Command: ['tpm2_activatecredential', '-c', '/var/lib/keylime/secure/tmpddd8az7b', '-C', '0x81000000', '-i', '/tmp/tmpp88lwea0', '-o', '/var/lib/keylime/secure/tmppopjbbc6', '-p', 'vvtqk3cilH1pntdGAEPz', '-P', 'session:/var/lib/keylime/secure/tmpdw4q_2pu'] returned 1, expected 0, output [], stderr [b'WARNING:esys:src/tss2-esys/api/Esys_ActivateCredential.c:321:Esys_ActivateCredential_Finish() Received TPM Error \n', b'ERROR:esys:src/tss2-esys/api/Esys_ActivateCredential.c:105:Esys_ActivateCredential() Esys Finish ErrorCode (0x000001df) \n', b'ERROR: Esys_ActivateCredential(0x1DF) - tpm:parameter(1):integrity check failed\n', b'ERROR: Unable to run tpm2_activatecredential\n']
keylime_agent[15085]: Traceback (most recent call last):
keylime_agent[15085]:   File "/usr/local/lib/python3.11/site-packages/keylime-6.6.0-py3.11.egg/keylime/tpm/tpm_main.py", line 781, in activate_identity
keylime_agent[15085]:     retDict = self.__run(command, outputpaths=secpath)
keylime_agent[15085]:               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
keylime_agent[15085]:   File "/usr/local/lib/python3.11/site-packages/keylime-6.6.0-py3.11.egg/keylime/tpm/tpm_main.py", line 211, in __run
keylime_agent[15085]:     raise Exception(
keylime_agent[15085]: Exception: Command: ['tpm2_activatecredential', '-c', '/var/lib/keylime/secure/tmpddd8az7b', '-C', '0x81000000', '-i', '/tmp/tmpp88lwea0', '-o', '/var/lib/keylime/secure/tmppopjbbc6', '-p', 'vvtqk3cilH1pntdGAEPz', '-P', 'session:/var/lib/keylime/secure/tmpdw4q_2pu'] returned 1, expected 0, output [], stderr [b'WARNING:esys:src/tss2-esys/api/Esys_ActivateCredential.c:321:Esys_ActivateCredential_Finish() Received TPM Error \n', b'ERROR:esys:src/tss2-esys/api/Esys_ActivateCredential.c:105:Esys_ActivateCredential() Esys Finish ErrorCode (0x000001df) \n', b'ERROR: Esys_ActivateCredential(0x1DF) - tpm:parameter(1):integrity check failed\n', b'ERROR: Unable to run tpm2_activatecredential\n']
keylime_agent[15085]: 2023-02-19 19:00:13.764 - keylime.tpm - DEBUG - Flushing keys from TPM...
keylime_agent[15085]: 2023-02-19 19:00:13.764 - keylime.keylime.cmd_exec - DEBUG - Executing command "tpm2_getcap handles-persistent"
keylime_agent[15085]: 2023-02-19 19:00:13.776 - keylime.tpm - DEBUG - Flushing key handle 0x81000000
keylime_agent[15085]: 2023-02-19 19:00:13.776 - keylime.keylime.cmd_exec - DEBUG - Executing command "tpm2_evictcontrol -C o -c 0x81000000 -P keylime"
keylime_agent[15085]: 2023-02-19 19:00:13.796 - keylime.tpm - DEBUG - Flushing key handle 0x81010001
keylime_agent[15085]: 2023-02-19 19:00:13.796 - keylime.keylime.cmd_exec - DEBUG - Executing command "tpm2_evictcontrol -C o -c 0x81010001 -P keylime"
keylime_agent[15085]: 2023-02-19 19:00:13.816 - keylime.tpm - DEBUG - Flushing key handle 0x81010016
keylime_agent[15085]: 2023-02-19 19:00:13.816 - keylime.keylime.cmd_exec - DEBUG - Executing command "tpm2_evictcontrol -C o -c 0x81010016 -P keylime"
keylime_agent[15085]: 2023-02-19 19:00:13.836 - keylime.keylime.cmd_exec - DEBUG - Executing command "tpm2_flushcontext -t"
keylime_agent[15085]: Traceback (most recent call last):
keylime_agent[15085]:   File "/usr/local/bin/keylime_agent", line 33, in <module>
keylime_agent[15085]:     sys.exit(load_entry_point('keylime==6.6.0', 'console_scripts', 'keylime_agent')())
keylime_agent[15085]:              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
keylime_agent[15085]:   File "/usr/local/lib/python3.11/site-packages/keylime-6.6.0-py3.11.egg/keylime/cmd/agent.py", line 7, in main
keylime_agent[15085]:     keylime_agent.main()
keylime_agent[15085]:   File "/usr/local/lib/python3.11/site-packages/keylime-6.6.0-py3.11.egg/keylime/keylime_agent.py", line 802, in main
keylime_agent[15085]:     raise Exception("Activation failed")
keylime_agent[15085]: Exception: Activation failed
systemd[1]: keylime_agent.service: Main process exited, code=exited, status=1/FAILURE

We are running TPM emulated through swtpm

Version-Release number of selected component (if applicable):
swtpm-0.8.0-2.fc38.x86_64
tpm2-tools-5.4-1.fc38.x86_64
tpm2-tss-4.0.1-3.fc38.x86_64
both F38 and Rawhide

How reproducible:
always

Steps to Reproduce:
1. attempt to start configured keylime_agent (reproducible with any keylime e2e test)

Actual results:
error

Expected results:
agent runs tpm2_activatecredential successfully

Additional info:
This is a regression, with tpm2-tools-5.4-1.fc38.x86_64 it works well.

Please, use PR workflow for Fedora updates so issues like this are identified through CI.

Comment 1 Peter Robinson 2023-02-20 09:55:08 UTC
> Expected results:
> agent runs tpm2_activatecredential successfully
> 
> Additional info:
> This is a regression, with tpm2-tools-5.4-1.fc38.x86_64 it works well.

Can you report this directly upstream.

> Please, use PR workflow for Fedora updates so issues like this are
> identified through CI.

Apologies I completely missed the CI changes would require that when we set that up.

Comment 2 Karel Srot 2023-02-20 10:16:48 UTC
(In reply to Peter Robinson from comment #1)
> Can you report this directly upstream.

Done. https://github.com/tpm2-software/tpm2-tools/issues/3210

Comment 3 Karel Srot 2023-02-25 07:50:47 UTC
Thore Sommer suggsted this could be related to LTO being enabled in Fedora and I have verified that tpm2-tools-5.5-1.fc38.src.rpm rebuilt with LTO disabled works fine. I don't know how it could impact the Rust keylime_agent which doesn't use tpm2-tools but the fact is that with rebuilt tpm2-tools installed our test passes even with the upstream Rust agent installed.

Comment 4 Karel Srot 2023-02-27 15:12:06 UTC
The issue is related to the  -U_FORTIFY_SOURCE,-D_FORTIFY_SOURCE=3 flags. See upstream issue for details.

Comment 5 Fedora Update System 2023-04-19 17:49:50 UTC
FEDORA-2023-01a9c38cdd has been submitted as an update to Fedora 39. https://bodhi.fedoraproject.org/updates/FEDORA-2023-01a9c38cdd

Comment 6 Fedora Update System 2023-04-19 18:16:05 UTC
FEDORA-2023-01a9c38cdd has been pushed to the Fedora 39 stable repository.
If problem still persists, please make note of it in this bug report.

Comment 7 Karel Srot 2023-04-20 06:18:24 UTC
Hi Peter ,
is there a fix also for F38? Thank you.

Comment 8 Karel Srot 2023-04-20 06:19:20 UTC
Found it, pls ignore.

Comment 9 Fedora Update System 2023-04-20 08:11:25 UTC
FEDORA-2023-c907a05c30 has been submitted as an update to Fedora 38. https://bodhi.fedoraproject.org/updates/FEDORA-2023-c907a05c30

Comment 10 Fedora Update System 2023-04-21 03:20:35 UTC
FEDORA-2023-c907a05c30 has been pushed to the Fedora 38 testing repository.
Soon you'll be able to install the update with the following command:
`sudo dnf upgrade --enablerepo=updates-testing --refresh --advisory=FEDORA-2023-c907a05c30`
You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-2023-c907a05c30

See also https://fedoraproject.org/wiki/QA:Updates_Testing for more information on how to test updates.

Comment 11 Fedora Update System 2023-04-22 00:48:25 UTC
FEDORA-2023-c907a05c30 has been pushed to the Fedora 38 stable repository.
If problem still persists, please make note of it in this bug report.


Note You need to log in before you can comment on or make changes to this bug.