From 651e48b1bd8e9a9d356b63f8cb05aaeba622840d Mon Sep 17 00:00:00 2001 From: Cameron Diver Date: Mon, 8 Jun 2020 13:57:31 +0100 Subject: [PATCH] Make logger module a singleton Change-type: patch Signed-off-by: Cameron Diver --- src/api-binder.ts | 18 +- src/application-manager.d.ts | 8 +- src/application-manager.js | 35 +-- src/compose/images.ts | 30 +- src/compose/network-manager.ts | 21 +- src/compose/network.ts | 28 +- src/compose/service-manager.ts | 47 ++- src/compose/volume-manager.ts | 25 +- src/compose/volume.ts | 29 +- src/config/backend.ts | 34 +- src/config/utils.ts | 8 +- src/device-api/v2.ts | 3 +- src/device-config.ts | 37 +-- src/device-state.ts | 21 +- src/local-mode.ts | 5 +- src/logger.ts | 467 ++++++++++++++-------------- src/logging/balena-backend.ts | 2 +- src/proxyvisor.js | 6 +- src/supervisor.ts | 19 +- test/05-device-state.spec.ts | 6 - test/11-api-binder.spec.ts | 5 +- test/12-logger.spec.ts | 56 ++-- test/13-device-config.spec.ts | 58 ++-- test/14-application-manager.spec.ts | 15 +- test/20-compose-volume.spec.ts | 81 ++--- test/22-local-mode.spec.ts | 4 +- test/lib/mocked-device-api.ts | 6 +- 27 files changed, 447 insertions(+), 627 deletions(-) diff --git a/src/api-binder.ts b/src/api-binder.ts index 06028ff7..04854a54 100644 --- a/src/api-binder.ts +++ b/src/api-binder.ts @@ -28,8 +28,8 @@ import log from './lib/supervisor-console'; import DeviceState from './device-state'; import * as globalEventBus from './event-bus'; -import Logger from './logger'; import * as TargetState from './device-state/target-state'; +import * as logger from './logger'; // The exponential backoff starts at 15s const MINIMUM_BACKOFF_DELAY = 15000; @@ -40,10 +40,6 @@ const INTERNAL_STATE_KEYS = [ 'update_failed', ]; -export interface APIBinderConstructOpts { - logger: Logger; -} - interface Device { id: number; @@ -67,7 +63,6 @@ export class APIBinder { public router: express.Router; private deviceState: DeviceState; - private logger: Logger; public balenaApi: PinejsClientRequest | null = null; private lastReportedState: DeviceStatus = { @@ -82,9 +77,7 @@ export class APIBinder { private stateReportErrors = 0; private readyForUpdates = false; - public constructor({ logger }: APIBinderConstructOpts) { - this.logger = logger; - + public constructor() { this.router = this.createAPIBinderRouter(this); } @@ -241,12 +234,7 @@ export class APIBinder { const lines = err.message.split(/\r?\n/); lines[0] = `Could not move to new release: ${lines[0]}`; for (const line of lines) { - this.logger.logSystemMessage( - line, - {}, - 'targetStateRejection', - false, - ); + logger.logSystemMessage(line, {}, 'targetStateRejection', false); } } else { log.error(`Failed to get target state for device: ${err}`); diff --git a/src/application-manager.d.ts b/src/application-manager.d.ts index 501cfab7..5e88b3cd 100644 --- a/src/application-manager.d.ts +++ b/src/application-manager.d.ts @@ -4,7 +4,6 @@ import { Router } from 'express'; import Knex = require('knex'); import { ServiceAction } from './device-api/common'; -import { Logger } from './logger'; import { DeviceStatus, InstancedAppState } from './types/state'; import ImageManager, { Image } from './compose/images'; @@ -46,7 +45,6 @@ class ApplicationManager extends EventEmitter { // TODO: When the module which is/declares these fields is converted to // typecript, type the following public _lockingIfNecessary: any; - public logger: Logger; public deviceState: DeviceState; public apiBinder: APIBinder; @@ -63,11 +61,7 @@ class ApplicationManager extends EventEmitter { public router: Router; - public constructor({ - logger: Logger, - deviceState: DeviceState, - apiBinder: APIBinder, - }); + public constructor({ deviceState: DeviceState, apiBinder: APIBinder }); public init(): Promise; diff --git a/src/application-manager.js b/src/application-manager.js index 1b891162..c1ffddb4 100644 --- a/src/application-manager.js +++ b/src/application-manager.js @@ -9,6 +9,7 @@ import * as path from 'path'; import * as constants from './lib/constants'; import { log } from './lib/supervisor-console'; import * as config from './config'; +import * as logger from './logger'; import { validateTargetContracts } from './lib/contracts'; import { docker } from './lib/docker-utils'; @@ -79,7 +80,7 @@ const createApplicationManagerRouter = function (applications) { }; export class ApplicationManager extends EventEmitter { - constructor({ logger, deviceState, apiBinder }) { + constructor({ deviceState, apiBinder }) { super(); this.serviceAction = serviceAction; @@ -169,27 +170,17 @@ export class ApplicationManager extends EventEmitter { this.removeAllVolumesForApp = this.removeAllVolumesForApp.bind(this); this.localModeSwitchCompletion = this.localModeSwitchCompletion.bind(this); this.reportOptionalContainers = this.reportOptionalContainers.bind(this); - this.logger = logger; this.deviceState = deviceState; this.apiBinder = apiBinder; - this.images = new Images({ - logger: this.logger, - }); - this.services = new ServiceManager({ - logger: this.logger, - }); - this.networks = new NetworkManager({ - logger: this.logger, - }); - this.volumes = new VolumeManager({ - logger: this.logger, - }); + this.images = new Images(); + this.services = new ServiceManager(); + this.networks = new NetworkManager(); + this.volumes = new VolumeManager(); this.proxyvisor = new Proxyvisor({ - logger: this.logger, images: this.images, applications: this, }); - this.localModeManager = new LocalModeManager(this.logger); + this.localModeManager = new LocalModeManager(); this.timeSpentFetching = 0; this.fetchesInProgress = 0; this._targetVolatilePerImageId = {}; @@ -252,7 +243,7 @@ export class ApplicationManager extends EventEmitter { .then(() => { const cleanup = () => { return docker.listContainers({ all: true }).then((containers) => { - return this.logger.clearOutOfDateDBLogs(_.map(containers, 'Id')); + return logger.clearOutOfDateDBLogs(_.map(containers, 'Id')); }); }; // Rather than relying on removing out of date database entries when we're no @@ -1052,15 +1043,11 @@ export class ApplicationManager extends EventEmitter { } createTargetVolume(name, appId, volume) { - return Volume.fromComposeObject(name, appId, volume, { - logger: this.logger, - }); + return Volume.fromComposeObject(name, appId, volume); } createTargetNetwork(name, appId, network) { - return Network.fromComposeObject(name, appId, network, { - logger: this.logger, - }); + return Network.fromComposeObject(name, appId, network); } normaliseAndExtendAppFromDB(app) { @@ -1702,7 +1689,7 @@ export class ApplicationManager extends EventEmitter { '. ', )}`; log.info(message); - return this.logger.logSystemMessage( + return logger.logSystemMessage( message, {}, 'optionalContainerViolation', diff --git a/src/compose/images.ts b/src/compose/images.ts index 9e92905c..afad483b 100644 --- a/src/compose/images.ts +++ b/src/compose/images.ts @@ -16,7 +16,7 @@ import * as dockerUtils from '../lib/docker-utils'; import { DeltaStillProcessingError, NotFoundError } from '../lib/errors'; import * as LogTypes from '../lib/log-types'; import * as validation from '../lib/validation'; -import Logger from '../logger'; +import * as logger from '../logger'; import { ImageDownloadBackoffError } from './errors'; import log from '../lib/supervisor-console'; @@ -27,10 +27,6 @@ interface ImageEvents { type ImageEventEmitter = StrictEventEmitter; -interface ImageConstructOpts { - logger: Logger; -} - interface FetchProgressEvent { percentage: number; } @@ -57,8 +53,6 @@ type NormalisedDockerImage = Docker.ImageInfo & { }; export class Images extends (EventEmitter as new () => ImageEventEmitter) { - private logger: Logger; - public appUpdatePollInterval: number; private imageFetchFailures: Dictionary = {}; @@ -69,10 +63,8 @@ export class Images extends (EventEmitter as new () => ImageEventEmitter) { // A store of volatile state for images (e.g. download progress), indexed by imageId private volatileState: { [imageId: number]: Image } = {}; - public constructor(opts: ImageConstructOpts) { + public constructor() { super(); - - this.logger = opts.logger; } public async triggerFetch( @@ -143,7 +135,7 @@ export class Images extends (EventEmitter as new () => ImageEventEmitter) { await db.models('image').update({ dockerImageId: id }).where(image); - this.logger.logSystemEvent(LogTypes.downloadImageSuccess, { image }); + logger.logSystemEvent(LogTypes.downloadImageSuccess, { image }); success = true; delete this.imageFetchFailures[image.name]; delete this.imageFetchLastFailureTime[image.name]; @@ -152,10 +144,10 @@ export class Images extends (EventEmitter as new () => ImageEventEmitter) { // If this is a delta image pull, and the delta still hasn't finished generating, // don't show a failure message, and instead just inform the user that it's remotely // processing - this.logger.logSystemEvent(LogTypes.deltaStillProcessingError, {}); + logger.logSystemEvent(LogTypes.deltaStillProcessingError, {}); } else { this.addImageFailure(image.name); - this.logger.logSystemEvent(LogTypes.downloadImageError, { + logger.logSystemEvent(LogTypes.downloadImageError, { image, error: err, }); @@ -173,7 +165,7 @@ export class Images extends (EventEmitter as new () => ImageEventEmitter) { try { await this.removeImageIfNotNeeded(image); } catch (e) { - this.logger.logSystemEvent(LogTypes.deleteImageError, { + logger.logSystemEvent(LogTypes.deleteImageError, { image, error: e, }); @@ -439,7 +431,7 @@ export class Images extends (EventEmitter as new () => ImageEventEmitter) { await docker.getImage(image).remove({ force: true }); delete this.imageCleanupFailures[image]; } catch (e) { - this.logger.logSystemMessage( + logger.logSystemMessage( `Error cleaning up ${image}: ${e.message} - will ignore for 1 hour`, { error: e }, 'Image cleanup error', @@ -512,7 +504,7 @@ export class Images extends (EventEmitter as new () => ImageEventEmitter) { image.imageId, _.merge(_.clone(image), { status: 'Deleting' }), ); - this.logger.logSystemEvent(LogTypes.deleteImage, { image }); + logger.logSystemEvent(LogTypes.deleteImage, { image }); docker.getImage(img.dockerImageId).remove({ force: true }); removed = true; } else if (!Images.hasDigest(img.name)) { @@ -549,7 +541,7 @@ export class Images extends (EventEmitter as new () => ImageEventEmitter) { await db.models('image').del().where({ id: img.id }); if (removed) { - this.logger.logSystemEvent(LogTypes.deleteImageSuccess, { image }); + logger.logSystemEvent(LogTypes.deleteImageSuccess, { image }); } } @@ -584,7 +576,7 @@ export class Images extends (EventEmitter as new () => ImageEventEmitter) { onProgress: (evt: FetchProgressEvent) => void, serviceName: string, ): Promise { - this.logger.logSystemEvent(LogTypes.downloadImageDelta, { image }); + logger.logSystemEvent(LogTypes.downloadImageDelta, { image }); const deltaOpts = (opts as unknown) as DeltaFetchOptions; const srcImage = await this.inspectByName(deltaOpts.deltaSource); @@ -610,7 +602,7 @@ export class Images extends (EventEmitter as new () => ImageEventEmitter) { opts: FetchOptions, onProgress: (evt: FetchProgressEvent) => void, ): Promise { - this.logger.logSystemEvent(LogTypes.downloadImage, { image }); + logger.logSystemEvent(LogTypes.downloadImage, { image }); return dockerUtils.fetchImageWithProgress(image.name, opts, onProgress); } diff --git a/src/compose/network-manager.ts b/src/compose/network-manager.ts index f9f88046..b5fe3c45 100644 --- a/src/compose/network-manager.ts +++ b/src/compose/network-manager.ts @@ -6,31 +6,20 @@ import * as constants from '../lib/constants'; import { docker } from '../lib/docker-utils'; import { ENOENT, NotFoundError } from '../lib/errors'; import logTypes = require('../lib/log-types'); -import { Logger } from '../logger'; -import { Network, NetworkOptions } from './network'; +import * as logger from '../logger'; +import { Network } from './network'; import log from '../lib/supervisor-console'; import { ResourceRecreationAttemptError } from './errors'; export class NetworkManager { - private logger: Logger; - - constructor(opts: NetworkOptions) { - this.logger = opts.logger; - } - public getAll(): Bluebird { return this.getWithBothLabels().map((network: { Name: string }) => { return docker .getNetwork(network.Name) .inspect() .then((net) => { - return Network.fromDockerNetwork( - { - logger: this.logger, - }, - net, - ); + return Network.fromDockerNetwork(net); }); }); } @@ -43,7 +32,7 @@ export class NetworkManager { const dockerNet = await docker .getNetwork(Network.generateDockerName(network.appId, network.name)) .inspect(); - return Network.fromDockerNetwork({ logger: this.logger }, dockerNet); + return Network.fromDockerNetwork(dockerNet); } public async create(network: Network) { @@ -60,7 +49,7 @@ export class NetworkManager { // already created, we can skip this } catch (e) { if (!NotFoundError(e)) { - this.logger.logSystemEvent(logTypes.createNetworkError, { + logger.logSystemEvent(logTypes.createNetworkError, { network: { name: network.name, appId: network.appId }, error: e, }); diff --git a/src/compose/network.ts b/src/compose/network.ts index b922c60c..e809233f 100644 --- a/src/compose/network.ts +++ b/src/compose/network.ts @@ -5,7 +5,7 @@ import { docker } from '../lib/docker-utils'; import { InvalidAppIdError } from '../lib/errors'; import logTypes = require('../lib/log-types'); import { checkInt } from '../lib/validation'; -import { Logger } from '../logger'; +import * as logger from '../logger'; import * as ComposeUtils from './utils'; import { @@ -21,26 +21,15 @@ import { InvalidNetworkNameError, } from './errors'; -export interface NetworkOptions { - logger: Logger; -} - export class Network { public appId: number; public name: string; public config: NetworkConfig; - private logger: Logger; + private constructor() {} - private constructor(opts: NetworkOptions) { - this.logger = opts.logger; - } - - public static fromDockerNetwork( - opts: NetworkOptions, - network: NetworkInspect, - ): Network { - const ret = new Network(opts); + public static fromDockerNetwork(network: NetworkInspect): Network { + const ret = new Network(); const match = network.Name.match(/^([0-9]+)_(.+)$/); if (match == null) { @@ -94,9 +83,8 @@ export class Network { network: Partial> & { ipam?: Partial; }, - opts: NetworkOptions, ): Network { - const net = new Network(opts); + const net = new Network(); net.name = name; net.appId = appId; @@ -138,7 +126,7 @@ export class Network { } public async create(): Promise { - this.logger.logSystemEvent(logTypes.createNetwork, { + logger.logSystemEvent(logTypes.createNetwork, { network: { name: this.name }, }); @@ -183,7 +171,7 @@ export class Network { } public remove(): Bluebird { - this.logger.logSystemEvent(logTypes.removeNetwork, { + logger.logSystemEvent(logTypes.removeNetwork, { network: { name: this.name, appId: this.appId }, }); @@ -192,7 +180,7 @@ export class Network { .getNetwork(Network.generateDockerName(this.appId, this.name)) .remove(), ).tapCatch((error) => { - this.logger.logSystemEvent(logTypes.removeNetworkError, { + logger.logSystemEvent(logTypes.removeNetworkError, { network: { name: this.name, appId: this.appId }, error, }); diff --git a/src/compose/service-manager.ts b/src/compose/service-manager.ts index 055ceb15..814fd452 100644 --- a/src/compose/service-manager.ts +++ b/src/compose/service-manager.ts @@ -9,7 +9,7 @@ import StrictEventEmitter from 'strict-event-emitter-types'; import * as config from '../config'; import { docker } from '../lib/docker-utils'; -import Logger from '../logger'; +import * as logger from '../logger'; import { PermissiveNumber } from '../config/types'; import constants = require('../lib/constants'); @@ -25,10 +25,6 @@ import { serviceNetworksToDockerNetworks } from './utils'; import log from '../lib/supervisor-console'; -interface ServiceConstructOpts { - logger: Logger; -} - interface ServiceManagerEvents { change: void; } @@ -43,8 +39,6 @@ interface KillOpts { } export class ServiceManager extends (EventEmitter as new () => ServiceManagerEventEmitter) { - private logger: Logger; - // Whether a container has died, indexed by ID private containerHasDied: Dictionary = {}; private listening = false; @@ -52,9 +46,8 @@ export class ServiceManager extends (EventEmitter as new () => ServiceManagerEve // we don't yet have an id) private volatileState: Dictionary> = {}; - public constructor(opts: ServiceConstructOpts) { + public constructor() { super(); - this.logger = opts.logger; } public async getAll( @@ -199,7 +192,7 @@ export class ServiceManager extends (EventEmitter as new () => ServiceManagerEve } public async remove(service: Service) { - this.logger.logSystemEvent(LogTypes.removeDeadService, { service }); + logger.logSystemEvent(LogTypes.removeDeadService, { service }); const existingService = await this.get(service); if (existingService.containerId == null) { @@ -214,7 +207,7 @@ export class ServiceManager extends (EventEmitter as new () => ServiceManagerEve .remove({ v: true }); } catch (e) { if (!NotFoundError(e)) { - this.logger.logSystemEvent(LogTypes.removeDeadServiceError, { + logger.logSystemEvent(LogTypes.removeDeadServiceError, { service, error: e, }); @@ -244,7 +237,7 @@ export class ServiceManager extends (EventEmitter as new () => ServiceManagerEve return docker.getContainer(existing.containerId); } catch (e) { if (!NotFoundError(e)) { - this.logger.logSystemEvent(LogTypes.installServiceError, { + logger.logSystemEvent(LogTypes.installServiceError, { service, error: e, }); @@ -274,7 +267,7 @@ export class ServiceManager extends (EventEmitter as new () => ServiceManagerEve service.extraNetworksToJoin(), ); - this.logger.logSystemEvent(LogTypes.installService, { service }); + logger.logSystemEvent(LogTypes.installService, { service }); this.reportNewStatus(mockContainerId, service, 'Installing'); const container = await docker.createContainer(conf); @@ -289,7 +282,7 @@ export class ServiceManager extends (EventEmitter as new () => ServiceManagerEve ), ); - this.logger.logSystemEvent(LogTypes.installServiceSuccess, { service }); + logger.logSystemEvent(LogTypes.installServiceSuccess, { service }); return container; } finally { this.reportChange(mockContainerId); @@ -303,7 +296,7 @@ export class ServiceManager extends (EventEmitter as new () => ServiceManagerEve try { const container = await this.create(service); containerId = container.id; - this.logger.logSystemEvent(LogTypes.startService, { service }); + logger.logSystemEvent(LogTypes.startService, { service }); this.reportNewStatus(containerId, service, 'Starting'); @@ -348,7 +341,7 @@ export class ServiceManager extends (EventEmitter as new () => ServiceManagerEve if (remove) { // If starting the container fialed, we remove it so that it doesn't litter await container.remove({ v: true }).catch(_.noop); - this.logger.logSystemEvent(LogTypes.startServiceError, { + logger.logSystemEvent(LogTypes.startServiceError, { service, error: err, }); @@ -363,10 +356,10 @@ export class ServiceManager extends (EventEmitter as new () => ServiceManagerEve ); } - this.logger.attach(container.id, { serviceId, imageId }); + logger.attach(container.id, { serviceId, imageId }); if (!alreadyStarted) { - this.logger.logSystemEvent(LogTypes.startServiceSuccess, { service }); + logger.logSystemEvent(LogTypes.startServiceSuccess, { service }); } service.config.running = true; @@ -410,14 +403,14 @@ export class ServiceManager extends (EventEmitter as new () => ServiceManagerEve if (service != null) { this.emit('change'); if (status === 'die') { - this.logger.logSystemEvent(LogTypes.serviceExit, { service }); + logger.logSystemEvent(LogTypes.serviceExit, { service }); this.containerHasDied[data.id] = true; } else if ( status === 'start' && this.containerHasDied[data.id] ) { delete this.containerHasDied[data.id]; - this.logger.logSystemEvent(LogTypes.serviceRestart, { + logger.logSystemEvent(LogTypes.serviceRestart, { service, }); @@ -428,7 +421,7 @@ export class ServiceManager extends (EventEmitter as new () => ServiceManagerEve `serviceId and imageId not defined for service: ${service.serviceName} in ServiceManager.listenToEvents`, ); } - this.logger.attach(data.id, { + logger.attach(data.id, { serviceId, imageId, }); @@ -481,7 +474,7 @@ export class ServiceManager extends (EventEmitter as new () => ServiceManagerEve `containerId not defined for service: ${service.serviceName} in ServiceManager.attachToRunning`, ); } - this.logger.attach(service.containerId, { + logger.attach(service.containerId, { serviceId, imageId, }); @@ -533,7 +526,7 @@ export class ServiceManager extends (EventEmitter as new () => ServiceManagerEve // TODO: Remove the need for the wait flag return Bluebird.try(() => { - this.logger.logSystemEvent(LogTypes.stopService, { service }); + logger.logSystemEvent(LogTypes.stopService, { service }); if (service.imageId != null) { this.reportNewStatus(containerId, service, 'Stopping'); } @@ -558,14 +551,14 @@ export class ServiceManager extends (EventEmitter as new () => ServiceManagerEve // 304 means the container was already stopped, so we can just remove it if (statusCode === 304) { - this.logger.logSystemEvent(LogTypes.stopServiceNoop, { service }); + logger.logSystemEvent(LogTypes.stopServiceNoop, { service }); // Why do we attempt to remove the container again? if (removeContainer) { return containerObj.remove({ v: true }); } } else if (statusCode === 404) { // 404 means the container doesn't exist, precisely what we want! - this.logger.logSystemEvent(LogTypes.stopRemoveServiceNoop, { + logger.logSystemEvent(LogTypes.stopRemoveServiceNoop, { service, }); } else { @@ -574,10 +567,10 @@ export class ServiceManager extends (EventEmitter as new () => ServiceManagerEve }) .tap(() => { delete this.containerHasDied[containerId]; - this.logger.logSystemEvent(LogTypes.stopServiceSuccess, { service }); + logger.logSystemEvent(LogTypes.stopServiceSuccess, { service }); }) .catch((e) => { - this.logger.logSystemEvent(LogTypes.stopServiceError, { + logger.logSystemEvent(LogTypes.stopServiceError, { service, error: e, }); diff --git a/src/compose/volume-manager.ts b/src/compose/volume-manager.ts index 919691a9..8a3d88c4 100644 --- a/src/compose/volume-manager.ts +++ b/src/compose/volume-manager.ts @@ -8,38 +8,25 @@ import { safeRename } from '../lib/fs-utils'; import { docker } from '../lib/docker-utils'; import * as LogTypes from '../lib/log-types'; import { defaultLegacyVolume } from '../lib/migration'; -import Logger from '../logger'; +import * as logger from '../logger'; import { ResourceRecreationAttemptError } from './errors'; import Volume, { VolumeConfig } from './volume'; -export interface VolumeMangerConstructOpts { - logger: Logger; -} - export interface VolumeNameOpts { name: string; appId: number; } export class VolumeManager { - private logger: Logger; - - public constructor(opts: VolumeMangerConstructOpts) { - this.logger = opts.logger; - } - public async get({ name, appId }: VolumeNameOpts): Promise { return Volume.fromDockerVolume( - { logger: this.logger }, await docker.getVolume(Volume.generateDockerName(appId, name)).inspect(), ); } public async getAll(): Promise { const volumeInspect = await this.listWithBothLabels(); - return volumeInspect.map((inspect) => - Volume.fromDockerVolume({ logger: this.logger }, inspect), - ); + return volumeInspect.map((inspect) => Volume.fromDockerVolume(inspect)); } public async getAllByAppId(appId: number): Promise { @@ -61,7 +48,7 @@ export class VolumeManager { } } catch (e) { if (!NotFoundError(e)) { - this.logger.logSystemEvent(LogTypes.createVolumeError, { + logger.logSystemEvent(LogTypes.createVolumeError, { volume: { name: volume.name }, error: e, }); @@ -89,7 +76,7 @@ export class VolumeManager { try { return await this.createFromPath({ name, appId }, {}, legacyPath); } catch (e) { - this.logger.logSystemMessage( + logger.logSystemMessage( `Warning: could not migrate legacy /data volume: ${e.message}`, { error: e }, 'Volume migration error', @@ -102,9 +89,7 @@ export class VolumeManager { config: Partial, oldPath: string, ): Promise { - const volume = Volume.fromComposeObject(name, appId, config, { - logger: this.logger, - }); + const volume = Volume.fromComposeObject(name, appId, config); await this.create(volume); const inspect = await docker diff --git a/src/compose/volume.ts b/src/compose/volume.ts index 261107ef..3291acb2 100644 --- a/src/compose/volume.ts +++ b/src/compose/volume.ts @@ -8,13 +8,9 @@ import { docker } from '../lib/docker-utils'; import { InternalInconsistencyError } from '../lib/errors'; import * as LogTypes from '../lib/log-types'; import { LabelObject } from '../lib/types'; -import Logger from '../logger'; +import * as logger from '../logger'; import * as ComposeUtils from './utils'; -export interface VolumeConstructOpts { - logger: Logger; -} - export interface VolumeConfig { labels: LabelObject; driver: string; @@ -28,21 +24,13 @@ export interface ComposeVolumeConfig { } export class Volume { - private logger: Logger; - private constructor( public name: string, public appId: number, public config: VolumeConfig, - opts: VolumeConstructOpts, - ) { - this.logger = opts.logger; - } + ) {} - public static fromDockerVolume( - opts: VolumeConstructOpts, - inspect: Docker.VolumeInspectInfo, - ): Volume { + public static fromDockerVolume(inspect: Docker.VolumeInspectInfo): Volume { // Convert the docker inspect to the config const config: VolumeConfig = { labels: inspect.Labels || {}, @@ -53,14 +41,13 @@ export class Volume { // Detect the name and appId from the inspect data const { name, appId } = this.deconstructDockerName(inspect.Name); - return new Volume(name, appId, config, opts); + return new Volume(name, appId, config); } public static fromComposeObject( name: string, appId: number, config: Partial, - opts: VolumeConstructOpts, ) { const filledConfig: VolumeConfig = { driverOpts: config.driver_opts || {}, @@ -72,7 +59,7 @@ export class Volume { // get it from the daemon, they should already be there assign(filledConfig.labels, constants.defaultVolumeLabels); - return new Volume(name, appId, filledConfig, opts); + return new Volume(name, appId, filledConfig); } public toComposeObject(): ComposeVolumeConfig { @@ -95,7 +82,7 @@ export class Volume { } public async create(): Promise { - this.logger.logSystemEvent(LogTypes.createVolume, { + logger.logSystemEvent(LogTypes.createVolume, { volume: { name: this.name }, }); await docker.createVolume({ @@ -107,7 +94,7 @@ export class Volume { } public async remove(): Promise { - this.logger.logSystemEvent(LogTypes.removeVolume, { + logger.logSystemEvent(LogTypes.removeVolume, { volume: { name: this.name }, }); @@ -116,7 +103,7 @@ export class Volume { .getVolume(Volume.generateDockerName(this.appId, this.name)) .remove(); } catch (e) { - this.logger.logSystemEvent(LogTypes.removeVolumeError, { + logger.logSystemEvent(LogTypes.removeVolumeError, { volume: { name: this.name, appId: this.appId }, error: e, }); diff --git a/src/config/backend.ts b/src/config/backend.ts index 3802c8a4..acf40f86 100644 --- a/src/config/backend.ts +++ b/src/config/backend.ts @@ -6,7 +6,7 @@ import * as constants from '../lib/constants'; import { writeFileAtomic } from '../lib/fs-utils'; import log from '../lib/supervisor-console'; -import Logger from '../logger'; +import * as logger from '../logger'; export interface ConfigOptions { [key: string]: string | string[]; @@ -34,13 +34,7 @@ async function remountAndWriteAtomic( await writeFileAtomic(file, data); } -export interface BackendOptions { - logger?: Logger; -} - export abstract class DeviceConfigBackend { - protected options: BackendOptions = {}; - // Does this config backend support the given device type? public abstract matches(deviceType: string): boolean; @@ -74,8 +68,7 @@ export abstract class DeviceConfigBackend { public abstract createConfigVarName(configName: string): string; // Allow a chosen config backend to be initialised - public async initialise(opts: BackendOptions): Promise { - this.options = { ...this.options, ...opts }; + public async initialise(): Promise { return this; } } @@ -484,8 +477,8 @@ export class ConfigfsConfigBackend extends DeviceConfigBackend { // log to system log if the AML doesn't exist... if (!(await fs.exists(amlSrcPath))) { log.error(`Missing AML for \'${aml}\'. Unable to load.`); - if (this.options.logger) { - this.options.logger.logSystemMessage( + if (logger) { + logger.logSystemMessage( `Missing AML for \'${aml}\'. Unable to load.`, { aml, path: amlSrcPath }, 'Load AML error', @@ -555,11 +548,9 @@ export class ConfigfsConfigBackend extends DeviceConfigBackend { } } - public async initialise( - opts: BackendOptions, - ): Promise { + public async initialise(): Promise { try { - await super.initialise(opts); + await super.initialise(); // load the acpi_configfs module... await child_process.exec('modprobe acpi_configfs'); @@ -575,13 +566,12 @@ export class ConfigfsConfigBackend extends DeviceConfigBackend { log.success('Initialised ConfigFS'); } catch (error) { log.error(error); - if (this.options.logger) { - this.options.logger.logSystemMessage( - 'Unable to initialise ConfigFS', - { error }, - 'ConfigFS initialisation error', - ); - } + await logger.initialized; + logger.logSystemMessage( + 'Unable to initialise ConfigFS', + { error }, + 'ConfigFS initialisation error', + ); } return this; } diff --git a/src/config/utils.ts b/src/config/utils.ts index 271d36b0..30a72afe 100644 --- a/src/config/utils.ts +++ b/src/config/utils.ts @@ -2,7 +2,6 @@ import * as _ from 'lodash'; import { EnvVarObject } from '../lib/types'; import { - BackendOptions, ConfigfsConfigBackend, ConfigOptions, DeviceConfigBackend, @@ -16,13 +15,10 @@ const configBackends = [ new ConfigfsConfigBackend(), ]; -export const initialiseConfigBackend = async ( - deviceType: string, - opts: BackendOptions, -) => { +export const initialiseConfigBackend = async (deviceType: string) => { const backend = getConfigBackend(deviceType); if (backend) { - await backend.initialise(opts); + await backend.initialise(); return backend; } }; diff --git a/src/device-api/v2.ts b/src/device-api/v2.ts index df8d101b..28356610 100644 --- a/src/device-api/v2.ts +++ b/src/device-api/v2.ts @@ -7,6 +7,7 @@ import { Service } from '../compose/service'; import Volume from '../compose/volume'; import * as config from '../config'; import * as db from '../db'; +import * as logger from '../logger'; import { spawnJournalctl } from '../lib/journald'; import { appNotFoundMessage, @@ -323,7 +324,7 @@ export function createV2Api(router: Router, applications: ApplicationManager) { router.get('/v2/local/logs', async (_req, res) => { const serviceNameCache: { [sId: number]: string } = {}; - const backend = applications.logger.getLocalBackend(); + const backend = logger.getLocalBackend(); // Cache the service names to IDs per call to the endpoint backend.assignServiceNameResolver(async (id: number) => { if (id in serviceNameCache) { diff --git a/src/device-config.ts b/src/device-config.ts index 4934d1a9..dfbab1a9 100644 --- a/src/device-config.ts +++ b/src/device-config.ts @@ -4,7 +4,7 @@ import { inspect } from 'util'; import * as config from './config'; import { SchemaTypeKey } from './config/schema-type'; import * as db from './db'; -import Logger from './logger'; +import * as logger from './logger'; import { ConfigOptions, DeviceConfigBackend } from './config/backend'; import * as configUtils from './config/utils'; @@ -16,10 +16,6 @@ import { DeviceStatus } from './types/state'; const vpnServiceName = 'openvpn'; -interface DeviceConfigConstructOpts { - logger: Logger; -} - interface ConfigOption { envVarName: string; varType: string; @@ -55,7 +51,6 @@ interface DeviceActionExecutors { } export class DeviceConfig { - private logger: Logger; private rebootRequired = false; private actionExecutors: DeviceActionExecutors; private configBackend: DeviceConfigBackend | null = null; @@ -146,14 +141,12 @@ export class DeviceConfig { }, }; - public constructor({ logger }: DeviceConfigConstructOpts) { - this.logger = logger; - + public constructor() { this.actionExecutors = { changeConfig: async (step) => { try { if (step.humanReadableTarget) { - this.logger.logConfigChange(step.humanReadableTarget); + logger.logConfigChange(step.humanReadableTarget); } if (!_.isObject(step.target)) { throw new Error('Non-dictionary value passed to changeConfig'); @@ -162,7 +155,7 @@ export class DeviceConfig { // work out and we don't need this cast to any await config.set(step.target as { [key in SchemaTypeKey]: any }); if (step.humanReadableTarget) { - this.logger.logConfigChange(step.humanReadableTarget, { + logger.logConfigChange(step.humanReadableTarget, { success: true, }); } @@ -171,7 +164,7 @@ export class DeviceConfig { } } catch (err) { if (step.humanReadableTarget) { - this.logger.logConfigChange(step.humanReadableTarget, { + logger.logConfigChange(step.humanReadableTarget, { err, }); } @@ -185,15 +178,15 @@ export class DeviceConfig { } const logValue = { SUPERVISOR_VPN_CONTROL: step.target }; if (!initial) { - this.logger.logConfigChange(logValue); + logger.logConfigChange(logValue); } try { await this.setVPNEnabled(step.target); if (!initial) { - this.logger.logConfigChange(logValue, { success: true }); + logger.logConfigChange(logValue, { success: true }); } } catch (err) { - this.logger.logConfigChange(logValue, { err }); + logger.logConfigChange(logValue, { err }); throw err; } }, @@ -218,9 +211,7 @@ export class DeviceConfig { } const dt = await config.get('deviceType'); this.configBackend = - (await configUtils.initialiseConfigBackend(dt, { - logger: this.logger, - })) ?? null; + (await configUtils.initialiseConfigBackend(dt)) ?? null; return this.configBackend; } @@ -350,7 +341,7 @@ export class DeviceConfig { if (!configBackend!.isSupportedConfig(key)) { if (currentBootConfig[key] !== value) { const err = `Attempt to change blacklisted config value ${key}`; - this.logger.logSystemMessage( + logger.logSystemMessage( err, { error: err }, 'Apply boot config error', @@ -419,7 +410,7 @@ export class DeviceConfig { const message = `Warning: Ignoring invalid device configuration value for ${key}, value: ${inspect( target[envVarName], )}. Falling back to default (${defaultValue})`; - this.logger.logSystemMessage( + logger.logSystemMessage( message, { key: envVarName, value: target[envVarName] }, 'invalidDeviceConfig', @@ -532,7 +523,7 @@ export class DeviceConfig { } const conf = configUtils.envToBootConfig(backend, target); - this.logger.logSystemMessage( + logger.logSystemMessage( `Applying boot config: ${JSON.stringify(conf)}`, {}, 'Apply boot config in progress', @@ -543,7 +534,7 @@ export class DeviceConfig { try { await backend.setBootConfig(conf); - this.logger.logSystemMessage( + logger.logSystemMessage( `Applied boot config: ${JSON.stringify(conf)}`, {}, 'Apply boot config success', @@ -551,7 +542,7 @@ export class DeviceConfig { this.rebootRequired = true; return true; } catch (err) { - this.logger.logSystemMessage( + logger.logSystemMessage( `Error setting boot config: ${err}`, { error: err }, 'Apply boot config error', diff --git a/src/device-state.ts b/src/device-state.ts index 41e400d1..8d9b8de8 100644 --- a/src/device-state.ts +++ b/src/device-state.ts @@ -10,7 +10,7 @@ import prettyMs = require('pretty-ms'); import * as config from './config'; import * as db from './db'; -import Logger from './logger'; +import * as logger from './logger'; import { CompositionStep, @@ -176,7 +176,6 @@ function createDeviceStateRouter(deviceState: DeviceState) { } interface DeviceStateConstructOpts { - logger: Logger; apiBinder: APIBinder; } @@ -216,8 +215,6 @@ type DeviceStateStep = | ConfigStep; export class DeviceState extends (EventEmitter as new () => DeviceStateEventEmitter) { - public logger: Logger; - public applications: ApplicationManager; public deviceConfig: DeviceConfig; @@ -239,14 +236,10 @@ export class DeviceState extends (EventEmitter as new () => DeviceStateEventEmit public connected: boolean; public router: express.Router; - constructor({ logger, apiBinder }: DeviceStateConstructOpts) { + constructor({ apiBinder }: DeviceStateConstructOpts) { super(); - this.logger = logger; - this.deviceConfig = new DeviceConfig({ - logger: this.logger, - }); + this.deviceConfig = new DeviceConfig(); this.applications = new ApplicationManager({ - logger: this.logger, deviceState: this, apiBinder, }); @@ -306,7 +299,7 @@ export class DeviceState extends (EventEmitter as new () => DeviceStateEventEmit public async init() { config.on('change', (changedConfig) => { if (changedConfig.loggingEnabled != null) { - this.logger.enable(changedConfig.loggingEnabled); + logger.enable(changedConfig.loggingEnabled); } if (changedConfig.apiSecret != null) { this.reportCurrentState({ api_secret: changedConfig.apiSecret }); @@ -551,7 +544,7 @@ export class DeviceState extends (EventEmitter as new () => DeviceStateEventEmit private async reboot(force?: boolean, skipLock?: boolean) { await this.applications.stopAll({ force, skipLock }); - this.logger.logSystemMessage('Rebooting', {}, 'Reboot'); + logger.logSystemMessage('Rebooting', {}, 'Reboot'); const reboot = await dbus.reboot(); this.shuttingDown = true; this.emitAsync('shutdown', undefined); @@ -560,7 +553,7 @@ export class DeviceState extends (EventEmitter as new () => DeviceStateEventEmit private async shutdown(force?: boolean, skipLock?: boolean) { await this.applications.stopAll({ force, skipLock }); - this.logger.logSystemMessage('Shutting down', {}, 'Shutdown'); + logger.logSystemMessage('Shutting down', {}, 'Shutdown'); const shutdown = await dbus.shutdown(); this.shuttingDown = true; this.emitAsync('shutdown', undefined); @@ -670,7 +663,7 @@ export class DeviceState extends (EventEmitter as new () => DeviceStateEventEmit const message = `Updates are locked, retrying in ${prettyMs(delay, { compact: true, })}...`; - this.logger.logSystemMessage(message, {}, 'updateLocked', false); + logger.logSystemMessage(message, {}, 'updateLocked', false); log.info(message); } else { log.error( diff --git a/src/local-mode.ts b/src/local-mode.ts index 611006e1..4d21dc05 100644 --- a/src/local-mode.ts +++ b/src/local-mode.ts @@ -7,7 +7,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 { Logger } from './logger'; +import * as logger from './logger'; // 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. @@ -71,7 +71,6 @@ const SUPERVISOR_CONTAINER_NAME_FALLBACK = 'resin_supervisor'; */ export class LocalModeManager { public constructor( - public logger: Logger, private containerId: string | undefined = constants.containerId, ) {} @@ -85,7 +84,7 @@ export class LocalModeManager { const local = changed.localMode || false; // First switch the logger to it's correct state - this.logger.switchBackend(local); + logger.switchBackend(local); this.startLocalModeChangeHandling(local); } diff --git a/src/logger.ts b/src/logger.ts index 237f8756..9f178e36 100644 --- a/src/logger.ts +++ b/src/logger.ts @@ -16,261 +16,252 @@ import { import LogMonitor from './logging/monitor'; import * as globalEventBus from './event-bus'; -import log from './lib/supervisor-console'; - -interface LoggerSetupOptions { - apiEndpoint: config.ConfigType<'apiEndpoint'>; - uuid: config.ConfigType<'uuid'>; - deviceApiKey: config.ConfigType<'deviceApiKey'>; - unmanaged: config.ConfigType<'unmanaged'>; - localMode: config.ConfigType<'localMode'>; - - enableLogs: boolean; -} +import superConsole from './lib/supervisor-console'; type LogEventObject = Dictionary | null; -export class Logger { - private backend: LogBackend | null = null; - private balenaBackend: BalenaLogBackend | null = null; - private localBackend: LocalLogBackend | null = null; +// export class Logger { +let backend: LogBackend | null = null; +let balenaBackend: BalenaLogBackend | null = null; +let localBackend: LocalLogBackend | null = null; - private containerLogs: { [containerId: string]: ContainerLogs } = {}; - private logMonitor: LogMonitor; +const containerLogs: { [containerId: string]: ContainerLogs } = {}; +const logMonitor = new LogMonitor(); - public constructor() { - this.backend = null; - this.logMonitor = new LogMonitor(); - } - - public init({ +export const initialized = (async () => { + await config.initialized; + const { apiEndpoint, uuid, deviceApiKey, unmanaged, - enableLogs, + loggingEnabled, localMode, - }: LoggerSetupOptions) { - this.balenaBackend = new BalenaLogBackend(apiEndpoint, uuid, deviceApiKey); - this.localBackend = new LocalLogBackend(); + } = await config.getMany([ + 'apiEndpoint', + 'uuid', + 'deviceApiKey', + 'unmanaged', + 'loggingEnabled', + 'localMode', + ]); - this.backend = localMode ? this.localBackend : this.balenaBackend; + balenaBackend = new BalenaLogBackend(apiEndpoint, uuid, deviceApiKey); + localBackend = new LocalLogBackend(); + backend = localMode ? localBackend : balenaBackend; + backend.unmanaged = unmanaged; + backend.publishEnabled = loggingEnabled; - this.backend.unmanaged = unmanaged; - this.backend.publishEnabled = enableLogs; + if (!balenaBackend.isInitialised()) { + globalEventBus.getInstance().once('deviceProvisioned', async () => { + const conf = await config.getMany([ + 'uuid', + 'apiEndpoint', + 'deviceApiKey', + ]); - // Only setup a config listener if we have to - if (!this.balenaBackend.isIntialised()) { - globalEventBus.getInstance().once('deviceProvisioned', async () => { - const conf = await config.getMany([ - 'uuid', - 'apiEndpoint', - '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 - this.balenaBackend!.assignFields( - conf.apiEndpoint, - conf.uuid!, - conf.deviceApiKey, - ); - } - }); - } - } - - public switchBackend(localMode: boolean) { - if (localMode) { - // Use the local mode backend - this.backend = this.localBackend; - log.info('Switching logging backend to LocalLogBackend'); - } else { - // Use the balena backend - this.backend = this.balenaBackend; - log.info('Switching logging backend to BalenaLogBackend'); - } - } - - public getLocalBackend(): LocalLogBackend { - // TODO: Think about this interface a little better, it would be - // nicer to proxy the logs via the logger module - if (this.localBackend == null) { - // TODO: Type this as an internal inconsistency error - throw new Error('Local backend logger is not defined.'); - } - return this.localBackend; - } - - public enable(value: boolean = true) { - if (this.backend != null) { - this.backend.publishEnabled = value; - } - } - - public logDependent(message: LogMessage, device: { uuid: string }) { - if (this.backend != null) { - message.uuid = device.uuid; - this.backend.log(message); - } - } - - public log(message: LogMessage) { - if (this.backend != null) { - this.backend.log(message); - } - } - - public logSystemMessage( - message: string, - eventObj?: LogEventObject, - eventName?: string, - track: boolean = true, - ) { - const msgObj: LogMessage = { message, isSystem: true }; - if (eventObj != null && eventObj.error != null) { - msgObj.isStdErr = true; - } - this.log(msgObj); - if (track) { - eventTracker.track( - eventName != null ? eventName : message, - eventObj != null ? eventObj : {}, - ); - } - } - - public lock(containerId: string): Bluebird.Disposer<() => void> { - return writeLock(containerId).disposer((release) => { - release(); - }); - } - - public attach( - containerId: string, - serviceInfo: { serviceId: number; imageId: number }, - ): Bluebird { - // First detect if we already have an attached log stream - // for this container - if (containerId in this.containerLogs) { - return Bluebird.resolve(); - } - - return Bluebird.using(this.lock(containerId), async () => { - const logs = new ContainerLogs(containerId); - this.containerLogs[containerId] = logs; - logs.on('error', (err) => { - log.error('Container log retrieval error', err); - delete this.containerLogs[containerId]; - }); - logs.on('log', async (logMessage) => { - this.log(_.merge({}, serviceInfo, logMessage)); - - // Take the timestamp and set it in the database as the last - // log sent for this - this.logMonitor.updateContainerSentTimestamp( - containerId, - logMessage.timestamp, + // 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.apiEndpoint, + conf.uuid!, + conf.deviceApiKey, ); - }); - - logs.on('closed', () => delete this.containerLogs[containerId]); - - const lastSentTimestamp = await this.logMonitor.getContainerSentTimestamp( - containerId, - ); - return logs.attach(lastSentTimestamp); + } }); } +})(); - public logSystemEvent( - logType: LogType, - obj: LogEventObject, - track: boolean = true, - ): void { - let message = logType.humanName; - const objectName = this.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'; - log.warn('Invalid error message', obj.error); - } - message += ` due to '${errorMessage}'`; - } - this.logSystemMessage(message, obj, logType.eventName, track); - } - - public 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'; - } - - this.logSystemMessage(message, obj, eventName); - } - - public async clearOutOfDateDBLogs(containerIds: string[]) { - log.debug('Performing database cleanup for container log timestamps'); - await db - .models('containerLogs') - .whereNotIn('containerId', containerIds) - .delete(); - } - - private 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; +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 default Logger; +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 function logDependent(message: LogMessage, device: { uuid: string }) { + if (backend != null) { + message.uuid = device.uuid; + backend.log(message); + } +} + +export function log(message: LogMessage) { + if (backend != null) { + backend.log(message); + } +} + +export function logSystemMessage( + message: string, + eventObj?: LogEventObject, + eventName?: string, + track: boolean = true, +) { + const msgObj: LogMessage = { message, isSystem: true }; + if (eventObj != null && eventObj.error != null) { + msgObj.isStdErr = true; + } + log(msgObj); + if (track) { + eventTracker.track( + eventName != null ? eventName : message, + eventObj != null ? eventObj : {}, + ); + } +} + +export function lock(containerId: string): Bluebird.Disposer<() => void> { + return writeLock(containerId).disposer((release) => { + release(); + }); +} + +export function attach( + containerId: string, + serviceInfo: { serviceId: number; imageId: number }, +): Bluebird { + // First detect if we already have an attached log stream + // for this container + if (containerId in containerLogs) { + return Bluebird.resolve(); + } + + return Bluebird.using(lock(containerId), async () => { + const logs = new ContainerLogs(containerId); + containerLogs[containerId] = logs; + logs.on('error', (err) => { + superConsole.error('Container log retrieval error', err); + delete containerLogs[containerId]; + }); + logs.on('log', async (logMessage) => { + log(_.merge({}, serviceInfo, logMessage)); + + // Take the timestamp and set it in the database as the last + // log sent for this + logMonitor.updateContainerSentTimestamp( + containerId, + logMessage.timestamp, + ); + }); + + logs.on('closed', () => delete containerLogs[containerId]); + + const lastSentTimestamp = await logMonitor.getContainerSentTimestamp( + containerId, + ); + return logs.attach(lastSentTimestamp); + }); +} + +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); +} + +export async function clearOutOfDateDBLogs(containerIds: string[]) { + superConsole.debug( + 'Performing database cleanup for container log timestamps', + ); + await db + .models('containerLogs') + .whereNotIn('containerId', containerIds) + .delete(); +} + +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/balena-backend.ts b/src/logging/balena-backend.ts index ba62907f..f2ab8479 100644 --- a/src/logging/balena-backend.ts +++ b/src/logging/balena-backend.ts @@ -70,7 +70,7 @@ export class BalenaLogBackend extends LogBackend { }); } - public isIntialised(): boolean { + public isInitialised(): boolean { return this.initialised; } diff --git a/src/proxyvisor.js b/src/proxyvisor.js index a27c0e43..3bdd2b15 100644 --- a/src/proxyvisor.js +++ b/src/proxyvisor.js @@ -18,6 +18,7 @@ import { log } from './lib/supervisor-console'; import * as db from './db'; import * as config from './config'; import * as dockerUtils from './lib/docker-utils'; +import * as logger from './logger'; const mkdirpAsync = Promise.promisify(mkdirp); @@ -186,7 +187,7 @@ const createProxyvisorRouter = function (proxyvisor) { if (device.markedForDeletion) { return res.status(410).send('Device deleted'); } - proxyvisor.logger.logDependent(m, uuid); + logger.logDependent(m, { uuid }); return res.status(202).send('OK'); }) .catch(function (err) { @@ -345,7 +346,7 @@ const createProxyvisorRouter = function (proxyvisor) { }; export class Proxyvisor { - constructor({ logger, images, applications }) { + constructor({ images, applications }) { this.bindToAPI = this.bindToAPI.bind(this); this.executeStepAction = this.executeStepAction.bind(this); this.getCurrentStates = this.getCurrentStates.bind(this); @@ -361,7 +362,6 @@ export class Proxyvisor { this.sendUpdate = this.sendUpdate.bind(this); this.sendDeleteHook = this.sendDeleteHook.bind(this); this.sendUpdates = this.sendUpdates.bind(this); - this.logger = logger; this.images = images; this.applications = applications; this.acknowledgedState = {}; diff --git a/src/supervisor.ts b/src/supervisor.ts index 0f7d7bbe..0760ad86 100644 --- a/src/supervisor.ts +++ b/src/supervisor.ts @@ -6,7 +6,7 @@ import * as eventTracker from './event-tracker'; import { intialiseContractRequirements } from './lib/contracts'; import { normaliseLegacyDatabase } from './lib/migration'; import * as osRelease from './lib/os-release'; -import Logger from './logger'; +import * as logger from './logger'; import SupervisorAPI from './supervisor-api'; import constants = require('./lib/constants'); @@ -29,18 +29,13 @@ const startupConfigFields: config.ConfigKey[] = [ ]; export class Supervisor { - private logger: Logger; private deviceState: DeviceState; private apiBinder: APIBinder; private api: SupervisorAPI; public constructor() { - this.logger = new Logger(); - this.apiBinder = new APIBinder({ - logger: this.logger, - }); + this.apiBinder = new APIBinder(); this.deviceState = new DeviceState({ - logger: this.logger, apiBinder: this.apiBinder, }); // workaround the circular dependency @@ -65,15 +60,11 @@ export class Supervisor { await db.initialized; await config.initialized; await eventTracker.initialized; + log.debug('Starting logging infrastructure'); + await logger.initialized; const conf = await config.getMany(startupConfigFields); - log.debug('Starting logging infrastructure'); - this.logger.init({ - enableLogs: conf.loggingEnabled, - ...conf, - }); - intialiseContractRequirements({ supervisorVersion: version, deviceType: await config.get('deviceType'), @@ -83,7 +74,7 @@ export class Supervisor { log.debug('Starting api binder'); await this.apiBinder.initClient(); - this.logger.logSystemMessage('Supervisor starting', {}, 'Supervisor start'); + logger.logSystemMessage('Supervisor starting', {}, 'Supervisor start'); if (conf.legacyAppsPresent && this.apiBinder.balenaApi != null) { log.info('Legacy app detected, running migration'); await normaliseLegacyDatabase( diff --git a/test/05-device-state.spec.ts b/test/05-device-state.spec.ts index b54f808e..f35dc31f 100644 --- a/test/05-device-state.spec.ts +++ b/test/05-device-state.spec.ts @@ -208,11 +208,6 @@ const testTargetInvalid = { }; describe('deviceState', () => { - const logger = { - clearOutOfDateDBLogs() { - /* noop */ - }, - }; let deviceState: DeviceState; before(async () => { await prepare(); @@ -228,7 +223,6 @@ describe('deviceState', () => { }); deviceState = new DeviceState({ - logger: logger as any, apiBinder: null as any, }); diff --git a/test/11-api-binder.spec.ts b/test/11-api-binder.spec.ts index 9b30b812..c489ea8b 100644 --- a/test/11-api-binder.spec.ts +++ b/test/11-api-binder.spec.ts @@ -35,12 +35,9 @@ const initModels = async (obj: Dictionary, filename: string) => { }, } as any; - obj.apiBinder = new ApiBinder({ - logger: obj.logger, - }); + obj.apiBinder = new ApiBinder(); obj.deviceState = new DeviceState({ - logger: obj.logger, apiBinder: obj.apiBinder, }); diff --git a/test/12-logger.spec.ts b/test/12-logger.spec.ts index 1411795f..6a2b371e 100644 --- a/test/12-logger.spec.ts +++ b/test/12-logger.spec.ts @@ -5,13 +5,14 @@ import * as Promise from 'bluebird'; import { expect } from './lib/chai-config'; import * as sinon from 'sinon'; -import { Logger } from '../src/logger'; import { ContainerLogs } from '../src/logging/container'; -import * as eventTracker from '../src/event-tracker'; -import { stub } from 'sinon'; +import * as config from '../src/config'; describe('Logger', function () { - beforeEach(function () { + let logger: typeof import('../src/logger'); + let configStub: sinon.SinonStub; + + beforeEach(async function () { this._req = new stream.PassThrough(); this._req.flushHeaders = sinon.spy(); this._req.end = sinon.spy(); @@ -23,27 +24,35 @@ describe('Logger', function () { this.requestStub = sinon.stub(https, 'request').returns(this._req); - this.eventTrackerStub = stub(eventTracker, 'track'); - - this.logger = new Logger(); - return this.logger.init({ - apiEndpoint: 'https://example.com', - uuid: 'deadbeef', - deviceApiKey: 'secretkey', - unmanaged: false, - enableLogs: true, - localMode: false, - }); + configStub = sinon.stub(config, 'getMany').returns( + // @ts-ignore this should actually work but the type system doesnt like it + Promise.resolve({ + apiEndpoint: 'https://example.com', + uuid: 'deadbeef', + deviceApiKey: 'secretkey', + unmanaged: false, + loggingEnabled: true, + localMode: false, + }), + ); + // delete the require cache for the logger module so we can force a refresh + delete require.cache[require.resolve('../src/logger')]; + logger = await import('../src/logger'); + await logger.initialized; }); afterEach(function () { this.requestStub.restore(); - this.eventTrackerStub.restore(); + configStub.restore(); + }); + + after(function () { + delete require.cache[require.resolve('../src/logger')]; }); it('waits the grace period before sending any logs', function () { const clock = sinon.useFakeTimers(); - this.logger.log({ message: 'foobar', serviceId: 15 }); + logger.log({ message: 'foobar', serviceId: 15 }); clock.tick(4999); clock.restore(); @@ -54,7 +63,7 @@ describe('Logger', function () { it('tears down the connection after inactivity', function () { const clock = sinon.useFakeTimers(); - this.logger.log({ message: 'foobar', serviceId: 15 }); + logger.log({ message: 'foobar', serviceId: 15 }); clock.tick(61000); clock.restore(); @@ -65,9 +74,9 @@ describe('Logger', function () { it('sends logs as gzipped ndjson', function () { const timestamp = Date.now(); - this.logger.log({ message: 'foobar', serviceId: 15 }); - this.logger.log({ timestamp: 1337, message: 'foobar', serviceId: 15 }); - this.logger.log({ message: 'foobar' }); // shold be ignored + logger.log({ message: 'foobar', serviceId: 15 }); + logger.log({ timestamp: 1337, message: 'foobar', serviceId: 15 }); + logger.log({ message: 'foobar' }); // shold be ignored return Promise.delay(5500).then(() => { expect(this.requestStub.calledOnce).to.be.true; @@ -102,16 +111,13 @@ describe('Logger', function () { it('allows logging system messages which are also reported to the eventTracker', function () { const timestamp = Date.now(); - this.logger.logSystemMessage( + logger.logSystemMessage( 'Hello there!', { someProp: 'someVal' }, 'Some event name', ); return Promise.delay(5500).then(() => { - expect(this.eventTrackerStub).to.be.calledWith('Some event name', { - someProp: 'someVal', - }); const lines = this._req.body.split('\n'); expect(lines.length).to.equal(2); expect(lines[1]).to.equal(''); diff --git a/test/13-device-config.spec.ts b/test/13-device-config.spec.ts index 29b95e1d..1440447a 100644 --- a/test/13-device-config.spec.ts +++ b/test/13-device-config.spec.ts @@ -1,7 +1,7 @@ import { Promise } from 'bluebird'; import { stripIndent } from 'common-tags'; import { child_process, fs } from 'mz'; -import { SinonSpy, SinonStub, spy, stub } from 'sinon'; +import { SinonSpy, SinonStub, stub } from 'sinon'; import * as config from '../src/config'; import { ExtlinuxConfigBackend, RPiConfigBackend } from '../src/config/backend'; @@ -9,6 +9,8 @@ import { DeviceConfig } from '../src/device-config'; import * as fsUtils from '../src/lib/fs-utils'; import { expect } from './lib/chai-config'; +import * as logger from '../src/logger'; + import prepare = require('./lib/prepare'); const extlinuxBackend = new ExtlinuxConfigBackend(); @@ -28,12 +30,12 @@ describe('DeviceConfig', function () { }); }, }; - this.fakeLogger = { - logSystemMessage: spy(), - }; - return (this.deviceConfig = new DeviceConfig({ - logger: this.fakeLogger, - })); + this.logStub = stub(logger, 'logSystemMessage'); + return (this.deviceConfig = new DeviceConfig()); + }); + + after(function () { + this.logStub.restore(); }); // Test that the format for special values like initramfs and array variables is parsed correctly @@ -97,15 +99,15 @@ describe('DeviceConfig', function () { }); expect(promise).to.be.rejected; return promise.catch((_err) => { - expect(this.fakeLogger.logSystemMessage).to.be.calledOnce; - expect(this.fakeLogger.logSystemMessage).to.be.calledWith( + expect(this.logStub).to.be.calledOnce; + expect(this.logStub).to.be.calledWith( 'Attempt to change blacklisted config value initramfs', { error: 'Attempt to change blacklisted config value initramfs', }, 'Apply boot config error', ); - return this.fakeLogger.logSystemMessage.resetHistory(); + return this.logStub.resetHistory(); }); }); @@ -133,8 +135,8 @@ describe('DeviceConfig', function () { }); expect(promise).to.eventually.equal(false); return promise.then(() => { - expect(this.fakeLogger.logSystemMessage).to.not.be.called; - return this.fakeLogger.logSystemMessage.resetHistory(); + expect(this.logStub).to.not.be.called; + return this.logStub.resetHistory(); }); }); @@ -168,8 +170,8 @@ describe('DeviceConfig', function () { .setBootConfig(rpiConfigBackend, target) .then(() => { expect(child_process.exec).to.be.calledOnce; - expect(this.fakeLogger.logSystemMessage).to.be.calledTwice; - expect(this.fakeLogger.logSystemMessage.getCall(1).args[2]).to.equal( + expect(this.logStub).to.be.calledTwice; + expect(this.logStub.getCall(1).args[2]).to.equal( 'Apply boot config success', ); expect(fsUtils.writeFileAtomic).to.be.calledWith( @@ -185,7 +187,7 @@ foobaz=bar\n\ ); (fsUtils.writeFileAtomic as SinonStub).restore(); (child_process.exec as SinonStub).restore(); - return this.fakeLogger.logSystemMessage.resetHistory(); + return this.logStub.resetHistory(); }); }); }); @@ -254,10 +256,10 @@ foobaz=bar\n\ .setBootConfig(extlinuxBackend, target) .then(() => { expect(child_process.exec).to.be.calledOnce; - expect(this.fakeLogger.logSystemMessage).to.be.calledTwice; - expect( - this.fakeLogger.logSystemMessage.getCall(1).args[2], - ).to.equal('Apply boot config success'); + expect(this.logStub).to.be.calledTwice; + expect(this.logStub.getCall(1).args[2]).to.equal( + 'Apply boot config success', + ); expect(fsUtils.writeFileAtomic).to.be.calledWith( './test/data/mnt/boot/extlinux/extlinux.conf', `\ @@ -272,7 +274,7 @@ APPEND \${cbootargs} \${resin_kernel_root} ro rootwait isolcpus=2\n\ ); (fsUtils.writeFileAtomic as SinonStub).restore(); (child_process.exec as SinonStub).restore(); - return this.fakeLogger.logSystemMessage.resetHistory(); + return this.logStub.resetHistory(); }); }); })); @@ -405,9 +407,7 @@ APPEND \${cbootargs} \${resin_kernel_root} ro rootwait isolcpus=2\n\ throw new Error('Unknown fake config key'); }); }); - this.upboardConfig = new DeviceConfig({ - logger: this.fakeLogger, - }); + this.upboardConfig = new DeviceConfig(); stub(child_process, 'exec').resolves(); stub(fs, 'exists').callsFake(() => Promise.resolve(true)); @@ -445,7 +445,7 @@ APPEND \${cbootargs} \${resin_kernel_root} ro rootwait isolcpus=2\n\ (fs.readFile as SinonStub).restore(); (fsUtils.writeFileAtomic as SinonStub).restore(); (config.get as SinonStub).restore(); - this.fakeLogger.logSystemMessage.resetHistory(); + this.logStub.resetHistory(); }); it('should correctly load the configfs.json file', function () { @@ -464,7 +464,7 @@ APPEND \${cbootargs} \${resin_kernel_root} ro rootwait isolcpus=2\n\ HOST_CONFIGFS_ssdt: 'spidev1,1', }; - this.fakeLogger.logSystemMessage.resetHistory(); + this.logStub.resetHistory(); (child_process.exec as SinonSpy).resetHistory(); (fs.exists as SinonSpy).resetHistory(); (fs.mkdir as SinonSpy).resetHistory(); @@ -493,10 +493,10 @@ APPEND \${cbootargs} \${resin_kernel_root} ro rootwait isolcpus=2\n\ ssdt: ['spidev1,1'], }), ); - expect(this.fakeLogger.logSystemMessage).to.be.calledTwice; - return expect( - this.fakeLogger.logSystemMessage.getCall(1).args[2], - ).to.equal('Apply boot config success'); + expect(this.logStub).to.be.calledTwice; + return expect(this.logStub.getCall(1).args[2]).to.equal( + 'Apply boot config success', + ); }); }); }); diff --git a/test/14-application-manager.spec.ts b/test/14-application-manager.spec.ts index 0d41a367..a289d001 100644 --- a/test/14-application-manager.spec.ts +++ b/test/14-application-manager.spec.ts @@ -125,13 +125,7 @@ const dependentDBFormat = { describe('ApplicationManager', function () { before(async function () { await prepare(); - this.logger = { - clearOutOfDateDBLogs: () => { - /* noop */ - }, - } as any; this.deviceState = new DeviceState({ - logger: this.logger, apiBinder: null as any, }); this.applications = this.deviceState.applications; @@ -171,9 +165,7 @@ describe('ApplicationManager', function () { appCloned.networks = _.mapValues( appCloned.networks, (config, name) => { - return Network.fromComposeObject(name, app.appId, config, { - logger: this.logger, - }); + return Network.fromComposeObject(name, app.appId, config); }, ); return appCloned; @@ -639,10 +631,7 @@ describe('ApplicationManager', function () { Bluebird.Promise.resolve([ { action: 'removeVolume', - current: Volume.fromComposeObject('my_volume', 12, {}, { - docker: null, - logger: null, - } as any), + current: Volume.fromComposeObject('my_volume', 12, {}), }, ]), ); diff --git a/test/20-compose-volume.spec.ts b/test/20-compose-volume.spec.ts index eeed3b93..7ccd374c 100644 --- a/test/20-compose-volume.spec.ts +++ b/test/20-compose-volume.spec.ts @@ -2,29 +2,29 @@ import { expect } from 'chai'; import { stub, SinonStub } from 'sinon'; import { docker } from '../src/lib/docker-utils'; +import * as logger from '../src/logger'; import Volume from '../src/compose/volume'; import logTypes = require('../src/lib/log-types'); -const fakeLogger = { - logSystemMessage: stub(), - logSystemEvent: stub(), -}; - -const opts: any = { logger: fakeLogger }; - describe('Compose volumes', () => { let createVolumeStub: SinonStub; + let logSystemStub: SinonStub; + let logMessageStub: SinonStub; before(() => { createVolumeStub = stub(docker, 'createVolume'); + logSystemStub = stub(logger, 'logSystemEvent'); + logMessageStub = stub(logger, 'logSystemMessage'); }); after(() => { createVolumeStub.restore(); + logSystemStub.restore(); + logMessageStub.restore(); }); describe('Parsing volumes', () => { it('should correctly parse docker volumes', () => { - const volume = Volume.fromDockerVolume(opts, { + const volume = Volume.fromDockerVolume({ Driver: 'local', Labels: { 'io.balena.supervised': 'true', @@ -54,19 +54,14 @@ describe('Compose volumes', () => { }); it('should correctly parse compose volumes without an explicit driver', () => { - const volume = Volume.fromComposeObject( - 'one_volume', - 1032480, - { - driver_opts: { - opt1: 'test', - }, - labels: { - 'my-label': 'test-label', - }, + const volume = Volume.fromComposeObject('one_volume', 1032480, { + driver_opts: { + opt1: 'test', }, - opts, - ); + labels: { + 'my-label': 'test-label', + }, + }); expect(volume).to.have.property('appId').that.equals(1032480); expect(volume).to.have.property('name').that.equals('one_volume'); @@ -90,20 +85,15 @@ describe('Compose volumes', () => { }); it('should correctly parse compose volumes with an explicit driver', () => { - const volume = Volume.fromComposeObject( - 'one_volume', - 1032480, - { - driver: 'other', - driver_opts: { - opt1: 'test', - }, - labels: { - 'my-label': 'test-label', - }, + const volume = Volume.fromComposeObject('one_volume', 1032480, { + driver: 'other', + driver_opts: { + opt1: 'test', }, - opts, - ); + labels: { + 'my-label': 'test-label', + }, + }); expect(volume).to.have.property('appId').that.equals(1032480); expect(volume).to.have.property('name').that.equals('one_volume'); @@ -130,23 +120,18 @@ describe('Compose volumes', () => { describe('Generating docker options', () => { afterEach(() => { createVolumeStub.reset(); - fakeLogger.logSystemEvent.reset(); - fakeLogger.logSystemMessage.reset(); + logSystemStub.reset(); + logMessageStub.reset(); }); it('should correctly generate docker options', async () => { - const volume = Volume.fromComposeObject( - 'one_volume', - 1032480, - { - driver_opts: { - opt1: 'test', - }, - labels: { - 'my-label': 'test-label', - }, + const volume = Volume.fromComposeObject('one_volume', 1032480, { + driver_opts: { + opt1: 'test', }, - opts, - ); + labels: { + 'my-label': 'test-label', + }, + }); await volume.create(); expect( @@ -161,7 +146,7 @@ describe('Compose volumes', () => { }), ); - expect(fakeLogger.logSystemEvent.calledWith(logTypes.createVolume)); + expect(logSystemStub.calledWith(logTypes.createVolume)); }); }); }); diff --git a/test/22-local-mode.spec.ts b/test/22-local-mode.spec.ts index e50cf7ac..49d84f99 100644 --- a/test/22-local-mode.spec.ts +++ b/test/22-local-mode.spec.ts @@ -9,7 +9,6 @@ import LocalModeManager, { EngineSnapshot, EngineSnapshotRecord, } from '../src/local-mode'; -import Logger from '../src/logger'; import ShortStackError from './lib/errors'; describe('LocalModeManager', () => { @@ -34,9 +33,8 @@ describe('LocalModeManager', () => { await db.initialized; dockerStub = sinon.stub(docker); - const loggerStub = (sinon.createStubInstance(Logger) as unknown) as Logger; - localMode = new LocalModeManager(loggerStub, supervisorContainerId); + localMode = new LocalModeManager(supervisorContainerId); }); after(async () => { diff --git a/test/lib/mocked-device-api.ts b/test/lib/mocked-device-api.ts index a7d0f514..ba846818 100644 --- a/test/lib/mocked-device-api.ts +++ b/test/lib/mocked-device-api.ts @@ -72,7 +72,6 @@ async function create(): Promise { setupStubs(); // Create ApplicationManager const appManager = new ApplicationManager({ - logger: null, deviceState, apiBinder: null, }); @@ -102,12 +101,9 @@ async function createAPIOpts(): Promise { await initConfig(); // Create deviceState const deviceState = new DeviceState({ - logger: null as any, apiBinder: null as any, }); - const apiBinder = new APIBinder({ - logger: null as any, - }); + const apiBinder = new APIBinder(); return { deviceState, apiBinder,