X-Git-Url: https://git.sur5r.net/?a=blobdiff_plain;f=bacula%2Fsrc%2Fstored%2Fblock.c;h=b80c4a0737cafcf2e9a6660e30083bafe8b42cb2;hb=5ed1ee243e5d6c7da42dc043ea89e577851206ec;hp=bda9911ff500832510347d891adee06c969b3ced;hpb=fc38f5f8fd46fc30f7518db365758d20abd8de21;p=bacula%2Fbacula diff --git a/bacula/src/stored/block.c b/bacula/src/stored/block.c index bda9911ff5..b80c4a0737 100644 --- a/bacula/src/stored/block.c +++ b/bacula/src/stored/block.c @@ -1,3 +1,30 @@ +/* + Bacula® - The Network Backup Solution + + 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 three of the GNU Affero General Public + License as published by the Free Software Foundation and included + in the file LICENSE. + + 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 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. + + 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. +*/ /* * * block.c -- tape block handling functions @@ -5,29 +32,25 @@ * Kern Sibbald, March MMI * added BB02 format October MMII * - * Version $Id$ - * */ -/* - Copyright (C) 2001-2005 Kern Sibbald - This program is free software; you can redistribute it and/or - 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 - the file LICENSE for additional details. +#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 -#include "bacula.h" -#include "stored.h" -extern int debug_level; static bool terminate_writing_volume(DCR *dcr); static bool do_new_file_bookkeeping(DCR *dcr); static bool do_dvd_size_checks(DCR *dcr); @@ -49,6 +72,7 @@ void dump_block(DEV_BLOCK *b, const char *msg) int32_t FileIndex; int32_t Stream; int bhl, rhl; + char buf1[100], buf2[100]; unser_begin(b->buf, BLKHDR1_LENGTH); unser_uint32(CheckSum); @@ -68,15 +92,15 @@ 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; } BlockCheckSum = bcrc32((uint8_t *)b->buf+BLKHDR_CS_LENGTH, block_len-BLKHDR_CS_LENGTH); - Pmsg6(000, "Dump block %s %x: size=%d BlkNum=%d\n" -" Hdrcksum=%x cksum=%x\n", + Pmsg6(000, _("Dump block %s %x: size=%d BlkNum=%d\n" +" Hdrcksum=%x cksum=%x\n"), msg, b, block_len, BlockNumber, CheckSum, BlockCheckSum); p = b->buf + bhl; while (p < (b->buf + block_len+WRITE_RECHDR_LENGTH)) { @@ -88,9 +112,9 @@ void dump_block(DEV_BLOCK *b, const char *msg) unser_int32(FileIndex); unser_int32(Stream); unser_uint32(data_len); - Pmsg6(000, " Rec: VId=%u VT=%u FI=%s Strm=%s len=%d p=%x\n", - VolSessionId, VolSessionTime, FI_to_ascii(FileIndex), - stream_to_ascii(Stream, FileIndex), data_len, p); + Pmsg6(000, _(" Rec: VId=%u VT=%u FI=%s Strm=%s len=%d p=%x\n"), + VolSessionId, VolSessionTime, FI_to_ascii(buf1, FileIndex), + stream_to_ascii(buf2, Stream, FileIndex), data_len, p); p += data_len + rhl; } } @@ -154,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 */ @@ -176,7 +202,7 @@ void empty_block(DEV_BLOCK *block) * in the buffer should have already been reserved by * init_block. */ -void ser_block_header(DEV_BLOCK *block) +static uint32_t ser_block_header(DEV_BLOCK *block, bool do_checksum) { ser_declare; uint32_t CheckSum = 0; @@ -194,11 +220,14 @@ void ser_block_header(DEV_BLOCK *block) } /* Checksum whole block except for the checksum */ - CheckSum = bcrc32((uint8_t *)block->buf+BLKHDR_CS_LENGTH, - block_len-BLKHDR_CS_LENGTH); + if (do_checksum) { + CheckSum = bcrc32((uint8_t *)block->buf+BLKHDR_CS_LENGTH, + block_len-BLKHDR_CS_LENGTH); + } 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; } /* @@ -260,6 +289,7 @@ static bool unser_block_header(JCR *jcr, DEVICE *dev, DEV_BLOCK *block) dev->dev_errno = EIO; Mmsg4(dev->errmsg, _("Volume data error at %u:%u! Wanted ID: \"%s\", got \"%s\". Buffer discarded.\n"), dev->file, dev->block_num, BLKHDR2_ID, Id); + Dmsg1(50, "%s", dev->errmsg); if (block->read_errors == 0 || verbose >= 2) { Jmsg(jcr, M_ERROR, 0, "%s", dev->errmsg); } @@ -293,7 +323,7 @@ static bool unser_block_header(JCR *jcr, DEVICE *dev, DEV_BLOCK *block) block->BlockNumber = BlockNumber; Dmsg3(390, "Read binbuf = %d %d block_len=%d\n", block->binbuf, bhl, block_len); - if (block_len <= block->read_len) { + if (block_len <= block->read_len && dev->do_checksum()) { BlockCheckSum = bcrc32((uint8_t *)block->buf+BLKHDR_CS_LENGTH, block_len-BLKHDR_CS_LENGTH); if (BlockCheckSum != CheckSum) { @@ -304,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) { @@ -321,19 +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->dev_locked) { - lock_device(dev); + if (!dcr->is_dev_locked()) { /* device already locked? */ + /* note, do not change this to dcr->r_dlock */ + dev->r_dlock(); /* no, lock it */ } /* @@ -345,28 +377,29 @@ 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; - Jmsg(jcr, M_FATAL, 0, _("Could not create JobMedia record for Volume=\"%s\" Job=%s\n"), - dcr->VolCatInfo.VolCatName, jcr->Job); + Jmsg2(jcr, M_FATAL, 0, _("Could not create JobMedia record for Volume=\"%s\" Job=%s\n"), + dcr->getVolCatName(), jcr->Job); set_new_volume_parameters(dcr); stat = false; + Dmsg0(100, "cannot create media record\n"); goto bail_out; } if (dcr->NewVol) { /* Note, setting a new volume also handles any pending new file */ set_new_volume_parameters(dcr); - dcr->NewFile = false; /* this handled for new file too */ } else { set_new_file_parameters(dcr); } } - if (!write_block_to_dev(dcr)) { - if (job_canceled(jcr) || jcr->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); @@ -374,8 +407,9 @@ bool write_block_to_device(DCR *dcr) } bail_out: - if (!dcr->dev_locked) { - unlock_device(dev); + if (!dcr->is_dev_locked()) { /* did we lock dev above? */ + /* note, do not change this to dcr->dunlock */ + dev->dunlock(); /* unlock it now */ } return stat; } @@ -386,39 +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; + + if (no_tape_write_test) { + empty_block(block); + return true; + } + if (job_canceled(jcr)) { + return false; + } -#ifdef NO_TAPE_WRITE_TEST - empty_block(block); - return true; -#endif ASSERT(block->binbuf == ((uint32_t) (block->bufp - block->buf))); + 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; - Jmsg(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. @@ -426,7 +473,7 @@ bool write_block_to_dev(DCR *dcr) if (wlen != block->buf_len) { uint32_t blen; /* current buffer length */ - Dmsg2(200, "binbuf=%d buf_len=%d\n", block->binbuf, block->buf_len); + Dmsg2(250, "binbuf=%d buf_len=%d\n", block->binbuf, block->buf_len); blen = wlen; /* Adjust write size to min/max for tapes only */ @@ -447,7 +494,7 @@ bool write_block_to_dev(DCR *dcr) } } - ser_block_header(block); + checksum = ser_block_header(block, dev->do_checksum()); /* Limit maximum Volume size to value specified by user */ hit_max1 = (dev->max_volume_size > 0) && @@ -457,7 +504,7 @@ bool write_block_to_dev(DCR *dcr) if (hit_max1 || hit_max2) { char ed1[50]; uint64_t max_cap; - Dmsg0(10, "==== Output bytes Triggered medium max capacity.\n"); + Dmsg0(100, "==== Output bytes Triggered medium max capacity.\n"); if (hit_max1) { max_cap = dev->max_volume_size; } else { @@ -476,10 +523,10 @@ bool write_block_to_dev(DCR *dcr) (dev->file_size+block->binbuf) >= dev->max_file_size) { dev->file_size = 0; /* reset file size */ - if (weof_dev(dev, 1) != 0) { /* write eof */ - Dmsg0(190, "WEOF error in max file size.\n"); + if (!dev->weof(1)) { /* write eof */ + Dmsg0(50, "WEOF error in max file size.\n"); Jmsg(jcr, M_FATAL, 0, _("Unable to write EOF. ERR=%s\n"), - strerror_dev(dev)); + dev->bstrerror()); terminate_writing_volume(dcr); dev->dev_errno = ENOSPC; return false; @@ -504,18 +551,41 @@ bool write_block_to_dev(DCR *dcr) #ifdef DEBUG_BLOCK_ZEROING uint32_t *bp = (uint32_t *)block->buf; if (bp[0] == 0 && bp[1] == 0 && bp[2] == 0 && block->buf[12] == 0) { - Jmsg0(jcr, M_ABORT, 0, "Write block header zeroed.\n"); + Jmsg0(jcr, M_ABORT, 0, _("Write block header zeroed.\n")); } #endif /* - * Do write here + * Do write here, make a somewhat feeble attempt to recover from + * I/O errors, or from the OS telling us it is busy. */ - stat = write(dev->fd, block->buf, (size_t)wlen); + int retry = 0; + errno = 0; + stat = 0; + do { + if (retry > 0 && stat == -1 && errno == EBUSY) { + berrno be; + Dmsg4(100, "===== write retry=%d stat=%d errno=%d: ERR=%s\n", + retry, stat, errno, be.bstrerror()); + bmicrosleep(5, 0); /* pause a bit if busy or lots of errors */ + dev->clrerror(-1); + } + stat = dev->write(block->buf, (size_t)wlen); + + } 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"); + Jmsg0(jcr, M_ABORT, 0, _("Write block header zeroed.\n")); } #endif @@ -528,25 +598,29 @@ bool write_block_to_dev(DCR *dcr) */ if (stat == -1) { berrno be; - clrerror_dev(dev, -1); + dev->clrerror(-1); if (dev->dev_errno == 0) { dev->dev_errno = ENOSPC; /* out of space */ } if (dev->dev_errno != ENOSPC) { + dev->VolCatInfo.VolCatErrors++; Jmsg4(jcr, M_ERROR, 0, _("Write error at %u:%u on device %s. ERR=%s.\n"), - dev->file, dev->block_num, dev->print_name(), be.strerror()); + dev->file, dev->block_num, dev->print_name(), be.bstrerror()); } } else { dev->dev_errno = ENOSPC; /* out of space */ } 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); } - Dmsg7(100, "=== Write error. fd=%d size=%u rtn=%d dev_blk=%d blk_blk=%d errno=%d: ERR=%s\n", - dev->fd, wlen, stat, dev->block_num, block->BlockNumber, - dev->dev_errno, strerror(dev->dev_errno)); + if (debug_level >= 100) { + berrno be; + Dmsg7(100, "=== Write error. fd=%d size=%u rtn=%d dev_blk=%d blk_blk=%d errno=%d: ERR=%s\n", + dev->fd(), wlen, stat, dev->block_num, block->BlockNumber, + dev->dev_errno, be.bstrerror(dev->dev_errno)); + } ok = terminate_writing_volume(dcr); if (!ok && !forge_on) { @@ -559,18 +633,20 @@ bool write_block_to_dev(DCR *dcr) } /* We successfully wrote the block, now do housekeeping */ - - dev->VolCatInfo.VolCatBytes += block->binbuf; + Dmsg2(1300, "VolCatBytes=%d newVolCatBytes=%d\n", (int)dev->VolCatInfo.VolCatBytes, + (int)(dev->VolCatInfo.VolCatBytes+wlen)); + dev->VolCatInfo.VolCatBytes += wlen; dev->VolCatInfo.VolCatBlocks++; dev->EndBlock = dev->block_num; dev->EndFile = dev->file; - dev->block_num++; + dev->LastBlock = block->BlockNumber; block->BlockNumber++; /* Update dcr values */ if (dev->is_tape()) { dcr->EndBlock = dev->EndBlock; dcr->EndFile = dev->EndFile; + dev->block_num++; } else { /* Save address of block just written */ uint64_t addr = dev->file_addr + wlen - 1; @@ -579,6 +655,7 @@ bool write_block_to_dev(DCR *dcr) dev->block_num = dcr->EndBlock; dev->file = dcr->EndFile; } + dcr->VolMediaId = dev->VolCatInfo.VolMediaId; if (dcr->VolFirstIndex == 0 && block->FirstIndex > 0) { dcr->VolFirstIndex = block->FirstIndex; } @@ -610,33 +687,33 @@ static void reread_last_block(DCR *dcr) * then re-read it and verify that the block number is * correct. */ - if (dev->is_tape() && dev_cap(dev, CAP_BSR)) { + if (dev->is_tape() && dev->has_cap(CAP_BSR)) { /* Now back up over what we wrote and read the last block */ - if (!bsf_dev(dev, 1)) { + if (!dev->bsf(1)) { berrno be; ok = false; Jmsg(jcr, M_ERROR, 0, _("Backspace file at EOT failed. ERR=%s\n"), - be.strerror(dev->dev_errno)); + be.bstrerror(dev->dev_errno)); } - if (ok && dev_cap(dev, CAP_TWOEOF) && !bsf_dev(dev, 1)) { + if (ok && dev->has_cap(CAP_TWOEOF) && !dev->bsf(1)) { berrno be; ok = false; Jmsg(jcr, M_ERROR, 0, _("Backspace file at EOT failed. ERR=%s\n"), - be.strerror(dev->dev_errno)); + be.bstrerror(dev->dev_errno)); } /* Backspace over record */ - if (ok && !bsr_dev(dev, 1)) { + if (ok && !dev->bsr(1)) { berrno be; ok = false; Jmsg(jcr, M_ERROR, 0, _("Backspace record at EOT failed. ERR=%s\n"), - be.strerror(dev->dev_errno)); + be.bstrerror(dev->dev_errno)); /* * On FreeBSD systems, if the user got here, it is likely that his/her * tape drive is "frozen". The correct thing to do is a * rewind(), but if we do that, higher levels in cleaning up, will * most likely write the EOS record over the beginning of the * tape. The rewind *is* done later in mount.c when another - * tape is requested. Note, the clrerror_dev() call in bsr_dev() + * tape is requested. Note, the clrerror() call in bsr() * calls ioctl(MTCERRSTAT), which *should* fix the problem. */ } @@ -644,16 +721,27 @@ 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 { - if (lblock->BlockNumber+1 == block->BlockNumber) { - Jmsg(jcr, M_INFO, 0, _("Re-read of last block succeeded.\n")); + /* + * If we wrote block and the block numbers don't agree + * we have a possible problem. + */ + if (lblock->BlockNumber != dev->LastBlock) { + if (dev->LastBlock > (lblock->BlockNumber + 1)) { + Jmsg(jcr, M_FATAL, 0, _( +"Re-read of last block: block numbers differ by more than one.\n" +"Probable tape misconfiguration and data loss. Read block=%u Want block=%u.\n"), + lblock->BlockNumber, dev->LastBlock); + } else { + Jmsg(jcr, M_ERROR, 0, _( +"Re-read of last block OK, but block numbers differ. Read block=%u Want block=%u.\n"), + lblock->BlockNumber, dev->LastBlock); + } } else { - Jmsg(jcr, M_ERROR, 0, _( -"Re-read of last block failed. Last block=%u Current block=%u.\n"), - lblock->BlockNumber, block->BlockNumber); + Jmsg(jcr, M_INFO, 0, _("Re-read of last block succeeded.\n")); } } free_block(lblock); @@ -663,6 +751,11 @@ static void reread_last_block(DCR *dcr) #endif } +/* + * If this routine is called, we do our bookkeeping and + * then assure that the volume will not be written any + * more. + */ static bool terminate_writing_volume(DCR *dcr) { DEVICE *dev = dcr->dev; @@ -671,36 +764,45 @@ 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; - Jmsg(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; - goto bail_out; } dcr->block->write_failed = true; - if (weof_dev(dev, 1) != 0) { /* end the tape */ + if (!dev->weof(1)) { /* end the tape */ dev->VolCatInfo.VolCatErrors++; - Jmsg(dcr->jcr, M_ERROR, 0, "Error writing final EOF to tape. This tape may not be readable.\n" - "%s", dev->errmsg); + 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); } bstrncpy(dev->VolCatInfo.VolCatStatus, "Full", sizeof(dev->VolCatInfo.VolCatStatus)); dev->VolCatInfo.VolCatFiles = dev->file; /* set number of files */ - dev->VolCatInfo.VolCatJobs++; /* increment number of jobs */ - if (dev->is_dvd()) { /* Write the current (and last) part. */ - open_next_part(dcr); + if (dev->is_dvd()) { + if (!dvd_write_part(dcr)) { /* write last part */ + dev->VolCatInfo.VolCatErrors++; + Jmsg(dcr->jcr, M_FATAL, 0, _("Error writing final part to DVD. " + "This Volume may not be readable.\n%s"), + dev->errmsg); + ok = false; + Dmsg0(100, "dvd_write_part error.\n"); + } + dev->VolCatInfo.VolCatParts = dev->num_dvd_parts; } - if (!dir_update_volume_info(dcr, false)) { + 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 @@ -716,14 +818,15 @@ static bool terminate_writing_volume(DCR *dcr) /* Set new file/block parameters for current dcr */ set_new_file_parameters(dcr); - if (ok && dev_cap(dev, CAP_TWOEOF) && weof_dev(dev, 1) != 0) { /* end the tape */ + if (ok && dev->has_cap(CAP_TWOEOF) && !dev->weof(1)) { /* end the tape */ 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"); } -bail_out: + dev->set_ateot(); /* no more writing this tape */ - Dmsg1(100, "Leave terminate_writing_volume -- %s\n", ok?"OK":"ERROR"); + Dmsg1(50, "*** Leave terminate_writing_volume -- %s\n", ok?"OK":"ERROR"); return ok; } @@ -739,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; - Jmsg(jcr, M_FATAL, 0, _("Could not create JobMedia record for Volume=\"%s\" Job=%s\n"), - dcr->VolCatInfo.VolCatName, jcr->Job); - terminate_writing_volume(dcr); - dev->dev_errno = EIO; - return false; + Jmsg2(jcr, M_FATAL, 0, _("Could not create JobMedia record for Volume=\"%s\" Job=%s\n"), + 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)) { - Dmsg0(190, "Error from update_vol_info.\n"); + if (!dir_update_volume_info(dcr, false, false)) { + Dmsg0(50, "Error from update_vol_info.\n"); terminate_writing_volume(dcr); dev->dev_errno = EIO; return false; @@ -781,54 +884,59 @@ static bool do_dvd_size_checks(DCR *dcr) JCR *jcr = dcr->jcr; DEV_BLOCK *block = dcr->block; + /* Don't go further if the device is not a dvd */ + if (!dev->is_dvd()) { + return true; + } + /* Limit maximum part size to value specified by user - * (not applicable to tapes/fifos) */ - if (!(dev->is_tape() || dev->is_fifo()) && dev->max_part_size > 0 && - (dev->part_size + block->binbuf) >= dev->max_part_size) { - if (dev->part < dev->num_parts) { + if (dev->max_part_size > 0 && ((dev->part_size + block->binbuf) >= dev->max_part_size)) { + if (dev->part < dev->num_dvd_parts) { Jmsg3(dcr->jcr, M_FATAL, 0, _("Error while writing, current part number" " is less than the total number of parts (%d/%d, device=%s)\n"), - dev->part, dev->num_parts, dev->print_name()); + dev->part, dev->num_dvd_parts, dev->print_name()); dev->dev_errno = EIO; return false; } - if (open_next_part(dcr) < 0) { + if (dvd_open_next_part(dcr) < 0) { Jmsg2(dcr->jcr, M_FATAL, 0, _("Unable to open device next part %s: ERR=%s\n"), - dev->print_name(), strerror_dev(dev)); + dev->print_name(), dev->bstrerror()); dev->dev_errno = EIO; return false; } - dev->VolCatInfo.VolCatParts = dev->num_parts; + dev->VolCatInfo.VolCatParts = dev->num_dvd_parts; - if (!dir_update_volume_info(dcr, false)) { + if (!dir_update_volume_info(dcr, false, false)) { Dmsg0(190, "Error from update_vol_info.\n"); dev->dev_errno = EIO; return false; } } + + dev->update_freespace(); - if (dev->free_space_errno < 0) { /* Error while getting free space */ + if (!dev->is_freespace_ok()) { /* Error while getting free space */ char ed1[50], ed2[50]; - Dmsg1(10, "Cannot get free space on the device ERR=%s.\n", dev->errmsg); + 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); - dev->dev_errno = -dev->free_space_errno; + dev->dev_errno = dev->free_space_errno; return false; } - if ((dev->free_space_errno > 0 && (dev->part_size + block->binbuf) >= dev->free_space)) { + if ((dev->is_freespace_ok() && (dev->part_size + block->binbuf) >= dev->free_space)) { char ed1[50], ed2[50]; - Dmsg0(10, "==== Just enough free space on the device to write the current part...\n"); + 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); @@ -844,15 +952,15 @@ 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(200, "Enter read_block_from_device\n"); - lock_device(dev); - ok = read_block_from_dev(dcr, check_block_numbers); - unlock_device(dev); - Dmsg0(200, "Leave read_block_from_device\n"); + + Dmsg0(250, "Enter read_block_from_device\n"); + dev->r_dlock(); + ok = read_block_from_dev(check_block_numbers); + dev->dunlock(); + Dmsg0(250, "Leave read_block_from_device\n"); return ok; } @@ -861,22 +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; + } 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(200, "Full read() in read_block_from_device() len=%d\n", + 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; @@ -887,59 +1009,47 @@ reread: return false; } - /*Dmsg1(100, "dev->file_size=%u\n",(unsigned int)dev->file_size); - Dmsg1(100, "dev->file_addr=%u\n",(unsigned int)dev->file_addr); - Dmsg1(100, "lseek=%u\n",(unsigned int)lseek(dev->fd, 0, SEEK_CUR)); - Dmsg1(100, "dev->part_start=%u\n",(unsigned int)dev->part_start); - Dmsg1(100, "dev->file_addr-dev->part_start=%u\n",(unsigned int)dev->file_addr-dev->part_start); - Dmsg1(100, "dev->file_size-dev->part_start=%u\n",(unsigned int)dev->file_size-dev->part_start); - Dmsg1(100, "dev->part_size=%u\n", (unsigned int)dev->part_size); - Dmsg1(100, "dev->part=%u\n", (unsigned int)dev->part); - Dmsg1(100, "dev->num_parts=%u\n", (unsigned int)dev->num_parts); - Dmsg1(100, "dev->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));*/ - /* Check for part file end */ - if ((dev->num_parts > 0) && - ((dev->file_addr-dev->part_start) == dev->part_size) && - (dev->part < dev->num_parts)) { - if (open_next_part(dcr) < 0) { - Jmsg2(dcr->jcr, M_FATAL, 0, _("Unable to open device next part %s: ERR=%s\n"), - dev->print_name(), strerror_dev(dev)); + /* 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) { + 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; } } retry = 0; + errno = 0; + stat = 0; do { -// uint32_t *bp = (uint32_t *)block->buf; -// Pmsg3(000, "Read %p %u at %llu\n", block->buf, block->buf_len, lseek(dev->fd, 0, SEEK_CUR)); - - stat = read(dev->fd, block->buf, (size_t)block->buf_len); - -// Pmsg8(000, "stat=%d Csum=%u blen=%u bnum=%u %c%c%c%c\n",stat, bp[0],bp[1],bp[2], -// block->buf[12],block->buf[13],block->buf[14],block->buf[15]); - - if (retry == 1) { - dev->VolCatInfo.VolCatErrors++; + if ((retry > 0 && stat == -1 && errno == EBUSY)) { + berrno be; + Dmsg4(100, "===== read retry=%d stat=%d errno=%d: ERR=%s\n", + retry, stat, errno, be.bstrerror()); + bmicrosleep(10, 0); /* pause a bit if busy or lots of errors */ + dev->clrerror(-1); } - } while (stat == -1 && (errno == EINTR || errno == EIO) && retry++ < 11); + stat = dev->read(block->buf, (size_t)block->buf_len); + + } while (stat == -1 && (errno == EBUSY || errno == EINTR || errno == EIO) && retry++ < 3); if (stat < 0) { berrno be; - clrerror_dev(dev, -1); - Dmsg1(200, "Read device got: ERR=%s\n", be.strerror()); + dev->clrerror(-1); + Dmsg1(250, "Read device got: ERR=%s\n", be.bstrerror()); block->read_len = 0; - Mmsg4(dev->errmsg, _("Read error at file:blk %u:%u on device %s. ERR=%s.\n"), - dev->file, dev->block_num, dev->print_name(), be.strerror()); + Mmsg5(dev->errmsg, _("Read error on fd=%d at file:blk %u:%u on device %s. ERR=%s.\n"), + dev->fd(), dev->file, dev->block_num, dev->print_name(), be.bstrerror()); Jmsg(jcr, M_ERROR, 0, "%s", dev->errmsg); if (dev->at_eof()) { /* EOF just seen? */ dev->set_eot(); /* yes, error => EOT */ } return false; } - Dmsg3(200, "Read device got %d bytes at %u:%u\n", stat, + Dmsg3(250, "Read device got %d bytes at %u:%u\n", stat, dev->file, dev->block_num); if (stat == 0) { /* Got EOF ! */ dev->block_num = 0; @@ -953,8 +1063,19 @@ reread: dev->set_ateof(); return false; /* return eof */ } + /* Continue here for successful read */ + block->read_len = stat; /* save length read */ + if (block->read_len == 80 && + (dcr->VolCatInfo.LabelType != B_BACULA_LABEL || + dcr->device->label_type != B_BACULA_LABEL)) { + /* ***FIXME*** should check label */ + Dmsg2(100, "Ignore 80 byte ANSI label at %u:%u\n", dev->file, dev->block_num); + dev->clear_eof(); + goto reread; /* skip ANSI/IBM label */ + } + if (block->read_len < BLKHDR2_LENGTH) { dev->dev_errno = EIO; Mmsg4(dev->errmsg, _("Volume data error at %u:%u! Very short block of %d bytes on device %s discarded.\n"), @@ -962,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; @@ -988,17 +1110,18 @@ reread: Pmsg1(000, "%s", dev->errmsg); /* Attempt to reposition to re-read the block */ if (dev->is_tape()) { - Dmsg0(200, "BSR for reread; block too big for buffer.\n"); - if (!bsr_dev(dev, 1)) { - Jmsg(jcr, M_ERROR, 0, "%s", strerror_dev(dev)); + Dmsg0(250, "BSR for reread; block too big for buffer.\n"); + if (!dev->bsr(1)) { + Mmsg(dev->errmsg, "%s", dev->bstrerror()); + Jmsg(jcr, M_ERROR, 0, "%s", dev->errmsg); block->read_len = 0; return false; } } else { - Dmsg0(200, "Seek to beginning of block for reread.\n"); - off_t pos = lseek_dev(dev, (off_t)0, SEEK_CUR); /* get curr pos */ + Dmsg0(250, "Seek to beginning of block for reread.\n"); + boffset_t pos = dev->lseek(dcr, (boffset_t)0, SEEK_CUR); /* get curr pos */ pos -= block->read_len; - lseek_dev(dev, pos, SEEK_SET); + dev->lseek(dcr, pos, SEEK_SET); dev->file_addr = pos; } Mmsg1(dev->errmsg, _("Setting block buffer size to %u bytes.\n"), block->block_len); @@ -1029,8 +1152,6 @@ reread: dev->VolCatInfo.VolCatReads++; dev->VolCatInfo.VolCatRBytes += block->read_len; - dev->VolCatInfo.VolCatBytes += block->block_len; - dev->VolCatInfo.VolCatBlocks++; dev->EndBlock = dev->block_num; dev->EndFile = dev->file; dev->block_num++; @@ -1040,12 +1161,17 @@ reread: dcr->EndBlock = dev->EndBlock; dcr->EndFile = dev->EndFile; } else { - uint64_t addr = dev->file_addr + block->read_len - 1; + /* We need to take care about a short block in EndBlock/File + * computation + */ + uint32_t len = MIN(block->read_len, block->block_len); + uint64_t addr = dev->file_addr + len - 1; dcr->EndBlock = (uint32_t)addr; dcr->EndFile = (uint32_t)(addr >> 32); - dev->block_num = dcr->EndBlock; - dev->file = dcr->EndFile; + dev->block_num = dev->EndBlock = dcr->EndBlock; + dev->file = dev->EndFile = dcr->EndFile; } + dcr->VolMediaId = dev->VolCatInfo.VolMediaId; dev->file_addr += block->read_len; dev->file_size += block->read_len; @@ -1062,19 +1188,20 @@ reread: * lseek(). One to get the position, then the second to do an * absolute positioning -- so much for efficiency. KES Sep 02. */ - Dmsg0(200, "At end of read block\n"); + Dmsg0(250, "At end of read block\n"); if (block->read_len > block->block_len && !dev->is_tape()) { char ed1[50]; - off_t pos = lseek_dev(dev, (off_t)0, SEEK_CUR); /* get curr pos */ + boffset_t pos = dev->lseek(dcr, (boffset_t)0, SEEK_CUR); /* get curr pos */ + Dmsg1(250, "Current lseek pos=%s\n", edit_int64(pos, ed1)); pos -= (block->read_len - block->block_len); - lseek_dev(dev, pos, SEEK_SET); - Dmsg3(200, "Did lseek pos=%s blk_size=%d rdlen=%d\n", - edit_uint64(pos, ed1), block->block_len, + dev->lseek(dcr, pos, SEEK_SET); + Dmsg3(250, "Did lseek pos=%s blk_size=%d rdlen=%d\n", + edit_int64(pos, ed1), block->block_len, block->read_len); dev->file_addr = pos; dev->file_size = pos; } - Dmsg2(200, "Exit read_block read_len=%d block_len=%d\n", + Dmsg2(250, "Exit read_block read_len=%d block_len=%d\n", block->read_len, block->block_len); block->block_read = true; return true;