]> git.sur5r.net Git - bacula/bacula/blobdiff - bacula/src/lib/jcr.c
ebl Add Plugin debug after a fatal signal.
[bacula/bacula] / bacula / src / lib / jcr.c
index ae4e40e9ecf1d88d2df5fdd68a5cccab19c149ce..65e48d816aa3ca2a078491a75dd6be8c9753bdf8 100644 (file)
@@ -1,7 +1,7 @@
 /*
    Bacula® - The Network Backup Solution
 
-   Copyright (C) 2000-2007 Free Software Foundation Europe e.V.
+   Copyright (C) 2000-2008 Free Software Foundation Europe e.V.
 
    The main author of Bacula is Kern Sibbald, with contributions from
    many others, a complete list can be found in the file AUTHORS.
@@ -20,7 +20,7 @@
    Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA
    02110-1301, USA.
 
-   Bacula® is a registered trademark of John Walker.
+   Bacula® is a registered trademark of Kern Sibbald.
    The licensor of Bacula is the Free Software Foundation Europe
    (FSFE), Fiduciary Program, Sumatrastrasse 25, 8006 Zürich,
    Switzerland, email:ftf@fsfeurope.org.
 
 const int dbglvl = 3400;
 
-/*
- * Setting a NULL in tsd doesn't clear the tsd but instead tells
- *   pthreads not to call the tsd destructor. Consequently, we 
- *   define this *invalid* jcr address and stuff it in the tsd
- *   when the jcr is no longer valid.
- */
-#define INVALID_JCR ((JCR *)(-1))
-
 /* External variables we reference */
 extern time_t watchdog_time;
 
@@ -124,6 +116,7 @@ void init_last_jobs_list()
 void term_last_jobs_list()
 {
    if (last_jobs) {
+      lock_last_jobs_list();
       while (!last_jobs->empty()) {
          void *je = last_jobs->first();
          last_jobs->remove(je);
@@ -131,6 +124,7 @@ void term_last_jobs_list()
       }
       delete last_jobs;
       last_jobs = NULL;
+      unlock_last_jobs_list();
    }
    if (jcrs) {
       delete jcrs;
@@ -142,9 +136,10 @@ bool read_last_jobs_list(int fd, uint64_t addr)
 {
    struct s_last_job *je, job;
    uint32_t num;
+   bool ok = true;
 
    Dmsg1(100, "read_last_jobs seek to %d\n", (int)addr);
-   if (addr == 0 || lseek(fd, (off_t)addr, SEEK_SET) < 0) {
+   if (addr == 0 || lseek(fd, (boffset_t)addr, SEEK_SET) < 0) {
       return false;
    }
    if (read(fd, &num, sizeof(num)) != sizeof(num)) {
@@ -154,11 +149,13 @@ bool read_last_jobs_list(int fd, uint64_t addr)
    if (num > 4 * max_last_jobs) {  /* sanity check */
       return false;
    }
+   lock_last_jobs_list();
    for ( ; num; num--) {
       if (read(fd, &job, sizeof(job)) != sizeof(job)) {
          berrno be;
          Pmsg1(000, "Read job entry. ERR=%s\n", be.bstrerror());
-         return false;
+         ok = false;
+         break;
       }
       if (job.JobId > 0) {
          je = (struct s_last_job *)malloc(sizeof(struct s_last_job));
@@ -174,41 +171,48 @@ bool read_last_jobs_list(int fd, uint64_t addr)
          }
       }
    }
-   return true;
+   unlock_last_jobs_list();
+   return ok;
 }
 
 uint64_t write_last_jobs_list(int fd, uint64_t addr)
 {
    struct s_last_job *je;
    uint32_t num;
+   ssize_t stat;
 
    Dmsg1(100, "write_last_jobs seek to %d\n", (int)addr);
-   if (lseek(fd, (off_t)addr, SEEK_SET) < 0) {
+   if (lseek(fd, (boffset_t)addr, SEEK_SET) < 0) {
       return 0;
    }
    if (last_jobs) {
+      lock_last_jobs_list();
       /* First record is number of entires */
       num = last_jobs->size();
       if (write(fd, &num, sizeof(num)) != sizeof(num)) {
          berrno be;
          Pmsg1(000, "Error writing num_items: ERR=%s\n", be.bstrerror());
-         return 0;
+         goto bail_out;
       }
       foreach_dlist(je, last_jobs) {
          if (write(fd, je, sizeof(struct s_last_job)) != sizeof(struct s_last_job)) {
             berrno be;
             Pmsg1(000, "Error writing job: ERR=%s\n", be.bstrerror());
-            return 0;
+            goto bail_out;
          }
       }
+      unlock_last_jobs_list();
    }
    /* Return current address */
-   ssize_t stat = lseek(fd, 0, SEEK_CUR);
+   stat = lseek(fd, 0, SEEK_CUR);
    if (stat < 0) {
       stat = 0;
    }
    return stat;
 
+bail_out:
+   unlock_last_jobs_list();
+   return 0;
 }
 
 void lock_last_jobs_list()
@@ -221,6 +225,83 @@ void unlock_last_jobs_list()
    V(last_jobs_mutex);
 }
 
+/* Get an ASCII representation of the Operation being performed as an english Noun */
+const char *JCR::get_OperationName()
+{
+   switch(m_JobType) {
+   case JT_BACKUP:
+      return _("Backup");
+   case JT_VERIFY:
+      return _("Verifying");
+   case JT_RESTORE:
+      return _("Restoring");
+   case JT_ARCHIVE:
+      return _("Archiving");
+   case JT_COPY:
+      return _("Copying");
+   case JT_MIGRATE:
+      return _("Migration");
+   case JT_SCAN:
+      return _("Scanning");
+   default:
+      return _("Unknown operation");
+   }
+}
+
+/* Get an ASCII representation of the Action being performed either an english Verb or Adjective */
+const char *JCR::get_ActionName(bool past)
+{
+   switch(m_JobType) {
+   case JT_BACKUP:
+      return _("backup");
+   case JT_VERIFY:
+      return (past == true) ? _("verified") : _("verify");
+   case JT_RESTORE:
+      return (past == true) ? _("restored") : _("restore");
+   case JT_ARCHIVE:
+      return (past == true) ? _("archived") : _("archive");
+   case JT_COPY:
+      return (past == true) ? _("copied") : _("copy");
+   case JT_MIGRATE:
+      return (past == true) ? _("migrated") : _("migrate");
+   case JT_SCAN:
+      return (past == true) ? _("scanned") : _("scan");
+   default:
+      return _("unknown action");
+   }
+}
+
+/* Set Job type in JCR and also set appropriate read flag */
+void JCR::set_JobType(int32_t JobType)
+{
+   m_JobType = JobType;
+}
+
+/* Set Job level in JCR and also set appropriate read flag */
+void JCR::set_JobLevel(int32_t JobLevel)
+{
+   m_JobLevel = JobLevel;
+}
+
+bool JCR::JobReads()
+{
+   switch (m_JobType) {
+   case JT_VERIFY:
+   case JT_RESTORE:
+   case JT_COPY:
+   case JT_MIGRATE:
+      return true;
+   case JT_BACKUP:
+      if (m_JobLevel == L_VIRTUAL_FULL) {
+         return true;
+      }
+      break;
+   default:
+      break;
+   }
+   return false;
+}
+
 /*
  * Push a subroutine address into the job end callback stack
  */
@@ -287,8 +368,8 @@ JCR *new_jcr(int size, JCR_free_HANDLER *daemon_free_jcr)
    /* Setup some dummy values */
    bstrncpy(jcr->Job, "*System*", sizeof(jcr->Job));
    jcr->JobId = 0;
-   jcr->JobType = JT_SYSTEM;          /* internal job until defined */
-   jcr->JobLevel = L_NONE;
+   jcr->set_JobType(JT_SYSTEM);          /* internal job until defined */
+   jcr->set_JobLevel(L_NONE);
    set_jcr_job_status(jcr, JS_Created);       /* ready to run */
    set_jcr_in_tsd(jcr);
    sigtimer.sa_flags = 0;
@@ -336,47 +417,6 @@ static void remove_jcr(JCR *jcr)
  */
 static void free_common_jcr(JCR *jcr)
 {
-   struct s_last_job *je, last_job;
-
-   /* Keep some statistics */
-   switch (jcr->JobType) {
-   case JT_BACKUP:
-   case JT_VERIFY:
-   case JT_RESTORE:
-   case JT_MIGRATE:
-   case JT_COPY:
-   case JT_ADMIN:
-      num_jobs_run++;
-      last_job.Errors = jcr->Errors;
-      last_job.JobType = jcr->JobType;
-      last_job.JobId = jcr->JobId;
-      last_job.VolSessionId = jcr->VolSessionId;
-      last_job.VolSessionTime = jcr->VolSessionTime;
-      bstrncpy(last_job.Job, jcr->Job, sizeof(last_job.Job));
-      last_job.JobFiles = jcr->JobFiles;
-      last_job.JobBytes = jcr->JobBytes;
-      last_job.JobStatus = jcr->JobStatus;
-      last_job.JobLevel = jcr->JobLevel;
-      last_job.start_time = jcr->start_time;
-      last_job.end_time = time(NULL);
-      /* Keep list of last jobs, but not Console where JobId==0 */
-      if (last_job.JobId > 0) {
-         je = (struct s_last_job *)malloc(sizeof(struct s_last_job));
-         memcpy((char *)je, (char *)&last_job, sizeof(last_job));
-         if (!last_jobs) {
-            init_last_jobs_list();
-         }
-         last_jobs->append(je);
-         if (last_jobs->size() > max_last_jobs) {
-            je = (struct s_last_job *)last_jobs->first();
-            last_jobs->remove(je);
-            free(je);
-         }
-      }
-      break;
-   default:
-      break;
-   }
    jcr->destroy_mutex();
 
    if (jcr->msg_queue) {
@@ -446,12 +486,15 @@ static void free_common_jcr(JCR *jcr)
 #ifdef DEBUG
 void b_free_jcr(const char *file, int line, JCR *jcr)
 {
+   struct s_last_job *je;
+
    Dmsg3(dbglvl, "Enter free_jcr jid=%u from %s:%d\n", jcr->JobId, file, line);
 
 #else
 
 void free_jcr(JCR *jcr)
 {
+   struct s_last_job *je;
 
    Dmsg3(dbglvl, "Enter free_jcr jid=%u use_count=%d Job=%s\n", 
          jcr->JobId, jcr->use_count(), jcr->Job);
@@ -462,7 +505,7 @@ void free_jcr(JCR *jcr)
    lock_jcr_chain();
    jcr->dec_use_count();              /* decrement use count */
    if (jcr->use_count() < 0) {
-      Emsg2(M_ERROR, 0, _("JCR use_count=%d JobId=%d\n"),
+      Jmsg2(jcr, M_ERROR, 0, _("JCR use_count=%d JobId=%d\n"),
          jcr->use_count(), jcr->JobId);
    }
    if (jcr->JobId > 0) {
@@ -478,14 +521,59 @@ void free_jcr(JCR *jcr)
             jcr->JobId, jcr->use_count(), jcr->Job);
    }
    remove_jcr(jcr);                   /* remove Jcr from chain */
-   unlock_jcr_chain();
 
    job_end_pop(jcr);                  /* pop and call hooked routines */
 
    Dmsg1(dbglvl, "End job=%d\n", jcr->JobId);
+
+   /* Keep some statistics */
+   switch (jcr->get_JobType()) {
+   case JT_BACKUP:
+   case JT_VERIFY:
+   case JT_RESTORE:
+   case JT_MIGRATE:
+   case JT_COPY:
+   case JT_ADMIN:
+      /* Keep list of last jobs, but not Console where JobId==0 */
+      if (jcr->JobId > 0) {
+         lock_last_jobs_list();
+         num_jobs_run++;
+         je = (struct s_last_job *)malloc(sizeof(struct s_last_job));
+         memset(je, 0, sizeof(struct s_last_job));  /* zero in case unset fields */
+         je->Errors = jcr->Errors;
+         je->JobType = jcr->get_JobType();
+         je->JobId = jcr->JobId;
+         je->VolSessionId = jcr->VolSessionId;
+         je->VolSessionTime = jcr->VolSessionTime;
+         bstrncpy(je->Job, jcr->Job, sizeof(je->Job));
+         je->JobFiles = jcr->JobFiles;
+         je->JobBytes = jcr->JobBytes;
+         je->JobStatus = jcr->JobStatus;
+         je->JobLevel = jcr->get_JobLevel();
+         je->start_time = jcr->start_time;
+         je->end_time = time(NULL);
+
+         if (!last_jobs) {
+            init_last_jobs_list();
+         }
+         last_jobs->append(je);
+         if (last_jobs->size() > max_last_jobs) {
+            je = (struct s_last_job *)last_jobs->first();
+            last_jobs->remove(je);
+            free(je);
+         }
+         unlock_last_jobs_list();
+      }
+      break;
+   default:
+      break;
+   }
+
    if (jcr->daemon_free_jcr) {
       jcr->daemon_free_jcr(jcr);      /* call daemon free routine */
    }
+
+   unlock_jcr_chain();
    free_common_jcr(jcr);
    close_msg(NULL);                   /* flush any daemon messages */
    garbage_collect_memory_pool();
@@ -626,35 +714,110 @@ JCR *get_jcr_by_full_name(char *Job)
    return jcr;
 }
 
-void set_jcr_job_status(JCR *jcr, int JobStatus)
+/* 
+ * Priority runs from 0 (lowest) to 10 (highest)
+ */
+static int get_status_priority(int JobStatus)
 {
-   /*
-    * For a set of errors, ... keep the current status
-    *   so it isn't lost. For all others, set it.
-    */
-   Dmsg3(300, "jid=%u OnEntry JobStatus=%c set=%c\n", (uint32_t)jcr->JobId,
-         jcr->JobStatus, JobStatus);
-   switch (jcr->JobStatus) {
+   int priority = 0;
+   switch (JobStatus) {
    case JS_ErrorTerminated:
    case JS_FatalError:
+      priority = 10;
+      break;
    case JS_Canceled:
+      priority = 9;
       break;
    case JS_Error:
+      priority = 8;
+      break;
    case JS_Differences:
-      switch (JobStatus) {
-      case JS_ErrorTerminated:
-      case JS_FatalError:
-      case JS_Canceled:
-         /* Override more minor status */
-         jcr->JobStatus = JobStatus;
-         break;
+      priority = 7;
+      break;
+   }
+   return priority;
+}
+
+
+static void update_wait_time(JCR *jcr, int newJobStatus)
+{
+   bool enter_in_waittime;
+   int oldJobStatus = jcr->JobStatus;
+
+   switch (newJobStatus) {
+   case JS_WaitFD:
+   case JS_WaitSD:
+   case JS_WaitMedia:
+   case JS_WaitMount:
+   case JS_WaitStoreRes:
+   case JS_WaitJobRes:
+   case JS_WaitClientRes:
+   case JS_WaitMaxJobs:
+   case JS_WaitPriority:
+      enter_in_waittime = true;
+      break;
+   default:
+      enter_in_waittime = false; /* not a Wait situation */
+      break;
+   }
+   
+   /*
+    * If we were previously waiting and are not any more
+    *   we want to update the wait_time variable, which is
+    *   the start of waiting.
+    */
+   switch (oldJobStatus) {
+   case JS_WaitFD:
+   case JS_WaitSD:
+   case JS_WaitMedia:
+   case JS_WaitMount:
+   case JS_WaitStoreRes:
+   case JS_WaitJobRes:
+   case JS_WaitClientRes:
+   case JS_WaitMaxJobs:
+   case JS_WaitPriority:
+      if (!enter_in_waittime) { /* we get out the wait time */
+         jcr->wait_time_sum += (time(NULL) - jcr->wait_time);
+         jcr->wait_time = 0;
       }
       break;
+
+   /* if wait state is new, we keep current time for watchdog MaxWaitTime */
    default:
-      jcr->JobStatus = JobStatus;
+      if (enter_in_waittime) {
+         jcr->wait_time = time(NULL);
+      }
+      break;
    }
-   Dmsg3(100, "jid=%u OnExit JobStatus=%c set=%c\n", (uint32_t)jcr->JobId,
+}
+
+void set_jcr_job_status(JCR *jcr, int JobStatus)
+{
+   int priority, old_priority;
+   int oldJobStatus = jcr->JobStatus;
+   priority = get_status_priority(JobStatus);
+   old_priority = get_status_priority(oldJobStatus);
+   
+   Dmsg2(800, "set_jcr_job_status(%s, %c)\n", jcr->Job, JobStatus);
+
+   /* Update wait_time depending on newJobStatus and oldJobStatus */
+   update_wait_time(jcr, JobStatus);
+
+   /*
+    * For a set of errors, ... keep the current status
+    *   so it isn't lost. For all others, set it.
+    */
+   Dmsg3(300, "jid=%u OnEntry JobStatus=%c set=%c\n", (uint32_t)jcr->JobId,
          jcr->JobStatus, JobStatus);
+   if (priority >= old_priority) {
+      jcr->JobStatus = JobStatus;     /* replace with new priority */
+   }
+
+   if (oldJobStatus != jcr->JobStatus) {
+      Dmsg3(200, "jid=%u leave set_old_job_status=%c new_set=%c\n", (uint32_t)jcr->JobId,
+         oldJobStatus, JobStatus);
+//    generate_plugin_event(jcr, bEventStatusChange, NULL);
+   }
 }
 
 #ifdef TRACE_JCR_CHAIN
@@ -691,7 +854,6 @@ static void unlock_jcr_chain()
    V(jcr_lock);
 }
 
-
 /*
  * Start walk of jcr chain
  * The proper way to walk the jcr chain is:
@@ -783,7 +945,7 @@ bool init_jcr_subsystem(void)
 static void jcr_timeout_check(watchdog_t *self)
 {
    JCR *jcr;
-   BSOCK *fd;
+   BSOCK *bs;
    time_t timer_start;
 
    Dmsg0(dbglvl, "Start JCR timeout checks\n");
@@ -796,37 +958,37 @@ static void jcr_timeout_check(watchdog_t *self)
       if (jcr->JobId == 0) {
          continue;
       }
-      fd = jcr->store_bsock;
-      if (fd) {
-         timer_start = fd->timer_start;
-         if (timer_start && (watchdog_time - timer_start) > fd->timeout) {
-            fd->timer_start = 0;      /* turn off timer */
-            fd->set_timed_out();
-            Jmsg(jcr, M_ERROR, 0, _(
+      bs = jcr->store_bsock;
+      if (bs) {
+         timer_start = bs->timer_start;
+         if (timer_start && (watchdog_time - timer_start) > bs->timeout) {
+            bs->timer_start = 0;      /* turn off timer */
+            bs->set_timed_out();
+            Qmsg(jcr, M_ERROR, 0, _(
 "Watchdog sending kill after %d secs to thread stalled reading Storage daemon.\n"),
                  watchdog_time - timer_start);
             pthread_kill(jcr->my_thread_id, TIMEOUT_SIGNAL);
          }
       }
-      fd = jcr->file_bsock;
-      if (fd) {
-         timer_start = fd->timer_start;
-         if (timer_start && (watchdog_time - timer_start) > fd->timeout) {
-            fd->timer_start = 0;      /* turn off timer */
-            fd->set_timed_out();
-            Jmsg(jcr, M_ERROR, 0, _(
+      bs = jcr->file_bsock;
+      if (bs) {
+         timer_start = bs->timer_start;
+         if (timer_start && (watchdog_time - timer_start) > bs->timeout) {
+            bs->timer_start = 0;      /* turn off timer */
+            bs->set_timed_out();
+            Qmsg(jcr, M_ERROR, 0, _(
 "Watchdog sending kill after %d secs to thread stalled reading File daemon.\n"),
                  watchdog_time - timer_start);
             pthread_kill(jcr->my_thread_id, TIMEOUT_SIGNAL);
          }
       }
-      fd = jcr->dir_bsock;
-      if (fd) {
-         timer_start = fd->timer_start;
-         if (timer_start && (watchdog_time - timer_start) > fd->timeout) {
-            fd->timer_start = 0;      /* turn off timer */
-            fd->set_timed_out();
-            Jmsg(jcr, M_ERROR, 0, _(
+      bs = jcr->dir_bsock;
+      if (bs) {
+         timer_start = bs->timer_start;
+         if (timer_start && (watchdog_time - timer_start) > bs->timeout) {
+            bs->timer_start = 0;      /* turn off timer */
+            bs->set_timed_out();
+            Qmsg(jcr, M_ERROR, 0, _(
 "Watchdog sending kill after %d secs to thread stalled reading Director.\n"),
                  watchdog_time - timer_start);
             pthread_kill(jcr->my_thread_id, TIMEOUT_SIGNAL);
@@ -845,3 +1007,65 @@ extern "C" void timeout_handler(int sig)
 {
    return;                            /* thus interrupting the function */
 }
+
+/* Used to display specific daemon information after a fatal signal 
+ * (like B_DB in the director)
+ */
+#define MAX_DBG_HOOK 10
+static dbg_jcr_hook_t *dbg_jcr_hooks[MAX_DBG_HOOK];
+static int dbg_jcr_handler_count;
+
+void dbg_jcr_add_hook(dbg_jcr_hook_t *fct)
+{
+   ASSERT(dbg_jcr_handler_count < MAX_DBG_HOOK);
+   dbg_jcr_hooks[dbg_jcr_handler_count++] = fct;
+}
+
+/*
+ * !!! WARNING !!! 
+ *
+ * This function should be used ONLY after a fatal signal. We walk through the
+ * JCR chain without doing any lock, bacula should not be running.
+ */
+void _dbg_print_jcr(FILE *fp)
+{
+   char buf1[128], buf2[128], buf3[128], buf4[128];
+   if (!jcrs) {
+      return;
+   }
+
+   fprintf(fp, "Attempt to dump current JCRs\n");
+
+   for (JCR *jcr = (JCR *)jcrs->first(); jcr ; jcr = (JCR *)jcrs->next(jcr)) {
+      if (!jcr) {               /* protect us against something ? */
+         continue;
+      }
+      
+      fprintf(fp, "JCR=%p JobId=%i name=%s JobStatus=%c\n", 
+              jcr, jcr->JobId, jcr->Job, jcr->JobStatus);
+#ifdef HAVE_WIN32
+      fprintf(fp, "\tuse_count=%i\n",
+              jcr->use_count());
+#else
+      fprintf(fp, "\tuse_count=%i threadid=0x%x\n",
+              jcr->use_count(), (int)jcr->my_thread_id);
+#endif
+      fprintf(fp, "\tJobType=%c JobLevel=%c\n",
+              jcr->get_JobType(), jcr->get_JobLevel());
+      bstrftime(buf1, sizeof(buf1), jcr->sched_time);
+      bstrftime(buf2, sizeof(buf2), jcr->start_time);
+      bstrftime(buf3, sizeof(buf3), jcr->end_time);
+      bstrftime(buf4, sizeof(buf4), jcr->wait_time);
+      fprintf(fp, "\tsched_time=%s start_time=%s\n\tend_time=%s wait_time=%s\n",
+              buf1, buf2, buf3, buf4);
+      fprintf(fp, "\tdequeing=%i\n", jcr->dequeuing);
+      fprintf(fp, "\tdb=%p db_batch=%p batch_started=%i\n", 
+              jcr->db, jcr->db_batch, jcr->batch_started);
+      
+      for(int i=0; i < dbg_jcr_handler_count; i++) {
+         dbg_jcr_hook_t *fct = dbg_jcr_hooks[i];
+         fct(jcr, fp);
+      }
+   }
+}
+