1/*
2 * Copyright (C) 2016, The Android Open Source Project
3 *
4 * Licensed under the Apache License, Version 2.0 (the "License");
5 * you may not use this file except in compliance with the License.
6 * You may obtain a copy of the License at
7 *
8 *     http://www.apache.org/licenses/LICENSE-2.0
9 *
10 * Unless required by applicable law or agreed to in writing, software
11 * distributed under the License is distributed on an "AS IS" BASIS,
12 * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
13 * See the License for the specific language governing permissions and
14 * limitations under the License.
15 */
16
17#include <errno.h>
18#include <unistd.h>
19
20#include <algorithm>
21#include <cstring>
22#include <memory>
23#include <string>
24#include <tuple>
25#include <type_traits>
26#include <utility>
27
28#include "android-base/unique_fd.h"
29#include "gmock/gmock.h"
30#include "gtest/gtest.h"
31
32#include "wifilogd/byte_buffer.h"
33#include "wifilogd/local_utils.h"
34#include "wifilogd/protocol.h"
35#include "wifilogd/tests/mock_os.h"
36
37#include "wifilogd/command_processor.h"
38
39namespace android {
40namespace wifilogd {
41namespace {
42
43using ::android::base::unique_fd;
44using ::testing::_;
45using ::testing::AnyNumber;
46using ::testing::AtLeast;
47using ::testing::EndsWith;
48using ::testing::HasSubstr;
49using ::testing::Invoke;
50using ::testing::Return;
51using ::testing::StartsWith;
52using ::testing::StrictMock;
53using local_utils::GetMaxVal;
54
55// The CommandBuffer is deliberately larger than the maximal permitted
56// command, so that we can test the CommandProcessor's handling of oversized
57// inputs.
58using CommandBuffer = ByteBuffer<protocol::kMaxMessageSize * 2>;
59
60constexpr size_t kBufferSizeBytes = protocol::kMaxMessageSize * 16;
61constexpr char kLogRecordSeparator = '\n';
62constexpr size_t kMaxAsciiMessagePayloadLen = protocol::kMaxMessageSize -
63                                              sizeof(protocol::Command) -
64                                              sizeof(protocol::AsciiMessage);
65
66class CommandProcessorTest : public ::testing::Test {
67 public:
68  CommandProcessorTest() {
69    os_ = new StrictMock<MockOs>();
70    auto& accumulator = written_to_os_;
71    ON_CALL(*os_, Write(_, _, _))
72        .WillByDefault(Invoke(
73            [&accumulator](int /*fd*/, const void* write_buf, size_t buflen) {
74              accumulator.append(static_cast<const char*>(write_buf), buflen);
75              return std::tuple<size_t, Os::Errno>(buflen, 0);
76            }));
77    command_processor_ = std::unique_ptr<CommandProcessor>(
78        new CommandProcessor(kBufferSizeBytes, std::unique_ptr<Os>(os_)));
79  }
80
81 protected:
82  CommandBuffer BuildAsciiMessageCommandWithAdjustments(
83      const std::string& tag, const std::string& message,
84      ssize_t command_payload_len_adjustment,
85      ssize_t ascii_message_tag_len_adjustment,
86      ssize_t ascii_message_data_len_adjustment) {
87    const size_t adjusted_tag_len =
88        tag.length() + ascii_message_tag_len_adjustment;
89    const size_t adjusted_data_len =
90        message.length() + ascii_message_data_len_adjustment;
91    const auto& ascii_message_header =
92        protocol::AsciiMessage()
93            .set_tag_len(SAFELY_CLAMP(
94                adjusted_tag_len, uint8_t, 0,
95                GetMaxVal<decltype(protocol::AsciiMessage::tag_len)>()))
96            .set_data_len(SAFELY_CLAMP(
97                adjusted_data_len, uint16_t, 0,
98                GetMaxVal<decltype(protocol::AsciiMessage::data_len)>()))
99            .set_severity(protocol::MessageSeverity::kError);
100    EXPECT_EQ(adjusted_tag_len, ascii_message_header.tag_len);
101    EXPECT_EQ(adjusted_data_len, ascii_message_header.data_len);
102
103    const size_t payload_len = sizeof(ascii_message_header) + tag.length() +
104                               message.length() +
105                               command_payload_len_adjustment;
106    const auto& command =
107        protocol::Command()
108            .set_opcode(protocol::Opcode::kWriteAsciiMessage)
109            .set_payload_len(SAFELY_CLAMP(
110                payload_len, uint16_t, 0,
111                GetMaxVal<decltype(protocol::Command::payload_len)>()));
112    EXPECT_EQ(payload_len, command.payload_len);
113    return CommandBuffer()
114        .AppendOrDie(&command, sizeof(command))
115        .AppendOrDie(&ascii_message_header, sizeof(ascii_message_header))
116        .AppendOrDie(tag.data(), tag.length())
117        .AppendOrDie(message.data(), message.length());
118  }
119
120  CommandBuffer BuildAsciiMessageCommand(const std::string& tag,
121                                         const std::string& message) {
122    return BuildAsciiMessageCommandWithAdjustments(tag, message, 0, 0, 0);
123  }
124
125  bool SendAsciiMessageWithAdjustments(
126      const std::string& tag, const std::string& message,
127      ssize_t transport_len_adjustment, ssize_t command_payload_len_adjustment,
128      ssize_t ascii_message_tag_len_adjustment,
129      ssize_t ascii_message_data_len_adjustment) {
130    const CommandBuffer& command_buffer(BuildAsciiMessageCommandWithAdjustments(
131        tag, message, command_payload_len_adjustment,
132        ascii_message_tag_len_adjustment, ascii_message_data_len_adjustment));
133    EXPECT_CALL(*os_, GetTimestamp(CLOCK_MONOTONIC));
134    EXPECT_CALL(*os_, GetTimestamp(CLOCK_BOOTTIME));
135    EXPECT_CALL(*os_, GetTimestamp(CLOCK_REALTIME));
136    return command_processor_->ProcessCommand(
137        command_buffer.data(), command_buffer.size() + transport_len_adjustment,
138        Os::kInvalidFd);
139  }
140
141  bool SendAsciiMessage(const std::string& tag, const std::string& message) {
142    return SendAsciiMessageWithAdjustments(tag, message, 0, 0, 0, 0);
143  }
144
145  bool SendDumpBuffers() {
146    const auto& command = protocol::Command()
147                              .set_opcode(protocol::Opcode::kDumpBuffers)
148                              .set_payload_len(0);
149    const auto& buf = CommandBuffer().AppendOrDie(&command, sizeof(command));
150    constexpr int kFakeFd = 100;
151    return command_processor_->ProcessCommand(buf.data(), buf.size(), kFakeFd);
152  }
153
154  std::string written_to_os_;  // Must out-live |os_|
155  std::unique_ptr<CommandProcessor> command_processor_;
156  // We use a raw pointer to access the mock, since ownership passes
157  // to |command_processor_|.
158  StrictMock<MockOs>* os_;
159};
160
161}  // namespace
162
163// A valid ASCII message should, of course, be processed successfully.
164TEST_F(CommandProcessorTest, ProcessCommandOnValidAsciiMessageSucceeds) {
165  EXPECT_TRUE(SendAsciiMessage("tag", "message"));
166}
167
168// If the buffer given to ProcessCommand() is shorter than a protocol::Command,
169// then we discard the data.
170TEST_F(CommandProcessorTest,
171       ProcessCommandOnAsciiMessageShorterThanCommandFails) {
172  const CommandBuffer& command_buffer(
173      BuildAsciiMessageCommand("tag", "message"));
174  EXPECT_FALSE(command_processor_->ProcessCommand(
175      command_buffer.data(), sizeof(protocol::Command) - 1, Os::kInvalidFd));
176}
177
178// In all other cases, we save the data we got, and will try to salvage the
179// contents when dumping.
180TEST_F(CommandProcessorTest, ProcessCommandOnAsciiMessageWithEmtpyTagSucceeds) {
181  EXPECT_TRUE(SendAsciiMessage("", "message"));
182}
183
184TEST_F(CommandProcessorTest,
185       ProcessCommandOnAsciiMessageWithEmptyMessageSucceeds) {
186  EXPECT_TRUE(SendAsciiMessage("tag", ""));
187}
188
189TEST_F(CommandProcessorTest,
190       ProcessCommandOnAsciiMessageWithEmptyTagAndMessageSucceeds) {
191  EXPECT_TRUE(SendAsciiMessage("", ""));
192}
193
194TEST_F(CommandProcessorTest,
195       ProcessCommandOnAsciiMessageWithBadCommandLengthSucceeds) {
196  EXPECT_TRUE(SendAsciiMessageWithAdjustments("tag", "message", 0, 1, 0, 0));
197  EXPECT_TRUE(SendAsciiMessageWithAdjustments("tag", "message", 0, -1, 0, 0));
198}
199
200TEST_F(CommandProcessorTest,
201       ProcessCommandOnAsciiMessageWithBadTagLengthSucceeds) {
202  EXPECT_TRUE(SendAsciiMessageWithAdjustments("tag", "message", 0, 0, 1, 0));
203  EXPECT_TRUE(SendAsciiMessageWithAdjustments("tag", "message", 0, 0, -1, 0));
204}
205
206TEST_F(CommandProcessorTest,
207       ProcessCommandOnAsciiMessageWithBadMessageLengthSucceeds) {
208  EXPECT_TRUE(SendAsciiMessageWithAdjustments("tag", "message", 0, 0, 0, 1));
209  EXPECT_TRUE(SendAsciiMessageWithAdjustments("tag", "message", 0, 0, 0, -1));
210}
211
212TEST_F(CommandProcessorTest, ProcessCommandOnOverlyLargeAsciiMessageSucceeds) {
213  const std::string tag{"tag"};
214  EXPECT_TRUE(SendAsciiMessage(
215      tag, std::string(kMaxAsciiMessagePayloadLen - tag.size() + 1, '.')));
216}
217
218TEST_F(CommandProcessorTest, ProcessCommandInvalidOpcodeReturnsFailure) {
219  using opcode_enum_t = decltype(protocol::Command::opcode);
220  using opcode_integral_t = std::underlying_type<opcode_enum_t>::type;
221  constexpr auto invalid_opcode = GetMaxVal<opcode_integral_t>();
222
223  const auto& command =
224      protocol::Command()
225          .set_opcode(local_utils::CopyFromBufferOrDie<opcode_enum_t>(
226              &invalid_opcode, sizeof(invalid_opcode)))
227          .set_payload_len(0);
228  const auto& buf = CommandBuffer().AppendOrDie(&command, sizeof(command));
229  constexpr int kFakeFd = 100;
230  EXPECT_FALSE(
231      command_processor_->ProcessCommand(buf.data(), buf.size(), kFakeFd));
232}
233
234TEST_F(CommandProcessorTest, ProcessCommandSucceedsEvenAfterFillingBuffer) {
235  const std::string tag{"tag"};
236  const std::string message(kMaxAsciiMessagePayloadLen - tag.size(), '.');
237  for (size_t cumulative_payload_bytes = 0;
238       cumulative_payload_bytes <= kBufferSizeBytes;
239       cumulative_payload_bytes += (tag.size() + message.size())) {
240    EXPECT_TRUE(SendAsciiMessage(tag, message));
241  }
242}
243
244TEST_F(CommandProcessorTest,
245       ProcessCommandDumpBuffersOutputIncludesCorrectlyFormattedTimestamps) {
246  const CommandBuffer& command_buf(BuildAsciiMessageCommand("tag", "message"));
247  EXPECT_CALL(*os_, GetTimestamp(CLOCK_MONOTONIC))
248      .WillOnce(Return(Os::Timestamp{0, 999}));
249  EXPECT_CALL(*os_, GetTimestamp(CLOCK_BOOTTIME))
250      .WillOnce(Return(Os::Timestamp{1, 1000}));
251  EXPECT_CALL(*os_, GetTimestamp(CLOCK_REALTIME))
252      .WillOnce(Return(Os::Timestamp{123456, 123456000}));
253  EXPECT_TRUE(command_processor_->ProcessCommand(
254      command_buf.data(), command_buf.size(), Os::kInvalidFd));
255
256  EXPECT_CALL(*os_, Write(_, _, _)).Times(AtLeast(1));
257  EXPECT_TRUE(SendDumpBuffers());
258  EXPECT_THAT(written_to_os_, StartsWith("0.000000 1.000001 123456.123456"));
259}
260
261TEST_F(CommandProcessorTest, ProcessCommandDumpBuffersSucceedsOnEmptyLog) {
262  EXPECT_CALL(*os_, Write(_, _, _)).Times(0);
263  EXPECT_TRUE(SendDumpBuffers());
264}
265
266TEST_F(CommandProcessorTest, ProcessCommandDumpBuffersIncludesAllMessages) {
267  constexpr int kNumMessages = 5;
268  for (size_t i = 0; i < kNumMessages; ++i) {
269    ASSERT_TRUE(SendAsciiMessage("tag", "message"));
270  }
271
272  EXPECT_CALL(*os_, Write(_, _, _)).Times(AtLeast(1));
273  EXPECT_TRUE(SendDumpBuffers());
274  EXPECT_EQ(kNumMessages,
275            std::count(written_to_os_.begin(), written_to_os_.end(),
276                       kLogRecordSeparator));
277}
278
279TEST_F(CommandProcessorTest,
280       ProcessCommandDumpBuffersAsciiMessageIncludesTagAndMessage) {
281  ASSERT_TRUE(SendAsciiMessage("tag", "message"));
282  EXPECT_CALL(*os_, Write(_, _, _)).Times(AtLeast(1));
283  ASSERT_TRUE(SendDumpBuffers());
284  EXPECT_THAT(written_to_os_, EndsWith("tag message\n"));
285}
286
287TEST_F(CommandProcessorTest,
288       ProcessCommandDumpBuffersAsciiMessageHandlesEmptyTag) {
289  ASSERT_TRUE(SendAsciiMessage("", "message"));
290  EXPECT_CALL(*os_, Write(_, _, _)).Times(AtLeast(1));
291  ASSERT_TRUE(SendDumpBuffers());
292  EXPECT_THAT(written_to_os_, EndsWith("[empty] message\n"));
293}
294
295TEST_F(CommandProcessorTest,
296       ProcessCommandDumpBuffersAsciiMessageHandlesEmptyMessage) {
297  ASSERT_TRUE(SendAsciiMessage("tag", ""));
298  EXPECT_CALL(*os_, Write(_, _, _)).Times(AtLeast(1));
299  ASSERT_TRUE(SendDumpBuffers());
300  EXPECT_THAT(written_to_os_, EndsWith("tag [empty]\n"));
301}
302
303TEST_F(CommandProcessorTest,
304       ProcessCommandDumpBuffersAsciiMessageHandlesEmptyTagAndEmptyMessage) {
305  ASSERT_TRUE(SendAsciiMessage("", ""));
306  EXPECT_CALL(*os_, Write(_, _, _)).Times(AtLeast(1));
307  ASSERT_TRUE(SendDumpBuffers());
308  EXPECT_THAT(written_to_os_, EndsWith("[empty] [empty]\n"));
309}
310
311TEST_F(CommandProcessorTest,
312       ProcessCommandDumpBuffersAsciiMessageSanitizesUnprintableChars) {
313  ASSERT_TRUE(SendAsciiMessage("\xfftag\xff", "\xffmessage\xff"));
314  EXPECT_CALL(*os_, Write(_, _, _)).Times(AtLeast(1));
315  ASSERT_TRUE(SendDumpBuffers());
316  EXPECT_THAT(written_to_os_, EndsWith("?tag? ?message?\n"));
317}
318
319TEST_F(
320    CommandProcessorTest,
321    ProcessCommandDumpBuffersAsciiMessageHandlesMessageTooShortForAsciiMessage) {  // NOLINT(whitespace/line_length)
322  ASSERT_TRUE(SendAsciiMessageWithAdjustments("", "", -1, 0, 0, 0));
323  EXPECT_CALL(*os_, Write(_, _, _)).Times(AtLeast(1));
324  ASSERT_TRUE(SendDumpBuffers());
325  EXPECT_THAT(written_to_os_, EndsWith("[truncated-header]\n"));
326}
327
328TEST_F(CommandProcessorTest,
329       ProcessCommandDumpBuffersAsciiMessageHandlesMessageTooShortForTagStart) {
330  constexpr char kTag[] = "tag";
331  constexpr char kMessage[] = "message";
332  ASSERT_TRUE(SendAsciiMessageWithAdjustments(
333      kTag, kMessage, -(std::strlen(kTag) + std::strlen(kMessage)), 0, 0, 0));
334  EXPECT_CALL(*os_, Write(_, _, _)).Times(AtLeast(1));
335  ASSERT_TRUE(SendDumpBuffers());
336  EXPECT_THAT(written_to_os_, EndsWith("[buffer-overrun] [buffer-overrun]\n"));
337}
338
339TEST_F(CommandProcessorTest,
340       ProcessCommandDumpBuffersAsciiMessageHandlesMessageTooShortForTagEnd) {
341  constexpr char kTag[] = "tag";
342  constexpr char kMessage[] = "message";
343  ASSERT_TRUE(SendAsciiMessageWithAdjustments(
344      kTag, kMessage, -(1 + std::strlen(kMessage)), 0, 0, 0));
345  EXPECT_CALL(*os_, Write(_, _, _)).Times(AtLeast(1));
346  ASSERT_TRUE(SendDumpBuffers());
347  EXPECT_THAT(written_to_os_,
348              EndsWith("ta[buffer-overrun] [buffer-overrun]\n"));
349}
350
351TEST_F(
352    CommandProcessorTest,
353    ProcessCommandDumpBuffersAsciiMessageHandlesMessageTooShortForLogMessageStart) {  // NOLINT(whitespace/line_length)
354  constexpr char kTag[] = "tag";
355  constexpr char kMessage[] = "message";
356  ASSERT_TRUE(SendAsciiMessageWithAdjustments(kTag, kMessage,
357                                              -std::strlen(kMessage), 0, 0, 0));
358  EXPECT_CALL(*os_, Write(_, _, _)).Times(AtLeast(1));
359  ASSERT_TRUE(SendDumpBuffers());
360  EXPECT_THAT(written_to_os_, EndsWith("tag [buffer-overrun]\n"));
361}
362
363TEST_F(
364    CommandProcessorTest,
365    ProcessCommandDumpBuffersAsciiMessageHandlesMessageTooShortForLogMessageEnd) {  // NOLINT(whitespace/line_length)
366  ASSERT_TRUE(SendAsciiMessageWithAdjustments("tag", "message", -1, 0, 0, 0));
367  EXPECT_CALL(*os_, Write(_, _, _)).Times(AtLeast(1));
368  ASSERT_TRUE(SendDumpBuffers());
369  EXPECT_THAT(written_to_os_, EndsWith("tag messag[buffer-overrun]\n"));
370}
371
372TEST_F(CommandProcessorTest,
373       ProcessCommandDumpBuffersAsciiMessageHandlesMessageTooLongForTag) {
374  ASSERT_TRUE(SendAsciiMessageWithAdjustments("tag", "", 100, 0, 0, 0));
375  EXPECT_CALL(*os_, Write(_, _, _)).Times(AtLeast(1));
376  ASSERT_TRUE(SendDumpBuffers());
377  EXPECT_THAT(written_to_os_, EndsWith("tag [empty]\n"));
378}
379
380TEST_F(CommandProcessorTest,
381       ProcessCommandDumpBuffersAsciiMessageHandlesMessageTooLongForMessage) {
382  ASSERT_TRUE(SendAsciiMessageWithAdjustments("tag", "message", 100, 0, 0, 0));
383  EXPECT_CALL(*os_, Write(_, _, _)).Times(AtLeast(1));
384  ASSERT_TRUE(SendDumpBuffers());
385  EXPECT_THAT(written_to_os_, EndsWith("tag message\n"));
386}
387
388TEST_F(CommandProcessorTest, ProcessCommandDumpBuffersStopsAfterFirstError) {
389  ASSERT_TRUE(SendAsciiMessage("tag", "message"));
390  ASSERT_TRUE(SendAsciiMessage("tag", "message"));
391
392  EXPECT_CALL(*os_, Write(_, _, _))
393      .WillOnce(Return(std::tuple<size_t, Os::Errno>{-1, EBADF}));
394  ASSERT_FALSE(SendDumpBuffers());
395}
396
397TEST_F(CommandProcessorTest, ProcessCommandDumpBuffersContinuesPastEintr) {
398  constexpr int kNumMessages = 5;
399  for (size_t i = 0; i < kNumMessages; ++i) {
400    ASSERT_TRUE(SendAsciiMessage("tag", "message"));
401  }
402
403  std::string written_to_os;
404  EXPECT_CALL(*os_, Write(_, _, _))
405      .WillRepeatedly(Invoke(
406          [&written_to_os](int /*fd*/, const void* write_buf, size_t buflen) {
407            written_to_os.append(static_cast<const char*>(write_buf), buflen);
408            return std::tuple<size_t, Os::Errno>{buflen / 2, EINTR};
409          }));
410  EXPECT_TRUE(SendDumpBuffers());
411  EXPECT_EQ(kNumMessages, std::count(written_to_os.begin(), written_to_os.end(),
412                                     kLogRecordSeparator));
413}
414
415TEST_F(CommandProcessorTest, ProcessCommandDumpBuffersIsIdempotent) {
416  ASSERT_TRUE(SendAsciiMessage("tag", "message"));
417
418  EXPECT_CALL(*os_, Write(_, _, _)).Times(AtLeast(1));
419  ASSERT_TRUE(SendDumpBuffers());
420  ASSERT_GT(written_to_os_.size(), 0U);
421  written_to_os_.clear();
422  ASSERT_EQ(0U, written_to_os_.size());
423
424  EXPECT_CALL(*os_, Write(_, _, _)).Times(AtLeast(1));
425  EXPECT_TRUE(SendDumpBuffers());
426  EXPECT_GT(written_to_os_.size(), 0U);
427}
428
429TEST_F(CommandProcessorTest,
430       ProcessCommandDumpBuffersIsIdempotentEvenWithWriteFailure) {
431  ASSERT_TRUE(SendAsciiMessage("tag", "message"));
432  EXPECT_CALL(*os_, Write(_, _, _))
433      .WillOnce(Return(std::tuple<size_t, Os::Errno>{-1, EBADF}));
434  ASSERT_FALSE(SendDumpBuffers());
435  ASSERT_EQ(0U, written_to_os_.size());
436
437  EXPECT_CALL(*os_, Write(_, _, _)).Times(AtLeast(1));
438  EXPECT_TRUE(SendDumpBuffers());
439  EXPECT_GT(written_to_os_.size(), 0U);
440}
441
442// Strictly speaking, this is not a unit test. But there's no easy way to get
443// unique_fd to call on an instance of our Os.
444TEST_F(CommandProcessorTest, ProcessCommandClosesFd) {
445  int pipe_fds[2];
446  ASSERT_EQ(0, pipe(pipe_fds));
447
448  const unique_fd our_fd{pipe_fds[0]};
449  const int their_fd = pipe_fds[1];
450  const CommandBuffer& command_buffer(
451      BuildAsciiMessageCommand("tag", "message"));
452  EXPECT_CALL(*os_, GetTimestamp(_)).Times(AnyNumber());
453  EXPECT_TRUE(command_processor_->ProcessCommand(
454      command_buffer.data(), command_buffer.size(), their_fd));
455  EXPECT_EQ(-1, close(their_fd));
456  EXPECT_EQ(EBADF, errno);
457}
458
459// Strictly speaking, this is not a unit test. But there's no easy way to get
460// unique_fd to call on an instance of our Os.
461TEST_F(CommandProcessorTest, ProcessCommandClosesFdEvenOnFailure) {
462  int pipe_fds[2];
463  ASSERT_EQ(0, pipe(pipe_fds));
464
465  const unique_fd our_fd{pipe_fds[0]};
466  const int their_fd = pipe_fds[1];
467  const CommandBuffer command_buffer;
468  EXPECT_FALSE(command_processor_->ProcessCommand(
469      command_buffer.data(), command_buffer.size(), their_fd));
470  EXPECT_EQ(-1, close(their_fd));
471  EXPECT_EQ(EBADF, errno);
472}
473
474}  // namespace wifilogd
475}  // namespace android
476