Cannot expire some tapes

[tecnico_infra]

Hello,

My master server is Netbackup 7.1.0.3 and runs on Windows Server 2008 R2

I need to expire some tapes but the command doesn't answer, it stays the way I attach forever. I've seen in some forums that this could occur when a image in the tape has a pending duplication, but this is not the case as this tape is the last destination of my duplications. Besides, I have the same problem with more tapes in the same destination.

Any idea?

Thanks in advance,

Ana

[revarooo]

What is logged in the admin log?

[tecnico_infra]

Hello,

The admin log:

16:49:54.620 [2584.7376] <2> bpexpdate: VERBOSE = 0
16:49:54.620 [2584.7376] <2> bpexpdate: INITIATING: NetBackup 7.1 created: 2011020314
16:49:54.620 [2584.7376] <2> logparams: -m px0469 -d 0 -force
16:49:54.620 [2584.7376] <2> vnet_same_host: ../../libvlibs/vnet_addrinfo.c.2928: 0: name2 is empty: 0 0x00000000
16:49:54.620 [2584.7376] <2> copy_preferred_network_list: ../../libvlibs/nbconf.c.1687: pseudo PN for : sm00210.int.clh.es
16:49:54.620 [2584.7376] <4> bpexpdate: emmserver_name = smbak00
16:49:54.620 [2584.7376] <4> bpexpdate: emmserver_port = 1556
16:49:54.635 [2584.7376] <2> copy_preferred_network_list: ../../libvlibs/nbconf.c.1687: pseudo PN for : sm00210.int.clh.es
16:49:54.635 [2584.7376] <2> Orb::init: initializing ORB EMMlib_Orb with: dbstunitq -ORBSvcConfDirective "-ORBDottedDecimalAddresses 0" -ORBSvcConfDirective "static PBXIOP_Factory '-enable_keepalive'" -ORBSvcConfDirective "static EndpointSelectorFactory ''" -ORBSvcConfDirective "static Resource_Factory '-ORBProtocolFactory PBXIOP_Factory'" -ORBSvcConfDirective "static Resource_Factory '-ORBProtocolFactory IIOP_Factory'" -ORBDefaultInitRef '' -ORBSvcConfDirective "static PBXIOP_Evaluator_Factory '-orb EMMlib_Orb'" -ORBSvcConfDirective "static Resource_Factory '-ORBConnectionCacheMax 1024 '" -ORBSvcConf nul -ORBSvcConfDirective "static Server_Strategy_Factory '-ORBMaxRecvGIOPPayloadSize 268435456'"(../Orb.cpp:823)
16:49:54.635 [2584.7376] <2> Orb::init: caching EndpointSelectorFactory(../Orb.cpp:838)
16:49:54.635 [2584.7376] <2> Orb::setOrbConnectTimeout: timeout seconds: 60(../Orb.cpp:1478)
16:49:54.635 [2584.7376] <2> Orb::setOrbRequestTimeout: timeout seconds: 1800(../Orb.cpp:1487)
16:49:54.651 [2584.7376] <2> ConnectionCache::connectAndCache: Acquiring new connection for host smbak00, query type 260
16:49:54.651 [2584.7376] <2> logconnections: BPDBM CONNECT FROM 10.194.1.127.60543 TO 10.194.1.129.13721 fd = 908
16:49:54.713 [2584.7376] <2> db_end: Need to collect reply
16:49:54.729 [2584.7376] <2> ConnectionCache::connectAndCache: Acquiring new connection for host smbak00, query type 87
16:49:54.745 [2584.7376] <2> logconnections: BPDBM CONNECT FROM 10.194.1.127.60555 TO 10.194.1.129.13721 fd = 908
16:49:54.791 [2584.7376] <2> db_end: Need to collect reply
16:49:55.213 [16888.14568] <2> bpduplicate: Received keep alive
16:50:00.532 [15636.16964] <2> bpduplicate: Received keep alive

[revarooo]

Hmm might need the full admin log and bpdbm log.

[Marianne]

Please show us output of:

nbemmcmd -listmedia -mediaid PX0469

[tecnico_infra]

Hello,

Finally the comand terminated 2 hours later with invalid command parameter:

C:\Program Files\Veritas\NetBackup\bin\admincmd>bpexpdate -m px0469 -d 0 -force
invalid command parameter

In the admin log:

18:36:24.520 [2584.7376] <2> db_end: no DONE from db_getreply(): invalid command parameter
18:36:24.520 [2584.7376] <16> bpexpdate: db_IMAGE() failed: invalid command parameter (20)
18:36:24.520 [2584.7376] <16> bpexpdate: invalid command parameter
18:36:24.520 [2584.7376] <2> bpexpdate: EXIT status = 20

In bpdbm log:

16:48:24.031 [9492.14572] <2> logconnections: BPDBM ACCEPT FROM 10.194.1.127.59859 TO 10.194.1.129.13721 fd = 760
16:48:24.031 [9492.14572] <2> process_request: request complete: exit status 0  ; query type: 98
16:49:54.713 [15856.6660] <2> logconnections: BPDBM ACCEPT FROM 10.194.1.127.60543 TO 10.194.1.129.13721 fd = 808
16:49:54.713 [15856.6660] <2> process_request: request complete: exit status 0  ; query type: 260
16:49:54.791 [16352.7936] <2> logconnections: BPDBM ACCEPT FROM 10.194.1.127.60555 TO 10.194.1.129.13721 fd = 808
16:49:54.791 [16352.7936] <2> image_db: Q_IMAGE_CHGEXP
16:49:54.823 [16352.7936] <4> expdate_by_media_id: changing media PX0469 to expiration date      1/1/1970 1:00:00 AM (0)
16:49:54.823 [16352.7936] <2> copy_preferred_network_list: ../../libvlibs/nbconf.c.1687: pseudo PN for : sm00210.int.clh.es
16:49:54.854 [16352.7936] <2> copy_preferred_network_list: ../../libvlibs/nbconf.c.1687: pseudo PN for : sm00210.int.clh.es
16:49:54.854 [16352.7936] <2> Orb::init: initializing ORB EMMlib_Orb with: connect_bpdbm_to_emm -ORBSvcConfDirective "-ORBDottedDecimalAddresses 0" -ORBSvcConfDirective "static PBXIOP_Factory '-enable_keepalive'" -ORBSvcConfDirective "static EndpointSelectorFactory ''" -ORBSvcConfDirective "static Resource_Factory '-ORBProtocolFactory PBXIOP_Factory'" -ORBSvcConfDirective "static Resource_Factory '-ORBProtocolFactory IIOP_Factory'" -ORBDefaultInitRef '' -ORBSvcConfDirective "static PBXIOP_Evaluator_Factory '-orb EMMlib_Orb'" -ORBSvcConfDirective "static Resource_Factory '-ORBConnectionCacheMax 1024 '" -ORBSvcConf nul -ORBSvcConfDirective "static Server_Strategy_Factory '-ORBMaxRecvGIOPPayloadSize 268435456'"(../Orb.cpp:823)
16:49:54.854 [16352.7936] <2> Orb::init: caching EndpointSelectorFactory(../Orb.cpp:838)
16:49:54.854 [16352.7936] <2> Orb::setOrbConnectTimeout: timeout seconds: 60(../Orb.cpp:1478)
16:49:54.854 [16352.7936] <2> Orb::setOrbRequestTimeout: timeout seconds: 1800(../Orb.cpp:1487)
16:49:54.854 [16352.7936] <4> connect_bpdbm_to_emm: succesfully initialized EMM interface
16:52:09.809 [11912.15824] <2> vnet_pbxAcceptSocket: Accepted sock[760] from 10.194.1.130:38282

.......

18:36:01.604 [17076.12500] <16> change_expiration_date: (-) Translating EMM_ERROR_FragmentsStillExist(2020003) to 20 in the NetBackup context
18:36:01.604 [17076.12500] <16> change_expiration_date: emmlib_MediaDBOp() failed: 20
18:36:01.604 [17076.12500] <16> change_expiration_date: unable to change expiration date for media ID EQY782
18:36:01.619 [17076.12500] <16> expdate_by_media_id: unable to change expiration date for media ID EQY782; EMM failure: invalid command parameter (20)
18:36:01.635 [17076.12500] <2> put_string: cannot write data to network:  An existing connection was forcibly closed by the remote host.
18:36:01.635 [17076.12500] <2> db_senddata: put_string(): network write error, An existing connection was forcibly closed by the remote host. , (10054)
18:36:01.635 [17076.12500] <2> db_sendSTATUS: db_senddata() failed: network write failed, (44)
18:36:01.635 [17076.12500] <2> process_request: request complete: exit status 20 invalid command parameter; query type: 87
18:36:08.249 [16352.7936] <8> rollbackTransaction: Rolled back the transaction
18:36:24.489 [16352.7936] <16> change_expiration_date: (-) Translating EMM_ERROR_FragmentsStillExist(2020003) to 20 in the NetBackup context
18:36:24.489 [16352.7936] <16> change_expiration_date: emmlib_MediaDBOp() failed: 20
18:36:24.489 [16352.7936] <16> change_expiration_date: unable to change expiration date for media ID PX0469
18:36:24.505 [16352.7936] <16> expdate_by_media_id: unable to change expiration date for media ID PX0469; EMM failure: invalid command parameter (20)
18:36:24.520 [16352.7936] <2> process_request: request complete: exit status 20 invalid command parameter; query type: 87
18:36:24.551 [13772.16616] <8> rollbackTransaction: Rolled back the transaction
18:36:25.222 [13772.16616] <16> change_expiration_date: (-) Translating EMM_ERROR_FragmentsStillExist(2020003) to 20 in the NetBackup context
18:36:25.222 [13772.16616] <16> change_expiration_date: emmlib_MediaDBOp() failed: 20
18:36:25.222 [13772.16616] <16> change_expiration_date: unable to change expiration date for media ID PX0469
18:36:25.238 [13772.16616] <16> expdate_by_media_id: unable to change expiration date for media ID PX0469; EMM failure: invalid command parameter (20)
18:36:25.253 [13772.16616] <2> put_string: cannot write data to network:  An existing connection was forcibly closed by the remote host.
18:36:25.253 [13772.16616] <2> db_senddata: put_string(): network write error, An existing connection was forcibly closed by the remote host. , (10054)
18:36:25.253 [13772.16616] <2> db_sendSTATUS: db_senddata() failed: network write failed, (44)
18:36:25.253 [13772.16616] <2> process_request: request complete: exit status 20 invalid command parameter; query type: 87

If you need the complete log, I'll try to upload it, but admin log has 150MB.

The output of nbemmcmd -listmedia -mediaid PX0469:

C:\Program Files\Veritas\NetBackup\bin\admincmd>nbemmcmd -listmedia -mediaid PX0469
NBEMMCMD, Version:7.1
====================================================================
Media GUID:                     142a36cd-4243-4b2b-a637-cef64b2a4f04
Media ID:                       PX0469
Partner:                        -
Media Type:                     HCART2
Volume Group:                   001_00000_TLD
Application:                    Netbackup
Media Flags:                    1
Description:                    Added by Media Manager
Barcode:                        PX0469
Partner Barcode:                --------
Last Write Host:                smbak04
Created:                        01/10/2013 11:13
Time Assigned:                  01/11/2013 23:09
First Mount:                    01/11/2013 23:46
Last Mount:                     01/11/2013 23:46
Volume Expiration:              -
Data Expiration:                01/03/2014 02:00
Last Written:                   01/12/2013 04:41
Last Read:                      -
Robot Type:                     TLD
Robot Control Host:             smbak04
Robot Number:                   0
Slot:                           17
Side/Face:                      -
Cleanings Remaining:            -
Number of Mounts:               1
Maximum Mounts Allowed:         0
Media Status:                   FULL MULTI-RETLEV
Kilobytes:                      830881442
Images:                         9
Valid Images:                   4
Retention Period:               8
Number of Restores:             0
Optical Header Size Bytes:      1024
Optical Sector Size Bytes:      0
Optical Partition Size Bytes:   0
Last Header Offset:             10565731
Adamm Guid:                     00000000-0000-0000-0000-000000000000
Rsm Guid:                       00000000-0000-0000-0000-000000000000
Origin Host:                    NONE
Master Host:                    smbak00
Server Group:                   NO_SHARING_GROUP
Upgrade Conflicts Flag:
Pool Number:                    26
Volume Pool:                    VAULTING_TORREJON
Previous Pool Name:             CintasLibres
Vault Flags:                    -
Vault Container:                -
Vault Name:                     -
Vault Slot:                     -
Session ID:                     -
Date Vaulted:                   -
Return Date:                    -
====================================================================
Command completed successfully.

Thanks again,

Ana

[revarooo · Accepted solution]

Take a look at this technote:

http://www.symantec.com/business/support/index?page=content&id=TECH156081

[tecnico_infra]

Hello,

C:\Program Files\Veritas\NetBackup\bin\admincmd>nbstlutil list -U -L -mediaid PX0469
V7.0.1 I smbak00 sm00146_1357174854 sm00146 1357174854 WIN_SM00146_DATOS_I 29 0
SLP_2M_1Y_C 2 1357264692 *NULL* 2  00000000-0000-0000-0000-000000000000 0 0 1357
257893
V7.0.1 C smbak00 sm00146_1357174854 4 1388710854 1388710854 smbak04-hcart2-robot
-tld-0 3 482493 0 0 2 *NULL* 1388710854 1357997786
V7.0.1 F smbak00 sm00146_1357174854 4 1 0 PX0469 smbak04 smbak04 2 1 1 158388322
304 1 PX0469

C:\Program Files\Veritas\NetBackup\bin\admincmd>nbstlutil cancel -backupid sm00146_1357174854

C:\Program Files\Veritas\NetBackup\bin\admincmd>nbstlutil list -U -L -mediaid PX0469

C:\Program Files\Veritas\NetBackup\bin\admincmd>bpexpdate -m px0469 -d 0 -force

After 107 min, the tape is expired. Yesterday the error appeared after 107 min too.  I don't understand why it takes so long. The performance of master and media server is normal. Any idea?

Thanks again,

Ana

[Mark_Solutions]

There are many things that can have an affect on performance and commands

I do see that the tape belonged to pool number 26

How many volume pools do you have?

This can affect things, but then so can Anti Virus, DNS etc

The Master is smbak00 and the media server is smbak04 - where did you run this command from and does it run quicker if you specify the media owner (I assume it is owned as it is in a "NO_SHARING_GROUP"

As the tape is in the library you shoudln't really need the -force option so try this, running it from the Master itself:

bpexpdate -m ABC123 -d 0 -host smbak04

[tecnico_infra]

Hello again,

We have 21 pools. I run all the commands from master server smbak00. I've tried what you said:

C:\Program Files\Veritas\NetBackup\bin\admincmd>nbstlutil list -U -L -mediaid PW9897

C:\Program Files\Veritas\NetBackup\bin\admincmd>bpexpdate -d 05/27/2014 06:38:14 -m PW9897 -host smbak04
Are you SURE you want to change PW9897
to expire on     5/27/2014 6:38:14 AM y/n (n)? y

and the command has not answered yet after more than two hours.

Otherwise, I've been able to expire another tape quickly. I think that it depends on the tape. This one selecting the robot where it is:

PW9897 PW9897 5/25/2023 9:47:50 AM 872693885 26 18 8 Full Multi-Retlev HCART2 TLD   0 smbak04  39 001_00000_TLD VAULTING_TORREJON  10 5/26/2013 9:09:54 PM  - NetBackup   -

i.e.                      Data Expiration: 5/25/2023 9:47:50 AM

                           Images: 26

                           Valid Images: 18

                           Retention Period: 8 (configured as 1 year, not 10)

Running a Tape Contents Report I can see images expiring in 10 years. (attached)

But in Catalog I can't see them.(attached)

The tape I could expire quickly wasn't Multi-Retlev and its retention period was 8 and the images it had expired in 1 year and could be seen in catalog.

I don't undestand it.

Ana
 

[Mark_Solutions]

OK, so just a few images on that tape - although part of one is also on another tape and so that backup id also has to be expired from the other tape

It does look like multi retention level and looking at the outputs one tape can actually have a huge number of backups associated with it and so potentially expiring one tape could expire many tapes - this is beacuse you may have one fragement of an image on the tape but other fragements reside on other tapes

When you say expire this tape it expires all images associated with that tape - and any fragments of those images that are also on other tapes - the tape contents report shows that up quite well

It may be that report that actually loads thetape and reads it - hence why you see more than in the catalog

Images on media may be of more help but even the catalog does suggest that two tapes are actually involved as the EQY* tape also has to be dealt with

[tecnico_infra]

Hello,

Finally the command terminated successfully after 2 hours and 36 minutes. Too long, isn't it?

What I don't understand is why the tape expires in 10 years when all the images I can see in Catalog and Images On Media Report expire in 1 year. I can only see images expiring in 10 years in Tape Contents Report (which takes the tape and reads everything it has) and why it takes so long to run the command. Is it because it has to expire images in 2 tapes (in this case)?

I've run Images on Tape EQY744 Report and all of them expire in 1 year, though the tape is supposed to expire in 10.

Thank you very much again.

Ana

[revarooo]

Tape expiration and image expiration are completely different things. After 10 years the tape will be unusable but images may have come and gone many many times.

[tecnico_infra]

Hello revaroo,

I didn't mean Tape expiration, I meant "Data Expiration" field in the list of tapes selecting the robot (which is in 2023). The Tape expiration you say is the field "Volume Expiration" and is empty in my case for all of the tapes.

Ana

[tecnico_infra]

Hello,

I finally can expire the data of a tape quickly by expiring the images I see in it in the Catalog and deassigning the tape.

Thank you very much everybody,

Ana