Re: [tpmdd-devel] [PATCH v3 1/4] tpm_tis: Improve reporting of IO errors

Re: [tpmdd-devel] [PATCH v3 1/4] tpm_tis: Improve reporting of IO errors

[Jarkko Sakkinen]

On Mon, Jun 06, 2016 at 08:37:26PM -0700, Ed Swierk wrote:
> Mysterious TPM behavior can be difficult to track down through all the
> layers of software. Add error messages for conditions that should
> never happen. Also include the manufacturer ID along with other chip
> data printed during init.
> 
> Signed-off-by: Ed Swierk <eswierk@skyportsystems.com>

Reviewed-by: Jarkko Sakkinen <jarkko.sakkinen@linux.intel.com>

PS. Please include at minimum also linux-kernel@vger.kernel.org and
linux-security-module@vger.kernel.org for these patches. Thanks.

> ---
>  drivers/char/tpm/tpm_tis.c | 8 +++++++-
>  1 file changed, 7 insertions(+), 1 deletion(-)
> 
> diff --git a/drivers/char/tpm/tpm_tis.c b/drivers/char/tpm/tpm_tis.c
> index 65f7eec..088fa86 100644
> --- a/drivers/char/tpm/tpm_tis.c
> +++ b/drivers/char/tpm/tpm_tis.c
> @@ -299,6 +299,8 @@ static int tpm_tis_recv(struct tpm_chip *chip, u8 *buf, size_t count)
>  
>  	expected = be32_to_cpu(*(__be32 *) (buf + 2));
>  	if (expected > count) {
> +		dev_err(chip->pdev, "Response too long (wanted %zd, got %d)\n",
> +			count, expected);
>  		size = -EIO;
>  		goto out;
>  	}
> @@ -366,6 +368,8 @@ static int tpm_tis_send_data(struct tpm_chip *chip, u8 *buf, size_t len)
>  				  &chip->vendor.int_queue, false);
>  		status = tpm_tis_status(chip);
>  		if (!itpm && (status & TPM_STS_DATA_EXPECT) == 0) {
> +			dev_err(chip->pdev, "Chip not accepting %zd bytes\n",
> +				len - count);
>  			rc = -EIO;
>  			goto out_err;
>  		}
> @@ -378,6 +382,7 @@ static int tpm_tis_send_data(struct tpm_chip *chip, u8 *buf, size_t len)
>  			  &chip->vendor.int_queue, false);
>  	status = tpm_tis_status(chip);
>  	if ((status & TPM_STS_DATA_EXPECT) != 0) {
> +		dev_err(chip->pdev, "Chip not accepting last byte\n");
>  		rc = -EIO;
>  		goto out_err;
>  	}
> @@ -689,8 +694,9 @@ static int tpm_tis_init(struct device *dev, struct tpm_info *tpm_info,
>  	vendor = ioread32(chip->vendor.iobase + TPM_DID_VID(0));
>  	chip->vendor.manufacturer_id = vendor;
>  
> -	dev_info(dev, "%s TPM (device-id 0x%X, rev-id %d)\n",
> +	dev_info(dev, "%s TPM (manufacturer-id 0x%X, device-id 0x%X, rev-id %d)\n",
>  		 (chip->flags & TPM_CHIP_FLAG_TPM2) ? "2.0" : "1.2",
> +		 chip->vendor.manufacturer_id,
>  		 vendor >> 16, ioread8(chip->vendor.iobase + TPM_RID(0)));
>  
>  	if (!itpm) {
> -- 
> 1.9.1

/Jarko

Re: [tpmdd-devel] [PATCH v3 2/4] tpm: Add optional logging of TPM command durations

[Jarkko Sakkinen]

On Mon, Jun 06, 2016 at 08:37:27PM -0700, Ed Swierk wrote:
> Some TPMs violate their own advertised command durations. This is much
> easier to debug with data about how long each command actually takes
> to complete. Add debug messages that can be enabled by running
> 
>   echo -n 'module tpm +p' >/sys/kernel/debug/dynamic_debug/control
> 
> on a kernel configured with DYNAMIC_DEBUG=y.
> 
> Signed-off-by: Ed Swierk <eswierk@skyportsystems.com>

Reviewed-by: Jarkko Sakkinen <jarkko.sakkinen@linux.intel.com>

> ---
>  drivers/char/tpm/tpm-interface.c | 17 +++++++++++++----
>  1 file changed, 13 insertions(+), 4 deletions(-)
> 
> diff --git a/drivers/char/tpm/tpm-interface.c b/drivers/char/tpm/tpm-interface.c
> index c50637d..cc1e5bc 100644
> --- a/drivers/char/tpm/tpm-interface.c
> +++ b/drivers/char/tpm/tpm-interface.c
> @@ -333,13 +333,14 @@ ssize_t tpm_transmit(struct tpm_chip *chip, const char *buf,
>  {
>  	ssize_t rc;
>  	u32 count, ordinal;
> -	unsigned long stop;
> +	unsigned long start, stop;
>  
>  	if (bufsiz > TPM_BUFSIZE)
>  		bufsiz = TPM_BUFSIZE;
>  
>  	count = be32_to_cpu(*((__be32 *) (buf + 2)));
>  	ordinal = be32_to_cpu(*((__be32 *) (buf + 6)));
> +	dev_dbg(chip->pdev, "starting command %d count %d\n", ordinal, count);
>  	if (count == 0)
>  		return -ENODATA;
>  	if (count > bufsiz) {
> @@ -360,18 +361,24 @@ ssize_t tpm_transmit(struct tpm_chip *chip, const char *buf,
>  	if (chip->vendor.irq)
>  		goto out_recv;
>  
> +	start = jiffies;
>  	if (chip->flags & TPM_CHIP_FLAG_TPM2)
> -		stop = jiffies + tpm2_calc_ordinal_duration(chip, ordinal);
> +		stop = start + tpm2_calc_ordinal_duration(chip, ordinal);
>  	else
> -		stop = jiffies + tpm_calc_ordinal_duration(chip, ordinal);
> +		stop = start + tpm_calc_ordinal_duration(chip, ordinal);
>  	do {
>  		u8 status = chip->ops->status(chip);
>  		if ((status & chip->ops->req_complete_mask) ==
> -		    chip->ops->req_complete_val)
> +		    chip->ops->req_complete_val) {
> +			dev_dbg(chip->pdev, "completed command %d in %d ms\n",
> +				ordinal, jiffies_to_msecs(jiffies - start));
>  			goto out_recv;
> +		}
>  
>  		if (chip->ops->req_canceled(chip, status)) {
>  			dev_err(chip->pdev, "Operation Canceled\n");
> +			dev_dbg(chip->pdev, "canceled command %d after %d ms\n",
> +				ordinal, jiffies_to_msecs(jiffies - start));
>  			rc = -ECANCELED;
>  			goto out;
>  		}
> @@ -382,6 +389,8 @@ ssize_t tpm_transmit(struct tpm_chip *chip, const char *buf,
>  
>  	chip->ops->cancel(chip);
>  	dev_err(chip->pdev, "Operation Timed out\n");
> +	dev_dbg(chip->pdev, "command %d timed out after %d ms\n", ordinal,
> +		jiffies_to_msecs(jiffies - start));
>  	rc = -ETIME;
>  	goto out;
>  
> -- 
> 1.9.1
> 
> 
> ------------------------------------------------------------------------------
> What NetFlow Analyzer can do for you? Monitors network bandwidth and traffic
> patterns at an interface-level. Reveals which users, apps, and protocols are 
> consuming the most bandwidth. Provides multi-vendor support for NetFlow, 
> J-Flow, sFlow and other flows. Make informed decisions using capacity 
> planning reports. https://ad.doubleclick.net/ddm/clk/305295220;132659582;e
> _______________________________________________
> tpmdd-devel mailing list
> tpmdd-devel@lists.sourceforge.net
> https://lists.sourceforge.net/lists/listinfo/tpmdd-devel

/Jarkko