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.JobParameters.OVERRIDE_HANDLE_ABANDONED_JOBS; 20 21 import static com.android.server.job.JobConcurrencyManager.WORK_TYPE_NONE; 22 import static com.android.server.job.JobSchedulerService.sElapsedRealtimeClock; 23 import static com.android.server.job.JobSchedulerService.safelyScaleBytesToKBForHistogram; 24 25 import android.Manifest; 26 import android.annotation.BytesLong; 27 import android.annotation.NonNull; 28 import android.annotation.Nullable; 29 import android.app.ActivityManager; 30 import android.app.ActivityManagerInternal; 31 import android.app.Notification; 32 import android.app.compat.CompatChanges; 33 import android.app.job.IJobCallback; 34 import android.app.job.IJobService; 35 import android.app.job.JobInfo; 36 import android.app.job.JobParameters; 37 import android.app.job.JobProtoEnums; 38 import android.app.job.JobWorkItem; 39 import android.app.usage.UsageStatsManagerInternal; 40 import android.compat.annotation.ChangeId; 41 import android.compat.annotation.EnabledAfter; 42 import android.content.ComponentName; 43 import android.content.Context; 44 import android.content.Intent; 45 import android.content.PermissionChecker; 46 import android.content.ServiceConnection; 47 import android.net.Network; 48 import android.net.TrafficStats; 49 import android.net.Uri; 50 import android.os.Binder; 51 import android.os.Build; 52 import android.os.Handler; 53 import android.os.IBinder; 54 import android.os.Looper; 55 import android.os.Message; 56 import android.os.PowerManager; 57 import android.os.RemoteException; 58 import android.os.Trace; 59 import android.os.UserHandle; 60 import android.util.EventLog; 61 import android.util.IndentingPrintWriter; 62 import android.util.Pair; 63 import android.util.Slog; 64 import android.util.TimeUtils; 65 66 import com.android.internal.annotations.GuardedBy; 67 import com.android.internal.annotations.VisibleForTesting; 68 import com.android.internal.app.IBatteryStats; 69 import com.android.internal.os.TimeoutRecord; 70 import com.android.internal.util.FrameworkStatsLog; 71 import com.android.modules.expresslog.Counter; 72 import com.android.modules.expresslog.Histogram; 73 import com.android.server.EventLogTags; 74 import com.android.server.LocalServices; 75 import com.android.server.job.controllers.JobStatus; 76 77 import java.util.Objects; 78 79 /** 80 * Handles client binding and lifecycle of a job. Jobs execute one at a time on an instance of this 81 * class. 82 * 83 * There are two important interactions into this class from the 84 * {@link com.android.server.job.JobSchedulerService}. To execute a job and to cancel a job. 85 * - Execution of a new job is handled by the {@link #mAvailable}. This bit is flipped once when a 86 * job lands, and again when it is complete. 87 * - Cancelling is trickier, because there are also interactions from the client. It's possible 88 * the {@link com.android.server.job.JobServiceContext.JobServiceHandler} tries to process a 89 * {@link #doCancelLocked} after the client has already finished. This is handled by having 90 * {@link com.android.server.job.JobServiceContext.JobServiceHandler#handleCancelLocked} check whether 91 * the context is still valid. 92 * To mitigate this, we avoid sending duplicate onStopJob() 93 * calls to the client after they've specified jobFinished(). 94 */ 95 public final class JobServiceContext implements ServiceConnection { 96 private static final boolean DEBUG = JobSchedulerService.DEBUG; 97 private static final boolean DEBUG_STANDBY = JobSchedulerService.DEBUG_STANDBY; 98 99 /** 100 * Whether to trigger an ANR when apps are slow to respond on pre-UDC APIs and functionality. 101 */ 102 @ChangeId 103 @EnabledAfter(targetSdkVersion = Build.VERSION_CODES.TIRAMISU) 104 private static final long ANR_PRE_UDC_APIS_ON_SLOW_RESPONSES = 258236856L; 105 106 private static final String TAG = "JobServiceContext"; 107 /** Amount of time the JobScheduler waits for the initial service launch+bind. */ 108 private static final long OP_BIND_TIMEOUT_MILLIS = 18 * 1000 * Build.HW_TIMEOUT_MULTIPLIER; 109 /** Amount of time the JobScheduler will wait for a response from an app for a message. */ 110 private static final long OP_TIMEOUT_MILLIS = 8 * 1000 * Build.HW_TIMEOUT_MULTIPLIER; 111 /** Amount of time the JobScheduler will wait for a job to provide a required notification. */ 112 private static final long NOTIFICATION_TIMEOUT_MILLIS = 10_000L * Build.HW_TIMEOUT_MULTIPLIER; 113 private static final long EXECUTION_DURATION_STAMP_PERIOD_MILLIS = 5 * 60_000L; 114 115 private static final Histogram sEnqueuedJwiAtJobStart = new Histogram( 116 "job_scheduler.value_hist_w_uid_enqueued_work_items_at_job_start", 117 new Histogram.ScaledRangeOptions(20, 1, 3, 1.4f)); 118 private static final Histogram sTransferredNetworkDownloadKBHighWaterMarkLogger = new Histogram( 119 "job_scheduler.value_hist_transferred_network_download_kilobytes_high_water_mark", 120 new Histogram.ScaledRangeOptions(50, 0, 32 /* 32 KB */, 1.31f)); 121 private static final Histogram sTransferredNetworkUploadKBHighWaterMarkLogger = new Histogram( 122 "job_scheduler.value_hist_transferred_network_upload_kilobytes_high_water_mark", 123 new Histogram.ScaledRangeOptions(50, 0, 32 /* 32 KB */, 1.31f)); 124 private static final Histogram sUpdatedEstimatedNetworkDownloadKBLogger = new Histogram( 125 "job_scheduler.value_hist_updated_estimated_network_download_kilobytes", 126 new Histogram.ScaledRangeOptions(50, 0, 32 /* 32 KB */, 1.31f)); 127 private static final Histogram sUpdatedEstimatedNetworkUploadKBLogger = new Histogram( 128 "job_scheduler.value_hist_updated_estimated_network_upload_kilobytes", 129 new Histogram.ScaledRangeOptions(50, 0, 32 /* 32 KB */, 1.31f)); 130 131 private static final String[] VERB_STRINGS = { 132 "VERB_BINDING", "VERB_STARTING", "VERB_EXECUTING", "VERB_STOPPING", "VERB_FINISHED" 133 }; 134 private static final String TRACE_ABANDONED_JOB = "abandonedJob:"; 135 private static final String TRACE_ABANDONED_JOB_DELIMITER = "#"; 136 137 // States that a job occupies while interacting with the client. 138 static final int VERB_BINDING = 0; 139 static final int VERB_STARTING = 1; 140 static final int VERB_EXECUTING = 2; 141 static final int VERB_STOPPING = 3; 142 static final int VERB_FINISHED = 4; 143 144 // Messages that result from interactions with the client service. 145 /** System timed out waiting for a response. */ 146 private static final int MSG_TIMEOUT = 0; 147 148 public static final int NO_PREFERRED_UID = -1; 149 150 private final Handler mCallbackHandler; 151 /** Make callbacks to {@link JobSchedulerService} to inform on job completion status. */ 152 private final JobCompletedListener mCompletedListener; 153 private final JobConcurrencyManager mJobConcurrencyManager; 154 private final JobNotificationCoordinator mNotificationCoordinator; 155 private final JobSchedulerService mService; 156 /** Used for service binding, etc. */ 157 private final Context mContext; 158 private final Object mLock; 159 private final ActivityManagerInternal mActivityManagerInternal; 160 private final IBatteryStats mBatteryStats; 161 private final JobPackageTracker mJobPackageTracker; 162 private final PowerManager mPowerManager; 163 private final UsageStatsManagerInternal mUsageStatsManagerInternal; 164 private PowerManager.WakeLock mWakeLock; 165 166 // Execution state. 167 private JobParameters mParams; 168 @VisibleForTesting 169 int mVerb; 170 private boolean mCancelled; 171 /** 172 * True if the previous job on this context successfully finished (ie. called jobFinished or 173 * dequeueWork with no work left). 174 */ 175 private boolean mPreviousJobHadSuccessfulFinish; 176 /** 177 * The last time a job on this context didn't finish successfully, in the elapsed realtime 178 * timebase. 179 */ 180 private long mLastUnsuccessfulFinishElapsed; 181 182 /** 183 * All the information maintained about the job currently being executed. 184 * 185 * Any reads (dereferences) not done from the handler thread must be synchronized on 186 * {@link #mLock}. 187 * Writes can only be done from the handler thread, 188 * or {@link #executeRunnableJob(JobStatus, int)}. 189 */ 190 private JobStatus mRunningJob; 191 @JobConcurrencyManager.WorkType 192 private int mRunningJobWorkType; 193 private JobCallback mRunningCallback; 194 /** Used to store next job to run when current job is to be preempted. */ 195 private int mPreferredUid; 196 IJobService service; 197 198 /** 199 * Whether this context is free. This is set to false at the start of execution, and reset to 200 * true when execution is complete. 201 */ 202 @GuardedBy("mLock") 203 private boolean mAvailable; 204 /** Track start time. */ 205 private long mExecutionStartTimeElapsed; 206 /** Track when job will timeout. */ 207 private long mTimeoutElapsed; 208 /** 209 * The minimum amount of time the context will allow the job to run before checking whether to 210 * stop it or not. 211 */ 212 private long mMinExecutionGuaranteeMillis; 213 /** The absolute maximum amount of time the job can run */ 214 private long mMaxExecutionTimeMillis; 215 /** Whether this job is required to provide a notification and we're still waiting for it. */ 216 private boolean mAwaitingNotification; 217 /** The last time we updated the job's execution duration, in the elapsed realtime timebase. */ 218 private long mLastExecutionDurationStampTimeElapsed; 219 220 private long mEstimatedDownloadBytes; 221 private long mEstimatedUploadBytes; 222 private long mTransferredDownloadBytes; 223 private long mTransferredUploadBytes; 224 225 /** 226 * The stop reason for a pending cancel. If there's not pending cancel, then the value should be 227 * {@link JobParameters#STOP_REASON_UNDEFINED}. 228 */ 229 private int mPendingStopReason = JobParameters.STOP_REASON_UNDEFINED; 230 private int mPendingInternalStopReason; 231 private String mPendingDebugStopReason; 232 233 private Network mPendingNetworkChange; 234 235 /** 236 * The reason this job is marked for death. If it's not marked for death, 237 * then the value should be {@link JobParameters#STOP_REASON_UNDEFINED}. 238 */ 239 private int mDeathMarkStopReason = JobParameters.STOP_REASON_UNDEFINED; 240 private int mDeathMarkInternalStopReason; 241 private String mDeathMarkDebugReason; 242 243 private long mInitialDownloadedBytesFromSource; 244 245 private long mInitialUploadedBytesFromSource; 246 247 private long mInitialDownloadedBytesFromCalling; 248 249 private long mInitialUploadedBytesFromCalling; 250 251 // Debugging: reason this job was last stopped. 252 public String mStoppedReason; 253 254 // Debugging: time this job was last stopped. 255 public long mStoppedTime; 256 257 final class JobCallback extends IJobCallback.Stub { 258 public String mStoppedReason; 259 public long mStoppedTime; 260 261 @Override acknowledgeGetTransferredDownloadBytesMessage(int jobId, int workId, @BytesLong long transferredBytes)262 public void acknowledgeGetTransferredDownloadBytesMessage(int jobId, int workId, 263 @BytesLong long transferredBytes) { 264 doAcknowledgeGetTransferredDownloadBytesMessage(this, jobId, workId, transferredBytes); 265 } 266 267 @Override acknowledgeGetTransferredUploadBytesMessage(int jobId, int workId, @BytesLong long transferredBytes)268 public void acknowledgeGetTransferredUploadBytesMessage(int jobId, int workId, 269 @BytesLong long transferredBytes) { 270 doAcknowledgeGetTransferredUploadBytesMessage(this, jobId, workId, transferredBytes); 271 } 272 273 @Override acknowledgeStartMessage(int jobId, boolean ongoing)274 public void acknowledgeStartMessage(int jobId, boolean ongoing) { 275 doAcknowledgeStartMessage(this, jobId, ongoing); 276 } 277 278 @Override acknowledgeStopMessage(int jobId, boolean reschedule)279 public void acknowledgeStopMessage(int jobId, boolean reschedule) { 280 doAcknowledgeStopMessage(this, jobId, reschedule); 281 } 282 283 @Override dequeueWork(int jobId)284 public JobWorkItem dequeueWork(int jobId) { 285 return doDequeueWork(this, jobId); 286 } 287 288 @Override completeWork(int jobId, int workId)289 public boolean completeWork(int jobId, int workId) { 290 return doCompleteWork(this, jobId, workId); 291 } 292 293 @Override jobFinished(int jobId, boolean reschedule)294 public void jobFinished(int jobId, boolean reschedule) { 295 doJobFinished(this, jobId, reschedule); 296 } 297 298 @Override handleAbandonedJob(int jobId)299 public void handleAbandonedJob(int jobId) { 300 doHandleAbandonedJob(this, jobId); 301 } 302 303 @Override updateEstimatedNetworkBytes(int jobId, JobWorkItem item, long downloadBytes, long uploadBytes)304 public void updateEstimatedNetworkBytes(int jobId, JobWorkItem item, 305 long downloadBytes, long uploadBytes) { 306 doUpdateEstimatedNetworkBytes(this, jobId, item, downloadBytes, uploadBytes); 307 } 308 309 @Override updateTransferredNetworkBytes(int jobId, JobWorkItem item, long downloadBytes, long uploadBytes)310 public void updateTransferredNetworkBytes(int jobId, JobWorkItem item, 311 long downloadBytes, long uploadBytes) { 312 doUpdateTransferredNetworkBytes(this, jobId, item, downloadBytes, uploadBytes); 313 } 314 315 @Override setNotification(int jobId, int notificationId, Notification notification, int jobEndNotificationPolicy)316 public void setNotification(int jobId, int notificationId, 317 Notification notification, int jobEndNotificationPolicy) { 318 doSetNotification(this, jobId, notificationId, notification, jobEndNotificationPolicy); 319 } 320 } 321 JobServiceContext(JobSchedulerService service, JobConcurrencyManager concurrencyManager, JobNotificationCoordinator notificationCoordinator, IBatteryStats batteryStats, JobPackageTracker tracker, Looper looper)322 JobServiceContext(JobSchedulerService service, JobConcurrencyManager concurrencyManager, 323 JobNotificationCoordinator notificationCoordinator, 324 IBatteryStats batteryStats, JobPackageTracker tracker, Looper looper) { 325 mContext = service.getContext(); 326 mLock = service.getLock(); 327 mService = service; 328 mActivityManagerInternal = LocalServices.getService(ActivityManagerInternal.class); 329 mBatteryStats = batteryStats; 330 mJobPackageTracker = tracker; 331 mCallbackHandler = new JobServiceHandler(looper); 332 mJobConcurrencyManager = concurrencyManager; 333 mNotificationCoordinator = notificationCoordinator; 334 mCompletedListener = service; 335 mPowerManager = mContext.getSystemService(PowerManager.class); 336 mUsageStatsManagerInternal = LocalServices.getService(UsageStatsManagerInternal.class); 337 mAvailable = true; 338 mVerb = VERB_FINISHED; 339 mPreferredUid = NO_PREFERRED_UID; 340 } 341 342 /** 343 * Give a job to this context for execution. Callers must first check {@link 344 * #getRunningJobLocked()} 345 * and ensure it is null to make sure this is a valid context. 346 * 347 * @param job The status of the job that we are going to run. 348 * @return True if the job is valid and is running. False if the job cannot be executed. 349 */ executeRunnableJob(JobStatus job, @JobConcurrencyManager.WorkType int workType)350 boolean executeRunnableJob(JobStatus job, @JobConcurrencyManager.WorkType int workType) { 351 synchronized (mLock) { 352 if (!mAvailable) { 353 Slog.e(TAG, "Starting new runnable but context is unavailable > Error."); 354 return false; 355 } 356 357 mPreferredUid = NO_PREFERRED_UID; 358 359 mRunningJob = job; 360 mRunningJobWorkType = workType; 361 mRunningCallback = new JobCallback(); 362 mPendingNetworkChange = null; 363 final boolean isDeadlineExpired = 364 job.hasDeadlineConstraint() && 365 (job.getLatestRunTimeElapsed() < sElapsedRealtimeClock.millis()); 366 Uri[] triggeredUris = null; 367 if (job.changedUris != null) { 368 triggeredUris = new Uri[job.changedUris.size()]; 369 job.changedUris.toArray(triggeredUris); 370 } 371 String[] triggeredAuthorities = null; 372 if (job.changedAuthorities != null) { 373 triggeredAuthorities = new String[job.changedAuthorities.size()]; 374 job.changedAuthorities.toArray(triggeredAuthorities); 375 } 376 final JobInfo ji = job.getJob(); 377 final Network passedNetwork = canGetNetworkInformation(job) ? job.network : null; 378 mParams = new JobParameters(mRunningCallback, job.getNamespace(), job.getJobId(), 379 ji.getExtras(), 380 ji.getTransientExtras(), ji.getClipData(), ji.getClipGrantFlags(), 381 isDeadlineExpired, job.shouldTreatAsExpeditedJob(), 382 job.shouldTreatAsUserInitiatedJob(), triggeredUris, triggeredAuthorities, 383 passedNetwork); 384 mExecutionStartTimeElapsed = sElapsedRealtimeClock.millis(); 385 mLastExecutionDurationStampTimeElapsed = mExecutionStartTimeElapsed; 386 mMinExecutionGuaranteeMillis = mService.getMinJobExecutionGuaranteeMs(job); 387 mMaxExecutionTimeMillis = 388 Math.max(mService.getMaxJobExecutionTimeMs(job), mMinExecutionGuaranteeMillis); 389 mEstimatedDownloadBytes = job.getEstimatedNetworkDownloadBytes(); 390 mEstimatedUploadBytes = job.getEstimatedNetworkUploadBytes(); 391 mTransferredDownloadBytes = mTransferredUploadBytes = 0; 392 mAwaitingNotification = job.isUserVisibleJob(); 393 394 final long whenDeferred = job.getWhenStandbyDeferred(); 395 if (whenDeferred > 0) { 396 final long deferral = mExecutionStartTimeElapsed - whenDeferred; 397 EventLog.writeEvent(EventLogTags.JOB_DEFERRED_EXECUTION, deferral); 398 if (DEBUG_STANDBY) { 399 StringBuilder sb = new StringBuilder(128); 400 sb.append("Starting job deferred for standby by "); 401 TimeUtils.formatDuration(deferral, sb); 402 sb.append(" ms : "); 403 sb.append(job.toShortString()); 404 Slog.v(TAG, sb.toString()); 405 } 406 } 407 408 // Once we'e begun executing a job, we by definition no longer care whether 409 // it was inflated from disk with not-yet-coherent delay/deadline bounds. 410 job.clearPersistedUtcTimes(); 411 412 mWakeLock = mPowerManager.newWakeLock(PowerManager.PARTIAL_WAKE_LOCK, 413 job.getWakelockTag()); 414 mWakeLock.setWorkSource( 415 mService.deriveWorkSource(job.getSourceUid(), job.getSourcePackageName())); 416 mWakeLock.setReferenceCounted(false); 417 mWakeLock.acquire(); 418 419 mVerb = VERB_BINDING; 420 scheduleOpTimeOutLocked(); 421 // Use FLAG_FROM_BACKGROUND to avoid resetting the bad-app tracking. 422 final Intent intent = new Intent().setComponent(job.getServiceComponent()) 423 .setFlags(Intent.FLAG_FROM_BACKGROUND); 424 boolean binding = false; 425 boolean startedWithForegroundFlag = false; 426 try { 427 long bindFlags = Context.BIND_AUTO_CREATE | Context.BIND_NOT_APP_COMPONENT_USAGE; 428 if (job.shouldTreatAsUserInitiatedJob() && !job.isUserBgRestricted()) { 429 // If the user has bg restricted the app, don't give the job FG privileges 430 // such as bypassing data saver or getting the higher foreground proc state. 431 // If we've gotten to this point, the app is most likely in the foreground, 432 // so the job will run just fine while the user keeps the app in the foreground. 433 bindFlags |= Context.BIND_ALMOST_PERCEPTIBLE; 434 if (job.hasConnectivityConstraint()) { 435 // Only add network restriction bypass flags if the job requires network. 436 bindFlags |= Context.BIND_BYPASS_POWER_NETWORK_RESTRICTIONS 437 | Context.BIND_BYPASS_USER_NETWORK_RESTRICTIONS; 438 } 439 startedWithForegroundFlag = true; 440 } else if (job.shouldTreatAsExpeditedJob() || job.shouldTreatAsUserInitiatedJob()) { 441 bindFlags |= Context.BIND_NOT_FOREGROUND | Context.BIND_ALMOST_PERCEPTIBLE; 442 if (job.hasConnectivityConstraint()) { 443 // Only add network restriction bypass flags if the job requires network. 444 bindFlags |= Context.BIND_BYPASS_POWER_NETWORK_RESTRICTIONS; 445 } 446 } else { 447 bindFlags |= Context.BIND_NOT_FOREGROUND | Context.BIND_NOT_PERCEPTIBLE; 448 } 449 binding = mContext.bindServiceAsUser(intent, this, 450 Context.BindServiceFlags.of(bindFlags), 451 UserHandle.of(job.getUserId())); 452 } catch (SecurityException e) { 453 // Some permission policy, for example INTERACT_ACROSS_USERS and 454 // android:singleUser, can result in a SecurityException being thrown from 455 // bindServiceAsUser(). If this happens, catch it and fail gracefully. 456 Slog.w(TAG, "Job service " + job.getServiceComponent().getShortClassName() 457 + " cannot be executed: " + e.getMessage()); 458 binding = false; 459 } 460 if (!binding) { 461 if (DEBUG) { 462 Slog.d(TAG, job.getServiceComponent().getShortClassName() + " unavailable."); 463 } 464 mContext.unbindService(this); 465 mRunningJob = null; 466 mRunningJobWorkType = WORK_TYPE_NONE; 467 mRunningCallback = null; 468 mParams = null; 469 mExecutionStartTimeElapsed = 0L; 470 mWakeLock.release(); 471 mVerb = VERB_FINISHED; 472 removeOpTimeOutLocked(); 473 return false; 474 } 475 mJobPackageTracker.noteActive(job); 476 final int sourceUid = job.getSourceUid(); 477 478 // Measure UID baseline traffic for deltas 479 mInitialDownloadedBytesFromSource = TrafficStats.getUidRxBytes(sourceUid); 480 mInitialUploadedBytesFromSource = TrafficStats.getUidTxBytes(sourceUid); 481 482 mInitialDownloadedBytesFromCalling = TrafficStats.getUidRxBytes(job.getUid()); 483 mInitialUploadedBytesFromCalling = TrafficStats.getUidTxBytes(job.getUid()); 484 485 int procState = mService.getUidProcState(job.getUid()); 486 if (Flags.useCorrectProcessStateForLogging() 487 && procState > ActivityManager.PROCESS_STATE_TRANSIENT_BACKGROUND) { 488 // Try to get the latest proc state from AMS, there might be some delay 489 // for the proc states worse than TRANSIENT_BACKGROUND. 490 procState = mActivityManagerInternal.getUidProcessState(job.getUid()); 491 } 492 493 FrameworkStatsLog.write(FrameworkStatsLog.SCHEDULED_JOB_STATE_CHANGED, 494 job.isProxyJob() ? new int[]{sourceUid, job.getUid()} : new int[]{sourceUid}, 495 // Given that the source tag is set by the calling app, it should be connected 496 // to the calling app in the attribution for a proxied job. 497 job.isProxyJob() 498 ? new String[]{null, job.getSourceTag()} 499 : new String[]{job.getSourceTag()}, 500 job.getBatteryName(), 501 FrameworkStatsLog.SCHEDULED_JOB_STATE_CHANGED__STATE__STARTED, 502 JobProtoEnums.INTERNAL_STOP_REASON_UNKNOWN, 503 job.getStandbyBucket(), 504 job.getLoggingJobId(), 505 job.hasChargingConstraint(), 506 job.hasBatteryNotLowConstraint(), 507 job.hasStorageNotLowConstraint(), 508 job.hasTimingDelayConstraint(), 509 job.hasDeadlineConstraint(), 510 job.hasIdleConstraint(), 511 job.hasConnectivityConstraint(), 512 job.hasContentTriggerConstraint(), 513 job.isRequestedExpeditedJob(), 514 job.shouldTreatAsExpeditedJob(), 515 JobProtoEnums.STOP_REASON_UNDEFINED, 516 job.getJob().isPrefetch(), 517 job.getJob().getPriority(), 518 job.getEffectivePriority(), 519 job.getNumPreviousAttempts(), 520 job.getJob().getMaxExecutionDelayMillis(), 521 isDeadlineExpired, 522 job.isConstraintSatisfied(JobInfo.CONSTRAINT_FLAG_CHARGING), 523 job.isConstraintSatisfied(JobInfo.CONSTRAINT_FLAG_BATTERY_NOT_LOW), 524 job.isConstraintSatisfied(JobInfo.CONSTRAINT_FLAG_STORAGE_NOT_LOW), 525 job.isConstraintSatisfied(JobStatus.CONSTRAINT_TIMING_DELAY), 526 job.isConstraintSatisfied(JobInfo.CONSTRAINT_FLAG_DEVICE_IDLE), 527 job.isConstraintSatisfied(JobStatus.CONSTRAINT_CONNECTIVITY), 528 job.isConstraintSatisfied(JobStatus.CONSTRAINT_CONTENT_TRIGGER), 529 mExecutionStartTimeElapsed - job.enqueueTime, 530 job.getJob().isUserInitiated(), 531 job.shouldTreatAsUserInitiatedJob(), 532 job.getJob().isPeriodic(), 533 job.getJob().getMinLatencyMillis(), 534 job.getEstimatedNetworkDownloadBytes(), 535 job.getEstimatedNetworkUploadBytes(), 536 job.getWorkCount(), 537 ActivityManager.processStateAmToProto(procState), 538 job.getNamespaceHash(), 539 /* system_measured_source_download_bytes */ 0, 540 /* system_measured_source_upload_bytes */ 0, 541 /* system_measured_calling_download_bytes */ 0, 542 /* system_measured_calling_upload_bytes */ 0, 543 job.getJob().getIntervalMillis(), 544 job.getJob().getFlexMillis(), 545 job.hasFlexibilityConstraint(), 546 job.isConstraintSatisfied(JobStatus.CONSTRAINT_FLEXIBLE), 547 job.canApplyTransportAffinities(), 548 job.getNumAppliedFlexibleConstraints(), 549 job.getNumDroppedFlexibleConstraints(), 550 job.getFilteredTraceTag(), 551 job.getFilteredDebugTags(), 552 job.getNumAbandonedFailures(), 553 /* 0 is reserved for UNKNOWN_POLICY */ 554 job.getJob().getBackoffPolicy() + 1, 555 mService.shouldUseAggressiveBackoff( 556 job.getNumAbandonedFailures(), job.getSourceUid())); 557 sEnqueuedJwiAtJobStart.logSampleWithUid(job.getUid(), job.getWorkCount()); 558 final String sourcePackage = job.getSourcePackageName(); 559 if (Trace.isTagEnabled(Trace.TRACE_TAG_SYSTEM_SERVER)) { 560 // Use the context's ID to distinguish traces since there'll only be one job 561 // running per context. 562 Trace.asyncTraceForTrackBegin(Trace.TRACE_TAG_SYSTEM_SERVER, 563 JobSchedulerService.TRACE_TRACK_NAME, job.computeSystemTraceTag(), 564 getId()); 565 } 566 if (job.getAppTraceTag() != null) { 567 // Use the job's ID to distinguish traces since the ID will be unique per app. 568 Trace.asyncTraceForTrackBegin(Trace.TRACE_TAG_APP, 569 JobSchedulerService.TRACE_TRACK_NAME, job.getAppTraceTag(), 570 job.getJobId()); 571 } 572 try { 573 mBatteryStats.noteJobStart(job.getBatteryName(), job.getSourceUid()); 574 } catch (RemoteException e) { 575 // Whatever. 576 } 577 final int jobUserId = job.getSourceUserId(); 578 mUsageStatsManagerInternal 579 .setLastJobRunTime(sourcePackage, jobUserId, mExecutionStartTimeElapsed); 580 mAvailable = false; 581 mStoppedReason = null; 582 mStoppedTime = 0; 583 // Wait until after bindService() returns a success value to set these so we don't 584 // have JobStatus objects that aren't running but have these set to true. 585 job.startedAsExpeditedJob = job.shouldTreatAsExpeditedJob(); 586 job.startedAsUserInitiatedJob = job.shouldTreatAsUserInitiatedJob(); 587 job.startedWithForegroundFlag = startedWithForegroundFlag; 588 return true; 589 } 590 } 591 canGetNetworkInformation(@onNull JobStatus job)592 private boolean canGetNetworkInformation(@NonNull JobStatus job) { 593 if (job.getJob().getRequiredNetwork() == null) { 594 // The job never had a network constraint, so we're not going to give it a network 595 // object. Add this check as an early return to avoid wasting cycles doing permission 596 // checks for this job. 597 return false; 598 } 599 // The calling app is doing the work, so use its UID, not the source UID. 600 final int uid = job.getUid(); 601 if (CompatChanges.isChangeEnabled( 602 JobSchedulerService.REQUIRE_NETWORK_PERMISSIONS_FOR_CONNECTIVITY_JOBS, uid)) { 603 final String pkgName = job.getServiceComponent().getPackageName(); 604 if (!hasPermissionForDelivery(uid, pkgName, Manifest.permission.ACCESS_NETWORK_STATE)) { 605 return false; 606 } 607 } 608 609 return true; 610 } 611 hasPermissionForDelivery(int uid, @NonNull String pkgName, @NonNull String permission)612 private boolean hasPermissionForDelivery(int uid, @NonNull String pkgName, 613 @NonNull String permission) { 614 final int result = PermissionChecker.checkPermissionForDataDelivery(mContext, permission, 615 PermissionChecker.PID_UNKNOWN, uid, pkgName, /* attributionTag */ null, 616 "network info via JS"); 617 return result == PermissionChecker.PERMISSION_GRANTED; 618 } 619 620 /** 621 * Used externally to query the running job. Will return null if there is no job running. 622 */ 623 @Nullable getRunningJobLocked()624 JobStatus getRunningJobLocked() { 625 return mRunningJob; 626 } 627 628 @VisibleForTesting setRunningJobLockedForTest(JobStatus job)629 void setRunningJobLockedForTest(JobStatus job) { 630 mRunningJob = job; 631 } 632 633 @VisibleForTesting setJobParamsLockedForTest(JobParameters params)634 void setJobParamsLockedForTest(JobParameters params) { 635 mParams = params; 636 } 637 638 @VisibleForTesting setRunningCallbackLockedForTest(JobCallback callback)639 void setRunningCallbackLockedForTest(JobCallback callback) { 640 mRunningCallback = callback; 641 } 642 643 @VisibleForTesting setPendingStopReasonLockedForTest(int stopReason)644 void setPendingStopReasonLockedForTest(int stopReason) { 645 mPendingStopReason = stopReason; 646 } 647 648 @JobConcurrencyManager.WorkType getRunningJobWorkType()649 int getRunningJobWorkType() { 650 return mRunningJobWorkType; 651 } 652 653 /** 654 * Used only for debugging. Will return <code>"<null>"</code> if there is no job running. 655 */ getRunningJobNameLocked()656 private String getRunningJobNameLocked() { 657 return mRunningJob != null ? mRunningJob.toShortString() : "<null>"; 658 } 659 660 /** Called externally when a job that was scheduled for execution should be cancelled. */ 661 @GuardedBy("mLock") cancelExecutingJobLocked(@obParameters.StopReason int reason, int internalStopReason, @NonNull String debugReason)662 void cancelExecutingJobLocked(@JobParameters.StopReason int reason, 663 int internalStopReason, @NonNull String debugReason) { 664 doCancelLocked(reason, internalStopReason, debugReason); 665 } 666 667 /** 668 * Called when an app's process is about to be killed and we want to update the job's stop 669 * reasons without telling the job it's going to be stopped. 670 */ 671 @GuardedBy("mLock") markForProcessDeathLocked(@obParameters.StopReason int reason, int internalStopReason, @NonNull String debugReason)672 void markForProcessDeathLocked(@JobParameters.StopReason int reason, 673 int internalStopReason, @NonNull String debugReason) { 674 if (mVerb == VERB_FINISHED) { 675 if (DEBUG) { 676 Slog.d(TAG, "Too late to mark for death (verb=" + mVerb + "), ignoring."); 677 } 678 return; 679 } 680 if (DEBUG) { 681 Slog.d(TAG, 682 "Marking " + mRunningJob.toShortString() + " for death because " 683 + reason + ":" + debugReason); 684 } 685 mDeathMarkStopReason = reason; 686 mDeathMarkInternalStopReason = internalStopReason; 687 mDeathMarkDebugReason = debugReason; 688 if (mParams.getStopReason() == JobParameters.STOP_REASON_UNDEFINED) { 689 // Only set the stop reason if we're not already trying to stop the job for some 690 // other reason in case that other stop is successful before the process dies. 691 mParams.setStopReason(reason, internalStopReason, debugReason); 692 } 693 } 694 getPreferredUid()695 int getPreferredUid() { 696 return mPreferredUid; 697 } 698 clearPreferredUid()699 void clearPreferredUid() { 700 mPreferredUid = NO_PREFERRED_UID; 701 } 702 getId()703 int getId() { 704 return hashCode(); 705 } 706 getExecutionStartTimeElapsed()707 long getExecutionStartTimeElapsed() { 708 return mExecutionStartTimeElapsed; 709 } 710 getTimeoutElapsed()711 long getTimeoutElapsed() { 712 return mTimeoutElapsed; 713 } 714 getRemainingGuaranteedTimeMs(long nowElapsed)715 long getRemainingGuaranteedTimeMs(long nowElapsed) { 716 return Math.max(0, mExecutionStartTimeElapsed + mMinExecutionGuaranteeMillis - nowElapsed); 717 } 718 informOfNetworkChangeLocked(Network newNetwork)719 void informOfNetworkChangeLocked(Network newNetwork) { 720 if (newNetwork != null && mRunningJob != null && !canGetNetworkInformation(mRunningJob)) { 721 // The app can't get network information, so there's no point informing it of network 722 // changes. This case may happen if an app had scheduled network job and then 723 // started targeting U+ without requesting the required network permissions. 724 if (DEBUG) { 725 Slog.d(TAG, "Skipping network change call because of missing permissions"); 726 } 727 return; 728 } 729 if (mVerb != VERB_EXECUTING) { 730 Slog.w(TAG, "Sending onNetworkChanged for a job that isn't started. " + mRunningJob); 731 if (mVerb == VERB_BINDING || mVerb == VERB_STARTING) { 732 // The network changed before the job has fully started. Hold the change push 733 // until the job has started executing. 734 mPendingNetworkChange = newNetwork; 735 } 736 return; 737 } 738 try { 739 mParams.setNetwork(newNetwork); 740 mPendingNetworkChange = null; 741 service.onNetworkChanged(mParams); 742 } catch (RemoteException e) { 743 Slog.e(TAG, "Error sending onNetworkChanged to client.", e); 744 // The job's host app apparently crashed during the job, so we should reschedule. 745 closeAndCleanupJobLocked(/* reschedule */ true, 746 "host crashed when trying to inform of network change"); 747 } 748 } 749 isWithinExecutionGuaranteeTime()750 boolean isWithinExecutionGuaranteeTime() { 751 return sElapsedRealtimeClock.millis() 752 < mExecutionStartTimeElapsed + mMinExecutionGuaranteeMillis; 753 } 754 755 @GuardedBy("mLock") stopIfExecutingLocked(String pkgName, int userId, @Nullable String namespace, boolean matchJobId, int jobId, int stopReason, int internalStopReason)756 boolean stopIfExecutingLocked(String pkgName, int userId, @Nullable String namespace, 757 boolean matchJobId, int jobId, int stopReason, int internalStopReason) { 758 final JobStatus executing = getRunningJobLocked(); 759 if (executing != null && (userId == UserHandle.USER_ALL || userId == executing.getUserId()) 760 && (pkgName == null || pkgName.equals(executing.getSourcePackageName())) 761 && Objects.equals(namespace, executing.getNamespace()) 762 && (!matchJobId || jobId == executing.getJobId())) { 763 if (mVerb == VERB_EXECUTING) { 764 mParams.setStopReason(stopReason, internalStopReason, "stop from shell"); 765 sendStopMessageLocked("stop from shell"); 766 return true; 767 } 768 } 769 return false; 770 } 771 772 @GuardedBy("mLock") getEstimatedNetworkBytes()773 Pair<Long, Long> getEstimatedNetworkBytes() { 774 return Pair.create(mEstimatedDownloadBytes, mEstimatedUploadBytes); 775 } 776 777 @GuardedBy("mLock") getTransferredNetworkBytes()778 Pair<Long, Long> getTransferredNetworkBytes() { 779 return Pair.create(mTransferredDownloadBytes, mTransferredUploadBytes); 780 } 781 doJobFinished(JobCallback cb, int jobId, boolean reschedule)782 void doJobFinished(JobCallback cb, int jobId, boolean reschedule) { 783 final long ident = Binder.clearCallingIdentity(); 784 try { 785 synchronized (mLock) { 786 if (!verifyCallerLocked(cb)) { 787 return; 788 } 789 mParams.setStopReason(JobParameters.STOP_REASON_UNDEFINED, 790 JobParameters.INTERNAL_STOP_REASON_SUCCESSFUL_FINISH, 791 "app called jobFinished"); 792 doCallbackLocked(reschedule, "app called jobFinished"); 793 } 794 } finally { 795 Binder.restoreCallingIdentity(ident); 796 } 797 } 798 799 /** 800 * This method just adds traces to evaluate jobs that leak jobparameters at the client. 801 * It does not stop the job. 802 */ doHandleAbandonedJob(JobCallback cb, int jobId)803 void doHandleAbandonedJob(JobCallback cb, int jobId) { 804 final long ident = Binder.clearCallingIdentity(); 805 try { 806 final JobStatus executing; 807 synchronized (mLock) { 808 // not the current job, presumably it has finished in some way already 809 if (!verifyCallerLocked(cb)) { 810 return; 811 } 812 if (mVerb != VERB_EXECUTING) { 813 // Any state other than executing means the 814 // job is in transient or stopped state 815 return; 816 } 817 executing = getRunningJobLocked(); 818 } 819 if (executing != null && jobId == executing.getJobId()) { 820 executing.setAbandoned(true); 821 final StringBuilder stateSuffix = new StringBuilder(); 822 stateSuffix.append(TRACE_ABANDONED_JOB); 823 stateSuffix.append(executing.getBatteryName()); 824 stateSuffix.append(TRACE_ABANDONED_JOB_DELIMITER); 825 stateSuffix.append(executing.getJobId()); 826 Trace.instant(Trace.TRACE_TAG_POWER, stateSuffix.toString()); 827 } 828 } finally { 829 Binder.restoreCallingIdentity(ident); 830 } 831 } 832 doAcknowledgeGetTransferredDownloadBytesMessage(JobCallback cb, int jobId, int workId, @BytesLong long transferredBytes)833 private void doAcknowledgeGetTransferredDownloadBytesMessage(JobCallback cb, int jobId, 834 int workId, @BytesLong long transferredBytes) { 835 // TODO(255393346): Make sure apps call this appropriately and monitor for abuse 836 synchronized (mLock) { 837 if (!verifyCallerLocked(cb)) { 838 return; 839 } 840 mTransferredDownloadBytes = transferredBytes; 841 } 842 } 843 doAcknowledgeGetTransferredUploadBytesMessage(JobCallback cb, int jobId, int workId, @BytesLong long transferredBytes)844 private void doAcknowledgeGetTransferredUploadBytesMessage(JobCallback cb, int jobId, 845 int workId, @BytesLong long transferredBytes) { 846 // TODO(255393346): Make sure apps call this appropriately and monitor for abuse 847 synchronized (mLock) { 848 if (!verifyCallerLocked(cb)) { 849 return; 850 } 851 mTransferredUploadBytes = transferredBytes; 852 } 853 } 854 doAcknowledgeStopMessage(JobCallback cb, int jobId, boolean reschedule)855 void doAcknowledgeStopMessage(JobCallback cb, int jobId, boolean reschedule) { 856 doCallback(cb, reschedule, null); 857 } 858 doAcknowledgeStartMessage(JobCallback cb, int jobId, boolean ongoing)859 void doAcknowledgeStartMessage(JobCallback cb, int jobId, boolean ongoing) { 860 doCallback(cb, ongoing, "finished start"); 861 } 862 doDequeueWork(JobCallback cb, int jobId)863 JobWorkItem doDequeueWork(JobCallback cb, int jobId) { 864 final long ident = Binder.clearCallingIdentity(); 865 try { 866 synchronized (mLock) { 867 if (!assertCallerLocked(cb)) { 868 return null; 869 } 870 if (mVerb == VERB_STOPPING || mVerb == VERB_FINISHED) { 871 // This job is either all done, or on its way out. Either way, it 872 // should not dispatch any more work. We will pick up any remaining 873 // work the next time we start the job again. 874 return null; 875 } 876 final JobWorkItem work = mRunningJob.dequeueWorkLocked(); 877 if (work == null && !mRunningJob.hasExecutingWorkLocked()) { 878 mParams.setStopReason(JobParameters.STOP_REASON_UNDEFINED, 879 JobParameters.INTERNAL_STOP_REASON_SUCCESSFUL_FINISH, 880 "last work dequeued"); 881 // This will finish the job. 882 doCallbackLocked(false, "last work dequeued"); 883 } else if (work != null) { 884 // Delivery count has been updated, so persist JobWorkItem change. 885 mService.mJobs.touchJob(mRunningJob); 886 } 887 return work; 888 } 889 } finally { 890 Binder.restoreCallingIdentity(ident); 891 } 892 } 893 doCompleteWork(JobCallback cb, int jobId, int workId)894 boolean doCompleteWork(JobCallback cb, int jobId, int workId) { 895 final long ident = Binder.clearCallingIdentity(); 896 try { 897 synchronized (mLock) { 898 if (!assertCallerLocked(cb)) { 899 // Return true instead of false here so we don't just kick the 900 // Exception-throwing-can down the road to JobParameters.completeWork >:( 901 return true; 902 } 903 if (mRunningJob.completeWorkLocked(workId)) { 904 mService.mJobs.touchJob(mRunningJob); 905 return true; 906 } 907 return false; 908 } 909 } finally { 910 Binder.restoreCallingIdentity(ident); 911 } 912 } 913 doUpdateEstimatedNetworkBytes(JobCallback cb, int jobId, @Nullable JobWorkItem item, long downloadBytes, long uploadBytes)914 private void doUpdateEstimatedNetworkBytes(JobCallback cb, int jobId, 915 @Nullable JobWorkItem item, long downloadBytes, long uploadBytes) { 916 // TODO(255393346): Make sure apps call this appropriately and monitor for abuse 917 synchronized (mLock) { 918 if (!verifyCallerLocked(cb)) { 919 return; 920 } 921 Counter.logIncrementWithUid( 922 "job_scheduler.value_cntr_w_uid_estimated_network_bytes_updated", 923 mRunningJob.getUid()); 924 sUpdatedEstimatedNetworkDownloadKBLogger.logSample( 925 safelyScaleBytesToKBForHistogram(downloadBytes)); 926 sUpdatedEstimatedNetworkUploadKBLogger.logSample( 927 safelyScaleBytesToKBForHistogram(uploadBytes)); 928 if (mEstimatedDownloadBytes != JobInfo.NETWORK_BYTES_UNKNOWN 929 && downloadBytes != JobInfo.NETWORK_BYTES_UNKNOWN) { 930 if (mEstimatedDownloadBytes < downloadBytes) { 931 Counter.logIncrementWithUid( 932 "job_scheduler." 933 + "value_cntr_w_uid_estimated_network_download_bytes_increased", 934 mRunningJob.getUid()); 935 } else if (mEstimatedDownloadBytes > downloadBytes) { 936 Counter.logIncrementWithUid( 937 "job_scheduler." 938 + "value_cntr_w_uid_estimated_network_download_bytes_decreased", 939 mRunningJob.getUid()); 940 } 941 } 942 if (mEstimatedUploadBytes != JobInfo.NETWORK_BYTES_UNKNOWN 943 && uploadBytes != JobInfo.NETWORK_BYTES_UNKNOWN) { 944 if (mEstimatedUploadBytes < uploadBytes) { 945 Counter.logIncrementWithUid( 946 "job_scheduler" 947 + ".value_cntr_w_uid_estimated_network_upload_bytes_increased", 948 mRunningJob.getUid()); 949 } else if (mEstimatedUploadBytes > uploadBytes) { 950 Counter.logIncrementWithUid( 951 "job_scheduler" 952 + ".value_cntr_w_uid_estimated_network_upload_bytes_decreased", 953 mRunningJob.getUid()); 954 } 955 } 956 mEstimatedDownloadBytes = downloadBytes; 957 mEstimatedUploadBytes = uploadBytes; 958 } 959 } 960 doUpdateTransferredNetworkBytes(JobCallback cb, int jobId, @Nullable JobWorkItem item, long downloadBytes, long uploadBytes)961 private void doUpdateTransferredNetworkBytes(JobCallback cb, int jobId, 962 @Nullable JobWorkItem item, long downloadBytes, long uploadBytes) { 963 // TODO(255393346): Make sure apps call this appropriately and monitor for abuse 964 synchronized (mLock) { 965 if (!verifyCallerLocked(cb)) { 966 return; 967 } 968 Counter.logIncrementWithUid( 969 "job_scheduler.value_cntr_w_uid_transferred_network_bytes_updated", 970 mRunningJob.getUid()); 971 sTransferredNetworkDownloadKBHighWaterMarkLogger.logSample( 972 safelyScaleBytesToKBForHistogram(downloadBytes)); 973 sTransferredNetworkUploadKBHighWaterMarkLogger.logSample( 974 safelyScaleBytesToKBForHistogram(uploadBytes)); 975 if (mTransferredDownloadBytes != JobInfo.NETWORK_BYTES_UNKNOWN 976 && downloadBytes != JobInfo.NETWORK_BYTES_UNKNOWN) { 977 if (mTransferredDownloadBytes < downloadBytes) { 978 Counter.logIncrementWithUid( 979 "job_scheduler." 980 + "value_cntr_w_uid_transferred_network_download_bytes_increased", 981 mRunningJob.getUid()); 982 } else if (mTransferredDownloadBytes > downloadBytes) { 983 Counter.logIncrementWithUid( 984 "job_scheduler." 985 + "value_cntr_w_uid_transferred_network_download_bytes_decreased", 986 mRunningJob.getUid()); 987 } 988 } 989 if (mTransferredUploadBytes != JobInfo.NETWORK_BYTES_UNKNOWN 990 && uploadBytes != JobInfo.NETWORK_BYTES_UNKNOWN) { 991 if (mTransferredUploadBytes < uploadBytes) { 992 Counter.logIncrementWithUid( 993 "job_scheduler." 994 + "value_cntr_w_uid_transferred_network_upload_bytes_increased", 995 mRunningJob.getUid()); 996 } else if (mTransferredUploadBytes > uploadBytes) { 997 Counter.logIncrementWithUid( 998 "job_scheduler." 999 + "value_cntr_w_uid_transferred_network_upload_bytes_decreased", 1000 mRunningJob.getUid()); 1001 } 1002 } 1003 mTransferredDownloadBytes = downloadBytes; 1004 mTransferredUploadBytes = uploadBytes; 1005 } 1006 } 1007 doSetNotification(JobCallback cb, int jodId, int notificationId, Notification notification, int jobEndNotificationPolicy)1008 private void doSetNotification(JobCallback cb, int jodId, int notificationId, 1009 Notification notification, int jobEndNotificationPolicy) { 1010 final int callingPid = Binder.getCallingPid(); 1011 final int callingUid = Binder.getCallingUid(); 1012 final long ident = Binder.clearCallingIdentity(); 1013 try { 1014 synchronized (mLock) { 1015 if (!verifyCallerLocked(cb)) { 1016 return; 1017 } 1018 if (callingUid != mRunningJob.getUid()) { 1019 Slog.wtfStack(TAG, "Calling UID isn't the same as running job's UID..."); 1020 throw new SecurityException("Can't post notification on behalf of another app"); 1021 } 1022 final String callingPkgName = mRunningJob.getServiceComponent().getPackageName(); 1023 mNotificationCoordinator.enqueueNotification(this, callingPkgName, 1024 callingPid, callingUid, notificationId, 1025 notification, jobEndNotificationPolicy); 1026 if (mAwaitingNotification) { 1027 mAwaitingNotification = false; 1028 if (mVerb == VERB_EXECUTING) { 1029 scheduleOpTimeOutLocked(); 1030 } 1031 } 1032 } 1033 } finally { 1034 Binder.restoreCallingIdentity(ident); 1035 } 1036 } 1037 1038 /** 1039 * We acquire/release a wakelock on onServiceConnected/unbindService. This mirrors the work 1040 * we intend to send to the client - we stop sending work when the service is unbound so until 1041 * then we keep the wakelock. 1042 * @param name The concrete component name of the service that has been connected. 1043 * @param service The IBinder of the Service's communication channel, 1044 */ 1045 @Override onServiceConnected(ComponentName name, IBinder service)1046 public void onServiceConnected(ComponentName name, IBinder service) { 1047 JobStatus runningJob; 1048 synchronized (mLock) { 1049 // This isn't strictly necessary b/c the JobServiceHandler is running on the main 1050 // looper and at this point we can't get any binder callbacks from the client. Better 1051 // safe than sorry. 1052 runningJob = mRunningJob; 1053 1054 if (runningJob == null || !name.equals(runningJob.getServiceComponent())) { 1055 closeAndCleanupJobLocked(true /* needsReschedule */, 1056 "connected for different component"); 1057 return; 1058 } 1059 this.service = IJobService.Stub.asInterface(service); 1060 doServiceBoundLocked(); 1061 } 1062 } 1063 1064 /** If the client service crashes we reschedule this job and clean up. */ 1065 @Override onServiceDisconnected(ComponentName name)1066 public void onServiceDisconnected(ComponentName name) { 1067 synchronized (mLock) { 1068 if (mDeathMarkStopReason != JobParameters.STOP_REASON_UNDEFINED) { 1069 // Service "unexpectedly" disconnected, but we knew the process was going to die. 1070 // Use that as the stop reason for logging/debugging purposes. 1071 mParams.setStopReason( 1072 mDeathMarkStopReason, mDeathMarkInternalStopReason, mDeathMarkDebugReason); 1073 } else if (mRunningJob != null) { 1074 Counter.logIncrementWithUid( 1075 "job_scheduler.value_cntr_w_uid_unexpected_service_disconnects", 1076 // Use the calling UID since that's the one this context was connected to. 1077 mRunningJob.getUid()); 1078 } 1079 closeAndCleanupJobLocked(true /* needsReschedule */, "unexpectedly disconnected"); 1080 } 1081 } 1082 1083 @Override onBindingDied(ComponentName name)1084 public void onBindingDied(ComponentName name) { 1085 synchronized (mLock) { 1086 if (mRunningJob == null) { 1087 Slog.e(TAG, "Binding died for " + name.getPackageName() 1088 + " but no running job on this context"); 1089 } else if (mRunningJob.getServiceComponent().equals(name)) { 1090 Slog.e(TAG, "Binding died for " 1091 + mRunningJob.getSourceUserId() + ":" + name.getPackageName()); 1092 } else { 1093 Slog.e(TAG, "Binding died for " + name.getPackageName() 1094 + " but context is running a different job"); 1095 } 1096 closeAndCleanupJobLocked(true /* needsReschedule */, "binding died"); 1097 } 1098 } 1099 1100 @Override onNullBinding(ComponentName name)1101 public void onNullBinding(ComponentName name) { 1102 synchronized (mLock) { 1103 if (mRunningJob == null) { 1104 Slog.wtf(TAG, "Got null binding for " + name.getPackageName() 1105 + " but no running job on this context"); 1106 } else if (mRunningJob.getServiceComponent().equals(name)) { 1107 Slog.wtf(TAG, "Got null binding for " 1108 + mRunningJob.getSourceUserId() + ":" + name.getPackageName()); 1109 } else { 1110 Slog.wtf(TAG, "Got null binding for " + name.getPackageName() 1111 + " but context is running a different job"); 1112 } 1113 // Don't reschedule the job since returning a null binding is an explicit choice by the 1114 // app which breaks things. 1115 closeAndCleanupJobLocked(false /* needsReschedule */, "null binding"); 1116 } 1117 } 1118 1119 /** 1120 * This class is reused across different clients, and passes itself in as a callback. Check 1121 * whether the client exercising the callback is the client we expect. 1122 * @return True if the binder calling is coming from the client we expect. 1123 */ verifyCallerLocked(JobCallback cb)1124 private boolean verifyCallerLocked(JobCallback cb) { 1125 if (mRunningCallback != cb) { 1126 if (DEBUG) { 1127 Slog.d(TAG, "Stale callback received, ignoring."); 1128 } 1129 return false; 1130 } 1131 return true; 1132 } 1133 1134 /** 1135 * Will throw a {@link SecurityException} if the callback is not for the currently running job, 1136 * but may decide not to throw an exception if the call from the previous job appears to be an 1137 * accident. 1138 * 1139 * @return true if the callback is for the current job, false otherwise 1140 */ assertCallerLocked(JobCallback cb)1141 private boolean assertCallerLocked(JobCallback cb) { 1142 if (!verifyCallerLocked(cb)) { 1143 final long nowElapsed = sElapsedRealtimeClock.millis(); 1144 if (!mPreviousJobHadSuccessfulFinish 1145 && (nowElapsed - mLastUnsuccessfulFinishElapsed) < 15_000L) { 1146 // Don't punish apps for race conditions 1147 return false; 1148 } 1149 // It's been long enough that the app should really not be calling into JS for the 1150 // stopped job. 1151 StringBuilder sb = new StringBuilder(128); 1152 sb.append("Caller no longer running"); 1153 if (cb.mStoppedReason != null) { 1154 sb.append(", last stopped "); 1155 TimeUtils.formatDuration(nowElapsed - cb.mStoppedTime, sb); 1156 sb.append(" because: "); 1157 sb.append(cb.mStoppedReason); 1158 } 1159 throw new SecurityException(sb.toString()); 1160 } 1161 return true; 1162 } 1163 1164 /** 1165 * Scheduling of async messages (basically timeouts at this point). 1166 */ 1167 private class JobServiceHandler extends Handler { JobServiceHandler(Looper looper)1168 JobServiceHandler(Looper looper) { 1169 super(looper); 1170 } 1171 1172 @Override handleMessage(Message message)1173 public void handleMessage(Message message) { 1174 switch (message.what) { 1175 case MSG_TIMEOUT: 1176 synchronized (mLock) { 1177 if (message.obj == mRunningCallback) { 1178 handleOpTimeoutLocked(); 1179 } else { 1180 JobCallback jc = (JobCallback)message.obj; 1181 StringBuilder sb = new StringBuilder(128); 1182 sb.append("Ignoring timeout of no longer active job"); 1183 if (jc.mStoppedReason != null) { 1184 sb.append(", stopped "); 1185 TimeUtils.formatDuration(sElapsedRealtimeClock.millis() 1186 - jc.mStoppedTime, sb); 1187 sb.append(" because: "); 1188 sb.append(jc.mStoppedReason); 1189 } 1190 Slog.w(TAG, sb.toString()); 1191 } 1192 } 1193 break; 1194 default: 1195 Slog.e(TAG, "Unrecognised message: " + message); 1196 } 1197 } 1198 } 1199 1200 @GuardedBy("mLock") doServiceBoundLocked()1201 void doServiceBoundLocked() { 1202 removeOpTimeOutLocked(); 1203 handleServiceBoundLocked(); 1204 } 1205 doCallback(JobCallback cb, boolean reschedule, String reason)1206 void doCallback(JobCallback cb, boolean reschedule, String reason) { 1207 final long ident = Binder.clearCallingIdentity(); 1208 try { 1209 synchronized (mLock) { 1210 if (!verifyCallerLocked(cb)) { 1211 return; 1212 } 1213 doCallbackLocked(reschedule, reason); 1214 } 1215 } finally { 1216 Binder.restoreCallingIdentity(ident); 1217 } 1218 } 1219 1220 @GuardedBy("mLock") doCallbackLocked(boolean reschedule, String reason)1221 void doCallbackLocked(boolean reschedule, String reason) { 1222 if (DEBUG) { 1223 Slog.d(TAG, "doCallback of : " + mRunningJob 1224 + " v:" + VERB_STRINGS[mVerb]); 1225 } 1226 removeOpTimeOutLocked(); 1227 1228 if (mVerb == VERB_STARTING) { 1229 handleStartedLocked(reschedule); 1230 } else if (mVerb == VERB_EXECUTING || 1231 mVerb == VERB_STOPPING) { 1232 handleFinishedLocked(reschedule, reason); 1233 } else { 1234 if (DEBUG) { 1235 Slog.d(TAG, "Unrecognised callback: " + mRunningJob); 1236 } 1237 } 1238 } 1239 1240 @GuardedBy("mLock") doCancelLocked(@obParameters.StopReason int stopReasonCode, int internalStopReasonCode, @Nullable String debugReason)1241 private void doCancelLocked(@JobParameters.StopReason int stopReasonCode, 1242 int internalStopReasonCode, @Nullable String debugReason) { 1243 if (mVerb == VERB_FINISHED || mVerb == VERB_STOPPING) { 1244 if (DEBUG) { 1245 Slog.d(TAG, 1246 "Too late to process cancel for context (verb=" + mVerb + "), ignoring."); 1247 } 1248 return; 1249 } 1250 if (mRunningJob.startedAsExpeditedJob 1251 && stopReasonCode == JobParameters.STOP_REASON_QUOTA) { 1252 // EJs should be able to run for at least the min upper limit regardless of quota. 1253 final long earliestStopTimeElapsed = 1254 mExecutionStartTimeElapsed + mMinExecutionGuaranteeMillis; 1255 final long nowElapsed = sElapsedRealtimeClock.millis(); 1256 if (nowElapsed < earliestStopTimeElapsed) { 1257 mPendingStopReason = stopReasonCode; 1258 mPendingInternalStopReason = internalStopReasonCode; 1259 mPendingDebugStopReason = debugReason; 1260 return; 1261 } 1262 } 1263 mParams.setStopReason(stopReasonCode, internalStopReasonCode, debugReason); 1264 if (stopReasonCode == JobParameters.STOP_REASON_PREEMPT) { 1265 // Only preserve the UID when we're preempting the job for another one of the same UID. 1266 mPreferredUid = mRunningJob != null ? mRunningJob.getUid() : NO_PREFERRED_UID; 1267 } 1268 handleCancelLocked(debugReason); 1269 } 1270 1271 /** Start the job on the service. */ 1272 @GuardedBy("mLock") handleServiceBoundLocked()1273 private void handleServiceBoundLocked() { 1274 if (DEBUG) { 1275 Slog.d(TAG, "handleServiceBound for " + getRunningJobNameLocked()); 1276 } 1277 if (mVerb != VERB_BINDING) { 1278 Slog.e(TAG, "Sending onStartJob for a job that isn't pending. " 1279 + VERB_STRINGS[mVerb]); 1280 closeAndCleanupJobLocked(false /* reschedule */, "started job not pending"); 1281 return; 1282 } 1283 if (mCancelled) { 1284 if (DEBUG) { 1285 Slog.d(TAG, "Job cancelled while waiting for bind to complete. " 1286 + mRunningJob); 1287 } 1288 closeAndCleanupJobLocked(true /* reschedule */, "cancelled while waiting for bind"); 1289 return; 1290 } 1291 try { 1292 mVerb = VERB_STARTING; 1293 scheduleOpTimeOutLocked(); 1294 service.startJob(mParams); 1295 } catch (Exception e) { 1296 // We catch 'Exception' because client-app malice or bugs might induce a wide 1297 // range of possible exception-throw outcomes from startJob() and its handling 1298 // of the client's ParcelableBundle extras. 1299 Slog.e(TAG, "Error sending onStart message to '" + 1300 mRunningJob.getServiceComponent().getShortClassName() + "' ", e); 1301 } 1302 } 1303 1304 /** 1305 * State behaviours. 1306 * VERB_STARTING -> Successful start, change job to VERB_EXECUTING and post timeout. 1307 * _PENDING -> Error 1308 * _EXECUTING -> Error 1309 * _STOPPING -> Error 1310 */ 1311 @GuardedBy("mLock") handleStartedLocked(boolean workOngoing)1312 private void handleStartedLocked(boolean workOngoing) { 1313 switch (mVerb) { 1314 case VERB_STARTING: 1315 mVerb = VERB_EXECUTING; 1316 if (!workOngoing) { 1317 // Job is finished already so fast-forward to handleFinished. 1318 handleFinishedLocked(false, "onStartJob returned false"); 1319 return; 1320 } 1321 if (mCancelled) { 1322 if (DEBUG) { 1323 Slog.d(TAG, "Job cancelled while waiting for onStartJob to complete."); 1324 } 1325 // Cancelled *while* waiting for acknowledgeStartMessage from client. 1326 handleCancelLocked(null); 1327 return; 1328 } 1329 scheduleOpTimeOutLocked(); 1330 if (mPendingNetworkChange != null 1331 && !Objects.equals(mParams.getNetwork(), mPendingNetworkChange)) { 1332 informOfNetworkChangeLocked(mPendingNetworkChange); 1333 } 1334 if (mRunningJob.isUserVisibleJob()) { 1335 mService.informObserversOfUserVisibleJobChange(this, mRunningJob, true); 1336 } 1337 break; 1338 default: 1339 Slog.e(TAG, "Handling started job but job wasn't starting! Was " 1340 + VERB_STRINGS[mVerb] + "."); 1341 return; 1342 } 1343 } 1344 1345 /** 1346 * VERB_EXECUTING -> Client called jobFinished(), clean up and notify done. 1347 * _STOPPING -> Successful finish, clean up and notify done. 1348 * _STARTING -> Error 1349 * _PENDING -> Error 1350 */ 1351 @GuardedBy("mLock") handleFinishedLocked(boolean reschedule, String reason)1352 private void handleFinishedLocked(boolean reschedule, String reason) { 1353 switch (mVerb) { 1354 case VERB_EXECUTING: 1355 case VERB_STOPPING: 1356 closeAndCleanupJobLocked(reschedule, reason); 1357 break; 1358 default: 1359 Slog.e(TAG, "Got an execution complete message for a job that wasn't being" + 1360 "executed. Was " + VERB_STRINGS[mVerb] + "."); 1361 } 1362 } 1363 1364 /** 1365 * A job can be in various states when a cancel request comes in: 1366 * VERB_BINDING -> Cancelled before bind completed. Mark as cancelled and wait for 1367 * {@link #onServiceConnected(android.content.ComponentName, android.os.IBinder)} 1368 * _STARTING -> Mark as cancelled and wait for 1369 * {@link JobServiceContext#doAcknowledgeStartMessage} 1370 * _EXECUTING -> call {@link #sendStopMessageLocked}}, but only if there are no callbacks 1371 * in the message queue. 1372 * _ENDING -> No point in doing anything here, so we ignore. 1373 */ 1374 @GuardedBy("mLock") handleCancelLocked(@ullable String reason)1375 private void handleCancelLocked(@Nullable String reason) { 1376 if (JobSchedulerService.DEBUG) { 1377 Slog.d(TAG, "Handling cancel for: " + mRunningJob.getJobId() + " " 1378 + VERB_STRINGS[mVerb]); 1379 } 1380 switch (mVerb) { 1381 case VERB_BINDING: 1382 case VERB_STARTING: 1383 mCancelled = true; 1384 applyStoppedReasonLocked(reason); 1385 break; 1386 case VERB_EXECUTING: 1387 sendStopMessageLocked(reason); 1388 break; 1389 case VERB_STOPPING: 1390 // Nada. 1391 break; 1392 default: 1393 Slog.e(TAG, "Cancelling a job without a valid verb: " + mVerb); 1394 break; 1395 } 1396 } 1397 1398 /** Process MSG_TIMEOUT here. */ 1399 @VisibleForTesting 1400 @GuardedBy("mLock") handleOpTimeoutLocked()1401 void handleOpTimeoutLocked() { 1402 switch (mVerb) { 1403 case VERB_BINDING: 1404 // The system may have been too busy. Don't drop the job or trigger an ANR. 1405 onSlowAppResponseLocked(/* reschedule */ true, /* updateStopReasons */ true, 1406 /* texCounterMetricId */ 1407 "job_scheduler.value_cntr_w_uid_slow_app_response_binding", 1408 /* debugReason */ "timed out while binding", 1409 /* anrMessage */ "Timed out while trying to bind", 1410 /* triggerAnr */ false); 1411 break; 1412 case VERB_STARTING: 1413 // Client unresponsive - wedged or failed to respond in time. We don't really 1414 // know what happened so let's log it and notify the JobScheduler 1415 // FINISHED/NO-RETRY. 1416 onSlowAppResponseLocked(/* reschedule */ false, /* updateStopReasons */ true, 1417 /* texCounterMetricId */ 1418 "job_scheduler.value_cntr_w_uid_slow_app_response_on_start_job", 1419 /* debugReason */ "timed out while starting", 1420 /* anrMessage */ "No response to onStartJob", 1421 CompatChanges.isChangeEnabled(ANR_PRE_UDC_APIS_ON_SLOW_RESPONSES, 1422 mRunningJob.getUid())); 1423 break; 1424 case VERB_STOPPING: 1425 // At least we got somewhere, so fail but ask the JobScheduler to reschedule. 1426 // Don't update the stop reasons since we were already stopping the job for some 1427 // other reason. 1428 onSlowAppResponseLocked(/* reschedule */ true, /* updateStopReasons */ false, 1429 /* texCounterMetricId */ 1430 "job_scheduler.value_cntr_w_uid_slow_app_response_on_stop_job", 1431 /* debugReason */ "timed out while stopping", 1432 /* anrMessage */ "No response to onStopJob", 1433 CompatChanges.isChangeEnabled(ANR_PRE_UDC_APIS_ON_SLOW_RESPONSES, 1434 mRunningJob.getUid())); 1435 break; 1436 case VERB_EXECUTING: 1437 if (mPendingStopReason != JobParameters.STOP_REASON_UNDEFINED) { 1438 if (mService.isReadyToBeExecutedLocked(mRunningJob, false)) { 1439 // Job became ready again while we were waiting to stop it (for example, 1440 // the device was temporarily taken off the charger). Ignore the pending 1441 // stop and see what the manager says. 1442 mPendingStopReason = JobParameters.STOP_REASON_UNDEFINED; 1443 mPendingInternalStopReason = 0; 1444 mPendingDebugStopReason = null; 1445 } else { 1446 Slog.i(TAG, "JS was waiting to stop this job." 1447 + " Sending onStop: " + getRunningJobNameLocked()); 1448 mParams.setStopReason(mPendingStopReason, mPendingInternalStopReason, 1449 mPendingDebugStopReason); 1450 sendStopMessageLocked(mPendingDebugStopReason); 1451 break; 1452 } 1453 } 1454 final long latestStopTimeElapsed = 1455 mExecutionStartTimeElapsed + mMaxExecutionTimeMillis; 1456 final long earliestStopTimeElapsed = 1457 mExecutionStartTimeElapsed + mMinExecutionGuaranteeMillis; 1458 final long nowElapsed = sElapsedRealtimeClock.millis(); 1459 if (nowElapsed >= latestStopTimeElapsed) { 1460 // Not an error - client ran out of time. 1461 Slog.i(TAG, "Client timed out while executing (no jobFinished received)." 1462 + " Sending onStop: " + getRunningJobNameLocked()); 1463 1464 final JobStatus executing = getRunningJobLocked(); 1465 int stopReason = JobParameters.STOP_REASON_TIMEOUT; 1466 int internalStopReason = JobParameters.INTERNAL_STOP_REASON_TIMEOUT; 1467 final StringBuilder stopMessage = new StringBuilder("timeout while executing"); 1468 final StringBuilder debugStopReason = new StringBuilder("client timed out"); 1469 1470 if (android.app.job.Flags.handleAbandonedJobs() 1471 && executing != null 1472 && !CompatChanges.isChangeEnabled( 1473 OVERRIDE_HANDLE_ABANDONED_JOBS, executing.getSourceUid()) 1474 && executing.isAbandoned()) { 1475 final String abandonedMessage = " and maybe abandoned"; 1476 stopReason = JobParameters.STOP_REASON_TIMEOUT_ABANDONED; 1477 internalStopReason = JobParameters.INTERNAL_STOP_REASON_TIMEOUT_ABANDONED; 1478 stopMessage.append(abandonedMessage); 1479 debugStopReason.append(abandonedMessage); 1480 } 1481 1482 mParams.setStopReason(stopReason, 1483 internalStopReason, debugStopReason.toString()); 1484 sendStopMessageLocked(stopMessage.toString()); 1485 } else if (nowElapsed >= earliestStopTimeElapsed) { 1486 // We've given the app the minimum execution time. See if we should stop it or 1487 // let it continue running 1488 final String reason = mJobConcurrencyManager.shouldStopRunningJobLocked(this); 1489 if (reason != null) { 1490 Slog.i(TAG, "Stopping client after min execution time: " 1491 + getRunningJobNameLocked() + " because " + reason); 1492 // Tell the developer we're stopping the job due to device state instead 1493 // of timeout since all of the reasons could equate to "the system needs 1494 // the resources the app is currently using." 1495 mParams.setStopReason(JobParameters.STOP_REASON_DEVICE_STATE, 1496 JobParameters.INTERNAL_STOP_REASON_TIMEOUT, reason); 1497 sendStopMessageLocked(reason); 1498 } else { 1499 Slog.i(TAG, "Letting " + getRunningJobNameLocked() 1500 + " continue to run past min execution time"); 1501 scheduleOpTimeOutLocked(); 1502 } 1503 } else if (mAwaitingNotification) { 1504 onSlowAppResponseLocked(/* reschedule */ true, /* updateStopReasons */ true, 1505 /* texCounterMetricId */ 1506 "job_scheduler.value_cntr_w_uid_slow_app_response_set_notification", 1507 /* debugReason */ "timed out while stopping", 1508 /* anrMessage */ "required notification not provided", 1509 /* triggerAnr */ true); 1510 } else { 1511 final long timeSinceDurationStampTimeMs = 1512 nowElapsed - mLastExecutionDurationStampTimeElapsed; 1513 if (timeSinceDurationStampTimeMs < EXECUTION_DURATION_STAMP_PERIOD_MILLIS) { 1514 Slog.e(TAG, "Unexpected op timeout while EXECUTING"); 1515 } 1516 // Update the execution time even if this wasn't the pre-set time. 1517 mRunningJob.incrementCumulativeExecutionTime(timeSinceDurationStampTimeMs); 1518 mService.mJobs.touchJob(mRunningJob); 1519 mLastExecutionDurationStampTimeElapsed = nowElapsed; 1520 scheduleOpTimeOutLocked(); 1521 } 1522 break; 1523 default: 1524 Slog.e(TAG, "Handling timeout for an invalid job state: " 1525 + getRunningJobNameLocked() + ", dropping."); 1526 closeAndCleanupJobLocked(false /* needsReschedule */, "invalid timeout"); 1527 } 1528 } 1529 1530 /** 1531 * Already running, need to stop. Will switch {@link #mVerb} from VERB_EXECUTING -> 1532 * VERB_STOPPING. 1533 */ 1534 @VisibleForTesting 1535 @GuardedBy("mLock") sendStopMessageLocked(@ullable String reason)1536 void sendStopMessageLocked(@Nullable String reason) { 1537 removeOpTimeOutLocked(); 1538 if (mVerb != VERB_EXECUTING) { 1539 Slog.e(TAG, "Sending onStopJob for a job that isn't started. " + mRunningJob); 1540 closeAndCleanupJobLocked(false /* reschedule */, reason); 1541 return; 1542 } 1543 try { 1544 applyStoppedReasonLocked(reason); 1545 mVerb = VERB_STOPPING; 1546 scheduleOpTimeOutLocked(); 1547 service.stopJob(mParams); 1548 } catch (RemoteException e) { 1549 Slog.e(TAG, "Error sending onStopJob to client.", e); 1550 // The job's host app apparently crashed during the job, so we should reschedule. 1551 closeAndCleanupJobLocked(true /* reschedule */, "host crashed when trying to stop"); 1552 } 1553 } 1554 1555 @GuardedBy("mLock") onSlowAppResponseLocked(boolean reschedule, boolean updateStopReasons, @NonNull String texCounterMetricId, @NonNull String debugReason, @NonNull String anrMessage, boolean triggerAnr)1556 private void onSlowAppResponseLocked(boolean reschedule, boolean updateStopReasons, 1557 @NonNull String texCounterMetricId, 1558 @NonNull String debugReason, @NonNull String anrMessage, boolean triggerAnr) { 1559 Slog.w(TAG, anrMessage + " for " + getRunningJobNameLocked()); 1560 // Use the calling UID since that's the one this context was connected to. 1561 Counter.logIncrementWithUid(texCounterMetricId, mRunningJob.getUid()); 1562 if (updateStopReasons) { 1563 mParams.setStopReason( 1564 JobParameters.STOP_REASON_UNDEFINED, 1565 JobParameters.INTERNAL_STOP_REASON_ANR, 1566 debugReason); 1567 } 1568 if (triggerAnr) { 1569 mActivityManagerInternal.appNotResponding( 1570 mRunningJob.serviceProcessName, mRunningJob.getUid(), 1571 TimeoutRecord.forJobService(anrMessage)); 1572 } 1573 closeAndCleanupJobLocked(reschedule, debugReason); 1574 } 1575 1576 /** 1577 * The provided job has finished, either by calling 1578 * {@link android.app.job.JobService#jobFinished(android.app.job.JobParameters, boolean)} 1579 * or from acknowledging the stop message we sent. Either way, we're done tracking it and 1580 * we want to clean up internally. 1581 */ 1582 @GuardedBy("mLock") closeAndCleanupJobLocked(boolean reschedule, @Nullable String loggingDebugReason)1583 private void closeAndCleanupJobLocked(boolean reschedule, @Nullable String loggingDebugReason) { 1584 final JobStatus completedJob; 1585 if (mVerb == VERB_FINISHED) { 1586 return; 1587 } 1588 if (DEBUG) { 1589 Slog.d(TAG, "Cleaning up " + mRunningJob.toShortString() 1590 + " reschedule=" + reschedule + " reason=" + loggingDebugReason); 1591 } 1592 final long nowElapsed = sElapsedRealtimeClock.millis(); 1593 applyStoppedReasonLocked(loggingDebugReason); 1594 completedJob = mRunningJob; 1595 completedJob.incrementCumulativeExecutionTime( 1596 nowElapsed - mLastExecutionDurationStampTimeElapsed); 1597 // Use the JobParameters stop reasons for logging and metric purposes, 1598 // but if the job was marked for death, use that reason for rescheduling purposes. 1599 // The discrepancy could happen if a job ends up stopping for some reason 1600 // in the time between the job being marked and the process actually dying. 1601 // Since the job stopped for another reason, we want to log the actual stop reason 1602 // for the sake of accurate metrics and debugging, 1603 // but we should use the death mark reasons when determining reschedule policy. 1604 final int loggingStopReason = mParams.getStopReason(); 1605 final int loggingInternalStopReason = mParams.getInternalStopReasonCode(); 1606 final int reschedulingStopReason, reschedulingInternalStopReason; 1607 if (mDeathMarkStopReason != JobParameters.STOP_REASON_UNDEFINED) { 1608 if (DEBUG) { 1609 Slog.d(TAG, "Job marked for death because of " 1610 + JobParameters.getInternalReasonCodeDescription( 1611 mDeathMarkInternalStopReason) 1612 + ": " + mDeathMarkDebugReason); 1613 } 1614 reschedulingStopReason = mDeathMarkStopReason; 1615 reschedulingInternalStopReason = mDeathMarkInternalStopReason; 1616 } else { 1617 reschedulingStopReason = loggingStopReason; 1618 reschedulingInternalStopReason = loggingInternalStopReason; 1619 } 1620 mPreviousJobHadSuccessfulFinish = 1621 (loggingInternalStopReason == JobParameters.INTERNAL_STOP_REASON_SUCCESSFUL_FINISH); 1622 if (!mPreviousJobHadSuccessfulFinish) { 1623 mLastUnsuccessfulFinishElapsed = nowElapsed; 1624 } 1625 mJobPackageTracker.noteInactive(completedJob, 1626 loggingInternalStopReason, loggingDebugReason); 1627 final int sourceUid = completedJob.getSourceUid(); 1628 int procState = mService.getUidProcState(completedJob.getUid()); 1629 if (Flags.useCorrectProcessStateForLogging() 1630 && procState > ActivityManager.PROCESS_STATE_TRANSIENT_BACKGROUND) { 1631 // Try to get the latest proc state from AMS, there might be some delay 1632 // for the proc states worse than TRANSIENT_BACKGROUND. 1633 procState = mActivityManagerInternal.getUidProcessState(completedJob.getUid()); 1634 } 1635 FrameworkStatsLog.write(FrameworkStatsLog.SCHEDULED_JOB_STATE_CHANGED, 1636 completedJob.isProxyJob() 1637 ? new int[]{sourceUid, completedJob.getUid()} : new int[]{sourceUid}, 1638 // Given that the source tag is set by the calling app, it should be connected 1639 // to the calling app in the attribution for a proxied job. 1640 completedJob.isProxyJob() 1641 ? new String[]{null, completedJob.getSourceTag()} 1642 : new String[]{completedJob.getSourceTag()}, 1643 completedJob.getBatteryName(), 1644 FrameworkStatsLog.SCHEDULED_JOB_STATE_CHANGED__STATE__FINISHED, 1645 loggingInternalStopReason, completedJob.getStandbyBucket(), 1646 completedJob.getLoggingJobId(), 1647 completedJob.hasChargingConstraint(), 1648 completedJob.hasBatteryNotLowConstraint(), 1649 completedJob.hasStorageNotLowConstraint(), 1650 completedJob.hasTimingDelayConstraint(), 1651 completedJob.hasDeadlineConstraint(), 1652 completedJob.hasIdleConstraint(), 1653 completedJob.hasConnectivityConstraint(), 1654 completedJob.hasContentTriggerConstraint(), 1655 completedJob.isRequestedExpeditedJob(), 1656 completedJob.startedAsExpeditedJob, 1657 loggingStopReason, 1658 completedJob.getJob().isPrefetch(), 1659 completedJob.getJob().getPriority(), 1660 completedJob.getEffectivePriority(), 1661 completedJob.getNumPreviousAttempts(), 1662 completedJob.getJob().getMaxExecutionDelayMillis(), 1663 mParams.isOverrideDeadlineExpired(), 1664 completedJob.isConstraintSatisfied(JobInfo.CONSTRAINT_FLAG_CHARGING), 1665 completedJob.isConstraintSatisfied(JobInfo.CONSTRAINT_FLAG_BATTERY_NOT_LOW), 1666 completedJob.isConstraintSatisfied(JobInfo.CONSTRAINT_FLAG_STORAGE_NOT_LOW), 1667 completedJob.isConstraintSatisfied(JobStatus.CONSTRAINT_TIMING_DELAY), 1668 completedJob.isConstraintSatisfied(JobInfo.CONSTRAINT_FLAG_DEVICE_IDLE), 1669 completedJob.isConstraintSatisfied(JobStatus.CONSTRAINT_CONNECTIVITY), 1670 completedJob.isConstraintSatisfied(JobStatus.CONSTRAINT_CONTENT_TRIGGER), 1671 mExecutionStartTimeElapsed - completedJob.enqueueTime, 1672 completedJob.getJob().isUserInitiated(), 1673 completedJob.startedAsUserInitiatedJob, 1674 completedJob.getJob().isPeriodic(), 1675 completedJob.getJob().getMinLatencyMillis(), 1676 completedJob.getEstimatedNetworkDownloadBytes(), 1677 completedJob.getEstimatedNetworkUploadBytes(), 1678 completedJob.getWorkCount(), 1679 ActivityManager 1680 .processStateAmToProto(procState), 1681 completedJob.getNamespaceHash(), 1682 TrafficStats.getUidRxBytes(completedJob.getSourceUid()) 1683 - mInitialDownloadedBytesFromSource, 1684 TrafficStats.getUidTxBytes(completedJob.getSourceUid()) 1685 - mInitialUploadedBytesFromSource, 1686 TrafficStats.getUidRxBytes(completedJob.getUid()) 1687 - mInitialDownloadedBytesFromCalling, 1688 TrafficStats.getUidTxBytes(completedJob.getUid()) 1689 - mInitialUploadedBytesFromCalling, 1690 completedJob.getJob().getIntervalMillis(), 1691 completedJob.getJob().getFlexMillis(), 1692 completedJob.hasFlexibilityConstraint(), 1693 completedJob.isConstraintSatisfied(JobStatus.CONSTRAINT_FLEXIBLE), 1694 completedJob.canApplyTransportAffinities(), 1695 completedJob.getNumAppliedFlexibleConstraints(), 1696 completedJob.getNumDroppedFlexibleConstraints(), 1697 completedJob.getFilteredTraceTag(), 1698 completedJob.getFilteredDebugTags(), 1699 completedJob.getNumAbandonedFailures(), 1700 /* 0 is reserved for UNKNOWN_POLICY */ 1701 completedJob.getJob().getBackoffPolicy() + 1, 1702 mService.shouldUseAggressiveBackoff( 1703 completedJob.getNumAbandonedFailures(), completedJob.getSourceUid())); 1704 if (Trace.isTagEnabled(Trace.TRACE_TAG_SYSTEM_SERVER)) { 1705 Trace.asyncTraceForTrackEnd(Trace.TRACE_TAG_SYSTEM_SERVER, 1706 JobSchedulerService.TRACE_TRACK_NAME, getId()); 1707 } 1708 if (completedJob.getAppTraceTag() != null) { 1709 Trace.asyncTraceForTrackEnd(Trace.TRACE_TAG_APP, 1710 JobSchedulerService.TRACE_TRACK_NAME, completedJob.getJobId()); 1711 } 1712 try { 1713 mBatteryStats.noteJobFinish(mRunningJob.getBatteryName(), mRunningJob.getSourceUid(), 1714 loggingInternalStopReason); 1715 } catch (RemoteException e) { 1716 // Whatever. 1717 } 1718 mNotificationCoordinator.removeNotificationAssociation(this, 1719 reschedulingStopReason, completedJob); 1720 if (mWakeLock != null) { 1721 mWakeLock.release(); 1722 } 1723 final int workType = mRunningJobWorkType; 1724 mContext.unbindService(JobServiceContext.this); 1725 mWakeLock = null; 1726 mRunningJob = null; 1727 mRunningJobWorkType = WORK_TYPE_NONE; 1728 mRunningCallback = null; 1729 mParams = null; 1730 mVerb = VERB_FINISHED; 1731 mCancelled = false; 1732 service = null; 1733 mAvailable = true; 1734 mDeathMarkStopReason = JobParameters.STOP_REASON_UNDEFINED; 1735 mDeathMarkInternalStopReason = 0; 1736 mDeathMarkDebugReason = null; 1737 mLastExecutionDurationStampTimeElapsed = 0; 1738 mPendingStopReason = JobParameters.STOP_REASON_UNDEFINED; 1739 mPendingInternalStopReason = 0; 1740 mPendingDebugStopReason = null; 1741 mPendingNetworkChange = null; 1742 removeOpTimeOutLocked(); 1743 if (completedJob.isUserVisibleJob()) { 1744 mService.informObserversOfUserVisibleJobChange(this, completedJob, false); 1745 } 1746 mCompletedListener.onJobCompletedLocked(completedJob, 1747 reschedulingStopReason, reschedulingInternalStopReason, reschedule); 1748 mJobConcurrencyManager.onJobCompletedLocked(this, completedJob, workType); 1749 } 1750 applyStoppedReasonLocked(@ullable String reason)1751 private void applyStoppedReasonLocked(@Nullable String reason) { 1752 if (reason != null && mStoppedReason == null) { 1753 mStoppedReason = reason; 1754 mStoppedTime = sElapsedRealtimeClock.millis(); 1755 if (mRunningCallback != null) { 1756 mRunningCallback.mStoppedReason = mStoppedReason; 1757 mRunningCallback.mStoppedTime = mStoppedTime; 1758 } 1759 } 1760 } 1761 1762 /** 1763 * Called when sending a message to the client, over whose execution we have no control. If 1764 * we haven't received a response in a certain amount of time, we want to give up and carry 1765 * on with life. 1766 */ scheduleOpTimeOutLocked()1767 private void scheduleOpTimeOutLocked() { 1768 removeOpTimeOutLocked(); 1769 1770 final long timeoutMillis; 1771 switch (mVerb) { 1772 case VERB_EXECUTING: 1773 long minTimeout; 1774 final long earliestStopTimeElapsed = 1775 mExecutionStartTimeElapsed + mMinExecutionGuaranteeMillis; 1776 final long latestStopTimeElapsed = 1777 mExecutionStartTimeElapsed + mMaxExecutionTimeMillis; 1778 final long nowElapsed = sElapsedRealtimeClock.millis(); 1779 if (nowElapsed < earliestStopTimeElapsed) { 1780 minTimeout = earliestStopTimeElapsed - nowElapsed; 1781 } else { 1782 minTimeout = latestStopTimeElapsed - nowElapsed; 1783 } 1784 if (mAwaitingNotification) { 1785 minTimeout = Math.min(minTimeout, NOTIFICATION_TIMEOUT_MILLIS); 1786 } 1787 minTimeout = Math.min(minTimeout, EXECUTION_DURATION_STAMP_PERIOD_MILLIS); 1788 timeoutMillis = minTimeout; 1789 break; 1790 1791 case VERB_BINDING: 1792 timeoutMillis = OP_BIND_TIMEOUT_MILLIS; 1793 break; 1794 1795 default: 1796 timeoutMillis = OP_TIMEOUT_MILLIS; 1797 break; 1798 } 1799 if (DEBUG) { 1800 Slog.d(TAG, "Scheduling time out for '" + 1801 mRunningJob.getServiceComponent().getShortClassName() + "' jId: " + 1802 mParams.getJobId() + ", in " + (timeoutMillis / 1000) + " s"); 1803 } 1804 Message m = mCallbackHandler.obtainMessage(MSG_TIMEOUT, mRunningCallback); 1805 mCallbackHandler.sendMessageDelayed(m, timeoutMillis); 1806 mTimeoutElapsed = sElapsedRealtimeClock.millis() + timeoutMillis; 1807 } 1808 removeOpTimeOutLocked()1809 private void removeOpTimeOutLocked() { 1810 mCallbackHandler.removeMessages(MSG_TIMEOUT); 1811 } 1812 dumpLocked(IndentingPrintWriter pw, final long nowElapsed)1813 void dumpLocked(IndentingPrintWriter pw, final long nowElapsed) { 1814 if (mRunningJob == null) { 1815 if (mStoppedReason != null) { 1816 pw.print("inactive since "); 1817 TimeUtils.formatDuration(mStoppedTime, nowElapsed, pw); 1818 pw.print(", stopped because: "); 1819 pw.println(mStoppedReason); 1820 } else { 1821 pw.println("inactive"); 1822 } 1823 } else { 1824 pw.println(mRunningJob.toShortString()); 1825 1826 pw.increaseIndent(); 1827 pw.print("Running for: "); 1828 TimeUtils.formatDuration(nowElapsed - mExecutionStartTimeElapsed, pw); 1829 pw.print(", timeout at: "); 1830 TimeUtils.formatDuration(mTimeoutElapsed - nowElapsed, pw); 1831 pw.println(); 1832 pw.print("Remaining execution limits: ["); 1833 TimeUtils.formatDuration( 1834 (mExecutionStartTimeElapsed + mMinExecutionGuaranteeMillis) - nowElapsed, pw); 1835 pw.print(", "); 1836 TimeUtils.formatDuration( 1837 (mExecutionStartTimeElapsed + mMaxExecutionTimeMillis) - nowElapsed, pw); 1838 pw.print("]"); 1839 if (mPendingStopReason != JobParameters.STOP_REASON_UNDEFINED) { 1840 pw.print(" Pending stop because "); 1841 pw.print(mPendingStopReason); 1842 pw.print("/"); 1843 pw.print(mPendingInternalStopReason); 1844 pw.print("/"); 1845 pw.print(mPendingDebugStopReason); 1846 } 1847 pw.println(); 1848 pw.decreaseIndent(); 1849 } 1850 } 1851 } 1852