DO NOT MERGE Add logging to detect the start of a sync problem.
Robert Greenwalt [Thu, 23 Jul 2015 22:52:42 +0000 (15:52 -0700)]
This should be removed prior to shipment!

The DctController is getting out of sync with the ApnContexts.  Add a callback
mechanism so the ApnContexts can let DctController know when they apply a change
and then when all is quiet we can compare and verify everything is good.

Potentially can fix the problem detected too (if there should be no live requests, nuke
the ref counts) but currently turned off so people will notice problems (battery life) and
file bugreports with the data of how it started.

bug:22632129
Change-Id: I84a67687f0b6dc43b2e429943935f4045ffc51ed

src/java/com/android/internal/telephony/PhoneFactory.java
src/java/com/android/internal/telephony/dataconnection/ApnContext.java
src/java/com/android/internal/telephony/dataconnection/DcSwitchAsyncChannel.java
src/java/com/android/internal/telephony/dataconnection/DcTracker.java
src/java/com/android/internal/telephony/dataconnection/DcTrackerBase.java
src/java/com/android/internal/telephony/dataconnection/DctController.java

index b4c1c94..76fb5da 100644 (file)
@@ -454,6 +454,12 @@ public class PhoneFactory {
         }
     }
 
+    public static LocalLog getLocalLog(String key) {
+        synchronized (sLocalLogs) {
+            return sLocalLogs.get(key);
+        }
+    }
+
     public static void dump(FileDescriptor fd, PrintWriter pw, String[] args) {
         pw.println("PhoneFactory:");
         PhoneProxy [] phones = (PhoneProxy[])PhoneFactory.getPhones();
index 9e9433e..4ce24b4 100644 (file)
@@ -285,7 +285,7 @@ public class ApnContext {
         }
     }
 
-    public void incRefCount(LocalLog log) {
+    public void incRefCount(LocalLog log, int serialNum) {
         synchronized (mRefCountLock) {
             if (mRefCount == 0) {
                // we wanted to leave the last in so it could actually capture the tear down
@@ -302,10 +302,11 @@ public class ApnContext {
             if (mRefCount++ == 0) {
                 mDcTracker.setEnabled(mDcTracker.apnTypeToId(mApnType), true);
             }
+            DctController.getInstance().ackNetworkExecution(serialNum);
         }
     }
 
-    public void decRefCount(LocalLog log) {
+    public void decRefCount(LocalLog log, int serialNum) {
         synchronized (mRefCountLock) {
             // leave the last log alive to capture the actual tear down
             if (mRefCount != 1) {
@@ -320,6 +321,29 @@ public class ApnContext {
             if (mRefCount-- == 1) {
                 mDcTracker.setEnabled(mDcTracker.apnTypeToId(mApnType), false);
             }
+            DctController.getInstance().ackNetworkExecution(serialNum);
+        }
+    }
+
+    public void clearRefCount() {
+        synchronized (mRefCountLock) {
+            for (LocalLog l : mLocalLogs) l.log("ApnContext.clearRefCount from " + mRefCount);
+            mLocalLogs.clear();
+            mRefCount = 0;
+            mDcTracker.setEnabled(mDcTracker.apnTypeToId(mApnType), false);
+        }
+    }
+
+    int getRefCount() {
+        return mRefCount;
+    }
+
+    void copyLogTo(LocalLog other) {
+        synchronized (mRefCountLock) {
+            for (LocalLog l : mLocalLogs) {
+                other.log("-----");
+                l.copyTo(other, 30);
+            }
         }
     }
 
index f56570f..ff87639 100644 (file)
@@ -64,6 +64,7 @@ public class DcSwitchAsyncChannel extends AsyncChannel {
         final NetworkRequest request;
         final int priority;
         private final LocalLog requestLog;
+        int executionSerialNumber;
 
         public RequestInfo(NetworkRequest request, int priority, LocalLog l) {
             this.request = request;
index 0cf9c08..f6af709 100644 (file)
@@ -69,6 +69,7 @@ import com.android.internal.telephony.ITelephony;
 import com.android.internal.telephony.TelephonyIntents;
 import com.android.internal.telephony.gsm.GSMPhone;
 import com.android.internal.telephony.PhoneConstants;
+import com.android.internal.telephony.PhoneFactory;
 import com.android.internal.telephony.RILConstants;
 import com.android.internal.telephony.uicc.IccRecords;
 import com.android.internal.telephony.uicc.UiccController;
@@ -253,20 +254,49 @@ public final class DcTracker extends DcTrackerBase {
     }
 
     @Override
-    public void incApnRefCount(String name, LocalLog log) {
+    public void incApnRefCount(String name, LocalLog log, int serialNum) {
         ApnContext apnContext = mApnContexts.get(name);
-        log.log("DcTracker.incApnRefCount on " + name + " found " + apnContext);
+        log.log("DcTracker.incApnRefCount on " + name + " found " + apnContext + " (" +
+                serialNum + ")");
         if (apnContext != null) {
-            apnContext.incRefCount(log);
+            apnContext.incRefCount(log, serialNum);
         }
+
     }
 
     @Override
-    public void decApnRefCount(String name, LocalLog log) {
+    public void decApnRefCount(String name, LocalLog log, int serialNum) {
         ApnContext apnContext = mApnContexts.get(name);
-        log.log("DcTracker.decApnRefCount on " + name + " found " + apnContext);
+        log.log("DcTracker.decApnRefCount on " + name + " found " + apnContext + " (" +
+                serialNum + ")");
         if (apnContext != null) {
-            apnContext.decRefCount(log);
+            apnContext.decRefCount(log, serialNum);
+        }
+    }
+
+    @Override
+    public int currentRequestCount() {
+        int total = 0;
+        for (ApnContext apnContext: mApnContexts.values()) {
+            total += apnContext.getRefCount();
+        }
+        return total;
+    }
+
+    @Override
+    public void clearApnRefCounts() {
+        for (ApnContext apnContext : mApnContexts.values()) {
+            apnContext.clearRefCount();
+        }
+    }
+
+    public void snapshotContexts(String logName) {
+        LocalLog l = PhoneFactory.getLocalLog(logName);
+        if (l != null) {
+            for (ApnContext apnContext : mApnContexts.values()) {
+                l.log(apnContext.toString());
+                apnContext.copyLogTo(l);
+            }
         }
     }
 
index 8d1323a..78baf43 100644 (file)
@@ -662,9 +662,15 @@ public abstract class DcTrackerBase extends Handler {
         mPhone.notifyDataActivity();
     }
 
-    abstract public void incApnRefCount(String name, LocalLog log);
+    abstract public void incApnRefCount(String name, LocalLog log, int serialNum);
 
-    abstract public void decApnRefCount(String name, LocalLog log);
+    abstract public void decApnRefCount(String name, LocalLog log, int serialNum);
+
+    abstract public int currentRequestCount();
+
+    abstract public void clearApnRefCounts();
+
+    abstract public void snapshotContexts(String logName);
 
     public boolean isApnSupported(String name) {
         return false;
index c2a08af..bb06da5 100644 (file)
@@ -31,11 +31,13 @@ import android.telephony.Rlog;
 import android.telephony.SubscriptionManager;
 import android.telephony.SubscriptionManager.OnSubscriptionsChangedListener;
 import android.util.LocalLog;
+import android.util.Log;
 import android.util.SparseArray;
 
 import com.android.internal.telephony.Phone;
 import com.android.internal.telephony.PhoneBase;
 import com.android.internal.telephony.PhoneConstants;
+import com.android.internal.telephony.PhoneFactory;
 import com.android.internal.telephony.PhoneProxy;
 import com.android.internal.telephony.SubscriptionController;
 import com.android.internal.telephony.dataconnection.DcSwitchAsyncChannel.RequestInfo;
@@ -59,6 +61,7 @@ public class DctController extends Handler {
     private static final int EVENT_RELEASE_REQUEST = 103;
     private static final int EVENT_RELEASE_ALL_REQUESTS = 104;
     private static final int EVENT_RETRY_ATTACH = 105;
+    private static final int EVENT_EXECUTION_TIMEOUT = 106;
 
     private static final int EVENT_DATA_ATTACHED = 500;
     private static final int EVENT_DATA_DETACHED = 600;
@@ -207,6 +210,8 @@ public class DctController extends Handler {
         mPhoneNum = phones.length;
         mPhones = phones;
 
+        createRequestExecLog();
+
         mDcSwitchStateMachine = new DcSwitchStateMachine[mPhoneNum];
         mDcSwitchAsyncChannel = new DcSwitchAsyncChannel[mPhoneNum];
         mDcSwitchStateHandler = new Handler[mPhoneNum];
@@ -275,7 +280,7 @@ public class DctController extends Handler {
                 onExecuteAllRequests(msg.arg1);
                 break;
             case EVENT_RELEASE_REQUEST:
-                onReleaseRequest((RequestInfo)msg.obj);
+                onReleaseRequest((RequestInfo)msg.obj, msg.arg1);
                 break;
             case EVENT_RELEASE_ALL_REQUESTS:
                 onReleaseAllRequests(msg.arg1);
@@ -283,17 +288,150 @@ public class DctController extends Handler {
             case EVENT_RETRY_ATTACH:
                 onRetryAttach(msg.arg1);
                 break;
+            case EVENT_EXECUTION_TIMEOUT:
+                onEventExecutionTimeout(msg.arg1);
+                break;
             default:
                 loge("Un-handled message [" + msg.what + "]");
         }
     }
 
+    // how long to wait for ApnContext to call us back..
+    private static final long EXECUTION_TIMEOUT_MS = 1000 * 30;
+    private final HashMap<Integer, RequestInfo> mExecutingNetworkRequestTransactions =
+            new HashMap<Integer, RequestInfo>();
+    private final HashMap<Integer, RequestInfo> mExecutingNetworkReleaseTransactions =
+            new HashMap<Integer, RequestInfo>();
+    private final Object mExecutingLock = new Object();
+    private static final int NO_SERIAL = 0;
+    private int mExecutingSerialNumber = 1;
+    private static final String REQUEST_LOG_NAME = "DctController Request Exec";
+
+    private static final boolean ATTEMPT_TO_REPAIR_EXEC_MISMATCH = false;
+
+    private void createRequestExecLog() {
+        PhoneFactory.addLocalLog(REQUEST_LOG_NAME, 200000);
+    }
+
+    private void requestExecLog(String log) {
+        PhoneFactory.localLog(REQUEST_LOG_NAME, log);
+    }
+
+    private void trackNetworkRequest(RequestInfo ri) {
+        synchronized (mExecutingLock) {
+            if (ri.executionSerialNumber != NO_SERIAL) {
+                Log.wtf(LOG_TAG, "networkRequest added twice?");
+            }
+            // need to store away so when we actually act on it we can pass this on
+            ri.executionSerialNumber = ++mExecutingSerialNumber;
+            mExecutingNetworkRequestTransactions.put(ri.executionSerialNumber, ri);
+            final Message msg = obtainMessage(EVENT_EXECUTION_TIMEOUT, ri.executionSerialNumber, 0);
+            sendMessageDelayed(msg, EXECUTION_TIMEOUT_MS);
+        }
+    }
+
+    private int trackNetworkRelease(RequestInfo ri) {
+        synchronized (mExecutingLock) {
+            final int executionSerialNumber = ++mExecutingSerialNumber;
+            mExecutingNetworkReleaseTransactions.put(executionSerialNumber, ri);
+            final Message msg = obtainMessage(EVENT_EXECUTION_TIMEOUT, executionSerialNumber, 0);
+            sendMessageDelayed(msg, EXECUTION_TIMEOUT_MS);
+            return executionSerialNumber;
+        }
+    }
+
+    /**
+     * the ack that a network was requested or released
+     * @param executionSerialNumber the number of the ask executed
+     * @param totalLiveRequests the number of requests alive *after* processing
+     */
+    void ackNetworkExecution(int executionSerialNumber) {
+        final Integer serialNum = new Integer(executionSerialNumber);
+        synchronized (mExecutingLock) {
+            if (mExecutingNetworkRequestTransactions.remove(serialNum) == null) {
+                if (mExecutingNetworkReleaseTransactions.remove(serialNum) == null) {
+                    Log.wtf(LOG_TAG, "ackNetworkExecution can't find request for " +
+                            executionSerialNumber);
+                }
+            }
+            verifyNetworkRequestsLocked();
+        }
+    }
+
+    private void onEventExecutionTimeout(int serialNum) {
+        synchronized (mExecutingLock) {
+            if ((mExecutingNetworkRequestTransactions.remove(serialNum) != null) ||
+                    (mExecutingNetworkReleaseTransactions.remove(serialNum) != null)) {
+                requestExecLog("Timeout on request " + serialNum);
+                verifyNetworkRequestsLocked();
+            }
+        }
+    }
+
+    private boolean loggedVerifyFailure = false;
+
+    private void verifyNetworkRequestsLocked() {
+        int ourLiveCount = mRequestInfos.size();
+        int ourExecutedCount = 0;
+        int phoneId = 0;
+        for (RequestInfo ri : mRequestInfos.values()) {
+            if (ri.executed) {
+                ourExecutedCount++;
+                phoneId = getRequestPhoneId(ri.request);
+            }
+        }
+
+        if (!SubscriptionManager.isValidPhoneId(phoneId)) return;
+
+        int pendingRequestCount = mExecutingNetworkRequestTransactions.size();
+        int pendingReleaseCount = mExecutingNetworkReleaseTransactions.size();
+
+        final PhoneBase phoneBase = (PhoneBase)mPhones[phoneId].getActivePhone();
+        final DcTrackerBase dcTracker = phoneBase.mDcTracker;
+
+        final int dcTrackerLiveRequests = dcTracker.currentRequestCount();
+
+        ourLiveCount += pendingReleaseCount;
+        ourLiveCount -= pendingRequestCount;
+
+        if (ourLiveCount != dcTrackerLiveRequests) {
+            if (!loggedVerifyFailure) {
+                requestExecLog("verifyNetworkRequestsLocked failed!  Ours=" + ourLiveCount +
+                        ", dcTrackers=" + dcTrackerLiveRequests);
+                requestExecLog("dc=" + dcTrackerLiveRequests + ", mRequestInfos=" +
+                        mRequestInfos.size() + ", exec=" + ourExecutedCount + ", pReq=" +
+                        pendingRequestCount + ", pRel=" + pendingReleaseCount);
+
+                dcTracker.snapshotContexts(REQUEST_LOG_NAME);
+                loggedVerifyFailure = true;
+            }
+
+            if (ATTEMPT_TO_REPAIR_EXEC_MISMATCH) {
+                if (ourLiveCount == 0) {
+                    if (mExecutingNetworkRequestTransactions.size() == 0 &&
+                            mExecutingNetworkReleaseTransactions.size() == 0) {
+                        requestExecLog("attempting to repair DcTracker");
+                        dcTracker.clearApnRefCounts();
+                    } else {
+                        requestExecLog("not attempting to repair due to pending transactions " +
+                                (mExecutingNetworkRequestTransactions.size() +
+                                mExecutingNetworkReleaseTransactions.size()));
+                    }
+                } else {
+                    requestExecLog("not attempting to repair due to our live count " +
+                            ourLiveCount);
+                }
+            }
+        }
+    }
+
     private int requestNetwork(NetworkRequest request, int priority, LocalLog l) {
         logd("requestNetwork request=" + request
                 + ", priority=" + priority);
         l.log("Dctc.requestNetwork, priority=" + priority);
 
         RequestInfo requestInfo = new RequestInfo(request, priority, l);
+        trackNetworkRequest(requestInfo);
         mRequestInfos.put(request.requestId, requestInfo);
         processRequests();
 
@@ -305,8 +443,9 @@ public class DctController extends Handler {
         logd("releaseNetwork request=" + request + ", requestInfo=" + requestInfo);
         requestInfo.log("DctController.releaseNetwork");
 
+        final int serialNum = trackNetworkRelease(requestInfo);
         mRequestInfos.remove(request.requestId);
-        releaseRequest(requestInfo);
+        releaseRequest(requestInfo, serialNum);
         processRequests();
         return PhoneConstants.APN_REQUEST_STARTED;
     }
@@ -326,9 +465,9 @@ public class DctController extends Handler {
         sendMessage(obtainMessage(EVENT_EXECUTE_ALL_REQUESTS, phoneId,0));
     }
 
-    void releaseRequest(RequestInfo request) {
+    void releaseRequest(RequestInfo request, int serialNum) {
         logd("releaseRequest, request= " + request);
-        sendMessage(obtainMessage(EVENT_RELEASE_REQUEST, request));
+        sendMessage(obtainMessage(EVENT_RELEASE_REQUEST, serialNum, 0, request));
     }
 
     void releaseAllRequests(int phoneId) {
@@ -385,7 +524,7 @@ public class DctController extends Handler {
             int phoneId = getRequestPhoneId(requestInfo.request);
             PhoneBase phoneBase = (PhoneBase)mPhones[phoneId].getActivePhone();
             DcTrackerBase dcTracker = phoneBase.mDcTracker;
-            dcTracker.incApnRefCount(apn, requestInfo.getLog());
+            dcTracker.incApnRefCount(apn, requestInfo.getLog(), requestInfo.executionSerialNumber);
         }
     }
 
@@ -400,7 +539,7 @@ public class DctController extends Handler {
         }
     }
 
-    private void onReleaseRequest(RequestInfo requestInfo) {
+    private void onReleaseRequest(RequestInfo requestInfo, int executionSerialNumber) {
         logd("onReleaseRequest request=" + requestInfo);
         requestInfo.log("DctController.onReleaseRequest");
         if (requestInfo != null && requestInfo.executed) {
@@ -408,7 +547,7 @@ public class DctController extends Handler {
             int phoneId = getRequestPhoneId(requestInfo.request);
             PhoneBase phoneBase = (PhoneBase)mPhones[phoneId].getActivePhone();
             DcTrackerBase dcTracker = phoneBase.mDcTracker;
-            dcTracker.decApnRefCount(apn, requestInfo.getLog());
+            dcTracker.decApnRefCount(apn, requestInfo.getLog(), executionSerialNumber);
             requestInfo.executed = false;
         }
     }
@@ -419,7 +558,8 @@ public class DctController extends Handler {
         while (iterator.hasNext()) {
             RequestInfo requestInfo = mRequestInfos.get(iterator.next());
             if (getRequestPhoneId(requestInfo.request) == phoneId) {
-                onReleaseRequest(requestInfo);
+                final int serialNum = trackNetworkRelease(requestInfo);
+                onReleaseRequest(requestInfo, serialNum);
             }
         }
     }
@@ -458,17 +598,7 @@ public class DctController extends Handler {
                 RequestInfo requestInfo = mRequestInfos.get(iterator.next());
                 String specifier = requestInfo.request.networkCapabilities.getNetworkSpecifier();
                 if (specifier == null || specifier.equals("")) {
-                    if (requestInfo.executed) {
-                        String apn = apnForNetworkRequest(requestInfo.request);
-                        logd("[setDataSubId] activePhoneId:" + activePhoneId + ", subId =" +
-                                dataSubId);
-                        requestInfo.log("DctController.onSettingsChange releasing request");
-                        PhoneBase phoneBase =
-                                (PhoneBase)mPhones[activePhoneId].getActivePhone();
-                        DcTrackerBase dcTracker = phoneBase.mDcTracker;
-                        dcTracker.decApnRefCount(apn, requestInfo.getLog());
-                        requestInfo.executed = false;
-                    }
+                    onReleaseRequest(requestInfo, trackNetworkRelease(requestInfo));
                 }
             }
         }