Improve logging (#604)

* Log request status 300 - 400

* Use remote logger in fetch schema

* Properly parse log message

* Format reponse log message better

* Use response end event to capture response log

* Add request received trace log

* Update changelog

* Fix tests

Changelog.md

@@ -4,6 +4,8 @@
 
 - **Fixed** context menu styles
   ([#600](https://github.com/aws/graph-explorer/pull/600))
+- **Improved** logging on server and around schema sync
+  ([#604](https://github.com/aws/graph-explorer/pull/604))
 - **Improved** support for databases with thousands of node & edge types
   ([#599](https://github.com/aws/graph-explorer/pull/599))
 - **Fixed** alignment of close button in search panel

packages/graph-explorer-proxy-server/src/error-handler.ts

@@ -1,5 +1,5 @@
 import { NextFunction, Request, Response } from "express";
-import { logger, logRequestAndResponse } from "./logging.js";
+import { logger } from "./logging.js";
 
 /**
  * Global error handler
@@ -14,16 +14,14 @@ export function handleError(error: unknown) {
 export function errorHandlingMiddleware() {
   return (
     error: unknown,
-    request: Request,
+    _request: Request,
     response: Response,
     _next: NextFunction
   ) => {
     const errorInfo = extractErrorInfo(error);
 
     response.status(errorInfo.status);
 
-    logRequestAndResponse(request, response);
-
     response.send({
       error: errorInfo,
     });

packages/graph-explorer-proxy-server/src/logging.ts

@@ -40,7 +40,7 @@ function logLevelFromStatusCode(statusCode: number): LogLevel {
   } else if (statusCode >= 500) {
     return "error";
   } else if (statusCode >= 300 && statusCode < 400) {
-    return "silent";
+    return "debug";
   }
   return "debug";
 }
@@ -49,7 +49,7 @@ function logLevelFromStatusCode(statusCode: number): LogLevel {
 export function logRequestAndResponse(req: Request, res: Response) {
   const logLevel = logLevelFromStatusCode(res.statusCode);
 
-  const requestMessage = `${res.statusCode} - ${req.method} ${req.path}`;
+  const requestMessage = `[${req.method} ${req.path}] Response ${res.statusCode} ${res.statusMessage}`;
 
   switch (logLevel) {
     case "debug":
@@ -79,8 +79,10 @@ export function requestLoggingMiddleware() {
       return;
     }
 
-    // Wait for the request to complete.
-    req.on("end", () => {
+    logger.trace(`[${req.method} ${req.path}] Request received`);
+
+    // Wait for the response to finish
+    res.on("finish", () => {
       logRequestAndResponse(req, res);
     });
 

packages/graph-explorer-proxy-server/src/node-server.ts

@@ -282,7 +282,7 @@ app.post("/gremlin", (req, res, next) => {
   if (!queryString) {
     return res
       .status(400)
-      .send({ error: "[Proxy]Gremlin: query not provided" });
+      .send({ error: "[Proxy] Gremlin: query not provided" });
   }
 
   if (shouldLogDbQuery) {
@@ -484,7 +484,7 @@ app.post("/logger", (req, res, next) => {
     if (headers["message"] === undefined) {
       throw new Error("No log message passed.");
     } else {
-      message = headers["message"].replaceAll("\\", "");
+      message = JSON.parse(headers["message"]).replaceAll("\\", "");
     }
     if (level.toLowerCase() === "error") {
       proxyLogger.error(message);

packages/graph-explorer/src/connector/gremlin/gremlinExplorer.ts

@@ -78,6 +78,7 @@ export function createGremlinExplorer(
       const summary = await fetchSummary(connection, featureFlags, options);
       return fetchSchema(
         _gremlinFetch(connection, featureFlags, options),
+        remoteLogger,
         summary
       );
     },

packages/graph-explorer/src/connector/gremlin/queries/fetchSchema.test.ts

@@ -1,12 +1,16 @@
 import globalMockFetch from "@/connector/testUtils/globalMockFetch";
 import mockGremlinFetch from "@/connector/testUtils/mockGremlinFetch";
 import fetchSchema from "./fetchSchema";
+import { ClientLoggerConnector } from "@/connector/LoggerConnector";
 
 describe("Gremlin > fetchSchema", () => {
   beforeEach(globalMockFetch);
 
   it("Should return an inferred schema", async () => {
-    const schemaResponse = await fetchSchema(mockGremlinFetch());
+    const schemaResponse = await fetchSchema(
+      mockGremlinFetch(),
+      new ClientLoggerConnector()
+    );
 
     expect(schemaResponse).toMatchObject({
       vertices: [

packages/graph-explorer/src/connector/gremlin/queries/fetchSchema.ts

@@ -1,4 +1,4 @@
-import { logger, sanitizeText } from "@/utils";
+import { sanitizeText } from "@/utils";
 import type { SchemaResponse } from "@/connector/useGEFetchTypes";
 import edgeLabelsTemplate from "../templates/edgeLabelsTemplate";
 import edgesSchemaTemplate from "../templates/edgesSchemaTemplate";
@@ -7,6 +7,7 @@ import verticesSchemaTemplate from "../templates/verticesSchemaTemplate";
 import type { GEdge, GInt64, GVertex } from "../types";
 import { GraphSummary, GremlinFetch } from "../types";
 import { chunk } from "lodash";
+import { LoggerConnector } from "@/connector/LoggerConnector";
 
 const BATCH_SIZE = 100;
 
@@ -87,10 +88,11 @@ type RawEdgesSchemaResponse = {
 };
 
 const fetchVertexLabels = async (
-  gremlinFetch: GremlinFetch
+  gremlinFetch: GremlinFetch,
+  remoteLogger: LoggerConnector
 ): Promise<Record<string, number>> => {
   const labelsTemplate = vertexLabelsTemplate();
-  logger.log("[Gremlin Explorer] Fetching vertex labels with counts...");
+  remoteLogger.info("[Gremlin Explorer] Fetching vertex labels with counts...");
   const data = await gremlinFetch<RawVertexLabelsResponse>(labelsTemplate);
 
   const values = data.result.data["@value"][0]["@value"];
@@ -99,6 +101,10 @@ const fetchVertexLabels = async (
     labelsWithCounts[values[i] as string] = (values[i + 1] as GInt64)["@value"];
   }
 
+  remoteLogger.info(
+    `[Gremlin Explorer] Found ${Object.keys(labelsWithCounts).length} vertex labels.`
+  );
+
   return labelsWithCounts;
 };
 
@@ -112,6 +118,7 @@ const TYPE_MAP = {
 
 const fetchVerticesAttributes = async (
   gremlinFetch: GremlinFetch,
+  remoteLogger: LoggerConnector,
   labels: Array<string>,
   countsByLabel: Record<string, number>
 ): Promise<SchemaResponse["vertices"]> => {
@@ -124,12 +131,12 @@ const fetchVerticesAttributes = async (
   // Batch in to sets of 100
   const batches = chunk(labels, BATCH_SIZE);
 
+  remoteLogger.info("[Gremlin Explorer] Fetching vertices attributes...");
   for (const batch of batches) {
     const verticesTemplate = verticesSchemaTemplate({
       types: batch,
     });
 
-    logger.log("[Gremlin Explorer] Fetching vertices attributes...");
     const response =
       await gremlinFetch<RawVerticesSchemaResponse>(verticesTemplate);
     const verticesSchemas = response.result.data["@value"][0]["@value"];
@@ -157,23 +164,34 @@ const fetchVerticesAttributes = async (
     }
   }
 
+  remoteLogger.info(
+    `[Gremlin Explorer] Found ${vertices.flatMap(v => v.attributes).length} vertex attributes across ${vertices.length} vertex types.`
+  );
+
   return vertices;
 };
 
 const fetchVerticesSchema = async (
-  gremlinFetch: GremlinFetch
+  gremlinFetch: GremlinFetch,
+  remoteLogger: LoggerConnector
 ): Promise<SchemaResponse["vertices"]> => {
-  const countsByLabel = await fetchVertexLabels(gremlinFetch);
+  const countsByLabel = await fetchVertexLabels(gremlinFetch, remoteLogger);
   const labels = Object.keys(countsByLabel);
 
-  return fetchVerticesAttributes(gremlinFetch, labels, countsByLabel);
+  return fetchVerticesAttributes(
+    gremlinFetch,
+    remoteLogger,
+    labels,
+    countsByLabel
+  );
 };
 
 const fetchEdgeLabels = async (
-  gremlinFetch: GremlinFetch
+  gremlinFetch: GremlinFetch,
+  remoteLogger: LoggerConnector
 ): Promise<Record<string, number>> => {
   const labelsTemplate = edgeLabelsTemplate();
-  logger.log("[Gremlin Explorer] Fetching edge labels with counts...");
+  remoteLogger.info("[Gremlin Explorer] Fetching edge labels with counts...");
   const data = await gremlinFetch<RawEdgeLabelsResponse>(labelsTemplate);
 
   const values = data.result.data["@value"][0]["@value"];
@@ -182,11 +200,16 @@ const fetchEdgeLabels = async (
     labelsWithCounts[values[i] as string] = (values[i + 1] as GInt64)["@value"];
   }
 
+  remoteLogger.info(
+    `[Gremlin Explorer] Found ${Object.keys(labelsWithCounts).length} edge labels.`
+  );
+
   return labelsWithCounts;
 };
 
 const fetchEdgesAttributes = async (
   gremlinFetch: GremlinFetch,
+  remoteLogger: LoggerConnector,
   labels: Array<string>,
   countsByLabel: Record<string, number>
 ): Promise<SchemaResponse["edges"]> => {
@@ -198,11 +221,11 @@ const fetchEdgesAttributes = async (
   // Batch in to sets of 100
   const batches = chunk(labels, BATCH_SIZE);
 
+  remoteLogger.info("[Gremlin Explorer] Fetching edges attributes...");
   for (const batch of batches) {
     const edgesTemplate = edgesSchemaTemplate({
       types: batch,
     });
-    logger.log("[Gremlin Explorer] Fetching edges attributes...");
     const data = await gremlinFetch<RawEdgesSchemaResponse>(edgesTemplate);
 
     const edgesSchemas = data.result.data["@value"][0]["@value"];
@@ -227,16 +250,26 @@ const fetchEdgesAttributes = async (
     }
   }
 
+  remoteLogger.info(
+    `[Gremlin Explorer] Found ${edges.flatMap(e => e.attributes).length} edge attributes across ${edges.length} edge types.`
+  );
+
   return edges;
 };
 
 const fetchEdgesSchema = async (
-  gremlinFetch: GremlinFetch
+  gremlinFetch: GremlinFetch,
+  remoteLogger: LoggerConnector
 ): Promise<SchemaResponse["edges"]> => {
-  const countsByLabel = await fetchEdgeLabels(gremlinFetch);
+  const countsByLabel = await fetchEdgeLabels(gremlinFetch, remoteLogger);
   const labels = Object.keys(countsByLabel);
 
-  return fetchEdgesAttributes(gremlinFetch, labels, countsByLabel);
+  return fetchEdgesAttributes(
+    gremlinFetch,
+    remoteLogger,
+    labels,
+    countsByLabel
+  );
 };
 
 /**
@@ -252,21 +285,26 @@ const fetchEdgesSchema = async (
  */
 const fetchSchema = async (
   gremlinFetch: GremlinFetch,
+  remoteLogger: LoggerConnector,
   summary?: GraphSummary
 ): Promise<SchemaResponse> => {
   if (!summary) {
-    logger.log("[Gremlin Explorer] No summary statistics");
+    remoteLogger.info("[Gremlin Explorer] No summary statistics");
 
-    const vertices = await fetchVerticesSchema(gremlinFetch);
+    const vertices = await fetchVerticesSchema(gremlinFetch, remoteLogger);
     const totalVertices = vertices.reduce((total, vertex) => {
       return total + (vertex.total ?? 0);
     }, 0);
 
-    const edges = await fetchEdgesSchema(gremlinFetch);
+    const edges = await fetchEdgesSchema(gremlinFetch, remoteLogger);
     const totalEdges = edges.reduce((total, edge) => {
       return total + (edge.total ?? 0);
     }, 0);
 
+    remoteLogger.info(
+      `[Gremlin Explorer] Schema sync successful (${totalVertices} vertices; ${totalEdges} edges; ${vertices.length} vertex types; ${edges.length} edge types)`
+    );
+
     return {
       totalVertices,
       vertices,
@@ -275,19 +313,25 @@ const fetchSchema = async (
     };
   }
 
-  logger.log("[Gremlin Explorer] Using summary statistics");
+  remoteLogger.info("[Gremlin Explorer] Using summary statistics");
 
   const vertices = await fetchVerticesAttributes(
     gremlinFetch,
+    remoteLogger,
     summary.nodeLabels,
     {}
   );
   const edges = await fetchEdgesAttributes(
     gremlinFetch,
+    remoteLogger,
     summary.edgeLabels,
     {}
   );
 
+  remoteLogger.info(
+    `[Gremlin Explorer] Schema sync successful (${summary.numNodes} vertices; ${summary.numEdges} edges; ${vertices.length} vertex types; ${edges.length} edge types)`
+  );
+
   return {
     totalVertices: summary.numNodes,
     vertices,

packages/graph-explorer/src/connector/openCypher/openCypherExplorer.ts

@@ -53,6 +53,7 @@ export function createOpenCypherExplorer(
       );
       return fetchSchema(
         _openCypherFetch(connection, featureFlags, options),
+        remoteLogger,
         summary
       );
     },