/* Copyright (c) 2010-2017, The Tor Project, Inc. */
/* See LICENSE for licensing information */
/**
* \file status.c
* \brief Collect status information and log heartbeat messages.
*
* This module is responsible for implementing the heartbeat log messages,
* which periodically inform users and operators about basic facts to
* do with their Tor instance. The log_heartbeat() function, invoked from
* main.c, is the principle entry point. It collects data from elsewhere
* in Tor, and logs it in a human-readable format.
**/
#define STATUS_PRIVATE
#include "or.h"
#include "circuituse.h"
#include "config.h"
#include "status.h"
#include "nodelist.h"
#include "relay.h"
#include "router.h"
#include "circuitlist.h"
#include "main.h"
#include "rephist.h"
#include "hibernate.h"
#include "statefile.h"
#include "hs_stats.h"
#include "hs_service.h"
#include "dos.h"
static void log_accounting(const time_t now, const or_options_t *options);
#include "geoip.h"
/** Return the total number of circuits. */
STATIC int
count_circuits(void)
{
return smartlist_len(circuit_get_global_list());
}
/** Take seconds secs and return a newly allocated human-readable
* uptime string. */
STATIC char *
secs_to_uptime(long secs)
{
long int days = secs / 86400;
int hours = (int)((secs - (days * 86400)) / 3600);
int minutes = (int)((secs - (days * 86400) - (hours * 3600)) / 60);
char *uptime_string = NULL;
switch (days) {
case 0:
tor_asprintf(&uptime_string, "%d:%02d hours", hours, minutes);
break;
case 1:
tor_asprintf(&uptime_string, "%ld day %d:%02d hours",
days, hours, minutes);
break;
default:
tor_asprintf(&uptime_string, "%ld days %d:%02d hours",
days, hours, minutes);
break;
}
return uptime_string;
}
/** Take bytes and returns a newly allocated human-readable usage
* string. */
STATIC char *
bytes_to_usage(uint64_t bytes)
{
char *bw_string = NULL;
if (bytes < (1<<20)) { /* Less than a megabyte. */
tor_asprintf(&bw_string, U64_FORMAT" kB", U64_PRINTF_ARG(bytes>>10));
} else if (bytes < (1<<30)) { /* Megabytes. Let's add some precision. */
double bw = U64_TO_DBL(bytes);
tor_asprintf(&bw_string, "%.2f MB", bw/(1<<20));
} else { /* Gigabytes. */
double bw = U64_TO_DBL(bytes);
tor_asprintf(&bw_string, "%.2f GB", bw/(1<<30));
}
return bw_string;
}
/** Log some usage info about our hidden service */
static void
log_onion_service_stats(void)
{
unsigned int num_services = hs_service_get_num_services();
/* If there are no active hidden services, no need to print logs */
if (num_services == 0) {
return;
}
log_notice(LD_HEARTBEAT,
"Our hidden service%s received %u v2 and %u v3 INTRODUCE2 cells "
"and attempted to launch %d rendezvous circuits.",
num_services == 1 ? "" : "s",
hs_stats_get_n_introduce2_v2_cells(),
hs_stats_get_n_introduce2_v3_cells(),
hs_stats_get_n_rendezvous_launches());
}
/** Log a "heartbeat" message describing Tor's status and history so that the
* user can know that there is indeed a running Tor. Return 0 on success and
* -1 on failure. */
int
log_heartbeat(time_t now)
{
char *bw_sent = NULL;
char *bw_rcvd = NULL;
char *uptime = NULL;
const routerinfo_t *me;
double r = tls_get_write_overhead_ratio();
const int hibernating = we_are_hibernating();
const or_options_t *options = get_options();
if (public_server_mode(options) && !hibernating) {
/* Let's check if we are in the current cached consensus. */
if (!(me = router_get_my_routerinfo()))
return -1; /* Something stinks, we won't even attempt this. */
else
if (!node_get_by_id(me->cache_info.identity_digest))
log_fn(LOG_NOTICE, LD_HEARTBEAT, "Heartbeat: It seems like we are not "
"in the cached consensus.");
}
uptime = secs_to_uptime(get_uptime());
bw_rcvd = bytes_to_usage(get_bytes_read());
bw_sent = bytes_to_usage(get_bytes_written());
log_fn(LOG_NOTICE, LD_HEARTBEAT, "Heartbeat: Tor's uptime is %s, with %d "
"circuits open. I've sent %s and received %s.%s",
uptime, count_circuits(), bw_sent, bw_rcvd,
hibernating?" We are currently hibernating.":"");
if (server_mode(options) && accounting_is_enabled(options) && !hibernating) {
log_accounting(now, options);
}
double fullness_pct = 100;
if (stats_n_data_cells_packaged && !hibernating) {
fullness_pct =
100*(U64_TO_DBL(stats_n_data_bytes_packaged) /
U64_TO_DBL(stats_n_data_cells_packaged*RELAY_PAYLOAD_SIZE));
}
const double overhead_pct = ( r - 1.0 ) * 100.0;
#define FULLNESS_PCT_THRESHOLD 80
#define TLS_OVERHEAD_THRESHOLD 15
const int severity = (fullness_pct < FULLNESS_PCT_THRESHOLD ||
overhead_pct > TLS_OVERHEAD_THRESHOLD)
? LOG_NOTICE : LOG_INFO;
log_fn(severity, LD_HEARTBEAT,
"Average packaged cell fullness: %2.3f%%. "
"TLS write overhead: %.f%%", fullness_pct, overhead_pct);
if (public_server_mode(options)) {
rep_hist_log_circuit_handshake_stats(now);
rep_hist_log_link_protocol_counts();
dos_log_heartbeat();
}
circuit_log_ancient_one_hop_circuits(1800);
if (options->BridgeRelay) {
char *msg = NULL;
msg = format_client_stats_heartbeat(now);
if (msg)
log_notice(LD_HEARTBEAT, "%s", msg);
tor_free(msg);
}
if (options->MainloopStats) {
const uint64_t main_loop_success_count = get_main_loop_success_count();
const uint64_t main_loop_error_count = get_main_loop_error_count();
const uint64_t main_loop_idle_count = get_main_loop_idle_count();
log_fn(LOG_NOTICE, LD_HEARTBEAT, "Main event loop statistics: "
U64_FORMAT " successful returns, "
U64_FORMAT " erroneous returns, and "
U64_FORMAT " idle returns.",
U64_PRINTF_ARG(main_loop_success_count),
U64_PRINTF_ARG(main_loop_error_count),
U64_PRINTF_ARG(main_loop_idle_count));
}
/** Now, if we are an HS service, log some stats about our usage */
log_onion_service_stats();
tor_free(uptime);
tor_free(bw_sent);
tor_free(bw_rcvd);
return 0;
}
static void
log_accounting(const time_t now, const or_options_t *options)
{
or_state_t *state = get_or_state();
char *acc_rcvd = bytes_to_usage(state->AccountingBytesReadInInterval);
char *acc_sent = bytes_to_usage(state->AccountingBytesWrittenInInterval);
char *acc_used = bytes_to_usage(get_accounting_bytes());
uint64_t acc_bytes = options->AccountingMax;
char *acc_max;
time_t interval_end = accounting_get_end_time();
char end_buf[ISO_TIME_LEN + 1];
char *remaining = NULL;
acc_max = bytes_to_usage(acc_bytes);
format_local_iso_time(end_buf, interval_end);
remaining = secs_to_uptime(interval_end - now);
const char *acc_rule;
switch (options->AccountingRule) {
case ACCT_MAX: acc_rule = "max";
break;
case ACCT_SUM: acc_rule = "sum";
break;
case ACCT_OUT: acc_rule = "out";
break;
case ACCT_IN: acc_rule = "in";
break;
default: acc_rule = "max";
break;
}
log_notice(LD_HEARTBEAT, "Heartbeat: Accounting enabled. "
"Sent: %s, Received: %s, Used: %s / %s, Rule: %s. The "
"current accounting interval ends on %s, in %s.",
acc_sent, acc_rcvd, acc_used, acc_max, acc_rule, end_buf, remaining);
tor_free(acc_rcvd);
tor_free(acc_sent);
tor_free(acc_used);
tor_free(acc_max);
tor_free(remaining);
}