refactor: Move query counter to the log manager. (serverpod#2553)

BenAuerDev · Jul 31, 2024 · 2142c8b · 2142c8b
1 parent 7ffe397
commit 2142c8b
Show file tree

Hide file tree

Showing 7 changed files with 109 additions and 13 deletions.
diff --git a/packages/serverpod/lib/src/server/log_manager/log_manager.dart b/packages/serverpod/lib/src/server/log_manager/log_manager.dart
@@ -21,6 +21,8 @@ class SessionLogManager {
 
   final LogSettings Function(Session) _settingsForSession;
 
+  int _numberOfQueries;
+
   int _logOrderId;
 
   int get _nextLogOrderId => ++_logOrderId;
@@ -32,6 +34,7 @@ class SessionLogManager {
     required LogSettings Function(Session) settingsForSession,
     required String serverId,
   })  : _logOrderId = 0,
+        _numberOfQueries = 0,
         _logWriter = logWriter,
         _settingsForSession = settingsForSession,
         _serverId = serverId;
@@ -144,6 +147,7 @@ class SessionLogManager {
     required StackTrace stackTrace,
   }) async {
     var executionTime = duration.inMicroseconds / _microNormalizer;
+    _numberOfQueries++;
 
     var logSettings = _settingsForSession(session);
 
@@ -314,10 +318,10 @@ class SessionLogManager {
     if (session.serverpod.runMode == ServerpodRunMode.development) {
       if (session is MethodCallSession) {
         stdout.writeln(
-            'METHOD CALL: ${session.endpointName}.${session.methodName} duration: ${duration.inMilliseconds}ms numQueries: ${cachedEntry.queries.length} authenticatedUser: $authenticatedUserId');
+            'METHOD CALL: ${session.endpointName}.${session.methodName} duration: ${duration.inMilliseconds}ms numQueries: $_numberOfQueries authenticatedUser: $authenticatedUserId');
       } else if (session is FutureCallSession) {
         stdout.writeln(
-            'FUTURE CALL: ${session.futureCallName} duration: ${duration.inMilliseconds}ms numQueries: ${cachedEntry.queries.length}');
+            'FUTURE CALL: ${session.futureCallName} duration: ${duration.inMilliseconds}ms numQueries: $_numberOfQueries');
       }
       if (exception != null) {
         stdout.writeln(exception);
@@ -347,7 +351,7 @@ class SessionLogManager {
         endpoint: session.endpointName,
         method: session.methodName,
         duration: duration.inMicroseconds / 1000000.0,
-        numQueries: cachedEntry.numQueries,
+        numQueries: _numberOfQueries,
         slow: isSlow,
         error: exception,
         stackTrace: stackTrace?.toString(),
@@ -368,7 +372,7 @@ class SessionLogManager {
         stderr.writeln('${DateTime.now().toUtc()} FAILED TO LOG SESSION');
         if (session.methodName != null) {
           stderr.writeln(
-              'CALL: ${session.endpointName}.${session.methodName} duration: ${duration.inMilliseconds}ms numQueries: ${cachedEntry.queries.length} authenticatedUser: $authenticatedUserId');
+              'CALL: ${session.endpointName}.${session.methodName} duration: ${duration.inMilliseconds}ms numQueries: $_numberOfQueries authenticatedUser: $authenticatedUserId');
         }
         stderr.writeln('CALL error: $exception');
         stderr.writeln('$logStackTrace');

diff --git a/packages/serverpod/lib/src/server/log_manager/session_log_cache.dart b/packages/serverpod/lib/src/server/log_manager/session_log_cache.dart
@@ -10,9 +10,6 @@ class SessionLogEntryCache {
   /// Queries made during the session.
   final List<QueryLogEntry> queries = [];
 
-  /// Number of queries made during this session.
-  int get numQueries => queries.length;
-
   /// Log entries made during the session.
   final List<LogEntry> logEntries = [];
 

diff --git a/tests/serverpod_test_client/lib/src/protocol/client.dart b/tests/serverpod_test_client/lib/src/protocol/client.dart
@@ -970,6 +970,12 @@ class EndpointLogging extends _i1.EndpointRef {
         {'seconds': seconds},
       );
 
+  _i2.Future<void> queryMethod(int queries) => caller.callServerEndpoint<void>(
+        'logging',
+        'queryMethod',
+        {'queries': queries},
+      );
+
   _i2.Future<void> failedQueryMethod() => caller.callServerEndpoint<void>(
         'logging',
         'failedQueryMethod',

diff --git a/tests/serverpod_test_server/lib/src/endpoints/logging.dart b/tests/serverpod_test_server/lib/src/endpoints/logging.dart
@@ -5,17 +5,21 @@ class LoggingEndpoint extends Endpoint {
   Future<void> slowQueryMethod(Session session, int seconds) async {
     try {
       await session.db.unsafeQuery('SELECT pg_sleep($seconds);');
-    } catch (e) {
-      print(e);
-    }
+    } catch (e) {}
+  }
+
+  Future<void> queryMethod(Session session, int queries) async {
+    try {
+      for (var i = 0; i < queries; i++) {
+        await Types.db.findFirstRow(session);
+      }
+    } catch (e) {}
   }
 
   Future<void> failedQueryMethod(Session session) async {
     try {
       await session.db.unsafeQuery('SELECT * FROM table_does_not_exist;');
-    } catch (e) {
-      print(e);
-    }
+    } catch (e) {}
   }
 
   Future<void> slowMethod(Session session, int delayMillis) async {

diff --git a/tests/serverpod_test_server/lib/src/generated/endpoints.dart b/tests/serverpod_test_server/lib/src/generated/endpoints.dart
@@ -2237,6 +2237,24 @@ class Endpoints extends _i1.EndpointDispatch {
             params['seconds'],
           ),
         ),
+        'queryMethod': _i1.MethodConnector(
+          name: 'queryMethod',
+          params: {
+            'queries': _i1.ParameterDescription(
+              name: 'queries',
+              type: _i1.getType<int>(),
+              nullable: false,
+            )
+          },
+          call: (
+            _i1.Session session,
+            Map<String, dynamic> params,
+          ) async =>
+              (endpoints['logging'] as _i17.LoggingEndpoint).queryMethod(
+            session,
+            params['queries'],
+          ),
+        ),
         'failedQueryMethod': _i1.MethodConnector(
           name: 'failedQueryMethod',
           params: {},

diff --git a/tests/serverpod_test_server/lib/src/generated/protocol.yaml b/tests/serverpod_test_server/lib/src/generated/protocol.yaml
@@ -119,6 +119,7 @@ listParameters:
   - returnDurationListNullableDurations:
 logging:
   - slowQueryMethod:
+  - queryMethod:
   - failedQueryMethod:
   - slowMethod:
   - failingMethod:

diff --git a/tests/serverpod_test_server/test_integration/logging/endpoint_call_logging_test.dart b/tests/serverpod_test_server/test_integration/logging/endpoint_call_logging_test.dart
@@ -146,6 +146,72 @@ void main() async {
       expect(logs.first.sessionLogEntry.method, 'slowQueryMethod');
     });
 
+    test(
+        'Given a log setting that enables all logs when calling a method executing a query then a query log is created',
+        () async {
+      var settings = RuntimeSettingsBuilder()
+          .withLogSettings(
+            LogSettingsBuilder().build(),
+          )
+          .build();
+
+      await server.updateRuntimeSettings(settings);
+
+      await client.logging.queryMethod(1);
+
+      var logs = await LoggingUtil.findAllLogs(session);
+
+      expect(logs, hasLength(1));
+
+      expect(logs.first.queries, hasLength(1));
+      expect(logs.first.sessionLogEntry.numQueries, 1);
+    });
+
+    test(
+        'Given a log setting that enables all logs when calling a method executing several queries then a log for each query is created',
+        () async {
+      var settings = RuntimeSettingsBuilder()
+          .withLogSettings(
+            LogSettingsBuilder().build(),
+          )
+          .build();
+
+      await server.updateRuntimeSettings(settings);
+
+      await client.logging.queryMethod(4);
+
+      var logs = await LoggingUtil.findAllLogs(session);
+
+      expect(logs, hasLength(1));
+
+      expect(logs.first.queries, hasLength(4));
+      expect(logs.first.sessionLogEntry.numQueries, 4);
+    });
+
+    test(
+        'Given a log setting that turns off all database query logging when calling a method executing several queries then the number of queries are still counted.',
+        () async {
+      var settings = RuntimeSettingsBuilder()
+          .withLogSettings(
+            LogSettingsBuilder()
+                .withLoggingTurnedDown()
+                .withLogAllSessions(true)
+                .build(),
+          )
+          .build();
+
+      await server.updateRuntimeSettings(settings);
+
+      await client.logging.queryMethod(4);
+
+      var logs = await LoggingUtil.findAllLogs(session);
+
+      expect(logs, hasLength(1));
+
+      expect(logs.first.queries, isEmpty);
+      expect(logs.first.sessionLogEntry.numQueries, 4);
+    });
+
     test(
         'Given a log setting that enables failed query logging when calling a method executing an invalid query then a single log entry is created.',
         () async {