]> git.sur5r.net Git - bacula/bacula/blobdiff - bacula/src/stored/block.c
Backport new lock calls + debug for SD
[bacula/bacula] / bacula / src / stored / block.c
index 7899621399baae42242e1b392e32105c8688d650..e731320b880b2a459c8916bfad46c32c18dded34 100644 (file)
@@ -1,12 +1,12 @@
 /*
    Bacula® - The Network Backup Solution
 
-   Copyright (C) 2001-2009 Free Software Foundation Europe e.V.
+   Copyright (C) 2001-2012 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.
    This program is Free Software; you can redistribute it and/or
-   modify it under the terms of version two of the GNU General Public
+   modify it under the terms of version three of the GNU Affero General Public
    License as published by the Free Software Foundation and included
    in the file LICENSE.
 
@@ -15,7 +15,7 @@
    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
+   You should have received a copy of the GNU Affero General Public License
    along with this program; if not, write to the Free Software
    Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA
    02110-1301, USA.
  *              Kern Sibbald, March MMI
  *                 added BB02 format October MMII
  *
- *   Version $Id$
- *
  */
 
 
 #include "bacula.h"
 #include "stored.h"
 
+#ifdef DEBUG_BLOCK_CHECKSUM
+static const bool debug_block_checksum = true;
+#else
+static const bool debug_block_checksum = false;
+#endif
+
+#ifdef NO_TAPE_WRITE_TEST
+static const bool no_tape_write_test = true;
+#else
+static const bool no_tape_write_test = false;
+#endif
+
+
 static bool terminate_writing_volume(DCR *dcr);
 static bool do_new_file_bookkeeping(DCR *dcr);
 static bool do_dvd_size_checks(DCR *dcr);
@@ -81,7 +92,7 @@ void dump_block(DEV_BLOCK *b, const char *msg)
       rhl = RECHDR1_LENGTH;
    }
 
-   if (block_len > 100000) {
+   if (block_len > 4000000) {
       Dmsg3(20, "Dump block %s 0x%x blocksize too big %u\n", msg, b, block_len);
       return;
    }
@@ -167,10 +178,12 @@ void print_block_read_errors(JCR *jcr, DEV_BLOCK *block)
  */
 void free_block(DEV_BLOCK *block)
 {
-   Dmsg1(999, "free_block buffer %x\n", block->buf);
-   free_memory(block->buf);
-   Dmsg1(999, "free_block block %x\n", block);
-   free_memory((POOLMEM *)block);
+   if (block) {
+      Dmsg1(999, "free_block buffer %x\n", block->buf);
+      free_memory(block->buf);
+      Dmsg1(999, "free_block block %x\n", block);
+      free_memory((POOLMEM *)block);
+   }
 }
 
 /* Empty the block -- for writing */
@@ -189,7 +202,7 @@ void empty_block(DEV_BLOCK *block)
  * in the buffer should have already been reserved by
  * init_block.
  */
-static void ser_block_header(DEV_BLOCK *block, bool do_checksum)
+static uint32_t ser_block_header(DEV_BLOCK *block, bool do_checksum)
 {
    ser_declare;
    uint32_t CheckSum = 0;
@@ -214,6 +227,7 @@ static void ser_block_header(DEV_BLOCK *block, bool do_checksum)
    Dmsg1(1390, "ser_bloc_header: checksum=%x\n", CheckSum);
    ser_begin(block->buf, BLKHDR2_LENGTH);
    ser_uint32(CheckSum);              /* now add checksum to block header */
+   return CheckSum;
 }
 
 /*
@@ -320,6 +334,7 @@ static bool unser_block_header(JCR *jcr, DEVICE *dev, DEV_BLOCK *block)
             block_len, BlockCheckSum, CheckSum);
          if (block->read_errors == 0 || verbose >= 2) {
             Jmsg(jcr, M_ERROR, 0, "%s", dev->errmsg);
+            dump_block(block, "with checksum error");
          }
          block->read_errors++;
          if (!forge_on) {
@@ -337,20 +352,20 @@ static bool unser_block_header(JCR *jcr, DEVICE *dev, DEV_BLOCK *block)
  *        : false on failure
  *
  */
-bool write_block_to_device(DCR *dcr)
+bool DCR::write_block_to_device()
 {
    bool stat = true;
-   DEVICE *dev = dcr->dev;
-   JCR *jcr = dcr->jcr;
+   DCR *dcr = this;
 
    if (dcr->spooling) {
+      Dmsg0(100, "Write to spool\n");
       stat = write_block_to_spool_file(dcr);
       return stat;
    }
 
    if (!dcr->is_dev_locked()) {        /* device already locked? */
       /* note, do not change this to dcr->r_dlock */
-      dev->r_dlock();                  /* no, lock it */
+      dev->rLock();                  /* no, lock it */
    }
 
    /*
@@ -362,15 +377,17 @@ bool write_block_to_device(DCR *dcr)
    if (dcr->NewVol || dcr->NewFile) {
       if (job_canceled(jcr)) {
          stat = false;
+         Dmsg0(100, "Canceled\n");
          goto bail_out;
       }
       /* Create a jobmedia record for this job */
       if (!dir_create_jobmedia_record(dcr)) {
          dev->dev_errno = EIO;
          Jmsg2(jcr, M_FATAL, 0, _("Could not create JobMedia record for Volume=\"%s\" Job=%s\n"),
-            dcr->VolCatInfo.VolCatName, jcr->Job);
+            dcr->getVolCatName(), jcr->Job);
          set_new_volume_parameters(dcr);
          stat = false;
+         Dmsg0(100, "cannot create media record\n");
          goto bail_out;
       }
       if (dcr->NewVol) {
@@ -381,8 +398,8 @@ bool write_block_to_device(DCR *dcr)
       }
    }
 
-   if (!write_block_to_dev(dcr)) {
-       if (job_canceled(jcr) || jcr->get_JobType() == JT_SYSTEM) {
+   if (!dcr->write_block_to_dev()) {
+       if (job_canceled(jcr) || jcr->getJobType() == JT_SYSTEM) {
           stat = false;
        } else {
           stat = fixup_device_block_write_error(dcr);
@@ -392,7 +409,7 @@ bool write_block_to_device(DCR *dcr)
 bail_out:
    if (!dcr->is_dev_locked()) {        /* did we lock dev above? */
       /* note, do not change this to dcr->dunlock */
-      dev->dunlock();                  /* unlock it now */
+      dev->Unlock();                  /* unlock it now */
    }
    return stat;
 }
@@ -403,43 +420,52 @@ bail_out:
  *  Returns: true  on success or EOT
  *           false on hard error
  */
-bool write_block_to_dev(DCR *dcr)
+bool DCR::write_block_to_dev()
 {
    ssize_t stat = 0;
    uint32_t wlen;                     /* length to write */
    int hit_max1, hit_max2;
    bool ok = true;
-   DEVICE *dev = dcr->dev;
-   JCR *jcr = dcr->jcr;
-   DEV_BLOCK *block = dcr->block;
+   DCR *dcr = this;
+   uint32_t checksum;
 
-#ifdef NO_TAPE_WRITE_TEST
-   empty_block(block);
-   return true;
-#endif
+   if (no_tape_write_test) {
+      empty_block(block);
+      return true;
+   }
    if (job_canceled(jcr)) {
       return false;
    }
+
    ASSERT(block->binbuf == ((uint32_t) (block->bufp - block->buf)));
-   ASSERT(dev->is_open());
+
+   wlen = block->binbuf;
+   if (wlen <= WRITE_BLKHDR_LENGTH) {  /* Does block have data in it? */
+      Dmsg0(100, "return write_block_to_dev no data to write\n");
+      return true;
+   }
 
    /* dump_block(block, "before write"); */
    if (dev->at_weot()) {
       Dmsg0(100, "return write_block_to_dev with ST_WEOT\n");
       dev->dev_errno = ENOSPC;
-      Jmsg0(jcr, M_FATAL, 0,  _("Cannot write block. Device at EOM.\n"));
+      Jmsg1(jcr, M_FATAL, 0,  _("Cannot write block. Device at EOM. dev=%s\n"), dev->print_name());
+      Dmsg1(100, "Attempt to write on read-only Volume. dev=%s\n", dev->print_name());
       return false;
    }
    if (!dev->can_append()) {
       dev->dev_errno = EIO;
-      Jmsg(jcr, M_FATAL, 0, _("Attempt to write on read-only Volume.\n"));
+      Jmsg1(jcr, M_FATAL, 0, _("Attempt to write on read-only Volume. dev=%s\n"), dev->print_name());
+      Dmsg1(100, "Attempt to write on read-only Volume. dev=%s\n", dev->print_name());
       return false;
    }
-   wlen = block->binbuf;
-   if (wlen <= WRITE_BLKHDR_LENGTH) {  /* Does block have data in it? */
-      Dmsg0(100, "return write_block_to_dev no data to write\n");
-      return true;
+   if (!dev->is_open()) {
+      Jmsg1(jcr, M_FATAL, 0, _("Attempt to write on closed device=%s\n"), dev->print_name());
+      Dmsg1(100, "Attempt to write on closed device=%s\n", dev->print_name());
+      return false;
    }
+
    /*
     * Clear to the end of the buffer if it is not full,
     *  and on tape devices, apply min and fixed blocking.
@@ -468,7 +494,7 @@ bool write_block_to_dev(DCR *dcr)
       }
    }
 
-   ser_block_header(block, dev->do_checksum());
+   checksum = ser_block_header(block, dev->do_checksum());
 
    /* Limit maximum Volume size to value specified by user */
    hit_max1 = (dev->max_volume_size > 0) &&
@@ -498,7 +524,7 @@ bool write_block_to_dev(DCR *dcr)
       dev->file_size = 0;             /* reset file size */
 
       if (!dev->weof(1)) {            /* write eof */
-         Dmsg0(190, "WEOF error in max file size.\n");
+         Dmsg0(50, "WEOF error in max file size.\n");
          Jmsg(jcr, M_FATAL, 0, _("Unable to write EOF. ERR=%s\n"), 
             dev->bstrerror());
          terminate_writing_volume(dcr);
@@ -548,6 +574,15 @@ bool write_block_to_dev(DCR *dcr)
 
    } while (stat == -1 && (errno == EBUSY || errno == EIO) && retry++ < 3);
 
+   if (debug_block_checksum) {
+      uint32_t achecksum = ser_block_header(block, dev->do_checksum());
+      if (checksum != achecksum) {
+         Jmsg2(jcr, M_ERROR, 0, _("Block checksum changed during write: before=%ud after=%ud\n"),
+            checksum, achecksum);
+         dump_block(block, "with checksum error");
+      }
+   }
+
 #ifdef DEBUG_BLOCK_ZEROING
    if (bp[0] == 0 && bp[1] == 0 && bp[2] == 0 && block->buf[12] == 0) {
       Jmsg0(jcr, M_ABORT, 0, _("Write block header zeroed.\n"));
@@ -577,7 +612,7 @@ bool write_block_to_dev(DCR *dcr)
       }
       if (dev->dev_errno == ENOSPC) {
          Jmsg(jcr, M_INFO, 0, _("End of Volume \"%s\" at %u:%u on device %s. Write of %u bytes got %d.\n"),
-            dev->VolCatInfo.VolCatName,
+            dev->getVolCatName(),
             dev->file, dev->block_num, dev->print_name(), wlen, stat);
       }
       if (debug_level >= 100) {
@@ -686,7 +721,7 @@ static void reread_last_block(DCR *dcr)
          DEV_BLOCK *lblock = new_block(dev);
          /* Note, this can destroy dev->errmsg */
          dcr->block = lblock;
-         if (!read_block_from_dev(dcr, NO_BLOCK_NUMBER_CHECK)) {
+         if (!dcr->read_block_from_dev(NO_BLOCK_NUMBER_CHECK)) {
             Jmsg(jcr, M_ERROR, 0, _("Re-read last block at EOT failed. ERR=%s"), 
                  dev->errmsg);
          } else {
@@ -729,10 +764,11 @@ static bool terminate_writing_volume(DCR *dcr)
    /* Create a JobMedia record to indicated end of tape */
    dev->VolCatInfo.VolCatFiles = dev->file;
    if (!dir_create_jobmedia_record(dcr)) {
-      Dmsg0(190, "Error from create JobMedia\n");
+      Dmsg0(50, "Error from create JobMedia\n");
       dev->dev_errno = EIO;
-       Jmsg2(dcr->jcr, M_FATAL, 0, _("Could not create JobMedia record for Volume=\"%s\" Job=%s\n"),
-            dcr->VolCatInfo.VolCatName, dcr->jcr->Job);
+        Mmsg2(dev->errmsg, _("Could not create JobMedia record for Volume=\"%s\" Job=%s\n"),
+            dcr->getVolCatName(), dcr->jcr->Job);
+       Jmsg(dcr->jcr, M_FATAL, 0, "%s", dev->errmsg);
        ok = false;
    }
    dcr->block->write_failed = true;
@@ -741,7 +777,7 @@ static bool terminate_writing_volume(DCR *dcr)
       Jmsg(dcr->jcr, M_ERROR, 0, _("Error writing final EOF to tape. This Volume may not be readable.\n"
            "%s"), dev->errmsg);
       ok = false;
-      Dmsg0(100, "WEOF error.\n");
+      Dmsg0(50, "Error writing final EOF to volume.\n");
    }
    if (ok) {
       ok = write_ansi_ibm_labels(dcr, ANSI_EOV_LABEL, dev->VolHdr.VolumeName);
@@ -762,9 +798,11 @@ static bool terminate_writing_volume(DCR *dcr)
    }
    
    if (!dir_update_volume_info(dcr, false, true)) {
+      Mmsg(dev->errmsg, _("Error sending Volume info to Director.\n"));
       ok = false;
+      Dmsg0(50, "Error updating volume info.\n");
    }
-   Dmsg1(100, "dir_update_volume_info terminate writing -- %s\n", ok?"OK":"ERROR");
+   Dmsg1(50, "dir_update_volume_info terminate writing -- %s\n", ok?"OK":"ERROR");
 
    /*
     * Walk through all attached dcrs setting flag to call
@@ -784,6 +822,7 @@ static bool terminate_writing_volume(DCR *dcr)
       dev->VolCatInfo.VolCatErrors++;
       /* This may not be fatal since we already wrote an EOF */
       Jmsg(dcr->jcr, M_ERROR, 0, "%s", dev->errmsg);
+      Dmsg0(50, "Writing second EOF failed.\n");
    }
 
    dev->set_ateot();                  /* no more writing this tape */
@@ -803,17 +842,17 @@ static bool do_new_file_bookkeeping(DCR *dcr)
 
    /* Create a JobMedia record so restore can seek */
    if (!dir_create_jobmedia_record(dcr)) {
-      Dmsg0(190, "Error from create_job_media.\n");
+      Dmsg0(50, "Error from create_job_media.\n");
       dev->dev_errno = EIO;
       Jmsg2(jcr, M_FATAL, 0, _("Could not create JobMedia record for Volume=\"%s\" Job=%s\n"),
-           dcr->VolCatInfo.VolCatName, jcr->Job);
+           dcr->getVolCatName(), jcr->Job);
       terminate_writing_volume(dcr);
       dev->dev_errno = EIO;
       return false;
    }
    dev->VolCatInfo.VolCatFiles = dev->file;
    if (!dir_update_volume_info(dcr, false, false)) {
-      Dmsg0(190, "Error from update_vol_info.\n");
+      Dmsg0(50, "Error from update_vol_info.\n");
       terminate_writing_volume(dcr);
       dev->dev_errno = EIO;
       return false;
@@ -884,7 +923,7 @@ static bool do_dvd_size_checks(DCR *dcr)
       Dmsg1(100, "Cannot get free space on the device ERR=%s.\n", dev->errmsg);
       Jmsg(jcr, M_FATAL, 0, _("End of Volume \"%s\" at %u:%u on device %s "
          "(part_size=%s, free_space=%s, free_space_errno=%d, errmsg=%s).\n"),
-           dev->VolCatInfo.VolCatName,
+           dev->getVolCatName(),
            dev->file, dev->block_num, dev->print_name(),
            edit_uint64_with_commas(dev->part_size, ed1), edit_uint64_with_commas(dev->free_space, ed2),
            dev->free_space_errno, dev->errmsg);
@@ -897,7 +936,7 @@ static bool do_dvd_size_checks(DCR *dcr)
       Dmsg0(100, "==== Just enough free space on the device to write the current part...\n");
       Jmsg(jcr, M_INFO, 0, _("End of Volume \"%s\" at %u:%u on device %s "
          "(part_size=%s, free_space=%s, free_space_errno=%d).\n"),
-            dev->VolCatInfo.VolCatName,
+            dev->getVolCatName(),
             dev->file, dev->block_num, dev->print_name(),
             edit_uint64_with_commas(dev->part_size, ed1), edit_uint64_with_commas(dev->free_space, ed2),
             dev->free_space_errno);
@@ -913,14 +952,14 @@ static bool do_dvd_size_checks(DCR *dcr)
  * Read block with locking
  *
  */
-bool read_block_from_device(DCR *dcr, bool check_block_numbers)
+bool DCR::read_block_from_device(bool check_block_numbers)
 {
    bool ok;
-   DEVICE *dev = dcr->dev;
+
    Dmsg0(250, "Enter read_block_from_device\n");
-   dev->r_dlock();
-   ok = read_block_from_dev(dcr, check_block_numbers);
-   dev->dunlock();
+   dev->rLock();
+   ok = read_block_from_dev(check_block_numbers);
+   dev->Unlock();
    Dmsg0(250, "Leave read_block_from_device\n");
    return ok;
 }
@@ -930,27 +969,36 @@ bool read_block_from_device(DCR *dcr, bool check_block_numbers)
  *  the block header.  For a file, the block may be partially
  *  or completely in the current buffer.
  */
-bool read_block_from_dev(DCR *dcr, bool check_block_numbers)
+bool DCR::read_block_from_dev(bool check_block_numbers)
 {
    ssize_t stat;
    int looping;
-   uint32_t BlockNumber;
    int retry;
-   JCR *jcr = dcr->jcr;
-   DEVICE *dev = dcr->dev;
-   DEV_BLOCK *block = dcr->block;
+   DCR *dcr = this;
 
    if (job_canceled(jcr)) {
+      Mmsg(dev->errmsg, _("Job failed or canceled.\n"));
+      block->read_len = 0;
       return false;
    }
-   ASSERT(dev->is_open());
    
    if (dev->at_eot()) {
+      Mmsg(dev->errmsg, _("Attempt to read past end of tape or file.\n"));
+      block->read_len = 0;
       return false;
    }
    looping = 0;
    Dmsg1(250, "Full read in read_block_from_device() len=%d\n",
          block->buf_len);
+
+   if (!dev->is_open()) {
+      Mmsg4(dev->errmsg, _("Attempt to read closed device: fd=%d at file:blk %u:%u on device %s\n"),
+         dev->fd(), dev->file, dev->block_num, dev->print_name());
+      Jmsg(dcr->jcr, M_WARNING, 0, "%s", dev->errmsg);
+      block->read_len = 0;
+      return false;
+    }
+
 reread:
    if (looping > 1) {
       dev->dev_errno = EIO;
@@ -961,29 +1009,14 @@ reread:
       return false;
    }
    
-// #define lots_of_debug
-#ifdef lots_of_debug
-   if (dev->at_eof() && dev->is_dvd()) {
-      Dmsg1(100, "file_size=%u\n",(unsigned int)dev->file_size);
-      Dmsg1(100, "file_addr=%u\n",(unsigned int)dev->file_addr);
-      Dmsg1(100, "lseek=%u\n",(unsigned int)lseek(dev->fd(), 0, SEEK_CUR));
-      Dmsg1(100, "part_start=%u\n",(unsigned int)dev->part_start);
-      Dmsg1(100, "part_size=%u\n", (unsigned int)dev->part_size);
-      Dmsg2(100, "part=%u num_dvd_parts=%u\n", dev->part, dev->num_dvd_parts);
-      Dmsg1(100, "VolCatInfo.VolCatParts=%u\n", (unsigned int)dev->VolCatInfo.VolCatParts);
-      Dmsg3(100, "Tests : %d %d %d\n", (dev->VolCatInfo.VolCatParts > 0), 
-         ((dev->file_addr-dev->part_start) == dev->part_size), 
-         (dev->part <= dev->VolCatInfo.VolCatParts));
-  }
-#endif
-
    /* Check for DVD part file end */
    if (dev->at_eof() && dev->is_dvd() && dev->num_dvd_parts > 0 &&
         dev->part <= dev->num_dvd_parts) {
       Dmsg0(400, "Call dvd_open_next_part\n");
       if (dvd_open_next_part(dcr) < 0) {
-         Jmsg3(dcr->jcr, M_FATAL, 0, _("Unable to open device part=%d %s: ERR=%s\n"),
+         Mmsg3(dev->errmsg, _("Unable to open device part=%d %s: ERR=%s\n"),
                dev->part, dev->print_name(), dev->bstrerror());
+         Jmsg(dcr->jcr, M_FATAL, 0, "%s", dev->errmsg);
          dev->dev_errno = EIO;
          return false;
       }
@@ -1050,10 +1083,11 @@ reread:
       Jmsg(jcr, M_ERROR, 0, "%s", dev->errmsg);
       dev->set_short_block();   
       block->read_len = block->binbuf = 0;
+      Dmsg2(200, "set block=%p binbuf=%d\n", block, block->binbuf);
       return false;             /* return error */
    }
 
-   BlockNumber = block->BlockNumber + 1;
+// BlockNumber = block->BlockNumber + 1;
    if (!unser_block_header(jcr, dev, block)) {
       if (forge_on) {
          dev->file_addr += block->read_len;
@@ -1078,7 +1112,8 @@ reread:
       if (dev->is_tape()) {
          Dmsg0(250, "BSR for reread; block too big for buffer.\n");
          if (!dev->bsr(1)) {
-            Jmsg(jcr, M_ERROR, 0, "%s", dev->bstrerror());
+            Mmsg(dev->errmsg, "%s", dev->bstrerror());
+            Jmsg(jcr, M_ERROR, 0, "%s", dev->errmsg);
             block->read_len = 0;
             return false;
          }