From 58ab9d81c3c1630970f1fafee14f1bee1843c5a7 Mon Sep 17 00:00:00 2001 From: Atneya Nair Date: Thu, 13 Apr 2023 16:18:18 -0700 Subject: [PATCH 1/3] Add SoundTrigger event types for logging - Encapsulate event types for use with EventLogger - Separate events into service-wide and sessioned events - Enumerate event types for all methods - Optional error string for distinguishing error events Bug: 272147641 Fixes: 278138038 Test: atest SoundTriggerEventTest Change-Id: I74075402f4c82aeb79444fd4d5ed17c38d97542e --- .../soundtrigger/SoundTriggerEventTest.java | 87 +++++++++++ .../soundtrigger/SoundTriggerEvent.java | 135 ++++++++++++++++++ 2 files changed, 222 insertions(+) create mode 100644 services/tests/voiceinteractiontests/src/com/android/server/soundtrigger/SoundTriggerEventTest.java create mode 100644 services/voiceinteraction/java/com/android/server/soundtrigger/SoundTriggerEvent.java diff --git a/services/tests/voiceinteractiontests/src/com/android/server/soundtrigger/SoundTriggerEventTest.java b/services/tests/voiceinteractiontests/src/com/android/server/soundtrigger/SoundTriggerEventTest.java new file mode 100644 index 0000000000000..1c8950696f59d --- /dev/null +++ b/services/tests/voiceinteractiontests/src/com/android/server/soundtrigger/SoundTriggerEventTest.java @@ -0,0 +1,87 @@ +/* + * Copyright (C) 2023 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.soundtrigger; + +import static com.google.common.truth.Truth.assertThat; + +import androidx.test.runner.AndroidJUnit4; + +import com.android.server.soundtrigger.SoundTriggerEvent.ServiceEvent; +import com.android.server.soundtrigger.SoundTriggerEvent.SessionEvent; + +import org.junit.Test; +import org.junit.runner.RunWith; + +import java.util.UUID; + +@RunWith(AndroidJUnit4.class) +public final class SoundTriggerEventTest { + private static final ServiceEvent.Type serviceEventType = ServiceEvent.Type.ATTACH; + private static final SessionEvent.Type sessionEventType = SessionEvent.Type.DETACH; + + @Test + public void serviceEventNoPackageNoError_getStringContainsType() { + final var event = new ServiceEvent(serviceEventType); + final var stringRep = event.eventToString(); + assertThat(stringRep).contains(serviceEventType.name()); + assertThat(stringRep).ignoringCase().doesNotContain("error"); + } + + @Test + public void serviceEventPackageNoError_getStringContainsTypeAndPackage() { + final var packageName = "com.android.package.name"; + final var event = new ServiceEvent(serviceEventType, packageName); + final var stringRep = event.eventToString(); + assertThat(stringRep).contains(serviceEventType.name()); + assertThat(stringRep).contains(packageName); + assertThat(stringRep).ignoringCase().doesNotContain("error"); + } + + @Test + public void serviceEventPackageError_getStringContainsTypeAndPackageAndErrorAndMessage() { + final var packageName = "com.android.package.name"; + final var errorString = "oh no an ERROR occurred"; + final var event = new ServiceEvent(serviceEventType, packageName, errorString); + final var stringRep = event.eventToString(); + assertThat(stringRep).contains(serviceEventType.name()); + assertThat(stringRep).contains(packageName); + assertThat(stringRep).contains(errorString); + assertThat(stringRep).ignoringCase().contains("error"); + } + + @Test + public void sessionEventUUIDNoError_getStringContainsUUID() { + final var uuid = new UUID(5, -7); + final var event = new SessionEvent(sessionEventType, uuid); + final var stringRep = event.eventToString(); + assertThat(stringRep).contains(sessionEventType.name()); + assertThat(stringRep).contains(uuid.toString()); + assertThat(stringRep).ignoringCase().doesNotContain("error"); + } + + @Test + public void sessionEventUUIDError_getStringContainsUUIDAndError() { + final var uuid = new UUID(5, -7); + final var errorString = "oh no an ERROR occurred"; + final var event = new SessionEvent(sessionEventType, uuid, errorString); + final var stringRep = event.eventToString(); + assertThat(stringRep).contains(sessionEventType.name()); + assertThat(stringRep).contains(uuid.toString()); + assertThat(stringRep).ignoringCase().contains("error"); + assertThat(stringRep).contains(errorString); + } +} diff --git a/services/voiceinteraction/java/com/android/server/soundtrigger/SoundTriggerEvent.java b/services/voiceinteraction/java/com/android/server/soundtrigger/SoundTriggerEvent.java new file mode 100644 index 0000000000000..2a55496d2cd1c --- /dev/null +++ b/services/voiceinteraction/java/com/android/server/soundtrigger/SoundTriggerEvent.java @@ -0,0 +1,135 @@ +/** + * Copyright (C) 2023 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.soundtrigger; + +import android.util.Slog; + +import com.android.server.utils.EventLogger.Event; + +import java.util.UUID; + +public abstract class SoundTriggerEvent extends Event { + + @Override + public Event printLog(int type, String tag) { + switch (type) { + case ALOGI: + Slog.i(tag, eventToString()); + break; + case ALOGE: + Slog.e(tag, eventToString()); + break; + case ALOGW: + Slog.w(tag, eventToString()); + break; + case ALOGV: + default: + Slog.v(tag, eventToString()); + } + return this; + } + + public static class ServiceEvent extends SoundTriggerEvent { + public enum Type { + ATTACH, + LIST_MODULE, + DETACH, + } + + private final Type mType; + private final String mPackageName; + private final String mErrorString; + + public ServiceEvent(Type type) { + this(type, null, null); + } + + public ServiceEvent(Type type, String packageName) { + this(type, packageName, null); + } + + public ServiceEvent(Type type, String packageName, String errorString) { + mType = type; + mPackageName = packageName; + mErrorString = errorString; + } + + @Override + public String eventToString() { + var res = new StringBuilder(String.format("%-12s", mType.name())); + if (mErrorString != null) { + res.append(" ERROR: ").append(mErrorString); + } + if (mPackageName != null) { + res.append(" for: ").append(mPackageName); + } + return res.toString(); + } + } + + public static class SessionEvent extends SoundTriggerEvent { + public enum Type { + // Downward calls + START_RECOGNITION, + STOP_RECOGNITION, + LOAD_MODEL, + UNLOAD_MODEL, + UPDATE_MODEL, + DELETE_MODEL, + START_RECOGNITION_SERVICE, + STOP_RECOGNITION_SERVICE, + GET_MODEL_STATE, + SET_PARAMETER, + GET_MODULE_PROPERTIES, + DETACH, + // Callback events + RECOGNITION, + RESUME, + RESUME_FAILED, + PAUSE, + PAUSE_FAILED, + RESOURCES_AVAILABLE, + MODULE_DIED + } + + private final UUID mModelUuid; + private final Type mType; + private final String mErrorString; + + public SessionEvent(Type type, UUID modelUuid, String errorString) { + mType = type; + mModelUuid = modelUuid; + mErrorString = errorString; + } + + public SessionEvent(Type type, UUID modelUuid) { + this(type, modelUuid, null); + } + + @Override + public String eventToString() { + var res = new StringBuilder(String.format("%-25s", mType.name())); + if (mErrorString != null) { + res.append(" ERROR: ").append(mErrorString); + } + if (mModelUuid != null) { + res.append(" for: ").append(mModelUuid); + } + return res.toString(); + } + } +} From 3932997b7401e028d86eefaa51f40c74facbcf92 Mon Sep 17 00:00:00 2001 From: Atneya Nair Date: Thu, 13 Apr 2023 17:58:22 -0700 Subject: [PATCH 2/3] 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 --- .../soundtrigger/SoundTriggerHelper.java | 122 ++-- .../soundtrigger/SoundTriggerService.java | 548 +++++++++--------- 2 files changed, 324 insertions(+), 346 deletions(-) diff --git a/services/voiceinteraction/java/com/android/server/soundtrigger/SoundTriggerHelper.java b/services/voiceinteraction/java/com/android/server/soundtrigger/SoundTriggerHelper.java index efe300951dc89..bee75dfe785f8 100644 --- a/services/voiceinteraction/java/com/android/server/soundtrigger/SoundTriggerHelper.java +++ b/services/voiceinteraction/java/com/android/server/soundtrigger/SoundTriggerHelper.java @@ -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 mModuleProvider; private final Supplier> mModulePropertiesProvider; + private final EventLogger mEventLogger; @GuardedBy("mLock") private boolean mIsDetached = false; - SoundTriggerHelper(Context context, + SoundTriggerHelper(Context context, EventLogger eventLogger, @NonNull Function moduleProvider, int moduleId, @NonNull Supplier> modulePropertiesProvider) { @@ -144,6 +150,7 @@ public class SoundTriggerHelper implements SoundTrigger.StatusListener { mModelDataMap = new HashMap(); mKeyphraseUuidMap = new HashMap(); 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() { diff --git a/services/voiceinteraction/java/com/android/server/soundtrigger/SoundTriggerService.java b/services/voiceinteraction/java/com/android/server/soundtrigger/SoundTriggerService.java index b6673ad1e3880..77e53177e6a81 100644 --- a/services/voiceinteraction/java/com/android/server/soundtrigger/SoundTriggerService.java +++ b/services/voiceinteraction/java/com/android/server/soundtrigger/SoundTriggerService.java @@ -31,6 +31,9 @@ import static android.hardware.soundtrigger.SoundTrigger.STATUS_OK; import static android.provider.Settings.Global.MAX_SOUND_TRIGGER_DETECTION_SERVICE_OPS_PER_DAY; import static android.provider.Settings.Global.SOUND_TRIGGER_DETECTION_SERVICE_OP_TIMEOUT; +import static com.android.server.soundtrigger.SoundTriggerEvent.SessionEvent.Type; +import static com.android.server.utils.EventLogger.Event.ALOGW; + import static com.android.internal.util.function.pooled.PooledLambda.obtainMessage; import android.Manifest; @@ -83,6 +86,7 @@ import android.os.UserHandle; import android.provider.Settings; import android.util.ArrayMap; import android.util.ArraySet; +import android.util.SparseArray; import android.util.Slog; import com.android.internal.annotations.GuardedBy; @@ -90,6 +94,9 @@ import com.android.internal.app.ISoundTriggerService; import com.android.internal.app.ISoundTriggerSession; import com.android.server.SoundTriggerInternal; import com.android.server.SystemService; +import com.android.server.soundtrigger.SoundTriggerEvent.ServiceEvent; +import com.android.server.soundtrigger.SoundTriggerEvent.SessionEvent; +import com.android.server.utils.EventLogger.Event; import com.android.server.utils.EventLogger; import java.io.FileDescriptor; @@ -97,11 +104,16 @@ import java.io.PrintWriter; import java.util.ArrayList; import java.util.Arrays; import java.util.List; +import java.util.Set; +import java.util.Deque; import java.util.Map; import java.util.Objects; import java.util.TreeMap; import java.util.UUID; +import java.util.concurrent.ConcurrentHashMap; +import java.util.concurrent.LinkedBlockingDeque; import java.util.concurrent.TimeUnit; +import java.util.concurrent.atomic.AtomicInteger; import java.util.stream.Collectors; /** @@ -116,6 +128,7 @@ import java.util.stream.Collectors; public class SoundTriggerService extends SystemService { private static final String TAG = "SoundTriggerService"; private static final boolean DEBUG = true; + private static final int SESSION_MAX_EVENT_SIZE = 128; final Context mContext; private Object mLock; @@ -123,6 +136,12 @@ public class SoundTriggerService extends SystemService { private final LocalSoundTriggerService mLocalSoundTriggerService; private SoundTriggerDbHelper mDbHelper; + private final EventLogger mServiceEventLogger = new EventLogger(256, "Service"); + + private final Set mSessionEventLoggers = ConcurrentHashMap.newKeySet(4); + private final Deque mDetachedSessionEventLoggers = new LinkedBlockingDeque<>(4); + private AtomicInteger mSessionIdCounter = new AtomicInteger(0); + class SoundModelStatTracker { private class SoundModelStat { SoundModelStat() { @@ -164,7 +183,7 @@ public class SoundTriggerService extends SystemService { public synchronized void onStop(UUID id) { SoundModelStat stat = mModelStats.get(id); if (stat == null) { - Slog.w(TAG, "error onStop(): Model " + id + " has no stats available"); + Slog.i(TAG, "error onStop(): Model " + id + " has no stats available"); return; } @@ -241,7 +260,9 @@ public class SoundTriggerService extends SystemService { } } - private SoundTriggerHelper newSoundTriggerHelper(ModuleProperties moduleProperties) { + private SoundTriggerHelper newSoundTriggerHelper( + ModuleProperties moduleProperties, EventLogger eventLogger) { + Identity middlemanIdentity = new Identity(); middlemanIdentity.packageName = ActivityThread.currentOpPackageName(); Identity originatorIdentity = IdentityContext.getNonNull(); @@ -260,6 +281,7 @@ public class SoundTriggerService extends SystemService { return new SoundTriggerHelper( mContext, + eventLogger, (SoundTrigger.StatusListener statusListener) -> SoundTrigger.attachModuleAsMiddleman( moduleId, statusListener, null /* handler */, @@ -269,14 +291,33 @@ public class SoundTriggerService extends SystemService { ); } + // Helper to add session logger to the capacity limited detached list. + // If we are at capacity, remove the oldest, and retry + private void addDetachedSessionLogger(EventLogger logger) { + // Attempt to push to the top of the queue + while (!mDetachedSessionEventLoggers.offerFirst(logger)) { + // Remove the oldest element, if one still exists + mDetachedSessionEventLoggers.pollLast(); + } + } + class SoundTriggerServiceStub extends ISoundTriggerService.Stub { @Override public ISoundTriggerSession attachAsOriginator(@NonNull Identity originatorIdentity, @NonNull ModuleProperties moduleProperties, @NonNull IBinder client) { + + int sessionId = mSessionIdCounter.getAndIncrement(); + mServiceEventLogger.enqueue(new ServiceEvent( + ServiceEvent.Type.ATTACH, originatorIdentity.packageName + "#" + sessionId)); try (SafeCloseable ignored = PermissionUtil.establishIdentityDirect( originatorIdentity)) { - return new SoundTriggerSessionStub(client, newSoundTriggerHelper(moduleProperties)); + var eventLogger = new EventLogger(SESSION_MAX_EVENT_SIZE, + "SoundTriggerSessionLogs for package: " + + Objects.requireNonNull(originatorIdentity.packageName) + + "#" + sessionId); + return new SoundTriggerSessionStub(client, + newSoundTriggerHelper(moduleProperties, eventLogger), eventLogger); } } @@ -285,15 +326,26 @@ public class SoundTriggerService extends SystemService { @NonNull Identity middlemanIdentity, @NonNull ModuleProperties moduleProperties, @NonNull IBinder client) { + + int sessionId = mSessionIdCounter.getAndIncrement(); + mServiceEventLogger.enqueue(new ServiceEvent( + ServiceEvent.Type.ATTACH, originatorIdentity.packageName + "#" + sessionId)); try (SafeCloseable ignored = PermissionUtil.establishIdentityIndirect(mContext, SOUNDTRIGGER_DELEGATE_IDENTITY, middlemanIdentity, originatorIdentity)) { - return new SoundTriggerSessionStub(client, newSoundTriggerHelper(moduleProperties)); + var eventLogger = new EventLogger(SESSION_MAX_EVENT_SIZE, + "SoundTriggerSessionLogs for package: " + + Objects.requireNonNull(originatorIdentity.packageName) + "#" + + sessionId); + return new SoundTriggerSessionStub(client, + newSoundTriggerHelper(moduleProperties, eventLogger), eventLogger); } } @Override public List listModuleProperties(@NonNull Identity originatorIdentity) { + mServiceEventLogger.enqueue(new ServiceEvent( + ServiceEvent.Type.LIST_MODULE, originatorIdentity.packageName)); try (SafeCloseable ignored = PermissionUtil.establishIdentityDirect( originatorIdentity)) { return listUnderlyingModuleProperties(originatorIdentity); @@ -316,6 +368,31 @@ public class SoundTriggerService extends SystemService { throw e.rethrowFromSystemServer(); } } + + @Override + public void dump(FileDescriptor fd, PrintWriter pw, String[] args) { + // Event loggers + pw.println("##Service-Wide logs:"); + mServiceEventLogger.dump(pw, /* indent = */ " "); + + pw.println("\n##Active Session dumps:\n"); + for (var sessionLogger : mSessionEventLoggers) { + sessionLogger.dump(pw, /* indent= */ " "); + pw.println(""); + } + pw.println("##Detached Session dumps:\n"); + for (var sessionLogger : mDetachedSessionEventLoggers) { + sessionLogger.dump(pw, /* indent= */ " "); + pw.println(""); + } + // enrolled models + pw.println("##Enrolled db dump:\n"); + mDbHelper.dump(pw); + + // stats + pw.println("\n##Sound Model Stats dump:\n"); + mSoundModelStatTracker.dump(pw); + } } class SoundTriggerSessionStub extends ISoundTriggerSession.Stub { @@ -326,17 +403,20 @@ public class SoundTriggerService extends SystemService { private final TreeMap mLoadedModels = new TreeMap<>(); private final Object mCallbacksLock = new Object(); private final TreeMap mCallbacks = new TreeMap<>(); + private final EventLogger mEventLogger; - SoundTriggerSessionStub(@NonNull IBinder client, SoundTriggerHelper soundTriggerHelper) { + SoundTriggerSessionStub(@NonNull IBinder client, + SoundTriggerHelper soundTriggerHelper, EventLogger eventLogger) { mSoundTriggerHelper = soundTriggerHelper; mClient = client; mOriginatorIdentity = IdentityContext.getNonNull(); + mEventLogger = eventLogger; + mSessionEventLoggers.add(mEventLogger); + try { - mClient.linkToDeath(() -> { - clientDied(); - }, 0); + mClient.linkToDeath(() -> clientDied(), 0); } catch (RemoteException e) { - Slog.e(TAG, "Failed to register death listener.", e); + clientDied(); } } @@ -344,11 +424,14 @@ public class SoundTriggerService extends SystemService { public int startRecognition(GenericSoundModel soundModel, IRecognitionStatusCallback callback, RecognitionConfig config, boolean runInBatterySaverMode) { + mEventLogger.enqueue(new SessionEvent(Type.START_RECOGNITION, getUuid(soundModel))); + try (SafeCloseable ignored = ClearCallingIdentityContext.create()) { enforceCallingPermission(Manifest.permission.MANAGE_SOUND_TRIGGER); if (soundModel == null) { - Slog.e(TAG, "Null model passed to startRecognition"); + mEventLogger.enqueue(new SessionEvent(Type.START_RECOGNITION, + getUuid(soundModel), "Invalid sound model").printLog(ALOGW, TAG)); return STATUS_ERROR; } @@ -356,13 +439,6 @@ public class SoundTriggerService extends SystemService { enforceCallingPermission(Manifest.permission.SOUND_TRIGGER_RUN_IN_BATTERY_SAVER); } - if (DEBUG) { - Slog.i(TAG, "startRecognition(): Uuid : " + soundModel.toString()); - } - - sEventLogger.enqueue(new EventLogger.StringEvent( - "startRecognition(): Uuid : " + soundModel.getUuid().toString())); - int ret = mSoundTriggerHelper.startGenericRecognition(soundModel.getUuid(), soundModel, callback, config, runInBatterySaverMode); @@ -375,15 +451,9 @@ public class SoundTriggerService extends SystemService { @Override public int stopRecognition(ParcelUuid parcelUuid, IRecognitionStatusCallback callback) { + mEventLogger.enqueue(new SessionEvent(Type.STOP_RECOGNITION, getUuid(parcelUuid))); try (SafeCloseable ignored = ClearCallingIdentityContext.create()) { enforceCallingPermission(Manifest.permission.MANAGE_SOUND_TRIGGER); - if (DEBUG) { - Slog.i(TAG, "stopRecognition(): Uuid : " + parcelUuid); - } - - sEventLogger.enqueue(new EventLogger.StringEvent("stopRecognition(): Uuid : " - + parcelUuid)); - int ret = mSoundTriggerHelper.stopGenericRecognition(parcelUuid.getUuid(), callback); if (ret == STATUS_OK) { @@ -397,13 +467,6 @@ public class SoundTriggerService extends SystemService { public SoundTrigger.GenericSoundModel getSoundModel(ParcelUuid soundModelId) { try (SafeCloseable ignored = ClearCallingIdentityContext.create()) { enforceCallingPermission(Manifest.permission.MANAGE_SOUND_TRIGGER); - if (DEBUG) { - Slog.i(TAG, "getSoundModel(): id = " + soundModelId); - } - - sEventLogger.enqueue(new EventLogger.StringEvent("getSoundModel(): id = " - + soundModelId)); - SoundTrigger.GenericSoundModel model = mDbHelper.getGenericSoundModel( soundModelId.getUuid()); return model; @@ -412,29 +475,18 @@ public class SoundTriggerService extends SystemService { @Override public void updateSoundModel(SoundTrigger.GenericSoundModel soundModel) { + mEventLogger.enqueue(new SessionEvent(Type.UPDATE_MODEL, getUuid(soundModel))); try (SafeCloseable ignored = ClearCallingIdentityContext.create()) { enforceCallingPermission(Manifest.permission.MANAGE_SOUND_TRIGGER); - if (DEBUG) { - Slog.i(TAG, "updateSoundModel(): model = " + soundModel); - } - - sEventLogger.enqueue(new EventLogger.StringEvent("updateSoundModel(): model = " - + soundModel)); - mDbHelper.updateGenericSoundModel(soundModel); + mDbHelper.updateGenericSoundModel(soundModel); } } @Override public void deleteSoundModel(ParcelUuid soundModelId) { + mEventLogger.enqueue(new SessionEvent(Type.DELETE_MODEL, getUuid(soundModelId))); try (SafeCloseable ignored = ClearCallingIdentityContext.create()) { enforceCallingPermission(Manifest.permission.MANAGE_SOUND_TRIGGER); - if (DEBUG) { - Slog.i(TAG, "deleteSoundModel(): id = " + soundModelId); - } - - sEventLogger.enqueue(new EventLogger.StringEvent("deleteSoundModel(): id = " - + soundModelId)); - // Unload the model if it is loaded. mSoundTriggerHelper.unloadGenericSoundModel(soundModelId.getUuid()); @@ -447,22 +499,14 @@ public class SoundTriggerService extends SystemService { @Override public int loadGenericSoundModel(GenericSoundModel soundModel) { + mEventLogger.enqueue(new SessionEvent(Type.LOAD_MODEL, getUuid(soundModel))); try (SafeCloseable ignored = ClearCallingIdentityContext.create()) { enforceCallingPermission(Manifest.permission.MANAGE_SOUND_TRIGGER); if (soundModel == null || soundModel.getUuid() == null) { - Slog.w(TAG, "Invalid sound model"); - - sEventLogger.enqueue(new EventLogger.StringEvent( - "loadGenericSoundModel(): Invalid sound model")); - + mEventLogger.enqueue(new SessionEvent(Type.LOAD_MODEL, + getUuid(soundModel), "Invalid sound model").printLog(ALOGW, TAG)); return STATUS_ERROR; } - if (DEBUG) { - Slog.i(TAG, "loadGenericSoundModel(): id = " + soundModel.getUuid()); - } - - sEventLogger.enqueue(new EventLogger.StringEvent("loadGenericSoundModel(): id = " - + soundModel.getUuid())); synchronized (mLock) { SoundModel oldModel = mLoadedModels.get(soundModel.getUuid()); @@ -483,32 +527,22 @@ public class SoundTriggerService extends SystemService { @Override public int loadKeyphraseSoundModel(KeyphraseSoundModel soundModel) { + mEventLogger.enqueue(new SessionEvent(Type.LOAD_MODEL, getUuid(soundModel))); + try (SafeCloseable ignored = ClearCallingIdentityContext.create()) { enforceCallingPermission(Manifest.permission.MANAGE_SOUND_TRIGGER); if (soundModel == null || soundModel.getUuid() == null) { - Slog.w(TAG, "Invalid sound model"); - - sEventLogger.enqueue(new EventLogger.StringEvent( - "loadKeyphraseSoundModel(): Invalid sound model")); + mEventLogger.enqueue(new SessionEvent(Type.LOAD_MODEL, getUuid(soundModel), + "Invalid sound model").printLog(ALOGW, TAG)); return STATUS_ERROR; } if (soundModel.getKeyphrases() == null || soundModel.getKeyphrases().length != 1) { - Slog.w(TAG, "Only one keyphrase per model is currently supported."); - - sEventLogger.enqueue(new EventLogger.StringEvent( - "loadKeyphraseSoundModel(): Only one keyphrase per model" - + " is currently supported.")); - + mEventLogger.enqueue(new SessionEvent(Type.LOAD_MODEL, getUuid(soundModel), + "Only one keyphrase supported").printLog(ALOGW, TAG)); return STATUS_ERROR; } - if (DEBUG) { - Slog.i(TAG, "loadKeyphraseSoundModel(): id = " + soundModel.getUuid()); - } - sEventLogger.enqueue( - new EventLogger.StringEvent("loadKeyphraseSoundModel(): id = " - + soundModel.getUuid())); synchronized (mLock) { SoundModel oldModel = mLoadedModels.get(soundModel.getUuid()); @@ -530,23 +564,17 @@ public class SoundTriggerService extends SystemService { @Override public int startRecognitionForService(ParcelUuid soundModelId, Bundle params, - ComponentName detectionService, SoundTrigger.RecognitionConfig config) { + ComponentName detectionService, SoundTrigger.RecognitionConfig config) { + mEventLogger.enqueue(new SessionEvent(Type.START_RECOGNITION_SERVICE, + getUuid(soundModelId))); try (SafeCloseable ignored = ClearCallingIdentityContext.create()) { Objects.requireNonNull(soundModelId); Objects.requireNonNull(detectionService); Objects.requireNonNull(config); enforceCallingPermission(Manifest.permission.MANAGE_SOUND_TRIGGER); - enforceDetectionPermissions(detectionService); - if (DEBUG) { - Slog.i(TAG, "startRecognition(): id = " + soundModelId); - } - - sEventLogger.enqueue(new EventLogger.StringEvent( - "startRecognitionForService(): id = " + soundModelId)); - IRecognitionStatusCallback callback = new RemoteSoundTriggerDetectionService(soundModelId.getUuid(), params, detectionService, Binder.getCallingUserHandle(), config); @@ -554,10 +582,10 @@ public class SoundTriggerService extends SystemService { synchronized (mLock) { SoundModel soundModel = mLoadedModels.get(soundModelId.getUuid()); if (soundModel == null) { - Slog.w(TAG, soundModelId + " is not loaded"); - - sEventLogger.enqueue(new EventLogger.StringEvent( - "startRecognitionForService():" + soundModelId + " is not loaded")); + mEventLogger.enqueue(new SessionEvent( + Type.START_RECOGNITION_SERVICE, + getUuid(soundModelId), + "Model not loaded").printLog(ALOGW, TAG)); return STATUS_ERROR; } @@ -566,12 +594,10 @@ public class SoundTriggerService extends SystemService { existingCallback = mCallbacks.get(soundModelId.getUuid()); } if (existingCallback != null) { - Slog.w(TAG, soundModelId + " is already running"); - - sEventLogger.enqueue(new EventLogger.StringEvent( - "startRecognitionForService():" - + soundModelId + " is already running")); - + mEventLogger.enqueue(new SessionEvent( + Type.START_RECOGNITION_SERVICE, + getUuid(soundModelId), + "Model already running").printLog(ALOGW, TAG)); return STATUS_ERROR; } int ret; @@ -581,20 +607,18 @@ public class SoundTriggerService extends SystemService { (GenericSoundModel) soundModel, callback, config, false); break; default: - Slog.e(TAG, "Unknown model type"); - - sEventLogger.enqueue(new EventLogger.StringEvent( - "startRecognitionForService(): Unknown model type")); - + mEventLogger.enqueue(new SessionEvent( + Type.START_RECOGNITION_SERVICE, + getUuid(soundModelId), + "Unsupported model type").printLog(ALOGW, TAG)); return STATUS_ERROR; } if (ret != STATUS_OK) { - Slog.e(TAG, "Failed to start model: " + ret); - - sEventLogger.enqueue(new EventLogger.StringEvent( - "startRecognitionForService(): Failed to start model:")); - + mEventLogger.enqueue(new SessionEvent( + Type.START_RECOGNITION_SERVICE, + getUuid(soundModelId), + "Model start fail").printLog(ALOGW, TAG)); return ret; } synchronized (mCallbacksLock) { @@ -609,23 +633,20 @@ public class SoundTriggerService extends SystemService { @Override public int stopRecognitionForService(ParcelUuid soundModelId) { + mEventLogger.enqueue(new SessionEvent(Type.STOP_RECOGNITION_SERVICE, + getUuid(soundModelId))); + try (SafeCloseable ignored = ClearCallingIdentityContext.create()) { enforceCallingPermission(Manifest.permission.MANAGE_SOUND_TRIGGER); - if (DEBUG) { - Slog.i(TAG, "stopRecognition(): id = " + soundModelId); - } - - sEventLogger.enqueue(new EventLogger.StringEvent( - "stopRecognitionForService(): id = " + soundModelId)); synchronized (mLock) { SoundModel soundModel = mLoadedModels.get(soundModelId.getUuid()); if (soundModel == null) { - Slog.w(TAG, soundModelId + " is not loaded"); - - sEventLogger.enqueue(new EventLogger.StringEvent( - "stopRecognitionForService(): " + soundModelId - + " is not loaded")); + mEventLogger.enqueue(new SessionEvent( + Type.STOP_RECOGNITION_SERVICE, + getUuid(soundModelId), + "Model not loaded") + .printLog(ALOGW, TAG)); return STATUS_ERROR; } @@ -634,12 +655,11 @@ public class SoundTriggerService extends SystemService { callback = mCallbacks.get(soundModelId.getUuid()); } if (callback == null) { - Slog.w(TAG, soundModelId + " is not running"); - - sEventLogger.enqueue(new EventLogger.StringEvent( - "stopRecognitionForService(): " + soundModelId - + " is not running")); - + mEventLogger.enqueue(new SessionEvent( + Type.STOP_RECOGNITION_SERVICE, + getUuid(soundModelId), + "Model not running") + .printLog(ALOGW, TAG)); return STATUS_ERROR; } int ret; @@ -649,20 +669,21 @@ public class SoundTriggerService extends SystemService { soundModel.getUuid(), callback); break; default: - Slog.e(TAG, "Unknown model type"); - - sEventLogger.enqueue(new EventLogger.StringEvent( - "stopRecognitionForService(): Unknown model type")); + mEventLogger.enqueue(new SessionEvent( + Type.STOP_RECOGNITION_SERVICE, + getUuid(soundModelId), + "Unknown model type") + .printLog(ALOGW, TAG)); return STATUS_ERROR; } if (ret != STATUS_OK) { - Slog.e(TAG, "Failed to stop model: " + ret); - - sEventLogger.enqueue(new EventLogger.StringEvent( - "stopRecognitionForService(): Failed to stop model: " + ret)); - + mEventLogger.enqueue(new SessionEvent( + Type.STOP_RECOGNITION_SERVICE, + getUuid(soundModelId), + "Failed to stop model") + .printLog(ALOGW, TAG)); return ret; } synchronized (mCallbacksLock) { @@ -677,23 +698,18 @@ public class SoundTriggerService extends SystemService { @Override public int unloadSoundModel(ParcelUuid soundModelId) { + mEventLogger.enqueue(new SessionEvent(Type.UNLOAD_MODEL, getUuid(soundModelId))); try (SafeCloseable ignored = ClearCallingIdentityContext.create()) { enforceCallingPermission(Manifest.permission.MANAGE_SOUND_TRIGGER); - if (DEBUG) { - Slog.i(TAG, "unloadSoundModel(): id = " + soundModelId); - } - - sEventLogger.enqueue(new EventLogger.StringEvent("unloadSoundModel(): id = " - + soundModelId)); synchronized (mLock) { SoundModel soundModel = mLoadedModels.get(soundModelId.getUuid()); if (soundModel == null) { - Slog.w(TAG, soundModelId + " is not loaded"); - - sEventLogger.enqueue(new EventLogger.StringEvent( - "unloadSoundModel(): " + soundModelId + " is not loaded")); - + mEventLogger.enqueue(new SessionEvent( + Type.UNLOAD_MODEL, + getUuid(soundModelId), + "Model not loaded") + .printLog(ALOGW, TAG)); return STATUS_ERROR; } int ret; @@ -706,19 +722,19 @@ public class SoundTriggerService extends SystemService { ret = mSoundTriggerHelper.unloadGenericSoundModel(soundModel.getUuid()); break; default: - Slog.e(TAG, "Unknown model type"); - - sEventLogger.enqueue(new EventLogger.StringEvent( - "unloadSoundModel(): Unknown model type")); - + mEventLogger.enqueue(new SessionEvent( + Type.UNLOAD_MODEL, + getUuid(soundModelId), + "Unknown model type") + .printLog(ALOGW, TAG)); return STATUS_ERROR; } if (ret != STATUS_OK) { - Slog.e(TAG, "Failed to unload model"); - - sEventLogger.enqueue(new EventLogger.StringEvent( - "unloadSoundModel(): Failed to unload model")); - + mEventLogger.enqueue(new SessionEvent( + Type.UNLOAD_MODEL, + getUuid(soundModelId), + "Failed to unload model") + .printLog(ALOGW, TAG)); return ret; } mLoadedModels.remove(soundModelId.getUuid()); @@ -743,24 +759,19 @@ public class SoundTriggerService extends SystemService { @Override public int getModelState(ParcelUuid soundModelId) { + mEventLogger.enqueue(new SessionEvent(Type.GET_MODEL_STATE, getUuid(soundModelId))); try (SafeCloseable ignored = ClearCallingIdentityContext.create()) { enforceCallingPermission(Manifest.permission.MANAGE_SOUND_TRIGGER); int ret = STATUS_ERROR; - if (DEBUG) { - Slog.i(TAG, "getModelState(): id = " + soundModelId); - } - - sEventLogger.enqueue(new EventLogger.StringEvent("getModelState(): id = " - + soundModelId)); synchronized (mLock) { SoundModel soundModel = mLoadedModels.get(soundModelId.getUuid()); if (soundModel == null) { - Slog.w(TAG, soundModelId + " is not loaded"); - - sEventLogger.enqueue(new EventLogger.StringEvent("getModelState(): " - + soundModelId + " is not loaded")); - + mEventLogger.enqueue(new SessionEvent( + Type.GET_MODEL_STATE, + getUuid(soundModelId), + "Model is not loaded") + .printLog(ALOGW, TAG)); return ret; } switch (soundModel.getType()) { @@ -769,13 +780,13 @@ public class SoundTriggerService extends SystemService { break; default: // SoundModel.TYPE_KEYPHRASE is not supported to increase privacy. - Slog.e(TAG, "Unsupported model type, " + soundModel.getType()); - sEventLogger.enqueue(new EventLogger.StringEvent( - "getModelState(): Unsupported model type, " - + soundModel.getType())); + mEventLogger.enqueue(new SessionEvent( + Type.GET_MODEL_STATE, + getUuid(soundModelId), + "Unsupported model type") + .printLog(ALOGW, TAG)); break; } - return ret; } } @@ -784,16 +795,11 @@ public class SoundTriggerService extends SystemService { @Override @Nullable public ModuleProperties getModuleProperties() { + mEventLogger.enqueue(new SessionEvent(Type.GET_MODULE_PROPERTIES, null)); try (SafeCloseable ignored = ClearCallingIdentityContext.create()) { enforceCallingPermission(Manifest.permission.MANAGE_SOUND_TRIGGER); - if (DEBUG) { - Slog.i(TAG, "getModuleProperties()"); - } - synchronized (mLock) { ModuleProperties properties = mSoundTriggerHelper.getModuleProperties(); - sEventLogger.enqueue(new EventLogger.StringEvent( - "getModuleProperties(): " + properties)); return properties; } } @@ -802,33 +808,21 @@ public class SoundTriggerService extends SystemService { @Override public int setParameter(ParcelUuid soundModelId, @ModelParams int modelParam, int value) { + mEventLogger.enqueue(new SessionEvent(Type.SET_PARAMETER, getUuid(soundModelId))); try (SafeCloseable ignored = ClearCallingIdentityContext.create()) { enforceCallingPermission(Manifest.permission.MANAGE_SOUND_TRIGGER); - if (DEBUG) { - Slog.d(TAG, "setParameter(): id=" + soundModelId - + ", param=" + modelParam - + ", value=" + value); - } - - sEventLogger.enqueue(new EventLogger.StringEvent( - "setParameter(): id=" + soundModelId - + ", param=" + modelParam - + ", value=" + value)); - synchronized (mLock) { SoundModel soundModel = mLoadedModels.get(soundModelId.getUuid()); if (soundModel == null) { - Slog.w(TAG, soundModelId + " is not loaded. Loaded models: " - + mLoadedModels.toString()); - - sEventLogger.enqueue(new EventLogger.StringEvent("setParameter(): " - + soundModelId + " is not loaded")); - + mEventLogger.enqueue(new SessionEvent( + Type.SET_PARAMETER, + getUuid(soundModelId), + "Model not loaded") + .printLog(ALOGW, TAG)); return STATUS_BAD_VALUE; } - - return mSoundTriggerHelper.setParameter(soundModel.getUuid(), modelParam, - value); + return mSoundTriggerHelper.setParameter( + soundModel.getUuid(), modelParam, value); } } } @@ -839,26 +833,11 @@ public class SoundTriggerService extends SystemService { throws UnsupportedOperationException, IllegalArgumentException { try (SafeCloseable ignored = ClearCallingIdentityContext.create()) { enforceCallingPermission(Manifest.permission.MANAGE_SOUND_TRIGGER); - if (DEBUG) { - Slog.d(TAG, "getParameter(): id=" + soundModelId - + ", param=" + modelParam); - } - - sEventLogger.enqueue(new EventLogger.StringEvent( - "getParameter(): id=" + soundModelId - + ", param=" + modelParam)); - synchronized (mLock) { SoundModel soundModel = mLoadedModels.get(soundModelId.getUuid()); if (soundModel == null) { - Slog.w(TAG, soundModelId + " is not loaded"); - - sEventLogger.enqueue(new EventLogger.StringEvent("getParameter(): " - + soundModelId + " is not loaded")); - throw new IllegalArgumentException("sound model is not loaded"); } - return mSoundTriggerHelper.getParameter(soundModel.getUuid(), modelParam); } } @@ -870,37 +849,28 @@ public class SoundTriggerService extends SystemService { @ModelParams int modelParam) { try (SafeCloseable ignored = ClearCallingIdentityContext.create()) { enforceCallingPermission(Manifest.permission.MANAGE_SOUND_TRIGGER); - if (DEBUG) { - Slog.d(TAG, "queryParameter(): id=" + soundModelId - + ", param=" + modelParam); - } - - sEventLogger.enqueue(new EventLogger.StringEvent( - "queryParameter(): id=" + soundModelId - + ", param=" + modelParam)); - synchronized (mLock) { SoundModel soundModel = mLoadedModels.get(soundModelId.getUuid()); if (soundModel == null) { - Slog.w(TAG, soundModelId + " is not loaded"); - - sEventLogger.enqueue(new EventLogger.StringEvent( - "queryParameter(): " - + soundModelId + " is not loaded")); - return null; } - return mSoundTriggerHelper.queryParameter(soundModel.getUuid(), modelParam); } } } private void clientDied() { - Slog.w(TAG, "Client died, cleaning up session."); - sEventLogger.enqueue(new EventLogger.StringEvent( - "Client died, cleaning up session.")); + mEventLogger.enqueue(new SessionEvent(Type.DETACH, null)); + mServiceEventLogger.enqueue(new ServiceEvent( + ServiceEvent.Type.DETACH, mOriginatorIdentity.packageName, "Client died") + .printLog(ALOGW, TAG)); + detach(); + } + + private void detach() { mSoundTriggerHelper.detach(); + mSessionEventLoggers.remove(mEventLogger); + addDetachedSessionLogger(mEventLogger); } private void enforceCallingPermission(String permission) { @@ -922,6 +892,14 @@ public class SoundTriggerService extends SystemService { } } + private UUID getUuid(ParcelUuid uuid) { + return (uuid != null) ? uuid.getUuid() : null; + } + + private UUID getUuid(SoundModel model) { + return (model != null) ? model.getUuid() : null; + } + /** * Local end for a {@link SoundTriggerDetectionService}. Operations are queued up and * executed when the service connects. @@ -1068,7 +1046,7 @@ public class SoundTriggerService extends SystemService { } catch (Exception e) { Slog.e(TAG, mPuuid + ": Cannot remove client", e); - sEventLogger.enqueue(new EventLogger.StringEvent(mPuuid + mEventLogger.enqueue(new EventLogger.StringEvent(mPuuid + ": Cannot remove client")); } @@ -1091,9 +1069,7 @@ public class SoundTriggerService extends SystemService { * dropped. */ private void destroy() { - if (DEBUG) Slog.v(TAG, mPuuid + ": destroy"); - - sEventLogger.enqueue(new EventLogger.StringEvent(mPuuid + ": destroy")); + mEventLogger.enqueue(new EventLogger.StringEvent(mPuuid + ": destroy")); synchronized (mRemoteServiceLock) { disconnectLocked(); @@ -1127,7 +1103,7 @@ public class SoundTriggerService extends SystemService { Slog.e(TAG, mPuuid + ": Could not stop operation " + mRunningOpIds.valueAt(i), e); - sEventLogger.enqueue(new EventLogger.StringEvent(mPuuid + mEventLogger.enqueue(new EventLogger.StringEvent(mPuuid + ": Could not stop operation " + mRunningOpIds.valueAt( i))); @@ -1157,7 +1133,7 @@ public class SoundTriggerService extends SystemService { if (ri == null) { Slog.w(TAG, mPuuid + ": " + mServiceName + " not found"); - sEventLogger.enqueue(new EventLogger.StringEvent(mPuuid + mEventLogger.enqueue(new EventLogger.StringEvent(mPuuid + ": " + mServiceName + " not found")); return; @@ -1168,7 +1144,7 @@ public class SoundTriggerService extends SystemService { Slog.w(TAG, mPuuid + ": " + mServiceName + " does not require " + BIND_SOUND_TRIGGER_DETECTION_SERVICE); - sEventLogger.enqueue(new EventLogger.StringEvent(mPuuid + mEventLogger.enqueue(new EventLogger.StringEvent(mPuuid + ": " + mServiceName + " does not require " + BIND_SOUND_TRIGGER_DETECTION_SERVICE)); @@ -1184,7 +1160,7 @@ public class SoundTriggerService extends SystemService { } else { Slog.w(TAG, mPuuid + ": Could not bind to " + mServiceName); - sEventLogger.enqueue(new EventLogger.StringEvent(mPuuid + mEventLogger.enqueue(new EventLogger.StringEvent(mPuuid + ": Could not bind to " + mServiceName)); } @@ -1206,7 +1182,7 @@ public class SoundTriggerService extends SystemService { mPuuid + ": Dropped operation as already destroyed or marked for " + "destruction"); - sEventLogger.enqueue(new EventLogger.StringEvent(mPuuid + mEventLogger.enqueue(new EventLogger.StringEvent(mPuuid + ":Dropped operation as already destroyed or marked for " + "destruction")); @@ -1238,7 +1214,7 @@ public class SoundTriggerService extends SystemService { mPuuid + ": Dropped operation as too many operations " + "were run in last 24 hours"); - sEventLogger.enqueue(new EventLogger.StringEvent(mPuuid + mEventLogger.enqueue(new EventLogger.StringEvent(mPuuid + ": Dropped operation as too many operations " + "were run in last 24 hours")); @@ -1248,7 +1224,7 @@ public class SoundTriggerService extends SystemService { } catch (Exception e) { Slog.e(TAG, mPuuid + ": Could not drop operation", e); - sEventLogger.enqueue(new EventLogger.StringEvent(mPuuid + mEventLogger.enqueue(new EventLogger.StringEvent(mPuuid + ": Could not drop operation")); } @@ -1265,7 +1241,7 @@ public class SoundTriggerService extends SystemService { try { if (DEBUG) Slog.v(TAG, mPuuid + ": runOp " + opId); - sEventLogger.enqueue(new EventLogger.StringEvent(mPuuid + mEventLogger.enqueue(new EventLogger.StringEvent(mPuuid + ": runOp " + opId)); op.run(opId, mService); @@ -1273,7 +1249,7 @@ public class SoundTriggerService extends SystemService { } catch (Exception e) { Slog.e(TAG, mPuuid + ": Could not run operation " + opId, e); - sEventLogger.enqueue(new EventLogger.StringEvent(mPuuid + mEventLogger.enqueue(new EventLogger.StringEvent(mPuuid + ": Could not run operation " + opId)); } @@ -1303,11 +1279,6 @@ public class SoundTriggerService extends SystemService { @Override public void onKeyphraseDetected(SoundTrigger.KeyphraseRecognitionEvent event) { - Slog.w(TAG, mPuuid + "->" + mServiceName + ": IGNORED onKeyphraseDetected(" + event - + ")"); - - sEventLogger.enqueue(new EventLogger.StringEvent(mPuuid + "->" + mServiceName - + ": IGNORED onKeyphraseDetected(" + event + ")")); } /** @@ -1325,7 +1296,7 @@ public class SoundTriggerService extends SystemService { AudioFormat originalFormat = event.getCaptureFormat(); - sEventLogger.enqueue(new EventLogger.StringEvent("createAudioRecordForEvent")); + mEventLogger.enqueue(new EventLogger.StringEvent("createAudioRecordForEvent")); return (new AudioRecord.Builder()) .setAudioAttributes(attributes) @@ -1340,11 +1311,6 @@ public class SoundTriggerService extends SystemService { @Override public void onGenericSoundTriggerDetected(SoundTrigger.GenericRecognitionEvent event) { - if (DEBUG) Slog.v(TAG, mPuuid + ": Generic sound trigger event: " + event); - - sEventLogger.enqueue(new EventLogger.StringEvent(mPuuid - + ": Generic sound trigger event: " + event)); - runOrAddOperation(new Operation( // always execute: () -> { @@ -1376,7 +1342,7 @@ public class SoundTriggerService extends SystemService { private void onError(int status) { if (DEBUG) Slog.v(TAG, mPuuid + ": onError: " + status); - sEventLogger.enqueue(new EventLogger.StringEvent(mPuuid + mEventLogger.enqueue(new EventLogger.StringEvent(mPuuid + ": onError: " + status)); runOrAddOperation( @@ -1421,27 +1387,17 @@ public class SoundTriggerService extends SystemService { @Override public void onRecognitionPaused() { - Slog.i(TAG, mPuuid + "->" + mServiceName + ": IGNORED onRecognitionPaused"); - - sEventLogger.enqueue(new EventLogger.StringEvent(mPuuid - + "->" + mServiceName + ": IGNORED onRecognitionPaused")); - } @Override public void onRecognitionResumed() { - Slog.i(TAG, mPuuid + "->" + mServiceName + ": IGNORED onRecognitionResumed"); - - sEventLogger.enqueue(new EventLogger.StringEvent(mPuuid - + "->" + mServiceName + ": IGNORED onRecognitionResumed")); - } @Override public void onServiceConnected(ComponentName name, IBinder service) { if (DEBUG) Slog.v(TAG, mPuuid + ": onServiceConnected(" + service + ")"); - sEventLogger.enqueue(new EventLogger.StringEvent(mPuuid + mEventLogger.enqueue(new EventLogger.StringEvent(mPuuid + ": onServiceConnected(" + service + ")")); synchronized (mRemoteServiceLock) { @@ -1464,7 +1420,7 @@ public class SoundTriggerService extends SystemService { public void onServiceDisconnected(ComponentName name) { if (DEBUG) Slog.v(TAG, mPuuid + ": onServiceDisconnected"); - sEventLogger.enqueue(new EventLogger.StringEvent(mPuuid + mEventLogger.enqueue(new EventLogger.StringEvent(mPuuid + ": onServiceDisconnected")); synchronized (mRemoteServiceLock) { @@ -1476,7 +1432,7 @@ public class SoundTriggerService extends SystemService { public void onBindingDied(ComponentName name) { if (DEBUG) Slog.v(TAG, mPuuid + ": onBindingDied"); - sEventLogger.enqueue(new EventLogger.StringEvent(mPuuid + mEventLogger.enqueue(new EventLogger.StringEvent(mPuuid + ": onBindingDied")); synchronized (mRemoteServiceLock) { @@ -1488,7 +1444,7 @@ public class SoundTriggerService extends SystemService { public void onNullBinding(ComponentName name) { Slog.w(TAG, name + " for model " + mPuuid + " returned a null binding"); - sEventLogger.enqueue(new EventLogger.StringEvent(name + " for model " + mEventLogger.enqueue(new EventLogger.StringEvent(name + " for model " + mPuuid + " returned a null binding")); synchronized (mRemoteServiceLock) { @@ -1613,17 +1569,25 @@ public class SoundTriggerService extends SystemService { private class SessionImpl implements Session { private final @NonNull SoundTriggerHelper mSoundTriggerHelper; private final @NonNull IBinder mClient; + private final EventLogger mEventLogger; + private final Identity mOriginatorIdentity; + + private final SparseArray mModelUuid = new SparseArray<>(1); + + private SessionImpl(@NonNull SoundTriggerHelper soundTriggerHelper, + @NonNull IBinder client, + @NonNull EventLogger eventLogger, @NonNull Identity originatorIdentity) { - private SessionImpl( - @NonNull SoundTriggerHelper soundTriggerHelper, @NonNull IBinder client) { mSoundTriggerHelper = soundTriggerHelper; mClient = client; + mOriginatorIdentity = originatorIdentity; + mEventLogger = eventLogger; + + mSessionEventLoggers.add(mEventLogger); try { - mClient.linkToDeath(() -> { - clientDied(); - }, 0); + mClient.linkToDeath(() -> clientDied(), 0); } catch (RemoteException e) { - Slog.e(TAG, "Failed to register death listener.", e); + clientDied(); } } @@ -1631,6 +1595,9 @@ public class SoundTriggerService extends SystemService { public int startRecognition(int keyphraseId, KeyphraseSoundModel soundModel, IRecognitionStatusCallback listener, RecognitionConfig recognitionConfig, boolean runInBatterySaverMode) { + mModelUuid.put(keyphraseId, soundModel.getUuid()); + mEventLogger.enqueue(new SessionEvent(Type.START_RECOGNITION, + soundModel.getUuid())); return mSoundTriggerHelper.startKeyphraseRecognition(keyphraseId, soundModel, listener, recognitionConfig, runInBatterySaverMode); } @@ -1638,16 +1605,21 @@ public class SoundTriggerService extends SystemService { @Override public synchronized int stopRecognition(int keyphraseId, IRecognitionStatusCallback listener) { + var uuid = mModelUuid.get(keyphraseId); + mEventLogger.enqueue(new SessionEvent(Type.STOP_RECOGNITION, uuid)); return mSoundTriggerHelper.stopKeyphraseRecognition(keyphraseId, listener); } @Override public ModuleProperties getModuleProperties() { + mEventLogger.enqueue(new SessionEvent(Type.GET_MODULE_PROPERTIES, null)); return mSoundTriggerHelper.getModuleProperties(); } @Override public int setParameter(int keyphraseId, @ModelParams int modelParam, int value) { + var uuid = mModelUuid.get(keyphraseId); + mEventLogger.enqueue(new SessionEvent(Type.SET_PARAMETER, uuid)); return mSoundTriggerHelper.setKeyphraseParameter(keyphraseId, modelParam, value); } @@ -1664,40 +1636,54 @@ public class SoundTriggerService extends SystemService { @Override public void detach() { - mSoundTriggerHelper.detach(); + detachInternal(); } @Override public int unloadKeyphraseModel(int keyphraseId) { + var uuid = mModelUuid.get(keyphraseId); + mEventLogger.enqueue(new SessionEvent(Type.UNLOAD_MODEL, uuid)); return mSoundTriggerHelper.unloadKeyphraseSoundModel(keyphraseId); } private void clientDied() { - Slog.w(TAG, "Client died, cleaning up session."); - sEventLogger.enqueue(new EventLogger.StringEvent( - "Client died, cleaning up session.")); + mServiceEventLogger.enqueue(new ServiceEvent( + ServiceEvent.Type.DETACH, mOriginatorIdentity.packageName, + "Client died") + .printLog(ALOGW, TAG)); + detachInternal(); + } + + private void detachInternal() { + mEventLogger.enqueue(new SessionEvent(Type.DETACH, null)); + mSessionEventLoggers.remove(mEventLogger); + addDetachedSessionLogger(mEventLogger); mSoundTriggerHelper.detach(); } } @Override public Session attach(@NonNull IBinder client, ModuleProperties underlyingModule) { - return new SessionImpl(newSoundTriggerHelper(underlyingModule), client); + var identity = IdentityContext.getNonNull(); + int sessionId = mSessionIdCounter.getAndIncrement(); + mServiceEventLogger.enqueue(new ServiceEvent( + ServiceEvent.Type.ATTACH, identity.packageName + "#" + sessionId)); + var eventLogger = new EventLogger(SESSION_MAX_EVENT_SIZE, + "LocalSoundTriggerEventLogger for package: " + + identity.packageName + "#" + sessionId); + + return new SessionImpl(newSoundTriggerHelper(underlyingModule, eventLogger), + client, eventLogger, identity); } @Override public List listModuleProperties(Identity originatorIdentity) { + mServiceEventLogger.enqueue(new ServiceEvent( + ServiceEvent.Type.LIST_MODULE, originatorIdentity.packageName)); try (SafeCloseable ignored = PermissionUtil.establishIdentityDirect( originatorIdentity)) { return listUnderlyingModuleProperties(originatorIdentity); } } } - - //================================================================= - // For logging - - private static final EventLogger sEventLogger = new EventLogger(200, - "SoundTrigger activity"); - } From 55dcabecd764bf3a3d9cb601a821e33db58a6948 Mon Sep 17 00:00:00 2001 From: Atneya Nair Date: Sun, 16 Apr 2023 23:44:59 -0700 Subject: [PATCH 3/3] Sessionize STMiddleware logging - Migrate STMiddleware to EventLogger - Keep separate loggers for each session to prevent over-runs, in addition to a service wide logger - Keep a cache of recently detached session loggers Bug: 272147641 Fixes: 274970620 Test: atest SoundTriggerMiddlewareLoggingTest Test: Manual verification of dumpsys and logcat formatting Test: Manual verification of dumpsys after detach Test: Manual verification of logcat Change-Id: I69bc716ce739b6ad69d7afb31e1699b1625ee3c0 --- .../SoundTriggerMiddlewareLoggingTest.java | 139 ++++ .../ObjectPrinter.java | 10 + .../SoundTriggerMiddlewareLogging.java | 617 +++++++++++------- 3 files changed, 539 insertions(+), 227 deletions(-) diff --git a/services/tests/voiceinteractiontests/src/com/android/server/soundtrigger_middleware/SoundTriggerMiddlewareLoggingTest.java b/services/tests/voiceinteractiontests/src/com/android/server/soundtrigger_middleware/SoundTriggerMiddlewareLoggingTest.java index 4d3c26f4973e4..eb117d1283836 100644 --- a/services/tests/voiceinteractiontests/src/com/android/server/soundtrigger_middleware/SoundTriggerMiddlewareLoggingTest.java +++ b/services/tests/voiceinteractiontests/src/com/android/server/soundtrigger_middleware/SoundTriggerMiddlewareLoggingTest.java @@ -16,6 +16,8 @@ package com.android.server.soundtrigger_middleware; +import static com.android.server.soundtrigger_middleware.SoundTriggerMiddlewareLogging.ServiceEvent; +import static com.android.server.soundtrigger_middleware.SoundTriggerMiddlewareLogging.SessionEvent; import static com.android.internal.util.LatencyTracker.ACTION_SHOW_VOICE_INTERACTION; import static com.google.common.truth.Truth.assertThat; @@ -55,6 +57,9 @@ import java.util.Optional; @RunWith(JUnit4.class) public class SoundTriggerMiddlewareLoggingTest { + private static final ServiceEvent.Type SERVICE_TYPE = ServiceEvent.Type.ATTACH; + private static final SessionEvent.Type SESSION_TYPE = SessionEvent.Type.LOAD_MODEL; + private FakeLatencyTracker mLatencyTracker; @Mock private BatteryStatsInternal mBatteryStatsInternal; @@ -184,4 +189,138 @@ public class SoundTriggerMiddlewareLoggingTest { callback.onPhraseRecognition(0 /* modelHandle */, successEventWithKeyphraseId, 0 /* captureSession */); } + + @Test + public void serviceEventException_getStringContainsInfo() { + String packageName = "com.android.test"; + Exception exception = new Exception("test"); + Object param1 = new Object(); + Object param2 = new Object(); + final var event = ServiceEvent.createForException( + SERVICE_TYPE, packageName, exception, param1, param2); + final var stringRep = event.eventToString(); + assertThat(stringRep).contains(SERVICE_TYPE.name()); + assertThat(stringRep).contains(packageName); + assertThat(stringRep).contains(exception.toString()); + assertThat(stringRep).contains(param1.toString()); + assertThat(stringRep).contains(param2.toString()); + assertThat(stringRep).ignoringCase().contains("error"); + } + + @Test + public void serviceEventExceptionNoArgs_getStringContainsInfo() { + String packageName = "com.android.test"; + Exception exception = new Exception("test"); + final var event = ServiceEvent.createForException( + SERVICE_TYPE, packageName, exception); + final var stringRep = event.eventToString(); + assertThat(stringRep).contains(SERVICE_TYPE.name()); + assertThat(stringRep).contains(packageName); + assertThat(stringRep).contains(exception.toString()); + assertThat(stringRep).ignoringCase().contains("error"); + } + + @Test + public void serviceEventReturn_getStringContainsInfo() { + String packageName = "com.android.test"; + Object param1 = new Object(); + Object param2 = new Object(); + Object retValue = new Object(); + final var event = ServiceEvent.createForReturn( + SERVICE_TYPE, packageName, retValue, param1, param2); + final var stringRep = event.eventToString(); + assertThat(stringRep).contains(SERVICE_TYPE.name()); + assertThat(stringRep).contains(packageName); + assertThat(stringRep).contains(retValue.toString()); + assertThat(stringRep).contains(param1.toString()); + assertThat(stringRep).contains(param2.toString()); + assertThat(stringRep).ignoringCase().doesNotContain("error"); + } + + @Test + public void serviceEventReturnNoArgs_getStringContainsInfo() { + String packageName = "com.android.test"; + Object retValue = new Object(); + final var event = ServiceEvent.createForReturn( + SERVICE_TYPE, packageName, retValue); + final var stringRep = event.eventToString(); + assertThat(stringRep).contains(SERVICE_TYPE.name()); + assertThat(stringRep).contains(packageName); + assertThat(stringRep).contains(retValue.toString()); + assertThat(stringRep).ignoringCase().doesNotContain("error"); + } + + @Test + public void sessionEventException_getStringContainsInfo() { + Object param1 = new Object(); + Object param2 = new Object(); + Exception exception = new Exception("test"); + final var event = SessionEvent.createForException( + SESSION_TYPE, exception, param1, param2); + final var stringRep = event.eventToString(); + assertThat(stringRep).contains(SESSION_TYPE.name()); + assertThat(stringRep).contains(exception.toString()); + assertThat(stringRep).contains(param1.toString()); + assertThat(stringRep).contains(param2.toString()); + assertThat(stringRep).ignoringCase().contains("error"); + } + + @Test + public void sessionEventExceptionNoArgs_getStringContainsInfo() { + Exception exception = new Exception("test"); + final var event = SessionEvent.createForException( + SESSION_TYPE, exception); + final var stringRep = event.eventToString(); + assertThat(stringRep).contains(SESSION_TYPE.name()); + assertThat(stringRep).contains(exception.toString()); + assertThat(stringRep).ignoringCase().contains("error"); + } + + @Test + public void sessionEventReturn_getStringContainsInfo() { + Object param1 = new Object(); + Object param2 = new Object(); + Object retValue = new Object(); + final var event = SessionEvent.createForReturn( + SESSION_TYPE, retValue, param1, param2); + final var stringRep = event.eventToString(); + assertThat(stringRep).contains(SESSION_TYPE.name()); + assertThat(stringRep).contains(retValue.toString()); + assertThat(stringRep).contains(param1.toString()); + assertThat(stringRep).contains(param2.toString()); + assertThat(stringRep).ignoringCase().doesNotContain("error"); + } + + @Test + public void sessionEventReturnNoArgs_getStringContainsInfo() { + Object retValue = new Object(); + final var event = SessionEvent.createForReturn( + SESSION_TYPE, retValue); + final var stringRep = event.eventToString(); + assertThat(stringRep).contains(SESSION_TYPE.name()); + assertThat(stringRep).contains(retValue.toString()); + assertThat(stringRep).ignoringCase().doesNotContain("error"); + } + + @Test + public void sessionEventVoid_getStringContainsInfo() { + Object param1 = new Object(); + Object param2 = new Object(); + final var event = SessionEvent.createForVoid( + SESSION_TYPE, param1, param2); + final var stringRep = event.eventToString(); + assertThat(stringRep).contains(SESSION_TYPE.name()); + assertThat(stringRep).contains(param1.toString()); + assertThat(stringRep).contains(param2.toString()); + assertThat(stringRep).ignoringCase().doesNotContain("error"); + } + + @Test + public void sessionEventVoidNoArgs_getStringContainsInfo() { + final var event = SessionEvent.createForVoid( + SESSION_TYPE); + final var stringRep = event.eventToString(); + assertThat(stringRep).contains(SESSION_TYPE.name()); + assertThat(stringRep).ignoringCase().doesNotContain("error"); + } } diff --git a/services/voiceinteraction/java/com/android/server/soundtrigger_middleware/ObjectPrinter.java b/services/voiceinteraction/java/com/android/server/soundtrigger_middleware/ObjectPrinter.java index fba0fb49da5cd..cbc959c0b33a4 100644 --- a/services/voiceinteraction/java/com/android/server/soundtrigger_middleware/ObjectPrinter.java +++ b/services/voiceinteraction/java/com/android/server/soundtrigger_middleware/ObjectPrinter.java @@ -44,6 +44,16 @@ class ObjectPrinter { return builder.toString(); } + /** + * Same as {@link #print(StringBuilder, Object, int)} with default max length. + * + * @param builder StringBuilder to print into. + * @param obj The object to print. + */ + static void print(@NonNull StringBuilder builder, @Nullable Object obj) { + print(builder, obj, kDefaultMaxCollectionLength); + } + /** * A version of {@link #print(Object, int)} that uses a {@link StringBuilder}. * diff --git a/services/voiceinteraction/java/com/android/server/soundtrigger_middleware/SoundTriggerMiddlewareLogging.java b/services/voiceinteraction/java/com/android/server/soundtrigger_middleware/SoundTriggerMiddlewareLogging.java index 4c134af185520..0e796d1afbd6b 100644 --- a/services/voiceinteraction/java/com/android/server/soundtrigger_middleware/SoundTriggerMiddlewareLogging.java +++ b/services/voiceinteraction/java/com/android/server/soundtrigger_middleware/SoundTriggerMiddlewareLogging.java @@ -16,6 +16,10 @@ package com.android.server.soundtrigger_middleware; +import static com.android.server.soundtrigger_middleware.SoundTriggerMiddlewareLogging.SessionEvent.Type.*; +import static com.android.server.utils.EventLogger.Event.ALOGI; +import static com.android.server.utils.EventLogger.Event.ALOGW; + import android.annotation.NonNull; import android.annotation.Nullable; import android.content.Context; @@ -41,13 +45,20 @@ import com.android.internal.annotations.VisibleForTesting; import com.android.internal.util.ArrayUtils; import com.android.internal.util.LatencyTracker; import com.android.server.LocalServices; +import com.android.server.utils.EventLogger.Event; +import com.android.server.utils.EventLogger; + import java.io.PrintWriter; -import java.text.SimpleDateFormat; -import java.util.Date; -import java.util.LinkedList; +import java.util.Arrays; import java.util.Objects; +import java.util.Set; +import java.util.concurrent.ConcurrentHashMap; +import java.util.concurrent.LinkedBlockingDeque; +import java.util.concurrent.atomic.AtomicInteger; import java.util.function.Supplier; +import java.util.Deque; + /** * An ISoundTriggerMiddlewareService decorator, which adds logging of all API calls (and @@ -74,9 +85,17 @@ import java.util.function.Supplier; */ public class SoundTriggerMiddlewareLogging implements ISoundTriggerMiddlewareInternal, Dumpable { private static final String TAG = "SoundTriggerMiddlewareLogging"; + private static final int SESSION_MAX_EVENT_SIZE = 128; private final @NonNull ISoundTriggerMiddlewareInternal mDelegate; private final @NonNull LatencyTracker mLatencyTracker; private final @NonNull Supplier mBatteryStatsInternalSupplier; + private final @NonNull EventLogger mServiceEventLogger = new EventLogger(256, + "Service Events"); + + private final Set mSessionEventLoggers = ConcurrentHashMap.newKeySet(4); + private final Deque mDetachedSessionEventLoggers = new LinkedBlockingDeque<>(4); + private final AtomicInteger mSessionCount = new AtomicInteger(0); + public SoundTriggerMiddlewareLogging(@NonNull Context context, @NonNull ISoundTriggerMiddlewareInternal delegate) { @@ -99,10 +118,19 @@ public class SoundTriggerMiddlewareLogging implements ISoundTriggerMiddlewareInt SoundTriggerModuleDescriptor[] listModules() { try { SoundTriggerModuleDescriptor[] result = mDelegate.listModules(); - logReturn("listModules", result); + var moduleSummary = Arrays.stream(result).map((descriptor) -> + new ModulePropertySummary(descriptor.handle, + descriptor.properties.implementor, + descriptor.properties.version)).toArray(ModulePropertySummary[]::new); + + mServiceEventLogger.enqueue(ServiceEvent.createForReturn( + ServiceEvent.Type.LIST_MODULE, + IdentityContext.get().packageName, moduleSummary).printLog(ALOGI, TAG)); return result; } catch (Exception e) { - logException("listModules", e); + mServiceEventLogger.enqueue(ServiceEvent.createForException( + ServiceEvent.Type.LIST_MODULE, + IdentityContext.get().packageName, e).printLog(ALOGW, TAG)); throw e; } } @@ -111,12 +139,29 @@ public class SoundTriggerMiddlewareLogging implements ISoundTriggerMiddlewareInt public @NonNull ISoundTriggerModule attach(int handle, ISoundTriggerCallback callback) { try { - ModuleLogging result = new ModuleLogging(callback); - result.attach(mDelegate.attach(handle, result.getCallbackWrapper())); - logReturn("attach", result, handle, callback); + var originatorIdentity = IdentityContext.getNonNull(); + String packageIdentification = originatorIdentity.packageName + + mSessionCount.getAndIncrement(); + ModuleLogging result = new ModuleLogging(); + var eventLogger = new EventLogger(SESSION_MAX_EVENT_SIZE, + "Session logger for: " + packageIdentification); + + var callbackWrapper = new CallbackLogging(callback, eventLogger, originatorIdentity); + + result.attach(mDelegate.attach(handle, callbackWrapper), eventLogger); + + mServiceEventLogger.enqueue(ServiceEvent.createForReturn( + ServiceEvent.Type.ATTACH, + packageIdentification, result, handle, callback) + .printLog(ALOGI, TAG)); + + mSessionEventLoggers.add(eventLogger); return result; } catch (Exception e) { - logException("attach", e, handle, callback); + mServiceEventLogger.enqueue(ServiceEvent.createForException( + ServiceEvent.Type.ATTACH, + IdentityContext.get().packageName, e, handle, callback) + .printLog(ALOGW, TAG)); throw e; } } @@ -127,44 +172,27 @@ public class SoundTriggerMiddlewareLogging implements ISoundTriggerMiddlewareInt return mDelegate.toString(); } - private void logException(String methodName, Exception ex, Object... args) { - logExceptionWithObject(this, IdentityContext.get(), methodName, ex, args); - } - - private void logReturn(String methodName, Object retVal, Object... args) { - logReturnWithObject(this, IdentityContext.get(), methodName, retVal, args); - } - - private void logVoidReturn(String methodName, Object... args) { - logVoidReturnWithObject(this, IdentityContext.get(), methodName, args); - } - private class ModuleLogging implements ISoundTriggerModule { private ISoundTriggerModule mDelegate; - private final @NonNull CallbackLogging mCallbackWrapper; - private final @NonNull Identity mOriginatorIdentity; + private EventLogger mEventLogger; - ModuleLogging(@NonNull ISoundTriggerCallback callback) { - mCallbackWrapper = new CallbackLogging(callback); - mOriginatorIdentity = IdentityContext.getNonNull(); - } - - void attach(@NonNull ISoundTriggerModule delegate) { + void attach(@NonNull ISoundTriggerModule delegate, EventLogger eventLogger) { mDelegate = delegate; - } - - ISoundTriggerCallback getCallbackWrapper() { - return mCallbackWrapper; + mEventLogger = eventLogger; } @Override public int loadModel(SoundModel model) throws RemoteException { try { int result = mDelegate.loadModel(model); - logReturn("loadModel", result, model); + mEventLogger.enqueue(SessionEvent.createForReturn( + LOAD_MODEL, result, model.uuid) + .printLog(ALOGI, TAG)); return result; } catch (Exception e) { - logException("loadModel", e, model); + mEventLogger.enqueue(SessionEvent.createForReturn( + LOAD_MODEL, e, model.uuid) + .printLog(ALOGW, TAG)); throw e; } } @@ -173,10 +201,14 @@ public class SoundTriggerMiddlewareLogging implements ISoundTriggerMiddlewareInt public int loadPhraseModel(PhraseSoundModel model) throws RemoteException { try { int result = mDelegate.loadPhraseModel(model); - logReturn("loadPhraseModel", result, model); + mEventLogger.enqueue(SessionEvent.createForReturn( + LOAD_PHRASE_MODEL, result, model.common.uuid) + .printLog(ALOGI, TAG)); return result; } catch (Exception e) { - logException("loadPhraseModel", e, model); + mEventLogger.enqueue(SessionEvent.createForException( + LOAD_PHRASE_MODEL, e, model.common.uuid) + .printLog(ALOGW, TAG)); throw e; } } @@ -185,9 +217,13 @@ public class SoundTriggerMiddlewareLogging implements ISoundTriggerMiddlewareInt public void unloadModel(int modelHandle) throws RemoteException { try { mDelegate.unloadModel(modelHandle); - logVoidReturn("unloadModel", modelHandle); + mEventLogger.enqueue(SessionEvent.createForVoid( + UNLOAD_MODEL, modelHandle) + .printLog(ALOGI, TAG)); } catch (Exception e) { - logException("unloadModel", e, modelHandle); + mEventLogger.enqueue(SessionEvent.createForException( + UNLOAD_MODEL, e, modelHandle) + .printLog(ALOGW, TAG)); throw e; } } @@ -197,9 +233,13 @@ public class SoundTriggerMiddlewareLogging implements ISoundTriggerMiddlewareInt throws RemoteException { try { mDelegate.startRecognition(modelHandle, config); - logVoidReturn("startRecognition", modelHandle, config); + mEventLogger.enqueue(SessionEvent.createForVoid( + START_RECOGNITION, modelHandle, config) + .printLog(ALOGI, TAG)); } catch (Exception e) { - logException("startRecognition", e, modelHandle, config); + mEventLogger.enqueue(SessionEvent.createForException( + START_RECOGNITION, e, modelHandle, config) + .printLog(ALOGW, TAG)); throw e; } } @@ -208,9 +248,13 @@ public class SoundTriggerMiddlewareLogging implements ISoundTriggerMiddlewareInt public void stopRecognition(int modelHandle) throws RemoteException { try { mDelegate.stopRecognition(modelHandle); - logVoidReturn("stopRecognition", modelHandle); + mEventLogger.enqueue(SessionEvent.createForVoid( + STOP_RECOGNITION, modelHandle) + .printLog(ALOGI, TAG)); } catch (Exception e) { - logException("stopRecognition", e, modelHandle); + mEventLogger.enqueue(SessionEvent.createForException( + STOP_RECOGNITION, e, modelHandle) + .printLog(ALOGW, TAG)); throw e; } } @@ -219,9 +263,13 @@ public class SoundTriggerMiddlewareLogging implements ISoundTriggerMiddlewareInt public void forceRecognitionEvent(int modelHandle) throws RemoteException { try { mDelegate.forceRecognitionEvent(modelHandle); - logVoidReturn("forceRecognitionEvent", modelHandle); + mEventLogger.enqueue(SessionEvent.createForVoid( + FORCE_RECOGNITION, modelHandle) + .printLog(ALOGI, TAG)); } catch (Exception e) { - logException("forceRecognitionEvent", e, modelHandle); + mEventLogger.enqueue(SessionEvent.createForException( + FORCE_RECOGNITION, e, modelHandle) + .printLog(ALOGW, TAG)); throw e; } } @@ -231,9 +279,13 @@ public class SoundTriggerMiddlewareLogging implements ISoundTriggerMiddlewareInt throws RemoteException { try { mDelegate.setModelParameter(modelHandle, modelParam, value); - logVoidReturn("setModelParameter", modelHandle, modelParam, value); + mEventLogger.enqueue(SessionEvent.createForVoid( + SET_MODEL_PARAMETER, modelHandle, modelParam, value) + .printLog(ALOGI, TAG)); } catch (Exception e) { - logException("setModelParameter", e, modelHandle, modelParam, value); + mEventLogger.enqueue(SessionEvent.createForException( + SET_MODEL_PARAMETER, e, modelHandle, modelParam, value) + .printLog(ALOGW, TAG)); throw e; } } @@ -242,10 +294,14 @@ public class SoundTriggerMiddlewareLogging implements ISoundTriggerMiddlewareInt public int getModelParameter(int modelHandle, int modelParam) throws RemoteException { try { int result = mDelegate.getModelParameter(modelHandle, modelParam); - logReturn("getModelParameter", result, modelHandle, modelParam); + mEventLogger.enqueue(SessionEvent.createForReturn( + GET_MODEL_PARAMETER, result, modelHandle, modelParam) + .printLog(ALOGI, TAG)); return result; } catch (Exception e) { - logException("getModelParameter", e, modelHandle, modelParam); + mEventLogger.enqueue(SessionEvent.createForException( + GET_MODEL_PARAMETER, e, modelHandle, modelParam) + .printLog(ALOGW, TAG)); throw e; } } @@ -256,10 +312,14 @@ public class SoundTriggerMiddlewareLogging implements ISoundTriggerMiddlewareInt try { ModelParameterRange result = mDelegate.queryModelParameterSupport(modelHandle, modelParam); - logReturn("queryModelParameterSupport", result, modelHandle, modelParam); + mEventLogger.enqueue(SessionEvent.createForReturn( + QUERY_MODEL_PARAMETER, result, modelHandle, modelParam) + .printLog(ALOGI, TAG)); return result; } catch (Exception e) { - logException("queryModelParameterSupport", e, modelHandle, modelParam); + mEventLogger.enqueue(SessionEvent.createForException( + QUERY_MODEL_PARAMETER, e, modelHandle, modelParam) + .printLog(ALOGW, TAG)); throw e; } } @@ -267,10 +327,20 @@ public class SoundTriggerMiddlewareLogging implements ISoundTriggerMiddlewareInt @Override public void detach() throws RemoteException { try { + if (mSessionEventLoggers.remove(mEventLogger)) { + while (!mDetachedSessionEventLoggers.offerFirst(mEventLogger)) { + // Remove the oldest element, if one still exists + mDetachedSessionEventLoggers.pollLast(); + } + } mDelegate.detach(); - logVoidReturn("detach"); + mEventLogger.enqueue(SessionEvent.createForVoid( + DETACH) + .printLog(ALOGI, TAG)); } catch (Exception e) { - logException("detach", e); + mEventLogger.enqueue(SessionEvent.createForException( + DETACH, e) + .printLog(ALOGW, TAG)); throw e; } } @@ -285,107 +355,112 @@ public class SoundTriggerMiddlewareLogging implements ISoundTriggerMiddlewareInt public String toString() { return Objects.toString(mDelegate); } + } - private void logException(String methodName, Exception ex, Object... args) { - logExceptionWithObject(this, mOriginatorIdentity, methodName, ex, args); + private class CallbackLogging implements ISoundTriggerCallback { + private final ISoundTriggerCallback mCallbackDelegate; + private final EventLogger mEventLogger; + private final Identity mOriginatorIdentity; + + private CallbackLogging(ISoundTriggerCallback delegate, + EventLogger eventLogger, Identity originatorIdentity) { + mCallbackDelegate = Objects.requireNonNull(delegate); + mEventLogger = Objects.requireNonNull(eventLogger); + mOriginatorIdentity = originatorIdentity; } - private void logReturn(String methodName, Object retVal, Object... args) { - logReturnWithObject(this, mOriginatorIdentity, methodName, retVal, args); + @Override + public void onRecognition(int modelHandle, RecognitionEvent event, int captureSession) + throws RemoteException { + try { + mBatteryStatsInternalSupplier.get().noteWakingSoundTrigger( + SystemClock.elapsedRealtime(), mOriginatorIdentity.uid); + mCallbackDelegate.onRecognition(modelHandle, event, captureSession); + mEventLogger.enqueue(SessionEvent.createForVoid( + RECOGNITION, modelHandle, event, captureSession) + .printLog(ALOGI, TAG)); + } catch (Exception e) { + mEventLogger.enqueue(SessionEvent.createForException( + RECOGNITION, e, modelHandle, event, captureSession) + .printLog(ALOGW, TAG)); + throw e; + } } - private void logVoidReturn(String methodName, Object... args) { - logVoidReturnWithObject(this, mOriginatorIdentity, methodName, args); + @Override + public void onPhraseRecognition(int modelHandle, PhraseRecognitionEvent event, + int captureSession) + throws RemoteException { + try { + mBatteryStatsInternalSupplier.get().noteWakingSoundTrigger( + SystemClock.elapsedRealtime(), mOriginatorIdentity.uid); + startKeyphraseEventLatencyTracking(event); + mCallbackDelegate.onPhraseRecognition(modelHandle, event, captureSession); + mEventLogger.enqueue(SessionEvent.createForVoid( + RECOGNITION, modelHandle, event, captureSession) + .printLog(ALOGI, TAG)); + } catch (Exception e) { + mEventLogger.enqueue(SessionEvent.createForException( + RECOGNITION, e, modelHandle, event, captureSession) + .printLog(ALOGW, TAG)); + throw e; + } } - private class CallbackLogging implements ISoundTriggerCallback { - private final ISoundTriggerCallback mCallbackDelegate; - - private CallbackLogging(ISoundTriggerCallback delegate) { - mCallbackDelegate = delegate; + @Override + public void onModelUnloaded(int modelHandle) throws RemoteException { + try { + mCallbackDelegate.onModelUnloaded(modelHandle); + mEventLogger.enqueue(SessionEvent.createForVoid( + MODEL_UNLOADED, modelHandle) + .printLog(ALOGI, TAG)); + } catch (Exception e) { + mEventLogger.enqueue(SessionEvent.createForException( + MODEL_UNLOADED, e, modelHandle) + .printLog(ALOGW, TAG)); + throw e; } + } - @Override - public void onRecognition(int modelHandle, RecognitionEvent event, int captureSession) - throws RemoteException { - try { - mBatteryStatsInternalSupplier.get().noteWakingSoundTrigger( - SystemClock.elapsedRealtime(), mOriginatorIdentity.uid); - mCallbackDelegate.onRecognition(modelHandle, event, captureSession); - logVoidReturn("onRecognition", modelHandle, event); - } catch (Exception e) { - logException("onRecognition", e, modelHandle, event); - throw e; - } + @Override + public void onResourcesAvailable() throws RemoteException { + try { + mCallbackDelegate.onResourcesAvailable(); + mEventLogger.enqueue(SessionEvent.createForVoid( + RESOURCES_AVAILABLE) + .printLog(ALOGI, TAG)); + } catch (Exception e) { + mEventLogger.enqueue(SessionEvent.createForException( + RESOURCES_AVAILABLE, e) + .printLog(ALOGW, TAG)); + throw e; } + } - @Override - public void onPhraseRecognition(int modelHandle, PhraseRecognitionEvent event, - int captureSession) - throws RemoteException { - try { - mBatteryStatsInternalSupplier.get().noteWakingSoundTrigger( - SystemClock.elapsedRealtime(), mOriginatorIdentity.uid); - startKeyphraseEventLatencyTracking(event); - mCallbackDelegate.onPhraseRecognition(modelHandle, event, captureSession); - logVoidReturn("onPhraseRecognition", modelHandle, event); - } catch (Exception e) { - logException("onPhraseRecognition", e, modelHandle, event); - throw e; - } + @Override + public void onModuleDied() throws RemoteException { + try { + mCallbackDelegate.onModuleDied(); + mEventLogger.enqueue(SessionEvent.createForVoid( + MODULE_DIED) + .printLog(ALOGW, TAG)); + } catch (Exception e) { + mEventLogger.enqueue(SessionEvent.createForException( + MODULE_DIED, e) + .printLog(ALOGW, TAG)); + throw e; } + } - @Override - public void onModelUnloaded(int modelHandle) throws RemoteException { - try { - mCallbackDelegate.onModelUnloaded(modelHandle); - logVoidReturn("onModelUnloaded", modelHandle); - } catch (Exception e) { - logException("onModelUnloaded", e, modelHandle); - throw e; - } - } + @Override + public IBinder asBinder() { + return mCallbackDelegate.asBinder(); + } - @Override - public void onResourcesAvailable() throws RemoteException { - try { - mCallbackDelegate.onResourcesAvailable(); - logVoidReturn("onResourcesAvailable"); - } catch (Exception e) { - logException("onResourcesAvailable", e); - throw e; - } - } - - @Override - public void onModuleDied() throws RemoteException { - try { - mCallbackDelegate.onModuleDied(); - logVoidReturn("onModuleDied"); - } catch (Exception e) { - logException("onModuleDied", e); - throw e; - } - } - - private void logException(String methodName, Exception ex, Object... args) { - logExceptionWithObject(this, mOriginatorIdentity, methodName, ex, args); - } - - private void logVoidReturn(String methodName, Object... args) { - logVoidReturnWithObject(this, mOriginatorIdentity, methodName, args); - } - - @Override - public IBinder asBinder() { - return mCallbackDelegate.asBinder(); - } - - // Override toString() in order to have the delegate's ID in it. - @Override - public String toString() { - return Objects.toString(mCallbackDelegate); - } + // Override toString() in order to have the delegate's ID in it. + @Override + public String toString() { + return Objects.toString(mCallbackDelegate); } } @@ -418,105 +493,193 @@ public class SoundTriggerMiddlewareLogging implements ISoundTriggerMiddlewareInt latencyTrackerTag); } - //////////////////////////////////////////////////////////////////////////////////////////////// - // Actual logging logic below. - private static final int NUM_EVENTS_TO_DUMP = 64; - private final static SimpleDateFormat DATE_FORMAT = new SimpleDateFormat("MM-dd HH:mm:ss:SSS"); - private final @NonNull LinkedList mLastEvents = new LinkedList<>(); - - static private class Event { - public final long timestamp = System.currentTimeMillis(); - public final String message; - - private Event(String message) { - this.message = message; - } - } - - private static String printArgs(@NonNull Object[] args) { - StringBuilder result = new StringBuilder(); + private static StringBuilder printArgs(StringBuilder builder, @NonNull Object[] args) { for (int i = 0; i < args.length; ++i) { if (i > 0) { - result.append(", "); + builder.append(", "); } - printObject(result, args[i]); - } - return result.toString(); - } - - private static void printObject(@NonNull StringBuilder builder, @Nullable Object obj) { - ObjectPrinter.print(builder, obj, 16); - } - - private static String printObject(@Nullable Object obj) { - StringBuilder builder = new StringBuilder(); - printObject(builder, obj); - return builder.toString(); - } - - private void logReturnWithObject(@NonNull Object object, @Nullable Identity originatorIdentity, - String methodName, - @Nullable Object retVal, - @NonNull Object[] args) { - final String message = String.format("%s[this=%s, client=%s](%s) -> %s", methodName, - object, - printObject(originatorIdentity), - printArgs(args), - printObject(retVal)); - Slog.i(TAG, message); - appendMessage(message); - } - - private void logVoidReturnWithObject(@NonNull Object object, - @Nullable Identity originatorIdentity, @NonNull String methodName, - @NonNull Object[] args) { - final String message = String.format("%s[this=%s, client=%s](%s)", methodName, - object, - printObject(originatorIdentity), - printArgs(args)); - Slog.i(TAG, message); - appendMessage(message); - } - - private void logExceptionWithObject(@NonNull Object object, - @Nullable Identity originatorIdentity, @NonNull String methodName, - @NonNull Exception ex, - Object[] args) { - final String message = String.format("%s[this=%s, client=%s](%s) threw", methodName, - object, - printObject(originatorIdentity), - printArgs(args)); - Slog.e(TAG, message, ex); - appendMessage(message + " " + ex.toString()); - } - - private void appendMessage(@NonNull String message) { - Event event = new Event(message); - synchronized (mLastEvents) { - if (mLastEvents.size() > NUM_EVENTS_TO_DUMP) { - mLastEvents.remove(); - } - mLastEvents.add(event); + ObjectPrinter.print(builder, args[i]); } + return builder; } @Override public void dump(PrintWriter pw) { - pw.println(); - pw.println("========================================="); - pw.println("Last events"); - pw.println("========================================="); - synchronized (mLastEvents) { - for (Event event : mLastEvents) { - pw.print(DATE_FORMAT.format(new Date(event.timestamp))); - pw.print('\t'); - pw.println(event.message); - } + // Event loggers + pw.println("##Service-Wide logs:"); + mServiceEventLogger.dump(pw, /* indent = */ " "); + + pw.println("\n##Active Session dumps:\n"); + for (var sessionLogger : mSessionEventLoggers) { + sessionLogger.dump(pw, /* indent= */ " "); + pw.println(""); + } + pw.println("##Detached Session dumps:\n"); + for (var sessionLogger : mDetachedSessionEventLoggers) { + sessionLogger.dump(pw, /* indent= */ " "); + pw.println(""); } - pw.println(); if (mDelegate instanceof Dumpable) { ((Dumpable) mDelegate).dump(pw); } } + + public static void printSystemLog(int type, String tag, String message, Exception e) { + switch (type) { + case Event.ALOGI: + Slog.i(tag, message, e); + break; + case Event.ALOGE: + Slog.e(tag, message, e); + break; + case Event.ALOGW: + Slog.w(tag, message, e); + break; + case Event.ALOGV: + default: + Slog.v(tag, message, e); + } + } + + public static class ServiceEvent extends Event { + private final Type mType; + private final String mPackageName; + private final Object mReturnValue; + private final Object[] mParams; + private final Exception mException; + + public enum Type { + ATTACH, + LIST_MODULE, + } + + public static ServiceEvent createForException(Type type, String packageName, + Exception exception, Object... params) { + return new ServiceEvent(exception, type, packageName, null, params); + } + + public static ServiceEvent createForReturn(Type type, String packageName, + Object returnValue, Object... params) { + return new ServiceEvent(null , type, packageName, returnValue, params); + } + + private ServiceEvent(Exception exception, Type type, String packageName, Object returnValue, + Object... params) { + mException = exception; + mType = type; + mPackageName = packageName; + mReturnValue = returnValue; + mParams = params; + } + + @Override + public Event printLog(int type, String tag) { + printSystemLog(type, tag, eventToString(), mException); + return this; + } + + @Override + public String eventToString() { + var sb = new StringBuilder(mType.name()).append(" [client= "); + ObjectPrinter.print(sb, mPackageName); + sb.append("] ("); + printArgs(sb, mParams); + sb.append(") -> "); + if (mException != null) { + sb.append("ERROR: "); + ObjectPrinter.print(sb, mException); + } else { + ObjectPrinter.print(sb, mReturnValue); + } + return sb.toString(); + } + } + + public static class SessionEvent extends Event { + public enum Type { + LOAD_MODEL, + LOAD_PHRASE_MODEL, + START_RECOGNITION, + STOP_RECOGNITION, + FORCE_RECOGNITION, + UNLOAD_MODEL, + GET_MODEL_PARAMETER, + SET_MODEL_PARAMETER, + QUERY_MODEL_PARAMETER, + DETACH, + RECOGNITION, + MODEL_UNLOADED, + MODULE_DIED, + RESOURCES_AVAILABLE, + } + + private final Type mType; + private final Exception mException; + private final Object mReturnValue; + private final Object[] mParams; + + public static SessionEvent createForException(Type type, Exception exception, + Object... params) { + return new SessionEvent(exception, type, null, params); + } + + public static SessionEvent createForReturn(Type type, + Object returnValue, Object... params) { + return new SessionEvent(null , type, returnValue, params); + } + + public static SessionEvent createForVoid(Type type, Object... params) { + return new SessionEvent(null, type, null, params); + } + + + private SessionEvent(Exception exception, Type type, Object returnValue, + Object... params) { + mException = exception; + mType = type; + mReturnValue = returnValue; + mParams = params; + } + + @Override + public Event printLog(int type, String tag) { + printSystemLog(type, tag, eventToString(), mException); + return this; + } + + @Override + public String eventToString() { + var sb = new StringBuilder(mType.name()); + sb.append(" ("); + printArgs(sb, mParams); + sb.append(")"); + if (mException != null) { + sb.append(" -> ERROR: "); + ObjectPrinter.print(sb, mException); + } else if (mReturnValue != null) { + sb.append(" -> "); + ObjectPrinter.print(sb, mReturnValue); + } + return sb.toString(); + } + } + + private static final class ModulePropertySummary { + private int mId; + private String mImplementor; + private int mVersion; + + ModulePropertySummary(int id, String implementor, int version) { + mId = id; + mImplementor = implementor; + mVersion = version; + } + + @Override + public String toString() { + return "{Id: " + mId + ", Implementor: " + mImplementor + + ", Version: " + mVersion + "}"; + } + } }