Improve error handling and logging (#403)

* Rewrite HTTP response classes * Parse error objects in HttpResponseError * Add exception to log message where possible * Improve logging plugin * Improve readability of IgnoreException output * Forward Level from package:logging * createNyxxRest returns INyxxRest * Give each plugin its own logger * Change output of Logging plugin * Add logging guidelines to CONTRIBUTING.md * Update library code to match logging guidelines * Remove extra log line * Correct typo in exception message Co-authored-by: Rapougnac <74512338+Rapougnac@users.noreply.github.com> * Log rate limit bucket updates * Censor token in log output Co-authored-by: Rapougnac <74512338+Rapougnac@users.noreply.github.com>
nyxx-discord · Nov 20, 2022 · 8b7e67b · 8b7e67b
1 parent 338144b
commit 8b7e67b
Showing 14 changed files with 442 additions and 107 deletions.
diff --git a/CONTRIBUTING.md b/CONTRIBUTING.md
@@ -27,3 +27,18 @@ We attempt to conform [Effective Dart Coding Style](https://dart.dev/guides/lang
 However, code style rules are not enforcement and code should be readable and easy to maintain.
 
 **One exception to rules above is line limit - we use 160 character line limit instead of 80 chars.**
+
+### Logging
+nyxx uses the [`logging`](https://pub.dev/packages/logging) package to do logging, and provides a `Logging` plugin for outputting those logs to the console.
+
+When contributing to the library, please be sure to include logs (if applicable) following these guidelines:
+- Use the appropriate logger. The name of the logger helps users filter log messages and quickly identify where a message comes from.
+- Use the appropriate level. Log levels are a high-level filter for the verbosity of log output, and knowing what level to send a message at can be difficult, but please try to follow these guidelines:
+    - `SHOUT` for messages that indicate that something unexpectedly failed. This is the level equivalent to throwing an exception/error.
+    - `SEVERE` for messages that indicate an assertion/sanity check was violated, or for errors not caused by the user.
+    - `WARNING` for messages that indicate something *might* fail in the future.
+    - `INFO` for messages that report useful information to the user, such as changes in connection state.
+    - `CONFIG` for logging values of unchanging fields that might be useful for debugging. These shouldn't be logged repeatedly.
+    - `FINE` for messages that report information useful for monitoring what the code is doing.
+    - `FINER` for messages bringing additional information to `FINE` level messages. You can think of these as `CONFIG` for `FINE` messages.
+    - `FINEST` for messages useful for tracing code execution.
diff --git a/lib/nyxx.dart b/lib/nyxx.dart
@@ -165,6 +165,7 @@ export 'src/internal/interfaces/disposable.dart' show Disposable;
 export 'src/internal/interfaces/message_author.dart' show IMessageAuthor;
 export 'src/internal/interfaces/send.dart' show ISend;
 export 'src/internal/interfaces/mentionable.dart' show Mentionable;
+export 'src/internal/response_wrapper/error_response_wrapper.dart' show IHttpErrorData, IFieldError;
 export 'src/internal/response_wrapper/thread_list_result_wrapper.dart' show IThreadListResultWrapper;
 export 'src/internal/shard/shard.dart' show IShard;
 export 'src/internal/shard/shard_manager.dart' show IShardManager;
@@ -198,5 +199,6 @@ export 'src/plugin/plugins/cli_integration.dart' show CliIntegration;
 export 'src/plugin/plugins/ignore_exception.dart' show IgnoreExceptions;
 export 'src/plugin/plugins/logging.dart' show Logging;
 
-// Forward `RetryOptions` to allow the usage of the class without importing the package
+// Export classes used in the nyxx API to avoid users having to import the package themselves
 export 'package:retry/retry.dart' show RetryOptions;
+export 'package:logging/logging.dart' show Level;
diff --git a/lib/src/internal/connection_manager.dart b/lib/src/internal/connection_manager.dart
@@ -19,7 +19,7 @@ class ConnectionManager {
   late final int recommendedShardsNum;
   late final int maxConcurrency;
 
-  final Logger _logger = Logger("Client");
+  final Logger _logger = Logger("Connection Manager");
 
   int _shardsReady = 0;
 
@@ -30,7 +30,7 @@ class ConnectionManager {
     final httpResponse = await (client.httpEndpoints as HttpEndpoints).getGatewayBot();
 
     if (httpResponse is HttpResponseError) {
-      throw UnrecoverableNyxxError("Cannot get gateway url: [${httpResponse.code}; ${httpResponse.message}]");
+      throw UnrecoverableNyxxError("Cannot get gateway url: $httpResponse");
     }
 
     final response = httpResponse as HttpResponseSuccess;
@@ -41,7 +41,13 @@ class ConnectionManager {
     recommendedShardsNum = response.jsonBody["shards"] as int;
     maxConcurrency = response.jsonBody["session_start_limit"]["max_concurrency"] as int;
 
-    _logger.fine("Got gateway info: Url: [$gateway]; Recommended shard num: [$recommendedShardsNum]");
+    _logger.config([
+      'Got gateway info:',
+      'Gateway URL: $gateway',
+      'Remaining connections: $remaining (reset at $resetAt)',
+      'Recommended shard count: $recommendedShardsNum',
+      'Max concurrency: $maxConcurrency',
+    ].join('\n'));
 
     checkForConnections();
 
@@ -56,8 +62,7 @@ class ConnectionManager {
     }
 
     if (remaining < 10) {
-      _logger.severe("Exiting to prevent API abuse. 10 connections starts left.");
-      throw UnrecoverableNyxxError('Exiting nyxx to prevent API ban. Remaining less that 10 connection to gateway');
+      throw UnrecoverableNyxxError('Exiting nyxx to prevent API ban. Less than 10 connections to gateway ($remaining)');
     }
   }
 

diff --git a/lib/src/internal/http/http_bucket.dart b/lib/src/internal/http/http_bucket.dart
@@ -1,4 +1,5 @@
 import 'package:http/http.dart' as http;
+import 'package:logging/logging.dart';
 
 import 'package:nyxx/src/internal/http/http_request.dart';
 
@@ -24,6 +25,8 @@ class HttpBucket {
 
   String get id => _bucketId;
 
+  late final Logger _logger = Logger('HttpBucket $id');
+
   HttpBucket(this._remaining, this._reset, this._resetAfter, this._bucketId);
 
   static HttpBucket? fromResponseSafe(http.StreamedResponse response) {
@@ -63,11 +66,19 @@ class HttpBucket {
 
   void updateRateLimit(http.StreamedResponse response) {
     if (isInBucket(response)) {
+      _logger.finest('Updating bucket');
+
       _remaining = getRemainingFromHeaders(response.headers) ?? _remaining;
 
       _reset = getResetFromHeaders(response.headers) ?? _reset;
 
       _resetAfter = getResetAfterFromHeaders(response.headers) ?? _resetAfter;
+
+      _logger.finest([
+        'Remaining: $_remaining',
+        'Reset at: $_reset',
+        'Reset after: $_resetAfter',
+      ].join('\n'));
     }
   }
 }
diff --git a/lib/src/internal/http/http_handler.dart b/lib/src/internal/http/http_handler.dart
@@ -6,7 +6,6 @@ import 'package:logging/logging.dart';
 import 'package:nyxx/src/events/http_events.dart';
 import 'package:nyxx/src/events/ratelimit_event.dart';
 import 'package:nyxx/src/internal/event_controller.dart';
-import 'package:nyxx/src/internal/exceptions/http_client_exception.dart';
 import 'package:nyxx/src/nyxx.dart';
 import 'package:nyxx/src/internal/http/http_bucket.dart';
 import 'package:nyxx/src/internal/http/http_request.dart';
@@ -53,8 +52,26 @@ class HttpHandler {
     }
 
     HttpBucket? currentBucket = _bucketByRequestRateLimitId[request.rateLimitId];
-    logger.fine(
-        "Executing request: [${request.uri.toString()}]; Bucket ID: [${currentBucket?.id}]; Reset at: [${currentBucket?.reset}]; Remaining: [${currentBucket?.remaining}]; Reset after: [${currentBucket?.resetAfter}]; Body: [${request is BasicRequest && request.body != null ? request.body : 'EMPTY'}]");
+
+    logger.fine('Executing request $request');
+    logger.finer([
+      'Headers: ${request.headers}',
+      'Authenticated: ${request.auth}',
+      if (request.auditLog != null) 'Audit Log Reason: ${request.auditLog}',
+      'Global rate limit: ${request.globalRateLimit}',
+      'Rate limit ID: ${request.rateLimitId}',
+      'Rate limit bucket: ${currentBucket?.id}',
+      if (currentBucket != null) ...[
+        'Reset at: ${currentBucket.reset}',
+        'Reset after: ${currentBucket.resetAfter}',
+        'Remaining: ${currentBucket.remaining}',
+      ],
+      if (request is BasicRequest) 'Request body: ${request.body}',
+      if (request is MultipartRequest) ...[
+        'Request body: ${request.fields}',
+        'Files: ${request.files.map((file) => file.filename).join(', ')}',
+      ],
+    ].join('\n'));
 
     // Get actual time and check if request can be executed based on data that bucket already have
     // and wait if rate limit could be possibly hit
@@ -81,25 +98,29 @@ class HttpHandler {
     currentBucket?.addInFlightRequest(request);
     final response = await client.options.httpRetryOptions.retry(
       () async => httpClient.send(await request.prepareRequest()),
-      onRetry: (ex) => logger.shout('Exception when sending HTTP request (retrying automatically): $ex'),
+      onRetry: (ex) => logger.warning('Exception when sending HTTP request (retrying automatically)', ex),
     );
     currentBucket?.removeInFlightRequest(request);
     currentBucket = _upsertBucket(request, response);
     return _handle(request, response);
   }
 
   Future<HttpResponse> _handle(HttpRequest request, http.StreamedResponse response) async {
+    logger.fine('Handling response (${response.statusCode}) from request $request');
+    logger.finer('Headers: ${response.headers}');
+
     if (response.statusCode >= 200 && response.statusCode < 300) {
-      final responseSuccess = HttpResponseSuccess(response);
-      await responseSuccess.finalize();
+      final responseSuccess = await HttpResponseSuccess.fromResponse(response);
 
       (client.eventsRest as RestEventController).onHttpResponseController.add(HttpResponseEvent(responseSuccess));
-      logger.finer("Got successful http response for endpoint: [${response.request?.url.toString()}]; Response: [${responseSuccess.jsonBody}]");
+      logger.finest('Successful response: $responseSuccess');
 
       return responseSuccess;
     }
 
-    // Check for 429, emmit events and wait given in response body time
+    final responseError = await HttpResponseError.fromResponse(response);
+
+    // Check for 429, emit events and wait given in response body time
     if (response.statusCode == 429) {
       final responseBody = jsonDecode(await response.stream.bytesToString());
       final retryAfter = Duration(milliseconds: ((responseBody["retry_after"] as double) * 1000).ceil());
@@ -110,16 +131,17 @@ class HttpHandler {
       }
 
       _events.onRateLimitedController.add(RatelimitEvent(request, false, response));
-      logger.warning("${isGlobal ? "Global " : ""}Rate limited via 429 on endpoint: ${request.uri}. Trying to send request again in $retryAfter");
+
+      logger.warning(
+        "${isGlobal ? "Global " : ""}Rate limited via 429 on endpoint: ${request.uri}. Trying to send request again in $retryAfter",
+        responseError,
+      );
 
       return Future.delayed(retryAfter, () => execute(request));
     }
 
-    final responseError = HttpResponseError(response);
-    await responseError.finalize();
-
     (client.eventsRest as RestEventController).onHttpErrorController.add(HttpErrorEvent(responseError));
-    logger.finer("Got failure http response for endpoint: [${response.request?.url.toString()}]; Response: [${responseError.message}]");
+    logger.finest('Unknown/error response: ${responseError.toString(short: true)}', responseError);
 
     return responseError;
   }

diff --git a/lib/src/internal/http/http_request.dart b/lib/src/internal/http/http_request.dart
@@ -29,6 +29,9 @@ abstract class HttpRequest {
       {...headers, if (auditLog != null) "X-Audit-Log-Reason": auditLog!, "User-Agent": "Nyxx (${Constants.repoUrl}, ${Constants.version})"};
 
   Future<http.BaseRequest> prepareRequest();
+
+  @override
+  String toString() => '$method $uri';
 }
 
 /// [BasicRequest] with json body