We probably to have to run a few commands with the tape mounted. Do you have the exact SCSI command sent somewhere in the logs ?
On Thu, Mar 15, 2018 at 4:53 PM, Milan Stubniak <[email protected]> wrote: > Hello, > i would like to ask about write error in TSM (Spectrum protect). Whe have > quadstor vtl server (3.0.25), which is destination library for TSM(Spectrum > protect for virtual enviroments- proxy backup for VM). > Sometimes (two times a week ) during backup from VM nodes to VTL (this > backup is performed by TSMforVirtualEnviroment Server) , we see TSM error > (below). Backup of VM failed. TSM marks this tape as read-only. > > 03/13/18 22:08:49 ANR8302E (Session: 838432, Origin: WBBHVN04_STA) > I/O > > error on drive DRV43 (mt2.9.0.1) with volume > B10001L5 > > (OP=LOCATE, Error Number=1104, CC=0, rc = 2865, > KEY= 08, > > ASC=00, ASCQ= 05, > SENSE=70.00.08.00.00.00.00.0A.00.00.00- > > .00.00.05.00.00.00, Description=An undetermined > error > > has occurred). Refer to the IBM Spectrum Protect > > documentation on I/O error code descriptions. > (SESSION: > > 838432) > > 1797225) > > 03/13/18 22:08:51 ANR0408I (Session: 838432, Origin: WBBHVN04_STA) > Session > > 28353 started for server BKPAPS1 (AIX) (Tcp/Ip) > for > > library sharing. (SESSION: 838432) > > 03/13/18 22:08:51 ANR0409I (Session: 838432, Origin: WBBHVN04_STA) > Session > > 28353 ended for server BKPAPS1 (AIX). (SESSION: > 838432) > > 03/13/18 22:08:51 ANR0523W (Session: 838432, Origin: WBBHVN04_STA) > > Transaction failed for session 28349 for node > > HYPERV_2012R2 (TDP HyperV) - error on output > storage > > device. (SESSION: 838432) > > 03/13/18 22:08:51 ANR0523W Transaction failed for session 1797219 for > node > > HYPERV_2012R2 (TDP HyperV) - error on output > storage > > device. (SESSION: 1797219) > > In VTL log we see only "standard" warnning: > > 13 22:08:04 oscsvtl1 kernel: WARN: __tdrive_cmd_validate_write:2316 VTL > obpds drive 3 validate write failed with error Operator selected write > protect > > After backup task from VM environment to VTL is done, we have scheduled job > to copy VTL storage pool to Physical tape. (from VTL to Physical tape - this > is done by TSM server). Operation failed with errors in TSM. > > > > 03/14/18 01:36:56 ANR9999D_0252090925 > NtpValidateComBlockHdr(pvrntp.c:6123) > > Thread<3631258>: Invalid block header read from > NTP > > drive DRV42 (/dev/rmt-vtl22). (magic=5A4D4E50, > ver=5, > > Hdr blk=11610832 <expected 11610832>, > dbytes=262096 > > <231220>) (SESSION: 1798707, PROCESS: 2009) > > 03/14/18 01:36:56 ANR9999D Thread<3631258> issued message 9999 from: > > (SESSION: 1798707, PROCESS: 2009) > > 03/14/18 01:36:56 ANR9999D Thread<3631258> 0x0000000100031254 > StdPutText > > (SESSION: 1798707, PROCESS: 2009) > > 03/14/18 01:36:56 ANR9999D Thread<3631258> 0x0000000100031e58 > > OutDiagToCons (SESSION: 1798707, PROCESS: 2009) > > 03/14/18 01:36:56 ANR9999D Thread<3631258> 0x000000010000adf4 > outDiagfExt > > (SESSION: 1798707, PROCESS: 2009) > > 03/14/18 01:36:56 ANR9999D Thread<3631258> 0x0000000100ade958 > > IPRA.$FetchBlock (SESSION: 1798707, PROCESS: > 2009) > > 03/14/18 01:36:56 ANR9999D Thread<3631258> 0x0000000100ae05d4 > NtpReadNC > > (SESSION: 1798707, PROCESS: 2009) > > 03/14/18 01:36:56 ANR9999D Thread<3631258> 0x0000000100b1dab0 > LtoReadNC > > (SESSION: 1798707, PROCESS: 2009) > > 03/14/18 01:36:56 ANR9999D Thread<3631258> 0x0000000100720dd8 > AgentThread > > (SESSION: 1798707, PROCESS: 2009) > > 03/14/18 01:36:56 ANR9999D Thread<3631258> 0x000000010000e300 > StartThread > > more... (<ENTER> to continue, 'C' to cancel) > > > > (SESSION: 1798707, PROCESS: 2009) > > 03/14/18 01:36:56 ANR1218E BACKUP STGPOOL: Process 2009 terminated - > > excessive read errors encountered. (SESSION: > 1798707, > > PROCESS: 2009) > > 03/14/18 01:36:56 ANR0986I Process 2009 for BACKUP STORAGE POOL > running in > > the BACKGROUND processed 63,319 items for a total > of > > 466,828,716,893 bytes with a completion state of > FAILURE > > at 01:36:56. (SESSION: 1798707, PROCESS: 2009) > > 03/14/18 01:36:56 ANR1893E Process 2009 for BACKUP STORAGE POOL > completed > > with a completion state of FAILURE. (SESSION: > 1798707, > > PROCESS: 2009) > > 03/14/18 01:36:56 ANR0514I Session 1798707 closed volume B10001L5. > > (SESSION: 1798707) > > > In VTL library log we see: > > > Mar 14 01:36:56 oscsvtl1 kernel: Warning at blk_map.c:blk_map_read:1974 > Mar 14 01:36:56 oscsvtl1 kernel: ------------[ cut here ]------------ > Mar 14 01:36:56 oscsvtl1 kernel: WARNING: at > /quadstorvtl/src/export/core_linux.c:336 debug_check+0x1a/0x20 [vtlcore]() > (Tainted: G W -- ------------ ) > Mar 14 01:36:56 oscsvtl1 kernel: Hardware name: ProLiant BL460c Gen8 > Mar 14 01:36:56 oscsvtl1 kernel: Modules linked in: ch osst st iscsit(U) > vtldev(U) vtlcore(U) autofs4 cpufreq_ondemand freq_table pcc_cpufreq bonding > iptable_filter ip_tables ip6t_REJECT nf_conntrack_ipv6 nf_defrag_ipv > 6 xt_state nf_conntrack ip6table_filter ip6_tables ipv6 video output > microcode power_meter acpi_ipmi ipmi_si ipmi_msghandler iTCO_wdt > iTCO_vendor_support hpilo hpwdt sg serio_raw lpc_ich mfd_core ioatdma dca > shpchp ext > 4 jbd2 mbcache dm_round_robin sd_mod crc_t10dif qla2xxx(U) scsi_transport_fc > scsi_tgt hpsa be2net dm_multipath dm_mirror dm_region_hash dm_log dm_mod > [last unloaded: scsi_wait_scan] > Mar 14 01:36:56 oscsvtl1 kernel: Pid: 6170, comm: tdrv00102 Tainted: G > W -- ------------ 2.6.32-642.13.1.el6.x86_64 #1 > Mar 14 01:36:56 oscsvtl1 kernel: Call Trace: > Mar 14 01:36:56 oscsvtl1 kernel: [<ffffffff8107c6f1>] ? > warn_slowpath_common+0x91/0xe0 > Mar 14 01:36:56 oscsvtl1 kernel: [<ffffffff8107c75a>] ? > warn_slowpath_null+0x1a/0x20 > Mar 14 01:36:56 oscsvtl1 kernel: [<ffffffffa045598a>] ? > debug_check+0x1a/0x20 [vtlcore] > Mar 14 01:36:56 oscsvtl1 kernel: [<ffffffffa0477c4a>] ? > blk_map_read+0xeaa/0x15e0 [vtlcore] > Mar 14 01:36:56 oscsvtl1 kernel: [<ffffffff81064855>] ? > find_busiest_group+0x9d5/0xa50 > Mar 14 01:36:56 oscsvtl1 kernel: [<ffffffff8106be68>] ? > load_balance_fair+0x208/0x300 > Mar 14 01:36:56 oscsvtl1 kernel: [<ffffffff8117ecbc>] ? > transfer_objects+0x5c/0x80 > Mar 14 01:36:56 oscsvtl1 kernel: [<ffffffff8117f76b>] ? > cache_alloc_refill+0x15b/0x240 > Mar 14 01:36:56 oscsvtl1 kernel: [<ffffffff8113a573>] ? __rmqueue+0xc3/0x490 > Mar 14 01:36:56 oscsvtl1 kernel: [<ffffffff810657e0>] ? > __dequeue_entity+0x30/0x50 > Mar 14 01:36:56 oscsvtl1 kernel: [<ffffffff81151319>] ? > zone_statistics+0x99/0xc0 > Mar 14 01:36:56 oscsvtl1 kernel: [<ffffffff8113dea9>] ? > __alloc_pages_nodemask+0x129/0x950 > Mar 14 01:36:56 oscsvtl1 kernel: [<ffffffff8100bc0e>] ? > apic_timer_interrupt+0xe/0x20 > Mar 14 01:36:56 oscsvtl1 kernel: [<ffffffffa010e02c>] ? > ctio_sglist_map+0x4c/0x140 [qla2xxx] > Mar 14 01:36:56 oscsvtl1 kernel: [<ffffffff8106b2a3>] ? > perf_event_task_sched_out+0x33/0x70 > Mar 14 01:36:56 oscsvtl1 kernel: [<ffffffffa04c105f>] ? > tape_partition_read+0x11f/0x130 [vtlcore] > Mar 14 01:36:56 oscsvtl1 kernel: [<ffffffffa04bc33c>] ? > tape_cmd_read+0x9c/0xd0 [vtlcore] > Mar 14 01:36:56 oscsvtl1 kernel: [<ffffffffa04c828a>] ? > tdrive_wait_for_write_queue+0x6a/0x80 [vtlcore] > Mar 14 01:36:56 oscsvtl1 kernel: [<ffffffffa04cce6f>] ? > __tdrive_cmd_read+0x16f/0x510 [vtlcore] > Mar 14 01:36:56 oscsvtl1 kernel: [<ffffffff8106b2a3>] ? > perf_event_task_sched_out+0x33/0x70 > Mar 14 01:36:56 oscsvtl1 kernel: [<ffffffff8100969d>] ? > __switch_to+0x7d/0x340 > Mar 14 01:36:56 oscsvtl1 kernel: [<ffffffffa04d029f>] ? > tdrive_proc_cmd+0xbff/0x1d80 [vtlcore] > Mar 14 01:36:56 oscsvtl1 kernel: [<ffffffff81548a1e>] ? schedule+0x3ee/0xb70 > Mar 14 01:36:56 oscsvtl1 kernel: [<ffffffff810a6c9c>] ? > remove_wait_queue+0x3c/0x50 > Mar 14 01:36:56 oscsvtl1 kernel: [<ffffffffa045616a>] ? > __wait_on_chan_sig+0x9a/0xc0 [vtlcore] > Mar 14 01:36:56 oscsvtl1 kernel: [<ffffffff810a68a0>] ? > autoremove_wake_function+0x0/0x40 > Mar 14 01:36:56 oscsvtl1 kernel: [<ffffffffa049226b>] ? > devq_thread+0xab/0x130 [vtlcore] > Mar 14 01:36:56 oscsvtl1 kernel: [<ffffffffa04921c0>] ? > devq_thread+0x0/0x130 [vtlcore] > Mar 14 01:36:56 oscsvtl1 kernel: [<ffffffff810a640e>] ? kthread+0x9e/0xc0 > Mar 14 01:36:56 oscsvtl1 kernel: [<ffffffff8100c28a>] ? child_rip+0xa/0x20 > Mar 14 01:36:56 oscsvtl1 kernel: [<ffffffff810a6370>] ? kthread+0x0/0xc0 > Mar 14 01:36:56 oscsvtl1 kernel: [<ffffffff8100c280>] ? child_rip+0x0/0x20 > Mar 14 01:36:56 oscsvtl1 kernel: ---[ end trace 7186d29d5e453da0 ]--- > Mar 14 01:36:56 oscsvtl1 kernel: WARN: blk_map_read:1988 Incomplete read > block(s) encountered read size 262144 todo 30876 fixed 0 num blocks 1 data > blocks 1 ili block size 0 > > This failed tape(VTL) we can move to another tape , but we have some damaged > - unrecoverable files on tape. > > > This behaviour is the same on our second quadstor server. We tried to > eliminate HW issues of VTL server. In VTL log we don`t see errors (VTL > errors) but in TSM are present: > > Backup from VTL to TSM server: > > > 03/13/18 09:31:25 ANR8337I LTO volume D00007L6 mounted in drive DRV62 > > (/dev/rmt1). (SESSION: 1786097, PROCESS: 1999) > > 03/13/18 09:31:25 ANR0512I Process 1999 opened input volume D00007L6. > > (SESSION: 1786097, PROCESS: 1999) > > 03/13/18 09:31:42 ANR8302E I/O error on drive DRV62 (/dev/rmt1) with > volume > > D00007L6 (OP=READ, Error Number=5, CC=0, rc = > 2865, KEY= > > 08, ASC=00, ASCQ= 05, > SENSE=F0.00.08.00.04.00.00.0A.00.0- > > 0.00.00.00.05.00.00.00.00, Description=An > undetermined > > error has occurred). Refer to the IBM Spectrum > Protect > > documentation on I/O error code descriptions. > (SESSION: > > 1786097, PROCESS: 1999) > > 03/13/18 09:31:42 ANR9999D_2412546014 NtpReadNC(pvrntp.c:3266) > > Thread<3606553>: Next block is unknown for volume > > D00007L6. (SESSION: 1786097, PROCESS: 1999) > > 03/13/18 09:31:42 ANR9999D Thread<3606553> issued message 9999 from: > > (SESSION: 1786097, PROCESS: 1999) > > 03/13/18 09:31:42 ANR9999D Thread<3606553> 0x0000000100031254 > StdPutText > > (SESSION: 1786097, PROCESS: 1999) > > 03/13/18 09:31:42 ANR9999D Thread<3606553> 0x0000000100031e58 > > OutDiagToCons (SESSION: 1786097, PROCESS: 1999) > > 03/13/18 09:31:42 ANR9999D Thread<3606553> 0x000000010000adf4 > outDiagfExt > > (SESSION: 1786097, PROCESS: 1999) > > 03/13/18 09:31:42 ANR9999D Thread<3606553> 0x0000000100ae0810 > NtpReadNC > > (SESSION: 1786097, PROCESS: 1999) > > 03/13/18 09:31:42 ANR9999D Thread<3606553> 0x0000000100b1dab0 > LtoReadNC > > (SESSION: 1786097, PROCESS: 1999) > > 03/13/18 09:31:42 ANR9999D Thread<3606553> 0x0000000100720dd8 > AgentThread > > (SESSION: 1786097, PROCESS: 1999) > > 03/13/18 09:31:42 ANR9999D Thread<3606553> 0x000000010000e300 > StartThread > > (SESSION: 1786097, PROCESS: 1999) > > 03/13/18 09:31:42 ANR1330E The server has detected possible > corruption in > > an object that is being restored or moved. The > actual values for the incorrect frame are: magic > 53454652 hdr > > version 2 hdr length 32 sequence number > 86 > > data length 3FFB0 server ID 0 segment ID > > 594476150 crc 0. (SESSION: 1786097, > PROCESS: > > 1999) > > 03/13/18 09:31:42 ANR1331E Invalid frame detected. Expected magic > 53454652 > > sequence number 88 server id 0 > segment id > > 594476150. (SESSION: 1786097, PROCESS: 1999) > > 03/13/18 09:31:44 ANR8302E I/O error on drive DRV62 (/dev/rmt1) with > volume > > D00007L6 (OP=LOCATE, Error Number=5, CC=0, rc = > 2865, > > KEY= 08, ASC=00, ASCQ= 05, > SENSE=70.00.08.00.00.00.00.0A- > > .00.00.00.00.00.05.00.00.00.00, Description=An > > undetermined error has occurred). Refer to the IBM > > Spectrum Protect documentation on I/O error code > > descriptions. (SESSION: 1786097, PROCESS: 1999) > > 03/13/18 09:31:44 ANR1218E BACKUP STGPOOL: Process 1999 terminated - > > excessive read errors encountered. (SESSION: > 1786097, > > PROCESS: 1999) > > 03/13/18 09:31:44 ANR0985I Process 1999 for BACKUP STORAGE POOL > running in > > the BACKGROUND completed with completion state > FAILURE > > at 09:31:44. (SESSION: 1786097, PROCESS: 1999) > > 03/13/18 09:31:44 ANR1893E Process 1999 for BACKUP STORAGE POOL > completed > > with a completion state of FAILURE. (SESSION: > 1786097, > > PROCESS: 1999) > > 03/13/18 09:31:44 ANR0514I Session 1786097 closed volume D00007L6. > > (SESSION: 1786097) > > 03/13/18 09:31:44 ANR0514I Session 1786097 closed volume A00065L7. > > (SESSION: 1786097) > > 03/13/18 09:31:44 ANR1214I The backup of the TAPE_BKPTPL16 primary > storage > > pool to the COPY_BKPTPL16 copy storage pool is > complete. > > Number of files backed up: 0. Number of bytes > backed up: > > 0. Deduplicated bytes backed up: 0. Unreadable > files: 1. > > Unreadable bytes: 607139076487. (SESSION: 1786097) > > 03/13/18 09:31:44 ANR8468I LTO volume D00007L6 dismounted from drive > DRV62 > > (/dev/rmt1) in library BKPTPL16. (SESSION: > 1786097, > > PROCESS: 1999 > > next day we have damaged files on VTL library: > > 03/14/18 09:30:10 ANR1257W Storage pool backup skipping damaged file > on > > volume D00007L6: Node PPSDAT1V_ORA, Type Backup, > File > > space /oracledb, fsId 2, File name > > //pps_db<pps_34349706144541>.dbf. (SESSION: > 1804482, > > PROCESS: 2024) > > Could you help us with that problem? > > Should we try a different type of tape device emulation. (Do you have > preffered one?) > > > Thanks for reply. > > > Milan. > > > > -- > You received this message because you are subscribed to the Google Groups > "QUADStor VTL" group. > To unsubscribe from this group and stop receiving emails from it, send an > email to [email protected]. > For more options, visit https://groups.google.com/d/optout. -- You received this message because you are subscribed to the Google Groups "QUADStor VTL" group. To unsubscribe from this group and stop receiving emails from it, send an email to [email protected]. For more options, visit https://groups.google.com/d/optout.
