Fixed
Status Update
No update yet.
Comments
ru...@gmail.com
We introduced a regression in beta02. Can you try using beta01 instead ?
su...@google.com
Also, beta03 is coming with a fix very soon.
ru...@gmail.com
Thank you for your prompt response. I've checked the functioning of OneTimeWorkRequest in beta01 and it works as expected. Looking forward to beta03 for the fix.
ra...@google.com
beta03 is out.
ra...@google.com
In beta03, the bug seems fixed when JobScheduler backend is used.
But the bug seems to remain when AlarmManager backend is used.
The following step-by-step fails for me on emulator "Nexus 7 (2012) API 22", but passes on emulator "Pixel 2 XL API 27".
STEP BY STEP:
1. Create a "Hello world" Android app using Android Studio wizard and add implementation("android.arch.work:work-runtime:1.0.0-beta03") to dependencies
2. Add the following to MainActivity.onCreate():
final String name = Long.toString(System.currentTimeMillis()); // To ensure fresh name each run
final OneTimeWorkRequest workRequest = new OneTimeWorkRequest.Builder(LogPrinter.class)
.setBackoffCriteria(BackoffPolicy.LINEAR, WorkRequest.MIN_BACKOFF_MILLIS, TimeUnit.MILLISECONDS)
.addTag(name)
.build();
Log.e("Repro", "Calling enqueueUniqueWork(" + name + ", ...)");
WorkManager.getInstance().enqueueUniqueWork(name, ExistingWorkPolicy.REPLACE, workRequest);
where LogPrinter.class doWork() is:
@NonNull
@Override
public Result doWork() {
Log.e("Repro", "doWork() called. Now swipe away app in App Switcher. Tags: " + getTags());
SystemClock.sleep(10000);
Log.e("Repro", "Too late, try again. Tags: " + getTags());
return Result.success();
}
3. Run the app and check adb logcat -s Repro
4. When you see "Now swipe away app in App Switcher", do that.
EXPECTED:
You should see "doWork() called ..." again after max 10 seconds (due to specified backoff time), since the WorkManager framework should ensure that the Worker that never was finished gets a chance to run again.
ACTUAL:
On API 22, you never see "doWork() called ..." again (Test fails).
On API 27, you do see "doWork() called ..." again (Test pass).
Let me know if you need more input.
Best regards,
Martin Nordholts
But the bug seems to remain when AlarmManager backend is used.
The following step-by-step fails for me on emulator "Nexus 7 (2012) API 22", but passes on emulator "Pixel 2 XL API 27".
STEP BY STEP:
1. Create a "Hello world" Android app using Android Studio wizard and add implementation("android.arch.work:work-runtime:1.0.0-beta03") to dependencies
2. Add the following to MainActivity.onCreate():
final String name = Long.toString(System.currentTimeMillis()); // To ensure fresh name each run
final OneTimeWorkRequest workRequest = new OneTimeWorkRequest.Builder(LogPrinter.class)
.setBackoffCriteria(BackoffPolicy.LINEAR, WorkRequest.MIN_BACKOFF_MILLIS, TimeUnit.MILLISECONDS)
.addTag(name)
.build();
Log.e("Repro", "Calling enqueueUniqueWork(" + name + ", ...)");
WorkManager.getInstance().enqueueUniqueWork(name, ExistingWorkPolicy.REPLACE, workRequest);
where LogPrinter.class doWork() is:
@NonNull
@Override
public Result doWork() {
Log.e("Repro", "doWork() called. Now swipe away app in App Switcher. Tags: " + getTags());
SystemClock.sleep(10000);
Log.e("Repro", "Too late, try again. Tags: " + getTags());
return Result.success();
}
3. Run the app and check adb logcat -s Repro
4. When you see "Now swipe away app in App Switcher", do that.
EXPECTED:
You should see "doWork() called ..." again after max 10 seconds (due to specified backoff time), since the WorkManager framework should ensure that the Worker that never was finished gets a chance to run again.
ACTUAL:
On API 22, you never see "doWork() called ..." again (Test fails).
On API 27, you do see "doWork() called ..." again (Test pass).
Let me know if you need more input.
Best regards,
Martin Nordholts
to...@gmail.com
When a swipe to dismiss happens you should see a message in logcat which looks like:
W/ActivityManager( 1532): Scheduling restart of crashed service androidx.work.integration.testapp/androidx.work.impl.background.systemalarm.SystemAlarmService in 47470ms
Service crashes are different from Worker retries or backoffs. So you won't see it in 10 seconds. It might take longer. Look at the logs for more info.
W/ActivityManager( 1532): Scheduling restart of crashed service androidx.work.integration.testapp/androidx.work.impl.background.systemalarm.SystemAlarmService in 47470ms
Service crashes are different from Worker retries or backoffs. So you won't see it in 10 seconds. It might take longer. Look at the logs for more info.
ru...@gmail.com
Thanks for the tip, this helped me debug this further.
Turns out that if you see "Scheduling restart of crashed service", then yes, doWork() will be called after the specified time.
But the problem is that SystemAlarmService is not always scheduled to restart, because SystemAlarmService is not always running when the app is closed.
In fact, it seems to be quite rare for SystemAlarmService to run.
If you increase the sleep from 10000 to 20000 in my step-by-step instructions, and let 10 seconds pass between ""doWork() called .., " being logged and you closing the app, I think you'll be able to reproduce the problem, namely that doWork() never becomes called again (since SystemAlarmService is not scheduled for a restart, since it wasn't running when the app was closed).
Are you able to reproduce the problem with these extra instructions?
Turns out that if you see "Scheduling restart of crashed service", then yes, doWork() will be called after the specified time.
But the problem is that SystemAlarmService is not always scheduled to restart, because SystemAlarmService is not always running when the app is closed.
In fact, it seems to be quite rare for SystemAlarmService to run.
If you increase the sleep from 10000 to 20000 in my step-by-step instructions, and let 10 seconds pass between ""doWork() called .., " being logged and you closing the app, I think you'll be able to reproduce the problem, namely that doWork() never becomes called again (since SystemAlarmService is not scheduled for a restart, since it wasn't running when the app was closed).
Are you able to reproduce the problem with these extra instructions?
ru...@gmail.com
Can you please turn on verbose logging and send us all the logs ? I am going to try and reproduce this on my end.
You will need to initialize WorkManager with a custom configuration for that.
* Remove the default WorkManager initializer using:
<provider
android:name="androidx.work.impl.WorkManagerInitializer"
android:authorities="${applicationId}.workmanager-init"
tools:node="remove"/>
* Initialize WorkManager in your own content provider or Application#onCreate() with a custom configuration
WorkManager.initialize(
applicationContext,
new Configuration.Builder().setMinimumLoggingLevel(Log.VERBOSE).build());
You will see a lot more WorkManager logs now.
You will need to initialize WorkManager with a custom configuration for that.
* Remove the default WorkManager initializer using:
<provider
android:name="androidx.work.impl.WorkManagerInitializer"
android:authorities="${applicationId}.workmanager-init"
tools:node="remove"/>
* Initialize WorkManager in your own content provider or Application#onCreate() with a custom configuration
WorkManager.initialize(
applicationContext,
new Configuration.Builder().setMinimumLoggingLevel(Log.VERBOSE).build());
You will see a lot more WorkManager logs now.
ed...@gmail.com
I think I know what is going on. There are 2 competing schedulers that can pick up work. When the in-process scheduler picks up work and the process gets killed there is nothing else that can wake up to reschedule that Worker until the application is launched again.
da...@gmail.com
Thanks for looking into this more.
I've attached the logs I captured when reproducing the problem as follows:
1. Create a brand new Nexus 7 (2012) API 22 emulator to make sure the system does not have any old state that affects behavior, and start it, and let it boot up and rest a bit. Double-check that in Settings -> Storage, it doesn't say "running out of storage". If it does say that, reboot the emulator. That should get rid of the message. If you try to install the app when the device is in its strange "running out of storage state", you will get "stale dex" errors when installing the app. I'm using the x86 emulator on a 2018 MacBook Pro.
2. Start log capturing with this command: adb -s emulator-5554 logcat -T 0 -v threadtime -s '*:V' | tee ~/log-workmanager-repro-verbose-3.txt
3. Start the app, and after ~10 seconds, close it (I've increased sleep to 20 s)
4. Wait for a long enough time to convince yourself of that the Worker will never be scheduled again (I waited for > 10 minutes)
5. Stop logging.
For your convenience, I have inlined the log filtered with: grep -e Repro -e WM- -e Killing.*workmanager ~/log-workmanager-repro-verbose-3.txt
at the end of the mail. For full logs, see attached file.
The last line with 'Killing' is from me swiping away the app in the App Switcher.
Note that the logs have this line:
WM-SystemAlarmService: All commands completed in dispatcher
So it looks like even though SystemAlarmService was used to dispatch the Worker, the bug happened. ("All commands completed in dispatcher" means SystemAlarmService is about to do Service.stopSelf() as you probably know.)
Let me know if I can help you in any other way.
BR Martin
01-30 09:42:31.954 3613 3613 D WM-Schedulers: Created SystemAlarmScheduler
01-30 09:42:31.960 3613 3613 D WM-PackageManagerHelper: androidx.work.impl.background.systemalarm.SystemAlarmService enabled
01-30 09:42:31.970 3613 3632 D WM-ForceStopRunnable: Application was force-stopped, rescheduling.
01-30 09:42:31.993 3613 3613 E Repro : Calling enqueueUniqueWork(1548837751988, ...)
01-30 09:42:32.040 3613 3632 D WM-PackageManagerHelper: androidx.work.impl.background.systemalarm.RescheduleReceiver enabled
01-30 09:42:32.043 3613 3632 D WM-SystemAlarmScheduler: Scheduling work with workSpecId 576d2452-a559-4c85-b217-c954c6905d7e
01-30 09:42:32.046 3613 3632 D WM-Processor: Processor: processing 576d2452-a559-4c85-b217-c954c6905d7e
01-30 09:42:32.054 3613 3613 D WM-SystemAlarmDispatche: Adding command Intent { act=ACTION_SCHEDULE_WORK cmp=com.github.enselic.workmanagerfailedscheduling/androidx.work.impl.background.systemalarm.SystemAlarmService (has extras) } (1)
01-30 09:42:32.055 3613 3632 D WM-SystemAlarmDispatche: Processing command Intent { act=ACTION_SCHEDULE_WORK cmp=com.github.enselic.workmanagerfailedscheduling/androidx.work.impl.background.systemalarm.SystemAlarmService (has extras) }, 1
01-30 09:42:32.055 3613 3632 D WM-SystemAlarmDispatche: Acquiring operation wake lock (ACTION_SCHEDULE_WORK) WakeLock{4e8f358 held=false, refCount=0}
01-30 09:42:32.055 3613 3632 D WM-CommandHandler: Handling schedule work for 576d2452-a559-4c85-b217-c954c6905d7e
01-30 09:42:32.056 3613 3637 E Repro : doWork() called. Now swipe away app in App Switcher. Tags: [com.github.enselic.workmanagerfailedscheduling.LogPrinter, 1548837751988]
01-30 09:42:32.056 3613 3632 W WM-CommandHandler: Skipping scheduling 576d2452-a559-4c85-b217-c954c6905d7e because it is no longer enqueued
01-30 09:42:32.056 3613 3632 D WM-SystemAlarmDispatche: Releasing operation wake lock (ACTION_SCHEDULE_WORK) WakeLock{4e8f358 held=true, refCount=1}
01-30 09:42:32.096 3613 3613 D WM-SystemAlarmDispatche: Checking if commands are complete.
01-30 09:42:32.096 3613 3613 D WM-SystemAlarmDispatche: Removing command Intent { act=ACTION_SCHEDULE_WORK cmp=com.github.enselic.workmanagerfailedscheduling/androidx.work.impl.background.systemalarm.SystemAlarmService (has extras) }
01-30 09:42:32.096 3613 3613 D WM-SystemAlarmDispatche: No more commands & intents.
01-30 09:42:32.096 3613 3613 D WM-SystemAlarmService: All commands completed in dispatcher
01-30 09:42:43.607 1647 2397 I ActivityManager: Killing 3613:com.github.enselic.workmanagerfailedscheduling/u0a58 (adj 9): remove task
I've attached the logs I captured when reproducing the problem as follows:
1. Create a brand new Nexus 7 (2012) API 22 emulator to make sure the system does not have any old state that affects behavior, and start it, and let it boot up and rest a bit. Double-check that in Settings -> Storage, it doesn't say "running out of storage". If it does say that, reboot the emulator. That should get rid of the message. If you try to install the app when the device is in its strange "running out of storage state", you will get "stale dex" errors when installing the app. I'm using the x86 emulator on a 2018 MacBook Pro.
2. Start log capturing with this command: adb -s emulator-5554 logcat -T 0 -v threadtime -s '*:V' | tee ~/log-workmanager-repro-verbose-3.txt
3. Start the app, and after ~10 seconds, close it (I've increased sleep to 20 s)
4. Wait for a long enough time to convince yourself of that the Worker will never be scheduled again (I waited for > 10 minutes)
5. Stop logging.
For your convenience, I have inlined the log filtered with: grep -e Repro -e WM- -e Killing.*workmanager ~/log-workmanager-repro-verbose-3.txt
at the end of the mail. For full logs, see attached file.
The last line with 'Killing' is from me swiping away the app in the App Switcher.
Note that the logs have this line:
WM-SystemAlarmService: All commands completed in dispatcher
So it looks like even though SystemAlarmService was used to dispatch the Worker, the bug happened. ("All commands completed in dispatcher" means SystemAlarmService is about to do Service.stopSelf() as you probably know.)
Let me know if I can help you in any other way.
BR Martin
01-30 09:42:31.954 3613 3613 D WM-Schedulers: Created SystemAlarmScheduler
01-30 09:42:31.960 3613 3613 D WM-PackageManagerHelper: androidx.work.impl.background.systemalarm.SystemAlarmService enabled
01-30 09:42:31.970 3613 3632 D WM-ForceStopRunnable: Application was force-stopped, rescheduling.
01-30 09:42:31.993 3613 3613 E Repro : Calling enqueueUniqueWork(1548837751988, ...)
01-30 09:42:32.040 3613 3632 D WM-PackageManagerHelper: androidx.work.impl.background.systemalarm.RescheduleReceiver enabled
01-30 09:42:32.043 3613 3632 D WM-SystemAlarmScheduler: Scheduling work with workSpecId 576d2452-a559-4c85-b217-c954c6905d7e
01-30 09:42:32.046 3613 3632 D WM-Processor: Processor: processing 576d2452-a559-4c85-b217-c954c6905d7e
01-30 09:42:32.054 3613 3613 D WM-SystemAlarmDispatche: Adding command Intent { act=ACTION_SCHEDULE_WORK cmp=com.github.enselic.workmanagerfailedscheduling/androidx.work.impl.background.systemalarm.SystemAlarmService (has extras) } (1)
01-30 09:42:32.055 3613 3632 D WM-SystemAlarmDispatche: Processing command Intent { act=ACTION_SCHEDULE_WORK cmp=com.github.enselic.workmanagerfailedscheduling/androidx.work.impl.background.systemalarm.SystemAlarmService (has extras) }, 1
01-30 09:42:32.055 3613 3632 D WM-SystemAlarmDispatche: Acquiring operation wake lock (ACTION_SCHEDULE_WORK) WakeLock{4e8f358 held=false, refCount=0}
01-30 09:42:32.055 3613 3632 D WM-CommandHandler: Handling schedule work for 576d2452-a559-4c85-b217-c954c6905d7e
01-30 09:42:32.056 3613 3637 E Repro : doWork() called. Now swipe away app in App Switcher. Tags: [com.github.enselic.workmanagerfailedscheduling.LogPrinter, 1548837751988]
01-30 09:42:32.056 3613 3632 W WM-CommandHandler: Skipping scheduling 576d2452-a559-4c85-b217-c954c6905d7e because it is no longer enqueued
01-30 09:42:32.056 3613 3632 D WM-SystemAlarmDispatche: Releasing operation wake lock (ACTION_SCHEDULE_WORK) WakeLock{4e8f358 held=true, refCount=1}
01-30 09:42:32.096 3613 3613 D WM-SystemAlarmDispatche: Checking if commands are complete.
01-30 09:42:32.096 3613 3613 D WM-SystemAlarmDispatche: Removing command Intent { act=ACTION_SCHEDULE_WORK cmp=com.github.enselic.workmanagerfailedscheduling/androidx.work.impl.background.systemalarm.SystemAlarmService (has extras) }
01-30 09:42:32.096 3613 3613 D WM-SystemAlarmDispatche: No more commands & intents.
01-30 09:42:32.096 3613 3613 D WM-SystemAlarmService: All commands completed in dispatcher
01-30 09:42:43.607 1647 2397 I ActivityManager: Killing 3613:com.github.enselic.workmanagerfailedscheduling/u0a58 (adj 9): remove task
Description
Version used: implementation 'android.arch.work:work-runtime:1.0.0-alpha12'
Devices/Android versions reproduced on: Moto e3 Power / Andorid 6.0 Marshmallow
Sometimes Periodic workManager gets called two times.
This is my built.gradle file:-
compileSdkVersion 28
minSdkVersion 22
targetSdkVersion 28
versionCode 1
versionName "1.0"
multiDexEnabled true
testInstrumentationRunner "androidx.test.runner.AndroidJUnitRunner"
Here is this code:-
//---------------------------------------------------------Class Login---------------------------------------------------------------------------------------//
SaveData("Frist");
PeriodicWorkRequest periodicWorkRequest = new PeriodicWorkRequest.Builder(DailyLogoutTask.class,
1, TimeUnit.DAYS)
.build();
WorkManager.getInstance().enqueueUniquePeriodicWork("DailyTaskRestaurantLite"
, ExistingPeriodicWorkPolicy.KEEP
, periodicWorkRequest);
private void SaveData(String str) {
SharedPreferences.Editor preferencesEditor = mPreferences.edit();
preferencesEditor.putString("Status1", str);
preferencesEditor.apply();
}
//------------------------------------------------------Class DailyLogoutTask-----------------------------------------------------------------------//
import android.content.Context;
import android.content.SharedPreferences;
import androidx.annotation.NonNull;
import android.util.Log;
import com.domo.ClsGlobal;
import com.demo.classes.ClsUserInfo;
import androidx.work.Result;
import androidx.work.WorkManager;
import androidx.work.Worker;
import androidx.work.WorkerParameters;
import static android.content.Context.MODE_PRIVATE;
public class DailyLogoutTask extends Worker {
private SharedPreferences mPreferences;
private static final String mPreferncesName = "MyPerfernces";
Context context;
public DailyLogoutTask(@NonNull Context context, @NonNull WorkerParameters workerParams) {
super(context, workerParams);
this.context = context;
mPreferences = context.getSharedPreferences(mPreferncesName, MODE_PRIVATE);
Log.e("DailyLogoutTask", "DailyLogoutTask call");
}
@NonNull
@Override
public Result doWork() {
String getstatus = mPreferences.getString("Status1", "No Task Perform");
Log.d("---getstatus---", "----getstatus---" + getstatus);
Log.e("doWork", "doWork call");
if (!getstatus.equalsIgnoreCase("Frist")) {
ClsUserInfo userInfo = new ClsUserInfo();
ClsUserInfo userLoginStatus = ClsGlobal.getUserInfo(context);
if (!userLoginStatus.getLoginStatus().equalsIgnoreCase("DEACTIVE")){
Log.e("chack", "Logout");
userInfo.setLoginStatus("DEACTIVE");
ClsGlobal.setUserInfo(userInfo, context);
// ClsGlobal.sendNotification("IF", "IF background Logout".concat(ClsGlobal.getEntryDate()),context);
WorkManager.getInstance().cancelUniqueWork("DailyTaskRestaurantLite");
Log.d("getFirstDateOfMonth", "----UserInfo---" + userLoginStatus.getLoginStatus());
}
} else {
Log.e("chack", "Not Frist");
// ClsGlobal.sendNotification("ELSE", "ELSE background Logout".concat(ClsGlobal.getEntryDate()),context);
SaveData("Second");
}
return Result.success();
}
private void SaveData(String str) {
Log.e("SaveData", str);
SharedPreferences.Editor preferencesEditor = mPreferences.edit();
preferencesEditor.putString("Status1", str);
preferencesEditor.apply();
}
If this is a bug in the library, we would appreciate if you could attach:
- Sample project to trigger the issue.
- A screenrecord or screenshots showing the issue (if UI related).