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/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 6b26a4c..e4a40ef 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? + 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 new file mode 100644 index 0000000..710af18 --- /dev/null +++ b/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(); + }); +}); diff --git a/server/src/EventLogger.ts b/server/src/EventLogger.ts new file mode 100644 index 0000000..f617253 --- /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; + 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 { + 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 }, + }); + } +} 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; })