CommandProcessor: dump AsciiMessage payloads
Update CommandProcessor::Dump(), to include the
payload for AsciiMessages.
Along the way:
- extend SendAsciiMessageWithAdjustments(),
to allow tweaking of the transport-layer
packet size
- simplify the loop in Dump()
While there: elaborate the documentation for
the |current_log_buffer_| field. The additional
comments explain what validity assumptions can
be made of data in |current_log_buffer_|.
Bug: 32240979
Test: ./runtests.sh (on angler)
Change-Id: I670b88782317e39e42f083cc298aa71075482a9c
diff --git a/command_processor.cpp b/command_processor.cpp
index 8cc30e3..fa0b745 100644
--- a/command_processor.cpp
+++ b/command_processor.cpp
@@ -16,6 +16,7 @@
#include <string.h>
+#include <algorithm>
#include <cinttypes>
#include <string>
#include <tuple>
@@ -27,6 +28,7 @@
#include "wifilogd/byte_buffer.h"
#include "wifilogd/command_processor.h"
#include "wifilogd/local_utils.h"
+#include "wifilogd/memory_reader.h"
#include "wifilogd/protocol.h"
namespace android {
@@ -38,7 +40,45 @@
using local_utils::GetMaxVal;
namespace {
+
+constexpr char kUnprintableCharReplacement = '?';
+
+std::string MakeSanitizedString(const uint8_t* buf, size_t buf_len);
+
+std::string GetStringFromMemoryReader(NONNULL MemoryReader* buffer_reader,
+ const size_t desired_len) {
+ constexpr char kBufferOverrunError[] = "[buffer-overrun]";
+ constexpr char kZeroLengthError[] = "[empty]";
+ if (!desired_len) {
+ // TODO(b/32098735): Incremement stats counter.
+ return kZeroLengthError;
+ }
+
+ auto effective_len = desired_len;
+ if (buffer_reader->size() < effective_len) {
+ // TODO(b/32098735): Incremement stats counter.
+ effective_len = buffer_reader->size();
+ }
+
+ auto out = MakeSanitizedString(buffer_reader->GetBytesOrDie(effective_len),
+ effective_len);
+ if (effective_len < desired_len) {
+ out += kBufferOverrunError;
+ }
+
+ return out;
+}
+
+std::string MakeSanitizedString(const uint8_t* buf, size_t buf_len) {
+ std::string out(buf_len, '\0');
+ std::replace_copy_if(buf, buf + buf_len, &out.front(),
+ [](auto c) { return !local_utils::IsAsciiPrintable(c); },
+ kUnprintableCharReplacement);
+ return out;
+}
+
uint32_t NsecToUsec(uint32_t nsec) { return nsec / 1000; }
+
} // namespace
CommandProcessor::CommandProcessor(size_t buffer_size_bytes)
@@ -135,26 +175,34 @@
}
bool CommandProcessor::Dump(unique_fd dump_fd) {
- const uint8_t* buf = nullptr;
- size_t buflen = 0;
- static_assert(
- GetMaxVal(buflen) - sizeof(TimestampHeader) - sizeof(protocol::Command) >=
- GetMaxVal<decltype(protocol::Command::payload_len)>(),
- "buflen cannot accommodate some messages");
-
MessageBuffer::ScopedRewinder rewinder(¤t_log_buffer_);
- std::tie(buf, buflen) = current_log_buffer_.ConsumeNextMessage();
- while (buf) {
- const auto& tstamp_header =
- CopyFromBufferOrDie<TimestampHeader>(buf, buflen);
- buf += sizeof(tstamp_header);
- buflen -= sizeof(tstamp_header);
+ while (auto buffer_reader =
+ MemoryReader(current_log_buffer_.ConsumeNextMessage())) {
+ const auto& tstamp_header = buffer_reader.CopyOutOrDie<TimestampHeader>();
+ const auto& command_header =
+ buffer_reader.CopyOutOrDie<protocol::Command>();
- const std::string timestamp_string(tstamp_header.ToString() + '\n');
+ // TOOO(b/32256098): validate |buffer_reader.size()| against payload_len,
+ // and use a smaller size if necessary. Update a stats counter if
+ // payload_len and
+ // buflen do not match.
+
+ std::string output_string = tstamp_header.ToString();
+ switch (command_header.opcode) {
+ using protocol::Opcode;
+ case Opcode::kWriteAsciiMessage:
+ output_string += ' ' + FormatAsciiMessage(buffer_reader);
+ break;
+ case Opcode::kDumpBuffers:
+ LOG(FATAL) << "Unexpected DumpBuffers command in log";
+ break;
+ }
+ output_string += '\n';
+
size_t n_written;
Os::Errno err;
std::tie(n_written, err) =
- os_->Write(dump_fd, timestamp_string.data(), timestamp_string.size());
+ os_->Write(dump_fd, output_string.data(), output_string.size());
if (err == EINTR) {
// The next write will probably succeed. We dont't retry the current
// message, however, because we want to guarantee forward progress.
@@ -166,12 +214,26 @@
LOG(ERROR) << "Terminating log dump, due to " << strerror(err);
return false;
}
-
- std::tie(buf, buflen) = current_log_buffer_.ConsumeNextMessage();
}
return true;
}
+std::string CommandProcessor::FormatAsciiMessage(MemoryReader buffer_reader) {
+ constexpr char kShortHeaderError[] = "[truncated-header]";
+ if (buffer_reader.size() < sizeof(protocol::AsciiMessage)) {
+ // TODO(b/32098735): Incremement stats counter.
+ return kShortHeaderError;
+ }
+
+ const auto& ascii_message_header =
+ buffer_reader.CopyOutOrDie<protocol::AsciiMessage>();
+ const std::string& formatted_tag =
+ GetStringFromMemoryReader(&buffer_reader, ascii_message_header.tag_len);
+ const std::string& formatted_msg =
+ GetStringFromMemoryReader(&buffer_reader, ascii_message_header.data_len);
+ return formatted_tag + ' ' + formatted_msg;
+}
+
} // namespace wifilogd
} // namespace android
diff --git a/command_processor.h b/command_processor.h
index 90ec9b9..24ac21f 100644
--- a/command_processor.h
+++ b/command_processor.h
@@ -24,6 +24,7 @@
#include "android-base/unique_fd.h"
#include "wifilogd/local_utils.h"
+#include "wifilogd/memory_reader.h"
#include "wifilogd/message_buffer.h"
#include "wifilogd/os.h"
@@ -75,8 +76,22 @@
// an unrecoverable error was encountered.
bool Dump(::android::base::unique_fd dump_fd);
+ // Returns a human-friendly string representation of the AsciiMessage
+ // contained at the head of the memory referenced by |memory_reader|.
+ // Validates that |memory_reader| has enough bytes to contain an AsciiMessage
+ // header, and the payload described by that header. Reports any errors in
+ // the returned string.
+ std::string FormatAsciiMessage(MemoryReader memory_reader);
+
// The MessageBuffer is inlined, since there's not much value to mocking
// simple data objects. See Testing on the Toilet Episode 173.
+ //
+ // Note that the messages in |current_log_buffer_| have not been validated,
+ // expect to ensure that:
+ // a) each message starts with a TimestampHeader, and
+ // b) each message is large enough for a protocol::Command to follow the
+ // TimestampHeader,and
+ // c) the protocol::Command::opcode for each message is a supported opcode.
MessageBuffer current_log_buffer_;
const std::unique_ptr<Os> os_;
diff --git a/tests/command_processor_unittest.cpp b/tests/command_processor_unittest.cpp
index d9e3a7b..7b5d645 100644
--- a/tests/command_processor_unittest.cpp
+++ b/tests/command_processor_unittest.cpp
@@ -18,6 +18,7 @@
#include <unistd.h>
#include <algorithm>
+#include <cstring>
#include <memory>
#include <string>
#include <tuple>
@@ -42,6 +43,7 @@
using ::testing::_;
using ::testing::AnyNumber;
using ::testing::AtLeast;
+using ::testing::EndsWith;
using ::testing::HasSubstr;
using ::testing::Invoke;
using ::testing::Return;
@@ -118,7 +120,7 @@
bool SendAsciiMessageWithAdjustments(
const std::string& tag, const std::string& message,
- ssize_t command_payload_len_adjustment,
+ ssize_t transport_len_adjustment, ssize_t command_payload_len_adjustment,
ssize_t ascii_message_tag_len_adjustment,
ssize_t ascii_message_data_len_adjustment) {
const CommandBuffer& command_buffer(BuildAsciiMessageCommandWithAdjustments(
@@ -128,11 +130,12 @@
EXPECT_CALL(*os_, GetTimestamp(CLOCK_BOOTTIME));
EXPECT_CALL(*os_, GetTimestamp(CLOCK_REALTIME));
return command_processor_->ProcessCommand(
- command_buffer.data(), command_buffer.size(), Os::kInvalidFd);
+ command_buffer.data(), command_buffer.size() + transport_len_adjustment,
+ Os::kInvalidFd);
}
bool SendAsciiMessage(const std::string& tag, const std::string& message) {
- return SendAsciiMessageWithAdjustments(tag, message, 0, 0, 0);
+ return SendAsciiMessageWithAdjustments(tag, message, 0, 0, 0, 0);
}
bool SendDumpBuffers() {
@@ -189,20 +192,20 @@
TEST_F(CommandProcessorTest,
ProcessCommandOnAsciiMessageWithBadCommandLengthSucceeds) {
- EXPECT_TRUE(SendAsciiMessageWithAdjustments("tag", "message", 1, 0, 0));
- EXPECT_TRUE(SendAsciiMessageWithAdjustments("tag", "message", -1, 0, 0));
+ EXPECT_TRUE(SendAsciiMessageWithAdjustments("tag", "message", 0, 1, 0, 0));
+ EXPECT_TRUE(SendAsciiMessageWithAdjustments("tag", "message", 0, -1, 0, 0));
}
TEST_F(CommandProcessorTest,
ProcessCommandOnAsciiMessageWithBadTagLengthSucceeds) {
- EXPECT_TRUE(SendAsciiMessageWithAdjustments("tag", "message", 0, 1, 0));
- EXPECT_TRUE(SendAsciiMessageWithAdjustments("tag", "message", 0, -1, 0));
+ EXPECT_TRUE(SendAsciiMessageWithAdjustments("tag", "message", 0, 0, 1, 0));
+ EXPECT_TRUE(SendAsciiMessageWithAdjustments("tag", "message", 0, 0, -1, 0));
}
TEST_F(CommandProcessorTest,
ProcessCommandOnAsciiMessageWithBadMessageLengthSucceeds) {
- EXPECT_TRUE(SendAsciiMessageWithAdjustments("tag", "message", 0, 0, 1));
- EXPECT_TRUE(SendAsciiMessageWithAdjustments("tag", "message", 0, 0, -1));
+ EXPECT_TRUE(SendAsciiMessageWithAdjustments("tag", "message", 0, 0, 0, 1));
+ EXPECT_TRUE(SendAsciiMessageWithAdjustments("tag", "message", 0, 0, 0, -1));
}
TEST_F(CommandProcessorTest, ProcessCommandOnOverlyLargeAsciiMessageSucceeds) {
@@ -256,6 +259,115 @@
kLogRecordSeparator));
}
+TEST_F(CommandProcessorTest,
+ ProcessCommandDumpBuffersAsciiMessageIncludesTagAndMessage) {
+ ASSERT_TRUE(SendAsciiMessage("tag", "message"));
+ EXPECT_CALL(*os_, Write(_, _, _)).Times(AtLeast(1));
+ ASSERT_TRUE(SendDumpBuffers());
+ EXPECT_THAT(written_to_os_, EndsWith("tag message\n"));
+}
+
+TEST_F(CommandProcessorTest,
+ ProcessCommandDumpBuffersAsciiMessageHandlesEmptyTag) {
+ ASSERT_TRUE(SendAsciiMessage("", "message"));
+ EXPECT_CALL(*os_, Write(_, _, _)).Times(AtLeast(1));
+ ASSERT_TRUE(SendDumpBuffers());
+ EXPECT_THAT(written_to_os_, EndsWith("[empty] message\n"));
+}
+
+TEST_F(CommandProcessorTest,
+ ProcessCommandDumpBuffersAsciiMessageHandlesEmptyMessage) {
+ ASSERT_TRUE(SendAsciiMessage("tag", ""));
+ EXPECT_CALL(*os_, Write(_, _, _)).Times(AtLeast(1));
+ ASSERT_TRUE(SendDumpBuffers());
+ EXPECT_THAT(written_to_os_, EndsWith("tag [empty]\n"));
+}
+
+TEST_F(CommandProcessorTest,
+ ProcessCommandDumpBuffersAsciiMessageHandlesEmptyTagAndEmptyMessage) {
+ ASSERT_TRUE(SendAsciiMessage("", ""));
+ EXPECT_CALL(*os_, Write(_, _, _)).Times(AtLeast(1));
+ ASSERT_TRUE(SendDumpBuffers());
+ EXPECT_THAT(written_to_os_, EndsWith("[empty] [empty]\n"));
+}
+
+TEST_F(CommandProcessorTest,
+ ProcessCommandDumpBuffersAsciiMessageSanitizesUnprintableChars) {
+ ASSERT_TRUE(SendAsciiMessage("\xfftag\xff", "\xffmessage\xff"));
+ EXPECT_CALL(*os_, Write(_, _, _)).Times(AtLeast(1));
+ ASSERT_TRUE(SendDumpBuffers());
+ EXPECT_THAT(written_to_os_, EndsWith("?tag? ?message?\n"));
+}
+
+TEST_F(
+ CommandProcessorTest,
+ ProcessCommandDumpBuffersAsciiMessageHandlesMessageTooShortForAsciiMessage) { // NOLINT(whitespace/line_length)
+ ASSERT_TRUE(SendAsciiMessageWithAdjustments("", "", -1, 0, 0, 0));
+ EXPECT_CALL(*os_, Write(_, _, _)).Times(AtLeast(1));
+ ASSERT_TRUE(SendDumpBuffers());
+ EXPECT_THAT(written_to_os_, EndsWith("[truncated-header]\n"));
+}
+
+TEST_F(CommandProcessorTest,
+ ProcessCommandDumpBuffersAsciiMessageHandlesMessageTooShortForTagStart) {
+ constexpr char kTag[] = "tag";
+ constexpr char kMessage[] = "message";
+ ASSERT_TRUE(SendAsciiMessageWithAdjustments(
+ kTag, kMessage, -(std::strlen(kTag) + std::strlen(kMessage)), 0, 0, 0));
+ EXPECT_CALL(*os_, Write(_, _, _)).Times(AtLeast(1));
+ ASSERT_TRUE(SendDumpBuffers());
+ EXPECT_THAT(written_to_os_, EndsWith("[buffer-overrun] [buffer-overrun]\n"));
+}
+
+TEST_F(CommandProcessorTest,
+ ProcessCommandDumpBuffersAsciiMessageHandlesMessageTooShortForTagEnd) {
+ constexpr char kTag[] = "tag";
+ constexpr char kMessage[] = "message";
+ ASSERT_TRUE(SendAsciiMessageWithAdjustments(
+ kTag, kMessage, -(1 + std::strlen(kMessage)), 0, 0, 0));
+ EXPECT_CALL(*os_, Write(_, _, _)).Times(AtLeast(1));
+ ASSERT_TRUE(SendDumpBuffers());
+ EXPECT_THAT(written_to_os_,
+ EndsWith("ta[buffer-overrun] [buffer-overrun]\n"));
+}
+
+TEST_F(
+ CommandProcessorTest,
+ ProcessCommandDumpBuffersAsciiMessageHandlesMessageTooShortForLogMessageStart) { // NOLINT(whitespace/line_length)
+ constexpr char kTag[] = "tag";
+ constexpr char kMessage[] = "message";
+ ASSERT_TRUE(SendAsciiMessageWithAdjustments(kTag, kMessage,
+ -std::strlen(kMessage), 0, 0, 0));
+ EXPECT_CALL(*os_, Write(_, _, _)).Times(AtLeast(1));
+ ASSERT_TRUE(SendDumpBuffers());
+ EXPECT_THAT(written_to_os_, EndsWith("tag [buffer-overrun]\n"));
+}
+
+TEST_F(
+ CommandProcessorTest,
+ ProcessCommandDumpBuffersAsciiMessageHandlesMessageTooShortForLogMessageEnd) { // NOLINT(whitespace/line_length)
+ ASSERT_TRUE(SendAsciiMessageWithAdjustments("tag", "message", -1, 0, 0, 0));
+ EXPECT_CALL(*os_, Write(_, _, _)).Times(AtLeast(1));
+ ASSERT_TRUE(SendDumpBuffers());
+ EXPECT_THAT(written_to_os_, EndsWith("tag messag[buffer-overrun]\n"));
+}
+
+TEST_F(CommandProcessorTest,
+ ProcessCommandDumpBuffersAsciiMessageHandlesMessageTooLongForTag) {
+ ASSERT_TRUE(SendAsciiMessageWithAdjustments("tag", "", 100, 0, 0, 0));
+ EXPECT_CALL(*os_, Write(_, _, _)).Times(AtLeast(1));
+ ASSERT_TRUE(SendDumpBuffers());
+ EXPECT_THAT(written_to_os_, EndsWith("tag [empty]\n"));
+}
+
+TEST_F(CommandProcessorTest,
+ ProcessCommandDumpBuffersAsciiMessageHandlesMessageTooLongForMessage) {
+ ASSERT_TRUE(SendAsciiMessageWithAdjustments("tag", "message", 100, 0, 0, 0));
+ EXPECT_CALL(*os_, Write(_, _, _)).Times(AtLeast(1));
+ ASSERT_TRUE(SendDumpBuffers());
+ EXPECT_THAT(written_to_os_, EndsWith("tag message\n"));
+}
+
TEST_F(CommandProcessorTest, ProcessCommandDumpBuffersStopsAfterFirstError) {
ASSERT_TRUE(SendAsciiMessage("tag", "message"));
ASSERT_TRUE(SendAsciiMessage("tag", "message"));
