got binary logging actually fully working (!!!)
diff --git a/aos/common/logging/logging_impl.cc b/aos/common/logging/logging_impl.cc
index bdc14ec..0413072 100644
--- a/aos/common/logging/logging_impl.cc
+++ b/aos/common/logging/logging_impl.cc
@@ -57,16 +57,15 @@
} // namespace
namespace internal {
+namespace {
-void FillInMessage(log_level level, const char *format, va_list ap,
- LogMessage *message) {
+void FillInMessageBase(log_level level, LogMessage *message) {
Context *context = Context::Get();
- ExecuteFormat(message->message, sizeof(message->message), format, ap);
-
message->level = level;
message->source = context->source;
- memcpy(message->name, context->name.c_str(), context->name.size() + 1);
+ memcpy(message->name, context->name.c_str(), context->name.size());
+ message->name_length = context->name.size();
time::Time now = time::Time::Now();
message->seconds = now.sec();
@@ -75,12 +74,75 @@
message->sequence = context->sequence++;
}
+} // namespace
+
+void FillInMessageStructure(log_level level,
+ const ::std::string &message_string, size_t size,
+ const MessageType *type,
+ const ::std::function<size_t(char *)> &serialize,
+ LogMessage *message) {
+ type_cache::AddShm(type->id);
+ message->structure.type_id = type->id;
+
+ FillInMessageBase(level, message);
+
+ if (message_string.size() + size > sizeof(message->structure.serialized)) {
+ LOG(FATAL, "serialized struct %s (size %zd) and message %s too big\n",
+ type->name.c_str(), size, message_string.c_str());
+ }
+ message->structure.string_length = message_string.size();
+ memcpy(message->structure.serialized, message_string.data(),
+ message->structure.string_length);
+
+ message->message_length = serialize(
+ &message->structure.serialized[message->structure.string_length]);
+ message->type = LogMessage::Type::kStruct;
+}
+
+void FillInMessage(log_level level, const char *format, va_list ap,
+ LogMessage *message) {
+ FillInMessageBase(level, message);
+
+ message->message_length =
+ ExecuteFormat(message->message, sizeof(message->message), format, ap);
+ message->type = LogMessage::Type::kString;
+}
+
void PrintMessage(FILE *output, const LogMessage &message) {
- fprintf(output, "%s(%" PRId32 ")(%05" PRIu16 "): %s at"
- " %010" PRId32 ".%09" PRId32 "s: %s",
- message.name, static_cast<int32_t>(message.source), message.sequence,
- log_str(message.level), message.seconds, message.nseconds,
- message.message);
+#define BASE_FORMAT \
+ "%.*s(%" PRId32 ")(%05" PRIu16 "): %s at %010" PRId32 ".%09" PRId32 "s: "
+#define BASE_ARGS \
+ static_cast<int>(message.name_length), message.name, \
+ static_cast<int32_t>(message.source), message.sequence, \
+ log_str(message.level), message.seconds, message.nseconds
+ switch (message.type) {
+ case LogMessage::Type::kString:
+ fprintf(output, BASE_FORMAT "%.*s", BASE_ARGS,
+ static_cast<int>(message.message_length), message.message);
+ break;
+ case LogMessage::Type::kStruct:
+ char buffer[LOG_MESSAGE_LEN];
+ size_t output_length = sizeof(buffer);
+ size_t input_length = message.message_length;
+ if (!PrintMessage(
+ buffer, &output_length,
+ message.structure.serialized + message.structure.string_length,
+ &input_length, type_cache::Get(message.structure.type_id))) {
+ LOG(FATAL,
+ "printing message (%.*s) of type %s into %zu-byte buffer failed\n",
+ static_cast<int>(message.message_length), message.message,
+ type_cache::Get(message.structure.type_id).name.c_str(),
+ sizeof(buffer));
+ }
+ if (input_length > 0) {
+ LOG(WARNING, "%zu extra bytes on message of type %s\n", input_length,
+ type_cache::Get(message.structure.type_id).name.c_str());
+ }
+ fprintf(output, BASE_FORMAT "%.*s: %.*s\n", BASE_ARGS,
+ static_cast<int>(message.message_length), message.message,
+ static_cast<int>(output_length), buffer);
+ break;
+ }
}
} // namespace internal
diff --git a/aos/common/logging/logging_impl.h b/aos/common/logging/logging_impl.h
index f2d9752..3d5b387 100644
--- a/aos/common/logging/logging_impl.h
+++ b/aos/common/logging/logging_impl.h
@@ -40,21 +40,30 @@
// using a gcc function attribute.
// The struct that the code uses for making logging calls.
-// Packed so that it ends up the same under both linux and vxworks.
-struct __attribute__((packed)) LogMessage {
-#ifdef __VXWORKS__
- static_assert(sizeof(pid_t) == sizeof(int),
- "we use task IDs (aka ints) and pid_t interchangeably");
-#endif
- // Actually the task ID (aka a pointer to the TCB) on the cRIO.
+struct LogMessage {
+ enum class Type : uint8_t {
+ kString, kStruct,
+ };
+
+ int32_t seconds, nseconds;
+ // message_length is the length of everything in message for all types.
+ size_t message_length, name_length;
pid_t source;
static_assert(sizeof(source) == 4, "that's how they get printed");
// Per task/thread.
uint16_t sequence;
+ Type type;
log_level level;
- int32_t seconds, nseconds;
char name[100];
- char message[LOG_MESSAGE_LEN];
+ union {
+ char message[LOG_MESSAGE_LEN];
+ struct {
+ uint32_t type_id;
+ size_t string_length;
+ // The message string and then the serialized structure.
+ char serialized[LOG_MESSAGE_LEN - sizeof(type) - sizeof(string_length)];
+ } structure;
+ };
};
static_assert(shm_ok<LogMessage>::value, "it's going in a queue");
@@ -245,8 +254,16 @@
} cork_data;
};
-// Fills in *message according to the given inputs. Used for implementing
-// LogImplementation::DoLog.
+// Fills in all the parts of message according to the given inputs (with type
+// kStruct).
+void FillInMessageStructure(log_level level,
+ const ::std::string &message_string, size_t size,
+ const MessageType *type,
+ const ::std::function<size_t(char *)> &serialize,
+ LogMessage *message);
+
+// Fills in *message according to the given inputs (with type kString).
+// Used for implementing LogImplementation::DoLog.
void FillInMessage(log_level level, const char *format, va_list ap,
LogMessage *message);
@@ -255,8 +272,8 @@
// Prints format (with ap) into output and correctly deals with the result
// being too long etc.
-void ExecuteFormat(char *output, size_t output_size, const char *format,
- va_list ap);
+size_t ExecuteFormat(char *output, size_t output_size, const char *format,
+ va_list ap);
// Runs the given function with the current LogImplementation (handles switching
// it out while running function etc).
diff --git a/aos/common/logging/logging_interface.cc b/aos/common/logging/logging_interface.cc
index 68a88a8..b4244fb 100644
--- a/aos/common/logging/logging_interface.cc
+++ b/aos/common/logging/logging_interface.cc
@@ -4,6 +4,8 @@
#include <stdarg.h>
#include <string.h>
+#include <type_traits>
+
#include "aos/common/die.h"
// This file only contains the code necessary to link (ie no implementations).
@@ -21,19 +23,21 @@
cork_data.Reset();
}
-void ExecuteFormat(char *output, size_t output_size,
- const char *format, va_list ap) {
- static const char *continued = "...\n";
+size_t ExecuteFormat(char *output, size_t output_size, const char *format,
+ va_list ap) {
+ static const char *const continued = "...\n";
const size_t size = output_size - strlen(continued);
const int ret = vsnprintf(output, size, format, ap);
+ typedef ::std::common_type<typeof(ret), typeof(size)>::type RetType;
if (ret < 0) {
LOG(FATAL, "vsnprintf(%p, %zd, %s, args) failed with %d (%s)\n",
output, size, format, errno, strerror(errno));
- } else if (static_cast<uintmax_t>(ret) >= static_cast<uintmax_t>(size)) {
+ } else if (static_cast<RetType>(ret) >= static_cast<RetType>(size)) {
// Overwrite the '\0' at the end of the existing data and
// copy in the one on the end of continued.
memcpy(&output[size - 1], continued, strlen(continued) + 1);
}
+ return ::std::min<RetType>(ret, size);
}
void RunWithCurrentImplementation(
diff --git a/aos/common/logging/queue_logging.h b/aos/common/logging/queue_logging.h
index 191d4c7..df343df 100644
--- a/aos/common/logging/queue_logging.h
+++ b/aos/common/logging/queue_logging.h
@@ -11,6 +11,7 @@
namespace aos {
namespace logging {
+#if 1
#define LOG_STRUCT(level, message, structure) \
do { \
static const ::std::string kAosLoggingMessage( \
@@ -23,6 +24,9 @@
abort(); \
} \
} while (false)
+#else
+#define LOG_STRUCT(level, message, structure)
+#endif
template <class T>
void DoLogStruct(log_level level, const ::std::string &message,
diff --git a/aos/linux_code/logging/binary_log_file.h b/aos/linux_code/logging/binary_log_file.h
index 83f8dde..58aa792 100644
--- a/aos/linux_code/logging/binary_log_file.h
+++ b/aos/linux_code/logging/binary_log_file.h
@@ -35,7 +35,7 @@
LogFileMessageHeader {
// Represents the type of an individual message.
enum class MessageType : uint16_t {
- // '\0'-terminated string.
+ // char[] (no '\0' on the end).
kString,
kStructType,
kStruct,
@@ -63,8 +63,7 @@
int32_t source;
static_assert(sizeof(source) >= sizeof(LogMessage::source), "PIDs won't fit");
- // Both including all of the bytes in that part of the message (ie any '\0's
- // etc).
+ // Both including all of the bytes in that part of the message.
uint32_t name_size, message_size;
uint16_t sequence;
diff --git a/aos/linux_code/logging/binary_log_writer.cc b/aos/linux_code/logging/binary_log_writer.cc
index 22c635e..aa81521 100644
--- a/aos/linux_code/logging/binary_log_writer.cc
+++ b/aos/linux_code/logging/binary_log_writer.cc
@@ -10,17 +10,52 @@
#include <fcntl.h>
#include <map>
+#include <unordered_set>
#include "aos/linux_code/logging/linux_logging.h"
#include "aos/linux_code/logging/binary_log_file.h"
#include "aos/linux_code/init.h"
#include "aos/linux_code/configuration.h"
+#include "aos/common/queue_types.h"
namespace aos {
namespace logging {
namespace linux_code {
namespace {
+void CheckTypeWritten(uint32_t type_id, LogFileAccessor &writer) {
+ static ::std::unordered_set<uint32_t> written_type_ids;
+ if (written_type_ids.count(type_id) > 0) return;
+ if (MessageType::IsPrimitive(type_id)) return;
+
+ const MessageType &type = type_cache::Get(type_id);
+ for (int i = 0; i < type.number_fields; ++i) {
+ CheckTypeWritten(type.fields[i]->type, writer);
+ }
+
+ char buffer[1024];
+ ssize_t size = type.Serialize(buffer, sizeof(buffer));
+ if (size == -1) {
+ LOG(WARNING, "%zu-byte buffer is too small to serialize type %s\n",
+ sizeof(buffer), type.name.c_str());
+ return;
+ }
+ LogFileMessageHeader *const output =
+ writer.GetWritePosition(sizeof(LogFileMessageHeader) + size);
+
+ output->time_sec = output->time_nsec = 0;
+ output->source = getpid();
+ output->name_size = 0;
+ output->sequence = 0;
+ output->level = FATAL;
+
+ memcpy(output + 1, buffer, size);
+ output->message_size = size;
+
+ output->type = LogFileMessageHeader::MessageType::kStructType;
+ futex_set(&output->marker);
+}
+
int BinaryLogReaderMain() {
InitNRT();
@@ -81,23 +116,52 @@
const LogMessage *const msg = ReadNext();
if (msg == NULL) continue;
- // add 1 for terminating '\0'
- size_t name_size = strlen(msg->name) + 1;
- size_t message_size = strlen(msg->message) + 1;
-
- LogFileMessageHeader *const output = writer.GetWritePosition(
- sizeof(LogFileMessageHeader) + name_size + message_size);
+ size_t output_length =
+ sizeof(LogFileMessageHeader) + msg->name_length + msg->message_length;
+ if (msg->type == LogMessage::Type::kStruct) {
+ output_length += sizeof(msg->structure.type_id) + sizeof(uint32_t) +
+ msg->structure.string_length;
+ CheckTypeWritten(msg->structure.type_id, writer);
+ }
+ LogFileMessageHeader *const output = writer.GetWritePosition(output_length);;
char *output_strings = reinterpret_cast<char *>(output) + sizeof(*output);
- output->name_size = name_size;
- output->message_size = message_size;
+ output->name_size = msg->name_length;
+ output->message_size = msg->message_length;
output->source = msg->source;
output->level = msg->level;
output->time_sec = msg->seconds;
output->time_nsec = msg->nseconds;
output->sequence = msg->sequence;
- output->type = LogFileMessageHeader::MessageType::kString;
- memcpy(output_strings, msg->name, name_size);
- memcpy(output_strings + name_size, msg->message, message_size);
+ memcpy(output_strings, msg->name, msg->name_length);
+
+ switch (msg->type) {
+ case LogMessage::Type::kString:
+ memcpy(output_strings + msg->name_length, msg->message,
+ msg->message_length);
+ output->type = LogFileMessageHeader::MessageType::kString;
+ break;
+ case LogMessage::Type::kStruct:
+ char *position = output_strings + msg->name_length;
+
+ memcpy(position, &msg->structure.type_id, sizeof(msg->structure.type_id));
+ position += sizeof(msg->structure.type_id);
+ output->message_size += sizeof(msg->structure.type_id);
+
+ uint32_t length = msg->structure.string_length;
+ memcpy(position, &length, sizeof(length));
+ position += sizeof(length);
+ memcpy(position, msg->structure.serialized, length);
+ position += length;
+ output->message_size += sizeof(length) + length;
+
+ memcpy(position,
+ msg->structure.serialized + msg->structure.string_length,
+ msg->message_length);
+
+ output->type = LogFileMessageHeader::MessageType::kStruct;
+ break;
+ }
+
futex_set(&output->marker);
logging::linux_code::Free(msg);
diff --git a/aos/linux_code/logging/linux_logging.cc b/aos/linux_code/logging/linux_logging.cc
index 985577b..676e3b7 100644
--- a/aos/linux_code/logging/linux_logging.cc
+++ b/aos/linux_code/logging/linux_logging.cc
@@ -25,15 +25,29 @@
namespace linux_code {
namespace {
-class linuxQueueLogImplementation : public LogImplementation {
- virtual void DoLog(log_level level, const char *format, va_list ap) {
+class LinuxQueueLogImplementation : public LogImplementation {
+ LogMessage *GetMessageOrDie() {
LogMessage *message = static_cast<LogMessage *>(queue->GetMessage());
if (message == NULL) {
- LOG(FATAL, "queue get message failed\n");
+ LOG(FATAL, "%p->GetMessage() failed\n", queue);
+ } else {
+ return message;
}
+ }
+ virtual void DoLog(log_level level, const char *format, va_list ap) override {
+ LogMessage *message = GetMessageOrDie();
internal::FillInMessage(level, format, ap, message);
+ Write(message);
+ }
+ virtual void LogStruct(log_level level, const ::std::string &message_string,
+ size_t size, const MessageType *type,
+ const ::std::function<size_t(char *)> &serialize)
+ override {
+ LogMessage *message = GetMessageOrDie();
+ internal::FillInMessageStructure(level, message_string, size, type,
+ serialize, message);
Write(message);
}
};
@@ -48,7 +62,7 @@
Die("logging: couldn't fetch queue\n");
}
- AddImplementation(new linuxQueueLogImplementation());
+ AddImplementation(new LinuxQueueLogImplementation());
}
const LogMessage *ReadNext(int flags, int *index) {
diff --git a/aos/linux_code/logging/log_displayer.cc b/aos/linux_code/logging/log_displayer.cc
index dc27c80..7b56f35 100644
--- a/aos/linux_code/logging/log_displayer.cc
+++ b/aos/linux_code/logging/log_displayer.cc
@@ -7,8 +7,13 @@
#include <inttypes.h>
#include <errno.h>
+#include <algorithm>
+
#include "aos/linux_code/logging/binary_log_file.h"
#include "aos/common/logging/logging_impl.h"
+#include "aos/common/queue_types.h"
+
+using ::aos::logging::linux_code::LogFileMessageHeader;
namespace {
@@ -45,6 +50,7 @@
int main(int argc, char **argv) {
const char *filter_name = NULL;
+ size_t filter_length;
log_level filter_level = INFO;
bool follow = false, start_at_beginning = true;
const char *filename = "aos_log-current";
@@ -80,6 +86,7 @@
abort();
case 'n':
filter_name = optarg;
+ filter_length = strlen(filter_name);
break;
case 'l':
filter_level = ::aos::logging::str_log(optarg);
@@ -141,7 +148,8 @@
if (!start_at_beginning) {
accessor.MoveToEnd();
}
- const ::aos::logging::linux_code::LogFileMessageHeader *msg;
+
+ const LogFileMessageHeader *msg;
::aos::logging::LogMessage log_message;
do {
msg = accessor.ReadNextMessage(follow);
@@ -149,25 +157,72 @@
fputs("reached end of file\n", stderr);
return 0;
}
- if (::aos::logging::log_gt_important(filter_level, msg->level)) continue;
- if (filter_name != NULL &&
- strcmp(filter_name,
- reinterpret_cast<const char *>(msg) + sizeof(*msg)) != 0) {
+
+ if (msg->type == LogFileMessageHeader::MessageType::kStructType) {
+ size_t bytes = msg->message_size;
+ ::aos::MessageType *type = ::aos::MessageType::Deserialize(
+ reinterpret_cast<const char *>(msg + 1), &bytes);
+ ::aos::type_cache::Add(*type);
continue;
}
+ if (::aos::logging::log_gt_important(filter_level, msg->level)) continue;
+ if (filter_name != NULL) {
+ if (filter_length != msg->name_size) continue;
+ if (memcmp(filter_name,
+ reinterpret_cast<const char *>(msg) + sizeof(*msg),
+ filter_length) !=
+ 0) {
+ continue;
+ }
+ }
+
log_message.source = msg->source;
log_message.sequence = msg->sequence;
log_message.level = msg->level;
log_message.seconds = msg->time_sec;
log_message.nseconds = msg->time_nsec;
- strncpy(log_message.name,
- reinterpret_cast<const char *>(msg) + sizeof(*msg),
- sizeof(log_message.name));
- strncpy(log_message.message,
- reinterpret_cast<const char *>(msg) + sizeof(*msg) +
- msg->name_size,
- sizeof(log_message.message));
+ memcpy(log_message.name, reinterpret_cast<const char *>(msg) + sizeof(*msg),
+ ::std::min<size_t>(sizeof(log_message.name), msg->name_size));
+ log_message.message_length = msg->message_size;
+ log_message.name_length = msg->name_size;
+
+ switch (msg->type) {
+ case LogFileMessageHeader::MessageType::kStruct: {
+ const char *position =
+ reinterpret_cast<const char *>(msg + 1) + msg->name_size;
+ memcpy(&log_message.structure.type_id, position,
+ sizeof(log_message.structure.type_id));
+ position += sizeof(log_message.structure.type_id);
+
+ uint32_t length;
+ memcpy(&length, position, sizeof(length));
+ log_message.structure.string_length = length;
+ position += sizeof(length);
+ memcpy(log_message.structure.serialized, position, length);
+ position += length;
+
+ log_message.message_length -=
+ sizeof(log_message.structure.type_id) + sizeof(uint32_t) +
+ log_message.structure.string_length;
+ memcpy(log_message.structure.serialized +
+ log_message.structure.string_length,
+ position, log_message.message_length);
+
+ log_message.type = ::aos::logging::LogMessage::Type::kStruct;
+ break;
+ }
+ case LogFileMessageHeader::MessageType::kString:
+ memcpy(
+ log_message.message,
+ reinterpret_cast<const char *>(msg) + sizeof(*msg) + msg->name_size,
+ ::std::min<size_t>(sizeof(log_message.message), msg->message_size));
+ log_message.type = ::aos::logging::LogMessage::Type::kString;
+ break;
+ case LogFileMessageHeader::MessageType::kStructType:
+ LOG(FATAL, "shouldn't get here\n");
+ break;
+ };
::aos::logging::internal::PrintMessage(stdout, log_message);
} while (msg != NULL);
}
diff --git a/aos/linux_code/logging/logging.gyp b/aos/linux_code/logging/logging.gyp
index 95459f3..32df43d 100644
--- a/aos/linux_code/logging/logging.gyp
+++ b/aos/linux_code/logging/logging.gyp
@@ -12,6 +12,7 @@
'<(AOS)/linux_code/linux_code.gyp:init',
'<(AOS)/linux_code/linux_code.gyp:configuration',
'binary_log_file',
+ '<(AOS)/common/common.gyp:queue_types',
],
},
{
@@ -37,6 +38,7 @@
'<(AOS)/build/aos.gyp:logging',
'<(AOS)/linux_code/linux_code.gyp:init',
'binary_log_file',
+ '<(AOS)/common/common.gyp:queue_types',
],
},
{