feat: 🔊 Add event logging for note read, writes and purges.

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;
     })