On 7 Oct 2007 at 9:37, Kern Sibbald wrote: > 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.
That may be wonky copy/paste followed by wrapping in replies... something like that. > > 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 > > -- 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
