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

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


On Mon, Nov 17, 2008 at 03:51:31PM +0000, Graham Keeling wrote:
> The above is an accurate description of the problem, except for the second
> point. I just re-ran broken-media-bug-test, but added two lines to it
> (the full test and output is attached to this email):
> 
> label storage=File volume=TestVolume0001
> label storage=File volume=TestVolume0002

Sorry, forgot to attach them. This mail should have them!
#!/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
setdebug level=150  Director
messages
@$out tmp/log1.out
label storage=File volume=TestVolume0001
label storage=File volume=TestVolume0002
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
setdebug level=150  Director
list volumes
llist volume=TestVolume0001
llist jobmedia
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 14:47:09 ===
 
Creating huge 300M file...
300+0 records in
300+0 records out
314572800 bytes (315 MB) copied, 119.365 seconds, 2.6 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
label storage=File volume=TestVolume0001
Automatically selected Catalog: MyCatalog
localhost-dir: ua_cmds.c:1931-0 UA Open database
localhost-dir: ua_cmds.c:1950-0 DB regress opened
localhost-dir: job.c:1298-0 wstore=File where=command line
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
Using Catalog "MyCatalog"
Automatically selected Pool: Default
Connecting to Storage daemon File at localhost:8103 ...
localhost-sd: dircmd.c:171-0 Conn: Hello Director localhost-dir calling
localhost-sd: dircmd.c:187-0 Got a DIR connection at 17-Nov-2008 14:49:11
localhost-sd: cram-md5.c:73-0 send: auth cram-md5 <1367518609.1226933351@localhost-sd> ssl=0
localhost-dir: cram-md5.c:133-0 cram-get received: auth cram-md5 <1367518609.1226933351@localhost-sd> ssl=0
localhost-dir: cram-md5.c:152-0 sending resp to challenge: 7T/v75xob9+Gl7BxD/QoQD
localhost-dir: cram-md5.c:80-0 send: auth cram-md5 <1060215728.1226933351@localhost-dir> ssl=0
localhost-sd: cram-md5.c:133-0 cram-get received: auth cram-md5 <1060215728.1226933351@localhost-dir> ssl=0
localhost-sd: cram-md5.c:152-0 sending resp to challenge: 7mg2gy1Ik9+Wq6BkdEQD+A
localhost-dir: cram-md5.c:99-0 Authenticate OK 7mg2gy1Ik9+Wq6BkdEQD+A
localhost-dir: authenticate.c:152-0 >stored: 1000 OK auth
localhost-sd: dircmd.c:209-0 Message channel init completed.
localhost-dir: authenticate.c:159-0 <stored: 3000 OK Hello
localhost-sd: dircmd.c:583-0 Found device FileStorage
localhost-sd: dircmd.c:623-0 Found device FileStorage
localhost-sd: dircmd.c:441-0 Stole device "FileStorage" (/usr/bin/bacula/regress/tmp) lock, writing label.
localhost-sd: dircmd.c:444-0 try_autoload_device - looking for volume_info
localhost-sd: autochanger.c:121-0 Device "FileStorage" (/usr/bin/bacula/regress/tmp) is not an autochanger
localhost-sd: dev.c:345-0 open dev: type=1 dev_name="FileStorage" (/usr/bin/bacula/regress/tmp) vol=TestVolume0001 mode=CREATE_READ_WRITE
localhost-sd: dev.c:354-0 call open_file_device mode=CREATE_READ_WRITE
localhost-sd: dev.c:526-0 open disk: mode=CREATE_READ_WRITE open(/usr/bin/bacula/regress/tmp/TestVolume0001, 0x42, 0640)
localhost-sd: dev.c:541-0 open dev: disk fd=7 opened, part=0/0, part_size=0
localhost-sd: dev.c:358-0 preserve=0x0 fd=7
localhost-sd: label.c:81-0 Enter read_volume_label res=0 device="FileStorage" (/usr/bin/bacula/regress/tmp) vol=TestVolume0001 dev_Vol=*NULL*
localhost-sd: label.c:130-0 Big if statement in read_volume_label
localhost-sd: label.c:135-0 Requested Volume "TestVolume0001" on "FileStorage" (/usr/bin/bacula/regress/tmp) is not a Bacula labeled Volume, because: ERR=block.c:1015 Read zero bytes at 0:0 on device "FileStorage" (/usr/bin/bacula/regress/tmp).
localhost-sd: label.c:163-0 No volume label - bailing out
localhost-sd: label.c:250-0 return 3
localhost-sd: label.c:304-0 write_volume_label()
localhost-sd: label.c:325-0 New VolName=TestVolume0001
localhost-sd: dev.c:336-0 Close fd for mode change.
localhost-sd: dev.c:345-0 open dev: type=1 dev_name="FileStorage" (/usr/bin/bacula/regress/tmp) vol=TestVolume0001 mode=OPEN_READ_WRITE
localhost-sd: dev.c:354-0 call open_file_device mode=OPEN_READ_WRITE
localhost-sd: dev.c:526-0 open disk: mode=OPEN_READ_WRITE open(/usr/bin/bacula/regress/tmp/TestVolume0001, 0x2, 0640)
localhost-sd: dev.c:541-0 open dev: disk fd=7 opened, part=0/0, part_size=0
localhost-sd: dev.c:358-0 preserve=0x0 fd=7
localhost-sd: label.c:334-0 Label type=0
localhost-sd: label.c:602-0 Start create_volume_label()
localhost-sd: dev.c:1892-0 Clear volhdr vol=

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

Volume Label:
Id                : Bacula 1.0 immortal
VerNo             : 11
VolName           : TestVolume0001
PrevVolName       : 
VolFile           : 0
LabelType         : PRE_LABEL
LabelSize         : 0
PoolName          : Default
MediaType         : File
PoolType          : Backup
HostName          : backuppilot
Date label written: 17-Nov-2008 14:49
localhost-sd: label.c:397-0 Call reserve_volume
localhost-sd: vol_mgr.c:350-0 enter reserve_volume=TestVolume0001 drive="FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: vol_mgr.c:269-0 new Vol=TestVolume0001 at 80a6f10 dev="FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: vol_mgr.c:454-0 === set in_use. vol=TestVolume0001 dev="FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: vol_mgr.c:212-0 List end new volume: TestVolume0001 in_use=1 on device "FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: vol_mgr.c:577-0 === set not reserved vol=TestVolume0001 num_writers=0 dev_reserved=0 dev="FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: vol_mgr.c:578-0 === clear in_use vol=TestVolume0001
localhost-sd: vol_mgr.c:606-0 === clear in_use vol=TestVolume0001
localhost-sd: vol_mgr.c:609-0 === remove volume TestVolume0001 dev="FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: dev.c:1902-0 close_dev "FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: dev.c:1892-0 Clear volhdr vol=TestVolume0001
Sending label command for Volume "TestVolume0001" Slot 0 ...
localhost-dir: ua_label.c:695-0 label FileStorage VolumeName=TestVolume0001 PoolName=Default MediaType=File Slot=0 drive=-1
3000 OK label. VolBytes=210 DVD=0 Volume="TestVolume0001" Device="FileStorage" (/usr/bin/bacula/regress/tmp)
Catalog record for Volume "TestVolume0001", Slot 0  successfully created.
Requesting to mount FileStorage ...
localhost-sd: dircmd.c:583-0 Found device FileStorage
localhost-sd: dircmd.c:623-0 Found device FileStorage
localhost-sd: dircmd.c:655-0 mount cmd blocked=0 must_unload=0
3906 File device "FileStorage" (/usr/bin/bacula/regress/tmp) is always mounted.
label storage=File volume=TestVolume0002
localhost-dir: job.c:1298-0 wstore=File where=command line
Automatically selected Pool: Default
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
Connecting to Storage daemon File at localhost:8103 ...
localhost-sd: dircmd.c:171-0 Conn: Hello Director localhost-dir calling
localhost-sd: dircmd.c:187-0 Got a DIR connection at 17-Nov-2008 14:49:11
localhost-sd: cram-md5.c:73-0 send: auth cram-md5 <2079390418.1226933351@localhost-sd> ssl=0
localhost-dir: cram-md5.c:133-0 cram-get received: auth cram-md5 <2079390418.1226933351@localhost-sd> ssl=0
localhost-dir: cram-md5.c:152-0 sending resp to challenge: G8sDjT4IBV/BVFM96T+akC
localhost-dir: cram-md5.c:80-0 send: auth cram-md5 <841607865.1226933351@localhost-dir> ssl=0
localhost-sd: cram-md5.c:133-0 cram-get received: auth cram-md5 <841607865.1226933351@localhost-dir> ssl=0
localhost-sd: cram-md5.c:152-0 sending resp to challenge: I6kCC++jew//GG+0Q/+t7B
localhost-dir: cram-md5.c:99-0 Authenticate OK I6kCC++jew//GG+0Q/+t7B
localhost-dir: authenticate.c:152-0 >stored: 1000 OK auth
localhost-sd: dircmd.c:209-0 Message channel init completed.
localhost-dir: authenticate.c:159-0 <stored: 3000 OK Hello
Sending label command for Volume "TestVolume0002" Slot 0 ...
localhost-dir: ua_label.c:695-0 label FileStorage VolumeName=TestVolume0002 PoolName=Default MediaType=File Slot=0 drive=-1
localhost-sd: dircmd.c:583-0 Found device FileStorage
localhost-sd: dircmd.c:623-0 Found device FileStorage
localhost-sd: dircmd.c:441-0 Stole device "FileStorage" (/usr/bin/bacula/regress/tmp) lock, writing label.
localhost-sd: dircmd.c:444-0 try_autoload_device - looking for volume_info
localhost-sd: autochanger.c:121-0 Device "FileStorage" (/usr/bin/bacula/regress/tmp) is not an autochanger
localhost-sd: dev.c:345-0 open dev: type=1 dev_name="FileStorage" (/usr/bin/bacula/regress/tmp) vol=TestVolume0002 mode=CREATE_READ_WRITE
localhost-sd: dev.c:354-0 call open_file_device mode=CREATE_READ_WRITE
localhost-sd: dev.c:526-0 open disk: mode=CREATE_READ_WRITE open(/usr/bin/bacula/regress/tmp/TestVolume0002, 0x42, 0640)
localhost-sd: dev.c:541-0 open dev: disk fd=7 opened, part=0/0, part_size=210
localhost-sd: dev.c:358-0 preserve=0x0 fd=7
localhost-sd: label.c:81-0 Enter read_volume_label res=0 device="FileStorage" (/usr/bin/bacula/regress/tmp) vol=TestVolume0002 dev_Vol=*NULL*
localhost-sd: label.c:130-0 Big if statement in read_volume_label
localhost-sd: label.c:135-0 Requested Volume "TestVolume0002" on "FileStorage" (/usr/bin/bacula/regress/tmp) is not a Bacula labeled Volume, because: ERR=block.c:1015 Read zero bytes at 0:0 on device "FileStorage" (/usr/bin/bacula/regress/tmp).
localhost-sd: label.c:163-0 No volume label - bailing out
localhost-sd: label.c:250-0 return 3
localhost-sd: label.c:304-0 write_volume_label()
localhost-sd: label.c:325-0 New VolName=TestVolume0002
localhost-sd: dev.c:336-0 Close fd for mode change.
localhost-sd: dev.c:345-0 open dev: type=1 dev_name="FileStorage" (/usr/bin/bacula/regress/tmp) vol=TestVolume0002 mode=OPEN_READ_WRITE
localhost-sd: dev.c:354-0 call open_file_device mode=OPEN_READ_WRITE
localhost-sd: dev.c:526-0 open disk: mode=OPEN_READ_WRITE open(/usr/bin/bacula/regress/tmp/TestVolume0002, 0x2, 0640)
localhost-sd: dev.c:541-0 open dev: disk fd=7 opened, part=0/0, part_size=210
localhost-sd: dev.c:358-0 preserve=0x0 fd=7
localhost-sd: label.c:334-0 Label type=0
localhost-sd: label.c:602-0 Start create_volume_label()
localhost-sd: dev.c:1892-0 Clear volhdr vol=

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

Volume Label:
Id                : Bacula 1.0 immortal
VerNo             : 11
VolName           : TestVolume0002
PrevVolName       : 
VolFile           : 0
LabelType         : PRE_LABEL
LabelSize         : 0
PoolName          : Default
MediaType         : File
PoolType          : Backup
HostName          : backuppilot
Date label written: 17-Nov-2008 14:49
localhost-sd: label.c:397-0 Call reserve_volume
localhost-sd: vol_mgr.c:350-0 enter reserve_volume=TestVolume0002 drive="FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: vol_mgr.c:269-0 new Vol=TestVolume0002 at 80b79b8 dev="FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: vol_mgr.c:454-0 === set in_use. vol=TestVolume0002 dev="FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: vol_mgr.c:212-0 List end new volume: TestVolume0002 in_use=1 on device "FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: vol_mgr.c:577-0 === set not reserved vol=TestVolume0002 num_writers=0 dev_reserved=0 dev="FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: vol_mgr.c:578-0 === clear in_use vol=TestVolume0002
localhost-sd: vol_mgr.c:606-0 === clear in_use vol=TestVolume0002
localhost-sd: vol_mgr.c:609-0 === remove volume TestVolume0002 dev="FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: dev.c:1902-0 close_dev "FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: dev.c:1892-0 Clear volhdr vol=TestVolume0002
3000 OK label. VolBytes=210 DVD=0 Volume="TestVolume0002" Device="FileStorage" (/usr/bin/bacula/regress/tmp)
Catalog record for Volume "TestVolume0002", Slot 0  successfully created.
Requesting to mount FileStorage ...
localhost-sd: dircmd.c:583-0 Found device FileStorage
localhost-sd: dircmd.c:623-0 Found device FileStorage
localhost-sd: dircmd.c:655-0 mount cmd blocked=0 must_unload=0
3906 File device "FileStorage" (/usr/bin/bacula/regress/tmp) is always mounted.
run job=First 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=First.2008-11-17_14.49.11.03
localhost-dir: job.c:127-0 Open database
localhost-dir: job.c:142-0 DB opened
localhost-dir: job.c:798-0 Created Client localhost-fd record 1
localhost-dir: job.c:173-1 Created job record JobId=1 Name=First.2008-11-17_14.49.11.03 Type=B Level=I
localhost-dir: job.c:835-1 Created FileSet Set1 record 1
localhost-dir: fd_cmds.c:241-1 Level=F last start time=0000-00-00 00:00:00
localhost-dir: job.c:638-1 get_or_create_pool=Default
localhost-dir: ua_run.c:182-1 JobId=1 NewJobId=1 using pool Default priority=10
Job queued. JobId=1
You have messages.
messages
17-Nov 14:49 localhost-dir JobId 1: No prior Full backup Job record found.
17-Nov 14:49 localhost-dir JobId 1: No prior or suitable Full backup found in catalog. Doing FULL backup.
quit
localhost-dir: backup.c:197-1 JobId=1 JobLevel=F
localhost-dir: backup.c:209-1 Open connection with storage daemon
localhost-dir: msgchan.c:104-1 bnet_connect to Storage daemon localhost:8103
localhost-dir: bsock.c:201-1 Current host[ipv4:127.0.0.1:8103] All host[ipv4:127.0.0.1:8103] 
localhost-sd: bnet.c:669-0 who=client host=127.0.0.1 port=42783
localhost-dir: bsock.c:155-1 who=Storage daemon host=localhost port=8103
localhost-sd: dircmd.c:171-0 Conn: Hello Director localhost-dir calling
localhost-sd: dircmd.c:187-0 Got a DIR connection at 17-Nov-2008 14:49:13
localhost-sd: cram-md5.c:73-0 send: auth cram-md5 <1024929676.1226933353@localhost-sd> ssl=0
localhost-dir: cram-md5.c:133-1 cram-get received: auth cram-md5 <1024929676.1226933353@localhost-sd> ssl=0
localhost-dir: cram-md5.c:152-1 sending resp to challenge: Dy+EiSQpL6+qI6/IuB9dtB
localhost-dir: cram-md5.c:80-1 send: auth cram-md5 <591345871.1226933353@localhost-dir> ssl=0
localhost-sd: cram-md5.c:133-0 cram-get received: auth cram-md5 <591345871.1226933353@localhost-dir> ssl=0
localhost-sd: cram-md5.c:152-0 sending resp to challenge: /++Xs3IhM4+3V6/qT++bWA
localhost-dir: cram-md5.c:99-1 Authenticate OK /++Xs3IhM4+3V6/qT++bWA
localhost-dir: authenticate.c:152-1 >stored: 1000 OK auth
localhost-sd: dircmd.c:209-0 Message channel init completed.
localhost-dir: authenticate.c:159-1 <stored: 3000 OK Hello
localhost-sd: job.c:92-0 <dird: JobId=1 job=First.2008-11-17_14.49.11.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=1226933348 Authorization=NHIH-OEPM-NGKM-EOLE-OHGI-GAHE-PMEI-JHIF
localhost-dir: msgchan.c:192-1 >stored: JobId=1 job=First.2008-11-17_14.49.11.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=1226933348 Authorization=NHIH-OEPM-NGKM-EOLE-OHGI-GAHE-PMEI-JHIF
localhost-dir: msgchan.c:202-1 sd_auth_key=NHIH-OEPM-NGKM-EOLE-OHGI-GAHE-PMEI-JHIF
localhost-sd: reserve.c:198-1 <dird: use storage=File media_type=File pool_name=Default pool_type=Backup append=1 copy=0 stripe=0
localhost-dir: msgchan.c:275-1 wstore >stored: use storage=File media_type=File pool_name=Default pool_type=Backup append=1 copy=0 stripe=0
localhost-dir: msgchan.c:282-1 >stored: use device=FileStorage
localhost-sd: reserve.c:227-1 <dird device: use device=FileStorage
localhost-sd: reserve.c:243-1 Storage=File media_type=File pool=Default pool_type=Backup append=1
localhost-sd: reserve.c:245-1      Device=FileStorage
localhost-sd: reserve.c:419-1 Start find_suit_dev PrefMnt=1 exact=1 suitable=0 chgronly=0 any=0
localhost-sd: reserve.c:544-1 search res for FileStorage
localhost-sd: reserve.c:578-1 Try match res=FileStorage
localhost-sd: reserve.c:615-1 chk MediaType device=File request=File
localhost-sd: reserve.c:638-1 try reserve FileStorage
localhost-sd: reserve.c:651-1 call reserve for append: have_vol=0 vol=
localhost-sd: reserve.c:835-1 reserve_append device is "FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: reserve.c:912-1 PrefMnt=1 exact=1 suitable=1 chgronly=0 any=0
localhost-sd: reserve.c:884-1 MaxJobs=0 Jobs=0 reserves=0 Status= Vol=
localhost-sd: reserve.c:1016-1 OK Dev avail reserved "FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: reserve.c:129-1 Inc reserve=0 dev="FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: reserve.c:660-1 Reserved=1 dev_name=FileStorage mediatype=File pool=Default ok=1
localhost-sd: reserve.c:662-1 Vol= num_writers=0, have_vol=0
localhost-sd: reserve.c:673-1 no vol, call find_next_appendable_vol.
localhost-sd: askdir.c:276-1 >dird CatReq Job=First.2008-11-17_14.49.11.03 FindMedia=1 pool_name=Default media_type=File
localhost-dir: catreq.c:126-1 catreq CatReq Job=First.2008-11-17_14.49.11.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:444-1 Rtn numrows=1
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=210 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 80a8a30 dev="FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: vol_mgr.c:454-1 === set in_use. vol=TestVolume0001 dev="FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: vol_mgr.c:212-1 List end new volume: TestVolume0001 in_use=1 on device "FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: askdir.c:292-1 dir_find_next_appendable_volume return true. vol=TestVolume0001
localhost-sd: reserve.c:677-1 looking for Volume=TestVolume0001
localhost-sd: reserve.c:734-1 >dird: 3000 OK use device device=FileStorage
localhost-sd: reserve.c:588-1 Device FileStorage reserved=1 for append.
localhost-sd: reserve.c:513-1 available device found=FileStorage
localhost-sd: reserve.c:528-1 OK dev found. Vol=TestVolume0001
localhost-dir: catreq.c:100-1 Vol Info for First.2008-11-17_14.49.11.03: 1000 OK VolName=TestVolume0001 VolJobs=0 VolFiles=0 VolBlocks=0 VolBytes=210 VolMounts=0 VolErrors=0 VolWrites=0 MaxVolBytes=0 VolCapacityBytes=0 VolStatus=Append Slot=0 MaxVolJobs=1 MaxVolFiles=0 InChanger=0 VolReadTime=0 VolWriteTime=0 EndFile=0 EndBlock=0 VolParts=0 LabelType=0 MediaId=1
localhost-dir: msgchan.c:288-1 <stored: 3000 OK use device device=FileStorage
localhost-sd: job.c:190-1 First.2008-11-17_14.49.11.03 waiting 1800 sec for FD to contact SD key=NHIH-OEPM-NGKM-EOLE-OHGI-GAHE-PMEI-JHIF
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 <1855069363.1226933353@localhost-fd> ssl=0
localhost-dir: cram-md5.c:152-1 sending resp to challenge: vAtUO4/se7sfH6FhnR/13D
localhost-dir: cram-md5.c:80-1 send: auth cram-md5 <857291690.1226933353@localhost-dir> ssl=0
localhost-dir: cram-md5.c:99-1 Authenticate OK 47+FEh/4wl/Hr/9IO0+rdD
localhost-dir: authenticate.c:263-1 >filed: 1000 OK auth
localhost-dir: authenticate.c:272-1 <filed: 2000 OK Hello 1
localhost-dir: fd_cmds.c:124-1 >filed: JobId=1 Job=First.2008-11-17_14.49.11.03 SDid=1 SDtime=1226933348 Authorization=NHIH-OEPM-NGKM-EOLE-OHGI-GAHE-PMEI-JHIF
localhost-dir: fd_cmds.c:126-1 <filed: 2000 OK Job 2.5.20 (13Nov08) i686-pc-linux-gnu,unknown,unknownlocalhost-dir: fd_cmds.c:292-1 >filed: level = full  mtime_only=0
localhost-sd: bnet.c:669-0 who=client host=127.0.0.1 port=42783
localhost-sd: dircmd.c:171-0 Conn: Hello Start Job First.2008-11-17_14.49.11.03
localhost-sd: dircmd.c:177-0 Got a FD connection at 17-Nov-2008 14:49:13
localhost-sd: dircmd.c:178-0 Hello Start Job First.2008-11-17_14.49.11.03
localhost-sd: job.c:238-0 Found Job First.2008-11-17_14.49.11.03
localhost-sd: cram-md5.c:73-0 send: auth cram-md5 <946704463.1226933353@localhost-sd> ssl=0
localhost-sd: cram-md5.c:133-0 cram-get received: auth cram-md5 <1963072840.1226933353@localhost-fd> ssl=0
localhost-sd: cram-md5.c:152-0 sending resp to challenge: V64JI7Zrc6/AQV+rY5+sLD
localhost-sd: job.c:261-0 OK Authentication jid=1 Job First.2008-11-17_14.49.11.03
localhost-sd: job.c:205-1 Auth=1 canceled=0 errstat=0
localhost-sd: job.c:211-1 Running job First.2008-11-17_14.49.11.03
localhost-sd: fd_cmds.c:122-1 Start run Job=First.2008-11-17_14.49.11.03
localhost-dir: fd_cmds.c:588-1 bdird: sending runscripts to fd
localhost-sd: fd_cmds.c:160-1 <filed: append open session
localhost-sd: fd_cmds.c:227-1 Append open session: append open session
localhost-sd: fd_cmds.c:237-1 >filed: 3000 OK open ticket = 1
localhost-sd: fd_cmds.c:160-1 <filed: append data 1
localhost-sd: fd_cmds.c:190-1 Append data: append data 1
localhost-sd: fd_cmds.c:192-1 <bfiled: append data 1
localhost-sd: append.c:73-1 Start append data. res=1
localhost-sd: acquire.c:346-1 acquire_append device is disk
localhost-sd: mount.c:77-1 Enter mount_next_volume(release=0) dev="FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: mount.c:88-1 mount_next_vol retry=0
localhost-sd: askdir.c:230-1 >dird CatReq Job=First.2008-11-17_14.49.11.03 GetVolInfo VolName=TestVolume0001 write=1
localhost-dir: catreq.c:126-1 catreq CatReq Job=First.2008-11-17_14.49.11.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=210 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:541-1 open dev: disk fd=8 opened, part=0/0, part_size=420
localhost-sd: dev.c:358-1 preserve=0x0 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=*NULL*
localhost-sd: label.c:130-1 Big if statement in read_volume_label
localhost-sd: label.c:202-1 Compare Vol names: VolName=TestVolume0001 hdr=TestVolume0001

Volume Label:
Id                : Bacula 1.0 immortal
VerNo             : 11
VolName           : TestVolume0001
PrevVolName       : 
VolFile           : 0
LabelType         : PRE_LABEL
LabelSize         : 174
PoolName          : Default
MediaType         : File
PoolType          : Backup
HostName          : backuppilot
Date label written: 17-Nov-2008 14:49
localhost-sd: label.c:223-1 Leave read_volume_label() VOL_OK
localhost-sd: label.c:236-1 Call reserve_volume=TestVolume0001
localhost-sd: vol_mgr.c:350-1 enter reserve_volume=TestVolume0001 drive="FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: vol_mgr.c:212-1 List begin reserve_volume: TestVolume0001 in_use=1 on device "FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: vol_mgr.c:365-1 Vol attached=TestVolume0001, newvol=TestVolume0001 volinuse=1 on "FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: vol_mgr.c:373-1 === set reserved vol=TestVolume0001 dev="FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: vol_mgr.c:454-1 === set in_use. vol=TestVolume0001 dev="FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: vol_mgr.c:212-1 List end new volume: TestVolume0001 in_use=1 on device "FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: mount.c:363-1 Want dirVol=TestVolume0001 dirStat=Append
localhost-sd: mount.c:370-1 Vol OK name=TestVolume0001
localhost-sd: label.c:267-1 write Label in write_volume_label_to_block()
localhost-sd: label.c:590-1 Created Vol label rec: FI=VOL_LABEL len=174
localhost-sd: label.c:282-1 Wrote label of 174 bytes to block. Vol=TestVolume0001
localhost-sd: label.c:438-1 wrote vol label to block. Vol=TestVolume0001
localhost-sd: label.c:510-1 dir_update_vol_info. Set Append vol=TestVolume0001
localhost-sd: askdir.c:345-1 Update cat VolFiles=0
localhost-sd: askdir.c:368-1 >dird CatReq Job=First.2008-11-17_14.49.11.03 UpdateMedia VolName=TestVolume0001 VolJobs=0 VolFiles=0 VolBlocks=0 VolBytes=210 VolMounts=1 VolErrors=0 VolWrites=1 MaxVolBytes=0 EndTime=1226933353 VolStatus=Append Slot=0 relabel=1 InChanger=0 VolReadTime=0 VolWriteTime=9 VolFirstWritten=0 VolParts=0
localhost-dir: catreq.c:100-1 Vol Info for First.2008-11-17_14.49.11.03: 1000 OK VolName=TestVolume0001 VolJobs=0 VolFiles=0 VolBlocks=0 VolBytes=210 VolMounts=0 VolErrors=0 VolWrites=0 MaxVolBytes=0 VolCapacityBytes=0 VolStatus=Append Slot=0 MaxVolJobs=1 MaxVolFiles=0 InChanger=0 VolReadTime=0 VolWriteTime=0 EndFile=0 EndBlock=0 VolParts=0 LabelType=0 MediaId=1
localhost-dir: catreq.c:126-1 catreq CatReq Job=First.2008-11-17_14.49.11.03 UpdateMedia VolName=TestVolume0001 VolJobs=0 VolFiles=0 VolBlocks=0 VolBytes=210 VolMounts=1 VolErrors=0 VolWrites=1 MaxVolBytes=0 EndTime=1226933353 VolStatus=Append Slot=0 relabel=1 InChanger=0 VolReadTime=0 VolWriteTime=9 VolFirstWritten=0 VolParts=0
localhost-dir: sql_update.c:338-1 update_media: FirstWritten=1226933353
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=9 EndFile=0 EndBlock=0 VolParts=0 LabelType=0 MediaId=1
localhost-sd: askdir.c:205-1 do_reqest_vol_info return true slot=0 Volume=TestVolume0001
localhost-sd: label.c:527-1 OK from rewrite vol label. Vol=TestVolume0001
localhost-sd: mount.c:293-1 set APPEND, normal return from mount_next_write_volume. dev="FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: askdir.c:345-1 Update cat VolFiles=0
localhost-sd: askdir.c:368-1 >dird CatReq Job=First.2008-11-17_14.49.11.03 UpdateMedia VolName=TestVolume0001 VolJobs=1 VolFiles=0 VolBlocks=0 VolBytes=210 VolMounts=1 VolErrors=0 VolWrites=1 MaxVolBytes=0 EndTime=1226933353 VolStatus=Append Slot=0 relabel=0 InChanger=0 VolReadTime=0 VolWriteTime=9 VolFirstWritten=0 VolParts=0
localhost-dir: catreq.c:100-1 Vol Info for First.2008-11-17_14.49.11.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=9 EndFile=0 EndBlock=0 VolParts=0 LabelType=0 MediaId=1
localhost-dir: catreq.c:126-1 catreq CatReq Job=First.2008-11-17_14.49.11.03 UpdateMedia VolName=TestVolume0001 VolJobs=1 VolFiles=0 VolBlocks=0 VolBytes=210 VolMounts=1 VolErrors=0 VolWrites=1 MaxVolBytes=0 EndTime=1226933353 VolStatus=Append Slot=0 relabel=0 InChanger=0 VolReadTime=0 VolWriteTime=9 VolFirstWritten=0 VolParts=0
localhost-dir: sql_update.c:338-1 update_media: FirstWritten=1226933353
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=1226933353
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=9 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=80b7c58
localhost-sd: label.c:749-1 Write sesson_label record JobId=1 FI=SOS_LABEL SessId=1 Strm=1 len=144 remainder=0
localhost-sd: label.c:753-1 Leave write_session_label Block=209d File=0d
localhost-dir: catreq.c:100-1 Vol Info for First.2008-11-17_14.49.11.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=9 EndFile=0 EndBlock=0 VolParts=0 LabelType=0 MediaId=1
localhost-dir: sql.c:737-1 initdb ref=1 connected=1 db=80bea30
Connecting to Director localhost:8101
localhost-dir: bnet.c:669-0 who=client host=127.0.0.1 port=42271
localhost-dir: job.c:1264-0 wstorage=File
localhost-dir: job.c:1273-0 wstore=File where=Job resource
localhost-dir: job.c:925-0 JobId=0 created Job=-Console-.2008-11-17_14.49.16.04
localhost-dir: cram-md5.c:73-0 send: auth cram-md5 <1918521826.1226933356@localhost-dir> ssl=0
localhost-dir: cram-md5.c:133-0 cram-get received: auth cram-md5 <1526151684.1226933356@bconsole> ssl=0
localhost-dir: cram-md5.c:152-0 sending resp to challenge: I/kHu4kw+W+9Ok4zk//HMC
1000 OK: localhost-dir Version: 2.5.20 (13 November 2008)
Enter a period to cancel a command.
setdebug level=150  storage=File
localhost-dir: ua_cmds.c:951-0 setdebug:setdebug level=150  storage=File:
localhost-dir: job.c:1298-0 wstore=File where=unknown source
localhost-dir: msgchan.c:104-0 bnet_connect to Storage daemon localhost:8103
Connecting to Storage daemon File at localhost:8103
localhost-dir: bsock.c:201-0 Current host[ipv4:127.0.0.1:8103] All host[ipv4:127.0.0.1:8103] 
localhost-sd: bnet.c:669-0 who=client host=127.0.0.1 port=42783
localhost-dir: bsock.c:155-0 who=Storage daemon host=localhost port=8103
localhost-sd: dircmd.c:171-0 Conn: Hello Director localhost-dir calling
localhost-sd: dircmd.c:187-0 Got a DIR connection at 17-Nov-2008 14:49:16
localhost-sd: cram-md5.c:73-0 send: auth cram-md5 <1265883970.1226933356@localhost-sd> ssl=0
localhost-dir: cram-md5.c:133-0 cram-get received: auth cram-md5 <1265883970.1226933356@localhost-sd> ssl=0
localhost-dir: cram-md5.c:152-0 sending resp to challenge: zx//u9dv67AXE+EHz45YFD
localhost-dir: cram-md5.c:80-0 send: auth cram-md5 <1972921263.1226933356@localhost-dir> ssl=0
localhost-sd: cram-md5.c:133-0 cram-get received: auth cram-md5 <1972921263.1226933356@localhost-dir> ssl=0
localhost-sd: cram-md5.c:152-0 sending resp to challenge: PkECl2/gs+grD9dL/DIOAD
localhost-dir: cram-md5.c:99-0 Authenticate OK PkECl2/gs+grD9dL/DIOAD
localhost-dir: authenticate.c:152-0 >stored: 1000 OK auth
localhost-sd: dircmd.c:209-0 Message channel init completed.
localhost-dir: authenticate.c:159-0 <stored: 3000 OK Hello
localhost-dir: ua_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           |
| 2       | TestVolume0002 | Append    | 1       | 210      | 0        | 31536000     | 1       | 0    | 0         | File      | 0           |
+---------+----------------+-----------+---------+----------+----------+--------------+---------+------+-----------+-----------+-------------+
llist volume=TestVolume0001
localhost-dir: ua_output.c:255-0 list: llist volume=TestVolume0001
          MediaId: 1
       VolumeName: TestVolume0001
             Slot: 0
           PoolId: 1
        MediaType: File
     FirstWritten: 2008-11-17 14:49:13
      LastWritten: 0
        LabelDate: 2008-11-17 14:49:13
          VolJobs: 1
         VolFiles: 0
        VolBlocks: 0
        VolMounts: 1
         VolBytes: 210
        VolErrors: 0
        VolWrites: 1
 VolCapacityBytes: 0
        VolStatus: Used
          Enabled: 1
          Recycle: 1
     VolRetention: 31536000
   VolUseDuration: 0
       MaxVolJobs: 1
      MaxVolFiles: 0
      MaxVolBytes: 0
        InChanger: 0
          EndFile: 0
         EndBlock: 0
         VolParts: 0
        LabelType: 0
        StorageId: 1
         DeviceId: 0
       LocationId: 0
     RecycleCount: 0
     InitialWrite: 0
    ScratchPoolId: 0
    RecyclePoolId: 0
          Comment: NULL

llist jobmedia
localhost-dir: ua_output.c:255-0 list: llist jobmedia
No results to list.
messages
17-Nov 14:49 localhost-dir JobId 1: Start Backup JobId 1, Job=First.2008-11-17_14.49.11.03
17-Nov 14:49 localhost-dir JobId 1: Using Device "FileStorage"
17-Nov 14:49 localhost-sd JobId 1: Wrote label to prelabeled Volume "TestVolume0001" on device "FileStorage" (/usr/bin/bacula/regress/tmp)
17-Nov 14:49 localhost-dir JobId 1: Max Volume jobs exceeded. Marking Volume "TestVolume0001" as Used.
@tee tmp/log2.out
run job=Second yes
localhost-dir: ua_run.c:1323-0 Using pool Default
localhost-dir: job.c:1264-0 wstorage=File
localhost-dir: job.c:1273-0 wstore=File where=Job resource
localhost-dir: job.c:1298-0 wstore=File where=Job resource
localhost-dir: ua_run.c:178-0 JobId=0 using pool Default priority=10
localhost-dir: job.c:925-0 JobId=0 created Job=Second.2008-11-17_14.49.16.05
localhost-dir: job.c:127-0 Open database
localhost-dir: job.c:142-0 DB opened
localhost-dir: job.c:798-0 Created Client localhost-fd record 1
localhost-dir: job.c:173-2 Created job record JobId=2 Name=Second.2008-11-17_14.49.16.05 Type=B Level=I
localhost-dir: job.c:835-2 Created FileSet Set2 record 2
localhost-dir: fd_cmds.c:241-2 Level=F last start time=0000-00-00 00:00:00
localhost-dir: job.c:638-2 get_or_create_pool=Default
localhost-dir: ua_run.c:182-2 JobId=2 NewJobId=2 using pool Default priority=10
Job queued. JobId=2
You have messages.
wait
localhost-dir: backup.c:197-2 JobId=2 JobLevel=F
localhost-dir: backup.c:209-2 Open connection with storage daemon
localhost-dir: msgchan.c:104-2 bnet_connect to Storage daemon localhost:8103
localhost-dir: bsock.c:201-2 Current host[ipv4:127.0.0.1:8103] All host[ipv4:127.0.0.1:8103] 
localhost-dir: bsock.c:155-2 who=Storage daemon host=localhost port=8103
localhost-sd: bnet.c:669-0 who=client host=127.0.0.1 port=42783
localhost-sd: dircmd.c:171-0 Conn: Hello Director localhost-dir calling
localhost-sd: dircmd.c:187-0 Got a DIR connection at 17-Nov-2008 14:49:19
localhost-sd: cram-md5.c:73-0 send: auth cram-md5 <1758981583.1226933359@localhost-sd> ssl=0
localhost-dir: cram-md5.c:133-2 cram-get received: auth cram-md5 <1758981583.1226933359@localhost-sd> ssl=0
localhost-dir: cram-md5.c:152-2 sending resp to challenge: V58ff0QtEW/nfwZPm44JyB
localhost-dir: cram-md5.c:80-2 send: auth cram-md5 <1804289383.1226933359@localhost-dir> ssl=0
localhost-sd: cram-md5.c:133-0 cram-get received: auth cram-md5 <1804289383.1226933359@localhost-dir> ssl=0
localhost-dir: cram-md5.c:99-2 Authenticate OK ABcwI1Fcf//d86/qx8Jn4B
localhost-dir: authenticate.c:152-2 >stored: 1000 OK auth
localhost-sd: cram-md5.c:152-0 sending resp to challenge: ABcwI1Fcf//d86/qx8Jn4B
localhost-dir: authenticate.c:159-2 <stored: 3000 OK Hello
localhost-sd: dircmd.c:209-0 Message channel init completed.
localhost-dir: msgchan.c:192-2 >stored: JobId=2 job=Second.2008-11-17_14.49.16.05 job_name=Second client_name=localhost-fd type=66 level=70 FileSet=Set2 NoAttr=0 SpoolAttr=0 FileSetMD5=B5lTmCERCG+gRWNQQg/88B SpoolData=0 WritePartAfterJob=1 PreferMountedVols=1 SpoolSize=0

localhost-sd: job.c:92-0 <dird: JobId=2 job=Second.2008-11-17_14.49.16.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=1226933348 Authorization=HGNC-FGAC-PGLA-AAJC-MGMC-KDKM-IAKD-KMEN
localhost-dir: msgchan.c:202-2 sd_auth_key=HGNC-FGAC-PGLA-AAJC-MGMC-KDKM-IAKD-KMEN
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=1226933348 Authorization=HGNC-FGAC-PGLA-AAJC-MGMC-KDKM-IAKD-KMEN
localhost-sd: reserve.c:198-2 <dird: use storage=File media_type=File pool_name=Default pool_type=Backup append=1 copy=0 stripe=0
localhost-sd: reserve.c:227-2 <dird device: use device=FileStorage
localhost-sd: reserve.c:243-2 Storage=File media_type=File pool=Default pool_type=Backup append=1
localhost-sd: reserve.c:245-2      Device=FileStorage
localhost-sd: reserve.c:419-2 Start find_suit_dev PrefMnt=1 exact=1 suitable=0 chgronly=0 any=0
localhost-sd: vol_mgr.c:748-2 lock volumes
localhost-sd: vol_mgr.c:750-2 duplicate vol list
localhost-sd: vol_mgr.c:766-2 unlock volumes
localhost-sd: reserve.c:433-2 look for vol in vol list
localhost-sd: askdir.c:230-2 >dird CatReq Job=Second.2008-11-17_14.49.16.05 GetVolInfo VolName=TestVolume0001 write=1
localhost-dir: catreq.c:126-2 catreq CatReq Job=Second.2008-11-17_14.49.16.05 GetVolInfo VolName=TestVolume0001 write=1
localhost-dir: catreq.c:163-2 CatReq GetVolInfo Vol=TestVolume0001
localhost-dir: next_vol.c:246-2 Vol=TestVolume0001 expired=0
localhost-sd: askdir.c:182-2 <dird 1998 Volume "TestVolume0001" status is Used, but should be Append, Purged or Recycle.
localhost-sd: askdir.c:195-2 Bad response from Dir fields=-1, len=86: 1998 Volume "TestVolume0001" status is Used, but should be Append, Purged or Recycle.
localhost-sd: reserve.c:492-2 lock volumes
localhost-sd: vol_mgr.c:640-2 free vol_list Volume=TestVolume0001 dev="FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: vol_mgr.c:783-2 deleted temp vol list
localhost-sd: vol_mgr.c:784-2 unlock volumes
localhost-sd: vol_mgr.c:212-2 List after free temp table: TestVolume0001 in_use=1 on device "FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: reserve.c:544-2 search res for FileStorage
localhost-sd: reserve.c:578-2 Try match res=FileStorage
localhost-sd: reserve.c:615-2 chk MediaType device=File request=File
localhost-sd: reserve.c:638-2 try reserve FileStorage
localhost-sd: reserve.c:651-2 call reserve for append: have_vol=0 vol=
localhost-sd: reserve.c:835-2 reserve_append device is "FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: reserve.c:912-2 PrefMnt=1 exact=1 suitable=1 chgronly=0 any=0
localhost-sd: reserve.c:884-2 MaxJobs=0 Jobs=0 reserves=0 Status= Vol=TestVolume0001
localhost-sd: reserve.c:860-2 OK dev: "FileStorage" (/usr/bin/bacula/regress/tmp) num_writers=0, reserved, pool matches
localhost-sd: reserve.c:129-2 Inc reserve=0 dev="FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: reserve.c:660-2 Reserved=1 dev_name=FileStorage mediatype=File pool=Default ok=1
localhost-sd: reserve.c:662-2 Vol= num_writers=1, have_vol=0
localhost-sd: reserve.c:673-2 no vol, call find_next_appendable_vol.
localhost-sd: askdir.c:276-2 >dird CatReq Job=Second.2008-11-17_14.49.16.05 FindMedia=1 pool_name=Default media_type=File
localhost-dir: catreq.c:126-2 catreq CatReq Job=Second.2008-11-17_14.49.16.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:444-2 Rtn numrows=1
localhost-dir: next_vol.c:164-2 VolJobs=0 FirstWritten=0
localhost-dir: next_vol.c:246-2 Vol=TestVolume0002 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=TestVolume0002
localhost-dir: catreq.c:100-2 Vol Info for Second.2008-11-17_14.49.16.05: 1000 OK VolName=TestVolume0002 VolJobs=0 VolFiles=0 VolBlocks=0 VolBytes=210 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=2
localhost-sd: askdir.c:182-2 <dird 1000 OK VolName=TestVolume0002 VolJobs=0 VolFiles=0 VolBlocks=0 VolBytes=210 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=2
localhost-sd: askdir.c:205-2 do_reqest_vol_info return true slot=0 Volume=TestVolume0002
localhost-sd: vol_mgr.c:512-2 find_vol=TestVolume0002 found=0
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:705-2 Vol=TestVolume0002 not in use.
localhost-sd: askdir.c:285-2 Call reserve_volume. Vol=TestVolume0002
localhost-sd: vol_mgr.c:350-2 enter reserve_volume=TestVolume0002 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=TestVolume0002 volinuse=1 on "FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: vol_mgr.c:378-2 Cannot free vol=TestVolume0001. It is reserved.
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:288-2 Could not reserve volume TestVolume0002 on "FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: askdir.c:276-2 >dird CatReq Job=Second.2008-11-17_14.49.16.05 FindMedia=2 pool_name=Default media_type=File
localhost-dir: catreq.c:126-2 catreq CatReq Job=Second.2008-11-17_14.49.16.05 FindMedia=2 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 2
localhost-dir: sql_find.c:375-2 item=2 got=1
localhost-dir: next_vol.c:81-2 after find_next_vol ok=0 index=2 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=2
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<1195397359
localhost-dir: autoprune.c:179-2 Num pruned = 0
localhost-dir: sql_update.c:338-2 update_media: FirstWritten=1226933353
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=2 vol=TestVolume0001
localhost-dir: catreq.c:100-2 Vol Info for Second.2008-11-17_14.49.16.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=9 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=9 EndFile=0 EndBlock=0 VolParts=0 LabelType=0 MediaId=1
localhost-sd: askdir.c:205-2 do_reqest_vol_info return true slot=0 Volume=TestVolume0001
localhost-sd: vol_mgr.c:512-2 find_vol=TestVolume0001 found=1
localhost-sd: vol_mgr.c:212-2 List find_volume: TestVolume0001 in_use=1 on device "FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: vol_mgr.c:711-2 Vol=TestVolume0001 on same dev.
localhost-sd: askdir.c:285-2 Call reserve_volume. Vol=TestVolume0001
localhost-sd: vol_mgr.c:350-2 enter reserve_volume=TestVolume0001 drive="FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: vol_mgr.c:212-2 List begin reserve_volume: TestVolume0001 in_use=1 on device "FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: vol_mgr.c:365-2 Vol attached=TestVolume0001, newvol=TestVolume0001 volinuse=1 on "FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: vol_mgr.c:373-2 === set reserved vol=TestVolume0001 dev="FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: vol_mgr.c:454-2 === set in_use. vol=TestVolume0001 dev="FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: vol_mgr.c:212-2 List end new volume: TestVolume0001 in_use=1 on device "FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: askdir.c:292-2 dir_find_next_appendable_volume return true. vol=TestVolume0001
localhost-sd: reserve.c:677-2 looking for Volume=TestVolume0001
localhost-sd: reserve.c:734-2 >dird: 3000 OK use device device=FileStorage
localhost-sd: reserve.c:588-2 Device FileStorage reserved=1 for append.
localhost-sd: reserve.c:513-2 available device found=FileStorage
localhost-sd: reserve.c:528-2 OK dev found. Vol=TestVolume0001
localhost-dir: msgchan.c:288-2 <stored: 3000 OK use device device=FileStorage
localhost-dir: msgchan.c:325-2 Start SD msg_thread.
localhost-sd: job.c:190-2 Second.2008-11-17_14.49.16.05 waiting 1800 sec for FD to contact SD key=HGNC-FGAC-PGLA-AAJC-MGMC-KDKM-IAKD-KMEN
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 <1927396279.1226933359@localhost-fd> ssl=0
localhost-dir: cram-md5.c:152-2 sending resp to challenge: //I6Ol/INnEtwl+FomZ6yB
localhost-dir: cram-md5.c:80-2 send: auth cram-md5 <1764960484.1226933359@localhost-dir> ssl=0
localhost-dir: cram-md5.c:99-2 Authenticate OK o//lKGAaFh9va6YTGg+hwC
localhost-dir: authenticate.c:263-2 >filed: 1000 OK auth
localhost-dir: authenticate.c:272-2 <filed: 2000 OK Hello 1
localhost-dir: fd_cmds.c:124-2 >filed: JobId=2 Job=Second.2008-11-17_14.49.16.05 SDid=2 SDtime=1226933348 Authorization=HGNC-FGAC-PGLA-AAJC-MGMC-KDKM-IAKD-KMEN
localhost-dir: fd_cmds.c:126-2 <filed: 2000 OK Job 2.5.20 (13Nov08) i686-pc-linux-gnu,unknown,unknownlocalhost-dir: fd_cmds.c:292-2 >filed: level = full  mtime_only=0
localhost-sd: bnet.c:669-0 who=client host=127.0.0.1 port=42783
localhost-sd: dircmd.c:171-0 Conn: Hello Start Job Second.2008-11-17_14.49.16.05
localhost-sd: dircmd.c:177-0 Got a FD connection at 17-Nov-2008 14:49:19
localhost-sd: dircmd.c:178-0 Hello Start Job Second.2008-11-17_14.49.16.05
localhost-sd: job.c:238-0 Found Job Second.2008-11-17_14.49.16.05
localhost-sd: cram-md5.c:73-0 send: auth cram-md5 <794594116.1226933359@localhost-sd> ssl=0
localhost-sd: cram-md5.c:133-0 cram-get received: auth cram-md5 <1876410139.1226933359@localhost-fd> ssl=0
localhost-sd: cram-md5.c:152-0 sending resp to challenge: 26/qt+tvqm//GDkKK/NODA
localhost-dir: fd_cmds.c:588-2 bdird: sending runscripts to fd
localhost-sd: job.c:261-0 OK Authentication jid=2 Job Second.2008-11-17_14.49.16.05
localhost-sd: job.c:205-2 Auth=1 canceled=0 errstat=0
localhost-sd: job.c:211-2 Running job Second.2008-11-17_14.49.16.05
localhost-sd: fd_cmds.c:122-2 Start run Job=Second.2008-11-17_14.49.16.05
localhost-sd: fd_cmds.c:160-2 <filed: append open session
localhost-sd: fd_cmds.c:227-2 Append open session: append open session
localhost-sd: fd_cmds.c:237-2 >filed: 3000 OK open ticket = 2
localhost-sd: fd_cmds.c:160-2 <filed: append data 2
localhost-sd: fd_cmds.c:190-2 Append data: append data 2
localhost-sd: fd_cmds.c:192-2 <bfiled: append data 2
localhost-sd: append.c:73-2 Start append data. res=1
localhost-sd: acquire.c:346-2 acquire_append device is disk
localhost-sd: askdir.c:230-2 >dird CatReq Job=Second.2008-11-17_14.49.16.05 GetVolInfo VolName=TestVolume0001 write=1
localhost-dir: catreq.c:126-2 catreq CatReq Job=Second.2008-11-17_14.49.16.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-17_14.49.16.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=9 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=9 EndFile=0 EndBlock=0 VolParts=0 LabelType=0 MediaId=1
localhost-sd: askdir.c:205-2 do_reqest_vol_info return true slot=0 Volume=TestVolume0001
localhost-sd: mount.c:77-2 Enter mount_next_volume(release=0) dev="FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: mount.c:88-2 mount_next_vol retry=0
localhost-sd: askdir.c:230-2 >dird CatReq Job=Second.2008-11-17_14.49.16.05 GetVolInfo VolName=TestVolume0001 write=1
localhost-dir: catreq.c:126-2 catreq CatReq Job=Second.2008-11-17_14.49.16.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-17_14.49.16.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=9 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=9 EndFile=0 EndBlock=0 VolParts=0 LabelType=0 MediaId=1
localhost-sd: askdir.c:205-2 do_reqest_vol_info return true slot=0 Volume=TestVolume0001
localhost-sd: mount.c:128-2 After find_next_append. Vol=TestVolume0001 Slot=0 Parts=0
localhost-sd: autochanger.c:121-2 Device "FileStorage" (/usr/bin/bacula/regress/tmp) is not an autochanger
localhost-sd: mount.c:149-2 autoload_dev returns 0
localhost-sd: mount.c:179-2 want vol=TestVolume0001 devvol=TestVolume0001 dev="FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: label.c:81-2 Enter read_volume_label res=1 device="FileStorage" (/usr/bin/bacula/regress/tmp) vol=TestVolume0001 dev_Vol=TestVolume0001
localhost-sd: label.c:130-2 Big if statement in read_volume_label
localhost-sd: label.c:202-2 Compare Vol names: VolName=TestVolume0001 hdr=TestVolume0001

Volume Label:
Id                : Bacula 1.0 immortal
VerNo             : 11
VolName           : TestVolume0001
PrevVolName       : 
VolFile           : 0
LabelType         : VOL_LABEL
LabelSize         : 174
PoolName          : Default
MediaType         : File
PoolType          : Backup
HostName          : backuppilot
Date label written: 17-Nov-2008 14:49
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-sd: askdir.c:368-2 >dird CatReq Job=Second.2008-11-17_14.49.16.05 UpdateMedia VolName=TestVolume0001 VolJobs=0 VolFiles=0 VolBlocks=0 VolBytes=210 VolMounts=2 VolErrors=0 VolWrites=2 MaxVolBytes=0 EndTime=1226933359 VolStatus=Append Slot=0 relabel=1 InChanger=0 VolReadTime=0 VolWriteTime=150 VolFirstWritten=0 VolParts=0
localhost-dir: catreq.c:126-2 catreq CatReq Job=Second.2008-11-17_14.49.16.05 UpdateMedia VolName=TestVolume0001 VolJobs=0 VolFiles=0 VolBlocks=0 VolBytes=210 VolMounts=2 VolErrors=0 VolWrites=2 MaxVolBytes=0 EndTime=1226933359 VolStatus=Append Slot=0 relabel=1 InChanger=0 VolReadTime=0 VolWriteTime=150 VolFirstWritten=0 VolParts=0
localhost-dir: sql_update.c:338-2 update_media: FirstWritten=1226933359
localhost-dir: next_vol.c:246-2 Vol=TestVolume0001 expired=0
localhost-dir: catreq.c:100-2 Vol Info for Second.2008-11-17_14.49.16.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=150 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=210 VolMounts=2 VolErrors=0 VolWrites=2 MaxVolBytes=0 VolCapacityBytes=0 VolStatus=Append Slot=0 MaxVolJobs=1 MaxVolFiles=0 InChanger=0 VolReadTime=0 VolWriteTime=150 EndFile=0 EndBlock=0 VolParts=0 LabelType=0 MediaId=1
localhost-sd: askdir.c:205-2 do_reqest_vol_info return true slot=0 Volume=TestVolume0001
localhost-sd: label.c:527-2 OK from rewrite vol label. Vol=TestVolume0001
localhost-sd: mount.c:293-2 set APPEND, normal return from mount_next_write_volume. dev="FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: askdir.c:345-2 Update cat VolFiles=0
localhost-sd: askdir.c:368-2 >dird CatReq Job=Second.2008-11-17_14.49.16.05 UpdateMedia VolName=TestVolume0001 VolJobs=1 VolFiles=0 VolBlocks=0 VolBytes=210 VolMounts=2 VolErrors=0 VolWrites=2 MaxVolBytes=0 EndTime=1226933359 VolStatus=Append Slot=0 relabel=0 InChanger=0 VolReadTime=0 VolWriteTime=150 VolFirstWritten=0 VolParts=0
localhost-dir: catreq.c:126-2 catreq CatReq Job=Second.2008-11-17_14.49.16.05 UpdateMedia VolName=TestVolume0001 VolJobs=1 VolFiles=0 VolBlocks=0 VolBytes=210 VolMounts=2 VolErrors=0 VolWrites=2 MaxVolBytes=0 EndTime=1226933359 VolStatus=Append Slot=0 relabel=0 InChanger=0 VolReadTime=0 VolWriteTime=150 VolFirstWritten=0 VolParts=0
localhost-dir: sql_update.c:338-2 update_media: FirstWritten=1226933359
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=1226933359
localhost-dir: next_vol.c:246-2 Vol=TestVolume0001 expired=1
localhost-dir: catreq.c:100-2 Vol Info for Second.2008-11-17_14.49.16.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=150 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=150 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=80aa758
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=8133998
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=80aa758
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=747178178d File=0d
localhost-sd: append.c:301-1 back from write_end_session_label()
localhost-sd: fd_cmds.c:160-2 <filed: append end session 2
localhost-sd: fd_cmds.c:210-2 store<file: append end session 2
localhost-sd: fd_cmds.c:160-2 <filed: append close session 2
localhost-sd: fd_cmds.c:251-2 <filed: append close session 2
localhost-sd: fd_cmds.c:258-2 >filed: 3000 OK close Status = 84
localhost-sd: 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: backup.c:373-2 FDStatus=T
localhost-sd: label.c:704-2 session_label record=80aa758
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=747221741d File=0d
localhost-sd: append.c:301-2 back from write_end_session_label()
localhost-dir: catreq.c:126-1 catreq CatReq Job=First.2008-11-17_14.49.11.03 CreateJobMedia FirstIndex=1 LastIndex=4447 StartFile=0 EndFile=0 StartBlock=210 EndBlock=747221741 Copy=0 Strip=0 MediaId=1
localhost-sd: askdir.c:412-1 >dird CatReq Job=First.2008-11-17_14.49.11.03 CreateJobMedia FirstIndex=1 LastIndex=4447 StartFile=0 EndFile=0 StartBlock=210 EndBlock=747221741 Copy=0 Strip=0 MediaId=1
localhost-sd: askdir.c:419-1 <dird 1000 OK CreateJobMedia
localhost-sd: askdir.c:345-1 Update cat VolFiles=0
localhost-dir: catreq.c:126-1 catreq CatReq Job=First.2008-11-17_14.49.11.03 UpdateMedia VolName=TestVolume0001 VolJobs=1 VolFiles=0 VolBlocks=11583 VolBytes=747221742 VolMounts=2 VolErrors=0 VolWrites=11585 MaxVolBytes=0 EndTime=1226933442 VolStatus=Used Slot=0 relabel=0 InChanger=0 VolReadTime=0 VolWriteTime=19518664 VolFirstWritten=0 VolParts=0
localhost-dir: sql_update.c:338-1 update_media: FirstWritten=1226933359
localhost-dir: next_vol.c:246-1 Vol=TestVolume0001 expired=0
localhost-dir: catreq.c:100-1 Vol Info for First.2008-11-17_14.49.11.03: 1000 OK VolName=TestVolume0001 VolJobs=1 VolFiles=0 VolBlocks=11583 VolBytes=747221742 VolMounts=2 VolErrors=0 VolWrites=11585 MaxVolBytes=0 VolCapacityBytes=0 VolStatus=Used Slot=0 MaxVolJobs=1 MaxVolFiles=0 InChanger=0 VolReadTime=0 VolWriteTime=19518664 EndFile=0 EndBlock=747221741 VolParts=0 LabelType=0 MediaId=1
localhost-sd: askdir.c:368-1 >dird CatReq Job=First.2008-11-17_14.49.11.03 UpdateMedia VolName=TestVolume0001 VolJobs=1 VolFiles=0 VolBlocks=11583 VolBytes=747221742 VolMounts=2 VolErrors=0 VolWrites=11585 MaxVolBytes=0 EndTime=1226933442 VolStatus=Used Slot=0 relabel=0 InChanger=0 VolReadTime=0 VolWriteTime=19518664 VolFirstWritten=0 VolParts=0
localhost-sd: askdir.c:182-1 <dird 1000 OK VolName=TestVolume0001 VolJobs=1 VolFiles=0 VolBlocks=11583 VolBytes=747221742 VolMounts=2 VolErrors=0 VolWrites=11585 MaxVolBytes=0 VolCapacityBytes=0 VolStatus=Used Slot=0 MaxVolJobs=1 MaxVolFiles=0 InChanger=0 VolReadTime=0 VolWriteTime=19518664 EndFile=0 EndBlock=747221741 VolParts=0 LabelType=0 MediaId=1
localhost-sd: askdir.c:205-1 do_reqest_vol_info return true slot=0 Volume=TestVolume0001
localhost-sd: acquire.c:485-1 1 writers, 0 reserve, dev="FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: vol_mgr.c:212-1 List acquire:release_device(): TestVolume0001 in_use=1 on device "FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: acquire.c:523-1 JobId=1 broadcast wait_device_release at 17-Nov-2008 14:50:42
localhost-sd: acquire.c:538-1 ===== Device "FileStorage" (/usr/bin/bacula/regress/tmp) released by JobId=1
localhost-sd: acquire.c:427-2 release_device device "FileStorage" (/usr/bin/bacula/regress/tmp) is disk
localhost-sd: acquire.c:450-2 There are 0 writers in release_device
localhost-dir: catreq.c:126-2 catreq CatReq Job=Second.2008-11-17_14.49.16.05 CreateJobMedia FirstIndex=1 LastIndex=4447 StartFile=0 EndFile=0 StartBlock=210 EndBlock=747265306 Copy=0 Strip=0 MediaId=1
localhost-sd: askdir.c:412-2 >dird CatReq Job=Second.2008-11-17_14.49.16.05 CreateJobMedia FirstIndex=1 LastIndex=4447 StartFile=0 EndFile=0 StartBlock=210 EndBlock=747265306 Copy=0 Strip=0 MediaId=1
localhost-sd: askdir.c:419-2 <dird 1000 OK CreateJobMedia
localhost-sd: dev.c:1690-2 === weof_dev="FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: askdir.c:345-2 Update cat VolFiles=0
localhost-dir: catreq.c:126-2 catreq CatReq Job=Second.2008-11-17_14.49.16.05 UpdateMedia VolName=TestVolume0001 VolJobs=1 VolFiles=0 VolBlocks=11584 VolBytes=747265307 VolMounts=2 VolErrors=0 VolWrites=11586 MaxVolBytes=0 EndTime=1226933442 VolStatus=Used Slot=0 relabel=0 InChanger=0 VolReadTime=0 VolWriteTime=19518960 VolFirstWritten=0 VolParts=0
localhost-dir: sql_update.c:338-2 update_media: FirstWritten=1226933359
localhost-dir: next_vol.c:246-2 Vol=TestVolume0001 expired=0
localhost-dir: catreq.c:100-2 Vol Info for Second.2008-11-17_14.49.16.05: 1000 OK VolName=TestVolume0001 VolJobs=1 VolFiles=0 VolBlocks=11584 VolBytes=747265307 VolMounts=2 VolErrors=0 VolWrites=11586 MaxVolBytes=0 VolCapacityBytes=0 VolStatus=Used Slot=0 MaxVolJobs=1 MaxVolFiles=0 InChanger=0 VolReadTime=0 VolWriteTime=19518960 EndFile=0 EndBlock=747265306 VolParts=0 LabelType=0 MediaId=1
localhost-sd: askdir.c:368-2 >dird CatReq Job=Second.2008-11-17_14.49.16.05 UpdateMedia VolName=TestVolume0001 VolJobs=1 VolFiles=0 VolBlocks=11584 VolBytes=747265307 VolMounts=2 VolErrors=0 VolWrites=11586 MaxVolBytes=0 EndTime=1226933442 VolStatus=Used Slot=0 relabel=0 InChanger=0 VolReadTime=0 VolWriteTime=19518960 VolFirstWritten=0 VolParts=0
localhost-sd: askdir.c:182-2 <dird 1000 OK VolName=TestVolume0001 VolJobs=1 VolFiles=0 VolBlocks=11584 VolBytes=747265307 VolMounts=2 VolErrors=0 VolWrites=11586 MaxVolBytes=0 VolCapacityBytes=0 VolStatus=Used Slot=0 MaxVolJobs=1 MaxVolFiles=0 InChanger=0 VolReadTime=0 VolWriteTime=19518960 EndFile=0 EndBlock=747265306 VolParts=0 LabelType=0 MediaId=1
localhost-sd: askdir.c:205-2 do_reqest_vol_info return true slot=0 Volume=TestVolume0001
localhost-sd: vol_mgr.c:577-2 === set not reserved vol=TestVolume0001 num_writers=0 dev_reserved=0 dev="FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: vol_mgr.c:578-2 === clear in_use vol=TestVolume0001
localhost-sd: vol_mgr.c:606-2 === clear in_use vol=TestVolume0001
localhost-sd: vol_mgr.c:609-2 === remove volume TestVolume0001 dev="FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: acquire.c:485-2 0 writers, 0 reserve, dev="FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: dev.c:1902-2 close_dev "FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: dev.c:1892-2 Clear volhdr vol=TestVolume0001
localhost-sd: acquire.c:523-2 JobId=2 broadcast wait_device_release at 17-Nov-2008 14:50:42
localhost-sd: acquire.c:538-2 ===== Device "FileStorage" (/usr/bin/bacula/regress/tmp) released by JobId=2
localhost-sd: spool.c:632-1 Commit attributes at 17-Nov-2008 14:50:42
localhost-sd: append.c:341-1 return from do_append_data() ok=1
localhost-sd: jcr.c:184-1 write_last_jobs seek to 188
localhost-dir: sql_create.c:768-1 db_create_file_record changes=4447
localhost-dir: sql_create.c:740-1 sql_batch_end started
localhost-dir: msgchan.c:348-1 === End msg_thread. JobId=1 usecnt=2
localhost-sd: spool.c:632-2 Commit attributes at 17-Nov-2008 14:50:43
localhost-sd: append.c:341-2 return from do_append_data() ok=1
localhost-sd: jcr.c:184-2 write_last_jobs seek to 188
localhost-dir: sql_create.c:768-2 db_create_file_record changes=4447
localhost-dir: sql_create.c:740-2 sql_batch_end started
localhost-dir: msgchan.c:348-2 === End msg_thread. JobId=2 usecnt=2
localhost-dir: backup.c:450-1 Enter backup_cleanup 84 T
localhost-dir: sql_get.c:436-1 VolNam=SELECT VolumeName,MediaType,FirstIndex,LastIndex,StartFile,JobMedia.EndFile,StartBlock,JobMedia.EndBlock,Copy,Slot,StorageId FROM JobMedia,Media WHERE JobMedia.JobId=1 AND JobMedia.MediaId=Media.MediaId ORDER BY VolIndex,JobMediaId
localhost-dir: sql_get.c:379-1 VolNam=SELECT VolumeName,MAX(VolIndex) FROM JobMedia,Media WHERE JobMedia.JobId=1 AND JobMedia.MediaId=Media.MediaId GROUP BY VolumeName ORDER BY 2 ASC
localhost-dir: sql_get.c:383-1 Num rows=1
localhost-dir: backup.c:617-1 Leave backup_cleanup()
localhost-dir: ua_prune.c:396-1 Query=SELECT DISTINCT DelCandidates.JobId,DelCandidates.PurgedFiles FROM Job,DelCandidates WHERE (Job.JobId=DelCandidates.JobId AND ((DelCandidates.JobFiles=0) OR (DelCandidates.JobStatus!='T'))) OR (Job.JobTDate>1211381444 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=1226933444 period=2592000 sql=SELECT count(*) from Job WHERE JobTDate<1224341444 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>1211381444 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=1226933444 period=2592000 sql=SELECT count(*) from Job WHERE JobTDate<1224341444 AND ClientId=1 AND PurgedFiles=0
localhost-dir: job.c:359-2 ======== End Job stat=T ==========
localhost-dir: jcr.c:184-2 write_last_jobs seek to 188
messages
17-Nov 14:49 localhost-dir JobId 2: No prior Full backup Job record found.
17-Nov 14:49 localhost-dir JobId 2: No prior or suitable Full backup found in catalog. Doing FULL backup.
17-Nov 14:49 localhost-dir JobId 2: Start Backup JobId 2, Job=Second.2008-11-17_14.49.16.05
17-Nov 14:49 localhost-dir JobId 2: There are no more Jobs associated with Volume "TestVolume0001". Marking it purged.
17-Nov 14:49 localhost-dir JobId 2: All records pruned from Volume "TestVolume0001"; marking it "Purged"
17-Nov 14:49 localhost-dir JobId 2: Recycled volume "TestVolume0001"
17-Nov 14:49 localhost-dir JobId 2: Using Device "FileStorage"
17-Nov 14:49 localhost-sd JobId 2: Recycled volume "TestVolume0001" on device "FileStorage" (/usr/bin/bacula/regress/tmp), all previous data lost.
17-Nov 14:49 localhost-dir JobId 2: Max Volume jobs exceeded. Marking Volume "TestVolume0001" as Used.
17-Nov 14:50 localhost-sd JobId 1: Job write elapsed time = 00:01:29, Transfer rate = 4.375 M bytes/second
17-Nov 14:50 localhost-sd JobId 2: Job write elapsed time = 00:01:23, Transfer rate = 4.691 M bytes/second
17-Nov 14:50 localhost-dir JobId 1: Bacula localhost-dir 2.5.20 (13Nov08): 17-Nov-2008 14:50:43
  Build OS:               i686-pc-linux-gnu unknown unknown
  JobId:                  1
  Job:                    First.2008-11-17_14.49.11.03
  Backup Level:           Full (upgraded from Incremental)
  Client:                 "localhost-fd" 2.5.20 (13Nov08) i686-pc-linux-gnu,unknown,unknown
  FileSet:                "Set1" 2008-11-17 14:49:11
  Pool:                   "Default" (From Job resource)
  Catalog:                "MyCatalog" (From Client resource)
  Storage:                "File" (From Job resource)
  Scheduled time:         17-Nov-2008 14:49:11
  Start time:             17-Nov-2008 14:49:13
  End time:               17-Nov-2008 14:50:43
  Elapsed time:           1 min 30 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,865 (389.3 MB)
  Rate:                   4319.2 KB/s
  Software Compression:   None
  VSS:                    no
  Encryption:             no
  Accurate:               no
  Volume name(s):         TestVolume0001
  Volume Session Id:      1
  Volume Session Time:    1226933348
  Last Volume Bytes:      747,265,307 (747.2 MB)
  Non-fatal FD errors:    0
  SD Errors:              0
  FD termination status:  OK
  SD termination status:  OK
  Termination:            Backup OK

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

17-Nov 14:50 localhost-dir JobId 2: Bacula localhost-dir 2.5.20 (13Nov08): 17-Nov-2008 14:50:44
  Build OS:               i686-pc-linux-gnu unknown unknown
  JobId:                  2
  Job:                    Second.2008-11-17_14.49.16.05
  Backup Level:           Full (upgraded from Incremental)
  Client:                 "localhost-fd" 2.5.20 (13Nov08) i686-pc-linux-gnu,unknown,unknown
  FileSet:                "Set2" 2008-11-17 14:49:16
  Pool:                   "Default" (From Job resource)
  Catalog:                "MyCatalog" (From Client resource)
  Storage:                "File" (From Job resource)
  Scheduled time:         17-Nov-2008 14:49:16
  Start time:             17-Nov-2008 14:49:19
  End time:               17-Nov-2008 14:50:44
  Elapsed time:           1 min 25 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,865 (389.3 MB)
  Rate:                   4573.2 KB/s
  Software Compression:   None
  VSS:                    no
  Encryption:             no
  Accurate:               no
  Volume name(s):         TestVolume0001
  Volume Session Id:      2
  Volume Session Time:    1226933348
  Last Volume Bytes:      747,265,307 (747.2 MB)
  Non-fatal FD errors:    0
  SD Errors:              0
  FD termination status:  OK
  SD termination status:  OK
  Termination:            Backup OK

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

restore fileset=Set1 where=/usr/bin/bacula/regress/tmp/bacula-restores select all storage=File done
Automatically selected Client: localhost-fd
+-------+-------+----------+-----------+---------------------+----------------+
| JobId | Level | JobFiles | JobBytes  | StartTime           | VolumeName     |
+-------+-------+----------+-----------+---------------------+----------------+
| 1     | F     | 4447     | 388725140 | 2008-11-17 14:49:13 | 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-1109421891 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=1226933348
VolFile=0
VolBlock=210-747221741
FileIndex=1-4447
Count=4447
localhost-dir: ua_run.c:1323-1109421891 Using pool Default
localhost-dir: job.c:1264-0 wstorage=File
localhost-dir: job.c:1273-0 wstore=File where=Job resource
localhost-dir: job.c:1298-0 wstore=File where=command line
Run Restore job
JobName:         RestoreFiles
Bootstrap:       /usr/bin/bacula/regress/working/localhost-dir.restore.1.bsr
Where:           /usr/bin/bacula/regress/tmp/bacula-restores
Replace:         always
FileSet:         Set1
Backup Client:   localhost-fd
Restore Client:  localhost-fd
Storage:         File
When:            2008-11-17 14:50:46
Catalog:         MyCatalog
Priority:        10
Plugin Options:  *None*
OK to run? (yes/mod/no): yes
localhost-dir: ua_run.c:178-0 JobId=0 using pool Default priority=10
localhost-dir: job.c:925-0 JobId=0 created Job=RestoreFiles.2008-11-17_14.50.46.06
localhost-dir: job.c:127-0 Open database
localhost-dir: job.c:142-0 DB opened
localhost-dir: job.c:798-0 Created Client localhost-fd record 1
localhost-dir: job.c:173-3 Created job record JobId=3 Name=RestoreFiles.2008-11-17_14.50.46.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-dir: bsock.c:155-3 who=Storage daemon host=localhost port=8103
localhost-sd: bnet.c:669-0 who=client host=127.0.0.1 port=42783
localhost-sd: dircmd.c:171-0 Conn: Hello Director localhost-dir calling
localhost-sd: dircmd.c:187-0 Got a DIR connection at 17-Nov-2008 14:50:48
localhost-sd: cram-md5.c:73-0 send: auth cram-md5 <451463441.1226933448@localhost-sd> ssl=0
localhost-dir: cram-md5.c:133-3 cram-get received: auth cram-md5 <451463441.1226933448@localhost-sd> ssl=0
localhost-dir: cram-md5.c:152-3 sending resp to challenge: kUllqCZaIj+83k/lun+sJA
localhost-dir: cram-md5.c:80-3 send: auth cram-md5 <1205566942.1226933448@localhost-dir> ssl=0
localhost-sd: cram-md5.c:133-0 cram-get received: auth cram-md5 <1205566942.1226933448@localhost-dir> ssl=0
localhost-dir: cram-md5.c:99-3 Authenticate OK f0heO9YTHH+2O2MUf+4iLD
localhost-dir: authenticate.c:152-3 >stored: 1000 OK auth
localhost-sd: cram-md5.c:152-0 sending resp to challenge: f0heO9YTHH+2O2MUf+4iLD
localhost-dir: authenticate.c:159-3 <stored: 3000 OK Hello
localhost-sd: dircmd.c:209-0 Message channel init completed.
localhost-dir: msgchan.c:192-3 >stored: JobId=3 job=RestoreFiles.2008-11-17_14.50.46.06 job_name=RestoreFiles client_name=localhost-fd type=82 level=70 FileSet=Set1 NoAttr=0 SpoolAttr=0 FileSetMD5=B5lTmCERCG+gRWNQQg/88B SpoolData=0 WritePartAfterJob=1 PreferMountedVols=1 SpoolSize=0

localhost-sd: job.c:92-0 <dird: JobId=3 job=RestoreFiles.2008-11-17_14.50.46.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-dir: msgchan.c:194-3 <stored: 3000 OK Job SDid=3 SDtime=1226933348 Authorization=MACG-NAHJ-MBCG-GOJK-IOEA-BPMO-MGPN-OBCN
localhost-dir: msgchan.c:202-3 sd_auth_key=MACG-NAHJ-MBCG-GOJK-IOEA-BPMO-MGPN-OBCN
localhost-sd: job.c:157-3 >dird jid=3: 3000 OK Job SDid=3 SDtime=1226933348 Authorization=MACG-NAHJ-MBCG-GOJK-IOEA-BPMO-MGPN-OBCN
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-dir: msgchan.c:253-3 <stored: 3000 OK use device device=FileStorage
localhost-dir: msgchan.c:325-3 Start SD msg_thread.
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-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-17_14.50.46.06 waiting 1800 sec for FD to contact SD key=MACG-NAHJ-MBCG-GOJK-IOEA-BPMO-MGPN-OBCN
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 <353761214.1226933448@localhost-fd> ssl=0
localhost-dir: cram-md5.c:152-3 sending resp to challenge: L6+br2I3JC+lV/EKf4/ktD
localhost-dir: cram-md5.c:80-3 send: auth cram-md5 <2141265922.1226933448@localhost-dir> ssl=0
localhost-dir: cram-md5.c:99-3 Authenticate OK VCFoFB+H5Q9Hw7UVN4E6RB
localhost-dir: authenticate.c:263-3 >filed: 1000 OK auth
localhost-dir: authenticate.c:272-3 <filed: 2000 OK Hello 1
localhost-dir: fd_cmds.c:124-3 >filed: JobId=3 Job=RestoreFiles.2008-11-17_14.50.46.06 SDid=3 SDtime=1226933348 Authorization=MACG-NAHJ-MBCG-GOJK-IOEA-BPMO-MGPN-OBCN
localhost-dir: fd_cmds.c:126-3 <filed: 2000 OK Job 2.5.20 (13Nov08) i686-pc-linux-gnu,unknown,unknownlocalhost-dir: restore.c:155-3 dird>filed: storage address=localhost port=8103 ssl=0

localhost-sd: bnet.c:669-0 who=client host=127.0.0.1 port=42783
localhost-sd: dircmd.c:171-0 Conn: Hello Start Job RestoreFiles.2008-11-17_14.50.46.06
localhost-sd: dircmd.c:177-0 Got a FD connection at 17-Nov-2008 14:50:48
localhost-sd: dircmd.c:178-0 Hello Start Job RestoreFiles.2008-11-17_14.50.46.06
localhost-sd: job.c:238-0 Found Job RestoreFiles.2008-11-17_14.50.46.06
localhost-sd: cram-md5.c:73-0 send: auth cram-md5 <91612031.1226933448@localhost-sd> ssl=0
localhost-sd: cram-md5.c:133-0 cram-get received: auth cram-md5 <1993067608.1226933448@localhost-fd> ssl=0
localhost-sd: cram-md5.c:152-0 sending resp to challenge: TiJZcGsbRi++gU9h7hl37C
localhost-dir: fd_cmds.c:588-3 bdird: sending runscripts to fd
localhost-sd: job.c:261-0 OK Authentication jid=3 Job RestoreFiles.2008-11-17_14.50.46.06
localhost-sd: job.c:205-3 Auth=1 canceled=0 errstat=0
localhost-sd: job.c:211-3 Running job RestoreFiles.2008-11-17_14.50.46.06
localhost-sd: fd_cmds.c:122-3 Start run Job=RestoreFiles.2008-11-17_14.50.46.06
localhost-sd: fd_cmds.c:160-3 <filed: read open session = DummyVolume 3 1226933348 0 0 0 0
localhost-sd: fd_cmds.c:296-3 read open session = DummyVolume 3 1226933348 0 0 0 0

localhost-sd: fd_cmds.c:311-3 read_open_session got: JobId=3 Vol=DummyVolume VolSessId=3 VolSessT=1226933348
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=1226933348
localhost-sd: fd_cmds.c:361-3 VolFile=0
localhost-sd: fd_cmds.c:361-3 VolBlock=210-747221741
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    : 0x80b7da8
VolumeName  : TestVolume0001
  MediaType : File
  Device    : FileStorage
  Slot      : 0
SessId      : 1
SessTime    : 1226933348
VolFile     : 0-0
VolBlock    : 210-747221741
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-dir: catreq.c:126-3 catreq CatReq Job=RestoreFiles.2008-11-17_14.50.46.06 GetVolInfo VolName=TestVolume0001 write=0
localhost-dir: catreq.c:163-3 CatReq GetVolInfo Vol=TestVolume0001
localhost-dir: catreq.c:100-3 Vol Info for RestoreFiles.2008-11-17_14.50.46.06: 1000 OK VolName=TestVolume0001 VolJobs=1 VolFiles=0 VolBlocks=11584 VolBytes=747265307 VolMounts=2 VolErrors=0 VolWrites=11586 MaxVolBytes=0 VolCapacityBytes=0 VolStatus=Used Slot=0 MaxVolJobs=1 MaxVolFiles=0 InChanger=0 VolReadTime=0 VolWriteTime=19518960 EndFile=0 EndBlock=747265306 VolParts=0 LabelType=0 MediaId=1
localhost-sd: askdir.c:230-3 >dird CatReq Job=RestoreFiles.2008-11-17_14.50.46.06 GetVolInfo VolName=TestVolume0001 write=0
localhost-sd: askdir.c:182-3 <dird 1000 OK VolName=TestVolume0001 VolJobs=1 VolFiles=0 VolBlocks=11584 VolBytes=747265307 VolMounts=2 VolErrors=0 VolWrites=11586 MaxVolBytes=0 VolCapacityBytes=0 VolStatus=Used Slot=0 MaxVolJobs=1 MaxVolFiles=0 InChanger=0 VolReadTime=0 VolWriteTime=19518960 EndFile=0 EndBlock=747265306 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=779650950
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         : 174
PoolName          : Default
MediaType         : File
PoolType          : Backup
HostName          : backuppilot
Date label written: 17-Nov-2008 14:49
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 80b7e20 dev="FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: vol_mgr.c:454-3 === set in_use. vol=TestVolume0001 dev="FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: vol_mgr.c:212-3 List end new volume: TestVolume0001 in_use=1 on device "FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: acquire.c:232-3 Got correct volume.
localhost-sd: reserve.c:138-3 Dec reserve=0 dev="FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: dev.c:1622-3 ===== lseek to 210
localhost-sd: vol_mgr.c:577-3 === set not reserved vol=TestVolume0001 num_writers=0 dev_reserved=0 dev="FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: vol_mgr.c:578-3 === clear in_use vol=TestVolume0001
localhost-sd: vol_mgr.c:606-3 === clear in_use vol=TestVolume0001
localhost-sd: vol_mgr.c:609-3 === remove volume TestVolume0001 dev="FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: mount.c:796-3 NumReadVolumes=1 CurReadVolume=1
localhost-sd: vol_mgr.c:558-3 vol_unused: no vol on "FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: mount.c:811-3 End of Device reached.
localhost-sd: acquire.c:427-3 release_device device "FileStorage" (/usr/bin/bacula/regress/tmp) is disk
localhost-sd: acquire.c:436-3 dir_update_vol_info. label=64 Vol=TestVolume0001
localhost-sd: askdir.c:345-3 Update cat VolFiles=0
localhost-sd: askdir.c:368-3 >dird CatReq Job=RestoreFiles.2008-11-17_14.50.46.06 UpdateMedia VolName=TestVolume0001 VolJobs=1 VolFiles=0 VolBlocks=11584 VolBytes=747265307 VolMounts=2 VolErrors=0 VolWrites=11586 MaxVolBytes=0 EndTime=1226933508 VolStatus=Used Slot=0 relabel=0 InChanger=0 VolReadTime=33862121 VolWriteTime=19518960 VolFirstWritten=0 VolParts=0
localhost-dir: catreq.c:126-3 catreq CatReq Job=RestoreFiles.2008-11-17_14.50.46.06 UpdateMedia VolName=TestVolume0001 VolJobs=1 VolFiles=0 VolBlocks=11584 VolBytes=747265307 VolMounts=2 VolErrors=0 VolWrites=11586 MaxVolBytes=0 EndTime=1226933508 VolStatus=Used Slot=0 relabel=0 InChanger=0 VolReadTime=33862121 VolWriteTime=19518960 VolFirstWritten=0 VolParts=0
localhost-dir: sql_update.c:338-3 update_media: FirstWritten=1226933359
localhost-dir: next_vol.c:246-3 Vol=TestVolume0001 expired=0
localhost-dir: catreq.c:100-3 Vol Info for RestoreFiles.2008-11-17_14.50.46.06: 1000 OK VolName=TestVolume0001 VolJobs=1 VolFiles=0 VolBlocks=11584 VolBytes=747265307 VolMounts=2 VolErrors=0 VolWrites=11586 MaxVolBytes=0 VolCapacityBytes=0 VolStatus=Used Slot=0 MaxVolJobs=1 MaxVolFiles=0 InChanger=0 VolReadTime=33862121 VolWriteTime=19518960 EndFile=0 EndBlock=747265306 VolParts=0 LabelType=0 MediaId=1
localhost-sd: askdir.c:182-3 <dird 1000 OK VolName=TestVolume0001 VolJobs=1 VolFiles=0 VolBlocks=11584 VolBytes=747265307 VolMounts=2 VolErrors=0 VolWrites=11586 MaxVolBytes=0 VolCapacityBytes=0 VolStatus=Used Slot=0 MaxVolJobs=1 MaxVolFiles=0 InChanger=0 VolReadTime=33862121 VolWriteTime=19518960 EndFile=0 EndBlock=747265306 VolParts=0 LabelType=0 MediaId=1
localhost-sd: askdir.c:205-3 do_reqest_vol_info return true slot=0 Volume=TestVolume0001
localhost-sd: vol_mgr.c:180-3 remove_read_vol=TestVolume0001 JobId=3 found=1
localhost-sd: vol_mgr.c:558-3 vol_unused: no vol on "FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: acquire.c:485-3 0 writers, 0 reserve, dev="FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: dev.c:1902-3 close_dev "FileStorage" (/usr/bin/bacula/regress/tmp)
localhost-sd: dev.c:1892-3 Clear volhdr vol=TestVolume0001
localhost-sd: acquire.c:523-3 JobId=3 broadcast wait_device_release at 17-Nov-2008 14:51:48
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: msgchan.c:348-3 === End msg_thread. JobId=3 usecnt=2
localhost-dir: restore.c:241-3 In restore_cleanup
localhost-dir: restore.c:331-3 Leaving restore_cleanup
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>1211381508 AND Job.ClientId=1 AND Job.Type='R')
localhost-dir: ua_prune.c:243-3 select now=1226933508 period=2592000 sql=SELECT count(*) from Job WHERE JobTDate<1224341508 AND ClientId=1 AND PurgedFiles=0
localhost-dir: job.c:359-3 ======== End Job stat=T ==========
localhost-dir: jcr.c:184-3 write_last_jobs seek to 188
You have messages.
messages
17-Nov 14:50 localhost-dir JobId 3: Start Restore Job RestoreFiles.2008-11-17_14.50.46.06
17-Nov 14:50 localhost-dir JobId 3: Using Device "FileStorage"
17-Nov 14:50 localhost-sd JobId 3: Ready to read from volume "TestVolume0001" on device "FileStorage" (/usr/bin/bacula/regress/tmp).
17-Nov 14:50 localhost-sd JobId 3: Forward spacing Volume "TestVolume0001" to file:block 0:210.
17-Nov 14:51 localhost-sd JobId 3: End of file 0 on device "FileStorage" (/usr/bin/bacula/regress/tmp), Volume "TestVolume0001"
17-Nov 14:51 localhost-sd JobId 3: End of Volume at file 0 on device "FileStorage" (/usr/bin/bacula/regress/tmp), Volume "TestVolume0001"
17-Nov 14:51 localhost-sd JobId 3: End of all volumes.
17-Nov 14:51 localhost-dir JobId 3: Bacula localhost-dir 2.5.20 (13Nov08): 17-Nov-2008 14:51:48
  Build OS:               i686-pc-linux-gnu unknown unknown
  JobId:                  3
  Job:                    RestoreFiles.2008-11-17_14.50.46.06
  Restore Client:         localhost-fd
  Start time:             17-Nov-2008 14:50:48
  End time:               17-Nov-2008 14:51:48
  Files Expected:         4,447
  Files Restored:         2,928
  Bytes Restored:         356,449,056
  Rate:                   5940.8 KB/s
  FD Errors:              0
  FD termination status:  OK
  SD termination status:  OK
  Termination:            Restore OK -- warning file count mismatch

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

quit
localhost-dir: bnet.c:669-0 who=client host=127.0.0.1 port=42271
localhost-dir: job.c:1264-0 wstorage=File
localhost-dir: job.c:1273-0 wstore=File where=Job resource
localhost-dir: job.c:925-0 JobId=0 created Job=-Console-.2008-11-17_14.51.49.07
localhost-dir: cram-md5.c:73-0 send: auth cram-md5 <1668588993.1226933509@localhost-dir> ssl=0
localhost-dir: cram-md5.c:133-0 cram-get received: auth cram-md5 <542263818.1226933509@bconsole> ssl=0
localhost-dir: cram-md5.c:152-0 sending resp to challenge: AT+kjm/wU3dCckYYU4+qyA
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 <684583896.1226933509@localhost-fd> ssl=0
localhost-dir: cram-md5.c:152-0 sending resp to challenge: c+/L5w4vF857J8/G77/uZD
localhost-dir: cram-md5.c:80-0 send: auth cram-md5 <650925327.1226933509@localhost-dir> ssl=0
localhost-dir: cram-md5.c:99-0 Authenticate OK a6+my++ZYHpw795ij6+uTC
localhost-dir: authenticate.c:263-0 >filed: 1000 OK auth
localhost-dir: authenticate.c:272-0 <filed: 2000 OK Hello 1
localhost-dir: fd_cmds.c:124-0 >filed: JobId=0 Job=-Console-.2008-11-17_14.51.49.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-dir: bsock.c:155-0 who=Storage daemon host=localhost port=8103
localhost-sd: bnet.c:669-0 who=client host=127.0.0.1 port=42783
localhost-sd: dircmd.c:171-0 Conn: Hello Director localhost-dir calling
localhost-sd: dircmd.c:187-0 Got a DIR connection at 17-Nov-2008 14:51:49
localhost-sd: cram-md5.c:73-0 send: auth cram-md5 <275625692.1226933509@localhost-sd> ssl=0
localhost-dir: cram-md5.c:133-0 cram-get received: auth cram-md5 <275625692.1226933509@localhost-sd> ssl=0
localhost-dir: cram-md5.c:152-0 sending resp to challenge: EE8I//UGwXlos4+GxW90YC
localhost-dir: cram-md5.c:80-0 send: auth cram-md5 <990800715.1226933509@localhost-dir> ssl=0
localhost-sd: cram-md5.c:133-0 cram-get received: auth cram-md5 <990800715.1226933509@localhost-dir> ssl=0
localhost-dir: cram-md5.c:99-0 Authenticate OK g+/xCQ+JV5wqnk9Sax+YLB
localhost-dir: authenticate.c:152-0 >stored: 1000 OK auth
localhost-sd: cram-md5.c:152-0 sending resp to challenge: g+/xCQ+JV5wqnk9Sax+YLB
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/patches: 1.34.6
Only in build/patches: 1.36.0
Only in build/patches: 1.36.1
Only in build/patches: 1.36.2
Only in build/patches: 1.36.3
Only in build/patches/1.38.x: 1.38.1-to-1.38.2.patch
Only in build/patches/1.38.x: 1.38.10-dvd-eof.patch
Only in build/patches/1.38.x: 1.38.10-scheduler.patch
Only in build/patches/1.38.x: 1.38.7-mysql.patch
Only in build: scripts
Only in build: src
 
 
  !!!!! broken-media-bug-test failed!!! 14:53:58 !!!!! 
  !!!!! 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.