fix: NFO timestamp consistency and enhanced episode processing debug

NFO Management Timestamp Fix:
- Fix NFO management comments to use local timezone instead of UTC
- Both movie and TV episode NFO files now show consistent local timezone
- Comments now show: <!-- managed by NFOGuard at 2025-09-14T09:29:06-04:00 -->

Enhanced Episode Processing Debug:
- Add comprehensive debug logging for webhook episode database lookups
- Track IMDb ID and season/episode info throughout processing pipeline
- Add database write verification to catch storage issues immediately
- Enhanced logging will help identify duplicate processing root causes

This addresses the issue where episodes were being treated as new downloads
instead of finding existing database entries, helping prevent duplicate processing.
This commit is contained in:
2025-09-14 10:27:05 -04:00
parent 7af7b1c43e
commit d8754e41a7
4 changed files with 51 additions and 9 deletions
+25 -1
View File
@@ -269,6 +269,30 @@ sonarr-nfo-cache | [2025-09-14T09:37:00-04:00] INFO: Batched movie webhook...
---
---
### 🆕 v0.6.6 NFO Timestamp & Duplicate Processing Fixes (September 2025)
**🕰️ NFO Management Timestamp Fix:**
- **Problem**: NFO management comments still showed UTC timestamps despite container timezone setting
- **Fix**: All NFO file comments now respect local timezone
- **Before**: `<!-- managed by NFOGuard at 2025-09-14T13:29:06+00:00 -->`
- **After**: `<!-- managed by NFOGuard at 2025-09-14T09:29:06-04:00 -->`
**🔍 Enhanced Episode Processing Debug:**
- **Enhanced Logging**: Added comprehensive debug logging for episode database lookups
- **Duplicate Detection**: Improved tracking of why episodes might be processed multiple times
- **Database Verification**: Added verification logging after database writes
- **IMDb ID Tracking**: Enhanced logging shows IMDb ID in processing messages
**🛠️ Technical Improvements:**
- **NFO Manager**: Updated both movie and TV episode NFO timestamp generation
- **Webhook Processing**: Added detailed debug logging for episode lookup failures
- **Database Integrity**: Added immediate verification of database writes
- **Troubleshooting Ready**: Enhanced logging will help identify duplicate processing causes
---
**Last Updated:** September 14, 2025
**Version:** v0.6.5
**Version:** v0.6.6
**Status:** Enhanced Production Ready
+1 -1
View File
@@ -1 +1 @@
0.6.5
0.6.6
+5 -3
View File
@@ -9,7 +9,7 @@ from datetime import datetime, timezone
from typing import Optional, Dict, Any
import xml.etree.ElementTree as ET
from core.logging import _log
from core.logging import _log, _get_local_timezone
class NFOManager:
@@ -194,7 +194,8 @@ class NFOManager:
# Add footer comments with timestamp
self._strip_existing_footer_comments(root)
current_time = datetime.now(timezone.utc).isoformat(timespec="seconds")
local_tz = _get_local_timezone()
current_time = datetime.now(local_tz).isoformat(timespec="seconds")
root.append(ET.Comment(f" source: Movie; {source_detail} "))
root.append(ET.Comment(f" managed by {self.manager_brand} at {current_time} "))
@@ -289,7 +290,8 @@ class NFOManager:
# Add source comments with timestamp
if source_detail:
current_time = datetime.now(timezone.utc).isoformat(timespec="seconds")
local_tz = _get_local_timezone()
current_time = datetime.now(local_tz).isoformat(timespec="seconds")
xml_lines.append(f" <!-- source: TV Episode; {source_detail} -->")
xml_lines.append(f" <!-- managed by {self.manager_brand} at {current_time} -->")
+19 -3
View File
@@ -755,7 +755,7 @@ class TVProcessor:
self.process_series(series_path)
return
_log("INFO", f"Processing {len(webhook_episodes)} webhook episodes for: {series_path.name}")
_log("INFO", f"Processing {len(webhook_episodes)} webhook episodes for: {series_path.name} (IMDb: {imdb_id})")
# Update database
self.db.upsert_series(imdb_id, str(series_path))
@@ -791,6 +791,7 @@ class TVProcessor:
continue
# Get episode date information - webhook processing prioritizes existing DB entries
_log("DEBUG", f"Processing webhook episode: IMDb={imdb_id}, S{season_num:02d}E{episode_num:02d}")
aired, dateadded, source = self._get_webhook_episode_date(imdb_id, season_num, episode_num, series_metadata)
enhanced_metadata = self._get_episode_metadata(series_metadata, season_num, episode_num) if series_metadata else None
@@ -809,6 +810,14 @@ class TVProcessor:
# Save to database
self.db.upsert_episode_date(imdb_id, season_num, episode_num, aired, dateadded, source, True)
# Verify database entry was saved (debug)
verification = self.db.get_episode_date(imdb_id, season_num, episode_num)
if verification:
_log("DEBUG", f"Verified database entry saved: S{season_num:02d}E{episode_num:02d} -> {verification['dateadded']}")
else:
_log("ERROR", f"Failed to save episode to database: S{season_num:02d}E{episode_num:02d}")
episodes_processed += 1
# Create season/tvshow NFOs if any episodes were processed
@@ -836,10 +845,17 @@ class TVProcessor:
3. Get aired date from Sonarr/TMDB for reference
"""
# Step 1: Check if we already have this episode in our database
_log("DEBUG", f"Checking database for existing episode: IMDb={imdb_id}, S{season_num:02d}E{episode_num:02d}")
existing = self.db.get_episode_date(imdb_id, season_num, episode_num)
if existing and existing.get("dateadded"):
_log("INFO", f"Using existing database entry for S{season_num:02d}E{episode_num:02d}: {existing['dateadded']}")
if existing:
_log("DEBUG", f"Found database entry: {existing}")
if existing.get("dateadded"):
_log("INFO", f"Using existing database entry for S{season_num:02d}E{episode_num:02d}: {existing['dateadded']} (source: {existing.get('source', 'unknown')})")
return existing.get("aired"), existing["dateadded"], existing.get("source", "database:existing")
else:
_log("DEBUG", f"Database entry found but no dateadded value: {existing}")
else:
_log("DEBUG", f"No database entry found for IMDb={imdb_id}, S{season_num:02d}E{episode_num:02d}")
# Step 2: This is a new download (webhook triggered) - use current time in local timezone
local_tz = _get_local_timezone()