Merge changes Ic2c84de7,I379aef92 into nyc-dev

* changes:
  Remove duplicated code in NetworkStateTrackerHandler.
  Improve Tethering and NativeDaemonConnector logging.

4 files changed, 132 insertions, 97 deletions

diff --git a/core/java/com/android/internal/util/Protocol.java b/core/java/com/android/internal/util/Protocol.java
index 5992f7a92e13..b075db881d6d 100644
--- a/core/java/com/android/internal/util/Protocol.java
+++ b/core/java/com/android/internal/util/Protocol.java
@@ -57,7 +57,7 @@ public class Protocol {
     public static final int BASE_DATA_CONNECTION                                    = 0x00040000;
     public static final int BASE_DATA_CONNECTION_AC                                 = 0x00041000;
     public static final int BASE_DATA_CONNECTION_TRACKER                            = 0x00042000;
-    public static final int BASE_DNS_PINGER                                         = 0x00050000;
+    public static final int BASE_TETHERING                                          = 0x00050000;
     public static final int BASE_NSD_MANAGER                                        = 0x00060000;
     public static final int BASE_NETWORK_STATE_TRACKER                              = 0x00070000;
     public static final int BASE_CONNECTIVITY_MANAGER                               = 0x00080000;
diff --git a/services/core/java/com/android/server/ConnectivityService.java b/services/core/java/com/android/server/ConnectivityService.java
index 966deb6520f4..ebef21fe5088 100644
--- a/services/core/java/com/android/server/ConnectivityService.java
+++ b/services/core/java/com/android/server/ConnectivityService.java
@@ -116,6 +116,7 @@ import com.android.internal.net.VpnInfo;
 import com.android.internal.net.VpnProfile;
 import com.android.internal.util.AsyncChannel;
 import com.android.internal.util.IndentingPrintWriter;
+import com.android.internal.util.MessageUtils;
 import com.android.internal.util.XmlUtils;
 import com.android.server.am.BatteryStatsService;
 import com.android.server.connectivity.DataConnectionStats;
@@ -224,6 +225,9 @@ public class ConnectivityService extends IConnectivityManager.Stub
     private static final int ENABLED  = 1;
     private static final int DISABLED = 0;
 
+    private static final SparseArray<String> sMagicDecoderRing = MessageUtils.findMessageNames(
+            new Class[] { AsyncChannel.class, ConnectivityService.class, NetworkAgent.class });
+
     private enum ReapUnvalidatedNetworks {
         // Tear down networks that have no chance (e.g. even if validated) of becoming
         // the highest scoring network satisfying a NetworkRequest.  This should be passed when
@@ -1900,11 +1904,12 @@ public class ConnectivityService extends IConnectivityManager.Stub
         }
     }
 
-    private boolean isLiveNetworkAgent(NetworkAgentInfo nai, String msg) {
+    private boolean isLiveNetworkAgent(NetworkAgentInfo nai, int what) {
         if (nai.network == null) return false;
         final NetworkAgentInfo officialNai = getNetworkAgentInfoForNetwork(nai.network);
         if (officialNai != null && officialNai.equals(nai)) return true;
         if (officialNai != null || VDBG) {
+            final String msg = sMagicDecoderRing.get(what, Integer.toString(what));
             loge(msg + " - isLiveNetworkAgent found mismatched netId: " + officialNai +
                 " - " + nai);
         }
@@ -1921,10 +1926,10 @@ public class ConnectivityService extends IConnectivityManager.Stub
             super(looper);
         }
 
-        @Override
-        public void handleMessage(Message msg) {
-            NetworkInfo info;
+        private boolean maybeHandleAsyncChannelMessage(Message msg) {
             switch (msg.what) {
+                default:
+                    return false;
                 case AsyncChannel.CMD_CHANNEL_HALF_CONNECTED: {
                     handleAsyncChannelHalfConnect(msg);
                     break;
@@ -1938,69 +1943,58 @@ public class ConnectivityService extends IConnectivityManager.Stub
                     handleAsyncChannelDisconnected(msg);
                     break;
                 }
+            }
+            return true;
+        }
+
+        private void maybeHandleNetworkAgentMessage(Message msg) {
+            NetworkAgentInfo nai = mNetworkAgentInfos.get(msg.replyTo);
+            if (nai == null) {
+                if (VDBG) {
+                    final String what = sMagicDecoderRing.get(msg.what, Integer.toString(msg.what));
+                    log(String.format("%s from unknown NetworkAgent", what));
+                }
+                return;
+            }
+
+            switch (msg.what) {
                 case NetworkAgent.EVENT_NETWORK_CAPABILITIES_CHANGED: {
-                    NetworkAgentInfo nai = mNetworkAgentInfos.get(msg.replyTo);
-                    if (nai == null) {
-                        loge("EVENT_NETWORK_CAPABILITIES_CHANGED from unknown NetworkAgent");
-                    } else {
-                        final NetworkCapabilities networkCapabilities =
-                                (NetworkCapabilities)msg.obj;
-                        if (networkCapabilities.hasCapability(NET_CAPABILITY_CAPTIVE_PORTAL) ||
-                                networkCapabilities.hasCapability(NET_CAPABILITY_VALIDATED)) {
-                            Slog.wtf(TAG, "BUG: " + nai + " has CS-managed capability.");
-                        }
-                        if (nai.created && !nai.networkCapabilities.equalImmutableCapabilities(
-                                networkCapabilities)) {
-                            Slog.wtf(TAG, "BUG: " + nai + " changed immutable capabilities: "
-                                    + nai.networkCapabilities + " -> " + networkCapabilities);
-                        }
-                        updateCapabilities(nai, networkCapabilities);
+                    final NetworkCapabilities networkCapabilities = (NetworkCapabilities) msg.obj;
+                    if (networkCapabilities.hasCapability(NET_CAPABILITY_CAPTIVE_PORTAL) ||
+                            networkCapabilities.hasCapability(NET_CAPABILITY_VALIDATED)) {
+                        Slog.wtf(TAG, "BUG: " + nai + " has CS-managed capability.");
+                    }
+                    if (nai.created && !nai.networkCapabilities.equalImmutableCapabilities(
+                            networkCapabilities)) {
+                        Slog.wtf(TAG, "BUG: " + nai + " changed immutable capabilities: "
+                                + nai.networkCapabilities + " -> " + networkCapabilities);
                     }
+                    updateCapabilities(nai, networkCapabilities);
                     break;
                 }
                 case NetworkAgent.EVENT_NETWORK_PROPERTIES_CHANGED: {
-                    NetworkAgentInfo nai = mNetworkAgentInfos.get(msg.replyTo);
-                    if (nai == null) {
-                        loge("NetworkAgent not found for EVENT_NETWORK_PROPERTIES_CHANGED");
-                    } else {
-                        if (VDBG) {
-                            log("Update of LinkProperties for " + nai.name() +
-                                    "; created=" + nai.created);
-                        }
-                        LinkProperties oldLp = nai.linkProperties;
-                        synchronized (nai) {
-                            nai.linkProperties = (LinkProperties)msg.obj;
-                        }
-                        if (nai.created) updateLinkProperties(nai, oldLp);
+                    if (VDBG) {
+                        log("Update of LinkProperties for " + nai.name() +
+                                "; created=" + nai.created);
+                    }
+                    LinkProperties oldLp = nai.linkProperties;
+                    synchronized (nai) {
+                        nai.linkProperties = (LinkProperties)msg.obj;
                     }
+                    if (nai.created) updateLinkProperties(nai, oldLp);
                     break;
                 }
                 case NetworkAgent.EVENT_NETWORK_INFO_CHANGED: {
-                    NetworkAgentInfo nai = mNetworkAgentInfos.get(msg.replyTo);
-                    if (nai == null) {
-                        loge("EVENT_NETWORK_INFO_CHANGED from unknown NetworkAgent");
-                        break;
-                    }
-                    info = (NetworkInfo) msg.obj;
+                    NetworkInfo info = (NetworkInfo) msg.obj;
                     updateNetworkInfo(nai, info);
                     break;
                 }
                 case NetworkAgent.EVENT_NETWORK_SCORE_CHANGED: {
-                    NetworkAgentInfo nai = mNetworkAgentInfos.get(msg.replyTo);
-                    if (nai == null) {
-                        loge("EVENT_NETWORK_SCORE_CHANGED from unknown NetworkAgent");
-                        break;
-                    }
                     Integer score = (Integer) msg.obj;
                     if (score != null) updateNetworkScore(nai, score.intValue());
                     break;
                 }
                 case NetworkAgent.EVENT_UID_RANGES_ADDED: {
-                    NetworkAgentInfo nai = mNetworkAgentInfos.get(msg.replyTo);
-                    if (nai == null) {
-                        loge("EVENT_UID_RANGES_ADDED from unknown NetworkAgent");
-                        break;
-                    }
                     try {
                         mNetd.addVpnUidRanges(nai.network.netId, (UidRange[])msg.obj);
                     } catch (Exception e) {
@@ -2010,11 +2004,6 @@ public class ConnectivityService extends IConnectivityManager.Stub
                     break;
                 }
                 case NetworkAgent.EVENT_UID_RANGES_REMOVED: {
-                    NetworkAgentInfo nai = mNetworkAgentInfos.get(msg.replyTo);
-                    if (nai == null) {
-                        loge("EVENT_UID_RANGES_REMOVED from unknown NetworkAgent");
-                        break;
-                    }
                     try {
                         mNetd.removeVpnUidRanges(nai.network.netId, (UidRange[])msg.obj);
                     } catch (Exception e) {
@@ -2024,11 +2013,6 @@ public class ConnectivityService extends IConnectivityManager.Stub
                     break;
                 }
                 case NetworkAgent.EVENT_SET_EXPLICITLY_SELECTED: {
-                    NetworkAgentInfo nai = mNetworkAgentInfos.get(msg.replyTo);
-                    if (nai == null) {
-                        loge("EVENT_SET_EXPLICITLY_SELECTED from unknown NetworkAgent");
-                        break;
-                    }
                     if (nai.created && !nai.networkMisc.explicitlySelected) {
                         loge("ERROR: created network explicitly selected.");
                     }
@@ -2037,17 +2021,19 @@ public class ConnectivityService extends IConnectivityManager.Stub
                     break;
                 }
                 case NetworkAgent.EVENT_PACKET_KEEPALIVE: {
-                    NetworkAgentInfo nai = mNetworkAgentInfos.get(msg.replyTo);
-                    if (nai == null) {
-                        loge("EVENT_PACKET_KEEPALIVE from unknown NetworkAgent");
-                        break;
-                    }
                     mKeepaliveTracker.handleEventPacketKeepalive(nai, msg);
                     break;
                 }
+            }
+        }
+
+        private boolean maybeHandleNetworkMonitorMessage(Message msg) {
+            switch (msg.what) {
+                default:
+                    return false;
                 case NetworkMonitor.EVENT_NETWORK_TESTED: {
                     NetworkAgentInfo nai = (NetworkAgentInfo)msg.obj;
-                    if (isLiveNetworkAgent(nai, "EVENT_NETWORK_TESTED")) {
+                    if (isLiveNetworkAgent(nai, msg.what)) {
                         final boolean valid =
                                 (msg.arg1 == NetworkMonitor.NETWORK_TEST_RESULT_VALID);
                         if (DBG) log(nai.name() + " validation " + (valid ? " passed" : "failed"));
@@ -2070,7 +2056,7 @@ public class ConnectivityService extends IConnectivityManager.Stub
                 }
                 case NetworkMonitor.EVENT_NETWORK_LINGER_COMPLETE: {
                     NetworkAgentInfo nai = (NetworkAgentInfo)msg.obj;
-                    if (isLiveNetworkAgent(nai, "EVENT_NETWORK_LINGER_COMPLETE")) {
+                    if (isLiveNetworkAgent(nai, msg.what)) {
                         handleLingerComplete(nai);
                     }
                     break;
@@ -2102,6 +2088,14 @@ public class ConnectivityService extends IConnectivityManager.Stub
                     break;
                 }
             }
+            return true;
+        }
+
+        @Override
+        public void handleMessage(Message msg) {
+            if (!maybeHandleAsyncChannelMessage(msg) && !maybeHandleNetworkMonitorMessage(msg)) {
+                maybeHandleNetworkAgentMessage(msg);
+            }
         }
     }
 
diff --git a/services/core/java/com/android/server/NativeDaemonConnector.java b/services/core/java/com/android/server/NativeDaemonConnector.java
index d6dbad87b060..7db9be20e95f 100644
--- a/services/core/java/com/android/server/NativeDaemonConnector.java
+++ b/services/core/java/com/android/server/NativeDaemonConnector.java
@@ -110,6 +110,14 @@ final class NativeDaemonConnector implements Runnable, Handler.Callback, Watchdo
     }
 
     /**
+     * Like SystemClock.uptimeMillis, except truncated to an int so it will fit in a message arg.
+     * Inaccurate across 49.7 days of uptime, but only used for debugging.
+     */
+    private int uptimeMillisInt() {
+        return (int) SystemClock.uptimeMillis() & Integer.MAX_VALUE;
+    }
+
+    /**
      * Yell loudly if someone tries making future {@link #execute(Command)}
      * calls while holding a lock on the given object.
      */
@@ -134,7 +142,9 @@ final class NativeDaemonConnector implements Runnable, Handler.Callback, Watchdo
 
     @Override
     public boolean handleMessage(Message msg) {
-        String event = (String) msg.obj;
+        final String event = (String) msg.obj;
+        final int start = uptimeMillisInt();
+        final int sent = msg.arg1;
         try {
             if (!mCallbacks.onEvent(msg.what, event, NativeDaemonEvent.unescapeArgs(event))) {
                 log(String.format("Unhandled event '%s'", event));
@@ -145,6 +155,13 @@ final class NativeDaemonConnector implements Runnable, Handler.Callback, Watchdo
             if (mCallbacks.onCheckHoldWakeLock(msg.what) && mWakeLock != null) {
                 mWakeLock.release();
             }
+            final int end = uptimeMillisInt();
+            if (start > sent && start - sent > WARN_EXECUTE_DELAY_MS) {
+                loge(String.format("NDC event {%s} processed too late: %dms", event, start - sent));
+            }
+            if (end > start && end - start > WARN_EXECUTE_DELAY_MS) {
+                loge(String.format("NDC event {%s} took too long: %dms", event, end - start));
+            }
         }
         return true;
     }
@@ -214,8 +231,9 @@ final class NativeDaemonConnector implements Runnable, Handler.Callback, Watchdo
                                     mWakeLock.acquire();
                                     releaseWl = true;
                                 }
-                                if (mCallbackHandler.sendMessage(mCallbackHandler.obtainMessage(
-                                        event.getCode(), event.getRawEvent()))) {
+                                Message msg = mCallbackHandler.obtainMessage(
+                                        event.getCode(), uptimeMillisInt(), 0, event.getRawEvent());
+                                if (mCallbackHandler.sendMessage(msg)) {
                                     releaseWl = false;
                                 }
                             } else {
diff --git a/services/core/java/com/android/server/connectivity/Tethering.java b/services/core/java/com/android/server/connectivity/Tethering.java
index 2cba93fdab90..79b5978998c4 100644
--- a/services/core/java/com/android/server/connectivity/Tethering.java
+++ b/services/core/java/com/android/server/connectivity/Tethering.java
@@ -57,12 +57,16 @@ import android.os.UserHandle;
 import android.provider.Settings;
 import android.telephony.CarrierConfigManager;
 import android.telephony.TelephonyManager;
+import android.text.TextUtils;
 import android.util.Log;
+import android.util.SparseArray;
 
 import com.android.internal.telephony.IccCardConstants;
 import com.android.internal.telephony.TelephonyIntents;
 import com.android.internal.util.IState;
 import com.android.internal.util.IndentingPrintWriter;
+import com.android.internal.util.MessageUtils;
+import com.android.internal.util.Protocol;
 import com.android.internal.util.State;
 import com.android.internal.util.StateMachine;
 import com.android.server.IoThread;
@@ -95,6 +99,12 @@ public class Tethering extends BaseNetworkObserver {
     private final static boolean DBG = false;
     private final static boolean VDBG = false;
 
+    private static final Class[] messageClasses = {
+            Tethering.class, TetherMasterSM.class, TetherInterfaceSM.class
+    };
+    private static final SparseArray<String> sMagicDecoderRing =
+            MessageUtils.findMessageNames(messageClasses);
+
     // TODO - remove both of these - should be part of interface inspection/selection stuff
     private String[] mTetherableUsbRegexs;
     private String[] mTetherableWifiRegexs;
@@ -235,6 +245,8 @@ public class Tethering extends BaseNetworkObserver {
 
     @Override
     public void interfaceStatusChanged(String iface, boolean up) {
+        // Never called directly: only called from interfaceLinkStateChanged.
+        // See NetlinkHandler.cpp:71.
         if (VDBG) Log.d(TAG, "interfaceStatusChanged " + iface + ", " + up);
         boolean found = false;
         boolean usb = false;
@@ -274,7 +286,6 @@ public class Tethering extends BaseNetworkObserver {
 
     @Override
     public void interfaceLinkStateChanged(String iface, boolean up) {
-        if (VDBG) Log.d(TAG, "interfaceLinkStateChanged " + iface + ", " + up);
         interfaceStatusChanged(iface, up);
     }
 
@@ -660,8 +671,11 @@ public class Tethering extends BaseNetworkObserver {
                 erroredList);
         mContext.sendStickyBroadcastAsUser(broadcast, UserHandle.ALL);
         if (DBG) {
-            Log.d(TAG, "sendTetherStateChangedBroadcast " + availableList.size() + ", " +
-                    activeList.size() + ", " + erroredList.size());
+            Log.d(TAG, String.format(
+                    "sendTetherStateChangedBroadcast avail=[%s] active=[%s] error=[%s]",
+                    TextUtils.join(",", availableList),
+                    TextUtils.join(",", activeList),
+                    TextUtils.join(",", erroredList)));
         }
 
         if (usbTethered) {
@@ -989,31 +1003,39 @@ public class Tethering extends BaseNetworkObserver {
         return retVal;
     }
 
+    private void maybeLogMessage(State state, int what) {
+        if (DBG) {
+            Log.d(TAG, state.getName() + " got " +
+                    sMagicDecoderRing.get(what, Integer.toString(what)));
+        }
+    }
+
     class TetherInterfaceSM extends StateMachine {
+        private static final int BASE_IFACE              = Protocol.BASE_TETHERING + 100;
         // notification from the master SM that it's not in tether mode
-        static final int CMD_TETHER_MODE_DEAD            =  1;
+        static final int CMD_TETHER_MODE_DEAD            = BASE_IFACE + 1;
         // request from the user that it wants to tether
-        static final int CMD_TETHER_REQUESTED            =  2;
+        static final int CMD_TETHER_REQUESTED            = BASE_IFACE + 2;
         // request from the user that it wants to untether
-        static final int CMD_TETHER_UNREQUESTED          =  3;
+        static final int CMD_TETHER_UNREQUESTED          = BASE_IFACE + 3;
         // notification that this interface is down
-        static final int CMD_INTERFACE_DOWN              =  4;
+        static final int CMD_INTERFACE_DOWN              = BASE_IFACE + 4;
         // notification that this interface is up
-        static final int CMD_INTERFACE_UP                =  5;
+        static final int CMD_INTERFACE_UP                = BASE_IFACE + 5;
         // notification from the master SM that it had an error turning on cellular dun
-        static final int CMD_CELL_DUN_ERROR              =  6;
+        static final int CMD_CELL_DUN_ERROR              = BASE_IFACE + 6;
         // notification from the master SM that it had trouble enabling IP Forwarding
-        static final int CMD_IP_FORWARDING_ENABLE_ERROR  =  7;
+        static final int CMD_IP_FORWARDING_ENABLE_ERROR  = BASE_IFACE + 7;
         // notification from the master SM that it had trouble disabling IP Forwarding
-        static final int CMD_IP_FORWARDING_DISABLE_ERROR =  8;
+        static final int CMD_IP_FORWARDING_DISABLE_ERROR = BASE_IFACE + 8;
         // notification from the master SM that it had trouble starting tethering
-        static final int CMD_START_TETHERING_ERROR       =  9;
+        static final int CMD_START_TETHERING_ERROR       = BASE_IFACE + 9;
         // notification from the master SM that it had trouble stopping tethering
-        static final int CMD_STOP_TETHERING_ERROR        = 10;
+        static final int CMD_STOP_TETHERING_ERROR        = BASE_IFACE + 10;
         // notification from the master SM that it had trouble setting the DNS forwarders
-        static final int CMD_SET_DNS_FORWARDERS_ERROR    = 11;
+        static final int CMD_SET_DNS_FORWARDERS_ERROR    = BASE_IFACE + 11;
         // the upstream connection has changed
-        static final int CMD_TETHER_CONNECTION_CHANGED   = 12;
+        static final int CMD_TETHER_CONNECTION_CHANGED   = BASE_IFACE + 12;
 
         private State mDefaultState;
 
@@ -1124,7 +1146,7 @@ public class Tethering extends BaseNetworkObserver {
 
             @Override
             public boolean processMessage(Message message) {
-                if (DBG) Log.d(TAG, "InitialState.processMessage what=" + message.what);
+                maybeLogMessage(this, message.what);
                 boolean retValue = true;
                 switch (message.what) {
                     case CMD_TETHER_REQUESTED:
@@ -1165,7 +1187,7 @@ public class Tethering extends BaseNetworkObserver {
             }
             @Override
             public boolean processMessage(Message message) {
-                if (DBG) Log.d(TAG, "StartingState.processMessage what=" + message.what);
+                maybeLogMessage(this, message.what);
                 boolean retValue = true;
                 switch (message.what) {
                     // maybe a parent class?
@@ -1255,7 +1277,7 @@ public class Tethering extends BaseNetworkObserver {
 
             @Override
             public boolean processMessage(Message message) {
-                if (DBG) Log.d(TAG, "TetheredState.processMessage what=" + message.what);
+                maybeLogMessage(this, message.what);
                 boolean retValue = true;
                 boolean error = false;
                 switch (message.what) {
@@ -1480,18 +1502,19 @@ public class Tethering extends BaseNetworkObserver {
     }
 
     class TetherMasterSM extends StateMachine {
+        private static final int BASE_MASTER                    = Protocol.BASE_TETHERING;
         // an interface SM has requested Tethering
-        static final int CMD_TETHER_MODE_REQUESTED              = 1;
+        static final int CMD_TETHER_MODE_REQUESTED              = BASE_MASTER + 1;
         // an interface SM has unrequested Tethering
-        static final int CMD_TETHER_MODE_UNREQUESTED            = 2;
+        static final int CMD_TETHER_MODE_UNREQUESTED            = BASE_MASTER + 2;
         // upstream connection change - do the right thing
-        static final int CMD_UPSTREAM_CHANGED                   = 3;
+        static final int CMD_UPSTREAM_CHANGED                   = BASE_MASTER + 3;
         // we don't have a valid upstream conn, check again after a delay
-        static final int CMD_RETRY_UPSTREAM                     = 4;
+        static final int CMD_RETRY_UPSTREAM                     = BASE_MASTER + 4;
         // Events from NetworkCallbacks that we process on the master state
         // machine thread on behalf of the UpstreamNetworkMonitor.
-        static final int EVENT_UPSTREAM_LINKPROPERTIES_CHANGED  = 5;
-        static final int EVENT_UPSTREAM_LOST                    = 6;
+        static final int EVENT_UPSTREAM_LINKPROPERTIES_CHANGED  = BASE_MASTER + 5;
+        static final int EVENT_UPSTREAM_LOST                    = BASE_MASTER + 6;
 
         // This indicates what a timeout event relates to.  A state that
         // sends itself a delayed timeout event and handles incoming timeout events
@@ -1748,7 +1771,7 @@ public class Tethering extends BaseNetworkObserver {
             }
 
             protected void notifyTetheredOfNewUpstreamIface(String ifaceName) {
-                if (DBG) Log.d(TAG, "notifying tethered with iface =" + ifaceName);
+                if (DBG) Log.d(TAG, "Notifying tethered with upstream=" + ifaceName);
                 mCurrentUpstreamIface = ifaceName;
                 for (TetherInterfaceSM sm : mNotifyList) {
                     sm.sendMessage(TetherInterfaceSM.CMD_TETHER_CONNECTION_CHANGED,
@@ -1862,7 +1885,7 @@ public class Tethering extends BaseNetworkObserver {
             }
             @Override
             public boolean processMessage(Message message) {
-                if (DBG) Log.d(TAG, "MasterInitialState.processMessage what=" + message.what);
+                maybeLogMessage(this, message.what);
                 boolean retValue = true;
                 switch (message.what) {
                     case CMD_TETHER_MODE_REQUESTED:
@@ -1910,7 +1933,7 @@ public class Tethering extends BaseNetworkObserver {
             }
             @Override
             public boolean processMessage(Message message) {
-                if (DBG) Log.d(TAG, "TetherModeAliveState.processMessage what=" + message.what);
+                maybeLogMessage(this, message.what);
                 boolean retValue = true;
                 switch (message.what) {
                     case CMD_TETHER_MODE_REQUESTED: