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