adding debug logs

- add debug status to WifiStatemachine message handling
- tracking scan requests: add scan request counter and addl debug information
- clean wifi packet stats when we disable RSSI polling
- count home network as >=6 BSSID for the purpose of calculating wifi score

Change-Id: Ic13ef303fdcfe60c0e27f225af4e233b9a2cffaa
diff --git a/service/java/com/android/server/wifi/WifiServiceImpl.java b/service/java/com/android/server/wifi/WifiServiceImpl.java
index fe673d9..a1f6333 100644
--- a/service/java/com/android/server/wifi/WifiServiceImpl.java
+++ b/service/java/com/android/server/wifi/WifiServiceImpl.java
@@ -111,6 +111,9 @@
 
     private String mInterfaceName;
 
+    // Debug counter tracking scan requests sent by WifiManager
+    private int scanRequestCounter = 0;
+
     /* Tracks the open wi-fi network notification */
     private WifiNotificationController mNotificationController;
     /* Polls traffic stats and notifies clients */
@@ -408,7 +411,8 @@
             // supplied WorkSource to allow future WorkSource combining.
             workSource.clearNames();
         }
-        mWifiStateMachine.startScan(Binder.getCallingUid(), settings, workSource);
+        mWifiStateMachine.startScan(Binder.getCallingUid(), scanRequestCounter++,
+                settings, workSource);
     }
 
     private class BatchedScanRequest extends DeathRecipient {
diff --git a/service/java/com/android/server/wifi/WifiStateMachine.java b/service/java/com/android/server/wifi/WifiStateMachine.java
index 4536c41..93dfc8f 100644
--- a/service/java/com/android/server/wifi/WifiStateMachine.java
+++ b/service/java/com/android/server/wifi/WifiStateMachine.java
@@ -212,6 +212,8 @@
     private static final int SCAN_REQUEST_BUFFER_MAX_SIZE = 10;
     private static final String CUSTOMIZED_SCAN_SETTING = "customized_scan_settings";
     private static final String CUSTOMIZED_SCAN_WORKSOURCE = "customized_scan_worksource";
+    private static final String SCAN_REQUEST_TIME = "scan_request_time";
+
     private static final String BATCHED_SETTING = "batched_settings";
     private static final String BATCHED_WORKSOURCE = "batched_worksource";
 
@@ -902,7 +904,7 @@
                     @Override
                     public void onReceive(Context context, Intent intent) {
                         sScanAlarmIntentCount++;
-                        startScan(SCAN_ALARM_SOURCE, null, null);
+                        startScan(SCAN_ALARM_SOURCE, -2, null, null);
                         if (VDBG)
                             loge("WiFiStateMachine SCAN ALARM");
                     }
@@ -1148,11 +1150,13 @@
      * @param workSource If not null, blame is given to workSource.
      * @param settings Scan settings, see {@link ScanSettings}.
      */
-    public void startScan(int callingUid, ScanSettings settings, WorkSource workSource) {
+    public void startScan(int callingUid, int scanCounter,
+                          ScanSettings settings, WorkSource workSource) {
         Bundle bundle = new Bundle();
         bundle.putParcelable(CUSTOMIZED_SCAN_SETTING, settings);
         bundle.putParcelable(CUSTOMIZED_SCAN_WORKSOURCE, workSource);
-        sendMessage(CMD_START_SCAN, callingUid, 0, bundle);
+        bundle.putLong(SCAN_REQUEST_TIME, System.currentTimeMillis());
+        sendMessage(CMD_START_SCAN, callingUid, scanCounter, bundle);
     }
 
     /**
@@ -1472,14 +1476,28 @@
         }
     }
 
-    //keeping track of scan requests
+    // Keeping track of scan requests
     private long lastStartScanTimeStamp = 0;
     private long lastScanDuration = 0;
-    //last connect attempt is used to prevent scan requests:
-    // - for a period of 10 seconds after attempting to connect
+    // Last connect attempt is used to prevent scan requests:
+    //  - for a period of 10 seconds after attempting to connect
     private long lastConnectAttempt = 0;
     private String lastScanFreqs = null;
 
+    // For debugging, keep track of last message status handling
+    // TODO, find an equivalent mechanism as part of parent class
+    private static int MESSAGE_HANDLING_STATUS_OK = 1;
+    private static int MESSAGE_HANDLING_STATUS_UNKNOWN = 0;
+    private static int MESSAGE_HANDLING_STATUS_REFUSED = -1;
+    private static int MESSAGE_HANDLING_STATUS_FAIL = -2;
+    private static int MESSAGE_HANDLING_STATUS_BUFFERED = -3;
+    private static int MESSAGE_HANDLING_STATUS_DEFERRED = -4;
+    private static int MESSAGE_HANDLING_STATUS_DISCARD = -5;
+    private static int MESSAGE_HANDLING_STATUS_LOOPED = -6;
+    private static int MESSAGE_HANDLING_STATUS_HANDLING_ERROR = -7;
+
+    private int messageHandlingStatus = 0;
+
     //TODO: this is used only to track connection attempts, however the link state and packet per
     //TODO: second logic should be folded into that
     private boolean isScanAllowed() {
@@ -1607,6 +1625,7 @@
             // a full scan covers everything, clearing scan request buffer
             if (freqs == null)
                 mBufferedScanMsg.clear();
+            messageHandlingStatus = MESSAGE_HANDLING_STATUS_OK;
             return;
         }
 
@@ -1614,26 +1633,34 @@
 
         if (!mIsScanOngoing) {
             // if rejection is NOT due to ongoing scan (e.g. bad scan parameters),
+
             // discard this request and pop up the next one
-            if (mBufferedScanMsg.size() > 0)
+            if (mBufferedScanMsg.size() > 0) {
                 sendMessage(mBufferedScanMsg.remove());
+            }
+            messageHandlingStatus = MESSAGE_HANDLING_STATUS_DISCARD;
         } else if (!mIsFullScanOngoing) {
             // if rejection is due to an ongoing scan, and the ongoing one is NOT a full scan,
             // buffer the scan request to make sure specified channels will be scanned eventually
             if (freqs == null)
                 mBufferedScanMsg.clear();
             if (mBufferedScanMsg.size() < SCAN_REQUEST_BUFFER_MAX_SIZE) {
-                Message msg = obtainMessage(CMD_START_SCAN, message.arg1, 0, bundle);
+                Message msg = obtainMessage(CMD_START_SCAN,
+                        message.arg1, message.arg2, bundle);
                 mBufferedScanMsg.add(msg);
             } else {
                 // if too many requests in buffer, combine them into a single full scan
                 bundle = new Bundle();
                 bundle.putParcelable(CUSTOMIZED_SCAN_SETTING, null);
                 bundle.putParcelable(CUSTOMIZED_SCAN_WORKSOURCE, workSource);
-                Message msg = obtainMessage(CMD_START_SCAN, message.arg1, 0, bundle);
+                Message msg = obtainMessage(CMD_START_SCAN, message.arg1, message.arg2, bundle);
                 mBufferedScanMsg.clear();
                 mBufferedScanMsg.add(msg);
             }
+            messageHandlingStatus = MESSAGE_HANDLING_STATUS_LOOPED;
+        } else {
+            // mIsScanOngoing and mIsFullScanOngoing
+            messageHandlingStatus = MESSAGE_HANDLING_STATUS_FAIL;
         }
     }
 
@@ -2135,6 +2162,7 @@
      ********************************************************/
 
     private void logStateAndMessage(Message message, String state) {
+        messageHandlingStatus = 0;
         if (mLogMessages) {
             //long now = SystemClock.elapsedRealtimeNanos();
             //String ts = String.format("[%,d us]", now/1000);
@@ -2151,24 +2179,37 @@
      */
     protected String getLogRecString(Message msg) {
         WifiConfiguration config;
+        Long now;
         StringBuilder sb = new StringBuilder();
         if (mScreenOn) {
             sb.append("!");
         }
+        if (messageHandlingStatus != MESSAGE_HANDLING_STATUS_UNKNOWN) {
+            sb.append("(").append(messageHandlingStatus).append(")");
+        }
         sb.append(smToString(msg));
 
         switch (msg.what) {
             case CMD_START_SCAN:
+                now = System.currentTimeMillis();
                 sb.append(" ");
                 sb.append(Integer.toString(msg.arg1));
                 sb.append(" ");
                 sb.append(Integer.toString(msg.arg2));
-                sb.append(" ");
+                sb.append(" ic=");
                 sb.append(Integer.toString(sScanAlarmIntentCount));
+                if (msg.obj != null) {
+                    Bundle bundle = (Bundle)msg.obj;
+                    Long request = bundle.getLong(SCAN_REQUEST_TIME, 0);
+                    if (request != 0) {
+                        sb.append(" proc(ms):").append(now - request);
+                    }
+                }
                 if (mIsScanOngoing) sb.append(" onGoing");
                 if (mIsFullScanOngoing) sb.append(" full");
                 if (lastStartScanTimeStamp != 0) {
                     sb.append(" started:").append(lastStartScanTimeStamp);
+                    sb.append(",").append(now - lastStartScanTimeStamp);
                 }
                 if (lastScanDuration != 0) {
                     sb.append(" dur:").append(lastScanDuration);
@@ -2181,7 +2222,7 @@
                 sb.append(String.format(" %.1f,", mWifiInfo.txRetriesRate));
                 sb.append(String.format(" %.1f ", mWifiInfo.txBadRate));
                 sb.append(String.format(" rx=%.1f", mWifiInfo.rxSuccessRate));
-                if (lastScanFreqs != null) sb.append(" ").append(lastScanFreqs);
+                if (lastScanFreqs != null) sb.append(" f=").append(lastScanFreqs);
                 break;
             case WifiMonitor.SUPPLICANT_STATE_CHANGE_EVENT:
                 sb.append(" ");
@@ -2329,7 +2370,7 @@
                         sb.append(" rs=").append(config.disableReason);
                     }
                     if (config.lastConnected != 0) {
-                        long now = System.currentTimeMillis();
+                        now = System.currentTimeMillis();
                         sb.append(" lastconn=").append(now - config.lastConnected).append("(ms)");
                     }
                     if (mLastBssid != null) {
@@ -3063,6 +3104,14 @@
         return false;
     }
 
+    // Polling has completed, hence we wont have a score anymore
+    private void cleanWifiScore() {
+        mWifiInfo.txBadRate = 0;
+        mWifiInfo.txSuccessRate = 0;
+        mWifiInfo.txRetriesRate = 0;
+        mWifiInfo.rxSuccessRate = 0;
+    }
+
     private void calculateWifiScore(WifiLinkLayerStats stats) {
 
         if (stats == null || mWifiLinkLayerStatsSupported <= 0) {
@@ -3103,11 +3152,11 @@
                     use24Thresholds = true;
                 }
             }
-            if (currentConfiguration.scanResultCache.size() <= 4
+            if (currentConfiguration.scanResultCache.size() <= 6
                 && currentConfiguration.allowedKeyManagement.cardinality() == 1
                 && currentConfiguration.allowedKeyManagement.
                     get(WifiConfiguration.KeyMgmt.WPA_PSK) == true) {
-                // A PSK network with less than 4 known BSSIDs
+                // A PSK network with less than 6 known BSSIDs
                 // This is most likely a home network and thus we want to stick to wifi more
                 homeNetworkBoost = true;
             }
@@ -4023,6 +4072,8 @@
                     break;
                     /* Discard */
                 case CMD_START_SCAN:
+                    messageHandlingStatus = MESSAGE_HANDLING_STATUS_DISCARD;
+                    break;
                 case CMD_START_SUPPLICANT:
                 case CMD_STOP_SUPPLICANT:
                 case CMD_STOP_SUPPLICANT_FAILED:
@@ -4075,6 +4126,7 @@
                 case CMD_AUTO_CONNECT:
                 case CMD_AUTO_ROAM:
                 case CMD_AUTO_SAVE_NETWORK:
+                    messageHandlingStatus = MESSAGE_HANDLING_STATUS_DISCARD;
                     break;
                 case DhcpStateMachine.CMD_ON_QUIT:
                     mDhcpStateMachine = null;
@@ -4145,6 +4197,7 @@
                     break;
                 case CMD_IP_CONFIGURATION_SUCCESSFUL:
                 case CMD_IP_CONFIGURATION_LOST:
+                    messageHandlingStatus = MESSAGE_HANDLING_STATUS_DISCARD;
                     break;
                 case CMD_GET_CONNECTION_STATISTICS:
                     replyToMessage(message, message.what, mWifiConnectionStatistics);
@@ -4329,6 +4382,7 @@
                 case CMD_SET_FREQUENCY_BAND:
                 case CMD_START_PACKET_FILTERING:
                 case CMD_STOP_PACKET_FILTERING:
+                    messageHandlingStatus = MESSAGE_HANDLING_STATUS_DEFERRED;
                     deferMessage(message);
                     break;
                 default:
@@ -4555,6 +4609,7 @@
                 case CMD_DISCONNECT:
                 case CMD_REASSOCIATE:
                 case CMD_RECONNECT:
+                    messageHandlingStatus = MESSAGE_HANDLING_STATUS_DEFERRED;
                     deferMessage(message);
                     break;
                 default:
@@ -4884,6 +4939,7 @@
                 case CMD_DISCONNECT:
                 case CMD_REASSOCIATE:
                 case CMD_RECONNECT:
+                    messageHandlingStatus = MESSAGE_HANDLING_STATUS_DEFERRED;
                     deferMessage(message);
                     break;
                 default:
@@ -4916,6 +4972,7 @@
                 case CMD_DISCONNECT:
                 case CMD_REASSOCIATE:
                 case CMD_RECONNECT:
+                    messageHandlingStatus = MESSAGE_HANDLING_STATUS_DEFERRED;
                     deferMessage(message);
                     break;
                 default:
@@ -5871,6 +5928,7 @@
                 noteScanStart(SCAN_ALARM_SOURCE, null);
                 // Return true
             }
+            messageHandlingStatus = MESSAGE_HANDLING_STATUS_OK;
             return true;
         } else {
             return false;
@@ -5972,6 +6030,7 @@
                     }
                     break;
                 case CMD_SET_COUNTRY_CODE:
+                    messageHandlingStatus = MESSAGE_HANDLING_STATUS_DEFERRED;
                     deferMessage(message);
                     break;
                 case CMD_START_SCAN:
@@ -6026,6 +6085,7 @@
                                         + " tx=" + String.format("%.2f", mWifiInfo.txSuccessRate)
                                         + " rx=" + String.format("%.2f", mWifiInfo.rxSuccessRate));
                                     }
+                                    messageHandlingStatus = MESSAGE_HANDLING_STATUS_REFUSED;
                                     return HANDLED;
                                 }
                             }
@@ -6070,8 +6130,12 @@
                                                 WifiNative.SCAN_WITHOUT_CONNECTION_SETUP, message);
                                 }
                             }
+                        } else {
+                            loge("CMD_START_SCAN : connected mode and no configuration");
+                            messageHandlingStatus = MESSAGE_HANDLING_STATUS_HANDLING_ERROR;
                         }
                     } else {
+                        // Not scan alarm source
                         handleScanRequest(WifiNative.SCAN_WITHOUT_CONNECTION_SETUP, message);
                     }
                     break;
@@ -6125,6 +6189,8 @@
                         fetchRssiLinkSpeedAndFrequencyNative();
                         sendMessageDelayed(obtainMessage(CMD_RSSI_POLL,
                                 mRssiPollToken, 0), POLL_RSSI_INTERVAL_MSECS);
+                    } else {
+                        cleanWifiScore();
                     }
                     break;
                 case WifiManager.RSSI_PKTCNT_FETCH:
@@ -6251,17 +6317,21 @@
                   break;
               case CMD_AUTO_CONNECT:
               case CMD_AUTO_ROAM:
+                  messageHandlingStatus = MESSAGE_HANDLING_STATUS_DISCARD;
                   break;
               case WifiManager.SAVE_NETWORK:
               case WifiStateMachine.CMD_AUTO_SAVE_NETWORK:
+                  messageHandlingStatus = MESSAGE_HANDLING_STATUS_DEFERRED;
                   deferMessage(message);
                   break;
                   /* Defer any power mode changes since we must keep active power mode at DHCP */
               case CMD_SET_HIGH_PERF_MODE:
+                  messageHandlingStatus = MESSAGE_HANDLING_STATUS_DEFERRED;
                   deferMessage(message);
                   break;
                   /* Defer scan request since we should not switch to other channels at DHCP */
               case CMD_START_SCAN:
+                  messageHandlingStatus = MESSAGE_HANDLING_STATUS_DEFERRED;
                   deferMessage(message);
                   break;
               case CMD_OBTAINING_IP_ADDRESS_WATCHDOG_TIMER:
@@ -6272,6 +6342,8 @@
                       transitionTo(mDisconnectingState);
                       break;
                   }
+                  messageHandlingStatus = MESSAGE_HANDLING_STATUS_DISCARD;
+                  break;
               default:
                   return NOT_HANDLED;
           }
@@ -6770,7 +6842,7 @@
                     if (mP2pConnected.get()) break;
                     if (message.arg1 == mPeriodicScanToken &&
                             mWifiConfigStore.getConfiguredNetworks().size() == 0) {
-                        startScan(UNKNOWN_SCAN_SOURCE, null, null);
+                        startScan(UNKNOWN_SCAN_SOURCE, -1, null, null);
                         sendMessageDelayed(obtainMessage(CMD_NO_NETWORKS_PERIODIC_SCAN,
                                     ++mPeriodicScanToken, 0), mSupplicantScanIntervalMs);
                     }
@@ -6958,7 +7030,10 @@
                     break;
                 case CMD_AUTO_CONNECT:
                 case CMD_AUTO_ROAM:
+                    messageHandlingStatus = MESSAGE_HANDLING_STATUS_DISCARD;
+                    return HANDLED;
                 case CMD_START_SCAN:
+                    messageHandlingStatus = MESSAGE_HANDLING_STATUS_DISCARD;
                     return HANDLED;
                 case WifiMonitor.NETWORK_DISCONNECTION_EVENT:
                     if (DBG) log("Network connection lost");