fix: enhance logging for request node

packages/request-node/package.json

@@ -58,6 +58,7 @@
     "graphql-request": "6.1.0",
     "http-shutdown": "1.2.2",
     "http-status-codes": "2.1.4",
+    "morgan": "1.10.0",
     "shelljs": "0.8.5",
     "tslib": "2.5.0",
     "yargs": "17.6.2"
@@ -66,6 +67,7 @@
     "@types/cors": "2.8.9",
     "@types/express": "4.17.17",
     "@types/jest": "29.5.6",
+    "@types/morgan": "1.9.9",
     "@types/node": "18.11.9",
     "@types/supertest": "2.0.10",
     "@types/yargs": "17.0.14",

packages/request-node/src/request/ipfsAdd.ts

@@ -24,10 +24,6 @@ export default class IpfsAddHandler {
     // Retrieves data access layer
     let dataAccessResponse;
 
-    // Set the timeout from the value from config and convert seconds to milliseconds
-    /* eslint-disable no-magic-numbers */
-    clientRequest.setTimeout(getPersistTransactionTimeout() * 1000);
-
     // Verifies if data send from post are correct
     // clientRequest.body is expected to contain data for data-acces layer:
     // transactionData: data of the transaction
@@ -43,17 +39,36 @@ export default class IpfsAddHandler {
         return;
       }
 
+      // Set the timeout from the value from config and convert seconds to milliseconds
+      /* eslint-disable no-magic-numbers */
+      clientRequest.setTimeout(getPersistTransactionTimeout() * 1000, () => {
+        this.logger.error(`ipfsAdd timeout. clientRequest.body.data: ${clientRequest.body.data}`, [
+          'timeout',
+        ]);
+        serverResponse.status(StatusCodes.GATEWAY_TIMEOUT).send('ipfsAdd timeout');
+      });
+
       try {
         dataAccessResponse = await this.ipfsStorage.ipfsAdd(
           JSON.stringify(clientRequest.body.data),
         );
 
-        this.logger.debug(`ipfsAdd successfully completed`, ['metric', 'successRate']);
+        this.logger.debug(
+          `ipfsAdd successfully completed ${JSON.stringify({
+            ipfsHash: dataAccessResponse.ipfsHash,
+            ipfsSize: dataAccessResponse.ipfsSize,
+          })}`,
+          ['metric', 'successRate'],
+        );
 
         serverResponse.status(StatusCodes.OK).send(dataAccessResponse);
       } catch (e) {
-        this.logger.error(`ipfsAdd error: ${e}`);
-        this.logger.debug(`ipfsAdd fail`, ['metric', 'successRate']);
+        this.logger.error(
+          `ipfsAdd fail  ${JSON.stringify({
+            error: e,
+            data: clientRequest.body.data,
+          })}`,
+        );
 
         serverResponse.status(StatusCodes.INTERNAL_SERVER_ERROR).send(e);
       }

packages/request-node/src/request/persistTransaction.ts

@@ -30,10 +30,6 @@ export default class PersistTransactionHandler {
     // Retrieves data access layer
     let dataAccessResponse: DataAccessTypes.IReturnPersistTransaction;
 
-    // Set the timeout from the value from config and convert seconds to milliseconds
-    /* eslint-disable no-magic-numbers */
-    clientRequest.setTimeout(getPersistTransactionTimeout() * 1000);
-
     // Verifies if data send from post are correct
     // clientRequest.body is expected to contain data for data-acces layer:
     // transactionData: data of the transaction
@@ -46,11 +42,25 @@ export default class PersistTransactionHandler {
       serverResponse.status(StatusCodes.UNPROCESSABLE_ENTITY).send('Incorrect data');
       return;
     }
-    try {
-      const transactionHash: MultiFormatTypes.HashTypes.IHash = normalizeKeccak256Hash(
-        clientRequest.body.transactionData,
+
+    const transactionHash: MultiFormatTypes.HashTypes.IHash = normalizeKeccak256Hash(
+      clientRequest.body.transactionData,
+    );
+
+    // Set the timeout from the value from config and convert seconds to milliseconds
+    /* eslint-disable no-magic-numbers */
+    clientRequest.setTimeout(getPersistTransactionTimeout() * 1000, () => {
+      this.logger.error(
+        `persistTransaction timeout ${JSON.stringify({
+          transactionHash,
+          channelId: clientRequest.body.channelId,
+        })}`,
+        ['timeout'],
       );
+      serverResponse.status(StatusCodes.GATEWAY_TIMEOUT).send('persistTransaction timeout');
+    });
 
+    try {
       this.logger.debug(
         `Persisting Transaction: ${JSON.stringify({
           transactionHash,
@@ -67,10 +77,13 @@ export default class PersistTransactionHandler {
       );
 
       dataAccessResponse.on('confirmed', async () => {
-        this.logger.info(`Transaction confirmed: ${transactionHash.value}`, [
-          'metric',
-          'successRate',
-        ]);
+        this.logger.info(
+          `Transaction confirmed: ${JSON.stringify({
+            transactionHash,
+            channelId: clientRequest.body.channelId,
+          })}`,
+          ['metric', 'successRate'],
+        );
       });
 
       // when the transaction fails, log an error
@@ -83,12 +96,25 @@ export default class PersistTransactionHandler {
           )}`);
       });
 
-      this.logger.debug(`persistTransaction successfully completed`, ['metric', 'successRate']);
+      this.logger.debug(
+        `persistTransaction successfully completed ${JSON.stringify({
+          transactionHash,
+          channelId: clientRequest.body.channelId,
+        })}`,
+        ['metric', 'successRate'],
+      );
 
       serverResponse.status(StatusCodes.OK).send(dataAccessResponse);
     } catch (e) {
-      this.logger.error(`persistTransaction error: ${e}`);
-      this.logger.debug(`persistTransaction fail`, ['metric', 'successRate']);
+      this.logger.error(
+        `persistTransaction fail ${JSON.stringify({
+          error: e,
+          transactionHash,
+          channelId: clientRequest.body.channelId,
+          topics: clientRequest.body.topics,
+          transactionData: clientRequest.body.transactionData,
+        })}`,
+      );
 
       serverResponse.status(StatusCodes.INTERNAL_SERVER_ERROR).send(e);
     }

packages/request-node/src/requestNode.ts

@@ -11,6 +11,7 @@ import PersistTransactionHandler from './request/persistTransaction';
 import GetChannelsByTopicHandler from './request/getChannelsByTopic';
 import GetStatusHandler from './request/getStatus';
 import IpfsAddHandler from './request/ipfsAdd';
+import morgan from 'morgan';
 
 // eslint-disable-next-line @typescript-eslint/no-var-requires
 const packageJson = require('../package.json');
@@ -133,6 +134,9 @@ export class RequestNode {
     // Enable all CORS requests
     this.express.use(cors());
 
+    // Enable logging of all requests
+    this.express.use(morgan('combined'));
+
     // Set the Request Node version to the header
     this.express.use((_, res, next) => {
       res.header(REQUEST_NODE_VERSION_HEADER, this.requestNodeVersion);

yarn.lock

@@ -5319,6 +5319,13 @@
   resolved "https://registry.npmjs.org/@types/mocha/-/mocha-8.2.3.tgz"
   integrity sha512-ekGvFhFgrc2zYQoX4JeZPmVzZxw6Dtllga7iGHzfbYIYkAMUx/sAFP2GdFpLff+vdHXu5fl7WX9AT+TtqYcsyw==
 
+"@types/[email protected]":
+  version "1.9.9"
+  resolved "https://registry.yarnpkg.com/@types/morgan/-/morgan-1.9.9.tgz#d60dec3979e16c203a000159daa07d3fb7270d7f"
+  integrity sha512-iRYSDKVaC6FkGSpEVVIvrRGw0DfJMiQzIn3qr2G5B3C//AWkulhXgaBd7tS9/J79GWSYMTHGs7PfI5b3Y8m+RQ==
+  dependencies:
+    "@types/node" "*"
+
 "@types/[email protected]":
   version "0.5.0"
   resolved "https://registry.npmjs.org/@types/multicoin-address-validator/-/multicoin-address-validator-0.5.0.tgz"
@@ -16876,9 +16883,9 @@ module-error@^1.0.1, module-error@^1.0.2:
   resolved "https://registry.npmjs.org/module-error/-/module-error-1.0.2.tgz"
   integrity sha512-0yuvsqSCv8LbaOKhnsQ/T5JhyFlCYLPXK3U2sgV10zoKQwzs/MyfuQUOZQ1V/6OCOJsK/TRgNVrPuPDqtdMFtA==
 
-morgan@^1.9.1:
+morgan@1.10.0, morgan@^1.9.1:
   version "1.10.0"
-  resolved "https://registry.npmjs.org/morgan/-/morgan-1.10.0.tgz"
+  resolved "https://registry.yarnpkg.com/morgan/-/morgan-1.10.0.tgz#091778abc1fc47cd3509824653dae1faab6b17d7"
   integrity sha512-AbegBVI4sh6El+1gNwvD5YIck7nSA36weD7xvIxG4in80j/UoK8AEGaWnnz8v1GxonMCltmlNs5ZKbGvl9b1XQ==
   dependencies:
     basic-auth "~2.0.1"