]> git.sur5r.net Git - bacula/bacula/blobdiff - bacula/src/stored/reserve.c
Tweak debug levels in reservations + Correct typo in UTF-8 error message as reported by:
[bacula/bacula] / bacula / src / stored / reserve.c
index bc590e210ad2a010bc1882951b76104cd38cfbd9..205062d620833dc61e88b4ba8dbe65634d703d31 100644 (file)
@@ -86,7 +86,7 @@ void init_reservations_lock()
    if ((errstat=rwl_init(&reservation_lock)) != 0) {
       berrno be;
       Emsg1(M_ABORT, 0, _("Unable to initialize reservation lock. ERR=%s\n"),
-            be.strerror(errstat));
+            be.bstrerror(errstat));
    }
 
 }
@@ -106,7 +106,7 @@ void _lock_reservations()
    if ((errstat=rwl_writelock(&reservation_lock)) != 0) {
       berrno be;
       Emsg2(M_ABORT, 0, "rwl_writelock failure. stat=%d: ERR=%s\n",
-           errstat, be.strerror(errstat));
+           errstat, be.bstrerror(errstat));
    }
 }
 
@@ -117,7 +117,7 @@ void _unlock_reservations()
    if ((errstat=rwl_writeunlock(&reservation_lock)) != 0) {
       berrno be;
       Emsg2(M_ABORT, 0, "rwl_writeunlock failure. stat=%d: ERR=%s\n",
-           errstat, be.strerror(errstat));
+           errstat, be.bstrerror(errstat));
    }
 }
 
@@ -151,7 +151,7 @@ static void debug_list_volumes(const char *imsg, bool do_lock)
    for (vol=(VOLRES *)vol_list->first(); vol; vol=(VOLRES *)vol_list->next(vol)) {
       if (vol->dev == dev) {
          Dmsg0(000, "Two Volumes on same device.\n");
-         ASSERT(1);
+         ASSERT(0);
          dev = vol->dev;
       }
    }
@@ -202,6 +202,9 @@ static VOLRES *new_vol_item(DCR *dcr, const char *VolumeName)
 static void free_vol_item(VOLRES *vol)
 {
    free(vol->vol_name);
+   if (vol->dev) {
+      vol->dev->vol = NULL;
+   }
    free(vol);
 }
 
@@ -261,7 +264,7 @@ static void free_vol_item(VOLRES *vol)
 
  *
  *  Return: VOLRES entry on success
- *          NULL error
+ *          NULL volume busy on another drive
  */
 VOLRES *reserve_volume(DCR *dcr, const char *VolumeName)
 {
@@ -276,7 +279,6 @@ VOLRES *reserve_volume(DCR *dcr, const char *VolumeName)
     *  when adding a new volume that no newly scheduled
     *  job can reserve it.
     */
-   lock_reservations();
    P(vol_list_lock);
    debug_list_volumes("begin reserve_volume", debug_nolock);
    /* 
@@ -316,22 +318,29 @@ VOLRES *reserve_volume(DCR *dcr, const char *VolumeName)
        */
       Dmsg3(100, "reserve_vol free-tmp vol=%s at %p JobId=%u\n", vol->vol_name,
             vol->vol_name, (int)dcr->jcr->JobId);
+      /*
+       * Clear dev pointer so that free_vol_item() doesn't 
+       *  take away our volume. 
+       */
+      nvol->dev = NULL;                   /* don't zap dev entry */
       free_vol_item(nvol);
 
       /* Check if we are trying to use the Volume on a different drive */
       if (dev != vol->dev) {
          /* Caller wants to switch Volume to another device */
-         if (!dev->is_busy()) {
-            /* OK to move it */
-            Dmsg3(100, "Swap vol=%s from dev=%s to %s\n", VolumeName,
-               dev->print_name(), dev->print_name());
-            vol->dev = dev;
+         if (!vol->dev->is_busy()) {
+            /* OK to move it -- I'm not sure this will work */
+            Dmsg3(100, "==== Swap vol=%s from dev=%s to %s\n", VolumeName,
+               vol->dev->print_name(), dev->print_name());
+            vol->dev->vol = NULL;         /* take vol from old drive */
+            vol->dev->VolHdr.VolumeName[0] = 0;
+            vol->dev = dev;               /* point vol at new drive */
+            dev->vol = vol;               /* point dev at vol */
             dev->VolHdr.VolumeName[0] = 0;
          } else {
+            Dmsg3(100, "Volume busy could not swap vol=%s from dev=%s to %s\n", VolumeName,
+               vol->dev->print_name(), dev->print_name());
             vol = NULL;                /* device busy */
-            Dmsg3(100, "Logic ERROR!!!! could not swap vol=%s from dev=%s to %s\n", VolumeName,
-               dev->print_name(), dcr->dev->print_name());
-            ASSERT(1);     /* blow up!!! */
          }
       }
    }
@@ -340,7 +349,6 @@ VOLRES *reserve_volume(DCR *dcr, const char *VolumeName)
 get_out:
    debug_list_volumes("end new volume", debug_nolock);
    V(vol_list_lock);
-   unlock_reservations();
    return vol;
 }
 
@@ -568,7 +576,8 @@ static bool use_storage_cmd(JCR *jcr)
    /* ***FIXME**** remove after 1.38 release */
    char *device_name;
    foreach_alist(store, dirstore) {
-      Dmsg5(110, "Storage=%s media_type=%s pool=%s pool_type=%s append=%d\n", 
+      Dmsg6(110, "JobId=%u Storage=%s media_type=%s pool=%s pool_type=%s append=%d\n", 
+         (int)rctx.jcr->JobId,
          store->name, store->media_type, store->pool_name, 
          store->pool_type, store->append);
       foreach_alist(device_name, store->device) {
@@ -588,7 +597,7 @@ static bool use_storage_cmd(JCR *jcr)
     * Wiffle through them and find one that can do the backup.
     */
    if (ok) {
-      bool first = true;           /* print wait message once */
+      int retries = 0;                /* wait for device retries */
       bool fail = false;
       rctx.notify_dir = true;
       lock_reservations();
@@ -607,7 +616,8 @@ static bool use_storage_cmd(JCR *jcr)
             rctx.PreferMountedVols = false;                
             rctx.exact_match = false;
             rctx.autochanger_only = true;
-            Dmsg5(110, "PrefMnt=%d exact=%d suitable=%d chgronly=%d any=%d\n",
+            Dmsg6(110, "JobId=%u PrefMnt=%d exact=%d suitable=%d chgronly=%d any=%d\n",
+               (int)rctx.jcr->JobId,
                rctx.PreferMountedVols, rctx.exact_match, rctx.suitable_device,
                rctx.autochanger_only, rctx.any_drive);
             if ((ok = find_suitable_device_for_job(jcr, rctx))) {
@@ -622,7 +632,8 @@ static bool use_storage_cmd(JCR *jcr)
                rctx.try_low_use_drive = false;
             }
             rctx.autochanger_only = false;
-            Dmsg5(110, "PrefMnt=%d exact=%d suitable=%d chgronly=%d any=%d\n",
+            Dmsg6(110, "JobId=%u PrefMnt=%d exact=%d suitable=%d chgronly=%d any=%d\n",
+               (int)rctx.jcr->JobId,
                rctx.PreferMountedVols, rctx.exact_match, rctx.suitable_device,
                rctx.autochanger_only, rctx.any_drive);
             if ((ok = find_suitable_device_for_job(jcr, rctx))) {
@@ -633,7 +644,8 @@ static bool use_storage_cmd(JCR *jcr)
          rctx.PreferMountedVols = true;
          rctx.exact_match = true;
          rctx.autochanger_only = false;
-         Dmsg5(110, "PrefMnt=%d exact=%d suitable=%d chgronly=%d any=%d\n",
+         Dmsg6(110, "JobId=%u PrefMnt=%d exact=%d suitable=%d chgronly=%d any=%d\n",
+            (int)rctx.jcr->JobId,
             rctx.PreferMountedVols, rctx.exact_match, rctx.suitable_device,
             rctx.autochanger_only, rctx.any_drive);
          if ((ok = find_suitable_device_for_job(jcr, rctx))) {
@@ -641,7 +653,8 @@ static bool use_storage_cmd(JCR *jcr)
          }
          /* Look for any mounted drive */
          rctx.exact_match = false;
-         Dmsg5(110, "PrefMnt=%d exact=%d suitable=%d chgronly=%d any=%d\n",
+         Dmsg6(110, "JobId=%u PrefMnt=%d exact=%d suitable=%d chgronly=%d any=%d\n",
+            (int)rctx.jcr->JobId,
             rctx.PreferMountedVols, rctx.exact_match, rctx.suitable_device,
             rctx.autochanger_only, rctx.any_drive);
          if ((ok = find_suitable_device_for_job(jcr, rctx))) {
@@ -649,7 +662,8 @@ static bool use_storage_cmd(JCR *jcr)
          }
          /* Try any drive */
          rctx.any_drive = true;
-         Dmsg5(110, "PrefMnt=%d exact=%d suitable=%d chgronly=%d any=%d\n",
+         Dmsg6(110, "JobId=%u PrefMnt=%d exact=%d suitable=%d chgronly=%d any=%d\n",
+            (int)rctx.jcr->JobId,
             rctx.PreferMountedVols, rctx.exact_match, rctx.suitable_device,
             rctx.autochanger_only, rctx.any_drive);
          if ((ok = find_suitable_device_for_job(jcr, rctx))) {
@@ -657,12 +671,12 @@ static bool use_storage_cmd(JCR *jcr)
          }
          /* Keep reservations locked *except* during wait_for_device() */
          unlock_reservations();
-         if (!rctx.suitable_device || !wait_for_device(jcr, first)) {
-            Dmsg0(100, "Fail. !suitable_device || !wait_for_device\n");
+         if (!rctx.suitable_device || !wait_for_device(jcr, retries)) {
+            Dmsg1(100, "JobId=%u Fail. !suitable_device || !wait_for_device\n",
+                 (int)rctx.jcr->JobId);
             fail = true;
          }   
          lock_reservations();
-         first = false;
          bnet_sig(dir, BNET_HEARTBEAT);  /* Inform Dir that we are alive */
       }
       unlock_reservations();
@@ -730,7 +744,8 @@ bool find_suitable_device_for_job(JCR *jcr, RCTX &rctx)
     * For each storage device that the user specified, we
     *  search and see if there is a resource for that device.
     */
-   Dmsg4(110, "PrefMnt=%d exact=%d suitable=%d chgronly=%d\n",
+   Dmsg5(110, "JobId=%u PrefMnt=%d exact=%d suitable=%d chgronly=%d\n",
+      (int)rctx.jcr->JobId,
       rctx.PreferMountedVols, rctx.exact_match, rctx.suitable_device,
       rctx.autochanger_only);
    ok = false;
@@ -741,14 +756,16 @@ bool find_suitable_device_for_job(JCR *jcr, RCTX &rctx)
          rctx.device_name = device_name;
          stat = search_res_for_device(rctx); 
          if (stat == 1) {             /* found available device */
-            Dmsg1(100, "Suitable device found=%s\n", device_name);
+            Dmsg2(100, "JobId=%u Suitable device found=%s\n", (int)rctx.jcr->JobId, 
+                  device_name);
             ok = true;
             break;
          } else if (stat == 0) {      /* device busy */
-            Dmsg1(110, "Suitable device=%s, busy: not use\n", device_name);
+            Dmsg2(110, "JobId=%u Suitable device=%s, busy: not use\n", 
+                  (int)rctx.jcr->JobId, device_name);
          } else {
             /* otherwise error */
-            Dmsg0(110, "No suitable device found.\n");
+            Dmsg1(110, "JobId=%u No suitable device found.\n", (int)rctx.jcr->JobId);
          }
       }
       if (ok) {
@@ -769,25 +786,28 @@ int search_res_for_device(RCTX &rctx)
    bool ok;
    int stat;
 
-   Dmsg1(110, "Search res for %s\n", rctx.device_name);
+   Dmsg2(110, "JobId=%u search res for %s\n", (int)rctx.jcr->JobId, rctx.device_name);
    /* Look through Autochangers first */
    foreach_res(changer, R_AUTOCHANGER) {
-      Dmsg1(150, "Try match changer res=%s\n", changer->hdr.name);
+      Dmsg2(150, "JobId=%u Try match changer res=%s\n", (int)rctx.jcr->JobId, changer->hdr.name);
       /* Find resource, and make sure we were able to open it */
       if (fnmatch(rctx.device_name, changer->hdr.name, 0) == 0) {
          /* Try each device in this AutoChanger */
          foreach_alist(rctx.device, changer->device) {
-            Dmsg1(110, "Try changer device %s\n", rctx.device->hdr.name);
+            Dmsg2(110, "JobId=%u Try changer device %s\n", (int)rctx.jcr->JobId, 
+                  rctx.device->hdr.name);
             stat = reserve_device(rctx);
             if (stat != 1) {             /* try another device */
                continue;
             }
             POOL_MEM dev_name;
             if (rctx.store->append == SD_APPEND) {
-               Dmsg2(100, "Device %s reserved=%d for append.\n", rctx.device->hdr.name,
+               Dmsg3(100, "JobId=%u Device %s reserved=%d for append.\n", 
+                  (int)rctx.jcr->JobId, rctx.device->hdr.name,
                   rctx.jcr->dcr->dev->reserved_device);
             } else {
-               Dmsg2(100, "Device %s reserved=%d for read.\n", rctx.device->hdr.name,
+               Dmsg3(100, "JobId=%u Device %s reserved=%d for read.\n", 
+                  (int)rctx.jcr->JobId, rctx.device->hdr.name,
                   rctx.jcr->read_dcr->dev->reserved_device);
             }
             if (rctx.notify_dir) {
@@ -806,7 +826,7 @@ int search_res_for_device(RCTX &rctx)
    /* Now if requested look through regular devices */
    if (!rctx.autochanger_only) {
       foreach_res(rctx.device, R_DEVICE) {
-         Dmsg1(150, "Try match res=%s\n", rctx.device->hdr.name);
+         Dmsg2(150, "JobId=%u Try match res=%s\n", (int)rctx.jcr->JobId, rctx.device->hdr.name);
          /* Find resource, and make sure we were able to open it */
          if (fnmatch(rctx.device_name, rctx.device->hdr.name, 0) == 0) {
             stat = reserve_device(rctx);
@@ -841,7 +861,8 @@ static int reserve_device(RCTX &rctx)
    const int name_len = MAX_NAME_LENGTH;
 
    /* Make sure MediaType is OK */
-   Dmsg2(110, "MediaType device=%s request=%s\n",
+   Dmsg3(110, "JobId=%u MediaType device=%s request=%s\n",
+         (int)rctx.jcr->JobId,
          rctx.device->media_type, rctx.store->media_type);
    if (strcmp(rctx.device->media_type, rctx.store->media_type) != 0) {
       return -1;
@@ -879,7 +900,8 @@ static int reserve_device(RCTX &rctx)
    bstrncpy(dcr->media_type, rctx.store->media_type, name_len);
    bstrncpy(dcr->dev_name, rctx.device_name, name_len);
    if (rctx.store->append == SD_APPEND) {
-      Dmsg2(100, "have_vol=%d vol=%s\n", rctx.have_volume, rctx.VolumeName);
+      Dmsg3(100, "JobId=%u have_vol=%d vol=%s\n", (int)rctx.jcr->JobId,
+          rctx.have_volume, rctx.VolumeName);                                   
       if (!rctx.have_volume) {
          dcr->any_volume = true;
          if (dir_find_next_appendable_volume(dcr)) {
@@ -887,7 +909,7 @@ static int reserve_device(RCTX &rctx)
             Dmsg2(100, "JobId=%u looking for Volume=%s\n", (int)rctx.jcr->JobId, rctx.VolumeName);
             rctx.have_volume = true;
          } else {
-            Dmsg0(100, "No next volume found\n");
+            Dmsg1(100, "JobId=%u No next volume found\n", (int)rctx.jcr->JobId);
             rctx.have_volume = false;
             rctx.VolumeName[0] = 0;
         }
@@ -895,7 +917,8 @@ static int reserve_device(RCTX &rctx)
       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",
+         Dmsg6(100, "JobId=%u Reserved=%d dev_name=%s mediatype=%s pool=%s ok=%d\n",
+               (int)rctx.jcr->JobId,
                dcr->dev->reserved_device,
                dcr->dev_name, dcr->media_type, dcr->pool_name, ok);
       }
@@ -903,7 +926,8 @@ static int reserve_device(RCTX &rctx)
       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",
+         Dmsg6(100, "JobId=%u Read reserved=%d dev_name=%s mediatype=%s pool=%s ok=%d\n",
+               (int)rctx.jcr->JobId,
                dcr->dev->reserved_device,
                dcr->dev_name, dcr->media_type, dcr->pool_name, ok);
       }
@@ -911,7 +935,7 @@ static int reserve_device(RCTX &rctx)
    if (!ok) {
       rctx.have_volume = false;
       free_dcr(dcr);
-      Dmsg0(110, "Not OK.\n");
+      Dmsg1(110, "JobId=%u Not OK.\n", (int)rctx.jcr->JobId);
       return 0;
    }
    return 1;
@@ -931,13 +955,11 @@ static bool reserve_device_for_read(DCR *dcr)
 
    ASSERT(dcr);
 
-   /* Get locks in correct order */
-   unlock_reservations();
    dev->dlock();  
-   lock_reservations();
 
    if (is_device_unmounted(dev)) {             
-      Dmsg1(200, "Device %s is BLOCKED due to user unmount.\n", dev->print_name());
+      Dmsg2(200, "JobId=%u Device %s is BLOCKED due to user unmount.\n", 
+         (int)jcr->JobId, dev->print_name());
       Mmsg(jcr->errmsg, _("3601 JobId=%u device %s is BLOCKED due to user unmount.\n"),
            jcr->JobId, dev->print_name());
       queue_reserve_message(jcr);
@@ -945,7 +967,8 @@ static bool reserve_device_for_read(DCR *dcr)
    }
 
    if (dev->is_busy()) {
-      Dmsg4(200, "Device %s is busy ST_READ=%d num_writers=%d reserved=%d.\n", dev->print_name(),
+      Dmsg5(200, "JobId=%u Device %s is busy ST_READ=%d num_writers=%d reserved=%d.\n", 
+         (int)jcr->JobId, dev->print_name(),
          dev->state & ST_READ?1:0, dev->num_writers, dev->reserved_device);
       Mmsg(jcr->errmsg, _("3602 JobId=%u device %s is busy (already reading/writing).\n"),
             jcr->JobId, dev->print_name());
@@ -957,8 +980,8 @@ static bool reserve_device_for_read(DCR *dcr)
    dev->set_read();
    ok = true;
    dev->reserved_device++;
-   Dmsg3(100, "Inc reserve=%d dev=%s %p\n", dev->reserved_device, 
-      dev->print_name(), dev);
+   Dmsg4(100, "JobId=%u Inc reserve=%d dev=%s %p\n", (int)jcr->JobId,
+      dev->reserved_device, dev->print_name(), dev);
    dcr->reserved_device = true;
 
 bail_out:
@@ -990,10 +1013,7 @@ static bool reserve_device_for_append(DCR *dcr, RCTX &rctx)
 
    ASSERT(dcr);
 
-   /* Get locks in correct order */
-   unlock_reservations();
    dev->dlock();
-   lock_reservations();
 
    /* If device is being read, we cannot write it */
    if (dev->can_read()) {
@@ -1013,16 +1033,17 @@ static bool reserve_device_for_append(DCR *dcr, RCTX &rctx)
       goto bail_out;
    }
 
-   Dmsg1(110, "reserve_append device is %s\n", dev->is_tape()?"tape":"disk");
+   Dmsg2(110, "JobId=%u reserve_append device is %s\n", 
+       (int)jcr->JobId, dev->is_tape()?"tape":"disk");
 
    /* Now do detailed tests ... */
    if (can_reserve_drive(dcr, rctx) != 1) {
-      Dmsg0(110, "can_reserve_drive!=1\n");
+      Dmsg1(110, "JobId=%u can_reserve_drive!=1\n", (int)jcr->JobId);
       goto bail_out;
    }
 
    dev->reserved_device++;
-   Dmsg3(100, "Inc reserve=%d dev=%s %p\n", dev->reserved_device, 
+   Dmsg4(100, "JobId=%u Inc reserve=%d dev=%s %p\n", (int)jcr->JobId, dev->reserved_device, 
       dev->print_name(), dev);
    dcr->reserved_device = true;
    ok = true;
@@ -1042,7 +1063,8 @@ static int can_reserve_drive(DCR *dcr, RCTX &rctx)
    DEVICE *dev = dcr->dev;
    JCR *jcr = dcr->jcr;
 
-   Dmsg5(110, "PrefMnt=%d exact=%d suitable=%d chgronly=%d any=%d\n",
+   Dmsg6(110, "JobId=%u PrefMnt=%d exact=%d suitable=%d chgronly=%d any=%d\n",
+         (int)jcr->JobId,
          rctx.PreferMountedVols, rctx.exact_match, rctx.suitable_device,
          rctx.autochanger_only, rctx.any_drive);
 
@@ -1065,11 +1087,11 @@ static int can_reserve_drive(DCR *dcr, RCTX &rctx)
          if ((dev->num_writers + dev->reserved_device) < rctx.num_writers) {
             rctx.num_writers = dev->num_writers + dev->reserved_device;
             rctx.low_use_drive = dev;
-            Dmsg2(110, "set low use drive=%s num_writers=%d\n", dev->print_name(),
-               rctx.num_writers);
+            Dmsg3(110, "JobId=%u set low use drive=%s num_writers=%d\n", 
+               (int)jcr->JobId, dev->print_name(), rctx.num_writers);
          } else {
-            Dmsg1(110, "not low use num_writers=%d\n", dev->num_writers+ 
-               dev->reserved_device);
+            Dmsg2(110, "JobId=%u not low use num_writers=%d\n", 
+               (int)jcr->JobId, dev->num_writers+dev->reserved_device);
          }
          Dmsg1(110, "failed: !prefMnt && busy. JobId=%u\n", jcr->JobId);
          Mmsg(jcr->errmsg, _("3605 JobId=%u wants free drive but device %s is busy.\n"), 
@@ -1079,28 +1101,31 @@ static int can_reserve_drive(DCR *dcr, RCTX &rctx)
       }
 
       /* Check for prefer mounted volumes */
-      if (rctx.PreferMountedVols && !dev->VolHdr.VolumeName[0] && dev->is_tape()) {
+//    if (rctx.PreferMountedVols && !dev->VolHdr.VolumeName[0] && dev->is_tape()) {
+      if (rctx.PreferMountedVols && !dev->vol && dev->is_tape()) {
          Mmsg(jcr->errmsg, _("3606 JobId=%u prefers mounted drives, but drive %s has no Volume.\n"), 
             jcr->JobId, dev->print_name());
          queue_reserve_message(jcr);
-         Dmsg1(110, "failed: want mounted -- no vol JobId=%u\n", jcr->JobId);
+         Dmsg1(110, "failed: want mounted -- no vol JobId=%u\n", (uint32_t)jcr->JobId);
          return 0;                 /* No volume mounted */
       }
 
       /* Check for exact Volume name match */
+      /*  ***FIXME***  use dev->vol.VolumeName */
       if (rctx.exact_match && rctx.have_volume &&
           strcmp(dev->VolHdr.VolumeName, rctx.VolumeName) != 0) {
          Mmsg(jcr->errmsg, _("3607 JobId=%u wants Vol=\"%s\" drive has Vol=\"%s\" on drive %s.\n"), 
             jcr->JobId, rctx.VolumeName, dev->VolHdr.VolumeName, 
             dev->print_name());
          queue_reserve_message(jcr);
-         Dmsg2(110, "failed: Not exact match have=%s want=%s\n",
-               dev->VolHdr.VolumeName, rctx.VolumeName);
+         Dmsg3(110, "JobId=%u failed: Not exact match have=%s want=%s\n",
+               (int)jcr->JobId, dev->VolHdr.VolumeName, rctx.VolumeName);
          return 0;
       }
    }
 
    /* Check for unused autochanger drive */
+   /* ***FIXME*** use !dev->is_busy() */
    if (rctx.autochanger_only && dev->num_writers == 0 &&
        dev->VolHdr.VolumeName[0] == 0) {
       /* Device is available but not yet reserved, reserve it for us */
@@ -1131,8 +1156,8 @@ static int can_reserve_drive(DCR *dcr, RCTX &rctx)
                   jcr->JobId, dcr->pool_name, dev->pool_name,
                   dev->reserved_device, dev->print_name());
             queue_reserve_message(jcr);
-            Dmsg2(110, "failed: busy num_writers=0, reserved, pool=%s wanted=%s\n",
-               dev->pool_name, dcr->pool_name);
+            Dmsg3(110, "JobId=%u failed: busy num_writers=0, reserved, pool=%s wanted=%s\n",
+               (int)jcr->JobId, dev->pool_name, dcr->pool_name);
             return 0;                 /* wait */
          }
       } else if (dev->can_append()) {
@@ -1145,7 +1170,8 @@ static int can_reserve_drive(DCR *dcr, RCTX &rctx)
             return 1;
          } else {
             /* Changing pool, unload old tape if any in drive */
-            Dmsg0(100, "OK dev: num_writers=0, not reserved, pool change, unload changer\n");
+            Dmsg1(100, "JobId=%u OK dev: num_writers=0, not reserved, pool change, unload changer\n",
+                (int)jcr->JobId);
             unload_autochanger(dcr, 0);
          }
       }
@@ -1174,12 +1200,12 @@ static int can_reserve_drive(DCR *dcr, RCTX &rctx)
          Mmsg(jcr->errmsg, _("3609 JobId=%u wants Pool=\"%s\" but has Pool=\"%s\" on drive %s.\n"), 
                jcr->JobId, dcr->pool_name, dev->pool_name, dev->print_name());
          queue_reserve_message(jcr);
-         Dmsg2(110, "failed: busy num_writers>0, can_append, pool=%s wanted=%s\n",
-            dev->pool_name, dcr->pool_name);
+         Dmsg3(110, "JobId=%u failed: busy num_writers>0, can_append, pool=%s wanted=%s\n",
+            (int)jcr->JobId, dev->pool_name, dcr->pool_name);
          return 0;                    /* wait */
       }
    } else {
-      Pmsg0(000, _("Logic error!!!! Should not get here.\n"));
+      Pmsg1(000, _("Logic error!!!! JobId=%u Should not get here.\n"), (int)jcr->JobId);
       Mmsg(jcr->errmsg, _("3910 JobId=%u Logic error!!!! drive %s Should not get here.\n"),
             jcr->JobId, dev->print_name());
       queue_reserve_message(jcr);