Commit 426c52b3 authored by Alexander Hansen Færøy's avatar Alexander Hansen Færøy 💬
Browse files

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
parent ed0bc85e

src/feature/client/transports.c

+75 −5
Original line number Diff line number Diff line
@@ -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;

  }



  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);



  log_info(LD_PT, "Managed proxy \"%s\" says: %s",

           mp->argv[0], message);

  /* 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;

}

src/feature/client/transports.h

+2 −0
Original line number Diff line number Diff line
@@ -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) */

src/feature/control/control.c

+5 −6
Original line number Diff line number Diff line
@@ -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

src/feature/control/control.h

+1 −1
Original line number Diff line number Diff line
@@ -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,

src/test/test_pt.c

+23 −6
Original line number Diff line number Diff line
@@ -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;