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

[Sebastian Parschauer <sebastian.riemer@profitbricks.com>]

[-- Attachment #1: Type: text/plain, Size: 4021 bytes --]

On 18.03.2016 13:08, Sebastian Parschauer wrote:
> 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:
> 
> [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:

> [   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
> [   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

[-- Attachment #2: resize_vol1.sh.txt --]
[-- Type: text/plain, Size: 523 bytes --]

#!/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

[-- Attachment #3: test_resize_fsync.sh.txt --]
[-- Type: text/plain, Size: 218 bytes --]

#!/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