Donate to e Foundation | Murena handsets with /e/OS | Own a part of Murena! Learn more

Commit 7504d838 authored by Ytai Ben-Tsvi's avatar Ytai Ben-Tsvi
Browse files

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
parent e617bc85
Loading
Loading
Loading
Loading
+376 −0
Original line number Diff line number Diff line
/*
 * 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:
 * <pre><code>
 * @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;
 *     }
 * }
 * </code></pre>
 * 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);
    }
}
+5 −4
Original line number Diff line number Diff line
@@ -172,10 +172,11 @@ public class SoundTriggerMiddlewareService extends ISoundTriggerMiddlewareServic

            publishBinderService(Context.SOUND_TRIGGER_MIDDLEWARE_SERVICE,
                    new SoundTriggerMiddlewareService(
                            new SoundTriggerMiddlewareLogging(
                                    new SoundTriggerMiddlewareValidation(
                                            new SoundTriggerMiddlewareImpl(factories,
                                                    new AudioSessionProviderImpl()),
                                    getContext())));
                                            getContext()))));
        }
    }
}
+0 −26
Original line number Diff line number Diff line
@@ -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);