ORCID flow debugging

desci-server/kubernetes/deployment_dev.yaml

@@ -95,6 +95,7 @@ spec:
           export ELASTIC_SEARCH_USER="{{ .Data.ELASTIC_SEARCH_USER }}"
           export ELASTIC_SEARCH_PW="{{ .Data.ELASTIC_SEARCH_PW }}"
           export OPEN_ALEX_DATABASE_URL="{{ .Data.OPEN_ALEX_DATABASE_URL }}"
+          export LOG_ENCRYPTION_KEY="{{ .Data.LOG_ENCRYPTION_KEY }}"
           export DEBUG_TEST=0;
           echo "appfinish";
           {{- end -}}

desci-server/kubernetes/deployment_prod.yaml

@@ -95,6 +95,7 @@ spec:
           export ELASTIC_SEARCH_USER="{{ .Data.ELASTIC_SEARCH_USER }}"
           export ELASTIC_SEARCH_PW="{{ .Data.ELASTIC_SEARCH_PW }}"
           export OPEN_ALEX_DATABASE_URL="{{ .Data.OPEN_ALEX_DATABASE_URL }}"
+          export LOG_ENCRYPTION_KEY="{{ .Data.LOG_ENCRYPTION_KEY }}"
           export IGNORE_LINE=0;
           export DEBUG_TEST=0;
           echo "appfinish";

desci-server/src/controllers/admin/analytics.ts

@@ -30,6 +30,7 @@ export const createCsv = async (req: Request, res: Response) => {
     const endMonth = new Date().getMonth();
     let curYear = endYear - 1;
     let curMonth = endMonth;
+    let monthsCovered = 0;
     interface DataRow {
       month: string;
       year: string;
@@ -40,7 +41,7 @@ export const createCsv = async (req: Request, res: Response) => {
       bytesUploaded: number;
     }
     const data: DataRow[] = [];
-    while (curYear < endYear || curMonth <= endMonth) {
+    while (monthsCovered <= 12) {
       const newUsers = await getCountNewUsersInMonth(curMonth, curYear);
       const newNodes = await getCountNewNodesInMonth(curMonth, curYear);
       const activeUsers = await getCountActiveUsersInMonth(curMonth, curYear);
@@ -61,6 +62,7 @@ export const createCsv = async (req: Request, res: Response) => {
         curYear++;
         curMonth = 0;
       }
+      monthsCovered++;
     }
     // export data to csv
 

desci-server/src/controllers/auth/logout.ts

@@ -11,7 +11,7 @@ export const logout = async (req: Request, res: Response, next: NextFunction) =>
     httpOnly: true, // Ineffective whilst we still return the bearer token to the client in the response
     secure: process.env.NODE_ENV === 'production',
     domain: process.env.NODE_ENV === 'production' ? '.desci.com' : 'localhost',
-    sameSite: 'strict',
+    sameSite: 'none',
     path: '/',
   });
 
@@ -21,7 +21,7 @@ export const logout = async (req: Request, res: Response, next: NextFunction) =>
       httpOnly: true, // Ineffective whilst we still return the bearer token to the client in the response
       secure: process.env.NODE_ENV === 'production',
       domain: process.env.NODE_ENV === 'production' ? domain || '.desci.com' : 'localhost',
-      sameSite: 'strict',
+      sameSite: 'none',
       path: '/',
     });
   });
@@ -31,7 +31,7 @@ export const logout = async (req: Request, res: Response, next: NextFunction) =>
     res.cookie(AUTH_COOKIE_FIELDNAME, 'unset', {
       maxAge: 0,
       httpOnly: true,
-      sameSite: 'strict',
+      sameSite: 'none',
       path: '/',
     });
   }

desci-server/src/controllers/auth/magic.ts

@@ -3,7 +3,7 @@ import { Request, Response, NextFunction } from 'express';
 import jwt from 'jsonwebtoken';
 
 import { prisma as prismaClient } from '../../client.js';
-import { logger } from '../../logger.js';
+import { logger as parentLogger } from '../../logger.js';
 import { magicLinkRedeem, sendMagicLink } from '../../services/auth.js';
 import { contributorService } from '../../services/Contributors.js';
 import { saveInteraction } from '../../services/interactionLog.js';
@@ -20,15 +20,27 @@ export const oneYear = 1000 * 60 * 60 * 24 * 365;
 export const oneDay = 1000 * 60 * 60 * 24;
 export const oneMinute = 1000 * 60;
 export const magic = async (req: Request, res: Response, next: NextFunction) => {
+  const { email, code, dev, orcid, access_token, refresh_token, expires_in } = req.body;
+  const cleanEmail = email.toLowerCase().trim();
+
+  const logger = parentLogger.child({
+    module: '[Auth]::Magic',
+    email: email,
+    cleanEmail: cleanEmail,
+    code: `${code ? 'XXXX' + code.slice(-2) : ''}`,
+    orcid,
+  });
+
   if (process.env.NODE_ENV === 'production') {
-    logger.info({ fn: 'magic', email: req.body.email }, `magic link requested`);
+    if (code) {
+      logger.info({ email: req.body.email }, `[MAGIC] User attempting to auth with magic code: XXXX${code.slice(-2)}`);
+    } else {
+      logger.info({ email: req.body.email }, `[MAGIC] User requested a magic code, cleanEmail: ${cleanEmail}`);
+    }
   } else {
     logger.info({ fn: 'magic', reqBody: req.body }, `magic link`);
   }
 
-  const { email, code, dev, orcid, access_token, refresh_token, expires_in } = req.body;
-  const cleanEmail = email.toLowerCase().trim();
-
   if (!code) {
     // we are sending the magic code
 
@@ -68,18 +80,32 @@ export const magic = async (req: Request, res: Response, next: NextFunction) =>
     try {
       const ip = req.ip;
       const ok = await sendMagicLink(cleanEmail, ip);
-      res.send({ ok });
+      logger.info({ ok }, 'Magic link sent');
+      res.send({ ok: !!ok });
     } catch (err) {
-      logger.error({ ...err, fn: 'magic' });
-      res.status(400).send({ ok: false, error: err.message });
+      logger.error({ err }, 'Failed sending code');
+      res.status(400).send({ ok: false, error: 'Failed sending code' });
     }
   } else {
     // we are validating the magic code is correct
     try {
       const user = await magicLinkRedeem(cleanEmail, code);
 
+      if (!user) throw new Error('User not found');
+
       if (orcid && user) {
-        logger.trace({ fn: 'magic', orcid }, `setting orcid for user`);
+        logger.trace(
+          {
+            orcid,
+            accessTokenLength: access_token?.length,
+            accessTokenPresent: !!access_token,
+            refreshTokenLength: refresh_token?.length,
+            refreshTokenPresent: !!refresh_token,
+            orcidAccessExpiry: expires_in,
+          },
+
+          `setting orcid for user`,
+        );
 
         if (!user.name) {
           const orcidRecord = await getOrcidRecord(orcid, access_token);
@@ -106,12 +132,15 @@ export const magic = async (req: Request, res: Response, next: NextFunction) =>
       // TODO: Bearer token still returned for backwards compatability, should look to remove in the future.
       res.send({ ok: true, user: { email: user.email, token, termsAccepted } });
 
+      logger.info('[MAGIC] User logged in successfully');
+
       if (!termsAccepted) {
         // saveInteraction(req, ActionType.USER_TERMS_CONSENT, { userId: user.id, email: user.email }, user.id);
       }
       saveInteraction(req, ActionType.USER_LOGIN, { userId: user.id }, user.id);
     } catch (err) {
-      res.status(200).send({ ok: false, error: err.message });
+      logger.error({ err }, 'Failed redeeming code');
+      res.status(400).send({ ok: false, error: 'Failed redeeming code' });
     }
   }
 };

desci-server/src/controllers/nodes/preparePublishPackage.ts

@@ -47,10 +47,19 @@ export const preparePublishPackage = async (
   // debugger; //
   logger.trace({ fn: 'Retrieving Publish Package' });
 
-  if (!nodeUuid) return res.status(400).json({ ok: false, error: 'nodeUuid is required.' });
+  if (!nodeUuid) {
+    logger.warn({}, 'nodeUuid is required');
+    return res.status(400).json({ ok: false, error: 'nodeUuid is required.' });
+  }
   // if (!doi) return res.status(400).json({ ok: false, error: 'doi is required.' });
-  if (!pdfCid) return res.status(400).json({ ok: false, error: 'pdfCid is required.' });
-  if (!manifestCid) return res.status(400).json({ ok: false, error: 'manifestCid is required.' });
+  if (!pdfCid) {
+    logger.warn({}, 'pdfCid is required');
+    return res.status(400).json({ ok: false, error: 'pdfCid is required.' });
+  }
+  if (!manifestCid) {
+    logger.warn({}, 'manifestCid is required');
+    return res.status(400).json({ ok: false, error: 'manifestCid is required.' });
+  }
 
   try {
     const node = await prisma.node.findFirst({
@@ -59,11 +68,18 @@ export const preparePublishPackage = async (
       },
     });
 
-    if (!node) return res.status(404).json({ ok: false, error: 'Node not found' });
+    if (!node) {
+      logger.warn({ nodeUuid }, 'Node not found');
+      return res.status(404).json({ ok: false, error: 'Node not found' });
+    }
 
     const manifest = await getManifestByCid(manifestCid);
-    if (!manifest) return res.status(404).json({ ok: false, error: 'Manifest not found' });
+    if (!manifest) {
+      logger.warn({ manifestCid }, 'Manifest not found');
+      return res.status(404).json({ ok: false, error: 'Manifest not found' });
+    }
     // debugger;
+    logger.trace({ nodeUuid, pdfCid, doi, manifestCid }, 'Preparing distribution package');
     const { pdfCid: distPdfCid } = await publishPackageService.prepareDistributionPdf({
       pdfCid,
       node,
@@ -77,9 +93,12 @@ export const preparePublishPackage = async (
 
     let previewMap: PreviewMap = {};
     if (withPreviews) {
+      logger.trace({ distPdfCid, fn: 'Generating PDF previews' });
       previewMap = await publishPackageService.generatePdfPreview(distPdfCid, 1000, [1, 2], node.uuid);
     }
 
+    logger.trace({ distPdfCid, previewMap, fn: 'Distribution package prepared' });
+
     return res.status(200).json({
       ok: true,
       distPdfCid,

desci-server/src/middleware/attachUser.ts

@@ -17,9 +17,9 @@ export const attachUser = async (req: Request, res: Response, next: NextFunction
   const authHeader = req.headers['authorization'];
   const apiKeyHeader = req.headers['api-key'];
 
-  const token = authHeader ? await extractAuthToken(req) : undefined;
+  const token = await extractAuthToken(req);
   const apiKey = apiKeyHeader ? await await extractApiKey(req) : undefined;
-  const authTokenRetrieval = authHeader ? await extractUserFromToken(token) : undefined;
+  const authTokenRetrieval = await extractUserFromToken(token);
   const apiKeyRetrieval = apiKeyHeader ? await extractUserFromApiKey(apiKey, req.ip) : undefined;
 
   const retrievedUser = authTokenRetrieval || apiKeyRetrieval;

desci-server/src/middleware/checkJwt.ts

@@ -44,7 +44,7 @@ export const checkJwt = (req: Request, res: Response, next: NextFunction) => {
       httpOnly: true, // Ineffective whilst we still return the bearer token to the client in the response
       secure: process.env.NODE_ENV === 'production',
       domain: process.env.NODE_ENV === 'production' ? '.desci.com' : 'localhost',
-      sameSite: 'strict',
+      sameSite: 'none',
     });
 
     return next();

desci-server/src/routes/v1/services.ts

@@ -3,6 +3,7 @@ import multer from 'multer';
 
 import { ephemeralThumbnail } from '../../controllers/proxy/ephemeralThumbnail.js';
 import { orcidDid, orcidProfile } from '../../controllers/proxy/orcidProfile.js';
+import { logger as parentLogger } from '../../logger.js';
 import { ensureUser } from '../../middleware/permissions.js';
 
 const router = Router();
@@ -12,6 +13,25 @@ const upload = multer();
 router.get('/orcid/profile/:orcidId', [], orcidProfile);
 router.get('/orcid/did/:did', [], orcidDid);
 
-router.post('/thumbnails/ephemeral', [ensureUser, upload.single('file')], ephemeralThumbnail);
+const logger = parentLogger.child({ module: 'Services UploadHandler' });
+
+const wrappedHandler = (req, res, next) => {
+  upload.single('file')(req, res, (err) => {
+    // debugger
+    if (err) {
+      if (err instanceof multer.MulterError) {
+        logger.error({ err, type: 'MulterError' }, 'MulterError');
+        throw err;
+      } else {
+        logger.error({ err }, 'Upload Handler Error encountered');
+        res.status(401).send({ msg: 'unauthorized', code: '5412419' });
+        return;
+      }
+    }
+    next();
+  });
+};
+
+router.post('/thumbnails/ephemeral', [ensureUser, wrappedHandler], ephemeralThumbnail);
 
 export default router;

desci-server/src/services/auth.ts

@@ -8,7 +8,7 @@ import { prisma as client } from '../client.js';
 import { logger as parentLogger } from '../logger.js';
 import { MagicCodeEmailHtml } from '../templates/emails/utils/emailRenderer.js';
 import createRandomCode from '../utils/createRandomCode.js';
-import { hideEmail } from '../utils.js';
+import { encryptForLog, hideEmail } from '../utils.js';
 
 AWS.config.update({ region: 'us-east-2' });
 sgMail.setApiKey(process.env.SENDGRID_API_KEY);
@@ -29,21 +29,43 @@ const registerUser = async (email: string) => {
 
 const magicLinkRedeem = async (email: string, token: string): Promise<User> => {
   email = email.toLowerCase();
+  if (!email) throw Error('Email is required');
   logger.trace({ fn: 'magicLinkRedeem', email: hideEmail(email) }, 'auth::magicLinkRedeem');
 
   const link = await client.magicLink.findFirst({
     where: {
       email,
     },
     orderBy: {
-      createdAt: 'desc',
+      id: 'desc',
     },
   });
 
   if (!link) {
     throw Error('No magic link found for the provided email.');
   }
 
+  const logEncryptionKeyPresent = process.env.LOG_ENCRYPTION_KEY && process.env.LOG_ENCRYPTION_KEY.length > 0;
+  logger.trace(
+    {
+      fn: 'magicLinkRedeem',
+      email: hideEmail(email),
+      tokenProvided: 'XXXX' + token.slice(-2),
+      tokenProvidedLength: token.length,
+      latestLinkFound: 'XXXX' + link.token.slice(-2),
+      linkEqualsToken: link.token === token,
+      latestLinkExpiry: link.expiresAt,
+      latestLinkId: link.id,
+      ...(logEncryptionKeyPresent
+        ? {
+            eTokenProvided: encryptForLog(token, process.env.LOG_ENCRYPTION_KEY),
+            eEmail: encryptForLog(email, process.env.LOG_ENCRYPTION_KEY),
+          }
+        : {}),
+    },
+    '[MAGIC]auth::magicLinkRedeem comparison debug',
+  );
+
   if (link.failedAttempts >= 5) {
     // Invalidate the token immediately
     await client.magicLink.update({
@@ -69,6 +91,21 @@ const magicLinkRedeem = async (email: string, token: string): Promise<User> => {
         },
       },
     });
+    logger.info(
+      {
+        fn: 'magicLinkRedeem',
+        linkId: link.id,
+        token: 'XXXX' + token.slice(-2),
+        ...(logEncryptionKeyPresent
+          ? {
+              eTokenProvided: encryptForLog(token, process.env.LOG_ENCRYPTION_KEY),
+              eEmail: encryptForLog(email, process.env.LOG_ENCRYPTION_KEY),
+            }
+          : {}),
+        newFailedAttempts: link.failedAttempts + 1,
+      },
+      'Invalid token attempt',
+    );
     throw Error('Invalid token.');
   }
 
@@ -176,10 +213,18 @@ const sendMagicLinkEmail = async (email: string, ip?: string) => {
       //   .sendEmail(params)
       //   .promise();
       // const data = await sendPromise;
-      logger.info({ fn: 'sendMagicLinkEmail', email, msg }, 'Email sent');
+      logger.info({ fn: 'sendMagicLinkEmail', email, tokenSent: 'XXXX' + token.slice(-2) }, '[MAGIC]Email sent');
     } catch (err) {
       logger.error({ fn: 'sendMagicLinkEmail', err, email }, 'Mail error');
     }
+    if (process.env.NODE_ENV === 'dev') {
+      // Print this anyway whilst developing, even if emails are being sent
+      const Reset = '\x1b[0m';
+      const BgGreen = '\x1b[42m';
+      const BgYellow = '\x1b[43m';
+      const BIG_SIGNAL = `\n\n${BgYellow}$$$$$$$$$$$$$$$$$$$$$$$$$$$$$$${Reset}\n\n`;
+      logger.info(`${BIG_SIGNAL}Email sent to ${email}\n\nToken: ${BgGreen}${token}${Reset}${BIG_SIGNAL}`);
+    }
     return true;
   } else {
     const Reset = '\x1b[0m';