arcserve 11.5 dds4 problem

[vandeplas]

I have a sbs server 2003sp1 standard.
The server is a HP ML150 with a
HP DDS4 Tape Drive C5685A Drive.

I'm curently using acrserve 11.5 to backup my server.
When i backup my server on the tape drive.
the backup starts to run and copy's files to the tape drive. this goes good. But when i use compare backup meda to disk the backup starts to run but at the moment when the backup is completed and the drive is going to compare im getting the following error.

unable to find media ID=8A58 seq=459 w3823

The tape is still in the tape drive.
NT backup works perfectly ( i used this to test te drive )

 

[vschumpy]

NT Backup works - you have drivers loaded then - disable the drivers and try again.

Also make sure you don't have the option for eject media after backup set. Check the tape.log for any related errors around the time too.

 

[vandeplas]

i used nt backup to check te drive if it runs correctly.
when i use arcserve the driver is disabled.
i don't use eject media after backup the tape remaint inside the tape drive.

But i still get the error and its the only error.

sorry for my english i normally speak dutch

 

[vschumpy]

ok - what is shown in the tape.log and activity log when this problem occurs?

 

[Cyklops]

Also do you use disk staging with version 11.5 and did you apply the available Device Fix ??

regards

 

[vandeplas]

Thanks for the support.
The device fix is installed.
and i do not use staging.

tape log:

Information 07-11-2005 09:42:48 4 *** Backup Summary for Job ID 4 ***
Information 07-11-2005 09:42:11 4 7 Target Directory: C:\Program Files\CA\BrightStor ARCserve Backup\DATABASE
Information 07-11-2005 09:41:58 4 7 Source Session 7 on Media TAPETEX TAKE2
Information 07-11-2005 09:41:58 4 7 Use media TAPETEX TAKE2, ID 122A, sequence #1
Information 07-11-2005 09:40:42 4 Mount media request cancelled by user or by default timeout.
Information 07-11-2005 09:35:57 4 7 [CAT] TAPETEX TAKE2 [ID:122A,SESSION:7] is merged.(files=1178)
Information 07-11-2005 09:35:57 4 6 [CAT] TAPETEX TAKE2 [ID:122A,SESSION:6] is merged.(files=14)
Information 07-11-2005 09:35:57 4 5 [CAT] TAPETEX TAKE2 [ID:122A,SESSION:5] is merged.(files=25)
Information 07-11-2005 09:35:57 4 4 [CAT] TAPETEX TAKE2 [ID:122A,SESSION:4] is merged.(files=2861)
Information 07-11-2005 09:35:51 4 3 [CAT] TAPETEX TAKE2 [ID:122A,SESSION:3] is merged.(files=5)
Information 07-11-2005 09:35:51 4 2 [CAT] TAPETEX TAKE2 [ID:122A,SESSION:2] is merged.(files=12897)
Information 07-11-2005 09:35:50 4 1 [CAT] TAPETEX TAKE2 [ID:122A,SESSION:1] is merged.(files=23765)
W3823 07-11-2005 09:35:42 4 Unable to find media. (MEDIA=TAPETEX TAKE2, ID=122a, SEQ=459)
Information 07-11-2005 09:35:42 4 Description: backup tapetex.local.
Information 07-11-2005 09:35:42 4 Start Compare Operation. (QUEUE=1, JOB=2)
Information 07-11-2005 09:35:42 4 2. Blank Media
Information 07-11-2005 09:35:42 4 1. TAPETEX TAKE2
Information 07-11-2005 09:35:42 4 The following media can be used in device group GROUP0 for next job on date 07-11-05
Information 07-11-2005 09:35:42 4 Creating DRIF DB on C:\Program Files\CA\BrightStor ARCserve Backup\DR\TAPETEXDC1
Information 07-11-2005 09:35:41 4 Average Throughput: 440,00 MB/min
Information 07-11-2005 09:35:41 4 Elapsed Time: 3s
Information 07-11-2005 09:35:41 4 22,00 MB Written to Media.
Information 07-11-2005 09:35:41 4 1 Directories 1.178 File(s) (18,44 MB) Backed Up to Media.
Information 07-11-2005 09:35:41 4 1 Session(s).

 

[vschumpy]

For what it's worth - that isn't the tape.log that is a cut and paste of the activity log from the GUI.

This however is wierd:

Unable to find media. (MEDIA=TAPETEX TAKE2, ID=122a, SEQ=459)

It would imply that you have 459 sequences in this logical tape - so, unless you have been appending forever this might indicate the problem, but without detailed analysis it is difficult to say what the exact nature of the problem is.

 

[vandeplas]

i haven't respond anymore to this post because the problem went away for unknown reasons.
now the error is backup again, this time the job was corrupt. After i made a new job the compare operation goes bad again. ik have tried new tapes, new jobs, smaller jobs, different verfication methods but the error remains.

This is the tape.log i don't know anything about stuck in countone queue maybe this is the problem?

2006/02/06 17:04:07 [0b9c] DaemonSuspend: Stuck in CountOneQueue(FREE)
2006/02/06 17:04:07 [0b9c] DaemonSuspend: Stuck in CountOneQueue(FREE)
2006/02/06 17:04:07 [0b9c] DaemonSuspend: Stuck in CountOneQueue(FREE)
2006/02/06 17:04:07 [0b9c] DaemonSuspend: Stuck in CountOneQueue(FREE)
2006/02/06 17:04:07 [0b9c] DaemonSuspend: Stuck in CountOneQueue(FREE)
2006/02/06 17:04:07 [0b9c] DaemonSuspend: Stuck in CountOneQueue(FREE)
2006/02/06 17:04:07 [0b9c] Call FreeSharedMemory(jobid=185,dcb=1,sesid=0)...
2006/02/06 17:04:07 [0b9c] FreeSharedMemory(): Release share memory successfully
2006/02/06 17:04:07 [0b9c] ClientEndSession: LDN:1 Verify Block Positon is not at ZERO.
2006/02/06 17:04:07 [0b9c] =>ABSL:2030 [READ POSITION ] 34 00 00 00 00 00 00 00 00 00 tt[6]
2006/02/06 17:04:07 [0b9c] DRV:1 Current block #: [00079bd5] [498645]
2006/02/06 17:04:07 [0b9c] =>ABSL:2030 [WRITE FILE MARK ] 10 00 00 00 01 00 00 00 00 00 tt[20]
2006/02/06 17:04:09 [0b9c] LDN:1 Device does not support TapeAlert
2006/02/06 17:04:09 [14bc] DRV:1 Tape Capacity NOT SUPPORTED BY DRIVE
2006/02/06 17:04:09 [11d4] DRV:1 ClientGetCompressionRatio: NOT SUPPORTED BY DRIVE
2006/02/06 17:04:09 [0b9c] GetGCBHandleFromGroupName(): GroupName [GROUP1]
2006/02/06 17:04:09 [0b9c] ...in DisConnectFromTape for JobID[185]
2006/02/06 17:04:09 [0b9c] DRV:[1] DisConnectFromTape leaveTapeAtEnd[1]
2006/02/06 17:04:09 [0b9c] =>ABSL:2030 [LOG SENSE ] 4d 00 42 00 00 00 00 00 40 00 tt[5]
2006/02/06 17:04:09 [0b9c] Getting Log Sense Recovered write errors.
2006/02/06 17:04:09 [0b9c] DRV:1 [HP C5683A C305] recovered [0] error for [writing.].
2006/02/06 17:04:09 [0b9c] The current drive usage time is 00:30:21
2006/02/06 17:04:09 [0b9c] Drive[1] Usage Time for this job 00001821
2006/02/06 17:04:09 [0b9c] DB: DBUpdateTape: Tapename[MAANDAG]
2006/02/06 17:04:09 [0b9c] DB: Updating tape info in database.
2006/02/06 17:04:09 [0b9c] DB: Updating tapeinfo in database[0014B9D0]: START
2006/02/06 17:04:09 [0b9c] DB: BABTapeDB Semaphore [280] Locking...
2006/02/06 17:04:09 [0b9c] DB: BABTapeDB Semaphore [280] LOCKED!
2006/02/06 17:04:09 [0b9c] DB: IMPERSONATE
2006/02/06 17:04:09 [0b9c] DB: BABTapeDB Semaphore [280] Releasing
2006/02/06 17:04:09 [0b9c] DB: Finished Updating tapeinfo in database: END
2006/02/06 17:04:09 [0b9c] DB: REVERT

 

[vschumpy]

Don't see anything in particular in the log that indicates any error/failure.

 

[vandeplas]

unable to find media ID=8A58 seq=459 w3823
this is the error message in arcserve, it must be stuck somewhere but i don't know were it gets stuck

 

[davidmichel]

seq=459 = sequence # 495 in other words the job is now asking for the 495th tape in the backup set.

Interesting that before an now it is asking for the same seq. #.

Nothing wrong in the above log but the end job process had already started before 2006/02/06 17:04:07.

Regardless I see this as a problem in Task or the Database and not in the Tape Engine. The Tape Engine is probably reporting back correctly that the seq. # 1 tape is loaded and Task is rejecting it and cancleing the job because it wants seq. # 495.

So the question is why is Task asking for seq. # 495.

Recommendation:
install ARCserve on another system to get a blank database.
Stop all ARCserve services close the manager and Move the production database to a temp location. Just move the whole Database directory.
Copy the new blank directory over.
Bring up ARCserve and run your job, or a few test jobs.

If the problem no longer happens safe to say it is related to a database problem. At that point you can either leave the new database in place or put back the old one and repair it.

 

[vandeplas]

i have called CA for support.
And they have been helping me for about 10 hours right now.
still with no solution, they say the databases are in good condition.
yet everytime is asks for seq # 495.

When running in debug mode.
i got some extra stuff from the log.

Cannot compare DBAgent session

Each time i runn a CRC check on the system state of on exchange it will give this error.

I have checked the permissions with CA and they say that it has been correctly applied.

this is from the brightstor log.

[02/10/2006-16:13:31 ,1,212,0,0,-1,2,18,0,0] Description: testjob47.
[02/10/2006-16:13:31 ,1,212,0,0,-1,2,18,0,0] Perform Operation for User. (USER=administrator).
[02/10/2006-16:13:31 ,1,212,0,0,-1,2,18,0,0] Checking With CRC Value
[02/10/2006-16:13:31 ,1,212,0,0,-1,2,2,0,0] W3823 Unable to find media. (MEDIA=10-02-06 12:25, ID=abc0, SEQ=459)
[02/10/2006-16:13:33 ,1,0,0,0,-1,2,18,0,0] [CAT] Start Merge Catalog Operation.
[02/10/2006-16:13:37 ,1,212,1,0,-1,2,18,0,0] [CAT] 10-02-06 12:25 [ID:ABC0,SESSION:1] is merged.(files=27022)
[02/10/2006-16:13:40 ,1,212,2,0,-1,2,18,0,0] [CAT] 10-02-06 12:25 [ID:ABC0,SESSION:2] is merged.(files=18130)
[02/10/2006-16:13:40 ,1,212,3,0,-1,2,18,0,0] [CAT] 10-02-06 12:25 [ID:ABC0,SESSION:3] is merged.(files=6)
[02/10/2006-16:13:48 ,1,212,4,0,-1,2,18,0,0] [CAT] 10-02-06 12:25 [ID:ABC0,SESSION:4] is merged.(files=2880)
[02/10/2006-16:13:48 ,1,212,5,0,-1,2,18,0,0] [CAT] 10-02-06 12:25 [ID:ABC0,SESSION:5] is merged.(files=26)
[02/10/2006-16:13:48 ,1,212,6,0,-1,2,18,0,0] [CAT] 10-02-06 12:25 [ID:ABC0,SESSION:6] is merged.(files=136)
[02/10/2006-16:13:48 ,1,212,7,0,-1,2,18,0,0] [CAT] 10-02-06 12:25 [ID:ABC0,SESSION:7] is merged.(files=1184)
[02/10/2006-16:13:48 ,1,0,0,0,-1,2,18,0,0] [CAT] Merge Catalog Operation Successful.
[02/10/2006-16:18:31 ,1,212,0,0,-1,2,18,0,0] Mount media request cancelled by user or by default timeout.
[02/10/2006-16:18:31 ,1,212,0,0,-1,2,18,0,0] Cannot Compare DBAgent Session
[02/10/2006-16:19:44 ,1,212,7,0,-1,2,18,0,0] Use media 10-02-06 12:25, ID ABC0, sequence #1
[02/10/2006-16:19:44 ,1,212,7,0,-1,2,18,0,0] Source Session 7 on Media 10-02-06 12:25
[02/10/2006-16:19:57 ,1,212,7,0,-1,2,18,0,0] File: CRC: tape:0, calculation:0
[02/10/2006-16:19:57 ,1,212,7,0,-1,2,18,0,0] Target Directory: C:\Program Files\CA\BrightStor ARCserve Backup\DATABASE

right now i have no idea where to look anymore.
could this be a client witch hangs?

 

[davidmichel]

Did they have you try replacing the database and reproducing the problem? If not i wonder how they can be so sure it is not related to the database.

Regardless, lets play what if. So what if they are right, well then they (this level of support) can not help you and they need to escalate the issue to a higher level.

 

[vandeplas]

no they have not yet replaced the database.
i wonder if they now what they are doing

but i wil replace the database and see what happens

 

[andyhqr]

Am trialling v11.5 on a Dell with PV-110T LTO2 drive. Since upgrading from 11.1, also get W3823 Unable to ... but my Verify SEQ is always 469 (not 459)!
Have used various tapes and swapped the Drive, but always the same. I did NOT try v11.5(raw), started with v11.5 plus the 5 updates 74774, 75196, 75197, 76166, 76448.
My server was an exact copy (DR) of a live v11.1 server and the existing/cloned backup jobs also fail, as does a 'Run Now'.
Have raised with ArcServe, but no result so far.
Any ideas?