Audio event logging

New class AudioEventLogger to store a configurable number of the
  last audio events. It hosts a circular buffer of lightweight
  event objects, an abstract class whose implementations are
  event-specific, and does the heavier string manipulations
  at the time of the dump, not during normal operation.
Add logging for:
  - phone state (a.k.a. audio mode) changes
  - wired device connections
  - playback activity monitor
  - force use

Test: adb shell dumpsys audio
Bug: 64470715
Change-Id: I8dbd936e2ffec39134f1a8837191c74f5cb9fc56

diff --git a/media/java/android/media/AudioSystem.java b/media/java/android/media/AudioSystem.java
index bfb81a0..e56944d 100644 (file)
--- a/media/java/android/media/AudioSystem.java
+++ b/media/java/android/media/AudioSystem.java
@@ -113,6 +113,17 @@ public class AudioSystem
     public static final int MODE_IN_COMMUNICATION   = 3;
     public static final int NUM_MODES               = 4;
 
+    public static String modeToString(int mode) {
+        switch (mode) {
+            case MODE_CURRENT: return "MODE_CURRENT";
+            case MODE_IN_CALL: return "MODE_IN_CALL";
+            case MODE_IN_COMMUNICATION: return "MODE_IN_COMMUNICATION";
+            case MODE_INVALID: return "MODE_INVALID";
+            case MODE_NORMAL: return "MODE_NORMAL";
+            case MODE_RINGTONE: return "MODE_RINGTONE";
+            default: return "unknown mode (" + mode + ")";
+        }
+    }
 
     /* Routing bits for the former setRouting/getRouting API */
     /** @deprecated */
@@ -498,6 +509,14 @@ public class AudioSystem
     public static final int DEVICE_STATE_AVAILABLE = 1;
     private static final int NUM_DEVICE_STATES = 1;
 
+    public static String deviceStateToString(int state) {
+        switch (state) {
+            case DEVICE_STATE_UNAVAILABLE: return "DEVICE_STATE_UNAVAILABLE";
+            case DEVICE_STATE_AVAILABLE: return "DEVICE_STATE_AVAILABLE";
+            default: return "unknown state (" + state + ")";
+        }
+    }
+
     public static final String DEVICE_OUT_EARPIECE_NAME = "earpiece";
     public static final String DEVICE_OUT_SPEAKER_NAME = "speaker";
     public static final String DEVICE_OUT_WIRED_HEADSET_NAME = "headset";
@@ -693,6 +712,27 @@ public class AudioSystem
     public static final int NUM_FORCE_CONFIG = 15;
     public static final int FORCE_DEFAULT = FORCE_NONE;
 
+    public static String forceUseConfigToString(int config) {
+        switch (config) {
+            case FORCE_NONE: return "FORCE_NONE";
+            case FORCE_SPEAKER: return "FORCE_SPEAKER";
+            case FORCE_HEADPHONES: return "FORCE_HEADPHONES";
+            case FORCE_BT_SCO: return "FORCE_BT_SCO";
+            case FORCE_BT_A2DP: return "FORCE_BT_A2DP";
+            case FORCE_WIRED_ACCESSORY: return "FORCE_WIRED_ACCESSORY";
+            case FORCE_BT_CAR_DOCK: return "FORCE_BT_CAR_DOCK";
+            case FORCE_BT_DESK_DOCK: return "FORCE_BT_DESK_DOCK";
+            case FORCE_ANALOG_DOCK: return "FORCE_ANALOG_DOCK";
+            case FORCE_DIGITAL_DOCK: return "FORCE_DIGITAL_DOCK";
+            case FORCE_NO_BT_A2DP: return "FORCE_NO_BT_A2DP";
+            case FORCE_SYSTEM_ENFORCED: return "FORCE_SYSTEM_ENFORCED";
+            case FORCE_HDMI_SYSTEM_AUDIO_ENFORCED: return "FORCE_HDMI_SYSTEM_AUDIO_ENFORCED";
+            case FORCE_ENCODED_SURROUND_NEVER: return "FORCE_ENCODED_SURROUND_NEVER";
+            case FORCE_ENCODED_SURROUND_ALWAYS: return "FORCE_ENCODED_SURROUND_ALWAYS";
+            default: return "unknown config (" + config + ")" ;
+        }
+    }
+
     // usage for setForceUse, must match audio_policy_force_use_t
     public static final int FOR_COMMUNICATION = 0;
     public static final int FOR_MEDIA = 1;
@@ -703,6 +743,19 @@ public class AudioSystem
     public static final int FOR_ENCODED_SURROUND = 6;
     private static final int NUM_FORCE_USE = 7;
 
+    public static String forceUseUsageToString(int usage) {
+        switch (usage) {
+            case FOR_COMMUNICATION: return "FOR_COMMUNICATION";
+            case FOR_MEDIA: return "FOR_MEDIA";
+            case FOR_RECORD: return "FOR_RECORD";
+            case FOR_DOCK: return "FOR_DOCK";
+            case FOR_SYSTEM: return "FOR_SYSTEM";
+            case FOR_HDMI_SYSTEM_AUDIO: return "FOR_HDMI_SYSTEM_AUDIO";
+            case FOR_ENCODED_SURROUND: return "FOR_ENCODED_SURROUND";
+            default: return "unknown usage (" + usage + ")" ;
+        }
+    }
+
     // usage for AudioRecord.startRecordingSync(), must match AudioSystem::sync_event_t
     public static final int SYNC_EVENT_NONE = 0;
     public static final int SYNC_EVENT_PRESENTATION_COMPLETE = 1;

diff --git a/services/core/java/com/android/server/audio/AudioEventLogger.java b/services/core/java/com/android/server/audio/AudioEventLogger.java
new file mode 100644 (file)
index 0000000..c96138f
--- /dev/null
+++ b/services/core/java/com/android/server/audio/AudioEventLogger.java
@@ -0,0 +1,97 @@
+/*
+ * Copyright (C) 2017 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.audio;
+
+import java.io.PrintWriter;
+import java.text.SimpleDateFormat;
+import java.util.Date;
+import java.util.LinkedList;
+
+public class AudioEventLogger {
+
+    // ring buffer of events to log.
+    private final LinkedList<Event> mEvents;
+
+    private final String mTitle;
+
+    // the maximum number of events to keep in log
+    private final int mMemSize;
+
+    public static abstract class Event {
+        // formatter for timestamps
+        private final static SimpleDateFormat sFormat = new SimpleDateFormat("MM-dd HH:mm:ss:SSS");
+
+        private final long mTimestamp;
+
+        Event() {
+            mTimestamp = System.currentTimeMillis();
+        }
+
+        public String toString() {
+            return (new StringBuilder(sFormat.format(new Date(mTimestamp))))
+                    .append(" ").append(eventToString()).toString();
+        }
+
+        /**
+         * Convert event to String.
+         * This method is only called when the logger history is about to the dumped,
+         * so this method is where expensive String conversions should be made, not when the Event
+         * subclass is created.
+         * Timestamp information will be automatically added, do not include it.
+         * @return a string representation of the event that occurred.
+         */
+        abstract public String eventToString();
+    }
+
+    public static class StringEvent extends Event {
+        private final String mMsg;
+
+        public StringEvent(String msg) {
+            mMsg = msg;
+        }
+
+        @Override
+        public String eventToString() {
+            return mMsg;
+        }
+    }
+
+    /**
+     * Constructor for logger.
+     * @param size the maximum number of events to keep in log
+     * @param title the string displayed before the recorded log
+     */
+    public AudioEventLogger(int size, String title) {
+        mEvents = new LinkedList<Event>();
+        mMemSize = size;
+        mTitle = title;
+    }
+
+    public synchronized void log(Event evt) {
+        if (mEvents.size() >= mMemSize) {
+            mEvents.removeFirst();
+        }
+        mEvents.add(evt);
+    }
+
+    public synchronized void dump(PrintWriter pw) {
+        pw.println("Audio event log: " + mTitle);
+        for (Event evt : mEvents) {
+            pw.println(evt.toString());
+        }
+    }
+}

diff --git a/services/core/java/com/android/server/audio/AudioService.java b/services/core/java/com/android/server/audio/AudioService.java
index 8de13bb..5038106 100644 (file)
--- a/services/core/java/com/android/server/audio/AudioService.java
+++ b/services/core/java/com/android/server/audio/AudioService.java
@@ -718,7 +718,7 @@ public class AudioService extends IAudioService.Stub
                 AudioSystem.FOR_SYSTEM,
                 cameraSoundForced ?
                         AudioSystem.FORCE_SYSTEM_ENFORCED : AudioSystem.FORCE_NONE,
-                null,
+                new String("AudioService ctor"),
                 0);
 
         mSafeMediaVolumeState = new Integer(Settings.Global.getInt(mContentResolver,
@@ -896,13 +896,23 @@ public class AudioService extends IAudioService.Stub
             }
         }
         // Restore call state
-        AudioSystem.setPhoneState(mMode);
+        if (AudioSystem.setPhoneState(mMode) ==  AudioSystem.AUDIO_STATUS_OK) {
+            mModeLogger.log(new AudioEventLogger.StringEvent(
+                "onAudioServerDied causes setPhoneState(" + AudioSystem.modeToString(mMode) + ")"));
+        }
 
-        // Restore forced usage for communcations and record
+        // Restore forced usage for communications and record
+        mForceUseLogger.log(new ForceUseEvent(AudioSystem.FOR_COMMUNICATION, mForcedUseForComm,
+                "onAudioServerDied"));
         AudioSystem.setForceUse(AudioSystem.FOR_COMMUNICATION, mForcedUseForComm);
+        mForceUseLogger.log(new ForceUseEvent(AudioSystem.FOR_RECORD, mForcedUseForComm,
+                "onAudioServerDied"));
         AudioSystem.setForceUse(AudioSystem.FOR_RECORD, mForcedUseForComm);
-        AudioSystem.setForceUse(AudioSystem.FOR_SYSTEM, mCameraSoundForced ?
-                        AudioSystem.FORCE_SYSTEM_ENFORCED : AudioSystem.FORCE_NONE);
+        final int forSys = mCameraSoundForced ?
+                AudioSystem.FORCE_SYSTEM_ENFORCED : AudioSystem.FORCE_NONE;
+        mForceUseLogger.log(new ForceUseEvent(AudioSystem.FOR_SYSTEM, forSys,
+                "onAudioServerDied"));
+        AudioSystem.setForceUse(AudioSystem.FOR_SYSTEM, forSys);
 
         // Restore stream volumes
         int numStreamTypes = AudioSystem.getNumStreamTypes();
@@ -929,16 +939,20 @@ public class AudioService extends IAudioService.Stub
         }
 
         synchronized (mBluetoothA2dpEnabledLock) {
-            AudioSystem.setForceUse(AudioSystem.FOR_MEDIA,
-                    mBluetoothA2dpEnabled ?
-                            AudioSystem.FORCE_NONE : AudioSystem.FORCE_NO_BT_A2DP);
+            final int forMed = mBluetoothA2dpEnabled ?
+                    AudioSystem.FORCE_NONE : AudioSystem.FORCE_NO_BT_A2DP;
+            mForceUseLogger.log(new ForceUseEvent(AudioSystem.FOR_MEDIA, forMed,
+                    "onAudioServerDied"));
+            AudioSystem.setForceUse(AudioSystem.FOR_MEDIA, forMed);
         }
 
         synchronized (mSettingsLock) {
-            AudioSystem.setForceUse(AudioSystem.FOR_DOCK,
-                    mDockAudioMediaEnabled ?
-                            AudioSystem.FORCE_ANALOG_DOCK : AudioSystem.FORCE_NONE);
-            sendEncodedSurroundMode(mContentResolver);
+            final int forDock = mDockAudioMediaEnabled ?
+                    AudioSystem.FORCE_ANALOG_DOCK : AudioSystem.FORCE_NONE;
+            mForceUseLogger.log(new ForceUseEvent(AudioSystem.FOR_DOCK, forDock,
+                    "onAudioServerDied"));
+            AudioSystem.setForceUse(AudioSystem.FOR_DOCK, forDock);
+            sendEncodedSurroundMode(mContentResolver, "onAudioServerDied");
         }
         if (mHdmiManager != null) {
             synchronized (mHdmiManager) {
@@ -1131,7 +1145,7 @@ public class AudioService extends IAudioService.Stub
                 AudioSystem.FOR_DOCK,
                 mDockAudioMediaEnabled ?
                         AudioSystem.FORCE_ANALOG_DOCK : AudioSystem.FORCE_NONE,
-                null,
+                new String("readDockAudioSettings"),
                 0);
     }
 
@@ -1146,15 +1160,15 @@ public class AudioService extends IAudioService.Stub
         AudioSystem.setMasterMono(masterMono);
     }
 
-    private void sendEncodedSurroundMode(ContentResolver cr)
+    private void sendEncodedSurroundMode(ContentResolver cr, String eventSource)
     {
         int encodedSurroundMode = Settings.Global.getInt(
                 cr, Settings.Global.ENCODED_SURROUND_OUTPUT,
                 Settings.Global.ENCODED_SURROUND_OUTPUT_AUTO);
-        sendEncodedSurroundMode(encodedSurroundMode);
+        sendEncodedSurroundMode(encodedSurroundMode, eventSource);
     }
 
-    private void sendEncodedSurroundMode(int encodedSurroundMode)
+    private void sendEncodedSurroundMode(int encodedSurroundMode, String eventSource)
     {
         // initialize to guaranteed bad value
         int forceSetting = AudioSystem.NUM_FORCE_CONFIG;
@@ -1179,7 +1193,7 @@ public class AudioService extends IAudioService.Stub
                     SENDMSG_QUEUE,
                     AudioSystem.FOR_ENCODED_SURROUND,
                     forceSetting,
-                    null,
+                    eventSource,
                     0);
         }
     }
@@ -1225,7 +1239,7 @@ public class AudioService extends IAudioService.Stub
 
             updateRingerModeAffectedStreams();
             readDockAudioSettings(cr);
-            sendEncodedSurroundMode(cr);
+            sendEncodedSurroundMode(cr, "readPersistedSettings");
         }
 
         mMuteAffectedStreams = System.getIntForUser(cr,
@@ -2542,6 +2556,7 @@ public class AudioService extends IAudioService.Stub
                 if (status == AudioSystem.AUDIO_STATUS_OK) {
                     if (DEBUG_MODE) { Log.v(TAG, " mode successfully set to " + mode); }
                     mMode = mode;
+                    mModeLogger.log(new PhoneStateEvent(caller, pid, mode));
                 } else {
                     if (hdlr != null) {
                         mSetModeDeathHandlers.remove(hdlr);
@@ -2836,11 +2851,16 @@ public class AudioService extends IAudioService.Stub
         if (!checkAudioSettingsPermission("setSpeakerphoneOn()")) {
             return;
         }
+        // for logging only
+        final String eventSource = new StringBuilder("setSpeakerphoneOn(").append(on)
+                .append(") from u/pid:").append(Binder.getCallingUid()).append("/")
+                .append(Binder.getCallingPid()).toString();
 
         if (on) {
             if (mForcedUseForComm == AudioSystem.FORCE_BT_SCO) {
                     sendMsg(mAudioHandler, MSG_SET_FORCE_USE, SENDMSG_QUEUE,
-                            AudioSystem.FOR_RECORD, AudioSystem.FORCE_NONE, null, 0);
+                            AudioSystem.FOR_RECORD, AudioSystem.FORCE_NONE,
+                            eventSource, 0);
             }
             mForcedUseForComm = AudioSystem.FORCE_SPEAKER;
         } else if (mForcedUseForComm == AudioSystem.FORCE_SPEAKER){
@@ -2848,7 +2868,7 @@ public class AudioService extends IAudioService.Stub
         }
 
         sendMsg(mAudioHandler, MSG_SET_FORCE_USE, SENDMSG_QUEUE,
-                AudioSystem.FOR_COMMUNICATION, mForcedUseForComm, null, 0);
+                AudioSystem.FOR_COMMUNICATION, mForcedUseForComm, eventSource, 0);
     }
 
     /** @see AudioManager#isSpeakerphoneOn() */
@@ -2861,10 +2881,14 @@ public class AudioService extends IAudioService.Stub
         if (!checkAudioSettingsPermission("setBluetoothScoOn()")) {
             return;
         }
-        setBluetoothScoOnInt(on);
+        // for logging only
+        final String eventSource = new StringBuilder("setBluetoothScoOn(").append(on)
+                .append(") from u/pid:").append(Binder.getCallingUid()).append("/")
+                .append(Binder.getCallingPid()).toString();
+        setBluetoothScoOnInt(on, eventSource);
     }
 
-    public void setBluetoothScoOnInt(boolean on) {
+    public void setBluetoothScoOnInt(boolean on, String eventSource) {
         if (on) {
             mForcedUseForComm = AudioSystem.FORCE_BT_SCO;
         } else if (mForcedUseForComm == AudioSystem.FORCE_BT_SCO) {
@@ -2872,9 +2896,9 @@ public class AudioService extends IAudioService.Stub
         }
 
         sendMsg(mAudioHandler, MSG_SET_FORCE_USE, SENDMSG_QUEUE,
-                AudioSystem.FOR_COMMUNICATION, mForcedUseForComm, null, 0);
+                AudioSystem.FOR_COMMUNICATION, mForcedUseForComm, eventSource, 0);
         sendMsg(mAudioHandler, MSG_SET_FORCE_USE, SENDMSG_QUEUE,
-                AudioSystem.FOR_RECORD, mForcedUseForComm, null, 0);
+                AudioSystem.FOR_RECORD, mForcedUseForComm, eventSource, 0);
     }
 
     /** @see AudioManager#isBluetoothScoOn() */
@@ -2884,12 +2908,17 @@ public class AudioService extends IAudioService.Stub
 
     /** @see AudioManager#setBluetoothA2dpOn(boolean) */
     public void setBluetoothA2dpOn(boolean on) {
+        // for logging only
+        final String eventSource = new StringBuilder("setBluetoothA2dpOn(").append(on)
+                .append(") from u/pid:").append(Binder.getCallingUid()).append("/")
+                .append(Binder.getCallingPid()).toString();
+
         synchronized (mBluetoothA2dpEnabledLock) {
             mBluetoothA2dpEnabled = on;
             sendMsg(mAudioHandler, MSG_SET_FORCE_BT_A2DP_USE, SENDMSG_QUEUE,
                     AudioSystem.FOR_MEDIA,
                     mBluetoothA2dpEnabled ? AudioSystem.FORCE_NONE : AudioSystem.FORCE_NO_BT_A2DP,
-                    null, 0);
+                    eventSource, 0);
         }
     }
 
@@ -3226,7 +3255,7 @@ public class AudioService extends IAudioService.Stub
             broadcastScoConnectionState(AudioManager.SCO_AUDIO_STATE_DISCONNECTED);
         }
         AudioSystem.setParameters("A2dpSuspended=false");
-        setBluetoothScoOnInt(false);
+        setBluetoothScoOnInt(false, "resetBluetoothSco");
     }
 
     private void broadcastScoConnectionState(int state) {
@@ -4837,9 +4866,9 @@ public class AudioService extends IAudioService.Stub
             }
         }
 
-        private void setForceUse(int usage, int config) {
+        private void setForceUse(int usage, int config, String eventSource) {
             synchronized (mConnectedDevices) {
-                setForceUseInt_SyncDevices(usage, config);
+                setForceUseInt_SyncDevices(usage, config, eventSource);
             }
         }
 
@@ -4905,7 +4934,7 @@ public class AudioService extends IAudioService.Stub
 
                 case MSG_SET_FORCE_USE:
                 case MSG_SET_FORCE_BT_A2DP_USE:
-                    setForceUse(msg.arg1, msg.arg2);
+                    setForceUse(msg.arg1, msg.arg2, (String) msg.obj);
                     break;
 
                 case MSG_BT_HEADSET_CNCT_FAILED:
@@ -4915,6 +4944,7 @@ public class AudioService extends IAudioService.Stub
                 case MSG_SET_WIRED_DEVICE_CONNECTION_STATE:
                     {   WiredDeviceConnectionState connectState =
                             (WiredDeviceConnectionState)msg.obj;
+                        mWiredDevLogger.log(new WiredDevConnectEvent(connectState));
                         onSetWiredDeviceConnectionState(connectState.mType, connectState.mState,
                                 connectState.mAddress, connectState.mName, connectState.mCaller);
                         mAudioEventWakeLock.release();
@@ -5062,7 +5092,7 @@ public class AudioService extends IAudioService.Stub
             // Did it change?
             if (mEncodedSurroundMode != newSurroundMode) {
                 // Send to AudioPolicyManager
-                sendEncodedSurroundMode(newSurroundMode);
+                sendEncodedSurroundMode(newSurroundMode, "SettingsObserver");
                 synchronized(mConnectedDevices) {
                     // Is HDMI connected?
                     String key = makeDeviceListKey(AudioSystem.DEVICE_OUT_HDMI, "");
@@ -5083,13 +5113,13 @@ public class AudioService extends IAudioService.Stub
     }
 
     // must be called synchronized on mConnectedDevices
-    private void makeA2dpDeviceAvailable(String address, String name) {
+    private void makeA2dpDeviceAvailable(String address, String name, String eventSource) {
         // enable A2DP before notifying A2DP connection to avoid unnecessary processing in
         // audio policy manager
         VolumeStreamState streamState = mStreamStates[AudioSystem.STREAM_MUSIC];
         sendMsg(mAudioHandler, MSG_SET_DEVICE_VOLUME, SENDMSG_QUEUE,
                 AudioSystem.DEVICE_OUT_BLUETOOTH_A2DP, 0, streamState, 0);
-        setBluetoothA2dpOnInt(true);
+        setBluetoothA2dpOnInt(true, eventSource);
         AudioSystem.setDeviceConnectionState(AudioSystem.DEVICE_OUT_BLUETOOTH_A2DP,
                 AudioSystem.DEVICE_STATE_AVAILABLE, address, name);
         // Reset A2DP suspend state each time a new sink is connected
@@ -5218,7 +5248,8 @@ public class AudioService extends IAudioService.Stub
                         makeA2dpDeviceUnavailableNow(mDockAddress);
                     }
                 }
-                makeA2dpDeviceAvailable(address, btDevice.getName());
+                makeA2dpDeviceAvailable(address, btDevice.getName(),
+                        "onSetA2dpSinkConnectionState");
                 synchronized (mCurAudioRoutes) {
                     String name = btDevice.getAliasName();
                     if (!TextUtils.equals(mCurAudioRoutes.bluetoothName, name)) {
@@ -5505,7 +5536,7 @@ public class AudioService extends IAudioService.Stub
 
         synchronized (mConnectedDevices) {
             if ((state == 0) && ((device & DEVICE_OVERRIDE_A2DP_ROUTE_ON_PLUG) != 0)) {
-                setBluetoothA2dpOnInt(true);
+                setBluetoothA2dpOnInt(true, "onSetWiredDeviceConnectionState state 0");
             }
 
             if (!handleDeviceConnection(state == 1, device, address, deviceName)) {
@@ -5514,7 +5545,7 @@ public class AudioService extends IAudioService.Stub
             }
             if (state != 0) {
                 if ((device & DEVICE_OVERRIDE_A2DP_ROUTE_ON_PLUG) != 0) {
-                    setBluetoothA2dpOnInt(false);
+                    setBluetoothA2dpOnInt(false, "onSetWiredDeviceConnectionState state not 0");
                 }
                 if ((device & mSafeMediaVolumeDevices) != 0) {
                     sendMsg(mAudioHandler,
@@ -5637,6 +5668,8 @@ public class AudioService extends IAudioService.Stub
                 if (!((dockState == Intent.EXTRA_DOCK_STATE_LE_DESK) ||
                       ((dockState == Intent.EXTRA_DOCK_STATE_UNDOCKED) &&
                        (mDockState == Intent.EXTRA_DOCK_STATE_LE_DESK)))) {
+                    mForceUseLogger.log(new ForceUseEvent(AudioSystem.FOR_DOCK, config,
+                            "ACTION_DOCK_EVENT intent"));
                     AudioSystem.setForceUse(AudioSystem.FOR_DOCK, config);
                 }
                 mDockState = dockState;
@@ -5967,7 +6000,7 @@ public class AudioService extends IAudioService.Stub
                             AudioSystem.FOR_SYSTEM,
                             cameraSoundForced ?
                                     AudioSystem.FORCE_SYSTEM_ENFORCED : AudioSystem.FORCE_NONE,
-                            null,
+                            new String("handleConfigurationChanged"),
                             0);
 
                     sendMsg(mAudioHandler,
@@ -6010,21 +6043,23 @@ public class AudioService extends IAudioService.Stub
 
     // Handles request to override default use of A2DP for media.
     // Must be called synchronized on mConnectedDevices
-    public void setBluetoothA2dpOnInt(boolean on) {
+    public void setBluetoothA2dpOnInt(boolean on, String eventSource) {
         synchronized (mBluetoothA2dpEnabledLock) {
             mBluetoothA2dpEnabled = on;
             mAudioHandler.removeMessages(MSG_SET_FORCE_BT_A2DP_USE);
             setForceUseInt_SyncDevices(AudioSystem.FOR_MEDIA,
-                    mBluetoothA2dpEnabled ? AudioSystem.FORCE_NONE : AudioSystem.FORCE_NO_BT_A2DP);
+                    mBluetoothA2dpEnabled ? AudioSystem.FORCE_NONE : AudioSystem.FORCE_NO_BT_A2DP,
+                            eventSource);
         }
     }
 
     // Must be called synchronized on mConnectedDevices
-    private void setForceUseInt_SyncDevices(int usage, int config) {
+    private void setForceUseInt_SyncDevices(int usage, int config, String eventSource) {
         if (usage == AudioSystem.FOR_MEDIA) {
             sendMsg(mAudioHandler, MSG_REPORT_NEW_ROUTES,
                     SENDMSG_NOOP, 0, 0, null, 0);
         }
+        mForceUseLogger.log(new ForceUseEvent(usage, config, eventSource));
         AudioSystem.setForceUse(usage, config);
     }
 
@@ -6229,9 +6264,11 @@ public class AudioService extends IAudioService.Stub
                 synchronized (mHdmiTvClient) {
                     if (mHdmiSystemAudioSupported != on) {
                         mHdmiSystemAudioSupported = on;
-                        AudioSystem.setForceUse(AudioSystem.FOR_HDMI_SYSTEM_AUDIO,
-                                on ? AudioSystem.FORCE_HDMI_SYSTEM_AUDIO_ENFORCED :
-                                     AudioSystem.FORCE_NONE);
+                        final int config = on ? AudioSystem.FORCE_HDMI_SYSTEM_AUDIO_ENFORCED :
+                            AudioSystem.FORCE_NONE;
+                        mForceUseLogger.log(new ForceUseEvent(AudioSystem.FOR_HDMI_SYSTEM_AUDIO,
+                                config, "setHdmiSystemAudioSupported"));
+                        AudioSystem.setForceUse(AudioSystem.FOR_HDMI_SYSTEM_AUDIO, config);
                     }
                     device = getDevicesForStream(AudioSystem.STREAM_MUSIC);
                 }
@@ -6329,6 +6366,82 @@ public class AudioService extends IAudioService.Stub
         }
     }
 
+    //==========================================================================================
+    // AudioService logging and dumpsys
+    //==========================================================================================
+    final int LOG_NB_EVENTS_PHONE_STATE = 20;
+    final int LOG_NB_EVENTS_WIRED_DEV_CONNECTION = 30;
+    final int LOG_NB_EVENTS_FORCE_USE = 20;
+
+    final private static class PhoneStateEvent extends AudioEventLogger.Event {
+        final String mPackage;
+        final int mPid;
+        final int mMode;
+
+        PhoneStateEvent(String callingPackage, int pid, int mode) {
+            mPackage = callingPackage;
+            mPid = pid;
+            mMode = mode;
+        }
+
+        @Override
+        public String eventToString() {
+            return new StringBuilder("setMode(").append(AudioSystem.modeToString(mMode))
+                    .append(") from package=").append(mPackage)
+                    .append(" pid=").append(mPid).toString();
+        }
+    }
+
+    final private static class WiredDevConnectEvent extends AudioEventLogger.Event {
+        final WiredDeviceConnectionState mState;
+
+        WiredDevConnectEvent(WiredDeviceConnectionState state) {
+            mState = state;
+        }
+
+        @Override
+        public String eventToString() {
+            return new StringBuilder("setWiredDeviceConnectionState(")
+                    .append(" type:").append(Integer.toHexString(mState.mType))
+                    .append(" state:").append(AudioSystem.deviceStateToString(mState.mState))
+                    .append(" addr:").append(mState.mAddress)
+                    .append(" name:").append(mState.mName)
+                    .append(") from ").append(mState.mCaller).toString();
+        }
+    }
+
+    final private static class ForceUseEvent extends AudioEventLogger.Event {
+        final int mUsage;
+        final int mConfig;
+        final String mReason;
+
+        ForceUseEvent(int usage, int config, String reason) {
+            mUsage = usage;
+            mConfig = config;
+            mReason = reason;
+        }
+
+        @Override
+        public String eventToString() {
+            return new StringBuilder("setForceUse(")
+                    .append(AudioSystem.forceUseUsageToString(mUsage))
+                    .append(", ").append(AudioSystem.forceUseConfigToString(mConfig))
+                    .append(") due to ").append(mReason).toString();
+        }
+    }
+
+    final private AudioEventLogger mModeLogger = new AudioEventLogger(LOG_NB_EVENTS_PHONE_STATE,
+            "phone state (logged after successfull call to AudioSystem.setPhoneState(int))");
+
+    final private AudioEventLogger mWiredDevLogger = new AudioEventLogger(
+            LOG_NB_EVENTS_WIRED_DEV_CONNECTION,
+            "wired device connection (logged before onSetWiredDeviceConnectionState() is executed)"
+            );
+
+    final private AudioEventLogger mForceUseLogger = new AudioEventLogger(
+            LOG_NB_EVENTS_FORCE_USE,
+            "force use (logged before setForceUse() is executed)");
+
     private static final String[] RINGER_MODE_NAMES = new String[] {
             "SILENT",
             "VIBRATE",
@@ -6399,6 +6512,13 @@ public class AudioService extends IAudioService.Stub
         mPlaybackMonitor.dump(pw);
 
         mRecordMonitor.dump(pw);
+
+        pw.println("\nEvent logs:");
+        mModeLogger.dump(pw);
+        pw.println("\n");
+        mWiredDevLogger.dump(pw);
+        pw.println("\n");
+        mForceUseLogger.dump(pw);
     }
 
     private static String safeMediaVolumeStateToString(Integer state) {

diff --git a/services/core/java/com/android/server/audio/PlaybackActivityMonitor.java b/services/core/java/com/android/server/audio/PlaybackActivityMonitor.java
index 9ef45ea..c075cdc 100644 (file)
--- a/services/core/java/com/android/server/audio/PlaybackActivityMonitor.java
+++ b/services/core/java/com/android/server/audio/PlaybackActivityMonitor.java
@@ -104,6 +104,9 @@ public final class PlaybackActivityMonitor
             final int index = mBannedUids.indexOf(new Integer(uid));
             if (index >= 0) {
                 if (!disable) {
+                    if (DEBUG) { // hidden behind DEBUG, too noisy otherwise
+                        mEventLogger.log(new AudioEventLogger.StringEvent("unbanning uid:" + uid));
+                    }
                     mBannedUids.remove(index);
                     // nothing else to do, future playback requests from this uid are ok
                 } // no else to handle, uid already present, so disabling again is no-op
@@ -112,6 +115,9 @@ public final class PlaybackActivityMonitor
                     for (AudioPlaybackConfiguration apc : mPlayers.values()) {
                         checkBanPlayer(apc, uid);
                     }
+                    if (DEBUG) { // hidden behind DEBUG, too noisy otherwise
+                        mEventLogger.log(new AudioEventLogger.StringEvent("banning uid:" + uid));
+                    }
                     mBannedUids.add(new Integer(uid));
                 } // no else to handle, uid already not in list, so enabling again is no-op
             }
@@ -145,6 +151,7 @@ public final class PlaybackActivityMonitor
                 new AudioPlaybackConfiguration(pic, newPiid,
                         Binder.getCallingUid(), Binder.getCallingPid());
         apc.init();
+        mEventLogger.log(new NewPlayerEvent(apc));
         synchronized(mPlayerLock) {
             mPlayers.put(newPiid, apc);
         }
@@ -156,6 +163,7 @@ public final class PlaybackActivityMonitor
         synchronized(mPlayerLock) {
             final AudioPlaybackConfiguration apc = mPlayers.get(new Integer(piid));
             if (checkConfigurationCaller(piid, apc, binderUid)) {
+                mEventLogger.log(new AudioAttrEvent(piid, attr));
                 change = apc.handleAudioAttributesEvent(attr);
             } else {
                 Log.e(TAG, "Error updating audio attributes");
@@ -175,10 +183,13 @@ public final class PlaybackActivityMonitor
             if (apc == null) {
                 return;
             }
+            mEventLogger.log(new PlayerEvent(piid, event));
             if (event == AudioPlaybackConfiguration.PLAYER_STATE_STARTED) {
                 for (Integer uidInteger: mBannedUids) {
                     if (checkBanPlayer(apc, uidInteger.intValue())) {
                         // player was banned, do not update its state
+                        mEventLogger.log(new AudioEventLogger.StringEvent(
+                                "not starting piid:" + piid + " ,is banned"));
                         return;
                     }
                 }
@@ -208,6 +219,8 @@ public final class PlaybackActivityMonitor
         synchronized(mPlayerLock) {
             final AudioPlaybackConfiguration apc = mPlayers.get(new Integer(piid));
             if (checkConfigurationCaller(piid, apc, binderUid)) {
+                mEventLogger.log(new AudioEventLogger.StringEvent(
+                        "releasing player piid:" + piid));
                 mPlayers.remove(new Integer(piid));
                 mDuckingManager.removeReleased(apc);
             }
@@ -250,6 +263,8 @@ public final class PlaybackActivityMonitor
                 pw.print(" " + uid);
             }
             pw.println();
+            // log
+            mEventLogger.dump(pw);
         }
     }
 
@@ -672,4 +687,65 @@ public final class PlaybackActivityMonitor
             }
         }
     }
+
+    //=================================================================
+    // For logging
+    private final static class PlayerEvent extends AudioEventLogger.Event {
+        // only keeping the player interface ID as it uniquely identifies the player in the event
+        final int mPlayerIId;
+        final int mState;
+
+        PlayerEvent(int piid, int state) {
+            mPlayerIId = piid;
+            mState = state;
+        }
+
+        @Override
+        public String eventToString() {
+            return new String("player piid:" + mPlayerIId + " state:"
+                    + AudioPlaybackConfiguration.toLogFriendlyPlayerState(mState));
+        }
+    }
+
+    private final static class NewPlayerEvent extends AudioEventLogger.Event {
+        private final int mPlayerIId;
+        private final int mPlayerType;
+        private final int mClientUid;
+        private final int mClientPid;
+        private final AudioAttributes mPlayerAttr;
+
+        NewPlayerEvent(AudioPlaybackConfiguration apc) {
+            mPlayerIId = apc.getPlayerInterfaceId();
+            mPlayerType = apc.getPlayerType();
+            mClientUid = apc.getClientUid();
+            mClientPid = apc.getClientPid();
+            mPlayerAttr = apc.getAudioAttributes();
+        }
+
+        @Override
+        public String eventToString() {
+            return new String("new player piid:" + mPlayerIId + " uid/pid:" + mClientUid + "/"
+                    + mClientPid + " type:"
+                    + AudioPlaybackConfiguration.toLogFriendlyPlayerType(mPlayerType)
+                    + " attr:" + mPlayerAttr);
+        }
+    }
+
+    private final static class AudioAttrEvent extends AudioEventLogger.Event {
+        private final int mPlayerIId;
+        private final AudioAttributes mPlayerAttr;
+
+        AudioAttrEvent(int piid, AudioAttributes attr) {
+            mPlayerIId = piid;
+            mPlayerAttr = attr;
+        }
+
+        @Override
+        public String eventToString() {
+            return new String("player piid:" + mPlayerIId + " new AudioAttributes:" + mPlayerAttr);
+        }
+    }
+
+    private final AudioEventLogger mEventLogger = new AudioEventLogger(100,
+            "playback activity as reported through PlayerBase");
 }