Improve backend logging (#1354)

gear-tech · Aug 22, 2023 · 19ea961 · 19ea961
1 parent ef4aca6
commit 19ea961
Show file tree

Hide file tree

Showing 35 changed files with 144 additions and 185 deletions.
diff --git a/.gitignore b/.gitignore
@@ -8,4 +8,5 @@ node_modules/
 !.yarn/sdks
 !.yarn/versions
 **/dist/
-.vscode/
+.vscode/
+idea/tmp/
diff --git a/idea/api-gateway/src/common/logger.ts b/idea/api-gateway/src/common/logger.ts
diff --git a/idea/api-gateway/src/config/index.ts → idea/api-gateway/src/config.ts b/idea/api-gateway/src/config/index.ts → idea/api-gateway/src/config.ts
diff --git a/idea/api-gateway/src/main.ts b/idea/api-gateway/src/main.ts
@@ -1,12 +1,13 @@
-import { logger } from './common/logger';
-import { RMQService } from './rabbitmq';
+import { logger } from '@gear-js/common';
+
+import { RMQService } from './rmq';
 import { Server, changeStatus } from './server';
 
 const bootstrap = async () => {
   const rmq = new RMQService();
   await rmq.init();
 
-  logger.info('Connected to RabbitMQ');
+  logger.info('RabbitMQ connection established sucessfuly');
 
   changeStatus();
 

diff --git a/idea/api-gateway/src/rabbitmq/index.ts → idea/api-gateway/src/rmq.ts b/idea/api-gateway/src/rabbitmq/index.ts → idea/api-gateway/src/rmq.ts
@@ -1,9 +1,8 @@
 import { CronJob } from 'cron';
 import { connect, Connection, Channel } from 'amqplib';
-import { RMQExchanges, RMQMessage, RMQQueues, RMQReply, RMQServiceActions, RMQServices } from '@gear-js/common';
+import { logger, RMQExchanges, RMQMessage, RMQQueues, RMQReply, RMQServiceActions, RMQServices } from '@gear-js/common';
 
-import config from '../config';
-import { logger } from '../common/logger';
+import config from './config';
 
 export class RMQService {
   private indexerChannels: Map<string, Channel>;
@@ -22,9 +21,8 @@ export class RMQService {
   public async init(): Promise<void> {
     try {
       this.connection = await connect(config.rabbitmq.url);
-    } catch (err) {
-      logger.error('Failed to connecto to RabbitMQ');
-      console.log(err);
+    } catch (error) {
+      logger.error('Failed to connect to to RabbitMQ', { error });
       process.exit(1);
     }
 
@@ -98,17 +96,15 @@ export class RMQService {
               autoDelete: true,
             });
 
-            logger.info(`Indexer: Add new genesis ${genesis}`);
-            logger.info(`Indexer genesises: ${JSON.stringify(Array.from(this.indexerChannels.keys()), undefined, 2)}`);
+            logger.info(`New indexer genesis: ${genesis}`, { all: Array.from(this.indexerChannels.keys()) });
           }
           if (service === RMQServices.TEST_BALANCE) {
             if (this.tbChannels.has(genesis)) return;
 
             const channel = await this.createChannel();
             this.tbChannels.set(genesis, channel);
             await channel.assertQueue(`${RMQServices.TEST_BALANCE}.${genesis}`, { durable: false, exclusive: false });
-            logger.info(`TB: Add new genesis ${genesis}`);
-            logger.info(`TB genesises: ${JSON.stringify(Array.from(this.tbChannels.keys()), undefined, 2)}`);
+            logger.info(`New test_balance genesis ${genesis}`, { all: Array.from(this.tbChannels.keys()) });
           }
         }
 
@@ -118,19 +114,15 @@ export class RMQService {
             if (channel) {
               await channel.close();
               this.indexerChannels.delete(genesis);
-              logger.info(`Indexer: Delete genesis ${genesis}`);
-              logger.info(
-                `Indexer genesises: ${JSON.stringify(Array.from(this.indexerChannels.keys()), undefined, 2)}`,
-              );
+              logger.info(`Remove indexer genesis ${genesis}`, { all: Array.from(this.indexerChannels.keys()) });
             }
           }
           if (service === RMQServices.TEST_BALANCE) {
             const channel = this.tbChannels.get(genesis);
             if (channel) {
               await channel.close();
               this.tbChannels.delete(genesis);
-              logger.info(`TB: Delete new genesis ${genesis}`);
-              logger.info(`TB genesises: ${JSON.stringify(Array.from(this.tbChannels.keys()), undefined, 2)}`);
+              logger.info(`Remove test_balance genesis ${genesis}`, { all: Array.from(this.tbChannels.keys()) });
             }
           }
         }

diff --git a/idea/api-gateway/src/server.ts b/idea/api-gateway/src/server.ts
@@ -1,10 +1,3 @@
-import { getResponse } from './utils';
-
-import express, { Express, Request, Response } from 'express';
-import { checkGenesisMiddleware, captchaMiddleware, validateJsonRpcRequestMiddleware } from './middleware';
-import { logger } from './common/logger';
-import config from './config';
-import { RMQService } from './rabbitmq';
 import {
   INDEXER_METHODS,
   META_STORAGE_METHODS,
@@ -15,8 +8,15 @@ import {
   IRpcResponse,
   JSONRPC_ERRORS,
   API_GATEWAY_METHODS,
+  logger,
 } from '@gear-js/common';
 import { nanoid } from 'nanoid';
+import express, { Express, Request, Response } from 'express';
+
+import { getResponse } from './utils';
+import { checkGenesisMiddleware, captchaMiddleware, validateJsonRpcRequestMiddleware } from './middleware';
+import config from './config';
+import { RMQService } from './rmq';
 
 const status = {
   rmq: false,
@@ -60,10 +60,8 @@ export class Server {
         try {
           const result = await this.handleRequest(req.body);
           res.json(result);
-        } catch (err) {
-          logger.error(`ApiGatewayRouter: ${err}`);
-          console.log(req.body);
-          console.log(err);
+        } catch (error) {
+          logger.error('Handle request error', { error, request: req.body });
         }
       },
     );
@@ -78,9 +76,7 @@ export class Server {
   }
 
   public run() {
-    return this.app.listen(config.server.port, () =>
-      console.log(`⚙️ 🚀 App successfully run on the ${config.server.port}`),
-    );
+    return this.app.listen(config.server.port, () => logger.info(`App successfully run on the ${config.server.port}`));
   }
 
   private async handleRequest(rpcBodyRequest: IRpcRequest | IRpcRequest[]): Promise<IRpcResponse | IRpcResponse[]> {

diff --git a/idea/common/src/decorators/form-response.ts b/idea/common/src/decorators/form-response.ts
@@ -1,11 +1,20 @@
+import { JSONRPC_ERRORS } from '../jsonrpc-errors';
+import { logger } from '../logger';
+
 export function FormResponse(target: unknown, propertyKey: string, descriptor: TypedPropertyDescriptor<any>) {
   const originalMethod = descriptor.value;
   descriptor.value = async function SafeWrapper() {
     try {
       return { result: await originalMethod.apply(this, arguments) };
-    } catch (ex) {
-      console.error(ex);
-      return { error: ex.name };
+    } catch (error) {
+      if (error.name) {
+        const { name, ...err } = error;
+        logger.error(name, { error: err, stack: error.stack });
+        return { error: name };
+      } else {
+        logger.error('Unknown error', { error, stack: error.stack });
+        return { error: JSONRPC_ERRORS.InternalError.name };
+      }
     }
   };
   return descriptor;

diff --git a/idea/common/src/logger.ts b/idea/common/src/logger.ts
@@ -0,0 +1,15 @@
+import { createLogger, format, transports } from 'winston';
+
+const TIMESTAMP_FORMAT = 'YY-MM-DD HH:mm:ss';
+
+export const logger = createLogger({
+  format: format.combine(
+    format.timestamp({ format: TIMESTAMP_FORMAT }),
+    format.printf(({ level, message, timestamp, ...meta }) => {
+      const msg = { message, ...meta };
+
+      return `${timestamp} [${level}] ${JSON.stringify(msg)}`;
+    }),
+  ),
+  transports: [new transports.Console()],
+});
diff --git a/idea/common/src/logger/index.ts b/idea/common/src/logger/index.ts
diff --git a/idea/indexer/src/common/index.ts b/idea/indexer/src/common/index.ts
@@ -3,4 +3,3 @@ export * from './enums';
 export * from './types';
 export * from './errors';
 export * from './helpers';
-export * from './logger';
diff --git a/idea/indexer/src/common/logger.ts b/idea/indexer/src/common/logger.ts
diff --git a/idea/indexer/src/gear/connect.ts b/idea/indexer/src/gear/connect.ts
@@ -1,9 +1,8 @@
 import { GearApi } from '@gear-js/api';
-import { RMQServiceActions } from '@gear-js/common';
+import { RMQServiceActions, logger } from '@gear-js/common';
 
 import config from '../config';
 import { changeStatus } from '../healthcheck.server';
-import { logger } from '../common';
 import { GearIndexer } from './indexer';
 
 const addresses = config.gear.providerAddresses;
@@ -33,6 +32,7 @@ export async function connectToNode(indexer: GearIndexer, cb: GenesisCb) {
   const genesis = api.genesisHash.toHex();
 
   api.on('disconnected', () => {
+    logger.warn('Disconnected from the node.');
     indexer.stop();
     genesis && cb(RMQServiceActions.DELETE, genesis);
     reconnect(api, indexer, cb);
@@ -41,7 +41,7 @@ export async function connectToNode(indexer: GearIndexer, cb: GenesisCb) {
   reconnectionsCounter = 0;
   await indexer.run(api);
   cb(RMQServiceActions.ADD, genesis);
-  logger.info(`⚙️ Connected to ${api.runtimeChain} with genesis ${genesis}`);
+  logger.info(`Connected to ${api.runtimeChain} with genesis ${genesis}`);
   changeStatus('gear');
 }
 
@@ -54,8 +54,8 @@ async function reconnect(api: GearApi, indexer: GearIndexer, cb: GenesisCb) {
 
   try {
     await api.disconnect();
-  } catch (err) {
-    console.log(err);
+  } catch (error) {
+    logger.error('Disconnected from the node1', { error });
   }
   reconnectionsCounter++;
 
@@ -64,7 +64,7 @@ async function reconnect(api: GearApi, indexer: GearIndexer, cb: GenesisCb) {
     reconnectionsCounter = 0;
   }
 
-  logger.info('⚙️ 📡 Reconnecting to the gear node...');
+  logger.info('Attempting to reconnect');
 
   return connectToNode(indexer, cb);
 }
diff --git a/idea/indexer/src/gear/indexer.ts b/idea/indexer/src/gear/indexer.ts
@@ -12,7 +12,7 @@ import { filterEvents } from '@polkadot/api/util';
 import { GenericEventData } from '@polkadot/types';
 import { ExtrinsicStatus } from '@polkadot/types/interfaces';
 import { SignedBlockExtended } from '@polkadot/api-derive/types';
-import { EventNames, CodeStatus } from '@gear-js/common';
+import { EventNames, CodeStatus, logger } from '@gear-js/common';
 import { VoidFn } from '@polkadot/api/types';
 import { Option } from '@polkadot/types';
 
@@ -23,7 +23,6 @@ import {
   eventDataHandlers,
   MessageEntryPoint,
   MessageType,
-  logger,
   UserMessageSentInput,
   UserMessageReadInput,
   ProgramChangedInput,
@@ -113,7 +112,7 @@ export class GearIndexer {
         }
       }
       if (this.api === null) {
-        console.log('api null');
+        logger.warn('api null');
         continue;
       }
 
@@ -129,9 +128,8 @@ export class GearIndexer {
 
     try {
       block = await this.api.derive.chain.getBlockByNumber(blockNumber);
-    } catch (err) {
-      logger.error(`Unable to get block ${blockNumber} due to the following error`);
-      console.log(err);
+    } catch (error) {
+      logger.error(`Unable to get block ${blockNumber}`, { error });
       return;
     }
 
@@ -152,8 +150,8 @@ export class GearIndexer {
 
     try {
       await this.tempState.save();
-    } catch (err) {
-      logger.error(`Error during saving the data of the block ${blockNumber}. ${err.message}`);
+    } catch (error) {
+      logger.error(`Error during saving the data of the block ${blockNumber}`, { error });
     }
     if (this.oneTimeSync) {
       await this.statusService.update(this.genesis, blockNumber.toString(), hash);
@@ -185,36 +183,34 @@ export class GearIndexer {
 
   private async handleEvents(block: SignedBlockExtended, timestamp: number): Promise<void> {
     const necessaryEvents = block.events.filter(({ event: { method } }) => Object.keys(EventNames).includes(method));
+    const blockHash = block.block.header.hash.toHex();
     for (const {
       event: { data, method },
     } of necessaryEvents) {
       let eventData = null;
       try {
         eventData = eventDataHandlers[method](data as GenericEventData);
-      } catch (err) {
-        logger.warn(`Unable to form event data, ${JSON.stringify({ method, data: data.toHuman() })}`);
-        console.log(err);
+      } catch (error) {
+        logger.warn('Unable to form event data.', {
+          error,
+          method,
+          data: data.toJSON(),
+          blockHash,
+        });
         continue;
       }
 
       if (eventData === null) continue;
 
-      const blockHash = block.block.header.hash.toHex();
       try {
         await this.eventHandlers[method](eventData, timestamp, blockHash);
       } catch (error) {
-        logger.warn(
-          JSON.stringify(
-            {
-              method,
-              data: eventData,
-              blockHash,
-            },
-            undefined,
-            2,
-          ),
-        );
-        console.error(error);
+        logger.warn('Unable to handle an event.', {
+          error,
+          method,
+          data: eventData,
+          blockHash,
+        });
       }
     }
   }

diff --git a/idea/indexer/src/healthcheck.server.ts b/idea/indexer/src/healthcheck.server.ts
@@ -1,7 +1,7 @@
 import http from 'http';
+import { logger } from '@gear-js/common';
 
 import config from './config';
-import { logger } from './common';
 
 export const statuses = {
   rmq: false,

diff --git a/idea/indexer/src/main.ts b/idea/indexer/src/main.ts
@@ -1,5 +1,5 @@
 import { waitReady } from '@polkadot/wasm-crypto';
-import { RMQServiceActions } from '@gear-js/common';
+import { RMQServiceActions, logger } from '@gear-js/common';
 
 import { changeStatus, runHealthcheckServer } from './healthcheck.server';
 import { AppDataSource } from './database';
@@ -17,6 +17,8 @@ async function bootstrap() {
 
   const dataSource = await AppDataSource.initialize();
 
+  logger.info('DB connection established');
+
   changeStatus('database');
 
   await waitReady();