On Wednesday 29 March 2006 20:53, Kern Sibbald wrote:
> > I think the jobs "full.2006-03-27_17.30.00",
> > "catalog.2006-03-27_17.30.01" and "closing.2006-03-27_17.30.02" should
> > all have been cancelled on the 28th, 15:30 (17:30 + timeout of 22 hours).
> >
> > MfG, Ulrich
>
> In looking at the output, I see no evidence that the messages are out of
> order or intermingled as I understood you were saying.
It is possible that I just don't understand the docs. But if a job is
scheduled for 17:30 and has a max start delay of 22 hours, shouldn't it
be cancelled at 15:30 the next day?
Scheduling and running of jobs is not logged, so the log is not as clear
as it could be. But e.g. the job "catalog.2006-03-27_17.30.01" was
not cancelled on 2006-03-28 15.30.01, but instead on 2006-03-28 at
19.16.06, /after/ another job, "full.2006-03-28_17.30.00" was completed,
although that job was scheduled a whole day later.
The mails are sent in the same order: success of full.2006-03-28_17.30.00,
failure of catalog.2006-03-27_17.30.01, success of catalog.2006-03-28_17.30.01
...
The "status director" command does show the same order:
Terminated Jobs:
JobId Level Files Bytes Status Finished Name
========================================================================
3 Full 803,049 172,003,756,473 OK 28-Mar-06 17:34 full
4 Incr 0 0 Error 28-Mar-06 17:34 full
7 Incr 9,788 5,295,056,880 OK 28-Mar-06 19:16 full
5 Full 0 0 Error 28-Mar-06 19:16 catalog
8 Full 1 101,405,753 OK 28-Mar-06 19:18 catalog
6 0 0 Error 28-Mar-06 19:18 closing
9 0 0 OK 28-Mar-06 19:19 closing
JobId 3 was the full backup I started manually, ids 4, 5 and 6 were
run on the same day, 7, 8 and 9 the next day.
>
> Unfortunately, the output end of line caracters were either removed or
> lost. This resulted in very long lines that were apparently truncated on
> your end, and so I could not see exactly what was going on as the end of
> each job report is missing. However, with what I see, it seems to me that
That is because I prefer to use syslog. Those long lines are just standard
completion notifications; I can't see anything unusual. I've appended them
anyway; please note the respective dates.
> despite the message that says that the jobs were canceled (apparently at
> the correct time), I see no evidence that they were actually canceled.
The log says e.g.:
Mar 28 17:34:22 mail bacula-dir: mail-dir: full.2006-03-27_17.30.00 Fatal
error: Job canceled because max start delay time exceeded.
What more should there be? And that cancellation should have been at 15:30:00.
MfG, Ulrich
--
Heinz Ulrich Stille / Tel.: +49-541-9400473 / Fax: +49-541-9400450
design_d gmbh / Wilhelmstr. 16 / 49076 Osnabrück / www.design-d.de
--- Begin Message ---
28-Mar 19:16 mail-dir: catalog.2006-03-27_17.30.01 Fatal error: Job canceled
because max start delay time exceeded.
28-Mar 19:16 mail-dir: No prior Full backup Job record found.
28-Mar 19:16 mail-dir: No prior or suitable Full backup found. Doing FULL
backup.
--- End Message ---
--- Begin Message ---
27-Mar 11:47 mail-dir: Start Backup JobId 3, Job=full.2006-03-27_11.47.02
27-Mar 11:47 mail-sd: full.2006-03-27_11.47.02 Warning: Director wanted Volume
"w02".
Current Volume "Mo" not acceptable because:
1998 Volume "Mo" status is Append, not in Pool.
27-Mar 11:47 mail-sd: Please mount Volume "w02" on Storage Device "DLT"
(/dev/nst0) for Job full.2006-03-27_11.47.02
27-Mar 11:59 mail-dir: Recycled current volume "w01"
27-Mar 11:59 mail-sd: Recycled volume "w01" on device "DLT" (/dev/nst0), all
previous data lost.
mail-fd: Filesystem change prohibited. Will not descend into /dev
mail-fd: Filesystem change prohibited. Will not descend into /sysfs
mail-fd: Filesystem change prohibited. Will not descend into /proc
mail-fd: Filesystem change prohibited. Will not descend into /var
mail-fd: Filesystem change prohibited. Will not descend into /export
mail-fd: Filesystem change prohibited. Will not descend into /sys
mail-fd: Filesystem change prohibited. Will not descend into
/var/lib/nfs/rpc_pipefs
mail-fd: Filesystem change prohibited. Will not descend into
/var/named/chroot/proc
27-Mar 15:59 mail-sd: End of Volume "w01" at 46:10244 on device "DLT"
(/dev/nst0). Write of 64512 bytes got -1.
27-Mar 16:00 mail-sd: Re-read of last block succeeded.
27-Mar 16:00 mail-sd: End of medium on Volume "w01" Bytes=46,657,914,977
Blocks=723,244 at 27-Mar-2006 16:00.
27-Mar 16:00 mail-sd: Please mount Volume "w02" on Storage Device "DLT"
(/dev/nst0) for Job full.2006-03-27_11.47.02
27-Mar 16:01 mail-sd: full.2006-03-27_11.47.02 Warning: Director wanted Volume
"w02".
Current Volume "w01" not acceptable because:
1998 Volume "w01" status is Full, but should be Append, Purged or Recycle.
27-Mar 16:26 mail-sd: Wrote label to prelabeled Volume "w02" on device "DLT"
(/dev/nst0)
27-Mar 16:26 mail-sd: New volume "w02" mounted on device "DLT" (/dev/nst0) at
27-Mar-2006 16:26.
27-Mar 20:11 mail-sd: End of Volume "w02" at 45:433 on device "DLT"
(/dev/nst0). Write of 64512 bytes got -1.
27-Mar 20:13 mail-sd: Re-read of last block succeeded.
27-Mar 20:13 mail-sd: End of medium on Volume "w02" Bytes=45,025,052,675
Blocks=697,933 at 27-Mar-2006 20:13.
27-Mar 20:13 mail-sd: Please mount Volume "w03" on Storage Device "DLT"
(/dev/nst0) for Job full.2006-03-27_11.47.02
27-Mar 20:14 mail-sd: full.2006-03-27_11.47.02 Warning: Director wanted Volume
"w03".
Current Volume "w02" not acceptable because:
1998 Volume "w02" status is Full, but should be Append, Purged or Recycle.
27-Mar 21:09 mail-sd: Wrote label to prelabeled Volume "w03" on device "DLT"
(/dev/nst0)
27-Mar 21:09 mail-sd: New volume "w03" mounted on device "DLT" (/dev/nst0) at
27-Mar-2006 21:09.
28-Mar 00:25 mail-sd: End of Volume "w03" at 44:10286 on device "DLT"
(/dev/nst0). Write of 64512 bytes got -1.
28-Mar 00:26 mail-sd: Re-read of last block succeeded.
28-Mar 00:26 mail-sd: End of medium on Volume "w03" Bytes=44,660,753,565
Blocks=692,286 at 28-Mar-2006 00:26.
28-Mar 00:26 mail-sd: Please mount Volume "w04" on Storage Device "DLT"
(/dev/nst0) for Job full.2006-03-27_11.47.02
28-Mar 00:27 mail-sd: full.2006-03-27_11.47.02 Warning: Director wanted Volume
"w04".
Current Volume "w03" not acceptable because:
1998 Volume "w03" status is Full, but should be Append, Purged or Recycle.
28-Mar 01:31 mail-sd: Please mount Volume "w04" on Storage Device "DLT"
(/dev/nst0) for Job full.2006-03-27_11.47.02
28-Mar 03:42 mail-sd: Please mount Volume "w04" on Storage Device "DLT"
(/dev/nst0) for Job full.2006-03-27_11.47.02
28-Mar 08:04 mail-sd: Please mount Volume "w04" on Storage Device "DLT"
(/dev/nst0) for Job full.2006-03-27_11.47.02
28-Mar 08:21 mail-sd: Wrote label to prelabeled Volume "w04" on device "DLT"
(/dev/nst0)
28-Mar 08:21 mail-sd: New volume "w04" mounted on device "DLT" (/dev/nst0) at
28-Mar-2006 08:21.
28-Mar 17:34 mail-dir: Bacula 1.38.5 (18Jan06): 28-Mar-2006 17:34:15
JobId: 3
Job: full.2006-03-27_11.47.02
Backup Level: Full
Client: "mail-fd" i686-pc-linux-gnu,redhat,(Rawhide)
FileSet: "full" 2006-03-26 00:53:58
Pool: "Weekly"
Storage: "Tape"
Scheduled time: 27-Mar-2006 11:46:40
Start time: 27-Mar-2006 11:47:04
End time: 28-Mar-2006 17:34:15
Priority: 10
FD Files Written: 803,049
SD Files Written: 803,049
FD Bytes Written: 172,003,756,473
SD Bytes Written: 172,116,756,062
Rate: 1604.0 KB/s
Software Compression: None
Volume name(s): w01|w02|w03|w04
Volume Session Id: 3
Volume Session Time: 1143310217
Last Volume Bytes: 35,923,416,643
Non-fatal FD errors: 0
SD Errors: 0
FD termination status: OK
SD termination status: OK
Termination: Backup OK
28-Mar 17:34 mail-dir: Begin pruning Jobs.
28-Mar 17:34 mail-dir: No Jobs found to prune.
28-Mar 17:34 mail-dir: Begin pruning Files.
28-Mar 17:34 mail-dir: No Files found to prune.
28-Mar 17:34 mail-dir: End auto prune.
--- End Message ---
--- Begin Message ---
28-Mar 17:34 mail-dir: full.2006-03-27_17.30.00 Fatal error: Job canceled
because max start delay time exceeded.
--- End Message ---
--- Begin Message ---
28-Mar 17:34 mail-dir: Start Backup JobId 7, Job=full.2006-03-28_17.30.00
28-Mar 17:34 mail-sd: full.2006-03-28_17.30.00 Warning: Director wanted Volume
"Mo".
Current Volume "w04" not acceptable because:
1998 Volume "w04" status is Append, not in Pool.
28-Mar 17:34 mail-sd: Please mount Volume "Mo" on Storage Device "DLT"
(/dev/nst0) for Job full.2006-03-28_17.30.00
28-Mar 18:32 mail-sd: Wrote label to prelabeled Volume "Mo" on device "DLT"
(/dev/nst0)
mail-fd: Filesystem change prohibited. Will not descend into /dev
mail-fd: Filesystem change prohibited. Will not descend into /sysfs
mail-fd: Filesystem change prohibited. Will not descend into /proc
mail-fd: Filesystem change prohibited. Will not descend into /var
mail-fd: Filesystem change prohibited. Will not descend into /export
mail-fd: Filesystem change prohibited. Will not descend into /sys
mail-fd: Filesystem change prohibited. Will not descend into
/var/lib/nfs/rpc_pipefs
mail-fd: Filesystem change prohibited. Will not descend into
/var/named/chroot/proc
28-Mar 19:16 mail-dir: Bacula 1.38.5 (18Jan06): 28-Mar-2006 19:16:02
JobId: 7
Job: full.2006-03-28_17.30.00
Backup Level: Incremental, since=2006-03-27 11:47:04
Client: "mail-fd" i686-pc-linux-gnu,redhat,(Rawhide)
FileSet: "full" 2006-03-26 00:53:58
Pool: "Daily"
Storage: "Tape"
Scheduled time: 28-Mar-2006 17:30:00
Start time: 28-Mar-2006 17:34:25
End time: 28-Mar-2006 19:16:02
Priority: 10
FD Files Written: 9,788
SD Files Written: 9,788
FD Bytes Written: 5,295,056,880
SD Bytes Written: 5,296,341,639
Rate: 868.5 KB/s
Software Compression: None
Volume name(s): Mo
Volume Session Id: 4
Volume Session Time: 1143310217
Last Volume Bytes: 5,300,566,960
Non-fatal FD errors: 0
SD Errors: 0
FD termination status: OK
SD termination status: OK
Termination: Backup OK
28-Mar 19:16 mail-dir: Begin pruning Jobs.
28-Mar 19:16 mail-dir: No Jobs found to prune.
28-Mar 19:16 mail-dir: Begin pruning Files.
28-Mar 19:16 mail-dir: No Files found to prune.
28-Mar 19:16 mail-dir: End auto prune.
--- End Message ---
--- Begin Message ---
28-Mar 19:16 mail-dir: No prior Full backup Job record found.
28-Mar 19:16 mail-dir: No prior or suitable Full backup found. Doing FULL
backup.
28-Mar 19:16 mail-dir: Start Backup JobId 8, Job=catalog.2006-03-28_17.30.01
28-Mar 19:16 mail-sd: Volume "Mo" previously written, moving to end of data.
28-Mar 19:17 mail-sd: Ready to append to end of Volume "Mo" at file=6.
28-Mar 19:18 mail-dir: Bacula 1.38.5 (18Jan06): 28-Mar-2006 19:18:45
JobId: 8
Job: catalog.2006-03-28_17.30.01
Backup Level: Full (upgraded from Incremental)
Client: "mail-fd" i686-pc-linux-gnu,redhat,(Rawhide)
FileSet: "Catalog" 2006-03-28 19:16:06
Pool: "Daily"
Storage: "Tape"
Scheduled time: 28-Mar-2006 17:30:00
Start time: 28-Mar-2006 19:16:10
End time: 28-Mar-2006 19:18:45
Priority: 50
FD Files Written: 1
SD Files Written: 1
FD Bytes Written: 101,405,753
SD Bytes Written: 101,405,868
Rate: 654.2 KB/s
Software Compression: None
Volume name(s): Mo
Volume Session Id: 5
Volume Session Time: 1143310217
Last Volume Bytes: 5,402,048,422
Non-fatal FD errors: 0
SD Errors: 0
FD termination status: OK
SD termination status: OK
Termination: Backup OK
28-Mar 19:18 mail-dir: Begin pruning Jobs.
28-Mar 19:18 mail-dir: No Jobs found to prune.
28-Mar 19:18 mail-dir: Begin pruning Files.
28-Mar 19:18 mail-dir: No Files found to prune.
28-Mar 19:18 mail-dir: End auto prune.
--- End Message ---
--- Begin Message ---
28-Mar 19:18 mail-dir: closing.2006-03-27_17.30.02 Fatal error: Job canceled
because max start delay time exceeded.
--- End Message ---
--- Begin Message ---
28-Mar 19:18 mail-dir: Start Admin JobId 9, Job=closing.2006-03-28_17.30.02
28-Mar 19:18 mail-dir: Bacula 1.38.5 (18Jan06): 28-Mar-2006 19:18
JobId: 9
Job: closing.2006-03-28_17.30.02
Start time: 28-Mar-2006 19:18
End time: 28-Mar-2006 19:18
Termination: Admin OK
28-Mar 19:18 mail-dir: Begin pruning Jobs.
28-Mar 19:18 mail-dir: No Jobs found to prune.
28-Mar 19:18 mail-dir: Begin pruning Files.
28-Mar 19:18 mail-dir: No Files found to prune.
28-Mar 19:18 mail-dir: End auto prune.
--- End Message ---
