I'm just documenting this test failure. It's is more of a freeze,
than a failure, but I have seen this issue before. Waiting for an
appendable volume.
On the console, I see:
=== Starting 2drive-incremental-2disk at 20:40:06 ===
That's about an hour ago. The test should take about 6 minutes.
I am going to control-c this, and run that given test about 200 times
overnight, with debug on.
FYI, here is what bconsole said.
Kern: you'll be tempted to analyse this issue, but don't, yet. ;)
Let someone else try. :)
[EMAIL PROTECTED]:~/src/BaculaRegressionTesting] $ bin/bconsole
Connecting to Director localhost:8101
1000 OK: localhost-dir Version: 2.3.4 (12 September 2007)
Enter a period to cancel a command.
*m
12-Sep 20:40 localhost-dir: No prior Full backup Job record found.
12-Sep 20:40 localhost-dir: No prior or suitable Full backup found in
catalog. Doing FULL backup.
12-Sep 20:40 localhost-dir: No prior Full backup Job record found.
12-Sep 20:40 localhost-dir: No prior or suitable Full backup found in
catalog. Doing FULL backup.
12-Sep 20:40 localhost-dir: Start Backup JobId 1,
Job=NightlySave.2007-09-12_20.40.16
12-Sep 20:40 localhost-dir: Using Device "Drive-0"
12-Sep 20:40 localhost-sd: 3301 Issuing autochanger "loaded? drive 0"
command.
12-Sep 20:40 localhost-dir: No prior Full backup Job record found.
12-Sep 20:40 localhost-dir: No prior or suitable Full backup found in
catalog. Doing FULL backup.
12-Sep 20:40 localhost-dir: Start Backup JobId 2,
Job=NightlySave.2007-09-12_20.40.17
12-Sep 20:40 localhost-dir: Start Backup JobId 3,
Job=NightlySave.2007-09-12_20.40.18
12-Sep 20:40 localhost-dir: Using Device "Drive-1"
12-Sep 20:40 localhost-dir: Using Device "Drive-0"
12-Sep 20:40 localhost-sd: 3302 Autochanger "loaded? drive 0", result
is Slot 1.
12-Sep 20:40 localhost-sd: 3301 Issuing autochanger "loaded? drive 0"
command.
12-Sep 20:40 localhost-dir: No prior Full backup Job record found.
12-Sep 20:40 localhost-dir: No prior or suitable Full backup found in
catalog. Doing FULL backup.
12-Sep 20:40 localhost-sd: 3302 Autochanger "loaded? drive 0", result
is Slot 1.
12-Sep 20:40 localhost-sd: 3301 Issuing autochanger "loaded? drive 1"
command.
12-Sep 20:40 localhost-sd: Wrote label to prelabeled Volume
"TestVolume001" on device "Drive-0"
(/usr/home/dan/src/BaculaRegressionTesting/tmp/disk-changer/drive0)
12-Sep 20:40 localhost-sd: Spooling data ...
12-Sep 20:40 localhost-sd: Spooling data ...
12-Sep 20:40 localhost-dir: No prior Full backup Job record found.
12-Sep 20:40 localhost-dir: No prior or suitable Full backup found in
catalog. Doing FULL backup.
12-Sep 20:40 localhost-sd: Job write elapsed time = 00:00:01,
Transfer rate = 866.1 K bytes/second
12-Sep 20:40 localhost-sd: Job write elapsed time = 00:00:01,
Transfer rate = 866.1 K bytes/second
12-Sep 20:40 localhost-sd: Committing spooled data to Volume
"TestVolume001". Despooling 868,696 bytes ...
12-Sep 20:40 localhost-sd: Despooling elapsed time = 00:00:01,
Transfer rate = 868.6 K bytes/second
12-Sep 20:40 localhost-sd: Committing spooled data to Volume
"TestVolume001". Despooling 868,696 bytes ...
12-Sep 20:40 localhost-sd: Sending spooled attrs to the Director.
Despooling 13,006 bytes ...
12-Sep 20:40 localhost-sd: Despooling elapsed time = 00:00:01,
Transfer rate = 868.6 K bytes/second
12-Sep 20:40 localhost-sd: Sending spooled attrs to the Director.
Despooling 13,006 bytes ...
12-Sep 20:40 localhost-dir: Bacula localhost-dir 2.3.4 (12Sep07): 12-
Sep-2007 20:40:20
Build OS: i386-unknown-freebsd7.0 freebsd 7.0-CURRENT
JobId: 1
Job: NightlySave.2007-09-12_20.40.16
Backup Level: Full (upgraded from Incremental)
Client: "2drive2disk" 2.3.4 (12Sep07) i386-unknown-
freebsd7.0,freebsd,7.0-CURRENT
FileSet: "Full Set" 2007-09-12 20:40:16
Pool: "Default" (From Job resource)
Storage: "DDS-4" (From Job resource)
Scheduled time: 12-Sep-2007 20:40:16
Start time: 12-Sep-2007 20:40:17
End time: 12-Sep-2007 20:40:20
Elapsed time: 3 secs
Priority: 10
FD Files Written: 42
SD Files Written: 42
FD Bytes Written: 859,964 (859.9 KB)
SD Bytes Written: 866,164 (866.1 KB)
Rate: 286.7 KB/s
Software Compression: None
VSS: no
Encryption: no
Volume name(s): TestVolume001
Volume Session Id: 1
Volume Session Time: 1189644006
Last Volume Bytes: 1,737,274 (1.737 MB)
Non-fatal FD errors: 0
SD Errors: 0
FD termination status: OK
SD termination status: OK
Termination: Backup OK
12-Sep 20:40 localhost-dir: Begin pruning Jobs.
12-Sep 20:40 localhost-sd: 3302 Autochanger "loaded? drive 1", result
is Slot 2.
12-Sep 20:40 localhost-dir: No Jobs found to prune.
12-Sep 20:40 localhost-dir: Begin pruning Files.
12-Sep 20:40 localhost-dir: No Files found to prune.
12-Sep 20:40 localhost-dir: End auto prune.
12-Sep 20:40 localhost-dir: Start Backup JobId 4,
Job=NightlySave.2007-09-12_20.40.19
12-Sep 20:40 localhost-dir: Bacula localhost-dir 2.3.4 (12Sep07): 12-
Sep-2007 20:40:20
Build OS: i386-unknown-freebsd7.0 freebsd 7.0-CURRENT
JobId: 3
Job: NightlySave.2007-09-12_20.40.18
Backup Level: Full (upgraded from Incremental)
Client: "2drive2disk" 2.3.4 (12Sep07) i386-unknown-
freebsd7.0,freebsd,7.0-CURRENT
FileSet: "Full Set" 2007-09-12 20:40:16
Pool: "Default" (From Job resource)
Storage: "DDS-4" (From Job resource)
Scheduled time: 12-Sep-2007 20:40:17
Start time: 12-Sep-2007 20:40:18
End time: 12-Sep-2007 20:40:20
Elapsed time: 2 secs
Priority: 10
FD Files Written: 42
SD Files Written: 42
FD Bytes Written: 859,964 (859.9 KB)
SD Bytes Written: 866,164 (866.1 KB)
Rate: 430.0 KB/s
Software Compression: None
VSS: no
Encryption: no
Volume name(s): TestVolume001
Volume Session Id: 3
Volume Session Time: 1189644006
Last Volume Bytes: 1,737,274 (1.737 MB)
Non-fatal FD errors: 0
SD Errors: 0
FD termination status: OK
SD termination status: OK
Termination: Backup OK
12-Sep 20:40 localhost-dir: Begin pruning Jobs.
12-Sep 20:40 localhost-sd: 3301 Issuing autochanger "loaded? drive 1"
command.
12-Sep 20:40 localhost-sd: 3302 Autochanger "loaded? drive 1", result
is Slot 2.
12-Sep 20:40 localhost-dir: No Jobs found to prune.
12-Sep 20:40 localhost-dir: Begin pruning Files.
12-Sep 20:40 localhost-sd: Wrote label to prelabeled Volume
"TestVolume002" on device "Drive-1"
(/usr/home/dan/src/BaculaRegressionTesting/tmp/disk-changer/drive1)
12-Sep 20:40 localhost-dir: No Files found to prune.
12-Sep 20:40 localhost-dir: End auto prune.
12-Sep 20:40 localhost-dir: Using Device "Drive-0"
12-Sep 20:40 localhost-sd: Spooling data ...
12-Sep 20:40 localhost-sd: Job write elapsed time = 00:00:01,
Transfer rate = 866.1 K bytes/second
12-Sep 20:40 localhost-sd: Committing spooled data to Volume
"TestVolume002". Despooling 868,696 bytes ...
12-Sep 20:40 localhost-sd: Despooling elapsed time = 00:00:01,
Transfer rate = 868.6 K bytes/second
12-Sep 20:40 localhost-sd: 3301 Issuing autochanger "loaded? drive 0"
command.
12-Sep 20:40 localhost-sd: Sending spooled attrs to the Director.
Despooling 13,006 bytes ...
12-Sep 20:40 localhost-sd: 3302 Autochanger "loaded? drive 0", result
is Slot 1.
12-Sep 20:40 localhost-sd: 3307 Issuing autochanger "unload slot 1,
drive 0" command.
12-Sep 20:40 localhost-dir: Bacula localhost-dir 2.3.4 (12Sep07): 12-
Sep-2007 20:40:21
Build OS: i386-unknown-freebsd7.0 freebsd 7.0-CURRENT
JobId: 2
Job: NightlySave.2007-09-12_20.40.17
Backup Level: Full (upgraded from Incremental)
Client: "2drive2disk" 2.3.4 (12Sep07) i386-unknown-
freebsd7.0,freebsd,7.0-CURRENT
FileSet: "Full Set" 2007-09-12 20:40:16
Pool: "Default" (From Job resource)
Storage: "DDS-4" (From Job resource)
Scheduled time: 12-Sep-2007 20:40:16
Start time: 12-Sep-2007 20:40:18
End time: 12-Sep-2007 20:40:21
Elapsed time: 3 secs
Priority: 10
FD Files Written: 42
SD Files Written: 42
FD Bytes Written: 859,964 (859.9 KB)
SD Bytes Written: 866,164 (866.1 KB)
Rate: 286.7 KB/s
Software Compression: None
VSS: no
Encryption: no
Volume name(s): TestVolume002
Volume Session Id: 2
Volume Session Time: 1189644006
Last Volume Bytes: 868,746 (868.7 KB)
Non-fatal FD errors: 0
SD Errors: 0
FD termination status: OK
SD termination status: OK
Termination: Backup OK
12-Sep 20:40 localhost-dir: Begin pruning Jobs.
12-Sep 20:40 localhost-dir: No Jobs found to prune.
12-Sep 20:40 localhost-dir: Begin pruning Files.
12-Sep 20:40 localhost-dir: No Files found to prune.
12-Sep 20:40 localhost-dir: End auto prune.
12-Sep 20:40 localhost-dir: Start Backup JobId 5,
Job=NightlySave.2007-09-12_20.40.20
12-Sep 20:40 localhost-dir: Using Device "Drive-1"
12-Sep 20:40 localhost-sd: 3304 Issuing autochanger "load slot 2,
drive 0" command.
12-Sep 20:40 localhost-sd: 3301 Issuing autochanger "loaded? drive 1"
command.
12-Sep 20:40 localhost-sd: 3305 Autochanger "load slot 2, drive 0",
status is OK.
12-Sep 20:40 localhost-sd: 3302 Autochanger "loaded? drive 1", result
is Slot 2.
12-Sep 20:40 localhost-sd: 3307 Issuing autochanger "unload slot 2,
drive 1" command.
12-Sep 20:40 localhost-sd: 3304 Issuing autochanger "load slot 1,
drive 1" command.
12-Sep 20:40 localhost-sd: 3305 Autochanger "load slot 1, drive 1",
status is OK.
12-Sep 20:40 localhost-sd: 3301 Issuing autochanger "loaded? drive 0"
command.
12-Sep 20:40 localhost-sd: 3301 Issuing autochanger "loaded? drive 1"
command.
12-Sep 20:40 localhost-sd: 3302 Autochanger "loaded? drive 1", result
is Slot 1.
12-Sep 20:40 localhost-sd: Volume "TestVolume001" previously written,
moving to end of data.
12-Sep 20:40 localhost-sd: Ready to append to end of Volume
"TestVolume001" size=1737274
12-Sep 20:40 localhost-sd: 3302 Autochanger "loaded? drive 0", result
is Slot 2.
12-Sep 20:40 localhost-sd: Volume "TestVolume002" previously written,
moving to end of data.
12-Sep 20:40 localhost-sd: NightlySave.2007-09-12_20.40.19 Error:
Bacula cannot write on disk Volume "TestVolume002" because: The sizes
do not match! Volume=868746 Catalog=218
12-Sep 20:40 localhost-sd: Marking Volume "TestVolume002" in Error in
Catalog.
12-Sep 20:40 localhost-sd: Spooling data ...
12-Sep 20:40 localhost-sd: Job write elapsed time = 00:00:01,
Transfer rate = 866.1 K bytes/second
12-Sep 20:40 localhost-sd: Committing spooled data to Volume
"TestVolume001". Despooling 868,696 bytes ...
12-Sep 20:40 localhost-sd: Despooling elapsed time = 00:00:01,
Transfer rate = 868.6 K bytes/second
12-Sep 20:40 localhost-sd: Sending spooled attrs to the Director.
Despooling 13,006 bytes ...
12-Sep 20:40 localhost-dir: Bacula localhost-dir 2.3.4 (12Sep07): 12-
Sep-2007 20:40:26
Build OS: i386-unknown-freebsd7.0 freebsd 7.0-CURRENT
JobId: 5
Job: NightlySave.2007-09-12_20.40.20
Backup Level: Full (upgraded from Incremental)
Client: "2drive2disk" 2.3.4 (12Sep07) i386-unknown-
freebsd7.0,freebsd,7.0-CURRENT
FileSet: "Full Set" 2007-09-12 20:40:16
Pool: "Default" (From Job resource)
Storage: "DDS-4" (From Job resource)
Scheduled time: 12-Sep-2007 20:40:19
Start time: 12-Sep-2007 20:40:22
End time: 12-Sep-2007 20:40:26
Elapsed time: 4 secs
Priority: 10
FD Files Written: 42
SD Files Written: 42
FD Bytes Written: 859,964 (859.9 KB)
SD Bytes Written: 866,164 (866.1 KB)
Rate: 215.0 KB/s
Software Compression: None
VSS: no
Encryption: no
Volume name(s): TestVolume001
Volume Session Id: 5
Volume Session Time: 1189644006
Last Volume Bytes: 2,605,802 (2.605 MB)
Non-fatal FD errors: 0
SD Errors: 0
FD termination status: OK
SD termination status: OK
Termination: Backup OK
12-Sep 20:40 localhost-dir: Begin pruning Jobs.
12-Sep 20:40 localhost-dir: No Jobs found to prune.
12-Sep 20:40 localhost-dir: Begin pruning Files.
12-Sep 20:40 localhost-dir: No Files found to prune.
12-Sep 20:40 localhost-dir: End auto prune.
12-Sep 20:40 localhost-sd: Job NightlySave.2007-09-12_20.40.19
waiting. Cannot find any appendable volumes.
Please use the "label" command to create a new Volume for:
Storage: "Drive-0"
(/usr/home/dan/src/BaculaRegressionTesting/tmp/disk-changer/drive0)
Pool: Default
Media type: DDS-4
12-Sep 20:40 localhost-dir: NightlySave.2007-09-12_20.40.19 Error:
message.c:719 Operator mail program terminated in error.
CMD=/usr/home/dan/src/BaculaRegressionTesting/bin/bsmtp -h localhost -
f "(Bacula regression Job NightlySave.2007-09-12_20.40.19)
[EMAIL PROTECTED]" -s "Regression: Intervention needed for
NightlySave.2007-09-12_20.40.19" [EMAIL PROTECTED]
ERR=Child exited with code 1
*
--
Dan Langille - http://www.langille.org/
Available for hire: http://www.freebsddiary.org/dan_langille.php
-------------------------------------------------------------------------
This SF.net email is sponsored by: Microsoft
Defy all challenges. Microsoft(R) Visual Studio 2005.
http://clk.atdmt.com/MRT/go/vse0120000070mrt/direct/01/
_______________________________________________
Bacula-devel mailing list
[email protected]
https://lists.sourceforge.net/lists/listinfo/bacula-devel
