On Friday 05 October 2007 18:21, Dan Langille wrote: > 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 traceback shows a problem, but the output of the debugger does not seem to be very coherent. In your debug output, there is some strange formatting problem that space files the output to a bit past the middle of a line then prints the last character or characters -- almost as if it inserted a couple of tabs. Kern > > 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 ===== ------------------------------------------------------------------------- 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
