Merge pull request #568 from desci-labs/develop

promote main
desci-labs · Oct 15, 2024 · 2d35938 · 2d35938
2 parents 6c9e80d + 77f3f8f
commit 2d35938
Show file tree

Hide file tree

Showing 64 changed files with 1,759 additions and 456 deletions.
diff --git a/.env.example b/.env.example
@@ -119,7 +119,10 @@ ETHEREUM_RPC_URL=http://host.docker.internal:8545
 # Use this for Sepolia testnet
 # ETHEREUM_RPC_URL=https://eth-sepolia.g.alchemy.com/v2/demo
 
-DPID_URL_OVERRIDE=https://dev-beta.dpid.org
+# Use resolver in compose cluster locally
+DPID_URL_OVERRIDE=http://host.docker.internal:5460
+# Use public dev resolver
+# DPID_URL_OVERRIDE=https://dev-beta.dpid.org
 
 # Set to true if you want to mute the publish worker in local dev
 MUTE_PUBLISH_WORKER=false
@@ -139,8 +142,6 @@ CROSSREF_PASSWORD=
 # Cross ref notification callback envs
 CROSSREF_NOTIFY_ENDPOINT=endpoint
 
-# automated metadata
-
 # Automated metadata
 AUTOMATED_METADATA_API=http://host.docker.internal:5005
 AUTOMATED_METADATA_API_KEY=
@@ -158,6 +159,5 @@ ES_DB_NAME=
 ES_DB_USER=
 ES_DB_PASSWORD=
 
-
 ### open Alex Database - Postgres 
 OPEN_ALEX_DATABASE_URL=postgresql://username:password@host/database?schema=openalex
diff --git a/desci-repo/package.json b/desci-repo/package.json
@@ -69,7 +69,8 @@
   },
   "dependencies": {
     "@desci-labs/desci-models": "0.2.11",
-    "@sentry/node": "^7.84.0",
+    "@sentry/node": "8.29.0",
+    "@sentry/profiling-node": "8.32.0",
     "@sentry/tracing": "^7.84.0",
     "axios": "^1.6.2",
     "cors": "^2.8.5",

diff --git a/desci-repo/src/controllers/nodes/documents.ts b/desci-repo/src/controllers/nodes/documents.ts
@@ -1,6 +1,6 @@
 import { Request, Response } from 'express';
 import { ResearchObjectDocument } from '../../types.js';
-import { logger } from '../../logger.js';
+import { logger as parentLogger } from '../../logger.js';
 import { AutomergeUrl, DocumentId } from '@automerge/automerge-repo';
 import { RequestWithNode } from '../../middleware/guard.js';
 import { backendRepo } from '../../repo.js';
@@ -13,18 +13,18 @@ import { ensureUuidEndsWithDot } from './utils.js';
 import { ManifestActions } from '@desci-labs/desci-models';
 
 export const createNodeDocument = async function (req: Request, res: Response) {
-  logger.info('START [CreateNodeDocument]', req.body, req.params);
+  const logger = parentLogger.child({ module: 'createNodeDocument', body: req.body, param: req.params });
+  logger.trace('createNodeDocument');
+
   try {
     if (!(req.body.uuid && req.body.manifest)) {
       res.status(400).send({ ok: false, message: 'Invalid data' });
       return;
     }
 
     let { uuid, manifest } = req.body;
-
-    logger.info('[Backend REPO]:', backendRepo.networkSubsystem.peerId);
-
     uuid = ensureUuidEndsWithDot(uuid);
+    logger.info({ peerId: backendRepo.networkSubsystem.peerId, uuid }, '[Backend REPO]:');
     const handle = backendRepo.create<ResearchObjectDocument>();
     handle.change(
       (d) => {
@@ -35,62 +35,111 @@ export const createNodeDocument = async function (req: Request, res: Response) {
       { message: 'Init Document', time: Date.now() },
     );
 
+    logger.trace({ peerId: backendRepo.networkSubsystem.peerId, uuid }, 'Document Created');
+
     const document = await handle.doc();
 
-    const node = await findNodeByUuid(uuid);
+    logger.trace({ handleReady: handle.isReady() }, 'Document Retrieved');
+
+    // const node = await findNodeByUuid(uuid);
+    // logger.trace({ node }, 'Node Retrieved');
     // await prisma.node.update({ where: { id: node.id }, data: { manifestDocumentId: handle.documentId } });
-    const result = await query('UPDATE "Node" SET "manifestDocumentId" = $1 WHERE uuid = $2', [
-      handle.documentId,
-      uuid,
-    ]);
+    // const result = await query('UPDATE "Node" SET "manifestDocumentId" = $1 WHERE uuid = $2', [
+    //   handle.documentId,
+    //   uuid,
+    // ]);
+
+    // logger.trace(
+    //   { node, uuid, documentId: handle.documentId, url: handle.url, isReady: handle.isReady() },
+    //   'Node Updated',
+    // );
 
-    logger.info({ node, result }, '[createNodeDocument] UPDATE DOCUMENT ID');
-    logger.info('[AUTOMERGE]::[HANDLE NEW CHANGED]', handle.url, handle.isReady(), document);
+    // logger.info({ result }, 'UPDATE DOCUMENT ID');
 
     res.status(200).send({ ok: true, documentId: handle.documentId, document });
-    logger.info('END [CreateNodeDocument]', { documentId: handle.documentId, document });
+
+    logger.info({ documentId: handle.documentId, document }, 'END');
   } catch (err) {
-    console.error('Error [CreateNodeDocument]', err);
-    logger.error('END [CreateNodeDocument]', err);
+    logger.error({ err }, 'Error');
     res.status(500).send({ ok: false, message: JSON.stringify(err) });
   }
 };
 
 export const getLatestNodeManifest = async function (req: Request, res: Response) {
-  logger.info({ params: req.params }, 'START [getLatestNodeManifest]');
+  const logger = parentLogger.child({ module: 'getLatestNodeManifest', params: req.params });
+  logger.trace('getLatestNodeManifest');
+  const { uuid } = req.params;
+  const { documentId } = req.query;
+
+  const getDocument = async (documentId: DocumentId) => {
+    const automergeUrl = getAutomergeUrl(documentId);
+    const handle = backendRepo.find<ResearchObjectDocument>(automergeUrl as AutomergeUrl);
+    logger.trace({ uuid, automergeUrl }, 'Document Handle retrieved');
+
+    logger.trace({ uuid, automergeUrl }, 'Get DOCUMENT');
+    const document = await handle.doc();
+    logger.trace({ uuid, automergeUrl }, 'DOCUMENT Retrieved');
+    return document;
+  };
+
   try {
-    logger.info({ params: req.params }, '[getLatestNodeManifest]');
-    if (!req.params.uuid) {
+    // todo: add support for documentId params and skip querying node
+    // fast track call if documentId is available
+    if (documentId) {
+      logger.trace({ documentId }, 'Fast track using documentId');
+      const document = await getDocument(documentId as DocumentId);
+      if (document) res.status(200).send({ ok: true, document });
+      logger.trace({ document: !!document }, 'Fast tracked call using documentId');
+      return;
+    }
+
+    // calls might never reach this place again now that documentId is
+    // used to fast track calls and skip database calls
+    if (!uuid) {
       res.status(400).send({ ok: false, message: 'Invalid data' });
+      logger.trace('No UUID FOUND');
       return;
     }
 
-    const { uuid } = req.params;
-    const node = await findNodeByUuid(uuid);
-    logger.trace('[getLatestNodeManifest::node]', { node });
+    const node = await findNodeByUuid(ensureUuidEndsWithDot(uuid));
+    logger.trace({ node }, 'Retrieve Node');
 
     if (!node) {
-      logger.warn('[getLatestNodeManifest]', `Node with uuid ${uuid} not found!`);
-      res.status(400).send({ ok: false, message: `Node with uuid ${uuid} not found!` });
+      logger.warn({ uuid }, `Node with uuid ${uuid} not found!`);
+      res.status(404).send({ ok: false, message: `Node with uuid ${uuid} not found!` });
       return;
     }
 
-    const automergeUrl = getAutomergeUrl(node.manifestDocumentId as DocumentId);
-    const handle = backendRepo.find<ResearchObjectDocument>(automergeUrl as AutomergeUrl);
+    logger.info(
+      { manifestDocumentId: node.manifestDocumentId, url: getAutomergeUrl(node.manifestDocumentId) },
+      'Node manifestDocumentId',
+    );
 
-    const document = await handle.doc();
+    // const automergeUrl = getAutomergeUrl(node.manifestDocumentId as DocumentId);
+    // const handle = backendRepo.find<ResearchObjectDocument>(automergeUrl as AutomergeUrl);
+    // logger.trace({ uuid, automergeUrl }, 'Document Handle retrieved');
+
+    // logger.trace({ uuid, automergeUrl }, 'Get DOCUMENT');
+    // const document = await handle.doc();
+    // logger.trace({ uuid, automergeUrl }, 'DOCUMENT Retrieved');
 
-    logger.info({ manifest: document?.manifest, automergeUrl }, '[getLatestNodeManifest::END]');
+    if (!node.manifestDocumentId) {
+      res.status(404).send({ ok: false, message: `node: ${uuid} has no documentId: ${node.manifestDocumentId}` });
+      return;
+    }
+
+    const document = await getDocument(node.manifestDocumentId as DocumentId);
+
+    logger.info({ manifest: document?.manifest }, '[getLatestNodeManifest::END]');
     res.status(200).send({ ok: true, document });
   } catch (err) {
-    console.error('Error [getLatestNodeManifest]', err);
-    logger.error(err, 'Error [getLatestNodeManifest]');
+    logger.error({ err }, 'Error');
     res.status(500).send({ ok: false, message: JSON.stringify(err) });
   }
 };
 
 export const dispatchDocumentChange = async function (req: RequestWithNode, res: Response) {
-  logger.info({ params: req.params }, 'START [dispatchDocumentChange]');
+  const logger = parentLogger.child({ module: 'dispatchDocumentChange', body: req.body, params: req.params });
   try {
     if (!(req.body.uuid && req.body.documentId && req.body.actions)) {
       res.status(400).send({ ok: false, message: 'Invalid data' });
@@ -109,8 +158,8 @@ export const dispatchDocumentChange = async function (req: RequestWithNode, res:
 
     const dispatchChange = getDocumentUpdater(documentId);
 
+    logger.info({ actions }, 'Actions');
     for (const action of actions) {
-      logger.info({ action }, '[AUTOMERGE]::[dispatch Update]');
       document = await dispatchChange(action);
     }
 
@@ -119,16 +168,16 @@ export const dispatchDocumentChange = async function (req: RequestWithNode, res:
       return;
     }
 
-    logger.info('END [dispatchDocumentChange]', { document });
     res.status(200).send({ ok: true, document });
+    logger.trace('END');
   } catch (err) {
-    logger.error(err, 'Error [dispatchDocumentChange]');
-
+    logger.error({ err }, 'Error [dispatchDocumentChange]');
     res.status(500).send({ ok: false, message: JSON.stringify(err) });
   }
 };
 
 export const dispatchDocumentActions = async function (req: RequestWithNode, res: Response) {
+  const logger = parentLogger.child({ module: 'dispatchDocumentActions' });
   logger.info({ body: req.body }, 'START [dispatchDocumentActions]');
   try {
     if (!(req.body.uuid && req.body.documentId && req.body.actions)) {

diff --git a/desci-repo/src/index.ts b/desci-repo/src/index.ts
@@ -1,6 +1,5 @@
 import { logger } from './logger.js';
 import { server } from './server.js';
-// import * as db from './dbs/index.js';
 
 server.ready().then(async (_) => {
   logger.info('server is ready');

diff --git a/desci-repo/src/logger.ts b/desci-repo/src/logger.ts
@@ -2,6 +2,9 @@ import { pino } from 'pino';
 import { fileURLToPath } from 'url';
 import path from 'path';
 import { pool } from './db/index.js';
+import { AsyncLocalStorage } from 'async_hooks';
+
+export const als = new AsyncLocalStorage();
 
 const __filename = fileURLToPath(import.meta.url);
 const __dirname = path.dirname(__filename);
@@ -24,17 +27,86 @@ const fileTransport = {
 
 console.log('[DIR NAME]::', __dirname, __filename, logLevel);
 
+function logMethodHooks(inputArgs, method) {
+  try {
+    //get caller
+    const stack = new Error()?.stack?.split('\n') ?? [];
+    // find first line that is not from this file
+
+    let callerFilePath;
+    try {
+      const intermediate = stack.filter(
+        (a) => a.includes('file:///') && !(a.includes('/dist/logger.') || a.includes('/src/logger.')),
+      )[0];
+
+      if (intermediate) {
+        callerFilePath = intermediate
+          .split('(')[1]
+          .split(')')[0]
+          .replace('file:///app/desci-repo/src/', '')
+          .replace('file:///app/dist/', '');
+      }
+    } catch (err) {
+      // callerFilePath = '-unknown-';
+    }
+
+    let target = typeof inputArgs[0] == 'string' ? 1 : 0;
+    let newInputArgs = [...inputArgs];
+
+    if (!newInputArgs[target]) {
+      newInputArgs[target] = {};
+    } else if (typeof newInputArgs[target] !== 'object') {
+      const rawValue = {};
+      rawValue['stringLogs'] = inputArgs;
+
+      rawValue['error'] =
+        'this means your pino log statement is incorrectly formatted, check the order of the arguments';
+      target = 0;
+      newInputArgs[target] = { rawValue };
+      newInputArgs = [newInputArgs[0], inputArgs[0]];
+    }
+
+    newInputArgs[target]['caller'] = callerFilePath;
+
+    const traceId = (als.getStore() as any)?.traceId;
+    const callerTraceId = (als.getStore() as any)?.callerTraceId;
+    if (traceId) {
+      newInputArgs[target]['traceId'] = traceId;
+      newInputArgs[target]['callerTraceId'] = callerTraceId || '';
+
+      const timingArray = (als.getStore() as any)?.timing;
+      if (timingArray) {
+        newInputArgs[target]['traceIndex'] = timingArray.length;
+        newInputArgs[target]['traceDelta'] = Date.now() - timingArray[timingArray.length - 1];
+      }
+      (als.getStore() as any)?.timing.push(Date.now());
+    }
+
+    return method.apply(this, [...newInputArgs]);
+  } catch (err) {
+    // logger.error({ err }, 'error in logMethod hook');
+    return method.apply(this, inputArgs);
+  }
+}
+
+const IS_PROD = process.env.NODE_ENV === 'production';
+const transport = {
+  ...(!IS_PROD && {
+    transport: {
+      targets: [devTransport, fileTransport],
+    },
+  }),
+};
+console.log('[transport]', transport);
 export const logger = pino({
+  ...transport,
   level: logLevel,
   serializers: {
     files: omitBuffer,
   },
-  transport:
-    process.env.NODE_ENV === 'production'
-      ? { targets: [] }
-      : {
-          targets: [devTransport, fileTransport],
-        },
+  hooks: {
+    logMethod: logMethodHooks,
+  },
   redact: {
     paths: [
       'req.headers.cookie',
@@ -69,25 +141,16 @@ function omitBuffer(array) {
 }
 
 type RejectionPayload = {
-  reason: unknown,
-  promise: Promise<unknown>,
+  reason: unknown;
+  promise: Promise<unknown>;
 };
 
-const shutdownNicely = async (
-  err: Error | RejectionPayload,
-  kind: string
-): Promise<void> => {
+const shutdownNicely = async (err: Error | RejectionPayload, kind: string): Promise<void> => {
   await pool.end();
   logger.fatal(err, kind);
   process.exit(1);
 };
 
-process.on(
-  'uncaughtException',
-  e => shutdownNicely(e, 'uncaughtException')
-);
+process.on('uncaughtException', (e) => shutdownNicely(e, 'uncaughtException'));
 
-process.on(
-  'unhandledRejection',
-  (reason, promise) => shutdownNicely({ reason, promise }, 'unhandledRejection')
-);
+process.on('unhandledRejection', (reason, promise) => shutdownNicely({ reason, promise }, 'unhandledRejection'));
diff --git a/desci-repo/src/middleware/ensureApiKey.ts b/desci-repo/src/middleware/ensureApiKey.ts
@@ -5,7 +5,7 @@ const REPO_SERVICE_API_KEY = process.env.REPO_SERVICE_SECRET_KEY;
 
 export const ensureApiKey = async (req: Request, res: Response, next: NextFunction) => {
   const apiKey = req.headers['x-api-key'];
-  logger.info({ module: 'EnsureApiKey', apiKeyLength: apiKey?.length }, 'VERIFY API KEY from', req.hostname);
+  logger.info({ module: 'EnsureApiKey', apiKeyLength: apiKey?.length, hostname: req.hostname }, 'VERIFY API KEY from');
   if (!apiKey || apiKey !== REPO_SERVICE_API_KEY) {
     res.sendStatus(401);
     return;

diff --git a/desci-repo/src/middleware/guard.ts b/desci-repo/src/middleware/guard.ts
@@ -20,6 +20,8 @@ export type Node = {
 
 export interface RequestWithUser extends Request {
   user: { email: string; id: number };
+  traceId?: string;
+  callerTraceId?: string;
 }
 
 export interface RequestWithNode extends RequestWithUser {