lists.openwall.net   lists  /  announce  owl-users  owl-dev  john-users  john-dev  passwdqc-users  yescrypt  popa3d-users  /  oss-security  kernel-hardening  musl  sabotage  tlsify  passwords  /  crypt-dev  xvendor  /  Bugtraq  Full-Disclosure  linux-kernel  linux-netdev  linux-ext4  linux-hardening  linux-cve-announce  PHC 
Open Source and information security mailing list archives
 
Hash Suite for Android: free password hash cracker in your pocket
[<prev] [next>] [<thread-prev] [day] [month] [year] [list]
Date:   Tue, 17 Mar 2020 12:24:49 +0100
From:   Michael Walle <michael@...le.cc>
To:     Vladimir Oltean <olteanv@...il.com>
Cc:     Mark Brown <broonie@...nel.org>, linux-spi@...r.kernel.org,
        lkml <linux-kernel@...r.kernel.org>,
        Shawn Guo <shawnguo@...nel.org>,
        Rob Herring <robh+dt@...nel.org>,
        Mark Rutland <mark.rutland@....com>,
        devicetree@...r.kernel.org, Esben Haabendal <eha@...f.com>,
        angelo@...am.it, andrew.smirnov@...il.com,
        "Gustavo A. R. Silva" <gustavo@...eddedor.com>,
        Wei Chen <weic@...dia.com>, Mohamed Hosny <mhosny@...dia.com>,
        peng.ma@....com
Subject: Re: [PATCH v3 06/12] spi: spi-fsl-dspi: Replace interruptible wait
 queue with a simple completion

Am 2020-03-16 18:15, schrieb Michael Walle:
>>> dd: /dev/mtd0: Input/output error
>> 
>> I don't really have a SPI flash connected to DSPI on any LS1028A 
>> board.
> 
> I'm already debugging it again.

Ok now maybe a more experienced kernel developer could have a look at 
this.

(1) the error is EIO because the actual_length doesn't match the 
expected
     length
(2) I've put trace_printk() where the actual_length is modified:
     in dspi_fifo_write()

         /* Update total number of bytes that were transferred */
         bytes_sent = dspi->words_in_flight * dspi->oper_word_size;
         msg->actual_length += bytes_sent;
         trace_printk("msg=%px actual_length=%d bytes_sent=%d 
word_in_flight=%d oper_word_size=%d\n",
                         msg, msg->actual_length,
                         bytes_sent, dspi->words_in_flight,
                         dspi->oper_word_size);
         dspi->progress += bytes_sent / DIV_ROUND_UP(xfer->bits_per_word, 
8);

    At the start of the foreach transfer loop in 
dspi_transfer_one_message():

         list_for_each_entry(transfer, &message->transfers, 
transfer_list) {
                 trace_printk("%d transfer->length=%d\n", i++, 
transfer->len);
                 dspi->cur_transfer = transfer;

    And at the end of this function:


         }
         trace_printk("returning actual_length=%d\n", 
message->actual_length);

         message->status = status;
         spi_finalize_current_message(ctlr);

         return status;

(3) The trace is attached at the end of this mail. There is a good case 
and the
     bad one. What I've noticed (besides returning the wrong count, eg 
13, which
     seems to be the first one) is the preempt-depth which is always none 
in the
     bad case. In all transfers before, the preempt-depth is 1. The flags 
are
     usually "d.h1", sometimes "d.H1" and in case of the error "d.H.".
     I also don't know why the fifo_write() with actual_length=13 is 
traced after
     all the ones printed inside the interrupt handler. Also something 
seems to
     be off with the words_in_flight and oper_word_size in the bad case.

     So besides the flags.. I still think there is a race between the
     dspi_fifo_write() call in transfer_one_message and the interrupt 
handler
     for the shared data like words_in_flight and oper_word_size.


good one:
               dd-1259  [000] ....  3383.499863: 
dspi_transfer_one_message: 0 transfer->length=1
               dd-1259  [000] ....  3383.499886: dspi_fifo_write: 
msg=ffff800011973840 actual_length=1 bytes_sent=1 word_in_flight=1 
oper_word_size=1
               dd-1259  [000] ....  3383.499891: 
dspi_transfer_one_message: 1 transfer->length=3
               dd-1259  [000] ....  3383.499915: dspi_fifo_write: 
msg=ffff800011973840 actual_length=4 bytes_sent=3 word_in_flight=3 
oper_word_size=1
               dd-1259  [000] ....  3383.499920: 
dspi_transfer_one_message: 2 transfer->length=1
               dd-1259  [000] ....  3383.499940: dspi_fifo_write: 
msg=ffff800011973840 actual_length=5 bytes_sent=1 word_in_flight=1 
oper_word_size=1
               dd-1259  [000] ....  3383.499946: 
dspi_transfer_one_message: 3 transfer->length=64
               dd-1259  [000] d.h1  3383.499973: dspi_fifo_write: 
msg=ffff800011973840 actual_length=21 bytes_sent=8 word_in_flight=2 
oper_word_size=4
               dd-1259  [000] d.h1  3383.499993: dspi_fifo_write: 
msg=ffff800011973840 actual_length=29 bytes_sent=8 word_in_flight=2 
oper_word_size=4
               dd-1259  [000] d.h1  3383.500013: dspi_fifo_write: 
msg=ffff800011973840 actual_length=37 bytes_sent=8 word_in_flight=2 
oper_word_size=4
               dd-1259  [000] d.h1  3383.500032: dspi_fifo_write: 
msg=ffff800011973840 actual_length=45 bytes_sent=8 word_in_flight=2 
oper_word_size=4
               dd-1259  [000] d.h1  3383.500051: dspi_fifo_write: 
msg=ffff800011973840 actual_length=53 bytes_sent=8 word_in_flight=2 
oper_word_size=4
               dd-1259  [000] d.h1  3383.500070: dspi_fifo_write: 
msg=ffff800011973840 actual_length=61 bytes_sent=8 word_in_flight=2 
oper_word_size=4
               dd-1259  [000] d.h1  3383.500089: dspi_fifo_write: 
msg=ffff800011973840 actual_length=69 bytes_sent=8 word_in_flight=4 
oper_word_size=2
               dd-1259  [000] ....  3383.500107: dspi_fifo_write: 
msg=ffff800011973840 actual_length=13 bytes_sent=8 word_in_flight=2 
oper_word_size=4
               dd-1259  [000] ....  3383.500111: 
dspi_transfer_one_message: returning actual_length=69

bad one:
               dd-1259  [000] ....  3383.500149: 
dspi_transfer_one_message: 0 transfer->length=1
               dd-1259  [000] ....  3383.500172: dspi_fifo_write: 
msg=ffff800011973840 actual_length=1 bytes_sent=1 word_in_flight=1 
oper_word_size=1
               dd-1259  [000] ....  3383.500178: 
dspi_transfer_one_message: 1 transfer->length=3
               dd-1259  [000] ....  3383.500202: dspi_fifo_write: 
msg=ffff800011973840 actual_length=4 bytes_sent=3 word_in_flight=3 
oper_word_size=1
               dd-1259  [000] ....  3383.500207: 
dspi_transfer_one_message: 2 transfer->length=1
               dd-1259  [000] ....  3383.500227: dspi_fifo_write: 
msg=ffff800011973840 actual_length=5 bytes_sent=1 word_in_flight=1 
oper_word_size=1
               dd-1259  [000] ....  3383.500232: 
dspi_transfer_one_message: 3 transfer->length=64
               dd-1259  [000] d.H.  3383.500286: dspi_fifo_write: 
msg=ffff800011973840 actual_length=13 bytes_sent=8 word_in_flight=2 
oper_word_size=4
               dd-1259  [000] d.H.  3383.500307: dspi_fifo_write: 
msg=ffff800011973840 actual_length=21 bytes_sent=8 word_in_flight=2 
oper_word_size=4
               dd-1259  [000] d.H.  3383.500327: dspi_fifo_write: 
msg=ffff800011973840 actual_length=29 bytes_sent=8 word_in_flight=2 
oper_word_size=4
               dd-1259  [000] d.H.  3383.500347: dspi_fifo_write: 
msg=ffff800011973840 actual_length=37 bytes_sent=8 word_in_flight=2 
oper_word_size=4
               dd-1259  [000] d.H.  3383.500366: dspi_fifo_write: 
msg=ffff800011973840 actual_length=45 bytes_sent=8 word_in_flight=2 
oper_word_size=4
               dd-1259  [000] d.H.  3383.500385: dspi_fifo_write: 
msg=ffff800011973840 actual_length=53 bytes_sent=8 word_in_flight=2 
oper_word_size=4
               dd-1259  [000] d.H.  3383.500404: dspi_fifo_write: 
msg=ffff800011973840 actual_length=61 bytes_sent=8 word_in_flight=4 
oper_word_size=2
               dd-1259  [000] ....  3383.500436: dspi_fifo_write: 
msg=ffff800011973840 actual_length=13 bytes_sent=8 word_in_flight=4 
oper_word_size=2
               dd-1259  [000] ....  3383.500441: 
dspi_transfer_one_message: returning actual_length=13


-michael

Powered by blists - more mailing lists