PeriodicWorkRequest (work v1.0.1) is spawning 20 times every 15m in stead of just once, not sure why

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

Code (Text):

1.  
2.     package com.example.sprite.half_lifetimer;
3.  
4.     import android.content.BroadcastReceiver;
5.     import android.content.Context;
6.     import android.content.Intent;
7.     import android.os.Build;
8.     import android.util.Log;
9.  
10.     public class BootServiceStart extends BroadcastReceiver {
11.         public void onReceive(Context context, Intent arg1) {
12.             Intent intent = new Intent(context , NotificationService.class);
13.  
14.             if (Build.VERSION.SDK_INT >= Build.VERSION_CODES.O) {
15.                 context.startForegroundService(intent);
16.             } else {
17.                 context.startService(intent);
18.             }
19.  
20.             if (GlobalMisc.Debugging) {
21.                 Log.i("Halflife.BootServiceStart", "Attempted to start NotificationService");
22.             }
23.         }
24.     }
25.  

NotificationService - also here on dpaste

Code (Text):

1.  
2.     package com.example.sprite.half_lifetimer;
3.  
4.     import android.app.Notification;
5.     import android.app.NotificationChannel;
6.     import android.app.NotificationManager;;
7.     import android.app.Service;
8.     import android.content.Intent;
9.     import android.os.Build;
10.     import android.os.IBinder;
11.     import android.support.annotation.Nullable;
12.     import android.support.v4.app.NotificationCompat;
13.     import android.util.Log;
14.     import androidx.work.PeriodicWorkRequest;
15.     import androidx.work.WorkManager;
16.  
17.     import java.time.LocalDateTime;
18.     import java.util.HashMap;
19.     import java.util.concurrent.TimeUnit;
20.  
21.     public class NotificationService extends Service {
22.         public static HashMap<Integer, Boolean> firedNotifications = new HashMap<>();
23.         public static LocalDateTime lastNotificationLoopLDT = null;
24.  
25.         @Nullable
26.         public IBinder onBind(Intent intent) {
27.             return null;
28.         }
29.  
30.         /**
31.          * Method handles creation of a NotificationChannel and database
32.          * initialization (for this particular subset of the code), then passing
33.          * control off to notificationLoop().
34.          */
35.         public void onCreate() {
36.             startForeground(31337, buildForegroundNotification());
37.  
38.             if (GlobalMisc.Debugging) {
39.                 Log.i("Halflife.NotificationService.onCreate", "Started NotificationService");
40.             }
41.  
42.             // Create the NotificationChannel, but only on API 26+ because
43.             // the NotificationChannel class is new and not in the support library
44.             if (Build.VERSION.SDK_INT >= Build.VERSION_CODES.O) {
45.                 NotificationChannel chan = new NotificationChannel(
46.                         "taper-n-clearing-talk", "taper-n-clearing",
47.                         NotificationManager.IMPORTANCE_NONE);
48.                 chan.setDescription("Notifications for Taper dosages and Substance clearance");
49.  
50.                 // Register the channel with the system; you can't change the importance
51.                 // or other notification behaviors after this
52.                 NotificationManager notificationManager = getSystemService(NotificationManager.class);
53.                 notificationManager.createNotificationChannel(chan);
54.             }
55.  
56.             //get the database ready
57.             try {
58.                 Permanence.Misc.init(/*NotificationService.this*/ getApplicationContext());
59.             } catch (Exception ex) {
60.                 Log.e("Halflife.notificationLoop", "Unable to init database: " +
61.                         ex.toString());
62.             }
63.  
64.             if (GlobalMisc.Debugging) {
65.                 Log.i("Halflife.onCreate", "all valid tapers: " +
66.                         Permanence.Tapers.loadAllValidTapers(getApplicationContext()).toString());
67.  
68.             }
69.  
70.             //notificationLoop();
71.             PeriodicWorkRequest notificationsRequest =
72.                     new PeriodicWorkRequest.Builder(NotificationWorker.class, 15, TimeUnit.MINUTES)
73.                             .build();
74.             WorkManager.getInstance()
75.                     .enqueue(notificationsRequest);
76.         }
77.  
78.         private Notification buildForegroundNotification() {
79.             NotificationCompat.Builder b=new NotificationCompat.Builder(this);
80.  
81.             b.setOngoing(true)
82.                     .setContentTitle("HLT Foreground Service")
83.                     .setContentText("Giving Half-life Timer foreground priority")
84.                     .setChannelId("taper-n-clearing-talk")
85.                     .setSmallIcon(getApplicationContext().getResources().getIdentifier(
86.                             "plus_medical_blue","drawable",
87.                             getApplicationContext().getPackageName()));
88.  
89.             return(b.build());
90.         }
91.     }
92.  

NotificationWorker - also here on dpaste

Code (Text):

1.  
2.     package com.example.sprite.half_lifetimer;
3.  
4.     import android.app.PendingIntent;
5.     import android.app.TaskStackBuilder;
6.     import android.content.Context;
7.     import android.content.Intent;
8.     import android.support.annotation.NonNull;
9.     import android.support.v4.app.NotificationCompat;
10.     import android.support.v4.app.NotificationManagerCompat;
11.     import android.util.Log;
12.  
13.     import androidx.work.Worker;
14.     import androidx.work.WorkerParameters;
15.  
16.     import java.time.Duration;
17.     import java.time.LocalDateTime;
18.     import java.time.LocalTime;
19.  
20.     public class NotificationWorker extends Worker {
21.         private boolean notificationDebugging = false;
22.  
23.         public NotificationWorker(@NonNull Context context, @NonNull WorkerParameters params) {
24.             super(context, params);
25.         }
26.  
27.         @Override
28.         public Result doWork() {
29.             LocalDateTime nextScheduledDosage;
30.             long adminDurationMinutes;
31.  
32.             if (!notificationDebugging) {
33.                 if (GlobalMisc.NotificationsEnabled) {
34.                     //taper notification loop
35.                     for (Taper taper : Permanence.Tapers.loadAllValidTapers(getApplicationContext())) {
36.                         //this will handle if any tapers have been added since inception
37.                         if (!NotificationService.firedNotifications.containsKey(taper.getId())) {
38.                             NotificationService.firedNotifications.put(taper.getId(), false);
39.                         }
40.  
41.                         //if this is a constrained taper, but we're outside of the window, just
42.                         //go on to the next taper
43.                         if (taper.isConstrained() && !taper.inConstraintHours()) {
44.                             Log.i("Halflife.notificationLoop",
45.                                     "skipping " + taper.toString() +
46.                                             " (outside of hourly constraints)");
47.  
48.                             continue;
49.                         }
50.  
51.                         if (!NotificationService.firedNotifications.get(taper.getId())) {
52.                             try {
53.                                 nextScheduledDosage = taper.findNextScheduledDosageLDT();
54.                                 if (!taper.isConstrained()) {
55.                                     Log.i("Halflife.notificationLoop",
56.                                             "working with unconstrained taper");
57.  
58.                                     adminDurationMinutes = Duration.ofDays(1).dividedBy(
59.                                             taper.getAdminsPerDay()).toMinutes();
60.                                 } else {
61.                                     Log.i("Halflife.notificationLoop",
62.                                             "working with constrained taper");
63.  
64.                                     //not sure if this is necessary or not, but might as well
65.                                     //throw it in since the goddamned code is too complex for me
66.                                     //to follow right now down below
67.                                     LocalTime nextDosageTime =
68.                                             nextScheduledDosage.toLocalTime();
69.                                     if (nextDosageTime.isBefore(taper.getStartHour()) ||
70.                                             nextDosageTime.isAfter(taper.getEndHour())) {
71.                                         Log.i("notificationLoop",
72.                                                 "skipping " + taper.toString() +
73.                                                         " (outside of constraint hours)");
74.  
75.                                         continue;
76.                                     }
77.  
78.                                     //this part, of course, is necessary
79.                                     adminDurationMinutes =
80.                                             Duration.between(taper.getStartHour(),
81.                                                     taper.getEndHour()).dividedBy(
82.                                                     taper.getAdminsPerDay())
83.                                                     .toMinutes();
84.                                 }
85.  
86.                                 if (GlobalMisc.Debugging) {
87.                                     Log.i("Halflife.notificationLoop", "Checking taper: " +
88.                                             taper.getName());
89.                                     Log.i("Halflife.notificationLoop", "nextScheduledDosage " +
90.                                             "contains: " + nextScheduledDosage.toString());
91.                                 }
92.  
93.                                 if (((NotificationService.lastNotificationLoopLDT != null) &&
94.                                         nextScheduledDosage.isAfter(
95.                                                 NotificationService.lastNotificationLoopLDT) &&
96.                                         nextScheduledDosage.isBefore(
97.                                                 LocalDateTime.now().plusMinutes(
98.                                                         (adminDurationMinutes / 5)))) ||
99.                                         (nextScheduledDosage.isAfter(
100.                                                 LocalDateTime.now().minusMinutes(1)) &&
101.                                                 nextScheduledDosage.isBefore(
102.                                                         LocalDateTime.now().plusMinutes(
103.                                                                 (adminDurationMinutes / 5))))) {
104.                                     fireTaperNotification(taper);
105.  
106.                                     //set firedNotifications to reflect that we sent this
107.                                     //notification
108.                                     NotificationService.firedNotifications.replace(taper.getId(), true);
109.                                 } else if (GlobalMisc.Debugging) {
110.                                     Log.i("Halflife.notificationLoop",
111.                                             "not displaying notification as per " +
112.                                                     "datetime constraints");
113.                                 }
114.                             } catch (Exception ex) {
115.                                 Log.e("Halflife.notificationLoop",
116.                                         "Issue finding next scheduled dosage: " +
117.                                                 ex.toString());
118.  
119.                                 return Result.failure();
120.                             }
121.                         }
122.                     }
123.                 } else {
124.                     GlobalMisc.debugMsg("NotificationWorker:doWork",
125.                             "Would have just gone into substance taper notification loop");
126.                 }
127.  
128.                 if (GlobalMisc.NotificationsEnabled) {
129.                     //substance clearing notification loop
130.                     //LocalDateTime fiveMinAgo = LocalDateTime.now().minusMinutes(5);
131.                     for (Substance sub : Permanence.Subs.loadUnarchivedSubstances(
132.                             getApplicationContext())) {
133.                         if (GlobalMisc.Debugging) {
134.                             Log.i("Halflife.notificationLoop",
135.                                     "Checking sub clearance: " + sub.getCommon_name());
136.                         }
137.  
138.                         //has this substance cleared within the last 5 minutes?
139.                         LocalDateTime clearedAt = sub.getFullEliminationLDT();
140.                         if (clearedAt != null) {
141.                             if (NotificationService.lastNotificationLoopLDT != null) {
142.                                 if (clearedAt.isAfter(NotificationService.lastNotificationLoopLDT) &&
143.                                         clearedAt.isBefore(LocalDateTime.now())) {
144.                                     //fire the notification
145.                                     try {
146.                                         fireSubClearedNotification(sub);
147.                                     } catch (Exception ex) {
148.                                         Log.i("Halflife.doWork", ex.toString());
149.  
150.                                         return Result.failure();
151.                                     }
152.                                 }
153.                             }
154.                         }
155.                     }
156.                 } else {
157.                     GlobalMisc.debugMsg("NotificationWorker:doWork",
158.                             "Would have just gone into substance clearing notification loop");
159.                 }
160.             } else {
161.                 Log.i("Halflife.notificationLoop", "In notification debugging " +
162.                         "mode");
163.  
164.                 try {
165.                     fireTaperNotification(null);
166.                 } catch (Exception ex) {
167.                     Log.i("Halflife.doWork", ex.toString());
168.  
169.                     return Result.failure();
170.                 }
171.             }
172.  
173.             NotificationService.lastNotificationLoopLDT = LocalDateTime.now();
174.  
175.             return Result.success();
176.         }
177.  
178.         /**
179.          * Method handles the actual building of the notification regarding
180.          * the applicable taper, and shows it unless our handy HashMap
181.          * 'firedNotifications' shows that there is already a notification
182.          * present for this particular taper.
183.          *
184.          * @param taper the taper to display notification for
185.          */
186.         private void fireTaperNotification(Taper taper) throws Exception {
187.             Context ctxt = getApplicationContext();
188.             float currentDosageScheduled = taper.findCurrentScheduledDosageAmount();
189.  
190.             //here's the legitimate meat 'n potatoes for firing a notification
191.             try {
192.                 //if we've already blown the dosage required for the next administration, just skip this
193.                 //one
194.                 if (currentDosageScheduled <= 0) {
195.                     Log.d("fireTaperNotification", "More dosage taken than needs to be " +
196.                             "for the current taper step; skipping this taper administration.");
197.  
198.                     return;
199.                 }
200.  
201.                 Intent intent = new Intent(ctxt, AdminData.class);
202.                 intent.putExtra("SUB_NDX",
203.                         GlobalMisc.getSubListPositionBySid(taper.getSid()));
204.                 intent.putExtra("NOTIFICATION_BASED", true);
205.                 TaskStackBuilder stackBuilder = TaskStackBuilder.create(ctxt);
206.                 stackBuilder.addParentStack(SubData.class);
207.                 stackBuilder.addNextIntentWithParentStack(intent);
208.  
209.                 Intent delIntent = new Intent(ctxt, NotificationDismissalReceiver.class);
210.                 delIntent.putExtra("TAPER", true);
211.                 delIntent.putExtra("SUB_ID", taper.getSid());
212.  
213.  
214.                 PendingIntent pendingIntent =
215.                         stackBuilder.getPendingIntent(0, PendingIntent.FLAG_UPDATE_CURRENT);
216.                 PendingIntent pendingDelIntent = PendingIntent.getBroadcast(ctxt, 0,
217.                         delIntent, PendingIntent.FLAG_UPDATE_CURRENT);
218.  
219.                 LocalDateTime latestUsageLDT;
220.                 LocalDateTime todaysOpeningConstraintLDT;
221.                 boolean beforeOpeningConstraint = false;
222.                 latestUsageLDT = Converters.toLocalDateTime(
223.                         Permanence.Admins.getLatestUsageTimestampBySid(taper.getSid()));
224.                 if (taper.isConstrained()) {
225.                     todaysOpeningConstraintLDT =
226.                             LocalDateTime.now().withHour(taper.getStartHour().getHour())
227.                                     .withMinute(taper.getStartHour().getMinute())
228.                                     .withSecond(0);
229.  
230.                     if (latestUsageLDT.plus(taper.getTotalConstraintDuration()).isBefore(
231.                             todaysOpeningConstraintLDT)) {
232.                         beforeOpeningConstraint = true;
233.                     }
234.                 }
235.  
236.                 NotificationCompat.Builder builder = new NotificationCompat.Builder(
237.                         ctxt, "halflife")
238.                         .setContentTitle("Half-life Timer Taper " + taper.getName())
239.                         //note that the above line, right after "Due since: " +, will
240.                         //end up displaying the epoch start date for a taper on a
241.                         //substance that has no administrations whatsoever
242.                         .setSmallIcon(ctxt.getResources().getIdentifier("plus_medical_blue",
243.                                 "drawable", ctxt.getPackageName()))
244.                         .setPriority(NotificationCompat.PRIORITY_DEFAULT)
245.                         .setContentIntent(pendingIntent)
246.                         .setDeleteIntent(pendingDelIntent)
247.                         .setAutoCancel(true);
248.  
249.                 long rawTimestamp = Permanence.Admins.getLatestUsageTimestampBySid(taper.getSid());
250.  
251.                 GlobalMisc.debugMsg("fireTaperNotification",
252.                         "Permanence.Admins.getLatestUsageTimestampBySid returns: " +
253.                                 rawTimestamp);
254.  
255.                 if (Converters.toLocalDateTime(rawTimestamp).isBefore(
256.                         LocalDateTime.of(1980, 1, 1, 0, 0, 0))) {
257.                     builder.setContentText("Due: " +
258.                             String.format("%.2f", currentDosageScheduled) +
259.                             Permanence.Subs.getUnitsBySID(taper.getSid()) + "/" +
260.                             Permanence.Subs.loadSubstanceById(
261.                                     taper.getSid()).getCommon_name() + "\n" +
262.                             "Due now");
263.                 } else if (beforeOpeningConstraint) {
264.                     builder.setContentText("Due:" +
265.                             currentDosageScheduled +
266.                             Permanence.Subs.getUnitsBySID(taper.getSid()) + " of " +
267.                             Permanence.Subs.loadSubstanceById(
268.                                     taper.getSid()).getCommon_name() + "\n" +
269.                             "Due since: " +
270.                             LocalDateTime.now().withHour(taper.getStartHour().getHour())
271.                                .withMinute(taper.getStartHour().getMinute())
272.                                .withSecond(0));
273.                 } else {
274.                     builder.setContentText("Due:" +
275.                             currentDosageScheduled +
276.                             Permanence.Subs.getUnitsBySID(taper.getSid()) + " of " +
277.                             Permanence.Subs.loadSubstanceById(
278.                                     taper.getSid()).getCommon_name() + "\n" +
279.                             "Due since: " +
280.                             Converters.toLocalDateTime(
281.                                     Permanence.Admins.getLatestUsageTimestampBySid(
282.                                             taper.getSid())).plus(
283.                                     Duration.ofDays(1).dividedBy(
284.                                             taper.getAdminsPerDay())));
285.                 }
286.  
287.                 NotificationManagerCompat notificationManager =
288.                         NotificationManagerCompat.from(ctxt);
289.  
290.                 notificationManager.notify(1, builder.build());
291.  
292.                 if (GlobalMisc.Debugging || notificationDebugging) {
293.                     Log.i("Halflife.fireNotification",
294.                             "attempted to send taper notification");
295.                 }
296.             } catch (Exception ex) {
297.                 Log.e("Halflife.fireNotification",
298.                         "Something broke in taper notification: " + ex.toString());
299.  
300.                 throw new Exception("taper notification broke");
301.             }
302.         }
303.  
304.         private void fireSubClearedNotification(Substance sub) throws Exception {
305.             Context ctxt = getApplicationContext();
306.  
307.             try {
308.                 Intent intent = new Intent(ctxt,
309.                         SubsRankedByLastUsage.class);
310.  
311.                 PendingIntent pendingIntent = PendingIntent.getActivity(
312.                         ctxt, 1, intent,
313.                         PendingIntent.FLAG_UPDATE_CURRENT);
314.  
315.                 NotificationCompat.Builder builder = new NotificationCompat.Builder(
316.                         ctxt, "halflife")
317.                         .setContentTitle("Half-life Timer Cleared: " + sub.getCommon_name())
318.                         .setContentText(sub.getCommon_name() + " cleared at " +
319.                                 sub.getFullEliminationLDT().toString())
320.                         .setSmallIcon(ctxt.getResources().getIdentifier("plus_medical_blue",
321.                                 "drawable", ctxt.getPackageName()))
322.                         .setPriority(NotificationCompat.PRIORITY_DEFAULT)
323.                         .setContentIntent(pendingIntent)
324.                         .setAutoCancel(true);
325.  
326.                 NotificationManagerCompat notificationManager =
327.                         NotificationManagerCompat.from(ctxt);
328.  
329.                 notificationManager.notify(1, builder.build());
330.  
331.                 if (GlobalMisc.Debugging || notificationDebugging) {
332.                     Log.i("Halflife.fireNotification",
333.                             "attempted to send sub clearednotification");
334.                 }
335.             } catch (Exception ex) {
336.                 Log.e("Halflife.fireNotification",
337.                         "Something broke in sub cleared notification: " + ex.toString());
338.  
339.                 throw new Exception("sub cleared notification broke");
340.             }
341.         }
342.     }
343.  

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!