Merge pull request #12 from mcndt/event-logging

Event logging to database

server/prisma/migrations/20220808203936_event_table/migration.sql

@@ -0,0 +1,12 @@
+-- CreateTable
+CREATE TABLE "event" (
+    "id" INTEGER NOT NULL PRIMARY KEY AUTOINCREMENT,
+    "time" DATETIME NOT NULL DEFAULT CURRENT_TIMESTAMP,
+    "type" TEXT NOT NULL,
+    "success" BOOLEAN NOT NULL,
+    "size_bytes" INTEGER,
+    "purge_count" INTEGER,
+    "host" TEXT,
+    "error" TEXT,
+    "expire_window_days" INTEGER
+);

server/prisma/migrations/20220808205230_update_event_table/migration.sql

@@ -0,0 +1,24 @@
+/*
+  Warnings:
+
+  - You are about to drop the column `purge_count` on the `event` table. All the data in the column will be lost.
+
+*/
+-- RedefineTables
+PRAGMA foreign_keys=OFF;
+CREATE TABLE "new_event" (
+    "id" INTEGER NOT NULL PRIMARY KEY AUTOINCREMENT,
+    "time" DATETIME NOT NULL DEFAULT CURRENT_TIMESTAMP,
+    "type" TEXT NOT NULL,
+    "success" BOOLEAN NOT NULL,
+    "size_bytes" INTEGER,
+    "note_id" TEXT,
+    "host" TEXT,
+    "error" TEXT,
+    "expire_window_days" INTEGER
+);
+INSERT INTO "new_event" ("error", "expire_window_days", "host", "id", "size_bytes", "success", "time", "type") SELECT "error", "expire_window_days", "host", "id", "size_bytes", "success", "time", "type" FROM "event";
+DROP TABLE "event";
+ALTER TABLE "new_event" RENAME TO "event";
+PRAGMA foreign_key_check;
+PRAGMA foreign_keys=ON;

server/prisma/schema.prisma

@@ -17,3 +17,15 @@ model EncryptedNote {
   ciphertext  String
   hmac        String
 }
+
+model event {
+  id                 Int      @id @default(autoincrement())
+  time               DateTime @default(now())
+  type               String
+  success            Boolean
+  size_bytes         Int?
+  note_id            String?
+  host               String?
+  error              String?
+  expire_window_days Int?
+}

server/src/EventLogger.integration.test.ts

@@ -0,0 +1,77 @@
+import { describe, it, expect } from "vitest";
+import EventLogger, { EventType } from "./EventLogger";
+import prisma from "./client";
+
+describe("Logging write events", () => {
+  it("Should write a write event to database", async () => {
+    const testWriteEvent = {
+      host: "localhost",
+      note_id: "test_id",
+      size_bytes: 100,
+      success: true,
+      expire_window_days: 30,
+    };
+
+    // Is event written successfully?
+    const logged = await EventLogger.writeEvent(testWriteEvent);
+    expect(logged).not.toBeNull();
+    expect(logged).toMatchObject(testWriteEvent);
+
+    // Is event in database?
+    const results = await prisma.event.findMany({
+      where: { type: EventType.WRITE, note_id: testWriteEvent.note_id },
+    });
+    expect(results.length).toBe(1);
+
+    // Are default fields populated?
+    expect(logged.time).not.toBeNull();
+    expect(logged.id).not.toBeNull();
+  });
+
+  it("Should log a read event to database", async () => {
+    const testReadEvent = {
+      host: "localhost",
+      note_id: "test_id",
+      size_bytes: 100,
+      success: true,
+    };
+
+    // Is event written successfully?
+    const logged = await EventLogger.readEvent(testReadEvent);
+    expect(logged).not.toBeNull();
+    expect(logged).toMatchObject(testReadEvent);
+
+    // Is event in database?
+    const results = await prisma.event.findMany({
+      where: { type: EventType.READ, note_id: testReadEvent.note_id },
+    });
+    expect(results.length).toBe(1);
+
+    // Are default fields populated?
+    expect(logged.time).not.toBeNull();
+    expect(logged.id).not.toBeNull();
+  });
+
+  it("Should log a purge event to database", async () => {
+    const testPurgeEvent = {
+      note_id: "test_id",
+      size_bytes: 100,
+      success: true,
+    };
+
+    // Is event written successfully?
+    const logged = await EventLogger.purgeEvent(testPurgeEvent);
+    expect(logged).not.toBeNull();
+    expect(logged).toMatchObject(testPurgeEvent);
+
+    // Is event in database?
+    const results = await prisma.event.findMany({
+      where: { type: EventType.PURGE, note_id: "test_id" },
+    });
+    expect(results.length).toBe(1);
+
+    // Are default fields populated?
+    expect(logged.time).not.toBeNull();
+    expect(logged.id).not.toBeNull();
+  });
+});

server/src/EventLogger.ts

@@ -0,0 +1,51 @@
+import prisma from "./client";
+import { event } from "@prisma/client";
+
+export enum EventType {
+  WRITE = "WRITE",
+  READ = "READ",
+  PURGE = "PURGE",
+}
+
+interface Event {
+  success: boolean;
+  error?: string;
+}
+
+interface ClientEvent extends Event {
+  host: string;
+  success: boolean;
+  note_id?: string;
+  size_bytes?: number;
+}
+
+interface WriteEvent extends ClientEvent {
+  expire_window_days?: number;
+}
+
+interface ReadEvent extends ClientEvent {}
+
+interface PurgeEvent extends Event {
+  note_id: string;
+  size_bytes?: number;
+}
+
+export default class EventLogger {
+  public static writeEvent(event: WriteEvent): Promise<event> {
+    return prisma.event.create({
+      data: { type: EventType.WRITE, ...event },
+    });
+  }
+
+  public static readEvent(event: ReadEvent): Promise<event> {
+    return prisma.event.create({
+      data: { type: EventType.READ, ...event },
+    });
+  }
+
+  public static purgeEvent(event: PurgeEvent): Promise<event> {
+    return prisma.event.create({
+      data: { type: EventType.PURGE, ...event },
+    });
+  }
+}

server/src/app.integration.test.ts

@@ -2,6 +2,7 @@ import app, { cleanExpiredNotes } from "./app";
 import request from "supertest";
 import { describe, it, expect } from "vitest";
 import prisma from "./client";
+import { EventType } from "./EventLogger";
 
 // const testNote with base64 ciphertext and hmac
 const testNote = {
@@ -29,6 +30,16 @@ describe("GET /api/note", () => {
     expect(res.body.id).toEqual(id);
     expect(res.body.ciphertext).toEqual(testNote.ciphertext);
     expect(res.body.hmac).toEqual(testNote.hmac);
+
+    // Is a read event logged?
+    const readEvents = await prisma.event.findMany({
+      where: { type: EventType.READ, note_id: id },
+    });
+    expect(readEvents.length).toBe(1);
+    expect(readEvents[0].success).toBe(true);
+    expect(readEvents[0].size_bytes).toBe(
+      res.body.ciphertext.length + res.body.hmac.length
+    );
   });
 
   it("responds 404 for invalid ID", async () => {
@@ -37,6 +48,13 @@ describe("GET /api/note", () => {
 
     // Validate returned note
     expect(res.statusCode).toBe(404);
+
+    // Is a read event logged?
+    const readEvents = await prisma.event.findMany({
+      where: { type: EventType.READ, note_id: "NaN" },
+    });
+    expect(readEvents.length).toBe(1);
+    expect(readEvents[0].success).toBe(false);
   });
 
   it("Applies rate limits to endpoint", async () => {
@@ -77,6 +95,17 @@ describe("POST /api/note", () => {
     expect(new Date(res.body.expire_time).getTime()).toBeGreaterThan(
       new Date().getTime()
     );
+
+    // Is a write event logged?
+    const writeEvents = await prisma.event.findMany({
+      where: { type: EventType.WRITE, note_id: res.body.id },
+    });
+    expect(writeEvents.length).toBe(1);
+    expect(writeEvents[0].success).toBe(true);
+    expect(writeEvents[0].expire_window_days).toBe(30);
+    expect(writeEvents[0].size_bytes).toBe(
+      testNote.ciphertext.length + testNote.hmac.length
+    );
   });
 
   it("Returns a bad request on invalid POST body", async () => {
@@ -123,7 +152,7 @@ describe("POST /api/note", () => {
   it("Applies rate limits to endpoint", async () => {
     // make more requests than the post limit set in .env.test
     const requests = [];
-    for (let i = 0; i < 51; i++) {
+    for (let i = 0; i < 52; i++) {
       requests.push(request(app).post("/api/note").send(testNote));
     }
     const responses = await Promise.all(requests);
@@ -158,5 +187,18 @@ describe("Clean expired notes", () => {
     // make sure note is gone
     res = await request(app).get(`/api/note/${id}`);
     expect(res.statusCode).toBe(404);
+
+    // sleep 100ms to allow all events to be logged
+    await new Promise((resolve) => setTimeout(resolve, 200));
+
+    // Is a delete event logged?
+    const deleteEvents = await prisma.event.findMany({
+      where: { type: EventType.PURGE, note_id: id },
+    });
+    expect(deleteEvents.length).toBe(1);
+    expect(deleteEvents[0].success).toBe(true);
+    expect(deleteEvents[0].size_bytes).toBe(
+      testNote.ciphertext.length + testNote.hmac.length
+    );
   });
 });

server/src/app.ts

@@ -10,6 +10,7 @@ import prisma from "./client";
 import bodyParser from "body-parser";
 import { NotePostRequest } from "./model/NotePostRequest";
 import { validateOrReject } from "class-validator";
+import EventLogger from "./EventLogger";
 
 // Initialize middleware clients
 const app: Express = express();
@@ -55,13 +56,34 @@ app.get("/api/note/:id", getLimiter, (req: Request, res: Response, next) => {
     .findUnique({
       where: { id: req.params.id },
     })
-    .then((note) => {
+    .then(async (note) => {
       if (note != null) {
+        await EventLogger.readEvent({
+          success: true,
+          host: req.hostname,
+          note_id: note.id,
+          size_bytes: note.ciphertext.length + note.hmac.length,
+        });
         res.send(note);
+      } else {
+        await EventLogger.readEvent({
+          success: false,
+          host: req.hostname,
+          note_id: req.params.id,
+          error: "Note not found",
+        });
+        res.status(404).send();
       }
-      res.status(404).send();
     })
-    .catch(next);
+    .catch(async (err) => {
+      await EventLogger.readEvent({
+        success: false,
+        host: req.hostname,
+        note_id: req.params.id,
+        error: err.message,
+      });
+      next(err);
+    });
 });
 
 // Post new encrypted note
@@ -72,34 +94,67 @@ app.post("/api/note/", postLimiter, (req: Request, res: Response, next) => {
     res.status(400).send(err.message);
   });
   const note = notePostRequest as EncryptedNote;
+  const EXPIRE_WINDOW_DAYS = 30;
   prisma.encryptedNote
     .create({
       data: {
         ...note,
-        expire_time: addDays(new Date(), 30),
+        expire_time: addDays(new Date(), EXPIRE_WINDOW_DAYS),
       },
     })
-    .then((savedNote) => {
+    .then(async (savedNote) => {
+      await EventLogger.writeEvent({
+        success: true,
+        host: req.hostname,
+        note_id: savedNote.id,
+        size_bytes: savedNote.ciphertext.length + savedNote.hmac.length,
+        expire_window_days: EXPIRE_WINDOW_DAYS,
+      });
       res.json({
         view_url: `${process.env.FRONTEND_URL}/note/${savedNote.id}`,
         expire_time: savedNote.expire_time,
       });
     })
-    .catch(next);
+    .catch(async (err) => {
+      await EventLogger.writeEvent({
+        success: false,
+        host: req.hostname,
+        error: err.message,
+      });
+      next(err);
+    });
 });
 
 // Clean up expired notes periodically
 export async function cleanExpiredNotes(): Promise<number> {
   logger.info("[Cleanup] Cleaning up expired notes...");
+
+  const toDelete = await prisma.encryptedNote.findMany({
+    where: {
+      expire_time: {
+        lte: new Date(),
+      },
+    },
+  });
+
   return prisma.encryptedNote
     .deleteMany({
-      where: {
-        expire_time: {
-          lte: new Date(),
-        },
-      },
+      where: { id: { in: toDelete.map((note) => note.id) } },
     })
-    .then((deleted) => {
+    .then(async (deleted) => {
+      const logs = toDelete.map(async (note) => {
+        logger.info(
+          `[Cleanup] Deleted note ${note.id} with size ${
+            note.ciphertext.length + note.hmac.length
+          } bytes`
+        );
+        return EventLogger.purgeEvent({
+          success: true,
+          note_id: note.id,
+          size_bytes: note.ciphertext.length + note.hmac.length,
+        });
+      });
+      await Promise.all(logs);
       logger.info(`[Cleanup] Deleted ${deleted.count} expired notes.`);
       return deleted.count;
     })