Donate to e Foundation | Murena handsets with /e/OS | Own a part of Murena! Learn more

Commit 3be0b432 authored by Yi Jin's avatar Yi Jin
Browse files

Make the logging more concise. 

Each section's name will start with its type, e.g. file, gzip, cmd.

Bug: 77333635
Test: atest incidentd_test
Change-Id: I7c86f2682b1c2055c6063f6395fc7fe7fc7ffea5
parent 010495e7

cmds/incidentd/src/Section.cpp

+34 −74
Original line number Diff line number Diff line
@@ -238,7 +238,8 @@ static inline bool isSysfs(const char* filename) { return strncmp(filename, "/sy 


FileSection::FileSection(int id, const char* filename, const int64_t timeoutMs)

    : Section(id, timeoutMs), mFilename(filename) {

    name = filename;

    name = "file ";

    name += filename;

    mIsSysfs = isSysfs(filename);

}
@@ -249,7 +250,7 @@ status_t FileSection::Execute(ReportRequestSet* requests) const { 
    // add O_CLOEXEC to make sure it is closed when exec incident helper

    unique_fd fd(open(mFilename, O_RDONLY | O_CLOEXEC));

    if (fd.get() == -1) {

        ALOGW("FileSection '%s' failed to open file", this->name.string());

        ALOGW("[%s] failed to open file", this->name.string());

        return -errno;

    }
@@ -258,13 +259,13 @@ status_t FileSection::Execute(ReportRequestSet* requests) const { 
    Fpipe c2pPipe;

    // initiate pipes to pass data to/from incident_helper

    if (!p2cPipe.init() || !c2pPipe.init()) {

        ALOGW("FileSection '%s' failed to setup pipes", this->name.string());

        ALOGW("[%s] failed to setup pipes", this->name.string());

        return -errno;

    }



    pid_t pid = fork_execute_incident_helper(this->id, &p2cPipe, &c2pPipe);

    if (pid == -1) {

        ALOGW("FileSection '%s' failed to fork", this->name.string());

        ALOGW("[%s] failed to fork", this->name.string());

        return -errno;

    }
@@ -274,7 +275,7 @@ status_t FileSection::Execute(ReportRequestSet* requests) const { 
                                                           this->timeoutMs, mIsSysfs);

    write_section_stats(requests->sectionStats(this->id), buffer);

    if (readStatus != NO_ERROR || buffer.timedOut()) {

        ALOGW("FileSection '%s' failed to read data from incident helper: %s, timedout: %s",

        ALOGW("[%s] failed to read data from incident helper: %s, timedout: %s",

              this->name.string(), strerror(-readStatus), buffer.timedOut() ? "true" : "false");

        kill_child(pid);

        return readStatus;
@@ -282,20 +283,11 @@ status_t FileSection::Execute(ReportRequestSet* requests) const { 


    status_t ihStatus = wait_child(pid);

    if (ihStatus != NO_ERROR) {

        ALOGW("FileSection '%s' abnormal child process: %s", this->name.string(),

              strerror(-ihStatus));

        ALOGW("[%s] abnormal child process: %s", this->name.string(), strerror(-ihStatus));

        return ihStatus;

    }



    VLOG("FileSection '%s' wrote %zd bytes in %d ms", this->name.string(), buffer.size(),

         (int)buffer.durationMs());

    status_t err = write_report_requests(this->id, buffer, requests);

    if (err != NO_ERROR) {

        ALOGW("FileSection '%s' failed writing: %s", this->name.string(), strerror(-err));

        return err;

    }



    return NO_ERROR;

    return write_report_requests(this->id, buffer, requests);

}

// ================================================================================

GZipSection::GZipSection(int id, const char* filename, ...) : Section(id) {
@@ -324,9 +316,8 @@ status_t GZipSection::Execute(ReportRequestSet* requests) const { 
        ALOGW("GZipSection failed to open file %s", mFilenames[index]);

        index++;  // look at the next file.

    }

    VLOG("GZipSection is using file %s, fd=%d", mFilenames[index], fd.get());

    if (fd.get() == -1) {

        ALOGW("GZipSection %s can't open all the files", this->name.string());

        ALOGW("[%s] can't open all the files", this->name.string());

        return NO_ERROR;  // e.g. LAST_KMSG will reach here in user build.

    }

    FdBuffer buffer;
@@ -334,13 +325,13 @@ status_t GZipSection::Execute(ReportRequestSet* requests) const { 
    Fpipe c2pPipe;

    // initiate pipes to pass data to/from gzip

    if (!p2cPipe.init() || !c2pPipe.init()) {

        ALOGW("GZipSection '%s' failed to setup pipes", this->name.string());

        ALOGW("[%s] failed to setup pipes", this->name.string());

        return -errno;

    }



    pid_t pid = fork_execute_cmd((char* const*)GZIP, &p2cPipe, &c2pPipe);

    if (pid == -1) {

        ALOGW("GZipSection '%s' failed to fork", this->name.string());

        ALOGW("[%s] failed to fork", this->name.string());

        return -errno;

    }

    // parent process
@@ -359,24 +350,22 @@ status_t GZipSection::Execute(ReportRequestSet* requests) const { 
    size_t editPos = internalBuffer->wp()->pos();

    internalBuffer->wp()->move(8);  // reserve 8 bytes for the varint of the data size.

    size_t dataBeginAt = internalBuffer->wp()->pos();

    VLOG("GZipSection '%s' editPos=%zd, dataBeginAt=%zd", this->name.string(), editPos,

         dataBeginAt);

    VLOG("[%s] editPos=%zu, dataBeginAt=%zu", this->name.string(), editPos, dataBeginAt);



    status_t readStatus = buffer.readProcessedDataInStream(

            fd.get(), std::move(p2cPipe.writeFd()), std::move(c2pPipe.readFd()), this->timeoutMs,

            isSysfs(mFilenames[index]));

    write_section_stats(requests->sectionStats(this->id), buffer);

    if (readStatus != NO_ERROR || buffer.timedOut()) {

        ALOGW("GZipSection '%s' failed to read data from gzip: %s, timedout: %s",

              this->name.string(), strerror(-readStatus), buffer.timedOut() ? "true" : "false");

        ALOGW("[%s] failed to read data from gzip: %s, timedout: %s", this->name.string(),

              strerror(-readStatus), buffer.timedOut() ? "true" : "false");

        kill_child(pid);

        return readStatus;

    }



    status_t gzipStatus = wait_child(pid);

    if (gzipStatus != NO_ERROR) {

        ALOGW("GZipSection '%s' abnormal child process: %s", this->name.string(),

              strerror(-gzipStatus));

        ALOGW("[%s] abnormal child process: %s", this->name.string(), strerror(-gzipStatus));

        return gzipStatus;

    }

    // Revisit the actual size from gzip result and edit the internal buffer accordingly.
@@ -384,15 +373,8 @@ status_t GZipSection::Execute(ReportRequestSet* requests) const { 
    internalBuffer->wp()->rewind()->move(editPos);

    internalBuffer->writeRawVarint32(dataSize);

    internalBuffer->copy(dataBeginAt, dataSize);

    VLOG("GZipSection '%s' wrote %zd bytes in %d ms, dataSize=%zd", this->name.string(),

         buffer.size(), (int)buffer.durationMs(), dataSize);

    status_t err = write_report_requests(this->id, buffer, requests);

    if (err != NO_ERROR) {

        ALOGW("GZipSection '%s' failed writing: %s", this->name.string(), strerror(-err));

        return err;

    }



    return NO_ERROR;

    return write_report_requests(this->id, buffer, requests);

}



// ================================================================================
@@ -477,8 +459,7 @@ status_t WorkerThreadSection::Execute(ReportRequestSet* requests) const { 
    err = buffer.read(data->pipe.readFd().get(), this->timeoutMs);

    if (err != NO_ERROR) {

        // TODO: Log this error into the incident report.

        ALOGW("WorkerThreadSection '%s' reader failed with error '%s'", this->name.string(),

              strerror(-err));

        ALOGW("[%s] reader failed with error '%s'", this->name.string(), strerror(-err));

    }



    // Done with the read fd. The worker thread closes the write one so
@@ -496,39 +477,25 @@ status_t WorkerThreadSection::Execute(ReportRequestSet* requests) const { 
            if (data->workerError != NO_ERROR) {

                err = data->workerError;

                // TODO: Log this error into the incident report.

                ALOGW("WorkerThreadSection '%s' worker failed with error '%s'", this->name.string(),

                      strerror(-err));

                ALOGW("[%s] worker failed with error '%s'", this->name.string(), strerror(-err));

            }

        }

    }

    write_section_stats(requests->sectionStats(this->id), buffer);

    if (timedOut || buffer.timedOut()) {

        ALOGW("WorkerThreadSection '%s' timed out", this->name.string());

        ALOGW("[%s] timed out", this->name.string());

        return NO_ERROR;

    }



    if (buffer.truncated()) {

        // TODO: Log this into the incident report.

    }



    // TODO: There was an error with the command or buffering. Report that.  For now

    // just exit with a log messasge.

    if (err != NO_ERROR) {

        ALOGW("WorkerThreadSection '%s' failed with error '%s'", this->name.string(),

              strerror(-err));

        ALOGW("[%s] failed with error '%s'", this->name.string(), strerror(-err));

        return NO_ERROR;

    }



    // Write the data that was collected

    VLOG("WorkerThreadSection '%s' wrote %zd bytes in %d ms", name.string(), buffer.size(),

         (int)buffer.durationMs());

    err = write_report_requests(this->id, buffer, requests);

    if (err != NO_ERROR) {

        ALOGW("WorkerThreadSection '%s' failed writing: '%s'", this->name.string(), strerror(-err));

        return err;

    }



    return NO_ERROR;

    return write_report_requests(this->id, buffer, requests);

}



// ================================================================================
@@ -565,18 +532,18 @@ status_t CommandSection::Execute(ReportRequestSet* requests) const { 
    Fpipe ihPipe;



    if (!cmdPipe.init() || !ihPipe.init()) {

        ALOGW("CommandSection '%s' failed to setup pipes", this->name.string());

        ALOGW("[%s] failed to setup pipes", this->name.string());

        return -errno;

    }



    pid_t cmdPid = fork_execute_cmd((char* const*)mCommand, NULL, &cmdPipe);

    if (cmdPid == -1) {

        ALOGW("CommandSection '%s' failed to fork", this->name.string());

        ALOGW("[%s] failed to fork", this->name.string());

        return -errno;

    }

    pid_t ihPid = fork_execute_incident_helper(this->id, &cmdPipe, &ihPipe);

    if (ihPid == -1) {

        ALOGW("CommandSection '%s' failed to fork", this->name.string());

        ALOGW("[%s] failed to fork", this->name.string());

        return -errno;

    }
@@ -584,7 +551,7 @@ status_t CommandSection::Execute(ReportRequestSet* requests) const { 
    status_t readStatus = buffer.read(ihPipe.readFd().get(), this->timeoutMs);

    write_section_stats(requests->sectionStats(this->id), buffer);

    if (readStatus != NO_ERROR || buffer.timedOut()) {

        ALOGW("CommandSection '%s' failed to read data from incident helper: %s, timedout: %s",

        ALOGW("[%s] failed to read data from incident helper: %s, timedout: %s",

              this->name.string(), strerror(-readStatus), buffer.timedOut() ? "true" : "false");

        kill_child(cmdPid);

        kill_child(ihPid);
@@ -596,20 +563,13 @@ status_t CommandSection::Execute(ReportRequestSet* requests) const { 
    status_t cmdStatus = wait_child(cmdPid);

    status_t ihStatus = wait_child(ihPid);

    if (cmdStatus != NO_ERROR || ihStatus != NO_ERROR) {

        ALOGW("CommandSection '%s' abnormal child processes, return status: command: %s, incident "

        ALOGW("[%s] abnormal child processes, return status: command: %s, incident "

              "helper: %s",

              this->name.string(), strerror(-cmdStatus), strerror(-ihStatus));

        return cmdStatus != NO_ERROR ? cmdStatus : ihStatus;

    }



    VLOG("CommandSection '%s' wrote %zd bytes in %d ms", this->name.string(), buffer.size(),

         (int)buffer.durationMs());

    status_t err = write_report_requests(this->id, buffer, requests);

    if (err != NO_ERROR) {

        ALOGW("CommandSection '%s' failed writing: %s", this->name.string(), strerror(-err));

        return err;

    }

    return NO_ERROR;

    return write_report_requests(this->id, buffer, requests);

}



// ================================================================================
@@ -659,7 +619,7 @@ status_t DumpsysSection::BlockingCall(int pipeWriteFd) const { 
map<log_id_t, log_time> LogSection::gLastLogsRetrieved;



LogSection::LogSection(int id, log_id_t logID) : WorkerThreadSection(id), mLogID(logID) {

    name += "logcat ";

    name = "logcat ";

    name += android_log_id_to_name(logID);

    switch (logID) {

        case LOG_ID_EVENTS:
@@ -700,7 +660,7 @@ status_t LogSection::BlockingCall(int pipeWriteFd) const { 
            android_logger_list_free);



    if (android_logger_open(loggers.get(), mLogID) == NULL) {

        ALOGE("LogSection %s: Can't get logger.", this->name.string());

        ALOGE("[%s] Can't get logger.", this->name.string());

        return -1;

    }
@@ -716,7 +676,7 @@ status_t LogSection::BlockingCall(int pipeWriteFd) const { 
        // err = -EAGAIN, graceful indication for ANDRODI_LOG_NONBLOCK that this is the end of data.

        if (err <= 0) {

            if (err != -EAGAIN) {

                ALOGW("LogSection %s: fails to read a log_msg.\n", this->name.string());

                ALOGW("[%s] fails to read a log_msg.\n", this->name.string());

            }

            // dump previous logs and don't consider this error a failure.

            break;
@@ -787,7 +747,7 @@ status_t LogSection::BlockingCall(int pipeWriteFd) const { 
            AndroidLogEntry entry;

            err = android_log_processLogBuffer(&msg.entry_v1, &entry);

            if (err != NO_ERROR) {

                ALOGW("LogSection %s: fails to process to an entry.\n", this->name.string());

                ALOGW("[%s] fails to process to an entry.\n", this->name.string());

                break;

            }

            lastTimestamp.tv_sec = entry.tv_sec;
@@ -816,7 +776,7 @@ status_t LogSection::BlockingCall(int pipeWriteFd) const { 


TombstoneSection::TombstoneSection(int id, const char* type, const int64_t timeoutMs)

    : WorkerThreadSection(id, timeoutMs), mType(type) {

    name += "tombstone ";

    name = "tombstone ";

    name += type;

}
@@ -871,7 +831,7 @@ status_t TombstoneSection::BlockingCall(int pipeWriteFd) const { 


        Fpipe dumpPipe;

        if (!dumpPipe.init()) {

            ALOGW("TombstoneSection '%s' failed to setup dump pipe", this->name.string());

            ALOGW("[%s] failed to setup dump pipe", this->name.string());

            err = -errno;

            break;

        }
@@ -903,7 +863,7 @@ status_t TombstoneSection::BlockingCall(int pipeWriteFd) const { 
        FdBuffer buffer;

        err = buffer.readFully(dumpPipe.readFd().get());

        if (err != NO_ERROR) {

            ALOGW("TombstoneSection '%s' failed to read stack dump: %d", this->name.string(), err);

            ALOGW("[%s] failed to read stack dump: %d", this->name.string(), err);

            dumpPipe.readFd().reset();

            break;

        }