This is still on FreeBSD 7.x so I would not put much effort into
tracking this down unless there is something very obvious in the
DEBUG output.
The following DEBUG output is from an incremental test. It can be
repeated, although not every time.
Traceback first, then the DEBUG output:
[EMAIL PROTECTED]:~/src/BaculaRegressionTesting] $ gdb bin/bacula-sd bacula-
sd.core
GNU gdb 6.1.1 [FreeBSD]
Copyright 2004 Free Software Foundation, Inc.
GDB is free software, covered by the GNU General Public License, and
you are
welcome to change it and/or distribute copies of it under certain
conditions.
Type "show copying" to see the conditions.
There is absolutely no warranty for GDB. Type "show warranty" for
details.
This GDB was configured as "i386-marcel-freebsd"...
Core was generated by `bacula-sd'.
Program terminated with signal 11, Segmentation fault.
Reading symbols from /lib/libz.so.4...done.
Loaded symbols for /lib/libz.so.4
Reading symbols from /lib/libthr.so.3...done.
Loaded symbols for /lib/libthr.so.3
Reading symbols from /usr/local/lib/libintl.so.8...done.
Loaded symbols for /usr/local/lib/libintl.so.8
Reading symbols from /usr/local/lib/libiconv.so.3...done.
Loaded symbols for /usr/local/lib/libiconv.so.3
Reading symbols from /usr/lib/libssl.so.5...done.
Loaded symbols for /usr/lib/libssl.so.5
Reading symbols from /lib/libcrypto.so.5...done.
Loaded symbols for /lib/libcrypto.so.5
Reading symbols from /usr/lib/libstdc++.so.6...done.
Loaded symbols for /usr/lib/libstdc++.so.6
Reading symbols from /lib/libm.so.5...done.
Loaded symbols for /lib/libm.so.5
Reading symbols from /lib/libgcc_s.so.1...done.
Loaded symbols for /lib/libgcc_s.so.1
Reading symbols from /lib/libc.so.7...done.
Loaded symbols for /lib/libc.so.7
Reading symbols from /libexec/ld-elf.so.1...done.
Loaded symbols for /libexec/ld-elf.so.1
#0 0x0807c338 in bvsnprintf (buffer=0xbf8fc6fe "free vol_list
Volume=TestVolume001 dev=n/src/BaculaRegressionTesting/tmp\n",
maxlen=4970, format=0x809d6ae "\n", args=0xbf8fda98
"¨Ú\217¿\224á\006\b") at bsnprintf.c:413
warning: Source file is more recent than executable.
413 strln = strlen(value);
[New Thread 0x28601300 (LWP 100270)]
[New Thread 0x28601100 (LWP 100445)]
(gdb) traceback
Undefined command: "traceback". Try "help".
(gdb) backtrace
#0 0x0807c338 in bvsnprintf (buffer=0xbf8fc6fe "free vol_list
Volume=TestVolume001 dev=n/src/BaculaRegressionTesting/tmp\n",
maxlen=4970, format=0x809d6ae "\n", args=0xbf8fda98
"¨Ú\217¿\224á\006\b") at bsnprintf.c:413
#1 0x08084a46 in d_msg (file=0x809cfa3 "reserve.c", line=513,
level=0, fmt=0x809d690 "free vol_list Volume=%s dev=%s\n")
at message.c:864
#2 0x0806e204 in free_volume_list () at reserve.c:515
#3 0x0804cf94 in terminate_stored (sig=15) at stored.c:608
#4 0x0808c245 in signal_handler (sig=15) at signal.c:180
#5 0xbfbfffb4 in ?? ()
#6 0x0000000f in ?? ()
#7 0x00000000 in ?? ()
#8 0xbf8fdbc0 in ?? ()
#9 0x00000000 in ?? ()
#10 0x0808bef0 in get_signal_name () at signal.c:72
#11 0x280f81de in pthread_cond_init () from /lib/libthr.so.3
#12 0x0808f74b in watchdog_thread (arg=0x0) at watchdog.c:307
#13 0x280f1a7f in pthread_getprio () from /lib/libthr.so.3
#14 0x00000000 in ?? ()
Current language: auto; currently c++
(gdb)
[EMAIL PROTECTED]:~/src/BaculaRegressionTesting] $ tests/incremental-2media
Orphaned buffer: localhost-sd 8 bytes buf=28608328 allocated at
workq.c:16 7
=== Starting incremental-2media at 15:40:06 ===
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.3.6 (30 September 2007)
Enter a period to cancel a command.
@tee /dev/null
messages
05-Oct 15:37 localhost-dir: threepooldisk.2007-10-05_15.31.07 Fatal
error:
Netwo rk
error with
FD during Backup: ERR=Broken pipe
05-Oct 15:37 localhost-dir: threepooldisk.2007-10-05_15.31.06 Fatal
error:
Netwo rk
error with
FD during Backup: ERR=Broken pipe
05-Oct 15:37 localhost-sd: Job threepooldisk.2007-10-05_15.31.07
marked to
be ca
nceled.
05-Oct 15:37 localhost-sd: Job threepooldisk.2007-10-05_15.31.06
marked to
be ca
nceled.
05-Oct 15:37 localhost-sd: Job threepooldisk.2007-10-05_15.31.06
canceled
while
waiting for
mount on Storage Device ""Drive-1" (/usr/home/dan/src/BaculaRegressi
onTesting/tmp/disk-changer/drive1)".
05-Oct 15:37 localhost-sd: threepooldisk.2007-10-05_15.31.07 Fatal
error:
Job 5
canceled.
05-Oct 15:37 localhost-dir: threepooldisk.2007-10-05_15.31.07 Fatal
error:
No Jo b
status
returned from FD.
05-Oct 15:37 localhost-dir: threepooldisk.2007-10-05_15.31.06 Fatal
error:
No Jo b
status
returned from FD.
05-Oct 15:37 localhost-dir: threepooldisk.2007-10-05_15.31.07 Error:
Bacula
loca lhost-
dir
2.3.6 (30Sep07): 05-Oct-2007 15:37:20
Build OS: i386-unknown-freebsd7.0 freebsd 7.0-CURRENT
JobId: 5
Job: threepooldisk.2007-10-05_15.31.07
Backup Level: Full
Client: "localhost-fd" 2.3.6 (30Sep07)
i386-unknown-freebsd7.0
,freebsd,7.0-CURRENT
FileSet: "Full Set" 2007-10-05 15:31:37
Pool: "Default" (From Job resource)
Storage: "DDS-4" (From Job resource)
Scheduled time: 05-Oct-2007 15:31:37
Start time: 05-Oct-2007 15:32:28
End time: 05-Oct-2007 15:37:20
Elapsed time: 4 mins 52 secs
Priority: 10
FD Files Written: 0
SD Files Written: 0
FD Bytes Written: 0 (0 B)
SD Bytes Written: 0 (0 B)
Rate: 0.0 KB/s
Software Compression: None
VSS: no
Encryption: no
Volume name(s):
Volume Session Id: 5
Volume Session Time: 1191598288
Last Volume Bytes: 218 (218 B)
Non-fatal FD errors: 0
SD Errors: 0
FD termination status: Error
SD termination status: Canceled
Termination: *** Backup Error ***
05-Oct 15:37 localhost-dir: threepooldisk.2007-10-05_15.31.06 Error:
Bacula
loca lhost-
dir
2.3.6 (30Sep07): 05-Oct-2007 15:37:20
Build OS: i386-unknown-freebsd7.0 freebsd 7.0-CURRENT
JobId: 4
Job: threepooldisk.2007-10-05_15.31.06
Backup Level: Full
Client: "localhost-fd" 2.3.6 (30Sep07)
i386-unknown-freebsd7.0
,freebsd,7.0-CURRENT
FileSet: "Full Set" 2007-10-05 15:31:37
Pool: "Default" (From Job resource)
Storage: "DDS-4" (From Job resource)
Scheduled time: 05-Oct-2007 15:31:37
Start time: 05-Oct-2007 15:31:41
End time: 05-Oct-2007 15:37:20
Elapsed time: 5 mins 39 secs
Priority: 10
FD Files Written: 0
SD Files Written: 0
FD Bytes Written: 0 (0 B)
SD Bytes Written: 0 (0 B)
Rate: 0.0 KB/s
Software Compression: None
VSS: no
Encryption: no
Volume name(s):
Volume Session Id: 4
Volume Session Time: 1191598288
Last Volume Bytes: 0 (0 B)
Non-fatal FD errors: 0
SD Errors: 0
FD termination status: Error
SD termination status: Canceled
Termination: *** Backup Error ***
05-Oct 15:37 localhost-dir: Start Restore Job
RestoreFiles.2007-10-05_15.37.09
05-Oct 15:37 localhost-dir: Using Device "Drive-0"
05-Oct 15:37 localhost-dir: RestoreFiles.2007-10-05_15.37.09 Warning:
bsock.c:12 3
Could
not connect to Client: localhost-fd on localhost:8102. ERR=Connection
re
fused
Retrying ...
@tee /usr/home/dan/src/BaculaRegressionTesting/tmp/log1.out
label storage=DDS-4 volume=TestVolume001 slot=1 Pool=Default drive=0
Automatically selected Catalog: MyCatalog
Using Catalog "MyCatalog"
Connecting to Storage daemon DDS-4 at localhost:8103 ...
Sending label command for Volume "TestVolume001" Slot 1 ...
3301 Issuing autochanger "loaded? drive 0" command.
3302 Autochanger "loaded? drive 0", result: nothing loaded.
3304 Issuing autochanger "load slot 1, drive 0" command.
3305 Autochanger "load slot 1, drive 0", status is OK.
3301 Issuing autochanger "loaded? drive 0" command.
3302 Autochanger "loaded? drive 0", result is Slot 1.
3301 Issuing autochanger "loaded? drive 0" command.
3302 Autochanger "loaded? drive 0", result is Slot 1.
3000 OK label. VolBytes=218 DVD=0 Volume="TestVolume001"
Device="Drive-0"
(/usr/
home/dan/src/BaculaRegressionTesting/tmp/disk-changer/drive0)
Catalog record for Volume "TestVolume001", Slot 1 successfully
created.
Requesting to mount DDS-4 ...
3002 Device "Drive-0"
(/usr/home/dan/src/BaculaRegressionTesting/tmp/disk-change
r/drive0) is mounted.
label storage=File volume=TestVolume002 Pool=Default
Connecting to Storage daemon File at localhost:8103 ...
Sending label command for Volume "TestVolume002" Slot 0 ...
3000 OK label. VolBytes=222 DVD=0 Volume="TestVolume002"
Device="FileStorage" (/
usr/home/dan/src/BaculaRegressionTesting/tmp)
Catalog record for Volume "TestVolume002", Slot 0 successfully
created.
Requesting to mount FileStorage ...
3906 File device "FileStorage"
(/usr/home/dan/src/BaculaRegressionTesting/tmp) i
s always mounted.
run job=Inc2media yes
Job queued. JobId=1
You have messages.
wait
messages
05-Oct 15:40 localhost-dir: No prior Full backup Job record found.
05-Oct 15:40 localhost-dir: No prior or suitable Full backup found in
catalog. D
oing
FULL backup.
05-Oct 15:40 localhost-dir: Start Backup JobId 1,
Job=Inc2media.2007-10-05_15.40
.03
05-Oct 15:40 localhost-dir: Using Device "Drive-0"
05-Oct 15:40 localhost-sd: 3301 Issuing autochanger "loaded? drive 0"
command.
05-Oct 15:40 localhost-sd: 3302 Autochanger "loaded? drive 0", result
is
Slot 1.
05-Oct 15:40 localhost-sd: 3301 Issuing autochanger "loaded? drive 0"
command.
05-Oct 15:40 localhost-sd: 3302 Autochanger "loaded? drive 0", result
is
Slot 1.
05-Oct 15:40 localhost-sd: Wrote label to prelabeled Volume
"TestVolume001"
on d evice
"Drive-0" (/usr/home/dan/src/BaculaRegressionTesting/tmp/disk-
changer/driv
e0)
05-Oct 15:40 localhost-sd: Spooling data ...
05-Oct 15:40 localhost-sd: Job write elapsed time = 00:00:17,
Transfer rate
= 4. 077 M
bytes/second
05-Oct 15:40 localhost-sd: Committing spooled data to Volume
"TestVolume001". De
spooling 69,554,708 bytes ...
05-Oct 15:40 localhost-sd: Despooling elapsed time = 00:00:02,
Transfer rate
= 3 4.77 M
bytes/second
05-Oct 15:40 localhost-sd: Sending spooled attrs to the Director.
Despooling
1,7 20,654
bytes
...
05-Oct 15:40 localhost-dir: Bacula localhost-dir 2.3.6 (30Sep07):
05-Oct-2007 15
:40:39
Build OS: i386-unknown-freebsd7.0 freebsd 7.0-CURRENT
JobId: 1
Job: Inc2media.2007-10-05_15.40.03
Backup Level: Full (upgraded from Incremental)
Client: "localhost-fd" 2.3.6 (30Sep07)
i386-unknown-freebsd7.0
,freebsd,7.0-CURRENT
FileSet: "Full Set" 2007-10-05 15:40:15
Pool: "Default" (From Job resource)
Storage: "DDS-4" (From Job resource)
Scheduled time: 05-Oct-2007 15:40:15
Start time: 05-Oct-2007 15:40:17
End time: 05-Oct-2007 15:40:39
Elapsed time: 22 secs
Priority: 10
FD Files Written: 5,484
SD Files Written: 5,484
FD Bytes Written: 68,392,516 (68.39 MB)
SD Bytes Written: 69,324,290 (69.32 MB)
Rate: 3108.8 KB/s
Software Compression: None
VSS: no
Encryption: no
Volume name(s): TestVolume001
Volume Session Id: 1
Volume Session Time: 1191598806
Last Volume Bytes: 69,541,990 (69.54 MB)
Non-fatal FD errors: 0
SD Errors: 0
FD termination status: OK
SD termination status: OK
Termination: Backup OK
05-Oct 15:40 localhost-dir: Begin pruning Jobs.
05-Oct 15:40 localhost-dir: No Jobs found to prune.
05-Oct 15:40 localhost-dir: Begin pruning Files.
05-Oct 15:40 localhost-dir: No Files found to prune.
05-Oct 15:40 localhost-dir: End auto prune.
quit
Backup 1 done
Connecting to Director localhost:8101
1000 OK: localhost-dir Version: 2.3.6 (30 September 2007)
Enter a period to cancel a command.
@tee /dev/null
messages
You have no messages.
@tee /usr/home/dan/src/BaculaRegressionTesting/tmp/log1.out
@# Force Incremental on the second Volume
update volume=TestVolume001 VolStatus=Used
Automatically selected Catalog: MyCatalog
Using Catalog "MyCatalog"
New Volume status is: Used
setdebug level=51 storage=File
Connecting to Storage daemon File at localhost:8103
3000 OK setdebug=51
run level=Incremental job=Inc2media storage=File yes
Job queued. JobId=2
wait
localhost-sd: cram-md5.c:73-0 send: auth cram-md5
<[EMAIL PROTECTED]
t-sd> ssl=0
localhost-sd: reserve.c:583-2 <dird: use storage=File
media_type=FileMedia
pool_
name=Default
pool_type=Backup append=1 copy=0 stripe=0
localhost-sd: reserve.c:612-2 <dird device: use device=FileStorage
localhost-sd: reserve.c:628-2 Storage=File media_type=FileMedia
pool=Default
poo
l_type=Backup
append=1
localhost-sd: reserve.c:630-2 Device=FileStorage
localhost-sd: reserve.c:708-2 PrefMnt=1 exact=1 suitable=0 chgronly=0
any=0
localhost-sd: reserve.c:815-2 PrefMnt=1 exact=1 suitable=0 chgronly=0
localhost-sd: reserve.c:827-2 lock volumes
localhost-sd: reserve.c:838-2 duplicate vol list
localhost-sd: reserve.c:854-2 unlock volumes
localhost-sd: reserve.c:858-2 look for vol in vol list
localhost-sd: reserve.c:870-2 vol=TestVolume002 OK for this job
localhost-sd: reserve.c:893-2 try vol=TestVolume002 on
device=FileStorage
localhost-sd: reserve.c:1036-2 chk MediaType device=FileMedia
request=FileMedia
localhost-sd: reserve.c:1059-2 try reserve FileStorage
localhost-sd: reserve.c:1072-2 have_vol=1 vol=TestVolume002
localhost-sd: reserve.c:1246-2 reserve_append device is "FileStorage"
(/usr/home
/dan/src/BaculaRegressionTesting/tmp)
localhost-sd: reserve.c:1322-2 PrefMnt=1 exact=1 suitable=1
chgronly=0 any=0
localhost-sd: reserve.c:1372-2 PrefMnt=1 exact=1 suitable=1
chgronly=0 any=0
localhost-sd: reserve.c:1375-2 have_vol=1 have= resvol=TestVolume002
want=TestVo
lume002
localhost-sd: reserve.c:405-2 find_vol=TestVolume002 found=1
localhost-sd: reserve.c:179-2 List from find_volume: TestVolume001 at
288090b8 o n
device
"Drive-0" (/usr/home/dan/src/BaculaRegressionTesting/tmp/disk-
changer/d
rive0)
localhost-sd: reserve.c:179-2 List from find_volume: TestVolume002 at
289090b8 o n
device
"FileStorage" (/usr/home/dan/src/BaculaRegressionTesting/tmp)
localhost-sd: reserve.c:535-2 Vol=TestVolume002 on same dev.
localhost-sd: reserve.c:1423-2 OK Dev avail reserved "FileStorage"
(/usr/home/da
n/src/BaculaRegressionTesting/tmp)
localhost-sd: reserve.c:1256-2 Inc reserve=1 dev="FileStorage"
(/usr/home/dan/sr
c/BaculaRegressionTesting/tmp) 2870c818
localhost-sd: reserve.c:1081-2 Reserved=1 dev_name=FileStorage
mediatype=FileMed
ia pool=Default ok=1
localhost-sd: reserve.c:1143-2 >dird: 3000 OK use device
device=FileStorage
localhost-sd: reserve.c:896-2 Suitable device found=FileStorage
localhost-sd: reserve.c:916-2 lock volumes
localhost-sd: reserve.c:513-2 free vol_list Volume=TestVolume001
dev="Drive-0" (
/usr/home/dan/src/BaculaRegressionTesting/tmp/disk-changer/drive0)
localhost-sd: reserve.c:513-2 free vol_list Volume=TestVolume002
/dev="FileStorag
e"
(/usr/home/dan/src/BaculaRegressionTesting/tmp)
localhost-sd: reserve.c:922-2 deleted temp vol list
localhost-sd: reserve.c:923-2 lock volumes
localhost-sd: reserve.c:927-2 got vol TestVolume002 from in-use vols
list
localhost-sd: job.c:177-2 Inc2media.2007-10-05_15.40.05 waiting 1800
sec for
FD to
contact SD
key=DNFE-BNLJ-GFFB-DCMH-CHNG-MPPO-GPPI-KDOA
localhost-sd: cram-md5.c:73-0 send: auth cram-md5
<[EMAIL PROTECTED]
st-sd> ssl=0
localhost-sd: reserve.c:405-2 find_vol=TestVolume002 found=1
localhost-sd: reserve.c:179-2 List from find_volume: TestVolume001 at
288090b8 o n
device
"Drive-0" (/usr/home/dan/src/BaculaRegressionTesting/tmp/disk-
changer/d
rive0)
localhost-sd: reserve.c:179-2 List from find_volume: TestVolume002 at
289090b8 o n
device
"FileStorage" (/usr/home/dan/src/BaculaRegressionTesting/tmp)
localhost-sd: reserve.c:535-2 Vol=TestVolume002 on same dev.
localhost-sd: reserve.c:311-2 reserve_volume TestVolume002
localhost-sd: reserve.c:179-2 List from begin reserve_volume:
TestVolume001
at 2 88090b8
on
device "Drive-0" (/usr/home/dan/src/BaculaRegressionTesting/tmp/disk-
changer/drive0)
localhost-sd: reserve.c:179-2 List from begin reserve_volume:
TestVolume002
at 2 89090b8
on
device "FileStorage" (/usr/home/dan/src/BaculaRegressionTesting/tmp)
localhost-sd: reserve.c:330-2 OK, vol=TestVolume002 on device.
localhost-sd: reserve.c:179-2 List from end new volume: TestVolume001
at
288090b 8 on
device
"Drive-0" (/usr/home/dan/src/BaculaRegressionTesting/tmp/disk-change
r/drive0)
localhost-sd: reserve.c:179-2 List from end new volume: TestVolume002
at
289090b 8 on
device
"FileStorage" (/usr/home/dan/src/BaculaRegressionTesting/tmp)
localhost-sd: reserve.c:311-2 reserve_volume TestVolume002
localhost-sd: reserve.c:179-2 List from begin reserve_volume:
TestVolume001
at 2 88090b8
on
device "Drive-0" (/usr/home/dan/src/BaculaRegressionTesting/tmp/disk-
changer/drive0)
localhost-sd: reserve.c:179-2 List from begin reserve_volume:
TestVolume002
at 2 89090b8
on
device "FileStorage" (/usr/home/dan/src/BaculaRegressionTesting/tmp)
localhost-sd: reserve.c:330-2 OK, vol=TestVolume002 on device.
localhost-sd: reserve.c:179-2 List from end new volume: TestVolume001
at
288090b 8 on
device
"Drive-0" (/usr/home/dan/src/BaculaRegressionTesting/tmp/disk-change
r/drive0)
localhost-sd: reserve.c:179-2 List from end new volume: TestVolume002
at
289090b 8 on
device
"FileStorage" (/usr/home/dan/src/BaculaRegressionTesting/tmp)
Volume Label:
Id : Bacula 1.0 immortal
VerNo : 11
VolName : TestVolume002
PrevVolName :
VolFile : 0
LabelType : PRE_LABEL
LabelSize : 186
PoolName : Default
MediaType : FileMedia
PoolType : Backup
HostName : pg82.unixathome.org
Date label written: 05-Oct-2007 15:40
localhost-sd: append.c:96-2 Begin append device="FileStorage"
(/usr/home/dan/src
/BaculaRegressionTesting/tmp)
localhost-sd: reserve.c:486-2 free_volume TestVolume002
dev="FileStorage"
/(/usr/
home/dan/src/BaculaRegressionTesting/tmp)
localhost-sd: reserve.c:179-2 List from free_volume: TestVolume001 at
288090b8 o n
device
"Drive-0" (/usr/home/dan/src/BaculaRegressionTesting/tmp/disk-
changer/d
rive0)
You have messages.
messages
05-Oct 15:40 localhost-dir: Start Backup JobId 2,
Job=Inc2media.2007-10-05_15.40
.05
05-Oct 15:40 localhost-dir: Using Device "FileStorage"
05-Oct 15:40 localhost-sd: Wrote label to prelabeled Volume
"TestVolume002"
on d evice
"FileStorage" (/usr/home/dan/src/BaculaRegressionTesting/tmp)
05-Oct 15:40 localhost-sd: Spooling data ...
05-Oct 15:40 localhost-sd: Job write elapsed time = 00:00:01,
Transfer rate
= 5. 441 M
bytes/second
05-Oct 15:40 localhost-sd: Committing spooled data to Volume
"TestVolume002". De
spooling 5,452,979 bytes ...
05-Oct 15:40 localhost-sd: Despooling elapsed time = 00:00:01,
Transfer rate
= 5 .452 M
bytes/second
05-Oct 15:40 localhost-sd: Sending spooled attrs to the Director.
Despooling
56, 433
bytes ...
05-Oct 15:40 localhost-dir: Bacula localhost-dir 2.3.6 (30Sep07):
05-Oct-2007 15
:40:44
Build OS: i386-unknown-freebsd7.0 freebsd 7.0-CURRENT
JobId: 2
Job: Inc2media.2007-10-05_15.40.05
Backup Level: Incremental, since=2007-10-05 15:40:17
Client: "localhost-fd" 2.3.6 (30Sep07)
i386-unknown-freebsd7.0
,freebsd,7.0-CURRENT
FileSet: "Full Set" 2007-10-05 15:40:15
Pool: "Default" (From Job resource)
Storage: "File" (From command line)
Scheduled time: 05-Oct-2007 15:40:40
Start time: 05-Oct-2007 15:40:42
End time: 05-Oct-2007 15:40:44
Elapsed time: 2 secs
Priority: 10
FD Files Written: 181
SD Files Written: 181
FD Bytes Written: 5,414,328 (5.414 MB)
SD Bytes Written: 5,441,801 (5.441 MB)
Rate: 2707.2 KB/s
Software Compression: None
VSS: no
Encryption: no
Volume name(s): TestVolume002
Volume Session Id: 2
Volume Session Time: 1191598806
Last Volume Bytes: 5,452,181 (5.452 MB)
Non-fatal FD errors: 0
SD Errors: 0
FD termination status: OK
SD termination status: OK
Termination: Backup OK
05-Oct 15:40 localhost-dir: Begin pruning Jobs.
05-Oct 15:40 localhost-dir: No Jobs found to prune.
05-Oct 15:40 localhost-dir: Begin pruning Files.
05-Oct 15:40 localhost-dir: No Files found to prune.
05-Oct 15:40 localhost-dir: End auto prune.
@#
@# now do a restore
@#
@tee /usr/home/dan/src/BaculaRegressionTesting/tmp/log2.out
setdebug level=51 storage=DDS-4
Connecting to Storage daemon DDS-4 at localhost:8103
localhost-sd: cram-md5.c:73-0 send: auth cram-md5
<[EMAIL PROTECTED]
st-sd> ssl=0
localhost-sd: dircmd.c:277-0 setdebug_cmd: setdebug=51 trace=-1
3000 OK setdebug=51
restore where=/usr/home/dan/src/BaculaRegressionTesting/tmp/bacula-
restores
sele ct all
done
Automatically selected Client: localhost-fd
Automatically selected FileSet: Full Set
+-------+-------+----------+------------+---------------------+-------
--------+
| jobid | level | jobfiles | jobbytes | starttime |
volumename
|
+-------+-------+----------+------------+---------------------+-------
--------+
| 1 | F | 5,484 | 68,392,516 | 2007-10-05 15:40:17 |
TestVolume001 |
| 2 | I | 181 | 5,414,328 | 2007-10-05 15:40:42 |
TestVolume002 |
+-------+-------+----------+------------+---------------------+-------
--------+
You have selected the following JobIds: 1,2
Building directory tree for JobId 1 ...
+++++++++++++++++++++++++++++++++++++++
+++++++
Building directory tree for JobId 2 ...
2 Jobs, 5,115 files inserted into the tree and marked for extraction.
Bootstrap records written to
/usr/home/dan/src/BaculaRegressionTesting/working/l
ocalhost-dir.restore.1.bsr
The job will require the following
Volume(s) Storage(s) SD Device(s)
======================================================================
=====
TestVolume001 DDS-4 DDS-4
TestVolume002 File FileStorage
5,484 files selected to be restored.
Run Restore job
JobName: RestoreFiles
Bootstrap:
/usr/home/dan/src/BaculaRegressionTesting/working/localhost-dir
.restore.1.bsr
Where:
/usr/home/dan/src/BaculaRegressionTesting/tmp/bacula-restores
Replace: always
FileSet: Full Set
Backup Client: localhost-fd
Restore Client: localhost-fd
Storage: DDS-4
When: 2007-10-05 15:40:45
Catalog: MyCatalog
Priority: 10
OK to run? (yes/mod/no): yes
Job queued. JobId=3
wait
localhost-sd: cram-md5.c:73-0 send: auth cram-md5
<[EMAIL PROTECTED]
st-sd> ssl=0
localhost-sd: reserve.c:583-3 <dird: use storage= media_type=DDS-4
pool_name=Def
ault
pool_type=Backup append=0 copy=0 stripe=0
localhost-sd: reserve.c:612-3 <dird device: use device=DDS-4
localhost-sd: reserve.c:628-3 Storage= media_type=DDS-4 pool=Default
pool_type=B
ackup
append=0
localhost-sd: reserve.c:630-3 Device=DDS-4
localhost-sd: reserve.c:708-3 PrefMnt=1 exact=1 suitable=0 chgronly=0
any=0
localhost-sd: reserve.c:815-3 PrefMnt=1 exact=1 suitable=0 chgronly=0
localhost-sd: reserve.c:970-3 search res for DDS-4
localhost-sd: reserve.c:973-3 Try match changer res=DDS-4
localhost-sd: reserve.c:978-3 Try changer device Drive-0
localhost-sd: reserve.c:1036-3 chk MediaType device=DDS-4 request=DDS-
4
localhost-sd: reserve.c:1059-3 try reserve Drive-0
localhost-sd: reserve.c:1194-3 Inc reserve=1 dev="Drive-0"
(/usr/home/dan/src/Ba
culaRegressionTesting/tmp/disk-changer/drive0) 2870c018
localhost-sd: reserve.c:1131-3 Read reserved=1 dev_name=DDS-4
mediatype=DDS-4 po
ol=Default ok=1
localhost-sd: reserve.c:1143-3 >dird: 3000 OK use device device=Drive-
0
localhost-sd: reserve.c:989-3 Device Drive-0 reserved=1 for read.
localhost-sd: reserve.c:944-3 available device found=DDS-4
localhost-sd: job.c:177-3 RestoreFiles.2007-10-05_15.40.06 waiting
1800 sec
for FD to
contact
SD key=KKAA-FDOJ-FOND-LDKO-HMAI-DFOI-PNKP-IHBP
localhost-sd: cram-md5.c:73-0 send: auth cram-md5
<[EMAIL PROTECTED]
t-sd> ssl=0
localhost-sd: fd_cmds.c:360-3 === Bootstrap file ===
localhost-sd: fd_cmds.c:362-3 Volume="TestVolume001"
localhost-sd: fd_cmds.c:362-3 MediaType="DDS-4"
localhost-sd: fd_cmds.c:362-3 Device="DDS-4"
localhost-sd: fd_cmds.c:362-3 Slot=1
localhost-sd: fd_cmds.c:362-3 VolSessionId=1
localhost-sd: fd_cmds.c:362-3 VolSessionTime=1191598806
localhost-sd: fd_cmds.c:362-3 VolFile=0
localhost-sd: fd_cmds.c:362-3 VolBlock=218-69541989
localhost-sd: fd_cmds.c:362-3 FileIndex=1-1984
localhost-sd: fd_cmds.c:362-3 FileIndex=1987-1988
localhost-sd: fd_cmds.c:362-3 FileIndex=1993-1994
localhost-sd: fd_cmds.c:362-3 FileIndex=1996
localhost-sd: fd_cmds.c:362-3 FileIndex=2019
localhost-sd: fd_cmds.c:362-3 FileIndex=2027
localhost-sd: fd_cmds.c:362-3 FileIndex=2031
localhost-sd: fd_cmds.c:362-3 FileIndex=2033
localhost-sd: fd_cmds.c:362-3 FileIndex=2035-2037
localhost-sd: fd_cmds.c:362-3 FileIndex=2079-3510
localhost-sd: fd_cmds.c:362-3 FileIndex=3512
localhost-sd: fd_cmds.c:362-3 FileIndex=3515
localhost-sd: fd_cmds.c:362-3 FileIndex=3517
localhost-sd: fd_cmds.c:362-3 FileIndex=3520-3521
localhost-sd: fd_cmds.c:362-3 FileIndex=3526
localhost-sd: fd_cmds.c:362-3 FileIndex=3528
localhost-sd: fd_cmds.c:362-3 FileIndex=3532-3535
localhost-sd: fd_cmds.c:362-3 FileIndex=3541-3543
localhost-sd: fd_cmds.c:362-3 FileIndex=3546-3547
localhost-sd: fd_cmds.c:362-3 FileIndex=3549
localhost-sd: fd_cmds.c:362-3 FileIndex=3551
localhost-sd: fd_cmds.c:362-3 FileIndex=3554-3555
localhost-sd: fd_cmds.c:362-3 FileIndex=3558
localhost-sd: fd_cmds.c:362-3 FileIndex=3562
localhost-sd: fd_cmds.c:362-3 FileIndex=3564-3565
localhost-sd: fd_cmds.c:362-3 FileIndex=3569-3571
localhost-sd: fd_cmds.c:362-3 FileIndex=3573-3574
localhost-sd: fd_cmds.c:362-3 FileIndex=3584-3585
localhost-sd: fd_cmds.c:362-3 FileIndex=3587
localhost-sd: fd_cmds.c:362-3 FileIndex=3589
localhost-sd: fd_cmds.c:362-3 FileIndex=3591
localhost-sd: fd_cmds.c:362-3 FileIndex=3593-3594
localhost-sd: fd_cmds.c:362-3 FileIndex=3597-3599
localhost-sd: fd_cmds.c:362-3 FileIndex=3649-5484
localhost-sd: fd_cmds.c:362-3 Count=5303
localhost-sd: fd_cmds.c:362-3 Volume="TestVolume002"
localhost-sd: fd_cmds.c:362-3 MediaType="FileMedia"
localhost-sd: fd_cmds.c:362-3 Device="FileStorage"
localhost-sd: fd_cmds.c:362-3 VolSessionId=2
localhost-sd: fd_cmds.c:362-3 VolSessionTime=1191598806
localhost-sd: fd_cmds.c:362-3 VolFile=0
localhost-sd: fd_cmds.c:362-3 VolBlock=222-5452180
localhost-sd: fd_cmds.c:362-3 FileIndex=1-181
localhost-sd: fd_cmds.c:362-3 Count=181
localhost-sd: fd_cmds.c:366-3 === end bootstrap file ===
Next : 0x288171e8
Root bsr : 0x28817178
VolumeName : TestVolume001
MediaType : DDS-4
Device : DDS-4
Slot : 1
SessId : 1
SessTime : 1191598806
VolFile : 0-0
VolBlock : 218-69541989
FileIndex : 1-1984
FileIndex : 1987-1988
FileIndex : 1993-1994
FileIndex : 1996
FileIndex : 2019
FileIndex : 2027
FileIndex : 2031
FileIndex : 2033
FileIndex : 2035-2037
FileIndex : 2079-3510
FileIndex : 3512
FileIndex : 3515
FileIndex : 3517
FileIndex : 3520-3521
FileIndex : 3526
FileIndex : 3528
FileIndex : 3532-3535
FileIndex : 3541-3543
FileIndex : 3546-3547
FileIndex : 3549
FileIndex : 3551
FileIndex : 3554-3555
FileIndex : 3558
FileIndex : 3562
FileIndex : 3564-3565
FileIndex : 3569-3571
FileIndex : 3573-3574
FileIndex : 3584-3585
FileIndex : 3587
FileIndex : 3589
FileIndex : 3591
FileIndex : 3593-3594
FileIndex : 3597-3599
FileIndex : 3649-5484
count : 5303
found : 0
done : no
positioning : 1
fast_reject : 1
Next : 0x0
Root bsr : 0x28817178
VolumeName : TestVolume002
MediaType : FileMedia
Device : FileStorage
Slot : 0
SessId : 2
SessTime : 1191598806
VolFile : 0-0
VolBlock : 222-5452180
FileIndex : 1-181
count : 181
found : 0
done : no
positioning : 0
fast_reject : 0
localhost-sd: read.c:59-3 Start read data.
localhost-sd: acquire.c:108-3 MediaType dcr=DDS-4 dev=DDS-4
localhost-sd: acquire.c:210-3 opened dev "Drive-0"
(/usr/home/dan/src/BaculaRegr
essionTesting/tmp/disk-changer/drive0) OK
localhost-sd: acquire.c:213-3 calling read-vol-label
localhost-sd: reserve.c:311-3 reserve_volume TestVolume001
localhost-sd: reserve.c:179-3 List from begin reserve_volume:
TestVolume001
at 2 88090b8
on
device "Drive-0" (/usr/home/dan/src/BaculaRegressionTesting/tmp/disk-
changer/drive0)
localhost-sd: reserve.c:330-3 OK, vol=TestVolume001 on device.
localhost-sd: reserve.c:179-3 List from end new volume: TestVolume001
at
288090b 8 on
device
"Drive-0" (/usr/home/dan/src/BaculaRegressionTesting/tmp/disk-change
r/drive0)
Volume Label:
Id : Bacula 1.0 immortal
VerNo : 11
VolName : TestVolume001
PrevVolName :
VolFile : 0
LabelType : VOL_LABEL
LabelSize : 182
PoolName : Default
MediaType : DDS-4
PoolType : Backup
HostName : pg82.unixathome.org
Date label written: 05-Oct-2007 15:40
localhost-sd: acquire.c:293-3 Dec reserve=0 dev="Drive-0"
(/usr/home/dan/src/Bac
ulaRegressionTesting/tmp/disk-changer/drive0)
localhost-sd: acquire.c:108-3 MediaType dcr=FileMedia dev=DDS-4
localhost-sd: acquire.c:119-3 Changing device. Want Media
Type="FileMedia"
have= "DDS-
4"
device="Drive-0"
(/usr/home/dan/src/BaculaRegressionTesting/tmp/disk-changer/d
rive0)
localhost-sd: reserve.c:970-3 search res for FileStorage
localhost-sd: reserve.c:973-3 Try match changer res=DDS-4
localhost-sd: reserve.c:999-3 Try match res=Drive-0
localhost-sd: reserve.c:999-3 Try match res=FileStorage
localhost-sd: reserve.c:1036-3 chk MediaType device=FileMedia
request=FileMedia
localhost-sd: reserve.c:1059-3 try reserve FileStorage
localhost-sd: reserve.c:1194-3 Inc reserve=1 dev="FileStorage"
(/usr/home/dan/sr
c/BaculaRegressionTesting/tmp) 2870c818
localhost-sd: reserve.c:1131-3 Read reserved=1 dev_name=FileStorage
mediatype=Fi
leMedia pool=Default ok=1
localhost-sd: reserve.c:1012-3 Device FileStorage reserved=1 for
read.
localhost-sd: acquire.c:154-3 Media Type change. New device
"FileStorage"
(/usr
/home/dan/src/BaculaRegressionTesting/tmp) chosen.
localhost-sd: acquire.c:210-3 opened dev "FileStorage"
/(/usr/home/dan/src/Bacula
RegressionTesting/tmp) OK
localhost-sd: acquire.c:213-3 calling read-vol-label
localhost-sd: reserve.c:311-3 reserve_volume TestVolume002
localhost-sd: reserve.c:179-3 List from begin reserve_volume:
TestVolume001
at 2 88090b8
on
device "Drive-0" (/usr/home/dan/src/BaculaRegressionTesting/tmp/disk-
changer/drive0)
localhost-sd: reserve.c:236-3 new Vol=TestVolume002 at 28809958
dev="FileStorage
"
(/usr/home/dan/src/BaculaRegressionTesting/tmp)
localhost-sd: reserve.c:179-3 List from end new volume: TestVolume001
at
288090b 8 on
device
"Drive-0" (/usr/home/dan/src/BaculaRegressionTesting/tmp/disk-change
r/drive0)
localhost-sd: reserve.c:179-3 List from end new volume: TestVolume002
at
2880995 8 on
device
"FileStorage" (/usr/home/dan/src/BaculaRegressionTesting/tmp)
Volume Label:
Id : Bacula 1.0 immortal
VerNo : 11
VolName : TestVolume002
PrevVolName :
VolFile : 0
LabelType : VOL_LABEL
LabelSize : 186
PoolName : Default
MediaType : FileMedia
PoolType : Backup
HostName : pg82.unixathome.org
Date label written: 05-Oct-2007 15:40
localhost-sd: acquire.c:293-3 Dec reserve=0 dev="FileStorage"
(/usr/home/dan/src
/BaculaRegressionTesting/tmp)
localhost-sd: reserve.c:486-3 free_volume TestVolume002
dev="FileStorage"
/(/usr/
home/dan/src/BaculaRegressionTesting/tmp)
localhost-sd: reserve.c:179-3 List from free_volume: TestVolume001 at
288090b8 o n
device
"Drive-0" (/usr/home/dan/src/BaculaRegressionTesting/tmp/disk-
changer/d
rive0)
localhost-sd: read.c:96-3 Done reading.
You have messages.
messages
05-Oct 15:40 localhost-dir: Start Restore Job
RestoreFiles.2007-10-05_15.40.06
05-Oct 15:40 localhost-dir: Using Device "Drive-0"
05-Oct 15:40 localhost-sd: 3301 Issuing autochanger "loaded? drive 0"
command.
05-Oct 15:40 localhost-sd: 3302 Autochanger "loaded? drive 0", result
is
Slot 1.
05-Oct 15:40 localhost-sd: 3301 Issuing autochanger "loaded? drive 0"
command.
05-Oct 15:40 localhost-sd: 3302 Autochanger "loaded? drive 0", result
is
Slot 1.
05-Oct 15:40 localhost-sd: Ready to read from volume "TestVolume001"
on
device "
Drive-0"
(/usr/home/dan/src/BaculaRegressionTesting/tmp/disk-changer/drive0).
05-Oct 15:40 localhost-sd: Forward spacing Volume "TestVolume001" to
file:block
0:218.
05-Oct 15:41 localhost-sd: End of file 0 on device "Drive-0"
(/usr/home/dan/src/
BaculaRegressionTesting/tmp/disk-changer/drive0), Volume
"TestVolume001"
05-Oct 15:41 localhost-sd: End of Volume at file 0 on device "Drive-
0"
(/usr/hom
e/dan/src/BaculaRegressionTesting/tmp/disk-changer/drive0), Volume
"TestVolume00
1"
05-Oct 15:41 localhost-sd: acquire.c:116 Changing device. Want Media
Type="FileM
edia"
have="DDS-4"
device="Drive-0"
(/usr/home/dan/src/BaculaRegressionTesting/tmp/disk-changer/d
rive0)
05-Oct 15:41 localhost-sd: Media Type change. New device
"FileStorage"
(/usr/ho
me/dan/src/BaculaRegressionTesting/tmp) chosen.
05-Oct 15:41 localhost-sd: Ready to read from volume "TestVolume002"
on
device "
FileStorage" (/usr/home/dan/src/BaculaRegressionTesting/tmp).
05-Oct 15:41 localhost-sd: Forward spacing Volume "TestVolume002" to
file:block
0:222.
05-Oct 15:41 localhost-sd: End of Volume at file 0 on device
"FileStorage"
(/usr
/home/dan/src/BaculaRegressionTesting/tmp), Volume "TestVolume002"
05-Oct 15:41 localhost-sd: End of all volumes.
05-Oct 15:41 localhost-dir: Bacula localhost-dir 2.3.6 (30Sep07):
05-Oct-2007 15
:41:03
Build OS: i386-unknown-freebsd7.0 freebsd 7.0-CURRENT
JobId: 3
Job: RestoreFiles.2007-10-05_15.40.06
Restore Client: localhost-fd
Start time: 05-Oct-2007 15:40:47
End time: 05-Oct-2007 15:41:03
Files Expected: 5,484
Files Restored: 5,484
Bytes Restored: 68,392,516
Rate: 4274.5 KB/s
FD Errors: 0
FD termination status: OK
SD termination status: OK
Termination: Restore OK
05-Oct 15:41 localhost-dir: Begin pruning Jobs.
05-Oct 15:41 localhost-dir: No Jobs found to prune.
05-Oct 15:41 localhost-dir: Begin pruning Files.
05-Oct 15:41 localhost-dir: No Files found to prune.
05-Oct 15:41 localhost-dir: End auto prune.
@tee
quit
localhost-sd: cram-md5.c:73-0 send: auth cram-md5
<[EMAIL PROTECTED]
st-sd> ssl=0
Pool Maxsize Maxused Inuse
NoPool 256 3 0
NAME 130 0 0
FNAME 256 11 0
MSG 65636 10 0
EMSG 1024 1 0
localhost-sd: stored.c:587-0 Term device
/usr/home/dan/src/BaculaRegressionTesti
ng/tmp/disk-changer/drive0
localhost-sd: stored.c:587-0 Term device
/usr/home/dan/src/BaculaRegressionTesti
ng/tmp
Pool Maxsize Maxused Inuse
NoPool 256 12 0
NAME 130 10 0
FNAME 256 4 0
MSG 65636 8 0
EMSG 1024 3 0
===== incremental-2media OK 15:41:19 =====
--
Dan Langille - http://www.langille.org/
Available for hire: http://www.freebsddiary.org/dan_langille.php
-------------------------------------------------------------------------
This SF.net email is sponsored by: Splunk Inc.
Still grepping through log files to find problems? Stop.
Now Search log events and configuration files using AJAX and a browser.
Download your FREE copy of Splunk now >> http://get.splunk.com/
_______________________________________________
Bacula-devel mailing list
[email protected]
https://lists.sourceforge.net/lists/listinfo/bacula-devel
