/* * Append Data sent from File daemon * */ bool do_append_data(JCR *jcr) { int32_t n; int32_t file_index, stream, last_file_index; BSOCK *fd = jcr->file_bsock; bool ok = true; DEV_RECORD rec; char buf1[100], buf2[100]; DCR *dcr = jcr->dcr; DEVICE *dev; char ec[50]; if (!dcr) { Jmsg0(jcr, M_FATAL, 0, _("DCR is NULL!!!\n")); return false; } dev = dcr->dev; if (!dev) { Jmsg0(jcr, M_FATAL, 0, _("DEVICE is NULL!!!\n")); return false; } Dmsg1(100, "Start append data. res=%d\n", dev->num_reserved()); memset(&rec, 0, sizeof(rec)); if (!fd->set_buffer_size(dcr->device->max_network_buffer_size, BNET_SETBUF_WRITE)) { jcr->setJobStatus(JS_ErrorTerminated); Jmsg0(jcr, M_FATAL, 0, _("Unable to set network buffer size.\n")); return false; } if (!acquire_device_for_append(dcr)) { jcr->setJobStatus(JS_ErrorTerminated); return false; } jcr->setJobStatus(JS_Running); dir_send_job_status(jcr); if (dev->VolCatInfo.VolCatName[0] == 0) { Pmsg0(000, _("NULL Volume name. This shouldn't happen!!!\n")); } Dmsg1(50, "Begin append device=%s\n", dev->print_name()); begin_data_spool(dcr); begin_attribute_spool(jcr); Dmsg0(100, "Just after acquire_device_for_append\n"); if (dev->VolCatInfo.VolCatName[0] == 0) { Pmsg0(000, _("NULL Volume name. This shouldn't happen!!!\n")); } /* * Write Begin Session Record */ if (!write_session_label(dcr, SOS_LABEL)) { Jmsg1(jcr, M_FATAL, 0, _("Write session label failed. ERR=%s\n"), dev->bstrerror()); jcr->setJobStatus(JS_ErrorTerminated); ok = false; } if (dev->VolCatInfo.VolCatName[0] == 0) { Pmsg0(000, _("NULL Volume name. This shouldn't happen!!!\n")); } /* Tell File daemon to send data */ if (!fd->fsend(OK_data)) { berrno be; Jmsg1(jcr, M_FATAL, 0, _("Network send error to FD. ERR=%s\n"), be.bstrerror(fd->b_errno)); ok = false; } /* * Get Data from File daemon, write to device. To clarify what is * going on here. We expect: * - A stream header * - Multiple records of data * - EOD record * * The Stream header is just used to sychronize things, and * none of the stream header is written to tape. * The Multiple records of data, contain first the Attributes, * then after another stream header, the file data, then * after another stream header, the MD5 data if any. * * So we get the (stream header, data, EOD) three time for each * file. 1. for the Attributes, 2. for the file data if any, * and 3. for the MD5 if any. */ dcr->VolFirstIndex = dcr->VolLastIndex = 0; jcr->run_time = time(NULL); /* start counting time for rates */ for (last_file_index = 0; ok && !jcr->is_job_canceled(); ) { /* Read Stream header from the File daemon. * The stream header consists of the following: * file_index (sequential Bacula file index, base 1) * stream (Bacula number to distinguish parts of data) * info (Info for Storage daemon -- compressed, encrypted, ...) * info is not currently used, so is read, but ignored! */ if ((n=bget_msg(fd)) <= 0) { if (n == BNET_SIGNAL && fd->msglen == BNET_EOD) { break; /* end of data */ } Jmsg1(jcr, M_FATAL, 0, _("Error reading data header from FD. ERR=%s\n"), fd->bstrerror()); possible_incomplete_job(jcr, last_file_index); ok = false; break; } if (sscanf(fd->msg, "%ld %ld", &file_index, &stream) != 2) { Jmsg1(jcr, M_FATAL, 0, _("Malformed data header from FD: %s\n"), fd->msg); ok = false; possible_incomplete_job(jcr, last_file_index); break; } Dmsg2(890, "<filed: Header FilInx=%d stream=%d\n", file_index, stream); /* * We make sure the file_index is advancing sequentially. * An incomplete job can start the file_index at any number. * otherwise, it must start at 1. */ if (jcr->rerunning && file_index > 0 && last_file_index == 0) { goto fi_checked; } if (file_index > 0 && (file_index == last_file_index || file_index == last_file_index + 1)) { goto fi_checked; } Jmsg2(jcr, M_FATAL, 0, _("FI=%d from FD not positive or sequential=%d\n"), file_index, last_file_index); possible_incomplete_job(jcr, last_file_index); ok = false; break; fi_checked: if (file_index != last_file_index) { jcr->JobFiles = file_index; last_file_index = file_index; } /* Read data stream from the File daemon. * The data stream is just raw bytes */ while ((n=bget_msg(fd)) > 0 && !jcr->is_job_canceled()) { rec.VolSessionId = jcr->VolSessionId; rec.VolSessionTime = jcr->VolSessionTime; rec.FileIndex = file_index; rec.Stream = stream; rec.maskedStream = stream & STREAMMASK_TYPE; /* strip high bits */ rec.data_len = fd->msglen; rec.data = fd->msg; /* use message buffer */ Dmsg4(850, "before writ_rec FI=%d SessId=%d Strm=%s len=%d\n", rec.FileIndex, rec.VolSessionId, stream_to_ascii(buf1, rec.Stream,rec.FileIndex), rec.data_len); while (!write_record_to_block(dcr->block, &rec)) { Dmsg2(850, "!write_record_to_block data_len=%d rem=%d\n", rec.data_len, rec.remainder); if (!write_block_to_device(dcr)) { Dmsg2(90, "Got write_block_to_dev error on device %s. %s\n", dev->print_name(), dev->bstrerror()); ok = false; break; } } if (!ok) { Dmsg0(400, "Not OK\n"); break; } jcr->JobBytes += rec.data_len; /* increment bytes this job */ Dmsg4(850, "write_record FI=%s SessId=%d Strm=%s len=%d\n", FI_to_ascii(buf1, rec.FileIndex), rec.VolSessionId, stream_to_ascii(buf2, rec.Stream, rec.FileIndex), rec.data_len); send_attrs_to_dir(jcr, &rec); Dmsg0(650, "Enter bnet_get\n"); } Dmsg1(650, "End read loop with FD. Stat=%d\n", n); if (fd->is_error()) { if (!jcr->is_job_canceled()) { Dmsg1(350, "Network read error from FD. ERR=%s\n", fd->bstrerror()); Jmsg1(jcr, M_FATAL, 0, _("Network error reading from FD. ERR=%s\n"), fd->bstrerror()); possible_incomplete_job(jcr, last_file_index); } ok = false; break; } } /* Create Job status for end of session label */ jcr->setJobStatus(ok?JS_Terminated:JS_ErrorTerminated); if (ok) { /* Terminate connection with FD */ fd->fsend(OK_append); do_fd_commands(jcr); /* finish dialog with FD */ } else { fd->fsend("3999 Failed append\n"); } /* * Don't use time_t for job_elapsed as time_t can be 32 or 64 bits, * and the subsequent Jmsg() editing will break */ int32_t job_elapsed = time(NULL) - jcr->run_time; if (job_elapsed <= 0) { job_elapsed = 1; } Jmsg(dcr->jcr, M_INFO, 0, _("Job write elapsed time = %02d:%02d:%02d, Transfer rate = %s Bytes/second\n"), job_elapsed / 3600, job_elapsed % 3600 / 60, job_elapsed % 60, edit_uint64_with_suffix(jcr->JobBytes / job_elapsed, ec)); Dmsg1(200, "Write EOS label JobStatus=%c\n", jcr->JobStatus); /* * Check if we can still write. This may not be the case * if we are at the end of the tape or we got a fatal I/O error. */ if (ok || dev->can_write()) { if (!write_session_label(dcr, EOS_LABEL)) { /* Print only if ok and not cancelled to avoid spurious messages */ if (ok && !jcr->is_job_canceled()) { Jmsg1(jcr, M_FATAL, 0, _("Error writing end session label. ERR=%s\n"), dev->bstrerror()); possible_incomplete_job(jcr, last_file_index); } jcr->setJobStatus(JS_ErrorTerminated); ok = false; } if (dev->VolCatInfo.VolCatName[0] == 0) { Pmsg0(000, _("NULL Volume name. This shouldn't happen!!!\n")); Dmsg0(000, _("NULL Volume name. This shouldn't happen!!!\n")); } Dmsg0(90, "back from write_end_session_label()\n"); /* Flush out final partial block of this session */ if (!write_block_to_device(dcr)) { /* Print only if ok and not cancelled to avoid spurious messages */ if (ok && !jcr->is_job_canceled()) { Jmsg2(jcr, M_FATAL, 0, _("Fatal append error on device %s: ERR=%s\n"), dev->print_name(), dev->bstrerror()); Dmsg0(100, _("Set ok=FALSE after write_block_to_device.\n")); possible_incomplete_job(jcr, last_file_index); } jcr->setJobStatus(JS_ErrorTerminated); ok = false; } } if (!ok && !jcr->is_JobStatus(JS_Incomplete)) { discard_data_spool(dcr); } else { /* Note: if commit is OK, the device will remain blocked */ commit_data_spool(dcr); } if (ok) { ok = dvd_close_job(dcr); /* do DVD cleanup if any */ } /* * Release the device -- and send final Vol info to DIR * and unlock it. */ release_device(dcr); if ((!ok || jcr->is_job_canceled()) && !jcr->is_JobStatus(JS_Incomplete)) { discard_attribute_spool(jcr); } else { commit_attribute_spool(jcr); } dir_send_job_status(jcr); /* update director */ Dmsg1(100, "return from do_append_data() ok=%d\n", ok); return ok; }
/* * List Volumes -- this should be moved to status.c */ void list_volumes(void sendit(const char *msg, int len, void *sarg), void *arg) { VOLRES *vol; POOL_MEM msg(PM_MESSAGE); int len; foreach_vol(vol) { DEVICE *dev = vol->dev; if (dev) { len = Mmsg(msg, "%s on device %s\n", vol->vol_name, dev->print_name()); sendit(msg.c_str(), len, arg); len = Mmsg(msg, " Reader=%d writers=%d reserves=%d volinuse=%d\n", dev->can_read() ? 1 : 0, dev->num_writers, dev->num_reserved(), vol->is_in_use()); sendit(msg.c_str(), len, arg); } else { len = Mmsg(msg, "Volume %s no device. volinuse= %d\n", vol->vol_name, vol->is_in_use()); sendit(msg.c_str(), len, arg); } } endeach_vol(vol); lock_read_volumes(); foreach_dlist(vol, read_vol_list) { DEVICE *dev = vol->dev; if (dev) { len = Mmsg(msg, "Read volume: %s on device %s\n", vol->vol_name, dev->print_name()); sendit(msg.c_str(), len, arg); len = Mmsg(msg, " Reader=%d writers=%d reserves=%d volinuse=%d JobId=%d\n", dev->can_read() ? 1 : 0, dev->num_writers, dev->num_reserved(), vol->is_in_use(), vol->get_jobid()); sendit(msg.c_str(), len, arg); } else { len = Mmsg(msg, "Volume: %s no device. volinuse= %d\n", vol->vol_name, vol->is_in_use()); sendit(msg.c_str(), len, arg); } }
/* * This job is done, so release the device. From a Unix standpoint, * the device remains open. * * Note, if we were spooling, we may enter with the device blocked. * We unblock at the end, only if it was us who blocked the * device. * */ bool release_device(DCR *dcr) { utime_t now; JCR *jcr = dcr->jcr; DEVICE *dev = dcr->dev; bool ok = true; char tbuf[100]; int was_blocked = BST_NOT_BLOCKED; /* * Capture job statistics now that we are done using this device. */ now = (utime_t)time(NULL); update_job_statistics(jcr, now); dev->Lock(); if (!dev->is_blocked()) { block_device(dev, BST_RELEASING); } else { was_blocked = dev->blocked(); dev->set_blocked(BST_RELEASING); } lock_volumes(); Dmsg2(100, "release_device device %s is %s\n", dev->print_name(), dev->is_tape() ? "tape" : "disk"); /* * If device is reserved, job never started, so release the reserve here */ dcr->clear_reserved(); if (dev->can_read()) { VOLUME_CAT_INFO *vol = &dev->VolCatInfo; dev->clear_read(); /* clear read bit */ Dmsg2(150, "dir_update_vol_info. label=%d Vol=%s\n", dev->is_labeled(), vol->VolCatName); if (dev->is_labeled() && vol->VolCatName[0] != 0) { dcr->dir_update_volume_info(false, false); /* send Volume info to Director */ remove_read_volume(jcr, dcr->VolumeName); volume_unused(dcr); } } else if (dev->num_writers > 0) { /* * Note if WEOT is set, we are at the end of the tape and may not be positioned correctly, * so the job_media_record and update_vol_info have already been done, * which means we skip them here. */ dev->num_writers--; Dmsg1(100, "There are %d writers in release_device\n", dev->num_writers); if (dev->is_labeled()) { Dmsg2(200, "dir_create_jobmedia. Release vol=%s dev=%s\n", dev->getVolCatName(), dev->print_name()); if (!dev->at_weot() && !dcr->dir_create_jobmedia_record(false)) { Jmsg2(jcr, M_FATAL, 0, _("Could not create JobMedia record for Volume=\"%s\" Job=%s\n"), dcr->getVolCatName(), jcr->Job); } /* * If no more writers, and no errors, and wrote something, write an EOF */ if (!dev->num_writers && dev->can_write() && dev->block_num > 0) { dev->weof(1); write_ansi_ibm_labels(dcr, ANSI_EOF_LABEL, dev->VolHdr.VolumeName); } if (!dev->at_weot()) { dev->VolCatInfo.VolCatFiles = dev->file; /* set number of files */ /* * Note! do volume update before close, which zaps VolCatInfo */ dcr->dir_update_volume_info(false, false); /* send Volume info to Director */ Dmsg2(200, "dir_update_vol_info. Release vol=%s dev=%s\n", dev->getVolCatName(), dev->print_name()); } if (dev->num_writers == 0) { /* if not being used */ volume_unused(dcr); /* we obviously are not using the volume */ } } } else { /* * If we reach here, it is most likely because the job has failed, * since the device is not in read mode and there are no writers. * It was probably reserved. */ volume_unused(dcr); } Dmsg3(100, "%d writers, %d reserve, dev=%s\n", dev->num_writers, dev->num_reserved(), dev->print_name()); /* * If no writers, close if file or !CAP_ALWAYS_OPEN */ if (dev->num_writers == 0 && (!dev->is_tape() || !dev->has_cap(CAP_ALWAYSOPEN))) { dev->close(dcr); free_volume(dev); } unlock_volumes(); /* * Fire off Alert command and include any output */ if (!job_canceled(jcr)) { if (!dcr->device->drive_tapealert_enabled && dcr->device->alert_command) { int status = 1; POOLMEM *alert, *line; BPIPE *bpipe; alert = get_pool_memory(PM_FNAME); line = get_pool_memory(PM_FNAME); alert = edit_device_codes(dcr, alert, dcr->device->alert_command, ""); /* * Wait maximum 5 minutes */ bpipe = open_bpipe(alert, 60 * 5, "r"); if (bpipe) { while (bfgets(line, bpipe->rfd)) { Jmsg(jcr, M_ALERT, 0, _("Alert: %s"), line); } status = close_bpipe(bpipe); } else { status = errno; } if (status != 0) { berrno be; Jmsg(jcr, M_ALERT, 0, _("3997 Bad alert command: %s: ERR=%s.\n"), alert, be.bstrerror(status)); } Dmsg1(400, "alert status=%d\n", status); free_pool_memory(alert); free_pool_memory(line); } else { /* * If all reservations are cleared for this device raise an event that SD plugins can register to. */ if (dev->num_reserved() == 0) { generate_plugin_event(jcr, bsdEventDeviceReleased, dcr); } } } pthread_cond_broadcast(&dev->wait_next_vol); Dmsg2(100, "JobId=%u broadcast wait_device_release at %s\n", (uint32_t)jcr->JobId, bstrftimes(tbuf, sizeof(tbuf), (utime_t)time(NULL))); release_device_cond(); /* * If we are the thread that blocked the device, then unblock it */ if (pthread_equal(dev->no_wait_id, pthread_self())) { dev->dunblock(true); } else { /* * Otherwise, reset the prior block status and unlock */ dev->set_blocked(was_blocked); dev->Unlock(); } if (dcr->keep_dcr) { detach_dcr_from_dev(dcr); } else { free_dcr(dcr); } Dmsg2(100, "Device %s released by JobId=%u\n", dev->print_name(), (uint32_t)jcr->JobId); return ok; }
/* * Acquire device for writing. We permit multiple writers. * If this is the first one, we read the label. * * Returns: NULL if failed for any reason * dcr if successful. * Note, normally reserve_device_for_append() is called * before this routine. */ DCR *acquire_device_for_append(DCR *dcr) { DEVICE *dev = dcr->dev; JCR *jcr = dcr->jcr; bool ok = false; bool have_vol = false; Enter(200); init_device_wait_timers(dcr); dev->Lock_acquire(); /* only one job at a time */ dev->Lock(); Dmsg1(100, "acquire_append device is %s\n", dev->is_tape() ? "tape" : "disk"); /* * With the reservation system, this should not happen */ if (dev->can_read()) { Jmsg1(jcr, M_FATAL, 0, _("Want to append, but device %s is busy reading.\n"), dev->print_name()); Dmsg1(200, "Want to append but device %s is busy reading.\n", dev->print_name()); goto get_out; } dev->clear_unload(); /* * have_vol defines whether or not mount_next_write_volume should * ask the Director again about what Volume to use. */ if (dev->can_append() && dcr->is_suitable_volume_mounted() && !bstrcmp(dcr->VolCatInfo.VolCatStatus, "Recycle")) { Dmsg0(190, "device already in append.\n"); /* * At this point, the correct tape is already mounted, so * we do not need to do mount_next_write_volume(), unless * we need to recycle the tape. */ if (dev->num_writers == 0) { dev->VolCatInfo = dcr->VolCatInfo; /* structure assignment */ } have_vol = dcr->is_tape_position_ok(); } if (!have_vol) { dev->rLock(true); block_device(dev, BST_DOING_ACQUIRE); dev->Unlock(); Dmsg1(190, "jid=%u Do mount_next_write_vol\n", (uint32_t)jcr->JobId); if (!dcr->mount_next_write_volume()) { if (!job_canceled(jcr)) { /* Reduce "noise" -- don't print if job canceled */ Jmsg(jcr, M_FATAL, 0, _("Could not ready device %s for append.\n"), dev->print_name()); Dmsg1(200, "Could not ready device %s for append.\n", dev->print_name()); } dev->Lock(); unblock_device(dev); goto get_out; } Dmsg2(190, "Output pos=%u:%u\n", dcr->dev->file, dcr->dev->block_num); dev->Lock(); unblock_device(dev); } dev->num_writers++; /* we are now a writer */ if (jcr->NumWriteVolumes == 0) { jcr->NumWriteVolumes = 1; } dev->VolCatInfo.VolCatJobs++; /* increment number of jobs on vol */ Dmsg4(100, "=== nwriters=%d nres=%d vcatjob=%d dev=%s\n", dev->num_writers, dev->num_reserved(), dev->VolCatInfo.VolCatJobs, dev->print_name()); dcr->dir_update_volume_info(false, false); /* send Volume info to Director */ ok = true; get_out: /* Don't plugin close here, we might have multiple writers */ dcr->clear_reserved(); dev->Unlock(); dev->Unlock_acquire(); Leave(200); return ok ? dcr : NULL; }
/* * Append Data sent from Client (FD/SD) * */ bool do_append_data(JCR *jcr) { int32_t n; int32_t file_index, stream, last_file_index; uint64_t stream_len; BSOCK *fd = jcr->file_bsock; bool ok = true; DEV_RECORD rec; char buf1[100], buf2[100]; DCR *dcr = jcr->dcr; DEVICE *dev; char ec[50]; POOLMEM *eblock = NULL; POOL_MEM errmsg(PM_EMSG); if (!dcr) { pm_strcpy(jcr->errmsg, _("DCR is NULL!!!\n")); Jmsg0(jcr, M_FATAL, 0, jcr->errmsg); return false; } dev = dcr->dev; if (!dev) { pm_strcpy(jcr->errmsg, _("DEVICE is NULL!!!\n")); Jmsg0(jcr, M_FATAL, 0, jcr->errmsg); return false; } Dmsg1(100, "Start append data. res=%d\n", dev->num_reserved()); memset(&rec, 0, sizeof(rec)); if (!fd->set_buffer_size(dcr->device->max_network_buffer_size, BNET_SETBUF_WRITE)) { jcr->setJobStatus(JS_ErrorTerminated); pm_strcpy(jcr->errmsg, _("Unable to set network buffer size.\n")); Jmsg0(jcr, M_FATAL, 0, jcr->errmsg); return false; } if (!acquire_device_for_append(dcr)) { jcr->setJobStatus(JS_ErrorTerminated); return false; } jcr->sendJobStatus(JS_Running); //ASSERT(dev->VolCatInfo.VolCatName[0]); if (dev->VolCatInfo.VolCatName[0] == 0) { Pmsg0(000, _("NULL Volume name. This shouldn't happen!!!\n")); } Dmsg1(50, "Begin append device=%s\n", dev->print_name()); begin_data_spool(dcr); begin_attribute_spool(jcr); Dmsg0(100, "Just after acquire_device_for_append\n"); //ASSERT(dev->VolCatInfo.VolCatName[0]); if (dev->VolCatInfo.VolCatName[0] == 0) { Pmsg0(000, _("NULL Volume name. This shouldn't happen!!!\n")); } /* * Write Begin Session Record */ if (!write_session_label(dcr, SOS_LABEL)) { Jmsg1(jcr, M_FATAL, 0, _("Write session label failed. ERR=%s\n"), dev->bstrerror()); jcr->setJobStatus(JS_ErrorTerminated); ok = false; } //ASSERT(dev->VolCatInfo.VolCatName[0]); if (dev->VolCatInfo.VolCatName[0] == 0) { Pmsg0(000, _("NULL Volume name. This shouldn't happen!!!\n")); } /* Tell File daemon to send data */ if (!fd->fsend(OK_data)) { berrno be; Jmsg1(jcr, M_FATAL, 0, _("Network send error to FD. ERR=%s\n"), be.bstrerror(fd->b_errno)); ok = false; } /* * Get Data from File daemon, write to device. To clarify what is * going on here. We expect: * - A stream header * - Multiple records of data * - EOD record * * The Stream header is just used to synchronize things, and * none of the stream header is written to tape. * The Multiple records of data, contain first the Attributes, * then after another stream header, the file data, then * after another stream header, the MD5 data if any. * * So we get the (stream header, data, EOD) three time for each * file. 1. for the Attributes, 2. for the file data if any, * and 3. for the MD5 if any. */ dcr->VolFirstIndex = dcr->VolLastIndex = 0; jcr->run_time = time(NULL); /* start counting time for rates */ GetMsg *qfd; qfd = New(GetMsg(jcr, fd, NULL, GETMSG_MAX_MSG_SIZE)); qfd->start_read_sock(); for (last_file_index = 0; ok && !jcr->is_job_canceled(); ) { /* Read Stream header from the File daemon. * The stream header consists of the following: * file_index (sequential Bacula file index, base 1) * stream (Bacula number to distinguish parts of data) * stream_len (Expected length of this stream. This * will be the size backed up if the file does not * grow during the backup. */ n = qfd->bget_msg(NULL); if (n <= 0) { if (n == BNET_SIGNAL && qfd->msglen == BNET_EOD) { Dmsg0(200, "Got EOD on reading header.\n"); break; /* end of data */ } Jmsg3(jcr, M_FATAL, 0, _("Error reading data header from FD. n=%d msglen=%d ERR=%s\n"), n, qfd->msglen, fd->bstrerror()); // ASX TODO the fd->bstrerror() can be related to the wrong error, I should Queue the error too possible_incomplete_job(jcr, last_file_index); ok = false; break; } if (sscanf(qfd->msg, "%ld %ld %lld", &file_index, &stream, &stream_len) != 3) { // TODO ASX already done in bufmsg, should reuse the values char buf[256]; Jmsg1(jcr, M_FATAL, 0, _("Malformed data header from FD: %s\n"), asciidump(qfd->msg, qfd->msglen, buf, sizeof(buf))); ok = false; possible_incomplete_job(jcr, last_file_index); break; } Dmsg3(890, "<filed: Header FilInx=%d stream=%d stream_len=%lld\n", file_index, stream, stream_len); /* * We make sure the file_index is advancing sequentially. * An incomplete job can start the file_index at any number. * otherwise, it must start at 1. */ if (jcr->rerunning && file_index > 0 && last_file_index == 0) { goto fi_checked; } Dmsg2(400, "file_index=%d last_file_index=%d\n", file_index, last_file_index); if (file_index > 0 && (file_index == last_file_index || file_index == last_file_index + 1)) { goto fi_checked; } Jmsg2(jcr, M_FATAL, 0, _("FI=%d from FD not positive or last_FI=%d\n"), file_index, last_file_index); possible_incomplete_job(jcr, last_file_index); ok = false; break; fi_checked: if (file_index != last_file_index) { jcr->JobFiles = file_index; last_file_index = file_index; } /* Read data stream from the File daemon. * The data stream is just raw bytes */ while ((n=qfd->bget_msg(NULL)) > 0 && !jcr->is_job_canceled()) { rec.VolSessionId = jcr->VolSessionId; rec.VolSessionTime = jcr->VolSessionTime; rec.FileIndex = file_index; rec.Stream = stream; rec.StreamLen = stream_len; rec.maskedStream = stream & STREAMMASK_TYPE; /* strip high bits */ rec.data_len = qfd->msglen; rec.data = qfd->msg; /* use message buffer */ Dmsg4(850, "before writ_rec FI=%d SessId=%d Strm=%s len=%d\n", rec.FileIndex, rec.VolSessionId, stream_to_ascii(buf1, rec.Stream,rec.FileIndex), rec.data_len); ok = dcr->write_record(&rec); if (!ok) { Dmsg2(90, "Got write_block_to_dev error on device %s. %s\n", dcr->dev->print_name(), dcr->dev->bstrerror()); break; } jcr->JobBytes += rec.data_len; /* increment bytes this job */ jcr->JobBytes += qfd->bmsg->jobbytes; // if the block as been downloaded, count it Dmsg4(850, "write_record FI=%s SessId=%d Strm=%s len=%d\n", FI_to_ascii(buf1, rec.FileIndex), rec.VolSessionId, stream_to_ascii(buf2, rec.Stream, rec.FileIndex), rec.data_len); send_attrs_to_dir(jcr, &rec); Dmsg0(650, "Enter bnet_get\n"); } Dmsg2(650, "End read loop with FD. JobFiles=%d Stat=%d\n", jcr->JobFiles, n); if (fd->is_error()) { if (!jcr->is_job_canceled()) { Dmsg1(350, "Network read error from FD. ERR=%s\n", fd->bstrerror()); Jmsg1(jcr, M_FATAL, 0, _("Network error reading from FD. ERR=%s\n"), fd->bstrerror()); possible_incomplete_job(jcr, last_file_index); } ok = false; break; } } qfd->wait_read_sock(); free_GetMsg(qfd); if (eblock != NULL) { free_pool_memory(eblock); } /* Create Job status for end of session label */ jcr->setJobStatus(ok?JS_Terminated:JS_ErrorTerminated); if (ok) { /* Terminate connection with Client */ fd->fsend(OK_append); do_client_commands(jcr); /* finish dialog with Client */ } else { fd->fsend("3999 Failed append\n"); } Dmsg1(200, "Write EOS label JobStatus=%c\n", jcr->JobStatus); /* * Check if we can still write. This may not be the case * if we are at the end of the tape or we got a fatal I/O error. */ if (ok || dev->can_write()) { if (!write_session_label(dcr, EOS_LABEL)) { /* Print only if ok and not cancelled to avoid spurious messages */ if (ok && !jcr->is_job_canceled()) { Jmsg1(jcr, M_FATAL, 0, _("Error writing end session label. ERR=%s\n"), dev->bstrerror()); possible_incomplete_job(jcr, last_file_index); } jcr->setJobStatus(JS_ErrorTerminated); ok = false; } /* Flush out final partial block of this session */ if (!dcr->write_final_block_to_device()) { /* Print only if ok and not cancelled to avoid spurious messages */ if (ok && !jcr->is_job_canceled()) { Jmsg2(jcr, M_FATAL, 0, _("Fatal append error on device %s: ERR=%s\n"), dev->print_name(), dev->bstrerror()); Dmsg0(100, _("Set ok=FALSE after write_final_block_to_device.\n")); possible_incomplete_job(jcr, last_file_index); } jcr->setJobStatus(JS_ErrorTerminated); ok = false; } } flush_jobmedia_queue(jcr); if (!ok && !jcr->is_JobStatus(JS_Incomplete)) { discard_data_spool(dcr); } else { /* Note: if commit is OK, the device will remain blocked */ commit_data_spool(dcr); } /* * Don't use time_t for job_elapsed as time_t can be 32 or 64 bits, * and the subsequent Jmsg() editing will break */ int32_t job_elapsed = time(NULL) - jcr->run_time; if (job_elapsed <= 0) { job_elapsed = 1; } Jmsg(dcr->jcr, M_INFO, 0, _("Elapsed time=%02d:%02d:%02d, Transfer rate=%s Bytes/second\n"), job_elapsed / 3600, job_elapsed % 3600 / 60, job_elapsed % 60, edit_uint64_with_suffix(jcr->JobBytes / job_elapsed, ec)); /* * Release the device -- and send final Vol info to DIR * and unlock it. */ release_device(dcr); if ((!ok || jcr->is_job_canceled()) && !jcr->is_JobStatus(JS_Incomplete)) { discard_attribute_spool(jcr); } else { commit_attribute_spool(jcr); } jcr->sendJobStatus(); /* update director */ Dmsg1(100, "return from do_append_data() ok=%d\n", ok); return ok; }
/********************************************************************* * Acquire device for reading. * The drive should have previously been reserved by calling * reserve_device_for_read(). We read the Volume label from the block and * leave the block pointers just after the label. * * Returns: false if failed for any reason * true if successful */ bool acquire_device_for_read(DCR *dcr) { DEVICE *dev; JCR *jcr = dcr->jcr; bool ok = false; bool tape_previously_mounted; VOL_LIST *vol; bool try_autochanger = true; int i; int vol_label_status; int retry = 0; Enter(rdbglvl); dev = dcr->dev; dev->Lock_read_acquire(); Dmsg2(rdbglvl, "dcr=%p dev=%p\n", dcr, dcr->dev); Dmsg2(rdbglvl, "MediaType dcr=%s dev=%s\n", dcr->media_type, dev->device->media_type); dev->dblock(BST_DOING_ACQUIRE); if (dev->num_writers > 0) { Jmsg2(jcr, M_FATAL, 0, _("Acquire read: num_writers=%d not zero. Job %d canceled.\n"), dev->num_writers, jcr->JobId); goto get_out; } /* Find next Volume, if any */ vol = jcr->VolList; if (!vol) { char ed1[50]; Jmsg(jcr, M_FATAL, 0, _("No volumes specified for reading. Job %s canceled.\n"), edit_int64(jcr->JobId, ed1)); goto get_out; } jcr->CurReadVolume++; for (i=1; i<jcr->CurReadVolume; i++) { vol = vol->next; } if (!vol) { Jmsg(jcr, M_FATAL, 0, _("Logic error: no next volume to read. Numvol=%d Curvol=%d\n"), jcr->NumReadVolumes, jcr->CurReadVolume); goto get_out; /* should not happen */ } set_dcr_from_vol(dcr, vol); if (generate_plugin_event(jcr, bsdEventDeviceOpen, dcr) != bRC_OK) { Jmsg(jcr, M_FATAL, 0, _("generate_plugin_event(bsdEventDeviceOpen) Failed\n")); goto get_out; } Dmsg2(rdbglvl, "Want Vol=%s Slot=%d\n", vol->VolumeName, vol->Slot); /* * If the MediaType requested for this volume is not the * same as the current drive, we attempt to find the same * device that was used to write the orginal volume. If * found, we switch to using that device. * * N.B. A lot of routines rely on the dcr pointer not changing * read_records.c even has multiple dcrs cached, so we take care * here to release all important parts of the dcr and re-acquire * them such as the block pointer (size may change), but we do * not release the dcr. */ Dmsg2(rdbglvl, "MediaType dcr=%s dev=%s\n", dcr->media_type, dev->device->media_type); if (dcr->media_type[0] && strcmp(dcr->media_type, dev->device->media_type) != 0) { RCTX rctx; DIRSTORE *store; int stat; Jmsg4(jcr, M_INFO, 0, _("Changing read device. Want Media Type=\"%s\" have=\"%s\"\n" " %s device=%s\n"), dcr->media_type, dev->device->media_type, dev->print_type(), dev->print_name()); Dmsg4(rdbglvl, "Changing read device. Want Media Type=\"%s\" have=\"%s\"\n" " %s device=%s\n", dcr->media_type, dev->device->media_type, dev->print_type(), dev->print_name()); generate_plugin_event(jcr, bsdEventDeviceClose, dcr); dev->dunblock(DEV_UNLOCKED); lock_reservations(); memset(&rctx, 0, sizeof(RCTX)); rctx.jcr = jcr; jcr->read_dcr = dcr; jcr->reserve_msgs = New(alist(10, not_owned_by_alist)); rctx.any_drive = true; rctx.device_name = vol->device; store = new DIRSTORE; memset(store, 0, sizeof(DIRSTORE)); store->name[0] = 0; /* No storage name */ bstrncpy(store->media_type, vol->MediaType, sizeof(store->media_type)); bstrncpy(store->pool_name, dcr->pool_name, sizeof(store->pool_name)); bstrncpy(store->pool_type, dcr->pool_type, sizeof(store->pool_type)); store->append = false; rctx.store = store; clean_device(dcr); /* clean up the dcr */ /* * Search for a new device */ stat = search_res_for_device(rctx); release_reserve_messages(jcr); /* release queued messages */ unlock_reservations(); if (stat == 1) { /* found new device to use */ /* * Switching devices, so acquire lock on new device, * then release the old one. */ dcr->dev->Lock_read_acquire(); /* lock new one */ dev->Unlock_read_acquire(); /* release old one */ dev = dcr->dev; /* get new device pointer */ dev->dblock(BST_DOING_ACQUIRE); dcr->VolumeName[0] = 0; Jmsg(jcr, M_INFO, 0, _("Media Type change. New read %s device %s chosen.\n"), dev->print_type(), dev->print_name()); Dmsg2(50, "Media Type change. New read %s device %s chosen.\n", dev->print_type(), dev->print_name()); if (generate_plugin_event(jcr, bsdEventDeviceOpen, dcr) != bRC_OK) { Jmsg(jcr, M_FATAL, 0, _("generate_plugin_event(bsdEventDeviceOpen) Failed\n")); goto get_out; } bstrncpy(dcr->VolumeName, vol->VolumeName, sizeof(dcr->VolumeName)); dcr->setVolCatName(vol->VolumeName); bstrncpy(dcr->media_type, vol->MediaType, sizeof(dcr->media_type)); dcr->VolCatInfo.Slot = vol->Slot; dcr->VolCatInfo.InChanger = vol->Slot > 0; bstrncpy(dcr->pool_name, store->pool_name, sizeof(dcr->pool_name)); bstrncpy(dcr->pool_type, store->pool_type, sizeof(dcr->pool_type)); } else { /* error */ Jmsg1(jcr, M_FATAL, 0, _("No suitable device found to read Volume \"%s\"\n"), vol->VolumeName); Dmsg1(rdbglvl, "No suitable device found to read Volume \"%s\"\n", vol->VolumeName); goto get_out; } } Dmsg2(rdbglvl, "MediaType dcr=%s dev=%s\n", dcr->media_type, dev->device->media_type); dev->clear_unload(); if (dev->vol && dev->vol->is_swapping()) { dev->vol->set_slot(vol->Slot); Dmsg3(rdbglvl, "swapping: slot=%d Vol=%s dev=%s\n", dev->vol->get_slot(), dev->vol->vol_name, dev->print_name()); } init_device_wait_timers(dcr); tape_previously_mounted = dev->can_read() || dev->can_append() || dev->is_labeled(); // tape_initially_mounted = tape_previously_mounted; /* Volume info is always needed because of VolType */ Dmsg1(rdbglvl, "dir_get_volume_info vol=%s\n", dcr->VolumeName); if (!dir_get_volume_info(dcr, GET_VOL_INFO_FOR_READ)) { Dmsg2(rdbglvl, "dir_get_vol_info failed for vol=%s: %s\n", dcr->VolumeName, jcr->errmsg); Jmsg1(jcr, M_WARNING, 0, "Read acquire: %s", jcr->errmsg); } dev->set_load(); /* set to load volume */ for ( ;; ) { /* If not polling limit retries */ if (!dev->poll && retry++ > 10) { break; } dev->clear_labeled(); /* force reread of label */ if (job_canceled(jcr)) { char ed1[50]; Mmsg1(dev->errmsg, _("Job %s canceled.\n"), edit_int64(jcr->JobId, ed1)); Jmsg(jcr, M_INFO, 0, dev->errmsg); goto get_out; /* error return */ } dcr->do_unload(); dcr->do_swapping(SD_READ); dcr->do_load(SD_READ); set_dcr_from_vol(dcr, vol); /* refresh dcr with desired volume info */ /* * This code ensures that the device is ready for * reading. If it is a file, it opens it. * If it is a tape, it checks the volume name */ Dmsg1(rdbglvl, "open vol=%s\n", dcr->VolumeName); if (!dev->open(dcr, OPEN_READ_ONLY)) { if (!dev->poll) { Jmsg4(jcr, M_WARNING, 0, _("Read open %s device %s Volume \"%s\" failed: ERR=%s\n"), dev->print_type(), dev->print_name(), dcr->VolumeName, dev->bstrerror()); } goto default_path; } Dmsg1(rdbglvl, "opened dev %s OK\n", dev->print_name()); /* Read Volume Label */ Dmsg0(rdbglvl, "calling read-vol-label\n"); vol_label_status = read_dev_volume_label(dcr); switch (vol_label_status) { case VOL_OK: Dmsg0(rdbglvl, "Got correct volume.\n"); ok = true; dev->VolCatInfo = dcr->VolCatInfo; /* structure assignment */ break; /* got it */ case VOL_IO_ERROR: Dmsg0(rdbglvl, "IO Error\n"); /* * Send error message generated by read_dev_volume_label() * only we really had a tape mounted. This supresses superfluous * error messages when nothing is mounted. */ if (tape_previously_mounted) { Jmsg(jcr, M_WARNING, 0, "Read acquire: %s", jcr->errmsg); } goto default_path; case VOL_TYPE_ERROR: Jmsg(jcr, M_FATAL, 0, dev->errmsg); goto get_out; case VOL_NAME_ERROR: Dmsg3(rdbglvl, "Vol name=%s want=%s drv=%s.\n", dev->VolHdr.VolumeName, dcr->VolumeName, dev->print_name()); if (dev->is_volume_to_unload()) { goto default_path; } dev->set_unload(); /* force unload of unwanted tape */ if (!unload_autochanger(dcr, -1)) { /* at least free the device so we can re-open with correct volume */ dev->close(); free_volume(dev); } dev->set_load(); /* Fall through */ default: Jmsg1(jcr, M_WARNING, 0, "Read acquire: %s", jcr->errmsg); default_path: Dmsg0(rdbglvl, "default path\n"); tape_previously_mounted = true; /* * If the device requires mount, close it, so the device can be ejected. */ if (dev->requires_mount()) { dev->close(); free_volume(dev); } /* Call autochanger only once unless ask_sysop called */ if (try_autochanger) { int stat; Dmsg2(rdbglvl, "calling autoload Vol=%s Slot=%d\n", dcr->VolumeName, dcr->VolCatInfo.Slot); stat = autoload_device(dcr, SD_READ, NULL); if (stat > 0) { try_autochanger = false; continue; /* try reading volume mounted */ } } /* Mount a specific volume and no other */ Dmsg0(rdbglvl, "calling dir_ask_sysop\n"); if (!dir_ask_sysop_to_mount_volume(dcr, SD_READ)) { goto get_out; /* error return */ } /* Volume info is always needed because of VolType */ Dmsg1(150, "dir_get_volume_info vol=%s\n", dcr->VolumeName); if (!dir_get_volume_info(dcr, GET_VOL_INFO_FOR_READ)) { Dmsg2(150, "dir_get_vol_info failed for vol=%s: %s\n", dcr->VolumeName, jcr->errmsg); Jmsg1(jcr, M_WARNING, 0, "Read acquire: %s", jcr->errmsg); } dev->set_load(); /* set to load volume */ try_autochanger = true; /* permit trying the autochanger again */ continue; /* try reading again */ } /* end switch */ break; } /* end for loop */ if (!ok) { Jmsg2(jcr, M_FATAL, 0, _("Too many errors trying to mount %s device %s for reading.\n"), dev->print_type(), dev->print_name()); goto get_out; } dev->clear_append(); dev->set_read(); jcr->sendJobStatus(JS_Running); Jmsg(jcr, M_INFO, 0, _("Ready to read from volume \"%s\" on %s device %s.\n"), dcr->VolumeName, dev->print_type(), dev->print_name()); get_out: dev->Lock(); dcr->clear_reserved(); /* If failed and not writing plugin close device */ if (!ok && dev->num_writers == 0 && dev->num_reserved() == 0) { generate_plugin_event(jcr, bsdEventDeviceClose, dcr); } /* * Normally we are blocked, but in at least one error case above * we are not blocked because we unsuccessfully tried changing * devices. */ if (dev->is_blocked()) { dev->dunblock(DEV_LOCKED); } else { dev->Unlock(); /* dunblock() unlock the device too */ } Dmsg2(rdbglvl, "dcr=%p dev=%p\n", dcr, dcr->dev); Dmsg2(rdbglvl, "MediaType dcr=%s dev=%s\n", dcr->media_type, dev->device->media_type); dev->Unlock_read_acquire(); Leave(rdbglvl); return ok; }