/* * Copyright (C) 2022 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.telecom; import static android.telephony.TelephonyManager.EmergencyCallDiagnosticData; import android.os.BugreportManager; import android.os.DropBoxManager; import android.provider.DeviceConfig; import android.telecom.DisconnectCause; import android.telecom.Log; import android.telephony.TelephonyManager; import android.util.LocalLog; import com.android.internal.annotations.VisibleForTesting; import com.android.internal.util.IndentingPrintWriter; import java.util.ArrayList; import java.util.Arrays; import java.util.List; import java.util.Map; import java.util.concurrent.ConcurrentHashMap; import java.util.concurrent.Executor; /** * The EmergencyCallDiagnosticsLogger monitors information required to diagnose potential outgoing * ecall failures on the device. When a potential failure is detected, it calls a Telephony API to * persist relevant information (dumpsys, logcat etc.) to the dropbox. This acts as a central place * to determine when and what to collect. * *

When a bugreport is triggered, this module will read the dropbox entries and add them to the * telecom dump. */ public class EmergencyCallDiagnosticLogger extends CallsManagerListenerBase implements Call.Listener { public static final int REPORT_REASON_RANGE_START = -1; //!!DO NOT CHANGE public static final int REPORT_REASON_RANGE_END = 5; //increment this and add new reason above public static final int COLLECTION_TYPE_BUGREPORT = 10; public static final int COLLECTION_TYPE_TELECOM_STATE = 11; public static final int COLLECTION_TYPE_TELEPHONY_STATE = 12; public static final int COLLECTION_TYPE_LOGCAT_BUFFERS = 13; private static final int REPORT_REASON_STUCK_CALL_DETECTED = 0; private static final int REPORT_REASON_INACTIVE_CALL_TERMINATED_BY_USER_AFTER_DELAY = 1; private static final int REPORT_REASON_CALL_FAILED = 2; private static final int REPORT_REASON_CALL_CREATED_BUT_NEVER_ADDED = 3; private static final int REPORT_REASON_SHORT_DURATION_AFTER_GOING_ACTIVE = 4; private static final String DROPBOX_TAG = "ecall_diagnostic_data"; private static final String ENABLE_BUGREPORT_COLLECTION_FOR_EMERGENCY_CALL_DIAGNOSTICS = "enable_bugreport_collection_for_emergency_call_diagnostics"; private static final String ENABLE_TELECOM_DUMP_COLLECTION_FOR_EMERGENCY_CALL_DIAGNOSTICS = "enable_telecom_dump_collection_for_emergency_call_diagnostics"; private static final String ENABLE_LOGCAT_COLLECTION_FOR_EMERGENCY_CALL_DIAGNOSTICS = "enable_logcat_collection_for_emergency_call_diagnostics"; private static final String ENABLE_TELEPHONY_DUMP_COLLECTION_FOR_EMERGENCY_CALL_DIAGNOSTICS = "enable_telephony_dump_collection_for_emergency_call_diagnostics"; private static final String DUMPSYS_ARG_FOR_DIAGNOSTICS = "EmergencyDiagnostics"; // max text size to read from dropbox entry private static final int DEFAULT_MAX_READ_BYTES_PER_DROP_BOX_ENTRY = 500000; private static final String MAX_BYTES_PER_DROP_BOX_ENTRY = "max_bytes_per_dropbox_entry"; private static final int MAX_DROPBOX_ENTRIES_TO_DUMP = 6; private final Timeouts.Adapter mTimeoutAdapter; // This map holds all calls, but keeps pruning non-emergency calls when we can determine it private final Map mEmergencyCallsMap = new ConcurrentHashMap<>(2); private final DropBoxManager mDropBoxManager; private final LocalLog mLocalLog = new LocalLog(10); private final TelephonyManager mTelephonyManager; private final BugreportManager mBugreportManager; private final Executor mAsyncTaskExecutor; private final ClockProxy mClockProxy; public EmergencyCallDiagnosticLogger( TelephonyManager tm, BugreportManager brm, Timeouts.Adapter timeoutAdapter, DropBoxManager dropBoxManager, Executor asyncTaskExecutor, ClockProxy clockProxy) { mTimeoutAdapter = timeoutAdapter; mDropBoxManager = dropBoxManager; mTelephonyManager = tm; mBugreportManager = brm; mAsyncTaskExecutor = asyncTaskExecutor; mClockProxy = clockProxy; } // this calculates time from ACTIVE --> removed private static long getCallTimeInActiveStateSec(CallEventTimestamps ts) { if (ts.getCallActiveTime() == 0 || ts.getCallRemovedTime() == 0) { return 0; } else { return (ts.getCallRemovedTime() - ts.getCallActiveTime()) / 1000; } } // this calculates time from call created --> removed private static long getTotalCallTimeSec(CallEventTimestamps ts) { if (ts.getCallRemovedTime() == 0 || ts.getCallCreatedTime() == 0) { return 0; } else { return (ts.getCallRemovedTime() - ts.getCallCreatedTime()) / 1000; } } //determines what to collect based on fail reason //if COLLECTION_TYPE_BUGREPORT is present in the returned list, then that //should be the only collection type in the list @VisibleForTesting public static List getDataCollectionTypes(int reason) { switch (reason) { case REPORT_REASON_SHORT_DURATION_AFTER_GOING_ACTIVE: return Arrays.asList(COLLECTION_TYPE_TELECOM_STATE); case REPORT_REASON_CALL_CREATED_BUT_NEVER_ADDED: return Arrays.asList( COLLECTION_TYPE_TELECOM_STATE, COLLECTION_TYPE_TELEPHONY_STATE); case REPORT_REASON_CALL_FAILED: case REPORT_REASON_INACTIVE_CALL_TERMINATED_BY_USER_AFTER_DELAY: case REPORT_REASON_STUCK_CALL_DETECTED: return Arrays.asList( COLLECTION_TYPE_TELECOM_STATE, COLLECTION_TYPE_TELEPHONY_STATE, COLLECTION_TYPE_LOGCAT_BUFFERS); default: } return new ArrayList<>(); } private int getMaxBytesPerDropboxEntry() { return DeviceConfig.getInt(DeviceConfig.NAMESPACE_TELEPHONY, MAX_BYTES_PER_DROP_BOX_ENTRY, DEFAULT_MAX_READ_BYTES_PER_DROP_BOX_ENTRY); } @VisibleForTesting public Map getEmergencyCallsMap() { return mEmergencyCallsMap; } private void triggerDiagnosticsCollection(Call call, int reason) { Log.i(this, "Triggering diagnostics for call %s reason: %d", call.getId(), reason); List dataCollectionTypes = getDataCollectionTypes(reason); boolean invokeTelephonyPersistApi = false; CallEventTimestamps ts = mEmergencyCallsMap.get(call); EmergencyCallDiagnosticData.Builder callDiagnosticBuilder = new EmergencyCallDiagnosticData.Builder(); for (Integer dataCollectionType : dataCollectionTypes) { switch (dataCollectionType) { case COLLECTION_TYPE_TELECOM_STATE: if (isTelecomDumpCollectionEnabled()) { callDiagnosticBuilder.setTelecomDumpsysCollectionEnabled(true); invokeTelephonyPersistApi = true; } break; case COLLECTION_TYPE_TELEPHONY_STATE: if (isTelephonyDumpCollectionEnabled()) { callDiagnosticBuilder.setTelephonyDumpsysCollectionEnabled(true); invokeTelephonyPersistApi = true; } break; case COLLECTION_TYPE_LOGCAT_BUFFERS: if (isLogcatCollectionEnabled()) { callDiagnosticBuilder.setLogcatCollectionStartTimeMillis( ts.getCallCreatedTime()); invokeTelephonyPersistApi = true; } break; case COLLECTION_TYPE_BUGREPORT: if (isBugreportCollectionEnabled()) { mAsyncTaskExecutor.execute(new Runnable() { @Override public void run() { persistBugreport(); } }); } break; default: } } EmergencyCallDiagnosticData ecdData = callDiagnosticBuilder.build(); if (invokeTelephonyPersistApi) { mAsyncTaskExecutor.execute(new Runnable() { @Override public void run() { Log.i(this, "Requesting Telephony to persist data %s", ecdData.toString()); try { mTelephonyManager.persistEmergencyCallDiagnosticData(DROPBOX_TAG, ecdData); } catch (Exception e) { Log.w(this, "Exception while invoking " + "Telephony#persistEmergencyCallDiagnosticData %s", e.toString()); } } }); } } private boolean isBugreportCollectionEnabled() { return DeviceConfig.getBoolean( DeviceConfig.NAMESPACE_TELEPHONY, ENABLE_BUGREPORT_COLLECTION_FOR_EMERGENCY_CALL_DIAGNOSTICS, false); } private boolean isTelecomDumpCollectionEnabled() { return DeviceConfig.getBoolean( DeviceConfig.NAMESPACE_TELEPHONY, ENABLE_TELECOM_DUMP_COLLECTION_FOR_EMERGENCY_CALL_DIAGNOSTICS, true); } private boolean isLogcatCollectionEnabled() { return DeviceConfig.getBoolean( DeviceConfig.NAMESPACE_TELEPHONY, ENABLE_LOGCAT_COLLECTION_FOR_EMERGENCY_CALL_DIAGNOSTICS, true); } private boolean isTelephonyDumpCollectionEnabled() { return DeviceConfig.getBoolean( DeviceConfig.NAMESPACE_TELEPHONY, ENABLE_TELEPHONY_DUMP_COLLECTION_FOR_EMERGENCY_CALL_DIAGNOSTICS, true); } private void persistBugreport() { if (isBugreportCollectionEnabled()) { // TODO: } } private boolean shouldTrackCall(Call call) { return (call != null && call.isEmergencyCall() && call.isOutgoing()); } public void reportStuckCall(Call call) { if (shouldTrackCall(call)) { Log.i(this, "Triggering diagnostics for stuck call %s", call.getId()); triggerDiagnosticsCollection(call, REPORT_REASON_STUCK_CALL_DETECTED); call.removeListener(this); mEmergencyCallsMap.remove(call); } } @Override public void onStartCreateConnection(Call call) { if (shouldTrackCall(call)) { long currentTime = mClockProxy.currentTimeMillis(); call.addListener(this); Log.i(this, "Tracking call %s timestamp: %d", call.getId(), currentTime); mEmergencyCallsMap.put(call, new CallEventTimestamps(currentTime)); } } @Override public void onCreateConnectionFailed(Call call) { if (shouldTrackCall(call)) { Log.i(this, "Triggering diagnostics for call %s that was never added", call.getId()); triggerDiagnosticsCollection(call, REPORT_REASON_CALL_CREATED_BUT_NEVER_ADDED); call.removeListener(this); mEmergencyCallsMap.remove(call); } } /** * Override of {@link CallsManagerListenerBase} to track when calls are removed * * @param call the call */ @Override public void onCallRemoved(Call call) { if (call != null && (mEmergencyCallsMap.get(call) != null)) { call.removeListener(this); CallEventTimestamps ts = mEmergencyCallsMap.get(call); long currentTime = mClockProxy.currentTimeMillis(); ts.setCallRemovedTime(currentTime); maybeTriggerDiagnosticsCollection(call, ts); mEmergencyCallsMap.remove(call); } } // !NOTE!: this method should only be called after we get onCallRemoved private void maybeTriggerDiagnosticsCollection(Call removedCall, CallEventTimestamps ts) { Log.i(this, "Evaluating emergency call for diagnostic logging: %s", removedCall.getId()); boolean wentActive = (ts.getCallActiveTime() != 0); long callActiveTimeSec = (wentActive ? getCallTimeInActiveStateSec(ts) : 0); long timeSinceCallCreatedSec = getTotalCallTimeSec(ts); int dc = removedCall.getDisconnectCause().getCode(); if (wentActive) { if (callActiveTimeSec < mTimeoutAdapter.getEmergencyCallActiveTimeThresholdMillis() / 1000) { // call connected but did not go on for long triggerDiagnosticsCollection( removedCall, REPORT_REASON_SHORT_DURATION_AFTER_GOING_ACTIVE); } } else { if (dc == DisconnectCause.LOCAL && timeSinceCallCreatedSec > mTimeoutAdapter.getEmergencyCallTimeBeforeUserDisconnectThresholdMillis() / 1000) { // call was disconnected by the user (but not immediately) triggerDiagnosticsCollection( removedCall, REPORT_REASON_INACTIVE_CALL_TERMINATED_BY_USER_AFTER_DELAY); } else if (dc != DisconnectCause.LOCAL) { // this can be a case for a full bugreport triggerDiagnosticsCollection(removedCall, REPORT_REASON_CALL_FAILED); } } } /** * Override of {@link com.android.server.telecom.CallsManager.CallsManagerListener} to track * call state changes. * * @param call the call * @param oldState its old state * @param newState the new state */ @Override public void onCallStateChanged(Call call, int oldState, int newState) { CallEventTimestamps ts = mEmergencyCallsMap.get(call); if (call != null && ts != null && newState == CallState.ACTIVE && ts.getCallActiveTime() == 0) { long currentTime = mClockProxy.currentTimeMillis(); ts.setCallActiveTime(currentTime); } } private void dumpDiagnosticDataFromDropbox(IndentingPrintWriter pw) { pw.increaseIndent(); pw.println("PERSISTED DIAGNOSTIC DATA FROM DROP BOX"); int totalEntriesDumped = 0; long currentTime = mClockProxy.currentTimeMillis(); long entriesAfterTime = currentTime - (mTimeoutAdapter.getDaysBackToSearchEmergencyDiagnosticEntries() * 24 * 60L * 60L * 1000L); Log.i(this, "current time: %d entriesafter: %d", currentTime, entriesAfterTime); DropBoxManager.Entry entry; entry = mDropBoxManager.getNextEntry(DROPBOX_TAG, entriesAfterTime); while (entry != null) { Log.i(this, "found entry with ts: %d", entry.getTimeMillis()); String content[] = entry.getText(getMaxBytesPerDropboxEntry()).split( System.lineSeparator()); long entryTime = entry.getTimeMillis(); if (content != null) { pw.increaseIndent(); pw.println("------------BEGIN ENTRY (" + entryTime + ")--------"); for (String line : content) { pw.println(line); } pw.println("--------END ENTRY--------"); pw.decreaseIndent(); totalEntriesDumped++; } entry = mDropBoxManager.getNextEntry(DROPBOX_TAG, entryTime); if (totalEntriesDumped > MAX_DROPBOX_ENTRIES_TO_DUMP) { /* Since Emergency calls are a rare/once in a lifetime time occurrence for most users, we should not be seeing too many entries. This code just guards against edge case like load testing, b2b failures etc. We may accumulate a lot of dropbox entries in such cases, but we limit to dumping only MAX_DROPBOX_ENTRIES_TO_DUMP in the bugreport The Dropbox API in its current state does not allow to query Entries in reverse chronological order efficiently. */ Log.i(this, "Skipping dump for remaining entries. dumped :%d", totalEntriesDumped); break; } } pw.println("END OF PERSISTED DIAGNOSTIC DATA FROM DROP BOX"); pw.decreaseIndent(); } public void dump(IndentingPrintWriter pw, String[] args) { pw.increaseIndent(); mLocalLog.dump(pw); pw.decreaseIndent(); if (args != null && args.length > 0 && args[0].equals(DUMPSYS_ARG_FOR_DIAGNOSTICS)) { //dont read dropbox entries since this dump is triggered by telephony for diagnostics Log.i(this, "skipped dumping diagnostic data"); return; } try { dumpDiagnosticDataFromDropbox(pw); } catch (Exception e) { pw.println("Exception was thrown while dumping diagnostic data from DropBox"); e.printStackTrace(); } } private static class CallEventTimestamps { private final long mCallCreatedTime; private long mCallActiveTime; private long mCallRemovedTime; public CallEventTimestamps(long createdTime) { mCallCreatedTime = createdTime; } public long getCallActiveTime() { return mCallActiveTime; } public void setCallActiveTime(long callActiveTime) { this.mCallActiveTime = callActiveTime; } public long getCallCreatedTime() { return mCallCreatedTime; } public long getCallRemovedTime() { return mCallRemovedTime; } public void setCallRemovedTime(long callRemovedTime) { this.mCallRemovedTime = callRemovedTime; } } }