chore: Improve log verbosity (#577)

Signed-off-by: Ivo Yankov <ivo@devlabs.bg>

src/services/ConnectionService.ts

@@ -24,6 +24,7 @@ import { LoggerService } from './LoggerService';
 import { ServiceLocator } from './ServiceLocator';
 import { CLIService } from './CLIService';
 import { Errors } from '../Errors/LocalNodeErrors';
+import debounce from '../utils/debounce';
 
 /**
  * ConnectionService is a service class that handles network connections.
@@ -52,6 +53,9 @@ export class ConnectionService implements IService{
      */
     private cliService: CLIService;
 
+    // Debounced function to print error message at most once every N seconds
+    private readonly debouncedErrorLog;
+
     /**
      * Constructs a new instance of the ConnectionService.
      * Initializes the logger and CLI service, and logs the initialization of the connection service.
@@ -61,6 +65,11 @@ export class ConnectionService implements IService{
         this.logger = ServiceLocator.Current.get<LoggerService>(LoggerService.name);
         this.cliService = ServiceLocator.Current.get<CLIService>(CLIService.name);
         this.logger.trace('Connection Service Initialized!', this.serviceName);
+
+        this.debouncedErrorLog = debounce((message: string) => {
+            this.logger.info(message, this.serviceName);
+        }, 5000);
+
     }
 
     /**
@@ -72,7 +81,7 @@ export class ConnectionService implements IService{
      * @returns {Promise<void>} A promise that resolves when the port is ready for connection.
      * @public
      */
-    public async waitForFiringUp(port: number): Promise<void> {
+    public async waitForFiringUp(port: number, serviceName: string): Promise<void> {
         const { host } = this.cliService.getCurrentArgv();
         let isReady = false;
         // this means that we wait around 100 seconds, normal consensus node startup takes around 60 seconds
@@ -83,12 +92,13 @@ export class ConnectionService implements IService{
             .on('data', () => {
               isReady = true;
             })
-            .on('error', (err) => {
-              this.logger.trace(
-                `Waiting for the containers at ${host}:${port}, retrying in 0.1 seconds...`,
-                this.serviceName
-              );
-              this.logger.error(err.message, this.serviceName);
+            .on('error', (err: any) => {
+              if (err.code === 'ECONNREFUSED') {
+                  this.debouncedErrorLog(`${serviceName} not yet available at: ${host}:${port}. Retrying...`);
+              }
+              else {
+                  this.logger.error(err.message, this.serviceName);
+              }
             });
 
             retries--;

src/services/DockerService.ts

@@ -251,7 +251,23 @@ export class DockerService implements IService{
       const recommendedMemory = isMultiNodeMode ? MIN_MEMORY_MULTI_MODE : MIN_MEMORY_SINGLE_MODE;
       this.logger.error(`Your docker memory resources are set to ${dockerMemory.toFixed(2)}GB. This is not enough, set to at least ${recommendedMemory}GB`, this.serviceName);
     }
-
+
+    private logShellOutput(shellExec: any) {
+        [shellExec.stdout, shellExec.stderr].forEach( (output: string) => {
+            output.split("\n").map((line: string) => {
+                if (line === "") return;
+                this.logger.debug(line, this.serviceName);
+            });
+        });
+    }
+
+    private async executeExternal(command: string, options = {}): Promise<shell.ShellString> {
+        this.logger.trace(`🚀 Executing command: ${command}`, this.serviceName);
+        const shellExec = shell.exec(command, options);
+        this.logShellOutput(shellExec);
+        return shellExec;
+    }
+
     /**
      * Returns a Docker container object for the given container label.
      * 
@@ -352,9 +368,7 @@ export class DockerService implements IService{
           composeFiles.push(...this.getUserComposeFiles(userComposeDir));
       }
 
-      return shell.exec(
-          `docker compose -f ${composeFiles.join(' -f ')} up -d 2>${this.getNullOutput()}`
-      );
+      return this.executeExternal(`docker compose -f ${composeFiles.join(' -f ')} up -d`, {silent: true});
     }
 
     /**
@@ -388,8 +402,8 @@ export class DockerService implements IService{
     public async tryDockerRecovery(stateName: string): Promise<void> {
         const nullOutput = this.getNullOutput();
         this.logger.trace('Stopping the docker containers...', stateName);
-        shell.exec(`docker compose kill --remove-orphans 2>${nullOutput}`);
-        shell.exec(`docker compose down -v --remove-orphans 2>${nullOutput}`);
+        this.executeExternal(`docker compose kill --remove-orphans`, {silent: true});
+        this.executeExternal(`docker compose down -v --remove-orphans`, {silent: true});
         this.logger.trace('Cleaning the volumes and temp files...', stateName);
         shell.exec(`rm -rf network-logs/* >${nullOutput} 2>&1`);
         SafeDockerNetworkRemover.removeAll();

src/state/StartState.ts

@@ -110,8 +110,8 @@ export class StartState implements IState{
         this.logger.info(START_STATE_STARTED_DETECTING, this.stateName);
 
         try {
-            await this.connectionService.waitForFiringUp(5600);
-            await this.connectionService.waitForFiringUp(50211);
+            await this.connectionService.waitForFiringUp(5600, 'Mirror Node GRPC');
+            await this.connectionService.waitForFiringUp(50211, 'Network Node');
         } catch (e: any) {
             if (e instanceof LocalNodeErrors) {
                 this.logger.error(e.message, this.stateName);

src/utils/debounce.ts

@@ -0,0 +1,37 @@
+/*-
+ *
+ * Hedera Local Node
+ *
+ * Copyright (C) 2023-2024 Hedera Hashgraph, LLC
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *      http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ *
+ */
+
+/**
+ * Limit the execution of a function to once every N ms
+ */
+const debounce = <F extends (...args: any[]) => void>(func: F, delay: number) => {
+    let timerActive = false;
+    return (...args: any) => {
+        if (!timerActive) {
+            timerActive = true;
+            func(...args);
+            setTimeout(() => {
+                timerActive = false;
+            }, delay);
+        }
+    };
+};
+
+export default debounce;