common_time: Turn the logging up to 11
Hand merge from ics-aah
> 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: John Grossman <johngro@google.com>
Change-Id: If7156d41ce4553d5ba5c3a8e1dd616564a569711
Signed-off-by: John Grossman <johngro@google.com>
diff --git a/services/common_time/common_time_server.cpp b/services/common_time/common_time_server.cpp
index 0125709..16be8f1 100644
--- a/services/common_time/common_time_server.cpp
+++ b/services/common_time/common_time_server.cpp
@@ -107,6 +107,9 @@
, 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,10 +333,11 @@
// 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.
- ALOGI("Entering networkless mode interface is %s, "
- "shouldAutoDisable = %s",
- mBindIfaceValid ? "valid" : "invalid",
- shouldAutoDisable() ? "true" : "false");
+ mStateChangeLog.log(ANDROID_LOG_INFO, LOG_TAG,
+ "Entering networkless mode interface is %s, "
+ "shouldAutoDisable = %s",
+ mBindIfaceValid ? "valid" : "invalid",
+ shouldAutoDisable() ? "true" : "false");
if ((mState != ICommonClock::STATE_INITIAL) &&
(mState != ICommonClock::STATE_MASTER)) {
if (mTimelineID == ICommonClock::kInvalidTimelineID)
@@ -415,20 +419,23 @@
sockaddrToString(mMasterElectionEP, true, masterElectionEPStr,
sizeof(masterElectionEPStr));
- ALOGI("Building socket :: bind = %s master election = %s",
- mBindIface.string(), masterElectionEPStr);
+ 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) {
- ALOGW("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) {
- ALOGE("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 @@
rc = setsockopt(mSocket, SOL_SOCKET, SO_BINDTODEVICE,
(void *)&ifr, sizeof(ifr));
if (rc) {
- ALOGE("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,8 +467,9 @@
reinterpret_cast<const sockaddr *>(&bindAddr),
sizeof(bindAddr));
if (rc) {
- ALOGE("Failed to bind socket to port %hu (errno = %d)",
- ntohs(bindAddr.sin_port), errno);
+ 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 @@
rc = setsockopt(mSocket, IPPROTO_IP, IP_MULTICAST_LOOP,
&zero, sizeof(zero));
if (rc == -1) {
- ALOGE("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) {
- ALOGE("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 @@
// the local subnet)
rc = setsockopt(mSocket, IPPROTO_IP, IP_TTL, &one, sizeof(one));
if (rc == -1) {
- ALOGE("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 @@
((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 @@
reinterpret_cast<const sockaddr *>(&srcAddr), &srcAddrLen);
if (recvBytes < 0) {
- ALOGE("%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 @@
break;
default: {
- ALOGD("%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::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 @@
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::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,
@@ -917,6 +996,14 @@
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) {
@@ -973,6 +1060,15 @@
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),
@@ -1049,6 +1145,15 @@
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),
@@ -1071,15 +1176,16 @@
sockaddrToString(masterEP, true, newEPStr, sizeof(newEPStr));
sockaddrToString(mMasterEP, mMasterEPValid, oldEPStr, sizeof(oldEPStr));
- ALOGI("%s --> CLIENT (%s) :%s"
- " OldMaster: %02x-%014llx::%016llx::%s"
- " NewMaster: %02x-%014llx::%016llx::%s",
- stateToString(mState), cause,
- (mTimelineID != timelineID) ? " (new timeline)" : "",
- mClient_MasterDevicePriority, mClient_MasterDeviceID,
- mTimelineID, oldEPStr,
- masterDevicePriority, masterDeviceID,
- timelineID, newEPStr);
+ mStateChangeLog.log(ANDROID_LOG_INFO, LOG_TAG,
+ "%s --> CLIENT (%s) :%s"
+ " OldMaster: %02x-%014llx::%016llx::%s"
+ " NewMaster: %02x-%014llx::%016llx::%s",
+ stateToString(mState), cause,
+ (mTimelineID != timelineID) ? " (new timeline)" : "",
+ mClient_MasterDevicePriority, mClient_MasterDeviceID,
+ mTimelineID, oldEPStr,
+ masterDevicePriority, masterDeviceID,
+ timelineID, newEPStr);
if (mTimelineID != timelineID) {
// start following a new timeline
@@ -1132,11 +1238,12 @@
notifyClockSync();
}
- ALOGI("%s --> MASTER (%s) : %s timeline %016llx",
- stateToString(mState), cause,
- (oldTimelineID == mTimelineID) ? "taking ownership of"
- : "creating new",
- mTimelineID);
+ mStateChangeLog.log(ANDROID_LOG_INFO, LOG_TAG,
+ "%s --> MASTER (%s) : %s timeline %016llx",
+ stateToString(mState), cause,
+ (oldTimelineID == mTimelineID) ? "taking ownership of"
+ : "creating new",
+ mTimelineID);
memset(&mMasterEP, 0, sizeof(mMasterEP));
mMasterEPValid = false;
@@ -1165,7 +1272,8 @@
mMasterEPValid = false;
if (mCommonClock.isValid()) {
- ALOGI("%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,
@@ -1178,7 +1286,8 @@
setState(ICommonClock::STATE_RONIN);
return sendWhoIsMasterRequest();
} else {
- ALOGI("%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,
@@ -1192,7 +1301,8 @@
}
bool CommonTimeServer::becomeWaitForElection(const char* cause) {
- ALOGI("%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);
@@ -1202,7 +1312,9 @@
}
bool CommonTimeServer::becomeInitial(const char* cause) {
- ALOGI("Entering INITIAL (%s), total reset.", cause);
+ mStateChangeLog.log(ANDROID_LOG_INFO, LOG_TAG,
+ "Entering INITIAL (%s), total reset.",
+ cause);
setState(ICommonClock::STATE_INITIAL);