Add additional logging to improve debugability of VcnManagementService (1d9c19a6) · Commits · e / os / android_frameworks_base

core/java/android/net/vcn/VcnNetworkPolicyResult.java

+10 −0

Original line number	Diff line number	Diff line
		@@ -87,6 +87,16 @@ public final class VcnNetworkPolicyResult implements Parcelable {
		&& mNetworkCapabilities.equals(that.mNetworkCapabilities);
		}

		@Override
		public String toString() {
		return "VcnNetworkPolicyResult { "
		+ "mIsTeardownRequested = "
		+ mIsTearDownRequested
		+ ", mNetworkCapabilities"
		+ mNetworkCapabilities
		+ " }";
		}

		/** {@inheritDoc} */
		@Override
		public int describeContents() {

core/java/android/net/vcn/VcnUnderlyingNetworkPolicy.java

+5 −0

Original line number	Diff line number	Diff line
		@@ -85,6 +85,11 @@ public final class VcnUnderlyingNetworkPolicy implements Parcelable {
		return mVcnNetworkPolicyResult.equals(that.mVcnNetworkPolicyResult);
		}

		@Override
		public String toString() {
		return mVcnNetworkPolicyResult.toString();
		}

		/** {@inheritDoc} */
		@Override
		public int describeContents() {

services/core/java/com/android/server/VcnManagementService.java

+12 −5

Original line number	Diff line number	Diff line
		@@ -434,6 +434,7 @@ public class VcnManagementService extends IVcnManagementService.Stub {
		synchronized (mLock) {
		final TelephonySubscriptionSnapshot oldSnapshot = mLastSnapshot;
		mLastSnapshot = snapshot;
		Slog.d(TAG, "new snapshot: " + mLastSnapshot);

		// Start any VCN instances as necessary
		for (Entry<ParcelUuid, VcnConfig> entry : mConfigs.entrySet()) {
		@@ -536,7 +537,7 @@ public class VcnManagementService extends IVcnManagementService.Stub {

		@GuardedBy("mLock")
		private void startVcnLocked(@NonNull ParcelUuid subscriptionGroup, @NonNull VcnConfig config) {
		Slog.v(TAG, "Starting VCN config for subGrp: " + subscriptionGroup);
		Slog.d(TAG, "Starting VCN config for subGrp: " + subscriptionGroup);

		// TODO(b/176939047): Support multiple VCNs active at the same time, or limit to one active
		// VCN.
		@@ -558,7 +559,7 @@ public class VcnManagementService extends IVcnManagementService.Stub {
		@GuardedBy("mLock")
		private void startOrUpdateVcnLocked(
		@NonNull ParcelUuid subscriptionGroup, @NonNull VcnConfig config) {
		Slog.v(TAG, "Starting or updating VCN config for subGrp: " + subscriptionGroup);
		Slog.d(TAG, "Starting or updating VCN config for subGrp: " + subscriptionGroup);

		if (mVcns.containsKey(subscriptionGroup)) {
		final Vcn vcn = mVcns.get(subscriptionGroup);
		@@ -584,7 +585,7 @@ public class VcnManagementService extends IVcnManagementService.Stub {
		if (!config.getProvisioningPackageName().equals(opPkgName)) {
		throw new IllegalArgumentException("Mismatched caller and VcnConfig creator");
		}
		Slog.v(TAG, "VCN config updated for subGrp: " + subscriptionGroup);
		Slog.d(TAG, "VCN config updated for subGrp: " + subscriptionGroup);

		mContext.getSystemService(AppOpsManager.class)
		.checkPackage(mDeps.getBinderCallingUid(), config.getProvisioningPackageName());
		@@ -609,7 +610,7 @@ public class VcnManagementService extends IVcnManagementService.Stub {
		public void clearVcnConfig(@NonNull ParcelUuid subscriptionGroup, @NonNull String opPkgName) {
		requireNonNull(subscriptionGroup, "subscriptionGroup was null");
		requireNonNull(opPkgName, "opPkgName was null");
		Slog.v(TAG, "VCN config cleared for subGrp: " + subscriptionGroup);
		Slog.d(TAG, "VCN config cleared for subGrp: " + subscriptionGroup);

		mContext.getSystemService(AppOpsManager.class)
		.checkPackage(mDeps.getBinderCallingUid(), opPkgName);
		@@ -845,8 +846,14 @@ public class VcnManagementService extends IVcnManagementService.Stub {
		}

		final NetworkCapabilities result = ncBuilder.build();
		return new VcnUnderlyingNetworkPolicy(
		final VcnUnderlyingNetworkPolicy policy = new VcnUnderlyingNetworkPolicy(
		mTrackingNetworkCallback.requiresRestartForCarrierWifi(result), result);

		if (VDBG) {
		Slog.d(TAG, "getUnderlyingNetworkPolicy() called for caps: " + networkCapabilities
		+ "; and lp: " + linkProperties + "; result = " + policy);
		}
		return policy;
		});
		}

services/core/java/com/android/server/vcn/Vcn.java

+26 −10

Original line number	Diff line number	Diff line
		@@ -311,7 +311,9 @@ public class Vcn extends Handler {

		private void handleConfigUpdated(@NonNull VcnConfig config) {
		// TODO: Add a dump function in VcnConfig that omits PII. Until then, use hashCode()
		Slog.v(getLogTag(), "Config updated: config = " + config.hashCode());
		Slog.d(
		getLogTag(),
		"Config updated: old = " + mConfig.hashCode() + "; new = " + config.hashCode());

		mConfig = config;

		@@ -340,6 +342,7 @@ public class Vcn extends Handler {
		}

		private void handleTeardown() {
		Slog.d(getLogTag(), "Tearing down");
		mVcnContext.getVcnNetworkProvider().unregisterListener(mRequestListener);

		for (VcnGatewayConnection gatewayConnection : mVcnGatewayConnections.values()) {
		@@ -350,6 +353,7 @@ public class Vcn extends Handler {
		}

		private void handleSafeModeStatusChanged() {
		Slog.d(getLogTag(), "VcnGatewayConnection safe mode status changed");
		boolean hasSafeModeGatewayConnection = false;

		// If any VcnGatewayConnection is in safe mode, mark the entire VCN as being in safe mode
		@@ -365,21 +369,24 @@ public class Vcn extends Handler {
		hasSafeModeGatewayConnection ? VCN_STATUS_CODE_SAFE_MODE : VCN_STATUS_CODE_ACTIVE;
		if (oldStatus != mCurrentStatus) {
		mVcnCallback.onSafeModeStatusChanged(hasSafeModeGatewayConnection);
		Slog.d(
		getLogTag(),
		"Safe mode "
		+ (mCurrentStatus == VCN_STATUS_CODE_SAFE_MODE ? "entered" : "exited"));
		}
		}

		private void handleNetworkRequested(@NonNull NetworkRequest request) {
		if (VDBG) {
		Slog.v(getLogTag(), "Received request " + request);
		}

		// If preexisting VcnGatewayConnection(s) satisfy request, return
		for (VcnGatewayConnectionConfig gatewayConnectionConfig : mVcnGatewayConnections.keySet()) {
		if (isRequestSatisfiedByGatewayConnectionConfig(request, gatewayConnectionConfig)) {
		if (VDBG) {
		Slog.v(
		Slog.d(
		getLogTag(),
		"Request already satisfied by existing VcnGatewayConnection: "
		+ request);
		}
		"Request already satisfied by existing VcnGatewayConnection: " + request);
		return;
		}
		}
		@@ -389,7 +396,7 @@ public class Vcn extends Handler {
		for (VcnGatewayConnectionConfig gatewayConnectionConfig :
		mConfig.getGatewayConnectionConfigs()) {
		if (isRequestSatisfiedByGatewayConnectionConfig(request, gatewayConnectionConfig)) {
		Slog.v(getLogTag(), "Bringing up new VcnGatewayConnection for request " + request);
		Slog.d(getLogTag(), "Bringing up new VcnGatewayConnection for request " + request);

		if (getExposedCapabilitiesForMobileDataState(gatewayConnectionConfig).isEmpty()) {
		// Skip; this network does not provide any services if mobile data is disabled.
		@@ -414,7 +421,13 @@ public class Vcn extends Handler {
		new VcnGatewayStatusCallbackImpl(gatewayConnectionConfig),
		mIsMobileDataEnabled);
		mVcnGatewayConnections.put(gatewayConnectionConfig, vcnGatewayConnection);

		return;
		}
		}

		if (VDBG) {
		Slog.v(getLogTag(), "Request could not be fulfilled by VCN: " + request);
		}
		}

		@@ -432,7 +445,7 @@ public class Vcn extends Handler {
		}

		private void handleGatewayConnectionQuit(VcnGatewayConnectionConfig config) {
		Slog.v(getLogTag(), "VcnGatewayConnection quit: " + config);
		Slog.d(getLogTag(), "VcnGatewayConnection quit: " + config);
		mVcnGatewayConnections.remove(config);

		// Trigger a re-evaluation of all NetworkRequests (to make sure any that can be satisfied
		@@ -479,6 +492,8 @@ public class Vcn extends Handler {

		// Trigger re-evaluation of all requests; mobile data state impacts supported caps.
		mVcnContext.getVcnNetworkProvider().resendAllRequests(mRequestListener);

		Slog.d(getLogTag(), "Mobile data " + (mIsMobileDataEnabled ? "enabled" : "disabled"));
		}
		}

		@@ -521,6 +536,7 @@ public class Vcn extends Handler {
		pw.increaseIndent();

		pw.println("mCurrentStatus: " + mCurrentStatus);
		pw.println("mIsMobileDataEnabled: " + mIsMobileDataEnabled);

		pw.println("mVcnGatewayConnections:");
		for (VcnGatewayConnection gw : mVcnGatewayConnections.values()) {

services/core/java/com/android/server/vcn/VcnGatewayConnection.java

+77 −3

Original line number	Diff line number	Diff line
		@@ -701,6 +701,7 @@ public class VcnGatewayConnection extends StateMachine {
		* <p>Once torn down, this VcnTunnel CANNOT be started again.
		*/
		public void teardownAsynchronously() {
		Slog.d(TAG, "Triggering async teardown");
		sendDisconnectRequestedAndAcquireWakelock(
		DISCONNECT_REASON_TEARDOWN, true /* shouldQuit */);

		@@ -710,6 +711,8 @@ public class VcnGatewayConnection extends StateMachine {

		@Override
		protected void onQuitting() {
		Slog.d(TAG, "Quitting VcnGatewayConnection");

		// No need to call setInterfaceDown(); the IpSecInterface is being fully torn down.
		if (mTunnelIface != null) {
		mTunnelIface.close();
		@@ -750,6 +753,11 @@ public class VcnGatewayConnection extends StateMachine {
		// TODO(b/180132994): explore safely removing this Thread check
		mVcnContext.ensureRunningOnLooperThread();

		Slog.d(
		TAG,
		"Selected underlying network changed: "
		+ (underlying == null ? null : underlying.network));

		// TODO(b/179091925): Move the delayed-message handling to BaseState

		// If underlying is null, all underlying networks have been lost. Disconnect VCN after a
		@@ -774,6 +782,10 @@ public class VcnGatewayConnection extends StateMachine {

		if (!mIsQuitting) {
		mWakeLock.acquire();

		if (VDBG) {
		Slog.v(TAG, "Wakelock acquired: " + mWakeLock);
		}
		}
		}

		@@ -781,6 +793,10 @@ public class VcnGatewayConnection extends StateMachine {
		mVcnContext.ensureRunningOnLooperThread();

		mWakeLock.release();

		if (VDBG) {
		Slog.v(TAG, "Wakelock released: " + mWakeLock);
		}
		}

		/**
		@@ -935,10 +951,17 @@ public class VcnGatewayConnection extends StateMachine {
		}

		private void setTeardownTimeoutAlarm() {
		if (VDBG) {
		Slog.v(TAG, "Setting teardown timeout alarm; mCurrentToken: " + mCurrentToken);
		}

		// Safe to assign this alarm because it is either 1) already null, or 2) already fired. In
		// either case, there is nothing to cancel.
		if (mTeardownTimeoutAlarm != null) {
		Slog.wtf(TAG, "mTeardownTimeoutAlarm should be null before being set");
		Slog.wtf(
		TAG,
		"mTeardownTimeoutAlarm should be null before being set; mCurrentToken: "
		+ mCurrentToken);
		}

		final Message delayedMessage = obtainMessage(EVENT_TEARDOWN_TIMEOUT_EXPIRED, mCurrentToken);
		@@ -950,6 +973,10 @@ public class VcnGatewayConnection extends StateMachine {
		}

		private void cancelTeardownTimeoutAlarm() {
		if (VDBG) {
		Slog.v(TAG, "Cancelling teardown timeout alarm; mCurrentToken: " + mCurrentToken);
		}

		if (mTeardownTimeoutAlarm != null) {
		mTeardownTimeoutAlarm.cancel();
		mTeardownTimeoutAlarm = null;
		@@ -960,6 +987,13 @@ public class VcnGatewayConnection extends StateMachine {
		}

		private void setDisconnectRequestAlarm() {
		if (VDBG) {
		Slog.v(
		TAG,
		"Setting alarm to disconnect due to underlying network loss; mCurrentToken: "
		+ mCurrentToken);
		}

		// Only schedule a NEW alarm if none is already set.
		if (mDisconnectRequestAlarm != null) {
		return;
		@@ -980,6 +1014,13 @@ public class VcnGatewayConnection extends StateMachine {
		}

		private void cancelDisconnectRequestAlarm() {
		if (VDBG) {
		Slog.v(
		TAG,
		"Cancelling alarm to disconnect due to underlying network loss; mCurrentToken: "
		+ mCurrentToken);
		}

		if (mDisconnectRequestAlarm != null) {
		mDisconnectRequestAlarm.cancel();
		mDisconnectRequestAlarm = null;
		@@ -993,10 +1034,17 @@ public class VcnGatewayConnection extends StateMachine {
		}

		private void setRetryTimeoutAlarm(long delay) {
		if (VDBG) {
		Slog.v(TAG, "Setting retry alarm; mCurrentToken: " + mCurrentToken);
		}

		// Safe to assign this alarm because it is either 1) already null, or 2) already fired. In
		// either case, there is nothing to cancel.
		if (mRetryTimeoutAlarm != null) {
		Slog.wtf(TAG, "mRetryTimeoutAlarm should be null before being set");
		Slog.wtf(
		TAG,
		"mRetryTimeoutAlarm should be null before being set; mCurrentToken: "
		+ mCurrentToken);
		}

		final Message delayedMessage = obtainMessage(EVENT_RETRY_TIMEOUT_EXPIRED, mCurrentToken);
		@@ -1004,6 +1052,10 @@ public class VcnGatewayConnection extends StateMachine {
		}

		private void cancelRetryTimeoutAlarm() {
		if (VDBG) {
		Slog.v(TAG, "Cancel retry alarm; mCurrentToken: " + mCurrentToken);
		}

		if (mRetryTimeoutAlarm != null) {
		mRetryTimeoutAlarm.cancel();
		mRetryTimeoutAlarm = null;
		@@ -1014,6 +1066,10 @@ public class VcnGatewayConnection extends StateMachine {

		@VisibleForTesting(visibility = Visibility.PRIVATE)
		void setSafeModeAlarm() {
		if (VDBG) {
		Slog.v(TAG, "Setting safe mode alarm; mCurrentToken: " + mCurrentToken);
		}

		// Only schedule a NEW alarm if none is already set.
		if (mSafeModeTimeoutAlarm != null) {
		return;
		@@ -1028,6 +1084,10 @@ public class VcnGatewayConnection extends StateMachine {
		}

		private void cancelSafeModeAlarm() {
		if (VDBG) {
		Slog.v(TAG, "Cancel safe mode alarm; mCurrentToken: " + mCurrentToken);
		}

		if (mSafeModeTimeoutAlarm != null) {
		mSafeModeTimeoutAlarm.cancel();
		mSafeModeTimeoutAlarm = null;
		@@ -1092,6 +1152,15 @@ public class VcnGatewayConnection extends StateMachine {
		+ exception.getMessage();
		}

		Slog.d(
		TAG,
		"Encountered error; code="
		+ errorCode
		+ ", exceptionClass="
		+ exceptionClass
		+ ", exceptionMessage="
		+ exceptionMessage);

		mGatewayStatusCallback.onGatewayConnectionError(
		mConnectionConfig.getGatewayConnectionName(),
		errorCode,
		@@ -1234,7 +1303,7 @@ public class VcnGatewayConnection extends StateMachine {
		protected void handleDisconnectRequested(EventDisconnectRequestedInfo info) {
		// TODO(b/180526152): notify VcnStatusCallback for Network loss

		Slog.v(TAG, "Tearing down. Cause: " + info.reason);
		Slog.d(TAG, "Tearing down. Cause: " + info.reason);
		mIsQuitting = info.shouldQuit;

		teardownNetwork();
		@@ -1250,6 +1319,7 @@ public class VcnGatewayConnection extends StateMachine {

		protected void handleSafeModeTimeoutExceeded() {
		mSafeModeTimeoutAlarm = null;
		Slog.d(TAG, "Entering safe mode after timeout exceeded");

		// Connectivity for this GatewayConnection is broken; tear down the Network.
		teardownNetwork();
		@@ -1722,6 +1792,8 @@ public class VcnGatewayConnection extends StateMachine {
		}

		private void handleMigrationCompleted(EventMigrationCompletedInfo migrationCompletedInfo) {
		Slog.v(TAG, "Migration completed: " + mUnderlying.network);

		applyTransform(
		mCurrentToken,
		mTunnelIface,
		@@ -1744,6 +1816,8 @@ public class VcnGatewayConnection extends StateMachine {
		mUnderlying = ((EventUnderlyingNetworkChangedInfo) msg.obj).newUnderlying;

		if (mUnderlying == null) {
		Slog.v(TAG, "Underlying network lost");

		// Ignored for now; a new network may be coming up. If none does, the delayed
		// NETWORK_LOST disconnect will be fired, and tear down the session + network.
		return;