Jump to content
cpragman

8.2 Finishes writing to tape, but won't start verify pass

Recommended Posts

Since upgrading to 8.2, i've noticed that the jobs I have that write to tape (copy backup) finish writing, but then don't start the verify pass. It just sits there, saying needs media, but that tape is in the drive...

 

I increased the logging level, and have attached logs below...

 

+ Retrospect version 8.2.0.399

Launched at 8/3/10 10:31:42 PM

thTop: AddCallbackDispatcherToRunLoop devID 1 [0|3|0], dvIf 0x48f2b560, rlRef 0x46b9f900

thTop: RemoveCallbackDispatcherToRunLoop dvIf 0x46be56e0, rlRef 0x497671a0

devsconCheckIdent:2: create driver after scsiscan for addr 1

devUnsetExec: mismatched release, devRef 0x70a19670, reserveType 0x70a19670

devSetExec: fully released devRef 0x70a19670

thTop: AddCallbackDispatcherToRunLoop devID 1 [0|3|0], dvIf 0x4a1b2570, rlRef 0x49756920

SCSI 0:3:0: 10:31:52 PM Read <1a 00 0f 00 1c 00> [28 bytes]

[28 bytes] > 1b 00 90 08 42 00 00 00 00 01 00 00 8f 0e c0 80 00 00 00 01 00 00 00 01 00 00 00 00

SCSI 0:3:0: 10:31:52 PM Read <1a 00 3c 00 12 00> [18 bytes]

Sense > 70 00 05 00 00 00 00 0e 00 00 00 00 24 00 00 cd 00 02

[18 bytes] > 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00

SCSI 0:3:0: 10:31:52 PM Read <1a 00 3e 00 10 00> [16 bytes]

Sense > 70 00 05 00 00 00 00 0e 00 00 00 00 24 00 00 cd 00 02

[16 bytes] > 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00

SCSI 0:3:0: 10:31:52 PM Read <12 01 83 00 08 00> [8 bytes]

[8 bytes] > 01 83 00 28 02 01 00 24

SCSI 0:3:0: 10:31:52 PM Read <12 01 83 00 2c 00> [44 bytes]

[44 bytes] > 01 83 00 28 02 01 00 24 54 41 4e 44 42 45 52 47 54 53 34 30 30 20 20 20 20 20 20 20 20 20 20 20

Tandberg Ultrium 2 DC, ID 0:3:0 has devIdentifier "TANDBERGTS400 400084600590"

cdrCheckRDI: (HL-DT-ST DVD-RW GH41N)

cdrCheckRDI: (HL-DT-ST DVD-RW GH41N)

devsconCheckIdent:2: create driver after scsiscan for addr 2

DConCheckLdrIdent:1: create driver after scsiscan for addr 2

DConCheckLdrIdent:2: create an inactive refnum for addr 2

devsconDoShowContents:1:log devref 0x4a1aaba0

devsconDoShowContents:log2 devRef 0x48039f10

devsconDoShowContents:log4 devRef 0x48c858a0

DConSetContext: devRef 0x493d79d0

SCSI 0:3:0: 10:31:54 PM Command <00 00 00 00 00 00>

Sense > 70 00 02 00 00 00 00 0e 00 00 00 00 3a 00 00 00 00 00

thTop: RemoveCallbackDispatcherToRunLoop dvIf 0x48cb62d0, rlRef 0x47f19a10

Exit at 8/4/10 5:40:41 AM

+ Retrospect version 8.2.0.399

Launched at 8/4/10 5:41:06 AM

thTop: AddCallbackDispatcherToRunLoop devID 1 [0|3|0], dvIf 0x4a1ed170, rlRef 0x49c6acb0

thTop: RemoveCallbackDispatcherToRunLoop dvIf 0x47f88760, rlRef 0x49c617e0

devsconCheckIdent:2: create driver after scsiscan for addr 1

devUnsetExec: mismatched release, devRef 0x70a19670, reserveType 0x70a19670

devSetExec: fully released devRef 0x70a19670

thTop: AddCallbackDispatcherToRunLoop devID 1 [0|3|0], dvIf 0x4793cde0, rlRef 0x4793ce20

SCSI 0:3:0: 5:41:16 AM Read <1a 00 0f 00 1c 00> [28 bytes]

[28 bytes] > 1b 00 90 08 42 00 00 00 00 01 00 00 8f 0e c0 80 00 00 00 01 00 00 00 01 00 00 00 00

SCSI 0:3:0: 5:41:16 AM Read <1a 00 3c 00 12 00> [18 bytes]

Sense > 70 00 05 00 00 00 00 0e 00 00 00 00 24 00 00 cd 00 02

[18 bytes] > 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00

SCSI 0:3:0: 5:41:16 AM Read <1a 00 3e 00 10 00> [16 bytes]

Sense > 70 00 05 00 00 00 00 0e 00 00 00 00 24 00 00 cd 00 02

[16 bytes] > 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00

SCSI 0:3:0: 5:41:16 AM Read <12 01 83 00 08 00> [8 bytes]

[8 bytes] > 01 83 00 28 02 01 00 24

SCSI 0:3:0: 5:41:16 AM Read <12 01 83 00 2c 00> [44 bytes]

[44 bytes] > 01 83 00 28 02 01 00 24 54 41 4e 44 42 45 52 47 54 53 34 30 30 20 20 20 20 20 20 20 20 20 20 20

Tandberg Ultrium 2 DC, ID 0:3:0 has devIdentifier "TANDBERGTS400 400084600590"

cdrCheckRDI: (HL-DT-ST DVD-RW GH41N)

cdrCheckRDI: (HL-DT-ST DVD-RW GH41N)

devsconCheckIdent:2: create driver after scsiscan for addr 2

DConCheckLdrIdent:1: create driver after scsiscan for addr 2

DConCheckLdrIdent:2: create an inactive refnum for addr 2

devsconDoShowContents:1:log devref 0x4a181480

devsconDoShowContents:log2 devRef 0x47fbcae0

devsconDoShowContents:log4 devRef 0x4a53a3b0

DConSetContext: devRef 0x484ce530

SCSI 0:3:0: 5:41:18 AM Command <00 00 00 00 00 00>

Sense > 70 00 02 00 00 00 00 0e 00 00 00 00 3a 00 00 00 00 00

devUnsetExec: mismatched release, devRef 0x70a19670, reserveType 0x70a19670

devSetExec: fully released devRef 0x70a19670

ddskUpdateVol: use disk space = 1758789107712u, used in catalog = 340476346368u, free on volume = 1511292760064u

devSetExec: fully released devRef 0x70a19670

devUnsetExec: mismatched release, devRef 0x70a19670, reserveType 0x70a19670

devSetExec: fully released devRef 0x70a19670

ddskUpdateVol: use disk space = 1758789107712u, used in catalog = 340597977088u, free on volume = 1511171121152u

devSetExec: fully released devRef 0x70a19670

devUnsetExec: mismatched release, devRef 0x70a19670, reserveType 0x70a19670

devSetExec: fully released devRef 0x70a19670

devSetExec: fully released devRef 0x70a19670

devSetExec: fully released devRef 0x70a19670

+ Normal backup using Proactive Clients Backup at 8/4/10 (Activity Thread 1)

Progress 4/8/2010 8:59:33: Preparing to execute...

Progress 4/8/2010 8:59:34: Updating Catalog File...

Progress 4/8/2010 8:59:34: Please wait...

To Media Set FFAS Disk to Disk Backups...

- 8/4/10 8:59:33 AM: Copying Users on Cristina’s eMac

Progress 4/8/2010 8:59:44: Preparing to execute...

Start matching @ 9:1:6

Progress 4/8/2010 9:1:33: Please wait...

devSetExec: already reserved devRef 0x70a19670, reserveType 0x4972c4d0, reserveCnt 1

Progress 4/8/2010 9:1:34: Copying Users on Cristina’s eMac...

Progress 4/8/2010 9:1:35: Copying Users on Cristina’s eMac...

vlocRDiskDoFileCreate: device number = 0x4a108700

ABd.rdb: 9:01:35 AM Write [720 bytes]

[720 bytes] > 2e 73 68 64 00 01 00 01 00 00 00 00 66 06 00 00 5e 00 00 00 41 0b 00 00 00 00 00 00 02 00 00 00

ABd.rdb: 9:01:35 AM Write [4096 bytes]

[4096 bytes] > 52 78 76 72 44 46 69 6c 00 05 00 00 00 00 00 00 44 56 48 2e 03 04 03 04 40 44 44 4b 00 00 01 01

ABd.rdb: 9:01:35 AM Write [1048576 bytes]

[1048576 bytes] > 53 67 6d 74 00 00 04 b0 52 78 72 2e 01 00 01 10 00 00 03 12 01 cb 33 b3 5b 75 7c e0 00 00 07 9b

Progress 4/8/2010 9:2:5: Closing...

ABd.rdb: (Write passed 114 more times)

ABd.rdb: 9:02:05 AM Write [1044480 bytes]

[1044480 bytes] > f1 49 e6 b1 a5 62 8d 56 bb cf 19 a8 9a e4 f6 35 9f e6 76 a1 a4 db 93 9e 94 d2 11 6a 4b 92 a3 ad

ABd.rdb: 9:02:05 AM Write [720 bytes]

[720 bytes] > 2e 73 68 64 00 01 00 01 00 00 00 00 66 06 00 00 5e 00 00 00 41 0b 00 00 00 00 00 00 02 00 00 00

ABd.rdb: 9:02:05 AM Write [4096 bytes]

[4096 bytes] > 52 78 76 72 44 46 69 6c 00 05 00 00 00 00 00 00 44 56 48 2e 03 04 03 04 40 44 44 4b 00 00 01 01

ddskUpdateVol: use disk space = 1758789107712u, used in catalog = 340476346368u, free on volume = 1511171121152u

Progress 4/8/2010 9:2:5: Updating Catalog File...

Progress 4/8/2010 9:2:6: Building Snapshot...

Progress 4/8/2010 9:4:30: Copying Snapshot...

Progress 4/8/2010 9:4:30: Please wait...

devSetExec: already reserved devRef 0x70a19670, reserveType 0x49c64a10, reserveCnt 1

Progress 4/8/2010 9:4:31: Copying Snapshot...

Progress 4/8/2010 9:4:31: Copying Snapshot...

Progress 4/8/2010 9:4:31: Closing...

vlocRDiskDoFileCreate: device number = 0x4a120380

ABd.rdb: 9:04:32 AM Write [720 bytes]

[720 bytes] > 2e 73 68 64 00 01 00 01 00 00 00 00 66 06 00 00 5e 00 00 00 42 0b 00 00 00 00 00 00 02 00 00 00

ABd.rdb: 9:04:32 AM Write [4096 bytes]

[4096 bytes] > 52 78 76 72 44 46 69 6c 00 05 00 00 00 00 00 00 44 56 48 2e 03 04 03 04 40 44 44 4b 00 00 01 01

ABd.rdb: 9:04:32 AM Write [1048576 bytes]

[1048576 bytes] > 53 67 6d 74 00 00 04 b0 52 78 72 2e 01 00 01 10 00 00 03 13 01 cb 33 b4 0c 52 48 40 00 00 07 9c

ABd.rdb: (Write passed 7 more times)

ABd.rdb: 9:04:32 AM Write [770048 bytes]

[770048 bytes] > 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 cc 00 00 00 42 00 00 60 00 00 00 00 91 fd ff ff

ABd.rdb: 9:04:32 AM Write [720 bytes]

[720 bytes] > 2e 73 68 64 00 01 00 01 00 00 00 00 66 06 00 00 5e 00 00 00 42 0b 00 00 00 00 00 00 02 00 00 00

ABd.rdb: 9:04:32 AM Write [4096 bytes]

[4096 bytes] > 52 78 76 72 44 46 69 6c 00 05 00 00 00 00 00 00 44 56 48 2e 03 04 03 04 40 44 44 4b 00 00 01 01

ddskUpdateVol: use disk space = 1758789107712u, used in catalog = 340597977088u, free on volume = 1511161954304u

8/4/10 9:04:30 AM: Snapshot stored, 8.7 MB

8/4/10 9:04:33 AM: Execution completed successfully

Completed: 346 files, 145.6 MB, with 20% compression

Performance: 256.9 MB/minute

Duration: 00:04:59 (00:04:25 idle/loading/preparing)

 

Progress 4/8/2010 9:4:37: Continuing execution...

- 8/4/10 9:04:37 AM: Verifying FFAS Disk to Disk Backups

Progress 4/8/2010 9:4:37: Verifying...

Progress 4/8/2010 9:4:37: Please wait...

devSetExec: already reserved devRef 0x70a19670, reserveType 0x479c9c10, reserveCnt 1

Progress 4/8/2010 9:4:37: Verifying...

vlocRDiskFileOpen: device number = 0x46b8a0e0

AB002881.rdb: 9:04:37 AM Read [1048576 bytes]

[1048576 bytes] > 53 67 6d 74 00 00 04 b0 52 78 72 2e 01 00 01 10 00 00 03 12 01 cb 33 b3 5b 75 7c e0 00 00 07 9b

AB002881.rdb: (Read passed 114 more times)

[1044480 bytes] > f1 49 e6 b1 a5 62 8d 56 bb cf 19 a8 9a e4 f6 35 9f e6 76 a1 a4 db 93 9e 94 d2 11 6a 4b 92 a3 ad

Progress 4/8/2010 9:4:39: Please wait...

devSetExec: already reserved devRef 0x70a19670, reserveType 0x47f9b0e0, reserveCnt 1

Progress 4/8/2010 9:4:39: Verifying...

vlocRDiskFileOpen: device number = 0x47f823c0

AB002882.rdb: 9:04:39 AM Read [1048576 bytes]

[1048576 bytes] > 53 67 6d 74 00 00 04 b0 52 78 72 2e 01 00 01 10 00 00 03 13 01 cb 33 b4 0c 52 48 40 00 00 07 9c

AB002882.rdb: (Read passed 7 more times)

AB002882.rdb: 9:04:39 AM Read [770048 bytes]

[770048 bytes] > 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 cc 00 00 00 42 00 00 60 00 00 00 00 91 fd ff ff

Progress 4/8/2010 9:4:39: Please wait...

8/4/10 9:04:39 AM: Execution completed successfully

Remaining: 3 files, 0 B

Completed: 343 files, 145.6 MB

Performance: 0.1 MB/minute

Duration: 00:00:02 (00:00:03 idle/loading/preparing)

 

Progress 4/8/2010 9:4:40: Execution completed successfully

SCSI 0:3:0: ( 0 failed more times)

Sense > 70 00 02 00 00 00 00 0e 00 00 00 00 04 01 00 00 00 00

SCSI 0:3:0: ( 0 failed more times)

Sense > 70 00 06 00 00 00 00 0e 00 00 00 00 28 00 00 00 00 00

SCSI 0:3:0: ( 0 failed more times)

(but this time it passed)

SCSI 0:3:0: 10:14:16 AM Command <01 00 00 00 00 00>

SCSI 0:3:0: 10:14:20 AM Command <00 00 00 00 00 00>

SCSI 0:3:0: 10:14:20 AM Read <1a 00 00 00 0c 00> [12 bytes]

[12 bytes] > 0b 28 10 08 42 00 00 00 00 01 00 00

SCSI 0:3:0: 10:14:20 AM Read <44 01 00 00 00 00 00 00 38 00> [56 bytes]

[56 bytes] > 00 36 00 00 42 42 a0 00 00 00 1c e6 00 7f 02 00 00 02 e9 0e 4c 54 4f 2d 43 56 45 20 55 2d 32 38

SCSI 0:3:0: 10:14:20 AM Read <1a 00 00 00 0c 00> [12 bytes]

[12 bytes] > 0b 28 10 08 42 00 00 00 00 01 00 00

SCSI 0:3:0: 10:14:20 AM Write <15 10 00 00 0c 00> [12 bytes]

[12 bytes] > 00 00 10 08 42 00 00 00 00 01 00 00

SCSI 0:3:0: 10:14:20 AM Read <1a 00 31 00 16 00> [22 bytes]

Sense > 70 00 05 00 00 00 00 0e 00 00 00 00 24 00 00 cd 00 02

[22 bytes] > 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00

SCSI 0:3:0: 10:14:20 AM Read <1a 00 00 00 0c 00> [12 bytes]

[12 bytes] > 0b 28 10 08 42 00 00 00 00 01 00 00

SCSI 0:3:0: 10:14:20 AM Write <15 10 00 00 0c 00> [12 bytes]

[12 bytes] > 00 00 10 08 00 00 00 00 00 01 00 00

SCSI 0:3:0: 10:14:20 AM Read <08 01 00 00 01 00> [65536 bytes]

[65536 bytes] > 52 78 76 72 44 6c 74 20 00 07 00 00 00 00 00 00 44 56 48 2e 03 04 03 04 40 44 6c 55 00 00 01 41

SCSI 0:3:0: 10:14:37 AM Read <1a 00 00 00 0c 00> [12 bytes]

[12 bytes] > 0b 28 10 08 42 00 00 00 00 01 00 00

SCSI 0:3:0: 10:14:37 AM Read <44 01 00 00 00 00 00 00 38 00> [56 bytes]

[56 bytes] > 00 36 00 00 42 42 a0 00 00 00 1c e6 00 7f 02 00 00 02 e9 0e 4c 54 4f 2d 43 56 45 20 55 2d 32 38

SCSI 0:3:0: 10:14:37 AM Read <1a 00 0f 00 1c 00> [28 bytes]

[28 bytes] > 1b 28 10 08 42 00 00 00 00 01 00 00 8f 0e c0 80 00 00 00 01 00 00 00 01 00 00 00 00

SCSI 0:3:0: 10:14:37 AM Write <15 10 00 00 1c 00> [28 bytes]

[28 bytes] > 00 00 10 08 42 00 00 00 00 01 00 00 0f 0e c0 80 00 00 00 01 00 00 00 01 00 00 00 00

SCSI 0:3:0: 10:14:37 AM Read <4d 00 2e 00 00 00 00 01 44 00> [324 bytes]

[324 bytes] > 2e 00 01 40 00 01 40 01 00 00 02 40 01 00 00 03 40 01 00 00 04 40 01 00 00 05 40 01 00 00 06 40

SCSI 0:3:0: 10:14:39 AM Command <00 00 00 00 00 00>

devUnsetExec: mismatched release, devRef 0x70a19670, reserveType 0x70a19670

devSetExec: fully released devRef 0x70a19670

ddskUpdateVol: use disk space = 1758789107712u, used in catalog = 340607135744u, free on volume = 1511161954304u

devSetExec: fully released devRef 0x70a19670

devUnsetExec: mismatched release, devRef 0x70a19670, reserveType 0x70a19670

devSetExec: fully released devRef 0x70a19670

ddskUpdateVol: use disk space = 1758789107712u, used in catalog = 340607242240u, free on volume = 1511161839616u

devSetExec: fully released devRef 0x70a19670

devUnsetExec: mismatched release, devRef 0x70a19670, reserveType 0x70a19670

devSetExec: fully released devRef 0x70a19670

devSetExec: fully released devRef 0x70a19670

devSetExec: fully released devRef 0x70a19670

+ Normal backup using Proactive Clients Backup at 8/4/10 (Activity Thread 1)

Progress 4/8/2010 11:9:11: Preparing to execute...

Progress 4/8/2010 11:9:12: Updating Catalog File...

Progress 4/8/2010 11:9:12: Please wait...

To Media Set FFAS Disk to Disk Backups...

- 8/4/10 11:09:11 AM: Copying Users on Sandy eMac

Progress 4/8/2010 11:9:22: Preparing to execute...

Start matching @ 11:9:54

Progress 4/8/2010 11:10:9: Please wait...

devSetExec: already reserved devRef 0x70a19670, reserveType 0x49c1cb40, reserveCnt 1

Progress 4/8/2010 11:10:10: Copying Users on Sandy eMac...

Progress 4/8/2010 11:10:10: Copying Users on Sandy eMac...

Progress 4/8/2010 11:10:11: Closing...

vlocRDiskDoFileCreate: device number = 0x48cf8770

ABd.rdb: 11:10:11 AM Write [720 bytes]

[720 bytes] > 2e 73 68 64 00 01 00 01 00 00 00 00 66 06 00 00 5e 00 00 00 43 0b 00 00 00 00 00 00 02 00 00 00

ABd.rdb: 11:10:11 AM Write [4096 bytes]

[4096 bytes] > 52 78 76 72 44 46 69 6c 00 05 00 00 00 00 00 00 44 56 48 2e 03 04 03 04 40 44 44 4b 00 00 01 01

ABd.rdb: 11:10:11 AM Write [106496 bytes]

[106496 bytes] > 53 67 6d 74 00 00 04 b0 52 78 72 2e 01 00 01 10 00 00 03 13 01 cb 33 c5 77 83 52 60 00 00 07 9d

ABd.rdb: 11:10:11 AM Write [720 bytes]

[720 bytes] > 2e 73 68 64 00 01 00 01 00 00 00 00 66 06 00 00 5e 00 00 00 43 0b 00 00 00 00 00 00 02 00 00 00

ABd.rdb: 11:10:11 AM Write [4096 bytes]

[4096 bytes] > 52 78 76 72 44 46 69 6c 00 05 00 00 00 00 00 00 44 56 48 2e 03 04 03 04 40 44 44 4b 00 00 01 01

ddskUpdateVol: use disk space = 1758789107712u, used in catalog = 340607135744u, free on volume = 1511161839616u

Progress 4/8/2010 11:10:11: Updating Catalog File...

Progress 4/8/2010 11:10:12: Building Snapshot...

Progress 4/8/2010 11:12:5: Copying Snapshot...

Progress 4/8/2010 11:12:5: Please wait...

devSetExec: already reserved devRef 0x70a19670, reserveType 0x47f0c500, reserveCnt 1

Progress 4/8/2010 11:12:5: Copying Snapshot...

Progress 4/8/2010 11:12:6: Copying Snapshot...

Progress 4/8/2010 11:12:6: Closing...

vlocRDiskDoFileCreate: device number = 0x468466b0

ABd.rdb: 11:12:06 AM Write [720 bytes]

[720 bytes] > 2e 73 68 64 00 01 00 01 00 00 00 00 66 06 00 00 5e 00 00 00 44 0b 00 00 00 00 00 00 02 00 00 00

ABd.rdb: 11:12:06 AM Write [4096 bytes]

[4096 bytes] > 52 78 76 72 44 46 69 6c 00 05 00 00 00 00 00 00 44 56 48 2e 03 04 03 04 40 44 44 4b 00 00 01 01

ABd.rdb: 11:12:06 AM Write [1048576 bytes]

[1048576 bytes] > 53 67 6d 74 00 00 04 b0 52 78 72 2e 01 00 01 10 00 00 03 14 01 cb 33 c5 df 25 03 f0 00 00 07 9e

ABd.rdb: (Write passed 2 more times)

ABd.rdb: 11:12:06 AM Write [323584 bytes]

[323584 bytes] > 45 00 32 00 36 00 2d 00 41 00 41 00 30 00 37 00 2d 00 43 00 39 00 41 00 32 00 33 00 44 00 45 00

ABd.rdb: 11:12:06 AM Write [720 bytes]

[720 bytes] > 2e 73 68 64 00 01 00 01 00 00 00 00 66 06 00 00 5e 00 00 00 44 0b 00 00 00 00 00 00 02 00 00 00

ABd.rdb: 11:12:06 AM Write [4096 bytes]

[4096 bytes] > 52 78 76 72 44 46 69 6c 00 05 00 00 00 00 00 00 44 56 48 2e 03 04 03 04 40 44 44 4b 00 00 01 01

ddskUpdateVol: use disk space = 1758789107712u, used in catalog = 340607242240u, free on volume = 1511158362112u

8/4/10 11:12:05 AM: Snapshot stored, 3.3 MB

8/4/10 11:12:07 AM: Execution completed successfully

Completed: 43 files, 264 KB, with 60% compression

Performance: 5.1 MB/minute

Duration: 00:02:56 (00:02:52 idle/loading/preparing)

 

Progress 4/8/2010 11:12:10: Continuing execution...

- 8/4/10 11:12:10 AM: Verifying FFAS Disk to Disk Backups

Progress 4/8/2010 11:12:10: Verifying...

Progress 4/8/2010 11:12:10: Please wait...

devSetExec: already reserved devRef 0x70a19670, reserveType 0x4a1d4b10, reserveCnt 1

Progress 4/8/2010 11:12:10: Verifying...

vlocRDiskFileOpen: device number = 0x4a1af9c0

AB002883.rdb: 11:12:11 AM Read [1048576 bytes]

[106496 bytes] > 53 67 6d 74 00 00 04 b0 52 78 72 2e 01 00 01 10 00 00 03 13 01 cb 33 c5 77 83 52 60 00 00 07 9d

Progress 4/8/2010 11:12:11: Please wait...

devSetExec: already reserved devRef 0x70a19670, reserveType 0x48089aa0, reserveCnt 1

Progress 4/8/2010 11:12:11: Verifying...

vlocRDiskFileOpen: device number = 0x4804c8d0

AB002884.rdb: 11:12:11 AM Read [1048576 bytes]

[1048576 bytes] > 53 67 6d 74 00 00 04 b0 52 78 72 2e 01 00 01 10 00 00 03 14 01 cb 33 c5 df 25 03 f0 00 00 07 9e

AB002884.rdb: (Read passed 2 more times)

AB002884.rdb: 11:12:11 AM Read [323584 bytes]

[323584 bytes] > 45 00 32 00 36 00 2d 00 41 00 41 00 30 00 37 00 2d 00 43 00 39 00 41 00 32 00 33 00 44 00 45 00

Progress 4/8/2010 11:12:11: Please wait...

8/4/10 11:12:11 AM: Execution completed successfully

Remaining: 1 files, 0 B

Completed: 42 files, 262 KB

Performance: 0.1 MB/minute

Duration: 00:00:00 (00:00:03 idle/loading/preparing)

 

Progress 4/8/2010 11:12:12: Execution completed successfully

devUnsetExec: mismatched release, devRef 0x70a19670, reserveType 0x70a19670

devSetExec: fully released devRef 0x70a19670

devSetExec: fully released devRef 0x49cef400

devSetExec: fully released devRef 0x70a19670

devUnsetExec: mismatched release, devRef 0x70a19670, reserveType 0x70a19670

devSetExec: fully released devRef 0x70a19670

devSetExec: fully released devRef 0x49c566c0

devSetExec: fully released devRef 0x70a19670

SCSI 0:3:0: 12:41:35 PM Command <00 00 00 00 00 00>

devUnsetExec: mismatched release, devRef 0x70a19670, reserveType 0x70a19670

devSetExec: fully released devRef 0x70a19670

devSetExec: fully released devRef 0x70a19670

devSetExec: fully released devRef 0x49c7d230

devSetExec: fully released devRef 0x70a19670

devUnsetExec: mismatched release, devRef 0x70a19670, reserveType 0x70a19670

devSetExec: fully released devRef 0x70a19670

devSetExec: fully released devRef 0x49c8fec0

devSetExec: fully released devRef 0x70a19670

SCSI 0:3:0: 12:42:15 PM Command <00 00 00 00 00 00>

devSetExec: fully released devRef 0x49cc2ab0

devUnsetExec: mismatched release, devRef 0x70a19670, reserveType 0x70a19670

devSetExec: fully released devRef 0x70a19670

devSetExec: fully released devRef 0x49cdab30

devSetExec: fully released devRef 0x70a19670

SCSI 0:3:0: 12:44:14 PM Command <00 00 00 00 00 00>

devUnsetExec: mismatched release, devRef 0x70a19670, reserveType 0x70a19670

devSetExec: fully released devRef 0x70a19670

devSetExec: fully released devRef 0x70a19670

devSetExec: fully released devRef 0x70a19670

devSetExec: fully released devRef 0x48f0f620

devSetExec: fully released devRef 0x70a19670

devUnsetExec: mismatched release, devRef 0x70a19670, reserveType 0x70a19670

devSetExec: fully released devRef 0x70a19670

devSetExec: fully released devRef 0x48f19680

devSetExec: fully released devRef 0x70a19670

SCSI 0:3:0: 12:48:14 PM Command <00 00 00 00 00 00>

devSetExec: fully released devRef 0x48f50c50

SCSI 0:3:0: 12:48:41 PM Command <00 00 00 00 00 00>

devUnsetExec: mismatched release, devRef 0x70a19670, reserveType 0x70a19670

devSetExec: fully released devRef 0x70a19670

devSetExec: fully released devRef 0x48fc2fd0

devSetExec: fully released devRef 0x70a19670

SCSI 0:3:0: 12:48:47 PM Command <00 00 00 00 00 00>

devUnsetExec: mismatched release, devRef 0x70a19670, reserveType 0x70a19670

devSetExec: fully released devRef 0x70a19670

devSetExec: fully released devRef 0x47984f70

devSetExec: fully released devRef 0x70a19670

devUnsetExec: mismatched release, devRef 0x70a19670, reserveType 0x70a19670

devSetExec: fully released devRef 0x70a19670

devSetExec: fully released devRef 0x48c9edd0

devSetExec: fully released devRef 0x70a19670

SCSI 0:3:0: 12:50:15 PM Command <00 00 00 00 00 00>

devUnsetExec: mismatched release, devRef 0x70a19670, reserveType 0x70a19670

devSetExec: fully released devRef 0x70a19670

devSetExec: fully released devRef 0x48c066f0

devSetExec: fully released devRef 0x70a19670

devUnsetExec: mismatched release, devRef 0x70a19670, reserveType 0x70a19670

devSetExec: fully released devRef 0x70a19670

devSetExec: fully released devRef 0x48c9cac0

devSetExec: fully released devRef 0x70a19670

SCSI 0:3:0: 12:51:35 PM Command <00 00 00 00 00 00>

devSetExec: fully released devRef 0x48c1f4a0

devUnsetExec: mismatched release, devRef 0x70a19670, reserveType 0x70a19670

devSetExec: fully released devRef 0x70a19670

devSetExec: fully released devRef 0x48c32db0

SCSI 0:3:0: 12:52:37 PM Command <00 00 00 00 00 00>

devSetExec: fully released devRef 0x70a19670

devSetExec: fully released devRef 0x48c6b260

devUnsetExec: mismatched release, devRef 0x70a19670, reserveType 0x70a19670

devSetExec: fully released devRef 0x70a19670

devSetExec: fully released devRef 0x48c6b6f0

SCSI 0:3:0: 12:58:59 PM Command <00 00 00 00 00 00>

devSetExec: fully released devRef 0x70a19670

devSetExec: fully released devRef 0x48ccc7c0

SCSI 0:3:0: 12:59:33 PM Command <00 00 00 00 00 00>

devUnsetExec: mismatched release, devRef 0x70a19670, reserveType 0x70a19670

devSetExec: fully released devRef 0x70a19670

devSetExec: fully released devRef 0x48cd9890

devSetExec: fully released devRef 0x70a19670

SCSI 0:3:0: 12:59:41 PM Command <00 00 00 00 00 00>

devUnsetExec: mismatched release, devRef 0x70a19670, reserveType 0x70a19670

devSetExec: fully released devRef 0x70a19670

devSetExec: fully released devRef 0x70a19670

devSetExec: fully released devRef 0x70a19670

devSetExec: fully released devRef 0x47fdb6a0

devSetExec: fully released devRef 0x70a19670

devUnsetExec: mismatched release, devRef 0x70a19670, reserveType 0x70a19670

devSetExec: fully released devRef 0x70a19670

devSetExec: fully released devRef 0x47fdd3c0

devSetExec: fully released devRef 0x70a19670

SCSI 0:3:0: 1:01:46 PM Command <00 00 00 00 00 00>

devSetExec: fully released devRef 0x47975e30

devUnsetExec: mismatched release, devRef 0x70a19670, reserveType 0x70a19670

devSetExec: fully released devRef 0x70a19670

devSetExec: fully released devRef 0x47988d70

SCSI 0:3:0: 1:03:25 PM Command <00 00 00 00 00 00>

devSetExec: fully released devRef 0x70a19670

devSetExec: fully released devRef 0x479ac6a0

SCSI 0:3:0: 1:05:12 PM Command <00 00 00 00 00 00>

devUnsetExec: mismatched release, devRef 0x70a19670, reserveType 0x70a19670

devSetExec: fully released devRef 0x70a19670

devSetExec: fully released devRef 0x479e7ad0

devSetExec: fully released devRef 0x70a19670

SCSI 0:3:0: 1:05:29 PM Command <00 00 00 00 00 00>

devSetExec: fully released devRef 0x4790d6e0

SCSI 0:3:0: 1:08:23 PM Command <00 00 00 00 00 00>

devUnsetExec: mismatched release, devRef 0x70a19670, reserveType 0x70a19670

devSetExec: fully released devRef 0x70a19670

devSetExec: fully released devRef 0x479b4e10

devSetExec: fully released devRef 0x70a19670

SCSI 0:3:0: 1:08:40 PM Command <00 00 00 00 00 00>

devUnsetExec: mismatched release, devRef 0x70a19670, reserveType 0x70a19670

devSetExec: fully released devRef 0x70a19670

devSetExec: fully released devRef 0x4793cbe0

devSetExec: fully released devRef 0x70a19670

devUnsetExec: mismatched release, devRef 0x70a19670, reserveType 0x70a19670

devSetExec: fully released devRef 0x70a19670

devSetExec: fully released devRef 0x47fae810

devSetExec: fully released devRef 0x70a19670

SCSI 0:3:0: 1:09:39 PM Command <00 00 00 00 00 00>

Share this post


Link to post
Share on other sites

A short update...

 

tried inserting a new blank tape and starting a new backup to it. stops at the same point.

 

Status says "needs media" but the tape is in there.

Share this post


Link to post
Share on other sites

some technical specs...

Tape is tandberg ultrium 2 DC - TS400, firmware rev 0412.

SCSI card is ATTO Express PCI UL5D driver version 4.4.1, firmware version April 10, 2009

 

MacOSX 10.6.4 server (up to date)

Retrospect 8.2.

Share this post


Link to post
Share on other sites

since i ám having the same problem with staged backups:

did you find a solution?

Funny thing is, that if you manually stop the verification and then manually start the verification (media sets-verify), Retrospect doesn`t complain about the missing tape but just goes on verifying the media set with that tape in the drive it said it couldn`t find in the scripted copy backup.

I might as well try the next backup to tape without verification and do this step with a verify-script, if such thing exists

Share this post


Link to post
Share on other sites

really funny.

i unchecked Media Verification (Scripts-Options).

I did uncheck in the middle of the copy backup with about 100GB more to go.

Retropsect doesn´t ask for the member now (which is still in the drive), but verifies nevertheless.

So it behaves like it should, except it shouldn`t verify. (might be, because i changed something in the middle of a script running.

Next test will be, whether Retrospect will change automatically to the next tape once the one i am using now is full.

Share this post


Link to post
Share on other sites

just finished a 2TB copy backup (without the verify step) to tape from my raid, spanning 3 tapes and it run through smoothly.

of course i have to do the verify step now as well.

i wonder whether this issue has anything to do with the "fast catalog rebuild" option" (Media Sets-Options), which i have unchecked now.

If i remember right, i did mark this option, when the Tape Media Set (the media set, which caused problems with verifying) already contained data on 3 Tapes

Share this post


Link to post
Share on other sites

My set has always had "fast catalog rebuild" turned on, and worked fine in 8.1.

 

Today I tried turning off media verification, and doing a seperate verify pass after the backup finished. The backup finished fine. When I went to go run my new verify script, it gave me a select media button. When I told it to use the tape that was in the drive, it said the media was already in use by another backup set. Pressing "Skip" did nothing. Had to press "stop" and abort the verify.

 

So right now I can backup, but not verify.

 

Logs don't say anythhing useful...

 

+ Executing Verify offsite backups-test at 8/13/10 (Activity Thread 1)

- 8/13/10 1:17:17 PM: Verifying FFAS Offsite Backups

Progress 13/8/2010 13:17:17: Verifying...

Progress 13/8/2010 13:17:17: Please wait...

Progress 13/8/2010 13:17:17: Waiting for media...

Progress 13/8/2010 13:18:56: Execution stopped by operator

Total duration: 00:01:39 (00:01:39 idle/loading/preparing)

Edited by Guest
added logs from failed verify

Share this post


Link to post
Share on other sites

Create an account or sign in to comment

You need to be a member in order to leave a comment

Create an account

Sign up for a new account in our community. It's easy!

Register a new account

Sign in

Already have an account? Sign in here.

Sign In Now

×