Bacula-users
[Top] [All Lists]
<prev [Date] next>
[Advanced]
 <prev [Thread] next>

[Bacula-users] Problems with Max vol Jobs & Recycled Volume

2009-04-30 04:37:21
Subject: [Bacula-users] Problems with Max vol Jobs & Recycled Volume
From: Jérémy Chaumont <jeremy.chaumont AT sis-ca DOT fr>
To: <bacula-users AT lists.sourceforge DOT net>
Date: Thu, 30 Apr 2009 10:31:25 +0200

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

 

 

 

 

 

Attachment: 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 AT lists.sourceforge DOT net
https://lists.sourceforge.net/lists/listinfo/bacula-users
[More with this subject...]
<Prev in Thread] Current Thread [Next in Thread>
  • [Bacula-users] Problems with Max vol Jobs & Recycled Volume, Jérémy Chaumont <=
Previous by Date:  Re: [Bacula-users] Does "Duplicate Jobs" interact with backup level?, Silver Salonen
Next by Date:  Re: [Bacula-users] Autochanger problem, Mordechai T. Abzug
Previous by Thread:  [Bacula-users] Bacula-users Digest, Vol 36, Issue 38, digithead
Next by Thread:  [Bacula-users] minimizing full backups, Silver Salonen
Indexes:  [Date] [Thread] [Top] [All Lists]