/* * Copyright (C) 2016, The Android Open Source Project * * Licensed under the Apache License, Version 2.0 (the "License"); * you may not use this file except in compliance with the License. * You may obtain a copy of the License at * * http://www.apache.org/licenses/LICENSE-2.0 * * Unless required by applicable law or agreed to in writing, software * distributed under the License is distributed on an "AS IS" BASIS, * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. * See the License for the specific language governing permissions and * limitations under the License. */ #include #include #include #include #include #include #include #include #include #include "android-base/unique_fd.h" #include "gmock/gmock.h" #include "gtest/gtest.h" #include "wifilogd/byte_buffer.h" #include "wifilogd/local_utils.h" #include "wifilogd/protocol.h" #include "wifilogd/tests/mock_os.h" #include "wifilogd/command_processor.h" namespace android { namespace wifilogd { namespace { using ::android::base::unique_fd; using ::testing::_; using ::testing::AnyNumber; using ::testing::AtLeast; using ::testing::EndsWith; using ::testing::HasSubstr; using ::testing::Invoke; using ::testing::Return; using ::testing::StartsWith; using ::testing::StrictMock; using local_utils::GetMaxVal; // The CommandBuffer is deliberately larger than the maximal permitted // command, so that we can test the CommandProcessor's handling of oversized // inputs. using CommandBuffer = ByteBuffer; constexpr size_t kBufferSizeBytes = protocol::kMaxMessageSize * 16; constexpr char kLogRecordSeparator = '\n'; constexpr size_t kMaxAsciiMessagePayloadLen = protocol::kMaxMessageSize - sizeof(protocol::Command) - sizeof(protocol::AsciiMessage); class CommandProcessorTest : public ::testing::Test { public: CommandProcessorTest() { os_ = new StrictMock(); auto& accumulator = written_to_os_; ON_CALL(*os_, Write(_, _, _)) .WillByDefault(Invoke( [&accumulator](int /*fd*/, const void* write_buf, size_t buflen) { accumulator.append(static_cast(write_buf), buflen); return std::tuple(buflen, 0); })); command_processor_ = std::unique_ptr( new CommandProcessor(kBufferSizeBytes, std::unique_ptr(os_))); } protected: CommandBuffer BuildAsciiMessageCommandWithAdjustments( const std::string& tag, const std::string& message, ssize_t command_payload_len_adjustment, ssize_t ascii_message_tag_len_adjustment, ssize_t ascii_message_data_len_adjustment) { const size_t adjusted_tag_len = tag.length() + ascii_message_tag_len_adjustment; const size_t adjusted_data_len = message.length() + ascii_message_data_len_adjustment; const auto ascii_message_header = protocol::AsciiMessage() .set_tag_len(SAFELY_CLAMP( adjusted_tag_len, uint8_t, 0, GetMaxVal())) .set_data_len(SAFELY_CLAMP( adjusted_data_len, uint16_t, 0, GetMaxVal())) .set_severity(protocol::MessageSeverity::kError); EXPECT_EQ(adjusted_tag_len, ascii_message_header.tag_len); EXPECT_EQ(adjusted_data_len, ascii_message_header.data_len); const size_t payload_len = sizeof(ascii_message_header) + tag.length() + message.length() + command_payload_len_adjustment; const auto command = protocol::Command() .set_opcode(protocol::Opcode::kWriteAsciiMessage) .set_payload_len(SAFELY_CLAMP( payload_len, uint16_t, 0, GetMaxVal())); EXPECT_EQ(payload_len, command.payload_len); return CommandBuffer() .AppendOrDie(&command, sizeof(command)) .AppendOrDie(&ascii_message_header, sizeof(ascii_message_header)) .AppendOrDie(tag.data(), tag.length()) .AppendOrDie(message.data(), message.length()); } CommandBuffer BuildAsciiMessageCommand(const std::string& tag, const std::string& message) { return BuildAsciiMessageCommandWithAdjustments(tag, message, 0, 0, 0); } bool SendAsciiMessageWithAdjustments( const std::string& tag, const std::string& message, 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( tag, message, command_payload_len_adjustment, ascii_message_tag_len_adjustment, ascii_message_data_len_adjustment)); EXPECT_CALL(*os_, GetTimestamp(CLOCK_MONOTONIC)); EXPECT_CALL(*os_, GetTimestamp(CLOCK_BOOTTIME)); EXPECT_CALL(*os_, GetTimestamp(CLOCK_REALTIME)); return command_processor_->ProcessCommand( 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, 0); } bool SendDumpBuffers() { const auto command = protocol::Command() .set_opcode(protocol::Opcode::kDumpBuffers) .set_payload_len(0); const auto buf = CommandBuffer().AppendOrDie(&command, sizeof(command)); constexpr int kFakeFd = 100; return command_processor_->ProcessCommand(buf.data(), buf.size(), kFakeFd); } std::string written_to_os_; // Must out-live |os_| std::unique_ptr command_processor_; // We use a raw pointer to access the mock, since ownership passes // to |command_processor_|. StrictMock* os_; }; } // namespace // A valid ASCII message should, of course, be processed successfully. TEST_F(CommandProcessorTest, ProcessCommandOnValidAsciiMessageSucceeds) { EXPECT_TRUE(SendAsciiMessage("tag", "message")); } // If the buffer given to ProcessCommand() is shorter than a protocol::Command, // then we discard the data. TEST_F(CommandProcessorTest, ProcessCommandOnAsciiMessageShorterThanCommandFails) { const CommandBuffer& command_buffer( BuildAsciiMessageCommand("tag", "message")); EXPECT_FALSE(command_processor_->ProcessCommand( command_buffer.data(), sizeof(protocol::Command) - 1, Os::kInvalidFd)); } // In all other cases, we save the data we got, and will try to salvage the // contents when dumping. TEST_F(CommandProcessorTest, ProcessCommandOnAsciiMessageWithEmtpyTagSucceeds) { EXPECT_TRUE(SendAsciiMessage("", "message")); } TEST_F(CommandProcessorTest, ProcessCommandOnAsciiMessageWithEmptyMessageSucceeds) { EXPECT_TRUE(SendAsciiMessage("tag", "")); } TEST_F(CommandProcessorTest, ProcessCommandOnAsciiMessageWithEmptyTagAndMessageSucceeds) { EXPECT_TRUE(SendAsciiMessage("", "")); } TEST_F(CommandProcessorTest, ProcessCommandOnAsciiMessageWithBadCommandLengthSucceeds) { 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, 0, 1, 0)); EXPECT_TRUE(SendAsciiMessageWithAdjustments("tag", "message", 0, 0, -1, 0)); } TEST_F(CommandProcessorTest, ProcessCommandOnAsciiMessageWithBadMessageLengthSucceeds) { EXPECT_TRUE(SendAsciiMessageWithAdjustments("tag", "message", 0, 0, 0, 1)); EXPECT_TRUE(SendAsciiMessageWithAdjustments("tag", "message", 0, 0, 0, -1)); } TEST_F(CommandProcessorTest, ProcessCommandOnOverlyLargeAsciiMessageSucceeds) { const std::string tag{"tag"}; EXPECT_TRUE(SendAsciiMessage( tag, std::string(kMaxAsciiMessagePayloadLen - tag.size() + 1, '.'))); } TEST_F(CommandProcessorTest, ProcessCommandInvalidOpcodeReturnsFailure) { using opcode_enum_t = decltype(protocol::Command::opcode); using opcode_integral_t = std::underlying_type::type; constexpr auto invalid_opcode = GetMaxVal(); const auto command = protocol::Command() .set_opcode(local_utils::CopyFromBufferOrDie( &invalid_opcode, sizeof(invalid_opcode))) .set_payload_len(0); const auto buf = CommandBuffer().AppendOrDie(&command, sizeof(command)); constexpr int kFakeFd = 100; EXPECT_FALSE( command_processor_->ProcessCommand(buf.data(), buf.size(), kFakeFd)); } TEST_F(CommandProcessorTest, ProcessCommandSucceedsEvenAfterFillingBuffer) { const std::string tag{"tag"}; const std::string message(kMaxAsciiMessagePayloadLen - tag.size(), '.'); for (size_t cumulative_payload_bytes = 0; cumulative_payload_bytes <= kBufferSizeBytes; cumulative_payload_bytes += (tag.size() + message.size())) { EXPECT_TRUE(SendAsciiMessage(tag, message)); } } 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)); EXPECT_CALL(*os_, Write(_, _, _)).Times(AtLeast(1)); 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")); } EXPECT_CALL(*os_, Write(_, _, _)).Times(AtLeast(1)); EXPECT_TRUE(SendDumpBuffers()); EXPECT_EQ(kNumMessages, std::count(written_to_os_.begin(), written_to_os_.end(), 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")); EXPECT_CALL(*os_, Write(_, _, _)) .WillOnce(Return(std::tuple{-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(write_buf), buflen); return std::tuple{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")); EXPECT_CALL(*os_, Write(_, _, _)).Times(AtLeast(1)); ASSERT_TRUE(SendDumpBuffers()); ASSERT_GT(written_to_os_.size(), 0U); written_to_os_.clear(); ASSERT_EQ(0U, written_to_os_.size()); EXPECT_CALL(*os_, Write(_, _, _)).Times(AtLeast(1)); 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{-1, EBADF})); ASSERT_FALSE(SendDumpBuffers()); ASSERT_EQ(0U, written_to_os_.size()); EXPECT_CALL(*os_, Write(_, _, _)).Times(AtLeast(1)); EXPECT_TRUE(SendDumpBuffers()); EXPECT_GT(written_to_os_.size(), 0U); } // 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) { int pipe_fds[2]; ASSERT_EQ(0, pipe(pipe_fds)); const unique_fd our_fd{pipe_fds[0]}; const int their_fd = pipe_fds[1]; const CommandBuffer& command_buffer( BuildAsciiMessageCommand("tag", "message")); EXPECT_CALL(*os_, GetTimestamp(_)).Times(AnyNumber()); EXPECT_TRUE(command_processor_->ProcessCommand( command_buffer.data(), command_buffer.size(), their_fd)); EXPECT_EQ(-1, close(their_fd)); EXPECT_EQ(EBADF, errno); } // 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, ProcessCommandClosesFdEvenOnFailure) { int pipe_fds[2]; ASSERT_EQ(0, pipe(pipe_fds)); const unique_fd our_fd{pipe_fds[0]}; const int their_fd = pipe_fds[1]; const CommandBuffer command_buffer; EXPECT_FALSE(command_processor_->ProcessCommand( command_buffer.data(), command_buffer.size(), their_fd)); EXPECT_EQ(-1, close(their_fd)); EXPECT_EQ(EBADF, errno); } } // namespace wifilogd } // namespace android