From 7504d838e8b8e848d44b38007e0ea68f5d113b08 Mon Sep 17 00:00:00 2001 From: Ytai Ben-Tsvi Date: Fri, 21 Feb 2020 15:20:16 -0800 Subject: [PATCH] SoundTriggerMiddlewareService logging decorator Rigorous logging of all SoundTriggerMiddlewareService interactions. This implements logging as a decorator and removes the ad-hoc logging done inside the implementation. This gives us a centralized place to handle SoundTriggerMiddlewareService events. We're planning to do more than just write these to the log eventually. Change-Id: I510ee3073095cca78ec0b9c5ff876610225d002f Merged-In: I510ee3073095cca78ec0b9c5ff876610225d002f Bug: 150325756 --- .../SoundTriggerMiddlewareLogging.java | 376 ++++++++++++++++++ .../SoundTriggerMiddlewareService.java | 9 +- .../SoundTriggerModule.java | 26 -- 3 files changed, 381 insertions(+), 30 deletions(-) create mode 100644 services/core/java/com/android/server/soundtrigger_middleware/SoundTriggerMiddlewareLogging.java diff --git a/services/core/java/com/android/server/soundtrigger_middleware/SoundTriggerMiddlewareLogging.java b/services/core/java/com/android/server/soundtrigger_middleware/SoundTriggerMiddlewareLogging.java new file mode 100644 index 0000000000000..d6546fe2126a0 --- /dev/null +++ b/services/core/java/com/android/server/soundtrigger_middleware/SoundTriggerMiddlewareLogging.java @@ -0,0 +1,376 @@ +/* + * Copyright (C) 2020 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_middleware; + +import android.annotation.NonNull; +import android.media.soundtrigger_middleware.ISoundTriggerCallback; +import android.media.soundtrigger_middleware.ISoundTriggerMiddlewareService; +import android.media.soundtrigger_middleware.ISoundTriggerModule; +import android.media.soundtrigger_middleware.ModelParameterRange; +import android.media.soundtrigger_middleware.PhraseRecognitionEvent; +import android.media.soundtrigger_middleware.PhraseSoundModel; +import android.media.soundtrigger_middleware.RecognitionConfig; +import android.media.soundtrigger_middleware.RecognitionEvent; +import android.media.soundtrigger_middleware.SoundModel; +import android.media.soundtrigger_middleware.SoundTriggerModuleDescriptor; +import android.os.IBinder; +import android.os.RemoteException; +import android.util.Log; + +import java.util.Arrays; +import java.util.Objects; + +/** + * An ISoundTriggerMiddlewareService decorator, which adds logging of all API calls (and + * callbacks). + * + * All API methods should follow this structure: + * 

+ * @Override
+ * public @NonNull ReturnType someMethod(ArgType1 arg1, ArgType2 arg2) throws ExceptionType {
+ *     try {
+ *         ReturnType result = mDelegate.someMethod(arg1, arg2);
+ *         logReturn("someMethod", result, arg1, arg2);
+ *         return result;
+ *     } catch (Exception e) {
+ *         logException("someMethod", e, arg1, arg2);
+ *         throw e;
+ *     }
+ * }
+ *
+ * The actual handling of these events is then done inside of {@link #logReturnWithObject(Object, + * String, Object, Object[])}, {@link #logVoidReturnWithObject(Object, String, Object[])} and {@link + * #logExceptionWithObject(Object, String, Exception, Object[])}. + */ +public class SoundTriggerMiddlewareLogging implements ISoundTriggerMiddlewareService { + private static final String TAG = "SoundTriggerMiddlewareLogging"; + + private final @NonNull ISoundTriggerMiddlewareService mDelegate; + + public SoundTriggerMiddlewareLogging( + @NonNull ISoundTriggerMiddlewareService delegate) { + mDelegate = delegate; + } + + @Override + public @NonNull SoundTriggerModuleDescriptor[] listModules() throws RemoteException { + try { + SoundTriggerModuleDescriptor[] result = mDelegate.listModules(); + logReturn("listModules", result); + return result; + } catch (Exception e) { + logException("listModules", e); + throw e; + } + } + + @Override + public @NonNull ISoundTriggerModule attach(int handle, ISoundTriggerCallback callback) + throws RemoteException { + try { + ISoundTriggerModule result = mDelegate.attach(handle, new CallbackLogging(callback)); + logReturn("attach", result, handle, callback); + return new ModuleLogging(result); + } catch (Exception e) { + logException("attach", e, handle, callback); + throw e; + } + } + + @Override + public void setExternalCaptureState(boolean active) throws RemoteException { + try { + mDelegate.setExternalCaptureState(active); + logVoidReturn("setExternalCaptureState", active); + } catch (Exception e) { + logException("setExternalCaptureState", e, active); + throw e; + } + } + + @Override public IBinder asBinder() { + throw new UnsupportedOperationException( + "This implementation is not inteded to be used directly with Binder."); + } + + // Override toString() in order to have the delegate's ID in it. + @Override + public String toString() { + return mDelegate.toString(); + } + + private void logException(String methodName, Exception ex, Object... args) { + logExceptionWithObject(this, methodName, ex, args); + } + + private void logReturn(String methodName, Object retVal, Object... args) { + logReturnWithObject(this, methodName, retVal, args); + } + + private void logVoidReturn(String methodName, Object... args) { + logVoidReturnWithObject(this, methodName, args); + } + + private class CallbackLogging implements ISoundTriggerCallback { + private final ISoundTriggerCallback mDelegate; + + private CallbackLogging(ISoundTriggerCallback delegate) { + mDelegate = delegate; + } + + @Override + public void onRecognition(int modelHandle, RecognitionEvent event) throws RemoteException { + try { + mDelegate.onRecognition(modelHandle, event); + logVoidReturn("onRecognition", modelHandle, event); + } catch (Exception e) { + logException("onRecognition", e, modelHandle, event); + throw e; + } + } + + @Override + public void onPhraseRecognition(int modelHandle, PhraseRecognitionEvent event) + throws RemoteException { + try { + mDelegate.onPhraseRecognition(modelHandle, event); + logVoidReturn("onPhraseRecognition", modelHandle, event); + } catch (Exception e) { + logException("onPhraseRecognition", e, modelHandle, event); + throw e; + } + } + + @Override + public void onRecognitionAvailabilityChange(boolean available) throws RemoteException { + try { + mDelegate.onRecognitionAvailabilityChange(available); + logVoidReturn("onRecognitionAvailabilityChange", available); + } catch (Exception e) { + logException("onRecognitionAvailabilityChange", e, available); + throw e; + } + } + + @Override + public void onModuleDied() throws RemoteException { + try { + mDelegate.onModuleDied(); + logVoidReturn("onModuleDied"); + } catch (Exception e) { + logException("onModuleDied", e); + throw e; + } + } + + private void logException(String methodName, Exception ex, Object... args) { + logExceptionWithObject(this, methodName, ex, args); + } + + private void logVoidReturn(String methodName, Object... args) { + logVoidReturnWithObject(this, methodName, args); + } + + @Override + public IBinder asBinder() { + return mDelegate.asBinder(); + } + + // Override toString() in order to have the delegate's ID in it. + @Override + public String toString() { + return mDelegate.toString(); + } + } + + private class ModuleLogging implements ISoundTriggerModule { + private final ISoundTriggerModule mDelegate; + + private ModuleLogging(ISoundTriggerModule delegate) { + mDelegate = delegate; + } + + @Override + public int loadModel(SoundModel model) throws RemoteException { + try { + int result = mDelegate.loadModel(model); + logReturn("loadModel", result, model); + return result; + } catch (Exception e) { + logException("loadModel", e, model); + throw e; + } + } + + @Override + public int loadPhraseModel(PhraseSoundModel model) throws RemoteException { + try { + int result = mDelegate.loadPhraseModel(model); + logReturn("loadPhraseModel", result, model); + return result; + } catch (Exception e) { + logException("loadPhraseModel", e, model); + throw e; + } + } + + @Override + public void unloadModel(int modelHandle) throws RemoteException { + try { + mDelegate.unloadModel(modelHandle); + logVoidReturn("unloadModel", modelHandle); + } catch (Exception e) { + logException("unloadModel", e, modelHandle); + throw e; + } + } + + @Override + public void startRecognition(int modelHandle, RecognitionConfig config) + throws RemoteException { + try { + mDelegate.startRecognition(modelHandle, config); + logVoidReturn("startRecognition", modelHandle, config); + } catch (Exception e) { + logException("startRecognition", e, modelHandle, config); + throw e; + } + } + + @Override + public void stopRecognition(int modelHandle) throws RemoteException { + try { + mDelegate.stopRecognition(modelHandle); + logVoidReturn("stopRecognition", modelHandle); + } catch (Exception e) { + logException("stopRecognition", e, modelHandle); + throw e; + } + } + + @Override + public void forceRecognitionEvent(int modelHandle) throws RemoteException { + try { + mDelegate.forceRecognitionEvent(modelHandle); + logVoidReturn("forceRecognitionEvent", modelHandle); + } catch (Exception e) { + logException("forceRecognitionEvent", e, modelHandle); + throw e; + } + } + + @Override + public void setModelParameter(int modelHandle, int modelParam, int value) + throws RemoteException { + try { + mDelegate.setModelParameter(modelHandle, modelParam, value); + logVoidReturn("setModelParameter", modelHandle, modelParam, value); + } catch (Exception e) { + logException("setModelParameter", e, modelHandle, modelParam, value); + throw e; + } + } + + @Override + public int getModelParameter(int modelHandle, int modelParam) throws RemoteException { + try { + int result = mDelegate.getModelParameter(modelHandle, modelParam); + logReturn("getModelParameter", result, modelHandle, modelParam); + return result; + } catch (Exception e) { + logException("getModelParameter", e, modelHandle, modelParam); + throw e; + } + } + + @Override + public ModelParameterRange queryModelParameterSupport(int modelHandle, int modelParam) + throws RemoteException { + try { + ModelParameterRange result = mDelegate.queryModelParameterSupport(modelHandle, + modelParam); + logReturn("queryModelParameterSupport", result, modelHandle, modelParam); + return result; + } catch (Exception e) { + logException("queryModelParameterSupport", e, modelHandle, modelParam); + throw e; + } + } + + @Override + public void detach() throws RemoteException { + try { + mDelegate.detach(); + logVoidReturn("detach"); + } catch (Exception e) { + logException("detach", e); + throw e; + } + } + + @Override + public IBinder asBinder() { + return mDelegate.asBinder(); + } + + // Override toString() in order to have the delegate's ID in it. + @Override + public String toString() { + return mDelegate.toString(); + } + + private void logException(String methodName, Exception ex, Object... args) { + logExceptionWithObject(this, methodName, ex, args); + } + + private void logReturn(String methodName, Object retVal, Object... args) { + logReturnWithObject(this, methodName, retVal, args); + } + + private void logVoidReturn(String methodName, Object... args) { + logVoidReturnWithObject(this, methodName, args); + } + } + + static private String formatArgs(Object[] args) { + String result = Arrays.toString(args); + // Strip the square brackets. + return result.substring(1, result.length() - 1); + } + + private void logReturnWithObject(Object object, String methodName, Object retVal, + Object[] args) { + // TODO(ytai): Save last N entries and emit on dump(). + Log.i(TAG, String.format("%s[this=%s](%s) -> %s", methodName, Objects.toString(object), + formatArgs(args), + Objects.toString(retVal))); + } + + private void logVoidReturnWithObject(Object object, String methodName, Object[] args) { + // TODO(ytai): Save last N entries and emit on dump(). + Log.i(TAG, String.format("%s[this=%s](%s)", methodName, Objects.toString(object), + formatArgs(args))); + } + + private void logExceptionWithObject(Object object, String methodName, Exception ex, + Object[] args) { + // TODO(ytai): Save last N entries and emit on dump(). + Log.e(TAG, String.format("%s[this=%s](%s) threw", methodName, Objects.toString(object), + formatArgs(args)), + ex); + } +} diff --git a/services/core/java/com/android/server/soundtrigger_middleware/SoundTriggerMiddlewareService.java b/services/core/java/com/android/server/soundtrigger_middleware/SoundTriggerMiddlewareService.java index fd7b638fde1be..ca3acbfa0f78c 100644 --- a/services/core/java/com/android/server/soundtrigger_middleware/SoundTriggerMiddlewareService.java +++ b/services/core/java/com/android/server/soundtrigger_middleware/SoundTriggerMiddlewareService.java @@ -172,10 +172,11 @@ public class SoundTriggerMiddlewareService extends ISoundTriggerMiddlewareServic publishBinderService(Context.SOUND_TRIGGER_MIDDLEWARE_SERVICE, new SoundTriggerMiddlewareService( - new SoundTriggerMiddlewareValidation( - new SoundTriggerMiddlewareImpl(factories, - new AudioSessionProviderImpl()), - getContext()))); + new SoundTriggerMiddlewareLogging( + new SoundTriggerMiddlewareValidation( + new SoundTriggerMiddlewareImpl(factories, + new AudioSessionProviderImpl()), + getContext())))); } } } diff --git a/services/core/java/com/android/server/soundtrigger_middleware/SoundTriggerModule.java b/services/core/java/com/android/server/soundtrigger_middleware/SoundTriggerModule.java index aa1558ebfc702..d6390184e3bd8 100644 --- a/services/core/java/com/android/server/soundtrigger_middleware/SoundTriggerModule.java +++ b/services/core/java/com/android/server/soundtrigger_middleware/SoundTriggerModule.java @@ -123,7 +123,6 @@ class SoundTriggerModule implements IHwBinder.DeathRecipient { */ synchronized @NonNull ISoundTriggerModule attach(@NonNull ISoundTriggerCallback callback) { - Log.d(TAG, "attach()"); Session session = new Session(callback); mActiveSessions.add(session); return session; @@ -149,8 +148,6 @@ class SoundTriggerModule implements IHwBinder.DeathRecipient { * @param active true iff external capture is active. */ synchronized void setExternalCaptureState(boolean active) { - Log.d(TAG, String.format("setExternalCaptureState(active=%b)", active)); - if (mProperties.concurrentCapture) { // If we support concurrent capture, we don't care about any of this. return; @@ -235,7 +232,6 @@ class SoundTriggerModule implements IHwBinder.DeathRecipient { @Override public void detach() { - Log.d(TAG, "detach()"); synchronized (SoundTriggerModule.this) { if (mCallback == null) { return; @@ -247,8 +243,6 @@ class SoundTriggerModule implements IHwBinder.DeathRecipient { @Override public int loadModel(@NonNull SoundModel model) { - Log.d(TAG, String.format("loadModel(model=%s)", model)); - // We must do this outside the lock, to avoid possible deadlocks with the remote process // that provides the audio sessions, which may also be calling into us. SoundTriggerMiddlewareImpl.AudioSessionProvider.AudioSession audioSession = @@ -276,8 +270,6 @@ class SoundTriggerModule implements IHwBinder.DeathRecipient { @Override public int loadPhraseModel(@NonNull PhraseSoundModel model) { - Log.d(TAG, String.format("loadPhraseModel(model=%s)", model)); - // We must do this outside the lock, to avoid possible deadlocks with the remote process // that provides the audio sessions, which may also be calling into us. SoundTriggerMiddlewareImpl.AudioSessionProvider.AudioSession audioSession = @@ -306,10 +298,7 @@ class SoundTriggerModule implements IHwBinder.DeathRecipient { @Override public void unloadModel(int modelHandle) { - Log.d(TAG, String.format("unloadModel(handle=%d)", modelHandle)); - int sessionId; - synchronized (SoundTriggerModule.this) { checkValid(); sessionId = mLoadedModels.get(modelHandle).unload(); @@ -323,8 +312,6 @@ class SoundTriggerModule implements IHwBinder.DeathRecipient { @Override public void startRecognition(int modelHandle, @NonNull RecognitionConfig config) { - Log.d(TAG, - String.format("startRecognition(handle=%d, config=%s)", modelHandle, config)); synchronized (SoundTriggerModule.this) { checkValid(); mLoadedModels.get(modelHandle).startRecognition(config); @@ -333,7 +320,6 @@ class SoundTriggerModule implements IHwBinder.DeathRecipient { @Override public void stopRecognition(int modelHandle) { - Log.d(TAG, String.format("stopRecognition(handle=%d)", modelHandle)); synchronized (SoundTriggerModule.this) { mLoadedModels.get(modelHandle).stopRecognition(); } @@ -341,7 +327,6 @@ class SoundTriggerModule implements IHwBinder.DeathRecipient { @Override public void forceRecognitionEvent(int modelHandle) { - Log.d(TAG, String.format("forceRecognitionEvent(handle=%d)", modelHandle)); synchronized (SoundTriggerModule.this) { checkValid(); mLoadedModels.get(modelHandle).forceRecognitionEvent(); @@ -350,9 +335,6 @@ class SoundTriggerModule implements IHwBinder.DeathRecipient { @Override public void setModelParameter(int modelHandle, int modelParam, int value) { - Log.d(TAG, - String.format("setModelParameter(handle=%d, param=%d, value=%d)", modelHandle, - modelParam, value)); synchronized (SoundTriggerModule.this) { checkValid(); mLoadedModels.get(modelHandle).setParameter(modelParam, value); @@ -361,8 +343,6 @@ class SoundTriggerModule implements IHwBinder.DeathRecipient { @Override public int getModelParameter(int modelHandle, int modelParam) { - Log.d(TAG, String.format("getModelParameter(handle=%d, param=%d)", modelHandle, - modelParam)); synchronized (SoundTriggerModule.this) { checkValid(); return mLoadedModels.get(modelHandle).getParameter(modelParam); @@ -372,8 +352,6 @@ class SoundTriggerModule implements IHwBinder.DeathRecipient { @Override @Nullable public ModelParameterRange queryModelParameterSupport(int modelHandle, int modelParam) { - Log.d(TAG, String.format("queryModelParameterSupport(handle=%d, param=%d)", modelHandle, - modelParam)); synchronized (SoundTriggerModule.this) { checkValid(); return mLoadedModels.get(modelHandle).queryModelParameterSupport(modelParam); @@ -584,8 +562,6 @@ class SoundTriggerModule implements IHwBinder.DeathRecipient { public void recognitionCallback( @NonNull ISoundTriggerHwCallback.RecognitionEvent recognitionEvent, int cookie) { - Log.d(TAG, String.format("recognitionCallback_2_1(event=%s, cookie=%d)", - recognitionEvent, cookie)); synchronized (SoundTriggerModule.this) { android.media.soundtrigger_middleware.RecognitionEvent aidlEvent = ConversionUtil.hidl2aidlRecognitionEvent(recognitionEvent); @@ -608,8 +584,6 @@ class SoundTriggerModule implements IHwBinder.DeathRecipient { public void phraseRecognitionCallback( @NonNull ISoundTriggerHwCallback.PhraseRecognitionEvent phraseRecognitionEvent, int cookie) { - Log.d(TAG, String.format("phraseRecognitionCallback_2_1(event=%s, cookie=%d)", - phraseRecognitionEvent, cookie)); synchronized (SoundTriggerModule.this) { android.media.soundtrigger_middleware.PhraseRecognitionEvent aidlEvent = ConversionUtil.hidl2aidlPhraseRecognitionEvent(phraseRecognitionEvent);