Problem with backup multiplexing

[mediatheque]

We have recently tried to do GFS backup using job multiplexing with append to media (with BrightStor ARCserver v. 11.0 Build 2670.

A few backups went fine, and much faster (by about a factor of 6) than sequential backups.

After a few days, ARCserve reports that the current job cannot be started. The detailed job log shows:

Job(JOBNO=2) cannot be started.
Check Device Group(ADMIN)/Media(A-GFS-MON-26/09/05) availability.

This media is in the daily save set, there are a few in the appropriate scratch set.

The tape log (see details below) seems to say that 4 jobs were created (threads?) - while there is only one backup in the job queue (job #2) and one prune job (job #1) - and that one of the cannot be started as "another job if[should be "is"?] joining or spanning or leaving." It then closes the job, and three remain active. However, there is no way I know of to find which are the jobs, and why they impede the backup. The only ways out were either rebooting or changing the job from multiplexing to non-multiplexing.

Looking at the first moment when the problem appears, the detailed job log shows that the backup started spanning subjobs and then seemed to have run into this problem. What is odd in this log is the "Pruned" mention (as the prune job does not appear to be active).

Any ideas what we should do to have this work would be much appreciated.

----------------------------
Detailed job log at first occurrence
----------------------------

Information 28/09/2005 18:10:23 [JOBQUEUE]: Pruned [Job No: 31] [Description: MULTIPLEXING [JOB 2] SUBJOB 1]
Information 28/09/2005 18:10:34 [JOBQUEUE]: Pruned [Job No: 32] [Description: MULTIPLEXING [JOB 2] SUBJOB 2]
Information 28/09/2005 18:11:40 [JOBQUEUE]: Pruned [Job No: 33] [Description: MULTIPLEXING [JOB 2] SUBJOB 3]
Information 28/09/2005 18:12:14 [JOBQUEUE]: Pruned [Job No: 34] [Description: MULTIPLEXING [JOB 2] SUBJOB 4]
Information 28/09/2005 18:14:37 [JOBQUEUE]: Pruned [Job No: 35] [Description: MULTIPLEXING [JOB 2] SUBJOB 5]
Information 28/09/2005 18:33:13 [JOBQUEUE]: Pruned [Job No: 36] [Description: MULTIPLEXING [JOB 2] SUBJOB 6]
Information 28/09/2005 18:34:42 [JOBQUEUE]: Pruned [Job No: 37] [Description: MULTIPLEXING [JOB 2] SUBJOB 7]
Information 28/09/2005 18:34:53 [JOBQUEUE]: Pruned [Job No: 38] [Description: MULTIPLEXING [JOB 2] SUBJOB 8]
Information 28/09/2005 18:39:07 [JOBQUEUE]: Pruned [Job No: 4] [Description: MULTIPLEXING [JOB 2] SUBJOB 10]
Information 28/09/2005 18:46:29 [JOBQUEUE]: Pruned [Job No: 5] [Description: MULTIPLEXING [JOB 2] SUBJOB 11]
Information 28/09/2005 18:48:20 [JOBQUEUE]: Pruned [Job No: 3] [Description: MULTIPLEXING [JOB 2] SUBJOB 9]
Information 28/09/2005 18:55:09 [JOBQUEUE]: Pruned [Job No: 7] [Description: MULTIPLEXING [JOB 2] SUBJOB 13]
Information 28/09/2005 18:59:45 [JOBQUEUE]: Pruned [Job No: 9] [Description: MULTIPLEXING [JOB 2] SUBJOB 15]
Information 28/09/2005 19:00:06 Job(JOBNO=2) cannot be started.

(this repeats for other subjobs, 25 or so in total)

----------------------------
Tape Log:
----------------------------



[11:23:28] -Total Jobs now ACTIVE: [4]-
[11:23:28] CREATEJOBHANDLE[010FFB30] JobID[16168] Generated for new Job Queue Ha
ndle
[11:23:28] CREATEJOBHANDLE[010FFB30] JobType:[2][Job Queue]
[11:23:28] CREATEJOBHANDLE[010FFB30] Client:[SYSTEM]
[11:23:28] CREATEJOBHANDLE[010FFB30] Connection:[Local]
[11:23:28] usJobID = [16168], muxId = 0, jobToken = 115053890
MUX_BEB_JOB_TAG_0:: chunkSize = 1024, maxNumberOfStreams = 4
[11:23:28] GRP: ClientGetGroupStatus:gbPrimaryServer == FALSE. call _ClientGet
GroupStatus()
[11:23:28] GRP: ClientGetGroupStatus: JobType:3 tapeName:[A-GFS-MON-26/09/05]
RID:[2f49] Seq:[1] Group:[ADMIN]
[11:23:28] GRP: ClientGetGroupStatus: OwnerName[SYSTEM] JobID[16168]
[11:23:28] GRP: LockGroupEnum:[ADMIN]
[11:23:28] usJobID = [16168], muxId = 115053890, jobToken = 115053890
Mux_Update_IfStreamCanJoin:: Tape info is GroupName = ADMIN, tapeName = A-GFS-MO
N-26/09/05, randomId = 12105, seq = 1
[11:23:28] usJobID = [16168], muxId = 115053890, jobToken = 115053890
Mux_Update_IfStreamCanJoin:: Another job[0] if joining or spanning or leaving..
So this job can not start now. Try for some other drive. Group = ADMIN, jobId =
16168
[11:23:28] DestroyJobHandle[010FFB30]
[11:23:28] usJobID = [16168], muxId = 0, jobToken = 0
Destroy JobID[16168]: Active Jobs now: [3]

 

[vschumpy]

Patch up, this was an early bug in r11.0 if I remember correctly:

http://supportconnect.ca.com/sc/redir.jsp?reqPage=search&searchID=TEC378659