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

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


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.
diff -Naur --exclude=test.out --exclude=working --exclude=build --exclude=bin --exclude=tmp --exclude=weird-files --exclude=docs --exclude=gui --exclude=bacula bacula.orig/regress/scripts/broken-media-bug-bacula-dir.conf bacula/regress/scripts/broken-media-bug-bacula-dir.conf
--- bacula.orig/regress/scripts/broken-media-bug-bacula-dir.conf	Thu Jan  1 01:00:00 1970
+++ bacula/regress/scripts/broken-media-bug-bacula-dir.conf	Tue Nov 11 11:14:27 2008
@@ -0,0 +1,131 @@
+# Configuration for the director for testing for the broken media bug.
+# Test written by Graham Keeling
+
+Director {                            # define myself
+  Name = localhost-dir
+  DIRPort = 8101                # where we listen for UA connections
+  QueryFile = "/usr/bin/bacula/regress/bin/query.sql"
+  WorkingDirectory = "/usr/bin/bacula/regress/working"
+  PidDirectory = "/usr/bin/bacula/regress/working"
+  SubSysDirectory = "/usr/bin/bacula/regress/working"
+  PluginDirectory = "/usr/bin/bacula/regress/bin"
+  Maximum Concurrent Jobs = 4
+  Password = "pNvX1WiXnwv2C/F7E52LGvw6rKjbbPvu2kyuPa9pVaL3"         # Console password
+  Messages = Standard
+}
+
+Job {
+  Name = "First"
+  Type = Backup
+  Client=localhost-fd 
+  FileSet="Set1"
+  Storage = File
+  Messages = Standard
+  Pool = Default
+  Write Bootstrap = "/usr/bin/bacula/regress/working/NightlySave.bsr"
+  Maximum Concurrent Jobs = 4
+}
+
+Job {
+  Name = "Second"
+  Type = Backup
+  Client=localhost-fd 
+  FileSet="Set2"
+  Storage = File
+  Messages = Standard
+  Pool = Default
+  Write Bootstrap = "/usr/bin/bacula/regress/working/NightlySave.bsr"
+  Maximum Concurrent Jobs = 4
+}
+
+# Standard Restore template, to be changed by Console program
+Job {
+  Name = "RestoreFiles"
+  Type = Restore
+  Client=localhost-fd 
+  FileSet="Set1"
+  Storage = File
+  Messages = Standard
+  Pool = Default
+  Where = /usr/bin/bacula/regress/tmp/bacula-restores
+}
+
+
+# List of files to be backed up
+FileSet {
+  Name = "Set1"
+  Include {  
+     Options { signature=MD5; }
+     File =  </usr/bin/bacula/regress/tmp/file-list
+  }
+}
+
+FileSet {
+  Name = "Set2"
+  Include {  
+     Options { signature=MD5; }
+     File =  </usr/bin/bacula/regress/tmp/file-list
+  }
+}
+
+
+# Client (File Services) to backup
+Client {
+  Name = localhost-fd
+  Address = localhost
+  FDPort = 8102
+  Catalog = MyCatalog
+  Password = "xevrjURYoCHhn26RaJoWbeWXEY/a3VqGKp/37tgWiuHc"          # password for FileDaemon
+  File Retention = 30d                # 30 days
+  Job Retention = 180d                # six months
+  AutoPrune = yes                     # Prune expired Jobs/Files
+  Maximum Concurrent Jobs = 4
+}
+
+# Definiton of file storage device
+Storage {
+  Name = File
+  Address = localhost                # N.B. Use a fully qualified name here
+  SDPort = 8103
+  Password = "ccV3lVTsQRsdIUGyab0N4sMDavui2hOBkmpBU0aQKOr9"
+  Device = FileStorage
+  Media Type = File
+  Maximum Concurrent Jobs = 4
+}
+
+# Generic catalog service
+Catalog {
+  Name = MyCatalog
+  
+  dbname = regress; user = regress; password = ""
+}
+
+# Reasonable message delivery -- send most everything to email address
+#  and to the console
+Messages {
+  Name = Standard
+  mailcommand = "/usr/bin/bacula/regress/bin/bsmtp -h localhost -f \"\(Bacula regression\) %r\" -s \"Regression: %t %e of %c %l\" %r"
+  operatorcommand = "/usr/bin/bacula/regress/bin/bsmtp -h localhost -f \"\(Bacula regression\) %r\" -s \"Regression: Intervention needed for %j\" %r"
+# MailOnError = graham@xxxxxxxxxxxx = all
+# operator = graham@xxxxxxxxxxxx = mount
+  console = all, !skipped, !terminate, !restored
+#
+# WARNING! the following will create a file that you must cycle from
+#          time to time as it will grow indefinitely. However, it will
+#          also keep all your messages if the scroll off the console.
+#
+  append = "/usr/bin/bacula/regress/working/log" = all, !skipped
+  catalog = all, !skipped
+}
+    
+# Default pool definition
+Pool {
+  Name = Default
+  Pool Type = Backup
+  Recycle = yes                       # Bacula can automatically recycle Volumes
+  AutoPrune = yes                     # Prune expired volumes
+  Volume Retention = 365d             # one year
+  Maximum Volume Jobs = 1
+  Label Format = TestVolume
+  Maximum Volumes = 0
+}
diff -Naur --exclude=test.out --exclude=working --exclude=build --exclude=bin --exclude=tmp --exclude=weird-files --exclude=docs --exclude=gui --exclude=bacula bacula.orig/regress/tests/broken-media-bug-test bacula/regress/tests/broken-media-bug-test
--- bacula.orig/regress/tests/broken-media-bug-test	Thu Jan  1 01:00:00 1970
+++ bacula/regress/tests/broken-media-bug-test	Tue Nov 11 11:24:48 2008
@@ -0,0 +1,59 @@
+#!/bin/sh
+#
+# Show the broken media bug. Test by Graham Keeling.
+#
+TestName="broken-media-bug-test"
+. scripts/functions
+
+cwd=`pwd`
+scripts/cleanup
+/bin/cp -f scripts/broken-media-bug-bacula-dir.conf bin/bacula-dir.conf
+/bin/cp -f scripts/test-bacula-sd.conf bin/bacula-sd.conf
+/bin/cp -f scripts/test-bacula-fd.conf bin/bacula-fd.conf
+/bin/cp -f scripts/test-console.conf bin/bconsole.conf
+hugefile=${cwd}/build/hugefile
+hugefilesize=300
+echo "${cwd}/build" >${cwd}/tmp/file-list
+
+start_test
+
+echo "Creating huge ${hugefilesize}M file..."
+dd if=/dev/urandom of="$hugefile" bs=1M count="$hugefilesize"
+echo "Done"
+
+cat >tmp/bconcmds <<END_OF_DATA
+setdebug level=150  storage=File
+messages
+@$out tmp/log1.out
+run job=First yes
+messages
+quit
+END_OF_DATA
+
+run_bacula
+
+# Give the first job a bit of time to get going.
+sleep 5
+
+cat >tmp/bconcmds <<END_OF_DATA
+setdebug level=150  storage=File
+messages
+@$out tmp/log2.out
+run job=Second yes
+wait
+messages
+restore fileset=Set1 where=${cwd}/tmp/bacula-restores select all storage=File done
+yes
+wait
+messages
+quit
+END_OF_DATA
+
+run_bconsole
+check_for_zombie_jobs storage=File
+stop_bacula
+
+check_two_logs
+check_restore_diff
+rm -f "$hugefile"
+end_test
 
 
 === Starting broken-media-bug-test at 11:33:42 ===
 
Creating huge 300M file...
300+0 records in
300+0 records out
314572800 bytes (315 MB) copied, 63.0484 seconds, 5.0 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.19 (07 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
messages
You have no messages.
@tee tmp/log1.out
run job=First yes
Using Catalog "MyCatalog"
Job queued. JobId=1
You have messages.
messages
11-Nov 11:34 localhost-dir JobId 1: No prior Full backup Job record found.
11-Nov 11:34 localhost-dir JobId 1: No prior or suitable Full backup found in catalog. Doing FULL backup.
quit
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 11-Nov-2008 11:34:55
localhost-sd: cram-md5.c:73-0 send: auth cram-md5 <1061895395.1226403295@localhost-sd> ssl=0
localhost-sd: cram-md5.c:133-0 cram-get received: auth cram-md5 <367170634.1226403295@localhost-dir> ssl=0
localhost-sd: cram-md5.c:152-0 sending resp to challenge: ShU9j8+EO4+c2/NgCWwneA
localhost-sd: dircmd.c:209-0 Message channel init completed.
localhost-sd: job.c:92-0 <dird: JobId=1 job=First.2008-11-11_11.34.53.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=1226403285 Authorization=EBHH-PEBK-EJDI-DDIK-PAIB-GIAC-CPEK-PCDH
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-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-11_11.34.53.03 FindMedia=1 pool_name=Default media_type=File
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 80b8b78 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-sd: job.c:190-1 First.2008-11-11_11.34.53.03 waiting 1800 sec for FD to contact SD key=EBHH-PEBK-EJDI-DDIK-PAIB-GIAC-CPEK-PCDH
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-11_11.34.53.03
localhost-sd: dircmd.c:177-0 Got a FD connection at 11-Nov-2008 11:34:56
localhost-sd: dircmd.c:178-0 Hello Start Job First.2008-11-11_11.34.53.03
localhost-sd: job.c:238-0 Found Job First.2008-11-11_11.34.53.03
localhost-sd: cram-md5.c:73-0 send: auth cram-md5 <2020320786.1226403296@localhost-sd> ssl=0
localhost-sd: cram-md5.c:133-0 cram-get received: auth cram-md5 <1136462060.1226403296@localhost-fd> ssl=0
localhost-sd: cram-md5.c:152-0 sending resp to challenge: vVJIvx+jL5+Pn++OlQxD/D
localhost-sd: job.c:261-0 OK Authentication jid=1 Job First.2008-11-11_11.34.53.03
localhost-sd: job.c:205-1 Auth=1 canceled=0 errstat=0
localhost-sd: job.c:211-1 Running job First.2008-11-11_11.34.53.03
localhost-sd: fd_cmds.c:122-1 Start run Job=First.2008-11-11_11.34.53.03
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-11_11.34.53.03 GetVolInfo VolName=TestVolume0001 write=1
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          : tdir
Date label written: 11-Nov-2008 11:34
localhost-sd: label.c:590-1 Created Vol label rec: FI=PRE_LABEL len=167
localhost-sd: label.c:369-1 Wrote label of 167 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          : tdir
Date label written: 11-Nov-2008 11:34
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-11_11.34.53.03 UpdateMedia VolName=TestVolume0001 VolJobs=0 VolFiles=0 VolBlocks=0 VolBytes=0 VolMounts=0 VolErrors=0 VolWrites=0 MaxVolBytes=0 EndTime=1226403296 VolStatus=Append Slot=0 relabel=1 InChanger=0 VolReadTime=0 VolWriteTime=0 VolFirstWritten=0 VolParts=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=203
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         : 167
PoolName          : Default
MediaType         : File
PoolType          : Backup
HostName          : tdir
Date label written: 11-Nov-2008 11:34
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=167
localhost-sd: label.c:282-1 Wrote label of 167 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-11_11.34.53.03 UpdateMedia VolName=TestVolume0001 VolJobs=0 VolFiles=0 VolBlocks=0 VolBytes=203 VolMounts=1 VolErrors=0 VolWrites=1 MaxVolBytes=0 EndTime=1226403296 VolStatus=Append Slot=0 relabel=1 InChanger=0 VolReadTime=0 VolWriteTime=8 VolFirstWritten=0 VolParts=0
localhost-sd: askdir.c:182-1 <dird 1000 OK VolName=TestVolume0001 VolJobs=0 VolFiles=0 VolBlocks=0 VolBytes=203 VolMounts=1 VolErrors=0 VolWrites=1 MaxVolBytes=0 VolCapacityBytes=0 VolStatus=Append Slot=0 MaxVolJobs=1 MaxVolFiles=0 InChanger=0 VolReadTime=0 VolWriteTime=8 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-11_11.34.53.03 UpdateMedia VolName=TestVolume0001 VolJobs=1 VolFiles=0 VolBlocks=0 VolBytes=203 VolMounts=1 VolErrors=0 VolWrites=1 MaxVolBytes=0 EndTime=1226403296 VolStatus=Append Slot=0 relabel=0 InChanger=0 VolReadTime=0 VolWriteTime=8 VolFirstWritten=0 VolParts=0
localhost-sd: askdir.c:182-1 <dird 1000 OK VolName=TestVolume0001 VolJobs=1 VolFiles=0 VolBlocks=0 VolBytes=203 VolMounts=1 VolErrors=0 VolWrites=1 MaxVolBytes=0 VolCapacityBytes=0 VolStatus=Used Slot=0 MaxVolJobs=1 MaxVolFiles=0 InChanger=0 VolReadTime=0 VolWriteTime=8 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=80b8a58
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=202d File=0d
Connecting to Director localhost:8101
1000 OK: localhost-dir Version: 2.5.19 (07 November 2008)
Enter a period to cancel a command.
setdebug level=150  storage=File
Connecting to Storage daemon File at localhost: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 11-Nov-2008 11:34:59
localhost-sd: cram-md5.c:73-0 send: auth cram-md5 <1130296109.1226403299@localhost-sd> ssl=0
localhost-sd: cram-md5.c:133-0 cram-get received: auth cram-md5 <411103160.1226403299@localhost-dir> ssl=0
localhost-sd: cram-md5.c:152-0 sending resp to challenge: y81aoD83I/+9h/+515tiWA
localhost-sd: dircmd.c:209-0 Message channel init completed.
localhost-sd: dircmd.c:279-0 setdebug_cmd: setdebug=150 trace=-1
3000 OK setdebug=150
You have messages.
messages
11-Nov 11:34 localhost-dir JobId 1: Start Backup JobId 1, Job=First.2008-11-11_11.34.53.03
11-Nov 11:34 localhost-dir JobId 1: Created new Volume "TestVolume0001" in catalog.
11-Nov 11:34 localhost-dir JobId 1: Using Device "FileStorage"
11-Nov 11:34 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
11-Nov 11:34 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
11-Nov 11:34 localhost-sd JobId 1: Labeled new Volume "TestVolume0001" on device "FileStorage" (/usr/bin/bacula/regress/tmp).
11-Nov 11:34 localhost-sd JobId 1: Wrote label to prelabeled Volume "TestVolume0001" on device "FileStorage" (/usr/bin/bacula/regress/tmp)
11-Nov 11:34 localhost-dir JobId 1: Max Volume jobs exceeded. Marking Volume "TestVolume0001" as Used.
@tee tmp/log2.out
run job=Second yes
Using Catalog "MyCatalog"
Job queued. JobId=2
You have messages.
wait
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 11-Nov-2008 11:35:01
localhost-sd: cram-md5.c:73-0 send: auth cram-md5 <151861581.1226403301@localhost-sd> ssl=0
localhost-sd: cram-md5.c:133-0 cram-get received: auth cram-md5 <615090210.1226403301@localhost-dir> ssl=0
localhost-sd: cram-md5.c:152-0 sending resp to challenge: 3BYSZ/+MNVk6V4/yZ5+GcC
localhost-sd: dircmd.c:209-0 Message channel init completed.
localhost-sd: job.c:92-0 <dird: JobId=2 job=Second.2008-11-11_11.34.59.05 job_name=Second client_name=localhost-fd type=66 level=70 FileSet=Set2 NoAttr=0 SpoolAttr=0 FileSetMD5=B5lTmCERCG+gRWNQQg/88B SpoolData=0 WritePartAfterJob=1 PreferMountedVols=1 SpoolSize=0
localhost-sd: job.c:157-2 >dird jid=2: 3000 OK Job SDid=2 SDtime=1226403285 Authorization=NNML-GHFI-ONOO-FDJI-NAOC-HOHG-GPLE-GCAM
localhost-sd: reserve.c:198-2 <dird: use storage=File media_type=File pool_name=Default pool_type=Backup append=1 copy=0 stripe=0
localhost-sd: reserve.c:227-2 <dird device: use device=FileStorage
localhost-sd: reserve.c:243-2 Storage=File media_type=File pool=Default pool_type=Backup append=1
localhost-sd: reserve.c:245-2      Device=FileStorage
localhost-sd: reserve.c:419-2 Start find_suit_dev PrefMnt=1 exact=1 suitable=0 chgronly=0 any=0
localhost-sd: vol_mgr.c:748-2 lock volumes
localhost-sd: vol_mgr.c:750-2 duplicate vol list
localhost-sd: vol_mgr.c:766-2 unlock volumes
localhost-sd: reserve.c:433-2 look for vol in vol list
localhost-sd: askdir.c:230-2 >dird CatReq Job=Second.2008-11-11_11.34.59.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-sd: askdir.c:276-2 >dird CatReq Job=Second.2008-11-11_11.34.59.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=8 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-sd: job.c:190-2 Second.2008-11-11_11.34.59.05 waiting 1800 sec for FD to contact SD key=NNML-GHFI-ONOO-FDJI-NAOC-HOHG-GPLE-GCAM
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-11_11.34.59.05
localhost-sd: dircmd.c:177-0 Got a FD connection at 11-Nov-2008 11:35:01
localhost-sd: dircmd.c:178-0 Hello Start Job Second.2008-11-11_11.34.59.05
localhost-sd: job.c:238-0 Found Job Second.2008-11-11_11.34.59.05
localhost-sd: cram-md5.c:73-0 send: auth cram-md5 <664266858.1226403301@localhost-sd> ssl=0
localhost-sd: cram-md5.c:133-0 cram-get received: auth cram-md5 <1236088752.1226403301@localhost-fd> ssl=0
localhost-sd: cram-md5.c:152-0 sending resp to challenge: X1hHO6sti6pK38hfh1+r0A
localhost-sd: job.c:261-0 OK Authentication jid=2 Job Second.2008-11-11_11.34.59.05
localhost-sd: job.c:205-2 Auth=1 canceled=0 errstat=0
localhost-sd: job.c:211-2 Running job Second.2008-11-11_11.34.59.05
localhost-sd: fd_cmds.c:122-2 Start run Job=Second.2008-11-11_11.34.59.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-11_11.34.59.05 GetVolInfo VolName=TestVolume0001 write=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=8 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-11_11.34.59.05 GetVolInfo VolName=TestVolume0001 write=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=8 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         : 167
PoolName          : Default
MediaType         : File
PoolType          : Backup
HostName          : tdir
Date label written: 11-Nov-2008 11:34
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=167
localhost-sd: label.c:282-2 Wrote label of 167 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-sd: askdir.c:368-2 >dird CatReq Job=Second.2008-11-11_11.34.59.05 UpdateMedia VolName=TestVolume0001 VolJobs=0 VolFiles=0 VolBlocks=0 VolBytes=203 VolMounts=2 VolErrors=0 VolWrites=2 MaxVolBytes=0 EndTime=1226403303 VolStatus=Append Slot=0 relabel=1 InChanger=0 VolReadTime=0 VolWriteTime=81 VolFirstWritten=0 VolParts=0
localhost-sd: askdir.c:182-2 <dird 1000 OK VolName=TestVolume0001 VolJobs=0 VolFiles=0 VolBlocks=0 VolBytes=203 VolMounts=2 VolErrors=0 VolWrites=2 MaxVolBytes=0 VolCapacityBytes=0 VolStatus=Append Slot=0 MaxVolJobs=1 MaxVolFiles=0 InChanger=0 VolReadTime=0 VolWriteTime=81 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-11_11.34.59.05 UpdateMedia VolName=TestVolume0001 VolJobs=1 VolFiles=0 VolBlocks=0 VolBytes=203 VolMounts=2 VolErrors=0 VolWrites=2 MaxVolBytes=0 EndTime=1226403303 VolStatus=Append Slot=0 relabel=0 InChanger=0 VolReadTime=0 VolWriteTime=81 VolFirstWritten=0 VolParts=0
localhost-sd: askdir.c:182-2 <dird 1000 OK VolName=TestVolume0001 VolJobs=1 VolFiles=0 VolBlocks=0 VolBytes=203 VolMounts=2 VolErrors=0 VolWrites=2 MaxVolBytes=0 VolCapacityBytes=0 VolStatus=Used Slot=0 MaxVolJobs=1 MaxVolFiles=0 InChanger=0 VolReadTime=0 VolWriteTime=81 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=80db0f0
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=202d File=0d
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-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-2 <filed: append close session 2
localhost-sd: fd_cmds.c:251-2 <filed: append close session 2
localhost-sd: fd_cmds.c:258-2 >filed: 3000 OK close Status = 84
localhost-sd: fd_cmds.c:160-1 <filed: append 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-sd: label.c:704-1 session_label record=80db0f0
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=732920999d 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-sd: askdir.c:412-1 >dird CatReq Job=First.2008-11-11_11.34.53.03 CreateJobMedia FirstIndex=1 LastIndex=4445 StartFile=0 EndFile=0 StartBlock=203 EndBlock=732976863 Copy=0 Strip=0 MediaId=1
localhost-sd: label.c:704-2 session_label record=80db0f0
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=732976863d File=0d
localhost-sd: append.c:301-2 back from write_end_session_label()
localhost-sd: askdir.c:419-1 <dird 1000 OK CreateJobMedia
localhost-sd: askdir.c:345-1 Update cat VolFiles=0
localhost-sd: askdir.c:368-1 >dird CatReq Job=First.2008-11-11_11.34.53.03 UpdateMedia VolName=TestVolume0001 VolJobs=1 VolFiles=0 VolBlocks=11362 VolBytes=732976864 VolMounts=2 VolErrors=0 VolWrites=11364 MaxVolBytes=0 EndTime=1226403349 VolStatus=Used Slot=0 relabel=0 InChanger=0 VolReadTime=0 VolWriteTime=19802862 VolFirstWritten=0 VolParts=0
localhost-sd: askdir.c:182-1 <dird 1000 OK VolName=TestVolume0001 VolJobs=1 VolFiles=0 VolBlocks=11362 VolBytes=732976864 VolMounts=2 VolErrors=0 VolWrites=11364 MaxVolBytes=0 VolCapacityBytes=0 VolStatus=Used Slot=0 MaxVolJobs=1 MaxVolFiles=0 InChanger=0 VolReadTime=0 VolWriteTime=19802862 EndFile=0 EndBlock=732976863 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 11-Nov-2008 11:35:49
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-11_11.34.59.05 CreateJobMedia FirstIndex=1 LastIndex=4445 StartFile=0 EndFile=0 StartBlock=203 EndBlock=733032729 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-11_11.34.59.05 UpdateMedia VolName=TestVolume0001 VolJobs=1 VolFiles=0 VolBlocks=11363 VolBytes=733032730 VolMounts=2 VolErrors=0 VolWrites=11365 MaxVolBytes=0 EndTime=1226403349 VolStatus=Used Slot=0 relabel=0 InChanger=0 VolReadTime=0 VolWriteTime=19803071 VolFirstWritten=0 VolParts=0
localhost-sd: askdir.c:182-2 <dird 1000 OK VolName=TestVolume0001 VolJobs=1 VolFiles=0 VolBlocks=11363 VolBytes=733032730 VolMounts=2 VolErrors=0 VolWrites=11365 MaxVolBytes=0 VolCapacityBytes=0 VolStatus=Used Slot=0 MaxVolJobs=1 MaxVolFiles=0 InChanger=0 VolReadTime=0 VolWriteTime=19803071 EndFile=0 EndBlock=733032729 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 11-Nov-2008 11:35:49
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 11-Nov-2008 11:35:49
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-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 11-Nov-2008 11:35:49
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
messages
11-Nov 11:34 localhost-dir JobId 2: No prior Full backup Job record found.
11-Nov 11:34 localhost-dir JobId 2: No prior or suitable Full backup found in catalog. Doing FULL backup.
11-Nov 11:35 localhost-dir JobId 2: Start Backup JobId 2, Job=Second.2008-11-11_11.34.59.05
11-Nov 11:35 localhost-dir JobId 2: There are no more Jobs associated with Volume "TestVolume0001". Marking it purged.
11-Nov 11:35 localhost-dir JobId 2: All records pruned from Volume "TestVolume0001"; marking it "Purged"
11-Nov 11:35 localhost-dir JobId 2: Recycled volume "TestVolume0001"
11-Nov 11:35 localhost-dir JobId 2: Using Device "FileStorage"
11-Nov 11:35 localhost-sd JobId 2: Recycled volume "TestVolume0001" on device "FileStorage" (/usr/bin/bacula/regress/tmp), all previous data lost.
11-Nov 11:35 localhost-dir JobId 2: Max Volume jobs exceeded. Marking Volume "TestVolume0001" as Used.
11-Nov 11:35 localhost-sd JobId 1: Job write elapsed time = 00:00:51, Transfer rate = 7.634 M bytes/second
11-Nov 11:35 localhost-sd JobId 2: Job write elapsed time = 00:00:44, Transfer rate = 8.848 M bytes/second
11-Nov 11:35 localhost-dir JobId 2: Bacula localhost-dir 2.5.19 (07Nov08): 11-Nov-2008 11:35:51
  Build OS:               i686-pc-linux-gnu unknown unknown
  JobId:                  2
  Job:                    Second.2008-11-11_11.34.59.05
  Backup Level:           Full (upgraded from Incremental)
  Client:                 "localhost-fd" 2.5.19 (07Nov08) i686-pc-linux-gnu,unknown,unknown
  FileSet:                "Set2" 2008-11-11 11:34:59
  Pool:                   "Default" (From Job resource)
  Catalog:                "MyCatalog" (From Client resource)
  Storage:                "File" (From Job resource)
  Scheduled time:         11-Nov-2008 11:34:59
  Start time:             11-Nov-2008 11:35:01
  End time:               11-Nov-2008 11:35:51
  Elapsed time:           50 secs
  Priority:               10
  FD Files Written:       4,445
  SD Files Written:       4,445
  FD Bytes Written:       388,669,234 (388.6 MB)
  SD Bytes Written:       389,336,786 (389.3 MB)
  Rate:                   7773.4 KB/s
  Software Compression:   None
  VSS:                    no
  Encryption:             no
  Accurate:               no
  Volume name(s):         TestVolume0001
  Volume Session Id:      2
  Volume Session Time:    1226403285
  Last Volume Bytes:      733,032,730 (733.0 MB)
  Non-fatal FD errors:    0
  SD Errors:              0
  FD termination status:  OK
  SD termination status:  OK
  Termination:            Backup OK

11-Nov 11:35 localhost-dir JobId 2: Begin pruning Jobs.
11-Nov 11:35 localhost-dir JobId 2: No Jobs found to prune.
11-Nov 11:35 localhost-dir JobId 2: Begin pruning Files.
11-Nov 11:35 localhost-dir JobId 2: No Files found to prune.
11-Nov 11:35 localhost-dir JobId 2: End auto prune.

11-Nov 11:35 localhost-dir JobId 1: Bacula localhost-dir 2.5.19 (07Nov08): 11-Nov-2008 11:35:51
  Build OS:               i686-pc-linux-gnu unknown unknown
  JobId:                  1
  Job:                    First.2008-11-11_11.34.53.03
  Backup Level:           Full (upgraded from Incremental)
  Client:                 "localhost-fd" 2.5.19 (07Nov08) i686-pc-linux-gnu,unknown,unknown
  FileSet:                "Set1" 2008-11-11 11:34:53
  Pool:                   "Default" (From Job resource)
  Catalog:                "MyCatalog" (From Client resource)
  Storage:                "File" (From Job resource)
  Scheduled time:         11-Nov-2008 11:34:53
  Start time:             11-Nov-2008 11:34:56
  End time:               11-Nov-2008 11:35:51
  Elapsed time:           55 secs
  Priority:               10
  FD Files Written:       4,445
  SD Files Written:       4,445
  FD Bytes Written:       388,669,234 (388.6 MB)
  SD Bytes Written:       389,336,786 (389.3 MB)
  Rate:                   7066.7 KB/s
  Software Compression:   None
  VSS:                    no
  Encryption:             no
  Accurate:               no
  Volume name(s):         TestVolume0001
  Volume Session Id:      1
  Volume Session Time:    1226403285
  Last Volume Bytes:      733,032,730 (733.0 MB)
  Non-fatal FD errors:    0
  SD Errors:              0
  FD termination status:  OK
  SD termination status:  OK
  Termination:            Backup OK

11-Nov 11:35 localhost-dir JobId 1: Begin pruning Jobs.
11-Nov 11:35 localhost-dir JobId 1: No Jobs found to prune.
11-Nov 11:35 localhost-dir JobId 1: Begin pruning Files.
11-Nov 11:35 localhost-dir JobId 1: No Files found to prune.
11-Nov 11:35 localhost-dir JobId 1: 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     | 4445     | 388669234 | 2008-11-11 11:34:56 | TestVolume0001 |
+-------+-------+----------+-----------+---------------------+----------------+
You have selected the following JobId: 1

Building directory tree for JobId(s) 1 ...  +++++++++++++++++++++++++++++++++++++++++++++++
4,217 files inserted into the tree and marked for extraction.
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,445 files selected to be restored.

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-11 11:35:53
Catalog:         MyCatalog
Priority:        10
Plugin Options:  *None*
OK to run? (yes/mod/no): yes
Job queued. JobId=3
wait
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 11-Nov-2008 11:35:55
localhost-sd: cram-md5.c:73-0 send: auth cram-md5 <1653249823.1226403355@localhost-sd> ssl=0
localhost-sd: cram-md5.c:133-0 cram-get received: auth cram-md5 <1595616085.1226403355@localhost-dir> ssl=0
localhost-sd: cram-md5.c:152-0 sending resp to challenge: fkNmwn0O67MH+U/4oD/01D
localhost-sd: dircmd.c:209-0 Message channel init completed.
localhost-sd: job.c:92-0 <dird: JobId=3 job=RestoreFiles.2008-11-11_11.35.53.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=1226403285 Authorization=CFIH-MOLE-FPBM-OOMG-OPEK-EKGB-GNJG-MPOG
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-sd: job.c:190-3 RestoreFiles.2008-11-11_11.35.53.06 waiting 1800 sec for FD to contact SD key=CFIH-MOLE-FPBM-OOMG-OPEK-EKGB-GNJG-MPOG
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-11_11.35.53.06
localhost-sd: dircmd.c:177-0 Got a FD connection at 11-Nov-2008 11:35:55
localhost-sd: dircmd.c:178-0 Hello Start Job RestoreFiles.2008-11-11_11.35.53.06
localhost-sd: job.c:238-0 Found Job RestoreFiles.2008-11-11_11.35.53.06
localhost-sd: cram-md5.c:73-0 send: auth cram-md5 <182922521.1226403355@localhost-sd> ssl=0
localhost-sd: cram-md5.c:133-0 cram-get received: auth cram-md5 <1930085834.1226403355@localhost-fd> ssl=0
localhost-sd: cram-md5.c:152-0 sending resp to challenge: I6+rslhGr6NTTi+0m5lWKB
localhost-sd: job.c:261-0 OK Authentication jid=3 Job RestoreFiles.2008-11-11_11.35.53.06
localhost-sd: job.c:205-3 Auth=1 canceled=0 errstat=0
localhost-sd: job.c:211-3 Running job RestoreFiles.2008-11-11_11.35.53.06
localhost-sd: fd_cmds.c:122-3 Start run Job=RestoreFiles.2008-11-11_11.35.53.06
localhost-sd: fd_cmds.c:160-3 <filed: read open session = DummyVolume 3 1226403285 0 0 0 0
localhost-sd: fd_cmds.c:296-3 read open session = DummyVolume 3 1226403285 0 0 0 0

localhost-sd: fd_cmds.c:311-3 read_open_session got: JobId=3 Vol=DummyVolume VolSessId=3 VolSessT=1226403285
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=1226403285
localhost-sd: fd_cmds.c:361-3 VolFile=0
localhost-sd: fd_cmds.c:361-3 VolBlock=203-732976863
localhost-sd: fd_cmds.c:361-3 FileIndex=1-4445
localhost-sd: fd_cmds.c:361-3 Count=4445
localhost-sd: fd_cmds.c:365-3 === end bootstrap file ===
Next        : 0x0
Root bsr    : 0x80a6e90
VolumeName  : TestVolume0001
  MediaType : File
  Device    : FileStorage
  Slot      : 0
SessId      : 1
SessTime    : 1226403285
VolFile     : 0-0
VolBlock    : 203-732976863
FileIndex   : 1-4445
count       : 4445
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-11_11.35.53.06 GetVolInfo VolName=TestVolume0001 write=0
localhost-sd: askdir.c:182-3 <dird 1000 OK VolName=TestVolume0001 VolJobs=1 VolFiles=0 VolBlocks=11363 VolBytes=733032730 VolMounts=2 VolErrors=0 VolWrites=11365 MaxVolBytes=0 VolCapacityBytes=0 VolStatus=Used Slot=0 MaxVolJobs=1 MaxVolFiles=0 InChanger=0 VolReadTime=0 VolWriteTime=19803071 EndFile=0 EndBlock=733032729 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=779546273
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-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         : 167
PoolName          : Default
MediaType         : File
PoolType          : Backup
HostName          : tdir
Date label written: 11-Nov-2008 11:34
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 80a5128 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 203
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-11_11.35.53.06 UpdateMedia VolName=TestVolume0001 VolJobs=1 VolFiles=0 VolBlocks=11363 VolBytes=733032730 VolMounts=2 VolErrors=0 VolWrites=11365 MaxVolBytes=0 EndTime=1226403398 VolStatus=Used Slot=0 relabel=0 InChanger=0 VolReadTime=33531192 VolWriteTime=19803071 VolFirstWritten=0 VolParts=0
localhost-sd: askdir.c:182-3 <dird 1000 OK VolName=TestVolume0001 VolJobs=1 VolFiles=0 VolBlocks=11363 VolBytes=733032730 VolMounts=2 VolErrors=0 VolWrites=11365 MaxVolBytes=0 VolCapacityBytes=0 VolStatus=Used Slot=0 MaxVolJobs=1 MaxVolFiles=0 InChanger=0 VolReadTime=33531192 VolWriteTime=19803071 EndFile=0 EndBlock=733032729 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 11-Nov-2008 11:36:38
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-sd: jcr.c:184-3 write_last_jobs seek to 188
You have messages.
messages
11-Nov 11:35 localhost-dir JobId 3: Start Restore Job RestoreFiles.2008-11-11_11.35.53.06
11-Nov 11:35 localhost-dir JobId 3: Using Device "FileStorage"
11-Nov 11:35 localhost-sd JobId 3: Ready to read from volume "TestVolume0001" on device "FileStorage" (/usr/bin/bacula/regress/tmp).
11-Nov 11:35 localhost-sd JobId 3: Forward spacing Volume "TestVolume0001" to file:block 0:203.
11-Nov 11:36 localhost-sd JobId 3: End of file 0 on device "FileStorage" (/usr/bin/bacula/regress/tmp), Volume "TestVolume0001"
11-Nov 11:36 localhost-sd JobId 3: End of Volume at file 0 on device "FileStorage" (/usr/bin/bacula/regress/tmp), Volume "TestVolume0001"
11-Nov 11:36 localhost-sd JobId 3: End of all volumes.
11-Nov 11:36 localhost-dir JobId 3: Bacula localhost-dir 2.5.19 (07Nov08): 11-Nov-2008 11:36:38
  Build OS:               i686-pc-linux-gnu unknown unknown
  JobId:                  3
  Job:                    RestoreFiles.2008-11-11_11.35.53.06
  Restore Client:         localhost-fd
  Start time:             11-Nov-2008 11:35:54
  End time:               11-Nov-2008 11:36:38
  Files Expected:         4,445
  Files Restored:         2,140
  Bytes Restored:         342,588,953
  Rate:                   7786.1 KB/s
  FD Errors:              0
  FD termination status:  OK
  SD termination status:  OK
  Termination:            Restore OK -- warning file count mismatch

11-Nov 11:36 localhost-dir JobId 3: Begin pruning Jobs.
11-Nov 11:36 localhost-dir JobId 3: No Jobs found to prune.
11-Nov 11:36 localhost-dir JobId 3: Begin pruning Files.
11-Nov 11:36 localhost-dir JobId 3: No Files found to prune.
11-Nov 11:36 localhost-dir JobId 3: End auto prune.

quit
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 11-Nov-2008 11:36:39
localhost-sd: cram-md5.c:73-0 send: auth cram-md5 <1419692413.1226403399@localhost-sd> ssl=0
localhost-sd: cram-md5.c:133-0 cram-get received: auth cram-md5 <1612386877.1226403399@localhost-dir> ssl=0
localhost-sd: cram-md5.c:152-0 sending resp to challenge: f8/Z9lpt4yYDu4/9K/+ccB
localhost-sd: dircmd.c:209-0 Message channel init completed.
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/art: CVS
Only in build/depkgs/sqlite-3.5.6/art: SQLite.eps
Only in build/depkgs/sqlite-3.5.6/art: SQLite.gif
Only in build/depkgs/sqlite-3.5.6/art: SQLiteLogo3.tiff
Only in build/depkgs/sqlite-3.5.6/art: SQLite_big.gif
Only in build/depkgs/sqlite-3.5.6/art: nocopy.gif
Only in build/depkgs/sqlite-3.5.6/art: tmp
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
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: mkso.sh
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!!! 11:39:05 !!!!! 
  !!!!! 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.