fix: enhanced Logger to accept a log file location (#2298)

* added log to file capability Signed-off-by: Jeromy Cannon <[email protected]> * updated test case and the way the grpc error is created Signed-off-by: Jeromy Cannon <[email protected]> * include the original grpc error message in the new error Signed-off-by: Jeromy Cannon <[email protected]> * bumped timeout because of pipeline failure Signed-off-by: Jeromy Cannon <[email protected]> * Update src/grpc/GrpcServiceError.js Co-authored-by: Alexander Gadzhalov <[email protected]> Signed-off-by: Jeromy Cannon <[email protected]> * updates based on PR review feedback Signed-off-by: Jeromy Cannon <[email protected]> * don't error if the tmp dir log file does not exist Signed-off-by: Jeromy Cannon <[email protected]> * use cgroups to prevent github runner from losing communication with server Signed-off-by: Jeromy Cannon <[email protected]> * fix syntax error Signed-off-by: Jeromy Cannon <[email protected]> --------- Signed-off-by: Jeromy Cannon <[email protected]> Co-authored-by: Alexander Gadzhalov <[email protected]>
hashgraph · Jun 3, 2024 · aa5411c · aa5411c
1 parent b3a1814
commit aa5411c
Show file tree

Hide file tree

Showing 8 changed files with 181 additions and 25 deletions.
diff --git a/.github/workflows/build.yml b/.github/workflows/build.yml
@@ -19,6 +19,9 @@ defaults:
 permissions:
   contents: read
 
+env:
+  CG_EXEC: export R_UID=$(id -u); CGROUP_LOGLEVEL=DEBUG cgexec -g cpu,memory:user.slice/user-${R_UID}.slice/user@${R_UID}.service/e2e-${{ github.run_id }} --sticky ionice -c 2 -n 2 nice -n 19
+
 jobs:
   build:
     name: Build using Node ${{ matrix.node }}
@@ -65,6 +68,47 @@ jobs:
         node: [ "16" ]
 
     steps:
+      - name: Setup Control Groups
+        run: |
+            echo "::group::Get System Configuration"
+              USR_ID="$(id -un)"
+              GRP_ID="$(id -gn)"
+              E2E_MEM_LIMIT="30064771072"
+              AGENT_MEM_LIMIT="2147483648"
+              USER_SLICE="user.slice/user-$(id -u).slice"
+              USER_SERVICE="${USER_SLICE}/user@$(id -u).service"
+              E2E_GROUP_NAME="${USER_SERVICE}/e2e-${{ github.run_id }}"
+              AGENT_GROUP_NAME="${USER_SERVICE}/agent-${{ github.run_id }}"
+            echo "::endgroup::"
+
+            echo "::group::Install Control Group Tools"
+              if ! command -v cgcreate >/dev/null 2>&1; then
+                sudo apt-get update
+                sudo apt-get install -y cgroup-tools
+              fi
+            echo "::endgroup::"
+
+            echo "::group::Create Control Groups"
+              sudo cgcreate -g cpu,memory:${USER_SLICE} -a ${USR_ID}:${GRP_ID} -t ${USR_ID}:${GRP_ID}
+              sudo cgcreate -g cpu,memory:${USER_SERVICE} -a ${USR_ID}:${GRP_ID} -t ${USR_ID}:${GRP_ID}
+              sudo cgcreate -g cpu,memory:${E2E_GROUP_NAME} -a ${USR_ID}:${GRP_ID} -t ${USR_ID}:${GRP_ID}
+              sudo cgcreate -g cpu,memory:${AGENT_GROUP_NAME} -a ${USR_ID}:${GRP_ID} -t ${USR_ID}:${GRP_ID}
+            echo "::endgroup::"
+
+            echo "::group::Set Control Group Limits"
+              cgset -r cpu.weight=768 ${E2E_GROUP_NAME}
+              cgset -r cpu.weight=500 ${AGENT_GROUP_NAME}
+              cgset -r memory.max=${E2E_MEM_LIMIT} ${E2E_GROUP_NAME}
+              cgset -r memory.max=${AGENT_MEM_LIMIT} ${AGENT_GROUP_NAME}
+              cgset -r memory.swap.max=${E2E_MEM_LIMIT} ${E2E_GROUP_NAME}
+              cgset -r memory.swap.max=${AGENT_MEM_LIMIT} ${AGENT_GROUP_NAME}
+            echo "::endgroup::"
+
+            echo "::group::Move Runner Processes to Control Groups"
+              sudo cgclassify --sticky -g cpu,memory:${AGENT_GROUP_NAME} $(pgrep 'Runner.Listener' | tr '\n' ' ')
+              sudo cgclassify -g cpu,memory:${AGENT_GROUP_NAME} $(pgrep 'Runner.Worker' | tr '\n' ' ')
+            echo "::endgroup::"
+
       -  name: Harden Runner
          uses: step-security/harden-runner@f086349bfa2bd1361f7909c78558e816508cdc10 # v2.8.0
          with:
@@ -112,38 +156,38 @@ jobs:
         id: start-local-node
         if: ${{ steps.build-sdk.conclusion == 'success' && !cancelled() && always() }}
         run: |
-          npx @hashgraph/hedera-local start -d --network-tag=0.49.7 --balance=100000
+          ${{ env.CG_EXEC }} npx @hashgraph/hedera-local start -d --network-tag=0.49.7 --balance=100000
           # Wait for the network to fully start
           sleep 30
 
       - name: Run Hedera SDK Integration Tests Codecov
         if: ${{ steps.build-sdk.conclusion == 'success' && steps.start-local-node.conclusion == 'success' && !cancelled() && always() }}
-        run: task test:integration:codecov
+        run: ${{ env.CG_EXEC }} task test:integration:codecov
 
       - name: Stop the local node
         id: stop-local-node
         if: ${{ steps.start-local-node.conclusion == 'success' && !cancelled() && always() }}
-        run: npx @hashgraph/hedera-local stop
+        run: ${{ env.CG_EXEC }} npx @hashgraph/hedera-local stop
 
       - name: Build @hashgraph/cryptography
         working-directory: packages/cryptography
         if: ${{ steps.build-sdk.conclusion == 'success' && steps.stop-local-node.conclusion == 'success' && !cancelled() && always() }}
-        run: task build
+        run: ${{ env.CG_EXEC }} task build
 
       - name: Unit Test @hashgraph/cryptography
         working-directory: packages/cryptography
         if: ${{ steps.build-sdk.conclusion == 'success' && steps.stop-local-node.conclusion == 'success' && !cancelled() && always() }}
-        run: task test:unit
+        run: ${{ env.CG_EXEC }} task test:unit
 
       - name: Codecov @hashgraph/cryptography
         working-directory: packages/cryptography
         if: ${{ steps.build-sdk.conclusion == 'success' && steps.stop-local-node.conclusion == 'success' && !cancelled() && always() }}
-        run: task test:unit:codecov
+        run: ${{ env.CG_EXEC }} task test:unit:codecov
 
       - name: Unit Test @hashgraph/sdk
         if: ${{ steps.build-sdk.conclusion == 'success' && steps.stop-local-node.conclusion == 'success' && steps.playwright-deps.conclusion == 'success' && !cancelled() && always() }}
-        run: task test:unit
+        run: ${{ env.CG_EXEC }} task test:unit
 
       - name: Codecov @hashgraph/sdk
         if: ${{ steps.build-sdk.conclusion == 'success' && steps.stop-local-node.conclusion == 'success' && !cancelled() && always() }}
-        run: task test:unit:codecov
+        run: ${{ env.CG_EXEC }} task test:unit:codecov
diff --git a/package.json b/package.json
@@ -116,6 +116,7 @@
         "npx": "^10.2.2",
         "nyc": "^15.1.0",
         "prettier": "^3.0.3",
+        "sinon": "^18.0.0",
         "typedoc": "^0.25.1",
         "typescript": "^5.1.6",
         "vite": "^4.4.9",

diff --git a/src/Executable.js b/src/Executable.js
@@ -725,7 +725,7 @@ export default class Executable {
                     throw this._mapStatusError(request, response);
                 default:
                     throw new Error(
-                        "(BUG) non-exhuastive switch statement for `ExecutionState`",
+                        "(BUG) non-exhaustive switch statement for `ExecutionState`",
                     );
             }
         }
@@ -742,7 +742,7 @@ export default class Executable {
     /**
      * The current purpose of this method is to easily support signature providers since
      * signature providers need to serialize _any_ request into bytes. `Query` and `Transaction`
-     * already implement `toBytes()` so it only made sense to make it avaiable here too.
+     * already implement `toBytes()` so it only made sense to make it available here too.
      *
      * @abstract
      * @returns {Uint8Array}

diff --git a/src/grpc/GrpcServiceError.js b/src/grpc/GrpcServiceError.js
@@ -33,7 +33,9 @@ export default class GrpcServiceError extends Error {
      * @param {GrpcStatus} status
      */
     constructor(status) {
-        super(`gRPC service failed with status: ${status.toString()}`);
+        super(
+            `gRPC service failed with: Status: ${status.toString()}, Code: ${status.valueOf()}`,
+        );
 
         /**
          * @readonly
@@ -55,10 +57,20 @@ export default class GrpcServiceError extends Error {
         if (obj.code != null && obj.details != null) {
             const status = GrpcStatus._fromValue(obj.code);
             const err = new GrpcServiceError(status);
-            err.message = obj.details;
+            err.stack += `\nCaused by: ${
+                obj.stack ? obj.stack.toString() : ""
+            }`;
+            err.message += `: ${obj.details}`;
             return err;
         } else {
             return /** @type {Error} */ (obj);
         }
     }
+
+    /**
+     * @returns {string}
+     */
+    toString() {
+        return `${this.name}: ${this.message}`;
+    }
 }
diff --git a/src/logger/Logger.js b/src/logger/Logger.js
@@ -23,22 +23,63 @@ import LogLevel from "./LogLevel.js";
 export default class Logger {
     /**
      * @param {LogLevel} level
+     * @param {string} logFile the file to log to, if empty, logs to console
+     * @param {boolean} sync perform writes synchronously (similar to console.log)
+     * @param {boolean} fsync perform a fsyncSync every time a write is completed
+     * @param {boolean} mkdir ensure directory for dest file exists when true (default false)
+     * @param {number} minLength the minimum length of the internal buffer that is required to be full before flushing
      */
-    constructor(level) {
+    constructor(
+        level,
+        logFile = "",
+        sync = true,
+        fsync = true,
+        mkdir = true,
+        minLength = 0,
+    ) {
+        const fileTransport = logFile
+            ? pino.destination({
+                  dest: logFile,
+                  sync,
+                  fsync,
+                  mkdir,
+                  minLength,
+              })
+            : null;
+
+        const loggerOptions = fileTransport
+            ? {
+                  level: level.toString(),
+                  timestamp: pino.stdTimeFunctions.isoTime,
+                  formatters: {
+                      bindings: () => {
+                          return {};
+                      },
+                      // @ts-ignore
+                      level: (label) => {
+                          // eslint-disable-next-line @typescript-eslint/no-unsafe-assignment,@typescript-eslint/no-unsafe-call,@typescript-eslint/no-unsafe-member-access
+                          return { level: label.toUpperCase() };
+                      },
+                  },
+              }
+            : {
+                  level: level.toString(),
+                  transport: {
+                      target: "pino-pretty",
+                      options: {
+                          translateTime: "SYS:dd-mm-yyyy HH:MM:ss",
+                          ignore: "pid,hostname",
+                      },
+                  },
+              };
+
         /**
          * @private
          * @type {import("pino").Logger}
          */
-        this._logger = pino({
-            level: level.toString(),
-            transport: {
-                target: "pino-pretty",
-                options: {
-                    translateTime: "SYS:dd-mm-yyyy HH:MM:ss",
-                    ignore: "pid,hostname",
-                },
-            },
-        });
+        this._logger = fileTransport
+            ? pino(loggerOptions, fileTransport)
+            : pino(loggerOptions);
 
         /**
          * @private

diff --git a/test/unit/AccountInfoMocking.js b/test/unit/AccountInfoMocking.js
@@ -154,7 +154,7 @@ describe("AccountInfoMocking", function () {
         await query.execute(client, 1);
 
         expect(query._queryPayment.toTinybars().toInt()).to.be.equal(10);
-    });
+    }, 15000);
 
     it("setQueryPayemnt() + setMaxQueryPayment() avoids querying actual cost", async function () {
         this.timeout(10000);

diff --git a/test/unit/FileAppendMocking.js b/test/unit/FileAppendMocking.js
@@ -168,7 +168,7 @@ describe("FileAppendMocking", function () {
         } catch (error) {
             if (
                 error.message !==
-                "max attempts of 1 was reached for request with last error being: GrpcServiceError: node is UNAVAILABLE"
+                "max attempts of 1 was reached for request with last error being: GrpcServiceError: gRPC service failed with: Status: UNAVAILABLE, Code: 14: node is UNAVAILABLE"
             ) {
                 throw error;
             }

diff --git a/test/unit/LoggerTest.js b/test/unit/LoggerTest.js
@@ -1,5 +1,8 @@
 import { Logger, LogLevel, Transaction } from "../../src/exports.js";
 import { Client } from "../../src/index.js";
+import { tmpdir } from "node:os";
+import fs from "fs";
+import { spy } from "sinon";
 
 describe("Logger", function () {
     this.timeout(50000);
@@ -68,4 +71,59 @@ describe("Logger", function () {
         expect(levels).to.include("error");
         expect(levels).to.include("fatal");
     });
+
+    it("check that it can write to a log file", function () {
+        const logFile = `${tmpdir()}/test.log`;
+        fs.rmSync(logFile, { force: true });
+        const logger = new Logger(LogLevel.Trace, logFile);
+        let assertionCount = 0;
+        for (const level of Object.values(LogLevel)) {
+            if (level === LogLevel.Silent) continue;
+            logger[level](`This is a test ${level} message`);
+
+            const logContent = fs.readFileSync(logFile, "utf8");
+            expect(logContent).to.contain(`This is a test ${level} message`);
+            expect(logContent).to.contain(
+                level.toString().toUpperCase(),
+                `should contain ${level.toString().toUpperCase()}`,
+            );
+            assertionCount += 2;
+        }
+        expect(assertionCount).to.be.equal(
+            12,
+            "should have made 12 assertions",
+        );
+    });
+
+    it("check that it can write to stdout", function () {
+        let assertionCount = 0;
+        const logger = new Logger(LogLevel.Trace);
+        for (const level of Object.values(LogLevel)) {
+            if (level === LogLevel.Silent) continue;
+            const loggerLogSpy = spy(logger._logger, level);
+            logger[level](`This is a test ${level} message`);
+            expect(loggerLogSpy.calledWith(`This is a test ${level} message`))
+                .to.be.true;
+            assertionCount++;
+        }
+        expect(assertionCount).to.be.equal(6, "should have made 6 assertions");
+    });
+
+    it("check that silent blocks output", function () {
+        const logFile = `${tmpdir()}/test2.log`;
+        fs.rmSync(logFile, { force: true });
+        const logger = new Logger(LogLevel.Trace, logFile);
+        expect(logger.silent).to.be.equal(false);
+        logger.warn("This is a test warn message");
+        logger.setSilent(true);
+        expect(logger.silent).to.be.equal(true);
+        logger.fatal("This is a test fatal message");
+        logger.setSilent(false);
+        logger.error("This is a test error message");
+        const logContent = fs.readFileSync(logFile, "utf8");
+        expect(logger.silent).to.be.equal(false);
+        expect(logContent).to.contain("This is a test warn message");
+        expect(logContent).to.contain("This is a test error message");
+        expect(logContent).to.not.contain("This is a test fatal message");
+    });
 });