From e62e245fc756a698206b8aa9f246e8e2c67a17f0 Mon Sep 17 00:00:00 2001 From: Christina Ying Wang Date: Tue, 5 Nov 2024 17:03:06 -0800 Subject: [PATCH 1/4] Modify log monitor logging to be more generic Includes other host services in addition to balena.service Signed-off-by: Christina Ying Wang --- src/logging/monitor.ts | 10 ++++------ 1 file changed, 4 insertions(+), 6 deletions(-) diff --git a/src/logging/monitor.ts b/src/logging/monitor.ts index d57640b3..a2219f72 100644 --- a/src/logging/monitor.ts +++ b/src/logging/monitor.ts @@ -81,7 +81,7 @@ class LogMonitor { } stderr?.on('data', (data) => - log.error('journalctl - balena.service stderr: ', data.toString()), + log.error('Journalctl process stderr: ', data.toString()), ); const self = this; @@ -102,9 +102,9 @@ class LogMonitor { } } }); - log.debug('balena.service journalctl process exit.'); + log.debug('Journalctl process exit.'); } catch (e: any) { - log.error('journalctl - balena.service error: ', e.message ?? e); + log.error('Journalctl process error: ', e.message ?? e); } // On exit of process try to create another @@ -113,9 +113,7 @@ class LogMonitor { JOURNALCTL_ERROR_RETRY_DELAY_MAX, ); log.debug( - `Spawning another process to watch balena.service logs in ${ - wait / 1000 - }s`, + `Spawning another process to watch journal logs in ${wait / 1000}s`, ); await setTimeout(wait); void this.start(); From c610710f03368cc0b3290fefc98963655743c559 Mon Sep 17 00:00:00 2001 From: Christina Ying Wang Date: Mon, 18 Nov 2024 12:15:37 -0800 Subject: [PATCH 2/4] Move logger.ts into logging/index.ts Signed-off-by: Christina Ying Wang --- src/api-binder/index.ts | 2 +- src/compose/application-manager.ts | 2 +- src/compose/images.ts | 2 +- src/compose/network-manager.ts | 2 +- src/compose/network.ts | 2 +- src/compose/service-manager.ts | 2 +- src/compose/volume-manager.ts | 2 +- src/compose/volume.ts | 2 +- src/config/backends/config-fs.ts | 2 +- src/device-api/actions.ts | 2 +- src/device-api/v2.ts | 2 +- src/device-config.ts | 2 +- src/device-state/index.ts | 2 +- src/lib/firewall.ts | 2 +- src/lib/legacy.ts | 2 +- src/lib/update-lock.ts | 2 +- src/local-mode.ts | 2 +- src/logger.ts | 229 ------------------ src/logging/index.ts | 228 ++++++++++++++++- src/supervisor.ts | 2 +- test/integration/compose/volume.spec.ts | 2 +- test/integration/device-config.spec.ts | 2 +- test/integration/lib/firewall.spec.ts | 2 +- .../{11-logger.spec.ts => 11-logging.spec.ts} | 2 +- test/legacy/42-device-api-v2.spec.ts | 2 +- 25 files changed, 249 insertions(+), 254 deletions(-) delete mode 100644 src/logger.ts rename test/legacy/{11-logger.spec.ts => 11-logging.spec.ts} (98%) diff --git a/src/api-binder/index.ts b/src/api-binder/index.ts index 887b882a..eae0c99a 100644 --- a/src/api-binder/index.ts +++ b/src/api-binder/index.ts @@ -20,7 +20,7 @@ import log from '../lib/supervisor-console'; import * as deviceState from '../device-state'; import * as globalEventBus from '../event-bus'; import * as TargetState from './poll'; -import * as logger from '../logger'; +import * as logger from '../logging'; import * as apiHelper from '../lib/api-helper'; import { startReporting, stateReportErrors } from './report'; diff --git a/src/compose/application-manager.ts b/src/compose/application-manager.ts index 93243e9c..cdec7b0e 100644 --- a/src/compose/application-manager.ts +++ b/src/compose/application-manager.ts @@ -4,7 +4,7 @@ import type StrictEventEmitter from 'strict-event-emitter-types'; import * as config from '../config'; import type { Transaction } from '../db'; -import * as logger from '../logger'; +import * as logger from '../logging'; import LocalModeManager from '../local-mode'; import * as dbFormat from '../device-state/db-format'; diff --git a/src/compose/images.ts b/src/compose/images.ts index 687a5bec..7bfb6104 100644 --- a/src/compose/images.ts +++ b/src/compose/images.ts @@ -15,7 +15,7 @@ import { StatusError, } from '../lib/errors'; import * as LogTypes from '../lib/log-types'; -import * as logger from '../logger'; +import * as logger from '../logging'; import { ImageDownloadBackoffError } from './errors'; import type { Service } from './service'; diff --git a/src/compose/network-manager.ts b/src/compose/network-manager.ts index e83eae1e..aeb302f9 100644 --- a/src/compose/network-manager.ts +++ b/src/compose/network-manager.ts @@ -6,7 +6,7 @@ import { isNotFoundError } from '../lib/errors'; import logTypes = require('../lib/log-types'); import log from '../lib/supervisor-console'; -import * as logger from '../logger'; +import * as logger from '../logging'; import { Network } from './network'; import { ResourceRecreationAttemptError } from './errors'; diff --git a/src/compose/network.ts b/src/compose/network.ts index 50d0353a..6dca1693 100644 --- a/src/compose/network.ts +++ b/src/compose/network.ts @@ -3,7 +3,7 @@ import type dockerode from 'dockerode'; import { docker } from '../lib/docker-utils'; import logTypes = require('../lib/log-types'); -import * as logger from '../logger'; +import * as logger from '../logging'; import log from '../lib/supervisor-console'; import * as ComposeUtils from './utils'; diff --git a/src/compose/service-manager.ts b/src/compose/service-manager.ts index 0ba7d740..e05a4492 100644 --- a/src/compose/service-manager.ts +++ b/src/compose/service-manager.ts @@ -8,7 +8,7 @@ import type StrictEventEmitter from 'strict-event-emitter-types'; import * as config from '../config'; import { docker } from '../lib/docker-utils'; -import * as logger from '../logger'; +import * as logger from '../logging'; import { PermissiveNumber } from '../config/types'; import * as constants from '../lib/constants'; diff --git a/src/compose/volume-manager.ts b/src/compose/volume-manager.ts index 511676de..52dde09e 100644 --- a/src/compose/volume-manager.ts +++ b/src/compose/volume-manager.ts @@ -8,7 +8,7 @@ import { pathOnData } from '../lib/host-utils'; import { docker } from '../lib/docker-utils'; import * as LogTypes from '../lib/log-types'; import log from '../lib/supervisor-console'; -import * as logger from '../logger'; +import * as logger from '../logging'; import { ResourceRecreationAttemptError } from './errors'; import type { VolumeConfig } from './types'; import { Volume } from './volume'; diff --git a/src/compose/volume.ts b/src/compose/volume.ts index 373913ef..c5578ea4 100644 --- a/src/compose/volume.ts +++ b/src/compose/volume.ts @@ -7,7 +7,7 @@ import { docker } from '../lib/docker-utils'; import { InternalInconsistencyError } from '../lib/errors'; import * as LogTypes from '../lib/log-types'; import type { LabelObject } from '../types'; -import * as logger from '../logger'; +import * as logger from '../logging'; import * as ComposeUtils from './utils'; import type { diff --git a/src/config/backends/config-fs.ts b/src/config/backends/config-fs.ts index e9855ee9..4ce4120d 100644 --- a/src/config/backends/config-fs.ts +++ b/src/config/backends/config-fs.ts @@ -7,7 +7,7 @@ import { ConfigBackend } from './backend'; import { exec, exists } from '../../lib/fs-utils'; import * as hostUtils from '../../lib/host-utils'; import * as constants from '../../lib/constants'; -import * as logger from '../../logger'; +import * as logger from '../../logging'; import log from '../../lib/supervisor-console'; /** diff --git a/src/device-api/actions.ts b/src/device-api/actions.ts index 02da7b71..737cbe8c 100644 --- a/src/device-api/actions.ts +++ b/src/device-api/actions.ts @@ -4,7 +4,7 @@ import { getGlobalApiKey, refreshKey } from '../lib/api-keys'; import * as messages from './messages'; import * as eventTracker from '../event-tracker'; import * as deviceState from '../device-state'; -import * as logger from '../logger'; +import * as logger from '../logging'; import * as config from '../config'; import * as hostConfig from '../host-config'; import type { diff --git a/src/device-api/v2.ts b/src/device-api/v2.ts index c255b9fe..f9d9cc97 100644 --- a/src/device-api/v2.ts +++ b/src/device-api/v2.ts @@ -12,7 +12,7 @@ import * as commitStore from '../compose/commit'; import * as config from '../config'; import * as db from '../db'; import * as deviceConfig from '../device-config'; -import * as logger from '../logger'; +import * as logger from '../logging'; import * as images from '../compose/images'; import * as volumeManager from '../compose/volume-manager'; import * as serviceManager from '../compose/service-manager'; diff --git a/src/device-config.ts b/src/device-config.ts index 5e37e033..724632bf 100644 --- a/src/device-config.ts +++ b/src/device-config.ts @@ -4,7 +4,7 @@ import { promises as fs } from 'fs'; import * as config from './config'; import * as db from './db'; -import * as logger from './logger'; +import * as logger from './logging'; import * as dbus from './lib/dbus'; import type { EnvVarObject } from './types'; import { UnitNotLoadedError } from './lib/errors'; diff --git a/src/device-state/index.ts b/src/device-state/index.ts index 327cd27f..8c25e4c9 100644 --- a/src/device-state/index.ts +++ b/src/device-state/index.ts @@ -6,7 +6,7 @@ import type StrictEventEmitter from 'strict-event-emitter-types'; import prettyMs from 'pretty-ms'; import * as config from '../config'; -import * as logger from '../logger'; +import * as logger from '../logging'; import * as network from '../network'; import * as deviceConfig from '../device-config'; diff --git a/src/lib/firewall.ts b/src/lib/firewall.ts index e2a5b581..4d230cda 100644 --- a/src/lib/firewall.ts +++ b/src/lib/firewall.ts @@ -4,7 +4,7 @@ import * as config from '../config/index'; import * as constants from './constants'; import * as iptables from './iptables'; import { log } from './supervisor-console'; -import { logSystemMessage } from '../logger'; +import { logSystemMessage } from '../logging'; import * as dbFormat from '../device-state/db-format'; diff --git a/src/lib/legacy.ts b/src/lib/legacy.ts index 886a4954..4572d346 100644 --- a/src/lib/legacy.ts +++ b/src/lib/legacy.ts @@ -14,7 +14,7 @@ import { docker } from './docker-utils'; import { log } from './supervisor-console'; import { pathOnData } from './host-utils'; import type { Volume } from '../compose/volume'; -import * as logger from '../logger'; +import * as logger from '../logging'; import type { DatabaseApp, DatabaseService, diff --git a/src/lib/update-lock.ts b/src/lib/update-lock.ts index b7f793be..08e8550b 100644 --- a/src/lib/update-lock.ts +++ b/src/lib/update-lock.ts @@ -9,7 +9,7 @@ import { mkdirp } from './fs-utils'; import * as lockfile from './lockfile'; import { takeGlobalLockRW } from './process-lock'; import * as logTypes from './log-types'; -import * as logger from '../logger'; +import * as logger from '../logging'; export const LOCKFILE_UID = 65534; export const BASE_LOCK_DIR = '/tmp/balena-supervisor/services'; diff --git a/src/local-mode.ts b/src/local-mode.ts index efb72104..f057e966 100644 --- a/src/local-mode.ts +++ b/src/local-mode.ts @@ -6,7 +6,7 @@ import * as constants from './lib/constants'; import { docker } from './lib/docker-utils'; import { SupervisorContainerNotFoundError } from './lib/errors'; import log from './lib/supervisor-console'; -import * as logger from './logger'; +import * as logger from './logging'; // EngineSnapshot represents a list of containers, images, volumens, and networks present on the engine. // A snapshot is taken before entering local mode in order to perform cleanup when we exit local mode. diff --git a/src/logger.ts b/src/logger.ts deleted file mode 100644 index da52f948..00000000 --- a/src/logger.ts +++ /dev/null @@ -1,229 +0,0 @@ -import Bluebird from 'bluebird'; -import _ from 'lodash'; - -import * as config from './config'; -import * as eventTracker from './event-tracker'; -import type { LogType } from './lib/log-types'; -import { takeGlobalLockRW } from './lib/process-lock'; -import type { LogBackend, LogMessage } from './logging'; -import { BalenaLogBackend, LocalLogBackend } from './logging'; -import logMonitor from './logging/monitor'; - -import * as globalEventBus from './event-bus'; -import superConsole from './lib/supervisor-console'; - -type LogEventObject = Dictionary | null; - -// export class Logger { -let backend: LogBackend | null = null; -let balenaBackend: BalenaLogBackend | null = null; -let localBackend: LocalLogBackend | null = null; - -export const initialized = _.once(async () => { - await config.initialized(); - const { - apiEndpoint, - logsEndpoint, - uuid, - deviceApiKey, - unmanaged, - loggingEnabled, - localMode, - } = await config.getMany([ - 'apiEndpoint', - 'logsEndpoint', - 'uuid', - 'deviceApiKey', - 'unmanaged', - 'loggingEnabled', - 'localMode', - ]); - - balenaBackend = new BalenaLogBackend( - logsEndpoint ?? apiEndpoint, - uuid, - deviceApiKey, - ); - localBackend = new LocalLogBackend(); - backend = localMode ? localBackend : balenaBackend; - backend.unmanaged = unmanaged; - backend.publishEnabled = loggingEnabled; - - if (!balenaBackend.isInitialised()) { - globalEventBus.getInstance().once('deviceProvisioned', async () => { - const conf = await config.getMany([ - 'uuid', - 'apiEndpoint', - 'logsEndpoint', - 'deviceApiKey', - ]); - - // We use Boolean here, as deviceApiKey when unset - // is '' for legacy reasons. Once we're totally - // typescript, we can make it have a default value - // of undefined. - if (_.every(conf, Boolean)) { - // Everything is set, provide the values to the - // balenaBackend, and remove our listener - balenaBackend!.assignFields( - conf.logsEndpoint ?? conf.apiEndpoint, - conf.uuid!, - conf.deviceApiKey, - ); - } - }); - } -}); - -export function switchBackend(localMode: boolean) { - if (localMode) { - // Use the local mode backend - backend = localBackend; - superConsole.info('Switching logging backend to LocalLogBackend'); - } else { - // Use the balena backend - backend = balenaBackend; - superConsole.info('Switching logging backend to BalenaLogBackend'); - } -} - -export function getLocalBackend(): LocalLogBackend { - // TODO: Think about this interface a little better, it would be - // nicer to proxy the logs via the logger module - if (localBackend == null) { - // TODO: Type this as an internal inconsistency error - throw new Error('Local backend logger is not defined.'); - } - return localBackend; -} - -export function enable(value: boolean = true) { - if (backend != null) { - backend.publishEnabled = value; - } -} - -export async function log(message: LogMessage) { - await backend?.log(message); -} - -export function logSystemMessage( - message: string, - eventObj?: LogEventObject, - eventName?: string, - track: boolean = true, -) { - const msgObj: LogMessage = { message, isSystem: true, timestamp: Date.now() }; - if (eventObj != null && eventObj.error != null) { - msgObj.isStdErr = true; - } - // IMPORTANT: this could potentially create a memory leak if logSystemMessage - // is used too quickly but we don't want supervisor logging to hold up other tasks - void log(msgObj); - if (track) { - eventTracker.track( - eventName != null ? eventName : message, - eventObj != null ? eventObj : {}, - ); - } -} - -export function lock(containerId: string): Bluebird.Disposer<() => void> { - return takeGlobalLockRW(containerId).disposer((release) => { - release(); - }); -} - -type ServiceInfo = { serviceId: number }; -export async function attach( - containerId: string, - { serviceId }: ServiceInfo, -): Promise { - // First detect if we already have an attached log stream - // for this container - if (logMonitor.isAttached(containerId)) { - return; - } - - return Bluebird.using(lock(containerId), async () => { - await logMonitor.attach(containerId, async (message) => { - await log({ ...message, serviceId }); - }); - }); -} - -export function logSystemEvent( - logType: LogType, - obj: LogEventObject, - track: boolean = true, -): void { - let message = logType.humanName; - const objectName = objectNameForLogs(obj); - if (objectName != null) { - message += ` '${objectName}'`; - } - if (obj && obj.error != null) { - let errorMessage = obj.error.message; - if (_.isEmpty(errorMessage)) { - errorMessage = - obj.error.name !== 'Error' ? obj.error.name : 'Unknown cause'; - superConsole.warn('Invalid error message', obj.error); - } - message += ` due to '${errorMessage}'`; - } - logSystemMessage(message, obj, logType.eventName, track); -} - -export function logConfigChange( - conf: { [configName: string]: string }, - { success = false, err }: { success?: boolean; err?: Error } = {}, -) { - const obj: LogEventObject = { conf }; - let message: string; - let eventName: string; - if (success) { - message = `Applied configuration change ${JSON.stringify(conf)}`; - eventName = 'Apply config change success'; - } else if (err != null) { - message = `Error applying configuration change: ${err}`; - eventName = 'Apply config change error'; - obj.error = err; - } else { - message = `Applying configuration change ${JSON.stringify(conf)}`; - eventName = 'Apply config change in progress'; - } - - logSystemMessage(message, obj, eventName); -} - -function objectNameForLogs(eventObj: LogEventObject): string | null { - if (eventObj == null) { - return null; - } - if ( - eventObj.service != null && - eventObj.service.serviceName != null && - eventObj.service.config != null && - eventObj.service.config.image != null - ) { - return `${eventObj.service.serviceName} ${eventObj.service.config.image}`; - } - - if (eventObj.image != null) { - return eventObj.image.name; - } - - if (eventObj.network != null && eventObj.network.name != null) { - return eventObj.network.name; - } - - if (eventObj.volume != null && eventObj.volume.name != null) { - return eventObj.volume.name; - } - - if (eventObj.fields != null) { - return eventObj.fields.join(','); - } - - return null; -} diff --git a/src/logging/index.ts b/src/logging/index.ts index 30011d8f..fdb84c45 100644 --- a/src/logging/index.ts +++ b/src/logging/index.ts @@ -1,5 +1,229 @@ +import Bluebird from 'bluebird'; +import _ from 'lodash'; + +import * as config from '../config'; +import * as eventTracker from '../event-tracker'; +import type { LogType } from '../lib/log-types'; +import { takeGlobalLockRW } from '../lib/process-lock'; import { BalenaLogBackend } from './balena-backend'; import { LocalLogBackend } from './local-backend'; -import { LogBackend, LogMessage } from './log-backend'; +import type { LogBackend, LogMessage } from './log-backend'; +import logMonitor from './monitor'; -export { LocalLogBackend, LogBackend, LogMessage, BalenaLogBackend }; +import * as globalEventBus from '../event-bus'; +import superConsole from '../lib/supervisor-console'; + +type LogEventObject = Dictionary | null; + +let backend: LogBackend | null = null; +let balenaBackend: BalenaLogBackend | null = null; +let localBackend: LocalLogBackend | null = null; + +export const initialized = _.once(async () => { + await config.initialized(); + const { + apiEndpoint, + logsEndpoint, + uuid, + deviceApiKey, + unmanaged, + loggingEnabled, + localMode, + } = await config.getMany([ + 'apiEndpoint', + 'logsEndpoint', + 'uuid', + 'deviceApiKey', + 'unmanaged', + 'loggingEnabled', + 'localMode', + ]); + + balenaBackend = new BalenaLogBackend( + logsEndpoint ?? apiEndpoint, + uuid, + deviceApiKey, + ); + localBackend = new LocalLogBackend(); + backend = localMode ? localBackend : balenaBackend; + backend.unmanaged = unmanaged; + backend.publishEnabled = loggingEnabled; + + if (!balenaBackend.isInitialised()) { + globalEventBus.getInstance().once('deviceProvisioned', async () => { + const conf = await config.getMany([ + 'uuid', + 'apiEndpoint', + 'logsEndpoint', + 'deviceApiKey', + ]); + + // We use Boolean here, as deviceApiKey when unset + // is '' for legacy reasons. Once we're totally + // typescript, we can make it have a default value + // of undefined. + if (_.every(conf, Boolean)) { + // Everything is set, provide the values to the + // balenaBackend, and remove our listener + balenaBackend!.assignFields( + conf.logsEndpoint ?? conf.apiEndpoint, + conf.uuid!, + conf.deviceApiKey, + ); + } + }); + } +}); + +export function switchBackend(localMode: boolean) { + if (localMode) { + // Use the local mode backend + backend = localBackend; + superConsole.info('Switching logging backend to LocalLogBackend'); + } else { + // Use the balena backend + backend = balenaBackend; + superConsole.info('Switching logging backend to BalenaLogBackend'); + } +} + +export function getLocalBackend(): LocalLogBackend { + // TODO: Think about this interface a little better, it would be + // nicer to proxy the logs via the logger module + if (localBackend == null) { + // TODO: Type this as an internal inconsistency error + throw new Error('Local backend logger is not defined.'); + } + return localBackend; +} + +export function enable(value: boolean = true) { + if (backend != null) { + backend.publishEnabled = value; + } +} + +export async function log(message: LogMessage) { + await backend?.log(message); +} + +export function logSystemMessage( + message: string, + eventObj?: LogEventObject, + eventName?: string, + track: boolean = true, +) { + const msgObj: LogMessage = { message, isSystem: true, timestamp: Date.now() }; + if (eventObj != null && eventObj.error != null) { + msgObj.isStdErr = true; + } + // IMPORTANT: this could potentially create a memory leak if logSystemMessage + // is used too quickly but we don't want supervisor logging to hold up other tasks + void log(msgObj); + if (track) { + eventTracker.track( + eventName != null ? eventName : message, + eventObj != null ? eventObj : {}, + ); + } +} + +function lock(containerId: string): Bluebird.Disposer<() => void> { + return takeGlobalLockRW(containerId).disposer((release) => { + release(); + }); +} + +type ServiceInfo = { serviceId: number }; +export async function attach( + containerId: string, + { serviceId }: ServiceInfo, +): Promise { + // First detect if we already have an attached log stream + // for this container + if (logMonitor.isAttached(containerId)) { + return; + } + + return Bluebird.using(lock(containerId), async () => { + await logMonitor.attach(containerId, async (message) => { + await log({ ...message, serviceId }); + }); + }); +} + +export function logSystemEvent( + logType: LogType, + obj: LogEventObject, + track: boolean = true, +): void { + let message = logType.humanName; + const objectName = objectNameForLogs(obj); + if (objectName != null) { + message += ` '${objectName}'`; + } + if (obj && obj.error != null) { + let errorMessage = obj.error.message; + if (_.isEmpty(errorMessage)) { + errorMessage = + obj.error.name !== 'Error' ? obj.error.name : 'Unknown cause'; + superConsole.warn('Invalid error message', obj.error); + } + message += ` due to '${errorMessage}'`; + } + logSystemMessage(message, obj, logType.eventName, track); +} + +export function logConfigChange( + conf: { [configName: string]: string }, + { success = false, err }: { success?: boolean; err?: Error } = {}, +) { + const obj: LogEventObject = { conf }; + let message: string; + let eventName: string; + if (success) { + message = `Applied configuration change ${JSON.stringify(conf)}`; + eventName = 'Apply config change success'; + } else if (err != null) { + message = `Error applying configuration change: ${err}`; + eventName = 'Apply config change error'; + obj.error = err; + } else { + message = `Applying configuration change ${JSON.stringify(conf)}`; + eventName = 'Apply config change in progress'; + } + + logSystemMessage(message, obj, eventName); +} + +function objectNameForLogs(eventObj: LogEventObject): string | null { + if (eventObj == null) { + return null; + } + if ( + eventObj.service != null && + eventObj.service.serviceName != null && + eventObj.service.config != null && + eventObj.service.config.image != null + ) { + return `${eventObj.service.serviceName} ${eventObj.service.config.image}`; + } + + if (eventObj.image != null) { + return eventObj.image.name; + } + + if (eventObj.network != null && eventObj.network.name != null) { + return eventObj.network.name; + } + + if (eventObj.volume != null && eventObj.volume.name != null) { + return eventObj.volume.name; + } + + if (eventObj.fields != null) { + return eventObj.fields.join(','); + } + + return null; +} diff --git a/src/supervisor.ts b/src/supervisor.ts index e6581543..c12127a7 100644 --- a/src/supervisor.ts +++ b/src/supervisor.ts @@ -2,7 +2,7 @@ import * as apiBinder from './api-binder'; import * as db from './db'; import * as config from './config'; import * as deviceState from './device-state'; -import * as logger from './logger'; +import * as logger from './logging'; import SupervisorAPI from './device-api'; import * as v1 from './device-api/v1'; import * as v2 from './device-api/v2'; diff --git a/test/integration/compose/volume.spec.ts b/test/integration/compose/volume.spec.ts index 7268d3f4..cacbe551 100644 --- a/test/integration/compose/volume.spec.ts +++ b/test/integration/compose/volume.spec.ts @@ -3,7 +3,7 @@ import type { SinonStub } from 'sinon'; import { stub } from 'sinon'; import { Volume } from '~/src/compose/volume'; import * as logTypes from '~/lib/log-types'; -import * as logger from '~/src/logger'; +import * as logger from '~/src/logging'; import Docker from 'dockerode'; diff --git a/test/integration/device-config.spec.ts b/test/integration/device-config.spec.ts index c2e437b0..78dd89d6 100644 --- a/test/integration/device-config.spec.ts +++ b/test/integration/device-config.spec.ts @@ -7,7 +7,7 @@ import { expect } from 'chai'; import * as deviceConfig from '~/src/device-config'; import * as fsUtils from '~/lib/fs-utils'; -import * as logger from '~/src/logger'; +import * as logger from '~/src/logging'; import { Extlinux } from '~/src/config/backends/extlinux'; import { ConfigTxt } from '~/src/config/backends/config-txt'; import { Odmdata } from '~/src/config/backends/odmdata'; diff --git a/test/integration/lib/firewall.spec.ts b/test/integration/lib/firewall.spec.ts index d0373e4b..9f55756d 100644 --- a/test/integration/lib/firewall.spec.ts +++ b/test/integration/lib/firewall.spec.ts @@ -3,7 +3,7 @@ import { expect } from 'chai'; import sinon from 'sinon'; import * as config from '~/src/config'; -import * as logger from '~/src/logger'; +import * as logger from '~/src/logging'; import * as iptablesMock from '~/test-lib/mocked-iptables'; import * as dbFormat from '~/src/device-state/db-format'; diff --git a/test/legacy/11-logger.spec.ts b/test/legacy/11-logging.spec.ts similarity index 98% rename from test/legacy/11-logger.spec.ts rename to test/legacy/11-logging.spec.ts index f3d53472..27e25ccb 100644 --- a/test/legacy/11-logger.spec.ts +++ b/test/legacy/11-logging.spec.ts @@ -9,7 +9,7 @@ import { setTimeout } from 'timers/promises'; import * as config from '~/src/config'; describe('Logger', function () { - let logger: typeof import('~/src/logger'); + let logger: typeof import('~/src/logging'); let configStub: sinon.SinonStub; beforeEach(async function () { diff --git a/test/legacy/42-device-api-v2.spec.ts b/test/legacy/42-device-api-v2.spec.ts index afcb5829..899752dd 100644 --- a/test/legacy/42-device-api-v2.spec.ts +++ b/test/legacy/42-device-api-v2.spec.ts @@ -14,7 +14,7 @@ import * as images from '~/src/compose/images'; import * as config from '~/src/config'; import * as mockedDockerode from '~/test-lib/mocked-dockerode'; import * as applicationManager from '~/src/compose/application-manager'; -import * as logger from '~/src/logger'; +import * as logger from '~/src/logging'; describe('SupervisorAPI [V2 Endpoints]', () => { let serviceManagerMock: SinonStub; From fb6fa9b16caa33eabeb44414d4681cea52d11784 Mon Sep 17 00:00:00 2001 From: Christina Ying Wang Date: Mon, 18 Nov 2024 13:41:41 -0800 Subject: [PATCH 3/4] Add ability to stream logs from host services to cloud Add `os-power-mode.service`, `nvpmodel.service`, and `os-fan-profile.service` which report status from applying power mode and fan profile configs as read from config.json. The Supervisor sets these configs in config.json for these host services to pick up and apply. Also add host log streaming from `jetson-qspi-manager.service` as it will very soon be needed for Jetson Orins. Relates-to: #2379 See: balena-io/open-balena-api#1792 See: balena-os/balena-jetson-orin#513 Change-type: minor Signed-off-by: Christina Ying Wang --- src/lib/journald.ts | 14 ++++++-- src/logging/balena-backend.ts | 2 +- src/logging/index.ts | 5 ++- src/logging/local-backend.ts | 2 +- src/logging/log-backend.ts | 16 +-------- src/logging/monitor.ts | 66 ++++++++++++++++++++++++++++------ src/logging/types.ts | 13 +++++++ test/unit/lib/journald.spec.ts | 3 ++ 8 files changed, 90 insertions(+), 31 deletions(-) create mode 100644 src/logging/types.ts diff --git a/src/lib/journald.ts b/src/lib/journald.ts index 5079819b..4d83ece4 100644 --- a/src/lib/journald.ts +++ b/src/lib/journald.ts @@ -21,7 +21,7 @@ export interface SpawnJournalctlOpts { unit?: string; containerId?: string; format: string; - filterString?: string; + filter?: string | string[]; since?: string; until?: string; } @@ -57,8 +57,16 @@ export function spawnJournalctl(opts: SpawnJournalctlOpts): ChildProcess { args.push('-o'); args.push(opts.format); - if (opts.filterString) { - args.push(opts.filterString); + if (opts.filter != null) { + // A single filter argument without spaces can be passed as a string + if (typeof opts.filter === 'string') { + args.push(opts.filter); + } else { + // Multiple filter arguments need to be passed as an array of strings + // instead of a single string with spaces, as `spawn` will interpret + // the single string as a single argument to journalctl, which is invalid. + args.push(...opts.filter); + } } log.debug('Spawning journalctl', args.join(' ')); diff --git a/src/logging/balena-backend.ts b/src/logging/balena-backend.ts index 39f9a1d2..44df25e2 100644 --- a/src/logging/balena-backend.ts +++ b/src/logging/balena-backend.ts @@ -6,7 +6,7 @@ import url from 'url'; import zlib from 'zlib'; import { setTimeout } from 'timers/promises'; -import type { LogMessage } from './log-backend'; +import type { LogMessage } from './types'; import { LogBackend } from './log-backend'; import log from '../lib/supervisor-console'; diff --git a/src/logging/index.ts b/src/logging/index.ts index fdb84c45..8973003d 100644 --- a/src/logging/index.ts +++ b/src/logging/index.ts @@ -7,7 +7,8 @@ import type { LogType } from '../lib/log-types'; import { takeGlobalLockRW } from '../lib/process-lock'; import { BalenaLogBackend } from './balena-backend'; import { LocalLogBackend } from './local-backend'; -import type { LogBackend, LogMessage } from './log-backend'; +import type { LogBackend } from './log-backend'; +import type { LogMessage } from './types'; import logMonitor from './monitor'; import * as globalEventBus from '../event-bus'; @@ -49,6 +50,8 @@ export const initialized = _.once(async () => { backend.unmanaged = unmanaged; backend.publishEnabled = loggingEnabled; + logMonitor.attachSystemLogger(log); + if (!balenaBackend.isInitialised()) { globalEventBus.getInstance().once('deviceProvisioned', async () => { const conf = await config.getMany([ diff --git a/src/logging/local-backend.ts b/src/logging/local-backend.ts index 51a6ee78..dad0c0cb 100644 --- a/src/logging/local-backend.ts +++ b/src/logging/local-backend.ts @@ -2,7 +2,7 @@ import _ from 'lodash'; import { Readable } from 'stream'; import { checkInt } from '../lib/validation'; -import type { LogMessage } from './log-backend'; +import type { LogMessage } from './types'; import { LogBackend } from './log-backend'; import log from '../lib/supervisor-console'; diff --git a/src/logging/log-backend.ts b/src/logging/log-backend.ts index 8c7239ac..27a4ce0b 100644 --- a/src/logging/log-backend.ts +++ b/src/logging/log-backend.ts @@ -1,18 +1,4 @@ -type BaseLogMessage = { - message: string; - isStdErr?: boolean; - timestamp: number; -}; -export type LogMessage = BaseLogMessage & - ( - | { - serviceId: number; - isSystem?: false; - } - | { - isSystem: true; - } - ); +import type { LogMessage } from './types'; export abstract class LogBackend { public unmanaged: boolean; diff --git a/src/logging/monitor.ts b/src/logging/monitor.ts index a2219f72..d8424b7d 100644 --- a/src/logging/monitor.ts +++ b/src/logging/monitor.ts @@ -1,14 +1,12 @@ import { pipeline } from 'stream/promises'; +import { setTimeout } from 'timers/promises'; import { spawnJournalctl, toJournalDate } from '../lib/journald'; import log from '../lib/supervisor-console'; -import { setTimeout } from 'timers/promises'; +import type { SystemLogMessage, BaseLogMessage } from './types'; -export type MonitorHook = (message: { - message: string; - isStdErr: boolean; - timestamp: number; -}) => Resolvable; +type MonitorHook = (message: BaseLogMessage) => Promise; +type SystemMonitorHook = (message: SystemLogMessage) => Promise; // This is nowhere near the amount of fields provided by journald, but simply the ones // that we are interested in @@ -18,12 +16,25 @@ interface JournalRow { MESSAGE: string | number[]; PRIORITY: string; __REALTIME_TIMESTAMP: string; + _SYSTEMD_UNIT: string; } // Wait 5s when journalctl failed before trying to read the logs again const JOURNALCTL_ERROR_RETRY_DELAY = 5000; const JOURNALCTL_ERROR_RETRY_DELAY_MAX = 15 * 60 * 1000; +// Additional host services we want to stream the logs for +const HOST_SERVICES = [ + // Balena service which applies power mode to config file on boot + 'os-power-mode.service', + // Balena service which applies fan profile to device at runtime + 'os-fan-profile.service', + // Nvidia power daemon which logs result from applying power mode from config file to device + 'nvpmodel.service', + // Runs at boot time and checks if Orin QSPI is accessible after provisioning + 'jetson-qspi-manager.service', +]; + function messageFieldToString(entry: JournalRow['MESSAGE']): string | null { if (Array.isArray(entry)) { return String.fromCharCode(...entry); @@ -60,6 +71,9 @@ class LogMonitor { hook: MonitorHook; }; } = {}; + private systemHook: SystemMonitorHook = async () => { + /* Default empty hook */ + }; private setupAttempts = 0; // Only stream logs since the start of the supervisor @@ -72,11 +86,16 @@ class LogMonitor { all: true, follow: true, format: 'json', - filterString: '_SYSTEMD_UNIT=balena.service', + filter: [ + // Monitor logs from balenad by default for container log-streaming + 'balena.service', + // Add any host services we want to stream + ...HOST_SERVICES, + ].map((s) => `_SYSTEMD_UNIT=${s}`), since: toJournalDate(this.lastSentTimestamp), }); if (!stdout) { - // this will be catched below + // This error will be caught below throw new Error('failed to open process stream'); } @@ -96,6 +115,8 @@ class LogMonitor { self.containers[row.CONTAINER_ID_FULL] ) { await self.handleRow(row); + } else if (HOST_SERVICES.includes(row._SYSTEMD_UNIT)) { + await self.handleHostServiceRow(row); } } catch { // ignore parsing errors @@ -135,6 +156,10 @@ class LogMonitor { delete this.containers[containerId]; } + public attachSystemLogger(hook: SystemMonitorHook) { + this.systemHook = hook; + } + private async handleRow(row: JournalRow) { if ( row.CONTAINER_ID_FULL == null || @@ -151,12 +176,33 @@ class LogMonitor { if (message == null) { return; } - const isStdErr = row.PRIORITY === '3'; + const isStdErr = parseInt(row.PRIORITY, 10) <= 3; const timestamp = Math.floor(Number(row.__REALTIME_TIMESTAMP) / 1000); // microseconds to milliseconds - await this.containers[containerId].hook({ message, isStdErr, timestamp }); + await this.containers[containerId].hook({ + message, + isStdErr, + timestamp, + }); this.lastSentTimestamp = timestamp; } + + private async handleHostServiceRow( + row: JournalRow & { _SYSTEMD_UNIT: string }, + ) { + const message = messageFieldToString(row.MESSAGE); + if (message == null) { + return; + } + const isStdErr = parseInt(row.PRIORITY, 10) <= 3; + const timestamp = Math.floor(Number(row.__REALTIME_TIMESTAMP) / 1000); // microseconds to milliseconds + void this.systemHook({ + message, + isStdErr, + timestamp, + isSystem: true, + }); + } } const logMonitor = new LogMonitor(); diff --git a/src/logging/types.ts b/src/logging/types.ts new file mode 100644 index 00000000..ec3db983 --- /dev/null +++ b/src/logging/types.ts @@ -0,0 +1,13 @@ +export type BaseLogMessage = { + message: string; + isStdErr?: boolean; + timestamp: number; +}; +export type SystemLogMessage = BaseLogMessage & { + isSystem: true; +}; +type ContainerLogMessage = BaseLogMessage & { + serviceId: number; + isSystem?: false; +}; +export type LogMessage = SystemLogMessage | ContainerLogMessage; diff --git a/test/unit/lib/journald.spec.ts b/test/unit/lib/journald.spec.ts index 34c97ea5..b0eb3052 100644 --- a/test/unit/lib/journald.spec.ts +++ b/test/unit/lib/journald.spec.ts @@ -28,6 +28,7 @@ describe('lib/journald', () => { unit: 'nginx.service', containerId: 'abc123', format: 'json-pretty', + filter: ['_SYSTEMD_UNIT=test.service', '_SYSTEMD_UNIT=test2.service'], since: '2014-03-25 03:59:56.654563', until: '2014-03-25 03:59:59.654563', }); @@ -48,6 +49,8 @@ describe('lib/journald', () => { '2014-03-25 03:59:56.654563', '-U', '2014-03-25 03:59:59.654563', + '_SYSTEMD_UNIT=test.service', + '_SYSTEMD_UNIT=test2.service', ]; const actualCommand = spawn.firstCall.args[0]; From 8f3eeff72d97a24c41a31507330fb157b0cc3e9f Mon Sep 17 00:00:00 2001 From: Christina Ying Wang Date: Mon, 18 Nov 2024 14:15:55 -0800 Subject: [PATCH 4/4] Stream logs from last SV's State.FinishedAt, process uptime otherwise This will catch any container or host logs between Supervisor runs. If FinishedAt is invalid (0), the last sent timestamp is already set (i.e. this isn't the first time logMonitor.start() has been called), or the Supervisor container metadata couldn't be acquired, use the Supervisor process uptime as the default. This has the downside of missing any logs generated during SV downtime, but at least means the log-streamer can proceed without error. Signed-off-by: Christina Ying Wang --- src/logging/monitor.ts | 77 ++++++++++++++++++++++++++++++++++-------- 1 file changed, 63 insertions(+), 14 deletions(-) diff --git a/src/logging/monitor.ts b/src/logging/monitor.ts index d8424b7d..9015bb3d 100644 --- a/src/logging/monitor.ts +++ b/src/logging/monitor.ts @@ -1,8 +1,11 @@ import { pipeline } from 'stream/promises'; import { setTimeout } from 'timers/promises'; +import type { ContainerInspectInfo } from 'dockerode'; import { spawnJournalctl, toJournalDate } from '../lib/journald'; import log from '../lib/supervisor-console'; +import { docker } from '../lib/docker-utils'; +import type { SpawnJournalctlOpts } from '../lib/journald'; import type { SystemLogMessage, BaseLogMessage } from './types'; type MonitorHook = (message: BaseLogMessage) => Promise; @@ -62,6 +65,19 @@ async function* splitStream(chunkIterable: AsyncIterable) { } } +const getSupervisorContainer = + async (): Promise => { + try { + return await Promise.any([ + docker.getContainer('balena_supervisor').inspect(), + docker.getContainer('resin_supervisor').inspect(), + ]); + } catch { + // If all promises reject, return null + return null; + } + }; + /** * Streams logs from journalctl and calls container hooks when a record is received matching container id */ @@ -76,24 +92,17 @@ class LogMonitor { }; private setupAttempts = 0; - // Only stream logs since the start of the supervisor - private lastSentTimestamp = Date.now() - performance.now(); + // By default, only stream logs since the start of the Supervisor process + private lastSentTimestamp: number | null = null; public async start(): Promise { + // Get journalctl spawn options + const opts = await this.getJournalctlOptions(); + + // Spawn journalctl process to stream logs try { // TODO: do not spawn journalctl if logging is not enabled - const { stdout, stderr } = spawnJournalctl({ - all: true, - follow: true, - format: 'json', - filter: [ - // Monitor logs from balenad by default for container log-streaming - 'balena.service', - // Add any host services we want to stream - ...HOST_SERVICES, - ].map((s) => `_SYSTEMD_UNIT=${s}`), - since: toJournalDate(this.lastSentTimestamp), - }); + const { stdout, stderr } = spawnJournalctl(opts); if (!stdout) { // This error will be caught below throw new Error('failed to open process stream'); @@ -140,6 +149,46 @@ class LogMonitor { void this.start(); } + private async getJournalctlOptions(): Promise { + // On SV start, journalctl is spawned with a timestamp to only + // get logs since the last Supervisor State.FinishedAt. This will catch any + // host and container logs generated while the Supervisor was not running. + const supervisorContainer = await getSupervisorContainer(); + if (supervisorContainer !== null) { + const finishedAt = supervisorContainer.State.FinishedAt; + const finishedAtDate = new Date(finishedAt).getTime(); + // When a container has never exited with any exit code, + // the FinishedAt timestamp is "0001-01-01T00:00:00Z". Any + // timestamp below 0 in ms value is from before the epoch. + // Only set the lastSentTimestamp to the last Supervisor State.FinishedAt if: + // - finishedAtDate is greater than 0 (i.e. the supervisor container has exited at least once) + // - lastSentTimestamp is null (i.e. this is the first time we've started the monitor) + // - This prevents the case of the logs getting streamed from State.FinishedAt for + // subsequent monitor.start() calls due to the underlying journalctl process dying. + if (finishedAtDate > 0 && this.lastSentTimestamp == null) { + this.lastSentTimestamp = finishedAtDate; + } + } + + // If the conditions weren't met to set the lastSentTimestamp, use the process uptime + if (this.lastSentTimestamp == null) { + this.lastSentTimestamp = Date.now() - performance.now(); + } + + return { + all: true, + follow: true, + format: 'json', + filter: [ + // Monitor logs from balenad by default for container log-streaming + 'balena.service', + // Add any host services we want to stream + ...HOST_SERVICES, + ].map((s) => `_SYSTEMD_UNIT=${s}`), + since: toJournalDate(this.lastSentTimestamp), + }; + } + public isAttached(containerId: string): boolean { return containerId in this.containers; }