Add logging and anomaly detection in CallsLogManager.
CallLogManager currently emits a Telecom event when we decide to log to
the call log. To aid in diagnosis of potential problems, we track the
count of call log entries and max id before and after adding an entry to
help try to ascertain in Telecom whether logging did suceeed. We will
also trigger an anomaly report if logging did not complete as expected to
help gain more information about this.
Test: Manual testing for new logging infrastructure.
Bug: 294080756
Change-Id: I1b6d7e889f4bffd8119d027a02e51243b0f95c1c
diff --git a/src/com/android/server/telecom/CallLogManager.java b/src/com/android/server/telecom/CallLogManager.java
index 3005656..72aecac 100644
--- a/src/com/android/server/telecom/CallLogManager.java
+++ b/src/com/android/server/telecom/CallLogManager.java
@@ -19,9 +19,12 @@
import static android.provider.CallLog.Calls.BLOCK_REASON_NOT_BLOCKED;
import static android.telephony.CarrierConfigManager.KEY_SUPPORT_IMS_CONFERENCE_EVENT_PACKAGE_BOOL;
+import android.annotation.NonNull;
import android.annotation.Nullable;
+import android.content.ContentResolver;
import android.content.Context;
import android.content.Intent;
+import android.database.Cursor;
import android.location.Country;
import android.location.CountryDetector;
import android.location.Location;
@@ -30,6 +33,7 @@
import android.os.Looper;
import android.os.UserHandle;
import android.os.PersistableBundle;
+import android.os.UserManager;
import android.provider.CallLog;
import android.provider.CallLog.Calls;
import android.telecom.Connection;
@@ -42,6 +46,7 @@
import android.telephony.CarrierConfigManager;
import android.telephony.PhoneNumberUtils;
import android.telephony.SubscriptionManager;
+import android.util.Pair;
import com.android.internal.annotations.VisibleForTesting;
import com.android.server.telecom.callfiltering.CallFilteringResult;
@@ -49,6 +54,7 @@
import java.util.Arrays;
import java.util.Locale;
import java.util.Objects;
+import java.util.UUID;
import java.util.stream.Stream;
/**
@@ -68,16 +74,19 @@
*/
private static class AddCallArgs {
public AddCallArgs(Context context, CallLog.AddCallParams params,
- @Nullable LogCallCompletedListener logCallCompletedListener) {
+ @Nullable LogCallCompletedListener logCallCompletedListener,
+ @NonNull String callId) {
this.context = context;
this.params = params;
this.logCallCompletedListener = logCallCompletedListener;
+ this.callId = callId;
}
// Since the members are accessed directly, we don't use the
// mXxxx notation.
public final Context context;
public final CallLog.AddCallParams params;
+ public final String callId;
@Nullable
public final LogCallCompletedListener logCallCompletedListener;
}
@@ -88,15 +97,20 @@
// TODO: come up with a better way to indicate in a android.telecom.DisconnectCause that
// a conference was merged successfully
private static final String REASON_IMS_MERGED_SUCCESSFULLY = "IMS_MERGED_SUCCESSFULLY";
+ private static final UUID LOG_CALL_FAILED_ANOMALY_ID =
+ UUID.fromString("1c4c15f3-ab4f-459c-b9ef-43d2988bae82");
+ private static final String LOG_CALL_FAILED_ANOMALY_DESC =
+ "Failed to record a call to the call log.";
private final Context mContext;
private final CarrierConfigManager mCarrierConfigManager;
private final PhoneAccountRegistrar mPhoneAccountRegistrar;
private final MissedCallNotifier mMissedCallNotifier;
+ private AnomalyReporterAdapter mAnomalyReporterAdapter;
private static final String ACTION_CALLS_TABLE_ADD_ENTRY =
- "com.android.server.telecom.intent.action.CALLS_ADD_ENTRY";
+ "com.android.server.telecom.intent.action.CALLS_ADD_ENTRY";
private static final String PERMISSION_PROCESS_CALLLOG_INFO =
- "android.permission.PROCESS_CALLLOG_INFO";
+ "android.permission.PROCESS_CALLLOG_INFO";
private static final String CALL_TYPE = "callType";
private static final String CALL_DURATION = "duration";
@@ -104,12 +118,13 @@
private String mCurrentCountryIso;
public CallLogManager(Context context, PhoneAccountRegistrar phoneAccountRegistrar,
- MissedCallNotifier missedCallNotifier) {
+ MissedCallNotifier missedCallNotifier, AnomalyReporterAdapter anomalyReporterAdapter) {
mContext = context;
mCarrierConfigManager = (CarrierConfigManager) mContext
.getSystemService(Context.CARRIER_CONFIG_SERVICE);
mPhoneAccountRegistrar = phoneAccountRegistrar;
mMissedCallNotifier = missedCallNotifier;
+ mAnomalyReporterAdapter = anomalyReporterAdapter;
mLock = new Object();
}
@@ -263,7 +278,7 @@
* {@link android.provider.CallLog.Calls#BLOCKED_TYPE}.
*/
void logCall(Call call, int callLogType,
- @Nullable LogCallCompletedListener logCallCompletedListener, CallFilteringResult result) {
+ @Nullable LogCallCompletedListener logCallCompletedListener, CallFilteringResult result) {
CallLog.AddCallParams.AddCallParametersBuilder paramBuilder =
new CallLog.AddCallParams.AddCallParametersBuilder();
@@ -385,7 +400,7 @@
okayToLogCall(accountHandle, logNumber, call.isEmergencyCall());
if (okayToLog) {
AddCallArgs args = new AddCallArgs(mContext, paramBuilder.build(),
- logCallCompletedListener);
+ logCallCompletedListener, call.getId());
Log.addEvent(call, LogUtils.Events.LOG_CALL, "number=" + Log.piiHandle(logNumber)
+ ",postDial=" + Log.piiHandle(call.getPostDialDigits()) + ",pres="
+ call.getHandlePresentation());
@@ -517,7 +532,26 @@
mListeners[i] = c.logCallCompletedListener;
try {
// May block.
+ ContentResolver resolver = c.context.getContentResolver();
+ Pair<Integer, Integer> startStats = getCallLogStats(resolver);
+ Log.i(TAG, "LogCall; about to log callId=%s, "
+ + "startCount=%d, startMaxId=%d",
+ c.callId, startStats.first, startStats.second);
+
result[i] = Calls.addCall(c.context, c.params);
+ Pair<Integer, Integer> endStats = getCallLogStats(resolver);
+ Log.i(TAG, "LogCall; logged callId=%s, uri=%s, "
+ + "endCount=%d, endMaxId=%s",
+ c.callId, result, endStats.first, endStats.second);
+ if ((endStats.second - startStats.second) <= 0) {
+ // No call was added or even worse we lost a call in the log. Trigger an
+ // anomaly report. Note: it technically possible that an app modified the
+ // call log while we were writing to it here; that is pretty unlikely, and
+ // the goal here is to try and identify potential anomalous conditions with
+ // logging calls.
+ mAnomalyReporterAdapter.reportAnomaly(LOG_CALL_FAILED_ANOMALY_ID,
+ LOG_CALL_FAILED_ANOMALY_DESC);
+ }
} catch (Exception e) {
// This is very rare but may happen in legitimate cases.
// E.g. If the phone is encrypted and thus write request fails, it may cause
@@ -526,8 +560,10 @@
//
// We don't want to crash the whole process just because of that, so just log
// it instead.
- Log.e(TAG, e, "Exception raised during adding CallLog entry.");
+ Log.e(TAG, e, "LogCall: Exception raised adding callId=%s", c.callId);
result[i] = null;
+ mAnomalyReporterAdapter.reportAnomaly(LOG_CALL_FAILED_ANOMALY_ID,
+ LOG_CALL_FAILED_ANOMALY_DESC);
}
}
return result;
@@ -602,4 +638,56 @@
return mCurrentCountryIso;
}
}
+
+
+ /**
+ * Returns a pair containing the number of rows in the call log, as well as the maximum call log
+ * ID. There is a limit of 500 entries in the call log for a phone account, so once we hit 500
+ * we can reasonably expect that number to not change before and after logging a call.
+ * We determine the maximum ID in the call log since this is a way we can objectively check if
+ * the provider did record a call log entry or not. Ideally there should me more call log
+ * entries after logging than before, and certainly not less.
+ * @param resolver content resolver
+ * @return pair with number of rows in the call log and max id.
+ */
+ private Pair<Integer, Integer> getCallLogStats(@NonNull ContentResolver resolver) {
+ try {
+ final UserManager userManager = mContext.getSystemService(UserManager.class);
+ final int currentUserId = userManager.getProcessUserId();
+
+ // Use shadow provider based on current user unlock state.
+ Uri providerUri;
+ if (userManager.isUserUnlocked(currentUserId)) {
+ providerUri = Calls.CONTENT_URI;
+ } else {
+ providerUri = Calls.SHADOW_CONTENT_URI;
+ }
+ int maxCallId = -1;
+ int numFound;
+ Cursor countCursor = resolver.query(providerUri,
+ new String[]{Calls._ID},
+ null,
+ null,
+ Calls._ID + " DESC");
+ try {
+ numFound = countCursor.getCount();
+ if (numFound > 0) {
+ countCursor.moveToFirst();
+ maxCallId = countCursor.getInt(0);
+ }
+ } finally {
+ countCursor.close();
+ }
+ return new Pair<>(numFound, maxCallId);
+ } catch (Exception e) {
+ // Oh jeepers, we crashed getting the call count.
+ Log.e(TAG, e, "getCountOfCallLogRows: failed");
+ return new Pair<>(-1, -1);
+ }
+ }
+
+ @VisibleForTesting
+ public void setAnomalyReporterAdapter(AnomalyReporterAdapter anomalyReporterAdapter){
+ mAnomalyReporterAdapter = anomalyReporterAdapter;
+ }
}
diff --git a/src/com/android/server/telecom/CallsManager.java b/src/com/android/server/telecom/CallsManager.java
index 04e0f74..4f4f20c 100644
--- a/src/com/android/server/telecom/CallsManager.java
+++ b/src/com/android/server/telecom/CallsManager.java
@@ -655,7 +655,8 @@
mTtyManager = new TtyManager(context, mWiredHeadsetManager);
mProximitySensorManager = proximitySensorManagerFactory.create(context, this);
mPhoneStateBroadcaster = new PhoneStateBroadcaster(this);
- mCallLogManager = new CallLogManager(context, phoneAccountRegistrar, mMissedCallNotifier);
+ mCallLogManager = new CallLogManager(context, phoneAccountRegistrar, mMissedCallNotifier,
+ mAnomalyReporter);
mConnectionServiceRepository =
new ConnectionServiceRepository(mPhoneAccountRegistrar, mContext, mLock, this);
mInCallWakeLockController = inCallWakeLockControllerFactory.create(context, this);
@@ -1381,8 +1382,11 @@
}
@VisibleForTesting
- public void setAnomalyReporterAdapter(AnomalyReporterAdapter mAnomalyReporterAdapter){
- mAnomalyReporter = mAnomalyReporterAdapter;
+ public void setAnomalyReporterAdapter(AnomalyReporterAdapter anomalyReporterAdapter){
+ mAnomalyReporter = anomalyReporterAdapter;
+ if (mCallLogManager != null) {
+ mCallLogManager.setAnomalyReporterAdapter(anomalyReporterAdapter);
+ }
}
void processIncomingConference(PhoneAccountHandle phoneAccountHandle, Bundle extras) {
diff --git a/tests/src/com/android/server/telecom/tests/CallLogManagerTest.java b/tests/src/com/android/server/telecom/tests/CallLogManagerTest.java
index 9466220..c68cbbf 100644
--- a/tests/src/com/android/server/telecom/tests/CallLogManagerTest.java
+++ b/tests/src/com/android/server/telecom/tests/CallLogManagerTest.java
@@ -65,6 +65,7 @@
import androidx.test.filters.FlakyTest;
import com.android.server.telecom.Analytics;
+import com.android.server.telecom.AnomalyReporterAdapter;
import com.android.server.telecom.Call;
import com.android.server.telecom.CallLogManager;
import com.android.server.telecom.CallState;
@@ -123,6 +124,8 @@
PhoneAccountRegistrar mMockPhoneAccountRegistrar;
@Mock
MissedCallNotifier mMissedCallNotifier;
+ @Mock
+ AnomalyReporterAdapter mAnomalyReporterAdapter;
@Override
@Before
@@ -130,7 +133,7 @@
super.setUp();
mContext = mComponentContextFixture.getTestDouble().getApplicationContext();
mCallLogManager = new CallLogManager(mContext, mMockPhoneAccountRegistrar,
- mMissedCallNotifier);
+ mMissedCallNotifier, mAnomalyReporterAdapter);
mDefaultAccountHandle = new PhoneAccountHandle(
new ComponentName("com.android.server.telecom.tests", "CallLogManagerTest"),
TEST_PHONE_ACCOUNT_ID,