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 #define DEBUG false 17 #include "Log.h" 18 19 #include "Section.h" 20 21 #include <dirent.h> 22 #include <errno.h> 23 24 #include <mutex> 25 #include <set> 26 27 #include <android-base/file.h> 28 #include <android-base/stringprintf.h> 29 #include <android/util/protobuf.h> 30 #include <binder/IServiceManager.h> 31 #include <debuggerd/client.h> 32 #include <dumputils/dump_utils.h> 33 #include <log/log_event_list.h> 34 #include <log/log_read.h> 35 #include <log/logprint.h> 36 #include <private/android_logger.h> 37 38 #include "FdBuffer.h" 39 #include "Privacy.h" 40 #include "PrivacyBuffer.h" 41 #include "frameworks/base/core/proto/android/os/backtrace.proto.h" 42 #include "frameworks/base/core/proto/android/os/data.proto.h" 43 #include "frameworks/base/core/proto/android/util/log.proto.h" 44 #include "incidentd_util.h" 45 46 namespace android { 47 namespace os { 48 namespace incidentd { 49 50 using namespace android::base; 51 using namespace android::util; 52 53 // special section ids 54 const int FIELD_ID_INCIDENT_HEADER = 1; 55 const int FIELD_ID_INCIDENT_METADATA = 2; 56 57 // incident section parameters 58 const char INCIDENT_HELPER[] = "/system/bin/incident_helper"; 59 const char* GZIP[] = {"/system/bin/gzip", NULL}; 60 61 static pid_t fork_execute_incident_helper(const int id, Fpipe* p2cPipe, Fpipe* c2pPipe) { 62 const char* ihArgs[]{INCIDENT_HELPER, "-s", String8::format("%d", id).string(), NULL}; 63 return fork_execute_cmd(const_cast<char**>(ihArgs), p2cPipe, c2pPipe); 64 } 65 66 // ================================================================================ 67 static status_t write_section_header(int fd, int sectionId, size_t size) { 68 uint8_t buf[20]; 69 uint8_t* p = write_length_delimited_tag_header(buf, sectionId, size); 70 return WriteFully(fd, buf, p - buf) ? NO_ERROR : -errno; 71 } 72 73 static void write_section_stats(IncidentMetadata::SectionStats* stats, const FdBuffer& buffer) { 74 stats->set_dump_size_bytes(buffer.data().size()); 75 stats->set_dump_duration_ms(buffer.durationMs()); 76 stats->set_timed_out(buffer.timedOut()); 77 stats->set_is_truncated(buffer.truncated()); 78 } 79 80 // Reads data from FdBuffer and writes it to the requests file descriptor. 81 static status_t write_report_requests(const int id, const FdBuffer& buffer, 82 ReportRequestSet* requests) { 83 status_t err = -EBADF; 84 EncodedBuffer::iterator data = buffer.data(); 85 PrivacyBuffer privacyBuffer(get_privacy_of_section(id), data); 86 int writeable = 0; 87 88 // The streaming ones, group requests by spec in order to save unnecessary strip operations 89 map<PrivacySpec, vector<sp<ReportRequest>>> requestsBySpec; 90 for (auto it = requests->begin(); it != requests->end(); it++) { 91 sp<ReportRequest> request = *it; 92 if (!request->ok() || !request->args.containsSection(id)) { 93 continue; // skip invalid request 94 } 95 PrivacySpec spec = PrivacySpec::new_spec(request->args.dest()); 96 requestsBySpec[spec].push_back(request); 97 } 98 99 for (auto mit = requestsBySpec.begin(); mit != requestsBySpec.end(); mit++) { 100 PrivacySpec spec = mit->first; 101 err = privacyBuffer.strip(spec); 102 if (err != NO_ERROR) return err; // it means the privacyBuffer data is corrupted. 103 if (privacyBuffer.size() == 0) continue; 104 105 for (auto it = mit->second.begin(); it != mit->second.end(); it++) { 106 sp<ReportRequest> request = *it; 107 err = write_section_header(request->fd, id, privacyBuffer.size()); 108 if (err != NO_ERROR) { 109 request->err = err; 110 continue; 111 } 112 err = privacyBuffer.flush(request->fd); 113 if (err != NO_ERROR) { 114 request->err = err; 115 continue; 116 } 117 writeable++; 118 VLOG("Section %d flushed %zu bytes to fd %d with spec %d", id, privacyBuffer.size(), 119 request->fd, spec.dest); 120 } 121 privacyBuffer.clear(); 122 } 123 124 // The dropbox file 125 if (requests->mainFd() >= 0) { 126 PrivacySpec spec = PrivacySpec::new_spec(requests->mainDest()); 127 err = privacyBuffer.strip(spec); 128 if (err != NO_ERROR) return err; // the buffer data is corrupted. 129 if (privacyBuffer.size() == 0) goto DONE; 130 131 err = write_section_header(requests->mainFd(), id, privacyBuffer.size()); 132 if (err != NO_ERROR) { 133 requests->setMainFd(-1); 134 goto DONE; 135 } 136 err = privacyBuffer.flush(requests->mainFd()); 137 if (err != NO_ERROR) { 138 requests->setMainFd(-1); 139 goto DONE; 140 } 141 writeable++; 142 VLOG("Section %d flushed %zu bytes to dropbox %d with spec %d", id, privacyBuffer.size(), 143 requests->mainFd(), spec.dest); 144 // Reports bytes of the section uploaded via dropbox after filtering. 145 requests->sectionStats(id)->set_report_size_bytes(privacyBuffer.size()); 146 } 147 148 DONE: 149 // only returns error if there is no fd to write to. 150 return writeable > 0 ? NO_ERROR : err; 151 } 152 153 // ================================================================================ 154 Section::Section(int i, int64_t timeoutMs, bool userdebugAndEngOnly, bool deviceSpecific) 155 : id(i), 156 timeoutMs(timeoutMs), 157 userdebugAndEngOnly(userdebugAndEngOnly), 158 deviceSpecific(deviceSpecific) {} 159 160 Section::~Section() {} 161 162 // ================================================================================ 163 HeaderSection::HeaderSection() : Section(FIELD_ID_INCIDENT_HEADER, 0) {} 164 165 HeaderSection::~HeaderSection() {} 166 167 status_t HeaderSection::Execute(ReportRequestSet* requests) const { 168 for (ReportRequestSet::iterator it = requests->begin(); it != requests->end(); it++) { 169 const sp<ReportRequest> request = *it; 170 const vector<vector<uint8_t>>& headers = request->args.headers(); 171 172 for (vector<vector<uint8_t>>::const_iterator buf = headers.begin(); buf != headers.end(); 173 buf++) { 174 if (buf->empty()) continue; 175 176 // So the idea is only requests with negative fd are written to dropbox file. 177 int fd = request->fd >= 0 ? request->fd : requests->mainFd(); 178 write_section_header(fd, id, buf->size()); 179 WriteFully(fd, (uint8_t const*)buf->data(), buf->size()); 180 // If there was an error now, there will be an error later and we will remove 181 // it from the list then. 182 } 183 } 184 return NO_ERROR; 185 } 186 // ================================================================================ 187 MetadataSection::MetadataSection() : Section(FIELD_ID_INCIDENT_METADATA, 0) {} 188 189 MetadataSection::~MetadataSection() {} 190 191 status_t MetadataSection::Execute(ReportRequestSet* requests) const { 192 ProtoOutputStream proto; 193 IncidentMetadata metadata = requests->metadata(); 194 proto.write(FIELD_TYPE_ENUM | IncidentMetadata::kDestFieldNumber, metadata.dest()); 195 proto.write(FIELD_TYPE_INT32 | IncidentMetadata::kRequestSizeFieldNumber, 196 metadata.request_size()); 197 proto.write(FIELD_TYPE_BOOL | IncidentMetadata::kUseDropboxFieldNumber, metadata.use_dropbox()); 198 for (auto iter = requests->allSectionStats().begin(); iter != requests->allSectionStats().end(); 199 iter++) { 200 IncidentMetadata::SectionStats stats = iter->second; 201 uint64_t token = proto.start(FIELD_TYPE_MESSAGE | IncidentMetadata::kSectionsFieldNumber); 202 proto.write(FIELD_TYPE_INT32 | IncidentMetadata::SectionStats::kIdFieldNumber, stats.id()); 203 proto.write(FIELD_TYPE_BOOL | IncidentMetadata::SectionStats::kSuccessFieldNumber, 204 stats.success()); 205 proto.write(FIELD_TYPE_INT32 | IncidentMetadata::SectionStats::kReportSizeBytesFieldNumber, 206 stats.report_size_bytes()); 207 proto.write(FIELD_TYPE_INT64 | IncidentMetadata::SectionStats::kExecDurationMsFieldNumber, 208 stats.exec_duration_ms()); 209 proto.write(FIELD_TYPE_INT32 | IncidentMetadata::SectionStats::kDumpSizeBytesFieldNumber, 210 stats.dump_size_bytes()); 211 proto.write(FIELD_TYPE_INT64 | IncidentMetadata::SectionStats::kDumpDurationMsFieldNumber, 212 stats.dump_duration_ms()); 213 proto.write(FIELD_TYPE_BOOL | IncidentMetadata::SectionStats::kTimedOutFieldNumber, 214 stats.timed_out()); 215 proto.write(FIELD_TYPE_BOOL | IncidentMetadata::SectionStats::kIsTruncatedFieldNumber, 216 stats.is_truncated()); 217 proto.end(token); 218 } 219 220 for (ReportRequestSet::iterator it = requests->begin(); it != requests->end(); it++) { 221 const sp<ReportRequest> request = *it; 222 if (request->fd < 0 || request->err != NO_ERROR) { 223 continue; 224 } 225 write_section_header(request->fd, id, proto.size()); 226 if (!proto.flush(request->fd)) { 227 ALOGW("Failed to write metadata to fd %d", request->fd); 228 // we don't fail if we can't write to a single request's fd. 229 } 230 } 231 if (requests->mainFd() >= 0) { 232 write_section_header(requests->mainFd(), id, proto.size()); 233 if (!proto.flush(requests->mainFd())) { 234 ALOGW("Failed to write metadata to dropbox fd %d", requests->mainFd()); 235 return -1; 236 } 237 } 238 return NO_ERROR; 239 } 240 // ================================================================================ 241 static inline bool isSysfs(const char* filename) { return strncmp(filename, "/sys/", 5) == 0; } 242 243 FileSection::FileSection(int id, const char* filename, const bool deviceSpecific, 244 const int64_t timeoutMs) 245 : Section(id, timeoutMs, false, deviceSpecific), mFilename(filename) { 246 name = filename; 247 mIsSysfs = isSysfs(filename); 248 } 249 250 FileSection::~FileSection() {} 251 252 status_t FileSection::Execute(ReportRequestSet* requests) const { 253 // read from mFilename first, make sure the file is available 254 // add O_CLOEXEC to make sure it is closed when exec incident helper 255 unique_fd fd(open(mFilename, O_RDONLY | O_CLOEXEC)); 256 if (fd.get() == -1) { 257 ALOGW("FileSection '%s' failed to open file", this->name.string()); 258 return this->deviceSpecific ? NO_ERROR : -errno; 259 } 260 261 FdBuffer buffer; 262 Fpipe p2cPipe; 263 Fpipe c2pPipe; 264 // initiate pipes to pass data to/from incident_helper 265 if (!p2cPipe.init() || !c2pPipe.init()) { 266 ALOGW("FileSection '%s' failed to setup pipes", this->name.string()); 267 return -errno; 268 } 269 270 pid_t pid = fork_execute_incident_helper(this->id, &p2cPipe, &c2pPipe); 271 if (pid == -1) { 272 ALOGW("FileSection '%s' failed to fork", this->name.string()); 273 return -errno; 274 } 275 276 // parent process 277 status_t readStatus = buffer.readProcessedDataInStream(fd.get(), std::move(p2cPipe.writeFd()), 278 std::move(c2pPipe.readFd()), 279 this->timeoutMs, mIsSysfs); 280 write_section_stats(requests->sectionStats(this->id), buffer); 281 if (readStatus != NO_ERROR || buffer.timedOut()) { 282 ALOGW("FileSection '%s' failed to read data from incident helper: %s, timedout: %s", 283 this->name.string(), strerror(-readStatus), buffer.timedOut() ? "true" : "false"); 284 kill_child(pid); 285 return readStatus; 286 } 287 288 status_t ihStatus = wait_child(pid); 289 if (ihStatus != NO_ERROR) { 290 ALOGW("FileSection '%s' abnormal child process: %s", this->name.string(), 291 strerror(-ihStatus)); 292 return ihStatus; 293 } 294 295 VLOG("FileSection '%s' wrote %zd bytes in %d ms", this->name.string(), buffer.size(), 296 (int)buffer.durationMs()); 297 status_t err = write_report_requests(this->id, buffer, requests); 298 if (err != NO_ERROR) { 299 ALOGW("FileSection '%s' failed writing: %s", this->name.string(), strerror(-err)); 300 return err; 301 } 302 303 return NO_ERROR; 304 } 305 // ================================================================================ 306 GZipSection::GZipSection(int id, const char* filename, ...) : Section(id) { 307 va_list args; 308 va_start(args, filename); 309 mFilenames = varargs(filename, args); 310 va_end(args); 311 name = "gzip"; 312 for (int i = 0; mFilenames[i] != NULL; i++) { 313 name += " "; 314 name += mFilenames[i]; 315 } 316 } 317 318 GZipSection::~GZipSection() { free(mFilenames); } 319 320 status_t GZipSection::Execute(ReportRequestSet* requests) const { 321 // Reads the files in order, use the first available one. 322 int index = 0; 323 unique_fd fd; 324 while (mFilenames[index] != NULL) { 325 fd.reset(open(mFilenames[index], O_RDONLY | O_CLOEXEC)); 326 if (fd.get() != -1) { 327 break; 328 } 329 ALOGW("GZipSection failed to open file %s", mFilenames[index]); 330 index++; // look at the next file. 331 } 332 VLOG("GZipSection is using file %s, fd=%d", mFilenames[index], fd.get()); 333 if (fd.get() == -1) { 334 ALOGW("GZipSection %s can't open all the files", this->name.string()); 335 return NO_ERROR; // e.g. LAST_KMSG will reach here in user build. 336 } 337 FdBuffer buffer; 338 Fpipe p2cPipe; 339 Fpipe c2pPipe; 340 // initiate pipes to pass data to/from gzip 341 if (!p2cPipe.init() || !c2pPipe.init()) { 342 ALOGW("GZipSection '%s' failed to setup pipes", this->name.string()); 343 return -errno; 344 } 345 346 pid_t pid = fork_execute_cmd((char* const*)GZIP, &p2cPipe, &c2pPipe); 347 if (pid == -1) { 348 ALOGW("GZipSection '%s' failed to fork", this->name.string()); 349 return -errno; 350 } 351 // parent process 352 353 // construct Fdbuffer to output GZippedfileProto, the reason to do this instead of using 354 // ProtoOutputStream is to avoid allocation of another buffer inside ProtoOutputStream. 355 EncodedBuffer* internalBuffer = buffer.getInternalBuffer(); 356 internalBuffer->writeHeader((uint32_t)GZippedFileProto::FILENAME, WIRE_TYPE_LENGTH_DELIMITED); 357 size_t fileLen = strlen(mFilenames[index]); 358 internalBuffer->writeRawVarint32(fileLen); 359 for (size_t i = 0; i < fileLen; i++) { 360 internalBuffer->writeRawByte(mFilenames[index][i]); 361 } 362 internalBuffer->writeHeader((uint32_t)GZippedFileProto::GZIPPED_DATA, 363 WIRE_TYPE_LENGTH_DELIMITED); 364 size_t editPos = internalBuffer->wp()->pos(); 365 internalBuffer->wp()->move(8); // reserve 8 bytes for the varint of the data size. 366 size_t dataBeginAt = internalBuffer->wp()->pos(); 367 VLOG("GZipSection '%s' editPos=%zd, dataBeginAt=%zd", this->name.string(), editPos, 368 dataBeginAt); 369 370 status_t readStatus = buffer.readProcessedDataInStream( 371 fd.get(), std::move(p2cPipe.writeFd()), std::move(c2pPipe.readFd()), this->timeoutMs, 372 isSysfs(mFilenames[index])); 373 write_section_stats(requests->sectionStats(this->id), buffer); 374 if (readStatus != NO_ERROR || buffer.timedOut()) { 375 ALOGW("GZipSection '%s' failed to read data from gzip: %s, timedout: %s", 376 this->name.string(), strerror(-readStatus), buffer.timedOut() ? "true" : "false"); 377 kill_child(pid); 378 return readStatus; 379 } 380 381 status_t gzipStatus = wait_child(pid); 382 if (gzipStatus != NO_ERROR) { 383 ALOGW("GZipSection '%s' abnormal child process: %s", this->name.string(), 384 strerror(-gzipStatus)); 385 return gzipStatus; 386 } 387 // Revisit the actual size from gzip result and edit the internal buffer accordingly. 388 size_t dataSize = buffer.size() - dataBeginAt; 389 internalBuffer->wp()->rewind()->move(editPos); 390 internalBuffer->writeRawVarint32(dataSize); 391 internalBuffer->copy(dataBeginAt, dataSize); 392 VLOG("GZipSection '%s' wrote %zd bytes in %d ms, dataSize=%zd", this->name.string(), 393 buffer.size(), (int)buffer.durationMs(), dataSize); 394 status_t err = write_report_requests(this->id, buffer, requests); 395 if (err != NO_ERROR) { 396 ALOGW("GZipSection '%s' failed writing: %s", this->name.string(), strerror(-err)); 397 return err; 398 } 399 400 return NO_ERROR; 401 } 402 403 // ================================================================================ 404 struct WorkerThreadData : public virtual RefBase { 405 const WorkerThreadSection* section; 406 Fpipe pipe; 407 408 // Lock protects these fields 409 mutex lock; 410 bool workerDone; 411 status_t workerError; 412 413 WorkerThreadData(const WorkerThreadSection* section); 414 virtual ~WorkerThreadData(); 415 }; 416 417 WorkerThreadData::WorkerThreadData(const WorkerThreadSection* sec) 418 : section(sec), workerDone(false), workerError(NO_ERROR) {} 419 420 WorkerThreadData::~WorkerThreadData() {} 421 422 // ================================================================================ 423 WorkerThreadSection::WorkerThreadSection(int id, const int64_t timeoutMs, bool userdebugAndEngOnly) 424 : Section(id, timeoutMs, userdebugAndEngOnly) {} 425 426 WorkerThreadSection::~WorkerThreadSection() {} 427 428 static void* worker_thread_func(void* cookie) { 429 WorkerThreadData* data = (WorkerThreadData*)cookie; 430 status_t err = data->section->BlockingCall(data->pipe.writeFd().get()); 431 432 { 433 unique_lock<mutex> lock(data->lock); 434 data->workerDone = true; 435 data->workerError = err; 436 } 437 438 data->pipe.writeFd().reset(); 439 data->decStrong(data->section); 440 // data might be gone now. don't use it after this point in this thread. 441 return NULL; 442 } 443 444 status_t WorkerThreadSection::Execute(ReportRequestSet* requests) const { 445 status_t err = NO_ERROR; 446 pthread_t thread; 447 pthread_attr_t attr; 448 bool timedOut = false; 449 FdBuffer buffer; 450 451 // Data shared between this thread and the worker thread. 452 sp<WorkerThreadData> data = new WorkerThreadData(this); 453 454 // Create the pipe 455 if (!data->pipe.init()) { 456 return -errno; 457 } 458 459 // The worker thread needs a reference and we can't let the count go to zero 460 // if that thread is slow to start. 461 data->incStrong(this); 462 463 // Create the thread 464 err = pthread_attr_init(&attr); 465 if (err != 0) { 466 return -err; 467 } 468 // TODO: Do we need to tweak thread priority? 469 err = pthread_attr_setdetachstate(&attr, PTHREAD_CREATE_DETACHED); 470 if (err != 0) { 471 pthread_attr_destroy(&attr); 472 return -err; 473 } 474 err = pthread_create(&thread, &attr, worker_thread_func, (void*)data.get()); 475 if (err != 0) { 476 pthread_attr_destroy(&attr); 477 return -err; 478 } 479 pthread_attr_destroy(&attr); 480 481 // Loop reading until either the timeout or the worker side is done (i.e. eof). 482 err = buffer.read(data->pipe.readFd().get(), this->timeoutMs); 483 if (err != NO_ERROR) { 484 // TODO: Log this error into the incident report. 485 ALOGW("WorkerThreadSection '%s' reader failed with error '%s'", this->name.string(), 486 strerror(-err)); 487 } 488 489 // Done with the read fd. The worker thread closes the write one so 490 // we never race and get here first. 491 data->pipe.readFd().reset(); 492 493 // If the worker side is finished, then return its error (which may overwrite 494 // our possible error -- but it's more interesting anyway). If not, then we timed out. 495 { 496 unique_lock<mutex> lock(data->lock); 497 if (!data->workerDone) { 498 // We timed out 499 timedOut = true; 500 } else { 501 if (data->workerError != NO_ERROR) { 502 err = data->workerError; 503 // TODO: Log this error into the incident report. 504 ALOGW("WorkerThreadSection '%s' worker failed with error '%s'", this->name.string(), 505 strerror(-err)); 506 } 507 } 508 } 509 write_section_stats(requests->sectionStats(this->id), buffer); 510 if (timedOut || buffer.timedOut()) { 511 ALOGW("WorkerThreadSection '%s' timed out", this->name.string()); 512 return NO_ERROR; 513 } 514 515 if (buffer.truncated()) { 516 // TODO: Log this into the incident report. 517 } 518 519 // TODO: There was an error with the command or buffering. Report that. For now 520 // just exit with a log messasge. 521 if (err != NO_ERROR) { 522 ALOGW("WorkerThreadSection '%s' failed with error '%s'", this->name.string(), 523 strerror(-err)); 524 return NO_ERROR; 525 } 526 527 // Write the data that was collected 528 VLOG("WorkerThreadSection '%s' wrote %zd bytes in %d ms", name.string(), buffer.size(), 529 (int)buffer.durationMs()); 530 err = write_report_requests(this->id, buffer, requests); 531 if (err != NO_ERROR) { 532 ALOGW("WorkerThreadSection '%s' failed writing: '%s'", this->name.string(), strerror(-err)); 533 return err; 534 } 535 536 return NO_ERROR; 537 } 538 539 // ================================================================================ 540 CommandSection::CommandSection(int id, const int64_t timeoutMs, const char* command, ...) 541 : Section(id, timeoutMs) { 542 va_list args; 543 va_start(args, command); 544 mCommand = varargs(command, args); 545 va_end(args); 546 name = "cmd"; 547 for (int i = 0; mCommand[i] != NULL; i++) { 548 name += " "; 549 name += mCommand[i]; 550 } 551 } 552 553 CommandSection::CommandSection(int id, const char* command, ...) : Section(id) { 554 va_list args; 555 va_start(args, command); 556 mCommand = varargs(command, args); 557 va_end(args); 558 name = "cmd"; 559 for (int i = 0; mCommand[i] != NULL; i++) { 560 name += " "; 561 name += mCommand[i]; 562 } 563 } 564 565 CommandSection::~CommandSection() { free(mCommand); } 566 567 status_t CommandSection::Execute(ReportRequestSet* requests) const { 568 FdBuffer buffer; 569 Fpipe cmdPipe; 570 Fpipe ihPipe; 571 572 if (!cmdPipe.init() || !ihPipe.init()) { 573 ALOGW("CommandSection '%s' failed to setup pipes", this->name.string()); 574 return -errno; 575 } 576 577 pid_t cmdPid = fork_execute_cmd((char* const*)mCommand, NULL, &cmdPipe); 578 if (cmdPid == -1) { 579 ALOGW("CommandSection '%s' failed to fork", this->name.string()); 580 return -errno; 581 } 582 pid_t ihPid = fork_execute_incident_helper(this->id, &cmdPipe, &ihPipe); 583 if (ihPid == -1) { 584 ALOGW("CommandSection '%s' failed to fork", this->name.string()); 585 return -errno; 586 } 587 588 cmdPipe.writeFd().reset(); 589 status_t readStatus = buffer.read(ihPipe.readFd().get(), this->timeoutMs); 590 write_section_stats(requests->sectionStats(this->id), buffer); 591 if (readStatus != NO_ERROR || buffer.timedOut()) { 592 ALOGW("CommandSection '%s' failed to read data from incident helper: %s, timedout: %s", 593 this->name.string(), strerror(-readStatus), buffer.timedOut() ? "true" : "false"); 594 kill_child(cmdPid); 595 kill_child(ihPid); 596 return readStatus; 597 } 598 599 // Waiting for command here has one trade-off: the failed status of command won't be detected 600 // until buffer timeout, but it has advatage on starting the data stream earlier. 601 status_t cmdStatus = wait_child(cmdPid); 602 status_t ihStatus = wait_child(ihPid); 603 if (cmdStatus != NO_ERROR || ihStatus != NO_ERROR) { 604 ALOGW("CommandSection '%s' abnormal child processes, return status: command: %s, incident " 605 "helper: %s", 606 this->name.string(), strerror(-cmdStatus), strerror(-ihStatus)); 607 return cmdStatus != NO_ERROR ? cmdStatus : ihStatus; 608 } 609 610 VLOG("CommandSection '%s' wrote %zd bytes in %d ms", this->name.string(), buffer.size(), 611 (int)buffer.durationMs()); 612 status_t err = write_report_requests(this->id, buffer, requests); 613 if (err != NO_ERROR) { 614 ALOGW("CommandSection '%s' failed writing: %s", this->name.string(), strerror(-err)); 615 return err; 616 } 617 return NO_ERROR; 618 } 619 620 // ================================================================================ 621 DumpsysSection::DumpsysSection(int id, bool userdebugAndEngOnly, const char* service, ...) 622 : WorkerThreadSection(id, REMOTE_CALL_TIMEOUT_MS, userdebugAndEngOnly), mService(service) { 623 name = "dumpsys "; 624 name += service; 625 626 va_list args; 627 va_start(args, service); 628 while (true) { 629 const char* arg = va_arg(args, const char*); 630 if (arg == NULL) { 631 break; 632 } 633 mArgs.add(String16(arg)); 634 name += " "; 635 name += arg; 636 } 637 va_end(args); 638 } 639 640 DumpsysSection::~DumpsysSection() {} 641 642 status_t DumpsysSection::BlockingCall(int pipeWriteFd) const { 643 // checkService won't wait for the service to show up like getService will. 644 sp<IBinder> service = defaultServiceManager()->checkService(mService); 645 646 if (service == NULL) { 647 // Returning an error interrupts the entire incident report, so just 648 // log the failure. 649 // TODO: have a meta record inside the report that would log this 650 // failure inside the report, because the fact that we can't find 651 // the service is good data in and of itself. This is running in 652 // another thread so lock that carefully... 653 ALOGW("DumpsysSection: Can't lookup service: %s", String8(mService).string()); 654 return NO_ERROR; 655 } 656 657 service->dump(pipeWriteFd, mArgs); 658 659 return NO_ERROR; 660 } 661 662 // ================================================================================ 663 // initialization only once in Section.cpp. 664 map<log_id_t, log_time> LogSection::gLastLogsRetrieved; 665 666 LogSection::LogSection(int id, log_id_t logID) : WorkerThreadSection(id), mLogID(logID) { 667 name += "logcat "; 668 name += android_log_id_to_name(logID); 669 switch (logID) { 670 case LOG_ID_EVENTS: 671 case LOG_ID_STATS: 672 case LOG_ID_SECURITY: 673 mBinary = true; 674 break; 675 default: 676 mBinary = false; 677 } 678 } 679 680 LogSection::~LogSection() {} 681 682 static size_t trimTail(char const* buf, size_t len) { 683 while (len > 0) { 684 char c = buf[len - 1]; 685 if (c == '\0' || c == ' ' || c == '\n' || c == '\r' || c == ':') { 686 len--; 687 } else { 688 break; 689 } 690 } 691 return len; 692 } 693 694 static inline int32_t get4LE(uint8_t const* src) { 695 return src[0] | (src[1] << 8) | (src[2] << 16) | (src[3] << 24); 696 } 697 698 status_t LogSection::BlockingCall(int pipeWriteFd) const { 699 // Open log buffer and getting logs since last retrieved time if any. 700 unique_ptr<logger_list, void (*)(logger_list*)> loggers( 701 gLastLogsRetrieved.find(mLogID) == gLastLogsRetrieved.end() 702 ? android_logger_list_alloc(ANDROID_LOG_RDONLY | ANDROID_LOG_NONBLOCK, 0, 0) 703 : android_logger_list_alloc_time(ANDROID_LOG_RDONLY | ANDROID_LOG_NONBLOCK, 704 gLastLogsRetrieved[mLogID], 0), 705 android_logger_list_free); 706 707 if (android_logger_open(loggers.get(), mLogID) == NULL) { 708 ALOGE("LogSection %s: Can't get logger.", this->name.string()); 709 return -1; 710 } 711 712 log_msg msg; 713 log_time lastTimestamp(0); 714 715 ProtoOutputStream proto; 716 while (true) { // keeps reading until logd buffer is fully read. 717 status_t err = android_logger_list_read(loggers.get(), &msg); 718 // err = 0 - no content, unexpected connection drop or EOF. 719 // err = +ive number - size of retrieved data from logger 720 // err = -ive number, OS supplied error _except_ for -EAGAIN 721 // err = -EAGAIN, graceful indication for ANDRODI_LOG_NONBLOCK that this is the end of data. 722 if (err <= 0) { 723 if (err != -EAGAIN) { 724 ALOGW("LogSection %s: fails to read a log_msg.\n", this->name.string()); 725 } 726 // dump previous logs and don't consider this error a failure. 727 break; 728 } 729 if (mBinary) { 730 // remove the first uint32 which is tag's index in event log tags 731 android_log_context context = create_android_log_parser(msg.msg() + sizeof(uint32_t), 732 msg.len() - sizeof(uint32_t)); 733 ; 734 android_log_list_element elem; 735 736 lastTimestamp.tv_sec = msg.entry_v1.sec; 737 lastTimestamp.tv_nsec = msg.entry_v1.nsec; 738 739 // format a BinaryLogEntry 740 uint64_t token = proto.start(LogProto::BINARY_LOGS); 741 proto.write(BinaryLogEntry::SEC, msg.entry_v1.sec); 742 proto.write(BinaryLogEntry::NANOSEC, msg.entry_v1.nsec); 743 proto.write(BinaryLogEntry::UID, (int)msg.entry_v4.uid); 744 proto.write(BinaryLogEntry::PID, msg.entry_v1.pid); 745 proto.write(BinaryLogEntry::TID, msg.entry_v1.tid); 746 proto.write(BinaryLogEntry::TAG_INDEX, 747 get4LE(reinterpret_cast<uint8_t const*>(msg.msg()))); 748 do { 749 elem = android_log_read_next(context); 750 uint64_t elemToken = proto.start(BinaryLogEntry::ELEMS); 751 switch (elem.type) { 752 case EVENT_TYPE_INT: 753 proto.write(BinaryLogEntry::Elem::TYPE, 754 BinaryLogEntry::Elem::EVENT_TYPE_INT); 755 proto.write(BinaryLogEntry::Elem::VAL_INT32, (int)elem.data.int32); 756 break; 757 case EVENT_TYPE_LONG: 758 proto.write(BinaryLogEntry::Elem::TYPE, 759 BinaryLogEntry::Elem::EVENT_TYPE_LONG); 760 proto.write(BinaryLogEntry::Elem::VAL_INT64, (long long)elem.data.int64); 761 break; 762 case EVENT_TYPE_STRING: 763 proto.write(BinaryLogEntry::Elem::TYPE, 764 BinaryLogEntry::Elem::EVENT_TYPE_STRING); 765 proto.write(BinaryLogEntry::Elem::VAL_STRING, elem.data.string, elem.len); 766 break; 767 case EVENT_TYPE_FLOAT: 768 proto.write(BinaryLogEntry::Elem::TYPE, 769 BinaryLogEntry::Elem::EVENT_TYPE_FLOAT); 770 proto.write(BinaryLogEntry::Elem::VAL_FLOAT, elem.data.float32); 771 break; 772 case EVENT_TYPE_LIST: 773 proto.write(BinaryLogEntry::Elem::TYPE, 774 BinaryLogEntry::Elem::EVENT_TYPE_LIST); 775 break; 776 case EVENT_TYPE_LIST_STOP: 777 proto.write(BinaryLogEntry::Elem::TYPE, 778 BinaryLogEntry::Elem::EVENT_TYPE_LIST_STOP); 779 break; 780 case EVENT_TYPE_UNKNOWN: 781 proto.write(BinaryLogEntry::Elem::TYPE, 782 BinaryLogEntry::Elem::EVENT_TYPE_UNKNOWN); 783 break; 784 } 785 proto.end(elemToken); 786 } while ((elem.type != EVENT_TYPE_UNKNOWN) && !elem.complete); 787 proto.end(token); 788 if (context) { 789 android_log_destroy(&context); 790 } 791 } else { 792 AndroidLogEntry entry; 793 err = android_log_processLogBuffer(&msg.entry_v1, &entry); 794 if (err != NO_ERROR) { 795 ALOGW("LogSection %s: fails to process to an entry.\n", this->name.string()); 796 break; 797 } 798 lastTimestamp.tv_sec = entry.tv_sec; 799 lastTimestamp.tv_nsec = entry.tv_nsec; 800 801 // format a TextLogEntry 802 uint64_t token = proto.start(LogProto::TEXT_LOGS); 803 proto.write(TextLogEntry::SEC, (long long)entry.tv_sec); 804 proto.write(TextLogEntry::NANOSEC, (long long)entry.tv_nsec); 805 proto.write(TextLogEntry::PRIORITY, (int)entry.priority); 806 proto.write(TextLogEntry::UID, entry.uid); 807 proto.write(TextLogEntry::PID, entry.pid); 808 proto.write(TextLogEntry::TID, entry.tid); 809 proto.write(TextLogEntry::TAG, entry.tag, trimTail(entry.tag, entry.tagLen)); 810 proto.write(TextLogEntry::LOG, entry.message, 811 trimTail(entry.message, entry.messageLen)); 812 proto.end(token); 813 } 814 } 815 gLastLogsRetrieved[mLogID] = lastTimestamp; 816 proto.flush(pipeWriteFd); 817 return NO_ERROR; 818 } 819 820 // ================================================================================ 821 822 TombstoneSection::TombstoneSection(int id, const char* type, const int64_t timeoutMs) 823 : WorkerThreadSection(id, timeoutMs), mType(type) { 824 name += "tombstone "; 825 name += type; 826 } 827 828 TombstoneSection::~TombstoneSection() {} 829 830 status_t TombstoneSection::BlockingCall(int pipeWriteFd) const { 831 std::unique_ptr<DIR, decltype(&closedir)> proc(opendir("/proc"), closedir); 832 if (proc.get() == nullptr) { 833 ALOGE("opendir /proc failed: %s\n", strerror(errno)); 834 return -errno; 835 } 836 837 const std::set<int> hal_pids = get_interesting_hal_pids(); 838 839 ProtoOutputStream proto; 840 struct dirent* d; 841 status_t err = NO_ERROR; 842 while ((d = readdir(proc.get()))) { 843 int pid = atoi(d->d_name); 844 if (pid <= 0) { 845 continue; 846 } 847 848 const std::string link_name = android::base::StringPrintf("/proc/%d/exe", pid); 849 std::string exe; 850 if (!android::base::Readlink(link_name, &exe)) { 851 ALOGE("Can't read '%s': %s\n", link_name.c_str(), strerror(errno)); 852 continue; 853 } 854 855 bool is_java_process; 856 if (exe == "/system/bin/app_process32" || exe == "/system/bin/app_process64") { 857 if (mType != "java") continue; 858 // Don't bother dumping backtraces for the zygote. 859 if (IsZygote(pid)) { 860 VLOG("Skipping Zygote"); 861 continue; 862 } 863 864 is_java_process = true; 865 } else if (should_dump_native_traces(exe.c_str())) { 866 if (mType != "native") continue; 867 is_java_process = false; 868 } else if (hal_pids.find(pid) != hal_pids.end()) { 869 if (mType != "hal") continue; 870 is_java_process = false; 871 } else { 872 // Probably a native process we don't care about, continue. 873 VLOG("Skipping %d", pid); 874 continue; 875 } 876 877 Fpipe dumpPipe; 878 if (!dumpPipe.init()) { 879 ALOGW("TombstoneSection '%s' failed to setup dump pipe", this->name.string()); 880 err = -errno; 881 break; 882 } 883 884 const uint64_t start = Nanotime(); 885 pid_t child = fork(); 886 if (child < 0) { 887 ALOGE("Failed to fork child process"); 888 break; 889 } else if (child == 0) { 890 // This is the child process. 891 dumpPipe.readFd().reset(); 892 const int ret = dump_backtrace_to_file_timeout( 893 pid, is_java_process ? kDebuggerdJavaBacktrace : kDebuggerdNativeBacktrace, 894 is_java_process ? 5 : 20, dumpPipe.writeFd().get()); 895 if (ret == -1) { 896 if (errno == 0) { 897 ALOGW("Dumping failed for pid '%d', likely due to a timeout\n", pid); 898 } else { 899 ALOGE("Dumping failed for pid '%d': %s\n", pid, strerror(errno)); 900 } 901 } 902 dumpPipe.writeFd().reset(); 903 _exit(EXIT_SUCCESS); 904 } 905 dumpPipe.writeFd().reset(); 906 // Parent process. 907 // Read from the pipe concurrently to avoid blocking the child. 908 FdBuffer buffer; 909 err = buffer.readFully(dumpPipe.readFd().get()); 910 // Wait on the child to avoid it becoming a zombie process. 911 status_t cStatus = wait_child(child); 912 if (err != NO_ERROR) { 913 ALOGW("TombstoneSection '%s' failed to read stack dump: %d", this->name.string(), err); 914 dumpPipe.readFd().reset(); 915 break; 916 } 917 if (cStatus != NO_ERROR) { 918 ALOGE("TombstoneSection '%s' child had an issue: %s\n", this->name.string(), strerror(-cStatus)); 919 } 920 921 auto dump = std::make_unique<char[]>(buffer.size()); 922 auto iterator = buffer.data(); 923 int i = 0; 924 while (iterator.hasNext()) { 925 dump[i] = iterator.next(); 926 i++; 927 } 928 uint64_t token = proto.start(android::os::BackTraceProto::TRACES); 929 proto.write(android::os::BackTraceProto::Stack::PID, pid); 930 proto.write(android::os::BackTraceProto::Stack::DUMP, dump.get(), i); 931 proto.write(android::os::BackTraceProto::Stack::DUMP_DURATION_NS, 932 static_cast<long long>(Nanotime() - start)); 933 proto.end(token); 934 dumpPipe.readFd().reset(); 935 } 936 937 proto.flush(pipeWriteFd); 938 return err; 939 } 940 941 } // namespace incidentd 942 } // namespace os 943 } // namespace android 944
