Add verbose logging that can be eanbled to debug issues.

Test: manual
Change-Id: Ifaeaba404a8fc6a0d68a90f7330982a26a46486c

4 files changed, 119 insertions, 1 deletions

diff --git a/apex/blobstore/service/java/com/android/server/blob/BlobStoreConfig.java b/apex/blobstore/service/java/com/android/server/blob/BlobStoreConfig.java
index 60fa23dec44a..ba2e559afdab 100644
--- a/apex/blobstore/service/java/com/android/server/blob/BlobStoreConfig.java
+++ b/apex/blobstore/service/java/com/android/server/blob/BlobStoreConfig.java
@@ -18,6 +18,7 @@ package com.android.server.blob;
 import android.annotation.NonNull;
 import android.annotation.Nullable;
 import android.os.Environment;
+import android.util.Log;
 import android.util.Slog;
 
 import java.io.File;
@@ -25,6 +26,7 @@ import java.util.concurrent.TimeUnit;
 
 class BlobStoreConfig {
     public static final String TAG = "BlobStore";
+    public static final boolean LOGV = Log.isLoggable(TAG, Log.VERBOSE);
 
     public static final int CURRENT_XML_VERSION = 1;
 
diff --git a/apex/blobstore/service/java/com/android/server/blob/BlobStoreIdleJobService.java b/apex/blobstore/service/java/com/android/server/blob/BlobStoreIdleJobService.java
index 1e2a9640699d..460e776b9ff6 100644
--- a/apex/blobstore/service/java/com/android/server/blob/BlobStoreIdleJobService.java
+++ b/apex/blobstore/service/java/com/android/server/blob/BlobStoreIdleJobService.java
@@ -17,6 +17,8 @@ package com.android.server.blob;
 
 import static com.android.server.blob.BlobStoreConfig.IDLE_JOB_ID;
 import static com.android.server.blob.BlobStoreConfig.IDLE_JOB_PERIOD_MILLIS;
+import static com.android.server.blob.BlobStoreConfig.LOGV;
+import static com.android.server.blob.BlobStoreConfig.TAG;
 
 import android.app.job.JobInfo;
 import android.app.job.JobParameters;
@@ -25,6 +27,7 @@ import android.app.job.JobService;
 import android.content.ComponentName;
 import android.content.Context;
 import android.os.AsyncTask;
+import android.util.Slog;
 
 import com.android.server.LocalServices;
 
@@ -45,6 +48,8 @@ public class BlobStoreIdleJobService extends JobService {
 
     @Override
     public boolean onStopJob(final JobParameters params) {
+        Slog.d(TAG, "Idle maintenance job is stopped; id=" + params.getJobId()
+                + ", reason=" + JobParameters.getReasonCodeDescription(params.getStopReason()));
         return false;
     }
 
@@ -58,5 +63,8 @@ public class BlobStoreIdleJobService extends JobService {
                         .setPeriodic(IDLE_JOB_PERIOD_MILLIS)
                         .build();
         jobScheduler.schedule(job);
+        if (LOGV) {
+            Slog.v(TAG, "Scheduling the idle maintenance job");
+        }
     }
 }
diff --git a/apex/blobstore/service/java/com/android/server/blob/BlobStoreManagerService.java b/apex/blobstore/service/java/com/android/server/blob/BlobStoreManagerService.java
index 775cd04a21df..0ba34cab6560 100644
--- a/apex/blobstore/service/java/com/android/server/blob/BlobStoreManagerService.java
+++ b/apex/blobstore/service/java/com/android/server/blob/BlobStoreManagerService.java
@@ -28,6 +28,7 @@ import static android.content.pm.PackageManager.MATCH_UNINSTALLED_PACKAGES;
 import static android.os.UserHandle.USER_NULL;
 
 import static com.android.server.blob.BlobStoreConfig.CURRENT_XML_VERSION;
+import static com.android.server.blob.BlobStoreConfig.LOGV;
 import static com.android.server.blob.BlobStoreConfig.SESSION_EXPIRY_TIMEOUT_MILLIS;
 import static com.android.server.blob.BlobStoreConfig.TAG;
 import static com.android.server.blob.BlobStoreSession.STATE_ABANDONED;
@@ -96,6 +97,7 @@ import java.io.IOException;
 import java.io.PrintWriter;
 import java.nio.charset.StandardCharsets;
 import java.util.ArrayList;
+import java.util.Arrays;
 import java.util.List;
 import java.util.Objects;
 import java.util.Set;
@@ -268,6 +270,10 @@ public class BlobStoreManagerService extends SystemService {
                     sessionId, blobHandle, callingUid, callingPackage,
                     mSessionStateChangeListener);
             addSessionForUserLocked(session, UserHandle.getUserId(callingUid));
+            if (LOGV) {
+                Slog.v(TAG, "Created session for " + blobHandle
+                        + "; callingUid=" + callingUid + ", callingPackage=" + callingPackage);
+            }
             writeBlobSessionsAsync();
             return sessionId;
         }
@@ -295,7 +301,10 @@ public class BlobStoreManagerService extends SystemService {
                     callingUid, callingPackage);
             session.open();
             session.abandon();
-
+            if (LOGV) {
+                Slog.v(TAG, "Deleted session with id " + sessionId
+                        + "; callingUid=" + callingUid + ", callingPackage=" + callingPackage);
+            }
             writeBlobSessionsAsync();
         }
     }
@@ -330,6 +339,10 @@ public class BlobStoreManagerService extends SystemService {
             }
             blobMetadata.addLeasee(callingPackage, callingUid,
                     descriptionResId, leaseExpiryTimeMillis);
+            if (LOGV) {
+                Slog.v(TAG, "Acquired lease on " + blobHandle
+                        + "; callingUid=" + callingUid + ", callingPackage=" + callingPackage);
+            }
             writeBlobsInfoAsync();
         }
     }
@@ -345,6 +358,10 @@ public class BlobStoreManagerService extends SystemService {
                         + "; callingUid=" + callingUid + ", callingPackage=" + callingPackage);
             }
             blobMetadata.removeLeasee(callingPackage, callingUid);
+            if (LOGV) {
+                Slog.v(TAG, "Released lease on " + blobHandle
+                        + "; callingUid=" + callingUid + ", callingPackage=" + callingPackage);
+            }
             writeBlobsInfoAsync();
         }
     }
@@ -374,6 +391,9 @@ public class BlobStoreManagerService extends SystemService {
                     getUserSessionsLocked(UserHandle.getUserId(session.getOwnerUid()))
                             .remove(session.getSessionId());
                     mKnownBlobIds.remove(session.getSessionId());
+                    if (LOGV) {
+                        Slog.v(TAG, "Session is invalid; deleted " + session);
+                    }
                     break;
                 case STATE_COMMITTED:
                     session.verifyBlobData();
@@ -400,6 +420,9 @@ public class BlobStoreManagerService extends SystemService {
                     }
                     getUserSessionsLocked(UserHandle.getUserId(session.getOwnerUid()))
                             .remove(session.getSessionId());
+                    if (LOGV) {
+                        Slog.v(TAG, "Successfully committed session " + session);
+                    }
                     break;
                 default:
                     Slog.wtf(TAG, "Invalid session state: "
@@ -442,6 +465,9 @@ public class BlobStoreManagerService extends SystemService {
             out.endTag(null, TAG_SESSIONS);
             out.endDocument();
             sessionsIndexFile.finishWrite(fos);
+            if (LOGV) {
+                Slog.v(TAG, "Finished persisting sessions data");
+            }
         } catch (Exception e) {
             sessionsIndexFile.failWrite(fos);
             Slog.wtf(TAG, "Error writing sessions data", e);
@@ -491,6 +517,9 @@ public class BlobStoreManagerService extends SystemService {
                     mCurrentMaxSessionId = Math.max(mCurrentMaxSessionId, session.getSessionId());
                 }
             }
+            if (LOGV) {
+                Slog.v(TAG, "Finished reading sessions data");
+            }
         } catch (Exception e) {
             Slog.wtf(TAG, "Error reading sessions data", e);
         }
@@ -524,6 +553,9 @@ public class BlobStoreManagerService extends SystemService {
             out.endTag(null, TAG_BLOBS);
             out.endDocument();
             blobsIndexFile.finishWrite(fos);
+            if (LOGV) {
+                Slog.v(TAG, "Finished persisting blobs data");
+            }
         } catch (Exception e) {
             blobsIndexFile.failWrite(fos);
             Slog.wtf(TAG, "Error writing blobs data", e);
@@ -567,6 +599,9 @@ public class BlobStoreManagerService extends SystemService {
                     mCurrentMaxSessionId = Math.max(mCurrentMaxSessionId, blobMetadata.getBlobId());
                 }
             }
+            if (LOGV) {
+                Slog.v(TAG, "Finished reading blobs data");
+            }
         } catch (Exception e) {
             Slog.wtf(TAG, "Error reading blobs data", e);
         }
@@ -687,6 +722,10 @@ public class BlobStoreManagerService extends SystemService {
                 userBlobs.removeAt(indicesToRemove.get(i));
             }
             writeBlobsInfoAsync();
+            if (LOGV) {
+                Slog.v(TAG, "Removed blobs data associated with pkg="
+                        + packageName + ", uid=" + uid);
+            }
         }
     }
 
@@ -711,6 +750,9 @@ public class BlobStoreManagerService extends SystemService {
                     mKnownBlobIds.remove(blobMetadata.getBlobId());
                 }
             }
+            if (LOGV) {
+                Slog.v(TAG, "Removed blobs data in user " + userId);
+            }
         }
     }
 
@@ -718,6 +760,7 @@ public class BlobStoreManagerService extends SystemService {
     @VisibleForTesting
     void handleIdleMaintenanceLocked() {
         // Cleanup any left over data on disk that is not part of index.
+        final ArrayList<Long> deletedBlobIds = new ArrayList<>();
         final ArrayList<File> filesToDelete = new ArrayList<>();
         final File blobsDir = BlobStoreConfig.getBlobsDir();
         if (blobsDir.exists()) {
@@ -726,8 +769,10 @@ public class BlobStoreManagerService extends SystemService {
                     final long id = Long.parseLong(file.getName());
                     if (mKnownBlobIds.indexOf(id) < 0) {
                         filesToDelete.add(file);
+                        deletedBlobIds.add(id);
                     }
                 } catch (NumberFormatException e) {
+                    Slog.wtf(TAG, "Error parsing the file name: " + file, e);
                     filesToDelete.add(file);
                 }
             }
@@ -758,6 +803,7 @@ public class BlobStoreManagerService extends SystemService {
                 if (shouldRemove) {
                     blobMetadata.getBlobFile().delete();
                     mKnownBlobIds.remove(blobMetadata.getBlobId());
+                    deletedBlobIds.add(blobMetadata.getBlobId());
                 }
                 return shouldRemove;
             });
@@ -788,12 +834,17 @@ public class BlobStoreManagerService extends SystemService {
                     blobStoreSession.getSessionFile().delete();
                     mKnownBlobIds.remove(blobStoreSession.getSessionId());
                     indicesToRemove.add(j);
+                    deletedBlobIds.add(blobStoreSession.getSessionId());
                 }
             }
             for (int j = 0; j < indicesToRemove.size(); ++j) {
                 userSessions.removeAt(indicesToRemove.get(j));
             }
         }
+        if (LOGV) {
+            Slog.v(TAG, "Completed idle maintenance; deleted "
+                    + Arrays.toString(deletedBlobIds.toArray()));
+        }
         writeBlobSessionsAsync();
     }
 
@@ -874,6 +925,9 @@ public class BlobStoreManagerService extends SystemService {
     private class PackageChangedReceiver extends BroadcastReceiver {
         @Override
         public void onReceive(Context context, Intent intent) {
+            if (LOGV) {
+                Slog.v(TAG, "Received " + intent);
+            }
             switch (intent.getAction()) {
                 case Intent.ACTION_PACKAGE_FULLY_REMOVED:
                 case Intent.ACTION_PACKAGE_DATA_CLEARED:
@@ -1025,6 +1079,14 @@ public class BlobStoreManagerService extends SystemService {
             final DumpArgs dumpArgs = DumpArgs.parse(args);
 
             final IndentingPrintWriter fout = new IndentingPrintWriter(writer, "    ");
+            if (dumpArgs.shouldDumpHelp()) {
+                writer.println("dumpsys blob_store [options]:");
+                fout.increaseIndent();
+                dumpArgs.dumpArgsUsage(fout);
+                fout.decreaseIndent();
+                return;
+            }
+
             synchronized (mBlobsLock) {
                 fout.println("mCurrentMaxSessionId: " + mCurrentMaxSessionId);
                 fout.println();
@@ -1058,6 +1120,7 @@ public class BlobStoreManagerService extends SystemService {
         private boolean mDumpOnlySelectedSections;
         private boolean mDumpSessions;
         private boolean mDumpBlobs;
+        private boolean mDumpHelp;
 
         public boolean shouldDumpSession(String packageName, int uid, long blobId) {
             if (!CollectionUtils.isEmpty(mDumpPackages)
@@ -1103,6 +1166,10 @@ public class BlobStoreManagerService extends SystemService {
                     || mDumpUserIds.indexOf(userId) >= 0;
         }
 
+        public boolean shouldDumpHelp() {
+            return mDumpHelp;
+        }
+
         private DumpArgs() {}
 
         public static DumpArgs parse(String[] args) {
@@ -1132,6 +1199,8 @@ public class BlobStoreManagerService extends SystemService {
                     dumpArgs.mDumpUserIds.add(getIntArgRequired(args, ++i, "userId"));
                 } else if ("--blob".equals(opt) || "-b".equals(opt)) {
                     dumpArgs.mDumpBlobIds.add(getLongArgRequired(args, ++i, "blobId"));
+                } else if ("--help".equals(opt) || "-h".equals(opt)) {
+                    dumpArgs.mDumpHelp = true;
                 } else {
                     // Everything else is assumed to be blob ids.
                     dumpArgs.mDumpBlobIds.add(getLongArgRequired(args, i, "blobId"));
@@ -1172,6 +1241,31 @@ public class BlobStoreManagerService extends SystemService {
             }
             return value;
         }
+
+        private void dumpArgsUsage(IndentingPrintWriter pw) {
+            pw.println("--help | -h");
+            printWithIndent(pw, "Dump this help text");
+            pw.println("--sessions");
+            printWithIndent(pw, "Dump only the sessions info");
+            pw.println("--blobs");
+            printWithIndent(pw, "Dump only the committed blobs info");
+            pw.println("--package | -p [package-name]");
+            printWithIndent(pw, "Dump blobs info associated with the given package");
+            pw.println("--uid | -u [uid]");
+            printWithIndent(pw, "Dump blobs info associated with the given uid");
+            pw.println("--user [user-id]");
+            printWithIndent(pw, "Dump blobs info in the given user");
+            pw.println("--blob | -b [session-id | blob-id]");
+            printWithIndent(pw, "Dump blob info corresponding to the given ID");
+            pw.println("--full | -f");
+            printWithIndent(pw, "Dump full unredacted blobs data");
+        }
+
+        private void printWithIndent(IndentingPrintWriter pw, String str) {
+            pw.increaseIndent();
+            pw.println(str);
+            pw.decreaseIndent();
+        }
     }
 
     private class LocalService extends BlobStoreManagerInternal {
diff --git a/apex/blobstore/service/java/com/android/server/blob/BlobStoreSession.java b/apex/blobstore/service/java/com/android/server/blob/BlobStoreSession.java
index 54a299722754..f37094d77d12 100644
--- a/apex/blobstore/service/java/com/android/server/blob/BlobStoreSession.java
+++ b/apex/blobstore/service/java/com/android/server/blob/BlobStoreSession.java
@@ -26,6 +26,7 @@ import static android.system.OsConstants.O_RDONLY;
 import static android.system.OsConstants.O_RDWR;
 import static android.system.OsConstants.SEEK_SET;
 
+import static com.android.server.blob.BlobStoreConfig.LOGV;
 import static com.android.server.blob.BlobStoreConfig.TAG;
 
 import android.annotation.BytesLong;
@@ -390,6 +391,9 @@ class BlobStoreSession extends IBlobStoreSession.Stub {
                 mState = STATE_VERIFIED_VALID;
                 // Commit callback will be sent once the data is persisted.
             } else {
+                if (LOGV) {
+                    Slog.v(TAG, "Digest of the data didn't match the given BlobHandle.digest");
+                }
                 mState = STATE_VERIFIED_INVALID;
                 sendCommitCallbackResult(COMMIT_RESULT_ERROR);
             }
@@ -447,6 +451,16 @@ class BlobStoreSession extends IBlobStoreSession.Stub {
         }
     }
 
+    @Override
+    public String toString() {
+        return "BlobStoreSession {"
+                + "id:" + mSessionId
+                + ",handle:" + mBlobHandle
+                + ",uid:" + mOwnerUid
+                + ",pkg:" + mOwnerPackageName
+                + "}";
+    }
+
     private void assertCallerIsOwner() {
         final int callingUid = Binder.getCallingUid();
         if (callingUid != mOwnerUid) {