From 9b1a4463407d7347175894f474a90a9671ae0fce Mon Sep 17 00:00:00 2001 From: Maxime Cannoodt Date: Mon, 8 Aug 2022 23:43:24 +0200 Subject: [PATCH] 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; })