[SOLVED] proxmox-tape barcode-label got timeout

G

gothbert

Well-Known Member
Apr 3, 2021
34
6
48
46
I run PBS 4.2.6. A Quantum Superloader 3 is connected via iSCSI. The iSCSI target is a Debian 13.7. PBS web interface shows the library slots and drives. I have a LTO-8 cartridge in the drive which is labeled BN0001L8.

Bildschirmfoto_20260920_115218.png

Bash: 
proxmox-tape barcode-label  -pool bn-continue --drive drive
gives
Code: 
checking/loading media 'BN0001L8'
TASK ERROR: open drive 'drive' (/dev/tape/by-id/scsi-XXXXXXXXXX-sg) failed - wait_until_ready failed - got timeout
Error: task failed (status open drive 'drive' (/dev/tape/by-id/scsi-XXXXXXXXXX-sg) failed - wait_until_ready failed - got timeout)
It takes quite some time for the error to appear and the command to end although the web interface of the Superloader shows the drive idling quite immediately. As a potential alternative
Code: 
proxmox-tape label --drive drive --label-text BN0001L8 -pool bn-continue
for labeling the single tape does not work either.

The tape seems okay, I can tar files to it and read successfully read them back. I even did a long-erase of the tape and cleaned the drive.

dmesg shows repeated messages:
Code: 
connection1:0: detected conn error (1020)
Though, I can still access the library from the PBS web GUI, e.g. unloading the tape from the drive into a slot in the library.

I have seen this thread but not the solution. Chatting with Gemini did not help either.

Any idea what to do? Can I manually write the "Inventory" to the tape?
 
Just a few tips: if you run lsscsi on the pbs server (you may have to install it) you can see which device the tape library and the drives are on. The try mtx -f /dev/sg0 (or whatever device the library is on). Note that the drives and the library are on differenct scsi devices.
 
Thanks for the tips. I already got quite deep into these things recently. The drive and the library on the target are referenced by-id because the generic device names /dev/sg0 /dev/sg1 ... are randomly assigned after a restart of the machine. The devices on the pbs server are correct, as far as I judge from

Code: 
root@pbs:~# proxmox-tape drive list
┌───────┬────────────────────────────────────┬─────────┬────────┬─────────────┬────────────┐
│ name  │ path                               │ changer │ vendor │ model       │ serial     │
╞═══════╪════════════════════════════════════╪═════════╪════════╪═════════════╪════════════╡
│ drive │ /dev/tape/by-id/scsi-XXXXXXXXXX-sg │ qsl3    │ IBM    │ ULTRIUM-HH8 │ XXXXXXXXXX │
└───────┴────────────────────────────────────┴─────────┴────────┴─────────────┴────────────┘
and my experiments with tar cvzf /dev/st0. According to the serial, I have the devices right.
 
Hi,

not sure what is happening, but we'll hopefully find out :)

gothbert said:
Any idea what to do? Can I manually write the "Inventory" to the tape?
Click to expand...
no manually adding will not help since the labeling also includes writing the first block to the tape (our 'media' header)

can you post the output of dmesg after a failed (manual) labeling of the tape?

also, please don't access any of the 'dev/st0' etc. devices during pbs tape operation, otherwise it can happen that the kernel interferes with our scsi commands.
 
That sounds promising, so let's go.

I choose a systematic reproducible approach.

*** 1
Power on the Quantum Superloader 3 (QSL3) and wait until it settles into "System Ready" state.

*** 2
Power on the target host (Debian 13.7) and wait until it has fully booted. Log in as root and check:

Code: 
root@pve-3:~# lsscsi -g
[0:0:0:0]    disk    ATA      Crucial_CCCCCCCC R031  /dev/sda   /dev/sg0
[2:0:0:0]    tape    IBM      ULTRIUM-HH8      S2T5  /dev/st0   /dev/sg1
[2:0:0:1]    mediumx QUANTUM  UHDL             0116  /dev/sch0  /dev/sg2

Though, the iscsi target configuration was incomplete and I had to add the drive again.

*** 3
Log into the Proxmox Backup Server (PBS) initiator host and check:

Code: 
root@pbs:~# lsscsi -g
[0:0:0:0]    disk    ATA      WDC WDWWWWWWWWWW 0A81  /dev/sda   /dev/sg0
[9:0:0:0]    mediumx QUANTUM  UHDL             0116  /dev/sch0  /dev/sg1
[9:0:0:1]    tape    IBM      ULTRIUM-HH8      S2T5  /dev/st0   /dev/sg2
[N:0:1:1]    disk    ADATA SSSSSSSSSSSS                         /dev/nvme0n1  -

I logged out of and back into the iscsi target to make sure that the drive is available.


Corresponding dmesg:
Code: 
[Sep22 19:57] scsi host9: iSCSI Initiator over TCP/IP
[  +0.006998] scsi 9:0:0:0: Medium Changer    QUANTUM  UHDL             0116 PQ: 0 ANSI: 2
[  +0.001488] ch 9:0:0:0: LUN assignments on this target have changed. The Linux SCSI layer does not automatically remap LUN assignments.
[  +0.110279] ch 9:0:0:0: [ch0] type #1 (mt): 0x0+1 [medium transport]
[  +0.000017] ch 9:0:0:0: [ch0] type #2 (st): 0x100+8 [storage]
[  +0.000011] ch 9:0:0:0: [ch0] type #3 (ie): 0x0+0 [import/export]
[  +0.000008] ch 9:0:0:0: [ch0] type #4 (dt): 0x20+1 [data transfer]
[  +0.124295] ch 9:0:0:0: [ch0] dt 0x20:
[  +0.000007] ch 9:0:0:0: [ch0] ID/LUN unknown
[  +0.000005] ch 9:0:0:0: [ch0] INITIALIZE ELEMENT STATUS, may take some time ...
[ +15.572633] ch 9:0:0:0: [ch0] ... finished
[  +0.000017] ch 9:0:0:0: Attached scsi changer ch0
[  +0.000398] ch 9:0:0:0: Attached scsi generic sg1 type 8
[  +0.005741] scsi 9:0:0:1: Sequential-Access IBM      ULTRIUM-HH8      S2T5 PQ: 0 ANSI: 6
[  +0.026445] st 9:0:0:1: Attached scsi tape st0
[  +0.000008] st 9:0:0:1: st0: try direct i/o: yes (alignment 512 B)
[  +0.000118] st 9:0:0:1: Attached scsi generic sg2 type 1

*** 4
Use the PBS Web GUI to load the tape from slot 1 to the drive.
This gives a timeout error quite early, though, the tape is finally in the drive and the Web GUI shows the exactly that.

dmesg shows:
Code: 
[Sep22 19:24]  connection1:0: detected conn error (1020)


Code: 
root@pbs:~# mtx -f /dev/sch0 status
  Storage Changer /dev/sch0:1 Drives, 8 Slots ( 0 Import/Export )
Data Transfer Element 0:Full (Storage Element 1 Loaded)
      Storage Element 1:Empty
      Storage Element 2:Empty
      Storage Element 3:Empty
      Storage Element 4:Empty
      Storage Element 5:Empty
      Storage Element 6:Empty
      Storage Element 7:Empty
      Storage Element 8:Full :VolumeTag=CLN001CU




I run
Code: 
proxmox-tape label --drive drive --label-text BN0001L8 -pool bn-continue

Corresponding dmesg on PBS:
Code: 
[Sep22 19:59]  connection2:0: detected conn error (1020)
[  +2.017900]  connection2:0: detected conn error (1020)
[  +2.024449]  connection2:0: detected conn error (1020)
[  +2.023055]  connection2:0: detected conn error (1020)
[  +3.024699]  connection2:0: detected conn error (1020)
[  +2.014132]  connection2:0: detected conn error (1020)
[  +2.020736]  connection2:0: detected conn error (1020)
[  +2.023409]  connection2:0: detected conn error (1020)
[  +2.022155]  connection2:0: detected conn error (1020)
[  +2.009352]  connection2:0: detected conn error (1020)
[  +2.023685]  connection2:0: detected conn error (1020)
[  +2.013886]  connection2:0: detected conn error (1020)
[  +2.022936]  connection2:0: detected conn error (1020)
[  +2.022124]  connection2:0: detected conn error (1020)
[  +2.013975]  connection2:0: detected conn error (1020)
[  +2.019390]  connection2:0: detected conn error (1020)
[  +2.023931]  connection2:0: detected conn error (1020)
[  +2.021252]  connection2:0: detected conn error (1020)
[  +2.017758]  connection2:0: detected conn error (1020)
[  +2.015700]  connection2:0: detected conn error (1020)
[  +2.023359]  connection2:0: detected conn error (1020)
[  +2.022505]  connection2:0: detected conn error (1020)
[  +2.023510]  connection2:0: detected conn error (1020)
[  +2.014686]  connection2:0: detected conn error (1020)
[  +2.015895]  connection2:0: detected conn error (1020)
repeating for a long long time...

The corresponding dmesg on the target host (host with the physically attached QSL3):
Code: 
[Sep22 19:59] ITT: 0x00000054 read_data_left is zero!
[  +0.000018] iscsit_get_datain_values failed for ITT: 0x00000054
[  +2.020891] ITT: 0x10000056 read_data_left is zero!
[  +0.000019] iscsit_get_datain_values failed for ITT: 0x10000056
[  +2.024462] ITT: 0x20000058 read_data_left is zero!
[  +0.000020] iscsit_get_datain_values failed for ITT: 0x20000058
[  +2.022805] ITT: 0x3000005a read_data_left is zero!
[  +0.000019] iscsit_get_datain_values failed for ITT: 0x3000005a
[  +3.024673] ITT: 0x4000005d read_data_left is zero!
[  +0.000020] iscsit_get_datain_values failed for ITT: 0x4000005d
[  +2.015434] ITT: 0x5000005f read_data_left is zero!
[  +0.000018] iscsit_get_datain_values failed for ITT: 0x5000005f
[  +2.020251] ITT: 0x60000061 read_data_left is zero!
[  +0.000019] iscsit_get_datain_values failed for ITT: 0x60000061
[  +2.022844] ITT: 0x70000064 read_data_left is zero!
[  +0.000020] iscsit_get_datain_values failed for ITT: 0x70000064
[  +2.022534] ITT: 0x80000066 read_data_left is zero!
[  +0.000020] iscsit_get_datain_values failed for ITT: 0x80000066
[  +2.009946] ITT: 0x90000068 read_data_left is zero!
[  +0.000015] iscsit_get_datain_values failed for ITT: 0x90000068
[  +2.022623] ITT: 0xa000006a read_data_left is zero!
[  +0.000019] iscsit_get_datain_values failed for ITT: 0xa000006a
[  +2.013777] ITT: 0xb000006c read_data_left is zero!
[  +0.000020] iscsit_get_datain_values failed for ITT: 0xb000006c
[  +2.022642] ITT: 0xc000006e read_data_left is zero!
[  +0.000020] iscsit_get_datain_values failed for ITT: 0xc000006e
[  +2.022682] ITT: 0xd0000070 read_data_left is zero!
[  +0.000019] iscsit_get_datain_values failed for ITT: 0xd0000070
[  +2.013601] ITT: 0xe0000072 read_data_left is zero!
[  +0.000019] iscsit_get_datain_values failed for ITT: 0xe0000072
[  +2.015247] ITT: 0xf0000074 read_data_left is zero!
[  +0.000020] iscsit_get_datain_values failed for ITT: 0xf0000074
[  +2.027210] ITT: 0x00000077 read_data_left is zero!
[  +0.000019] iscsit_get_datain_values failed for ITT: 0x00000077
[  +2.022472] ITT: 0x10000079 read_data_left is zero!
[  +0.000020] iscsit_get_datain_values failed for ITT: 0x10000079
[  +2.016341] ITT: 0x2000007b read_data_left is zero!
[  +0.000019] iscsit_get_datain_values failed for ITT: 0x2000007b
[  +2.016327] ITT: 0x3000007e read_data_left is zero!
[  +0.000019] iscsit_get_datain_values failed for ITT: 0x3000007e
[  +2.022683] ITT: 0x40000001 read_data_left is zero!
[  +0.000017] iscsit_get_datain_values failed for ITT: 0x40000001
[  +2.023096] ITT: 0x50000003 read_data_left is zero!
[  +0.000019] iscsit_get_datain_values failed for ITT: 0x50000003
[  +2.023674] ITT: 0x60000007 read_data_left is zero!
[  +0.000020] iscsit_get_datain_values failed for ITT: 0x60000007
[  +2.014573] ITT: 0x70000009 read_data_left is zero!
[  +0.000020] iscsit_get_datain_values failed for ITT: 0x70000009
[  +2.016274] ITT: 0x8000000a read_data_left is zero!
[  +0.000020] iscsit_get_datain_values failed for ITT: 0x8000000a
[  +2.020403] ITT: 0x9000000c read_data_left is zero!
[  +0.000016] iscsit_get_datain_values failed for ITT: 0x9000000c
[  +2.014128] ITT: 0xa000000e read_data_left is zero!
repeating for a long long time...

And this is where I am lost. QSL3 is idle, the label command hangs and the wait-cursor in the Web GUI continues.

Edit: finally the proxmox-tape command bails out with
Code: 
TASK ERROR: open drive 'drive' (/dev/tape/by-id/scsi-TTTTTTTTT-sg) failed - wait_until_ready failed - got timeout
Error: task failed (status open drive 'drive' (/dev/tape/by-id/scsi-TTTTTTTTT-sg) failed - wait_until_ready failed - got timeout)
an no additional information in the dmesg kernel logs on either end.
 
Last edited:
ok reading the errors from the target side, it seems this is an issue in our code that was recentyl fixed:
https://lore.proxmox.com/pbs-devel/20260817123128.2813924-1-d.csapak@proxmox.com/T/#t

the patch is applied, but not yet in a bumped package

The patch fixes an issue where we would set up a buffer for the tape/changer/etc. to write in but the commands we send don't have any data to write data to. so I think the target side sees that and errors out.

to verify, could you enable debug logging for iscsi/lio (i assume that's what you using for the iscsi target) ?
 
It's ISCSI/LIO. Here is the relevant part in the log (repeating) after issuing the label command:

Code: 
[  +0.000006] Known ACL iqn.1993-08.org.debian:01:eac885df5da1 is trying to connect
[  +0.000008] Entering iscsi_target_restore_sock_callbacks: conn: 00000000ccd18d91
[  +0.000008] Sending Login Response, Flags: 0x87, ITT: 0xf0000000, ExpCmdSN; 0x000004fd, MaxCmdSN: 0x000004fd, StatSN: 0xd1d20552, Length: 312
[  +0.000465] tx_loop: 360, total_tx: 360, data: 360
[  +0.000010] Login timer stopped
[  +0.000009] Moving to TARG_CONN_STATE_LOGGED_IN.
[  +0.000004] ------------------------------------------------------------------
[  +0.000004] HeaderDigest:                 None
[  +0.000003] DataDigest:                   None
[  +0.000004] MaxXmitDataSegmentLength:     262144
[  +0.000003] MaxRecvDataSegmentLength:     262144
[  +0.000005] ------------------------------------------------------------------
[  +0.000003] ------------------------------------------------------------------
[  +0.000003] MaxConnections:               1
[  +0.000004] TargetName:                   iqn.2026-09.de.gs21:qsl3
[  +0.000003] InitiatorName:                iqn.1993-08.org.debian:01:eac885df5da1
[  +0.000003] TargetAlias:                  LIO Target
[  +0.000003] InitiatorAlias:               pbs
[  +0.000003] TargetPortalGroupTag:         1
[  +0.000003] InitialR2T:                   Yes
[  +0.000003] ImmediateData:                Yes
[  +0.000004] MaxBurstLength:               262144
[  +0.000003] FirstBurstLength:             65536
[  +0.000003] DefaultTime2Wait:             2
[  +0.000003] DefaultTime2Retain:           0
[  +0.000003] MaxOutstandingR2T:            1
[  +0.000003] DataPDUInOrder:               Yes
[  +0.000002] DataSequenceInOrder:          Yes
[  +0.000003] ErrorRecoveryLevel:           0
[  +0.000003] SessionType:                  Normal
[  +0.000003] ------------------------------------------------------------------
[  +0.000014] TARGET_CORE[iSCSI]: Registered fabric_sess_ptr: 0000000065b21343
[  +0.000005] Moving to TARG_SESS_STATE_LOGGED_IN.
[  +0.000003] iSCSI Login successful on CID: 0 from 10.21.1.7:56958 to 10.21.1.230:3260,1
[  +0.000007] Incremented iSCSI Connection count to 1 from node: iqn.1993-08.org.debian:01:eac885df5da1
[  +0.000003] Established iSCSI session from node: iqn.1993-08.org.debian:01:eac885df5da1
[  +0.000004] Incremented number of active iSCSI sessions to 1 on iSCSI Target Portal Group: 1
[  +0.000005] Started NOPIN Timer on CID: 0 at 15 second interval
[  +0.000011] Moving to TARG_CONN_STATE_FREE.
[  +0.008976] rx_loop: 48, total_rx: 48, data: 48
[  +0.000033] Got SCSI Command, ITT: 0x0000004b, CmdSN: 0xfd040000, ExpXferLen: 16, Length: 0, CID: 0
[  +0.000018] Received CmdSN matches ExpCmdSN, incremented ExpCmdSN to: 0x000004fe
[  +0.000102] rx_loop: 48, total_rx: 48, data: 48
[  +0.000013] Got SCSI Command, ITT: 0x0000004c, CmdSN: 0xfe040000, ExpXferLen: 4, Length: 0, CID: 0
[  +0.000010] Received CmdSN matches ExpCmdSN, incremented ExpCmdSN to: 0x000004ff
[  +0.000943] ITT: 0x0000004b read_data_left is zero!
[  +0.000009] iscsit_get_datain_values failed for ITT: 0x0000004b
[  +0.000007] Moving to TARG_CONN_STATE_CLEANUP_WAIT.
[  +0.000005] Performing cleanup for failed iSCSI Connection ID: 0 from iqn.1993-08.org.debian:01:eac885df5da1
[  +0.000007] Closing iSCSI connection CID 0 on SID: 134
[  +0.000027] rx_loop: -512 total_rx: 0
[  +0.000052] Updated MaxCmdSN to 0x0000053d
[  +0.000016] Entering lio_release_cmd for se_cmd: 00000000e4a73f0a
[  +0.000010] Updated MaxCmdSN to 0x0000053e
[  +0.000007] Entering lio_release_cmd for se_cmd: 00000000317e3335
[  +0.000007] Stopping command counter.
[  +0.000007] Waiting for running cmds to complete.
[  +0.005851] Waiting for cmds done.
[  +0.000103] Moving to TARG_CONN_STATE_FREE.
[  +0.000017] Decremented iSCSI connection count to 0 from node: iqn.1993-08.org.debian:01:eac885df5da1
[  +0.000020] TARGET_CORE[iSCSI]: Deregistered fabric_sess
[  +0.000025] Moving to TARG_SESS_STATE_FREE.
[  +0.000006] Released iSCSI session from node: iqn.1993-08.org.debian:01:eac885df5da1
[  +0.000005] Decremented number of active iSCSI Sessions on iSCSI TPG: 1 to 0

Here is the error from above:
Code: 
[  +0.000013] Got SCSI Command, ITT: 0x0000004c, CmdSN: 0xfe040000, ExpXferLen: 4, Length: 0, CID: 0
[  +0.000010] Received CmdSN matches ExpCmdSN, incremented ExpCmdSN to: 0x000004ff
[  +0.000943] ITT: 0x0000004b read_data_left is zero!
[  +0.000009] iscsit_get_datain_values failed for ITT: 0x0000004b
[  +0.000007] Moving to TARG_CONN_STATE_CLEANUP_WAIT.
[  +0.000005] Performing cleanup for failed iSCSI Connection ID: 0 from iqn.1993-08.org.debian:01:eac885df5da1
[  +0.000007] Closing iSCSI connection CID 0 on SID: 134

What I see corresponds to the issue you mentioned.
 
yep seems like it:

gothbert said:
[ +0.000033] Got SCSI Command, ITT: 0x0000004b, CmdSN: 0xfd040000, ExpXferLen: 16, Length: 0, CID: 0
Click to expand...
says : 'ExpXferLen: 16' so 'expected transfer len 16' which would match our code before the patch

and then
gothbert said:
[ +0.000943] ITT: 0x0000004b read_data_left is zero!
Click to expand...
which is exactly that ITT

in the meantime the package was bumped (should be included in proxmox-backup-server 4.2.7-1) and uploaded to the pbstest repository, would be great if you could test that
 
Upgraded to PBS 4.2.7, rebooted.
Can get the status of the tape library and can read the test data I have previously written to the tape from PBS, but now labeling the tape fails immediately in another way:

Bash: 
root@pbs:~# proxmox-tape label --drive drive --label-text BN0001L8 -pool bn-continue
TASK ERROR: media read error - read failed - unexpected block len (10240 != 262144)
Error: task failed (status media read error - read failed - unexpected block len (10240 != 262144))

Debug log on target:
Code: 
[Sep25 16:44] rx_loop: 48, total_rx: 48, data: 48
[  +0.000034] Got SCSI Command, ITT: 0x0000000e, CmdSN: 0x55010000, ExpXferLen: 8192, Length: 0, CID: 0
[  +0.000023] Received CmdSN matches ExpCmdSN, incremented ExpCmdSN to: 0x00000156
[  +0.000071] Entering lio_release_cmd for se_cmd: 0000000097c299b2
[  +0.001197] Updated MaxCmdSN to 0x00000195
[  +0.000017] Built DataIN ITT: 0x0000000e, StatSN: 0x7ed12f0e, DataSN: 0x00000000, Offset: 0, Length: 445, CID: 0
[  +0.000012] Attaching 3 padding bytes
[  +0.000074] tx_loop: 48, total_tx: 48, data: 48
[  +0.000042] tx_loop: 3, total_tx: 3, data: 3
[  +5.057294] rx_loop: 48, total_rx: 48, data: 48
[  +0.000033] Got SCSI Command, ITT: 0x0000000f, CmdSN: 0x56010000, ExpXferLen: 8192, Length: 0, CID: 0
[  +0.000022] Received CmdSN matches ExpCmdSN, incremented ExpCmdSN to: 0x00000157
[  +0.000068] Entering lio_release_cmd for se_cmd: 00000000a42a485e
[  +0.001108] Updated MaxCmdSN to 0x00000196
[  +0.000009] Built DataIN ITT: 0x0000000f, StatSN: 0x7ed12f0f, DataSN: 0x00000000, Offset: 0, Length: 445, CID: 0
[  +0.000008] Attaching 3 padding bytes
[  +0.000067] tx_loop: 48, total_tx: 48, data: 48
[  +0.000028] tx_loop: 3, total_tx: 3, data: 3
[  +2.598691] Started NOPIN Response Timer on CID: 0 to 30 seconds
[  +0.000615] Built NOPIN Unsolicited Response ITT: 0xffffffff, TTT: 0x00000140, StatSN: 0x7ed12f10, Length 0
[  +0.000020] Sending Unsolicited NOPIN TTT: 0x40010000 StatSN: 0x7ed12f10 CID: 0
[  +0.000134] tx_loop: 48, total_tx: 48, data: 48
[  +0.000312] rx_loop: 48, total_rx: 48, data: 48
[  +0.000021] Got NOPOUT Ping Response ITT: 0xffffffff, TTT: 0x40010000, CmdSN: 0x57010000, ExpStatSN: 0x102fd17e, Length: 0
[  +0.000017] Started NOPIN Timer on CID: 0 at 15 second interval
[  +2.429494] rx_loop: 48, total_rx: 48, data: 48
[  +0.000093] Got SCSI Command, ITT: 0x00000011, CmdSN: 0x57010000, ExpXferLen: 8192, Length: 0, CID: 0
[  +0.000023] Received CmdSN matches ExpCmdSN, incremented ExpCmdSN to: 0x00000158
[  +0.000070] Entering lio_release_cmd for se_cmd: 0000000036495947
[  +0.001100] Updated MaxCmdSN to 0x00000197
[  +0.000014] Built DataIN ITT: 0x00000011, StatSN: 0x7ed12f10, DataSN: 0x00000000, Offset: 0, Length: 445, CID: 0
[  +0.000012] Attaching 3 padding bytes
[  +0.000061] tx_loop: 48, total_tx: 48, data: 48
[  +0.000039] tx_loop: 3, total_tx: 3, data: 3
[  +5.025858] rx_loop: 48, total_rx: 48, data: 48
[  +0.000033] Got SCSI Command, ITT: 0x00000012, CmdSN: 0x58010000, ExpXferLen: 8192, Length: 0, CID: 0
[  +0.000021] Received CmdSN matches ExpCmdSN, incremented ExpCmdSN to: 0x00000159
[  +0.000068] Entering lio_release_cmd for se_cmd: 000000004435b300
[  +0.001125] Updated MaxCmdSN to 0x00000198
[  +0.000009] Built DataIN ITT: 0x00000012, StatSN: 0x7ed12f11, DataSN: 0x00000000, Offset: 0, Length: 445, CID: 0
[  +0.000009] Attaching 3 padding bytes
[  +0.000067] tx_loop: 48, total_tx: 48, data: 48
[  +0.000029] tx_loop: 3, total_tx: 3, data: 3
[  +4.156871] rx_loop: 48, total_rx: 48, data: 48
[  +0.000034] Got SCSI Command, ITT: 0x00000013, CmdSN: 0x59010000, ExpXferLen: 36, Length: 0, CID: 0
[  +0.000022] Received CmdSN matches ExpCmdSN, incremented ExpCmdSN to: 0x0000015a
[  +0.000069] Entering lio_release_cmd for se_cmd: 00000000da2f7bb2
[  +0.000919] Updated MaxCmdSN to 0x00000199
[  +0.000013] Built DataIN ITT: 0x00000013, StatSN: 0x7ed12f12, DataSN: 0x00000000, Offset: 0, Length: 36, CID: 0
[  +0.000080] tx_loop: 48, total_tx: 48, data: 48
[  +0.000417] rx_loop: 48, total_rx: 48, data: 48
[  +0.000015] Got SCSI Command, ITT: 0x00000014, CmdSN: 0x5a010000, ExpXferLen: 0, Length: 0, CID: 0
[  +0.000010] Received CmdSN matches ExpCmdSN, incremented ExpCmdSN to: 0x0000015b
[  +0.000029] Entering lio_release_cmd for se_cmd: 000000005ea6eb6a
[  +0.000618] Updated MaxCmdSN to 0x0000019a
[  +0.000009] Built SCSI Response, ITT: 0x00000014, StatSN: 0x7ed12f13, Response: 0x00, SAM Status: 0x00, CID: 0
[  +0.000039] tx_loop: 48, total_tx: 48, data: 48
[  +0.000407] rx_loop: 48, total_rx: 48, data: 48
[  +0.000011] Got SCSI Command, ITT: 0x00000015, CmdSN: 0x5b010000, ExpXferLen: 0, Length: 0, CID: 0
[  +0.000009] Received CmdSN matches ExpCmdSN, incremented ExpCmdSN to: 0x0000015c
[  +0.000018] Entering lio_release_cmd for se_cmd: 0000000018c467fb
[  +0.000662] Updated MaxCmdSN to 0x0000019b
[  +0.000009] Built SCSI Response, ITT: 0x00000015, StatSN: 0x7ed12f14, Response: 0x00, SAM Status: 0x00, CID: 0
[  +0.000024] tx_loop: 48, total_tx: 48, data: 48
[  +0.000412] rx_loop: 48, total_rx: 48, data: 48
[  +0.000015] Got SCSI Command, ITT: 0x00000016, CmdSN: 0x5c010000, ExpXferLen: 4096, Length: 0, CID: 0
[  +0.000011] Received CmdSN matches ExpCmdSN, incremented ExpCmdSN to: 0x0000015d
[  +0.000037] Entering lio_release_cmd for se_cmd: 0000000071134bc7
[  +0.000975] Updated MaxCmdSN to 0x0000019c
[  +0.000009] Built DataIN ITT: 0x00000016, StatSN: 0x7ed12f15, DataSN: 0x00000000, Offset: 0, Length: 32, CID: 0
[  +0.000052] tx_loop: 48, total_tx: 48, data: 48
[  +0.000546] rx_loop: 48, total_rx: 48, data: 48
[  +0.000012] Got SCSI Command, ITT: 0x00000017, CmdSN: 0x5d010000, ExpXferLen: 32, Length: 32, CID: 0
[  +0.000014] Entering lio_release_cmd for se_cmd: 000000007fdc3cfa
[  +0.000031] rx_loop: 32, total_rx: 32, data: 32
[  +0.000007] Received CmdSN matches ExpCmdSN, incremented ExpCmdSN to: 0x0000015e
[  +0.001035] Updated MaxCmdSN to 0x0000019d
[  +0.000009] Built SCSI Response, ITT: 0x00000017, StatSN: 0x7ed12f16, Response: 0x00, SAM Status: 0x00, CID: 0
[  +0.000036] tx_loop: 48, total_tx: 48, data: 48
[  +0.000262] rx_loop: 48, total_rx: 48, data: 48
[  +0.000013] Got SCSI Command, ITT: 0x00000008, CmdSN: 0x5e010000, ExpXferLen: 4096, Length: 0, CID: 0
[  +0.000010] Received CmdSN matches ExpCmdSN, incremented ExpCmdSN to: 0x0000015f
[  +0.000031] Entering lio_release_cmd for se_cmd: 00000000fef0bee3
[  +0.000683] Updated MaxCmdSN to 0x0000019e
[  +0.000008] Built DataIN ITT: 0x00000008, StatSN: 0x7ed12f17, DataSN: 0x00000000, Offset: 0, Length: 48, CID: 0
[  +0.000032] tx_loop: 48, total_tx: 48, data: 48
[  +0.000312] rx_loop: 48, total_rx: 48, data: 48
[  +0.000011] Got SCSI Command, ITT: 0x00000018, CmdSN: 0x5f010000, ExpXferLen: 48, Length: 48, CID: 0
[  +0.000013] Entering lio_release_cmd for se_cmd: 00000000ab519676
[  +0.000030] rx_loop: 48, total_rx: 48, data: 48
[  +0.000007] Received CmdSN matches ExpCmdSN, incremented ExpCmdSN to: 0x00000160
[  +0.001995] Updated MaxCmdSN to 0x0000019f
[  +0.000022] Built SCSI Response, ITT: 0x00000018, StatSN: 0x7ed12f18, Response: 0x00, SAM Status: 0x00, CID: 0
[  +0.000093] tx_loop: 48, total_tx: 48, data: 48
[  +0.000723] rx_loop: 48, total_rx: 48, data: 48
[  +0.000019] Got SCSI Command, ITT: 0x0000001a, CmdSN: 0x60010000, ExpXferLen: 0, Length: 0, CID: 0
[  +0.000018] Received CmdSN matches ExpCmdSN, incremented ExpCmdSN to: 0x00000161
[  +0.000042] Entering lio_release_cmd for se_cmd: 0000000046b10eb7
[  +0.004066] Updated MaxCmdSN to 0x000001a0
[  +0.000031] Built SCSI Response, ITT: 0x0000001a, StatSN: 0x7ed12f19, Response: 0x00, SAM Status: 0x00, CID: 0
[  +0.000088] tx_loop: 48, total_tx: 48, data: 48
[  +0.001693] rx_loop: 48, total_rx: 48, data: 48
[  +0.000033] Got SCSI Command, ITT: 0x0000001b, CmdSN: 0x61010000, ExpXferLen: 262144, Length: 0, CID: 0
[  +0.000020] Received CmdSN matches ExpCmdSN, incremented ExpCmdSN to: 0x00000162
[  +0.000207] Entering lio_release_cmd for se_cmd: 00000000549d3c3d
[  +0.005893] Updated MaxCmdSN to 0x000001a1
[  +0.000022] Built DataIN ITT: 0x0000001b, StatSN: 0x7ed12f1a, DataSN: 0x00000000, Offset: 0, Length: 10240, CID: 0
[  +0.000100] tx_loop: 48, total_tx: 48, data: 48
[  +0.001122] rx_loop: 48, total_rx: 48, data: 48
[  +0.000028] Got SCSI Command, ITT: 0x0000001c, CmdSN: 0x62010000, ExpXferLen: 8192, Length: 0, CID: 0
[  +0.000018] Received CmdSN matches ExpCmdSN, incremented ExpCmdSN to: 0x00000163
[  +0.000089] Entering lio_release_cmd for se_cmd: 000000007ce24eff
[  +0.000700] Updated MaxCmdSN to 0x000001a2
[  +0.000011] Built DataIN ITT: 0x0000001c, StatSN: 0x7ed12f1b, DataSN: 0x00000000, Offset: 0, Length: 92, CID: 0
[  +0.000065] tx_loop: 48, total_tx: 48, data: 48
[  +0.000275] rx_loop: 48, total_rx: 48, data: 48
[  +0.000010] Got SCSI Command, ITT: 0x0000001d, CmdSN: 0x63010000, ExpXferLen: 20, Length: 20, CID: 0
[  +0.000031] Entering lio_release_cmd for se_cmd: 000000006ec98978
[  +0.000033] rx_loop: 20, total_rx: 20, data: 20
[  +0.000007] Received CmdSN matches ExpCmdSN, incremented ExpCmdSN to: 0x00000164
[  +0.001451] Updated MaxCmdSN to 0x000001a3
[  +0.000010] Built SCSI Response, ITT: 0x0000001d, StatSN: 0x7ed12f1c, Response: 0x00, SAM Status: 0x00, CID: 0
[  +0.000041] tx_loop: 48, total_tx: 48, data: 48
[  +0.000362] rx_loop: 48, total_rx: 48, data: 48
[  +0.000012] Got SCSI Command, ITT: 0x0000001f, CmdSN: 0x64010000, ExpXferLen: 8192, Length: 0, CID: 0
[  +0.000010] Received CmdSN matches ExpCmdSN, incremented ExpCmdSN to: 0x00000165
[  +0.000031] Entering lio_release_cmd for se_cmd: 0000000052936955
[  +0.000678] Updated MaxCmdSN to 0x000001a4
[  +0.000009] Built DataIN ITT: 0x0000001f, StatSN: 0x7ed12f1d, DataSN: 0x00000000, Offset: 0, Length: 24, CID: 0
[  +0.000041] tx_loop: 48, total_tx: 48, data: 48
[  +0.902847] rx_loop: 48, total_rx: 48, data: 48
[  +0.000033] Got SCSI Command, ITT: 0x00000020, CmdSN: 0x65010000, ExpXferLen: 8192, Length: 0, CID: 0
[  +0.000023] Received CmdSN matches ExpCmdSN, incremented ExpCmdSN to: 0x00000166
[  +0.000067] Entering lio_release_cmd for se_cmd: 0000000064b24c94
[  +0.001193] Updated MaxCmdSN to 0x000001a5
[  +0.000014] Built DataIN ITT: 0x00000020, StatSN: 0x7ed12f1e, DataSN: 0x00000000, Offset: 0, Length: 445, CID: 0
[  +0.000011] Attaching 3 padding bytes
[  +0.000077] tx_loop: 48, total_tx: 48, data: 48
[  +0.000065] tx_loop: 3, total_tx: 3, data: 3
[Sep25 16:45] Started NOPIN Response Timer on CID: 0 to 30 seconds
[  +0.000173] Built NOPIN Unsolicited Response ITT: 0xffffffff, TTT: 0x0000014a, StatSN: 0x7ed12f1f, Length 0
[  +0.000013] Sending Unsolicited NOPIN TTT: 0x4a010000 StatSN: 0x7ed12f1f CID: 0
[  +0.000090] tx_loop: 48, total_tx: 48, data: 48
[  +0.000758] rx_loop: 48, total_rx: 48, data: 48
[  +0.000011] Got NOPOUT Ping Response ITT: 0xffffffff, TTT: 0x4a010000, CmdSN: 0x66010000, ExpStatSN: 0x1f2fd17e, Length: 0
[  +0.000015] Started NOPIN Timer on CID: 0 at 15 second interval
[  +2.233279] rx_loop: 48, total_rx: 48, data: 48
[  +0.000023] Got SCSI Command, ITT: 0x00000022, CmdSN: 0x66010000, ExpXferLen: 8192, Length: 0, CID: 0
[  +0.000013] Received CmdSN matches ExpCmdSN, incremented ExpCmdSN to: 0x00000167
[  +0.000056] Entering lio_release_cmd for se_cmd: 000000005692026b
[  +0.001005] Updated MaxCmdSN to 0x000001a6
[  +0.000011] Built DataIN ITT: 0x00000022, StatSN: 0x7ed12f1f, DataSN: 0x00000000, Offset: 0, Length: 445, CID: 0
[  +0.000007] Attaching 3 padding bytes
[  +0.000080] tx_loop: 48, total_tx: 48, data: 48
[  +0.000030] tx_loop: 3, total_tx: 3, data: 3
[  +5.037006] rx_loop: 48, total_rx: 48, data: 48
[  +0.000030] Got NOPOUT Ping Request ITT: 0x00000023, TTT: 0xffffffff, CmdSN: 0x67010000, ExpStatSN: 0x202fd17e, Length: 0
[  +0.000021] Entering lio_release_cmd for se_cmd: 00000000240dd8ef
[  +0.000047] Built NOPIN Solicited Response ITT: 0x00000023, TTT: 0xffffffff, StatSN: 0x7ed12f20, Length 0
[  +0.000015] Echoing back 0 bytes of ping data.
[  +0.000073] tx_loop: 48, total_tx: 48, data: 48
[  +0.025397] rx_loop: 48, total_rx: 48, data: 48
[  +0.000033] Got SCSI Command, ITT: 0x00000024, CmdSN: 0x67010000, ExpXferLen: 8192, Length: 0, CID: 0
[  +0.000023] Received CmdSN matches ExpCmdSN, incremented ExpCmdSN to: 0x00000168
[  +0.001217] Updated MaxCmdSN to 0x000001a7
[  +0.000034] Built DataIN ITT: 0x00000024, StatSN: 0x7ed12f21, DataSN: 0x00000000, Offset: 0, Length: 445, CID: 0
[  +0.000013] Attaching 3 padding bytes
[  +0.000064] tx_loop: 48, total_tx: 48, data: 48
[  +0.000029] tx_loop: 3, total_tx: 3, data: 3
[  +5.080657] rx_loop: 48, total_rx: 48, data: 48
[  +0.000027] Got SCSI Command, ITT: 0x00000025, CmdSN: 0x68010000, ExpXferLen: 8192, Length: 0, CID: 0
[  +0.000015] Received CmdSN matches ExpCmdSN, incremented ExpCmdSN to: 0x00000169
[  +0.000057] Entering lio_release_cmd for se_cmd: 000000003d851a38
[  +0.001083] Updated MaxCmdSN to 0x000001a8
[  +0.000008] Built DataIN ITT: 0x00000025, StatSN: 0x7ed12f22, DataSN: 0x00000000, Offset: 0, Length: 445, CID: 0
[  +0.000008] Attaching 3 padding bytes
[  +0.000058] tx_loop: 48, total_tx: 48, data: 48
[  +0.000028] tx_loop: 3, total_tx: 3, data: 3
[  +2.978915] Started NOPIN Response Timer on CID: 0 to 30 seconds
[  +0.000069] Built NOPIN Unsolicited Response ITT: 0xffffffff, TTT: 0x0000014e, StatSN: 0x7ed12f23, Length 0
[  +0.000013] Sending Unsolicited NOPIN TTT: 0x4e010000 StatSN: 0x7ed12f23 CID: 0
[  +0.000088] tx_loop: 48, total_tx: 48, data: 48
[  +0.001875] rx_loop: 48, total_rx: 48, data: 48
[  +0.000016] Got NOPOUT Ping Response ITT: 0xffffffff, TTT: 0x4e010000, CmdSN: 0x69010000, ExpStatSN: 0x232fd17e, Length: 0
[  +0.000019] Started NOPIN Timer on CID: 0 at 15 second interval
[  +2.037356] rx_loop: 48, total_rx: 48, data: 48
[  +0.000032] Got SCSI Command, ITT: 0x00000019, CmdSN: 0x69010000, ExpXferLen: 8192, Length: 0, CID: 0
[  +0.000021] Received CmdSN matches ExpCmdSN, incremented ExpCmdSN to: 0x0000016a
[  +0.000071] Entering lio_release_cmd for se_cmd: 00000000443a4303
[  +0.001166] Updated MaxCmdSN to 0x000001a9
[  +0.000009] Built DataIN ITT: 0x00000019, StatSN: 0x7ed12f23, DataSN: 0x00000000, Offset: 0, Length: 445, CID: 0
[  +0.000008] Attaching 3 padding bytes
[  +0.000041] tx_loop: 48, total_tx: 48, data: 48
[  +0.000027] tx_loop: 3, total_tx: 3, data: 3
[  +5.019792] rx_loop: 48, total_rx: 48, data: 48
[  +0.000034] Got SCSI Command, ITT: 0x00000027, CmdSN: 0x6a010000, ExpXferLen: 8192, Length: 0, CID: 0
[  +0.000024] Received CmdSN matches ExpCmdSN, incremented ExpCmdSN to: 0x0000016b
[  +0.000067] Entering lio_release_cmd for se_cmd: 00000000f40ac055
[  +0.001473] Updated MaxCmdSN to 0x000001aa
[  +0.000023] Built DataIN ITT: 0x00000027, StatSN: 0x7ed12f24, DataSN: 0x00000000, Offset: 0, Length: 445, CID: 0
[  +0.000016] Attaching 3 padding bytes
[  +0.000089] tx_loop: 48, total_tx: 48, data: 48
[  +0.000046] tx_loop: 3, total_tx: 3, data: 3
 
looks weird, we request 262144 byte but only get 10240 back...

[ +0.000033] Got SCSI Command, ITT: 0x0000001b, CmdSN: 0x61010000, ExpXferLen: 262144, Length: 0, CID: 0
[ +0.000020] Received CmdSN matches ExpCmdSN, incremented ExpCmdSN to: 0x00000162
[ +0.000207] Entering lio_release_cmd for se_cmd: 00000000549d3c3d
[ +0.005893] Updated MaxCmdSN to 0x000001a1
[ +0.000022] Built DataIN ITT: 0x0000001b, StatSN: 0x7ed12f1a, DataSN: 0x00000000, Offset: 0, Length: 10240, CID: 0
Click to expand...

is there some transfer size limit on the lio side maybe?

EDIT: did you format the tape beforehand? (this is necessary for labeling)
 
Last edited:
I finally solved it.

The parameter MaxRecvDataSegmentLength was 8192.
Code: 
set parameter MaxRecvDataSegmentLength=262144
in targetcli did not fix the issue.

The reason was the small tar archive previously written to the tape for testing purposes. It created a 10k block whereas
Code: 
proxmox-tape label ...
expects a 256k block. Writing a 256k block with
Code: 
dd if=/dev/zero of=/dev/st0 bs=256k count=1
followed by
Code: 
mt -f /dev/st0 eof
initialized the tape into a reasonable state. After that,
Code: 
proxmox-tape label ...
succeeded.

Conclusions:
  • The fix included in proxmox-backup-server 4.2.7-1 solves the initial issue.
  • Suggestion: As a service to the user, the proxmox-tape label command should account for non-empty tapes with size of first block different from 256k.
  • Writing a 256k block with an EOF mark at the beginning is a means of bringing the tape into a compliant state.
 
  • Like
Reactions: Onslow
gothbert said:
  • Suggestion: As a service to the user, the proxmox-tape labelcommand should account for non-empty tapes with size of first block different from 256k.
Click to expand...
for that i sent a patch [0] to improve the error message in that case:

what should also have worked besides clearing out the tape manually would have been:

Code: 
proxmox-tape format --drive <driveid>

(or clicking format in the webui)

this erases the tape content


0: https://lore.proxmox.com/pbs-devel/20260928131405.3659144-1-d.csapak@proxmox.com/T/#u
 
  • Like
Reactions: Onslow
Thank you for considering my suggestion regarding the error message!

Actually, yesterday, I was tempted to clear or format the tape. Though, last week, I initiated what I thought was a short erase but clearing the tape lasted hours. So fiddling with the first block was my quick fix for the size mismatch.
 
You must log in or register to reply here.
Top Bottom
Back