]> git.sur5r.net Git - bacula/bacula/blobdiff - bacula/src/stored/mount.c
Tweak: set non-zero level on debug line
[bacula/bacula] / bacula / src / stored / mount.c
index 0a9634de2c493077e489888ac0ea0d019a6f69f1..774c63c3b01291435f76a2cef54b8efe099adf42 100644 (file)
@@ -1,7 +1,7 @@
 /*
    Bacula® - The Network Backup Solution
 
-   Copyright (C) 2002-2008 Free Software Foundation Europe e.V.
+   Copyright (C) 2002-2010 Free Software Foundation Europe e.V.
 
    The main author of Bacula is Kern Sibbald, with contributions from
    many others, a complete list can be found in the file AUTHORS.
@@ -20,7 +20,7 @@
    Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA
    02110-1301, USA.
 
-   Bacula® is a registered trademark of John Walker.
+   Bacula® is a registered trademark of Kern Sibbald.
    The licensor of Bacula is the Free Software Foundation Europe
    (FSFE), Fiduciary Program, Sumatrastrasse 25, 8006 Zürich,
    Switzerland, email:ftf@fsfeurope.org.
@@ -32,7 +32,6 @@
  *
  *   Kern Sibbald, August MMII
  *
- *   Version $Id$
  */
 
 #include "bacula.h"                   /* pull in global headers */
@@ -64,6 +63,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()
 {
@@ -86,7 +88,7 @@ bool DCR::mount_next_write_volume()
 mount_next_vol:
    Dmsg1(150, "mount_next_vol retry=%d\n", retry);
    /* Ignore retry if this is poll request */
-   if (!dev->poll && retry++ > 4) {
+   if (retry++ > 4) {
       /* Last ditch effort before giving up, force operator to respond */
       VolCatInfo.Slot = 0;
       unlock_volumes();
@@ -96,6 +98,7 @@ mount_next_vol:
          goto no_lock_bail_out;
       }
       lock_volumes();
+      Dmsg1(150, "Continue after dir_ask_sysop_to_mount. must_load=%d\n", dev->must_load());
    }
    if (job_canceled(jcr)) {
       Jmsg(jcr, M_FATAL, 0, _("Job %d canceled.\n"), jcr->JobId);
@@ -106,41 +109,21 @@ mount_next_vol:
    if (dev->must_unload()) {
       ask = true;                     /* ask operator to mount tape */
    }
-   do_swapping(true /*writing*/);
+   unlock_volumes();
+   do_unload();
+   do_swapping(true /*is_writing*/);
+   do_load(true /*is_writing*/);
 
-   if (!is_suitable_volume_mounted()) {
-      bool have_vol = false;
-      /* Do we have a candidate volume? */
-      if (dev->vol) {
-         bstrncpy(VolumeName, dev->vol->vol_name, sizeof(VolumeName));
-         have_vol = dir_get_volume_info(this, GET_VOL_INFO_FOR_WRITE);
-      }
-      /*
-       * Get Director's idea of what tape we should have mounted.
-       *    in dcr->VolCatInfo
-       */
-      if (!have_vol) {
-         Dmsg0(200, "Before dir_find_next_appendable_volume.\n");
-         while (!dir_find_next_appendable_volume(dcr)) {
-            Dmsg0(200, "not dir_find_next\n");
-            if (job_canceled(jcr)) {
-               goto bail_out;
-            }
-            unlock_volumes();
-            if (!dir_ask_sysop_to_create_appendable_volume(dcr)) {
-               goto no_lock_bail_out;
-             }
-             lock_volumes();
-             Dmsg0(200, "Again dir_find_next_append...\n");
-         }
-         goto mount_next_vol;   
-      }
+   lock_volumes();
+   if (!find_a_volume()) {
+      goto no_lock_bail_out;
    }
+
    if (job_canceled(jcr)) {
       goto bail_out;
    }
    Dmsg3(150, "After find_next_append. Vol=%s Slot=%d Parts=%d\n",
-         VolCatInfo.VolCatName, VolCatInfo.Slot, VolCatInfo.VolCatParts);
+         getVolCatName(), VolCatInfo.Slot, VolCatInfo.VolCatParts);
    
    /*
     * Get next volume and ready it for append
@@ -153,13 +136,17 @@ mount_next_vol:
     * and move the tape to the end of data.
     *
     */
+   unlock_volumes();
+   dcr->setVolCatInfo(false);   /* out of date when Vols unlocked */
    if (autoload_device(dcr, true/*writing*/, NULL) > 0) {
       autochanger = true;
       ask = false;
    } else {
       autochanger = false;
       VolCatInfo.Slot = 0;
+      ask = retry >= 2;
    }
+   lock_volumes();
    Dmsg1(150, "autoload_dev returns %d\n", autochanger);
    /*
     * If we autochanged to correct Volume or (we have not just
@@ -168,20 +155,24 @@ mount_next_vol:
     *   we will fail, recurse and ask the operator the next time.
     */
    if (!dev->must_unload() && dev->is_tape() && dev->has_cap(CAP_AUTOMOUNT)) {
-      Dmsg0(150, "(1)Ask=0\n");
+      Dmsg0(250, "(1)Ask=0\n");
       ask = false;                 /* don't ask SYSOP this time */
    }
    /* Don't ask if not removable */
    if (!dev->is_removable()) {
-      Dmsg0(150, "(2)Ask=0\n");
+      Dmsg0(250, "(2)Ask=0\n");
       ask = false;
    }
-   Dmsg2(150, "Ask=%d autochanger=%d\n", ask, autochanger);
-   dev->must_unload();       /* release next time if we "recurse" */
+   Dmsg2(250, "Ask=%d autochanger=%d\n", ask, autochanger);
 
-   if (ask && !dir_ask_sysop_to_mount_volume(dcr, ST_APPEND)) {
-      Dmsg0(150, "Error return ask_sysop ...\n");
-      goto bail_out;          /* error return */
+   if (ask) {
+      unlock_volumes();
+      dcr->setVolCatInfo(false);   /* out of date when Vols unlocked */
+      if (!dir_ask_sysop_to_mount_volume(dcr, ST_APPEND)) {
+         Dmsg0(150, "Error return ask_sysop ...\n");
+         goto no_lock_bail_out;
+      }
+      lock_volumes();
    }
    if (job_canceled(jcr)) {
       goto bail_out;
@@ -191,6 +182,7 @@ mount_next_vol:
 
    if (dev->poll && dev->has_cap(CAP_CLOSEONPOLL)) {
       dev->close();
+      free_volume(dev);
    }
 
    /* Ensure the device is open */
@@ -225,24 +217,24 @@ mount_next_vol:
       if (try_autolabel(false) == try_read_vol) {
          break;                       /* created a new volume label */
       }
-      /* If DVD, ignore the error, very often you cannot open the device
-       * (when there is no DVD, or when the one inserted is a wrong one) */
-      if (dev->poll || dev->is_dvd() || dev->is_removable()) {
-         goto mount_next_vol;
-      } else {
-         Jmsg(jcr, M_ERROR, 0, _("Could not open device %s: ERR=%s\n"),
-            dev->print_name(), dev->print_errmsg());
-         goto bail_out;
-      }
+      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;
+      Dmsg0(150, "goto mount_next_vol\n");
+      goto mount_next_vol;
    }
 
    /*
     * Now check the volume label to make sure we have the right tape mounted
     */
 read_volume:
-
    switch (check_volume_label(ask, autochanger)) {
    case check_next_vol:
+      Dmsg0(50, "set_unload\n");
+      dev->set_unload();                 /* want a different Volume */
+      Dmsg0(150, "goto mount_next_vol\n");
       goto mount_next_vol;
    case check_read_vol:
       goto read_volume;
@@ -251,6 +243,16 @@ read_volume:
    case check_ok:
       break;
    }
+   /*
+    * Check that volcatinfo is good   
+    */
+   if (!dev->haveVolCatInfo()) {
+      Dmsg0(100, "Do not have volcatinfo\n");
+      if (!find_a_volume()) {
+         goto mount_next_vol;
+      }
+      dev->VolCatInfo = VolCatInfo;      /* structure assignment */
+   }
 
    /*
     * See if we have a fresh tape or a tape with data.
@@ -277,17 +279,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(100, "goto mount_next_vol\n");
          goto mount_next_vol;
       }
 
@@ -314,6 +320,51 @@ no_lock_bail_out:
    return false;
 }
 
+/*
+ * 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()  
+{
+   DCR *dcr = this;
+   if (!is_suitable_volume_mounted()) {
+      bool have_vol = false;
+      /* Do we have a candidate volume? */
+      if (dev->vol) {
+         bstrncpy(VolumeName, dev->vol->vol_name, sizeof(VolumeName));
+         have_vol = dir_get_volume_info(this, GET_VOL_INFO_FOR_WRITE);
+      }
+      /*
+       * Get Director's idea of what tape we should have mounted.
+       *    in dcr->VolCatInfo
+       */
+      if (!have_vol) {
+         Dmsg0(200, "Before dir_find_next_appendable_volume.\n");
+         while (!dir_find_next_appendable_volume(dcr)) {
+            Dmsg0(200, "not dir_find_next\n");
+            if (job_canceled(jcr)) {
+               unlock_volumes();
+               return false;
+            }
+            unlock_volumes();
+            if (!dir_ask_sysop_to_create_appendable_volume(dcr)) {
+               return false;
+             }
+             lock_volumes();
+             Dmsg0(150, "Again dir_find_next_append...\n");
+         }
+      }
+   }
+   if (dcr->haveVolCatInfo()) {
+      return true;
+   }
+   return dir_get_volume_info(dcr, GET_VOL_INFO_FOR_WRITE);
+}
+
 int DCR::check_volume_label(bool &ask, bool &autochanger)
 {
    int vol_label_status;
@@ -334,6 +385,7 @@ int DCR::check_volume_label(bool &ask, bool &autochanger)
 
    Dmsg2(150, "Want dirVol=%s dirStat=%s\n", VolumeName,
       VolCatInfo.VolCatStatus);
+
    /*
     * At this point, dev->VolCatInfo has what is in the drive, if anything,
     *          and   dcr->VolCatInfo has what the Director wants.
@@ -347,6 +399,12 @@ int DCR::check_volume_label(bool &ask, bool &autochanger)
       VOLUME_CAT_INFO dcrVolCatInfo, devVolCatInfo;
       char saveVolumeName[MAX_NAME_LENGTH];
 
+      Dmsg2(150, "Vol NAME Error Have=%s, want=%s\n", dev->VolHdr.VolumeName, VolumeName);
+      if (dev->is_volume_to_unload()) {
+         ask = true;
+         goto check_next_volume;
+      }
+
       /* If not removable, Volume is broken */
       if (!dev->is_removable()) {
          Jmsg(jcr, M_WARNING, 0, _("Volume \"%s\" not on device %s.\n"),
@@ -355,13 +413,6 @@ int DCR::check_volume_label(bool &ask, bool &autochanger)
          goto check_next_volume;
       }
 
-      Dmsg1(150, "Vol NAME Error Name=%s\n", VolumeName);
-      /* If polling and got a previous bad name, ignore it */
-      if (dev->poll && strcmp(dev->BadVolName, dev->VolHdr.VolumeName) == 0) {
-         ask = true;
-         Dmsg1(200, "Vol Name error supress due to poll. Name=%s\n", VolumeName);
-         goto check_next_volume;
-      }
       /*
        * OK, we got a different volume mounted. First save the
        *  requested Volume info (dcr) structure, then query if
@@ -388,7 +439,7 @@ int DCR::check_volume_label(bool &ask, bool &autochanger)
             mark_volume_not_inchanger();
          }
          dev->VolCatInfo = devVolCatInfo;    /* structure assignment */
-         bstrncpy(dev->BadVolName, dev->VolHdr.VolumeName, sizeof(dev->BadVolName));
+         dev->set_unload();                  /* unload this volume */
          Jmsg(jcr, M_WARNING, 0, _("Director wanted Volume \"%s\".\n"
               "    Current Volume \"%s\" not acceptable because:\n"
               "    %s"),
@@ -406,6 +457,15 @@ int DCR::check_volume_label(bool &ask, bool &autochanger)
        */
       Dmsg1(150, "Got new Volume name=%s\n", VolumeName);
       dev->VolCatInfo = VolCatInfo;   /* structure assignment */
+      Dmsg1(100, "Call reserve_volume=%s\n", dev->VolHdr.VolumeName);
+      if (reserve_volume(this, dev->VolHdr.VolumeName) == NULL) {
+         Jmsg2(jcr, M_WARNING, 0, _("Could not reserve volume %s on %s\n"),
+            dev->VolHdr.VolumeName, dev->print_name());
+         ask = true;
+         dev->setVolCatInfo(false);
+         setVolCatInfo(false);
+         goto check_next_volume;
+      }
       break;                /* got a Volume */
    /*
     * At this point, we assume we have a blank tape mounted.
@@ -428,7 +488,6 @@ int DCR::check_volume_label(bool &ask, bool &autochanger)
       case try_default:
          break;
       }
-
       /* NOTE! Fall-through wanted. */
    case VOL_NO_MEDIA:
    default:
@@ -442,12 +501,15 @@ 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;
    }
    return check_ok;
 
 check_next_volume:
+   dev->setVolCatInfo(false);
+   setVolCatInfo(false);
    return check_next_vol;
 
 check_bail_out:
@@ -461,7 +523,6 @@ check_read_volume:
 
 bool DCR::is_suitable_volume_mounted()
 {
-
    /* Volume mounted? */
    if (dev->VolHdr.VolumeName[0] == 0 || dev->swap_dev || dev->must_unload()) {
       return false;                      /* no */
@@ -470,14 +531,30 @@ bool DCR::is_suitable_volume_mounted()
    return dir_get_volume_info(this, GET_VOL_INFO_FOR_WRITE);
 }
 
-void DCR::do_swapping(bool is_writing)
+bool DCR::do_unload()
 {
    if (dev->must_unload()) {
-      Dmsg1(100, "swapping: unloading %s\n", dev->print_name());
-      unload_autochanger(this, -1);
+      Dmsg1(100, "must_unload release %s\n", dev->print_name());
       release_volume();
-      dev->clear_unload();
    }
+   return false;
+}
+
+bool DCR::do_load(bool is_writing)
+{
+   if (dev->must_load()) {
+      Dmsg1(100, "Must load %s\n", dev->print_name());
+      if (autoload_device(this, is_writing, NULL) > 0) {
+         dev->clear_load();
+         return true;
+      }
+      return false;
+   }
+   return true;
+}
+
+void DCR::do_swapping(bool is_writing)
+{
    /*
     * See if we are asked to swap the Volume from another device
     *  if so, unload the other device here, and attach the
@@ -486,25 +563,25 @@ void DCR::do_swapping(bool is_writing)
    if (dev->swap_dev) {
       if (dev->swap_dev->must_unload()) {
          if (dev->vol) {
-            dev->Slot = dev->vol->get_slot();
+            dev->swap_dev->set_slot(dev->vol->get_slot());
          }
-         Dmsg2(100, "Swap unloading slot=%d %s\n", dev->Slot, 
+         Dmsg2(100, "Swap unloading slot=%d %s\n", dev->swap_dev->get_slot(),
                dev->swap_dev->print_name());
          unload_dev(this, dev->swap_dev);
-         dev->Slot = -1;
       }
       if (dev->vol) {
          dev->vol->clear_swapping();
+         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());
       }
-      dev->swap_dev = NULL;
-   }
-   if (dev->must_load()) {
-      Dmsg1(100, "swapping: must load %s\n", dev->print_name());
-      if (autoload_device(this, is_writing, NULL) > 0) {
-         dev->clear_load();
+      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;
    }
 }
 
@@ -554,11 +631,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;
       }
@@ -602,7 +681,8 @@ int DCR::try_autolabel(bool opened)
       /* Create a new Volume label and write it to the device */
       if (!write_new_volume_label_to_dev(dcr, VolumeName,
              pool_name, false, /* no relabel */ false /* defer DVD label */)) {
-         Dmsg0(150, "!write_vol_label\n");
+         Dmsg2(150, "write_vol_label failed. vol=%s, pool=%s\n",
+           VolumeName, pool_name);
          if (opened) { 
             mark_volume_in_error();
          }
@@ -645,6 +725,7 @@ void DCR::mark_volume_in_error()
    Dmsg0(150, "dir_update_vol_info. Set Error.\n");
    dir_update_volume_info(this, false, false);
    volume_unused(this);
+   Dmsg0(50, "set_unload\n");
    dev->set_unload();                 /* must get a new volume */
 }
 
@@ -656,7 +737,7 @@ void DCR::mark_volume_not_inchanger()
 {
    Jmsg(jcr, M_ERROR, 0, _("Autochanger Volume \"%s\" not found in slot %d.\n"
 "    Setting InChanger to zero in catalog.\n"),
-        VolCatInfo.VolCatName, VolCatInfo.Slot);
+        getVolCatName(), VolCatInfo.Slot);
    dev->VolCatInfo = VolCatInfo;    /* structure assignment */
    VolCatInfo.InChanger = false;
    dev->VolCatInfo.InChanger = false;
@@ -670,9 +751,11 @@ void DCR::mark_volume_not_inchanger()
  */
 void DCR::release_volume()
 {
+   unload_autochanger(this, -1);
+
    if (WroteVol) {
       Jmsg0(jcr, M_ERROR, 0, _("Hey!!!!! WroteVol non-zero !!!!!\n"));
-      Dmsg0(190, "Hey!!!!! WroteVol non-zero !!!!!\n");
+      Pmsg0(190, "Hey!!!!! WroteVol non-zero !!!!!\n");
    }
    /*
     * First erase all memory of the current volume
@@ -681,7 +764,6 @@ void DCR::release_volume()
    dev->block_num = dev->file = 0;
    dev->EndBlock = dev->EndFile = 0;
    memset(&dev->VolCatInfo, 0, sizeof(dev->VolCatInfo));
-// memset(&VolCatInfo, 0, sizeof(VolCatInfo));
    dev->clear_volhdr();
    /* Force re-read of label */
    dev->clear_labeled();
@@ -698,10 +780,49 @@ void DCR::release_volume()
    if (dev->is_open()) {
       dev->offline_or_rewind();
    }
-   dev->set_unload();
+// Dmsg0(50, "set_unload\n");
+// dev->set_unload();
    Dmsg0(190, "release_volume\n");
 }
 
+/*
+ *      Insanity check 
+ *
+ * Check to see if the tape position as defined by the OS is
+ *  the same as our concept.  If it is not, 
+ *  it means the user has probably manually rewound the tape.
+ * Note, we check only if num_writers == 0, but this code will
+ *  also work fine for any number of writers. If num_writers > 0,
+ *  we probably should cancel all jobs using this device, or 
+ *  perhaps even abort the SD, or at a minimum, mark the tape
+ *  in error.  Another strategy with num_writers == 0, would be
+ *  to rewind the tape and do a new eod() request.
+ */
+bool DCR::is_tape_position_ok()
+{
+   if (dev->is_tape() && dev->num_writers == 0) {
+      int32_t file = dev->get_os_tape_file();
+      if (file >= 0 && file != (int32_t)dev->get_file()) {
+         Jmsg(jcr, M_ERROR, 0, _("Invalid tape position on volume \"%s\"" 
+              " on device %s. Expected %d, got %d\n"), 
+              dev->VolHdr.VolumeName, dev->print_name(), dev->get_file(), file);
+         /* 
+          * If the current file is greater than zero, it means we probably
+          *  have some bad count of EOF marks, so mark tape in error.  Otherwise
+          *  the operator might have moved the tape, so we just release it
+          *  and try again.
+          */
+         if (file > 0) {
+            mark_volume_in_error();
+         }
+         release_volume();
+         return false;
+      }
+   }
+   return true;
+}
+
+
 /*
  * If we are reading, we come here at the end of the tape
  *  and see if there are more volumes to be mounted.