]> git.sur5r.net Git - bacula/bacula/blob - bacula/src/stored/block.c
Add block checksum debug code
[bacula/bacula] / bacula / src / stored / block.c
1 /*
2    Bacula® - The Network Backup Solution
3
4    Copyright (C) 2001-2012 Free Software Foundation Europe e.V.
5
6    The main author of Bacula is Kern Sibbald, with contributions from
7    many others, a complete list can be found in the file AUTHORS.
8    This program is Free Software; you can redistribute it and/or
9    modify it under the terms of version three of the GNU Affero General Public
10    License as published by the Free Software Foundation and included
11    in the file LICENSE.
12
13    This program is distributed in the hope that it will be useful, but
14    WITHOUT ANY WARRANTY; without even the implied warranty of
15    MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the GNU
16    General Public License for more details.
17
18    You should have received a copy of the GNU Affero General Public License
19    along with this program; if not, write to the Free Software
20    Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA
21    02110-1301, USA.
22
23    Bacula® is a registered trademark of Kern Sibbald.
24    The licensor of Bacula is the Free Software Foundation Europe
25    (FSFE), Fiduciary Program, Sumatrastrasse 25, 8006 Zürich,
26    Switzerland, email:ftf@fsfeurope.org.
27 */
28 /*
29  *
30  *   block.c -- tape block handling functions
31  *
32  *              Kern Sibbald, March MMI
33  *                 added BB02 format October MMII
34  *
35  */
36
37
38 #include "bacula.h"
39 #include "stored.h"
40
41 static bool terminate_writing_volume(DCR *dcr);
42 static bool do_new_file_bookkeeping(DCR *dcr);
43 static bool do_dvd_size_checks(DCR *dcr);
44 static void reread_last_block(DCR *dcr);
45
46 /*
47  * Dump the block header, then walk through
48  * the block printing out the record headers.
49  */
50 void dump_block(DEV_BLOCK *b, const char *msg)
51 {
52    ser_declare;
53    char *p;
54    char Id[BLKHDR_ID_LENGTH+1];
55    uint32_t CheckSum, BlockCheckSum;
56    uint32_t block_len;
57    uint32_t BlockNumber;
58    uint32_t VolSessionId, VolSessionTime, data_len;
59    int32_t  FileIndex;
60    int32_t  Stream;
61    int bhl, rhl;
62    char buf1[100], buf2[100];
63
64    unser_begin(b->buf, BLKHDR1_LENGTH);
65    unser_uint32(CheckSum);
66    unser_uint32(block_len);
67    unser_uint32(BlockNumber);
68    unser_bytes(Id, BLKHDR_ID_LENGTH);
69    ASSERT(unser_length(b->buf) == BLKHDR1_LENGTH);
70    Id[BLKHDR_ID_LENGTH] = 0;
71    if (Id[3] == '2') {
72       unser_uint32(VolSessionId);
73       unser_uint32(VolSessionTime);
74       bhl = BLKHDR2_LENGTH;
75       rhl = RECHDR2_LENGTH;
76    } else {
77       VolSessionId = VolSessionTime = 0;
78       bhl = BLKHDR1_LENGTH;
79       rhl = RECHDR1_LENGTH;
80    }
81
82    if (block_len > 4000000) {
83       Dmsg3(20, "Dump block %s 0x%x blocksize too big %u\n", msg, b, block_len);
84       return;
85    }
86
87    BlockCheckSum = bcrc32((uint8_t *)b->buf+BLKHDR_CS_LENGTH,
88                          block_len-BLKHDR_CS_LENGTH);
89    Pmsg6(000, _("Dump block %s %x: size=%d BlkNum=%d\n"
90 "               Hdrcksum=%x cksum=%x\n"),
91       msg, b, block_len, BlockNumber, CheckSum, BlockCheckSum);
92    p = b->buf + bhl;
93    while (p < (b->buf + block_len+WRITE_RECHDR_LENGTH)) {
94       unser_begin(p, WRITE_RECHDR_LENGTH);
95       if (rhl == RECHDR1_LENGTH) {
96          unser_uint32(VolSessionId);
97          unser_uint32(VolSessionTime);
98       }
99       unser_int32(FileIndex);
100       unser_int32(Stream);
101       unser_uint32(data_len);
102       Pmsg6(000, _("   Rec: VId=%u VT=%u FI=%s Strm=%s len=%d p=%x\n"),
103            VolSessionId, VolSessionTime, FI_to_ascii(buf1, FileIndex),
104            stream_to_ascii(buf2, Stream, FileIndex), data_len, p);
105       p += data_len + rhl;
106   }
107 }
108
109 /*
110  * Create a new block structure.
111  * We pass device so that the block can inherit the
112  * min and max block sizes.
113  */
114 DEV_BLOCK *new_block(DEVICE *dev)
115 {
116    DEV_BLOCK *block = (DEV_BLOCK *)get_memory(sizeof(DEV_BLOCK));
117
118    memset(block, 0, sizeof(DEV_BLOCK));
119
120    /* If the user has specified a max_block_size, use it as the default */
121    if (dev->max_block_size == 0) {
122       block->buf_len = DEFAULT_BLOCK_SIZE;
123    } else {
124       block->buf_len = dev->max_block_size;
125    }
126    block->dev = dev;
127    block->block_len = block->buf_len;  /* default block size */
128    block->buf = get_memory(block->buf_len);
129    empty_block(block);
130    block->BlockVer = BLOCK_VER;       /* default write version */
131    Dmsg1(650, "Returning new block=%x\n", block);
132    return block;
133 }
134
135
136 /*
137  * Duplicate an existing block (eblock)
138  */
139 DEV_BLOCK *dup_block(DEV_BLOCK *eblock)
140 {
141    DEV_BLOCK *block = (DEV_BLOCK *)get_memory(sizeof(DEV_BLOCK));
142    int buf_len = sizeof_pool_memory(eblock->buf);
143
144    memcpy(block, eblock, sizeof(DEV_BLOCK));
145    block->buf = get_memory(buf_len);
146    memcpy(block->buf, eblock->buf, buf_len);
147    return block;
148 }
149
150
151 /*
152  * Only the first block checksum error was reported.
153  *   If there are more, report it now.
154  */
155 void print_block_read_errors(JCR *jcr, DEV_BLOCK *block)
156 {
157    if (block->read_errors > 1) {
158       Jmsg(jcr, M_ERROR, 0, _("%d block read errors not printed.\n"),
159          block->read_errors);
160    }
161 }
162
163 /*
164  * Free block
165  */
166 void free_block(DEV_BLOCK *block)
167 {
168    Dmsg1(999, "free_block buffer %x\n", block->buf);
169    free_memory(block->buf);
170    Dmsg1(999, "free_block block %x\n", block);
171    free_memory((POOLMEM *)block);
172 }
173
174 /* Empty the block -- for writing */
175 void empty_block(DEV_BLOCK *block)
176 {
177    block->binbuf = WRITE_BLKHDR_LENGTH;
178    block->bufp = block->buf + block->binbuf;
179    block->read_len = 0;
180    block->write_failed = false;
181    block->block_read = false;
182    block->FirstIndex = block->LastIndex = 0;
183 }
184
185 /*
186  * Create block header just before write. The space
187  * in the buffer should have already been reserved by
188  * init_block.
189  */
190 static uint32_t ser_block_header(DEV_BLOCK *block, bool do_checksum)
191 {
192    ser_declare;
193    uint32_t CheckSum = 0;
194    uint32_t block_len = block->binbuf;
195
196    Dmsg1(1390, "ser_block_header: block_len=%d\n", block_len);
197    ser_begin(block->buf, BLKHDR2_LENGTH);
198    ser_uint32(CheckSum);
199    ser_uint32(block_len);
200    ser_uint32(block->BlockNumber);
201    ser_bytes(WRITE_BLKHDR_ID, BLKHDR_ID_LENGTH);
202    if (BLOCK_VER >= 2) {
203       ser_uint32(block->VolSessionId);
204       ser_uint32(block->VolSessionTime);
205    }
206
207    /* Checksum whole block except for the checksum */
208    if (do_checksum) {
209       CheckSum = bcrc32((uint8_t *)block->buf+BLKHDR_CS_LENGTH,
210                     block_len-BLKHDR_CS_LENGTH);
211    }
212    Dmsg1(1390, "ser_bloc_header: checksum=%x\n", CheckSum);
213    ser_begin(block->buf, BLKHDR2_LENGTH);
214    ser_uint32(CheckSum);              /* now add checksum to block header */
215    return CheckSum;
216 }
217
218 /*
219  * Unserialize the block header for reading block.
220  *  This includes setting all the buffer pointers correctly.
221  *
222  *  Returns: false on failure (not a block)
223  *           true  on success
224  */
225 static bool unser_block_header(JCR *jcr, DEVICE *dev, DEV_BLOCK *block)
226 {
227    ser_declare;
228    char Id[BLKHDR_ID_LENGTH+1];
229    uint32_t CheckSum, BlockCheckSum;
230    uint32_t block_len;
231    uint32_t block_end;
232    uint32_t BlockNumber;
233    int bhl;
234
235    unser_begin(block->buf, BLKHDR_LENGTH);
236    unser_uint32(CheckSum);
237    unser_uint32(block_len);
238    unser_uint32(BlockNumber);
239    unser_bytes(Id, BLKHDR_ID_LENGTH);
240    ASSERT(unser_length(block->buf) == BLKHDR1_LENGTH);
241
242    Id[BLKHDR_ID_LENGTH] = 0;
243    if (Id[3] == '1') {
244       bhl = BLKHDR1_LENGTH;
245       block->BlockVer = 1;
246       block->bufp = block->buf + bhl;
247       if (strncmp(Id, BLKHDR1_ID, BLKHDR_ID_LENGTH) != 0) {
248          dev->dev_errno = EIO;
249          Mmsg4(dev->errmsg, _("Volume data error at %u:%u! Wanted ID: \"%s\", got \"%s\". Buffer discarded.\n"),
250             dev->file, dev->block_num, BLKHDR1_ID, Id);
251          if (block->read_errors == 0 || verbose >= 2) {
252             Jmsg(jcr, M_ERROR, 0, "%s", dev->errmsg);
253          }
254          block->read_errors++;
255          return false;
256       }
257    } else if (Id[3] == '2') {
258       unser_uint32(block->VolSessionId);
259       unser_uint32(block->VolSessionTime);
260       bhl = BLKHDR2_LENGTH;
261       block->BlockVer = 2;
262       block->bufp = block->buf + bhl;
263       if (strncmp(Id, BLKHDR2_ID, BLKHDR_ID_LENGTH) != 0) {
264          dev->dev_errno = EIO;
265          Mmsg4(dev->errmsg, _("Volume data error at %u:%u! Wanted ID: \"%s\", got \"%s\". Buffer discarded.\n"),
266             dev->file, dev->block_num, BLKHDR2_ID, Id);
267          if (block->read_errors == 0 || verbose >= 2) {
268             Jmsg(jcr, M_ERROR, 0, "%s", dev->errmsg);
269          }
270          block->read_errors++;
271          return false;
272       }
273    } else {
274       dev->dev_errno = EIO;
275       Mmsg4(dev->errmsg, _("Volume data error at %u:%u! Wanted ID: \"%s\", got \"%s\". Buffer discarded.\n"),
276           dev->file, dev->block_num, BLKHDR2_ID, Id);
277       Dmsg1(50, "%s", dev->errmsg);
278       if (block->read_errors == 0 || verbose >= 2) {
279          Jmsg(jcr, M_ERROR, 0, "%s", dev->errmsg);
280       }
281       block->read_errors++;
282       unser_uint32(block->VolSessionId);
283       unser_uint32(block->VolSessionTime);
284       return false;
285    }
286
287    /* Sanity check */
288    if (block_len > MAX_BLOCK_LENGTH) {
289       dev->dev_errno = EIO;
290       Mmsg3(dev->errmsg,  _("Volume data error at %u:%u! Block length %u is insane (too large), probably due to a bad archive.\n"),
291          dev->file, dev->block_num, block_len);
292       if (block->read_errors == 0 || verbose >= 2) {
293          Jmsg(jcr, M_ERROR, 0, "%s", dev->errmsg);
294       }
295       block->read_errors++;
296       return false;
297    }
298
299    Dmsg1(390, "unser_block_header block_len=%d\n", block_len);
300    /* Find end of block or end of buffer whichever is smaller */
301    if (block_len > block->read_len) {
302       block_end = block->read_len;
303    } else {
304       block_end = block_len;
305    }
306    block->binbuf = block_end - bhl;
307    block->block_len = block_len;
308    block->BlockNumber = BlockNumber;
309    Dmsg3(390, "Read binbuf = %d %d block_len=%d\n", block->binbuf,
310       bhl, block_len);
311    if (block_len <= block->read_len && dev->do_checksum()) {
312       BlockCheckSum = bcrc32((uint8_t *)block->buf+BLKHDR_CS_LENGTH,
313                          block_len-BLKHDR_CS_LENGTH);
314       if (BlockCheckSum != CheckSum) {
315          dev->dev_errno = EIO;
316          Mmsg6(dev->errmsg, _("Volume data error at %u:%u!\n" 
317             "Block checksum mismatch in block=%u len=%d: calc=%x blk=%x\n"),
318             dev->file, dev->block_num, (unsigned)BlockNumber, 
319             block_len, BlockCheckSum, CheckSum);
320          if (block->read_errors == 0 || verbose >= 2) {
321             Jmsg(jcr, M_ERROR, 0, "%s", dev->errmsg);
322             dump_block(block, "with checksum error");
323          }
324          block->read_errors++;
325          if (!forge_on) {
326             return false;
327          }
328       }
329    }
330    return true;
331 }
332
333 /*
334  * Write a block to the device, with locking and unlocking
335  *
336  * Returns: true  on success
337  *        : false on failure
338  *
339  */
340 bool DCR::write_block_to_device()
341 {
342    bool stat = true;
343    DCR *dcr = this;
344
345    if (dcr->spooling) {
346       stat = write_block_to_spool_file(dcr);
347       return stat;
348    }
349
350    if (!dcr->is_dev_locked()) {        /* device already locked? */
351       /* note, do not change this to dcr->r_dlock */
352       dev->r_dlock();                  /* no, lock it */
353    }
354
355    /*
356     * If a new volume has been mounted since our last write
357     *   Create a JobMedia record for the previous volume written,
358     *   and set new parameters to write this volume
359     * The same applies for if we are in a new file.
360     */
361    if (dcr->NewVol || dcr->NewFile) {
362       if (job_canceled(jcr)) {
363          stat = false;
364          goto bail_out;
365       }
366       /* Create a jobmedia record for this job */
367       if (!dir_create_jobmedia_record(dcr)) {
368          dev->dev_errno = EIO;
369          Jmsg2(jcr, M_FATAL, 0, _("Could not create JobMedia record for Volume=\"%s\" Job=%s\n"),
370             dcr->getVolCatName(), jcr->Job);
371          set_new_volume_parameters(dcr);
372          stat = false;
373          goto bail_out;
374       }
375       if (dcr->NewVol) {
376          /* Note, setting a new volume also handles any pending new file */
377          set_new_volume_parameters(dcr);
378       } else {
379          set_new_file_parameters(dcr);
380       }
381    }
382
383    if (!dcr->write_block_to_dev()) {
384        if (job_canceled(jcr) || jcr->getJobType() == JT_SYSTEM) {
385           stat = false;
386        } else {
387           stat = fixup_device_block_write_error(dcr);
388        }
389    }
390
391 bail_out:
392    if (!dcr->is_dev_locked()) {        /* did we lock dev above? */
393       /* note, do not change this to dcr->dunlock */
394       dev->dunlock();                  /* unlock it now */
395    }
396    return stat;
397 }
398
399 /*
400  * Write a block to the device
401  *
402  *  Returns: true  on success or EOT
403  *           false on hard error
404  */
405 bool DCR::write_block_to_dev()
406 {
407    ssize_t stat = 0;
408    uint32_t wlen;                     /* length to write */
409    int hit_max1, hit_max2;
410    bool ok = true;
411    DCR *dcr = this;
412
413 #ifdef NO_TAPE_WRITE_TEST
414    empty_block(block);
415    return true;
416 #endif
417    if (job_canceled(jcr)) {
418       return false;
419    }
420
421    ASSERT(block->binbuf == ((uint32_t) (block->bufp - block->buf)));
422
423    wlen = block->binbuf;
424    if (wlen <= WRITE_BLKHDR_LENGTH) {  /* Does block have data in it? */
425       Dmsg0(100, "return write_block_to_dev no data to write\n");
426       return true;
427    }
428
429    /* dump_block(block, "before write"); */
430    if (dev->at_weot()) {
431       Dmsg0(100, "return write_block_to_dev with ST_WEOT\n");
432       dev->dev_errno = ENOSPC;
433       Jmsg1(jcr, M_FATAL, 0,  _("Cannot write block. Device at EOM. dev=%s\n"), dev->print_name());
434       return false;
435    }
436    if (!dev->can_append()) {
437       dev->dev_errno = EIO;
438       Jmsg1(jcr, M_FATAL, 0, _("Attempt to write on read-only Volume. dev=%s\n"), dev->print_name());
439       return false;
440    }
441
442    if (!dev->is_open()) {
443       Jmsg1(jcr, M_FATAL, 0, _("Attempt to write on closed device=%s\n"), dev->print_name());
444       return false;
445    }
446    /*
447     * Clear to the end of the buffer if it is not full,
448     *  and on tape devices, apply min and fixed blocking.
449     */
450    if (wlen != block->buf_len) {
451       uint32_t blen;                  /* current buffer length */
452
453       Dmsg2(250, "binbuf=%d buf_len=%d\n", block->binbuf, block->buf_len);
454       blen = wlen;
455
456       /* Adjust write size to min/max for tapes only */
457       if (dev->is_tape()) {
458          /* check for fixed block size */
459          if (dev->min_block_size == dev->max_block_size) {
460             wlen = block->buf_len;    /* fixed block size already rounded */
461          /* Check for min block size */
462          } else if (wlen < dev->min_block_size) {
463             wlen =  ((dev->min_block_size + TAPE_BSIZE - 1) / TAPE_BSIZE) * TAPE_BSIZE;
464          /* Ensure size is rounded */
465          } else {
466             wlen = ((wlen + TAPE_BSIZE - 1) / TAPE_BSIZE) * TAPE_BSIZE;
467          }
468       }
469       if (wlen-blen > 0) {
470          memset(block->bufp, 0, wlen-blen); /* clear garbage */
471       }
472    }
473
474 #ifdef DEBUG_BLOCK_CHECKSUM
475    uint32_t checksum;
476    checksum = ser_block_header(block, dev->do_checksum());
477 #else
478    ser_block_header(block, dev->do_checksum());
479 #endif
480
481    /* Limit maximum Volume size to value specified by user */
482    hit_max1 = (dev->max_volume_size > 0) &&
483        ((dev->VolCatInfo.VolCatBytes + block->binbuf)) >= dev->max_volume_size;
484    hit_max2 = (dev->VolCatInfo.VolCatMaxBytes > 0) &&
485        ((dev->VolCatInfo.VolCatBytes + block->binbuf)) >= dev->VolCatInfo.VolCatMaxBytes;
486    if (hit_max1 || hit_max2) {
487       char ed1[50];
488       uint64_t max_cap;
489       Dmsg0(100, "==== Output bytes Triggered medium max capacity.\n");
490       if (hit_max1) {
491          max_cap = dev->max_volume_size;
492       } else {
493          max_cap = dev->VolCatInfo.VolCatMaxBytes;
494       }
495       Jmsg(jcr, M_INFO, 0, _("User defined maximum volume capacity %s exceeded on device %s.\n"),
496             edit_uint64_with_commas(max_cap, ed1),  dev->print_name());
497       terminate_writing_volume(dcr);
498       reread_last_block(dcr);   /* DEBUG */
499       dev->dev_errno = ENOSPC;
500       return false;
501    }
502
503    /* Limit maximum File size on volume to user specified value */
504    if ((dev->max_file_size > 0) &&
505        (dev->file_size+block->binbuf) >= dev->max_file_size) {
506       dev->file_size = 0;             /* reset file size */
507
508       if (!dev->weof(1)) {            /* write eof */
509          Dmsg0(50, "WEOF error in max file size.\n");
510          Jmsg(jcr, M_FATAL, 0, _("Unable to write EOF. ERR=%s\n"), 
511             dev->bstrerror());
512          terminate_writing_volume(dcr);
513          dev->dev_errno = ENOSPC;
514          return false;
515       }
516       if (!write_ansi_ibm_labels(dcr, ANSI_EOF_LABEL, dev->VolHdr.VolumeName)) {
517          return false;
518       }
519
520       if (!do_new_file_bookkeeping(dcr)) {
521          /* Error message already sent */
522          return false;
523       }
524    }
525    
526    if (!do_dvd_size_checks(dcr)) {
527       /* Error message already sent */
528       return false;
529    }
530
531    dev->VolCatInfo.VolCatWrites++;
532    Dmsg1(1300, "Write block of %u bytes\n", wlen);
533 #ifdef DEBUG_BLOCK_ZEROING
534    uint32_t *bp = (uint32_t *)block->buf;
535    if (bp[0] == 0 && bp[1] == 0 && bp[2] == 0 && block->buf[12] == 0) {
536       Jmsg0(jcr, M_ABORT, 0, _("Write block header zeroed.\n"));
537    }
538 #endif
539
540    /*
541     * Do write here, make a somewhat feeble attempt to recover from 
542     *  I/O errors, or from the OS telling us it is busy.
543     */ 
544    int retry = 0;
545    errno = 0;
546    stat = 0;
547    do {
548       if (retry > 0 && stat == -1 && errno == EBUSY) {
549          berrno be;
550          Dmsg4(100, "===== write retry=%d stat=%d errno=%d: ERR=%s\n",
551                retry, stat, errno, be.bstrerror());
552          bmicrosleep(5, 0);    /* pause a bit if busy or lots of errors */
553          dev->clrerror(-1);
554       }
555       stat = dev->write(block->buf, (size_t)wlen);
556
557    } while (stat == -1 && (errno == EBUSY || errno == EIO) && retry++ < 3);
558
559 #ifdef DEBUG_BLOCK_CHECKSUM
560    uint32_t achecksum = ser_block_header(block, dev->do_checksum());
561    if (checksum != achecksum) {
562       Jmsg2(jcr, M_ERROR, 0, _("Block checksum changed during write: before=%ud after=%ud\n"),
563          checksum, achecksum);
564       dump_block(block, "with checksum error");
565    }
566 #endif
567
568 #ifdef DEBUG_BLOCK_ZEROING
569    if (bp[0] == 0 && bp[1] == 0 && bp[2] == 0 && block->buf[12] == 0) {
570       Jmsg0(jcr, M_ABORT, 0, _("Write block header zeroed.\n"));
571    }
572 #endif
573
574    if (stat != (ssize_t)wlen) {
575       /* Some devices simply report EIO when the volume is full.
576        * With a little more thought we may be able to check
577        * capacity and distinguish real errors and EOT
578        * conditions.  In any case, we probably want to
579        * simulate an End of Medium.
580        */
581       if (stat == -1) {
582          berrno be;
583          dev->clrerror(-1);
584          if (dev->dev_errno == 0) {
585             dev->dev_errno = ENOSPC;        /* out of space */
586          }
587          if (dev->dev_errno != ENOSPC) {
588             dev->VolCatInfo.VolCatErrors++;
589             Jmsg4(jcr, M_ERROR, 0, _("Write error at %u:%u on device %s. ERR=%s.\n"),
590                dev->file, dev->block_num, dev->print_name(), be.bstrerror());
591          }
592       } else {
593         dev->dev_errno = ENOSPC;            /* out of space */
594       }
595       if (dev->dev_errno == ENOSPC) {
596          Jmsg(jcr, M_INFO, 0, _("End of Volume \"%s\" at %u:%u on device %s. Write of %u bytes got %d.\n"),
597             dev->getVolCatName(),
598             dev->file, dev->block_num, dev->print_name(), wlen, stat);
599       }
600       if (debug_level >= 100) {
601          berrno be;
602          Dmsg7(100, "=== Write error. fd=%d size=%u rtn=%d dev_blk=%d blk_blk=%d errno=%d: ERR=%s\n",
603             dev->fd(), wlen, stat, dev->block_num, block->BlockNumber, 
604             dev->dev_errno, be.bstrerror(dev->dev_errno));
605       }
606
607       ok = terminate_writing_volume(dcr);
608       if (!ok && !forge_on) {
609          return false;
610       }
611       if (ok) {
612          reread_last_block(dcr);
613       }
614       return false;
615    }
616
617    /* We successfully wrote the block, now do housekeeping */
618    Dmsg2(1300, "VolCatBytes=%d newVolCatBytes=%d\n", (int)dev->VolCatInfo.VolCatBytes,
619       (int)(dev->VolCatInfo.VolCatBytes+wlen));
620    dev->VolCatInfo.VolCatBytes += wlen;         
621    dev->VolCatInfo.VolCatBlocks++;
622    dev->EndBlock = dev->block_num;
623    dev->EndFile  = dev->file;
624    dev->LastBlock = block->BlockNumber;
625    block->BlockNumber++;
626
627    /* Update dcr values */
628    if (dev->is_tape()) {
629       dcr->EndBlock = dev->EndBlock;
630       dcr->EndFile  = dev->EndFile;
631       dev->block_num++;
632    } else {
633       /* Save address of block just written */
634       uint64_t addr = dev->file_addr + wlen - 1;
635       dcr->EndBlock = (uint32_t)addr;
636       dcr->EndFile = (uint32_t)(addr >> 32);
637       dev->block_num = dcr->EndBlock;
638       dev->file = dcr->EndFile;
639    }
640    dcr->VolMediaId = dev->VolCatInfo.VolMediaId;
641    if (dcr->VolFirstIndex == 0 && block->FirstIndex > 0) {
642       dcr->VolFirstIndex = block->FirstIndex;
643    }
644    if (block->LastIndex > 0) {
645       dcr->VolLastIndex = block->LastIndex;
646    }
647    dcr->WroteVol = true;
648    dev->file_addr += wlen;            /* update file address */
649    dev->file_size += wlen;
650    dev->part_size += wlen;
651
652    Dmsg2(1300, "write_block: wrote block %d bytes=%d\n", dev->block_num, wlen);
653    empty_block(block);
654    return true;
655 }
656
657 static void reread_last_block(DCR *dcr)
658 {
659 #define CHECK_LAST_BLOCK
660 #ifdef  CHECK_LAST_BLOCK
661    bool ok = true;
662    DEVICE *dev = dcr->dev;
663    JCR *jcr = dcr->jcr;
664    DEV_BLOCK *block = dcr->block;
665    /*
666     * If the device is a tape and it supports backspace record,
667     *   we backspace over one or two eof marks depending on
668     *   how many we just wrote, then over the last record,
669     *   then re-read it and verify that the block number is
670     *   correct.
671     */
672    if (dev->is_tape() && dev->has_cap(CAP_BSR)) {
673       /* Now back up over what we wrote and read the last block */
674       if (!dev->bsf(1)) {
675          berrno be;
676          ok = false;
677          Jmsg(jcr, M_ERROR, 0, _("Backspace file at EOT failed. ERR=%s\n"), 
678               be.bstrerror(dev->dev_errno));
679       }
680       if (ok && dev->has_cap(CAP_TWOEOF) && !dev->bsf(1)) {
681          berrno be;
682          ok = false;
683          Jmsg(jcr, M_ERROR, 0, _("Backspace file at EOT failed. ERR=%s\n"), 
684               be.bstrerror(dev->dev_errno));
685       }
686       /* Backspace over record */
687       if (ok && !dev->bsr(1)) {
688          berrno be;
689          ok = false;
690          Jmsg(jcr, M_ERROR, 0, _("Backspace record at EOT failed. ERR=%s\n"), 
691               be.bstrerror(dev->dev_errno));
692          /*
693           *  On FreeBSD systems, if the user got here, it is likely that his/her
694           *    tape drive is "frozen".  The correct thing to do is a
695           *    rewind(), but if we do that, higher levels in cleaning up, will
696           *    most likely write the EOS record over the beginning of the
697           *    tape.  The rewind *is* done later in mount.c when another
698           *    tape is requested. Note, the clrerror() call in bsr()
699           *    calls ioctl(MTCERRSTAT), which *should* fix the problem.
700           */
701       }
702       if (ok) {
703          DEV_BLOCK *lblock = new_block(dev);
704          /* Note, this can destroy dev->errmsg */
705          dcr->block = lblock;
706          if (!dcr->read_block_from_dev(NO_BLOCK_NUMBER_CHECK)) {
707             Jmsg(jcr, M_ERROR, 0, _("Re-read last block at EOT failed. ERR=%s"), 
708                  dev->errmsg);
709          } else {
710             /*
711              * If we wrote block and the block numbers don't agree
712              *  we have a possible problem.
713              */
714             if (lblock->BlockNumber != dev->LastBlock) {
715                 if (dev->LastBlock > (lblock->BlockNumber + 1)) {
716                    Jmsg(jcr, M_FATAL, 0, _(
717 "Re-read of last block: block numbers differ by more than one.\n"
718 "Probable tape misconfiguration and data loss. Read block=%u Want block=%u.\n"),
719                        lblock->BlockNumber, dev->LastBlock);
720                  } else {
721                    Jmsg(jcr, M_ERROR, 0, _(
722 "Re-read of last block OK, but block numbers differ. Read block=%u Want block=%u.\n"),
723                        lblock->BlockNumber, dev->LastBlock);
724                  }
725             } else {
726                Jmsg(jcr, M_INFO, 0, _("Re-read of last block succeeded.\n"));
727             }
728          }
729          free_block(lblock);
730          dcr->block = block;
731       }
732    }
733 #endif
734 }
735
736 /*
737  * If this routine is called, we do our bookkeeping and
738  *   then assure that the volume will not be written any
739  *   more.
740  */
741 static bool terminate_writing_volume(DCR *dcr)
742 {
743    DEVICE *dev = dcr->dev;
744    bool ok = true;
745
746    /* Create a JobMedia record to indicated end of tape */
747    dev->VolCatInfo.VolCatFiles = dev->file;
748    if (!dir_create_jobmedia_record(dcr)) {
749       Dmsg0(50, "Error from create JobMedia\n");
750       dev->dev_errno = EIO;
751        Jmsg2(dcr->jcr, M_FATAL, 0, _("Could not create JobMedia record for Volume=\"%s\" Job=%s\n"),
752             dcr->getVolCatName(), dcr->jcr->Job);
753        ok = false;
754    }
755    dcr->block->write_failed = true;
756    if (!dev->weof(1)) {         /* end the tape */
757       dev->VolCatInfo.VolCatErrors++;
758       Jmsg(dcr->jcr, M_ERROR, 0, _("Error writing final EOF to tape. This Volume may not be readable.\n"
759            "%s"), dev->errmsg);
760       ok = false;
761       Dmsg0(50, "Error writing final EOF to volume.\n");
762    }
763    if (ok) {
764       ok = write_ansi_ibm_labels(dcr, ANSI_EOV_LABEL, dev->VolHdr.VolumeName);
765    }
766    bstrncpy(dev->VolCatInfo.VolCatStatus, "Full", sizeof(dev->VolCatInfo.VolCatStatus));
767    dev->VolCatInfo.VolCatFiles = dev->file;   /* set number of files */
768    
769    if (dev->is_dvd()) {
770       if (!dvd_write_part(dcr)) {             /* write last part */
771          dev->VolCatInfo.VolCatErrors++;
772          Jmsg(dcr->jcr, M_FATAL, 0, _("Error writing final part to DVD. "
773                                  "This Volume may not be readable.\n%s"),
774                          dev->errmsg);
775          ok = false;
776          Dmsg0(100, "dvd_write_part error.\n");
777       }
778       dev->VolCatInfo.VolCatParts = dev->num_dvd_parts;
779    }
780    
781    if (!dir_update_volume_info(dcr, false, true)) {
782       ok = false;
783       Dmsg0(50, "Error updating volume info.\n");
784    }
785    Dmsg1(50, "dir_update_volume_info terminate writing -- %s\n", ok?"OK":"ERROR");
786
787    /*
788     * Walk through all attached dcrs setting flag to call
789     * set_new_file_parameters() when that dcr is next used.
790     */
791    DCR *mdcr;
792    foreach_dlist(mdcr, dev->attached_dcrs) {
793       if (mdcr->jcr->JobId == 0) {
794          continue;
795       }
796       mdcr->NewFile = true;        /* set reminder to do set_new_file_params */
797    }
798    /* Set new file/block parameters for current dcr */
799    set_new_file_parameters(dcr);
800
801    if (ok && dev->has_cap(CAP_TWOEOF) && !dev->weof(1)) {  /* end the tape */
802       dev->VolCatInfo.VolCatErrors++;
803       /* This may not be fatal since we already wrote an EOF */
804       Jmsg(dcr->jcr, M_ERROR, 0, "%s", dev->errmsg);
805       Dmsg0(50, "Writing second EOF failed.\n");
806    }
807
808    dev->set_ateot();                  /* no more writing this tape */
809    Dmsg1(50, "*** Leave terminate_writing_volume -- %s\n", ok?"OK":"ERROR");
810    return ok;
811 }
812
813 /*
814  * Do bookkeeping when a new file is created on a Volume. This is
815  *  also done for disk files to generate the jobmedia records for
816  *  quick seeking.
817  */
818 static bool do_new_file_bookkeeping(DCR *dcr) 
819 {
820    DEVICE *dev = dcr->dev;
821    JCR *jcr = dcr->jcr;
822
823    /* Create a JobMedia record so restore can seek */
824    if (!dir_create_jobmedia_record(dcr)) {
825       Dmsg0(50, "Error from create_job_media.\n");
826       dev->dev_errno = EIO;
827       Jmsg2(jcr, M_FATAL, 0, _("Could not create JobMedia record for Volume=\"%s\" Job=%s\n"),
828            dcr->getVolCatName(), jcr->Job);
829       terminate_writing_volume(dcr);
830       dev->dev_errno = EIO;
831       return false;
832    }
833    dev->VolCatInfo.VolCatFiles = dev->file;
834    if (!dir_update_volume_info(dcr, false, false)) {
835       Dmsg0(50, "Error from update_vol_info.\n");
836       terminate_writing_volume(dcr);
837       dev->dev_errno = EIO;
838       return false;
839    }
840    Dmsg0(100, "dir_update_volume_info max file size -- OK\n");
841
842    /*
843     * Walk through all attached dcrs setting flag to call
844     * set_new_file_parameters() when that dcr is next used.
845     */
846    DCR *mdcr;
847    foreach_dlist(mdcr, dev->attached_dcrs) {
848       if (mdcr->jcr->JobId == 0) {
849          continue;
850       }
851       mdcr->NewFile = true;        /* set reminder to do set_new_file_params */
852    }
853    /* Set new file/block parameters for current dcr */
854    set_new_file_parameters(dcr);
855    return true;
856 }
857
858 /*
859  * Do all checks for DVD sizes during writing.
860  */
861 static bool do_dvd_size_checks(DCR *dcr) 
862 {
863    DEVICE *dev = dcr->dev;
864    JCR *jcr = dcr->jcr;
865    DEV_BLOCK *block = dcr->block;
866
867    /* Don't go further if the device is not a dvd */
868    if (!dev->is_dvd()) {
869       return true;
870    }
871    
872    /* Limit maximum part size to value specified by user 
873     */
874    if (dev->max_part_size > 0 && ((dev->part_size + block->binbuf) >= dev->max_part_size)) {
875       if (dev->part < dev->num_dvd_parts) {
876          Jmsg3(dcr->jcr, M_FATAL, 0, _("Error while writing, current part number"
877                " is less than the total number of parts (%d/%d, device=%s)\n"),
878                dev->part, dev->num_dvd_parts, dev->print_name());
879          dev->dev_errno = EIO;
880          return false;
881       }
882       
883       if (dvd_open_next_part(dcr) < 0) {
884          Jmsg2(dcr->jcr, M_FATAL, 0, _("Unable to open device next part %s: ERR=%s\n"),
885                 dev->print_name(), dev->bstrerror());
886          dev->dev_errno = EIO;
887          return false;
888       }
889       
890       dev->VolCatInfo.VolCatParts = dev->num_dvd_parts;
891             
892       if (!dir_update_volume_info(dcr, false, false)) {
893          Dmsg0(190, "Error from update_vol_info.\n");
894          dev->dev_errno = EIO;
895          return false;
896       }
897    }
898
899    dev->update_freespace();
900    
901    if (!dev->is_freespace_ok()) { /* Error while getting free space */
902       char ed1[50], ed2[50];
903       Dmsg1(100, "Cannot get free space on the device ERR=%s.\n", dev->errmsg);
904       Jmsg(jcr, M_FATAL, 0, _("End of Volume \"%s\" at %u:%u on device %s "
905          "(part_size=%s, free_space=%s, free_space_errno=%d, errmsg=%s).\n"),
906            dev->getVolCatName(),
907            dev->file, dev->block_num, dev->print_name(),
908            edit_uint64_with_commas(dev->part_size, ed1), edit_uint64_with_commas(dev->free_space, ed2),
909            dev->free_space_errno, dev->errmsg);
910       dev->dev_errno = dev->free_space_errno;
911       return false;
912    }
913    
914    if ((dev->is_freespace_ok() && (dev->part_size + block->binbuf) >= dev->free_space)) {
915       char ed1[50], ed2[50];
916       Dmsg0(100, "==== Just enough free space on the device to write the current part...\n");
917       Jmsg(jcr, M_INFO, 0, _("End of Volume \"%s\" at %u:%u on device %s "
918          "(part_size=%s, free_space=%s, free_space_errno=%d).\n"),
919             dev->getVolCatName(),
920             dev->file, dev->block_num, dev->print_name(),
921             edit_uint64_with_commas(dev->part_size, ed1), edit_uint64_with_commas(dev->free_space, ed2),
922             dev->free_space_errno);
923       terminate_writing_volume(dcr);
924       dev->dev_errno = ENOSPC;
925       return false;
926    }   
927    return true;
928 }
929
930
931 /*
932  * Read block with locking
933  *
934  */
935 bool DCR::read_block_from_device(bool check_block_numbers)
936 {
937    bool ok;
938
939    Dmsg0(250, "Enter read_block_from_device\n");
940    dev->r_dlock();
941    ok = read_block_from_dev(check_block_numbers);
942    dev->dunlock();
943    Dmsg0(250, "Leave read_block_from_device\n");
944    return ok;
945 }
946
947 /*
948  * Read the next block into the block structure and unserialize
949  *  the block header.  For a file, the block may be partially
950  *  or completely in the current buffer.
951  */
952 bool DCR::read_block_from_dev(bool check_block_numbers)
953 {
954    ssize_t stat;
955    int looping;
956    int retry;
957    DCR *dcr = this;
958
959    if (job_canceled(jcr)) {
960       Mmsg(dev->errmsg, _("Job failed or canceled.\n"));
961       block->read_len = 0;
962       return false;
963    }
964    
965    if (dev->at_eot()) {
966       Mmsg(dev->errmsg, _("Attempt to read past end of tape or file.\n"));
967       block->read_len = 0;
968       return false;
969    }
970    looping = 0;
971    Dmsg1(250, "Full read in read_block_from_device() len=%d\n",
972          block->buf_len);
973
974    if (!dev->is_open()) {
975       Mmsg4(dev->errmsg, _("Attempt to read closed device: fd=%d at file:blk %u:%u on device %s\n"),
976          dev->fd(), dev->file, dev->block_num, dev->print_name());
977       Jmsg(dcr->jcr, M_WARNING, 0, "%s", dev->errmsg);
978       block->read_len = 0;
979       return false;
980     }
981
982 reread:
983    if (looping > 1) {
984       dev->dev_errno = EIO;
985       Mmsg1(dev->errmsg, _("Block buffer size looping problem on device %s\n"),
986          dev->print_name());
987       Jmsg(jcr, M_ERROR, 0, "%s", dev->errmsg);
988       block->read_len = 0;
989       return false;
990    }
991    
992    /* Check for DVD part file end */
993    if (dev->at_eof() && dev->is_dvd() && dev->num_dvd_parts > 0 &&
994         dev->part <= dev->num_dvd_parts) {
995       Dmsg0(400, "Call dvd_open_next_part\n");
996       if (dvd_open_next_part(dcr) < 0) {
997          Jmsg3(dcr->jcr, M_FATAL, 0, _("Unable to open device part=%d %s: ERR=%s\n"),
998                dev->part, dev->print_name(), dev->bstrerror());
999          dev->dev_errno = EIO;
1000          return false;
1001       }
1002    }
1003    
1004    retry = 0;
1005    errno = 0;
1006    stat = 0;
1007    do {
1008       if ((retry > 0 && stat == -1 && errno == EBUSY)) {
1009          berrno be;
1010          Dmsg4(100, "===== read retry=%d stat=%d errno=%d: ERR=%s\n",
1011                retry, stat, errno, be.bstrerror());
1012          bmicrosleep(10, 0);    /* pause a bit if busy or lots of errors */
1013          dev->clrerror(-1);
1014       }
1015       stat = dev->read(block->buf, (size_t)block->buf_len);
1016
1017    } while (stat == -1 && (errno == EBUSY || errno == EINTR || errno == EIO) && retry++ < 3);
1018    if (stat < 0) {
1019       berrno be;
1020       dev->clrerror(-1);
1021       Dmsg1(250, "Read device got: ERR=%s\n", be.bstrerror());
1022       block->read_len = 0;
1023       Mmsg5(dev->errmsg, _("Read error on fd=%d at file:blk %u:%u on device %s. ERR=%s.\n"),
1024          dev->fd(), dev->file, dev->block_num, dev->print_name(), be.bstrerror());
1025       Jmsg(jcr, M_ERROR, 0, "%s", dev->errmsg);
1026       if (dev->at_eof()) {        /* EOF just seen? */
1027          dev->set_eot();          /* yes, error => EOT */
1028       }
1029       return false;
1030    }
1031    Dmsg3(250, "Read device got %d bytes at %u:%u\n", stat,
1032       dev->file, dev->block_num);
1033    if (stat == 0) {             /* Got EOF ! */
1034       dev->block_num = 0;
1035       block->read_len = 0;
1036       Mmsg3(dev->errmsg, _("Read zero bytes at %u:%u on device %s.\n"),
1037          dev->file, dev->block_num, dev->print_name());
1038       if (dev->at_eof()) {       /* EOF already read? */
1039          dev->set_eot();         /* yes, 2 EOFs => EOT */
1040          return 0;
1041       }
1042       dev->set_ateof();
1043       return false;             /* return eof */
1044    }
1045
1046    /* Continue here for successful read */
1047
1048    block->read_len = stat;      /* save length read */
1049    if (block->read_len == 80 && 
1050         (dcr->VolCatInfo.LabelType != B_BACULA_LABEL ||
1051          dcr->device->label_type != B_BACULA_LABEL)) {
1052       /* ***FIXME*** should check label */
1053       Dmsg2(100, "Ignore 80 byte ANSI label at %u:%u\n", dev->file, dev->block_num);
1054       dev->clear_eof();
1055       goto reread;             /* skip ANSI/IBM label */
1056    }
1057                                           
1058    if (block->read_len < BLKHDR2_LENGTH) {
1059       dev->dev_errno = EIO;
1060       Mmsg4(dev->errmsg, _("Volume data error at %u:%u! Very short block of %d bytes on device %s discarded.\n"),
1061          dev->file, dev->block_num, block->read_len, dev->print_name());
1062       Jmsg(jcr, M_ERROR, 0, "%s", dev->errmsg);
1063       dev->set_short_block();   
1064       block->read_len = block->binbuf = 0;
1065       return false;             /* return error */
1066    }
1067
1068 // BlockNumber = block->BlockNumber + 1;
1069    if (!unser_block_header(jcr, dev, block)) {
1070       if (forge_on) {
1071          dev->file_addr += block->read_len;
1072          dev->file_size += block->read_len;
1073          goto reread;
1074       }
1075       return false;
1076    }
1077
1078    /*
1079     * If the block is bigger than the buffer, we reposition for
1080     *  re-reading the block, allocate a buffer of the correct size,
1081     *  and go re-read.
1082     */
1083    if (block->block_len > block->buf_len) {
1084       dev->dev_errno = EIO;
1085       Mmsg2(dev->errmsg,  _("Block length %u is greater than buffer %u. Attempting recovery.\n"),
1086          block->block_len, block->buf_len);
1087       Jmsg(jcr, M_ERROR, 0, "%s", dev->errmsg);
1088       Pmsg1(000, "%s", dev->errmsg);
1089       /* Attempt to reposition to re-read the block */
1090       if (dev->is_tape()) {
1091          Dmsg0(250, "BSR for reread; block too big for buffer.\n");
1092          if (!dev->bsr(1)) {
1093             Jmsg(jcr, M_ERROR, 0, "%s", dev->bstrerror());
1094             block->read_len = 0;
1095             return false;
1096          }
1097       } else {
1098          Dmsg0(250, "Seek to beginning of block for reread.\n");
1099          boffset_t pos = dev->lseek(dcr, (boffset_t)0, SEEK_CUR); /* get curr pos */
1100          pos -= block->read_len;
1101          dev->lseek(dcr, pos, SEEK_SET);
1102          dev->file_addr = pos;
1103       }
1104       Mmsg1(dev->errmsg, _("Setting block buffer size to %u bytes.\n"), block->block_len);
1105       Jmsg(jcr, M_INFO, 0, "%s", dev->errmsg);
1106       Pmsg1(000, "%s", dev->errmsg);
1107       /* Set new block length */
1108       dev->max_block_size = block->block_len;
1109       block->buf_len = block->block_len;
1110       free_memory(block->buf);
1111       block->buf = get_memory(block->buf_len);
1112       empty_block(block);
1113       looping++;
1114       goto reread;                    /* re-read block with correct block size */
1115    }
1116
1117    if (block->block_len > block->read_len) {
1118       dev->dev_errno = EIO;
1119       Mmsg4(dev->errmsg, _("Volume data error at %u:%u! Short block of %d bytes on device %s discarded.\n"),
1120          dev->file, dev->block_num, block->read_len, dev->print_name());
1121       Jmsg(jcr, M_ERROR, 0, "%s", dev->errmsg);
1122       dev->set_short_block();
1123       block->read_len = block->binbuf = 0;
1124       return false;             /* return error */
1125    }
1126
1127    dev->clear_short_block();
1128    dev->clear_eof();
1129    dev->VolCatInfo.VolCatReads++;
1130    dev->VolCatInfo.VolCatRBytes += block->read_len;
1131
1132    dev->EndBlock = dev->block_num;
1133    dev->EndFile  = dev->file;
1134    dev->block_num++;
1135
1136    /* Update dcr values */
1137    if (dev->is_tape()) {
1138       dcr->EndBlock = dev->EndBlock;
1139       dcr->EndFile  = dev->EndFile;
1140    } else {
1141       /* We need to take care about a short block in EndBlock/File
1142        * computation 
1143        */
1144       uint32_t len = MIN(block->read_len, block->block_len);
1145       uint64_t addr = dev->file_addr + len - 1;
1146       dcr->EndBlock = (uint32_t)addr;
1147       dcr->EndFile = (uint32_t)(addr >> 32);
1148       dev->block_num = dev->EndBlock = dcr->EndBlock;
1149       dev->file = dev->EndFile = dcr->EndFile;
1150    }
1151    dcr->VolMediaId = dev->VolCatInfo.VolMediaId;
1152    dev->file_addr += block->read_len;
1153    dev->file_size += block->read_len;
1154
1155    /*
1156     * If we read a short block on disk,
1157     * seek to beginning of next block. This saves us
1158     * from shuffling blocks around in the buffer. Take a
1159     * look at this from an efficiency stand point later, but
1160     * it should only happen once at the end of each job.
1161     *
1162     * I've been lseek()ing negative relative to SEEK_CUR for 30
1163     *   years now. However, it seems that with the new off_t definition,
1164     *   it is not possible to seek negative amounts, so we use two
1165     *   lseek(). One to get the position, then the second to do an
1166     *   absolute positioning -- so much for efficiency.  KES Sep 02.
1167     */
1168    Dmsg0(250, "At end of read block\n");
1169    if (block->read_len > block->block_len && !dev->is_tape()) {
1170       char ed1[50];
1171       boffset_t pos = dev->lseek(dcr, (boffset_t)0, SEEK_CUR); /* get curr pos */
1172       Dmsg1(250, "Current lseek pos=%s\n", edit_int64(pos, ed1));
1173       pos -= (block->read_len - block->block_len);
1174       dev->lseek(dcr, pos, SEEK_SET);
1175       Dmsg3(250, "Did lseek pos=%s blk_size=%d rdlen=%d\n", 
1176          edit_int64(pos, ed1), block->block_len,
1177             block->read_len);
1178       dev->file_addr = pos;
1179       dev->file_size = pos;
1180    }
1181    Dmsg2(250, "Exit read_block read_len=%d block_len=%d\n",
1182       block->read_len, block->block_len);
1183    block->block_read = true;
1184    return true;
1185 }