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