Harden server logging and production boot experience
CI / test (push) Has been cancelled

Replace ad-hoc console output with a structured logger (pretty/JSON,
levels, redaction, optional file rotation), a clean startup banner with
Docker/feature probes, graceful shutdown signals, and slow-RPC warnings.
This commit is contained in:
2026-07-10 23:59:13 -04:00
parent d87e6fe486
commit fa99bd8c6e
7 changed files with 482 additions and 143 deletions
+7 -2
View File
@@ -9,9 +9,12 @@ import DHT from 'hyperdht'
import b4a from 'b4a'
import crypto from 'hypercore-crypto'
import dotenv from 'dotenv'
import logger from '../utils/logger.js'
dotenv.config()
const log = logger.child('keys')
/**
* @param {string} [envPath]
* @returns {{ seed: Uint8Array, keyPair: { publicKey: Uint8Array, secretKey: Uint8Array }, publicKeyHex: string, seedHex: string }}
@@ -26,7 +29,9 @@ export function loadOrCreateKeyPair(envPath = '.env') {
const publicKeyHex = b4a.toString(DHT.keyPair(seed).publicKey, 'hex')
const line = `\nSERVER_SEED=${seedHex}\nSERVER_PUBLIC_KEY=${publicKeyHex}\n`
fs.appendFileSync(envPath, line, { flag: 'a' })
console.log('[INFO] Generated new SERVER_SEED and SERVER_PUBLIC_KEY in', path.resolve(envPath))
log.info('Generated new SERVER_SEED and SERVER_PUBLIC_KEY', {
path: path.resolve(envPath),
})
}
if (!/^[0-9a-fA-F]{64}$/.test(seedHex)) {
@@ -54,7 +59,7 @@ export function loadOrCreateKeyPair(envPath = '.env') {
}
fs.writeFileSync(envPath, env)
} catch (err) {
console.warn('[WARN] Could not update .env with SERVER_PUBLIC_KEY:', err.message)
log.warn('Could not update .env with SERVER_PUBLIC_KEY', { error: err.message })
}
}
+9 -1
View File
@@ -1,6 +1,10 @@
/**
* Tracks live ProtomuxRPC sessions for broadcast and cleanup.
*/
import logger from '../utils/logger.js'
const log = logger.child('peers')
export class PeerRegistry {
constructor() {
/** @type {Map<string, import('../rpc/session.js').PeerSession>} */
@@ -46,7 +50,11 @@ export class PeerRegistry {
try {
session.push(method, payload)
} catch (err) {
console.error(`[ERROR] Broadcast to ${session.id.slice(0, 12)} failed: ${err.message}`)
log.debug('Broadcast failed', {
peerId: session.id.slice(0, 12),
method,
error: err.message,
})
}
}
}
+4 -1
View File
@@ -248,7 +248,10 @@ export function registerDeployHandlers(session) {
`Deploy rolled back: could not attach network "${args.customNetwork}". ${formatted.message}`
)
}
console.warn(`[WARN] Failed to connect to network ${args.customNetwork}: ${netErr.message}`)
logger.warn('Failed to connect container to network', {
network: args.customNetwork,
error: netErr.message,
})
}
}
+15 -1
View File
@@ -110,7 +110,21 @@ export class PeerSession {
args: args ?? {},
})
}
recordRpc(method, { ok: true, latencyMs: Date.now() - t0 })
const latencyMs = Date.now() - t0
recordRpc(method, { ok: true, latencyMs })
if (latencyMs >= 2000) {
logger.warn('Slow RPC', {
method,
peerId: this.id.slice(0, 12),
latencyMs,
})
} else {
logger.debug('RPC ok', {
method,
peerId: this.id.slice(0, 12),
latencyMs,
})
}
return result
} catch (err) {
if (shouldAudit(method) || err?.code === 'PERMISSION_DENIED') {
+127 -41
View File
@@ -2,8 +2,7 @@
* peardock server entry point.
*
* HyperDHT listener + protomux-rpc API for remote Docker management.
*
* Clients connect with the server public key (printed on start / stored as SERVER_PUBLIC_KEY).
* Clients connect with the server public key printed at startup.
*/
import DHT from 'hyperdht'
import b4a from 'b4a'
@@ -23,18 +22,34 @@ import {
restoreTunnelsFromDisk,
} from './services/holesail-tunnels.js'
import { restoreSchedules } from './services/schedules.js'
import { docker } from './services/docker.js'
import logger from './utils/logger.js'
import { isSwarmEnabled } from './handlers/swarm.js'
import { isPluginsEnabled } from './handlers/plugins.js'
const { keyPair, publicKeyHex } = loadOrCreateKeyPair()
const bootStarted = Date.now()
const log = logger.child('server')
/** @type {{ keyPair: any, publicKeyHex: string }} */
let keyPair
let publicKeyHex
try {
;({ keyPair, publicKeyHex } = loadOrCreateKeyPair())
} catch (err) {
log.error('Failed to load server keypair', { error: err.message })
process.exit(1)
}
const dht = new DHT()
const server = dht.createServer()
server.on('connection', (socket) => {
const peerId = socket.remotePublicKey ? b4a.toString(socket.remotePublicKey, 'hex') : null
// Only hard-reject revoked peers here; allowlist + invite redeem run at handshake
const peerId = socket.remotePublicKey
? b4a.toString(socket.remotePublicKey, 'hex')
: null
if (peerId && isPeerRevoked(peerId)) {
logger.warn('Rejected revoked peer', { peerId: peerId.slice(0, 12) })
log.warn('Rejected revoked peer', { peerId: peerId.slice(0, 12) })
try {
socket.destroy()
} catch {
@@ -49,79 +64,150 @@ server.on('connection', (socket) => {
cleanupSession(s)
peers.remove(s.id)
recordPeerDisconnect()
logger.info('Peer disconnected', { peerId: s.id.slice(0, 12) })
log.info('Peer disconnected', {
peerId: s.id.slice(0, 12),
role: s.role,
peers: peers.size,
})
},
})
registerAllHandlers(session)
peers.add(session)
recordPeerConnect()
logger.info('Peer connected', {
log.info('Peer connected', {
peerId: session.id.slice(0, 12),
role: session.role,
peers: peers.size,
})
})
server.on('error', (err) => {
log.error('HyperDHT server error', { error: err.message, code: err.code })
})
/**
* Probe Docker socket for the boot banner.
* @returns {Promise<{ ok: boolean, apiVersion?: string, os?: string, error?: string }>}
*/
async function probeDocker() {
try {
const version = await docker.version()
return {
ok: true,
apiVersion: version.ApiVersion || version.apiVersion || undefined,
os: version.Os || version.os || undefined,
}
} catch (err) {
return { ok: false, error: err.message || String(err) }
}
}
await server.listen(keyPair)
logger.info('peardock server listening on HyperDHT')
console.log('')
console.log('═══════════════════════════════════════════════════════════')
console.log(' peardock server ready')
console.log(` Public key (paste into the client):`)
console.log(` ${publicKeyHex}`)
if (isHolesailEnabled()) {
const hs = holesailStatus()
console.log(
` Holesail tunnels: ${hs.available ? 'enabled' : 'enabled but package missing'} (max ${hs.max})`
)
} else {
console.log(' Holesail tunnels: off (ENABLE_HOLESAIL=0)')
const dockerStatus = await probeDocker()
const hs = isHolesailEnabled() ? holesailStatus() : null
const bootMs = Date.now() - bootStarted
logger.banner([
'peardock server ready',
'',
'Public key (paste into the Pear client):',
publicKeyHex,
'',
`Docker: ${dockerStatus.ok ? `ok · API ${dockerStatus.apiVersion || '?'} · ${dockerStatus.os || '?'}` : `unavailable · ${dockerStatus.error || 'socket error'}`}`,
`Holesail: ${
!isHolesailEnabled()
? 'off (ENABLE_HOLESAIL=0)'
: hs?.available
? `on · max ${hs.max} tunnels`
: 'on but package missing'
}`,
`Swarm RPC: ${isSwarmEnabled() ? 'on' : 'off'} · Plugins: ${isPluginsEnabled() ? 'on' : 'off'}`,
`Log: ${logger.format} · level ${['error', 'warn', 'info', 'debug'][logger.level] || 'info'}`,
`Boot ${bootMs}ms · pid ${process.pid} · Node ${process.version}`,
])
log.info('Listening on HyperDHT', {
publicKey: publicKeyHex.slice(0, 16) + '…',
docker: dockerStatus.ok,
bootMs,
})
if (!dockerStatus.ok) {
log.warn('Docker socket not reachable — RPC that needs Docker will fail until dockerd is up', {
error: dockerStatus.error,
})
}
console.log('═══════════════════════════════════════════════════════════')
console.log('')
startDockerEventStream()
startStatsBroadcast()
// Recreate persisted Holesail tunnels (same hs:// keys when possible)
if (isHolesailEnabled()) {
restoreTunnelsFromDisk().catch((err) => {
logger.warn('Tunnel restore failed', { error: err.message })
})
restoreTunnelsFromDisk()
.then((r) => {
if (r?.restored || r?.failed) {
log.info('Restored Holesail tunnels', r)
}
})
.catch((err) => {
log.warn('Tunnel restore failed', { error: err.message })
})
}
// Interval maintenance jobs (system prune, etc.)
try {
restoreSchedules()
log.debug('Schedules restored')
} catch (err) {
logger.warn('Schedule restore failed', { error: err.message })
log.warn('Schedule restore failed', { error: err.message })
}
async function shutdown() {
console.log('[INFO] Server shutting down…')
let shuttingDown = false
async function shutdown(signal = 'shutdown') {
if (shuttingDown) return
shuttingDown = true
log.info('Shutting down', { signal, peers: peers.size, uptimeSec: Math.round(process.uptime()) })
stopStatsBroadcast()
stopDockerEventStream()
try {
await closeAllTunnels()
} catch {
// ignore
} catch (err) {
log.warn('Error closing tunnels', { error: err.message })
}
peers.clear()
try {
await server.close()
} catch {
// ignore
} catch (err) {
log.debug('server.close', { error: err.message })
}
try {
await dht.destroy()
} catch {
// ignore
} catch (err) {
log.debug('dht.destroy', { error: err.message })
}
process.exit(0)
log.info('Bye')
// Allow log flush
setTimeout(() => process.exit(0), 50).unref?.()
}
gracefulGoodbye(shutdown)
process.on('SIGINT', shutdown)
process.on('SIGTERM', shutdown)
gracefulGoodbye(() => shutdown('goodbye'))
process.on('SIGINT', () => shutdown('SIGINT'))
process.on('SIGTERM', () => shutdown('SIGTERM'))
process.on('uncaughtException', (err) => {
log.error('Uncaught exception', { error: err.message, stack: err.stack })
shutdown('uncaughtException')
})
process.on('unhandledRejection', (reason) => {
const msg = reason instanceof Error ? reason.message : String(reason)
const stack = reason instanceof Error ? reason.stack : undefined
log.error('Unhandled rejection', { error: msg, stack })
})
+299 -97
View File
@@ -1,162 +1,364 @@
/**
* Structured logging utility with levels and rotation
* Production-grade logger for peardock server.
*
* - Levels: error | warn | info | debug (env LOG_LEVEL)
* - Console: pretty colored (default TTY) or JSON lines (LOG_FORMAT=json / non-TTY)
* - Optional file logging with size rotation (ENABLE_FILE_LOGGING=1)
* - Redacts secrets in meta (password, seed, token, …)
*/
import fs from 'fs';
import path from 'path';
import fs from 'fs'
import path from 'path'
import { inspect } from 'util'
const LOG_LEVELS = {
ERROR: 0,
WARN: 1,
INFO: 2,
DEBUG: 3,
};
const LEVELS = Object.freeze({
error: 0,
warn: 1,
info: 2,
debug: 3,
})
const LOG_LEVEL_NAMES = ['ERROR', 'WARN', 'INFO', 'DEBUG'];
const LEVEL_LABEL = {
0: 'error',
1: 'warn',
2: 'info',
3: 'debug',
}
const LEVEL_COLOR = {
0: '\x1b[31m', // red
1: '\x1b[33m', // yellow
2: '\x1b[36m', // cyan
3: '\x1b[90m', // gray
}
const DIM = '\x1b[2m'
const BOLD = '\x1b[1m'
const RESET = '\x1b[0m'
const GREEN = '\x1b[32m'
const MAGENTA = '\x1b[35m'
const REDACT_KEYS = /^(password|passwd|secret|token|seed|authorization|auth|api[_-]?key|private[_-]?key|server_seed|invite)$/i
/**
* @param {string} [raw]
* @returns {number}
*/
export function parseLogLevel(raw) {
const v = String(raw || process.env.LOG_LEVEL || '')
.trim()
.toLowerCase()
if (v === 'error' || v === '0') return LEVELS.error
if (v === 'warn' || v === 'warning' || v === '1') return LEVELS.warn
if (v === 'info' || v === '2') return LEVELS.info
if (v === 'debug' || v === 'trace' || v === '3') return LEVELS.debug
// Default: info in production, debug otherwise
if (process.env.NODE_ENV === 'production') return LEVELS.info
return LEVELS.debug
}
/**
* @param {unknown} value
* @param {number} [depth]
*/
function redact(value, depth = 0) {
if (depth > 4) return '[Depth]'
if (value == null) return value
if (Array.isArray(value)) return value.map((v) => redact(v, depth + 1))
if (typeof value === 'object') {
if (value instanceof Error) {
return {
name: value.name,
message: value.message,
code: value.code,
stack: process.env.LOG_STACK === '1' ? value.stack : undefined,
}
}
const out = {}
for (const [k, v] of Object.entries(value)) {
if (REDACT_KEYS.test(k)) {
out[k] = '[Redacted]'
} else if (typeof v === 'string' && v.length > 2000) {
out[k] = `${v.slice(0, 2000)}…(+${v.length - 2000})`
} else {
out[k] = redact(v, depth + 1)
}
}
return out
}
if (typeof value === 'string' && value.length > 4000) {
return `${value.slice(0, 4000)}…(+${value.length - 4000})`
}
return value
}
/**
* @param {unknown} meta
*/
function formatMetaPretty(meta) {
if (meta == null) return ''
const keys = Object.keys(meta)
if (!keys.length) return ''
try {
return (
' ' +
inspect(meta, {
colors: true,
depth: 4,
compact: true,
breakLength: 100,
sorted: true,
})
)
} catch {
return ` ${JSON.stringify(meta)}`
}
}
class Logger {
/**
* @param {{
* level?: number,
* name?: string,
* enableFileLogging?: boolean,
* logDir?: string,
* maxFileSize?: number,
* maxFiles?: number,
* format?: 'pretty'|'json',
* color?: boolean,
* }} [options]
*/
constructor(options = {}) {
this.level = options.level || (process.env.NODE_ENV === 'production' ? LOG_LEVELS.INFO : LOG_LEVELS.DEBUG);
this.enableFileLogging = options.enableFileLogging || false;
this.logDir = options.logDir || './logs';
this.maxFileSize = options.maxFileSize || 10 * 1024 * 1024; // 10MB
this.maxFiles = options.maxFiles || 5;
this.level = options.level ?? parseLogLevel()
this.name = options.name || 'peardock'
this.enableFileLogging =
options.enableFileLogging !== undefined
? Boolean(options.enableFileLogging)
: process.env.ENABLE_FILE_LOGGING === 'true' ||
process.env.ENABLE_FILE_LOGGING === '1'
this.logDir = options.logDir || process.env.LOG_DIR || './logs'
this.maxFileSize = options.maxFileSize || 10 * 1024 * 1024
this.maxFiles = options.maxFiles || 5
const fmtEnv = String(process.env.LOG_FORMAT || options.format || '').toLowerCase()
const isTty = Boolean(process.stdout?.isTTY)
this.format =
fmtEnv === 'json' || fmtEnv === 'pretty'
? fmtEnv
: isTty
? 'pretty'
: process.env.NODE_ENV === 'production'
? 'json'
: 'pretty'
this.color =
options.color !== undefined
? Boolean(options.color)
: this.format === 'pretty' && isTty && process.env.NO_COLOR !== '1'
if (this.enableFileLogging) {
this.ensureLogDirectory();
this.currentLogFile = this.getLogFileName();
this.ensureLogDirectory()
this.currentLogFile = this.getLogFileName()
}
}
/**
* Child logger with bound name / base meta.
* @param {string} name
* @param {Record<string, unknown>} [baseMeta]
*/
child(name, baseMeta = {}) {
const child = new Logger({
level: this.level,
name: this.name === 'peardock' ? name : `${this.name}:${name}`,
enableFileLogging: this.enableFileLogging,
logDir: this.logDir,
maxFileSize: this.maxFileSize,
maxFiles: this.maxFiles,
format: this.format,
color: this.color,
})
child._baseMeta = { ...(this._baseMeta || {}), ...baseMeta }
return child
}
ensureLogDirectory() {
if (!fs.existsSync(this.logDir)) {
fs.mkdirSync(this.logDir, { recursive: true });
fs.mkdirSync(this.logDir, { recursive: true, mode: 0o750 })
}
}
getLogFileName() {
const date = new Date().toISOString().split('T')[0];
return path.join(this.logDir, `peardock-${date}.log`);
const date = new Date().toISOString().split('T')[0]
return path.join(this.logDir, `peardock-${date}.log`)
}
rotateLogFile() {
if (!this.enableFileLogging) return;
if (!this.enableFileLogging || !this.currentLogFile) return
try {
const stats = fs.statSync(this.currentLogFile);
if (stats.size > this.maxFileSize) {
// Rotate: move current to archive
const archiveName = this.currentLogFile.replace('.log', `-${Date.now()}.log`);
fs.renameSync(this.currentLogFile, archiveName);
// Clean up old files
this.cleanupOldLogs();
// Create new log file
this.currentLogFile = this.getLogFileName();
}
} catch (err) {
// File doesn't exist yet, that's okay
if (!fs.existsSync(this.currentLogFile)) return
const stats = fs.statSync(this.currentLogFile)
if (stats.size <= this.maxFileSize) return
const archiveName = this.currentLogFile.replace(
/\.log$/,
`-${Date.now()}.log`
)
fs.renameSync(this.currentLogFile, archiveName)
this.cleanupOldLogs()
this.currentLogFile = this.getLogFileName()
} catch {
// ignore
}
}
cleanupOldLogs() {
try {
const files = fs.readdirSync(this.logDir)
.filter(f => f.startsWith('peardock-') && f.endsWith('.log'))
.map(f => ({
const files = fs
.readdirSync(this.logDir)
.filter((f) => f.startsWith('peardock-') && f.endsWith('.log'))
.map((f) => ({
name: f,
path: path.join(this.logDir, f),
time: fs.statSync(path.join(this.logDir, f)).mtime.getTime()
time: fs.statSync(path.join(this.logDir, f)).mtime.getTime(),
}))
.sort((a, b) => b.time - a.time);
.sort((a, b) => b.time - a.time)
// Keep only the most recent maxFiles
if (files.length > this.maxFiles) {
files.slice(this.maxFiles).forEach(file => {
for (const file of files.slice(this.maxFiles)) {
try {
fs.unlinkSync(file.path);
} catch (err) {
console.error(`Failed to delete old log file: ${file.name}`, err);
fs.unlinkSync(file.path)
} catch {
// ignore
}
});
}
}
} catch (err) {
console.error('Failed to cleanup old logs:', err);
} catch {
// ignore
}
}
formatMessage(level, message, meta = {}) {
const timestamp = new Date().toISOString();
const metaStr = Object.keys(meta).length > 0 ? ` ${JSON.stringify(meta)}` : '';
return `[${timestamp}] [${LOG_LEVEL_NAMES[level]}] ${message}${metaStr}`;
/**
* @param {number} level
* @param {string} message
* @param {Record<string, unknown>} [meta]
*/
formatPretty(level, message, meta = {}) {
const ts = new Date().toISOString()
const label = LEVEL_LABEL[level] || 'info'
const c = this.color
const lvl = c
? `${LEVEL_COLOR[level] || ''}${BOLD}${label.toUpperCase().padEnd(5)}${RESET}`
: label.toUpperCase().padEnd(5)
const time = c ? `${DIM}${ts}${RESET}` : ts
const name = c ? `${MAGENTA}${this.name}${RESET}` : this.name
const msg = c && level === LEVELS.info ? `${GREEN}${message}${RESET}` : message
const metaStr = formatMetaPretty(meta)
return `${time} ${lvl} [${name}] ${msg}${metaStr}`
}
writeToFile(message) {
if (!this.enableFileLogging) return;
/**
* @param {number} level
* @param {string} message
* @param {Record<string, unknown>} [meta]
*/
formatJson(level, message, meta = {}) {
return JSON.stringify({
ts: new Date().toISOString(),
level: LEVEL_LABEL[level] || 'info',
name: this.name,
msg: message,
pid: process.pid,
...meta,
})
}
writeToFile(line) {
if (!this.enableFileLogging) return
try {
this.rotateLogFile();
fs.appendFileSync(this.currentLogFile, message + '\n');
this.rotateLogFile()
// Always store JSON lines in files for grepping
fs.appendFileSync(this.currentLogFile, line + '\n', { mode: 0o640 })
} catch (err) {
console.error('Failed to write to log file:', err);
console.error('Failed to write log file:', err.message)
}
}
log(level, message, meta = {}) {
if (level > this.level) return;
/**
* @param {number} level
* @param {string} message
* @param {Record<string, unknown>|Error} [metaOrErr]
*/
log(level, message, metaOrErr = {}) {
if (level > this.level) return
const formatted = this.formatMessage(level, message, meta);
// Console output
switch (level) {
case LOG_LEVELS.ERROR:
console.error(formatted);
break;
case LOG_LEVELS.WARN:
console.warn(formatted);
break;
case LOG_LEVELS.INFO:
console.log(formatted);
break;
case LOG_LEVELS.DEBUG:
console.log(formatted);
break;
let meta = {}
if (metaOrErr instanceof Error) {
meta = { err: metaOrErr }
} else if (metaOrErr && typeof metaOrErr === 'object') {
meta = metaOrErr
}
// File output
this.writeToFile(formatted);
const merged = redact({ ...(this._baseMeta || {}), ...meta })
const consoleLine =
this.format === 'json'
? this.formatJson(level, message, merged)
: this.formatPretty(level, message, merged)
switch (level) {
case LEVELS.error:
console.error(consoleLine)
break
case LEVELS.warn:
console.warn(consoleLine)
break
default:
console.log(consoleLine)
}
// File always JSON for production tooling
if (this.enableFileLogging) {
this.writeToFile(this.formatJson(level, message, merged))
}
}
error(message, meta) {
this.log(LOG_LEVELS.ERROR, message, meta);
this.log(LEVELS.error, message, meta)
}
warn(message, meta) {
this.log(LOG_LEVELS.WARN, message, meta);
this.log(LEVELS.warn, message, meta)
}
info(message, meta) {
this.log(LOG_LEVELS.INFO, message, meta);
this.log(LEVELS.info, message, meta)
}
debug(message, meta) {
this.log(LOG_LEVELS.DEBUG, message, meta);
this.log(LEVELS.debug, message, meta)
}
/**
* Multi-line banner (startup). Always shown at info+.
* @param {string[]} lines
*/
banner(lines) {
if (LEVELS.info > this.level) return
const width = Math.min(
72,
Math.max(40, ...lines.map((l) => String(l).length)) + 4
)
const bar = '─'.repeat(width)
const c = this.color
const paint = (s) => (c ? `${BOLD}${GREEN}${s}${RESET}` : s)
console.log('')
console.log(paint(`${bar}`))
for (const line of lines) {
const pad = ' '.repeat(Math.max(0, width - String(line).length - 1))
console.log(paint(`${line}${pad}`))
}
console.log(paint(`${bar}`))
console.log('')
}
}
// Create singleton instance
const logger = new Logger({
enableFileLogging: process.env.ENABLE_FILE_LOGGING === 'true',
level: process.env.LOG_LEVEL === 'ERROR' ? LOG_LEVELS.ERROR :
process.env.LOG_LEVEL === 'WARN' ? LOG_LEVELS.WARN :
process.env.LOG_LEVEL === 'INFO' ? LOG_LEVELS.INFO :
LOG_LEVELS.DEBUG,
});
export default logger;
const logger = new Logger()
export { Logger, LEVELS }
export default logger