Bug 219419

The strategy to handle device resets in st is conservative because it is used for archives and backups: if there is any indication of possible bus reset, make the user retry. So, I think that any POR UA should set pos_unknown, unless it can be proved false in all possible cases.

The EIO response to MTIOCGET results from calling flush_buffer(). But, looking at the code, it seems to be called twice. First, pos_unknown is tested and flush_buffer() only if pos_unknown is false. If it is true, some commands, including MTIOCGET, can continue. But, later there is an unconditional call to flush_buffer(). I have to look at the history to see why there are two calls. I don't have enough time for that tonight, but I will continue later.

Created attachment 307074 [details]
st-mtiocget-pos_unknown-1.diff

The first flush_buffer() was for only MTIOCTOP.

The attached patch (against current torvalds/linux.git) should enable MTIOCGET also after device reset. The received data should be correct as far as it can (which is not much). (The modified st compiles, but I can't test it because I don't have access to any tape hardware any more.)

One thing puzzles me though: is MTIOCGET failing after device reset a bug or a feature? Is someone using the fact that it fails to gain some information?

OK. I will test out this patch.

Here's an example of how not everything works as expected after sg_reset.

When I unload the tape and then reset the tape drive, I am unable to to issue the load command.

[root@to-be-determined ~]# mt -f /dev/nst0 status
SCSI 2 tape drive:
File number=-1, block number=-1, partition=0.
Tape block size 0 bytes. Density code 0x0 (default).
Soft error count since last status=0
General status bits on (50000):
 DR_OPEN IM_REP_EN
[root@to-be-determined ~]# mt -f /dev/nst0 load
/dev/nst0: Input/output error

Well, status succeeded ;-)

Load is failing probably because it is not in the list of allowed commands after reset
(as it should be). The attached patch adds fix to this (the second item starting from
line 3619).

(Now the patch already includes two bug fixes, in addition to allowing MTIOCGET
after reset.)

Created attachment 307083 [details]
st-mtiocget-pos_unknown-2.diff

The new patch.

OK, good news.  Your patch fixed pretty much all of the problems.

I'm attaching some before and after log files from my test runs.

The tests I ran can be seen here:

 https://github.com/johnmeneghini/tape_tests

Please take a quick look at these tests/logs and let me know if the tests are valid and you agree the results are good.

Thanks.

Created attachment 307093 [details]
Failing test logs

Test log showing failures with the tape_reset_test before the proposed patch.

Tests run are from: https://github.com/johnmeneghini/tape_tests

Created attachment 307094 [details]
Failing scsi_debug test logs

Test log showing failures with the tape_reset_debug test before the proposed patch.

Tests run are from: https://github.com/johnmeneghini/tape_tests

mt -f $DEV status
SCSI 2 tape drive:
File number=1, block number=0, partition=0.
Tape block size 0 bytes. Density code 0x46 (LTO-4).
Soft error count since last status=0
General status bits on (81010000):
 EOF ONLINE IM_REP_EN
dd if=$DEV count=1024 of=/dev/null
1024+0 records in
1024+0 records out
524288 bytes (524 kB, 512 KiB) copied, 0.101394 s, 5.2 MB/s
mt -f $DEV status
SCSI 2 tape drive:
File number=1, block number=1024, partition=0.
Tape block size 0 bytes. Density code 0x46 (LTO-4).
Soft error count since last status=0
General status bits on (1010000):
 ONLINE IM_REP_EN
mt -f $DEV eod
mt -f $DEV status
/dev/nst0: Input/output error

Here's an example of why we need to clear was_reset every time we clear pos_unkown.  

See my attached patch.

[Wed Oct 30 16:19:35 2024] st 6:0:0:0: [st0] st_flush: 1386: pos_unknown 0x0 was_reset 0x1 ready 0x0
[Wed Oct 30 16:19:35 2024] st 6:0:0:0: [st0] Number of r/w requests 1024, dio used in 1024, pages 1024.
[Wed Oct 30 16:19:35 2024] st 6:0:0:0: [st0] flush_buffer: 844: pos_unknown 0x0 was_reset 0x1 ready 0x0
[Wed Oct 30 16:19:35 2024] st 6:0:0:0: [st0] check_tape: 1064: pos_unknown 0x0 was_reset 0x1 ready 0x0
[Wed Oct 30 16:19:35 2024] st 6:0:0:0: [st0] Block limits 1 - 16777215 bytes.
[Wed Oct 30 16:19:35 2024] st 6:0:0:0: [st0] Mode sense. Length 11, medium 0, WBS 10, BLL 8
[Wed Oct 30 16:19:35 2024] st 6:0:0:0: [st0] Density 46, tape length: 0, drv buffer: 1
[Wed Oct 30 16:19:35 2024] st 6:0:0:0: [st0] Block size: 0, buffer size: 4096 (1 blocks).
[Wed Oct 30 16:19:35 2024] st 6:0:0:0: [st0] check_tape: 1265: CHKRES_READY pos_unknown 0x0 was_reset 0x1 ready 0x0
[Wed Oct 30 16:19:35 2024] st 6:0:0:0: [st0] flush_buffer: 844: pos_unknown 0x0 was_reset 0x1 ready 0x0
[Wed Oct 30 16:19:35 2024] st 6:0:0:0: [st0] st_flush: 1386: pos_unknown 0x0 was_reset 0x1 ready 0x0
[Wed Oct 30 16:19:35 2024] st 6:0:0:0: [st0] flush_buffer: 844: pos_unknown 0x0 was_reset 0x1 ready 0x0
[Wed Oct 30 16:19:35 2024] st 6:0:0:0: [st0] check_tape: 1064: pos_unknown 0x0 was_reset 0x1 ready 0x0
[Wed Oct 30 16:19:35 2024] st 6:0:0:0: [st0] Block limits 1 - 16777215 bytes.
[Wed Oct 30 16:19:35 2024] st 6:0:0:0: [st0] Mode sense. Length 11, medium 0, WBS 10, BLL 8
[Wed Oct 30 16:19:35 2024] st 6:0:0:0: [st0] Density 46, tape length: 0, drv buffer: 1
[Wed Oct 30 16:19:35 2024] st 6:0:0:0: [st0] Block size: 0, buffer size: 4096 (1 blocks).
[Wed Oct 30 16:19:35 2024] st 6:0:0:0: [st0] check_tape: 1265: CHKRES_READY pos_unknown 0x0 was_reset 0x1 ready 0x0
[Wed Oct 30 16:19:35 2024] st 6:0:0:0: [st0] flush_buffer: 844: pos_unknown 0x0 was_reset 0x1 ready 0x0
[Wed Oct 30 16:19:35 2024] st 6:0:0:0: [st0] Spacing tape forward over 8388607 filemarks.

[Wed Oct 30 16:19:48 2024] st 6:0:0:0: [st0] Error: 402, cmd: 11 1 7f ff ff 0
[Wed Oct 30 16:19:48 2024] st 6:0:0:0: [st0] Sense Key : Blank Check [current] 
[Wed Oct 30 16:19:48 2024] st 6:0:0:0: [st0] Add. Sense: End-of-data detected

^^^ this check condition at eod re-asserts pos_unknown.

[Wed Oct 30 16:19:48 2024] st 6:0:0:0: [st0] st_chk_result: 424: pos_unknown 0x1 was_reset 0x1 ready 0x0, result 1026
[Wed Oct 30 16:19:48 2024] st 6:0:0:0: [st0] st_flush: 1386: pos_unknown 0x1 was_reset 0x1 ready 0x0
[Wed Oct 30 16:19:48 2024] st 6:0:0:0: [st0] flush_buffer: 844: pos_unknown 0x1 was_reset 0x1 ready 0x0
[Wed Oct 30 16:19:48 2024] st 6:0:0:0: [st0] check_tape: 1064: pos_unknown 0x1 was_reset 0x1 ready 0x0
[Wed Oct 30 16:19:48 2024] st 6:0:0:0: [st0] Block limits 1 - 16777215 bytes.
[Wed Oct 30 16:19:48 2024] st 6:0:0:0: [st0] Mode sense. Length 11, medium 0, WBS 10, BLL 8
[Wed Oct 30 16:19:48 2024] st 6:0:0:0: [st0] Density 46, tape length: 0, drv buffer: 1
[Wed Oct 30 16:19:48 2024] st 6:0:0:0: [st0] Block size: 0, buffer size: 4096 (1 blocks).
[Wed Oct 30 16:19:48 2024] st 6:0:0:0: [st0] check_tape: 1265: CHKRES_READY pos_unknown 0x1 was_reset 0x1 ready 0x0
[Wed Oct 30 16:19:48 2024] st 6:0:0:0: [st0] flush_buffer: 844: pos_unknown 0x1 was_reset 0x1 ready 0x0
[Wed Oct 30 16:19:48 2024] st 6:0:0:0: [st0] st_flush: 1386: pos_unknown 0x1 was_reset 0x1 ready 0x0
[Wed Oct 30 16:19:48 2024] st 6:0:0:0: [st0] flush_buffer: 844: pos_unknown 0x1 was_reset 0x1 ready 0x0

Created attachment 307095 [details]
Simple patch to clear was_reset

> git diff HEAD^^ HEAD^ > clear_was_reset.patch
 
> git show HEAD^
commit c5d061be5eab53d9c7ef13260d41bd39dcf1e70b
Author: John Meneghini <jmeneghi@redhat.com>
Date:   Wed Oct 23 15:55:05 2024 -0400

    scsi: st: clear was_reset when CHKRES_NEW_SESSION
    
    Be sure to clear was_reset when ever we clear pos_unknown. If we don't
    then the code in st_chk_result() will turn on pos_unknown again.
    
            STp->pos_unknown |= STp->device->was_reset;
    
    This results in confusion as future commands fail unexpectedly.
    
    Signed-off-by: John Meneghini <jmeneghi@redhat.com>

diff --git a/drivers/scsi/st.c b/drivers/scsi/st.c
index 9c0f9779768e..e9d1cb6c8a86 100644
--- a/drivers/scsi/st.c
+++ b/drivers/scsi/st.c
@@ -1083,6 +1083,7 @@ static int check_tape(struct scsi_tape *STp, struct file *filp)
 
        if (retval == CHKRES_NEW_SESSION) {
                STp->pos_unknown = 0;
+               STp->device->was_reset = 0;
                STp->partition = STp->new_partition = 0;
                if (STp->can_partitions)
                        STp->nbr_partitions = 1; /* This guess will be updated later

Created attachment 307097 [details]
Passing test logs

Test logs collected from a test run with the patches from:

 https://lore.kernel.org/linux-scsi/20241031010032.117296-1-jmeneghi@redhat.com/T/#ma155e0b7bd87bb081ec94644a9689c8c494c879b

Note there are some failures here which are unexpected.

> grep "^---" tape_reset_test-after.log
---TEST FAILED--- with status 0
---TEST FAILED--- with status 0
---TEST FAILED--- with status 0
---TEST FAILED--- with status 0
---TEST FAILED--- with status 0
---TEST FAILED--- with status 0


# Reset the device with tape at EOD
#
$PWD/tape_reset.sh $SDEV 1 &
sleep 3
sleeping 1 seconds   
sg_reset --target /dev/sg1

#
# These commands should fail
#
dd if=/dev/random count=1001024 of=$DEV && echo "---TEST FAILED--- with status $?"
1001024+0 records in
1001024+0 records out
512524288 bytes (513 MB, 489 MiB) copied, 97.2296 s, 5.3 MB/s
---TEST FAILED--- with status 0
mt -f $DEV weof 1 && echo "---TEST FAILED--- with status $?"
---TEST FAILED--- with status 0
mt -f $DEV wset 1 && echo "---TEST FAILED--- with status $?"
/dev/nst0: Input/output error
mt: The tape is write-protected.
dd if=$DEV count=1024 of=/dev/null && echo "---TEST FAILED--- with status $?"
dd: error reading '/dev/nst0': Input/output error

See the verbose logs for more information.

Created attachment 307098 [details]
Passing verbose test logs

Same test run with dmesg.log

Created attachment 307099 [details]
Passing scsi_debug test logs

The tape_reset_debug test log run with the patches from:

https://lore.kernel.org/linux-scsi/20241031010032.117296-1-jmeneghi@redhat.com/

Created attachment 307146 [details]
Latest test logs created with upstream patches

Thanks for the patches!

I've made some improvement to the tests. This is test log of the new test_reset_status.sh test script run against your newest patches set upstream at:

https://lore.kernel.org/linux-scsi/20241104112623.2675-1-Kai.Makisara@kolumbus.fi/

I'd like to ask some questions about these test results.

The first error is found in the test sequence which resets the tape device while the file handle is closed while the tape is at EOD.

mt -f /dev/nst0 eod

mt -f /dev/nst0 status
SCSI 2 tape drive:
File number=2, block number=-1, partition=0.
Tape block size 0 bytes. Density code 0x46 (LTO-4).
Soft error count since last status=0
General status bits on (9010000):
 EOD ONLINE IM_REP_EN

^^^^^^^^^^^^^^^^^^^^^
Two files have been written to the tape and the tape is positioned at EOD.

sg_reset --target /dev/sg1

mt -f /dev/nst0 status
SCSI 2 tape drive:
File number=0, block number=0, partition=0.
Tape block size 0 bytes. Density code 0x46 (LTO-4).
Soft error count since last status=0
General status bits on (41010000):
 BOT ONLINE IM_REP_EN
--- mt -f /dev/nst0 status TEST FAILED--- with status 0

^^^^^^^^^^^^^^^^^^^^
Shouldn't this status command return EIO from st_open?  It looks like it has
cleared the pos_unknown statement set by the UA found in check_tape/test_ready.

mt -f /dev/nst0 status
SCSI 2 tape drive:
File number=0, block number=0, partition=0.
Tape block size 0 bytes. Density code 0x46 (LTO-4).
Soft error count since last status=0
General status bits on (41010000):

dd if=/dev/random count=1001024 of=/dev/nst0
1001024+0 records in
1001024+0 records out
512524288 bytes (513 MB, 489 MiB) copied, 95.6305 s, 5.4 MB/s
--- dd if=/dev/random count=1001024 of=/dev/nst0  TEST FAILED--- with status 0

mt -f /dev/nst0 weof 1
--- mt -f /dev/nst0 weof 1  TEST FAILED--- with status 0

^^^^^^^^^^^^^^^^
Here's the worry... we are allowing writes to the tape w/out requiring a tape reposition after reset.

Created attachment 307147 [details]
tape_reset_load test results.

This log is taken from the tape_reset_load.sh test.  This verifies that the "mt load" now works after reset.

Created attachment 307148 [details]
new-media.diff

> On 5. Nov 2024, at 20.22, bugzilla-daemon@kernel.org wrote:
> 
...
> I've made some improvement to the tests. This is test log of the new
> test_reset_status.sh test script run against your newest patches set upstream
> at:
> 
>
> https://lore.kernel.org/linux-scsi/20241104112623.2675-1-Kai.Makisara@kolumbus.fi/
> 
> I'd like to ask some questions about these test results.
> 
> The first error is found in the test sequence which resets the tape device
> while the file handle is closed while the tape is at EOD.
> 
> mt -f /dev/nst0 eod
> 
> mt -f /dev/nst0 status
> SCSI 2 tape drive:
> File number=2, block number=-1, partition=0.
> Tape block size 0 bytes. Density code 0x46 (LTO-4).
> Soft error count since last status=0
> General status bits on (9010000):
> EOD ONLINE IM_REP_EN
> 
> ^^^^^^^^^^^^^^^^^^^^^
> Two files have been written to the tape and the tape is positioned at EOD.
> 
> sg_reset --target /dev/sg1
> 
> mt -f /dev/nst0 status
> SCSI 2 tape drive:
> File number=0, block number=0, partition=0.
> Tape block size 0 bytes. Density code 0x46 (LTO-4).
> Soft error count since last status=0
> General status bits on (41010000):
> BOT ONLINE IM_REP_EN
> --- mt -f /dev/nst0 status TEST FAILED--- with status 0
> 
> ^^^^^^^^^^^^^^^^^^^^
> Shouldn't this status command return EIO from st_open?  It looks like it has
> cleared the pos_unknown statement set by the UA found in
> check_tape/test_ready.
> 

I think this status should succeed, as it does. The patch just modifies the code so
that MTIOCGET is allowed also after reset. So, this 'mt status' is not different from
the next ones.


> mt -f /dev/nst0 status
> SCSI 2 tape drive:
> File number=0, block number=0, partition=0.
> Tape block size 0 bytes. Density code 0x46 (LTO-4).
> Soft error count since last status=0
> General status bits on (41010000):
> 
> dd if=/dev/random count=1001024 of=/dev/nst0
> 1001024+0 records in
> 1001024+0 records out
> 512524288 bytes (513 MB, 489 MiB) copied, 95.6305 s, 5.4 MB/s
> --- dd if=/dev/random count=1001024 of=/dev/nst0  TEST FAILED--- with status
> 0
> 
> mt -f /dev/nst0 weof 1
> --- mt -f /dev/nst0 weof 1  TEST FAILED--- with status 0
> 
> ^^^^^^^^^^^^^^^^
> Here's the worry... we are allowing writes to the tape w/out requiring a tape
> reposition after reset.

Yes, this is worrying. I have been developing a patch to get rid of of was_reset
and there I have found a problem that may explain this behavior: UA handling in
test_ready() sets new_session also for reset if it is seen before open(). New
session clears pos_unknown. If reset is seen when writing, then this does
not happen. Scsi error handling clears was_reset if it re-locks a locked door
and this may explain why pos_unknown is not set if reset occurs just before
'mt status'.

If my theory is correct, the attached patch may fix the problem.

(In reply to Kai Mäkisara from comment #16)
> > mt -f /dev/nst0 weof 1
> > --- mt -f /dev/nst0 weof 1  TEST FAILED--- with status 0
> > 
> > ^^^^^^^^^^^^^^^^
> > Here's the worry... we are allowing writes to the tape w/out requiring a
> tape
> > reposition after reset.
> 
> Yes, this is worrying. I have been developing a patch to get rid of of
> was_reset
> and there I have found a problem that may explain this behavior: UA handling
> in
> test_ready() sets new_session also for reset if it is seen before open(). New
> session clears pos_unknown. If reset is seen when writing, then this does
> not happen. Scsi error handling clears was_reset if it re-locks a locked door
> and this may explain why pos_unknown is not set if reset occurs just before
> 'mt status'.
> 
> If my theory is correct, the attached patch may fix the problem.

OK, I'm looking at this patch and I don't think it will help because setting
new_session will result in test_ready() clearing pos_unknown.  I'll test it out and see what it does.

                        if (scode == UNIT_ATTENTION) { /* New media? */
-                               new_session = 1;
+                               if (cmdstatp->sense_hdr.asc == 0x28) { /* New media */
+                                       new_session = 1;
+                                       DEBC_printk(STp, "New tape session.");
+                               }

Created attachment 307151 [details]
new-media.diff test_tape_status.log

OK testing with your new-media patch seems to work. Attached is the new log file.

Please add this patch to your series upstream.

Here are the sections of the test run with this patch (on top of your other patches) which matter:

mt -f /dev/nst0 eod

mt -f /dev/nst0 status
SCSI 2 tape drive:
File number=2, block number=-1, partition=0.
Tape block size 0 bytes. Density code 0x46 (LTO-4).
Soft error count since last status=0
General status bits on (9010000):
 EOD ONLINE IM_REP_EN
sg_reset --target /dev/sg1

mt -f /dev/nst0 status
SCSI 2 tape drive:
File number=-1, block number=-1, partition=0.
Tape block size 0 bytes. Density code 0x46 (LTO-4).
Soft error count since last status=0
General status bits on (1010000):
 ONLINE IM_REP_EN

^^^^^^^^^^^^^^^^^^^^^^
mt status after reset works correctly, I've updated my test.

dd if=/dev/random count=1001024 of=/dev/nst0
dd: writing to '/dev/nst0': Input/output error
dd: closing output file '/dev/nst0': Input/output error

mt -f /dev/nst0 weof 1
/dev/nst0: Input/output error
mt: The tape is write-protected.

mt -f /dev/nst0 wset 1
/dev/nst0: Input/output error
mt: The tape is write-protected.

dd if=/dev/nst0 count=1024 of=/dev/null
dd: error reading '/dev/nst0': Input/output error
dd: closing input file '/dev/nst0': Input/output error

dd if=/dev/random count=1001024 of=/dev/nst0
dd: writing to '/dev/nst0': Input/output error
dd: closing output file '/dev/nst0': Input/output error
^^^^^^^^^^^^^^^^^^^^^^^

All reads and writes correctly fail after reset.

mt -f /dev/nst0 status
SCSI 2 tape drive:
File number=-1, block number=-1, partition=0.
Tape block size 0 bytes. Density code 0x46 (LTO-4).
Soft error count since last status=0
General status bits on (1010000):
 ONLINE IM_REP_EN
mt -f /dev/nst0 rewind

mt -f /dev/nst0 status
SCSI 2 tape drive:
File number=0, block number=0, partition=0.
Tape block size 0 bytes. Density code 0x46 (LTO-4).
Soft error count since last status=0
General status bits on (41010000):
 BOT ONLINE IM_REP_EN

dd if=/dev/nst0 count=1024 of=/dev/null
1024+0 records in
1024+0 records out
524288 bytes (524 kB, 512 KiB) copied, 2.23899 s, 234 kB/s

^^^^^^^^^^^^^^^^^^^^^^
mt rewind clears the condition.
mt -f /dev/nst0 fsf 1

dd if=/dev/nst0 count=1024 of=/dev/null
1024+0 records in
1024+0 records out

Created attachment 307152 [details]
final passing test results with new-media

Using the new-media patch together with "[PATCH 0/2] scsi: st: Device reset patches" all tests are now passing.  Including the concatenated log file "tape_reset_tests.log"

See the updated test scripts in https://github.com/johnmeneghini/tape_tests

This issue can be closed as soon as these patches are merged upstream.

Thanks for all of your help, Kai.

Created attachment 307228 [details]
More reset patches - test results

Adding the passing test results with new patches from:

 https://lore.kernel.org/linux-scsi/20241115162003.3908-1-Kai.Makisara@kolumbus.fi/

linux(tape_test) > git logl -7
177c3f710de4 2024-11-15 1729629595  (HEAD -> tape_test, johnm/tape_test2) scsi: st: instrument the pos_unknown code [ John Meneghini / jmeneghi@redhat.com ]
7373d7d717a0 2024-11-15 1731687603  (tape_test_noinst) scsi: st: Restore some drive settings after reset [ John Meneghini / Kai.Makisara@kolumbus.fi ]
25be4d26ef58 2024-11-15 1731687602  scsi: st: Remove use of device->was_reset [ John Meneghini / Kai.Makisara@kolumbus.fi ]
c5e0a7687c6b 2024-11-15 1730887043  scsi: st: New session only when Unit Attention for new tape [ John Meneghini / Kai.Makisara@kolumbus.fi ]
1ab8b314a34b 2024-11-15 1730887042  scsi: st: Add MTIOCGET and MTLOAD to ioctls allowed after device reset [ John Meneghini / Kai.Makisara@kolumbus.fi ]
0013312311da 2024-11-15 1730887041  scsi: st: Don't modify unknown block number in MTIOCGET [ John Meneghini / Kai.Makisara@kolumbus.fi ]
2d5404caa8c7 2024-11-10 1731277175  (tag: v6.12-rc7, branch_v6.12-rc7) Linux 6.12-rc7 [ Linus Torvalds / torvalds@linux-foundation.org ]

Created attachment 307345 [details]
tape_reset_debug_sg.sh test results

scsi_debug tape emulation test results for latest upstream patches at:

https://lore.kernel.org/linux-scsi/20241125140301.3912-1-Kai.Makisara@kolumbus.fi/

Created attachment 307346 [details]
run_tests.sh test results.

run_tests.sh test results

These are the results for the hardware tape tests run with the latest upstream patches: 

https://lore.kernel.org/linux-scsi/20241125140301.3912-1-Kai.Makisara@kolumbus.fi/