From b54f716fd7aa5165bb3cbebbb64a46500018d7c6 Mon Sep 17 00:00:00 2001 From: Hariom Balhara Date: Thu, 28 Sep 2023 18:31:24 +0530 Subject: [PATCH] chore: Improved logging booking flow (#11543) --- .../googlecalendar/lib/CalendarService.ts | 5 + packages/core/CalendarManager.ts | 26 +++- packages/core/getBusyTimes.ts | 21 +++- packages/core/getUserAvailability.ts | 16 ++- packages/core/videoClient.ts | 3 +- .../bookings/lib/handleConfirmation.ts | 2 +- .../features/bookings/lib/handleNewBooking.ts | 111 ++++++++++++++---- packages/lib/piiFreeData.ts | 46 ++++++++ 8 files changed, 200 insertions(+), 30 deletions(-) create mode 100644 packages/lib/piiFreeData.ts diff --git a/packages/app-store/googlecalendar/lib/CalendarService.ts b/packages/app-store/googlecalendar/lib/CalendarService.ts index 5aad95178fc5b7..12c515239642f4 100644 --- a/packages/app-store/googlecalendar/lib/CalendarService.ts +++ b/packages/app-store/googlecalendar/lib/CalendarService.ts @@ -298,6 +298,11 @@ export default class GoogleCalendarService implements Calendar { conferenceDataVersion: 1, }); + this.log.debug("Updated Google Calendar Event", { + startTime: evt?.data.start, + endTime: evt?.data.end, + }); + if (evt && evt.data.id && evt.data.hangoutLink && event.location === MeetLocationType) { calendar.events.patch({ // Update the same event but this time we know the hangout link diff --git a/packages/core/CalendarManager.ts b/packages/core/CalendarManager.ts index 8c55c176517597..cac2f56696fa1b 100644 --- a/packages/core/CalendarManager.ts +++ b/packages/core/CalendarManager.ts @@ -7,6 +7,7 @@ import getApps from "@calcom/app-store/utils"; import dayjs from "@calcom/dayjs"; import { getUid } from "@calcom/lib/CalEventParser"; import logger from "@calcom/lib/logger"; +import { getPiiFreeCalendarEvent } from "@calcom/lib/piiFreeData"; import { performance } from "@calcom/lib/server/perfObserver"; import type { CalendarEvent, @@ -225,6 +226,12 @@ export const createEvent = async ( let success = true; let calError: string | undefined = undefined; + log.debug( + "Creating calendar event", + JSON.stringify({ + calEvent: getPiiFreeCalendarEvent(calEvent), + }) + ); // Check if the disabledNotes flag is set to true if (calEvent.hideCalendarNotes) { calEvent.additionalNotes = "Notes have been hidden by the organizer"; // TODO: i18n this string? @@ -280,9 +287,19 @@ export const updateEvent = async ( let success = false; let calError: string | undefined = undefined; let calWarnings: string[] | undefined = []; - + log.debug( + "Updating calendar event", + JSON.stringify({ + bookingRefUid, + calEvent: getPiiFreeCalendarEvent(calEvent), + }) + ); if (bookingRefUid === "") { - log.error("updateEvent failed", "bookingRefUid is empty", calEvent, credential); + log.error( + "updateEvent failed", + "bookingRefUid is empty", + JSON.stringify({ calEvent: getPiiFreeCalendarEvent(calEvent) }) + ); } const updatedResult: NewCalendarEventType | NewCalendarEventType[] | undefined = calendar && bookingRefUid @@ -296,7 +313,10 @@ export const updateEvent = async ( // @TODO: This code will be off till we can investigate an error with it // @see https://github.com/calcom/cal.com/issues/3949 // await sendBrokenIntegrationEmail(calEvent, "calendar"); - log.error("updateEvent failed", e, calEvent); + log.error( + "updateEvent failed", + JSON.stringify({ e, calEvent: getPiiFreeCalendarEvent(calEvent) }) + ); if (e?.calError) { calError = e.calError; } diff --git a/packages/core/getBusyTimes.ts b/packages/core/getBusyTimes.ts index c9e484a11eca40..d27a42d9e3273c 100644 --- a/packages/core/getBusyTimes.ts +++ b/packages/core/getBusyTimes.ts @@ -4,6 +4,7 @@ import { getBusyCalendarTimes } from "@calcom/core/CalendarManager"; import dayjs from "@calcom/dayjs"; import { subtract } from "@calcom/lib/date-ranges"; import logger from "@calcom/lib/logger"; +import { getPiiFreeBooking } from "@calcom/lib/piiFreeData"; import { performance } from "@calcom/lib/server/perfObserver"; import prisma from "@calcom/prisma"; import type { SelectedCalendar } from "@calcom/prisma/client"; @@ -89,7 +90,6 @@ export async function getBusyTimes(params: { in: [BookingStatus.ACCEPTED], }, }; - // INFO: Refactored to allow this method to take in a list of current bookings for the user. // Will keep support for retrieving a user's bookings if the caller does not already supply them. // This function is called from multiple places but we aren't refactoring all of them at this moment @@ -179,7 +179,13 @@ export async function getBusyTimes(params: { [] ); - logger.silly(`Busy Time from Cal Bookings ${JSON.stringify(busyTimes)}`); + logger.debug( + `Busy Time from Cal Bookings ${JSON.stringify({ + busyTimes, + bookings: bookings?.map((booking) => getPiiFreeBooking(booking)), + numCredentials: credentials?.length, + })}` + ); performance.mark("prismaBookingGetEnd"); performance.measure(`prisma booking get took $1'`, "prismaBookingGetStart", "prismaBookingGetEnd"); if (credentials?.length > 0) { @@ -195,7 +201,10 @@ export async function getBusyTimes(params: { logger.debug( `Connected Calendars get took ${ endConnectedCalendarsGet - startConnectedCalendarsGet - } ms for user ${username}` + } ms for user ${username}`, + JSON.stringify({ + calendarBusyTimes, + }) ); const openSeatsDateRanges = Object.keys(bookingSeatCountMap).map((key) => { @@ -241,6 +250,12 @@ export async function getBusyTimes(params: { busyTimes.push(...videoBusyTimes); */ } + logger.debug( + "getBusyTimes:", + JSON.stringify({ + allBusyTimes: busyTimes, + }) + ); return busyTimes; } diff --git a/packages/core/getUserAvailability.ts b/packages/core/getUserAvailability.ts index 07ea15a0fee3d5..98178d4b55deff 100644 --- a/packages/core/getUserAvailability.ts +++ b/packages/core/getUserAvailability.ts @@ -244,7 +244,6 @@ export const getUserAvailability = async function getUsersWorkingHoursLifeTheUni const workingHours = getWorkingHours({ timeZone }, availability); const endGetWorkingHours = performance.now(); - logger.debug(`getWorkingHours took ${endGetWorkingHours - startGetWorkingHours}ms for userId ${userId}`); const dateOverrides = availability .filter((availability) => !!availability.date) @@ -269,10 +268,23 @@ export const getUserAvailability = async function getUsersWorkingHoursLifeTheUni end: dayjs(busy.end), })); + const dateRangesInWhichUserIsAvailable = subtract(dateRanges, formattedBusyTimes); + + logger.debug( + `getWorkingHours took ${endGetWorkingHours - startGetWorkingHours}ms for userId ${userId}`, + JSON.stringify({ + workingHoursInUtc: workingHours, + dateOverrides, + dateRangesAsPerAvailability: dateRanges, + dateRangesInWhichUserIsAvailable, + detailedBusyTimes, + }) + ); + return { busy: detailedBusyTimes, timeZone, - dateRanges: subtract(dateRanges, formattedBusyTimes), + dateRanges: dateRangesInWhichUserIsAvailable, workingHours, dateOverrides, currentSeats, diff --git a/packages/core/videoClient.ts b/packages/core/videoClient.ts index 425224fdd898cf..1f5a4d996b7933 100644 --- a/packages/core/videoClient.ts +++ b/packages/core/videoClient.ts @@ -6,6 +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 { prisma } from "@calcom/prisma"; import type { GetRecordingsResponseSchema } from "@calcom/prisma/zod-utils"; import type { CalendarEvent, EventBusyDate } from "@calcom/types/Calendar"; @@ -95,7 +96,7 @@ const createMeeting = async (credential: CredentialPayload, calEvent: CalendarEv returnObject = { ...returnObject, createdEvent: createdMeeting, success: true }; } catch (err) { await sendBrokenIntegrationEmail(calEvent, "video"); - console.error("createMeeting failed", err, calEvent); + log.error("createMeeting failed", JSON.stringify({ err, calEvent: getPiiFreeCalendarEvent(calEvent) })); // Default to calVideo const defaultMeeting = await createMeetingWithCalVideo(calEvent); diff --git a/packages/features/bookings/lib/handleConfirmation.ts b/packages/features/bookings/lib/handleConfirmation.ts index ec049110fdb56e..892a7d00c9d41c 100644 --- a/packages/features/bookings/lib/handleConfirmation.ts +++ b/packages/features/bookings/lib/handleConfirmation.ts @@ -52,7 +52,7 @@ export async function handleConfirmation(args: { message: "Booking failed", }; - log.error(`Booking ${user.username} failed`, error, results); + log.error(`Booking ${user.username} failed`, JSON.stringify({ error, results })); } else { const metadata: AdditionalInformation = {}; diff --git a/packages/features/bookings/lib/handleNewBooking.ts b/packages/features/bookings/lib/handleNewBooking.ts index 23eb562b749023..0a134c75866290 100644 --- a/packages/features/bookings/lib/handleNewBooking.ts +++ b/packages/features/bookings/lib/handleNewBooking.ts @@ -376,6 +376,7 @@ async function ensureAvailableUsers( ) : undefined; + log.debug("getUserAvailability for users", JSON.stringify({ users: eventType.users.map((u) => u.id) })); /** Let's start checking for availability */ for (const user of eventType.users) { const { dateRanges, busy: bufferedBusyTimes } = await getUserAvailability( @@ -392,13 +393,16 @@ async function ensureAvailableUsers( } ); + log.debug( + "calendarBusyTimes==>>>", + JSON.stringify({ bufferedBusyTimes, dateRanges, isRecurringEvent: eventType.recurringEvent }) + ); + if (!dateRanges.length) { // user does not have availability at this time, skip user. continue; } - console.log("calendarBusyTimes==>>>", bufferedBusyTimes); - let foundConflict = false; try { if ( @@ -638,7 +642,6 @@ async function handler( } ) { const { userId } = req; - const userIp = getIP(req); await checkRateLimitAndThrowError({ @@ -680,10 +683,29 @@ async function handler( eventType, }); + const loggerWithEventDetails = logger.getChildLogger({ + prefix: ["book:user", `${eventTypeId}:${reqBody.user}/${eventTypeSlug}`], + }); + + if (isLoggingEnabled({ 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"); - log.debug(`Booking eventType ${eventTypeId} started`); + 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" }); @@ -702,12 +724,12 @@ async function handler( periodCountCalendarDays: eventType.periodCountCalendarDays, }); } catch (error) { - log.warn({ + loggerWithEventDetails.warn({ message: "NewBooking: Unable set timeOutOfBounds. Using false. ", }); if (error instanceof BookingDateInPastError) { // TODO: HttpError should not bleed through to the console. - log.info(`Booking eventType ${eventTypeId} failed`, error); + loggerWithEventDetails.info(`Booking eventType ${eventTypeId} failed`, JSON.stringify({ error })); throw new HttpError({ statusCode: 400, message: error.message }); } } @@ -717,7 +739,7 @@ async function handler( errorCode: "BookingTimeOutOfBounds", message: `EventType '${eventType.eventName}' cannot be booked at this time.`, }; - log.warn({ + loggerWithEventDetails.warn({ message: `NewBooking: EventType '${eventType.eventName}' cannot be booked at this time.`, }); throw new HttpError({ statusCode: 400, message: error.message }); @@ -774,7 +796,9 @@ async function handler( const isDynamicAllowed = !users.some((user) => !user.allowDynamicBooking); if (!isDynamicAllowed && !eventTypeId) { - log.warn({ message: "NewBooking: Some of the users in this group do not allow dynamic booking" }); + loggerWithEventDetails.warn({ + message: "NewBooking: Some of the users in this group do not allow dynamic booking", + }); throw new HttpError({ message: "Some of the users in this group do not allow dynamic booking", statusCode: 400, @@ -796,7 +820,7 @@ async function handler( }, }); if (!eventTypeUser) { - log.warn({ message: "NewBooking: eventTypeUser.notFound" }); + loggerWithEventDetails.warn({ message: "NewBooking: eventTypeUser.notFound" }); throw new HttpError({ statusCode: 404, message: "eventTypeUser.notFound" }); } users.push(eventTypeUser); @@ -1365,7 +1389,10 @@ async function handler( errorCode: "BookingReschedulingMeetingFailed", message: "Booking Rescheduling failed", }; - log.error(`Booking ${organizerUser.name} failed`, error, results); + loggerWithEventDetails.error( + `Booking ${organizerUser.name} failed`, + JSON.stringify({ error, results }) + ); } else { const metadata: AdditionalInformation = {}; if (results.length) { @@ -1759,7 +1786,7 @@ async function handler( eventTypeRequiresConfirmation: eventType.requiresConfirmation, }); } catch (error) { - log.error("Error while scheduling workflow reminders", error); + loggerWithEventDetails.error("Error while scheduling workflow reminders", JSON.stringify({ error })); } const webhookData = { @@ -2002,7 +2029,11 @@ async function handler( } } catch (_err) { const err = getErrorFromUnknown(_err); - log.error(`Booking ${eventTypeId} failed`, "Error when saving booking to db", err.message); + loggerWithEventDetails.error( + `Booking ${eventTypeId} failed`, + "Error when saving booking to db", + err.message + ); if (err.code === "P2002") { throw new HttpError({ statusCode: 409, message: "booking.conflict" }); } @@ -2056,7 +2087,10 @@ async function handler( // cancel workflow reminders from previous rescheduled booking await cancelWorkflowReminders(originalRescheduledBooking.workflowReminders); } catch (error) { - log.error("Error while canceling scheduled workflow reminders", error); + loggerWithEventDetails.error( + "Error while canceling scheduled workflow reminders", + JSON.stringify({ error }) + ); } // Use EventManager to conditionally use all needed integrations. @@ -2087,7 +2121,10 @@ async function handler( message: "Booking Rescheduling failed", }; - log.error(`Booking ${organizerUser.name} failed`, error, results); + loggerWithEventDetails.error( + `Booking ${organizerUser.name} failed`, + JSON.stringify({ error, results }) + ); } else { const metadata: AdditionalInformation = {}; const calendarResult = results.find((result) => result.type.includes("_calendar")); @@ -2139,7 +2176,10 @@ async function handler( message: "Booking failed", }; - log.error(`Booking ${organizerUser.username} failed`, error, results); + loggerWithEventDetails.error( + `Booking ${organizerUser.username} failed`, + JSON.stringify({ error, results }) + ); } else { const metadata: AdditionalInformation = {}; @@ -2294,7 +2334,7 @@ async function handler( return { ...booking, message: "Payment required", paymentUid: payment?.uid }; } - log.debug(`Booking ${organizerUser.username} completed`); + loggerWithEventDetails.debug(`Booking ${organizerUser.username} completed`); if (booking.location?.startsWith("http")) { videoCallUrl = booking.location; @@ -2335,7 +2375,10 @@ async function handler( } }); } catch (error) { - log.error("Error while running scheduledJobs for booking", error); + loggerWithEventDetails.error( + "Error while running scheduledJobs for booking", + JSON.stringify({ error }) + ); } // Send Webhook call if hooked to BOOKING_CREATED & BOOKING_RESCHEDULED @@ -2365,7 +2408,7 @@ async function handler( }); } } catch (error) { - log.error("Error while updating hashed link", error); + loggerWithEventDetails.error("Error while updating hashed link", JSON.stringify({ error })); } if (!booking) throw new HttpError({ statusCode: 400, message: "Booking failed" }); @@ -2385,7 +2428,7 @@ async function handler( }, }); } catch (error) { - log.error("Error while creating booking references", error); + loggerWithEventDetails.error("Error while creating booking references", JSON.stringify({ error })); } const metadataFromEvent = videoCallUrl ? { videoCallUrl } : undefined; @@ -2406,7 +2449,7 @@ async function handler( eventTypeRequiresConfirmation: eventType.requiresConfirmation, }); } catch (error) { - log.error("Error while scheduling workflow reminders", error); + loggerWithEventDetails.error("Error while scheduling workflow reminders", JSON.stringify({ error })); } // booking successful @@ -2499,3 +2542,31 @@ 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/lib/piiFreeData.ts b/packages/lib/piiFreeData.ts new file mode 100644 index 00000000000000..075fdcfc3fbd73 --- /dev/null +++ b/packages/lib/piiFreeData.ts @@ -0,0 +1,46 @@ +import type { CalendarEvent } from "@calcom/types/Calendar"; + +export function getPiiFreeCalendarEvent(calEvent: CalendarEvent) { + return { + eventTypeId: calEvent.eventTypeId, + type: calEvent.type, + startTime: calEvent.startTime, + endTime: calEvent.endTime, + schedulingType: calEvent.schedulingType, + seatsPerTimeSlot: calEvent.seatsPerTimeSlot, + appsStatus: calEvent.appsStatus, + recurringEvent: calEvent.recurringEvent, + recurrence: calEvent.recurrence, + requiresConfirmation: calEvent.requiresConfirmation, + uid: calEvent.uid, + /** + * Let's just get a boolean value for PII sensitive fields so that we atleast know if it's present or not + */ + // Not okay to have title which can have Booker and Organizer names + title: !!calEvent.title, + // .... Add all other props here that we don't want to be logged. It prevents those properties from being logged accidentally + }; +} + +export function getPiiFreeBooking(booking: { + id: number; + uid: string; + userId: number | null; + startTime: Date; + endTime: Date; + title: string; +}) { + return { + id: booking.id, + uid: booking.uid, + userId: booking.userId, + startTime: booking.startTime, + endTime: booking.endTime, + /** + * Let's just get a boolean value for PII sensitive fields so that we atleast know if it's present or not + */ + // Not okay to have title which can have Booker and Organizer names + title: !!booking.title, + // .... Add all other props here that we don't want to be logged. It prevents those properties from being logged accidentally + }; +}