[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]

Re: [Bacula-devel] Director bug when using two storage daemons?


On Sat, Nov 15, 2008 at 09:51:05AM +0100, Kern Sibbald wrote:
> Would you please run it one more time and add just after the "list 
> volumes" a:
> 
>   llist volume=TestVolume0001
> 
> Note, it really is "llist" with two l's.

OK, the full output is attached. The llist part says this:

llist volume=TestVolume0001
localhost-dir: ua_output.c:255-0 list: llist volume=TestVolume0001
          MediaId: 1
       VolumeName: TestVolume0001
             Slot: 0
           PoolId: 1
        MediaType: File
     FirstWritten: 2008-11-17 09:03:50
      LastWritten: 0
        LabelDate: 2008-11-17 09:03:50
          VolJobs: 1
         VolFiles: 0
        VolBlocks: 0
        VolMounts: 1
         VolBytes: 210
        VolErrors: 0
        VolWrites: 1
 VolCapacityBytes: 0
        VolStatus: Used
          Enabled: 1
          Recycle: 1
     VolRetention: 31536000
   VolUseDuration: 0
       MaxVolJobs: 1
      MaxVolFiles: 0
      MaxVolBytes: 0
        InChanger: 0
          EndFile: 0
         EndBlock: 0
         VolParts: 0
        LabelType: 0
        StorageId: 1
         DeviceId: 0
       LocationId: 0
     RecycleCount: 0
     InitialWrite: 0
    ScratchPoolId: 0
    RecyclePoolId: 0
          Comment: NULL
 
 
 === Starting broken-media-bug-test at 09:01:54 ===
 
Creating huge 300M file...
300+0 records in
300+0 records out
314572800 bytes (315 MB) copied, 110.079 seconds, 2.9 MB/s
Done
Starting the Bacula Storage daemon
Starting the Bacula File daemon
Starting the Bacula Director daemon
Connecting to Director localhost:8101
1000 OK: localhost-dir Version: 2.5.20 (13 November 2008)
Enter a period to cancel a command.
setdebug level=150  storage=File
Connecting to Storage daemon File at localhost:8103
3000 OK setdebug=150
setdebug level=150  Director
messages
You have no messages.
@tee tmp/log1.out
run job=First yes
localhost-dir: ua_cmds.c:1931-0 UA Open database
Using Catalog "MyCatalog"
localhost-dir: ua_cmds.c:1950-0 DB regress opened
localhost-dir: ua_run.c:1323-0 Using pool Default
localhost-dir: job.c:1264-0 wstorage=File
localhost-dir: job.c:1273-0 wstore=File where=Job resource
localhost-dir: job.c:1298-0 wstore=File where=Job resource
localhost-dir: ua_run.c:178-0 JobId=0 using pool Default priority=10
localhost-dir: job.c:925-0 JobId=0 created Job=First.2008-11-17_09.03.48.03
localhost-dir: job.c:127-0 Open database
localhost-dir: job.c:142-0 DB opened
localhost-dir: job.c:798-0 Created Client localhost-fd record 1
localhost-dir: job.c:173-1 Created job record JobId=1 Name=First.2008-11-17_09.03.48.03 Type=B Level=I
localhost-dir: job.c:835-1 Created FileSet Set1 record 1
localhost-dir: fd_cmds.c:241-1 Level=F last start time=0000-00-00 00:00:00
localhost-dir: job.c:638-1 get_or_create_pool=Default
localhost-dir: ua_run.c:182-1 JobId=1 NewJobId=1 using pool Default priority=10
Job queued. JobId=1
You have messages.
messages
17-Nov 09:03 localhost-dir JobId 1: No prior Full backup Job record found.
17-Nov 09:03 localhost-dir JobId 1: No prior or suitable Full backup found in catalog. Doing FULL backup.
quit
localhost-dir: backup.c:197-1 JobId=1 JobLevel=F
localhost-dir: backup.c:209-1 Open connection with storage daemon
localhost-dir: msgchan.c:104-1 bnet_connect to Storage daemon localhost:8103
localhost-dir: bsock.c:201-1 Current host[ipv4:127.0.0.1:8103] All host[ipv4:127.0.0.1:8103] 
localhost-sd: bnet.c:669-0 who=client host=127.0.0.1 port=42783
localhost-dir: bsock.c:155-1 who=Storage daemon host=localhost port=8103
localhost-sd: dircmd.c:171-0 Conn: Hello Director localhost-dir calling
localhost-sd: dircmd.c:187-0 Got a DIR connection at 17-Nov-2008 09:03:50
localhost-sd: cram-md5.c:73-0 send: auth cram-md5 <1676085357.1226912630@localhost-sd> ssl=0
localhost-dir: cram-md5.c:133-1 cram-get received: auth cram-md5 <1676085357.1226912630@localhost-sd> ssl=0
localhost-dir: cram-md5.c:152-1 sending resp to challenge: Bg/jPTJQ/H9YPW+gkTwPtD
localhost-dir: cram-md5.c:80-1 send: auth cram-md5 <1688427831.1226912630@localhost-dir> ssl=0
localhost-sd: cram-md5.c:133-0 cram-get received: auth cram-md5 <1688427831.1226912630@localhost-dir> ssl=0
localhost-sd: cram-md5.c:152-0 sending resp to challenge: C7B877+QYHd/LDwlBUw0YD
localhost-dir: cram-md5.c:99-1 Authenticate OK C7B877+QYHd/LDwlBUw0YD
localhost-dir: authenticate.c:152-1 >stored: 1000 OK auth
localhost-sd: dircmd.c:209-0 Message channel init completed.
localhost-dir: authenticate.c:159-1 <stored: 3000 OK Hello
localhost-sd: job.c:92-0 <dird: JobId=1 job=First.2008-11-17_09.03.48.03 job_name=First client_name=localhost-fd type=66 level=70 FileSet=Set1 NoAttr=0 SpoolAttr=0 FileSetMD5=B5lTmCERCG+gRWNQQg/88B SpoolData=0 WritePartAfterJob=1 PreferMountedVols=1 SpoolSize=0
localhost-sd: job.c:157-1 >dird jid=1: 3000 OK Job SDid=1 SDtime=1226912624 Authorization=MIIM-OOKL-MFNH-HNLL-KFON-KIKL-AHCI-AEFE
localhost-dir: msgchan.c:192-1 >stored: JobId=1 job=First.2008-11-17_09.03.48.03 job_name=First client_name=localhost-fd type=66 level=70 FileSet=Set1 NoAttr=0 SpoolAttr=0 FileSetMD5=B5lTmCERCG+gRWNQQg/88B SpoolData=0 WritePartAfterJob=1 PreferMountedVols=1 SpoolSize=0

localhost-dir: msgchan.c:194-1 <stored: 3000 OK Job SDid=1 SDtime=1226912624 Authorization=MIIM-OOKL-MFNH-HNLL-KFON-KIKL-AHCI-AEFE
localhost-dir: msgchan.c:202-1 sd_auth_key=MIIM-OOKL-MFNH-HNLL-KFON-KIKL-AHCI-AEFE
localhost-sd: reserve.c:198-1 <dird: use storage=File media_type=File pool_name=Default pool_type=Backup append=1 copy=0 stripe=0
localhost-dir: msgchan.c:275-1 wstore >stored: use storage=File media_type=File pool_name=Default pool_type=Backup append=1 copy=0 stripe=0
localhost-dir: msgchan.c:282-1 >stored: use device=FileStorage
localhost-sd: reserve.c:227-1 <dird device: use device=FileStorage
localhost-sd: reserve.c:243-1 Storage=File media_type=File pool=Default pool_type=Backup append=1
localhost-sd: reserve.c:245-1      Device=FileStorage
localhost-sd: reserve.c:419-1 Start find_suit_dev PrefMnt=1 exact=1 suitable=0 chgronly=0 any=0
localhost-sd: reserve.c:544-1 search res for FileStorage
localhost-sd: reserve.c:578-1 Try match res=FileStorage
localhost-sd: reserve.c:615-1 chk MediaType device=File request=File
localhost-sd: reserve.c:638-1 try reserve FileStorage
localhost-sd: reserve.c:651-1 call reserve for append: have_vol=0 vol=
localhost-sd: reserve.c:835-1 reserve_append device is "FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: reserve.c:912-1 PrefMnt=1 exact=1 suitable=1 chgronly=0 any=0
localhost-sd: reserve.c:884-1 MaxJobs=0 Jobs=0 reserves=0 Status= Vol=
localhost-sd: reserve.c:1016-1 OK Dev avail reserved "FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: reserve.c:129-1 Inc reserve=0 dev="FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: reserve.c:660-1 Reserved=1 dev_name=FileStorage mediatype=File pool=Default ok=1
localhost-sd: reserve.c:662-1 Vol= num_writers=0, have_vol=0
localhost-sd: reserve.c:673-1 no vol, call find_next_appendable_vol.
localhost-sd: askdir.c:276-1 >dird CatReq Job=First.2008-11-17_09.03.48.03 FindMedia=1 pool_name=Default media_type=File
localhost-dir: catreq.c:126-1 catreq CatReq Job=First.2008-11-17_09.03.48.03 FindMedia=1 pool_name=Default media_type=File
localhost-dir: next_vol.c:62-1 find_next_vol_for_append: JobId=1 PoolId=1, MediaType=File
localhost-dir: sql_find.c:367-1 fnextvol=SELECT MediaId,VolumeName,VolJobs,VolFiles,VolBlocks,VolBytes,VolMounts,VolErrors,VolWrites,MaxVolBytes,VolCapacityBytes,MediaType,VolStatus,PoolId,VolRetention,VolUseDuration,MaxVolJobs,MaxVolFiles,Recycle,Slot,FirstWritten,LastWritten,InChanger,EndFile,EndBlock,VolParts,LabelType,LabelDate,StorageId,Enabled,LocationId,RecycleCount,InitialWrite,ScratchPoolId,RecyclePoolId,VolReadTime,VolWriteTime FROM Media WHERE PoolId=1 AND MediaType='File' AND Enabled=1 AND VolStatus='Append'  ORDER BY LastWritten IS NULL,LastWritten DESC,MediaId LIMIT 1
localhost-dir: sql_find.c:375-1 item=1 got=0
localhost-dir: next_vol.c:81-1 after find_next_vol ok=0 index=1 InChanger=0 Vstat=Append
localhost-dir: sql_find.c:367-1 fnextvol=SELECT MediaId,VolumeName,VolJobs,VolFiles,VolBlocks,VolBytes,VolMounts,VolErrors,VolWrites,MaxVolBytes,VolCapacityBytes,MediaType,VolStatus,PoolId,VolRetention,VolUseDuration,MaxVolJobs,MaxVolFiles,Recycle,Slot,FirstWritten,LastWritten,InChanger,EndFile,EndBlock,VolParts,LabelType,LabelDate,StorageId,Enabled,LocationId,RecycleCount,InitialWrite,ScratchPoolId,RecyclePoolId,VolReadTime,VolWriteTime FROM Media WHERE PoolId=1 AND MediaType='File' AND Enabled=1 AND VolStatus='Recycle'  AND Recycle=1 ORDER BY LastWritten ASC,MediaId LIMIT 1
localhost-dir: sql_find.c:375-1 item=1 got=0
localhost-dir: next_vol.c:86-1 find_recycled_volume ok=0 FW=0
localhost-dir: sql_find.c:367-1 fnextvol=SELECT MediaId,VolumeName,VolJobs,VolFiles,VolBlocks,VolBytes,VolMounts,VolErrors,VolWrites,MaxVolBytes,VolCapacityBytes,MediaType,VolStatus,PoolId,VolRetention,VolUseDuration,MaxVolJobs,MaxVolFiles,Recycle,Slot,FirstWritten,LastWritten,InChanger,EndFile,EndBlock,VolParts,LabelType,LabelDate,StorageId,Enabled,LocationId,RecycleCount,InitialWrite,ScratchPoolId,RecyclePoolId,VolReadTime,VolWriteTime FROM Media WHERE PoolId=1 AND MediaType='File' AND Enabled=1 AND VolStatus='Purged'  AND Recycle=1 ORDER BY LastWritten ASC,MediaId LIMIT 1
localhost-dir: sql_find.c:375-1 item=1 got=0
localhost-dir: recycle.c:70-1 return 0  recycle_oldest_purged_volume end
localhost-dir: next_vol.c:97-1 Call prune_volumes
localhost-dir: autoprune.c:99-1 Prune volumes PoolId=1
localhost-dir: autoprune.c:125-1 Scratch pool=
localhost-dir: autoprune.c:150-1 query=SELECT DISTINCT MediaId,LastWritten FROM Media WHERE (PoolId=1 OR RecyclePoolId IN (1)) AND MediaType='File' ORDER BY LastWritten ASC,MediaId
localhost-dir: autoprune.c:156-1 Volume prune num_ids=0
localhost-dir: autoprune.c:223-1 Leave prune volumes
localhost-dir: sql_find.c:367-1 fnextvol=SELECT MediaId,VolumeName,VolJobs,VolFiles,VolBlocks,VolBytes,VolMounts,VolErrors,VolWrites,MaxVolBytes,VolCapacityBytes,MediaType,VolStatus,PoolId,VolRetention,VolUseDuration,MaxVolJobs,MaxVolFiles,Recycle,Slot,FirstWritten,LastWritten,InChanger,EndFile,EndBlock,VolParts,LabelType,LabelDate,StorageId,Enabled,LocationId,RecycleCount,InitialWrite,ScratchPoolId,RecyclePoolId,VolReadTime,VolWriteTime FROM Media WHERE PoolId=1 AND MediaType='File' AND Enabled=1 AND VolStatus='Purged'  AND Recycle=1 ORDER BY LastWritten ASC,MediaId LIMIT 1
localhost-dir: sql_find.c:375-1 item=1 got=0
localhost-dir: recycle.c:70-1 return 0  recycle_oldest_purged_volume end
localhost-dir: next_vol.c:103-1 after prune volumes_vol ok=0 index=1 InChanger=0 Vstat=Purged
localhost-dir: next_vol.c:109-1 after get scratch volume ok=0 index=1 InChanger=0 Vstat=Purged
localhost-dir: newvol.c:105-1 Created new Volume=TestVolume0001
localhost-dir: next_vol.c:164-1 VolJobs=0 FirstWritten=0
localhost-dir: next_vol.c:246-1 Vol=TestVolume0001 expired=0
localhost-dir: next_vol.c:179-1 return ok=1 find_next_vol
localhost-dir: catreq.c:147-1 find_media ok=1 idx=1 vol=TestVolume0001
localhost-sd: askdir.c:182-1 <dird 1000 OK VolName=TestVolume0001 VolJobs=0 VolFiles=0 VolBlocks=0 VolBytes=0 VolMounts=0 VolErrors=0 VolWrites=0 MaxVolBytes=0 VolCapacityBytes=0 VolStatus=Append Slot=0 MaxVolJobs=1 MaxVolFiles=0 InChanger=0 VolReadTime=0 VolWriteTime=0 EndFile=0 EndBlock=0 VolParts=0 LabelType=0 MediaId=1
localhost-sd: askdir.c:205-1 do_reqest_vol_info return true slot=0 Volume=TestVolume0001
localhost-sd: vol_mgr.c:705-1 Vol=TestVolume0001 not in use.
localhost-sd: askdir.c:285-1 Call reserve_volume. Vol=TestVolume0001
localhost-sd: vol_mgr.c:350-1 enter reserve_volume=TestVolume0001 drive="FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: vol_mgr.c:269-1 new Vol=TestVolume0001 at 80b8588 dev="FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: vol_mgr.c:454-1 === set in_use. vol=TestVolume0001 dev="FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: vol_mgr.c:212-1 List end new volume: TestVolume0001 in_use=1 on device "FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: askdir.c:292-1 dir_find_next_appendable_volume return true. vol=TestVolume0001
localhost-sd: reserve.c:677-1 looking for Volume=TestVolume0001
localhost-sd: reserve.c:734-1 >dird: 3000 OK use device device=FileStorage
localhost-sd: reserve.c:588-1 Device FileStorage reserved=1 for append.
localhost-sd: reserve.c:513-1 available device found=FileStorage
localhost-sd: reserve.c:528-1 OK dev found. Vol=TestVolume0001
localhost-dir: catreq.c:100-1 Vol Info for First.2008-11-17_09.03.48.03: 1000 OK VolName=TestVolume0001 VolJobs=0 VolFiles=0 VolBlocks=0 VolBytes=0 VolMounts=0 VolErrors=0 VolWrites=0 MaxVolBytes=0 VolCapacityBytes=0 VolStatus=Append Slot=0 MaxVolJobs=1 MaxVolFiles=0 InChanger=0 VolReadTime=0 VolWriteTime=0 EndFile=0 EndBlock=0 VolParts=0 LabelType=0 MediaId=1
localhost-dir: msgchan.c:288-1 <stored: 3000 OK use device device=FileStorage
localhost-sd: job.c:190-1 First.2008-11-17_09.03.48.03 waiting 1800 sec for FD to contact SD key=MIIM-OOKL-MFNH-HNLL-KFON-KIKL-AHCI-AEFE
localhost-dir: msgchan.c:325-1 Start SD msg_thread.
localhost-dir: msgchan.c:376-1 Start msg_thread loop
localhost-dir: msgchan.c:337-1 SD msg_thread started. use=2
localhost-dir: backup.c:242-1 Storage daemon connection OK
localhost-dir: bsock.c:201-1 Current host[ipv4:127.0.0.1:8102] All host[ipv4:127.0.0.1:8102] 
localhost-dir: bsock.c:155-1 who=Client: localhost-fd host=localhost port=8102
localhost-dir: fd_cmds.c:103-1 Opened connection with File daemon
localhost-dir: authenticate.c:196-1 Sent: Hello Director localhost-dir calling
localhost-dir: cram-md5.c:133-1 cram-get received: auth cram-md5 <1180833524.1226912630@localhost-fd> ssl=0
localhost-dir: cram-md5.c:152-1 sending resp to challenge: 58xg+l/0d4pyji/bUCRXlC
localhost-dir: cram-md5.c:80-1 send: auth cram-md5 <565129231.1226912630@localhost-dir> ssl=0
localhost-dir: cram-md5.c:99-1 Authenticate OK fXoIV++Sx/0VnG+V8+NakD
localhost-dir: authenticate.c:263-1 >filed: 1000 OK auth
localhost-dir: authenticate.c:272-1 <filed: 2000 OK Hello 1
localhost-dir: fd_cmds.c:124-1 >filed: JobId=1 Job=First.2008-11-17_09.03.48.03 SDid=1 SDtime=1226912624 Authorization=MIIM-OOKL-MFNH-HNLL-KFON-KIKL-AHCI-AEFE
localhost-dir: fd_cmds.c:126-1 <filed: 2000 OK Job 2.5.20 (13Nov08) i686-pc-linux-gnu,unknown,unknownlocalhost-dir: fd_cmds.c:292-1 >filed: level = full  mtime_only=0
localhost-sd: bnet.c:669-0 who=client host=127.0.0.1 port=42783
localhost-sd: dircmd.c:171-0 Conn: Hello Start Job First.2008-11-17_09.03.48.03
localhost-sd: dircmd.c:177-0 Got a FD connection at 17-Nov-2008 09:03:50
localhost-sd: dircmd.c:178-0 Hello Start Job First.2008-11-17_09.03.48.03
localhost-sd: job.c:238-0 Found Job First.2008-11-17_09.03.48.03
localhost-sd: cram-md5.c:73-0 send: auth cram-md5 <1180833524.1226912630@localhost-sd> ssl=0
localhost-sd: cram-md5.c:133-0 cram-get received: auth cram-md5 <1880692096.1226912630@localhost-fd> ssl=0
localhost-sd: cram-md5.c:152-0 sending resp to challenge: bXVI/wAcSkAv/9/Tx7+kGA
localhost-sd: job.c:261-0 OK Authentication jid=1 Job First.2008-11-17_09.03.48.03
localhost-sd: job.c:205-1 Auth=1 canceled=0 errstat=0
localhost-sd: job.c:211-1 Running job First.2008-11-17_09.03.48.03
localhost-sd: fd_cmds.c:122-1 Start run Job=First.2008-11-17_09.03.48.03
localhost-dir: fd_cmds.c:588-1 bdird: sending runscripts to fd
localhost-sd: fd_cmds.c:160-1 <filed: append open session
localhost-sd: fd_cmds.c:227-1 Append open session: append open session
localhost-sd: fd_cmds.c:237-1 >filed: 3000 OK open ticket = 1
localhost-sd: fd_cmds.c:160-1 <filed: append data 1
localhost-sd: fd_cmds.c:190-1 Append data: append data 1
localhost-sd: fd_cmds.c:192-1 <bfiled: append data 1
localhost-sd: append.c:73-1 Start append data. res=1
localhost-sd: acquire.c:346-1 acquire_append device is disk
localhost-sd: mount.c:77-1 Enter mount_next_volume(release=0) dev="FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: mount.c:88-1 mount_next_vol retry=0
localhost-sd: askdir.c:230-1 >dird CatReq Job=First.2008-11-17_09.03.48.03 GetVolInfo VolName=TestVolume0001 write=1
localhost-dir: catreq.c:126-1 catreq CatReq Job=First.2008-11-17_09.03.48.03 GetVolInfo VolName=TestVolume0001 write=1
localhost-dir: catreq.c:163-1 CatReq GetVolInfo Vol=TestVolume0001
localhost-dir: next_vol.c:246-1 Vol=TestVolume0001 expired=0
localhost-sd: askdir.c:182-1 <dird 1000 OK VolName=TestVolume0001 VolJobs=0 VolFiles=0 VolBlocks=0 VolBytes=0 VolMounts=0 VolErrors=0 VolWrites=0 MaxVolBytes=0 VolCapacityBytes=0 VolStatus=Append Slot=0 MaxVolJobs=1 MaxVolFiles=0 InChanger=0 VolReadTime=0 VolWriteTime=0 EndFile=0 EndBlock=0 VolParts=0 LabelType=0 MediaId=1
localhost-sd: askdir.c:205-1 do_reqest_vol_info return true slot=0 Volume=TestVolume0001
localhost-sd: mount.c:128-1 After find_next_append. Vol=TestVolume0001 Slot=0 Parts=0
localhost-sd: autochanger.c:121-1 Device "FileStorage" (/usr/bin/bacula/regress/tmp) is not an autochanger
localhost-sd: mount.c:149-1 autoload_dev returns 0
localhost-sd: mount.c:179-1 want vol=TestVolume0001 devvol= dev="FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: dev.c:345-1 open dev: type=1 dev_name="FileStorage" (/usr/bin/bacula/regress/tmp) vol=TestVolume0001 mode=OPEN_READ_WRITE
localhost-sd: dev.c:354-1 call open_file_device mode=OPEN_READ_WRITE
localhost-sd: dev.c:526-1 open disk: mode=OPEN_READ_WRITE open(/usr/bin/bacula/regress/tmp/TestVolume0001, 0x2, 0640)
localhost-sd: dev.c:533-1 open failed: dev.c:532 Could not open: /usr/bin/bacula/regress/tmp/TestVolume0001, ERR=No such file or directory
localhost-sd: dev.c:541-1 open dev: disk fd=-1 opened, part=0/0, part_size=0
localhost-sd: dev.c:358-1 preserve=0x0 fd=-1
localhost-sd: mount.c:642-1 Create volume label
localhost-sd: label.c:304-1 write_volume_label()
localhost-sd: label.c:325-1 New VolName=TestVolume0001
localhost-sd: dev.c:345-1 open dev: type=1 dev_name="FileStorage" (/usr/bin/bacula/regress/tmp) vol=TestVolume0001 mode=OPEN_READ_WRITE
localhost-sd: dev.c:354-1 call open_file_device mode=OPEN_READ_WRITE
localhost-sd: dev.c:526-1 open disk: mode=OPEN_READ_WRITE open(/usr/bin/bacula/regress/tmp/TestVolume0001, 0x2, 0640)
localhost-sd: dev.c:533-1 open failed: dev.c:532 Could not open: /usr/bin/bacula/regress/tmp/TestVolume0001, ERR=No such file or directory
localhost-sd: dev.c:541-1 open dev: disk fd=-1 opened, part=0/0, part_size=0
localhost-sd: dev.c:358-1 preserve=0x0 fd=-1
localhost-sd: dev.c:345-1 open dev: type=1 dev_name="FileStorage" (/usr/bin/bacula/regress/tmp) vol=TestVolume0001 mode=CREATE_READ_WRITE
localhost-sd: dev.c:354-1 call open_file_device mode=CREATE_READ_WRITE
localhost-sd: dev.c:526-1 open disk: mode=CREATE_READ_WRITE open(/usr/bin/bacula/regress/tmp/TestVolume0001, 0x42, 0640)
localhost-sd: dev.c:541-1 open dev: disk fd=8 opened, part=0/0, part_size=0
localhost-sd: dev.c:358-1 preserve=0x0 fd=8
localhost-sd: label.c:334-1 Label type=0
localhost-sd: label.c:602-1 Start create_volume_label()
localhost-sd: dev.c:1892-1 Clear volhdr vol=

Volume Label:
Id                : Bacula 1.0 immortal
VerNo             : 11
VolName           : TestVolume0001
PrevVolName       : 
VolFile           : 0
LabelType         : PRE_LABEL
LabelSize         : 0
PoolName          : Default
MediaType         : File
PoolType          : Backup
HostName          : backuppilot
Date label written: 17-Nov-2008 09:03
localhost-sd: label.c:590-1 Created Vol label rec: FI=PRE_LABEL len=174
localhost-sd: label.c:369-1 Wrote label of 174 bytes to "FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: label.c:372-1 Call write_block_to_dev()
localhost-sd: label.c:387-1  Wrote block to device
localhost-sd: dev.c:1690-1 === weof_dev="FileStorage" (/usr/bin/bacula/regress/tmp)

Volume Label:
Id                : Bacula 1.0 immortal
VerNo             : 11
VolName           : TestVolume0001
PrevVolName       : 
VolFile           : 0
LabelType         : PRE_LABEL
LabelSize         : 0
PoolName          : Default
MediaType         : File
PoolType          : Backup
HostName          : backuppilot
Date label written: 17-Nov-2008 09:03
localhost-sd: label.c:397-1 Call reserve_volume
localhost-sd: vol_mgr.c:350-1 enter reserve_volume=TestVolume0001 drive="FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: vol_mgr.c:212-1 List begin reserve_volume: TestVolume0001 in_use=1 on device "FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: vol_mgr.c:365-1 Vol attached=TestVolume0001, newvol=TestVolume0001 volinuse=1 on "FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: vol_mgr.c:373-1 === set reserved vol=TestVolume0001 dev="FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: vol_mgr.c:454-1 === set in_use. vol=TestVolume0001 dev="FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: vol_mgr.c:212-1 List end new volume: TestVolume0001 in_use=1 on device "FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: mount.c:653-1 dir_update_vol_info. Set Append
localhost-sd: askdir.c:345-1 Update cat VolFiles=0
localhost-sd: askdir.c:368-1 >dird CatReq Job=First.2008-11-17_09.03.48.03 UpdateMedia VolName=TestVolume0001 VolJobs=0 VolFiles=0 VolBlocks=0 VolBytes=0 VolMounts=0 VolErrors=0 VolWrites=0 MaxVolBytes=0 EndTime=1226912630 VolStatus=Append Slot=0 relabel=1 InChanger=0 VolReadTime=0 VolWriteTime=0 VolFirstWritten=0 VolParts=0
localhost-dir: catreq.c:100-1 Vol Info for First.2008-11-17_09.03.48.03: 1000 OK VolName=TestVolume0001 VolJobs=0 VolFiles=0 VolBlocks=0 VolBytes=0 VolMounts=0 VolErrors=0 VolWrites=0 MaxVolBytes=0 VolCapacityBytes=0 VolStatus=Append Slot=0 MaxVolJobs=1 MaxVolFiles=0 InChanger=0 VolReadTime=0 VolWriteTime=0 EndFile=0 EndBlock=0 VolParts=0 LabelType=0 MediaId=1
localhost-dir: catreq.c:126-1 catreq CatReq Job=First.2008-11-17_09.03.48.03 UpdateMedia VolName=TestVolume0001 VolJobs=0 VolFiles=0 VolBlocks=0 VolBytes=0 VolMounts=0 VolErrors=0 VolWrites=0 MaxVolBytes=0 EndTime=1226912630 VolStatus=Append Slot=0 relabel=1 InChanger=0 VolReadTime=0 VolWriteTime=0 VolFirstWritten=0 VolParts=0
localhost-dir: sql_update.c:338-1 update_media: FirstWritten=1226912630
localhost-dir: next_vol.c:246-1 Vol=TestVolume0001 expired=0
localhost-sd: askdir.c:182-1 <dird 1000 OK VolName=TestVolume0001 VolJobs=0 VolFiles=0 VolBlocks=0 VolBytes=0 VolMounts=0 VolErrors=0 VolWrites=0 MaxVolBytes=0 VolCapacityBytes=0 VolStatus=Append Slot=0 MaxVolJobs=1 MaxVolFiles=0 InChanger=0 VolReadTime=0 VolWriteTime=0 EndFile=0 EndBlock=0 VolParts=0 LabelType=0 MediaId=1
localhost-sd: askdir.c:205-1 do_reqest_vol_info return true slot=0 Volume=TestVolume0001
localhost-sd: dev.c:336-1 Close fd for mode change.
localhost-sd: dev.c:345-1 open dev: type=1 dev_name="FileStorage" (/usr/bin/bacula/regress/tmp) vol=TestVolume0001 mode=OPEN_READ_WRITE
localhost-sd: dev.c:354-1 call open_file_device mode=OPEN_READ_WRITE
localhost-sd: dev.c:526-1 open disk: mode=OPEN_READ_WRITE open(/usr/bin/bacula/regress/tmp/TestVolume0001, 0x2, 0640)
localhost-sd: dev.c:541-1 open dev: disk fd=8 opened, part=0/0, part_size=210
localhost-sd: dev.c:358-1 preserve=0x40 fd=8
localhost-sd: label.c:81-1 Enter read_volume_label res=1 device="FileStorage" (/usr/bin/bacula/regress/tmp) vol=TestVolume0001 dev_Vol=TestVolume0001
localhost-sd: label.c:130-1 Big if statement in read_volume_label
localhost-sd: label.c:202-1 Compare Vol names: VolName=TestVolume0001 hdr=TestVolume0001

Volume Label:
Id                : Bacula 1.0 immortal
VerNo             : 11
VolName           : TestVolume0001
PrevVolName       : 
VolFile           : 0
LabelType         : PRE_LABEL
LabelSize         : 174
PoolName          : Default
MediaType         : File
PoolType          : Backup
HostName          : backuppilot
Date label written: 17-Nov-2008 09:03
localhost-sd: label.c:223-1 Leave read_volume_label() VOL_OK
localhost-sd: label.c:236-1 Call reserve_volume=TestVolume0001
localhost-sd: vol_mgr.c:350-1 enter reserve_volume=TestVolume0001 drive="FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: vol_mgr.c:212-1 List begin reserve_volume: TestVolume0001 in_use=1 on device "FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: vol_mgr.c:365-1 Vol attached=TestVolume0001, newvol=TestVolume0001 volinuse=1 on "FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: vol_mgr.c:373-1 === set reserved vol=TestVolume0001 dev="FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: vol_mgr.c:454-1 === set in_use. vol=TestVolume0001 dev="FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: vol_mgr.c:212-1 List end new volume: TestVolume0001 in_use=1 on device "FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: mount.c:363-1 Want dirVol=TestVolume0001 dirStat=Append
localhost-sd: mount.c:370-1 Vol OK name=TestVolume0001
localhost-sd: label.c:267-1 write Label in write_volume_label_to_block()
localhost-sd: label.c:590-1 Created Vol label rec: FI=VOL_LABEL len=174
localhost-sd: label.c:282-1 Wrote label of 174 bytes to block. Vol=TestVolume0001
localhost-sd: label.c:438-1 wrote vol label to block. Vol=TestVolume0001
localhost-sd: label.c:510-1 dir_update_vol_info. Set Append vol=TestVolume0001
localhost-sd: askdir.c:345-1 Update cat VolFiles=0
localhost-sd: askdir.c:368-1 >dird CatReq Job=First.2008-11-17_09.03.48.03 UpdateMedia VolName=TestVolume0001 VolJobs=0 VolFiles=0 VolBlocks=0 VolBytes=210 VolMounts=1 VolErrors=0 VolWrites=1 MaxVolBytes=0 EndTime=1226912630 VolStatus=Append Slot=0 relabel=1 InChanger=0 VolReadTime=0 VolWriteTime=10 VolFirstWritten=0 VolParts=0
localhost-dir: catreq.c:100-1 Vol Info for First.2008-11-17_09.03.48.03: 1000 OK VolName=TestVolume0001 VolJobs=0 VolFiles=0 VolBlocks=0 VolBytes=0 VolMounts=0 VolErrors=0 VolWrites=0 MaxVolBytes=0 VolCapacityBytes=0 VolStatus=Append Slot=0 MaxVolJobs=1 MaxVolFiles=0 InChanger=0 VolReadTime=0 VolWriteTime=0 EndFile=0 EndBlock=0 VolParts=0 LabelType=0 MediaId=1
localhost-dir: catreq.c:126-1 catreq CatReq Job=First.2008-11-17_09.03.48.03 UpdateMedia VolName=TestVolume0001 VolJobs=0 VolFiles=0 VolBlocks=0 VolBytes=210 VolMounts=1 VolErrors=0 VolWrites=1 MaxVolBytes=0 EndTime=1226912630 VolStatus=Append Slot=0 relabel=1 InChanger=0 VolReadTime=0 VolWriteTime=10 VolFirstWritten=0 VolParts=0
localhost-dir: sql_update.c:338-1 update_media: FirstWritten=1226912630
localhost-dir: next_vol.c:246-1 Vol=TestVolume0001 expired=0
localhost-sd: askdir.c:182-1 <dird 1000 OK VolName=TestVolume0001 VolJobs=0 VolFiles=0 VolBlocks=0 VolBytes=210 VolMounts=1 VolErrors=0 VolWrites=1 MaxVolBytes=0 VolCapacityBytes=0 VolStatus=Append Slot=0 MaxVolJobs=1 MaxVolFiles=0 InChanger=0 VolReadTime=0 VolWriteTime=10 EndFile=0 EndBlock=0 VolParts=0 LabelType=0 MediaId=1
localhost-sd: askdir.c:205-1 do_reqest_vol_info return true slot=0 Volume=TestVolume0001
localhost-sd: label.c:527-1 OK from rewrite vol label. Vol=TestVolume0001
localhost-sd: mount.c:293-1 set APPEND, normal return from mount_next_write_volume. dev="FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: askdir.c:345-1 Update cat VolFiles=0
localhost-sd: askdir.c:368-1 >dird CatReq Job=First.2008-11-17_09.03.48.03 UpdateMedia VolName=TestVolume0001 VolJobs=1 VolFiles=0 VolBlocks=0 VolBytes=210 VolMounts=1 VolErrors=0 VolWrites=1 MaxVolBytes=0 EndTime=1226912630 VolStatus=Append Slot=0 relabel=0 InChanger=0 VolReadTime=0 VolWriteTime=10 VolFirstWritten=0 VolParts=0
localhost-dir: catreq.c:100-1 Vol Info for First.2008-11-17_09.03.48.03: 1000 OK VolName=TestVolume0001 VolJobs=0 VolFiles=0 VolBlocks=0 VolBytes=210 VolMounts=1 VolErrors=0 VolWrites=1 MaxVolBytes=0 VolCapacityBytes=0 VolStatus=Append Slot=0 MaxVolJobs=1 MaxVolFiles=0 InChanger=0 VolReadTime=0 VolWriteTime=10 EndFile=0 EndBlock=0 VolParts=0 LabelType=0 MediaId=1
localhost-dir: catreq.c:126-1 catreq CatReq Job=First.2008-11-17_09.03.48.03 UpdateMedia VolName=TestVolume0001 VolJobs=1 VolFiles=0 VolBlocks=0 VolBytes=210 VolMounts=1 VolErrors=0 VolWrites=1 MaxVolBytes=0 EndTime=1226912630 VolStatus=Append Slot=0 relabel=0 InChanger=0 VolReadTime=0 VolWriteTime=10 VolFirstWritten=0 VolParts=0
localhost-dir: sql_update.c:338-1 update_media: FirstWritten=1226912630
localhost-dir: next_vol.c:215-1 MaxVolJobs=1 JobId=1 Vol=TestVolume0001
localhost-dir: next_vol.c:240-1 Vol=TestVolume0001 has expired update media record
localhost-dir: sql_update.c:338-1 update_media: FirstWritten=1226912630
localhost-dir: next_vol.c:246-1 Vol=TestVolume0001 expired=1
localhost-sd: askdir.c:182-1 <dird 1000 OK VolName=TestVolume0001 VolJobs=1 VolFiles=0 VolBlocks=0 VolBytes=210 VolMounts=1 VolErrors=0 VolWrites=1 MaxVolBytes=0 VolCapacityBytes=0 VolStatus=Used Slot=0 MaxVolJobs=1 MaxVolFiles=0 InChanger=0 VolReadTime=0 VolWriteTime=10 EndFile=0 EndBlock=0 VolParts=0 LabelType=0 MediaId=1
localhost-sd: askdir.c:205-1 do_reqest_vol_info return true slot=0 Volume=TestVolume0001
localhost-sd: reserve.c:138-1 Dec reserve=0 dev="FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: append.c:96-1 Begin append device="FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: append.c:101-1 Just after acquire_device_for_append
localhost-sd: label.c:704-1 session_label record=80b8468
localhost-sd: label.c:749-1 Write sesson_label record JobId=1 FI=SOS_LABEL SessId=1 Strm=1 len=144 remainder=0
localhost-sd: label.c:753-1 Leave write_session_label Block=209d File=0d
localhost-dir: catreq.c:100-1 Vol Info for First.2008-11-17_09.03.48.03: 1000 OK VolName=TestVolume0001 VolJobs=1 VolFiles=0 VolBlocks=0 VolBytes=210 VolMounts=1 VolErrors=0 VolWrites=1 MaxVolBytes=0 VolCapacityBytes=0 VolStatus=Used Slot=0 MaxVolJobs=1 MaxVolFiles=0 InChanger=0 VolReadTime=0 VolWriteTime=10 EndFile=0 EndBlock=0 VolParts=0 LabelType=0 MediaId=1
localhost-dir: sql.c:737-1 initdb ref=1 connected=1 db=80dbdc8
Connecting to Director localhost:8101
localhost-dir: bnet.c:669-0 who=client host=127.0.0.1 port=42271
localhost-dir: job.c:1264-0 wstorage=File
localhost-dir: job.c:1273-0 wstore=File where=Job resource
localhost-dir: job.c:925-0 JobId=0 created Job=-Console-.2008-11-17_09.03.53.04
localhost-dir: cram-md5.c:73-0 send: auth cram-md5 <286521156.1226912633@localhost-dir> ssl=0
localhost-dir: cram-md5.c:133-0 cram-get received: auth cram-md5 <242062111.1226912633@bconsole> ssl=0
localhost-dir: cram-md5.c:152-0 sending resp to challenge: P5+ao9+i9B1x9S/yR++HiD
1000 OK: localhost-dir Version: 2.5.20 (13 November 2008)
Enter a period to cancel a command.
setdebug level=150  storage=File
localhost-dir: ua_cmds.c:951-0 setdebug:setdebug level=150  storage=File:
localhost-dir: job.c:1298-0 wstore=File where=unknown source
localhost-dir: msgchan.c:104-0 bnet_connect to Storage daemon localhost:8103
Connecting to Storage daemon File at localhost:8103
localhost-dir: bsock.c:201-0 Current host[ipv4:127.0.0.1:8103] All host[ipv4:127.0.0.1:8103] 
localhost-sd: bnet.c:669-0 who=client host=127.0.0.1 port=42783
localhost-dir: bsock.c:155-0 who=Storage daemon host=localhost port=8103
localhost-sd: dircmd.c:171-0 Conn: Hello Director localhost-dir calling
localhost-sd: dircmd.c:187-0 Got a DIR connection at 17-Nov-2008 09:03:53
localhost-sd: cram-md5.c:73-0 send: auth cram-md5 <823814477.1226912633@localhost-sd> ssl=0
localhost-dir: cram-md5.c:133-0 cram-get received: auth cram-md5 <823814477.1226912633@localhost-sd> ssl=0
localhost-dir: cram-md5.c:152-0 sending resp to challenge: o4g5G9/0c6ZiUVNT9m1j7C
localhost-dir: cram-md5.c:80-0 send: auth cram-md5 <1587933097.1226912633@localhost-dir> ssl=0
localhost-sd: cram-md5.c:133-0 cram-get received: auth cram-md5 <1587933097.1226912633@localhost-dir> ssl=0
localhost-dir: cram-md5.c:99-0 Authenticate OK Z7+Id9Bu6k/cZ74y58/sbC
localhost-dir: authenticate.c:152-0 >stored: 1000 OK auth
localhost-sd: cram-md5.c:152-0 sending resp to challenge: Z7+Id9Bu6k/cZ74y58/sbC
localhost-dir: authenticate.c:159-0 <stored: 3000 OK Hello
localhost-sd: dircmd.c:209-0 Message channel init completed.
localhost-dir: ua_cmds.c:823-0 Connected to storage daemon
localhost-sd: dircmd.c:279-0 setdebug_cmd: setdebug=150 trace=-1
3000 OK setdebug=150
You have messages.
setdebug level=150  Director
localhost-dir: ua_cmds.c:951-0 setdebug:setdebug level=150  Director:
list volumes
localhost-dir: ua_cmds.c:1931-0 UA Open database
localhost-dir: ua_cmds.c:1950-0 DB regress opened
localhost-dir: ua_output.c:255-0 list: list volumes
Automatically selected Catalog: MyCatalog
Using Catalog "MyCatalog"
Pool: Default
+---------+----------------+-----------+---------+----------+----------+--------------+---------+------+-----------+-----------+-------------+
| MediaId | VolumeName     | VolStatus | Enabled | VolBytes | VolFiles | VolRetention | Recycle | Slot | InChanger | MediaType | LastWritten |
+---------+----------------+-----------+---------+----------+----------+--------------+---------+------+-----------+-----------+-------------+
| 1       | TestVolume0001 | Used      | 1       | 210      | 0        | 31536000     | 1       | 0    | 0         | File      | 0           |
+---------+----------------+-----------+---------+----------+----------+--------------+---------+------+-----------+-----------+-------------+
llist volume=TestVolume0001
localhost-dir: ua_output.c:255-0 list: llist volume=TestVolume0001
          MediaId: 1
       VolumeName: TestVolume0001
             Slot: 0
           PoolId: 1
        MediaType: File
     FirstWritten: 2008-11-17 09:03:50
      LastWritten: 0
        LabelDate: 2008-11-17 09:03:50
          VolJobs: 1
         VolFiles: 0
        VolBlocks: 0
        VolMounts: 1
         VolBytes: 210
        VolErrors: 0
        VolWrites: 1
 VolCapacityBytes: 0
        VolStatus: Used
          Enabled: 1
          Recycle: 1
     VolRetention: 31536000
   VolUseDuration: 0
       MaxVolJobs: 1
      MaxVolFiles: 0
      MaxVolBytes: 0
        InChanger: 0
          EndFile: 0
         EndBlock: 0
         VolParts: 0
        LabelType: 0
        StorageId: 1
         DeviceId: 0
       LocationId: 0
     RecycleCount: 0
     InitialWrite: 0
    ScratchPoolId: 0
    RecyclePoolId: 0
          Comment: NULL

messages
17-Nov 09:03 localhost-dir JobId 1: Start Backup JobId 1, Job=First.2008-11-17_09.03.48.03
17-Nov 09:03 localhost-dir JobId 1: Created new Volume "TestVolume0001" in catalog.
17-Nov 09:03 localhost-dir JobId 1: Using Device "FileStorage"
17-Nov 09:03 localhost-sd JobId 1: Warning: dev.c:534 dev.c:532 Could not open: /usr/bin/bacula/regress/tmp/TestVolume0001, ERR=No such file or directory
17-Nov 09:03 localhost-sd JobId 1: Warning: dev.c:534 dev.c:532 Could not open: /usr/bin/bacula/regress/tmp/TestVolume0001, ERR=No such file or directory
17-Nov 09:03 localhost-sd JobId 1: Labeled new Volume "TestVolume0001" on device "FileStorage" (/usr/bin/bacula/regress/tmp).
17-Nov 09:03 localhost-sd JobId 1: Wrote label to prelabeled Volume "TestVolume0001" on device "FileStorage" (/usr/bin/bacula/regress/tmp)
17-Nov 09:03 localhost-dir JobId 1: Max Volume jobs exceeded. Marking Volume "TestVolume0001" as Used.
@tee tmp/log2.out
run job=Second yes
localhost-dir: ua_run.c:1323-0 Using pool Default
localhost-dir: job.c:1264-0 wstorage=File
localhost-dir: job.c:1273-0 wstore=File where=Job resource
localhost-dir: job.c:1298-0 wstore=File where=Job resource
localhost-dir: ua_run.c:178-0 JobId=0 using pool Default priority=10
localhost-dir: job.c:925-0 JobId=0 created Job=Second.2008-11-17_09.03.53.05
localhost-dir: job.c:127-0 Open database
localhost-dir: job.c:142-0 DB opened
localhost-dir: job.c:798-0 Created Client localhost-fd record 1
localhost-dir: job.c:173-2 Created job record JobId=2 Name=Second.2008-11-17_09.03.53.05 Type=B Level=I
localhost-dir: job.c:835-2 Created FileSet Set2 record 2
localhost-dir: fd_cmds.c:241-2 Level=F last start time=0000-00-00 00:00:00
localhost-dir: job.c:638-2 get_or_create_pool=Default
localhost-dir: ua_run.c:182-2 JobId=2 NewJobId=2 using pool Default priority=10
Job queued. JobId=2
You have messages.
wait
localhost-dir: backup.c:197-2 JobId=2 JobLevel=F
localhost-dir: backup.c:209-2 Open connection with storage daemon
localhost-dir: msgchan.c:104-2 bnet_connect to Storage daemon localhost:8103
localhost-dir: bsock.c:201-2 Current host[ipv4:127.0.0.1:8103] All host[ipv4:127.0.0.1:8103] 
localhost-dir: bsock.c:155-2 who=Storage daemon host=localhost port=8103
localhost-sd: bnet.c:669-0 who=client host=127.0.0.1 port=42783
localhost-sd: dircmd.c:171-0 Conn: Hello Director localhost-dir calling
localhost-sd: dircmd.c:187-0 Got a DIR connection at 17-Nov-2008 09:03:55
localhost-sd: cram-md5.c:73-0 send: auth cram-md5 <1551748599.1226912635@localhost-sd> ssl=0
localhost-dir: cram-md5.c:133-2 cram-get received: auth cram-md5 <1551748599.1226912635@localhost-sd> ssl=0
localhost-dir: cram-md5.c:152-2 sending resp to challenge: Zg+D29R+lw1Qc8Fng1AA4A
localhost-dir: cram-md5.c:80-2 send: auth cram-md5 <2077589205.1226912635@localhost-dir> ssl=0
localhost-sd: cram-md5.c:133-0 cram-get received: auth cram-md5 <2077589205.1226912635@localhost-dir> ssl=0
localhost-sd: cram-md5.c:152-0 sending resp to challenge: 7VlCUh/ixU/yD6/Zkh/WmB
localhost-dir: cram-md5.c:99-2 Authenticate OK 7VlCUh/ixU/yD6/Zkh/WmB
localhost-dir: authenticate.c:152-2 >stored: 1000 OK auth
localhost-sd: dircmd.c:209-0 Message channel init completed.
localhost-dir: authenticate.c:159-2 <stored: 3000 OK Hello
localhost-dir: msgchan.c:192-2 >stored: JobId=2 job=Second.2008-11-17_09.03.53.05 job_name=Second client_name=localhost-fd type=66 level=70 FileSet=Set2 NoAttr=0 SpoolAttr=0 FileSetMD5=B5lTmCERCG+gRWNQQg/88B SpoolData=0 WritePartAfterJob=1 PreferMountedVols=1 SpoolSize=0

localhost-sd: job.c:92-0 <dird: JobId=2 job=Second.2008-11-17_09.03.53.05 job_name=Second client_name=localhost-fd type=66 level=70 FileSet=Set2 NoAttr=0 SpoolAttr=0 FileSetMD5=B5lTmCERCG+gRWNQQg/88B SpoolData=0 WritePartAfterJob=1 PreferMountedVols=1 SpoolSize=0
localhost-sd: job.c:157-2 >dird jid=2: 3000 OK Job SDid=2 SDtime=1226912624 Authorization=JMEA-KPAM-PHEL-CAJI-FBMC-IKHA-OKLM-JJNF
localhost-dir: msgchan.c:194-2 <stored: 3000 OK Job SDid=2 SDtime=1226912624 Authorization=JMEA-KPAM-PHEL-CAJI-FBMC-IKHA-OKLM-JJNF
localhost-dir: msgchan.c:202-2 sd_auth_key=JMEA-KPAM-PHEL-CAJI-FBMC-IKHA-OKLM-JJNF
localhost-dir: msgchan.c:275-2 wstore >stored: use storage=File media_type=File pool_name=Default pool_type=Backup append=1 copy=0 stripe=0
localhost-dir: msgchan.c:282-2 >stored: use device=FileStorage
localhost-sd: reserve.c:198-2 <dird: use storage=File media_type=File pool_name=Default pool_type=Backup append=1 copy=0 stripe=0
localhost-sd: reserve.c:227-2 <dird device: use device=FileStorage
localhost-sd: reserve.c:243-2 Storage=File media_type=File pool=Default pool_type=Backup append=1
localhost-sd: reserve.c:245-2      Device=FileStorage
localhost-sd: reserve.c:419-2 Start find_suit_dev PrefMnt=1 exact=1 suitable=0 chgronly=0 any=0
localhost-sd: vol_mgr.c:748-2 lock volumes
localhost-sd: vol_mgr.c:750-2 duplicate vol list
localhost-sd: vol_mgr.c:766-2 unlock volumes
localhost-sd: reserve.c:433-2 look for vol in vol list
localhost-sd: askdir.c:230-2 >dird CatReq Job=Second.2008-11-17_09.03.53.05 GetVolInfo VolName=TestVolume0001 write=1
localhost-dir: catreq.c:126-2 catreq CatReq Job=Second.2008-11-17_09.03.53.05 GetVolInfo VolName=TestVolume0001 write=1
localhost-dir: catreq.c:163-2 CatReq GetVolInfo Vol=TestVolume0001
localhost-dir: next_vol.c:246-2 Vol=TestVolume0001 expired=0
localhost-sd: askdir.c:182-2 <dird 1998 Volume "TestVolume0001" status is Used, but should be Append, Purged or Recycle.
localhost-sd: askdir.c:195-2 Bad response from Dir fields=-1, len=86: 1998 Volume "TestVolume0001" status is Used, but should be Append, Purged or Recycle.
localhost-sd: reserve.c:492-2 lock volumes
localhost-sd: vol_mgr.c:640-2 free vol_list Volume=TestVolume0001 dev="FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: vol_mgr.c:783-2 deleted temp vol list
localhost-sd: vol_mgr.c:784-2 unlock volumes
localhost-sd: vol_mgr.c:212-2 List after free temp table: TestVolume0001 in_use=1 on device "FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: reserve.c:544-2 search res for FileStorage
localhost-sd: reserve.c:578-2 Try match res=FileStorage
localhost-sd: reserve.c:615-2 chk MediaType device=File request=File
localhost-sd: reserve.c:638-2 try reserve FileStorage
localhost-sd: reserve.c:651-2 call reserve for append: have_vol=0 vol=
localhost-sd: reserve.c:835-2 reserve_append device is "FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: reserve.c:912-2 PrefMnt=1 exact=1 suitable=1 chgronly=0 any=0
localhost-sd: reserve.c:884-2 MaxJobs=0 Jobs=0 reserves=0 Status= Vol=TestVolume0001
localhost-sd: reserve.c:860-2 OK dev: "FileStorage" (/usr/bin/bacula/regress/tmp) num_writers=0, reserved, pool matches
localhost-sd: reserve.c:129-2 Inc reserve=0 dev="FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: reserve.c:660-2 Reserved=1 dev_name=FileStorage mediatype=File pool=Default ok=1
localhost-sd: reserve.c:662-2 Vol= num_writers=1, have_vol=0
localhost-sd: reserve.c:673-2 no vol, call find_next_appendable_vol.
localhost-sd: askdir.c:276-2 >dird CatReq Job=Second.2008-11-17_09.03.53.05 FindMedia=1 pool_name=Default media_type=File
localhost-dir: catreq.c:126-2 catreq CatReq Job=Second.2008-11-17_09.03.53.05 FindMedia=1 pool_name=Default media_type=File
localhost-dir: next_vol.c:62-2 find_next_vol_for_append: JobId=2 PoolId=1, MediaType=File
localhost-dir: sql_find.c:367-2 fnextvol=SELECT MediaId,VolumeName,VolJobs,VolFiles,VolBlocks,VolBytes,VolMounts,VolErrors,VolWrites,MaxVolBytes,VolCapacityBytes,MediaType,VolStatus,PoolId,VolRetention,VolUseDuration,MaxVolJobs,MaxVolFiles,Recycle,Slot,FirstWritten,LastWritten,InChanger,EndFile,EndBlock,VolParts,LabelType,LabelDate,StorageId,Enabled,LocationId,RecycleCount,InitialWrite,ScratchPoolId,RecyclePoolId,VolReadTime,VolWriteTime FROM Media WHERE PoolId=1 AND MediaType='File' AND Enabled=1 AND VolStatus='Append'  ORDER BY LastWritten IS NULL,LastWritten DESC,MediaId LIMIT 1
localhost-dir: sql_find.c:375-2 item=1 got=0
localhost-dir: next_vol.c:81-2 after find_next_vol ok=0 index=1 InChanger=0 Vstat=Append
localhost-dir: sql_find.c:367-2 fnextvol=SELECT MediaId,VolumeName,VolJobs,VolFiles,VolBlocks,VolBytes,VolMounts,VolErrors,VolWrites,MaxVolBytes,VolCapacityBytes,MediaType,VolStatus,PoolId,VolRetention,VolUseDuration,MaxVolJobs,MaxVolFiles,Recycle,Slot,FirstWritten,LastWritten,InChanger,EndFile,EndBlock,VolParts,LabelType,LabelDate,StorageId,Enabled,LocationId,RecycleCount,InitialWrite,ScratchPoolId,RecyclePoolId,VolReadTime,VolWriteTime FROM Media WHERE PoolId=1 AND MediaType='File' AND Enabled=1 AND VolStatus='Recycle'  AND Recycle=1 ORDER BY LastWritten ASC,MediaId LIMIT 1
localhost-dir: sql_find.c:375-2 item=1 got=0
localhost-dir: next_vol.c:86-2 find_recycled_volume ok=0 FW=0
localhost-dir: sql_find.c:367-2 fnextvol=SELECT MediaId,VolumeName,VolJobs,VolFiles,VolBlocks,VolBytes,VolMounts,VolErrors,VolWrites,MaxVolBytes,VolCapacityBytes,MediaType,VolStatus,PoolId,VolRetention,VolUseDuration,MaxVolJobs,MaxVolFiles,Recycle,Slot,FirstWritten,LastWritten,InChanger,EndFile,EndBlock,VolParts,LabelType,LabelDate,StorageId,Enabled,LocationId,RecycleCount,InitialWrite,ScratchPoolId,RecyclePoolId,VolReadTime,VolWriteTime FROM Media WHERE PoolId=1 AND MediaType='File' AND Enabled=1 AND VolStatus='Purged'  AND Recycle=1 ORDER BY LastWritten ASC,MediaId LIMIT 1
localhost-dir: sql_find.c:375-2 item=1 got=0
localhost-dir: recycle.c:70-2 return 0  recycle_oldest_purged_volume end
localhost-dir: next_vol.c:97-2 Call prune_volumes
localhost-dir: autoprune.c:99-2 Prune volumes PoolId=1
localhost-dir: autoprune.c:125-2 Scratch pool=
localhost-dir: autoprune.c:150-2 query=SELECT DISTINCT MediaId,LastWritten FROM Media WHERE (PoolId=1 OR RecyclePoolId IN (1)) AND MediaType='File' ORDER BY LastWritten ASC,MediaId
localhost-dir: autoprune.c:156-2 Volume prune num_ids=1
localhost-dir: autoprune.c:163-2 Get record MediaId=1
localhost-dir: autoprune.c:168-2 Examine vol=TestVolume0001
localhost-dir: autoprune.c:177-2 Add prune list MediaId=1 Volume TestVolume0001
localhost-dir: ua_prune.c:491-2 Query=SELECT DISTINCT JobMedia.JobId FROM JobMedia,Job WHERE MediaId=1 AND Job.JobId=JobMedia.JobId AND Job.JobTDate<1195376636
localhost-dir: autoprune.c:179-2 Num pruned = 0
localhost-dir: sql_update.c:338-2 update_media: FirstWritten=1226912630
localhost-dir: next_vol.c:246-2 Vol=TestVolume0001 expired=0
localhost-dir: autoprune.c:215-2 Got Vol=TestVolume0001 MediaId=1 purged.
localhost-dir: autoprune.c:223-2 Leave prune volumes
localhost-dir: sql_find.c:367-2 fnextvol=SELECT MediaId,VolumeName,VolJobs,VolFiles,VolBlocks,VolBytes,VolMounts,VolErrors,VolWrites,MaxVolBytes,VolCapacityBytes,MediaType,VolStatus,PoolId,VolRetention,VolUseDuration,MaxVolJobs,MaxVolFiles,Recycle,Slot,FirstWritten,LastWritten,InChanger,EndFile,EndBlock,VolParts,LabelType,LabelDate,StorageId,Enabled,LocationId,RecycleCount,InitialWrite,ScratchPoolId,RecyclePoolId,VolReadTime,VolWriteTime FROM Media WHERE PoolId=1 AND MediaType='File' AND Enabled=1 AND VolStatus='Purged'  AND Recycle=1 ORDER BY LastWritten ASC,MediaId LIMIT 1
localhost-dir: sql_find.c:444-2 Rtn numrows=1
localhost-dir: sql_update.c:338-2 update_media: FirstWritten=0
localhost-dir: recycle.c:66-2 return 1  recycle_oldest_purged_volume Vol=TestVolume0001
localhost-dir: next_vol.c:164-2 VolJobs=0 FirstWritten=0
localhost-dir: next_vol.c:246-2 Vol=TestVolume0001 expired=0
localhost-dir: next_vol.c:179-2 return ok=1 find_next_vol
localhost-dir: catreq.c:147-2 find_media ok=1 idx=1 vol=TestVolume0001
localhost-dir: catreq.c:100-2 Vol Info for Second.2008-11-17_09.03.53.05: 1000 OK VolName=TestVolume0001 VolJobs=0 VolFiles=0 VolBlocks=0 VolBytes=1 VolMounts=1 VolErrors=0 VolWrites=1 MaxVolBytes=0 VolCapacityBytes=0 VolStatus=Recycle Slot=0 MaxVolJobs=1 MaxVolFiles=0 InChanger=0 VolReadTime=0 VolWriteTime=10 EndFile=0 EndBlock=0 VolParts=0 LabelType=0 MediaId=1
localhost-sd: askdir.c:182-2 <dird 1000 OK VolName=TestVolume0001 VolJobs=0 VolFiles=0 VolBlocks=0 VolBytes=1 VolMounts=1 VolErrors=0 VolWrites=1 MaxVolBytes=0 VolCapacityBytes=0 VolStatus=Recycle Slot=0 MaxVolJobs=1 MaxVolFiles=0 InChanger=0 VolReadTime=0 VolWriteTime=10 EndFile=0 EndBlock=0 VolParts=0 LabelType=0 MediaId=1
localhost-sd: askdir.c:205-2 do_reqest_vol_info return true slot=0 Volume=TestVolume0001
localhost-sd: vol_mgr.c:512-2 find_vol=TestVolume0001 found=1
localhost-sd: vol_mgr.c:212-2 List find_volume: TestVolume0001 in_use=1 on device "FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: vol_mgr.c:711-2 Vol=TestVolume0001 on same dev.
localhost-sd: askdir.c:285-2 Call reserve_volume. Vol=TestVolume0001
localhost-sd: vol_mgr.c:350-2 enter reserve_volume=TestVolume0001 drive="FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: vol_mgr.c:212-2 List begin reserve_volume: TestVolume0001 in_use=1 on device "FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: vol_mgr.c:365-2 Vol attached=TestVolume0001, newvol=TestVolume0001 volinuse=1 on "FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: vol_mgr.c:373-2 === set reserved vol=TestVolume0001 dev="FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: vol_mgr.c:454-2 === set in_use. vol=TestVolume0001 dev="FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: vol_mgr.c:212-2 List end new volume: TestVolume0001 in_use=1 on device "FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: askdir.c:292-2 dir_find_next_appendable_volume return true. vol=TestVolume0001
localhost-sd: reserve.c:677-2 looking for Volume=TestVolume0001
localhost-sd: reserve.c:734-2 >dird: 3000 OK use device device=FileStorage
localhost-sd: reserve.c:588-2 Device FileStorage reserved=1 for append.
localhost-sd: reserve.c:513-2 available device found=FileStorage
localhost-sd: reserve.c:528-2 OK dev found. Vol=TestVolume0001
localhost-dir: msgchan.c:288-2 <stored: 3000 OK use device device=FileStorage
localhost-dir: msgchan.c:325-2 Start SD msg_thread.
localhost-sd: job.c:190-2 Second.2008-11-17_09.03.53.05 waiting 1800 sec for FD to contact SD key=JMEA-KPAM-PHEL-CAJI-FBMC-IKHA-OKLM-JJNF
localhost-dir: msgchan.c:376-2 Start msg_thread loop
localhost-dir: msgchan.c:337-2 SD msg_thread started. use=2
localhost-dir: backup.c:242-2 Storage daemon connection OK
localhost-dir: bsock.c:201-2 Current host[ipv4:127.0.0.1:8102] All host[ipv4:127.0.0.1:8102] 
localhost-dir: bsock.c:155-2 who=Client: localhost-fd host=localhost port=8102
localhost-dir: fd_cmds.c:103-2 Opened connection with File daemon
localhost-dir: authenticate.c:196-2 Sent: Hello Director localhost-dir calling
localhost-dir: cram-md5.c:133-2 cram-get received: auth cram-md5 <840230668.1226912636@localhost-fd> ssl=0
localhost-dir: cram-md5.c:152-2 sending resp to challenge: y/+Jsz/MMHxwDQF3J/Eo7D
localhost-dir: cram-md5.c:80-2 send: auth cram-md5 <1819971086.1226912636@localhost-dir> ssl=0
localhost-dir: cram-md5.c:99-2 Authenticate OK /7+eM9+Y06/9VyEnUXNPCC
localhost-dir: authenticate.c:263-2 >filed: 1000 OK auth
localhost-dir: authenticate.c:272-2 <filed: 2000 OK Hello 1
localhost-dir: fd_cmds.c:124-2 >filed: JobId=2 Job=Second.2008-11-17_09.03.53.05 SDid=2 SDtime=1226912624 Authorization=JMEA-KPAM-PHEL-CAJI-FBMC-IKHA-OKLM-JJNF
localhost-dir: fd_cmds.c:126-2 <filed: 2000 OK Job 2.5.20 (13Nov08) i686-pc-linux-gnu,unknown,unknownlocalhost-dir: fd_cmds.c:292-2 >filed: level = full  mtime_only=0
localhost-sd: bnet.c:669-0 who=client host=127.0.0.1 port=42783
localhost-sd: dircmd.c:171-0 Conn: Hello Start Job Second.2008-11-17_09.03.53.05
localhost-sd: dircmd.c:177-0 Got a FD connection at 17-Nov-2008 09:03:56
localhost-sd: dircmd.c:178-0 Hello Start Job Second.2008-11-17_09.03.53.05
localhost-sd: job.c:238-0 Found Job Second.2008-11-17_09.03.53.05
localhost-sd: cram-md5.c:73-0 send: auth cram-md5 <502115240.1226912636@localhost-sd> ssl=0
localhost-sd: cram-md5.c:133-0 cram-get received: auth cram-md5 <255134222.1226912636@localhost-fd> ssl=0
localhost-sd: cram-md5.c:152-0 sending resp to challenge: Ew/Oo+spPUc0FwoS/7+JWD
localhost-dir: fd_cmds.c:588-2 bdird: sending runscripts to fd
localhost-sd: job.c:261-0 OK Authentication jid=2 Job Second.2008-11-17_09.03.53.05
localhost-sd: job.c:205-2 Auth=1 canceled=0 errstat=0
localhost-sd: job.c:211-2 Running job Second.2008-11-17_09.03.53.05
localhost-sd: fd_cmds.c:122-2 Start run Job=Second.2008-11-17_09.03.53.05
localhost-sd: fd_cmds.c:160-2 <filed: append open session
localhost-sd: fd_cmds.c:227-2 Append open session: append open session
localhost-sd: fd_cmds.c:237-2 >filed: 3000 OK open ticket = 2
localhost-sd: fd_cmds.c:160-2 <filed: append data 2
localhost-sd: fd_cmds.c:190-2 Append data: append data 2
localhost-sd: fd_cmds.c:192-2 <bfiled: append data 2
localhost-sd: append.c:73-2 Start append data. res=1
localhost-sd: acquire.c:346-2 acquire_append device is disk
localhost-sd: askdir.c:230-2 >dird CatReq Job=Second.2008-11-17_09.03.53.05 GetVolInfo VolName=TestVolume0001 write=1
localhost-dir: catreq.c:126-2 catreq CatReq Job=Second.2008-11-17_09.03.53.05 GetVolInfo VolName=TestVolume0001 write=1
localhost-dir: catreq.c:163-2 CatReq GetVolInfo Vol=TestVolume0001
localhost-dir: next_vol.c:246-2 Vol=TestVolume0001 expired=0
localhost-sd: askdir.c:182-2 <dird 1000 OK VolName=TestVolume0001 VolJobs=0 VolFiles=0 VolBlocks=0 VolBytes=1 VolMounts=1 VolErrors=0 VolWrites=1 MaxVolBytes=0 VolCapacityBytes=0 VolStatus=Recycle Slot=0 MaxVolJobs=1 MaxVolFiles=0 InChanger=0 VolReadTime=0 VolWriteTime=10 EndFile=0 EndBlock=0 VolParts=0 LabelType=0 MediaId=1
localhost-sd: askdir.c:205-2 do_reqest_vol_info return true slot=0 Volume=TestVolume0001
localhost-sd: mount.c:77-2 Enter mount_next_volume(release=0) dev="FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: mount.c:88-2 mount_next_vol retry=0
localhost-sd: askdir.c:230-2 >dird CatReq Job=Second.2008-11-17_09.03.53.05 GetVolInfo VolName=TestVolume0001 write=1
localhost-dir: catreq.c:100-2 Vol Info for Second.2008-11-17_09.03.53.05: 1000 OK VolName=TestVolume0001 VolJobs=0 VolFiles=0 VolBlocks=0 VolBytes=1 VolMounts=1 VolErrors=0 VolWrites=1 MaxVolBytes=0 VolCapacityBytes=0 VolStatus=Recycle Slot=0 MaxVolJobs=1 MaxVolFiles=0 InChanger=0 VolReadTime=0 VolWriteTime=10 EndFile=0 EndBlock=0 VolParts=0 LabelType=0 MediaId=1
localhost-dir: catreq.c:126-2 catreq CatReq Job=Second.2008-11-17_09.03.53.05 GetVolInfo VolName=TestVolume0001 write=1
localhost-dir: catreq.c:163-2 CatReq GetVolInfo Vol=TestVolume0001
localhost-dir: next_vol.c:246-2 Vol=TestVolume0001 expired=0
localhost-sd: askdir.c:182-2 <dird 1000 OK VolName=TestVolume0001 VolJobs=0 VolFiles=0 VolBlocks=0 VolBytes=1 VolMounts=1 VolErrors=0 VolWrites=1 MaxVolBytes=0 VolCapacityBytes=0 VolStatus=Recycle Slot=0 MaxVolJobs=1 MaxVolFiles=0 InChanger=0 VolReadTime=0 VolWriteTime=10 EndFile=0 EndBlock=0 VolParts=0 LabelType=0 MediaId=1
localhost-sd: askdir.c:205-2 do_reqest_vol_info return true slot=0 Volume=TestVolume0001
localhost-sd: mount.c:128-2 After find_next_append. Vol=TestVolume0001 Slot=0 Parts=0
localhost-sd: autochanger.c:121-2 Device "FileStorage" (/usr/bin/bacula/regress/tmp) is not an autochanger
localhost-sd: mount.c:149-2 autoload_dev returns 0
localhost-sd: mount.c:179-2 want vol=TestVolume0001 devvol=TestVolume0001 dev="FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: label.c:81-2 Enter read_volume_label res=1 device="FileStorage" (/usr/bin/bacula/regress/tmp) vol=TestVolume0001 dev_Vol=TestVolume0001
localhost-sd: label.c:130-2 Big if statement in read_volume_label
localhost-sd: label.c:202-2 Compare Vol names: VolName=TestVolume0001 hdr=TestVolume0001

Volume Label:
Id                : Bacula 1.0 immortal
VerNo             : 11
VolName           : TestVolume0001
PrevVolName       : 
VolFile           : 0
LabelType         : VOL_LABEL
LabelSize         : 174
PoolName          : Default
MediaType         : File
PoolType          : Backup
HostName          : backuppilot
Date label written: 17-Nov-2008 09:03
localhost-sd: label.c:223-2 Leave read_volume_label() VOL_OK
localhost-sd: label.c:236-2 Call reserve_volume=TestVolume0001
localhost-sd: vol_mgr.c:350-2 enter reserve_volume=TestVolume0001 drive="FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: vol_mgr.c:212-2 List begin reserve_volume: TestVolume0001 in_use=1 on device "FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: vol_mgr.c:365-2 Vol attached=TestVolume0001, newvol=TestVolume0001 volinuse=1 on "FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: vol_mgr.c:373-2 === set reserved vol=TestVolume0001 dev="FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: vol_mgr.c:454-2 === set in_use. vol=TestVolume0001 dev="FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: vol_mgr.c:212-2 List end new volume: TestVolume0001 in_use=1 on device "FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: mount.c:363-2 Want dirVol=TestVolume0001 dirStat=Recycle
localhost-sd: mount.c:370-2 Vol OK name=TestVolume0001
localhost-sd: label.c:267-2 write Label in write_volume_label_to_block()
localhost-sd: label.c:590-2 Created Vol label rec: FI=VOL_LABEL len=174
localhost-sd: label.c:282-2 Wrote label of 174 bytes to block. Vol=TestVolume0001
localhost-sd: label.c:438-2 wrote vol label to block. Vol=TestVolume0001
localhost-sd: label.c:456-2 Doing recycle. Vol=TestVolume0001
localhost-sd: dev.c:1986-2 truncate "FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-dir: catreq.c:100-2 Vol Info for Second.2008-11-17_09.03.53.05: 1000 OK VolName=TestVolume0001 VolJobs=0 VolFiles=0 VolBlocks=0 VolBytes=1 VolMounts=1 VolErrors=0 VolWrites=1 MaxVolBytes=0 VolCapacityBytes=0 VolStatus=Recycle Slot=0 MaxVolJobs=1 MaxVolFiles=0 InChanger=0 VolReadTime=0 VolWriteTime=10 EndFile=0 EndBlock=0 VolParts=0 LabelType=0 MediaId=1
localhost-sd: label.c:510-2 dir_update_vol_info. Set Append vol=TestVolume0001
localhost-sd: askdir.c:345-2 Update cat VolFiles=0
localhost-sd: askdir.c:368-2 >dird CatReq Job=Second.2008-11-17_09.03.53.05 UpdateMedia VolName=TestVolume0001 VolJobs=0 VolFiles=0 VolBlocks=0 VolBytes=210 VolMounts=2 VolErrors=0 VolWrites=2 MaxVolBytes=0 EndTime=1226912636 VolStatus=Append Slot=0 relabel=1 InChanger=0 VolReadTime=0 VolWriteTime=168 VolFirstWritten=0 VolParts=0
localhost-dir: catreq.c:126-2 catreq CatReq Job=Second.2008-11-17_09.03.53.05 UpdateMedia VolName=TestVolume0001 VolJobs=0 VolFiles=0 VolBlocks=0 VolBytes=210 VolMounts=2 VolErrors=0 VolWrites=2 MaxVolBytes=0 EndTime=1226912636 VolStatus=Append Slot=0 relabel=1 InChanger=0 VolReadTime=0 VolWriteTime=168 VolFirstWritten=0 VolParts=0
localhost-dir: sql_update.c:338-2 update_media: FirstWritten=1226912636
localhost-dir: next_vol.c:246-2 Vol=TestVolume0001 expired=0
localhost-sd: askdir.c:182-2 <dird 1000 OK VolName=TestVolume0001 VolJobs=0 VolFiles=0 VolBlocks=0 VolBytes=210 VolMounts=2 VolErrors=0 VolWrites=2 MaxVolBytes=0 VolCapacityBytes=0 VolStatus=Append Slot=0 MaxVolJobs=1 MaxVolFiles=0 InChanger=0 VolReadTime=0 VolWriteTime=168 EndFile=0 EndBlock=0 VolParts=0 LabelType=0 MediaId=1
localhost-sd: askdir.c:205-2 do_reqest_vol_info return true slot=0 Volume=TestVolume0001
localhost-sd: label.c:527-2 OK from rewrite vol label. Vol=TestVolume0001
localhost-sd: mount.c:293-2 set APPEND, normal return from mount_next_write_volume. dev="FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: askdir.c:345-2 Update cat VolFiles=0
localhost-sd: askdir.c:368-2 >dird CatReq Job=Second.2008-11-17_09.03.53.05 UpdateMedia VolName=TestVolume0001 VolJobs=1 VolFiles=0 VolBlocks=0 VolBytes=210 VolMounts=2 VolErrors=0 VolWrites=2 MaxVolBytes=0 EndTime=1226912636 VolStatus=Append Slot=0 relabel=0 InChanger=0 VolReadTime=0 VolWriteTime=168 VolFirstWritten=0 VolParts=0
localhost-dir: catreq.c:100-2 Vol Info for Second.2008-11-17_09.03.53.05: 1000 OK VolName=TestVolume0001 VolJobs=0 VolFiles=0 VolBlocks=0 VolBytes=210 VolMounts=2 VolErrors=0 VolWrites=2 MaxVolBytes=0 VolCapacityBytes=0 VolStatus=Append Slot=0 MaxVolJobs=1 MaxVolFiles=0 InChanger=0 VolReadTime=0 VolWriteTime=168 EndFile=0 EndBlock=0 VolParts=0 LabelType=0 MediaId=1
localhost-dir: catreq.c:126-2 catreq CatReq Job=Second.2008-11-17_09.03.53.05 UpdateMedia VolName=TestVolume0001 VolJobs=1 VolFiles=0 VolBlocks=0 VolBytes=210 VolMounts=2 VolErrors=0 VolWrites=2 MaxVolBytes=0 EndTime=1226912636 VolStatus=Append Slot=0 relabel=0 InChanger=0 VolReadTime=0 VolWriteTime=168 VolFirstWritten=0 VolParts=0
localhost-dir: sql_update.c:338-2 update_media: FirstWritten=1226912636
localhost-dir: next_vol.c:215-2 MaxVolJobs=1 JobId=2 Vol=TestVolume0001
localhost-dir: next_vol.c:240-2 Vol=TestVolume0001 has expired update media record
localhost-dir: sql_update.c:338-2 update_media: FirstWritten=1226912636
localhost-dir: next_vol.c:246-2 Vol=TestVolume0001 expired=1
localhost-sd: askdir.c:182-2 <dird 1000 OK VolName=TestVolume0001 VolJobs=1 VolFiles=0 VolBlocks=0 VolBytes=210 VolMounts=2 VolErrors=0 VolWrites=2 MaxVolBytes=0 VolCapacityBytes=0 VolStatus=Used Slot=0 MaxVolJobs=1 MaxVolFiles=0 InChanger=0 VolReadTime=0 VolWriteTime=168 EndFile=0 EndBlock=0 VolParts=0 LabelType=0 MediaId=1
localhost-sd: askdir.c:205-2 do_reqest_vol_info return true slot=0 Volume=TestVolume0001
localhost-sd: reserve.c:138-2 Dec reserve=0 dev="FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: append.c:96-2 Begin append device="FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: append.c:101-2 Just after acquire_device_for_append
localhost-sd: label.c:704-2 session_label record=80dab08
localhost-sd: label.c:749-2 Write sesson_label record JobId=2 FI=SOS_LABEL SessId=2 Strm=2 len=146 remainder=0
localhost-sd: label.c:753-2 Leave write_session_label Block=209d File=0d
localhost-dir: catreq.c:100-2 Vol Info for Second.2008-11-17_09.03.53.05: 1000 OK VolName=TestVolume0001 VolJobs=1 VolFiles=0 VolBlocks=0 VolBytes=210 VolMounts=2 VolErrors=0 VolWrites=2 MaxVolBytes=0 VolCapacityBytes=0 VolStatus=Used Slot=0 MaxVolJobs=1 MaxVolFiles=0 InChanger=0 VolReadTime=0 VolWriteTime=168 EndFile=0 EndBlock=0 VolParts=0 LabelType=0 MediaId=1
localhost-dir: sql.c:737-2 initdb ref=1 connected=1 db=8129478
localhost-sd: fd_cmds.c:160-2 <filed: append end session 2
localhost-sd: fd_cmds.c:210-2 store<file: append end session 2
localhost-sd: fd_cmds.c:160-2 <filed: append close session 2
localhost-sd: fd_cmds.c:251-2 <filed: append close session 2
localhost-sd: fd_cmds.c:258-2 >filed: 3000 OK close Status = 84
localhost-sd: fd_cmds.c:160-1 <filed: append end session 1
localhost-sd: fd_cmds.c:210-1 store<file: append end session 1
localhost-sd: fd_cmds.c:160-1 <filed: append close session 1
localhost-sd: fd_cmds.c:251-1 <filed: append close session 1
localhost-sd: fd_cmds.c:258-1 >filed: 3000 OK close Status = 84
localhost-dir: backup.c:373-2 FDStatus=T
localhost-sd: label.c:704-2 session_label record=80dab08
localhost-sd: label.c:749-2 Write sesson_label record JobId=2 FI=EOS_LABEL SessId=2 Strm=2 len=182 remainder=0
localhost-sd: label.c:753-2 Leave write_session_label Block=751887555d File=0d
localhost-sd: append.c:301-2 back from write_end_session_label()
localhost-dir: backup.c:373-1 FDStatus=T
localhost-sd: label.c:704-1 session_label record=80dab08
localhost-sd: label.c:749-1 Write sesson_label record JobId=1 FI=EOS_LABEL SessId=1 Strm=1 len=180 remainder=0
localhost-sd: label.c:753-1 Leave write_session_label Block=751930435d File=0d
localhost-sd: append.c:301-1 back from write_end_session_label()
localhost-sd: acquire.c:427-1 release_device device "FileStorage" (/usr/bin/bacula/regress/tmp) is disk
localhost-sd: acquire.c:450-1 There are 1 writers in release_device
localhost-dir: catreq.c:126-1 catreq CatReq Job=First.2008-11-17_09.03.48.03 CreateJobMedia FirstIndex=1 LastIndex=4447 StartFile=0 EndFile=0 StartBlock=210 EndBlock=751973313 Copy=0 Strip=0 MediaId=1
localhost-sd: askdir.c:412-1 >dird CatReq Job=First.2008-11-17_09.03.48.03 CreateJobMedia FirstIndex=1 LastIndex=4447 StartFile=0 EndFile=0 StartBlock=210 EndBlock=751973313 Copy=0 Strip=0 MediaId=1
localhost-sd: askdir.c:419-1 <dird 1000 OK CreateJobMedia
localhost-sd: askdir.c:345-1 Update cat VolFiles=0
localhost-dir: catreq.c:126-1 catreq CatReq Job=First.2008-11-17_09.03.48.03 UpdateMedia VolName=TestVolume0001 VolJobs=1 VolFiles=0 VolBlocks=11657 VolBytes=751973314 VolMounts=2 VolErrors=0 VolWrites=11659 MaxVolBytes=0 EndTime=1226912726 VolStatus=Used Slot=0 relabel=0 InChanger=0 VolReadTime=0 VolWriteTime=21463245 VolFirstWritten=0 VolParts=0
localhost-dir: sql_update.c:338-1 update_media: FirstWritten=1226912636
localhost-dir: next_vol.c:246-1 Vol=TestVolume0001 expired=0
localhost-dir: catreq.c:100-1 Vol Info for First.2008-11-17_09.03.48.03: 1000 OK VolName=TestVolume0001 VolJobs=1 VolFiles=0 VolBlocks=11657 VolBytes=751973314 VolMounts=2 VolErrors=0 VolWrites=11659 MaxVolBytes=0 VolCapacityBytes=0 VolStatus=Used Slot=0 MaxVolJobs=1 MaxVolFiles=0 InChanger=0 VolReadTime=0 VolWriteTime=21463245 EndFile=0 EndBlock=751973313 VolParts=0 LabelType=0 MediaId=1
localhost-sd: askdir.c:368-1 >dird CatReq Job=First.2008-11-17_09.03.48.03 UpdateMedia VolName=TestVolume0001 VolJobs=1 VolFiles=0 VolBlocks=11657 VolBytes=751973314 VolMounts=2 VolErrors=0 VolWrites=11659 MaxVolBytes=0 EndTime=1226912726 VolStatus=Used Slot=0 relabel=0 InChanger=0 VolReadTime=0 VolWriteTime=21463245 VolFirstWritten=0 VolParts=0
localhost-sd: askdir.c:182-1 <dird 1000 OK VolName=TestVolume0001 VolJobs=1 VolFiles=0 VolBlocks=11657 VolBytes=751973314 VolMounts=2 VolErrors=0 VolWrites=11659 MaxVolBytes=0 VolCapacityBytes=0 VolStatus=Used Slot=0 MaxVolJobs=1 MaxVolFiles=0 InChanger=0 VolReadTime=0 VolWriteTime=21463245 EndFile=0 EndBlock=751973313 VolParts=0 LabelType=0 MediaId=1
localhost-sd: askdir.c:205-1 do_reqest_vol_info return true slot=0 Volume=TestVolume0001
localhost-sd: acquire.c:485-1 1 writers, 0 reserve, dev="FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: vol_mgr.c:212-1 List acquire:release_device(): TestVolume0001 in_use=1 on device "FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: acquire.c:523-1 JobId=1 broadcast wait_device_release at 17-Nov-2008 09:05:26
localhost-sd: acquire.c:427-2 release_device device "FileStorage" (/usr/bin/bacula/regress/tmp) is disk
localhost-sd: acquire.c:450-2 There are 0 writers in release_device
localhost-dir: catreq.c:126-2 catreq CatReq Job=Second.2008-11-17_09.03.53.05 CreateJobMedia FirstIndex=1 LastIndex=4447 StartFile=0 EndFile=0 StartBlock=210 EndBlock=751930435 Copy=0 Strip=0 MediaId=1
localhost-sd: askdir.c:412-2 >dird CatReq Job=Second.2008-11-17_09.03.53.05 CreateJobMedia FirstIndex=1 LastIndex=4447 StartFile=0 EndFile=0 StartBlock=210 EndBlock=751930435 Copy=0 Strip=0 MediaId=1
localhost-sd: askdir.c:419-2 <dird 1000 OK CreateJobMedia
localhost-sd: dev.c:1690-2 === weof_dev="FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: askdir.c:345-2 Update cat VolFiles=0
localhost-dir: catreq.c:126-2 catreq CatReq Job=Second.2008-11-17_09.03.53.05 UpdateMedia VolName=TestVolume0001 VolJobs=1 VolFiles=0 VolBlocks=11657 VolBytes=751973314 VolMounts=2 VolErrors=0 VolWrites=11659 MaxVolBytes=0 EndTime=1226912726 VolStatus=Used Slot=0 relabel=0 InChanger=0 VolReadTime=0 VolWriteTime=21463245 VolFirstWritten=0 VolParts=0
localhost-dir: sql_update.c:338-2 update_media: FirstWritten=1226912636
localhost-dir: next_vol.c:246-2 Vol=TestVolume0001 expired=0
localhost-dir: catreq.c:100-2 Vol Info for Second.2008-11-17_09.03.53.05: 1000 OK VolName=TestVolume0001 VolJobs=1 VolFiles=0 VolBlocks=11657 VolBytes=751973314 VolMounts=2 VolErrors=0 VolWrites=11659 MaxVolBytes=0 VolCapacityBytes=0 VolStatus=Used Slot=0 MaxVolJobs=1 MaxVolFiles=0 InChanger=0 VolReadTime=0 VolWriteTime=21463245 EndFile=0 EndBlock=751930435 VolParts=0 LabelType=0 MediaId=1
localhost-sd: askdir.c:368-2 >dird CatReq Job=Second.2008-11-17_09.03.53.05 UpdateMedia VolName=TestVolume0001 VolJobs=1 VolFiles=0 VolBlocks=11657 VolBytes=751973314 VolMounts=2 VolErrors=0 VolWrites=11659 MaxVolBytes=0 EndTime=1226912726 VolStatus=Used Slot=0 relabel=0 InChanger=0 VolReadTime=0 VolWriteTime=21463245 VolFirstWritten=0 VolParts=0
localhost-sd: askdir.c:182-2 <dird 1000 OK VolName=TestVolume0001 VolJobs=1 VolFiles=0 VolBlocks=11657 VolBytes=751973314 VolMounts=2 VolErrors=0 VolWrites=11659 MaxVolBytes=0 VolCapacityBytes=0 VolStatus=Used Slot=0 MaxVolJobs=1 MaxVolFiles=0 InChanger=0 VolReadTime=0 VolWriteTime=21463245 EndFile=0 EndBlock=751930435 VolParts=0 LabelType=0 MediaId=1
localhost-sd: askdir.c:205-2 do_reqest_vol_info return true slot=0 Volume=TestVolume0001
localhost-sd: vol_mgr.c:577-2 === set not reserved vol=TestVolume0001 num_writers=0 dev_reserved=0 dev="FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: vol_mgr.c:578-2 === clear in_use vol=TestVolume0001
localhost-sd: vol_mgr.c:606-2 === clear in_use vol=TestVolume0001
localhost-sd: vol_mgr.c:609-2 === remove volume TestVolume0001 dev="FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: acquire.c:485-2 0 writers, 0 reserve, dev="FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: dev.c:1902-2 close_dev "FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: dev.c:1892-2 Clear volhdr vol=TestVolume0001
localhost-sd: acquire.c:523-2 JobId=2 broadcast wait_device_release at 17-Nov-2008 09:05:26
localhost-sd: acquire.c:538-1 ===== Device "FileStorage" (/usr/bin/bacula/regress/tmp) released by JobId=1
localhost-sd: acquire.c:538-2 ===== Device "FileStorage" (/usr/bin/bacula/regress/tmp) released by JobId=2
localhost-sd: spool.c:632-1 Commit attributes at 17-Nov-2008 09:05:27
localhost-sd: append.c:341-1 return from do_append_data() ok=1
localhost-sd: jcr.c:184-1 write_last_jobs seek to 188
localhost-dir: sql_create.c:768-1 db_create_file_record changes=4447
localhost-dir: sql_create.c:740-1 sql_batch_end started
localhost-dir: msgchan.c:348-1 === End msg_thread. JobId=1 usecnt=2
localhost-sd: spool.c:632-2 Commit attributes at 17-Nov-2008 09:05:27
localhost-sd: append.c:341-2 return from do_append_data() ok=1
localhost-sd: jcr.c:184-2 write_last_jobs seek to 188
localhost-dir: sql_create.c:768-2 db_create_file_record changes=4447
localhost-dir: sql_create.c:740-2 sql_batch_end started
localhost-dir: msgchan.c:348-2 === End msg_thread. JobId=2 usecnt=2
localhost-dir: backup.c:450-1 Enter backup_cleanup 84 T
localhost-dir: sql_get.c:436-1 VolNam=SELECT VolumeName,MediaType,FirstIndex,LastIndex,StartFile,JobMedia.EndFile,StartBlock,JobMedia.EndBlock,Copy,Slot,StorageId FROM JobMedia,Media WHERE JobMedia.JobId=1 AND JobMedia.MediaId=Media.MediaId ORDER BY VolIndex,JobMediaId
localhost-dir: sql_get.c:379-1 VolNam=SELECT VolumeName,MAX(VolIndex) FROM JobMedia,Media WHERE JobMedia.JobId=1 AND JobMedia.MediaId=Media.MediaId GROUP BY VolumeName ORDER BY 2 ASC
localhost-dir: sql_get.c:383-1 Num rows=1
localhost-dir: backup.c:617-1 Leave backup_cleanup()
localhost-dir: ua_prune.c:396-1 Query=SELECT DISTINCT DelCandidates.JobId,DelCandidates.PurgedFiles FROM Job,DelCandidates WHERE (Job.JobId=DelCandidates.JobId AND ((DelCandidates.JobFiles=0) OR (DelCandidates.JobStatus!='T'))) OR (Job.JobTDate>1211360728 AND Job.ClientId=1 AND Job.Level='F' AND Job.JobStatus='T' AND Job.Type IN ('B','M') AND Job.FileSetId=DelCandidates.FileSetId)
localhost-dir: ua_prune.c:243-1 select now=1226912728 period=2592000 sql=SELECT count(*) from Job WHERE JobTDate<1224320728 AND ClientId=1 AND PurgedFiles=0
localhost-dir: job.c:359-1 ======== End Job stat=T ==========
localhost-dir: jcr.c:184-1 write_last_jobs seek to 188
localhost-dir: backup.c:450-2 Enter backup_cleanup 84 T
localhost-dir: sql_get.c:436-2 VolNam=SELECT VolumeName,MediaType,FirstIndex,LastIndex,StartFile,JobMedia.EndFile,StartBlock,JobMedia.EndBlock,Copy,Slot,StorageId FROM JobMedia,Media WHERE JobMedia.JobId=2 AND JobMedia.MediaId=Media.MediaId ORDER BY VolIndex,JobMediaId
localhost-dir: sql_get.c:379-2 VolNam=SELECT VolumeName,MAX(VolIndex) FROM JobMedia,Media WHERE JobMedia.JobId=2 AND JobMedia.MediaId=Media.MediaId GROUP BY VolumeName ORDER BY 2 ASC
localhost-dir: sql_get.c:383-2 Num rows=1
localhost-dir: backup.c:617-2 Leave backup_cleanup()
localhost-dir: ua_prune.c:396-2 Query=SELECT DISTINCT DelCandidates.JobId,DelCandidates.PurgedFiles FROM Job,DelCandidates WHERE (Job.JobId=DelCandidates.JobId AND ((DelCandidates.JobFiles=0) OR (DelCandidates.JobStatus!='T'))) OR (Job.JobTDate>1211360728 AND Job.ClientId=1 AND Job.Level='F' AND Job.JobStatus='T' AND Job.Type IN ('B','M') AND Job.FileSetId=DelCandidates.FileSetId)
localhost-dir: ua_prune.c:243-2 select now=1226912728 period=2592000 sql=SELECT count(*) from Job WHERE JobTDate<1224320728 AND ClientId=1 AND PurgedFiles=0
localhost-dir: job.c:359-2 ======== End Job stat=T ==========
localhost-dir: jcr.c:184-2 write_last_jobs seek to 188
messages
17-Nov 09:03 localhost-dir JobId 2: No prior Full backup Job record found.
17-Nov 09:03 localhost-dir JobId 2: No prior or suitable Full backup found in catalog. Doing FULL backup.
17-Nov 09:03 localhost-dir JobId 2: Start Backup JobId 2, Job=Second.2008-11-17_09.03.53.05
17-Nov 09:03 localhost-dir JobId 2: There are no more Jobs associated with Volume "TestVolume0001". Marking it purged.
17-Nov 09:03 localhost-dir JobId 2: All records pruned from Volume "TestVolume0001"; marking it "Purged"
17-Nov 09:03 localhost-dir JobId 2: Recycled volume "TestVolume0001"
17-Nov 09:03 localhost-dir JobId 2: Using Device "FileStorage"
17-Nov 09:03 localhost-sd JobId 2: Recycled volume "TestVolume0001" on device "FileStorage" (/usr/bin/bacula/regress/tmp), all previous data lost.
17-Nov 09:03 localhost-dir JobId 2: Max Volume jobs exceeded. Marking Volume "TestVolume0001" as Used.
17-Nov 09:05 localhost-sd JobId 2: Job write elapsed time = 00:01:30, Transfer rate = 4.326 M bytes/second
17-Nov 09:05 localhost-sd JobId 1: Job write elapsed time = 00:01:36, Transfer rate = 4.056 M bytes/second
17-Nov 09:05 localhost-dir JobId 1: Bacula localhost-dir 2.5.20 (13Nov08): 17-Nov-2008 09:05:27
  Build OS:               i686-pc-linux-gnu unknown unknown
  JobId:                  1
  Job:                    First.2008-11-17_09.03.48.03
  Backup Level:           Full (upgraded from Incremental)
  Client:                 "localhost-fd" 2.5.20 (13Nov08) i686-pc-linux-gnu,unknown,unknown
  FileSet:                "Set1" 2008-11-17 09:03:48
  Pool:                   "Default" (From Job resource)
  Catalog:                "MyCatalog" (From Client resource)
  Storage:                "File" (From Job resource)
  Scheduled time:         17-Nov-2008 09:03:48
  Start time:             17-Nov-2008 09:03:50
  End time:               17-Nov-2008 09:05:27
  Elapsed time:           1 min 37 secs
  Priority:               10
  FD Files Written:       4,447
  SD Files Written:       4,447
  FD Bytes Written:       388,725,140 (388.7 MB)
  SD Bytes Written:       389,388,186 (389.3 MB)
  Rate:                   4007.5 KB/s
  Software Compression:   None
  VSS:                    no
  Encryption:             no
  Accurate:               no
  Volume name(s):         TestVolume0001
  Volume Session Id:      1
  Volume Session Time:    1226912624
  Last Volume Bytes:      751,973,314 (751.9 MB)
  Non-fatal FD errors:    0
  SD Errors:              0
  FD termination status:  OK
  SD termination status:  OK
  Termination:            Backup OK

17-Nov 09:05 localhost-dir JobId 1: Begin pruning Jobs.
17-Nov 09:05 localhost-dir JobId 1: No Jobs found to prune.
17-Nov 09:05 localhost-dir JobId 1: Begin pruning Files.
17-Nov 09:05 localhost-dir JobId 1: No Files found to prune.
17-Nov 09:05 localhost-dir JobId 1: End auto prune.

17-Nov 09:05 localhost-dir JobId 2: Bacula localhost-dir 2.5.20 (13Nov08): 17-Nov-2008 09:05:28
  Build OS:               i686-pc-linux-gnu unknown unknown
  JobId:                  2
  Job:                    Second.2008-11-17_09.03.53.05
  Backup Level:           Full (upgraded from Incremental)
  Client:                 "localhost-fd" 2.5.20 (13Nov08) i686-pc-linux-gnu,unknown,unknown
  FileSet:                "Set2" 2008-11-17 09:03:53
  Pool:                   "Default" (From Job resource)
  Catalog:                "MyCatalog" (From Client resource)
  Storage:                "File" (From Job resource)
  Scheduled time:         17-Nov-2008 09:03:53
  Start time:             17-Nov-2008 09:03:56
  End time:               17-Nov-2008 09:05:28
  Elapsed time:           1 min 32 secs
  Priority:               10
  FD Files Written:       4,447
  SD Files Written:       4,447
  FD Bytes Written:       388,725,140 (388.7 MB)
  SD Bytes Written:       389,388,186 (389.3 MB)
  Rate:                   4225.3 KB/s
  Software Compression:   None
  VSS:                    no
  Encryption:             no
  Accurate:               no
  Volume name(s):         TestVolume0001
  Volume Session Id:      2
  Volume Session Time:    1226912624
  Last Volume Bytes:      751,973,314 (751.9 MB)
  Non-fatal FD errors:    0
  SD Errors:              0
  FD termination status:  OK
  SD termination status:  OK
  Termination:            Backup OK

17-Nov 09:05 localhost-dir JobId 2: Begin pruning Jobs.
17-Nov 09:05 localhost-dir JobId 2: No Jobs found to prune.
17-Nov 09:05 localhost-dir JobId 2: Begin pruning Files.
17-Nov 09:05 localhost-dir JobId 2: No Files found to prune.
17-Nov 09:05 localhost-dir JobId 2: End auto prune.

restore fileset=Set1 where=/usr/bin/bacula/regress/tmp/bacula-restores select all storage=File done
Automatically selected Client: localhost-fd
+-------+-------+----------+-----------+---------------------+----------------+
| JobId | Level | JobFiles | JobBytes  | StartTime           | VolumeName     |
+-------+-------+----------+-----------+---------------------+----------------+
| 1     | F     | 4447     | 388725140 | 2008-11-17 09:03:50 | TestVolume0001 |
+-------+-------+----------+-----------+---------------------+----------------+
You have selected the following JobId: 1

Building directory tree for JobId(s) 1 ...  +++++++++++++++++++++++++++++++++++++++++++++++
4,219 files inserted into the tree and marked for extraction.
localhost-dir: sql_get.c:436-0 VolNam=SELECT VolumeName,MediaType,FirstIndex,LastIndex,StartFile,JobMedia.EndFile,StartBlock,JobMedia.EndBlock,Copy,Slot,StorageId FROM JobMedia,Media WHERE JobMedia.JobId=1 AND JobMedia.MediaId=Media.MediaId ORDER BY VolIndex,JobMediaId
Bootstrap records written to /usr/bin/bacula/regress/working/localhost-dir.restore.1.bsr

The job will require the following
   Volume(s)                 Storage(s)                SD Device(s)
===========================================================================
   
   TestVolume0001            File                      FileStorage              


4,447 files selected to be restored.

Volume="TestVolume0001"
MediaType="File"
Device="FileStorage"
VolSessionId=1
VolSessionTime=1226912624
VolFile=0
VolBlock=210-751973313
FileIndex=1-4447
Count=4447
localhost-dir: ua_run.c:1323-0 Using pool Default
localhost-dir: job.c:1264-0 wstorage=File
localhost-dir: job.c:1273-0 wstore=File where=Job resource
localhost-dir: job.c:1298-0 wstore=File where=command line
Run Restore job
JobName:         RestoreFiles
Bootstrap:       /usr/bin/bacula/regress/working/localhost-dir.restore.1.bsr
Where:           /usr/bin/bacula/regress/tmp/bacula-restores
Replace:         always
FileSet:         Set1
Backup Client:   localhost-fd
Restore Client:  localhost-fd
Storage:         File
When:            2008-11-17 09:05:29
Catalog:         MyCatalog
Priority:        10
Plugin Options:  *None*
OK to run? (yes/mod/no): yes
localhost-dir: ua_run.c:178-0 JobId=0 using pool Default priority=10
localhost-dir: job.c:925-0 JobId=0 created Job=RestoreFiles.2008-11-17_09.05.29.06
localhost-dir: job.c:127-0 Open database
localhost-dir: job.c:142-0 DB opened
localhost-dir: job.c:798-0 Created Client localhost-fd record 1
localhost-dir: job.c:173-3 Created job record JobId=3 Name=RestoreFiles.2008-11-17_09.05.29.06 Type=R Level=F
localhost-dir: ua_run.c:182-3 JobId=3 NewJobId=3 using pool Default priority=10
Job queued. JobId=3
wait
localhost-dir: restore.c:88-3 Updated job start record
localhost-dir: restore.c:90-3 RestoreJobId=0
localhost-dir: restore.c:109-3 Open connection with storage daemon
localhost-dir: msgchan.c:104-3 bnet_connect to Storage daemon localhost:8103
localhost-dir: bsock.c:201-3 Current host[ipv4:127.0.0.1:8103] All host[ipv4:127.0.0.1:8103] 
localhost-sd: bnet.c:669-0 who=client host=127.0.0.1 port=42783
localhost-dir: bsock.c:155-3 who=Storage daemon host=localhost port=8103
localhost-sd: dircmd.c:171-0 Conn: Hello Director localhost-dir calling
localhost-sd: dircmd.c:187-0 Got a DIR connection at 17-Nov-2008 09:05:31
localhost-sd: cram-md5.c:73-0 send: auth cram-md5 <798389466.1226912731@localhost-sd> ssl=0
localhost-dir: cram-md5.c:133-3 cram-get received: auth cram-md5 <798389466.1226912731@localhost-sd> ssl=0
localhost-dir: cram-md5.c:152-3 sending resp to challenge: 5X+8ki+05S/c++0DGT+5vA
localhost-dir: cram-md5.c:80-3 send: auth cram-md5 <910745367.1226912731@localhost-dir> ssl=0
localhost-sd: cram-md5.c:133-0 cram-get received: auth cram-md5 <910745367.1226912731@localhost-dir> ssl=0
localhost-sd: cram-md5.c:152-0 sending resp to challenge: +V+fcBFs0w+3y04fS4YC4B
localhost-dir: cram-md5.c:99-3 Authenticate OK +V+fcBFs0w+3y04fS4YC4B
localhost-dir: authenticate.c:152-3 >stored: 1000 OK auth
localhost-sd: dircmd.c:209-0 Message channel init completed.
localhost-dir: authenticate.c:159-3 <stored: 3000 OK Hello
localhost-dir: msgchan.c:192-3 >stored: JobId=3 job=RestoreFiles.2008-11-17_09.05.29.06 job_name=RestoreFiles client_name=localhost-fd type=82 level=70 FileSet=Set1 NoAttr=0 SpoolAttr=0 FileSetMD5=B5lTmCERCG+gRWNQQg/88B SpoolData=0 WritePartAfterJob=1 PreferMountedVols=1 SpoolSize=0

localhost-sd: job.c:92-0 <dird: JobId=3 job=RestoreFiles.2008-11-17_09.05.29.06 job_name=RestoreFiles client_name=localhost-fd type=82 level=70 FileSet=Set1 NoAttr=0 SpoolAttr=0 FileSetMD5=B5lTmCERCG+gRWNQQg/88B SpoolData=0 WritePartAfterJob=1 PreferMountedVols=1 SpoolSize=0
localhost-sd: job.c:157-3 >dird jid=3: 3000 OK Job SDid=3 SDtime=1226912624 Authorization=BPJC-IBOD-DDHI-BBDO-DMEO-LEEP-BFKN-MPBG
localhost-dir: msgchan.c:194-3 <stored: 3000 OK Job SDid=3 SDtime=1226912624 Authorization=BPJC-IBOD-DDHI-BBDO-DMEO-LEEP-BFKN-MPBG
localhost-dir: msgchan.c:202-3 sd_auth_key=BPJC-IBOD-DDHI-BBDO-DMEO-LEEP-BFKN-MPBG
localhost-dir: msgchan.c:233-3 Rstore=File
localhost-dir: msgchan.c:240-3 rstore >stored: use storage=File media_type=File pool_name=Default pool_type=Backup append=0 copy=0 stripe=0
localhost-dir: msgchan.c:247-3 >stored: use device=FileStorage
localhost-sd: reserve.c:198-3 <dird: use storage=File media_type=File pool_name=Default pool_type=Backup append=0 copy=0 stripe=0
localhost-sd: reserve.c:227-3 <dird device: use device=FileStorage
localhost-sd: reserve.c:243-3 Storage=File media_type=File pool=Default pool_type=Backup append=0
localhost-sd: reserve.c:245-3      Device=FileStorage
localhost-sd: reserve.c:419-3 Start find_suit_dev PrefMnt=1 exact=1 suitable=0 chgronly=0 any=0
localhost-sd: reserve.c:544-3 search res for FileStorage
localhost-sd: reserve.c:578-3 Try match res=FileStorage
localhost-sd: reserve.c:615-3 chk MediaType device=File request=File
localhost-sd: reserve.c:638-3 try reserve FileStorage
localhost-sd: reserve.c:129-3 Inc reserve=0 dev="FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: reserve.c:721-3 Read reserved=1 dev_name=FileStorage mediatype=File pool=Default ok=1
localhost-sd: reserve.c:734-3 >dird: 3000 OK use device device=FileStorage
localhost-sd: reserve.c:591-3 Device FileStorage reserved=1 for read.
localhost-sd: reserve.c:513-3 available device found=FileStorage
localhost-sd: reserve.c:528-3 OK dev found. Vol=
localhost-dir: msgchan.c:253-3 <stored: 3000 OK use device device=FileStorage
localhost-dir: msgchan.c:325-3 Start SD msg_thread.
localhost-sd: job.c:190-3 RestoreFiles.2008-11-17_09.05.29.06 waiting 1800 sec for FD to contact SD key=BPJC-IBOD-DDHI-BBDO-DMEO-LEEP-BFKN-MPBG
localhost-dir: msgchan.c:376-3 Start msg_thread loop
localhost-dir: msgchan.c:337-3 SD msg_thread started. use=2
localhost-dir: restore.c:132-3 Storage daemon connection OK
localhost-dir: bsock.c:201-3 Current host[ipv4:127.0.0.1:8102] All host[ipv4:127.0.0.1:8102] 
localhost-dir: bsock.c:155-3 who=Client: localhost-fd host=localhost port=8102
localhost-dir: fd_cmds.c:103-3 Opened connection with File daemon
localhost-dir: authenticate.c:196-3 Sent: Hello Director localhost-dir calling
localhost-dir: cram-md5.c:133-3 cram-get received: auth cram-md5 <1668670507.1226912731@localhost-fd> ssl=0
localhost-dir: cram-md5.c:152-3 sending resp to challenge: Ml9MpV/5WmVROkZ/b/+/1C
localhost-dir: cram-md5.c:80-3 send: auth cram-md5 <129262954.1226912731@localhost-dir> ssl=0
localhost-dir: cram-md5.c:99-3 Authenticate OK BD+FQj+eE3+0Wz+FV9oPlD
localhost-dir: authenticate.c:263-3 >filed: 1000 OK auth
localhost-dir: authenticate.c:272-3 <filed: 2000 OK Hello 1
localhost-dir: fd_cmds.c:124-3 >filed: JobId=3 Job=RestoreFiles.2008-11-17_09.05.29.06 SDid=3 SDtime=1226912624 Authorization=BPJC-IBOD-DDHI-BBDO-DMEO-LEEP-BFKN-MPBG
localhost-dir: fd_cmds.c:126-3 <filed: 2000 OK Job 2.5.20 (13Nov08) i686-pc-linux-gnu,unknown,unknownlocalhost-dir: restore.c:155-3 dird>filed: storage address=localhost port=8103 ssl=0

localhost-sd: bnet.c:669-0 who=client host=127.0.0.1 port=42783
localhost-sd: dircmd.c:171-0 Conn: Hello Start Job RestoreFiles.2008-11-17_09.05.29.06
localhost-sd: dircmd.c:177-0 Got a FD connection at 17-Nov-2008 09:05:31
localhost-sd: dircmd.c:178-0 Hello Start Job RestoreFiles.2008-11-17_09.05.29.06
localhost-sd: job.c:238-0 Found Job RestoreFiles.2008-11-17_09.05.29.06
localhost-sd: cram-md5.c:73-0 send: auth cram-md5 <1971583870.1226912731@localhost-sd> ssl=0
localhost-sd: cram-md5.c:133-0 cram-get received: auth cram-md5 <373405612.1226912731@localhost-fd> ssl=0
localhost-sd: cram-md5.c:152-0 sending resp to challenge: rGA4O6/p9m+yjH/0O5EobD
localhost-dir: fd_cmds.c:588-3 bdird: sending runscripts to fd
localhost-sd: job.c:261-0 OK Authentication jid=3 Job RestoreFiles.2008-11-17_09.05.29.06
localhost-sd: job.c:205-3 Auth=1 canceled=0 errstat=0
localhost-sd: job.c:211-3 Running job RestoreFiles.2008-11-17_09.05.29.06
localhost-sd: fd_cmds.c:122-3 Start run Job=RestoreFiles.2008-11-17_09.05.29.06
localhost-sd: fd_cmds.c:160-3 <filed: read open session = DummyVolume 3 1226912624 0 0 0 0
localhost-sd: fd_cmds.c:296-3 read open session = DummyVolume 3 1226912624 0 0 0 0

localhost-sd: fd_cmds.c:311-3 read_open_session got: JobId=3 Vol=DummyVolume VolSessId=3 VolSessT=1226912624
localhost-sd: fd_cmds.c:314-3   StartF=0 EndF=0 StartB=0 EndB=0
localhost-sd: fd_cmds.c:322-3 >filed: 3000 OK open ticket = 3
localhost-sd: fd_cmds.c:160-3 <filed: bootstrap
localhost-sd: fd_cmds.c:359-3 === Bootstrap file ===
localhost-sd: fd_cmds.c:361-3 Volume="TestVolume0001"
localhost-sd: fd_cmds.c:361-3 MediaType="File"
localhost-sd: fd_cmds.c:361-3 Device="FileStorage"
localhost-sd: fd_cmds.c:361-3 VolSessionId=1
localhost-sd: fd_cmds.c:361-3 VolSessionTime=1226912624
localhost-sd: fd_cmds.c:361-3 VolFile=0
localhost-sd: fd_cmds.c:361-3 VolBlock=210-751973313
localhost-sd: fd_cmds.c:361-3 FileIndex=1-4447
localhost-sd: fd_cmds.c:361-3 Count=4447
localhost-sd: fd_cmds.c:365-3 === end bootstrap file ===
Next        : 0x0
Root bsr    : 0x80a4b08
VolumeName  : TestVolume0001
  MediaType : File
  Device    : FileStorage
  Slot      : 0
SessId      : 1
SessTime    : 1226912624
VolFile     : 0-0
VolBlock    : 210-751973313
FileIndex   : 1-4447
count       : 4447
found       : 0
done        : no
positioning : 1
fast_reject : 1
localhost-sd: fd_cmds.c:160-3 <filed: read data 3
localhost-sd: fd_cmds.c:276-3 Read data: read data 3
localhost-sd: fd_cmds.c:278-3 <bfiled: read data 3
localhost-sd: read.c:59-3 Start read data.
localhost-sd: vol_mgr.c:163-3 add read_vol=TestVolume0001 JobId=3
localhost-sd: acquire.c:94-3 Want Vol=TestVolume0001 Slot=0
localhost-sd: acquire.c:108-3 MediaType dcr=File dev=File
localhost-sd: acquire.c:186-3 dir_get_volume_info vol=TestVolume0001
localhost-sd: askdir.c:230-3 >dird CatReq Job=RestoreFiles.2008-11-17_09.05.29.06 GetVolInfo VolName=TestVolume0001 write=0
localhost-dir: catreq.c:126-3 catreq CatReq Job=RestoreFiles.2008-11-17_09.05.29.06 GetVolInfo VolName=TestVolume0001 write=0
localhost-dir: catreq.c:163-3 CatReq GetVolInfo Vol=TestVolume0001
localhost-sd: askdir.c:182-3 <dird 1000 OK VolName=TestVolume0001 VolJobs=1 VolFiles=0 VolBlocks=11657 VolBytes=751973314 VolMounts=2 VolErrors=0 VolWrites=11659 MaxVolBytes=0 VolCapacityBytes=0 VolStatus=Used Slot=0 MaxVolJobs=1 MaxVolFiles=0 InChanger=0 VolReadTime=0 VolWriteTime=21463245 EndFile=0 EndBlock=751930435 VolParts=0 LabelType=0 MediaId=1
localhost-sd: askdir.c:205-3 do_reqest_vol_info return true slot=0 Volume=TestVolume0001
localhost-sd: mount.c:516-3 Must load "FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: autochanger.c:121-3 Device "FileStorage" (/usr/bin/bacula/regress/tmp) is not an autochanger
localhost-sd: acquire.c:217-3 bstored: open vol=TestVolume0001
localhost-sd: dev.c:345-3 open dev: type=1 dev_name="FileStorage" (/usr/bin/bacula/regress/tmp) vol=TestVolume0001 mode=OPEN_READ_ONLY
localhost-sd: dev.c:354-3 call open_file_device mode=OPEN_READ_ONLY
localhost-sd: dev.c:526-3 open disk: mode=OPEN_READ_ONLY open(/usr/bin/bacula/regress/tmp/TestVolume0001, 0x0, 0640)
localhost-sd: dev.c:541-3 open dev: disk fd=8 opened, part=0/0, part_size=779649382
localhost-sd: dev.c:358-3 preserve=0x0 fd=8
localhost-sd: acquire.c:225-3 opened dev "FileStorage" (/usr/bin/bacula/regress/tmp) OK
localhost-sd: acquire.c:228-3 calling read-vol-label
localhost-sd: label.c:81-3 Enter read_volume_label res=1 device="FileStorage" (/usr/bin/bacula/regress/tmp) vol=TestVolume0001 dev_Vol=*NULL*
localhost-sd: label.c:130-3 Big if statement in read_volume_label
localhost-dir: catreq.c:100-3 Vol Info for RestoreFiles.2008-11-17_09.05.29.06: 1000 OK VolName=TestVolume0001 VolJobs=1 VolFiles=0 VolBlocks=11657 VolBytes=751973314 VolMounts=2 VolErrors=0 VolWrites=11659 MaxVolBytes=0 VolCapacityBytes=0 VolStatus=Used Slot=0 MaxVolJobs=1 MaxVolFiles=0 InChanger=0 VolReadTime=0 VolWriteTime=21463245 EndFile=0 EndBlock=751930435 VolParts=0 LabelType=0 MediaId=1
localhost-sd: label.c:202-3 Compare Vol names: VolName=TestVolume0001 hdr=TestVolume0001

Volume Label:
Id                : Bacula 1.0 immortal
VerNo             : 11
VolName           : TestVolume0001
PrevVolName       : 
VolFile           : 0
LabelType         : VOL_LABEL
LabelSize         : 174
PoolName          : Default
MediaType         : File
PoolType          : Backup
HostName          : backuppilot
Date label written: 17-Nov-2008 09:03
localhost-sd: label.c:223-3 Leave read_volume_label() VOL_OK
localhost-sd: label.c:236-3 Call reserve_volume=TestVolume0001
localhost-sd: vol_mgr.c:350-3 enter reserve_volume=TestVolume0001 drive="FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: vol_mgr.c:269-3 new Vol=TestVolume0001 at 80dadd8 dev="FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: vol_mgr.c:454-3 === set in_use. vol=TestVolume0001 dev="FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: vol_mgr.c:212-3 List end new volume: TestVolume0001 in_use=1 on device "FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: acquire.c:232-3 Got correct volume.
localhost-sd: reserve.c:138-3 Dec reserve=0 dev="FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: dev.c:1622-3 ===== lseek to 210
localhost-sd: vol_mgr.c:577-3 === set not reserved vol=TestVolume0001 num_writers=0 dev_reserved=0 dev="FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: vol_mgr.c:578-3 === clear in_use vol=TestVolume0001
localhost-sd: vol_mgr.c:606-3 === clear in_use vol=TestVolume0001
localhost-sd: vol_mgr.c:609-3 === remove volume TestVolume0001 dev="FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: mount.c:796-3 NumReadVolumes=1 CurReadVolume=1
localhost-sd: vol_mgr.c:558-3 vol_unused: no vol on "FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: mount.c:811-3 End of Device reached.
localhost-sd: acquire.c:427-3 release_device device "FileStorage" (/usr/bin/bacula/regress/tmp) is disk
localhost-sd: acquire.c:436-3 dir_update_vol_info. label=64 Vol=TestVolume0001
localhost-sd: askdir.c:345-3 Update cat VolFiles=0
localhost-sd: askdir.c:368-3 >dird CatReq Job=RestoreFiles.2008-11-17_09.05.29.06 UpdateMedia VolName=TestVolume0001 VolJobs=1 VolFiles=0 VolBlocks=11657 VolBytes=751973314 VolMounts=2 VolErrors=0 VolWrites=11659 MaxVolBytes=0 EndTime=1226912799 VolStatus=Used Slot=0 relabel=0 InChanger=0 VolReadTime=40118973 VolWriteTime=21463245 VolFirstWritten=0 VolParts=0
localhost-dir: catreq.c:126-3 catreq CatReq Job=RestoreFiles.2008-11-17_09.05.29.06 UpdateMedia VolName=TestVolume0001 VolJobs=1 VolFiles=0 VolBlocks=11657 VolBytes=751973314 VolMounts=2 VolErrors=0 VolWrites=11659 MaxVolBytes=0 EndTime=1226912799 VolStatus=Used Slot=0 relabel=0 InChanger=0 VolReadTime=40118973 VolWriteTime=21463245 VolFirstWritten=0 VolParts=0
localhost-dir: sql_update.c:338-3 update_media: FirstWritten=1226912636
localhost-dir: next_vol.c:246-3 Vol=TestVolume0001 expired=0
localhost-dir: catreq.c:100-3 Vol Info for RestoreFiles.2008-11-17_09.05.29.06: 1000 OK VolName=TestVolume0001 VolJobs=1 VolFiles=0 VolBlocks=11657 VolBytes=751973314 VolMounts=2 VolErrors=0 VolWrites=11659 MaxVolBytes=0 VolCapacityBytes=0 VolStatus=Used Slot=0 MaxVolJobs=1 MaxVolFiles=0 InChanger=0 VolReadTime=40118973 VolWriteTime=21463245 EndFile=0 EndBlock=751930435 VolParts=0 LabelType=0 MediaId=1
localhost-sd: askdir.c:182-3 <dird 1000 OK VolName=TestVolume0001 VolJobs=1 VolFiles=0 VolBlocks=11657 VolBytes=751973314 VolMounts=2 VolErrors=0 VolWrites=11659 MaxVolBytes=0 VolCapacityBytes=0 VolStatus=Used Slot=0 MaxVolJobs=1 MaxVolFiles=0 InChanger=0 VolReadTime=40118973 VolWriteTime=21463245 EndFile=0 EndBlock=751930435 VolParts=0 LabelType=0 MediaId=1
localhost-sd: askdir.c:205-3 do_reqest_vol_info return true slot=0 Volume=TestVolume0001
localhost-sd: vol_mgr.c:180-3 remove_read_vol=TestVolume0001 JobId=3 found=1
localhost-sd: vol_mgr.c:558-3 vol_unused: no vol on "FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: acquire.c:485-3 0 writers, 0 reserve, dev="FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: dev.c:1902-3 close_dev "FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: dev.c:1892-3 Clear volhdr vol=TestVolume0001
localhost-sd: acquire.c:523-3 JobId=3 broadcast wait_device_release at 17-Nov-2008 09:06:39
localhost-sd: acquire.c:538-3 ===== Device "FileStorage" (/usr/bin/bacula/regress/tmp) released by JobId=3
localhost-sd: read.c:96-3 Done reading.
localhost-sd: fd_cmds.c:160-3 <filed: read close session 3
localhost-sd: fd_cmds.c:396-3 Read close session: read close session 3

localhost-dir: backup.c:373-3 FDStatus=T
localhost-dir: restore.c:241-3 In restore_cleanup
localhost-dir: restore.c:331-3 Leaving restore_cleanup
localhost-dir: msgchan.c:348-3 === End msg_thread. JobId=3 usecnt=2
localhost-sd: jcr.c:184-3 write_last_jobs seek to 188
localhost-dir: ua_prune.c:396-3 Query=SELECT DISTINCT DelCandidates.JobId,DelCandidates.PurgedFiles FROM Job,DelCandidates WHERE (Job.JobId=DelCandidates.JobId AND DelCandidates.JobStatus!='T') OR (Job.JobTDate>1211360799 AND Job.ClientId=1 AND Job.Type='R')
localhost-dir: ua_prune.c:243-3 select now=1226912799 period=2592000 sql=SELECT count(*) from Job WHERE JobTDate<1224320799 AND ClientId=1 AND PurgedFiles=0
localhost-dir: job.c:359-3 ======== End Job stat=T ==========
localhost-dir: jcr.c:184-3 write_last_jobs seek to 188
You have messages.
messages
17-Nov 09:05 localhost-dir JobId 3: Start Restore Job RestoreFiles.2008-11-17_09.05.29.06
17-Nov 09:05 localhost-dir JobId 3: Using Device "FileStorage"
17-Nov 09:05 localhost-sd JobId 3: Ready to read from volume "TestVolume0001" on device "FileStorage" (/usr/bin/bacula/regress/tmp).
17-Nov 09:05 localhost-sd JobId 3: Forward spacing Volume "TestVolume0001" to file:block 0:210.
17-Nov 09:06 localhost-sd JobId 3: End of file 0 on device "FileStorage" (/usr/bin/bacula/regress/tmp), Volume "TestVolume0001"
17-Nov 09:06 localhost-sd JobId 3: End of Volume at file 0 on device "FileStorage" (/usr/bin/bacula/regress/tmp), Volume "TestVolume0001"
17-Nov 09:06 localhost-sd JobId 3: End of all volumes.
17-Nov 09:06 localhost-dir JobId 3: Bacula localhost-dir 2.5.20 (13Nov08): 17-Nov-2008 09:06:39
  Build OS:               i686-pc-linux-gnu unknown unknown
  JobId:                  3
  Job:                    RestoreFiles.2008-11-17_09.05.29.06
  Restore Client:         localhost-fd
  Start time:             17-Nov-2008 09:05:31
  End time:               17-Nov-2008 09:06:39
  Files Expected:         4,447
  Files Restored:         3,286
  Bytes Restored:         361,256,965
  Rate:                   5312.6 KB/s
  FD Errors:              0
  FD termination status:  OK
  SD termination status:  OK
  Termination:            Restore OK -- warning file count mismatch

17-Nov 09:06 localhost-dir JobId 3: Begin pruning Jobs.
17-Nov 09:06 localhost-dir JobId 3: No Jobs found to prune.
17-Nov 09:06 localhost-dir JobId 3: Begin pruning Files.
17-Nov 09:06 localhost-dir JobId 3: No Files found to prune.
17-Nov 09:06 localhost-dir JobId 3: End auto prune.

quit
localhost-dir: bnet.c:669-0 who=client host=127.0.0.1 port=42271
localhost-dir: job.c:1264-0 wstorage=File
localhost-dir: job.c:1273-0 wstore=File where=Job resource
localhost-dir: job.c:925-0 JobId=0 created Job=-Console-.2008-11-17_09.06.41.07
localhost-dir: cram-md5.c:73-0 send: auth cram-md5 <604426966.1226912801@localhost-dir> ssl=0
localhost-dir: cram-md5.c:133-0 cram-get received: auth cram-md5 <754980813.1226912801@bconsole> ssl=0
localhost-dir: cram-md5.c:152-0 sending resp to challenge: 8U+t4j+lt0/ce5+zWj+hbC
localhost-dir: ua_status.c:142-0 status:status dir:
localhost-dir: ua_status.c:142-0 status:status client=localhost-fd:
localhost-dir: bsock.c:201-0 Current host[ipv4:127.0.0.1:8102] All host[ipv4:127.0.0.1:8102] 
localhost-dir: bsock.c:155-0 who=Client: localhost-fd host=localhost port=8102
localhost-dir: fd_cmds.c:103-0 Opened connection with File daemon
localhost-dir: authenticate.c:196-0 Sent: Hello Director localhost-dir calling
localhost-dir: cram-md5.c:133-0 cram-get received: auth cram-md5 <488369609.1226912801@localhost-fd> ssl=0
localhost-dir: cram-md5.c:152-0 sending resp to challenge: 1g+SH5ISd58wfQ+Nk9BcPA
localhost-dir: cram-md5.c:80-0 send: auth cram-md5 <604426966.1226912801@localhost-dir> ssl=0
localhost-dir: cram-md5.c:99-0 Authenticate OK By+od/lRx9+iVF+Up2+47D
localhost-dir: authenticate.c:263-0 >filed: 1000 OK auth
localhost-dir: authenticate.c:272-0 <filed: 2000 OK Hello 1
localhost-dir: fd_cmds.c:124-0 >filed: JobId=0 Job=-Console-.2008-11-17_09.06.41.07 SDid=0 SDtime=0 Authorization=dummy
localhost-dir: fd_cmds.c:126-0 <filed: 2000 OK Job 2.5.20 (13Nov08) i686-pc-linux-gnu,unknown,unknownlocalhost-dir: ua_status.c:412-0 Connected to file daemon
localhost-dir: ua_status.c:142-0 status:status storage=File:
localhost-dir: job.c:1298-0 wstore=File where=unknown source
localhost-dir: msgchan.c:104-0 bnet_connect to Storage daemon localhost:8103
localhost-dir: bsock.c:201-0 Current host[ipv4:127.0.0.1:8103] All host[ipv4:127.0.0.1:8103] 
localhost-sd: bnet.c:669-0 who=client host=127.0.0.1 port=42783
localhost-dir: bsock.c:155-0 who=Storage daemon host=localhost port=8103
localhost-sd: dircmd.c:171-0 Conn: Hello Director localhost-dir calling
localhost-sd: dircmd.c:187-0 Got a DIR connection at 17-Nov-2008 09:06:41
localhost-sd: cram-md5.c:73-0 send: auth cram-md5 <645187951.1226912801@localhost-sd> ssl=0
localhost-dir: cram-md5.c:133-0 cram-get received: auth cram-md5 <645187951.1226912801@localhost-sd> ssl=0
localhost-dir: cram-md5.c:152-0 sending resp to challenge: OiQyU1/nt//9w++r561Z9D
localhost-dir: cram-md5.c:80-0 send: auth cram-md5 <1793289447.1226912801@localhost-dir> ssl=0
localhost-sd: cram-md5.c:133-0 cram-get received: auth cram-md5 <1793289447.1226912801@localhost-dir> ssl=0
localhost-sd: cram-md5.c:152-0 sending resp to challenge: 66+y7y+S02//mS+PP7/iaC
localhost-dir: cram-md5.c:99-0 Authenticate OK 66+y7y+S02//mS+PP7/iaC
localhost-dir: authenticate.c:152-0 >stored: 1000 OK auth
localhost-sd: dircmd.c:209-0 Message channel init completed.
localhost-dir: authenticate.c:159-0 <stored: 3000 OK Hello
localhost-dir: ua_status.c:370-0 Connected to storage daemon
Only in build/src: cats
Only in build/src: console
Only in build/src: dird
Only in build/src: filed
Only in build/src: gnome2-console
Only in build/src/lib: Makefile.in
Only in build/src/lib: address_conf.h
Only in build/src/lib: alist.c
Only in build/src/lib: alist.h
Only in build/src/lib: attr.c
Only in build/src/lib: attr.h
Only in build/src/lib: berrno.c
Only in build/src/lib: berrno.h
Only in build/src/lib: bits.h
Only in build/src/lib: bnet.c
Only in build/src/lib: bnet_server.c
Only in build/src/lib: bpipe.c
Only in build/src/lib: bpipe.h
Only in build/src/lib: breg.c
Only in build/src/lib: breg.h
Only in build/src/lib: bregex.c
Only in build/src/lib: bregex.h
Only in build/src/lib: bsnprintf.c
Only in build/src/lib: bsock.c
Only in build/src/lib: bsock.h
Only in build/src/lib: btime.c
Only in build/src/lib: btime.h
Only in build/src/lib: btimers.c
Only in build/src/lib: btimers.h
Only in build/src/lib: cram-md5.c
Only in build/src/lib: crc32.c
Only in build/src/lib: daemon.c
Only in build/src/lib: dlist.c
Only in build/src/lib: dlist.h
Only in build/src/lib: guid_to_name.c
Only in build/src/lib: guid_to_name.h
Only in build/src/lib: hmac.c
Only in build/src/lib: htable.c
Only in build/src/lib: htable.h
Only in build/src/lib: jcr.c
Only in build/src/lib: lib.h
Only in build/src/lib: md5.c
Only in build/src/lib: md5.h
Only in build/src/lib: mem_pool.c
Only in build/src/lib: mem_pool.h
Only in build/src/lib: message.c
Only in build/src/lib: message.h
Only in build/src/lib: parse_conf.c
Only in build/src/lib: parse_conf.h
Only in build/src/lib: protos.h
Only in build/src/lib: pythonlib.c
Only in build/src/lib: pythonlib.h
Only in build/src/lib: rblist.c
Only in build/src/lib: rblist.h
Only in build/src/lib: res.c
Only in build/src/lib: runscript.h
Only in build/src/lib: rwlock.c
Only in build/src/lib: rwlock.h
Only in build/src/lib: scan.c
Only in build/src/lib: serial.c
Only in build/src/lib: serial.h
Only in build/src/lib: sha1.c
Only in build/src/lib: sha1.h
Only in build/src/lib: signal.c
Only in build/src/lib: status.h
Only in build/src/lib: tcpd.h
Only in build/src/lib: tls.c
Only in build/src/lib: tls.h
Only in build/src/lib: tree.c
Only in build/src/lib: tree.h
Only in build/src/lib: util.c
Only in build/src/lib: waitq.h
Only in build/src/lib: watchdog.c
Only in build/src/lib: watchdog.h
Only in build/src/lib: workq.c
Only in build/src/lib: workq.h
Only in build/src: plugins
Only in build/src: qt-console
Only in build/src: stored
Only in build/src: tools
Only in build/src: tray-monitor
Only in build/src: win32
Only in build/src: wx-console
 
 
  !!!!! broken-media-bug-test failed!!! 09:08:33 !!!!! 
  !!!!! Bad termination status       !!!!! 
   Status: backup=1 restore=3 diff=1
 
-------------------------------------------------------------------------
This SF.Net email is sponsored by the Moblin Your Move Developer's challenge
Build the coolest Linux based applications with Moblin SDK & win great prizes
Grand prize is a trip for two to an Open Source event anywhere in the world
http://moblin-contest.org/redirect.php?banner_id=100&url=/
_______________________________________________
Bacula-devel mailing list
Bacula-devel@xxxxxxxxxxxxxxxxxxxxx
https://lists.sourceforge.net/lists/listinfo/bacula-devel


This mailing list archive is a service of Copilot Consulting.