/*
* 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;
}