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

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

[Jeffrin Jose]

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

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

[Will Deacon]

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

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

[Jarkko Sakkinen]

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

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

[Tadeusz Struk]

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

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

[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 <tadeusz.struk@intel.com>
---
 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()

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

[Jarkko Sakkinen]

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 <tadeusz.struk@intel.com>

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

/Jarkko

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

[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: stable@vger.kernel.org
Fixes: 9e1b74a63f776 (tpm: add support for nonblocking operation)
Signed-off-by: Tadeusz Struk <tadeusz.struk@intel.com>
---
 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;
 	}

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

[Jarkko Sakkinen]

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: stable@vger.kernel.org
> Fixes: 9e1b74a63f776 (tpm: add support for nonblocking operation)
> Signed-off-by: Tadeusz Struk <tadeusz.struk@intel.com>

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

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

[Jarkko Sakkinen]

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

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

[Jarkko Sakkinen]

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

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

[Jeffrin Jose]

> 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

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

[Tadeusz Struk]

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

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

[Jeffrin Jose]

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 <jeffrin@rajagiritech.edu.in>
Tested-by: Jeffrin Jose T <jeffrin@rajagiritech.edu.in>

--
software engineer
rajagiri school of engineering and technology

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

[Jarkko Sakkinen]

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

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

[Jeffrin Jose]

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

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

[Jeffrin Jose]

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