From 2d28217de6c4ddfb26362dfa8422f0d9e3ef989c Mon Sep 17 00:00:00 2001 From: lpeter Date: Fri, 25 Jun 2021 02:15:54 +0800 Subject: [PATCH 1/2] Set the Debug flag to false Set the Debug flag to false, but we also reserve some logs for clarifying the issue. Bug: 177502877 Test: atest CtsVoiceInteractionTestCases Test: atest CtsVoiceInteractionTestCases --instant Change-Id: Idf5dd82d8db27bb682b473eb4584e8b230073d08 --- .../voice/HotwordDetectionService.java | 7 +-- .../voice/SoftwareHotwordDetector.java | 2 +- .../HotwordDetectionConnection.java | 46 +++++-------------- .../VoiceInteractionManagerServiceImpl.java | 7 +-- 4 files changed, 17 insertions(+), 45 deletions(-) diff --git a/core/java/android/service/voice/HotwordDetectionService.java b/core/java/android/service/voice/HotwordDetectionService.java index a43523974480f..e3bb589c9a19d 100644 --- a/core/java/android/service/voice/HotwordDetectionService.java +++ b/core/java/android/service/voice/HotwordDetectionService.java @@ -72,8 +72,7 @@ import java.util.function.IntConsumer; @SystemApi public abstract class HotwordDetectionService extends Service { private static final String TAG = "HotwordDetectionService"; - // TODO (b/177502877): Set the Debug flag to false before shipping. - private static final boolean DBG = true; + private static final boolean DBG = false; private static final long UPDATE_TIMEOUT_MILLIS = 5000; @@ -151,9 +150,7 @@ public abstract class HotwordDetectionService extends Service { @Override public void updateState(PersistableBundle options, SharedMemory sharedMemory, IRemoteCallback callback) throws RemoteException { - if (DBG) { - Log.d(TAG, "#updateState"); - } + Log.v(TAG, "#updateState" + (callback != null ? " with callback" : "")); HotwordDetectionService.this.onUpdateStateInternal( options, sharedMemory, diff --git a/core/java/android/service/voice/SoftwareHotwordDetector.java b/core/java/android/service/voice/SoftwareHotwordDetector.java index fb540b1622e62..02294e5720aee 100644 --- a/core/java/android/service/voice/SoftwareHotwordDetector.java +++ b/core/java/android/service/voice/SoftwareHotwordDetector.java @@ -47,7 +47,7 @@ import java.io.PrintWriter; **/ class SoftwareHotwordDetector extends AbstractHotwordDetector { private static final String TAG = SoftwareHotwordDetector.class.getSimpleName(); - private static final boolean DEBUG = true; + private static final boolean DEBUG = false; private final IVoiceInteractionManagerService mManagerService; private final HotwordDetector.Callback mCallback; diff --git a/services/voiceinteraction/java/com/android/server/voiceinteraction/HotwordDetectionConnection.java b/services/voiceinteraction/java/com/android/server/voiceinteraction/HotwordDetectionConnection.java index 1c8291def9694..655bfe2a1a464 100644 --- a/services/voiceinteraction/java/com/android/server/voiceinteraction/HotwordDetectionConnection.java +++ b/services/voiceinteraction/java/com/android/server/voiceinteraction/HotwordDetectionConnection.java @@ -87,8 +87,7 @@ import java.util.function.Function; */ final class HotwordDetectionConnection { private static final String TAG = "HotwordDetectionConnection"; - // TODO (b/177502877): Set the Debug flag to false before shipping. - static final boolean DEBUG = true; + static final boolean DEBUG = false; // TODO: These constants need to be refined. private static final long VALIDATION_TIMEOUT_MILLIS = 3000; @@ -159,10 +158,7 @@ final class HotwordDetectionConnection { // TODO(volnov): we need to be smarter here, e.g. schedule it a bit more often, but wait // until the current session is closed. mCancellationTaskFuture = mScheduledExecutorService.scheduleAtFixedRate(() -> { - if (DEBUG) { - Slog.i(TAG, "Time to restart the process, TTL has passed"); - } - + Slog.v(TAG, "Time to restart the process, TTL has passed"); synchronized (mLock) { restartProcessLocked(); } @@ -268,9 +264,7 @@ final class HotwordDetectionConnection { } void cancelLocked() { - if (DEBUG) { - Slog.d(TAG, "cancelLocked"); - } + Slog.v(TAG, "cancelLocked"); if (mRemoteHotwordDetectionService.isBound()) { mRemoteHotwordDetectionService.unbind(); LocalServices.getService(PermissionManagerServiceInternal.class) @@ -288,6 +282,7 @@ final class HotwordDetectionConnection { // TODO(b/191742511): this logic needs a test if (!mUpdateStateAfterStartFinished.get() && Instant.now().minus(MAX_UPDATE_TIMEOUT_DURATION).isBefore(mLastRestartInstant)) { + Slog.v(TAG, "call updateStateAfterProcessStart"); updateStateAfterProcessStart(options, sharedMemory); } else { mRemoteHotwordDetectionService.run( @@ -407,15 +402,11 @@ final class HotwordDetectionConnection { private void detectFromDspSourceForTest(SoundTrigger.KeyphraseRecognitionEvent recognitionEvent, IHotwordRecognitionStatusCallback externalCallback) { - if (DEBUG) { - Slog.d(TAG, "detectFromDspSourceForTest"); - } + Slog.v(TAG, "detectFromDspSourceForTest"); IDspHotwordDetectionCallback internalCallback = new IDspHotwordDetectionCallback.Stub() { @Override public void onDetected(HotwordDetectedResult result) throws RemoteException { - if (DEBUG) { - Slog.d(TAG, "onDetected"); - } + Slog.v(TAG, "onDetected"); synchronized (mLock) { if (mValidatingDspTrigger) { mValidatingDspTrigger = false; @@ -433,9 +424,7 @@ final class HotwordDetectionConnection { @Override public void onRejected(HotwordRejectedResult result) throws RemoteException { - if (DEBUG) { - Slog.d(TAG, "onRejected"); - } + Slog.v(TAG, "onRejected"); synchronized (mLock) { if (mValidatingDspTrigger) { mValidatingDspTrigger = false; @@ -514,19 +503,14 @@ final class HotwordDetectionConnection { } void forceRestart() { - if (DEBUG) { - Slog.i(TAG, "Requested to restart the service internally. Performing the restart"); - } + Slog.v(TAG, "Requested to restart the service internally. Performing the restart"); synchronized (mLock) { restartProcessLocked(); } } private void restartProcessLocked() { - if (DEBUG) { - Slog.i(TAG, "Restarting hotword detection process"); - } - + Slog.v(TAG, "Restarting hotword detection process"); ServiceConnection oldConnection = mRemoteHotwordDetectionService; // TODO(volnov): this can be done after connect() has been successful. @@ -547,9 +531,7 @@ final class HotwordDetectionConnection { // Recreate connection to reset the cache. mRemoteHotwordDetectionService = mServiceConnectionFactory.createLocked(); - if (DEBUG) { - Slog.i(TAG, "Started the new process, issuing #onProcessRestarted"); - } + Slog.v(TAG, "Started the new process, issuing #onProcessRestarted"); try { mCallback.onProcessRestarted(); } catch (RemoteException e) { @@ -773,9 +755,7 @@ final class HotwordDetectionConnection { } synchronized (mLock) { if (!mRespectServiceConnectionStatusChanged) { - if (DEBUG) { - Slog.d(TAG, "Ignored onServiceConnectionStatusChanged event"); - } + Slog.v(TAG, "Ignored onServiceConnectionStatusChanged event"); return; } mIsBound = connected; @@ -792,9 +772,7 @@ final class HotwordDetectionConnection { super.binderDied(); synchronized (mLock) { if (!mRespectServiceConnectionStatusChanged) { - if (DEBUG) { - Slog.d(TAG, "Ignored #binderDied event"); - } + Slog.v(TAG, "Ignored #binderDied event"); return; } diff --git a/services/voiceinteraction/java/com/android/server/voiceinteraction/VoiceInteractionManagerServiceImpl.java b/services/voiceinteraction/java/com/android/server/voiceinteraction/VoiceInteractionManagerServiceImpl.java index cbcbf52c2c9c5..92fe33a3b8703 100644 --- a/services/voiceinteraction/java/com/android/server/voiceinteraction/VoiceInteractionManagerServiceImpl.java +++ b/services/voiceinteraction/java/com/android/server/voiceinteraction/VoiceInteractionManagerServiceImpl.java @@ -79,8 +79,7 @@ import java.util.List; class VoiceInteractionManagerServiceImpl implements VoiceInteractionSessionConnection.Callback { final static String TAG = "VoiceInteractionServiceManager"; - // TODO (b/177502877): Set the Debug flag to false before shipping. - static final boolean DEBUG = true; + static final boolean DEBUG = false; final static String CLOSE_REASON_VOICE_INTERACTION = "voiceinteraction"; @@ -420,9 +419,7 @@ class VoiceInteractionManagerServiceImpl implements VoiceInteractionSessionConne @Nullable PersistableBundle options, @Nullable SharedMemory sharedMemory, IHotwordRecognitionStatusCallback callback) { - if (DEBUG) { - Slog.d(TAG, "updateStateLocked"); - } + Slog.v(TAG, "updateStateLocked"); if (mHotwordDetectionComponentName == null) { Slog.w(TAG, "Hotword detection service name not found"); throw new IllegalStateException("Hotword detection service name not found"); From d28177c7e7f44e247775955f37243ef2a0fe5299 Mon Sep 17 00:00:00 2001 From: lpeter Date: Fri, 23 Jul 2021 17:26:09 +0800 Subject: [PATCH 2/2] Provide the way to enable/disable debug mode for logging egressed data Currently we provide the Shell command to enable/disable one debug mode that we will log the HotwordDetectedResult and HotwordRejectedResult if the debug mode is wnable. But we will reset the debug mode after one hour from last enable. Bug: 194339253 Test: Use the Shell command and check the log Change-Id: I212ad58c7550b297babed50249a08db6f0e24b3a --- .../HotwordDetectionConnection.java | 49 +++++++++++++++++++ .../VoiceInteractionManagerService.java | 11 +++++ .../VoiceInteractionManagerServiceImpl.java | 8 +++ ...InteractionManagerServiceShellCommand.java | 18 +++++++ 4 files changed, 86 insertions(+) diff --git a/services/voiceinteraction/java/com/android/server/voiceinteraction/HotwordDetectionConnection.java b/services/voiceinteraction/java/com/android/server/voiceinteraction/HotwordDetectionConnection.java index 655bfe2a1a464..965f126000fd8 100644 --- a/services/voiceinteraction/java/com/android/server/voiceinteraction/HotwordDetectionConnection.java +++ b/services/voiceinteraction/java/com/android/server/voiceinteraction/HotwordDetectionConnection.java @@ -94,6 +94,7 @@ final class HotwordDetectionConnection { private static final long MAX_UPDATE_TIMEOUT_MILLIS = 6000; private static final Duration MAX_UPDATE_TIMEOUT_DURATION = Duration.ofMillis(MAX_UPDATE_TIMEOUT_MILLIS); + private static final long RESET_DEBUG_HOTWORD_LOGGING_TIMEOUT_MILLIS = 60 * 60 * 1000; // 1 hour private final Executor mAudioCopyExecutor = Executors.newCachedThreadPool(); // TODO: This may need to be a Handler(looper) @@ -114,6 +115,7 @@ final class HotwordDetectionConnection { private Instant mLastRestartInstant; private ScheduledFuture mCancellationTaskFuture; + private ScheduledFuture mDebugHotwordLoggingTimeoutFuture = null; /** Identity used for attributing app ops when delivering data to the Interactor. */ @GuardedBy("mLock") @@ -127,6 +129,7 @@ final class HotwordDetectionConnection { private boolean mPerformingSoftwareHotwordDetection; private @NonNull ServiceConnection mRemoteHotwordDetectionService; private IBinder mAudioFlinger; + private boolean mDebugHotwordLogging = false; HotwordDetectionConnection(Object lock, Context context, int voiceInteractionServiceUid, Identity voiceInteractorIdentity, ComponentName serviceName, int userId, @@ -265,6 +268,8 @@ final class HotwordDetectionConnection { void cancelLocked() { Slog.v(TAG, "cancelLocked"); + clearDebugHotwordLoggingTimeoutLocked(); + mDebugHotwordLogging = false; if (mRemoteHotwordDetectionService.isBound()) { mRemoteHotwordDetectionService.unbind(); LocalServices.getService(PermissionManagerServiceInternal.class) @@ -325,6 +330,9 @@ final class HotwordDetectionConnection { if (result != null) { Slog.i(TAG, "Egressed " + HotwordDetectedResult.getUsageSize(result) + " bits from hotword trusted process"); + if (mDebugHotwordLogging) { + Slog.i(TAG, "Egressed detected result: " + result); + } } } else { Slog.i(TAG, "Hotword detection has already completed"); @@ -415,6 +423,9 @@ final class HotwordDetectionConnection { if (result != null) { Slog.i(TAG, "Egressed " + HotwordDetectedResult.getUsageSize(result) + " bits from hotword trusted process"); + if (mDebugHotwordLogging) { + Slog.i(TAG, "Egressed detected result: " + result); + } } } else { Slog.i(TAG, "Ignored hotword detected since trigger has been handled"); @@ -429,6 +440,9 @@ final class HotwordDetectionConnection { if (mValidatingDspTrigger) { mValidatingDspTrigger = false; externalCallback.onRejected(result); + if (mDebugHotwordLogging && result != null) { + Slog.i(TAG, "Egressed rejected result: " + result); + } } else { Slog.i(TAG, "Ignored hotword rejected since trigger has been handled"); } @@ -471,6 +485,9 @@ final class HotwordDetectionConnection { if (result != null) { Slog.i(TAG, "Egressed " + HotwordDetectedResult.getUsageSize(result) + " bits from hotword trusted process"); + if (mDebugHotwordLogging) { + Slog.i(TAG, "Egressed detected result: " + result); + } } } } @@ -487,6 +504,9 @@ final class HotwordDetectionConnection { } mValidatingDspTrigger = false; externalCallback.onRejected(result); + if (mDebugHotwordLogging && result != null) { + Slog.i(TAG, "Egressed rejected result: " + result); + } } } }; @@ -509,6 +529,29 @@ final class HotwordDetectionConnection { } } + void setDebugHotwordLoggingLocked(boolean logging) { + Slog.v(TAG, "setDebugHotwordLoggingLocked: " + logging); + clearDebugHotwordLoggingTimeoutLocked(); + mDebugHotwordLogging = logging; + + if (logging) { + // Reset mDebugHotwordLogging to false after one hour + mDebugHotwordLoggingTimeoutFuture = mScheduledExecutorService.schedule(() -> { + Slog.v(TAG, "Timeout to reset mDebugHotwordLogging to false"); + synchronized (mLock) { + mDebugHotwordLogging = false; + } + }, RESET_DEBUG_HOTWORD_LOGGING_TIMEOUT_MILLIS, TimeUnit.MILLISECONDS); + } + } + + private void clearDebugHotwordLoggingTimeoutLocked() { + if (mDebugHotwordLoggingTimeoutFuture != null) { + mDebugHotwordLoggingTimeoutFuture.cancel(/* mayInterruptIfRunning= */true); + mDebugHotwordLoggingTimeoutFuture = null; + } + } + private void restartProcessLocked() { Slog.v(TAG, "Restarting hotword detection process"); ServiceConnection oldConnection = mRemoteHotwordDetectionService; @@ -682,6 +725,9 @@ final class HotwordDetectionConnection { bestEffortClose(serviceAudioSource); bestEffortClose(audioSource); + if (mDebugHotwordLogging && result != null) { + Slog.i(TAG, "Egressed rejected result: " + result); + } // TODO: Propagate the HotwordRejectedResult. } @@ -696,6 +742,9 @@ final class HotwordDetectionConnection { if (triggerResult != null) { Slog.i(TAG, "Egressed " + HotwordDetectedResult.getUsageSize( triggerResult) + " bits from hotword trusted process"); + if (mDebugHotwordLogging) { + Slog.i(TAG, "Egressed detected result: " + triggerResult); + } } // TODO: Add a delay before closing. bestEffortClose(audioSource); diff --git a/services/voiceinteraction/java/com/android/server/voiceinteraction/VoiceInteractionManagerService.java b/services/voiceinteraction/java/com/android/server/voiceinteraction/VoiceInteractionManagerService.java index ccf4267a0fbce..71541ad729d53 100644 --- a/services/voiceinteraction/java/com/android/server/voiceinteraction/VoiceInteractionManagerService.java +++ b/services/voiceinteraction/java/com/android/server/voiceinteraction/VoiceInteractionManagerService.java @@ -832,6 +832,17 @@ public class VoiceInteractionManagerService extends SystemService { mImpl.forceRestartHotwordDetector(); } + // Called by Shell command + void setDebugHotwordLogging(boolean logging) { + synchronized (this) { + if (mImpl == null) { + Slog.w(TAG, "setTemporaryLogging without running voice interaction service"); + return; + } + mImpl.setDebugHotwordLoggingLocked(logging); + } + } + @Override public void showSession(Bundle args, int flags) { synchronized (this) { diff --git a/services/voiceinteraction/java/com/android/server/voiceinteraction/VoiceInteractionManagerServiceImpl.java b/services/voiceinteraction/java/com/android/server/voiceinteraction/VoiceInteractionManagerServiceImpl.java index 92fe33a3b8703..558a9ac9298ea 100644 --- a/services/voiceinteraction/java/com/android/server/voiceinteraction/VoiceInteractionManagerServiceImpl.java +++ b/services/voiceinteraction/java/com/android/server/voiceinteraction/VoiceInteractionManagerServiceImpl.java @@ -581,6 +581,14 @@ class VoiceInteractionManagerServiceImpl implements VoiceInteractionSessionConne mHotwordDetectionConnection.forceRestart(); } + void setDebugHotwordLoggingLocked(boolean logging) { + if (mHotwordDetectionConnection == null) { + Slog.w(TAG, "Failed to set temporary debug logging: no hotword detection active"); + return; + } + mHotwordDetectionConnection.setDebugHotwordLoggingLocked(logging); + } + void resetHotwordDetectionConnectionLocked() { if (DEBUG) { Slog.d(TAG, "resetHotwordDetectionConnectionLocked"); diff --git a/services/voiceinteraction/java/com/android/server/voiceinteraction/VoiceInteractionManagerServiceShellCommand.java b/services/voiceinteraction/java/com/android/server/voiceinteraction/VoiceInteractionManagerServiceShellCommand.java index cdd8f7b91d9d8..9bdf4e418a527 100644 --- a/services/voiceinteraction/java/com/android/server/voiceinteraction/VoiceInteractionManagerServiceShellCommand.java +++ b/services/voiceinteraction/java/com/android/server/voiceinteraction/VoiceInteractionManagerServiceShellCommand.java @@ -56,6 +56,8 @@ final class VoiceInteractionManagerServiceShellCommand extends ShellCommand { return requestDisable(pw); case "restart-detection": return requestRestartDetection(pw); + case "set-debug-hotword-logging": + return setDebugHotwordLogging(pw); default: return handleDefaultCommands(cmd); } @@ -76,9 +78,14 @@ final class VoiceInteractionManagerServiceShellCommand extends ShellCommand { pw.println(""); pw.println(" disable [true|false]"); pw.println(" Temporarily disable (when true) service"); + pw.println(""); pw.println(" restart-detection"); pw.println(" Force a restart of a hotword detection service"); pw.println(""); + pw.println(" set-debug-hotword-logging [true|false]"); + pw.println(" Temporarily enable or disable debug logging for hotword result."); + pw.println(" The debug logging will be reset after one hour from last enable."); + pw.println(""); } } @@ -157,6 +164,17 @@ final class VoiceInteractionManagerServiceShellCommand extends ShellCommand { return 0; } + private int setDebugHotwordLogging(PrintWriter pw) { + boolean logging = Boolean.parseBoolean(getNextArgRequired()); + Slog.i(TAG, "setDebugHotwordLogging(): " + logging); + try { + mService.setDebugHotwordLogging(logging); + } catch (Exception e) { + return handleError(pw, "setDebugHotwordLogging()", e); + } + return 0; + } + private static int handleError(PrintWriter pw, String message, Exception e) { Slog.e(TAG, "error calling " + message, e); pw.printf("Error calling %s: %s\n", message, e);