On Wed, 2005-08-17 at 17:38 +0200, Kern Sibbald wrote:
> On Wednesday 17 August 2005 15:36, Peter Sjöberg wrote:
> > On Wed, 2005-08-17 at 14:06 +0200, Jonas Björklund wrote:
> > > Hello,
> > >
> > > On Wed, 17 Aug 2005, viktorija wrote:
> > > > tonight i got following situation:
> > > >
> > > > 17-Aug 01:07 backup-dir: Start Backup JobId 1840,
> > > > Job=wise.2005-08-16_22.00.21 17-Aug 01:07 backup-sd:
> > > > wise.2005-08-16_22.00.21 Fatal error: Device /baculabk is busy writing
> > > > on another Volume. 17-Aug 01:07 wise-fd: wise.2005-08-16_22.00.21
> > > > Fatal error: job.c:1665 Bad response to Append Data command. Wanted
> > > > 3000 OK data , got 3903 Error append data
> > > >
> > > > Now i checked all seems ok, but why it happened? What does mean this
> > > > error?
> > >
> > > I guess you running multiple jobs at the same time to different pools
> > > on a file device. This is fixed in 1.37.??. Search the list archive.
>
> The problem here depends on what version it is. If it is 1.36.x, then the
> problem is that she is trying to "mount" two volumes on the same drive (yes,
> Bacula disk backup mimics tape drives ...).
>
> If it is 1.37, the problem is probably fixed in the latest CVS.
>
> >
> > Actually, it's probably not yet fixed but is worked on getting fixed in
> > a thread on the developers list.
> > It seems to be some locking problem and if several jobs that needs to
> > change tape starts at the same time one job allocates the device and the
> > other fails (when it should wait/share it).
> > At the moment my workaround is to make sure the no tape (by executing
> > "update slots" which has the side effect of kicking out the tapes from
> > the drives) or the right tape is loaded before starting the backups. I
> > would stagger the start time but that's to much work for me so I'm
> > holding my breath for Kern to be fixed soon (as usual).
>
> I'm working on it and have made a lot of progress. The good news is that I
> now have simulated something similar and *finally* know what needs to be
> done. The bad news is that some health problems have been dragging me down
> for a month now, so programming is going at about half speed. For those of
> you who are waiting for responses from me -- sorry, I'll get to them as soon
> as I can.
>
> Peter, if you can pull the latest CVS (17Aug05 or later) and run the same
> test
> producing only the SD debug log file as you previously did, it would help.
> I've added more debug statements where I was lacking info, and I've,
> hopefully, improved the reservation algorithm. I don't expect this version
> to fix everything ...
Actually, it seems like it made it worse, only waits.
I tried twice with the same result, only one job started and still
waiting to reserv tape. First time I waited at least 15 minutes with no
change.
from messages:
17-Aug 20:43 riker-dir: Start Backup JobId 4771,
Job=BackupLister.2005-08-17_20.43.00
17-Aug 20:43 riker-sd: Job BackupLister.2005-08-17_20.43.00 waiting to reserve
a device.
17-Aug 21:10 riker-dir: BackupLister.2005-08-17_20.43.00 Fatal error:
Storage daemon didn't accept Device "TL892" because:
17-Aug 21:10 riker-dir: BackupLister.2005-08-17_20.43.00 Error: Bacula 1.37.36
(16Aug05): 17-Aug-2005 21:10:25
[EMAIL PROTECTED]:/opt/bacula # echo stat dir|./bconsole
...
Running Jobs:
JobId Level Name Status
======================================================================
4772 Differe BackupLister.2005-08-17_21.13.02 is waiting on Storage TL892
====
[EMAIL PROTECTED]:/opt/bacula # echo stat storage=TL892 drive=0|./bconsole
Connecting to Director riker:9101
1000 OK: riker-dir Version: 1.37.36 (16 August 2005)
Enter a period to cancel a command.
stat storage=TL892 drive=0
Using default Catalog name=MyCatalog DB=bacula
Connecting to Storage daemon TL892 at riker.intra.techwiz.ca:9103
riker-sd Version: 1.37.36 (16 August 2005) i686-pc-linux-gnu mandrake for
Daemon started 17-Aug-05 21:12, 0 Jobs run since started.
Heap: bytes=31,850 max_bytes=95,505 bufs=127 max_bufs=129
Running Jobs:
No Jobs running.
====
Terminated Jobs:
JobId Level Files Bytes Status Finished Name
======================================================================
4762 Incr 117 55,221,918 OK 17-Aug-05 03:06 BackupKryten
4760 Incr 782 87,207,802 OK 17-Aug-05 03:06 BackupYar
4763 Incr 21 28,224,818 OK 17-Aug-05 03:07 BackupSmeghead
4765 Incr 134 3,876,571 OK 17-Aug-05 03:07 BackupCat
4764 Incr 1,585 140,300,335 OK 17-Aug-05 03:10 BackupQueeg
4761 Incr 58 3,375,775 OK 17-Aug-05 03:21 BackupLister
4759 Incr 1,920 2,586,493,863 OK 17-Aug-05 03:21 BackupTroy
4766 Incr 216 10,764,675,672 OK 17-Aug-05 04:01 BackupPicard
4767 Incr 10,634 8,232,371,952 OK 17-Aug-05 04:24 BackupRiker
4768 Full 228 635,956,669 OK 17-Aug-05 05:32 BackupCatalog
====
Device status:
Autochanger "TL892" with devices:
"TL0" (/dev/tape2)
"TL1" (/dev/tape3)
Device "FileStorage" (/spare/bacula/File) is not open or does not exist.
Configured device capabilities:
EOF BSR BSF FSR FSF EOM !REM RACCESS AUTOMOUNT LABEL !ANONVOLS !ALWAYSOPEN
Device state:
!OPENED !TAPE !LABEL MALLOC !APPEND !READ !EOT !WEOT !EOF !NEXTVOL !SHORT
!MOUNTED
num_writers=0 JobStatus=C block=0
Device parameters:
Archive name: /spare/bacula/File Device name: FileStorage
File=0 block=0
Min block=0 Max block=0
Device "DLT" (/dev/tape) is mounted with Volume "db0003"
Configured device capabilities:
EOF BSR BSF FSR FSF EOM REM !RACCESS AUTOMOUNT LABEL !ANONVOLS ALWAYSOPEN
Device state:
OPENED TAPE LABEL MALLOC !APPEND !READ !EOT !WEOT !EOF !NEXTVOL !SHORT !MOUNTED
num_writers=0 JobStatus=C block=0
Device parameters:
Archive name: /dev/tape Device name: DLT
File=0 block=0
Min block=0 Max block=0
Total Bytes Read=0 Blocks Read=0 Bytes/block=0
Positioned at File=0 Block=0
Device "TL0" (/dev/tape2) is not open or does not exist.
Drive 0 is not loaded.
Configured device capabilities:
EOF BSR BSF FSR FSF EOM REM !RACCESS AUTOMOUNT LABEL !ANONVOLS ALWAYSOPEN
Device state:
!OPENED TAPE !LABEL MALLOC !APPEND !READ !EOT !WEOT !EOF !NEXTVOL !SHORT
!MOUNTED
num_writers=0 JobStatus=C block=0
Device parameters:
Archive name: /dev/tape2 Device name: TL0
File=0 block=0
Min block=0 Max block=0
Device "TL1" (/dev/tape3) open but no Bacula volume is mounted.
Drive 1 is not loaded.
Configured device capabilities:
EOF BSR BSF FSR FSF EOM REM !RACCESS AUTOMOUNT LABEL !ANONVOLS ALWAYSOPEN
Device state:
OPENED TAPE !LABEL MALLOC !APPEND !READ !EOT !WEOT !EOF !NEXTVOL !SHORT !MOUNTED
num_writers=0 JobStatus=C block=0
Device parameters:
Archive name: /dev/tape3 Device name: TL1
File=0 block=0
Min block=0 Max block=0
Total Bytes Read=0 Blocks Read=0 Bytes/block=0
Positioned at File=0 Block=0
====
Volume status:
db0003
You have messages.
bacula-sd: lex.c:148 Open config file: /opt/bacula/etc/bacula-sd.conf
bacula-sd: stored_conf.c:613 Inserting device res: DLT
bacula-sd: stored_conf.c:613 Inserting device res: TL0
bacula-sd: stored_conf.c:613 Inserting device res: TL1
bacula-sd: lex.c:148 Open config file: /opt/bacula/etc/bacula-sd.conf
bacula-sd: message.c:238 Copy message resource 0x80b5688 to 0x80bd448
Unloading Data Transfer Element into Storage Element 4...done
Orphaned buffer: 528 bytes allocated at line 235 of riker-sd jcr.c
Orphaned buffer: 272 bytes allocated at line 233 of riker-sd jcr.c
Orphaned buffer: 528 bytes allocated at line 1133 of riker-sd bnet.c
Orphaned buffer: 146 bytes allocated at line 81 of riker-sd
../lib/mem_pool.h
Orphaned buffer: 528 bytes allocated at line 1132 of riker-sd bnet.c
Orphaned buffer: 104 bytes allocated at line 1126 of riker-sd bnet.c
Orphaned buffer: 7 bytes allocated at line 1134 of riker-sd bnet.c
Orphaned buffer: 13 bytes allocated at line 1135 of riker-sd bnet.c
Orphaned buffer: 8 bytes allocated at line 157 of riker-sd workq.c
Orphaned buffer: 16 bytes allocated at line 226 of riker-sd jcr.c
Orphaned buffer: 24 bytes allocated at line 170 of riker-sd dircmd.c
Orphaned buffer: 146 bytes allocated at line 81 of riker-sd
../lib/mem_pool.h
Orphaned buffer: 146 bytes allocated at line 81 of riker-sd
../lib/mem_pool.h
Orphaned buffer: 146 bytes allocated at line 81 of riker-sd
../lib/mem_pool.h
Orphaned buffer: 146 bytes allocated at line 81 of riker-sd
../lib/mem_pool.h
Orphaned buffer: 146 bytes allocated at line 98 of riker-sd job.c
Orphaned buffer: 146 bytes allocated at line 101 of riker-sd job.c
Orphaned buffer: 146 bytes allocated at line 104 of riker-sd job.c
Orphaned buffer: 146 bytes allocated at line 112 of riker-sd job.c
Orphaned buffer: 40 bytes allocated at line 124 of riker-sd job.c
Orphaned buffer: 24 bytes allocated at line 269 of riker-sd reserve.c
Orphaned buffer: 40 bytes allocated at line 45 of riker-sd alist.c
Orphaned buffer: 24 bytes allocated at line 284 of riker-sd reserve.c
Orphaned buffer: 6 bytes allocated at line 298 of riker-sd reserve.c
Orphaned buffer: 40 bytes allocated at line 45 of riker-sd alist.c
bacula-sd: lex.c:148 Open config file: /opt/bacula/etc/bacula-sd.conf
bacula-sd: stored_conf.c:613 Inserting device res: DLT
bacula-sd: stored_conf.c:613 Inserting device res: TL0
bacula-sd: stored_conf.c:613 Inserting device res: TL1
bacula-sd: lex.c:148 Open config file: /opt/bacula/etc/bacula-sd.conf
bacula-sd: message.c:238 Copy message resource 0x80b5688 to 0x80bd448
riker-sd: jcr.c:113 read_last_jobs seek to 188
riker-sd: jcr.c:120 Read num_items=10
riker-sd: bpipe.c:291 Run program returning 0
riker-sd: pythonlib.c:94 No script dir. prog=SDStartUp
riker-sd: stored.c:492 calling init_dev /spare/bacula/File
riker-sd: bnet_server.c:83 Addresses host[ipv4:0.0.0.0:9103]
riker-sd: dev.c:242 init_dev: tape=0 dev_name=/spare/bacula/File
riker-sd: stored.c:494 SD init done /spare/bacula/File
riker-sd: stored.c:492 calling init_dev /dev/tape
riker-sd: dev.c:242 init_dev: tape=2 dev_name=/dev/tape
riker-sd: stored.c:494 SD init done /dev/tape
riker-sd: stored.c:507 calling first_open_device "DLT" (/dev/tape)
riker-sd: device.c:250 start open_output_device()
riker-sd: device.c:270 Opening device.
riker-sd: dev.c:275 open dev: tape=2 dev_name="DLT" (/dev/tape) vol=
mode=OPEN_READ_ONLY
riker-sd: dev.c:333 open dev: device is tape
riker-sd: dev.c:354 Try open "DLT" (/dev/tape) mode=OPEN_READ_ONLY
nonblocking=2048
riker-sd: dev.c:403 openmode=3 OPEN_READ_ONLY
riker-sd: dev.c:417 open dev: tape 4 opened
riker-sd: device.c:278 open dev "DLT" (/dev/tape) OK
riker-sd: label.c:71 Enter read_volume_label device="DLT" (/dev/tape) vol=
dev_Vol=*NULL*
riker-sd: dev.c:648 rewind_dev fd=4 "DLT" (/dev/tape)
riker-sd: label.c:138 Big if statement in read_volume_label
riker-sd: block.c:879 Full read() in read_block_from_device() len=64512
riker-sd: block.c:943 Read device got 64512 bytes at 0:0
riker-sd: block.c:284 unser_block_header block_len=208
riker-sd: block.c:295 Read binbuf = 184 24 block_len=208
riker-sd: block.c:1065 At end of read block
riker-sd: block.c:1078 Exit read_block read_len=64512 block_len=208
riker-sd: label.c:748 unser_vol_label
Volume Label:
Id : Bacula 1.0 immortal
VerNo : 11
VolName : db0003
PrevVolName :
VolFile : 0
LabelType : VOL_LABEL
LabelSize : 172
PoolName : DataBase
MediaType : DLT15
PoolType : Backup
HostName : riker.intra.techwiz.ca
Date label written: 21-Jun-2005 15:53
riker-sd: reserve.c:113 new_volume db0003
riker-sd: label.c:206 Compare Vol names: VolName= hdr=db0003
riker-sd: label.c:222 Copy vol_name=db0003
Volume Label:
Id : Bacula 1.0 immortal
VerNo : 11
VolName : db0003
PrevVolName :
VolFile : 0
LabelType : VOL_LABEL
LabelSize : 172
PoolName : DataBase
MediaType : DLT15
PoolType : Backup
HostName : riker.intra.techwiz.ca
Date label written: 21-Jun-2005 15:53
riker-sd: label.c:227 Leave read_volume_label() VOL_OK
riker-sd: dev.c:648 rewind_dev fd=4 "DLT" (/dev/tape)
riker-sd: stored.c:492 calling init_dev /dev/tape2
riker-sd: dev.c:242 init_dev: tape=2 dev_name=/dev/tape2
riker-sd: stored.c:494 SD init done /dev/tape2
riker-sd: autochanger.c:180 Locking changer TL892
riker-sd: bpipe.c:291 Run program returning 0
riker-sd: autochanger.c:151 run_prog: /opt/bacula/mtx-changer-ps.sh
/dev/changer loaded 0 /dev/tape2 0 stat=0 result=4
riker-sd: autochanger.c:189 Unlocking changer TL892
riker-sd: stored.c:507 calling first_open_device "TL0" (/dev/tape2)
riker-sd: device.c:250 start open_output_device()
riker-sd: device.c:270 Opening device.
riker-sd: dev.c:275 open dev: tape=2 dev_name="TL0" (/dev/tape2) vol=
mode=OPEN_READ_ONLY
riker-sd: dev.c:333 open dev: device is tape
riker-sd: autochanger.c:180 Locking changer TL892
riker-sd: bpipe.c:291 Run program returning 0
riker-sd: autochanger.c:151 run_prog: /opt/bacula/mtx-changer-ps.sh
/dev/changer loaded 0 /dev/tape2 0 stat=0 result=4
riker-sd: autochanger.c:189 Unlocking changer TL892
riker-sd: dev.c:354 Try open "TL0" (/dev/tape2) mode=OPEN_READ_ONLY
nonblocking=2048
riker-sd: dev.c:403 openmode=3 OPEN_READ_ONLY
riker-sd: dev.c:417 open dev: tape 5 opened
riker-sd: device.c:278 open dev "TL0" (/dev/tape2) OK
riker-sd: label.c:71 Enter read_volume_label device="TL0" (/dev/tape2) vol=
dev_Vol=*NULL*
riker-sd: dev.c:648 rewind_dev fd=5 "TL0" (/dev/tape2)
riker-sd: label.c:138 Big if statement in read_volume_label
riker-sd: block.c:879 Full read() in read_block_from_device() len=64512
riker-sd: block.c:943 Read device got 64512 bytes at 0:0
riker-sd: block.c:284 unser_block_header block_len=212
riker-sd: block.c:295 Read binbuf = 188 24 block_len=212
riker-sd: block.c:1065 At end of read block
riker-sd: block.c:1078 Exit read_block read_len=64512 block_len=212
riker-sd: label.c:748 unser_vol_label
Volume Label:
Id : Bacula 1.0 immortal
VerNo : 11
VolName : DIF017
PrevVolName :
VolFile : 0
LabelType : VOL_LABEL
LabelSize : 176
PoolName : Diff
MediaType : DLT35
PoolType : Backup
HostName : laforge.intra.techwiz.ca
Date label written: 17-Sep-2004 17:20
riker-sd: reserve.c:113 new_volume DIF017
riker-sd: label.c:206 Compare Vol names: VolName= hdr=DIF017
riker-sd: label.c:222 Copy vol_name=DIF017
Volume Label:
Id : Bacula 1.0 immortal
VerNo : 11
VolName : DIF017
PrevVolName :
VolFile : 0
LabelType : VOL_LABEL
LabelSize : 176
PoolName : Diff
MediaType : DLT35
PoolType : Backup
HostName : laforge.intra.techwiz.ca
Date label written: 17-Sep-2004 17:20
riker-sd: label.c:227 Leave read_volume_label() VOL_OK
riker-sd: dev.c:648 rewind_dev fd=5 "TL0" (/dev/tape2)
riker-sd: stored.c:492 calling init_dev /dev/tape3
riker-sd: dev.c:242 init_dev: tape=2 dev_name=/dev/tape3
riker-sd: stored.c:494 SD init done /dev/tape3
riker-sd: autochanger.c:180 Locking changer TL892
riker-sd: bpipe.c:291 Run program returning 0
riker-sd: autochanger.c:151 run_prog: /opt/bacula/mtx-changer-ps.sh
/dev/changer loaded 0 /dev/tape3 1 stat=0 result=0
riker-sd: autochanger.c:189 Unlocking changer TL892
riker-sd: stored.c:507 calling first_open_device "TL1" (/dev/tape3)
riker-sd: device.c:250 start open_output_device()
riker-sd: device.c:270 Opening device.
riker-sd: dev.c:275 open dev: tape=2 dev_name="TL1" (/dev/tape3) vol=
mode=OPEN_READ_ONLY
riker-sd: dev.c:333 open dev: device is tape
riker-sd: autochanger.c:180 Locking changer TL892
riker-sd: bpipe.c:291 Run program returning 0
riker-sd: autochanger.c:151 run_prog: /opt/bacula/mtx-changer-ps.sh
/dev/changer loaded 0 /dev/tape3 1 stat=0 result=0
riker-sd: autochanger.c:189 Unlocking changer TL892
riker-sd: dev.c:354 Try open "TL1" (/dev/tape3) mode=OPEN_READ_ONLY
nonblocking=2048
riker-sd: dev.c:403 openmode=3 OPEN_READ_ONLY
riker-sd: dev.c:417 open dev: tape 6 opened
riker-sd: device.c:278 open dev "TL1" (/dev/tape3) OK
riker-sd: label.c:71 Enter read_volume_label device="TL1" (/dev/tape3) vol=
dev_Vol=*NULL*
riker-sd: dev.c:648 rewind_dev fd=6 "TL1" (/dev/tape3)
riker-sd: dev.c:674 Rewind error, No medium found. retrying ...
riker-sd: label.c:104 return VOL_NO_MEDIA: Couldn't rewind device "TL1"
(/dev/tape3): ERR=dev.c:682 Rewind error on "TL1" (/dev/tape3). ERR=No medium
found.
riker-sd: bnet.c:1125 who=client host=172.21.15.12 port=36643
riker-sd: dircmd.c:157 Conn: Hello Director riker-dir calling
riker-sd: dircmd.c:166 Start Dir Job
riker-sd: cram-md5.c:57 send: auth cram-md5 <[EMAIL PROTECTED]> ssl=0
riker-sd: cram-md5.c:72 Authenticate OK 02MS0S+MD3An77+pX9+vmA
riker-sd: cram-md5.c:101 cram-get: auth cram-md5 <[EMAIL PROTECTED]> ssl=0
riker-sd: cram-md5.c:117 sending resp to challenge: lmNux//SE8BoN65OJ7FDgA
riker-sd: dircmd.c:187 Message channel init completed.
riker-sd: dircmd.c:194 <dird: autochanger slots TL892
riker-sd: dircmd.c:208 Do command: autochanger
riker-sd: dircmd.c:510 Try changer device TL0
riker-sd: dircmd.c:525 Found changer device TL0
riker-sd: autochanger.c:180 Locking changer TL892
riker-sd: autochanger.c:296 <stored: slots=10
riker-sd: bnet.c:1125 who=client host=172.21.15.12 port=36643
riker-sd: autochanger.c:189 Unlocking changer TL892
riker-sd: pythonlib.c:216 No startup module.
riker-sd: dircmd.c:157 Conn: Hello Director riker-dir calling
riker-sd: dircmd.c:166 Start Dir Job
riker-sd: cram-md5.c:57 send: auth cram-md5 <[EMAIL PROTECTED]> ssl=0
riker-sd: cram-md5.c:72 Authenticate OK q7I6oWlIY7UH89+VR8dOtD
riker-sd: cram-md5.c:101 cram-get: auth cram-md5 <[EMAIL PROTECTED]> ssl=0
riker-sd: cram-md5.c:117 sending resp to challenge: Y9/N37+CIB+KZ9+/A5kicB
riker-sd: dircmd.c:187 Message channel init completed.
riker-sd: dircmd.c:194 <dird: autochanger list TL892
riker-sd: dircmd.c:208 Do command: autochanger
riker-sd: dircmd.c:510 Try changer device TL0
riker-sd: dircmd.c:525 Found changer device TL0
riker-sd: dev.c:648 rewind_dev fd=5 "TL0" (/dev/tape2)
riker-sd: device.c:332 Force close_dev "TL0" (/dev/tape2)
riker-sd: dev.c:1700 really close_dev "TL0" (/dev/tape2)
riker-sd: dvd.c:93 Enter unmount_dev
riker-sd: reserve.c:163 free_volume DIF017
riker-sd: autochanger.c:180 Locking changer TL892
riker-sd: bpipe.c:291 Run program returning 0
riker-sd: autochanger.c:151 run_prog: /opt/bacula/mtx-changer-ps.sh
/dev/changer loaded 0 /dev/tape2 0 stat=0 result=4
riker-sd: autochanger.c:189 Unlocking changer TL892
riker-sd: autochanger.c:180 Locking changer TL892
riker-sd: bpipe.c:291 Run program returning 0
riker-sd: autochanger.c:189 Unlocking changer TL892
riker-sd: autochanger.c:180 Locking changer TL892
riker-sd: autochanger.c:288 <stored: 1:FUL115
riker-sd: autochanger.c:288 <stored: 2:FUL116
riker-sd: autochanger.c:288 <stored: 3:FUL117
riker-sd: autochanger.c:288 <stored: 4:DIF017
riker-sd: autochanger.c:288 <stored: 5:DIF018
riker-sd: autochanger.c:288 <stored: 6:DIF019
riker-sd: autochanger.c:288 <stored: 7:DIF020
riker-sd: autochanger.c:288 <stored: 8:INC018
riker-sd: autochanger.c:288 <stored: 9:INC019
riker-sd: autochanger.c:288 <stored: 10:CLN001
riker-sd: autochanger.c:189 Unlocking changer TL892
riker-sd: pythonlib.c:216 No startup module.
riker-sd: bnet.c:1125 who=client host=172.21.15.12 port=36643
riker-sd: dircmd.c:157 Conn: Hello Director riker-dir calling
riker-sd: dircmd.c:166 Start Dir Job
riker-sd: cram-md5.c:57 send: auth cram-md5 <[EMAIL PROTECTED]> ssl=0
riker-sd: cram-md5.c:72 Authenticate OK N7QrF8wUjG+3E/tEMjskjA
riker-sd: cram-md5.c:101 cram-get: auth cram-md5 <[EMAIL PROTECTED]> ssl=0
riker-sd: cram-md5.c:117 sending resp to challenge: HF/UxEZJcxt/w+UPSV+O9B
riker-sd: dircmd.c:187 Message channel init completed.
riker-sd: dircmd.c:194 <dird: autochanger slots TL892
riker-sd: dircmd.c:208 Do command: autochanger
riker-sd: dircmd.c:510 Try changer device TL0
riker-sd: dircmd.c:525 Found changer device TL0
riker-sd: autochanger.c:180 Locking changer TL892
riker-sd: autochanger.c:296 <stored: slots=10
riker-sd: bnet.c:1125 who=client host=172.21.15.12 port=36643
riker-sd: autochanger.c:189 Unlocking changer TL892
riker-sd: pythonlib.c:216 No startup module.
riker-sd: dircmd.c:157 Conn: Hello Director riker-dir calling
riker-sd: dircmd.c:166 Start Dir Job
riker-sd: cram-md5.c:57 send: auth cram-md5 <[EMAIL PROTECTED]> ssl=0
riker-sd: cram-md5.c:72 Authenticate OK y++WoBo2N++OfDgoDRkoZB
riker-sd: cram-md5.c:101 cram-get: auth cram-md5 <[EMAIL PROTECTED]> ssl=0
riker-sd: cram-md5.c:117 sending resp to challenge: 08+TZ+Z/Q8VJz0+Dd8+FuD
riker-sd: dircmd.c:187 Message channel init completed.
riker-sd: dircmd.c:194 <dird: autochanger list TL892
riker-sd: dircmd.c:208 Do command: autochanger
riker-sd: dircmd.c:510 Try changer device TL0
riker-sd: dircmd.c:525 Found changer device TL0
riker-sd: device.c:332 Force close_dev "TL0" (/dev/tape2)
riker-sd: dev.c:1700 really close_dev "TL0" (/dev/tape2)
riker-sd: dvd.c:93 Enter unmount_dev
riker-sd: autochanger.c:180 Locking changer TL892
riker-sd: bpipe.c:291 Run program returning 0
riker-sd: autochanger.c:151 run_prog: /opt/bacula/mtx-changer-ps.sh
/dev/changer loaded 0 /dev/tape2 0 stat=0 result=0
riker-sd: autochanger.c:189 Unlocking changer TL892
riker-sd: autochanger.c:180 Locking changer TL892
riker-sd: autochanger.c:288 <stored: 1:FUL115
riker-sd: autochanger.c:288 <stored: 2:FUL116
riker-sd: autochanger.c:288 <stored: 3:FUL117
riker-sd: autochanger.c:288 <stored: 4:DIF017
riker-sd: autochanger.c:288 <stored: 5:DIF018
riker-sd: autochanger.c:288 <stored: 6:DIF019
riker-sd: autochanger.c:288 <stored: 7:DIF020
riker-sd: autochanger.c:288 <stored: 8:INC018
riker-sd: autochanger.c:288 <stored: 9:INC019
riker-sd: autochanger.c:288 <stored: 10:CLN001
riker-sd: autochanger.c:189 Unlocking changer TL892
riker-sd: pythonlib.c:216 No startup module.
riker-sd: bnet.c:1125 who=client host=172.21.15.12 port=36643
riker-sd: dircmd.c:157 Conn: Hello Director riker-dir calling
riker-sd: dircmd.c:166 Start Dir Job
riker-sd: cram-md5.c:57 send: auth cram-md5 <[EMAIL PROTECTED]> ssl=0
riker-sd: cram-md5.c:72 Authenticate OK T4Y3eU+Mbx5pyw/fx4NQMD
riker-sd: cram-md5.c:101 cram-get: auth cram-md5 <[EMAIL PROTECTED]> ssl=0
riker-sd: cram-md5.c:117 sending resp to challenge: Lg/iqx+su++vDi/QQSxNSD
riker-sd: dircmd.c:187 Message channel init completed.
riker-sd: dircmd.c:194 <dird: JobId=4771 job=BackupLister.2005-08-17_20.43.00
job_name=BackupLister client_name=lister-fd type=66 level=68 FileSet=AllLocal
NoAttr=0 SpoolAttr=1 FileSetMD5=z++Kqi4yQ+Afu8o/G4/Q8A SpoolData=1
WritePartAfterJob=0 PreferMountedVols=1
riker-sd: dircmd.c:208 Do command: JobId=
riker-sd: job.c:70 <dird: JobId=4771 job=BackupLister.2005-08-17_20.43.00
job_name=BackupLister client_name=lister-fd type=66 level=68 FileSet=AllLocal
NoAttr=0 SpoolAttr=1 FileSetMD5=z++Kqi4yQ+Afu8o/G4/Q8A SpoolData=1
WritePartAfterJob=0 PreferMountedVols=1
riker-sd: job.c:123 >dird: 3000 OK Job SDid=1 SDtime=1124325605
Authorization=OHKN-FKKG-HDCF-COEC-HIEK-MJKD-PJHB-ALHB
riker-sd: pythonlib.c:216 No startup module.
riker-sd: dircmd.c:194 <dird: use storage=TL892 media_type=DLT35 pool_name=Diff
pool_type=Backup append=1 copy=0 stripe=0
riker-sd: dircmd.c:208 Do command: use storage=
riker-sd: reserve.c:268 <dird: use storage=TL892 media_type=DLT35
pool_name=Diff pool_type=Backup append=1 copy=0 stripe=0
riker-sd: reserve.c:309 Storage=TL892 media_type=DLT35 pool=Diff
pool_type=Backup
riker-sd: reserve.c:311 Device=TL892
riker-sd: reserve.c:456 Search res for TL892
riker-sd: reserve.c:458 Try res=FileStorage
riker-sd: reserve.c:458 Try res=DLT
riker-sd: reserve.c:458 Try res=TL0
riker-sd: reserve.c:458 Try res=TL1
riker-sd: reserve.c:473 Try changer res=TL892
riker-sd: reserve.c:478 Try changer device TL0
riker-sd: reserve.c:532 Found device TL0
riker-sd: reserve.c:636 reserve_append device is tape
riker-sd: reserve.c:640 reserve.c:639 Device "TL0" (/dev/tape2) is busy writing
on another Volume.
riker-sd: reserve.c:547 dev_name=TL892 mediatype=DLT35 ok=0
riker-sd: reserve.c:478 Try changer device TL1
riker-sd: reserve.c:532 Found device TL1
riker-sd: reserve.c:636 reserve_append device is tape
riker-sd: reserve.c:640 reserve.c:639 Device "TL1" (/dev/tape3) is busy writing
on another Volume.
riker-sd: reserve.c:547 dev_name=TL892 mediatype=DLT35 ok=0
riker-sd: wait.c:174 Enter wait_for_device
riker-sd: wait.c:200 I'm going to wait for a device. HB=0 wait=3600 remwait=3600
riker-sd: bnet.c:1125 who=client host=172.21.15.12 port=36643
riker-sd: dircmd.c:157 Conn: Hello Director riker-dir calling
riker-sd: dircmd.c:166 Start Dir Job
riker-sd: cram-md5.c:57 send: auth cram-md5 <[EMAIL PROTECTED]> ssl=0
riker-sd: cram-md5.c:72 Authenticate OK q6lpU9Ed9jMRAlEki/kdtB
riker-sd: cram-md5.c:101 cram-get: auth cram-md5 <[EMAIL PROTECTED]> ssl=0
riker-sd: cram-md5.c:117 sending resp to challenge: ij8NF8VHWSpQCH+RH5hU/B
riker-sd: dircmd.c:187 Message channel init completed.
riker-sd: dircmd.c:194 <dird: status
riker-sd: dircmd.c:208 Do command: status
riker-sd: pythonlib.c:216 No startup module.
riker-sd: bnet.c:1125 who=client host=172.21.15.12 port=36643
riker-sd: dircmd.c:157 Conn: Hello Director riker-dir calling
riker-sd: dircmd.c:166 Start Dir Job
riker-sd: cram-md5.c:57 send: auth cram-md5 <[EMAIL PROTECTED]> ssl=0
riker-sd: cram-md5.c:72 Authenticate OK 48/hMz+Jn6/fA/+bq9+8VA
riker-sd: cram-md5.c:101 cram-get: auth cram-md5 <[EMAIL PROTECTED]> ssl=0
riker-sd: cram-md5.c:117 sending resp to challenge: k8tLXW+ueTl06+ZjH/EHmD
riker-sd: dircmd.c:187 Message channel init completed.
riker-sd: dircmd.c:194 <dird: status
riker-sd: dircmd.c:208 Do command: status
riker-sd: pythonlib.c:216 No startup module.
riker-sd: bnet.c:1125 who=client host=172.21.15.12 port=36643
riker-sd: dircmd.c:157 Conn: Hello Director riker-dir calling
riker-sd: dircmd.c:166 Start Dir Job
riker-sd: cram-md5.c:57 send: auth cram-md5 <[EMAIL PROTECTED]> ssl=0
riker-sd: cram-md5.c:72 Authenticate OK yUYFk5ZLxR//N5tUPl/aFD
riker-sd: cram-md5.c:101 cram-get: auth cram-md5 <[EMAIL PROTECTED]> ssl=0
riker-sd: cram-md5.c:117 sending resp to challenge: a4+O8C51w+Up0B+Tfw8oCD
riker-sd: dircmd.c:187 Message channel init completed.
riker-sd: dircmd.c:194 <dird: autochanger slots TL892
riker-sd: dircmd.c:208 Do command: autochanger
riker-sd: dircmd.c:510 Try changer device TL0
riker-sd: dircmd.c:525 Found changer device TL0
riker-sd: autochanger.c:180 Locking changer TL892
riker-sd: autochanger.c:296 <stored: slots=10
riker-sd: autochanger.c:189 Unlocking changer TL892
riker-sd: pythonlib.c:216 No startup module.
riker-sd: bnet.c:1125 who=client host=172.21.15.12 port=36643
riker-sd: dircmd.c:157 Conn: Hello Director riker-dir calling
riker-sd: dircmd.c:166 Start Dir Job
riker-sd: cram-md5.c:57 send: auth cram-md5 <[EMAIL PROTECTED]> ssl=0
riker-sd: cram-md5.c:72 Authenticate OK bU+5L//VPl1bim5UA88FAC
riker-sd: cram-md5.c:101 cram-get: auth cram-md5 <[EMAIL PROTECTED]> ssl=0
riker-sd: cram-md5.c:117 sending resp to challenge: cx+7P2UJJw+wQC/ALlhI7D
riker-sd: dircmd.c:187 Message channel init completed.
riker-sd: dircmd.c:194 <dird: autochanger list TL892
riker-sd: dircmd.c:208 Do command: autochanger
riker-sd: dircmd.c:510 Try changer device TL0
riker-sd: dircmd.c:525 Found changer device TL0
riker-sd: device.c:332 Force close_dev "TL0" (/dev/tape2)
riker-sd: dev.c:1700 really close_dev "TL0" (/dev/tape2)
riker-sd: dvd.c:93 Enter unmount_dev
riker-sd: autochanger.c:180 Locking changer TL892
riker-sd: bpipe.c:291 Run program returning 0
riker-sd: autochanger.c:151 run_prog: /opt/bacula/mtx-changer-ps.sh
/dev/changer loaded 0 /dev/tape2 0 stat=0 result=0
riker-sd: autochanger.c:189 Unlocking changer TL892
riker-sd: autochanger.c:180 Locking changer TL892
riker-sd: autochanger.c:288 <stored: 1:FUL115
riker-sd: autochanger.c:288 <stored: 2:FUL116
riker-sd: autochanger.c:288 <stored: 3:FUL117
riker-sd: autochanger.c:288 <stored: 4:DIF017
riker-sd: autochanger.c:288 <stored: 5:DIF018
riker-sd: autochanger.c:288 <stored: 6:DIF019
riker-sd: autochanger.c:288 <stored: 7:DIF020
riker-sd: autochanger.c:288 <stored: 8:INC018
riker-sd: autochanger.c:288 <stored: 9:INC019
riker-sd: autochanger.c:288 <stored: 10:CLN001
riker-sd: autochanger.c:189 Unlocking changer TL892
riker-sd: pythonlib.c:216 No startup module.
riker-sd: bnet.c:1125 who=client host=172.21.15.12 port=36643
riker-sd: dircmd.c:157 Conn: Hello Director riker-dir calling
riker-sd: dircmd.c:166 Start Dir Job
riker-sd: cram-md5.c:57 send: auth cram-md5 <[EMAIL PROTECTED]> ssl=0
riker-sd: cram-md5.c:72 Authenticate OK b4xsf9gzx4ACSXptSX/jaB
riker-sd: cram-md5.c:101 cram-get: auth cram-md5 <[EMAIL PROTECTED]> ssl=0
riker-sd: cram-md5.c:117 sending resp to challenge: 70/y26kUe5+6e7+VY3ESbA
riker-sd: dircmd.c:187 Message channel init completed.
riker-sd: dircmd.c:194 <dird: status
riker-sd: dircmd.c:208 Do command: status
riker-sd: pythonlib.c:216 No startup module.
riker-sd: jcr.c:150 write_last_jobs seek to 188
riker-sd: stored.c:580 In terminate_stored() sig=15
riker-sd: stored.c:583 Term device /spare/bacula/File
riker-sd: dev.c:1826 term_dev: "FileStorage" (/spare/bacula/File)
riker-sd: dev.c:1700 really close_dev "FileStorage" (/spare/bacula/File)
riker-sd: dvd.c:93 Enter unmount_dev
riker-sd: stored.c:583 Term device /dev/tape
riker-sd: reserve.c:163 free_volume db0003
riker-sd: dev.c:1826 term_dev: "DLT" (/dev/tape)
riker-sd: dev.c:1700 really close_dev "DLT" (/dev/tape)
riker-sd: dvd.c:93 Enter unmount_dev
riker-sd: stored.c:583 Term device /dev/tape2
riker-sd: dev.c:1826 term_dev: "TL0" (/dev/tape2)
riker-sd: dev.c:1700 really close_dev "TL0" (/dev/tape2)
riker-sd: dvd.c:93 Enter unmount_dev
riker-sd: stored.c:583 Term device /dev/tape3
riker-sd: dev.c:1826 term_dev: "TL1" (/dev/tape3)
riker-sd: dev.c:1700 really close_dev "TL1" (/dev/tape3)
riker-sd: dvd.c:93 Enter unmount_dev
Pool Maxsize Maxused Inuse
NoPool 256 15 0
NAME 130 10 9
FNAME 256 5 1
MSG 1024 8 3
EMSG 1024 6 0
bacula-sd: lex.c:148 Open config file: /opt/bacula/etc/bacula-sd.conf
bacula-sd: stored_conf.c:613 Inserting device res: DLT
bacula-sd: stored_conf.c:613 Inserting device res: TL0
bacula-sd: stored_conf.c:613 Inserting device res: TL1
bacula-sd: lex.c:148 Open config file: /opt/bacula/etc/bacula-sd.conf
bacula-sd: message.c:238 Copy message resource 0x80b5688 to 0x80bd448
Orphaned buffer: 528 bytes allocated at line 235 of riker-sd jcr.c
Orphaned buffer: 272 bytes allocated at line 233 of riker-sd jcr.c
Orphaned buffer: 528 bytes allocated at line 1133 of riker-sd bnet.c
Orphaned buffer: 1040 bytes allocated at line 1132 of riker-sd bnet.c
Orphaned buffer: 146 bytes allocated at line 81 of riker-sd
../lib/mem_pool.h
Orphaned buffer: 104 bytes allocated at line 1126 of riker-sd bnet.c
Orphaned buffer: 7 bytes allocated at line 1134 of riker-sd bnet.c
Orphaned buffer: 13 bytes allocated at line 1135 of riker-sd bnet.c
Orphaned buffer: 8 bytes allocated at line 157 of riker-sd workq.c
Orphaned buffer: 16 bytes allocated at line 226 of riker-sd jcr.c
Orphaned buffer: 24 bytes allocated at line 170 of riker-sd dircmd.c
Orphaned buffer: 146 bytes allocated at line 81 of riker-sd
../lib/mem_pool.h
Orphaned buffer: 146 bytes allocated at line 81 of riker-sd
../lib/mem_pool.h
Orphaned buffer: 146 bytes allocated at line 81 of riker-sd
../lib/mem_pool.h
Orphaned buffer: 146 bytes allocated at line 81 of riker-sd
../lib/mem_pool.h
Orphaned buffer: 146 bytes allocated at line 98 of riker-sd job.c
Orphaned buffer: 146 bytes allocated at line 101 of riker-sd job.c
Orphaned buffer: 146 bytes allocated at line 104 of riker-sd job.c
Orphaned buffer: 146 bytes allocated at line 112 of riker-sd job.c
Orphaned buffer: 40 bytes allocated at line 124 of riker-sd job.c
Orphaned buffer: 24 bytes allocated at line 269 of riker-sd reserve.c
Orphaned buffer: 40 bytes allocated at line 45 of riker-sd alist.c
Orphaned buffer: 24 bytes allocated at line 284 of riker-sd reserve.c
Orphaned buffer: 6 bytes allocated at line 298 of riker-sd reserve.c
Orphaned buffer: 40 bytes allocated at line 45 of riker-sd alist.c
bacula-sd: lex.c:148 Open config file: /opt/bacula/etc/bacula-sd.conf
bacula-sd: stored_conf.c:613 Inserting device res: DLT
bacula-sd: stored_conf.c:613 Inserting device res: TL0
bacula-sd: stored_conf.c:613 Inserting device res: TL1
bacula-sd: lex.c:148 Open config file: /opt/bacula/etc/bacula-sd.conf
bacula-sd: message.c:238 Copy message resource 0x80b5688 to 0x80bd448
riker-sd: jcr.c:113 read_last_jobs seek to 188
riker-sd: jcr.c:120 Read num_items=10
riker-sd: bpipe.c:291 Run program returning 0
riker-sd: pythonlib.c:94 No script dir. prog=SDStartUp
riker-sd: stored.c:492 calling init_dev /spare/bacula/File
riker-sd: bnet_server.c:83 Addresses host[ipv4:0.0.0.0:9103]
riker-sd: dev.c:242 init_dev: tape=0 dev_name=/spare/bacula/File
riker-sd: stored.c:494 SD init done /spare/bacula/File
riker-sd: stored.c:492 calling init_dev /dev/tape
riker-sd: dev.c:242 init_dev: tape=2 dev_name=/dev/tape
riker-sd: stored.c:494 SD init done /dev/tape
riker-sd: stored.c:507 calling first_open_device "DLT" (/dev/tape)
riker-sd: device.c:250 start open_output_device()
riker-sd: device.c:270 Opening device.
riker-sd: dev.c:275 open dev: tape=2 dev_name="DLT" (/dev/tape) vol=
mode=OPEN_READ_ONLY
riker-sd: dev.c:333 open dev: device is tape
riker-sd: dev.c:354 Try open "DLT" (/dev/tape) mode=OPEN_READ_ONLY
nonblocking=2048
riker-sd: dev.c:403 openmode=3 OPEN_READ_ONLY
riker-sd: dev.c:417 open dev: tape 4 opened
riker-sd: device.c:278 open dev "DLT" (/dev/tape) OK
riker-sd: label.c:71 Enter read_volume_label device="DLT" (/dev/tape) vol=
dev_Vol=*NULL*
riker-sd: dev.c:648 rewind_dev fd=4 "DLT" (/dev/tape)
riker-sd: label.c:138 Big if statement in read_volume_label
riker-sd: block.c:879 Full read() in read_block_from_device() len=64512
riker-sd: block.c:943 Read device got 64512 bytes at 0:0
riker-sd: block.c:284 unser_block_header block_len=208
riker-sd: block.c:295 Read binbuf = 184 24 block_len=208
riker-sd: block.c:1065 At end of read block
riker-sd: block.c:1078 Exit read_block read_len=64512 block_len=208
riker-sd: label.c:748 unser_vol_label
Volume Label:
Id : Bacula 1.0 immortal
VerNo : 11
VolName : db0003
PrevVolName :
VolFile : 0
LabelType : VOL_LABEL
LabelSize : 172
PoolName : DataBase
MediaType : DLT15
PoolType : Backup
HostName : riker.intra.techwiz.ca
Date label written: 21-Jun-2005 15:53
riker-sd: reserve.c:113 new_volume db0003
riker-sd: label.c:206 Compare Vol names: VolName= hdr=db0003
riker-sd: label.c:222 Copy vol_name=db0003
Volume Label:
Id : Bacula 1.0 immortal
VerNo : 11
VolName : db0003
PrevVolName :
VolFile : 0
LabelType : VOL_LABEL
LabelSize : 172
PoolName : DataBase
MediaType : DLT15
PoolType : Backup
HostName : riker.intra.techwiz.ca
Date label written: 21-Jun-2005 15:53
riker-sd: label.c:227 Leave read_volume_label() VOL_OK
riker-sd: dev.c:648 rewind_dev fd=4 "DLT" (/dev/tape)
riker-sd: stored.c:492 calling init_dev /dev/tape2
riker-sd: dev.c:242 init_dev: tape=2 dev_name=/dev/tape2
riker-sd: stored.c:494 SD init done /dev/tape2
riker-sd: autochanger.c:180 Locking changer TL892
riker-sd: bpipe.c:291 Run program returning 0
riker-sd: autochanger.c:151 run_prog: /opt/bacula/mtx-changer-ps.sh
/dev/changer loaded 0 /dev/tape2 0 stat=0 result=0
riker-sd: autochanger.c:189 Unlocking changer TL892
riker-sd: stored.c:507 calling first_open_device "TL0" (/dev/tape2)
riker-sd: device.c:250 start open_output_device()
riker-sd: device.c:270 Opening device.
riker-sd: dev.c:275 open dev: tape=2 dev_name="TL0" (/dev/tape2) vol=
mode=OPEN_READ_ONLY
riker-sd: dev.c:333 open dev: device is tape
riker-sd: autochanger.c:180 Locking changer TL892
riker-sd: bpipe.c:291 Run program returning 0
riker-sd: autochanger.c:151 run_prog: /opt/bacula/mtx-changer-ps.sh
/dev/changer loaded 0 /dev/tape2 0 stat=0 result=0
riker-sd: autochanger.c:189 Unlocking changer TL892
riker-sd: dev.c:354 Try open "TL0" (/dev/tape2) mode=OPEN_READ_ONLY
nonblocking=2048
riker-sd: dev.c:403 openmode=3 OPEN_READ_ONLY
riker-sd: dev.c:417 open dev: tape 5 opened
riker-sd: device.c:278 open dev "TL0" (/dev/tape2) OK
riker-sd: label.c:71 Enter read_volume_label device="TL0" (/dev/tape2) vol=
dev_Vol=*NULL*
riker-sd: dev.c:648 rewind_dev fd=5 "TL0" (/dev/tape2)
riker-sd: dev.c:674 Rewind error, No medium found. retrying ...
riker-sd: label.c:104 return VOL_NO_MEDIA: Couldn't rewind device "TL0"
(/dev/tape2): ERR=dev.c:682 Rewind error on "TL0" (/dev/tape2). ERR=No medium
found.
riker-sd: stored.c:492 calling init_dev /dev/tape3
riker-sd: dev.c:242 init_dev: tape=2 dev_name=/dev/tape3
riker-sd: stored.c:494 SD init done /dev/tape3
riker-sd: autochanger.c:180 Locking changer TL892
riker-sd: bpipe.c:291 Run program returning 0
riker-sd: autochanger.c:151 run_prog: /opt/bacula/mtx-changer-ps.sh
/dev/changer loaded 0 /dev/tape3 1 stat=0 result=0
riker-sd: autochanger.c:189 Unlocking changer TL892
riker-sd: stored.c:507 calling first_open_device "TL1" (/dev/tape3)
riker-sd: device.c:250 start open_output_device()
riker-sd: device.c:270 Opening device.
riker-sd: dev.c:275 open dev: tape=2 dev_name="TL1" (/dev/tape3) vol=
mode=OPEN_READ_ONLY
riker-sd: dev.c:333 open dev: device is tape
riker-sd: autochanger.c:180 Locking changer TL892
riker-sd: bpipe.c:291 Run program returning 0
riker-sd: autochanger.c:151 run_prog: /opt/bacula/mtx-changer-ps.sh
/dev/changer loaded 0 /dev/tape3 1 stat=0 result=0
riker-sd: autochanger.c:189 Unlocking changer TL892
riker-sd: dev.c:354 Try open "TL1" (/dev/tape3) mode=OPEN_READ_ONLY
nonblocking=2048
riker-sd: dev.c:403 openmode=3 OPEN_READ_ONLY
riker-sd: dev.c:417 open dev: tape 6 opened
riker-sd: device.c:278 open dev "TL1" (/dev/tape3) OK
riker-sd: label.c:71 Enter read_volume_label device="TL1" (/dev/tape3) vol=
dev_Vol=*NULL*
riker-sd: dev.c:648 rewind_dev fd=6 "TL1" (/dev/tape3)
riker-sd: dev.c:674 Rewind error, No medium found. retrying ...
riker-sd: label.c:104 return VOL_NO_MEDIA: Couldn't rewind device "TL1"
(/dev/tape3): ERR=dev.c:682 Rewind error on "TL1" (/dev/tape3). ERR=No medium
found.
riker-sd: bnet.c:1125 who=client host=172.21.15.12 port=36643
riker-sd: dircmd.c:157 Conn: Hello Director riker-dir calling
riker-sd: dircmd.c:166 Start Dir Job
riker-sd: cram-md5.c:57 send: auth cram-md5 <[EMAIL PROTECTED]> ssl=0
riker-sd: cram-md5.c:72 Authenticate OK gnYfY8+U5y/aO3/VNAcVOB
riker-sd: cram-md5.c:101 cram-get: auth cram-md5 <[EMAIL PROTECTED]> ssl=0
riker-sd: cram-md5.c:117 sending resp to challenge: XldtH7xv+FxKpm5NH8+JrB
riker-sd: dircmd.c:187 Message channel init completed.
riker-sd: dircmd.c:194 <dird: autochanger slots TL892
riker-sd: dircmd.c:208 Do command: autochanger
riker-sd: dircmd.c:510 Try changer device TL0
riker-sd: dircmd.c:525 Found changer device TL0
riker-sd: autochanger.c:180 Locking changer TL892
riker-sd: autochanger.c:296 <stored: slots=10
riker-sd: autochanger.c:189 Unlocking changer TL892
riker-sd: pythonlib.c:216 No startup module.
riker-sd: bnet.c:1125 who=client host=172.21.15.12 port=36643
riker-sd: dircmd.c:157 Conn: Hello Director riker-dir calling
riker-sd: dircmd.c:166 Start Dir Job
riker-sd: cram-md5.c:57 send: auth cram-md5 <[EMAIL PROTECTED]> ssl=0
riker-sd: cram-md5.c:72 Authenticate OK Dx+KB8/4T9+pc7/BgnEswC
riker-sd: cram-md5.c:101 cram-get: auth cram-md5 <[EMAIL PROTECTED]> ssl=0
riker-sd: cram-md5.c:117 sending resp to challenge: 17/nlV/Uq9RQsR+uPmUgjD
riker-sd: dircmd.c:187 Message channel init completed.
riker-sd: dircmd.c:194 <dird: autochanger list TL892
riker-sd: dircmd.c:208 Do command: autochanger
riker-sd: dircmd.c:510 Try changer device TL0
riker-sd: dircmd.c:525 Found changer device TL0
riker-sd: dev.c:648 rewind_dev fd=5 "TL0" (/dev/tape2)
riker-sd: dev.c:674 Rewind error, No medium found. retrying ...
riker-sd: device.c:332 Force close_dev "TL0" (/dev/tape2)
riker-sd: dev.c:1700 really close_dev "TL0" (/dev/tape2)
riker-sd: dvd.c:93 Enter unmount_dev
riker-sd: autochanger.c:180 Locking changer TL892
riker-sd: bpipe.c:291 Run program returning 0
riker-sd: autochanger.c:151 run_prog: /opt/bacula/mtx-changer-ps.sh
/dev/changer loaded 0 /dev/tape2 0 stat=0 result=0
riker-sd: autochanger.c:189 Unlocking changer TL892
riker-sd: autochanger.c:180 Locking changer TL892
riker-sd: autochanger.c:288 <stored: 1:FUL115
riker-sd: autochanger.c:288 <stored: 2:FUL116
riker-sd: autochanger.c:288 <stored: 3:FUL117
riker-sd: autochanger.c:288 <stored: 4:DIF017
riker-sd: autochanger.c:288 <stored: 5:DIF018
riker-sd: autochanger.c:288 <stored: 6:DIF019
riker-sd: autochanger.c:288 <stored: 7:DIF020
riker-sd: autochanger.c:288 <stored: 8:INC018
riker-sd: autochanger.c:288 <stored: 9:INC019
riker-sd: autochanger.c:288 <stored: 10:CLN001
riker-sd: autochanger.c:189 Unlocking changer TL892
riker-sd: pythonlib.c:216 No startup module.
riker-sd: bnet.c:1125 who=client host=172.21.15.12 port=36643
riker-sd: dircmd.c:157 Conn: Hello Director riker-dir calling
riker-sd: dircmd.c:166 Start Dir Job
riker-sd: cram-md5.c:57 send: auth cram-md5 <[EMAIL PROTECTED]> ssl=0
riker-sd: cram-md5.c:72 Authenticate OK rQEJoRJUxh/Ma8+kn6ttbB
riker-sd: cram-md5.c:101 cram-get: auth cram-md5 <[EMAIL PROTECTED]> ssl=0
riker-sd: cram-md5.c:117 sending resp to challenge: /+/+qAV+L6/uK2kjDj/NhA
riker-sd: dircmd.c:187 Message channel init completed.
riker-sd: dircmd.c:194 <dird: status
riker-sd: dircmd.c:208 Do command: status
riker-sd: pythonlib.c:216 No startup module.
riker-sd: bnet.c:1125 who=client host=172.21.15.12 port=36643
riker-sd: dircmd.c:157 Conn: Hello Director riker-dir calling
riker-sd: dircmd.c:166 Start Dir Job
riker-sd: cram-md5.c:57 send: auth cram-md5 <[EMAIL PROTECTED]> ssl=0
riker-sd: cram-md5.c:72 Authenticate OK 6XViL4/B63IVUy+F2j/fAC
riker-sd: cram-md5.c:101 cram-get: auth cram-md5 <[EMAIL PROTECTED]> ssl=0
riker-sd: cram-md5.c:117 sending resp to challenge: U9/e59+4C9sya7Fl/R+8lA
riker-sd: dircmd.c:187 Message channel init completed.
riker-sd: dircmd.c:194 <dird: JobId=4772 job=BackupLister.2005-08-17_21.13.02
job_name=BackupLister client_name=lister-fd type=66 level=68 FileSet=AllLocal
NoAttr=0 SpoolAttr=1 FileSetMD5=z++Kqi4yQ+Afu8o/G4/Q8A SpoolData=1
WritePartAfterJob=0 PreferMountedVols=1
riker-sd: dircmd.c:208 Do command: JobId=
riker-sd: job.c:70 <dird: JobId=4772 job=BackupLister.2005-08-17_21.13.02
job_name=BackupLister client_name=lister-fd type=66 level=68 FileSet=AllLocal
NoAttr=0 SpoolAttr=1 FileSetMD5=z++Kqi4yQ+Afu8o/G4/Q8A SpoolData=1
WritePartAfterJob=0 PreferMountedVols=1
riker-sd: job.c:123 >dird: 3000 OK Job SDid=1 SDtime=1124327545
Authorization=JDAH-NEKJ-MLGO-NBGL-IKLC-HHLO-IGLE-LEOJ
riker-sd: pythonlib.c:216 No startup module.
riker-sd: dircmd.c:194 <dird: use storage=TL892 media_type=DLT35 pool_name=Diff
pool_type=Backup append=1 copy=0 stripe=0
riker-sd: dircmd.c:208 Do command: use storage=
riker-sd: reserve.c:268 <dird: use storage=TL892 media_type=DLT35
pool_name=Diff pool_type=Backup append=1 copy=0 stripe=0
riker-sd: reserve.c:309 Storage=TL892 media_type=DLT35 pool=Diff
pool_type=Backup
riker-sd: reserve.c:311 Device=TL892
riker-sd: reserve.c:456 Search res for TL892
riker-sd: reserve.c:458 Try res=FileStorage
riker-sd: reserve.c:458 Try res=DLT
riker-sd: reserve.c:458 Try res=TL0
riker-sd: reserve.c:458 Try res=TL1
riker-sd: reserve.c:473 Try changer res=TL892
riker-sd: reserve.c:478 Try changer device TL0
riker-sd: reserve.c:532 Found device TL0
riker-sd: reserve.c:636 reserve_append device is tape
riker-sd: reserve.c:640 reserve.c:639 Device "TL0" (/dev/tape2) is busy writing
on another Volume.
riker-sd: reserve.c:547 dev_name=TL892 mediatype=DLT35 ok=0
riker-sd: reserve.c:478 Try changer device TL1
riker-sd: reserve.c:532 Found device TL1
riker-sd: reserve.c:636 reserve_append device is tape
riker-sd: reserve.c:640 reserve.c:639 Device "TL1" (/dev/tape3) is busy writing
on another Volume.
riker-sd: reserve.c:547 dev_name=TL892 mediatype=DLT35 ok=0
riker-sd: wait.c:174 Enter wait_for_device
riker-sd: wait.c:200 I'm going to wait for a device. HB=0 wait=3600 remwait=3600
riker-sd: bnet.c:1125 who=client host=172.21.15.12 port=36643
riker-sd: dircmd.c:157 Conn: Hello Director riker-dir calling
riker-sd: dircmd.c:166 Start Dir Job
riker-sd: cram-md5.c:57 send: auth cram-md5 <[EMAIL PROTECTED]> ssl=0
riker-sd: cram-md5.c:72 Authenticate OK N++8T5/FvltBsT4/YE+eiB
riker-sd: cram-md5.c:101 cram-get: auth cram-md5 <[EMAIL PROTECTED]> ssl=0
riker-sd: cram-md5.c:117 sending resp to challenge: 4W+/1nprJA/Un6UlT5/W3C
riker-sd: dircmd.c:187 Message channel init completed.
riker-sd: dircmd.c:194 <dird: status
riker-sd: dircmd.c:208 Do command: status
riker-sd: pythonlib.c:216 No startup module.
riker-sd: bnet.c:1125 who=client host=172.21.15.12 port=36643
riker-sd: dircmd.c:157 Conn: Hello Director riker-dir calling
riker-sd: dircmd.c:166 Start Dir Job
riker-sd: cram-md5.c:57 send: auth cram-md5 <[EMAIL PROTECTED]> ssl=0
riker-sd: cram-md5.c:72 Authenticate OK a2lXQx/tJH+6Rn9dH8/N4C
riker-sd: cram-md5.c:101 cram-get: auth cram-md5 <[EMAIL PROTECTED]> ssl=0
riker-sd: cram-md5.c:117 sending resp to challenge: L8/rD6+ju/+Iu+/ck/dY2C
riker-sd: dircmd.c:187 Message channel init completed.
riker-sd: dircmd.c:194 <dird: status
riker-sd: dircmd.c:208 Do command: status
riker-sd: pythonlib.c:216 No startup module.
riker-sd: jcr.c:150 write_last_jobs seek to 188
riker-sd: stored.c:580 In terminate_stored() sig=15
riker-sd: stored.c:583 Term device /spare/bacula/File
riker-sd: dev.c:1826 term_dev: "FileStorage" (/spare/bacula/File)
riker-sd: dev.c:1700 really close_dev "FileStorage" (/spare/bacula/File)
riker-sd: dvd.c:93 Enter unmount_dev
riker-sd: stored.c:583 Term device /dev/tape
riker-sd: reserve.c:163 free_volume db0003
riker-sd: dev.c:1826 term_dev: "DLT" (/dev/tape)
riker-sd: dev.c:1700 really close_dev "DLT" (/dev/tape)
riker-sd: dvd.c:93 Enter unmount_dev
riker-sd: stored.c:583 Term device /dev/tape2
riker-sd: dev.c:1826 term_dev: "TL0" (/dev/tape2)
riker-sd: dev.c:1700 really close_dev "TL0" (/dev/tape2)
riker-sd: dvd.c:93 Enter unmount_dev
riker-sd: stored.c:583 Term device /dev/tape3
riker-sd: dev.c:1826 term_dev: "TL1" (/dev/tape3)
riker-sd: dev.c:1700 really close_dev "TL1" (/dev/tape3)
riker-sd: dvd.c:93 Enter unmount_dev
Pool Maxsize Maxused Inuse
NoPool 256 15 0
NAME 130 9 9
FNAME 256 4 1
MSG 1024 7 3
EMSG 1024 6 0
