- Remove argument from create_bacula_database for SQLite as it

  caused an error.
- Add back index code so that two drive autochangers can get
  a second tape.
- Change a bunch of debug levels to aid debugging autochangers.
- Fix reservation so that mutexes are properly applied.
- Rework reservation algorithm so that two drives can be used
  at the same time.

git-svn-id: https://bacula.svn.sourceforge.net/svnroot/bacula/trunk@2646 91ce42f0-d328-0410-95d8-f526ca767f89

diff --git a/bacula/kes-1.39 b/bacula/kes-1.39
index 8ced04a928ec6eac5a7a0d25fd2fca728f40b7f4..e3fdfdccc12b43a74b3c6e57bcd299dc27df858e 100644 (file)
--- a/bacula/kes-1.39
+++ b/bacula/kes-1.39
@@ -4,6 +4,16 @@
 General:
 
 Changes to 1.39.2:
+05Dec05
+- Remove argument from create_bacula_database for SQLite as it
+  caused an error.
+- Add back index code so that two drive autochangers can get
+  a second tape.
+- Change a bunch of debug levels to aid debugging autochangers.
+- Fix reservation so that mutexes are properly applied.
+- Rework reservation algorithm so that two drives can be used
+  at the same time.
+04Dec05
 - Landon merged his data encription changes into the HEAD
 - Apply days keyword patch from Alexander.Bergolth at wu-wien.ac.at 
   If this patch is applied, the number of days can be specified with

diff --git a/bacula/src/cats/create_bacula_database.in b/bacula/src/cats/create_bacula_database.in
index 6a3775f823d4219cd65a4a142c4fdd98d7287b13..7ee767b133fb6ded05e9289d07d1d6ee9ce70df3 100644 (file)
--- a/bacula/src/cats/create_bacula_database.in
+++ b/bacula/src/cats/create_bacula_database.in
@@ -5,7 +5,7 @@
 #
 if test xsqlite = x@DB_NAME@ -o xsqlite3 = x@DB_NAME@ ; then
   echo "Creating SQLite database"
-  @scriptdir@/create_@DB_NAME@_database $*
+  @scriptdir@/create_@DB_NAME@_database
 else
   if test xmysql = x@DB_NAME@ ; then
     echo "Creating MySQL database"

diff --git a/bacula/src/dird/catreq.c b/bacula/src/dird/catreq.c
index d8c879cef716f7d005e6c6c74136717a5444c519..955d0469cca1a0ec91845482b216652e2c9c58ad 100644 (file)
--- a/bacula/src/dird/catreq.c
+++ b/bacula/src/dird/catreq.c
@@ -122,7 +122,7 @@ void catalog_request(JCR *jcr, BSOCK *bs)
       ok = db_get_pool_record(jcr, jcr->db, &pr);
       if (ok) {
          mr.PoolId = pr.PoolId;
-         ok = find_next_volume_for_append(jcr, &mr, true /*permit create new vol*/);
+         ok = find_next_volume_for_append(jcr, &mr, index, true /*permit create new vol*/);
       }
       /*
        * Send Find Media response to Storage daemon

diff --git a/bacula/src/dird/next_vol.c b/bacula/src/dird/next_vol.c
index 9a64bf3921cd31da480325f94d24ead8acbb2cf0..922bb924359354cd1a983b0f2eaf0cd826468c65 100644 (file)
--- a/bacula/src/dird/next_vol.c
+++ b/bacula/src/dird/next_vol.c
@@ -35,7 +35,7 @@
  *   MEDIA_DBR mr (zeroed out)
  *   create -- whether or not to create a new volume
  */
-int find_next_volume_for_append(JCR *jcr, MEDIA_DBR *mr, bool create)
+int find_next_volume_for_append(JCR *jcr, MEDIA_DBR *mr, int index, bool create)
 {
    int retry = 0;
    bool ok;
@@ -58,7 +58,7 @@ int find_next_volume_for_append(JCR *jcr, MEDIA_DBR *mr, bool create)
       /*
        *  1. Look for volume with "Append" status.
        */
-      ok = db_find_next_volume(jcr, jcr->db, 1, InChanger, mr);
+      ok = db_find_next_volume(jcr, jcr->db, index, InChanger, mr);
       Dmsg2(100, "catreq after find_next_vol ok=%d FW=%d\n", ok, mr->FirstWritten);
       if (!ok) {
          /*

diff --git a/bacula/src/dird/protos.h b/bacula/src/dird/protos.h
index d2e36f22018baa3e65af7a3f41fa25ecd0a12ea5..4417a800a78d1bbfca61889b8505c8bb99f79f88 100644 (file)
--- a/bacula/src/dird/protos.h
+++ b/bacula/src/dird/protos.h
@@ -117,7 +117,7 @@ extern int bget_dirmsg(BSOCK *bs);
 extern void wait_for_storage_daemon_termination(JCR *jcr);
 
 /* next_vol.c */
-int find_next_volume_for_append(JCR *jcr, MEDIA_DBR *mr, bool create);
+int find_next_volume_for_append(JCR *jcr, MEDIA_DBR *mr, int index, bool create);
 bool has_volume_expired(JCR *jcr, MEDIA_DBR *mr);
 void check_if_volume_valid_or_recyclable(JCR *jcr, MEDIA_DBR *mr, const char **reason);
 

diff --git a/bacula/src/dird/ua_output.c b/bacula/src/dird/ua_output.c
index f3e1916692a24c766029140f56684035e6556d38..809b8009cfc405528087be741a4979a0724bb752 100644 (file)
--- a/bacula/src/dird/ua_output.c
+++ b/bacula/src/dird/ua_output.c
@@ -407,18 +407,18 @@ static int do_list_cmd(UAContext *ua, const char *cmd, e_list_type llist)
       /* List next volume */
       } else if (strcasecmp(ua->argk[i], N_("nextvol")) == 0 ||
                  strcasecmp(ua->argk[i], N_("nextvolume")) == 0) {
-        n = 1;
+         n = 1;
          j = find_arg_with_value(ua, N_("days"));
          if (j >= 0) {
             n = atoi(ua->argv[j]);
-           if ((n < 0) || (n > 50)) {
-             bsendmsg(ua, _("Ignoring illegal value for days.\n"));
-             n = 1;
-           }
+            if ((n < 0) || (n > 50)) {
+              bsendmsg(ua, _("Ignoring illegal value for days.\n"));
+              n = 1;
+            }
          }
          list_nextvol(ua, n);
       } else if (strcasecmp(ua->argk[i], N_("limit")) == 0
-                || strcasecmp(ua->argk[i], N_("days")) == 0) {
+                 || strcasecmp(ua->argk[i], N_("days")) == 0) {
          /* Ignore it */
       } else {
          bsendmsg(ua, _("Unknown list keyword: %s\n"), NPRT(ua->argk[i]));
@@ -465,14 +465,14 @@ static bool list_nextvol(UAContext *ua, int ndays)
       memset(&pr, 0, sizeof(pr));
       pr.PoolId = jcr->PoolId;
       if (! db_get_pool_record(ua->jcr, ua->db, &pr)) {
-        strcpy(pr.Name, "*UnknownPool*");
+         strcpy(pr.Name, "*UnknownPool*");
       }
-      if (!find_next_volume_for_append(jcr, &mr, 0)) {
-        bsendmsg(ua, _("Could not find next Volume for Job %s (%s, %s).\n"),
-           job->hdr.name, pr.Name, level_to_str(run->level));
+      if (!find_next_volume_for_append(jcr, &mr, 1, false/*no create*/)) {
+         bsendmsg(ua, _("Could not find next Volume for Job %s (%s, %s).\n"),
+            job->hdr.name, pr.Name, level_to_str(run->level));
       } else {
          bsendmsg(ua,
-           _("The next Volume to be used by Job \"%s\" (%s, %s) will be %s\n"),
+            _("The next Volume to be used by Job \"%s\" (%s, %s) will be %s\n"),
             job->hdr.name, pr.Name, level_to_str(run->level), mr.VolumeName);
          found = true;
       }
@@ -483,7 +483,7 @@ static bool list_nextvol(UAContext *ua, int ndays)
    }
    if (!found) {
       bsendmsg(ua, _("Could not find next Volume for Job %s.\n"),
-        job->hdr.name);
+         job->hdr.name);
       return false;
    }
    return true;
@@ -523,58 +523,58 @@ RUN *find_next_run(RUN *run, JOB *job, time_t &runtime, int ndays)
        * Find runs in next 24 hours
        */
       for (day = 0; day <= ndays; day++) {
-        future = now + (day * 60 * 60 * 24);
+         future = now + (day * 60 * 60 * 24);
 
-        /* Break down the time into components */
-        localtime_r(&future, &tm);
-        mday = tm.tm_mday - 1;
-        wday = tm.tm_wday;
-        month = tm.tm_mon;
-        wom = mday / 7;
-        woy = tm_woy(future);
+         /* Break down the time into components */
+         localtime_r(&future, &tm);
+         mday = tm.tm_mday - 1;
+         wday = tm.tm_wday;
+         month = tm.tm_mon;
+         wom = mday / 7;
+         woy = tm_woy(future);
 
-        is_scheduled = bit_is_set(mday, run->mday) && bit_is_set(wday, run->wday) &&
+         is_scheduled = bit_is_set(mday, run->mday) && bit_is_set(wday, run->wday) &&
             bit_is_set(month, run->month) && bit_is_set(wom, run->wom) &&
             bit_is_set(woy, run->woy);
  
 #ifdef xxx
-        Dmsg2(000, "day=%d is_scheduled=%d\n", day, is_scheduled);
-        Dmsg1(000, "bit_set_mday=%d\n", bit_is_set(mday, run->mday));
-        Dmsg1(000, "bit_set_wday=%d\n", bit_is_set(wday, run->wday));
-        Dmsg1(000, "bit_set_month=%d\n", bit_is_set(month, run->month));
-        Dmsg1(000, "bit_set_wom=%d\n", bit_is_set(wom, run->wom));
-        Dmsg1(000, "bit_set_woy=%d\n", bit_is_set(woy, run->woy));
+         Dmsg2(000, "day=%d is_scheduled=%d\n", day, is_scheduled);
+         Dmsg1(000, "bit_set_mday=%d\n", bit_is_set(mday, run->mday));
+         Dmsg1(000, "bit_set_wday=%d\n", bit_is_set(wday, run->wday));
+         Dmsg1(000, "bit_set_month=%d\n", bit_is_set(month, run->month));
+         Dmsg1(000, "bit_set_wom=%d\n", bit_is_set(wom, run->wom));
+         Dmsg1(000, "bit_set_woy=%d\n", bit_is_set(woy, run->woy));
 #endif
 
-        if (is_scheduled) { /* Jobs scheduled on that day */
+         if (is_scheduled) { /* Jobs scheduled on that day */
 #ifdef xxx
-           char buf[300], num[10];
-           bsnprintf(buf, sizeof(buf), "tm.hour=%d hour=", tm.tm_hour);
-           for (i=0; i<24; i++) {
-              if (bit_is_set(i, run->hour)) {
-                 bsnprintf(num, sizeof(num), "%d ", i);
-                 bstrncat(buf, num, sizeof(buf));
-              }
-           }
-           bstrncat(buf, "\n", sizeof(buf));
-           Dmsg1(000, "%s", buf);
+            char buf[300], num[10];
+            bsnprintf(buf, sizeof(buf), "tm.hour=%d hour=", tm.tm_hour);
+            for (i=0; i<24; i++) {
+               if (bit_is_set(i, run->hour)) {
+                  bsnprintf(num, sizeof(num), "%d ", i);
+                  bstrncat(buf, num, sizeof(buf));
+               }
+            }
+            bstrncat(buf, "\n", sizeof(buf));
+            Dmsg1(000, "%s", buf);
 #endif
-           /* find time (time_t) job is to be run */
-           localtime_r(&future, &runtm);
-           for (i= 0; i < 24; i++) {
-              if (bit_is_set(i, run->hour)) {
-                 runtm.tm_hour = i;
-                 runtm.tm_min = run->minute;
-                 runtm.tm_sec = 0;
-                 runtime = mktime(&runtm);
-                 Dmsg2(200, "now=%d runtime=%d\n", now, runtime);
-                 if ((runtime > now) && (runtime < endtime)) {
-                    Dmsg2(200, "Found it level=%d %c\n", run->level, run->level);
-                    return run;         /* found it, return run resource */
-                 }
-              }
-           }
-        }
+            /* find time (time_t) job is to be run */
+            localtime_r(&future, &runtm);
+            for (i= 0; i < 24; i++) {
+               if (bit_is_set(i, run->hour)) {
+                  runtm.tm_hour = i;
+                  runtm.tm_min = run->minute;
+                  runtm.tm_sec = 0;
+                  runtime = mktime(&runtm);
+                  Dmsg2(200, "now=%d runtime=%d\n", now, runtime);
+                  if ((runtime > now) && (runtime < endtime)) {
+                     Dmsg2(200, "Found it level=%d %c\n", run->level, run->level);
+                     return run;         /* found it, return run resource */
+                  }
+               }
+            }
+         }
       }
    } /* end for loop over runs */
    /* Nothing found */

diff --git a/bacula/src/dird/ua_status.c b/bacula/src/dird/ua_status.c
index f1a07d4ed437c4c175019e62cde43a501ac0d1c3..d242f6ff2b4a77e866bcc75e22b13c576bac838f 100644 (file)
--- a/bacula/src/dird/ua_status.c
+++ b/bacula/src/dird/ua_status.c
@@ -380,7 +380,7 @@ static void prt_runtime(UAContext *ua, sched_pkt *sp)
       }
       if (ok) {
          mr.PoolId = jcr->PoolId;
-         ok = find_next_volume_for_append(jcr, &mr, 0);
+         ok = find_next_volume_for_append(jcr, &mr, 1, false/*no create*/);
       }
       if (!ok) {
          bstrncpy(mr.VolumeName, "*unknown*", sizeof(mr.VolumeName));

diff --git a/bacula/src/lib/bpipe.c b/bacula/src/lib/bpipe.c
index 39109bf22215f323df1f971ccb22a0a83dd7fae9..ca8291366355dbb0fca49dceb68612df423ed147 100644 (file)
--- a/bacula/src/lib/bpipe.c
+++ b/bacula/src/lib/bpipe.c
@@ -269,11 +269,11 @@ int run_program(char *prog, int wait, POOLMEM *results)
          stat1 = ferror(bpipe->rfd);
       }
       if (stat1 < 0) {
-         Dmsg2(100, "Run program fgets stat=%d ERR=%s\n", stat1, strerror(errno));
+         Dmsg2(150, "Run program fgets stat=%d ERR=%s\n", stat1, strerror(errno));
       } else if (stat1 != 0) {
-         Dmsg1(100, "Run program fgets stat=%d\n", stat1);
+         Dmsg1(150, "Run program fgets stat=%d\n", stat1);
          if (bpipe->timer_id) {
-            Dmsg1(100, "Run program fgets killed=%d\n", bpipe->timer_id->killed);
+            Dmsg1(150, "Run program fgets killed=%d\n", bpipe->timer_id->killed);
             /* NB: I'm not sure it is really useful for run_program. Without the
              * following lines run_program would not detect if the program was killed
              * by the watchdog. */
@@ -288,7 +288,7 @@ int run_program(char *prog, int wait, POOLMEM *results)
    }
    stat2 = close_bpipe(bpipe);
    stat1 = stat2 != 0 ? stat2 : stat1;
-   Dmsg1(100, "Run program returning %d\n", stat1);
+   Dmsg1(150, "Run program returning %d\n", stat1);
    return stat1;
 }
 
@@ -356,7 +356,7 @@ int run_program_full_output(char *prog, int wait, POOLMEM *results)
       } else if (stat1 != 0) {
          Dmsg1(900, "Run program fgets stat=%d\n", stat1);
          if (bpipe->timer_id) {
-            Dmsg1(100, "Run program fgets killed=%d\n", bpipe->timer_id->killed);
+            Dmsg1(150, "Run program fgets killed=%d\n", bpipe->timer_id->killed);
             if (bpipe->timer_id->killed) {
                pm_strcat(tmp, _("Program killed by Bacula watchdog (timeout)\n"));
                stat1 = ETIME;

diff --git a/bacula/src/stored/acquire.c b/bacula/src/stored/acquire.c
index e0ce9c5be3ff54ebcd71d16e3877ac96453a54f1..4741c583758b99850e9c8a67250756a21a4e0896 100644 (file)
--- a/bacula/src/stored/acquire.c
+++ b/bacula/src/stored/acquire.c
@@ -86,7 +86,7 @@ void free_dcr(DCR *dcr)
    if (dcr->reserved_device) {
       lock_device(dev);
       dev->reserved_device--;
-      Dmsg1(200, "Dec reserve=%d\n", dev->reserved_device);
+      Dmsg1(100, "Dec reserve=%d\n", dev->reserved_device);
       dcr->reserved_device = false;
       if (dev->num_writers < 0) {
          Jmsg1(dcr->jcr, M_ERROR, 0, _("Hey! num_writers=%d!!!!\n"), dev->num_writers);
@@ -298,12 +298,6 @@ DCR *acquire_device_for_append(DCR *dcr)
    Dmsg1(190, "acquire_append device is %s\n", dev->is_tape()?"tape":
         (dev->is_dvd()?"DVD":"disk"));
 
-   if (dcr->reserved_device) {
-      dev->reserved_device--;
-      Dmsg1(200, "Dec reserve=%d\n", dev->reserved_device);
-      dcr->reserved_device = false;
-   }
-
    /*
     * With the reservation system, this should not happen
     */
@@ -402,6 +396,13 @@ get_out:
    free_dcr(dcr);
    dcr = NULL;
 ok_out:
+   P(dev->mutex);
+   if (dcr->reserved_device) {
+      dev->reserved_device--;
+      Dmsg1(100, "Dec reserve=%d\n", dev->reserved_device);
+      dcr->reserved_device = false;
+   }
+   V(dev->mutex);
    dev->unblock();
    return dcr;
 }
@@ -424,7 +425,7 @@ bool release_device(DCR *dcr)
    /* if device is reserved, job never started, so release the reserve here */
    if (dcr->reserved_device) {
       dev->reserved_device--;
-      Dmsg1(200, "Dec reserve=%d\n", dev->reserved_device);
+      Dmsg1(100, "Dec reserve=%d\n", dev->reserved_device);
       dcr->reserved_device = false;
    }
 

diff --git a/bacula/src/stored/append.c b/bacula/src/stored/append.c
index 39ec6d3903659859db0bbb052d3d3b535ef4f3f2..539f63ead5acd318f5220619de11b60c23ff0dff 100644 (file)
--- a/bacula/src/stored/append.c
+++ b/bacula/src/stored/append.c
@@ -45,7 +45,7 @@ bool do_append_data(JCR *jcr)
    char buf1[100], buf2[100];
 
 
-   Dmsg0(100, "Start append data.\n");
+   Dmsg1(100, "Start append data. res=%d\n", dev->reserved_device);
 
    memset(&rec, 0, sizeof(rec));
 

diff --git a/bacula/src/stored/dev.c b/bacula/src/stored/dev.c
index 7dc108cab7eb336bd7a42e8a4716c489d8b34879..30a54538b29a6e18f13aafc79dd05f2b826300cb 100644 (file)
--- a/bacula/src/stored/dev.c
+++ b/bacula/src/stored/dev.c
@@ -653,7 +653,8 @@ bool rewind_dev(DEVICE *dev)
    struct mtop mt_com;
    unsigned int i;
 
-   Dmsg2(29, "rewind_dev fd=%d %s\n", dev->fd, dev->print_name());
+   Dmsg3(29, "rewind_dev res=%d fd=%d %s\n", dev->reserved_device, 
+      dev->fd, dev->print_name());
    if (dev->fd < 0) {
       if (!dev->is_dvd()) { /* In case of major error, the fd is not open on DVD, so we don't want to abort. */
          dev->dev_errno = EBADF;
@@ -1700,7 +1701,7 @@ int flush_dev(DEVICE *dev)
 static void do_close(DEVICE *dev)
 {
 
-   Dmsg1(29, "really close_dev %s\n", dev->print_name());
+   Dmsg1(100, "really close_dev %s\n", dev->print_name());
    if (dev->fd >= 0) {
       close(dev->fd);
    }
@@ -1754,7 +1755,8 @@ void DEVICE::close()
    /*if (fd >= 0 && use_count == 1) {*/
    /* No need to check if fd >= 0: it is checked again
     * in do_close, and do_close MUST be called for volumes
-    * splitted in parts, even if fd == -1. */
+    * split in parts, even if fd == -1. 
+    */
    if (use_count == 1) {
       do_close(this);
    } else if (use_count > 0) {

diff --git a/bacula/src/stored/job.c b/bacula/src/stored/job.c
index 5faac87ba3be40f5f6ce935fb2f3a016de7e623e..1176ef45f8e64de2fddbb2b7493a94b215f46e0c 100644 (file)
--- a/bacula/src/stored/job.c
+++ b/bacula/src/stored/job.c
@@ -134,7 +134,7 @@ bool run_cmd(JCR *jcr)
    struct timespec timeout;
    int errstat;
 
-   Dmsg1(100, "Run_cmd: %s\n", jcr->dir_bsock->msg);
+   Dmsg1(200, "Run_cmd: %s\n", jcr->dir_bsock->msg);
    /* The following jobs don't need the FD */
    switch (jcr->JobType) {
    case JT_MIGRATE:

diff --git a/bacula/src/stored/label.c b/bacula/src/stored/label.c
index 306f143289d17dc1d64fc38365e4ba1bad381b9f..6de8a603dbdeb7af5a11a7f72a7da8f4dadf2d9a 100644 (file)
--- a/bacula/src/stored/label.c
+++ b/bacula/src/stored/label.c
@@ -66,9 +66,9 @@ int read_dev_volume_label(DCR *dcr)
    bool want_ansi_label;
    bool have_ansi_label = false;
 
-   Dmsg3(100, "Enter read_volume_label device=%s vol=%s dev_Vol=%s\n",
-      dev->print_name(), VolName, dev->VolHdr.VolumeName[0]?dev->VolHdr.VolumeName:
-      "*NULL*");
+   Dmsg4(100, "Enter read_volume_label res=%d device=%s vol=%s dev_Vol=%s\n",
+      dev->reserved_device, dev->print_name(), VolName, 
+      dev->VolHdr.VolumeName[0]?dev->VolHdr.VolumeName:"*NULL*");
 
    if (!dev->is_open()) {
       Emsg0(M_ABORT, 0, _("BAD call to read_dev_volume_label\n"));
@@ -85,7 +85,7 @@ int read_dev_volume_label(DCR *dcr)
          if (!dev->poll && jcr->label_errors++ > 100) {
             Jmsg(jcr, M_FATAL, 0, _("Too many tries: %s"), jcr->errmsg);
          }
-         Dmsg0(100, "return VOL_NAME_ERROR\n");
+         Dmsg0(150, "return VOL_NAME_ERROR\n");
          stat = VOL_NAME_ERROR;
          goto bail_out;
       }
@@ -194,7 +194,7 @@ int read_dev_volume_label(DCR *dcr)
       if (!dev->poll && jcr->label_errors++ > 100) {
          Jmsg(jcr, M_FATAL, 0, _("Too many tries: %s"), jcr->errmsg);
       }
-      Dmsg0(100, "return VOL_LABEL_ERROR\n");
+      Dmsg0(150, "return VOL_LABEL_ERROR\n");
       stat = VOL_LABEL_ERROR;
       goto bail_out;
    }
@@ -215,7 +215,7 @@ int read_dev_volume_label(DCR *dcr)
       if (!dev->poll && jcr->label_errors++ > 100) {
          Jmsg(jcr, M_FATAL, 0, "Too many tries: %s", jcr->errmsg);
       }
-      Dmsg0(100, "return VOL_NAME_ERROR\n");
+      Dmsg0(150, "return VOL_NAME_ERROR\n");
       stat = VOL_NAME_ERROR;
       goto bail_out;
    }
@@ -242,7 +242,7 @@ int read_dev_volume_label(DCR *dcr)
 bail_out:
    empty_block(block);
    rewind_dev(dev);
-   Dmsg1(100, "return %d\n", stat);
+   Dmsg1(150, "return %d\n", stat);
    return stat;
 }
 
@@ -302,7 +302,7 @@ bool write_new_volume_label_to_dev(DCR *dcr, const char *VolName, const char *Po
    if (dev->open(dcr, OPEN_READ_WRITE) < 0) {
       goto bail_out;
    }
-   Dmsg1(100, "Label type=%d\n", dev->label_type);
+   Dmsg1(150, "Label type=%d\n", dev->label_type);
    if (!rewind_dev(dev)) {
       free_volume(dev);
       memset(&dev->VolHdr, 0, sizeof(dev->VolHdr));
@@ -446,7 +446,7 @@ bool rewrite_volume_label(DCR *dcr, bool recycle)
       dev->VolCatInfo.VolCatWrites = 1;
       dev->VolCatInfo.VolCatReads = 1;
    }
-   Dmsg0(100, "dir_update_vol_info. Set Append\n");
+   Dmsg0(150, "dir_update_vol_info. Set Append\n");
    bstrncpy(dev->VolCatInfo.VolCatStatus, "Append", sizeof(dev->VolCatInfo.VolCatStatus));
    if (!dir_update_volume_info(dcr, true)) {  /* indicate doing relabel */
       return false;
@@ -523,7 +523,7 @@ static void create_volume_label_record(DCR *dcr, DEV_RECORD *rec)
    rec->VolSessionId = jcr->VolSessionId;
    rec->VolSessionTime = jcr->VolSessionTime;
    rec->Stream = jcr->NumVolumes;
-   Dmsg2(100, "Created Vol label rec: FI=%s len=%d\n", FI_to_ascii(buf, rec->FileIndex),
+   Dmsg2(150, "Created Vol label rec: FI=%s len=%d\n", FI_to_ascii(buf, rec->FileIndex),
       rec->data_len);
 }
 
@@ -668,7 +668,7 @@ bool write_session_label(DCR *dcr, int label)
     *  read the next block).
     */
    if (!can_write_record_to_block(block, rec)) {
-      Dmsg0(100, "Cannot write session label to block.\n");
+      Dmsg0(150, "Cannot write session label to block.\n");
       if (!write_block_to_device(dcr)) {
          Dmsg0(90, "Got session label write_block_to_dev error.\n");
          /* ****FIXME***** errno is not set here */

diff --git a/bacula/src/stored/mount.c b/bacula/src/stored/mount.c
index a70e13e21917fb67fd1afce00d511c23e28fd963..5e642ff0bb912e96832545287ff5c2db64f74fd2 100644 (file)
--- a/bacula/src/stored/mount.c
+++ b/bacula/src/stored/mount.c
@@ -48,7 +48,7 @@ bool mount_next_write_volume(DCR *dcr, bool release)
    JCR *jcr = dcr->jcr;
    DEV_BLOCK *block = dcr->block;
 
-   Dmsg1(100, "Enter mount_next_volume(release=%d)\n", release);
+   Dmsg1(150, "Enter mount_next_volume(release=%d)\n", release);
 
    init_device_wait_timers(dcr);
 
@@ -74,7 +74,7 @@ mount_next_vol:
    }
    recycle = false;
    if (release) {
-      Dmsg0(100, "mount_next_volume release=1\n");
+      Dmsg0(150, "mount_next_volume release=1\n");
       release_volume(dcr);
       ask = true;                     /* ask operator to mount tape */
    }
@@ -94,7 +94,7 @@ mount_next_vol:
    if (job_canceled(jcr)) {
       return false;
    }
-   Dmsg3(100, "After find_next_append. Vol=%s Slot=%d Parts=%d\n",
+   Dmsg3(150, "After find_next_append. Vol=%s Slot=%d Parts=%d\n",
          dcr->VolCatInfo.VolCatName, dcr->VolCatInfo.Slot, dcr->VolCatInfo.VolCatParts);
    
    /*
@@ -115,7 +115,7 @@ mount_next_vol:
       autochanger = false;
       dcr->VolCatInfo.Slot = 0;
    }
-   Dmsg1(100, "autoload_dev returns %d\n", autochanger);
+   Dmsg1(200, "autoload_dev returns %d\n", autochanger);
    /*
     * If we autochanged to correct Volume or (we have not just
     *   released the Volume AND we can automount) we go ahead
@@ -123,25 +123,25 @@ mount_next_vol:
     *   we will err, recurse and ask the operator the next time.
     */
    if (!release && dev->is_tape() && dev_cap(dev, CAP_AUTOMOUNT)) {
-      Dmsg0(100, "(1)Ask=0");
+      Dmsg0(150, "(1)Ask=0\n");
       ask = false;                 /* don't ask SYSOP this time */
    }
    /* Don't ask if not removable */
    if (!dev_cap(dev, CAP_REM)) {
-      Dmsg0(100, "(2)Ask=0");
+      Dmsg0(150, "(2)Ask=0\n");
       ask = false;
    }
-   Dmsg2(100, "Ask=%d autochanger=%d\n", ask, autochanger);
+   Dmsg2(150, "Ask=%d autochanger=%d\n", ask, autochanger);
    release = true;                /* release next time if we "recurse" */
 
    if (ask && !dir_ask_sysop_to_mount_volume(dcr)) {
-      Dmsg0(100, "Error return ask_sysop ...\n");
+      Dmsg0(150, "Error return ask_sysop ...\n");
       return false;          /* error return */
    }
    if (job_canceled(jcr)) {
       return false;
    }
-   Dmsg1(100, "want vol=%s\n", dcr->VolumeName);
+   Dmsg1(150, "want vol=%s\n", dcr->VolumeName);
 
    if (dev->poll && dev_cap(dev, CAP_CLOSEONPOLL)) {
       force_close_device(dev);
@@ -177,7 +177,7 @@ read_volume:
       return false;
    }
 
-   Dmsg2(100, "Want dirVol=%s dirStat=%s\n", dcr->VolumeName,
+   Dmsg2(150, "Want dirVol=%s dirStat=%s\n", dcr->VolumeName,
       dcr->VolCatInfo.VolCatStatus);
    /*
     * At this point, dev->VolCatInfo has what is in the drive, if anything,
@@ -185,7 +185,7 @@ read_volume:
     */
    switch (vol_label_status) {
    case VOL_OK:
-      Dmsg1(100, "Vol OK name=%s\n", dcr->VolumeName);
+      Dmsg1(150, "Vol OK name=%s\n", dcr->VolumeName);
       memcpy(&dev->VolCatInfo, &dcr->VolCatInfo, sizeof(dev->VolCatInfo));
       recycle = strcmp(dev->VolCatInfo.VolCatStatus, "Recycle") == 0;
       break;                    /* got a Volume */
@@ -200,7 +200,7 @@ read_volume:
          goto mount_next_vol;
       }
 
-      Dmsg1(100, "Vol NAME Error Name=%s\n", dcr->VolumeName);
+      Dmsg1(150, "Vol NAME Error Name=%s\n", dcr->VolumeName);
       /* If polling and got a previous bad name, ignore it */
       if (dev->poll && strcmp(dev->BadVolName, dev->VolHdr.VolumeName) == 0) {
          ask = true;
@@ -238,7 +238,7 @@ read_volume:
       /* This was not the volume we expected, but it is OK with
        * the Director, so use it.
        */
-      Dmsg1(100, "want new name=%s\n", dcr->VolumeName);
+      Dmsg1(150, "want new name=%s\n", dcr->VolumeName);
       memcpy(&dev->VolCatInfo, &dcr->VolCatInfo, sizeof(dev->VolCatInfo));
       recycle = strcmp(dev->VolCatInfo.VolCatStatus, "Recycle") == 0;
       break;                /* got a Volume */
@@ -267,15 +267,15 @@ read_volume:
       if (dev_cap(dev, CAP_LABEL) && (dcr->VolCatInfo.VolCatBytes == 0 ||
             (!dev->is_tape() && strcmp(dcr->VolCatInfo.VolCatStatus,
                                    "Recycle") == 0))) {
-         Dmsg0(100, "Create volume label\n");
+         Dmsg0(150, "Create volume label\n");
          /* Create a new Volume label and write it to the device */
          if (!write_new_volume_label_to_dev(dcr, dcr->VolumeName,
                 dcr->pool_name)) {
-            Dmsg0(100, "!write_vol_label\n");
+            Dmsg0(150, "!write_vol_label\n");
             mark_volume_in_error(dcr);
             goto mount_next_vol;
          }
-         Dmsg0(100, "dir_update_vol_info. Set Append\n");
+         Dmsg0(150, "dir_update_vol_info. Set Append\n");
          /* Copy Director's info into the device info */
          memcpy(&dev->VolCatInfo, &dcr->VolCatInfo, sizeof(dev->VolCatInfo));
          if (!dir_update_volume_info(dcr, true)) {  /* indicate tape labeled */
@@ -363,7 +363,7 @@ read_volume:
          }
       }
       dev->VolCatInfo.VolCatMounts++;      /* Update mounts */
-      Dmsg1(100, "update volinfo mounts=%d\n", dev->VolCatInfo.VolCatMounts);
+      Dmsg1(150, "update volinfo mounts=%d\n", dev->VolCatInfo.VolCatMounts);
       if (!dir_update_volume_info(dcr, false)) {
          return false;
       }
@@ -381,7 +381,7 @@ read_volume:
        */
 #ifdef xxx
       if (dev->is_dvd()) {
-         Dmsg2(100, "DVD/File sanity check addr=%u vs endblock=%u\n", (unsigned int)dev->file_addr, (unsigned int)dev->VolCatInfo.EndBlock);
+         Dmsg2(150, "DVD/File sanity check addr=%u vs endblock=%u\n", (unsigned int)dev->file_addr, (unsigned int)dev->VolCatInfo.EndBlock);
          if (dev->file_addr == dev->VolCatInfo.EndBlock+1) {
             Jmsg(jcr, M_INFO, 0, _("Ready to append to end of Volume \"%s\" at file address=%u.\n"),
                  dcr->VolumeName, (unsigned int)dev->file_addr);
@@ -401,7 +401,7 @@ read_volume:
       empty_block(block);             /* we used it for reading so set for write */
    }
    dev->set_append();
-   Dmsg0(100, "set APPEND, normal return from read_dev_for_append\n");
+   Dmsg0(150, "set APPEND, normal return from read_dev_for_append\n");
    return true;
 }
 
@@ -417,7 +417,7 @@ void mark_volume_in_error(DCR *dcr)
         dcr->VolumeName);
    memcpy(&dev->VolCatInfo, &dcr->VolCatInfo, sizeof(dev->VolCatInfo));
    bstrncpy(dev->VolCatInfo.VolCatStatus, "Error", sizeof(dev->VolCatInfo.VolCatStatus));
-   Dmsg0(100, "dir_update_vol_info. Set Error.\n");
+   Dmsg0(150, "dir_update_vol_info. Set Error.\n");
    dir_update_volume_info(dcr, false);
 }
 

diff --git a/bacula/src/stored/reserve.c b/bacula/src/stored/reserve.c
index f38d223fb1361f5799fe9c3366540c2392b8f2ed..f852e6f1e5a0327668960730f48ccd96e3816b52 100644 (file)
--- a/bacula/src/stored/reserve.c
+++ b/bacula/src/stored/reserve.c
@@ -362,6 +362,7 @@ static bool use_storage_cmd(JCR *jcr)
     * Wiffle through them and find one that can do the backup.
     */
    if (ok) {
+#ifdef OLD_ALGORITHM
       /*
        * First look for an exact match of Volume name as the
        *  tape may already be mounted.
@@ -401,6 +402,36 @@ static bool use_storage_cmd(JCR *jcr)
             goto done;
          }
       }
+#else /* NEW SEARCH ALGORITHM */ 
+      rctx.do_not_wait = true;
+      if (!jcr->PreferMountedVols) {
+         /* Look for unused drives in autochangers */
+         rctx.PreferMountedVols = false;                
+         rctx.exact_match = false;
+         rctx.available_autochanger = true;
+         if ((ok = find_suitable_device_for_job(jcr, rctx))) {
+            goto done;
+         }
+         /* Look through all drives */
+         rctx.available_autochanger = false;
+         if ((ok = find_suitable_device_for_job(jcr, rctx))) {
+            goto done;
+         }
+      }
+      /* Look for an exact match all drives */
+      rctx.PreferMountedVols = false;                
+      rctx.exact_match = true;
+      rctx.available_autochanger = false;
+      if ((ok = find_suitable_device_for_job(jcr, rctx))) {
+         goto done;
+      }
+      /* Wait for any drive anywhere */
+      rctx.exact_match = false;
+      rctx.do_not_wait = false;
+      if ((ok = find_suitable_device_for_job(jcr, rctx))) {
+         goto done;
+      }
+#endif
       if (verbose) {
          unbash_spaces(dir->msg);
          pm_strcpy(jcr->errmsg, dir->msg);
@@ -453,6 +484,9 @@ bool find_suitable_device_for_job(JCR *jcr, RCTX &rctx)
    DIRSTORE *store;
    char *device_name;
 
+   Dmsg4(100, "PrefMnt=%d exact=%d no_wait=%d availchgr=%d\n",
+      rctx.PreferMountedVols, rctx.exact_match, rctx.do_not_wait,
+      rctx.available_autochanger);
    init_jcr_device_wait_timers(jcr);
    for ( ;; ) {
       int can_wait = false;
@@ -539,7 +573,13 @@ static int search_res_for_device(RCTX &rctx)
                continue;
             }
             POOL_MEM dev_name;
-            Dmsg1(100, "Device %s opened.\n", rctx.device_name);
+            if (rctx.store->append == SD_APPEND) {
+               Dmsg2(100, "Device %s reserved=%d.\n", rctx.device_name,
+                  rctx.jcr->dcr->dev->reserved_device);
+            } else {
+               Dmsg2(100, "Device %s reserved=%d.\n", rctx.device_name,
+                  rctx.jcr->read_dcr->dev->reserved_device);
+            }
             pm_strcpy(dev_name, rctx.device->hdr.name);
             bash_spaces(dev_name);
             ok = bnet_fsend(dir, OK_device, dev_name.c_str());  /* Return real device name */
@@ -584,7 +624,8 @@ static int reserve_device(RCTX &rctx)
       }
       return -1;  /* no use waiting */
    }  
-   Dmsg1(100, "Found device %s\n", rctx.device->hdr.name);
+   Dmsg2(100, "Try reserve %s jobid=%d\n", rctx.device->hdr.name,
+         rctx.jcr->JobId);
    dcr = new_dcr(rctx.jcr, rctx.device->dev);
    if (!dcr) {
       BSOCK *dir = rctx.jcr->dir_bsock;
@@ -600,30 +641,35 @@ static int reserve_device(RCTX &rctx)
       if (rctx.exact_match && !rctx.have_volume) {
          dcr->any_volume = true;
          if (dir_find_next_appendable_volume(dcr)) {
-            Dmsg1(200, "Looking for Volume=%s\n", dcr->VolumeName);
+            Dmsg1(100, "Looking for Volume=%s\n", dcr->VolumeName);
             bstrncpy(rctx.VolumeName, dcr->VolumeName, sizeof(rctx.VolumeName));
             rctx.have_volume = true;
          } else {
-            Dmsg0(200, "No next volume found\n");
+            Dmsg0(100, "No next volume found\n");
             rctx.VolumeName[0] = 0;
         }
       }
       ok = reserve_device_for_append(dcr, rctx);
       if (ok) {
          rctx.jcr->dcr = dcr;
+         Dmsg5(100, "Reserved=%d dev_name=%s mediatype=%s pool=%s ok=%d\n",
+               dcr->dev->reserved_device,
+               dcr->dev_name, dcr->media_type, dcr->pool_name, ok);
       }
    } else {
       ok = reserve_device_for_read(dcr);
       if (ok) {
          rctx.jcr->read_dcr = dcr;
+         Dmsg5(100, "Read reserved=%d dev_name=%s mediatype=%s pool=%s ok=%d\n",
+               dcr->dev->reserved_device,
+               dcr->dev_name, dcr->media_type, dcr->pool_name, ok);
       }
    }
    if (!ok) {
       free_dcr(dcr);
+      Dmsg0(100, "Not OK.\n");
       return 0;
    }
-   Dmsg4(100, "Reserved dev_name=%s mediatype=%s pool=%s ok=%d\n",
-         dcr->dev_name, dcr->media_type, dcr->pool_name, ok);
    return 1;
 }
 
@@ -641,7 +687,7 @@ static bool reserve_device_for_read(DCR *dcr)
 
    ASSERT(dcr);
 
-   dev->block(BST_DOING_ACQUIRE);
+   P(dev->mutex);
 
    if (is_device_unmounted(dev)) {             
       Dmsg1(200, "Device %s is BLOCKED due to user unmount.\n", dev->print_name());
@@ -663,7 +709,7 @@ static bool reserve_device_for_read(DCR *dcr)
    ok = true;
 
 bail_out:
-   dev->unblock();
+   V(dev->mutex);
    return ok;
 }
 
@@ -691,7 +737,7 @@ static bool reserve_device_for_append(DCR *dcr, RCTX &rctx)
 
    ASSERT(dcr);
 
-   dev->block(BST_DOING_ACQUIRE);
+   P(dev->mutex);
 
    if (dev->can_read()) {
       Mmsg1(jcr->errmsg, _("Device %s is busy reading.\n"), dev->print_name());
@@ -705,20 +751,21 @@ static bool reserve_device_for_append(DCR *dcr, RCTX &rctx)
       goto bail_out;
    }
 
-   Dmsg1(190, "reserve_append device is %s\n", dev->is_tape()?"tape":"disk");
+   Dmsg1(100, "reserve_append device is %s\n", dev->is_tape()?"tape":"disk");
 
    if (can_reserve_drive(dcr, rctx) != 1) {
-      Dmsg1(100, "%s", jcr->errmsg);
+      Dmsg0(100, "can_reserve_drive!=1\n");
       goto bail_out;
    }
 
    dev->reserved_device++;
-   Dmsg1(200, "Inc reserve=%d\n", dev->reserved_device);
+   Dmsg3(100, "Inc reserve=%d dev=%s %p\n", dev->reserved_device, 
+      dev->print_name(), dev);
    dcr->reserved_device = true;
    ok = true;
 
 bail_out:
-   dev->unblock();
+   V(dev->mutex);
    return ok;
 }
 
@@ -732,19 +779,24 @@ static int can_reserve_drive(DCR *dcr, RCTX &rctx)
    DEVICE *dev = dcr->dev;
    JCR *jcr = dcr->jcr;
 
+   /* If he wants a free drive, but this one is busy, no go */
+   if (!rctx.PreferMountedVols && dev->is_busy()) {
+      Dmsg1(100, "!prefMnt && busy. JobId=%d\n", jcr->JobId);
+      return 0;
+   }
+   Dmsg3(100, "prefmnt=%d busy=%d res=%d\n", rctx.PreferMountedVols, 
+      dev->is_busy(), dev->reserved_device);
+
    /* Check for prefer mounted volumes */
    if (rctx.PreferMountedVols && !dev->VolHdr.VolumeName[0] && dev->is_tape()) {
-      Mmsg0(jcr->errmsg, _("Want mounted Volume, drive is empty\n"));
-      Dmsg0(200, "want mounted -- no vol\n");
+      Dmsg1(100, "want mounted -- no vol JobId=%d\n", jcr->JobId);
       return 0;                 /* No volume mounted */
    }
 
    /* Check for exact Volume name match */
    if (rctx.exact_match && rctx.have_volume &&
        strcmp(dev->VolHdr.VolumeName, rctx.VolumeName) != 0) {
-      Mmsg2(jcr->errmsg, _("Not exact match have=%s want=%s\n"),
-            dev->VolHdr.VolumeName, rctx.VolumeName);
-      Dmsg2(200, "Not exact match have=%s want=%s\n",
+      Dmsg2(100, "Not exact match have=%s want=%s\n",
             dev->VolHdr.VolumeName, rctx.VolumeName);
       return 0;
    }
@@ -753,6 +805,8 @@ static int can_reserve_drive(DCR *dcr, RCTX &rctx)
    if (rctx.available_autochanger && dev->num_writers == 0 &&
        dev->VolHdr.VolumeName[0] == 0) {
       /* Device is available but not yet reserved, reserve it for us */
+      Dmsg2(100, "Res Unused autochanger %s JobId=%d.\n",
+         dev->print_name(), jcr->JobId);
       bstrncpy(dev->pool_name, dcr->pool_name, sizeof(dev->pool_name));
       bstrncpy(dev->pool_type, dcr->pool_type, sizeof(dev->pool_type));
       return 1;                       /* reserve drive */
@@ -768,13 +822,12 @@ static int can_reserve_drive(DCR *dcr, RCTX &rctx)
          if (strcmp(dev->pool_name, dcr->pool_name) == 0 &&
              strcmp(dev->pool_type, dcr->pool_type) == 0) {
             /* OK, compatible device */
-            Dmsg0(200, "got dev: num_writers=0, reserved, pool matches\n");
+            Dmsg2(100, "got dev: %s num_writers=0, reserved, pool matches JobId=%d\n",
+               dev->print_name(), jcr->JobId);
             return 1;
          } else {
             /* Drive not suitable for us */
-            Mmsg2(jcr->errmsg, _("Drive busy wrong pool: num_writers=0, reserved, pool=%s wanted=%s\n"),
-               dev->pool_name, dcr->pool_name);
-            Dmsg2(200, "busy: num_writers=0, reserved, pool=%s wanted=%s\n",
+            Dmsg2(100, "busy: num_writers=0, reserved, pool=%s wanted=%s\n",
                dev->pool_name, dcr->pool_name);
             return 0;                 /* wait */
          }
@@ -782,16 +835,19 @@ static int can_reserve_drive(DCR *dcr, RCTX &rctx)
          /* Device in append mode, check if changing pool */
          if (strcmp(dev->pool_name, dcr->pool_name) == 0 &&
              strcmp(dev->pool_type, dcr->pool_type) == 0) {
-            Dmsg0(200, "got dev: num_writers=0, can_append, pool matches\n");
+            Dmsg2(100, "got dev: %s num_writers=0, can_append, pool matches. JobId=%d\n",
+               dev->print_name(), jcr->JobId);
             /* OK, compatible device */
             return 1;
          } else {
             /* Changing pool, unload old tape if any in drive */
-            Dmsg0(200, "got dev: num_writers=0, not reserved, pool change, unload changer\n");
+            Dmsg0(100, "got dev: num_writers=0, not reserved, pool change, unload changer\n");
             unload_autochanger(dcr, 0);
          }
       }
       /* Device is available but not yet reserved, reserve it for us */
+      Dmsg2(100, "Dev avail reserved %s JobId=%d\n", dev->print_name(),
+         jcr->JobId);
       bstrncpy(dev->pool_name, dcr->pool_name, sizeof(dev->pool_name));
       bstrncpy(dev->pool_type, dcr->pool_type, sizeof(dev->pool_type));
       return 1;                       /* reserve drive */
@@ -802,18 +858,16 @@ static int can_reserve_drive(DCR *dcr, RCTX &rctx)
     *  available if pool is the same).
     */
    if (dev->can_append() || dev->num_writers > 0) {
-      Dmsg0(190, "device already in append.\n");
       /* Yes, now check if we want the same Pool and pool type */
       if (strcmp(dev->pool_name, dcr->pool_name) == 0 &&
           strcmp(dev->pool_type, dcr->pool_type) == 0) {
-         Dmsg0(200, "got dev: num_writers>=0, can_append, pool matches\n");
+         Dmsg2(100, "got dev: %s num_writers>=0, can_append, pool matches. JobId=%d\n",
+            dev->print_name(), jcr->JobId);
          /* OK, compatible device */
          return 1;
       } else {
          /* Drive not suitable for us */
-         Mmsg(jcr->errmsg, _("Wanted Pool \"%s\", but device %s is using Pool \"%s\" .\n"), 
-                 dcr->pool_name, dev->print_name(), dev->pool_name);
-         Dmsg2(200, "busy: num_writers>0, can_append, pool=%s wanted=%s\n",
+         Dmsg2(100, "busy: num_writers>0, can_append, pool=%s wanted=%s\n",
             dev->pool_name, dcr->pool_name);
          return 0;                    /* wait */
       }
@@ -822,6 +876,6 @@ static int can_reserve_drive(DCR *dcr, RCTX &rctx)
       Jmsg0(jcr, M_FATAL, 0, _("Logic error!!!! Should not get here.\n"));
       return -1;                      /* error, should not get here */
    }
-
+   Dmsg2(100, "No reserve %s JobId=%d\n", dev->print_name(), jcr->JobId);
    return 0;
 }

diff --git a/bacula/src/version.h b/bacula/src/version.h
index 39b53383cfa2e941b37f7ec8d1f1cc24bb76e6e8..78d0faa2ac6b8262ce118f0e11f64ed8a321b44f 100644 (file)
--- a/bacula/src/version.h
+++ b/bacula/src/version.h
@@ -4,8 +4,8 @@
 
 #undef  VERSION
 #define VERSION "1.39.2"
-#define BDATE   "04 December 2005"
-#define LSMDATE "04Dec05"
+#define BDATE   "05 December 2005"
+#define LSMDATE "05Dec05"
 
 /* Debug flags */
 #undef  DEBUG