From 6d597ecd1a14663a74de5da2d9cd6b8cd1c0df3f Mon Sep 17 00:00:00 2001 From: hatim boufnichel Date: Tue, 7 May 2024 15:36:54 +0200 Subject: [PATCH] logger fix --- env.example | 3 ++ src/auth.ts | 4 +- src/nostrMiddleware.ts | 6 +-- src/services/helpers/functionQueue.ts | 2 +- src/services/helpers/logger.ts | 57 +++++++++++++++++++---- src/services/lnd/lnd.ts | 2 +- src/services/main/index.ts | 19 ++++---- src/services/main/paymentManager.ts | 2 +- src/services/main/sanityChecker.ts | 2 +- src/services/main/watchdog.ts | 6 +-- src/services/metrics/htlcTracker.ts | 4 +- src/services/nostr/handler.ts | 10 ++-- src/services/storage/eventsLog.ts | 2 +- src/services/storage/transactionsQueue.ts | 2 +- src/services/storage/userStorage.ts | 10 ++-- 15 files changed, 85 insertions(+), 46 deletions(-) diff --git a/env.example b/env.example index 4a709cd8..4c256b2a 100644 --- a/env.example +++ b/env.example @@ -6,6 +6,9 @@ LND_MACAROON_PATH=/root/.lnd/data/chain/bitcoin/mainnet/admin.macaroon #DB DATABASE_FILE=db.sqlite METRICS_DATABASE_FILE=metrics.sqlite +LOGS_DIR=logs + +LOG_LEVEL=DEBUG #LOCAL ADMIN_TOKEN= diff --git a/src/auth.ts b/src/auth.ts index febe1e5f..8c380592 100644 --- a/src/auth.ts +++ b/src/auth.ts @@ -1,11 +1,11 @@ import { ServerOptions } from "../proto/autogenerated/ts/express_server"; import { AdminContext, MetricsContext } from "../proto/autogenerated/ts/types"; import Main from './services/main' -import { getLogger } from './services/helpers/logger.js' +import { ERROR, getLogger } from './services/helpers/logger.js' const serverOptions = (mainHandler: Main): ServerOptions => { const log = getLogger({}) return { - logger: { log, error: err => log("ERROR", err) }, + logger: { log, error: err => log(ERROR, err) }, AdminAuthGuard: adminAuth, MetricsAuthGuard: metricsAuth, AppAuthGuard: async (authHeader) => { return { app_id: mainHandler.applicationManager.DecodeAppToken(stripBearer(authHeader)) } }, diff --git a/src/nostrMiddleware.ts b/src/nostrMiddleware.ts index d4cb4eef..e800adc0 100644 --- a/src/nostrMiddleware.ts +++ b/src/nostrMiddleware.ts @@ -3,7 +3,7 @@ import Nostr from "./services/nostr/index.js" import { NostrSend, NostrSettings } from "./services/nostr/handler.js" import * as Types from '../proto/autogenerated/ts/types.js' import NewNostrTransport, { NostrRequest } from '../proto/autogenerated/ts/nostr_transport.js'; -import { getLogger } from "./services/helpers/logger.js"; +import { ERROR, getLogger } from "./services/helpers/logger.js"; export default (serverMethods: Types.ServerMethods, mainHandler: Main, nostrSettings: NostrSettings): { Stop: () => void, Send: NostrSend } => { const log = getLogger({}) @@ -14,7 +14,7 @@ export default (serverMethods: Types.ServerMethods, mainHandler: Main, nostrSett return { user_id: nostrUser.user.user_id, app_user_id: nostrUser.identifier, app_id: appId || "" } }, metricsCallback: metrics => mainHandler.settings.recordPerformance ? mainHandler.metricsManager.AddMetrics(metrics) : null, - logger: { log: console.log, error: err => log("ERROR", err) } + logger: { log: console.log, error: err => log(ERROR, err) } }) const nostr = new Nostr(nostrSettings, event => { let j: NostrRequest @@ -22,7 +22,7 @@ export default (serverMethods: Types.ServerMethods, mainHandler: Main, nostrSett j = JSON.parse(event.content) log("nostr event", j.rpcName || 'no rpc name') } catch { - log("ERROR", "invalid json event received", event.content) + log(ERROR, "invalid json event received", event.content) return } nostrTransport({ ...j, appId: event.appId }, res => { diff --git a/src/services/helpers/functionQueue.ts b/src/services/helpers/functionQueue.ts index 5d3b5f21..00170e2c 100644 --- a/src/services/helpers/functionQueue.ts +++ b/src/services/helpers/functionQueue.ts @@ -7,7 +7,7 @@ export default class FunctionQueue { running: boolean = false f: () => Promise constructor(name: string, f: () => Promise) { - this.log = getLogger({ appName: name }) + this.log = getLogger({ component: name }) this.f = f } diff --git a/src/services/helpers/logger.ts b/src/services/helpers/logger.ts index a28cc0da..591ff0e5 100644 --- a/src/services/helpers/logger.ts +++ b/src/services/helpers/logger.ts @@ -1,37 +1,74 @@ import fs from 'fs' -type LoggerParams = { appName?: string, userId?: string } -export type PubLogger = (...message: (string | number | object)[]) => void +export const DEBUG = Symbol("DEBUG") +export const ERROR = Symbol("ERROR") +export const WARN = Symbol("WARN") +type LoggerParams = { appName?: string, userId?: string, component?: string } +export type PubLogger = (...message: (string | number | object | symbol)[]) => void type Writer = (message: string) => void +const logsDir = process.env.LOGS_DIR || "logs" +const logLevel = process.env.LOG_LEVEL || "DEBUG" try { - fs.mkdirSync("logs") + fs.mkdirSync(logsDir) } catch { } +if (logLevel !== "DEBUG" && logLevel !== "WARN" && logLevel !== "ERROR") { + throw new Error("Invalid log level " + logLevel + " must be one of (DEBUG, WARN, ERROR)") +} const z = (n: number) => n < 10 ? `0${n}` : `${n}` const openWriter = (fileName: string): Writer => { - const logStream = fs.createWriteStream(`logs/${fileName}`, { flags: 'a' }); + const now = new Date() + const date = `${now.getFullYear()}-${z(now.getMonth() + 1)}-${z(now.getDate())}` + const logStream = fs.createWriteStream(`${logsDir}/${fileName}_${date}.log`, { flags: 'a' }); return (message) => { logStream.write(message + "\n") } } const rootWriter = openWriter("ROOT.log") -if (!fs.existsSync("logs/apps")) { - fs.mkdirSync("logs/apps", { recursive: true }); +if (!fs.existsSync(`${logsDir}/apps`)) { + fs.mkdirSync(`${logsDir}/apps`, { recursive: true }); } -if (!fs.existsSync("logs/users")) { - fs.mkdirSync("logs/users", { recursive: true }); +if (!fs.existsSync(`${logsDir}/users`)) { + fs.mkdirSync(`${logsDir}/users`, { recursive: true }); +} +if (!fs.existsSync(`${logsDir}/components`)) { + fs.mkdirSync(`${logsDir}/components`, { recursive: true }); } export const getLogger = (params: LoggerParams): PubLogger => { const writers: Writer[] = [] if (params.appName) { - writers.push(openWriter(`apps/${params.appName}.log`)) + writers.push(openWriter(`apps/${params.appName}`)) } if (params.userId) { - writers.push(openWriter(`users/${params.userId}.log`)) + writers.push(openWriter(`users/${params.userId}`)) + } + if (params.component) { + writers.push(openWriter(`components/${params.component}`)) } if (writers.length === 0) { writers.push(rootWriter) } return (...message) => { + switch (message[0]) { + case DEBUG: + if (logLevel !== "DEBUG") { + return + } + message[0] = "DEBUG" + break; + case WARN: + if (logLevel === "ERROR") { + return + } + message[0] = "WARN" + break; + case ERROR: + message[0] = "ERROR" + break; + default: + if (logLevel !== "DEBUG") { + return + } + } const now = new Date() const timestamp = `${now.getFullYear()}-${z(now.getMonth() + 1)}-${z(now.getDate())} ${z(now.getHours())}:${z(now.getMinutes())}:${z(now.getSeconds())}` const toLog = [timestamp] diff --git a/src/services/lnd/lnd.ts b/src/services/lnd/lnd.ts index 655653af..f2fdcdd8 100644 --- a/src/services/lnd/lnd.ts +++ b/src/services/lnd/lnd.ts @@ -32,7 +32,7 @@ export default class { invoicePaidCb: InvoicePaidCb newBlockCb: NewBlockCb htlcCb: HtlcCb - log = getLogger({ appName: 'lndManager' }) + log = getLogger({ component: 'lndManager' }) outgoingOpsLocked = false constructor(settings: LndSettings, addressPaidCb: AddressPaidCb, invoicePaidCb: InvoicePaidCb, newBlockCb: NewBlockCb, htlcCb: HtlcCb) { this.settings = settings diff --git a/src/services/main/index.ts b/src/services/main/index.ts index ef33a17c..7b486394 100644 --- a/src/services/main/index.ts +++ b/src/services/main/index.ts @@ -7,7 +7,7 @@ import PaymentManager, { PendingTx } from './paymentManager.js' import { MainSettings } from './settings.js' import LND from "../lnd/lnd.js" import { AddressPaidCb, HtlcCb, InvoicePaidCb, NewBlockCb } from "../lnd/settings.js" -import { getLogger, PubLogger } from "../helpers/logger.js" +import { ERROR, getLogger, PubLogger } from "../helpers/logger.js" import AppUserManager from "./appUserManager.js" import { Application } from '../storage/entity/Application.js' import { UserReceivingInvoice } from '../storage/entity/UserReceivingInvoice.js' @@ -77,7 +77,7 @@ export default class { await this.metricsManager.NewBlockCb(height, balanceEvents) confirmed = await this.paymentManager.CheckNewlyConfirmedTxs(height) } catch (err: any) { - log("failed to check transactions after new block", err.message || err) + log(ERROR, "failed to check transactions after new block", err.message || err) return } await Promise.all(confirmed.map(async c => { @@ -91,7 +91,7 @@ export default class { this.storage.StartTransaction(async tx => { const { user_address: userAddress, paid_amount: amount, service_fee: serviceFee, serial_id: serialId, tx_hash } = c.tx if (!userAddress.linkedApplication) { - log("ERROR", "an address was paid, that has no linked application") + log(ERROR, "an address was paid, that has no linked application") return } const updateResult = await this.storage.paymentStorage.UpdateAddressReceivingTransaction(serialId, { confs: c.confs }, tx) @@ -108,7 +108,6 @@ export default class { const op = { amount, paidAtUnix: Date.now() / 1000, inbound: true, type: Types.UserOperationType.INCOMING_TX, identifier: userAddress.address, operationId, network_fee: 0, service_fee: serviceFee, confirmed: true, tx_hash: c.tx.tx_hash, internal: c.tx.internal } this.sendOperationToNostr(userAddress.linkedApplication!, userAddress.user.user_id, op) }) - } })) } @@ -120,7 +119,7 @@ export default class { if (!userAddress) { return } let log = getLogger({}) if (!userAddress.linkedApplication) { - log("ERROR", "an address was paid, that has no linked application") + log(ERROR, "an address was paid, that has no linked application") return } log = getLogger({ appName: userAddress.linkedApplication.name }) @@ -145,7 +144,7 @@ export default class { const op = { amount, paidAtUnix: Date.now() / 1000, inbound: true, type: Types.UserOperationType.INCOMING_TX, identifier: userAddress.address, operationId, network_fee: 0, service_fee: fee, confirmed: internal, tx_hash: txOutput.hash, internal: false } this.sendOperationToNostr(userAddress.linkedApplication, userAddress.user.user_id, op) } catch { - + log(ERROR, "cannot process address paid transaction, already registered") } }) } @@ -158,7 +157,7 @@ export default class { if (userInvoice.paid_at_unix > 0 && internal) { log("cannot pay internally, invoice already paid"); return } if (userInvoice.paid_at_unix > 0 && !internal && userInvoice.paidByLnd) { log("invoice already paid by lnd"); return } if (!userInvoice.linkedApplication) { - log("ERROR", "an invoice was paid, that has no linked application") + log(ERROR, "an invoice was paid, that has no linked application") return } log = getLogger({ appName: userInvoice.linkedApplication.name }) @@ -181,7 +180,7 @@ export default class { this.createZapReceipt(log, userInvoice) log("paid invoice processed successfully") } catch (err: any) { - log("ERROR", "cannot process paid invoice", err.message || "") + log(ERROR, "cannot process paid invoice", err.message || "") } }) } @@ -193,7 +192,7 @@ export default class { try { await fetch(url + "&ok=true") } catch (err: any) { - log("error sending paid callback for invoice", err.message || "") + log(ERROR, "error sending paid callback for invoice", err.message || "") } } @@ -210,7 +209,7 @@ export default class { async createZapReceipt(log: PubLogger, invoice: UserReceivingInvoice) { const zapInfo = invoice.zap_info if (!zapInfo || !invoice.linkedApplication || !invoice.linkedApplication.nostr_public_key) { - log("no zap info linked to payment") + log(ERROR, "no zap info linked to payment") return } const tags = [["p", zapInfo.pub], ["bolt11", invoice.invoice], ["description", zapInfo.description]] diff --git a/src/services/main/paymentManager.ts b/src/services/main/paymentManager.ts index 7e629fb0..9730add7 100644 --- a/src/services/main/paymentManager.ts +++ b/src/services/main/paymentManager.ts @@ -45,7 +45,7 @@ export default class { lnd: LND addressPaidCb: AddressPaidCb invoicePaidCb: InvoicePaidCb - log = getLogger({ appName: "PaymentManager" }) + log = getLogger({ component: "PaymentManager" }) watchDog: Watchdog constructor(storage: Storage, lnd: LND, settings: MainSettings, addressPaidCb: AddressPaidCb, invoicePaidCb: InvoicePaidCb) { this.storage = storage diff --git a/src/services/main/sanityChecker.ts b/src/services/main/sanityChecker.ts index 73d94d6f..bdad7154 100644 --- a/src/services/main/sanityChecker.ts +++ b/src/services/main/sanityChecker.ts @@ -20,7 +20,7 @@ export default class SanityChecker { incrementSources: Record = {} decrementSources: Record = {} decrementEvents: Record = {} - log = getLogger({ appName: "SanityChecker" }) + log = getLogger({ component: "SanityChecker" }) users: Record = {} constructor(storage: Storage, lnd: LND) { this.storage = storage diff --git a/src/services/main/watchdog.ts b/src/services/main/watchdog.ts index 693504ad..8a64eec1 100644 --- a/src/services/main/watchdog.ts +++ b/src/services/main/watchdog.ts @@ -23,14 +23,14 @@ export class Watchdog { settings: WatchdogSettings; storage: Storage; latestCheckStart = 0 - log = getLogger({ appName: "watchdog" }) + log = getLogger({ component: "watchdog" }) ready = false interval: NodeJS.Timer; constructor(settings: WatchdogSettings, lnd: LND, storage: Storage) { this.lnd = lnd; this.settings = settings; this.storage = storage; - this.queue = new FunctionQueue("watchdog::queue", () => this.StartCheck()) + this.queue = new FunctionQueue("watchdog_queue", () => this.StartCheck()) } Stop() { @@ -73,7 +73,7 @@ export class Watchdog { const walletBalance = await this.lnd.GetWalletBalance() this.log(Number(walletBalance.confirmedBalance), "sats in chain wallet") const channelsBalance = await this.lnd.GetChannelBalance() - getLogger({ appName: "debugLndBalancev3" })({ w: walletBalance, c: channelsBalance, u: usersTotal, f: this.accumulatedHtlcFees }) + getLogger({ component: "debugLndBalancev3" })({ w: walletBalance, c: channelsBalance, u: usersTotal, f: this.accumulatedHtlcFees }) const localChannelsBalance = Number(channelsBalance.localBalance?.sat || 0) const unsettledLocalBalance = Number(channelsBalance.unsettledLocalBalance?.sat || 0) diff --git a/src/services/metrics/htlcTracker.ts b/src/services/metrics/htlcTracker.ts index c95ef0ca..0bd99fe9 100644 --- a/src/services/metrics/htlcTracker.ts +++ b/src/services/metrics/htlcTracker.ts @@ -16,9 +16,9 @@ export default class HtlcTracker { constructor(storage: Storage) { this.storage = storage } - log = getLogger({ appName: 'htlcTracker' }) + log = getLogger({ component: 'htlcTracker' }) onHtlcEvent = async (htlc: HtlcEvent) => { - getLogger({ appName: 'debugHtlcs' })(htlc) + getLogger({ component: 'debugHtlcs' })(htlc) const htlcEvent = htlc.event if (htlcEvent.oneofKind === 'subscribedEvent') { this.log("htlc subscribed") diff --git a/src/services/nostr/handler.ts b/src/services/nostr/handler.ts index e7e65e51..9e213400 100644 --- a/src/services/nostr/handler.ts +++ b/src/services/nostr/handler.ts @@ -1,7 +1,7 @@ //import { SimplePool, Sub, Event, UnsignedEvent, getEventHash, signEvent } from 'nostr-tools' import { SimplePool, Sub, Event, UnsignedEvent, getEventHash, finishEvent, relayInit } from './tools/index.js' import { encryptData, decryptData, getSharedSecret, decodePayload, encodePayload } from './nip44.js' -import { getLogger } from '../helpers/logger.js' +import { ERROR, getLogger } from '../helpers/logger.js' import { encodeNprofile } from '../../custom-nip19.js' const handledEvents: string[] = [] // TODO: - big memory leak here, add TTL type AppInfo = { appId: string, publicKey: string, privateKey: string, name: string } @@ -56,13 +56,13 @@ process.on("message", (message: ChildProcessRequest) => { sendToNostr(message.appId, message.data, message.relays) break default: - getLogger({ appName: "nostrMiddleware" })("ERROR", "unknown nostr request", message) + getLogger({ component: "nostrMiddleware" })(ERROR, "unknown nostr request", message) break } }) const initSubprocessHandler = (settings: NostrSettings) => { if (subProcessHandler) { - getLogger({ appName: "nostrMiddleware" })("ERROR", "nostr settings ignored since handler already exists") + getLogger({ component: "nostrMiddleware" })(ERROR, "nostr settings ignored since handler already exists") return } subProcessHandler = new Handler(settings, event => { @@ -74,7 +74,7 @@ const initSubprocessHandler = (settings: NostrSettings) => { } const sendToNostr: NostrSend = (appId, data, relays) => { if (!subProcessHandler) { - getLogger({ appName: "nostrMiddleware" })("ERROR", "nostr was not initialized") + getLogger({ component: "nostrMiddleware" })(ERROR, "nostr was not initialized") return } subProcessHandler.Send(appId, data, relays) @@ -87,7 +87,7 @@ export default class Handler { subs: Sub[] = [] apps: Record = {} eventCallback: (event: NostrEvent) => void - log = getLogger({ appName: "nostrMiddleware" }) + log = getLogger({ component: "nostrMiddleware" }) constructor(settings: NostrSettings, eventCallback: (event: NostrEvent) => void) { this.settings = settings this.log( diff --git a/src/services/storage/eventsLog.ts b/src/services/storage/eventsLog.ts index 6983bcd3..4df1ee0e 100644 --- a/src/services/storage/eventsLog.ts +++ b/src/services/storage/eventsLog.ts @@ -23,7 +23,7 @@ const columns = ["timestampMs", "userId", "appUserId", "appId", "balance", "type type StringerWrite = (chunk: any, cb: (error: Error | null | undefined) => void) => boolean export default class EventsLogManager { eventLogPath: string - log = getLogger({ appName: "EventsLogManager" }) + log = getLogger({ component: "EventsLogManager" }) stringerWrite: StringerWrite constructor(eventLogPath: string) { this.eventLogPath = eventLogPath diff --git a/src/services/storage/transactionsQueue.ts b/src/services/storage/transactionsQueue.ts index 8a1894b2..48e090e8 100644 --- a/src/services/storage/transactionsQueue.ts +++ b/src/services/storage/transactionsQueue.ts @@ -15,7 +15,7 @@ export default class { log: PubLogger constructor(name: string, DB: DataSource | EntityManager) { this.DB = DB - this.log = getLogger({ appName: name }) + this.log = getLogger({ component: name }) } PushToQueue(op: TxOperation) { diff --git a/src/services/storage/userStorage.ts b/src/services/storage/userStorage.ts index 8c1d5b2d..74f0296c 100644 --- a/src/services/storage/userStorage.ts +++ b/src/services/storage/userStorage.ts @@ -94,10 +94,10 @@ export default class { user_id: userId, }, "balance_sats", increment) if (!res.affected) { - getLogger({ userId: userId, appName: "balanceUpdates" })("user unaffected by increment") + getLogger({ userId: userId, component: "balanceUpdates" })("user unaffected by increment") throw new Error("unaffected balance increment for " + userId) // TODO: fix logs doxing } - getLogger({ userId: userId, appName: "balanceUpdates" })("incremented balance from", user.balance_sats, "sats, by", increment, "sats") + getLogger({ userId: userId, component: "balanceUpdates" })("incremented balance from", user.balance_sats, "sats, by", increment, "sats") this.eventsLog.LogEvent({ type: 'balance_increment', userId, appId: "", appUserId: "", balance: user.balance_sats, data: reason, amount: increment }) } async DecrementUserBalance(userId: string, decrement: number, reason: string, entityManager?: DataSource | EntityManager) { @@ -116,17 +116,17 @@ export default class { async DecrementUserBalanceInTx(userId: string, decrement: number, reason: string, dbTx: DataSource | EntityManager) { const user = await this.GetUser(userId, dbTx) if (!user || user.balance_sats < decrement) { - getLogger({ userId: userId, appName: "balanceUpdates" })("not enough balance to decrement") + getLogger({ userId: userId, component: "balanceUpdates" })("not enough balance to decrement") throw new Error("not enough balance to decrement") } const res = await dbTx.getRepository(User).decrement({ user_id: userId, }, "balance_sats", decrement) if (!res.affected) { - getLogger({ userId: userId, appName: "balanceUpdates" })("user unaffected by decrement") + getLogger({ userId: userId, component: "balanceUpdates" })("user unaffected by decrement") throw new Error("unaffected balance decrement for " + userId) // TODO: fix logs doxing } - getLogger({ userId: userId, appName: "balanceUpdates" })("decremented balance from", user.balance_sats, "sats, by", decrement, "sats") + getLogger({ userId: userId, component: "balanceUpdates" })("decremented balance from", user.balance_sats, "sats, by", decrement, "sats") this.eventsLog.LogEvent({ type: 'balance_decrement', userId, appId: "", appUserId: "", balance: user.balance_sats, data: reason, amount: decrement }) }