forked from trent_larson/crowd-funder-for-time-pwa
28a825a460
Add comprehensive instrumentation to diagnose why native fetcher is not being called during prefetch operations. Instrumentation Added: - TimeSafariApplication: Log app initialization, fetcher registration, and verification with process ID and timestamps - TimeSafariNativeFetcher: Log configuration, fetch start, source resolution (native vs fallback), and write completion - Diagnostic script: Filter logcat for prefetch-related events - Investigation summary: Document root cause hypotheses and diagnostic checklist Log Tags: - APP|ON_CREATE: App initialization timing and process info - FETCHER|REGISTER_START/REGISTERED: Fetcher registration lifecycle - FETCHER|CONFIGURE_START/CONFIGURE_COMPLETE: Configuration tracking - PREFETCH|START/SOURCE/WRITE_OK: Prefetch operation tracking - DISPLAY|START/LOOKUP: Display worker tracking (future) - STORAGE|POST_PREFETCH/PRE_DISPLAY: Storage verification (future) This instrumentation will help diagnose: 1. Registration timing issues (worker before onCreate) 2. Fetcher resolution failures (null fetcher) 3. Process mismatches (multi-process issues) 4. ID schema inconsistencies (prefetch vs display) 5. Storage persistence issues (content not saved) Author: Matthew Raymer
110 lines
4.2 KiB
Markdown
110 lines
4.2 KiB
Markdown
# Prefetch Investigation Summary
|
|
|
|
## Problem Statement
|
|
|
|
The daily notification prefetch job (T-5 min) is not calling the native fetcher, resulting in:
|
|
- `from: null` in prefetch logs
|
|
- Fallback/mock content being used
|
|
- `DISPLAY_SKIP content_not_found` at notification time
|
|
- Storage empty (`[]`) when display worker runs
|
|
|
|
## Root Cause Hypothesis
|
|
|
|
Based on the directive analysis, likely causes (ranked):
|
|
|
|
1. **Registration Timing**: Prefetch worker runs before `Application.onCreate()` completes
|
|
2. **Discovery Failure**: Worker resolves fetcher to `null` (wrong scope, process mismatch)
|
|
3. **Persistence Bug**: Content written but wiped/deduped before display
|
|
4. **ID Mismatch**: Prefetch writes `notify_...` but display looks for `daily_...`
|
|
|
|
## Instrumentation Added
|
|
|
|
### TimeSafariApplication.java
|
|
- `APP|ON_CREATE ts=... pid=... processName=...` - App initialization timing
|
|
- `FETCHER|REGISTER_START instanceHash=... ts=...` - Before registration
|
|
- `FETCHER|REGISTERED providerKey=... instanceHash=... registered=... ts=...` - After registration with verification
|
|
|
|
### TimeSafariNativeFetcher.java
|
|
- `FETCHER|CONFIGURE_START instanceHash=... pid=... ts=...` - Configuration start
|
|
- `FETCHER|CONFIGURE_COMPLETE instanceHash=... configured=... apiBaseUrl=... activeDid=... jwtLength=... ts=...` - Configuration completion
|
|
- `PREFETCH|START id=... notifyAt=... trigger=... instanceHash=... pid=... ts=...` - Fetch start
|
|
- `PREFETCH|SOURCE from=native/fallback reason=... ts=...` - Source resolution
|
|
- `PREFETCH|WRITE_OK id=... items=... ts=...` - Successful fetch
|
|
|
|
## Diagnostic Tools
|
|
|
|
### Log Filtering Script
|
|
```bash
|
|
./scripts/diagnose-prefetch.sh app.timesafari.app
|
|
```
|
|
|
|
Filters logcat for:
|
|
- `APP|ON_CREATE`
|
|
- `FETCHER|*`
|
|
- `PREFETCH|*`
|
|
- `DISPLAY|*`
|
|
- `STORAGE|*`
|
|
|
|
### Manual Filtering
|
|
```bash
|
|
adb logcat | grep -E "APP\|ON_CREATE|FETCHER\||PREFETCH\||DISPLAY\||STORAGE\|"
|
|
```
|
|
|
|
## Investigation Checklist
|
|
|
|
### A. App/Plugin Initialization Order
|
|
- [ ] Confirm `APP|ON_CREATE` appears before `PREFETCH|START`
|
|
- [ ] Verify `FETCHER|REGISTERED registered=true`
|
|
- [ ] Check for multiple `onCreate` invocations (process restarts)
|
|
- [ ] Confirm single process (no `android:process` on workers)
|
|
|
|
### B. Prefetch Worker Resolution
|
|
- [ ] Check `PREFETCH|SOURCE from=native` (not `from=fallback`)
|
|
- [ ] Verify `instanceHash` matches between registration and fetch
|
|
- [ ] Compare `pid` values (should be same process)
|
|
- [ ] Check `FETCHER|CONFIGURE_COMPLETE configured=true` before prefetch
|
|
|
|
### C. Storage & Persistence
|
|
- [ ] Verify `PREFETCH|WRITE_OK items>=1`
|
|
- [ ] Check storage logs for content persistence
|
|
- [ ] Compare prefetch ID vs display lookup ID (must match)
|
|
|
|
### D. ID Schema Consistency
|
|
- [ ] Prefetch ID format: `daily_<epoch>` or `notify_<epoch>`
|
|
- [ ] Display lookup ID format: must match prefetch ID
|
|
- [ ] Verify ID derivation rules are consistent
|
|
|
|
## Next Steps
|
|
|
|
1. **Run diagnostic script** during a notification cycle
|
|
2. **Analyze logs** for timing issues and process mismatches
|
|
3. **If fetcher is null**: Implement Fix #2 (Pass Fetcher Context With Work) or Fix #3 (Process-Safe DI)
|
|
4. **If ID mismatch**: Normalize ID schema across prefetch and display
|
|
5. **If storage issue**: Add transactional writes and read-after-write verification
|
|
|
|
## Expected Log Flow (Success Case)
|
|
|
|
```
|
|
APP|ON_CREATE ts=... pid=... processName=app.timesafari.app
|
|
FETCHER|REGISTER_START instanceHash=... ts=...
|
|
FETCHER|REGISTERED providerKey=DailyNotificationPlugin instanceHash=... registered=true ts=...
|
|
FETCHER|CONFIGURE_START instanceHash=... pid=... ts=...
|
|
FETCHER|CONFIGURE_COMPLETE instanceHash=... configured=true ... ts=...
|
|
PREFETCH|START id=daily_... notifyAt=... trigger=prefetch instanceHash=... pid=... ts=...
|
|
PREFETCH|SOURCE from=native instanceHash=... apiBaseUrl=... ts=...
|
|
PREFETCH|WRITE_OK id=daily_... items=1 ts=...
|
|
STORAGE|POST_PREFETCH total=1 ids=[daily_...]
|
|
DISPLAY|START id=daily_...
|
|
STORAGE|PRE_DISPLAY total=1 ids=[daily_...]
|
|
DISPLAY|LOOKUP result=hit id=daily_...
|
|
```
|
|
|
|
## Failure Indicators
|
|
|
|
- `PREFETCH|SOURCE from=fallback` - Native fetcher not resolved
|
|
- `PREFETCH|SOURCE from=null` - Fetcher registration failed
|
|
- `FETCHER|REGISTERED registered=false` - Registration verification failed
|
|
- `STORAGE|PRE_DISPLAY total=0` - Content not persisted
|
|
- `DISPLAY|LOOKUP result=miss` - ID mismatch or content cleared
|
|
|