Merge "common_time: Turn the logging up to 11" (9169b558) · Commits · e / os / android_frameworks_base

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.
		ALOGI("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));
		ALOGI("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) {
		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 @@ bool CommonTimeServer::setupSocket_l() {
		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,7 +467,8 @@ bool CommonTimeServer::setupSocket_l() {
		reinterpret_cast<const sockaddr *>(&bindAddr),
		sizeof(bindAddr));
		if (rc) {
		ALOGE("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) {
		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 @@ bool CommonTimeServer::setupSocket_l() {
		// 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 @@ 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) {
		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 @@ bool CommonTimeServer::handlePacket() {
		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::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,
		@@ -917,6 +996,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) {
		@@ -973,6 +1060,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),
		@@ -1049,6 +1145,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),
		@@ -1071,7 +1176,8 @@ bool CommonTimeServer::becomeClient(const sockaddr_storage& masterEP,
		sockaddrToString(masterEP, true, newEPStr, sizeof(newEPStr));
		sockaddrToString(mMasterEP, mMasterEPValid, oldEPStr, sizeof(oldEPStr));

		ALOGI("%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,
		@@ -1132,7 +1238,8 @@ bool CommonTimeServer::becomeMaster(const char* cause) {
		notifyClockSync();
		}

		ALOGI("%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",
		@@ -1165,7 +1272,8 @@ bool CommonTimeServer::becomeRonin(const char* cause) {
		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 @@ bool CommonTimeServer::becomeRonin(const char* cause) {
		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::becomeRonin(const char* cause) {
		}

		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::becomeWaitForElection(const char* cause) {
		}

		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);

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;