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

Commit 1bcfeafe authored by John Grossman's avatar John Grossman
Browse files

DO NOT MERGE: common_time: Turn the logging up to 11 



Actually, despite the CL title, no addition log messages are being
sent to logcat.  Generally speaking, the common_time service tends to
be rather quiet from a log perspective.  Events related to master
election and arbitration as well as state changes tend to be
infrequent in steady state operation.  Unfortunately, if there is a
problem with the system, it frequently gets pushed out of logcat by
other messages and is missing from the logs when a bugreport is
finally taken.

This change adds a utility class which can be used to store the last N
log message in a ring buffer to be dumped later during a dumpsys
operation.  Three internal log buffers were added to the system.  One
to record messages having to do with state transitions.  Another was
added to record traffic relating to master election, and one final
buffer to record basic data on packets which were received but
discarded for any reason.  During a bugreport, these common_time.clock
service will be able to dump these messages regardless of the amt of
other logcat activity, which should assist in debugging long running
issues.

Change-Id: Ic3bbf7480c8978f9bf82bafaba04cf4586db60cf
Signed-off-by: default avatarJohn Grossman <johngro@google.com>
parent c43a685c

services/common_time/clock_recovery.cpp

+7 −5
Original line number Diff line number Diff line
@@ -225,6 +225,9 @@ bool ClockRecoveryLoop::pushDisciplineEvent(int64_t local_time, 
    if (current_point == min_rtt || rtt < control_thresh_) {

        delta_f = delta = nominal_common_time - observed_common;



        last_error_est_valid_ = true;

        last_error_est_usec_ = delta;



        // Compute the error then clamp to the panic threshold.  If we ever

        // exceed this amt of error, its time to panic and reset the system.

        // Given that the error in the measurement of the error could be as
@@ -258,7 +261,6 @@ bool ClockRecoveryLoop::pushDisciplineEvent(int64_t local_time, 


    // Save error terms for later.

    last_delta_f_ = delta_f;

    last_delta_ = delta;



    // Clamp CO to +/- 100ppm.

    if (CO < COmin)
@@ -295,8 +297,8 @@ bool ClockRecoveryLoop::pushDisciplineEvent(int64_t local_time, 
int32_t ClockRecoveryLoop::getLastErrorEstimate() {

    Mutex::Autolock lock(&lock_);



    if (last_delta_valid_)

        return last_delta_;

    if (last_error_est_valid_)

        return last_error_est_usec_;

    else

        return ICommonClock::kErrorEstimateUnknown;

}
@@ -310,8 +312,8 @@ void ClockRecoveryLoop::reset_l(bool position, bool frequency) { 
    }



    if (frequency) {

        last_delta_valid_ = false;

        last_delta_ = 0;

        last_error_est_valid_ = false;

        last_error_est_usec_ = 0;

        last_delta_f_ = 0.0;

        CO = 0.0f;

        lastCObias = CObias = 0.0f;

services/common_time/clock_recovery.h

+2 −2
Original line number Diff line number Diff line
@@ -108,8 +108,8 @@ class ClockRecoveryLoop { 


    // parameters maintained while running and reset during a reset

    // of the frequency correction.

    bool    last_delta_valid_;

    int32_t last_delta_;

    bool    last_error_est_valid_;

    int32_t last_error_est_usec_;

    float last_delta_f_;

    int32_t integrated_error_;

    int32_t tgt_correction_;

services/common_time/common_time_server.cpp

+151 −39
Original line number Diff line number Diff line
@@ -107,6 +107,9 @@ CommonTimeServer::CommonTimeServer() 
    , mTimelineID(ICommonClock::kInvalidTimelineID)

    , mClockSynced(false)

    , mCommonClockHasClients(false)

    , mStateChangeLog("Recent State Change Events", 30)

    , mElectionLog("Recent Master Election Traffic", 30)

    , mBadPktLog("Recent Bad Packet RX Info", 8)

    , mInitial_WhoIsMasterRequestTimeouts(0)

    , mClient_MasterDeviceID(0)

    , mClient_MasterDevicePriority(0)
@@ -330,7 +333,8 @@ bool CommonTimeServer::runStateMachine_l() { 
            // we are in any other state (CLIENT, RONIN or WAIT_FOR_ELECTION),

            // then transition to either INITIAL or MASTER depending on whether

            // or not our timeline is valid.

            LOGI("Entering networkless mode interface is %s, "

            mStateChangeLog.log(ANDROID_LOG_INFO, LOG_TAG,

                    "Entering networkless mode interface is %s, "

                    "shouldAutoDisable = %s",

                    mBindIfaceValid ? "valid" : "invalid",

                    shouldAutoDisable() ? "true" : "false");
@@ -415,20 +419,23 @@ bool CommonTimeServer::setupSocket_l() { 


    sockaddrToString(mMasterElectionEP, true, masterElectionEPStr,

                     sizeof(masterElectionEPStr));

    LOGI("Building socket :: bind = %s master election = %s",

    mStateChangeLog.log(ANDROID_LOG_INFO, LOG_TAG,

                        "Building socket :: bind = %s master election = %s",

                        mBindIface.string(), masterElectionEPStr);



    // TODO: add proper support for IPv6.  Right now, we block IPv6 addresses at

    // the configuration interface level.

    if (AF_INET != mMasterElectionEP.ss_family) {

        LOGW("TODO: add proper IPv6 support");

        mStateChangeLog.log(ANDROID_LOG_WARN, LOG_TAG,

                            "TODO: add proper IPv6 support");

        goto bailout;

    }



    // open a UDP socket for the timeline serivce

    mSocket = socket(AF_INET, SOCK_DGRAM, IPPROTO_UDP);

    if (mSocket < 0) {

        LOGE("Failed to create socket (errno = %d)", errno);

        mStateChangeLog.log(ANDROID_LOG_ERROR, LOG_TAG,

                            "Failed to create socket (errno = %d)", errno);

        goto bailout;

    }
@@ -440,8 +447,9 @@ bool CommonTimeServer::setupSocket_l() { 
    rc = setsockopt(mSocket, SOL_SOCKET, SO_BINDTODEVICE,

                    (void *)&ifr, sizeof(ifr));

    if (rc) {

        LOGE("Failed to bind socket at to interface %s (errno = %d)",

              ifr.ifr_name, errno);

        mStateChangeLog.log(ANDROID_LOG_ERROR, LOG_TAG,

                            "Failed to bind socket at to interface %s "

                            "(errno = %d)", ifr.ifr_name, errno);

        goto bailout;

    }
@@ -459,7 +467,8 @@ bool CommonTimeServer::setupSocket_l() { 
              reinterpret_cast<const sockaddr *>(&bindAddr),

              sizeof(bindAddr));

    if (rc) {

        LOGE("Failed to bind socket to port %hu (errno = %d)",

        mStateChangeLog.log(ANDROID_LOG_ERROR, LOG_TAG,

                            "Failed to bind socket to port %hu (errno = %d)",

                            ntohs(bindAddr.sin_port), errno);

        goto bailout;

    }
@@ -483,17 +492,20 @@ bool CommonTimeServer::setupSocket_l() { 
        rc = setsockopt(mSocket, IPPROTO_IP, IP_MULTICAST_LOOP,

                        &zero, sizeof(zero));

        if (rc == -1) {

            LOGE("Failed to disable multicast loopback (errno = %d)", errno);

            mStateChangeLog.log(ANDROID_LOG_ERROR, LOG_TAG,

                                "Failed to disable multicast loopback "

                                "(errno = %d)", errno);

            goto bailout;

        }

    } else

    if (ntohl(ipv4_addr->sin_addr.s_addr) == 0xFFFFFFFF) {

        // If the master election address is the broadcast address, then enable

        // the broadcast socket option

        const int one = 1;

        rc = setsockopt(mSocket, SOL_SOCKET, SO_BROADCAST, &one, sizeof(one));

        if (rc == -1) {

            LOGE("Failed to enable broadcast (errno = %d)", errno);

            mStateChangeLog.log(ANDROID_LOG_ERROR, LOG_TAG,

                                "Failed to enable broadcast (errno = %d)",

                                errno);

            goto bailout;

        }

    } else {
@@ -507,7 +519,8 @@ bool CommonTimeServer::setupSocket_l() { 
    // the local subnet)

    rc = setsockopt(mSocket, IPPROTO_IP, IP_TTL, &one, sizeof(one));

    if (rc == -1) {

        LOGE("Failed to set TTL to %d (errno = %d)", one, errno);

        mStateChangeLog.log(ANDROID_LOG_ERROR, LOG_TAG,

                            "Failed to set TTL to %d (errno = %d)", one, errno);

        goto bailout;

    }
@@ -569,6 +582,31 @@ bool CommonTimeServer::arbitrateMaster( 
           ((devicePrio1 == devicePrio2) && (deviceID1 > deviceID2)));

}



static void hexDumpToString(const uint8_t* src, size_t src_len,

                            char* dst, size_t dst_len) {

    size_t offset;

    size_t i;



    for (i = 0; (i < src_len) && (offset < dst_len); ++i) {

        int res;

        if (0 == (i % 16)) {

            res = snprintf(dst + offset, dst_len - offset, "\n%04x :", i);

            if (res < 0)

                break;

            offset += res;

            if (offset >= dst_len)

                break;

        }



        res = snprintf(dst + offset, dst_len - offset, " %02x", src[i]);

        if (res < 0)

            break;

        offset += res;

    }



    dst[dst_len - 1] = 0;

}



bool CommonTimeServer::handlePacket() {

    uint8_t buf[256];

    struct sockaddr_storage srcAddr;
@@ -579,14 +617,24 @@ bool CommonTimeServer::handlePacket() { 
            reinterpret_cast<const sockaddr *>(&srcAddr), &srcAddrLen);



    if (recvBytes < 0) {

        LOGE("%s:%d recvfrom failed", __PRETTY_FUNCTION__, __LINE__);

        mBadPktLog.log(ANDROID_LOG_ERROR, LOG_TAG,

                       "recvfrom failed (res %d, errno %d)",

                       recvBytes, errno);

        return false;

    }



    UniversalTimeServicePacket pkt;

    recvBytes = pkt.deserializePacket(buf, recvBytes, mSyncGroupID);

    if (recvBytes < 0)

    if (pkt.deserializePacket(buf, recvBytes, mSyncGroupID) < 0) {

        char hex[256];

        char srcEPStr[64];



        hexDumpToString(buf, static_cast<size_t>(recvBytes), hex, sizeof(hex));

        sockaddrToString(srcAddr, true, srcEPStr, sizeof(srcEPStr));



        mBadPktLog.log("Failed to parse %d byte packet from %s.%s",

                       recvBytes, srcEPStr, hex);

        return false;

    }



    bool result;

    switch (pkt.packetType) {
@@ -614,8 +662,13 @@ bool CommonTimeServer::handlePacket() { 
            break;



        default: {

            LOGD("%s:%d unknown packet type(%d)",

                    __PRETTY_FUNCTION__, __LINE__, pkt.packetType);

            char srcEPStr[64];

            sockaddrToString(srcAddr, true, srcEPStr, sizeof(srcEPStr));



            mBadPktLog.log(ANDROID_LOG_WARN, LOG_TAG,

                           "unknown packet type (%d) from %s",

                           pkt.packetType, srcEPStr);



            result = false;

        } break;

    }
@@ -699,6 +752,14 @@ bool CommonTimeServer::handleTimeoutWaitForElection() { 
bool CommonTimeServer::handleWhoIsMasterRequest(

        const WhoIsMasterRequestPacket* request,

        const sockaddr_storage& srcAddr) {



    char srcEPStr[64];

    sockaddrToString(srcAddr, true, srcEPStr, sizeof(srcEPStr));

    mElectionLog.log("RXed WhoIs master request while in state %s.  "

                     "src %s reqTID %016llx ourTID %016llx",

                     stateToString(mState), srcEPStr,

                     request->timelineID, mTimelineID);



    if (mState == ICommonClock::STATE_MASTER) {

        // is this request related to this master's timeline?

        if (request->timelineID != ICommonClock::kInvalidTimelineID &&
@@ -710,6 +771,13 @@ bool CommonTimeServer::handleWhoIsMasterRequest( 
        pkt.deviceID = mDeviceID;

        pkt.devicePriority = effectivePriority();



        mElectionLog.log("TXing WhoIs master resp to %s while in state %s.  "

                         "ourTID %016llx ourGID %016llx ourDID %016llx "

                         "ourPrio %u",

                         srcEPStr, stateToString(mState),

                         mTimelineID, mSyncGroupID,

                         pkt.deviceID, pkt.devicePriority);



        uint8_t buf[256];

        ssize_t bufSz = pkt.serializePacket(buf, sizeof(buf));

        if (bufSz < 0)
@@ -761,6 +829,17 @@ bool CommonTimeServer::handleWhoIsMasterRequest( 
bool CommonTimeServer::handleWhoIsMasterResponse(

        const WhoIsMasterResponsePacket* response,

        const sockaddr_storage& srcAddr) {

    char srcEPStr[64];

    sockaddrToString(srcAddr, true, srcEPStr, sizeof(srcEPStr));

    mElectionLog.log("RXed WhoIs master response while in state %s.  "

                     "src %s respTID %016llx respDID %016llx respPrio %u "

                     "ourTID %016llx",

                     stateToString(mState), srcEPStr,

                     response->timelineID,

                     response->deviceID,

                     static_cast<uint32_t>(response->devicePriority),

                     mTimelineID);



    if (mState == ICommonClock::STATE_INITIAL || mState == ICommonClock::STATE_RONIN) {

        return becomeClient(srcAddr,

                            response->deviceID,
@@ -916,6 +995,14 @@ bool CommonTimeServer::handleMasterAnnouncement( 
    uint8_t  newDevicePrio = packet->devicePriority;

    uint64_t newTimelineID = packet->timelineID;



    char srcEPStr[64];

    sockaddrToString(srcAddr, true, srcEPStr, sizeof(srcEPStr));

    mElectionLog.log("RXed master announcement while in state %s.  "

                     "src %s srcDevID %lld srcPrio %u srcTID %016llx",

                     stateToString(mState), srcEPStr,

                     newDeviceID, static_cast<uint32_t>(newDevicePrio),

                     newTimelineID);



    if (mState == ICommonClock::STATE_INITIAL ||

        mState == ICommonClock::STATE_RONIN ||

        mState == ICommonClock::STATE_WAIT_FOR_ELECTION) {
@@ -972,6 +1059,15 @@ bool CommonTimeServer::sendWhoIsMasterRequest() { 
    uint8_t buf[256];

    ssize_t bufSz = pkt.serializePacket(buf, sizeof(buf));

    if (bufSz >= 0) {

        char dstEPStr[64];

        sockaddrToString(mMasterElectionEP, true, dstEPStr, sizeof(dstEPStr));

        mElectionLog.log("TXing WhoIs master request to %s while in state %s.  "

                         "ourTID %016llx ourGID %016llx ourDID %016llx "

                         "ourPrio %u",

                         dstEPStr, stateToString(mState),

                         mTimelineID, mSyncGroupID,

                         pkt.senderDeviceID, pkt.senderDevicePriority);



        ssize_t sendBytes = sendto(

                mSocket, buf, bufSz, 0,

                reinterpret_cast<const sockaddr *>(&mMasterElectionEP),
@@ -1048,6 +1144,15 @@ bool CommonTimeServer::sendMasterAnnouncement() { 
    uint8_t buf[256];

    ssize_t bufSz = pkt.serializePacket(buf, sizeof(buf));

    if (bufSz >= 0) {

        char dstEPStr[64];

        sockaddrToString(mMasterElectionEP, true, dstEPStr, sizeof(dstEPStr));

        mElectionLog.log("TXing Master announcement to %s while in state %s.  "

                         "ourTID %016llx ourGID %016llx ourDID %016llx "

                         "ourPrio %u",

                         dstEPStr, stateToString(mState),

                         mTimelineID, mSyncGroupID,

                         pkt.deviceID, pkt.devicePriority);



        ssize_t sendBytes = sendto(

                mSocket, buf, bufSz, 0,

                reinterpret_cast<const sockaddr *>(&mMasterElectionEP),
@@ -1070,7 +1175,8 @@ bool CommonTimeServer::becomeClient(const sockaddr_storage& masterEP, 
    sockaddrToString(masterEP, true, newEPStr, sizeof(newEPStr));

    sockaddrToString(mMasterEP, mMasterEPValid, oldEPStr, sizeof(oldEPStr));



    LOGI("%s --> CLIENT (%s) :%s"

    mStateChangeLog.log(ANDROID_LOG_INFO, LOG_TAG,

            "%s --> CLIENT (%s) :%s"

            " OldMaster: %02x-%014llx::%016llx::%s"

            " NewMaster: %02x-%014llx::%016llx::%s",

            stateToString(mState), cause,
@@ -1131,7 +1237,8 @@ bool CommonTimeServer::becomeMaster(const char* cause) { 
        notifyClockSync();

    }



    LOGI("%s --> MASTER (%s) : %s timeline %016llx",

    mStateChangeLog.log(ANDROID_LOG_INFO, LOG_TAG,

            "%s --> MASTER (%s) : %s timeline %016llx",

            stateToString(mState), cause,

            (oldTimelineID == mTimelineID) ? "taking ownership of"

                                           : "creating new",
@@ -1164,7 +1271,8 @@ bool CommonTimeServer::becomeRonin(const char* cause) { 
    mMasterEPValid = false;



    if (mCommonClock.isValid()) {

        LOGI("%s --> RONIN (%s) : lost track of previously valid timeline "

        mStateChangeLog.log(ANDROID_LOG_INFO, LOG_TAG,

             "%s --> RONIN (%s) : lost track of previously valid timeline "

             "%02x-%014llx::%016llx::%s (%d TXed %d RXed %d RXExpired)",

             stateToString(mState), cause,

             mClient_MasterDevicePriority, mClient_MasterDeviceID,
@@ -1177,7 +1285,8 @@ bool CommonTimeServer::becomeRonin(const char* cause) { 
        setState(ICommonClock::STATE_RONIN);

        return sendWhoIsMasterRequest();

    } else {

        LOGI("%s --> INITIAL (%s) : never synced timeline "

        mStateChangeLog.log(ANDROID_LOG_INFO, LOG_TAG,

             "%s --> INITIAL (%s) : never synced timeline "

             "%02x-%014llx::%016llx::%s (%d TXed %d RXed %d RXExpired)",

             stateToString(mState), cause,

             mClient_MasterDevicePriority, mClient_MasterDeviceID,
@@ -1191,7 +1300,8 @@ bool CommonTimeServer::becomeRonin(const char* cause) { 
}



bool CommonTimeServer::becomeWaitForElection(const char* cause) {

    LOGI("%s --> WAIT_FOR_ELECTION (%s) : dropping out of election,"

    mStateChangeLog.log(ANDROID_LOG_INFO, LOG_TAG,

         "%s --> WAIT_FOR_ELECTION (%s) : dropping out of election,"

         " waiting %d mSec for completion.",

         stateToString(mState), cause, kWaitForElection_TimeoutMs);
@@ -1201,7 +1311,9 @@ bool CommonTimeServer::becomeWaitForElection(const char* cause) { 
}



bool CommonTimeServer::becomeInitial(const char* cause) {

    LOGI("Entering INITIAL (%s), total reset.", cause);

    mStateChangeLog.log(ANDROID_LOG_INFO, LOG_TAG,

                        "Entering INITIAL (%s), total reset.",

                        cause);



    setState(ICommonClock::STATE_INITIAL);

services/common_time/common_time_server.h

+5 −0
Original line number Diff line number Diff line
@@ -238,6 +238,11 @@ class CommonTimeServer : public Thread { 
    // interface AND currently active common clock clients.

    bool mCommonClockHasClients;



    // Internal logs used for dumpsys.

    LogRing                 mStateChangeLog;

    LogRing                 mElectionLog;

    LogRing                 mBadPktLog;



    // Configuration info

    struct sockaddr_storage mMasterElectionEP;          // Endpoint over which we conduct master election

    String8                 mBindIface;                 // Endpoint for the service to bind to.

services/common_time/common_time_server_api.cpp

+3 −0
Original line number Diff line number Diff line
@@ -354,6 +354,9 @@ status_t CommonTimeServer::dumpClockInterface(int fd, 


        dump_printf("Active Clients : %u\n", activeClients);

        mClient_PacketRTTLog.dumpLog(fd, mCommonClock);

        mStateChangeLog.dumpLog(fd);

        mElectionLog.dumpLog(fd);

        mBadPktLog.dumpLog(fd);

    }



    return NO_ERROR;