Android-job: JobRescheduleService incorrectly reschedules my job

[AndreiHarasemiuc]

Hello guys,

Your library is helping me a lot and you have my sincerest appreciation for your work. However, I think I have stumbled upon a bug.

The way I'm using the library is similar to a calendar type app. I am scheduling exact type jobs. When a job runs I schedule another job for tomorrow at the exact same time or next week at the exact same day and time.

I think I have found an issue where the JobRescheduleService class will incorrectly reschedule one of my jobs. It basically reschedules the job for right now without a delay, when initially it was scheduled with a 24 hour delay.

I have prepared a detailed log together with explanations of what the app is doing at every point in the log and in what state the app is.

I have managed to reproduce the issue with the exact steps below on Android versions 6.0 & 7.1.1.
Whatever else information I should provide please let me know.

//Open app, schedule a job in a few seconds

D/JobProxy14: Scheduled alarm, request{id=1, tag=activity:55f8b160dba84c2e86759bf384d0a118}, delay 00:00:26, exact true, reschedule count 0

//Close app completely (swipe off app in recent apps)
//Job time comes and it starts

08-09 17:53:00.581 9635-9667/? D/JobRescheduleService: Reschedule service started
08-09 17:53:00.585 9635-9668/? D/PlatformAlarmService: Run job, request{id=1, tag=activity:55f8b160dba84c2e86759bf384d0a118}, waited 00:00:26, delay 00:00:26
08-09 17:53:00.590 9635-9668/? I/JobExecutor: Executing request{id=1, tag=activity:55f8b160dba84c2e86759bf384d0a118}, context PlatformAlarmService

//Job runs. My job does 2 things. Fires up a notification (opening the app process).  And schedules another job with a delay of 24 hours (Tomorrow at the same time)
//If you're wondering why I'm not using a periodic job, it's because I need daily and weekly reminders at the exact same time.

08-09 17:53:00.632 9635-9669/? D/JobProxy14: Scheduled alarm, request{id=2, tag=activity:55f8b160dba84c2e86759bf384d0a118}, delay 23:59:59, exact true, reschedule count 0
08-09 17:53:00.632 9635-9669/? I/JobExecutor: Finished job{id=1, finished=true, result=SUCCESS, canceled=false, periodic=false, class=ReminderJob, tag=activity:55f8b160dba84c2e86759bf384d0a118}
08-09 17:53:00.635 9635-9668/? D/PlatformAlarmService: Finished job, request{id=1, tag=activity:55f8b160dba84c2e86759bf384d0a118} SUCCESS

//at this point the Job ran, displayed the notification and correctly scheduled the next job for tomorrow (id = 2)
//I tap on the notification which opens the app (the app was completely closed) and then I immediately background the app.

09 17:53:10.616 9635-9667/? I/JobManager: Found pending job request{id=2, tag=activity:55f8b160dba84c2e86759bf384d0a118}, canceling
08-09 17:53:10.628 9635-9667/? D/JobProxy14: Scheduled alarm, request{id=2, tag=activity:55f8b160dba84c2e86759bf384d0a118}, delay 00:00:00, exact true, reschedule count 0
08-09 17:53:10.628 9635-9667/? D/JobRescheduleService: Reschedule 1 jobs of 1 jobs
08-09 17:53:10.932 9635-9856/? D/PlatformAlarmService: Run job, request{id=2, tag=activity:55f8b160dba84c2e86759bf384d0a118}, waited 00:00:00, delay 00:00:00
08-09 17:53:10.940 9635-9856/io.healthsteps.healthsteps I/JobExecutor: Executing request{id=2, tag=activity:55f8b160dba84c2e86759bf384d0a118}, context PlatformAlarmService

//Since the app has just been started (by way of the notification) it looks like your *JobRescheduleService* runs at app start and is cleaning up all the jobs and reschedules them or something.

//The problem is that the job I scheduled above for tomorrow is cancelled and is incorrectly rescheduled for right now, without a delay.
//And immediately, it runs:

08-09 17:53:10.984 9635-9669/? D/JobProxy14: Scheduled alarm, request{id=3, tag=activity:55f8b160dba84c2e86759bf384d0a118}, delay 23:59:49 (+1 day), exact true, reschedule count 0
08-09 17:53:10.985 9635-9669/? I/JobExecutor: Finished job{id=2, finished=true, result=SUCCESS, canceled=false, periodic=false, class=ReminderJob, tag=activity:55f8b160dba84c2e86759bf384d0a118}
08-09 17:53:10.989 9635-9856/? D/PlatformAlarmService: Finished job, request{id=2, tag=activity:55f8b160dba84c2e86759bf384d0a118} SUCCESS

I can reproduce this issue 100% of the time provided I follow the exact steps above. The app must be closed off after the first job is scheduled. The app must be opened when the job runs and then it must be backgrounded (paused). These last last 2 steps must be done before the JobRescheduleService starts doing its thing.

I forgot to mention, this is how I'm scheduling the jobs:

new JobRequest.Builder(repeatingReminder.getActivityID()) .setExact(timeToFireIn) .setExtras(extras) .setPersisted(true) .build() .schedule();

[vRallev]

Thank you for the detailed explanation. However, I can't find the reason for this issue. Can you provide a sample with the bug?

Please also give version 1.2.0-alpha3 a try: https://github.com/evernote/android-job/wiki/Version-1.2.0-and-Android-O It contains some fixes, maybe the issue is gone with the newer version. We already use 1.2.0-alpha3 in production.

[AndreiHarasemiuc]

Hey, I made a repository with a sample app with which I have managed to reproduce the issue 100% of times provided I follow these exact steps.

https://github.com/AndreiHarasemiuc/Android-Job-Rescheduling-Issue-sample

1. Launch the app
2. App will wait 10 seconds (Handler.postDelayed) and schedule an exact job with a delay of 20 seconds.
3. At the moment you see in the logs that the job has been scheduled, close off the app from recent tasks.
4. In 20 seconds the job will run. The job will do 2 things. Show a notification & schedule another job with a delay of 1 minute.
5. When the job runs and the notification is displayed, immediately click the notification. Clicking the notification will take you to an empty activity. As soon as that activity opens, background the app.

Result: The second job that you just scheduled (with a delay of 1 minute) will run with a delay of 0 seconds soon after you background the app.

Please note that the sample app does not use _1.2.0-alpha3_ because I had some weird errors and couldn't buld the project and didn't have time to see what they were about. so I used _1.1.11_ However, I succesfully added _1.2.0-alpha3_ in my main project and I could still reproduce the issue just like before.

[vRallev]

Thanks, I'll take a look next week!

[vRallev]

I've tested your demo with an SDK 25 emulator and couldn't reproduce what you describe. That's my log:

08-20 17:05:19.106 1698-1719/system_process I/ActivityManager: Displayed dev.cosmos.android_job_reschedule_issue/.MainActivity: +412ms
08-20 17:05:28.855 4730-4730/dev.cosmos.android_job_reschedule_issue D/JobProxy14: Scheduled alarm, request{id=1, tag=tag}, delay 00:00:20, exact true, reschedule count 0
08-20 17:05:28.945 4730-4752/dev.cosmos.android_job_reschedule_issue D/JobRescheduleService: Reschedule 0 jobs of 1 jobs
08-20 17:05:44.907 1698-2150/system_process I/ActivityManager: Killing 4730:dev.cosmos.android_job_reschedule_issue/u0a87 (adj 900): remove task
08-20 17:05:48.898 4766-4782/? D/JobRescheduleService: Reschedule service started
08-20 17:05:48.903 4766-4783/? D/PlatformAlarmService: Run job, request{id=1, tag=tag}, waited 00:00:20, delay 00:00:20
08-20 17:05:48.908 4766-4783/? I/JobExecutor: Executing request{id=1, tag=tag}, context PlatformAlarmService
08-20 17:05:48.929 4766-4784/? D/JobProxy14: Scheduled alarm, request{id=2, tag=tag}, delay 00:01:00, exact true, reschedule count 0
08-20 17:05:48.929 4766-4784/? I/JobExecutor: Finished job{id=1, finished=true, result=SUCCESS, canceled=false, periodic=false, class=ReminderJob, tag=tag}
08-20 17:05:48.930 4766-4783/? D/PlatformAlarmService: Finished job, request{id=1, tag=tag} SUCCESS
08-20 17:05:50.026 1698-3069/system_process W/ActivityManager: startActivity called from non-Activity context; forcing Intent.FLAG_ACTIVITY_NEW_TASK for: Intent { cmp=dev.cosmos.android_job_reschedule_issue/.ActivityTopOpenFromNotification }
08-20 17:05:50.251 1698-1719/system_process I/ActivityManager: Displayed dev.cosmos.android_job_reschedule_issue/.ActivityTopOpenFromNotification: +222ms
08-20 17:05:58.942 4766-4782/dev.cosmos.android_job_reschedule_issue D/JobRescheduleService: Reschedule 0 jobs of 1 jobs
08-20 17:06:48.933 4766-4857/dev.cosmos.android_job_reschedule_issue D/PlatformAlarmService: Run job, request{id=2, tag=tag}, waited 00:01:00, delay 00:01:00
08-20 17:06:48.938 4766-4857/dev.cosmos.android_job_reschedule_issue I/JobExecutor: Executing request{id=2, tag=tag}, context PlatformAlarmService
08-20 17:06:48.951 4766-4784/dev.cosmos.android_job_reschedule_issue D/JobProxy14: Scheduled alarm, request{id=3, tag=tag}, delay 00:01:00, exact true, reschedule count 0
08-20 17:06:48.952 4766-4784/dev.cosmos.android_job_reschedule_issue I/JobExecutor: Finished job{id=2, finished=true, result=SUCCESS, canceled=false, periodic=false, class=ReminderJob, tag=tag}
08-20 17:06:48.952 4766-4857/dev.cosmos.android_job_reschedule_issue D/PlatformAlarmService: Finished job, request{id=2, tag=tag} SUCCESS

My only idea what could cause issues was fixed in 072e2d410356364ab20ea225df0ed8a8c158b56c I've published a new version with this fix 1.2.0-alpha4. Could you give the new version a try and maybe test your demo again? If I can't reproduce the issue, I cannot help you or fix the bug.

[AndreiHarasemiuc]

I have tested the new version you published and I can still replicate the issue on several of my devices as well as on an emulator. Looking at your logs, I am under the impression you are missing a step when trying to replicate the issue.

The last step says:

When the job runs and the notification is displayed, immediately click the notification. Clicking the notification will take you to an empty activity. As soon as that activity opens, background the app.

The highlighted part will make the reschedule service run when the app was backgrounded, and only in that case it will mis-schedule a job for me.

Let me summarize:

1. Open app (it will schedule a job in 20 sec)
2. Close app completely (swipe off task list)
3. Immediately tap on the notification when it shows (due to the 20 sec job running)
4. Background the app (tap Home) immediately after the empty activity appears (as a result of tapping the notification)
5. Job scheduled a minute from now will run a couple of seconds later.

I am aware this is frustrating but I have triple checked everything and I can still reproduce this with a 100% success rate on any device I try. Please give it another shot.

[AndreiHarasemiuc]

@vRallev My last comment might have flown under the radar because of all the other new tickets and I also failed to mention your name. Could you please take a look at this when you have a chance?

Thanks!

[Abdullah-Hussein]

@AndreiHarasemiuc I have same issue , but happen with my huawei device only and not in emulator , i set 5 alarm with same way you use and some times 1 alarm fire , but alot off times 3 , 4 or all alarm fire together !!
did you find solution for this issue ?

[vRallev]

@AndreiHarasemiuc I'm sorry for the delay, but I didn't forget you. There simply was too much other stuff on my plate.

@Abdullah-Hussein Your issue sounds different. If you schedule 5 jobs, then it can happen, that they'll run at the same time. The system tries to batch jobs and alarms. That's expected behavior.

[AndreiHarasemiuc]

@vRallev No worries, thank you for your responses, I was just making sure my comment didn't fly under the radar. I'm a novice github user.

[Abdullah-Hussein]

@vRallev thanks for fast replay , but i confused how to schedule 5 jobs in different times everyday without faceing this problem ?
and i see in documentation that if i use setExact this job will not reschedule , so why JobRescheduleService called?

[vRallev]

JobRescheduleService is an internal helper service, which reschedules YOUR jobs if that's necessary, e.g. after a reboot.

[Abdullah-Hussein]

@vRallev but in my case just alarm fire! ,why it called ?

[vRallev]

@Abdullah-Hussein https://developer.android.com/reference/android/app/AlarmManager.html#set(int, long, android.app.PendingIntent) Please don't post in this issue anymore. If you still have questions, create another issue. Your "problem" is expected behavior and working properly.

[vRallev]

@AndreiHarasemiuc @dshatz I'm pretty confident that I found the cause for the bug. Thanks for your patience! Could you give version 1.2.0-RC2 a try? This one includes the fix.

[AndreiHarasemiuc]

@vRallev Hey man, looks like the bug is gone! Thanks for the fix!