In the follow code excerpts, I am utilizing a BroadcastReceiver to start up a Service on device boot and/or package reload. This NotificationService is calling my Worker via PeriodicWorkRequest every fifteen minutes. Everything initially works as it is supposed to, until the NotificationWorker is executed. It seems that, at the point where the Worker is invoked, it runs twenty times instead of just once. I believe that is twenty times exactly, as well. After all of it is said and done, it waits for ~15 minutes, as it should, and then exhibits the same behavior when it again invokes the Worker. Ideally this Worker should only be run once every 15m, especially being as some of the computation that it will be doing is rather expensive.
I have spent days now, googling for more information (I've partially been hampered in this due to using Work v1.0.1, instead of the more recent, androidx v2.4.0, but I'm not ready to upgrade everything that would be broken in my project with that change) and doing my best to debug this issue. Unfortunately, the debugging has been rather slow and unproductive, due to the fact that I can rarely get my Log.?() messages to even show up, let alone to give me any hints as to where this behavior is coming from. This behavior (Log messages not showing up) has been a problem in BootServiceStart, NotificationWorker, and NotificationService, and I've got no idea why.
Here is the applicable code for the issue; please note that if you follow the dpaste links you will find the general areas of the problematic code highlighted in order to ease diagnosis a bit (dpasted code will only be available for 6 more days):
BootServiceStart - also here on dpaste
NotificationService - also here on dpaste
NotificationWorker - also here on dpaste
I would be very grateful to anybody who might be able to offer any insight on why this behavior is happening, tips on how to avoid this behavior, where to find API & other documentation on the older, deprecated JetPack work v1.0.1 library, or what I can do in Android Studio to better diagnose this issue, as attempts for debugging with what I know how to do have proven futile.
Thank you very much for your time and help on this matter!
I have spent days now, googling for more information (I've partially been hampered in this due to using Work v1.0.1, instead of the more recent, androidx v2.4.0, but I'm not ready to upgrade everything that would be broken in my project with that change) and doing my best to debug this issue. Unfortunately, the debugging has been rather slow and unproductive, due to the fact that I can rarely get my Log.?() messages to even show up, let alone to give me any hints as to where this behavior is coming from. This behavior (Log messages not showing up) has been a problem in BootServiceStart, NotificationWorker, and NotificationService, and I've got no idea why.
Here is the applicable code for the issue; please note that if you follow the dpaste links you will find the general areas of the problematic code highlighted in order to ease diagnosis a bit (dpasted code will only be available for 6 more days):
BootServiceStart - also here on dpaste
Code:
package com.example.sprite.half_lifetimer;
import android.content.BroadcastReceiver;
import android.content.Context;
import android.content.Intent;
import android.os.Build;
import android.util.Log;
public class BootServiceStart extends BroadcastReceiver {
public void onReceive(Context context, Intent arg1) {
Intent intent = new Intent(context , NotificationService.class);
if (Build.VERSION.SDK_INT >= Build.VERSION_CODES.O) {
context.startForegroundService(intent);
} else {
context.startService(intent);
}
if (GlobalMisc.Debugging) {
Log.i("Halflife.BootServiceStart", "Attempted to start NotificationService");
}
}
}NotificationService - also here on dpaste
Code:
package com.example.sprite.half_lifetimer;
import android.app.Notification;
import android.app.NotificationChannel;
import android.app.NotificationManager;;
import android.app.Service;
import android.content.Intent;
import android.os.Build;
import android.os.IBinder;
import android.support.annotation.Nullable;
import android.support.v4.app.NotificationCompat;
import android.util.Log;
import androidx.work.PeriodicWorkRequest;
import androidx.work.WorkManager;
import java.time.LocalDateTime;
import java.util.HashMap;
import java.util.concurrent.TimeUnit;
public class NotificationService extends Service {
public static HashMap<Integer, Boolean> firedNotifications = new HashMap<>();
public static LocalDateTime lastNotificationLoopLDT = null;
@Nullable
public IBinder onBind(Intent intent) {
return null;
}
/**
* Method handles creation of a NotificationChannel and database
* initialization (for this particular subset of the code), then passing
* control off to notificationLoop().
*/
public void onCreate() {
startForeground(31337, buildForegroundNotification());
if (GlobalMisc.Debugging) {
Log.i("Halflife.NotificationService.onCreate", "Started NotificationService");
}
// Create the NotificationChannel, but only on API 26+ because
// the NotificationChannel class is new and not in the support library
if (Build.VERSION.SDK_INT >= Build.VERSION_CODES.O) {
NotificationChannel chan = new NotificationChannel(
"taper-n-clearing-talk", "taper-n-clearing",
NotificationManager.IMPORTANCE_NONE);
chan.setDescription("Notifications for Taper dosages and Substance clearance");
// Register the channel with the system; you can't change the importance
// or other notification behaviors after this
NotificationManager notificationManager = getSystemService(NotificationManager.class);
notificationManager.createNotificationChannel(chan);
}
//get the database ready
try {
Permanence.Misc.init(/*NotificationService.this*/ getApplicationContext());
} catch (Exception ex) {
Log.e("Halflife.notificationLoop", "Unable to init database: " +
ex.toString());
}
if (GlobalMisc.Debugging) {
Log.i("Halflife.onCreate", "all valid tapers: " +
Permanence.Tapers.loadAllValidTapers(getApplicationContext()).toString());
}
//notificationLoop();
PeriodicWorkRequest notificationsRequest =
new PeriodicWorkRequest.Builder(NotificationWorker.class, 15, TimeUnit.MINUTES)
.build();
WorkManager.getInstance()
.enqueue(notificationsRequest);
}
private Notification buildForegroundNotification() {
NotificationCompat.Builder b=new NotificationCompat.Builder(this);
b.setOngoing(true)
.setContentTitle("HLT Foreground Service")
.setContentText("Giving Half-life Timer foreground priority")
.setChannelId("taper-n-clearing-talk")
.setSmallIcon(getApplicationContext().getResources().getIdentifier(
"plus_medical_blue","drawable",
getApplicationContext().getPackageName()));
return(b.build());
}
}NotificationWorker - also here on dpaste
Code:
package com.example.sprite.half_lifetimer;
import android.app.PendingIntent;
import android.app.TaskStackBuilder;
import android.content.Context;
import android.content.Intent;
import android.support.annotation.NonNull;
import android.support.v4.app.NotificationCompat;
import android.support.v4.app.NotificationManagerCompat;
import android.util.Log;
import androidx.work.Worker;
import androidx.work.WorkerParameters;
import java.time.Duration;
import java.time.LocalDateTime;
import java.time.LocalTime;
public class NotificationWorker extends Worker {
private boolean notificationDebugging = false;
public NotificationWorker(@NonNull Context context, @NonNull WorkerParameters params) {
super(context, params);
}
@Override
public Result doWork() {
LocalDateTime nextScheduledDosage;
long adminDurationMinutes;
if (!notificationDebugging) {
if (GlobalMisc.NotificationsEnabled) {
//taper notification loop
for (Taper taper : Permanence.Tapers.loadAllValidTapers(getApplicationContext())) {
//this will handle if any tapers have been added since inception
if (!NotificationService.firedNotifications.containsKey(taper.getId())) {
NotificationService.firedNotifications.put(taper.getId(), false);
}
//if this is a constrained taper, but we're outside of the window, just
//go on to the next taper
if (taper.isConstrained() && !taper.inConstraintHours()) {
Log.i("Halflife.notificationLoop",
"skipping " + taper.toString() +
" (outside of hourly constraints)");
continue;
}
if (!NotificationService.firedNotifications.get(taper.getId())) {
try {
nextScheduledDosage = taper.findNextScheduledDosageLDT();
if (!taper.isConstrained()) {
Log.i("Halflife.notificationLoop",
"working with unconstrained taper");
adminDurationMinutes = Duration.ofDays(1).dividedBy(
taper.getAdminsPerDay()).toMinutes();
} else {
Log.i("Halflife.notificationLoop",
"working with constrained taper");
//not sure if this is necessary or not, but might as well
//throw it in since the goddamned code is too complex for me
//to follow right now down below
LocalTime nextDosageTime =
nextScheduledDosage.toLocalTime();
if (nextDosageTime.isBefore(taper.getStartHour()) ||
nextDosageTime.isAfter(taper.getEndHour())) {
Log.i("notificationLoop",
"skipping " + taper.toString() +
" (outside of constraint hours)");
continue;
}
//this part, of course, is necessary
adminDurationMinutes =
Duration.between(taper.getStartHour(),
taper.getEndHour()).dividedBy(
taper.getAdminsPerDay())
.toMinutes();
}
if (GlobalMisc.Debugging) {
Log.i("Halflife.notificationLoop", "Checking taper: " +
taper.getName());
Log.i("Halflife.notificationLoop", "nextScheduledDosage " +
"contains: " + nextScheduledDosage.toString());
}
if (((NotificationService.lastNotificationLoopLDT != null) &&
nextScheduledDosage.isAfter(
NotificationService.lastNotificationLoopLDT) &&
nextScheduledDosage.isBefore(
LocalDateTime.now().plusMinutes(
(adminDurationMinutes / 5)))) ||
(nextScheduledDosage.isAfter(
LocalDateTime.now().minusMinutes(1)) &&
nextScheduledDosage.isBefore(
LocalDateTime.now().plusMinutes(
(adminDurationMinutes / 5))))) {
fireTaperNotification(taper);
//set firedNotifications to reflect that we sent this
//notification
NotificationService.firedNotifications.replace(taper.getId(), true);
} else if (GlobalMisc.Debugging) {
Log.i("Halflife.notificationLoop",
"not displaying notification as per " +
"datetime constraints");
}
} catch (Exception ex) {
Log.e("Halflife.notificationLoop",
"Issue finding next scheduled dosage: " +
ex.toString());
return Result.failure();
}
}
}
} else {
GlobalMisc.debugMsg("NotificationWorker:doWork",
"Would have just gone into substance taper notification loop");
}
if (GlobalMisc.NotificationsEnabled) {
//substance clearing notification loop
//LocalDateTime fiveMinAgo = LocalDateTime.now().minusMinutes(5);
for (Substance sub : Permanence.Subs.loadUnarchivedSubstances(
getApplicationContext())) {
if (GlobalMisc.Debugging) {
Log.i("Halflife.notificationLoop",
"Checking sub clearance: " + sub.getCommon_name());
}
//has this substance cleared within the last 5 minutes?
LocalDateTime clearedAt = sub.getFullEliminationLDT();
if (clearedAt != null) {
if (NotificationService.lastNotificationLoopLDT != null) {
if (clearedAt.isAfter(NotificationService.lastNotificationLoopLDT) &&
clearedAt.isBefore(LocalDateTime.now())) {
//fire the notification
try {
fireSubClearedNotification(sub);
} catch (Exception ex) {
Log.i("Halflife.doWork", ex.toString());
return Result.failure();
}
}
}
}
}
} else {
GlobalMisc.debugMsg("NotificationWorker:doWork",
"Would have just gone into substance clearing notification loop");
}
} else {
Log.i("Halflife.notificationLoop", "In notification debugging " +
"mode");
try {
fireTaperNotification(null);
} catch (Exception ex) {
Log.i("Halflife.doWork", ex.toString());
return Result.failure();
}
}
NotificationService.lastNotificationLoopLDT = LocalDateTime.now();
return Result.success();
}
/**
* Method handles the actual building of the notification regarding
* the applicable taper, and shows it unless our handy HashMap
* 'firedNotifications' shows that there is already a notification
* present for this particular taper.
*
* @param taper the taper to display notification for
*/
private void fireTaperNotification(Taper taper) throws Exception {
Context ctxt = getApplicationContext();
float currentDosageScheduled = taper.findCurrentScheduledDosageAmount();
//here's the legitimate meat 'n potatoes for firing a notification
try {
//if we've already blown the dosage required for the next administration, just skip this
//one
if (currentDosageScheduled <= 0) {
Log.d("fireTaperNotification", "More dosage taken than needs to be " +
"for the current taper step; skipping this taper administration.");
return;
}
Intent intent = new Intent(ctxt, AdminData.class);
intent.putExtra("SUB_NDX",
GlobalMisc.getSubListPositionBySid(taper.getSid()));
intent.putExtra("NOTIFICATION_BASED", true);
TaskStackBuilder stackBuilder = TaskStackBuilder.create(ctxt);
stackBuilder.addParentStack(SubData.class);
stackBuilder.addNextIntentWithParentStack(intent);
Intent delIntent = new Intent(ctxt, NotificationDismissalReceiver.class);
delIntent.putExtra("TAPER", true);
delIntent.putExtra("SUB_ID", taper.getSid());
PendingIntent pendingIntent =
stackBuilder.getPendingIntent(0, PendingIntent.FLAG_UPDATE_CURRENT);
PendingIntent pendingDelIntent = PendingIntent.getBroadcast(ctxt, 0,
delIntent, PendingIntent.FLAG_UPDATE_CURRENT);
LocalDateTime latestUsageLDT;
LocalDateTime todaysOpeningConstraintLDT;
boolean beforeOpeningConstraint = false;
latestUsageLDT = Converters.toLocalDateTime(
Permanence.Admins.getLatestUsageTimestampBySid(taper.getSid()));
if (taper.isConstrained()) {
todaysOpeningConstraintLDT =
LocalDateTime.now().withHour(taper.getStartHour().getHour())
.withMinute(taper.getStartHour().getMinute())
.withSecond(0);
if (latestUsageLDT.plus(taper.getTotalConstraintDuration()).isBefore(
todaysOpeningConstraintLDT)) {
beforeOpeningConstraint = true;
}
}
NotificationCompat.Builder builder = new NotificationCompat.Builder(
ctxt, "halflife")
.setContentTitle("Half-life Timer Taper " + taper.getName())
//note that the above line, right after "Due since: " +, will
//end up displaying the epoch start date for a taper on a
//substance that has no administrations whatsoever
.setSmallIcon(ctxt.getResources().getIdentifier("plus_medical_blue",
"drawable", ctxt.getPackageName()))
.setPriority(NotificationCompat.PRIORITY_DEFAULT)
.setContentIntent(pendingIntent)
.setDeleteIntent(pendingDelIntent)
.setAutoCancel(true);
long rawTimestamp = Permanence.Admins.getLatestUsageTimestampBySid(taper.getSid());
GlobalMisc.debugMsg("fireTaperNotification",
"Permanence.Admins.getLatestUsageTimestampBySid returns: " +
rawTimestamp);
if (Converters.toLocalDateTime(rawTimestamp).isBefore(
LocalDateTime.of(1980, 1, 1, 0, 0, 0))) {
builder.setContentText("Due: " +
String.format("%.2f", currentDosageScheduled) +
Permanence.Subs.getUnitsBySID(taper.getSid()) + "/" +
Permanence.Subs.loadSubstanceById(
taper.getSid()).getCommon_name() + "\n" +
"Due now");
} else if (beforeOpeningConstraint) {
builder.setContentText("Due:" +
currentDosageScheduled +
Permanence.Subs.getUnitsBySID(taper.getSid()) + " of " +
Permanence.Subs.loadSubstanceById(
taper.getSid()).getCommon_name() + "\n" +
"Due since: " +
LocalDateTime.now().withHour(taper.getStartHour().getHour())
.withMinute(taper.getStartHour().getMinute())
.withSecond(0));
} else {
builder.setContentText("Due:" +
currentDosageScheduled +
Permanence.Subs.getUnitsBySID(taper.getSid()) + " of " +
Permanence.Subs.loadSubstanceById(
taper.getSid()).getCommon_name() + "\n" +
"Due since: " +
Converters.toLocalDateTime(
Permanence.Admins.getLatestUsageTimestampBySid(
taper.getSid())).plus(
Duration.ofDays(1).dividedBy(
taper.getAdminsPerDay())));
}
NotificationManagerCompat notificationManager =
NotificationManagerCompat.from(ctxt);
notificationManager.notify(1, builder.build());
if (GlobalMisc.Debugging || notificationDebugging) {
Log.i("Halflife.fireNotification",
"attempted to send taper notification");
}
} catch (Exception ex) {
Log.e("Halflife.fireNotification",
"Something broke in taper notification: " + ex.toString());
throw new Exception("taper notification broke");
}
}
private void fireSubClearedNotification(Substance sub) throws Exception {
Context ctxt = getApplicationContext();
try {
Intent intent = new Intent(ctxt,
SubsRankedByLastUsage.class);
PendingIntent pendingIntent = PendingIntent.getActivity(
ctxt, 1, intent,
PendingIntent.FLAG_UPDATE_CURRENT);
NotificationCompat.Builder builder = new NotificationCompat.Builder(
ctxt, "halflife")
.setContentTitle("Half-life Timer Cleared: " + sub.getCommon_name())
.setContentText(sub.getCommon_name() + " cleared at " +
sub.getFullEliminationLDT().toString())
.setSmallIcon(ctxt.getResources().getIdentifier("plus_medical_blue",
"drawable", ctxt.getPackageName()))
.setPriority(NotificationCompat.PRIORITY_DEFAULT)
.setContentIntent(pendingIntent)
.setAutoCancel(true);
NotificationManagerCompat notificationManager =
NotificationManagerCompat.from(ctxt);
notificationManager.notify(1, builder.build());
if (GlobalMisc.Debugging || notificationDebugging) {
Log.i("Halflife.fireNotification",
"attempted to send sub clearednotification");
}
} catch (Exception ex) {
Log.e("Halflife.fireNotification",
"Something broke in sub cleared notification: " + ex.toString());
throw new Exception("sub cleared notification broke");
}
}
}I would be very grateful to anybody who might be able to offer any insight on why this behavior is happening, tips on how to avoid this behavior, where to find API & other documentation on the older, deprecated JetPack work v1.0.1 library, or what I can do in Android Studio to better diagnose this issue, as attempts for debugging with what I know how to do have proven futile.
Thank you very much for your time and help on this matter!
