Android/frameworks_base
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

Merge "Add log prefixes to uniquely identify each VCN/gwConn" am: fae9ba6535

Browse Source 
Original change: https://android-review.googlesource.com/c/platform/frameworks/base/+/1700307

Change-Id: I7096daeb9d45dcedbebf5c95b9c681c1e1c78935
This commit is contained in:
Benedict Wong
2021-05-11 05:37:35 +00:00
committed by Automerger Merge Worker
parent f980436b32 fae9ba6535
commit af9b507963
3 changed files with 190 additions and 121 deletions
Download Patch File Download Diff File Expand all files Collapse all files

78
services/core/java/com/android/server/vcn/Vcn.java
View File

@@ -50,6 +50,7 @@ import com.android.internal.annotations.VisibleForTesting.Visibility;
import com.android.internal.util.IndentingPrintWriter; import com.android.internal.util.IndentingPrintWriter;
import com.android.server.VcnManagementService.VcnCallback; import com.android.server.VcnManagementService.VcnCallback;
import com.android.server.vcn.TelephonySubscriptionTracker.TelephonySubscriptionSnapshot; import com.android.server.vcn.TelephonySubscriptionTracker.TelephonySubscriptionSnapshot;
import com.android.server.vcn.util.LogUtils;
import java.util.Arrays; import java.util.Arrays;
import java.util.Collections; import java.util.Collections;
@@ -305,15 +306,13 @@ public class Vcn extends Handler {
handleTeardown(); handleTeardown();
break; break;
default: default:
Slog.wtf(getLogTag(), "Unknown msg.what: " + msg.what); logWtf("Unknown msg.what: " + msg.what);
} }
} }
private void handleConfigUpdated(@NonNull VcnConfig config) { private void handleConfigUpdated(@NonNull VcnConfig config) {
// TODO: Add a dump function in VcnConfig that omits PII. Until then, use hashCode() // TODO: Add a dump function in VcnConfig that omits PII. Until then, use hashCode()
Slog.d( logDbg("Config updated: old = " + mConfig.hashCode() + "; new = " + config.hashCode());
getLogTag(),
"Config updated: old = " + mConfig.hashCode() + "; new = " + config.hashCode());
mConfig = config; mConfig = config;
@@ -328,8 +327,7 @@ public class Vcn extends Handler {
// connection details may have changed). // connection details may have changed).
if (!mConfig.getGatewayConnectionConfigs().contains(gatewayConnectionConfig)) { if (!mConfig.getGatewayConnectionConfigs().contains(gatewayConnectionConfig)) {
if (gatewayConnection == null) { if (gatewayConnection == null) {
Slog.wtf( logWtf("Found gatewayConnectionConfig without GatewayConnection");
getLogTag(), "Found gatewayConnectionConfig without GatewayConnection");
} else { } else {
gatewayConnection.teardownAsynchronously(); gatewayConnection.teardownAsynchronously();
} }
@@ -342,7 +340,7 @@ public class Vcn extends Handler {
} }
private void handleTeardown() { private void handleTeardown() {
Slog.d(getLogTag(), "Tearing down"); logDbg("Tearing down");
mVcnContext.getVcnNetworkProvider().unregisterListener(mRequestListener); mVcnContext.getVcnNetworkProvider().unregisterListener(mRequestListener);
for (VcnGatewayConnection gatewayConnection : mVcnGatewayConnections.values()) { for (VcnGatewayConnection gatewayConnection : mVcnGatewayConnections.values()) {
@@ -353,7 +351,7 @@ public class Vcn extends Handler {
} }
private void handleSafeModeStatusChanged() { private void handleSafeModeStatusChanged() {
Slog.d(getLogTag(), "VcnGatewayConnection safe mode status changed"); logDbg("VcnGatewayConnection safe mode status changed");
boolean hasSafeModeGatewayConnection = false; boolean hasSafeModeGatewayConnection = false;
// If any VcnGatewayConnection is in safe mode, mark the entire VCN as being in safe mode // If any VcnGatewayConnection is in safe mode, mark the entire VCN as being in safe mode
@@ -369,24 +367,19 @@ public class Vcn extends Handler {
hasSafeModeGatewayConnection ? VCN_STATUS_CODE_SAFE_MODE : VCN_STATUS_CODE_ACTIVE; hasSafeModeGatewayConnection ? VCN_STATUS_CODE_SAFE_MODE : VCN_STATUS_CODE_ACTIVE;
if (oldStatus != mCurrentStatus) { if (oldStatus != mCurrentStatus) {
mVcnCallback.onSafeModeStatusChanged(hasSafeModeGatewayConnection); mVcnCallback.onSafeModeStatusChanged(hasSafeModeGatewayConnection);
Slog.d( logDbg(
getLogTag(),
"Safe mode " "Safe mode "
+ (mCurrentStatus == VCN_STATUS_CODE_SAFE_MODE ? "entered" : "exited")); + (mCurrentStatus == VCN_STATUS_CODE_SAFE_MODE ? "entered" : "exited"));
} }
} }
private void handleNetworkRequested(@NonNull NetworkRequest request) { private void handleNetworkRequested(@NonNull NetworkRequest request) {
if (VDBG) { logVdbg("Received request " + request);
Slog.v(getLogTag(), "Received request " + request);
}
// If preexisting VcnGatewayConnection(s) satisfy request, return // If preexisting VcnGatewayConnection(s) satisfy request, return
for (VcnGatewayConnectionConfig gatewayConnectionConfig : mVcnGatewayConnections.keySet()) { for (VcnGatewayConnectionConfig gatewayConnectionConfig : mVcnGatewayConnections.keySet()) {
if (isRequestSatisfiedByGatewayConnectionConfig(request, gatewayConnectionConfig)) { if (isRequestSatisfiedByGatewayConnectionConfig(request, gatewayConnectionConfig)) {
Slog.d( logDbg("Request already satisfied by existing VcnGatewayConnection: " + request);
getLogTag(),
"Request already satisfied by existing VcnGatewayConnection: " + request);
return; return;
} }
} }
@@ -396,7 +389,7 @@ public class Vcn extends Handler {
for (VcnGatewayConnectionConfig gatewayConnectionConfig : for (VcnGatewayConnectionConfig gatewayConnectionConfig :
mConfig.getGatewayConnectionConfigs()) { mConfig.getGatewayConnectionConfigs()) {
if (isRequestSatisfiedByGatewayConnectionConfig(request, gatewayConnectionConfig)) { if (isRequestSatisfiedByGatewayConnectionConfig(request, gatewayConnectionConfig)) {
Slog.d(getLogTag(), "Bringing up new VcnGatewayConnection for request " + request); logDbg("Bringing up new VcnGatewayConnection for request " + request);
if (getExposedCapabilitiesForMobileDataState(gatewayConnectionConfig).isEmpty()) { if (getExposedCapabilitiesForMobileDataState(gatewayConnectionConfig).isEmpty()) {
// Skip; this network does not provide any services if mobile data is disabled. // Skip; this network does not provide any services if mobile data is disabled.
@@ -407,8 +400,9 @@ public class Vcn extends Handler {
// pre-existing VcnGatewayConnections that satisfy a given request, but if state // pre-existing VcnGatewayConnections that satisfy a given request, but if state
// that affects the satsifying of requests changes, this is theoretically possible. // that affects the satsifying of requests changes, this is theoretically possible.
if (mVcnGatewayConnections.containsKey(gatewayConnectionConfig)) { if (mVcnGatewayConnections.containsKey(gatewayConnectionConfig)) {
Slog.wtf(getLogTag(), "Attempted to bring up VcnGatewayConnection for config " logWtf(
+ "with existing VcnGatewayConnection"); "Attempted to bring up VcnGatewayConnection for config "
+ "with existing VcnGatewayConnection");
return; return;
} }
@@ -426,9 +420,7 @@ public class Vcn extends Handler {
} }
} }
if (VDBG) { logVdbg("Request could not be fulfilled by VCN: " + request);
Slog.v(getLogTag(), "Request could not be fulfilled by VCN: " + request);
}
} }
private Set<Integer> getExposedCapabilitiesForMobileDataState( private Set<Integer> getExposedCapabilitiesForMobileDataState(
@@ -445,7 +437,7 @@ public class Vcn extends Handler {
} }
private void handleGatewayConnectionQuit(VcnGatewayConnectionConfig config) { private void handleGatewayConnectionQuit(VcnGatewayConnectionConfig config) {
Slog.d(getLogTag(), "VcnGatewayConnection quit: " + config); logDbg("VcnGatewayConnection quit: " + config);
mVcnGatewayConnections.remove(config); mVcnGatewayConnections.remove(config);
// Trigger a re-evaluation of all NetworkRequests (to make sure any that can be satisfied // Trigger a re-evaluation of all NetworkRequests (to make sure any that can be satisfied
@@ -480,9 +472,7 @@ public class Vcn extends Handler {
if (exposedCaps.contains(NET_CAPABILITY_INTERNET) if (exposedCaps.contains(NET_CAPABILITY_INTERNET)
|| exposedCaps.contains(NET_CAPABILITY_DUN)) { || exposedCaps.contains(NET_CAPABILITY_DUN)) {
if (gatewayConnection == null) { if (gatewayConnection == null) {
Slog.wtf( logWtf("Found gatewayConnectionConfig without" + " GatewayConnection");
getLogTag(),
"Found gatewayConnectionConfig without GatewayConnection");
} else { } else {
// TODO(b/184868850): Optimize by restarting NetworkAgents without teardown. // TODO(b/184868850): Optimize by restarting NetworkAgents without teardown.
gatewayConnection.teardownAsynchronously(); gatewayConnection.teardownAsynchronously();
@@ -493,7 +483,7 @@ public class Vcn extends Handler {
// Trigger re-evaluation of all requests; mobile data state impacts supported caps. // Trigger re-evaluation of all requests; mobile data state impacts supported caps.
mVcnContext.getVcnNetworkProvider().resendAllRequests(mRequestListener); mVcnContext.getVcnNetworkProvider().resendAllRequests(mRequestListener);
Slog.d(getLogTag(), "Mobile data " + (mIsMobileDataEnabled ? "enabled" : "disabled")); logDbg("Mobile data " + (mIsMobileDataEnabled ? "enabled" : "disabled"));
} }
} }
@@ -522,8 +512,38 @@ public class Vcn extends Handler {
return request.canBeSatisfiedBy(builder.build()); return request.canBeSatisfiedBy(builder.build());
} }
private String getLogTag() { private String getLogPrefix() {
return TAG + " [" + mSubscriptionGroup.hashCode() + "]"; return "[" + LogUtils.getHashedSubscriptionGroup(mSubscriptionGroup) + "]: ";
}
private void logVdbg(String msg) {
if (VDBG) {
Slog.v(TAG, getLogPrefix() + msg);
}
}
private void logDbg(String msg) {
Slog.d(TAG, getLogPrefix() + msg);
}
private void logDbg(String msg, Throwable tr) {
Slog.d(TAG, getLogPrefix() + msg, tr);
}
private void logErr(String msg) {
Slog.e(TAG, getLogPrefix() + msg);
}
private void logErr(String msg, Throwable tr) {
Slog.e(TAG, getLogPrefix() + msg, tr);
}
private void logWtf(String msg) {
Slog.wtf(TAG, getLogPrefix() + msg);
}
private void logWtf(String msg, Throwable tr) {
Slog.wtf(TAG, getLogPrefix() + msg, tr);
} }
/** /**

194
services/core/java/com/android/server/vcn/VcnGatewayConnection.java
View File

@@ -88,6 +88,7 @@ import com.android.server.vcn.TelephonySubscriptionTracker.TelephonySubscription
import com.android.server.vcn.UnderlyingNetworkTracker.UnderlyingNetworkRecord; import com.android.server.vcn.UnderlyingNetworkTracker.UnderlyingNetworkRecord;
import com.android.server.vcn.UnderlyingNetworkTracker.UnderlyingNetworkTrackerCallback; import com.android.server.vcn.UnderlyingNetworkTracker.UnderlyingNetworkTrackerCallback;
import com.android.server.vcn.Vcn.VcnGatewayStatusCallback; import com.android.server.vcn.Vcn.VcnGatewayStatusCallback;
import com.android.server.vcn.util.LogUtils;
import com.android.server.vcn.util.MtuUtils; import com.android.server.vcn.util.MtuUtils;
import java.io.IOException; import java.io.IOException;
@@ -701,7 +702,7 @@ public class VcnGatewayConnection extends StateMachine {
* <p>Once torn down, this VcnTunnel CANNOT be started again. * <p>Once torn down, this VcnTunnel CANNOT be started again.
*/ */
public void teardownAsynchronously() { public void teardownAsynchronously() {
Slog.d(TAG, "Triggering async teardown"); logDbg("Triggering async teardown");
sendDisconnectRequestedAndAcquireWakelock( sendDisconnectRequestedAndAcquireWakelock(
DISCONNECT_REASON_TEARDOWN, true /* shouldQuit */); DISCONNECT_REASON_TEARDOWN, true /* shouldQuit */);
@@ -711,7 +712,7 @@ public class VcnGatewayConnection extends StateMachine {
@Override @Override
protected void onQuitting() { protected void onQuitting() {
Slog.d(TAG, "Quitting VcnGatewayConnection"); logDbg("Quitting VcnGatewayConnection");
// No need to call setInterfaceDown(); the IpSecInterface is being fully torn down. // No need to call setInterfaceDown(); the IpSecInterface is being fully torn down.
if (mTunnelIface != null) { if (mTunnelIface != null) {
@@ -753,8 +754,7 @@ public class VcnGatewayConnection extends StateMachine {
// TODO(b/180132994): explore safely removing this Thread check // TODO(b/180132994): explore safely removing this Thread check
mVcnContext.ensureRunningOnLooperThread(); mVcnContext.ensureRunningOnLooperThread();
Slog.d( logDbg(
TAG,
"Selected underlying network changed: " "Selected underlying network changed: "
+ (underlying == null ? null : underlying.network)); + (underlying == null ? null : underlying.network));
@@ -783,9 +783,7 @@ public class VcnGatewayConnection extends StateMachine {
if (!mIsQuitting) { if (!mIsQuitting) {
mWakeLock.acquire(); mWakeLock.acquire();
if (VDBG) { logVdbg("Wakelock acquired: " + mWakeLock);
Slog.v(TAG, "Wakelock acquired: " + mWakeLock);
}
} }
} }
@@ -794,9 +792,7 @@ public class VcnGatewayConnection extends StateMachine {
mWakeLock.release(); mWakeLock.release();
if (VDBG) { logVdbg("Wakelock released: " + mWakeLock);
Slog.v(TAG, "Wakelock released: " + mWakeLock);
}
} }
/** /**
@@ -814,8 +810,7 @@ public class VcnGatewayConnection extends StateMachine {
@Override @Override
public void sendMessage(int what) { public void sendMessage(int what) {
Slog.wtf( logWtf(
TAG,
"sendMessage should not be used in VcnGatewayConnection. See" "sendMessage should not be used in VcnGatewayConnection. See"
+ " sendMessageAndAcquireWakeLock()"); + " sendMessageAndAcquireWakeLock()");
super.sendMessage(what); super.sendMessage(what);
@@ -823,8 +818,7 @@ public class VcnGatewayConnection extends StateMachine {
@Override @Override
public void sendMessage(int what, Object obj) { public void sendMessage(int what, Object obj) {
Slog.wtf( logWtf(
TAG,
"sendMessage should not be used in VcnGatewayConnection. See" "sendMessage should not be used in VcnGatewayConnection. See"
+ " sendMessageAndAcquireWakeLock()"); + " sendMessageAndAcquireWakeLock()");
super.sendMessage(what, obj); super.sendMessage(what, obj);
@@ -832,8 +826,7 @@ public class VcnGatewayConnection extends StateMachine {
@Override @Override
public void sendMessage(int what, int arg1) { public void sendMessage(int what, int arg1) {
Slog.wtf( logWtf(
TAG,
"sendMessage should not be used in VcnGatewayConnection. See" "sendMessage should not be used in VcnGatewayConnection. See"
+ " sendMessageAndAcquireWakeLock()"); + " sendMessageAndAcquireWakeLock()");
super.sendMessage(what, arg1); super.sendMessage(what, arg1);
@@ -841,8 +834,7 @@ public class VcnGatewayConnection extends StateMachine {
@Override @Override
public void sendMessage(int what, int arg1, int arg2) { public void sendMessage(int what, int arg1, int arg2) {
Slog.wtf( logWtf(
TAG,
"sendMessage should not be used in VcnGatewayConnection. See" "sendMessage should not be used in VcnGatewayConnection. See"
+ " sendMessageAndAcquireWakeLock()"); + " sendMessageAndAcquireWakeLock()");
super.sendMessage(what, arg1, arg2); super.sendMessage(what, arg1, arg2);
@@ -850,8 +842,7 @@ public class VcnGatewayConnection extends StateMachine {
@Override @Override
public void sendMessage(int what, int arg1, int arg2, Object obj) { public void sendMessage(int what, int arg1, int arg2, Object obj) {
Slog.wtf( logWtf(
TAG,
"sendMessage should not be used in VcnGatewayConnection. See" "sendMessage should not be used in VcnGatewayConnection. See"
+ " sendMessageAndAcquireWakeLock()"); + " sendMessageAndAcquireWakeLock()");
super.sendMessage(what, arg1, arg2, obj); super.sendMessage(what, arg1, arg2, obj);
@@ -859,8 +850,7 @@ public class VcnGatewayConnection extends StateMachine {
@Override @Override
public void sendMessage(Message msg) { public void sendMessage(Message msg) {
Slog.wtf( logWtf(
TAG,
"sendMessage should not be used in VcnGatewayConnection. See" "sendMessage should not be used in VcnGatewayConnection. See"
+ " sendMessageAndAcquireWakeLock()"); + " sendMessageAndAcquireWakeLock()");
super.sendMessage(msg); super.sendMessage(msg);
@@ -951,15 +941,12 @@ public class VcnGatewayConnection extends StateMachine {
} }
private void setTeardownTimeoutAlarm() { private void setTeardownTimeoutAlarm() {
if (VDBG) { logVdbg("Setting teardown timeout alarm; mCurrentToken: " + mCurrentToken);
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 // Safe to assign this alarm because it is either 1) already null, or 2) already fired. In
// either case, there is nothing to cancel. // either case, there is nothing to cancel.
if (mTeardownTimeoutAlarm != null) { if (mTeardownTimeoutAlarm != null) {
Slog.wtf( logWtf(
TAG,
"mTeardownTimeoutAlarm should be null before being set; mCurrentToken: " "mTeardownTimeoutAlarm should be null before being set; mCurrentToken: "
+ mCurrentToken); + mCurrentToken);
} }
@@ -973,9 +960,7 @@ public class VcnGatewayConnection extends StateMachine {
} }
private void cancelTeardownTimeoutAlarm() { private void cancelTeardownTimeoutAlarm() {
if (VDBG) { logVdbg("Cancelling teardown timeout alarm; mCurrentToken: " + mCurrentToken);
Slog.v(TAG, "Cancelling teardown timeout alarm; mCurrentToken: " + mCurrentToken);
}
if (mTeardownTimeoutAlarm != null) { if (mTeardownTimeoutAlarm != null) {
mTeardownTimeoutAlarm.cancel(); mTeardownTimeoutAlarm.cancel();
@@ -987,12 +972,10 @@ public class VcnGatewayConnection extends StateMachine {
} }
private void setDisconnectRequestAlarm() { private void setDisconnectRequestAlarm() {
if (VDBG) { logVdbg(
Slog.v( "Setting alarm to disconnect due to underlying network loss;"
TAG, + " mCurrentToken: "
"Setting alarm to disconnect due to underlying network loss; mCurrentToken: " + mCurrentToken);
+ mCurrentToken);
}
// Only schedule a NEW alarm if none is already set. // Only schedule a NEW alarm if none is already set.
if (mDisconnectRequestAlarm != null) { if (mDisconnectRequestAlarm != null) {
@@ -1014,12 +997,10 @@ public class VcnGatewayConnection extends StateMachine {
} }
private void cancelDisconnectRequestAlarm() { private void cancelDisconnectRequestAlarm() {
if (VDBG) { logVdbg(
Slog.v( "Cancelling alarm to disconnect due to underlying network loss;"
TAG, + " mCurrentToken: "
"Cancelling alarm to disconnect due to underlying network loss; mCurrentToken: " + mCurrentToken);
+ mCurrentToken);
}
if (mDisconnectRequestAlarm != null) { if (mDisconnectRequestAlarm != null) {
mDisconnectRequestAlarm.cancel(); mDisconnectRequestAlarm.cancel();
@@ -1034,15 +1015,12 @@ public class VcnGatewayConnection extends StateMachine {
} }
private void setRetryTimeoutAlarm(long delay) { private void setRetryTimeoutAlarm(long delay) {
if (VDBG) { logVdbg("Setting retry alarm; mCurrentToken: " + mCurrentToken);
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 // Safe to assign this alarm because it is either 1) already null, or 2) already fired. In
// either case, there is nothing to cancel. // either case, there is nothing to cancel.
if (mRetryTimeoutAlarm != null) { if (mRetryTimeoutAlarm != null) {
Slog.wtf( logWtf(
TAG,
"mRetryTimeoutAlarm should be null before being set; mCurrentToken: " "mRetryTimeoutAlarm should be null before being set; mCurrentToken: "
+ mCurrentToken); + mCurrentToken);
} }
@@ -1052,9 +1030,7 @@ public class VcnGatewayConnection extends StateMachine {
} }
private void cancelRetryTimeoutAlarm() { private void cancelRetryTimeoutAlarm() {
if (VDBG) { logVdbg("Cancel retry alarm; mCurrentToken: " + mCurrentToken);
Slog.v(TAG, "Cancel retry alarm; mCurrentToken: " + mCurrentToken);
}
if (mRetryTimeoutAlarm != null) { if (mRetryTimeoutAlarm != null) {
mRetryTimeoutAlarm.cancel(); mRetryTimeoutAlarm.cancel();
@@ -1066,9 +1042,7 @@ public class VcnGatewayConnection extends StateMachine {
@VisibleForTesting(visibility = Visibility.PRIVATE) @VisibleForTesting(visibility = Visibility.PRIVATE)
void setSafeModeAlarm() { void setSafeModeAlarm() {
if (VDBG) { logVdbg("Setting safe mode alarm; mCurrentToken: " + mCurrentToken);
Slog.v(TAG, "Setting safe mode alarm; mCurrentToken: " + mCurrentToken);
}
// Only schedule a NEW alarm if none is already set. // Only schedule a NEW alarm if none is already set.
if (mSafeModeTimeoutAlarm != null) { if (mSafeModeTimeoutAlarm != null) {
@@ -1084,9 +1058,7 @@ public class VcnGatewayConnection extends StateMachine {
} }
private void cancelSafeModeAlarm() { private void cancelSafeModeAlarm() {
if (VDBG) { logVdbg("Cancel safe mode alarm; mCurrentToken: " + mCurrentToken);
Slog.v(TAG, "Cancel safe mode alarm; mCurrentToken: " + mCurrentToken);
}
if (mSafeModeTimeoutAlarm != null) { if (mSafeModeTimeoutAlarm != null) {
mSafeModeTimeoutAlarm.cancel(); mSafeModeTimeoutAlarm.cancel();
@@ -1152,8 +1124,7 @@ public class VcnGatewayConnection extends StateMachine {
+ exception.getMessage(); + exception.getMessage();
} }
Slog.d( logDbg(
TAG,
"Encountered error; code=" "Encountered error; code="
+ errorCode + errorCode
+ ", exceptionClass=" + ", exceptionClass="
@@ -1206,7 +1177,7 @@ public class VcnGatewayConnection extends StateMachine {
try { try {
enterState(); enterState();
} catch (Exception e) { } catch (Exception e) {
Slog.wtf(TAG, "Uncaught exception", e); logWtf("Uncaught exception", e);
sendDisconnectRequestedAndAcquireWakelock( sendDisconnectRequestedAndAcquireWakelock(
DISCONNECT_REASON_INTERNAL_ERROR + e.toString(), true /* shouldQuit */); DISCONNECT_REASON_INTERNAL_ERROR + e.toString(), true /* shouldQuit */);
} }
@@ -1238,14 +1209,14 @@ public class VcnGatewayConnection extends StateMachine {
public final boolean processMessage(Message msg) { public final boolean processMessage(Message msg) {
final int token = msg.arg1; final int token = msg.arg1;
if (!isValidToken(token)) { if (!isValidToken(token)) {
Slog.v(TAG, "Message called with obsolete token: " + token + "; what: " + msg.what); logDbg("Message called with obsolete token: " + token + "; what: " + msg.what);
return HANDLED; return HANDLED;
} }
try { try {
processStateMsg(msg); processStateMsg(msg);
} catch (Exception e) { } catch (Exception e) {
Slog.wtf(TAG, "Uncaught exception", e); logWtf("Uncaught exception", e);
sendDisconnectRequestedAndAcquireWakelock( sendDisconnectRequestedAndAcquireWakelock(
DISCONNECT_REASON_INTERNAL_ERROR + e.toString(), true /* shouldQuit */); DISCONNECT_REASON_INTERNAL_ERROR + e.toString(), true /* shouldQuit */);
} }
@@ -1263,7 +1234,7 @@ public class VcnGatewayConnection extends StateMachine {
try { try {
exitState(); exitState();
} catch (Exception e) { } catch (Exception e) {
Slog.wtf(TAG, "Uncaught exception", e); logWtf("Uncaught exception", e);
sendDisconnectRequestedAndAcquireWakelock( sendDisconnectRequestedAndAcquireWakelock(
DISCONNECT_REASON_INTERNAL_ERROR + e.toString(), true /* shouldQuit */); DISCONNECT_REASON_INTERNAL_ERROR + e.toString(), true /* shouldQuit */);
} }
@@ -1303,7 +1274,7 @@ public class VcnGatewayConnection extends StateMachine {
protected void handleDisconnectRequested(EventDisconnectRequestedInfo info) { protected void handleDisconnectRequested(EventDisconnectRequestedInfo info) {
// TODO(b/180526152): notify VcnStatusCallback for Network loss // TODO(b/180526152): notify VcnStatusCallback for Network loss
Slog.d(TAG, "Tearing down. Cause: " + info.reason); logDbg("Tearing down. Cause: " + info.reason);
mIsQuitting = info.shouldQuit; mIsQuitting = info.shouldQuit;
teardownNetwork(); teardownNetwork();
@@ -1319,7 +1290,7 @@ public class VcnGatewayConnection extends StateMachine {
protected void handleSafeModeTimeoutExceeded() { protected void handleSafeModeTimeoutExceeded() {
mSafeModeTimeoutAlarm = null; mSafeModeTimeoutAlarm = null;
Slog.d(TAG, "Entering safe mode after timeout exceeded"); logDbg("Entering safe mode after timeout exceeded");
// Connectivity for this GatewayConnection is broken; tear down the Network. // Connectivity for this GatewayConnection is broken; tear down the Network.
teardownNetwork(); teardownNetwork();
@@ -1328,13 +1299,15 @@ public class VcnGatewayConnection extends StateMachine {
} }
protected void logUnexpectedEvent(int what) { protected void logUnexpectedEvent(int what) {
Slog.d(TAG, String.format( logDbg(
"Unexpected event code %d in state %s", what, this.getClass().getSimpleName())); "Unexpected event code "
+ what
+ " in state "
+ this.getClass().getSimpleName());
} }
protected void logWtfUnknownEvent(int what) { protected void logWtfUnknownEvent(int what) {
Slog.wtf(TAG, String.format( logWtf("Unknown event code " + what + " in state " + this.getClass().getSimpleName());
"Unknown event code %d in state %s", what, this.getClass().getSimpleName()));
} }
} }
@@ -1351,7 +1324,7 @@ public class VcnGatewayConnection extends StateMachine {
} }
if (mIkeSession != null || mNetworkAgent != null) { if (mIkeSession != null || mNetworkAgent != null) {
Slog.wtf(TAG, "Active IKE Session or NetworkAgent in DisconnectedState"); logWtf("Active IKE Session or NetworkAgent in DisconnectedState");
} }
cancelSafeModeAlarm(); cancelSafeModeAlarm();
@@ -1419,7 +1392,7 @@ public class VcnGatewayConnection extends StateMachine {
@Override @Override
protected void enterState() throws Exception { protected void enterState() throws Exception {
if (mIkeSession == null) { if (mIkeSession == null) {
Slog.wtf(TAG, "IKE session was already closed when entering Disconnecting state."); logWtf("IKE session was already closed when entering Disconnecting state.");
sendMessageAndAcquireWakeLock(EVENT_SESSION_CLOSED, mCurrentToken); sendMessageAndAcquireWakeLock(EVENT_SESSION_CLOSED, mCurrentToken);
return; return;
} }
@@ -1506,7 +1479,7 @@ public class VcnGatewayConnection extends StateMachine {
@Override @Override
protected void enterState() { protected void enterState() {
if (mIkeSession != null) { if (mIkeSession != null) {
Slog.wtf(TAG, "ConnectingState entered with active session"); logWtf("ConnectingState entered with active session");
// Attempt to recover. // Attempt to recover.
mIkeSession.kill(); mIkeSession.kill();
@@ -1525,7 +1498,7 @@ public class VcnGatewayConnection extends StateMachine {
if (oldUnderlying == null) { if (oldUnderlying == null) {
// This should never happen, but if it does, there's likely a nasty bug. // This should never happen, but if it does, there's likely a nasty bug.
Slog.wtf(TAG, "Old underlying network was null in connected state. Bug?"); logWtf("Old underlying network was null in connected state. Bug?");
} }
// If new underlying is null, all underlying networks have been lost; disconnect // If new underlying is null, all underlying networks have been lost; disconnect
@@ -1620,11 +1593,11 @@ public class VcnGatewayConnection extends StateMachine {
// new NetworkAgent replaces an old one before the unwanted() call // new NetworkAgent replaces an old one before the unwanted() call
// is processed. // is processed.
if (mNetworkAgent != agentRef) { if (mNetworkAgent != agentRef) {
Slog.d(TAG, "unwanted() called on stale NetworkAgent"); logDbg("unwanted() called on stale NetworkAgent");
return; return;
} }
Slog.d(TAG, "NetworkAgent was unwanted"); logDbg("NetworkAgent was unwanted");
teardownAsynchronously(); teardownAsynchronously();
} /* networkUnwantedCallback */, } /* networkUnwantedCallback */,
(status) -> { (status) -> {
@@ -1638,8 +1611,7 @@ public class VcnGatewayConnection extends StateMachine {
setSafeModeAlarm(); setSafeModeAlarm();
break; break;
default: default:
Slog.wtf( logWtf(
TAG,
"Unknown validation status " "Unknown validation status "
+ status + status
+ "; ignoring"); + "; ignoring");
@@ -1691,7 +1663,7 @@ public class VcnGatewayConnection extends StateMachine {
tunnelIface, IpSecManager.DIRECTION_FWD, transform); tunnelIface, IpSecManager.DIRECTION_FWD, transform);
} }
} catch (IOException e) { } catch (IOException e) {
Slog.d(TAG, "Transform application failed for network " + token, e); logDbg("Transform application failed for network " + token, e);
sessionLost(token, e); sessionLost(token, e);
} }
} }
@@ -1725,7 +1697,7 @@ public class VcnGatewayConnection extends StateMachine {
tunnelIface.removeAddress(address.getAddress(), address.getPrefixLength()); tunnelIface.removeAddress(address.getAddress(), address.getPrefixLength());
} }
} catch (IOException e) { } catch (IOException e) {
Slog.d(TAG, "Adding address to tunnel failed for token " + token, e); logDbg("Adding address to tunnel failed for token " + token, e);
sessionLost(token, e); sessionLost(token, e);
} }
} }
@@ -1805,7 +1777,7 @@ public class VcnGatewayConnection extends StateMachine {
} }
private void handleMigrationCompleted(EventMigrationCompletedInfo migrationCompletedInfo) { private void handleMigrationCompleted(EventMigrationCompletedInfo migrationCompletedInfo) {
Slog.v(TAG, "Migration completed: " + mUnderlying.network); logDbg("Migration completed: " + mUnderlying.network);
applyTransform( applyTransform(
mCurrentToken, mCurrentToken,
@@ -1829,7 +1801,7 @@ public class VcnGatewayConnection extends StateMachine {
mUnderlying = ((EventUnderlyingNetworkChangedInfo) msg.obj).newUnderlying; mUnderlying = ((EventUnderlyingNetworkChangedInfo) msg.obj).newUnderlying;
if (mUnderlying == null) { if (mUnderlying == null) {
Slog.v(TAG, "Underlying network lost"); logDbg("Underlying network lost");
// Ignored for now; a new network may be coming up. If none does, the delayed // 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. // NETWORK_LOST disconnect will be fired, and tear down the session + network.
@@ -1839,7 +1811,7 @@ public class VcnGatewayConnection extends StateMachine {
// mUnderlying assumed non-null, given check above. // mUnderlying assumed non-null, given check above.
// If network changed, migrate. Otherwise, update any existing networkAgent. // If network changed, migrate. Otherwise, update any existing networkAgent.
if (oldUnderlying == null || !oldUnderlying.network.equals(mUnderlying.network)) { if (oldUnderlying == null || !oldUnderlying.network.equals(mUnderlying.network)) {
Slog.v(TAG, "Migrating to new network: " + mUnderlying.network); logDbg("Migrating to new network: " + mUnderlying.network);
mIkeSession.setNetwork(mUnderlying.network); mIkeSession.setNetwork(mUnderlying.network);
} else { } else {
// oldUnderlying is non-null & underlying network itself has not changed // oldUnderlying is non-null & underlying network itself has not changed
@@ -1890,7 +1862,7 @@ public class VcnGatewayConnection extends StateMachine {
mFailedAttempts++; mFailedAttempts++;
if (mUnderlying == null) { if (mUnderlying == null) {
Slog.wtf(TAG, "Underlying network was null in retry state"); logWtf("Underlying network was null in retry state");
transitionTo(mDisconnectedState); transitionTo(mDisconnectedState);
} else { } else {
// Safe to blindly set up, as it is cancelled and cleared on exiting this state // Safe to blindly set up, as it is cancelled and cleared on exiting this state
@@ -2060,25 +2032,25 @@ public class VcnGatewayConnection extends StateMachine {
@Override @Override
public void onOpened(@NonNull IkeSessionConfiguration ikeSessionConfig) { public void onOpened(@NonNull IkeSessionConfiguration ikeSessionConfig) {
Slog.v(TAG, "IkeOpened for token " + mToken); logDbg("IkeOpened for token " + mToken);
// Nothing to do here. // Nothing to do here.
} }
@Override @Override
public void onClosed() { public void onClosed() {
Slog.v(TAG, "IkeClosed for token " + mToken); logDbg("IkeClosed for token " + mToken);
sessionClosed(mToken, null); sessionClosed(mToken, null);
} }
@Override @Override
public void onClosedExceptionally(@NonNull IkeException exception) { public void onClosedExceptionally(@NonNull IkeException exception) {
Slog.v(TAG, "IkeClosedExceptionally for token " + mToken, exception); logDbg("IkeClosedExceptionally for token " + mToken, exception);
sessionClosed(mToken, exception); sessionClosed(mToken, exception);
} }
@Override @Override
public void onError(@NonNull IkeProtocolException exception) { public void onError(@NonNull IkeProtocolException exception) {
Slog.v(TAG, "IkeError for token " + mToken, exception); logDbg("IkeError for token " + mToken, exception);
// Non-fatal, log and continue. // Non-fatal, log and continue.
} }
} }
@@ -2095,7 +2067,7 @@ public class VcnGatewayConnection extends StateMachine {
/** Internal proxy method for injecting of mocked ChildSessionConfiguration */ /** Internal proxy method for injecting of mocked ChildSessionConfiguration */
@VisibleForTesting(visibility = Visibility.PRIVATE) @VisibleForTesting(visibility = Visibility.PRIVATE)
void onOpened(@NonNull VcnChildSessionConfiguration childConfig) { void onOpened(@NonNull VcnChildSessionConfiguration childConfig) {
Slog.v(TAG, "ChildOpened for token " + mToken); logDbg("ChildOpened for token " + mToken);
childOpened(mToken, childConfig); childOpened(mToken, childConfig);
} }
@@ -2106,19 +2078,19 @@ public class VcnGatewayConnection extends StateMachine {
@Override @Override
public void onClosed() { public void onClosed() {
Slog.v(TAG, "ChildClosed for token " + mToken); logDbg("ChildClosed for token " + mToken);
sessionLost(mToken, null); sessionLost(mToken, null);
} }
@Override @Override
public void onClosedExceptionally(@NonNull IkeException exception) { public void onClosedExceptionally(@NonNull IkeException exception) {
Slog.v(TAG, "ChildClosedExceptionally for token " + mToken, exception); logDbg("ChildClosedExceptionally for token " + mToken, exception);
sessionLost(mToken, exception); sessionLost(mToken, exception);
} }
@Override @Override
public void onIpSecTransformCreated(@NonNull IpSecTransform transform, int direction) { public void onIpSecTransformCreated(@NonNull IpSecTransform transform, int direction) {
Slog.v(TAG, "ChildTransformCreated; Direction: " + direction + "; token " + mToken); logDbg("ChildTransformCreated; Direction: " + direction + "; token " + mToken);
childTransformCreated(mToken, transform, direction); childTransformCreated(mToken, transform, direction);
} }
@@ -2126,7 +2098,7 @@ public class VcnGatewayConnection extends StateMachine {
public void onIpSecTransformsMigrated( public void onIpSecTransformsMigrated(
@NonNull IpSecTransform inIpSecTransform, @NonNull IpSecTransform inIpSecTransform,
@NonNull IpSecTransform outIpSecTransform) { @NonNull IpSecTransform outIpSecTransform) {
Slog.v(TAG, "ChildTransformsMigrated; token " + mToken); logDbg("ChildTransformsMigrated; token " + mToken);
migrationCompleted(mToken, inIpSecTransform, outIpSecTransform); migrationCompleted(mToken, inIpSecTransform, outIpSecTransform);
} }
@@ -2134,10 +2106,48 @@ public class VcnGatewayConnection extends StateMachine {
public void onIpSecTransformDeleted(@NonNull IpSecTransform transform, int direction) { public void onIpSecTransformDeleted(@NonNull IpSecTransform transform, int direction) {
// Nothing to be done; no references to the IpSecTransform are held, and this transform // Nothing to be done; no references to the IpSecTransform are held, and this transform
// will be closed by the IKE library. // will be closed by the IKE library.
Slog.v(TAG, "ChildTransformDeleted; Direction: " + direction + "; for token " + mToken); logDbg("ChildTransformDeleted; Direction: " + direction + "; for token " + mToken);
} }
} }
private String getLogPrefix() {
return "["
+ LogUtils.getHashedSubscriptionGroup(mSubscriptionGroup)
+ "-"
+ mConnectionConfig.getGatewayConnectionName()
+ "]: ";
}
private void logVdbg(String msg) {
if (VDBG) {
Slog.v(TAG, getLogPrefix() + msg);
}
}
private void logDbg(String msg) {
Slog.d(TAG, getLogPrefix() + msg);
}
private void logDbg(String msg, Throwable tr) {
Slog.d(TAG, getLogPrefix() + msg, tr);
}
private void logErr(String msg) {
Slog.e(TAG, getLogPrefix() + msg);
}
private void logErr(String msg, Throwable tr) {
Slog.e(TAG, getLogPrefix() + msg, tr);
}
private void logWtf(String msg) {
Slog.wtf(TAG, getLogPrefix() + msg);
}
private void logWtf(String msg, Throwable tr) {
Slog.wtf(TAG, getLogPrefix() + msg, tr);
}
/** /**
* Dumps the state of this VcnGatewayConnection for logging and debugging purposes. * Dumps the state of this VcnGatewayConnection for logging and debugging purposes.
* *

39
services/core/java/com/android/server/vcn/util/LogUtils.java Normal file
View File

@@ -0,0 +1,39 @@
/*
* Copyright (C) 2021 The Android Open Source Project
*
* Licensed under the Apache License, Version 2.0 (the "License");
* you may not use this file except in compliance with the License.
* You may obtain a copy of the License at
*
* http://www.apache.org/licenses/LICENSE-2.0
*
* Unless required by applicable law or agreed to in writing, software
* distributed under the License is distributed on an "AS IS" BASIS,
* WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
* See the License for the specific language governing permissions and
* limitations under the License.
*/
package com.android.server.vcn.util;
import android.annotation.Nullable;
import android.os.ParcelUuid;
import com.android.internal.util.HexDump;
/** @hide */
public class LogUtils {
/**
* Returns the hash of the subscription group in hexadecimal format.
*
* @return the hexadecimal encoded string if uuid was non-null, else {@code null}
*/
@Nullable
public static String getHashedSubscriptionGroup(@Nullable ParcelUuid uuid) {
if (uuid == null) {
return null;
}
return HexDump.toHexString(uuid.hashCode());
}
}