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 haven’t make any change on it !!
I check all the volume, from 1 to 15, I have
the recycling, but since 16, no. I haven’t make any changes between 15
and 16. I don’t understand.
So, please help me !! ^^
Thanks all