diff --git a/libnetutil/massdns.h b/libnetutil/massdns.h index 5fc06b22b..205d87037 100644 --- a/libnetutil/massdns.h +++ b/libnetutil/massdns.h @@ -265,8 +265,11 @@ struct Stats void reset() { servers = names = actual = ok = nx = sf = trans = dropped = system = 0; } + int statDone() const { + return ok + nx + sf + dropped; + } double getCompletion() const { - return (double) (ok + nx + sf + dropped) / actual; + return (double) statDone() / actual; } }; diff --git a/nmap_dns.cc b/nmap_dns.cc index 49457fed4..0bceb6420 100644 --- a/nmap_dns.cc +++ b/nmap_dns.cc @@ -84,7 +84,7 @@ void nmap_massdns_status(const DNS::Stats *stat) { if (keyWasPressed()) { assert(SPM != NULL); - SPM->printStats(stat->getCompletion(), NULL); + SPM->printStats(stat->statDone(), stat->actual, NULL); /* Because this can change with runtime interaction */ nmap_adjust_loglevel(o.packetTrace()); } diff --git a/nmap_ftp.cc b/nmap_ftp.cc index df0fe8540..5d9bc6f2e 100644 --- a/nmap_ftp.cc +++ b/nmap_ftp.cc @@ -341,11 +341,9 @@ void bounce_scan(Target *target, u16 *portarray, int numports, } } nextport: - if (SPM->mayBePrinted(NULL)) { - SPM->printStatsIfNecessary((double) i / numports, NULL); - } - else if (keyWasPressed()) { - SPM->printStats((double) i / numports, NULL); + if (!SPM->printStatsIfNecessary(i, numports, NULL) + && keyWasPressed()) { + SPM->printStats(i, numports, NULL); log_flush(LOG_STDOUT); } } diff --git a/nse_main.cc b/nse_main.cc index 2382688bd..85da7f983 100644 --- a/nse_main.cc +++ b/nse_main.cc @@ -161,10 +161,10 @@ static int scp (lua_State *L) switch (luaL_checkoption(L, 1, NULL, ops)) { case 0: /* printStats */ - progress->printStats((double) luaL_checknumber(L, 2), NULL); + progress->printStats(luaL_checkinteger(L, 2), luaL_checkinteger(L, 3), NULL); break; case 1: - progress->printStatsIfNecessary((double) luaL_checknumber(L, 2), NULL); + progress->printStatsIfNecessary(luaL_checkinteger(L, 2), luaL_checkinteger(L, 3), NULL); break; case 2: /*mayBePrinted */ lua_pushboolean(L, progress->mayBePrinted(NULL)); diff --git a/nse_main.lua b/nse_main.lua index 596aba9ba..fbee47c83 100644 --- a/nse_main.lua +++ b/nse_main.lua @@ -994,7 +994,7 @@ local function run (threads_iter) if total > 0 and cnse.key_was_pressed() then print_verbose(1, "Active NSE Script Threads: %d (%d waiting)", nr+nw, nw); - progress("printStats", 1-(nr+nw)/total); + progress("printStats", total - (nr+nw), total); if debugging() >= 2 then for co, thread in pairs(running) do thread:d("Running: %THREAD_AGAINST\n\t%s", @@ -1042,9 +1042,9 @@ local function run (threads_iter) end elseif total > 0 and progress "mayBePrinted" then if verbosity() > 1 or debugging() > 0 then - progress("printStats", 1-(nr+nw)/total); + progress("printStats", total - (nr+nw), total); else - progress("printStatsIfNecessary", 1-(nr+nw)/total); + progress("printStatsIfNecessary", total - (nr+nw), total); end end diff --git a/scan_engine.cc b/scan_engine.cc index 7fcd6bfee..62663d953 100644 --- a/scan_engine.cc +++ b/scan_engine.cc @@ -778,27 +778,24 @@ HostScanStats *UltraScanInfo::nextIncompleteHost() { /* Return a number between 0.0 and 1.0 inclusive indicating how much of the scan is done. */ double UltraScanInfo::getCompletionFraction() const { + size_t denominator = 0; + size_t numerator = this->getCompletionFraction(&denominator); + return (double) numerator / denominator; +} +size_t UltraScanInfo::getCompletionFraction(size_t *denominator) const { std::multiset::const_iterator hostI; - double total; + size_t done = send_rate_meter.getNumPackets(); + size_t total = done; - /* Add 1 for each completed host. */ - total = gstats->numtargets - numIncompleteHosts(); /* Get the completion fraction for each incomplete host. */ for (hostI = incompleteHosts.begin(); hostI != incompleteHosts.end(); hostI++) { const HostScanStats *host = *hostI; - int maxtries = host->allowedTryno(NULL, NULL) + 1; - double thishostpercdone; + int maxtries = host->allowedTryno(NULL, NULL); - // This is inexact (maxtries - 1) because numprobes_sent includes - // at least one try of ports_finished. - thishostpercdone = host->ports_finished * (maxtries - 1) + host->numprobes_sent; - thishostpercdone /= maxtries * gstats->numprobes; - if (thishostpercdone >= 0.9999) - thishostpercdone = 0.9999; - total += thishostpercdone; + total += maxtries * (gstats->numprobes - host->ports_finished); } - - return total / gstats->numtargets; + *denominator = total; + return done; } /* Initialize the state for ports that don't receive a response in all the @@ -2536,7 +2533,11 @@ static void printAnyStats(UltraScanInfo *USI) { } if (USI->SPM->mayBePrinted(&USI->now)) - USI->SPM->printStatsIfNecessary(USI->getCompletionFraction(), &USI->now); + { + size_t total = 0; + size_t done = USI->getCompletionFraction(&total); + USI->SPM->printStatsIfNecessary(done, total, &USI->now); + } } static void waitForResponses(UltraScanInfo *USI) { @@ -2800,7 +2801,9 @@ void ultra_scan(std::vector &Targets, const struct scan_lists *ports, if (keyWasPressed()) { // This prints something like // SYN Stealth Scan Timing: About 1.14% done; ETC: 15:01 (0:43:23 remaining); - USI.SPM->printStats(USI.getCompletionFraction(), NULL); + size_t total = 0; + size_t done = USI.getCompletionFraction(&total); + USI.SPM->printStats(done, total, NULL); if (o.debugging) { /* Don't update when getting the current rates, otherwise we can get anomalies (rates are too low) from having just done a potentially diff --git a/scan_engine.h b/scan_engine.h index 8de11db32..8ec67703b 100644 --- a/scan_engine.h +++ b/scan_engine.h @@ -594,6 +594,7 @@ public: HostScanStats *findHost(const struct sockaddr_storage *ss) const; double getCompletionFraction() const; + size_t getCompletionFraction(size_t *denominator) const; unsigned int numIncompleteHosts() const { return incompleteHosts.size(); diff --git a/service_scan.cc b/service_scan.cc index 59f889816..92d1bd2ba 100644 --- a/service_scan.cc +++ b/service_scan.cc @@ -217,6 +217,7 @@ public: std::list services_finished; // Services finished (discovered or not) std::list services_in_progress; // Services currently being probed std::list services_remaining; // Probes not started yet + size_t total_services; unsigned int ideal_parallelism; // Max (and desired) number of probes out at once. ScanProgressMeter *SPM; int num_hosts_timedout; // # of hosts timed out during (or before) scan @@ -1992,6 +1993,7 @@ ServiceGroup::ServiceGroup(std::vector &Targets, AllProbes *AP) { svc->proto = nxtport->proto; services_remaining.push_back(svc); } + total_services = services_remaining.size(); /* Check if any early responses can help */ for (std::vector::iterator it = target->earlySvcResponses.begin(); @@ -2232,17 +2234,13 @@ static void considerPrintingStats(ServiceGroup *SG) { /* Check for status requests */ if (keyWasPressed()) { nmap_adjust_loglevel(o.versionTrace()); - SG->SPM->printStats(SG->services_finished.size() / - ((double)SG->services_remaining.size() + SG->services_in_progress.size() + - SG->services_finished.size()), nsock_gettimeofday()); + SG->SPM->printStats(SG->services_finished.size(), SG->total_services, nsock_gettimeofday()); + } + else { + /* Perhaps this should be made more complex, but I suppose it should be + good enough for now. */ + SG->SPM->printStatsIfNecessary(SG->services_finished.size(), SG->total_services, nsock_gettimeofday()); } - - - /* Perhaps this should be made more complex, but I suppose it should be - good enough for now. */ - if (SG->SPM->mayBePrinted(nsock_gettimeofday())) { - SG->SPM->printStatsIfNecessary(SG->services_finished.size() / ((double)SG->services_remaining.size() + SG->services_in_progress.size() + SG->services_finished.size()), nsock_gettimeofday()); - } } /* Check if target is done (no more probes remaining for it in service group), @@ -2441,9 +2439,7 @@ static void servicescan_write_handler(nsock_pool nsp, nsock_event nse, void *myd // Check if a status message was requested if (keyWasPressed()) { - SG->SPM->printStats(SG->services_finished.size() / - ((double)SG->services_remaining.size() + SG->services_in_progress.size() + - SG->services_finished.size()), nsock_gettimeofday()); + SG->SPM->printStats(SG->services_finished.size(), SG->total_services, nsock_gettimeofday()); } diff --git a/timing.cc b/timing.cc index 994714106..c96b583e8 100644 --- a/timing.cc +++ b/timing.cc @@ -494,10 +494,12 @@ unsigned long long PacketRateMeter::getNumBytes(void) const { return (unsigned long long) byte_rate_meter.getTotal(); } -ScanProgressMeter::ScanProgressMeter(const char *stypestr) { +ScanProgressMeter::ScanProgressMeter(const char *stypestr) + : prev_done(0), prev_rate(0.0), last_time_left(0) { scantypestr = strdup(stypestr); gettimeofday(&begin, NULL); last_print_test = begin; + prev_time = begin; memset(&last_print, 0, sizeof(last_print)); memset(&last_est, 0, sizeof(last_est)); beginOrEndTask(&begin, NULL, true); @@ -532,44 +534,84 @@ bool ScanProgressMeter::mayBePrinted(const struct timeval *now) { if (last_print.tv_sec == 0) { /* We've never printed before -- the rules are less stringent */ - if (difftime(now->tv_sec, begin.tv_sec) > 30) + if (TIMEVAL_SEC_SUBTRACT(*now, begin) > 30) return true; else return false; } - if (difftime(now->tv_sec, last_print_test.tv_sec) < 3) + if (TIMEVAL_SEC_SUBTRACT(*now, last_print_test) < 3) return false; /* No point even checking too often */ /* We'd never want to print more than once per 30 seconds */ - if (difftime(now->tv_sec, last_print.tv_sec) < 30) + if (TIMEVAL_SEC_SUBTRACT(*now, last_print) < 30) return false; return true; } -/* Return an estimate of the time remaining if a process was started at begin - and is perc_done of the way finished. Returns inf if perc_done == 0.0. */ -static double estimate_time_left(double perc_done, - const struct timeval *begin, +// Cap ETA at 10 days. Beyond that is useless. +static const unsigned int MAX_ETA_SECONDS = 864000; + +/* Return the estimated seconds remaining */ +unsigned int ScanProgressMeter::estimate_time_left(size_t num_done, size_t num_total, const struct timeval *now) { - double time_used_s; - double time_needed_s; + if (num_done >= num_total) + return 0; + if (num_done < prev_done) + prev_done = num_done; + size_t completed = num_done - prev_done; + // Check for unrecovered stall + if (completed == 0 && prev_rate == 0.0) + return MAX_ETA_SECONDS; - time_used_s = difftime(now->tv_sec, begin->tv_sec); - time_needed_s = time_used_s / perc_done; + double time_since_prev = TIMEVAL_FSEC_SUBTRACT(*now, prev_time); + if (time_since_prev < 5.0 // Don't recalculate more often than every 5 seconds + && last_time_left > time_since_prev) // unless we've passed the last estimate + { + return last_time_left - time_since_prev; + } - return time_needed_s - time_used_s; + double rate = completed / time_since_prev; + + if (prev_rate == 0.0) { + // Either we're just starting out or we're coming back from a stall. + // In both cases, fall back to the old average time estimate. + double time_since_start = TIMEVAL_FSEC_SUBTRACT(*now, begin); + assert(time_since_start > 0.0); + if (time_since_start > 0.0) + prev_rate = num_done / time_since_start; + else + prev_rate = 1.0; // Bogus, but ought to be unreachable + } + + // Average the previous rate with the current rate + rate = 0.25 * rate + 0.75 * prev_rate; + assert(rate > 0.0); + + double remaining = (num_total - num_done) / rate; + if (remaining > (double) MAX_ETA_SECONDS) { + // Effectively stalled, signal with rate/prev_rate = 0.0 + rate = 0.0; + last_time_left = MAX_ETA_SECONDS; + } + else + last_time_left = remaining; + + prev_time = *now; + prev_done = num_done; + prev_rate = rate; + + return last_time_left; } /* Prints an estimate of when this scan will complete. It only does so if mayBePrinted() is true, and it seems reasonable to do so because the estimate has changed significantly. Returns whether or not a line was printed.*/ -bool ScanProgressMeter::printStatsIfNecessary(double perc_done, +bool ScanProgressMeter::printStatsIfNecessary(size_t num_done, size_t num_total, const struct timeval *now) { struct timeval tvtmp; - double time_left_s; bool printit = false; if (!now) { @@ -582,12 +624,11 @@ bool ScanProgressMeter::printStatsIfNecessary(double perc_done, last_print_test = *now; + double perc_done = (double) num_done / num_total; if (perc_done <= 0.003) return false; /* Need more info first */ - assert(perc_done <= 1.0); - - time_left_s = estimate_time_left(perc_done, &begin, now); + unsigned int time_left_s = estimate_time_left(num_done, num_total, now); if (time_left_s < 30) return false; /* No point in updating when it is virtually finished. */ @@ -609,32 +650,29 @@ bool ScanProgressMeter::printStatsIfNecessary(double perc_done, } if (printit) { - return printStats(perc_done, now); + return printStats_common(time_left_s, perc_done, now); } return false; } /* Prints an estimate of when this scan will complete. */ -bool ScanProgressMeter::printStats(double perc_done, +bool ScanProgressMeter::printStats(size_t num_done, size_t num_total, const struct timeval *now) { struct timeval tvtmp; - double time_left_s; - time_t timet; - struct tm ltime; - int err; if (!now) { gettimeofday(&tvtmp, NULL); now = (const struct timeval *) &tvtmp; } - last_print = *now; + double perc_done = (double) num_done / num_total; // If we're less than 1% done we probably don't have enough // data for decent timing estimates. Also with perc_done == 0 // these elements will be nonsensical. if (perc_done < 0.01) { + last_print = *now; log_write(LOG_STDOUT, "%s Timing: About %.2f%% done\n", scantypestr, perc_done * 100); xml_open_start_tag("taskprogress"); @@ -647,37 +685,51 @@ bool ScanProgressMeter::printStats(double perc_done, return true; } - /* Add 0.5 to get the effect of rounding in integer calculations. */ - time_left_s = estimate_time_left(perc_done, &begin, now) + 0.5; + unsigned int time_left_s = estimate_time_left(num_done, num_total, now); - last_est = *now; - last_est.tv_sec += (time_t)time_left_s; + return printStats_common(time_left_s, perc_done, now); +} - /* Get the estimated time of day at completion */ - timet = last_est.tv_sec; - err = n_localtime(&timet, <ime); +bool ScanProgressMeter::printStats_common(unsigned int time_left_s, double perc_done, const struct timeval *now) +{ + // Avoid saying something is 100.00% done when it's clearly not. + if (perc_done > 0.9999) + perc_done = 0.9999; - if (!err) { - log_write(LOG_STDOUT, "%s Timing: About %.2f%% done; ETC: %02d:%02d (%.f:%02.f:%02.f remaining)\n", - scantypestr, perc_done * 100, ltime.tm_hour, ltime.tm_min, - floor(time_left_s / 60.0 / 60.0), - floor(fmod(time_left_s / 60.0, 60.0)), - floor(fmod(time_left_s, 60.0))); - } - else { - log_write(LOG_STDERR, "Timing error: n_localtime(%f): %s\n", (double) timet, strerror(err)); - log_write(LOG_STDOUT, "%s Timing: About %.2f%% done; ETC: Unknown (%.f:%02.f:%02.f remaining)\n", - scantypestr, perc_done * 100, - floor(time_left_s / 60.0 / 60.0), - floor(fmod(time_left_s / 60.0, 60.0)), - floor(fmod(time_left_s, 60.0))); - } xml_open_start_tag("taskprogress"); xml_attribute("task", "%s", scantypestr); xml_attribute("time", "%lu", (unsigned long) now->tv_sec); xml_attribute("percent", "%.2f", perc_done * 100); - xml_attribute("remaining", "%.f", time_left_s); - xml_attribute("etc", "%lu", (unsigned long) last_est.tv_sec); + xml_attribute("remaining", "%u", time_left_s); + + if (time_left_s == MAX_ETA_SECONDS) { + log_write(LOG_STDOUT, "%s Timing: About %.2f%% done; ETC: Unknown (>10 days remaining)\n", + scantypestr, perc_done * 100); + } + else { + char etc_str[] = "Unknown"; + last_est = *now; + last_est.tv_sec += (time_t)time_left_s; + + /* Get the estimated time of day at completion */ + struct tm ltime; + time_t timet = last_est.tv_sec; + int err = n_localtime(&timet, <ime); + + last_print = *now; + if (!err) { + Snprintf(etc_str, sizeof(etc_str), "%02d:%02d", ltime.tm_hour, ltime.tm_min); + } + else { + log_write(LOG_STDERR, "Timing error: n_localtime(%f): %s\n", (double) timet, strerror(err)); + } + log_write(LOG_STDOUT, "%s Timing: About %.2f%% done; ETC: %s (%.f:%02.f:%02.f remaining)\n", + scantypestr, perc_done * 100, etc_str, + floor(time_left_s / 60.0 / 60.0), + floor(fmod(time_left_s / 60.0, 60.0)), + floor(fmod(time_left_s, 60.0))); + xml_attribute("etc", "%lu", (unsigned long) last_est.tv_sec); + } xml_close_empty_tag(); xml_newline(); log_flush(LOG_STDOUT|LOG_XML); diff --git a/timing.h b/timing.h index 61c23864c..0d9396a19 100644 --- a/timing.h +++ b/timing.h @@ -232,10 +232,10 @@ class ScanProgressMeter { so if mayBePrinted() is true, and it seems reasonable to do so because the estimate has changed significantly. Returns whether or not a line was printed.*/ - bool printStatsIfNecessary(double perc_done, const struct timeval *now); + bool printStatsIfNecessary(size_t num_done, size_t num_total, const struct timeval *now); /* Prints an estimate of when this scan will complete. */ - bool printStats(double perc_done, const struct timeval *now); + bool printStats(size_t num_done, size_t num_total, const struct timeval *now); /* Prints that this task is complete. */ bool endTask(const struct timeval *now, const char *additional_info) { return beginOrEndTask(now, additional_info, false); } @@ -246,8 +246,14 @@ class ScanProgressMeter { struct timeval last_print; /* The most recent time the ETC was printed */ char *scantypestr; struct timeval last_est; /* The latest PRINTED estimate */ + struct timeval prev_time; + size_t prev_done; + double prev_rate; + unsigned int last_time_left; bool beginOrEndTask(const struct timeval *now, const char *additional_info, bool beginning); + unsigned int estimate_time_left(size_t num_done, size_t num_total, const struct timeval *now); + bool printStats_common(unsigned int time_left_s, double perc_done, const struct timeval *now); }; #endif /* NMAP_TIMING_H */ diff --git a/traceroute.cc b/traceroute.cc index 4e5f6f45a..0014aadcd 100644 --- a/traceroute.cc +++ b/traceroute.cc @@ -237,7 +237,7 @@ public: int cancel_probes_above(u8 ttl); Hop *insert_hop(u8 ttl, const struct sockaddr_storage *addr, float rtt); void link_to(Hop *hop); - double completion_fraction() const; + unsigned int completion() const; private: void child_parent_ttl(u8 ttl, Hop **child, Hop **parent) const; @@ -289,7 +289,7 @@ public: void resolve_hops(); void transfer_hops(); - double completion_fraction() const; + unsigned int completion(unsigned int *total) const; private: netutil_eth_t *ethsd; @@ -491,11 +491,11 @@ void HostState::link_to(Hop *hop) { prev->parent = hop; } -double HostState::completion_fraction() const { +unsigned int HostState::completion() const { unsigned int i, n; if (this->is_finished()) - return 1.0; + return sent_ttls.size(); n = 0; for (i = 0; i < sent_ttls.size(); i++) { @@ -503,7 +503,7 @@ double HostState::completion_fraction() const { n++; } - return (double) n / sent_ttls.size(); + return n; } void HostState::child_parent_ttl(u8 ttl, Hop **child, Hop **parent) const { @@ -1414,14 +1414,18 @@ Probe *TracerouteState::lookup_probe( return NULL; } -double TracerouteState::completion_fraction() const { +unsigned int TracerouteState::completion(unsigned int *total) const { std::vector::const_iterator it; - double sum; + unsigned int complete = 0; + unsigned int sum = 0; - sum = 0.0; for (it = hosts.begin(); it != hosts.end(); it++) - sum += (*it)->completion_fraction(); - return sum / hosts.size(); + { + complete += (*it)->completion(); + sum += (*it)->sent_ttls.size(); + } + *total = sum; + return complete; } /* This is a special case of traceroute when all the targets are directly @@ -1479,8 +1483,11 @@ static int traceroute_remote(std::vector targets) { global_state.cull_timeouts(); global_state.remove_finished_hosts(); - if (keyWasPressed()) - SPM.printStats(global_state.completion_fraction(), NULL); + if (keyWasPressed()) { + unsigned int complete, total; + complete = global_state.completion(&total); + SPM.printStats(complete, total, NULL); + } } SPM.endTask(NULL, NULL);