Browse Source
- Add comprehensive logging to scheduleBackgroundFetch method - Log scheduledTime and currentTime for comparison - Log calculated fetch time and delay in ms, hours, and minutes - Log detailed timing information for future vs past fetch times - Add fallback path logging for immediate fetch scenarios - Add logging to scheduleDailyNotification callback - Log scheduled notification result with content details - Log when scheduleBackgroundFetch is called - Add error logging when notification scheduling fails - Add WorkManager status logging in DailyNotificationFetcher - Log work ID when work is enqueued - Log detailed timing information (delay_ms, delay_hours) - Add past time detection with duration logging - Improve immediate fetch fallback logging - Add prefetch scheduling trace documentation - Document complete code flow from notification to prefetch - Include debugging checklist and log search patterns - Add ADB commands for troubleshooting These changes enable better debugging of prefetch scheduling issues by providing detailed timing and execution information at every decision point in the prefetch scheduling flow.master
Matthew Raymer
5 days ago
4 changed files with 285 additions and 7 deletions
@ -0,0 +1,251 @@ |
|||||
|
# Prefetch Scheduling Trace Analysis |
||||
|
|
||||
|
**Analysis Date**: October 27, 2025 - 12:18:37 UTC |
||||
|
**Author**: Matthew Raymer |
||||
|
**Status**: Investigation Complete |
||||
|
|
||||
|
## Summary |
||||
|
|
||||
|
This document traces how prefetch scheduling works solo and in conjunction with notification schedules. Investigation reveals that **prefetch schedules ARE being set**, but there may be issues with logging visibility and execution. |
||||
|
|
||||
|
## Code Flow Analysis |
||||
|
|
||||
|
### 1. Notification Scheduling Flow |
||||
|
|
||||
|
When a user schedules a notification via the plugin: |
||||
|
|
||||
|
``` |
||||
|
DailyNotificationPlugin.scheduleDailyNotification() |
||||
|
↓ |
||||
|
DailyNotificationScheduler.scheduleNotification() |
||||
|
↓ |
||||
|
Plugin.scheduleBackgroundFetch(content.getScheduledTime()) |
||||
|
``` |
||||
|
|
||||
|
**Location**: `android/plugin/src/main/java/com/timesafari/dailynotification/DailyNotificationPlugin.java:658` |
||||
|
|
||||
|
### 2. Prefetch Scheduling Flow |
||||
|
|
||||
|
The `scheduleBackgroundFetch` method calculates the fetch time: |
||||
|
|
||||
|
```java |
||||
|
private void scheduleBackgroundFetch(long scheduledTime) { |
||||
|
try { |
||||
|
Log.d(TAG, "DN|SCHEDULE_FETCH_START time=" + scheduledTime); |
||||
|
|
||||
|
// Schedule fetch 5 minutes before notification |
||||
|
long fetchTime = scheduledTime - TimeUnit.MINUTES.toMillis(5); |
||||
|
|
||||
|
if (fetchTime > System.currentTimeMillis()) { |
||||
|
Log.d(TAG, "DN|SCHEDULE_FETCH_CALC fetch_at=" + fetchTime + " notification_at=" + scheduledTime); |
||||
|
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=" + System.currentTimeMillis()); |
||||
|
} |
||||
|
} catch (Exception e) { |
||||
|
Log.e(TAG, "DN|SCHEDULE_FETCH_ERR Error scheduling background fetch", e); |
||||
|
} |
||||
|
} |
||||
|
``` |
||||
|
|
||||
|
**Location**: `DailyNotificationPlugin.java:961-978` |
||||
|
|
||||
|
### 3. WorkManager Enqueuing |
||||
|
|
||||
|
The `fetcher.scheduleFetch()` method creates a WorkManager request: |
||||
|
|
||||
|
```java |
||||
|
public void scheduleFetch(long scheduledTime) { |
||||
|
try { |
||||
|
Log.d(TAG, "Scheduling background fetch for " + scheduledTime); |
||||
|
|
||||
|
// Calculate fetch time (5 minutes before notification) |
||||
|
long fetchTime = scheduledTime - TimeUnit.MINUTES.toMillis(5); |
||||
|
|
||||
|
if (fetchTime > System.currentTimeMillis()) { |
||||
|
// Create work data |
||||
|
Data inputData = new Data.Builder() |
||||
|
.putLong("scheduled_time", scheduledTime) |
||||
|
.putLong("fetch_time", fetchTime) |
||||
|
.putInt("retry_count", 0) |
||||
|
.build(); |
||||
|
|
||||
|
// Create one-time work request |
||||
|
OneTimeWorkRequest fetchWork = new OneTimeWorkRequest.Builder( |
||||
|
DailyNotificationFetchWorker.class) |
||||
|
.setInputData(inputData) |
||||
|
.addTag(WORK_TAG_FETCH) |
||||
|
.setInitialDelay(fetchTime - System.currentTimeMillis(), TimeUnit.MILLISECONDS) |
||||
|
.build(); |
||||
|
|
||||
|
// Enqueue the work |
||||
|
workManager.enqueue(fetchWork); |
||||
|
|
||||
|
Log.i(TAG, "Background fetch scheduled successfully"); |
||||
|
|
||||
|
} else { |
||||
|
Log.w(TAG, "Fetch time has already passed, scheduling immediate fetch"); |
||||
|
scheduleImmediateFetch(); |
||||
|
} |
||||
|
|
||||
|
} catch (Exception e) { |
||||
|
Log.e(TAG, "Error scheduling background fetch", e); |
||||
|
// Fallback to immediate fetch |
||||
|
scheduleImmediateFetch(); |
||||
|
} |
||||
|
} |
||||
|
``` |
||||
|
|
||||
|
**Location**: `DailyNotificationFetcher.java:77-115` |
||||
|
|
||||
|
## Key Findings |
||||
|
|
||||
|
### ✅ Prefetch Scheduling IS Implemented |
||||
|
|
||||
|
The code shows that: |
||||
|
|
||||
|
1. **When a notification is scheduled**, `scheduleBackgroundFetch()` is called **if scheduling succeeds** |
||||
|
2. **The prefetch time is calculated**: `fetchTime = scheduledTime - 5 minutes` |
||||
|
3. **WorkManager work is enqueued** with the calculated delay |
||||
|
4. **Logs ARE generated** at several points |
||||
|
|
||||
|
### ⚠️ Potential Issues |
||||
|
|
||||
|
1. **Logging Visibility** |
||||
|
- Logs may not be visible if: |
||||
|
- The app is closed (logs go to system logcat) |
||||
|
- Filters are not capturing the right tags |
||||
|
- Log level is not set correctly |
||||
|
|
||||
|
2. **Conditional Logging** |
||||
|
- The `scheduleBackgroundFetch` is only called when `scheduled == true` |
||||
|
- If notification scheduling fails, no prefetch is scheduled |
||||
|
- This is at line 655-666 in `DailyNotificationPlugin.java` |
||||
|
|
||||
|
3. **Timing Issues** |
||||
|
- If `fetchTime` is in the past, it schedules immediate fetch |
||||
|
- This might cause confusion if timing calculations are wrong |
||||
|
|
||||
|
## Expected Log Sequence |
||||
|
|
||||
|
When properly scheduling a notification: |
||||
|
|
||||
|
``` |
||||
|
DN|SCHEDULE_CALLBACK scheduled=true, calling scheduleBackgroundFetch |
||||
|
DN|SCHEDULE_FETCH_START time=<scheduledTime> |
||||
|
DN|SCHEDULE_FETCH_CALC fetch_at=<fetchTime> notification_at=<scheduledTime> |
||||
|
Scheduling background fetch for <scheduledTime> |
||||
|
Background fetch scheduled successfully |
||||
|
DN|SCHEDULE_FETCH_OK Background fetch scheduled for <fetchTime> (5 minutes before notification at <scheduledTime>) |
||||
|
``` |
||||
|
|
||||
|
## How to Debug |
||||
|
|
||||
|
### 1. Check if Prefetch is Being Scheduled |
||||
|
|
||||
|
Look for these log tags in logcat: |
||||
|
|
||||
|
```bash |
||||
|
adb logcat | grep -E "DN\|SCHEDULE_FETCH|DailyNotificationFetcher" |
||||
|
``` |
||||
|
|
||||
|
Expected logs: |
||||
|
- `DN|SCHEDULE_FETCH_START` |
||||
|
- `DN|SCHEDULE_FETCH_CALC` |
||||
|
- `DN|SCHEDULE_FETCH_OK` |
||||
|
- `Scheduling background fetch for` |
||||
|
|
||||
|
### 2. Check WorkManager Queue |
||||
|
|
||||
|
Verify that work is actually enqueued: |
||||
|
|
||||
|
```bash |
||||
|
adb shell dumpsys job scheduler | grep -A 5 "daily_notification_fetch" |
||||
|
``` |
||||
|
|
||||
|
### 3. Check if Notification Scheduling Succeeded |
||||
|
|
||||
|
Verify the notification scheduling succeeded (this is a prerequisite): |
||||
|
|
||||
|
```bash |
||||
|
adb logcat | grep "DN|SCHEDULE" |
||||
|
``` |
||||
|
|
||||
|
Look for: |
||||
|
- `DN|SCHEDULE_CALLBACK scheduled=true` - **Good**, prefetch will be scheduled |
||||
|
- `DN|SCHEDULE_CALLBACK scheduled=false` - **Bad**, prefetch will NOT be scheduled |
||||
|
|
||||
|
### 4. Check AlarmManager Schedule |
||||
|
|
||||
|
Verify the actual alarm is set: |
||||
|
|
||||
|
```bash |
||||
|
adb shell dumpsys alarm | grep -i "dailynotification" |
||||
|
``` |
||||
|
|
||||
|
## Investigation Checklist |
||||
|
|
||||
|
To diagnose why prefetch logs aren't appearing: |
||||
|
|
||||
|
- [ ] Check if notification scheduling is succeeding (look for `DN|SCHEDULE_CALLBACK scheduled=true`) |
||||
|
- [ ] Check if `scheduleBackgroundFetch` is being called (look for `DN|SCHEDULE_FETCH_START`) |
||||
|
- [ ] Check if fetch time calculation is correct (look for `DN|SCHEDULE_FETCH_CALC`) |
||||
|
- [ ] Check if WorkManager is enqueuing the work (look for "Background fetch scheduled successfully") |
||||
|
- [ ] Check if fetch time is in the past (look for "Fetch time has already passed") |
||||
|
- [ ] Check WorkManager queue status via `dumpsys job scheduler` |
||||
|
- [ ] Check for any exceptions (look for "DN|SCHEDULE_FETCH_ERR" or "Error scheduling background fetch") |
||||
|
|
||||
|
## Recommendations |
||||
|
|
||||
|
### 1. Add More Diagnostic Logging |
||||
|
|
||||
|
Add logs at critical decision points: |
||||
|
|
||||
|
```java |
||||
|
// In scheduleDailyNotification, after scheduler.scheduleNotification() |
||||
|
if (scheduled) { |
||||
|
Log.i(TAG, "DN|SCHEDULE_CALLBACK scheduled=true, calling scheduleBackgroundFetch"); |
||||
|
Log.d(TAG, "DN|SCHEDULE_CALLBACK content.getScheduledTime()=" + content.getScheduledTime()); |
||||
|
scheduleBackgroundFetch(content.getScheduledTime()); |
||||
|
} else { |
||||
|
Log.w(TAG, "DN|SCHEDULE_CALLBACK scheduled=false, NOT calling scheduleBackgroundFetch"); |
||||
|
} |
||||
|
``` |
||||
|
|
||||
|
### 2. Add WorkManager Status Logging |
||||
|
|
||||
|
Add a log after enqueuing to verify: |
||||
|
|
||||
|
```java |
||||
|
workManager.enqueue(fetchWork); |
||||
|
Log.i(TAG, "DN|SCHEDULE_WORK_ENQUEUED work_id=" + fetchWork.getId() + |
||||
|
" fetch_at=" + fetchTime + " delay_ms=" + (fetchTime - System.currentTimeMillis())); |
||||
|
``` |
||||
|
|
||||
|
### 3. Add User-Zero Specific Logging |
||||
|
|
||||
|
For stars querying, add specific event IDs: |
||||
|
|
||||
|
```java |
||||
|
Log.i(TAG, "EVT_PREFETCH_SCHEDULED time=" + fetchTime + " stars_query=true"); |
||||
|
``` |
||||
|
|
||||
|
## Next Steps |
||||
|
|
||||
|
1. **Capture logcat** during notification scheduling |
||||
|
2. **Search for specific log prefixes** documented above |
||||
|
3. **Check WorkManager queue** to verify work is enqueued |
||||
|
4. **Add diagnostic logging** if needed |
||||
|
5. **Test with actual notification scheduling** to see full flow |
||||
|
|
||||
|
## Conclusion |
||||
|
|
||||
|
The prefetch scheduling **IS implemented** in the codebase. The issue is likely one of: |
||||
|
|
||||
|
- Logging visibility (logs not being captured) |
||||
|
- Timing issues (fetch time in past) |
||||
|
- Notification scheduling failure (prefetch not called) |
||||
|
- WorkManager not executing (system-level issue) |
||||
|
|
||||
|
The infrastructure is there, but we need to verify the execution path. |
||||
Loading…
Reference in new issue