From aa56a6cde39b80fa1edd61052dc8ad595d4562cc Mon Sep 17 00:00:00 2001
From: Bernardo Rufino <brufino@google.com>
Date: Tue, 16 Jan 2018 14:10:19 +0000
Subject: Move event logging to TransportClient and add connection event

Move event logging from registration to TransportClient and add new
event for connection.

Change-Id: I32022590a36b6f28f960e91f8880a0430e862852
Ref: http://go/br-binding-on-demand
Bug: 17140907
Test: m -j RunFrameworksServicesRoboTest
Test: adb logcat -b events, check relevant events
---
 .../android/server/backup/TransportManager.java    |  5 --
 .../server/backup/transport/TransportClient.java   | 45 ++++++++++++
 .../java/com/android/server/EventLogTags.logtags   |  1 +
 .../backup/transport/TransportClientTest.java      | 84 +++++++++++++++++++++-
 .../com/android/server/testing/ShadowEventLog.java | 71 ++++++++++++++++++
 5 files changed, 199 insertions(+), 7 deletions(-)
 create mode 100644 services/robotests/src/com/android/server/testing/ShadowEventLog.java

diff --git a/services/backup/java/com/android/server/backup/TransportManager.java b/services/backup/java/com/android/server/backup/TransportManager.java
index 09456b68e1c0..30fd25a92484 100644
--- a/services/backup/java/com/android/server/backup/TransportManager.java
+++ b/services/backup/java/com/android/server/backup/TransportManager.java
@@ -29,14 +29,12 @@ import android.content.pm.ResolveInfo;
 import android.os.RemoteException;
 import android.os.UserHandle;
 import android.util.ArrayMap;
-import android.util.EventLog;
 import android.util.Slog;
 
 import com.android.internal.annotations.GuardedBy;
 import com.android.internal.annotations.VisibleForTesting;
 import com.android.internal.backup.IBackupTransport;
 import com.android.internal.util.Preconditions;
-import com.android.server.EventLogTags;
 import com.android.server.backup.transport.OnTransportRegisteredListener;
 import com.android.server.backup.transport.TransportClient;
 import com.android.server.backup.transport.TransportClientManager;
@@ -574,8 +572,6 @@ public class TransportManager {
             return BackupManager.ERROR_TRANSPORT_UNAVAILABLE;
         }
 
-        EventLog.writeEvent(EventLogTags.BACKUP_TRANSPORT_LIFECYCLE, transportString, 1);
-
         int result;
         try {
             String transportName = transport.name();
@@ -587,7 +583,6 @@ public class TransportManager {
             result = BackupManager.SUCCESS;
         } catch (RemoteException e) {
             Slog.e(TAG, "Transport " + transportString + " died while registering");
-            EventLog.writeEvent(EventLogTags.BACKUP_TRANSPORT_LIFECYCLE, transportString, 0);
             result = BackupManager.ERROR_TRANSPORT_UNAVAILABLE;
         }
 
diff --git a/services/backup/java/com/android/server/backup/transport/TransportClient.java b/services/backup/java/com/android/server/backup/transport/TransportClient.java
index bd4a0bb57072..399f338d26b2 100644
--- a/services/backup/java/com/android/server/backup/transport/TransportClient.java
+++ b/services/backup/java/com/android/server/backup/transport/TransportClient.java
@@ -29,12 +29,14 @@ import android.os.IBinder;
 import android.os.Looper;
 import android.os.UserHandle;
 import android.util.ArrayMap;
+import android.util.EventLog;
 import android.util.Log;
 
 import com.android.internal.annotations.GuardedBy;
 import com.android.internal.annotations.VisibleForTesting;
 import com.android.internal.backup.IBackupTransport;
 import com.android.internal.util.Preconditions;
+import com.android.server.EventLogTags;
 import com.android.server.backup.TransportManager;
 
 import java.lang.annotation.Retention;
@@ -419,10 +421,45 @@ public class TransportClient {
     @GuardedBy("mStateLock")
     private void setStateLocked(@State int state, @Nullable IBackupTransport transport) {
         log(Log.VERBOSE, "State: " + stateToString(mState) + " => " + stateToString(state));
+        onStateTransition(mState, state);
         mState = state;
         mTransport = transport;
     }
 
+    private void onStateTransition(int oldState, int newState) {
+        String transport = mTransportComponent.flattenToShortString();
+        int bound = transitionThroughState(oldState, newState, State.BOUND_AND_CONNECTING);
+        int connected = transitionThroughState(oldState, newState, State.CONNECTED);
+        if (bound != Transition.NO_TRANSITION) {
+            int value = (bound == Transition.UP) ? 1 : 0; // 1 is bound, 0 is not bound
+            EventLog.writeEvent(EventLogTags.BACKUP_TRANSPORT_LIFECYCLE, transport, value);
+        }
+        if (connected != Transition.NO_TRANSITION) {
+            int value = (connected == Transition.UP) ? 1 : 0; // 1 is connected, 0 is not connected
+            EventLog.writeEvent(EventLogTags.BACKUP_TRANSPORT_CONNECTION, transport, value);
+        }
+    }
+
+    /**
+     * Returns:
+     *
+     * <ul>
+     *   <li>{@link Transition#UP}, if oldState < stateReference <= newState
+     *   <li>{@link Transition#DOWN}, if oldState >= stateReference > newState
+     *   <li>{@link Transition#NO_TRANSITION}, otherwise
+     */
+    @Transition
+    private int transitionThroughState(
+            @State int oldState, @State int newState, @State int stateReference) {
+        if (oldState < stateReference && stateReference <= newState) {
+            return Transition.UP;
+        }
+        if (oldState >= stateReference && stateReference > newState) {
+            return Transition.DOWN;
+        }
+        return Transition.NO_TRANSITION;
+    }
+
     @GuardedBy("mStateLock")
     private void checkStateIntegrityLocked() {
         switch (mState) {
@@ -481,6 +518,14 @@ public class TransportClient {
         // CharSequence time = DateFormat.format("yyyy-MM-dd HH:mm:ss", System.currentTimeMillis());
     }
 
+    @IntDef({Transition.DOWN, Transition.NO_TRANSITION, Transition.UP})
+    @Retention(RetentionPolicy.SOURCE)
+    private @interface Transition {
+        int DOWN = -1;
+        int NO_TRANSITION = 0;
+        int UP = 1;
+    }
+
     @IntDef({State.UNUSABLE, State.IDLE, State.BOUND_AND_CONNECTING, State.CONNECTED})
     @Retention(RetentionPolicy.SOURCE)
     private @interface State {
diff --git a/services/core/java/com/android/server/EventLogTags.logtags b/services/core/java/com/android/server/EventLogTags.logtags
index 8361132f24bc..732ac66b41de 100644
--- a/services/core/java/com/android/server/EventLogTags.logtags
+++ b/services/core/java/com/android/server/EventLogTags.logtags
@@ -133,6 +133,7 @@ option java_package com.android.server
 2846 full_backup_cancelled (Package|3),(Message|3)
 
 2850 backup_transport_lifecycle (Transport|3),(Bound|1|1)
+2851 backup_transport_connection (Transport|3),(Connected|1|1)
 
 
 # ---------------------------
diff --git a/services/robotests/src/com/android/server/backup/transport/TransportClientTest.java b/services/robotests/src/com/android/server/backup/transport/TransportClientTest.java
index 9b4dec6019f4..10442b7e467d 100644
--- a/services/robotests/src/com/android/server/backup/transport/TransportClientTest.java
+++ b/services/robotests/src/com/android/server/backup/transport/TransportClientTest.java
@@ -35,8 +35,10 @@ import android.os.Looper;
 import android.os.UserHandle;
 import android.platform.test.annotations.Presubmit;
 import com.android.internal.backup.IBackupTransport;
+import com.android.server.EventLogTags;
 import com.android.server.backup.TransportManager;
 import com.android.server.testing.FrameworkRobolectricTestRunner;
+import com.android.server.testing.ShadowEventLog;
 import com.android.server.testing.SystemLoaderClasses;
 import org.junit.Before;
 import org.junit.Test;
@@ -48,7 +50,7 @@ import org.robolectric.annotation.Config;
 import org.robolectric.shadows.ShadowLooper;
 
 @RunWith(FrameworkRobolectricTestRunner.class)
-@Config(manifest = Config.NONE, sdk = 26)
+@Config(manifest = Config.NONE, sdk = 26, shadows = {ShadowEventLog.class})
 @SystemLoaderClasses({TransportManager.class, TransportClient.class})
 @Presubmit
 public class TransportClientTest {
@@ -60,6 +62,7 @@ public class TransportClientTest {
     @Mock private IBackupTransport.Stub mIBackupTransport;
     private TransportClient mTransportClient;
     private ComponentName mTransportComponent;
+    private String mTransportString;
     private Intent mBindIntent;
     private ShadowLooper mShadowLooper;
 
@@ -71,6 +74,7 @@ public class TransportClientTest {
         mShadowLooper = shadowOf(mainLooper);
         mTransportComponent =
                 new ComponentName(PACKAGE_NAME, PACKAGE_NAME + ".transport.Transport");
+        mTransportString = mTransportComponent.flattenToShortString();
         mBindIntent = new Intent(SERVICE_ACTION_TRANSPORT_HOST).setComponent(mTransportComponent);
         mTransportClient =
                 new TransportClient(
@@ -161,7 +165,7 @@ public class TransportClientTest {
     }
 
     @Test
-    public void testConnectAsync_whenFrameworkDoesntBind_releasesConnection() throws Exception {
+    public void testConnectAsync_whenFrameworkDoesNotBind_releasesConnection() throws Exception {
         when(mContext.bindServiceAsUser(
                         eq(mBindIntent),
                         any(ServiceConnection.class),
@@ -234,6 +238,82 @@ public class TransportClientTest {
                 .onTransportConnectionResult(isNull(), eq(mTransportClient));
     }
 
+    @Test
+    public void testConnectAsync_beforeFrameworkCall_logsBoundTransition() {
+        ShadowEventLog.clearEvents();
+
+        mTransportClient.connectAsync(mTransportConnectionListener, "caller1");
+
+        assertEventLogged(EventLogTags.BACKUP_TRANSPORT_LIFECYCLE, mTransportString, 1);
+    }
+
+    @Test
+    public void testConnectAsync_afterOnServiceConnected_logsBoundAndConnectedTransitions() {
+        ShadowEventLog.clearEvents();
+
+        mTransportClient.connectAsync(mTransportConnectionListener, "caller1");
+        ServiceConnection connection = verifyBindServiceAsUserAndCaptureServiceConnection(mContext);
+        connection.onServiceConnected(mTransportComponent, mIBackupTransport);
+
+        assertEventLogged(EventLogTags.BACKUP_TRANSPORT_LIFECYCLE, mTransportString, 1);
+        assertEventLogged(EventLogTags.BACKUP_TRANSPORT_CONNECTION, mTransportString, 1);
+    }
+
+    @Test
+    public void testConnectAsync_afterOnBindingDied_logsBoundAndUnboundTransitions() {
+        ShadowEventLog.clearEvents();
+
+        mTransportClient.connectAsync(mTransportConnectionListener, "caller1");
+        ServiceConnection connection = verifyBindServiceAsUserAndCaptureServiceConnection(mContext);
+        connection.onBindingDied(mTransportComponent);
+
+        assertEventLogged(EventLogTags.BACKUP_TRANSPORT_LIFECYCLE, mTransportString, 1);
+        assertEventLogged(EventLogTags.BACKUP_TRANSPORT_LIFECYCLE, mTransportString, 0);
+    }
+
+    @Test
+    public void testUnbind_whenConnected_logsDisconnectedAndUnboundTransitions() {
+        mTransportClient.connectAsync(mTransportConnectionListener, "caller1");
+        ServiceConnection connection = verifyBindServiceAsUserAndCaptureServiceConnection(mContext);
+        connection.onServiceConnected(mTransportComponent, mIBackupTransport);
+        ShadowEventLog.clearEvents();
+
+        mTransportClient.unbind("caller1");
+
+        assertEventLogged(EventLogTags.BACKUP_TRANSPORT_CONNECTION, mTransportString, 0);
+        assertEventLogged(EventLogTags.BACKUP_TRANSPORT_LIFECYCLE, mTransportString, 0);
+    }
+
+    @Test
+    public void testOnServiceDisconnected_whenConnected_logsDisconnectedAndUnboundTransitions() {
+        mTransportClient.connectAsync(mTransportConnectionListener, "caller1");
+        ServiceConnection connection = verifyBindServiceAsUserAndCaptureServiceConnection(mContext);
+        connection.onServiceConnected(mTransportComponent, mIBackupTransport);
+        ShadowEventLog.clearEvents();
+
+        connection.onServiceDisconnected(mTransportComponent);
+
+        assertEventLogged(EventLogTags.BACKUP_TRANSPORT_CONNECTION, mTransportString, 0);
+        assertEventLogged(EventLogTags.BACKUP_TRANSPORT_LIFECYCLE, mTransportString, 0);
+    }
+
+    @Test
+    public void testOnBindingDied_whenConnected_logsDisconnectedAndUnboundTransitions() {
+        mTransportClient.connectAsync(mTransportConnectionListener, "caller1");
+        ServiceConnection connection = verifyBindServiceAsUserAndCaptureServiceConnection(mContext);
+        connection.onServiceConnected(mTransportComponent, mIBackupTransport);
+        ShadowEventLog.clearEvents();
+
+        connection.onBindingDied(mTransportComponent);
+
+        assertEventLogged(EventLogTags.BACKUP_TRANSPORT_CONNECTION, mTransportString, 0);
+        assertEventLogged(EventLogTags.BACKUP_TRANSPORT_LIFECYCLE, mTransportString, 0);
+    }
+
+    private void assertEventLogged(int tag, Object... values) {
+        assertThat(ShadowEventLog.hasEvent(tag, values)).isTrue();
+    }
+
     private ServiceConnection verifyBindServiceAsUserAndCaptureServiceConnection(Context context) {
         ArgumentCaptor<ServiceConnection> connectionCaptor =
                 ArgumentCaptor.forClass(ServiceConnection.class);
diff --git a/services/robotests/src/com/android/server/testing/ShadowEventLog.java b/services/robotests/src/com/android/server/testing/ShadowEventLog.java
new file mode 100644
index 000000000000..b8059f4fde87
--- /dev/null
+++ b/services/robotests/src/com/android/server/testing/ShadowEventLog.java
@@ -0,0 +1,71 @@
+/*
+ * Copyright (C) 2018 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.testing;
+
+import android.util.EventLog;
+
+import org.robolectric.annotation.Implementation;
+import org.robolectric.annotation.Implements;
+
+import java.util.Arrays;
+import java.util.LinkedHashSet;
+import java.util.List;
+
+@Implements(EventLog.class)
+public class ShadowEventLog {
+    private final static LinkedHashSet<Entry> ENTRIES = new LinkedHashSet<>();
+
+    @Implementation
+    public static int writeEvent(int tag, Object... values) {
+        ENTRIES.add(new Entry(tag, Arrays.asList(values)));
+        // Currently we don't care about the return value, if we do, estimate it correctly
+        return 0;
+    }
+
+    public static boolean hasEvent(int tag, Object... values) {
+        return ENTRIES.contains(new Entry(tag, Arrays.asList(values)));
+    }
+
+    public static void clearEvents() {
+        ENTRIES.clear();
+    }
+
+    public static class Entry {
+        public final int tag;
+        public final List<Object> values;
+
+        public Entry(int tag, List<Object> values) {
+            this.tag = tag;
+            this.values = values;
+        }
+
+        @Override
+        public boolean equals(Object o) {
+            if (this == o) return true;
+            if (o == null || getClass() != o.getClass()) return false;
+            Entry entry = (Entry) o;
+            return tag == entry.tag && values.equals(entry.values);
+        }
+
+        @Override
+        public int hashCode() {
+            int result = tag;
+            result = 31 * result + values.hashCode();
+            return result;
+        }
+    }
+}
-- 
cgit v1.2.3-59-g8ed1b