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

Attachment: smime.p7s
Description: S/MIME cryptographic signature

Reply via email to