Dear Kern,
in message <[EMAIL PROTECTED]> you wrote:
>
> Thanks for the feedback. I'm happy to see that your problem is resolved.
I start seeing this problem now, too, especially when running several
jobs (with data spooling) in parallel, and when the tape gets full.
> I guess that the next time I respond, I should not only mention the fact that
> Bacula tends to expose a lot of driver bugs AND hardware problems, both of
> which are difficult and time consuming to debug ...
I don't think it's either of these in my case. When I run into this
situation, I can reliably reproduce the problem (but I don't know
which exact conditions trigger it in the first place). Here is what
happens:
17-Aug 00:40 nyx-sd: Spooling data ...
17-Aug 00:40 nyx-sd: Committing spooled data to Volume "K-V-DAT-3". Despooling
1,985,286 bytes ...
17-Aug 00:40 nyx-sd: Source-Other.2006-08-17_00.10.04 Error: block.c:538 Write
error at 22:2740 on device "DDS-3" (/dev/nst0). ERR=Device or resource busy.
17-Aug 00:40 nyx-sd: Re-read of last block succeeded.
17-Aug 00:40 nyx-sd: End of medium on Volume "K-V-DAT-3" Bytes=15,118,094,426
Blocks=234,370 at 17-Aug-2006 00:40.
17-Aug 00:41 nyx-sd: 3301 Issuing autochanger "loaded drive 0" command.
17-Aug 00:41 nyx-sd: 3302 Autochanger "loaded drive 0", result is Slot 3.
17-Aug 00:41 nyx-sd: 3307 Issuing autochanger "unload slot 3, drive 0" command.
17-Aug 00:42 nyx-sd: 3304 Issuing autochanger "load slot 4, drive 0" command.
17-Aug 00:43 nyx-sd: 3305 Autochanger "load slot 4, drive 0", status is OK.
17-Aug 00:43 nyx-sd: 3301 Issuing autochanger "loaded drive 0" command.
17-Aug 00:43 nyx-sd: 3302 Autochanger "loaded drive 0", result is Slot 4.
17-Aug 00:43 nyx-sd: Wrote label to prelabeled Volume "K-V-DAT-4" on device
"DDS-3" (/dev/nst0)
17-Aug 00:43 nyx-sd: New volume "K-V-DAT-4" mounted on device "DDS-3"
(/dev/nst0) at 17-Aug-2006 00:43.
17-Aug 00:43 nyx-sd: Source-Other.2006-08-17_00.10.04 Error: block.c:538 Write
error at 0:1 on device "DDS-3" (/dev/nst0). ERR=Device or resource busy.
17-Aug 00:43 nyx-sd: Source-Other.2006-08-17_00.10.04 Error: Re-read of last
block OK, but block numbers differ. Last block=0 Current block=0.
17-Aug 00:43 nyx-sd: Source-Other.2006-08-17_00.10.04 Fatal error: spool.c:249
Fatal append error on device "DDS-3" (/dev/nst0): ERR=dev.c:678 Rewind error on
"DDS-3" (/dev/nst0). ERR=Input/output error.
...
18-Aug 00:40 nyx-sd: Committing spooled data to Volume "K-V-DAT-4". Despooling
948,750,016 bytes ...
18-Aug 00:40 nyx-sd: Castor-Home-1.2006-08-18_00.05.00 Error: block.c:538 Write
error at 2:6438 on device "DDS-3" (/dev/nst0). ERR=Device or resource busy.
18-Aug 00:41 nyx-sd: Re-read of last block succeeded.
18-Aug 00:41 nyx-sd: End of medium on Volume "K-V-DAT-4" Bytes=691,688,327
Blocks=10,727 at 18-Aug-2006 00:41.
18-Aug 00:41 castor-dir: Recycled volume "K-V-DAT-1"
18-Aug 00:41 nyx-sd: 3301 Issuing autochanger "loaded drive 0" command.
18-Aug 00:41 nyx-sd: 3302 Autochanger "loaded drive 0", result is Slot 4.
18-Aug 00:41 nyx-sd: 3307 Issuing autochanger "unload slot 4, drive 0" command.
18-Aug 00:41 nyx-sd: 3304 Issuing autochanger "load slot 1, drive 0" command.
18-Aug 00:42 nyx-sd: 3305 Autochanger "load slot 1, drive 0", status is OK.
18-Aug 00:42 nyx-sd: 3301 Issuing autochanger "loaded drive 0" command.
18-Aug 00:42 nyx-sd: 3302 Autochanger "loaded drive 0", result is Slot 1.
18-Aug 00:42 nyx-sd: Recycled volume "K-V-DAT-1" on device "DDS-3" (/dev/nst0),
all previous data lost.
18-Aug 00:42 nyx-sd: New volume "K-V-DAT-1" mounted on device "DDS-3"
(/dev/nst0) at 18-Aug-2006 00:42.
18-Aug 00:42 nyx-sd: Castor-Home-1.2006-08-18_00.05.00 Error: block.c:538 Write
error at 0:1 on device "DDS-3" (/dev/nst0). ERR=Device or resource busy.
18-Aug 00:42 nyx-sd: Castor-Home-1.2006-08-18_00.05.00 Error: Re-read of last
block OK, but block numbers differ. Last block=0 Current block=0.
18-Aug 00:42 nyx-sd: Castor-Home-1.2006-08-18_00.05.00 Fatal error: spool.c:249
Fatal append error on device "DDS-3" (/dev/nst0): ERR=dev.c:678 Rewind error on
"DDS-3" (/dev/nst0). ERR=Input/output error.
...
18-Aug 00:42 nyx-sd: 3301 Issuing autochanger "loaded drive 0" command.
18-Aug 00:42 nyx-sd: 3302 Autochanger "loaded drive 0", result is Slot 1.
18-Aug 00:42 nyx-sd: Castor-Home-2.2006-08-18_00.10.00 Error: block.c:538 Write
error at 0:0 on device "DDS-3" (/dev/nst0). ERR=Device or resource busy.
18-Aug 00:43 nyx-sd: Castor-Home-2.2006-08-18_00.10.00 Error: Backspace record
at EOT failed. ERR=Input/output error
18-Aug 00:43 nyx-sd: Castor-Home-2.2006-08-18_00.10.00 Error: label.c:441
Unable to write device "DDS-3" (/dev/nst0): ERR=dev.c:1430 ioctl MTBSR error on
"DDS-3" (/dev/nst0). ERR=Input/output error.
18-Aug 00:43 nyx-sd: Marking Volume "K-V-DAT-1" in Error in Catalog.
In this state, the newly mounted volumes ("K-V-DAT-4" and
"K-V-DAT-1") are empty, i. e. they have NO data on it. Even the
previously existing bacula labels are gone.
I can now reproduce this failure mode; for example, I try to recycle
the last corrupted tape (which has no data on it anyway): I unmount
it, delete it from the catalog, label it again (using the same or
another volume name), mount it again. The hanging backup job will
attempt to write on it again, and corrupt it again:
18-Aug 01:14 nyx-sd: 3301 Issuing autochanger "loaded drive 0" command.
18-Aug 01:14 nyx-sd: 3302 Autochanger "loaded drive 0", result is Slot 1.
18-Aug 01:14 nyx-sd: Castor-Home-2.2006-08-18_00.10.00 Error: block.c:538 Write
error at 0:0 on device "DDS-3" (/dev/nst0). ERR=Device or resource busy.
18-Aug 01:14 nyx-sd: Castor-Home-2.2006-08-18_00.10.00 Error: Backspace record
at EOT failed. ERR=Input/output error
18-Aug 01:14 nyx-sd: Castor-Home-2.2006-08-18_00.10.00 Error: label.c:441
Unable to write device "DDS-3" (/dev/nst0): ERR=dev.c:1430 ioctl MTBSR error on
"DDS-3" (/dev/nst0). ERR=Input/output error.
18-Aug 01:14 nyx-sd: Marking Volume "K-V-DAT-1" in Error in Catalog.
18-Aug 01:14 nyx-sd: Invalid slot=0 defined, cannot autoload Volume.
18-Aug 01:14 nyx-sd: Please mount Volume "K-T-DAT-2" on Storage Device "DDS-3"
(/dev/nst0) for Job Castor-Home-2.2006-08-18_00.10.00
18-Aug 01:38 nyx-sd: 3301 Issuing autochanger "loaded drive 0" command.
18-Aug 01:38 nyx-sd: 3302 Autochanger "loaded drive 0", result is Slot 1.
18-Aug 01:38 nyx-sd: Castor-Home-2.2006-08-18_00.10.00 Error: block.c:538 Write
error at 0:0 on device "DDS-3" (/dev/nst0). ERR=Device or resource busy.
18-Aug 01:38 nyx-sd: Castor-Home-2.2006-08-18_00.10.00 Error: Backspace record
at EOT failed. ERR=Input/output error
18-Aug 01:38 nyx-sd: Castor-Home-2.2006-08-18_00.10.00 Error: label.c:441
Unable to write device "DDS-3" (/dev/nst0): ERR=dev.c:1430 ioctl MTBSR error on
"DDS-3" (/dev/nst0). ERR=Input/output error.
18-Aug 01:38 nyx-sd: Marking Volume "K-V-DAT-1" in Error in Catalog.
18-Aug 01:38 nyx-sd: Invalid slot=0 defined, cannot autoload Volume.
18-Aug 01:38 nyx-sd: Please mount Volume "K-T-DAT-2" on Storage Device "DDS-3"
(/dev/nst0) for Job Castor-Home-2.2006-08-18_00.10.00
18-Aug 01:43 nyx-sd: Please mount Volume "K-T-DAT-2" on Storage Device "DDS-3"
(/dev/nst0) for Job Castor-Home-2.2006-08-18_00.10.00
18-Aug 03:43 nyx-sd: Please mount Volume "K-T-DAT-2" on Storage Device "DDS-3"
(/dev/nst0) for Job Castor-Home-2.2006-08-18_00.10.00
18-Aug 07:43 nyx-sd: Please mount Volume "K-T-DAT-2" on Storage Device "DDS-3"
(/dev/nst0) for Job Castor-Home-2.2006-08-18_00.10.00
18-Aug 10:19 nyx-sd: 3301 Issuing autochanger "loaded drive 0" command.
18-Aug 10:19 nyx-sd: 3302 Autochanger "loaded drive 0", result is Slot 1.
18-Aug 10:19 nyx-sd: Castor-Home-2.2006-08-18_00.10.00 Error: block.c:538 Write
error at 0:0 on device "DDS-3" (/dev/nst0). ERR=Device or resource busy.
18-Aug 10:19 nyx-sd: Castor-Home-2.2006-08-18_00.10.00 Error: Backspace record
at EOT failed. ERR=Input/output error
18-Aug 10:19 nyx-sd: Castor-Home-2.2006-08-18_00.10.00 Error: label.c:441
Unable to write device "DDS-3" (/dev/nst0): ERR=dev.c:1430 ioctl MTBSR error on
"DDS-3" (/dev/nst0). ERR=Input/output error.
18-Aug 10:19 nyx-sd: Marking Volume "K-V-DAT-1" in Error in Catalog.
18-Aug 10:19 nyx-sd: Invalid slot=0 defined, cannot autoload Volume.
18-Aug 10:19 nyx-sd: Please mount Volume "K-T-DAT-2" on Storage Device "DDS-3"
(/dev/nst0) for Job Castor-Home-2.2006-08-18_00.10.00
18-Aug 10:29 nyx-sd: 3301 Issuing autochanger "loaded drive 0" command.
18-Aug 10:29 nyx-sd: 3302 Autochanger "loaded drive 0", result is Slot 1.
18-Aug 10:29 nyx-sd: Castor-Home-2.2006-08-18_00.10.00 Error: block.c:538 Write
error at 0:0 on device "DDS-3" (/dev/nst0). ERR=Device or resource busy.
18-Aug 10:29 nyx-sd: Castor-Home-2.2006-08-18_00.10.00 Error: Backspace record
at EOT failed. ERR=Input/output error
18-Aug 10:29 nyx-sd: Castor-Home-2.2006-08-18_00.10.00 Error: label.c:441
Unable to write device "DDS-3" (/dev/nst0): ERR=dev.c:1430 ioctl MTBSR error on
"DDS-3" (/dev/nst0). ERR=Input/output error.
18-Aug 10:29 nyx-sd: Marking Volume "K-V-DAT-1" in Error in Catalog.
18-Aug 10:29 nyx-sd: Please mount Volume "K-V-DAT-1" on Storage Device "DDS-3"
(/dev/nst0) for Job Castor-Home-2.2006-08-18_00.10.00
To me it seems as if bacula somehwat gets confused when several jobs
are despooling data in parallel, and a medium gets full and is
changed.
All this is with Bacula 1.38.11 (28Jun06).
Any ideas?
Best regards,
Wolfgang Denk
--
Software Engineering: Embedded and Realtime Systems, Embedded Linux
Phone: (+49)-8142-66989-10 Fax: (+49)-8142-66989-80 Email: [EMAIL PROTECTED]
When the ax entered the forest, the trees said, "The handle is one of
us!" -- Turkish proverb
-------------------------------------------------------------------------
Using Tomcat but need to do more? Need to support web services, security?
Get stuff done quickly with pre-integrated technology to make your job easier
Download IBM WebSphere Application Server v.1.0.1 based on Apache Geronimo
http://sel.as-us.falkag.net/sel?cmd=lnk&kid=120709&bid=263057&dat=121642
_______________________________________________
Bacula-users mailing list
Bacula-users@lists.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/bacula-users
