1 /* 2 * Copyright (C) 2023 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.adservices.spe; 18 19 import static com.android.adservices.service.stats.AdServicesStatsLog.AD_SERVICES_BACKGROUND_JOBS_EXECUTION_REPORTED__EXECUTION_RESULT_CODE__FAILED_WITHOUT_RETRY; 20 import static com.android.adservices.service.stats.AdServicesStatsLog.AD_SERVICES_BACKGROUND_JOBS_EXECUTION_REPORTED__EXECUTION_RESULT_CODE__FAILED_WITH_RETRY; 21 import static com.android.adservices.service.stats.AdServicesStatsLog.AD_SERVICES_BACKGROUND_JOBS_EXECUTION_REPORTED__EXECUTION_RESULT_CODE__HALTED_FOR_UNKNOWN_REASON; 22 import static com.android.adservices.service.stats.AdServicesStatsLog.AD_SERVICES_BACKGROUND_JOBS_EXECUTION_REPORTED__EXECUTION_RESULT_CODE__ONSTOP_CALLED_WITHOUT_RETRY; 23 import static com.android.adservices.service.stats.AdServicesStatsLog.AD_SERVICES_BACKGROUND_JOBS_EXECUTION_REPORTED__EXECUTION_RESULT_CODE__ONSTOP_CALLED_WITH_RETRY; 24 import static com.android.adservices.service.stats.AdServicesStatsLog.AD_SERVICES_BACKGROUND_JOBS_EXECUTION_REPORTED__EXECUTION_RESULT_CODE__SUCCESSFUL; 25 import static com.android.adservices.spe.JobServiceConstants.MILLISECONDS_PER_MINUTE; 26 import static com.android.adservices.spe.JobServiceConstants.SHARED_PREFS_BACKGROUND_JOBS; 27 import static com.android.adservices.spe.JobServiceConstants.UNAVAILABLE_JOB_EXECUTION_PERIOD; 28 import static com.android.adservices.spe.JobServiceConstants.UNAVAILABLE_JOB_EXECUTION_START_TIMESTAMP; 29 import static com.android.adservices.spe.JobServiceConstants.UNAVAILABLE_JOB_EXECUTION_STOP_TIMESTAMP; 30 import static com.android.adservices.spe.JobServiceConstants.UNAVAILABLE_JOB_LATENCY; 31 import static com.android.adservices.spe.JobServiceConstants.UNAVAILABLE_STOP_REASON; 32 33 import android.annotation.NonNull; 34 import android.annotation.TargetApi; 35 import android.app.job.JobParameters; 36 import android.app.job.JobService; 37 import android.content.Context; 38 import android.content.SharedPreferences; 39 import android.os.Build; 40 41 import com.android.adservices.LogUtil; 42 import com.android.adservices.service.FlagsFactory; 43 import com.android.adservices.service.stats.Clock; 44 import com.android.adservices.service.stats.StatsdAdServicesLogger; 45 import com.android.adservices.spe.stats.ExecutionReportedStats; 46 import com.android.internal.annotations.VisibleForTesting; 47 import com.android.modules.utils.build.SdkLevel; 48 49 /** Class for logging methods used by background jobs. */ 50 public final class AdservicesJobServiceLogger { 51 private static final Object SINGLETON_LOCK = new Object(); 52 53 private static volatile AdservicesJobServiceLogger sSingleton; 54 55 private final Context mContext; 56 private final Clock mClock; 57 private final StatsdAdServicesLogger mStatsdLogger; 58 59 /** Create an instance of {@link AdservicesJobServiceLogger}. */ 60 @VisibleForTesting AdservicesJobServiceLogger( @onNull Context context, @NonNull Clock clock, @NonNull StatsdAdServicesLogger statsdLogger)61 public AdservicesJobServiceLogger( 62 @NonNull Context context, 63 @NonNull Clock clock, 64 @NonNull StatsdAdServicesLogger statsdLogger) { 65 mContext = context.getApplicationContext(); 66 mClock = clock; 67 mStatsdLogger = statsdLogger; 68 } 69 70 /** Get a singleton instance of {@link AdservicesJobServiceLogger} to be used. */ 71 @NonNull getInstance(@onNull Context context)72 public static AdservicesJobServiceLogger getInstance(@NonNull Context context) { 73 if (sSingleton == null) { 74 synchronized (SINGLETON_LOCK) { 75 if (sSingleton == null) { 76 sSingleton = 77 new AdservicesJobServiceLogger( 78 context, 79 Clock.SYSTEM_CLOCK, 80 StatsdAdServicesLogger.getInstance()); 81 } 82 } 83 } 84 85 return sSingleton; 86 } 87 88 /** 89 * {@link JobService} calls this method in {@link JobService#onStartJob(JobParameters)} to 90 * record that onStartJob was called. 91 * 92 * @param jobId the unique id of the job to log for. 93 */ recordOnStartJob(int jobId)94 public void recordOnStartJob(int jobId) { 95 if (FlagsFactory.getFlags().getBackgroundJobsLoggingKillSwitch()) { 96 return; 97 } 98 99 long startJobTimestamp = mClock.currentTimeMillis(); 100 101 persistJobExecutionData(jobId, startJobTimestamp); 102 } 103 104 /** 105 * Record that the {@link JobService#jobFinished(JobParameters, boolean)} is called or is about 106 * to be called. 107 * 108 * @param jobId the unique id of the job to log for. 109 * @param isSuccessful indicates if the execution is successful. 110 * @param shouldRetry indicates whether to retry the execution. 111 */ recordJobFinished(int jobId, boolean isSuccessful, boolean shouldRetry)112 public void recordJobFinished(int jobId, boolean isSuccessful, boolean shouldRetry) { 113 if (FlagsFactory.getFlags().getBackgroundJobsLoggingKillSwitch()) { 114 return; 115 } 116 117 int resultCode = 118 isSuccessful 119 ? AD_SERVICES_BACKGROUND_JOBS_EXECUTION_REPORTED__EXECUTION_RESULT_CODE__SUCCESSFUL 120 : (shouldRetry 121 ? AD_SERVICES_BACKGROUND_JOBS_EXECUTION_REPORTED__EXECUTION_RESULT_CODE__FAILED_WITH_RETRY 122 : AD_SERVICES_BACKGROUND_JOBS_EXECUTION_REPORTED__EXECUTION_RESULT_CODE__FAILED_WITHOUT_RETRY); 123 logExecutionStats(jobId, mClock.currentTimeMillis(), resultCode, UNAVAILABLE_STOP_REASON); 124 } 125 126 /** 127 * {@link JobService} calls this method in {@link JobService#onStopJob(JobParameters)}} to 128 * enable logging. 129 * 130 * @param params configured {@link JobParameters} 131 * @param jobId the unique id of the job to log for. 132 * @param shouldRetry whether to reschedule the job. 133 */ 134 @TargetApi(Build.VERSION_CODES.S) recordOnStopJob(@onNull JobParameters params, int jobId, boolean shouldRetry)135 public void recordOnStopJob(@NonNull JobParameters params, int jobId, boolean shouldRetry) { 136 if (FlagsFactory.getFlags().getBackgroundJobsLoggingKillSwitch()) { 137 return; 138 } 139 140 long endJobTimestamp = mClock.currentTimeMillis(); 141 142 // StopReason is only supported for Android Version S+. 143 int stopReason = SdkLevel.isAtLeastS() ? params.getStopReason() : UNAVAILABLE_STOP_REASON; 144 145 int resultCode = 146 shouldRetry 147 ? AD_SERVICES_BACKGROUND_JOBS_EXECUTION_REPORTED__EXECUTION_RESULT_CODE__ONSTOP_CALLED_WITH_RETRY 148 : AD_SERVICES_BACKGROUND_JOBS_EXECUTION_REPORTED__EXECUTION_RESULT_CODE__ONSTOP_CALLED_WITHOUT_RETRY; 149 150 logExecutionStats(jobId, endJobTimestamp, resultCode, stopReason); 151 } 152 153 /** 154 * Log when the execution is skipped due to customized reasons. 155 * 156 * @param jobId the unique id of the job to log for 157 * @param skipReason the result to skip the execution 158 */ recordJobSkipped(int jobId, int skipReason)159 public void recordJobSkipped(int jobId, int skipReason) { 160 if (FlagsFactory.getFlags().getBackgroundJobsLoggingKillSwitch()) { 161 return; 162 } 163 164 logExecutionStats(jobId, mClock.currentTimeMillis(), skipReason, UNAVAILABLE_STOP_REASON); 165 } 166 167 /** 168 * Log for various lifecycles of an execution. 169 * 170 * <p>a completed lifecycle includes job finished in {@link 171 * JobService#jobFinished(JobParameters, boolean)} or {@link 172 * JobService#onStopJob(JobParameters)}. 173 * 174 * @param jobId the job id 175 * @param jobStopExecutionTimestamp the timestamp of the end of an execution. Note it can happen 176 * in either {@link JobService#jobFinished(JobParameters, boolean)} or {@link 177 * JobService#onStopJob(JobParameters)}. 178 * @param executionResultCode the result code for current execution 179 * @param possibleStopReason if {@link JobService#onStopJob(JobParameters)} is invoked. Set 180 * {@link JobServiceConstants#UNAVAILABLE_STOP_REASON} if {@link 181 * JobService#onStopJob(JobParameters)} is not invoked. 182 */ 183 @VisibleForTesting logExecutionStats( int jobId, long jobStopExecutionTimestamp, int executionResultCode, int possibleStopReason)184 public void logExecutionStats( 185 int jobId, 186 long jobStopExecutionTimestamp, 187 int executionResultCode, 188 int possibleStopReason) { 189 String jobStartTimestampKey = getJobStartTimestampKey(jobId); 190 String executionPeriodKey = getExecutionPeriodKey(jobId); 191 String jobStopTimestampKey = getJobStopTimestampKey(jobId); 192 193 SharedPreferences sharedPreferences = 194 mContext.getSharedPreferences(SHARED_PREFS_BACKGROUND_JOBS, Context.MODE_PRIVATE); 195 SharedPreferences.Editor editor = sharedPreferences.edit(); 196 197 long jobStartExecutionTimestamp = 198 sharedPreferences.getLong( 199 jobStartTimestampKey, UNAVAILABLE_JOB_EXECUTION_START_TIMESTAMP); 200 long jobExecutionPeriodMs = 201 sharedPreferences.getLong(executionPeriodKey, UNAVAILABLE_JOB_EXECUTION_PERIOD); 202 203 // Stop telemetry the metrics and log error in logcat if the stat is not valid. 204 if (jobStartExecutionTimestamp == UNAVAILABLE_JOB_EXECUTION_START_TIMESTAMP 205 || jobStartExecutionTimestamp > jobStopExecutionTimestamp) { 206 // TODO(b/279231865): Log CEL with SPE_UNAVAILABLE_JOB_EXECUTION_START_TIMESTAMP 207 LogUtil.e( 208 "Execution Stat is INVALID for job %s, jobStartTimestamp: %d, jobStopTimestamp:" 209 + " %d.", 210 AdservicesJobInfo.getJobIdToInfoMap().get(jobId), 211 jobStartExecutionTimestamp, 212 jobStopExecutionTimestamp); 213 return; 214 } 215 216 // Compute the execution latency. 217 long executionLatencyMs = jobStopExecutionTimestamp - jobStartExecutionTimestamp; 218 219 // Update jobStopExecutionTimestamp in storage. 220 editor.putLong(jobStopTimestampKey, jobStopExecutionTimestamp); 221 222 if (!editor.commit()) { 223 // The commitment failure should be rare. It may result in 1 problematic data but the 224 // impact could be ignored compared to a job's lifecycle. 225 // TODO(b/279231865): Log CEL with SPE_FAIL_TO_COMMIT_JOB_STOP_TIME 226 LogUtil.e( 227 "Failed to update job Ending Execution Logging Data for Job %s.", 228 AdservicesJobInfo.getJobIdToInfoMap().get(jobId).getJobServiceName()); 229 } 230 231 // Actually upload the metrics to statsD. 232 logJobStatsHelper( 233 jobId, 234 executionLatencyMs, 235 jobExecutionPeriodMs, 236 executionResultCode, 237 possibleStopReason); 238 } 239 240 /** 241 * Do background job telemetry. 242 * 243 * @param jobId the job ID 244 * @param executionLatencyMs the latency of an execution. Defined as the difference of timestamp 245 * between end and start of an execution. 246 * @param executionPeriodMs the execution period. Defined as the difference of timestamp between 247 * current and previous start of an execution. This is only valid for periodical jobs to 248 * monitor the difference between actual and configured execution period. 249 * @param resultCode the result code of an execution 250 * @param stopReason {@link JobParameters#getStopReason()} if {@link 251 * JobService#onStopJob(JobParameters)} is invoked. Otherwise, set it to {@link 252 * JobServiceConstants#UNAVAILABLE_STOP_REASON}. 253 */ 254 @VisibleForTesting logJobStatsHelper( int jobId, long executionLatencyMs, long executionPeriodMs, int resultCode, int stopReason)255 public void logJobStatsHelper( 256 int jobId, 257 long executionLatencyMs, 258 long executionPeriodMs, 259 int resultCode, 260 int stopReason) { 261 long executionPeriodMinute = executionPeriodMs / MILLISECONDS_PER_MINUTE; 262 263 ExecutionReportedStats stats = 264 ExecutionReportedStats.builder() 265 .setJobId(jobId) 266 .setExecutionLatencyMs(convertLongToInteger(executionLatencyMs)) 267 .setExecutionPeriodMinute(convertLongToInteger(executionPeriodMinute)) 268 .setExecutionResultCode(resultCode) 269 .setStopReason(stopReason) 270 .build(); 271 mStatsdLogger.logExecutionReportedStats(stats); 272 273 LogUtil.v( 274 "[Adservices background job logging] jobId: %d, executionLatencyInMs: %d, " 275 + "executionPeriodInMs: %d, resultCode: %d, stopReason: %d", 276 jobId, executionLatencyMs, executionPeriodMs, resultCode, stopReason); 277 } 278 279 /** 280 * Compute execution data such as latency and period then store the data in persistent so that 281 * we can compute the job stats later. Store start job timestamp and execution period into the 282 * storage. 283 * 284 * @param jobId the job id 285 * @param startJobTimestamp the timestamp when {@link JobService#onStartJob(JobParameters)} is 286 * invoked. 287 */ 288 @VisibleForTesting persistJobExecutionData(int jobId, long startJobTimestamp)289 public void persistJobExecutionData(int jobId, long startJobTimestamp) { 290 SharedPreferences sharedPreferences = 291 mContext.getSharedPreferences(SHARED_PREFS_BACKGROUND_JOBS, Context.MODE_PRIVATE); 292 293 String jobStartTimestampKey = getJobStartTimestampKey(jobId); 294 String executionPeriodKey = getExecutionPeriodKey(jobId); 295 String jobStopTimestampKey = getJobStopTimestampKey(jobId); 296 297 // When onStartJob() is invoked, the data stored in the shared preference is for previous 298 // execution. 299 // 300 // JobService is scheduled as JobStatus in JobScheduler infra. Before a JobStatus instance 301 // is pushed to pendingJobQueue, it checks a few criteria like whether a same JobStatus is 302 // ready to execute, not pending, not running, etc. To determine if two JobStatus instances 303 // are same, it checks jobId, callingUid (the package that schedules the job). Therefore, 304 // there won't have two pending/running job instances with a same jobId. For more details, 305 // please check source code of JobScheduler. 306 long previousJobStartTimestamp = 307 sharedPreferences.getLong( 308 jobStartTimestampKey, UNAVAILABLE_JOB_EXECUTION_START_TIMESTAMP); 309 long previousJobStopTimestamp = 310 sharedPreferences.getLong( 311 jobStopTimestampKey, UNAVAILABLE_JOB_EXECUTION_STOP_TIMESTAMP); 312 long previousExecutionPeriod = 313 sharedPreferences.getLong(executionPeriodKey, UNAVAILABLE_JOB_EXECUTION_PERIOD); 314 315 SharedPreferences.Editor editor = sharedPreferences.edit(); 316 317 // The first execution, pass execution period with UNAVAILABLE_JOB_EXECUTION_PERIOD. 318 if (previousJobStartTimestamp == UNAVAILABLE_JOB_EXECUTION_START_TIMESTAMP) { 319 editor.putLong(executionPeriodKey, UNAVAILABLE_JOB_EXECUTION_PERIOD); 320 } else { 321 // If previousJobStartTimestamp is later than previousJobStopTimestamp, it indicates the 322 // last execution didn't finish with calling jobFinished() or onStopJob(). In this case, 323 // we log as an unknown issue, which may come from system/device. 324 if (previousJobStartTimestamp > previousJobStopTimestamp) { 325 logJobStatsHelper( 326 jobId, 327 UNAVAILABLE_JOB_LATENCY, 328 previousExecutionPeriod, 329 AD_SERVICES_BACKGROUND_JOBS_EXECUTION_REPORTED__EXECUTION_RESULT_CODE__HALTED_FOR_UNKNOWN_REASON, 330 UNAVAILABLE_STOP_REASON); 331 } 332 333 // Compute execution period if there has been multiple executions. 334 // Define the execution period = difference of the timestamp of two consecutive 335 // invocations of onStartJob(). 336 // TODO(b/279231865): TODO log to CEL: SPE_INVALID_EXECUTION_PERIOD 337 long executionPeriodInMs = startJobTimestamp - previousJobStartTimestamp; 338 339 // Store the execution period into shared preference. 340 editor.putLong(executionPeriodKey, executionPeriodInMs); 341 } 342 // Store current JobStartTimestamp into shared preference. 343 editor.putLong(jobStartTimestampKey, startJobTimestamp); 344 345 if (!editor.commit()) { 346 // The commitment failure should be rare. It may result in 1 problematic data but the 347 // impact could be ignored compared to a job's lifecycle. 348 // TODO(b/279231865): Log CEL with SPE_FAIL_TO_COMMIT_JOB_START_TIME. 349 LogUtil.e( 350 "Failed to update onStartJob() Logging Data for Job %s.", 351 AdservicesJobInfo.getJobIdToInfoMap().get(jobId).getJobServiceName()); 352 } 353 } 354 355 @VisibleForTesting getJobStartTimestampKey(int jobId)356 static String getJobStartTimestampKey(int jobId) { 357 return jobId + JobServiceConstants.SHARED_PREFS_START_TIMESTAMP_SUFFIX; 358 } 359 360 @VisibleForTesting getJobStopTimestampKey(int jobId)361 static String getJobStopTimestampKey(int jobId) { 362 return jobId + JobServiceConstants.SHARED_PREFS_STOP_TIMESTAMP_SUFFIX; 363 } 364 365 @VisibleForTesting getExecutionPeriodKey(int jobId)366 static String getExecutionPeriodKey(int jobId) { 367 return jobId + JobServiceConstants.SHARED_PREFS_EXEC_PERIOD_SUFFIX; 368 } 369 370 // Convert a long value to an integer. 371 // 372 // Used to convert a time period in long-format but needs to be logged with integer-format. 373 // Generally, a time period should always be a positive integer with a proper design of its 374 // unit. 375 // 376 // Defensively use this method to avoid any Exception. 377 @VisibleForTesting convertLongToInteger(long longVal)378 static int convertLongToInteger(long longVal) { 379 int intValue; 380 381 // The given time period should always be in the range of positive integer. Defensively 382 // handle overflow values to avoid potential Exceptions. 383 if (longVal <= Integer.MIN_VALUE) { 384 intValue = Integer.MIN_VALUE; 385 } else if (longVal >= Integer.MAX_VALUE) { 386 intValue = Integer.MAX_VALUE; 387 } else { 388 intValue = (int) longVal; 389 } 390 391 return intValue; 392 } 393 } 394