Merge remote-tracking branch 'tor-github/pr/609'

changes/ticket28180

@@ -1,3 +1,3 @@
   o Minor features (pluggable transports):
     - Add support for logging to Tor's logging subsystem from a pluggable
-      transport process. Partial implementation for ticket 28180
+      transport process. Closes ticket 28180

changes/ticket28846

@@ -0,0 +1,3 @@
+  o Minor features (pluggable transports):
+    - Add support for emitting STATUS updates to Tor's control port from a
+      pluggable transport process. Closes ticket 28846.

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"
@@ -128,6 +130,7 @@ static void parse_method_error(const char *line, int is_server_method);
 #define PROTO_PROXY_DONE "PROXY DONE"
 #define PROTO_PROXY_ERROR "PROXY-ERROR"
 #define PROTO_LOG "LOG"
+#define PROTO_STATUS "STATUS"
 
 /** The first and only supported - at the moment - configuration
     protocol version. */
@@ -910,12 +913,16 @@ handle_proxy_line(const char *line, managed_proxy_t *mp)
     parse_proxy_error(line);
     goto err;
 
-    /* We check for the additional " " after the PROTO_LOG string to make sure
-     * we can later extend this big if/else-if table with something that begins
-     * with "LOG" without having to get the order right. */
+    /* We check for the additional " " after the PROTO_LOG * PROTO_STATUS
+     * string to make sure we can later extend this big if/else-if table with
+     * something that begins with "LOG" without having to get the order right.
+     * */
   } else if (!strcmpstart(line, PROTO_LOG " ")) {
     parse_log_line(line, mp);
     return;
+  } else if (!strcmpstart(line, PROTO_STATUS " ")) {
+    parse_status_line(line, mp);
+    return;
   }
 
   log_notice(LD_GENERAL, "Unknown line received by managed proxy (%s).", line);
@@ -1144,22 +1151,112 @@ 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], escaped(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], escaped(data));
+    goto done;
+  }
+
+  int log_severity = managed_proxy_severity_parse(severity->value);
 
-  log_info(LD_PT, "Managed proxy \"%s\" says: %s",
-           mp->argv[0], message);
+  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);
+}
+
+/** Parses a STATUS <b>line</b> and emit control events accordingly. */
+STATIC void
+parse_status_line(const char *line, managed_proxy_t *mp)
+{
+  tor_assert(line);
+  tor_assert(mp);
+
+  config_line_t *values = NULL;
+  char *status_message = NULL;
+
+  if (strlen(line) < (strlen(PROTO_STATUS) + 1)) {
+    log_warn(LD_PT, "Managed proxy sent us a %s line "
+                    "with missing argument.", PROTO_STATUS);
+    goto done;
+  }
+
+  const char *data = line + strlen(PROTO_STATUS) + 1;
+
+  values = kvline_parse(data, KV_QUOTED);
+
+  if (! values) {
+    log_warn(LD_PT, "Managed proxy \"%s\" wrote an invalid "
+             "STATUS message: %s", mp->argv[0], escaped(data));
+    goto done;
+  }
+
+  /* We check if we received the TYPE parameter, which is the only *required*
+   * value. */
+  const config_line_t *type = config_line_find(values, "TYPE");
+
+  if (! type) {
+    log_warn(LD_PT, "Managed proxy \"%s\" wrote a STATUS line without "
+                    "TYPE: %s", mp->argv[0], escaped(data));
+    goto done;
+  }
+
+  /* Prepend the PT name. */
+  config_line_prepend(&values, "PT", mp->argv[0]);
+  status_message = kvline_encode(values, KV_QUOTED);
+
+  /* We have checked that TYPE is there, we can now emit the STATUS event via
+   * the control port. */
+  control_event_pt_status(status_message);
+
+ done:
+  config_free_lines(values);
+  tor_free(status_message);
 }
 
 /** Return a newly allocated string that tor should place in
@@ -1779,3 +1876,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

@@ -129,6 +129,7 @@ STATIC void parse_env_error(const char *line);
 STATIC void parse_proxy_error(const char *line);
 STATIC void handle_proxy_line(const char *line, managed_proxy_t *mp);
 STATIC void parse_log_line(const char *line, managed_proxy_t *mp);
+STATIC void parse_status_line(const char *line, managed_proxy_t *mp);
 STATIC char *get_transport_options_for_server_proxy(const managed_proxy_t *mp);
 
 STATIC void managed_proxy_destroy(managed_proxy_t *mp,
@@ -147,6 +148,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

@@ -7033,15 +7033,24 @@ 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);
+}
+
+/** A pluggable transport has emitted a STATUS message found in
+ * <b>status</b>. */
+void
+control_event_pt_status(const char *status)
+{
+  send_control_event(EVENT_PT_STATUS,
+                     "650 PT_STATUS %s\r\n",
+                     status);
 }
 
 /** Convert rendezvous auth type to string for HS_DESC control events

src/feature/control/control.h

@@ -207,7 +207,8 @@ 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);
+void control_event_pt_status(const char *status);
 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,
@@ -297,7 +298,8 @@ void control_free_all(void);
 #define EVENT_HS_DESC_CONTENT         0x0022
 #define EVENT_NETWORK_LIVENESS        0x0023
 #define EVENT_PT_LOG                  0x0024
-#define EVENT_MAX_                    0x0024
+#define EVENT_PT_STATUS               0x0025
+#define EVENT_MAX_                    0x0025
 
 /* sizeof(control_connection_t.event_mask) in bits, currently a uint64_t */
 #define EVENT_CAPACITY_               0x0040

src/test/test_pt.c

@@ -310,8 +310,16 @@ 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");
+  } else if (times_called <= 8) {
+    buf_add_string(buffer, "STATUS TYPE=a K_1=a K_2=b K_3=\"foo bar\"\n");
+    buf_add_string(buffer, "STATUS TYPE=b K_1=a K_2=b K_3=\"foo bar\"\n");
+    buf_add_string(buffer, "STATUS TYPE=c K_1=a K_2=b K_3=\"foo bar\"\n");
   }
 
   return (int)buf_datalen(buffer);
@@ -416,12 +424,42 @@ 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");
+
+  /* Get the STATUS messages out. */
+  process_notify_event_stdout(mp->process);
+
+  tt_int_op(controlevent_n, OP_EQ, 13);
+  tt_int_op(controlevent_event, OP_EQ, EVENT_PT_STATUS);
+  tt_int_op(smartlist_len(controlevent_msgs), OP_EQ, 13);
+
+  tt_str_op(smartlist_get(controlevent_msgs, 10), OP_EQ,
+            "650 PT_STATUS "
+            "PT=<testcase> TYPE=a K_1=a K_2=b K_3=\"foo bar\"\r\n");
+  tt_str_op(smartlist_get(controlevent_msgs, 11), OP_EQ,
+            "650 PT_STATUS "
+            "PT=<testcase> TYPE=b K_1=a K_2=b K_3=\"foo bar\"\r\n");
+  tt_str_op(smartlist_get(controlevent_msgs, 12), OP_EQ,
+            "650 PT_STATUS "
+            "PT=<testcase> TYPE=c K_1=a K_2=b K_3=\"foo bar\"\r\n");
 
   { /* check that the transport info were saved properly in the tor state */
     config_line_t *transport_in_state = NULL;