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;
192 time_t overload_general_time;
195 time_t overload_ratelimits_time;
197 uint64_t overload_read_count;
199 uint64_t overload_write_count;
202 time_t overload_fd_exhausted_time;
204 uint64_t overload_fd_exhausted;
215 if (overload_time >
approx_time() - 3600 * n_hours) {
222 #define OVERLOAD_STATS_VERSION 1
230 char tbuf[ISO_TIME_LEN+1];
236 OVERLOAD_STATS_VERSION, tbuf);
249 char tbuf[ISO_TIME_LEN+1];
256 "overload-ratelimits %d %s %" PRIu64
" %" PRIu64
257 " %" PRIu64
" %" PRIu64
"\n",
258 OVERLOAD_STATS_VERSION, tbuf,
269 OVERLOAD_STATS_VERSION, tbuf);
273 if (smartlist_len(chunks) == 0) {
281 smartlist_free(chunks);
286 #define SET_TO_START_OF_HOUR(a) STMT_BEGIN \
287 (a) = approx_time() - (approx_time() % 3600); \
294 static time_t last_read_counted = 0;
295 static time_t last_write_counted = 0;
298 case OVERLOAD_GENERAL:
301 case OVERLOAD_READ: {
309 case OVERLOAD_WRITE: {
317 case OVERLOAD_FD_EXHAUSTED:
367 const uint16_t at_port, time_t when)
371 char tbuf[ISO_TIME_LEN+1];
372 int addr_changed, port_changed;
375 tor_assert((!at_addr && !at_port) || (at_addr && at_port));
382 if (!started_tracking_stability)
383 started_tracking_stability = time(NULL);
388 if (hist->start_of_downtime) {
392 log_info(
LD_HIST,
"Router %s is now Running; it had been down since %s.",
395 log_info(
LD_HIST,
" (Paradoxically, it was already Running too.)");
397 down_length = when - hist->start_of_downtime;
398 hist->total_weighted_time += down_length;
399 hist->start_of_downtime = 0;
400 }
else if (addr_changed || port_changed) {
412 penalty = (int)(fresh_interval + live_interval) / 2;
415 log_info(
LD_HIST,
"Router %s still seems Running, but its address appears "
416 "to have changed since the last time it was reachable. I'm "
417 "going to treat it as having been down for %d seconds",
424 log_debug(
LD_HIST,
"Router %s is still Running; it has been Running "
427 log_info(
LD_HIST,
"Router %s is now Running; it was previously untracked",
442 char tbuf[ISO_TIME_LEN+1];
444 if (!started_tracking_stability)
445 started_tracking_stability = time(NULL);
456 if (run_length < 0) {
457 unsigned long penalty = -run_length;
458 #define SUBTRACT_CLAMPED(var, penalty) \
459 do { (var) = (var) < (penalty) ? 0 : (var) - (penalty); } while (0)
462 SUBTRACT_CLAMPED(hist->weighted_uptime, penalty);
465 hist->weighted_uptime += run_length;
466 hist->total_weighted_time += run_length;
469 log_info(
LD_HIST,
"Router %s is now non-Running: it had previously been "
470 "Running since %s. Its total weighted uptime is %lu/%lu.",
472 hist->total_weighted_time);
474 if (!hist->start_of_downtime) {
475 hist->start_of_downtime = when;
478 log_info(
LD_HIST,
"Router %s is now non-Running; it was previously "
484 log_info(
LD_HIST,
"Router %s is still non-Running; it has been "
501 hist->weighted_uptime = 0;
509 digestmap_iter_t *orhist_it;
528 log_info(
LD_HIST,
"Discounting all old stability info by a factor of %f",
533 !digestmap_iter_done(orhist_it);
534 orhist_it = digestmap_iter_next(
history_map,orhist_it)) {
535 digestmap_iter_get(orhist_it, &digest1, &hist_p);
542 hist->weighted_uptime = (
unsigned long)(hist->weighted_uptime * alpha);
543 hist->total_weighted_time = (
unsigned long)
544 (hist->total_weighted_time * alpha);
561 total_weights += 1.0;
568 return total / total_weights;
576 long total = hist->total_weighted_time;
579 }
else if (hist->start_of_downtime) {
580 total += (when - hist->start_of_downtime);
590 long total = hist->total_weighted_time;
591 long up = hist->weighted_uptime;
597 }
else if (hist->start_of_downtime) {
598 total += (when - hist->start_of_downtime);
608 return ((
double) up) / total;
672 return started_tracking_stability < time(NULL) - 4*60*60;
681 digestmap_iter_t *orhist_it;
682 const char *name1, *digest1;
690 tor_log(severity,
LD_HIST,
"--------------- Dumping history information:");
693 !digestmap_iter_done(orhist_it);
694 orhist_it = digestmap_iter_next(
history_map,orhist_it)) {
697 digestmap_iter_get(orhist_it, &digest1, &or_history_p);
708 "OR %s [%s]: wmtbf %lu:%02lu:%02lu",
710 stability/3600, (stability/60)%60, stability%60);
723 digestmap_iter_t *orhist_it;
727 while (!digestmap_iter_done(orhist_it)) {
729 digestmap_iter_get(orhist_it, &d1, &or_history_p);
730 or_history = or_history_p;
732 should_remove = authority ?
735 : (or_history->
changed < before);
737 orhist_it = digestmap_iter_next_rmv(
history_map, orhist_it);
741 orhist_it = digestmap_iter_next(
history_map, orhist_it);
753 char time_buf[ISO_TIME_LEN+1];
755 digestmap_iter_t *orhist_it;
763 char *filename = get_datadir_fname(
"router-stability");
780 #define PUT(s) STMT_BEGIN if (fputs((s),f)<0) goto err; STMT_END
781 #define PRINTF(args) STMT_BEGIN if (fprintf args <0) goto err; STMT_END
786 PRINTF((f,
"stored-at %s\n", time_buf));
788 if (started_tracking_stability) {
790 PRINTF((f,
"tracked-since %s\n", time_buf));
794 PRINTF((f,
"last-downrated %s\n", time_buf));
803 !digestmap_iter_done(orhist_it);
804 orhist_it = digestmap_iter_next(
history_map,orhist_it)) {
806 const char *t = NULL;
807 digestmap_iter_get(orhist_it, &digest, &or_history_p);
818 "Relay '%s' is listed as up in rephist, but it's not in "
819 "our routerlist. Correcting.", dbuf);
823 PRINTF((f,
"R %s\n", dbuf));
828 PRINTF((f,
"+MTBF %lu %.5f%s%s\n",
830 t ?
" S=" :
"", t ? t :
""));
832 if (hist->start_of_downtime > 0) {
836 PRINTF((f,
"+WFU %lu %lu%s%s\n",
837 hist->weighted_uptime, hist->total_weighted_time,
838 t ?
" S=" :
"", t ? t :
""));
858 for ( ; i < smartlist_len(sl); ++i) {
859 const char *line = smartlist_get(sl, i);
877 strlcpy(b, s,
sizeof(b));
894 correct_time(time_t t, time_t now, time_t stored_at, time_t started_measuring)
896 if (t < started_measuring - 24*60*60*365)
898 else if (t < started_measuring)
899 return started_measuring;
900 else if (t > stored_at)
903 long run_length = stored_at - t;
904 t = (time_t)(now - run_length);
905 if (t < started_measuring)
906 t = started_measuring;
918 const char *line = NULL;
920 time_t last_downrated = 0, stored_at = 0, tracked_since = 0;
921 time_t latest_possible_start = now;
925 char *filename = get_datadir_fname(
"router-stability");
936 const char *firstline;
937 if (smartlist_len(lines)>4) {
938 firstline = smartlist_get(lines, 0);
941 10, -1, LONG_MAX, NULL, NULL);
944 if (format != 1 && format != 2) {
946 "Unrecognized format in mtbf history file. Skipping.");
949 for (i = 1; i < smartlist_len(lines); ++i) {
950 line = smartlist_get(lines, i);
951 if (!strcmp(line,
"data"))
954 if (
parse_iso_time(line+strlen(
"last-downrated "), &last_downrated)<0)
955 log_warn(
LD_HIST,
"Couldn't parse downrate time in mtbf "
960 log_warn(
LD_HIST,
"Couldn't parse stored time in mtbf "
964 if (
parse_iso_time(line+strlen(
"tracked-since "), &tracked_since)<0)
965 log_warn(
LD_HIST,
"Couldn't parse started-tracking time in mtbf "
969 if (last_downrated > now)
970 last_downrated = now;
971 if (tracked_since > now)
975 log_warn(
LD_HIST,
"No stored time recorded.");
979 if (line && !strcmp(line,
"data"))
984 for (; i < smartlist_len(lines); ++i) {
987 char mtbf_timebuf[ISO_TIME_LEN+1];
988 char wfu_timebuf[ISO_TIME_LEN+1];
989 time_t start_of_run = 0;
990 time_t start_of_downtime = 0;
991 int have_mtbf = 0, have_wfu = 0;
994 long wt_uptime = 0, total_wt_time = 0;
997 line = smartlist_get(lines, i);
998 if (!strcmp(line,
"."))
1001 mtbf_timebuf[0] =
'\0';
1002 wfu_timebuf[0] =
'\0';
1005 n =
tor_sscanf(line,
"%40s %ld %lf S=%10s %8s",
1006 hexbuf, &wrl, &trw, mtbf_timebuf, mtbf_timebuf+11);
1007 if (n != 3 && n != 5) {
1014 int mtbf_idx, wfu_idx;
1017 strlcpy(hexbuf, line+2,
sizeof(hexbuf));
1020 if (mtbf_idx >= 0) {
1021 const char *mtbfline = smartlist_get(lines, mtbf_idx);
1022 n =
tor_sscanf(mtbfline,
"+MTBF %lu %lf S=%10s %8s",
1023 &wrl, &trw, mtbf_timebuf, mtbf_timebuf+11);
1024 if (n == 2 || n == 4) {
1027 log_warn(
LD_HIST,
"Couldn't scan +MTBF line %s",
1032 const char *wfuline = smartlist_get(lines, wfu_idx);
1033 n =
tor_sscanf(wfuline,
"+WFU %lu %lu S=%10s %8s",
1034 &wt_uptime, &total_wt_time,
1035 wfu_timebuf, wfu_timebuf+11);
1036 if (n == 2 || n == 4) {
1039 log_warn(
LD_HIST,
"Couldn't scan +WFU line %s",
escaped(wfuline));
1057 if (mtbf_timebuf[0]) {
1058 mtbf_timebuf[10] =
' ';
1060 log_warn(
LD_HIST,
"Couldn't parse time %s",
1066 latest_possible_start = (time_t)(hist->
start_of_run - wrl);
1072 if (wfu_timebuf[0]) {
1073 wfu_timebuf[10] =
' ';
1075 log_warn(
LD_HIST,
"Couldn't parse time %s",
escaped(wfu_timebuf));
1078 hist->start_of_downtime =
correct_time(start_of_downtime, now, stored_at,
1080 hist->weighted_uptime = wt_uptime;
1081 hist->total_weighted_time = total_wt_time;
1083 if (strcmp(line,
"."))
1084 log_warn(
LD_HIST,
"Truncated MTBF file.");
1086 if (tracked_since < 86400*365)
1087 tracked_since = latest_possible_start;
1090 started_tracking_stability = tracked_since;
1097 smartlist_free(lines);
1105 #define EXIT_STATS_ROUND_UP_BYTES 1024
1107 #define EXIT_STATS_ROUND_UP_STREAMS 4
1109 #define EXIT_STATS_NUM_PORTS 65536
1111 #define EXIT_STATS_TOP_N_PORTS 10
1164 return (*(
int*)x - *(
int*)y);
1173 int i, j, top_elements = 0, cur_min_idx = 0, cur_port;
1176 uint64_t cur_bytes = 0, other_read = 0, other_written = 0,
1177 total_read = 0, total_written = 0;
1178 uint32_t total_streams = 0, other_streams = 0;
1179 smartlist_t *written_strings, *read_strings, *streams_strings;
1180 char *written_string, *read_string, *streams_string;
1181 char t[ISO_TIME_LEN+1];
1220 if (cur_bytes == 0) {
1224 top_bytes[top_elements] = cur_bytes;
1225 top_ports[top_elements++] = i;
1226 }
else if (cur_bytes > top_bytes[cur_min_idx]) {
1227 top_bytes[cur_min_idx] = cur_bytes;
1228 top_ports[cur_min_idx] = i;
1233 for (j = 1; j < top_elements; j++) {
1234 if (top_bytes[j] < top_bytes[cur_min_idx]) {
1244 other_read = total_read;
1245 other_written = total_written;
1246 other_streams = total_streams;
1249 qsort(top_ports, top_elements,
sizeof(
int),
compare_int_);
1250 for (j = 0; j < top_elements; j++) {
1251 cur_port = top_ports[j];
1282 other_written /= 1024;
1301 smartlist_free(written_strings);
1302 smartlist_free(read_strings);
1303 smartlist_free(streams_strings);
1308 "exit-kibibytes-written %s\n"
1309 "exit-kibibytes-read %s\n"
1310 "exit-streams-opened %s\n",
1335 log_info(
LD_HIST,
"Writing exit port statistics to disk.");
1363 log_debug(
LD_HIST,
"Written %lu bytes and read %lu bytes to/from an "
1364 "exit connection to port %d.",
1365 (
unsigned long)num_written, (
unsigned long)num_read, port);
1375 log_debug(
LD_HIST,
"Opened exit stream to port %d", port);
1410 double mean_time_cells_in_queue, uint32_t processed_cells)
1430 time_t start_of_interval;
1431 int interval_length;
1433 double mean_num_cells_in_queue, mean_time_cells_in_queue;
1434 uint32_t processed_cells;
1444 interval_length = (int) (end_of_interval - start_of_interval);
1445 if (interval_length <= 0)
1450 (
double) interval_length / 1000.0 / 2.0;
1451 mean_time_cells_in_queue =
1457 mean_time_cells_in_queue,
1503 uint64_t processed_cells[SHARES];
1504 uint32_t circs_in_share[SHARES];
1505 int number_of_circuits, i;
1506 double queued_cells[SHARES], time_in_queue[SHARES];
1507 smartlist_t *processed_cells_strings, *queued_cells_strings,
1508 *time_in_queue_strings;
1509 char *processed_cells_string, *queued_cells_string,
1510 *time_in_queue_string;
1511 char t[ISO_TIME_LEN+1];
1520 memset(processed_cells, 0, SHARES *
sizeof(uint64_t));
1521 memset(circs_in_share, 0, SHARES *
sizeof(uint32_t));
1522 memset(queued_cells, 0, SHARES *
sizeof(
double));
1523 memset(time_in_queue, 0, SHARES *
sizeof(
double));
1527 if (number_of_circuits > 0) {
1534 int share = i++ * SHARES / number_of_circuits;
1535 processed_cells[share] += stats->processed_cells;
1536 queued_cells[share] += stats->mean_num_cells_in_queue;
1537 time_in_queue[share] += stats->mean_time_cells_in_queue;
1538 circs_in_share[share]++;
1540 SMARTLIST_FOREACH_END(stats);
1547 for (i = 0; i < SHARES; i++) {
1549 "%"PRIu64, !circs_in_share[i] ? 0 :
1550 (processed_cells[i] /
1551 circs_in_share[i]));
1553 for (i = 0; i < SHARES; i++) {
1555 circs_in_share[i] == 0 ? 0.0 :
1556 queued_cells[i] / (
double) circs_in_share[i]);
1558 for (i = 0; i < SHARES; i++) {
1560 circs_in_share[i] == 0 ? 0.0 :
1561 time_in_queue[i] / (
double) circs_in_share[i]);
1574 smartlist_free(processed_cells_strings);
1575 smartlist_free(queued_cells_strings);
1576 smartlist_free(time_in_queue_strings);
1581 "cell-processed-cells %s\n"
1582 "cell-queued-cells %s\n"
1583 "cell-time-in-queue %s\n"
1584 "cell-circuits-per-decile %d\n",
1586 processed_cells_string,
1587 queued_cells_string,
1588 time_in_queue_string,
1589 CEIL_DIV(number_of_circuits, SHARES));
1616 SMARTLIST_FOREACH_END(circ);
1653 log_warn(
LD_BUG,
"Called rep_hist_desc_stats_init() when desc stats were "
1654 "already initialized. This is probably harmless.");
1688 char t[ISO_TIME_LEN+1];
1691 digestmap_iter_t *iter;
1695 int *vals, max = 0, q3 = 0, md = 0, q1 = 0, min = 0;
1703 vals = tor_calloc(size,
sizeof(
int));
1705 !digestmap_iter_done(iter);
1708 digestmap_iter_get(iter, &key, &val);
1709 count = (uintptr_t)val;
1710 vals[n++] = (int)count;
1713 max = find_nth_int(vals, size, size-1);
1714 q3 = find_nth_int(vals, size, (3*size-1)/4);
1715 md = find_nth_int(vals, size, (size-1)/2);
1716 q1 = find_nth_int(vals, size, (size-1)/4);
1717 min = find_nth_int(vals, size, 0);
1724 "served-descs-stats-end %s (%d s) total=%lu unique=%u "
1725 "max=%d q3=%d md=%d q1=%d min=%d\n",
1729 size, max, q3, md, q1, min);
1742 char *filename = NULL, *str = NULL;
1755 filename = get_datadir_fname2(
"stats",
"served-desc-stats");
1757 log_warn(
LD_HIST,
"Unable to write served descs statistics to disk!");
1778 count = (uintptr_t)val;
1779 if (count != INT_MAX)
1792 STATIC int onion_handshakes_assigned[MAX_ONION_HANDSHAKE_TYPE+1] = {0};
1799 if (type <= MAX_ONION_HANDSHAKE_TYPE)
1808 if (type <= MAX_ONION_HANDSHAKE_TYPE)
1809 onion_handshakes_assigned[type]++;
1816 if (BUG(type > MAX_ONION_HANDSHAKE_TYPE)) {
1826 if (BUG(type > MAX_ONION_HANDSHAKE_TYPE)) {
1829 return onion_handshakes_assigned[type];
1837 log_notice(
LD_HEARTBEAT,
"Circuit handshake stats since last time: "
1838 "%d/%d TAP, %d/%d NTor.",
1839 onion_handshakes_assigned[ONION_HANDSHAKE_TYPE_TAP],
1841 onion_handshakes_assigned[ONION_HANDSHAKE_TYPE_NTOR],
1843 memset(onion_handshakes_assigned, 0,
sizeof(onion_handshakes_assigned));
1859 static hs_v2_stats_t *
1862 hs_v2_stats_t *new_hs_v2_stats = tor_malloc_zero(
sizeof(hs_v2_stats_t));
1864 return new_hs_v2_stats;
1867 #define hs_v2_stats_free(val) \
1868 FREE_AND_NULL(hs_v2_stats_t, hs_v2_stats_free_, (val))
1874 if (!victim_hs_v2_stats) {
1931 static hs_v3_stats_t *
1934 hs_v3_stats_t *new_hs_v3_stats = tor_malloc_zero(
sizeof(hs_v3_stats_t));
1935 new_hs_v3_stats->v3_onions_seen_this_period = digest256map_new();
1937 return new_hs_v3_stats;
1940 #define hs_v3_stats_free(val) \
1941 FREE_AND_NULL(hs_v3_stats_t, hs_v3_stats_free_, (val))
1947 if (!victim_hs_v3_stats) {
1951 digest256map_free(victim_hs_v3_stats->v3_onions_seen_this_period, NULL);
1964 digest256map_free(
hs_v3_stats->v3_onions_seen_this_period, NULL);
1965 hs_v3_stats->v3_onions_seen_this_period = digest256map_new();
1999 !!digest256map_get(
hs_v3_stats->v3_onions_seen_this_period,
2002 log_info(
LD_GENERAL,
"Considering v3 descriptor with %s (%sseen before)",
2003 safe_str(
hex_str((
char*)blinded_key, 32)),
2004 seen_before ?
"" :
"not ");
2008 digest256map_set(
hs_v3_stats->v3_onions_seen_this_period,
2009 blinded_key, (
void*)(uintptr_t)1);
2018 log_debug(
LD_GENERAL,
"New RP cell (%d)", is_v2);
2062 #define REND_CELLS_DELTA_F 2048
2066 #define REND_CELLS_EPSILON 0.3
2069 #define REND_CELLS_BIN_SIZE 1024
2073 #define ONIONS_SEEN_DELTA_F 8
2077 #define ONIONS_SEEN_EPSILON 0.3
2080 #define ONIONS_SEEN_BIN_SIZE 8
2089 char t[ISO_TIME_LEN+1];
2090 char *hs_stats_string;
2091 int64_t obfuscated_onions_seen, obfuscated_cells_seen;
2093 uint64_t rp_cells_seen = is_v3 ?
2095 size_t onions_seen = is_v3 ?
2096 digest256map_size(
hs_v3_stats->v3_onions_seen_this_period) : 0;
2097 time_t start_of_hs_stats_interval = is_v3 ?
2100 uint64_t rounded_cells_seen
2102 rounded_cells_seen = MIN(rounded_cells_seen, INT64_MAX);
2107 uint64_t rounded_onions_seen =
2109 rounded_onions_seen = MIN(rounded_onions_seen, INT64_MAX);
2112 ONIONS_SEEN_EPSILON);
2116 "%s %"PRId64
" delta_f=%d epsilon=%.2f bin_size=%d\n"
2117 "%s %"PRId64
" delta_f=%d epsilon=%.2f bin_size=%d\n",
2118 is_v3 ?
"hidserv-v3-stats-end" :
"hidserv-stats-end",
2119 t, (
unsigned) (now - start_of_hs_stats_interval),
2121 "hidserv-rend-v3-relayed-cells" :
"hidserv-rend-relayed-cells",
2123 REND_CELLS_EPSILON, REND_CELLS_BIN_SIZE,
2124 is_v3 ?
"hidserv-dir-v3-onions-seen" :
"hidserv-dir-onions-seen",
2125 obfuscated_onions_seen, ONIONS_SEEN_DELTA_F,
2126 ONIONS_SEEN_EPSILON, ONIONS_SEEN_BIN_SIZE);
2128 return hs_stats_string;
2142 time_t start_of_hs_stats_interval = is_v3 ?
2145 if (!start_of_hs_stats_interval) {
2149 if (start_of_hs_stats_interval + WRITE_STATS_INTERVAL > now) {
2166 is_v3 ?
"hidserv-v3-stats" :
"hidserv-stats",
2167 str,
"hidden service stats");
2172 return start_of_hs_stats_interval + WRITE_STATS_INTERVAL;
2175 static uint64_t link_proto_count[MAX_LINK_PROTO+1][2];
2183 started_here = !!started_here;
2184 if (link_proto > MAX_LINK_PROTO) {
2185 log_warn(
LD_BUG,
"Can't log link protocol %u", link_proto);
2189 link_proto_count[link_proto][started_here]++;
2275 #define MIN_CELL_COUNTS_TO_PUBLISH 1
2276 #define ROUND_CELL_COUNTS_TO 10000
2278 rep_hist_prep_published_padding_counts(time_t now)
2289 #define ROUND_AND_SET_COUNT(x) (x) = round_uint64_to_next_multiple_of((x), \
2290 ROUND_CELL_COUNTS_TO)
2301 #undef ROUND_AND_SET_COUNT
2311 char *result = NULL;
2320 " write-drop=%"PRIu64
2321 " write-pad=%"PRIu64
2322 " write-total=%"PRIu64
2323 " read-drop=%"PRIu64
2325 " read-total=%"PRIu64
2326 " enabled-read-pad=%"PRIu64
2327 " enabled-read-total=%"PRIu64
2328 " enabled-write-pad=%"PRIu64
2329 " enabled-write-total=%"PRIu64
2330 " max-chanpad-timers=%"PRIu64
2334 (uint64_t)ROUND_CELL_COUNTS_TO,
2359 for (
int i = 1; i <= MAX_LINK_PROTO; i++) {
2361 tor_asprintf(&line,
"initiated %"PRIu64
" and received "
2362 "%"PRIu64
" v%d connections", link_proto_count[i][1],
2363 link_proto_count[i][0], i);
2369 log_notice(
LD_HEARTBEAT,
"Since startup we %s.", log_line);
2372 smartlist_free(lines);
2404 #ifdef TOR_UNIT_TESTS
2406 const hs_v2_stats_t *
2407 rep_hist_get_hs_v2_stats(
void)
2413 const hs_v3_stats_t *
2414 rep_hist_get_hs_v3_stats(
void)