A lot of changes to the AniDB Rate Limiter and Internal Logic for Pin…

…gs and Logout

Shoko.Server/API/v3/Controllers/DebugController.cs

@@ -108,8 +108,8 @@ public async Task<AnidbUdpResponse> CallAniDB([FromBody] AnidbUdpRequest request
             }
 
             var fullResponse = request.Unsafe ?
-                await _udpHandler.CallAniDBUDPDirectly(request.Command, isPing: request.IsPing) :
-                await _udpHandler.CallAniDBUDP(request.Command, isPing: request.IsPing);
+                await _udpHandler.SendDirectly(request.Command, resetTimers: request.IsPing) :
+                await _udpHandler.Send(request.Command, isPing: request.IsPing);
             var decodedParts = fullResponse.Split('\n');
             var decodedResponse = string.Join('\n',
                 fullResponse.Split(new[] { '\n' }, StringSplitOptions.RemoveEmptyEntries | StringSplitOptions.TrimEntries)
@@ -144,7 +144,7 @@ await _udpHandler.CallAniDBUDPDirectly(request.Command, isPing: request.IsPing)
                     {
                         var errorMessage = $"{(int)returnCode} {returnCode}";
                         _logger.LogTrace("Waiting. AniDB returned {StatusCode} {Status}", (int)returnCode, returnCode);
-                        _udpHandler.ExtendBanTimer(300, errorMessage);
+                        _udpHandler.StartBackoffTimer(300, errorMessage);
                         break;
                     }
                 case UDPReturnCode.UNKNOWN_COMMAND:

Shoko.Server/Providers/AniDB/AniDBRateLimiter.cs

@@ -1,14 +1,16 @@
-using System.Diagnostics;
+using System;
+using System.Diagnostics;
 using System.Threading;
-using NLog;
+using Microsoft.Extensions.Logging;
 
 namespace Shoko.Server.Providers.AniDB;
 
 public abstract class AniDBRateLimiter
 {
-    protected static readonly Logger Logger = LogManager.GetCurrentClassLogger();
-
+    private readonly ILogger _logger;
     private readonly object _lock = new();
+    private readonly Stopwatch _requestWatch = new();
+    private readonly Stopwatch _activeTimeWatch = new();
 
     // Short Term:
     // A Client MUST NOT send more than 0.5 packets per second(that's one packet every two seconds, not two packets a second!)
@@ -26,56 +28,50 @@ public abstract class AniDBRateLimiter
     // Switch to shorter delay after 30 minutes of inactivity
     protected abstract long resetPeriod { get; init; }
 
-    private readonly Stopwatch _requestWatch = new();
-
-    private readonly Stopwatch _activeTimeWatch = new();
-
-    public AniDBRateLimiter()
+    protected AniDBRateLimiter(ILogger logger)
     {
+        _logger = logger;
         _requestWatch.Start();
         _activeTimeWatch.Start();
     }
 
-    public void ResetRate()
+    private void ResetRate()
     {
         var elapsedTime = _activeTimeWatch.ElapsedMilliseconds;
         _activeTimeWatch.Restart();
-        Logger.Trace($"Rate is reset. Active time was {elapsedTime} ms.");
+        _logger.LogTrace("Rate is reset. Active time was {Time} ms", elapsedTime);
     }
 
-    public void Reset()
+    public T EnsureRate<T>(Func<T> action)
     {
-        _requestWatch.Restart();
-    }
-
-    public void EnsureRate()
-    {
-        lock (_lock)
+        try
         {
-            var delay = _requestWatch.ElapsedMilliseconds;
-
-            if (delay > resetPeriod)
-            {
-                ResetRate();
-            }
+            Monitor.Enter(_lock);
 
+            var delay = _requestWatch.ElapsedMilliseconds;
+            if (delay > resetPeriod) ResetRate();
             var currentDelay = _activeTimeWatch.ElapsedMilliseconds > shortPeriod ? LongDelay : ShortDelay;
 
             if (delay > currentDelay)
             {
-                Logger.Trace($"Time since last request is {delay} ms, not throttling.");
-                _requestWatch.Restart();
-                return;
+                _logger.LogTrace("Time since last request is {Delay} ms, not throttling", delay);
+                _logger.LogTrace("Sending AniDB command");
+                return action();
             }
 
             // add 50ms for good measure
             var waitTime = currentDelay - (int)delay + 50;
 
-            Logger.Trace($"Time since last request is {delay} ms, throttling for {waitTime}.");
+            _logger.LogTrace("Time since last request is {Delay} ms, throttling for {Time}", delay, waitTime);
             Thread.Sleep(waitTime);
 
-            Logger.Trace("Sending AniDB command.");
+            _logger.LogTrace("Sending AniDB command");
+            return action();
+        }
+        finally
+        {
             _requestWatch.Restart();
+            Monitor.Exit(_lock);
         }
     }
 }

Shoko.Server/Providers/AniDB/ConnectionHandler.cs

@@ -11,10 +11,10 @@ public abstract class ConnectionHandler
     protected AniDBRateLimiter RateLimiter { get; set; }
     public abstract double BanTimerResetLength { get; }
     public abstract string Type { get; }
-    public abstract UpdateType BanEnum { get; }
+    protected abstract UpdateType BanEnum { get; }
 
     public event EventHandler<AniDBStateUpdate> AniDBStateUpdate;
-    protected AniDBStateUpdate _currentState;
+    private AniDBStateUpdate _currentState;
 
     public AniDBStateUpdate State
     {
@@ -29,8 +29,9 @@ public AniDBStateUpdate State
         }
     }
 
-    protected int? ExtendPauseSecs { get; set; }
-    private Timer BanResetTimer;
+    protected int? BackoffSecs { get; set; }
+    private readonly Timer _backoffTimer;
+    private readonly Timer _banResetTimer;
     public DateTime? BanTime { get; set; }
     private bool _isBanned;
 
@@ -44,13 +45,13 @@ public bool IsBanned
             {
                 BanTime = DateTime.Now;
                 Logger.LogWarning("AniDB {Type} Banned!", Type);
-                if (BanResetTimer.Enabled)
+                if (_banResetTimer.Enabled)
                 {
                     Logger.LogWarning("AniDB {Type} ban timer was already running, ban time extending", Type);
-                    BanResetTimer.Stop(); //re-start implies stop
+                    _banResetTimer.Stop(); //re-start implies stop
                 }
 
-                BanResetTimer.Start();
+                _banResetTimer.Start();
                 State = new AniDBStateUpdate
                 {
                     Value = true,
@@ -61,9 +62,9 @@ public bool IsBanned
             }
             else
             {
-                if (BanResetTimer.Enabled)
+                if (_banResetTimer.Enabled)
                 {
-                    BanResetTimer.Stop();
+                    _banResetTimer.Stop();
                     Logger.LogInformation("AniDB {Type} ban timer stopped. Resuming queue if not paused", Type);
                 }
 
@@ -72,21 +73,24 @@ public bool IsBanned
         }
     }
 
-    public ConnectionHandler(ILoggerFactory loggerFactory, AniDBRateLimiter rateLimiter)
+    protected ConnectionHandler(ILoggerFactory loggerFactory, AniDBRateLimiter rateLimiter)
     {
         _loggerFactory = loggerFactory;
         Logger = loggerFactory.CreateLogger(GetType());
         RateLimiter = rateLimiter;
-        BanResetTimer = new Timer
+        _banResetTimer = new Timer
         {
             AutoReset = false, Interval = TimeSpan.FromHours(BanTimerResetLength).TotalMilliseconds
         };
-        BanResetTimer.Elapsed += BanResetTimerElapsed;
+        _banResetTimer.Elapsed += BanResetTimerElapsed;
+        _backoffTimer = new Timer { AutoReset = false };
+        _backoffTimer.Elapsed += ResetBackoffTimer;
     }
 
     ~ConnectionHandler()
     {
-        BanResetTimer.Elapsed -= BanResetTimerElapsed;
+        _banResetTimer.Elapsed -= BanResetTimerElapsed;
+        _backoffTimer.Elapsed -= ResetBackoffTimer;
     }
 
     private void BanResetTimerElapsed(object sender, ElapsedEventArgs e)
@@ -95,10 +99,12 @@ private void BanResetTimerElapsed(object sender, ElapsedEventArgs e)
         IsBanned = false;
     }
 
-    protected void ExtendBanTimer(int secsToPause, string pauseReason)
+    protected void StartBackoffTimer(int secsToPause, string pauseReason)
     {
         // This Handles the Waiting Period For When AniDB is under heavy load. Not likely to be used
-        ExtendPauseSecs = secsToPause;
+        BackoffSecs = secsToPause;
+        _backoffTimer.Interval = secsToPause * 1000;
+        _backoffTimer.Start();
         AniDBStateUpdate?.Invoke(this,
             new AniDBStateUpdate
             {
@@ -110,10 +116,10 @@ protected void ExtendBanTimer(int secsToPause, string pauseReason)
             });
     }
 
-    protected void ResetBanTimer()
+    protected void ResetBackoffTimer(object sender, ElapsedEventArgs args)
     {
         // This Handles the Waiting Period For When AniDB is under heavy load. Not likely to be used
-        ExtendPauseSecs = null;
+        BackoffSecs = null;
         AniDBStateUpdate?.Invoke(this,
             new AniDBStateUpdate { UpdateType = UpdateType.OverloadBackoff, Value = false, UpdateTime = DateTime.Now });
     }

Shoko.Server/Providers/AniDB/HTTP/AniDBHttpConnectionHandler.cs

@@ -14,7 +14,7 @@ public class AniDBHttpConnectionHandler : ConnectionHandler, IHttpConnectionHand
     public override double BanTimerResetLength => 12;
 
     public override string Type => "HTTP";
-    public override UpdateType BanEnum => UpdateType.HTTPBan;
+    protected override UpdateType BanEnum => UpdateType.HTTPBan;
     public bool IsAlive => true;
 
     public AniDBHttpConnectionHandler(ILoggerFactory loggerFactory, HttpRateLimiter rateLimiter) : base(loggerFactory, rateLimiter)
@@ -46,37 +46,40 @@ public async Task<HttpResponse<string>> GetHttpDirectly(string url)
             };
         }
 
-        RateLimiter.EnsureRate();
-
-        using var response = await _httpClient.GetAsync(url);
-        response.EnsureSuccessStatusCode();
-
-        var responseStream = await response.Content.ReadAsStreamAsync();
-        if (responseStream == null)
+        var response = await RateLimiter.EnsureRate(async () =>
         {
-            throw new EndOfStreamException("Response Body was expected, but none returned");
-        }
+            using var response = await _httpClient.GetAsync(url);
+            response.EnsureSuccessStatusCode();
 
-        var charset = response.Content.Headers.ContentType?.CharSet;
-        Encoding encoding = null;
-        if (!string.IsNullOrEmpty(charset))
-        {
-            encoding = Encoding.GetEncoding(charset);
-        }
+            var responseStream = await response.Content.ReadAsStreamAsync();
+            if (responseStream == null)
+            {
+                throw new EndOfStreamException("Response Body was expected, but none returned");
+            }
 
-        encoding ??= Encoding.UTF8;
-        using var reader = new StreamReader(responseStream, encoding);
-        var output = await reader.ReadToEndAsync();
+            var charset = response.Content.Headers.ContentType?.CharSet;
+            Encoding encoding = null;
+            if (!string.IsNullOrEmpty(charset))
+            {
+                encoding = Encoding.GetEncoding(charset);
+            }
 
-        if (CheckForBan(output))
-        {
-            throw new AniDBBannedException
+            encoding ??= Encoding.UTF8;
+            using var reader = new StreamReader(responseStream, encoding);
+            var output = await reader.ReadToEndAsync();
+
+            if (CheckForBan(output))
             {
-                BanType = UpdateType.HTTPBan, BanExpires = BanTime?.AddHours(BanTimerResetLength)
-            };
-        }
+                throw new AniDBBannedException
+                {
+                    BanType = UpdateType.HTTPBan, BanExpires = BanTime?.AddHours(BanTimerResetLength)
+                };
+            }
+
+            return new HttpResponse<string> { Response = output, Code = response.StatusCode };
+        });
 
-        return new HttpResponse<string> { Response = output, Code = response.StatusCode };
+        return response;
     }
 
     private bool CheckForBan(string xmlResult)

Shoko.Server/Providers/AniDB/HTTP/HttpRateLimiter.cs

@@ -1,3 +1,5 @@
+using Microsoft.Extensions.Logging;
+
 namespace Shoko.Server.Providers.AniDB.HTTP;
 
 public class HttpRateLimiter : AniDBRateLimiter
@@ -6,4 +8,8 @@ public class HttpRateLimiter : AniDBRateLimiter
     protected override int LongDelay { get; init; } = 4000;
     protected override long shortPeriod { get; init; } = 1000000;
     protected override long resetPeriod { get; init; } = 1800000;
+
+    public HttpRateLimiter(ILogger<HttpRateLimiter> logger) : base(logger)
+    {
+    }
 }

Shoko.Server/Providers/AniDB/Interfaces/IUDPConnectionHandler.cs

@@ -16,12 +16,12 @@ public interface IUDPConnectionHandler : IConnectionHandler
     void ForceLogout();
     Task CloseConnections();
     Task ForceReconnection();
-    void ExtendBanTimer(int time, string message);
+    void StartBackoffTimer(int time, string message);
     Task<bool> Init();
     Task<bool> Init(string username, string password, string serverName, ushort serverPort, ushort clientPort);
     Task<bool> TestLogin(string username, string password);
 
-    Task<string> CallAniDBUDPDirectly(string command, bool needsUnicode = true, bool isPing = false);
+    Task<string> SendDirectly(string command, bool needsUnicode = true, bool resetTimers = true);
 
-    Task<string> CallAniDBUDP(string command, bool needsUnicode = true, bool isPing = false);
+    Task<string> Send(string command, bool needsUnicode = true, bool isPing = false);
 }