From: Kern Sibbald Date: Mon, 5 Dec 2005 11:49:34 +0000 (+0000) Subject: - Remove argument from create_bacula_database for SQLite as it X-Git-Tag: Release-1.38.3~41 X-Git-Url: https://git.sur5r.net/?a=commitdiff_plain;h=c4c4407e509b5d807b7cffa82e00cabeb80b04b6;p=bacula%2Fbacula - Remove argument from create_bacula_database for SQLite as it caused an error. - Add back index code so that two drive autochangers can get a second tape. - Change a bunch of debug levels to aid debugging autochangers. - Fix reservation so that mutexes are properly applied. - Rework reservation algorithm so that two drives can be used at the same time. git-svn-id: https://bacula.svn.sourceforge.net/svnroot/bacula/trunk@2646 91ce42f0-d328-0410-95d8-f526ca767f89 --- diff --git a/bacula/kes-1.39 b/bacula/kes-1.39 index 8ced04a928..e3fdfdccc1 100644 --- a/bacula/kes-1.39 +++ b/bacula/kes-1.39 @@ -4,6 +4,16 @@ General: Changes to 1.39.2: +05Dec05 +- Remove argument from create_bacula_database for SQLite as it + caused an error. +- Add back index code so that two drive autochangers can get + a second tape. +- Change a bunch of debug levels to aid debugging autochangers. +- Fix reservation so that mutexes are properly applied. +- Rework reservation algorithm so that two drives can be used + at the same time. +04Dec05 - Landon merged his data encription changes into the HEAD - Apply days keyword patch from Alexander.Bergolth at wu-wien.ac.at If this patch is applied, the number of days can be specified with diff --git a/bacula/src/cats/create_bacula_database.in b/bacula/src/cats/create_bacula_database.in index 6a3775f823..7ee767b133 100644 --- a/bacula/src/cats/create_bacula_database.in +++ b/bacula/src/cats/create_bacula_database.in @@ -5,7 +5,7 @@ # if test xsqlite = x@DB_NAME@ -o xsqlite3 = x@DB_NAME@ ; then echo "Creating SQLite database" - @scriptdir@/create_@DB_NAME@_database $* + @scriptdir@/create_@DB_NAME@_database else if test xmysql = x@DB_NAME@ ; then echo "Creating MySQL database" diff --git a/bacula/src/dird/catreq.c b/bacula/src/dird/catreq.c index d8c879cef7..955d0469cc 100644 --- a/bacula/src/dird/catreq.c +++ b/bacula/src/dird/catreq.c @@ -122,7 +122,7 @@ void catalog_request(JCR *jcr, BSOCK *bs) ok = db_get_pool_record(jcr, jcr->db, &pr); if (ok) { mr.PoolId = pr.PoolId; - ok = find_next_volume_for_append(jcr, &mr, true /*permit create new vol*/); + ok = find_next_volume_for_append(jcr, &mr, index, true /*permit create new vol*/); } /* * Send Find Media response to Storage daemon diff --git a/bacula/src/dird/next_vol.c b/bacula/src/dird/next_vol.c index 9a64bf3921..922bb92435 100644 --- a/bacula/src/dird/next_vol.c +++ b/bacula/src/dird/next_vol.c @@ -35,7 +35,7 @@ * MEDIA_DBR mr (zeroed out) * create -- whether or not to create a new volume */ -int find_next_volume_for_append(JCR *jcr, MEDIA_DBR *mr, bool create) +int find_next_volume_for_append(JCR *jcr, MEDIA_DBR *mr, int index, bool create) { int retry = 0; bool ok; @@ -58,7 +58,7 @@ int find_next_volume_for_append(JCR *jcr, MEDIA_DBR *mr, bool create) /* * 1. Look for volume with "Append" status. */ - ok = db_find_next_volume(jcr, jcr->db, 1, InChanger, mr); + ok = db_find_next_volume(jcr, jcr->db, index, InChanger, mr); Dmsg2(100, "catreq after find_next_vol ok=%d FW=%d\n", ok, mr->FirstWritten); if (!ok) { /* diff --git a/bacula/src/dird/protos.h b/bacula/src/dird/protos.h index d2e36f2201..4417a800a7 100644 --- a/bacula/src/dird/protos.h +++ b/bacula/src/dird/protos.h @@ -117,7 +117,7 @@ extern int bget_dirmsg(BSOCK *bs); extern void wait_for_storage_daemon_termination(JCR *jcr); /* next_vol.c */ -int find_next_volume_for_append(JCR *jcr, MEDIA_DBR *mr, bool create); +int find_next_volume_for_append(JCR *jcr, MEDIA_DBR *mr, int index, bool create); bool has_volume_expired(JCR *jcr, MEDIA_DBR *mr); void check_if_volume_valid_or_recyclable(JCR *jcr, MEDIA_DBR *mr, const char **reason); diff --git a/bacula/src/dird/ua_output.c b/bacula/src/dird/ua_output.c index f3e1916692..809b8009cf 100644 --- a/bacula/src/dird/ua_output.c +++ b/bacula/src/dird/ua_output.c @@ -407,18 +407,18 @@ static int do_list_cmd(UAContext *ua, const char *cmd, e_list_type llist) /* List next volume */ } else if (strcasecmp(ua->argk[i], N_("nextvol")) == 0 || strcasecmp(ua->argk[i], N_("nextvolume")) == 0) { - n = 1; + n = 1; j = find_arg_with_value(ua, N_("days")); if (j >= 0) { n = atoi(ua->argv[j]); - if ((n < 0) || (n > 50)) { - bsendmsg(ua, _("Ignoring illegal value for days.\n")); - n = 1; - } + if ((n < 0) || (n > 50)) { + bsendmsg(ua, _("Ignoring illegal value for days.\n")); + n = 1; + } } list_nextvol(ua, n); } else if (strcasecmp(ua->argk[i], N_("limit")) == 0 - || strcasecmp(ua->argk[i], N_("days")) == 0) { + || strcasecmp(ua->argk[i], N_("days")) == 0) { /* Ignore it */ } else { bsendmsg(ua, _("Unknown list keyword: %s\n"), NPRT(ua->argk[i])); @@ -465,14 +465,14 @@ static bool list_nextvol(UAContext *ua, int ndays) memset(&pr, 0, sizeof(pr)); pr.PoolId = jcr->PoolId; if (! db_get_pool_record(ua->jcr, ua->db, &pr)) { - strcpy(pr.Name, "*UnknownPool*"); + strcpy(pr.Name, "*UnknownPool*"); } - if (!find_next_volume_for_append(jcr, &mr, 0)) { - bsendmsg(ua, _("Could not find next Volume for Job %s (%s, %s).\n"), - job->hdr.name, pr.Name, level_to_str(run->level)); + if (!find_next_volume_for_append(jcr, &mr, 1, false/*no create*/)) { + bsendmsg(ua, _("Could not find next Volume for Job %s (%s, %s).\n"), + job->hdr.name, pr.Name, level_to_str(run->level)); } else { bsendmsg(ua, - _("The next Volume to be used by Job \"%s\" (%s, %s) will be %s\n"), + _("The next Volume to be used by Job \"%s\" (%s, %s) will be %s\n"), job->hdr.name, pr.Name, level_to_str(run->level), mr.VolumeName); found = true; } @@ -483,7 +483,7 @@ static bool list_nextvol(UAContext *ua, int ndays) } if (!found) { bsendmsg(ua, _("Could not find next Volume for Job %s.\n"), - job->hdr.name); + job->hdr.name); return false; } return true; @@ -523,58 +523,58 @@ RUN *find_next_run(RUN *run, JOB *job, time_t &runtime, int ndays) * Find runs in next 24 hours */ for (day = 0; day <= ndays; day++) { - future = now + (day * 60 * 60 * 24); + future = now + (day * 60 * 60 * 24); - /* Break down the time into components */ - localtime_r(&future, &tm); - mday = tm.tm_mday - 1; - wday = tm.tm_wday; - month = tm.tm_mon; - wom = mday / 7; - woy = tm_woy(future); + /* Break down the time into components */ + localtime_r(&future, &tm); + mday = tm.tm_mday - 1; + wday = tm.tm_wday; + month = tm.tm_mon; + wom = mday / 7; + woy = tm_woy(future); - is_scheduled = bit_is_set(mday, run->mday) && bit_is_set(wday, run->wday) && + is_scheduled = bit_is_set(mday, run->mday) && bit_is_set(wday, run->wday) && bit_is_set(month, run->month) && bit_is_set(wom, run->wom) && bit_is_set(woy, run->woy); #ifdef xxx - Dmsg2(000, "day=%d is_scheduled=%d\n", day, is_scheduled); - Dmsg1(000, "bit_set_mday=%d\n", bit_is_set(mday, run->mday)); - Dmsg1(000, "bit_set_wday=%d\n", bit_is_set(wday, run->wday)); - Dmsg1(000, "bit_set_month=%d\n", bit_is_set(month, run->month)); - Dmsg1(000, "bit_set_wom=%d\n", bit_is_set(wom, run->wom)); - Dmsg1(000, "bit_set_woy=%d\n", bit_is_set(woy, run->woy)); + Dmsg2(000, "day=%d is_scheduled=%d\n", day, is_scheduled); + Dmsg1(000, "bit_set_mday=%d\n", bit_is_set(mday, run->mday)); + Dmsg1(000, "bit_set_wday=%d\n", bit_is_set(wday, run->wday)); + Dmsg1(000, "bit_set_month=%d\n", bit_is_set(month, run->month)); + Dmsg1(000, "bit_set_wom=%d\n", bit_is_set(wom, run->wom)); + Dmsg1(000, "bit_set_woy=%d\n", bit_is_set(woy, run->woy)); #endif - if (is_scheduled) { /* Jobs scheduled on that day */ + if (is_scheduled) { /* Jobs scheduled on that day */ #ifdef xxx - char buf[300], num[10]; - bsnprintf(buf, sizeof(buf), "tm.hour=%d hour=", tm.tm_hour); - for (i=0; i<24; i++) { - if (bit_is_set(i, run->hour)) { - bsnprintf(num, sizeof(num), "%d ", i); - bstrncat(buf, num, sizeof(buf)); - } - } - bstrncat(buf, "\n", sizeof(buf)); - Dmsg1(000, "%s", buf); + char buf[300], num[10]; + bsnprintf(buf, sizeof(buf), "tm.hour=%d hour=", tm.tm_hour); + for (i=0; i<24; i++) { + if (bit_is_set(i, run->hour)) { + bsnprintf(num, sizeof(num), "%d ", i); + bstrncat(buf, num, sizeof(buf)); + } + } + bstrncat(buf, "\n", sizeof(buf)); + Dmsg1(000, "%s", buf); #endif - /* find time (time_t) job is to be run */ - localtime_r(&future, &runtm); - for (i= 0; i < 24; i++) { - if (bit_is_set(i, run->hour)) { - runtm.tm_hour = i; - runtm.tm_min = run->minute; - runtm.tm_sec = 0; - runtime = mktime(&runtm); - Dmsg2(200, "now=%d runtime=%d\n", now, runtime); - if ((runtime > now) && (runtime < endtime)) { - Dmsg2(200, "Found it level=%d %c\n", run->level, run->level); - return run; /* found it, return run resource */ - } - } - } - } + /* find time (time_t) job is to be run */ + localtime_r(&future, &runtm); + for (i= 0; i < 24; i++) { + if (bit_is_set(i, run->hour)) { + runtm.tm_hour = i; + runtm.tm_min = run->minute; + runtm.tm_sec = 0; + runtime = mktime(&runtm); + Dmsg2(200, "now=%d runtime=%d\n", now, runtime); + if ((runtime > now) && (runtime < endtime)) { + Dmsg2(200, "Found it level=%d %c\n", run->level, run->level); + return run; /* found it, return run resource */ + } + } + } + } } } /* end for loop over runs */ /* Nothing found */ diff --git a/bacula/src/dird/ua_status.c b/bacula/src/dird/ua_status.c index f1a07d4ed4..d242f6ff2b 100644 --- a/bacula/src/dird/ua_status.c +++ b/bacula/src/dird/ua_status.c @@ -380,7 +380,7 @@ static void prt_runtime(UAContext *ua, sched_pkt *sp) } if (ok) { mr.PoolId = jcr->PoolId; - ok = find_next_volume_for_append(jcr, &mr, 0); + ok = find_next_volume_for_append(jcr, &mr, 1, false/*no create*/); } if (!ok) { bstrncpy(mr.VolumeName, "*unknown*", sizeof(mr.VolumeName)); diff --git a/bacula/src/lib/bpipe.c b/bacula/src/lib/bpipe.c index 39109bf222..ca82913663 100644 --- a/bacula/src/lib/bpipe.c +++ b/bacula/src/lib/bpipe.c @@ -269,11 +269,11 @@ int run_program(char *prog, int wait, POOLMEM *results) stat1 = ferror(bpipe->rfd); } if (stat1 < 0) { - Dmsg2(100, "Run program fgets stat=%d ERR=%s\n", stat1, strerror(errno)); + Dmsg2(150, "Run program fgets stat=%d ERR=%s\n", stat1, strerror(errno)); } else if (stat1 != 0) { - Dmsg1(100, "Run program fgets stat=%d\n", stat1); + Dmsg1(150, "Run program fgets stat=%d\n", stat1); if (bpipe->timer_id) { - Dmsg1(100, "Run program fgets killed=%d\n", bpipe->timer_id->killed); + Dmsg1(150, "Run program fgets killed=%d\n", bpipe->timer_id->killed); /* NB: I'm not sure it is really useful for run_program. Without the * following lines run_program would not detect if the program was killed * by the watchdog. */ @@ -288,7 +288,7 @@ int run_program(char *prog, int wait, POOLMEM *results) } stat2 = close_bpipe(bpipe); stat1 = stat2 != 0 ? stat2 : stat1; - Dmsg1(100, "Run program returning %d\n", stat1); + Dmsg1(150, "Run program returning %d\n", stat1); return stat1; } @@ -356,7 +356,7 @@ int run_program_full_output(char *prog, int wait, POOLMEM *results) } else if (stat1 != 0) { Dmsg1(900, "Run program fgets stat=%d\n", stat1); if (bpipe->timer_id) { - Dmsg1(100, "Run program fgets killed=%d\n", bpipe->timer_id->killed); + Dmsg1(150, "Run program fgets killed=%d\n", bpipe->timer_id->killed); if (bpipe->timer_id->killed) { pm_strcat(tmp, _("Program killed by Bacula watchdog (timeout)\n")); stat1 = ETIME; diff --git a/bacula/src/stored/acquire.c b/bacula/src/stored/acquire.c index e0ce9c5be3..4741c58375 100644 --- a/bacula/src/stored/acquire.c +++ b/bacula/src/stored/acquire.c @@ -86,7 +86,7 @@ void free_dcr(DCR *dcr) if (dcr->reserved_device) { lock_device(dev); dev->reserved_device--; - Dmsg1(200, "Dec reserve=%d\n", dev->reserved_device); + Dmsg1(100, "Dec reserve=%d\n", dev->reserved_device); dcr->reserved_device = false; if (dev->num_writers < 0) { Jmsg1(dcr->jcr, M_ERROR, 0, _("Hey! num_writers=%d!!!!\n"), dev->num_writers); @@ -298,12 +298,6 @@ DCR *acquire_device_for_append(DCR *dcr) Dmsg1(190, "acquire_append device is %s\n", dev->is_tape()?"tape": (dev->is_dvd()?"DVD":"disk")); - if (dcr->reserved_device) { - dev->reserved_device--; - Dmsg1(200, "Dec reserve=%d\n", dev->reserved_device); - dcr->reserved_device = false; - } - /* * With the reservation system, this should not happen */ @@ -402,6 +396,13 @@ get_out: free_dcr(dcr); dcr = NULL; ok_out: + P(dev->mutex); + if (dcr->reserved_device) { + dev->reserved_device--; + Dmsg1(100, "Dec reserve=%d\n", dev->reserved_device); + dcr->reserved_device = false; + } + V(dev->mutex); dev->unblock(); return dcr; } @@ -424,7 +425,7 @@ bool release_device(DCR *dcr) /* if device is reserved, job never started, so release the reserve here */ if (dcr->reserved_device) { dev->reserved_device--; - Dmsg1(200, "Dec reserve=%d\n", dev->reserved_device); + Dmsg1(100, "Dec reserve=%d\n", dev->reserved_device); dcr->reserved_device = false; } diff --git a/bacula/src/stored/append.c b/bacula/src/stored/append.c index 39ec6d3903..539f63ead5 100644 --- a/bacula/src/stored/append.c +++ b/bacula/src/stored/append.c @@ -45,7 +45,7 @@ bool do_append_data(JCR *jcr) char buf1[100], buf2[100]; - Dmsg0(100, "Start append data.\n"); + Dmsg1(100, "Start append data. res=%d\n", dev->reserved_device); memset(&rec, 0, sizeof(rec)); diff --git a/bacula/src/stored/dev.c b/bacula/src/stored/dev.c index 7dc108cab7..30a54538b2 100644 --- a/bacula/src/stored/dev.c +++ b/bacula/src/stored/dev.c @@ -653,7 +653,8 @@ bool rewind_dev(DEVICE *dev) struct mtop mt_com; unsigned int i; - Dmsg2(29, "rewind_dev fd=%d %s\n", dev->fd, dev->print_name()); + Dmsg3(29, "rewind_dev res=%d fd=%d %s\n", dev->reserved_device, + dev->fd, dev->print_name()); if (dev->fd < 0) { if (!dev->is_dvd()) { /* In case of major error, the fd is not open on DVD, so we don't want to abort. */ dev->dev_errno = EBADF; @@ -1700,7 +1701,7 @@ int flush_dev(DEVICE *dev) static void do_close(DEVICE *dev) { - Dmsg1(29, "really close_dev %s\n", dev->print_name()); + Dmsg1(100, "really close_dev %s\n", dev->print_name()); if (dev->fd >= 0) { close(dev->fd); } @@ -1754,7 +1755,8 @@ void DEVICE::close() /*if (fd >= 0 && use_count == 1) {*/ /* No need to check if fd >= 0: it is checked again * in do_close, and do_close MUST be called for volumes - * splitted in parts, even if fd == -1. */ + * split in parts, even if fd == -1. + */ if (use_count == 1) { do_close(this); } else if (use_count > 0) { diff --git a/bacula/src/stored/job.c b/bacula/src/stored/job.c index 5faac87ba3..1176ef45f8 100644 --- a/bacula/src/stored/job.c +++ b/bacula/src/stored/job.c @@ -134,7 +134,7 @@ bool run_cmd(JCR *jcr) struct timespec timeout; int errstat; - Dmsg1(100, "Run_cmd: %s\n", jcr->dir_bsock->msg); + Dmsg1(200, "Run_cmd: %s\n", jcr->dir_bsock->msg); /* The following jobs don't need the FD */ switch (jcr->JobType) { case JT_MIGRATE: diff --git a/bacula/src/stored/label.c b/bacula/src/stored/label.c index 306f143289..6de8a603db 100644 --- a/bacula/src/stored/label.c +++ b/bacula/src/stored/label.c @@ -66,9 +66,9 @@ int read_dev_volume_label(DCR *dcr) bool want_ansi_label; bool have_ansi_label = false; - Dmsg3(100, "Enter read_volume_label device=%s vol=%s dev_Vol=%s\n", - dev->print_name(), VolName, dev->VolHdr.VolumeName[0]?dev->VolHdr.VolumeName: - "*NULL*"); + Dmsg4(100, "Enter read_volume_label res=%d device=%s vol=%s dev_Vol=%s\n", + dev->reserved_device, dev->print_name(), VolName, + dev->VolHdr.VolumeName[0]?dev->VolHdr.VolumeName:"*NULL*"); if (!dev->is_open()) { Emsg0(M_ABORT, 0, _("BAD call to read_dev_volume_label\n")); @@ -85,7 +85,7 @@ int read_dev_volume_label(DCR *dcr) if (!dev->poll && jcr->label_errors++ > 100) { Jmsg(jcr, M_FATAL, 0, _("Too many tries: %s"), jcr->errmsg); } - Dmsg0(100, "return VOL_NAME_ERROR\n"); + Dmsg0(150, "return VOL_NAME_ERROR\n"); stat = VOL_NAME_ERROR; goto bail_out; } @@ -194,7 +194,7 @@ int read_dev_volume_label(DCR *dcr) if (!dev->poll && jcr->label_errors++ > 100) { Jmsg(jcr, M_FATAL, 0, _("Too many tries: %s"), jcr->errmsg); } - Dmsg0(100, "return VOL_LABEL_ERROR\n"); + Dmsg0(150, "return VOL_LABEL_ERROR\n"); stat = VOL_LABEL_ERROR; goto bail_out; } @@ -215,7 +215,7 @@ int read_dev_volume_label(DCR *dcr) if (!dev->poll && jcr->label_errors++ > 100) { Jmsg(jcr, M_FATAL, 0, "Too many tries: %s", jcr->errmsg); } - Dmsg0(100, "return VOL_NAME_ERROR\n"); + Dmsg0(150, "return VOL_NAME_ERROR\n"); stat = VOL_NAME_ERROR; goto bail_out; } @@ -242,7 +242,7 @@ int read_dev_volume_label(DCR *dcr) bail_out: empty_block(block); rewind_dev(dev); - Dmsg1(100, "return %d\n", stat); + Dmsg1(150, "return %d\n", stat); return stat; } @@ -302,7 +302,7 @@ bool write_new_volume_label_to_dev(DCR *dcr, const char *VolName, const char *Po if (dev->open(dcr, OPEN_READ_WRITE) < 0) { goto bail_out; } - Dmsg1(100, "Label type=%d\n", dev->label_type); + Dmsg1(150, "Label type=%d\n", dev->label_type); if (!rewind_dev(dev)) { free_volume(dev); memset(&dev->VolHdr, 0, sizeof(dev->VolHdr)); @@ -446,7 +446,7 @@ bool rewrite_volume_label(DCR *dcr, bool recycle) dev->VolCatInfo.VolCatWrites = 1; dev->VolCatInfo.VolCatReads = 1; } - Dmsg0(100, "dir_update_vol_info. Set Append\n"); + Dmsg0(150, "dir_update_vol_info. Set Append\n"); bstrncpy(dev->VolCatInfo.VolCatStatus, "Append", sizeof(dev->VolCatInfo.VolCatStatus)); if (!dir_update_volume_info(dcr, true)) { /* indicate doing relabel */ return false; @@ -523,7 +523,7 @@ static void create_volume_label_record(DCR *dcr, DEV_RECORD *rec) rec->VolSessionId = jcr->VolSessionId; rec->VolSessionTime = jcr->VolSessionTime; rec->Stream = jcr->NumVolumes; - Dmsg2(100, "Created Vol label rec: FI=%s len=%d\n", FI_to_ascii(buf, rec->FileIndex), + Dmsg2(150, "Created Vol label rec: FI=%s len=%d\n", FI_to_ascii(buf, rec->FileIndex), rec->data_len); } @@ -668,7 +668,7 @@ bool write_session_label(DCR *dcr, int label) * read the next block). */ if (!can_write_record_to_block(block, rec)) { - Dmsg0(100, "Cannot write session label to block.\n"); + Dmsg0(150, "Cannot write session label to block.\n"); if (!write_block_to_device(dcr)) { Dmsg0(90, "Got session label write_block_to_dev error.\n"); /* ****FIXME***** errno is not set here */ diff --git a/bacula/src/stored/mount.c b/bacula/src/stored/mount.c index a70e13e219..5e642ff0bb 100644 --- a/bacula/src/stored/mount.c +++ b/bacula/src/stored/mount.c @@ -48,7 +48,7 @@ bool mount_next_write_volume(DCR *dcr, bool release) JCR *jcr = dcr->jcr; DEV_BLOCK *block = dcr->block; - Dmsg1(100, "Enter mount_next_volume(release=%d)\n", release); + Dmsg1(150, "Enter mount_next_volume(release=%d)\n", release); init_device_wait_timers(dcr); @@ -74,7 +74,7 @@ mount_next_vol: } recycle = false; if (release) { - Dmsg0(100, "mount_next_volume release=1\n"); + Dmsg0(150, "mount_next_volume release=1\n"); release_volume(dcr); ask = true; /* ask operator to mount tape */ } @@ -94,7 +94,7 @@ mount_next_vol: if (job_canceled(jcr)) { return false; } - Dmsg3(100, "After find_next_append. Vol=%s Slot=%d Parts=%d\n", + Dmsg3(150, "After find_next_append. Vol=%s Slot=%d Parts=%d\n", dcr->VolCatInfo.VolCatName, dcr->VolCatInfo.Slot, dcr->VolCatInfo.VolCatParts); /* @@ -115,7 +115,7 @@ mount_next_vol: autochanger = false; dcr->VolCatInfo.Slot = 0; } - Dmsg1(100, "autoload_dev returns %d\n", autochanger); + Dmsg1(200, "autoload_dev returns %d\n", autochanger); /* * If we autochanged to correct Volume or (we have not just * released the Volume AND we can automount) we go ahead @@ -123,25 +123,25 @@ mount_next_vol: * we will err, recurse and ask the operator the next time. */ if (!release && dev->is_tape() && dev_cap(dev, CAP_AUTOMOUNT)) { - Dmsg0(100, "(1)Ask=0"); + Dmsg0(150, "(1)Ask=0\n"); ask = false; /* don't ask SYSOP this time */ } /* Don't ask if not removable */ if (!dev_cap(dev, CAP_REM)) { - Dmsg0(100, "(2)Ask=0"); + Dmsg0(150, "(2)Ask=0\n"); ask = false; } - Dmsg2(100, "Ask=%d autochanger=%d\n", ask, autochanger); + Dmsg2(150, "Ask=%d autochanger=%d\n", ask, autochanger); release = true; /* release next time if we "recurse" */ if (ask && !dir_ask_sysop_to_mount_volume(dcr)) { - Dmsg0(100, "Error return ask_sysop ...\n"); + Dmsg0(150, "Error return ask_sysop ...\n"); return false; /* error return */ } if (job_canceled(jcr)) { return false; } - Dmsg1(100, "want vol=%s\n", dcr->VolumeName); + Dmsg1(150, "want vol=%s\n", dcr->VolumeName); if (dev->poll && dev_cap(dev, CAP_CLOSEONPOLL)) { force_close_device(dev); @@ -177,7 +177,7 @@ read_volume: return false; } - Dmsg2(100, "Want dirVol=%s dirStat=%s\n", dcr->VolumeName, + Dmsg2(150, "Want dirVol=%s dirStat=%s\n", dcr->VolumeName, dcr->VolCatInfo.VolCatStatus); /* * At this point, dev->VolCatInfo has what is in the drive, if anything, @@ -185,7 +185,7 @@ read_volume: */ switch (vol_label_status) { case VOL_OK: - Dmsg1(100, "Vol OK name=%s\n", dcr->VolumeName); + Dmsg1(150, "Vol OK name=%s\n", dcr->VolumeName); memcpy(&dev->VolCatInfo, &dcr->VolCatInfo, sizeof(dev->VolCatInfo)); recycle = strcmp(dev->VolCatInfo.VolCatStatus, "Recycle") == 0; break; /* got a Volume */ @@ -200,7 +200,7 @@ read_volume: goto mount_next_vol; } - Dmsg1(100, "Vol NAME Error Name=%s\n", dcr->VolumeName); + Dmsg1(150, "Vol NAME Error Name=%s\n", dcr->VolumeName); /* If polling and got a previous bad name, ignore it */ if (dev->poll && strcmp(dev->BadVolName, dev->VolHdr.VolumeName) == 0) { ask = true; @@ -238,7 +238,7 @@ read_volume: /* This was not the volume we expected, but it is OK with * the Director, so use it. */ - Dmsg1(100, "want new name=%s\n", dcr->VolumeName); + Dmsg1(150, "want new name=%s\n", dcr->VolumeName); memcpy(&dev->VolCatInfo, &dcr->VolCatInfo, sizeof(dev->VolCatInfo)); recycle = strcmp(dev->VolCatInfo.VolCatStatus, "Recycle") == 0; break; /* got a Volume */ @@ -267,15 +267,15 @@ read_volume: if (dev_cap(dev, CAP_LABEL) && (dcr->VolCatInfo.VolCatBytes == 0 || (!dev->is_tape() && strcmp(dcr->VolCatInfo.VolCatStatus, "Recycle") == 0))) { - Dmsg0(100, "Create volume label\n"); + Dmsg0(150, "Create volume label\n"); /* Create a new Volume label and write it to the device */ if (!write_new_volume_label_to_dev(dcr, dcr->VolumeName, dcr->pool_name)) { - Dmsg0(100, "!write_vol_label\n"); + Dmsg0(150, "!write_vol_label\n"); mark_volume_in_error(dcr); goto mount_next_vol; } - Dmsg0(100, "dir_update_vol_info. Set Append\n"); + Dmsg0(150, "dir_update_vol_info. Set Append\n"); /* Copy Director's info into the device info */ memcpy(&dev->VolCatInfo, &dcr->VolCatInfo, sizeof(dev->VolCatInfo)); if (!dir_update_volume_info(dcr, true)) { /* indicate tape labeled */ @@ -363,7 +363,7 @@ read_volume: } } dev->VolCatInfo.VolCatMounts++; /* Update mounts */ - Dmsg1(100, "update volinfo mounts=%d\n", dev->VolCatInfo.VolCatMounts); + Dmsg1(150, "update volinfo mounts=%d\n", dev->VolCatInfo.VolCatMounts); if (!dir_update_volume_info(dcr, false)) { return false; } @@ -381,7 +381,7 @@ read_volume: */ #ifdef xxx if (dev->is_dvd()) { - Dmsg2(100, "DVD/File sanity check addr=%u vs endblock=%u\n", (unsigned int)dev->file_addr, (unsigned int)dev->VolCatInfo.EndBlock); + Dmsg2(150, "DVD/File sanity check addr=%u vs endblock=%u\n", (unsigned int)dev->file_addr, (unsigned int)dev->VolCatInfo.EndBlock); if (dev->file_addr == dev->VolCatInfo.EndBlock+1) { Jmsg(jcr, M_INFO, 0, _("Ready to append to end of Volume \"%s\" at file address=%u.\n"), dcr->VolumeName, (unsigned int)dev->file_addr); @@ -401,7 +401,7 @@ read_volume: empty_block(block); /* we used it for reading so set for write */ } dev->set_append(); - Dmsg0(100, "set APPEND, normal return from read_dev_for_append\n"); + Dmsg0(150, "set APPEND, normal return from read_dev_for_append\n"); return true; } @@ -417,7 +417,7 @@ void mark_volume_in_error(DCR *dcr) dcr->VolumeName); memcpy(&dev->VolCatInfo, &dcr->VolCatInfo, sizeof(dev->VolCatInfo)); bstrncpy(dev->VolCatInfo.VolCatStatus, "Error", sizeof(dev->VolCatInfo.VolCatStatus)); - Dmsg0(100, "dir_update_vol_info. Set Error.\n"); + Dmsg0(150, "dir_update_vol_info. Set Error.\n"); dir_update_volume_info(dcr, false); } diff --git a/bacula/src/stored/reserve.c b/bacula/src/stored/reserve.c index f38d223fb1..f852e6f1e5 100644 --- a/bacula/src/stored/reserve.c +++ b/bacula/src/stored/reserve.c @@ -362,6 +362,7 @@ static bool use_storage_cmd(JCR *jcr) * Wiffle through them and find one that can do the backup. */ if (ok) { +#ifdef OLD_ALGORITHM /* * First look for an exact match of Volume name as the * tape may already be mounted. @@ -401,6 +402,36 @@ static bool use_storage_cmd(JCR *jcr) goto done; } } +#else /* NEW SEARCH ALGORITHM */ + rctx.do_not_wait = true; + if (!jcr->PreferMountedVols) { + /* Look for unused drives in autochangers */ + rctx.PreferMountedVols = false; + rctx.exact_match = false; + rctx.available_autochanger = true; + if ((ok = find_suitable_device_for_job(jcr, rctx))) { + goto done; + } + /* Look through all drives */ + rctx.available_autochanger = false; + if ((ok = find_suitable_device_for_job(jcr, rctx))) { + goto done; + } + } + /* Look for an exact match all drives */ + rctx.PreferMountedVols = false; + rctx.exact_match = true; + rctx.available_autochanger = false; + if ((ok = find_suitable_device_for_job(jcr, rctx))) { + goto done; + } + /* Wait for any drive anywhere */ + rctx.exact_match = false; + rctx.do_not_wait = false; + if ((ok = find_suitable_device_for_job(jcr, rctx))) { + goto done; + } +#endif if (verbose) { unbash_spaces(dir->msg); pm_strcpy(jcr->errmsg, dir->msg); @@ -453,6 +484,9 @@ bool find_suitable_device_for_job(JCR *jcr, RCTX &rctx) DIRSTORE *store; char *device_name; + Dmsg4(100, "PrefMnt=%d exact=%d no_wait=%d availchgr=%d\n", + rctx.PreferMountedVols, rctx.exact_match, rctx.do_not_wait, + rctx.available_autochanger); init_jcr_device_wait_timers(jcr); for ( ;; ) { int can_wait = false; @@ -539,7 +573,13 @@ static int search_res_for_device(RCTX &rctx) continue; } POOL_MEM dev_name; - Dmsg1(100, "Device %s opened.\n", rctx.device_name); + if (rctx.store->append == SD_APPEND) { + Dmsg2(100, "Device %s reserved=%d.\n", rctx.device_name, + rctx.jcr->dcr->dev->reserved_device); + } else { + Dmsg2(100, "Device %s reserved=%d.\n", rctx.device_name, + rctx.jcr->read_dcr->dev->reserved_device); + } pm_strcpy(dev_name, rctx.device->hdr.name); bash_spaces(dev_name); ok = bnet_fsend(dir, OK_device, dev_name.c_str()); /* Return real device name */ @@ -584,7 +624,8 @@ static int reserve_device(RCTX &rctx) } return -1; /* no use waiting */ } - Dmsg1(100, "Found device %s\n", rctx.device->hdr.name); + Dmsg2(100, "Try reserve %s jobid=%d\n", rctx.device->hdr.name, + rctx.jcr->JobId); dcr = new_dcr(rctx.jcr, rctx.device->dev); if (!dcr) { BSOCK *dir = rctx.jcr->dir_bsock; @@ -600,30 +641,35 @@ static int reserve_device(RCTX &rctx) if (rctx.exact_match && !rctx.have_volume) { dcr->any_volume = true; if (dir_find_next_appendable_volume(dcr)) { - Dmsg1(200, "Looking for Volume=%s\n", dcr->VolumeName); + Dmsg1(100, "Looking for Volume=%s\n", dcr->VolumeName); bstrncpy(rctx.VolumeName, dcr->VolumeName, sizeof(rctx.VolumeName)); rctx.have_volume = true; } else { - Dmsg0(200, "No next volume found\n"); + Dmsg0(100, "No next volume found\n"); rctx.VolumeName[0] = 0; } } ok = reserve_device_for_append(dcr, rctx); if (ok) { rctx.jcr->dcr = dcr; + Dmsg5(100, "Reserved=%d dev_name=%s mediatype=%s pool=%s ok=%d\n", + dcr->dev->reserved_device, + dcr->dev_name, dcr->media_type, dcr->pool_name, ok); } } else { ok = reserve_device_for_read(dcr); if (ok) { rctx.jcr->read_dcr = dcr; + Dmsg5(100, "Read reserved=%d dev_name=%s mediatype=%s pool=%s ok=%d\n", + dcr->dev->reserved_device, + dcr->dev_name, dcr->media_type, dcr->pool_name, ok); } } if (!ok) { free_dcr(dcr); + Dmsg0(100, "Not OK.\n"); return 0; } - Dmsg4(100, "Reserved dev_name=%s mediatype=%s pool=%s ok=%d\n", - dcr->dev_name, dcr->media_type, dcr->pool_name, ok); return 1; } @@ -641,7 +687,7 @@ static bool reserve_device_for_read(DCR *dcr) ASSERT(dcr); - dev->block(BST_DOING_ACQUIRE); + P(dev->mutex); if (is_device_unmounted(dev)) { Dmsg1(200, "Device %s is BLOCKED due to user unmount.\n", dev->print_name()); @@ -663,7 +709,7 @@ static bool reserve_device_for_read(DCR *dcr) ok = true; bail_out: - dev->unblock(); + V(dev->mutex); return ok; } @@ -691,7 +737,7 @@ static bool reserve_device_for_append(DCR *dcr, RCTX &rctx) ASSERT(dcr); - dev->block(BST_DOING_ACQUIRE); + P(dev->mutex); if (dev->can_read()) { Mmsg1(jcr->errmsg, _("Device %s is busy reading.\n"), dev->print_name()); @@ -705,20 +751,21 @@ static bool reserve_device_for_append(DCR *dcr, RCTX &rctx) goto bail_out; } - Dmsg1(190, "reserve_append device is %s\n", dev->is_tape()?"tape":"disk"); + Dmsg1(100, "reserve_append device is %s\n", dev->is_tape()?"tape":"disk"); if (can_reserve_drive(dcr, rctx) != 1) { - Dmsg1(100, "%s", jcr->errmsg); + Dmsg0(100, "can_reserve_drive!=1\n"); goto bail_out; } dev->reserved_device++; - Dmsg1(200, "Inc reserve=%d\n", dev->reserved_device); + Dmsg3(100, "Inc reserve=%d dev=%s %p\n", dev->reserved_device, + dev->print_name(), dev); dcr->reserved_device = true; ok = true; bail_out: - dev->unblock(); + V(dev->mutex); return ok; } @@ -732,19 +779,24 @@ static int can_reserve_drive(DCR *dcr, RCTX &rctx) DEVICE *dev = dcr->dev; JCR *jcr = dcr->jcr; + /* If he wants a free drive, but this one is busy, no go */ + if (!rctx.PreferMountedVols && dev->is_busy()) { + Dmsg1(100, "!prefMnt && busy. JobId=%d\n", jcr->JobId); + return 0; + } + Dmsg3(100, "prefmnt=%d busy=%d res=%d\n", rctx.PreferMountedVols, + dev->is_busy(), dev->reserved_device); + /* Check for prefer mounted volumes */ if (rctx.PreferMountedVols && !dev->VolHdr.VolumeName[0] && dev->is_tape()) { - Mmsg0(jcr->errmsg, _("Want mounted Volume, drive is empty\n")); - Dmsg0(200, "want mounted -- no vol\n"); + Dmsg1(100, "want mounted -- no vol JobId=%d\n", jcr->JobId); return 0; /* No volume mounted */ } /* Check for exact Volume name match */ if (rctx.exact_match && rctx.have_volume && strcmp(dev->VolHdr.VolumeName, rctx.VolumeName) != 0) { - Mmsg2(jcr->errmsg, _("Not exact match have=%s want=%s\n"), - dev->VolHdr.VolumeName, rctx.VolumeName); - Dmsg2(200, "Not exact match have=%s want=%s\n", + Dmsg2(100, "Not exact match have=%s want=%s\n", dev->VolHdr.VolumeName, rctx.VolumeName); return 0; } @@ -753,6 +805,8 @@ static int can_reserve_drive(DCR *dcr, RCTX &rctx) if (rctx.available_autochanger && dev->num_writers == 0 && dev->VolHdr.VolumeName[0] == 0) { /* Device is available but not yet reserved, reserve it for us */ + Dmsg2(100, "Res Unused autochanger %s JobId=%d.\n", + dev->print_name(), jcr->JobId); bstrncpy(dev->pool_name, dcr->pool_name, sizeof(dev->pool_name)); bstrncpy(dev->pool_type, dcr->pool_type, sizeof(dev->pool_type)); return 1; /* reserve drive */ @@ -768,13 +822,12 @@ static int can_reserve_drive(DCR *dcr, RCTX &rctx) if (strcmp(dev->pool_name, dcr->pool_name) == 0 && strcmp(dev->pool_type, dcr->pool_type) == 0) { /* OK, compatible device */ - Dmsg0(200, "got dev: num_writers=0, reserved, pool matches\n"); + Dmsg2(100, "got dev: %s num_writers=0, reserved, pool matches JobId=%d\n", + dev->print_name(), jcr->JobId); return 1; } else { /* Drive not suitable for us */ - Mmsg2(jcr->errmsg, _("Drive busy wrong pool: num_writers=0, reserved, pool=%s wanted=%s\n"), - dev->pool_name, dcr->pool_name); - Dmsg2(200, "busy: num_writers=0, reserved, pool=%s wanted=%s\n", + Dmsg2(100, "busy: num_writers=0, reserved, pool=%s wanted=%s\n", dev->pool_name, dcr->pool_name); return 0; /* wait */ } @@ -782,16 +835,19 @@ static int can_reserve_drive(DCR *dcr, RCTX &rctx) /* Device in append mode, check if changing pool */ if (strcmp(dev->pool_name, dcr->pool_name) == 0 && strcmp(dev->pool_type, dcr->pool_type) == 0) { - Dmsg0(200, "got dev: num_writers=0, can_append, pool matches\n"); + Dmsg2(100, "got dev: %s num_writers=0, can_append, pool matches. JobId=%d\n", + dev->print_name(), jcr->JobId); /* OK, compatible device */ return 1; } else { /* Changing pool, unload old tape if any in drive */ - Dmsg0(200, "got dev: num_writers=0, not reserved, pool change, unload changer\n"); + Dmsg0(100, "got dev: num_writers=0, not reserved, pool change, unload changer\n"); unload_autochanger(dcr, 0); } } /* Device is available but not yet reserved, reserve it for us */ + Dmsg2(100, "Dev avail reserved %s JobId=%d\n", dev->print_name(), + jcr->JobId); bstrncpy(dev->pool_name, dcr->pool_name, sizeof(dev->pool_name)); bstrncpy(dev->pool_type, dcr->pool_type, sizeof(dev->pool_type)); return 1; /* reserve drive */ @@ -802,18 +858,16 @@ static int can_reserve_drive(DCR *dcr, RCTX &rctx) * available if pool is the same). */ if (dev->can_append() || dev->num_writers > 0) { - Dmsg0(190, "device already in append.\n"); /* Yes, now check if we want the same Pool and pool type */ if (strcmp(dev->pool_name, dcr->pool_name) == 0 && strcmp(dev->pool_type, dcr->pool_type) == 0) { - Dmsg0(200, "got dev: num_writers>=0, can_append, pool matches\n"); + Dmsg2(100, "got dev: %s num_writers>=0, can_append, pool matches. JobId=%d\n", + dev->print_name(), jcr->JobId); /* OK, compatible device */ return 1; } else { /* Drive not suitable for us */ - Mmsg(jcr->errmsg, _("Wanted Pool \"%s\", but device %s is using Pool \"%s\" .\n"), - dcr->pool_name, dev->print_name(), dev->pool_name); - Dmsg2(200, "busy: num_writers>0, can_append, pool=%s wanted=%s\n", + Dmsg2(100, "busy: num_writers>0, can_append, pool=%s wanted=%s\n", dev->pool_name, dcr->pool_name); return 0; /* wait */ } @@ -822,6 +876,6 @@ static int can_reserve_drive(DCR *dcr, RCTX &rctx) Jmsg0(jcr, M_FATAL, 0, _("Logic error!!!! Should not get here.\n")); return -1; /* error, should not get here */ } - + Dmsg2(100, "No reserve %s JobId=%d\n", dev->print_name(), jcr->JobId); return 0; } diff --git a/bacula/src/version.h b/bacula/src/version.h index 39b53383cf..78d0faa2ac 100644 --- a/bacula/src/version.h +++ b/bacula/src/version.h @@ -4,8 +4,8 @@ #undef VERSION #define VERSION "1.39.2" -#define BDATE "04 December 2005" -#define LSMDATE "04Dec05" +#define BDATE "05 December 2005" +#define LSMDATE "05Dec05" /* Debug flags */ #undef DEBUG