From 98cf03348ecfbb549b8a51059f9f8688c8c08cbe Mon Sep 17 00:00:00 2001
From: Yohei Yukawa <yukawa@google.com>
Date: Thu, 31 Aug 2017 15:49:15 -0700
Subject: [PATCH] Print correct timeout messages in JobServiceContext

This is a follow up CL to a previous CL [1] that added some useful
debug messages to diagnose issues like Bug 62390590 and another
follow up CL [2] that aimed to address Bug 62787070.

What went wrong is that

  "x" + y != null ? y.toShortString() : "<null>" + "z"

is interpretted as

  ("x" + y) != null ? y.toShortString() : ("<null>" + "z")

while what we wanted to see was

  "x" + (y != null ? y.toShortString() : "<null>") + "z"

This CL addresses the above unexpected string concatenation by
explicitly having a private utility method
JobServiceContext#getRunningJobNameLocked().

 [1]: Ia7155248b4b4f032cbf8e8754c5437f658ed192c
      729a328aca436d71b80f3d72f5d54e38d4d2c12e
 [2]: I7bc55f55da645a9e116d3f0ee02f2ee115383ea9
      62292daa208d007a8c57b073303e8bb6169a2016

Bug: 62787070
Bug: 64569041
Bug: 65188019
Test: Manually verified by explicitly causing timeout.
Change-Id: I3e51f40d3fcf0e2ddd200da2812aba109d89794e
---
 .../android/server/job/JobServiceContext.java | 29 +++++++++++--------
 1 file changed, 17 insertions(+), 12 deletions(-)

diff --git a/services/core/java/com/android/server/job/JobServiceContext.java b/services/core/java/com/android/server/job/JobServiceContext.java
index 031bdd0ee39cc..d3fd3a992a310 100644
--- a/services/core/java/com/android/server/job/JobServiceContext.java
+++ b/services/core/java/com/android/server/job/JobServiceContext.java
@@ -261,6 +261,13 @@ public final class JobServiceContext implements ServiceConnection {
         return mRunningJob;
     }
 
+    /**
+     * Used only for debugging. Will return <code>"&lt;null&gt;"</code> if there is no job running.
+     */
+    private String getRunningJobNameLocked() {
+        return mRunningJob != null ? mRunningJob.toShortString() : "<null>";
+    }
+
     /** Called externally when a job that was scheduled for execution should be cancelled. */
     void cancelExecutingJobLocked(int reason, String debugReason) {
         doCancelLocked(reason, debugReason);
@@ -522,7 +529,7 @@ public final class JobServiceContext implements ServiceConnection {
     /** Start the job on the service. */
     private void handleServiceBoundLocked() {
         if (DEBUG) {
-            Slog.d(TAG, "handleServiceBound for " + mRunningJob.toShortString());
+            Slog.d(TAG, "handleServiceBound for " + getRunningJobNameLocked());
         }
         if (mVerb != VERB_BINDING) {
             Slog.e(TAG, "Sending onStartJob for a job that isn't pending. "
@@ -639,36 +646,34 @@ public final class JobServiceContext implements ServiceConnection {
     private void handleOpTimeoutLocked() {
         switch (mVerb) {
             case VERB_BINDING:
-                Slog.w(TAG, "Time-out while trying to bind " + mRunningJob.toShortString() +
-                        ", dropping.");
+                Slog.w(TAG, "Time-out while trying to bind " + getRunningJobNameLocked()
+                        + ", dropping.");
                 closeAndCleanupJobLocked(false /* needsReschedule */, "timed out while binding");
                 break;
             case VERB_STARTING:
                 // Client unresponsive - wedged or failed to respond in time. We don't really
                 // know what happened so let's log it and notify the JobScheduler
                 // FINISHED/NO-RETRY.
-                Slog.w(TAG, "No response from client for onStartJob " +
-                        mRunningJob != null ? mRunningJob.toShortString() : "<null>");
+                Slog.w(TAG, "No response from client for onStartJob "
+                        + getRunningJobNameLocked());
                 closeAndCleanupJobLocked(false /* needsReschedule */, "timed out while starting");
                 break;
             case VERB_STOPPING:
                 // At least we got somewhere, so fail but ask the JobScheduler to reschedule.
-                Slog.w(TAG, "No response from client for onStopJob " +
-                        mRunningJob != null ? mRunningJob.toShortString() : "<null>");
+                Slog.w(TAG, "No response from client for onStopJob "
+                        + getRunningJobNameLocked());
                 closeAndCleanupJobLocked(true /* needsReschedule */, "timed out while stopping");
                 break;
             case VERB_EXECUTING:
                 // Not an error - client ran out of time.
                 Slog.i(TAG, "Client timed out while executing (no jobFinished received), " +
-                        "sending onStop: "  +
-                        mRunningJob != null ? mRunningJob.toShortString() : "<null>");
+                        "sending onStop: " + getRunningJobNameLocked());
                 mParams.setStopReason(JobParameters.REASON_TIMEOUT);
                 sendStopMessageLocked("timeout while executing");
                 break;
             default:
-                Slog.e(TAG, "Handling timeout for an invalid job state: " +
-                        mRunningJob != null ? mRunningJob.toShortString() : "<null>"
-                        + ", dropping.");
+                Slog.e(TAG, "Handling timeout for an invalid job state: "
+                        + getRunningJobNameLocked() + ", dropping.");
                 closeAndCleanupJobLocked(false /* needsReschedule */, "invalid timeout");
         }
     }