LinearTapeFileSystem / ltfs

Reference implementation of the LTFS format Spec for stand alone tape drive
BSD 3-Clause "New" or "Revised" License
256 stars 76 forks source link

Unexpected LTFS mount crash <-> Failed to execute SG_IO ioctl, opcode = 0a (12). #349

Closed vguilleaume closed 2 years ago

vguilleaume commented 2 years ago

Bug Description We would like to report an LTFS problem we are facing with one specific case which 'break' LTFS mount point with unexpected sg / drive / .... errors.

We are familiar in using LTFS solution ; and we have multiple different system using the same solution which included OpenLTFS software ; and we are facing strange experience with one specific LTFS implementation.

We execute a mount LTFS of a tape 'exemple 000043L8' with success , we start to copy files into the LTFS mount point of the tape 000043L8. This works fine , and copy can be executed during at least one hour. Very stable.

In // , we start to execute others LTFS operations such as others LTFS mount or LTFS format operations ; these operations work fine during couple of minutes. 10 / 15 Minutes.

Suddenly, something happened that 'break' all LTFS mount operations. The first LTFS mount is not accessible anymore ; we can't copy files anymore. Then we do an LTFS check - try to umount - remount and after couple of try, we can have it remounted. And after couple of minutes, we have again the same issue.

We have experiences with such kind of operations (but with others hardware components : tape library - drive - hba - .... ) ; and we have this situation in only 1 specific case.

Hardware context

To Reproduce Execute multiple LTFS operation in // into multiple drives with multiple sg devices.

Expected behavior Get back the LTFS mounted operations stable.

Trace - Log We have different logs of the LTFS operation and we have detected some strange issues. We had a look into others opened issues and more specially the one related to the HBA Emulex, ...

In the var/log/messages, we detect LTFS issues such as Failed to execute SG_IO ioctl, opcode = 0a (12). but also message in from the kernel such as kernel: st 18:0:0:0: Mode parameters changed and st 18:0:0:0: [sg6] tag#0 Add. Sense: Rounded parameter

The allow_dio is at 0 ; and we don't have used this option --enable-buggy-ifs

Extract of the logs , i tried to clean the log in keeping the 'most interesting' information (i have others similar logs i can shared) :

Apr 21 10:01:18 archive ltfs[21760]: 5504 LTFS11338I Syncing index of        C42A857128.
Apr 21 10:01:18 archive ltfs[21760]: 5504 LTFS17068I Syncing index of        (Reason: Periodic Sync) C42A857128.
Apr 21 10:01:18 archive ltfs[21760]: 5504 LTFS17235I Writing index of NO_BARCODE to b (Reason: Periodic Sync, 1329 files) C42A857128.

Apr 21 10:01:22 archive kernel: st 18:0:0:0: Mode parameters changed
...
Apr 21 10:01:22 archive kernel: st 18:0:0:0: [sg6] tag#0 Add. Sense: Rounded parameter

Apr 21 10:01:26 archive ltfs[21760]: 5504 LTFS17236I Wrote index of NO_BARCODE (b, C42A857128).
Apr 21 10:01:26 archive ltfs[21760]: 5504 LTFS11337I Update index-dirty flag (0) - NO_BARCODE (0x0x22f7d60).
Apr 21 10:01:26 archive ltfs[21760]: 5504 LTFS17070I Synced index of        (0) C42A857128.
Apr 21 10:01:45 archive ltfs[21760]: 5503 LTFS11337I Update index-dirty flag (1) - NO_BARCODE (0x0x22f7d60).
 ...
Apr 21 10:02:39 archive ltfs[21760]: 5503 LTFS30200I Failed to execute SG_IO ioctl, opcode = 0a (12).
Apr 21 10:02:39 archive ltfs[21760]: 5503 LTFS30264E WRITE returns msg = NULL (-21700) /dev/sg5.
Apr 21 10:02:39 archive ltfs[21760]: 5503 LTFS12045E Cannot write block: backend call failed (-21700). Dropping to read-only mode.
Apr 21 10:02:39 archive ltfs[21760]: 5503 LTFS11072E Cannot write blocks: failed to write to the medium (-21700).
Apr 21 10:02:39 archive ltfs[21760]: 5503 LTFS11077E Cannot write: failed to write blocks to the medium (-21700).
Apr 21 10:02:39 archive ltfs[21760]: 5503 LTFS13014W Data partition writer: failed to write data to the tape (-21700).

Apr 21 10:02:44 archive mount_point_scanning: 2022/04/21 10:02:44 Mount terminated detected on /mnt/Pool/000043L8
Apr 21 10:03:02 archive ltfs[21760]: 5500 LTFS11033E Cannot unmount: failed to write an index.
Apr 21 10:03:02 archive ltfs[21760]: 5500 LTFS30252I Logical block protection is disabled.

I have no idea about what's happened, thanks for your further support,

Software Version

vguilleaume commented 2 years ago

I continue to work on this to understand what's happened, i went through the question of the table size of the scatter-gather. I verify the value of the table size of our Qlogic adaptor and i can confirm that the value is 1024 , higher than 256.


root@nodeum:~# cat /sys/class/scsi_host/host2/model_name
QLE2672
root@nodeum:~# cat /sys/class/scsi_host/host2/sg_tablesize
1024
root@nodeum:~# cat /sys/class/scsi_host/host3/model_name
QLE2672
root@nodeum:~# cat /sys/class/scsi_host/host3/sg_tablesize
1024

Even if allow_dio is set at 0, potentially the problem we have can come from the Emulex adaptors ; we will test the default size of the adaptor and keep you informed.

vguilleaume commented 2 years ago

I confirm that the value is at 64 for this Emulex HBA

[root@archive host15]# cd /sys/class/scsi_host/host15/
[root@archive host15]# cat sg_tablesize
64
piste-jp commented 2 years ago

The kay is the lines below.

Apr 21 10:02:39 archive ltfs[21760]: 5503 LTFS30200I Failed to execute SG_IO ioctl, opcode = 0a (12).
Apr 21 10:02:39 archive ltfs[21760]: 5503 LTFS30264E WRITE returns msg = NULL (-21700) /dev/sg5.
Apr 21 10:02:39 archive ltfs[21760]: 5503 LTFS12045E Cannot write block: backend call failed (-21700). Dropping to read-only mode.

The log LTFS30200 shows an error of calling ioctl() against the sg device below. And 12 shows a errno returned from ioctl().

https://github.com/LinearTapeFileSystem/ltfs/blob/3b26f034e11a2a0cb767dfd914597b9a3527ffdc/src/tape_drivers/linux/sg/sg_scsi_tape.c#L202-L204

errno == 12 is #define ENOMEM 12 /* Out of memory */

21700 in the log LTFS12045E shows the ltfs internal error code defined in ltfs_error.h.

https://github.com/LinearTapeFileSystem/ltfs/blob/3b26f034e11a2a0cb767dfd914597b9a3527ffdc/src/libltfs/ltfs_error.h#L455

It looks LTFS says it is an internal error because ioctl() returns very unexpected error (ENOMEM).

piste-jp commented 2 years ago

I changed the code to reserve transfer buffer into a sg dvice before #164, #215.

https://github.com/LinearTapeFileSystem/ltfs/blob/3b26f034e11a2a0cb767dfd914597b9a3527ffdc/src/tape_drivers/linux/sg/sg_tape.c#L1369-L1376

Please check the log of LTFS30284I or LTFS30285I and confirm how many length is reserved as a sg transfer buffer.

Normally it would be 512 * 1024 * 1024 and this kind of error never happen when you use the LTFS under conditions below.

  1. Format a tape with default block size (512 * 1024 * 1024)
  2. Without scsi_lbprotect=on option (in this case, LTFS transfers 512 * 1024 * 1024 + 4 bytes in a WRITE command so the sg device tries to allocate new memory for the command)
  3. When allow_dio == 0 (scatter gather table is related only when allow_dio == 1)
piste-jp commented 2 years ago

Software Version

  • OS: CentOS 7.9.2009
  • LTFS version 2.4.0.2
  • LTFS Format Specification version 2.4.0

It looks the code base is too old. The enhancement is implemented into 2.4.2.0 or later.

c861306 2020-04-01 08:56:12 +0900 Update version number for release 2.4.2.0 (10418)  (tag: v2.4.2.0-10418) [Atsushi Abe]
...
91ae567 2019-10-15 15:25:30 +0900 Support HBA load balancing (#164)  [Atsushi Abe](#168)  [Atsushi Abe]

By the way, the LTFS project released new versions for fixing critical issues. I strongly recommend to use 2.4.3.1 or 2.4.4.0 at this time. These are the safest version at this time.

See details into https://github.com/LinearTapeFileSystem/ltfs/releases.

vguilleaume commented 2 years ago

Thanks @piste-jp-ibm for your quick and valuable support. We will upgrade to 2.4.4.0 or even to the branch which include the code changed you referred to :

int reserved_size = 1 * MB; 
 ioctl(priv->dev.fd, SG_SET_RESERVED_SIZE, &reserved_size); 
 ret = ioctl(priv->dev.fd, SG_GET_RESERVED_SIZE, &reserved_size); 
 if (ret < 0) { 
    ltfsmsg(LTFS_INFO, 30284I, devname); 
    goto free; 
 } 
 ltfsmsg(LTFS_INFO, 30285I, devname, reserved_size); 

Keep you posted quicky

vguilleaume commented 2 years ago

Hi @piste-jp-ibm , thanks again, we have updated the LTFS version as you suggested.

We are now running the test with OpenLTFS from the 2.4-stable branch with the LTFS version 2.4.4.1

For now, this works as expected ; we do not have execute long run of copy as end of last week ; but the status seems better for now.

We can confirmed that the reserved buffer size of the /dev/sg3 is 524288. I will keep you informed about the status after more in deep test. We have tested mkltfs command and mount - umount command. Here is the full log of a mount.

Apr 25 12:48:57 archive ltfs[13358]: 342e LTFS14000I LTFS starting, LTFS version 2.4.4.1 (Prelim), log level 2.
Apr 25 12:48:57 archive ltfs[13358]: 342e LTFS14058I LTFS Format Specification version 2.4.0.
Apr 25 12:48:57 archive ltfs[13358]: 342e LTFS14104I Launched by "ltfs /mnt/Pool/38/Archive/000042L8 -o devname=/dev/sg3 -o nonempty -o sync_type=time@5".
Apr 25 12:48:57 archive ltfs[13358]: 342e LTFS14105I This binary is built for Linux (x86_64).
Apr 25 12:48:57 archive ltfs[13358]: 342e LTFS14106I GCC version is 4.8.5 20150623 (Red Hat 4.8.5-44).
Apr 25 12:48:57 archive ltfs[13358]: 342e LTFS17087I Kernel version: Linux version 3.10.0-1160.62.1.el7.x86_64 (mockbuild@kbuilder.bsys.centos.org) (gcc version 4.8.5 20150623 (Red Hat 4.8.5-44) (GCC) ) #1 SMP Tue Apr 5 16:57:59 UTC 2022 i386.
Apr 25 12:48:57 archive ltfs[13358]: 342e LTFS17089I Distribution: CentOS Linux release 7.9.2009 (Core).
Apr 25 12:48:57 archive ltfs[13358]: 342e LTFS17089I Distribution: NAME="CentOS Linux".
Apr 25 12:48:57 archive ltfs[13358]: 342e LTFS17089I Distribution: CentOS Linux release 7.9.2009 (Core).
Apr 25 12:48:57 archive ltfs[13358]: 342e LTFS17089I Distribution: CentOS Linux release 7.9.2009 (Core).
Apr 25 12:48:57 archive ltfs[13358]: 342e LTFS14063I Sync type is "time", Sync time is 300 sec.
Apr 25 12:48:57 archive ltfs[13358]: 342e LTFS17085I Plugin: Loading "sg" tape backend.
Apr 25 12:48:57 archive ltfs[13358]: 342e LTFS17085I Plugin: Loading "unified" iosched backend.
Apr 25 12:48:57 archive ltfs[13358]: 342e LTFS14095I Set the tape device write-anywhere mode to avoid cartridge ejection.
Apr 25 12:48:57 archive ltfs[13358]: 342e LTFS30209I Opening a device through sg-ibmtape driver (/dev/sg3).
Apr 25 12:48:57 archive ltfs[13358]: 342e LTFS30250I Opened the SCSI tape device 17.0.0.0 (/dev/sg3).
Apr 25 12:48:57 archive ltfs[13358]: 342e LTFS30207I Vendor ID is IBM     .
Apr 25 12:48:57 archive ltfs[13358]: 342e LTFS30208I Product ID is ULTRIUM-TD9     .
Apr 25 12:48:57 archive ltfs[13358]: 342e LTFS30214I Firmware revision is N9B0.
Apr 25 12:48:57 archive ltfs[13358]: 342e LTFS30215I Drive serial is C42A857128.
Apr 25 12:48:57 archive ltfs[13358]: 342e LTFS30285I The reserved buffer size of /dev/sg3 is 524288.
Apr 25 12:48:57 archive ltfs[13358]: 342e LTFS30205I RSOC (0xa3) returns -20601.
Apr 25 12:48:57 archive ltfs[13358]: 342e LTFS30263I RSOC returns Not Ready to Ready Transition, Medium May Have Changed (-20601) /dev/sg3.
Apr 25 12:48:57 archive ltfs[13358]: 342e LTFS30262I Forcing drive dump.
Apr 25 12:48:57 archive ltfs[13358]: 342e LTFS39802W Unknown SCSI OP code 0x1d, use default timeout.
Apr 25 12:48:57 archive ltfs[13358]: 342e LTFS30253I Saving drive dump to /tmp/ltfs_C42A857128_2022_0425_124857_f.dmp.
Apr 25 12:48:57 archive ltfs[13358]: 342e LTFS39802W Unknown SCSI OP code 0x3c, use default timeout.
Apr 25 12:49:11 archive ltfs[13358]: 342e LTFS39802W Unknown SCSI OP code 0x3c, use default timeout.
Apr 25 12:49:11 archive ltfs[13358]: 342e LTFS39802W Unknown SCSI OP code 0x3c, use default timeout.
Apr 25 12:49:11 archive ltfs[13358]: 342e LTFS39802W Unknown SCSI OP code 0x3c, use default timeout.
Apr 25 12:49:11 archive ltfs[13358]: 342e LTFS39802W Unknown SCSI OP code 0x3c, use default timeout.
Apr 25 12:49:11 archive ltfs[13358]: 342e LTFS39802W Unknown SCSI OP code 0x3c, use default timeout.
Apr 25 12:49:11 archive ltfs[13358]: 342e LTFS39802W Unknown SCSI OP code 0x3c, use default timeout.
Apr 25 12:49:11 archive ltfs[13358]: 342e LTFS39802W Unknown SCSI OP code 0x3c, use default timeout.
Apr 25 12:49:11 archive ltfs[13358]: 342e LTFS39802W Unknown SCSI OP code 0x3c, use default timeout.
Apr 25 12:49:11 archive ltfs[13358]: 342e LTFS39802W Unknown SCSI OP code 0x3c, use default timeout.
Apr 25 12:49:11 archive ltfs[13358]: 342e LTFS39802W Unknown SCSI OP code 0x3c, use default timeout.
Apr 25 12:49:11 archive ltfs[13358]: 342e LTFS39802W Unknown SCSI OP code 0x3c, use default timeout.
Apr 25 12:49:11 archive ltfs[13358]: 342e LTFS30294I Setting up timeout values from vendor and device.
Apr 25 12:49:11 archive ltfs[13358]: 342e LTFS17160I Maximum device block size is 1048576.
Apr 25 12:49:11 archive ltfs[13358]: 342e LTFS11330I Loading cartridge.
Apr 25 12:49:14 archive ltfs[13358]: 342e LTFS30252I Logical block protection is disabled.
Apr 25 12:49:14 archive ltfs[13358]: 342e LTFS11332I Load successful.
Apr 25 12:49:14 archive ltfs[13358]: 342e LTFS17157I Changing the drive setting to write-anywhere mode.
Apr 25 12:49:14 archive ltfs[13358]: 342e LTFS11005I Mounting the volume.
Apr 25 12:49:14 archive ltfs[13358]: 342e LTFS30252I Logical block protection is disabled.
Apr 25 12:49:24 archive ltfs[13358]: 342e LTFS17227I Tape attribute: Vendor = QUANTUM .
Apr 25 12:49:24 archive ltfs[13358]: 342e LTFS17227I Tape attribute: Application Name = LTFS                            .
Apr 25 12:49:24 archive ltfs[13358]: 342e LTFS17227I Tape attribute: Application Version = 2.4.0.2 .
Apr 25 12:49:24 archive ltfs[13358]: 342e LTFS17227I Tape attribute: Medium Label = .
Apr 25 12:49:24 archive ltfs[13358]: 342e LTFS17228I Tape attribute: Text Localization ID = 0x81.
Apr 25 12:49:24 archive ltfs[13358]: 342e LTFS17227I Tape attribute: Barcode = 000042L8                        .
Apr 25 12:49:24 archive ltfs[13358]: 342e LTFS17227I Tape attribute: Application Format Version = 2.4.0           .
Apr 25 12:49:24 archive ltfs[13358]: 342e LTFS17228I Tape attribute: Volume Lock Status = 0x00.
Apr 25 12:49:24 archive ltfs[13358]: 342e LTFS17227I Tape attribute: Media Pool name = .
Apr 25 12:49:24 archive ltfs[13358]: 342e LTFS11031I Volume mounted successfully. NO_BARCODE : Gen = 34 / (a, 22) -> (b, 3075344) / C42A857128.
Apr 25 12:49:24 archive ltfs[13358]: 342e LTFS14111I Initial setup completed successfully.
Apr 25 12:49:24 archive ltfs[13358]: 342e LTFS14112I Invoke 'mount' command to check the result of final setup.
Apr 25 12:49:24 archive ltfs[13358]: 342e LTFS14113I Specified mount point is listed if succeeded.
Apr 25 12:49:24 archive ltfs[13956]: 3685 LTFS14029I Ready to receive file system requests.
Apr 25 12:49:27 archive ltfs[13956]: 3686 LTFS11337I Update index-dirty flag (1) - NO_BARCODE (0x0x21c70c0).
Apr 25 12:49:31 archive mount_point_scanning: 2022/04/25 12:49:31 Mount detected on /mnt/Pool/38/Archive/000042L8

Side question , perhaps i have to open another ticket ; do you have any idea about these logs , i never seen such kind of event in LTFS logs :

Apr 25 12:48:57 archive ltfs[13358]: 342e LTFS30205I RSOC (0xa3) returns -20601.
Apr 25 12:48:57 archive ltfs[13358]: 342e LTFS30263I RSOC returns Not Ready to Ready Transition, Medium May Have Changed (-20601) /dev/sg3.
Apr 25 12:48:57 archive ltfs[13358]: 342e LTFS30262I Forcing drive dump.
Apr 25 12:48:57 archive ltfs[13358]: 342e LTFS39802W Unknown SCSI OP code 0x1d, use default timeout.
Apr 25 12:48:57 archive ltfs[13358]: 342e LTFS30253I Saving drive dump to /tmp/ltfs_C42A857128_2022_0425_124857_f.dmp.
Apr 25 12:48:57 archive ltfs[13358]: 342e LTFS39802W Unknown SCSI OP code 0x3c, use default timeout.
Apr 25 12:49:11 archive ltfs[13358]: 342e LTFS39802W Unknown SCSI OP code 0x3c, use default timeout.
Apr 25 12:49:11 archive ltfs[13358]: 342e LTFS39802W Unknown SCSI OP code 0x3c, use default timeout.
Apr 25 12:49:11 archive ltfs[13358]: 342e LTFS39802W Unknown SCSI OP code 0x3c, use default timeout.
Apr 25 12:49:11 archive ltfs[13358]: 342e LTFS39802W Unknown SCSI OP code 0x3c, use default timeout.
Apr 25 12:49:11 archive ltfs[13358]: 342e LTFS39802W Unknown SCSI OP code 0x3c, use default timeout.
Apr 25 12:49:11 archive ltfs[13358]: 342e LTFS39802W Unknown SCSI OP code 0x3c, use default timeout.
Apr 25 12:49:11 archive ltfs[13358]: 342e LTFS39802W Unknown SCSI OP code 0x3c, use default timeout.
Apr 25 12:49:11 archive ltfs[13358]: 342e LTFS39802W Unknown SCSI OP code 0x3c, use default timeout.
Apr 25 12:49:11 archive ltfs[13358]: 342e LTFS39802W Unknown SCSI OP code 0x3c, use default timeout.
Apr 25 12:49:11 archive ltfs[13358]: 342e LTFS39802W Unknown SCSI OP code 0x3c, use default timeout.
Apr 25 12:49:11 archive ltfs[13358]: 342e LTFS39802W Unknown SCSI OP code 0x3c, use default timeout.

Thanks again for your great support

piste-jp commented 2 years ago

Interesting... You might get a very short window.

I think you might insert the tape and start the ltfs command when load operation is almost finished.

In the most case, cartridge load operation is completed after RSOC command, rhish is the command to fetch time out values from the drive. So RSOC command returns good state and the LTFS successfully configure the time out values. But in this case, load operation is finished just before the RSOC command and the drive returns Not Ready to Ready Transition against it. It is unexpected behavior in the current code and the command sequence after the error to capture the drive dump reports a lot of LTFS39802W because of unconfigured time out values.

But finally, LTFS falles back and configure the time out value from preset one, LTFS30294I . So I believe this is minor issue at this time.

Apr 25 12:48:57 archive ltfs[13358]: 342e LTFS30205I RSOC (0xa3) returns -20601.
Apr 25 12:48:57 archive ltfs[13358]: 342e LTFS30263I RSOC returns Not Ready to Ready Transition, Medium May Have Changed (-20601) /dev/sg3.
Apr 25 12:48:57 archive ltfs[13358]: 342e LTFS30262I Forcing drive dump.
Apr 25 12:48:57 archive ltfs[13358]: 342e LTFS39802W Unknown SCSI OP code 0x1d, use default timeout.
Apr 25 12:48:57 archive ltfs[13358]: 342e LTFS30253I Saving drive dump to /tmp/ltfs_C42A857128_2022_0425_124857_f.dmp.
Apr 25 12:48:57 archive ltfs[13358]: 342e LTFS39802W Unknown SCSI OP code 0x3c, use default timeout.
...
Apr 25 12:49:11 archive ltfs[13358]: 342e LTFS39802W Unknown SCSI OP code 0x3c, use default timeout.
Apr 25 12:49:11 archive ltfs[13358]: 342e LTFS30294I Setting up timeout values from vendor and device.
vguilleaume commented 2 years ago

thanks for the feedback , glad to hear that it is minor issue ; i can confirm it is the first time i see this type of error message.

In the same time, i can confirm that the version we deployed works fine without any problem any more.

And this with

piste-jp commented 2 years ago

Close this.

vguilleaume commented 2 years ago

thanks @piste-jp-ibm for the great support; for now we do not have any issue any more.