WIP feat(billing): implement context aware json logger

refs #247

apps/api/.env.functional.test

@@ -4,4 +4,5 @@ POSTGRES_DB_URI=postgres://postgres:[email protected]:5432/cloudmos-users
 RPC_NODE_ENDPOINT=https://rpc.sandbox-01.aksh.pw:443
 TRIAL_DEPLOYMENT_ALLOWANCE_AMOUNT=100000
 TRIAL_FEES_ALLOWANCE_AMOUNT=100000
-TRIAL_ALLOWANCE_DENOM=uakt
+TRIAL_ALLOWANCE_DENOM=uakt
+LOG_LEVEL=info

apps/api/package.json

@@ -61,6 +61,7 @@
     "node-fetch": "^2.6.1",
     "pg": "^8.12.0",
     "pg-hstore": "^2.3.4",
+    "pino": "^9.2.0",
     "protobufjs": "^6.11.2",
     "semver": "^7.3.8",
     "sequelize": "^6.21.3",

apps/api/src/app.ts

@@ -9,6 +9,9 @@ import * as Sentry from "@sentry/node";
 import { Hono } from "hono";
 import { cors } from "hono/cors";
 
+import { logHttpRequests } from "@src/core/services/log-http-requests/logHttpRequests";
+import { Logger } from "@src/core/services/logger/Logger";
+import { RequestStorage } from "@src/core/services/request-storage/RequestStorage";
 import packageJson from "../package.json";
 import { chainDb, syncUserSchema, userDb } from "./db/dbConnection";
 import { apiRouter } from "./routers/apiRouter";
@@ -58,6 +61,8 @@ const scheduler = new Scheduler({
   }
 });
 
+appHono.use(RequestStorage.middleware());
+appHono.use(logHttpRequests());
 appHono.use(
   "*",
   sentry({
@@ -99,6 +104,8 @@ function startScheduler() {
   scheduler.start();
 }
 
+const appLogger = new Logger({ context: "APP" });
+
 /**
  * Initialize database
  * Start scheduler
@@ -109,15 +116,14 @@ export async function initApp() {
     await initDb();
     startScheduler();
 
-    console.log("Starting server at http://localhost:" + PORT);
+    appLogger.info({ event: "SERVER_STARTING", url: `http://localhost:${PORT}` });
     serve({
       fetch: appHono.fetch,
       port: typeof PORT === "string" ? parseInt(PORT) : PORT
     });
-  } catch (err) {
-    console.error("Error while initializing app", err);
-
-    Sentry.captureException(err);
+  } catch (error) {
+    appLogger.error({ event: "APP_INIT_ERROR", error });
+    Sentry.captureException(error);
   }
 }
 
@@ -127,20 +133,18 @@ export async function initApp() {
  * Create backups per version
  * Load from backup if exists for current version
  */
-export async function initDb(options: { log?: boolean } = { log: true }) {
-  const log = (value: string) => options?.log && console.log(value);
-
-  log(`Connecting to chain database (${chainDb.config.host}/${chainDb.config.database})...`);
+export async function initDb() {
+  appLogger.debug(`Connecting to chain database (${chainDb.config.host}/${chainDb.config.database})...`);
   await chainDb.authenticate();
-  log("Connection has been established successfully.");
+  appLogger.debug("Connection has been established successfully.");
 
-  log(`Connecting to user database (${userDb.config.host}/${userDb.config.database})...`);
+  appLogger.debug(`Connecting to user database (${userDb.config.host}/${userDb.config.database})...`);
   await userDb.authenticate();
-  log("Connection has been established successfully.");
+  appLogger.debug("Connection has been established successfully.");
 
-  log("Sync user schema...");
+  appLogger.debug("Sync user schema...");
   await syncUserSchema();
-  log("User schema synced.");
+  appLogger.debug("User schema synced.");
 }
 
 export { appHono as app };

apps/api/src/billing/providers/configProvider.ts

@@ -2,6 +2,6 @@ import { container } from "tsyringe";
 
 import { config } from "@src/billing/config";
 
-export const CONFIG = "CONFIG";
+export const BILLING_CONFIG = "BILLING_CONFIG";
 
-container.register(CONFIG, { useValue: config });
+container.register(BILLING_CONFIG, { useValue: config });

apps/api/src/billing/services/wallet-manager/WalletManager.ts

@@ -5,8 +5,9 @@ import add from "date-fns/add";
 import { inject, singleton } from "tsyringe";
 
 import type { BillingConfig } from "@src/billing/config";
-import { CONFIG } from "@src/billing/providers/configProvider";
+import { BILLING_CONFIG } from "@src/billing/providers/configProvider";
 import { RpcMessageService } from "@src/billing/services/rpc-message-service/RpcMessageService";
+import { ContextualLogger } from "@src/core/services/contextual-logger/ContextualLogger";
 
 interface SpendingAuthorizationOptions {
   address: string;
@@ -27,8 +28,10 @@ export class WalletManager {
 
   private client: SigningStargateClient;
 
+  private readonly logger = new ContextualLogger({ context: WalletManager.name });
+
   constructor(
-    @inject(CONFIG) private readonly config: BillingConfig,
+    @inject(BILLING_CONFIG) private readonly config: BillingConfig,
     private readonly rpcMessageService: RpcMessageService
   ) {}
 
@@ -53,6 +56,7 @@ export class WalletManager {
       hdPaths: [hdPath]
     });
     const [account] = await wallet.getAccounts();
+    this.logger.debug({ event: "WALLET_CREATED", address: account.address });
 
     return { address: account.address };
   }
@@ -78,21 +82,23 @@ export class WalletManager {
       ];
       const client = await this.getClient();
       const fee = await this.estimateFee(messages, this.config.TRIAL_ALLOWANCE_DENOM);
-      console.log("DEBUG fee", fee);
-      const result = await client.signAndBroadcast(masterWalletAddress, messages, fee);
-      console.log("DEBUG result", JSON.stringify(result, null, 2));
-      console.log("DEBUG result", JSON.stringify(JSON.parse(result.rawLog), null, 2));
+      await client.signAndBroadcast(masterWalletAddress, messages, fee);
+      this.logger.debug({ event: "SPENDING_AUTHORIZED", address: options.address });
     } catch (error) {
-      console.error("DEBUG error", error);
-      throw error;
+      if (error.message.includes("fee allowance already exists")) {
+        this.logger.debug({ event: "SPENDING_ALREADY_AUTHORIZED", address: options.address });
+      } else {
+        error.message = `Failed to authorize spending for address ${options.address}: ${error.message}`;
+        this.logger.error(error);
+        throw error;
+      }
     }
   }
 
   private async estimateFee(messages: readonly EncodeObject[], denom: string) {
     const client = await this.getClient();
     const address = await this.getMasterWalletAddress();
     const gasEstimation = await client.simulate(address, messages, "allowance grant");
-    console.log("DEBUG gasEstimation", gasEstimation);
     const estimatedGas = Math.round(gasEstimation * this.config.GAS_SAFETY_MULTIPLIER);
 
     return calculateFee(estimatedGas, GasPrice.fromString(`0.025${denom}`));

apps/api/src/core/config/env.ts

@@ -0,0 +1,11 @@
+import dotenv from "dotenv";
+import { z } from "zod";
+
+dotenv.config({ path: ".env.local" });
+dotenv.config();
+
+const envSchema = z.object({
+  LOG_LEVEL: z.enum(["fatal", "error", "warn", "info", "debug", "trace"]).optional().default("info")
+});
+
+export const env = envSchema.parse(process.env);

apps/api/src/core/config/index.ts

@@ -0,0 +1,6 @@
+import { env } from "./env";
+
+export const config = {
+  ...env
+};
+export type CoreConfig = typeof config;

apps/api/src/core/providers/configProvider.ts

@@ -0,0 +1,7 @@
+import { container } from "tsyringe";
+
+import { config } from "@src/core/config";
+
+export const CORE_CONFIG = "CORE_CONFIG";
+
+container.register(CORE_CONFIG, { useValue: config });

apps/api/src/core/providers/index.ts

@@ -1 +1,2 @@
 export * from "./PostgresProvider";
+export * from "./configProvider";

apps/api/src/core/services/contextual-logger/ContextualLogger.ts

@@ -0,0 +1,11 @@
+import { Logger } from "@src/core/services/logger/Logger";
+import { RequestStorage } from "@src/core/services/request-storage/RequestStorage";
+
+export class ContextualLogger extends Logger {
+  protected get logger() {
+    const context = RequestStorage.getContext();
+    const requestId = context?.get("requestId");
+
+    return requestId ? super.logger.child({ requestId }) : super.logger;
+  }
+}

apps/api/src/core/services/log-http-requests/logHttpRequests.ts

@@ -0,0 +1,19 @@
+import { Context, Next } from "hono";
+
+import { ContextualLogger } from "@src/core/services/contextual-logger/ContextualLogger";
+
+export const logHttpRequests = () => async (c: Context, next: Next) => {
+  const logger = new ContextualLogger({ context: "HTTP" });
+  const timer = performance.now();
+  logger.info({
+    method: c.req.method,
+    url: c.req.url
+  });
+
+  await next();
+
+  logger.info({
+    status: c.res.status,
+    duration: `${(performance.now() - timer).toFixed(3)}ms`
+  });
+};

apps/api/src/core/services/logger/Logger.ts

@@ -0,0 +1,44 @@
+import pino, { Bindings } from "pino";
+
+import { env } from "@src/core/config/env";
+
+export class Logger {
+  private readonly pino: pino.Logger;
+
+  protected get logger() {
+    return this.pino;
+  }
+
+  constructor(bindings?: Bindings) {
+    this.pino = pino({ level: env.LOG_LEVEL });
+
+    if (bindings) {
+      this.pino = this.logger.child(bindings);
+    }
+  }
+
+  info(message: any) {
+    message = this.toLoggableInput(message);
+    return this.logger.info(message);
+  }
+
+  error(message: any) {
+    this.logger.error(this.toLoggableInput(message));
+  }
+
+  warn(message: any) {
+    return this.logger.warn(this.toLoggableInput(message));
+  }
+
+  debug(message: any) {
+    return this.logger.debug(this.toLoggableInput(message));
+  }
+
+  private toLoggableInput(message: any) {
+    if (message instanceof Error) {
+      return message.stack;
+    }
+
+    return message;
+  }
+}

apps/api/src/core/services/postgres/postgres.ts

@@ -1,15 +1,25 @@
-import { DefaultLogger } from "drizzle-orm/logger";
+import { DefaultLogger, LogWriter } from "drizzle-orm/logger";
 import { drizzle } from "drizzle-orm/node-postgres";
 import { migrate } from "drizzle-orm/node-postgres/migrator";
 import { Pool } from "pg";
 
 import * as billingSchemas from "@src/billing/model-schemas";
+import { ContextualLogger } from "@src/core/services/contextual-logger/ContextualLogger";
 import { env } from "@src/utils/env";
 
 const pool = new Pool({
   connectionString: env.UserDatabaseCS
 });
-export const pgDatabase = drizzle(pool, { logger: new DefaultLogger(), schema: billingSchemas });
+
+class ContextualLogWriter implements LogWriter {
+  logger = new ContextualLogger({ context: "POSTGRES" });
+
+  write(message: string) {
+    this.logger.debug({ query: message.replace(/^Query: /, "") });
+  }
+}
+
+export const pgDatabase = drizzle(pool, { logger: new DefaultLogger({ writer: new ContextualLogWriter() }), schema: billingSchemas });
 export const migrateDb = () => migrate(pgDatabase, { migrationsFolder: "./drizzle" });
 
 export type ApiPgSchema = typeof billingSchemas;

apps/api/src/core/services/request-storage/RequestStorage.ts

@@ -0,0 +1,31 @@
+import { Context, Next } from "hono";
+import { AsyncLocalStorage } from "node:async_hooks";
+import { v4 as uuid } from "uuid";
+
+export class RequestStorage {
+  static CONTEXT_KEY = "CONTEXT";
+
+  static storage = new AsyncLocalStorage<Map<string, Context>>();
+
+  static middleware() {
+    return async (c: Context, next: Next) => {
+      const requestId = c.req.header("X-Request-Id") || uuid();
+      c.set("requestId", requestId);
+
+      await this.runWithContext(c, next);
+    };
+  }
+
+  static async runWithContext(context: Context, cb: () => Promise<void>) {
+    return await new Promise((resolve, reject) => {
+      this.storage.run(new Map(), () => {
+        this.storage.getStore().set(this.CONTEXT_KEY, context);
+        cb().then(resolve).catch(reject);
+      });
+    });
+  }
+
+  static getContext() {
+    return this.storage.getStore()?.get(this.CONTEXT_KEY);
+  }
+}

apps/api/test/functional/create-wallet.spec.ts

@@ -15,7 +15,7 @@ describe("app", () => {
   const userWalletsTable = db.query.userWalletSchema;
 
   beforeAll(async () => {
-    await initDb({ log: false });
+    await initDb();
   });
 
   afterAll(async () => {