Add since_visible_millis to Settings action logs.

This change adds a new action logging method on MetricsFeatureProvider
within Settings.

Uses the VisibilityLoggerMixin to calculate the elapsed time since
the fragment has been visible. Adds tagged data in
MetricsFeatureProvider#action() to store this elapsed time in
NOTIFICATION_SINCE_VISIBLE_MILLIS in MetricsEvents. Modifies the
LogWriter interface to accept variadic taggedData args in its action()
methods. Annotates the old subtype #action() methods as deprecated.

EventLogWriter also no longer casts the subtype values to strings before
sending them to MetricsLogger, so they are correctly stored as subtype
instead of package.

Bug: 65371699, 65631695
Test: make RunSettingsRoboTests
Change-Id: Iec6a61dd6a49ab237e2bdc4469fed45e89d9c380

src/com/android/settings/core/InstrumentedPreferenceFragment.java

@@ -65,4 +65,8 @@ public abstract class InstrumentedPreferenceFragment extends ObservablePreferenc
     protected final Context getPrefContext() {
         return getPreferenceManager().getContext();
     }
+
+    protected final VisibilityLoggerMixin getVisibilityLogger() {
+        return mVisibilityLoggerMixin;
+    }
 }

src/com/android/settings/core/instrumentation/EventLogWriter.java

@@ -18,6 +18,7 @@ package com.android.settings.core.instrumentation;
 
 import android.content.Context;
 import android.metrics.LogMaker;
+import android.util.Log;
 import android.util.Pair;
 
 import com.android.internal.logging.MetricsLogger;
@@ -28,6 +29,8 @@ import com.android.internal.logging.nano.MetricsProto;
  */
 public class EventLogWriter implements LogWriter {
 
+    private final MetricsLogger mMetricsLogger = new MetricsLogger();
+
     public void visible(Context context, int source, int category) {
         final LogMaker logMaker = new LogMaker(category)
                 .setType(MetricsProto.MetricsEvent.TYPE_OPEN)
@@ -39,6 +42,24 @@ public class EventLogWriter implements LogWriter {
         MetricsLogger.hidden(context, category);
     }
 
+    public void action(int category, int value, Pair<Integer, Object>... taggedData) {
+        if (taggedData == null || taggedData.length == 0) {
+            mMetricsLogger.action(category, value);
+        } else {
+            final LogMaker logMaker = new LogMaker(category)
+                    .setType(MetricsProto.MetricsEvent.TYPE_ACTION)
+                    .setSubtype(value);
+            for (Pair<Integer, Object> pair : taggedData) {
+                logMaker.addTaggedData(pair.first, pair.second);
+            }
+            mMetricsLogger.write(logMaker);
+        }
+    }
+
+    public void action(int category, boolean value, Pair<Integer, Object>... taggedData) {
+        action(category, value ? 1 : 0, taggedData);
+    }
+
     public void action(Context context, int category, Pair<Integer, Object>... taggedData) {
         action(context, category, "", taggedData);
     }
@@ -52,12 +73,16 @@ public class EventLogWriter implements LogWriter {
         MetricsLogger.action(logMaker);
     }
 
+    /** @deprecated use {@link #action(int, int, Pair[])} */
+    @Deprecated
     public void action(Context context, int category, int value) {
-        MetricsLogger.action(context, category, Integer.toString(value));
+        MetricsLogger.action(context, category, value);
     }
 
+    /** @deprecated use {@link #action(int, boolean, Pair[])} */
+    @Deprecated
     public void action(Context context, int category, boolean value) {
-        MetricsLogger.action(context, category, Boolean.toString(value));
+        MetricsLogger.action(context, category, value);
     }
 
     public void action(Context context, int category, String pkg,

src/com/android/settings/core/instrumentation/LogWriter.java

@@ -33,6 +33,16 @@ public interface LogWriter {
      */
     void hidden(Context context, int category);
 
+    /**
+     * Logs a user action.
+     */
+    void action(int category, int value, Pair<Integer, Object>... taggedData);
+
+    /**
+     * Logs a user action.
+     */
+    void action(int category, boolean value, Pair<Integer, Object>... taggedData);
+
     /**
      * Logs an user action.
      */
@@ -45,12 +55,16 @@ public interface LogWriter {
 
     /**
      * Logs an user action.
+     * @deprecated use {@link #action(int, int, Pair[])}
      */
+    @Deprecated
     void action(Context context, int category, int value);
 
     /**
      * Logs an user action.
+     * @deprecated use {@link #action(int, boolean, Pair[])}
      */
+    @Deprecated
     void action(Context context, int category, boolean value);
 
     /**

src/com/android/settings/core/instrumentation/MetricsFeatureProvider.java

@@ -21,7 +21,7 @@ import android.content.Intent;
 import android.text.TextUtils;
 import android.util.Pair;
 
-import com.android.internal.logging.nano.MetricsProto;
+import com.android.internal.logging.nano.MetricsProto.MetricsEvent;
 
 import java.util.ArrayList;
 import java.util.List;
@@ -60,18 +60,44 @@ public class MetricsFeatureProvider {
         }
     }
 
+    /**
+     * Logs a user action. Includes the elapsed time since the containing
+     * fragment has been visible.
+     */
+    public void action(VisibilityLoggerMixin visibilityLogger, int category, int value) {
+        for (LogWriter writer : mLoggerWriters) {
+            writer.action(category, value,
+                    sinceVisibleTaggedData(visibilityLogger.elapsedTimeSinceVisible()));
+        }
+    }
+
+    /**
+     * Logs a user action. Includes the elapsed time since the containing
+     * fragment has been visible.
+     */
+    public void action(VisibilityLoggerMixin visibilityLogger, int category, boolean value) {
+        for (LogWriter writer : mLoggerWriters) {
+            writer.action(category, value,
+                    sinceVisibleTaggedData(visibilityLogger.elapsedTimeSinceVisible()));
+        }
+    }
+
     public void action(Context context, int category, Pair<Integer, Object>... taggedData) {
         for (LogWriter writer : mLoggerWriters) {
             writer.action(context, category, taggedData);
         }
     }
 
+    /** @deprecated use {@link #action(VisibilityLoggerMixin, int, int)} */
+    @Deprecated
     public void action(Context context, int category, int value) {
         for (LogWriter writer : mLoggerWriters) {
             writer.action(context, category, value);
         }
     }
 
+    /** @deprecated use {@link #action(VisibilityLoggerMixin, int, boolean)} */
+    @Deprecated
     public void action(Context context, int category, boolean value) {
         for (LogWriter writer : mLoggerWriters) {
             writer.action(context, category, value);
@@ -99,7 +125,7 @@ public class MetricsFeatureProvider {
 
     public int getMetricsCategory(Object object) {
         if (object == null || !(object instanceof Instrumentable)) {
-            return MetricsProto.MetricsEvent.VIEW_UNKNOWN;
+            return MetricsEvent.VIEW_UNKNOWN;
         }
         return ((Instrumentable) object).getMetricsCategory();
     }
@@ -116,15 +142,19 @@ public class MetricsFeatureProvider {
                 // Not loggable
                 return;
             }
-            action(context, MetricsProto.MetricsEvent.ACTION_SETTINGS_TILE_CLICK, action,
+            action(context, MetricsEvent.ACTION_SETTINGS_TILE_CLICK, action,
-                    Pair.create(MetricsProto.MetricsEvent.FIELD_CONTEXT, sourceMetricsCategory));
+                    Pair.create(MetricsEvent.FIELD_CONTEXT, sourceMetricsCategory));
             return;
         } else if (TextUtils.equals(cn.getPackageName(), context.getPackageName())) {
             // Going to a Setting internal page, skip click logging in favor of page's own
             // visibility logging.
             return;
         }
-        action(context, MetricsProto.MetricsEvent.ACTION_SETTINGS_TILE_CLICK, cn.flattenToString(),
+        action(context, MetricsEvent.ACTION_SETTINGS_TILE_CLICK, cn.flattenToString(),
-                Pair.create(MetricsProto.MetricsEvent.FIELD_CONTEXT, sourceMetricsCategory));
+                Pair.create(MetricsEvent.FIELD_CONTEXT, sourceMetricsCategory));
+    }
+
+    private Pair<Integer, Object> sinceVisibleTaggedData(long timestamp) {
+        return Pair.create(MetricsEvent.NOTIFICATION_SINCE_VISIBLE_MILLIS, timestamp);
     }
 }

src/com/android/settings/core/instrumentation/SettingSuggestionsLogWriter.java

@@ -45,6 +45,14 @@ public class SettingSuggestionsLogWriter implements LogWriter {
     public void actionWithSource(Context context, int source, int category) {
     }
 
+    @Override
+    public void action(int category, int value, Pair<Integer, Object>... taggedData) {
+    }
+
+    @Override
+    public void action(int category, boolean value, Pair<Integer, Object>... taggedData) {
+    }
+
     @Override
     public void action(Context context, int category, int value) {
     }

src/com/android/settings/core/instrumentation/VisibilityLoggerMixin.java

@@ -20,6 +20,7 @@ import android.app.Activity;
 import android.content.Context;
 import android.content.Intent;
 
+import android.os.SystemClock;
 import com.android.internal.logging.nano.MetricsProto;
 import com.android.settings.SettingsActivity;
 import com.android.settings.overlay.FeatureFactory;
@@ -41,6 +42,7 @@ public class VisibilityLoggerMixin implements LifecycleObserver, OnResume, OnPau
 
     private MetricsFeatureProvider mMetricsFeature;
     private int mSourceMetricsCategory = MetricsProto.MetricsEvent.VIEW_UNKNOWN;
+    private long mVisibleTimestamp;
 
     public VisibilityLoggerMixin(int metricsCategory) {
         // MetricsFeature will be set during onAttach.
@@ -59,6 +61,7 @@ public class VisibilityLoggerMixin implements LifecycleObserver, OnResume, OnPau
 
     @Override
     public void onResume() {
+        mVisibleTimestamp = SystemClock.elapsedRealtime();
         if (mMetricsFeature != null && mMetricsCategory != METRICS_CATEGORY_UNKNOWN) {
             mMetricsFeature.visible(null /* context */, mSourceMetricsCategory, mMetricsCategory);
         }
@@ -66,6 +69,7 @@ public class VisibilityLoggerMixin implements LifecycleObserver, OnResume, OnPau
 
     @Override
     public void onPause() {
+        mVisibleTimestamp = 0;
         if (mMetricsFeature != null && mMetricsCategory != METRICS_CATEGORY_UNKNOWN) {
             mMetricsFeature.hidden(null /* context */, mMetricsCategory);
         }
@@ -85,4 +89,12 @@ public class VisibilityLoggerMixin implements LifecycleObserver, OnResume, OnPau
         mSourceMetricsCategory = intent.getIntExtra(SettingsActivity.EXTRA_SOURCE_METRICS_CATEGORY,
                 MetricsProto.MetricsEvent.VIEW_UNKNOWN);
     }
+
+    /** Returns elapsed time since onResume() */
+    public long elapsedTimeSinceVisible() {
+        if (mVisibleTimestamp == 0) {
+            return 0;
+        }
+        return SystemClock.elapsedRealtime() - mVisibleTimestamp;
+    }
 }

src/com/android/settings/wifi/WifiSettings.java

@@ -1070,7 +1070,7 @@ public class WifiSettings extends RestrictedSettingsFragment
 
     protected void connect(final WifiConfiguration config, boolean isSavedNetwork) {
         // Log subtype if configuration is a saved network.
-        mMetricsFeatureProvider.action(getActivity(), MetricsEvent.ACTION_WIFI_CONNECT,
+        mMetricsFeatureProvider.action(getVisibilityLogger(), MetricsEvent.ACTION_WIFI_CONNECT,
                 isSavedNetwork);
         mWifiManager.connect(config, mConnectListener);
         mClickedConnect = true;

tests/robotests/src/com/android/settings/core/instrumentation/MetricsFeatureProviderTest.java

@@ -28,6 +28,8 @@ import com.android.settings.overlay.FeatureFactory;
 import org.junit.Before;
 import org.junit.Test;
 import org.junit.runner.RunWith;
+import org.mockito.ArgumentCaptor;
+import org.mockito.Captor;
 import org.mockito.Mock;
 import org.mockito.MockitoAnnotations;
 import org.robolectric.RuntimeEnvironment;
@@ -42,24 +44,35 @@ import static org.mockito.Matchers.anyString;
 import static org.mockito.Matchers.eq;
 import static org.mockito.Mockito.verify;
 import static org.mockito.Mockito.verifyNoMoreInteractions;
+import static org.mockito.Mockito.when;
 
 @RunWith(SettingsRobolectricTestRunner.class)
 @Config(manifest = TestConfig.MANIFEST_PATH, sdk = TestConfig.SDK_VERSION)
 public class MetricsFeatureProviderTest {
+    private static int CATEGORY = 10;
+    private static boolean SUBTYPE_BOOLEAN = true;
+    private static int SUBTYPE_INTEGER = 1;
+    private static long ELAPSED_TIME = 1000;
+
+    @Mock private LogWriter mockLogWriter;
+    @Mock private VisibilityLoggerMixin mockVisibilityLogger;
 
-    @Mock
-    private LogWriter mLogWriter;
     private Context mContext;
     private MetricsFeatureProvider mProvider;
 
+    @Captor
+    private ArgumentCaptor<Pair> mPairCaptor;
+
     @Before
     public void setUp() {
         MockitoAnnotations.initMocks(this);
         mContext = RuntimeEnvironment.application;
         mProvider = new MetricsFeatureProvider();
         List<LogWriter> writers = new ArrayList<>();
-        writers.add(mLogWriter);
+        writers.add(mockLogWriter);
         ReflectionHelpers.setField(mProvider, "mLoggerWriters", writers);
+
+        when(mockVisibilityLogger.elapsedTimeSinceVisible()).thenReturn(ELAPSED_TIME);
     }
 
     @Test
@@ -77,7 +90,7 @@ public class MetricsFeatureProviderTest {
         mProvider.logDashboardStartIntent(mContext, null /* intent */,
                 MetricsEvent.SETTINGS_GESTURES);
 
-        verifyNoMoreInteractions(mLogWriter);
+        verifyNoMoreInteractions(mockLogWriter);
     }
 
     @Test
@@ -86,7 +99,7 @@ public class MetricsFeatureProviderTest {
 
         mProvider.logDashboardStartIntent(mContext, intent, MetricsEvent.SETTINGS_GESTURES);
 
-        verify(mLogWriter).action(
+        verify(mockLogWriter).action(
                 eq(mContext),
                 eq(MetricsEvent.ACTION_SETTINGS_TILE_CLICK),
                 anyString(),
@@ -99,10 +112,32 @@ public class MetricsFeatureProviderTest {
 
         mProvider.logDashboardStartIntent(mContext, intent, MetricsEvent.SETTINGS_GESTURES);
 
-        verify(mLogWriter).action(
+        verify(mockLogWriter).action(
                 eq(mContext),
                 eq(MetricsEvent.ACTION_SETTINGS_TILE_CLICK),
                 anyString(),
                 eq(Pair.create(MetricsEvent.FIELD_CONTEXT, MetricsEvent.SETTINGS_GESTURES)));
     }
+
+    @Test
+    public void action_BooleanLogsElapsedTime() {
+        mProvider.action(mockVisibilityLogger, CATEGORY, SUBTYPE_BOOLEAN);
+        verify(mockLogWriter).action(eq(CATEGORY), eq(SUBTYPE_BOOLEAN), mPairCaptor.capture());
+
+        Pair value = mPairCaptor.getValue();
+        assertThat(value.first instanceof Integer).isTrue();
+        assertThat((int) value.first).isEqualTo(MetricsEvent.NOTIFICATION_SINCE_VISIBLE_MILLIS);
+        assertThat(value.second).isEqualTo(ELAPSED_TIME);
+    }
+
+    @Test
+    public void action_IntegerLogsElapsedTime() {
+        mProvider.action(mockVisibilityLogger, CATEGORY, SUBTYPE_INTEGER);
+        verify(mockLogWriter).action(eq(CATEGORY), eq(SUBTYPE_INTEGER), mPairCaptor.capture());
+
+        Pair value = mPairCaptor.getValue();
+        assertThat(value.first instanceof Integer).isTrue();
+        assertThat((int) value.first).isEqualTo(MetricsEvent.NOTIFICATION_SINCE_VISIBLE_MILLIS);
+        assertThat(value.second).isEqualTo(ELAPSED_TIME);
+    }
 }