Kernel 5.0 regression in /dev/tpm0 access

Kernel 5.0 regression in /dev/tpm0 access

[Mantas Mikulėnas]

Hello, I'm not entirely sure where I'm supposed to send this –

As of kernel 5.0.0, I'm unable to use the TPM on my laptop (HP
EliteBook 840 G4, with Infineon TPM 2.0) with the current version of
Intel TPM2 tools (tpm2-tss 2.2.0, tpm2-tools 3.1.3). The tools – e.g.
tpm2_pcrlist or tpm2_nvread – sometimes succeed, sometimes are unable
to read anything from /dev/tpm0 at all (immediately report an EOF),
and sometimes are able to read part of the response but stop halfway.

The problem seems to be caused by commit 9488585b21bef0df12 ("tpm: add
support for partial reads"); I've compiled 5.0.0 with that commit
reverted and the tpm2 tools no longer have problems. Investigating
with `strace` shows that the tools frequently get 0 bytes out of a 4k
read:

[good]
write(3, "\200\1\0\0\0\32\0\0\1~\0\0\0\2\0\4\3\0\0\0\0\v\3\0\377\377", 26) = 26
poll([{fd=3, events=POLLIN}], 1, -1)    = 1 ([{fd=3, revents=POLLIN}])
read(3, "\200\1\0\0\0012\0\0\0\0\0\0\0h\0\0\0\2\0\4\3\0\0\0\0\v\3\0\377\0\0\0"...,
4096) = 306

[bad]
write(3, "\200\1\0\0\0\32\0\0\1~\0\0\0\2\0\4\3\0\0\0\0\v\3\0\0\377", 26) = 26
poll([{fd=3, events=POLLIN}], 1, -1)    = 1 ([{fd=3, revents=POLLIN}])
read(3, "", 4096)                       = 0
write(2, "WARNING:tcti:src/tss2-tcti/tcti-"..., 97) = 97
write(2, "ERROR: ", 7)                  = 7
write(2, "read pcr failed. tpm error 0xa00"..., 34) = 34

(Interestingly, this is very difficult to reproduce under strace, yet
almost guaranteed to happen when not being traced. It almost feels as
if this is a timing issue?)

-- 
Mantas Mikulėnas

Re: Kernel 5.0 regression in /dev/tpm0 access

[James Bottomley]

On Sat, 2019-03-09 at 22:48 +0200, Mantas Mikulėnas wrote:
> Hello, I'm not entirely sure where I'm supposed to send this –
> 
> As of kernel 5.0.0, I'm unable to use the TPM on my laptop (HP
> EliteBook 840 G4, with Infineon TPM 2.0) with the current version of
> Intel TPM2 tools (tpm2-tss 2.2.0, tpm2-tools 3.1.3). The tools – e.g.
> tpm2_pcrlist or tpm2_nvread – sometimes succeed, sometimes are unable
> to read anything from /dev/tpm0 at all (immediately report an EOF),
> and sometimes are able to read part of the response but stop halfway.

Just as a data point, I don't see this on 5.0 with my setup.  However,
unlike you I'm using the ibmtss which makes direct connections to
/dev/tpmrm0 so our two situations definitely aren't equivalent.

> The problem seems to be caused by commit 9488585b21bef0df12 ("tpm:
> add support for partial reads"); I've compiled 5.0.0 with that commit
> reverted and the tpm2 tools no longer have problems. Investigating
> with `strace` shows that the tools frequently get 0 bytes out of a 4k
> read:
> 
> [good]
> write(3,
> "\200\1\0\0\0\32\0\0\1~\0\0\0\2\0\4\3\0\0\0\0\v\3\0\377\377", 26) =
> 26
> poll([{fd=3, events=POLLIN}], 1, -1)    = 1 ([{fd=3,
> revents=POLLIN}])
> read(3,
> "\200\1\0\0\0012\0\0\0\0\0\0\0h\0\0\0\2\0\4\3\0\0\0\0\v\3\0\377\0\0\0
> "...,
> 4096) = 306
> 
> [bad]
> write(3, "\200\1\0\0\0\32\0\0\1~\0\0\0\2\0\4\3\0\0\0\0\v\3\0\0\377",
> 26) = 26
> poll([{fd=3, events=POLLIN}], 1, -1)    = 1 ([{fd=3,
> revents=POLLIN}])
> read(3, "", 4096)                       = 0
> write(2, "WARNING:tcti:src/tss2-tcti/tcti-"..., 97) = 97
> write(2, "ERROR: ", 7)                  = 7
> write(2, "read pcr failed. tpm error 0xa00"..., 34) = 34
> 
> (Interestingly, this is very difficult to reproduce under strace, yet
> almost guaranteed to happen when not being traced. It almost feels as
> if this is a timing issue?)

There is a significant difference in the way our applications are
working.  for instance if I strace

tssgetcapability -cap 0

I see this (cutting out everything before the TPM open and after the
TPM close)

openat(AT_FDCWD, "/dev/tpmrm0", O_RDWR) = 3
write(3,
"\200\1\0\0\0\26\0\0\1z\0\0\0\0\0\0\0\0\0\0\0@", 22) = 22
read(3,
"\200\1\0\0\0\235\0\0\0\0\0\0\0\0\0\0\0\0\27\0\1\0\0\0\t\0\4\0\0\0\4\0"
..., 4096) = 157
close(3)

So we do a simple write command and read the return (which simply hangs
until the TPM is ready with the data).  We don't poll like your
application does above, so it seems obvious that the break must be in
the polling code.

James

Re: Kernel 5.0 regression in /dev/tpm0 access

[James Bottomley]

On Sat, 2019-03-09 at 14:01 -0800, James Bottomley wrote:
> On Sat, 2019-03-09 at 22:48 +0200, Mantas Mikulėnas wrote:
[...]
> openat(AT_FDCWD, "/dev/tpmrm0", O_RDWR) = 3
> write(3,
> "\200\1\0\0\0\26\0\0\1z\0\0\0\0\0\0\0\0\0\0\0@", 22) = 22
> read(3,
> "\200\1\0\0\0\235\0\0\0\0\0\0\0\0\0\0\0\0\27\0\1\0\0\0\t\0\4\0\0\0\4\
> 0"
> ..., 4096) = 157
> close(3)
> 
> So we do a simple write command and read the return (which simply
> hangs until the TPM is ready with the data).  We don't poll like your
> application does above, so it seems obvious that the break must be in
> the polling code.

OK, so the polled sequence should be 

write()
poll()
read()

So I think this condition in tpm_common_poll is the problem:

	if (!priv->response_read || priv->response_length)
		mask = EPOLLIN | EPOLLRDNORM;

If something wakes poll_wait() before the command returns, that
condition is true because we set response_read to false in write().  So
I think poll_wait() is returning prematurely.

The reason you don't often see the problem under tracing is that if the
queued work has time to execute *before* poll returns, it's taken the
mutex and the read() will block until the command completes trying to
acquire the mutex.  If you're fast enough, the queue doesn't run, the
mutex isn't taken and read acquires it and returns with no data.

I think the fix may be to make poll only return POLLIN if we have a
response_length, so

	if (priv->response_length)
			mask = EPOLLIN | EPOLLRDNORM;

That way the calling program will get POLLOUT and go back to re-polling 
until we have data.

James

Re: Kernel 5.0 regression in /dev/tpm0 access

[Jarkko Sakkinen]

On Sat, Mar 09, 2019 at 02:44:27PM -0800, James Bottomley wrote:
> OK, so the polled sequence should be 
> 
> write()
> poll()
> read()
> 
> So I think this condition in tpm_common_poll is the problem:
> 
> 	if (!priv->response_read || priv->response_length)
> 		mask = EPOLLIN | EPOLLRDNORM;

Tadeusz, why on earth the code does not lock buffer_mutex?? Just noticed
when I checked the function in question. It is an awful bug alone.

Maybe I'm missing something but that is the root cause for this mess
i.e. race condition with tpm_common_write().

I'm sorry for not noticing that during the review process :-( So
obviously wrong...

/Jarkko

Re: Kernel 5.0 regression in /dev/tpm0 access

[Tadeusz Struk]

Hi Jarkko,
On 3/11/19 6:09 AM, Jarkko Sakkinen wrote:
> Tadeusz, why on earth the code does not lock buffer_mutex?? Just noticed
> when I checked the function in question. It is an awful bug alone.

Because the tpm_common_poll() just reads the flags and doesn't modify
them, so the logic was that if the response_length is not 0 or
response_read is flase then the first poll should return EPOLLIN
and if not, the application should call the poll again and only call read
if the EPOLLIN is set in the mask. It looks like the tpm_timeout_work()
kicks in and messes things out.
Looking at it again I think the response_read flag is redundant
and only the response_length should be used.

>
> Maybe I'm missing something but that is the root cause for this mess
> i.e. race condition with tpm_common_write().
>
> I'm sorry for not noticing that during the review process  So
> obviously wrong...

Mantas, could you please give this below a quick try and see if it helps.
I have tested this quickly, but couldn't reproduce the original problem.
If it will help I will send a proper patch.
Thanks,

--- 8< ---
diff --git a/drivers/char/tpm/tpm-dev-common.c b/drivers/char/tpm/tpm-dev-common.c
index 5eecad233ea1..496b965c865f 100644
--- a/drivers/char/tpm/tpm-dev-common.c
+++ b/drivers/char/tpm/tpm-dev-common.c
@@ -63,7 +63,6 @@ static void tpm_timeout_work(struct work_struct *work)
 					      timeout_work);
 
 	mutex_lock(&priv->buffer_mutex);
-	priv->response_read = true;
 	priv->response_length = 0;
 	memset(priv->data_buffer, 0, sizeof(priv->data_buffer));
 	mutex_unlock(&priv->buffer_mutex);
@@ -75,7 +74,6 @@ void tpm_common_open(struct file *file, struct tpm_chip *chip,
 {
 	priv->chip = chip;
 	priv->space = space;
-	priv->response_read = true;
 
 	mutex_init(&priv->buffer_mutex);
 	timer_setup(&priv->user_read_timer, user_reader_timeout, 0);
@@ -95,8 +93,6 @@ ssize_t tpm_common_read(struct file *file, char __user *buf,
 	mutex_lock(&priv->buffer_mutex);
 
 	if (priv->response_length) {
-		priv->response_read = true;
-
 		ret_size = min_t(ssize_t, size, priv->response_length);
 		if (!ret_size) {
 			priv->response_length = 0;
@@ -140,8 +136,7 @@ ssize_t tpm_common_write(struct file *file, const char __user *buf,
 	 * tpm_read or a user_read_timer timeout. This also prevents split
 	 * buffered writes from blocking here.
 	 */
-	if ((!priv->response_read && priv->response_length) ||
-	    priv->command_enqueued) {
+	if (priv->response_length || priv->command_enqueued) {
 		ret = -EBUSY;
 		goto out;
 	}
@@ -167,7 +162,6 @@ ssize_t tpm_common_write(struct file *file, const char __user *buf,
 	}
 
 	priv->response_length = 0;
-	priv->response_read = false;
 	*off = 0;
 
 	/*
@@ -202,13 +196,15 @@ __poll_t tpm_common_poll(struct file *file, poll_table *wait)
 	struct file_priv *priv = file->private_data;
 	__poll_t mask = 0;
 
+	mutex_lock(&priv->buffer_mutex);
 	poll_wait(file, &priv->async_wait, wait);
 
-	if (!priv->response_read || priv->response_length)
+	if (priv->response_length)
 		mask = EPOLLIN | EPOLLRDNORM;
 	else
 		mask = EPOLLOUT | EPOLLWRNORM;
 
+	mutex_unlock(&priv->buffer_mutex);
 	return mask;
 }
 
diff --git a/drivers/char/tpm/tpm-dev.h b/drivers/char/tpm/tpm-dev.h
index 1089fc0bb290..403ae3efc6e0 100644
--- a/drivers/char/tpm/tpm-dev.h
+++ b/drivers/char/tpm/tpm-dev.h
@@ -15,7 +15,6 @@ struct file_priv {
 	struct work_struct async_work;
 	wait_queue_head_t async_wait;
 	size_t response_length;
-	bool response_read;
 	bool command_enqueued;
 
 	u8 data_buffer[TPM_BUFSIZE];

Re: Kernel 5.0 regression in /dev/tpm0 access

[James Bottomley]

On Tue, 2019-03-12 at 15:42 -0700, Tadeusz Struk wrote:
> @@ -202,13 +196,15 @@ __poll_t tpm_common_poll(struct file *file,
> poll_table *wait)
>  	struct file_priv *priv = file->private_data;
>  	__poll_t mask = 0;
>  
> +	mutex_lock(&priv->buffer_mutex);
>  	poll_wait(file, &priv->async_wait, wait);
>  
> -	if (!priv->response_read || priv->response_length)
> +	if (priv->response_length)
>  		mask = EPOLLIN | EPOLLRDNORM;
>  	else
>  		mask = EPOLLOUT | EPOLLWRNORM;
>  
> +	mutex_unlock(&priv->buffer_mutex);

Isn't this setting us up for a deadlock?  If the work queued by write
hasn't run by the time you call poll, you take the buffer mutex and
sleep.  Now if the work runs, it blocks acquiring the mutex in
tpm_async_work and never calls wakeup on async_wait.

James

Re: Kernel 5.0 regression in /dev/tpm0 access

[Jarkko Sakkinen]

On Tue, Mar 12, 2019 at 03:42:00PM -0700, Tadeusz Struk wrote:
> Hi Jarkko,
> On 3/11/19 6:09 AM, Jarkko Sakkinen wrote:
> > Tadeusz, why on earth the code does not lock buffer_mutex?? Just noticed
> > when I checked the function in question. It is an awful bug alone.
> 
> Because the tpm_common_poll() just reads the flags and doesn't modify
> them, so the logic was that if the response_length is not 0 or
> response_read is flase then the first poll should return EPOLLIN
> and if not, the application should call the poll again and only call read
> if the EPOLLIN is set in the mask. It looks like the tpm_timeout_work()
> kicks in and messes things out.

1. You have *two* variables that you read, which can lead up reading
   a partial state.
2. You are not using atomic_t even if there was one variable.

> Looking at it again I think the response_read flag is redundant
> and only the response_length should be used.

Please provide a minimal fix to the issue. Only the fix for lock is
needed and send a proper patch (did not read the code below).

/Jarkko

Re: Kernel 5.0 regression in /dev/tpm0 access

[Jarkko Sakkinen]

On Tue, Mar 12, 2019 at 03:50:49PM -0700, James Bottomley wrote:
> On Tue, 2019-03-12 at 15:42 -0700, Tadeusz Struk wrote:
> > @@ -202,13 +196,15 @@ __poll_t tpm_common_poll(struct file *file,
> > poll_table *wait)
> >  	struct file_priv *priv = file->private_data;
> >  	__poll_t mask = 0;
> >  
> > +	mutex_lock(&priv->buffer_mutex);
> >  	poll_wait(file, &priv->async_wait, wait);
> >  
> > -	if (!priv->response_read || priv->response_length)
> > +	if (priv->response_length)
> >  		mask = EPOLLIN | EPOLLRDNORM;
> >  	else
> >  		mask = EPOLLOUT | EPOLLWRNORM;
> >  
> > +	mutex_unlock(&priv->buffer_mutex);
> 
> Isn't this setting us up for a deadlock?  If the work queued by write
> hasn't run by the time you call poll, you take the buffer mutex and
> sleep.  Now if the work runs, it blocks acquiring the mutex in
> tpm_async_work and never calls wakeup on async_wait.

Yes, the lock should be taken after poll_wait().

/Jarkko

Re: Kernel 5.0 regression in /dev/tpm0 access

[Jarkko Sakkinen]

On Wed, Mar 13, 2019 at 03:59:26PM +0200, Jarkko Sakkinen wrote:
> On Tue, Mar 12, 2019 at 03:42:00PM -0700, Tadeusz Struk wrote:
> > Hi Jarkko,
> > On 3/11/19 6:09 AM, Jarkko Sakkinen wrote:
> > > Tadeusz, why on earth the code does not lock buffer_mutex?? Just noticed
> > > when I checked the function in question. It is an awful bug alone.
> > 
> > Because the tpm_common_poll() just reads the flags and doesn't modify
> > them, so the logic was that if the response_length is not 0 or
> > response_read is flase then the first poll should return EPOLLIN
> > and if not, the application should call the poll again and only call read
> > if the EPOLLIN is set in the mask. It looks like the tpm_timeout_work()
> > kicks in and messes things out.
> 
> 1. You have *two* variables that you read, which can lead up reading
>    a partial state.
> 2. You are not using atomic_t even if there was one variable.
> 
> > Looking at it again I think the response_read flag is redundant
> > and only the response_length should be used.
> 
> Please provide a minimal fix to the issue. Only the fix for lock is
> needed and send a proper patch (did not read the code below).

Are you planning to submit a fix for this?

/Jarkko

Re: Kernel 5.0 regression in /dev/tpm0 access

[Tadeusz Struk]

On 3/17/19 6:22 AM, Jarkko Sakkinen wrote:
> Are you planning to submit a fix for this?

Yes, sorry for the delay. I will send something soon.
Thanks,
-- 
Tadeusz

Re: Kernel 5.0 regression in /dev/tpm0 access

[Jarkko Sakkinen]

On Mon, Mar 18, 2019 at 08:50:30AM -0700, Tadeusz Struk wrote:
> On 3/17/19 6:22 AM, Jarkko Sakkinen wrote:
> > Are you planning to submit a fix for this?
> 
> Yes, sorry for the delay. I will send something soon.
> Thanks,

Thank you.

/Jarkko