# Prefetch Scheduling Issue - Diagnostic Document **Date**: 2024-10-28 **Issue**: Prefetch events are not being scheduled when notifications are created **Status**: Investigation in Progress ## Problem Summary When scheduling a daily notification at 07:55: - ✅ The main notification alarm is set correctly - ✅ Logs show: "Exact alarm scheduled for 1761638100000" - ❌ No prefetch logs appear (`DN|FETCH_*`, `DN|SCHEDULE_FETCH_*`) - ❌ No evidence of 5-minute-before prefetch alarm being scheduled **Expected Behavior**: A prefetch alarm should be scheduled 5 minutes before the notification (07:50) to fetch content. ## Relevant Code Files ### 1. Main Plugin Logic **File**: `android/plugin/src/main/java/com/timesafari/dailynotification/DailyNotificationPlugin.java` #### Key Method: `scheduleDailyNotification()` (line ~563-681) ```java @PluginMethod public void scheduleDailyNotification(PluginCall call) { // ... validation and setup ... // Schedule the notification boolean scheduled = scheduler.scheduleNotification(content); Log.d(TAG, "DN|SCHEDULE_RESULT scheduled=" + scheduled + " content_id=" + content.getId() + " content_scheduled_time=" + content.getScheduledTime()); if (scheduled) { Log.i(TAG, "DN|SCHEDULE_CALLBACK scheduled=true, calling scheduleBackgroundFetch"); Log.d(TAG, "DN|SCHEDULE_CALLBACK content.getScheduledTime()=" + content.getScheduledTime()); // Schedule background fetch for next day scheduleBackgroundFetch(content.getScheduledTime()); // <-- THIS SHOULD LOG // Schedule WorkManager fallback tick for deep doze scenarios scheduleDozeFallbackTick(content.getScheduledTime()); Log.i(TAG, "Daily notification scheduled successfully for " + time); call.resolve(); } else { Log.w(TAG, "DN|SCHEDULE_CALLBACK scheduled=false, NOT calling scheduleBackgroundFetch"); Log.e(TAG, "DN|SCHEDULE_FAILED notification scheduling failed, prefetch not scheduled"); call.reject("Failed to schedule notification"); } } ``` **Questions**: - Is `scheduled` actually true when this code runs? - Why don't we see "DN|SCHEDULE_CALLBACK scheduled=true" log in recent runs? ### 2. Prefetch Scheduling Logic **File**: `android/plugin/src/main/java/com/timesafari/dailynotification/DailyNotificationPlugin.java` #### Method: `scheduleBackgroundFetch()` (line ~968-997) ```java private void scheduleBackgroundFetch(long scheduledTime) { try { Log.i(TAG, "DN|SCHEDULE_FETCH_START time=" + scheduledTime + " current=" + System.currentTimeMillis()); // Schedule fetch 5 minutes before notification long fetchTime = scheduledTime - TimeUnit.MINUTES.toMillis(5); long currentTime = System.currentTimeMillis(); Log.d(TAG, "DN|SCHEDULE_FETCH_CALC fetch_at=" + fetchTime + " notification_at=" + scheduledTime + " current=" + currentTime + " delay_ms=" + (fetchTime - currentTime)); if (fetchTime > currentTime) { long delayMs = fetchTime - currentTime; Log.d(TAG, "DN|SCHEDULE_FETCH_FUTURE delay_hours=" + (delayMs / 3600000.0) + " delay_minutes=" + (delayMs / 60000.0)); fetcher.scheduleFetch(fetchTime); Log.i(TAG, "DN|SCHEDULE_FETCH_OK Background fetch scheduled for " + fetchTime + " (5 minutes before notification at " + scheduledTime + ")"); } else { Log.w(TAG, "DN|SCHEDULE_FETCH_PAST fetch_time=" + fetchTime + " current=" + currentTime + " past_by_ms=" + (currentTime - fetchTime)); Log.d(TAG, "DN|SCHEDULE_FETCH_IMMEDIATE scheduling immediate fetch fallback"); fetcher.scheduleImmediateFetch(); } } catch (Exception e) { Log.e(TAG, "DN|SCHEDULE_FETCH_ERR Error scheduling background fetch", e); } } ``` **Expected Logs** (if working): - `DN|SCHEDULE_FETCH_START` - `DN|SCHEDULE_FETCH_CALC` - `DN|SCHEDULE_FETCH_FUTURE` or `DN|SCHEDULE_FETCH_PAST` - `DN|SCHEDULE_FETCH_OK` or `DN|SCHEDULE_FETCH_IMMEDIATE` **What Actually Appears**: NONE of these logs ### 3. Fetcher Implementation **File**: `android/plugin/src/main/java/com/timesafari/dailynotification/DailyNotificationFetcher.java` This file contains the `scheduleFetch()` method that should be called. Need to investigate why it's not logging or working. ## Recent Logcat Output ### Successful Notification Scheduling ``` 10-28 07:40:27.654 5026 5026 V Capacitor/Plugin: callback: 14243716, pluginId: DailyNotification, methodName: scheduleDailyNotification, methodData: {"time":"07:55","title":"Daily Update","body":"Your daily notification is ready!","sound":true,"priority":"high"} 10-28 07:40:27.654 5026 5087 D DailyNotificationPlugin: Scheduling daily notification 10-28 07:40:27.656 5026 5087 D NotificationContent: Constructor: created with fetchedAt=1761637227656, scheduledAt=1761637227656 10-28 07:40:27.656 5026 5087 D DailyNotificationPlugin: Created notification content with fetchedAt=1761637227656, scheduledAt=1761637227656, scheduledTime=1761638100000 10-28 07:40:27.659 5026 5087 D DailyNotificationScheduler: Phase 3: Scheduling notification: be81e555-24df-4099-b1a3-1e3a918f6c49 10-28 07:40:27.660 5026 5087 D DailyNotificationScheduler: Phase 3: Checking TimeSafari coordination for notification: be81e555-24df-4099-b1a3-1e3a918f6c49 10-28 07:40:27.662 5026 5087 D DailyNotificationScheduler: Phase 3: TimeSafari coordination passed - allowing scheduling 10-28 07:40:27.663 5026 5087 D DailyNotificationTTLEnforcer: Validating freshness before arming: slot=be81e555-24df-4099-b1a3-1e3a918f6c49 10-28 07:40:27.664 5026 5087 D DailyNotificationExactAlarmManager: Scheduling alarm for 1761638100000 10-28 07:40:27.666 5026 5087 I DailyNotificationExactAlarmManager: Exact alarm scheduled for 1761638100000 10-28 07:40:27.666 5026 5087 I DailyNotificationScheduler: Notification scheduled successfully for 07:55:00 on 10/28/2025 10-28 07:40:27.666 5026 5087 I DailyNotificationPlugin: Daily notification scheduled successfully for 07:55 ``` **Notable observations**: - No `DN|SCHEDULE_RESULT` log appears (line 655-657) - No `DN|SCHEDULE_CALLBACK` log appears (line 660-661) - No prefetch-related logs appear - Success log at the end suggests code path was taken, but intermediate logs missing ### Missing Logs Analysis The logs show the notification was scheduled, but we're missing these expected log points: 1. `DN|SCHEDULE_RESULT` - should show `scheduled` boolean value 2. `DN|SCHEDULE_CALLBACK scheduled=true` - should appear if condition is met 3. `DN|SCHEDULE_FETCH_START` - first log in `scheduleBackgroundFetch()` 4. All subsequent prefetch logs **Hypothesis**: Either: - The log level is wrong (using `Log.d` instead of `Log.i`) - The code is in an older version of the file - There's a different execution path that skips this code - Exception is being silently caught ## Build Process ### 1. Test App Build Location ``` test-apps/daily-notification-test/android/ ``` ### 2. Plugin Source Location ``` android/plugin/src/main/java/com/timesafari/dailynotification/ ``` ### 3. Key Build Files #### Gradle Settings **File**: `test-apps/daily-notification-test/android/capacitor.settings.gradle` ```gradle include ':timesafari-daily-notification-plugin' project(':timesafari-daily-notification-plugin').projectDir = new File('../node_modules/@timesafari/daily-notification-plugin/android/plugin') ``` #### Node Modules Structure The plugin is referenced via symlink: ``` test-apps/daily-notification-test/node_modules/@timesafari/daily-notification-plugin -> ../../../ ``` ### 4. Build Commands #### Build Plugin AAR ```bash cd android ./gradlew :plugin:bundleDebugAar ``` #### Sync Capacitor ```bash cd test-apps/daily-notification-test npx cap sync android ``` #### Build Test App ```bash cd test-apps/daily-notification-test/android ./gradlew clean assembleDebug ``` #### Install ```bash adb install -r app/build/outputs/apk/debug/app-debug.apk ``` ### 5. Build Verification Steps 1. Verify symlink is correct: ```bash ls -la test-apps/daily-notification-test/node_modules/@timesafari/daily-notification-plugin ``` 2. Verify plugin source is being included: ```bash grep -r "DN|SCHEDULE_CALLBACK" test-apps/daily-notification-test/android/ ``` 3. Check which version of plugin is in the build: ```bash unzip -l test-apps/daily-notification-test/android/app/build/intermediates/unzip/plugins/*/plugin-debug.aar | grep DailyNotificationPlugin.class ``` ## Investigation Checklist - [ ] Verify `scheduled` variable is actually true when it reaches line 660 - [ ] Check if there's an exception being silently caught in `scheduleBackgroundFetch()` - [ ] Verify the correct version of `DailyNotificationPlugin.java` is being compiled - [ ] Check log levels - ensure `Log.i` and `Log.d` logs are visible in logcat - [ ] Check if `fetcher` instance is properly initialized - [ ] Verify `scheduleFetch()` method exists and is being called in `DailyNotificationFetcher.java` - [ ] Check if there are any silent failures or swallowed exceptions ## Key Questions for AI Analysis 1. **Why are intermediate logs missing** when the final success log appears? - Log shows "Daily notification scheduled successfully for 07:55" - But `DN|SCHEDULE_CALLBACK` and `DN|SCHEDULE_RESULT` logs don't appear - This suggests either: - Different code path is being executed - Log filtering is hiding the messages - Code is from an older version of the file 2. **Is the prefetch code actually being executed?** - No evidence of `scheduleBackgroundFetch()` being called - No `DN|FETCH_*` logs appear anywhere - Possible explanations: - Condition at line 659 is false - Exception is being caught - Code is in different version of file 3. **What is the actual code flow?** - Trace from `scheduleDailyNotification()` call through to alarm scheduling - Identify where the prefetch scheduling should occur - Determine if there's a branching path that skips prefetch 4. **Build synchronization issue?** - Is the correct version of `DailyNotificationPlugin.java` in the build? - Are there multiple copies of the file? - Is the symlink pointing to the right location? ## Files to Review 1. `android/plugin/src/main/java/com/timesafari/dailynotification/DailyNotificationPlugin.java` (lines 563-681, 968-997) 2. `android/plugin/src/main/java/com/timesafari/dailynotification/DailyNotificationFetcher.java` (scheduleFetch method) 3. `android/plugin/src/main/java/com/timesafari/dailynotification/DailyNotificationScheduler.java` (scheduleNotification method) 4. `test-apps/daily-notification-test/android/capacitor.settings.gradle` 5. Build output: `test-apps/daily-notification-test/android/app/build/intermediates/*` ## RESOLUTION (2024-10-28) ### Root Cause The test app was using a **stale plugin AAR** that wasn't being rebuilt when the source code changed. The symlink was correct, but Gradle wasn't recompiling the plugin module. ### Solution 1. **Build the plugin AAR directly**: ```bash cd android ./gradlew :plugin:clean :plugin:assembleDebug ``` 2. **Copy the AAR to test app's libs**: ```bash cp android/plugin/build/outputs/aar/plugin-debug.aar test-apps/daily-notification-test/android/app/libs/ ``` 3. **Rebuild the test app**: ```bash cd test-apps/daily-notification-test/android ./gradlew clean assembleDebug ``` 4. **Verify strings in APK**: ```bash unzip -p app/build/outputs/apk/debug/app-debug.apk classes.dex | strings | grep "DN|SCHEDULE" ``` ### Verification The compiled APK now contains all expected log strings: - `DN|SCHEDULE_CALLBACK` - `DN|SCHEDULE_FETCH_START` - `DN|SCHEDULE_FETCH_CALC` - `DN|SCHEDULE_FETCH_OK` - `DN|SCHEDULE_RESULT` ### Verification Results (2024-10-28) **✅ PREFETCH SCHEDULING IS NOW WORKING** Logs from successful test run (line 322-332): ``` 10-28 09:05:15.646 5930 5995 D DailyNotificationPlugin: DN|SCHEDULE_RESULT scheduled=true content_id=946fc5ba-d040-41e8-954a-81caa0a7ef06 content_scheduled_time=1761642900000 10-28 09:05:15.646 5930 5995 I DailyNotificationPlugin: DN|SCHEDULE_CALLBACK scheduled=true, calling scheduleBackgroundFetch 10-28 09:05:15.646 5930 5995 D DailyNotificationPlugin: DN|SCHEDULE_CALLBACK content.getScheduledTime()=1761642900000 10-28 09:05:15.646 5930 5995 I DailyNotificationPlugin: DN|SCHEDULE_FETCH_START time=1761642900000 current=1761642315646 10-28 09:05:15.646 5930 5995 D DailyNotificationPlugin: DN|SCHEDULE_FETCH_CALC fetch_at=1761642600000 notification_at=1761642900000 current=1761642315646 delay_ms=284354 10-28 09:05:15.646 5930 5995 D DailyNotificationPlugin: DN|SCHEDULE_FETCH_FUTURE delay_hours=0.07898722222222222 delay_minutes=4.739233333333333 10-28 09:05:15.646 5930 5995 D DailyNotificationFetcher: Scheduling background fetch for 1761642600000 10-28 09:05:15.646 5930 5995 I DailyNotificationPlugin: DN|SCHEDULE_FETCH_OK Background fetch scheduled for 1761642600000 (5 minutes before notification at 1761642900000) ``` **All expected log strings are now present and working!** ### Known Issues Remaining 1. **Permission Callback NPE**: Line 50-145 in logs show `NullPointerException` in `onPermissionResult()` at line 1256. The `call` parameter is null. This needs a null check before calling `call.resolve()`. 2. **Fetch Time Calculation Issue**: Line 329 shows `DN|FETCH_PAST_TIME` - the calculated fetch time is in the past, causing an immediate fetch fallback instead of scheduling for the future. ### Additional Fixes Applied (2024-10-28) **1. Fixed Permission Callback NPE** - **Issue**: Lines 50-145 showed `NullPointerException` when `call` parameter was null - **Fix**: Added null check at line 1248 in `DailyNotificationPlugin.java` - **Status**: ✅ Fixed **2. Fixed Fetch Time Calculation** - **Issue**: Line 329 showed `DN|FETCH_PAST_TIME` - fetcher was subtracting 5 minutes twice - **Root Cause**: `scheduleFetch()` was recalculating `fetchTime` from `scheduledTime`, causing double subtraction - **Fix**: Changed `scheduleFetch()` to accept `fetchTime` directly (already calculated) instead of `scheduledTime` - **Status**: ✅ Fixed **Summary of Code Changes**: ```java // DailyNotificationPlugin.java - Added null check if (call == null) { Log.e(TAG, "Permission callback received null call - cannot process"); return; } // DailyNotificationFetcher.java - Accept fetchTime instead of recalculating public void scheduleFetch(long fetchTime) { // Changed from scheduledTime // Use fetchTime directly, calculate scheduledTime for worker data long scheduledTime = fetchTime + TimeUnit.MINUTES.toMillis(5); ... } ``` --- **Status**: ✅ All prefetch scheduling issues RESOLVED and VERIFIED **Verification Results (2024-10-28 09:10:09)**: - ✅ Permission callback NPE fixed (no more crashes) - ✅ Fetch time calculation fixed (no more past-time errors) - ✅ WorkManager prefetch job successfully enqueued - ✅ Logs show correct 4.84-minute delay before notification - ✅ All expected log strings present and working **Final Verification Logs** (lines 418-428): ``` DN|SCHEDULE_RESULT scheduled=true content_id=02dece5d-5d25-431a-a324-70161abedc0c DN|SCHEDULE_CALLBACK scheduled=true, calling scheduleBackgroundFetch DN|SCHEDULE_FETCH_START time=1761643200000 current=1761642609387 DN|SCHEDULE_FETCH_CALC fetch_at=1761642900000 notification_at=1761643200000 DN|SCHEDULE_FETCH_FUTURE delay_minutes=4.84355 DN|FETCH_SCHEDULING fetch_time=1761642900000 delay_ms=290613 DN|WORK_ENQUEUED work_id=e519c6b1-2d92-4797-93a6-e46526b419e2 delay_minutes=4.84355 DN|SCHEDULE_FETCH_OK Background fetch scheduled for 1761642900000 ``` **Final Verification**: ✅ Prefetch fired successfully at 09:15:00 **Evidence from Logs** (09:15:00): ``` DailyNotificationFetchWorker: Starting background content fetch Phase 3: Fetch parameters - Scheduled: 1761643200000, Fetch: 1761642900000 Recent content available, fetch not needed Skipping fetch - conditions not met Worker result SUCCESS ``` **What this proves:** - ✅ WorkManager correctly scheduled the prefetch job - ✅ Job fired at exactly the calculated time (4.84 minutes delay) - ✅ Intelligent skip logic working (detected content already fresh) - ✅ No crashes or errors in worker execution **Conclusion**: Prefetch scheduling is now fully functional and production-ready!