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

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


On Fri, Nov 14, 2008 at 05:13:52PM +0100, Kern Sibbald wrote:
> On Tuesday 11 November 2008 12:51:56 Graham Keeling wrote:
> > Hello,
> >
> > Since my last email, I found out that you only need one director, one file
> > daemon, and one storage daemon in order to see the problem.
> >
> > Since there has been no response to my last email, I tried to come up with
> > an easy way for others to demonstrate it for themselves.
> >
> > So, I made a regress test.
> >
> > I've called the test 'broken-media-bug-test', and it does this:
> > a) creates a huge 300M file in the build directory
> > b) starts job "First" (using fileset Set1) backing up the build directory
> > c) waits 5 seconds
> > d) starts job "Second" (using fileset Set2) backing up the build directory
> > e) waits for both jobs to finish
> > f) tries to restore the build directory using fileset Set1.
> >
> > The restore doesn't manage to restore all the files, and looking back at
> > the debug output, you can see the volume that the first backup creates
> > being stomped on by the second backup.
> >
> > The patch for the test is attached, along with a file containing the
> > REGRESS_DEBUG=1 output that it gives. The problem can be seen in the output
> > around line 453, where it decides to purge the Volume.
> 
> Please add a "list volumes" after step c and send us the job output.

OK, it says this (I've also turned on some debug for the director). The
full output for this run is also attached, along with my regress config file
(without my email address).


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 | VolRete
ntion | Recycle | Slot | InChanger | MediaType | LastWritten |
+---------+----------------+-----------+---------+----------+----------+--------
------+---------+------+-----------+-----------+-------------+
| 1       | TestVolume0001 | Used      | 1       | 210      | 0        | 3153600
0     | 1       | 0    | 0         | File      | 0           |
+---------+----------------+-----------+---------+----------+----------+--------
------+---------+------+-----------+-----------+-------------+

# Where to get the source to be tested
BACULA_SOURCE="/usr/bin/bacula/bacula"
#BACULA_SOURCE="/home/graham/chroot/usr/bin/bacula/bacula"

# Where to send email   !!!!! Change me !!!!!!!
EMAIL=<ADD YOUR EMAIL HERE>
SMTP_HOST="localhost"

# Full "default" path where to find sqlite (no quotes!)
SQLITE3_DIR=/usr/bin/bacula/bacula/depkgs/sqlite3
SQLITE_DIR=/usr/bin/bacula/bacula/depkgs/sqlite

# set to /dev/null if you do not have a tape drive
# Note this is used for both the tape tests and the
#   autochanger
TAPE_DRIVE="/dev/null"

# if you don't have an autochanger set AUTOCHANGER to /dev/null
AUTOCHANGER="/dev/null"

# drive index of first autochanger drive
DRIVE1=0

# drive index of second autochanger drive or "none" (in lowercase)
DRIVE2="none"

# what slot to use for first tape
SLOT1=1

# what slot to use for the second tape
SLOT2=2

# For two drive tests -- set to /dev/null if you do not have it 
TAPE_DRIVE1="/dev/null"

# Set this if you are using fake tape driver
USE_VTAPE=yes

# Change this to use disk-changer with vtape
AUTOCHANGER_SCRIPT=disk-changer

# This must be the path to the autochanger including its name
#AUTOCHANGER_PATH="/usr/sbin/mtx"

# Set your database here
#WHICHDB="--with-sqlite=${SQLITE_DIR}"
WHICHDB="--with-sqlite3=${SQLITE3_DIR}"
#WHICHDB="--with-postgresql"
#WHICHDB="--with-mysql" 

# DB parameters
db_name="regress"
db_user="regress"
db_password=

# Set this if you use libdbi framework
#LIBDBI="dbdriver = "dbi:postgresql"; dbaddress = 127.0.0.1; dbport = 5432"

# Set this to "--with-tcp-wrappers" or "--without-tcp-wrappers"
TCPWRAPPERS="--without-tcp-wrappers"

# Set this to "" to disable OpenSSL support, "--with-openssl=yes"
# to enable it, or provide the path to the OpenSSL installation,
# eg "--with-openssl=/usr/local"
#   
# Note, you can also add any other (as many as you want) special   
#  Bacula configuration options here, such as --disable-batch-insert
#
OPENSSL="--with-openssl"

# You may put your real host name here, but localhost is valid also
#  and it has the advantage that it works on a non-newtworked machine
HOST="localhost"

# see --with-base-port at
# http://www.bacula.org/rel-manual/Installing_Bacula.html
# You only need to change this if you want to run more than one instance
# of regression testing on the same box. You'll need to set BASEPORT
# to values that do not overlap.  BASEPORT is the first of three ports
# required by each instance, one for each of Dir, SD, and the FD.
#
BASEPORT=8101

#
# If you want to post items to the Bacula Dart dashboard, you need to
#  create a unique name here for each of your test machines.
# We recommend that you prefix it by your name, and if you have multiple
#  test machines, add some indication of the machine.
#
#SITE_NAME=<your-name>-bacula-${HOST}

#
# The following are used only if you want to run Win32 tests, which
#   is a real pain since the Win32 machine is not localhost and you
#   also need to specify what to backup.
#
WIN32_CLIENT="yyyy"
WIN32_ADDR="yyyy"
WIN32_FILE="c:/users/xxxx"
WIN32_PORT=9102
WIN32_PASSWORD="zzzzz"
 
 
 === Starting broken-media-bug-test at 16:42:31 ===
 
Creating huge 300M file...
300+0 records in
300+0 records out
314572800 bytes (315 MB) copied, 109.045 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-14_16.44.23.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-14_16.44.23.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
14-Nov 16:44 localhost-dir JobId 1: No prior Full backup Job record found.
14-Nov 16:44 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 14-Nov-2008 16:44:25
localhost-sd: cram-md5.c:73-0 send: auth cram-md5 <1166688750.1226681065@localhost-sd> ssl=0
localhost-dir: cram-md5.c:133-1 cram-get received: auth cram-md5 <1166688750.1226681065@localhost-sd> ssl=0
localhost-dir: cram-md5.c:152-1 sending resp to challenge: Ph/7lw+gFx4kax/h2G+KmA
localhost-dir: cram-md5.c:80-1 send: auth cram-md5 <2089143244.1226681065@localhost-dir> ssl=0
localhost-sd: cram-md5.c:133-0 cram-get received: auth cram-md5 <2089143244.1226681065@localhost-dir> ssl=0
localhost-sd: cram-md5.c:152-0 sending resp to challenge: h4NGPD+134QKQ7xo2/ptzA
localhost-dir: cram-md5.c:99-1 Authenticate OK h4NGPD+134QKQ7xo2/ptzA
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-14_16.44.23.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=1226681060 Authorization=PKGD-CFAP-GAJA-AHNL-LNAP-PPJF-GBFN-LMEC
localhost-dir: msgchan.c:192-1 >stored: JobId=1 job=First.2008-11-14_16.44.23.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=1226681060 Authorization=PKGD-CFAP-GAJA-AHNL-LNAP-PPJF-GBFN-LMEC
localhost-dir: msgchan.c:202-1 sd_auth_key=PKGD-CFAP-GAJA-AHNL-LNAP-PPJF-GBFN-LMEC
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-14_16.44.23.03 FindMedia=1 pool_name=Default media_type=File
localhost-dir: catreq.c:126-1 catreq CatReq Job=First.2008-11-14_16.44.23.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 80b8310 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-14_16.44.23.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-14_16.44.23.03 waiting 1800 sec for FD to contact SD key=PKGD-CFAP-GAJA-AHNL-LNAP-PPJF-GBFN-LMEC
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 <1982103739.1226681065@localhost-fd> ssl=0
localhost-dir: cram-md5.c:152-1 sending resp to challenge: E5/Iz/+w1/Met9Jut8976D
localhost-dir: cram-md5.c:80-1 send: auth cram-md5 <1305618948.1226681065@localhost-dir> ssl=0
localhost-dir: cram-md5.c:99-1 Authenticate OK Z6/LGF+jsw47Z+FtI9JBsA
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-14_16.44.23.03 SDid=1 SDtime=1226681060 Authorization=PKGD-CFAP-GAJA-AHNL-LNAP-PPJF-GBFN-LMEC
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-14_16.44.23.03
localhost-sd: dircmd.c:177-0 Got a FD connection at 14-Nov-2008 16:44:25
localhost-sd: dircmd.c:178-0 Hello Start Job First.2008-11-14_16.44.23.03
localhost-sd: job.c:238-0 Found Job First.2008-11-14_16.44.23.03
localhost-sd: cram-md5.c:73-0 send: auth cram-md5 <1301901170.1226681065@localhost-sd> ssl=0
localhost-sd: cram-md5.c:133-0 cram-get received: auth cram-md5 <632253219.1226681065@localhost-fd> ssl=0
localhost-sd: cram-md5.c:152-0 sending resp to challenge: k6pBZ94a94/d2DMFOU/vAD
localhost-sd: job.c:261-0 OK Authentication jid=1 Job First.2008-11-14_16.44.23.03
localhost-sd: job.c:205-1 Auth=1 canceled=0 errstat=0
localhost-sd: job.c:211-1 Running job First.2008-11-14_16.44.23.03
localhost-sd: fd_cmds.c:122-1 Start run Job=First.2008-11-14_16.44.23.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-14_16.44.23.03 GetVolInfo VolName=TestVolume0001 write=1
localhost-dir: catreq.c:126-1 catreq CatReq Job=First.2008-11-14_16.44.23.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: 14-Nov-2008 16:44
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: 14-Nov-2008 16:44
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-14_16.44.23.03 UpdateMedia VolName=TestVolume0001 VolJobs=0 VolFiles=0 VolBlocks=0 VolBytes=0 VolMounts=0 VolErrors=0 VolWrites=0 MaxVolBytes=0 EndTime=1226681065 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-14_16.44.23.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-14_16.44.23.03 UpdateMedia VolName=TestVolume0001 VolJobs=0 VolFiles=0 VolBlocks=0 VolBytes=0 VolMounts=0 VolErrors=0 VolWrites=0 MaxVolBytes=0 EndTime=1226681065 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=1226681065
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: 14-Nov-2008 16:44
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-14_16.44.23.03 UpdateMedia VolName=TestVolume0001 VolJobs=0 VolFiles=0 VolBlocks=0 VolBytes=210 VolMounts=1 VolErrors=0 VolWrites=1 MaxVolBytes=0 EndTime=1226681065 VolStatus=Append Slot=0 relabel=1 InChanger=0 VolReadTime=0 VolWriteTime=12 VolFirstWritten=0 VolParts=0
localhost-dir: catreq.c:100-1 Vol Info for First.2008-11-14_16.44.23.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-14_16.44.23.03 UpdateMedia VolName=TestVolume0001 VolJobs=0 VolFiles=0 VolBlocks=0 VolBytes=210 VolMounts=1 VolErrors=0 VolWrites=1 MaxVolBytes=0 EndTime=1226681065 VolStatus=Append Slot=0 relabel=1 InChanger=0 VolReadTime=0 VolWriteTime=12 VolFirstWritten=0 VolParts=0
localhost-dir: sql_update.c:338-1 update_media: FirstWritten=1226681065
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=12 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-14_16.44.23.03 UpdateMedia VolName=TestVolume0001 VolJobs=1 VolFiles=0 VolBlocks=0 VolBytes=210 VolMounts=1 VolErrors=0 VolWrites=1 MaxVolBytes=0 EndTime=1226681065 VolStatus=Append Slot=0 relabel=0 InChanger=0 VolReadTime=0 VolWriteTime=12 VolFirstWritten=0 VolParts=0
localhost-dir: catreq.c:100-1 Vol Info for First.2008-11-14_16.44.23.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=12 EndFile=0 EndBlock=0 VolParts=0 LabelType=0 MediaId=1
localhost-dir: catreq.c:126-1 catreq CatReq Job=First.2008-11-14_16.44.23.03 UpdateMedia VolName=TestVolume0001 VolJobs=1 VolFiles=0 VolBlocks=0 VolBytes=210 VolMounts=1 VolErrors=0 VolWrites=1 MaxVolBytes=0 EndTime=1226681065 VolStatus=Append Slot=0 relabel=0 InChanger=0 VolReadTime=0 VolWriteTime=12 VolFirstWritten=0 VolParts=0
localhost-dir: sql_update.c:338-1 update_media: FirstWritten=1226681065
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=1226681065
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=12 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=80b81f0
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-14_16.44.23.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=12 EndFile=0 EndBlock=0 VolParts=0 LabelType=0 MediaId=1
localhost-dir: sql.c:737-1 initdb ref=1 connected=1 db=80daee0
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-14_16.44.28.04
localhost-dir: cram-md5.c:73-0 send: auth cram-md5 <1658328248.1226681068@localhost-dir> ssl=0
localhost-dir: cram-md5.c:133-0 cram-get received: auth cram-md5 <822169703.1226681068@bconsole> ssl=0
localhost-dir: cram-md5.c:152-0 sending resp to challenge: 34+BeW//Il+6BmIqQl9SXC
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 14-Nov-2008 16:44:28
localhost-sd: cram-md5.c:73-0 send: auth cram-md5 <2022786908.1226681068@localhost-sd> ssl=0
localhost-dir: cram-md5.c:133-0 cram-get received: auth cram-md5 <2022786908.1226681068@localhost-sd> ssl=0
localhost-dir: cram-md5.c:152-0 sending resp to challenge: y6+keG1woHR099/w7//vYC
localhost-dir: cram-md5.c:80-0 send: auth cram-md5 <173122161.1226681068@localhost-dir> ssl=0
localhost-sd: cram-md5.c:133-0 cram-get received: auth cram-md5 <173122161.1226681068@localhost-dir> ssl=0
localhost-dir: cram-md5.c:99-0 Authenticate OK 94UeFgJpJkIyvyBrH7tXzA
localhost-dir: authenticate.c:152-0 >stored: 1000 OK auth
localhost-sd: cram-md5.c:152-0 sending resp to challenge: 94UeFgJpJkIyvyBrH7tXzA
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           |
+---------+----------------+-----------+---------+----------+----------+--------------+---------+------+-----------+-----------+-------------+
messages
14-Nov 16:44 localhost-dir JobId 1: Start Backup JobId 1, Job=First.2008-11-14_16.44.23.03
14-Nov 16:44 localhost-dir JobId 1: Created new Volume "TestVolume0001" in catalog.
14-Nov 16:44 localhost-dir JobId 1: Using Device "FileStorage"
14-Nov 16:44 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
14-Nov 16:44 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
14-Nov 16:44 localhost-sd JobId 1: Labeled new Volume "TestVolume0001" on device "FileStorage" (/usr/bin/bacula/regress/tmp).
14-Nov 16:44 localhost-sd JobId 1: Wrote label to prelabeled Volume "TestVolume0001" on device "FileStorage" (/usr/bin/bacula/regress/tmp)
14-Nov 16:44 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-14_16.44.28.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-14_16.44.28.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 14-Nov-2008 16:44:30
localhost-sd: cram-md5.c:73-0 send: auth cram-md5 <1293367506.1226681070@localhost-sd> ssl=0
localhost-dir: cram-md5.c:133-2 cram-get received: auth cram-md5 <1293367506.1226681070@localhost-sd> ssl=0
localhost-dir: cram-md5.c:152-2 sending resp to challenge: vy/Od0R5N78U28/5DSNTjC
localhost-dir: cram-md5.c:80-2 send: auth cram-md5 <255204050.1226681070@localhost-dir> ssl=0
localhost-sd: cram-md5.c:133-0 cram-get received: auth cram-md5 <255204050.1226681070@localhost-dir> ssl=0
localhost-dir: cram-md5.c:99-2 Authenticate OK W8/HV9Vp9AMbX+ptNR5dmA
localhost-dir: authenticate.c:152-2 >stored: 1000 OK auth
localhost-sd: cram-md5.c:152-0 sending resp to challenge: W8/HV9Vp9AMbX+ptNR5dmA
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-14_16.44.28.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-14_16.44.28.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-dir: msgchan.c:194-2 <stored: 3000 OK Job SDid=2 SDtime=1226681060 Authorization=AMMD-ECEN-PFKF-POKI-MFNC-GPAN-JJKG-POCI
localhost-dir: msgchan.c:202-2 sd_auth_key=AMMD-ECEN-PFKF-POKI-MFNC-GPAN-JJKG-POCI
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: job.c:157-2 >dird jid=2: 3000 OK Job SDid=2 SDtime=1226681060 Authorization=AMMD-ECEN-PFKF-POKI-MFNC-GPAN-JJKG-POCI
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-dir: catreq.c:126-2 catreq CatReq Job=Second.2008-11-14_16.44.28.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:230-2 >dird CatReq Job=Second.2008-11-14_16.44.28.05 GetVolInfo VolName=TestVolume0001 write=1
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-dir: catreq.c:126-2 catreq CatReq Job=Second.2008-11-14_16.44.28.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<1195145070
localhost-dir: autoprune.c:179-2 Num pruned = 0
localhost-dir: sql_update.c:338-2 update_media: FirstWritten=1226681065
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-14_16.44.28.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=12 EndFile=0 EndBlock=0 VolParts=0 LabelType=0 MediaId=1
localhost-sd: askdir.c:276-2 >dird CatReq Job=Second.2008-11-14_16.44.28.05 FindMedia=1 pool_name=Default media_type=File
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=12 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-14_16.44.28.05 waiting 1800 sec for FD to contact SD key=AMMD-ECEN-PFKF-POKI-MFNC-GPAN-JJKG-POCI
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 <1804289383.1226681070@localhost-fd> ssl=0
localhost-dir: cram-md5.c:152-2 sending resp to challenge: f9NMn7/HVm/mEQ/CknF9CB
localhost-dir: cram-md5.c:80-2 send: auth cram-md5 <970869694.1226681070@localhost-dir> ssl=0
localhost-dir: cram-md5.c:99-2 Authenticate OK R/03ry/1HBpvDT9ew6/RPD
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-14_16.44.28.05 SDid=2 SDtime=1226681060 Authorization=AMMD-ECEN-PFKF-POKI-MFNC-GPAN-JJKG-POCI
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-14_16.44.28.05
localhost-sd: dircmd.c:177-0 Got a FD connection at 14-Nov-2008 16:44:31
localhost-sd: dircmd.c:178-0 Hello Start Job Second.2008-11-14_16.44.28.05
localhost-sd: job.c:238-0 Found Job Second.2008-11-14_16.44.28.05
localhost-sd: cram-md5.c:73-0 send: auth cram-md5 <1366166219.1226681071@localhost-sd> ssl=0
localhost-sd: cram-md5.c:133-0 cram-get received: auth cram-md5 <306074974.1226681071@localhost-fd> ssl=0
localhost-sd: cram-md5.c:152-0 sending resp to challenge: G9RU54Nlc4kJR6/r/4kE4A
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-14_16.44.28.05
localhost-sd: job.c:205-2 Auth=1 canceled=0 errstat=0
localhost-sd: job.c:211-2 Running job Second.2008-11-14_16.44.28.05
localhost-sd: fd_cmds.c:122-2 Start run Job=Second.2008-11-14_16.44.28.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-14_16.44.28.05 GetVolInfo VolName=TestVolume0001 write=1
localhost-dir: catreq.c:126-2 catreq CatReq Job=Second.2008-11-14_16.44.28.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-dir: catreq.c:100-2 Vol Info for Second.2008-11-14_16.44.28.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=12 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=12 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-14_16.44.28.05 GetVolInfo VolName=TestVolume0001 write=1
localhost-dir: catreq.c:126-2 catreq CatReq Job=Second.2008-11-14_16.44.28.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-dir: catreq.c:100-2 Vol Info for Second.2008-11-14_16.44.28.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=12 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=12 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: 14-Nov-2008 16:44
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-sd: label.c:510-2 dir_update_vol_info. Set Append vol=TestVolume0001
localhost-sd: askdir.c:345-2 Update cat VolFiles=0
localhost-dir: catreq.c:126-2 catreq CatReq Job=Second.2008-11-14_16.44.28.05 UpdateMedia VolName=TestVolume0001 VolJobs=0 VolFiles=0 VolBlocks=0 VolBytes=210 VolMounts=2 VolErrors=0 VolWrites=2 MaxVolBytes=0 EndTime=1226681071 VolStatus=Append Slot=0 relabel=1 InChanger=0 VolReadTime=0 VolWriteTime=177 VolFirstWritten=0 VolParts=0
localhost-dir: sql_update.c:338-2 update_media: FirstWritten=1226681071
localhost-dir: next_vol.c:246-2 Vol=TestVolume0001 expired=0
localhost-dir: catreq.c:100-2 Vol Info for Second.2008-11-14_16.44.28.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=177 EndFile=0 EndBlock=0 VolParts=0 LabelType=0 MediaId=1
localhost-sd: askdir.c:368-2 >dird CatReq Job=Second.2008-11-14_16.44.28.05 UpdateMedia VolName=TestVolume0001 VolJobs=0 VolFiles=0 VolBlocks=0 VolBytes=210 VolMounts=2 VolErrors=0 VolWrites=2 MaxVolBytes=0 EndTime=1226681071 VolStatus=Append Slot=0 relabel=1 InChanger=0 VolReadTime=0 VolWriteTime=177 VolFirstWritten=0 VolParts=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=177 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-14_16.44.28.05 UpdateMedia VolName=TestVolume0001 VolJobs=1 VolFiles=0 VolBlocks=0 VolBytes=210 VolMounts=2 VolErrors=0 VolWrites=2 MaxVolBytes=0 EndTime=1226681071 VolStatus=Append Slot=0 relabel=0 InChanger=0 VolReadTime=0 VolWriteTime=177 VolFirstWritten=0 VolParts=0
localhost-dir: catreq.c:126-2 catreq CatReq Job=Second.2008-11-14_16.44.28.05 UpdateMedia VolName=TestVolume0001 VolJobs=1 VolFiles=0 VolBlocks=0 VolBytes=210 VolMounts=2 VolErrors=0 VolWrites=2 MaxVolBytes=0 EndTime=1226681071 VolStatus=Append Slot=0 relabel=0 InChanger=0 VolReadTime=0 VolWriteTime=177 VolFirstWritten=0 VolParts=0
localhost-dir: sql_update.c:338-2 update_media: FirstWritten=1226681071
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=1226681071
localhost-dir: next_vol.c:246-2 Vol=TestVolume0001 expired=1
localhost-dir: catreq.c:100-2 Vol Info for Second.2008-11-14_16.44.28.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=177 EndFile=0 EndBlock=0 VolParts=0 LabelType=0 MediaId=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=177 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=80da890
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: sql.c:737-2 initdb ref=1 connected=1 db=81595a8
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-1 FDStatus=T
localhost-sd: label.c:704-1 session_label record=80da890
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=728405187d 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-14_16.44.23.03 CreateJobMedia FirstIndex=1 LastIndex=4447 StartFile=0 EndFile=0 StartBlock=210 EndBlock=728448065 Copy=0 Strip=0 MediaId=1
localhost-sd: askdir.c:412-1 >dird CatReq Job=First.2008-11-14_16.44.23.03 CreateJobMedia FirstIndex=1 LastIndex=4447 StartFile=0 EndFile=0 StartBlock=210 EndBlock=728448065 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-14_16.44.23.03 UpdateMedia VolName=TestVolume0001 VolJobs=1 VolFiles=0 VolBlocks=11303 VolBytes=729157698 VolMounts=2 VolErrors=0 VolWrites=11305 MaxVolBytes=0 EndTime=1226681150 VolStatus=Used Slot=0 relabel=0 InChanger=0 VolReadTime=0 VolWriteTime=21606500 VolFirstWritten=0 VolParts=0
localhost-dir: sql_update.c:338-1 update_media: FirstWritten=1226681071
localhost-dir: next_vol.c:246-1 Vol=TestVolume0001 expired=0
localhost-dir: catreq.c:100-1 Vol Info for First.2008-11-14_16.44.23.03: 1000 OK VolName=TestVolume0001 VolJobs=1 VolFiles=0 VolBlocks=11303 VolBytes=729157698 VolMounts=2 VolErrors=0 VolWrites=11305 MaxVolBytes=0 VolCapacityBytes=0 VolStatus=Used Slot=0 MaxVolJobs=1 MaxVolFiles=0 InChanger=0 VolReadTime=0 VolWriteTime=21606500 EndFile=0 EndBlock=728448065 VolParts=0 LabelType=0 MediaId=1
localhost-sd: askdir.c:368-1 >dird CatReq Job=First.2008-11-14_16.44.23.03 UpdateMedia VolName=TestVolume0001 VolJobs=1 VolFiles=0 VolBlocks=11303 VolBytes=729157698 VolMounts=2 VolErrors=0 VolWrites=11305 MaxVolBytes=0 EndTime=1226681150 VolStatus=Used Slot=0 relabel=0 InChanger=0 VolReadTime=0 VolWriteTime=21606500 VolFirstWritten=0 VolParts=0
localhost-sd: askdir.c:182-1 <dird 1000 OK VolName=TestVolume0001 VolJobs=1 VolFiles=0 VolBlocks=11303 VolBytes=729157698 VolMounts=2 VolErrors=0 VolWrites=11305 MaxVolBytes=0 VolCapacityBytes=0 VolStatus=Used Slot=0 MaxVolJobs=1 MaxVolFiles=0 InChanger=0 VolReadTime=0 VolWriteTime=21606500 EndFile=0 EndBlock=728448065 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 14-Nov-2008 16:45:50
localhost-sd: acquire.c:538-1 ===== Device "FileStorage" (/usr/bin/bacula/regress/tmp) released by JobId=1
localhost-sd: spool.c:632-1 Commit attributes at 14-Nov-2008 16:45:50
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: 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-dir: backup.c:373-2 FDStatus=T
localhost-sd: label.c:704-2 session_label record=80b8400
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=733286465d File=0d
localhost-sd: append.c:301-2 back from write_end_session_label()
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-sd: askdir.c:412-2 >dird CatReq Job=Second.2008-11-14_16.44.28.05 CreateJobMedia FirstIndex=1 LastIndex=4447 StartFile=0 EndFile=0 StartBlock=210 EndBlock=733329345 Copy=0 Strip=0 MediaId=1
localhost-dir: catreq.c:126-2 catreq CatReq Job=Second.2008-11-14_16.44.28.05 CreateJobMedia FirstIndex=1 LastIndex=4447 StartFile=0 EndFile=0 StartBlock=210 EndBlock=733329345 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-sd: askdir.c:368-2 >dird CatReq Job=Second.2008-11-14_16.44.28.05 UpdateMedia VolName=TestVolume0001 VolJobs=1 VolFiles=0 VolBlocks=11368 VolBytes=733329346 VolMounts=2 VolErrors=0 VolWrites=11370 MaxVolBytes=0 EndTime=1226681151 VolStatus=Used Slot=0 relabel=0 InChanger=0 VolReadTime=0 VolWriteTime=21659189 VolFirstWritten=0 VolParts=0
localhost-dir: catreq.c:126-2 catreq CatReq Job=Second.2008-11-14_16.44.28.05 UpdateMedia VolName=TestVolume0001 VolJobs=1 VolFiles=0 VolBlocks=11368 VolBytes=733329346 VolMounts=2 VolErrors=0 VolWrites=11370 MaxVolBytes=0 EndTime=1226681151 VolStatus=Used Slot=0 relabel=0 InChanger=0 VolReadTime=0 VolWriteTime=21659189 VolFirstWritten=0 VolParts=0
localhost-dir: sql_update.c:338-2 update_media: FirstWritten=1226681071
localhost-dir: next_vol.c:246-2 Vol=TestVolume0001 expired=0
localhost-dir: catreq.c:100-2 Vol Info for Second.2008-11-14_16.44.28.05: 1000 OK VolName=TestVolume0001 VolJobs=1 VolFiles=0 VolBlocks=11368 VolBytes=733329346 VolMounts=2 VolErrors=0 VolWrites=11370 MaxVolBytes=0 VolCapacityBytes=0 VolStatus=Used Slot=0 MaxVolJobs=1 MaxVolFiles=0 InChanger=0 VolReadTime=0 VolWriteTime=21659189 EndFile=0 EndBlock=733329345 VolParts=0 LabelType=0 MediaId=1
localhost-sd: askdir.c:182-2 <dird 1000 OK VolName=TestVolume0001 VolJobs=1 VolFiles=0 VolBlocks=11368 VolBytes=733329346 VolMounts=2 VolErrors=0 VolWrites=11370 MaxVolBytes=0 VolCapacityBytes=0 VolStatus=Used Slot=0 MaxVolJobs=1 MaxVolFiles=0 InChanger=0 VolReadTime=0 VolWriteTime=21659189 EndFile=0 EndBlock=733329345 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 14-Nov-2008 16:45:51
localhost-sd: acquire.c:538-2 ===== Device "FileStorage" (/usr/bin/bacula/regress/tmp) released by JobId=2
localhost-sd: spool.c:632-2 Commit attributes at 14-Nov-2008 16:45:51
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: msgchan.c:348-2 === End msg_thread. JobId=2 usecnt=2
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: 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>1211129153 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=1226681153 period=2592000 sql=SELECT count(*) from Job WHERE JobTDate<1224089153 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>1211129153 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=1226681153 period=2592000 sql=SELECT count(*) from Job WHERE JobTDate<1224089153 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
14-Nov 16:44 localhost-dir JobId 2: No prior Full backup Job record found.
14-Nov 16:44 localhost-dir JobId 2: No prior or suitable Full backup found in catalog. Doing FULL backup.
14-Nov 16:44 localhost-dir JobId 2: Start Backup JobId 2, Job=Second.2008-11-14_16.44.28.05
14-Nov 16:44 localhost-dir JobId 2: There are no more Jobs associated with Volume "TestVolume0001". Marking it purged.
14-Nov 16:44 localhost-dir JobId 2: All records pruned from Volume "TestVolume0001"; marking it "Purged"
14-Nov 16:44 localhost-dir JobId 2: Recycled volume "TestVolume0001"
14-Nov 16:44 localhost-dir JobId 2: Using Device "FileStorage"
14-Nov 16:44 localhost-sd JobId 2: Recycled volume "TestVolume0001" on device "FileStorage" (/usr/bin/bacula/regress/tmp), all previous data lost.
14-Nov 16:44 localhost-dir JobId 2: Max Volume jobs exceeded. Marking Volume "TestVolume0001" as Used.
14-Nov 16:45 localhost-sd JobId 1: Job write elapsed time = 00:01:25, Transfer rate = 4.581 M bytes/second
14-Nov 16:45 localhost-sd JobId 2: Job write elapsed time = 00:01:20, Transfer rate = 4.867 M bytes/second
14-Nov 16:45 localhost-dir JobId 1: Bacula localhost-dir 2.5.20 (13Nov08): 14-Nov-2008 16:45:52
  Build OS:               i686-pc-linux-gnu unknown unknown
  JobId:                  1
  Job:                    First.2008-11-14_16.44.23.03
  Backup Level:           Full (upgraded from Incremental)
  Client:                 "localhost-fd" 2.5.20 (13Nov08) i686-pc-linux-gnu,unknown,unknown
  FileSet:                "Set1" 2008-11-14 16:44:23
  Pool:                   "Default" (From Job resource)
  Catalog:                "MyCatalog" (From Client resource)
  Storage:                "File" (From Job resource)
  Scheduled time:         14-Nov-2008 16:44:23
  Start time:             14-Nov-2008 16:44:25
  End time:               14-Nov-2008 16:45:52
  Elapsed time:           1 min 27 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:                   4468.1 KB/s
  Software Compression:   None
  VSS:                    no
  Encryption:             no
  Accurate:               no
  Volume name(s):         TestVolume0001
  Volume Session Id:      1
  Volume Session Time:    1226681060
  Last Volume Bytes:      733,329,346 (733.3 MB)
  Non-fatal FD errors:    0
  SD Errors:              0
  FD termination status:  OK
  SD termination status:  OK
  Termination:            Backup OK

14-Nov 16:45 localhost-dir JobId 1: Begin pruning Jobs.
14-Nov 16:45 localhost-dir JobId 1: No Jobs found to prune.
14-Nov 16:45 localhost-dir JobId 1: Begin pruning Files.
14-Nov 16:45 localhost-dir JobId 1: No Files found to prune.
14-Nov 16:45 localhost-dir JobId 1: End auto prune.

14-Nov 16:45 localhost-dir JobId 2: Bacula localhost-dir 2.5.20 (13Nov08): 14-Nov-2008 16:45:53
  Build OS:               i686-pc-linux-gnu unknown unknown
  JobId:                  2
  Job:                    Second.2008-11-14_16.44.28.05
  Backup Level:           Full (upgraded from Incremental)
  Client:                 "localhost-fd" 2.5.20 (13Nov08) i686-pc-linux-gnu,unknown,unknown
  FileSet:                "Set2" 2008-11-14 16:44:28
  Pool:                   "Default" (From Job resource)
  Catalog:                "MyCatalog" (From Client resource)
  Storage:                "File" (From Job resource)
  Scheduled time:         14-Nov-2008 16:44:28
  Start time:             14-Nov-2008 16:44:31
  End time:               14-Nov-2008 16:45:53
  Elapsed time:           1 min 22 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:                   4740.6 KB/s
  Software Compression:   None
  VSS:                    no
  Encryption:             no
  Accurate:               no
  Volume name(s):         TestVolume0001
  Volume Session Id:      2
  Volume Session Time:    1226681060
  Last Volume Bytes:      733,329,346 (733.3 MB)
  Non-fatal FD errors:    0
  SD Errors:              0
  FD termination status:  OK
  SD termination status:  OK
  Termination:            Backup OK

14-Nov 16:45 localhost-dir JobId 2: Begin pruning Jobs.
14-Nov 16:45 localhost-dir JobId 2: No Jobs found to prune.
14-Nov 16:45 localhost-dir JobId 2: Begin pruning Files.
14-Nov 16:45 localhost-dir JobId 2: No Files found to prune.
14-Nov 16:45 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-14 16:44:25 | 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-1868646474 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=1226681060
VolFile=0
VolBlock=210-728448065
FileIndex=1-4447
Count=4447
localhost-dir: ua_run.c:1323-1868646474 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-14 16:45:54
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-14_16.45.54.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-14_16.45.54.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 14-Nov-2008 16:45:56
localhost-sd: cram-md5.c:73-0 send: auth cram-md5 <1273174415.1226681156@localhost-sd> ssl=0
localhost-dir: cram-md5.c:133-3 cram-get received: auth cram-md5 <1273174415.1226681156@localhost-sd> ssl=0
localhost-dir: cram-md5.c:152-3 sending resp to challenge: eR/UB/5Gn418R9/cU1/jAB
localhost-dir: cram-md5.c:80-3 send: auth cram-md5 <1692385273.1226681156@localhost-dir> ssl=0
localhost-sd: cram-md5.c:133-0 cram-get received: auth cram-md5 <1692385273.1226681156@localhost-dir> ssl=0
localhost-sd: cram-md5.c:152-0 sending resp to challenge: KBt+TXxepm+u85xmR+/OmA
localhost-dir: cram-md5.c:99-3 Authenticate OK KBt+TXxepm+u85xmR+/OmA
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-14_16.45.54.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-14_16.45.54.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=1226681060 Authorization=FHHM-NOGI-MDNA-JGJJ-KBIN-BIAL-DDFM-HMPP
localhost-dir: msgchan.c:194-3 <stored: 3000 OK Job SDid=3 SDtime=1226681060 Authorization=FHHM-NOGI-MDNA-JGJJ-KBIN-BIAL-DDFM-HMPP
localhost-dir: msgchan.c:202-3 sd_auth_key=FHHM-NOGI-MDNA-JGJJ-KBIN-BIAL-DDFM-HMPP
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-14_16.45.54.06 waiting 1800 sec for FD to contact SD key=FHHM-NOGI-MDNA-JGJJ-KBIN-BIAL-DDFM-HMPP
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 <1899330557.1226681156@localhost-fd> ssl=0
localhost-dir: cram-md5.c:152-3 sending resp to challenge: Kk+rTkxr/9+db7+nj8tQkB
localhost-dir: cram-md5.c:80-3 send: auth cram-md5 <620571418.1226681156@localhost-dir> ssl=0
localhost-dir: cram-md5.c:99-3 Authenticate OK T9tRF5/b0lZzI5pSk/lUQC
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-14_16.45.54.06 SDid=3 SDtime=1226681060 Authorization=FHHM-NOGI-MDNA-JGJJ-KBIN-BIAL-DDFM-HMPP
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-14_16.45.54.06
localhost-sd: dircmd.c:177-0 Got a FD connection at 14-Nov-2008 16:45:56
localhost-sd: dircmd.c:178-0 Hello Start Job RestoreFiles.2008-11-14_16.45.54.06
localhost-sd: job.c:238-0 Found Job RestoreFiles.2008-11-14_16.45.54.06
localhost-sd: cram-md5.c:73-0 send: auth cram-md5 <409825617.1226681156@localhost-sd> ssl=0
localhost-sd: cram-md5.c:133-0 cram-get received: auth cram-md5 <178279081.1226681156@localhost-fd> ssl=0
localhost-sd: cram-md5.c:152-0 sending resp to challenge: y9+iGHI+b8Ysd8+wY0+4OB
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-14_16.45.54.06
localhost-sd: job.c:205-3 Auth=1 canceled=0 errstat=0
localhost-sd: job.c:211-3 Running job RestoreFiles.2008-11-14_16.45.54.06
localhost-sd: fd_cmds.c:122-3 Start run Job=RestoreFiles.2008-11-14_16.45.54.06
localhost-sd: fd_cmds.c:160-3 <filed: read open session = DummyVolume 3 1226681060 0 0 0 0
localhost-sd: fd_cmds.c:296-3 read open session = DummyVolume 3 1226681060 0 0 0 0

localhost-sd: fd_cmds.c:311-3 read_open_session got: JobId=3 Vol=DummyVolume VolSessId=3 VolSessT=1226681060
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=1226681060
localhost-sd: fd_cmds.c:361-3 VolFile=0
localhost-sd: fd_cmds.c:361-3 VolBlock=210-728448065
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    : 0x80eaf08
VolumeName  : TestVolume0001
  MediaType : File
  Device    : FileStorage
  Slot      : 0
SessId      : 1
SessTime    : 1226681060
VolFile     : 0-0
VolBlock    : 210-728448065
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-14_16.45.54.06 GetVolInfo VolName=TestVolume0001 write=0
localhost-dir: catreq.c:126-3 catreq CatReq Job=RestoreFiles.2008-11-14_16.45.54.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=11368 VolBytes=733329346 VolMounts=2 VolErrors=0 VolWrites=11370 MaxVolBytes=0 VolCapacityBytes=0 VolStatus=Used Slot=0 MaxVolJobs=1 MaxVolFiles=0 InChanger=0 VolReadTime=0 VolWriteTime=21659189 EndFile=0 EndBlock=733329345 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-14_16.45.54.06: 1000 OK VolName=TestVolume0001 VolJobs=1 VolFiles=0 VolBlocks=11368 VolBytes=733329346 VolMounts=2 VolErrors=0 VolWrites=11370 MaxVolBytes=0 VolCapacityBytes=0 VolStatus=Used Slot=0 MaxVolJobs=1 MaxVolFiles=0 InChanger=0 VolReadTime=0 VolWriteTime=21659189 EndFile=0 EndBlock=733329345 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: 14-Nov-2008 16:44
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 80a6398 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-14_16.45.54.06 UpdateMedia VolName=TestVolume0001 VolJobs=1 VolFiles=0 VolBlocks=11368 VolBytes=733329346 VolMounts=2 VolErrors=0 VolWrites=11370 MaxVolBytes=0 EndTime=1226681216 VolStatus=Used Slot=0 relabel=0 InChanger=0 VolReadTime=33821789 VolWriteTime=21659189 VolFirstWritten=0 VolParts=0
localhost-dir: catreq.c:126-3 catreq CatReq Job=RestoreFiles.2008-11-14_16.45.54.06 UpdateMedia VolName=TestVolume0001 VolJobs=1 VolFiles=0 VolBlocks=11368 VolBytes=733329346 VolMounts=2 VolErrors=0 VolWrites=11370 MaxVolBytes=0 EndTime=1226681216 VolStatus=Used Slot=0 relabel=0 InChanger=0 VolReadTime=33821789 VolWriteTime=21659189 VolFirstWritten=0 VolParts=0
localhost-dir: sql_update.c:338-3 update_media: FirstWritten=1226681071
localhost-dir: next_vol.c:246-3 Vol=TestVolume0001 expired=0
localhost-dir: catreq.c:100-3 Vol Info for RestoreFiles.2008-11-14_16.45.54.06: 1000 OK VolName=TestVolume0001 VolJobs=1 VolFiles=0 VolBlocks=11368 VolBytes=733329346 VolMounts=2 VolErrors=0 VolWrites=11370 MaxVolBytes=0 VolCapacityBytes=0 VolStatus=Used Slot=0 MaxVolJobs=1 MaxVolFiles=0 InChanger=0 VolReadTime=33821789 VolWriteTime=21659189 EndFile=0 EndBlock=733329345 VolParts=0 LabelType=0 MediaId=1
localhost-sd: askdir.c:182-3 <dird 1000 OK VolName=TestVolume0001 VolJobs=1 VolFiles=0 VolBlocks=11368 VolBytes=733329346 VolMounts=2 VolErrors=0 VolWrites=11370 MaxVolBytes=0 VolCapacityBytes=0 VolStatus=Used Slot=0 MaxVolJobs=1 MaxVolFiles=0 InChanger=0 VolReadTime=33821789 VolWriteTime=21659189 EndFile=0 EndBlock=733329345 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 14-Nov-2008 16:46:56
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>1211129216 AND Job.ClientId=1 AND Job.Type='R')
localhost-dir: ua_prune.c:243-3 select now=1226681216 period=2592000 sql=SELECT count(*) from Job WHERE JobTDate<1224089216 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
14-Nov 16:45 localhost-dir JobId 3: Start Restore Job RestoreFiles.2008-11-14_16.45.54.06
14-Nov 16:45 localhost-dir JobId 3: Using Device "FileStorage"
14-Nov 16:45 localhost-sd JobId 3: Ready to read from volume "TestVolume0001" on device "FileStorage" (/usr/bin/bacula/regress/tmp).
14-Nov 16:45 localhost-sd JobId 3: Forward spacing Volume "TestVolume0001" to file:block 0:210.
14-Nov 16:46 localhost-sd JobId 3: End of file 0 on device "FileStorage" (/usr/bin/bacula/regress/tmp), Volume "TestVolume0001"
14-Nov 16:46 localhost-sd JobId 3: End of Volume at file 0 on device "FileStorage" (/usr/bin/bacula/regress/tmp), Volume "TestVolume0001"
14-Nov 16:46 localhost-sd JobId 3: End of all volumes.
14-Nov 16:46 localhost-dir JobId 3: Bacula localhost-dir 2.5.20 (13Nov08): 14-Nov-2008 16:46:56
  Build OS:               i686-pc-linux-gnu unknown unknown
  JobId:                  3
  Job:                    RestoreFiles.2008-11-14_16.45.54.06
  Restore Client:         localhost-fd
  Start time:             14-Nov-2008 16:45:56
  End time:               14-Nov-2008 16:46:56
  Files Expected:         4,447
  Files Restored:         2,162
  Bytes Restored:         342,736,812
  Rate:                   5712.3 KB/s
  FD Errors:              0
  FD termination status:  OK
  SD termination status:  OK
  Termination:            Restore OK -- warning file count mismatch

14-Nov 16:46 localhost-dir JobId 3: Begin pruning Jobs.
14-Nov 16:46 localhost-dir JobId 3: No Jobs found to prune.
14-Nov 16:46 localhost-dir JobId 3: Begin pruning Files.
14-Nov 16:46 localhost-dir JobId 3: No Files found to prune.
14-Nov 16:46 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-14_16.46.56.07
localhost-dir: cram-md5.c:73-0 send: auth cram-md5 <880258832.1226681216@localhost-dir> ssl=0
localhost-dir: cram-md5.c:133-0 cram-get received: auth cram-md5 <1300698552.1226681216@bconsole> ssl=0
localhost-dir: cram-md5.c:152-0 sending resp to challenge: +4c2kz+CM70BCk5VCk/FAB
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 <2066372968.1226681216@localhost-fd> ssl=0
localhost-dir: cram-md5.c:152-0 sending resp to challenge: y6/bAEYjg58CW80Cvn+AnB
localhost-dir: cram-md5.c:80-0 send: auth cram-md5 <2135517402.1226681217@localhost-dir> ssl=0
localhost-dir: cram-md5.c:99-0 Authenticate OK sn+eIzIDlk/R1E+te49frC
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-14_16.46.56.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 14-Nov-2008 16:46:57
localhost-sd: cram-md5.c:73-0 send: auth cram-md5 <1804289383.1226681217@localhost-sd> ssl=0
localhost-dir: cram-md5.c:133-0 cram-get received: auth cram-md5 <1804289383.1226681217@localhost-sd> ssl=0
localhost-dir: cram-md5.c:152-0 sending resp to challenge: G/0x54oubh/72//5U/xQbB
localhost-dir: cram-md5.c:80-0 send: auth cram-md5 <1088820515.1226681217@localhost-dir> ssl=0
localhost-sd: cram-md5.c:133-0 cram-get received: auth cram-md5 <1088820515.1226681217@localhost-dir> ssl=0
localhost-dir: cram-md5.c:99-0 Authenticate OK Jm+v3ygyuB/8cVER45+J9A
localhost-dir: authenticate.c:152-0 >stored: 1000 OK auth
localhost-sd: cram-md5.c:152-0 sending resp to challenge: Jm+v3ygyuB/8cVER45+J9A
localhost-dir: authenticate.c:159-0 <stored: 3000 OK Hello
localhost-sd: dircmd.c:209-0 Message channel init completed.
localhost-dir: ua_status.c:370-0 Connected to storage daemon
Only in build: AUTHORS
Only in build: ChangeLog
Only in build: LICENSE
Only in build: Makefile.in
Only in build: README
Only in build: ReleaseNotes
Only in build: autoconf
Only in build: configure
Only in build/depkgs: Makefile.save
Only in build/depkgs: README
Only in build/depkgs: build-sqlite
Only in build/depkgs: build-sqlite3
Only in build/depkgs: qwtconfig.pri
Only in build/depkgs/sqlite-3.5.6: CVS
Only in build/depkgs/sqlite-3.5.6: Makefile.arm-wince-mingw32ce-gcc
Only in build/depkgs/sqlite-3.5.6: Makefile.in.orig
Only in build/depkgs/sqlite-3.5.6: Makefile.linux-gcc
Only in build/depkgs/sqlite-3.5.6: README
Only in build/depkgs/sqlite-3.5.6: VERSION
Only in build/depkgs/sqlite-3.5.6: aclocal.m4
Only in build/depkgs/sqlite-3.5.6: addopcodes.awk
Only in build/depkgs/sqlite-3.5.6: config.guess
Only in build/depkgs/sqlite-3.5.6: config.sub
Only in build/depkgs/sqlite-3.5.6: configure
Only in build/depkgs/sqlite-3.5.6: configure.ac
Only in build/depkgs/sqlite-3.5.6: contrib
Only in build/depkgs/sqlite-3.5.6: doc
Only in build/depkgs/sqlite-3.5.6/ext: CVS
Only in build/depkgs/sqlite-3.5.6/ext: README.txt
Only in build/depkgs/sqlite-3.5.6/ext: fts1
Only in build/depkgs/sqlite-3.5.6/ext: fts2
Only in build/depkgs/sqlite-3.5.6/ext/fts3: CVS
Only in build/depkgs/sqlite-3.5.6/ext/fts3: README.tokenizers
Only in build/depkgs/sqlite-3.5.6/ext/fts3: README.txt
Only in build/depkgs/sqlite-3.5.6/ext/fts3: fts3.c
Only in build/depkgs/sqlite-3.5.6/ext/fts3: fts3_porter.c
Only in build/depkgs/sqlite-3.5.6/ext/fts3: fts3_tokenizer.c
Only in build/depkgs/sqlite-3.5.6/ext/fts3: fts3_tokenizer.h
Only in build/depkgs/sqlite-3.5.6/ext/fts3: fts3_tokenizer1.c
Only in build/depkgs/sqlite-3.5.6/ext/fts3: mkfts3amal.tcl
Only in build/depkgs/sqlite-3.5.6/ext: icu
Only in build/depkgs/sqlite-3.5.6: install-sh
Only in build/depkgs/sqlite-3.5.6: ltmain.sh
Only in build/depkgs/sqlite-3.5.6: main.mk
Only in build/depkgs/sqlite-3.5.6: mkdll.sh
Only in build/depkgs/sqlite-3.5.6: mkextw.sh
Only in build/depkgs/sqlite-3.5.6: mkopcodeh.awk
Only in build/depkgs/sqlite-3.5.6: notes
Only in build/depkgs/sqlite-3.5.6: publish.sh
Only in build/depkgs/sqlite-3.5.6: publish_osx.sh
Only in build/depkgs/sqlite-3.5.6: sqlite.pc.in
Only in build/depkgs/sqlite-3.5.6: sqlite3.h
Only in build/depkgs/sqlite-3.5.6: src
Only in build/depkgs/sqlite-3.5.6: tclinstaller.tcl
Only in build/depkgs/sqlite-3.5.6: www
Only in build: examples
Only in build: manpages
Only in build: patches
Only in build: platforms
Only in build: po
Only in build: projects
Only in build: scripts
Only in build: src
Only in build: technotes-2.5
Only in build: updatedb
 
 
  !!!!! broken-media-bug-test failed!!! 16:49:03 !!!!! 
  !!!!! 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.