[WIP] music platform user data scraper
teal-fm atproto

Added a dedicated logger with prefix to most services

authored by baileytownsend.dev and committed by Kyle Loveless 9faa99db bb519076

Changed files
+115 -100
cmd
oauth
service
lastfm
musicbrainz
spotify
+3 -3
cmd/main.go
··· 108 lastfmInterval = 30 * time.Second 109 } 110 111 - if err := spotifyService.LoadAllUsers(); err != nil { 112 - log.Printf("Warning: Failed to preload Spotify users: %v", err) 113 - } 114 go spotifyService.StartListeningTracker(trackerInterval) 115 116 go lastfmService.StartListeningTracker(lastfmInterval)
··· 108 lastfmInterval = 30 * time.Second 109 } 110 111 + //if err := spotifyService.LoadAllUsers(); err != nil { 112 + // log.Printf("Warning: Failed to preload Spotify users: %v", err) 113 + //} 114 go spotifyService.StartListeningTracker(trackerInterval) 115 116 go lastfmService.StartListeningTracker(lastfmInterval)
+9 -7
oauth/oauth_manager.go
··· 15 services map[string]AuthService 16 sessionManager *session.SessionManager 17 mu sync.RWMutex 18 } 19 20 func NewOAuthServiceManager(sessionManager *session.SessionManager) *OAuthServiceManager { 21 return &OAuthServiceManager{ 22 services: make(map[string]AuthService), 23 sessionManager: sessionManager, 24 } 25 } 26 ··· 29 m.mu.Lock() 30 defer m.mu.Unlock() 31 m.services[name] = service 32 - log.Printf("Registered auth service: %s", name) 33 } 34 35 // get an AuthService by registered name ··· 51 return 52 } 53 54 - log.Printf("Auth service '%s' not found for login request", serviceName) 55 http.Error(w, fmt.Sprintf("Auth service '%s' not found", serviceName), http.StatusNotFound) 56 } 57 } ··· 62 service, exists := m.services[serviceName] 63 m.mu.RUnlock() 64 65 - log.Printf("Logging in with service %s", serviceName) 66 67 if !exists { 68 - log.Printf("Auth service '%s' not found for callback request", serviceName) 69 http.Error(w, fmt.Sprintf("OAuth service '%s' not found", serviceName), http.StatusNotFound) 70 return 71 } ··· 73 userID, err := service.HandleCallback(w, r) 74 75 if err != nil { 76 - log.Printf("Error handling callback for service '%s': %v", serviceName, err) 77 http.Error(w, fmt.Sprintf("Error handling callback for service '%s'", serviceName), http.StatusInternalServerError) 78 return 79 } ··· 83 84 m.sessionManager.SetSessionCookie(w, session) 85 86 - log.Printf("Created session for user %d via service %s", userID, serviceName) 87 88 http.Redirect(w, r, "/", http.StatusSeeOther) 89 } else { 90 - log.Printf("Callback for service '%s' did not result in a valid user ID.", serviceName) 91 // todo: redirect to an error page 92 // right now this just redirects home but we don't want this behaviour ideally 93 http.Redirect(w, r, "/", http.StatusSeeOther)
··· 15 services map[string]AuthService 16 sessionManager *session.SessionManager 17 mu sync.RWMutex 18 + logger *log.Logger 19 } 20 21 func NewOAuthServiceManager(sessionManager *session.SessionManager) *OAuthServiceManager { 22 return &OAuthServiceManager{ 23 services: make(map[string]AuthService), 24 sessionManager: sessionManager, 25 + logger: log.New(log.Writer(), "oauth: ", log.LstdFlags|log.Lmsgprefix), 26 } 27 } 28 ··· 31 m.mu.Lock() 32 defer m.mu.Unlock() 33 m.services[name] = service 34 + m.logger.Printf("Registered auth service: %s", name) 35 } 36 37 // get an AuthService by registered name ··· 53 return 54 } 55 56 + m.logger.Printf("Auth service '%s' not found for login request", serviceName) 57 http.Error(w, fmt.Sprintf("Auth service '%s' not found", serviceName), http.StatusNotFound) 58 } 59 } ··· 64 service, exists := m.services[serviceName] 65 m.mu.RUnlock() 66 67 + m.logger.Printf("Logging in with service %s", serviceName) 68 69 if !exists { 70 + m.logger.Printf("Auth service '%s' not found for callback request", serviceName) 71 http.Error(w, fmt.Sprintf("OAuth service '%s' not found", serviceName), http.StatusNotFound) 72 return 73 } ··· 75 userID, err := service.HandleCallback(w, r) 76 77 if err != nil { 78 + m.logger.Printf("Error handling callback for service '%s': %v", serviceName, err) 79 http.Error(w, fmt.Sprintf("Error handling callback for service '%s'", serviceName), http.StatusInternalServerError) 80 return 81 } ··· 85 86 m.sessionManager.SetSessionCookie(w, session) 87 88 + m.logger.Printf("Created session for user %d via service %s", userID, serviceName) 89 90 http.Redirect(w, r, "/", http.StatusSeeOther) 91 } else { 92 + m.logger.Printf("Callback for service '%s' did not result in a valid user ID.", serviceName) 93 // todo: redirect to an error page 94 // right now this just redirects home but we don't want this behaviour ideally 95 http.Redirect(w, r, "/", http.StatusSeeOther)
+45 -40
service/lastfm/lastfm.go
··· 9 "log" 10 "net/http" 11 "net/url" 12 "strconv" 13 "sync" 14 "time" ··· 40 atprotoService *atprotoauth.ATprotoAuthService 41 lastSeenNowPlaying map[string]Track 42 mu sync.Mutex 43 } 44 45 func NewLastFMService(db *db.DB, apiKey string, musicBrainzService *musicbrainz.MusicBrainzService, atprotoService *atprotoauth.ATprotoAuthService) *LastFMService { 46 return &LastFMService{ 47 db: db, 48 httpClient: &http.Client{ ··· 56 musicBrainzService: musicBrainzService, 57 lastSeenNowPlaying: make(map[string]Track), 58 mu: sync.Mutex{}, 59 } 60 } 61 62 func (l *LastFMService) loadUsernames() error { 63 u, err := l.db.GetAllUsersWithLastFM() 64 if err != nil { 65 - log.Printf("Error loading users with Last.fm from DB: %v", err) 66 return fmt.Errorf("failed to load users from database: %w", err) 67 } 68 usernames := make([]string, len(u)) ··· 71 if user.LastFMUsername != nil { // Check if the username is set 72 usernames[i] = *user.LastFMUsername 73 } else { 74 - log.Printf("User ID %d has Last.fm enabled but no username set", user.ID) 75 } 76 } 77 ··· 84 } 85 86 l.Usernames = filteredUsernames 87 - log.Printf("Loaded %d Last.fm usernames", len(l.Usernames)) 88 89 return nil 90 } ··· 113 return nil, fmt.Errorf("failed to create request for %s: %w", username, err) 114 } 115 116 - log.Printf("Fetching recent tracks for user: %s", username) 117 resp, err := l.httpClient.Do(req) 118 if err != nil { 119 return nil, fmt.Errorf("failed to fetch recent tracks for %s: %w", username, err) ··· 134 } 135 if err := json.Unmarshal(bodyBytes, &recentTracksResp); err != nil { 136 // Log the body content that failed to decode 137 - log.Printf("Failed to decode response body for %s: %s", username, string(bodyBytes)) 138 return nil, fmt.Errorf("failed to decode response for %s: %w", username, err) 139 } 140 141 if len(recentTracksResp.RecentTracks.Tracks) > 0 { 142 - log.Printf("Fetched %d tracks for %s. Most recent: %s - %s", 143 len(recentTracksResp.RecentTracks.Tracks), 144 username, 145 recentTracksResp.RecentTracks.Tracks[0].Artist.Text, 146 recentTracksResp.RecentTracks.Tracks[0].Name) 147 } else { 148 - log.Printf("No recent tracks found for %s", username) 149 } 150 151 return &recentTracksResp, nil ··· 153 154 func (l *LastFMService) StartListeningTracker(interval time.Duration) { 155 if err := l.loadUsernames(); err != nil { 156 - log.Printf("Failed to perform initial username load: %v", err) 157 // Decide if we should proceed without initial load or return error 158 } 159 160 if len(l.Usernames) == 0 { 161 - log.Println("No Last.fm users configured. Tracker will run but fetch cycles will be skipped until users are added.") 162 } else { 163 - log.Printf("Found %d Last.fm users.", len(l.Usernames)) 164 } 165 166 ticker := time.NewTicker(interval) ··· 169 if len(l.Usernames) > 0 { 170 l.fetchAllUserTracks(context.Background()) 171 } else { 172 - log.Println("Skipping initial fetch cycle as no users are configured.") 173 } 174 175 for { ··· 177 case <-ticker.C: 178 // refresh usernames periodically from db 179 if err := l.loadUsernames(); err != nil { 180 - log.Printf("Error reloading usernames in ticker: %v", err) 181 // Continue ticker loop even if reload fails? Or log and potentially stop? 182 continue // Continue for now 183 } 184 if len(l.Usernames) > 0 { 185 l.fetchAllUserTracks(context.Background()) 186 } else { 187 - log.Println("No Last.fm users configured. Skipping fetch cycle.") 188 } 189 // TODO: Implement graceful shutdown using context cancellation 190 // case <-ctx.Done(): 191 - // log.Println("Stopping Last.fm listening tracker.") 192 // ticker.Stop() 193 // return 194 } 195 } 196 }() 197 198 - log.Printf("Last.fm Listening Tracker started with interval %v", interval) 199 } 200 201 // fetchAllUserTracks iterates through users and fetches their tracks. 202 func (l *LastFMService) fetchAllUserTracks(ctx context.Context) { 203 - log.Printf("Starting fetch cycle for %d users...", len(l.Usernames)) 204 var wg sync.WaitGroup // Use WaitGroup to fetch concurrently (optional) 205 fetchErrors := make(chan error, len(l.Usernames)) // Channel for errors 206 207 for _, username := range l.Usernames { 208 if ctx.Err() != nil { 209 - log.Printf("Context cancelled before starting fetch for user %s.", username) 210 break // Exit loop if context is cancelled 211 } 212 ··· 214 go func(uname string) { // Launch fetch and process in a goroutine per user 215 defer wg.Done() 216 if ctx.Err() != nil { 217 - log.Printf("Context cancelled during fetch cycle for user %s.", uname) 218 return // Exit goroutine if context is cancelled 219 } 220 ··· 223 const fetchLimit = 5 224 recentTracks, err := l.getRecentTracks(ctx, uname, fetchLimit) 225 if err != nil { 226 - log.Printf("Error fetching tracks for %s: %v", uname, err) 227 fetchErrors <- fmt.Errorf("fetch failed for %s: %w", uname, err) // Report error 228 return 229 } 230 231 if recentTracks == nil || len(recentTracks.RecentTracks.Tracks) == 0 { 232 - log.Printf("No tracks returned for user %s", uname) 233 return 234 } 235 236 // Process the fetched tracks 237 if err := l.processTracks(ctx, uname, recentTracks.RecentTracks.Tracks); err != nil { 238 - log.Printf("Error processing tracks for %s: %v", uname, err) 239 fetchErrors <- fmt.Errorf("process failed for %s: %w", uname, err) // Report error 240 } 241 }(username) ··· 247 // Log any errors that occurred during the fetch cycle 248 errorCount := 0 249 for err := range fetchErrors { 250 - log.Printf("Fetch cycle error: %v", err) 251 errorCount++ 252 } 253 254 if errorCount > 0 { 255 - log.Printf("Finished fetch cycle with %d errors.", errorCount) 256 } else { 257 - log.Println("Finished fetch cycle successfully.") 258 } 259 } 260 ··· 274 } 275 276 if lastKnownTimestamp == nil { 277 - log.Printf("no previous scrobble timestamp found for user %s. processing latest track.", username) 278 } else { 279 - log.Printf("last known scrobble for %s was at %s", username, lastKnownTimestamp.Format(time.RFC3339)) 280 } 281 282 var ( ··· 287 // handle now playing track separately 288 if len(tracks) > 0 && tracks[0].Attr != nil && tracks[0].Attr.NowPlaying == "true" { 289 nowPlayingTrack := tracks[0] 290 - log.Printf("now playing track for %s: %s - %s", username, nowPlayingTrack.Artist.Text, nowPlayingTrack.Name) 291 l.mu.Lock() 292 lastSeen, existed := l.lastSeenNowPlaying[username] 293 // if our current track matches with last seen 294 // just compare artist/album/name for now 295 if existed && lastSeen.Album == nowPlayingTrack.Album && lastSeen.Name == nowPlayingTrack.Name && lastSeen.Artist == nowPlayingTrack.Artist { 296 - log.Printf("current track matches last seen track for %s", username) 297 } else { 298 - log.Printf("current track does not match last seen track for %s", username) 299 // aha! we record this! 300 l.lastSeenNowPlaying[username] = nowPlayingTrack 301 } ··· 312 } 313 314 if lastNonNowPlaying == nil { 315 - log.Printf("no non-now-playing tracks found for user %s.", username) 316 return nil 317 } 318 319 latestTrackTime := lastNonNowPlaying.Date 320 321 // print both 322 - fmt.Printf("latestTrackTime: %s\n", latestTrackTime) 323 - fmt.Printf("lastKnownTimestamp: %s\n", lastKnownTimestamp) 324 325 if lastKnownTimestamp != nil && lastKnownTimestamp.Equal(latestTrackTime.Time) { 326 - log.Printf("no new tracks to process for user %s.", username) 327 return nil 328 } 329 330 for _, track := range tracks { 331 if track.Date == nil { 332 - log.Printf("skipping track without timestamp for %s: %s - %s", username, track.Artist.Text, track.Name) 333 continue 334 } 335 ··· 337 // before or at last known 338 if lastKnownTimestamp != nil && (trackTime.Before(*lastKnownTimestamp) || trackTime.Equal(*lastKnownTimestamp)) { 339 if processedCount == 0 { 340 - log.Printf("reached already known scrobbles for user %s (track time: %s, last known: %s).", 341 username, trackTime.Format(time.RFC3339), lastKnownTimestamp.Format(time.RFC3339)) 342 } 343 break ··· 360 361 hydratedTrack, err := musicbrainz.HydrateTrack(l.musicBrainzService, baseTrack) 362 if err != nil { 363 - log.Printf("error hydrating track for user %s: %s - %s: %v", username, track.Artist.Text, track.Name, err) 364 // we can use the track without MBIDs, it's still valid 365 hydratedTrack = &baseTrack 366 } 367 l.db.SaveTrack(user.ID, hydratedTrack) 368 - log.Printf("Submitting track") 369 err = l.SubmitTrackToPDS(*user.ATProtoDID, hydratedTrack, ctx) 370 if err != nil { 371 - log.Printf("error submitting track for user %s: %s - %s: %v", username, track.Artist.Text, track.Name, err) 372 } 373 processedCount++ 374 ··· 382 } 383 384 if processedCount > 0 { 385 - log.Printf("processed %d new track(s) for user %s. latest timestamp: %s", 386 processedCount, username, latestProcessedTime.Format(time.RFC3339)) 387 } 388 ··· 407 } 408 409 // printout the session details 410 - fmt.Printf("Submitting track for the did: %+v\n", sess.DID) 411 412 artists := make([]*teal.AlphaFeedDefs_Artist, 0, len(track.Artist)) 413 for _, a := range track.Artist {
··· 9 "log" 10 "net/http" 11 "net/url" 12 + "os" 13 "strconv" 14 "sync" 15 "time" ··· 41 atprotoService *atprotoauth.ATprotoAuthService 42 lastSeenNowPlaying map[string]Track 43 mu sync.Mutex 44 + logger *log.Logger 45 } 46 47 func NewLastFMService(db *db.DB, apiKey string, musicBrainzService *musicbrainz.MusicBrainzService, atprotoService *atprotoauth.ATprotoAuthService) *LastFMService { 48 + logger := log.New(os.Stdout, "lastfm: ", log.LstdFlags|log.Lmsgprefix) 49 + 50 return &LastFMService{ 51 db: db, 52 httpClient: &http.Client{ ··· 60 musicBrainzService: musicBrainzService, 61 lastSeenNowPlaying: make(map[string]Track), 62 mu: sync.Mutex{}, 63 + logger: logger, 64 } 65 } 66 67 func (l *LastFMService) loadUsernames() error { 68 u, err := l.db.GetAllUsersWithLastFM() 69 if err != nil { 70 + l.logger.Printf("Error loading users with Last.fm from DB: %v", err) 71 return fmt.Errorf("failed to load users from database: %w", err) 72 } 73 usernames := make([]string, len(u)) ··· 76 if user.LastFMUsername != nil { // Check if the username is set 77 usernames[i] = *user.LastFMUsername 78 } else { 79 + l.logger.Printf("User ID %d has Last.fm enabled but no username set", user.ID) 80 } 81 } 82 ··· 89 } 90 91 l.Usernames = filteredUsernames 92 + l.logger.Printf("Loaded %d Last.fm usernames", len(l.Usernames)) 93 94 return nil 95 } ··· 118 return nil, fmt.Errorf("failed to create request for %s: %w", username, err) 119 } 120 121 + l.logger.Printf("Fetching recent tracks for user: %s", username) 122 resp, err := l.httpClient.Do(req) 123 if err != nil { 124 return nil, fmt.Errorf("failed to fetch recent tracks for %s: %w", username, err) ··· 139 } 140 if err := json.Unmarshal(bodyBytes, &recentTracksResp); err != nil { 141 // Log the body content that failed to decode 142 + l.logger.Printf("Failed to decode response body for %s: %s", username, string(bodyBytes)) 143 return nil, fmt.Errorf("failed to decode response for %s: %w", username, err) 144 } 145 146 if len(recentTracksResp.RecentTracks.Tracks) > 0 { 147 + l.logger.Printf("Fetched %d tracks for %s. Most recent: %s - %s", 148 len(recentTracksResp.RecentTracks.Tracks), 149 username, 150 recentTracksResp.RecentTracks.Tracks[0].Artist.Text, 151 recentTracksResp.RecentTracks.Tracks[0].Name) 152 } else { 153 + l.logger.Printf("No recent tracks found for %s", username) 154 } 155 156 return &recentTracksResp, nil ··· 158 159 func (l *LastFMService) StartListeningTracker(interval time.Duration) { 160 if err := l.loadUsernames(); err != nil { 161 + l.logger.Printf("Failed to perform initial username load: %v", err) 162 // Decide if we should proceed without initial load or return error 163 } 164 165 if len(l.Usernames) == 0 { 166 + l.logger.Println("No Last.fm users configured. Tracker will run but fetch cycles will be skipped until users are added.") 167 } else { 168 + l.logger.Printf("Found %d Last.fm users.", len(l.Usernames)) 169 } 170 171 ticker := time.NewTicker(interval) ··· 174 if len(l.Usernames) > 0 { 175 l.fetchAllUserTracks(context.Background()) 176 } else { 177 + l.logger.Println("Skipping initial fetch cycle as no users are configured.") 178 } 179 180 for { ··· 182 case <-ticker.C: 183 // refresh usernames periodically from db 184 if err := l.loadUsernames(); err != nil { 185 + l.logger.Printf("Error reloading usernames in ticker: %v", err) 186 // Continue ticker loop even if reload fails? Or log and potentially stop? 187 continue // Continue for now 188 } 189 if len(l.Usernames) > 0 { 190 l.fetchAllUserTracks(context.Background()) 191 } else { 192 + l.logger.Println("No Last.fm users configured. Skipping fetch cycle.") 193 } 194 // TODO: Implement graceful shutdown using context cancellation 195 // case <-ctx.Done(): 196 + // l.logger.Println("Stopping Last.fm listening tracker.") 197 // ticker.Stop() 198 // return 199 } 200 } 201 }() 202 203 + l.logger.Printf("Last.fm Listening Tracker started with interval %v", interval) 204 } 205 206 // fetchAllUserTracks iterates through users and fetches their tracks. 207 func (l *LastFMService) fetchAllUserTracks(ctx context.Context) { 208 + l.logger.Printf("Starting fetch cycle for %d users...", len(l.Usernames)) 209 var wg sync.WaitGroup // Use WaitGroup to fetch concurrently (optional) 210 fetchErrors := make(chan error, len(l.Usernames)) // Channel for errors 211 212 for _, username := range l.Usernames { 213 if ctx.Err() != nil { 214 + l.logger.Printf("Context cancelled before starting fetch for user %s.", username) 215 break // Exit loop if context is cancelled 216 } 217 ··· 219 go func(uname string) { // Launch fetch and process in a goroutine per user 220 defer wg.Done() 221 if ctx.Err() != nil { 222 + l.logger.Printf("Context cancelled during fetch cycle for user %s.", uname) 223 return // Exit goroutine if context is cancelled 224 } 225 ··· 228 const fetchLimit = 5 229 recentTracks, err := l.getRecentTracks(ctx, uname, fetchLimit) 230 if err != nil { 231 + l.logger.Printf("Error fetching tracks for %s: %v", uname, err) 232 fetchErrors <- fmt.Errorf("fetch failed for %s: %w", uname, err) // Report error 233 return 234 } 235 236 if recentTracks == nil || len(recentTracks.RecentTracks.Tracks) == 0 { 237 + l.logger.Printf("No tracks returned for user %s", uname) 238 return 239 } 240 241 // Process the fetched tracks 242 if err := l.processTracks(ctx, uname, recentTracks.RecentTracks.Tracks); err != nil { 243 + l.logger.Printf("Error processing tracks for %s: %v", uname, err) 244 fetchErrors <- fmt.Errorf("process failed for %s: %w", uname, err) // Report error 245 } 246 }(username) ··· 252 // Log any errors that occurred during the fetch cycle 253 errorCount := 0 254 for err := range fetchErrors { 255 + l.logger.Printf("Fetch cycle error: %v", err) 256 errorCount++ 257 } 258 259 if errorCount > 0 { 260 + l.logger.Printf("Finished fetch cycle with %d errors.", errorCount) 261 } else { 262 + l.logger.Println("Finished fetch cycle successfully.") 263 } 264 } 265 ··· 279 } 280 281 if lastKnownTimestamp == nil { 282 + l.logger.Printf("no previous scrobble timestamp found for user %s. processing latest track.", username) 283 } else { 284 + l.logger.Printf("last known scrobble for %s was at %s", username, lastKnownTimestamp.Format(time.RFC3339)) 285 } 286 287 var ( ··· 292 // handle now playing track separately 293 if len(tracks) > 0 && tracks[0].Attr != nil && tracks[0].Attr.NowPlaying == "true" { 294 nowPlayingTrack := tracks[0] 295 + l.logger.Printf("now playing track for %s: %s - %s", username, nowPlayingTrack.Artist.Text, nowPlayingTrack.Name) 296 l.mu.Lock() 297 lastSeen, existed := l.lastSeenNowPlaying[username] 298 // if our current track matches with last seen 299 // just compare artist/album/name for now 300 if existed && lastSeen.Album == nowPlayingTrack.Album && lastSeen.Name == nowPlayingTrack.Name && lastSeen.Artist == nowPlayingTrack.Artist { 301 + l.logger.Printf("current track matches last seen track for %s", username) 302 } else { 303 + l.logger.Printf("current track does not match last seen track for %s", username) 304 // aha! we record this! 305 l.lastSeenNowPlaying[username] = nowPlayingTrack 306 } ··· 317 } 318 319 if lastNonNowPlaying == nil { 320 + l.logger.Printf("no non-now-playing tracks found for user %s.", username) 321 return nil 322 } 323 324 latestTrackTime := lastNonNowPlaying.Date 325 326 // print both 327 + l.logger.Printf("latestTrackTime: %s\n", latestTrackTime) 328 + l.logger.Printf("lastKnownTimestamp: %s\n", lastKnownTimestamp) 329 330 if lastKnownTimestamp != nil && lastKnownTimestamp.Equal(latestTrackTime.Time) { 331 + l.logger.Printf("no new tracks to process for user %s.", username) 332 return nil 333 } 334 335 for _, track := range tracks { 336 if track.Date == nil { 337 + l.logger.Printf("skipping track without timestamp for %s: %s - %s", username, track.Artist.Text, track.Name) 338 continue 339 } 340 ··· 342 // before or at last known 343 if lastKnownTimestamp != nil && (trackTime.Before(*lastKnownTimestamp) || trackTime.Equal(*lastKnownTimestamp)) { 344 if processedCount == 0 { 345 + l.logger.Printf("reached already known scrobbles for user %s (track time: %s, last known: %s).", 346 username, trackTime.Format(time.RFC3339), lastKnownTimestamp.Format(time.RFC3339)) 347 } 348 break ··· 365 366 hydratedTrack, err := musicbrainz.HydrateTrack(l.musicBrainzService, baseTrack) 367 if err != nil { 368 + l.logger.Printf("error hydrating track for user %s: %s - %s: %v", username, track.Artist.Text, track.Name, err) 369 // we can use the track without MBIDs, it's still valid 370 hydratedTrack = &baseTrack 371 } 372 l.db.SaveTrack(user.ID, hydratedTrack) 373 + l.logger.Printf("Submitting track") 374 err = l.SubmitTrackToPDS(*user.ATProtoDID, hydratedTrack, ctx) 375 if err != nil { 376 + l.logger.Printf("error submitting track for user %s: %s - %s: %v", username, track.Artist.Text, track.Name, err) 377 } 378 processedCount++ 379 ··· 387 } 388 389 if processedCount > 0 { 390 + l.logger.Printf("processed %d new track(s) for user %s. latest timestamp: %s", 391 processedCount, username, latestProcessedTime.Format(time.RFC3339)) 392 } 393 ··· 412 } 413 414 // printout the session details 415 + l.logger.Printf("Submitting track for the did: %+v\n", sess.DID) 416 417 artists := make([]*teal.AlphaFeedDefs_Artist, 0, len(track.Artist)) 418 for _, a := range track.Artist {
+11 -8
service/musicbrainz/musicbrainz.go
··· 8 "log" 9 "net/http" 10 "net/url" 11 "sort" 12 "strings" 13 "sync" // Added for mutex ··· 75 cacheMutex sync.RWMutex // Mutex to protect the cache 76 cacheTTL time.Duration // Time-to-live for cache entries 77 cleaner MetadataCleaner // Cleaner for cleaning up expired cache entries 78 } 79 80 // NewMusicBrainzService creates a new service instance with rate limiting and caching. ··· 83 limiter := rate.NewLimiter(rate.Every(time.Second), 1) 84 // Set a default cache TTL (e.g., 1 hour) 85 defaultCacheTTL := 1 * time.Hour 86 - 87 return &MusicBrainzService{ 88 db: db, 89 httpClient: &http.Client{ ··· 94 cacheTTL: defaultCacheTTL, // Set the cache TTL 95 cleaner: *NewMetadataCleaner("Latin"), // Initialize the cleaner 96 // cacheMutex is zero-value ready 97 } 98 } 99 ··· 127 s.cacheMutex.RUnlock() 128 129 if found && now.Before(entry.expiresAt) { 130 - log.Printf("Cache hit for MusicBrainz search: key=%s", cacheKey) 131 // Return the cached data directly. Consider if a deep copy is needed if callers modify results. 132 return entry.recordings, nil 133 } 134 // --- Cache Miss or Expired --- 135 if found { 136 - log.Printf("Cache expired for MusicBrainz search: key=%s", cacheKey) 137 } else { 138 - log.Printf("Cache miss for MusicBrainz search: key=%s", cacheKey) 139 } 140 141 // --- Proceed with API call --- ··· 191 expiresAt: time.Now().UTC().Add(s.cacheTTL), 192 } 193 s.cacheMutex.Unlock() 194 - log.Printf("Cached MusicBrainz search result for key=%s, TTL=%s", cacheKey, s.cacheTTL) 195 196 // Return the newly fetched results 197 return result.Recordings, nil 198 } 199 200 // GetBestRelease selects the 'best' release from a list based on specific criteria. 201 - func GetBestRelease(releases []MusicBrainzRelease, trackTitle string) *MusicBrainzRelease { 202 if len(releases) == 0 { 203 return nil 204 } ··· 251 } 252 253 // 3. If none found, return the oldest release overall (which is the first one after sorting) 254 - log.Printf("Could not find a suitable release for '%s', picking oldest: '%s' (%s)", trackTitle, releases[0].Title, releases[0].ID) 255 r := releases[0] 256 return &r 257 } ··· 279 } 280 281 firstResult := res[0] 282 - firstResultAlbum := GetBestRelease(firstResult.Releases, firstResult.Title) 283 284 // woof. we Might not have any ISRCs! 285 var bestISRC string
··· 8 "log" 9 "net/http" 10 "net/url" 11 + "os" 12 "sort" 13 "strings" 14 "sync" // Added for mutex ··· 76 cacheMutex sync.RWMutex // Mutex to protect the cache 77 cacheTTL time.Duration // Time-to-live for cache entries 78 cleaner MetadataCleaner // Cleaner for cleaning up expired cache entries 79 + logger *log.Logger // Logger for logging 80 } 81 82 // NewMusicBrainzService creates a new service instance with rate limiting and caching. ··· 85 limiter := rate.NewLimiter(rate.Every(time.Second), 1) 86 // Set a default cache TTL (e.g., 1 hour) 87 defaultCacheTTL := 1 * time.Hour 88 + logger := log.New(os.Stdout, "musicbrainz: ", log.LstdFlags|log.Lmsgprefix) 89 return &MusicBrainzService{ 90 db: db, 91 httpClient: &http.Client{ ··· 96 cacheTTL: defaultCacheTTL, // Set the cache TTL 97 cleaner: *NewMetadataCleaner("Latin"), // Initialize the cleaner 98 // cacheMutex is zero-value ready 99 + logger: logger, 100 } 101 } 102 ··· 130 s.cacheMutex.RUnlock() 131 132 if found && now.Before(entry.expiresAt) { 133 + s.logger.Printf("Cache hit for MusicBrainz search: key=%s", cacheKey) 134 // Return the cached data directly. Consider if a deep copy is needed if callers modify results. 135 return entry.recordings, nil 136 } 137 // --- Cache Miss or Expired --- 138 if found { 139 + s.logger.Printf("Cache expired for MusicBrainz search: key=%s", cacheKey) 140 } else { 141 + s.logger.Printf("Cache miss for MusicBrainz search: key=%s", cacheKey) 142 } 143 144 // --- Proceed with API call --- ··· 194 expiresAt: time.Now().UTC().Add(s.cacheTTL), 195 } 196 s.cacheMutex.Unlock() 197 + s.logger.Printf("Cached MusicBrainz search result for key=%s, TTL=%s", cacheKey, s.cacheTTL) 198 199 // Return the newly fetched results 200 return result.Recordings, nil 201 } 202 203 // GetBestRelease selects the 'best' release from a list based on specific criteria. 204 + func (s *MusicBrainzService) GetBestRelease(releases []MusicBrainzRelease, trackTitle string) *MusicBrainzRelease { 205 if len(releases) == 0 { 206 return nil 207 } ··· 254 } 255 256 // 3. If none found, return the oldest release overall (which is the first one after sorting) 257 + s.logger.Printf("Could not find a suitable release for '%s', picking oldest: '%s' (%s)", trackTitle, releases[0].Title, releases[0].ID) 258 r := releases[0] 259 return &r 260 } ··· 282 } 283 284 firstResult := res[0] 285 + firstResultAlbum := mb.GetBestRelease(firstResult.Releases, firstResult.Title) 286 287 // woof. we Might not have any ISRCs! 288 var bestISRC string
+47 -42
service/spotify/spotify.go
··· 9 "log" 10 "net/http" 11 "net/url" 12 "strings" 13 "sync" 14 "time" ··· 34 userTracks map[int64]*models.Track 35 userTokens map[int64]string 36 mu sync.RWMutex 37 } 38 39 func NewSpotifyService(database *db.DB, atprotoService *atprotoauth.ATprotoAuthService, musicBrainzService *musicbrainz.MusicBrainzService) *SpotifyService { 40 return &SpotifyService{ 41 DB: database, 42 atprotoService: atprotoService, 43 mb: musicBrainzService, 44 userTracks: make(map[int64]*models.Track), 45 userTokens: make(map[int64]string), 46 } 47 } 48 49 func (s *SpotifyService) SubmitTrackToPDS(did string, track *models.Track, ctx context.Context) error { 50 client, err := s.atprotoService.GetATProtoClient() 51 if err != nil || client == nil { 52 - log.Printf("Error getting ATProto client: %v", err) 53 return fmt.Errorf("failed to get ATProto client: %w", err) 54 } 55 ··· 110 111 var out atproto.RepoCreateRecord_Output 112 if err := xrpcClient.Do(ctx, authArgs, xrpc.Procedure, "application/json", "com.atproto.repo.createRecord", nil, input, &out); err != nil { 113 - log.Printf("Error creating record for DID %s: %v. Input: %+v", did, err, input) 114 return fmt.Errorf("failed to create record on PDS for DID %s: %w", did, err) 115 } 116 117 - log.Printf("Successfully submitted track '%s' to PDS for DID %s. Record URI: %s", track.Name, did, out.Uri) 118 return nil 119 } 120 121 func (s *SpotifyService) SetAccessToken(token string, refreshToken string, userId int64, hasSession bool) (int64, error) { 122 userID, err := s.identifyAndStoreUser(token, refreshToken, userId, hasSession) 123 if err != nil { 124 - log.Printf("Error identifying and storing user: %v", err) 125 return 0, err 126 } 127 return userID, nil ··· 130 func (s *SpotifyService) identifyAndStoreUser(token string, refreshToken string, userId int64, hasSession bool) (int64, error) { 131 userProfile, err := s.fetchSpotifyProfile(token) 132 if err != nil { 133 - log.Printf("Error fetching Spotify profile: %v", err) 134 return 0, err 135 } 136 137 - fmt.Printf("uid: %d hasSession: %t", userId, hasSession) 138 139 user, err := s.DB.GetUserBySpotifyID(userProfile.ID) 140 if err != nil { 141 // This error might mean DB connection issue, not just user not found. 142 - log.Printf("Error checking for user by Spotify ID %s: %v", userProfile.ID, err) 143 return 0, err 144 } 145 ··· 148 // We don't intend users to log in via spotify! 149 if user == nil { 150 if !hasSession { 151 - log.Printf("User does not seem to exist") 152 return 0, fmt.Errorf("user does not seem to exist") 153 } else { 154 // overwrite prev user 155 user, err = s.DB.AddSpotifySession(userId, userProfile.DisplayName, userProfile.Email, userProfile.ID, token, refreshToken, tokenExpiryTime) 156 if err != nil { 157 - log.Printf("Error adding Spotify session for user ID %d: %v", userId, err) 158 return 0, err 159 } 160 } ··· 162 err = s.DB.UpdateUserToken(user.ID, token, refreshToken, tokenExpiryTime) 163 if err != nil { 164 // for now log and continue 165 - log.Printf("Error updating user token for user ID %d: %v", user.ID, err) 166 } else { 167 - log.Printf("Updated token for existing user: %s (ID: %d)", *user.Username, user.ID) 168 } 169 } 170 user.AccessToken = &token ··· 174 s.userTokens[user.ID] = token 175 s.mu.Unlock() 176 177 - log.Printf("User authenticated via Spotify: %s (ID: %d)", *user.Username, user.ID) 178 return user.ID, nil 179 } 180 ··· 203 token, err := s.refreshTokenInner(user.ID) 204 if err != nil { 205 //Probably should remove the access token and refresh in long run? 206 - log.Printf("Error refreshing token for user %d: %v", user.ID, err) 207 continue 208 } 209 s.userTokens[user.ID] = token 210 } 211 } 212 213 - log.Printf("Loaded %d active users with valid tokens", count) 214 return nil 215 } 216 ··· 280 // Also clear the bad refresh token from the DB 281 updateErr := s.DB.UpdateUserToken(userID, "", "", time.Now().UTC()) // Clear tokens 282 if updateErr != nil { 283 - log.Printf("Failed to clear bad refresh token for user %d: %v", userID, updateErr) 284 } 285 return "", fmt.Errorf("spotify token refresh failed (%d): %s", resp.StatusCode, string(body)) 286 } ··· 306 // Update DB 307 if err := s.DB.UpdateUserToken(userID, tokenResponse.AccessToken, newRefreshToken, newExpiry); err != nil { 308 // Log error but continue, as we have the token in memory 309 - log.Printf("Error updating user token in DB for user %d after refresh: %v", userID, err) 310 } 311 312 // Update in-memory cache ··· 314 s.userTokens[userID] = tokenResponse.AccessToken 315 s.mu.Unlock() 316 317 - log.Printf("Successfully refreshed token for user %d", userID) 318 return tokenResponse.AccessToken, nil 319 } 320 ··· 329 func (s *SpotifyService) RefreshExpiredTokens() { 330 users, err := s.DB.GetUsersWithExpiredTokens() 331 if err != nil { 332 - log.Printf("Error fetching users with expired tokens: %v", err) 333 return 334 } 335 ··· 344 345 if err != nil { 346 // just print out errors here for now 347 - log.Printf("Error from service/spotify/spotify.go when refreshing tokens: %s", err.Error()) 348 } 349 350 refreshed++ 351 } 352 353 if refreshed > 0 { 354 - log.Printf("Refreshed tokens for %d users", refreshed) 355 } 356 } 357 ··· 412 tracks, err := s.DB.GetRecentTracks(userID, 20) 413 if err != nil { 414 http.Error(w, "Error retrieving track history", http.StatusInternalServerError) 415 - log.Printf("Error retrieving track history: %v", err) 416 return 417 } 418 ··· 454 455 // oops, token expired or other client error 456 if resp.StatusCode == 401 && attempt == 0 { // Only refresh on 401 on the first attempt 457 - log.Printf("Spotify token potentially expired for user %d, attempting refresh...", userID) 458 newAccessToken, refreshErr := s.refreshTokenInner(userID) 459 if refreshErr != nil { 460 - log.Printf("Token refresh failed for user %d: %v", userID, refreshErr) 461 // No point retrying if refresh failed 462 return nil, fmt.Errorf("spotify token expired or invalid for user %d and refresh failed: %w", userID, refreshErr) 463 } 464 - log.Printf("Token refreshed for user %d, retrying request...", userID) 465 token = newAccessToken // Update token for the next attempt 466 req.Header.Set("Authorization", "Bearer "+token) // Update header for retry 467 continue // Go to next attempt in the loop ··· 555 for range ticker.C { 556 err := s.LoadAllUsers() 557 if err != nil { 558 - log.Printf("Error loading spotify users: %v", err) 559 continue 560 } 561 // copy userIDs to avoid holding the lock too long ··· 569 for _, userID := range userIDs { 570 track, err := s.FetchCurrentTrack(userID) 571 if err != nil { 572 - log.Printf("Error fetching track for user %d: %v", userID, err) 573 continue 574 } 575 ··· 603 604 // just log when we stamp tracks 605 if isNewTrack && isLastTrackStamped && !currentTrack.HasStamped { 606 - log.Printf("User %d stamped (previous) track: %s by %s", userID, currentTrack.Name, currentTrack.Artist) 607 currentTrack.HasStamped = true 608 if currentTrack.PlayID != 0 { 609 s.DB.UpdateTrack(currentTrack.PlayID, currentTrack) 610 611 - log.Printf("Updated!") 612 } 613 } 614 615 if isStamped && !currentTrack.HasStamped { 616 - log.Printf("User %d stamped track: %s by %s", userID, track.Name, track.Artist) 617 track.HasStamped = true 618 // if currenttrack has a playid and the last track is the same as the current track 619 if !isNewTrack && currentTrack.PlayID != 0 { ··· 624 s.userTracks[userID] = track 625 s.mu.Unlock() 626 627 - log.Printf("Updated!") 628 } 629 } 630 631 if isNewTrack { 632 id, err := s.DB.SaveTrack(userID, track) 633 if err != nil { 634 - log.Printf("Error saving track for user %d: %v", userID, err) 635 continue 636 } 637 ··· 645 // The 'track' variable is *models.Track and has been saved to DB, PlayID is populated. 646 dbUser, errUser := s.DB.GetUserByID(userID) // Fetch user by their internal ID 647 if errUser != nil { 648 - log.Printf("User %d: Error fetching user details for PDS submission: %v", userID, errUser) 649 } else if dbUser == nil { 650 - log.Printf("User %d: User not found in DB. Skipping PDS submission.", userID) 651 } else if dbUser.ATProtoDID == nil || *dbUser.ATProtoDID == "" { 652 - log.Printf("User %d (%d): ATProto DID not set. Skipping PDS submission for track '%s'.", userID, dbUser.ATProtoDID, track.Name) 653 } else { 654 // User has a DID, proceed with hydration and submission 655 var trackToSubmitToPDS *models.Track = track // Default to the original track (already *models.Track) ··· 658 // and it returns *models.Track 659 hydratedTrack, errHydrate := musicbrainz.HydrateTrack(s.mb, *track) 660 if errHydrate != nil { 661 - log.Printf("User %d (%d): Error hydrating track '%s' with MusicBrainz: %v. Proceeding with original track data for PDS.", userID, dbUser.ATProtoDID, track.Name, errHydrate) 662 } else { 663 - log.Printf("User %d (%d): Successfully hydrated track '%s' with MusicBrainz.", userID, dbUser.ATProtoDID, track.Name) 664 trackToSubmitToPDS = hydratedTrack // hydratedTrack is *models.Track 665 } 666 } else { 667 - log.Printf("User %d (%d): MusicBrainz service not configured. Proceeding with original track data for PDS.", userID, dbUser.ATProtoDID) 668 } 669 670 artistName := "Unknown Artist" ··· 672 artistName = trackToSubmitToPDS.Artist[0].Name 673 } 674 675 - log.Printf("User %d (%d): Attempting to submit track '%s' by %s to PDS (DID: %s)", userID, dbUser.ATProtoDID, trackToSubmitToPDS.Name, artistName, *dbUser.ATProtoDID) 676 // Use context.Background() for now, or pass down a context if available 677 if errPDS := s.SubmitTrackToPDS(*dbUser.ATProtoDID, trackToSubmitToPDS, context.Background()); errPDS != nil { 678 - log.Printf("User %d (%d): Error submitting track '%s' to PDS: %v", userID, dbUser.ATProtoDID, trackToSubmitToPDS.Name, errPDS) 679 } else { 680 - log.Printf("User %d (%d): Successfully submitted track '%s' to PDS.", userID, dbUser.ATProtoDID, trackToSubmitToPDS.Name) 681 } 682 } 683 // End of PDS submission block 684 685 - log.Printf("User %d is listening to: %s by %s", userID, track.Name, track.Artist) 686 } 687 } 688 689 //unloading users to save memory and make sure we get new signups 690 err = s.LoadAllUsers() 691 if err != nil { 692 - log.Printf("Error loading spotify users: %v", err) 693 } 694 } 695 }
··· 9 "log" 10 "net/http" 11 "net/url" 12 + "os" 13 "strings" 14 "sync" 15 "time" ··· 35 userTracks map[int64]*models.Track 36 userTokens map[int64]string 37 mu sync.RWMutex 38 + logger *log.Logger 39 } 40 41 func NewSpotifyService(database *db.DB, atprotoService *atprotoauth.ATprotoAuthService, musicBrainzService *musicbrainz.MusicBrainzService) *SpotifyService { 42 + logger := log.New(os.Stdout, "spotify: ", log.LstdFlags|log.Lmsgprefix) 43 + 44 return &SpotifyService{ 45 DB: database, 46 atprotoService: atprotoService, 47 mb: musicBrainzService, 48 userTracks: make(map[int64]*models.Track), 49 userTokens: make(map[int64]string), 50 + logger: logger, 51 } 52 } 53 54 func (s *SpotifyService) SubmitTrackToPDS(did string, track *models.Track, ctx context.Context) error { 55 client, err := s.atprotoService.GetATProtoClient() 56 if err != nil || client == nil { 57 + s.logger.Printf("Error getting ATProto client: %v", err) 58 return fmt.Errorf("failed to get ATProto client: %w", err) 59 } 60 ··· 115 116 var out atproto.RepoCreateRecord_Output 117 if err := xrpcClient.Do(ctx, authArgs, xrpc.Procedure, "application/json", "com.atproto.repo.createRecord", nil, input, &out); err != nil { 118 + s.logger.Printf("Error creating record for DID %s: %v. Input: %+v", did, err, input) 119 return fmt.Errorf("failed to create record on PDS for DID %s: %w", did, err) 120 } 121 122 + s.logger.Printf("Successfully submitted track '%s' to PDS for DID %s. Record URI: %s", track.Name, did, out.Uri) 123 return nil 124 } 125 126 func (s *SpotifyService) SetAccessToken(token string, refreshToken string, userId int64, hasSession bool) (int64, error) { 127 userID, err := s.identifyAndStoreUser(token, refreshToken, userId, hasSession) 128 if err != nil { 129 + s.logger.Printf("Error identifying and storing user: %v", err) 130 return 0, err 131 } 132 return userID, nil ··· 135 func (s *SpotifyService) identifyAndStoreUser(token string, refreshToken string, userId int64, hasSession bool) (int64, error) { 136 userProfile, err := s.fetchSpotifyProfile(token) 137 if err != nil { 138 + s.logger.Printf("Error fetching Spotify profile: %v", err) 139 return 0, err 140 } 141 142 + s.logger.Printf("uid: %d hasSession: %t", userId, hasSession) 143 144 user, err := s.DB.GetUserBySpotifyID(userProfile.ID) 145 if err != nil { 146 // This error might mean DB connection issue, not just user not found. 147 + s.logger.Printf("Error checking for user by Spotify ID %s: %v", userProfile.ID, err) 148 return 0, err 149 } 150 ··· 153 // We don't intend users to log in via spotify! 154 if user == nil { 155 if !hasSession { 156 + s.logger.Printf("User does not seem to exist") 157 return 0, fmt.Errorf("user does not seem to exist") 158 } else { 159 // overwrite prev user 160 user, err = s.DB.AddSpotifySession(userId, userProfile.DisplayName, userProfile.Email, userProfile.ID, token, refreshToken, tokenExpiryTime) 161 if err != nil { 162 + s.logger.Printf("Error adding Spotify session for user ID %d: %v", userId, err) 163 return 0, err 164 } 165 } ··· 167 err = s.DB.UpdateUserToken(user.ID, token, refreshToken, tokenExpiryTime) 168 if err != nil { 169 // for now log and continue 170 + s.logger.Printf("Error updating user token for user ID %d: %v", user.ID, err) 171 } else { 172 + s.logger.Printf("Updated token for existing user: %s (ID: %d)", *user.Username, user.ID) 173 } 174 } 175 user.AccessToken = &token ··· 179 s.userTokens[user.ID] = token 180 s.mu.Unlock() 181 182 + s.logger.Printf("User authenticated via Spotify: %s (ID: %d)", *user.Username, user.ID) 183 return user.ID, nil 184 } 185 ··· 208 token, err := s.refreshTokenInner(user.ID) 209 if err != nil { 210 //Probably should remove the access token and refresh in long run? 211 + s.logger.Printf("Error refreshing token for user %d: %v", user.ID, err) 212 continue 213 } 214 s.userTokens[user.ID] = token 215 } 216 } 217 218 + s.logger.Printf("Loaded %d active users with valid tokens", count) 219 return nil 220 } 221 ··· 285 // Also clear the bad refresh token from the DB 286 updateErr := s.DB.UpdateUserToken(userID, "", "", time.Now().UTC()) // Clear tokens 287 if updateErr != nil { 288 + s.logger.Printf("Failed to clear bad refresh token for user %d: %v", userID, updateErr) 289 } 290 return "", fmt.Errorf("spotify token refresh failed (%d): %s", resp.StatusCode, string(body)) 291 } ··· 311 // Update DB 312 if err := s.DB.UpdateUserToken(userID, tokenResponse.AccessToken, newRefreshToken, newExpiry); err != nil { 313 // Log error but continue, as we have the token in memory 314 + s.logger.Printf("Error updating user token in DB for user %d after refresh: %v", userID, err) 315 } 316 317 // Update in-memory cache ··· 319 s.userTokens[userID] = tokenResponse.AccessToken 320 s.mu.Unlock() 321 322 + s.logger.Printf("Successfully refreshed token for user %d", userID) 323 return tokenResponse.AccessToken, nil 324 } 325 ··· 334 func (s *SpotifyService) RefreshExpiredTokens() { 335 users, err := s.DB.GetUsersWithExpiredTokens() 336 if err != nil { 337 + s.logger.Printf("Error fetching users with expired tokens: %v", err) 338 return 339 } 340 ··· 349 350 if err != nil { 351 // just print out errors here for now 352 + s.logger.Printf("Error from service/spotify/spotify.go when refreshing tokens: %s", err.Error()) 353 } 354 355 refreshed++ 356 } 357 358 if refreshed > 0 { 359 + s.logger.Printf("Refreshed tokens for %d users", refreshed) 360 } 361 } 362 ··· 417 tracks, err := s.DB.GetRecentTracks(userID, 20) 418 if err != nil { 419 http.Error(w, "Error retrieving track history", http.StatusInternalServerError) 420 + s.logger.Printf("Error retrieving track history: %v", err) 421 return 422 } 423 ··· 459 460 // oops, token expired or other client error 461 if resp.StatusCode == 401 && attempt == 0 { // Only refresh on 401 on the first attempt 462 + s.logger.Printf("Spotify token potentially expired for user %d, attempting refresh...", userID) 463 newAccessToken, refreshErr := s.refreshTokenInner(userID) 464 if refreshErr != nil { 465 + s.logger.Printf("Token refresh failed for user %d: %v", userID, refreshErr) 466 // No point retrying if refresh failed 467 return nil, fmt.Errorf("spotify token expired or invalid for user %d and refresh failed: %w", userID, refreshErr) 468 } 469 + s.logger.Printf("Token refreshed for user %d, retrying request...", userID) 470 token = newAccessToken // Update token for the next attempt 471 req.Header.Set("Authorization", "Bearer "+token) // Update header for retry 472 continue // Go to next attempt in the loop ··· 560 for range ticker.C { 561 err := s.LoadAllUsers() 562 if err != nil { 563 + s.logger.Printf("Error loading spotify users: %v", err) 564 continue 565 } 566 // copy userIDs to avoid holding the lock too long ··· 574 for _, userID := range userIDs { 575 track, err := s.FetchCurrentTrack(userID) 576 if err != nil { 577 + s.logger.Printf("Error fetching track for user %d: %v", userID, err) 578 continue 579 } 580 ··· 608 609 // just log when we stamp tracks 610 if isNewTrack && isLastTrackStamped && !currentTrack.HasStamped { 611 + s.logger.Printf("User %d stamped (previous) track: %s by %s", userID, currentTrack.Name, currentTrack.Artist) 612 currentTrack.HasStamped = true 613 if currentTrack.PlayID != 0 { 614 s.DB.UpdateTrack(currentTrack.PlayID, currentTrack) 615 616 + s.logger.Printf("Updated!") 617 } 618 } 619 620 if isStamped && !currentTrack.HasStamped { 621 + s.logger.Printf("User %d stamped track: %s by %s", userID, track.Name, track.Artist) 622 track.HasStamped = true 623 // if currenttrack has a playid and the last track is the same as the current track 624 if !isNewTrack && currentTrack.PlayID != 0 { ··· 629 s.userTracks[userID] = track 630 s.mu.Unlock() 631 632 + s.logger.Printf("Updated!") 633 } 634 } 635 636 if isNewTrack { 637 id, err := s.DB.SaveTrack(userID, track) 638 if err != nil { 639 + s.logger.Printf("Error saving track for user %d: %v", userID, err) 640 continue 641 } 642 ··· 650 // The 'track' variable is *models.Track and has been saved to DB, PlayID is populated. 651 dbUser, errUser := s.DB.GetUserByID(userID) // Fetch user by their internal ID 652 if errUser != nil { 653 + s.logger.Printf("User %d: Error fetching user details for PDS submission: %v", userID, errUser) 654 } else if dbUser == nil { 655 + s.logger.Printf("User %d: User not found in DB. Skipping PDS submission.", userID) 656 } else if dbUser.ATProtoDID == nil || *dbUser.ATProtoDID == "" { 657 + s.logger.Printf("User %d (%d): ATProto DID not set. Skipping PDS submission for track '%s'.", userID, dbUser.ATProtoDID, track.Name) 658 } else { 659 // User has a DID, proceed with hydration and submission 660 var trackToSubmitToPDS *models.Track = track // Default to the original track (already *models.Track) ··· 663 // and it returns *models.Track 664 hydratedTrack, errHydrate := musicbrainz.HydrateTrack(s.mb, *track) 665 if errHydrate != nil { 666 + s.logger.Printf("User %d (%d): Error hydrating track '%s' with MusicBrainz: %v. Proceeding with original track data for PDS.", userID, dbUser.ATProtoDID, track.Name, errHydrate) 667 } else { 668 + s.logger.Printf("User %d (%d): Successfully hydrated track '%s' with MusicBrainz.", userID, dbUser.ATProtoDID, track.Name) 669 trackToSubmitToPDS = hydratedTrack // hydratedTrack is *models.Track 670 } 671 } else { 672 + s.logger.Printf("User %d (%d): MusicBrainz service not configured. Proceeding with original track data for PDS.", userID, dbUser.ATProtoDID) 673 } 674 675 artistName := "Unknown Artist" ··· 677 artistName = trackToSubmitToPDS.Artist[0].Name 678 } 679 680 + s.logger.Printf("User %d (%d): Attempting to submit track '%s' by %s to PDS (DID: %s)", userID, dbUser.ATProtoDID, trackToSubmitToPDS.Name, artistName, *dbUser.ATProtoDID) 681 // Use context.Background() for now, or pass down a context if available 682 if errPDS := s.SubmitTrackToPDS(*dbUser.ATProtoDID, trackToSubmitToPDS, context.Background()); errPDS != nil { 683 + s.logger.Printf("User %d (%d): Error submitting track '%s' to PDS: %v", userID, dbUser.ATProtoDID, trackToSubmitToPDS.Name, errPDS) 684 } else { 685 + s.logger.Printf("User %d (%d): Successfully submitted track '%s' to PDS.", userID, dbUser.ATProtoDID, trackToSubmitToPDS.Name) 686 } 687 } 688 // End of PDS submission block 689 690 + s.logger.Printf("User %d is listening to: %s by %s", userID, track.Name, track.Artist) 691 } 692 } 693 694 //unloading users to save memory and make sure we get new signups 695 err = s.LoadAllUsers() 696 if err != nil { 697 + s.logger.Printf("Error loading spotify users: %v", err) 698 } 699 } 700 }