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 <string.h>
18
19 #include <algorithm>
20 #include <cinttypes>
21 #include <string>
22 #include <tuple>
23 #include <utility>
24
25 #include "android-base/logging.h"
26 #include "android-base/stringprintf.h"
27
28 #include "wifilogd/byte_buffer.h"
29 #include "wifilogd/command_processor.h"
30 #include "wifilogd/local_utils.h"
31 #include "wifilogd/memory_reader.h"
32 #include "wifilogd/protocol.h"
33
34 namespace android {
35 namespace wifilogd {
36
37 using ::android::base::unique_fd;
38
39 using local_utils::CopyFromBufferOrDie;
40 using local_utils::GetMaxVal;
41
42 namespace {
43
44 uint32_t NsecToUsec(uint32_t nsec);
45
46 class TimestampHeader {
47 public:
set_since_boot_awake_only(Os::Timestamp new_value)48 TimestampHeader& set_since_boot_awake_only(Os::Timestamp new_value) {
49 since_boot_awake_only = new_value;
50 return *this;
51 }
52
set_since_boot_with_sleep(Os::Timestamp new_value)53 TimestampHeader& set_since_boot_with_sleep(Os::Timestamp new_value) {
54 since_boot_with_sleep = new_value;
55 return *this;
56 }
57
set_since_epoch(Os::Timestamp new_value)58 TimestampHeader& set_since_epoch(Os::Timestamp new_value) {
59 since_epoch = new_value;
60 return *this;
61 }
62
63 // Returns a string with a formatted representation of the timestamps
64 // contained within this header.
ToString() const65 std::string ToString() const {
66 const auto& awake_time = since_boot_awake_only;
67 const auto& up_time = since_boot_with_sleep;
68 const auto& wall_time = since_epoch;
69 return base::StringPrintf("%" PRIu32 ".%06" PRIu32
70 " "
71 "%" PRIu32 ".%06" PRIu32
72 " "
73 "%" PRIu32 ".%06" PRIu32,
74 awake_time.secs, NsecToUsec(awake_time.nsecs),
75 up_time.secs, NsecToUsec(up_time.nsecs),
76 wall_time.secs, NsecToUsec(wall_time.nsecs));
77 }
78
79 Os::Timestamp since_boot_awake_only;
80 Os::Timestamp since_boot_with_sleep;
81 Os::Timestamp since_epoch; // non-monotonic
82 };
83
84 constexpr char kUnprintableCharReplacement = '?';
85
86 std::string MakeSanitizedString(const uint8_t* buf, size_t buf_len);
87
GetStringFromMemoryReader(NONNULL MemoryReader * buffer_reader,const size_t desired_len)88 std::string GetStringFromMemoryReader(NONNULL MemoryReader* buffer_reader,
89 const size_t desired_len) {
90 constexpr char kBufferOverrunError[] = "[buffer-overrun]";
91 constexpr char kZeroLengthError[] = "[empty]";
92 if (!desired_len) {
93 // TODO(b/32098735): Increment stats counter.
94 return kZeroLengthError;
95 }
96
97 auto effective_len = desired_len;
98 if (buffer_reader->size() < effective_len) {
99 // TODO(b/32098735): Increment stats counter.
100 effective_len = buffer_reader->size();
101 }
102
103 auto out = MakeSanitizedString(buffer_reader->GetBytesOrDie(effective_len),
104 effective_len);
105 if (effective_len < desired_len) {
106 out += kBufferOverrunError;
107 }
108
109 return out;
110 }
111
MakeSanitizedString(const uint8_t * buf,size_t buf_len)112 std::string MakeSanitizedString(const uint8_t* buf, size_t buf_len) {
113 std::string out(buf_len, '\0');
114 std::replace_copy_if(buf, buf + buf_len, &out.front(),
115 [](auto c) { return !local_utils::IsAsciiPrintable(c); },
116 kUnprintableCharReplacement);
117 return out;
118 }
119
NsecToUsec(uint32_t nsec)120 uint32_t NsecToUsec(uint32_t nsec) { return nsec / 1000; }
121
122 } // namespace
123
CommandProcessor(size_t buffer_size_bytes)124 CommandProcessor::CommandProcessor(size_t buffer_size_bytes)
125 : current_log_buffer_(buffer_size_bytes), os_(new Os()) {}
126
CommandProcessor(size_t buffer_size_bytes,std::unique_ptr<Os> os)127 CommandProcessor::CommandProcessor(size_t buffer_size_bytes,
128 std::unique_ptr<Os> os)
129 : current_log_buffer_(buffer_size_bytes), os_(std::move(os)) {}
130
~CommandProcessor()131 CommandProcessor::~CommandProcessor() {}
132
ProcessCommand(const void * input_buffer,size_t n_bytes_read,int fd)133 bool CommandProcessor::ProcessCommand(const void* input_buffer,
134 size_t n_bytes_read, int fd) {
135 unique_fd wrapped_fd(fd);
136
137 if (n_bytes_read < sizeof(protocol::Command)) {
138 // TODO(b/32098735): Increment stats counter.
139 return false;
140 }
141
142 const auto& command_header =
143 CopyFromBufferOrDie<protocol::Command>(input_buffer, n_bytes_read);
144 switch (command_header.opcode) {
145 using protocol::Opcode;
146 case Opcode::kWriteAsciiMessage:
147 // Copy the entire command to the log. This defers the cost of
148 // validating the rest of the CommandHeader until we dump the
149 // message.
150 //
151 // Note that most messages will be written but never read. So, in
152 // the common case, the validation cost is actually eliminated,
153 // rather than just deferred.
154 return CopyCommandToLog(input_buffer, n_bytes_read);
155 case Opcode::kDumpBuffers:
156 return Dump(std::move(wrapped_fd));
157 }
158
159 LOG(DEBUG) << "Received unexpected opcode "
160 << local_utils::CastEnumToInteger(command_header.opcode);
161 // TODO(b/32098735): Increment stats counter.
162 return false;
163 }
164
165 // Private methods below.
166
CopyCommandToLog(const void * command_buffer,size_t command_len_in)167 bool CommandProcessor::CopyCommandToLog(const void* command_buffer,
168 size_t command_len_in) {
169 const uint16_t command_len =
170 SAFELY_CLAMP(command_len_in, uint16_t, 0, protocol::kMaxMessageSize);
171
172 uint16_t total_size;
173 static_assert(GetMaxVal(total_size) > sizeof(TimestampHeader) &&
174 GetMaxVal(total_size) - sizeof(TimestampHeader) >=
175 protocol::kMaxMessageSize,
176 "total_size cannot represent some input messages");
177 total_size = sizeof(TimestampHeader) + command_len;
178 CHECK(current_log_buffer_.CanFitEver(total_size));
179
180 if (!current_log_buffer_.CanFitNow(total_size)) {
181 // TODO(b/31867689):
182 // 1. compress current buffer
183 // 2. move old buffer to linked list
184 // 3. prune old buffers, if needed
185 current_log_buffer_.Clear();
186 }
187 CHECK(current_log_buffer_.CanFitNow(total_size));
188
189 const auto tstamp_header =
190 TimestampHeader()
191 .set_since_boot_awake_only(os_->GetTimestamp(CLOCK_MONOTONIC))
192 .set_since_boot_with_sleep(os_->GetTimestamp(CLOCK_BOOTTIME))
193 .set_since_epoch(os_->GetTimestamp(CLOCK_REALTIME));
194 const auto message_buf =
195 ByteBuffer<sizeof(TimestampHeader) + protocol::kMaxMessageSize>()
196 .AppendOrDie(&tstamp_header, sizeof(tstamp_header))
197 .AppendOrDie(command_buffer, command_len);
198 bool did_write = current_log_buffer_.Append(
199 message_buf.data(),
200 SAFELY_CLAMP(message_buf.size(), uint16_t, 0, GetMaxVal<uint16_t>()));
201 if (!did_write) {
202 // Given that we checked for enough free space, Append() should
203 // have succeeded. Hence, a failure here indicates a logic error,
204 // rather than a runtime error.
205 LOG(FATAL) << "Unexpected failure to Append()";
206 }
207
208 return true;
209 }
210
Dump(unique_fd dump_fd)211 bool CommandProcessor::Dump(unique_fd dump_fd) {
212 MessageBuffer::ScopedRewinder rewinder(¤t_log_buffer_);
213 while (auto buffer_reader =
214 MemoryReader(current_log_buffer_.ConsumeNextMessage())) {
215 const auto& tstamp_header = buffer_reader.CopyOutOrDie<TimestampHeader>();
216 const auto& command_header =
217 buffer_reader.CopyOutOrDie<protocol::Command>();
218
219 // TOOO(b/32256098): validate |buffer_reader.size()| against payload_len,
220 // and use a smaller size if necessary. Update a stats counter if
221 // payload_len and
222 // buflen do not match.
223
224 std::string output_string = tstamp_header.ToString();
225 switch (command_header.opcode) {
226 using protocol::Opcode;
227 case Opcode::kWriteAsciiMessage:
228 output_string += ' ' + FormatAsciiMessage(buffer_reader);
229 break;
230 case Opcode::kDumpBuffers:
231 LOG(FATAL) << "Unexpected DumpBuffers command in log";
232 }
233 output_string += '\n';
234
235 size_t n_written;
236 Os::Errno err;
237 std::tie(n_written, err) =
238 os_->Write(dump_fd, output_string.data(), output_string.size());
239 if (err == EINTR) {
240 // The next write will probably succeed. We dont't retry the current
241 // message, however, because we want to guarantee forward progress.
242 //
243 // TODO(b/32098735): Increment a counter, and attempt to output that
244 // counter after we've dumped all the log messages.
245 } else if (err) {
246 // Any error other than EINTR is considered unrecoverable.
247 LOG(ERROR) << "Terminating log dump, due to " << strerror(err);
248 return false;
249 }
250 }
251
252 return true;
253 }
254
FormatAsciiMessage(MemoryReader buffer_reader)255 std::string CommandProcessor::FormatAsciiMessage(MemoryReader buffer_reader) {
256 constexpr char kShortHeaderError[] = "[truncated-header]";
257 if (buffer_reader.size() < sizeof(protocol::AsciiMessage)) {
258 // TODO(b/32098735): Increment stats counter.
259 return kShortHeaderError;
260 }
261
262 const auto& ascii_message_header =
263 buffer_reader.CopyOutOrDie<protocol::AsciiMessage>();
264 const std::string& formatted_tag =
265 GetStringFromMemoryReader(&buffer_reader, ascii_message_header.tag_len);
266 const std::string& formatted_msg =
267 GetStringFromMemoryReader(&buffer_reader, ascii_message_header.data_len);
268 return formatted_tag + ' ' + formatted_msg;
269 }
270
271 } // namespace wifilogd
272 } // namespace android
273