The scheduled backup happened to behave strangely tonight, causing an incomplete backup.
Five Jobs are scheduled starting at 21:30, with 5 mins difference each.
The Volume for tonight was inserted correctly.
I see the message "Volume recycled" at 22:36, one hour later than the first scheduled job, causing one hour wait, then Bacula still waits many hours (until 7:35 morning) asking for the volume, then it finally says "Recycled volume xxx on device yyy" and starts backup 10 hours in late, meanwhile starting to cancel jobs because MaxWaitTime or MaxUsedTime was reached....
I am almost sure that the volume was in Used or Recycle state yesterday evening, and I suspect Bacula was not mounting the inserted volume, like if it was empty, until 7:35.....
How can this happen?.... is there any possible build bug on Solaris 10 (I built it by myself)?
Here is the output of "messages":
28-Oct 21:35 iserver-dir: Start Backup JobId 150, Job=Enterprise_Backup_ISERVER.2005-10-28_21.35.00
28-Oct 21:36 iserver-dir: Pruned 5 Jobs on Volume "VENERDI" from catalog.
28-Oct 21:36 iserver-sd: Job Enterprise_Backup_ISERVER.2005-10-28_21.35.00 waiting. Cannot find any appendable volumes.
Please use the "label" command to create a new Volume for:
Storage: QUANTUM
Media type: LTO
Pool: FridayPool
28-Oct 22:36 iserver-dir: There are no Jobs associated with Volume "VENERDI". Marking it purged.
28-Oct 22:36 iserver-dir: Recycled volume "VENERDI"
28-Oct 22:36 iserver-sd: Please mount Volume "VENERDI" on Storage Device "QUANTUM" for Job Enterprise_Backup_ISERVER.2005-10-28_21.35.00
Use "mount" command to release Job.
29-Oct 00:36 iserver-sd: Please mount Volume "VENERDI" on Storage Device "QUANTUM" for Job Enterprise_Backup_ISERVER.2005-10-28_21.35.00
Use "mount" command to release Job.
29-Oct 04:36 iserver-sd: Please mount Volume "VENERDI" on Storage Device "QUANTUM" for Job Enterprise_Backup_ISERVER.2005-10-28_21.35.00
Use "mount" command to release Job.
29-Oct 07:35 iserver-dir: 2001 Job Enterprise_Backup_ISERVER.2005-10-28_21.35.00 marked to be canceled.
29-Oct 07:35 iserver-dir: 3000 Job Enterprise_Backup_ISERVER.2005-10-28_21.35.00 marked to be canceled.
29-Oct 07:35 iserver-dir: Bacula 1.36.2 (28Feb05): 29-Oct-2005 07:35:21
JobId: 150
Job: Enterprise_Backup_ISERVER.2005-10-28_21.35.00
.............
.............
FD termination status: Canceled
SD termination status: Canceled
Termination: Backup Canceled
29-Oct 07:35 iserver-dir: Start Backup JobId 151, Job=Enterprise_Backup_SMARTLINK.2005-10-28_21.40.00
29-Oct 07:35 iserver-sd: Recycled volume "VENERDI" on device "/dev/rst20", all previous data lost.
29-Oct 07:45 iserver-dir: JobId 152, Job Enterprise_Backup_MACDUE.2005-10-28_21.45.00 marked to be canceled.
29-Oct 07:50 iserver-dir: JobId 153, Job Enterprise_Backup_OFFICE.2005-10-28_21.50.00 marked to be canceled.
29-Oct 07:58 iserver-dir: Bacula 1.36.2 (28Feb05): 29-Oct-2005 07:58:00
JobId: 151
Job: Enterprise_Backup_SMARTLINK.2005-10-28_21.40.00
.............
.............
FD termination status: OK
SD termination status: OK
Termination: Backup OK
29-Oct 07:58 iserver-dir: Begin pruning Jobs.
29-Oct 07:58 iserver-dir: No Jobs found to prune.
29-Oct 07:58 iserver-dir: Begin pruning Files.
29-Oct 07:58 iserver-dir: No Files found to prune.
29-Oct 07:58 iserver-dir: End auto prune.
29-Oct 07:58 iserver-dir: Start Backup JobId 154, Job=Catalog_Backup.2005-10-28_22.15.00
29-Oct 07:58 iserver-sd: Volume "VENERDI" previously written, moving to end of data.
29-Oct 08:00 iserver-sd: Ready to append to end of Volume "VENERDI" at file=10.
29-Oct 08:02 iserver-dir: Bacula 1.36.2 (28Feb05): 29-Oct-2005 08:02:30
JobId: 154
Job: Catalog_Backup.2005-10-28_22.15.00
.............
.............
FD termination status: OK
SD termination status: OK
Termination: Backup OK
29-Oct 08:02 iserver-dir: Begin pruning Jobs.
29-Oct 08:02 iserver-dir: No Jobs found to prune.
29-Oct 08:02 iserver-dir: Begin pruning Files.
29-Oct 08:02 iserver-dir: No Files found to prune.
29-Oct 08:02 iserver-dir: End auto prune.
Five Jobs are scheduled starting at 21:30, with 5 mins difference each.
The Volume for tonight was inserted correctly.
I see the message "Volume recycled" at 22:36, one hour later than the first scheduled job, causing one hour wait, then Bacula still waits many hours (until 7:35 morning) asking for the volume, then it finally says "Recycled volume xxx on device yyy" and starts backup 10 hours in late, meanwhile starting to cancel jobs because MaxWaitTime or MaxUsedTime was reached....
I am almost sure that the volume was in Used or Recycle state yesterday evening, and I suspect Bacula was not mounting the inserted volume, like if it was empty, until 7:35.....
How can this happen?.... is there any possible build bug on Solaris 10 (I built it by myself)?
Here is the output of "messages":
28-Oct 21:35 iserver-dir: Start Backup JobId 150, Job=Enterprise_Backup_ISERVER.2005-10-28_21.35.00
28-Oct 21:36 iserver-dir: Pruned 5 Jobs on Volume "VENERDI" from catalog.
28-Oct 21:36 iserver-sd: Job Enterprise_Backup_ISERVER.2005-10-28_21.35.00 waiting. Cannot find any appendable volumes.
Please use the "label" command to create a new Volume for:
Storage: QUANTUM
Media type: LTO
Pool: FridayPool
28-Oct 22:36 iserver-dir: There are no Jobs associated with Volume "VENERDI". Marking it purged.
28-Oct 22:36 iserver-dir: Recycled volume "VENERDI"
28-Oct 22:36 iserver-sd: Please mount Volume "VENERDI" on Storage Device "QUANTUM" for Job Enterprise_Backup_ISERVER.2005-10-28_21.35.00
Use "mount" command to release Job.
29-Oct 00:36 iserver-sd: Please mount Volume "VENERDI" on Storage Device "QUANTUM" for Job Enterprise_Backup_ISERVER.2005-10-28_21.35.00
Use "mount" command to release Job.
29-Oct 04:36 iserver-sd: Please mount Volume "VENERDI" on Storage Device "QUANTUM" for Job Enterprise_Backup_ISERVER.2005-10-28_21.35.00
Use "mount" command to release Job.
29-Oct 07:35 iserver-dir: 2001 Job Enterprise_Backup_ISERVER.2005-10-28_21.35.00 marked to be canceled.
29-Oct 07:35 iserver-dir: 3000 Job Enterprise_Backup_ISERVER.2005-10-28_21.35.00 marked to be canceled.
29-Oct 07:35 iserver-dir: Bacula 1.36.2 (28Feb05): 29-Oct-2005 07:35:21
JobId: 150
Job: Enterprise_Backup_ISERVER.2005-10-28_21.35.00
.............
.............
FD termination status: Canceled
SD termination status: Canceled
Termination: Backup Canceled
29-Oct 07:35 iserver-dir: Start Backup JobId 151, Job=Enterprise_Backup_SMARTLINK.2005-10-28_21.40.00
29-Oct 07:35 iserver-sd: Recycled volume "VENERDI" on device "/dev/rst20", all previous data lost.
29-Oct 07:45 iserver-dir: JobId 152, Job Enterprise_Backup_MACDUE.2005-10-28_21.45.00 marked to be canceled.
29-Oct 07:50 iserver-dir: JobId 153, Job Enterprise_Backup_OFFICE.2005-10-28_21.50.00 marked to be canceled.
29-Oct 07:58 iserver-dir: Bacula 1.36.2 (28Feb05): 29-Oct-2005 07:58:00
JobId: 151
Job: Enterprise_Backup_SMARTLINK.2005-10-28_21.40.00
.............
.............
FD termination status: OK
SD termination status: OK
Termination: Backup OK
29-Oct 07:58 iserver-dir: Begin pruning Jobs.
29-Oct 07:58 iserver-dir: No Jobs found to prune.
29-Oct 07:58 iserver-dir: Begin pruning Files.
29-Oct 07:58 iserver-dir: No Files found to prune.
29-Oct 07:58 iserver-dir: End auto prune.
29-Oct 07:58 iserver-dir: Start Backup JobId 154, Job=Catalog_Backup.2005-10-28_22.15.00
29-Oct 07:58 iserver-sd: Volume "VENERDI" previously written, moving to end of data.
29-Oct 08:00 iserver-sd: Ready to append to end of Volume "VENERDI" at file=10.
29-Oct 08:02 iserver-dir: Bacula 1.36.2 (28Feb05): 29-Oct-2005 08:02:30
JobId: 154
Job: Catalog_Backup.2005-10-28_22.15.00
.............
.............
FD termination status: OK
SD termination status: OK
Termination: Backup OK
29-Oct 08:02 iserver-dir: Begin pruning Jobs.
29-Oct 08:02 iserver-dir: No Jobs found to prune.
29-Oct 08:02 iserver-dir: Begin pruning Files.
29-Oct 08:02 iserver-dir: No Files found to prune.
29-Oct 08:02 iserver-dir: End auto prune.
|
|
|
Gabriele Bulfon - Sonicle S.r.l. Tel +39 028246016 Int. 30 - Fax +39 028243880 Via Felice Cavallotti 16 - 20089, Rozzano - Milano - ITALY http://www.sonicle.com |
