69 #define REPHIST_PRIVATE
85 #include "core/or/or_circuit_st.h"
98 #define STABILITY_EPSILON 0.0001
101 #define STABILITY_ALPHA 0.95
103 #define STABILITY_INTERVAL (12*60*60)
133 time_t start_of_downtime;
134 unsigned long weighted_uptime;
135 unsigned long total_weighted_time;
181 static time_t started_tracking_stability = 0;
229 const uint16_t at_port, time_t when)
233 char tbuf[ISO_TIME_LEN+1];
234 int addr_changed, port_changed;
237 tor_assert((!at_addr && !at_port) || (at_addr && at_port));
244 if (!started_tracking_stability)
245 started_tracking_stability = time(NULL);
250 if (hist->start_of_downtime) {
254 log_info(
LD_HIST,
"Router %s is now Running; it had been down since %s.",
257 log_info(
LD_HIST,
" (Paradoxically, it was already Running too.)");
259 down_length = when - hist->start_of_downtime;
260 hist->total_weighted_time += down_length;
261 hist->start_of_downtime = 0;
262 }
else if (addr_changed || port_changed) {
274 penalty = (int)(fresh_interval + live_interval) / 2;
277 log_info(
LD_HIST,
"Router %s still seems Running, but its address appears "
278 "to have changed since the last time it was reachable. I'm "
279 "going to treat it as having been down for %d seconds",
286 log_debug(
LD_HIST,
"Router %s is still Running; it has been Running "
289 log_info(
LD_HIST,
"Router %s is now Running; it was previously untracked",
304 char tbuf[ISO_TIME_LEN+1];
306 if (!started_tracking_stability)
307 started_tracking_stability = time(NULL);
318 if (run_length < 0) {
319 unsigned long penalty = -run_length;
320 #define SUBTRACT_CLAMPED(var, penalty) \
321 do { (var) = (var) < (penalty) ? 0 : (var) - (penalty); } while (0)
324 SUBTRACT_CLAMPED(hist->weighted_uptime, penalty);
327 hist->weighted_uptime += run_length;
328 hist->total_weighted_time += run_length;
331 log_info(
LD_HIST,
"Router %s is now non-Running: it had previously been "
332 "Running since %s. Its total weighted uptime is %lu/%lu.",
334 hist->total_weighted_time);
336 if (!hist->start_of_downtime) {
337 hist->start_of_downtime = when;
340 log_info(
LD_HIST,
"Router %s is now non-Running; it was previously "
346 log_info(
LD_HIST,
"Router %s is still non-Running; it has been "
363 hist->weighted_uptime = 0;
371 digestmap_iter_t *orhist_it;
390 log_info(
LD_HIST,
"Discounting all old stability info by a factor of %f",
395 !digestmap_iter_done(orhist_it);
396 orhist_it = digestmap_iter_next(
history_map,orhist_it)) {
397 digestmap_iter_get(orhist_it, &digest1, &hist_p);
404 hist->weighted_uptime = (
unsigned long)(hist->weighted_uptime * alpha);
405 hist->total_weighted_time = (
unsigned long)
406 (hist->total_weighted_time * alpha);
423 total_weights += 1.0;
430 return total / total_weights;
438 long total = hist->total_weighted_time;
441 }
else if (hist->start_of_downtime) {
442 total += (when - hist->start_of_downtime);
452 long total = hist->total_weighted_time;
453 long up = hist->weighted_uptime;
459 }
else if (hist->start_of_downtime) {
460 total += (when - hist->start_of_downtime);
470 return ((
double) up) / total;
534 return started_tracking_stability < time(NULL) - 4*60*60;
543 digestmap_iter_t *orhist_it;
544 const char *name1, *digest1;
552 tor_log(severity,
LD_HIST,
"--------------- Dumping history information:");
555 !digestmap_iter_done(orhist_it);
556 orhist_it = digestmap_iter_next(
history_map,orhist_it)) {
559 digestmap_iter_get(orhist_it, &digest1, &or_history_p);
570 "OR %s [%s]: wmtbf %lu:%02lu:%02lu",
572 stability/3600, (stability/60)%60, stability%60);
585 digestmap_iter_t *orhist_it;
589 while (!digestmap_iter_done(orhist_it)) {
591 digestmap_iter_get(orhist_it, &d1, &or_history_p);
592 or_history = or_history_p;
594 should_remove = authority ?
597 : (or_history->
changed < before);
599 orhist_it = digestmap_iter_next_rmv(
history_map, orhist_it);
603 orhist_it = digestmap_iter_next(
history_map, orhist_it);
615 char time_buf[ISO_TIME_LEN+1];
617 digestmap_iter_t *orhist_it;
625 char *filename = get_datadir_fname(
"router-stability");
642 #define PUT(s) STMT_BEGIN if (fputs((s),f)<0) goto err; STMT_END
643 #define PRINTF(args) STMT_BEGIN if (fprintf args <0) goto err; STMT_END
648 PRINTF((f,
"stored-at %s\n", time_buf));
650 if (started_tracking_stability) {
652 PRINTF((f,
"tracked-since %s\n", time_buf));
656 PRINTF((f,
"last-downrated %s\n", time_buf));
665 !digestmap_iter_done(orhist_it);
666 orhist_it = digestmap_iter_next(
history_map,orhist_it)) {
668 const char *t = NULL;
669 digestmap_iter_get(orhist_it, &digest, &or_history_p);
680 "Relay '%s' is listed as up in rephist, but it's not in "
681 "our routerlist. Correcting.", dbuf);
685 PRINTF((f,
"R %s\n", dbuf));
690 PRINTF((f,
"+MTBF %lu %.5f%s%s\n",
692 t ?
" S=" :
"", t ? t :
""));
694 if (hist->start_of_downtime > 0) {
698 PRINTF((f,
"+WFU %lu %lu%s%s\n",
699 hist->weighted_uptime, hist->total_weighted_time,
700 t ?
" S=" :
"", t ? t :
""));
720 for ( ; i < smartlist_len(sl); ++i) {
721 const char *line = smartlist_get(sl, i);
739 strlcpy(b, s,
sizeof(b));
756 correct_time(time_t t, time_t now, time_t stored_at, time_t started_measuring)
758 if (t < started_measuring - 24*60*60*365)
760 else if (t < started_measuring)
761 return started_measuring;
762 else if (t > stored_at)
765 long run_length = stored_at - t;
766 t = (time_t)(now - run_length);
767 if (t < started_measuring)
768 t = started_measuring;
780 const char *line = NULL;
782 time_t last_downrated = 0, stored_at = 0, tracked_since = 0;
783 time_t latest_possible_start = now;
787 char *filename = get_datadir_fname(
"router-stability");
798 const char *firstline;
799 if (smartlist_len(lines)>4) {
800 firstline = smartlist_get(lines, 0);
803 10, -1, LONG_MAX, NULL, NULL);
806 if (format != 1 && format != 2) {
808 "Unrecognized format in mtbf history file. Skipping.");
811 for (i = 1; i < smartlist_len(lines); ++i) {
812 line = smartlist_get(lines, i);
813 if (!strcmp(line,
"data"))
816 if (
parse_iso_time(line+strlen(
"last-downrated "), &last_downrated)<0)
817 log_warn(
LD_HIST,
"Couldn't parse downrate time in mtbf "
822 log_warn(
LD_HIST,
"Couldn't parse stored time in mtbf "
826 if (
parse_iso_time(line+strlen(
"tracked-since "), &tracked_since)<0)
827 log_warn(
LD_HIST,
"Couldn't parse started-tracking time in mtbf "
831 if (last_downrated > now)
832 last_downrated = now;
833 if (tracked_since > now)
837 log_warn(
LD_HIST,
"No stored time recorded.");
841 if (line && !strcmp(line,
"data"))
846 for (; i < smartlist_len(lines); ++i) {
849 char mtbf_timebuf[ISO_TIME_LEN+1];
850 char wfu_timebuf[ISO_TIME_LEN+1];
851 time_t start_of_run = 0;
852 time_t start_of_downtime = 0;
853 int have_mtbf = 0, have_wfu = 0;
856 long wt_uptime = 0, total_wt_time = 0;
859 line = smartlist_get(lines, i);
860 if (!strcmp(line,
"."))
863 mtbf_timebuf[0] =
'\0';
864 wfu_timebuf[0] =
'\0';
867 n =
tor_sscanf(line,
"%40s %ld %lf S=%10s %8s",
868 hexbuf, &wrl, &trw, mtbf_timebuf, mtbf_timebuf+11);
869 if (n != 3 && n != 5) {
876 int mtbf_idx, wfu_idx;
879 strlcpy(hexbuf, line+2,
sizeof(hexbuf));
883 const char *mtbfline = smartlist_get(lines, mtbf_idx);
884 n =
tor_sscanf(mtbfline,
"+MTBF %lu %lf S=%10s %8s",
885 &wrl, &trw, mtbf_timebuf, mtbf_timebuf+11);
886 if (n == 2 || n == 4) {
889 log_warn(
LD_HIST,
"Couldn't scan +MTBF line %s",
894 const char *wfuline = smartlist_get(lines, wfu_idx);
895 n =
tor_sscanf(wfuline,
"+WFU %lu %lu S=%10s %8s",
896 &wt_uptime, &total_wt_time,
897 wfu_timebuf, wfu_timebuf+11);
898 if (n == 2 || n == 4) {
901 log_warn(
LD_HIST,
"Couldn't scan +WFU line %s",
escaped(wfuline));
919 if (mtbf_timebuf[0]) {
920 mtbf_timebuf[10] =
' ';
922 log_warn(
LD_HIST,
"Couldn't parse time %s",
928 latest_possible_start = (time_t)(hist->
start_of_run - wrl);
934 if (wfu_timebuf[0]) {
935 wfu_timebuf[10] =
' ';
937 log_warn(
LD_HIST,
"Couldn't parse time %s",
escaped(wfu_timebuf));
940 hist->start_of_downtime =
correct_time(start_of_downtime, now, stored_at,
942 hist->weighted_uptime = wt_uptime;
943 hist->total_weighted_time = total_wt_time;
945 if (strcmp(line,
"."))
946 log_warn(
LD_HIST,
"Truncated MTBF file.");
948 if (tracked_since < 86400*365)
949 tracked_since = latest_possible_start;
952 started_tracking_stability = tracked_since;
959 smartlist_free(lines);
967 #define EXIT_STATS_ROUND_UP_BYTES 1024
969 #define EXIT_STATS_ROUND_UP_STREAMS 4
971 #define EXIT_STATS_NUM_PORTS 65536
973 #define EXIT_STATS_TOP_N_PORTS 10
1026 return (*(
int*)x - *(
int*)y);
1035 int i, j, top_elements = 0, cur_min_idx = 0, cur_port;
1038 uint64_t cur_bytes = 0, other_read = 0, other_written = 0,
1039 total_read = 0, total_written = 0;
1040 uint32_t total_streams = 0, other_streams = 0;
1041 smartlist_t *written_strings, *read_strings, *streams_strings;
1042 char *written_string, *read_string, *streams_string;
1043 char t[ISO_TIME_LEN+1];
1082 if (cur_bytes == 0) {
1086 top_bytes[top_elements] = cur_bytes;
1087 top_ports[top_elements++] = i;
1088 }
else if (cur_bytes > top_bytes[cur_min_idx]) {
1089 top_bytes[cur_min_idx] = cur_bytes;
1090 top_ports[cur_min_idx] = i;
1095 for (j = 1; j < top_elements; j++) {
1096 if (top_bytes[j] < top_bytes[cur_min_idx]) {
1106 other_read = total_read;
1107 other_written = total_written;
1108 other_streams = total_streams;
1111 qsort(top_ports, top_elements,
sizeof(
int),
compare_int_);
1112 for (j = 0; j < top_elements; j++) {
1113 cur_port = top_ports[j];
1144 other_written /= 1024;
1163 smartlist_free(written_strings);
1164 smartlist_free(read_strings);
1165 smartlist_free(streams_strings);
1170 "exit-kibibytes-written %s\n"
1171 "exit-kibibytes-read %s\n"
1172 "exit-streams-opened %s\n",
1197 log_info(
LD_HIST,
"Writing exit port statistics to disk.");
1225 log_debug(
LD_HIST,
"Written %lu bytes and read %lu bytes to/from an "
1226 "exit connection to port %d.",
1227 (
unsigned long)num_written, (
unsigned long)num_read, port);
1237 log_debug(
LD_HIST,
"Opened exit stream to port %d", port);
1272 double mean_time_cells_in_queue, uint32_t processed_cells)
1292 time_t start_of_interval;
1293 int interval_length;
1295 double mean_num_cells_in_queue, mean_time_cells_in_queue;
1296 uint32_t processed_cells;
1306 interval_length = (int) (end_of_interval - start_of_interval);
1307 if (interval_length <= 0)
1312 (
double) interval_length / 1000.0 / 2.0;
1313 mean_time_cells_in_queue =
1319 mean_time_cells_in_queue,
1365 uint64_t processed_cells[SHARES];
1366 uint32_t circs_in_share[SHARES];
1367 int number_of_circuits, i;
1368 double queued_cells[SHARES], time_in_queue[SHARES];
1369 smartlist_t *processed_cells_strings, *queued_cells_strings,
1370 *time_in_queue_strings;
1371 char *processed_cells_string, *queued_cells_string,
1372 *time_in_queue_string;
1373 char t[ISO_TIME_LEN+1];
1382 memset(processed_cells, 0, SHARES *
sizeof(uint64_t));
1383 memset(circs_in_share, 0, SHARES *
sizeof(uint32_t));
1384 memset(queued_cells, 0, SHARES *
sizeof(
double));
1385 memset(time_in_queue, 0, SHARES *
sizeof(
double));
1389 if (number_of_circuits > 0) {
1396 int share = i++ * SHARES / number_of_circuits;
1397 processed_cells[share] += stats->processed_cells;
1398 queued_cells[share] += stats->mean_num_cells_in_queue;
1399 time_in_queue[share] += stats->mean_time_cells_in_queue;
1400 circs_in_share[share]++;
1402 SMARTLIST_FOREACH_END(stats);
1409 for (i = 0; i < SHARES; i++) {
1411 "%"PRIu64, !circs_in_share[i] ? 0 :
1412 (processed_cells[i] /
1413 circs_in_share[i]));
1415 for (i = 0; i < SHARES; i++) {
1417 circs_in_share[i] == 0 ? 0.0 :
1418 queued_cells[i] / (
double) circs_in_share[i]);
1420 for (i = 0; i < SHARES; i++) {
1422 circs_in_share[i] == 0 ? 0.0 :
1423 time_in_queue[i] / (
double) circs_in_share[i]);
1436 smartlist_free(processed_cells_strings);
1437 smartlist_free(queued_cells_strings);
1438 smartlist_free(time_in_queue_strings);
1443 "cell-processed-cells %s\n"
1444 "cell-queued-cells %s\n"
1445 "cell-time-in-queue %s\n"
1446 "cell-circuits-per-decile %d\n",
1448 processed_cells_string,
1449 queued_cells_string,
1450 time_in_queue_string,
1451 CEIL_DIV(number_of_circuits, SHARES));
1478 SMARTLIST_FOREACH_END(circ);
1515 log_warn(
LD_BUG,
"Called rep_hist_desc_stats_init() when desc stats were "
1516 "already initialized. This is probably harmless.");
1550 char t[ISO_TIME_LEN+1];
1553 digestmap_iter_t *iter;
1557 int *vals, max = 0, q3 = 0, md = 0, q1 = 0, min = 0;
1565 vals = tor_calloc(size,
sizeof(
int));
1567 !digestmap_iter_done(iter);
1570 digestmap_iter_get(iter, &key, &val);
1571 count = (uintptr_t)val;
1572 vals[n++] = (int)count;
1575 max = find_nth_int(vals, size, size-1);
1576 q3 = find_nth_int(vals, size, (3*size-1)/4);
1577 md = find_nth_int(vals, size, (size-1)/2);
1578 q1 = find_nth_int(vals, size, (size-1)/4);
1579 min = find_nth_int(vals, size, 0);
1586 "served-descs-stats-end %s (%d s) total=%lu unique=%u "
1587 "max=%d q3=%d md=%d q1=%d min=%d\n",
1591 size, max, q3, md, q1, min);
1604 char *filename = NULL, *str = NULL;
1617 filename = get_datadir_fname2(
"stats",
"served-desc-stats");
1619 log_warn(
LD_HIST,
"Unable to write served descs statistics to disk!");
1640 count = (uintptr_t)val;
1641 if (count != INT_MAX)
1654 STATIC int onion_handshakes_assigned[MAX_ONION_HANDSHAKE_TYPE+1] = {0};
1661 if (type <= MAX_ONION_HANDSHAKE_TYPE)
1670 if (type <= MAX_ONION_HANDSHAKE_TYPE)
1671 onion_handshakes_assigned[type]++;
1678 if (BUG(type > MAX_ONION_HANDSHAKE_TYPE)) {
1688 if (BUG(type > MAX_ONION_HANDSHAKE_TYPE)) {
1691 return onion_handshakes_assigned[type];
1699 log_notice(
LD_HEARTBEAT,
"Circuit handshake stats since last time: "
1700 "%d/%d TAP, %d/%d NTor.",
1701 onion_handshakes_assigned[ONION_HANDSHAKE_TYPE_TAP],
1703 onion_handshakes_assigned[ONION_HANDSHAKE_TYPE_NTOR],
1705 memset(onion_handshakes_assigned, 0,
sizeof(onion_handshakes_assigned));
1721 static hs_v2_stats_t *
1724 hs_v2_stats_t *new_hs_v2_stats = tor_malloc_zero(
sizeof(hs_v2_stats_t));
1725 new_hs_v2_stats->v2_onions_seen_this_period = digestmap_new();
1727 return new_hs_v2_stats;
1730 #define hs_v2_stats_free(val) \
1731 FREE_AND_NULL(hs_v2_stats_t, hs_v2_stats_free_, (val))
1737 if (!victim_hs_v2_stats) {
1741 digestmap_free(victim_hs_v2_stats->v2_onions_seen_this_period, NULL);
1756 digestmap_free(
hs_v2_stats->v2_onions_seen_this_period, NULL);
1757 hs_v2_stats->v2_onions_seen_this_period = digestmap_new();
1783 if (!digestmap_get(
hs_v2_stats->v2_onions_seen_this_period,
1785 digestmap_set(
hs_v2_stats->v2_onions_seen_this_period,
1786 pubkey_hash, (
void*)(uintptr_t)1);
1827 static hs_v3_stats_t *
1830 hs_v3_stats_t *new_hs_v3_stats = tor_malloc_zero(
sizeof(hs_v3_stats_t));
1831 new_hs_v3_stats->v3_onions_seen_this_period = digest256map_new();
1833 return new_hs_v3_stats;
1836 #define hs_v3_stats_free(val) \
1837 FREE_AND_NULL(hs_v3_stats_t, hs_v3_stats_free_, (val))
1843 if (!victim_hs_v3_stats) {
1847 digest256map_free(victim_hs_v3_stats->v3_onions_seen_this_period, NULL);
1860 digest256map_free(
hs_v3_stats->v3_onions_seen_this_period, NULL);
1861 hs_v3_stats->v3_onions_seen_this_period = digest256map_new();
1895 !!digest256map_get(
hs_v3_stats->v3_onions_seen_this_period,
1898 log_info(
LD_GENERAL,
"Considering v3 descriptor with %s (%sseen before)",
1899 safe_str(
hex_str((
char*)blinded_key, 32)),
1900 seen_before ?
"" :
"not ");
1904 digest256map_set(
hs_v3_stats->v3_onions_seen_this_period,
1905 blinded_key, (
void*)(uintptr_t)1);
1914 log_debug(
LD_GENERAL,
"New RP cell (%d)", is_v2);
1958 #define REND_CELLS_DELTA_F 2048
1962 #define REND_CELLS_EPSILON 0.3
1965 #define REND_CELLS_BIN_SIZE 1024
1969 #define ONIONS_SEEN_DELTA_F 8
1973 #define ONIONS_SEEN_EPSILON 0.3
1976 #define ONIONS_SEEN_BIN_SIZE 8
1985 char t[ISO_TIME_LEN+1];
1986 char *hs_stats_string;
1987 int64_t obfuscated_onions_seen, obfuscated_cells_seen;
1989 uint64_t rp_cells_seen = is_v3 ?
1991 size_t onions_seen = is_v3 ?
1992 digest256map_size(
hs_v3_stats->v3_onions_seen_this_period) :
1993 digestmap_size(
hs_v2_stats->v2_onions_seen_this_period);
1994 time_t start_of_hs_stats_interval = is_v3 ?
1997 uint64_t rounded_cells_seen
1999 rounded_cells_seen = MIN(rounded_cells_seen, INT64_MAX);
2004 uint64_t rounded_onions_seen =
2006 rounded_onions_seen = MIN(rounded_onions_seen, INT64_MAX);
2009 ONIONS_SEEN_EPSILON);
2013 "%s %"PRId64
" delta_f=%d epsilon=%.2f bin_size=%d\n"
2014 "%s %"PRId64
" delta_f=%d epsilon=%.2f bin_size=%d\n",
2015 is_v3 ?
"hidserv-v3-stats-end" :
"hidserv-stats-end",
2016 t, (
unsigned) (now - start_of_hs_stats_interval),
2018 "hidserv-rend-v3-relayed-cells" :
"hidserv-rend-relayed-cells",
2020 REND_CELLS_EPSILON, REND_CELLS_BIN_SIZE,
2021 is_v3 ?
"hidserv-dir-v3-onions-seen" :
"hidserv-dir-onions-seen",
2022 obfuscated_onions_seen, ONIONS_SEEN_DELTA_F,
2023 ONIONS_SEEN_EPSILON, ONIONS_SEEN_BIN_SIZE);
2025 return hs_stats_string;
2039 time_t start_of_hs_stats_interval = is_v3 ?
2042 if (!start_of_hs_stats_interval) {
2046 if (start_of_hs_stats_interval + WRITE_STATS_INTERVAL > now) {
2063 is_v3 ?
"hidserv-v3-stats" :
"hidserv-stats",
2064 str,
"hidden service stats");
2069 return start_of_hs_stats_interval + WRITE_STATS_INTERVAL;
2072 static uint64_t link_proto_count[MAX_LINK_PROTO+1][2];
2080 started_here = !!started_here;
2081 if (link_proto > MAX_LINK_PROTO) {
2082 log_warn(
LD_BUG,
"Can't log link protocol %u", link_proto);
2086 link_proto_count[link_proto][started_here]++;
2172 #define MIN_CELL_COUNTS_TO_PUBLISH 1
2173 #define ROUND_CELL_COUNTS_TO 10000
2175 rep_hist_prep_published_padding_counts(time_t now)
2186 #define ROUND_AND_SET_COUNT(x) (x) = round_uint64_to_next_multiple_of((x), \
2187 ROUND_CELL_COUNTS_TO)
2198 #undef ROUND_AND_SET_COUNT
2208 char *result = NULL;
2217 " write-drop=%"PRIu64
2218 " write-pad=%"PRIu64
2219 " write-total=%"PRIu64
2220 " read-drop=%"PRIu64
2222 " read-total=%"PRIu64
2223 " enabled-read-pad=%"PRIu64
2224 " enabled-read-total=%"PRIu64
2225 " enabled-write-pad=%"PRIu64
2226 " enabled-write-total=%"PRIu64
2227 " max-chanpad-timers=%"PRIu64
2231 (uint64_t)ROUND_CELL_COUNTS_TO,
2256 for (
int i = 1; i <= MAX_LINK_PROTO; i++) {
2258 tor_asprintf(&line,
"initiated %"PRIu64
" and received "
2259 "%"PRIu64
" v%d connections", link_proto_count[i][1],
2260 link_proto_count[i][0], i);
2266 log_notice(
LD_HEARTBEAT,
"Since startup we %s.", log_line);
2269 smartlist_free(lines);
2301 #ifdef TOR_UNIT_TESTS
2303 const hs_v2_stats_t *
2304 rep_hist_get_hs_v2_stats(
void)
2310 const hs_v3_stats_t *
2311 rep_hist_get_hs_v3_stats(
void)