mukesh agrawal | 6306897 | 2016-09-29 17:42:46 -0700 | [diff] [blame] | 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 | |
mukesh agrawal | fd08064 | 2016-10-07 15:45:37 -0700 | [diff] [blame] | 17 | #include <string.h> |
| 18 | |
mukesh agrawal | 93f78dc | 2016-10-13 16:07:40 -0700 | [diff] [blame] | 19 | #include <algorithm> |
mukesh agrawal | 6306897 | 2016-09-29 17:42:46 -0700 | [diff] [blame] | 20 | #include <cinttypes> |
mukesh agrawal | fd08064 | 2016-10-07 15:45:37 -0700 | [diff] [blame] | 21 | #include <string> |
| 22 | #include <tuple> |
mukesh agrawal | 6306897 | 2016-09-29 17:42:46 -0700 | [diff] [blame] | 23 | #include <utility> |
| 24 | |
| 25 | #include "android-base/logging.h" |
mukesh agrawal | fd08064 | 2016-10-07 15:45:37 -0700 | [diff] [blame] | 26 | #include "android-base/stringprintf.h" |
mukesh agrawal | 6306897 | 2016-09-29 17:42:46 -0700 | [diff] [blame] | 27 | |
| 28 | #include "wifilogd/byte_buffer.h" |
| 29 | #include "wifilogd/command_processor.h" |
| 30 | #include "wifilogd/local_utils.h" |
mukesh agrawal | 93f78dc | 2016-10-13 16:07:40 -0700 | [diff] [blame] | 31 | #include "wifilogd/memory_reader.h" |
mukesh agrawal | 6306897 | 2016-09-29 17:42:46 -0700 | [diff] [blame] | 32 | #include "wifilogd/protocol.h" |
| 33 | |
| 34 | namespace android { |
| 35 | namespace wifilogd { |
| 36 | |
mukesh agrawal | cc8458a | 2016-10-06 15:45:35 -0700 | [diff] [blame] | 37 | using ::android::base::unique_fd; |
| 38 | |
mukesh agrawal | 6306897 | 2016-09-29 17:42:46 -0700 | [diff] [blame] | 39 | using local_utils::CopyFromBufferOrDie; |
| 40 | using local_utils::GetMaxVal; |
| 41 | |
mukesh agrawal | fd08064 | 2016-10-07 15:45:37 -0700 | [diff] [blame] | 42 | namespace { |
mukesh agrawal | 93f78dc | 2016-10-13 16:07:40 -0700 | [diff] [blame] | 43 | |
mukesh agrawal | 188f047 | 2016-11-11 14:19:42 -0800 | [diff] [blame] | 44 | uint32_t NsecToUsec(uint32_t nsec); |
| 45 | |
| 46 | class TimestampHeader { |
| 47 | public: |
| 48 | TimestampHeader& set_since_boot_awake_only(Os::Timestamp new_value) { |
| 49 | since_boot_awake_only = new_value; |
| 50 | return *this; |
| 51 | } |
| 52 | |
| 53 | TimestampHeader& set_since_boot_with_sleep(Os::Timestamp new_value) { |
| 54 | since_boot_with_sleep = new_value; |
| 55 | return *this; |
| 56 | } |
| 57 | |
| 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. |
| 65 | 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 | |
mukesh agrawal | 93f78dc | 2016-10-13 16:07:40 -0700 | [diff] [blame] | 84 | constexpr char kUnprintableCharReplacement = '?'; |
| 85 | |
| 86 | std::string MakeSanitizedString(const uint8_t* buf, size_t buf_len); |
| 87 | |
| 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) { |
mukesh agrawal | 82816d2 | 2016-10-27 14:18:29 -0700 | [diff] [blame] | 93 | // TODO(b/32098735): Increment stats counter. |
mukesh agrawal | 93f78dc | 2016-10-13 16:07:40 -0700 | [diff] [blame] | 94 | return kZeroLengthError; |
| 95 | } |
| 96 | |
| 97 | auto effective_len = desired_len; |
| 98 | if (buffer_reader->size() < effective_len) { |
mukesh agrawal | 82816d2 | 2016-10-27 14:18:29 -0700 | [diff] [blame] | 99 | // TODO(b/32098735): Increment stats counter. |
mukesh agrawal | 93f78dc | 2016-10-13 16:07:40 -0700 | [diff] [blame] | 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 | |
| 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 | |
mukesh agrawal | fd08064 | 2016-10-07 15:45:37 -0700 | [diff] [blame] | 120 | uint32_t NsecToUsec(uint32_t nsec) { return nsec / 1000; } |
mukesh agrawal | 93f78dc | 2016-10-13 16:07:40 -0700 | [diff] [blame] | 121 | |
mukesh agrawal | fd08064 | 2016-10-07 15:45:37 -0700 | [diff] [blame] | 122 | } // namespace |
| 123 | |
mukesh agrawal | 6306897 | 2016-09-29 17:42:46 -0700 | [diff] [blame] | 124 | CommandProcessor::CommandProcessor(size_t buffer_size_bytes) |
| 125 | : current_log_buffer_(buffer_size_bytes), os_(new Os()) {} |
| 126 | |
| 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 | |
mukesh agrawal | 82816d2 | 2016-10-27 14:18:29 -0700 | [diff] [blame] | 131 | CommandProcessor::~CommandProcessor() {} |
| 132 | |
mukesh agrawal | cc8458a | 2016-10-06 15:45:35 -0700 | [diff] [blame] | 133 | bool CommandProcessor::ProcessCommand(const void* input_buffer, |
| 134 | size_t n_bytes_read, int fd) { |
| 135 | unique_fd wrapped_fd(fd); |
| 136 | |
mukesh agrawal | 6306897 | 2016-09-29 17:42:46 -0700 | [diff] [blame] | 137 | if (n_bytes_read < sizeof(protocol::Command)) { |
mukesh agrawal | 82816d2 | 2016-10-27 14:18:29 -0700 | [diff] [blame] | 138 | // TODO(b/32098735): Increment stats counter. |
mukesh agrawal | 6306897 | 2016-09-29 17:42:46 -0700 | [diff] [blame] | 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); |
mukesh agrawal | fd08064 | 2016-10-07 15:45:37 -0700 | [diff] [blame] | 155 | case Opcode::kDumpBuffers: |
| 156 | return Dump(std::move(wrapped_fd)); |
mukesh agrawal | 6306897 | 2016-09-29 17:42:46 -0700 | [diff] [blame] | 157 | } |
mukesh agrawal | b0f1f44 | 2016-10-20 15:09:35 -0700 | [diff] [blame] | 158 | |
| 159 | LOG(DEBUG) << "Received unexpected opcode " |
| 160 | << local_utils::CastEnumToInteger(command_header.opcode); |
mukesh agrawal | 82816d2 | 2016-10-27 14:18:29 -0700 | [diff] [blame] | 161 | // TODO(b/32098735): Increment stats counter. |
mukesh agrawal | b0f1f44 | 2016-10-20 15:09:35 -0700 | [diff] [blame] | 162 | return false; |
mukesh agrawal | 6306897 | 2016-09-29 17:42:46 -0700 | [diff] [blame] | 163 | } |
| 164 | |
| 165 | // Private methods below. |
| 166 | |
| 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 | |
xshu | 31aa7aa | 2017-09-29 14:05:32 -0700 | [diff] [blame] | 189 | const auto tstamp_header = |
mukesh agrawal | 188f047 | 2016-11-11 14:19:42 -0800 | [diff] [blame] | 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)); |
xshu | 31aa7aa | 2017-09-29 14:05:32 -0700 | [diff] [blame] | 194 | const auto message_buf = |
mukesh agrawal | 937164d | 2016-10-20 15:35:26 -0700 | [diff] [blame] | 195 | ByteBuffer<sizeof(TimestampHeader) + protocol::kMaxMessageSize>() |
| 196 | .AppendOrDie(&tstamp_header, sizeof(tstamp_header)) |
| 197 | .AppendOrDie(command_buffer, command_len); |
mukesh agrawal | 6306897 | 2016-09-29 17:42:46 -0700 | [diff] [blame] | 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 | |
mukesh agrawal | fd08064 | 2016-10-07 15:45:37 -0700 | [diff] [blame] | 211 | bool CommandProcessor::Dump(unique_fd dump_fd) { |
mukesh agrawal | fd08064 | 2016-10-07 15:45:37 -0700 | [diff] [blame] | 212 | MessageBuffer::ScopedRewinder rewinder(¤t_log_buffer_); |
mukesh agrawal | 93f78dc | 2016-10-13 16:07:40 -0700 | [diff] [blame] | 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>(); |
mukesh agrawal | fd08064 | 2016-10-07 15:45:37 -0700 | [diff] [blame] | 218 | |
mukesh agrawal | 93f78dc | 2016-10-13 16:07:40 -0700 | [diff] [blame] | 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 | break; |
| 233 | } |
| 234 | output_string += '\n'; |
| 235 | |
mukesh agrawal | fd08064 | 2016-10-07 15:45:37 -0700 | [diff] [blame] | 236 | size_t n_written; |
| 237 | Os::Errno err; |
| 238 | std::tie(n_written, err) = |
mukesh agrawal | 93f78dc | 2016-10-13 16:07:40 -0700 | [diff] [blame] | 239 | os_->Write(dump_fd, output_string.data(), output_string.size()); |
mukesh agrawal | fd08064 | 2016-10-07 15:45:37 -0700 | [diff] [blame] | 240 | if (err == EINTR) { |
| 241 | // The next write will probably succeed. We dont't retry the current |
| 242 | // message, however, because we want to guarantee forward progress. |
| 243 | // |
| 244 | // TODO(b/32098735): Increment a counter, and attempt to output that |
| 245 | // counter after we've dumped all the log messages. |
| 246 | } else if (err) { |
| 247 | // Any error other than EINTR is considered unrecoverable. |
| 248 | LOG(ERROR) << "Terminating log dump, due to " << strerror(err); |
| 249 | return false; |
| 250 | } |
mukesh agrawal | fd08064 | 2016-10-07 15:45:37 -0700 | [diff] [blame] | 251 | } |
| 252 | |
| 253 | return true; |
| 254 | } |
| 255 | |
mukesh agrawal | 93f78dc | 2016-10-13 16:07:40 -0700 | [diff] [blame] | 256 | std::string CommandProcessor::FormatAsciiMessage(MemoryReader buffer_reader) { |
| 257 | constexpr char kShortHeaderError[] = "[truncated-header]"; |
| 258 | if (buffer_reader.size() < sizeof(protocol::AsciiMessage)) { |
mukesh agrawal | 82816d2 | 2016-10-27 14:18:29 -0700 | [diff] [blame] | 259 | // TODO(b/32098735): Increment stats counter. |
mukesh agrawal | 93f78dc | 2016-10-13 16:07:40 -0700 | [diff] [blame] | 260 | return kShortHeaderError; |
| 261 | } |
| 262 | |
| 263 | const auto& ascii_message_header = |
| 264 | buffer_reader.CopyOutOrDie<protocol::AsciiMessage>(); |
| 265 | const std::string& formatted_tag = |
| 266 | GetStringFromMemoryReader(&buffer_reader, ascii_message_header.tag_len); |
| 267 | const std::string& formatted_msg = |
| 268 | GetStringFromMemoryReader(&buffer_reader, ascii_message_header.data_len); |
| 269 | return formatted_tag + ' ' + formatted_msg; |
| 270 | } |
| 271 | |
mukesh agrawal | 6306897 | 2016-09-29 17:42:46 -0700 | [diff] [blame] | 272 | } // namespace wifilogd |
| 273 | } // namespace android |