From 7b0adde83a6967e05d85b2f159eaa35bad6267bf Mon Sep 17 00:00:00 2001 From: Chris Knight Date: Mon, 1 May 2023 15:11:32 +0100 Subject: [PATCH] Auto flush (#9) * feat: auto-flush file buffer * feat: auto-flush file buffer * chore: upgrade to Deno 1.32.1/typescript v5 * Empty-Commit * test: add debug output for failing CI * Empty-Commit * test: remove debug output * test: attempt to fix bizarre CI failure * test: attempt to fix bizarre CI failure * test: attempt to fix bizarre CI failure * test: attempt to fix bizarre CI failure * test: attempt to fix bizarre CI failure * test: attempt to fix bizarre CI failure * test: attempt to fix bizarre CI failure * test: attempt to fix bizarre CI failure * test: attempt to fix bizarre CI failure * test: attempt to fix bizarre CI failure --- .github/workflows/optic-ci.yml | 2 +- deps.ts | 2 +- formatters/color.ts | 4 +-- formatters/color_test.ts | 3 -- formatters/tokenReplacer_test.ts | 16 ++++++----- logger/dedupe.ts | 8 +++++- logger/levels.ts | 31 ++++++++++++--------- logger/levels_test.ts | 4 +-- logger/logger_test.ts | 8 +++--- logger/profileMeasure_test.ts | 15 ++++++++++ project_utils/pre-commit.sh | 18 +++++++++++- streams/fileStream/README.md | 15 ++++++++++ streams/fileStream/deps.ts | 6 ++-- streams/fileStream/fileStream.ts | 29 +++++++++++++++++-- streams/fileStream/fileStream_test.ts | 29 +++++++++++++++++++ test_deps.ts | 2 +- utils/timeInterval.ts | 37 +++++++++++++++++++++++++ utils/timeInterval_test.ts | 40 +++++++++++++++++++++++++++ 18 files changed, 227 insertions(+), 42 deletions(-) create mode 100644 utils/timeInterval.ts create mode 100644 utils/timeInterval_test.ts diff --git a/.github/workflows/optic-ci.yml b/.github/workflows/optic-ci.yml index bebb4d6..a3e85ac 100644 --- a/.github/workflows/optic-ci.yml +++ b/.github/workflows/optic-ci.yml @@ -13,7 +13,7 @@ jobs: - name: download deno uses: denolib/setup-deno@v2 with: - deno-version: v1.30.3 + deno-version: v1.32.1 - name: check format if: matrix.os == 'ubuntu-latest' run: deno fmt --check diff --git a/deps.ts b/deps.ts index d3ce0e9..3ba99a0 100644 --- a/deps.ts +++ b/deps.ts @@ -5,4 +5,4 @@ export { gray, red, yellow, -} from "https://deno.land/std@0.180.0/fmt/colors.ts"; +} from "https://deno.land/std@0.181.0/fmt/colors.ts"; diff --git a/formatters/color.ts b/formatters/color.ts index c25be66..93c8fef 100644 --- a/formatters/color.ts +++ b/formatters/color.ts @@ -12,14 +12,14 @@ export type ColorRule = (msg: string) => string; * A map of coloring rules per log level. Custom log levels may also register * a new color rule, and existing levels may be updated with new rules too. */ -const colorRules: Map = new Map(); +export const colorRules: Map = new Map(); colorRules.set(Level.Debug, (msg: string) => gray(msg)); colorRules.set(Level.Info, (msg: string) => blue(msg)); colorRules.set(Level.Warn, (msg: string) => yellow(msg)); colorRules.set(Level.Error, (msg: string) => red(msg)); colorRules.set(Level.Critical, (msg: string) => bold(red(msg))); -export function getColorForLevel(level: number): ColorRule { +export function getColorForLevel(level: Level): ColorRule { const color: ColorRule | undefined = colorRules.get(level); return color ? color : (msg: string) => msg; } diff --git a/formatters/color_test.ts b/formatters/color_test.ts index 7647b1b..383509a 100644 --- a/formatters/color_test.ts +++ b/formatters/color_test.ts @@ -11,8 +11,5 @@ test({ assert(typeof getColorForLevel(Level.Warn) === "function"); assert(typeof getColorForLevel(Level.Error) === "function"); assert(typeof getColorForLevel(Level.Critical) === "function"); - - // unrecognized level - assert(getColorForLevel(9999)("msg") === "msg"); }, }); diff --git a/formatters/tokenReplacer_test.ts b/formatters/tokenReplacer_test.ts index b84e72b..f2c595c 100644 --- a/formatters/tokenReplacer_test.ts +++ b/formatters/tokenReplacer_test.ts @@ -8,8 +8,9 @@ import { } from "../test_deps.ts"; import { TokenReplacer } from "./tokenReplacer.ts"; import { Level } from "../logger/levels.ts"; -import { gray } from "../deps.ts"; +import { gray, yellow } from "../deps.ts"; import { ValidationError } from "../types.ts"; +import { colorRules } from "./color.ts"; const lr = { msg: "Log Message", @@ -159,23 +160,24 @@ test({ test({ name: "Given no color available for level, then no coloring is applied", fn() { + colorRules.delete(Level.Warn); const tr = new TokenReplacer().withColor(); - lr.level = 99; + lr.level = Level.Warn; assertEquals( tr.format(lr), - "2020-06-17T02:24:00.000Z UNKNOWN Log Message The metadata", - // dateTime: new Date("2020-06-17T03:24:00"), + "2020-06-17T02:24:00.000Z Warn Log Message The metadata", ); + colorRules.set(Level.Warn, (msg: string) => yellow(msg)); }, }); + test({ name: "Logger name is a valid token", fn() { - const tr = new TokenReplacer().withFormat("{msg} {logger}"); - lr.level = 99; + const tr = new TokenReplacer().withFormat("{msg} (logger: {logger})"); assertEquals( tr.format(lr), - "Log Message default", + "Log Message (logger: default)", ); }, }); diff --git a/logger/dedupe.ts b/logger/dedupe.ts index 04b9a0c..d683a4d 100644 --- a/logger/dedupe.ts +++ b/logger/dedupe.ts @@ -1,13 +1,19 @@ // Copyright 2020-2023 the optic authors. All rights reserved. MIT license. import { LogRecord, Stream } from "../types.ts"; import { asString } from "../utils/asString.ts"; +import { Level } from "./levels.ts"; import { ImmutableLogRecord } from "./logRecord.ts"; import { LogMetaImpl } from "./meta.ts"; export class Dedupe { #streams: Stream[]; #meta: LogMetaImpl; - #lastLogRecord: LogRecord = new ImmutableLogRecord(undefined, [], 0, ""); + #lastLogRecord: LogRecord = new ImmutableLogRecord( + undefined, + [], + Level.Debug, + "", + ); #lastLogString = ""; #dupeCount = 0; diff --git a/logger/levels.ts b/logger/levels.ts index 74dc576..638e11b 100644 --- a/logger/levels.ts +++ b/logger/levels.ts @@ -9,15 +9,15 @@ export enum Level { Critical = 60, } -const levelMap = new Map(); -levelMap.set(10, "Trace"); -levelMap.set(20, "Debug"); -levelMap.set(30, "Info"); -levelMap.set(40, "Warn"); -levelMap.set(50, "Error"); -levelMap.set(60, "Critical"); - -const levelNameMap = new Map(); +const levelMap = new Map(); +levelMap.set(Level.Trace, "Trace"); +levelMap.set(Level.Debug, "Debug"); +levelMap.set(Level.Info, "Info"); +levelMap.set(Level.Warn, "Warn"); +levelMap.set(Level.Error, "Error"); +levelMap.set(Level.Critical, "Critical"); + +const levelNameMap = new Map(); levelNameMap.set("Trace", Level.Trace); levelNameMap.set("Debug", Level.Debug); levelNameMap.set("Info", Level.Info); @@ -31,9 +31,9 @@ export function levelToName(level: Level): string { return levelAsString ? levelAsString : "UNKNOWN"; } -/** Translate string value to Level, or 1 if not found */ -export function nameToLevel(name: string): number { - const level: number | undefined = levelNameMap.get(name); +/** Translate string value to Level, or Level.Info if not found */ +export function nameToLevel(name: string): Level { + const level: Level | undefined = levelNameMap.get(name); //try a case insentive match if (level === undefined) { @@ -44,7 +44,12 @@ export function nameToLevel(name: string): number { } } - return level === undefined ? 1 : level; + if (!level) { + console.log(`Unknown log level: ${name}, defaulting to 'Info'`); + return Level.Info; + } + + return level; } /** Returns the length of the longest log level name. This is used when diff --git a/logger/levels_test.ts b/logger/levels_test.ts index e63552a..3e08f3d 100644 --- a/logger/levels_test.ts +++ b/logger/levels_test.ts @@ -11,8 +11,6 @@ test({ assertEquals(levelToName(Level.Warn), "Warn"); assertEquals(levelToName(Level.Error), "Error"); assertEquals(levelToName(Level.Critical), "Critical"); - assertEquals(levelToName(0), "UNKNOWN"); - assertEquals(levelToName(999), "UNKNOWN"); }, }); @@ -25,7 +23,7 @@ test({ assertEquals(nameToLevel("Warn"), Level.Warn); assertEquals(nameToLevel("Error"), Level.Error); assertEquals(nameToLevel("Critical"), Level.Critical); - assertEquals(nameToLevel("made up level"), 1); + assertEquals(nameToLevel("made up level"), Level.Info); }, }); diff --git a/logger/logger_test.ts b/logger/logger_test.ts index d20295b..c10ce14 100644 --- a/logger/logger_test.ts +++ b/logger/logger_test.ts @@ -135,14 +135,14 @@ test({ }); test({ - name: "Logger min level set to 1 if rubbish set for cli argument", + name: "Logger min level set to Level.Info if rubbish set for cli argument", fn() { const logger = new class extends Logger { protected getArgs(): string[] { return ["minLogLevel=rubbish!"]; } }(); - assertEquals(logger.addStream(new TestStream()).minLogLevel(), 1); + assertEquals(logger.addStream(new TestStream()).minLogLevel(), Level.Info); }, }); @@ -166,7 +166,7 @@ test({ }); test({ - name: "Logger min level set to 1 if rubbish set for env variable", + name: "Logger min level set to Level.Info if rubbish set for env variable", fn() { const logger = new class extends Logger { protected getEnv(): { get(key: string): string | undefined } { @@ -177,7 +177,7 @@ test({ }; } }(); - assertEquals(logger.addStream(new TestStream()).minLogLevel(), 1); + assertEquals(logger.addStream(new TestStream()).minLogLevel(), Level.Info); }, }); diff --git a/logger/profileMeasure_test.ts b/logger/profileMeasure_test.ts index 8f410b4..07e27e5 100644 --- a/logger/profileMeasure_test.ts +++ b/logger/profileMeasure_test.ts @@ -169,6 +169,21 @@ test({ startOfTestMark, getMark({ label: "Now", memory: true, ops: false }), ); + + assert( + outputWithHeapIncrease.startsWith( + "Measuring 'start of test' -> 'Now', took ", + ), + ); + + assert( + /.*\d+(?:\.\d+)?ms;.*/.test(outputWithHeapIncrease), + ); + + assert( + outputWithHeapIncrease.includes(""), + ); + assert( /^Measuring 'start of test' -> 'Now', took \d+(?:\.\d+)?ms; heap usage increased \d+\.\d+ [A-Z]{2} to \d+\.\d+ [A-Z]{2}$/ .test(outputWithHeapIncrease), diff --git a/project_utils/pre-commit.sh b/project_utils/pre-commit.sh index 728c5e6..2343ed3 100755 --- a/project_utils/pre-commit.sh +++ b/project_utils/pre-commit.sh @@ -8,17 +8,21 @@ rm -f *.log* rm -f *_log.file_* rm -rf coverage +echo '' echo '*** Adding to git' git add . +echo '' echo '*** Updating dependencies' udd ./deps.ts udd ./test_deps.ts udd ./streams/fileStream/deps.ts +echo '' echo '*** Formatting code' deno fmt +echo '' echo '*** Linting code ***' deno lint @@ -26,19 +30,31 @@ deno lint #deno test -A --coverage=cov_profile #deno coverage cov_profile --lcov > cov_profile/cov.lcov #genhtml -o cov_profile/html cov_profile/cov.lcov - +echo '' +echo '*** Testing code' deno test -A +echo '' echo '*** Check license and copyright headers' deno run --allow-read=. https://deno.land/x/copyright_license_checker@1.1.1/checker.ts project_utils/header_config.json +if [ $? -eq 0 ]; then + echo '' +else + echo '---License and copyright headers are NOT OK---' + echo 'Run: deno run --allow-read=. --allow-write=. https://deno.land/x/copyright_license_checker@1.1.1/updater.ts project_utils/header_config.json' + echo '' +fi + echo '*** Check unstable also compiles' deno cache --reload --unstable mod.ts deno cache --reload --unstable streams/fileStream/mod.ts +echo '' echo '*** Checking git status' git status +echo '' echo '#####' echo "Latest tag is: $(git describe --abbrev=0)" echo 'To sign a new tag: git tag -s 1.3.13 -m "your tag message"' diff --git a/streams/fileStream/README.md b/streams/fileStream/README.md index c285fde..cf4eb48 100644 --- a/streams/fileStream/README.md +++ b/streams/fileStream/README.md @@ -54,6 +54,21 @@ The buffer is flushed in the following scenarios: event) - `flush()` is called manually. (e.g. `fileStream.flush()`) +### Auto-flushing + +You can also setup an auto-flush interval which will flush the buffer on a +regular basis. Example: + +```typescript +import { FileStream } from "https://deno.land/x/optic/streams/fileStream/mod.ts"; +import { intervalOf } from "https://deno.land/x/optic/utils/timeInterval.ts"; + +const fileStream = new FileStream("./logFile.txt") + .withAutoFlushEvery(intervalOf(5).seconds()); +``` + +which will flush the logs to the filesystem every 5 seconds. + ## Log file initialization A log file may already exist when your logger initializes. You can control what diff --git a/streams/fileStream/deps.ts b/streams/fileStream/deps.ts index fad2e42..bc9f340 100644 --- a/streams/fileStream/deps.ts +++ b/streams/fileStream/deps.ts @@ -2,9 +2,9 @@ export { basename as posixBasename, dirname as posixDirname, -} from "https://deno.land/std@0.180.0/path/posix.ts"; +} from "https://deno.land/std@0.181.0/path/posix.ts"; export { basename as win32Basename, dirname as win32Dirname, -} from "https://deno.land/std@0.180.0/path/win32.ts"; -export { BufWriterSync } from "https://deno.land/std@0.180.0/io/buf_writer.ts"; +} from "https://deno.land/std@0.181.0/path/win32.ts"; +export { BufWriterSync } from "https://deno.land/std@0.181.0/io/buf_writer.ts"; diff --git a/streams/fileStream/fileStream.ts b/streams/fileStream/fileStream.ts index c78fa5f..0d2c56a 100644 --- a/streams/fileStream/fileStream.ts +++ b/streams/fileStream/fileStream.ts @@ -5,6 +5,7 @@ import { TokenReplacer } from "../../formatters/tokenReplacer.ts"; import { Level } from "../../logger/levels.ts"; import { LogFileInitStrategy, RotationStrategy } from "./types.ts"; import { BufWriterSync } from "./deps.ts"; +import { TimeInterval } from "../../utils/timeInterval.ts"; /** * A stream for log messages to go to a file. You may also configure the following: @@ -23,7 +24,6 @@ export class FileStream extends BaseStream { #deferredLogQueue: LogRecord[] = []; #encoder = new TextEncoder(); #autoFlushId = -1; - #autoFlushInterval = -1; constructor(filename: string) { super(new TokenReplacer()); @@ -53,6 +53,9 @@ export class FileStream extends BaseStream { destroy(): void { this.flush(); + if (this.#autoFlushId !== -1) { + clearInterval(this.#autoFlushId); + } super.destroy(); this.#logFile.close(); } @@ -133,7 +136,7 @@ export class FileStream extends BaseStream { return this; } - /** The maximum size in bytes of the buffer storage before it is flushed. */ + /** The maximum size in bytes of the buffer storage before it is flushed (default is 8192, e.g. 8kb)*/ withBufferSize(bytes: number): this { if (bytes < 0) { throw new ValidationError("Buffer size cannot be negative"); @@ -142,6 +145,28 @@ export class FileStream extends BaseStream { return this; } + /** Automatically flush the log buffer every `amount` of time. Examples: + * ```typescript + * withAutoFlushEvery(intervalOf(5).seconds()) + * withAutoFlushEvery(intervalOf(4).minutes()) + * withAutoFlushEvery(intervalOf(3).hours()) + * withAutoFlushEvery(intervalOf(2).days()) + * ``` + */ + withAutoFlushEvery(amount: TimeInterval): this { + if (this.#autoFlushId !== -1) { + clearInterval(this.#autoFlushId); + } + + this.#autoFlushId = setInterval(() => { + this.flush(); + }, amount.getPeriod() * 1000); + + Deno.unrefTimer(this.#autoFlushId); + + return this; + } + /** The strategy to take when initializing logs: * * `"append"` - Reuse log file if it exists, create otherwise * * `"overwrite"` - Always start with an empty log file, overwriting any existing one diff --git a/streams/fileStream/fileStream_test.ts b/streams/fileStream/fileStream_test.ts index 33e894d..468f118 100644 --- a/streams/fileStream/fileStream_test.ts +++ b/streams/fileStream/fileStream_test.ts @@ -10,6 +10,7 @@ import { LogMetaImpl } from "../../logger/meta.ts"; import { Level } from "../../logger/levels.ts"; import { LogRecord, ValidationError } from "../../types.ts"; import { BufWriterSync } from "./deps.ts"; +import { intervalOf } from "../../utils/timeInterval.ts"; const LOG_FILE = "./logFile.txt"; const ENCODER = new TextEncoder(); @@ -274,3 +275,31 @@ test({ Deno.removeSync(LOG_FILE); }, }); + +test({ + name: "Auto flush should flush buffer on interval", + async fn() { + const fs = new TestableFileStream(LOG_FILE).withAutoFlushEvery( + intervalOf(1).seconds(), + ); + fs.setup(); + fs.log("hello world"); + + //Assert that the log file is empty after 200ms, e.g. the buffer hasn't been flushed yet + await new Promise((res) => { + setTimeout((): void => { + assertEquals(readFile(LOG_FILE), ""); + res(); + }, 500); + }); + + await new Promise((res) => { + setTimeout((): void => { + assertEquals(readFile(LOG_FILE), "hello world\n"); + fs.destroy(); + Deno.removeSync(LOG_FILE); + res(); + }, 600); //600ms + 500ms = 1100ms which is greater than the 1 second interval + }); + }, +}); diff --git a/test_deps.ts b/test_deps.ts index 31fe0c7..72811cc 100644 --- a/test_deps.ts +++ b/test_deps.ts @@ -9,4 +9,4 @@ export { assertStrictEquals, assertStringIncludes, assertThrows, -} from "https://deno.land/std@0.180.0/testing/asserts.ts"; +} from "https://deno.land/std@0.181.0/testing/asserts.ts"; diff --git a/utils/timeInterval.ts b/utils/timeInterval.ts new file mode 100644 index 0000000..6bc887c --- /dev/null +++ b/utils/timeInterval.ts @@ -0,0 +1,37 @@ +// Copyright 2020-2023 the optic authors. All rights reserved. MIT license. +import { IllegalStateError } from "../types.ts"; + +export function intervalOf(period: number): OngoingInterval { + return new OngoingInterval(period); +} + +class OngoingInterval { + constructor(private period: number) { + if (period < 1) { + throw new IllegalStateError("Invalid interval period: " + period); + } + } + seconds(): TimeInterval { + return new TimeInterval(this.period); + } + minutes(): TimeInterval { + return new TimeInterval(this.period * 60); + } + hours(): TimeInterval { + return new TimeInterval(this.period * 60 * 60); + } + days(): TimeInterval { + return new TimeInterval(this.period * 60 * 60 * 24); + } +} + +export class TimeInterval { + constructor(private period: number) { + if (period < 1) { + throw new IllegalStateError("Invalid interval period: " + period); + } + } + getPeriod(): number { + return this.period; + } +} diff --git a/utils/timeInterval_test.ts b/utils/timeInterval_test.ts new file mode 100644 index 0000000..c4ab614 --- /dev/null +++ b/utils/timeInterval_test.ts @@ -0,0 +1,40 @@ +// Copyright 2020-2023 the optic authors. All rights reserved. MIT license. +import { assertEquals, assertThrows } from "../test_deps.ts"; +import { intervalOf, TimeInterval } from "./timeInterval.ts"; + +Deno.test({ + name: "timeInterval should have valid input", + fn() { + const interval = new TimeInterval(1); + assertEquals(interval.getPeriod(), 1); + assertThrows( + () => new TimeInterval(0), + Error, + "Invalid interval period: 0", + ); + }, +}); + +Deno.test({ + name: "intervalOf should have valid input", + fn() { + const interval = intervalOf(1); + assertEquals(interval.seconds().getPeriod(), 1); + assertThrows( + () => intervalOf(0), + Error, + "Invalid interval period: 0", + ); + }, +}); + +Deno.test({ + name: "different time intervals should have different periods", + fn() { + const interval = intervalOf(1); + assertEquals(interval.seconds().getPeriod(), 1); + assertEquals(interval.minutes().getPeriod(), 60); + assertEquals(interval.hours().getPeriod(), 3600); + assertEquals(interval.days().getPeriod(), 86400); + }, +});