CommandProcessor: start dump implementation
Update CommandProcessor, to support dumping existing
logs. In order to keep the CL size reasonable, this
CL only implements dumping of the timestamps of each
message. Dumping the payload will be added in a follow-on
CL.
Note that the new unit tests use ::testing::Invoke(),
in a way that mixes the mocking and faking test
strategies in a single object. The GMock documentation
discourages this kind of mixing, in favor of splitting
a class into one piece that is to be mocked, and another
that is to be faked [1].
The reason we mix the strategies, despite the recommendation
to the contrary, is that we don't always want to fake
Os::Write(). Some times, we just want to mock that method.
Along the way:
- add a ScopedRewinder to MessageBuffer
- add the kDumpBuffers command to protocol::Opcode.
This command is numbered 0x20, to leave room for
addition kWrite<MessageType> commands.
[1]
https://github.com/google/googletest/blob/master/googlemock/docs/v1_6/CookBook.md
Specifically, "Having to mix a mock and a fake..."
Bug: 32098312
Test: ./runtests.sh
Change-Id: If221b47ae5615bbc114db5755ce9eb46b9934b6e
diff --git a/command_processor.cpp b/command_processor.cpp
index db2cc5c..8cc30e3 100644
--- a/command_processor.cpp
+++ b/command_processor.cpp
@@ -14,11 +14,15 @@
* limitations under the License.
*/
+#include <string.h>
+
#include <cinttypes>
+#include <string>
+#include <tuple>
#include <utility>
#include "android-base/logging.h"
-#include "android-base/unique_fd.h"
+#include "android-base/stringprintf.h"
#include "wifilogd/byte_buffer.h"
#include "wifilogd/command_processor.h"
@@ -33,6 +37,10 @@
using local_utils::CopyFromBufferOrDie;
using local_utils::GetMaxVal;
+namespace {
+uint32_t NsecToUsec(uint32_t nsec) { return nsec / 1000; }
+} // namespace
+
CommandProcessor::CommandProcessor(size_t buffer_size_bytes)
: current_log_buffer_(buffer_size_bytes), os_(new Os()) {}
@@ -61,11 +69,27 @@
// the common case, the validation cost is actually eliminated,
// rather than just deferred.
return CopyCommandToLog(input_buffer, n_bytes_read);
+ case Opcode::kDumpBuffers:
+ return Dump(std::move(wrapped_fd));
}
}
// Private methods below.
+std::string CommandProcessor::TimestampHeader::ToString() const {
+ const auto& awake_time = since_boot_awake_only;
+ const auto& up_time = since_boot_with_sleep;
+ const auto& wall_time = since_epoch;
+ return base::StringPrintf("%" PRIu32 ".%06" PRIu32
+ " "
+ "%" PRIu32 ".%06" PRIu32
+ " "
+ "%" PRIu32 ".%06" PRIu32,
+ awake_time.secs, NsecToUsec(awake_time.nsecs),
+ up_time.secs, NsecToUsec(up_time.nsecs),
+ wall_time.secs, NsecToUsec(wall_time.nsecs));
+}
+
bool CommandProcessor::CopyCommandToLog(const void* command_buffer,
size_t command_len_in) {
const uint16_t command_len =
@@ -110,5 +134,44 @@
return true;
}
+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);
+
+ const std::string timestamp_string(tstamp_header.ToString() + '\n');
+ size_t n_written;
+ Os::Errno err;
+ std::tie(n_written, err) =
+ os_->Write(dump_fd, timestamp_string.data(), timestamp_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.
+ //
+ // TODO(b/32098735): Increment a counter, and attempt to output that
+ // counter after we've dumped all the log messages.
+ } else if (err) {
+ // Any error other than EINTR is considered unrecoverable.
+ LOG(ERROR) << "Terminating log dump, due to " << strerror(err);
+ return false;
+ }
+
+ std::tie(buf, buflen) = current_log_buffer_.ConsumeNextMessage();
+ }
+
+ return true;
+}
+
} // namespace wifilogd
} // namespace android
diff --git a/command_processor.h b/command_processor.h
index 0c2ae66..90ec9b9 100644
--- a/command_processor.h
+++ b/command_processor.h
@@ -18,8 +18,10 @@
#define COMMAND_PROCESSOR_H_
#include <memory>
+#include <string>
#include "android-base/macros.h"
+#include "android-base/unique_fd.h"
#include "wifilogd/local_utils.h"
#include "wifilogd/message_buffer.h"
@@ -52,7 +54,12 @@
int fd);
private:
- struct TimestampHeader {
+ class TimestampHeader {
+ public:
+ // Returns a string with a formatted representation of the timestamps
+ // contained within this header.
+ std::string ToString() const;
+
Os::Timestamp since_boot_awake_only;
Os::Timestamp since_boot_with_sleep;
Os::Timestamp since_epoch; // non-monotonic
@@ -64,6 +71,10 @@
// true.
bool CopyCommandToLog(NONNULL const void* command_buffer, size_t command_len);
+ // Dumps all of the logged messages to |dump_fd|. Returns true unless
+ // an unrecoverable error was encountered.
+ bool Dump(::android::base::unique_fd dump_fd);
+
// The MessageBuffer is inlined, since there's not much value to mocking
// simple data objects. See Testing on the Toilet Episode 173.
MessageBuffer current_log_buffer_;
diff --git a/message_buffer.h b/message_buffer.h
index 15e394e..e56aa95 100644
--- a/message_buffer.h
+++ b/message_buffer.h
@@ -32,6 +32,18 @@
// a sequence of messages.
class MessageBuffer {
public:
+ // A wrapper which guarantees that a MessageBuffer will be rewound,
+ // when the program exits the wrapper's scope. The user must ensure that
+ // |buffer| does not expire before the ScopedRewinder.
+ class ScopedRewinder {
+ public:
+ explicit ScopedRewinder(NONNULL MessageBuffer* buffer) : buffer_(buffer) {}
+ ~ScopedRewinder() { buffer_->Rewind(); }
+
+ private:
+ MessageBuffer* const buffer_;
+ };
+
// Constructs the buffer. |size| must be greater than GetHeaderSize().
explicit MessageBuffer(size_t size);
diff --git a/protocol.h b/protocol.h
index 61c3627..369a9e5 100644
--- a/protocol.h
+++ b/protocol.h
@@ -39,6 +39,7 @@
enum class Opcode : uint16_t {
kWriteAsciiMessage,
+ kDumpBuffers = 0x20,
};
enum class MessageSeverity : uint8_t {
diff --git a/tests/command_processor_unittest.cpp b/tests/command_processor_unittest.cpp
index 3dc0579..4c25c33 100644
--- a/tests/command_processor_unittest.cpp
+++ b/tests/command_processor_unittest.cpp
@@ -14,10 +14,13 @@
* limitations under the License.
*/
+#include <errno.h>
#include <unistd.h>
+#include <algorithm>
#include <memory>
#include <string>
+#include <tuple>
#include <utility>
#include "android-base/unique_fd.h"
@@ -38,6 +41,11 @@
using ::android::base::unique_fd;
using ::testing::_;
using ::testing::AnyNumber;
+using ::testing::AtLeast;
+using ::testing::HasSubstr;
+using ::testing::Invoke;
+using ::testing::Return;
+using ::testing::StartsWith;
using ::testing::StrictMock;
using local_utils::GetMaxVal;
@@ -47,6 +55,7 @@
using CommandBuffer = ByteBuffer<protocol::kMaxMessageSize * 2>;
constexpr size_t kBufferSizeBytes = protocol::kMaxMessageSize * 16;
+constexpr char kLogRecordSeparator = '\n';
constexpr size_t kMaxAsciiMessagePayloadLen = protocol::kMaxMessageSize -
sizeof(protocol::Command) -
sizeof(protocol::AsciiMessage);
@@ -118,6 +127,18 @@
return SendAsciiMessageWithSizeAdjustments(tag, message, 0, 0, 0);
}
+ bool SendDumpBuffers() {
+ protocol::Command command{};
+ command.opcode = protocol::Opcode::kDumpBuffers;
+ command.payload_len = 0;
+
+ CommandBuffer buf;
+ buf.AppendOrDie(&command, sizeof(command));
+
+ constexpr int kFakeFd = 100;
+ return command_processor_->ProcessCommand(buf.data(), buf.size(), kFakeFd);
+ }
+
std::unique_ptr<CommandProcessor> command_processor_;
// We use a raw pointer to access the mock, since ownership passes
// to |command_processor_|.
@@ -191,6 +212,115 @@
}
}
+TEST_F(CommandProcessorTest,
+ ProcessCommandDumpBuffersOutputIncludesCorrectlyFormattedTimestamps) {
+ const CommandBuffer& command_buf(BuildAsciiMessageCommand("tag", "message"));
+ EXPECT_CALL(*os_, GetTimestamp(CLOCK_MONOTONIC))
+ .WillOnce(Return(Os::Timestamp{0, 999}));
+ EXPECT_CALL(*os_, GetTimestamp(CLOCK_BOOTTIME))
+ .WillOnce(Return(Os::Timestamp{1, 1000}));
+ EXPECT_CALL(*os_, GetTimestamp(CLOCK_REALTIME))
+ .WillOnce(Return(Os::Timestamp{123456, 123456000}));
+ EXPECT_TRUE(command_processor_->ProcessCommand(
+ command_buf.data(), command_buf.size(), Os::kInvalidFd));
+
+ std::string written_to_os;
+ EXPECT_CALL(*os_, Write(_, _, _))
+ .Times(AtLeast(1))
+ .WillRepeatedly(Invoke(
+ [&written_to_os](int /*fd*/, const void* write_buf, size_t buflen) {
+ written_to_os.append(static_cast<const char*>(write_buf), buflen);
+ return std::tuple<size_t, Os::Errno>(buflen, 0);
+ }));
+ EXPECT_TRUE(SendDumpBuffers());
+ EXPECT_THAT(written_to_os, StartsWith("0.000000 1.000001 123456.123456"));
+}
+
+TEST_F(CommandProcessorTest, ProcessCommandDumpBuffersSucceedsOnEmptyLog) {
+ EXPECT_CALL(*os_, Write(_, _, _)).Times(0);
+ EXPECT_TRUE(SendDumpBuffers());
+}
+
+TEST_F(CommandProcessorTest, ProcessCommandDumpBuffersIncludesAllMessages) {
+ constexpr int kNumMessages = 5;
+ for (size_t i = 0; i < kNumMessages; ++i) {
+ ASSERT_TRUE(SendAsciiMessage("tag", "message"));
+ }
+
+ std::string written_to_os;
+ EXPECT_CALL(*os_, Write(_, _, _))
+ .WillRepeatedly(Invoke(
+ [&written_to_os](int /*fd*/, const void* write_buf, size_t buflen) {
+ written_to_os.append(static_cast<const char*>(write_buf), buflen);
+ return std::tuple<size_t, Os::Errno>(buflen, 0);
+ }));
+ EXPECT_TRUE(SendDumpBuffers());
+ EXPECT_EQ(kNumMessages, std::count(written_to_os.begin(), written_to_os.end(),
+ kLogRecordSeparator));
+}
+
+TEST_F(CommandProcessorTest, ProcessCommandDumpBuffersStopsAfterFirstError) {
+ ASSERT_TRUE(SendAsciiMessage("tag", "message"));
+ ASSERT_TRUE(SendAsciiMessage("tag", "message"));
+
+ EXPECT_CALL(*os_, Write(_, _, _))
+ .WillOnce(Return(std::tuple<size_t, Os::Errno>{-1, EBADF}));
+ ASSERT_FALSE(SendDumpBuffers());
+}
+
+TEST_F(CommandProcessorTest, ProcessCommandDumpBuffersContinuesPastEintr) {
+ constexpr int kNumMessages = 5;
+ for (size_t i = 0; i < kNumMessages; ++i) {
+ ASSERT_TRUE(SendAsciiMessage("tag", "message"));
+ }
+
+ std::string written_to_os;
+ EXPECT_CALL(*os_, Write(_, _, _))
+ .WillRepeatedly(Invoke(
+ [&written_to_os](int /*fd*/, const void* write_buf, size_t buflen) {
+ written_to_os.append(static_cast<const char*>(write_buf), buflen);
+ return std::tuple<size_t, Os::Errno>{buflen / 2, EINTR};
+ }));
+ EXPECT_TRUE(SendDumpBuffers());
+ EXPECT_EQ(kNumMessages, std::count(written_to_os.begin(), written_to_os.end(),
+ kLogRecordSeparator));
+}
+
+TEST_F(CommandProcessorTest, ProcessCommandDumpBuffersIsIdempotent) {
+ ASSERT_TRUE(SendAsciiMessage("tag", "message"));
+
+ std::string written_to_os;
+ EXPECT_CALL(*os_, Write(_, _, _))
+ .WillRepeatedly(Invoke(
+ [&written_to_os](int /*fd*/, const void* write_buf, size_t buflen) {
+ written_to_os.append(static_cast<const char*>(write_buf), buflen);
+ return std::tuple<size_t, Os::Errno>(buflen, 0);
+ }));
+ ASSERT_TRUE(SendDumpBuffers());
+ ASSERT_GT(written_to_os.size(), 0U);
+ written_to_os.clear();
+
+ ASSERT_EQ(0U, written_to_os.size());
+ EXPECT_TRUE(SendDumpBuffers());
+ EXPECT_GT(written_to_os.size(), 0U);
+}
+
+TEST_F(CommandProcessorTest,
+ ProcessCommandDumpBuffersIsIdempotentEvenWithWriteFailure) {
+ ASSERT_TRUE(SendAsciiMessage("tag", "message"));
+ EXPECT_CALL(*os_, Write(_, _, _))
+ .WillOnce(Return(std::tuple<size_t, Os::Errno>{-1, EBADF}));
+ ASSERT_FALSE(SendDumpBuffers());
+
+ EXPECT_CALL(*os_, Write(_, _, _))
+ .Times(AtLeast(1))
+ .WillRepeatedly(
+ Invoke([](int /*fd*/, const void* /*write_buf*/, size_t buflen) {
+ return std::tuple<size_t, Os::Errno>(buflen, 0);
+ }));
+ EXPECT_TRUE(SendDumpBuffers());
+}
+
// Strictly speaking, this is not a unit test. But there's no easy way to get
// unique_fd to call on an instance of our Os.
TEST_F(CommandProcessorTest, ProcessCommandClosesFd) {
diff --git a/tests/protocol_unittest.cpp b/tests/protocol_unittest.cpp
index 9f810b1..76de58b 100644
--- a/tests/protocol_unittest.cpp
+++ b/tests/protocol_unittest.cpp
@@ -90,6 +90,7 @@
using protocol::Opcode;
EXPECT_EQ(2U, sizeof(Opcode));
EXPECT_EQ(0U, static_cast<uint16_t>(Opcode::kWriteAsciiMessage));
+ EXPECT_EQ(0x20U, static_cast<uint16_t>(Opcode::kDumpBuffers));
}
} // namespace wifilogd
