BT: Audio: Enhance default BT application logging for Audio.

 - Make default logging for HeadsetStateMachine.
   state transitions, connection state changes etc.
 - Control verbose logging at runtime from adb shell.
 - Enable debug flag for A2DP and AVRCP.

CRs-Fixed: 601899

Conflicts:
	src/com/android/bluetooth/hfp/HeadsetStateMachine.java

Change-Id: I39eb8b31c29bd3616747181fe8a4540bdcbe7e76

9 files changed, 71 insertions, 56 deletions

diff --git a/src/com/android/bluetooth/a2dp/A2dpService.java b/src/com/android/bluetooth/a2dp/A2dpService.java
index e14302caf..a0d1c30f1 100755
--- a/src/com/android/bluetooth/a2dp/A2dpService.java
+++ b/src/com/android/bluetooth/a2dp/A2dpService.java
@@ -38,7 +38,7 @@ import java.util.Map;
  * @hide
  */
 public class A2dpService extends ProfileService {
-    private static final boolean DBG = false;
+    private static final boolean DBG = true;
     private static final String TAG="A2dpService";
 
     private A2dpStateMachine mStateMachine;
diff --git a/src/com/android/bluetooth/a2dp/A2dpSinkService.java b/src/com/android/bluetooth/a2dp/A2dpSinkService.java
index 02e920be5..433dcd34b 100644
--- a/src/com/android/bluetooth/a2dp/A2dpSinkService.java
+++ b/src/com/android/bluetooth/a2dp/A2dpSinkService.java
@@ -33,7 +33,7 @@ import java.util.Map;
  * @hide
  */
 public class A2dpSinkService extends ProfileService {
-    private static final boolean DBG = false;
+    private static final boolean DBG = true;
     private static final String TAG = "A2dpSinkService";
 
     private A2dpSinkStateMachine mStateMachine;
diff --git a/src/com/android/bluetooth/a2dp/A2dpSinkStateMachine.java b/src/com/android/bluetooth/a2dp/A2dpSinkStateMachine.java
index b99dd36c7..6cc05dbb4 100644
--- a/src/com/android/bluetooth/a2dp/A2dpSinkStateMachine.java
+++ b/src/com/android/bluetooth/a2dp/A2dpSinkStateMachine.java
@@ -69,7 +69,7 @@ import java.util.HashMap;
 import java.util.Set;
 
 final class A2dpSinkStateMachine extends StateMachine {
-    private static final boolean DBG = false;
+    private static final boolean DBG = true;
 
     static final int CONNECT = 1;
     static final int DISCONNECT = 2;
diff --git a/src/com/android/bluetooth/a2dp/A2dpStateMachine.java b/src/com/android/bluetooth/a2dp/A2dpStateMachine.java
index cfa2d0e14..745198cce 100644
--- a/src/com/android/bluetooth/a2dp/A2dpStateMachine.java
+++ b/src/com/android/bluetooth/a2dp/A2dpStateMachine.java
@@ -58,7 +58,7 @@ import java.util.List;
 import java.util.Set;
 
 final class A2dpStateMachine extends StateMachine {
-    private static final boolean DBG = false;
+    private static final boolean DBG = true;
 
     static final int CONNECT = 1;
     static final int DISCONNECT = 2;
diff --git a/src/com/android/bluetooth/avrcp/Avrcp.java b/src/com/android/bluetooth/avrcp/Avrcp.java
index b438d4709..3c9dd2d77 100755
--- a/src/com/android/bluetooth/avrcp/Avrcp.java
+++ b/src/com/android/bluetooth/avrcp/Avrcp.java
@@ -71,7 +71,7 @@ import android.net.Uri;
  * support metadata, play status and event notification
  */
 public final class Avrcp {
-    private static final boolean DEBUG = false;
+    private static final boolean DEBUG = true;
     private static final String TAG = "Avrcp";
 
     private Context mContext;
diff --git a/src/com/android/bluetooth/avrcp/AvrcpControllerService.java b/src/com/android/bluetooth/avrcp/AvrcpControllerService.java
index e880fdfa9..1d8e3aba5 100644
--- a/src/com/android/bluetooth/avrcp/AvrcpControllerService.java
+++ b/src/com/android/bluetooth/avrcp/AvrcpControllerService.java
@@ -54,7 +54,7 @@ import java.nio.ByteBuffer;
  * @hide
  */
 public class AvrcpControllerService extends ProfileService {
-    private static final boolean DBG = false;
+    private static final boolean DBG = true;
     private static final String TAG = "AvrcpControllerService";
 
     //private Context mContext;
diff --git a/src/com/android/bluetooth/hfp/AtPhonebook.java b/src/com/android/bluetooth/hfp/AtPhonebook.java
index 868733a35..ffa654123 100755
--- a/src/com/android/bluetooth/hfp/AtPhonebook.java
+++ b/src/com/android/bluetooth/hfp/AtPhonebook.java
@@ -243,7 +243,7 @@ public class AtPhonebook {
                 while (pb.endsWith("\"")) pb = pb.substring(0, pb.length() - 1);
                 while (pb.startsWith("\"")) pb = pb.substring(1, pb.length());
                 if (getPhonebookResult(pb, false) == null && !"SM".equals(pb)) {
-                   if (DBG) log("Dont know phonebook: '" + pb + "'");
+                   log("Dont know phonebook: '" + pb + "'");
                    atCommandErrorCode = BluetoothCmeError.OPERATION_NOT_ALLOWED;
                    break;
                 }
@@ -530,7 +530,7 @@ public class AtPhonebook {
                     }
                     c.close();
                 }
-                if (DBG && name == null) log("Caller ID lookup failed for " + number);
+                if (name == null) log("Caller ID lookup failed for " + number);
 
             } else if (pbr.nameColumn != -1) {
                 name = pbr.cursor.getString(pbr.nameColumn);
diff --git a/src/com/android/bluetooth/hfp/HeadsetService.java b/src/com/android/bluetooth/hfp/HeadsetService.java
index 562d005fc..af4124b28 100755
--- a/src/com/android/bluetooth/hfp/HeadsetService.java
+++ b/src/com/android/bluetooth/hfp/HeadsetService.java
@@ -44,7 +44,7 @@ import java.util.Map;
  * @hide
  */
 public class HeadsetService extends ProfileService {
-    private static final boolean DBG = false;
+    private static final boolean DBG = Log.isLoggable("Handsfree", Log.VERBOSE);
     private static final String TAG = "HeadsetService";
     private static final String MODIFY_PHONE_STATE = android.Manifest.permission.MODIFY_PHONE_STATE;
 
@@ -105,8 +105,7 @@ public class HeadsetService extends ProfileService {
                     mStateMachine.sendMessage(HeadsetStateMachine.INTENT_SCO_VOLUME_CHANGED,
                                               intent);
                 }
-            }
-            else if (action.equals(BluetoothDevice.ACTION_CONNECTION_ACCESS_REPLY)) {
+            } else if (action.equals(BluetoothDevice.ACTION_CONNECTION_ACCESS_REPLY)) {
                 int requestType = intent.getIntExtra(BluetoothDevice.EXTRA_ACCESS_REQUEST_TYPE,
                                                BluetoothDevice.REQUEST_TYPE_PHONEBOOK_ACCESS);
                 if (requestType == BluetoothDevice.REQUEST_TYPE_PHONEBOOK_ACCESS) {
@@ -160,7 +159,9 @@ public class HeadsetService extends ProfileService {
         public boolean disconnect(BluetoothDevice device) {
             HeadsetService service = getService();
             if (service == null) return false;
+
             if (DBG) Log.d(TAG, "disconnect in HeadsetService");
+
             return service.disconnect(device);
         }
 
@@ -306,10 +307,12 @@ public class HeadsetService extends ProfileService {
     //API methods
     public static synchronized HeadsetService getHeadsetService(){
         if (sHeadsetService != null && sHeadsetService.isAvailable()) {
-            if (DBG) Log.d(TAG, "getHeadsetService(): returning " + sHeadsetService);
+            if (DBG) {
+                Log.d(TAG, "getHeadsetService(): returning " + sHeadsetService);
+            }
             return sHeadsetService;
         }
-        if (DBG)  {
+        if (DBG) {
             if (sHeadsetService == null) {
                 Log.d(TAG, "getHeadsetService(): service is NULL");
             } else if (!(sHeadsetService.isAvailable())) {
@@ -321,10 +324,12 @@ public class HeadsetService extends ProfileService {
 
     private static synchronized void setHeadsetService(HeadsetService instance) {
         if (instance != null && instance.isAvailable()) {
-            if (DBG) Log.d(TAG, "setHeadsetService(): set to: " + sHeadsetService);
+            if (DBG) {
+                Log.d(TAG, "setHeadsetService(): set to: " + sHeadsetService);
+            }
             sHeadsetService = instance;
         } else {
-            if (DBG)  {
+            if (DBG) {
                 if (sHeadsetService == null) {
                     Log.d(TAG, "setHeadsetService(): service not available");
                 } else if (!sHeadsetService.isAvailable()) {
@@ -391,7 +396,9 @@ public class HeadsetService extends ProfileService {
         Settings.Global.putInt(getContentResolver(),
             Settings.Global.getBluetoothHeadsetPriorityKey(device.getAddress()),
             priority);
-        if (DBG) Log.d(TAG, "Saved priority " + device + " = " + priority);
+        if (DBG) {
+            Log.d(TAG, "Saved priority " + device + " = " + priority);
+        }
         return true;
     }
 
@@ -406,6 +413,9 @@ public class HeadsetService extends ProfileService {
 
     boolean startVoiceRecognition(BluetoothDevice device) {
         enforceCallingOrSelfPermission(BLUETOOTH_PERM, "Need BLUETOOTH permission");
+        if (DBG) {
+            Log.d(TAG, "startVoiceRecognition");
+        }
         int connectionState = mStateMachine.getConnectionState(device);
         if (connectionState != BluetoothProfile.STATE_CONNECTED &&
             connectionState != BluetoothProfile.STATE_CONNECTING) {
@@ -417,6 +427,9 @@ public class HeadsetService extends ProfileService {
 
     boolean stopVoiceRecognition(BluetoothDevice device) {
         enforceCallingOrSelfPermission(BLUETOOTH_PERM, "Need BLUETOOTH permission");
+        if (DBG) {
+            Log.d(TAG, "stopVoiceRecognition");
+        }
         // It seem that we really need to check the AudioOn state.
         // But since we allow startVoiceRecognition in STATE_CONNECTED and
         // STATE_CONNECTING state, we do these 2 in this method
diff --git a/src/com/android/bluetooth/hfp/HeadsetStateMachine.java b/src/com/android/bluetooth/hfp/HeadsetStateMachine.java
index 8ac840fb7..9da73c313 100644..100755
--- a/src/com/android/bluetooth/hfp/HeadsetStateMachine.java
+++ b/src/com/android/bluetooth/hfp/HeadsetStateMachine.java
@@ -79,7 +79,7 @@ import android.os.SystemProperties;
 
 final class HeadsetStateMachine extends StateMachine {
     private static final String TAG = "HeadsetStateMachine";
-    private static final boolean DBG = false;
+    private static final boolean DBG = Log.isLoggable("Handsfree", Log.VERBOSE);
     //For Debugging only
     private static int sRefCount=0;
 
@@ -289,6 +289,7 @@ final class HeadsetStateMachine extends StateMachine {
 
 
     public void doQuit() {
+        log("quit");
         quitNow();
     }
 
@@ -343,7 +344,7 @@ final class HeadsetStateMachine extends StateMachine {
     private class Disconnected extends State {
         @Override
         public void enter() {
-            log("Enter Disconnected: " + getCurrentMessage().what +
+            Log.d(TAG, "Enter Disconnected: " + getCurrentMessage().what +
                                 ", size: " + mConnectedDevicesList.size());
             mPhonebook.resetAtState();
             mPhoneState.listenForPhoneState(false);
@@ -354,7 +355,7 @@ final class HeadsetStateMachine extends StateMachine {
 
         @Override
         public boolean processMessage(Message message) {
-            log("Disconnected process message: " + message.what +
+            Log.d(TAG, "Disconnected process message: " + message.what +
                                 ", size: " + mConnectedDevicesList.size());
             if (mConnectedDevicesList.size() != 0 || mTargetDevice != null ||
                                 mIncomingDevice != null) {
@@ -430,9 +431,7 @@ final class HeadsetStateMachine extends StateMachine {
                     break;
                 case STACK_EVENT:
                     StackEvent event = (StackEvent) message.obj;
-                    if (DBG) {
-                        log("event type: " + event.type);
-                    }
+                    Log.d(TAG, "event type: " + event.type);
                     switch (event.type) {
                         case EVENT_TYPE_CONNECTION_STATE_CHANGED:
                             processConnectionEvent(event.valueInt, event.device);
@@ -450,20 +449,21 @@ final class HeadsetStateMachine extends StateMachine {
 
         @Override
         public void exit() {
-            log("Exit Disconnected: " + getCurrentMessage().what);
+            Log.d(TAG, "Exit Disconnected: " + getCurrentMessage().what);
         }
 
         // in Disconnected state
         private void processConnectionEvent(int state, BluetoothDevice device) {
             Log.d(TAG, "processConnectionEvent state = " + state +
-                             ", device = " + device);
+                              ", device = " + device);
             switch (state) {
             case HeadsetHalConstants.CONNECTION_STATE_DISCONNECTED:
-                Log.w(TAG, "Ignore HF DISCONNECTED event, device: " + device);
+                Log.d(TAG, "Ignore HF DISCONNECTED event, device: " + device);
                 break;
             case HeadsetHalConstants.CONNECTION_STATE_CONNECTING:
-                if (okToConnect(device)) {
-                    Log.i(TAG,"Incoming Hf accepted");
+                if (okToConnect(device)){
+                    Log.d(TAG, "Incoming Hf accepted");
+
                     broadcastConnectionState(device, BluetoothProfile.STATE_CONNECTING,
                                              BluetoothProfile.STATE_DISCONNECTED);
                     synchronized (HeadsetStateMachine.this) {
@@ -471,7 +471,7 @@ final class HeadsetStateMachine extends StateMachine {
                         transitionTo(mPending);
                     }
                 } else {
-                    Log.i(TAG,"Incoming Hf rejected. priority=" + mService.getPriority(device)+
+                    Log.d(TAG,"Incoming Hf rejected. priority=" + mService.getPriority(device)+
                               " bondState=" + device.getBondState());
                     //reject the connection and stay in Disconnected state itself
                     disconnectHfpNative(getByteAddress(device));
@@ -484,7 +484,7 @@ final class HeadsetStateMachine extends StateMachine {
                 }
                 break;
             case HeadsetHalConstants.CONNECTION_STATE_CONNECTED:
-                Log.w(TAG, "HFP Connected from Disconnected state");
+                Log.d(TAG, "HFP Connected from Disconnected state");
                 if (okToConnect(device)) {
                     Log.d(TAG, "Incoming Hf accepted");
                     if (mPhoneProxy != null) {
@@ -509,7 +509,7 @@ final class HeadsetStateMachine extends StateMachine {
                     configAudioParameters(device);
                 } else {
                     //reject the connection and stay in Disconnected state itself
-                    Log.i(TAG,"Incoming Hf rejected. priority=" + mService.getPriority(device) +
+                    Log.d(TAG, "Incoming Hf rejected. priority=" + mService.getPriority(device) +
                               " bondState=" + device.getBondState());
                     disconnectHfpNative(getByteAddress(device));
                     // the other profile connection should be initiated
@@ -521,7 +521,7 @@ final class HeadsetStateMachine extends StateMachine {
                 }
                 break;
             case HeadsetHalConstants.CONNECTION_STATE_DISCONNECTING:
-                Log.w(TAG, "Ignore HF DISCONNECTING event, device: " + device);
+                Log.d(TAG, "Ignore HF DISCONNECTING event, device: " + device);
                 break;
             default:
                 Log.e(TAG, "Incorrect state: " + state);
@@ -533,12 +533,12 @@ final class HeadsetStateMachine extends StateMachine {
     private class Pending extends State {
         @Override
         public void enter() {
-            log("Enter Pending: " + getCurrentMessage().what);
+            Log.d(TAG, "Enter Pending: " + getCurrentMessage().what);
         }
 
         @Override
         public boolean processMessage(Message message) {
-            log("Pending process message: " + message.what + ", size: "
+            Log.d(TAG, "Pending process message: " + message.what + ", size: "
                                         + mConnectedDevicesList.size());
 
             boolean retValue = HANDLED;
@@ -574,9 +574,7 @@ final class HeadsetStateMachine extends StateMachine {
                     break;
                 case STACK_EVENT:
                     StackEvent event = (StackEvent) message.obj;
-                    if (DBG) {
-                        log("event type: " + event.type);
-                    }
+                    Log.d(TAG, "event type: " + event.type);
                     switch (event.type) {
                         case EVENT_TYPE_CONNECTION_STATE_CHANGED:
                             BluetoothDevice device1 = getDeviceForMessage(CONNECT_TIMEOUT);
@@ -601,6 +599,7 @@ final class HeadsetStateMachine extends StateMachine {
         private void processConnectionEvent(int state, BluetoothDevice device) {
             Log.d(TAG, "processConnectionEvent state = " + state +
                                               ", device = " + device);
+
             switch (state) {
                 case HeadsetHalConstants.CONNECTION_STATE_DISCONNECTED:
                     if (mConnectedDevicesList.contains(device)) {
@@ -816,8 +815,7 @@ final class HeadsetStateMachine extends StateMachine {
             // devices that previously successfully connected.
             // TODO: This needs to check for multiple HFP connections, once supported...
             removeDeferredMessages(CONNECT);
-
-            log("Enter Connected: " + getCurrentMessage().what +
+            Log.d(TAG, "Enter Connected: " + getCurrentMessage().what +
                            ", size: " + mConnectedDevicesList.size());
             // start phone state listener here so that the CIND response as part of SLC can be
             // responded to, correctly.
@@ -828,8 +826,9 @@ final class HeadsetStateMachine extends StateMachine {
 
         @Override
         public boolean processMessage(Message message) {
-            log("Connected process message: " + message.what +
+            Log.d(TAG, "Connected process message: " + message.what +
                           ", size: " + mConnectedDevicesList.size());
+
             if (DBG) {
                 if (mConnectedDevicesList.size() == 0) {
                     log("ERROR: mConnectedDevicesList is empty in Connected");
@@ -1040,10 +1039,8 @@ final class HeadsetStateMachine extends StateMachine {
                     break;
                 case STACK_EVENT:
                     StackEvent event = (StackEvent) message.obj;
-                    if (DBG) {
-                        log("event type: " + event.type + "event device : "
+                    Log.d(TAG, "event type: " + event.type + "event device : "
                                                   + event.device);
-                    }
                     switch (event.type) {
                         case EVENT_TYPE_CONNECTION_STATE_CHANGED:
                             processConnectionEvent(event.valueInt, event.device);
@@ -1119,8 +1116,8 @@ final class HeadsetStateMachine extends StateMachine {
 
         // in Connected state
         private void processConnectionEvent(int state, BluetoothDevice device) {
-        Log.d(TAG, "processConnectionEvent state = " + state + ", device = "
-                                                           + device);
+            Log.d(TAG, "processConnectionEvent state = " + state +
+                              ", device = " + device);
             switch (state) {
                 case HeadsetHalConstants.CONNECTION_STATE_DISCONNECTED:
                     if (mConnectedDevicesList.contains(device)) {
@@ -1280,19 +1277,18 @@ final class HeadsetStateMachine extends StateMachine {
 
         @Override
         public void enter() {
-            log("Enter AudioOn: " + getCurrentMessage().what + ", size: " +
+            Log.d(TAG, "Enter AudioOn: " + getCurrentMessage().what + ", size: " +
                                   mConnectedDevicesList.size());
+
         }
 
         @Override
         public boolean processMessage(Message message) {
-            log("AudioOn process message: " + message.what + ", size: " +
+            Log.d(TAG, "AudioOn process message: " + message.what + ", size: " +
                                   mConnectedDevicesList.size());
-            if (DBG) {
-                if (mConnectedDevicesList.size() == 0) {
-                    log("ERROR: mConnectedDevicesList is empty in AudioOn");
-                    return NOT_HANDLED;
-                }
+            if (mConnectedDevicesList.size() == 0) {
+                log("ERROR: mConnectedDevicesList is empty in AudioOn");
+                return NOT_HANDLED;
             }
 
             boolean retValue = HANDLED;
@@ -1510,9 +1506,7 @@ final class HeadsetStateMachine extends StateMachine {
                     break;
                 case STACK_EVENT:
                     StackEvent event = (StackEvent) message.obj;
-                    if (DBG) {
-                        log("event type: " + event.type);
-                    }
+                    Log.d(TAG, "event type: " + event.type);
                     switch (event.type) {
                         case EVENT_TYPE_CONNECTION_STATE_CHANGED:
                             BluetoothDevice device1 = getDeviceForMessage(CONNECT_TIMEOUT);
@@ -1587,6 +1581,7 @@ final class HeadsetStateMachine extends StateMachine {
 
         // in AudioOn state. Some headsets disconnect RFCOMM prior to SCO down. Handle this
         private void processConnectionEvent(int state, BluetoothDevice device) {
+
         Log.d(TAG, "processConnectionEvent state = " + state + ", device = " +
                                                    device);
             switch (state) {
@@ -2073,6 +2068,7 @@ final class HeadsetStateMachine extends StateMachine {
                         Log.i(TAG,"Incoming Hf accepted");
                         broadcastConnectionState(device, BluetoothProfile.STATE_CONNECTED,
                                          BluetoothProfile.STATE_DISCONNECTED);
+
                         synchronized (HeadsetStateMachine.this) {
                             if (!mConnectedDevicesList.contains(device)) {
                                 mCurrentDevice = device;
@@ -2543,7 +2539,7 @@ final class HeadsetStateMachine extends StateMachine {
 
     // This method does not check for error conditon (newState == prevState)
     private void broadcastConnectionState(BluetoothDevice device, int newState, int prevState) {
-        log("Connection state " + device + ": " + prevState + "->" + newState);
+        Log.d(TAG, "Connection state " + device + ": " + prevState + "->" + newState);
         if(prevState == BluetoothProfile.STATE_CONNECTED) {
             // Headset is disconnecting, stop Virtual call if active.
             terminateScoUsingVirtualVoiceCall();
@@ -2574,7 +2570,9 @@ final class HeadsetStateMachine extends StateMachine {
         intent.putExtra(BluetoothDevice.EXTRA_DEVICE, device);
         mService.sendBroadcastAsUser(intent, UserHandle.ALL,
                 HeadsetService.BLUETOOTH_PERM);
-        log("Audio state " + device + ": " + prevState + "->" + newState);
+        Log.d(TAG, "Audio state " + device + ": " + prevState + "->" + newState);
+
+
     }
 
     /*
@@ -2739,6 +2737,7 @@ final class HeadsetStateMachine extends StateMachine {
             }
         }
 
+
         // 2. Send virtual phone state changed to initialize SCO
         processCallState(new HeadsetCallState(0, 0,
             HeadsetHalConstants.CALL_STATE_DIALING, "", 0), true);
@@ -2846,6 +2845,7 @@ final class HeadsetStateMachine extends StateMachine {
         if(device == null) {
             Log.w(TAG, "processAnswerCall device is null");
             return;
+
         }
 
         if (mPhoneProxy != null) {
@@ -3023,6 +3023,7 @@ final class HeadsetStateMachine extends StateMachine {
                 terminateScoUsingVirtualVoiceCall();
             }
 
+
             // Specific handling for case of starting MO/MT call while VOIP
             // ongoing, terminateScoUsingVirtualVoiceCall() resets callState
             // INCOMING/DIALING to IDLE. Some HS send AT+CIND? to read call
@@ -3030,6 +3031,7 @@ final class HeadsetStateMachine extends StateMachine {
             // SCO for VOIP call is not terminated via SDK API call.
             if (mPhoneState.getCallState() != callState.mCallState) {
                 mPhoneState.setCallState(callState.mCallState);
+
             }
 
             // at this step: if there is virtual call ongoing, it means there is no CSV call