feat(logging): audit trail and progress by jmlrt · Pull Request #35 · jmlrt/spotfm

jmlrt · 2026-03-15T17:00:12Z

Summary

Implements comprehensive logging improvements for visibility and auditability:

Always-on audit log (~/.spotfm/spotfm.log) capturing all track add/remove operations with track IDs for remediation
Default progress output showing real-time feedback on long-running commands without needing flags
Cleaner logging hierarchy with per-entity logs demoted to DEBUG
Graceful error handling for filesystem issues (permission denied, read-only home, etc.)
Documentation updates (CHANGELOG.md, README.md) explaining new features and logging strategy

User-Facing Changes

Progress Output (No Flags Needed)

update-playlists: Shows fetching playlist {id} ({idx}/{total}) + summary
discover-from-playlists: Shows per-playlist discovery counts + total summary
Output to stderr with proper flushing for redirected environments

Audit Log File

Location: ~/.spotfm/spotfm.log (rotating: 1MB max, 3 backups)
Content: All Spotify API calls, DB modifications, track add/remove operations
Format: timestamp LEVEL message with track IDs for remediation
UTF-8 encoding for non-ASCII track/playlist names
Graceful fallback to console-only logging if filesystem unavailable

Logging Hierarchy (After Changes)

Trigger	Destination	Content
Default (no flags)	stderr	Progress output + ERROR/WARNING
`--info`	stderr	+ INFO events (API calls, DB syncs)
`-v`/`--verbose`	stderr	+ DEBUG (per-entity logs, raw SQL)
Always	~/.spotfm/spotfm.log	INFO+ events (audit trail)

Implementation Details

Core Changes

cli.py: Root logger set to INFO, console handler starts at WARNING, both configurable via flags
client.py: Progress output for update-playlists with track count logging
playlist.py: Audit logging in add_tracks() and remove_tracks() with full track IDs and batch progress
misc.py: Command-level context logging + per-playlist progress output in discover_from_playlists
track.py, album.py, artist.py: Per-entity logs demoted to DEBUG (not changed by this PR, already in place)
utils.py: LOG_FILE constant + cache logs demoted to DEBUG

Simplifications (KISS/YAGNI)

Removed command-level file source logging from add/remove-from-file commands (not needed for remediation)
Kept command-level context in discover_from_playlists (complements add_tracks logging)
No configuration required — audit log is always on by default

Review Feedback Addressed

✅ All 9 review comments resolved:

Root logger level set correctly (INFO by default, DEBUG only with -v)
UTF-8 encoding on RotatingFileHandler (handles non-ASCII names)
Filesystem error handling with graceful fallback
Performance: Root logger doesn't create unnecessary LogRecords
Progress message wording standardized ("fetching playlist")
All print statements use flush=True for reliable output
Misleading log messages corrected

Testing & Validation

✅ 319/319 tests passing
✅ No linting violations (ruff)
✅ Coverage: 79.26%
✅ Pre-commit hooks pass
✅ No breaking changes or regressions

Examples

Default behavior (no flags):

fetching playlist abc123 (1/3)
fetching playlist def456 (2/3)
synced 3 playlists (247 total tracks)

With --info (operational debugging):

[... above progress ...]
2026-03-15 14:23:45 INFO Synced 82 tracks from playlist abc123 - My Playlist to database
2026-03-15 14:23:46 INFO Fetching playlist def456 from api
...

Audit log (~/.spotfm/spotfm.log):

2026-03-15 14:23:45 INFO Adding 12 tracks to playlist xyz789 - Discover [track_ids: id1,id2,id3,...]
2026-03-15 14:23:45 INFO Batch: 1/1 (12 tracks)
2026-03-15 14:23:46 INFO Playlist xyz789: successfully added 12/12 tracks

Related Issues

Implements logging improvements from user requirements:

Progress visibility for long-running Spotify commands
Audit trail with track IDs for debugging and remediation
Simplification of per-entity noise
Last.FM logging unaffected

🤖 Generated with Claude Code

## Changes 1. **Always-on audit log** (~/.spotfm/spotfm.log): - Added RotatingFileHandler to cli.py with 1MB file size, 3 backups - Captures INFO level events (API calls, DB changes, operations) - Never rotated off unless explicitly configured 2. **Default visible progress output**: - discover_from_playlists now prints per-playlist progress to stderr - Progress format: "fetching playlist {name} {idx}/{total}" - Summary after all playlists: "total discovered from all playlists: {count}" 3. **Demoted per-entity initialization logs** (INFO -> DEBUG): - Track, Album, Artist, Playlist init: "Initializing {type} {id}" - Cache hits/misses: moved to DEBUG (utils.py) - Per-entity DB lookups: "Track/Album/Artist/Playlist ID {id} not found/retrieved" 4. **Demoted per-track discovery logs** (INFO -> DEBUG): - "New track found: {id}" in discover_from_playlists is now DEBUG - Allows INFO level to focus on operation summaries ## Logging destinations after changes | Destination | Level | Content | Trigger | |---|---|---|---| | stderr (print) | always | progress + summary | default | | ~/.spotfm/spotfm.log | INFO | API calls + DB changes | always | | stderr console | INFO | audit events | --info flag | | stderr console | DEBUG | per-entity noise + raw SQL | -v flag | ## Result - Users see high-level progress by default (no flags needed) - All API and DB changes logged to file for debugging/remediation - --info flag is now useful for operational debugging without entity noise - Tests: all 319 pass; coverage 79.88% Co-Authored-By: Claude Haiku 4.5 <noreply@anthropic.com>

Copilot

Pull request overview

This PR improves SpotFM’s user-facing and diagnostic logging by adding an always-on rotating audit log file, making discover_from_playlists emit progress to stderr by default, and reducing INFO-level noise by demoting per-entity/per-track logs to DEBUG.

Changes:

Add a rotating audit log file at ~/.spotfm/spotfm.log and route INFO+ events into it.
Emit default stderr progress + summary output for discover_from_playlists.
Demote various per-entity initialization/DB/cache logs from INFO to DEBUG to reduce console verbosity.

Reviewed changes

Copilot reviewed 7 out of 7 changed files in this pull request and generated 4 comments.

Show a summary per file

File	Description
`spotfm/cli.py`	Adds a rotating file handler intended to capture audit logs.
`spotfm/utils.py`	Introduces `LOG_FILE` constant; demotes cache hit/miss logs to DEBUG.
`spotfm/spotify/misc.py`	Adds default stderr progress output for discover workflow; demotes per-track discovery log to DEBUG.
`spotfm/spotify/track.py`	Demotes Track init/DB retrieval logs from INFO to DEBUG.
`spotfm/spotify/album.py`	Demotes Album init/DB retrieval logs from INFO to DEBUG.
`spotfm/spotify/artist.py`	Demotes Artist init/DB retrieval logs from INFO to DEBUG.
`spotfm/spotify/playlist.py`	Demotes Playlist init/DB retrieval logs from INFO to DEBUG.

💡 Add Copilot custom instructions for smarter, more guided reviews. Learn how to get started.

spotfm/spotify/misc.py

spotfm/cli.py

## Issues Fixed 1. **Logging level not capturing INFO to file**: Set root logger to DEBUG to allow all messages through handlers. File handler captures INFO level, while console handler level is controlled by --info/-v flags. This ensures the always-on audit log actually captures INFO events. 2. **Progress message misleading**: Changed "fetching playlist" to "processing playlist" since the API fetch has already occurred at that point. 3. **Missing flush=True on progress output**: Added flush=True to all stderr print statements to ensure progress is visible immediately, even when stderr is redirected or buffered. 4. **Missing UTF-8 encoding on log file**: Added encoding='utf-8' to RotatingFileHandler to handle non-ASCII playlist/track names without raising UnicodeEncodeError on Windows or other platforms. ## Changes - cli.py: - Set root logger to DEBUG instead of using basicConfig() - Add console handler with dynamic level based on flags - Add UTF-8 encoding to RotatingFileHandler - Update flag-based logging to set console handler level - misc.py: - Change "fetching" to "processing" in progress message - Add flush=True to remaining progress print statements All tests pass (319/319), linting clean, coverage 79.66%. Co-Authored-By: Claude Haiku 4.5 <noreply@anthropic.com>

Copilot

Pull request overview

This PR improves SpotFM’s logging and user-facing progress output by adding an always-on rotating audit log file, reducing INFO-level verbosity for per-entity/per-track logs, and printing default progress for discover_from_playlists.

Changes:

Add a rotating audit log file at ~/.spotfm/spotfm.log and configure CLI logging handlers (file + console).
Print per-playlist progress and end-of-run discovery summary to stderr in discover_from_playlists.
Demote various high-volume INFO logs (entity init/cache/discovery) to DEBUG to keep default output cleaner.

Reviewed changes

Copilot reviewed 7 out of 7 changed files in this pull request and generated 3 comments.

Show a summary per file

File	Description
spotfm/cli.py	Configure root logger + rotating file handler for audit logging; adjust console log level by flags.
spotfm/utils.py	Introduce `LOG_FILE` constant and demote cache hit/miss logs to DEBUG.
spotfm/spotify/misc.py	Add stderr progress output and reduce per-track discovery logs to DEBUG.
spotfm/spotify/track.py	Demote Track init/DB retrieval logs to DEBUG.
spotfm/spotify/playlist.py	Demote Playlist init/DB retrieval logs to DEBUG.
spotfm/spotify/artist.py	Demote Artist init/DB retrieval logs to DEBUG.
spotfm/spotify/album.py	Demote Album init/DB retrieval logs to DEBUG.

💡 Add Copilot custom instructions for smarter, more guided reviews. Learn how to get started.

spotfm/spotify/misc.py

spotfm/spotify/track.py

spotfm/cli.py

- cli.py: Add try/except error handling for filesystem issues creating audit log file (fallback to console-only logging) - cli.py: Add sys import to support stderr output in error handler - misc.py: Change progress message from 'processing' to 'fetching' to match PR description - track.py: Fix misleading log message - change 'Album ID' to 'Album mapping' since it's a track context error All changes ensure PR description matches implementation and handle edge cases gracefully.

Copilot

Pull request overview

This PR updates SpotFM’s logging/UX behavior by adding an always-on rotating audit log file, reducing default console log noise, and adding default progress output for discover-from-playlists.

Changes:

Add a rotating audit log at ~/.spotfm/spotfm.log and adjust CLI logging handlers/levels.
Print per-playlist progress and a final summary to stderr during discover_from_playlists.
Demote several per-entity/per-track logs from INFO to DEBUG to reduce default verbosity.

Reviewed changes

Copilot reviewed 7 out of 7 changed files in this pull request and generated 2 comments.

Show a summary per file

File	Description
`spotfm/cli.py`	Adds rotating file handler + console handler and updates how log levels are controlled via flags.
`spotfm/utils.py`	Introduces `LOG_FILE` constant and demotes cache hit/miss logs to DEBUG.
`spotfm/spotify/misc.py`	Adds stderr progress output for playlist discovery and demotes “new track found” to DEBUG.
`spotfm/spotify/track.py`	Demotes Track init/DB retrieval logs to DEBUG and refines one message.
`spotfm/spotify/playlist.py`	Demotes Playlist init/DB retrieval logs to DEBUG.
`spotfm/spotify/artist.py`	Demotes Artist init/DB retrieval logs to DEBUG.
`spotfm/spotify/album.py`	Demotes Album init/DB retrieval logs to DEBUG.

💡 Add Copilot custom instructions for smarter, more guided reviews. Learn how to get started.

spotfm/cli.py

spotfm/spotify/misc.py

- cli.py: Lower root logger default from DEBUG to INFO; only raise to DEBUG when -v/--verbose is set after arg parsing. Avoids creating LogRecords for debug calls in tight loops (per-track processing) and prevents DEBUG output from third-party libraries unless explicitly requested. - misc.py: Move "fetching playlist" progress print to before Playlist.get_playlist() so the message displays before the slow API fetch, making the progress indicator accurate and immediately visible during the wait. Co-Authored-By: Claude Sonnet 4.6 <noreply@anthropic.com>

- Print progress to stderr before each playlist fetch: "updating playlist X (N/total)" - Log track counts per playlist to audit log: "Synced N tracks from playlist X" - Show summary: "synced N playlists (M total tracks)" - Log cleanup of deleted playlists from database Provides real-time progress feedback and detailed audit trail for debugging. Similar to discover-from-playlists logging pattern from PR #35. Co-Authored-By: Claude Haiku 4.5 <noreply@anthropic.com>

Enables detailed remediation support by logging: **Playlist.add_tracks() and Playlist.remove_tracks():** - Total track count and track IDs (for full audit trail) - Playlist ID and name - Batch progress and status - Success/failure per batch with detailed error messages **Command-level logging (discover_from_playlists, remove_tracks_from_file, etc.):** - Command name and source file/context - Total tracks affected - Summary of success/failure (N/M tracks) - Track IDs for remediation (can reverse operations) **Log examples:** - "Adding 47 tracks to playlist 3abc123 - My Discoveries [track_ids: track1,track2,...]" - "Command: discover_from_playlists | Found 12 new tracks from 3 source playlists | Adding..." - "Command: remove_tracks_from_file | File: /tmp/tracks.txt | Removed 5/10 tracks..." Audit log now contains enough information to reconstruct and reverse any operation: - Which tracks were added/removed (track IDs in log) - To/from which playlist (playlist ID/name) - When (timestamp via logging) - Success/failure details (for debugging) Co-Authored-By: Claude Haiku 4.5 <noreply@anthropic.com>

- Remove command-level logging from add_tracks_from_file and add_tracks_from_file_batch (no file source context needed for DB-only operations) - Simplify remove_tracks_from_file to remove duplicated file source context (playlist-level remove_tracks already logs track IDs) - Keep command-level context logging in discover_from_playlists (complementary to playlist-level add_tracks logging, provides discovery summary) - Reduces redundant logging while preserving audit trail with track IDs for remediation Co-Authored-By: Claude Haiku 4.5 <noreply@anthropic.com>

- Standardize progress message wording: 'fetching' instead of 'updating' (consistent with discover-from-playlists) - Add flush=True to summary print statement to ensure output appears immediately in redirected stderr Fixes review comments: - Issue #1/#5: Progress message wording consistency (fetching vs updating) - Issue #2: Missing flush=True on final summary print (can cause reordered output) Co-Authored-By: Claude Haiku 4.5 <noreply@anthropic.com>

- Document new always-on audit log at ~/.spotfm/spotfm.log with track IDs for remediation - Document real-time progress output for long-running commands - Clarify logging hierarchy: default progress, --info for operational debugging, -v for developer details - Update CHANGELOG.md with complete feature list and user-visible changes Co-Authored-By: Claude Haiku 4.5 <noreply@anthropic.com>

- Document dual-handler strategy (console + file separation) - Explain root logger level management (INFO default, DEBUG only with -v) - Clarify RotatingFileHandler with UTF-8 encoding and graceful fallback - Add rationale for architectural choices and alternatives considered - Include implementation details and log destination table Addresses quality gate gap: SPEC.md as source of truth for architecture. Co-Authored-By: Claude Haiku 4.5 <noreply@anthropic.com>

Logging Improvements (first HIGH PRIORITY item) has been completed in PR #35: - ✅ Progress output visible by default for update-playlists and discover-from-playlists - ✅ Always-on audit log with track IDs for debugging and remediation - ✅ Cleaner logging hierarchy (per-entity logs demoted to DEBUG) - ✅ No excess noise in default or --info modes Closes the first TODO item. Co-Authored-By: Claude Haiku 4.5 <noreply@anthropic.com>

This item has been fully addressed in PR #35: - Always-on audit log with track IDs - Default progress output - Cleaner logging hierarchy - All review feedback addressed Co-Authored-By: Claude Haiku 4.5 <noreply@anthropic.com>

jmlrt marked this pull request as ready for review March 15, 2026 17:14

Copilot AI review requested due to automatic review settings March 15, 2026 17:14

Copilot started reviewing on behalf of jmlrt March 15, 2026 17:14 View session

Copilot AI reviewed Mar 15, 2026

View reviewed changes

spotfm/spotify/misc.py Outdated Show resolved Hide resolved

spotfm/spotify/misc.py Outdated Show resolved Hide resolved

spotfm/cli.py Outdated Show resolved Hide resolved

spotfm/cli.py Outdated Show resolved Hide resolved

jmlrt requested a review from Copilot March 15, 2026 17:38

Copilot started reviewing on behalf of jmlrt March 15, 2026 17:39 View session

Copilot AI reviewed Mar 15, 2026

View reviewed changes

spotfm/spotify/misc.py Show resolved Hide resolved

spotfm/spotify/track.py Outdated Show resolved Hide resolved

spotfm/cli.py Outdated Show resolved Hide resolved

jmlrt requested a review from Copilot March 15, 2026 17:59

Copilot started reviewing on behalf of jmlrt March 15, 2026 17:59 View session

Copilot AI reviewed Mar 15, 2026

View reviewed changes

spotfm/cli.py Outdated Show resolved Hide resolved

spotfm/spotify/misc.py Outdated Show resolved Hide resolved

jmlrt and others added 6 commits March 15, 2026 19:25

jmlrt and others added 3 commits March 15, 2026 22:09

docs: Remove completed logging improvements from TODO.md

32e9990

This item has been fully addressed in PR #35: - Always-on audit log with track IDs - Default progress output - Cleaner logging hierarchy - All review feedback addressed Co-Authored-By: Claude Haiku 4.5 <noreply@anthropic.com>

jmlrt merged commit baa20d8 into main Mar 15, 2026
3 checks passed

jmlrt deleted the feat/logging-improvements branch March 15, 2026 21:22

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

feat(logging): audit trail and progress#35

feat(logging): audit trail and progress#35
jmlrt merged 12 commits intomainfrom
feat/logging-improvements

jmlrt commented Mar 15, 2026 •

edited

Loading

Uh oh!

Copilot AI left a comment

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Copilot AI left a comment

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Copilot AI left a comment

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

2 participants

Conversation

jmlrt commented Mar 15, 2026 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Summary

User-Facing Changes

Progress Output (No Flags Needed)

Audit Log File

Logging Hierarchy (After Changes)

Implementation Details

Core Changes

Simplifications (KISS/YAGNI)

Review Feedback Addressed

Testing & Validation

Examples

Related Issues

Uh oh!

Copilot AI left a comment

Choose a reason for hiding this comment

Pull request overview

Reviewed changes

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Copilot AI left a comment

Choose a reason for hiding this comment

Pull request overview

Reviewed changes

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Copilot AI left a comment

Choose a reason for hiding this comment

Pull request overview

Reviewed changes

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

2 participants

jmlrt commented Mar 15, 2026 •

edited

Loading