1 /* 2 * Copyright (C) 2014 The Android Open Source Project 3 * 4 * Licensed under the Apache License, Version 2.0 (the "License"); 5 * you may not use this file except in compliance with the License. 6 * You may obtain a copy of the License at 7 * 8 * http://www.apache.org/licenses/LICENSE-2.0 9 * 10 * Unless required by applicable law or agreed to in writing, software 11 * distributed under the License is distributed on an "AS IS" BASIS, 12 * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. 13 * See the License for the specific language governing permissions and 14 * limitations under the License 15 */ 16 17 package com.android.server.job; 18 19 import static android.app.job.JobInfo.getPriorityString; 20 21 import static com.android.server.job.JobConcurrencyManager.WORK_TYPE_NONE; 22 import static com.android.server.job.JobSchedulerService.sElapsedRealtimeClock; 23 24 import android.annotation.NonNull; 25 import android.annotation.Nullable; 26 import android.app.job.IJobCallback; 27 import android.app.job.IJobService; 28 import android.app.job.JobInfo; 29 import android.app.job.JobParameters; 30 import android.app.job.JobProtoEnums; 31 import android.app.job.JobWorkItem; 32 import android.app.usage.UsageStatsManagerInternal; 33 import android.content.ComponentName; 34 import android.content.Context; 35 import android.content.Intent; 36 import android.content.ServiceConnection; 37 import android.net.Uri; 38 import android.os.Binder; 39 import android.os.Build; 40 import android.os.Handler; 41 import android.os.IBinder; 42 import android.os.Looper; 43 import android.os.Message; 44 import android.os.PowerManager; 45 import android.os.RemoteException; 46 import android.os.Trace; 47 import android.os.UserHandle; 48 import android.util.EventLog; 49 import android.util.IndentingPrintWriter; 50 import android.util.Slog; 51 import android.util.TimeUtils; 52 53 import com.android.internal.annotations.GuardedBy; 54 import com.android.internal.annotations.VisibleForTesting; 55 import com.android.internal.app.IBatteryStats; 56 import com.android.internal.util.FrameworkStatsLog; 57 import com.android.server.EventLogTags; 58 import com.android.server.LocalServices; 59 import com.android.server.job.controllers.JobStatus; 60 import com.android.server.tare.EconomicPolicy; 61 import com.android.server.tare.EconomyManagerInternal; 62 import com.android.server.tare.JobSchedulerEconomicPolicy; 63 64 /** 65 * Handles client binding and lifecycle of a job. Jobs execute one at a time on an instance of this 66 * class. 67 * 68 * There are two important interactions into this class from the 69 * {@link com.android.server.job.JobSchedulerService}. To execute a job and to cancel a job. 70 * - Execution of a new job is handled by the {@link #mAvailable}. This bit is flipped once when a 71 * job lands, and again when it is complete. 72 * - Cancelling is trickier, because there are also interactions from the client. It's possible 73 * the {@link com.android.server.job.JobServiceContext.JobServiceHandler} tries to process a 74 * {@link #doCancelLocked} after the client has already finished. This is handled by having 75 * {@link com.android.server.job.JobServiceContext.JobServiceHandler#handleCancelLocked} check whether 76 * the context is still valid. 77 * To mitigate this, we avoid sending duplicate onStopJob() 78 * calls to the client after they've specified jobFinished(). 79 */ 80 public final class JobServiceContext implements ServiceConnection { 81 private static final boolean DEBUG = JobSchedulerService.DEBUG; 82 private static final boolean DEBUG_STANDBY = JobSchedulerService.DEBUG_STANDBY; 83 84 private static final String TAG = "JobServiceContext"; 85 /** Amount of time the JobScheduler waits for the initial service launch+bind. */ 86 private static final long OP_BIND_TIMEOUT_MILLIS = 18 * 1000 * Build.HW_TIMEOUT_MULTIPLIER; 87 /** Amount of time the JobScheduler will wait for a response from an app for a message. */ 88 private static final long OP_TIMEOUT_MILLIS = 8 * 1000 * Build.HW_TIMEOUT_MULTIPLIER; 89 90 private static final String[] VERB_STRINGS = { 91 "VERB_BINDING", "VERB_STARTING", "VERB_EXECUTING", "VERB_STOPPING", "VERB_FINISHED" 92 }; 93 94 // States that a job occupies while interacting with the client. 95 static final int VERB_BINDING = 0; 96 static final int VERB_STARTING = 1; 97 static final int VERB_EXECUTING = 2; 98 static final int VERB_STOPPING = 3; 99 static final int VERB_FINISHED = 4; 100 101 // Messages that result from interactions with the client service. 102 /** System timed out waiting for a response. */ 103 private static final int MSG_TIMEOUT = 0; 104 105 public static final int NO_PREFERRED_UID = -1; 106 107 private final Handler mCallbackHandler; 108 /** Make callbacks to {@link JobSchedulerService} to inform on job completion status. */ 109 private final JobCompletedListener mCompletedListener; 110 private final JobConcurrencyManager mJobConcurrencyManager; 111 private final JobSchedulerService mService; 112 /** Used for service binding, etc. */ 113 private final Context mContext; 114 private final Object mLock; 115 private final IBatteryStats mBatteryStats; 116 private final EconomyManagerInternal mEconomyManagerInternal; 117 private final JobPackageTracker mJobPackageTracker; 118 private final PowerManager mPowerManager; 119 private PowerManager.WakeLock mWakeLock; 120 121 // Execution state. 122 private JobParameters mParams; 123 @VisibleForTesting 124 int mVerb; 125 private boolean mCancelled; 126 /** 127 * True if the previous job on this context successfully finished (ie. called jobFinished or 128 * dequeueWork with no work left). 129 */ 130 private boolean mPreviousJobHadSuccessfulFinish; 131 /** 132 * The last time a job on this context didn't finish successfully, in the elapsed realtime 133 * timebase. 134 */ 135 private long mLastUnsuccessfulFinishElapsed; 136 137 /** 138 * All the information maintained about the job currently being executed. 139 * 140 * Any reads (dereferences) not done from the handler thread must be synchronized on 141 * {@link #mLock}. 142 * Writes can only be done from the handler thread, 143 * or {@link #executeRunnableJob(JobStatus, int)}. 144 */ 145 private JobStatus mRunningJob; 146 @JobConcurrencyManager.WorkType 147 private int mRunningJobWorkType; 148 private JobCallback mRunningCallback; 149 /** Used to store next job to run when current job is to be preempted. */ 150 private int mPreferredUid; 151 IJobService service; 152 153 /** 154 * Whether this context is free. This is set to false at the start of execution, and reset to 155 * true when execution is complete. 156 */ 157 @GuardedBy("mLock") 158 private boolean mAvailable; 159 /** Track start time. */ 160 private long mExecutionStartTimeElapsed; 161 /** Track when job will timeout. */ 162 private long mTimeoutElapsed; 163 /** 164 * The minimum amount of time the context will allow the job to run before checking whether to 165 * stop it or not. 166 */ 167 private long mMinExecutionGuaranteeMillis; 168 /** The absolute maximum amount of time the job can run */ 169 private long mMaxExecutionTimeMillis; 170 171 /** 172 * The stop reason for a pending cancel. If there's not pending cancel, then the value should be 173 * {@link JobParameters#STOP_REASON_UNDEFINED}. 174 */ 175 private int mPendingStopReason = JobParameters.STOP_REASON_UNDEFINED; 176 private int mPendingInternalStopReason; 177 private String mPendingDebugStopReason; 178 179 // Debugging: reason this job was last stopped. 180 public String mStoppedReason; 181 182 // Debugging: time this job was last stopped. 183 public long mStoppedTime; 184 185 final class JobCallback extends IJobCallback.Stub { 186 public String mStoppedReason; 187 public long mStoppedTime; 188 189 @Override acknowledgeStartMessage(int jobId, boolean ongoing)190 public void acknowledgeStartMessage(int jobId, boolean ongoing) { 191 doAcknowledgeStartMessage(this, jobId, ongoing); 192 } 193 194 @Override acknowledgeStopMessage(int jobId, boolean reschedule)195 public void acknowledgeStopMessage(int jobId, boolean reschedule) { 196 doAcknowledgeStopMessage(this, jobId, reschedule); 197 } 198 199 @Override dequeueWork(int jobId)200 public JobWorkItem dequeueWork(int jobId) { 201 return doDequeueWork(this, jobId); 202 } 203 204 @Override completeWork(int jobId, int workId)205 public boolean completeWork(int jobId, int workId) { 206 return doCompleteWork(this, jobId, workId); 207 } 208 209 @Override jobFinished(int jobId, boolean reschedule)210 public void jobFinished(int jobId, boolean reschedule) { 211 doJobFinished(this, jobId, reschedule); 212 } 213 } 214 JobServiceContext(JobSchedulerService service, JobConcurrencyManager concurrencyManager, IBatteryStats batteryStats, JobPackageTracker tracker, Looper looper)215 JobServiceContext(JobSchedulerService service, JobConcurrencyManager concurrencyManager, 216 IBatteryStats batteryStats, JobPackageTracker tracker, Looper looper) { 217 mContext = service.getContext(); 218 mLock = service.getLock(); 219 mService = service; 220 mBatteryStats = batteryStats; 221 mEconomyManagerInternal = LocalServices.getService(EconomyManagerInternal.class); 222 mJobPackageTracker = tracker; 223 mCallbackHandler = new JobServiceHandler(looper); 224 mJobConcurrencyManager = concurrencyManager; 225 mCompletedListener = service; 226 mPowerManager = mContext.getSystemService(PowerManager.class); 227 mAvailable = true; 228 mVerb = VERB_FINISHED; 229 mPreferredUid = NO_PREFERRED_UID; 230 } 231 232 /** 233 * Give a job to this context for execution. Callers must first check {@link 234 * #getRunningJobLocked()} 235 * and ensure it is null to make sure this is a valid context. 236 * 237 * @param job The status of the job that we are going to run. 238 * @return True if the job is valid and is running. False if the job cannot be executed. 239 */ executeRunnableJob(JobStatus job, @JobConcurrencyManager.WorkType int workType)240 boolean executeRunnableJob(JobStatus job, @JobConcurrencyManager.WorkType int workType) { 241 synchronized (mLock) { 242 if (!mAvailable) { 243 Slog.e(TAG, "Starting new runnable but context is unavailable > Error."); 244 return false; 245 } 246 247 mPreferredUid = NO_PREFERRED_UID; 248 249 mRunningJob = job; 250 mRunningJobWorkType = workType; 251 mRunningCallback = new JobCallback(); 252 final boolean isDeadlineExpired = 253 job.hasDeadlineConstraint() && 254 (job.getLatestRunTimeElapsed() < sElapsedRealtimeClock.millis()); 255 Uri[] triggeredUris = null; 256 if (job.changedUris != null) { 257 triggeredUris = new Uri[job.changedUris.size()]; 258 job.changedUris.toArray(triggeredUris); 259 } 260 String[] triggeredAuthorities = null; 261 if (job.changedAuthorities != null) { 262 triggeredAuthorities = new String[job.changedAuthorities.size()]; 263 job.changedAuthorities.toArray(triggeredAuthorities); 264 } 265 final JobInfo ji = job.getJob(); 266 mParams = new JobParameters(mRunningCallback, job.getJobId(), ji.getExtras(), 267 ji.getTransientExtras(), ji.getClipData(), ji.getClipGrantFlags(), 268 isDeadlineExpired, job.shouldTreatAsExpeditedJob(), 269 triggeredUris, triggeredAuthorities, job.network); 270 mExecutionStartTimeElapsed = sElapsedRealtimeClock.millis(); 271 mMinExecutionGuaranteeMillis = mService.getMinJobExecutionGuaranteeMs(job); 272 mMaxExecutionTimeMillis = 273 Math.max(mService.getMaxJobExecutionTimeMs(job), mMinExecutionGuaranteeMillis); 274 275 final long whenDeferred = job.getWhenStandbyDeferred(); 276 if (whenDeferred > 0) { 277 final long deferral = mExecutionStartTimeElapsed - whenDeferred; 278 EventLog.writeEvent(EventLogTags.JOB_DEFERRED_EXECUTION, deferral); 279 if (DEBUG_STANDBY) { 280 StringBuilder sb = new StringBuilder(128); 281 sb.append("Starting job deferred for standby by "); 282 TimeUtils.formatDuration(deferral, sb); 283 sb.append(" ms : "); 284 sb.append(job.toShortString()); 285 Slog.v(TAG, sb.toString()); 286 } 287 } 288 289 // Once we'e begun executing a job, we by definition no longer care whether 290 // it was inflated from disk with not-yet-coherent delay/deadline bounds. 291 job.clearPersistedUtcTimes(); 292 293 mWakeLock = mPowerManager.newWakeLock(PowerManager.PARTIAL_WAKE_LOCK, job.getTag()); 294 mWakeLock.setWorkSource( 295 mService.deriveWorkSource(job.getSourceUid(), job.getSourcePackageName())); 296 mWakeLock.setReferenceCounted(false); 297 mWakeLock.acquire(); 298 299 // Note the start when we try to bind so that the app is charged for some processing 300 // even if binding fails. 301 mEconomyManagerInternal.noteInstantaneousEvent( 302 job.getSourceUserId(), job.getSourcePackageName(), 303 getStartActionId(job), String.valueOf(job.getJobId())); 304 mVerb = VERB_BINDING; 305 scheduleOpTimeOutLocked(); 306 final Intent intent = new Intent().setComponent(job.getServiceComponent()); 307 boolean binding = false; 308 try { 309 final int bindFlags; 310 if (job.shouldTreatAsExpeditedJob()) { 311 bindFlags = Context.BIND_AUTO_CREATE | Context.BIND_NOT_FOREGROUND 312 | Context.BIND_ALMOST_PERCEPTIBLE 313 | Context.BIND_BYPASS_POWER_NETWORK_RESTRICTIONS 314 | Context.BIND_NOT_APP_COMPONENT_USAGE; 315 } else { 316 bindFlags = Context.BIND_AUTO_CREATE | Context.BIND_NOT_FOREGROUND 317 | Context.BIND_NOT_PERCEPTIBLE 318 | Context.BIND_NOT_APP_COMPONENT_USAGE; 319 } 320 binding = mContext.bindServiceAsUser(intent, this, bindFlags, 321 UserHandle.of(job.getUserId())); 322 } catch (SecurityException e) { 323 // Some permission policy, for example INTERACT_ACROSS_USERS and 324 // android:singleUser, can result in a SecurityException being thrown from 325 // bindServiceAsUser(). If this happens, catch it and fail gracefully. 326 Slog.w(TAG, "Job service " + job.getServiceComponent().getShortClassName() 327 + " cannot be executed: " + e.getMessage()); 328 binding = false; 329 } 330 if (!binding) { 331 if (DEBUG) { 332 Slog.d(TAG, job.getServiceComponent().getShortClassName() + " unavailable."); 333 } 334 mRunningJob = null; 335 mRunningJobWorkType = WORK_TYPE_NONE; 336 mRunningCallback = null; 337 mParams = null; 338 mExecutionStartTimeElapsed = 0L; 339 mWakeLock.release(); 340 mVerb = VERB_FINISHED; 341 removeOpTimeOutLocked(); 342 return false; 343 } 344 mJobPackageTracker.noteActive(job); 345 FrameworkStatsLog.write_non_chained(FrameworkStatsLog.SCHEDULED_JOB_STATE_CHANGED, 346 job.getSourceUid(), null, job.getBatteryName(), 347 FrameworkStatsLog.SCHEDULED_JOB_STATE_CHANGED__STATE__STARTED, 348 JobProtoEnums.INTERNAL_STOP_REASON_UNKNOWN, 349 job.getStandbyBucket(), job.getJobId(), 350 job.hasChargingConstraint(), 351 job.hasBatteryNotLowConstraint(), 352 job.hasStorageNotLowConstraint(), 353 job.hasTimingDelayConstraint(), 354 job.hasDeadlineConstraint(), 355 job.hasIdleConstraint(), 356 job.hasConnectivityConstraint(), 357 job.hasContentTriggerConstraint(), 358 job.isRequestedExpeditedJob(), 359 job.shouldTreatAsExpeditedJob(), 360 JobProtoEnums.STOP_REASON_UNDEFINED, 361 job.getJob().isPrefetch(), 362 job.getJob().getPriority(), 363 job.getEffectivePriority(), 364 job.getNumFailures()); 365 // Use the context's ID to distinguish traces since there'll only be one job running 366 // per context. 367 Trace.asyncTraceBegin(Trace.TRACE_TAG_SYSTEM_SERVER, job.getTag(), getId()); 368 try { 369 mBatteryStats.noteJobStart(job.getBatteryName(), job.getSourceUid()); 370 } catch (RemoteException e) { 371 // Whatever. 372 } 373 final String jobPackage = job.getSourcePackageName(); 374 final int jobUserId = job.getSourceUserId(); 375 UsageStatsManagerInternal usageStats = 376 LocalServices.getService(UsageStatsManagerInternal.class); 377 usageStats.setLastJobRunTime(jobPackage, jobUserId, mExecutionStartTimeElapsed); 378 mAvailable = false; 379 mStoppedReason = null; 380 mStoppedTime = 0; 381 job.startedAsExpeditedJob = job.shouldTreatAsExpeditedJob(); 382 return true; 383 } 384 } 385 386 @EconomicPolicy.AppAction getStartActionId(@onNull JobStatus job)387 private static int getStartActionId(@NonNull JobStatus job) { 388 switch (job.getEffectivePriority()) { 389 case JobInfo.PRIORITY_MAX: 390 return JobSchedulerEconomicPolicy.ACTION_JOB_MAX_START; 391 case JobInfo.PRIORITY_HIGH: 392 return JobSchedulerEconomicPolicy.ACTION_JOB_HIGH_START; 393 case JobInfo.PRIORITY_LOW: 394 return JobSchedulerEconomicPolicy.ACTION_JOB_LOW_START; 395 case JobInfo.PRIORITY_MIN: 396 return JobSchedulerEconomicPolicy.ACTION_JOB_MIN_START; 397 default: 398 Slog.wtf(TAG, "Unknown priority: " + getPriorityString(job.getEffectivePriority())); 399 // Intentional fallthrough 400 case JobInfo.PRIORITY_DEFAULT: 401 return JobSchedulerEconomicPolicy.ACTION_JOB_DEFAULT_START; 402 } 403 } 404 405 /** 406 * Used externally to query the running job. Will return null if there is no job running. 407 */ 408 @Nullable getRunningJobLocked()409 JobStatus getRunningJobLocked() { 410 return mRunningJob; 411 } 412 413 @JobConcurrencyManager.WorkType getRunningJobWorkType()414 int getRunningJobWorkType() { 415 return mRunningJobWorkType; 416 } 417 418 /** 419 * Used only for debugging. Will return <code>"<null>"</code> if there is no job running. 420 */ getRunningJobNameLocked()421 private String getRunningJobNameLocked() { 422 return mRunningJob != null ? mRunningJob.toShortString() : "<null>"; 423 } 424 425 /** Called externally when a job that was scheduled for execution should be cancelled. */ 426 @GuardedBy("mLock") cancelExecutingJobLocked(@obParameters.StopReason int reason, int internalStopReason, @NonNull String debugReason)427 void cancelExecutingJobLocked(@JobParameters.StopReason int reason, 428 int internalStopReason, @NonNull String debugReason) { 429 doCancelLocked(reason, internalStopReason, debugReason); 430 } 431 getPreferredUid()432 int getPreferredUid() { 433 return mPreferredUid; 434 } 435 clearPreferredUid()436 void clearPreferredUid() { 437 mPreferredUid = NO_PREFERRED_UID; 438 } 439 getId()440 int getId() { 441 return hashCode(); 442 } 443 getExecutionStartTimeElapsed()444 long getExecutionStartTimeElapsed() { 445 return mExecutionStartTimeElapsed; 446 } 447 getTimeoutElapsed()448 long getTimeoutElapsed() { 449 return mTimeoutElapsed; 450 } 451 isWithinExecutionGuaranteeTime()452 boolean isWithinExecutionGuaranteeTime() { 453 return sElapsedRealtimeClock.millis() 454 < mExecutionStartTimeElapsed + mMinExecutionGuaranteeMillis; 455 } 456 457 @GuardedBy("mLock") timeoutIfExecutingLocked(String pkgName, int userId, boolean matchJobId, int jobId, String reason)458 boolean timeoutIfExecutingLocked(String pkgName, int userId, boolean matchJobId, int jobId, 459 String reason) { 460 final JobStatus executing = getRunningJobLocked(); 461 if (executing != null && (userId == UserHandle.USER_ALL || userId == executing.getUserId()) 462 && (pkgName == null || pkgName.equals(executing.getSourcePackageName())) 463 && (!matchJobId || jobId == executing.getJobId())) { 464 if (mVerb == VERB_EXECUTING) { 465 mParams.setStopReason(JobParameters.STOP_REASON_TIMEOUT, 466 JobParameters.INTERNAL_STOP_REASON_TIMEOUT, reason); 467 sendStopMessageLocked("force timeout from shell"); 468 return true; 469 } 470 } 471 return false; 472 } 473 doJobFinished(JobCallback cb, int jobId, boolean reschedule)474 void doJobFinished(JobCallback cb, int jobId, boolean reschedule) { 475 final long ident = Binder.clearCallingIdentity(); 476 try { 477 synchronized (mLock) { 478 if (!verifyCallerLocked(cb)) { 479 return; 480 } 481 mParams.setStopReason(JobParameters.STOP_REASON_UNDEFINED, 482 JobParameters.INTERNAL_STOP_REASON_SUCCESSFUL_FINISH, 483 "app called jobFinished"); 484 doCallbackLocked(reschedule, "app called jobFinished"); 485 } 486 } finally { 487 Binder.restoreCallingIdentity(ident); 488 } 489 } 490 doAcknowledgeStopMessage(JobCallback cb, int jobId, boolean reschedule)491 void doAcknowledgeStopMessage(JobCallback cb, int jobId, boolean reschedule) { 492 doCallback(cb, reschedule, null); 493 } 494 doAcknowledgeStartMessage(JobCallback cb, int jobId, boolean ongoing)495 void doAcknowledgeStartMessage(JobCallback cb, int jobId, boolean ongoing) { 496 doCallback(cb, ongoing, "finished start"); 497 } 498 doDequeueWork(JobCallback cb, int jobId)499 JobWorkItem doDequeueWork(JobCallback cb, int jobId) { 500 final long ident = Binder.clearCallingIdentity(); 501 try { 502 synchronized (mLock) { 503 if (!assertCallerLocked(cb)) { 504 return null; 505 } 506 if (mVerb == VERB_STOPPING || mVerb == VERB_FINISHED) { 507 // This job is either all done, or on its way out. Either way, it 508 // should not dispatch any more work. We will pick up any remaining 509 // work the next time we start the job again. 510 return null; 511 } 512 final JobWorkItem work = mRunningJob.dequeueWorkLocked(); 513 if (work == null && !mRunningJob.hasExecutingWorkLocked()) { 514 mParams.setStopReason(JobParameters.STOP_REASON_UNDEFINED, 515 JobParameters.INTERNAL_STOP_REASON_SUCCESSFUL_FINISH, 516 "last work dequeued"); 517 // This will finish the job. 518 doCallbackLocked(false, "last work dequeued"); 519 } 520 return work; 521 } 522 } finally { 523 Binder.restoreCallingIdentity(ident); 524 } 525 } 526 doCompleteWork(JobCallback cb, int jobId, int workId)527 boolean doCompleteWork(JobCallback cb, int jobId, int workId) { 528 final long ident = Binder.clearCallingIdentity(); 529 try { 530 synchronized (mLock) { 531 if (!assertCallerLocked(cb)) { 532 // Return true instead of false here so we don't just kick the 533 // Exception-throwing-can down the road to JobParameters.completeWork >:( 534 return true; 535 } 536 return mRunningJob.completeWorkLocked(workId); 537 } 538 } finally { 539 Binder.restoreCallingIdentity(ident); 540 } 541 } 542 543 /** 544 * We acquire/release a wakelock on onServiceConnected/unbindService. This mirrors the work 545 * we intend to send to the client - we stop sending work when the service is unbound so until 546 * then we keep the wakelock. 547 * @param name The concrete component name of the service that has been connected. 548 * @param service The IBinder of the Service's communication channel, 549 */ 550 @Override onServiceConnected(ComponentName name, IBinder service)551 public void onServiceConnected(ComponentName name, IBinder service) { 552 JobStatus runningJob; 553 synchronized (mLock) { 554 // This isn't strictly necessary b/c the JobServiceHandler is running on the main 555 // looper and at this point we can't get any binder callbacks from the client. Better 556 // safe than sorry. 557 runningJob = mRunningJob; 558 559 if (runningJob == null || !name.equals(runningJob.getServiceComponent())) { 560 closeAndCleanupJobLocked(true /* needsReschedule */, 561 "connected for different component"); 562 return; 563 } 564 this.service = IJobService.Stub.asInterface(service); 565 doServiceBoundLocked(); 566 } 567 } 568 569 /** If the client service crashes we reschedule this job and clean up. */ 570 @Override onServiceDisconnected(ComponentName name)571 public void onServiceDisconnected(ComponentName name) { 572 synchronized (mLock) { 573 closeAndCleanupJobLocked(true /* needsReschedule */, "unexpectedly disconnected"); 574 } 575 } 576 577 @Override onBindingDied(ComponentName name)578 public void onBindingDied(ComponentName name) { 579 synchronized (mLock) { 580 if (mRunningJob == null) { 581 Slog.e(TAG, "Binding died for " + name.getPackageName() 582 + " but no running job on this context"); 583 } else if (mRunningJob.getServiceComponent().equals(name)) { 584 Slog.e(TAG, "Binding died for " 585 + mRunningJob.getSourceUserId() + ":" + name.getPackageName()); 586 } else { 587 Slog.e(TAG, "Binding died for " + name.getPackageName() 588 + " but context is running a different job"); 589 } 590 closeAndCleanupJobLocked(true /* needsReschedule */, "binding died"); 591 } 592 } 593 594 @Override onNullBinding(ComponentName name)595 public void onNullBinding(ComponentName name) { 596 synchronized (mLock) { 597 if (mRunningJob == null) { 598 Slog.wtf(TAG, "Got null binding for " + name.getPackageName() 599 + " but no running job on this context"); 600 } else if (mRunningJob.getServiceComponent().equals(name)) { 601 Slog.wtf(TAG, "Got null binding for " 602 + mRunningJob.getSourceUserId() + ":" + name.getPackageName()); 603 } else { 604 Slog.wtf(TAG, "Got null binding for " + name.getPackageName() 605 + " but context is running a different job"); 606 } 607 // Don't reschedule the job since returning a null binding is an explicit choice by the 608 // app which breaks things. 609 closeAndCleanupJobLocked(false /* needsReschedule */, "null binding"); 610 } 611 } 612 613 /** 614 * This class is reused across different clients, and passes itself in as a callback. Check 615 * whether the client exercising the callback is the client we expect. 616 * @return True if the binder calling is coming from the client we expect. 617 */ verifyCallerLocked(JobCallback cb)618 private boolean verifyCallerLocked(JobCallback cb) { 619 if (mRunningCallback != cb) { 620 if (DEBUG) { 621 Slog.d(TAG, "Stale callback received, ignoring."); 622 } 623 return false; 624 } 625 return true; 626 } 627 628 /** 629 * Will throw a {@link SecurityException} if the callback is not for the currently running job, 630 * but may decide not to throw an exception if the call from the previous job appears to be an 631 * accident. 632 * 633 * @return true if the callback is for the current job, false otherwise 634 */ assertCallerLocked(JobCallback cb)635 private boolean assertCallerLocked(JobCallback cb) { 636 if (!verifyCallerLocked(cb)) { 637 final long nowElapsed = sElapsedRealtimeClock.millis(); 638 if (!mPreviousJobHadSuccessfulFinish 639 && (nowElapsed - mLastUnsuccessfulFinishElapsed) < 15_000L) { 640 // Don't punish apps for race conditions 641 return false; 642 } 643 // It's been long enough that the app should really not be calling into JS for the 644 // stopped job. 645 StringBuilder sb = new StringBuilder(128); 646 sb.append("Caller no longer running"); 647 if (cb.mStoppedReason != null) { 648 sb.append(", last stopped "); 649 TimeUtils.formatDuration(nowElapsed - cb.mStoppedTime, sb); 650 sb.append(" because: "); 651 sb.append(cb.mStoppedReason); 652 } 653 throw new SecurityException(sb.toString()); 654 } 655 return true; 656 } 657 658 /** 659 * Scheduling of async messages (basically timeouts at this point). 660 */ 661 private class JobServiceHandler extends Handler { JobServiceHandler(Looper looper)662 JobServiceHandler(Looper looper) { 663 super(looper); 664 } 665 666 @Override handleMessage(Message message)667 public void handleMessage(Message message) { 668 switch (message.what) { 669 case MSG_TIMEOUT: 670 synchronized (mLock) { 671 if (message.obj == mRunningCallback) { 672 handleOpTimeoutLocked(); 673 } else { 674 JobCallback jc = (JobCallback)message.obj; 675 StringBuilder sb = new StringBuilder(128); 676 sb.append("Ignoring timeout of no longer active job"); 677 if (jc.mStoppedReason != null) { 678 sb.append(", stopped "); 679 TimeUtils.formatDuration(sElapsedRealtimeClock.millis() 680 - jc.mStoppedTime, sb); 681 sb.append(" because: "); 682 sb.append(jc.mStoppedReason); 683 } 684 Slog.w(TAG, sb.toString()); 685 } 686 } 687 break; 688 default: 689 Slog.e(TAG, "Unrecognised message: " + message); 690 } 691 } 692 } 693 694 @GuardedBy("mLock") doServiceBoundLocked()695 void doServiceBoundLocked() { 696 removeOpTimeOutLocked(); 697 handleServiceBoundLocked(); 698 } 699 doCallback(JobCallback cb, boolean reschedule, String reason)700 void doCallback(JobCallback cb, boolean reschedule, String reason) { 701 final long ident = Binder.clearCallingIdentity(); 702 try { 703 synchronized (mLock) { 704 if (!verifyCallerLocked(cb)) { 705 return; 706 } 707 doCallbackLocked(reschedule, reason); 708 } 709 } finally { 710 Binder.restoreCallingIdentity(ident); 711 } 712 } 713 714 @GuardedBy("mLock") doCallbackLocked(boolean reschedule, String reason)715 void doCallbackLocked(boolean reschedule, String reason) { 716 if (DEBUG) { 717 Slog.d(TAG, "doCallback of : " + mRunningJob 718 + " v:" + VERB_STRINGS[mVerb]); 719 } 720 removeOpTimeOutLocked(); 721 722 if (mVerb == VERB_STARTING) { 723 handleStartedLocked(reschedule); 724 } else if (mVerb == VERB_EXECUTING || 725 mVerb == VERB_STOPPING) { 726 handleFinishedLocked(reschedule, reason); 727 } else { 728 if (DEBUG) { 729 Slog.d(TAG, "Unrecognised callback: " + mRunningJob); 730 } 731 } 732 } 733 734 @GuardedBy("mLock") doCancelLocked(@obParameters.StopReason int stopReasonCode, int internalStopReasonCode, @Nullable String debugReason)735 private void doCancelLocked(@JobParameters.StopReason int stopReasonCode, 736 int internalStopReasonCode, @Nullable String debugReason) { 737 if (mVerb == VERB_FINISHED) { 738 if (DEBUG) { 739 Slog.d(TAG, 740 "Trying to process cancel for torn-down context, ignoring."); 741 } 742 return; 743 } 744 if (mRunningJob.startedAsExpeditedJob 745 && stopReasonCode == JobParameters.STOP_REASON_QUOTA) { 746 // EJs should be able to run for at least the min upper limit regardless of quota. 747 final long earliestStopTimeElapsed = 748 mExecutionStartTimeElapsed + mMinExecutionGuaranteeMillis; 749 final long nowElapsed = sElapsedRealtimeClock.millis(); 750 if (nowElapsed < earliestStopTimeElapsed) { 751 mPendingStopReason = stopReasonCode; 752 mPendingInternalStopReason = internalStopReasonCode; 753 mPendingDebugStopReason = debugReason; 754 return; 755 } 756 } 757 mParams.setStopReason(stopReasonCode, internalStopReasonCode, debugReason); 758 if (stopReasonCode == JobParameters.STOP_REASON_PREEMPT) { 759 // Only preserve the UID when we're preempting the job for another one of the same UID. 760 mPreferredUid = mRunningJob != null ? mRunningJob.getUid() : NO_PREFERRED_UID; 761 } 762 handleCancelLocked(debugReason); 763 } 764 765 /** Start the job on the service. */ 766 @GuardedBy("mLock") handleServiceBoundLocked()767 private void handleServiceBoundLocked() { 768 if (DEBUG) { 769 Slog.d(TAG, "handleServiceBound for " + getRunningJobNameLocked()); 770 } 771 if (mVerb != VERB_BINDING) { 772 Slog.e(TAG, "Sending onStartJob for a job that isn't pending. " 773 + VERB_STRINGS[mVerb]); 774 closeAndCleanupJobLocked(false /* reschedule */, "started job not pending"); 775 return; 776 } 777 if (mCancelled) { 778 if (DEBUG) { 779 Slog.d(TAG, "Job cancelled while waiting for bind to complete. " 780 + mRunningJob); 781 } 782 closeAndCleanupJobLocked(true /* reschedule */, "cancelled while waiting for bind"); 783 return; 784 } 785 try { 786 mVerb = VERB_STARTING; 787 scheduleOpTimeOutLocked(); 788 service.startJob(mParams); 789 } catch (Exception e) { 790 // We catch 'Exception' because client-app malice or bugs might induce a wide 791 // range of possible exception-throw outcomes from startJob() and its handling 792 // of the client's ParcelableBundle extras. 793 Slog.e(TAG, "Error sending onStart message to '" + 794 mRunningJob.getServiceComponent().getShortClassName() + "' ", e); 795 } 796 } 797 798 /** 799 * State behaviours. 800 * VERB_STARTING -> Successful start, change job to VERB_EXECUTING and post timeout. 801 * _PENDING -> Error 802 * _EXECUTING -> Error 803 * _STOPPING -> Error 804 */ 805 @GuardedBy("mLock") handleStartedLocked(boolean workOngoing)806 private void handleStartedLocked(boolean workOngoing) { 807 switch (mVerb) { 808 case VERB_STARTING: 809 mVerb = VERB_EXECUTING; 810 if (!workOngoing) { 811 // Job is finished already so fast-forward to handleFinished. 812 handleFinishedLocked(false, "onStartJob returned false"); 813 return; 814 } 815 if (mCancelled) { 816 if (DEBUG) { 817 Slog.d(TAG, "Job cancelled while waiting for onStartJob to complete."); 818 } 819 // Cancelled *while* waiting for acknowledgeStartMessage from client. 820 handleCancelLocked(null); 821 return; 822 } 823 scheduleOpTimeOutLocked(); 824 break; 825 default: 826 Slog.e(TAG, "Handling started job but job wasn't starting! Was " 827 + VERB_STRINGS[mVerb] + "."); 828 return; 829 } 830 } 831 832 /** 833 * VERB_EXECUTING -> Client called jobFinished(), clean up and notify done. 834 * _STOPPING -> Successful finish, clean up and notify done. 835 * _STARTING -> Error 836 * _PENDING -> Error 837 */ 838 @GuardedBy("mLock") handleFinishedLocked(boolean reschedule, String reason)839 private void handleFinishedLocked(boolean reschedule, String reason) { 840 switch (mVerb) { 841 case VERB_EXECUTING: 842 case VERB_STOPPING: 843 closeAndCleanupJobLocked(reschedule, reason); 844 break; 845 default: 846 Slog.e(TAG, "Got an execution complete message for a job that wasn't being" + 847 "executed. Was " + VERB_STRINGS[mVerb] + "."); 848 } 849 } 850 851 /** 852 * A job can be in various states when a cancel request comes in: 853 * VERB_BINDING -> Cancelled before bind completed. Mark as cancelled and wait for 854 * {@link #onServiceConnected(android.content.ComponentName, android.os.IBinder)} 855 * _STARTING -> Mark as cancelled and wait for 856 * {@link JobServiceContext#doAcknowledgeStartMessage} 857 * _EXECUTING -> call {@link #sendStopMessageLocked}}, but only if there are no callbacks 858 * in the message queue. 859 * _ENDING -> No point in doing anything here, so we ignore. 860 */ 861 @GuardedBy("mLock") handleCancelLocked(@ullable String reason)862 private void handleCancelLocked(@Nullable String reason) { 863 if (JobSchedulerService.DEBUG) { 864 Slog.d(TAG, "Handling cancel for: " + mRunningJob.getJobId() + " " 865 + VERB_STRINGS[mVerb]); 866 } 867 switch (mVerb) { 868 case VERB_BINDING: 869 case VERB_STARTING: 870 mCancelled = true; 871 applyStoppedReasonLocked(reason); 872 break; 873 case VERB_EXECUTING: 874 sendStopMessageLocked(reason); 875 break; 876 case VERB_STOPPING: 877 // Nada. 878 break; 879 default: 880 Slog.e(TAG, "Cancelling a job without a valid verb: " + mVerb); 881 break; 882 } 883 } 884 885 /** Process MSG_TIMEOUT here. */ 886 @GuardedBy("mLock") handleOpTimeoutLocked()887 private void handleOpTimeoutLocked() { 888 switch (mVerb) { 889 case VERB_BINDING: 890 Slog.w(TAG, "Time-out while trying to bind " + getRunningJobNameLocked() 891 + ", dropping."); 892 closeAndCleanupJobLocked(false /* needsReschedule */, "timed out while binding"); 893 break; 894 case VERB_STARTING: 895 // Client unresponsive - wedged or failed to respond in time. We don't really 896 // know what happened so let's log it and notify the JobScheduler 897 // FINISHED/NO-RETRY. 898 Slog.w(TAG, "No response from client for onStartJob " 899 + getRunningJobNameLocked()); 900 closeAndCleanupJobLocked(false /* needsReschedule */, "timed out while starting"); 901 break; 902 case VERB_STOPPING: 903 // At least we got somewhere, so fail but ask the JobScheduler to reschedule. 904 Slog.w(TAG, "No response from client for onStopJob " 905 + getRunningJobNameLocked()); 906 closeAndCleanupJobLocked(true /* needsReschedule */, "timed out while stopping"); 907 break; 908 case VERB_EXECUTING: 909 if (mPendingStopReason != JobParameters.STOP_REASON_UNDEFINED) { 910 if (mService.isReadyToBeExecutedLocked(mRunningJob, false)) { 911 // Job became ready again while we were waiting to stop it (for example, 912 // the device was temporarily taken off the charger). Ignore the pending 913 // stop and see what the manager says. 914 mPendingStopReason = JobParameters.STOP_REASON_UNDEFINED; 915 mPendingInternalStopReason = 0; 916 mPendingDebugStopReason = null; 917 } else { 918 Slog.i(TAG, "JS was waiting to stop this job." 919 + " Sending onStop: " + getRunningJobNameLocked()); 920 mParams.setStopReason(mPendingStopReason, mPendingInternalStopReason, 921 mPendingDebugStopReason); 922 sendStopMessageLocked(mPendingDebugStopReason); 923 break; 924 } 925 } 926 final long latestStopTimeElapsed = 927 mExecutionStartTimeElapsed + mMaxExecutionTimeMillis; 928 final long nowElapsed = sElapsedRealtimeClock.millis(); 929 if (nowElapsed >= latestStopTimeElapsed) { 930 // Not an error - client ran out of time. 931 Slog.i(TAG, "Client timed out while executing (no jobFinished received)." 932 + " Sending onStop: " + getRunningJobNameLocked()); 933 mParams.setStopReason(JobParameters.STOP_REASON_TIMEOUT, 934 JobParameters.INTERNAL_STOP_REASON_TIMEOUT, "client timed out"); 935 sendStopMessageLocked("timeout while executing"); 936 } else { 937 // We've given the app the minimum execution time. See if we should stop it or 938 // let it continue running 939 final String reason = mJobConcurrencyManager.shouldStopRunningJobLocked(this); 940 if (reason != null) { 941 Slog.i(TAG, "Stopping client after min execution time: " 942 + getRunningJobNameLocked() + " because " + reason); 943 // Tell the developer we're stopping the job due to device state instead 944 // of timeout since all of the reasons could equate to "the system needs 945 // the resources the app is currently using." 946 mParams.setStopReason(JobParameters.STOP_REASON_DEVICE_STATE, 947 JobParameters.INTERNAL_STOP_REASON_TIMEOUT, reason); 948 sendStopMessageLocked(reason); 949 } else { 950 Slog.i(TAG, "Letting " + getRunningJobNameLocked() 951 + " continue to run past min execution time"); 952 scheduleOpTimeOutLocked(); 953 } 954 } 955 break; 956 default: 957 Slog.e(TAG, "Handling timeout for an invalid job state: " 958 + getRunningJobNameLocked() + ", dropping."); 959 closeAndCleanupJobLocked(false /* needsReschedule */, "invalid timeout"); 960 } 961 } 962 963 /** 964 * Already running, need to stop. Will switch {@link #mVerb} from VERB_EXECUTING -> 965 * VERB_STOPPING. 966 */ 967 @GuardedBy("mLock") sendStopMessageLocked(@ullable String reason)968 private void sendStopMessageLocked(@Nullable String reason) { 969 removeOpTimeOutLocked(); 970 if (mVerb != VERB_EXECUTING) { 971 Slog.e(TAG, "Sending onStopJob for a job that isn't started. " + mRunningJob); 972 closeAndCleanupJobLocked(false /* reschedule */, reason); 973 return; 974 } 975 try { 976 applyStoppedReasonLocked(reason); 977 mVerb = VERB_STOPPING; 978 scheduleOpTimeOutLocked(); 979 service.stopJob(mParams); 980 } catch (RemoteException e) { 981 Slog.e(TAG, "Error sending onStopJob to client.", e); 982 // The job's host app apparently crashed during the job, so we should reschedule. 983 closeAndCleanupJobLocked(true /* reschedule */, "host crashed when trying to stop"); 984 } 985 } 986 987 /** 988 * The provided job has finished, either by calling 989 * {@link android.app.job.JobService#jobFinished(android.app.job.JobParameters, boolean)} 990 * or from acknowledging the stop message we sent. Either way, we're done tracking it and 991 * we want to clean up internally. 992 */ 993 @GuardedBy("mLock") closeAndCleanupJobLocked(boolean reschedule, @Nullable String reason)994 private void closeAndCleanupJobLocked(boolean reschedule, @Nullable String reason) { 995 final JobStatus completedJob; 996 if (mVerb == VERB_FINISHED) { 997 return; 998 } 999 if (DEBUG) { 1000 Slog.d(TAG, "Cleaning up " + mRunningJob.toShortString() 1001 + " reschedule=" + reschedule + " reason=" + reason); 1002 } 1003 applyStoppedReasonLocked(reason); 1004 completedJob = mRunningJob; 1005 final int internalStopReason = mParams.getInternalStopReasonCode(); 1006 mPreviousJobHadSuccessfulFinish = 1007 (internalStopReason == JobParameters.INTERNAL_STOP_REASON_SUCCESSFUL_FINISH); 1008 if (!mPreviousJobHadSuccessfulFinish) { 1009 mLastUnsuccessfulFinishElapsed = sElapsedRealtimeClock.millis(); 1010 } 1011 mJobPackageTracker.noteInactive(completedJob, internalStopReason, reason); 1012 FrameworkStatsLog.write_non_chained(FrameworkStatsLog.SCHEDULED_JOB_STATE_CHANGED, 1013 completedJob.getSourceUid(), null, completedJob.getBatteryName(), 1014 FrameworkStatsLog.SCHEDULED_JOB_STATE_CHANGED__STATE__FINISHED, 1015 internalStopReason, completedJob.getStandbyBucket(), completedJob.getJobId(), 1016 completedJob.hasChargingConstraint(), 1017 completedJob.hasBatteryNotLowConstraint(), 1018 completedJob.hasStorageNotLowConstraint(), 1019 completedJob.hasTimingDelayConstraint(), 1020 completedJob.hasDeadlineConstraint(), 1021 completedJob.hasIdleConstraint(), 1022 completedJob.hasConnectivityConstraint(), 1023 completedJob.hasContentTriggerConstraint(), 1024 completedJob.isRequestedExpeditedJob(), 1025 completedJob.startedAsExpeditedJob, 1026 mParams.getStopReason(), 1027 completedJob.getJob().isPrefetch(), 1028 completedJob.getJob().getPriority(), 1029 completedJob.getEffectivePriority(), 1030 completedJob.getNumFailures()); 1031 Trace.asyncTraceEnd(Trace.TRACE_TAG_SYSTEM_SERVER, completedJob.getTag(), getId()); 1032 try { 1033 mBatteryStats.noteJobFinish(mRunningJob.getBatteryName(), mRunningJob.getSourceUid(), 1034 internalStopReason); 1035 } catch (RemoteException e) { 1036 // Whatever. 1037 } 1038 if (mParams.getStopReason() == JobParameters.STOP_REASON_TIMEOUT) { 1039 mEconomyManagerInternal.noteInstantaneousEvent( 1040 mRunningJob.getSourceUserId(), mRunningJob.getSourcePackageName(), 1041 JobSchedulerEconomicPolicy.ACTION_JOB_TIMEOUT, 1042 String.valueOf(mRunningJob.getJobId())); 1043 } 1044 if (mWakeLock != null) { 1045 mWakeLock.release(); 1046 } 1047 final int workType = mRunningJobWorkType; 1048 mContext.unbindService(JobServiceContext.this); 1049 mWakeLock = null; 1050 mRunningJob = null; 1051 mRunningJobWorkType = WORK_TYPE_NONE; 1052 mRunningCallback = null; 1053 mParams = null; 1054 mVerb = VERB_FINISHED; 1055 mCancelled = false; 1056 service = null; 1057 mAvailable = true; 1058 mPendingStopReason = JobParameters.STOP_REASON_UNDEFINED; 1059 mPendingInternalStopReason = 0; 1060 mPendingDebugStopReason = null; 1061 removeOpTimeOutLocked(); 1062 mCompletedListener.onJobCompletedLocked(completedJob, internalStopReason, reschedule); 1063 mJobConcurrencyManager.onJobCompletedLocked(this, completedJob, workType); 1064 } 1065 applyStoppedReasonLocked(@ullable String reason)1066 private void applyStoppedReasonLocked(@Nullable String reason) { 1067 if (reason != null && mStoppedReason == null) { 1068 mStoppedReason = reason; 1069 mStoppedTime = sElapsedRealtimeClock.millis(); 1070 if (mRunningCallback != null) { 1071 mRunningCallback.mStoppedReason = mStoppedReason; 1072 mRunningCallback.mStoppedTime = mStoppedTime; 1073 } 1074 } 1075 } 1076 1077 /** 1078 * Called when sending a message to the client, over whose execution we have no control. If 1079 * we haven't received a response in a certain amount of time, we want to give up and carry 1080 * on with life. 1081 */ scheduleOpTimeOutLocked()1082 private void scheduleOpTimeOutLocked() { 1083 removeOpTimeOutLocked(); 1084 1085 final long timeoutMillis; 1086 switch (mVerb) { 1087 case VERB_EXECUTING: 1088 final long earliestStopTimeElapsed = 1089 mExecutionStartTimeElapsed + mMinExecutionGuaranteeMillis; 1090 final long latestStopTimeElapsed = 1091 mExecutionStartTimeElapsed + mMaxExecutionTimeMillis; 1092 final long nowElapsed = sElapsedRealtimeClock.millis(); 1093 if (nowElapsed < earliestStopTimeElapsed) { 1094 timeoutMillis = earliestStopTimeElapsed - nowElapsed; 1095 } else { 1096 timeoutMillis = latestStopTimeElapsed - nowElapsed; 1097 } 1098 break; 1099 1100 case VERB_BINDING: 1101 timeoutMillis = OP_BIND_TIMEOUT_MILLIS; 1102 break; 1103 1104 default: 1105 timeoutMillis = OP_TIMEOUT_MILLIS; 1106 break; 1107 } 1108 if (DEBUG) { 1109 Slog.d(TAG, "Scheduling time out for '" + 1110 mRunningJob.getServiceComponent().getShortClassName() + "' jId: " + 1111 mParams.getJobId() + ", in " + (timeoutMillis / 1000) + " s"); 1112 } 1113 Message m = mCallbackHandler.obtainMessage(MSG_TIMEOUT, mRunningCallback); 1114 mCallbackHandler.sendMessageDelayed(m, timeoutMillis); 1115 mTimeoutElapsed = sElapsedRealtimeClock.millis() + timeoutMillis; 1116 } 1117 removeOpTimeOutLocked()1118 private void removeOpTimeOutLocked() { 1119 mCallbackHandler.removeMessages(MSG_TIMEOUT); 1120 } 1121 dumpLocked(IndentingPrintWriter pw, final long nowElapsed)1122 void dumpLocked(IndentingPrintWriter pw, final long nowElapsed) { 1123 if (mRunningJob == null) { 1124 if (mStoppedReason != null) { 1125 pw.print("inactive since "); 1126 TimeUtils.formatDuration(mStoppedTime, nowElapsed, pw); 1127 pw.print(", stopped because: "); 1128 pw.println(mStoppedReason); 1129 } else { 1130 pw.println("inactive"); 1131 } 1132 } else { 1133 pw.println(mRunningJob.toShortString()); 1134 1135 pw.increaseIndent(); 1136 pw.print("Running for: "); 1137 TimeUtils.formatDuration(nowElapsed - mExecutionStartTimeElapsed, pw); 1138 pw.print(", timeout at: "); 1139 TimeUtils.formatDuration(mTimeoutElapsed - nowElapsed, pw); 1140 pw.println(); 1141 pw.print("Remaining execution limits: ["); 1142 TimeUtils.formatDuration( 1143 (mExecutionStartTimeElapsed + mMinExecutionGuaranteeMillis) - nowElapsed, pw); 1144 pw.print(", "); 1145 TimeUtils.formatDuration( 1146 (mExecutionStartTimeElapsed + mMaxExecutionTimeMillis) - nowElapsed, pw); 1147 pw.print("]"); 1148 if (mPendingStopReason != JobParameters.STOP_REASON_UNDEFINED) { 1149 pw.print(" Pending stop because "); 1150 pw.print(mPendingStopReason); 1151 pw.print("/"); 1152 pw.print(mPendingInternalStopReason); 1153 pw.print("/"); 1154 pw.print(mPendingDebugStopReason); 1155 } 1156 pw.println(); 1157 pw.decreaseIndent(); 1158 } 1159 } 1160 } 1161