public-offering
/
cal.pub0.org
1
0
Fork 0
Code Issues Pull Requests Packages Projects Releases Wiki Activity

chore: Improved logging booking flow (#11543)

pull/11583/head
Hariom Balhara 2023-09-28 18:31:24 +05:30 committed by GitHub
parent 57e712dd9e
commit b54f716fd7
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
8 changed files with 200 additions and 30 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

5
packages/app-store/googlecalendar/lib/CalendarService.ts
View File

@ -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

26
packages/core/CalendarManager.ts
View File

@ -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;
}

21
packages/core/getBusyTimes.ts
View File

@ -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;
}

16
packages/core/getUserAvailability.ts
View File

@ -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,

3
packages/core/videoClient.ts
View File

@ -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);

2
packages/features/bookings/lib/handleConfirmation.ts
View File

@ -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 = {};

111
packages/features/bookings/lib/handleNewBooking.ts
View File

@ -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());
});
}

46
packages/lib/piiFreeData.ts Normal file
View File

@ -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
};
}