Hi all,
Since 2 weeks, I encountered some problems with bacula.
When I arrived in the company, bacula was configured for 4 jobs, with Max
Vol Jobs at 5. No problem, all saves were going perfectly.
First job :
13-Apr 23:05 SISCABK01-dir JobId 396: BeforeJob: run command
"/opt/bacula/etc/make_catalog_backup bacula bacula"
13-Apr 23:05 SISCABK01-dir JobId 396: Start Backup JobId 396,
Job=SISCABKO1-J01.2009-04-13_23.05.00.38
13-Apr 23:05 SISCABK01-dir JobId 396: Recycled volume "000009L3"
13-Apr 23:05 SISCABK01-dir JobId 396: Using Device "Drive-1"
13-Apr 23:05 SISCABK01-sd JobId 396: 3301 Issuing autochanger "loaded? drive
0" command.
13-Apr 23:05 SISCABK01-sd JobId 396: 3302 Autochanger "loaded? drive 0",
result: nothing loaded.
13-Apr 23:05 SISCABK01-sd JobId 396: 3304 Issuing autochanger "load slot 2,
drive 0" command.
13-Apr 23:05 SISCABK01-sd JobId 396: 3305 Autochanger "load slot 2, drive
0", status is OK.
13-Apr 23:05 SISCABK01-sd JobId 396: Recycled volume "000009L3" on device
"Drive-1" (/dev/nst0), all previous data lost.
13-Apr 23:05 SISCABK01-sd JobId 396: Job write elapsed time = 00:00:10,
Transfer rate = 79.54 M bytes/second 13-Apr 23:06 SISCABK01-dir JobId 396:
Bacula SISCABK01-dir 2.4.4 (28Dec08): 13-Apr-2009 23:06:01
Last job :
13-Apr 23:10 SISCABK01-dir JobId 399: BeforeJob: run command
"/opt/bacula/etc/make_catalog_backup bacula bacula"
13-Apr 23:10 SISCABK01-dir JobId 399: Start Backup JobId 399,
Job=SISCAPSO1-J01.2009-04-13_23.05.00.41
13-Apr 23:10 SISCABK01-dir JobId 399: Using Device "Drive-1"
13-Apr 23:10 SISCABK01-sd JobId 399: 3301 Issuing autochanger "loaded? drive
0" command.
13-Apr 23:10 SISCABK01-sd JobId 399: 3302 Autochanger "loaded? drive 0",
result: nothing loaded.
13-Apr 23:10 SISCABK01-sd JobId 399: 3304 Issuing autochanger "load slot 2,
drive 0" command.
13-Apr 23:10 SISCABK01-sd JobId 399: 3305 Autochanger "load slot 2, drive
0", status is OK.
13-Apr 23:10 SISCABK01-sd JobId 399: Volume "000009L3" previously written,
moving to end of data.
13-Apr 23:10 SISCABK01-sd JobId 399: Ready to append to end of Volume
"000009L3" at file=3.
13-Apr 23:10 SISCABK01-sd JobId 399: Job write elapsed time = 00:00:02,
Transfer rate = 1.785 M bytes/second 13-Apr 23:10 SISCABK01-dir JobId 399:
Bacula SISCABK01-dir 2.4.4 (28Dec08): 13-Apr-2009 23:10:55
I have to add 2 new jobs, so I put the Max Vol Jobs at 7 and for a week, no
problem.
First job :
15-Apr 23:05 SISCABK01-dir JobId 409: BeforeJob: run command
"/opt/bacula/etc/make_catalog_backup bacula bacula"
15-Apr 23:05 SISCABK01-dir JobId 409: Start Backup JobId 409,
Job=SISCABKO1-J01.2009-04-15_23.05.00.45
15-Apr 23:05 SISCABK01-dir JobId 409: There are no more Jobs associated with
Volume "000011L3". Marking it purged.
15-Apr 23:05 SISCABK01-dir JobId 409: All records pruned from Volume
"000011L3"; marking it "Purged"
15-Apr 23:05 SISCABK01-dir JobId 409: Recycled volume "000011L3"
15-Apr 23:05 SISCABK01-dir JobId 409: Using Device "Drive-1"
15-Apr 23:05 SISCABK01-sd JobId 409: 3301 Issuing autochanger "loaded? drive
0" command.
15-Apr 23:05 SISCABK01-sd JobId 409: 3302 Autochanger "loaded? drive 0",
result: nothing loaded.
15-Apr 23:05 SISCABK01-sd JobId 409: 3304 Issuing autochanger "load slot 4,
drive 0" command.
15-Apr 23:05 SISCABK01-sd JobId 409: 3305 Autochanger "load slot 4, drive
0", status is OK.
15-Apr 23:05 SISCABK01-sd JobId 409: Recycled volume "000011L3" on device
"Drive-1" (/dev/nst0), all previous data lost.
15-Apr 23:06 SISCABK01-sd JobId 409: Job write elapsed time = 00:00:10,
Transfer rate = 82.73 M bytes/second 15-Apr 23:06 SISCABK01-dir JobId 409:
Bacula SISCABK01-dir 2.4.4 (28Dec08): 15-Apr-2009 23:06:06
Last Job:
15-Apr 23:15 SISCABK01-dir JobId 414: BeforeJob: run command
"/opt/bacula/etc/make_catalog_backup bacula bacula"
15-Apr 23:16 SISCABK01-dir JobId 414: Start Backup JobId 414,
Job=SISCAASB01-J01.2009-04-15_23.05.00.50
15-Apr 23:16 SISCABK01-dir JobId 414: Using Device "Drive-1"
15-Apr 23:16 SISCABK01-fd JobId 414: DIR and FD clocks differ by 44 seconds,
FD automatically compensating.
15-Apr 23:16 SISCABK01-sd JobId 414: 3301 Issuing autochanger "loaded? drive
0" command.
15-Apr 23:16 SISCABK01-sd JobId 414: 3302 Autochanger "loaded? drive 0",
result: nothing loaded.
15-Apr 23:16 SISCABK01-sd JobId 414: 3304 Issuing autochanger "load slot 4,
drive 0" command.
15-Apr 23:16 SISCABK01-sd JobId 414: 3305 Autochanger "load slot 4, drive
0", status is OK.
15-Apr 23:16 SISCABK01-sd JobId 414: Volume "000011L3" previously written,
moving to end of data.
15-Apr 23:17 SISCABK01-sd JobId 414: Ready to append to end of Volume
"000011L3" at file=8.
15-Apr 23:19 SISCABK01-sd JobId 414: Job write elapsed time = 00:02:18,
Transfer rate = 9.417 M bytes/second 15-Apr 23:19 SISCABK01-dir JobId 414:
Bacula SISCABK01-dir 2.4.4 (28Dec08): 15-Apr-2009 23:19:35
But one week ago, bacula started to send me errors. Only the first 3 jobs
succeeded.
First Job :
20-Apr 23:05 SISCABK01-dir JobId 439: BeforeJob: run command
"/opt/bacula/etc/make_catalog_backup bacula bacula"
20-Apr 23:05 SISCABK01-dir JobId 439: Start Backup JobId 439,
Job=SISCABKO1-J01.2009-04-20_23.05.00.00
20-Apr 23:05 SISCABK01-dir JobId 439: Using Device "Drive-1"
20-Apr 23:05 SISCABK01-sd JobId 439: 3301 Issuing autochanger "loaded? drive
0" command.
20-Apr 23:05 SISCABK01-sd JobId 439: 3302 Autochanger "loaded? drive 0",
result: nothing loaded.
20-Apr 23:05 SISCABK01-sd JobId 439: 3304 Issuing autochanger "load slot 2,
drive 0" command.
20-Apr 23:05 SISCABK01-sd JobId 439: 3305 Autochanger "load slot 2, drive
0", status is OK.
20-Apr 23:05 SISCABK01-sd JobId 439: Volume "000016L3" previously written,
moving to end of data.
20-Apr 23:05 SISCABK01-sd JobId 439: Ready to append to end of Volume
"000016L3" at file=4.
20-Apr 23:06 SISCABK01-sd JobId 439: Job write elapsed time = 00:00:12,
Transfer rate = 75.53 M bytes/second 20-Apr 23:06 SISCABK01-dir JobId 439:
Bacula SISCABK01-dir 2.4.4 (28Dec08): 20-Apr-2009 23:06:11
Last one successful :
20-Apr 23:08 SISCABK01-dir JobId 441: BeforeJob: run command
"/opt/bacula/etc/make_catalog_backup bacula bacula"
20-Apr 23:09 SISCABK01-dir JobId 441: Start Backup JobId 441,
Job=SISCAFTO1-J01.2009-04-20_23.05.00.02
20-Apr 23:09 SISCABK01-dir JobId 441: Using Device "Drive-1"
20-Apr 23:09 SISCABK01-sd JobId 441: 3301 Issuing autochanger "loaded? drive
0" command.
20-Apr 23:09 SISCABK01-sd JobId 441: 3302 Autochanger "loaded? drive 0",
result: nothing loaded.
20-Apr 23:09 SISCABK01-sd JobId 441: 3304 Issuing autochanger "load slot 2,
drive 0" command.
20-Apr 23:09 SISCABK01-sd JobId 441: 3305 Autochanger "load slot 2, drive
0", status is OK.
20-Apr 23:09 SISCABK01-sd JobId 441: Volume "000016L3" previously written,
moving to end of data.
20-Apr 23:09 SISCABK01-sd JobId 441: Ready to append to end of Volume
"000016L3" at file=6.
20-Apr 23:09 SISCABK01-dir JobId 441: Max Volume jobs exceeded. Marking
Volume "000016L3" as Used.
20-Apr 23:10 SISCABK01-sd JobId 441: Job write elapsed time = 00:00:20,
Transfer rate = 11.05 M bytes/second 20-Apr 23:10 SISCABK01-dir JobId 441:
Bacula SISCABK01-dir 2.4.4 (28Dec08): 20-Apr-2009 23:10:10
Error :
20-Apr 23:11 SISCABK01-sd JobId 442: Please mount Volume "000009L3" or label
a new one for:
Job: SISCAASO1-J01.2009-04-20_23.05.00.03
Storage: "Drive-1" (/dev/nst0)
Pool: MondayPool
Media type: LTO3
I update all pools, volume etc., looked at all configuration files but
nothing. So one day I updated the Max Vol Jobs to 10 and all jobs were
successful.
Last :
24-avr 23:13 SISCABK01-dir JobId 466: BeforeJob: run command
"/opt/bacula/etc/make_catalog_backup bacula bacula"
24-avr 23:13 SISCABK01-dir JobId 466: Start Backup JobId 466,
Job=SISCAASB01-J01.2009-04-24_23.05.00.20
24-avr 23:13 SISCABK01-dir JobId 466: Using Device "Drive-1"
24-avr 23:14 SISCABK01-fd JobId 466: DIR and FD clocks differ by 66 seconds,
FD automatically compensating.
24-avr 23:13 SISCABK01-sd JobId 466: 3301 Issuing autochanger "loaded? drive
0" command.
24-avr 23:13 SISCABK01-sd JobId 466: 3302 Autochanger "loaded? drive 0",
result: nothing loaded.
24-avr 23:13 SISCABK01-sd JobId 466: 3304 Issuing autochanger "load slot 6,
drive 0" command.
24-avr 23:14 SISCABK01-sd JobId 466: 3305 Autochanger "load slot 6, drive
0", status is OK.
24-avr 23:14 SISCABK01-sd JobId 466: Volume "000020L3" previously written,
moving to end of data.
24-avr 23:14 SISCABK01-sd JobId 466: Ready to append to end of Volume
"000020L3" at file=7.
24-avr 23:15 SISCABK01-sd JobId 466: Job write elapsed time = 00:00:20,
Transfer rate = 5.058 M bytes/second 24-avr 23:15 SISCABK01-dir JobId 466:
Bacula SISCABK01-dir 2.4.4 (28Dec08): 24-avr-2009 23:15:03
And this morning when I check the logs and I can see an error. 6 jobs with
success, and not the last one.
Same problem than one week ago before update Max Vol jobs to 10.
And after reading all logs from 3 weeks, I can tell (I think) where the
problem is, but not how to solve it.
If we look at the logs, the first job have not the line :
Recycled volume "00000***" on device "Drive-1" (/dev/nst0), all previous
data lost
I think this problem come from the autoprune option, but I havent make any
change on it !!
I check all the volume, from 1 to 15, I have the recycling, but since 16,
no. I havent make any changes between 15 and 16. I dont understand.
So, please help me !! ^^
Thanks all
bacula-dir.conf
Description: Binary data
------------------------------------------------------------------------------ Register Now & Save for Velocity, the Web Performance & Operations Conference from O'Reilly Media. Velocity features a full day of expert-led, hands-on workshops and two days of sessions from industry leaders in dedicated Performance & Operations tracks. Use code vel09scf and Save an extra 15% before 5/3. http://p.sf.net/sfu/velocityconf
_______________________________________________ Bacula-users mailing list Bacula-users@lists.sourceforge.net https://lists.sourceforge.net/lists/listinfo/bacula-users
