introduce logging context

packages/pockethost/src/cli/commands/EdgeCommand/DaemonCommand/ServeCommand/daemon.ts

@@ -1,6 +1,6 @@
 import Dockerode from 'dockerode'
 import { ErrorRequestHandler } from 'express'
-import { LoggerService } from '../../../../../common'
+import { logger } from '../../../../../common'
 import {
   MOTHERSHIP_ADMIN_PASSWORD,
   MOTHERSHIP_ADMIN_USERNAME,
@@ -18,8 +18,7 @@ import {
 } from '../../../../../services'
 
 export async function daemon() {
-  const logger = LoggerService().create(`EdgeDaemonCommand`)
-  const { dbg, error, info, warn } = logger
+  const { info, warn } = logger()
   info(`Starting`)
 
   const docker = new Dockerode()

packages/pockethost/src/cli/commands/EdgeCommand/DaemonCommand/ServeCommand/index.ts

@@ -1,4 +1,5 @@
 import { Command } from 'commander'
+import { logger } from '../../../../../../common'
 import { daemon } from './daemon'
 
 type Options = {
@@ -9,6 +10,7 @@ export const ServeCommand = () => {
   const cmd = new Command(`serve`)
     .description(`Run an edge daemon server`)
     .action(async (options: Options) => {
+      logger().context({ cli: 'edge:daemon:serve' })
       await daemon()
     })
   return cmd

packages/pockethost/src/cli/commands/EdgeCommand/FtpCommand/FtpService/index.ts

@@ -1,8 +1,8 @@
 import { readFileSync } from 'fs'
 import { FtpSrv } from 'ftp-srv'
 import {
-  LoggerService,
   PocketBase,
+  logger,
   mergeConfig,
   mkSingleton,
 } from '../../../../../common'
@@ -31,13 +31,13 @@ export const ftpService = mkSingleton((config: Partial<FtpConfig> = {}) => {
     key: readFileSync(SSL_KEY()),
     cert: readFileSync(SSL_CERT()),
   }
-  const _ftpServiceLogger = LoggerService().create('FtpService')
+  const _ftpServiceLogger = logger()
   const { dbg, info } = _ftpServiceLogger
 
   const ftpServer = new FtpSrv({
     url: 'ftp://0.0.0.0:' + PH_FTP_PORT(),
     anonymous: false,
-    log: _ftpServiceLogger.create(`ftpServer`),
+    log: _ftpServiceLogger,
     tls,
     pasv_url: PH_FTP_PASV_IP(),
     pasv_max: PH_FTP_PASV_PORT_MAX(),
@@ -60,7 +60,11 @@ export const ftpService = mkSingleton((config: Partial<FtpConfig> = {}) => {
           await client.collection('users').authWithPassword(username, password)
         }
         dbg(`Logged in`)
-        const fs = new PhFs(connection, client, _ftpServiceLogger)
+        const fs = new PhFs(
+          connection,
+          client,
+          _ftpServiceLogger.child(username).context({ ftpSession: Date.now() }),
+        )
         resolve({ fs })
       } catch (e) {
         reject(new Error(`Invalid username or password`))

packages/pockethost/src/cli/commands/EdgeCommand/FtpCommand/ServeCommand/ftp.ts

@@ -1,10 +1,12 @@
-import { LoggerService } from '../../../../../common'
-import { MOTHERSHIP_URL, tryFetch } from '../../../../../core'
+import { logger } from '../../../../../common'
+import {
+  MOTHERSHIP_URL,
+  tryFetch,
+} from '../../../../../core'
 import { ftpService } from '../FtpService'
 
 export async function ftp() {
-  const logger = LoggerService().create(`EdgeFtpCommand`)
-  const { dbg, error, info, warn } = logger
+  const { info } = logger()
   info(`Starting`)
 
   await tryFetch(MOTHERSHIP_URL(`/api/health`), {})

packages/pockethost/src/cli/commands/EdgeCommand/FtpCommand/ServeCommand/index.ts

@@ -1,4 +1,5 @@
 import { Command } from 'commander'
+import { logger } from '../../../../../../common'
 import { ftp } from './ftp'
 
 type Options = {
@@ -9,6 +10,7 @@ export const ServeCommand = () => {
   const cmd = new Command(`serve`)
     .description(`Run an edge FTP server`)
     .action(async (options: Options) => {
+      logger().context({ cli: 'edge:ftp:serve' })
       await ftp()
     })
   return cmd

packages/pockethost/src/cli/commands/EdgeCommand/SyslogCommand/ServeCommand/index.ts

@@ -1,4 +1,5 @@
 import { Command } from 'commander'
+import { logger } from '../../../../../../common'
 import { syslog } from './syslog'
 
 type Options = {
@@ -9,6 +10,7 @@ export const ServeCommand = () => {
   const cmd = new Command(`serve`)
     .description(`Run an edge syslog server`)
     .action(async (options: Options) => {
+      logger().context({ cli: 'edge:syslog:serve' })
       await syslog()
     })
   return cmd

packages/pockethost/src/cli/commands/FirewallCommand/ServeCommand/index.ts

@@ -1,4 +1,5 @@
 import { Command } from 'commander'
+import { logger } from '../../../../common'
 import { firewall } from './firewall/server'
 
 type Options = {
@@ -9,6 +10,7 @@ export const ServeCommand = () => {
   const cmd = new Command(`serve`)
     .description(`Serve the root firewall`)
     .action(async (options: Options) => {
+      logger().context({ cli: 'firewall:serve' })
       await firewall()
     })
   return cmd

packages/pockethost/src/cli/commands/FirewallCommand/index.ts

@@ -1,4 +1,5 @@
 import { Command } from 'commander'
+import { logger } from '../../../../common'
 import { ServeCommand } from './ServeCommand'
 
 type Options = {
@@ -10,6 +11,7 @@ export const FirewallCommand = () => {
     .description(`Root firewall commands`)
     .addCommand(ServeCommand())
     .action(() => {
+      logger().context({ cli: 'firewall' })
       cmd.help()
     })
   return cmd

packages/pockethost/src/cli/commands/HealthCommand/index.ts

@@ -1,5 +1,5 @@
 import { Command } from 'commander'
-import { LoggerService } from '../../../../core'
+import { logger } from '../../../../core'
 
 type Options = {
   debug: boolean
@@ -11,8 +11,8 @@ export const HealthCommand = () => {
       new Command(`check`)
         .description(`Perform a health check on the PocketHost system`)
         .action(async (options: Options) => {
-          const logger = LoggerService().create(`HealthCommand`)
-          const { dbg, error, info, warn } = logger
+          logger().context({ cli: 'health:check' })
+          const { dbg, error, info, warn } = logger()
           info(`Starting`)
           const { checkHealth } = await import(`./checkHealth`)
           await checkHealth()
@@ -24,8 +24,8 @@ export const HealthCommand = () => {
           `Compact SQLite databases by removing old SHM and WAL files`,
         )
         .action(async (options: Options) => {
-          const logger = LoggerService().create(`HealthCommand`)
-          const { dbg, error, info, warn } = logger
+          logger().context({ cli: 'health:compact' })
+          const { dbg, error, info, warn } = logger()
           info(`Starting`)
           const { compact } = await import(`./compact`)
           await compact()

packages/pockethost/src/cli/commands/MothershipCommand/SchemaCommand/index.ts

@@ -1,10 +1,12 @@
 import { Command } from 'commander'
+import { logger } from '../../../../common'
 import { schema } from './schema'
 
 export const SchemaCommand = () => {
   const cmd = new Command(`schema`)
     .description(`Create  snapshot of the current PocketHost mothership schema`)
     .action(async (options) => {
+      logger().context({ cli: 'mothership:schema' })
       await schema()
     })
   return cmd

packages/pockethost/src/cli/commands/MothershipCommand/ServeCommand/index.ts

@@ -1,4 +1,5 @@
 import { Command } from 'commander'
+import { logger } from '../../../../common'
 import { mothership } from './mothership'
 
 type Options = {
@@ -10,6 +11,7 @@ export const ServeCommand = () => {
     .description(`Run the PocketHost mothership`)
     .option(`--isolate`, `Use Docker for process isolation.`, false)
     .action(async (options: Options) => {
+      logger().context({ cli: 'mothership:serve' })
       console.log({ options })
       await mothership(options)
     })

packages/pockethost/src/cli/commands/PocketBaseCommand/UpdateCommand/index.ts

@@ -1,11 +1,15 @@
 import { Command } from 'commander'
+import { logger } from '../../../../common'
 import { freshenPocketbaseVersions } from './freshenPocketbaseVersions'
 
 export const UpdateCommand = () => {
   const cmd = new Command(`update`)
     .description(`Update PocketBase versions`)
     .action(async (options) => {
+      logger().context({ cli: 'pocketbase:update' })
+      const { info } = logger()
       await freshenPocketbaseVersions()
+      info('PocketBase versions updated')
     })
   return cmd
 }

packages/pockethost/src/cli/commands/SendMailCommand/sendmail.ts

@@ -30,7 +30,8 @@ export const SendMailCommand = () =>
     .option('--confirm', `Really send messages`, false)
 
     .action(async (messageId, { limit, confirm }) => {
-      const { dbg, info } = logger().create(`mail.ts`)
+      logger().context({ cli: 'sendmail' })
+      const { dbg, info } = logger()
 
       function interpolateString(
         template: string,

packages/pockethost/src/cli/commands/ServeCommand/index.ts

@@ -1,4 +1,5 @@
 import { Command } from 'commander'
+import { logger } from '../../../common'
 import { LoggerService } from '../../../common'
 import { daemon } from '../EdgeCommand/DaemonCommand/ServeCommand/daemon'
 import { syslog } from '../EdgeCommand/SyslogCommand/ServeCommand/syslog'
@@ -13,8 +14,8 @@ export const ServeCommand = () => {
   const cmd = new Command(`serve`)
     .description(`Run the entire PocketHost stack`)
     .action(async (options: Options) => {
-      const logger = LoggerService().create(`ServeCommand`)
-      const { dbg, error, info, warn } = logger
+      logger().context({ cli: 'serve' })
+      const { dbg, error, info, warn } = logger()
       info(`Starting`)
 
       await syslog()

packages/pockethost/src/cli/index.ts

@@ -2,7 +2,7 @@
 
 import { program } from 'commander'
 import EventSource from 'eventsource'
-import { LogLevelName, LoggerService } from '../../core'
+import { LogLevelName, gracefulExit, logger } from '../../core'
 import { version } from '../../package.json'
 import { EdgeCommand } from './commands/EdgeCommand'
 import { FirewallCommand } from './commands/FirewallCommand'
@@ -11,7 +11,7 @@ import { MothershipCommand } from './commands/MothershipCommand'
 import { PocketBaseCommand } from './commands/PocketBaseCommand'
 import { MailCommand } from './commands/SendMailCommand'
 import { ServeCommand } from './commands/ServeCommand'
-import './ioc'
+import { initIoc } from './ioc'
 
 export type GlobalOptions = {
   logLevel?: LogLevelName
@@ -22,6 +22,7 @@ export type GlobalOptions = {
 global.EventSource = EventSource
 
 export const main = async () => {
+  await initIoc()
   program.name('pockethost').description('Multitenant PocketBase hosting')
 
   program
@@ -33,13 +34,15 @@ export const main = async () => {
     .addCommand(ServeCommand())
     .addCommand(PocketBaseCommand())
     .action(async () => {
-      const { info, dbg } = LoggerService()
+      logger().context({ cli: 'main' })
+      const { info, dbg } = logger()
       info('PocketHost CLI')
       info(`Version: ${version}`, { version })
       program.help()
     })
 
   await program.parseAsync()
+  await gracefulExit()
 }
 
 main()

packages/pockethost/src/cli/ioc.ts

@@ -1,9 +1,12 @@
+import { version } from '../../package.json'
 import { ioc } from '../common'
 import { RegisterEnvSettingsService } from '../constants'
 import { WinstonLoggerService } from '../core/winston'
 import { GobotService } from '../services/GobotService'
 
-ioc('logger', WinstonLoggerService({}))
-
-RegisterEnvSettingsService()
-GobotService({})
+export const initIoc = async () => {
+  const logger = await WinstonLoggerService({})
+  ioc('logger', logger.context('ph_version', version))
+  RegisterEnvSettingsService()
+  GobotService({})
+}

packages/pockethost/src/common/ConsoleLogger.ts

@@ -66,6 +66,10 @@ export function ConsoleLogger(
       console.log('Breadcrumb:', s)
       return logger
     },
+    context(name: string | object, value?: string | number): Logger {
+      console.log('Context:', name, value)
+      return logger
+    },
     abort(...args: any[]): never {
       log(LogLevelName.Abort, ...args)
       process.exit(1)

packages/pockethost/src/common/Logger.ts

@@ -60,6 +60,7 @@ export type Logger = {
   trace: (...args: any[]) => void
   debug: (...args: any[]) => void
   breadcrumb: (s: object) => Logger
+  context: (name: string | object, value?: string | number) => Logger
   abort: (...args: any[]) => never
   shutdown: () => void
   setLevel: (level: LogLevelName) => void

packages/pockethost/src/core/winston.ts

@@ -1,5 +1,6 @@
 import { inspect } from 'node:util'
 import winston from 'winston'
+import { exitHook } from '..'
 import { Logger, mkSingleton } from '../common'
 import { DEBUG, DISCORD_ALERT_CHANNEL_URL } from '../constants'
 import { DiscordTransport } from './DiscordTransport'
@@ -8,11 +9,15 @@ const format = winston.format.combine(
   winston.format.colorize(),
   winston.format.printf(({ level, message, timestamp, ...meta }) => {
     const final: string[] = []
-    message.forEach((m: string) => {
+    ;[...message, meta].forEach((m: string) => {
       if (typeof m === 'string' && !!m.match(/\n/)) {
         final.push(...m.split(/\n/))
       } else if (typeof m === 'object') {
-        final.push(inspect(m, { depth: null }))
+        // Filter out Symbol properties and inspect the object
+        const filtered = Object.fromEntries(
+          Object.entries(m).filter(([key]) => typeof key === 'string'),
+        )
+        final.push(inspect(filtered, { depth: null }))
       } else {
         final.push(m)
       }
@@ -72,6 +77,11 @@ export const WinstonLoggerService = mkSingleton<{}, Logger>(() => {
   })
   logger.exitOnError = true
 
+  exitHook(() => {
+    // console.log('Closing Winston logger')
+    logger.close()
+  })
+
   {
     const url = DISCORD_ALERT_CHANNEL_URL()
     if (url) {
@@ -97,8 +107,20 @@ export const WinstonLoggerService = mkSingleton<{}, Logger>(() => {
         Object.assign(logger.defaultMeta, s)
         return api
       },
+      context: (name: string | object, value?: string | number) => {
+        if (typeof name === 'string') {
+          if (value !== undefined) {
+            logger.defaultMeta[name] = value
+          } else {
+            delete logger.defaultMeta[name]
+          }
+        } else {
+          Object.assign(logger.defaultMeta, name)
+        }
+        return api
+      },
       shutdown: () => {},
-      child: (name) => createApi(logger.child({ name })),
+      child: (name) => api.create(name),
       abort: (...args) => {
         logger.error(args)
         process.exit(1)