From c8601cd3c2184c038ec7ea0fc90b06572ad54b4e Mon Sep 17 00:00:00 2001
From: Kern Sibbald <kern@sibbald.com>
Date: Sun, 15 Jan 2006 11:21:54 +0000
Subject: [PATCH] 15Jan06 - Add periodic (every 24 hours) garbage collection of
 memory   pool by releasing free buffers. 14Jan06 - Correct bug counting sized
 (for display only) in smartall.c - Print FD mempool stats if debug > 0 rather
 than 5. 12Jan06 - Make db_lock() mutex error fail the job rather than abort  
 Bacula.  Canceling the job caused the mutex to fail. - Correct bug in alist.c
 that re-allocated the list if the   number of items goes to zero. - Move the
 reservation system thread locking to the top level   so that one job at a
 time tries all possible drives before   waiting. - Implement a reservation
 'fail' message queue that is built   and destroyed on each pass through the
 reservation system.   These messages are displayed in a 'Jobs waiting to
 reserve   a drive' list during a 'status storage='.  Note, multiple  
 messages will generally print for each JobId because they   represent the
 different problems with either the same drive   or different drives.  If this
 output proves too confusing   of voluminous, I will display it only when
 debug level 1   or greater is enabled in the SD. 11Jan06 - Add enable/disable
 job=<job-name>.  This command prevents   the specified job from being
 scheduled. Even when disabled,   the job can be manually started from the
 console. - During 'update slots' clear all InChanger flags where the  
 StorageId is zero (old Media records).

git-svn-id: https://bacula.svn.sourceforge.net/svnroot/bacula/trunk@2746 91ce42f0-d328-0410-95d8-f526ca767f89
---
 bacula/examples/autochangers/chio-changer |   2 +-
 bacula/kernstodo                          |  15 +-
 bacula/kes-1.38                           |  48 +++-
 bacula/src/baconfig.h                     |   4 +-
 bacula/src/c                              |   2 +-
 bacula/src/cats/sql.c                     |   8 +-
 bacula/src/dird/ua_output.c               |   3 +-
 bacula/src/filed/filed.c                  |   8 +-
 bacula/src/jcr.h                          |   3 +-
 bacula/src/lib/alist.c                    |   4 +-
 bacula/src/lib/alist.h                    |   6 +-
 bacula/src/lib/jcr.c                      |   1 +
 bacula/src/lib/mem_pool.c                 |  51 ++++-
 bacula/src/lib/mem_pool.h                 |  18 +-
 bacula/src/lib/protos.h                   |   1 +
 bacula/src/lib/smartall.c                 | 256 +++++++++++-----------
 bacula/src/stored/append.c                |   2 +-
 bacula/src/stored/autochanger.c           |  30 +--
 bacula/src/stored/btape.c                 |  27 ++-
 bacula/src/stored/dev.h                   |   2 +-
 bacula/src/stored/protos.h                |   3 +-
 bacula/src/stored/reserve.c               | 165 +++++++++++---
 bacula/src/stored/status.c                |  23 ++
 bacula/src/version.h                      |   4 +-
 24 files changed, 444 insertions(+), 242 deletions(-)

diff --git a/bacula/examples/autochangers/chio-changer b/bacula/examples/autochangers/chio-changer
index 60b2d5395e..5437cba65f 100644
--- a/bacula/examples/autochangers/chio-changer
+++ b/bacula/examples/autochangers/chio-changer
@@ -120,6 +120,6 @@ case "$COMMAND" in
       ;;
 
    slots)
-      ${MTX} -f $CHANGER status slot  | wc -l | bc
+      ${MTX} -f $CHANGER status slot  | wc -l
       ;;
 esac
diff --git a/bacula/kernstodo b/bacula/kernstodo
index ce5d91d32a..a857ee2233 100644
--- a/bacula/kernstodo
+++ b/bacula/kernstodo
@@ -1,5 +1,5 @@
                     Kern's ToDo List
-                     07 January 2006
+                     11 January 2006
 
 Major development:      
 Project                     Developer
@@ -15,8 +15,6 @@ Document:
 - %d and %v only valid on Director, not for ClientRunBefore/After.
 
 Priority:
-- Implement status that shows why a job is being held in reserve, or
-  rather why none of the drives are suitable.
 - Implement a way to disable a drive (so you can use the second
   drive of an autochanger, and the first one will not be used or
   even defined).
@@ -29,10 +27,6 @@ For 1.39:
 - Queue warning/error messages during restore so that they
   are reported at the end of the report rather than being
   hidden in the file listing ...
-- A Volume taken from Scratch should take on the retention period
-  of the new pool.
-- Correct doc for Maximum Changer Wait (and others) accepting only
-  integers.
 - Fix Maximum Changer Wait (and others) to accept qualifiers.
 - Look at -D_FORTIFY_SOURCE=2
 - Add Win32 FileSet definition somewhere
@@ -1276,4 +1270,9 @@ Block Position: 0
   for ( ; jcr; (jcr=jcr_walk_next(jcr)) )
   ...
   jcr_walk_end(jcr);
-
+- A Volume taken from Scratch should take on the retention period
+  of the new pool.
+- Correct doc for Maximum Changer Wait (and others) accepting only
+  integers.
+- Implement status that shows why a job is being held in reserve, or
+  rather why none of the drives are suitable.
diff --git a/bacula/kes-1.38 b/bacula/kes-1.38
index bec8fbcee7..3cb95e905a 100644
--- a/bacula/kes-1.38
+++ b/bacula/kes-1.38
@@ -3,7 +3,45 @@
 
 General:
 
-1.38.4:
+Release 1.38.4:
+15Jan06
+- Add periodic (every 24 hours) garbage collection of memory 
+  pool by releasing free buffers.
+14Jan06
+- Correct bug counting sized (for display only) in smartall.c
+- Print FD mempool stats if debug > 0 rather than 5.
+12Jan06
+- Make db_lock() mutex error fail the job rather than abort
+  Bacula.  Canceling the job caused the mutex to fail.
+- Correct bug in alist.c that re-allocated the list if the
+  number of items goes to zero.
+- Move the reservation system thread locking to the top level
+  so that one job at a time tries all possible drives before
+  waiting.
+- Implement a reservation 'fail' message queue that is built         
+  and destroyed on each pass through the reservation system.
+  These messages are displayed in a 'Jobs waiting to reserve
+  a drive' list during a 'status storage='.  Note, multiple
+  messages will generally print for each JobId because they
+  represent the different problems with either the same drive
+  or different drives.  If this output proves too confusing
+  of voluminous, I will display it only when debug level 1
+  or greater is enabled in the SD.
+11Jan06
+- Add enable/disable job=<job-name>.  This command prevents
+  the specified job from being scheduled. Even when disabled,
+  the job can be manually started from the console.
+- During 'update slots' clear all InChanger flags where the
+  StorageId is zero (old Media records).
+
+Beta release 1.38.4:
+09Jan06
+- Fix autochanger code to strip leading spaces from returned
+  slots number. Remove bc from chio-changer.
+- Back port a bit of 1.39 crypto code to reduce diffs.
+- Fix first call to autochanger that missed close()ing the
+  drive. Put close() just before each run_program().  Fixes
+  Arno's changer bug.
 07Jan06
 - Add PoolId to Job record when updating it at job start time.
 06Jan06
@@ -34,7 +72,7 @@ Beta release 23Dec05:
   volume so that it can handle multiple returns from the wait
   code.
 - Modify the wait code to permit multiple returns.
-- Return a zero when "autochanger drives" is called and
+- Return a zero when 'autochanger drives' is called and
   it is not an autochanger.
 - Make rewind_dev() a method taking a DCR as an argument.
   This permits closing and reopening the drive if the
@@ -149,9 +187,9 @@ Beta release 10Dec05:
 04Dec05
 - 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
-  "list nextvol days=xx"
+  'list nextvol days=xx'
   or
-  "status dir days=xx"
+  'status dir days=xx'
   My use case is to be able to preview the next scheduled job (and the 
   next tape to be used) on fridays if there are no scheduled jobs during 
   the weekend.
@@ -209,7 +247,7 @@ Changes to 1.38.1: 15 November 2005
 - Add Solaris ACL detection in configure.in as supplied by
   Attila Fulop. 
 12Nov05
-- Implement "autochanger drives" protocol so that Dir knows
+- Implement 'autochanger drives' protocol so that Dir knows
   how many drives an autochanger has.
 - Do not request drive number in label, ... if only one drive.
 - Turn off debug code.
diff --git a/bacula/src/baconfig.h b/bacula/src/baconfig.h
index e2233fe562..ca29db2897 100644
--- a/bacula/src/baconfig.h
+++ b/bacula/src/baconfig.h
@@ -5,7 +5,7 @@
  *   Version $Id$
  */
 /*
-   Copyright (C) 2000-2005 Kern Sibbald
+   Copyright (C) 2000-2006 Kern Sibbald
 
    This program is free software; you can redistribute it and/or
    modify it under the terms of the GNU General Public License
@@ -147,6 +147,7 @@
 #define STREAM_NONE               0    /* Reserved Non-Stream */
 #define STREAM_UNIX_ATTRIBUTES    1    /* Generic Unix attributes */
 #define STREAM_FILE_DATA          2    /* Standard uncompressed data */
+#define STREAM_MD5_SIGNATURE      3    /* deprecated */
 #define STREAM_MD5_DIGEST         3    /* MD5 digest for the file */
 #define STREAM_GZIP_DATA          4    /* GZip compressed file data */
 /* Extended Unix attributes with Win32 Extended data.  Deprecated. */
@@ -155,6 +156,7 @@
 #define STREAM_SPARSE_GZIP_DATA   7
 #define STREAM_PROGRAM_NAMES      8    /* program names for program data */
 #define STREAM_PROGRAM_DATA       9    /* Data needing program */
+#define STREAM_SHA1_SIGNATURE    10    /* deprecated */
 #define STREAM_SHA1_DIGEST       10    /* SHA1 digest for the file */
 #define STREAM_WIN32_DATA        11    /* Win32 BackupRead data */
 #define STREAM_WIN32_GZIP_DATA   12    /* Gzipped Win32 BackupRead data */
diff --git a/bacula/src/c b/bacula/src/c
index 471938c83b..782a6114cd 100644
--- a/bacula/src/c
+++ b/bacula/src/c
@@ -1,5 +1,5 @@
 /*
-   Copyright (C) 2000-2005 Kern Sibbald
+   Copyright (C) 2000-2006 Kern Sibbald
 
    This program is free software; you can redistribute it and/or
    modify it under the terms of the GNU General Public License
diff --git a/bacula/src/cats/sql.c b/bacula/src/cats/sql.c
index c962803767..7446ed9fd0 100644
--- a/bacula/src/cats/sql.c
+++ b/bacula/src/cats/sql.c
@@ -237,8 +237,8 @@ void _db_lock(const char *file, int line, B_DB *mdb)
    int errstat;
    if ((errstat=rwl_writelock(&mdb->lock)) != 0) {
       berrno be;
-      e_msg(file, line, M_ABORT, 0, "rwl_writelock failure. ERR=%s\n",
-           be.strerror(errstat));
+      e_msg(file, line, M_FATAL, 0, "rwl_writelock failure. stat=%d: ERR=%s\n",
+           errstat, be.strerror(errstat));
    }
 }
 
@@ -252,8 +252,8 @@ void _db_unlock(const char *file, int line, B_DB *mdb)
    int errstat;
    if ((errstat=rwl_writeunlock(&mdb->lock)) != 0) {
       berrno be;
-      e_msg(file, line, M_ABORT, 0, "rwl_writeunlock failure. ERR=%s\n",
-           be.strerror(errstat));
+      e_msg(file, line, M_FATAL, 0, "rwl_writeunlock failure. stat=%d: ERR=%s\n",
+           errstat, be.strerror(errstat));
    }
 }
 
diff --git a/bacula/src/dird/ua_output.c b/bacula/src/dird/ua_output.c
index d97bf8a7fb..913adb9f1b 100644
--- a/bacula/src/dird/ua_output.c
+++ b/bacula/src/dird/ua_output.c
@@ -518,7 +518,8 @@ RUN *find_next_run(RUN *run, JOB *job, time_t &runtime, int ndays)
    }
    for ( ; run; run=run->next) {
       /*
-       * Find runs in next 24 hours
+       * Find runs in next 24 hours.  Day 0 is today, so if
+       *   ndays=1, look at today and tomorrow.
        */
       for (day = 0; day <= ndays; day++) {
          future = now + (day * 60 * 60 * 24);
diff --git a/bacula/src/filed/filed.c b/bacula/src/filed/filed.c
index 7bb2a3a2f8..c97926d0c7 100644
--- a/bacula/src/filed/filed.c
+++ b/bacula/src/filed/filed.c
@@ -254,7 +254,7 @@ void terminate_filed(int sig)
    if (configfile != NULL) {
       free(configfile);
    }
-   if (debug_level > 5) {
+   if (debug_level > 0) {
       print_memory_pool_stats();
    }
    free_config_resources();
@@ -344,7 +344,7 @@ static int check_resources()
       if ((me->pki_encrypt || me->pki_sign) && !me->pki_keypairfile) {
          Emsg2(M_FATAL, 0, _("\"PKI Key Pair\" must be defined for File"
             " daemon \"%s\" in %s if either \"PKI Sign\" or"
-	    " \"PKI Encrypt\" are enabled.\n"), me->hdr.name, configfile);
+            " \"PKI Encrypt\" are enabled.\n"), me->hdr.name, configfile);
          OK = false;
       }
 
@@ -378,7 +378,7 @@ static int check_resources()
          me->pki_signers->append(crypto_keypair_dup(me->pki_keypair));
 
          /* If additional trusted keys have been specified, load them up */
-	 if (me->pki_trustedkeys) {
+         if (me->pki_trustedkeys) {
             foreach_alist(filepath, me->pki_trustedkeys) {
                X509_KEYPAIR *keypair;
 
@@ -396,7 +396,7 @@ static int check_resources()
                   }
                }
             }
-	 }
+         }
 
          if (me->pki_encrypt) {
             /*
diff --git a/bacula/src/jcr.h b/bacula/src/jcr.h
index 1eb61fc145..152bf65778 100644
--- a/bacula/src/jcr.h
+++ b/bacula/src/jcr.h
@@ -268,7 +268,8 @@ public:
    bool spool_data;                   /* set to spool data */
    int CurVol;                        /* Current Volume count */
    DIRRES* director;                  /* Director resource */
-   alist *dirstore;   
+   alist *dirstore;                   /* list of storage devices sent by DIR */ 
+   alist *reserve_msgs;               /* reserve fail messages */
    bool write_part_after_job;         /* Set to write part after job */
    bool PreferMountedVols;            /* Prefer mounted vols rather than new */
    
diff --git a/bacula/src/lib/alist.c b/bacula/src/lib/alist.c
index bf12f3439b..70a7895b23 100644
--- a/bacula/src/lib/alist.c
+++ b/bacula/src/lib/alist.c
@@ -11,7 +11,7 @@
  *
  */
 /*
-   Copyright (C) 2003-2005 Kern Sibbald
+   Copyright (C) 2003-2006 Kern Sibbald
 
    This program is free software; you can redistribute it and/or
    modify it under the terms of the GNU General Public License
@@ -33,7 +33,7 @@
  */
 void alist::grow_list()
 {
-   if (num_items == 0) {
+   if (items == NULL) {
       if (num_grow == 0) {
          num_grow = 1;                /* default if not initialized */
       }
diff --git a/bacula/src/lib/alist.h b/bacula/src/lib/alist.h
index c4727e8ab5..1682575703 100644
--- a/bacula/src/lib/alist.h
+++ b/bacula/src/lib/alist.h
@@ -4,7 +4,7 @@
  *  Kern Sibbald, June MMIII
  */
 /*
-   Copyright (C) 2003-2005 Kern Sibbald
+   Copyright (C) 2003-2006 Kern Sibbald
 
    This program is free software; you can redistribute it and/or
    modify it under the terms of the GNU General Public License
@@ -33,7 +33,7 @@
 
 #ifdef the_easy_way
 #define foreach_alist(var, list) \
-        for(((void*)(var))=(list)->first(); (var); ((void*)(var))=(list)->next(var)); )
+        for(((void*)(var))=(list)->first(); (var); ((void*)(var))=(list)->next()); )
 #endif
 
 
@@ -75,7 +75,7 @@ public:
 
    /* Use it as a stack, pushing and poping from the end */
    void push(void *item) { append(item); };
-   void pop() { num_items?NULL:remove(num_items-1); };
+   void *pop() { return remove(num_items-1); };
 };
 
 inline void * alist::operator [](int index) const {
diff --git a/bacula/src/lib/jcr.c b/bacula/src/lib/jcr.c
index cc1a24eaac..f52bed5c51 100755
--- a/bacula/src/lib/jcr.c
+++ b/bacula/src/lib/jcr.c
@@ -417,6 +417,7 @@ void free_jcr(JCR *jcr)
    }
    free_common_jcr(jcr);
    close_msg(NULL);                   /* flush any daemon messages */
+   garbage_collect_memory_pool();
    Dmsg0(3400, "Exit free_jcr\n");
 }
 
diff --git a/bacula/src/lib/mem_pool.c b/bacula/src/lib/mem_pool.c
index d4d03795bf..b43c60c621 100644
--- a/bacula/src/lib/mem_pool.c
+++ b/bacula/src/lib/mem_pool.c
@@ -21,22 +21,17 @@
  */
 
 /*
-   Copyright (C) 2000-2004 Kern Sibbald
+   Copyright (C) 2000-2006 Kern Sibbald
 
    This program is free software; you can redistribute it and/or
-   modify it under the terms of the GNU General Public License as
-   published by the Free Software Foundation; either version 2 of
-   the License, or (at your option) any later version.
+   modify it under the terms of the GNU General Public License
+   version 2 as amended with additional clauses defined in the
+   file LICENSE in the main source directory.
 
    This program is distributed in the hope that it will be useful,
    but WITHOUT ANY WARRANTY; without even the implied warranty of
-   MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the GNU
-   General Public License for more details.
-
-   You should have received a copy of the GNU General Public
-   License along with this program; if not, write to the Free
-   Software Foundation, Inc., 59 Temple Place - Suite 330, Boston,
-   MA 02111-1307, USA.
+   MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the 
+   the file LICENSE for additional details.
 
  */
 
@@ -354,6 +349,33 @@ void free_pool_memory(POOLMEM *obuf)
 #endif /* SMARTALLOC */
 
 
+/*
+ * Clean up memory pool periodically
+ *
+ */
+static time_t last_garbage_collection = 0;
+const int garbage_interval = 24 * 60 * 60;  /* garbage collect every 24 hours */
+
+void garbage_collect_memory_pool()
+{
+   time_t now;
+
+   Dmsg0(200, "garbage collect memory pool\n");
+   P(mutex);
+   if (last_garbage_collection == 0) {
+      last_garbage_collection = time(NULL);
+      V(mutex);
+      return;
+   }
+   now = time(NULL);
+   if (now >= last_garbage_collection + garbage_interval) {
+      last_garbage_collection = now;
+      V(mutex);
+      close_memory_pool();
+   } else {
+      V(mutex);
+   }
+}
 
 
 
@@ -362,6 +384,9 @@ void free_pool_memory(POOLMEM *obuf)
 void close_memory_pool()
 {
    struct abufhead *buf, *next;
+   int count = 0;
+   uint64_t bytes = 0;
+   char ed1[50];
 
    sm_check(__FILE__, __LINE__, false);
    P(mutex);
@@ -369,12 +394,16 @@ void close_memory_pool()
       buf = pool_ctl[i].free_buf;
       while (buf) {
          next = buf->next;
+         count++;
+         bytes += sizeof_pool_memory((char *)buf);
          free((char *)buf);
          buf = next;
       }
       pool_ctl[i].free_buf = NULL;
    }
+   Dmsg2(100, "Freed mem_pool count=%d size=%s\n", count, edit_uint64_with_commas(bytes, ed1));
    V(mutex);
+
 }
 
 #ifdef DEBUG
diff --git a/bacula/src/lib/mem_pool.h b/bacula/src/lib/mem_pool.h
index ee4dfbbbe6..1a36331b6f 100644
--- a/bacula/src/lib/mem_pool.h
+++ b/bacula/src/lib/mem_pool.h
@@ -6,22 +6,17 @@
  *   Version $Id$
  */
 /*
-   Copyright (C) 2000-2004 Kern Sibbald and John Walker
+   Copyright (C) 2000-2006 Kern Sibbald
 
    This program is free software; you can redistribute it and/or
-   modify it under the terms of the GNU General Public License as
-   published by the Free Software Foundation; either version 2 of
-   the License, or (at your option) any later version.
+   modify it under the terms of the GNU General Public License
+   version 2 as amended with additional clauses defined in the
+   file LICENSE in the main source directory.
 
    This program is distributed in the hope that it will be useful,
    but WITHOUT ANY WARRANTY; without even the implied warranty of
-   MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the GNU
-   General Public License for more details.
-
-   You should have received a copy of the GNU General Public
-   License along with this program; if not, write to the Free
-   Software Foundation, Inc., 59 Temple Place - Suite 330, Boston,
-   MA 02111-1307, USA.
+   MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the 
+   the file LICENSE for additional details.
 
  */
 
@@ -63,6 +58,7 @@ extern void   free_pool_memory(POOLMEM *buf);
 
 #endif
 
+extern void garbage_collect_memory_pool();
 extern void  close_memory_pool();
 extern void  print_memory_pool_stats();
 
diff --git a/bacula/src/lib/protos.h b/bacula/src/lib/protos.h
index 138b8f181a..7fdc4c574f 100644
--- a/bacula/src/lib/protos.h
+++ b/bacula/src/lib/protos.h
@@ -147,6 +147,7 @@ void     daemon_start            ();
 /* edit.c */
 uint64_t         str_to_uint64(char *str);
 int64_t          str_to_int64(char *str);
+#define str_to_int32(str) ((int32_t)str_to_int64(str))
 char *           edit_uint64_with_commas   (uint64_t val, char *buf);
 char *           add_commas              (char *val, char *buf);
 char *           edit_uint64             (uint64_t val, char *buf);
diff --git a/bacula/src/lib/smartall.c b/bacula/src/lib/smartall.c
index 138522d20b..7fe164f96c 100644
--- a/bacula/src/lib/smartall.c
+++ b/bacula/src/lib/smartall.c
@@ -1,25 +1,25 @@
 /*
 
-			 S M A R T A L L O C
-			Smart Memory Allocator
+                         S M A R T A L L O C
+                        Smart Memory Allocator
 
-	Evolved   over	 several  years,  starting  with  the  initial
-	SMARTALLOC code for AutoSketch in 1986, guided	by  the  Blind
-	Watchbreaker,  John  Walker.  Isolated in this general-purpose
-	form in  September  of	1989.	Updated  with  be  more  POSIX
-	compliant  and	to  include Web-friendly HTML documentation in
-	October  of  1998  by  the  same  culprit.    For   additional
-	information and the current version visit the Web page:
+        Evolved   over   several  years,  starting  with  the  initial
+        SMARTALLOC code for AutoSketch in 1986, guided  by  the  Blind
+        Watchbreaker,  John  Walker.  Isolated in this general-purpose
+        form in  September  of  1989.   Updated  with  be  more  POSIX
+        compliant  and  to  include Web-friendly HTML documentation in
+        October  of  1998  by  the  same  culprit.    For   additional
+        information and the current version visit the Web page:
 
-		  http://www.fourmilab.ch/smartall/
+                  http://www.fourmilab.ch/smartall/
 
 
-	 Version $Id$
+         Version $Id$
 
 */
 
 /*
-   Copyright (C) 2000-2005 Kern Sibbald
+   Copyright (C) 2000-2006 Kern Sibbald
 
    This program is free software; you can redistribute it and/or
    modify it under the terms of the GNU General Public License
@@ -63,7 +63,7 @@ uint32_t sm_buffers = 0;
 
 static pthread_mutex_t mutex = PTHREAD_MUTEX_INITIALIZER;
 
-extern char my_name[];		      /* daemon name */
+extern char my_name[];                /* daemon name */
 
 typedef unsigned short sm_ushort;
 
@@ -75,10 +75,10 @@ typedef unsigned short sm_ushort;
 /*  Memory allocation control structures and storage.  */
 
 struct abufhead {
-   struct b_queue abq;	       /* Links on allocated queue */
-   unsigned ablen;	       /* Buffer length in bytes */
+   struct b_queue abq;         /* Links on allocated queue */
+   unsigned ablen;             /* Buffer length in bytes */
    const char *abfname;        /* File name pointer */
-   sm_ushort ablineno;	       /* Line number of allocation */
+   sm_ushort ablineno;         /* Line number of allocation */
 };
 
 static struct b_queue abqueue = {    /* Allocated buffer queue */
@@ -86,13 +86,13 @@ static struct b_queue abqueue = {    /* Allocated buffer queue */
 };
 
 
-static bool bufimode = false;	/* Buffers not tracked when True */
+static bool bufimode = false;   /* Buffers not tracked when True */
 
 #define HEAD_SIZE BALIGN(sizeof(struct abufhead))
 
 
 /*  SMALLOC  --  Allocate buffer, enqueing on the orphaned buffer
-		 tracking list.  */
+                 tracking list.  */
 
 static void *smalloc(const char *fname, int lineno, unsigned int nbytes)
 {
@@ -121,11 +121,11 @@ static void *smalloc(const char *fname, int lineno, unsigned int nbytes)
       buf[nbytes - 1] = (uint8_t)((((long) buf) & 0xFF) ^ 0xC5);
       buf += HEAD_SIZE;  /* Increment to user data start */
       if (++sm_buffers > sm_max_buffers) {
-	 sm_max_buffers = sm_buffers;
+         sm_max_buffers = sm_buffers;
       }
       sm_bytes += nbytes;
       if (sm_bytes > sm_max_bytes) {
-	 sm_max_bytes = sm_bytes;
+         sm_max_bytes = sm_bytes;
       }
       V(mutex);
    } else {
@@ -136,7 +136,7 @@ static void *smalloc(const char *fname, int lineno, unsigned int nbytes)
 }
 
 /*  SM_NEW_OWNER -- Update the File and line number for a buffer
-		    This is to accomodate mem_pool. */
+                    This is to accomodate mem_pool. */
 
 void sm_new_owner(const char *fname, int lineno, char *buf)
 {
@@ -147,9 +147,9 @@ void sm_new_owner(const char *fname, int lineno, char *buf)
 }
 
 /*  SM_FREE  --  Update free pool availability.  FREE is never called
-		 except  through  this interface or by actuallyfree().
-		 free(x)  is  defined  to  generate  a	call  to  this
-		 routine.  */
+                 except  through  this interface or by actuallyfree().
+                 free(x)  is  defined  to  generate  a  call  to  this
+                 routine.  */
 
 void sm_free(const char *file, int line, void *fp)
 {
@@ -166,8 +166,8 @@ void sm_free(const char *file, int line, void *fp)
 
    P(mutex);
    Dmsg4(1150, "sm_free %d at %x from %s:%d\n",
-	 head->ablen, fp,
-	 head->abfname, head->ablineno);
+         head->ablen, fp,
+         head->abfname, head->ablineno);
 
    /* The following assertions will catch virtually every release
       of an address which isn't an allocated buffer. */
@@ -180,9 +180,9 @@ void sm_free(const char *file, int line, void *fp)
       Emsg2(M_ABORT, 0, _("qp->qprev->qnext != qp called from %s:%d\n"), file, line);
    }
 
-   /* The following assertion detects storing off the  end  of	the
+   /* The following assertion detects storing off the  end  of  the
       allocated  space in the buffer by comparing the end of buffer
-      checksum with the address of the buffer.	*/
+      checksum with the address of the buffer.  */
 
    if (((unsigned char *)cp)[head->ablen - 1] != ((((long) cp) & 0xFF) ^ 0xC5)) {
       V(mutex);
@@ -194,7 +194,7 @@ void sm_free(const char *file, int line, void *fp)
    qdchain(qp);
    V(mutex);
 
-   /* Now we wipe the contents of  the	just-released  buffer  with
+   /* Now we wipe the contents of  the  just-released  buffer  with
       "designer  garbage"  (Duff  Kurland's  phrase) of alternating
       bits.  This is intended to ruin the day for any miscreant who
       attempts to access data through a pointer into storage that's
@@ -206,7 +206,7 @@ void sm_free(const char *file, int line, void *fp)
 }
 
 /*  SM_MALLOC  --  Allocate buffer.  NULL is returned if no memory
-		   was available.  */
+                   was available.  */
 
 void *sm_malloc(const char *fname, int lineno, unsigned int nbytes)
 {
@@ -215,7 +215,7 @@ void *sm_malloc(const char *fname, int lineno, unsigned int nbytes)
    if ((buf = smalloc(fname, lineno, nbytes)) != NULL) {
 
       /* To catch sloppy code that assumes  buffers  obtained  from
-	 malloc()  are	zeroed,  we  preset  the buffer contents to
+         malloc()  are  zeroed,  we  preset  the buffer contents to
          "designer garbage" consisting of alternating bits.  */
 
       memset(buf, 0x55, (int) nbytes);
@@ -228,7 +228,7 @@ void *sm_malloc(const char *fname, int lineno, unsigned int nbytes)
 /*  SM_CALLOC  --  Allocate an array and clear it to zero.  */
 
 void *sm_calloc(const char *fname, int lineno,
-		unsigned int nelem, unsigned int elsize)
+                unsigned int nelem, unsigned int elsize)
 {
    void *buf;
 
@@ -240,14 +240,14 @@ void *sm_calloc(const char *fname, int lineno,
    return buf;
 }
 
-/*  SM_REALLOC	--  Adjust the size of a  previously  allocated  buffer.
+/*  SM_REALLOC  --  Adjust the size of a  previously  allocated  buffer.
                     Note  that  the trick of "resurrecting" a previously
-		    freed buffer with realloc() is NOT supported by this
-		    function.	Further, because of the need to maintain
-		    our control storage, SM_REALLOC must always allocate
-		    a  new  block  and	copy  the data in the old block.
-		    This may result in programs which make heavy use  of
-		    realloc() running much slower than normally.  */
+                    freed buffer with realloc() is NOT supported by this
+                    function.   Further, because of the need to maintain
+                    our control storage, SM_REALLOC must always allocate
+                    a  new  block  and  copy  the data in the old block.
+                    This may result in programs which make heavy use  of
+                    realloc() running much slower than normally.  */
 
 void *sm_realloc(const char *fname, int lineno, void *ptr, unsigned int size)
 {
@@ -260,7 +260,7 @@ void *sm_realloc(const char *fname, int lineno, void *ptr, unsigned int size)
       e_msg(fname, lineno, M_ABORT, 0, _("sm_realloc size: %d\n"), size);
    }
 
-   /*  If  the	old  block  pointer  is  NULL, treat realloc() as a
+   /*  If  the  old  block  pointer  is  NULL, treat realloc() as a
       malloc().  SVID is silent  on  this,  but  many  C  libraries
       permit this.  */
 
@@ -280,18 +280,18 @@ void *sm_realloc(const char *fname, int lineno, void *ptr, unsigned int size)
 
    /* Sizes differ.  Allocate a new buffer of the  requested  size.
       If  we  can't  obtain  such a buffer, act as defined in SVID:
-      return NULL from	realloc()  and	leave  the  buffer  in	PTR
+      return NULL from  realloc()  and  leave  the  buffer  in  PTR
       intact.  */
 
    sm_buffers--;
-   sm_bytes -= osize;
+   sm_bytes -= head->ablen;
 
    if ((buf = smalloc(fname, lineno, size)) != NULL) {
       memcpy(buf, ptr, (int) sm_min(size, osize));
       /* If the new buffer is larger than the old, fill the balance
          of it with "designer garbage". */
       if (size > osize) {
-	 memset(((char *) buf) + osize, 0x55, (int) (size - osize));
+         memset(((char *) buf) + osize, 0x55, (int) (size - osize));
       }
 
       /* All done.  Free and dechain the original buffer. */
@@ -302,20 +302,20 @@ void *sm_realloc(const char *fname, int lineno, void *ptr, unsigned int size)
    return buf;
 }
 
-/*  ACTUALLYMALLOC  --	Call the system malloc() function to obtain
-			storage which will eventually be released
-			by system or library routines not compiled
-			using SMARTALLOC.  */
+/*  ACTUALLYMALLOC  --  Call the system malloc() function to obtain
+                        storage which will eventually be released
+                        by system or library routines not compiled
+                        using SMARTALLOC.  */
 
 void *actuallymalloc(unsigned int size)
 {
    return malloc(size);
 }
 
-/*  ACTUALLYCALLOC  --	Call the system calloc() function to obtain
-			storage which will eventually be released
-			by system or library routines not compiled
-			using SMARTALLOC.  */
+/*  ACTUALLYCALLOC  --  Call the system calloc() function to obtain
+                        storage which will eventually be released
+                        by system or library routines not compiled
+                        using SMARTALLOC.  */
 
 void *actuallycalloc(unsigned int nelem, unsigned int elsize)
 {
@@ -323,9 +323,9 @@ void *actuallycalloc(unsigned int nelem, unsigned int elsize)
 }
 
 /*  ACTUALLYREALLOC  --  Call the system realloc() function to obtain
-			 storage which will eventually be released
-			 by system or library routines not compiled
-			 using SMARTALLOC.  */
+                         storage which will eventually be released
+                         by system or library routines not compiled
+                         using SMARTALLOC.  */
 
 void *actuallyrealloc(void *ptr, unsigned int size)
 {
@@ -334,7 +334,7 @@ void *actuallyrealloc(void *ptr, unsigned int size)
 }
 
 /*  ACTUALLYFREE  --  Interface to system free() function to release
-		      buffers allocated by low-level routines. */
+                      buffers allocated by low-level routines. */
 
 void actuallyfree(void *cp)
 {
@@ -342,7 +342,7 @@ void actuallyfree(void *cp)
 }
 
 /*  SM_DUMP  --  Print orphaned buffers (and dump them if BUFDUMP is
- *		 True).
+ *               True).
  *  N.B. DO NOT USE any Bacula print routines (Dmsg, Jmsg, Emsg, ...)
  *    as they have all been shut down at this point.
  */
@@ -357,45 +357,45 @@ void sm_dump(bool bufdump)
    while (ap != (struct abufhead *) &abqueue) {
 
       if ((ap == NULL) ||
-	  (ap->abq.qnext->qprev != (struct b_queue *) ap) ||
-	  (ap->abq.qprev->qnext != (struct b_queue *) ap)) {
-	 fprintf(stderr, _(
+          (ap->abq.qnext->qprev != (struct b_queue *) ap) ||
+          (ap->abq.qprev->qnext != (struct b_queue *) ap)) {
+         fprintf(stderr, _(
             "\nOrphaned buffers exist.  Dump terminated following\n"
             "  discovery of bad links in chain of orphaned buffers.\n"
             "  Buffer address with bad links: %lx\n"), (long) ap);
-	 break;
+         break;
       }
 
       if (ap->abfname != NULL) {
-	 unsigned memsize = ap->ablen - (HEAD_SIZE + 1);
-	 char errmsg[500];
+         unsigned memsize = ap->ablen - (HEAD_SIZE + 1);
+         char errmsg[500];
 
-	 bsnprintf(errmsg, sizeof(errmsg),
+         bsnprintf(errmsg, sizeof(errmsg),
            _("Orphaned buffer:  %6u bytes allocated at line %d of %s %s\n"),
-	    memsize, ap->ablineno, my_name, ap->abfname
-	 );
+            memsize, ap->ablineno, my_name, ap->abfname
+         );
          fprintf(stderr, "%s", errmsg);
-	 if (bufdump) {
-	    char buf[20];
-	    unsigned llen = 0;
-	    char *cp = ((char *) ap) + HEAD_SIZE;
-
-	    errmsg[0] = EOS;
-	    while (memsize) {
-	       if (llen >= 16) {
+         if (bufdump) {
+            char buf[20];
+            unsigned llen = 0;
+            char *cp = ((char *) ap) + HEAD_SIZE;
+
+            errmsg[0] = EOS;
+            while (memsize) {
+               if (llen >= 16) {
                   bstrncat(errmsg, "\n", sizeof(errmsg));
-		  llen = 0;
+                  llen = 0;
                   fprintf(stderr, "%s", errmsg);
-		  errmsg[0] = EOS;
-	       }
+                  errmsg[0] = EOS;
+               }
                bsnprintf(buf, sizeof(buf), " %02X",
-		  (*cp++) & 0xFF);
-	       bstrncat(errmsg, buf, sizeof(errmsg));
-	       llen++;
-	       memsize--;
-	    }
+                  (*cp++) & 0xFF);
+               bstrncat(errmsg, buf, sizeof(errmsg));
+               llen++;
+               memsize--;
+            }
             fprintf(stderr, "%s\n", errmsg);
-	 }
+         }
       }
       ap = (struct abufhead *) ap->abq.qnext;
    }
@@ -406,10 +406,10 @@ void sm_dump(bool bufdump)
 /*  SM_CHECK --  Check the buffers and dump if any damage exists. */
 void sm_check(const char *fname, int lineno, bool bufdump)
 {
-	if (!sm_check_rtn(fname, lineno, bufdump)) {
+        if (!sm_check_rtn(fname, lineno, bufdump)) {
            Emsg2(M_ABORT, 0, _("Damaged buffer found. Called from %s:%d\n"),
-	      fname, lineno);
-	}
+              fname, lineno);
+        }
 }
 
 #undef sm_check_rtn
@@ -424,66 +424,66 @@ int sm_check_rtn(const char *fname, int lineno, bool bufdump)
    while (ap != (struct abufhead *) &abqueue) {
       bad = 0;
       if ((ap == NULL) ||
-	  (ap->abq.qnext->qprev != (struct b_queue *) ap)) {
-	 bad = 0x1;
+          (ap->abq.qnext->qprev != (struct b_queue *) ap)) {
+         bad = 0x1;
       }
       if (ap->abq.qprev->qnext != (struct b_queue *) ap) {
-	 bad |= 0x2;
+         bad |= 0x2;
       }
       if (((unsigned char *) ap)[((struct abufhead *) ap)->ablen - 1] !=
-	   ((((long) ap) & 0xFF) ^ 0xC5)) {
-	 bad |= 0x4;
+           ((((long) ap) & 0xFF) ^ 0xC5)) {
+         bad |= 0x4;
       }
       badbuf |= bad;
       if (bad) {
-	 fprintf(stderr,
+         fprintf(stderr,
             _("\nDamaged buffers found at %s:%d\n"), fname, lineno);
 
-	 if (bad & 0x1) {
+         if (bad & 0x1) {
             fprintf(stderr, _("  discovery of bad prev link.\n"));
-	 }
-	 if (bad & 0x2) {
+         }
+         if (bad & 0x2) {
             fprintf(stderr, _("  discovery of bad next link.\n"));
-	 }
-	 if (bad & 0x4) {
+         }
+         if (bad & 0x4) {
             fprintf(stderr, _("  discovery of data overrun.\n"));
-	 }
+         }
 
          fprintf(stderr, _("  Buffer address: %lx\n"), (long) ap);
 
-	 if (ap->abfname != NULL) {
-	    unsigned memsize = ap->ablen - (HEAD_SIZE + 1);
-	    char errmsg[80];
+         if (ap->abfname != NULL) {
+            unsigned memsize = ap->ablen - (HEAD_SIZE + 1);
+            char errmsg[80];
 
-	    fprintf(stderr,
+            fprintf(stderr,
               _("Damaged buffer:  %6u bytes allocated at line %d of %s %s\n"),
-	       memsize, ap->ablineno, my_name, ap->abfname
-	    );
-	    if (bufdump) {
-	       unsigned llen = 0;
-	       char *cp = ((char *) ap) + HEAD_SIZE;
-
-	       errmsg[0] = EOS;
-	       while (memsize) {
-		  if (llen >= 16) {
+               memsize, ap->ablineno, my_name, ap->abfname
+            );
+            if (bufdump) {
+               unsigned llen = 0;
+               char *cp = ((char *) ap) + HEAD_SIZE;
+
+               errmsg[0] = EOS;
+               while (memsize) {
+                  if (llen >= 16) {
                      strcat(errmsg, "\n");
-		     llen = 0;
+                     llen = 0;
                      fprintf(stderr, "%s", errmsg);
-		     errmsg[0] = EOS;
-		  }
-		  if (*cp < 0x20) {
+                     errmsg[0] = EOS;
+                  }
+                  if (*cp < 0x20) {
                      sprintf(errmsg + strlen(errmsg), " %02X",
-			(*cp++) & 0xFF);
-		  } else {
+                        (*cp++) & 0xFF);
+                  } else {
                      sprintf(errmsg + strlen(errmsg), " %c ",
-			(*cp++) & 0xFF);
-		  }
-		  llen++;
-		  memsize--;
-	       }
+                        (*cp++) & 0xFF);
+                  }
+                  llen++;
+                  memsize--;
+               }
                fprintf(stderr, "%s\n", errmsg);
-	    }
-	 }
+            }
+         }
       }
       ap = (struct abufhead *) ap->abq.qnext;
    }
@@ -493,11 +493,11 @@ int sm_check_rtn(const char *fname, int lineno, bool bufdump)
 
 
 /*  SM_STATIC  --  Orphaned buffer detection can be disabled  (for  such
-		   items  as buffers allocated during initialisation) by
-		   calling   sm_static(1).    Normal   orphaned   buffer
-		   detection  can be re-enabled with sm_static(0).  Note
-		   that all the other safeguards still apply to  buffers
-		   allocated  when  sm_static(1)  mode is in effect.  */
+                   items  as buffers allocated during initialisation) by
+                   calling   sm_static(1).    Normal   orphaned   buffer
+                   detection  can be re-enabled with sm_static(0).  Note
+                   that all the other safeguards still apply to  buffers
+                   allocated  when  sm_static(1)  mode is in effect.  */
 
 void sm_static(int mode)
 {
diff --git a/bacula/src/stored/append.c b/bacula/src/stored/append.c
index fb9bc58f79..1e5153e019 100644
--- a/bacula/src/stored/append.c
+++ b/bacula/src/stored/append.c
@@ -5,7 +5,7 @@
  *  Version $Id$
  */
 /*
-   Copyright (C) 2000-2005 Kern Sibbald
+   Copyright (C) 2000-2006 Kern Sibbald
 
    This program is free software; you can redistribute it and/or
    modify it under the terms of the GNU General Public License
diff --git a/bacula/src/stored/autochanger.c b/bacula/src/stored/autochanger.c
index 35127d4a3a..bd08996814 100644
--- a/bacula/src/stored/autochanger.c
+++ b/bacula/src/stored/autochanger.c
@@ -7,7 +7,7 @@
  *   Version $Id$
  */
 /*
-   Copyright (C) 2002-2005 Kern Sibbald
+   Copyright (C) 2002-2006 Kern Sibbald
 
    This program is free software; you can redistribute it and/or
    modify it under the terms of the GNU General Public License
@@ -151,6 +151,8 @@ int autoload_device(DCR *dcr, int writing, BSOCK *dir)
          dcr->VolCatInfo.Slot = slot;    /* slot to be loaded */
          changer = edit_device_codes(dcr, changer, 
                       dcr->device->changer_command, "load");
+         offline_or_rewind_dev(dev);
+         force_close_device(dev);
          status = run_program(changer, timeout, NULL);
          if (status == 0) {
             Jmsg(jcr, M_INFO, 0, _("3305 Autochanger \"load slot %d, drive %d\", status is OK.\n"),
@@ -217,7 +219,7 @@ int get_autochanger_loaded_slot(DCR *dcr)
    status = run_program(changer, timeout, results);
    Dmsg3(50, "run_prog: %s stat=%d result=%s\n", changer, status, results);
    if (status == 0) {
-      loaded = atoi(results);
+      loaded = str_to_int32(results);
       if (loaded > 0) {
          Jmsg(jcr, M_INFO, 0, _("3302 Autochanger \"loaded drive %d\", result is Slot %d.\n"),
               drive, loaded);
@@ -285,10 +287,6 @@ bool unload_autochanger(DCR *dcr, int loaded)
       loaded = get_autochanger_loaded_slot(dcr);
    }
 
-   /* We are going to load a new tape, so close the device */
-   offline_or_rewind_dev(dev);
-   force_close_device(dev);
-
    if (loaded > 0) {
       POOLMEM *changer = get_pool_memory(PM_FNAME);
       lock_changer(dcr);
@@ -299,6 +297,8 @@ bool unload_autochanger(DCR *dcr, int loaded)
       dcr->VolCatInfo.Slot = loaded;
       changer = edit_device_codes(dcr, changer, 
                    dcr->device->changer_command, "unload");
+      offline_or_rewind_dev(dev);
+      force_close_device(dev);
       int stat = run_program(changer, timeout, NULL);
       dcr->VolCatInfo.Slot = slot;
       if (stat != 0) {
@@ -357,10 +357,6 @@ static bool unload_other_drive(DCR *dcr, int slot)
       return false;
    }
 
-   /* We are going to unload a tape, so close the device */
-   offline_or_rewind_dev(dev);
-   force_close_device(dev);
-
    POOLMEM *changer_cmd = get_pool_memory(PM_FNAME);
    lock_changer(dcr);
    Jmsg(jcr, M_INFO, 0,
@@ -377,6 +373,8 @@ static bool unload_other_drive(DCR *dcr, int slot)
    changer_cmd = edit_device_codes(dcr, changer_cmd, 
                 dcr->device->changer_command, "unload");
    Dmsg1(200, "Run program=%s\n", changer_cmd);
+   offline_or_rewind_dev(dev);
+   force_close_device(dev);
    int stat = run_program(changer_cmd, timeout, NULL);
    dcr->VolCatInfo.Slot = save_slot;
    dcr->dev = save_dev;
@@ -459,12 +457,16 @@ bool autochanger_cmd(DCR *dcr, BSOCK *dir, const char *cmd)
          bnet_send(dir);
       }
    } else if (strcmp(cmd, "slots") == 0 ) {
+      char buf[100], *p;
       /* For slots command, read a single line */
-      bstrncpy(dir->msg, "slots=", len);
-      fgets(dir->msg+6, len-6, bpipe->rfd);
-      dir->msglen = strlen(dir->msg);
+      buf[0] = 0;
+      fgets(buf, sizeof(buf)-1, bpipe->rfd);
+      buf[sizeof(buf)-1] = 0;
+      /* Strip any leading space in front of # of slots */
+      for (p=buf; B_ISSPACE(*p); p++)
+        { }
+      bnet_fsend(dir, "slots=%s", p);
       Dmsg1(100, "<stored: %s", dir->msg);
-      bnet_send(dir);
    } 
                  
    stat = close_bpipe(bpipe);
diff --git a/bacula/src/stored/btape.c b/bacula/src/stored/btape.c
index c4e7d50da2..e6ef6ec914 100644
--- a/bacula/src/stored/btape.c
+++ b/bacula/src/stored/btape.c
@@ -1777,6 +1777,7 @@ static void fillcmd()
    int fd;
    uint32_t i;
    uint32_t min_block_size;
+   struct tm tm;
 
    ok = true;
    stop = 0;
@@ -1882,10 +1883,12 @@ static void fillcmd()
     */
    jcr->dcr->VolFirstIndex = 0;
    time(&jcr->run_time);              /* start counting time for rates */
+   localtime_r(&jcr->run_time, &tm);
+   strftime(buf1, sizeof(buf1), "%T", &tm);
    if (simple) {
-      Pmsg0(-1, _("Begin writing Bacula records to tape ...\n"));
+      Pmsg1(-1, _("%s Begin writing Bacula records to tape ...\n"), buf1);
    } else {
-      Pmsg0(-1, _("Begin writing Bacula records to first tape ...\n"));
+      Pmsg1(-1, _("%s Begin writing Bacula records to first tape ...\n"), buf1);
    }
    for (file_index = 0; ok && !job_canceled(jcr); ) {
       rec.VolSessionId = jcr->VolSessionId;
@@ -1930,10 +1933,13 @@ static void fillcmd()
                block->BlockNumber, dev->block_num,
                edit_uint64_with_commas(dev->VolCatInfo.VolCatBytes, ec1), (float)kbs);
          }
-         /* Every 15000 blocks (approx 1GB) write an EOF.
+         /* Every 32000 blocks (approx 2GB) write an EOF.
           */
-         if ((block->BlockNumber % 15000) == 0) {
-            Pmsg0(-1, _("Flush block, write EOF\n"));
+         if ((block->BlockNumber % 32000) == 0) {
+            now = time(NULL);
+            localtime_r(&now, &tm);
+            strftime(buf1, sizeof(buf1), "%T", &tm);
+            Pmsg1(-1, _("%s Flush block, write EOF\n"), buf1);
             flush_block(block, 0);
             weof_dev(dev, 1);
          }
@@ -2007,13 +2013,16 @@ static void fillcmd()
                  be.strerror());
    }
 
+   now = time(NULL);
+   localtime_r(&now, &tm);
+   strftime(buf1, sizeof(buf1), "%T", &tm);
    if (simple) {
-      Pmsg2(-1, _("\n\nDone filling tape at %d:%d. Now beginning re-read of tape ...\n"),
-         jcr->dcr->dev->file, jcr->dcr->dev->block_num);
+      Pmsg3(-1, _("\n\n%s Done filling tape at %d:%d. Now beginning re-read of tape ...\n"),
+         buf1, jcr->dcr->dev->file, jcr->dcr->dev->block_num);
    }
    else {
-      Pmsg2(-1, _("\n\nDone filling tapes at %d:%d. Now beginning re-read of first tape ...\n"),
-         jcr->dcr->dev->file, jcr->dcr->dev->block_num);
+      Pmsg3(-1, _("\n\n%s Done filling tapes at %d:%d. Now beginning re-read of first tape ...\n"),
+         buf1, jcr->dcr->dev->file, jcr->dcr->dev->block_num);
    }
 
    jcr->dcr->block = block;
diff --git a/bacula/src/stored/dev.h b/bacula/src/stored/dev.h
index 0ccee75db5..5d953e6045 100644
--- a/bacula/src/stored/dev.h
+++ b/bacula/src/stored/dev.h
@@ -8,7 +8,7 @@
  *
  */
 /*
-   Copyright (C) 2000-2005 Kern Sibbald
+   Copyright (C) 2000-2006 Kern Sibbald
 
    This program is free software; you can redistribute it and/or
    modify it under the terms of the GNU General Public License
diff --git a/bacula/src/stored/protos.h b/bacula/src/stored/protos.h
index 2dc535451e..c5b458fd2a 100644
--- a/bacula/src/stored/protos.h
+++ b/bacula/src/stored/protos.h
@@ -4,7 +4,7 @@
  *   Version $Id$
  */
 /*
-   Copyright (C) 2000-2005 Kern Sibbald
+   Copyright (C) 2000-2006 Kern Sibbald
 
    This program is free software; you can redistribute it and/or
    modify it under the terms of the GNU General Public License
@@ -223,6 +223,7 @@ void    create_volume_list();
 void    free_volume_list();
 void    list_volumes(BSOCK *user);
 bool    is_volume_in_use(DCR *dcr);
+void    send_drive_reserve_messages(JCR *jcr, BSOCK *user);
 
 
 /* From spool.c */
diff --git a/bacula/src/stored/reserve.c b/bacula/src/stored/reserve.c
index be97a764e5..e0611f7505 100644
--- a/bacula/src/stored/reserve.c
+++ b/bacula/src/stored/reserve.c
@@ -76,6 +76,7 @@ static bool reserve_device_for_read(DCR *dcr);
 static bool reserve_device_for_append(DCR *dcr, RCTX &rctx);
 static bool use_storage_cmd(JCR *jcr);
 bool find_suitable_device_for_job(JCR *jcr, RCTX &rctx);
+static void queue_reserve_message(JCR *jcr);
 
 /* Requests from the Director daemon */
 static char use_storage[]  = "use storage=%127s media_type=%127s "
@@ -307,6 +308,8 @@ static bool use_storage_cmd(JCR *jcr)
    int Copy, Stripe;
    DIRSTORE *store;
    RCTX rctx;
+   char *msg;
+   alist *msgs;
 
    memset(&rctx, 0, sizeof(RCTX));
    rctx.jcr = jcr;
@@ -315,6 +318,7 @@ static bool use_storage_cmd(JCR *jcr)
     *   use_device for each device that it wants to use.
     */
    jcr->dirstore = New(alist(10, not_owned_by_alist));
+   msgs = jcr->reserve_msgs = New(alist(10, not_owned_by_alist));  
    do {
       Dmsg1(100, "<dird: %s", dir->msg);
       ok = sscanf(dir->msg, use_storage, store_name.c_str(), 
@@ -363,6 +367,7 @@ static bool use_storage_cmd(JCR *jcr)
    }
 #endif
 
+   init_jcr_device_wait_timers(jcr);
    /*                    
     * At this point, we have a list of all the Director's Storage
     *  resources indicated for this Job, which include Pool, PoolType,
@@ -375,6 +380,10 @@ static bool use_storage_cmd(JCR *jcr)
    if (ok) {
       bool first = true;           /* print wait message once */
       for ( ; !job_canceled(jcr); ) {
+         P(search_lock);           /* only one thread at a time */
+         while ((msg = (char *)msgs->pop())) {
+            free(msg);
+         }
          rctx.suitable_device = false;
          rctx.have_volume = false;
          rctx.any_drive = false;
@@ -389,13 +398,13 @@ static bool use_storage_cmd(JCR *jcr)
                rctx.PreferMountedVols, rctx.exact_match, rctx.suitable_device,
                rctx.autochanger_only, rctx.any_drive);
             if ((ok = find_suitable_device_for_job(jcr, rctx))) {
-               goto done;
+               break;
             }
             /* Look through all drives possibly for low_use drive */
             if (rctx.low_use_drive) {
                rctx.try_low_use_drive = true;
                if ((ok = find_suitable_device_for_job(jcr, rctx))) {
-                  goto done;
+                  break;
                }
                rctx.try_low_use_drive = false;
             }
@@ -404,7 +413,7 @@ static bool use_storage_cmd(JCR *jcr)
                rctx.PreferMountedVols, rctx.exact_match, rctx.suitable_device,
                rctx.autochanger_only, rctx.any_drive);
             if ((ok = find_suitable_device_for_job(jcr, rctx))) {
-               goto done;
+               break;
             }
          }
          /* Look for an exact match all drives */
@@ -415,7 +424,7 @@ static bool use_storage_cmd(JCR *jcr)
             rctx.PreferMountedVols, rctx.exact_match, rctx.suitable_device,
             rctx.autochanger_only, rctx.any_drive);
          if ((ok = find_suitable_device_for_job(jcr, rctx))) {
-            goto done;
+            break;
          }
          /* Look for any mounted drive */
          rctx.exact_match = false;
@@ -423,7 +432,7 @@ static bool use_storage_cmd(JCR *jcr)
             rctx.PreferMountedVols, rctx.exact_match, rctx.suitable_device,
             rctx.autochanger_only, rctx.any_drive);
          if ((ok = find_suitable_device_for_job(jcr, rctx))) {
-            goto done;
+            break;
          }
          /* Try any drive */
          rctx.any_drive = true;
@@ -431,14 +440,21 @@ static bool use_storage_cmd(JCR *jcr)
             rctx.PreferMountedVols, rctx.exact_match, rctx.suitable_device,
             rctx.autochanger_only, rctx.any_drive);
          if ((ok = find_suitable_device_for_job(jcr, rctx))) {
-            goto done;
+            break;
          }
+         /* Unlock before possible wait */
+         V(search_lock);
          if (!rctx.suitable_device || !wait_for_device(jcr, first)) {
             break;       /* Get out, failure ... */
          }   
          first = false;
          bnet_sig(dir, BNET_HEARTBEAT);  /* Inform Dir that we are alive */
       }
+      /* Note if !ok then search_lock is already cleared */
+      if (ok) {
+         V(search_lock);
+         goto all_done;
+      } 
 
       /*
        * If we get here, there are no suitable devices available, which
@@ -466,17 +482,19 @@ static bool use_storage_cmd(JCR *jcr)
       Dmsg1(100, ">dird: %s", dir->msg);
    }
 
-done:
+all_done:
    foreach_alist(store, jcr->dirstore) {
       delete store->device;
       delete store;
    }
    delete jcr->dirstore;
-#ifdef implemented
-   while (error=(char*)rctx->errors.first()) {
-      free(error);
+   P(search_lock);
+   while ((msg = (char *)msgs->pop())) {
+      free(msg);
    }
-#endif
+   delete msgs;
+   jcr->reserve_msgs = NULL;
+   V(search_lock);
    return ok;
 }
 
@@ -497,9 +515,7 @@ bool find_suitable_device_for_job(JCR *jcr, RCTX &rctx)
    Dmsg4(100, "PrefMnt=%d exact=%d suitable=%d chgronly=%d\n",
       rctx.PreferMountedVols, rctx.exact_match, rctx.suitable_device,
       rctx.autochanger_only);
-   init_jcr_device_wait_timers(jcr);
    ok = false;
-   P(search_lock);
    foreach_alist(store, jcr->dirstore) {
       rctx.store = store;
       foreach_alist(device_name, store->device) {
@@ -521,7 +537,6 @@ bool find_suitable_device_for_job(JCR *jcr, RCTX &rctx)
          break;
       }
    }
-   V(search_lock);
 
    return ok;
 }
@@ -624,7 +639,7 @@ static int reserve_device(RCTX &rctx)
    }  
 
    rctx.suitable_device = true;
-   Dmsg2(100, "Try reserve %s jobid=%d\n", rctx.device->hdr.name,
+   Dmsg2(100, "Try reserve %s JobId=%u\n", rctx.device->hdr.name,
          rctx.jcr->JobId);
    dcr = new_dcr(rctx.jcr, rctx.device->dev);
    if (!dcr) {
@@ -641,8 +656,8 @@ 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(100, "Looking for Volume=%s\n", dcr->VolumeName);
             bstrncpy(rctx.VolumeName, dcr->VolumeName, sizeof(rctx.VolumeName));
+            Dmsg2(100, "JobId=%u looking for Volume=%s\n", rctx.jcr->JobId, rctx.VolumeName);
             rctx.have_volume = true;
          } else {
             Dmsg0(100, "No next volume found\n");
@@ -691,16 +706,18 @@ static bool reserve_device_for_read(DCR *dcr)
 
    if (is_device_unmounted(dev)) {             
       Dmsg1(200, "Device %s is BLOCKED due to user unmount.\n", dev->print_name());
-      Mmsg(jcr->errmsg, _("Device %s is BLOCKED due to user unmount.\n"),
-           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);
       goto bail_out;
    }
 
    if (dev->is_busy()) {
       Dmsg4(200, "Device %s is busy ST_READ=%d num_writers=%d reserved=%d.\n", dev->print_name(),
          dev->state & ST_READ?1:0, dev->num_writers, dev->reserved_device);
-      Mmsg1(jcr->errmsg, _("Device %s is busy.\n"),
-            dev->print_name());
+      Mmsg(jcr->errmsg, _("3602 JobId=%u device %s is busy (already reading/writing).\n"),
+            jcr->JobId, dev->print_name());
+      queue_reserve_message(jcr);
       goto bail_out;
    }
 
@@ -741,15 +758,19 @@ static bool reserve_device_for_append(DCR *dcr, RCTX &rctx)
 
    /* If device is being read, we cannot write it */
    if (dev->can_read()) {
-      Mmsg1(jcr->errmsg, _("Device %s is busy reading.\n"), dev->print_name());
+      Mmsg(jcr->errmsg, _("3603 JobId=%u device %s is busy reading.\n"), 
+         jcr->JobId, dev->print_name());
       Dmsg1(100, "%s", jcr->errmsg);
+      queue_reserve_message(jcr);
       goto bail_out;
    }
 
    /* If device is unmounted, we are out of luck */
    if (is_device_unmounted(dev)) {
-      Mmsg(jcr->errmsg, _("Device %s is BLOCKED due to user unmount.\n"), dev->print_name());
+      Mmsg(jcr->errmsg, _("3604 JobId=%u device %s is BLOCKED due to user unmount.\n"), 
+         jcr->JobId, dev->print_name());
       Dmsg1(100, "%s", jcr->errmsg);
+      queue_reserve_message(jcr);
       goto bail_out;
    }
 
@@ -795,7 +816,7 @@ static int can_reserve_drive(DCR *dcr, RCTX &rctx)
        *  helps spread the load to the least used drives.  
        */
       if (rctx.try_low_use_drive && dev == rctx.low_use_drive) {
-         Dmsg3(100, "OK dev=%s == low_drive=%s. JobId=%d\n",
+         Dmsg3(100, "OK dev=%s == low_drive=%s. JobId=%u\n",
             dev->print_name(), rctx.low_use_drive->print_name(), jcr->JobId);
          return 1;
       }
@@ -811,19 +832,29 @@ static int can_reserve_drive(DCR *dcr, RCTX &rctx)
             Dmsg1(100, "not low use num_writers=%d\n", dev->num_writers+ 
                dev->reserved_device);
          }
-         Dmsg1(100, "failed: !prefMnt && busy. JobId=%d\n", jcr->JobId);
+         Dmsg1(100, "failed: !prefMnt && busy. JobId=%u\n", jcr->JobId);
+         Mmsg(jcr->errmsg, _("3605 JobId=%u wants free drive but device %s is busy.\n"), 
+            jcr->JobId, dev->print_name());
+         queue_reserve_message(jcr);
          return 0;
       }
 
       /* Check for prefer mounted volumes */
       if (rctx.PreferMountedVols && !dev->VolHdr.VolumeName[0] && dev->is_tape()) {
-         Dmsg1(100, "failed: want mounted -- no vol JobId=%d\n", jcr->JobId);
+         Mmsg(jcr->errmsg, _("3606 JobId=%u wants mounted, but drive %s has no Volume.\n"), 
+            jcr->JobId, dev->print_name());
+         queue_reserve_message(jcr);
+         Dmsg1(100, "failed: want mounted -- no vol JobId=%u\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) {
+         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(100, "failed: Not exact match have=%s want=%s\n",
                dev->VolHdr.VolumeName, rctx.VolumeName);
          return 0;
@@ -834,7 +865,7 @@ static int can_reserve_drive(DCR *dcr, RCTX &rctx)
    if (rctx.autochanger_only && dev->num_writers == 0 &&
        dev->VolHdr.VolumeName[0] == 0) {
       /* Device is available but not yet reserved, reserve it for us */
-      Dmsg2(100, "OK Res Unused autochanger %s JobId=%d.\n",
+      Dmsg2(100, "OK Res Unused autochanger %s JobId=%u.\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));
@@ -851,11 +882,14 @@ 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 */
-            Dmsg2(100, "OK dev: %s num_writers=0, reserved, pool matches JobId=%d\n",
+            Dmsg2(100, "OK dev: %s num_writers=0, reserved, pool matches JobId=%u\n",
                dev->print_name(), jcr->JobId);
             return 1;
          } else {
-            /* Drive not suitable for us */
+            /* Drive Pool not suitable for us */
+            Mmsg(jcr->errmsg, _("3608 JobId=%u wants Pool=\"%s\" but have Pool=\"%s\" on drive %s.\n"), 
+                  jcr->JobId, dcr->pool_name, dev->pool_name, dev->print_name());
+            queue_reserve_message(jcr);
             Dmsg2(100, "failed: busy num_writers=0, reserved, pool=%s wanted=%s\n",
                dev->pool_name, dcr->pool_name);
             return 0;                 /* wait */
@@ -864,7 +898,7 @@ 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) {
-            Dmsg2(100, "OK dev: %s num_writers=0, can_append, pool matches. JobId=%d\n",
+            Dmsg2(100, "OK dev: %s num_writers=0, can_append, pool matches. JobId=%u\n",
                dev->print_name(), jcr->JobId);
             /* OK, compatible device */
             return 1;
@@ -875,7 +909,7 @@ static int can_reserve_drive(DCR *dcr, RCTX &rctx)
          }
       }
       /* Device is available but not yet reserved, reserve it for us */
-      Dmsg2(100, "OK Dev avail reserved %s JobId=%d\n", dev->print_name(),
+      Dmsg2(100, "OK Dev avail reserved %s JobId=%u\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));
@@ -890,21 +924,86 @@ static int can_reserve_drive(DCR *dcr, RCTX &rctx)
       /* 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) {
-         Dmsg2(100, "OK dev: %s num_writers>=0, can_append, pool matches. JobId=%d\n",
+         Dmsg2(100, "OK dev: %s num_writers>=0, can_append, pool matches. JobId=%u\n",
             dev->print_name(), jcr->JobId);
          /* OK, compatible device */
          return 1;
       } else {
-         /* Drive not suitable for us */
+         /* Drive Pool not suitable for us */
+         Mmsg(jcr->errmsg, _("3609 JobId=%u wants Pool=\"%s\" but have Pool=\"%s\" on drive %s.\n"), 
+               jcr->JobId, dcr->pool_name, dev->pool_name, dev->print_name());
+         queue_reserve_message(jcr);
          Dmsg2(100, "failed: busy num_writers>0, can_append, pool=%s wanted=%s\n",
             dev->pool_name, dcr->pool_name);
          return 0;                    /* wait */
       }
    } else {
       Pmsg0(000, _("Logic error!!!! Should not get here.\n"));
+      Mmsg(jcr->errmsg, _("3910 JobId=%u Logic error!!!! drive %s Should not get here.\n"),
+            jcr->JobId, dev->print_name());
+      queue_reserve_message(jcr);
       Jmsg0(jcr, M_FATAL, 0, _("Logic error!!!! Should not get here.\n"));
       return -1;                      /* error, should not get here */
    }
-   Dmsg2(100, "failed: No reserve %s JobId=%d\n", dev->print_name(), jcr->JobId);
+   Mmsg(jcr->errmsg, _("3911 JobId=%u failed reserve drive %s.\n"), 
+         jcr->JobId, dev->print_name());
+   queue_reserve_message(jcr);
+   Dmsg2(100, "failed: No reserve %s JobId=%u\n", dev->print_name(), jcr->JobId);
    return 0;
 }
+
+/*
+ * search_lock is already set on entering this routine 
+ */
+static void queue_reserve_message(JCR *jcr)
+{
+   int i;   
+   alist *msgs = jcr->reserve_msgs;
+   char *msg;
+
+   if (!msgs) {
+      return;
+   }
+   /*
+    * Look for duplicate message.  If found, do
+    * not insert
+    */
+   for (i=msgs->size()-1; i >= 0; i--) {
+      msg = (char *)msgs->get(i);
+      if (!msg) {
+         return;
+      }
+      /* Comparison based on 4 digit message number */
+      if (strncmp(msg, jcr->errmsg, 4) == 0) {
+         return;
+      }
+   }      
+   /* Message unique, so insert it */
+   jcr->reserve_msgs->push(bstrdup(jcr->errmsg));
+}
+
+/*
+ * Send any reservation messages queued for this jcr
+ */
+void send_drive_reserve_messages(JCR *jcr, BSOCK *user)
+{
+   int i;
+   alist *msgs;
+   char *msg;
+
+   P(search_lock);
+   msgs = jcr->reserve_msgs;
+   if (!msgs || msgs->size() == 0) {
+      V(search_lock);
+      return;
+   }
+   for (i=msgs->size()-1; i >= 0; i--) {
+      msg = (char *)msgs->get(i);
+      if (msg) {
+         bnet_fsend(user, "   %s", msg);
+      } else {
+         break;
+      }
+   }
+   V(search_lock);
+}
diff --git a/bacula/src/stored/status.c b/bacula/src/stored/status.c
index 3ad2076e06..596bbafc14 100644
--- a/bacula/src/stored/status.c
+++ b/bacula/src/stored/status.c
@@ -46,6 +46,7 @@ static char DotStatusJob[] = "JobId=%d JobStatus=%c JobErrors=%d\n";
 static void send_blocked_status(JCR *jcr, DEVICE *dev);
 static void list_terminated_jobs(void *arg);
 static void list_running_jobs(BSOCK *user);
+static void list_jobs_waiting_on_reservation(BSOCK *user);
 static void sendit(const char *msg, int len, void *arg);
 static const char *level_to_str(int level);
 
@@ -86,6 +87,11 @@ bool status_cmd(JCR *jcr)
     */
    list_running_jobs(user);
 
+   /*
+    * List jobs stuck in reservation system
+    */
+   list_jobs_waiting_on_reservation(user);
+
    /*
     * List terminated jobs
     */
@@ -339,6 +345,23 @@ static void list_running_jobs(BSOCK *user)
    bnet_fsend(user, _("====\n"));
 }
 
+static void list_jobs_waiting_on_reservation(BSOCK *user)
+{ 
+   JCR *jcr;
+
+   bnet_fsend(user, _("\nJobs waiting to reserve a drive:\n"));
+   foreach_jcr(jcr) {
+      if (!jcr->reserve_msgs) {
+         continue;
+      }
+      send_drive_reserve_messages(jcr, user);
+   }
+   endeach_jcr(jcr);
+
+   bnet_fsend(user, _("====\n"));
+}
+
+
 static void list_terminated_jobs(void *arg)
 {
    char dt[MAX_TIME_LENGTH], b1[30], b2[30];
diff --git a/bacula/src/version.h b/bacula/src/version.h
index 10513be5fc..4a0082afe5 100644
--- a/bacula/src/version.h
+++ b/bacula/src/version.h
@@ -4,8 +4,8 @@
 
 #undef  VERSION
 #define VERSION "1.39.4"
-#define BDATE   "06 January 2006"
-#define LSMDATE "06Jan06"
+#define BDATE   "09 January 2006"
+#define LSMDATE "09Jan06"
 
 /* Debug flags */
 #undef  DEBUG
-- 
2.39.2