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
      729a328aca
 [2]: I7bc55f55da645a9e116d3f0ee02f2ee115383ea9
      62292daa20

Bug: 62787070
Bug: 64569041
Bug: 65188019
Test: Manually verified by explicitly causing timeout.
Change-Id: I3e51f40d3fcf0e2ddd200da2812aba109d89794e
This commit is contained in:
Yohei Yukawa
2017-08-31 15:49:15 -07:00
parent 01b6ff0178
commit 98cf03348e

View File

@@ -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");
}
}