: WARNING: lock held when returning to user space! (5.4.1 #16 Tainted: G )

PROBLEM In review Jeffrin Jose 4 participants 16 messages Dec 7, 2019 – Dec 12, 2019

Subsystems (4)

Stable branch Kselftest Keys-trusted TPM device driver

lore

Share & tools

lore

Jeffrin Jose

author

2019-12-07 17:35 UTC #0 lore raw

hello all,

i got the following output related from typical dmesg output from 5.4.1 kernel

================================================
WARNING: lock held when returning to user space!
5.4.1 #16 Tainted: G E
------------------------------------------------
tpm2-abrmd/691 is leaving the kernel with locks still held!
2 locks held by tpm2-abrmd/691:
#0: ffff8881ee784ba8 (&chip->ops_sem){.+.+}, at: tpm_try_get_ops+0x2b/0xc0 [tpm] #1: ffff8881ee784d88 (&chip->tpm_mutex){+.+.}, at: tpm_try_get_ops+0x57/0xc0 [tpm]

--
software engineer
rajagiri school of engineering and technology

Will Deacon

2019-12-09 10:34 UTC #1 lore raw

Hi,

[expanding cc list]

Quoted 1 line · Jeffrin Jose

i got the following output related from typical dmesg output from 5.4.1 kernel

Was this during boot or during some other operation?

Quoted 8 lines

================================================
WARNING: lock held when returning to user space!
5.4.1 #16 Tainted: G E
------------------------------------------------
tpm2-abrmd/691 is leaving the kernel with locks still held!
2 locks held by tpm2-abrmd/691:
#0: ffff8881ee784ba8 (&chip->ops_sem){.+.+}, at: tpm_try_get_ops+0x2b/0xc0 [tpm] #1: ffff8881ee784d88 (&chip->tpm_mutex){+.+.}, at: tpm_try_get_ops+0x57/0xc0 [tpm]

Can you reproduce this failure on v5.5-rc1?

Thanks,

Will

Jarkko Sakkinen

2019-12-09 20:31 UTC #2 lore raw

Quoted 18 lines · Will Deacon

Hi,
[expanding cc list]
Quoted 1 line · Jeffrin Jose
i got the following output related from typical dmesg output from 5.4.1 kernel
Was this during boot or during some other operation?
Quoted 8 lines
================================================
WARNING: lock held when returning to user space!
5.4.1 #16 Tainted: G E
------------------------------------------------
tpm2-abrmd/691 is leaving the kernel with locks still held!
2 locks held by tpm2-abrmd/691:
#0: ffff8881ee784ba8 (&chip->ops_sem){.+.+}, at: tpm_try_get_ops+0x2b/0xc0 [tpm] #1: ffff8881ee784d88 (&chip->tpm_mutex){+.+.}, at: tpm_try_get_ops+0x57/0xc0 [tpm]

Quoted 1 line

Can you reproduce this failure on v5.5-rc1?

Does this appear after variable amount of time or detemitically always at certain point of time (e.g. when the daemon starts or perhaps always when doing a certain operations with TSS)?

Do we have possibility to get the user code path that gets executed when this happens?

/Jarkko

Tadeusz Struk

2019-12-09 21:34 UTC #3 lore raw

Quoted 19 lines · Jarkko Sakkinen

Quoted 18 lines · Will Deacon
Hi,
[expanding cc list]
Quoted 1 line · Jeffrin Jose
i got the following output related from typical dmesg output from 5.4.1 kernel
Was this during boot or during some other operation?
Quoted 8 lines
================================================
WARNING: lock held when returning to user space!
5.4.1 #16 Tainted: G E
------------------------------------------------
tpm2-abrmd/691 is leaving the kernel with locks still held!
2 locks held by tpm2-abrmd/691:
#0: ffff8881ee784ba8 (&chip->ops_sem){.+.+}, at: tpm_try_get_ops+0x2b/0xc0 [tpm] #1: ffff8881ee784d88 (&chip->tpm_mutex){+.+.}, at: tpm_try_get_ops+0x57/0xc0 [tpm]

Quoted 8 lines

Quoted 1 line
Can you reproduce this failure on v5.5-rc1?
Does this appear after variable amount of time or detemitically always at certain point of time (e.g. when the daemon starts or perhaps always when doing a certain operations with TSS)?
Do we have possibility to get the user code path that gets executed when this happens?

I think that's expected for a non-blocking operation.
To get rid of the warning it should be changed to something like this:

(quoted diff) +0 -0

b/drivers/char/tpm/tpm-dev-common.c
index 2ec47a69a2a6..47f1c0c5c8de 100644

drivers/char/tpm/tpm-dev-common.c +7 -0

@@ -61,6 +61,12 @@ static void tpm_dev_async_work(struct work_struct *work)
 
 	mutex_lock(&priv->buffer_mutex);
 	priv->command_enqueued = false;
+	ret = tpm_try_get_ops(priv->chip);
+	if (ret) {
+		priv->response_length = ret;
+		goto out;
+	}
+
 	ret = tpm_dev_transmit(priv->chip, priv->space, priv->data_buffer,
 			       sizeof(priv->data_buffer));
 	tpm_put_ops(priv->chip);

@@ -68,6 +74,7 @@ static void tpm_dev_async_work(struct work_struct *work)
 		priv->response_length = ret;
 		mod_timer(&priv->user_read_timer, jiffies + (120 * HZ));
 	}
+out:
 	mutex_unlock(&priv->buffer_mutex);
 	wake_up_interruptible(&priv->async_wait);
 }

@@ -205,6 +212,7 @@ ssize_t tpm_common_write(struct file *file, const

char __user *buf,
priv->command_enqueued = true; queue_work(tpm_dev_wq, &priv->async_work); mutex_unlock(&priv->buffer_mutex);
+ tpm_put_ops(priv->chip);
return size;
}

Signature · 1 line

Tadeusz

Tadeusz Struk

2019-12-10 19:04 UTC #4 lore raw

PATCH 1/1 tpm: selftest: add test covering async mode

Add a test that sends a tpm cmd in an asyn mode. Currently there is a gap in test coverage with regards to this functionality.

Signed-off-by Tadeusz Struk <[email protected]>

---
 tools/testing/selftests/tpm2/test_smoke.sh |    1 +
 tools/testing/selftests/tpm2/tpm2.py       |   19 +++++++++++++++++--
 tools/testing/selftests/tpm2/tpm2_tests.py |   13 +++++++++++++
 3 files changed, 31 insertions(+), 2 deletions(-)

tools/testing/selftests/tpm2/test_smoke.sh +1 -0

index 80521d46220c..cb54ab637ea6 100755
@@ -2,3 +2,4 @@
 # SPDX-License-Identifier: (GPL-2.0 OR BSD-3-Clause)
 
 python -m unittest -v tpm2_tests.SmokeTest
+python -m unittest -v tpm2_tests.AsyncTest

tools/testing/selftests/tpm2/tpm2.py +17 -2

index 828c18584624..d0fcb66a88a6 100644
@@ -6,8 +6,8 @@ import socket
 import struct
 import sys
 import unittest
-from fcntl import ioctl
-
+import fcntl
+import select
 
 TPM2_ST_NO_SESSIONS = 0x8001
 TPM2_ST_SESSIONS = 0x8002

@@ -352,6 +352,7 @@ def hex_dump(d):
 class Client:
     FLAG_DEBUG = 0x01
     FLAG_SPACE = 0x02
+    FLAG_NONBLOCK = 0x04
     TPM_IOC_NEW_SPACE = 0xa200
 
     def __init__(self, flags = 0):

@@ -362,13 +363,27 @@ class Client:
         else:
             self.tpm = open('/dev/tpmrm0', 'r+b', buffering=0)
 
+        if (self.flags & Client.FLAG_NONBLOCK):
+            flags = fcntl.fcntl(self.tpm, fcntl.F_GETFL)
+            flags |= os.O_NONBLOCK
+            fcntl.fcntl(self.tpm, fcntl.F_SETFL, flags)
+            self.tpm_poll = select.poll()
+
     def close(self):
         self.tpm.close()
 
     def send_cmd(self, cmd):
         self.tpm.write(cmd)
+
+        if (self.flags & Client.FLAG_NONBLOCK):
+            self.tpm_poll.register(self.tpm, select.POLLIN)
+            self.tpm_poll.poll(10000)
+
         rsp = self.tpm.read()
 
+        if (self.flags & Client.FLAG_NONBLOCK):
+            self.tpm_poll.unregister(self.tpm)
+
         if (self.flags & Client.FLAG_DEBUG) != 0:
             sys.stderr.write('cmd' + os.linesep)
             sys.stderr.write(hex_dump(cmd) + os.linesep)

tools/testing/selftests/tpm2/tpm2_tests.py +13 -0

index d4973be53493..728be7c69b76 100644
@@ -288,3 +288,16 @@ class SpaceTest(unittest.TestCase):
 
         self.assertEqual(rc, tpm2.TPM2_RC_COMMAND_CODE |
                          tpm2.TSS2_RESMGR_TPM_RC_LAYER)
+
+class AsyncTest(unittest.TestCase):
+    def setUp(self):
+        logging.basicConfig(filename='AsyncTest.log', level=logging.DEBUG)
+
+    def test_async(self):
+        log = logging.getLogger(__name__)
+        log.debug(sys._getframe().f_code.co_name)
+
+        async_client = tpm2.Client(tpm2.Client.FLAG_NONBLOCK)
+        log.debug("Calling get_cap in a NON_BLOCKING mode")
+        async_client.get_cap(tpm2.TPM2_CAP_HANDLES, tpm2.HR_LOADED_SESSION)
+        async_client.close()

Jarkko Sakkinen

2019-12-11 17:42 UTC #5 lore raw

Re: [PATCH] tpm: selftest: add test covering async mode

Quoted 5 lines · Tadeusz Struk

Add a test that sends a tpm cmd in an asyn mode. Currently there is a gap in test coverage with regards to this functionality.
Signed-off-by Tadeusz Struk <[email protected]>

Please include this with a bug fix to same patch set.

/Jarkko

Tadeusz Struk

2019-12-10 21:17 UTC #6 lore raw

PATCH 1/1 tpm: fix WARNING: lock held when returning to user space

In reply to Tadeusz Struk

When an application sends TPM commands in NONBLOCKING mode the driver holds chip->tpm_mutex returning from write(), which triggers WARNING: lock held when returning to user space! To silence this warning the driver needs to release the mutex and acquire it again in tpm_dev_async_work() before sending the command.

Cc [email protected]

Fixes 9e1b74a63f776 (tpm: add support for nonblocking operation)

Signed-off-by Tadeusz Struk <[email protected]>

---
 drivers/char/tpm/tpm-dev-common.c |    8 ++++++++
 1 file changed, 8 insertions(+)

drivers/char/tpm/tpm-dev-common.c +8 -0

index 2ec47a69a2a6..b23b0b999232 100644
@@ -61,6 +61,12 @@ static void tpm_dev_async_work(struct work_struct *work)
 
 	mutex_lock(&priv->buffer_mutex);
 	priv->command_enqueued = false;
+	ret = tpm_try_get_ops(priv->chip);
+	if (ret) {
+		priv->response_length = ret;
+		goto out;
+	}
+
 	ret = tpm_dev_transmit(priv->chip, priv->space, priv->data_buffer,
 			       sizeof(priv->data_buffer));
 	tpm_put_ops(priv->chip);

@@ -68,6 +74,7 @@ static void tpm_dev_async_work(struct work_struct *work)
 		priv->response_length = ret;
 		mod_timer(&priv->user_read_timer, jiffies + (120 * HZ));
 	}
+out:
 	mutex_unlock(&priv->buffer_mutex);
 	wake_up_interruptible(&priv->async_wait);
 }

@@ -204,6 +211,7 @@ ssize_t tpm_common_write(struct file *file, const char __user *buf,
 	if (file->f_flags & O_NONBLOCK) {
 		priv->command_enqueued = true;
 		queue_work(tpm_dev_wq, &priv->async_work);
+		tpm_put_ops(priv->chip);
 		mutex_unlock(&priv->buffer_mutex);
 		return size;
 	}

Jarkko Sakkinen

2019-12-11 17:47 UTC #7 lore raw

Re: [PATCH] tpm: fix WARNING: lock held when returning to user space

Quoted 10 lines · Tadeusz Struk

When an application sends TPM commands in NONBLOCKING mode the driver holds chip->tpm_mutex returning from write(), which triggers WARNING: lock held when returning to user space! To silence this warning the driver needs to release the mutex and acquire it again in tpm_dev_async_work() before sending the command.
Cc [email protected]
Fixes 9e1b74a63f776 (tpm: add support for nonblocking operation)
Signed-off-by Tadeusz Struk <[email protected]>

Bundle the patch and test into same patch set (no need for cover letter) in the case we need to iterate (as they must be in sync anyway).

/Jarkko

Jarkko Sakkinen

2019-12-11 18:10 UTC #8 lore raw

Re: [PATCH] tpm: fix WARNING: lock held when returning to user space

In reply to Tadeusz Struk

Quoted 6 lines · Tadeusz Struk

When an application sends TPM commands in NONBLOCKING mode the driver holds chip->tpm_mutex returning from write(), which triggers WARNING: lock held when returning to user space! To silence this warning the driver needs to release the mutex and acquire it again in tpm_dev_async_work() before sending the command.

This commit message is nonsense ATM. The code leaves locks held, which is unacceptable.

Silencing warnings is worst possible rationale for a code change that I can think of starting from the fact that is straight out wrong and malicious.

/Jarkko

Jarkko Sakkinen

2019-12-11 18:00 UTC #9 lore raw

Re: [PATCH] tpm: fix WARNING: lock held when returning to user space

Quoted 8 lines · Jarkko Sakkinen

Quoted 6 lines · Tadeusz Struk
When an application sends TPM commands in NONBLOCKING mode the driver holds chip->tpm_mutex returning from write(), which triggers WARNING: lock held when returning to user space! To silence this warning the driver needs to release the mutex and acquire it again in tpm_dev_async_work() before sending the command.

Quoted 6 lines

This commit message is nonsense ATM. The code leaves locks held, which is unacceptable.
Silencing warnings is worst possible rationale for a code change that I can think of starting from the fact that is straight out wrong and malicious.

The code change, however, seems to be doing the right thing.

Please bundle it with the test and fix the commit message appropriately.

/Jarkko

Jeffrin Jose

author

2019-12-11 15:54 UTC #10 lore raw

In reply to Tadeusz Struk

Quoted 39 lines

drivers/char/tpm/tpm-dev-common.c +8 -0

index 2ec47a69a2a6..47f1c0c5c8de 100644
@@ -61,6 +61,12 @@ static void tpm_dev_async_work(struct work_struct *work)
 
 	mutex_lock(&priv->buffer_mutex);
 	priv->command_enqueued = false;
+	ret = tpm_try_get_ops(priv->chip);
+	if (ret) {
+		priv->response_length = ret;
+		goto out;
+	}
+
 	ret = tpm_dev_transmit(priv->chip, priv->space, priv->data_buffer,
 			       sizeof(priv->data_buffer));
 	tpm_put_ops(priv->chip);

@@ -68,6 +74,7 @@ static void tpm_dev_async_work(struct work_struct *work)
 		priv->response_length = ret;
 		mod_timer(&priv->user_read_timer, jiffies + (120 * HZ));
 	}
+out:
 	mutex_unlock(&priv->buffer_mutex);
 	wake_up_interruptible(&priv->async_wait);
 }

@@ -205,6 +212,7 @@ ssize_t tpm_common_write(struct file *file, const
 char __user *buf,
 		priv->command_enqueued = true;
 		queue_work(tpm_dev_wq, &priv->async_work);
 		mutex_unlock(&priv->buffer_mutex);
+		tpm_put_ops(priv->chip);
 		return size;
 	}

Signature · 2 lines

-- 
Tadeusz

above patch shows errors when i try to apply it. --------------------x------------------------x------------------
error: git diff header lacks filename information when removing 1 leading pathname component (line 2) when i did related to this "diff --git a/drivers/char/tpm/tpm-dev-common.c b/drivers/char/tpm/tpm-dev-common.c" i get another error
error: corrupt patch at line 27 ----------------------x------------------------x-----------------

i use "git apply"

--
software engineer
rajagiri school of engineering and technology

Tadeusz Struk

2019-12-11 18:50 UTC #11 lore raw

Quoted 9 lines · Jeffrin Jose

above patch shows errors when i try to apply it. --------------------x------------------------x------------------
error: git diff header lacks filename information when removing 1 leading pathname component (line 2) when i did related to this "diff --git a/drivers/char/tpm/tpm-dev-common.c b/drivers/char/tpm/tpm-dev-common.c" i get another error
error: corrupt patch at line 27 ----------------------x------------------------x-----------------
i use "git apply"

Hi,
This was just a copy and paste that wasn't meant to be applied. If you want to try it please use the patch that I sent later:
https://patchwork.kernel.org/patch/11283317/

Thanks,

Signature · 1 line

Tadeusz

Jeffrin Jose

author Tested-by Applied

2019-12-12 08:12 UTC #12 lore raw

Quoted 9 lines · Tadeusz Struk

Quoted 8 lines · Jeffrin Jose
above patch shows errors when i try to apply it. --------------------x------------------------x------------------
error: git diff header lacks filename information when removing 1 leading pathname component (line 2) when i did related to this "diff --git a/drivers/char/tpm/tpm-dev-common.c b/drivers/char/tpm/tpm-dev-common.c" i get another error
error: corrupt patch at line 27 ----------------------x------------------------x-----------------

Quoted 7 lines

Quoted 1 line
i use "git apply"
Hi,
This was just a copy and paste that wasn't meant to be applied. If you want to try it please use the patch that I sent later:
https://patchwork.kernel.org/patch/11283317/

i applied the patch and problem seem to be fixed.

Reported-by Jeffrin Jose T <[email protected]>

Tested-by Jeffrin Jose T <[email protected]>

--
software engineer
rajagiri school of engineering and technology

Jarkko Sakkinen

2019-12-11 17:45 UTC #13 lore raw

In reply to Tadeusz Struk

Quoted 1 line · Tadeusz Struk

I think that's expected for a non-blocking operation.

What do you mean by "expected"?

It is a locking bug. When you implemented the feature you failed to free locks before going back to the user space and I failed to notice this when I reviewed the code.

Quoted 41 lines

To get rid of the warning it should be changed to something like this:

drivers/char/tpm/tpm-dev-common.c +8 -0

index 2ec47a69a2a6..47f1c0c5c8de 100644
@@ -61,6 +61,12 @@ static void tpm_dev_async_work(struct work_struct *work)
 
 	mutex_lock(&priv->buffer_mutex);
 	priv->command_enqueued = false;
+	ret = tpm_try_get_ops(priv->chip);
+	if (ret) {
+		priv->response_length = ret;
+		goto out;
+	}
+
 	ret = tpm_dev_transmit(priv->chip, priv->space, priv->data_buffer,
 			       sizeof(priv->data_buffer));
 	tpm_put_ops(priv->chip);

@@ -68,6 +74,7 @@ static void tpm_dev_async_work(struct work_struct *work)
 		priv->response_length = ret;
 		mod_timer(&priv->user_read_timer, jiffies + (120 * HZ));
 	}
+out:
 	mutex_unlock(&priv->buffer_mutex);
 	wake_up_interruptible(&priv->async_wait);
 }

@@ -205,6 +212,7 @@ ssize_t tpm_common_write(struct file *file, const
 char __user *buf,
 		priv->command_enqueued = true;
 		queue_work(tpm_dev_wq, &priv->async_work);
 		mutex_unlock(&priv->buffer_mutex);
+		tpm_put_ops(priv->chip);
 		return size;
 	}