commit 426c52b377057dc5f4428c664ee56ca77d648c9e Author: Alexander Færøy ahf@torproject.org Date: Thu Dec 20 02:10:42 2018 +0100

Use K/V parser to handle LOG messages for pluggable transports.

This patch changes the LOG pluggable transport message to use the recent K/V parser that landed in Tor. This allows PT's to specify the log severity level as well as the message. A mapping between the PT log severity levels and Tor's log serverity level is provided.

See: https://bugs.torproject.org/28846 --- src/feature/client/transports.c | 80 ++++++++++++++++++++++++++++++++++++++--- src/feature/client/transports.h | 2 ++ src/feature/control/control.c | 11 +++--- src/feature/control/control.h | 2 +- src/test/test_pt.c | 29 +++++++++++---- 5 files changed, 106 insertions(+), 18 deletions(-)

diff --git a/src/feature/client/transports.c b/src/feature/client/transports.c index de53fe346..6a3479a47 100644 --- a/src/feature/client/transports.c +++ b/src/feature/client/transports.c @@ -101,6 +101,8 @@ #include "core/or/connection_or.h" #include "feature/relay/ext_orport.h" #include "feature/control/control.h" +#include "lib/encoding/confline.h" +#include "lib/encoding/kvline.h"

#include "lib/process/process.h" #include "lib/process/env.h" @@ -1144,22 +1146,63 @@ parse_log_line(const char *line, managed_proxy_t *mp) tor_assert(line); tor_assert(mp);

+ config_line_t *values = NULL; + char *log_message = NULL; + if (strlen(line) < (strlen(PROTO_LOG) + 1)) { log_warn(LD_PT, "Managed proxy sent us a %s line " "with missing argument.", PROTO_LOG); goto done; }

- const char *message = line + strlen(PROTO_LOG) + 1; + const char *data = line + strlen(PROTO_LOG) + 1; + values = kvline_parse(data, KV_QUOTED); + + if (! values) { + log_warn(LD_PT, "Managed proxy "%s" wrote an invalid LOG message: %s", + mp->argv[0], data); + goto done; + } + + const config_line_t *severity = config_line_find(values, "SEVERITY"); + const config_line_t *message = config_line_find(values, "MESSAGE"); + + /* Check if we got a message. */ + if (! message) { + log_warn(LD_PT, "Managed proxy "%s" wrote a LOG line without " + "MESSAGE: %s", mp->argv[0], data); + goto done; + } + + /* Check if severity is there and whether it's valid. */ + if (! severity) { + log_warn(LD_PT, "Managed proxy "%s" wrote a LOG line without " + "SEVERITY: %s", mp->argv[0], data); + goto done; + }

- log_info(LD_PT, "Managed proxy "%s" says: %s", - mp->argv[0], message); + int log_severity = managed_proxy_severity_parse(severity->value); + + if (log_severity == -1) { + log_warn(LD_PT, "Managed proxy "%s" wrote a LOG line with an " + "invalid severity level: %s", + mp->argv[0], severity->value); + goto done; + } + + tor_log(log_severity, LD_PT, "Managed proxy "%s": %s", + mp->argv[0], message->value); + + /* Prepend the PT name. */ + config_line_prepend(&values, "PT", mp->argv[0]); + log_message = kvline_encode(values, KV_QUOTED);

/* Emit control port event. */ - control_event_pt_log(mp->argv[0], message); + control_event_pt_log(log_message);

done: - return; + config_free_lines(values); + tor_free(log_message); }

/** Return a newly allocated string that tor should place in @@ -1779,3 +1822,30 @@ managed_proxy_exit_callback(process_t *process, process_exit_code_t exit_code)

return true; } + +/** Returns a valid integer log severity level from <b>severity</b> that + * is compatible with Tor's logging functions. Returns <b>-1</b> on + * error. */ +STATIC int +managed_proxy_severity_parse(const char *severity) +{ + tor_assert(severity); + + /* Slightly different than log.c's parse_log_level :-( */ + if (! strcmp(severity, "debug")) + return LOG_DEBUG; + + if (! strcmp(severity, "info")) + return LOG_INFO; + + if (! strcmp(severity, "notice")) + return LOG_NOTICE; + + if (! strcmp(severity, "warning")) + return LOG_WARN; + + if (! strcmp(severity, "error")) + return LOG_ERR; + + return -1; +} diff --git a/src/feature/client/transports.h b/src/feature/client/transports.h index a3994a009..b8d1bb008 100644 --- a/src/feature/client/transports.h +++ b/src/feature/client/transports.h @@ -147,6 +147,8 @@ STATIC void managed_proxy_stdout_callback(process_t *, const char *, size_t); STATIC void managed_proxy_stderr_callback(process_t *, const char *, size_t); STATIC bool managed_proxy_exit_callback(process_t *, process_exit_code_t);

+STATIC int managed_proxy_severity_parse(const char *); + #endif /* defined(PT_PRIVATE) */

#endif /* !defined(TOR_TRANSPORTS_H) */ diff --git a/src/feature/control/control.c b/src/feature/control/control.c index 7fae3b7a1..849f11707 100644 --- a/src/feature/control/control.c +++ b/src/feature/control/control.c @@ -7033,15 +7033,14 @@ control_event_transport_launched(const char *mode, const char *transport_name, mode, transport_name, fmt_addr(addr), port); }

-/** A pluggable transport called <b>pt_name</b> has emitted a log - * message found in <b>message</b>. */ +/** A pluggable transport called <b>pt_name</b> has emitted a log message + * found in <b>message</b> at <b>severity</b> log level. */ void -control_event_pt_log(const char *pt_name, const char *message) +control_event_pt_log(const char *log) { send_control_event(EVENT_PT_LOG, - "650 PT_LOG %s %s\r\n", - pt_name, - message); + "650 PT_LOG %s\r\n", + log); }

/** Convert rendezvous auth type to string for HS_DESC control events diff --git a/src/feature/control/control.h b/src/feature/control/control.h index a1609b0f0..b3a270767 100644 --- a/src/feature/control/control.h +++ b/src/feature/control/control.h @@ -207,7 +207,7 @@ void control_event_clients_seen(const char *controller_str); void control_event_transport_launched(const char *mode, const char *transport_name, tor_addr_t *addr, uint16_t port); -void control_event_pt_log(const char *pt_name, const char *message); +void control_event_pt_log(const char *log); const char *rend_auth_type_to_string(rend_auth_type_t auth_type); MOCK_DECL(const char *, node_describe_longname_by_id,(const char *id_digest)); void control_event_hs_descriptor_requested(const char *onion_address, diff --git a/src/test/test_pt.c b/src/test/test_pt.c index 8fcdd5c1e..271d74f26 100644 --- a/src/test/test_pt.c +++ b/src/test/test_pt.c @@ -310,8 +310,12 @@ process_read_stdout_replacement(process_t *process, buf_t *buffer) } else if (times_called <= 6) { buf_add_string(buffer, "SMETHODS DONE\n"); } else if (times_called <= 7) { - buf_add_string(buffer, "LOG Oh noes, something bad happened. " - "What do we do!?\n"); + buf_add_string(buffer, "LOG SEVERITY=error MESSAGE="Oh noes, something " + "bad happened. What do we do!?"\n"); + buf_add_string(buffer, "LOG SEVERITY=warning MESSAGE="warning msg"\n"); + buf_add_string(buffer, "LOG SEVERITY=notice MESSAGE="notice msg"\n"); + buf_add_string(buffer, "LOG SEVERITY=info MESSAGE="info msg"\n"); + buf_add_string(buffer, "LOG SEVERITY=debug MESSAGE="debug msg"\n"); }

return (int)buf_datalen(buffer); @@ -416,12 +420,25 @@ test_pt_configure_proxy(void *arg) /* Get the log message out. */ process_notify_event_stdout(mp->process);

- tt_int_op(controlevent_n, OP_EQ, 6); + tt_int_op(controlevent_n, OP_EQ, 10); tt_int_op(controlevent_event, OP_EQ, EVENT_PT_LOG); - tt_int_op(smartlist_len(controlevent_msgs), OP_EQ, 6); + tt_int_op(smartlist_len(controlevent_msgs), OP_EQ, 10); tt_str_op(smartlist_get(controlevent_msgs, 5), OP_EQ, - "650 PT_LOG <testcase> Oh noes, something bad happened. " - "What do we do!?\r\n"); + "650 PT_LOG PT=<testcase> SEVERITY=error " + "MESSAGE="Oh noes, " + "something bad happened. What do we do!?"\r\n"); + tt_str_op(smartlist_get(controlevent_msgs, 6), OP_EQ, + "650 PT_LOG PT=<testcase> SEVERITY=warning " + "MESSAGE="warning msg"\r\n"); + tt_str_op(smartlist_get(controlevent_msgs, 7), OP_EQ, + "650 PT_LOG PT=<testcase> SEVERITY=notice " + "MESSAGE="notice msg"\r\n"); + tt_str_op(smartlist_get(controlevent_msgs, 8), OP_EQ, + "650 PT_LOG PT=<testcase> SEVERITY=info " + "MESSAGE="info msg"\r\n"); + tt_str_op(smartlist_get(controlevent_msgs, 9), OP_EQ, + "650 PT_LOG PT=<testcase> SEVERITY=debug " + "MESSAGE="debug msg"\r\n");

{ /* check that the transport info were saved properly in the tor state */ config_line_t *transport_in_state = NULL;