...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