Merge pull request #63 from CodeGrade/feat/logging

Logging on Orchestrator and Worker

orchestrator/package.json

@@ -17,7 +17,8 @@
     "test": "jest"
   },
   "dependencies": {
-    "concurrently": "^8.2.2"
+    "concurrently": "^8.2.2",
+    "pino": "^9.3.2"
   },
   "devDependencies": {
     "@types/jest": "^29.5.12",

orchestrator/packages/api/src/controllers/docker-image-controller.ts

@@ -2,6 +2,7 @@ import { Request, Response } from "express";
 import { errorResponse } from "./utils";
 import {
     graderImageExists,
+  logger,
   validations,
 } from "@codegrade-orca/common";
 import { GradingQueueOperationException, enqueueImageBuild, imageIsAwaitingBuild, imageIsBeingBuilt } from "@codegrade-orca/db";
@@ -20,10 +21,10 @@ export const createGraderImage = async (req: Request, res: Response) => {
     await enqueueImageBuild(req.body);
     return res.status(200).json({ message: "OK" });
   } catch (error) {
-    console.error(error);
     if (error instanceof GradingQueueOperationException) {
       return errorResponse(res, 400, [error.message]);
     } else {
+      logger.error(`Could not enqueue image build; ${error}`);
       return errorResponse(res, 500, [
         "An error occured while trying to enqueue the image build request. Please contact an admin.",
       ]);

orchestrator/packages/api/src/controllers/grading-queue-controller.ts

@@ -12,6 +12,7 @@ import {
   filterGradingJobs,
   getFilterInfo,
   getGradingQueueStats,
+  logger,
   validations,
 } from "@codegrade-orca/common";
 import {
@@ -94,7 +95,6 @@ export const getGradingJobs = async (req: Request, res: Response) => {
       filter_info: filterInfo,
     });
   } catch (err) {
-    console.error(err);
     if (err instanceof GradingQueueOperationException) {
       return errorResponse(res, 400, [err.message]);
     }
@@ -111,20 +111,17 @@ export const createOrUpdateImmediateJob = async (
   if (!validations.gradingJobConfig(req.body)) {
     return errorResponse(res, 400, ["Invalid grading job configuration."]);
   }
-  const gradingJobConfig = req.body;
-
   try {
-    // TODO: Return job id from db operation and in response obj
     const status = await putJobInQueue(req.body, true);
+    logger.info(`New job from ${new URL(req.body.response_url).host} sent to ${status.location} with database id ${status.id}.`);
     return res.status(200).json({ message: "OK", status });
   } catch (error) {
-    console.error(error);
     if (error instanceof GradingQueueOperationException) {
       return errorResponse(res, 400, [error.message]);
     }
     return errorResponse(res, 500, [
       "An error occurred while trying to create an immediate job or update an " +
-      `existing one for ${gradingJobConfig.collation.type} with ID ${gradingJobConfig.collation.id}.`,
+      `existing one for ${req.body.collation.type} with ID ${req.body.collation.id}.`,
     ]);
   }
 };
@@ -133,13 +130,11 @@ export const createOrUpdateJob = async (req: Request, res: Response) => {
   if (!validations.gradingJobConfig(req.body)) {
     return errorResponse(res, 400, ["The given grading job was invalid."]);
   }
-
   try {
-    // TODO: Return job id from db operation and in response obj
     const status = await putJobInQueue(req.body, false);
+    logger.info(`New job from ${new URL(req.body.response_url).host} sent to ${status.location} with database id ${status.id}.`);
     return res.status(200).json({ message: "OK", status });
   } catch (err) {
-    console.error(err);
     if (err instanceof GradingQueueOperationException) {
       return errorResponse(res, 400, [err.message]);
     } else {
@@ -170,6 +165,7 @@ export const deleteJob = async (req: Request, res: Response) => {
     }
     const deletedJob = await deleteJobInQueue(jobID);
     const deletedJobConfig = deletedJob.config as object as GradingJobConfig;
+    logger.info(`Deleted job from ${new URL(deletedJobConfig.response_url).host} with former id ${jobID}.`);
     notifyClientOfCancelledJob(deletedJobConfig)
     return res.status(200).json({ message: "OK" });
   } catch (err) {

orchestrator/packages/api/src/controllers/utils.ts

@@ -1,20 +1,26 @@
-import { GradingJobConfig, GradingJobResult } from "@codegrade-orca/common";
+import { GradingJobConfig, GradingJobResult, logger } from "@codegrade-orca/common";
 import { Response } from "express";
 
 export const errorResponse = (
   res: Response,
   status: number,
   errors: string[],
 ) => {
+  if (isClientError(status)) {
+    logger.warn(errors.join(', '));
+  } else {
+    logger.error(errors.join(', '));
+  }
   return res.status(status).json({ errors: errors });
 };
 
+const isClientError = (statusCode: number): boolean => statusCode > 399 && statusCode < 500;
+
 export const notifyClientOfCancelledJob = (jobConfig: GradingJobConfig) => {
   const result: GradingJobResult = {
     shell_responses: [],
     errors: ["Job cancelled by a course professor or Orca admin."]
   };
-  console.info(jobConfig.response_url);
   fetch(jobConfig.response_url, {
     method: "POST",
     headers: {
@@ -23,7 +29,7 @@ export const notifyClientOfCancelledJob = (jobConfig: GradingJobConfig) => {
     },
     body: JSON.stringify({ ...result, key: jobConfig.key })
   }).catch((err) =>
-    console.error(
+    logger.error(
       `Encountered the following error while attempting to notify client of Job cancellation: ${err}`
     ));
 }

orchestrator/packages/api/src/index.ts

@@ -1,7 +1,7 @@
 import { Express } from "express";
 import gradingQueueRouter from "./routes/grading-queue";
 import { existsSync, mkdirSync } from "fs";
-import { getConfig } from "@codegrade-orca/common";
+import { getConfig, logger } from "@codegrade-orca/common";
 import express = require("express");
 import cors = require("cors");
 import dockerImagesRouter from "./routes/docker-images";
@@ -23,5 +23,5 @@ app.listen(PORT, () => {
   if (!existsSync(CONFIG.dockerImageFolder)) {
     mkdirSync(CONFIG.dockerImageFolder);
   }
-  console.info(`Server listening on port ${PORT}`);
+  logger.info(`Server listening on port ${PORT}`);
 });

orchestrator/packages/common/src/config.ts

@@ -4,6 +4,7 @@ export interface OrchestratorConfig {
   api: OrchestratorAPIOptions;
   dockerImageFolder: string;
   postgresURL: string;
+  environment: string;
 }
 
 interface OrchestratorAPIOptions {
@@ -16,4 +17,5 @@ export const getConfig = (): OrchestratorConfig => ({
     port: process.env.API_PORT ? parseInt(process.env.API_PORT) : 8090,
   },
   dockerImageFolder: join(__dirname, "../../../", "images"),
+  environment: process.env.ENVIRONMENT?.toLowerCase() || 'dev'
 });

orchestrator/packages/common/src/index.ts

@@ -1,5 +1,6 @@
 import path from "path";
 import { getConfig } from "./config";
+import logger from "./logger";
 import validations from "./validations";
 import { existsSync } from "fs";
 
@@ -8,6 +9,7 @@ export * from "./types";
 export * from "./config";
 export * from "./utils";
 export { validations };
+export { logger };
 
 export const toMilliseconds = (seconds: number) => seconds * 1_000;
 export const imageWithSHAExists = (dockerfileSHASum: string): boolean => {

orchestrator/packages/common/src/logger.ts

@@ -0,0 +1,26 @@
+import pino from "pino";
+import { getConfig } from "./config";
+import path from "path";
+
+const transport = pino.transport({
+  targets: [
+    {
+      target: 'pino/file',
+      options: {
+        destination: path.join(__dirname, '../../../', 'logs', `${getConfig().environment}.log`),
+        mkdir: true
+      }
+    },
+    {
+      target: 'pino/file',
+      options: { destination: 2 }
+    }
+  ]
+});
+
+const logger = pino({
+  level: getConfig().environment === 'production' ? 'info' : 'debug',
+  timestamp: true,
+}, transport);
+
+export default logger;

orchestrator/packages/common/src/utils/push-status-update.ts

@@ -1,3 +1,4 @@
+import logger from "../logger";
 import { JobStatus } from "../types";
 
 export const pushStatusUpdate = async (status: JobStatus, responseURL: string, key: string): Promise<void> => {
@@ -7,6 +8,6 @@ export const pushStatusUpdate = async (status: JobStatus, responseURL: string, k
     const body = JSON.stringify({ key, status });
     await fetch(responseURL, { body, method: 'POST', headers: { 'Content-Type': 'application/json' } });
   } catch (err) {
-    console.error(`Could not POST status update to ${responseURL}; ${err instanceof Error ? err.message : err}`);
+    logger.warn(`Could not POST status update to ${responseURL}; ${err instanceof Error ? err.message : err}`);
   }
 };

orchestrator/packages/image-build-service/src/index.ts

@@ -4,7 +4,8 @@ import {
   isImageBuildResult,
   pushStatusUpdate,
   getConfig,
-  GraderImageBuildResult
+  GraderImageBuildResult,
+  logger
 } from "@codegrade-orca/common";
 import { getNextImageBuild, handleCompletedImageBuild } from "@codegrade-orca/db";
 import { createAndStoreGraderImage, removeStaleImageFiles } from "./process-request";
@@ -16,7 +17,7 @@ import { existsSync, rmSync } from "fs";
 const LOOP_SLEEP_TIME = 5; // Seconds
 
 const main = async () => {
-  console.info("Cleaning up stale build info...");
+  logger.info("Cleaning up stale build info...");
   const shaSumJobInfoPairs = await cleanStaleBuildInfo();
   shaSumJobInfoPairs.forEach(([originalReq, enqueuedJobs]) => {
     removeDockerfileIfExists(originalReq.dockerfile_sha_sum);
@@ -25,7 +26,7 @@ const main = async () => {
       ({ response_url, key, ...status }) => pushStatusUpdate(status, response_url, key)
     );
   });
-  console.info("Build service initialized.");
+  logger.info("Build service initialized.");
   while (true) {
     let infoAsBuildReq: GraderImageBuildRequest | undefined = undefined;
     try {
@@ -36,7 +37,7 @@ const main = async () => {
         continue;
       }
 
-      console.info(`Attempting to build image with SHA ${nextBuildReq.dockerfileSHA}.`);
+      logger.info(`Attempting to build image with SHA ${nextBuildReq.dockerfileSHA}.`);
 
       infoAsBuildReq = {
         dockerfile_sha_sum: nextBuildReq.dockerfileSHA,
@@ -49,7 +50,7 @@ const main = async () => {
 
       notifyClientOfBuildResult(result, infoAsBuildReq);
       jobInfo.forEach(({ key, response_url, ...status }) => pushStatusUpdate(status, response_url, key));
-      console.info(`Successfully built image with SHA ${nextBuildReq.dockerfileSHA}.`);
+      logger.info(`Successfully built image with SHA ${nextBuildReq.dockerfileSHA}.`);
     } catch (err) {
       if (isImageBuildResult(err) && infoAsBuildReq) {
         const cancelledJobInfoList = await handleCompletedImageBuild(infoAsBuildReq.dockerfile_sha_sum, false);
@@ -59,7 +60,7 @@ const main = async () => {
         notifyClientOfBuildResult(err, infoAsBuildReq);
         await cleanUpDockerFiles(infoAsBuildReq.dockerfile_sha_sum);
       }
-      console.error(err);
+      logger.error(`Encountered during image build: ${err}.`);
     } finally {
       if (infoAsBuildReq) {
         await removeImageFromDockerIfExists(infoAsBuildReq.dockerfile_sha_sum);

orchestrator/packages/image-build-service/src/utils.ts

@@ -1,4 +1,4 @@
-import { GraderImageBuildRequest, GraderImageBuildResult, GradingJobResult, getConfig } from "@codegrade-orca/common";
+import { GraderImageBuildRequest, GraderImageBuildResult, GradingJobResult, getConfig, logger } from "@codegrade-orca/common";
 import { CancelJobInfo } from "@codegrade-orca/db/dist/image-builder-operations/handle-completed-image-build";
 import { execFile } from "child_process";
 import { existsSync, rmSync } from "fs";
@@ -59,7 +59,7 @@ export const sendJobResultForBuildFail = (cancelInfo: CancelJobInfo) => {
       "Content-Type": "application/json"
     },
     body: JSON.stringify({ ...result, key: cancelInfo.key })
-  }).catch((err) => console.error(err));
+  }).catch((err) => logger.error(`Could not update client on job result; ${err}`));
 }
 
 export const notifyClientOfBuildResult = (result: GraderImageBuildResult, originalReq: GraderImageBuildRequest) => {
@@ -71,5 +71,5 @@ export const notifyClientOfBuildResult = (result: GraderImageBuildResult, origin
       "Content-Type": "application/json"
     },
     body: JSON.stringify(result)
-  }).catch((err) => console.error(err));
+  }).catch((err) => logger.error(`Encountered the following error when sending result to ${response_url}: ${err}`));
 }