feat: Improved logging (closes #62)

wrestling_scoreboard_server/.env.example

@@ -5,11 +5,14 @@ CORS_ALLOW_ORIGIN='*'
 WEB_SOCKET_PING_INTERVAL_SECS=30
 
 JWT_ISSUER='Wrestling Scoreboard (oberhauser.dev)'
-JWT_SECRET=my-32-character-ultra-secure-and-ultra-long-secret
+JWT_SECRET=my-ultra-secure-and-ultra-long-secret
 JWT_EXPIRES_IN_DAYS=90
 
 DATABASE_HOST='localhost'
 DATABASE_PORT=5432
 DATABASE_USER='wrestling'
 DATABASE_PASSWORD=''
 DATABASE_NAME='wrestling_scoreboard'
+
+# One of: ALL, FINEST, FINER, FINE, CONFIG, INFO, WARNING, SEVERE, SHOUT, OFF
+LOG_LEVEL='INFO'

wrestling_scoreboard_server/.gitignore

@@ -1,3 +1,6 @@
+# Misc
+*.log
+
 # Files and directories created by pub.
 .dart_tool/
 .packages

wrestling_scoreboard_server/README.md

@@ -55,6 +55,9 @@ Additionally, enable session for user `www` on boot:
 sudo loginctl enable-linger www
 ```
 
+To view server logs: 
+`journalctl --user -u wrestling-scoreboard-server`
+
 ### Web server
 
 If using [Nginx](https://en.wikipedia.org/wiki/Nginx) as Reverse Proxy, you can take advantage of [this config](docs/nginx/wrestling-scoreboard-server.conf) files.

wrestling_scoreboard_server/database/README.md

@@ -34,7 +34,7 @@ On Linux you may want to log in as postgres user: `sudo -u postgres -i`
 
 Use this on peer authentication:
 ```shell
-sudo -u postgres psql postgres # For creation
+sudo -u postgres psql postgres # For creation and dropping
 sudo -u postgres psql wrestling_scoreboard # For altering database wrestling_scoreboard
 ```
 

wrestling_scoreboard_server/lib/controllers/organizational_controller.dart

@@ -1,9 +1,12 @@
+import 'package:logging/logging.dart';
 import 'package:postgres/postgres.dart' as psql;
 import 'package:wrestling_scoreboard_common/common.dart';
 import 'package:wrestling_scoreboard_server/controllers/entity_controller.dart';
 import 'package:wrestling_scoreboard_server/services/postgres_db.dart';
 
 abstract class OrganizationalController<T extends Organizational> extends ShelfController<T> {
+  final _logger = Logger('OrganizationalController');
+
   OrganizationalController({required super.tableName});
 
   late Future<psql.Statement> getSingleOfOrgRawStmt;
@@ -25,7 +28,7 @@ abstract class OrganizationalController<T extends Organizational> extends ShelfC
   Future<Map<String, dynamic>> getSingleOfOrgRaw(String orgSyncId, {required int orgId}) async {
     if (orgSyncId != orgSyncId.trim()) {
       orgSyncId = orgSyncId.trim();
-      print('$T with orgSyncId "$orgSyncId" was trimmed');
+      _logger.warning('$T with orgSyncId "$orgSyncId" was trimmed');
     }
     final resStream = (await getSingleOfOrgRawStmt).bind({'orgSyncId': orgSyncId, 'orgId': orgId});
     final many = await resStream.toColumnMap().toList();

wrestling_scoreboard_server/lib/controllers/websocket_handler.dart

@@ -1,5 +1,6 @@
 import 'dart:convert';
 
+import 'package:logging/logging.dart';
 import 'package:shelf_web_socket/shelf_web_socket.dart';
 import 'package:web_socket_channel/web_socket_channel.dart';
 import 'package:wrestling_scoreboard_common/common.dart';
@@ -19,6 +20,8 @@ import 'package:wrestling_scoreboard_server/services/auth.dart';
 import 'entity_controller.dart';
 import 'league_team_participation_controller.dart';
 
+final _logger = Logger('Websocket');
+
 final Map<WebSocketChannel, UserPrivilege> webSocketPool = <WebSocketChannel, UserPrivilege>{};
 
 void broadcast(Future<String> Function(bool obfuscate) builder) async {
@@ -297,7 +300,7 @@ Future<int> handleSingle<T extends DataObject>({
   required T single,
   UserPrivilege privilege = UserPrivilege.write,
 }) async {
-  print('${DateTime.now()} ${operation.name.toUpperCase()} ${single.tableName}/${single.id}');
+  _logger.fine('${DateTime.now()} ${operation.name.toUpperCase()} ${single.tableName}/${single.id}');
   final controller = ShelfController.getControllerFromDataType(T);
   if (operation == CRUD.update) {
     if (privilege < UserPrivilege.write) {
@@ -336,7 +339,7 @@ Future<int> handleSingleRaw<T extends DataObject>({
   required Map<String, dynamic> single,
   UserPrivilege privilege = UserPrivilege.write,
 }) async {
-  print('${DateTime.now()} ${operation.name.toUpperCase()} ${getTableNameFromType(T)}/${single['id']}');
+  _logger.fine('${DateTime.now()} ${operation.name.toUpperCase()} ${getTableNameFromType(T)}/${single['id']}');
   final controller = ShelfController.getControllerFromDataType(T);
   if (operation == CRUD.update) {
     if (privilege < UserPrivilege.write) {
@@ -374,7 +377,7 @@ Future<void> handleMany<T extends DataObject>({
   required ManyDataObject<T> many,
   UserPrivilege privilege = UserPrivilege.none,
 }) {
-  print('${DateTime.now()} ${operation.name.toUpperCase()} ${getTableNameFromType(T)}s');
+  _logger.fine('${DateTime.now()} ${operation.name.toUpperCase()} ${getTableNameFromType(T)}s');
   throw DataUnimplementedError(operation, many.runtimeType);
 }
 
@@ -383,7 +386,7 @@ Future<void> handleManyRaw<T extends DataObject>({
   required ManyDataObject<Map<String, dynamic>> many,
   UserPrivilege privilege = UserPrivilege.none,
 }) {
-  print('${DateTime.now()} ${operation.name.toUpperCase()} ${getTableNameFromType(T)}s');
+  _logger.fine('${DateTime.now()} ${operation.name.toUpperCase()} ${getTableNameFromType(T)}s');
   throw DataUnimplementedError(operation, many.runtimeType);
 }
 

wrestling_scoreboard_server/lib/server.dart

@@ -38,16 +38,29 @@ Future init() async {
   await _parsePubspec();
 
   // Init logger
-  Logger.root.level = Level.INFO;
-  Logger.root.onRecord.listen((record) {
-    print('[${record.time}] ${record.level.name}: ${record.message}');
-    if (record.error != null) {
-      print('Error: ${record.error}');
-      if (record.stackTrace != null) {
-        print('StackTrace: ${record.stackTrace}');
+  Logger.root.level =
+      Level.LEVELS.where((level) => level.name == env['LOG_LEVEL']?.toUpperCase()).singleOrNull ?? Level.INFO;
+  Logger.root.onRecord.listen(
+    (record) async {
+      String text = '[${record.time}] ${record.level.name}: ${record.message}';
+      if (record.error != null) {
+        text += '\nError: ${record.error}';
+        if (record.stackTrace != null) {
+          text += 'StackTrace: ${record.stackTrace}';
+        }
       }
-    }
-  });
+      text = switch (record.level) {
+        Level.FINEST => '\x1B[38;5;247m$text\x1B[0m',
+        Level.FINER => '\x1B[38;5;248m$text\x1B[0m',
+        Level.FINE => '\x1B[38;5;249m$text\x1B[0m',
+        Level.CONFIG => '\x1B[34m$text\x1B[0m',
+        Level.WARNING => '\x1B[33m$text\x1B[0m',
+        Level.SEVERE || Level.SHOUT => '\x1B[31m$text\x1B[0m',
+        _ => text,
+      };
+      print(text);
+    },
+  );
 
   // If the "PORT" environment variable is set, listen to it. Otherwise, 8080.
   // https://cloud.google.com/run/docs/reference/container-contract#port
@@ -56,6 +69,8 @@ Future init() async {
   // Must open the database before initializing any routes.
   await PostgresDb().open();
 
+  final webSocketLog = Logger('Websocket');
+
   // Router instance to handler requests.
   final router = shelf_router.Router()
     ..mount('/api', ApiRoute().pipeline)
@@ -64,12 +79,12 @@ Future init() async {
         return websocketHandler(request);
       } on HijackException catch (error, _) {
         // A HijackException should bypass the response-writing logic entirely.
-        print('Warning: HijackException thrown on WebsocketHandler.\n$error');
+        webSocketLog.warning('Warning: HijackException thrown on WebsocketHandler.\n$error');
         // TODO hide stack trace or handle better
         // Exception is handled here: https://pub.dev/documentation/shelf/latest/shelf_io/handleRequest.html
         rethrow;
       } catch (error, _) {
-        print('Error thrown by handler.\n$error');
+        webSocketLog.severe('Error thrown by Websocket Handler handler.\n$error');
         return Response.internalServerError();
       }
     })
@@ -106,8 +121,11 @@ Future init() async {
     port,
   );
 
+  final serverLog = Logger('Server');
+
   final serverUrl = 'http://${server.address.host}:${server.port}';
-  print('Serving at $serverUrl');
-  print('Serving API at $serverUrl/api');
-  print('Serving Websocket at $serverUrl/ws');
+  serverLog.info('\n\n############## Server started at ${DateTime.now().toIso8601String()} ###########\n');
+  serverLog.info('Serving at $serverUrl');
+  serverLog.info('Serving API at $serverUrl/api');
+  serverLog.info('Serving Websocket at $serverUrl/ws');
 }