chore: add diagnostic logging for predicted rating lifecycle (#11)
Add structured Pino logging across four hot-spots to make the
predicted rating data-loss visible in production logs:
- rating-calculator.js: log on calculation start, each 0-return early
exit (no_rounds / no_rounds_after_date_filter / no_eligible_rounds),
and on successful calculation with full algorithm branch metadata.
Accepts optional context={pdgaNumber,callsite} to correlate logs.
- models/player.js: savePlayerToDB now logs before INSERT OR REPLACE,
explicitly naming the derived columns that will be reset to NULL.
savePredictedRatingToDB reads the old value first and emits a warn
when a positive predicted_rating is overwritten with 0.
- services/player-service.js: structured debug/info/warn logs in
getPlayerDataFromDB (lazy recompute trigger, failed recompute) and
getPredictedRatingFromDB (no round history, 0 despite having rounds).
- routes/players.js: refresh-round-history route now logs each step
(official_history_scrape, rounds_scrape_save, predicted_calc) with
success/count fields; outer catch uses structured error log.
refresh-all and refresh-player log their INSERT OR REPLACE trigger.
Also adds GET /api/admin/player-state/:pdgaNumber — a read-only
diagnostic endpoint returning raw DB columns plus round count and
date-window breakdowns.
Closes #11
This commit is contained in:
Samuel Enocsson
+23
-9
@@ -1,5 +1,6 @@
|
||||
const { db } = require('../db');
|
||||
const { parseDate } = require('../services/rating-calculator');
|
||||
const logger = require('../logger');
|
||||
|
||||
function getPlayerFromDB(pdgaNumber) {
|
||||
return new Promise((resolve, reject) => {
|
||||
@@ -16,6 +17,7 @@ function getPlayerFromDB(pdgaNumber) {
|
||||
|
||||
function savePlayerToDB(playerData) {
|
||||
return new Promise((resolve, reject) => {
|
||||
logger.info({ pdgaNumber: playerData.pdgaNumber, name: playerData.name, currentRating: playerData.rating, ratingChange: playerData.ratingChange, resetColumns: ['predicted_rating', 'std_dev', 'excluded_rounds_count', 'cutoff_rating', 'last_round_update'] }, 'INSERT OR REPLACE on players — derived columns will be reset to NULL');
|
||||
db.run(
|
||||
`INSERT OR REPLACE INTO players (pdga_number, name, current_rating, rating_change, last_updated)
|
||||
VALUES (?, ?, ?, ?, datetime('now'))`,
|
||||
@@ -172,16 +174,28 @@ function saveRoundHistoryToDB(pdgaNumber, roundData, isIncremental = false) {
|
||||
});
|
||||
}
|
||||
|
||||
function savePredictedRatingToDB(pdgaNumber, predictedRating, stdDev = null, excludedRoundsCount = null, cutoffRating = null) {
|
||||
function savePredictedRatingToDB(pdgaNumber, predictedRating, stdDev = null, excludedRoundsCount = null, cutoffRating = null, callsite = 'unknown') {
|
||||
return new Promise((resolve, reject) => {
|
||||
db.run(
|
||||
'UPDATE players SET predicted_rating = ?, std_dev = ?, excluded_rounds_count = ?, cutoff_rating = ? WHERE pdga_number = ?',
|
||||
[predictedRating, stdDev, excludedRoundsCount, cutoffRating, pdgaNumber],
|
||||
function(err) {
|
||||
if (err) reject(err);
|
||||
else resolve();
|
||||
}
|
||||
);
|
||||
db.get('SELECT predicted_rating AS oldValue FROM players WHERE pdga_number = ?', [pdgaNumber], (selectErr, row) => {
|
||||
if (selectErr) return reject(selectErr);
|
||||
const oldValue = row ? row.oldValue : null;
|
||||
|
||||
db.run(
|
||||
'UPDATE players SET predicted_rating = ?, std_dev = ?, excluded_rounds_count = ?, cutoff_rating = ? WHERE pdga_number = ?',
|
||||
[predictedRating, stdDev, excludedRoundsCount, cutoffRating, pdgaNumber],
|
||||
function(err) {
|
||||
if (err) return reject(err);
|
||||
|
||||
const logData = { pdgaNumber, oldValue, newValue: predictedRating, callsite };
|
||||
if (predictedRating === 0 && oldValue != null && oldValue > 0) {
|
||||
logger.warn(logData, 'predicted rating overwritten with 0');
|
||||
} else {
|
||||
logger.info(logData, 'predicted rating saved');
|
||||
}
|
||||
resolve();
|
||||
}
|
||||
);
|
||||
});
|
||||
});
|
||||
}
|
||||
|
||||
|
||||
+61
-25
@@ -19,6 +19,7 @@ router.post('/api/refresh-all', async (req, res, next) => {
|
||||
return res.status(409).json({ error: 'Refresh already in progress' });
|
||||
}
|
||||
refreshInProgress = true;
|
||||
logger.info({ pdgaNumber: 'all' }, 'refresh-all triggered — will invoke savePlayerToDB for all players (INSERT OR REPLACE wipes derived columns)');
|
||||
try {
|
||||
try {
|
||||
await refreshAllPlayersInDB();
|
||||
@@ -253,7 +254,7 @@ router.post('/api/add-player', async (req, res) => {
|
||||
router.post('/api/refresh-player/:pdgaNumber', async (req, res) => {
|
||||
try {
|
||||
const { pdgaNumber } = req.params;
|
||||
logger.info(`Manually refreshing player data for PDGA ${pdgaNumber}`);
|
||||
logger.info({ pdgaNumber }, 'refresh-player triggered — will invoke savePlayerToDB (INSERT OR REPLACE wipes derived columns)');
|
||||
|
||||
const html = await fetchPlayerDataHTTP(pdgaNumber);
|
||||
const playerData = parsePlayerData(html, pdgaNumber);
|
||||
@@ -349,48 +350,45 @@ router.post('/api/refresh-round-history/:pdgaNumber', async (req, res) => {
|
||||
|
||||
const isIncremental = !!sinceDate;
|
||||
|
||||
logger.info(`${isIncremental ? 'Incrementally updating' : 'Fully refreshing'} round history for PDGA ${pdgaNumber}${sinceDate ? ` since ${sinceDate.toDateString()}` : ''}`);
|
||||
logger.info({ pdgaNumber, lastRoundUpdate, isIncremental }, 'refresh-round-history started');
|
||||
|
||||
browser = await launchBrowser();
|
||||
|
||||
|
||||
let officialHistory;
|
||||
try {
|
||||
officialHistory = await getOfficialRatingHistory(browser, pdgaNumber);
|
||||
if (officialHistory.length > 0) {
|
||||
await saveRatingHistoryToDB(pdgaNumber, officialHistory);
|
||||
}
|
||||
logger.info({ pdgaNumber, step: 'official_history_scrape', success: officialHistory.length > 0, count: officialHistory.length }, 'official history scrape completed');
|
||||
} catch (historyError) {
|
||||
logger.error('Failed to fetch official history:', historyError.message);
|
||||
logger.warn({ pdgaNumber, step: 'official_history_scrape', success: false, error: historyError.message }, 'official history scrape failed');
|
||||
officialHistory = [];
|
||||
}
|
||||
|
||||
|
||||
let allRounds = [];
|
||||
try {
|
||||
logger.info(`Using optimized approach: /details + new tournaments only for PDGA ${pdgaNumber}...`);
|
||||
allRounds = await getOptimizedPlayerRounds(browser, pdgaNumber);
|
||||
|
||||
|
||||
if (allRounds.length > 0) {
|
||||
const roundsForDB = allRounds.map(round => ({
|
||||
rating: round.rating,
|
||||
date: round.date,
|
||||
competition: round.competition
|
||||
}));
|
||||
|
||||
|
||||
await saveRoundHistoryToDB(pdgaNumber, roundsForDB, false);
|
||||
logger.info(`✓ Saved ${allRounds.length} rounds using optimized approach`);
|
||||
|
||||
await updateLastRoundUpdateDate(pdgaNumber);
|
||||
} else {
|
||||
logger.info('ℹ No rounds found');
|
||||
}
|
||||
logger.info({ pdgaNumber, step: 'rounds_scrape_save', success: allRounds.length > 0, count: allRounds.length, lastRoundUpdateTouched: allRounds.length > 0 }, 'rounds scrape and save completed');
|
||||
} catch (detailsError) {
|
||||
logger.error('Failed to fetch rounds using optimized approach:', detailsError.message);
|
||||
logger.warn({ pdgaNumber, step: 'rounds_scrape_save', success: false, error: detailsError.message }, 'rounds scrape and save failed');
|
||||
allRounds = [];
|
||||
}
|
||||
|
||||
|
||||
await browser.close();
|
||||
browser = null;
|
||||
|
||||
|
||||
const dbRounds = await getRoundHistoryFromDB(pdgaNumber);
|
||||
const roundsForPrediction = dbRounds.map(round => ({
|
||||
rating: round.rating,
|
||||
@@ -398,9 +396,10 @@ router.post('/api/refresh-round-history/:pdgaNumber', async (req, res) => {
|
||||
competition: round.competition_name
|
||||
}));
|
||||
|
||||
const result = calculatePredictedRating(roundsForPrediction);
|
||||
const result = calculatePredictedRating(roundsForPrediction, { pdgaNumber, callsite: 'refresh-round-history' });
|
||||
logger.info({ pdgaNumber, step: 'predicted_calc', rating: result.rating, stdDev: result.stdDev, excludedRoundsCount: result.excludedRoundsCount }, 'predicted rating calculation step completed');
|
||||
|
||||
await savePredictedRatingToDB(pdgaNumber, result.rating, result.stdDev, result.excludedRoundsCount, result.cutoffRating);
|
||||
await savePredictedRatingToDB(pdgaNumber, result.rating, result.stdDev, result.excludedRoundsCount, result.cutoffRating, 'refresh-round-history');
|
||||
|
||||
const officialCount = allRounds.filter(r => r.source === 'official').length;
|
||||
const newCount = allRounds.filter(r => r.source === 'new').length;
|
||||
@@ -418,10 +417,8 @@ router.post('/api/refresh-round-history/:pdgaNumber', async (req, res) => {
|
||||
message: `Used /details (${officialCount} rounds) + new tournaments (${newCount} rounds)`
|
||||
});
|
||||
} catch (error) {
|
||||
logger.error(`=== Error refreshing round history for PDGA ${pdgaNumber} ===`);
|
||||
logger.error('Error type:', error.constructor.name);
|
||||
logger.error('Error message:', error.message);
|
||||
|
||||
logger.error({ pdgaNumber, step: 'unknown_or_orchestration', errorType: error.constructor.name, errorMessage: error.message }, 'refresh-round-history failed');
|
||||
|
||||
if (browser) {
|
||||
try {
|
||||
await browser.close();
|
||||
@@ -429,14 +426,14 @@ router.post('/api/refresh-round-history/:pdgaNumber', async (req, res) => {
|
||||
logger.error('Error closing browser:', closeError.message);
|
||||
}
|
||||
}
|
||||
|
||||
res.status(500).json({
|
||||
|
||||
res.status(500).json({
|
||||
error: 'Failed to refresh round history',
|
||||
details: error.message,
|
||||
errorType: error.constructor.name,
|
||||
timestamp: new Date().toISOString(),
|
||||
suggestion: error.message.includes('socket hang up') ?
|
||||
'Rate limited by PDGA - try again in a few minutes.' :
|
||||
suggestion: error.message.includes('socket hang up') ?
|
||||
'Rate limited by PDGA - try again in a few minutes.' :
|
||||
error.message.includes('timeout') ?
|
||||
'PDGA pages are loading slowly - try again later.' :
|
||||
'Tournament scraping failed - check server logs for details'
|
||||
@@ -444,6 +441,45 @@ router.post('/api/refresh-round-history/:pdgaNumber', async (req, res) => {
|
||||
}
|
||||
});
|
||||
|
||||
router.get('/api/admin/player-state/:pdgaNumber', async (req, res) => {
|
||||
const { pdgaNumber } = req.params;
|
||||
try {
|
||||
const player = await getPlayerFromDB(pdgaNumber);
|
||||
if (!player) {
|
||||
return res.status(404).json({ error: 'Player not found', pdgaNumber: parseInt(pdgaNumber) });
|
||||
}
|
||||
const rounds = await getRoundHistoryFromDB(pdgaNumber);
|
||||
const now = new Date();
|
||||
const twelveMonthsAgo = new Date(now); twelveMonthsAgo.setFullYear(now.getFullYear() - 1);
|
||||
const twentyFourMonthsAgo = new Date(now); twentyFourMonthsAgo.setFullYear(now.getFullYear() - 2);
|
||||
|
||||
const roundsInLast12mo = rounds.filter(r => new Date(r.date) >= twelveMonthsAgo).length;
|
||||
const roundsInLast24mo = rounds.filter(r => new Date(r.date) >= twentyFourMonthsAgo).length;
|
||||
const dates = rounds.map(r => r.date).sort();
|
||||
|
||||
res.json({
|
||||
pdgaNumber: player.pdga_number,
|
||||
name: player.name,
|
||||
currentRating: player.current_rating,
|
||||
ratingChange: player.rating_change,
|
||||
predictedRating: player.predicted_rating,
|
||||
stdDev: player.std_dev,
|
||||
excludedRoundsCount: player.excluded_rounds_count,
|
||||
cutoffRating: player.cutoff_rating,
|
||||
lastUpdated: player.last_updated,
|
||||
lastRoundUpdate: player.last_round_update,
|
||||
roundCount: rounds.length,
|
||||
roundsInLast12mo,
|
||||
roundsInLast24mo,
|
||||
oldestRound: dates[0] ?? null,
|
||||
newestRound: dates[dates.length - 1] ?? null
|
||||
});
|
||||
} catch (err) {
|
||||
logger.error({ err: err.message, pdgaNumber }, 'admin player-state endpoint failed');
|
||||
res.status(500).json({ error: 'Failed to fetch player state', details: err.message });
|
||||
}
|
||||
});
|
||||
|
||||
router.post('/api/calculate-target-rating/:pdgaNumber', async (req, res) => {
|
||||
const { pdgaNumber } = req.params;
|
||||
const pdgaNum = parseInt(pdgaNumber, 10);
|
||||
|
||||
@@ -36,22 +36,29 @@ async function getPlayerDataFromDB(pdgaNumber, { includeMonthlyHistory = true }
|
||||
try {
|
||||
const cachedPlayer = await getPlayerFromDB(pdgaNumber);
|
||||
if (cachedPlayer) {
|
||||
logger.debug(`Loading PDGA ${pdgaNumber} from DB (source of truth)`);
|
||||
logger.debug({ pdgaNumber }, 'Loading player from DB (source of truth)');
|
||||
|
||||
let predictedRating = cachedPlayer.predicted_rating;
|
||||
let stdDev = cachedPlayer.std_dev;
|
||||
let excludedRoundsCount = cachedPlayer.excluded_rounds_count;
|
||||
let cutoffRating = cachedPlayer.cutoff_rating;
|
||||
if (!predictedRating || predictedRating === 0) {
|
||||
logger.debug({ pdgaNumber, dbValue: cachedPlayer.predicted_rating }, 'lazy recompute triggered for predicted_rating');
|
||||
predictedRating = await getPredictedRatingFromDB(pdgaNumber);
|
||||
const updatedPlayer = await getPlayerFromDB(pdgaNumber);
|
||||
stdDev = updatedPlayer?.std_dev;
|
||||
excludedRoundsCount = updatedPlayer?.excluded_rounds_count;
|
||||
cutoffRating = updatedPlayer?.cutoff_rating;
|
||||
if (!predictedRating || predictedRating === 0) {
|
||||
logger.info({ pdgaNumber, recomputedValue: predictedRating }, 'lazy recompute did not yield a positive predicted rating');
|
||||
}
|
||||
}
|
||||
|
||||
const rating = cachedPlayer.current_rating;
|
||||
const rawRatingChange = cachedPlayer.rating_change;
|
||||
if (predictedRating != null && predictedRating <= 0) {
|
||||
logger.warn({ pdgaNumber, dbValue: predictedRating }, 'predicted rating present but <= 0 — rendered as empty');
|
||||
}
|
||||
const resolvedPredicted = predictedRating > 0 ? predictedRating : null;
|
||||
const resolvedStdDev = stdDev > 0 ? stdDev : null;
|
||||
|
||||
@@ -140,22 +147,28 @@ async function scrapePDGARating(pdgaNumber, retries = 3) {
|
||||
async function getPredictedRatingFromDB(pdgaNumber) {
|
||||
try {
|
||||
const roundHistory = await getRoundHistoryFromDB(pdgaNumber);
|
||||
if (roundHistory.length > 0) {
|
||||
logger.debug(`Using ${roundHistory.length} cached rounds for PDGA ${pdgaNumber} prediction`);
|
||||
|
||||
const roundRatings = roundHistory.map(round => ({
|
||||
rating: round.rating,
|
||||
date: new Date(round.date),
|
||||
competition: round.competition_name || 'Unknown'
|
||||
}));
|
||||
|
||||
const result = calculatePredictedRating(roundRatings);
|
||||
|
||||
await savePredictedRatingToDB(pdgaNumber, result.rating, result.stdDev, result.excludedRoundsCount, result.cutoffRating);
|
||||
|
||||
return result.rating;
|
||||
if (roundHistory.length === 0) {
|
||||
logger.info({ pdgaNumber, reason: 'no_round_history_in_db' }, 'predicted recompute returning 0 — no round history available');
|
||||
return 0;
|
||||
}
|
||||
return 0;
|
||||
|
||||
logger.debug({ pdgaNumber, cachedRounds: roundHistory.length }, 'Using cached rounds for prediction');
|
||||
|
||||
const roundRatings = roundHistory.map(round => ({
|
||||
rating: round.rating,
|
||||
date: new Date(round.date),
|
||||
competition: round.competition_name || 'Unknown'
|
||||
}));
|
||||
|
||||
const result = calculatePredictedRating(roundRatings, { pdgaNumber, callsite: 'getPredictedRatingFromDB' });
|
||||
|
||||
if (result.rating === 0) {
|
||||
logger.warn({ pdgaNumber, roundsInDb: roundHistory.length }, 'predicted recompute returned 0 despite having rounds in DB');
|
||||
}
|
||||
|
||||
await savePredictedRatingToDB(pdgaNumber, result.rating, result.stdDev, result.excludedRoundsCount, result.cutoffRating, 'lazy-recompute');
|
||||
|
||||
return result.rating;
|
||||
} catch (err) {
|
||||
logger.error(`Error getting predicted rating from DB for ${pdgaNumber}:`, err.message);
|
||||
return 0;
|
||||
|
||||
@@ -1,3 +1,5 @@
|
||||
const logger = require('../logger');
|
||||
|
||||
function parseDate(dateStr) {
|
||||
const multiDayMatch = dateStr.match(/^(\d{1,2})(-([A-Za-z]{3}))?(\s+to\s+)(\d{1,2})-([A-Za-z]{3})-(\d{4})$/);
|
||||
if (multiDayMatch) {
|
||||
@@ -79,15 +81,19 @@ function calculateStandardDeviation(ratings) {
|
||||
return Math.sqrt(variance);
|
||||
}
|
||||
|
||||
function calculatePredictedRating(roundRatings) {
|
||||
function calculatePredictedRating(roundRatings, context = {}) {
|
||||
const pdgaNumber = context.pdgaNumber ?? null;
|
||||
const callsite = context.callsite ?? 'unknown';
|
||||
const debugLog = [];
|
||||
debugLog.push('=== PDGA RATING CALCULATION (Following Official Rules) ===');
|
||||
|
||||
if (!roundRatings || roundRatings.length === 0) {
|
||||
debugLog.push('❌ No rounds provided for prediction');
|
||||
logger.warn({ pdgaNumber, callsite, reason: 'no_rounds' }, 'predicted rating computed as 0');
|
||||
return { rating: 0, debugLog, excludedRoundsCount: null, cutoffRating: null };
|
||||
}
|
||||
|
||||
logger.info({ pdgaNumber, callsite, inputRounds: roundRatings.length }, 'predicted rating calculation started');
|
||||
debugLog.push(`📊 Starting with ${roundRatings.length} total rounds`);
|
||||
|
||||
const nextUpdateDate = getNextPDGAUpdateDate();
|
||||
@@ -100,6 +106,7 @@ function calculatePredictedRating(roundRatings) {
|
||||
|
||||
if (allSortedRounds.length === 0) {
|
||||
debugLog.push('❌ No valid rounds after filtering for update date');
|
||||
logger.warn({ pdgaNumber, callsite, reason: 'no_rounds_after_date_filter', inputRounds: roundRatings.length, nextUpdateDate: nextUpdateDate.toISOString() }, 'predicted rating computed as 0');
|
||||
return { rating: 0, debugLog, excludedRoundsCount: null, cutoffRating: null };
|
||||
}
|
||||
|
||||
@@ -117,8 +124,9 @@ function calculatePredictedRating(roundRatings) {
|
||||
debugLog.push('🗓️ 12-MONTH FILTERING:');
|
||||
debugLog.push(`✅ Rounds in last 12 months: ${eligibleRounds.length}`);
|
||||
|
||||
let twentyFourMonthsBeforeUpdate = null;
|
||||
if (eligibleRounds.length < 8) {
|
||||
const twentyFourMonthsBeforeUpdate = new Date(nextUpdateDate);
|
||||
twentyFourMonthsBeforeUpdate = new Date(nextUpdateDate);
|
||||
twentyFourMonthsBeforeUpdate.setFullYear(twentyFourMonthsBeforeUpdate.getFullYear() - 2);
|
||||
|
||||
eligibleRounds = allSortedRounds.filter(r => r.date >= twentyFourMonthsBeforeUpdate);
|
||||
@@ -127,6 +135,7 @@ function calculatePredictedRating(roundRatings) {
|
||||
|
||||
if (eligibleRounds.length === 0) {
|
||||
debugLog.push('❌ No eligible rounds found');
|
||||
logger.warn({ pdgaNumber, callsite, reason: 'no_eligible_rounds', afterDateFilter: allSortedRounds.length, twelveMonthCutoff: twelveMonthsBeforeUpdate.toISOString(), twentyFourMonthCutoff: twentyFourMonthsBeforeUpdate ? twentyFourMonthsBeforeUpdate.toISOString() : null }, 'predicted rating computed as 0');
|
||||
return { rating: 0, debugLog, excludedRoundsCount: null, cutoffRating: null };
|
||||
}
|
||||
|
||||
@@ -235,6 +244,19 @@ function calculatePredictedRating(roundRatings) {
|
||||
debugLog.push(` Final Rating: ${finalRating}`);
|
||||
debugLog.push('=== END PDGA CALCULATION ===');
|
||||
|
||||
logger.info({
|
||||
pdgaNumber,
|
||||
callsite,
|
||||
finalRating,
|
||||
inputRounds: roundRatings.length,
|
||||
afterDateFilter: allSortedRounds.length,
|
||||
eligibleRounds: eligibleRounds.length,
|
||||
outlierExclusionApplied: workingRatings.length >= 7,
|
||||
doubleWeightingApplied: workingRatings.length >= 9,
|
||||
excludedRoundsCount,
|
||||
cutoffRating
|
||||
}, 'predicted rating calculated');
|
||||
|
||||
return { rating: finalRating, stdDev: Math.round(stdDev), debugLog, excludedRoundsCount, cutoffRating };
|
||||
}
|
||||
|
||||
|
||||
@@ -8,7 +8,7 @@ function calculateRequiredAverage(roundRatings, targetRating, numRounds) {
|
||||
throw err;
|
||||
}
|
||||
|
||||
const currentPredicted = calculatePredictedRating(roundRatings).rating;
|
||||
const currentPredicted = calculatePredictedRating(roundRatings, { callsite: 'target-rating-calculator' }).rating;
|
||||
const nextUpdate = getNextPDGAUpdateDate();
|
||||
const syntheticDate = new Date(nextUpdate.getTime() - 24 * 60 * 60 * 1000);
|
||||
|
||||
|
||||
Reference in New Issue
Block a user