diff --git a/AGENTS.md b/AGENTS.md index 1ba4253..c5c1a83 100644 --- a/AGENTS.md +++ b/AGENTS.md @@ -27,6 +27,25 @@ - Preserve console color state: use save/restore pattern for temporary color changes - API rate limits must use `ApiKeyPool.MarkRateLimited()`/`MarkAvailable()` +### API Failure Classification +Tumblr sits behind a CDN that returns HTML error pages (403, 5xx) which never reach the API. These +say nothing about the item being fetched, so they must not be recorded as per-item failures. + +- A response body that will not parse as JSON did not come from the API. Flag it with + `Root.transientFailure`, never as `FAILURE` +- Transient failures retry in place (`TransientBackoffSeconds`) before the item is skipped; a skipped + item stays unmarked in the DB so a later launch retries it +- `MaxConsecutiveTransient` consecutive transient failures aborts the pass rather than skipping + item-by-item against an edge that is refusing all traffic +- Only call `ApiKeyPool.MarkAvailable()` on a response that actually reached the API. A transport or + CDN failure says nothing about the key's standing and must not clear its flag +- Only a real HTTP 429 (or `meta.status == 429`) counts as a rate limit. Do not infer one from the + presence of `X-RateLimit-*` headers, which Tumblr sends on every response +- Rate limiters must pace with `await AcquireAsync()`. `AttemptAcquire()` does not wait, so a + saturated window aborts the run instead of throttling it +- Long-running commands return exit 3 when a pass ends incomplete (rate-limit pause, breaker trip, or + skipped items), so a caller can distinguish that from a clean run + ### Testing - No existing test suite; use xUnit if adding tests - Test critical logic: `ApiKeyPool` init, color parsing, config persistence diff --git a/URLNotesGrabberCORE/DataAccess.cs b/URLNotesGrabberCORE/DataAccess.cs index 99e9490..3c3f6f0 100644 --- a/URLNotesGrabberCORE/DataAccess.cs +++ b/URLNotesGrabberCORE/DataAccess.cs @@ -2710,6 +2710,10 @@ namespace URLNotesGrabberCORE public static void MarkAvailable(ApiKeyConfig key) { + // Called after every successful call; skip the write and the log line when nothing was flagged. + if (GetRetryUntil(key) == 0) + return; + using var conn = new System.Data.SQLite.SQLiteConnection("Data Source=" + _dbPath); conn.Open(); using var cmd = new System.Data.SQLite.SQLiteCommand( @@ -2803,6 +2807,15 @@ namespace URLNotesGrabberCORE private static string FormatKeyLabel(ApiKeyConfig key) => $"[Key#{key.KeyNumber}]"; + private static string SummarizeBody(string body) + { + if (string.IsNullOrWhiteSpace(body)) + return "(empty)"; + + var flat = System.Text.RegularExpressions.Regex.Replace(body, @"<[^>]+>|\s+", " ").Trim(); + return flat.Length <= 80 ? flat : flat.Substring(0, 80) + "..."; + } + private static int GetRetryDelaySecondsFromHeaders(IEnumerable? headers) { if (headers == null) @@ -2881,144 +2894,63 @@ namespace URLNotesGrabberCORE Console.WriteLine($"{FormatKeyLabel(key)} {timestamp}\t{DateTime.Now}\t{DataAccess.UpdateAPICount()}"); var myDeserializedClass = new Root(); + // Never reached the API: there is no body to interpret, so the post's state is still unknown. + if (response.ResponseStatus != ResponseStatus.Completed) + { + myDeserializedClass.statusCode = response.ResponseStatus.ToString(); + myDeserializedClass.transientFailure = true; + Console.WriteLine($"[Transient] {FormatKeyLabel(key)} transport {response.ResponseStatus}: {response.ErrorException?.Message}"); + return myDeserializedClass; + } + try { var deserializedResult = JsonConvert.DeserializeObject(myJsonResponse); - if (deserializedResult != null) + if (deserializedResult == null) { - myDeserializedClass = deserializedResult; - myDeserializedClass.rawJson = myJsonResponse; + // Empty body behind an HTTP status: an edge/proxy response, not the API. + myDeserializedClass.statusCode = response.StatusCode.ToString(); + myDeserializedClass.transientFailure = true; + Console.WriteLine($"[Transient] {FormatKeyLabel(key)} HTTP {(int)response.StatusCode} {response.StatusDescription} — empty body"); + return myDeserializedClass; + } - if (myDeserializedClass.meta != null && myDeserializedClass.meta.status == 404) - { - myDeserializedClass.statusCode = "NotFound"; - } + myDeserializedClass = deserializedResult; + myDeserializedClass.rawJson = myJsonResponse; - bool metaIndicatesRateLimit = myDeserializedClass.meta != null && myDeserializedClass.meta.status == 429; - bool metaMsgIndicatesRateLimit = myDeserializedClass.meta != null && !string.IsNullOrEmpty(myDeserializedClass.meta.msg) && myDeserializedClass.meta.msg.IndexOf("Too Many", StringComparison.OrdinalIgnoreCase) >= 0; + if (myDeserializedClass.meta != null && myDeserializedClass.meta.status == 404) + { + myDeserializedClass.statusCode = "NotFound"; + } - if (metaIndicatesRateLimit || metaMsgIndicatesRateLimit || (response != null && (response.StatusDescription?.IndexOf("Too Many", StringComparison.OrdinalIgnoreCase) >= 0 || response.StatusCode == System.Net.HttpStatusCode.TooManyRequests))) - { - if (response?.Headers != null) - { - bool checkResetLocal = false; - foreach (var header in response.Headers) - { - string? headerName = header?.Name; - string? headerValue = header?.Value?.ToString(); - if (string.IsNullOrEmpty(headerName) || string.IsNullOrEmpty(headerValue)) - continue; + bool metaIndicatesRateLimit = myDeserializedClass.meta != null && myDeserializedClass.meta.status == 429; + bool metaMsgIndicatesRateLimit = myDeserializedClass.meta != null && !string.IsNullOrEmpty(myDeserializedClass.meta.msg) && myDeserializedClass.meta.msg.IndexOf("Too Many", StringComparison.OrdinalIgnoreCase) >= 0; - if (string.Equals(headerName, "Retry-After", StringComparison.OrdinalIgnoreCase)) - { - if (int.TryParse(headerValue, out int retrySecs)) - myDeserializedClass.retryInSeconds = Math.Max(myDeserializedClass.retryInSeconds, retrySecs); - else if (DateTimeOffset.TryParse(headerValue, out var dto)) - myDeserializedClass.retryInSeconds = Math.Max(myDeserializedClass.retryInSeconds, (int)Math.Max(0, (dto - DateTimeOffset.UtcNow).TotalSeconds)); - } - - if (headerName.IndexOf("X-RateLimit-Reset", StringComparison.OrdinalIgnoreCase) >= 0 && long.TryParse(headerValue, out long epoch)) - { - var secs = (int)Math.Max(0, epoch - DateTimeOffset.UtcNow.ToUnixTimeSeconds()); - myDeserializedClass.retryInSeconds = Math.Max(myDeserializedClass.retryInSeconds, secs); - } - - if (headerName.Contains("Remaining", StringComparison.OrdinalIgnoreCase) && headerValue == "0") - checkResetLocal = true; - - if (checkResetLocal && headerName.IndexOf("Reset", StringComparison.OrdinalIgnoreCase) >= 0) - { - if (int.TryParse(headerValue, out int resetValue)) - myDeserializedClass.retryInSeconds = Math.Max(myDeserializedClass.retryInSeconds, resetValue); - else if (long.TryParse(headerValue, out long epochVal)) - myDeserializedClass.retryInSeconds = Math.Max(myDeserializedClass.retryInSeconds, (int)Math.Max(0, epochVal - DateTimeOffset.UtcNow.ToUnixTimeSeconds())); - } - } - } - - myDeserializedClass.statusCode = "TooManyRequests"; - } + if (metaIndicatesRateLimit || metaMsgIndicatesRateLimit || response.StatusDescription?.IndexOf("Too Many", StringComparison.OrdinalIgnoreCase) >= 0 || response.StatusCode == System.Net.HttpStatusCode.TooManyRequests) + { + myDeserializedClass.retryInSeconds = Math.Max(myDeserializedClass.retryInSeconds, GetRetryDelaySecondsFromHeaders(response.Headers)); + myDeserializedClass.statusCode = "TooManyRequests"; } } catch (Exception ex) { - Console.WriteLine($"Failed JSON: {myJsonResponse}"); - Console.WriteLine(ex.ToString()); + // A body that will not parse came from infrastructure (CDN/proxy/WAF), not the Tumblr + // API, so it says nothing about this post. Retryable, not a failure of the post itself. + myDeserializedClass.statusCode = response.StatusCode.ToString(); - if (!response.IsSuccessful) + if (response.StatusCode == System.Net.HttpStatusCode.TooManyRequests) { - string? statusStr = null; - try { statusStr = response != null ? response.StatusCode.ToString() : null; } catch { statusStr = null; } - Console.WriteLine($"{statusStr}\t{response?.StatusDescription}"); - if (!string.IsNullOrEmpty(statusStr)) - myDeserializedClass.statusCode = statusStr; + myDeserializedClass.retryInSeconds = GetRetryDelaySecondsFromHeaders(response.Headers); + myDeserializedClass.statusCode = "TooManyRequests"; + } + else + { + myDeserializedClass.transientFailure = true; + Console.WriteLine($"[Transient] {FormatKeyLabel(key)} HTTP {(int)response.StatusCode} {response.StatusDescription} — unparseable body: {SummarizeBody(myJsonResponse)}"); - bool checkReset = false; - - if ((myDeserializedClass.statusCode != "NotFound" || myDeserializedClass.retryInSeconds > 0) && response.Headers != null) - { - bool foundRateLimitHeader = false; - foreach (var header in response.Headers) - { - if (header.Name != null && header.Value != null) - { - Console.WriteLine($"{header.Name} - {header.Value}"); - var headerValue = header.Value?.ToString(); - if (!string.IsNullOrEmpty(headerValue)) - { - if (string.Equals(header.Name, "Retry-After", StringComparison.OrdinalIgnoreCase)) - { - if (int.TryParse(headerValue, out int retrySecs)) - { - if (myDeserializedClass.retryInSeconds < retrySecs) - myDeserializedClass.retryInSeconds = retrySecs; - } - else if (DateTimeOffset.TryParse(headerValue, out DateTimeOffset dto)) - { - var secs = (int)Math.Max(0, (dto - DateTimeOffset.UtcNow).TotalSeconds); - if (myDeserializedClass.retryInSeconds < secs) - myDeserializedClass.retryInSeconds = secs; - } - } - - if (checkReset && header.Name.Contains("Reset", StringComparison.OrdinalIgnoreCase)) - { - if (int.TryParse(headerValue, out int resetValue)) - { - if (myDeserializedClass.retryInSeconds < resetValue) - myDeserializedClass.retryInSeconds = resetValue; - } - else if (long.TryParse(headerValue, out long epochVal)) - { - var secs = (int)Math.Max(0, epochVal - DateTimeOffset.UtcNow.ToUnixTimeSeconds()); - if (myDeserializedClass.retryInSeconds < secs) - myDeserializedClass.retryInSeconds = secs; - } - } - - if (header.Name.IndexOf("X-RateLimit-Reset", StringComparison.OrdinalIgnoreCase) >= 0) - { - if (long.TryParse(headerValue, out long epoch)) - { - var secs = (int)Math.Max(0, epoch - DateTimeOffset.UtcNow.ToUnixTimeSeconds()); - if (myDeserializedClass.retryInSeconds < secs) - myDeserializedClass.retryInSeconds = secs; - } - foundRateLimitHeader = true; - } - } - if (header.Name.Contains("Remaining", StringComparison.OrdinalIgnoreCase) && header.Value.ToString() == "0") - checkReset = true; - else - checkReset = false; - } - - if (foundRateLimitHeader || (response != null && response.StatusCode == System.Net.HttpStatusCode.TooManyRequests)) - { - myDeserializedClass.statusCode = "TooManyRequests"; - } - } - } + // A 2xx that will not parse is a genuine surprise; keep the detail for that case only. + if (response.IsSuccessful) + Console.WriteLine(ex.ToString()); } } diff --git a/URLNotesGrabberCORE/Program.cs b/URLNotesGrabberCORE/Program.cs index 1604dd8..8583213 100644 --- a/URLNotesGrabberCORE/Program.cs +++ b/URLNotesGrabberCORE/Program.cs @@ -273,7 +273,7 @@ namespace URLNotesGrabberCORE managedCollectRun = true; } - CollectNotes(settings.GetValue("PathOutput"), withoutNotesOnly, beforeDate, managedCollectRun).GetAwaiter().GetResult(); + exitCode = CollectNotes(settings.GetValue("PathOutput"), withoutNotesOnly, beforeDate, managedCollectRun).GetAwaiter().GetResult(); break; case "--blogsR": //collect notes from all posts @@ -442,7 +442,7 @@ namespace URLNotesGrabberCORE Console.WriteLine("--importposts [path-to-posts.db]\t One-time migration: copy legacy ThreeTxtFileHelper posts.db rows into TL.db"); Console.WriteLine(); - Console.WriteLine("Exit status: 0 = success; 1 = unexpected error; 2 = usage error (unknown command or bad/missing arguments)"); + Console.WriteLine("Exit status: 0 = success; 1 = unexpected error; 2 = usage error (unknown command or bad/missing arguments); 3 = incomplete (--collect paused on a rate limit, or skipped posts after transient API failures) - relaunch to resume"); } static void WritePostBlogsToFile(string outPath) @@ -837,7 +837,9 @@ namespace URLNotesGrabberCORE RateLimiter limiter = new SlidingWindowRateLimiter(new SlidingWindowRateLimiterOptions { - PermitLimit = 300, + // 1/sec average, matching --collect: the CDN reacts to aggregate traffic from the IP, + // not to per-command rates. + PermitLimit = 60, QueueProcessingOrder = QueueProcessingOrder.OldestFirst, QueueLimit = 1, Window = TimeSpan.FromMinutes(1), @@ -873,7 +875,9 @@ namespace URLNotesGrabberCORE while (hasMoreLikes) { - using RateLimitLease lease = limiter.AttemptAcquire(1); + // Wait for a permit rather than giving up on one: the limiter paces the loop, it is + // not a failure condition. Only one acquire is ever pending, so QueueLimit = 1 suffices. + using RateLimitLease lease = await limiter.AcquireAsync(1); if (!lease.IsAcquired) { Console.WriteLine("!@@@@@@@ - Rate Limited Exceeded: No Lease Available"); @@ -1119,6 +1123,43 @@ if (shouldInsert) } } + // Backoff between in-place retries of a transient infrastructure failure. Most CDN 403s and edge + // 5xxs clear within a few seconds, so retrying here saves the post its single attempt for the pass. + static readonly int[] TransientBackoffSeconds = { 1, 4, 10 }; + + // Fetches one page, retrying transient failures in place. Rate limits are returned to the caller + // untouched — those are handled by pausing the whole run, not by retrying this post. + static async Task FetchNotesPage(Tuple post, string beforeTimestamp) + { + Root response = null!; + + for (int attempt = 0; ; attempt++) + { + var key = ApiKeyPool.GetCurrentKey(); + response = await APIAccess.GrabNotes(key, post.Item1, post.Item2, beforeTimestamp); + + if (response.statusCode == "TooManyRequests") + { + ApiKeyPool.MarkRateLimited(key, response.retryInSeconds > 0 ? response.retryInSeconds : 60); + return response; + } + + if (!response.transientFailure) + { + // Only a response that actually reached the API says anything about the key's standing. + ApiKeyPool.MarkAvailable(key); + return response; + } + + if (attempt >= TransientBackoffSeconds.Length) + return response; + + int delay = TransientBackoffSeconds[attempt]; + Console.WriteLine($"[Transient] retry {attempt + 1}/{TransientBackoffSeconds.Length} in {delay}s"); + await Task.Delay(delay * 1000); + } + } + static async Task GrabNotes(Tuple post) { try @@ -1136,18 +1177,16 @@ if (shouldInsert) string beforeTimestamp = post.Item3.ToString(); bool hasReplies = false; const int maxPages = 500; - var key = ApiKeyPool.GetCurrentKey(); - var response = await APIAccess.GrabNotes(key, post.Item1, post.Item2, beforeTimestamp); + var response = await FetchNotesPage(post, beforeTimestamp); if (response.statusCode == "TooManyRequests") - { - int retry = response.retryInSeconds > 0 ? response.retryInSeconds : 60; - ApiKeyPool.MarkRateLimited(key, retry); return "TooManyRequests"; - } - if (response.meta?.status != 429) - ApiKeyPool.MarkAvailable(key); + if (response.transientFailure) + { + Console.WriteLine($"[Skip] {post.Item1}/{post.Item2} — {response.statusCode} after {TransientBackoffSeconds.Length} retries"); + return "Transient"; + } if (IsNotFound(response)) { @@ -1156,19 +1195,6 @@ if (shouldInsert) Thread.Sleep(1000); return "NotFound"; } - if (response == null) - { - Console.WriteLine("##### Response is null - API Failure? ###"); - return "FAILURE"; - } - if (response.statusCode == "TooManyRequests") - { - int retry = response.retryInSeconds > 0 ? response.retryInSeconds : 60; - ApiKeyPool.MarkRateLimited(key, retry); - - ApiKeyPool.SleepUntilAnyAvailable(30); - return response.statusCode; - } // Pagination loop while (true) @@ -1218,16 +1244,15 @@ if (shouldInsert) break; } - key = ApiKeyPool.GetCurrentKey(); - response = await APIAccess.GrabNotes(key, post.Item1, post.Item2, beforeTimestamp); + response = await FetchNotesPage(post, beforeTimestamp); if (response.statusCode == "TooManyRequests") - { - int retry = response.retryInSeconds > 0 ? response.retryInSeconds : 60; - ApiKeyPool.MarkRateLimited(key, retry); return "TooManyRequests"; + + if (response.transientFailure) + { + Console.WriteLine($"[Skip] {post.Item1}/{post.Item2} — {response.statusCode} on page {page} after {TransientBackoffSeconds.Length} retries"); + return "Transient"; } - if (response.meta?.status != 429) - ApiKeyPool.MarkAvailable(key); if (IsNotFound(response)) { @@ -1258,7 +1283,11 @@ if (shouldInsert) return "UNKNOWN"; } - static async Task CollectNotes(string outPath, bool withoutNotesOnly = true, DateTime? beforeDate = null, bool managedRun = false) + // Consecutive transient failures that mean the API edge is rejecting traffic wholesale rather than + // blipping on one post. Past this, skipping post-by-post would just hammer a closed door. + const int MaxConsecutiveTransient = 10; + + static async Task CollectNotes(string outPath, bool withoutNotesOnly = true, DateTime? beforeDate = null, bool managedRun = false) { List> posts = DataAccess.GetPosts(withoutNotesOnly, beforeDate); @@ -1267,9 +1296,14 @@ if (shouldInsert) // post that keeps returning FAILURE/UNKNOWN. Successful/NotFound posts drop out via the DB filter anyway. HashSet<(string, long)> attempted = new HashSet<(string, long)>(); + int skipped = 0; + int consecutiveTransient = 0; + RateLimiter limiter = new SlidingWindowRateLimiter(new SlidingWindowRateLimiterOptions { - PermitLimit = 300, + // 1/sec average. Sustained higher rates draw CDN-level 403s that the API's own rate-limit + // headers never warn about, so this sits well under the per-key quota on purpose. + PermitLimit = 60, QueueProcessingOrder = QueueProcessingOrder.OldestFirst, QueueLimit = 1, Window = TimeSpan.FromMinutes(1), @@ -1294,43 +1328,60 @@ if (shouldInsert) ApiKeyPool.SleepUntilAnyAvailable(30); - string status; - - using RateLimitLease lease = limiter.AttemptAcquire(1); - if (lease.IsAcquired) - { - Console.WriteLine("{0,32} - {1,15} - {2}", post.Item1, post.Item2, DateTimeOffset.FromUnixTimeSeconds(post.Item4).ToString()); - status = await GrabNotes(post); - } - else + // Wait for a permit rather than giving up on one: the limiter paces the loop, it is + // not a failure condition. Only one acquire is ever pending, so QueueLimit = 1 suffices. + using RateLimitLease lease = await limiter.AcquireAsync(1); + if (!lease.IsAcquired) { Console.WriteLine("!@@@@@@@ - Rate Limited Exceeded: No Lease Available"); - return; // throttle: abort without completing the run so a later launch resumes + return 3; // abort without completing the run so a later launch resumes } - if (status == "Success") + Console.WriteLine("{0,32} - {1,15} - {2}", post.Item1, post.Item2, DateTimeOffset.FromUnixTimeSeconds(post.Item4).ToString()); + string status = await GrabNotes(post); + + if (status == "Transient") { + // Retries in GrabNotes are already exhausted. Skip the post so the pass can make + // progress; it stays unmarked in the DB, so the next launch picks it up again. attempted.Add((post.Item1, post.Item2)); - DataAccess.UpdatePostMarkNotesCollected(post.Item1, post.Item2); - } - else if (status == "NotFound") - { - attempted.Add((post.Item1, post.Item2)); - Console.WriteLine("GrabNotes Result: NotFound"); - DataAccess.UpdatePostMarkNotFound(post.Item1, post.Item2); - } - else if (status == "TooManyRequests") - { - // Throttle, not a real per-post failure: don't consume this post's single attempt. - // Abort the pass without completing so a later launch resumes against the same cutoff. - Console.WriteLine("GrabNotes Result: TooManyRequests - pausing run; relaunch to resume."); - return; + skipped++; + consecutiveTransient++; + + if (consecutiveTransient >= MaxConsecutiveTransient) + { + Console.WriteLine($"[Abort] {consecutiveTransient} consecutive transient failures - the API edge is rejecting traffic. Pausing run; relaunch to resume. ({skipped} post(s) skipped)"); + return 3; + } } else { - // FAILURE / UNKNOWN: count as attempted so the pass can finish instead of retrying forever. - attempted.Add((post.Item1, post.Item2)); - Console.WriteLine("GrabNotes Result: " + status); + consecutiveTransient = 0; + + if (status == "Success") + { + attempted.Add((post.Item1, post.Item2)); + DataAccess.UpdatePostMarkNotesCollected(post.Item1, post.Item2); + } + else if (status == "NotFound") + { + attempted.Add((post.Item1, post.Item2)); + Console.WriteLine("GrabNotes Result: NotFound"); + DataAccess.UpdatePostMarkNotFound(post.Item1, post.Item2); + } + else if (status == "TooManyRequests") + { + // Throttle, not a real per-post failure: don't consume this post's single attempt. + // Abort the pass without completing so a later launch resumes against the same cutoff. + Console.WriteLine($"GrabNotes Result: TooManyRequests - pausing run; relaunch to resume. ({skipped} post(s) skipped)"); + return 3; + } + else + { + // FAILURE / UNKNOWN: count as attempted so the pass can finish instead of retrying forever. + attempted.Add((post.Item1, post.Item2)); + Console.WriteLine("GrabNotes Result: " + status); + } } // Re-fetch the updated list after processing the current post @@ -1344,10 +1395,19 @@ if (shouldInsert) DataAccess.CompleteCollectRun(); Console.WriteLine("Full re-check run complete."); } + + if (skipped > 0) + { + Console.WriteLine($"Pass finished with {skipped} post(s) skipped after transient failures; relaunch to retry them."); + return 3; + } + + return 0; } catch (Exception ex) { Console.WriteLine(ex.ToString()); + return 1; } } diff --git a/URLNotesGrabberCORE/ResponseNotes.cs b/URLNotesGrabberCORE/ResponseNotes.cs index c80f66c..1a6d919 100644 --- a/URLNotesGrabberCORE/ResponseNotes.cs +++ b/URLNotesGrabberCORE/ResponseNotes.cs @@ -85,6 +85,10 @@ namespace URLNotesGrabberCORE public int retryInSeconds { get; set; } public string rawJson { get; set; } + + // The request never reached the Tumblr API (transport error, or an edge/CDN response with a + // non-JSON body). Says nothing about the post, so the caller should retry rather than fail it. + public bool transientFailure { get; set; } } // Classes for Posts API endpoint (for reply_text)