From aa5411cf26fba80bee638bc74714300997ed4231 Mon Sep 17 00:00:00 2001 From: Jeromy Cannon Date: Mon, 3 Jun 2024 13:14:24 +0100 Subject: [PATCH] fix: enhanced Logger to accept a log file location (#2298) * added log to file capability Signed-off-by: Jeromy Cannon * updated test case and the way the grpc error is created Signed-off-by: Jeromy Cannon * include the original grpc error message in the new error Signed-off-by: Jeromy Cannon * bumped timeout because of pipeline failure Signed-off-by: Jeromy Cannon * Update src/grpc/GrpcServiceError.js Co-authored-by: Alexander Gadzhalov Signed-off-by: Jeromy Cannon * updates based on PR review feedback Signed-off-by: Jeromy Cannon * don't error if the tmp dir log file does not exist Signed-off-by: Jeromy Cannon * use cgroups to prevent github runner from losing communication with server Signed-off-by: Jeromy Cannon * fix syntax error Signed-off-by: Jeromy Cannon --------- Signed-off-by: Jeromy Cannon Co-authored-by: Alexander Gadzhalov --- .github/workflows/build.yml | 60 ++++++++++++++++++++++++++----- package.json | 1 + src/Executable.js | 4 +-- src/grpc/GrpcServiceError.js | 16 +++++++-- src/logger/Logger.js | 63 +++++++++++++++++++++++++++------ test/unit/AccountInfoMocking.js | 2 +- test/unit/FileAppendMocking.js | 2 +- test/unit/LoggerTest.js | 58 ++++++++++++++++++++++++++++++ 8 files changed, 181 insertions(+), 25 deletions(-) diff --git a/.github/workflows/build.yml b/.github/workflows/build.yml index 577bf1157..e5df90329 100644 --- 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 index 937ac93f4..738d50fbf 100644 --- 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 index 0171cea13..9d8140d64 100644 --- 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 index 5345043c4..5a80b0197 100644 --- 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 index 704d925d2..dd60158eb 100644 --- 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 index 7af12a535..6366938f3 100644 --- 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 index aab0ccf5d..e0c55883a 100644 --- 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 index 59d968a73..a42238df7 100644 --- 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"); + }); });