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