On Wednesday 11 April 2007 14:46, Ralf Gross wrote:
> Kern Sibbald schrieb:
> > > > At them moment I would consider this as a bug, but I would like to
> > > > here Kern's opinion on this before I open a bug report.
> > >
> > > ... to confirm that assumption and give Kern something to work on.
> >
> > >From this email, I would probably close the bug report right away. I
don't
> > have any idea what system it is, what version of Bacula, nor do I see any
> > output generated by Bacula. "llist volume=xxx" is best not a raw copy of
> > some stdin. Also, there is no job output showing what happened with the
> > volume before, during and after its status was changed.
>
> Sorry Kern, you seem to have missed my first mail in this thread.
>
> (Message-ID: <[EMAIL PROTECTED]>, Date:
> 2007-04-10 07:29:05 GMT)
>
> I'll cut & paste it again. If it's still missing important information,
please
> let me know.
>
> ######
>
> Hi,
>
> bacula-dir 2.0.3, bacula-sd 2.0.3, bacula-fd 2.0.2, debian etch amd64,
> postgres 8.1.7
>
> Bacula is running fine here for a while. But this weekend bacula
> chose to use fresh tape from the scratch pool for job #2 of a diff backup
> instead of appending the data to the tape it was writing to a few
> minutes before by the first of the two jobs.
>
> Here are the two jobs:
>
> Job {
> Name = "SMTCZB0003"
> Type = Backup
> Client = SMTCZB0003
> FileSet = "SMTCZB0003"
> Schedule = "Regular Backup"
> Storage = NEC-T40A
> Messages = "Regular Backup"
> Pool = Default
> SpoolData=yes
> Write Bootstrap = "/opt/bacula/var/bacula/working/SMTCZB0003.bsr"
> Priority = 5
> RunBeforeJob = "/usr/bin/ssh [snip]"
> RunAfterJob = "/usr/bin/ssh [snip]"
> }
>
> Job {
> Name = "VU0EM003"
> Type = Backup
> Client = VU0EM003
> FileSet = "VU0EM003 Full"
> Schedule = "Regular Backup"
> Storage = NEC-T40A
> Messages = "Regular Backup"
> Pool = Default
> SpoolData=yes
> Write Bootstrap = "/opt/bacula/var/bacula/working/VU0EM003.bsr"
> Priority = 10
> }
>
> ..and the schedule:
>
> Schedule {
> Name = "Regular Backup"
> Run = Level=Full Pool=Full 1st sun at 00:05
> Run = Level=Differential Pool=Differential FullPool=Full 2nd-5th sun at
00:05
> Run = Level=Incremental Pool=Incremental DifferentialPool=Differential
FullPool=Full tue-sat at 00:05
> }
>
> Both jobs have the same start time, but different priorities.
>
> llist volumes shows
>
> volretention: 2,678,400 <--- (31 days)
> voluseduration: 345,600 <--- (4 days)
>
> for all tapes in the diff pool
>
> This is what happend this weekend:
>
> Job #1:
>
> 08-Apr 00:05 VU0EM005: BeforeJob: run command "/usr/bin/ssh [snip]"
> 08-Apr 00:07 VU0EM005: Start Backup JobId 121,
Job=SMTCZB0003.2007-04-08_00.05.00
> 08-Apr 00:08 VU0EM005: 3307 Issuing autochanger "unload slot 4, drive 0"
command.
> 08-Apr 00:09 VU0EM005: 3304 Issuing autochanger "load slot 5, drive 0"
command.
> 08-Apr 00:10 VU0EM005: 3305 Autochanger "load slot 5, drive 0", status is
OK.
> 08-Apr 00:10 VU0EM005: 3301 Issuing autochanger "loaded? drive 0" command.
> 08-Apr 00:10 VU0EM005: 3302 Autochanger "loaded? drive 0", result is Slot 5.
> 08-Apr 00:10 VU0EM005: Recycled volume "06D124L3" on device "LTO3"
(/dev/nst0), all previous data lost.
>
> That's fine, I expected volume 06D124L3 to be overwritten at this time.
>
> 08-Apr 00:10 VU0EM005: Max configured use duration exceeded. Marking
Volume "06D124L3" as Used.
>
> But I don't know what happend at this point. Why does bacula mark volume
> 06D124L3 as used right after the job started. The configured duration time
> is 4 days, I checked this.
>
> 08-Apr 00:10 VU0EM005: Spooling data ...
> SMTCZB0003-fd: Filesystem change prohibited. Will not descend
into /var/lib/nfs/rpc_pipefs
> SMTCZB0003-fd: Filesystem change prohibited. Will not descend into /dev
> SMTCZB0003-fd: Filesystem change prohibited. Will not descend into /sys
> SMTCZB0003-fd: Filesystem change prohibited. Will not descend
into /boot
> 08-Apr 00:12 VU0EM005: Job write elapsed time = 00:02:23, Transfer rate =
6.766 M bytes/second
> 08-Apr 00:12 VU0EM005: Committing spooled data to Volume "06D124L3".
Despooling 968,636,754 bytes ...
> 08-Apr 00:12 VU0EM005: Despooling elapsed time = 00:00:07, Transfer rate =
138.3 M bytes/second
> 08-Apr 00:12 VU0EM005: Sending spooled attrs to the Director. Despooling
1,543,784 bytes ...
> 08-Apr 00:12 VU0EM005: AfterJob: run command "/usr/bin/ssh [snip]"
> 08-Apr 00:12 VU0EM005: Bacula 2.0.3 (06Mar07): 08-Apr-2007 00:12:47
> JobId: 121
> Job: SMTCZB0003.2007-04-08_00.05.00
> Backup Level: Differential, since=2007-04-01 00:07:10
> Client: "SMTCZB0003" i686-pc-linux-gnu,redhat,Enterprise
release
> FileSet: "SMTCZB0003" 2007-02-20 22:25:00
> Pool: "Differential" (From Run pool override)
> Storage: "NEC-T40A" (From Job resource)
> Scheduled time: 08-Apr-2007 00:05:00
> Start time: 08-Apr-2007 00:07:08
> End time: 08-Apr-2007 00:12:47
> Elapsed time: 5 mins 39 secs
> Priority: 5
> FD Files Written: 4,807
> SD Files Written: 4,807
> FD Bytes Written: 966,711,641 (966.7 MB)
> SD Bytes Written: 967,611,394 (967.6 MB)
> Rate: 2851.7 KB/s
> Software Compression: None
> VSS: no
> Encryption: no
> Volume name(s): 06D124L3
> Volume Session Id: 40
> Volume Session Time: 1174319761
> Last Volume Bytes: 968,583,168 (968.5 MB)
> Non-fatal FD errors: 0
> SD Errors: 0
> FD termination status: OK
> SD termination status: OK
> Termination: Backup OK
>
> 08-Apr 00:12 VU0EM005: Begin pruning Jobs.
> 08-Apr 00:12 VU0EM005: No Jobs found to prune.
> 08-Apr 00:12 VU0EM005: Begin pruning Files.
> 08-Apr 00:12 VU0EM005: Pruned Files from 1 Jobs for client SMTCZB0003 from
catalog.
> 08-Apr 00:12 VU0EM005: End auto prune.
>
> Job #2:
>
> 08-Apr 00:12 VU0EM005: Start Backup JobId 122,
Job=VU0EM003.2007-04-08_00.05.01
> 08-Apr 00:12 VU0EM005: Using Volume "06D137L3" from 'Scratch' pool.
>
> Ok, here bacula decided to use a volumes from the scratch pool, because
> 06D124L3 was marked as used a few minutes ago.
>
> 08-Apr 00:12 VU0EM005: 3307 Issuing autochanger "unload slot 5, drive 0"
command.
> 08-Apr 00:13 VU0EM005: 3304 Issuing autochanger "load slot 18, drive 0"
command.
> 08-Apr 00:14 VU0EM005: 3305 Autochanger "load slot 18, drive 0", status is
OK.
> 08-Apr 00:14 VU0EM005: 3301 Issuing autochanger "loaded? drive 0" command.
> 08-Apr 00:14 VU0EM005: 3302 Autochanger "loaded? drive 0", result is Slot
18.
> 08-Apr 00:14 VU0EM005: Wrote label to prelabeled Volume "06D137L3" on
device "LTO3" (/dev/nst0)
> 08-Apr 00:14 VU0EM005: Spooling data ...
> VU0EM003: /home is a different filesystem. Will not descend from /
into /home
> VU0EM003: /public is a different filesystem. Will not descend from /
into /public
> VU0EM003: /lib/init/rw is a different filesystem. Will not descend
from / into /lib/init/rw
> VU0EM003: /server is a different filesystem. Will not descend from /
into /server
> 08-Apr 00:16 VU0EM005: Job write elapsed time = 00:02:29, Transfer rate =
22.33 M bytes/second
> 08-Apr 00:16 VU0EM005: Committing spooled data to Volume "06D137L3".
Despooling 3,331,622,332 bytes ...
> 08-Apr 00:17 VU0EM005: Despooling elapsed time = 00:00:47, Transfer rate =
70.88 M bytes/second
> 08-Apr 00:17 VU0EM005: Sending spooled attrs to the Director. Despooling
3,858,055 bytes ...
> 08-Apr 00:17 VU0EM005: Bacula 2.0.3 (06Mar07): 08-Apr-2007 00:17:46
> JobId: 122
> Job: VU0EM003.2007-04-08_00.05.01
> Backup Level: Differential, since=2007-04-01 02:09:55
> Client: "VU0EM003" 2.0.2 (28Jan07)
x86_64-unknown-linux-gnu,debian,4.0
> FileSet: "VU0EM003 Full" 2007-02-25 16:22:49
> Pool: "Differential" (From Run pool override)
> Storage: "NEC-T40A" (From Job resource)
> Scheduled time: 08-Apr-2007 00:05:00
> Start time: 08-Apr-2007 00:12:51
> End time: 08-Apr-2007 00:17:46
> Elapsed time: 4 mins 55 secs
> Priority: 10
> FD Files Written: 12,681
> SD Files Written: 12,681
> FD Bytes Written: 3,325,991,618 (3.325 GB)
> SD Bytes Written: 3,327,999,098 (3.327 GB)
> Rate: 11274.5 KB/s
> Software Compression: None
> VSS: no
> Encryption: no
> Volume name(s): 06D137L3
> Volume Session Id: 41
> Volume Session Time: 1174319761
> Last Volume Bytes: 3,331,077,120 (3.331 GB)
> Non-fatal FD errors: 0
> SD Errors: 0
> FD termination status: OK
> SD termination status: OK
> Termination: Backup OK
>
> 08-Apr 00:17 VU0EM005: Begin pruning Jobs.
> 08-Apr 00:17 VU0EM005: No Jobs found to prune.
> 08-Apr 00:17 VU0EM005: Begin pruning Files.
> 08-Apr 00:17 VU0EM005: Pruned Files from 1 Jobs for client VU0EM003 from
catalog.
> 08-Apr 00:17 VU0EM005: End auto prune.
>
> Here's the shortened 'list volumes' output from today:
>
>
+-------+----------+---------+--------------+------------+-------+-------------------+
> |mediaid|volumename|volstatus|volbytes |volretention|recycle|
lastwritten |
>
+-------+----------+---------+--------------+------------+-------+-------------------+
> | 5 |06D124L3 |Used | 968,583,168| 2,678,400 | 1|2007-04-08
00:12:44|
> | 6 |06D125L3 |Used |17,191,802,880| 2,678,400 | 1|2007-03-11
00:33:24|
> | 7 |06D126L3 |Used | 6,299,725,824| 2,678,400 | 1|2007-03-19
21:07:48|
> | 8 |06D127L3 |Used | 9,633,254,400| 2,678,400 | 1|2007-03-25
00:22:52|
> | 19 |06D137L3 |Append | 3,497,001,984| 2,678,400 | 1|2007-04-08
00:18:03|
>
+-------+----------+---------+--------------+------------+-------+-------------------+
>
> The main question is, why did bacula mark volumes 06D124L3 as used right
after
> the first job started when the voluseduration is set to 4 days?
I'm not sure that recycling a volume resets its use duration. Perhaps the use
duration expired at about the time or just after when the volume was
recycled.
-------------------------------------------------------------------------
Take Surveys. Earn Cash. Influence the Future of IT
Join SourceForge.net's Techsay panel and you'll get the chance to share your
opinions on IT & business topics through brief surveys-and earn cash
http://www.techsay.com/default.php?page=join.php&p=sourceforge&CID=DEVDEV
_______________________________________________
Bacula-users mailing list
Bacula-users@lists.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/bacula-users
