homeio

1import { afterEach, beforeEach, describe, expect, it, vi } from "vitest";
2
3describe("server logger", () => {
4  const originalNodeEnv = process.env.NODE_ENV;
5
6  beforeEach(() => {
7    vi.resetModules();
8  });
9
10  afterEach(() => {
11    process.env.NODE_ENV = originalNodeEnv;
12    vi.unstubAllEnvs();
13  });
14
15  it("writes structured logs to console and file", async () => {
16    process.env.NODE_ENV = "development";
17
18    const appendFile = vi.fn(async () => undefined);
19    const mkdir = vi.fn(async () => undefined);
20    const stat = vi.fn(async () => ({ size: 0 }));
21    const rename = vi.fn(async () => undefined);
22
23    vi.doMock("node:fs/promises", () => ({ appendFile, mkdir, stat, rename }));
24    vi.doMock("@/lib/server/env", () => ({
25      serverEnv: {
26        LOG_LEVEL: "info",
27        LOG_FILE_PATH: "logs/test.log",
28        LOG_TO_FILE: true,
29      },
30    }));
31
32    const logSpy = vi.spyOn(console, "log").mockImplementation(() => {});
33
34    const { flushServerLogsForTests, logServerAction } = await import(
35      "@/lib/server/logging/logger"
36    );
37
38    logServerAction({
39      layer: "api",
40      action: "health.get",
41      status: "success",
42      meta: { requestId: "r1" },
43    });
44
45    await flushServerLogsForTests();
46
47    expect(logSpy).toHaveBeenCalledTimes(1);
48    expect(mkdir).toHaveBeenCalledTimes(1);
49    expect(appendFile).toHaveBeenCalledTimes(1);
50    expect(String(appendFile.mock.calls[0][1])).toContain('"action":"health.get"');
51  });
52
53  it("appends lines logged together in one write", async () => {
54    vi.stubEnv("NODE_ENV", "development");
55    const appendFile = vi.fn(async (_path: string, _data: string) => undefined);
56    vi.doMock("node:fs/promises", () => ({
57      appendFile,
58      mkdir: vi.fn(async () => undefined),
59      stat: vi.fn(async () => ({ size: 0 })),
60      rename: vi.fn(async () => undefined),
61    }));
62    vi.doMock("@/lib/server/env", () => ({
63      serverEnv: { LOG_LEVEL: "info", LOG_FILE_PATH: "logs/test.log", LOG_TO_FILE: true },
64    }));
65    vi.spyOn(console, "log").mockImplementation(() => {});
66    const { flushServerLogsForTests, logServerAction } = await import("@/lib/server/logging/logger");
67
68    for (const action of ["one", "two", "three"]) {
69      logServerAction({ layer: "api", action, status: "success" });
70    }
71    await flushServerLogsForTests();
72
73    expect(appendFile).toHaveBeenCalledTimes(1);
74    const written = String(appendFile.mock.calls[0][1]);
75    expect(written.trim().split("\n")).toHaveLength(3);
76  });
77
78  it("rotates the file once it would grow past 10 MB", async () => {
79    vi.stubEnv("NODE_ENV", "development");
80    const appendFile = vi.fn(async (_path: string, _data: string) => undefined);
81    const rename = vi.fn(async (_from: string, _to: string) => undefined);
82    vi.doMock("node:fs/promises", () => ({
83      appendFile,
84      rename,
85      mkdir: vi.fn(async () => undefined),
86      stat: vi.fn(async () => ({ size: 10 * 1024 * 1024 - 10 })),
87    }));
88    vi.doMock("@/lib/server/env", () => ({
89      serverEnv: { LOG_LEVEL: "info", LOG_FILE_PATH: "/var/log/homeio/test.log", LOG_TO_FILE: true },
90    }));
91    vi.spyOn(console, "log").mockImplementation(() => {});
92    const { flushServerLogsForTests, logServerAction } = await import("@/lib/server/logging/logger");
93
94    logServerAction({ layer: "api", action: "health.get", status: "success" });
95    await flushServerLogsForTests();
96
97    expect(rename).toHaveBeenCalledWith("/var/log/homeio/test.log", "/var/log/homeio/test.log.1");
98    expect(rename.mock.invocationCallOrder[0]).toBeLessThan(appendFile.mock.invocationCallOrder[0]);
99  });
100
101  it("logs and rethrows timed operation errors", async () => {
102    const errorSpy = vi.spyOn(console, "error").mockImplementation(() => {});
103
104    vi.doMock("@/lib/server/env", () => ({
105      serverEnv: {
106        LOG_LEVEL: "debug",
107        LOG_FILE_PATH: "logs/test.log",
108        LOG_TO_FILE: false,
109      },
110    }));
111
112    const { withServerTiming } = await import("@/lib/server/logging/logger");
113
114    await expect(
115      withServerTiming(
116        {
117          layer: "db",
118          action: "pg.query",
119        },
120        async () => {
121          throw new Error("boom");
122        },
123      ),
124    ).rejects.toThrow("boom");
125
126    expect(errorSpy).toHaveBeenCalled();
127  });
128
129  it("suppresses debug logs when the server log level is info", async () => {
130    vi.doMock("@/lib/server/env", () => ({
131      serverEnv: {
132        LOG_LEVEL: "info",
133        LOG_FILE_PATH: "logs/test.log",
134        LOG_TO_FILE: false,
135      },
136    }));
137
138    const logSpy = vi.spyOn(console, "log").mockImplementation(() => {});
139
140    const { withServerTiming } = await import("@/lib/server/logging/logger");
141
142    await withServerTiming(
143      {
144        level: "debug",
145        layer: "api",
146        action: "network.status.get",
147      },
148      async () => "ok",
149    );
150
151    expect(logSpy).not.toHaveBeenCalled();
152  });
153});
154