Lazely initialize AccountManager debug table.

Prevent crash if the database cannot be opened.
Guard not thread safe SQLiteStatement.

Change-Id: I2af9074e50bddc5a1d18ea781cc6f56934f21302
Test: atest com.android.server.accounts
Bug: 31708085
diff --git a/services/core/java/com/android/server/accounts/AccountManagerService.java b/services/core/java/com/android/server/accounts/AccountManagerService.java
index 9c60b8c..e879efd 100644
--- a/services/core/java/com/android/server/accounts/AccountManagerService.java
+++ b/services/core/java/com/android/server/accounts/AccountManagerService.java
@@ -241,9 +241,6 @@
         private final HashMap<Account, AtomicReference<String>> previousNameCache =
                 new HashMap<Account, AtomicReference<String>>();
 
-        private int debugDbInsertionPoint = -1;
-        private SQLiteStatement statementForLogging; // TODO Move to AccountsDb
-
         UserAccounts(Context context, int userId, File preNDbFile, File deDbFile) {
             this.userId = userId;
             synchronized (dbLock) {
@@ -1299,7 +1296,6 @@
                 File preNDbFile = new File(mInjector.getPreNDatabaseName(userId));
                 File deDbFile = new File(mInjector.getDeDatabaseName(userId));
                 accounts = new UserAccounts(mContext, userId, preNDbFile, deDbFile);
-                initializeDebugDbSizeAndCompileSqlStatementForLogging(accounts);
                 mUsers.append(userId, accounts);
                 purgeOldGrants(accounts);
                 validateAccounts = true;
@@ -1400,7 +1396,7 @@
         if (accounts != null) {
             synchronized (accounts.dbLock) {
                 synchronized (accounts.cacheLock) {
-                    accounts.statementForLogging.close();
+                    accounts.accountsDb.closeDebugStatement();
                     accounts.accountsDb.close();
                 }
             }
@@ -5124,41 +5120,36 @@
 
             @Override
             public void run() {
-                SQLiteStatement logStatement = userAccount.statementForLogging;
-                logStatement.bindLong(1, accountId);
-                logStatement.bindString(2, action);
-                logStatement.bindString(3, mDateFormat.format(new Date()));
-                logStatement.bindLong(4, callingUid);
-                logStatement.bindString(5, tableName);
-                logStatement.bindLong(6, userDebugDbInsertionPoint);
-                try {
-                    logStatement.execute();
-                } catch (IllegalStateException e) {
-                    // Guard against crash, DB can already be closed
-                    // since this statement is executed on a handler thread
-                    Slog.w(TAG, "Failed to insert a log record. accountId=" + accountId
-                            + " action=" + action + " tableName=" + tableName + " Error: " + e);
-                } finally {
-                    logStatement.clearBindings();
+                synchronized (userAccount.accountsDb.mDebugStatementLock) {
+                    SQLiteStatement logStatement = userAccount.accountsDb.getStatementForLogging();
+                    if (logStatement == null) {
+                        return; // Can't log.
+                    }
+                    logStatement.bindLong(1, accountId);
+                    logStatement.bindString(2, action);
+                    logStatement.bindString(3, mDateFormat.format(new Date()));
+                    logStatement.bindLong(4, callingUid);
+                    logStatement.bindString(5, tableName);
+                    logStatement.bindLong(6, userDebugDbInsertionPoint);
+                    try {
+                        logStatement.execute();
+                    } catch (IllegalStateException e) {
+                        // Guard against crash, DB can already be closed
+                        // since this statement is executed on a handler thread
+                        Slog.w(TAG, "Failed to insert a log record. accountId=" + accountId
+                                + " action=" + action + " tableName=" + tableName + " Error: " + e);
+                    } finally {
+                        logStatement.clearBindings();
+                    }
                 }
             }
         }
-
-        LogRecordTask logTask = new LogRecordTask(action, tableName, accountId, userAccount,
-                callingUid, userAccount.debugDbInsertionPoint);
-        userAccount.debugDbInsertionPoint = (userAccount.debugDbInsertionPoint + 1)
-                % AccountsDb.MAX_DEBUG_DB_SIZE;
-        mHandler.post(logTask);
-    }
-
-    /*
-     * This should only be called once to compile the sql statement for logging
-     * and to find the insertion point.
-     */
-    private void initializeDebugDbSizeAndCompileSqlStatementForLogging(UserAccounts userAccount) {
-        userAccount.debugDbInsertionPoint = userAccount.accountsDb
-                .calculateDebugTableInsertionPoint();
-        userAccount.statementForLogging = userAccount.accountsDb.compileSqlStatementForLogging();
+        long insertionPoint = userAccount.accountsDb.reserveDebugDbInsertionPoint();
+        if (insertionPoint != -1) {
+            LogRecordTask logTask = new LogRecordTask(action, tableName, accountId, userAccount,
+                    callingUid, insertionPoint);
+            mHandler.post(logTask);
+        }
     }
 
     public IBinder onBind(@SuppressWarnings("unused") Intent intent) {
diff --git a/services/core/java/com/android/server/accounts/AccountsDb.java b/services/core/java/com/android/server/accounts/AccountsDb.java
index 0c3d268..712edcc 100644
--- a/services/core/java/com/android/server/accounts/AccountsDb.java
+++ b/services/core/java/com/android/server/accounts/AccountsDb.java
@@ -17,11 +17,13 @@
 package com.android.server.accounts;
 
 import android.accounts.Account;
+import android.annotation.Nullable;
 import android.content.ContentValues;
 import android.content.Context;
 import android.database.Cursor;
 import android.database.DatabaseUtils;
 import android.database.sqlite.SQLiteDatabase;
+import android.database.sqlite.SQLiteException;
 import android.database.sqlite.SQLiteOpenHelper;
 import android.database.sqlite.SQLiteStatement;
 import android.os.FileUtils;
@@ -183,6 +185,10 @@
     private final Context mContext;
     private final File mPreNDatabaseFile;
 
+    final Object mDebugStatementLock = new Object();
+    private volatile long mDebugDbInsertionPoint = -1;
+    private volatile SQLiteStatement mDebugStatementForLogging; // not thread safe.
+
     AccountsDb(DeDatabaseHelper deDatabase, Context context, File preNDatabaseFile) {
         mDeDatabase = deDatabase;
         mContext = context;
@@ -1278,31 +1284,72 @@
      * Finds the row key where the next insertion should take place. Returns number of rows
      * if it is less {@link #MAX_DEBUG_DB_SIZE}, otherwise finds the lowest number available.
      */
-    int calculateDebugTableInsertionPoint() {
-        SQLiteDatabase db = mDeDatabase.getReadableDatabase();
-        String queryCountDebugDbRows = "SELECT COUNT(*) FROM " + TABLE_DEBUG;
-        int size = (int) DatabaseUtils.longForQuery(db, queryCountDebugDbRows, null);
-        if (size < MAX_DEBUG_DB_SIZE) {
-            return size;
-        }
+    long calculateDebugTableInsertionPoint() {
+        try {
+            SQLiteDatabase db = mDeDatabase.getReadableDatabase();
+            String queryCountDebugDbRows = "SELECT COUNT(*) FROM " + TABLE_DEBUG;
+            int size = (int) DatabaseUtils.longForQuery(db, queryCountDebugDbRows, null);
+            if (size < MAX_DEBUG_DB_SIZE) {
+                return size;
+            }
 
-        // This query finds the smallest timestamp value (and if 2 records have
-        // same timestamp, the choose the lower id).
-        queryCountDebugDbRows = "SELECT " + DEBUG_TABLE_KEY +
-                " FROM " + TABLE_DEBUG +
-                " ORDER BY "  + DEBUG_TABLE_TIMESTAMP + "," + DEBUG_TABLE_KEY +
-                " LIMIT 1";
-        return (int) DatabaseUtils.longForQuery(db, queryCountDebugDbRows, null);
+            // This query finds the smallest timestamp value (and if 2 records have
+            // same timestamp, the choose the lower id).
+            queryCountDebugDbRows =
+                    "SELECT " + DEBUG_TABLE_KEY
+                    + " FROM " + TABLE_DEBUG
+                    + " ORDER BY "  + DEBUG_TABLE_TIMESTAMP + ","
+                    + DEBUG_TABLE_KEY
+                    + " LIMIT 1";
+            return DatabaseUtils.longForQuery(db, queryCountDebugDbRows, null);
+        } catch (SQLiteException e) {
+            Log.e(TAG, "Failed to open debug table" + e);
+            return -1;
+        }
     }
 
     SQLiteStatement compileSqlStatementForLogging() {
-        // TODO b/31708085 Fix debug logging - it eagerly opens database for write without a need
         SQLiteDatabase db = mDeDatabase.getWritableDatabase();
         String sql = "INSERT OR REPLACE INTO " + AccountsDb.TABLE_DEBUG
                 + " VALUES (?,?,?,?,?,?)";
         return db.compileStatement(sql);
     }
 
+    /**
+     * Returns statement for logging or {@code null} on database open failure.
+     * Returned value must be guarded by {link #debugStatementLock}
+     */
+    @Nullable SQLiteStatement getStatementForLogging() {
+        if (mDebugStatementForLogging != null) {
+            return mDebugStatementForLogging;
+        }
+        try {
+            mDebugStatementForLogging =  compileSqlStatementForLogging();
+            return mDebugStatementForLogging;
+        } catch (SQLiteException e) {
+            Log.e(TAG, "Failed to open debug table" + e);
+            return null;
+        }
+    }
+
+    void closeDebugStatement() {
+        synchronized (mDebugStatementLock) {
+            if (mDebugStatementForLogging != null) {
+                mDebugStatementForLogging.close();
+                mDebugStatementForLogging = null;
+            }
+        }
+    }
+
+    long reserveDebugDbInsertionPoint() {
+        if (mDebugDbInsertionPoint == -1) {
+            mDebugDbInsertionPoint = calculateDebugTableInsertionPoint();
+            return mDebugDbInsertionPoint;
+        }
+        mDebugDbInsertionPoint = (mDebugDbInsertionPoint + 1) % MAX_DEBUG_DB_SIZE;
+        return mDebugDbInsertionPoint;
+    }
+
     void dumpDebugTable(PrintWriter pw) {
         SQLiteDatabase db = mDeDatabase.getReadableDatabase();
         Cursor cursor = db.query(TABLE_DEBUG, null,
diff --git a/services/tests/servicestests/src/com/android/server/accounts/AccountsDbTest.java b/services/tests/servicestests/src/com/android/server/accounts/AccountsDbTest.java
index 72c22fd..29a920a 100644
--- a/services/tests/servicestests/src/com/android/server/accounts/AccountsDbTest.java
+++ b/services/tests/servicestests/src/com/android/server/accounts/AccountsDbTest.java
@@ -22,9 +22,14 @@
 import static org.junit.Assert.assertNull;
 import static org.junit.Assert.assertTrue;
 
+import static org.mockito.Matchers.anyString;
+import static org.mockito.Mockito.times;
+import static org.mockito.Mockito.verify;
+
 import android.accounts.Account;
 import android.content.Context;
 import android.database.Cursor;
+import android.database.sqlite.SQLiteStatement;
 import android.os.Build;
 import android.test.suitebuilder.annotation.SmallTest;
 import android.util.Pair;
@@ -37,7 +42,11 @@
 import org.junit.Test;
 import org.junit.runner.RunWith;
 
+import org.mockito.Mock;
+import org.mockito.MockitoAnnotations;
+
 import java.io.File;
+import java.io.PrintWriter;
 import java.util.Arrays;
 import java.util.List;
 import java.util.Map;
@@ -64,8 +73,11 @@
     private File deDb;
     private File ceDb;
 
+    @Mock private PrintWriter mockWriter;
+
     @Before
     public void setUp() {
+        MockitoAnnotations.initMocks(this);
         Context context = InstrumentationRegistry.getContext();
         preNDb = new File(context.getCacheDir(), PREN_DB);
         ceDb = new File(context.getCacheDir(), CE_DB);
@@ -444,4 +456,33 @@
         assertTrue(mAccountsDb.deleteDeAccount(accId)); // Trigger should remove visibility.
         assertNull(mAccountsDb.findAccountVisibility(account, packageName1));
     }
+
+    @Test
+    public void testDumpDebugTable() {
+        long accId = 10;
+        long insertionPoint = mAccountsDb.reserveDebugDbInsertionPoint();
+
+        SQLiteStatement logStatement = mAccountsDb.getStatementForLogging();
+
+        logStatement.bindLong(1, accId);
+        logStatement.bindString(2, "action");
+        logStatement.bindString(3, "date");
+        logStatement.bindLong(4, 10);
+        logStatement.bindString(5, "table");
+        logStatement.bindLong(6, insertionPoint);
+        logStatement.execute();
+
+        mAccountsDb.dumpDebugTable(mockWriter);
+
+        verify(mockWriter, times(3)).println(anyString());
+    }
+
+    @Test
+    public void testReserveDebugDbInsertionPoint() {
+        long insertionPoint = mAccountsDb.reserveDebugDbInsertionPoint();
+        long insertionPoint2 = mAccountsDb.reserveDebugDbInsertionPoint();
+
+        assertEquals(0, insertionPoint);
+        assertEquals(1, insertionPoint2);
+    }
 }