reduce and normalize logging (#2615)

* reduce and normalize logging

* don't regen protos while testing

pkgs/dart_services/benchmark/bench.dart

@@ -10,6 +10,7 @@ import 'package:dart_services/src/analysis_server.dart';
 import 'package:dart_services/src/bench.dart';
 import 'package:dart_services/src/common.dart';
 import 'package:dart_services/src/compiler.dart';
+import 'package:dart_services/src/logging.dart';
 import 'package:dart_services/src/protos/dart_services.pb.dart' as proto;
 import 'package:dart_services/src/sdk.dart';
 import 'package:logging/logging.dart';
@@ -19,11 +20,8 @@ void main(List<String> args) async {
   final harness = BenchmarkHarness(asJson: json);
   final compiler = Compiler(Sdk.create(stableChannel));
 
-  Logger.root.level = Level.WARNING;
-  Logger.root.onRecord.listen((LogRecord record) {
-    print(record);
-    if (record.stackTrace != null) print(record.stackTrace);
-  });
+  Logger.root.level = Level.INFO;
+  emitLogsToStdout();
 
   final benchmarks = <Benchmark>[
     AnalyzerBenchmark('hello', sampleCode),

pkgs/dart_services/lib/services_cloud_run.dart

@@ -16,9 +16,9 @@ import 'package:shelf/shelf_io.dart' as shelf;
 import 'src/common_server_api.dart';
 import 'src/common_server_impl.dart';
 import 'src/github_oauth_handler.dart';
+import 'src/logging.dart';
 import 'src/sdk.dart';
 import 'src/server_cache.dart';
-import 'src/shelf_cors.dart' as shelf_cors;
 
 final Logger _logger = Logger('services');
 
@@ -45,22 +45,21 @@ Future<void> main(List<String> args) async {
   final redisServerUri = results['redis-url'] as String;
 
   Logger.root.level = Level.FINER;
-  Logger.root.onRecord.listen((LogRecord record) {
-    print(record);
-    if (record.stackTrace != null) print(record.stackTrace);
-  });
+  emitLogsToStdout();
 
   final cloudRunEnvVars = Platform.environment.entries
       .where((entry) => entry.key.startsWith('K_'))
       .map((entry) => '${entry.key}: ${entry.value}')
       .join('\n');
 
-  _logger.info('''Initializing dart-services:
-    port: $port
-    sdkPath: ${sdk.dartSdkPath}
-    redisServerUri: $redisServerUri
-    Cloud Run Environment variables:
-    $cloudRunEnvVars''');
+  _logger.info('''
+Initializing dart-services:
+port: $port
+sdkPath: ${sdk.dartSdkPath}
+redisServerUri: $redisServerUri
+Cloud Run Environment variables:
+$cloudRunEnvVars
+''');
 
   await GitHubOAuthHandler.initFromEnvironmentalVars();
 
@@ -70,15 +69,19 @@ Future<void> main(List<String> args) async {
 
 class EndpointsServer {
   static Future<EndpointsServer> serve(
-      int port, String redisServerUri, Sdk sdk) async {
+    int port,
+    String redisServerUri,
+    Sdk sdk,
+  ) async {
     final endpointsServer = EndpointsServer._(redisServerUri, sdk);
-
     await endpointsServer.init();
+
     endpointsServer.server = await shelf.serve(
       endpointsServer.handler,
       InternetAddress.anyIPv4,
       port,
     );
+
     return endpointsServer;
   }
 
@@ -106,32 +109,25 @@ class EndpointsServer {
     commonServerApi = CommonServerApi(_commonServerImpl);
 
     // Set cache for GitHub OAuth and add GitHub OAuth routes to our router.
-    GitHubOAuthHandler.setCache(redisServerUri == null
-        ? InMemoryCache()
-        : RedisCache(
-            redisServerUri,
-            sdk,
-            // The name of the Cloud Run revision being run, for more detail please see:
-            // https://cloud.google.com/run/docs/reference/container-contract#env-vars
-            Platform.environment['K_REVISION'],
-          ));
+    GitHubOAuthHandler.setCache(
+      redisServerUri == null
+          ? InMemoryCache()
+          : RedisCache(
+              redisServerUri,
+              sdk,
+              // The name of the Cloud Run revision being run, for more detail please see:
+              // https://cloud.google.com/run/docs/reference/container-contract#env-vars
+              Platform.environment['K_REVISION'],
+            ),
+    );
     GitHubOAuthHandler.addRoutes(commonServerApi.router);
 
     pipeline = const Pipeline()
-        .addMiddleware(logRequests())
-        .addMiddleware(_createCustomCorsHeadersMiddleware());
+        .addMiddleware(logRequestsToLogger(_logger))
+        .addMiddleware(createCustomCorsHeadersMiddleware());
 
     handler = pipeline.addHandler(commonServerApi.router.call);
   }
 
   Future<void> init() => _commonServerImpl.init();
-
-  Middleware _createCustomCorsHeadersMiddleware() {
-    return shelf_cors.createCorsHeadersMiddleware(corsHeaders: <String, String>{
-      'Access-Control-Allow-Origin': '*',
-      'Access-Control-Allow-Methods': 'GET, POST, OPTIONS',
-      'Access-Control-Allow-Headers':
-          'Origin, X-Requested-With, Content-Type, Accept, x-goog-api-client'
-    });
-  }
 }

pkgs/dart_services/lib/services_dev.dart

@@ -16,9 +16,9 @@ import 'package:shelf/shelf_io.dart' as shelf;
 import 'src/common_server_api.dart';
 import 'src/common_server_impl.dart';
 import 'src/github_oauth_handler.dart';
+import 'src/logging.dart';
 import 'src/sdk.dart';
 import 'src/server_cache.dart';
-import 'src/shelf_cors.dart' as shelf_cors;
 
 final Logger _logger = Logger('services');
 
@@ -39,57 +39,52 @@ Future<void> main(List<String> args) async {
   }
 
   Logger.root.level = Level.FINER;
-  Logger.root.onRecord.listen((LogRecord record) {
-    print(record);
-    if (record.stackTrace != null) print(record.stackTrace);
-  });
+  emitLogsToStdout();
 
   await GitHubOAuthHandler.initFromEnvironmentalVars();
 
-  await EndpointsServer.serve(port, Sdk.create(result['channel'] as String),
-      result['null-safety'] as bool);
+  final channelName = result['channel'] as String;
+  final nullSafety = result['null-safety'] as bool;
+
+  await EndpointsServer.serve(port, Sdk.create(channelName), nullSafety);
+
   _logger.info('Listening on port $port');
 }
 
 class EndpointsServer {
   static Future<EndpointsServer> serve(
       int port, Sdk sdk, bool nullSafety) async {
     final endpointsServer = EndpointsServer._(sdk, nullSafety);
+    await endpointsServer.init();
+
     await shelf.serve(endpointsServer.handler, InternetAddress.anyIPv4, port);
     return endpointsServer;
   }
 
   late final Pipeline pipeline;
   late final Handler handler;
   late final CommonServerApi commonServerApi;
+  late final CommonServerImpl commonServerImpl;
 
   EndpointsServer._(Sdk sdk, bool nullSafety) {
-    final commonServerImpl = CommonServerImpl(
+    commonServerImpl = CommonServerImpl(
       _Cache(),
       sdk,
     );
     commonServerApi = CommonServerApi(commonServerImpl);
-    commonServerImpl.init();
 
     // Set cache for GitHub OAuth and add GitHub OAuth routes to our router.
     GitHubOAuthHandler.setCache(InMemoryCache());
     GitHubOAuthHandler.addRoutes(commonServerApi.router);
 
     pipeline = const Pipeline()
-        .addMiddleware(logRequests())
-        .addMiddleware(_createCustomCorsHeadersMiddleware());
+        .addMiddleware(logRequestsToLogger(_logger))
+        .addMiddleware(createCustomCorsHeadersMiddleware());
 
     handler = pipeline.addHandler(commonServerApi.router.call);
   }
 
-  Middleware _createCustomCorsHeadersMiddleware() {
-    return shelf_cors.createCorsHeadersMiddleware(corsHeaders: <String, String>{
-      'Access-Control-Allow-Origin': '*',
-      'Access-Control-Allow-Methods': 'GET, POST, OPTIONS',
-      'Access-Control-Allow-Headers':
-          'Origin, X-Requested-With, Content-Type, Accept, x-goog-api-client'
-    });
-  }
+  Future<void> init() => commonServerImpl.init();
 }
 
 class _Cache implements ServerCache {

pkgs/dart_services/lib/src/analysis_server.dart

@@ -493,7 +493,7 @@ abstract class AnalysisServerWrapper {
       Map<String, String> sources, String sourceName, int offset) async {
     if (serverScheduler.queueCount > 0) {
       _logger
-          .info('completeImpl: Scheduler queue: ${serverScheduler.queueCount}');
+          .fine('completeImpl: Scheduler queue: ${serverScheduler.queueCount}');
     }
 
     return serverScheduler.schedule(ClosureTask<CompletionResults>(() async {

pkgs/dart_services/lib/src/analysis_servers.dart

@@ -41,8 +41,8 @@ class AnalysisServersWrapper {
       _restartingSince == null ||
       DateTime.now().difference(_restartingSince!).inMinutes < 30;
 
-  Future<void> warmup() async {
-    _logger.info('Beginning AnalysisServersWrapper init().');
+  Future<void> init() async {
+    _logger.fine('Beginning AnalysisServersWrapper init().');
     _dartAnalysisServer = DartAnalysisServerWrapper(dartSdkPath: _dartSdkPath);
     _flutterAnalysisServer =
         FlutterAnalysisServerWrapper(dartSdkPath: _dartSdkPath);
@@ -75,7 +75,7 @@ class AnalysisServersWrapper {
     await shutdown();
     _logger.info('shutdown');
 
-    await warmup();
+    await init();
     _logger.warning('Restart complete');
   }
 
@@ -218,7 +218,7 @@ class AnalysisServersWrapper {
     try {
       final watch = Stopwatch()..start();
       final response = await body(imports, location);
-      _logger.info('PERF: Computed $action in ${watch.elapsedMilliseconds}ms.');
+      _logger.fine('PERF: Computed $action in ${watch.elapsedMilliseconds}ms.');
       return response;
     } catch (e, st) {
       _logger.severe(errorDescription, e, st);

pkgs/dart_services/lib/src/common_server_api.dart

@@ -5,13 +5,15 @@
 import 'dart:async';
 import 'dart:convert';
 
+import 'package:logging/logging.dart';
 import 'package:meta/meta.dart';
 import 'package:protobuf/protobuf.dart';
 import 'package:shelf/shelf.dart';
 import 'package:shelf_router/shelf_router.dart';
 
 import 'common_server_impl.dart' show BadRequest, CommonServerImpl;
 import 'protos/dart_services.pb.dart' as proto;
+import 'shelf_cors.dart' as shelf_cors;
 
 export 'common_server_impl.dart' show log;
 
@@ -241,3 +243,57 @@ class CommonServerApi {
     'Content-Type': protobufContentType
   };
 }
+
+Middleware createCustomCorsHeadersMiddleware() {
+  return shelf_cors.createCorsHeadersMiddleware(corsHeaders: <String, String>{
+    'Access-Control-Allow-Origin': '*',
+    'Access-Control-Allow-Methods': 'GET, POST, OPTIONS',
+    'Access-Control-Allow-Headers':
+        'Origin, X-Requested-With, Content-Type, Accept, x-goog-api-client'
+  });
+}
+
+Middleware logRequestsToLogger(Logger log) {
+  return (Handler innerHandler) {
+    return (request) {
+      final watch = Stopwatch()..start();
+
+      return Future.sync(() => innerHandler(request)).then((response) {
+        log.info(_formatMessage(request, watch.elapsed, response: response));
+
+        return response;
+      }, onError: (Object error, StackTrace stackTrace) {
+        if (error is HijackException) throw error;
+
+        log.info(_formatMessage(request, watch.elapsed, error: error));
+
+        // ignore: only_throw_errors
+        throw error;
+      });
+    };
+  };
+}
+
+String _formatMessage(
+  Request request,
+  Duration elapsedTime, {
+  Response? response,
+  Object? error,
+}) {
+  final method = request.method;
+  final requestedUri = request.requestedUri;
+  final statusCode = response?.statusCode;
+  final bytes = response?.contentLength;
+  final size = ((bytes ?? 0) + 1023) ~/ 1024;
+
+  final ms = elapsedTime.inMilliseconds;
+  final query = requestedUri.query == '' ? '' : '?${requestedUri.query}';
+
+  var message = '${ms.toString().padLeft(5)}ms ${size.toString().padLeft(4)}k '
+      '$statusCode $method ${requestedUri.path}$query';
+  if (error != null) {
+    message = '$message [$error]';
+  }
+
+  return message;
+}