Tweak debug

[bacula/bacula] / bacula / src / stored / mount.c

diff --git a/bacula/src/stored/mount.c b/bacula/src/stored/mount.c
index 06d48b36d14fbae78382fbea0608f1b1fbd07825..ab65753a7433776eb82159c65f5ff83e1d73c464 100644 (file)
--- a/bacula/src/stored/mount.c
+++ b/bacula/src/stored/mount.c
@@ -64,6 +64,9 @@ enum {
  * This routine returns a 0 only if it is REALLY
  *  impossible to get the requested Volume.
  *
+ * This routine is entered with the device blocked, but not
+ *   locked.
+ *
  */
 bool DCR::mount_next_write_volume()
 {
@@ -113,9 +116,11 @@ mount_next_vol:
       ask = true;                     /* ask operator to mount tape */
       do_find = true;                 /* re-find a volume after unload */
    }
+   unlock_volumes();
    do_unload();
    do_swapping(true /*is_writing*/);
    do_load(true /*is_writing*/);
+   lock_volumes();
 
    if (do_find && !find_a_volume()) {
       goto no_lock_bail_out;
@@ -138,6 +143,7 @@ mount_next_vol:
     * and move the tape to the end of data.
     *
     */
+   unlock_volumes();
    if (autoload_device(dcr, true/*writing*/, NULL) > 0) {
       autochanger = true;
       ask = false;
@@ -145,7 +151,9 @@ mount_next_vol:
       autochanger = false;
       VolCatInfo.Slot = 0;
       ask = retry >= 2;
+      do_find = true;           /* do find_a_volume if we retry */
    }
+   lock_volumes();
    Dmsg1(150, "autoload_dev returns %d\n", autochanger);
    /*
     * If we autochanged to correct Volume or (we have not just
@@ -180,6 +188,7 @@ mount_next_vol:
 
    if (dev->poll && dev->has_cap(CAP_CLOSEONPOLL)) {
       dev->close();
+      free_volume(dev);
    }
 
    /* Ensure the device is open */
@@ -214,6 +223,8 @@ mount_next_vol:
       if (try_autolabel(false) == try_read_vol) {
          break;                       /* created a new volume label */
       }
+      Jmsg3(jcr, M_WARNING, 0, _("Open device %s Volume \"%s\" failed: ERR=%s\n"),
+            dev->print_name(), dcr->VolumeName, dev->bstrerror());
       Dmsg0(50, "set_unload\n");
       dev->set_unload();              /* force ask sysop */
       ask = true;
@@ -264,18 +275,21 @@ read_volume:
        * we need to position to the end of the volume, since we are
        * just now putting it into append mode.
        */
-      Dmsg0(200, "Device previously written, moving to end of data\n");
+      Dmsg1(100, "Device previously written, moving to end of data. Expect %lld bytes\n",
+           dev->VolCatInfo.VolCatBytes);
       Jmsg(jcr, M_INFO, 0, _("Volume \"%s\" previously written, moving to end of data.\n"),
          VolumeName);
 
       if (!dev->eod(dcr)) {
+         Dmsg2(050, "Unable to position to end of data on device %s: ERR=%s\n", 
+            dev->print_name(), dev->bstrerror());
          Jmsg(jcr, M_ERROR, 0, _("Unable to position to end of data on device %s: ERR=%s\n"),
             dev->print_name(), dev->bstrerror());
          mark_volume_in_error();
          goto mount_next_vol;
       }
       if (!is_eod_valid()) {
-         Dmsg0(150, "goto mount_next_vol\n");
+         Dmsg0(100, "goto mount_next_vol\n");
          goto mount_next_vol;
       }
 
@@ -306,6 +320,9 @@ no_lock_bail_out:
  * This routine is meant to be called once the first pass
  *   to ensure that we have a candidate volume to mount.
  *   Otherwise, we ask the sysop to created one.
+ * Note, the the Volumes are locked on entry.
+ *   They are unlocked on failure and remain locked on
+ *   success.  The caller must know this!!!
  */
 bool DCR::find_a_volume()  
 {
@@ -474,6 +491,7 @@ int DCR::check_volume_label(bool &ask, bool &autochanger)
       /* Needed, so the medium can be changed */
       if (dev->requires_mount()) {
          dev->close();
+         free_volume(dev);
       }
       goto check_next_volume;
    }
@@ -544,6 +562,12 @@ void DCR::do_swapping(bool is_writing)
          Dmsg1(100, "=== set in_use vol=%s\n", dev->vol->vol_name);
          dev->vol->set_in_use();
          dev->VolHdr.VolumeName[0] = 0;  /* don't yet have right Volume */
+      } else {
+         Dmsg1(100, "No vol on dev=%s\n", dev->print_name());
+      }
+      if (dev->swap_dev->vol) {
+         Dmsg2(100, "Vol=%s on dev=%s\n", dev->swap_dev->vol->vol_name,
+              dev->swap_dev->print_name());
       }
       dev->swap_dev = NULL;
    }
@@ -595,11 +619,13 @@ bool DCR::is_eod_valid()
               " size=%s\n"), VolumeName, 
               edit_uint64(dev->VolCatInfo.VolCatBytes, ed1));
       } else {
-         Jmsg(jcr, M_ERROR, 0, _("Bacula cannot write on disk Volume \"%s\" because: "
+         Mmsg(jcr->errmsg, _("Bacula cannot write on disk Volume \"%s\" because: "
               "The sizes do not match! Volume=%s Catalog=%s\n"),
               VolumeName,
               edit_uint64(pos, ed1),
               edit_uint64(dev->VolCatInfo.VolCatBytes, ed2));
+         Jmsg(jcr, M_ERROR, 0, jcr->errmsg);
+         Dmsg0(050, jcr->errmsg);
          mark_volume_in_error();
          return false;
       }