[Bacula-bugs] [bacula 0000496]: Annoying error message from dev.c

SourceForge Headquarters 225 Broadway Suite 1600 San Diego, CA 92101 +1 (858) 454-5900

The following bug requires your FEEDBACK.
======================================================================
http://bugs.bacula.org/bug_view_advanced_page.php?bug_id=0000496
======================================================================
Reported By:                ifmpeter
Assigned To:                
======================================================================
Project:                    bacula
Bug ID:                     496
Category:                   Storage Daemon
Reproducibility:            always
Severity:                   minor
Priority:                   normal
Status:                     feedback
======================================================================
Date Submitted:             11-24-2005 05:16 PST
Last Modified:              11-24-2005 06:22 PST
======================================================================
Summary:                    Annoying error message from dev.c
Description: 
Whenever I run a backup job I every now and then get this 
message:

Subject: Bacula: Backup OK of Bakis Incremental

24-Nov 12:26 Bakis: Bakis.2005-11-24_12.24.36 Error: dev.c:381 Unable to
open device "DLT-0" (/dev/rmt/0cbn): ERR=I/O error

It seems this isn't a fatal error since it runs the backup anyway. Please
find enclosed the full output from a backup run:

24-Nov 12:24 Bakis: Start Backup JobId 6834,
Job=Bakis.2005-11-24_12.24.36
24-Nov 12:24 Bakis: 3301 Issuing autochanger "loaded drive 1" command.
24-Nov 12:24 Bakis: 3302 Autochanger "loaded drive 1", result: nothing
loaded.
24-Nov 12:24 Bakis: 3304 Issuing autochanger "load slot 86, drive 1"
command.
24-Nov 12:26 Bakis: 3305 Autochanger "load slot 86, drive 1", status is
OK.
24-Nov 12:26 Bakis: 3301 Issuing autochanger "loaded drive 1" command.
24-Nov 12:26 Bakis: 3302 Autochanger "loaded drive 1", result is Slot 86.
24-Nov 12:26 Bakis: Bakis.2005-11-24_12.24.36 Error: dev.c:381 Unable to
open device "DLT-0" (/dev/rmt/0cbn): ERR=I/O error
24-Nov 12:26 Bakis: Volume "LYSD085" previously written, moving to end of
data.
24-Nov 12:28 Bakis: Bakis.2005-11-24_12.24.36 Error: I cannot write on
Volume "LYSD085" because:
The number of files mismatch! Volume=6 Catalog=5
24-Nov 12:28 Bakis: Marking Volume "LYSD085" in Error in Catalog.
24-Nov 12:30 Bakis: There are no Jobs associated with Volume "LYSD077".
Marking it purged.
24-Nov 12:30 Bakis: There are no Jobs associated with Volume "LYSD079".
Marking it purged.
24-Nov 12:30 Bakis: There are no Jobs associated with Volume "LYSD080".
Marking it purged.
24-Nov 12:30 Bakis: There are no Jobs associated with Volume "LYSD082".
Marking it purged.
24-Nov 12:30 Bakis: There are no Jobs associated with Volume "LYSD086".
Marking it purged.
24-Nov 12:30 Bakis: There are no Jobs associated with Volume "LYSD087".
Marking it purged.
24-Nov 12:30 Bakis: There are no Jobs associated with Volume "LYSD088".
Marking it purged.
24-Nov 12:30 Bakis: There are no Jobs associated with Volume "LYSD089".
Marking it purged.
24-Nov 12:31 Bakis: Pruned 10 Jobs on Volume "LYSD090" from catalog.
24-Nov 12:32 Bakis: Pruned 6 Jobs on Volume "LYSD091" from catalog.
24-Nov 12:33 Bakis: Pruned 3 Jobs on Volume "LYSD092" from catalog.
24-Nov 12:33 Bakis: Pruned 6 Jobs on Volume "LYSD093" from catalog.
24-Nov 12:33 Bakis: There are no Jobs associated with Volume "LYSD108".
Marking it purged.
24-Nov 12:33 Bakis: There are no Jobs associated with Volume "LYSD109".
Marking it purged.
24-Nov 12:33 Bakis: There are no Jobs associated with Volume "LYSD110".
Marking it purged.
24-Nov 12:33 Bakis: There are no Jobs associated with Volume "LYSD111".
Marking it purged.
24-Nov 12:33 Bakis: Recycled volume "LYSD077"
24-Nov 12:33 Bakis: 3301 Issuing autochanger "loaded drive 1" command.
24-Nov 12:33 Bakis: 3302 Autochanger "loaded drive 1", result is Slot 86.
24-Nov 12:33 Bakis: 3307 Issuing autochanger "unload slot 86, drive 1"
command.
24-Nov 12:34 Bakis: 3304 Issuing autochanger "load slot 78, drive 1"
command.
24-Nov 12:35 Bakis: 3305 Autochanger "load slot 78, drive 1", status is
OK.
24-Nov 12:35 Bakis: 3301 Issuing autochanger "loaded drive 1" command.
24-Nov 12:35 Bakis: 3302 Autochanger "loaded drive 1", result is Slot 78.
24-Nov 12:35 Bakis: Bakis.2005-11-24_12.24.36 Error: dev.c:381 Unable to
open device "DLT-0" (/dev/rmt/0cbn): ERR=I/O error
24-Nov 12:36 Bakis: Recycled volume "LYSD077" on device "DLT-0"
(/dev/rmt/0cbn), all previous data lost.
24-Nov 12:36 Bakis: Spooling data ...
Bakis:      Filesystem change prohibited. Will not descend into /usr
Bakis:      Filesystem change prohibited. Will not descend into /var
Bakis:      Filesystem change prohibited. Will not descend into
/etc/svc/volatile
Bakis:      Filesystem change prohibited. Will not descend into /net
Bakis:      Filesystem change prohibited. Will not descend into
/system/contract
Bakis:      Filesystem change prohibited. Will not descend into
/system/object
Bakis:      Filesystem change prohibited. Will not descend into /vol
Bakis:      Filesystem change prohibited. Will not descend into /lysator
Bakis:      Filesystem change prohibited. Will not descend into
/var/bacula
Bakis:      Filesystem change prohibited. Will not descend into
/var/mysql
24-Nov 12:38 Bakis: Committing spooled data to Volume. Despooling
342,657,757 bytes ...
24-Nov 12:39 Bakis: Sending spooled attrs to the Director. Despooling
52,984 bytes ...
24-Nov 12:39 Bakis: Bacula 1.38.2 (20Nov05): 24-Nov-2005 12:39:47
  JobId:                  6834
  Job:                    Bakis.2005-11-24_12.24.36
  Backup Level:           Incremental, since=2005-11-20 01:05:01
  Client:                 "Bakis" sparc-sun-solaris2.10,solaris,5.10
  FileSet:                "Bakis" 2004-05-29 01:05:01
  Pool:                   "Default"
  Storage:                "Sun-L11000"
  Scheduled time:         24-Nov-2005 12:24:35
  Start time:             24-Nov-2005 12:24:38
  End time:               24-Nov-2005 12:39:47
  Priority:               10
  FD Files Written:       221
  SD Files Written:       221
  FD Bytes Written:       342,247,327
  SD Bytes Written:       342,270,823
  Rate:                   376.5 KB/s
  Software Compression:   None
  Volume name(s):         LYSD077
  Volume Session Id:      1
  Volume Session Time:    1132830403
  Last Volume Bytes:      342,594,026
  Non-fatal FD errors:    0
  SD Errors:              0
  FD termination status:  OK
  SD termination status:  OK
  Termination:            Backup OK

24-Nov 12:39 Bakis: Begin pruning Jobs.
24-Nov 12:39 Bakis: Pruned 1 Job for client Bakis from catalog.
24-Nov 12:39 Bakis: Begin pruning Files.
24-Nov 12:39 Bakis: Pruned Files from 5 Jobs for client Bakis from
catalog.
24-Nov 12:39 Bakis: End auto prune.

======================================================================

----------------------------------------------------------------------
 kern - 11-24-2005 06:22 PST 
----------------------------------------------------------------------
I don't believe that this is a bug, rather what it is telling you is
correct. After calling the autoloader, Bacula found the drive empty.
Conclusion: your wait in your autochanger script (default mtx-changer) is
not long enough to allow your autochanger to settle down.

Bug History
Date Modified  Username       Field                    Change              
======================================================================
11-24-05 05:16 ifmpeter       New Bug                                      
11-24-05 06:22 kern           Bugnote Added: 0001341                       
11-24-05 06:22 kern           Status                   new => feedback     
======================================================================