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

Re: [Bacula-devel] tests/virtual-backup2-test says OK but is actually failing?


On Mon, Oct 20, 2008 at 06:07:21PM +0200, Kern Sibbald wrote:
> Hello,
> 
> Several points:
> 
> 1. You have apparently modified the test.  What you show below does not at
> all correspond to the virtual-backup-test that we are currently running.

Hello,

No, I haven't modified the test. In case I was mistaken, I just checked out a 
fresh copy of svn trunk and ran it again.
In bacula/regress/tests/, there are two scripts:
virtual-backup-test
virtual-backup2-test

virtual-backup-test works fine.
virtual-backup2-test reports that it works, but JobId 6 and JobId 9 fail.

In my last email, I extracted and cleaned up the relevant parts of the output
so that it was easier to read.
As this seems to have caused confusion, I have saved the entire output of the
test and attached it to this email.

> 2. In a number of the regression tests, there is a need for more testing and 
> verification.  This is a project that we (mostly Eric) are working on, but it 
> is not at all easy to use portable shell scripting to check the details of a 
> job.
> 
> 3. If you want to submit some code that improves the testing, we would be 
> happy to see it, but one needs to take a lot of care to make sure it is 
> portable and will run on all Unix flavors ...

OK, I will bear these points in mind.
 
 
 === Starting virtual-backup-test at 10:17:17 ===
 
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.16 (18 October 2008)
Enter a period to cancel a command.
@output
messages
You have no messages.
@tee /usr/bin/bacula/regress/tmp/log1.out
setdebug level=150 storage=DiskChanger
Connecting to Storage daemon DiskChanger at localhost:8103
3000 OK setdebug=150
label storage=DiskChanger volume=ChangerVolume001 slot=1 Pool=Default drive=0
Automatically selected Catalog: MyCatalog
localhost-sd: bnet.c:669-0 who=client host=127.0.0.1 port=42783
Using Catalog "MyCatalog"
Connecting to Storage daemon DiskChanger at localhost:8103 ...
localhost-sd: dircmd.c:171-0 Conn: Hello Director localhost-dir calling
localhost-sd: dircmd.c:186-0 Got a DIR connection at 21-Oct-2008 10:17:19
localhost-sd: cram-md5.c:73-0 send: auth cram-md5 <1808685792.1224580639@localhost-sd> ssl=0
localhost-sd: cram-md5.c:133-0 cram-get received: auth cram-md5 <573117676.1224580639@localhost-dir> ssl=0
localhost-sd: cram-md5.c:152-0 sending resp to challenge: NA+HP5/Qm++eCWxdP5/53A
localhost-sd: dircmd.c:208-0 Message channel init completed.
localhost-sd: dircmd.c:593-0 Try changer device Drive-0
localhost-sd: dircmd.c:609-0 Found changer device Drive-0
localhost-sd: dircmd.c:622-0 Found device Drive-0
localhost-sd: dircmd.c:440-0 Stole device "Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0) lock, writing label.
localhost-sd: dircmd.c:443-0 try_autoload_device - looking for volume_info
localhost-sd: autochanger.c:133-0 autoload: slot=1 InChgr=1 Vol=
localhost-sd: autochanger.c:273-0 Run program=/usr/bin/bacula/regress/bin/disk-changer /usr/bin/bacula/regress/tmp/disk-changer/conf loaded 1 /usr/bin/bacula/regress/tmp/disk-changer/drive0 0
Sending label command for Volume "ChangerVolume001" Slot 1 ...
3301 Issuing autochanger "loaded? drive 0" command.
localhost-sd: autochanger.c:275-0 run_prog: /usr/bin/bacula/regress/bin/disk-changer /usr/bin/bacula/regress/tmp/disk-changer/conf loaded 1 /usr/bin/bacula/regress/tmp/disk-changer/drive0 0 stat=0 result=0
localhost-sd: autochanger.c:190-0 Doing changer load slot 1 "Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0)
localhost-sd: dev.c:1902-0 close_dev "Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0)
localhost-sd: dev.c:1909-0 device "Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0) already closed vol=
3302 Autochanger "loaded? drive 0", result: nothing loaded.
3304 Issuing autochanger "load slot 1, drive 0" command.
localhost-sd: autochanger.c:202-0 load slot 1, drive 0, status is OK.
localhost-sd: autochanger.c:215-0 load slot 1 status=0
localhost-sd: autochanger.c:221-0 After changer, status=0
localhost-sd: dev.c:345-0 open dev: type=1 dev_name="Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0) vol=ChangerVolume001 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/disk-changer/drive0, 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="Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0) vol=ChangerVolume001 dev_Vol=*NULL*
localhost-sd: label.c:130-0 Big if statement in read_volume_label
localhost-sd: label.c:135-0 Requested Volume "ChangerVolume001" on "Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0) is not a Bacula labeled Volume, because: ERR=block.c:1015 Read zero bytes at 0:0 on device "Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0).
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=ChangerVolume001
localhost-sd: dev.c:336-0 Close fd for mode change.
localhost-sd: dev.c:345-0 open dev: type=1 dev_name="Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0) vol=ChangerVolume001 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/disk-changer/drive0, 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           : ChangerVolume001
PrevVolName       : 
VolFile           : 0
LabelType         : PRE_LABEL
LabelSize         : 0
PoolName          : Default
MediaType         : DiskChangerMedia
PoolType          : Backup
HostName          : tserv
Date label written: 21-Oct-2008 10:17
localhost-sd: label.c:590-0 Created Vol label rec: FI=PRE_LABEL len=181
localhost-sd: label.c:369-0 Wrote label of 181 bytes to "Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0)
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="Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0)

Volume Label:
Id                : Bacula 1.0 immortal
VerNo             : 11
VolName           : ChangerVolume001
PrevVolName       : 
VolFile           : 0
LabelType         : PRE_LABEL
LabelSize         : 0
PoolName          : Default
MediaType         : DiskChangerMedia
PoolType          : Backup
HostName          : tserv
Date label written: 21-Oct-2008 10:17
localhost-sd: label.c:397-0 Call reserve_volume
localhost-sd: reserve.c:314-0 enter reserve_volume=ChangerVolume001 drive="Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0)
localhost-sd: reserve.c:234-0 new Vol=ChangerVolume001 at 80b8130 dev="Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0)
localhost-sd: reserve.c:418-0 === set in_use. vol=ChangerVolume001 dev="Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0)
localhost-sd: reserve.c:187-0 List end new volume: ChangerVolume001 in_use=1 on device "Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0)
localhost-sd: reserve.c:553-0 === set not reserved vol=ChangerVolume001 num_writers=0 dev_reserved=0 dev="Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0)
localhost-sd: reserve.c:554-0 === clear in_use vol=ChangerVolume001
localhost-sd: dev.c:1902-0 close_dev "Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0)
localhost-sd: dev.c:1892-0 Clear volhdr vol=ChangerVolume001
localhost-sd: dircmd.c:593-0 Try changer device Drive-0
localhost-sd: dircmd.c:609-0 Found changer device Drive-0
localhost-sd: dircmd.c:622-0 Found device Drive-0
localhost-sd: dircmd.c:654-0 mount cmd blocked=0 must_unload=0
3305 Autochanger "load slot 1, drive 0", status is OK.
3000 OK label. VolBytes=217 DVD=0 Volume="ChangerVolume001" Device="Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0)
Catalog record for Volume "ChangerVolume001", Slot 1  successfully created.
Requesting to mount DiskChanger ...
3002 Device "Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0) is mounted.
label storage=DiskChanger volume=ChangerVolume002 slot=2 Pool=Full drive=0
Connecting to Storage daemon DiskChanger at localhost:8103 ...
localhost-sd: bnet.c:669-0 who=client host=127.0.0.1 port=42783
localhost-sd: dircmd.c:171-0 Conn: Hello Director localhost-dir calling
localhost-sd: dircmd.c:186-0 Got a DIR connection at 21-Oct-2008 10:17:20
localhost-sd: cram-md5.c:73-0 send: auth cram-md5 <284791753.1224580640@localhost-sd> ssl=0
localhost-sd: cram-md5.c:133-0 cram-get received: auth cram-md5 <1092543763.1224580640@localhost-dir> ssl=0
localhost-sd: cram-md5.c:152-0 sending resp to challenge: BwB5M5+rY6/0jU/55/ReZD
localhost-sd: dircmd.c:208-0 Message channel init completed.
Sending label command for Volume "ChangerVolume002" Slot 2 ...
localhost-sd: dircmd.c:593-0 Try changer device Drive-0
localhost-sd: dircmd.c:609-0 Found changer device Drive-0
localhost-sd: dircmd.c:622-0 Found device Drive-0
localhost-sd: dircmd.c:440-0 Stole device "Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0) lock, writing label.
localhost-sd: dircmd.c:443-0 try_autoload_device - looking for volume_info
localhost-sd: autochanger.c:133-0 autoload: slot=2 InChgr=1 Vol=
3307 Issuing autochanger "unload slot 1, drive 0" command.
localhost-sd: dev.c:1902-0 close_dev "Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0)
localhost-sd: dev.c:1909-0 device "Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0) already closed vol=
localhost-sd: autochanger.c:362-0 Run program=/usr/bin/bacula/regress/bin/disk-changer /usr/bin/bacula/regress/tmp/disk-changer/conf unload 1 /usr/bin/bacula/regress/tmp/disk-changer/drive0 0
localhost-sd: reserve.c:582-0 === clear in_use vol=ChangerVolume001
localhost-sd: reserve.c:585-0 === remove volume ChangerVolume001 dev="Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0)
localhost-sd: autochanger.c:190-0 Doing changer load slot 2 "Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0)
localhost-sd: dev.c:1902-0 close_dev "Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0)
localhost-sd: dev.c:1909-0 device "Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0) already closed vol=
3304 Issuing autochanger "load slot 2, drive 0" command.
localhost-sd: autochanger.c:202-0 load slot 2, drive 0, status is OK.
localhost-sd: autochanger.c:215-0 load slot 2 status=0
localhost-sd: autochanger.c:221-0 After changer, status=0
localhost-sd: dev.c:345-0 open dev: type=1 dev_name="Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0) vol=ChangerVolume002 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/disk-changer/drive0, 0x42, 0640)
localhost-sd: dev.c:541-0 open dev: disk fd=7 opened, part=0/0, part_size=217
localhost-sd: dev.c:358-0 preserve=0x0 fd=7
localhost-sd: label.c:81-0 Enter read_volume_label res=0 device="Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0) vol=ChangerVolume002 dev_Vol=*NULL*
localhost-sd: label.c:130-0 Big if statement in read_volume_label
localhost-sd: label.c:135-0 Requested Volume "ChangerVolume002" on "Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0) is not a Bacula labeled Volume, because: ERR=block.c:1015 Read zero bytes at 0:0 on device "Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0).
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=ChangerVolume002
localhost-sd: dev.c:336-0 Close fd for mode change.
localhost-sd: dev.c:345-0 open dev: type=1 dev_name="Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0) vol=ChangerVolume002 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/disk-changer/drive0, 0x2, 0640)
localhost-sd: dev.c:541-0 open dev: disk fd=7 opened, part=0/0, part_size=217
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           : ChangerVolume002
PrevVolName       : 
VolFile           : 0
LabelType         : PRE_LABEL
LabelSize         : 0
PoolName          : Full
MediaType         : DiskChangerMedia
PoolType          : Backup
HostName          : tserv
Date label written: 21-Oct-2008 10:17
localhost-sd: label.c:590-0 Created Vol label rec: FI=PRE_LABEL len=178
localhost-sd: label.c:369-0 Wrote label of 178 bytes to "Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0)
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="Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0)

Volume Label:
Id                : Bacula 1.0 immortal
VerNo             : 11
VolName           : ChangerVolume002
PrevVolName       : 
VolFile           : 0
LabelType         : PRE_LABEL
LabelSize         : 0
PoolName          : Full
MediaType         : DiskChangerMedia
PoolType          : Backup
HostName          : tserv
Date label written: 21-Oct-2008 10:17
localhost-sd: label.c:397-0 Call reserve_volume
localhost-sd: reserve.c:314-0 enter reserve_volume=ChangerVolume002 drive="Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0)
localhost-sd: reserve.c:234-0 new Vol=ChangerVolume002 at 80b8130 dev="Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0)
localhost-sd: reserve.c:418-0 === set in_use. vol=ChangerVolume002 dev="Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0)
localhost-sd: reserve.c:187-0 List end new volume: ChangerVolume002 in_use=1 on device "Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0)
localhost-sd: reserve.c:553-0 === set not reserved vol=ChangerVolume002 num_writers=0 dev_reserved=0 dev="Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0)
localhost-sd: reserve.c:554-0 === clear in_use vol=ChangerVolume002
localhost-sd: dev.c:1902-0 close_dev "Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0)
localhost-sd: dev.c:1892-0 Clear volhdr vol=ChangerVolume002
localhost-sd: dircmd.c:593-0 Try changer device Drive-0
localhost-sd: dircmd.c:609-0 Found changer device Drive-0
localhost-sd: dircmd.c:622-0 Found device Drive-0
localhost-sd: dircmd.c:654-0 mount cmd blocked=0 must_unload=0
3305 Autochanger "load slot 2, drive 0", status is OK.
3000 OK label. VolBytes=214 DVD=0 Volume="ChangerVolume002" Device="Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0)
Catalog record for Volume "ChangerVolume002", Slot 2  successfully created.
Requesting to mount DiskChanger ...
3002 Device "Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0) is mounted.
label storage=DiskChanger volume=ChangerVolume003 slot=3 Pool=Full drive=0
Connecting to Storage daemon DiskChanger at localhost:8103 ...
localhost-sd: bnet.c:669-0 who=client host=127.0.0.1 port=42783
localhost-sd: dircmd.c:171-0 Conn: Hello Director localhost-dir calling
localhost-sd: dircmd.c:186-0 Got a DIR connection at 21-Oct-2008 10:17:20
localhost-sd: cram-md5.c:73-0 send: auth cram-md5 <707289610.1224580640@localhost-sd> ssl=0
localhost-sd: cram-md5.c:133-0 cram-get received: auth cram-md5 <1921073975.1224580640@localhost-dir> ssl=0
localhost-sd: cram-md5.c:152-0 sending resp to challenge: n4Z1/URRu7lGoCJcw6/t5B
localhost-sd: dircmd.c:208-0 Message channel init completed.
Sending label command for Volume "ChangerVolume003" Slot 3 ...
localhost-sd: dircmd.c:593-0 Try changer device Drive-0
localhost-sd: dircmd.c:609-0 Found changer device Drive-0
localhost-sd: dircmd.c:622-0 Found device Drive-0
localhost-sd: dircmd.c:440-0 Stole device "Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0) lock, writing label.
localhost-sd: dircmd.c:443-0 try_autoload_device - looking for volume_info
localhost-sd: autochanger.c:133-0 autoload: slot=3 InChgr=1 Vol=
3307 Issuing autochanger "unload slot 2, drive 0" command.
localhost-sd: dev.c:1902-0 close_dev "Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0)
localhost-sd: dev.c:1909-0 device "Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0) already closed vol=
localhost-sd: autochanger.c:362-0 Run program=/usr/bin/bacula/regress/bin/disk-changer /usr/bin/bacula/regress/tmp/disk-changer/conf unload 2 /usr/bin/bacula/regress/tmp/disk-changer/drive0 0
localhost-sd: reserve.c:582-0 === clear in_use vol=ChangerVolume002
localhost-sd: reserve.c:585-0 === remove volume ChangerVolume002 dev="Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0)
localhost-sd: autochanger.c:190-0 Doing changer load slot 3 "Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0)
localhost-sd: dev.c:1902-0 close_dev "Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0)
localhost-sd: dev.c:1909-0 device "Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0) already closed vol=
3304 Issuing autochanger "load slot 3, drive 0" command.
localhost-sd: autochanger.c:202-0 load slot 3, drive 0, status is OK.
localhost-sd: autochanger.c:215-0 load slot 3 status=0
localhost-sd: autochanger.c:221-0 After changer, status=0
localhost-sd: dev.c:345-0 open dev: type=1 dev_name="Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0) vol=ChangerVolume003 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/disk-changer/drive0, 0x42, 0640)
localhost-sd: dev.c:541-0 open dev: disk fd=7 opened, part=0/0, part_size=431
localhost-sd: dev.c:358-0 preserve=0x0 fd=7
localhost-sd: label.c:81-0 Enter read_volume_label res=0 device="Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0) vol=ChangerVolume003 dev_Vol=*NULL*
localhost-sd: label.c:130-0 Big if statement in read_volume_label
localhost-sd: label.c:135-0 Requested Volume "ChangerVolume003" on "Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0) is not a Bacula labeled Volume, because: ERR=block.c:1015 Read zero bytes at 0:0 on device "Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0).
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=ChangerVolume003
localhost-sd: dev.c:336-0 Close fd for mode change.
localhost-sd: dev.c:345-0 open dev: type=1 dev_name="Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0) vol=ChangerVolume003 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/disk-changer/drive0, 0x2, 0640)
localhost-sd: dev.c:541-0 open dev: disk fd=7 opened, part=0/0, part_size=431
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           : ChangerVolume003
PrevVolName       : 
VolFile           : 0
LabelType         : PRE_LABEL
LabelSize         : 0
PoolName          : Full
MediaType         : DiskChangerMedia
PoolType          : Backup
HostName          : tserv
Date label written: 21-Oct-2008 10:17
localhost-sd: label.c:590-0 Created Vol label rec: FI=PRE_LABEL len=178
localhost-sd: label.c:369-0 Wrote label of 178 bytes to "Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0)
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="Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0)

Volume Label:
Id                : Bacula 1.0 immortal
VerNo             : 11
VolName           : ChangerVolume003
PrevVolName       : 
VolFile           : 0
LabelType         : PRE_LABEL
LabelSize         : 0
PoolName          : Full
MediaType         : DiskChangerMedia
PoolType          : Backup
HostName          : tserv
Date label written: 21-Oct-2008 10:17
localhost-sd: label.c:397-0 Call reserve_volume
localhost-sd: reserve.c:314-0 enter reserve_volume=ChangerVolume003 drive="Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0)
localhost-sd: reserve.c:234-0 new Vol=ChangerVolume003 at 80a5958 dev="Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0)
localhost-sd: reserve.c:418-0 === set in_use. vol=ChangerVolume003 dev="Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0)
localhost-sd: reserve.c:187-0 List end new volume: ChangerVolume003 in_use=1 on device "Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0)
localhost-sd: reserve.c:553-0 === set not reserved vol=ChangerVolume003 num_writers=0 dev_reserved=0 dev="Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0)
localhost-sd: reserve.c:554-0 === clear in_use vol=ChangerVolume003
localhost-sd: dev.c:1902-0 close_dev "Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0)
localhost-sd: dev.c:1892-0 Clear volhdr vol=ChangerVolume003
localhost-sd: dircmd.c:593-0 Try changer device Drive-0
localhost-sd: dircmd.c:609-0 Found changer device Drive-0
localhost-sd: dircmd.c:622-0 Found device Drive-0
localhost-sd: dircmd.c:654-0 mount cmd blocked=0 must_unload=0
3305 Autochanger "load slot 3, drive 0", status is OK.
3000 OK label. VolBytes=214 DVD=0 Volume="ChangerVolume003" Device="Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0)
Catalog record for Volume "ChangerVolume003", Slot 3  successfully created.
Requesting to mount DiskChanger ...
3002 Device "Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0) is mounted.
setdebug level=0 storage=DiskChanger
Connecting to Storage daemon DiskChanger at localhost:8103
localhost-sd: bnet.c:669-0 who=client host=127.0.0.1 port=42783
localhost-sd: dircmd.c:171-0 Conn: Hello Director localhost-dir calling
localhost-sd: dircmd.c:186-0 Got a DIR connection at 21-Oct-2008 10:17:20
localhost-sd: cram-md5.c:73-0 send: auth cram-md5 <50654120.1224580640@localhost-sd> ssl=0
localhost-sd: cram-md5.c:133-0 cram-get received: auth cram-md5 <1892556720.1224580640@localhost-dir> ssl=0
localhost-sd: cram-md5.c:152-0 sending resp to challenge: R8cfGS/Mn5+A44tlvQ8pjA
localhost-sd: dircmd.c:208-0 Message channel init completed.
localhost-sd: dircmd.c:278-0 setdebug_cmd: setdebug=0 trace=-1
3000 OK setdebug=0
@# run several jobs
@exec "sh -c 'date > /usr/bin/bacula/regress/build/date'"
run job=Vbackup level=Full storage=DiskChanger yes
Job queued. JobId=1
wait
You have messages.
messages
21-Oct 10:17 localhost-dir JobId 1: Start Backup JobId 1, Job=Vbackup.2008-10-21_10.17.03
21-Oct 10:17 localhost-dir JobId 1: Using Device "Drive-0"
21-Oct 10:17 localhost-sd JobId 1: 3307 Issuing autochanger "unload slot 3, drive 0" command.
21-Oct 10:17 localhost-sd JobId 1: 3304 Issuing autochanger "load slot 1, drive 0" command.
21-Oct 10:17 localhost-sd JobId 1: 3305 Autochanger "load slot 1, drive 0", status is OK.
21-Oct 10:17 localhost-sd JobId 1: Wrote label to prelabeled Volume "ChangerVolume001" on device "Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0)
21-Oct 10:17 localhost-sd JobId 1: Spooling data ...
21-Oct 10:17 localhost-sd JobId 1: Job write elapsed time = 00:00:07, Transfer rate = 10.60 M bytes/second
21-Oct 10:17 localhost-sd JobId 1: Committing spooled data to Volume "ChangerVolume001". Despooling 74,429,207 bytes ...
21-Oct 10:17 localhost-sd JobId 1: Despooling elapsed time = 00:00:01, Transfer rate = 74.42 M bytes/second
21-Oct 10:17 localhost-sd JobId 1: Sending spooled attrs to the Director. Despooling 1,327,874 bytes ...
21-Oct 10:17 localhost-dir JobId 1: Bacula localhost-dir 2.5.16 (18Oct08): 21-Oct-2008 10:17:37
  Build OS:               i686-pc-linux-gnu unknown unknown
  JobId:                  1
  Job:                    Vbackup.2008-10-21_10.17.03
  Backup Level:           Full
  Client:                 "localhost-fd" 2.5.16 (18Oct08) i686-pc-linux-gnu,unknown,unknown
  FileSet:                "Full Set" 2008-10-21 10:17:20
  Pool:                   "Default" (From Job resource)
  Catalog:                "MyCatalog" (From Client resource)
  Storage:                "DiskChanger" (From command line)
  Scheduled time:         21-Oct-2008 10:17:20
  Start time:             21-Oct-2008 10:17:23
  End time:               21-Oct-2008 10:17:37
  Elapsed time:           14 secs
  Priority:               10
  FD Files Written:       4,414
  SD Files Written:       4,414
  FD Bytes Written:       73,555,187 (73.55 MB)
  SD Bytes Written:       74,213,977 (74.21 MB)
  Rate:                   5253.9 KB/s
  Software Compression:   None
  VSS:                    no
  Encryption:             no
  Accurate:               no
  Volume name(s):         ChangerVolume001
  Volume Session Id:      1
  Volume Session Time:    1224580637
  Last Volume Bytes:      74,415,576 (74.41 MB)
  Non-fatal FD errors:    0
  SD Errors:              0
  FD termination status:  OK
  SD termination status:  OK
  Termination:            Backup OK

21-Oct 10:17 localhost-dir JobId 1: Begin pruning Jobs.
21-Oct 10:17 localhost-dir JobId 1: No Jobs found to prune.
21-Oct 10:17 localhost-dir JobId 1: Begin pruning Files.
21-Oct 10:17 localhost-dir JobId 1: No Files found to prune.
21-Oct 10:17 localhost-dir JobId 1: End auto prune.

list jobs
+-------+---------+---------------------+------+-------+----------+----------+-----------+
| JobId | Name    | StartTime           | Type | Level | JobFiles | JobBytes | JobStatus |
+-------+---------+---------------------+------+-------+----------+----------+-----------+
| 1     | Vbackup | 2008-10-21 10:17:23 | B    | F     | 4414     | 73555187 | T         |
+-------+---------+---------------------+------+-------+----------+----------+-----------+
@exec "sh -c 'touch /usr/bin/bacula/regress/build/src/dird/*.c'"
run job=Vbackup level=Incremental storage=DiskChanger yes
Job queued. JobId=2
wait
You have messages.
messages
21-Oct 10:17 localhost-dir JobId 2: Start Backup JobId 2, Job=Vbackup.2008-10-21_10.17.04
21-Oct 10:17 localhost-dir JobId 2: Using Device "Drive-0"
21-Oct 10:17 localhost-sd JobId 2: Volume "ChangerVolume001" previously written, moving to end of data.
21-Oct 10:17 localhost-sd JobId 2: Ready to append to end of Volume "ChangerVolume001" size=74415576
21-Oct 10:17 localhost-sd JobId 2: Spooling data ...
21-Oct 10:17 localhost-sd JobId 2: Job write elapsed time = 00:00:01, Transfer rate = 936.7 K bytes/second
21-Oct 10:17 localhost-sd JobId 2: Committing spooled data to Volume "ChangerVolume001". Despooling 939,418 bytes ...
21-Oct 10:17 localhost-sd JobId 2: Despooling elapsed time = 00:00:01, Transfer rate = 939.4 K bytes/second
21-Oct 10:17 localhost-sd JobId 2: Sending spooled attrs to the Director. Despooling 12,355 bytes ...
21-Oct 10:17 localhost-dir JobId 2: Bacula localhost-dir 2.5.16 (18Oct08): 21-Oct-2008 10:17:41
  Build OS:               i686-pc-linux-gnu unknown unknown
  JobId:                  2
  Job:                    Vbackup.2008-10-21_10.17.04
  Backup Level:           Incremental, since=2008-10-21 10:17:23
  Client:                 "localhost-fd" 2.5.16 (18Oct08) i686-pc-linux-gnu,unknown,unknown
  FileSet:                "Full Set" 2008-10-21 10:17:20
  Pool:                   "Default" (From Job resource)
  Catalog:                "MyCatalog" (From Client resource)
  Storage:                "DiskChanger" (From command line)
  Scheduled time:         21-Oct-2008 10:17:38
  Start time:             21-Oct-2008 10:17:40
  End time:               21-Oct-2008 10:17:41
  Elapsed time:           1 sec
  Priority:               10
  FD Files Written:       43
  SD Files Written:       43
  FD Bytes Written:       931,145 (931.1 KB)
  SD Bytes Written:       936,792 (936.7 KB)
  Rate:                   931.1 KB/s
  Software Compression:   None
  VSS:                    no
  Encryption:             no
  Accurate:               no
  Volume name(s):         ChangerVolume001
  Volume Session Id:      2
  Volume Session Time:    1224580637
  Last Volume Bytes:      75,354,814 (75.35 MB)
  Non-fatal FD errors:    0
  SD Errors:              0
  FD termination status:  OK
  SD termination status:  OK
  Termination:            Backup OK

21-Oct 10:17 localhost-dir JobId 2: Begin pruning Jobs.
21-Oct 10:17 localhost-dir JobId 2: No Jobs found to prune.
21-Oct 10:17 localhost-dir JobId 2: Begin pruning Files.
21-Oct 10:17 localhost-dir JobId 2: No Files found to prune.
21-Oct 10:17 localhost-dir JobId 2: End auto prune.

list jobs
+-------+---------+---------------------+------+-------+----------+----------+-----------+
| JobId | Name    | StartTime           | Type | Level | JobFiles | JobBytes | JobStatus |
+-------+---------+---------------------+------+-------+----------+----------+-----------+
| 1     | Vbackup | 2008-10-21 10:17:23 | B    | F     | 4414     | 73555187 | T         |
| 2     | Vbackup | 2008-10-21 10:17:40 | B    | I     | 43       | 931145   | T         |
+-------+---------+---------------------+------+-------+----------+----------+-----------+
@exec "sh -c 'touch /usr/bin/bacula/regress/build/src/dird/*.o'"
run job=Vbackup level=Differential storage=DiskChanger yes
Job queued. JobId=3
wait
You have messages.
messages
21-Oct 10:17 localhost-dir JobId 3: Start Backup JobId 3, Job=Vbackup.2008-10-21_10.17.05
21-Oct 10:17 localhost-dir JobId 3: Using Device "Drive-0"
21-Oct 10:17 localhost-sd JobId 3: Volume "ChangerVolume001" previously written, moving to end of data.
21-Oct 10:17 localhost-sd JobId 3: Ready to append to end of Volume "ChangerVolume001" size=75354814
21-Oct 10:17 localhost-sd JobId 3: Spooling data ...
21-Oct 10:17 localhost-sd JobId 3: Job write elapsed time = 00:00:01, Transfer rate = 3.659 M bytes/second
21-Oct 10:17 localhost-sd JobId 3: Committing spooled data to Volume "ChangerVolume001". Despooling 3,666,328 bytes ...
21-Oct 10:17 localhost-sd JobId 3: Despooling elapsed time = 00:00:01, Transfer rate = 3.666 M bytes/second
21-Oct 10:17 localhost-sd JobId 3: Sending spooled attrs to the Director. Despooling 24,757 bytes ...
21-Oct 10:17 localhost-dir JobId 3: Bacula localhost-dir 2.5.16 (18Oct08): 21-Oct-2008 10:17:45
  Build OS:               i686-pc-linux-gnu unknown unknown
  JobId:                  3
  Job:                    Vbackup.2008-10-21_10.17.05
  Backup Level:           Differential, since=2008-10-21 10:17:23
  Client:                 "localhost-fd" 2.5.16 (18Oct08) i686-pc-linux-gnu,unknown,unknown
  FileSet:                "Full Set" 2008-10-21 10:17:20
  Pool:                   "Default" (From Job resource)
  Catalog:                "MyCatalog" (From Client resource)
  Storage:                "DiskChanger" (From command line)
  Scheduled time:         21-Oct-2008 10:17:41
  Start time:             21-Oct-2008 10:17:44
  End time:               21-Oct-2008 10:17:45
  Elapsed time:           1 sec
  Priority:               10
  FD Files Written:       86
  SD Files Written:       86
  FD Bytes Written:       3,648,605 (3.648 MB)
  SD Bytes Written:       3,659,946 (3.659 MB)
  Rate:                   3648.6 KB/s
  Software Compression:   None
  VSS:                    no
  Encryption:             no
  Accurate:               no
  Volume name(s):         ChangerVolume001
  Volume Session Id:      3
  Volume Session Time:    1224580637
  Last Volume Bytes:      79,020,458 (79.02 MB)
  Non-fatal FD errors:    0
  SD Errors:              0
  FD termination status:  OK
  SD termination status:  OK
  Termination:            Backup OK

21-Oct 10:17 localhost-dir JobId 3: Begin pruning Jobs.
21-Oct 10:17 localhost-dir JobId 3: No Jobs found to prune.
21-Oct 10:17 localhost-dir JobId 3: Begin pruning Files.
21-Oct 10:17 localhost-dir JobId 3: No Files found to prune.
21-Oct 10:17 localhost-dir JobId 3: End auto prune.

list jobs
+-------+---------+---------------------+------+-------+----------+----------+-----------+
| JobId | Name    | StartTime           | Type | Level | JobFiles | JobBytes | JobStatus |
+-------+---------+---------------------+------+-------+----------+----------+-----------+
| 1     | Vbackup | 2008-10-21 10:17:23 | B    | F     | 4414     | 73555187 | T         |
| 2     | Vbackup | 2008-10-21 10:17:40 | B    | I     | 43       | 931145   | T         |
| 3     | Vbackup | 2008-10-21 10:17:44 | B    | D     | 86       | 3648605  | T         |
+-------+---------+---------------------+------+-------+----------+----------+-----------+
@exec "sh -c 'date > /usr/bin/bacula/regress/build/date'"
@exec "sh -c 'touch /usr/bin/bacula/regress/build/src/dird/*.o'"
run job=Vbackup level=Incremental storage=DiskChanger yes
Job queued. JobId=4
wait
You have messages.
messages
21-Oct 10:17 localhost-dir JobId 4: Start Backup JobId 4, Job=Vbackup.2008-10-21_10.17.06
21-Oct 10:17 localhost-dir JobId 4: Using Device "Drive-0"
21-Oct 10:17 localhost-sd JobId 4: Volume "ChangerVolume001" previously written, moving to end of data.
21-Oct 10:17 localhost-sd JobId 4: Ready to append to end of Volume "ChangerVolume001" size=79020458
21-Oct 10:17 localhost-sd JobId 4: Spooling data ...
21-Oct 10:17 localhost-sd JobId 4: Job write elapsed time = 00:00:01, Transfer rate = 2.723 M bytes/second
21-Oct 10:17 localhost-sd JobId 4: Committing spooled data to Volume "ChangerVolume001". Despooling 2,727,473 bytes ...
21-Oct 10:17 localhost-sd JobId 4: Despooling elapsed time = 00:00:01, Transfer rate = 2.727 M bytes/second
21-Oct 10:17 localhost-sd JobId 4: Sending spooled attrs to the Director. Despooling 12,662 bytes ...
21-Oct 10:17 localhost-dir JobId 4: Bacula localhost-dir 2.5.16 (18Oct08): 21-Oct-2008 10:17:49
  Build OS:               i686-pc-linux-gnu unknown unknown
  JobId:                  4
  Job:                    Vbackup.2008-10-21_10.17.06
  Backup Level:           Incremental, since=2008-10-21 10:17:44
  Client:                 "localhost-fd" 2.5.16 (18Oct08) i686-pc-linux-gnu,unknown,unknown
  FileSet:                "Full Set" 2008-10-21 10:17:20
  Pool:                   "Default" (From Job resource)
  Catalog:                "MyCatalog" (From Client resource)
  Storage:                "DiskChanger" (From command line)
  Scheduled time:         21-Oct-2008 10:17:46
  Start time:             21-Oct-2008 10:17:48
  End time:               21-Oct-2008 10:17:49
  Elapsed time:           1 sec
  Priority:               10
  FD Files Written:       44
  SD Files Written:       44
  FD Bytes Written:       2,717,489 (2.717 MB)
  SD Bytes Written:       2,723,287 (2.723 MB)
  Rate:                   2717.5 KB/s
  Software Compression:   None
  VSS:                    no
  Encryption:             no
  Accurate:               no
  Volume name(s):         ChangerVolume001
  Volume Session Id:      4
  Volume Session Time:    1224580637
  Last Volume Bytes:      81,747,415 (81.74 MB)
  Non-fatal FD errors:    0
  SD Errors:              0
  FD termination status:  OK
  SD termination status:  OK
  Termination:            Backup OK

21-Oct 10:17 localhost-dir JobId 4: Begin pruning Jobs.
21-Oct 10:17 localhost-dir JobId 4: No Jobs found to prune.
21-Oct 10:17 localhost-dir JobId 4: Begin pruning Files.
21-Oct 10:17 localhost-dir JobId 4: No Files found to prune.
21-Oct 10:17 localhost-dir JobId 4: End auto prune.

list jobs
+-------+---------+---------------------+------+-------+----------+----------+-----------+
| JobId | Name    | StartTime           | Type | Level | JobFiles | JobBytes | JobStatus |
+-------+---------+---------------------+------+-------+----------+----------+-----------+
| 1     | Vbackup | 2008-10-21 10:17:23 | B    | F     | 4414     | 73555187 | T         |
| 2     | Vbackup | 2008-10-21 10:17:40 | B    | I     | 43       | 931145   | T         |
| 3     | Vbackup | 2008-10-21 10:17:44 | B    | D     | 86       | 3648605  | T         |
| 4     | Vbackup | 2008-10-21 10:17:48 | B    | I     | 44       | 2717489  | T         |
+-------+---------+---------------------+------+-------+----------+----------+-----------+
list volumes
Pool: Default
+---------+------------------+-----------+---------+----------+----------+--------------+---------+------+-----------+------------------+---------------------+
| MediaId | VolumeName       | VolStatus | Enabled | VolBytes | VolFiles | VolRetention | Recycle | Slot | InChanger | MediaType        | LastWritten         |
+---------+------------------+-----------+---------+----------+----------+--------------+---------+------+-----------+------------------+---------------------+
| 1       | ChangerVolume001 | Append    | 1       | 81747415 | 0        | 31536000     | 1       | 1    | 1         | DiskChangerMedia | 2008-10-21 10:17:49 |
+---------+------------------+-----------+---------+----------+----------+--------------+---------+------+-----------+------------------+---------------------+
Pool: Full
+---------+------------------+-----------+---------+----------+----------+--------------+---------+------+-----------+------------------+-------------+
| MediaId | VolumeName       | VolStatus | Enabled | VolBytes | VolFiles | VolRetention | Recycle | Slot | InChanger | MediaType        | LastWritten |
+---------+------------------+-----------+---------+----------+----------+--------------+---------+------+-----------+------------------+-------------+
| 2       | ChangerVolume002 | Append    | 1       | 214      | 0        | 31536000     | 1       | 2    | 1         | DiskChangerMedia | 0           |
| 3       | ChangerVolume003 | Append    | 1       | 214      | 0        | 31536000     | 1       | 3    | 1         | DiskChangerMedia | 0           |
+---------+------------------+-----------+---------+----------+----------+--------------+---------+------+-----------+------------------+-------------+
@# 
@# now do a restore
@#
@tee /usr/bin/bacula/regress/tmp/log2.out
restore where=/usr/bin/bacula/regress/tmp/bacula-restores select
Automatically selected Client: localhost-fd
Automatically selected FileSet: Full Set
+-------+-------+----------+----------+---------------------+------------------+
| JobId | Level | JobFiles | JobBytes | StartTime           | VolumeName       |
+-------+-------+----------+----------+---------------------+------------------+
| 1     | F     | 4414     | 73555187 | 2008-10-21 10:17:23 | ChangerVolume001 |
| 3     | D     | 86       | 3648605  | 2008-10-21 10:17:44 | ChangerVolume001 |
| 4     | I     | 44       | 2717489  | 2008-10-21 10:17:48 | ChangerVolume001 |
+-------+-------+----------+----------+---------------------+------------------+
You have selected the following JobIds: 1,3,4

Building directory tree for JobId(s) 1,3,4 ...  +++++++++++++++++++++++++++++++++++++++++++++++
4,188 files inserted into the tree.

You are now entering file selection mode where you add (mark) and
remove (unmark) files to be restored. No files are initially added, unless
you used the "all" keyword on the command line.
Enter "done" to leave this mode.

cwd is: /
$ unmark *
4,414 files unmarked.
$ mark *
4,414 files marked.
$ done
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)
===========================================================================
   
   ChangerVolume001          DiskChanger               DiskChanger              


4,414 files selected to be restored.

Run Restore job
JobName:         RestoreFiles
Bootstrap:       /usr/bin/bacula/regress/working/localhost-dir.restore.1.bsr
Where:           /usr/bin/bacula/regress/tmp/bacula-restores
Replace:         always
FileSet:         Full Set
Backup Client:   localhost-fd
Restore Client:  localhost-fd
Storage:         DiskChanger
When:            2008-10-21 10:17:51
Catalog:         MyCatalog
Priority:        10
Plugin Options:  *None*
OK to run? (yes/mod/no): yes
Job queued. JobId=5
wait
You have messages.
list volumes
Pool: Default
+---------+------------------+-----------+---------+----------+----------+--------------+---------+------+-----------+------------------+---------------------+
| MediaId | VolumeName       | VolStatus | Enabled | VolBytes | VolFiles | VolRetention | Recycle | Slot | InChanger | MediaType        | LastWritten         |
+---------+------------------+-----------+---------+----------+----------+--------------+---------+------+-----------+------------------+---------------------+
| 1       | ChangerVolume001 | Append    | 1       | 81747415 | 0        | 31536000     | 1       | 1    | 1         | DiskChangerMedia | 2008-10-21 10:17:49 |
+---------+------------------+-----------+---------+----------+----------+--------------+---------+------+-----------+------------------+---------------------+
Pool: Full
+---------+------------------+-----------+---------+----------+----------+--------------+---------+------+-----------+------------------+-------------+
| MediaId | VolumeName       | VolStatus | Enabled | VolBytes | VolFiles | VolRetention | Recycle | Slot | InChanger | MediaType        | LastWritten |
+---------+------------------+-----------+---------+----------+----------+--------------+---------+------+-----------+------------------+-------------+
| 2       | ChangerVolume002 | Append    | 1       | 214      | 0        | 31536000     | 1       | 2    | 1         | DiskChangerMedia | 0           |
| 3       | ChangerVolume003 | Append    | 1       | 214      | 0        | 31536000     | 1       | 3    | 1         | DiskChangerMedia | 0           |
+---------+------------------+-----------+---------+----------+----------+--------------+---------+------+-----------+------------------+-------------+
@#setdebug level=100 dir
@#
@# Now do a Virtual backup
@#
setdebug level=151 storage=DiskChanger
Connecting to Storage daemon DiskChanger at localhost:8103
3000 OK setdebug=151
run job=Vbackup level=VirtualFull storage=DiskChanger yes
Job queued. JobId=6
wait
messages
21-Oct 10:17 localhost-dir JobId 5: Start Restore Job RestoreFiles.2008-10-21_10.17.07
21-Oct 10:17 localhost-dir JobId 5: Using Device "Drive-0"
21-Oct 10:17 localhost-sd JobId 5: Ready to read from volume "ChangerVolume001" on device "Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0).
21-Oct 10:17 localhost-sd JobId 5: Forward spacing Volume "ChangerVolume001" to file:block 0:217.
21-Oct 10:18 localhost-sd JobId 5: End of file 0 on device "Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0), Volume "ChangerVolume001"
21-Oct 10:18 localhost-sd JobId 5: End of Volume at file 0 on device "Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0), Volume "ChangerVolume001"
21-Oct 10:18 localhost-sd JobId 5: End of all volumes.
21-Oct 10:18 localhost-dir JobId 5: Bacula localhost-dir 2.5.16 (18Oct08): 21-Oct-2008 10:18:00
  Build OS:               i686-pc-linux-gnu unknown unknown
  JobId:                  5
  Job:                    RestoreFiles.2008-10-21_10.17.07
  Restore Client:         localhost-fd
  Start time:             21-Oct-2008 10:17:53
  End time:               21-Oct-2008 10:18:00
  Files Expected:         4,414
  Files Restored:         4,414
  Bytes Restored:         73,555,187
  Rate:                   10507.9 KB/s
  FD Errors:              0
  FD termination status:  OK
  SD termination status:  OK
  Termination:            Restore OK

21-Oct 10:18 localhost-dir JobId 5: Begin pruning Jobs.
21-Oct 10:18 localhost-dir JobId 5: No Jobs found to prune.
21-Oct 10:18 localhost-dir JobId 5: Begin pruning Files.
21-Oct 10:18 localhost-dir JobId 5: No Files found to prune.
21-Oct 10:18 localhost-dir JobId 5: End auto prune.

21-Oct 10:18 localhost-dir JobId 6: Fatal error: Job canceled. Attempt to read and write same device.
    Read storage "DiskChanger" (From Job resource) -- Write storage "DiskChanger" (From Storage from Pool's NextPool resource)
list volumes
Pool: Default
+---------+------------------+-----------+---------+----------+----------+--------------+---------+------+-----------+------------------+---------------------+
| MediaId | VolumeName       | VolStatus | Enabled | VolBytes | VolFiles | VolRetention | Recycle | Slot | InChanger | MediaType        | LastWritten         |
+---------+------------------+-----------+---------+----------+----------+--------------+---------+------+-----------+------------------+---------------------+
| 1       | ChangerVolume001 | Append    | 1       | 81747415 | 0        | 31536000     | 1       | 1    | 1         | DiskChangerMedia | 2008-10-21 10:17:49 |
+---------+------------------+-----------+---------+----------+----------+--------------+---------+------+-----------+------------------+---------------------+
Pool: Full
+---------+------------------+-----------+---------+----------+----------+--------------+---------+------+-----------+------------------+-------------+
| MediaId | VolumeName       | VolStatus | Enabled | VolBytes | VolFiles | VolRetention | Recycle | Slot | InChanger | MediaType        | LastWritten |
+---------+------------------+-----------+---------+----------+----------+--------------+---------+------+-----------+------------------+-------------+
| 2       | ChangerVolume002 | Append    | 1       | 214      | 0        | 31536000     | 1       | 2    | 1         | DiskChangerMedia | 0           |
| 3       | ChangerVolume003 | Append    | 1       | 214      | 0        | 31536000     | 1       | 3    | 1         | DiskChangerMedia | 0           |
+---------+------------------+-----------+---------+----------+----------+--------------+---------+------+-----------+------------------+-------------+
list jobs
+-------+--------------+---------------------+------+-------+----------+----------+-----------+
| JobId | Name         | StartTime           | Type | Level | JobFiles | JobBytes | JobStatus |
+-------+--------------+---------------------+------+-------+----------+----------+-----------+
| 1     | Vbackup      | 2008-10-21 10:17:23 | B    | F     | 4414     | 73555187 | T         |
| 2     | Vbackup      | 2008-10-21 10:17:40 | B    | I     | 43       | 931145   | T         |
| 3     | Vbackup      | 2008-10-21 10:17:44 | B    | D     | 86       | 3648605  | T         |
| 4     | Vbackup      | 2008-10-21 10:17:48 | B    | I     | 44       | 2717489  | T         |
| 5     | RestoreFiles | 2008-10-21 10:17:53 | R    | F     | 4414     | 73555187 | T         |
| 6     | Vbackup      | 2008-10-21 10:18:02 | B    | F     | 0        | 0        | f         |
+-------+--------------+---------------------+------+-------+----------+----------+-----------+
@# 
@# now do a restore of the Virtual backup
@#
@tee /usr/bin/bacula/regress/tmp/log2.out
restore where=/usr/bin/bacula/regress/tmp/bacula-restores select storage=DiskChanger
Automatically selected Client: localhost-fd
Automatically selected FileSet: Full Set
+-------+-------+----------+----------+---------------------+------------------+
| JobId | Level | JobFiles | JobBytes | StartTime           | VolumeName       |
+-------+-------+----------+----------+---------------------+------------------+
| 1     | F     | 4414     | 73555187 | 2008-10-21 10:17:23 | ChangerVolume001 |
| 3     | D     | 86       | 3648605  | 2008-10-21 10:17:44 | ChangerVolume001 |
| 4     | I     | 44       | 2717489  | 2008-10-21 10:17:48 | ChangerVolume001 |
+-------+-------+----------+----------+---------------------+------------------+
You have selected the following JobIds: 1,3,4

Building directory tree for JobId(s) 1,3,4 ...  +++++++++++++++++++++++++++++++++++++++++++++++
4,188 files inserted into the tree.

You are now entering file selection mode where you add (mark) and
remove (unmark) files to be restored. No files are initially added, unless
you used the "all" keyword on the command line.
Enter "done" to leave this mode.

cwd is: /
$ unmark *
4,414 files unmarked.
$ mark *
4,414 files marked.
$ done
Bootstrap records written to /usr/bin/bacula/regress/working/localhost-dir.restore.2.bsr

The job will require the following
   Volume(s)                 Storage(s)                SD Device(s)
===========================================================================
   
   ChangerVolume001          DiskChanger               DiskChanger              


4,414 files selected to be restored.

Run Restore job
JobName:         RestoreFiles
Bootstrap:       /usr/bin/bacula/regress/working/localhost-dir.restore.2.bsr
Where:           /usr/bin/bacula/regress/tmp/bacula-restores
Replace:         always
FileSet:         Full Set
Backup Client:   localhost-fd
Restore Client:  localhost-fd
Storage:         DiskChanger
When:            2008-10-21 10:18:04
Catalog:         MyCatalog
Priority:        10
Plugin Options:  *None*
OK to run? (yes/mod/no): yes
Job queued. JobId=7
wait
localhost-sd: bnet.c:669-0 who=client host=127.0.0.1 port=42783
localhost-sd: dircmd.c:171-0 Conn: Hello Director localhost-dir calling
localhost-sd: dircmd.c:186-0 Got a DIR connection at 21-Oct-2008 10:18:06
localhost-sd: cram-md5.c:73-0 send: auth cram-md5 <1734946721.1224580686@localhost-sd> ssl=0
localhost-sd: cram-md5.c:133-0 cram-get received: auth cram-md5 <744262039.1224580686@localhost-dir> ssl=0
localhost-sd: cram-md5.c:152-0 sending resp to challenge: sxVqmG/VzH/jP9+Sy/03qC
localhost-sd: dircmd.c:208-0 Message channel init completed.
localhost-sd: job.c:92-0 <dird: JobId=7 job=RestoreFiles.2008-10-21_10.18.09 job_name=RestoreFiles client_name=localhost-fd type=82 level=70 FileSet=FullSet NoAttr=0 SpoolAttr=0 FileSetMD5=B5lTmCERCG+gRWNQQg/88B SpoolData=0 WritePartAfterJob=1 PreferMountedVols=1 SpoolSize=0
localhost-sd: job.c:157-7 >dird jid=7: 3000 OK Job SDid=6 SDtime=1224580637 Authorization=OIOI-NJHC-GKIJ-NCNJ-HKHC-BPFE-BPJJ-KDIC
localhost-sd: reserve.c:693-7 <dird: use storage=DiskChanger media_type=DiskChangerMedia pool_name=Default pool_type=Backup append=0 copy=0 stripe=0
localhost-sd: reserve.c:722-7 <dird device: use device=DiskChanger
localhost-sd: reserve.c:738-7 Storage=DiskChanger media_type=DiskChangerMedia pool=Default pool_type=Backup append=0
localhost-sd: reserve.c:740-7      Device=DiskChanger
localhost-sd: reserve.c:914-7 Start find_suit_dev PrefMnt=1 exact=1 suitable=0 chgronly=0 any=0
localhost-sd: reserve.c:1076-7 search res for DiskChanger
localhost-sd: reserve.c:1079-7 Try match changer res=DiskChanger
localhost-sd: reserve.c:1084-7 Try changer device Drive-0
localhost-sd: reserve.c:1147-7 chk MediaType device=DiskChangerMedia request=DiskChangerMedia
localhost-sd: reserve.c:1170-7 try reserve Drive-0
localhost-sd: reserve.c:481-7 Inc reserve=0 dev="Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0)
localhost-sd: reserve.c:1253-7 Read reserved=1 dev_name=DiskChanger mediatype=DiskChangerMedia pool=Default ok=1
localhost-sd: reserve.c:1266-7 >dird: 3000 OK use device device=Drive-0
localhost-sd: reserve.c:1100-7 Device Drive-0 reserved=1 for read.
localhost-sd: reserve.c:1045-7 available device found=DiskChanger
localhost-sd: reserve.c:1060-7 OK dev found. Vol=
localhost-sd: job.c:190-7 RestoreFiles.2008-10-21_10.18.09 waiting 1800 sec for FD to contact SD key=OIOI-NJHC-GKIJ-NCNJ-HKHC-BPFE-BPJJ-KDIC
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-10-21_10.18.09
localhost-sd: dircmd.c:177-0 Got a FD connection at 21-Oct-2008 10:18:06
localhost-sd: job.c:239-0 Found Job RestoreFiles.2008-10-21_10.18.09
localhost-sd: cram-md5.c:73-0 send: auth cram-md5 <1596940632.1224580686@localhost-sd> ssl=0
localhost-sd: cram-md5.c:133-0 cram-get received: auth cram-md5 <319664574.1224580686@localhost-fd> ssl=0
localhost-sd: cram-md5.c:152-0 sending resp to challenge: D9/NUS+hm8/euxYU0H/OcA
localhost-sd: job.c:256-0 OK Authentication jid=7 Job RestoreFiles.2008-10-21_10.18.09
localhost-sd: job.c:205-7 Auth=1 canceled=0 errstat=0
localhost-sd: job.c:211-7 Running job RestoreFiles.2008-10-21_10.18.09
localhost-sd: fd_cmds.c:122-7 Start run Job=RestoreFiles.2008-10-21_10.18.09
localhost-sd: fd_cmds.c:160-7 <filed: read open session = DummyVolume 6 1224580637 0 0 0 0
localhost-sd: fd_cmds.c:297-7 read open session = DummyVolume 6 1224580637 0 0 0 0

localhost-sd: fd_cmds.c:312-7 read_open_session got: JobId=7 Vol=DummyVolume VolSessId=6 VolSessT=1224580637
localhost-sd: fd_cmds.c:315-7   StartF=0 EndF=0 StartB=0 EndB=0
localhost-sd: fd_cmds.c:323-7 >filed: 3000 OK open ticket = 6
localhost-sd: fd_cmds.c:160-7 <filed: bootstrap
localhost-sd: fd_cmds.c:360-7 === Bootstrap file ===
localhost-sd: fd_cmds.c:362-7 Volume="ChangerVolume001"
localhost-sd: fd_cmds.c:362-7 MediaType="DiskChangerMedia"
localhost-sd: fd_cmds.c:362-7 Device="DiskChanger"
localhost-sd: fd_cmds.c:362-7 Slot=1
localhost-sd: fd_cmds.c:362-7 VolSessionId=1
localhost-sd: fd_cmds.c:362-7 VolSessionTime=1224580637
localhost-sd: fd_cmds.c:362-7 VolFile=0
localhost-sd: fd_cmds.c:362-7 VolBlock=217-74415575
localhost-sd: fd_cmds.c:362-7 FileIndex=1-25
localhost-sd: fd_cmds.c:362-7 FileIndex=28-29
localhost-sd: fd_cmds.c:362-7 FileIndex=34
localhost-sd: fd_cmds.c:362-7 FileIndex=36
localhost-sd: fd_cmds.c:362-7 FileIndex=42
localhost-sd: fd_cmds.c:362-7 FileIndex=61
localhost-sd: fd_cmds.c:362-7 FileIndex=69
localhost-sd: fd_cmds.c:362-7 FileIndex=73
localhost-sd: fd_cmds.c:362-7 FileIndex=75
localhost-sd: fd_cmds.c:362-7 FileIndex=78-80
localhost-sd: fd_cmds.c:362-7 FileIndex=124-4412
localhost-sd: fd_cmds.c:362-7 FileIndex=4414
localhost-sd: fd_cmds.c:362-7 Count=4327
localhost-sd: fd_cmds.c:362-7 Volume="ChangerVolume001"
localhost-sd: fd_cmds.c:362-7 MediaType="DiskChangerMedia"
localhost-sd: fd_cmds.c:362-7 Device="DiskChanger"
localhost-sd: fd_cmds.c:362-7 Slot=1
localhost-sd: fd_cmds.c:362-7 VolSessionId=3
localhost-sd: fd_cmds.c:362-7 VolSessionTime=1224580637
localhost-sd: fd_cmds.c:362-7 VolFile=0
localhost-sd: fd_cmds.c:362-7 VolBlock=75354814-79020457
localhost-sd: fd_cmds.c:362-7 FileIndex=1-43
localhost-sd: fd_cmds.c:362-7 Count=43
localhost-sd: fd_cmds.c:362-7 Volume="ChangerVolume001"
localhost-sd: fd_cmds.c:362-7 MediaType="DiskChangerMedia"
localhost-sd: fd_cmds.c:362-7 Device="DiskChanger"
localhost-sd: fd_cmds.c:362-7 Slot=1
localhost-sd: fd_cmds.c:362-7 VolSessionId=4
localhost-sd: fd_cmds.c:362-7 VolSessionTime=1224580637
localhost-sd: fd_cmds.c:362-7 VolFile=0
localhost-sd: fd_cmds.c:362-7 VolBlock=79020458-81747414
localhost-sd: fd_cmds.c:362-7 FileIndex=1-44
localhost-sd: fd_cmds.c:362-7 Count=44
localhost-sd: fd_cmds.c:366-7 === end bootstrap file ===
Next        : 0x80bb7d8
Root bsr    : 0x80a2ff8
VolumeName  : ChangerVolume001
  MediaType : DiskChangerMedia
  Device    : DiskChanger
  Slot      : 1
SessId      : 1
SessTime    : 1224580637
VolFile     : 0-0
VolBlock    : 217-74415575
FileIndex   : 1-25
FileIndex   : 28-29
FileIndex   : 34
FileIndex   : 36
FileIndex   : 42
FileIndex   : 61
FileIndex   : 69
FileIndex   : 73
FileIndex   : 75
FileIndex   : 78-80
FileIndex   : 124-4412
FileIndex   : 4414
count       : 4327
found       : 0
done        : no
positioning : 1
fast_reject : 1

Next        : 0x80bbae8
Root bsr    : 0x80a2ff8
VolumeName  : ChangerVolume001
  MediaType : DiskChangerMedia
  Device    : DiskChanger
  Slot      : 1
SessId      : 3
SessTime    : 1224580637
VolFile     : 0-0
VolBlock    : 75354814-79020457
FileIndex   : 1-43
count       : 43
found       : 0
done        : no
positioning : 0
fast_reject : 0

Next        : 0x0
Root bsr    : 0x80a2ff8
VolumeName  : ChangerVolume001
  MediaType : DiskChangerMedia
  Device    : DiskChanger
  Slot      : 1
SessId      : 4
SessTime    : 1224580637
VolFile     : 0-0
VolBlock    : 79020458-81747414
FileIndex   : 1-44
count       : 44
found       : 0
done        : no
positioning : 0
fast_reject : 0
localhost-sd: fd_cmds.c:160-7 <filed: read data 6
localhost-sd: fd_cmds.c:277-7 Read data: read data 6
localhost-sd: fd_cmds.c:279-7 <bfiled: read data 6
localhost-sd: read.c:59-7 Start read data.
localhost-sd: acquire.c:94-7 Want Vol=ChangerVolume001 Slot=1
localhost-sd: acquire.c:108-7 MediaType dcr=DiskChangerMedia dev=DiskChangerMedia
localhost-sd: acquire.c:186-7 dir_get_volume_info vol=ChangerVolume001
localhost-sd: askdir.c:230-7 >dird CatReq Job=RestoreFiles.2008-10-21_10.18.09 GetVolInfo VolName=ChangerVolume001 write=0
localhost-sd: askdir.c:182-7 <dird 1000 OK VolName=ChangerVolume001 VolJobs=4 VolFiles=0 VolBlocks=1269 VolBytes=81747415 VolMounts=4 VolErrors=0 VolWrites=1270 MaxVolBytes=0 VolCapacityBytes=0 VolStatus=Append Slot=1 MaxVolJobs=0 MaxVolFiles=0 InChanger=1 VolReadTime=731695 VolWriteTime=885450 EndFile=0 EndBlock=81747414 VolParts=0 LabelType=0 MediaId=1
localhost-sd: askdir.c:205-7 do_reqest_vol_info return true slot=1 Volume=ChangerVolume001
localhost-sd: mount.c:516-7 Must load "Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0)
localhost-sd: autochanger.c:133-7 autoload: slot=1 InChgr=1 Vol=ChangerVolume001
localhost-sd: autochanger.c:221-7 After changer, status=0
localhost-sd: acquire.c:217-7 bstored: open vol=ChangerVolume001
localhost-sd: dev.c:345-7 open dev: type=1 dev_name="Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0) vol=ChangerVolume001 mode=OPEN_READ_ONLY
localhost-sd: dev.c:354-7 call open_file_device mode=OPEN_READ_ONLY
localhost-sd: dev.c:526-7 open disk: mode=OPEN_READ_ONLY open(/usr/bin/bacula/regress/tmp/disk-changer/drive0, 0x0, 0640)
localhost-sd: dev.c:541-7 open dev: disk fd=8 opened, part=0/0, part_size=81748060
localhost-sd: dev.c:358-7 preserve=0x0 fd=8
localhost-sd: acquire.c:225-7 opened dev "Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0) OK
localhost-sd: acquire.c:228-7 calling read-vol-label
localhost-sd: label.c:81-7 Enter read_volume_label res=1 device="Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0) vol=ChangerVolume001 dev_Vol=*NULL*
localhost-sd: label.c:130-7 Big if statement in read_volume_label
localhost-sd: label.c:202-7 Compare Vol names: VolName=ChangerVolume001 hdr=ChangerVolume001

Volume Label:
Id                : Bacula 1.0 immortal
VerNo             : 11
VolName           : ChangerVolume001
PrevVolName       : 
VolFile           : 0
LabelType         : VOL_LABEL
LabelSize         : 181
PoolName          : Default
MediaType         : DiskChangerMedia
PoolType          : Backup
HostName          : tserv
Date label written: 21-Oct-2008 10:17
localhost-sd: label.c:223-7 Leave read_volume_label() VOL_OK
localhost-sd: label.c:236-7 Call reserve_volume=ChangerVolume001
localhost-sd: reserve.c:314-7 enter reserve_volume=ChangerVolume001 drive="Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0)
localhost-sd: reserve.c:187-7 List begin reserve_volume: ChangerVolume001 in_use=0 on device "Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0)
localhost-sd: reserve.c:329-7 Vol attached=ChangerVolume001, newvol=ChangerVolume001 volinuse=0 on "Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0)
localhost-sd: reserve.c:337-7 === set reserved vol=ChangerVolume001 dev="Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0)
localhost-sd: reserve.c:418-7 === set in_use. vol=ChangerVolume001 dev="Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0)
localhost-sd: reserve.c:187-7 List end new volume: ChangerVolume001 in_use=1 on device "Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0)
localhost-sd: acquire.c:232-7 Got correct volume.
localhost-sd: reserve.c:490-7 Dec reserve=0 dev="Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0)
localhost-sd: dev.c:1622-7 ===== lseek to 217
localhost-sd: reserve.c:553-7 === set not reserved vol=ChangerVolume001 num_writers=0 dev_reserved=0 dev="Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0)
localhost-sd: reserve.c:554-7 === clear in_use vol=ChangerVolume001
localhost-sd: mount.c:796-7 NumReadVolumes=1 CurReadVolume=1
localhost-sd: reserve.c:553-7 === set not reserved vol=ChangerVolume001 num_writers=0 dev_reserved=0 dev="Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0)
localhost-sd: reserve.c:554-7 === clear in_use vol=ChangerVolume001
localhost-sd: mount.c:811-7 End of Device reached.
localhost-sd: acquire.c:427-7 release_device device "Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0) is disk
localhost-sd: acquire.c:436-7 dir_update_vol_info. label=64 Vol=ChangerVolume001
localhost-sd: askdir.c:345-7 Update cat VolFiles=0
localhost-sd: askdir.c:368-7 >dird CatReq Job=RestoreFiles.2008-10-21_10.18.09 UpdateMedia VolName=ChangerVolume001 VolJobs=4 VolFiles=0 VolBlocks=1269 VolBytes=81747415 VolMounts=4 VolErrors=0 VolWrites=1270 MaxVolBytes=0 EndTime=1224580693 VolStatus=Append Slot=1 relabel=0 InChanger=1 VolReadTime=1460417 VolWriteTime=885450 VolFirstWritten=0 VolParts=0
localhost-sd: askdir.c:182-7 <dird 1000 OK VolName=ChangerVolume001 VolJobs=4 VolFiles=0 VolBlocks=1269 VolBytes=81747415 VolMounts=4 VolErrors=0 VolWrites=1270 MaxVolBytes=0 VolCapacityBytes=0 VolStatus=Append Slot=1 MaxVolJobs=0 MaxVolFiles=0 InChanger=1 VolReadTime=1460417 VolWriteTime=885450 EndFile=0 EndBlock=81747414 VolParts=0 LabelType=0 MediaId=1
localhost-sd: askdir.c:205-7 do_reqest_vol_info return true slot=1 Volume=ChangerVolume001
localhost-sd: reserve.c:553-7 === set not reserved vol=ChangerVolume001 num_writers=0 dev_reserved=0 dev="Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0)
localhost-sd: reserve.c:554-7 === clear in_use vol=ChangerVolume001
localhost-sd: acquire.c:484-7 0 writers, 0 reserve, dev="Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0)
localhost-sd: reserve.c:187-7 List acquire:release_device(): ChangerVolume001 in_use=0 on device "Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0)
localhost-sd: dev.c:1902-7 close_dev "Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0)
localhost-sd: dev.c:1892-7 Clear volhdr vol=ChangerVolume001
localhost-sd: acquire.c:522-7 JobId=7 broadcast wait_device_release at 21-Oct-2008 10:18:13
localhost-sd: acquire.c:537-7 ===== Device "Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0) released by JobId=7
localhost-sd: read.c:96-7 Done reading.
localhost-sd: fd_cmds.c:160-7 <filed: read close session 6
localhost-sd: fd_cmds.c:397-7 Read close session: read close session 6

localhost-sd: jcr.c:184-7 write_last_jobs seek to 188
You have messages.
@# Move Volume to Default pool
update Volume=ChangerVolume002
Parameters to modify:
     1: Volume Status
     2: Volume Retention Period
     3: Volume Use Duration
     4: Maximum Volume Jobs
     5: Maximum Volume Files
     6: Maximum Volume Bytes
     7: Recycle Flag
     8: Slot
     9: InChanger Flag
    10: Volume Files
    11: Pool
    12: Volume from Pool
    13: All Volumes from Pool
    14: All Volumes from all Pools
    15: Enabled
    16: RecyclePool
    17: Done
Select parameter to modify (1-17): 11
Updating Volume "ChangerVolume002"
Current Pool is: Full
Enter new Pool name: Default
New Pool is: Default
list volumes
Pool: Default
+---------+------------------+-----------+---------+----------+----------+--------------+---------+------+-----------+------------------+---------------------+
| MediaId | VolumeName       | VolStatus | Enabled | VolBytes | VolFiles | VolRetention | Recycle | Slot | InChanger | MediaType        | LastWritten         |
+---------+------------------+-----------+---------+----------+----------+--------------+---------+------+-----------+------------------+---------------------+
| 1       | ChangerVolume001 | Append    | 1       | 81747415 | 0        | 31536000     | 1       | 1    | 1         | DiskChangerMedia | 2008-10-21 10:17:49 |
| 2       | ChangerVolume002 | Append    | 1       | 214      | 0        | 31536000     | 1       | 2    | 1         | DiskChangerMedia | 0                   |
+---------+------------------+-----------+---------+----------+----------+--------------+---------+------+-----------+------------------+---------------------+
Pool: Full
+---------+------------------+-----------+---------+----------+----------+--------------+---------+------+-----------+------------------+-------------+
| MediaId | VolumeName       | VolStatus | Enabled | VolBytes | VolFiles | VolRetention | Recycle | Slot | InChanger | MediaType        | LastWritten |
+---------+------------------+-----------+---------+----------+----------+--------------+---------+------+-----------+------------------+-------------+
| 3       | ChangerVolume003 | Append    | 1       | 214      | 0        | 31536000     | 1       | 3    | 1         | DiskChangerMedia | 0           |
+---------+------------------+-----------+---------+----------+----------+--------------+---------+------+-----------+------------------+-------------+
list jobs
+-------+--------------+---------------------+------+-------+----------+----------+-----------+
| JobId | Name         | StartTime           | Type | Level | JobFiles | JobBytes | JobStatus |
+-------+--------------+---------------------+------+-------+----------+----------+-----------+
| 1     | Vbackup      | 2008-10-21 10:17:23 | B    | F     | 4414     | 73555187 | T         |
| 2     | Vbackup      | 2008-10-21 10:17:40 | B    | I     | 43       | 931145   | T         |
| 3     | Vbackup      | 2008-10-21 10:17:44 | B    | D     | 86       | 3648605  | T         |
| 4     | Vbackup      | 2008-10-21 10:17:48 | B    | I     | 44       | 2717489  | T         |
| 5     | RestoreFiles | 2008-10-21 10:17:53 | R    | F     | 4414     | 73555187 | T         |
| 6     | Vbackup      | 2008-10-21 10:18:02 | B    | F     | 0        | 0        | f         |
| 7     | RestoreFiles | 2008-10-21 10:18:06 | R    | F     | 4414     | 73555187 | T         |
+-------+--------------+---------------------+------+-------+----------+----------+-----------+
messages
21-Oct 10:18 localhost-dir JobId 7: Start Restore Job RestoreFiles.2008-10-21_10.18.09
21-Oct 10:18 localhost-dir JobId 7: Using Device "Drive-0"
21-Oct 10:18 localhost-sd JobId 7: Ready to read from volume "ChangerVolume001" on device "Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0).
21-Oct 10:18 localhost-sd JobId 7: Forward spacing Volume "ChangerVolume001" to file:block 0:217.
21-Oct 10:18 localhost-sd JobId 7: End of file 0 on device "Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0), Volume "ChangerVolume001"
21-Oct 10:18 localhost-sd JobId 7: End of Volume at file 0 on device "Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0), Volume "ChangerVolume001"
21-Oct 10:18 localhost-sd JobId 7: End of all volumes.
21-Oct 10:18 localhost-dir JobId 7: Bacula localhost-dir 2.5.16 (18Oct08): 21-Oct-2008 10:18:13
  Build OS:               i686-pc-linux-gnu unknown unknown
  JobId:                  7
  Job:                    RestoreFiles.2008-10-21_10.18.09
  Restore Client:         localhost-fd
  Start time:             21-Oct-2008 10:18:06
  End time:               21-Oct-2008 10:18:13
  Files Expected:         4,414
  Files Restored:         4,414
  Bytes Restored:         73,555,187
  Rate:                   10507.9 KB/s
  FD Errors:              0
  FD termination status:  OK
  SD termination status:  OK
  Termination:            Restore OK

21-Oct 10:18 localhost-dir JobId 7: Begin pruning Jobs.
21-Oct 10:18 localhost-dir JobId 7: No Jobs found to prune.
21-Oct 10:18 localhost-dir JobId 7: Begin pruning Files.
21-Oct 10:18 localhost-dir JobId 7: No Files found to prune.
21-Oct 10:18 localhost-dir JobId 7: End auto prune.

@exec "sh -c 'touch /usr/bin/bacula/regress/build/src/dird/*.o'"
@#
@# Do an incremental on top of the Virtual Full
@#
run job=Vbackup level=Incremental storage=DiskChanger yes
Job queued. JobId=8
wait
localhost-sd: bnet.c:669-0 who=client host=127.0.0.1 port=42783
localhost-sd: dircmd.c:171-0 Conn: Hello Director localhost-dir calling
localhost-sd: dircmd.c:186-0 Got a DIR connection at 21-Oct-2008 10:18:16
localhost-sd: cram-md5.c:73-0 send: auth cram-md5 <1376031652.1224580696@localhost-sd> ssl=0
localhost-sd: cram-md5.c:133-0 cram-get received: auth cram-md5 <1837124357.1224580696@localhost-dir> ssl=0
localhost-sd: cram-md5.c:152-0 sending resp to challenge: /lxYkz/LpR/cY7oF26/ylD
localhost-sd: dircmd.c:208-0 Message channel init completed.
localhost-sd: job.c:92-0 <dird: JobId=8 job=Vbackup.2008-10-21_10.18.10 job_name=Vbackup client_name=localhost-fd type=66 level=73 FileSet=FullSet NoAttr=0 SpoolAttr=0 FileSetMD5=B5lTmCERCG+gRWNQQg/88B SpoolData=1 WritePartAfterJob=1 PreferMountedVols=1 SpoolSize=0
localhost-sd: job.c:157-8 >dird jid=8: 3000 OK Job SDid=7 SDtime=1224580637 Authorization=MCAB-MNNI-JFLC-HAKJ-CMBC-KJKO-HKEB-MDPN
localhost-sd: reserve.c:693-8 <dird: use storage=DiskChanger media_type=DiskChangerMedia pool_name=Default pool_type=Backup append=1 copy=0 stripe=0
localhost-sd: reserve.c:722-8 <dird device: use device=DiskChanger
localhost-sd: reserve.c:738-8 Storage=DiskChanger media_type=DiskChangerMedia pool=Default pool_type=Backup append=1
localhost-sd: reserve.c:740-8      Device=DiskChanger
localhost-sd: reserve.c:914-8 Start find_suit_dev PrefMnt=1 exact=1 suitable=0 chgronly=0 any=0
localhost-sd: reserve.c:926-8 lock volumes
localhost-sd: reserve.c:937-8 duplicate vol list
localhost-sd: reserve.c:953-8 unlock volumes
localhost-sd: reserve.c:957-8 look for vol in vol list
localhost-sd: askdir.c:230-8 >dird CatReq Job=Vbackup.2008-10-21_10.18.10 GetVolInfo VolName=ChangerVolume001 write=1
localhost-sd: askdir.c:182-8 <dird 1000 OK VolName=ChangerVolume001 VolJobs=4 VolFiles=0 VolBlocks=1269 VolBytes=81747415 VolMounts=4 VolErrors=0 VolWrites=1270 MaxVolBytes=0 VolCapacityBytes=0 VolStatus=Append Slot=1 MaxVolJobs=0 MaxVolFiles=0 InChanger=1 VolReadTime=1460417 VolWriteTime=885450 EndFile=0 EndBlock=81747414 VolParts=0 LabelType=0 MediaId=1
localhost-sd: askdir.c:205-8 do_reqest_vol_info return true slot=1 Volume=ChangerVolume001
localhost-sd: reserve.c:969-8 vol=ChangerVolume001 OK for this job
localhost-sd: reserve.c:979-8 vol=ChangerVolume001 is in changer
localhost-sd: reserve.c:885-8 Found changer device Drive-0
localhost-sd: reserve.c:992-8 try vol=ChangerVolume001 on device=DiskChanger
localhost-sd: reserve.c:1147-8 chk MediaType device=DiskChangerMedia request=DiskChangerMedia
localhost-sd: reserve.c:1170-8 try reserve Drive-0
localhost-sd: reserve.c:1183-8 call reserve for append: have_vol=1 vol=ChangerVolume001
localhost-sd: reserve.c:1367-8 reserve_append device is "Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0)
localhost-sd: reserve.c:1444-8 PrefMnt=1 exact=1 suitable=1 chgronly=0 any=0
localhost-sd: reserve.c:1416-8 MaxJobs=0 Jobs=4 reserves=0 Status=Append Vol=ChangerVolume001
localhost-sd: reserve.c:1499-8 PrefMnt=1 exact=1 suitable=1 chgronly=0 any=0
localhost-sd: reserve.c:1502-8 have_vol=1 have= resvol=ChangerVolume001 want=ChangerVolume001
localhost-sd: reserve.c:472-8 find_vol=ChangerVolume001 found=1
localhost-sd: reserve.c:187-8 List find_volume: ChangerVolume001 in_use=0 on device "Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0)
localhost-sd: reserve.c:639-8 Vol=ChangerVolume001 on same dev.
localhost-sd: reserve.c:1548-8 OK Dev avail reserved "Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0)
localhost-sd: reserve.c:481-8 Inc reserve=0 dev="Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0)
localhost-sd: reserve.c:1192-8 Reserved=1 dev_name=DiskChanger mediatype=DiskChangerMedia pool=Default ok=1
localhost-sd: reserve.c:1194-8 Vol=ChangerVolume001 num_writers=0, have_vol=1
localhost-sd: reserve.c:1196-8 Call reserve_volume
localhost-sd: reserve.c:314-8 enter reserve_volume=ChangerVolume001 drive="Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0)
localhost-sd: reserve.c:187-8 List begin reserve_volume: ChangerVolume001 in_use=0 on device "Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0)
localhost-sd: reserve.c:329-8 Vol attached=ChangerVolume001, newvol=ChangerVolume001 volinuse=0 on "Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0)
localhost-sd: reserve.c:337-8 === set reserved vol=ChangerVolume001 dev="Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0)
localhost-sd: reserve.c:418-8 === set in_use. vol=ChangerVolume001 dev="Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0)
localhost-sd: reserve.c:187-8 List end new volume: ChangerVolume001 in_use=1 on device "Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0)
localhost-sd: reserve.c:1198-8 Reserved vol=ChangerVolume001
localhost-sd: reserve.c:1266-8 >dird: 3000 OK use device device=Drive-0
localhost-sd: reserve.c:995-8 Suitable device found=DiskChanger
localhost-sd: reserve.c:1016-8 lock volumes
localhost-sd: reserve.c:613-8 free vol_list Volume=ChangerVolume001 dev="Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0)
localhost-sd: reserve.c:1022-8 deleted temp vol list
localhost-sd: reserve.c:1023-8 unlock volumes
localhost-sd: reserve.c:187-8 List after free temp table: ChangerVolume001 in_use=1 on device "Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0)
localhost-sd: reserve.c:1028-8 OK dev found. Vol=ChangerVolume001 from in-use vols list
localhost-sd: job.c:190-8 Vbackup.2008-10-21_10.18.10 waiting 1800 sec for FD to contact SD key=MCAB-MNNI-JFLC-HAKJ-CMBC-KJKO-HKEB-MDPN
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 Vbackup.2008-10-21_10.18.10
localhost-sd: dircmd.c:177-0 Got a FD connection at 21-Oct-2008 10:18:17
localhost-sd: job.c:239-0 Found Job Vbackup.2008-10-21_10.18.10
localhost-sd: cram-md5.c:73-0 send: auth cram-md5 <230308380.1224580697@localhost-sd> ssl=0
localhost-sd: cram-md5.c:133-0 cram-get received: auth cram-md5 <96017054.1224580697@localhost-fd> ssl=0
localhost-sd: cram-md5.c:152-0 sending resp to challenge: X+/a84+trx/056+sl9/spC
localhost-sd: job.c:256-0 OK Authentication jid=8 Job Vbackup.2008-10-21_10.18.10
localhost-sd: job.c:205-8 Auth=1 canceled=0 errstat=0
localhost-sd: job.c:211-8 Running job Vbackup.2008-10-21_10.18.10
localhost-sd: fd_cmds.c:122-8 Start run Job=Vbackup.2008-10-21_10.18.10
localhost-sd: fd_cmds.c:160-8 <filed: append open session
localhost-sd: fd_cmds.c:228-8 Append open session: append open session
localhost-sd: fd_cmds.c:238-8 >filed: 3000 OK open ticket = 7
localhost-sd: fd_cmds.c:160-8 <filed: append data 7
localhost-sd: fd_cmds.c:190-8 Append data: append data 7
localhost-sd: fd_cmds.c:192-8 <bfiled: append data 7
localhost-sd: append.c:73-8 Start append data. res=1
localhost-sd: acquire.c:346-8 acquire_append device is disk
localhost-sd: mount.c:77-8 Enter mount_next_volume(release=0) dev="Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0)
localhost-sd: mount.c:88-8 mount_next_vol retry=0
localhost-sd: askdir.c:230-8 >dird CatReq Job=Vbackup.2008-10-21_10.18.10 GetVolInfo VolName=ChangerVolume001 write=1
localhost-sd: askdir.c:182-8 <dird 1000 OK VolName=ChangerVolume001 VolJobs=4 VolFiles=0 VolBlocks=1269 VolBytes=81747415 VolMounts=4 VolErrors=0 VolWrites=1270 MaxVolBytes=0 VolCapacityBytes=0 VolStatus=Append Slot=1 MaxVolJobs=0 MaxVolFiles=0 InChanger=1 VolReadTime=1460417 VolWriteTime=885450 EndFile=0 EndBlock=81747414 VolParts=0 LabelType=0 MediaId=1
localhost-sd: askdir.c:205-8 do_reqest_vol_info return true slot=1 Volume=ChangerVolume001
localhost-sd: mount.c:128-8 After find_next_append. Vol=ChangerVolume001 Slot=1 Parts=0
localhost-sd: autochanger.c:133-8 autoload: slot=1 InChgr=1 Vol=ChangerVolume001
localhost-sd: autochanger.c:221-8 After changer, status=0
localhost-sd: mount.c:149-8 autoload_dev returns 1
localhost-sd: mount.c:179-8 want vol=ChangerVolume001 devvol= dev="Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0)
localhost-sd: dev.c:345-8 open dev: type=1 dev_name="Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0) vol=ChangerVolume001 mode=OPEN_READ_WRITE
localhost-sd: dev.c:354-8 call open_file_device mode=OPEN_READ_WRITE
localhost-sd: dev.c:526-8 open disk: mode=OPEN_READ_WRITE open(/usr/bin/bacula/regress/tmp/disk-changer/drive0, 0x2, 0640)
localhost-sd: dev.c:541-8 open dev: disk fd=8 opened, part=0/0, part_size=81748060
localhost-sd: dev.c:358-8 preserve=0x0 fd=8
localhost-sd: label.c:81-8 Enter read_volume_label res=1 device="Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0) vol=ChangerVolume001 dev_Vol=*NULL*
localhost-sd: label.c:130-8 Big if statement in read_volume_label
localhost-sd: label.c:202-8 Compare Vol names: VolName=ChangerVolume001 hdr=ChangerVolume001

Volume Label:
Id                : Bacula 1.0 immortal
VerNo             : 11
VolName           : ChangerVolume001
PrevVolName       : 
VolFile           : 0
LabelType         : VOL_LABEL
LabelSize         : 181
PoolName          : Default
MediaType         : DiskChangerMedia
PoolType          : Backup
HostName          : tserv
Date label written: 21-Oct-2008 10:17
localhost-sd: label.c:223-8 Leave read_volume_label() VOL_OK
localhost-sd: label.c:236-8 Call reserve_volume=ChangerVolume001
localhost-sd: reserve.c:314-8 enter reserve_volume=ChangerVolume001 drive="Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0)
localhost-sd: reserve.c:187-8 List begin reserve_volume: ChangerVolume001 in_use=1 on device "Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0)
localhost-sd: reserve.c:329-8 Vol attached=ChangerVolume001, newvol=ChangerVolume001 volinuse=1 on "Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0)
localhost-sd: reserve.c:337-8 === set reserved vol=ChangerVolume001 dev="Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0)
localhost-sd: reserve.c:418-8 === set in_use. vol=ChangerVolume001 dev="Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0)
localhost-sd: reserve.c:187-8 List end new volume: ChangerVolume001 in_use=1 on device "Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0)
localhost-sd: mount.c:363-8 Want dirVol=ChangerVolume001 dirStat=Append
localhost-sd: mount.c:370-8 Vol OK name=ChangerVolume001
localhost-sd: dev.c:879-8 eod
localhost-sd: mount.c:283-8 update volinfo mounts=5
localhost-sd: askdir.c:345-8 Update cat VolFiles=0
localhost-sd: askdir.c:368-8 >dird CatReq Job=Vbackup.2008-10-21_10.18.10 UpdateMedia VolName=ChangerVolume001 VolJobs=4 VolFiles=0 VolBlocks=1269 VolBytes=81747415 VolMounts=5 VolErrors=0 VolWrites=1270 MaxVolBytes=0 EndTime=1224580697 VolStatus=Append Slot=1 relabel=0 InChanger=1 VolReadTime=1460417 VolWriteTime=885450 VolFirstWritten=0 VolParts=0
localhost-sd: askdir.c:182-8 <dird 1000 OK VolName=ChangerVolume001 VolJobs=4 VolFiles=0 VolBlocks=1269 VolBytes=81747415 VolMounts=5 VolErrors=0 VolWrites=1270 MaxVolBytes=0 VolCapacityBytes=0 VolStatus=Append Slot=1 MaxVolJobs=0 MaxVolFiles=0 InChanger=1 VolReadTime=1460417 VolWriteTime=885450 EndFile=0 EndBlock=81747414 VolParts=0 LabelType=0 MediaId=1
localhost-sd: askdir.c:205-8 do_reqest_vol_info return true slot=1 Volume=ChangerVolume001
localhost-sd: mount.c:293-8 set APPEND, normal return from mount_next_write_volume. dev="Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0)
localhost-sd: askdir.c:345-8 Update cat VolFiles=0
localhost-sd: askdir.c:368-8 >dird CatReq Job=Vbackup.2008-10-21_10.18.10 UpdateMedia VolName=ChangerVolume001 VolJobs=5 VolFiles=0 VolBlocks=1269 VolBytes=81747415 VolMounts=5 VolErrors=0 VolWrites=1270 MaxVolBytes=0 EndTime=1224580697 VolStatus=Append Slot=1 relabel=0 InChanger=1 VolReadTime=1460417 VolWriteTime=885450 VolFirstWritten=0 VolParts=0
localhost-sd: askdir.c:182-8 <dird 1000 OK VolName=ChangerVolume001 VolJobs=5 VolFiles=0 VolBlocks=1269 VolBytes=81747415 VolMounts=5 VolErrors=0 VolWrites=1270 MaxVolBytes=0 VolCapacityBytes=0 VolStatus=Append Slot=1 MaxVolJobs=0 MaxVolFiles=0 InChanger=1 VolReadTime=1460417 VolWriteTime=885450 EndFile=0 EndBlock=81747414 VolParts=0 LabelType=0 MediaId=1
localhost-sd: askdir.c:205-8 do_reqest_vol_info return true slot=1 Volume=ChangerVolume001
localhost-sd: reserve.c:490-8 Dec reserve=0 dev="Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0)
localhost-sd: append.c:96-8 Begin append device="Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0)
localhost-sd: spool.c:108-8 Turning on data spooling
localhost-sd: spool.c:177-8 Created spool file: /usr/bin/bacula/regress/working/localhost-sd.data.8.Vbackup.2008-10-21_10.18.10.Drive-0.spool
localhost-sd: append.c:101-8 Just after acquire_device_for_append
localhost-sd: label.c:704-8 session_label record=80bad98
localhost-sd: label.c:749-8 Write sesson_label record JobId=8 FI=SOS_LABEL SessId=7 Strm=8 len=149 remainder=0
localhost-sd: label.c:753-8 Leave write_session_label Block=81747415d File=0d
localhost-sd: fd_cmds.c:160-8 <filed: append end session 7
localhost-sd: fd_cmds.c:210-8 store<file: append end session 7
localhost-sd: fd_cmds.c:160-8 <filed: append close session 7
localhost-sd: fd_cmds.c:252-8 <filed: append close session 7
localhost-sd: fd_cmds.c:259-8 >filed: 3000 OK close Status = 84
localhost-sd: label.c:704-8 session_label record=80bad98
localhost-sd: label.c:749-8 Write sesson_label record JobId=8 FI=EOS_LABEL SessId=7 Strm=8 len=185 remainder=0
localhost-sd: label.c:753-8 Leave write_session_label Block=81747415d File=0d
localhost-sd: append.c:301-8 back from write_end_session_label()
localhost-sd: spool.c:136-8 Committing spooled data
localhost-sd: spool.c:223-8 Despooling data
localhost-sd: spool.c:385-8 EOT on spool read.
localhost-sd: askdir.c:412-8 >dird CatReq Job=Vbackup.2008-10-21_10.18.10 CreateJobMedia FirstIndex=1 LastIndex=43 StartFile=0 EndFile=0 StartBlock=81747415 EndBlock=84474193 Copy=0 Strip=0 MediaId=1
localhost-sd: askdir.c:419-8 <dird 1000 OK CreateJobMedia
localhost-sd: spool.c:202-8 Deleted spool file: /usr/bin/bacula/regress/working/localhost-sd.data.8.Vbackup.2008-10-21_10.18.10.Drive-0.spool
localhost-sd: acquire.c:427-8 release_device device "Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0) is disk
localhost-sd: acquire.c:449-8 There are 0 writers in release_device
localhost-sd: dev.c:1690-8 === weof_dev="Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0)
localhost-sd: askdir.c:345-8 Update cat VolFiles=0
localhost-sd: askdir.c:368-8 >dird CatReq Job=Vbackup.2008-10-21_10.18.10 UpdateMedia VolName=ChangerVolume001 VolJobs=5 VolFiles=0 VolBlocks=1312 VolBytes=84474194 VolMounts=5 VolErrors=0 VolWrites=1313 MaxVolBytes=0 EndTime=1224580698 VolStatus=Append Slot=1 relabel=0 InChanger=1 VolReadTime=1460417 VolWriteTime=916949 VolFirstWritten=0 VolParts=0
localhost-sd: askdir.c:182-8 <dird 1000 OK VolName=ChangerVolume001 VolJobs=5 VolFiles=0 VolBlocks=1312 VolBytes=84474194 VolMounts=5 VolErrors=0 VolWrites=1313 MaxVolBytes=0 VolCapacityBytes=0 VolStatus=Append Slot=1 MaxVolJobs=0 MaxVolFiles=0 InChanger=1 VolReadTime=1460417 VolWriteTime=916949 EndFile=0 EndBlock=84474193 VolParts=0 LabelType=0 MediaId=1
localhost-sd: askdir.c:205-8 do_reqest_vol_info return true slot=1 Volume=ChangerVolume001
localhost-sd: reserve.c:553-8 === set not reserved vol=ChangerVolume001 num_writers=0 dev_reserved=0 dev="Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0)
localhost-sd: reserve.c:554-8 === clear in_use vol=ChangerVolume001
localhost-sd: acquire.c:484-8 0 writers, 0 reserve, dev="Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0)
localhost-sd: reserve.c:187-8 List acquire:release_device(): ChangerVolume001 in_use=0 on device "Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0)
localhost-sd: dev.c:1902-8 close_dev "Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0)
localhost-sd: dev.c:1892-8 Clear volhdr vol=ChangerVolume001
localhost-sd: acquire.c:522-8 JobId=8 broadcast wait_device_release at 21-Oct-2008 10:18:18
localhost-sd: acquire.c:537-8 ===== Device "Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0) released by JobId=8
localhost-sd: spool.c:630-8 Commit attributes at 21-Oct-2008 10:18:18
localhost-sd: spool.c:699-8 Close attr spool file at 21-Oct-2008 10:18:18
localhost-sd: append.c:341-8 return from do_append_data() ok=1
localhost-sd: jcr.c:184-8 write_last_jobs seek to 188
You have messages.
messages
21-Oct 10:18 localhost-dir JobId 8: Start Backup JobId 8, Job=Vbackup.2008-10-21_10.18.10
21-Oct 10:18 localhost-dir JobId 8: Using Device "Drive-0"
21-Oct 10:18 localhost-sd JobId 8: Volume "ChangerVolume001" previously written, moving to end of data.
21-Oct 10:18 localhost-sd JobId 8: Ready to append to end of Volume "ChangerVolume001" size=81747415
21-Oct 10:18 localhost-sd JobId 8: Spooling data ...
21-Oct 10:18 localhost-sd JobId 8: Job write elapsed time = 00:00:01, Transfer rate = 2.723 M bytes/second
21-Oct 10:18 localhost-sd JobId 8: Committing spooled data to Volume "ChangerVolume001". Despooling 2,727,295 bytes ...
21-Oct 10:18 localhost-sd JobId 8: Despooling elapsed time = 00:00:01, Transfer rate = 2.727 M bytes/second
21-Oct 10:18 localhost-sd JobId 8: Sending spooled attrs to the Director. Despooling 12,393 bytes ...
21-Oct 10:18 localhost-dir JobId 8: Bacula localhost-dir 2.5.16 (18Oct08): 21-Oct-2008 10:18:18
  Build OS:               i686-pc-linux-gnu unknown unknown
  JobId:                  8
  Job:                    Vbackup.2008-10-21_10.18.10
  Backup Level:           Incremental, since=2008-10-21 10:17:48
  Client:                 "localhost-fd" 2.5.16 (18Oct08) i686-pc-linux-gnu,unknown,unknown
  FileSet:                "Full Set" 2008-10-21 10:17:20
  Pool:                   "Default" (From Job resource)
  Catalog:                "MyCatalog" (From Client resource)
  Storage:                "DiskChanger" (From command line)
  Scheduled time:         21-Oct-2008 10:18:14
  Start time:             21-Oct-2008 10:18:17
  End time:               21-Oct-2008 10:18:18
  Elapsed time:           1 sec
  Priority:               10
  FD Files Written:       43
  SD Files Written:       43
  FD Bytes Written:       2,717,460 (2.717 MB)
  SD Bytes Written:       2,723,145 (2.723 MB)
  Rate:                   2717.5 KB/s
  Software Compression:   None
  VSS:                    no
  Encryption:             no
  Accurate:               no
  Volume name(s):         ChangerVolume001
  Volume Session Id:      7
  Volume Session Time:    1224580637
  Last Volume Bytes:      84,474,194 (84.47 MB)
  Non-fatal FD errors:    0
  SD Errors:              0
  FD termination status:  OK
  SD termination status:  OK
  Termination:            Backup OK

21-Oct 10:18 localhost-dir JobId 8: Begin pruning Jobs.
21-Oct 10:18 localhost-dir JobId 8: No Jobs found to prune.
21-Oct 10:18 localhost-dir JobId 8: Begin pruning Files.
21-Oct 10:18 localhost-dir JobId 8: No Files found to prune.
21-Oct 10:18 localhost-dir JobId 8: End auto prune.

list jobs
+-------+--------------+---------------------+------+-------+----------+----------+-----------+
| JobId | Name         | StartTime           | Type | Level | JobFiles | JobBytes | JobStatus |
+-------+--------------+---------------------+------+-------+----------+----------+-----------+
| 1     | Vbackup      | 2008-10-21 10:17:23 | B    | F     | 4414     | 73555187 | T         |
| 2     | Vbackup      | 2008-10-21 10:17:40 | B    | I     | 43       | 931145   | T         |
| 3     | Vbackup      | 2008-10-21 10:17:44 | B    | D     | 86       | 3648605  | T         |
| 4     | Vbackup      | 2008-10-21 10:17:48 | B    | I     | 44       | 2717489  | T         |
| 5     | RestoreFiles | 2008-10-21 10:17:53 | R    | F     | 4414     | 73555187 | T         |
| 6     | Vbackup      | 2008-10-21 10:18:02 | B    | F     | 0        | 0        | f         |
| 7     | RestoreFiles | 2008-10-21 10:18:06 | R    | F     | 4414     | 73555187 | T         |
| 8     | Vbackup      | 2008-10-21 10:18:17 | B    | I     | 43       | 2717460  | T         |
+-------+--------------+---------------------+------+-------+----------+----------+-----------+
list volumes
Pool: Default
+---------+------------------+-----------+---------+----------+----------+--------------+---------+------+-----------+------------------+---------------------+
| MediaId | VolumeName       | VolStatus | Enabled | VolBytes | VolFiles | VolRetention | Recycle | Slot | InChanger | MediaType        | LastWritten         |
+---------+------------------+-----------+---------+----------+----------+--------------+---------+------+-----------+------------------+---------------------+
| 1       | ChangerVolume001 | Append    | 1       | 84474194 | 0        | 31536000     | 1       | 1    | 1         | DiskChangerMedia | 2008-10-21 10:18:18 |
| 2       | ChangerVolume002 | Append    | 1       | 214      | 0        | 31536000     | 1       | 2    | 1         | DiskChangerMedia | 0                   |
+---------+------------------+-----------+---------+----------+----------+--------------+---------+------+-----------+------------------+---------------------+
Pool: Full
+---------+------------------+-----------+---------+----------+----------+--------------+---------+------+-----------+------------------+-------------+
| MediaId | VolumeName       | VolStatus | Enabled | VolBytes | VolFiles | VolRetention | Recycle | Slot | InChanger | MediaType        | LastWritten |
+---------+------------------+-----------+---------+----------+----------+--------------+---------+------+-----------+------------------+-------------+
| 3       | ChangerVolume003 | Append    | 1       | 214      | 0        | 31536000     | 1       | 3    | 1         | DiskChangerMedia | 0           |
+---------+------------------+-----------+---------+----------+----------+--------------+---------+------+-----------+------------------+-------------+
@#
@# Now do another Consolidation
@#
setdebug level=150 storage=DiskChanger
Connecting to Storage daemon DiskChanger at localhost:8103
localhost-sd: bnet.c:669-0 who=client host=127.0.0.1 port=42783
localhost-sd: dircmd.c:171-0 Conn: Hello Director localhost-dir calling
localhost-sd: dircmd.c:186-0 Got a DIR connection at 21-Oct-2008 10:18:19
localhost-sd: cram-md5.c:73-0 send: auth cram-md5 <746449674.1224580699@localhost-sd> ssl=0
localhost-sd: cram-md5.c:133-0 cram-get received: auth cram-md5 <1813495190.1224580699@localhost-dir> ssl=0
localhost-sd: cram-md5.c:152-0 sending resp to challenge: x4/QiCcOG5NhFj/3cxAyIA
localhost-sd: dircmd.c:208-0 Message channel init completed.
localhost-sd: dircmd.c:278-0 setdebug_cmd: setdebug=150 trace=-1
3000 OK setdebug=150
run job=Vbackup level=VirtualFull storage=DiskChanger yes
Job queued. JobId=9
wait
You have messages.
messages
21-Oct 10:18 localhost-dir JobId 9: Fatal error: Job canceled. Attempt to read and write same device.
    Read storage "DiskChanger" (From Job resource) -- Write storage "DiskChanger" (From Storage from Pool's NextPool resource)
list volumes
Pool: Default
+---------+------------------+-----------+---------+----------+----------+--------------+---------+------+-----------+------------------+---------------------+
| MediaId | VolumeName       | VolStatus | Enabled | VolBytes | VolFiles | VolRetention | Recycle | Slot | InChanger | MediaType        | LastWritten         |
+---------+------------------+-----------+---------+----------+----------+--------------+---------+------+-----------+------------------+---------------------+
| 1       | ChangerVolume001 | Append    | 1       | 84474194 | 0        | 31536000     | 1       | 1    | 1         | DiskChangerMedia | 2008-10-21 10:18:18 |
| 2       | ChangerVolume002 | Append    | 1       | 214      | 0        | 31536000     | 1       | 2    | 1         | DiskChangerMedia | 0                   |
+---------+------------------+-----------+---------+----------+----------+--------------+---------+------+-----------+------------------+---------------------+
Pool: Full
+---------+------------------+-----------+---------+----------+----------+--------------+---------+------+-----------+------------------+-------------+
| MediaId | VolumeName       | VolStatus | Enabled | VolBytes | VolFiles | VolRetention | Recycle | Slot | InChanger | MediaType        | LastWritten |
+---------+------------------+-----------+---------+----------+----------+--------------+---------+------+-----------+------------------+-------------+
| 3       | ChangerVolume003 | Append    | 1       | 214      | 0        | 31536000     | 1       | 3    | 1         | DiskChangerMedia | 0           |
+---------+------------------+-----------+---------+----------+----------+--------------+---------+------+-----------+------------------+-------------+
list jobs
+-------+--------------+---------------------+------+-------+----------+----------+-----------+
| JobId | Name         | StartTime           | Type | Level | JobFiles | JobBytes | JobStatus |
+-------+--------------+---------------------+------+-------+----------+----------+-----------+
| 1     | Vbackup      | 2008-10-21 10:17:23 | B    | F     | 4414     | 73555187 | T         |
| 2     | Vbackup      | 2008-10-21 10:17:40 | B    | I     | 43       | 931145   | T         |
| 3     | Vbackup      | 2008-10-21 10:17:44 | B    | D     | 86       | 3648605  | T         |
| 4     | Vbackup      | 2008-10-21 10:17:48 | B    | I     | 44       | 2717489  | T         |
| 5     | RestoreFiles | 2008-10-21 10:17:53 | R    | F     | 4414     | 73555187 | T         |
| 6     | Vbackup      | 2008-10-21 10:18:02 | B    | F     | 0        | 0        | f         |
| 7     | RestoreFiles | 2008-10-21 10:18:06 | R    | F     | 4414     | 73555187 | T         |
| 8     | Vbackup      | 2008-10-21 10:18:17 | B    | I     | 43       | 2717460  | T         |
| 9     | Vbackup      | 2008-10-21 10:18:21 | B    | F     | 0        | 0        | f         |
+-------+--------------+---------------------+------+-------+----------+----------+-----------+
@# 
@# now do a restore should restore from new Virtual backup
@#
@tee /usr/bin/bacula/regress/tmp/log2.out
setdebug level=0 storage=DiskChanger
Connecting to Storage daemon DiskChanger at localhost:8103
localhost-sd: bnet.c:669-0 who=client host=127.0.0.1 port=42783
localhost-sd: dircmd.c:171-0 Conn: Hello Director localhost-dir calling
localhost-sd: dircmd.c:186-0 Got a DIR connection at 21-Oct-2008 10:18:21
localhost-sd: cram-md5.c:73-0 send: auth cram-md5 <1495332426.1224580701@localhost-sd> ssl=0
localhost-sd: cram-md5.c:133-0 cram-get received: auth cram-md5 <952800829.1224580701@localhost-dir> ssl=0
localhost-sd: cram-md5.c:152-0 sending resp to challenge: nU+A96BadVdMw7+6XgosyD
localhost-sd: dircmd.c:208-0 Message channel init completed.
localhost-sd: dircmd.c:278-0 setdebug_cmd: setdebug=0 trace=-1
3000 OK setdebug=0
restore where=/usr/bin/bacula/regress/tmp/bacula-restores select storage=DiskChanger
Automatically selected Client: localhost-fd
Automatically selected FileSet: Full Set
+-------+-------+----------+----------+---------------------+------------------+
| JobId | Level | JobFiles | JobBytes | StartTime           | VolumeName       |
+-------+-------+----------+----------+---------------------+------------------+
| 1     | F     | 4414     | 73555187 | 2008-10-21 10:17:23 | ChangerVolume001 |
| 3     | D     | 86       | 3648605  | 2008-10-21 10:17:44 | ChangerVolume001 |
| 4     | I     | 44       | 2717489  | 2008-10-21 10:17:48 | ChangerVolume001 |
| 8     | I     | 43       | 2717460  | 2008-10-21 10:18:17 | ChangerVolume001 |
+-------+-------+----------+----------+---------------------+------------------+
You have selected the following JobIds: 1,3,4,8

Building directory tree for JobId(s) 1,3,4,8 ...  +++++++++++++++++++++++++++++++++++++++++++++++
4,188 files inserted into the tree.

You are now entering file selection mode where you add (mark) and
remove (unmark) files to be restored. No files are initially added, unless
you used the "all" keyword on the command line.
Enter "done" to leave this mode.

cwd is: /
$ unmark *
4,414 files unmarked.
$ mark *
4,414 files marked.
$ done
Bootstrap records written to /usr/bin/bacula/regress/working/localhost-dir.restore.3.bsr

The job will require the following
   Volume(s)                 Storage(s)                SD Device(s)
===========================================================================
   
   ChangerVolume001          DiskChanger               DiskChanger              


4,414 files selected to be restored.

Run Restore job
JobName:         RestoreFiles
Bootstrap:       /usr/bin/bacula/regress/working/localhost-dir.restore.3.bsr
Where:           /usr/bin/bacula/regress/tmp/bacula-restores
Replace:         always
FileSet:         Full Set
Backup Client:   localhost-fd
Restore Client:  localhost-fd
Storage:         DiskChanger
When:            2008-10-21 10:18:22
Catalog:         MyCatalog
Priority:        10
Plugin Options:  *None*
OK to run? (yes/mod/no): yes
Job queued. JobId=10
wait
You have messages.
list volumes
Pool: Default
+---------+------------------+-----------+---------+----------+----------+--------------+---------+------+-----------+------------------+---------------------+
| MediaId | VolumeName       | VolStatus | Enabled | VolBytes | VolFiles | VolRetention | Recycle | Slot | InChanger | MediaType        | LastWritten         |
+---------+------------------+-----------+---------+----------+----------+--------------+---------+------+-----------+------------------+---------------------+
| 1       | ChangerVolume001 | Append    | 1       | 84474194 | 0        | 31536000     | 1       | 1    | 1         | DiskChangerMedia | 2008-10-21 10:18:18 |
| 2       | ChangerVolume002 | Append    | 1       | 214      | 0        | 31536000     | 1       | 2    | 1         | DiskChangerMedia | 0                   |
+---------+------------------+-----------+---------+----------+----------+--------------+---------+------+-----------+------------------+---------------------+
Pool: Full
+---------+------------------+-----------+---------+----------+----------+--------------+---------+------+-----------+------------------+-------------+
| MediaId | VolumeName       | VolStatus | Enabled | VolBytes | VolFiles | VolRetention | Recycle | Slot | InChanger | MediaType        | LastWritten |
+---------+------------------+-----------+---------+----------+----------+--------------+---------+------+-----------+------------------+-------------+
| 3       | ChangerVolume003 | Append    | 1       | 214      | 0        | 31536000     | 1       | 3    | 1         | DiskChangerMedia | 0           |
+---------+------------------+-----------+---------+----------+----------+--------------+---------+------+-----------+------------------+-------------+
list jobs
+-------+--------------+---------------------+------+-------+----------+----------+-----------+
| JobId | Name         | StartTime           | Type | Level | JobFiles | JobBytes | JobStatus |
+-------+--------------+---------------------+------+-------+----------+----------+-----------+
| 1     | Vbackup      | 2008-10-21 10:17:23 | B    | F     | 4414     | 73555187 | T         |
| 2     | Vbackup      | 2008-10-21 10:17:40 | B    | I     | 43       | 931145   | T         |
| 3     | Vbackup      | 2008-10-21 10:17:44 | B    | D     | 86       | 3648605  | T         |
| 4     | Vbackup      | 2008-10-21 10:17:48 | B    | I     | 44       | 2717489  | T         |
| 5     | RestoreFiles | 2008-10-21 10:17:53 | R    | F     | 4414     | 73555187 | T         |
| 6     | Vbackup      | 2008-10-21 10:18:02 | B    | F     | 0        | 0        | f         |
| 7     | RestoreFiles | 2008-10-21 10:18:06 | R    | F     | 4414     | 73555187 | T         |
| 8     | Vbackup      | 2008-10-21 10:18:17 | B    | I     | 43       | 2717460  | T         |
| 9     | Vbackup      | 2008-10-21 10:18:21 | B    | F     | 0        | 0        | f         |
| 10    | RestoreFiles | 2008-10-21 10:18:24 | R    | F     | 4414     | 73555187 | T         |
+-------+--------------+---------------------+------+-------+----------+----------+-----------+
messages
21-Oct 10:18 localhost-dir JobId 10: Start Restore Job RestoreFiles.2008-10-21_10.18.12
21-Oct 10:18 localhost-dir JobId 10: Using Device "Drive-0"
21-Oct 10:18 localhost-sd JobId 10: Ready to read from volume "ChangerVolume001" on device "Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0).
21-Oct 10:18 localhost-sd JobId 10: Forward spacing Volume "ChangerVolume001" to file:block 0:217.
21-Oct 10:18 localhost-sd JobId 10: End of file 0 on device "Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0), Volume "ChangerVolume001"
21-Oct 10:18 localhost-sd JobId 10: End of Volume at file 0 on device "Drive-0" (/usr/bin/bacula/regress/tmp/disk-changer/drive0), Volume "ChangerVolume001"
21-Oct 10:18 localhost-sd JobId 10: End of all volumes.
21-Oct 10:18 localhost-dir JobId 10: Bacula localhost-dir 2.5.16 (18Oct08): 21-Oct-2008 10:18:32
  Build OS:               i686-pc-linux-gnu unknown unknown
  JobId:                  10
  Job:                    RestoreFiles.2008-10-21_10.18.12
  Restore Client:         localhost-fd
  Start time:             21-Oct-2008 10:18:24
  End time:               21-Oct-2008 10:18:32
  Files Expected:         4,414
  Files Restored:         4,414
  Bytes Restored:         73,555,187
  Rate:                   9194.4 KB/s
  FD Errors:              0
  FD termination status:  OK
  SD termination status:  OK
  Termination:            Restore OK

21-Oct 10:18 localhost-dir JobId 10: Begin pruning Jobs.
21-Oct 10:18 localhost-dir JobId 10: No Jobs found to prune.
21-Oct 10:18 localhost-dir JobId 10: Begin pruning Files.
21-Oct 10:18 localhost-dir JobId 10: No Files found to prune.
21-Oct 10:18 localhost-dir JobId 10: End auto prune.

@output
quit
  ===== virtual-backup-test OK 10:18:39 ===== 
-------------------------------------------------------------------------
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 Copilotco.