From e7f17dbe4d7064a034c205c931ff91395f21c80e Mon Sep 17 00:00:00 2001 From: Maxime Cannoodt Date: Mon, 8 Aug 2022 22:46:50 +0200 Subject: [PATCH 1/3] feat: :card_file_box: Add event table to schema, add EventLogger class to server --- .../20220808203936_event_table/migration.sql | 12 +++ server/prisma/schema.prisma | 12 +++ server/src/EventLogger.integration.test.ts | 79 +++++++++++++++++++ server/src/EventLogger.ts | 51 ++++++++++++ 4 files changed, 154 insertions(+) create mode 100644 server/prisma/migrations/20220808203936_event_table/migration.sql create mode 100644 server/src/EventLogger.integration.test.ts create mode 100644 server/src/EventLogger.ts diff --git a/server/prisma/migrations/20220808203936_event_table/migration.sql b/server/prisma/migrations/20220808203936_event_table/migration.sql new file mode 100644 index 0000000..dc3393b --- /dev/null +++ b/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 +); diff --git a/server/prisma/schema.prisma b/server/prisma/schema.prisma index 6b26a4c..b3d73f2 100644 --- a/server/prisma/schema.prisma +++ b/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? + purge_count Int? + host String? + error String? + expire_window_days Int? +} diff --git a/server/src/EventLogger.integration.test.ts b/server/src/EventLogger.integration.test.ts new file mode 100644 index 0000000..207bb8d --- /dev/null +++ b/server/src/EventLogger.integration.test.ts @@ -0,0 +1,79 @@ +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", + 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 }, + }); + 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", + size_bytes: 100, + success: true, + }; + + // Is event written successfully? + const logged = await EventLogger.readEvent({ + host: "localhost", + size_bytes: 100, + success: true, + }); + expect(logged).not.toBeNull(); + expect(logged).toMatchObject(testReadEvent); + + // Is event in database? + const results = await prisma.event.findMany({ + where: { type: EventType.READ }, + }); + 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 = { + success: true, + purge_count: 1, + size_bytes: 100, + }; + + // 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 }, + }); + expect(results.length).toBe(1); + + // Are default fields populated? + expect(logged.time).not.toBeNull(); + expect(logged.id).not.toBeNull(); + }); +}); diff --git a/server/src/EventLogger.ts b/server/src/EventLogger.ts new file mode 100644 index 0000000..7a3b00d --- /dev/null +++ b/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; + size_bytes: number; + success: boolean; +} + +interface WriteEvent extends ClientEvent { + expire_window_days: number; +} + +interface ReadEvent extends ClientEvent {} + +interface PurgeEvent extends Event { + success: boolean; + purge_count: number; + size_bytes: number; +} + +export default class EventLogger { + public static writeEvent(event: WriteEvent): Promise { + return prisma.event.create({ + data: { type: EventType.WRITE, ...event }, + }); + } + + public static readEvent(event: ReadEvent): Promise { + return prisma.event.create({ + data: { type: EventType.READ, ...event }, + }); + } + + public static purgeEvent(event: PurgeEvent): Promise { + return prisma.event.create({ + data: { type: EventType.PURGE, ...event }, + }); + } +} From 293af7f34b7554b8b436bf3f02dc2cb0c885fc14 Mon Sep 17 00:00:00 2001 From: Maxime Cannoodt Date: Mon, 8 Aug 2022 23:39:37 +0200 Subject: [PATCH 2/3] refactor: :card_file_box: Change event log database for note purges --- .../migration.sql | 24 +++++++++++++++++++ server/prisma/schema.prisma | 2 +- server/src/EventLogger.integration.test.ts | 18 +++++++------- server/src/EventLogger.ts | 10 ++++---- 4 files changed, 38 insertions(+), 16 deletions(-) create mode 100644 server/prisma/migrations/20220808205230_update_event_table/migration.sql diff --git a/server/prisma/migrations/20220808205230_update_event_table/migration.sql b/server/prisma/migrations/20220808205230_update_event_table/migration.sql new file mode 100644 index 0000000..0a7a74c --- /dev/null +++ b/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; diff --git a/server/prisma/schema.prisma b/server/prisma/schema.prisma index b3d73f2..e4a40ef 100644 --- a/server/prisma/schema.prisma +++ b/server/prisma/schema.prisma @@ -24,7 +24,7 @@ model event { type String success Boolean size_bytes Int? - purge_count Int? + note_id String? host String? error String? expire_window_days Int? diff --git a/server/src/EventLogger.integration.test.ts b/server/src/EventLogger.integration.test.ts index 207bb8d..710af18 100644 --- a/server/src/EventLogger.integration.test.ts +++ b/server/src/EventLogger.integration.test.ts @@ -6,6 +6,7 @@ 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, @@ -18,7 +19,7 @@ describe("Logging write events", () => { // Is event in database? const results = await prisma.event.findMany({ - where: { type: EventType.WRITE }, + where: { type: EventType.WRITE, note_id: testWriteEvent.note_id }, }); expect(results.length).toBe(1); @@ -30,22 +31,19 @@ describe("Logging write events", () => { 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({ - host: "localhost", - size_bytes: 100, - success: true, - }); + 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 }, + where: { type: EventType.READ, note_id: testReadEvent.note_id }, }); expect(results.length).toBe(1); @@ -56,9 +54,9 @@ describe("Logging write events", () => { it("Should log a purge event to database", async () => { const testPurgeEvent = { - success: true, - purge_count: 1, + note_id: "test_id", size_bytes: 100, + success: true, }; // Is event written successfully? @@ -68,7 +66,7 @@ describe("Logging write events", () => { // Is event in database? const results = await prisma.event.findMany({ - where: { type: EventType.PURGE }, + where: { type: EventType.PURGE, note_id: "test_id" }, }); expect(results.length).toBe(1); diff --git a/server/src/EventLogger.ts b/server/src/EventLogger.ts index 7a3b00d..f617253 100644 --- a/server/src/EventLogger.ts +++ b/server/src/EventLogger.ts @@ -14,20 +14,20 @@ interface Event { interface ClientEvent extends Event { host: string; - size_bytes: number; success: boolean; + note_id?: string; + size_bytes?: number; } interface WriteEvent extends ClientEvent { - expire_window_days: number; + expire_window_days?: number; } interface ReadEvent extends ClientEvent {} interface PurgeEvent extends Event { - success: boolean; - purge_count: number; - size_bytes: number; + note_id: string; + size_bytes?: number; } export default class EventLogger { From 9b1a4463407d7347175894f474a90a9671ae0fce Mon Sep 17 00:00:00 2001 From: Maxime Cannoodt Date: Mon, 8 Aug 2022 23:43:24 +0200 Subject: [PATCH 3/3] feat: :loud_sound: Add event logging for note read, writes and purges. --- server/src/app.integration.test.ts | 44 ++++++++++++++++- server/src/app.ts | 79 +++++++++++++++++++++++++----- 2 files changed, 110 insertions(+), 13 deletions(-) diff --git a/server/src/app.integration.test.ts b/server/src/app.integration.test.ts index 85c4fe9..e6cb344 100644 --- a/server/src/app.integration.test.ts +++ b/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 + ); }); }); diff --git a/server/src/app.ts b/server/src/app.ts index f81a489..114978f 100644 --- a/server/src/app.ts +++ b/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 { 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; })