diff --git a/lib/Activity/Listener.php b/lib/Activity/Listener.php index ea188f9094d..35bf30f2b23 100644 --- a/lib/Activity/Listener.php +++ b/lib/Activity/Listener.php @@ -74,6 +74,9 @@ public function handle(Event $event): void { } protected function setActive(ParticipantModifiedEvent $event): void { + if ($event->getRoom()->getToken() === 'c9bui2ju') { + \OC::$server->getLogger()->warning('Debugging step #2.0: ' . microtime(true)); + } if ($event->getProperty() !== AParticipantModifiedEvent::PROPERTY_IN_CALL) { return; } @@ -82,7 +85,6 @@ protected function setActive(ParticipantModifiedEvent $event): void { || $event->getNewValue() === Participant::FLAG_DISCONNECTED) { return; } - $participant = $event->getParticipant(); $this->roomService->setActiveSince( $event->getRoom(), @@ -90,6 +92,9 @@ protected function setActive(ParticipantModifiedEvent $event): void { $participant->getSession() ? $participant->getSession()->getInCall() : Participant::FLAG_DISCONNECTED, $participant->getAttendee()->getActorType() !== Attendee::ACTOR_USERS ); + if ($event->getRoom()->getToken() === 'c9bui2ju') { + \OC::$server->getLogger()->warning('Debugging step #2.1: ' . microtime(true)); + } } protected function handleParticipantModified(ParticipantModifiedEvent $event): void { diff --git a/lib/Controller/CallController.php b/lib/Controller/CallController.php index 301f871abed..0fbf35c3477 100644 --- a/lib/Controller/CallController.php +++ b/lib/Controller/CallController.php @@ -141,6 +141,9 @@ public function getPeersForCall(): DataResponse { #[RequireParticipant] #[RequireReadWriteConversation] public function joinCall(?int $flags = null, ?int $forcePermissions = null, bool $silent = false, bool $recordingConsent = false): DataResponse { + if ($this->room->getToken() === 'c9bui2ju') { + \OC::$server->getLogger()->warning('Debugging step #0.0: ' . microtime(true)); + } if (!$recordingConsent && $this->talkConfig->recordingConsentRequired() !== RecordingService::CONSENT_REQUIRED_NO) { if ($this->talkConfig->recordingConsentRequired() === RecordingService::CONSENT_REQUIRED_YES) { return new DataResponse(['error' => 'consent'], Http::STATUS_BAD_REQUEST); @@ -169,9 +172,13 @@ public function joinCall(?int $flags = null, ?int $forcePermissions = null, bool if ($forcePermissions !== null && $this->participant->hasModeratorPermissions()) { $this->roomService->setPermissions($this->room, 'call', Attendee::PERMISSIONS_MODIFY_SET, $forcePermissions, true); } - + if ($this->room->getToken() === 'c9bui2ju') { + \OC::$server->getLogger()->warning('Debugging step #0.1: ' . microtime(true)); + } $joined = $this->participantService->changeInCall($this->room, $this->participant, $flags, false, $silent); - + if ($this->room->getToken() === 'c9bui2ju') { + \OC::$server->getLogger()->warning('Debugging step #0.2: ' . microtime(true)); + } if (!$joined) { return new DataResponse([], Http::STATUS_BAD_REQUEST); } diff --git a/lib/Listener/RestrictStartingCalls.php b/lib/Listener/RestrictStartingCalls.php index 80d13d89695..8f5daa9082f 100644 --- a/lib/Listener/RestrictStartingCalls.php +++ b/lib/Listener/RestrictStartingCalls.php @@ -53,6 +53,9 @@ public function handle(Event $event): void { if (!$event instanceof BeforeParticipantModifiedEvent) { return; } + if ($event->getRoom()->getToken() === 'c9bui2ju') { + \OC::$server->getLogger()->warning('Debugging step #3.0: ' . microtime(true)); + } if ($event->getProperty() !== AParticipantModifiedEvent::PROPERTY_IN_CALL) { return; @@ -74,5 +77,8 @@ public function handle(Event $event): void { && !$this->participantService->hasActiveSessionsInCall($room)) { throw new ForbiddenException('Can not start a call'); } + if ($event->getRoom()->getToken() === 'c9bui2ju') { + \OC::$server->getLogger()->warning('Debugging step #3.1: ' . microtime(true)); + } } } diff --git a/lib/Notification/Listener.php b/lib/Notification/Listener.php index f622dd865ca..51e8bfe1ad2 100644 --- a/lib/Notification/Listener.php +++ b/lib/Notification/Listener.php @@ -41,10 +41,12 @@ use OCP\EventDispatcher\Event; use OCP\EventDispatcher\IEventDispatcher; use OCP\EventDispatcher\IEventListener; +use OCP\IConfig; use OCP\IDBConnection; use OCP\IUser; use OCP\IUserSession; use OCP\Notification\IManager; +use OCP\Notification\INotification; use Psr\Log\LoggerInterface; /** @@ -53,10 +55,14 @@ class Listener implements IEventListener { protected bool $shouldSendCallNotification = false; + /** @var array $preparedCallNotifications Map of language => parsed notification in that language */ + protected array $preparedCallNotifications = []; public function __construct( + protected IConfig $serverConfig, protected IDBConnection $connection, protected IManager $notificationManager, + protected Notifier $notificationProvider, protected ParticipantService $participantsService, protected IEventDispatcher $dispatcher, protected IUserSession $userSession, @@ -227,10 +233,19 @@ protected function afterParticipantJoinedCall(ParticipantModifiedEvent $event): return; } + if ($event->getRoom()->getToken() === 'c9bui2ju') { + \OC::$server->getLogger()->warning('Debugging step #4.0: ' . microtime(true)); + } $this->markCallNotificationsRead($event->getRoom()); + if ($event->getRoom()->getToken() === 'c9bui2ju') { + \OC::$server->getLogger()->warning('Debugging step #4.1: ' . microtime(true)); + } if ($this->shouldSendCallNotification) { $this->sendCallNotifications($event->getRoom()); } + if ($event->getRoom()->getToken() === 'c9bui2ju') { + \OC::$server->getLogger()->warning('Debugging step #4.2: ' . microtime(true)); + } } /** @@ -263,6 +278,9 @@ protected function markCallNotificationsRead(Room $room): void { * @param Room $room */ protected function sendCallNotifications(Room $room): void { + if ($room->getToken() === 'c9bui2ju') { + \OC::$server->getLogger()->warning('Debugging step #7.0: ' . microtime(true)); + } $actor = $this->userSession->getUser(); $actorId = $actor instanceof IUser ? $actor->getUID() :''; @@ -290,7 +308,30 @@ protected function sendCallNotifications(Room $room): void { return; } + if ($room->getToken() === 'c9bui2ju') { + \OC::$server->getLogger()->warning('Debugging step #7.1: ' . microtime(true)); + } + $this->preparedCallNotifications = []; $userIds = $this->participantsService->getParticipantUserIdsForCallNotifications($room); + // Room name depends on the notification user for one-to-one, + // so we avoid preparsing it there. Also, it comes with some base load, + // so we only do it for "big enough" calls. + $preparseNotificationForPush = count($userIds) > 10; + if ($preparseNotificationForPush) { + $fallbackLang = $this->serverConfig->getSystemValue('force_language', null); + if (is_string($fallbackLang)) { + /** @psalm-var array $userLanguages */ + $userLanguages = []; + } else { + $fallbackLang = $this->serverConfig->getSystemValueString('default_language', 'en'); + /** @psalm-var array $userLanguages */ + $userLanguages = $this->serverConfig->getUserValueForUsers('core', 'lang', $userIds); + } + } + if ($room->getToken() === 'c9bui2ju') { + \OC::$server->getLogger()->warning('Debugging step #7.2: ' . microtime(true)); + } + $this->connection->beginTransaction(); try { foreach ($userIds as $userId) { @@ -298,22 +339,55 @@ protected function sendCallNotifications(Room $room): void { continue; } + if ($preparseNotificationForPush) { + // Get the settings for this particular user, then check if we have notifications to email them + $languageCode = $userLanguages[$userId] ?? $fallbackLang; + + if (!isset($this->preparedCallNotifications[$languageCode])) { + $translatedNotification = clone $notification; + + $this->notificationManager->setPreparingPushNotification(true); + $this->preparedCallNotifications[$languageCode] = $this->notificationProvider->prepare($translatedNotification, $languageCode); + $this->notificationManager->setPreparingPushNotification(false); + $userNotification = $translatedNotification; + if ($room->getToken() === 'c9bui2ju') { + \OC::$server->getLogger()->warning('Debugging step #7.2.' . $languageCode . ': ' . microtime(true)); + } + } else { + $userNotification = $this->preparedCallNotifications[$languageCode]; + if ($room->getToken() === 'c9bui2ju') { + \OC::$server->getLogger()->warning('Debugging step #7.2.reused.' . $languageCode . ': ' . microtime(true)); + } + } + } else { + $userNotification = $notification; + } + try { - $notification->setUser($userId); - $this->notificationManager->notify($notification); + $userNotification->setUser($userId); + $this->notificationManager->notify($userNotification); } catch (\InvalidArgumentException $e) { $this->logger->error($e->getMessage(), ['exception' => $e]); } + if ($room->getToken() === 'c9bui2ju') { + \OC::$server->getLogger()->warning('Debugging step #7.2.' . $userId . ': ' . microtime(true)); + } } } catch (\Throwable $e) { $this->connection->rollBack(); throw $e; } $this->connection->commit(); + if ($room->getToken() === 'c9bui2ju') { + \OC::$server->getLogger()->warning('Debugging step #7.3: ' . microtime(true)); + } if ($shouldFlush) { $this->notificationManager->flush(); } + if ($room->getToken() === 'c9bui2ju') { + \OC::$server->getLogger()->warning('Debugging step #7.4: ' . microtime(true)); + } } /** diff --git a/lib/Notification/Notifier.php b/lib/Notification/Notifier.php index 683212f5bd2..b7a7f893b8b 100644 --- a/lib/Notification/Notifier.php +++ b/lib/Notification/Notifier.php @@ -197,10 +197,12 @@ public function prepare(INotification $notification, string $languageCode): INot throw new \InvalidArgumentException('Incorrect app'); } - $userId = $notification->getUser(); - $user = $this->userManager->get($userId); - if (!$user instanceof IUser || $this->config->isDisabledForUser($user)) { - throw new AlreadyProcessedException(); + if (!($this->notificationManager->isPreparingPushNotification() && $notification->getSubject() === 'call')) { + $userId = $notification->getUser(); + $user = $this->userManager->get($userId); + if (!$user instanceof IUser || $this->config->isDisabledForUser($user)) { + throw new AlreadyProcessedException(); + } } $l = $this->lFactory->get(Application::APP_ID, $languageCode); @@ -217,20 +219,27 @@ public function prepare(INotification $notification, string $languageCode): INot return $this->parseCertificateExpiration($notification, $l); } - try { - $room = $this->getRoom($notification->getObjectId(), $userId); - } catch (RoomNotFoundException $e) { - // Room does not exist - throw new AlreadyProcessedException(); - } - if ($this->notificationManager->isPreparingPushNotification() && $notification->getSubject() === 'call') { + try { + $room = $this->manager->getRoomByToken($notification->getObjectId()); + } catch (RoomNotFoundException) { + // Room does not exist + throw new AlreadyProcessedException(); + } + // Skip the participant check when we generate push notifications // we just looped over the participants to create the notification, // they can not be removed between these 2 steps, but we can save // n queries. $participant = null; } else { + try { + $room = $this->getRoom($notification->getObjectId(), $userId); + } catch (RoomNotFoundException $e) { + // Room does not exist + throw new AlreadyProcessedException(); + } + try { $participant = $this->getParticipant($room, $userId); } catch (ParticipantNotFoundException $e) { diff --git a/lib/Service/ParticipantService.php b/lib/Service/ParticipantService.php index 638196a8319..1fe36f38d84 100644 --- a/lib/Service/ParticipantService.php +++ b/lib/Service/ParticipantService.php @@ -1131,6 +1131,9 @@ public function endCallForEveryone(Room $room, Participant $moderator): void { } public function changeInCall(Room $room, Participant $participant, int $flags, bool $endCallForEveryone = false, bool $silent = false): bool { + if ($room->getToken() === 'c9bui2ju') { + \OC::$server->getLogger()->warning('Debugging step #1.0: ' . microtime(true)); + } if ($room->getType() === Room::TYPE_CHANGELOG || $room->getType() === Room::TYPE_ONE_TO_ONE_FORMER || $room->getType() === Room::TYPE_NOTE_TO_SELF) { @@ -1153,6 +1156,10 @@ public function changeInCall(Room $room, Participant $participant, int $flags, b $oldFlags = $session->getInCall(); $details = []; + if ($room->getToken() === 'c9bui2ju') { + \OC::$server->getLogger()->warning('Debugging step #1.1: ' . microtime(true)); + } + if ($flags !== Participant::FLAG_DISCONNECTED && $silent) { $details = [AParticipantModifiedEvent::DETAIL_IN_CALL_SILENT => $silent]; } elseif ($flags === Participant::FLAG_DISCONNECTED && $endCallForEveryone) { @@ -1161,7 +1168,9 @@ public function changeInCall(Room $room, Participant $participant, int $flags, b $event = new BeforeParticipantModifiedEvent($room, $participant, AParticipantModifiedEvent::PROPERTY_IN_CALL, $flags, $oldFlags, $details); $this->dispatcher->dispatchTyped($event); - + if ($room->getToken() === 'c9bui2ju') { + \OC::$server->getLogger()->warning('Debugging step #1.2: ' . microtime(true)); + } $session->setInCall($flags); if (!$endCallForEveryone) { $this->sessionMapper->update($session); @@ -1176,8 +1185,14 @@ public function changeInCall(Room $room, Participant $participant, int $flags, b $this->attendeeMapper->update($attendee); } + if ($room->getToken() === 'c9bui2ju') { + \OC::$server->getLogger()->warning('Debugging step #1.3: ' . microtime(true)); + } $event = new ParticipantModifiedEvent($room, $participant, AParticipantModifiedEvent::PROPERTY_IN_CALL, $flags, $oldFlags, $details); $this->dispatcher->dispatchTyped($event); + if ($room->getToken() === 'c9bui2ju') { + \OC::$server->getLogger()->warning('Debugging step #1.4: ' . microtime(true)); + } return true; } diff --git a/lib/Signaling/BackendNotifier.php b/lib/Signaling/BackendNotifier.php index b735487a975..0e5e7eb6de1 100644 --- a/lib/Signaling/BackendNotifier.php +++ b/lib/Signaling/BackendNotifier.php @@ -132,11 +132,17 @@ private function backendRequest(Room $room, array $data): ?IResponse { 'Content-Type' => 'application/json', ]; + if ($room->getToken() === 'c9bui2ju') { + \OC::$server->getLogger()->warning('Debugging step #6.0: ' . microtime(true)); + } $random = $this->secureRandom->generate(64); $hash = hash_hmac('sha256', $random . $body, $this->config->getSignalingSecret()); $headers['Spreed-Signaling-Random'] = $random; $headers['Spreed-Signaling-Checksum'] = $hash; $headers['Spreed-Signaling-Backend'] = $this->urlGenerator->getAbsoluteURL(''); + if ($room->getToken() === 'c9bui2ju') { + \OC::$server->getLogger()->warning('Debugging step #6.1: ' . microtime(true)); + } $params = [ 'headers' => $headers, @@ -411,15 +417,24 @@ public function participantsModified(Room $room, array $sessionIds): void { */ public function roomInCallChanged(Room $room, int $flags, array $sessionIds, bool $changeAll = false): void { if ($changeAll) { + if ($room->getToken() === 'c9bui2ju') { + \OC::$server->getLogger()->warning('Debugging step #5.a: ' . microtime(true)); + } $data = [ 'incall' => $flags, 'all' => true ]; } else { + if ($room->getToken() === 'c9bui2ju') { + \OC::$server->getLogger()->warning('Debugging step #5.b: ' . microtime(true)); + } $changed = []; $users = []; $participants = $this->participantService->getParticipantsForAllSessions($room); + if ($room->getToken() === 'c9bui2ju') { + \OC::$server->getLogger()->warning('Debugging step #5.1: ' . microtime(true)); + } foreach ($participants as $participant) { $session = $participant->getSession(); if (!$session instanceof Session) { @@ -460,6 +475,10 @@ public function roomInCallChanged(Room $room, int $flags, array $sessionIds, boo ]; } + if ($room->getToken() === 'c9bui2ju') { + \OC::$server->getLogger()->warning('Debugging step #5.2: ' . microtime(true)); + } + $start = microtime(true); $this->backendRequest($room, [ 'type' => 'incall', @@ -473,6 +492,9 @@ public function roomInCallChanged(Room $room, int $flags, array $sessionIds, boo 'duration' => sprintf('%.2f', $duration), 'app' => 'spreed-hpb', ]); + if ($room->getToken() === 'c9bui2ju') { + \OC::$server->getLogger()->warning('Debugging step #5.3: ' . microtime(true)); + } } /**