scst_vdisk: Resize-fsync() race fails IO

DISCUSSION Sebastian Parschauer 1 participant 2 messages Mar 21, 2016 – Mar 24, 2016 4 messages not in the archive SCSI

lore

Share & tools

lore

A message that is not in the archive (sent off-list or not yet received): [email protected]

Sebastian Parschauer

author

2016-03-21 15:22 UTC #1 lore raw

Quoted 26 lines · Sebastian Parschauer

Hi,
we are live resizing LVM LVs below SCST/SRP but we only increase the size.
Writing to /sys/kernel/scst_tgt/devices/$DEV/resync_size with a new device size races against fsync() from the SRP initiator so that IO is failed. Resizing SCST devices only with reads/writes going on works.
With the vdisk_fileio handler this is quite sporadic but with vdisk_blockio it can be triggered immediately.
I'm attaching my LV resizing test script and the fsync() script run on the initiator on top of ib_srp devices.
I suspect an issue with usage of virt_dev->file_size in vdisk_synchronize_cache() at
https://sourceforge.net/p/scst/svn/HEAD/tree/trunk/scst/src/dev_handlers/scst_vdisk.c#l1866.
Cheers,
Sebastian
=== Details ===
Error in kernel log:

Quoted 9 lines

[69514.891904] sd 10:0:0:1: Capacity data has changed
[69514.891962] end_request: I/O error, dev sdc, sector 0
fsync script output:
Traceback (most recent call last):
File "<string>", line 1, in <module>
OSError: [Errno 5] Input/output error

+CC: linux-scsi, hch

Hi SCSI developers,

I've debugged this further with a v4.5 kernel and full SCSI command logging enabled on the initiator side. It seems to be a SCSI issue. SCSI commands succeed but result 8000002 is reported to the upper driver which seems to fail IO.

What does result 8000002 mean?

Please help me to fix the issue.

Thanks,
Sebastian

dmesg output of the IO error with SCSI debugging:

Quoted 25 lines

[   84.450906] sd 6:0:0:1: [sdc] sd_open
[   84.451008] sd 6:0:0:1: scsi_block_when_processing_errors: rtn: 1
[   84.451084] sd 6:0:0:1: [sdc] tag#1 Send: scmd 0xffff880210357080
[   84.451143] sd 6:0:0:1: [sdc] tag#1 CDB: Synchronize Cache(10) 35 00 00 00 00 00 00 00 00 00
[   84.456081] sd 6:0:0:1: [sdc] tag#0 Done: SUCCESS Result: hostbyte=DID_OK driverbyte=DRIVER_OK
[   84.456209] sd 6:0:0:1: [sdc] tag#0 CDB: Read(10) 28 00 00 00 01 10 00 00 08 00
[   84.456295] sd 6:0:0:1: [sdc] tag#0 scsi host busy 2 failed 0
[   84.456374] sd 6:0:0:1: Notifying upper driver of completion (result 0)
[   84.456438] sd 6:0:0:1: [sdc] tag#0 sd_done: completed 4096 of 4096 bytes
[   84.456498] sd 6:0:0:1: [sdc] tag#0 8 sectors total, 4096 bytes done.
[   84.456595] sd 6:0:0:1: Capacity data has changed
[   84.456612] sd 6:0:0:1: [sdc] sd_setup_read_write_cmnd: block=280, count=8
[   84.456616] sd 6:0:0:1: [sdc] block=280
[   84.456620] sd 6:0:0:1: [sdc] reading 8/8 512 byte blocks.
[   84.456628] sd 6:0:0:1: [sdc] tag#0 Send: scmd 0xffff8800ca41ed80
[   84.456634] sd 6:0:0:1: [sdc] tag#0 CDB: Read(10) 28 00 00 00 01 18 00 00 08 00
[   84.457003] sd 6:0:0:1: [sdc] tag#1 Done: SUCCESS Result: hostbyte=DID_OK driverbyte=DRIVER_OK
[   84.457090] sd 6:0:0:1: [sdc] tag#1 CDB: Synchronize Cache(10) 35 00 00 00 00 00 00 00 00 00
[   84.457211] sd 6:0:0:1: [sdc] tag#1 Sense Key : Unit Attention [current] 
[   84.457272] sd 6:0:0:1: [sdc] tag#1 Add. Sense: Capacity data has changed
[   84.457331] sd 6:0:0:1: [sdc] tag#1 scsi host busy 2 failed 0
[   84.457387] sd 6:0:0:1: Notifying upper driver of completion (result 8000002)
[   84.457445] sd 6:0:0:1: [sdc] tag#1 sd_done: completed 0 of 0 bytes
[   84.457503] sd 6:0:0:1: [sdc] tag#1 0 sectors total, 0 bytes done.
[   84.457562] blk_update_request: I/O error, dev sdc, sector 0

Quoted 8 lines

[   84.457637] sd 6:0:0:1: [sdc] tag#0 Done: SUCCESS Result: hostbyte=DID_OK driverbyte=DRIVER_OK
[   84.457757] sd 6:0:0:1: [sdc] tag#0 CDB: Read(10) 28 00 00 00 01 18 00 00 08 00
[   84.457842] sd 6:0:0:1: [sdc] tag#0 scsi host busy 1 failed 0
[   84.457899] sd 6:0:0:1: Notifying upper driver of completion (result 0)
[   84.457959] sd 6:0:0:1: [sdc] tag#0 sd_done: completed 4096 of 4096 bytes
[   84.458019] sd 6:0:0:1: [sdc] tag#0 8 sectors total, 4096 bytes done.
[   84.458111] sd 6:0:0:1: [sdc] sd_setup_read_write_cmnd: block=288, count=8
[   84.458180] sd 6:0:0:1: [sdc] block=288

#!/bin/bash

set -e
#set -x

FILE1="/dev/storage/vol1"
INC=4

do_resize() {
    FILE=$1
    DEV=`basename $FILE`
    echo "FILE: $FILE"
    SIZE=`blockdev --getsize64 $FILE`
    let "SIZE /= (1024 * 1024)"
    echo "SIZE: $SIZE"
    let "SIZE += INC"
    echo "NEW_SIZE: $SIZE"
    lvresize -L "+${INC}M" $FILE >/dev/null
    SIZE=`blockdev --getsize64 $FILE`
    let "SIZE /= (1024 * 1024)"
    echo "SET_SIZE: $SIZE"
    echo 1 > /sys/kernel/scst_tgt/devices/$DEV/resync_size
}

while [ 1 ]; do
do_resize $FILE1
done

#!/bin/bash

# test resize on storage while we do fsync()s all the time
# on the SRP initiator

DEV=/dev/sdc

RC=0
while [ $RC -eq 0 ]; do

    python -c "import os; os.fsync(os.open('$DEV', os.O_RDWR))"
    RC=$?

done

A message that is not in the archive (sent off-list or not yet received): [email protected]

Sebastian Parschauer

author

2016-03-24 09:46 UTC #5 lore raw

Re: sd: Resize-fsync() race fails IO

On 24.03.2016 05:11, Vladislav Bolkhovitin wrote:
[snip]

Quoted 17 lines

Quoted 17 lines
Quoted 9 lines
Quoted 9 lines
+CC: linux-scsi, hch
Hi SCSI developers,
I've debugged this further with a v4.5 kernel and full SCSI command logging enabled on the initiator side. It seems to be a SCSI issue. SCSI commands succeed but result 8000002 is reported to the upper driver which seems to fail IO.
Quoted 4 lines
Quoted 1 line
What does result 8000002 mean?
It is driver_byte() DID_RESET and status_byte() CHECK_CONDITION (see the corresponding kernel's functions). It sounds like you have timeouts and resets somewhere.
Thanks for the hint! But it is definitely not DID_RESET. It is DRIVER_SENSE and CHECK_CONDITION then. The host byte is DID_OK.

Quoted 8 lines

Quoted 5 lines
If Unit Attention and "Capacity data has changed" is part of a read or a write, then the result is the same but this is handled correctly and IO is not failed. But with a zero bytes fsync()/flush resulting in SYNCHRONIZE_CACHE_16, it fails IO as the sd driver doesn't handle this correctly it seems.
I'm not sure, what is not handled correctly? Zero length SYNCHRONIZE_CACHE is perfectly legal, and vdisk_fsync() should never see data_len 0.

The issue is located in the SCSI stack. I think the problem is located in the sd driver. It can't handle zero length SYNCHRONIZE_CACHE together with UA and "Capacity data changed". The race exists to which SCSI command UA is put to.

Quoted 5 lines

There should be no race around virt_dev->file_size, because assignments to 64-bit integers are atomic, the compiler supposed to align it to 64-bit boundaries and it's never assigned to any invalid value. At worst, accesses to it should be covered by ACCESS_ONCE(), but I'm not sure it is really needed, so would prefer to keep it away from the fast path. Although, probably, vdisk_synchronize_cache() is not too fast path.

SCST is fine. I couldn't break it with my tests. It succeeds the commands but the sd driver fails IO because of the sense data.

So discussion should be moved to the linux-scsi list again. I've changed the prefix in the subject from "scst_vdisk" to "sd".

[snip]