Merge pull request #2695 from Azure/dpwatrous/vnext-logger

Refactored logger to add context

desktop/src/app/app.component.ts

@@ -10,7 +10,8 @@ import { PermissionService } from "@batch-flask/ui/permission";
 import { EnvironmentMode, initEnvironment } from "@batch/ui-common";
 import { DependencyName } from "@batch/ui-common/lib/environment";
 import { DefaultFormControlResolver, DefaultFormLayoutProvider, FormControlResolver } from "@batch/ui-react/lib/components/form";
-import { ConsoleLogger } from "@batch/ui-common/lib/logging";
+import { StandardClock } from "@batch/ui-common/lib/datetime";
+import { createConsoleLogger } from "@batch/ui-common/lib/logging";
 import { BrowserDependencyName } from "@batch/ui-react";
 import { StorageAccountServiceImpl, SubscriptionServiceImpl } from "@batch/ui-service";
 import { registerIcons } from "app/config";
@@ -74,8 +75,9 @@ export class AppComponent implements OnInit, OnDestroy {
                 mode: ENV === Environment.prod ? EnvironmentMode.Production : EnvironmentMode.Development
             },
             {
+                [DependencyName.Clock]: () => new StandardClock(),
                 // TODO: Create an adapter which hooks up to the desktop logger
-                [DependencyName.Logger]: () => new ConsoleLogger(),
+                [DependencyName.LoggerFactory]: () => createConsoleLogger,
                 [DependencyName.Localizer]: () => new StandardLocalizer(),
                 [DependencyName.HttpClient]:
                     () => new BatchExplorerHttpClient(authService),

packages/common/src/ui-common/action/__tests__/action.spec.ts

@@ -1,9 +1,12 @@
+import { initMockEnvironment } from "../../environment";
 import { createForm, Form, ValidationStatus } from "../../form";
 import { StringParameter } from "../../form/string-parameter";
 import { delay, mergeDeep } from "../../util";
 import { AbstractAction } from "../action";
 
 describe("Action tests", () => {
+    beforeEach(() => initMockEnvironment());
+
     test("Simple action execution", async () => {
         const action = new HelloAction({
             subject: "planet",

packages/common/src/ui-common/action/action.ts

@@ -157,7 +157,10 @@ export abstract class AbstractAction<V extends FormValues>
                 executionResult.success = true;
             } catch (e) {
                 executionResult.error = e;
-                getLogger().warn("Action failed to execute:", e);
+                getLogger("AbstractAction").warn(
+                    "Action failed to execute:",
+                    e
+                );
             }
 
             this._executionDeferred.resolve();

packages/common/src/ui-common/__tests__/datetime.spec.ts → packages/common/src/ui-common/datetime/__tests__/datetime-util.spec.ts

@@ -1,6 +1,6 @@
 import { DateTime } from "luxon";
-import { fromIso, isDate, toIsoLocal, toIsoUtc } from "../datetime";
-import { initMockEnvironment } from "../environment";
+import { fromIso, isDate, toIsoLocal, toIsoUtc } from "../datetime-util";
+import { initMockEnvironment } from "../../environment";
 
 describe("Date/time utilities", () => {
     beforeEach(() => initMockEnvironment());

packages/common/src/ui-common/datetime/__tests__/fake-clock.spec.ts

@@ -0,0 +1,34 @@
+import { initMockEnvironment } from "../../environment";
+import { fromIso, getClock } from "../datetime-util";
+import { FakeClock } from "../fake-clock";
+
+describe("Fake clock", () => {
+    beforeEach(() => initMockEnvironment());
+
+    test("Can manipulate fake clock", () => {
+        const clock = getClock() as FakeClock;
+
+        // Hard-coded current time
+        expect(clock.now().getTime()).toEqual(
+            fromIso("2022-02-02T00:00:00Z").getTime()
+        );
+
+        // Advance 60 seconds
+        clock.advance(60_000);
+        expect(clock.now().getTime()).toEqual(
+            fromIso("2022-02-02T00:01:00Z").getTime()
+        );
+
+        // Set time to 2011-01-01 00:00:00 UTC
+        clock.setTime(1293840000000);
+        expect(clock.now().getTime()).toEqual(
+            fromIso("2011-01-01T00:00:00Z").getTime()
+        );
+
+        // Reset back to original time
+        clock.reset();
+        expect(clock.now().getTime()).toEqual(
+            fromIso("2022-02-02T00:00:00Z").getTime()
+        );
+    });
+});

packages/common/src/ui-common/datetime/clock.ts

@@ -0,0 +1,3 @@
+export interface Clock {
+    now(): Date;
+}

packages/common/src/ui-common/datetime.ts → packages/common/src/ui-common/datetime/datetime-util.ts

@@ -1,8 +1,18 @@
 import { Settings, DateTime, Zone } from "luxon";
+import { getEnvironment } from "../environment";
+import { Clock } from "./clock";
 
 // Stored so that the timezone can be reset to its original value in unit tests
 const initialSystemTimeZone = getSystemTimeZone();
 
+/**
+ * Gets the currently configured clock for the environment
+ * @returns A clock implementation
+ */
+export function getClock(): Clock {
+    return getEnvironment().getClock();
+}
+
 /**
  * Gets the current local time zone.
  * Note: Getting always returns a zone object, so this cast should be safe.
@@ -17,6 +27,10 @@ function getSystemTimeZone(): Zone {
  * @returns The number of hours of the current timezone offset
  */
 export function getLocalTimeZoneOffset(): number {
+    // KLUDGE: This should really use the fake clock, but there's a
+    //         conflict between this and the mock environment test
+    //         that checks the local timezone offset before the
+    //         environment is initialized
     const offsetMinutes = getSystemTimeZone().offset(new Date().getTime());
     return offsetMinutes / 60;
 }

packages/common/src/ui-common/datetime/fake-clock.ts

@@ -0,0 +1,27 @@
+import { Clock } from "./clock";
+
+// 2022-02-02 00:00:00 UTC
+const INITIAL_MS = 1643760000000;
+
+export class FakeClock implements Clock {
+    private _ms: number = INITIAL_MS;
+
+    now(): Date {
+        return new Date(this._ms);
+    }
+
+    advance(ms: number) {
+        if (ms <= 0) {
+            throw new Error("Can't advance clock by zero or a negative number");
+        }
+        this._ms = ms + this._ms;
+    }
+
+    setTime(ms: number) {
+        this._ms = ms;
+    }
+
+    reset() {
+        this._ms = INITIAL_MS;
+    }
+}

packages/common/src/ui-common/datetime/index.ts

@@ -0,0 +1,3 @@
+export * from "./datetime-util";
+export * from "./clock";
+export * from "./standard-clock";

packages/common/src/ui-common/datetime/standard-clock.ts

@@ -0,0 +1,7 @@
+import { Clock } from "./clock";
+
+export class StandardClock implements Clock {
+    now(): Date {
+        return new Date();
+    }
+}

packages/common/src/ui-common/environment/__tests__/environment-util.spec.ts

@@ -1,6 +1,7 @@
+import { FakeClock } from "../../datetime/fake-clock";
 import { MockHttpClient } from "../../http";
 import { StandardLocalizer } from "../../localization/standard-localizer";
-import { MockLogger } from "../../logging";
+import { createMockLogger } from "../../logging";
 import { AbstractEnvironment } from "../abstract-environment";
 import {
     DependencyFactories,
@@ -99,6 +100,18 @@ describe("Environment tests", () => {
         );
     });
 
+    test("Loading different environments injects different dependencies", () => {
+        // Dog goes woof
+        initEnvironment(new DogEnvironment(cfg));
+        expect(new Room().listen()).toEqual("You hear 'Woof!'");
+
+        destroyEnvironment();
+
+        // Cat goes meow
+        initEnvironment(new CatEnvironment(cfg));
+        expect(new Room().listen()).toEqual("You hear 'Meow!'");
+    });
+
     interface Animal {
         speak(): string;
     }
@@ -135,7 +148,8 @@ describe("Environment tests", () => {
 
         constructor(config: EnvironmentConfig) {
             super(config, {
-                logger: () => new MockLogger(),
+                clock: () => new FakeClock(),
+                loggerFactory: () => createMockLogger,
                 localizer: () => new StandardLocalizer(),
                 httpClient: () => new MockHttpClient(),
                 animal: () => new Dog(),
@@ -159,7 +173,8 @@ describe("Environment tests", () => {
 
         constructor(config: EnvironmentConfig) {
             super(config, {
-                logger: () => new MockLogger(),
+                clock: () => new FakeClock(),
+                loggerFactory: () => createMockLogger,
                 localizer: () => new StandardLocalizer(),
                 httpClient: () => new MockHttpClient(),
                 animal: () => new Cat(),
@@ -174,16 +189,4 @@ describe("Environment tests", () => {
             // No-op
         }
     }
-
-    test("Loading different environments injects different dependencies", () => {
-        // Dog goes woof
-        initEnvironment(new DogEnvironment(cfg));
-        expect(new Room().listen()).toEqual("You hear 'Woof!'");
-
-        destroyEnvironment();
-
-        // Cat goes meow
-        initEnvironment(new CatEnvironment(cfg));
-        expect(new Room().listen()).toEqual("You hear 'Meow!'");
-    });
 });

packages/common/src/ui-common/environment/__tests__/mock-environment.spec.ts

@@ -21,9 +21,11 @@ describe("Mock environment tests", () => {
     test("Default mock environment uses a mock logger", () => {
         initMockEnvironment();
         const env = getMockEnvironment();
-        const mockLogger = env.getLogger() as MockLogger;
+        const mockLogger = env.getLogger("mock-environment.spec") as MockLogger;
         mockLogger.enableChecking = true;
-        mockLogger.expectInfo("This is from a mock logger");
+        mockLogger.expectInfo(
+            "[mock-environment.spec] - This is from a mock logger"
+        );
         mockLogger.info("This is from a mock logger");
     });
 

packages/common/src/ui-common/environment/abstract-environment.ts

@@ -1,7 +1,7 @@
 import { DependencyFactories } from ".";
 import { Localizer } from "../localization";
 import { HttpClient } from "../http";
-import type { Logger } from "../logging";
+import type { Logger, LoggerFactory, LoggingContext } from "../logging";
 import { DiContainer } from "./di-container";
 import {
     DependencyName,
@@ -10,6 +10,7 @@ import {
     EnvironmentMode,
     EnvironmentName,
 } from "./environment";
+import { Clock } from "../datetime/clock";
 
 /**
  * Abstract base class for shared functionality across different environments
@@ -30,15 +31,28 @@ export abstract class AbstractEnvironment<
 
     private _diContainer: DiContainer<D>;
 
+    /**
+     * Get the currently configured clock
+     */
+    getClock(): Clock {
+        const clock = this.getInjectable<Clock>(DependencyName.Clock);
+        if (!clock) {
+            throw new Error("No clock configured for the current environment");
+        }
+        return clock;
+    }
+
     /**
      * Get an instance of the global logger
      */
-    getLogger(): Logger {
-        const logger = this.getInjectable<Logger>(DependencyName.Logger);
-        if (!logger) {
+    getLogger(context: string | LoggingContext): Logger {
+        const createLogger = this.getInjectable<LoggerFactory>(
+            DependencyName.LoggerFactory
+        );
+        if (!createLogger) {
             throw new Error("No logger configured for the current environment");
         }
-        return logger;
+        return createLogger(context);
     }
 
     /**

packages/common/src/ui-common/environment/environment.ts

@@ -1,6 +1,7 @@
+import { Clock } from "../datetime/clock";
 import { HttpClient } from "../http";
 import { Localizer } from "../localization";
-import type { Logger } from "../logging";
+import type { Logger, LoggerFactory, LoggingContext } from "../logging";
 
 /**
  * Represents the execution environment of the application. Acts as a
@@ -25,10 +26,15 @@ export interface Environment<C extends EnvironmentConfig> {
      */
     readonly initialized: boolean;
 
+    /**
+     * Gets the currently configured clock
+     */
+    getClock(): Clock;
+
     /**
      * Gets the logger for the current environment
      */
-    getLogger(): Logger;
+    getLogger(context: string | LoggingContext): Logger;
 
     /**
      * Gets the localizer for the current environment
@@ -78,7 +84,8 @@ export interface Environment<C extends EnvironmentConfig> {
 }
 
 export enum DependencyName {
-    Logger = "logger",
+    Clock = "clock",
+    LoggerFactory = "loggerFactory",
     Localizer = "localizer",
     HttpClient = "httpClient",
 }
@@ -88,7 +95,8 @@ export enum DependencyName {
  * be defined as strings in the DependencyName enum.
  */
 export interface DependencyFactories {
-    [DependencyName.Logger]: () => Logger;
+    [DependencyName.Clock]: () => Clock;
+    [DependencyName.LoggerFactory]: () => LoggerFactory;
     [DependencyName.Localizer]: () => Localizer;
     [DependencyName.HttpClient]: () => HttpClient;
 }

packages/common/src/ui-common/environment/mock-environment.ts

@@ -1,8 +1,9 @@
 import { DependencyFactories } from ".";
 import { setLocalTimeZoneOffset } from "../datetime";
+import { FakeClock } from "../datetime/fake-clock";
 import { MockHttpClient } from "../http/mock-http-client";
 import { StandardLocalizer } from "../localization/standard-localizer";
-import { MockLogger } from "../logging";
+import { createMockLogger } from "../logging";
 import { AbstractEnvironment } from "./abstract-environment";
 import {
     EnvironmentName,
@@ -15,7 +16,8 @@ export const mockEnvironmentConfig: EnvironmentConfig = {
 };
 
 export const mockDependencyFactories: DependencyFactories = {
-    logger: () => new MockLogger(),
+    clock: () => new FakeClock(),
+    loggerFactory: () => createMockLogger,
     localizer: () => new StandardLocalizer(),
     httpClient: () => new MockHttpClient(),
 };