SoundTriggerService logging cleanup

- Add a dump method for SoundTriggerService
- Migrate to log with per-session and service-wide event loggers with
  event attribution and method codes.
- Retain event loggers for recent detached sessions
- Combine error logging to logcat and dumpsys via event loggers
- Cleanup unnecessary logging
- Minor cleaup to handle all RemoteException, not just DeadObject

Bug: 272147641
Fixes: 278146571
Fixes: 278105467
Test: Verify dumpsys formatting
Test: Verify expected method calls in dumpsys
Test: Verify detached sessions are properly logged in dumpsys
Test: Verify errors are in both logcat and dumpsys
Change-Id: Ifc184548b561bf1bc73cd00aef72fa956802aa24
This commit is contained in:
Atneya Nair
2023-04-13 17:58:22 -07:00
parent 58ab9d81c3
commit 3932997b74
2 changed files with 324 additions and 346 deletions

View File

@@ -16,6 +16,9 @@
package com.android.server.soundtrigger;
import static com.android.server.soundtrigger.SoundTriggerEvent.SessionEvent.Type;
import static com.android.server.utils.EventLogger.Event.ALOGW;
import android.annotation.NonNull;
import android.annotation.Nullable;
import android.content.BroadcastReceiver;
@@ -51,6 +54,9 @@ import android.util.Slog;
import com.android.internal.annotations.GuardedBy;
import com.android.internal.logging.MetricsLogger;
import com.android.server.soundtrigger.SoundTriggerEvent.SessionEvent;
import com.android.server.utils.EventLogger.Event;
import com.android.server.utils.EventLogger;
import java.io.FileDescriptor;
import java.io.PrintWriter;
@@ -76,7 +82,6 @@ import java.util.function.Supplier;
*/
public class SoundTriggerHelper implements SoundTrigger.StatusListener {
static final String TAG = "SoundTriggerHelper";
static final boolean DBG = false;
// Module ID if there is no available module to connect to.
public static final int INVALID_MODULE_ID = -1;
@@ -129,11 +134,12 @@ public class SoundTriggerHelper implements SoundTrigger.StatusListener {
private final int mModuleId;
private final Function<SoundTrigger.StatusListener, SoundTriggerModule> mModuleProvider;
private final Supplier<List<ModuleProperties>> mModulePropertiesProvider;
private final EventLogger mEventLogger;
@GuardedBy("mLock")
private boolean mIsDetached = false;
SoundTriggerHelper(Context context,
SoundTriggerHelper(Context context, EventLogger eventLogger,
@NonNull Function<SoundTrigger.StatusListener, SoundTriggerModule> moduleProvider,
int moduleId,
@NonNull Supplier<List<ModuleProperties>> modulePropertiesProvider) {
@@ -144,6 +150,7 @@ public class SoundTriggerHelper implements SoundTrigger.StatusListener {
mModelDataMap = new HashMap<UUID, ModelData>();
mKeyphraseUuidMap = new HashMap<Integer, UUID>();
mModuleProvider = moduleProvider;
mEventLogger = eventLogger;
mModulePropertiesProvider = modulePropertiesProvider;
if (moduleId == INVALID_MODULE_ID) {
mModule = null;
@@ -234,14 +241,6 @@ public class SoundTriggerHelper implements SoundTrigger.StatusListener {
throw new IllegalStateException("SoundTriggerHelper has been detached");
}
if (DBG) {
Slog.d(TAG, "startKeyphraseRecognition for keyphraseId=" + keyphraseId
+ " soundModel=" + soundModel + ", callback=" + callback.asBinder()
+ ", recognitionConfig=" + recognitionConfig
+ ", runInBatterySaverMode=" + runInBatterySaverMode);
dumpModelStateLocked();
}
ModelData model = getKeyphraseModelDataLocked(keyphraseId);
if (model != null && !model.isKeyphraseModel()) {
Slog.e(TAG, "Generic model with same UUID exists.");
@@ -301,9 +300,6 @@ public class SoundTriggerHelper implements SoundTrigger.StatusListener {
}
modelData.setHandle(handle[0]);
modelData.setLoaded();
if (DBG) {
Slog.d(TAG, "prepareForRecognition: Sound model loaded with handle:" + handle[0]);
}
}
return STATUS_OK;
}
@@ -448,13 +444,6 @@ public class SoundTriggerHelper implements SoundTrigger.StatusListener {
return STATUS_ERROR;
}
if (DBG) {
Slog.d(TAG, "stopRecognition for keyphraseId=" + keyphraseId + ", callback =" +
callback.asBinder());
Slog.d(TAG, "current callback="
+ ((modelData == null || modelData.getCallback() == null) ? "null" :
modelData.getCallback().asBinder()));
}
int status = stopRecognition(modelData, callback);
if (status != SoundTrigger.STATUS_OK) {
return status;
@@ -635,7 +624,6 @@ public class SoundTriggerHelper implements SoundTrigger.StatusListener {
// Remove it from existence.
mModelDataMap.remove(modelId);
if (DBG) dumpModelStateLocked();
return status;
}
}
@@ -797,7 +785,6 @@ public class SoundTriggerHelper implements SoundTrigger.StatusListener {
return;
}
if (DBG) Slog.d(TAG, "onRecognition: " + event);
synchronized (mLock) {
switch (event.status) {
case SoundTrigger.RECOGNITION_STATUS_ABORT:
@@ -845,12 +832,14 @@ public class SoundTriggerHelper implements SoundTrigger.StatusListener {
}
try {
mEventLogger.enqueue(new SessionEvent(Type.RECOGNITION, model.getModelId()));
callback.onGenericSoundTriggerDetected((GenericRecognitionEvent) event);
} catch (DeadObjectException e) {
} catch (RemoteException e) {
mEventLogger.enqueue(new SessionEvent(
Type.RECOGNITION, model.getModelId(), "RemoteException")
.printLog(ALOGW, TAG));
forceStopAndUnloadModelLocked(model, e);
return;
} catch (RemoteException e) {
Slog.w(TAG, "RemoteException in onGenericSoundTriggerDetected", e);
}
RecognitionConfig config = model.getRecognitionConfig();
@@ -869,7 +858,6 @@ public class SoundTriggerHelper implements SoundTrigger.StatusListener {
@Override
public void onModelUnloaded(int modelHandle) {
if (DBG) Slog.d(TAG, "onModelUnloaded: " + modelHandle);
synchronized (mLock) {
MetricsLogger.count(mContext, "sth_sound_model_updated", 1);
onModelUnloadedLocked(modelHandle);
@@ -878,7 +866,6 @@ public class SoundTriggerHelper implements SoundTrigger.StatusListener {
@Override
public void onResourcesAvailable() {
if (DBG) Slog.d(TAG, "onResourcesAvailable");
synchronized (mLock) {
onResourcesAvailableLocked();
}
@@ -920,6 +907,7 @@ public class SoundTriggerHelper implements SoundTrigger.StatusListener {
}
private void onResourcesAvailableLocked() {
mEventLogger.enqueue(new SessionEvent(Type.RESOURCES_AVAILABLE, null));
updateAllRecognitionsLocked();
}
@@ -932,12 +920,14 @@ public class SoundTriggerHelper implements SoundTrigger.StatusListener {
try {
IRecognitionStatusCallback callback = modelData.getCallback();
if (callback != null) {
mEventLogger.enqueue(new SessionEvent(Type.PAUSE, modelData.getModelId()));
callback.onRecognitionPaused();
}
} catch (DeadObjectException e) {
forceStopAndUnloadModelLocked(modelData, e);
} catch (RemoteException e) {
Slog.w(TAG, "RemoteException in onRecognitionPaused", e);
mEventLogger.enqueue(new SessionEvent(
Type.PAUSE, modelData.getModelId(), "RemoteException")
.printLog(ALOGW, TAG));
forceStopAndUnloadModelLocked(modelData, e);
}
updateRecognitionLocked(modelData, true);
}
@@ -979,12 +969,14 @@ public class SoundTriggerHelper implements SoundTrigger.StatusListener {
}
try {
mEventLogger.enqueue(new SessionEvent(Type.RECOGNITION, modelData.getModelId()));
modelData.getCallback().onKeyphraseDetected((KeyphraseRecognitionEvent) event);
} catch (DeadObjectException e) {
} catch (RemoteException e) {
mEventLogger.enqueue(new SessionEvent(
Type.RECOGNITION, modelData.getModelId(), "RemoteException")
.printLog(ALOGW, TAG));
forceStopAndUnloadModelLocked(modelData, e);
return;
} catch (RemoteException e) {
Slog.w(TAG, "RemoteException in onKeyphraseDetected", e);
}
RecognitionConfig config = modelData.getRecognitionConfig();
@@ -1036,10 +1028,13 @@ public class SoundTriggerHelper implements SoundTrigger.StatusListener {
IRecognitionStatusCallback callback = modelData.getCallback();
if (callback != null) {
try {
mEventLogger.enqueue(new SessionEvent(Type.MODULE_DIED,
modelData.getModelId()).printLog(ALOGW, TAG));
callback.onModuleDied();
} catch (RemoteException e) {
Slog.w(TAG, "RemoteException send moduleDied for model handle " +
modelData.getHandle(), e);
mEventLogger.enqueue(new SessionEvent(Type.MODULE_DIED,
modelData.getModelId(), "RemoteException")
.printLog(ALOGW, TAG));
}
}
}
@@ -1085,7 +1080,6 @@ public class SoundTriggerHelper implements SoundTrigger.StatusListener {
@Override
public void onCallStateChanged(int state, String arg1) {
if (DBG) Slog.d(TAG, "onCallStateChanged: " + state);
if (mHandler != null) {
synchronized (mLock) {
@@ -1107,9 +1101,6 @@ public class SoundTriggerHelper implements SoundTrigger.StatusListener {
}
@SoundTriggerPowerSaveMode int soundTriggerPowerSaveMode =
mPowerManager.getSoundTriggerPowerSaveMode();
if (DBG) {
Slog.d(TAG, "onPowerSaveModeChanged: " + soundTriggerPowerSaveMode);
}
synchronized (mLock) {
onPowerSaveModeChangedLocked(soundTriggerPowerSaveMode);
}
@@ -1151,13 +1142,13 @@ public class SoundTriggerHelper implements SoundTrigger.StatusListener {
public void detach() {
synchronized (mLock) {
if (mIsDetached) return;
mIsDetached = true;
for (ModelData model : mModelDataMap.values()) {
forceStopAndUnloadModelLocked(model, null);
}
mModelDataMap.clear();
internalClearGlobalStateLocked();
if (mModule != null) {
mIsDetached = true;
mModule.detach();
mModule = null;
}
@@ -1361,11 +1352,16 @@ public class SoundTriggerHelper implements SoundTrigger.StatusListener {
// Notify of error if needed.
if (notifyClientOnError) {
try {
mEventLogger.enqueue(new SessionEvent(Type.RESUME_FAILED,
modelData.getModelId(), String.valueOf(status))
.printLog(ALOGW, TAG));
callback.onResumeFailed(status);
} catch (DeadObjectException e) {
forceStopAndUnloadModelLocked(modelData, e);
} catch (RemoteException e) {
Slog.w(TAG, "RemoteException in onResumeFailed", e);
mEventLogger.enqueue(new SessionEvent(Type.RESUME_FAILED,
modelData.getModelId(),
String.valueOf(status) + " - RemoteException")
.printLog(ALOGW, TAG));
forceStopAndUnloadModelLocked(modelData, e);
}
}
} else {
@@ -1375,17 +1371,16 @@ public class SoundTriggerHelper implements SoundTrigger.StatusListener {
// Notify of resume if needed.
if (notifyClientOnError) {
try {
mEventLogger.enqueue(new SessionEvent(Type.RESUME,
modelData.getModelId()));
callback.onRecognitionResumed();
} catch (DeadObjectException e) {
forceStopAndUnloadModelLocked(modelData, e);
} catch (RemoteException e) {
Slog.w(TAG, "RemoteException in onRecognitionResumed", e);
mEventLogger.enqueue(new SessionEvent(Type.RESUME,
modelData.getModelId(), "RemoteException").printLog(ALOGW, TAG));
forceStopAndUnloadModelLocked(modelData, e);
}
}
}
if (DBG) {
Slog.d(TAG, "Model being started :" + modelData.toString());
}
return status;
}
@@ -1405,11 +1400,16 @@ public class SoundTriggerHelper implements SoundTrigger.StatusListener {
MetricsLogger.count(mContext, "sth_stop_recognition_error", 1);
if (notify) {
try {
mEventLogger.enqueue(new SessionEvent(Type.PAUSE_FAILED,
modelData.getModelId(), String.valueOf(status))
.printLog(ALOGW, TAG));
callback.onPauseFailed(status);
} catch (DeadObjectException e) {
forceStopAndUnloadModelLocked(modelData, e);
} catch (RemoteException e) {
Slog.w(TAG, "RemoteException in onPauseFailed", e);
mEventLogger.enqueue(new SessionEvent(Type.PAUSE_FAILED,
modelData.getModelId(),
String.valueOf(status) + " - RemoteException")
.printLog(ALOGW, TAG));
forceStopAndUnloadModelLocked(modelData, e);
}
}
} else {
@@ -1418,27 +1418,19 @@ public class SoundTriggerHelper implements SoundTrigger.StatusListener {
// Notify of pause if needed.
if (notify) {
try {
mEventLogger.enqueue(new SessionEvent(Type.PAUSE,
modelData.getModelId()));
callback.onRecognitionPaused();
} catch (DeadObjectException e) {
forceStopAndUnloadModelLocked(modelData, e);
} catch (RemoteException e) {
Slog.w(TAG, "RemoteException in onRecognitionPaused", e);
mEventLogger.enqueue(new SessionEvent(Type.PAUSE,
modelData.getModelId(), "RemoteException").printLog(ALOGW, TAG));
forceStopAndUnloadModelLocked(modelData, e);
}
}
}
if (DBG) {
Slog.d(TAG, "Model being stopped :" + modelData.toString());
}
return status;
}
private void dumpModelStateLocked() {
for (UUID modelId : mModelDataMap.keySet()) {
ModelData modelData = mModelDataMap.get(modelId);
Slog.i(TAG, "Model :" + modelData.toString());
}
}
// Computes whether we have any recognition running at all (voice or generic). Sets
// the mRecognitionRequested variable with the result.
private boolean computeRecognitionRequestedLocked() {