...with -d99999, here are the relevant decision making parts: Without looking at the code, I think this may be a database error related to:
mindwipe-dir: postgresql.c:334 my_postgresql_fetch_row finishes
returning 8128018^M
mindwipe-dir: next_vol.c:62 catreq after find_next_vol ok=1 FW=0^M
mindwipe-dir: next_vol.c:175 VolJobs=1 FirstWritten=0^M
But I'll have to check.
Full Debug:
mindwipe-dir: next_vol.c:46 CatReq FindMedia: Id=2, MediaType=File^M
mindwipe-dir: postgresql.c:408 my_postgresql_query started^M
mindwipe-dir: postgresql.c:418 my_postgresql_query starts with 'SELECT
MediaId,VolumeName,VolJobs,VolFiles,VolBlocks,VolBytes,VolMounts,V
olErrors,VolWrites,MaxVolBytes,VolCapacityBytes,VolRetention,VolUseDuration,MaxVolJobs,MaxVolFiles,Recycle,Slot,FirstWritten,LastWritten,
VolStatus,InChanger,VolParts,LabelType FROM Media WHERE PoolId=2 AND
MediaType='File' AND VolStatus='Append' ORDER BY LastWritten IS NUL
L,LastWritten DESC,MediaId LIMIT 1'^M
mindwipe-dir: postgresql.c:422 we have a result^M
mindwipe-dir: postgresql.c:426 we have 23 fields^M
mindwipe-dir: postgresql.c:429 we have 1 rows^M
mindwipe-dir: postgresql.c:437 my_postgresql_query finishing^M
mindwipe-dir: postgresql.c:301 my_postgresql_fetch_row start^M
mindwipe-dir: postgresql.c:304 we have need space of 92 bytes^M
mindwipe-dir: postgresql.c:320 my_postgresql_fetch_row row number '0' is
acceptable (0..1)^M
mindwipe-dir: postgresql.c:324 my_postgresql_fetch_row field '0' has
value '7'^M
mindwipe-dir: postgresql.c:324 my_postgresql_fetch_row field '1' has
value 'CFusionWeekly0'^M
mindwipe-dir: postgresql.c:418 my_postgresql_query starts with 'SELECT
MediaId,VolumeName,VolJobs,VolFiles,VolBlocks,VolBytes,VolMounts,V
olErrors,VolWrites,MaxVolBytes,VolCapacityBytes,VolRetention,VolUseDuration,MaxVolJobs,MaxVolFiles,Recycle,Slot,FirstWritten,LastWritten,
VolStatus,InChanger,VolParts,LabelType FROM Media WHERE PoolId=2 AND
MediaType='File' AND VolStatus='Append' ORDER BY LastWritten IS NUL
L,LastWritten DESC,MediaId LIMIT 1'^M
mindwipe-dir: postgresql.c:422 we have a result^M
mindwipe-dir: postgresql.c:426 we have 23 fields^M
mindwipe-dir: postgresql.c:429 we have 1 rows^M
mindwipe-dir: postgresql.c:437 my_postgresql_query finishing^M
mindwipe-dir: postgresql.c:301 my_postgresql_fetch_row start^M
mindwipe-dir: postgresql.c:304 we have need space of 92 bytes^M
mindwipe-dir: postgresql.c:320 my_postgresql_fetch_row row number '0' is
acceptable (0..1)^M
mindwipe-dir: postgresql.c:324 my_postgresql_fetch_row field '0' has
value '7'^M
mindwipe-dir: postgresql.c:324 my_postgresql_fetch_row field '1' has
value 'CFusionWeekly0'^M
mindwipe-dir: postgresql.c:324 my_postgresql_fetch_row field '2' has
value '1'^M
mindwipe-dir: postgresql.c:324 my_postgresql_fetch_row field '3' has
value '0'^M
mindwipe-dir: postgresql.c:324 my_postgresql_fetch_row field '4' has
value '35'^M
mindwipe-dir: postgresql.c:324 my_postgresql_fetch_row field '5' has
value '2246868'^M
mindwipe-dir: postgresql.c:324 my_postgresql_fetch_row field '6' has
value '1'^M
mindwipe-dir: postgresql.c:324 my_postgresql_fetch_row field '7' has
value '0'^M
mindwipe-dir: postgresql.c:324 my_postgresql_fetch_row field '8' has
value '36'^M
mindwipe-dir: postgresql.c:324 my_postgresql_fetch_row field '9' has
value '0'^M
mindwipe-dir: postgresql.c:324 my_postgresql_fetch_row field '10' has
value '0'^M
mindwipe-dir: postgresql.c:324 my_postgresql_fetch_row field '11' has
value '2505600'^M
mindwipe-dir: postgresql.c:324 my_postgresql_fetch_row field '12' has
value '82800'^M
mindwipe-dir: postgresql.c:324 my_postgresql_fetch_row field '13' has
value '0'^M
mindwipe-dir: postgresql.c:324 my_postgresql_fetch_row field '14' has
value '0'^M
mindwipe-dir: postgresql.c:324 my_postgresql_fetch_row field '15' has
value '1'^M
mindwipe-dir: postgresql.c:324 my_postgresql_fetch_row field '16' has
value '0'^M
mindwipe-dir: postgresql.c:324 my_postgresql_fetch_row field '17' has
value '02/14/2006 17:06:15'^M
mindwipe-dir: postgresql.c:324 my_postgresql_fetch_row field '18' has
value '02/14/2006 17:06:20'^M
mindwipe-dir: postgresql.c:324 my_postgresql_fetch_row field '19' has
value 'Append'^M
mindwipe-dir: postgresql.c:324 my_postgresql_fetch_row field '20' has
value '1'^M
mindwipe-dir: postgresql.c:324 my_postgresql_fetch_row field '21' has
value '0'^M
mindwipe-dir: postgresql.c:324 my_postgresql_fetch_row field '22' has
value '0'^M
mindwipe-dir: postgresql.c:334 my_postgresql_fetch_row finishes
returning 8128018^M
mindwipe-dir: next_vol.c:62 catreq after find_next_vol ok=1 FW=0^M
mindwipe-dir: next_vol.c:175 VolJobs=1 FirstWritten=0^M
mindwipe-dir: message.c:993 Enter Jmsg type=6^M
mindwipe-dir: message.c:565 Enter dispatch_msg type=6 msg=mindwipe-dir:
Max configured use duration exceeded. Marking Volume "CFusionWeek
ly0" as Used.^M
mindwipe-dir: message.c:659 MAIL for following msg: mindwipe-dir: Max
configured use duration exceeded. Marking Volume "CFusionWeekly0" a
s Used.^M
mindwipe-dir: message.c:606 CONSOLE for following msg: mindwipe-dir: Max
configured use duration exceeded. Marking Volume "CFusionWeekly0
" as Used.^M
mindwipe-dir: message.c:699 APPEND for following msg: mindwipe-dir: Max
configured use duration exceeded. Marking Volume "CFusionWeekly0"
as Used.^M
mindwipe-dir: sql_update.c:293 update_media: FirstWritten=0^M
mindwipe-dir: sql_update.c:350 UPDATE Media SET
VolJobs=1,VolFiles=0,VolBlocks=35,VolBytes=2246868,VolMounts=1,VolErrors=0,VolWrites=36,M
axVolBytes=0,VolStatus='Used',Slot=0,InChanger=1,VolReadTime=0,VolWriteTime=0,VolParts=0,LabelType=0,StorageId=0,PoolId=2,VolRetention=25
05600,VolUseDuration=82800,MaxVolJobs=0,MaxVolFiles=0 WHERE
VolumeName='CFusionWeekly0'^M
mindwipe-dir: postgresql.c:408 my_postgresql_query started^M
mindwipe-dir: postgresql.c:418 my_postgresql_query starts with 'UPDATE
Media SET VolJobs=1,VolFiles=0,VolBlocks=35,VolBytes=2246868,VolMo
unts=1,VolErrors=0,VolWrites=36,MaxVolBytes=0,VolStatus='Used',Slot=0,InChanger=1,VolReadTime=0,VolWriteTime=0,VolParts=0,LabelType=0,Sto
rageId=0,PoolId=2,VolRetention=2505600,VolUseDuration=82800,MaxVolJobs=0,MaxVolFiles=0
WHERE VolumeName='CFusionWeekly0''^M
~BAS
On Tue, 2006-02-14 at 16:03 -0500, Brian A. Seklecki wrote:
> Platform:
> $ uname -a
> FreeBSD mindwipe 5.3-RELEASE-p23 FreeBSD 5.3-RELEASE-p23 #0: Wed Oct 12
>
> -bash-2.05b$ pkg_info |grep -i bacula
> bacula-client-1.38.5_1 The network backup solution (client)
> bacula-server-1.38.5_1 The network backup solution (server)
>
>
> Here's what I know so far:
>
> *) This bug is not related to manual manipulation of the system clock (I
> can simulate it with and NTP sync)
> *) It does not matter if the two jobs in question start from the
> scheduler or by bconsole manually
>
> Description:
>
> I create a Daily and a Weekly pool for GFS, both with "23h" "Max Use
> Duration"'s to ensure the tapes are only used once/week.
>
> Pool {
> Name = Daily
> Volume Use Duration = 23h
> Pool Type = Backup
> AutoPrune = yes
> Recycle Oldest Volume = yes
> VolumeRetention = 6d # recycle in 6 days
> Maximum Volumes = 6
> Recycle = yes
> }
>
> Pool {
> Name = Weekly
> Pool Type = Backup
> Volume Use Duration = 23h
> AutoPrune = yes
> VolumeRetention = 29d # recycle in 29 days
> Maximum Volumes = 4
> Recycle Oldest Volume = yes
> Recycle = yes
> }
>
> In theory, once the volume in the pool is elected for use in a Job, as
> many other qualifying jobs should also be able to write to it until it's
> full or more than 23 hours since "firstwritten: ".
>
> An llist of the "pool" and "media" show the appropriate
> "voluseduration:" of 82,800 seconds. When I run the first job,
> Promotion sends the data to CFusionWeekly0 per the auto-upgrade logic.
> When I run the second job 15 seconds later, for some reason the previous
> tape/volume is flagged as having "Exceeded Volume Use Duration".
>
> Here are the logs of the first job:
> -------------------------------------------------
>
> 14-Feb 15:53 mindwipe-dir: No prior Full backup Job record found.
> 14-Feb 15:53 mindwipe-dir: No prior or suitable Full backup found. Doing
> FULL backup.
> 14-Feb 15:53 mindwipe-dir: Start Backup JobId 1,
> Job=Blackout-CFusionDefaults.2006-02-14_15.53.31
> 14-Feb 15:53 mindwipe-sd: Wrote label to prelabeled Volume
> "CFusionWeekly0" on device "FileStorage" (/usr/dump/bacula)
> 14-Feb 15:53 mindwipe-dir: Bacula 1.38.5 (18Jan06): 14-Feb-2006 15:53:44
> [snip]
> FileSet: "CFDefaults" 2006-02-14 15:53:33
> Pool: "Weekly"
> Storage: "FileStorage"
> Scheduled time: 14-Feb-2006 15:53:20
> Start time: 14-Feb-2006 15:53:33
> End time: 14-Feb-2006 15:53:44
> Priority: 10
> FD Files Written: 722
> SD Files Written: 722
> FD Bytes Written: 14,749,540
> SD Bytes Written: 14,826,848
> [snip]
> Volume name(s): CFusionWeekly0
> Volume Session Id: 1
> Volume Session Time: 1139949980
> [snip]
> Termination: Backup OK
>
> 14-Feb 15:53 mindwipe-dir: Begin pruning Jobs.
> 14-Feb 15:53 mindwipe-dir: No Jobs found to prune.
> 14-Feb 15:53 mindwipe-dir: Begin pruning Files.
> 14-Feb 15:53 mindwipe-dir: No Files found to prune.
> 14-Feb 15:53 mindwipe-dir: End auto prune.
>
> Here are the logs of the second job (an 'llist media' between jobs can
> be found below):
>
> ---------------------------------------------------------
>
> 14-Feb 15:59 mindwipe-dir: No prior Full backup Job record found.
> 14-Feb 15:59 mindwipe-dir: No prior or suitable Full backup found. Doing
> FULL backup.
> 14-Feb 15:59 mindwipe-dir: Start Backup JobId 2,
> Job=Blackout-LDAP.2006-02-14_15.59.01
> 14-Feb 15:59 mindwipe-dir: Max configured use duration exceeded. Marking
> Volume "CFusionWeekly0" as Used.
>
>
> --------------------------------------
>
> Clearly the Director is confused because the Mark Used event should not
> occur until 15-Feb 14:53.33 per the following llist output exerpt from
> below:
>
> firstwritten: 02/14/2006 15:53:33
> lastwritten: 02/14/2006 15:53:43
> labeldate: 02/14/2006 15:53:33
>
>
> ---------------------------------------------------------
> --------------------------------------------------------
>
> Here is the "llist media" prior to the first job:
>
> *llist media
> Pool: Monthly
> No results to list.
> Pool: Daily
> mediaid: 1
> volumename: CFusionDaily0
> slot: 0
> poolid: 1
> mediatype: File
> firstwritten:
> lastwritten:
> labeldate: 02/14/2006 15:46:46
> voljobs: 0
> volfiles: 0
> volblocks: 0
> volmounts: 0
> volbytes: 1
> volerrors: 0
> volwrites: 0
> volcapacitybytes: 0
> volstatus: Append
> recycle: 1
> volretention: 518,400
> voluseduration: 82,800
> maxvoljobs: 0
> maxvolfiles: 0
> maxvolbytes: 0
> inchanger: 1
> endfile: 0
> endblock: 0
> volparts: 0
> labeltype: 0
> storageid: 1
>
> mediaid: 2
> volumename: CFusionDaily1
> slot: 0
> poolid: 1
> mediatype: File
> firstwritten:
> lastwritten:
> labeldate: 02/14/2006 15:47:03
> voljobs: 0
> volfiles: 0
> volblocks: 0
> volmounts: 0
> volbytes: 1
> volerrors: 0
> volwrites: 0
> volcapacitybytes: 0
> volstatus: Append
> recycle: 1
> volretention: 518,400
> voluseduration: 82,800
> maxvoljobs: 0
> maxvolfiles: 0
> maxvolbytes: 0
> inchanger: 1
> endfile: 0
> endblock: 0
> volparts: 0
> labeltype: 0
> storageid: 1
>
> Pool: Weekly
> mediaid: 3
> volumename: CFusionWeekly0
> slot: 0
> poolid: 2
> mediatype: File
> firstwritten:
> lastwritten:
> labeldate: 02/14/2006 15:47:15
> voljobs: 0
> volfiles: 0
> volblocks: 0
> volmounts: 0
> volbytes: 1
> volerrors: 0
> volwrites: 0
> volcapacitybytes: 0
> volstatus: Append
> recycle: 1
> volretention: 2,505,600
> voluseduration: 82,800
> maxvoljobs: 0
> maxvolfiles: 0
> maxvolbytes: 0
> inchanger: 1
> endfile: 0
> endblock: 0
> volparts: 0
> labeltype: 0
> storageid: 1
>
>
>
> ----
>
> LList in between jobs:
> Pool: Daily
> mediaid: 1
> volumename: CFusionDaily0
> slot: 0
> poolid: 1
> mediatype: File
> firstwritten:
> lastwritten:
> labeldate: 02/14/2006 15:46:46
> voljobs: 0
> volfiles: 0
> volblocks: 0
> volmounts: 0
> volbytes: 1
> volerrors: 0
> volwrites: 0
> volcapacitybytes: 0
> volstatus: Append
> recycle: 1
> volretention: 518,400
> voluseduration: 82,800
> maxvoljobs: 0
> maxvolfiles: 0
> maxvolbytes: 0
> inchanger: 1
> endfile: 0
> endblock: 0
> volparts: 0
> labeltype: 0
> storageid: 1
>
> mediaid: 2
> volumename: CFusionDaily1
> slot: 0
> poolid: 1
> mediatype: File
> firstwritten:
> lastwritten:
> labeldate: 02/14/2006 15:47:03
> voljobs: 0
> volfiles: 0
> volblocks: 0
> volmounts: 0
> volbytes: 1
> volerrors: 0
> volwrites: 0
> volcapacitybytes: 0
> volstatus: Append
> recycle: 1
> volretention: 518,400
> voluseduration: 82,800
> maxvoljobs: 0
> maxvolfiles: 0
> maxvolbytes: 0
> inchanger: 1
> endfile: 0
> endblock: 0
> volparts: 0
> labeltype: 0
> storageid: 1
>
> Pool: Weekly
> mediaid: 3
> volumename: CFusionWeekly0
> slot: 0
> poolid: 2
> mediatype: File
> firstwritten: 02/14/2006 15:53:33
> lastwritten: 02/14/2006 15:53:43
> labeldate: 02/14/2006 15:53:33
> voljobs: 1
> volfiles: 0
> volblocks: 231
> volmounts: 1
> volbytes: 14,861,739
> volerrors: 0
> volwrites: 232
> volcapacitybytes: 0
> volstatus: Append
> recycle: 1
> volretention: 2,505,600
> voluseduration: 82,800
> maxvoljobs: 0
> maxvolfiles: 0
> maxvolbytes: 0
> inchanger: 1
> endfile: 0
> endblock: 14,861,941
> volparts: 0
> labeltype: 0
> storageid: 1
>
>
>
>
>
smime.p7s
Description: S/MIME cryptographic signature
