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
fork_execute_incident_helper(const int id,Fpipe * p2cPipe,Fpipe * c2pPipe)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 // ================================================================================
write_section_header(int fd,int sectionId,size_t size)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
write_section_stats(IncidentMetadata::SectionStats * stats,const FdBuffer & buffer)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.
write_report_requests(const int id,const FdBuffer & buffer,ReportRequestSet * requests)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 // ================================================================================
Section(int i,int64_t timeoutMs,bool userdebugAndEngOnly,bool deviceSpecific)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
~Section()160 Section::~Section() {}
161
162 // ================================================================================
HeaderSection()163 HeaderSection::HeaderSection() : Section(FIELD_ID_INCIDENT_HEADER, 0) {}
164
~HeaderSection()165 HeaderSection::~HeaderSection() {}
166
Execute(ReportRequestSet * requests) const167 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 // ================================================================================
MetadataSection()187 MetadataSection::MetadataSection() : Section(FIELD_ID_INCIDENT_METADATA, 0) {}
188
~MetadataSection()189 MetadataSection::~MetadataSection() {}
190
Execute(ReportRequestSet * requests) const191 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 // ================================================================================
isSysfs(const char * filename)241 static inline bool isSysfs(const char* filename) { return strncmp(filename, "/sys/", 5) == 0; }
242
FileSection(int id,const char * filename,const bool deviceSpecific,const int64_t timeoutMs)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
~FileSection()250 FileSection::~FileSection() {}
251
Execute(ReportRequestSet * requests) const252 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 // ================================================================================
GZipSection(int id,const char * filename,...)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
~GZipSection()318 GZipSection::~GZipSection() { free(mFilenames); }
319
Execute(ReportRequestSet * requests) const320 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
WorkerThreadData(const WorkerThreadSection * sec)417 WorkerThreadData::WorkerThreadData(const WorkerThreadSection* sec)
418 : section(sec), workerDone(false), workerError(NO_ERROR) {}
419
~WorkerThreadData()420 WorkerThreadData::~WorkerThreadData() {}
421
422 // ================================================================================
WorkerThreadSection(int id,const int64_t timeoutMs,bool userdebugAndEngOnly)423 WorkerThreadSection::WorkerThreadSection(int id, const int64_t timeoutMs, bool userdebugAndEngOnly)
424 : Section(id, timeoutMs, userdebugAndEngOnly) {}
425
~WorkerThreadSection()426 WorkerThreadSection::~WorkerThreadSection() {}
427
worker_thread_func(void * cookie)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
Execute(ReportRequestSet * requests) const444 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 // ================================================================================
CommandSection(int id,const int64_t timeoutMs,const char * command,...)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
CommandSection(int id,const char * command,...)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
~CommandSection()565 CommandSection::~CommandSection() { free(mCommand); }
566
Execute(ReportRequestSet * requests) const567 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 // ================================================================================
DumpsysSection(int id,bool userdebugAndEngOnly,const char * service,...)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
~DumpsysSection()640 DumpsysSection::~DumpsysSection() {}
641
BlockingCall(int pipeWriteFd) const642 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
LogSection(int id,log_id_t logID)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
~LogSection()680 LogSection::~LogSection() {}
681
trimTail(char const * buf,size_t len)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
get4LE(uint8_t const * src)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
BlockingCall(int pipeWriteFd) const698 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
TombstoneSection(int id,const char * type,const int64_t timeoutMs)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
~TombstoneSection()828 TombstoneSection::~TombstoneSection() {}
829
BlockingCall(int pipeWriteFd) const830 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