improve logging separation, enable patch-package

docker/rootfs/root/.bash_profile

@@ -19,3 +19,5 @@ fi
 alias ll='ls -alF'
 alias la='ls -A'
 alias l='ls -CF'
+
+export PATH=/opt/typedaemon/node_modules/.bin/:$PATH

src/commands/dev_env.ts

@@ -4,10 +4,10 @@ import fse = require("fs-extra")
 import path = require("path");
 import { CommandModule } from "yargs";
 
+import { saveGeneratedTsconfig } from "../common/generate_tsconfig";
+import { TD_DEVELOPER_MODE, TD_MODULES_PATH, TD_VERSION, __package_dir } from "../common/util";
 import { UtilityHypervisor } from "../hypervisor/hypervisor";
 import { InstallOpts, installDependencies } from "../hypervisor/packages";
-import { TD_DEVELOPER_MODE, TD_MODULES_PATH, TD_VERSION, __package_dir } from "../common/util";
-import { saveGeneratedTsconfig } from "../common/generate_tsconfig";
 
 const INSTALL_MODE: 'download' | 'copy' | 'link' = 'copy';
 
@@ -29,7 +29,6 @@ export async function syncDevEnv(wdir: string) {
         };
         const depOpts: InstallOpts = {
             dir: hv.operations_directory,
-            logger: (msg) => console.log('  ' + msg),
             lockfile: false,
         }
         await installDependencies(depOpts, deps);

src/hypervisor/application_instance.ts

@@ -64,9 +64,17 @@ export class ApplicationInstance extends BaseInstance<AppConfiguration, Applicat
         const lopts = this.options.logging;
         const file = this.loggerFile();
         return {
-            tag: chalk.blue`Application: ${this.id}`,
-            manager: { file: file, level: lopts?.system_level },
-            user: { file: file, level: lopts?.level },
+            tag: chalk.blue`App: ${this.id}`,
+            manager: {
+                file: file,
+                level: lopts?.system_level,
+            },
+            user: {
+                file: file,
+                level: lopts?.level,
+                // domain: chalk.blue.italic`App: ${this.id}`,
+                label_format: "[[%MSG%]]"
+            },
         }
     }
 
@@ -195,12 +203,13 @@ export class ApplicationInstance extends BaseInstance<AppConfiguration, Applicat
 
         // if (Object.keys(packageJson?.dependencies || {}).length > 0) {
         this.logMessage("info", `Installing packages`);
-        await installDependencies({
+        // TODO Skip if unchanged
+        //   - Add a file (eg .tdmeta) to the shared_operating_directory?
+        await this.invoke(() => installDependencies({
             dir: this.shared_operating_directory,
-            logger: (...args) => this.logMessage("debug", ...args),
             lockfile: this.isThickApp,
             devPackages: true,
-        });
+        }));
 
         // Abort if the app started shutting down
         if (this.state as AppLifecycle != "initializing") return;
@@ -342,8 +351,10 @@ export class ApplicationInstance extends BaseInstance<AppConfiguration, Applicat
     }
 
     private async compileModule() {
-        const vm = await this.vm();
-        return vm.runFile(this.entrypoint);
+        return await this.invoke(async () => {
+            const vm = await this.vm();
+            return vm.runFile(this.entrypoint);
+        })
     }
 
     private _vm: AsyncReturnType<typeof createApplicationVM>;

src/hypervisor/logging.ts

@@ -12,6 +12,8 @@ require('winston-daily-rotate-file');
 import { mapStackTrace } from "../app_transformer/source_maps";
 import { pojso } from "../common/util";
 import { current } from "./current";
+import { PluginInstance } from "./plugin_instance";
+import { HyperWrapper } from "./managed_apps";
 
 export const CONSOLE_METHODS = ['debug', 'info', 'warn', 'error', 'dir'] as const;
 export type ConsoleMethod = TupleToUnion<typeof CONSOLE_METHODS>
@@ -31,8 +33,8 @@ const NUMERIC_LOG_LEVELS = {
 
 export const ORIGINAL_CONSOLE = { ...console };
 
-export function colorLogLevel(level: ConsoleMethod | string) {
-    const nlevel = level.toLowerCase();
+export function colorLogLevel(level: ConsoleMethod | string, clevel = level) {
+    const nlevel = clevel.toLowerCase();
     if (nlevel == "error") return chalk.red(level);
     if (nlevel == "warn") return chalk.yellow(level);
     if (nlevel == "info") return chalk.blue(level);
@@ -71,9 +73,11 @@ export function cleanAndMapStacktrace(err: Error) {
 const fmt = winston.format;
 
 function formatMessage(m: winston.Logform.TransformableInfo) {
-    let { level, message, label } = m;
-    level = level.toUpperCase();
-    return chalk`[${label}] - ${colorLogLevel(level)} - ${message}`;
+    let { level, message, label, level_prefix, label_format } = m;
+    label = (label_format as string || "[%MSG%]").replace('%MSG%', label);
+    let flevel = (level_prefix || '') + level;
+    flevel = flevel.toUpperCase();
+    return chalk`${label} - ${colorLogLevel(flevel, level)} - ${message}`;
 }
 
 const formatter = fmt.printf(formatMessage)
@@ -101,6 +105,8 @@ const filter = fmt((info) => {
 })
 
 export interface LoggerOptions {
+    level_prefix?: string;
+    label_format?: string;
     domain?: string;
     level?: LogLevel;
     file?: string;
@@ -155,7 +161,11 @@ export function createDomainLogger(opts: LoggerOptions) {
             fmt.label({ label: opts.domain || 'System' }),
             filter(),
         ),
-        defaultMeta: { service: 'user-service' },
+        defaultMeta: {
+            service: 'user-service',
+            level_prefix: opts.level_prefix,
+            label_format: opts.label_format,
+        },
         transports,
     }) as any as ExtendedLoger;
 
@@ -204,33 +214,48 @@ export function createDomainLogger(opts: LoggerOptions) {
 
 export type LogAMessage = typeof logMessage;
 
+export function logClientMessage(level: LogLevel, ...rest: any[]) {
+    const ctx = current.application;
+    const logger = ctx?.userSpaceLogger || UNKNOWN_LOGGER
+    logger.logMessage(level, rest);
+}
+
+export function logPluginClientMessage(plugin: any, level: LogLevel, ...rest: any[]) {
+    if (!(plugin instanceof PluginInstance)) plugin = plugin[HyperWrapper];
+
+    const ctx = current.application;
+    const logger = ctx?.logger || UNKNOWN_LOGGER
+    logger.logMessage(level, ["[" + chalk.blueBright`${plugin.id}` + "]", ...rest], {});
+}
+
 export function logMessage(level: LogLevel, ...rest: any[]) {
     const ctx = current.application || current.hypervisor;
-    const logger = ctx?.logger || UKNOWN_LOGGER
+    const logger = ctx?.logger || UNKNOWN_LOGGER
     logger.logMessage(level, rest);
 }
 
-export function logSystemMessage(level: LogLevel, ...rest: any[]) {
+export function logHVMessage(level: LogLevel, ...rest: any[]) {
     const ctx = current.hypervisor;
-    const logger = ctx?.logger || UKNOWN_LOGGER
+    const logger = ctx?.logger || UNKNOWN_LOGGER
     logger.logMessage(level, rest);
 }
 
-let UKNOWN_LOGGER = createDomainLogger({ domain: chalk.yellow("???") });
+export let UNKNOWN_LOGGER = createDomainLogger({ domain: chalk.yellow("???") });
 export function setFallbackLogger(logger: ExtendedLoger) {
-    UKNOWN_LOGGER = logger;
+    UNKNOWN_LOGGER = logger;
 }
 
 export function redirectConsole() {
     for (let cm of CONSOLE_METHODS) {
         console[cm] = (m, ...rest) => {
             const ctx = current.application || current.hypervisor;
-            const logger = ctx?.logger || UKNOWN_LOGGER
+            const logger = ctx?.logger || UNKNOWN_LOGGER
             try {
                 logger.logMessage(cm, [m, ...rest]);
             } catch (ex) {
                 ORIGINAL_CONSOLE.error(ex)
             }
         }
     }
+    console.log = (...rest) => console.info(...rest);
 }

src/hypervisor/managed_apps.ts

@@ -10,7 +10,7 @@ import { LifecycleHelper } from "../common/lifecycle_helper";
 import { timeoutPromise } from "../common/util";
 import { AppLifecycle } from "./application_instance";
 import { Hypervisor } from "./hypervisor";
-import { ExtendedLoger, LogLevel, createDomainLogger } from "./logging";
+import { ExtendedLoger, LogLevel, LoggerOptions, createDomainLogger } from "./logging";
 
 interface LifecycleEvents {
     // started: () => void;
@@ -52,10 +52,15 @@ interface InstanceContext {
     namespace: AppNamespace;
 }
 
+interface LoggerTypeOptions extends LoggerOptions {
+    level: LogLevel;
+    file: string;
+}
+
 export interface InstanceLogConfig {
     tag: string;
-    user?: { level: LogLevel, file: string };
-    manager?: { level: LogLevel, file: string };
+    user?: LoggerTypeOptions;
+    manager?: LoggerTypeOptions;
 }
 
 export abstract class BaseInstance<C, A extends BaseInstanceClient<any> = BaseInstanceClient<any>, const L extends ListenerSignature<L> = any> extends TypedEmitter<Merge<L, LifecycleEvents>> {
@@ -104,15 +109,15 @@ export abstract class BaseInstance<C, A extends BaseInstanceClient<any> = BaseIn
         this._logger = createDomainLogger({
             level: "warn",
             domain,
-            ...manager,
             ...rest,
+            ...manager,
         })
 
         this._userSpaceLogger = createDomainLogger({
             level: "debug",
             domain,
-            ...user,
             ...rest,
+            ...user,
         })
     }
 
@@ -142,7 +147,7 @@ export abstract class BaseInstance<C, A extends BaseInstanceClient<any> = BaseIn
     private _state: AppLifecycle = "initializing";
     protected transitionState(nstate: AppLifecycle) {
         this._state = nstate;
-        this.logMessage("lifecycle", upcaseFirstChar(nstate))
+        this.logClientMessage("lifecycle", upcaseFirstChar(nstate))
         // @ts-ignore
         this.emit("lifecycle", nstate);
         // @ts-ignore

src/hypervisor/packages.ts

@@ -1,16 +1,16 @@
 import fs = require("fs");
 import execa = require("execa");
 import path = require("path");
-import { __package_dir } from "../common/util";
+import { TD_MODULES_PATH } from "../common/util";
+import { LogLevel, logMessage } from "./logging";
 
 export interface InstallOpts {
     dir: string;
     lockfile?: boolean;
     devPackages?: boolean;
-    logger: (...args: any[]) => void;
 }
 
-export async function installDependencies({ dir, logger, ...opts }: InstallOpts, dependencies?) {
+export async function installDependencies({ dir, ...opts }: InstallOpts, dependencies?) {
     const flags: string[] = ["--non-interactive"];
 
     if (opts.lockfile === false) {
@@ -44,33 +44,44 @@ export async function installDependencies({ dir, logger, ...opts }: InstallOpts,
                 NODE_ENV: "development",
             }
         }),
-        logger,
+        {
+            ignored_patterns: [
+                "No license field",
+            ]
+        }
     )
 
-    // logger("Patching Packages")
+    logMessage("info", "Patching packages")
 
-    // await handle_subproc(
-    //     execa('patch-package', ['--patch-dir', path.join(__package_dir, 'patches')], {
-    //         cwd: dir,
-    //     }),
-    //     logger,
-    // )
+    await handle_subproc(
+        execa(path.join(TD_MODULES_PATH, '.bin', `patch-package`), [], {
+            cwd: dir,
+        }),
+        {
+            ignored_patterns: [
+                "No license field",
+                "No patch files found",
+            ]
+        }
+    )
 
     if (dependencies) {
         await fs.promises.unlink(pkgjsonFile);
     }
 }
 
-async function handle_subproc(proc: execa.ExecaChildProcess, logger: InstallOpts['logger']) {
-    proc.stdout.on('data', (data) => {
-        logger(data.toString().trim())
-    });
-    proc.stderr.on('data', (data) => {
-        logger(data.toString().trim())
-    });
-    // subprocess.stderr.on('data', (data) => {
-    //     host.logMessage("error", `yarn - ${data.toString().trim()}`)
-    // });
+async function handle_subproc(proc: execa.ExecaChildProcess, { ignored_patterns }: { ignored_patterns?: (string | RegExp)[] } = { ignored_patterns: [] }) {
+    const printer_factory = (level: LogLevel) => (data) => {
+        const lines = (data.toString() as string).trim().split("\n");
+        lineloop: for (let l of lines) {
+            for (let p of ignored_patterns) {
+                if (l.match(p)) continue lineloop;
+            }
+            logMessage(level, l);
+        }
+    }
+    proc.stdout.on('data', printer_factory("debug"));
+    proc.stderr.on('data', printer_factory("warn"));
     const { stdout, stderr, exitCode, failed } = await proc;
     if (failed || exitCode > 0) {
         throw new Error(`Failed to install dependencies with yarn`);

src/hypervisor/plugin_instance.ts

@@ -2,8 +2,8 @@ import path = require("path");
 import chalk = require("chalk");
 import deepEqual = require("deep-eql");
 
-import { BaseInstance, InstanceLogConfig } from "../hypervisor/managed_apps";
 import { PluginConfiguration } from "../hypervisor/config_plugin";
+import { BaseInstance, InstanceLogConfig } from "../hypervisor/managed_apps";
 import { PLUGIN_TYPES } from "../plugins";
 import { Plugin } from "../plugins/base";
 import { configChangeHandler } from "./managed_config_events";

src/plugins/home_assistant/entity_api/auto_cleaning.ts

@@ -3,11 +3,10 @@ import { AbstractConstructor } from "type-fest";
 import { TDEntity } from ".";
 import { HomeAssistantPlugin } from "..";
 import { DestroyerStore } from "../../../hypervisor/destroyer";
-import { logMessage } from "../../../hypervisor/logging";
+import { logMessage, logPluginClientMessage } from "../../../hypervisor/logging";
 import { HyperWrapper } from "../../../hypervisor/managed_apps";
-import { HomeAssistantApi, homeAssistantApi } from "../api";
-import { EntityStore } from "./store";
 import { get_plugin } from "../../base";
+import { EntityStore } from "./store";
 
 export interface AutoCleanEntry {
     uuid: string;
@@ -53,7 +52,7 @@ export const trackAutocleanEntity = (store: EntityStore, entity: TDEntity<any>)
     const cleaner: Autocleaner = entity.constructor[SymbolAutocleaner];
     if (!cleaner) return;
 
-    console.debug(`Adding '${entity.uuid}' to autocleans`);
+    logPluginClientMessage(store.plugin, "debug", `Adding '${entity.uuid}' to autocleans`);
 
     const { application, plugin } = store;
 
@@ -87,12 +86,12 @@ export const autocleanEntities = async (store: EntityStore) => {
             keepEntriesByCUID[cuid] = ent;
         } else {
             try {
-                console.debug(`Autocleaning '${ent.uuid}'`);
+                logPluginClientMessage(plugin, "debug", `Autocleaning '${ent.uuid}'`);
                 const cleaner = getAutocleaner(ent.cleaner_key);
                 // TODO Should this hold up the thread, or occur totally asynchronously?
                 await cleaner.destroy_entity(ent.cleaner_opts, store);
             } catch (ex) {
-                application.logMessage("warn", `Failed to autoclean entity '${ent.uuid}':`, ex)
+                logPluginClientMessage(plugin, "warn", `Failed to autoclean entity '${ent.uuid}':`, ex)
             }
         }
     }

src/plugins/home_assistant/entity_api/store.ts

@@ -1,7 +1,7 @@
 import { TDEntity } from ".";
 import type { HomeAssistantPlugin } from "..";
 import { ApplicationInstance } from "../../../hypervisor/application_instance";
-import { logMessage } from "../../../hypervisor/logging";
+import { logPluginClientMessage } from "../../../hypervisor/logging";
 import { HyperWrapper } from "../../../hypervisor/managed_apps";
 import { MqttPlugin } from "../../mqtt";
 import { HAEntititesDestroyer, autocleanEntities } from "./auto_cleaning";
@@ -34,7 +34,7 @@ export class EntityStore {
         }
 
         entity['_bound_store'] = this;
-        logMessage("debug", `Registering entity '${entity.uuid}'`)
+        logPluginClientMessage(this.plugin, "debug", `Registering entity '${entity.uuid}'`)
 
         entity['_disposers'].prepend(() => {
             this._untrackEntity(entity)