terminated ioc 804b scsi 0 state c xfer 0

Tue May 10 11:10:08 UTC 2016

> On Apr 25, 2016, at 12:30 PM, Scott Long via freebsd-scsi <freebsd-scsi at freebsd.org> wrote:
> 
> 
>> On Apr 25, 2016, at 10:38 AM, Stephen McConnell via freebsd-scsi <freebsd-scsi at freebsd.org> wrote:
>> 
>> 
>> 
>>> -----Original Message-----
>>> From: owner-freebsd-scsi at freebsd.org [mailto:owner-freebsd-
>>> scsi at freebsd.org] On Behalf Of Dan Langille
>>> Sent: Monday, April 25, 2016 9:40 AM
>>> To: freebsd-scsi at freebsd.org
>>> Subject: Re: terminated ioc 804b scsi 0 state c xfer 0
>>> 
>>>>> On Apr 25, 2016, at 8:17 AM, Dan Langille <dan at langille.org> wrote:
>>>>> 
>>>>> 
>>>>> On Apr 24, 2016, at 9:35 AM, Dan Langille <dan at langille.org> wrote:
>>>>> 
>>>>> More of the pasted output is also at
>>> https://gist.github.com/dlangille/1fa3135334089c6603e2ec5da946d9ae
>>> <https://gist.github.com/dlangille/1fa3135334089c6603e2ec5da946d9ae>
>>> and added smartctl output.
>>>>> 
>>>>> I have a FreeBSD 10.2-RELEASE-p14 box in which there is an LSI SAS2008
>>> card.  It's running a zfs root system.
>>>>> 
>>>>> This morning the system was unresponsive via ssh. Attempts to log in at
>>> the console did not yield a password prompt.
>>>>> 
>>>>> A power cycle brought the system online.  Inspecting /var/log/messages,
>> I
>>> found about 63,000 entries similar to those which appear below.
>>>>> 
>>>>> zpool status of all are OK. A scrub is in progress for one pool (since
>> before
>>> this issue arose). da7 is in that pool.
>>>>> 
>>>>> 
>>>>> Apr 24 11:25:55 knew kernel: (da7:mps1:0:17:0): READ(10). CDB: 28 00
>>>>> 8d 90 c6 18 00 00 10 00 length 8192 SMID 774 terminated ioc 804b scsi
>>>>> 0 state c xfer 0 Apr 24 11:25:55 knew kernel: (da7:mps1:0:17:0):
>>>>> READ(10). CDB: 28 00 8b d9 97 70 00 00 20 00 length 16384 SMID 614
>>>>> terminated ioc 804b scsi 0 state c xfer 0 Apr 24 11:25:55 knew
>>>>> kernel: (da7:mps1:0:17:0): READ(10). CDB: 28 00 8b d9 97 50 00 00 20
>>>>> 00 length 16384 SMID 792 terminated ioc 804b scsi 0 state c xfer 0
>>>>> Apr 24 11:25:55 knew kernel: (da7:mps1:0:17:0): READ(10). CDB: 28 00
>>>>> 8b d9 97 08 00 00 20 00 length 16384 SMID 974 terminated ioc 804b
>>>>> scsi 0 state c xfer 0 Apr 24 11:25:55 knew kernel: (da7:mps1:0:17:0):
>>>>> READ(10). CDB: 28 00 8b 6f ef 50 00 00 08 00 length 4096 SMID 674
>>>>> terminated ioc 804b scsi 0 state c xfer 0 Apr 24 11:25:55 knew
>>>>> kernel: (da7:mps1:0:17:0): WRITE(10). CDB: 2a 00 8b 0f a2 48 00 00 18
>>>>> 00 length 12288 SMID 177 terminated ioc 804b scsi 0 state c xfer
>>>>> 12288 Apr 24 11:25:55 knew kernel: (da7:mps1:0:17:0): READ(10). CDB:
>>>>> 28 00 ab 8f a1 38 00 00 08 00 length 4096 SMID 908 terminated ioc
>>>>> 804b scsi 0 state c xfer 0 Apr 24 11:25:56 knew kernel:
>>>>> (da7:mps1:0:17:0): READ(10). CDB: 28 00 8b d9 97 70 00 00 20 00
>>>>> length 16384 SMID 376 terminated ioc 804b scsi 0 state c xfer 0 Apr
>>>>> 24 11:25:56 knew kernel: (da7:mps1:0:17:0): READ(10). CDB: 28 00 8b
>>>>> d9 97 50 00 00 20 00 length 16384 SMID 172 terminated ioc 804b scsi 0
>>>>> state c xfer 0
>>>>> 
>>>>> Is this a cabling issue?  The drive is a SATA device (smartctl output
>> in the
>>> URL above).  Anyone familiar with these errors?
>>>> 
>>>> This morning:
>>>> 
>>>> 13410079654596185797  REMOVED      0     0     0  was /dev/da7p3
>>>> 
>>>> At least I know i'm looking for Serial Number: 13Q8PNBYS
>>>> 
>>>> From the logs:
>>>> 
>>>> Apr 25 05:34:50 knew kernel: da7 at mps1 bus 0 scbus1 target 17 lun 0
>>>> Apr 25 05:34:50 knew kernel: da7: <ATA TOSHIBA DT01ACA3 ABB0> s/n
>>> 13Q8PNBYS detached
>>>> Apr 25 05:34:51 knew kernel: (da7:mps1:0:17:0): READ(10). CDB: 28 00
>>>> d8 33 53 e0 00 00 08 00 length 4096 SMID 88 terminated ioc 804b scsi 0
>>>> state c xfer 0 Apr 25 05:34:51 knew kernel: (da7:mps1:0:17:0):
>>>> READ(10). CDB: 28 00 d8 33 26 f8 00 00 20 00 length 16384 SMID 204
>>>> terminated ioc 804b scsi 0 state c xfer(da7:mps1:0:17:0): READ(10). CDB:
>> 28
>>> 00 d8 33 53 e0 00 00 08 00 Apr 25 05:34:51 knew kernel: 0 Apr 25 05:34:51
>>> knew kernel: (da7:mps1:0:17:0): CAM status: Unconditionally Re-queue
>>> Request Apr 25 05:34:51 knew kernel: (da7:mps1:0:17:0): READ(10). CDB: 28
>>> 00 d8 33 26 d8 00 00 20 00 length 16384 SMID 260 terminated ioc 804b scsi
>> 0
>>> state c xfer(da7: 0
>>>> Apr 25 05:34:51 knew kernel: mps1:0:    (da7:mps1:0:17:0): READ(10).
>> CDB:
>>> 28 00 e6 6c 42 40 00 00 10 00 length 8192 SMID 484 terminated ioc 804b
>> scsi 0
>>> state c xfer 17:0
>>>> Apr 25 05:34:51 knew kernel: 0):        (da7:mps1:0:17:0): WRITE(10).
>> CDB: 2a
>>> 00 e4 d8 2a 90 00 00 90 00 length 73728 SMID 548 terminated ioc 804b scsi
>> 0
>>> state c xfeError 5, Periph was invalidated
>>>> Apr 25 05:34:51 knew kernel: r 0
>>>> Apr 25 05:34:51 knew kernel: (da7:mps1:0:17:0): READ(10). CDB: 28 00
>>>> d8 33 26 f8 00 00 20 00 Apr 25 05:34:51 knew kernel:
>>>> (da7:mps1:0:17:0): READ(10). CDB: 28 00 4d ac ed b8 00 00 08 00 length
>>>> 4096 SMID 435 terminated ioc 804b scsi 0 state c xfer
>>>> (da7:mps1:0:17:0): CAM status: Unconditionally Re-queue Request Apr 25
>>>> 05:34:51 knew kernel: 0 Apr 25 05:34:51 knew kernel: (da7:mps1:
>>>> mps1:0:IOCStatus = 0x4b while resetting device 0xa Apr 25 05:34:51
>>>> knew kernel: 17:mps1: 0): Unfreezing devq for target ID 17 Apr 25
>>>> 05:34:51 knew kernel: Error 5, Periph was invalidated Apr 25 05:34:51
>>>> knew kernel: (da7:mps1:0:17:0): READ(10). CDB: 28 00 d8 33 26 d8 00 00
>>>> 20 00 Apr 25 05:34:51 knew kernel: (da7:mps1:0:17:0): CAM status:
>>>> Unconditionally Re-queue Request Apr 25 05:34:51 knew kernel:
>>>> (da7:mps1:0:17:0): Error 5, Periph was invalidated Apr 25 05:34:51
>>>> knew kernel: (da7:mps1:0:17:0): READ(10). CDB: 28 00 e6 6c 42 40 00 00
>>>> 10 00 Apr 25 05:34:51 knew kernel: (da7:mps1:0:17:0): CAM status:
>>>> Unconditionally Re-queue Request Apr 25 05:34:51 knew kernel:
>>>> (da7:mps1:0:17:0): Error 5, Periph was invalidated Apr 25 05:34:51
>>>> knew kernel: (da7:mps1:0:17:0): WRITE(10). CDB: 2a 00 e4 d8 2a 90 00
>>>> 00 90 00 Apr 25 05:34:51 knew kernel: (da7:mps1:0:17:0): CAM status:
>>> Unconditionally Re-queue Request Apr 25 05:34:51 knew kernel:
>>> (da7:mps1:0:17:0): Error 5, Periph was invalidated Apr 25 05:34:51 knew
>>> kernel: (da7:mps1:0:17:0): READ(10). CDB: 28 00 4d ac ed b8 00 00 08 00
>> Apr
>>> 25 05:34:51 knew kernel: (da7:mps1:0:17:0): CAM status: Unconditionally
>> Re-
>>> queue Request Apr 25 05:34:51 knew kernel: (da7:mps1:0:17:0): Error 5,
>>> Periph was invalidated Apr 25 05:34:51 knew kernel: GEOM_MIRROR: Device
>>> swap: provider da7p2 disconnected.
>>>> Apr 25 05:34:51 knew devd: Executing 'logger -p kern.notice -t ZFS 'vdev
>> is
>>> removed, pool_guid=15378250086669402288
>>> vdev_guid=13410079654596185797''
>>>> Apr 25 05:34:51 knew kernel: (da7:mps1:0:17:0): Periph destroyed Apr
>>>> 25 05:34:51 knew ZFS: vdev is removed, pool_guid=15378250086669402288
>>>> vdev_guid=13410079654596185797
>>> 
>>> Current status: after powering off the box, reseating the cables for that
>> drive, I
>>> powered up the system and a resilver commenced which completed in 30
>>> minutes.
>>> 
>>> Seems OK now.  I am not sure if the two events are related.
>> 
>> Recently, a bug was uncovered where a device is gets 'lost'.
>> 
>> Here's what happens:
>> The first message in your "failure on Monday"  log is for
>> 'mpssas_prepare_remove'.  This message is likely logged because the FW sends
>> an event to the driver that the device is no longer responsive (pulled,
>> cable issue, or something else).  When the driver gets this event, it sends
>> a reset to the device to clear out any pending I/O.  This is where the
>> 'terminated ioc' messages come from.  When the reset completes, the driver
>> is supposed to send a SAS_IO_UNIT message to FW so that the DevHandle for
>> that disk is removed from FW's list.  Then, when the device comes back
>> on-line, everything is fine. But, with this bug, before that SAS_IO_UNIT
>> message is sent to FW, the driver exits the function where that happens
>> (mpssas_remove_device).  This happens where you see the log message,
>> "IOCStatus - 0x4b while resetting device 0x0a".  The driver logs that
>> message and then exits.  What the driver should do is log that message and
>> continue on to send the SAS_IO_UNIT message to FW.  The fix is to remove the
>> two lines in the driver shown here with '>>':
>> 
>>    if (le16toh(reply->IOCStatus) != MPI2_IOCSTATUS_SUCCESS) {
>>        mps_printf(sc, "IOCStatus = 0x%x while resetting device
>> 0x%x\n",
>>           le16toh(reply->IOCStatus), handle);
>>>>        mpssas_free_tm(sc, tm);
>>>>        return;
>>    }
>> 
>> A reboot will solve the problem, as you saw, but the real fix is to remove
>> the DevHandle as described above.  This fix will go into the driver before
>> the next scheduled release and then MFC'd to 10.x.
> 
> Thanks for the diagnosis, Steve.  I forgot about that case.  We should also make
> this chain of events more evident in the syslog, it’s very confusing when it happens.
> I’m not exactly sure yet what it should look like.
> 
> Scott
> 

Steve,

We are seeing this same error case for mpr and mps in FreeNAS. We are decoupled from FreeBSD releases and have an auto-update mechanism.

I'd be very happy to test patches against stable/10 on our nightly users. 