Logging improvements (#87)

* logger + tact 1.5.3

* more logging

package.json

@@ -18,6 +18,7 @@
     "ipfs-utils": "^9.0.14",
     "mkdirp": "^1.0.4",
     "multer": "^1.4.5-lts.1",
+    "randomstring": "^1.3.0",
     "tact-1.0.0": "npm:@tact-lang/[email protected]",
     "tact-1.1.0": "npm:@tact-lang/[email protected]",
     "tact-1.1.1": "npm:@tact-lang/[email protected]",
@@ -36,12 +37,14 @@
     "tact-1.5.0": "npm:@tact-lang/[email protected]",
     "tact-1.5.1": "npm:@tact-lang/[email protected]",
     "tact-1.5.2": "npm:@tact-lang/[email protected]",
+    "tact-1.5.3": "npm:@tact-lang/[email protected]",
     "ton": "^13.4.1",
     "ton-core": "^0.49.0",
     "ts-node": "^10.9.1",
     "ts-sinon": "^2.0.2",
     "tweetnacl": "^1.0.3",
-    "typescript": "^4.8.4"
+    "typescript": "^4.8.4",
+    "winston": "^3.17.0"
   },
   "scripts": {
     "__prebuild": "tslint -p tsconfig.json --fix",
@@ -60,6 +63,7 @@
     "@types/mkdirp": "^1.0.2",
     "@types/multer": "^1.4.7",
     "@types/node": "^16.11.45",
+    "@types/randomstring": "^1.3.0",
     "@types/semver": "^7.5.8",
     "husky": "^8.0.0",
     "jest-mock-extended": "^2.0.7",

src/controller.ts

@@ -21,9 +21,12 @@ import {
   verifierRegistryForwardMessage,
 } from "./cell-builders";
 import mkdirp from "mkdirp";
+import { getLogger } from "./logger";
 
 export type Base64URL = string;
 
+const logger = getLogger("controller");
+
 interface ControllerConfig {
   verifierId: string;
   privateKey: string;
@@ -113,7 +116,7 @@ export class Controller {
       true,
     );
 
-    console.log(ipfsLink);
+    logger.info(ipfsLink);
 
     const queryId = random64BitNumber();
 

src/latest-known-contracts.ts

@@ -6,6 +6,7 @@ import { sha256 } from "./utils";
 import { getTonClient } from "./ton-reader-client";
 import { toBigIntBE } from "bigint-buffer";
 import { SourceItem } from "./wrappers/source-item";
+import { getLogger } from "./logger";
 
 dotenv.config({ path: ".env.local" });
 dotenv.config({ path: ".env" });
@@ -18,6 +19,8 @@ const contracts: {
 }[] = [];
 let lastUpdateTime: null | Date = null;
 
+const logger = getLogger("latest-known-contracts");
+
 async function update(verifierIdSha256: Buffer, ipfsProvider: string) {
   // TODO - this means that clients get empty responses quickly instead of waiting
   // for the single-instance fetch. needsfix
@@ -94,7 +97,7 @@ async function update(verifierIdSha256: Buffer, ipfsProvider: string) {
             compiler: ipfsData.data.compiler,
           });
         } catch (e) {
-          console.warn(e);
+          logger.error(e);
           callback(null);
         }
       },
@@ -103,7 +106,7 @@ async function update(verifierIdSha256: Buffer, ipfsProvider: string) {
     // @ts-ignore
     contracts.unshift(...results.filter((o: any) => o));
   } catch (e) {
-    console.warn(e);
+    logger.error(e);
     lastUpdateTime = null;
   }
 }

src/logger.ts

@@ -0,0 +1,179 @@
+import winston, { format, LoggerModified, LoggerOptions } from "winston";
+
+import { AsyncLocalStorage } from "async_hooks";
+import { randomUUID } from "crypto";
+import randomstring from "randomstring";
+
+const asyncLocalStorage = new AsyncLocalStorage<Map<string, unknown>>();
+const globalContext = new Map<string, unknown>();
+
+declare module "winston" {
+  interface LoggerModified {
+    debug: Logger["debug"];
+    info: Logger["info"];
+    warn: Logger["warn"];
+    error: Logger["error"];
+
+    addToContext: (entries: { [key: string]: unknown }) => LoggerModified;
+    addToGlobalContext: (entries: { [key: string]: unknown }) => LoggerModified;
+
+    debugSampled: (rate: number, message: unknown, ...args: unknown[]) => LoggerModified;
+  }
+}
+
+const instanceId = randomstring.generate(6);
+
+const customLevels = {
+  levels: {
+    critical: 0,
+    error: 1,
+    warn: 2,
+    info: 3,
+    debug: 4,
+  },
+};
+
+export function getLogger(
+  module: string,
+  meta: Record<string, unknown> = {},
+  level: string = "debug",
+) {
+  const defaultMeta: LoggerOptions["defaultMeta"] = {
+    module,
+    instanceId,
+  };
+
+  const addMetaAndStack = winston.format.printf((info) => {
+    info.meta = (info[Symbol.for("splat")] as unknown[])?.[0] ?? {};
+    info.meta = { ...(info.meta as any), ...meta };
+
+    if (info.stack) (info.message as any) += info.stack;
+
+    let stringified = JSON.stringify(info.meta);
+    delete info.meta;
+
+    if (stringified === "{}") stringified = "";
+    return `${info.timestamp} ${info.service} ${module} ${info.level.toUpperCase()} ${
+      info.message
+    } ${stringified}`;
+  });
+
+  const _logger = winston.createLogger({
+    levels: customLevels.levels,
+    level,
+    format: winston.format.combine(
+      winston.format.timestamp(),
+      winston.format.errors({ stack: true }),
+      winston.format.prettyPrint(),
+      addMetaAndStack,
+      winston.format((info) => {
+        info.context = { ...(info.context ?? {}), ...Object.fromEntries(globalContext) };
+        const store = asyncLocalStorage.getStore();
+        if (!store) return info;
+        info.context = { ...(info.context as any), ...Object.fromEntries(store.entries()) };
+        return info;
+      })(),
+    ),
+    defaultMeta: defaultMeta,
+    transports: [
+      new winston.transports.Console({
+        format: process.env.NO_JSON_LOGGING
+          ? format.printf((info) => {
+              return `${info[Symbol.for("message")]}`;
+            })
+          : winston.format.json(),
+      }),
+    ],
+  });
+
+  const logWithStackTrace = (errorCode: string, message: unknown, ...args: unknown[]) => {
+    let msg = message;
+
+    args[0] = { errorCode, ...(args[0] ?? {}) };
+
+    if (typeof message === "string") {
+      const err = new Error(message as never);
+      // Remove the line coming from the synthetic error created the line above
+      err.stack = err.stack?.replace(new RegExp(`^\\s+at.*_logger\\.${"error"}.*$\\n`, "m"), "");
+      msg = err;
+    } else if (!(message instanceof Error) && typeof message === "object") {
+      msg = JSON.stringify(message);
+    }
+
+    _logger.log("error", msg as never, ...args);
+
+    return _logger;
+  };
+
+  // Override logger error to always print stack traces
+  _logger.error = (message: unknown, ...args: unknown[]) =>
+    logWithStackTrace("error", message, ...args);
+
+  const logger = _logger as unknown as LoggerModified;
+
+  logger.addToContext = (entries: { [key: string]: unknown }) => {
+    const store = asyncLocalStorage.getStore();
+    if (!store) {
+      logger.error(
+        "addToContext must be called inside of an async function wrapped in withContext",
+        {
+          ...entries,
+        },
+      );
+      return logger;
+    }
+
+    Object.entries(entries).forEach(([key, value]) => store.set(key, value));
+
+    return logger;
+  };
+
+  logger.debugSampled = (rate: number, message: unknown, ...args: unknown[]) => {
+    if (rate <= 0 || rate > 1) {
+      logger.warn("sampleOnce rate must be between 0 and 1, ignoring", { rate });
+      return logger;
+    }
+
+    if (Math.random() < rate) {
+      logger.debug(message as unknown as string, ...args);
+    }
+
+    return logger;
+  };
+
+  logger.addToGlobalContext = (entries: { [key: string]: unknown }) => {
+    Object.entries(entries).forEach(([key, value]) => globalContext.set(key, value));
+    return logger;
+  };
+
+  return logger;
+}
+
+export function withContext<T>(fn: () => T) {
+  let store = asyncLocalStorage.getStore();
+
+  if (store) {
+    throw new Error(
+      "cannot use withContext inside an async function that is already wrapped in withContext",
+    );
+  }
+
+  store = new Map();
+  store.set("traceId", randomUUID());
+
+  return asyncLocalStorage.run(store, fn);
+}
+
+export function hasContext() {
+  return asyncLocalStorage.getStore() !== undefined;
+}
+
+export function getContext() {
+  const store = asyncLocalStorage.getStore();
+
+  if (!store) {
+    throw new Error("getContext must be called inside of an async function wrapped in withContext");
+  }
+
+  return Object.fromEntries(store.entries());
+}

src/server.ts

@@ -22,6 +22,9 @@ import { TonReaderClientImpl } from "./ton-reader-client";
 import { getLatestVerified } from "./latest-known-contracts";
 import { DeployController } from "./deploy-controller";
 import { getSupportedVersions } from "./fetch-compiler-versions";
+import { getLogger } from "./logger";
+
+const logger = getLogger("server");
 
 const app = express();
 app.use(idMiddleware());
@@ -212,7 +215,7 @@ app.get("/hc", (req, res) => {
         });
         res.json(result);
       } catch (e) {
-        console.error(e.toString());
+        logger.error(e);
         res.status(500).send(e.toString());
       }
     },
@@ -227,14 +230,13 @@ app.get("/hc", (req, res) => {
   });
 
   app.use(function (err: any, req: any, res: any, next: any) {
-    console.error(err.message); // Log error message in our server's console
+    logger.error(err); // Log error message in our server's console
     if (!err.statusCode) err.statusCode = 500; // If err has no specified error code, set error code to 'Internal Server Error (500)'
-    console.error(err.stack);
     res.status(err.statusCode).send(err); // All HTTP requests must have a response, so let's send back an error with its status
   });
 
   app.listen(port, () => {
-    console.log(
+    logger.info(
       `Ton Contract Verifier Server running on ${port}. Verifier Id: ${process.env.VERIFIER_ID}`,
     );
   });

src/source-verifier/fift-source-verifier.ts

@@ -8,6 +8,9 @@ import { Cell } from "ton";
 import { FuncCompilerVersion } from "@ton-community/contract-verifier-sdk";
 import { binaryPath } from "../binaries";
 import { specialCharsRegex } from "./func-source-verifier";
+import { getLogger } from "../logger";
+
+const logger = getLogger("fift-source-verifier");
 
 export async function fiftToCodeCell(
   funcVersion: FuncCompilerVersion,
@@ -61,7 +64,7 @@ export class FiftSourceVerifier implements SourceVerifier {
         sources,
       };
     } catch (e) {
-      console.error(e);
+      logger.error(e);
       return {
         hash: null,
         result: "unknown_error",

src/source-verifier/tact-source-verifier.ts

@@ -7,6 +7,9 @@ import { Cell } from "ton";
 import { getSupportedVersions } from "../fetch-compiler-versions";
 import { CompileResult, SourceVerifier, SourceVerifyPayload } from "../types";
 import { timeoutPromise } from "../utils";
+import { getLogger } from "../logger";
+
+const logger = getLogger("tact-source-verifier");
 
 export type FileSystem = {
   readFile: (path: string) => Promise<Buffer>;
@@ -74,7 +77,10 @@ export class TactSourceVerifier implements SourceVerifier {
           pkgParsed.compiler.parameters = pkgParsed.compiler.parameters?.replace(/\\/g, "/");
         }
       } catch (e) {
-        console.warn("Unable to replace windows paths in entrypoint. ", pkgParsed.compiler);
+        logger.error(e);
+        logger.warn("Unable to replace windows paths in entrypoint. ", {
+          info: pkgParsed.compiler,
+        });
       }
       // Fix windows paths (END)
 
@@ -119,22 +125,29 @@ export class TactSourceVerifier implements SourceVerifier {
         });
       }
 
-      const v = await timeoutPromise(vPromise, parseInt(process.env.COMPILE_TIMEOUT ?? "3000"));
+      const verificationResult = await timeoutPromise(
+        vPromise,
+        parseInt(process.env.COMPILE_TIMEOUT ?? "3000"),
+      );
 
-      if (!v.ok) {
-        console.log(output, "shahar", v.error);
-        console.error("Failed to compile tact package", output.join("\n"));
+      if (!verificationResult.ok) {
+        logger.error("Failed to compile tact package", {
+          output: output.join("\n"),
+          verificationResult: verificationResult,
+          compilerSettings,
+        });
         return {
           compilerSettings,
-          error: [v.error, ...output].join("\n"),
+          error: [verificationResult.error, ...output].join("\n"),
           hash: null,
-          result: v.error === "verification-failed" ? "not_similar" : "unknown_error",
+          result:
+            verificationResult.error === "verification-failed" ? "not_similar" : "unknown_error",
           sources: [],
         };
       }
 
       const sources = await Promise.all(
-        Object.entries(v.files)
+        Object.entries(verificationResult.files)
           .filter(([filename]) => filename.match(/\.(abi|tact|pkg)$/) && !filename.match(/\.\./))
           .map(async ([filename, contentB64]) => {
             const writePath = path.join(payload.tmpDir, filename);
@@ -158,7 +171,7 @@ export class TactSourceVerifier implements SourceVerifier {
       */
       sources.push({ filename: pkgFilePath });
 
-      const compiledHash = Cell.fromBoc(Buffer.from(v.package.code, "base64"))[0]
+      const compiledHash = Cell.fromBoc(Buffer.from(verificationResult.package.code, "base64"))[0]
         .hash()
         .toString("base64");