sarsoo/Selector
1
0
Fork 0
Code Issues 21 Pull Requests Actions Packages Projects Releases Wiki Activity

removing $ from logging, using scopes

Browse Source
This commit is contained in:
andy 2022-07-01 22:04:17 +01:00
parent e2fcc58877
commit 8c9e9c637b
23 changed files with 117 additions and 73 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

17
Selector.CLI/nlog.config
View File

@ -7,8 +7,11 @@
internalLogFile="./log/selector.nlog.log" internalLogFile="./log/selector.nlog.log"
internalLogLevel="Info" > internalLogLevel="Info" >
<variable name="scopeFormat"
value="${all-event-properties:format=[[key]\:[value]]:includeScopeProperties=true:separator= }"/>
<variable name="format" <variable name="format"
value="${longdate}|${level:uppercase=true}|${callsite}:${callsite-linenumber}|${message}${onexception:inner=${newline}}${exception:format=tostring,data:exceptionDataSeparator=\r\n}"/> value="${longdate}|${level:uppercase=true}|${callsite}:${callsite-linenumber}|${message}${onexception:inner=${newline}}${exception:format=tostring,data:exceptionDataSeparator=\r\n}${newline} ${scopeFormat}"/>
<!-- the targets to write to --> <!-- the targets to write to -->
<targets> <targets>
@ -21,15 +24,21 @@
name="tracefile" name="tracefile"
fileName="./log/selector.trace-${shortdate}.log" fileName="./log/selector.trace-${shortdate}.log"
layout="${format}" /> layout="${format}" />
<target xsi:type="Console" <target xsi:type="ColoredConsole"
name="logconsole" name="logconsole"
layout="${format}" /> layout="${format}" />
</targets> </targets>
<!-- rules to map from logger name to target --> <!-- rules to map from logger name to target -->
<rules> <rules>
<logger name="*" minlevel="Debug" writeTo="logfile" /> <!--<logger name="*" minlevel="Debug" writeTo="logfile" />-->
<logger name="*" minlevel="Trace" writeTo="tracefile" /> <logger name="Selector.*" minlevel="Debug" writeTo="logfile" />
<logger name="Microsoft.*" minlevel="Warning" writeTo="logfile" />
<!--<logger name="*" minlevel="Trace" writeTo="tracefile" />-->
<logger name="Selector.*" minlevel="Debug" writeTo="tracefile" />
<logger name="Microsoft.*" minlevel="Warning" writeTo="tracefile" />
<logger name="Selector.*" minlevel="Debug" writeTo="logconsole" /> <logger name="Selector.*" minlevel="Debug" writeTo="logconsole" />
<logger name="Microsoft.*" minlevel="Warning" writeTo="logconsole" /> <logger name="Microsoft.*" minlevel="Warning" writeTo="logconsole" />
</rules> </rules>

4
Selector.Cache/Consumer/AudioInjectorCaching.cs
View File

@ -47,11 +47,11 @@ namespace Selector.Cache
{ {
var payload = JsonSerializer.Serialize(e.Features, JsonContext.Default.TrackAudioFeatures); var payload = JsonSerializer.Serialize(e.Features, JsonContext.Default.TrackAudioFeatures);
Logger.LogTrace($"Caching current for [{e.Track.DisplayString()}]"); Logger.LogTrace("Caching current for [{track}]", e.Track.DisplayString());
var resp = await Db.StringSetAsync(Key.AudioFeature(e.Track.Id), payload, expiry: CacheExpiry); var resp = await Db.StringSetAsync(Key.AudioFeature(e.Track.Id), payload, expiry: CacheExpiry);
Logger.LogDebug($"Cached audio feature for [{e.Track.DisplayString()}], {(resp ? "value set" : "value NOT set")}"); Logger.LogDebug("Cached audio feature for [{track}], {state}", e.Track.DisplayString(), (resp ? "value set" : "value NOT set"));
} }
} }
} }

6
Selector.Cache/Consumer/CacheWriterConsumer.cs
View File

@ -50,13 +50,15 @@ namespace Selector.Cache
public async Task AsyncCallback(ListeningChangeEventArgs e) public async Task AsyncCallback(ListeningChangeEventArgs e)
{ {
using var scope = Logger.GetListeningEventArgsScope(e);
var payload = JsonSerializer.Serialize((CurrentlyPlayingDTO) e, JsonContext.Default.CurrentlyPlayingDTO); var payload = JsonSerializer.Serialize((CurrentlyPlayingDTO) e, JsonContext.Default.CurrentlyPlayingDTO);
Logger.LogTrace($"Caching current for [{e.Id}/{e.SpotifyUsername}]"); Logger.LogTrace("Caching current");
var resp = await Db.StringSetAsync(Key.CurrentlyPlaying(e.Id), payload, expiry: CacheExpiry); var resp = await Db.StringSetAsync(Key.CurrentlyPlaying(e.Id), payload, expiry: CacheExpiry);
Logger.LogDebug($"Cached current for [{e.Id}/{e.SpotifyUsername}], {(resp ? "value set" : "value NOT set")}"); Logger.LogDebug("Cached current, {state}", (resp ? "value set" : "value NOT set"));
} }

4
Selector.Cache/Consumer/PlayCounterCaching.cs
View File

@ -52,7 +52,7 @@ namespace Selector.Cache
public async Task AsyncCacheCallback(PlayCount e) public async Task AsyncCacheCallback(PlayCount e)
{ {
var track = e.ListeningEvent.Current.Item as FullTrack; var track = e.ListeningEvent.Current.Item as FullTrack;
Logger.LogTrace($"Caching play count for [{track.DisplayString()}]"); Logger.LogTrace("Caching play count for [{track}]", track.DisplayString());
var tasks = new Task[] var tasks = new Task[]
{ {
@ -64,7 +64,7 @@ namespace Selector.Cache
await Task.WhenAll(tasks); await Task.WhenAll(tasks);
Logger.LogDebug($"Cached play count for [{track.DisplayString()}]"); Logger.LogDebug("Cached play count for [{track}]", track.DisplayString());
} }
} }
} }

6
Selector.Cache/Consumer/PublisherConsumer.cs
View File

@ -48,14 +48,16 @@ namespace Selector.Cache
public async Task AsyncCallback(ListeningChangeEventArgs e) public async Task AsyncCallback(ListeningChangeEventArgs e)
{ {
using var scope = Logger.GetListeningEventArgsScope(e);
var payload = JsonSerializer.Serialize((CurrentlyPlayingDTO) e, JsonContext.Default.CurrentlyPlayingDTO); var payload = JsonSerializer.Serialize((CurrentlyPlayingDTO) e, JsonContext.Default.CurrentlyPlayingDTO);
Logger.LogTrace($"Publishing current for [{e.Id}/{e.SpotifyUsername}]"); Logger.LogTrace("Publishing current");
// TODO: currently using spotify username for cache key, use db username // TODO: currently using spotify username for cache key, use db username
var receivers = await Subscriber.PublishAsync(Key.CurrentlyPlaying(e.Id), payload); var receivers = await Subscriber.PublishAsync(Key.CurrentlyPlaying(e.Id), payload);
Logger.LogDebug($"Published current for [{e.Id}/{e.SpotifyUsername}], {receivers} receivers"); Logger.LogDebug("Published current, {receivers} receivers", receivers);
} }
public void Subscribe(IWatcher watch = null) public void Subscribe(IWatcher watch = null)

6
Selector.Cache/Services/PlayCountPuller.cs
View File

@ -110,7 +110,7 @@ namespace Selector.Cache
} }
else else
{ {
Logger.LogDebug($"Track info error [{username}] [{trackHttp.Result.Status}]"); Logger.LogDebug("Track info error [{username}] [{status}]", username, trackHttp.Result.Status);
} }
} }
@ -122,7 +122,7 @@ namespace Selector.Cache
} }
else else
{ {
Logger.LogDebug($"Album info error [{username}] [{albumHttp.Result.Status}]"); Logger.LogDebug("Album info error [{username}] [{status}]", username, albumHttp.Result.Status);
} }
} }
@ -136,7 +136,7 @@ namespace Selector.Cache
} }
else else
{ {
Logger.LogDebug($"User info error [{username}] [{userHttp.Result.Status}]"); Logger.LogDebug("User info error [{username}] [{userHttp.Result.Status}]", username, userHttp.Result.Status);
} }
} }

2
Selector.Event/CacheMappings/NowPlayingMapping.cs
View File

@ -41,7 +41,7 @@ namespace Selector.Events
} }
catch (Exception e) catch (Exception e)
{ {
Logger.LogError(e, $"Error parsing new currently playing [{message}]"); Logger.LogError(e, "Error parsing new currently playing [{message}]", message);
} }
}); });
} }

2
Selector.Model/ApplicationDbContext.cs
View File

@ -97,7 +97,7 @@ namespace Selector.Model
{ {
if(Watcher.Any(w => w.UserId == userId && w.Type == WatcherType.Player)) if(Watcher.Any(w => w.UserId == userId && w.Type == WatcherType.Player))
{ {
Logger.LogWarning($"Trying to create more than one player watcher for user [{userId}]"); Logger.LogWarning("Trying to create more than one player watcher for user [{id}]", userId);
return; return;
} }

4
Selector.Web/Areas/Identity/Pages/Account/Login.cshtml.cs
View File

@ -85,7 +85,7 @@ namespace Selector.Web.Areas.Identity.Pages.Account
var result = await _signInManager.PasswordSignInAsync(Input.Username, Input.Password, Input.RememberMe, lockoutOnFailure: false); var result = await _signInManager.PasswordSignInAsync(Input.Username, Input.Password, Input.RememberMe, lockoutOnFailure: false);
if (result.Succeeded) if (result.Succeeded)
{ {
_logger.LogInformation($"[{Input.Username}] logged in."); _logger.LogInformation("[{username}] logged in.", Input.Username);
return LocalRedirect(returnUrl); return LocalRedirect(returnUrl);
} }
if (result.RequiresTwoFactor) if (result.RequiresTwoFactor)
@ -94,7 +94,7 @@ namespace Selector.Web.Areas.Identity.Pages.Account
} }
if (result.IsLockedOut) if (result.IsLockedOut)
{ {
_logger.LogWarning($"[{Input.Username}] locked out."); _logger.LogWarning("[{username}] locked out.", Input.Username);
return RedirectToPage("./Lockout"); return RedirectToPage("./Lockout");
} }
else else

4
Selector.Web/Areas/Identity/Pages/Account/Manage/Spotify.cshtml.cs
View File

@ -67,14 +67,14 @@ namespace Selector.Web.Areas.Identity.Pages.Account.Manage
if(Config.ClientId is null) if(Config.ClientId is null)
{ {
Logger.LogError($"Cannot link user, no Spotify client ID"); Logger.LogError("Cannot link user, no Spotify client ID");
StatusMessage = "Could not link Spotify, no app credentials"; StatusMessage = "Could not link Spotify, no app credentials";
return RedirectToPage(); return RedirectToPage();
} }
if (Config.ClientSecret is null) if (Config.ClientSecret is null)
{ {
Logger.LogError($"Cannot link user, no Spotify client secret"); Logger.LogError("Cannot link user, no Spotify client secret");
StatusMessage = "Could not link Spotify, no app credentials"; StatusMessage = "Could not link Spotify, no app credentials";
return RedirectToPage(); return RedirectToPage();
} }

4
Selector.Web/Controller/SpotifyController.cs
View File

@ -42,14 +42,14 @@ namespace Selector.Web.Controller
{ {
if (Config.ClientId is null) if (Config.ClientId is null)
{ {
Logger.LogError($"Cannot link user, no Spotify client ID"); Logger.LogError("Cannot link user, no Spotify client ID");
TempData["StatusMessage"] = "Could not link Spotify, no app credentials"; TempData["StatusMessage"] = "Could not link Spotify, no app credentials";
return Redirect(ManageSpotifyPath); return Redirect(ManageSpotifyPath);
} }
if (Config.ClientSecret is null) if (Config.ClientSecret is null)
{ {
Logger.LogError($"Cannot link user, no Spotify client secret"); Logger.LogError("Cannot link user, no Spotify client secret");
TempData["StatusMessage"] = "Could not link Spotify, no app credentials"; TempData["StatusMessage"] = "Could not link Spotify, no app credentials";
return Redirect(ManageSpotifyPath); return Redirect(ManageSpotifyPath);
} }

4
Selector.Web/Controller/UserController.cs
View File

@ -53,7 +53,7 @@ namespace Selector.Web.Controller
if (user is null) if (user is null)
{ {
Logger.LogWarning($"No user found for [{userId}], even though the 'me' route was used"); Logger.LogWarning("No user found for [{id}], even though the 'me' route was used", userId);
return NotFound(); return NotFound();
} }
@ -61,7 +61,7 @@ namespace Selector.Web.Controller
if (!isAuthed.Succeeded) if (!isAuthed.Succeeded)
{ {
Logger.LogWarning($"User [{user.UserName}] not authorised to view themselves?"); Logger.LogWarning("User [{username}] not authorised to view themselves?", user.UserName);
return Unauthorized(); return Unauthorized();
} }

11
Selector.Web/nlog.config
View File

@ -11,8 +11,11 @@
<add assembly="NLog.Web.AspNetCore"/> <add assembly="NLog.Web.AspNetCore"/>
</extensions> </extensions>
<variable name="scopeFormat"
value="${all-event-properties:format=[[key]\:[value]]:includeScopeProperties=true:separator= }"/>
<variable name="format" <variable name="format"
value="${longdate}|${level:uppercase=true}|${callsite}:${callsite-linenumber}|${message}${onexception:inner=${newline}}${exception:format=tostring,data:exceptionDataSeparator=\r\n}"/> value="${longdate}|${level:uppercase=true}|${callsite}:${callsite-linenumber}|${message}${onexception:inner=${newline}}${exception:format=tostring,data:exceptionDataSeparator=\r\n}${newline} ${scopeFormat}"/>
<!-- the targets to write to --> <!-- the targets to write to -->
<targets> <targets>
@ -25,14 +28,14 @@
name="tracefile" name="tracefile"
fileName="./log/selector.trace-${shortdate}.log" fileName="./log/selector.trace-${shortdate}.log"
layout="${format}" /> layout="${format}" />
<target xsi:type="Console" <target xsi:type="ColoredConsole"
name="logconsole" name="logconsole"
layout="${format}" /> layout="${format}" />
</targets> </targets>
<!-- rules to map from logger name to target --> <!-- rules to map from logger name to target -->
<rules> <rules>
<logger name="*" minlevel="Trace" writeTo="tracefile" /> <!--<logger name="*" minlevel="Trace" writeTo="tracefile" />-->
<logger name="Selector.*" minlevel="Debug" writeTo="logconsole" /> <logger name="Selector.*" minlevel="Debug" writeTo="logconsole" />
<!--Output hosting lifetime messages to console target for faster startup detection --> <!--Output hosting lifetime messages to console target for faster startup detection -->
@ -42,6 +45,6 @@
<logger name="Microsoft.*" maxlevel="Info" final="true" /> <logger name="Microsoft.*" maxlevel="Info" final="true" />
<logger name="System.Net.Http.*" maxlevel="Info" final="true" /> <logger name="System.Net.Http.*" maxlevel="Info" final="true" />
<logger name="*" minlevel="Debug" writeTo="logfile" /> <!--<logger name="*" minlevel="Debug" writeTo="logfile" />-->
</rules> </rules>
</nlog> </nlog>

16
Selector/Consumers/AudioFeatureInjector.cs
View File

@ -51,6 +51,8 @@ namespace Selector
public async Task AsyncCallback(ListeningChangeEventArgs e) public async Task AsyncCallback(ListeningChangeEventArgs e)
{ {
using var scope = Logger.GetListeningEventArgsScope(e);
if (e.Current.Item is FullTrack track) if (e.Current.Item is FullTrack track)
{ {
if (string.IsNullOrWhiteSpace(track.Id)) return; if (string.IsNullOrWhiteSpace(track.Id)) return;
@ -58,7 +60,7 @@ namespace Selector
try { try {
Logger.LogTrace("Making Spotify call"); Logger.LogTrace("Making Spotify call");
var audioFeatures = await TrackClient.GetAudioFeatures(track.Id); var audioFeatures = await TrackClient.GetAudioFeatures(track.Id);
Logger.LogDebug($"Adding audio features [{track.DisplayString()}]: [{audioFeatures.DisplayString()}]"); Logger.LogDebug("Adding audio features [{track}]: [{audio_features}]", track.DisplayString(), audioFeatures.DisplayString());
var analysedTrack = AnalysedTrack.From(track, audioFeatures); var analysedTrack = AnalysedTrack.From(track, audioFeatures);
@ -67,17 +69,17 @@ namespace Selector
} }
catch (APIUnauthorizedException ex) catch (APIUnauthorizedException ex)
{ {
Logger.LogDebug($"Unauthorised error: [{ex.Message}] (should be refreshed and retried?)"); Logger.LogDebug("Unauthorised error: [{message}] (should be refreshed and retried?)", ex.Message);
//throw ex; //throw ex;
} }
catch (APITooManyRequestsException ex) catch (APITooManyRequestsException ex)
{ {
Logger.LogDebug($"Too many requests error: [{ex.Message}]"); Logger.LogDebug("Too many requests error: [{message}]", ex.Message);
throw ex; throw ex;
} }
catch (APIException ex) catch (APIException ex)
{ {
Logger.LogDebug($"API error: [{ex.Message}]"); Logger.LogDebug("API error: [{message}]", ex.Message);
throw ex; throw ex;
} }
} }
@ -85,15 +87,15 @@ namespace Selector
{ {
if (string.IsNullOrWhiteSpace(episode.Id)) return; if (string.IsNullOrWhiteSpace(episode.Id)) return;
Logger.LogDebug($"Ignoring podcast episdoe [{episode.DisplayString()}]"); Logger.LogDebug("Ignoring podcast episdoe [{episode}]", episode.DisplayString());
} }
else if (e.Current.Item is null) else if (e.Current.Item is null)
{ {
Logger.LogDebug($"Skipping audio feature pulling for null item [{e.Current.DisplayString()}]"); Logger.LogDebug("Skipping audio feature pulling for null item [{context}]", e.Current.DisplayString());
} }
else else
{ {
Logger.LogError($"Unknown item pulled from API [{e.Current.Item}]"); Logger.LogError("Unknown item pulled from API [{item}]", e.Current.Item);
} }
} }

24
Selector/Consumers/PlayCounter.cs
View File

@ -68,6 +68,8 @@ namespace Selector
public async Task AsyncCallback(ListeningChangeEventArgs e) public async Task AsyncCallback(ListeningChangeEventArgs e)
{ {
using var scope = Logger.BeginScope(new Dictionary<string, object>() { { "spotify_username", e.SpotifyUsername }, { "id", e.Id }, { "username", Credentials.Username } });
if (Credentials is null || string.IsNullOrWhiteSpace(Credentials.Username)) if (Credentials is null || string.IsNullOrWhiteSpace(Credentials.Username))
{ {
Logger.LogDebug("No Last.fm username, skipping play count"); Logger.LogDebug("No Last.fm username, skipping play count");
@ -76,6 +78,8 @@ namespace Selector
if (e.Current.Item is FullTrack track) if (e.Current.Item is FullTrack track)
{ {
using var trackScope = Logger.BeginScope(new Dictionary<string, object>() { { "track", track.DisplayString() } });
Logger.LogTrace("Making Last.fm call"); Logger.LogTrace("Making Last.fm call");
var trackInfo = TrackClient.GetInfoAsync(track.Name, track.Artists[0].Name, username: Credentials?.Username); var trackInfo = TrackClient.GetInfoAsync(track.Name, track.Artists[0].Name, username: Credentials?.Username);
@ -95,12 +99,12 @@ namespace Selector
} }
else else
{ {
Logger.LogDebug($"Track info error [{e.Id}/{e.SpotifyUsername}] [{trackInfo.Result.Status}]"); Logger.LogDebug("Track info error [{status}]", trackInfo.Result.Status);
} }
} }
else else
{ {
Logger.LogError(trackInfo.Exception, $"Track info task faulted, [{e.Id}/{e.SpotifyUsername}] [{e.Current.DisplayString()}]"); Logger.LogError(trackInfo.Exception, "Track info task faulted, [{context}]", e.Current.DisplayString());
} }
if (albumInfo.IsCompletedSuccessfully) if (albumInfo.IsCompletedSuccessfully)
@ -111,12 +115,12 @@ namespace Selector
} }
else else
{ {
Logger.LogDebug($"Album info error [{e.Id}/{e.SpotifyUsername}] [{albumInfo.Result.Status}]"); Logger.LogDebug("Album info error [{status}]", albumInfo.Result.Status);
} }
} }
else else
{ {
Logger.LogError(albumInfo.Exception, $"Album info task faulted, [{e.Id}/{e.SpotifyUsername}] [{e.Current.DisplayString()}]"); Logger.LogError(albumInfo.Exception, "Album info task faulted, [{context}]", e.Current.DisplayString());
} }
//TODO: Add artist count //TODO: Add artist count
@ -129,15 +133,15 @@ namespace Selector
} }
else else
{ {
Logger.LogDebug($"User info error [{e.Id}/{e.SpotifyUsername}] [{userInfo.Result.Status}]"); Logger.LogDebug("User info error [{status}]", userInfo.Result.Status);
} }
} }
else else
{ {
Logger.LogError(userInfo.Exception, $"User info task faulted, [{e.Id}/{e.SpotifyUsername}] [{e.Current.DisplayString()}]"); Logger.LogError(userInfo.Exception, "User info task faulted, [{context}]", e.Current.DisplayString());
} }
Logger.LogDebug($"Adding Last.fm data [{e.Id}/{e.SpotifyUsername}/{Credentials.Username}] [{track.DisplayString()}], track: {trackCount}, album: {albumCount}, artist: {artistCount}, user: {userCount}"); Logger.LogDebug("Adding Last.fm data [{username}], track: {track_count}, album: {album_count}, artist: {artist_count}, user: {user_count}", Credentials.Username, trackCount, albumCount, artistCount, userCount);
PlayCount playCount = new() PlayCount playCount = new()
{ {
@ -155,15 +159,15 @@ namespace Selector
} }
else if (e.Current.Item is FullEpisode episode) else if (e.Current.Item is FullEpisode episode)
{ {
Logger.LogDebug($"Ignoring podcast episdoe [{episode.DisplayString()}]"); Logger.LogDebug("Ignoring podcast episdoe [{episode}]", episode.DisplayString());
} }
else if (e.Current.Item is null) else if (e.Current.Item is null)
{ {
Logger.LogDebug($"Skipping play count pulling for null item [{e.Current.DisplayString()}]"); Logger.LogDebug("Skipping play count pulling for null item [{context}]", e.Current.DisplayString());
} }
else else
{ {
Logger.LogError($"Unknown item pulled from API [{e.Current.Item}]"); Logger.LogError("Unknown item pulled from API [{item}]", e.Current.Item);
} }
} }

10
Selector/Consumers/WebHook.cs
View File

@ -79,23 +79,25 @@ namespace Selector
public async Task AsyncCallback(ListeningChangeEventArgs e) public async Task AsyncCallback(ListeningChangeEventArgs e)
{ {
using var scope = Logger.BeginScope(new Dictionary<string, object>() { { "spotify_username", e.SpotifyUsername }, { "id", e.Id }, { "name", Config.Name }, { "url", Config.Url } });
if (Config.ShouldRequest(e)) if (Config.ShouldRequest(e))
{ {
try try
{ {
Logger.LogDebug("[{name}] predicate passed, making request to [{url}]", Config.Name, Config.Url); Logger.LogDebug("Predicate passed, making request");
OnPredicatePass(new EventArgs()); OnPredicatePass(new EventArgs());
var response = await HttpClient.PostAsync(Config.Url, Config.Content, CancelToken); var response = await HttpClient.PostAsync(Config.Url, Config.Content, CancelToken);
if (response.IsSuccessStatusCode) if (response.IsSuccessStatusCode)
{ {
Logger.LogDebug("[{name}] request success", Config.Name); Logger.LogDebug("Request success");
OnSuccessfulRequest(new EventArgs()); OnSuccessfulRequest(new EventArgs());
} }
else else
{ {
Logger.LogDebug("[{name}] request failed [{error}] [{content}]", Config.Name, response.StatusCode, response.Content); Logger.LogDebug("Request failed [{error}] [{content}]", response.StatusCode, response.Content);
OnFailedRequest(new EventArgs()); OnFailedRequest(new EventArgs());
} }
} }
@ -110,7 +112,7 @@ namespace Selector
} }
else else
{ {
Logger.LogTrace("[{name}] predicate failed, skipping", Config.Name); Logger.LogTrace("Predicate failed, skipping");
} }
} }

12
Selector/Extensions/LoggingExtensions.cs Normal file
View File

@ -0,0 +1,12 @@
using System;
using System.Collections.Generic;
using Microsoft.Extensions.Logging;
namespace Selector
{
public static class LoggingExtensions
{
public static IDisposable GetListeningEventArgsScope(this ILogger logger, ListeningChangeEventArgs e) => logger.BeginScope(new Dictionary<string, object>() { { "spotify_username", e.SpotifyUsername }, { "id", e.Id } });
}
}

10
Selector/Scrobble/ScrobbleRequest.cs
View File

@ -50,7 +50,9 @@ namespace Selector
public Task Execute() public Task Execute()
{ {
logger.LogInformation("Scrobble request #{} for {} by {} from {} to {}", pageNumber, username, pageSize, from, to); using var scope = logger.BeginScope(new Dictionary<string, object>() { { "username", username }, { "page_number", pageNumber }, { "page_size", pageSize }, { "from", from }, { "to", to } });
logger.LogInformation("Starting request");
var netTime = Stopwatch.StartNew(); var netTime = Stopwatch.StartNew();
currentTask = userClient.GetRecentScrobbles(username, pagenumber: pageNumber, count: pageSize, from: from, to: to); currentTask = userClient.GetRecentScrobbles(username, pagenumber: pageNumber, count: pageSize, from: from, to: to);
@ -77,12 +79,12 @@ namespace Selector
{ {
if (Attempts < MaxAttempts) if (Attempts < MaxAttempts)
{ {
logger.LogDebug("Request failed for {}, #{} by {}: {}, retrying ({} of {})", username, pageNumber, pageSize, result.Status, Attempts + 1, MaxAttempts); logger.LogDebug("Request failed: {}, retrying ({} of {})", result.Status, Attempts + 1, MaxAttempts);
await Execute(); await Execute();
} }
else else
{ {
logger.LogDebug("Request failed for {}, #{} by {}: {}, max retries exceeded {}, not retrying", username, pageNumber, pageSize, result.Status, MaxAttempts); logger.LogDebug("Request failed: {}, max retries exceeded {}, not retrying", result.Status, MaxAttempts);
AggregateTaskSource.SetCanceled(); AggregateTaskSource.SetCanceled();
} }
} }
@ -95,7 +97,7 @@ namespace Selector
} }
catch(Exception e) catch(Exception e)
{ {
logger.LogError(e, "Error while making scrobble request #{} for {} by {} from {} to {} on attempt {}", pageNumber, username, pageSize, from, to, Attempts); logger.LogError(e, "Error while making scrobble request on attempt {}", Attempts);
Succeeded = false; Succeeded = false;
} }
}); });

2
Selector/Spotify/FactoryProvider/CachingRefreshTokenFactoryProvider.cs
View File

@ -35,7 +35,7 @@ namespace Selector
} }
else else
{ {
Logger.LogDebug($"New user token factory added [{userDetails.DisplayName}]"); Logger.LogDebug("New user token factory added [{spotify_name}]", userDetails.DisplayName);
Configs[userDetails.Id] = configProvider; Configs[userDetails.Id] = configProvider;
return configProvider; return configProvider;
} }

5
Selector/Watcher/BaseWatcher.cs
View File

@ -1,4 +1,5 @@
using System; using System;
using System.Collections.Generic;
using System.Diagnostics; using System.Diagnostics;
using System.Threading; using System.Threading;
using System.Threading.Tasks; using System.Threading.Tasks;
@ -26,6 +27,8 @@ namespace Selector
public async Task Watch(CancellationToken cancelToken) public async Task Watch(CancellationToken cancelToken)
{ {
using var logScope = Logger.BeginScope(new Dictionary<string, object>() { { "spotify_username", SpotifyUsername }, { "id", Id } });
Logger.LogDebug("Starting watcher"); Logger.LogDebug("Starting watcher");
while (true) { while (true) {
@ -46,7 +49,7 @@ namespace Selector
var waitTime = decimal.ToInt32(Math.Max(0, PollPeriod - ExecutionTimer.ElapsedMilliseconds)); var waitTime = decimal.ToInt32(Math.Max(0, PollPeriod - ExecutionTimer.ElapsedMilliseconds));
ExecutionTimer.Reset(); ExecutionTimer.Reset();
Logger.LogTrace($"Finished watch one, delaying \"{PollPeriod}\"ms (\"{waitTime}\"ms)..."); Logger.LogTrace("Finished watch one, delaying \"{poll_period}\"ms ({wait_time}ms)...", PollPeriod, waitTime);
await Task.Delay(waitTime, cancelToken); await Task.Delay(waitTime, cancelToken);
} }
} }

4
Selector/Watcher/Collection/WatcherCollection.cs
View File

@ -59,7 +59,7 @@ namespace Selector
{ {
if (IsRunning) return; if (IsRunning) return;
Logger.LogDebug($"Starting {Count} watcher(s)"); Logger.LogDebug("Starting {} watcher(s)", Count);
foreach(var watcher in Watchers) foreach(var watcher in Watchers)
{ {
watcher.Start(); watcher.Start();
@ -73,7 +73,7 @@ namespace Selector
try try
{ {
Logger.LogDebug($"Stopping {Count} watcher(s)"); Logger.LogDebug("Stopping {} watcher(s)", Count);
foreach (var watcher in Watchers) foreach (var watcher in Watchers)
{ {
watcher.Stop(); watcher.Stop();

21
Selector/Watcher/PlayerWatcher.cs
View File

@ -58,7 +58,10 @@ namespace Selector
try{ try{
Logger.LogTrace("Making Spotify call"); Logger.LogTrace("Making Spotify call");
var polledCurrent = await spotifyClient.GetCurrentPlayback(); var polledCurrent = await spotifyClient.GetCurrentPlayback();
Logger.LogTrace("Received Spotify call [{context}]", polledCurrent?.DisplayString());
using var polledLogScope = Logger.BeginScope(new Dictionary<string, object>() { { "context", polledCurrent?.DisplayString() } });
Logger.LogTrace("Received Spotify call");
if (polledCurrent != null) StoreCurrentPlaying(polledCurrent); if (polledCurrent != null) StoreCurrentPlaying(polledCurrent);
@ -76,18 +79,18 @@ namespace Selector
} }
catch(APIUnauthorizedException e) catch(APIUnauthorizedException e)
{ {
Logger.LogDebug($"Unauthorised error: [{e.Message}] (should be refreshed and retried?)"); Logger.LogDebug("Unauthorised error: [{message}] (should be refreshed and retried?)", e.Message);
//throw e; //throw e;
} }
catch(APITooManyRequestsException e) catch(APITooManyRequestsException e)
{ {
Logger.LogDebug($"Too many requests error: [{e.Message}]"); Logger.LogDebug("Too many requests error: [{message}]", e.Message);
await Task.Delay(e.RetryAfter, token); await Task.Delay(e.RetryAfter, token);
// throw e; // throw e;
} }
catch(APIException e) catch(APIException e)
{ {
Logger.LogDebug($"API error: [{e.Message}]"); Logger.LogDebug("API error: [{message}]", e.Message);
// throw e; // throw e;
} }
} }
@ -153,7 +156,7 @@ namespace Selector
case ({ Item: FullEpisode previousEp }, { Item: FullEpisode currentEp }): case ({ Item: FullEpisode previousEp }, { Item: FullEpisode currentEp }):
if (!eq.IsEqual(previousEp, currentEp)) if (!eq.IsEqual(previousEp, currentEp))
{ {
Logger.LogDebug($"Podcast changed: {previousEp.DisplayString()} -> {currentEp.DisplayString()}"); Logger.LogDebug("Podcast changed: {previous_ep} -> {current_ep}", previousEp.DisplayString(), currentEp.DisplayString());
OnItemChange(GetEvent()); OnItemChange(GetEvent());
} }
break; break;
@ -170,7 +173,7 @@ namespace Selector
} }
else if (!eq.IsEqual(Previous?.Context, Live?.Context)) else if (!eq.IsEqual(Previous?.Context, Live?.Context))
{ {
Logger.LogDebug($"Context changed: {Previous?.Context?.DisplayString() ?? "none"} -> {Live?.Context?.DisplayString() ?? "none"}"); Logger.LogDebug("Context changed: {previous_context} -> {live_context}", Previous?.Context?.DisplayString() ?? "none", Live?.Context?.DisplayString() ?? "none");
OnContextChange(GetEvent()); OnContextChange(GetEvent());
} }
} }
@ -193,7 +196,7 @@ namespace Selector
// IS PLAYING // IS PLAYING
if (Previous?.IsPlaying != Live?.IsPlaying) if (Previous?.IsPlaying != Live?.IsPlaying)
{ {
Logger.LogDebug($"Playing state changed: {Previous?.IsPlaying} -> {Live?.IsPlaying}"); Logger.LogDebug("Playing state changed: {previous_playing} -> {live_playing}", Previous?.IsPlaying, Live?.IsPlaying);
OnPlayingChange(GetEvent()); OnPlayingChange(GetEvent());
} }
} }
@ -203,14 +206,14 @@ namespace Selector
// DEVICE // DEVICE
if (!eq.IsEqual(Previous?.Device, Live?.Device)) if (!eq.IsEqual(Previous?.Device, Live?.Device))
{ {
Logger.LogDebug($"Device changed: {Previous?.Device?.DisplayString() ?? "none"} -> {Live?.Device?.DisplayString() ?? "none"}"); Logger.LogDebug("Device changed: {previous_device} -> {live_device}", Previous?.Device?.DisplayString() ?? "none", Live?.Device?.DisplayString() ?? "none");
OnDeviceChange(GetEvent()); OnDeviceChange(GetEvent());
} }
// VOLUME // VOLUME
if (Previous?.Device?.VolumePercent != Live?.Device?.VolumePercent) if (Previous?.Device?.VolumePercent != Live?.Device?.VolumePercent)
{ {
Logger.LogDebug($"Volume changed: {Previous?.Device?.VolumePercent}% -> {Live?.Device?.VolumePercent}%"); Logger.LogDebug("Volume changed: {previous_volume}% -> {live_volume}%", Previous?.Device?.VolumePercent, Live?.Device?.VolumePercent);
OnVolumeChange(GetEvent()); OnVolumeChange(GetEvent());
} }
} }

8
Selector/Watcher/PlaylistWatcher.cs
View File

@ -68,7 +68,7 @@ namespace Selector
{ {
token.ThrowIfCancellationRequested(); token.ThrowIfCancellationRequested();
using var logScope = Logger.BeginScope(new Dictionary<string, object> { { "playlist_id", config.PlaylistId } }); using var logScope = Logger.BeginScope(new Dictionary<string, object> { { "playlist_id", config.PlaylistId }, { "pull_tracks", config.PullTracks } });
try{ try{
string id; string id;
@ -99,18 +99,18 @@ namespace Selector
} }
catch(APIUnauthorizedException e) catch(APIUnauthorizedException e)
{ {
Logger.LogDebug($"Unauthorised error: [{e.Message}] (should be refreshed and retried?)"); Logger.LogDebug("Unauthorised error: [{message}] (should be refreshed and retried?)", e.Message);
//throw e; //throw e;
} }
catch(APITooManyRequestsException e) catch(APITooManyRequestsException e)
{ {
Logger.LogDebug($"Too many requests error: [{e.Message}]"); Logger.LogDebug("Too many requests error: [{message}]", e.Message);
await Task.Delay(e.RetryAfter, token); await Task.Delay(e.RetryAfter, token);
// throw e; // throw e;
} }
catch(APIException e) catch(APIException e)
{ {
Logger.LogDebug($"API error: [{e.Message}]"); Logger.LogDebug("API error: [{message}]", e.Message);
// throw e; // throw e;
} }
} }