diff options
| author | 2019-04-16 15:35:55 +0800 | |
|---|---|---|
| committer | 2019-04-29 12:14:41 +0800 | |
| commit | 1363f581dccb7dd74acf695ce19e3fd2ca15ee60 (patch) | |
| tree | 0724862105a072b700ef2505c38b9909c494f8fc | |
| parent | 8bfe7fd32c3863b894e5cafc18b29d6246803252 (diff) | |
SoundTrigger Event logging
check bugreport DUMPSYS - voiceinteraction
BUG: 128965282
Test: manual
Change-Id: If2032e2cc5c0e071f9205e516987462625248b1c
Signed-off-by: Jason Hsu <jasonchhsu@google.com>
2 files changed, 334 insertions, 0 deletions
diff --git a/services/voiceinteraction/java/com/android/server/soundtrigger/SoundTriggerLogger.java b/services/voiceinteraction/java/com/android/server/soundtrigger/SoundTriggerLogger.java new file mode 100644 index 000000000000..73b4ce767d0d --- /dev/null +++ b/services/voiceinteraction/java/com/android/server/soundtrigger/SoundTriggerLogger.java @@ -0,0 +1,136 @@ +/* + * Copyright (C) 2019 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.Log; + +import java.io.PrintWriter; +import java.text.SimpleDateFormat; +import java.util.Date; +import java.util.LinkedList; + +/** +* Constructor SoundTriggerLogger class +*/ +public class SoundTriggerLogger { + + // ring buffer of events to log. + private final LinkedList<Event> mEvents; + + private final String mTitle; + + // the maximum number of events to keep in log + private final int mMemSize; + + /** + * Constructor for Event class. + */ + public abstract static class Event { + // formatter for timestamps + private static final SimpleDateFormat sFormat = new SimpleDateFormat("MM-dd HH:mm:ss:SSS"); + + private final long mTimestamp; + + Event() { + mTimestamp = System.currentTimeMillis(); + } + + /** + * Convert event to String + * @return StringBuilder + */ + public String toString() { + return (new StringBuilder(sFormat.format(new Date(mTimestamp)))) + .append(" ").append(eventToString()).toString(); + } + + /** + * Causes the string message for the event to appear in the logcat. + * Here is an example of how to create a new event (a StringEvent), adding it to the logger + * (an instance of SoundTriggerLogger) while also making it show in the logcat: + * <pre> + * myLogger.log( + * (new StringEvent("something for logcat and logger")).printLog(MyClass.TAG) ); + * </pre> + * @param tag the tag for the android.util.Log.v + * @return the same instance of the event + */ + public Event printLog(String tag) { + Log.i(tag, eventToString()); + return this; + } + + /** + * Convert event to String. + * This method is only called when the logger history is about to the dumped, + * so this method is where expensive String conversions should be made, not when the Event + * subclass is created. + * Timestamp information will be automatically added, do not include it. + * @return a string representation of the event that occurred. + */ + public abstract String eventToString(); + } + + /** + * Constructor StringEvent class + */ + public static class StringEvent extends Event { + private final String mMsg; + + public StringEvent(String msg) { + mMsg = msg; + } + + @Override + public String eventToString() { + return mMsg; + } + } + + /** + * Constructor for logger. + * @param size the maximum number of events to keep in log + * @param title the string displayed before the recorded log + */ + public SoundTriggerLogger(int size, String title) { + mEvents = new LinkedList<Event>(); + mMemSize = size; + mTitle = title; + } + + /** + * Constructor for logger. + * @param evt the maximum number of events to keep in log + */ + public synchronized void log(Event evt) { + if (mEvents.size() >= mMemSize) { + mEvents.removeFirst(); + } + mEvents.add(evt); + } + + /** + * Constructor for logger. + * @param pw the maximum number of events to keep in log + */ + public synchronized void dump(PrintWriter pw) { + pw.println("ST Event log: " + mTitle); + for (Event evt : mEvents) { + pw.println(evt.toString()); + } + } +} diff --git a/services/voiceinteraction/java/com/android/server/soundtrigger/SoundTriggerService.java b/services/voiceinteraction/java/com/android/server/soundtrigger/SoundTriggerService.java index 697469a3c680..9c4c0998b21a 100644 --- a/services/voiceinteraction/java/com/android/server/soundtrigger/SoundTriggerService.java +++ b/services/voiceinteraction/java/com/android/server/soundtrigger/SoundTriggerService.java @@ -180,9 +180,16 @@ public class SoundTriggerService extends SystemService { Slog.i(TAG, "startRecognition(): Uuid : " + parcelUuid); } + sEventLogger.log(new SoundTriggerLogger.StringEvent("startRecognition(): Uuid : " + + parcelUuid)); + GenericSoundModel model = getSoundModel(parcelUuid); if (model == null) { Slog.e(TAG, "Null model in database for id: " + parcelUuid); + + sEventLogger.log(new SoundTriggerLogger.StringEvent( + "startRecognition(): Null model in database for id: " + parcelUuid)); + return STATUS_ERROR; } @@ -196,6 +203,10 @@ public class SoundTriggerService extends SystemService { if (DEBUG) { Slog.i(TAG, "stopRecognition(): Uuid : " + parcelUuid); } + + sEventLogger.log(new SoundTriggerLogger.StringEvent("stopRecognition(): Uuid : " + + parcelUuid)); + if (!isInitialized()) return STATUS_ERROR; return mSoundTriggerHelper.stopGenericRecognition(parcelUuid.getUuid(), callback); } @@ -206,6 +217,10 @@ public class SoundTriggerService extends SystemService { if (DEBUG) { Slog.i(TAG, "getSoundModel(): id = " + soundModelId); } + + sEventLogger.log(new SoundTriggerLogger.StringEvent("getSoundModel(): id = " + + soundModelId)); + SoundTrigger.GenericSoundModel model = mDbHelper.getGenericSoundModel( soundModelId.getUuid()); return model; @@ -217,6 +232,10 @@ public class SoundTriggerService extends SystemService { if (DEBUG) { Slog.i(TAG, "updateSoundModel(): model = " + soundModel); } + + sEventLogger.log(new SoundTriggerLogger.StringEvent("updateSoundModel(): model = " + + soundModel)); + mDbHelper.updateGenericSoundModel(soundModel); } @@ -226,6 +245,10 @@ public class SoundTriggerService extends SystemService { if (DEBUG) { Slog.i(TAG, "deleteSoundModel(): id = " + soundModelId); } + + sEventLogger.log(new SoundTriggerLogger.StringEvent("deleteSoundModel(): id = " + + soundModelId)); + // Unload the model if it is loaded. mSoundTriggerHelper.unloadGenericSoundModel(soundModelId.getUuid()); mDbHelper.deleteGenericSoundModel(soundModelId.getUuid()); @@ -237,11 +260,19 @@ public class SoundTriggerService extends SystemService { if (!isInitialized()) return STATUS_ERROR; if (soundModel == null || soundModel.uuid == null) { Slog.e(TAG, "Invalid sound model"); + + sEventLogger.log(new SoundTriggerLogger.StringEvent( + "loadGenericSoundModel(): Invalid sound model")); + return STATUS_ERROR; } if (DEBUG) { Slog.i(TAG, "loadGenericSoundModel(): id = " + soundModel.uuid); } + + sEventLogger.log(new SoundTriggerLogger.StringEvent("loadGenericSoundModel(): id = " + + soundModel.uuid)); + synchronized (mLock) { SoundModel oldModel = mLoadedModels.get(soundModel.uuid); // If the model we're loading is actually different than what we had loaded, we @@ -264,15 +295,28 @@ public class SoundTriggerService extends SystemService { if (!isInitialized()) return STATUS_ERROR; if (soundModel == null || soundModel.uuid == null) { Slog.e(TAG, "Invalid sound model"); + + sEventLogger.log(new SoundTriggerLogger.StringEvent( + "loadKeyphraseSoundModel(): Invalid sound model")); + return STATUS_ERROR; } if (soundModel.keyphrases == null || soundModel.keyphrases.length != 1) { Slog.e(TAG, "Only one keyphrase per model is currently supported."); + + sEventLogger.log(new SoundTriggerLogger.StringEvent( + "loadKeyphraseSoundModel(): Only one keyphrase per model" + + " is currently supported.")); + return STATUS_ERROR; } if (DEBUG) { Slog.i(TAG, "loadKeyphraseSoundModel(): id = " + soundModel.uuid); } + + sEventLogger.log(new SoundTriggerLogger.StringEvent("loadKeyphraseSoundModel(): id = " + + soundModel.uuid)); + synchronized (mLock) { SoundModel oldModel = mLoadedModels.get(soundModel.uuid); // If the model we're loading is actually different than what we had loaded, we @@ -303,6 +347,9 @@ public class SoundTriggerService extends SystemService { Slog.i(TAG, "startRecognition(): id = " + soundModelId); } + sEventLogger.log(new SoundTriggerLogger.StringEvent( + "startRecognitionForService(): id = " + soundModelId)); + IRecognitionStatusCallback callback = new RemoteSoundTriggerDetectionService(soundModelId.getUuid(), params, detectionService, Binder.getCallingUserHandle(), config); @@ -311,6 +358,10 @@ public class SoundTriggerService extends SystemService { SoundModel soundModel = mLoadedModels.get(soundModelId.getUuid()); if (soundModel == null) { Slog.e(TAG, soundModelId + " is not loaded"); + + sEventLogger.log(new SoundTriggerLogger.StringEvent( + "startRecognitionForService():" + soundModelId + " is not loaded")); + return STATUS_ERROR; } IRecognitionStatusCallback existingCallback = null; @@ -319,6 +370,11 @@ public class SoundTriggerService extends SystemService { } if (existingCallback != null) { Slog.e(TAG, soundModelId + " is already running"); + + sEventLogger.log(new SoundTriggerLogger.StringEvent( + "startRecognitionForService():" + + soundModelId + " is already running")); + return STATUS_ERROR; } int ret; @@ -329,11 +385,19 @@ public class SoundTriggerService extends SystemService { break; default: Slog.e(TAG, "Unknown model type"); + + sEventLogger.log(new SoundTriggerLogger.StringEvent( + "startRecognitionForService(): Unknown model type")); + return STATUS_ERROR; } if (ret != STATUS_OK) { Slog.e(TAG, "Failed to start model: " + ret); + + sEventLogger.log(new SoundTriggerLogger.StringEvent( + "startRecognitionForService(): Failed to start model:")); + return ret; } synchronized (mCallbacksLock) { @@ -351,10 +415,18 @@ public class SoundTriggerService extends SystemService { Slog.i(TAG, "stopRecognition(): id = " + soundModelId); } + sEventLogger.log(new SoundTriggerLogger.StringEvent( + "stopRecognitionForService(): id = " + soundModelId)); + synchronized (mLock) { SoundModel soundModel = mLoadedModels.get(soundModelId.getUuid()); if (soundModel == null) { Slog.e(TAG, soundModelId + " is not loaded"); + + sEventLogger.log(new SoundTriggerLogger.StringEvent( + "stopRecognitionForService(): " + soundModelId + + " is not loaded")); + return STATUS_ERROR; } IRecognitionStatusCallback callback = null; @@ -363,6 +435,11 @@ public class SoundTriggerService extends SystemService { } if (callback == null) { Slog.e(TAG, soundModelId + " is not running"); + + sEventLogger.log(new SoundTriggerLogger.StringEvent( + "stopRecognitionForService(): " + soundModelId + + " is not running")); + return STATUS_ERROR; } int ret; @@ -372,11 +449,19 @@ public class SoundTriggerService extends SystemService { break; default: Slog.e(TAG, "Unknown model type"); + + sEventLogger.log(new SoundTriggerLogger.StringEvent( + "stopRecognitionForService(): Unknown model type")); + return STATUS_ERROR; } if (ret != STATUS_OK) { Slog.e(TAG, "Failed to stop model: " + ret); + + sEventLogger.log(new SoundTriggerLogger.StringEvent( + "stopRecognitionForService(): Failed to stop model: " + ret)); + return ret; } synchronized (mCallbacksLock) { @@ -394,10 +479,17 @@ public class SoundTriggerService extends SystemService { Slog.i(TAG, "unloadSoundModel(): id = " + soundModelId); } + sEventLogger.log(new SoundTriggerLogger.StringEvent("unloadSoundModel(): id = " + + soundModelId)); + synchronized (mLock) { SoundModel soundModel = mLoadedModels.get(soundModelId.getUuid()); if (soundModel == null) { Slog.e(TAG, soundModelId + " is not loaded"); + + sEventLogger.log(new SoundTriggerLogger.StringEvent( + "unloadSoundModel(): " + soundModelId + " is not loaded")); + return STATUS_ERROR; } int ret; @@ -411,10 +503,18 @@ public class SoundTriggerService extends SystemService { break; default: Slog.e(TAG, "Unknown model type"); + + sEventLogger.log(new SoundTriggerLogger.StringEvent( + "unloadSoundModel(): Unknown model type")); + return STATUS_ERROR; } if (ret != STATUS_OK) { Slog.e(TAG, "Failed to unload model"); + + sEventLogger.log(new SoundTriggerLogger.StringEvent( + "unloadSoundModel(): Failed to unload model")); + return ret; } mLoadedModels.remove(soundModelId.getUuid()); @@ -444,10 +544,17 @@ public class SoundTriggerService extends SystemService { Slog.i(TAG, "getModelState(): id = " + soundModelId); } + sEventLogger.log(new SoundTriggerLogger.StringEvent("getModelState(): id = " + + soundModelId)); + synchronized (mLock) { SoundModel soundModel = mLoadedModels.get(soundModelId.getUuid()); if (soundModel == null) { Slog.e(TAG, soundModelId + " is not loaded"); + + sEventLogger.log(new SoundTriggerLogger.StringEvent("getModelState(): " + + soundModelId + " is not loaded")); + return ret; } switch (soundModel.type) { @@ -459,6 +566,10 @@ public class SoundTriggerService extends SystemService { break; default: Slog.e(TAG, "Unknown model type"); + + sEventLogger.log(new SoundTriggerLogger.StringEvent( + "getModelState(): Unknown model type")); + break; } @@ -708,6 +819,10 @@ public class SoundTriggerService extends SystemService { mService.removeClient(mPuuid); } catch (Exception e) { Slog.e(TAG, mPuuid + ": Cannot remove client", e); + + sEventLogger.log(new SoundTriggerLogger.StringEvent(mPuuid + + ": Cannot remove client")); + } mService = null; @@ -730,6 +845,8 @@ public class SoundTriggerService extends SystemService { private void destroy() { if (DEBUG) Slog.v(TAG, mPuuid + ": destroy"); + sEventLogger.log(new SoundTriggerLogger.StringEvent(mPuuid + ": destroy")); + synchronized (mRemoteServiceLock) { disconnectLocked(); @@ -761,6 +878,10 @@ public class SoundTriggerService extends SystemService { } catch (Exception e) { Slog.e(TAG, mPuuid + ": Could not stop operation " + mRunningOpIds.valueAt(i), e); + + sEventLogger.log(new SoundTriggerLogger.StringEvent(mPuuid + + ": Could not stop operation " + mRunningOpIds.valueAt(i))); + } } @@ -786,6 +907,10 @@ public class SoundTriggerService extends SystemService { if (ri == null) { Slog.w(TAG, mPuuid + ": " + mServiceName + " not found"); + + sEventLogger.log(new SoundTriggerLogger.StringEvent(mPuuid + + ": " + mServiceName + " not found")); + return; } @@ -793,6 +918,11 @@ public class SoundTriggerService extends SystemService { .equals(ri.serviceInfo.permission)) { Slog.w(TAG, mPuuid + ": " + mServiceName + " does not require " + BIND_SOUND_TRIGGER_DETECTION_SERVICE); + + sEventLogger.log(new SoundTriggerLogger.StringEvent(mPuuid + + ": " + mServiceName + " does not require " + + BIND_SOUND_TRIGGER_DETECTION_SERVICE)); + return; } @@ -803,6 +933,10 @@ public class SoundTriggerService extends SystemService { mRemoteServiceWakeLock.acquire(); } else { Slog.w(TAG, mPuuid + ": Could not bind to " + mServiceName); + + sEventLogger.log(new SoundTriggerLogger.StringEvent(mPuuid + + ": Could not bind to " + mServiceName)); + } } finally { Binder.restoreCallingIdentity(token); @@ -821,6 +955,9 @@ public class SoundTriggerService extends SystemService { Slog.w(TAG, mPuuid + ": Dropped operation as already destroyed or marked for " + "destruction"); + sEventLogger.log(new SoundTriggerLogger.StringEvent(mPuuid + + ":Dropped operation as already destroyed or marked for destruction")); + op.drop(); return; } @@ -847,11 +984,20 @@ public class SoundTriggerService extends SystemService { if (DEBUG || opsAllowed + 10 > opsAdded) { Slog.w(TAG, mPuuid + ": Dropped operation as too many operations " + "were run in last 24 hours"); + + sEventLogger.log(new SoundTriggerLogger.StringEvent(mPuuid + + ": Dropped operation as too many operations " + + "were run in last 24 hours")); + } op.drop(); } catch (Exception e) { Slog.e(TAG, mPuuid + ": Could not drop operation", e); + + sEventLogger.log(new SoundTriggerLogger.StringEvent(mPuuid + + ": Could not drop operation")); + } } else { mNumOps.addOp(currentTime); @@ -866,10 +1012,17 @@ public class SoundTriggerService extends SystemService { try { if (DEBUG) Slog.v(TAG, mPuuid + ": runOp " + opId); + sEventLogger.log(new SoundTriggerLogger.StringEvent(mPuuid + + ": runOp " + opId)); + op.run(opId, mService); mRunningOpIds.add(opId); } catch (Exception e) { Slog.e(TAG, mPuuid + ": Could not run operation " + opId, e); + + sEventLogger.log(new SoundTriggerLogger.StringEvent(mPuuid + + ": Could not run operation " + opId)); + } } @@ -897,6 +1050,10 @@ public class SoundTriggerService extends SystemService { public void onKeyphraseDetected(SoundTrigger.KeyphraseRecognitionEvent event) { Slog.w(TAG, mPuuid + "->" + mServiceName + ": IGNORED onKeyphraseDetected(" + event + ")"); + + sEventLogger.log(new SoundTriggerLogger.StringEvent(mPuuid + "->" + mServiceName + + ": IGNORED onKeyphraseDetected(" + event + ")")); + } /** @@ -928,6 +1085,8 @@ public class SoundTriggerService extends SystemService { : AudioFormat.CHANNEL_IN_MONO, captureFormat.getEncoding()); + sEventLogger.log(new SoundTriggerLogger.StringEvent("createAudioRecordForEvent")); + return new AudioRecord(attributes, captureFormat, bufferSize, event.getCaptureSession()); } @@ -936,6 +1095,9 @@ public class SoundTriggerService extends SystemService { public void onGenericSoundTriggerDetected(SoundTrigger.GenericRecognitionEvent event) { if (DEBUG) Slog.v(TAG, mPuuid + ": Generic sound trigger event: " + event); + sEventLogger.log(new SoundTriggerLogger.StringEvent(mPuuid + + ": Generic sound trigger event: " + event)); + runOrAddOperation(new Operation( // always execute: () -> { @@ -966,6 +1128,9 @@ public class SoundTriggerService extends SystemService { public void onError(int status) { if (DEBUG) Slog.v(TAG, mPuuid + ": onError: " + status); + sEventLogger.log(new SoundTriggerLogger.StringEvent(mPuuid + + ": onError: " + status)); + runOrAddOperation( new Operation( // always execute: @@ -985,17 +1150,28 @@ public class SoundTriggerService extends SystemService { @Override public void onRecognitionPaused() { Slog.i(TAG, mPuuid + "->" + mServiceName + ": IGNORED onRecognitionPaused"); + + sEventLogger.log(new SoundTriggerLogger.StringEvent(mPuuid + + "->" + mServiceName + ": IGNORED onRecognitionPaused")); + } @Override public void onRecognitionResumed() { Slog.i(TAG, mPuuid + "->" + mServiceName + ": IGNORED onRecognitionResumed"); + + sEventLogger.log(new SoundTriggerLogger.StringEvent(mPuuid + + "->" + mServiceName + ": IGNORED onRecognitionResumed")); + } @Override public void onServiceConnected(ComponentName name, IBinder service) { if (DEBUG) Slog.v(TAG, mPuuid + ": onServiceConnected(" + service + ")"); + sEventLogger.log(new SoundTriggerLogger.StringEvent(mPuuid + + ": onServiceConnected(" + service + ")")); + synchronized (mRemoteServiceLock) { mService = ISoundTriggerDetectionService.Stub.asInterface(service); @@ -1016,6 +1192,9 @@ public class SoundTriggerService extends SystemService { public void onServiceDisconnected(ComponentName name) { if (DEBUG) Slog.v(TAG, mPuuid + ": onServiceDisconnected"); + sEventLogger.log(new SoundTriggerLogger.StringEvent(mPuuid + + ": onServiceDisconnected")); + synchronized (mRemoteServiceLock) { mService = null; } @@ -1025,6 +1204,9 @@ public class SoundTriggerService extends SystemService { public void onBindingDied(ComponentName name) { if (DEBUG) Slog.v(TAG, mPuuid + ": onBindingDied"); + sEventLogger.log(new SoundTriggerLogger.StringEvent(mPuuid + + ": onBindingDied")); + synchronized (mRemoteServiceLock) { destroy(); } @@ -1034,6 +1216,9 @@ public class SoundTriggerService extends SystemService { public void onNullBinding(ComponentName name) { Slog.w(TAG, name + " for model " + mPuuid + " returned a null binding"); + sEventLogger.log(new SoundTriggerLogger.StringEvent(name + " for model " + + mPuuid + " returned a null binding")); + synchronized (mRemoteServiceLock) { disconnectLocked(); } @@ -1082,11 +1267,17 @@ public class SoundTriggerService extends SystemService { public void dump(FileDescriptor fd, PrintWriter pw, String[] args) { if (!isInitialized()) return; mSoundTriggerHelper.dump(fd, pw, args); + // log + sEventLogger.dump(pw); } private synchronized boolean isInitialized() { if (mSoundTriggerHelper == null ) { Slog.e(TAG, "SoundTriggerHelper not initialized."); + + sEventLogger.log(new SoundTriggerLogger.StringEvent( + "SoundTriggerHelper not initialized.")); + return false; } return true; @@ -1099,4 +1290,11 @@ public class SoundTriggerService extends SystemService { throw new SecurityException("Caller does not hold the permission " + permission); } } + + //================================================================= + // For logging + + private static final SoundTriggerLogger sEventLogger = new SoundTriggerLogger(200, + "SoundTrigger activity"); + } |