chore: add token validation logs (#137)

CHANGELOG.md

@@ -7,6 +7,9 @@ and this project adheres to [Semantic Versioning](http://semver.org/spec/v2.0.0.
 
 ## [Unreleased]
 
+### Added
+- Add token validation logs
+
 ### Removed
 - Reverted changes from versions 1.40.3, 1.40.2 and 1.40.1
 

node/directives/auditAccess.ts

@@ -27,6 +27,7 @@ export class AuditAccess extends SchemaDirectiveVisitor {
     } = context
 
     const operation = field.astNode?.name?.value ?? request.url
+    const userAgent = request.headers['user-agent'] as string
     const forwardedHost = request.headers['x-forwarded-host'] as string
     const caller =
       context.vtex.sender ?? (request.headers['x-vtex-caller'] as string)
@@ -40,6 +41,7 @@ export class AuditAccess extends SchemaDirectiveVisitor {
 
     const authMetric = new AuthMetric(account, {
       caller,
+      userAgent,
       forwardedHost,
       hasAdminToken,
       hasApiToken,

node/directives/checkAdminAccess.ts

@@ -3,6 +3,8 @@ import { AuthenticationError, ForbiddenError } from '@vtex/api'
 import type { GraphQLField } from 'graphql'
 import { defaultFieldResolver } from 'graphql'
 
+import sendAuthMetric, { AuthMetric } from '../metrics/auth'
+
 export class CheckAdminAccess extends SchemaDirectiveVisitor {
   public visitFieldDefinition(field: GraphQLField<any, any>) {
     const { resolve = defaultFieldResolver } = field
@@ -18,16 +20,63 @@ export class CheckAdminAccess extends SchemaDirectiveVisitor {
         clients: { identity },
       } = context
 
+      const operation = field.astNode?.name?.value ?? context.request.url
+      const metric = new AuthMetric(
+        context.vtex.account,
+        {
+          operation,
+          forwardedHost: context.request.header['x-forwarded-host'] as string,
+          caller: context.request.header['x-vtex-caller'] as string,
+          userAgent: context.request.header['user-agent'] as string,
+          hasAdminToken: !!adminUserAuthToken,
+          hasStoreToken: false,
+          hasApiToken: false,
+        },
+        'CheckAdminAccess'
+      )
+
       if (!adminUserAuthToken) {
+        metric.error = 'No admin token provided'
+        sendAuthMetric(logger, metric)
+        logger.warn({
+          message: 'CheckAdminAccess: No admin token provided',
+          userAgent: context.request.header['user-agent'],
+          vtexCaller: context.request.header['x-vtex-caller'],
+          forwardedHost: context.request.header['x-forwarded-host'],
+          operation,
+        })
         throw new AuthenticationError('No token was provided')
       }
 
       try {
-        await identity.validateToken({ token: adminUserAuthToken })
+        const authUser = await identity.validateToken({
+          token: adminUserAuthToken,
+        })
+
+        // This is the first step before actually enabling this code.
+        // For now we only log in case of errors, but in follow up commits
+        // we should also throw an exception inside this if in case of errors
+        if (!authUser?.audience || authUser?.audience !== 'admin') {
+          metric.error = 'Token is not an admin token'
+          sendAuthMetric(logger, metric)
+          logger.warn({
+            message: `CheckUserAccess: Token is not an admin token`,
+            userAgent: context.request.header['user-agent'],
+            vtexCaller: context.request.header['x-vtex-caller'],
+            forwardedHost: context.request.header['x-forwarded-host'],
+            operation,
+          })
+        }
       } catch (err) {
+        metric.error = 'Invalid token'
+        sendAuthMetric(logger, metric)
         logger.warn({
           error: err,
           message: 'CheckAdminAccess: Invalid token',
+          userAgent: context.request.header['user-agent'],
+          vtexCaller: context.request.header['x-vtex-caller'],
+          forwardedHost: context.request.header['x-forwarded-host'],
+          operation,
           token: adminUserAuthToken,
         })
         throw new ForbiddenError('Unauthorized Access')

node/directives/checkUserAccess.ts

@@ -3,6 +3,9 @@ import type { GraphQLField } from 'graphql'
 import { defaultFieldResolver } from 'graphql'
 import { SchemaDirectiveVisitor } from 'graphql-tools'
 
+import { getActiveUserByEmail } from '../resolvers/Queries/Users'
+import sendAuthMetric, { AuthMetric } from '../metrics/auth'
+
 export async function checkUserOrAdminTokenAccess(
   ctx: Context,
   operation?: string
@@ -12,21 +15,62 @@ export async function checkUserOrAdminTokenAccess(
     clients: { identity, vtexId },
   } = ctx
 
+  const metric = new AuthMetric(
+    ctx.vtex.account,
+    {
+      operation: operation ?? ctx.request.url,
+      forwardedHost: ctx.request.header['x-forwarded-host'] as string,
+      caller: ctx.request.header['x-vtex-caller'] as string,
+      userAgent: ctx.request.header['user-agent'] as string,
+      hasAdminToken: !!adminUserAuthToken,
+      hasStoreToken: !!storeUserAuthToken,
+      hasApiToken: false,
+    },
+    'CheckUserAccess'
+  )
+
   if (!adminUserAuthToken && !storeUserAuthToken) {
+    metric.error = 'No admin or store token was provided'
+    sendAuthMetric(logger, metric)
     logger.warn({
       message: `CheckUserAccess: No admin or store token was provided`,
+      userAgent: ctx.request.header['user-agent'],
+      vtexCaller: ctx.request.header['x-vtex-caller'],
+      forwardedHost: ctx.request.header['x-forwarded-host'],
       operation,
     })
     throw new AuthenticationError('No admin or store token was provided')
   }
 
   if (adminUserAuthToken) {
     try {
-      await identity.validateToken({ token: adminUserAuthToken })
+      const authUser = await identity.validateToken({
+        token: adminUserAuthToken,
+      })
+
+      // This is the first step before actually enabling this code.
+      // For now we only log in case of errors, but in follow up commits
+      // we should also throw an exception inside this if in case of errors
+      if (!authUser?.audience || authUser?.audience !== 'admin') {
+        metric.error = 'Token is not an admin token'
+        sendAuthMetric(logger, metric)
+        logger.warn({
+          message: `CheckUserAccess: Token is not an admin token`,
+          userAgent: ctx.request.header['user-agent'],
+          vtexCaller: ctx.request.header['x-vtex-caller'],
+          forwardedHost: ctx.request.header['x-forwarded-host'],
+          operation,
+        })
+      }
     } catch (err) {
+      metric.error = 'Invalid admin token'
+      sendAuthMetric(logger, metric)
       logger.warn({
         error: err,
         message: `CheckUserAccess: Invalid admin token`,
+        userAgent: ctx.request.header['user-agent'],
+        vtexCaller: ctx.request.header['x-vtex-caller'],
+        forwardedHost: ctx.request.header['x-forwarded-host'],
         operation,
       })
       throw new ForbiddenError('Unauthorized Access')
@@ -37,16 +81,61 @@ export async function checkUserOrAdminTokenAccess(
     try {
       authUser = await vtexId.getAuthenticatedUser(storeUserAuthToken)
       if (!authUser?.user) {
+        metric.error = 'No valid user found by store user token'
+        sendAuthMetric(logger, metric)
         logger.warn({
           message: `CheckUserAccess: No valid user found by store user token`,
+          userAgent: ctx.request.header['user-agent'],
+          vtexCaller: ctx.request.header['x-vtex-caller'],
+          forwardedHost: ctx.request.header['x-forwarded-host'],
           operation,
         })
         authUser = null
+      } else {
+        // This is the first step before actually enabling this code.
+        // For now we only log in case of errors, but in follow up commits
+        // we will remove this additional try/catch and set authUser = null
+        // in case of errors
+        try {
+          const user = (await getActiveUserByEmail(
+            null,
+            { email: authUser?.user },
+            ctx
+          )) as { roleId: string } | null
+
+          if (!user?.roleId) {
+            metric.error = 'No active user found by store user token'
+            sendAuthMetric(logger, metric)
+            logger.warn({
+              message: `CheckUserAccess: No active user found by store user token`,
+              userAgent: ctx.request.header['user-agent'],
+              vtexCaller: ctx.request.header['x-vtex-caller'],
+              forwardedHost: ctx.request.header['x-forwarded-host'],
+              operation,
+            })
+          }
+        } catch (err) {
+          metric.error = 'Error getting user by email'
+          sendAuthMetric(logger, metric)
+          logger.warn({
+            error: err,
+            message: `CheckUserAccess: Error getting user by email`,
+            userAgent: ctx.request.header['user-agent'],
+            vtexCaller: ctx.request.header['x-vtex-caller'],
+            forwardedHost: ctx.request.header['x-forwarded-host'],
+            operation,
+          })
+        }
       }
     } catch (err) {
+      metric.error = 'Invalid store user token'
+      sendAuthMetric(logger, metric)
       logger.warn({
         error: err,
         message: `CheckUserAccess: Invalid store user token`,
+        userAgent: ctx.request.header['user-agent'],
+        vtexCaller: ctx.request.header['x-vtex-caller'],
+        forwardedHost: ctx.request.header['x-forwarded-host'],
         operation,
       })
       authUser = null

node/metrics/auth.ts

@@ -7,6 +7,7 @@ export interface AuthAuditMetric {
   operation: string
   forwardedHost: string
   caller: string
+  userAgent: string
   role?: string
   permissions?: string[]
   hasAdminToken: boolean
@@ -20,12 +21,13 @@ export class AuthMetric implements Metric {
   public readonly account: string
   public readonly fields: AuthAuditMetric
   public readonly name = B2B_METRIC_NAME
+  public error?: string
 
-  constructor(account: string, fields: AuthAuditMetric) {
+  constructor(account: string, fields: AuthAuditMetric, description?: string) {
     this.account = account
     this.fields = fields
     this.kind = 'b2b-storefront-permissions-auth-event'
-    this.description = 'Auth metric event'
+    this.description = description ?? 'Auth metric event'
   }
 }