trent_larson/daily-notification-plugin
4
0
Fork 0
Code Issues Pull Requests 2 Projects Releases Wiki Activity

fix(android): resolve prefetch scheduling and permission callback issues

Browse Source 
- Add null safety check to permission callback to prevent NPE
- Fix fetch time calculation bug that caused double subtraction
  - scheduleFetch() now accepts pre-calculated fetchTime directly
  - Calculate scheduledTime back from fetchTime for worker data
- Add structured logging (DN|FETCH_SCHEDULING) for better traceability

The permission callback was crashing with NullPointerException when
Capacitor passed a null call parameter. The prefetch scheduling had a
logic error where fetchTime was calculated twice - once in the plugin
and once in the fetcher, causing 10-minute delays instead of 5-minute.

Both issues are now fixed and verified working:
- Permission callback handles null gracefully
- Prefetch schedules correctly 5 minutes before notification
- WorkManager job fires at the correct time
- All structured logs appear in logcat

Closes prefetch scheduling investigation.
This commit is contained in:
Matthew Raymer
2025-10-28 09:35:33 +00:00
parent 0e783a8a2d
commit 333c435b89
5 changed files with 491 additions and 13 deletions
Download Patch File Download Diff File Expand all files Collapse all files

392
docs/prefetch-scheduling-diagnosis.md Normal file
View File

@@ -0,0 +1,392 @@
# 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!