Merge pull request #1616 from atsign-foundation/gkc/reduce-root-log-n…

…oise

feat: at_root_server: rate limiting for invalid atSigns; misc logging and other cleanup

packages/at_root_server/CHANGELOG.md

@@ -1,3 +1,7 @@
+## 2.1.0
+- feat: rate limiting when looking up non-existent atSigns
+- feat: miscellaneous logging enhancements
+- fix: removed unnecessary 10-second delay during normal startup
 ## 2.0.5
 - upgrade persistence spec version
 ## 2.0.4

packages/at_root_server/lib/src/client/at_root_client.dart

@@ -5,13 +5,17 @@ import 'package:at_persistence_root_server/at_persistence_root_server.dart';
 import 'package:at_utils/at_logger.dart';
 import 'package:at_commons/at_commons.dart';
 
+enum RootClientState {listening,closing,closed}
+
 /// Represents Root Server client instance which contains socket on which a connection got established
 class RootClient {
   late Socket _socket;
   String? _address;
   int? _port;
   static final _keyStoreManager = KeystoreManagerImpl();
   final _buffer = StringBuffer(capacity: 255);
+  int notFoundCount = 0;
+  late RootClientState state;
 
   RootClient(Socket s) {
     _socket = s;
@@ -20,6 +24,7 @@ class RootClient {
     RootClientPool().add(this);
     _socket.listen(_messageHandler,
         onError: _errorHandler, onDone: _finishedHandler);
+    state = RootClientState.listening;
   }
 
   var logger = AtSignLogger('RootClient');
@@ -29,26 +34,43 @@ class RootClient {
   ///  @param - data : data received from client over the socket
   Future<void> _messageHandler(data) async {
     try {
-      logger.info('In root client _messagehandler');
+      logger.finest('${_address}:${_port} In root client _messagehandler');
       var message = utf8.decode(data);
       message = message.toLowerCase();
       _buffer.append(message);
-      if (_buffer.getData()!.trim() == '@exit') {
+      var lookupPayload = _buffer.getData()!.trim();
+      if (lookupPayload == '@exit') {
         _finishedHandler();
         return;
       } else {
         if (_buffer.isEnd()) {
           var result = await _keyStoreManager
               .getKeyStore()
-              .get(_buffer.getData()!.trim());
-          logger.finer('result:${result}');
+              .get(lookupPayload);
+          logger.info('${_address}:${_port} Looked up: $lookupPayload | Found: $result');
+
+          if (result == null) {
+            notFoundCount++;
+            if (notFoundCount > 1) {
+              // If we've already had at least one lookup of a non-existent atSign
+              // then we will wait a few seconds before responding
+              await Future.delayed(Duration(seconds: 3));
+            }
+
+            if (notFoundCount > 2) {
+              // And if we've already had at least two lookups of a non-existent
+              // atSign then we will terminate the connection
+              _finishedHandler();
+              return;
+            }
+          }
           result ??= 'null';
           write(result + '\r\n@');
           _buffer.clear();
         }
       }
     } on Exception catch (exception) {
-      logger.severe(exception);
+      logger.severe('${_address}:${_port} _messageHandler | $exception');
       _socket.destroy();
     } catch (error) {
       _errorHandler(error.toString());
@@ -59,16 +81,19 @@ class RootClient {
   ///  Return type - void
   ///  @param - error : error string
   void _errorHandler(error) {
-    logger.severe('${_address}:${_port} Error: $error');
-    removeClient(this);
-    _socket.destroy();
+    if (state == RootClientState.listening) {
+      logger.severe('${_address}:${_port} Error: $error');
+      removeClient(this);
+    }
   }
 
   /// _finishedHandler close the client connection and remove from client pool
   ///  Return type - void
   void _finishedHandler() {
-    logger.info('${_address}:${_port} Disconnected');
-    removeClient(this);
+    if (state == RootClientState.listening) {
+      logger.info('${_address}:${_port} Disconnected');
+      removeClient(this);
+    }
   }
 
   /// write - Writes received message to the client socket
@@ -83,7 +108,9 @@ class RootClient {
   /// return type - void
   /// @param - rootClient - Instance of RootClient
   void removeClient(RootClient rootClient) {
+    state = RootClientState.closing;
     rootClient._socket.destroy();
     RootClientPool().remove(rootClient);
+    state = RootClientState.closed;
   }
 }

packages/at_root_server/lib/src/server/at_root_server_impl.dart

@@ -85,7 +85,7 @@ class RootServerImpl implements AtRootServer {
     logger.info('Connection from '
         '${socket.remoteAddress.address}:${socket.remotePort}');
     var client = RootClient(socket);
-    logger.info('connection successful\n');
+    logger.info('connection successful');
     client.write('@');
   }
 
@@ -130,6 +130,9 @@ class RootServerImpl implements AtRootServer {
       var certsAvailable = false;
       // if certs are unavailable then retry max 10 minutes
       while (true) {
+        if (retryCount > 0) {
+          sleep(Duration(seconds: 10));
+        }
         try {
           if (certsAvailable || retryCount > 60) {
             break;
@@ -142,7 +145,6 @@ class RootServerImpl implements AtRootServer {
           retryCount++;
           logger.info('certs unavailable. Retry count ${retryCount}');
         }
-        sleep(Duration(seconds: 10));
       }
       if (certsAvailable) {
         SecureServerSocket.bind(InternetAddress.anyIPv4, port!, secCon)
@@ -178,7 +180,12 @@ class RootServerImpl implements AtRootServer {
     serverSocket.listen((connection) {
       _handle(AtClientConnectionImpl(connection));
     }, onError: (error) {
-      logger.severe('rootServer Socket Error :' +
+      if (error is HandshakeException) {
+        // This is not unusual.
+        // See https://github.com/atsign-foundation/at_server/issues/1590
+        return;
+      }
+      logger.warning('ServerSocket stream error :' +
           error.toString() +
           'connecting to ' +
           serverSocket.address.toString());

packages/at_root_server/pubspec.yaml

@@ -1,6 +1,6 @@
 name: at_root_server
 description: Root server implementation.
-version: 2.0.5
+version: 2.1.0
 repository: https://github.com/atsign-foundation/at_server
 homepage: https://atsign.dev
 publish_to: none
@@ -9,12 +9,12 @@ environment:
   sdk: '>=2.15.0 <4.0.0'
 
 dependencies:
-  args: ^2.1.0
-  uuid: ^3.0.4
-  yaml: ^3.1.0
-  at_commons: 3.0.53
+  args: 2.4.2
+  uuid: 3.0.6
+  yaml: 3.1.2
+  at_commons: 3.0.56
   at_utils: 3.0.15
-  at_server_spec: 3.0.13
+  at_server_spec: 3.0.15
   at_persistence_root_server:
     git:
       url: https://github.com/atsign-foundation/at_server.git
@@ -25,6 +25,6 @@ dependencies:
 dev_dependencies:
   # Adding test_cov for generating the test coverage.
   test_cov: ^1.0.1
-  lints: ^1.0.1
+  lints: ^2.1.1
   test: ^1.24.6
-  coverage: ^1.0.3
+  coverage: ^1.6.3