Ryan/drop
1
0
Fork 0
mirror of https://github.com/Drop-OSS/drop.git synced 2025-11-15 09:11:21 +10:00
Code Issues Packages Projects Releases Wiki Activity

Logging (#131)

Browse Source 
* ci: pull version from package.json on build

* fix: implicit any type

* feat: inital support for logger

* style: fix lint

* feat: move more logging over to pino

* fix: logging around company importing
This commit is contained in:
Husky
2025-07-08 22:01:23 -04:00
committed by GitHub
parent e4fbc7cd50
commit 2b70cea4e0
33 changed files with 481 additions and 171 deletions
Download Patch File Download Diff File Expand all files Collapse all files

145
server/internal/tasks/index.ts
View File

@ -10,6 +10,9 @@ import cleanupObjects from "./registry/objects";
import { taskGroups, type TaskGroup } from "./group";
import prisma from "../db/database";
import { type } from "arktype";
import pino from "pino";
import { logger } from "~/server/internal/logging";
import { Writable } from "node:stream";
// a task that has been run
type FinishedTask = {
@ -80,7 +83,7 @@ class TaskHandler {
// if a task is already running, we don't want to start another
if (existingTask.taskGroup === task.taskGroup) {
// TODO: handle this more gracefully, maybe with a queue? should be configurable
console.warn(
logger.warn(
`Task group ${task.taskGroup} does not allow concurrent tasks. Task ${task.id} will not be started.`,
);
throw new Error(
@ -126,16 +129,82 @@ class TaskHandler {
}, 100);
});
const log = (entry: string) => {
const taskEntry = this.taskPool.get(task.id);
if (!taskEntry) return;
taskEntry.log.push(msgWithTimestamp(entry));
updateAllClients();
};
const taskPool = this.taskPool;
// Create a pino transport that replicates the old log function behavior
// const taskLogger = pino({
// hooks: {
// logMethod(args, method) {
// // Combine all arguments into a single string message
// const message = args.map(String).join(" ");
// const now = new Date();
// const pad = (n: number, width = 2) =>
// n.toString().padStart(width, "0");
// const year = now.getUTCFullYear();
// const month = pad(now.getUTCMonth() + 1);
// const day = pad(now.getUTCDate());
// const hours = pad(now.getUTCHours());
// const minutes = pad(now.getUTCMinutes());
// const seconds = pad(now.getUTCSeconds());
// const milliseconds = pad(now.getUTCMilliseconds(), 3);
// const logObj = {
// timestamp: `${year}-${month}-${day} ${hours}:${minutes}:${seconds}.${milliseconds} UTC`,
// message,
// };
// // Push the formatted log string to the task's log array
// const taskEntry = taskPool.get(task.id);
// if (taskEntry) {
// taskEntry.log.push(JSON.stringify(logObj));
// updateAllClients();
// }
// // Optionally, still call the original method if you want logs elsewhere
// method.apply(this, args);
// },
// },
// });
// Custom writable stream to capture logs
const logStream = new Writable({
objectMode: true,
write(chunk, encoding, callback) {
try {
// chunk is a stringified JSON log line
const logObj = JSON.parse(chunk.toString());
const taskEntry = taskPool.get(task.id);
if (taskEntry) {
taskEntry.log.push(JSON.stringify(logObj));
updateAllClients();
}
} catch (e) {
// fallback: ignore or log error
logger.error("Failed to parse log chunk", {
error: e,
chunk: chunk,
});
}
callback();
},
});
// Use pino with the custom stream
const taskLogger = pino(
{
// You can configure timestamp, level, etc. here
timestamp: pino.stdTimeFunctions.isoTime,
base: null, // Remove pid/hostname if not needed
},
logStream,
);
const progress = (progress: number) => {
if (progress < 0 || progress > 100) {
console.error("Progress must be between 0 and 100", { progress });
logger.error("Progress must be between 0 and 100", { progress });
return;
}
const taskEntry = this.taskPool.get(task.id);
@ -165,7 +234,7 @@ class TaskHandler {
if (!taskEntry) throw new Error("No task entry");
try {
await task.run({ progress, log });
await task.run({ progress, logger: taskLogger });
taskEntry.success = true;
} catch (error: unknown) {
taskEntry.success = false;
@ -226,7 +295,7 @@ class TaskHandler {
const allowed = await aclManager.hasACL(request, task.acls);
if (!allowed) {
console.warn("user does not have necessary ACLs");
// logger.warn("user does not have necessary ACLs");
peer.send(
`error/${taskId}/Unknown task/Drop couldn't find the task you're looking for.`,
);
@ -304,7 +373,7 @@ class TaskHandler {
runTaskGroupByName(name: TaskGroup) {
const task = this.taskCreators.get(name);
if (!task) {
console.warn(`No task found for group ${name}`);
logger.warn(`No task found for group ${name}`);
return;
}
this.create(task());
@ -365,17 +434,21 @@ class TaskHandler {
export type TaskRunContext = {
progress: (progress: number) => void;
log: (message: string) => void;
logger: typeof logger;
};
export function wrapTaskContext(
context: TaskRunContext,
options: { min: number; max: number; prefix: string },
): TaskRunContext {
const child = context.logger.child({
prefix: options.prefix,
});
return {
progress(progress) {
if (progress > 100 || progress < 0) {
console.warn("[wrapTaskContext] progress must be between 0 and 100");
logger.warn("[wrapTaskContext] progress must be between 0 and 100");
}
// I was too tired to figure this out
@ -385,9 +458,7 @@ export function wrapTaskContext(
const adjustedProgress = (progress * newRange) / oldRange + options.min;
return context.progress(adjustedProgress);
},
log(message) {
return context.log(options.prefix + message);
},
logger: child,
};
}
@ -431,31 +502,31 @@ export const TaskLog = type({
message: "string",
});
/**
* Create a log message with a timestamp in the format YYYY-MM-DD HH:mm:ss.SSS UTC
* @param message
* @returns
*/
function msgWithTimestamp(message: string): string {
const now = new Date();
// /**
// * Create a log message with a timestamp in the format YYYY-MM-DD HH:mm:ss.SSS UTC
// * @param message
// * @returns
// */
// function msgWithTimestamp(message: string): string {
// const now = new Date();
const pad = (n: number, width = 2) => n.toString().padStart(width, "0");
// const pad = (n: number, width = 2) => n.toString().padStart(width, "0");
const year = now.getUTCFullYear();
const month = pad(now.getUTCMonth() + 1);
const day = pad(now.getUTCDate());
// const year = now.getUTCFullYear();
// const month = pad(now.getUTCMonth() + 1);
// const day = pad(now.getUTCDate());
const hours = pad(now.getUTCHours());
const minutes = pad(now.getUTCMinutes());
const seconds = pad(now.getUTCSeconds());
const milliseconds = pad(now.getUTCMilliseconds(), 3);
// const hours = pad(now.getUTCHours());
// const minutes = pad(now.getUTCMinutes());
// const seconds = pad(now.getUTCSeconds());
// const milliseconds = pad(now.getUTCMilliseconds(), 3);
const log: typeof TaskLog.infer = {
timestamp: `${year}-${month}-${day} ${hours}:${minutes}:${seconds}.${milliseconds} UTC`,
message,
};
return JSON.stringify(log);
}
// const log: typeof TaskLog.infer = {
// timestamp: `${year}-${month}-${day} ${hours}:${minutes}:${seconds}.${milliseconds} UTC`,
// message,
// };
// return JSON.stringify(log);
// }
export function defineDropTask(buildTask: BuildTask): DropTask {
// TODO: only let one task with the same taskGroup run at the same time if specified

7
server/internal/tasks/registry/invitations.ts
View File

@ -6,8 +6,8 @@ export default defineDropTask({
name: "Cleanup Invitations",
acls: ["system:maintenance:read"],
taskGroup: "cleanup:invitations",
async run({ log }) {
log("Cleaning invitations");
async run({ progress, logger }) {
logger.info("Cleaning invitations");
const now = new Date();
@ -19,6 +19,7 @@ export default defineDropTask({
},
});
log("Done");
logger.info("Done");
progress(100);
},
});

24
server/internal/tasks/registry/objects.ts
View File

@ -15,36 +15,38 @@ export default defineDropTask({
name: "Cleanup Objects",
acls: ["system:maintenance:read"],
taskGroup: "cleanup:objects",
async run({ progress, log }) {
log("Cleaning unreferenced objects");
async run({ progress, logger }) {
logger.info("Cleaning unreferenced objects");
// get all objects
const objects = await objectHandler.listAll();
log(`searching for ${objects.length} objects`);
logger.info(`searching for ${objects.length} objects`);
progress(30);
// find unreferenced objects
const refMap = buildRefMap();
log("Building reference map");
log(`Found ${Object.keys(refMap).length} models with reference fields`);
log("Searching for unreferenced objects");
logger.info("Building reference map");
logger.info(
`Found ${Object.keys(refMap).length} models with reference fields`,
);
logger.info("Searching for unreferenced objects");
const unrefedObjects = await findUnreferencedStrings(objects, refMap);
log(`found ${unrefedObjects.length} Unreferenced objects`);
// console.log(unrefedObjects);
logger.info(`found ${unrefedObjects.length} Unreferenced objects`);
// logger.info(unrefedObjects);
progress(60);
// remove objects
const deletePromises: Promise<boolean>[] = [];
for (const obj of unrefedObjects) {
log(`Deleting object ${obj}`);
logger.info(`Deleting object ${obj}`);
deletePromises.push(objectHandler.deleteAsSystem(obj));
}
await Promise.all(deletePromises);
// Remove any possible leftover metadata
objectHandler.cleanupMetadata();
await objectHandler.cleanupMetadata(logger);
log("Done");
logger.info("Done");
progress(100);
},
});

7
server/internal/tasks/registry/sessions.ts
View File

@ -6,9 +6,10 @@ export default defineDropTask({
name: "Cleanup Sessions",
acls: ["system:maintenance:read"],
taskGroup: "cleanup:sessions",
async run({ log }) {
log("Cleaning up sessions");
async run({ progress, logger }) {
logger.info("Cleaning up sessions");
await sessionHandler.cleanupSessions();
log("Done");
logger.info("Done");
progress(100);
},
});

36
server/internal/tasks/registry/update.ts
View File

@ -21,38 +21,38 @@ export default defineDropTask({
name: "Check for Update",
acls: ["system:maintenance:read"],
taskGroup: "check:update",
async run({ log }) {
async run({ progress, logger }) {
// TODO: maybe implement some sort of rate limit thing to prevent this from calling github api a bunch in the event of crashloop or whatever?
// probably will require custom task scheduler for object cleanup anyway, so something to thing about
if (!systemConfig.shouldCheckForUpdates()) {
log("Update check is disabled by configuration");
logger.info("Update check is disabled by configuration");
progress(100);
return;
}
log("Checking for update");
logger.info("Checking for update");
const currVerStr = systemConfig.getDropVersion();
const currVer = semver.coerce(currVerStr);
if (currVer === null) {
const msg = "Drop provided a invalid semver tag";
log(msg);
logger.info(msg);
throw new Error(msg);
}
progress(30);
const response = await fetch(
"https://api.github.com/repos/Drop-OSS/drop/releases/latest",
);
progress(50);
// if response failed somehow
if (!response.ok) {
log(
"Failed to check for update " +
JSON.stringify({
status: response.status,
body: response.body,
}),
);
logger.info("Failed to check for update ", {
status: response.status,
body: response.body,
});
throw new Error(
`Failed to check for update: ${response.status} ${response.body}`,
@ -63,8 +63,8 @@ export default defineDropTask({
const resJson = await response.json();
const body = latestRelease(resJson);
if (body instanceof type.errors) {
log(body.summary);
log("GitHub Api response" + JSON.stringify(resJson));
logger.info(body.summary);
logger.info("GitHub Api response" + JSON.stringify(resJson));
throw new Error(
`GitHub Api response did not match expected schema: ${body.summary}`,
);
@ -74,14 +74,15 @@ export default defineDropTask({
const latestVer = semver.coerce(body.tag_name);
if (latestVer === null) {
const msg = "Github Api returned invalid semver tag";
log(msg);
logger.info(msg);
throw new Error(msg);
}
progress(70);
// TODO: handle prerelease identifiers https://github.com/npm/node-semver#prerelease-identifiers
// check if is newer version
if (semver.gt(latestVer, currVer)) {
log("Update available");
logger.info("Update available");
notificationSystem.systemPush({
nonce: `drop-update-available-${currVer}-to-${latestVer}`,
title: `Update available to v${latestVer}`,
@ -90,9 +91,10 @@ export default defineDropTask({
acls: ["system:notifications:read"],
});
} else {
log("no update available");
logger.info("no update available");
}
log("Done");
logger.info("Done");
progress(100);
},
});