Exch2k3 SP1 brick level restore fails with no error message

[redcrosssun]

I have a serious problem restoring my exch2k3 brick level mailboxes. When I start a restore job, the restore begins, but aftfer 0,06 mb it freezes. I am not able to manualy stop the job, when I try, the status is "stopping" but it stays that way untill I restart the win2k3 backup server. stopping the engines does not help.
It does not matter if I try to restore several mailboxes, a single mailbox or even a single mail folder.

I get the following debug messages:
Job log for stalled exch2k3 brick level restore:


brightstor log:
[09/29/2004-22:35:18 ,1,0,0,0,-1,2,3,0,0] [JOBQUEUE]: Added [Job No: 19] [Description: jal restore debug mode]
[09/29/2004-22:35:28 ,1,0,0,0,-1,2,18,0,0] >> BrightStor ARCserve Backup Job Runner
[09/29/2004-22:35:28 ,1,0,0,0,-1,2,18,0,0] >> BrightStor ARCserve Backup
[09/29/2004-22:35:28 ,1,0,0,0,-1,2,18,0,0] >> Version 11.0
[09/29/2004-22:35:28 ,1,0,0,0,-1,2,18,0,0] >> Release 042902
[09/29/2004-22:35:28 ,1,0,0,0,-1,2,18,0,0] >> Build 2672
[09/29/2004-22:35:28 ,1,0,0,0,-1,2,18,0,0] >>
[09/29/2004-22:35:28 ,1,0,0,0,-1,2,18,0,0] Single Processor system, SetProcessAffinityMask is not called.

[09/29/2004-22:35:28 ,1,778,0,0,-1,2,18,0,0] Run Restore Job Now.
[09/29/2004-22:35:28 ,1,778,0,0,-1,2,18,0,0] Japanese? 0406
[09/29/2004-22:35:28 ,1,778,0,0,-1,2,18,0,0] Find group name: RAIDE
[09/29/2004-22:35:28 ,1,778,0,0,-1,2,18,0,0] Start Restore Operation. (QUEUE=1, JOB=19)
[09/29/2004-22:35:28 ,1,778,0,0,-1,2,18,0,0] Description: jal restore debug mode.
[09/29/2004-22:35:28 ,1,778,0,0,-1,2,18,0,0] Perform Operation for User. (USER=Administrator).
[09/29/2004-22:35:28 ,1,778,0,0,-1,2,18,0,0] Backup/restore privilege enabled.
[09/29/2004-22:35:28 ,1,778,0,0,-1,2,18,0,0] Called AsLogRegisterLogFile to create job log file <E:\Program Files\CA\BrightStor ARCserve Backup\LOG\cas_user_logs\caroot\J0000778.LOG>
[09/29/2004-22:37:15 ,1,778,1,0,-1,2,18,0,0] Use media M-TAPE-FRI-27-08-04, serial # 000056, ID A66C, sequence #1
[09/29/2004-22:37:16 ,1,778,1,0,-1,2,18,0,0] Source Session 1 on Media M-TAPE-FRI-27-08-04 Serial # 000056
[09/29/2004-22:37:16 ,1,778,1,0,-1,2,18,0,0] Target Directory: \\SOLFERINO\dbaxchg2
[09/29/2004-22:38:40 ,1,778,1,0,-1,2,18,0,0] Next media M-TAPE-FRI-27-08-04, serial # 000057, ID A66C, sequence #2
[09/29/2004-22:41:21 ,1,778,1,0,-1,2,18,0,0] Resume Restore Operation.

TskJob19.log:
20040929 223528 00 TSIF TSI Funcs TSICreateTSIHandle

20040929 223528 00 TSIF TSI Funcs calling TASK_TSIMUXSendJobToken

20040929 223528 00 TSIF TSI Funcs calling TSIGetXCB : MUX_BEB_JOB_TAB_6 [job token = 0x1840b5b]

20040929 223528 00 TSIF TSI Funcs exit TASK_TSIMUXSendJobToken [0]

20040929 223528 00 TSIF TSI Funcs TSIFindGroupOpen

20040929 223528 00 TSIF TSI Funcs TSIFindGroupClose

20040929 223528 00 TSIF TSI Funcs TSIConnectToGroup Name:RAIDE Mode:2

20040929 223528 00 Misc Report Report job description: Comments [jal restore debug mode], Owner [caroot], Job ID [778], WriteToJobLog [0]

20040929 223528 00 Misc Report AsLogGetJobLogPath returns job log name [E:\Program Files\CA\BrightStor ARCserve Backup\LOG\J0000778.LOG]

20040929 223528 00 Misc Report Job log path [E:\Program Files\CA\BrightStor ARCserve Backup\LOG\cas_user_logs\caroot\J0000778.LOG]

20040929 223528 00 TSIF TSI Funcs TSIEnumTapeName Asking For SelFlag:7,State:1,iTapeName:M-TAPE-FRI-27-08-04,iRandID:42604,iSeq:1,iSerialNo:

20040929 223528 00 TSIF TSI Funcs TSIEnumTapeName returns (rc=0) with oTapeName:M-TAPE-FRI-27-08-04,oRandID:42604,oSeq:1,oSerialNo:000056

20040929 223714 00 TSIF TSI Funcs TSIConnectToTapeEx flags:7 tapeFlags: 301991938,ulMode:2 DeviceNumber:4 ret:0

20040929 223714 00 TSIF TSI Funcs TSIReadTapeHeader

20040929 223714 00 TSIF TSI Funcs TSIGotoSession ulSession:1

20040929 223716 00 TSIF TSI Funcs calling TASK_TSIMUXGetBufferSize

20040929 223716 00 TSIF TSI Funcs calling TSIGetXCB : MUX_BEB_JOB_TAG_4

20040929 223716 00 TSIF TSI Funcs TSIGetXCB : MUX_BEB_JOB_TAG_4 returns chunk # 0

20040929 223716 00 TSIF TSI Funcs exit TASK_TSIMUXGetBufferSize [0]

20040929 223716 00 TSIF TSI Funcs TSIStartSession jobFlag:2 tapeSessionID: 0

20040929 223716 00 TSIF TSI Funcs TSIQFALocate

20040929 223828 00 TSIF TSI Funcs TSIDisConnectFromTape

20040929 223840 00 TSIF TSI Funcs TSIEnumTapeName Asking For SelFlag:7,State:1,iTapeName:M-TAPE-FRI-27-08-04,iRandID:42604,iSeq:2,iSerialNo:

20040929 223840 00 TSIF TSI Funcs TSIEnumTapeName returns (rc=0) with oTapeName:M-TAPE-FRI-27-08-04,oRandID:42604,oSeq:2,oSerialNo:000057

20040929 224119 00 TSIF TSI Funcs TSIConnectToTapeEx flags:7 tapeFlags: 268437506,ulMode:2 DeviceNumber:4 ret:0

20040929 224119 00 TSIF TSI Funcs TSIReadTapeHeader

20040929 224119 00 TSIF TSI Funcs TSIContinueSession

20040929 224121 00 TSIF TSI Funcs TSIQFALocate


Tape.log:
09/29 22:35:18 [0860] usJobID = [5000], muxId = 0, jobToken = 0
ClientReserveGroup:: Reserving a GROUP = RAIDE. Reserved Drives:1 Free Drives:1
09/29 22:35:18 [0860] usJobID = [5000], muxId = 0, jobToken = 0
ClientReserveGroup:: GROUP RESERVED. nReservedDrives = 1, nFreeDrives = 1
09/29 22:35:18 [0860] usJobID = [5000], muxId = 0, jobToken = 0
ClientReserveGroup:: nReservedDrives = 1, nFreeDrives = 1
09/29 22:35:28 [085c] usJobID = [778], muxId = 0, jobToken = 25430875
ClientConnectToTape:: Decremented reserved drives. nReservedDrives = 0, nFreeDrives = 0
09/29 22:35:28 [085c] =>ABSL:4110 Command:[LOAD ] <Drive>
09/29 22:35:28 [085c] ABSL:4110 Sense Key status: Not Ready [02]
09/29 22:35:28 [085c] ABSL:4110 Additional sense: Medium Not Present [3a, 00]
09/29 22:37:14 [085c] usJobID = [778], muxId = 0, jobToken = 25430875, dcb = 4
ClientConnectToTape:: usSlotNo = 6, currentDrive = 4, nReservedDrives = 0, nFreeDrives = 0
09/29 22:37:16 [06d8] DRV:4 WriteShots:4
09/29 22:38:28 [0860] SpaceForwardsync : Req [114664960], Spaced [95171584]
09/29 22:38:28 [0860] SpaceForwardsync : Req [114664960], Spaced [95171584]
09/29 22:41:19 [0860] usJobID = [778], muxId = 0, jobToken = 25430875, dcb = 4
ClientConnectToTape:: usSlotNo = 7, currentDrive = 4, nReservedDrives = 0, nFreeDrives = 0
09/29 22:43:20 [06d8] SpaceForwardsync : Req [19492480], Spaced [19492480]

 

[redcrosssun]

P.S. I am running Brightstor ARCserve 11

 

[ACiDelic]

BAB r11 comes with a very detailed troubleshooting section in the Agent Guide. You should review the information in the guide to make sure that you are using the agent correctly and that you have everything configured appropriately.