From 3ca74568858fd93fb3011521e368eaadefadfeb9 Mon Sep 17 00:00:00 2001 From: Hariom Balhara Date: Mon, 2 Oct 2023 16:21:04 +0530 Subject: [PATCH] test: Booking flow App failure and ics file tests and improved logging (#11646) --- .../utils/bookingScenario/bookingScenario.ts | 64 +++--- .../web/test/utils/bookingScenario/expects.ts | 100 ++++++++- package.json | 1 + packages/app-store/_utils/getCalendar.ts | 2 +- packages/core/CalendarManager.ts | 13 +- packages/core/EventManager.ts | 17 +- packages/core/getCalendarsEvents.ts | 21 +- packages/core/videoClient.ts | 18 +- .../emails/src/components/LocationInfo.tsx | 2 - .../bookings/lib/handleNewBooking.test.ts | 204 ++++++++---------- .../features/bookings/lib/handleNewBooking.ts | 112 ++++++---- .../bookings/lib/isEventTypeLoggingEnabled.ts | 27 +++ packages/lib/piiFreeData.ts | 56 ++++- packages/lib/sync/SyncServiceManager.ts | 19 +- packages/lib/testEmails.ts | 4 + .../trpc/server/routers/viewer/slots/util.ts | 30 +-- yarn.lock | 62 +++++- 17 files changed, 513 insertions(+), 239 deletions(-) create mode 100644 packages/features/bookings/lib/isEventTypeLoggingEnabled.ts diff --git a/apps/web/test/utils/bookingScenario/bookingScenario.ts b/apps/web/test/utils/bookingScenario/bookingScenario.ts index 9aebffa764..3989b0159c 100644 --- a/apps/web/test/utils/bookingScenario/bookingScenario.ts +++ b/apps/web/test/utils/bookingScenario/bookingScenario.ts @@ -12,6 +12,7 @@ import { appStoreMetadata } from "@calcom/app-store/appStoreMetaData"; import { handleStripePaymentSuccess } from "@calcom/features/ee/payments/api/webhook"; import type { HttpError } from "@calcom/lib/http-error"; import logger from "@calcom/lib/logger"; +import { safeStringify } from "@calcom/lib/safeStringify"; import type { SchedulingType } from "@calcom/prisma/enums"; import type { BookingStatus } from "@calcom/prisma/enums"; import type { NewCalendarEventType } from "@calcom/types/Calendar"; @@ -19,6 +20,8 @@ import type { EventBusyDate } from "@calcom/types/Calendar"; import { getMockPaymentService } from "./MockPaymentService"; +logger.setSettings({ minLevel: "silly" }); +const log = logger.getChildLogger({ prefix: ["[bookingScenario]"] }); type App = { slug: string; dirName: string; @@ -123,7 +126,6 @@ const Timezones = { "+5:30": "Asia/Kolkata", "+6:00": "Asia/Dhaka", }; -logger.setSettings({ minLevel: "silly" }); async function addEventTypesToDb( eventTypes: (Omit & { @@ -135,11 +137,11 @@ async function addEventTypesToDb( destinationCalendar?: any; })[] ) { - logger.silly("TestData: Add EventTypes to DB", JSON.stringify(eventTypes)); + log.silly("TestData: Add EventTypes to DB", JSON.stringify(eventTypes)); await prismock.eventType.createMany({ data: eventTypes, }); - logger.silly( + log.silly( "TestData: All EventTypes in DB are", JSON.stringify({ eventTypes: await prismock.eventType.findMany({ @@ -197,7 +199,7 @@ async function addEventTypes(eventTypes: InputEventType[], usersStore: InputUser : eventType.destinationCalendar, }; }); - logger.silly("TestData: Creating EventType", JSON.stringify(eventTypesWithUsers)); + log.silly("TestData: Creating EventType", JSON.stringify(eventTypesWithUsers)); await addEventTypesToDb(eventTypesWithUsers); } @@ -216,7 +218,7 @@ async function addBookingsToDb( await prismock.booking.createMany({ data: bookings, }); - logger.silly( + log.silly( "TestData: Booking as in DB", JSON.stringify({ bookings: await prismock.booking.findMany({ @@ -229,7 +231,7 @@ async function addBookingsToDb( } async function addBookings(bookings: InputBooking[]) { - logger.silly("TestData: Creating Bookings", JSON.stringify(bookings)); + log.silly("TestData: Creating Bookings", JSON.stringify(bookings)); const allBookings = [...bookings].map((booking) => { if (booking.references) { addBookingReferencesToDB( @@ -277,19 +279,22 @@ async function addWebhooksToDb(webhooks: any[]) { } async function addWebhooks(webhooks: InputWebhook[]) { - logger.silly("TestData: Creating Webhooks", webhooks); + log.silly("TestData: Creating Webhooks", safeStringify(webhooks)); await addWebhooksToDb(webhooks); } async function addUsersToDb(users: (Prisma.UserCreateInput & { schedules: Prisma.ScheduleCreateInput[] })[]) { - logger.silly("TestData: Creating Users", JSON.stringify(users)); + log.silly("TestData: Creating Users", JSON.stringify(users)); await prismock.user.createMany({ data: users, }); - logger.silly("Added users to Db", { - allUsers: await prismock.user.findMany(), - }); + log.silly( + "Added users to Db", + safeStringify({ + allUsers: await prismock.user.findMany(), + }) + ); } async function addUsers(users: InputUser[]) { @@ -339,7 +344,7 @@ async function addUsers(users: InputUser[]) { } export async function createBookingScenario(data: ScenarioData) { - logger.silly("TestData: Creating Scenario", JSON.stringify({ data })); + log.silly("TestData: Creating Scenario", JSON.stringify({ data })); await addUsers(data.users); const eventType = await addEventTypes(data.eventTypes, data.users); @@ -690,6 +695,7 @@ export function enableEmailFeature() { } export function mockNoTranslations() { + log.silly("Mocking i18n.getTranslation to return identity function"); // @ts-expect-error FIXME i18nMock.getTranslation.mockImplementation(() => { return new Promise((resolve) => { @@ -707,10 +713,14 @@ export function mockCalendar( metadataLookupKey: keyof typeof appStoreMetadata, calendarData?: { create?: { + id?: string; uid?: string; + iCalUID?: string; }; update?: { + id?: string; uid: string; + iCalUID?: string; }; busySlots?: { start: `${string}Z`; end: `${string}Z` }[]; creationCrash?: boolean; @@ -727,7 +737,7 @@ export function mockCalendar( uid: "UPDATED_MOCK_ID", }, }; - logger.silly(`Mocking ${appStoreLookupKey} on appStoreMock`); + log.silly(`Mocking ${appStoreLookupKey} on appStoreMock`); // eslint-disable-next-line @typescript-eslint/no-explicit-any const createEventCalls: any[] = []; // eslint-disable-next-line @typescript-eslint/no-explicit-any @@ -745,13 +755,15 @@ export function mockCalendar( throw new Error("MockCalendarService.createEvent fake error"); } const [calEvent, credentialId] = rest; - logger.silly("mockCalendar.createEvent", JSON.stringify({ calEvent, credentialId })); + log.silly("mockCalendar.createEvent", JSON.stringify({ calEvent, credentialId })); createEventCalls.push(rest); return Promise.resolve({ type: app.type, additionalInfo: {}, uid: "PROBABLY_UNUSED_UID", - id: normalizedCalendarData.create?.uid || "FALLBACK_MOCK_ID", + // A Calendar is always expected to return an id. + id: normalizedCalendarData.create?.id || "FALLBACK_MOCK_CALENDAR_EVENT_ID", + iCalUID: normalizedCalendarData.create?.iCalUID, // Password and URL seems useless for CalendarService, plan to remove them if that's the case password: "MOCK_PASSWORD", url: "https://UNUSED_URL", @@ -763,13 +775,15 @@ export function mockCalendar( throw new Error("MockCalendarService.updateEvent fake error"); } const [uid, event, externalCalendarId] = rest; - logger.silly("mockCalendar.updateEvent", JSON.stringify({ uid, event, externalCalendarId })); + log.silly("mockCalendar.updateEvent", JSON.stringify({ uid, event, externalCalendarId })); // eslint-disable-next-line prefer-rest-params updateEventCalls.push(rest); return Promise.resolve({ type: app.type, additionalInfo: {}, uid: "PROBABLY_UNUSED_UID", + iCalUID: normalizedCalendarData.update?.iCalUID, + // eslint-disable-next-line @typescript-eslint/no-non-null-assertion id: normalizedCalendarData.update?.uid || "FALLBACK_MOCK_ID", // Password and URL seems useless for CalendarService, plan to remove them if that's the case @@ -797,14 +811,7 @@ export function mockCalendar( export function mockCalendarToHaveNoBusySlots( metadataLookupKey: keyof typeof appStoreMetadata, - calendarData?: { - create: { - uid?: string; - }; - update?: { - uid: string; - }; - } + calendarData?: Parameters[1] ) { calendarData = calendarData || { create: { @@ -848,10 +855,7 @@ export function mockVideoApp({ password: "MOCK_PASS", url: `http://mock-${metadataLookupKey}.example.com`, }; - logger.silly( - "mockSuccessfulVideoMeetingCreation", - JSON.stringify({ metadataLookupKey, appStoreLookupKey }) - ); + log.silly("mockSuccessfulVideoMeetingCreation", JSON.stringify({ metadataLookupKey, appStoreLookupKey })); const createMeetingCalls: any[] = []; const updateMeetingCalls: any[] = []; // eslint-disable-next-line @typescript-eslint/ban-ts-comment @@ -888,7 +892,7 @@ export function mockVideoApp({ if (!calEvent.organizer) { throw new Error("calEvent.organizer is not defined"); } - logger.silly( + log.silly( "mockSuccessfulVideoMeetingCreation.updateMeeting", JSON.stringify({ bookingRef, calEvent }) ); @@ -1019,7 +1023,7 @@ export async function mockPaymentSuccessWebhookFromStripe({ externalId }: { exte try { await handleStripePaymentSuccess(getMockedStripePaymentEvent({ paymentIntentId: externalId })); } catch (e) { - logger.silly("mockPaymentSuccessWebhookFromStripe:catch", JSON.stringify(e)); + log.silly("mockPaymentSuccessWebhookFromStripe:catch", JSON.stringify(e)); webhookResponse = e as HttpError; } diff --git a/apps/web/test/utils/bookingScenario/expects.ts b/apps/web/test/utils/bookingScenario/expects.ts index 550b07b5c6..e988017b9b 100644 --- a/apps/web/test/utils/bookingScenario/expects.ts +++ b/apps/web/test/utils/bookingScenario/expects.ts @@ -1,10 +1,12 @@ import prismaMock from "../../../../../tests/libs/__mocks__/prisma"; import type { WebhookTriggerEvents, Booking, BookingReference } from "@prisma/client"; +import ical from "node-ical"; import { expect } from "vitest"; import "vitest-fetch-mock"; import logger from "@calcom/lib/logger"; +import { safeStringify } from "@calcom/lib/safeStringify"; import { BookingStatus } from "@calcom/prisma/enums"; import type { CalendarEvent } from "@calcom/types/Calendar"; import type { Fixtures } from "@calcom/web/test/fixtures/fixtures"; @@ -15,7 +17,19 @@ declare global { // eslint-disable-next-line @typescript-eslint/no-namespace namespace jest { interface Matchers { - toHaveEmail(expectedEmail: { htmlToContain?: string; to: string }, to: string): R; + toHaveEmail( + expectedEmail: { + //TODO: Support email HTML parsing to target specific elements + htmlToContain?: string; + to: string; + noIcs?: true; + ics?: { + filename: string; + iCalUID: string; + }; + }, + to: string + ): R; } } } @@ -27,11 +41,18 @@ expect.extend({ //TODO: Support email HTML parsing to target specific elements htmlToContain?: string; to: string; + ics: { + filename: string; + iCalUID: string; + }; + noIcs: true; }, to: string ) { const testEmail = emails.get().find((email) => email.to.includes(to)); - const emailsToLog = emails.get().map((email) => ({ to: email.to, html: email.html })); + const emailsToLog = emails + .get() + .map((email) => ({ to: email.to, html: email.html, ics: email.icalEvent })); if (!testEmail) { logger.silly("All Emails", JSON.stringify({ numEmails: emailsToLog.length, emailsToLog })); return { @@ -39,11 +60,20 @@ expect.extend({ message: () => `No email sent to ${to}`, }; } + const ics = testEmail.icalEvent; + const icsObject = ics?.content ? ical.sync.parseICS(ics?.content) : null; + let isHtmlContained = true; let isToAddressExpected = true; + const isIcsFilenameExpected = expectedEmail.ics ? ics?.filename === expectedEmail.ics.filename : true; + const isIcsUIDExpected = expectedEmail.ics + ? !!(icsObject ? icsObject[expectedEmail.ics.iCalUID] : null) + : true; + if (expectedEmail.htmlToContain) { isHtmlContained = testEmail.html.includes(expectedEmail.htmlToContain); } + isToAddressExpected = expectedEmail.to === testEmail.to; if (!isHtmlContained || !isToAddressExpected) { @@ -51,12 +81,29 @@ expect.extend({ } return { - pass: isHtmlContained && isToAddressExpected, + pass: + isHtmlContained && + isToAddressExpected && + (expectedEmail.noIcs ? true : isIcsFilenameExpected && isIcsUIDExpected), message: () => { if (!isHtmlContained) { return `Email HTML is not as expected. Expected:"${expectedEmail.htmlToContain}" isn't contained in "${testEmail.html}"`; } - return `Email To address is not as expected. Expected:${expectedEmail.to} isn't equal to ${testEmail.to}`; + + if (!isToAddressExpected) { + return `Email To address is not as expected. Expected:${expectedEmail.to} isn't equal to ${testEmail.to}`; + } + + if (!isIcsFilenameExpected) { + return `ICS Filename is not as expected. Expected:${expectedEmail.ics.filename} isn't equal to ${ics?.filename}`; + } + + if (!isIcsUIDExpected) { + return `ICS UID is not as expected. Expected:${ + expectedEmail.ics.iCalUID + } isn't present in ${JSON.stringify(icsObject)}`; + } + throw new Error("Unknown error"); }, }; }, @@ -73,7 +120,7 @@ export function expectWebhookToHaveBeenCalledWith( const webhooksToSubscriberUrl = fetchCalls.filter((call) => { return call[0] === subscriberUrl; }); - logger.silly("Scanning fetchCalls for webhook", fetchCalls); + logger.silly("Scanning fetchCalls for webhook", safeStringify(fetchCalls)); const webhookFetchCall = webhooksToSubscriberUrl.find((call) => { const body = call[1]?.body; const parsedBody = JSON.parse((body as string) || "{}"); @@ -135,15 +182,21 @@ export function expectSuccessfulBookingCreationEmails({ emails, organizer, booker, + iCalUID, }: { emails: Fixtures["emails"]; organizer: { email: string; name: string }; booker: { email: string; name: string }; + iCalUID: string; }) { expect(emails).toHaveEmail( { htmlToContain: "confirmed_event_type_subject", to: `${organizer.email}`, + ics: { + filename: "event.ics", + iCalUID: iCalUID, + }, }, `${organizer.email}` ); @@ -152,6 +205,10 @@ export function expectSuccessfulBookingCreationEmails({ { htmlToContain: "confirmed_event_type_subject", to: `${booker.name} <${booker.email}>`, + ics: { + filename: "event.ics", + iCalUID: iCalUID, + }, }, `${booker.name} <${booker.email}>` ); @@ -160,17 +217,20 @@ export function expectSuccessfulBookingCreationEmails({ export function expectBrokenIntegrationEmails({ emails, organizer, - booker, }: { emails: Fixtures["emails"]; organizer: { email: string; name: string }; - booker: { email: string; name: string }; }) { // Broken Integration email is only sent to the Organizer expect(emails).toHaveEmail( { htmlToContain: "broken_integration", to: `${organizer.email}`, + // No ics goes in case of broken integration email it seems + // ics: { + // filename: "event.ics", + // iCalUID: iCalUID, + // }, }, `${organizer.email}` ); @@ -188,15 +248,21 @@ export function expectCalendarEventCreationFailureEmails({ emails, organizer, booker, + iCalUID, }: { emails: Fixtures["emails"]; organizer: { email: string; name: string }; booker: { email: string; name: string }; + iCalUID: string; }) { expect(emails).toHaveEmail( { htmlToContain: "broken_integration", to: `${organizer.email}`, + ics: { + filename: "event.ics", + iCalUID, + }, }, `${organizer.email}` ); @@ -205,6 +271,10 @@ export function expectCalendarEventCreationFailureEmails({ { htmlToContain: "calendar_event_creation_failure_subject", to: `${booker.name} <${booker.email}>`, + ics: { + filename: "event.ics", + iCalUID, + }, }, `${booker.name} <${booker.email}>` ); @@ -214,15 +284,21 @@ export function expectSuccessfulBookingRescheduledEmails({ emails, organizer, booker, + iCalUID, }: { emails: Fixtures["emails"]; organizer: { email: string; name: string }; booker: { email: string; name: string }; + iCalUID: string; }) { expect(emails).toHaveEmail( { htmlToContain: "event_type_has_been_rescheduled_on_time_date", to: `${organizer.email}`, + ics: { + filename: "event.ics", + iCalUID, + }, }, `${organizer.email}` ); @@ -231,6 +307,10 @@ export function expectSuccessfulBookingRescheduledEmails({ { htmlToContain: "event_type_has_been_rescheduled_on_time_date", to: `${booker.name} <${booker.email}>`, + ics: { + filename: "event.ics", + iCalUID, + }, }, `${booker.name} <${booker.email}>` ); @@ -247,6 +327,7 @@ export function expectAwaitingPaymentEmails({ { htmlToContain: "awaiting_payment_subject", to: `${booker.name} <${booker.email}>`, + noIcs: true, }, `${booker.email}` ); @@ -265,6 +346,7 @@ export function expectBookingRequestedEmails({ { htmlToContain: "event_awaiting_approval_subject", to: `${organizer.email}`, + noIcs: true, }, `${organizer.email}` ); @@ -273,6 +355,7 @@ export function expectBookingRequestedEmails({ { htmlToContain: "booking_submitted_subject", to: `${booker.email}`, + noIcs: true, }, `${booker.email}` ); @@ -346,7 +429,7 @@ export function expectBookingCreatedWebhookToHaveBeenFired({ subscriberUrl: string; location: string; paidEvent?: boolean; - videoCallUrl?: string; + videoCallUrl?: string | null; }) { if (!paidEvent) { expectWebhookToHaveBeenCalledWith(subscriberUrl, { @@ -545,6 +628,7 @@ export function expectSuccessfulVideoMeetingUpdationInCalendar( expect(calendarEvent).toEqual(expect.objectContaining(expected.calEvent)); } +// eslint-disable-next-line @typescript-eslint/no-explicit-any export async function expectBookingInDBToBeRescheduledFromTo({ from, to }: { from: any; to: any }) { // Expect previous booking to be cancelled await expectBookingToBeInDatabase({ diff --git a/package.json b/package.json index 74de710939..effb13590d 100644 --- a/package.json +++ b/package.json @@ -87,6 +87,7 @@ "jsdom": "^22.0.0", "lint-staged": "^12.5.0", "mailhog": "^4.16.0", + "node-ical": "^0.16.1", "prettier": "^2.8.6", "prismock": "^1.21.1", "tsc-absolute": "^1.0.0", diff --git a/packages/app-store/_utils/getCalendar.ts b/packages/app-store/_utils/getCalendar.ts index dd864929be..2524fe5ba6 100644 --- a/packages/app-store/_utils/getCalendar.ts +++ b/packages/app-store/_utils/getCalendar.ts @@ -42,7 +42,7 @@ export const getCalendar = async (credential: CredentialPayload | null): Promise log.warn(`calendar of type ${calendarType} is not implemented`); return null; } - log.info("calendarApp", calendarApp.lib.CalendarService); + log.info("Got calendarApp", calendarApp.lib.CalendarService); const CalendarService = calendarApp.lib.CalendarService; return new CalendarService(credential); }; diff --git a/packages/core/CalendarManager.ts b/packages/core/CalendarManager.ts index 094e0f7750..4f35fb83f0 100644 --- a/packages/core/CalendarManager.ts +++ b/packages/core/CalendarManager.ts @@ -256,7 +256,10 @@ export const createEvent = async ( if (error?.calError) { calError = error.calError; } - log.error("createEvent failed", JSON.stringify(error), calEvent); + log.error( + "createEvent failed", + safeStringify({ error, calEvent: getPiiFreeCalendarEvent(calEvent) }) + ); // @TODO: This code will be off till we can investigate an error with it //https://github.com/calcom/cal.com/issues/3949 // await sendBrokenIntegrationEmail(calEvent, "calendar"); @@ -266,7 +269,13 @@ export const createEvent = async ( if (!creationResult) { logger.silly("createEvent failed", { success, uid, creationResult, originalEvent: calEvent, calError }); } - + log.debug( + "Created calendar event", + JSON.stringify({ + calEvent: getPiiFreeCalendarEvent(calEvent), + creationResult, + }) + ); return { appName: credential.appId || "", type: credential.type, diff --git a/packages/core/EventManager.ts b/packages/core/EventManager.ts index 39215f5800..57394dc024 100644 --- a/packages/core/EventManager.ts +++ b/packages/core/EventManager.ts @@ -10,6 +10,7 @@ import { appKeysSchema as calVideoKeysSchema } from "@calcom/app-store/dailyvide import { getEventLocationTypeFromApp, MeetLocationType } from "@calcom/app-store/locations"; import getApps from "@calcom/app-store/utils"; import logger from "@calcom/lib/logger"; +import { getPiiFreeUser } from "@calcom/lib/piiFreeData"; import { safeStringify } from "@calcom/lib/safeStringify"; import prisma from "@calcom/prisma"; import { credentialForCalendarServiceSelect } from "@calcom/prisma/selects/credential"; @@ -27,6 +28,7 @@ import type { import { createEvent, updateEvent } from "./CalendarManager"; import { createMeeting, updateMeeting } from "./videoClient"; +const log = logger.getChildLogger({ prefix: ["EventManager"] }); export const isDedicatedIntegration = (location: string): boolean => { return location !== MeetLocationType && location.includes("integrations:"); }; @@ -81,7 +83,7 @@ export default class EventManager { * @param user */ constructor(user: EventManagerUser) { - logger.silly("Initializing EventManager", JSON.stringify({ user })); + log.silly("Initializing EventManager", safeStringify({ user: getPiiFreeUser(user) })); const appCredentials = getApps(user.credentials, true).flatMap((app) => app.credentials.map((creds) => ({ ...creds, appName: app.name })) ); @@ -124,6 +126,7 @@ export default class EventManager { const [mainHostDestinationCalendar] = (evt.destinationCalendar as [undefined | NonNullable[number]]) ?? []; if (evt.location === MeetLocationType && mainHostDestinationCalendar?.integration !== "google_calendar") { + log.warn("Falling back to Cal Video integration as Google Calendar not installed"); evt["location"] = "integrations:daily"; } const isDedicated = evt.location ? isDedicatedIntegration(evt.location) : null; @@ -362,7 +365,7 @@ export default class EventManager { [] as DestinationCalendar[] ); for (const destination of destinationCalendars) { - logger.silly("Creating Calendar event", JSON.stringify({ destination })); + log.silly("Creating Calendar event", JSON.stringify({ destination })); if (destination.credentialId) { let credential = this.calendarCredentials.find((c) => c.id === destination.credentialId); if (!credential) { @@ -402,7 +405,7 @@ export default class EventManager { } } } else { - logger.silly( + log.silly( "No destination Calendar found, falling back to first connected calendar", safeStringify({ calendarCredentials: this.calendarCredentials, @@ -416,7 +419,7 @@ export default class EventManager { const [credential] = this.calendarCredentials.filter((cred) => !cred.type.endsWith("other_calendar")); if (credential) { const createdEvent = await createEvent(credential, event); - logger.silly("Created Calendar event", { createdEvent }); + log.silly("Created Calendar event", safeStringify({ createdEvent })); if (createdEvent) { createdEvents.push(createdEvent); } @@ -465,7 +468,7 @@ export default class EventManager { * @todo remove location from event types that has missing credentials * */ if (!videoCredential) { - logger.warn( + log.warn( 'Falling back to "daily" video integration for event with location: ' + event.location + " because credential is missing for the app" @@ -513,7 +516,7 @@ export default class EventManager { ): Promise>> { let calendarReference: PartialReference[] | undefined = undefined, credential; - logger.silly("updateAllCalendarEvents", JSON.stringify({ event, booking, newBookingId })); + log.silly("updateAllCalendarEvents", JSON.stringify({ event, booking, newBookingId })); try { // If a newBookingId is given, update that calendar event let newBooking; @@ -575,7 +578,7 @@ export default class EventManager { (credential) => credential.type === reference?.type ); for (const credential of credentials) { - logger.silly("updateAllCalendarEvents-credential", JSON.stringify({ credentials })); + log.silly("updateAllCalendarEvents-credential", JSON.stringify({ credentials })); result.push(updateEvent(credential, event, bookingRefUid, calenderExternalId)); } } diff --git a/packages/core/getCalendarsEvents.ts b/packages/core/getCalendarsEvents.ts index 27b371e5e4..6cf85100cc 100644 --- a/packages/core/getCalendarsEvents.ts +++ b/packages/core/getCalendarsEvents.ts @@ -3,6 +3,7 @@ import type { SelectedCalendar } from "@prisma/client"; import { getCalendar } from "@calcom/app-store/_utils/getCalendar"; import logger from "@calcom/lib/logger"; import { getPiiFreeCredential, getPiiFreeSelectedCalendar } from "@calcom/lib/piiFreeData"; +import { safeStringify } from "@calcom/lib/safeStringify"; import { performance } from "@calcom/lib/server/perfObserver"; import type { EventBusyDate } from "@calcom/types/Calendar"; import type { CredentialPayload } from "@calcom/types/Credential"; @@ -35,6 +36,13 @@ const getCalendarsEvents = async ( const selectedCalendarIds = passedSelectedCalendars.map((sc) => sc.externalId); /** If we don't then we actually fetch external calendars (which can be very slow) */ performance.mark("eventBusyDatesStart"); + log.debug( + `Getting availability for`, + safeStringify({ + calendarService: c.constructor.name, + selectedCalendars: passedSelectedCalendars.map(getPiiFreeSelectedCalendar), + }) + ); const eventBusyDates = await c.getAvailability(dateFrom, dateTo, passedSelectedCalendars); performance.mark("eventBusyDatesEnd"); performance.measure( @@ -52,11 +60,14 @@ const getCalendarsEvents = async ( "getBusyCalendarTimesStart", "getBusyCalendarTimesEnd" ); - log.debug({ - calendarCredentials: calendarCredentials.map(getPiiFreeCredential), - selectedCalendars: selectedCalendars.map(getPiiFreeSelectedCalendar), - calendarEvents: awaitedResults, - }); + log.debug( + "Result", + safeStringify({ + calendarCredentials: calendarCredentials.map(getPiiFreeCredential), + selectedCalendars: selectedCalendars.map(getPiiFreeSelectedCalendar), + calendarEvents: awaitedResults, + }) + ); return awaitedResults; }; diff --git a/packages/core/videoClient.ts b/packages/core/videoClient.ts index 52b9194f71..6d7be5535e 100644 --- a/packages/core/videoClient.ts +++ b/packages/core/videoClient.ts @@ -6,7 +6,7 @@ import { getDailyAppKeys } from "@calcom/app-store/dailyvideo/lib/getDailyAppKey import { sendBrokenIntegrationEmail } from "@calcom/emails"; import { getUid } from "@calcom/lib/CalEventParser"; import logger from "@calcom/lib/logger"; -import { getPiiFreeCalendarEvent } from "@calcom/lib/piiFreeData"; +import { getPiiFreeCalendarEvent, getPiiFreeCredential } from "@calcom/lib/piiFreeData"; import { safeStringify } from "@calcom/lib/safeStringify"; import { prisma } from "@calcom/prisma"; import type { GetRecordingsResponseSchema } from "@calcom/prisma/zod-utils"; @@ -25,7 +25,7 @@ const getVideoAdapters = async (withCredentials: CredentialPayload[]): Promise const createMeeting = async (credential: CredentialPayload, calEvent: CalendarEvent) => { const uid: string = getUid(calEvent); - log.silly("videoClient:createMeeting", JSON.stringify({ credential, uid, calEvent })); + log.silly( + "createMeeting", + safeStringify({ + credential: getPiiFreeCredential(credential), + uid, + calEvent: getPiiFreeCalendarEvent(calEvent), + }) + ); if (!credential || !credential.appId) { throw new Error( "Credentials must be set! Video platforms are optional, so this method shouldn't even be called when no video credentials are set." @@ -159,7 +166,10 @@ const updateMeeting = async ( const deleteMeeting = async (credential: CredentialPayload | null, uid: string): Promise => { if (credential) { const videoAdapter = (await getVideoAdapters([credential]))[0]; - logger.debug("videoAdapter inside deleteMeeting", { credential, uid }); + log.debug( + "Calling deleteMeeting for", + safeStringify({ credential: getPiiFreeCredential(credential), uid }) + ); // There are certain video apps with no video adapter defined. e.g. riverby,whereby if (videoAdapter) { return videoAdapter.deleteMeeting(uid); diff --git a/packages/emails/src/components/LocationInfo.tsx b/packages/emails/src/components/LocationInfo.tsx index 2388ce432e..efbde3d190 100644 --- a/packages/emails/src/components/LocationInfo.tsx +++ b/packages/emails/src/components/LocationInfo.tsx @@ -2,7 +2,6 @@ import type { TFunction } from "next-i18next"; import { guessEventLocationType } from "@calcom/app-store/locations"; import { getVideoCallUrlFromCalEvent } from "@calcom/lib/CalEventParser"; -import logger from "@calcom/lib/logger"; import type { CalendarEvent } from "@calcom/types/Calendar"; import { Info } from "./Info"; @@ -12,7 +11,6 @@ export function LocationInfo(props: { calEvent: CalendarEvent; t: TFunction }) { // We would not be able to determine provider name for DefaultEventLocationTypes const providerName = guessEventLocationType(props.calEvent.location)?.label; - logger.debug(`LocationInfo: ${JSON.stringify(props.calEvent)} ${providerName}`); const location = props.calEvent.location; let meetingUrl = location?.search(/^https?:/) !== -1 ? location : undefined; diff --git a/packages/features/bookings/lib/handleNewBooking.test.ts b/packages/features/bookings/lib/handleNewBooking.test.ts index c497246b77..9299fb01e6 100644 --- a/packages/features/bookings/lib/handleNewBooking.test.ts +++ b/packages/features/bookings/lib/handleNewBooking.test.ts @@ -147,7 +147,8 @@ describe("handleNewBooking", () => { const calendarMock = mockCalendarToHaveNoBusySlots("googlecalendar", { create: { - uid: "MOCK_ID", + id: "MOCKED_GOOGLE_CALENDAR_EVENT_ID", + iCalUID: "MOCKED_GOOGLE_CALENDAR_ICS_ID", }, }); @@ -193,8 +194,8 @@ describe("handleNewBooking", () => { }, { type: "google_calendar", - uid: "MOCK_ID", - meetingId: "MOCK_ID", + uid: "MOCKED_GOOGLE_CALENDAR_EVENT_ID", + meetingId: "MOCKED_GOOGLE_CALENDAR_EVENT_ID", meetingPassword: "MOCK_PASSWORD", meetingUrl: "https://UNUSED_URL", }, @@ -207,7 +208,13 @@ describe("handleNewBooking", () => { videoCallUrl: "http://mock-dailyvideo.example.com/meeting-1", }); - expectSuccessfulBookingCreationEmails({ booker, organizer, emails }); + expectSuccessfulBookingCreationEmails({ + booker, + organizer, + emails, + iCalUID: "MOCKED_GOOGLE_CALENDAR_ICS_ID", + }); + expectBookingCreatedWebhookToHaveBeenFired({ booker, organizer, @@ -281,9 +288,12 @@ describe("handleNewBooking", () => { }, }); + // Mock a Scenario where iCalUID isn't returned by Google Calendar in which case booking UID is used as the ics UID const calendarMock = mockCalendarToHaveNoBusySlots("googlecalendar", { create: { + id: "GOOGLE_CALENDAR_EVENT_ID", uid: "MOCK_ID", + iCalUID: "MOCKED_GOOGLE_CALENDAR_ICS_ID", }, }); @@ -329,8 +339,8 @@ describe("handleNewBooking", () => { }, { type: "google_calendar", - uid: "MOCK_ID", - meetingId: "MOCK_ID", + uid: "GOOGLE_CALENDAR_EVENT_ID", + meetingId: "GOOGLE_CALENDAR_EVENT_ID", meetingPassword: "MOCK_PASSWORD", meetingUrl: "https://UNUSED_URL", }, @@ -346,7 +356,12 @@ describe("handleNewBooking", () => { calendarId: null, }); - expectSuccessfulBookingCreationEmails({ booker, organizer, emails }); + expectSuccessfulBookingCreationEmails({ + booker, + organizer, + emails, + iCalUID: "MOCKED_GOOGLE_CALENDAR_ICS_ID", + }); expectBookingCreatedWebhookToHaveBeenFired({ booker, organizer, @@ -425,6 +440,8 @@ describe("handleNewBooking", () => { const calendarMock = mockCalendarToHaveNoBusySlots("googlecalendar", { create: { uid: "MOCK_ID", + id: "GOOGLE_CALENDAR_EVENT_ID", + iCalUID: "MOCKED_GOOGLE_CALENDAR_ICS_ID", }, }); @@ -470,8 +487,8 @@ describe("handleNewBooking", () => { }, { type: "google_calendar", - uid: "MOCK_ID", - meetingId: "MOCK_ID", + uid: "GOOGLE_CALENDAR_EVENT_ID", + meetingId: "GOOGLE_CALENDAR_EVENT_ID", meetingPassword: "MOCK_PASSWORD", meetingUrl: "https://UNUSED_URL", }, @@ -484,7 +501,13 @@ describe("handleNewBooking", () => { videoCallUrl: "http://mock-dailyvideo.example.com/meeting-1", }); - expectSuccessfulBookingCreationEmails({ booker, organizer, emails }); + expectSuccessfulBookingCreationEmails({ + booker, + organizer, + emails, + iCalUID: "MOCKED_GOOGLE_CALENDAR_ICS_ID", + }); + expectBookingCreatedWebhookToHaveBeenFired({ booker, organizer, @@ -498,7 +521,7 @@ describe("handleNewBooking", () => { test( `an error in creating a calendar event should not stop the booking creation - Current behaviour is wrong as the booking is created but no-one is notified of it`, - async ({ emails }) => { + async ({}) => { const handleNewBooking = (await import("@calcom/features/bookings/lib/handleNewBooking")).default; const booker = getBooker({ email: "booker@example.com", @@ -546,7 +569,7 @@ describe("handleNewBooking", () => { }) ); - const calendarMock = mockCalendarToCrashOnCreateEvent("googlecalendar"); + const _calendarMock = mockCalendarToCrashOnCreateEvent("googlecalendar"); const mockBookingData = getMockRequestDataForBooking({ data: { @@ -672,9 +695,15 @@ describe("handleNewBooking", () => { }, }), }); - await handleNewBooking(req); + const createdBooking = await handleNewBooking(req); - expectSuccessfulBookingCreationEmails({ booker, organizer, emails }); + expectSuccessfulBookingCreationEmails({ + booker, + organizer, + emails, + // Because no calendar was involved, we don't have an ics UID + iCalUID: createdBooking.uid, + }); expectBookingCreatedWebhookToHaveBeenFired({ booker, @@ -893,95 +922,10 @@ describe("handleNewBooking", () => { }) ); - const calendarMock = mockCalendar("googlecalendar", { - create: { - uid: "MOCK_ID", - }, - busySlots: [ - { - start: `${plus1DateString}T05:00:00.000Z`, - end: `${plus1DateString}T05:15:00.000Z`, - }, - ], - }); - - const mockBookingData = getMockRequestDataForBooking({ - data: { - start: `${getDate({ dateIncrement: 1 }).dateString}T04:00:00.000Z`, - end: `${getDate({ dateIncrement: 1 }).dateString}T05:30:00.000Z`, - eventTypeId: 1, - responses: { - email: booker.email, - name: booker.name, - location: { optionValue: "", value: "New York" }, - }, - }, - }); - - const { req } = createMockNextJsRequest({ - method: "POST", - body: mockBookingData, - }); - - await expect(async () => await handleNewBooking(req)).rejects.toThrowError( - "No available users found" - ); - }, - timeout - ); - - test( - `should fail a booking if there is already a booking in the organizer's selectedCalendars(Single Calendar) with the overlapping time`, - async () => { - const handleNewBooking = (await import("@calcom/features/bookings/lib/handleNewBooking")).default; - const organizerId = 101; - const booker = getBooker({ - email: "booker@example.com", - name: "Booker", - }); - - const organizer = getOrganizer({ - name: "Organizer", - email: "organizer@example.com", - id: organizerId, - schedules: [TestData.schedules.IstWorkHours], - credentials: [getGoogleCalendarCredential()], - selectedCalendars: [TestData.selectedCalendars.google], - }); - const { dateString: plus1DateString } = getDate({ dateIncrement: 1 }); - - await createBookingScenario( - getScenarioData({ - webhooks: [ - { - userId: organizer.id, - eventTriggers: ["BOOKING_CREATED"], - subscriberUrl: "http://my-webhook.example.com", - active: true, - eventTypeId: 1, - appId: null, - }, - ], - eventTypes: [ - { - id: 1, - slotInterval: 45, - length: 45, - users: [ - { - id: 101, - }, - ], - }, - ], - organizer, - apps: [TestData.apps["google-calendar"]], - }) - ); - - const calendarMock = mockCalendar("googlecalendar", { + const _calendarMock = mockCalendar("googlecalendar", { create: { uid: "MOCK_ID", + iCalUID: "MOCKED_GOOGLE_CALENDAR_ICS_ID", }, busySlots: [ { @@ -1075,7 +1019,11 @@ describe("handleNewBooking", () => { metadataLookupKey: "dailyvideo", }); - mockCalendarToHaveNoBusySlots("googlecalendar"); + mockCalendarToHaveNoBusySlots("googlecalendar", { + create: { + iCalUID: "MOCKED_GOOGLE_CALENDAR_ICS_ID", + }, + }); const mockBookingData = getMockRequestDataForBooking({ data: { @@ -1193,7 +1141,11 @@ describe("handleNewBooking", () => { metadataLookupKey: "dailyvideo", }); - mockCalendarToHaveNoBusySlots("googlecalendar"); + mockCalendarToHaveNoBusySlots("googlecalendar", { + create: { + iCalUID: "MOCKED_GOOGLE_CALENDAR_ICS_ID", + }, + }); const mockBookingData = getMockRequestDataForBooking({ data: { @@ -1231,7 +1183,12 @@ describe("handleNewBooking", () => { expectWorkflowToBeTriggered(); - expectSuccessfulBookingCreationEmails({ booker, organizer, emails }); + expectSuccessfulBookingCreationEmails({ + booker, + organizer, + emails, + iCalUID: "MOCKED_GOOGLE_CALENDAR_ICS_ID", + }); expectBookingCreatedWebhookToHaveBeenFired({ booker, @@ -1306,7 +1263,11 @@ describe("handleNewBooking", () => { metadataLookupKey: "dailyvideo", }); - mockCalendarToHaveNoBusySlots("googlecalendar"); + mockCalendarToHaveNoBusySlots("googlecalendar", { + create: { + iCalUID: "MOCKED_GOOGLE_CALENDAR_ICS_ID", + }, + }); const mockBookingData = getMockRequestDataForBooking({ data: { @@ -1489,7 +1450,11 @@ describe("handleNewBooking", () => { apps: [TestData.apps["google-calendar"], TestData.apps["daily-video"]], }); - mockCalendarToHaveNoBusySlots("googlecalendar"); + mockCalendarToHaveNoBusySlots("googlecalendar", { + create: { + iCalUID: "MOCKED_GOOGLE_CALENDAR_ICS_ID", + }, + }); await createBookingScenario(scenarioData); const createdBooking = await handleNewBooking(req); @@ -1512,7 +1477,12 @@ describe("handleNewBooking", () => { expectWorkflowToBeTriggered(); - expectSuccessfulBookingCreationEmails({ booker, organizer, emails }); + expectSuccessfulBookingCreationEmails({ + booker, + organizer, + emails, + iCalUID: "MOCKED_GOOGLE_CALENDAR_ICS_ID", + }); expectBookingCreatedWebhookToHaveBeenFired({ booker, organizer, @@ -1918,6 +1888,7 @@ describe("handleNewBooking", () => { }, update: { uid: "UPDATED_MOCK_ID", + iCalUID: "MOCKED_GOOGLE_CALENDAR_ICS_ID", }, }); @@ -2027,7 +1998,12 @@ describe("handleNewBooking", () => { uid: "MOCK_ID", }); - expectSuccessfulBookingRescheduledEmails({ booker, organizer, emails }); + expectSuccessfulBookingRescheduledEmails({ + booker, + organizer, + emails, + iCalUID: "MOCKED_GOOGLE_CALENDAR_ICS_ID", + }); expectBookingRescheduledWebhookToHaveBeenFired({ booker, organizer, @@ -2132,6 +2108,7 @@ describe("handleNewBooking", () => { uid: "MOCK_ID", }, update: { + iCalUID: "MOCKED_GOOGLE_CALENDAR_ICS_ID", uid: "UPDATED_MOCK_ID", }, }); @@ -2223,7 +2200,12 @@ describe("handleNewBooking", () => { uid: "MOCK_ID", }); - expectSuccessfulBookingRescheduledEmails({ booker, organizer, emails }); + expectSuccessfulBookingRescheduledEmails({ + booker, + organizer, + emails, + iCalUID: "MOCKED_GOOGLE_CALENDAR_ICS_ID", + }); expectBookingRescheduledWebhookToHaveBeenFired({ booker, organizer, @@ -2237,7 +2219,7 @@ describe("handleNewBooking", () => { test( `an error in updating a calendar event should not stop the rescheduling - Current behaviour is wrong as the booking is resheduled but no-one is notified of it`, - async ({ emails }) => { + async ({}) => { const handleNewBooking = (await import("@calcom/features/bookings/lib/handleNewBooking")).default; const booker = getBooker({ email: "booker@example.com", @@ -2315,7 +2297,7 @@ describe("handleNewBooking", () => { }) ); - const calendarMock = mockCalendarToCrashOnUpdateEvent("googlecalendar"); + const _calendarMock = mockCalendarToCrashOnUpdateEvent("googlecalendar"); const mockBookingData = getMockRequestDataForBooking({ data: { diff --git a/packages/features/bookings/lib/handleNewBooking.ts b/packages/features/bookings/lib/handleNewBooking.ts index b7c413c987..997da0e8a4 100644 --- a/packages/features/bookings/lib/handleNewBooking.ts +++ b/packages/features/bookings/lib/handleNewBooking.ts @@ -35,6 +35,7 @@ import { import { getBookingFieldsWithSystemFields } from "@calcom/features/bookings/lib/getBookingFields"; import { getCalEventResponses } from "@calcom/features/bookings/lib/getCalEventResponses"; import { handleWebhookTrigger } from "@calcom/features/bookings/lib/handleWebhookTrigger"; +import { isEventTypeLoggingEnabled } from "@calcom/features/bookings/lib/isEventTypeLoggingEnabled"; import { userOrgQuery } from "@calcom/features/ee/organizations/lib/orgDomains"; import { allowDisablingAttendeeConfirmationEmails, @@ -60,6 +61,7 @@ import { HttpError } from "@calcom/lib/http-error"; import isOutOfBounds, { BookingDateInPastError } from "@calcom/lib/isOutOfBounds"; import logger from "@calcom/lib/logger"; import { handlePayment } from "@calcom/lib/payment/handlePayment"; +import { getPiiFreeCalendarEvent, getPiiFreeEventType, getPiiFreeUser } from "@calcom/lib/piiFreeData"; import { safeStringify } from "@calcom/lib/safeStringify"; import { checkBookingLimits, checkDurationLimits, getLuckyUser } from "@calcom/lib/server"; import { getBookerUrl } from "@calcom/lib/server/getBookerUrl"; @@ -688,25 +690,14 @@ async function handler( prefix: ["book:user", `${eventTypeId}:${reqBody.user}/${eventTypeSlug}`], }); - if (isLoggingEnabled({ eventTypeId, usernameOrTeamName: reqBody.user })) { + if (isEventTypeLoggingEnabled({ eventTypeId, usernameOrTeamName: reqBody.user })) { logger.setSettings({ minLevel: "silly" }); } - loggerWithEventDetails.debug( - "handleNewBooking called", - JSON.stringify({ - eventTypeId, - eventTypeSlug, - startTime: reqBody.start, - endTime: reqBody.end, - rescheduleUid: reqBody.rescheduleUid, - }) - ); - const fullName = getFullName(bookerName); const tGuests = await getTranslation("en", "common"); - loggerWithEventDetails.debug(`Booking eventType ${eventTypeId} started`); + const dynamicUserList = Array.isArray(reqBody.user) ? reqBody.user : getUsernameList(reqBody.user); if (!eventType) throw new HttpError({ statusCode: 404, message: "eventType.notFound" }); @@ -714,6 +705,30 @@ async function handler( !!eventType.schedulingType && ["COLLECTIVE", "ROUND_ROBIN"].includes(eventType.schedulingType); const paymentAppData = getPaymentAppData(eventType); + loggerWithEventDetails.debug( + `Booking eventType ${eventTypeId} started`, + safeStringify({ + reqBody: { + user: reqBody.user, + eventTypeId, + eventTypeSlug, + startTime: reqBody.start, + endTime: reqBody.end, + rescheduleUid: reqBody.rescheduleUid, + location: location, + }, + isTeamEventType, + eventType: getPiiFreeEventType(eventType), + dynamicUserList, + paymentAppData: { + enabled: paymentAppData.enabled, + price: paymentAppData.price, + paymentOption: paymentAppData.paymentOption, + currency: paymentAppData.currency, + appId: paymentAppData.appId, + }, + }) + ); let timeOutOfBounds = false; try { @@ -837,6 +852,13 @@ async function handler( : user.isFixed || eventType.schedulingType !== SchedulingType.ROUND_ROBIN, })); + loggerWithEventDetails.debug( + "Concerned users", + safeStringify({ + users: users.map(getPiiFreeUser), + }) + ); + let locationBodyString = location; // TODO: It's definition should be moved to getLocationValueForDb @@ -921,6 +943,13 @@ async function handler( const luckyUsers: typeof users = []; const luckyUserPool = availableUsers.filter((user) => !user.isFixed); + loggerWithEventDetails.debug( + "Computed available users", + safeStringify({ + availableUsers: availableUsers.map((user) => user.id), + luckyUserPool: luckyUserPool.map((user) => user.id), + }) + ); // loop through all non-fixed hosts and get the lucky users while (luckyUserPool.length > 0 && luckyUsers.length < 1 /* TODO: Add variable */) { const newLuckyUser = await getLuckyUser("MAXIMIZE_AVAILABILITY", { @@ -946,6 +975,7 @@ async function handler( } const [organizerUser] = users; + const tOrganizer = await getTranslation(organizerUser?.locale ?? "en", "common"); const allCredentials = await getAllCredentials(organizerUser, eventType); @@ -1988,6 +2018,17 @@ async function handler( type Booking = Prisma.PromiseReturnType; let booking: (Booking & { appsStatus?: AppsStatus[] }) | null = null; + loggerWithEventDetails.debug( + "Going to create booking in DB now", + safeStringify({ + organizerUser: organizerUser.id, + attendeesList: attendeesList.map((guest) => ({ timeZone: guest.timeZone })), + requiresConfirmation, + isConfirmedByDefault, + userReschedulingIsOwner, + }) + ); + try { booking = await createBooking(); @@ -2177,7 +2218,7 @@ async function handler( }; loggerWithEventDetails.error( - `Booking ${organizerUser.username} failed`, + `Failure in creating events in some of the integrations ${organizerUser.username} failed`, safeStringify({ error, results }) ); } else { @@ -2201,6 +2242,7 @@ async function handler( const googleCalResult = results[googleCalIndex]; if (!googleCalResult) { + loggerWithEventDetails.warn("Google Calendar not installed but using Google Meet as location"); results.push({ ...googleMeetResult, success: false, @@ -2263,6 +2305,12 @@ async function handler( } } + loggerWithEventDetails.debug( + "Sending scheduled emails for booking confirmation", + safeStringify({ + calEvent: getPiiFreeCalendarEvent(evt), + }) + ); await sendScheduledEmails( { ...evt, @@ -2285,9 +2333,16 @@ async function handler( !!booking; if (!isConfirmedByDefault && noEmail !== true && !bookingRequiresPayment) { + loggerWithEventDetails.debug( + `Booking ${organizerUser.username} requires confirmation, sending request emails`, + safeStringify({ + calEvent: getPiiFreeCalendarEvent(evt), + }) + ); await sendOrganizerRequestEmail({ ...evt, additionalNotes }); await sendAttendeeRequestEmail({ ...evt, additionalNotes }, attendeesList[0]); } + const metadata = videoCallUrl ? { videoCallUrl: getVideoCallUrlFromCalEvent(evt), @@ -2311,6 +2366,7 @@ async function handler( }; if (bookingRequiresPayment) { + loggerWithEventDetails.debug(`Booking ${organizerUser.username} requires payment`); // Load credentials.app.categories const credentialPaymentAppCategories = await prisma.credential.findMany({ where: { @@ -2555,31 +2611,3 @@ const findBookingQuery = async (bookingId: number) => { // Don't leak any sensitive data return foundBooking; }; - -function isLoggingEnabled({ - eventTypeId, - usernameOrTeamName, -}: { - eventTypeId?: number | null; - usernameOrTeamName?: string | string[]; -}) { - const usernameOrTeamnamesList = - usernameOrTeamName instanceof Array ? usernameOrTeamName : [usernameOrTeamName]; - // eslint-disable-next-line turbo/no-undeclared-env-vars - const bookingLoggingEventIds = process.env.BOOKING_LOGGING_EVENT_IDS || ""; - const isEnabled = bookingLoggingEventIds.split(",").some((id) => { - if (Number(id.trim()) === eventTypeId) { - return true; - } - }); - - if (isEnabled) { - return true; - } - - // eslint-disable-next-line turbo/no-undeclared-env-vars - const bookingLoggingUsername = process.env.BOOKING_LOGGING_USER_OR_TEAM_NAME || ""; - return bookingLoggingUsername.split(",").some((u) => { - return usernameOrTeamnamesList.some((foundUsername) => foundUsername === u.trim()); - }); -} diff --git a/packages/features/bookings/lib/isEventTypeLoggingEnabled.ts b/packages/features/bookings/lib/isEventTypeLoggingEnabled.ts new file mode 100644 index 0000000000..5f79a0bdb2 --- /dev/null +++ b/packages/features/bookings/lib/isEventTypeLoggingEnabled.ts @@ -0,0 +1,27 @@ +export function isEventTypeLoggingEnabled({ + eventTypeId, + usernameOrTeamName, +}: { + eventTypeId?: number | null; + usernameOrTeamName?: string | string[]; +}) { + const usernameOrTeamnamesList = + usernameOrTeamName instanceof Array ? usernameOrTeamName : [usernameOrTeamName]; + // eslint-disable-next-line turbo/no-undeclared-env-vars + const bookingLoggingEventIds = process.env.BOOKING_LOGGING_EVENT_IDS || ""; + const isEnabled = bookingLoggingEventIds.split(",").some((id) => { + if (Number(id.trim()) === eventTypeId) { + return true; + } + }); + + if (isEnabled) { + return true; + } + + // eslint-disable-next-line turbo/no-undeclared-env-vars + const bookingLoggingUsername = process.env.BOOKING_LOGGING_USER_OR_TEAM_NAME || ""; + return bookingLoggingUsername.split(",").some((u) => { + return usernameOrTeamnamesList.some((foundUsername) => foundUsername === u.trim()); + }); +} diff --git a/packages/lib/piiFreeData.ts b/packages/lib/piiFreeData.ts index c5e614a93f..088ab39ec5 100644 --- a/packages/lib/piiFreeData.ts +++ b/packages/lib/piiFreeData.ts @@ -1,5 +1,6 @@ -import type { Credential, SelectedCalendar } from "@prisma/client"; +import type { Credential, SelectedCalendar, DestinationCalendar } from "@prisma/client"; +import type { EventType } from "@calcom/prisma/client"; import type { CalendarEvent } from "@calcom/types/Calendar"; export function getPiiFreeCalendarEvent(calEvent: CalendarEvent) { @@ -15,6 +16,7 @@ export function getPiiFreeCalendarEvent(calEvent: CalendarEvent) { recurrence: calEvent.recurrence, requiresConfirmation: calEvent.requiresConfirmation, uid: calEvent.uid, + iCalUID: calEvent.iCalUID, /** * Let's just get a boolean value for PII sensitive fields so that we atleast know if it's present or not */ @@ -66,10 +68,54 @@ export function getPiiFreeSelectedCalendar(selectedCalendar: Partial) { + return { + integration: destinationCalendar.integration, + userId: destinationCalendar.userId, + /** + * Let's just get a boolean value for PII sensitive fields so that we atleast know if it's present or not + */ + externalId: !!destinationCalendar.externalId, + credentialId: !!destinationCalendar.credentialId, + }; +} + +export function getPiiFreeEventType(eventType: Partial>) { + return { + id: eventType.id, + schedulingType: eventType.schedulingType, + seatsPerTimeSlot: eventType.seatsPerTimeSlot, + }; +} + +export function getPiiFreeUser(user: { + id?: number; + username?: string | null; + isFixed?: boolean; + timeZone?: string; + allowDynamicBooking?: boolean | null; + defaultScheduleId?: number | null; + organizationId?: number | null; + credentials?: Credential[]; + destinationCalendar?: DestinationCalendar | null; +}) { + return { + id: user.id, + username: user.username, + isFixed: user.isFixed, + timeZone: user.timeZone, + allowDynamicBooking: user.allowDynamicBooking, + defaultScheduleId: user.defaultScheduleId, + organizationId: user.organizationId, + credentials: user.credentials?.map(getPiiFreeCredential), + destinationCalendar: user.destinationCalendar + ? getPiiFreeDestinationCalendar(user.destinationCalendar) + : user.destinationCalendar, + }; +} diff --git a/packages/lib/sync/SyncServiceManager.ts b/packages/lib/sync/SyncServiceManager.ts index 14096dddd8..95cbd14b64 100644 --- a/packages/lib/sync/SyncServiceManager.ts +++ b/packages/lib/sync/SyncServiceManager.ts @@ -1,6 +1,7 @@ import logger from "@calcom/lib/logger"; import type { MembershipRole } from "@calcom/prisma/enums"; +import { safeStringify } from "../safeStringify"; import type { ConsoleUserInfoType, TeamInfoType, WebUserInfoType } from "./ISyncService"; import services from "./services"; import CloseComService from "./services/CloseComService"; @@ -9,7 +10,7 @@ const log = logger.getChildLogger({ prefix: [`[[SyncServiceManager] `] }); export const createConsoleUser = async (user: ConsoleUserInfoType | null | undefined) => { if (user) { - log.debug("createConsoleUser", { user }); + log.debug("createConsoleUser", safeStringify({ user })); try { Promise.all( services.map(async (serviceClass) => { @@ -24,16 +25,16 @@ export const createConsoleUser = async (user: ConsoleUserInfoType | null | undef }) ); } catch (e) { - log.warn("createConsoleUser", e); + log.warn("createConsoleUser", safeStringify({ error: e })); } } else { - log.warn("createConsoleUser:noUser", { user }); + log.warn("createConsoleUser:noUser", safeStringify({ user })); } }; export const createWebUser = async (user: WebUserInfoType | null | undefined) => { if (user) { - log.debug("createWebUser", { user }); + log.debug("createWebUser", safeStringify({ user })); try { Promise.all( services.map(async (serviceClass) => { @@ -48,16 +49,16 @@ export const createWebUser = async (user: WebUserInfoType | null | undefined) => }) ); } catch (e) { - log.warn("createWebUser", e); + log.warn("createWebUser", safeStringify({ error: e })); } } else { - log.warn("createWebUser:noUser", { user }); + log.warn("createWebUser:noUser", safeStringify({ user })); } }; export const updateWebUser = async (user: WebUserInfoType | null | undefined) => { if (user) { - log.debug("updateWebUser", { user }); + log.debug("updateWebUser", safeStringify({ user })); try { Promise.all( services.map(async (serviceClass) => { @@ -72,10 +73,10 @@ export const updateWebUser = async (user: WebUserInfoType | null | undefined) => }) ); } catch (e) { - log.warn("updateWebUser", e); + log.warn("updateWebUser", safeStringify({ error: e })); } } else { - log.warn("updateWebUser:noUser", { user }); + log.warn("updateWebUser:noUser", safeStringify({ user })); } }; diff --git a/packages/lib/testEmails.ts b/packages/lib/testEmails.ts index fff8da1079..b6687be0ba 100644 --- a/packages/lib/testEmails.ts +++ b/packages/lib/testEmails.ts @@ -1,6 +1,10 @@ declare global { // eslint-disable-next-line no-var var testEmails: { + icalEvent?: { + filename: string; + content: string; + }; to: string; from: string; subject: string; diff --git a/packages/trpc/server/routers/viewer/slots/util.ts b/packages/trpc/server/routers/viewer/slots/util.ts index ac62bb4cd1..b49412eebf 100644 --- a/packages/trpc/server/routers/viewer/slots/util.ts +++ b/packages/trpc/server/routers/viewer/slots/util.ts @@ -8,6 +8,7 @@ import { getUserAvailability } from "@calcom/core/getUserAvailability"; import type { Dayjs } from "@calcom/dayjs"; import dayjs from "@calcom/dayjs"; import { getSlugOrRequestedSlug, orgDomainConfig } from "@calcom/ee/organizations/lib/orgDomains"; +import { isEventTypeLoggingEnabled } from "@calcom/features/bookings/lib/isEventTypeLoggingEnabled"; import { getDefaultEvent } from "@calcom/lib/defaultEvents"; import isTimeOutOfBounds from "@calcom/lib/isOutOfBounds"; import logger from "@calcom/lib/logger"; @@ -266,25 +267,30 @@ export function getRegularOrDynamicEventType( export async function getAvailableSlots({ input, ctx }: GetScheduleOptions) { const orgDetails = orgDomainConfig(ctx?.req?.headers.host ?? ""); - - if (input.debug === true) { - logger.setSettings({ minLevel: "debug" }); - } if (process.env.INTEGRATION_TEST_MODE === "true") { logger.setSettings({ minLevel: "silly" }); } const startPrismaEventTypeGet = performance.now(); const eventType = await getRegularOrDynamicEventType(input, orgDetails); const endPrismaEventTypeGet = performance.now(); - logger.debug( - `Prisma eventType get took ${endPrismaEventTypeGet - startPrismaEventTypeGet}ms for event:${ - input.eventTypeId - }` - ); + if (!eventType) { throw new TRPCError({ code: "NOT_FOUND" }); } + if (isEventTypeLoggingEnabled({ eventTypeId: eventType.id })) { + logger.setSettings({ minLevel: "debug" }); + } + + const loggerWithEventDetails = logger.getChildLogger({ + prefix: ["getAvailableSlots", `${eventType.id}:${input.usernameList}/${input.eventTypeSlug}`], + }); + + loggerWithEventDetails.debug( + `Prisma eventType get took ${endPrismaEventTypeGet - startPrismaEventTypeGet}ms for event:${ + input.eventTypeId + }` + ); const getStartTime = (startTimeInput: string, timeZone?: string) => { const startTimeMin = dayjs.utc().add(eventType.minimumBookingNotice, "minutes"); const startTime = timeZone === "Etc/GMT" ? dayjs.utc(startTimeInput) : dayjs(startTimeInput).tz(timeZone); @@ -598,12 +604,12 @@ export async function getAvailableSlots({ input, ctx }: GetScheduleOptions) { Object.create(null) ); - logger.debug(`getSlots took ${getSlotsTime}ms and executed ${getSlotsCount} times`); + loggerWithEventDetails.debug(`getSlots took ${getSlotsTime}ms and executed ${getSlotsCount} times`); - logger.debug( + loggerWithEventDetails.debug( `checkForAvailability took ${checkForAvailabilityTime}ms and executed ${checkForAvailabilityCount} times` ); - logger.silly(`Available slots: ${JSON.stringify(computedAvailableSlots)}`); + loggerWithEventDetails.debug(`Available slots: ${JSON.stringify(computedAvailableSlots)}`); return { slots: computedAvailableSlots, diff --git a/yarn.lock b/yarn.lock index b8c007aa76..6320449a24 100644 --- a/yarn.lock +++ b/yarn.lock @@ -15519,6 +15519,17 @@ __metadata: languageName: node linkType: hard +"axios@npm:1.4.0": + version: 1.4.0 + resolution: "axios@npm:1.4.0" + dependencies: + follow-redirects: ^1.15.0 + form-data: ^4.0.0 + proxy-from-env: ^1.1.0 + checksum: 7fb6a4313bae7f45e89d62c70a800913c303df653f19eafec88e56cea2e3821066b8409bc68be1930ecca80e861c52aa787659df0ffec6ad4d451c7816b9386b + languageName: node + linkType: hard + "axios@npm:>=0.21.2, axios@npm:^0.26.0, axios@npm:^0.26.1": version: 0.26.1 resolution: "axios@npm:0.26.1" @@ -16677,6 +16688,7 @@ __metadata: lint-staged: ^12.5.0 lucide-react: ^0.171.0 mailhog: ^4.16.0 + node-ical: ^0.16.1 prettier: ^2.8.6 prismock: ^1.21.1 tsc-absolute: ^1.0.0 @@ -27381,6 +27393,13 @@ __metadata: languageName: node linkType: hard +"luxon@npm:^1.21.3": + version: 1.28.1 + resolution: "luxon@npm:1.28.1" + checksum: 2c62999adea79645fd1e931d685f61aeb33eda7f39fbf79b84261a233b62f9590f48336654ee9efd405848bd9e13dc7fe087c701b7126187201a88998dc68b04 + languageName: node + linkType: hard + "luxon@npm:^1.26.0": version: 1.28.0 resolution: "luxon@npm:1.28.0" @@ -28729,6 +28748,15 @@ __metadata: languageName: node linkType: hard +"moment-timezone@npm:^0.5.31": + version: 0.5.43 + resolution: "moment-timezone@npm:0.5.43" + dependencies: + moment: ^2.29.4 + checksum: 8075c897ed8a044f992ef26fe8cdbcad80caf974251db424cae157473cca03be2830de8c74d99341b76edae59f148c9d9d19c1c1d9363259085688ec1cf508d0 + languageName: node + linkType: hard + "moment-timezone@npm:^0.5.34": version: 0.5.34 resolution: "moment-timezone@npm:0.5.34" @@ -28745,6 +28773,13 @@ __metadata: languageName: node linkType: hard +"moment@npm:^2.29.4": + version: 2.29.4 + resolution: "moment@npm:2.29.4" + checksum: 0ec3f9c2bcba38dc2451b1daed5daded747f17610b92427bebe1d08d48d8b7bdd8d9197500b072d14e326dd0ccf3e326b9e3d07c5895d3d49e39b6803b76e80e + languageName: node + linkType: hard + "mongodb-connection-string-url@npm:^2.6.0": version: 2.6.0 resolution: "mongodb-connection-string-url@npm:2.6.0" @@ -29438,6 +29473,18 @@ __metadata: languageName: node linkType: hard +"node-ical@npm:^0.16.1": + version: 0.16.1 + resolution: "node-ical@npm:0.16.1" + dependencies: + axios: 1.4.0 + moment-timezone: ^0.5.31 + rrule: 2.6.4 + uuid: ^9.0.0 + checksum: be917c2a38b5514d4ae8c3ae6563d298fa772082b76f428c534eaa2a3f30acbf97a4d010a04ac0d39851c838e41fe65b7f2467cb35b70d1587f870361309a8d8 + languageName: node + linkType: hard + "node-int64@npm:^0.4.0": version: 0.4.0 resolution: "node-int64@npm:0.4.0" @@ -34330,6 +34377,19 @@ __metadata: languageName: node linkType: hard +"rrule@npm:2.6.4": + version: 2.6.4 + resolution: "rrule@npm:2.6.4" + dependencies: + luxon: ^1.21.3 + tslib: ^1.10.0 + dependenciesMeta: + luxon: + optional: true + checksum: 510cddbdfae9d91dab84fe484d54cd0a46f2a9cfd58c24fe470b9341f511c3999abc06fd33735884a08b369f700d87cfd49b46999f2f30b11f5b07c43858d695 + languageName: node + linkType: hard + "rrule@npm:^2.7.1": version: 2.7.1 resolution: "rrule@npm:2.7.1" @@ -37547,7 +37607,7 @@ __metadata: languageName: node linkType: hard -"tslib@npm:^1.0.0, tslib@npm:^1.11.1, tslib@npm:^1.8.1, tslib@npm:^1.9.3": +"tslib@npm:^1.0.0, tslib@npm:^1.10.0, tslib@npm:^1.11.1, tslib@npm:^1.8.1, tslib@npm:^1.9.3": version: 1.14.1 resolution: "tslib@npm:1.14.1" checksum: dbe628ef87f66691d5d2959b3e41b9ca0045c3ee3c7c7b906cc1e328b39f199bb1ad9e671c39025bd56122ac57dfbf7385a94843b1cc07c60a4db74795829acd