feat(auth-service): log OTP send duration, messageId and SMTP response

aspiers · claude · aspiers · commit 2193515970c5 · 2026-07-20T14:04:16.000+01:00
Closes #183. The per-send completion line previously carried only the recipient, so a slow-but-successful SMTP handoff was indistinguishable from a fast one and app logs could not be joined to Resend's per-message delivery events. Wrap every sendMail() in a timedSendMail() helper that measures the handoff, captures the result, and folds elapsedMs, messageId and smtpResponse into the existing success line — one enriched line per send across all four paths (client-branded, sign-in, welcome, backup). On failure it stamps elapsedMs onto the thrown error so the existing "failed to send OTP email" line carries the duration without adding a second failure line. The explicit-SMTP-timeouts part of #183 is intentionally deferred: it would change send behaviour (a slow-but-successful handshake could start failing) and the right values need to be chosen from real latency data, which the elapsedMs logging added here will itself provide. Tracked separately. Co-Authored-By: Claude Opus 4.8 <noreply@anthropic.com>
diff --git a/.changeset/otp-send-timing-logging.md b/.changeset/otp-send-timing-logging.md
@@ -0,0 +1,9 @@
+---
+'ePDS': minor
+---
+
+OTP send logs now record how long the email handoff took, the provider's message ID, and the SMTP server response.
+
+**Affects:** Operators
+
+**Operators:** every OTP email completion line (all four paths — client-branded, sign-in, welcome, backup-email verification) now carries `elapsedMs`, `messageId`, and `smtpResponse` alongside `email`. `messageId` lets these logs be joined to Resend delivery events; `elapsedMs` isolates a slow SMTP handoff from other causes of late-arriving codes. Failed sends log `elapsedMs` too, on the existing `better-auth: failed to send OTP email` error line.
diff --git a/packages/auth-service/src/__tests__/email-template.test.ts b/packages/auth-service/src/__tests__/email-template.test.ts
@@ -13,6 +13,7 @@ import {
   EmailSender,
   _seedTemplateCacheForTest,
   _clearTemplateCacheForTest,
+  _loggerForTest,
 } from '../email/sender.js'
 import {
   formatOtpHtmlGrouped,
@@ -267,4 +268,102 @@ describe('EmailSender', () => {
       ).resolves.toBeUndefined()
     })
   })
+
+  // Regression cover for #183: the per-send completion line must carry
+  // the SMTP handoff duration and the provider's messageId / server
+  // response so app logs can be timed and joined to Resend delivery
+  // events. jsonTransport supplies a real messageId + response.
+  describe('per-send diagnostic logging', () => {
+    it('folds elapsedMs, messageId and smtpResponse into the success line', async () => {
+      const sender = makeSender()
+      const info = vi
+        .spyOn(_loggerForTest, 'info')
+        .mockImplementation(() => _loggerForTest)
+
+      await sender.sendOtpCode({
+        to: 'user@test.com',
+        code: '12345678',
+        clientAppName: 'Test App',
+        pdsName: 'Test PDS',
+        pdsDomain: 'pds.example',
+      })
+
+      expect(info).toHaveBeenCalledOnce()
+      const [fields, message] = info.mock.calls[0] as [
+        Record<string, unknown>,
+        string,
+      ]
+      expect(message).toBe('Sent sign-in OTP email')
+      expect(fields.email).toBe('user@test.com')
+      expect(fields.elapsedMs).toEqual(expect.any(Number))
+      expect(fields.elapsedMs as number).toBeGreaterThanOrEqual(0)
+      expect(fields.messageId).toEqual(expect.any(String))
+      // jsonTransport reports its serialized envelope as the response.
+      expect(fields).toHaveProperty('smtpResponse')
+
+      info.mockRestore()
+    })
+
+    it('carries clientId alongside the diagnostic fields on the branded line', async () => {
+      const TRUSTED_ID = 'https://branded.app/client-metadata.json'
+      _seedClientMetadataCacheForTest(TRUSTED_ID, {
+        client_name: 'Branded App',
+        email_template_uri: 'https://branded.app/email-template.html',
+        logo_uri: 'https://branded.app/logo.png',
+      })
+      _seedTemplateCacheForTest(
+        'https://branded.app/email-template.html',
+        '<html><body>Your code is {{code}}</body></html>',
+      )
+      const sender = makeSender([TRUSTED_ID])
+      const info = vi
+        .spyOn(_loggerForTest, 'info')
+        .mockImplementation(() => _loggerForTest)
+
+      await sender.sendOtpCode({
+        to: 'branded@test.com',
+        code: '99999999',
+        clientAppName: 'Fallback Name',
+        clientId: TRUSTED_ID,
+        pdsName: 'Test PDS',
+        pdsDomain: 'pds.example',
+      })
+
+      const [fields, message] = info.mock.calls[0] as [
+        Record<string, unknown>,
+        string,
+      ]
+      expect(message).toBe('Sent client-branded OTP email')
+      expect(fields.clientId).toBe(TRUSTED_ID)
+      expect(fields.elapsedMs).toEqual(expect.any(Number))
+      expect(fields.messageId).toEqual(expect.any(String))
+
+      info.mockRestore()
+    })
+
+    it('stamps elapsedMs onto a failed send for the caller error log', async () => {
+      const sender = makeSender()
+      vi.spyOn(sender['transporter'], 'sendMail').mockRejectedValue(
+        new Error('SMTP handshake timed out'),
+      )
+
+      let caught: (Error & { elapsedMs?: number }) | undefined
+      try {
+        await sender.sendOtpCode({
+          to: 'user@test.com',
+          code: '12345678',
+          clientAppName: 'Test App',
+          pdsName: 'Test PDS',
+          pdsDomain: 'pds.example',
+        })
+      } catch (e) {
+        caught = e as Error & { elapsedMs?: number }
+      }
+
+      expect(caught).toBeInstanceOf(Error)
+      expect(caught?.message).toBe('SMTP handshake timed out')
+      expect(caught?.elapsedMs).toEqual(expect.any(Number))
+      expect(caught?.elapsedMs as number).toBeGreaterThanOrEqual(0)
+    })
+  })
 })
diff --git a/packages/auth-service/src/better-auth.ts b/packages/auth-service/src/better-auth.ts
@@ -362,9 +362,15 @@ export function createBetterAuth(
               isNewUser,
             })
             .catch((err: unknown) => {
-              // Log and swallow — caller does not await this
+              // Log and swallow — caller does not await this.
+              // `EmailSender.timedSendMail` stamps the SMTP handoff
+              // duration onto the error so this single line carries it.
+              const elapsedMs =
+                err instanceof Error
+                  ? (err as Error & { elapsedMs?: number }).elapsedMs
+                  : undefined
               logger.error(
-                { err, email, isNewUser },
+                { err, email, isNewUser, elapsedMs },
                 'better-auth: failed to send OTP email',
               )
             })
diff --git a/packages/auth-service/src/email/sender.ts b/packages/auth-service/src/email/sender.ts
@@ -1,6 +1,6 @@
 import * as nodemailer from 'nodemailer'
 import { createLogger } from '@certified-app/shared'
-import type { Transporter } from 'nodemailer'
+import type { SendMailOptions, SentMessageInfo, Transporter } from 'nodemailer'
 import type { EmailConfig } from '@certified-app/shared'
 import {
   buildSignInCodeEmail,
@@ -11,6 +11,11 @@ import { buildClientBrandedEmail } from './client-template.js'
 
 const logger = createLogger('auth:email')
 
+// Exposed for tests that assert the structured fields on the per-send
+// completion line (elapsedMs / messageId / smtpResponse). Production
+// code must not import this.
+export const _loggerForTest: ReturnType<typeof createLogger> = logger
+
 // Re-exports so existing tests that reach for the template cache still
 // resolve through sender.js. New code should import directly from
 // ./client-template.js.
@@ -95,6 +100,47 @@ export class EmailSender {
     }
   }
 
+  /**
+   * Send one message, measuring how long the SMTP handoff takes and
+   * folding the elapsed time plus the provider's `messageId` / server
+   * `response` into a single structured completion line. `messageId`
+   * lets these app logs be joined to Resend's per-message delivery
+   * events (see #183 / #198) so provider-side latency can be told apart
+   * from users submitting stale codes.
+   *
+   * On failure the error is re-thrown after stamping it with
+   * `elapsedMs`, so the caller's existing error log can carry the
+   * duration without adding a second line per failure.
+   */
+  private async timedSendMail(
+    mail: SendMailOptions,
+    message: string,
+    extra: Record<string, unknown> = {},
+  ): Promise<void> {
+    const startedAt = performance.now()
+    try {
+      const info: SentMessageInfo = await this.transporter.sendMail(mail)
+      const elapsedMs = Math.round(performance.now() - startedAt)
+      logger.info(
+        {
+          email: mail.to,
+          ...extra,
+          elapsedMs,
+          messageId: info.messageId,
+          smtpResponse: info.response,
+        },
+        message,
+      )
+    } catch (err) {
+      const elapsedMs = Math.round(performance.now() - startedAt)
+      if (err instanceof Error) {
+        // Stamp the duration so the caller's error log carries it.
+        ;(err as Error & { elapsedMs?: number }).elapsedMs = elapsedMs
+      }
+      throw err
+    }
+  }
+
   async sendOtpCode(opts: {
     to: string
     code: string
@@ -125,16 +171,16 @@ export class EmailSender {
         trustedClients: this.trustedClients,
       })
       if (branded) {
-        await this.transporter.sendMail({
-          from: `"${branded.fromName}" <${this.config.from}>`,
-          to,
-          subject: branded.subject,
-          text: branded.text,
-          html: branded.html,
-        })
-        logger.info(
-          { email: to, clientId: opts.clientId },
+        await this.timedSendMail(
+          {
+            from: `"${branded.fromName}" <${this.config.from}>`,
+            to,
+            subject: branded.subject,
+            text: branded.text,
+            html: branded.html,
+          },
           'Sent client-branded OTP email',
+          { clientId: opts.clientId },
         )
         return
       }
@@ -158,14 +204,16 @@ export class EmailSender {
     const { to, ...rest } = opts
     const { subject, text, html } = buildSignInCodeEmail(rest)
 
-    await this.transporter.sendMail({
-      from: `"${this.config.fromName}" <${this.config.from}>`,
-      to,
-      subject,
-      text,
-      html,
-    })
-    logger.info({ email: to }, 'Sent sign-in OTP email')
+    await this.timedSendMail(
+      {
+        from: `"${this.config.fromName}" <${this.config.from}>`,
+        to,
+        subject,
+        text,
+        html,
+      },
+      'Sent sign-in OTP email',
+    )
   }
 
   private async sendWelcomeCode(opts: {
@@ -177,14 +225,16 @@ export class EmailSender {
     const { to, ...rest } = opts
     const { subject, text, html } = buildWelcomeCodeEmail(rest)
 
-    await this.transporter.sendMail({
-      from: `"${this.config.fromName}" <${this.config.from}>`,
-      to,
-      subject,
-      text,
-      html,
-    })
-    logger.info({ email: to }, 'Sent welcome OTP email')
+    await this.timedSendMail(
+      {
+        from: `"${this.config.fromName}" <${this.config.from}>`,
+        to,
+        subject,
+        text,
+        html,
+      },
+      'Sent welcome OTP email',
+    )
   }
 
   async sendBackupEmailVerification(opts: {
@@ -196,13 +246,15 @@ export class EmailSender {
     const { to, ...rest } = opts
     const { subject, text, html } = buildBackupEmailVerificationEmail(rest)
 
-    await this.transporter.sendMail({
-      from: `"${this.config.fromName}" <${this.config.from}>`,
-      to,
-      subject,
-      text,
-      html,
-    })
-    logger.info({ email: to }, 'Sent backup email verification')
+    await this.timedSendMail(
+      {
+        from: `"${this.config.fromName}" <${this.config.from}>`,
+        to,
+        subject,
+        text,
+        html,
+      },
+      'Sent backup email verification',
+    )
   }
 }
