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
Hi,
[expanding cc list]
On Sat, Dec 07, 2019 at 11:04:20PM +0530, Jeffrin Jose wrote:
> i got the following output related from typical dmesg output from 5.4.1 kernel
Was this during boot or during some other operation?
> ================================================
> 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
On Mon, Dec 09, 2019 at 10:34:32AM +0000, Will Deacon wrote:
> Hi,
>
> [expanding cc list]
>
> On Sat, Dec 07, 2019 at 11:04:20PM +0530, Jeffrin Jose wrote:
> > i got the following output related from typical dmesg output from 5.4.1 kernel
>
> Was this during boot or during some other operation?
>
> > ================================================
> > 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?
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
On 12/9/19 12:25 PM, Jarkko Sakkinen wrote:
> On Mon, Dec 09, 2019 at 10:34:32AM +0000, Will Deacon wrote:
>> Hi,
>>
>> [expanding cc list]
>>
>> On Sat, Dec 07, 2019 at 11:04:20PM +0530, Jeffrin Jose wrote:
>>> i got the following output related from typical dmesg output from 5.4.1 kernel
>>
>> Was this during boot or during some other operation?
>>
>>> ================================================
>>> 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?
>
> 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:
diff --git a/drivers/char/tpm/tpm-dev-common.c
b/drivers/char/tpm/tpm-dev-common.c
index 2ec47a69a2a6..47f1c0c5c8de 100644
--- a/drivers/char/tpm/tpm-dev-common.c
+++ b/drivers/char/tpm/tpm-dev-common.c
@@ -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;
}
--
Tadeusz
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(-)
diff --git a/tools/testing/selftests/tpm2/test_smoke.sh b/tools/testing/selftests/tpm2/test_smoke.sh
index 80521d46220c..cb54ab637ea6 100755
--- a/tools/testing/selftests/tpm2/test_smoke.sh
+++ b/tools/testing/selftests/tpm2/test_smoke.sh
@@ -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
diff --git a/tools/testing/selftests/tpm2/tpm2.py b/tools/testing/selftests/tpm2/tpm2.py
index 828c18584624..d0fcb66a88a6 100644
--- a/tools/testing/selftests/tpm2/tpm2.py
+++ b/tools/testing/selftests/tpm2/tpm2.py
@@ -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)
diff --git a/tools/testing/selftests/tpm2/tpm2_tests.py b/tools/testing/selftests/tpm2/tpm2_tests.py
index d4973be53493..728be7c69b76 100644
--- a/tools/testing/selftests/tpm2/tpm2_tests.py
+++ b/tools/testing/selftests/tpm2/tpm2_tests.py
@@ -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()
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(+)
diff --git a/drivers/char/tpm/tpm-dev-common.c b/drivers/char/tpm/tpm-dev-common.c
index 2ec47a69a2a6..b23b0b999232 100644
--- a/drivers/char/tpm/tpm-dev-common.c
+++ b/drivers/char/tpm/tpm-dev-common.c
@@ -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;
}
> diff --git a/drivers/char/tpm/tpm-dev-common.c
> b/drivers/char/tpm/tpm-dev-common.c
> index 2ec47a69a2a6..47f1c0c5c8de 100644
> --- a/drivers/char/tpm/tpm-dev-common.c
> +++ b/drivers/char/tpm/tpm-dev-common.c
> @@ -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;
> }
>
>
>
> --
> 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
On Tue, Dec 10, 2019 at 11:04:59AM -0800, Tadeusz Struk wrote:
> 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
On Mon, Dec 09, 2019 at 01:34:29PM -0800, Tadeusz Struk wrote:
> 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.
> To get rid of the warning it should be changed to something like this:
>
> diff --git a/drivers/char/tpm/tpm-dev-common.c
> b/drivers/char/tpm/tpm-dev-common.c
> index 2ec47a69a2a6..47f1c0c5c8de 100644
> --- a/drivers/char/tpm/tpm-dev-common.c
> +++ b/drivers/char/tpm/tpm-dev-common.c
> @@ -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;
> }
>
>
>
> --
> Tadeusz
The fix looks appropriate but needs to be formalized as a patch.
/Jarkko
On Tue, Dec 10, 2019 at 01:17:51PM -0800, Tadeusz Struk wrote:
> 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
On Wed, Dec 11, 2019 at 07:52:02PM +0200, Jarkko Sakkinen wrote:
> On Tue, Dec 10, 2019 at 01:17:51PM -0800, Tadeusz Struk wrote:
> > 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.
The code change, however, seems to be doing the right thing.
Please bundle it with the test and fix the commit message
appropriately.
/Jarkko
On Tue, Dec 10, 2019 at 01:17:51PM -0800, Tadeusz Struk wrote:
> 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
On Mon, Dec 09, 2019 at 10:34:32AM +0000, Will Deacon wrote:
> Can you reproduce this failure on v5.5-rc1?
i compiled and tested v5.5-rc1 . Yes the failure was there
--
software engineer
rajagiri school of engineering and technology
On Mon, Dec 09, 2019 at 10:34:32AM +0000, Will Deacon wrote:
> Was this during boot or during some other operation?
It was during boot.
--
software engineer
rajagiri school of engineering and technology
On 12/11/19 7:17 AM, Jeffrin Jose wrote:
> 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,
--
Tadeusz
On Wed, Dec 11, 2019 at 10:36:15AM -0800, Tadeusz Struk wrote:
> On 12/11/19 7:17 AM, Jeffrin Jose wrote:
> > 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/
>
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