enh(appointments): add moar debug logging and overwrite app id

miaulalala · miaulalala · commit 7b9cb93b8644 · 2024-02-12T14:53:26.000+01:00
Signed-off-by: Anna Larch &lt;anna@nextcloud.com&gt;
diff --git a/lib/Service/Appointments/AvailabilityGenerator.php b/lib/Service/Appointments/AvailabilityGenerator.php
@@ -31,6 +31,7 @@
 use DateTimeZone;
 use OCA\Calendar\Db\AppointmentConfig;
 use OCP\AppFramework\Utility\ITimeFactory;
+use Psr\Log\LoggerInterface;
 use function ceil;
 use function max;
 use function min;
@@ -39,7 +40,7 @@ class AvailabilityGenerator {
 	/** @var ITimeFactory */
 	private $timeFactory;
 
-	public function __construct(ITimeFactory $timeFactory) {
+	public function __construct(ITimeFactory $timeFactory, private LoggerInterface $logger) {
 		$this->timeFactory = $timeFactory;
 	}
 
@@ -79,11 +80,17 @@ public function generate(AppointmentConfig $config,
 
 		// If we reach this state then there are no available dates anymore
 		if ($latestEnd <= $earliestStart) {
+			$this->logger->debug('Appointment config ' . $config->getToken() . ' has {latestEnd} as latest end but {earliestStart} as earliest start. No slots available.', [
+				'latestEnd' => $latestEnd,
+				'earliestStart' => $earliestStart,
+				'app' => 'calendar-appointments'
+			]);
 			return [];
 		}
 
 		if (empty($config->getAvailability())) {
 			// No availability -> full time range is available
+			$this->logger->debug('Full time range available', ['app' => 'calendar-appointments']);
 			return [
 				new Interval($earliestStart, $latestEnd),
 			];
@@ -95,6 +102,7 @@ public function generate(AppointmentConfig $config,
 		$slots = $availabilityRule['slots'];
 
 		$applicableSlots = $this->filterDates($start, $slots, $timeZone);
+		$this->logger->debug('Found ' . count($applicableSlots) . ' applicable slot(s) after date filtering', ['app' => 'calendar-appointments']);
 
 		$intervals = [];
 		foreach ($applicableSlots as $slot) {
diff --git a/lib/Service/Appointments/BookingService.php b/lib/Service/Appointments/BookingService.php
@@ -142,13 +142,13 @@ public function confirmBooking(Booking $booking, AppointmentConfig $config): Boo
 			$this->mailService->sendBookingInformationEmail($booking, $config, $calendar);
 			$this->mailService->sendOrganizerBookingInformationEmail($booking, $config, $calendar);
 		} catch (ServiceException $e) {
-			$this->logger->info('Could not send booking emails after confirmation from user ' . $booking->getEmail(), ['exception' => $e]);
+			$this->logger->info('Could not send booking emails after confirmation from user ' . $booking->getEmail(), ['exception' => $e, 'app' => 'calendar-appointments']);
 		}
 
 		try {
 			$this->mailService->sendOrganizerBookingInformationNotification($booking, $config);
 		} catch (\InvalidArgumentException $e) {
-			$this->logger->warning('Could not send booking information notification after confirmation by user ' . $booking->getEmail(), ['exception' => $e]);
+			$this->logger->warning('Could not send booking information notification after confirmation by user ' . $booking->getEmail(), ['exception' => $e, 'app' => 'calendar-appointments']);
 		}
 
 		return $booking;
@@ -203,10 +203,13 @@ public function getAvailableSlots(AppointmentConfig $config, int $startTime, int
 		if ($config->getFutureLimit() !== null) {
 			/** @var int $maxEndTime */
 			$maxEndTime = time() + $config->getFutureLimit();
+			$this->logger->debug('Maximum end time: ' . $maxEndTime, ['app' => 'calendar-appointments']);
 			if ($startTime > $maxEndTime) {
+				$this->logger->debug('Start time is higher than maximum end time. Start time: ' . $startTime, ['app' => 'calendar-appointments']);
 				return [];
 			}
 			if ($endTime > $maxEndTime) {
+				$this->logger->debug('End time is higher than maximum end time. Setting end time to maximum end time. End time: ' . $endTime, ['app' => 'calendar-appointments']);
 				$endTime = $maxEndTime;
 			}
 		}
@@ -224,7 +227,8 @@ public function getAvailableSlots(AppointmentConfig $config, int $startTime, int
 			'availabilityIntervals' => count($availabilityIntervals),
 			'allPossibleSlots' => count($allPossibleSlots),
 			'filteredByDailyLimit' => count($filteredByDailyLimit),
-			'available' => count($available)
+			'available' => count($available),
+			'app' => 'calendar-appointments',
 		]);
 
 		return $available;
diff --git a/lib/Service/Appointments/DailyLimitFilter.php b/lib/Service/Appointments/DailyLimitFilter.php
@@ -28,6 +28,7 @@
 use OCA\Calendar\Db\AppointmentConfig;
 use OCP\Calendar\ICalendarQuery;
 use OCP\Calendar\IManager;
+use Psr\Log\LoggerInterface;
 use function array_filter;
 use function array_values;
 use function count;
@@ -36,7 +37,7 @@ class DailyLimitFilter {
 	/** @var IManager */
 	private $calendarManger;
 
-	public function __construct(IManager $calendarManger) {
+	public function __construct(IManager $calendarManger, private LoggerInterface $logger) {
 		$this->calendarManger = $calendarManger;
 	}
 
@@ -47,6 +48,10 @@ public function __construct(IManager $calendarManger) {
 	 * @return Interval[]
 	 */
 	public function filter(AppointmentConfig $config, array $slots): array {
+		$this->logger->debug('Slots before daily limit filtering:' . count($slots), ['app' => 'calendar-appointments']);
+		if(empty($slots)) {
+			return [];
+		}
 		// 0. If there is no limit then we don't have to filter anything
 		if ($config->getDailyMax() === null) {
 			return $slots;
@@ -90,10 +95,13 @@ public function filter(AppointmentConfig $config, array $slots): array {
 		}
 
 		// 3. Filter out the slots that are on an unavailable day
-		return array_values(array_filter($slots, function (Interval $slot) use ($available): bool {
+		$available = array_values(array_filter($slots, function (Interval $slot) use ($available): bool {
 			$startOfDay = $slot->getStartAsObject()->setTime(0, 0, 0, 0);
 			$ts = $startOfDay->getTimestamp();
 			return $available[$ts];
 		}));
+
+		$this->logger->debug('Slots after daily limit filtering:' . count($available), ['app' => 'calendar-appointments']);
+		return $available;
 	}
 }
diff --git a/lib/Service/Appointments/EventConflictFilter.php b/lib/Service/Appointments/EventConflictFilter.php
@@ -54,6 +54,10 @@ public function __construct(IManager $calendarManager,
 	 * @return Interval[]
 	 */
 	public function filter(AppointmentConfig $config, array $slots): array {
+		$this->logger->debug('Slots before event conflict filtering:' . count($slots), ['app' => 'calendar-appointments']);
+		if(empty($slots)) {
+			return [];
+		}
 		$query = $this->calendarManager->newQuery($config->getPrincipalUri());
 		foreach ($config->getCalendarFreebusyUrisAsArray() as $uri) {
 			$query->addSearchCalendar($uri);
@@ -63,7 +67,7 @@ public function filter(AppointmentConfig $config, array $slots): array {
 		$query->addType('VEVENT');
 		$preparationDuration = DateInterval::createFromDateString($config->getPreparationDuration() . ' seconds');
 		$followUpDuration = DateInterval::createFromDateString($config->getFollowupDuration() . ' seconds');
-		return array_filter($slots, function (Interval $slot) use ($followUpDuration, $preparationDuration, $query, $config): bool {
+		$available = array_filter($slots, function (Interval $slot) use ($followUpDuration, $preparationDuration, $query, $config): bool {
 			$query->setTimerangeStart($slot->getStartAsObject()->sub($preparationDuration));
 			$query->setTimerangeEnd($slot->getEndAsObject()->add($followUpDuration));
 
@@ -81,13 +85,16 @@ public function filter(AppointmentConfig $config, array $slots): array {
 
 			$this->logger->debug('Appointment config ' . $config->getToken() . ' is looking within {start} and {followup} in calendar {calendarUri}. Conflicting UIDs are {uids}', [
 				'start' => $slot->getStartAsObject()->sub($preparationDuration)->format(DateTimeInterface::ATOM),
-				'end' => $slot->getEndAsObject()->add($followUpDuration)->format(DateTimeInterface::ATOM),
+				'followup' => $slot->getEndAsObject()->add($followUpDuration)->format(DateTimeInterface::ATOM),
 				'calendarUri' => $config->getTargetCalendarUri(),
 				'uids' => implode(' : ', $uids)
 			]);
 
 			// If there is at least one event at this time then the slot is taken
 			return empty($objects);
 		});
+
+		$this->logger->debug('Slots after event conflict filtering:' . count($available), ['app' => 'calendar-appointments']);
+		return $available;
 	}
 }
diff --git a/lib/Service/Appointments/MailService.php b/lib/Service/Appointments/MailService.php
@@ -146,14 +146,14 @@ public function sendConfirmationEmail(Booking $booking, AppointmentConfig $confi
 		try {
 			$failed = $this->mailer->send($message);
 			if (count($failed) > 0) {
-				$this->logger->warning('Mail delivery failed for some recipients.');
+				$this->logger->warning('Mail delivery failed for some recipients.', ['app' => 'calendar-appointments']);
 				foreach ($failed as $fail) {
-					$this->logger->debug('Failed to deliver email to ' . $fail);
+					$this->logger->debug('Failed to deliver email to ' . $fail, ['app' => 'calendar-appointments']);
 				}
 				throw new ServiceException('Could not send mail for recipient(s) ' . implode(', ', $failed));
 			}
 		} catch (Exception $ex) {
-			$this->logger->error($ex->getMessage(), ['exception' => $ex]);
+			$this->logger->error($ex->getMessage(), ['exception' => $ex, 'app' => 'calendar-appointments']);
 			throw new ServiceException('Could not send mail: ' . $ex->getMessage(), $ex->getCode(), $ex);
 		}
 	}
@@ -215,14 +215,14 @@ public function sendBookingInformationEmail(Booking $booking, AppointmentConfig
 		try {
 			$failed = $this->mailer->send($message);
 			if (count($failed) > 0) {
-				$this->logger->warning('Mail delivery failed for some recipients.');
+				$this->logger->warning('Mail delivery failed for some recipients.', ['app' => 'calendar-appointments']);
 				foreach ($failed as $fail) {
-					$this->logger->debug('Failed to deliver email to ' . $fail);
+					$this->logger->debug('Failed to deliver email to ' . $fail, ['app' => 'calendar-appointments']);
 				}
 				throw new ServiceException('Could not send mail for recipient(s) ' . implode(', ', $failed));
 			}
 		} catch (Exception $ex) {
-			$this->logger->error($ex->getMessage(), ['exception' => $ex]);
+			$this->logger->error($ex->getMessage(), ['exception' => $ex, 'app' => 'calendar-appointments']);
 			throw new ServiceException('Could not send mail: ' . $ex->getMessage(), $ex->getCode(), $ex);
 		}
 	}
@@ -320,14 +320,14 @@ public function sendOrganizerBookingInformationEmail(Booking $booking, Appointme
 		try {
 			$failed = $this->mailer->send($message);
 			if (count($failed) > 0) {
-				$this->logger->warning('Mail delivery failed for some recipients.');
+				$this->logger->warning('Mail delivery failed for some recipients.', ['app' => 'calendar-appointments']);
 				foreach ($failed as $fail) {
-					$this->logger->debug('Failed to deliver email to ' . $fail);
+					$this->logger->debug('Failed to deliver email to ' . $fail, ['app' => 'calendar-appointments']);
 				}
 				throw new ServiceException('Could not send mail for recipient(s) ' . implode(', ', $failed));
 			}
 		} catch (Exception $ex) {
-			$this->logger->error('Could not send appointment organizer email: ' . $ex->getMessage(), ['exception' => $ex]);
+			$this->logger->error('Could not send appointment organizer email: ' . $ex->getMessage(), ['exception' => $ex, 'app' => 'calendar-appointments']);
 			throw new ServiceException('Could not send mail: ' . $ex->getMessage(), $ex->getCode(), $ex);
 		}
 	}
diff --git a/lib/Service/Appointments/SlotExtrapolator.php b/lib/Service/Appointments/SlotExtrapolator.php
@@ -26,17 +26,28 @@
 namespace OCA\Calendar\Service\Appointments;
 
 use OCA\Calendar\Db\AppointmentConfig;
+use Psr\Log\LoggerInterface;
 
 class SlotExtrapolator {
+
+	public function __construct(private LoggerInterface $logger) {
+
+	}
 	/**
 	 * @param AppointmentConfig $config
 	 * @param Interval[] $availabilityIntervals
-	 * @param int $to
 	 *
 	 * @return Interval[]
 	 */
 	public function extrapolate(AppointmentConfig $config,
 		array $availabilityIntervals): array {
+		$this->logger->debug('Intervals before extrapolating:' . count($availabilityIntervals), ['app' => 'calendar-appointments']);
+		if(empty($availabilityIntervals)) {
+			return [];
+		}
+		foreach ($availabilityIntervals as $availabilityInterval) {
+			$this->logger->debug('Interval start: ' . $availabilityInterval->getStart() . ', interval end: ' . $availabilityInterval->getEnd(), ['app' => 'calendar-appointments']);
+		}
 		$increment = $config->getIncrement();
 		$length = $config->getLength();
 		$slots = [];
@@ -50,6 +61,7 @@ public function extrapolate(AppointmentConfig $config,
 			}
 		}
 
+		$this->logger->debug('Slots after extrapolating:' . count($slots), ['app' => 'calendar-appointments']);
 		return $slots;
 	}
 }

Original file line number	Diff line number	Diff line change
`@@ -146,14 +146,14 @@ public function sendConfirmationEmail(Booking $booking, AppointmentConfig $confi`
`146`	`146`	`try {`
`147`	`147`	`$failed = $this->mailer->send($message);`
`148`	`148`	`if (count($failed) > 0) {`
`149`		`- $this->logger->warning('Mail delivery failed for some recipients.');`
	`149`	`+ $this->logger->warning('Mail delivery failed for some recipients.', ['app' => 'calendar-appointments']);`
`150`	`150`	`foreach ($failed as $fail) {`
`151`		`- $this->logger->debug('Failed to deliver email to ' . $fail);`
	`151`	`+ $this->logger->debug('Failed to deliver email to ' . $fail, ['app' => 'calendar-appointments']);`
`152`	`152`	`}`
`153`	`153`	`throw new ServiceException('Could not send mail for recipient(s) ' . implode(', ', $failed));`
`154`	`154`	`}`
`155`	`155`	`} catch (Exception $ex) {`
`156`		`- $this->logger->error($ex->getMessage(), ['exception' => $ex]);`
	`156`	`+ $this->logger->error($ex->getMessage(), ['exception' => $ex, 'app' => 'calendar-appointments']);`
`157`	`157`	`throw new ServiceException('Could not send mail: ' . $ex->getMessage(), $ex->getCode(), $ex);`
`158`	`158`	`}`
`159`	`159`	`}`
`@@ -215,14 +215,14 @@ public function sendBookingInformationEmail(Booking $booking, AppointmentConfig`
`215`	`215`	`try {`
`216`	`216`	`$failed = $this->mailer->send($message);`
`217`	`217`	`if (count($failed) > 0) {`
`218`		`- $this->logger->warning('Mail delivery failed for some recipients.');`
	`218`	`+ $this->logger->warning('Mail delivery failed for some recipients.', ['app' => 'calendar-appointments']);`
`219`	`219`	`foreach ($failed as $fail) {`
`220`		`- $this->logger->debug('Failed to deliver email to ' . $fail);`
	`220`	`+ $this->logger->debug('Failed to deliver email to ' . $fail, ['app' => 'calendar-appointments']);`
`221`	`221`	`}`
`222`	`222`	`throw new ServiceException('Could not send mail for recipient(s) ' . implode(', ', $failed));`
`223`	`223`	`}`
`224`	`224`	`} catch (Exception $ex) {`
`225`		`- $this->logger->error($ex->getMessage(), ['exception' => $ex]);`
	`225`	`+ $this->logger->error($ex->getMessage(), ['exception' => $ex, 'app' => 'calendar-appointments']);`
`226`	`226`	`throw new ServiceException('Could not send mail: ' . $ex->getMessage(), $ex->getCode(), $ex);`
`227`	`227`	`}`
`228`	`228`	`}`
`@@ -320,14 +320,14 @@ public function sendOrganizerBookingInformationEmail(Booking $booking, Appointme`
`320`	`320`	`try {`
`321`	`321`	`$failed = $this->mailer->send($message);`
`322`	`322`	`if (count($failed) > 0) {`
`323`		`- $this->logger->warning('Mail delivery failed for some recipients.');`
	`323`	`+ $this->logger->warning('Mail delivery failed for some recipients.', ['app' => 'calendar-appointments']);`
`324`	`324`	`foreach ($failed as $fail) {`
`325`		`- $this->logger->debug('Failed to deliver email to ' . $fail);`
	`325`	`+ $this->logger->debug('Failed to deliver email to ' . $fail, ['app' => 'calendar-appointments']);`
`326`	`326`	`}`
`327`	`327`	`throw new ServiceException('Could not send mail for recipient(s) ' . implode(', ', $failed));`
`328`	`328`	`}`
`329`	`329`	`} catch (Exception $ex) {`
`330`		`- $this->logger->error('Could not send appointment organizer email: ' . $ex->getMessage(), ['exception' => $ex]);`
	`330`	`+ $this->logger->error('Could not send appointment organizer email: ' . $ex->getMessage(), ['exception' => $ex, 'app' => 'calendar-appointments']);`
`331`	`331`	`throw new ServiceException('Could not send mail: ' . $ex->getMessage(), $ex->getCode(), $ex);`
`332`	`332`	`}`
`333`	`333`	`}`