IssueTracker

Why are you using PeriodicWork to update a widget ? If the widget was removed, then your PeriodicWorkRequests are still going to be executed which is not very useful.

--

When you have more information, please let us know.

Erm, when the widget is removed I also cancel the periodic work associated with the widget... it's really quite simple.

So, have there been any reports?  I've reverted back to 2.0.1 and the users who were experiencing issues with 2.1.0-alpha are no longer experiencing the same issues.

> Erm, when the widget is removed I also cancel the periodic work associated with the widget... it's really quite simple.
I did not mean it cant' be done. But PeriodicWorkRequests are not a great fit, as they involve much more book-keeping than your use-case demands. You could just use a background thread pool, and spin it down when the Widget is removed.

Can you please elaborate on the actual problem ? What are you seeing ?

> could just use a background thread pool, and spin it down when the Widget is removed

why have I never read anything out there that suggests this approach to updating widgets on a regular schedule (e.g. roughly once every hour)?  Even if I understood the relevance of background thread pools in this context, and how to set up a regular schedule with background pool threads, how would it survive a device reboot?

Anyway, that's a bit off topic.  Back on topic, I'm not doing anything complicated.  When the user updates the widget settings and saves, it sets up a periodic work request along the following lines:

        PeriodicWorkRequest.Builder workRequestBuilder = new PeriodicWorkRequest.Builder(MyWorker.class, interval, TimeUnit.MILLISECONDS, flexInterval, TimeUnit.MILLISECONDS);
        workRequestBuilder.setConstraints(constraints);
        workRequestBuilder.setInputData(inputData);
        workRequestBuilder.addTag(workTag);
        workRequestBuilder.addTag(PERIODIC);
        PeriodicWorkRequest myWork = workRequestBuilder.build();
        WorkManager workManager = WorkManager.getInstance(/*context*/);
        workManager.enqueueUniquePeriodicWork(name, ExistingPeriodicWorkPolicy.REPLACE, myWork);

With 2.1.0-alpha, and passing contect to WorkManager.getInstance(), this doesn't work reliably.  Sometimes, **on some devices** (works fine on my own test devices), the periodic work request doesn't seem to stick... the widget doesn't update on a regular schedule.  With 2.0.1, using EXACTLY the same code (except for NOT passing context), it all works fine.  Sorry, I don't have any more information at present.

> Even if I understood the relevance of background thread pools in this context, and how to set up a regular schedule with background pool threads, how would it survive a device reboot?
You could use a ScheduledThreadPoolExecutor which executes a Runnable which eventually schedules itself simulating periodic work. You don't have to survive reboot because your Widget is eventually re-created (post reboot) where you setup an executor and your work again.


> With 2.1.0-alpha, and passing contect to WorkManager.getInstance(), this doesn't work reliably.  Sometimes, **on some devices** (works fine on my own test devices), the periodic work request doesn't seem to stick... the widget doesn't update on a regular schedule.  With 2.0.1, using EXACTLY the same code (except for NOT passing context), it all works fine.  Sorry, I don't have any more information at present.
Which devices ?
One other thing you could do - is to turn on verbose logging using a custom Configuration. Use Configuration#setMinimumLoggingLevel() and set it to Log.DEBUG.
Once you get those logs - please attach them to the bug report.

> use ScheduledThreadPoolExecutor

And with that method how do you benefit from adding e.g. a network constraint which allows the widget to refresh its content immediately when network is restored?  As mentioned, I've seen anyone ever recommend Scheduled Thread Pools for widget auto updating.  The general guidance (even from the official guides, e.g. https://developer.android.com/guide/topics/appwidgets#MetaData) suggest using AlarmManager for "custom" auto updating, and WorkManager is effectively just a higher-level wrapper around AlarmManager, JobScheduler etc.  WorkManager seems like a perfect fit to me!

> Which devices ?

Confirmed so far as having problems with 2.1.0-alpha that are fixed by reverting to 2.0.1:

BlackBerry BBF100-2 running Android 8.1.0
Motorola Moto G running Android 8.1.0
Asus ZenPad 10 running Android 7.0

> turn on verbose logging and provide logs

Will try to get some logs from at least one of these users.

If you have a sample, that would help as well.

Out of curiosity, why are you using REPLACE ? I think KEEP might be a better fit.

I'm using REPLACE because there might be multiple triggers for setting up a periodic schedule for a widget add I only want one active.  Shouldn't replace be safe?

It's safe but you are doing more work than necessary.

Also, it's only safe if you are handling stoppages correctly. Even if there are multiple triggers, is there value in stopping an instance of this Worker, and  enqueuing a new request ?
KEEP treats your enqueue() as a no-op and I think that is probably the behavior you want.

You mentioned that you are cancelling this Worker when the widget is being removed. Never mind, you should use REPLACE for a new copy of this WorkRequest.

Ideally you should keep track of whether the WorkRequest was cancelled or not, and then do nothing if it was not in a cancelled state (then multiple triggers would be a no-op).
If it was cancelled, you could then do a REPLACE.

So I should be using REPLACE after all?

Still haven't managed to get useful logs.

Have obtained logs, and so far as I can see, the periodic work is set up OK, and at a later time (when the periodic work appears to be "dead") the periodic work is still visible in the work queue in state ENQUEUED, but it's just not firing.  My next line of enquiry is whether the network constraint I'm adding is causing this... maybe the work doesn't run because it thinks there is no network, even though there is.  I'll try without adding the network constraint and see if it runs better.

Have you managed to reproduce this on your own / or does this happen to one of your users ?
Can you provide us with a sample app so I can try investigating this on my end as well ?

Also, can you try using 2.1.0-alpha03 ?

Yep, as suspected, when I don't set a NETWORK constraint with 2.1.0-alpha02 it all works nicely for those problematic devices.

Next, I'll try 2.1.0-alpha03 with a NETWORK constraint and see how that behaves.

Which network constraint are you using?  If you change it to a different one, does it work?

NetworkType.UNMETERED or NetworkType.CONNECTED depending on user settings

On my device I am experiencing a couple of strange things, and I don't know whether it's related to this.  After setting up a scheduling periodic work request as per the code above (though I now also set an initialInterval as is allowed for in the new API), when the first periodic work fires I see the following in the logs, but the work itself does not actually run (seems to stop before it gets anywhere):

2019-06-11 16:55:46.657 21002-21002/com.mydomain.myapp D/WM-PackageManagerHelper: androidx.work.impl.background.systemjob.SystemJobService enabled
2019-06-11 16:55:46.657 21002-21002/com.mydomain.myapp D/WM-Schedulers: Created SystemJobScheduler and enabled SystemJobService
2019-06-11 16:55:46.692 21002-21002/com.mydomain.myapp D/WM-SystemJobService: onStartJob for 9cfda55f-299d-4c93-bcb2-692ea5b4d39f
2019-06-11 16:55:46.714 21002-21026/com.mydomain.myapp D/WM-ForceStopRunnable: Found unfinished work, scheduling it.
2019-06-11 16:55:46.719 21002-21026/com.mydomain.myapp D/WM-SystemJobScheduler: Scheduling work ID 9cfda55f-299d-4c93-bcb2-692ea5b4d39f Job ID 7640
2019-06-11 16:55:46.721 21002-21002/com.mydomain.myapp D/WM-SystemJobService: onStopJob for 9cfda55f-299d-4c93-bcb2-692ea5b4d39f
2019-06-11 16:55:46.737 21002-21032/com.mydomain.myapp D/WM-Processor: Processor: processing 9cfda55f-299d-4c93-bcb2-692ea5b4d39f
2019-06-11 16:55:46.738 21002-21033/com.mydomain.myapp D/WM-Processor: Processor stopping 9cfda55f-299d-4c93-bcb2-692ea5b4d39f
2019-06-11 16:55:46.739 21002-21033/com.mydomain.myapp D/WM-WorkerWrapper: Work interrupted for null
2019-06-11 16:55:46.740 21002-21033/com.mydomain.myapp D/WM-Processor: WorkerWrapper stopped for 9cfda55f-299d-4c93-bcb2-692ea5b4d39f
2019-06-11 16:55:46.740 21002-21033/com.mydomain.myapp D/WM-StopWorkRunnable: StopWorkRunnable for 9cfda55f-299d-4c93-bcb2-692ea5b4d39f; Processor.stopWork = true
2019-06-11 16:55:46.741 21002-21033/com.mydomain.myapp D/WM-WorkerWrapper: Work interrupted for Work [ id=9cfda55f-299d-4c93-bcb2-692ea5b4d39f, tags={ periodic, widget-632, com.mydomain.myapp.MyWorker } ]
2019-06-11 16:55:46.749 21002-21002/com.mydomain.myapp D/WM-Processor: Processor 9cfda55f-299d-4c93-bcb2-692ea5b4d39f executed; reschedule = true

What does this "Found unfinished work, scheduling it" mean??  Maybe it relates to the initialInterval functionality for periodic work, and nothing to be concerned about?

This is nothing to be concerned about. "Found unfinished work, scheduling it" is something we do automatically on Application#onCreate(). This is meant to be a recovery mechanism for WorkRequests, if your application crashed unexpectedly previously. WorkManager looks at WorkRequests that are in the ENQUEUED state and re-schedules them. However rescheduling is idempotent. We will only reschedule Workers if they have not been previously rescheduled and we will never run Workers before their scheduled run time.

The other sets of logs are about Workers being interrupted (either due to cancellations or in reaction to changes in constraints) but they are still getting rescheduled.

My guess is the system thinks you have network and then immediately says you don't, causing it to get stopped right away.  That's really strange.  Can you reproduce this on a stock Android device or emulator?  I wonder if there's a bug with these devices.

OK but I just saw the exact same thing again, after enqueuing a new periodic work.  This happens when the periodic work first fires.  i.e. I enqueue the periodic work with an interval of 30 mins and an initialInterval of 30 mins too.  No flexInterval.  After 30 mins, these logs are generated.  No work is actually performed.  I do set a network constraint, but the constraint is DEFINITELY satisfied because WiFi is on, and the device is plugged into the PC.  Why doesn't the work run normally after 30 mins, without all of this unfinished work / rescheduling stuff?

And I wonder if this is related to what my app users (some of them anyway) are seeing.

It's probably simpler at this point if you can give us a sample app where you can reproduce this problem so we can investigate.

I tried creating a sample app, but typically it doesn't reproduce the issue.

What about about the following log message... what is it meant to mean??

D/WM-WorkerWrapper: Work interrupted for null

That just means the work was interrupted before its description could be generated (nearly immediately).

Anyway, I don't think there's anything for us to diagnose until we get a minimal repro case.  I would focus on getting that and then get back to us.  You can do this by building a sample app from the ground up until you get it, or removing things from your app until you no longer reproduce the problem.

I note that this behaviour started for me in 2.1.0, and the main (only) change I had to make from 2.0.1 is to call WorkManager.getInstance(Context) rather than just WorkManager.getInstance().  Are there any gotchas to watch out for in this change, e.g. what context is used in the call?  If the periodic work is being performed in the background (no app or activity in foreground) to trigger a content refresh of a widget (via an AppWidgetProvider), is the new context requirement going to cause problems?  The sample app I produced didn't attempt to replicate the widget-based nature of my actual app... just did things via an Activity so maybe that's why it didn't reproduce the problem.  Anyway, maybe you have some insights to share regarding the new context requirement in WorkManager.getInstance()?

... follow-up to the post just above... from some unscientific tests (am short of time)... it seems that the widget that is being triggered by the PeriodicWorkRequest seems to update more consistently when the configuration Activity that is associated with the widget is open or has been opened recently.  So I am wondering whether this is indeed a context-related issue... maybe passing an Activity context to WorkManager.getInstance() rather than an Application context? ... I need to dig back into the code (don't have access right now).

Internally, will WorkManager.getInstance() be sensitive to what context is passed in?  

I note that the docs for WorkManager.initialize() is more explicit about what type of context can be passed in (i.e. *any* context, because getApplicationContext() is called internally anyway):

"Context: A Context object for configuration purposes. Internally, this class will call Context.getApplicationContext(), so you may safely pass in any Context without risking a memory leak."

There should be no difference. We always use the application context.

Dang, another theory bites the dust.  I can't fathom what's going on.  I'm going to revert to 2.0.1 until the dust settles.

I know it doesn't help get to the bottom of this issue, but when I revert to 2.0.1 (with the only change being to NOT pass context to WorkManager.getInstance function) everything works fine for me and also for all the beta users.  With 2.1.0 alpha 03... doesn't work reliably at all.  It's as stark as that.  No changes other than as stated above.  Wish I could reproduce this in a sample app.

Does it reproduce if you use the newest version and use the deprecated (no-argument) method?

So, going from 2.0.1 to 2.1.0-alpha03 and making **no changes whatsoever**, including using the deprecated no-argument method, the problem is there.  i.e. when the flexInterval for the first periodic period arrives (30 mins interval, with 5 mins flexInterval), rather than actually start the work, the following logs are generated:

2019-06-13 18:17:06.088 10790-10790/com.mydomain.myapp D/WM-PackageManagerHelper: androidx.work.impl.background.systemjob.SystemJobService enabled
2019-06-13 18:17:06.088 10790-10790/com.mydomain.myapp D/WM-Schedulers: Created SystemJobScheduler and enabled SystemJobService
2019-06-13 18:17:06.120 10790-10790/com.mydomain.myapp D/WM-SystemJobService: onStartJob for 4b023ffc-7da0-4ec5-b6ef-5607e8148591
2019-06-13 18:17:06.141 10790-10811/com.mydomain.myapp D/WM-ForceStopRunnable: Found unfinished work, scheduling it.
2019-06-13 18:17:06.149 10790-10811/com.mydomain.myapp D/WM-SystemJobScheduler: Scheduling work ID ab5daf97-bb4a-4680-942e-d30f119f0d75 Job ID 7714
2019-06-13 18:17:06.160 10790-10811/com.mydomain.myapp D/WM-SystemJobScheduler: Scheduling work ID 4b023ffc-7da0-4ec5-b6ef-5607e8148591 Job ID 7715
2019-06-13 18:17:06.176 10790-10790/com.mydomain.myapp D/WM-SystemJobService: onStopJob for 4b023ffc-7da0-4ec5-b6ef-5607e8148591
2019-06-13 18:17:06.206 10790-10817/com.mydomain.myapp D/WM-Processor: Processor: processing 4b023ffc-7da0-4ec5-b6ef-5607e8148591
2019-06-13 18:17:06.208 10790-10818/com.mydomain.myapp D/WM-Processor: Processor stopping 4b023ffc-7da0-4ec5-b6ef-5607e8148591
2019-06-13 18:17:06.208 10790-10818/com.mydomain.myapp D/WM-WorkerWrapper: Work interrupted for null
2019-06-13 18:17:06.211 10790-10818/com.mydomain.myapp D/WM-Processor: WorkerWrapper stopped for 4b023ffc-7da0-4ec5-b6ef-5607e8148591
2019-06-13 18:17:06.211 10790-10818/com.mydomain.myapp D/WM-StopWorkRunnable: StopWorkRunnable for 4b023ffc-7da0-4ec5-b6ef-5607e8148591; Processor.stopWork = true
2019-06-13 18:17:06.211 10790-10790/com.mydomain.myapp D/WM-Processor: Processor 4b023ffc-7da0-4ec5-b6ef-5607e8148591 executed; reschedule = true
2019-06-13 18:17:06.212 10790-10816/com.mydomain.myapp D/WM-WorkerWrapper: Work interrupted for Work [ id=4b023ffc-7da0-4ec5-b6ef-5607e8148591, tags={ periodic, widget-632, com.mydomain.myapp.MyWorker } ]

I remember you mentioning that it works reliably when you remove a Network constraint. Is that still the case ?

Just tried that now.  The only constraint I ever put on the periodic work request is a Network constraint, based on something like:

Constraints constraints = constraintsBuilder.setRequiredNetworkType(wifiOnly ? NetworkType.UNMETERED : NetworkType.CONNECTED).build();

then

workRequestBuilder.setConstraints(constraints);

instead of the above I just tested with setting constraints to NONE:

Constraints constraints = Constraints.NONE;

and exactly the same happens as before... same log messages.  So the network constraint was a red herring in this case.  I think I saw improved reliability on user devices when not setting a network constraint, but I was working somewhat blind so may have been seeing something else.  Now I'm able to reproduce this behaviour on my own device and can see all the logs for sure.

I left the device sitting there after the last logs (setting Contraints.NONE but it appears to make no difference), and half an hour after the "Work interrupted for null" logs (like those above), the work appears to fire and run normally, with following logs:

2019-06-13 19:38:59.637 12468-12468/com.mydomain.myapp D/WM-SystemJobService: onStartJob for f4f1140c-e3b6-4eab-8017-6896cee38e47
2019-06-13 19:38:59.642 12468-12496/com.mydomain.myapp D/WM-Processor: Processor: processing f4f1140c-e3b6-4eab-8017-6896cee38e47
2019-06-13 19:38:59.712 12468-12468/com.mydomain.myapp D/WM-WorkerWrapper: Starting work for com.cloud3squared.meteogram.MeteogramWorker
2019-06-13 19:39:11.262 12468-12496/com.mydomain.myapp D/WM-WorkerWrapper: com.cloud3squared.meteogram.MeteogramWorker returned a Success {mOutputData=androidx.work.Data@0} result.
2019-06-13 19:39:11.281 12468-12468/com.mydomain.myapp D/WM-Processor: Processor f4f1140c-e3b6-4eab-8017-6896cee38e47 executed; reschedule = false
2019-06-13 19:39:11.281 12468-12468/com.mydomain.myapp D/WM-SystemJobService: f4f1140c-e3b6-4eab-8017-6896cee38e47 executed on JobScheduler
2019-06-13 19:39:11.325 12468-12496/com.mydomain.myapp D/WM-SystemJobScheduler: Scheduling work ID f4f1140c-e3b6-4eab-8017-6896cee38e47 Job ID 7718

So is it just that first firing of the periodic work that produces the weird logs and failed run?

And here are the logs for the previous (apparently failed) attempt:

2019-06-13 19:12:50.879 12468-12468/com.mydomain.myapp D/WM-PackageManagerHelper: androidx.work.impl.background.systemjob.SystemJobService enabled
2019-06-13 19:12:50.879 12468-12468/com.mydomain.myapp D/WM-Schedulers: Created SystemJobScheduler and enabled SystemJobService
2019-06-13 19:12:50.918 12468-12468/com.mydomain.myapp D/WM-SystemJobService: onStartJob for f4f1140c-e3b6-4eab-8017-6896cee38e47
2019-06-13 19:12:50.955 12468-12490/com.mydomain.myapp D/WM-ForceStopRunnable: Found unfinished work, scheduling it.
2019-06-13 19:12:50.965 12468-12490/com.mydomain.myapp D/WM-SystemJobScheduler: Scheduling work ID f4f1140c-e3b6-4eab-8017-6896cee38e47 Job ID 7718
2019-06-13 19:12:50.966 12468-12468/com.mydomain.myapp D/WM-SystemJobService: onStopJob for f4f1140c-e3b6-4eab-8017-6896cee38e47
2019-06-13 19:12:50.979 12468-12497/com.mydomain.myapp D/WM-Processor: Processor: processing f4f1140c-e3b6-4eab-8017-6896cee38e47
2019-06-13 19:12:50.981 12468-12498/com.mydomain.myapp D/WM-Processor: Processor stopping f4f1140c-e3b6-4eab-8017-6896cee38e47
2019-06-13 19:12:50.981 12468-12498/com.mydomain.myapp D/WM-WorkerWrapper: Work interrupted for null
2019-06-13 19:12:50.983 12468-12498/com.mydomain.myapp D/WM-Processor: WorkerWrapper stopped for f4f1140c-e3b6-4eab-8017-6896cee38e47
2019-06-13 19:12:50.983 12468-12498/com.mydomain.myapp D/WM-StopWorkRunnable: StopWorkRunnable for f4f1140c-e3b6-4eab-8017-6896cee38e47; Processor.stopWork = true
2019-06-13 19:12:50.984 12468-12498/com.mydomain.myapp D/WM-WorkerWrapper: Work interrupted for Work [ id=f4f1140c-e3b6-4eab-8017-6896cee38e47, tags={ periodic, widget-632, com.mydomain.myapp.MyWorker} ]
2019-06-13 19:12:50.991 12468-12468/com.mydomain.myapp D/WM-Processor: Processor f4f1140c-e3b6-4eab-8017-6896cee38e47 executed; reschedule = true
2019-06-13 19:12:50.991 12468-12468/com.mydomain.myapp D/WM-SystemJobService: f4f1140c-e3b6-4eab-8017-6896cee38e47 executed on JobScheduler

2019-06-13 19:12:50.966 12468-12468/com.mydomain.myapp D/WM-SystemJobService: onStopJob for f4f1140c-e3b6-4eab-8017-6896cee38e47

I just noticed this. This means that the OS is explicitly asking WorkManager to stop whatever it was doing for that job. Which is why WorkManager stops, but the reschedule bit is set to true.

And the next two firings (half an hour after the above, then another half hour after that):

2019-06-13 20:10:00.809 25899-25899/com.mydomain.myapp D/WM-PackageManagerHelper: androidx.work.impl.background.systemjob.SystemJobService enabled
2019-06-13 20:10:00.809 25899-25899/com.mydomain.myapp D/WM-Schedulers: Created SystemJobScheduler and enabled SystemJobService
2019-06-13 20:10:00.850 25899-25899/com.mydomain.myapp D/WM-SystemJobService: onStartJob for f4f1140c-e3b6-4eab-8017-6896cee38e47
2019-06-13 20:10:00.877 25899-25924/com.mydomain.myapp D/WM-ForceStopRunnable: Found unfinished work, scheduling it.
2019-06-13 20:10:00.883 25899-25924/com.mydomain.myapp D/WM-SystemJobScheduler: Scheduling work ID f4f1140c-e3b6-4eab-8017-6896cee38e47 Job ID 7718
2019-06-13 20:10:00.884 25899-25899/com.mydomain.myapp D/WM-SystemJobService: onStopJob for f4f1140c-e3b6-4eab-8017-6896cee38e47
2019-06-13 20:10:00.894 25899-25930/com.mydomain.myapp D/WM-Processor: Processor: processing f4f1140c-e3b6-4eab-8017-6896cee38e47
2019-06-13 20:10:00.895 25899-25931/com.mydomain.myapp D/WM-Processor: Processor stopping f4f1140c-e3b6-4eab-8017-6896cee38e47
2019-06-13 20:10:00.896 25899-25931/com.mydomain.myapp D/WM-WorkerWrapper: Work interrupted for null
2019-06-13 20:10:00.897 25899-25931/com.mydomain.myapp D/WM-Processor: WorkerWrapper stopped for f4f1140c-e3b6-4eab-8017-6896cee38e47
2019-06-13 20:10:00.898 25899-25931/com.mydomain.myapp D/WM-StopWorkRunnable: StopWorkRunnable for f4f1140c-e3b6-4eab-8017-6896cee38e47; Processor.stopWork = true
2019-06-13 20:10:00.899 25899-25929/com.mydomain.myapp D/WM-WorkerWrapper: Work interrupted for Work [ id=f4f1140c-e3b6-4eab-8017-6896cee38e47, tags={ periodic, widget-632, com.mydomain.myapp.MyWorker } ]
2019-06-13 20:10:00.901 25899-25899/com.mydomain.myapp D/WM-Processor: Processor f4f1140c-e3b6-4eab-8017-6896cee38e47 executed; reschedule = true
2019-06-13 20:10:00.901 25899-25899/com.mydomain.myapp D/WM-SystemJobService: f4f1140c-e3b6-4eab-8017-6896cee38e47 executed on JobScheduler
2019-06-13 20:10:00.908 25899-25899/com.mydomain.myapp D/WM-SystemJobService: onStartJob for f4f1140c-e3b6-4eab-8017-6896cee38e47
2019-06-13 20:10:00.908 25899-25931/com.mydomain.myapp D/WM-Processor: Processor: processing f4f1140c-e3b6-4eab-8017-6896cee38e47
2019-06-13 20:10:00.920 25899-25899/com.mydomain.myapp D/WM-WorkerWrapper: Starting work for com.mydomain.myapp.MyWorker
2019-06-13 20:10:10.453 25899-25931/com.mydomain.myapp D/WM-WorkerWrapper: com.mydomain.myapp.MyWorker returned a Success {mOutputData=androidx.work.Data@0} result.
2019-06-13 20:10:10.484 25899-25899/com.mydomain.myapp D/WM-Processor: Processor f4f1140c-e3b6-4eab-8017-6896cee38e47 executed; reschedule = false
2019-06-13 20:10:10.484 25899-25899/com.mydomain.myapp D/WM-SystemJobService: f4f1140c-e3b6-4eab-8017-6896cee38e47 executed on JobScheduler
2019-06-13 20:10:10.599 25899-25931/com.mydomain.myapp D/WM-SystemJobScheduler: Scheduling work ID f4f1140c-e3b6-4eab-8017-6896cee38e47 Job ID 7718

2019-06-13 20:40:10.583 25899-25899/com.mydomain.myapp D/WM-SystemJobService: onStartJob for f4f1140c-e3b6-4eab-8017-6896cee38e47
2019-06-13 20:40:10.593 25899-25929/com.mydomain.myapp D/WM-Processor: Processor: processing f4f1140c-e3b6-4eab-8017-6896cee38e47
2019-06-13 20:40:10.649 25899-25899/com.mydomain.myapp D/WM-WorkerWrapper: Starting work for com.mydomain.myapp.MyWorker
2019-06-13 20:40:22.394 25899-25931/com.mydomain.myapp D/WM-WorkerWrapper: com.mydomain.myapp.MyWorker returned a Success {mOutputData=androidx.work.Data@0} result.
2019-06-13 20:40:22.416 25899-25899/com.mydomain.myapp D/WM-Processor: Processor f4f1140c-e3b6-4eab-8017-6896cee38e47 executed; reschedule = false
2019-06-13 20:40:22.417 25899-25899/com.mydomain.myapp D/WM-SystemJobService: f4f1140c-e3b6-4eab-8017-6896cee38e47 executed on JobScheduler
2019-06-13 20:40:22.553 25899-25931/com.mydomain.myapp D/WM-SystemJobScheduler: Scheduling work ID f4f1140c-e3b6-4eab-8017-6896cee38e47 Job ID 7718

> the OS is explicitly asking WorkManager to stop whatever it was doing for that job

is this expected?

So apart from the missed "first" firing after setting up the periodic work (see #34), subsequent firings do seem to happen, despite the onStopJob message each time

If this happens consistently on first run of the periodic work, you can set a breakpoint in onStopJob() and look at the stack. You can also put another breakpoint on WorkerWrapper.interrupt() to see the call stack and that might give you more hints on why the first run of this Worker seems to be getting interrupted.

--
You cannot reproduce this behavior in a sample app, right ?

In the logs you sent me:

2019-06-13 20:10:00.884 25899-25899/com.mydomain.myapp D/WM-SystemJobService: onStopJob for f4f1140c-e3b6-4eab-8017-6896cee38e47 is the only instance of onStopJob().
Subequent logs only have onStartJob() and subsequent rescheduling unless you are referring to other logs.

> You cannot reproduce this behavior in a sample app, right?

not yet

> is the only instance of onStopJob

In the above logs snippets I can see four instances:

2019-06-11 16:55:46.721 21002-21002/com.mydomain.myapp D/WM-SystemJobService: onStopJob for 9cfda55f-299d-4c93-bcb2-692ea5b4d39f
2019-06-13 18:17:06.176 10790-10790/com.mydomain.myapp D/WM-SystemJobService: onStopJob for 4b023ffc-7da0-4ec5-b6ef-5607e8148591
2019-06-13 19:12:50.966 12468-12468/com.mydomain.myapp D/WM-SystemJobService: onStopJob for f4f1140c-e3b6-4eab-8017-6896cee38e47
2019-06-13 20:10:00.884 25899-25899/com.mydomain.myapp D/WM-SystemJobService: onStopJob for f4f1140c-e3b6-4eab-8017-6896cee38e47

Its expected (in many of the listed cases apart from the one I specifically called out) because Workers can potentially run on multiple schedulers (JobScheduler, GreedyScheduler etc). So once a Worker is done, to make sure we have consistent book-keeping we ask all other schedulers to cancel.
That's why you see them.

I think rather than trying to dig into more implementation details - its best if you try and reproduce this behavior stand-alone. That will help us narrow down potential issues if any.

OK I'll try.

BTW in my current sample app I'm seeing lots of constraint-related WM logging, like:

2019-06-13 21:56:11.520 28703-28732/com.example.workrequesttest D/WM-ConstraintTracker: NetworkStateTracker: initial state = [ Connected=true Validated=true Metered=false NotRoaming=true ]
2019-06-13 21:56:11.520 28703-28732/com.example.workrequesttest D/WM-NetworkStateTracker: Registering network callback
2019-06-13 21:56:11.523 28703-28732/com.example.workrequesttest D/WM-WorkConstraintsTrack: Constraints met for d5d17c8b-dca3-4beb-8a3e-c41650e6ff7f
2019-06-13 21:56:11.523 28703-28732/com.example.workrequesttest D/WM-GreedyScheduler: Constraints met: Scheduling work ID d5d17c8b-dca3-4beb-8a3e-c41650e6ff7f

I'm not seeing this logging in my actual app logs... any reason why?  For both, I'm setting WM logging level to Log.VERBOSE.

I'm looking at the result of:

adb shell dumpsys jobscheduler

and comparing my test app to my actual app.  So far as I can see, I'm using the same methods, but in one (using WM 2.0.1) I see:

    Required constraints: TIMING_DELAY DEADLINE CONNECTIVITY
    Satisfied constraints: CONNECTIVITY UNMETERED NOT_ROAMING APP_NOT_IDLE DEVICE_NOT_DOZING
    Unsatisfied constraints: TIMING_DELAY DEADLINE
    Earliest run time: 09:53
    Latest run time: 14:53

and in the other (using 2.1.0 beta 01) I see:

    Required constraints: TIMING_DELAY CONNECTIVITY
    Satisfied constraints: CONNECTIVITY UNMETERED NOT_ROAMING APP_NOT_IDLE DEVICE_NOT_DOZING
    Unsatisfied constraints: TIMING_DELAY
    Earliest run time: 07:27
    Latest run time: none

The difference is in the DEADLINE being a required (and unsatisfied) constraint in one but not the other.  What is that, and what am I doing to set it?  I'm only AFAIK setting a network constraint.

Also I wonder (being ever hopeful) that the lack of a DEADLINE (and "latest run time" being NONE) in 2.1.0-beta-01 is the reason why it is more problematic for me that 2.0.1.

I reverted my sample app to 2.0.1 and sure enough, the sheduled jobs now have a DEADLINE and "latest run time".

Sample app is at: https://bitbucket.org/drmrbrewer/sample

It comes with an app and also a widget.  The app doesn't do anything exciting.  The WorkManager stuff is triggered via the widget.

So, add a widget to the home screen... in the config screen for the widget, just hit the "Add/Update Widget" button... it will set up a simple widget with "EXAMPLE" text initially, that is soon replaced by the current time.

Then every 15 mins the time in the widget should update itself, to show it's auto updating.  If the time is more than 15 mins ago, it may have stopped auto updating.

I ran the sample app, and so far I don't see anything out of the ordinary. The widget is updating every 15 miins.
Will keep the app running for the rest of the day.

Here are some logs that I see:

2019-06-17 14:08:29.052 11426-11426/com.example.mysampleapp D/WM-SystemJobService: onStartJob for 09719581-3564-4800-a89b-577f293a3605
2019-06-17 14:08:29.054 11426-11480/com.example.mysampleapp D/WM-Processor: Processor: processing 09719581-3564-4800-a89b-577f293a3605
2019-06-17 14:08:29.068 11426-11426/com.example.mysampleapp D/WM-WorkerWrapper: Starting work for com.example.mysampleapp.MyWorker
2019-06-17 14:08:29.068 11426-11426/com.example.mysampleapp D/MyWorker: starting work 09719581-3564-4800-a89b-577f293a3605
2019-06-17 14:08:29.070 11426-11426/com.example.mysampleapp D/MyWorker: startWork (appWidgetId = 7) (method = periodic) (trigger = routine) (orientation = 1)
2019-06-17 14:08:29.070 11426-11426/com.example.mysampleapp D/MyWorker: starting some imaginary work
2019-06-17 14:08:34.074 11426-11426/com.example.mysampleapp D/MyWorker: finished the imaginary work
2019-06-17 14:08:34.081 11426-11481/com.example.mysampleapp D/WM-WorkerWrapper: com.example.mysampleapp.MyWorker returned a Success {mOutputData=androidx.work.Data@0} result.
2019-06-17 14:08:34.083 11426-11481/com.example.mysampleapp I/WM-WorkerWrapper: Worker result SUCCESS for Work [ id=09719581-3564-4800-a89b-577f293a3605, tags={ periodic, widget-7, com.example.mysampleapp.MyWorker } ]
2019-06-17 14:08:34.088 11426-11426/com.example.mysampleapp D/WM-Processor: Processor 09719581-3564-4800-a89b-577f293a3605 executed; reschedule = false
2019-06-17 14:08:34.088 11426-11426/com.example.mysampleapp D/WM-SystemJobService: 09719581-3564-4800-a89b-577f293a3605 executed on JobScheduler
2019-06-17 14:08:34.102 11426-11481/com.example.mysampleapp D/WM-SystemJobScheduler: Scheduling work ID 09719581-3564-4800-a89b-577f293a3605 Job ID 2

2019-06-17 14:23:34.105 11426-11426/com.example.mysampleapp D/WM-SystemJobService: onStartJob for 09719581-3564-4800-a89b-577f293a3605
2019-06-17 14:23:34.106 11426-11480/com.example.mysampleapp D/WM-Processor: Processor: processing 09719581-3564-4800-a89b-577f293a3605
2019-06-17 14:23:34.119 11426-11426/com.example.mysampleapp D/WM-WorkerWrapper: Starting work for com.example.mysampleapp.MyWorker
2019-06-17 14:23:34.119 11426-11426/com.example.mysampleapp D/MyWorker: starting work 09719581-3564-4800-a89b-577f293a3605
2019-06-17 14:23:34.120 11426-11426/com.example.mysampleapp D/MyWorker: startWork (appWidgetId = 7) (method = periodic) (trigger = routine) (orientation = 1)
2019-06-17 14:23:34.120 11426-11426/com.example.mysampleapp D/MyWorker: starting some imaginary work
2019-06-17 14:23:39.126 11426-11426/com.example.mysampleapp D/MyWorker: finished the imaginary work
2019-06-17 14:23:39.135 11426-11481/com.example.mysampleapp D/WM-WorkerWrapper: com.example.mysampleapp.MyWorker returned a Success {mOutputData=androidx.work.Data@0} result.
2019-06-17 14:23:39.139 11426-11481/com.example.mysampleapp I/WM-WorkerWrapper: Worker result SUCCESS for Work [ id=09719581-3564-4800-a89b-577f293a3605, tags={ periodic, widget-7, com.example.mysampleapp.MyWorker } ]
2019-06-17 14:23:39.141 11426-11426/com.example.mysampleapp D/WM-Processor: Processor 09719581-3564-4800-a89b-577f293a3605 executed; reschedule = false
2019-06-17 14:23:39.141 11426-11426/com.example.mysampleapp D/WM-SystemJobService: 09719581-3564-4800-a89b-577f293a3605 executed on JobScheduler
2019-06-17 14:23:39.161 11426-11481/com.example.mysampleapp D/WM-SystemJobScheduler: Scheduling work ID 09719581-3564-4800-a89b-577f293a3605 Job ID 2

2019-06-17 14:39:37.815 11426-11426/com.example.mysampleapp D/WM-SystemJobService: onStartJob for 09719581-3564-4800-a89b-577f293a3605
2019-06-17 14:39:37.817 11426-11481/com.example.mysampleapp D/WM-Processor: Processor: processing 09719581-3564-4800-a89b-577f293a3605
2019-06-17 14:39:37.828 11426-11426/com.example.mysampleapp D/WM-WorkerWrapper: Starting work for com.example.mysampleapp.MyWorker
2019-06-17 14:39:37.828 11426-11426/com.example.mysampleapp D/MyWorker: starting work 09719581-3564-4800-a89b-577f293a3605
2019-06-17 14:39:37.828 11426-11426/com.example.mysampleapp D/MyWorker: startWork (appWidgetId = 7) (method = periodic) (trigger = routine) (orientation = 1)
2019-06-17 14:39:37.828 11426-11426/com.example.mysampleapp D/MyWorker: starting some imaginary work
2019-06-17 14:39:42.833 11426-11426/com.example.mysampleapp D/MyWorker: finished the imaginary work
2019-06-17 14:39:42.840 11426-11480/com.example.mysampleapp D/WM-WorkerWrapper: com.example.mysampleapp.MyWorker returned a Success {mOutputData=androidx.work.Data@0} result.
2019-06-17 14:39:42.843 11426-11480/com.example.mysampleapp I/WM-WorkerWrapper: Worker result SUCCESS for Work [ id=09719581-3564-4800-a89b-577f293a3605, tags={ periodic, widget-7, com.example.mysampleapp.MyWorker } ]
2019-06-17 14:39:42.846 11426-11426/com.example.mysampleapp D/WM-Processor: Processor 09719581-3564-4800-a89b-577f293a3605 executed; reschedule = false
2019-06-17 14:39:42.846 11426-11426/com.example.mysampleapp D/WM-SystemJobService: 09719581-3564-4800-a89b-577f293a3605 executed on JobScheduler
2019-06-17 14:39:42.861 11426-11480/com.example.mysampleapp D/WM-SystemJobScheduler: Scheduling work ID 09719581-3564-4800-a89b-577f293a3605 Job ID 2

What about comment #52, and the lack of a DEADLINE (and "latest run time" being NONE) in 2.1.0-beta-01 ?

What about it ? We changed how treat scheduling periodic work internally to allow for initial delays. This reflects that.
There is nothing unexpected here.

I still don't see any problems with the frequency at which the PeriodicWorkRequest runs / other issues in your sample app.

OK well just keep the widget running for a good while and see if it ever ends up showing more than 15 mins in the past.

One user who is running the sample widget and my actual widget alongside each other found once that the sample widget appeared to have stopped updating at the same time as the actual widget.  But then some time later the sample widget picked up again but the actual widget didn't.  Wonder whether there was some event on the device which was causing an issue, from which the sample widget recovered but the actual widget didn't... I tried to make the two as close as possible but maybe there's a subtle difference.

Anyway, see if the sample widget on your device ever seems to stop.

Did you manage to reproduce this issue when you tested this yourself ?
i.e. on a device / an emulator - did your sample widget ever misbehave ?

I have seen it "miss a beat" once or twice but it does seem to recover (as per the user observation).  I'm still trying to find a nailed-down way to reproduce it.  For the time being just leave it updating on your device and see for yourself if it ever appears to stop updating.

Another thing to try and break it is to tap on the widget and then hit "ADD/UPDATE WIDGET"... then sets up a new periodic work request to replace the existing one, using ExistingWorkPolicy.REPLACE.

P.S. it would be nice to be able to set an interval of less than 15 mins, for testing purposes... frustrating having to wait 15 mins every time until the next chance to see if the thing is working or not :-/

Right now the sample widget is displaying 23:03 while the system clock is displaying 23:31.

Now both showing 23:54.

From https://issuetracker.google.com/issues/135272196#comment10 (reporting oddity in scheduling of period work requests with initial delay):

"We introduce some drift due to the way we reschedule ENQUEUED work on init (on process death)"

From #55 of this thread:

"What about it ? We changed how treat scheduling periodic work internally to allow for initial delays. This reflects that. There is nothing unexpected here."

You seem to be very dismissive of my observations in #50 and #51 about the lack of a DEADLINE (and the "latest run time" being set to "none") in the jobs scheduled under 2.1.0 (which is different behaviour to 2.0.1).

But to my mind, and forgive me because I don't know what WorkManager is doing behind the scenes and you're probably right to dismiss this as "nothing unexpected", but to me the lack of a DEADLINE might well explain what I'm seeing.

Let's take a device that has 100 jobs to perform in a short window, or at a time when then device is under stress.  Let's say 99 of those jobs have a DEADLINE set, and your job doesn't.  It seems to me to be quite reasonable behaviour for the device's job management system to prioritise those 99 other jobs ahead of your job, and get them done first.  It's the same in normal personal and work life... one prioritises jobs that have a known deadline, and particularly those with an imminent deadline.  Those jobs that won't kick up a fuss if you don't do them even though they're overdue, like painting the skirting boards, tend to get neglected.

For me, it's just like what I'm seeing with my sample widget.  Most often it does indeed seem to update every 15 mins.  But sometimes, it just seems to update whenever the heck it feels like it...

Surely a periodic work scheduled via WorkManager should perform the work within the set interval.. I don't care *when* it happens within the interval, but definitely it should be *within* the interval?  (obviously subject to Doze etc)

To me, seeing the following in the adb jobscheduler output is somewhat troubling:

    Unsatisfied constraints: TIMING_DELAY
    Earliest run time: 07:27
    Latest run time: none

Yes in theory once the unsatisfied "TIMING_DELAY" constraint is met, the job is free to run, but isn't it still up to the device to decide WHEN it runs, and in the absence of any DEADLINE this could be any time?

I'm reading between too many lines and making too many assumptions about what's going on under the hood.  However, it seems like more than coincidence that these scheduling issues I'm seeing started when going from WM 2.0.1 to WM 2.1.0, just when the above changes were made (to "introduce some drift" and to not set a DEADLINE on a scheduled job so that there is no "latest run time").

Attached example of sample widget not updating within the requested 15 minute interval... despite device being awake.  It got to at least 23:31 without having updated, but then at 23:54 (when I next looked, having put the device down for a few minutes) the widget had updated.  So the widget schedule wasn't "dead"... it just seemed like a case of "I'll do this work whenever the heck I feel like it", as described above.

There is no specific guarantee in any of the APIs you are looking at (WorkManager, JobScheduler) that a job will run at an exact time or within an exact time window.  This is not just because of doze or constraints, but also due to system load and OS internals.  For example, JobScheduler has a certain number of execution slots, some of which are guaranteed to the foreground app.  Execution windows can change based on how many OTHER jobs need to run at a given time, or the power state of the device (notably, no background jobs run in the equivalent of battery saver mode), the app's bucket, and other factors like load-balancing between various apps.

Nothing about WorkManager can guarantee "this work WILL run within [x to y] time" - we know that the work WILL run, and most likely run in the necessary time, but there is a reason we usually use the word "deferrable" first when we describe WorkManager.

So please can you explain the meaning of the DEADLINE constraint that appears in the adb jobscheduler output (at least until WM 2.1.0)?  Surely it must have some sort of meaning?  And dropping the DEADLINE constraint must have some effect?  Otherwise what is the point of it?

And what about "Latest run time: none" vs "Latest run time: 14:53" .. again, surely there must be some difference between these two?  

And yes of course it's all subject to Doze, system load etc, and there is no guarantee it will run from in a specified window, but I've had instances where not only did it not run in the specified window, but it also didn't run for at least another interval's duration after that, and that's when the device was awake and not particularly under any stress.

I ran your sample for 2 days, and was unable to reproduce the problem you mentioned.
I think the reason why you are seeing these drifts are related to https://issuetracker.google.com/issues/135272196

I am going to mark this bug as a duplicate of that. 2.1.0-beta02 should be out this week so give that a go and see if that fixes your issues.
Comment on this bug again, if you do see issues after switching to beta02.

OK thanks, will give it a go.

Still interested in your thoughts on #65, out of curiosity if nothing else.

Still no beta02 to try, so here are some further observations using beta01.  The sample widget has been performing well, but right now my actual widget has stopped auto updating.  The following are three adb jobscheduler outputs for this package taken at three different times, showing that there is definitely a job scheduled and active.  What happens is that the "Earliest run time" counts down to zero, at which point I'd expect the job to run (and the widget to update)... but it doesn't.  Instead, it counts down to zero (or a few seconds below zero), and then the "Earliest run time" resets itself back to 55 mins (makes sense as the interval is 1 hour with a flex of 5 mins)... then it counts down again, and resets to 55 mins, without actually triggering any work:

  JOB #u0a534/60: 11bc82f com.example.myapp/androidx.work.impl.background.systemjob.SystemJobService
    u0a534 tag=*job*/com.example.myapp/androidx.work.impl.background.systemjob.SystemJobService
    Source: uid=u0a534 user=0 pkg=com.example.myapp
    JobInfo:
      Service: com.example.myapp/androidx.work.impl.background.systemjob.SystemJobService
      Requires: charging=false deviceIdle=false
      Network type: 1
      Minimum latency: +55m0s0ms
      Backoff: policy=1 initial=+30s0ms
      Has early constraint
    Required constraints: TIMING_DELAY CONNECTIVITY
    Satisfied constraints: CONNECTIVITY NOT_ROAMING APP_NOT_IDLE DEVICE_NOT_DOZING
    Unsatisfied constraints: TIMING_DELAY
    Earliest run time: 00:53
    Latest run time: none
    Ready: false (job=false pending=false active=false user=true)

  JOB #u0a534/60: 11bc82f com.example.myapp/androidx.work.impl.background.systemjob.SystemJobService
    u0a534 tag=*job*/com.example.myapp/androidx.work.impl.background.systemjob.SystemJobService
    Source: uid=u0a534 user=0 pkg=com.example.myapp
    JobInfo:
      Service: com.example.myapp/androidx.work.impl.background.systemjob.SystemJobService
      Requires: charging=false deviceIdle=false
      Network type: 1
      Minimum latency: +55m0s0ms
      Backoff: policy=1 initial=+30s0ms
      Has early constraint
    Required constraints: TIMING_DELAY CONNECTIVITY
    Satisfied constraints: CONNECTIVITY NOT_ROAMING APP_NOT_IDLE DEVICE_NOT_DOZING
    Unsatisfied constraints: TIMING_DELAY
    Earliest run time: -00:05
    Latest run time: none
    Ready: false (job=false pending=false active=false user=true)

  JOB #u0a534/60: 8a9945f com.example.myapp/androidx.work.impl.background.systemjob.SystemJobService
    u0a534 tag=*job*/com.example.myapp/androidx.work.impl.background.systemjob.SystemJobService
    Source: uid=u0a534 user=0 pkg=com.example.myapp
    JobInfo:
      Service: com.example.myapp/androidx.work.impl.background.systemjob.SystemJobService
      Requires: charging=false deviceIdle=false
      Network type: 1
      Minimum latency: +55m0s0ms
      Backoff: policy=1 initial=+30s0ms
      Has early constraint
    Required constraints: TIMING_DELAY CONNECTIVITY
    Satisfied constraints: CONNECTIVITY NOT_ROAMING APP_NOT_IDLE DEVICE_NOT_DOZING
    Unsatisfied constraints: TIMING_DELAY
    Earliest run time: 54:41
    Latest run time: none
    Ready: false (job=false pending=false active=false user=true)

OK I think I've finally found a reliable way to reproduce this.  And to me it seems to be a context-related issue, despite what is stated in comment #30.  

Specifically, it seems to me that when a periodic work request is set up from an AppWidgetProvider context, you get the sort of behaviour noted just above in comment #68... i.e. there is a job scheduled, and it does kinda repeat (from monitoring adb shell dumpsys jobscheduler), but it doesn't actually trigger any work.

Makes sense to me that it could be context related, considering that the biggest outward change in 2.1.0 was the requirement to pass a context to WorkManager.getInstance(), as I suggested in comment #28 and #29.

Anyhow, I've updated the sample app linked in comment #52, so please uninstall the previous sample, and load and install the new version on your device.  Note, it's based on 2.0.1-beta01 so it's just possible that what I'm seeing is already dealt with in beta02... but try this sample based on beta01 even if just to see the behaviour and check that it has indeed been addressed in beta02.

Add a new sample widget to the home screen, and just hit ADD/UPDATE WIDGET.  If you watch the widget, you should see a couple of different texts flash up, starting with EXAMPLE (what is set in the config activity), then e.g. "on_update: 13:29:16", then e.g. "configure: 13:29:18".

The first bit of the text is the "trigger" variable used in the code... this identifies what triggered the periodic work request that resulted in this widget update... there are multiple triggers and the trigger strings and associated functions are summarised below:

"configure": see MyAppWidgetConfigureActivity.onClick()  --  Activity context
"on_update": see MyAppWidget.onUpdate()  --  AppWidgetProvider context
"on_enabled": see MyAppWidget.onEnabled()  --  AppWidgetProvider context

To break the widget updating, *after* adding a new widget:

(a) turn the device OFF, wait a minute, then turn the device back ON
(b) during the boot-up process **and for the next 15 mins or so** keep the device active with the screen ON
(c) after boot-up, for good measure add another sample widget... and again, keep the screen on and the device active **for at least 15 mins**
(d) optionally, check the output of "adb shell dumpsys jobscheduler" to confirm that there are now two jobs safely scheduled for the sample app, so all appears to be in order
(e) after 15 mins with device awake, has either widget updated?
(f) still not?
(g) optionally, check the output of "adb shell dumpsys jobscheduler" again to confirm that there are still two jobs scheduled (maybe in the next cycle by now)

BTW in case the launcher matters since this involves an app widget, I'm using Nova launcher (https://play.google.com/store/apps/details?id=com.teslacoilsw.launcher).

I'm not sure it's necessary, to reproduce the problem, to keep the screen on and the device active in the above steps, but it may be.

Because it appears to me that if you turn the screen off and put the device down for a while, then pick it up again, a previously-stale sample widget will suddenly update itself.  Maybe it's waking up from idle that does this.  Or maybe it is when the lock screen has activated, and the device is then unlocked.  Maybe, when waking up or being unlocked, the AppWidgetProvider context is available again and this is why the work performs?  No idea really, I just know that it happens.

(BTW yes there are multiple triggers, via onEnabled and onUpdated and config activity, that lead to a new periodic work being scheduled, but this shouldn't matter since we're using REPLACE so there will only be a single periodic schedule in place regardless.  And in practice we can clean things up and ensure that we trigger from only one place at any one time.  The key point is that a periodic work will, at some point, be scheduled from the AppWidgetProvider context.)

I had thought that when the periodic work request is set up based on an Activity context (like it was in the previous sample app), it works fine.  But now, with this new sample app, setting up a new widget from the config Activity results in triggers from both "on_updated" and "config", apparently with "config" being the last, and yet it also doesn't work (at least initially).

We released 2.1.0-beta02 today.

When i tried to reproduce the problem with 2.1.0-beta01 sometimes I would see a message "Problem updating widget". This problem would eventually fix itself - when the Worker eventually ran. The underlying problem is the same as the one I fixed in issue 135272196.

* This bug has got nothing to do with the Context being used. I reiterate, we always use getApplicationContext().
* The issue here is what we did on Application#onCreate.  The way we re-schedule jobs before on Application#onCreate() caused drifts.

I cannot reproduce the problem with 2.1.0-beta02.

> we released 2.1.0-beta02 today
> I cannot reproduce the problem with 2.1.0-beta02

I can confirm that the problem is gone having upgraded to 2.1.0-beta02, both in the sample app and the actual app.  Thanks.

Everything ticking along more smoothly than ever.