Hi,
On 4/11/2007 2:46 PM, 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.
This should meant that effectively only that one job was active. It
looks something went wrong in the volume selection process, or - ah,
inspiration! - you did a 'status dir' while the tape was already
reserved for the job but not actually accessed AND the DIR needed to
trigger recycling etc., which in turn activated the pruning / volume use
time checks... just a wild idea. Or, to finish the thought, you have a
misconfiguration, wrong volume metadata, or a catalog problem, perhaps
time-related. Which is what we discussed and everything looks good.
Arno
> 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?
>
> -------------------------------------------------------------------------
> 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
--
IT-Service Lehmann [EMAIL PROTECTED]
Arno Lehmann http://www.its-lehmann.de
-------------------------------------------------------------------------
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
