Print sendtime of messsages.

Change-Id: I42579bce6133a536df61da9355aed763a0b2e614
diff --git a/aos/common/controls/BUILD b/aos/common/controls/BUILD
index de100bb..2e7af21 100644
--- a/aos/common/controls/BUILD
+++ b/aos/common/controls/BUILD
@@ -78,12 +78,12 @@
     'control_loop.h',
   ],
   deps = [
-    '//aos/common/messages:robot_state',
-    '//aos/common/logging',
-    '//aos/common:time',
     ':control_loop_queues',
+    '//aos/common/logging',
     '//aos/common/logging:queue_logging',
+    '//aos/common/messages:robot_state',
     '//aos/common/util:log_interval',
     '//aos/common:queues',
+    '//aos/common:time',
   ],
 )
diff --git a/aos/common/controls/control_loop-tmpl.h b/aos/common/controls/control_loop-tmpl.h
index d6813fb..b2f85e7 100644
--- a/aos/common/controls/control_loop-tmpl.h
+++ b/aos/common/controls/control_loop-tmpl.h
@@ -2,8 +2,8 @@
 #include <inttypes.h>
 
 #include "aos/common/logging/logging.h"
-#include "aos/common/messages/robot_state.q.h"
 #include "aos/common/logging/queue_logging.h"
+#include "aos/common/messages/robot_state.q.h"
 
 namespace aos {
 namespace controls {
@@ -88,6 +88,7 @@
         control_loop_->output.MakeMessage();
     RunIteration(goal, position, output.get(), status.get());
 
+    output->SetTimeToNow();
     LOG_STRUCT(DEBUG, "output", *output);
     output.Send();
   } else {
@@ -96,6 +97,7 @@
     ZeroOutputs();
   }
 
+  status->SetTimeToNow();
   LOG_STRUCT(DEBUG, "status", *status);
   status.Send();
 }
diff --git a/aos/common/message.cc b/aos/common/message.cc
index 818c945..18acaa9 100644
--- a/aos/common/message.cc
+++ b/aos/common/message.cc
@@ -13,7 +13,7 @@
 
 size_t Message::Deserialize(const char *buffer) {
   int32_t sec;
-  int32_t nsec;
+  uint32_t nsec;
   to_host(&buffer[0], &sec);
   to_host(&buffer[4], &nsec);
   sent_time = monotonic_clock::time_point(chrono::seconds(sec) +
@@ -26,9 +26,9 @@
   int32_t sec =
       chrono::duration_cast<chrono::seconds>(sent_time.time_since_epoch())
           .count();
-  int32_t nsec = chrono::duration_cast<chrono::nanoseconds>(
-                     sent_time.time_since_epoch() - chrono::seconds(sec))
-                     .count();
+  uint32_t nsec = chrono::duration_cast<chrono::nanoseconds>(
+                      sent_time.time_since_epoch() - chrono::seconds(sec))
+                      .count();
   to_network(&sec, &buffer[0]);
   to_network(&nsec, &buffer[4]);
   return Size();
@@ -38,10 +38,10 @@
   int32_t sec =
       chrono::duration_cast<chrono::seconds>(sent_time.time_since_epoch())
           .count();
-  int32_t nsec = chrono::duration_cast<chrono::nanoseconds>(
-                     sent_time.time_since_epoch() - chrono::seconds(sec))
-                     .count();
-  return snprintf(buffer, length, "%" PRId32 ".%09" PRId32 "s", sec, nsec);
+  uint32_t nsec = chrono::duration_cast<chrono::nanoseconds>(
+                      sent_time.time_since_epoch() - chrono::seconds(sec))
+                      .count();
+  return snprintf(buffer, length, "%" PRId32 ".%09" PRIu32 "s", sec, nsec);
 }
 
 }  // namespace aos
diff --git a/aos/common/message.h b/aos/common/message.h
index 8ae7f16..f46969f 100644
--- a/aos/common/message.h
+++ b/aos/common/message.h
@@ -28,7 +28,11 @@
   size_t Serialize(char *buffer) const;
 
   // Populates sent_time with the current time.
-  void SetTimeToNow() { sent_time = monotonic_clock::now(); }
+  void SetTimeToNow() {
+    if (sent_time == monotonic_clock::min_time) {
+      sent_time = monotonic_clock::now();
+    }
+  }
 
   // Writes the contents of the message to the provided buffer.
   size_t Print(char *buffer, int length) const;
diff --git a/aos/common/queue_types.cc b/aos/common/queue_types.cc
index cff3c4f..3945395 100644
--- a/aos/common/queue_types.cc
+++ b/aos/common/queue_types.cc
@@ -164,16 +164,35 @@
 
 bool PrintMessage(char *output, size_t *output_bytes, const void *input,
                   size_t *input_bytes, const MessageType &type) {
-  *input_bytes -= type.super_size;
-  input = static_cast<const char *>(input) + type.super_size;
-
   if (*output_bytes < type.name.size() + 1) return false;
   *output_bytes -= type.name.size() + 1;
   memcpy(output, type.name.data(), type.name.size());
   output += type.name.size();
-  *(output++) = '{';
+  *output = '{';
+  ++output;
 
   bool first = true;
+  if (type.super_size == 8) {
+    size_t start_input_bytes = *input_bytes;
+
+    if (*output_bytes < 10) return false;
+    memcpy(output, "sendtime: ", 10);
+    output += 10;
+    *output_bytes -= 10;
+
+    size_t output_bytes_before = *output_bytes;
+    if (!PrintField(output, output_bytes, input, input_bytes, 0x5f372008u)) {
+      return false;
+    }
+    output += output_bytes_before - *output_bytes;
+    input = static_cast<const char *>(input) + type.super_size;
+    first = false;
+    CHECK(start_input_bytes == (*input_bytes + 8));
+  } else {
+    *input_bytes -= type.super_size;
+    input = static_cast<const char *>(input) + type.super_size;
+  }
+
   for (int i = 0; i < type.number_fields; ++i) {
     if (first) {
       first = false;
diff --git a/aos/common/queue_types_test.cc b/aos/common/queue_types_test.cc
index bbadf34..96d02bc 100644
--- a/aos/common/queue_types_test.cc
+++ b/aos/common/queue_types_test.cc
@@ -89,7 +89,7 @@
 
 class PrintMessageTest : public ::testing::Test {
  public:
-  char input[128], output[256];
+  char input[512], output[512];
   size_t input_bytes, output_bytes;
 };
 
@@ -194,18 +194,18 @@
 
 static const OtherTestingMessage kTestMessage1(true, 8971, 3.2);
 static const ::std::string kTestMessage1String =
-    ".aos.common.testing.OtherTestingMessage{test_bool:T, test_int:8971"
+    ".aos.common.testing.OtherTestingMessage{sendtime: -633437440.3735158s, test_bool:T, test_int:8971"
     ", test_double:3.200000}";
 static const Structure kTestStructure1(false, 973, 8.56);
 static const ::std::string kTestStructure1String =
-    ".aos.common.testing.Structure{struct_bool:f, struct_int:973"
-    ", struct_float:8.560000}";
+    ".aos.common.testing.Structure{struct_bool:f, struct_int:973, "
+    "struct_float:8.560000}";
 static const ::aos::common::testing::Structure kStructureValue(true, 973, 3.14);
 static const MessageWithArrays kTestMessageWithArrays({{971, 254, 1678}},
                                                       {{kStructureValue,
                                                         kStructureValue}});
 static const ::std::string kTestMessageWithArraysString =
-    ".aos.common.testing.MessageWithArrays{test_int:[971, 254, 1678], "
+    ".aos.common.testing.MessageWithArrays{sendtime: -633437440.3735158s, test_int:[971, 254, 1678], "
     "test_struct:[.aos.common.testing.Structure{struct_bool:T, struct_int:973, "
     "struct_float:3.140000}, .aos.common.testing.Structure{struct_bool:T, "
     "struct_int:973, struct_float:3.140000}]}";