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
46namespace android {
47namespace os {
48namespace incidentd {
49
50using namespace android::base;
51using namespace android::util;
52
53// special section ids
54const int FIELD_ID_INCIDENT_HEADER = 1;
55const int FIELD_ID_INCIDENT_METADATA = 2;
56
57// incident section parameters
58const char INCIDENT_HELPER[] = "/system/bin/incident_helper";
59const char* GZIP[] = {"/system/bin/gzip", NULL};
60
61static 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// ================================================================================
67static 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
73static 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.
81static 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
148DONE:
149    // only returns error if there is no fd to write to.
150    return writeable > 0 ? NO_ERROR : err;
151}
152
153// ================================================================================
154Section::Section(int i, int64_t timeoutMs, bool userdebugAndEngOnly, bool deviceSpecific)
155    : id(i),
156      timeoutMs(timeoutMs),
157      userdebugAndEngOnly(userdebugAndEngOnly),
158      deviceSpecific(deviceSpecific) {}
159
160Section::~Section() {}
161
162// ================================================================================
163HeaderSection::HeaderSection() : Section(FIELD_ID_INCIDENT_HEADER, 0) {}
164
165HeaderSection::~HeaderSection() {}
166
167status_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// ================================================================================
187MetadataSection::MetadataSection() : Section(FIELD_ID_INCIDENT_METADATA, 0) {}
188
189MetadataSection::~MetadataSection() {}
190
191status_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// ================================================================================
241static inline bool isSysfs(const char* filename) { return strncmp(filename, "/sys/", 5) == 0; }
242
243FileSection::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
250FileSection::~FileSection() {}
251
252status_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// ================================================================================
306GZipSection::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
318GZipSection::~GZipSection() { free(mFilenames); }
319
320status_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// ================================================================================
404struct 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
417WorkerThreadData::WorkerThreadData(const WorkerThreadSection* sec)
418    : section(sec), workerDone(false), workerError(NO_ERROR) {}
419
420WorkerThreadData::~WorkerThreadData() {}
421
422// ================================================================================
423WorkerThreadSection::WorkerThreadSection(int id, const int64_t timeoutMs, bool userdebugAndEngOnly)
424    : Section(id, timeoutMs, userdebugAndEngOnly) {}
425
426WorkerThreadSection::~WorkerThreadSection() {}
427
428static 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
444status_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// ================================================================================
540CommandSection::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
553CommandSection::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
565CommandSection::~CommandSection() { free(mCommand); }
566
567status_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// ================================================================================
621DumpsysSection::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
640DumpsysSection::~DumpsysSection() {}
641
642status_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.
664map<log_id_t, log_time> LogSection::gLastLogsRetrieved;
665
666LogSection::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
680LogSection::~LogSection() {}
681
682static 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
694static inline int32_t get4LE(uint8_t const* src) {
695    return src[0] | (src[1] << 8) | (src[2] << 16) | (src[3] << 24);
696}
697
698status_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
822TombstoneSection::TombstoneSection(int id, const char* type, const int64_t timeoutMs)
823    : WorkerThreadSection(id, timeoutMs), mType(type) {
824    name += "tombstone ";
825    name += type;
826}
827
828TombstoneSection::~TombstoneSection() {}
829
830status_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