From 45712157946a93067b21c8ca25206d9d71204807 Mon Sep 17 00:00:00 2001 From: Volnei Munhoz Date: Wed, 7 Jan 2026 08:27:40 -0300 Subject: [PATCH] feat(calendar-subscription): add telemetry metrics for cache performance and webhook calls (#26501) * feat(calendar-subscription): add telemetry metrics for cache performance and webhook calls - Add Sentry span telemetry to CalendarCacheWrapper.getAvailability() and getAvailabilityWithTimeZones() to measure: - Cache fetch duration (cacheFetchDurationMs) - Original calendar fetch duration (originalFetchDurationMs) - Number of calendars from cache vs original source - Number of events from each source - Whether cache was used (cacheUsed) - Add Sentry span telemetry to CalendarSubscriptionService.processWebhook() to track: - Provider (google_calendar, office365_calendar) - Success/failure status - Processing duration (durationMs) - Error messages on failure - Channel ID and selected calendar ID - Create telemetry module with types, sentry-span, and no-op-span implementations Co-Authored-By: Volnei Munhoz * refactor(calendar-subscription): move telemetry to @calcom/lib for reusability - Add withSpan helper to @calcom/lib/sentryWrapper for reusable telemetry - Update CalendarCacheWrapper to use withSpan from @calcom/lib - Update CalendarTelemetryWrapper to use withSpan from @calcom/lib - Update CalendarSubscriptionService to use withSpan from @calcom/lib - Remove old telemetry module from calendar-subscription feature - Add telemetry tracking when cache is disabled for performance comparison Co-Authored-By: Volnei Munhoz * fix(calendar-subscription): only apply telemetry wrapper when Sentry is configured - Fix unit test failures by checking if Sentry is configured before wrapping - Remove ESLint inline rules from getCalendar.ts Co-Authored-By: Volnei Munhoz * refactor(calendar-subscription): move CalendarTelemetryWrapper to telemetry directory - Move CalendarTelemetryWrapper from cache/ to telemetry/ directory - Update import path in getCalendar.ts Co-Authored-By: Volnei Munhoz * feat(telemetry): add console fallback when Sentry is not configured - Add console logging fallback in development mode when Sentry is not configured - Create isTelemetryEnabled() helper to check if telemetry should be enabled - Update getCalendar.ts to use isTelemetryEnabled() helper - Logs span name, operation, duration, and attributes to console via @calcom/lib/logger Co-Authored-By: Volnei Munhoz * refactor(calendar-subscription): wrap all calendars with CalendarTelemetryWrapper - CalendarTelemetryWrapper now wraps ALL cache-supported calendars with cacheEnabled parameter - CalendarCacheWrapper keeps cache-specific metrics with distinct op (calendar.cache.internal.*) - CalendarTelemetryWrapper uses canonical op (calendar.getAvailability) for consistent querying - Nested spans: outer telemetry wrapper measures end-to-end, inner cache wrapper measures cache internals Co-Authored-By: Volnei Munhoz --------- Co-authored-by: Devin AI <158243242+devin-ai-integration[bot]@users.noreply.github.com> --- packages/app-store/_utils/getCalendar.ts | 56 +++- .../lib/CalendarSubscriptionService.ts | 315 ++++++++++++++---- .../lib/cache/CalendarCacheWrapper.ts | 197 +++++++---- .../lib/telemetry/CalendarTelemetryWrapper.ts | 202 +++++++++++ packages/lib/sentryWrapper.ts | 130 +++++++- 5 files changed, 756 insertions(+), 144 deletions(-) create mode 100644 packages/features/calendar-subscription/lib/telemetry/CalendarTelemetryWrapper.ts diff --git a/packages/app-store/_utils/getCalendar.ts b/packages/app-store/_utils/getCalendar.ts index c705038cb1..8d2f68e5d4 100644 --- a/packages/app-store/_utils/getCalendar.ts +++ b/packages/app-store/_utils/getCalendar.ts @@ -2,8 +2,10 @@ import { CalendarSubscriptionService } from "@calcom/features/calendar-subscript import { CalendarCacheEventRepository } from "@calcom/features/calendar-subscription/lib/cache/CalendarCacheEventRepository"; import { CalendarCacheEventService } from "@calcom/features/calendar-subscription/lib/cache/CalendarCacheEventService"; import { CalendarCacheWrapper } from "@calcom/features/calendar-subscription/lib/cache/CalendarCacheWrapper"; +import { CalendarTelemetryWrapper } from "@calcom/features/calendar-subscription/lib/telemetry/CalendarTelemetryWrapper"; import { FeaturesRepository } from "@calcom/features/flags/features.repository"; import logger from "@calcom/lib/logger"; +import { isTelemetryEnabled } from "@calcom/lib/sentryWrapper"; import { prisma } from "@calcom/prisma"; import type { Calendar } from "@calcom/types/Calendar"; import type { CredentialForCalendarService } from "@calcom/types/Credential"; @@ -57,21 +59,47 @@ export const getCalendar = async ( ] ); shouldServeCache = isCalendarSubscriptionCacheEnabled && isCalendarSubscriptionCacheEnabledForUser; + log.debug("Cache feature flag check", { + credentialId: credential.id, + userId: credential.userId, + isCalendarSubscriptionCacheEnabled, + isCalendarSubscriptionCacheEnabledForUser, + shouldServeCache, + }); } - if (CalendarCacheEventService.isCalendarTypeSupported(calendarType) && shouldServeCache) { - log.info(`Calendar Cache is enabled, using CalendarCacheService for credential ${credential.id}`); - // eslint-disable-next-line @typescript-eslint/no-explicit-any - const originalCalendar = new CalendarService(credential as any); - if (originalCalendar) { - // return cacheable calendar - const calendarCacheEventRepository = new CalendarCacheEventRepository(prisma); - return new CalendarCacheWrapper({ - originalCalendar, - calendarCacheEventRepository, - }); - } + const isCacheSupported = CalendarCacheEventService.isCalendarTypeSupported(calendarType); + + const originalCalendar = new CalendarService(credential as any); + + // Determine if we should use cache + const useCache = isCacheSupported && shouldServeCache; + + // Build the calendar chain: original -> cache (if enabled) -> telemetry (if enabled) + let calendar: Calendar = originalCalendar; + + if (useCache) { + log.info(`Calendar Cache is enabled, using CalendarCacheWrapper for credential ${credential.id}`); + const calendarCacheEventRepository = new CalendarCacheEventRepository(prisma); + calendar = new CalendarCacheWrapper({ + originalCalendar: calendar, + calendarCacheEventRepository, + }); } - // eslint-disable-next-line @typescript-eslint/no-explicit-any - return new CalendarService(credential as any); + // Wrap ALL calendars with telemetry when telemetry is enabled + // This provides consistent metrics for all calendar types + if (isTelemetryEnabled()) { + log.info( + `Using CalendarTelemetryWrapper for credential ${credential.id} (cacheSupported: ${isCacheSupported}, cacheEnabled: ${useCache})` + ); + calendar = new CalendarTelemetryWrapper({ + originalCalendar: calendar, + calendarType, + cacheSupported: isCacheSupported, + cacheEnabled: useCache, + credentialId: credential.id, + }); + } + + return calendar; }; diff --git a/packages/features/calendar-subscription/lib/CalendarSubscriptionService.ts b/packages/features/calendar-subscription/lib/CalendarSubscriptionService.ts index 796bbcab89..a1854d5648 100644 --- a/packages/features/calendar-subscription/lib/CalendarSubscriptionService.ts +++ b/packages/features/calendar-subscription/lib/CalendarSubscriptionService.ts @@ -12,8 +12,10 @@ import type { CalendarSyncService } from "@calcom/features/calendar-subscription import type { FeaturesRepository } from "@calcom/features/flags/features.repository"; import type { ISelectedCalendarRepository } from "@calcom/features/selectedCalendar/repositories/SelectedCalendarRepository.interface"; import logger from "@calcom/lib/logger"; +import { withSpan } from "@calcom/lib/sentryWrapper"; import type { SelectedCalendar } from "@calcom/prisma/client"; +// biome-ignore lint/nursery/useExplicitType: logger type is inferred const log = logger.getSubLogger({ prefix: ["CalendarSubscriptionService"] }); export class CalendarSubscriptionService { @@ -110,23 +112,93 @@ export class CalendarSubscriptionService { /** * Process webhook */ + // biome-ignore lint/nursery/useExplicitType: return type is inferred from withSpan + // biome-ignore lint/complexity/noExcessiveLinesPerFunction: webhook processing requires multiple steps async processWebhook(provider: CalendarSubscriptionProvider, request: Request) { - log.debug("processWebhook", { provider }); - const calendarSubscriptionAdapter = this.deps.adapterFactory.get(provider); + return withSpan( + { + name: "CalendarSubscriptionService.processWebhook", + op: "calendar.subscription.webhook", + attributes: { + provider, + }, + }, + // biome-ignore lint/complexity/noExcessiveLinesPerFunction: webhook processing requires multiple steps + async (span) => { + const startTime = performance.now(); + log.debug("processWebhook", { provider }); - const isValid = await calendarSubscriptionAdapter.validate(request); - if (!isValid) throw new Error("Invalid webhook request"); + try { + const calendarSubscriptionAdapter = this.deps.adapterFactory.get(provider); - const channelId = await calendarSubscriptionAdapter.extractChannelId(request); - if (!channelId) throw new Error("Missing channel ID in webhook"); + const isValid = await calendarSubscriptionAdapter.validate(request); + if (!isValid) { + span.setAttribute("success", false); + span.setAttribute("errorMessage", "Invalid webhook request"); + throw new Error("Invalid webhook request"); + } - log.debug("Processing webhook", { channelId }); - const selectedCalendar = await this.deps.selectedCalendarRepository.findByChannelId(channelId); - // it maybe caused by an old subscription being triggered - if (!selectedCalendar) return null; + const channelId = await calendarSubscriptionAdapter.extractChannelId(request); + if (!channelId) { + span.setAttribute("success", false); + span.setAttribute("errorMessage", "Missing channel ID in webhook"); + throw new Error("Missing channel ID in webhook"); + } - // incremental event loading - await this.processEvents(selectedCalendar); + log.debug("Processing webhook", { channelId }); + span.setAttribute("channelId", channelId); + + const selectedCalendar = await this.deps.selectedCalendarRepository.findByChannelId(channelId); + // it maybe caused by an old subscription being triggered + if (!selectedCalendar) { + span.setAttribute("success", true); + span.setAttribute("skipped", true); + span.setAttribute("skipReason", "Calendar not found for channel"); + log.info("Webhook processed - calendar not found", { + provider, + channelId, + durationMs: performance.now() - startTime, + }); + return null; + } + + span.setAttribute("selectedCalendarId", selectedCalendar.id); + span.setAttribute("userId", selectedCalendar.userId); + + // incremental event loading + const eventsProcessed = await this.processEvents(selectedCalendar); + + const durationMs = performance.now() - startTime; + span.setAttribute("success", true); + span.setAttribute("durationMs", durationMs); + span.setAttribute("eventsProcessedCount", eventsProcessed.eventsFetched); + span.setAttribute("eventsCachedCount", eventsProcessed.eventsCached); + span.setAttribute("eventsSyncedCount", eventsProcessed.eventsSynced); + + log.info("Webhook processed successfully", { + provider, + channelId, + selectedCalendarId: selectedCalendar.id, + durationMs, + }); + } catch (error) { + const durationMs = performance.now() - startTime; + span.setAttribute("success", false); + span.setAttribute("durationMs", durationMs); + // biome-ignore lint/nursery/noTernary: simple error message extraction + span.setAttribute("errorMessage", error instanceof Error ? error.message : "Unknown error"); + + log.error("Webhook processing failed", { + provider, + durationMs, + // biome-ignore lint/nursery/noTernary: simple error message extraction + error: error instanceof Error ? error.message : "Unknown error", + }); + + throw error; + } + } + ); } /** @@ -136,73 +208,181 @@ export class CalendarSubscriptionService { * - update selected calendar * - update cache * - update sync + * @returns Object with counts of events fetched, cached, and synced, plus propagation lag metrics */ - async processEvents(selectedCalendar: SelectedCalendar): Promise { - const calendarSubscriptionAdapter = this.deps.adapterFactory.get( - selectedCalendar.integration as CalendarSubscriptionProvider + // biome-ignore lint/complexity/noExcessiveLinesPerFunction: event processing requires multiple steps + async processEvents( + selectedCalendar: SelectedCalendar + ): Promise<{ + eventsFetched: number; + eventsCached: number; + eventsSynced: number; + propagationLagMs?: { avg: number; max: number; min: number; count: number }; + }> { + return withSpan( + { + name: "CalendarSubscriptionService.processEvents", + op: "calendar.subscription.processEvents", + attributes: { + provider: selectedCalendar.integration, + selectedCalendarId: selectedCalendar.id, + userId: selectedCalendar.userId, + isIncremental: !!selectedCalendar.syncToken, + }, + }, + // biome-ignore lint/complexity/noExcessiveLinesPerFunction: event processing requires multiple steps + async (span) => { + const result: { + eventsFetched: number; + eventsCached: number; + eventsSynced: number; + propagationLagMs?: { avg: number; max: number; min: number; count: number }; + } = { eventsFetched: 0, eventsCached: 0, eventsSynced: 0 }; + + const calendarSubscriptionAdapter = this.deps.adapterFactory.get( + selectedCalendar.integration as CalendarSubscriptionProvider + ); + + if (!selectedCalendar.credentialId && !selectedCalendar.delegationCredentialId) { + log.debug("Selected Calendar doesn't have credentials", { selectedCalendarId: selectedCalendar.id }); + span.setAttribute("skipped", true); + span.setAttribute("skipReason", "No credentials"); + return result; + } + + // for cache the feature should be enabled globally and by user/team features + const [cacheEnabled, syncEnabled, cacheEnabledForUser] = await Promise.all([ + this.isCacheEnabled(), + this.isSyncEnabled(), + this.isCacheEnabledForUser(selectedCalendar.userId), + ]); + + if (!cacheEnabled && !syncEnabled) { + log.info("Cache and sync are globally disabled", { channelId: selectedCalendar.channelId }); + span.setAttribute("skipped", true); + span.setAttribute("skipReason", "Cache and sync disabled"); + return result; + } + + log.debug("Processing events", { channelId: selectedCalendar.channelId }); + const credential = await this.getCredential(selectedCalendar); + if (!credential) { + span.setAttribute("skipped", true); + span.setAttribute("skipReason", "No credential found"); + return result; + } + + let events: CalendarSubscriptionEvent | null = null; + try { + events = await calendarSubscriptionAdapter.fetchEvents(selectedCalendar, credential); + } catch (err) { + log.debug("Error fetching events", { channelId: selectedCalendar.channelId, err }); + await this.deps.selectedCalendarRepository.updateSyncStatus(selectedCalendar.id, { + syncErrorAt: new Date(), + syncErrorCount: { increment: 1 }, + }); + span.setAttribute("success", false); + // biome-ignore lint/nursery/noTernary: simple error message extraction + span.setAttribute("errorMessage", err instanceof Error ? err.message : "Unknown error"); + throw err; + } + + if (!events?.items?.length) { + log.debug("No events fetched", { channelId: selectedCalendar.channelId }); + span.setAttribute("eventsFetched", 0); + return result; + } + + result.eventsFetched = events.items.length; + span.setAttribute("eventsFetched", events.items.length); + + // Calculate propagation lag: time between event update in Google and now + // Only meaningful for incremental syncs (when syncToken exists) + const now = Date.now(); + const lagStats = this.calculatePropagationLag(events.items, now); + if (lagStats) { + result.propagationLagMs = lagStats; + span.setAttribute("propagationLagAvgMs", lagStats.avg); + span.setAttribute("propagationLagMaxMs", lagStats.max); + span.setAttribute("propagationLagMinMs", lagStats.min); + span.setAttribute("propagationLagEventCount", lagStats.count); + log.info("Propagation lag calculated", { + channelId: selectedCalendar.channelId, + avgMs: lagStats.avg, + maxMs: lagStats.max, + minMs: lagStats.min, + eventCount: lagStats.count, + }); + } + + log.debug("Processing events", { channelId: selectedCalendar.channelId, count: events.items.length }); + await this.deps.selectedCalendarRepository.updateSyncStatus(selectedCalendar.id, { + syncToken: events.syncToken || selectedCalendar.syncToken, + syncedAt: new Date(), + syncErrorAt: null, + syncErrorCount: 0, + }); + + // it requires both global and team/user feature cache enabled + if (cacheEnabled && cacheEnabledForUser) { + log.debug("Caching events", { count: events.items.length }); + await this.deps.calendarCacheEventService.handleEvents(selectedCalendar, events.items); + result.eventsCached = events.items.length; + span.setAttribute("eventsCached", events.items.length); + } + + if (syncEnabled) { + log.debug("Syncing events", { count: events.items.length }); + await this.deps.calendarSyncService.handleEvents(selectedCalendar, events.items); + result.eventsSynced = events.items.length; + span.setAttribute("eventsSynced", events.items.length); + } + + span.setAttribute("success", true); + return result; + } ); + } - if (!selectedCalendar.credentialId && !selectedCalendar.delegationCredentialId) { - log.debug("Selected Calendar doesn't have credentials", { selectedCalendarId: selectedCalendar.id }); - return; + /** + * Calculate propagation lag statistics from event timestamps + * Uses updatedAt or createdAt to determine when the event was last modified in the provider + */ + private calculatePropagationLag( + items: CalendarSubscriptionEvent["items"], + now: number + ): { avg: number; max: number; min: number; count: number } | null { + const lags: number[] = []; + + for (const item of items) { + // Use updatedAt if available, otherwise fall back to createdAt + const eventTimestamp = item.updatedAt ?? item.createdAt; + if (eventTimestamp) { + const lagMs = now - eventTimestamp.getTime(); + // Only count positive lags (ignore clock skew / future timestamps) + if (lagMs >= 0) { + lags.push(lagMs); + } + } } - // for cache the feature should be enabled globally and by user/team features - const [cacheEnabled, syncEnabled, cacheEnabledForUser] = await Promise.all([ - this.isCacheEnabled(), - this.isSyncEnabled(), - this.isCacheEnabledForUser(selectedCalendar.userId), - ]); - - if (!cacheEnabled && !syncEnabled) { - log.info("Cache and sync are globally disabled", { channelId: selectedCalendar.channelId }); - return; + if (lags.length === 0) { + return null; } - log.debug("Processing events", { channelId: selectedCalendar.channelId }); - const credential = await this.getCredential(selectedCalendar); - if (!credential) return; - - let events: CalendarSubscriptionEvent | null = null; - try { - events = await calendarSubscriptionAdapter.fetchEvents(selectedCalendar, credential); - } catch (err) { - log.debug("Error fetching events", { channelId: selectedCalendar.channelId, err }); - await this.deps.selectedCalendarRepository.updateSyncStatus(selectedCalendar.id, { - syncErrorAt: new Date(), - syncErrorCount: { increment: 1 }, - }); - throw err; - } - - if (!events?.items?.length) { - log.debug("No events fetched", { channelId: selectedCalendar.channelId }); - return; - } - - log.debug("Processing events", { channelId: selectedCalendar.channelId, count: events.items.length }); - await this.deps.selectedCalendarRepository.updateSyncStatus(selectedCalendar.id, { - syncToken: events.syncToken || selectedCalendar.syncToken, - syncedAt: new Date(), - syncErrorAt: null, - syncErrorCount: 0, - }); - - // it requires both global and team/user feature cache enabled - if (cacheEnabled && cacheEnabledForUser) { - log.debug("Caching events", { count: events.items.length }); - await this.deps.calendarCacheEventService.handleEvents(selectedCalendar, events.items); - } - - if (syncEnabled) { - log.debug("Syncing events", { count: events.items.length }); - await this.deps.calendarSyncService.handleEvents(selectedCalendar, events.items); - } + const sum = lags.reduce((a, b) => a + b, 0); + return { + avg: Math.round(sum / lags.length), + max: Math.max(...lags), + min: Math.min(...lags), + count: lags.length, + }; } /** * Subscribe periodically to new calendars */ + // biome-ignore lint/nursery/useExplicitType: return type is void async checkForNewSubscriptions() { const teamIds = await this.deps.featuresRepository.getTeamsWithFeatureEnabled( CalendarSubscriptionService.CALENDAR_SUBSCRIPTION_CACHE_FEATURE @@ -260,6 +440,7 @@ export class CalendarSubscriptionService { if (!credential) return null; return { ...credential, + // biome-ignore lint/nursery/noTernary: conditional delegation credential mapping delegatedTo: credential.delegatedTo?.serviceAccountKey?.client_email ? { serviceAccountKey: { diff --git a/packages/features/calendar-subscription/lib/cache/CalendarCacheWrapper.ts b/packages/features/calendar-subscription/lib/cache/CalendarCacheWrapper.ts index 0c4afee116..e9991edaf3 100644 --- a/packages/features/calendar-subscription/lib/cache/CalendarCacheWrapper.ts +++ b/packages/features/calendar-subscription/lib/cache/CalendarCacheWrapper.ts @@ -1,5 +1,6 @@ import type { ICalendarCacheEventRepository } from "@calcom/features/calendar-subscription/lib/cache/CalendarCacheEventRepository.interface"; import logger from "@calcom/lib/logger"; +import { withSpan } from "@calcom/lib/sentryWrapper"; import type { Calendar, CalendarEvent, @@ -66,38 +67,74 @@ export class CalendarCacheWrapper implements Calendar { dateTo: string, selectedCalendars: IntegrationCalendar[] ): Promise { - log.debug("getAvailability (mixed cache + original)", { - dateFrom, - dateTo, - calendarIds: selectedCalendars.map((c) => c.id), - calendarCount: selectedCalendars.length, - }); + return withSpan( + { + name: "CalendarCacheWrapper.getAvailability", + op: "calendar.cache.internal.getAvailability", + attributes: { + calendarCount: selectedCalendars?.length ?? 0, + }, + }, + async (span) => { + log.debug("getAvailability (mixed cache + original)", { + dateFrom, + dateTo, + calendarIds: selectedCalendars.map((c) => c.id), + calendarCount: selectedCalendars.length, + }); - if (!selectedCalendars?.length) return []; + if (!selectedCalendars?.length) return []; - const withSync = selectedCalendars.filter((c) => c.syncToken && c.syncSubscribedAt); - const withoutSync = selectedCalendars.filter((c) => !c.syncToken || !c.syncSubscribedAt); + const withSync = selectedCalendars.filter((c) => c.syncToken && c.syncSubscribedAt); + const withoutSync = selectedCalendars.filter((c) => !c.syncToken || !c.syncSubscribedAt); - const results: EventBusyDate[] = []; + const results: EventBusyDate[] = []; - // Fetch from cache for synced calendars - if (withSync.length) { - const ids = withSync.map((c) => c.id).filter((id): id is string => Boolean(id)); - const cached = await this.deps.calendarCacheEventRepository.findAllBySelectedCalendarIdsBetween( - ids, - new Date(dateFrom), - new Date(dateTo) - ); - results.push(...cached); - } + // Fetch from cache for synced calendars + if (withSync.length) { + const cacheStartTime = performance.now(); + const ids = withSync.map((c) => c.id).filter((id): id is string => Boolean(id)); + const cached = await this.deps.calendarCacheEventRepository.findAllBySelectedCalendarIdsBetween( + ids, + new Date(dateFrom), + new Date(dateTo) + ); + const cacheDurationMs = performance.now() - cacheStartTime; + results.push(...cached); - // Fetch from original calendar for unsynced ones - if (withoutSync.length) { - const original = await this.deps.originalCalendar.getAvailability(dateFrom, dateTo, withoutSync); - results.push(...original); - } + span.setAttribute("cachedCalendarCount", withSync.length); + span.setAttribute("cacheFetchDurationMs", cacheDurationMs); + span.setAttribute("cachedEventsCount", cached.length); + log.info("Calendar cache fetch completed", { + cachedCalendarCount: withSync.length, + cacheFetchDurationMs: cacheDurationMs, + cachedEventsCount: cached.length, + }); + } - return results; + // Fetch from original calendar for unsynced ones + if (withoutSync.length) { + const originalStartTime = performance.now(); + const original = await this.deps.originalCalendar.getAvailability(dateFrom, dateTo, withoutSync); + const originalDurationMs = performance.now() - originalStartTime; + results.push(...original); + + span.setAttribute("originalCalendarCount", withoutSync.length); + span.setAttribute("originalFetchDurationMs", originalDurationMs); + span.setAttribute("originalEventsCount", original.length); + log.info("Original calendar fetch completed", { + originalCalendarCount: withoutSync.length, + originalFetchDurationMs: originalDurationMs, + originalEventsCount: original.length, + }); + } + + span.setAttribute("cacheUsed", withSync.length > 0); + span.setAttribute("totalEventsCount", results.length); + + return results; + } + ); } /** @@ -117,48 +154,84 @@ export class CalendarCacheWrapper implements Calendar { dateTo: string, selectedCalendars: IntegrationCalendar[] ): Promise<{ start: Date | string; end: Date | string; timeZone: string }[]> { - log.debug("getAvailabilityWithTimeZones (mixed cache + original)", { - dateFrom, - dateTo, - calendarIds: selectedCalendars.map((c) => c.id), - calendarCount: selectedCalendars.length, - }); + return withSpan( + { + name: "CalendarCacheWrapper.getAvailabilityWithTimeZones", + op: "calendar.cache.internal.getAvailabilityWithTimeZones", + attributes: { + calendarCount: selectedCalendars?.length ?? 0, + }, + }, + async (span) => { + log.debug("getAvailabilityWithTimeZones (mixed cache + original)", { + dateFrom, + dateTo, + calendarIds: selectedCalendars.map((c) => c.id), + calendarCount: selectedCalendars.length, + }); - if (!selectedCalendars?.length) return []; + if (!selectedCalendars?.length) return []; - const withSync = selectedCalendars.filter((c) => c.syncToken && c.syncSubscribedAt); - const withoutSync = selectedCalendars.filter((c) => !c.syncToken || !c.syncSubscribedAt); + const withSync = selectedCalendars.filter((c) => c.syncToken && c.syncSubscribedAt); + const withoutSync = selectedCalendars.filter((c) => !c.syncToken || !c.syncSubscribedAt); - const results: { start: Date | string; end: Date | string; timeZone: string }[] = []; + const results: { start: Date | string; end: Date | string; timeZone: string }[] = []; - // Fetch from cache for synced calendars - if (withSync.length) { - const ids = withSync.map((c) => c.id).filter((id): id is string => Boolean(id)); - const cached = await this.deps.calendarCacheEventRepository.findAllBySelectedCalendarIdsBetween( - ids, - new Date(dateFrom), - new Date(dateTo) - ); - results.push( - ...cached.map(({ start, end, timeZone }) => ({ - start, - end, - timeZone: timeZone || "UTC", - })) - ); - } + // Fetch from cache for synced calendars + if (withSync.length) { + const cacheStartTime = performance.now(); + const ids = withSync.map((c) => c.id).filter((id): id is string => Boolean(id)); + const cached = await this.deps.calendarCacheEventRepository.findAllBySelectedCalendarIdsBetween( + ids, + new Date(dateFrom), + new Date(dateTo) + ); + const cacheDurationMs = performance.now() - cacheStartTime; + results.push( + ...cached.map(({ start, end, timeZone }) => ({ + start, + end, + timeZone: timeZone || "UTC", + })) + ); - // Fetch from original calendar for unsynced ones - if (withoutSync.length) { - const original = await this.deps.originalCalendar.getAvailabilityWithTimeZones?.( - dateFrom, - dateTo, - withoutSync - ); - if (original?.length) results.push(...original); - } + span.setAttribute("cachedCalendarCount", withSync.length); + span.setAttribute("cacheFetchDurationMs", cacheDurationMs); + span.setAttribute("cachedEventsCount", cached.length); + log.info("Calendar cache fetch with timezones completed", { + cachedCalendarCount: withSync.length, + cacheFetchDurationMs: cacheDurationMs, + cachedEventsCount: cached.length, + }); + } - return results; + // Fetch from original calendar for unsynced ones + if (withoutSync.length) { + const originalStartTime = performance.now(); + const original = await this.deps.originalCalendar.getAvailabilityWithTimeZones?.( + dateFrom, + dateTo, + withoutSync + ); + const originalDurationMs = performance.now() - originalStartTime; + if (original?.length) results.push(...original); + + span.setAttribute("originalCalendarCount", withoutSync.length); + span.setAttribute("originalFetchDurationMs", originalDurationMs); + span.setAttribute("originalEventsCount", original?.length ?? 0); + log.info("Original calendar fetch with timezones completed", { + originalCalendarCount: withoutSync.length, + originalFetchDurationMs: originalDurationMs, + originalEventsCount: original?.length ?? 0, + }); + } + + span.setAttribute("cacheUsed", withSync.length > 0); + span.setAttribute("totalEventsCount", results.length); + + return results; + } + ); } fetchAvailabilityAndSetCache?(selectedCalendars: IntegrationCalendar[]): Promise { diff --git a/packages/features/calendar-subscription/lib/telemetry/CalendarTelemetryWrapper.ts b/packages/features/calendar-subscription/lib/telemetry/CalendarTelemetryWrapper.ts new file mode 100644 index 0000000000..deb6c7b618 --- /dev/null +++ b/packages/features/calendar-subscription/lib/telemetry/CalendarTelemetryWrapper.ts @@ -0,0 +1,202 @@ +import logger from "@calcom/lib/logger"; +import { withSpan } from "@calcom/lib/sentryWrapper"; +import type { + Calendar, + CalendarEvent, + CalendarServiceEvent, + EventBusyDate, + IntegrationCalendar, + NewCalendarEventType, + SelectedCalendarEventTypeIds, +} from "@calcom/types/Calendar"; + +const log = logger.getSubLogger({ prefix: ["CalendarTelemetryWrapper"] }); + +/** + * A wrapper to add telemetry to all calendar services. + * This provides consistent metrics for comparing performance between cached and non-cached calendar loading. + * + * @see Calendar + */ +export class CalendarTelemetryWrapper implements Calendar { + constructor( + private deps: { + originalCalendar: Calendar; + calendarType: string; + cacheSupported: boolean; + cacheEnabled: boolean; + credentialId: number; + } + ) {} + + getCredentialId?(): number { + return this.deps.originalCalendar.getCredentialId ? this.deps.originalCalendar.getCredentialId() : -1; + } + + createEvent( + event: CalendarServiceEvent, + credentialId: number, + externalCalendarId?: string + ): Promise { + return this.deps.originalCalendar.createEvent(event, credentialId, externalCalendarId); + } + + updateEvent( + uid: string, + event: CalendarServiceEvent, + externalCalendarId?: string | null + ): Promise { + return this.deps.originalCalendar.updateEvent(uid, event, externalCalendarId); + } + + deleteEvent(uid: string, event: CalendarEvent, externalCalendarId?: string | null): Promise { + return this.deps.originalCalendar.deleteEvent(uid, event, externalCalendarId); + } + + /** + * Retrieves availability with telemetry tracking when cache is disabled. + * + * @param dateFrom - Start date (ISO string) + * @param dateTo - End date (ISO string) + * @param selectedCalendars - List of calendars to retrieve availability from + * @returns Array of busy date ranges + */ + async getAvailability( + dateFrom: string, + dateTo: string, + selectedCalendars: IntegrationCalendar[] + ): Promise { + return withSpan( + { + name: "CalendarTelemetryWrapper.getAvailability", + op: "calendar.getAvailability", + attributes: { + credentialId: this.deps.credentialId, + calendarCount: selectedCalendars?.length ?? 0, + calendarType: this.deps.calendarType, + cacheSupported: this.deps.cacheSupported, + cacheEnabled: this.deps.cacheEnabled, + }, + }, + async (span) => { + log.debug("getAvailability", { + dateFrom, + dateTo, + calendarCount: selectedCalendars.length, + cacheSupported: this.deps.cacheSupported, + cacheEnabled: this.deps.cacheEnabled, + }); + + if (!selectedCalendars?.length) return []; + + const startTime = performance.now(); + const results = await this.deps.originalCalendar.getAvailability(dateFrom, dateTo, selectedCalendars); + const totalFetchDurationMs = performance.now() - startTime; + + span.setAttribute("totalFetchDurationMs", totalFetchDurationMs); + span.setAttribute("totalEventsCount", results.length); + + log.info("Calendar fetch completed", { + calendarCount: selectedCalendars.length, + totalFetchDurationMs, + totalEventsCount: results.length, + cacheSupported: this.deps.cacheSupported, + cacheEnabled: this.deps.cacheEnabled, + }); + + return results; + } + ); + } + + /** + * Retrieves availability with time zones and telemetry tracking when cache is disabled. + * + * @param dateFrom - Start date (ISO string) + * @param dateTo - End date (ISO string) + * @param selectedCalendars - List of calendars to retrieve availability from + * @returns Array of time-zone-aware availability ranges + */ + async getAvailabilityWithTimeZones( + dateFrom: string, + dateTo: string, + selectedCalendars: IntegrationCalendar[] + ): Promise<{ start: Date | string; end: Date | string; timeZone: string }[]> { + // Check if the original calendar supports this method + if (!this.deps.originalCalendar.getAvailabilityWithTimeZones) { + return []; + } + + return withSpan( + { + name: "CalendarTelemetryWrapper.getAvailabilityWithTimeZones", + op: "calendar.getAvailabilityWithTimeZones", + attributes: { + credentialId: this.deps.credentialId, + calendarCount: selectedCalendars?.length ?? 0, + calendarType: this.deps.calendarType, + cacheSupported: this.deps.cacheSupported, + cacheEnabled: this.deps.cacheEnabled, + }, + }, + async (span) => { + log.debug("getAvailabilityWithTimeZones", { + dateFrom, + dateTo, + calendarCount: selectedCalendars.length, + cacheSupported: this.deps.cacheSupported, + cacheEnabled: this.deps.cacheEnabled, + }); + + if (!selectedCalendars?.length) return []; + + const startTime = performance.now(); + const results = await this.deps.originalCalendar.getAvailabilityWithTimeZones?.( + dateFrom, + dateTo, + selectedCalendars + ); + const totalFetchDurationMs = performance.now() - startTime; + + span.setAttribute("totalFetchDurationMs", totalFetchDurationMs); + span.setAttribute("totalEventsCount", results?.length ?? 0); + + log.info("Calendar fetch with timezones completed", { + calendarCount: selectedCalendars.length, + totalFetchDurationMs, + totalEventsCount: results?.length ?? 0, + cacheSupported: this.deps.cacheSupported, + cacheEnabled: this.deps.cacheEnabled, + }); + + return results ?? []; + } + ); + } + + fetchAvailabilityAndSetCache?(selectedCalendars: IntegrationCalendar[]): Promise { + return this.deps.originalCalendar.fetchAvailabilityAndSetCache?.(selectedCalendars) || Promise.resolve(); + } + + listCalendars(event?: CalendarEvent): Promise { + return this.deps.originalCalendar.listCalendars(event); + } + + testDelegationCredentialSetup?(): Promise { + return this.deps.originalCalendar.testDelegationCredentialSetup?.() || Promise.resolve(false); + } + + watchCalendar?(options: { + calendarId: string; + eventTypeIds: SelectedCalendarEventTypeIds; + }): Promise { + return this.deps.originalCalendar.watchCalendar?.(options) || Promise.resolve(); + } + + unwatchCalendar?(options: { + calendarId: string; + eventTypeIds: SelectedCalendarEventTypeIds; + }): Promise { + return this.deps.originalCalendar.unwatchCalendar?.(options) || Promise.resolve(); + } +} diff --git a/packages/lib/sentryWrapper.ts b/packages/lib/sentryWrapper.ts index 1c2b0eef37..8cb3afaa32 100644 --- a/packages/lib/sentryWrapper.ts +++ b/packages/lib/sentryWrapper.ts @@ -1,7 +1,10 @@ -import { startSpan, captureException } from "@sentry/nextjs"; +import { captureException, startSpan } from "@sentry/nextjs"; +import logger from "./logger"; import { redactSensitiveData } from "./redactSensitiveData"; +const log = logger.getSubLogger({ prefix: ["Telemetry"] }); + /* WHEN TO USE We ran a script that performs a simple mathematical calculation within a loop of 1000000 iterations. @@ -104,6 +107,131 @@ function createErrorHandler(name: string, args: unknown[]) { * // sync implementation * }, "mySyncFunction"); */ +/** + * Minimal interface for setting span attributes during execution. + * Compatible with Sentry's Span interface. + */ +export interface TelemetrySpan { + setAttribute(key: string, value: string | number | boolean): void; +} + +/** + * Options for creating a telemetry span. + */ +export interface TelemetrySpanOptions { + /** Name of the span (required) */ + name: string; + /** Operation type for categorization in Sentry (e.g., "calendar.cache.getAvailability") */ + op?: string; + /** Initial attributes to set on the span */ + attributes?: Record; +} + +/** + * No-op span implementation for when telemetry is completely disabled. + */ +const noOpSpan: TelemetrySpan = { + setAttribute: () => {}, +}; + +/** + * Creates a console-logging span for local development when Sentry is not configured. + * Tracks attributes and logs them with duration when the span completes. + */ +function createConsoleSpan( + options: TelemetrySpanOptions +): { span: TelemetrySpan; logCompletion: (durationMs: number, error?: unknown) => void } { + const attributes: Record = { ...options.attributes }; + + const span: TelemetrySpan = { + setAttribute: (key, value) => { + attributes[key] = value; + }, + }; + + const logCompletion = (durationMs: number, error?: unknown) => { + const redactedAttributes = redactSensitiveData(attributes); + const status = error ? "error" : "ok"; + log.debug( + `[${options.op || options.name}] ${options.name} completed in ${durationMs}ms (${status})`, + redactedAttributes as Record + ); + }; + + return { span, logCompletion }; +} + +/** + * Check if telemetry should be enabled (either Sentry or console fallback in development). + */ +export function isTelemetryEnabled(): boolean { + const hasSentry = Boolean(process.env.NEXT_PUBLIC_SENTRY_DSN && process.env.SENTRY_TRACES_SAMPLE_RATE); + const isDevelopment = process.env.NODE_ENV === "development"; + return hasSentry || isDevelopment; +} + +/** + * Wraps an async function with a Sentry span for telemetry tracking. + * Supports custom span attributes and operation types for better categorization in Sentry. + * Falls back to console logging in development mode when Sentry is not configured. + * + * @example + * const result = await withSpan( + * { + * name: "CalendarCacheWrapper.getAvailability", + * op: "calendar.cache.getAvailability", + * attributes: { calendarCount: 5, cacheEnabled: true } + * }, + * async (span) => { + * // Your async code here + * span.setAttribute("eventsCount", results.length); + * return results; + * } + * ); + */ +export async function withSpan( + options: TelemetrySpanOptions, + callback: (span: TelemetrySpan) => Promise +): Promise { + const hasSentry = Boolean(process.env.NEXT_PUBLIC_SENTRY_DSN && process.env.SENTRY_TRACES_SAMPLE_RATE); + const isDevelopment = process.env.NODE_ENV === "development"; + + // Use Sentry if configured + if (hasSentry) { + return startSpan( + { + name: options.name, + op: options.op, + attributes: options.attributes, + }, + async (span) => { + const telemetrySpan: TelemetrySpan = { + setAttribute: (key, value) => span.setAttribute(key, value), + }; + return callback(telemetrySpan); + } + ); + } + + // Fall back to console logging in development mode + if (isDevelopment) { + const startTime = Date.now(); + const { span, logCompletion } = createConsoleSpan(options); + + try { + const result = await callback(span); + logCompletion(Date.now() - startTime); + return result; + } catch (error) { + logCompletion(Date.now() - startTime, error); + throw error; + } + } + + // No-op in production without Sentry (e.g., CI/tests) + return callback(noOpSpan); +} + export function withReporting(func: (...args: T) => R, name: string): (...args: T) => R { if (!name?.trim()) { throw new Error("withReporting requires a non-empty name parameter");