From 4b5a743645dd245cea11b32ff35a7df50b51016d Mon Sep 17 00:00:00 2001 From: Michael Date: Sat, 14 May 2022 05:38:01 +0000 Subject: [PATCH 1/8] Handle timeout --- src/Util/HTTPSignature.php | 31 ++++++++++++++++++++++++------- src/Worker/APDelivery.php | 33 ++++++++++++++++++++++++++------- 2 files changed, 50 insertions(+), 14 deletions(-) diff --git a/src/Util/HTTPSignature.php b/src/Util/HTTPSignature.php index db1d7a2799..b76c12f591 100644 --- a/src/Util/HTTPSignature.php +++ b/src/Util/HTTPSignature.php @@ -29,6 +29,7 @@ use Friendica\Model\APContact; use Friendica\Model\Contact; use Friendica\Model\ItemURI; use Friendica\Model\User; +use Friendica\Network\HTTPClient\Capability\ICanHandleHttpResponses; use Friendica\Network\HTTPClient\Client\HttpClientAccept; use Friendica\Network\HTTPClient\Client\HttpClientOptions; @@ -264,21 +265,21 @@ class HTTPSignature */ /** - * Transmit given data to a target for a user + * Post given data to a target for a user, returns the result class * * @param array $data Data that is about to be send * @param string $target The URL of the inbox * @param integer $uid User id of the sender * - * @return boolean Was the transmission successful? + * @return ICanHandleHttpResponses * @throws \Friendica\Network\HTTPException\InternalServerErrorException */ - public static function transmit($data, $target, $uid) + public static function post(array $data, string $target, int $uid): ICanHandleHttpResponses { $owner = User::getOwnerDataById($uid); if (!$owner) { - return; + return null; } $content = json_encode($data, JSON_UNESCAPED_SLASHES | JSON_UNESCAPED_UNICODE); @@ -310,11 +311,27 @@ class HTTPSignature Logger::info('Transmit to ' . $target . ' returned ' . $return_code); - $success = ($return_code >= 200) && ($return_code <= 299); + self::setInboxStatus($target, ($return_code >= 200) && ($return_code <= 299)); - self::setInboxStatus($target, $success); + return $postResult; + } - return $success; + /** + * Transmit given data to a target for a user + * + * @param array $data Data that is about to be send + * @param string $target The URL of the inbox + * @param integer $uid User id of the sender + * + * @return boolean Was the transmission successful? + * @throws \Friendica\Network\HTTPException\InternalServerErrorException + */ + public static function transmit(array $data, string $target, int $uid): bool + { + $postResult = self::post($data, $target, $uid); + $return_code = $postResult->getReturnCode(); + + return ($return_code >= 200) && ($return_code <= 299); } /** diff --git a/src/Worker/APDelivery.php b/src/Worker/APDelivery.php index df9df8128a..e06fca12dc 100644 --- a/src/Worker/APDelivery.php +++ b/src/Worker/APDelivery.php @@ -68,11 +68,12 @@ class APDelivery Logger::info('Invoked', ['cmd' => $cmd, 'inbox' => $inbox, 'id' => $item_id, 'uri-id' => $uri_id, 'uid' => $uid]); if (empty($uri_id)) { - $result = self::deliver($inbox); + $result = self::deliver($inbox); $success = $result['success']; $uri_ids = $result['uri_ids']; } else { - $success = self::deliverToInbox($cmd, $item_id, $inbox, $uid, $receivers, $uri_id); + $result = self::deliverToInbox($cmd, $item_id, $inbox, $uid, $receivers, $uri_id); + $success = $result['success']; $uri_ids = [$uri_id]; } @@ -84,13 +85,25 @@ class APDelivery } } - private static function deliver(string $inbox) + private static function deliver(string $inbox):array { $uri_ids = []; $posts = Post\Delivery::selectForInbox($inbox); + $timeout = false; foreach ($posts as $post) { - if (!self::deliverToInbox($post['command'], 0, $inbox, $post['uid'], $post['receivers'], $post['uri-id'])) { + if (!$timeout) { + $result = self::deliverToInbox($post['command'], 0, $inbox, $post['uid'], $post['receivers'], $post['uri-id']); + + if ($result['timeout']) { + // In a timeout situation we assume that every delivery to that inbox will time out. + // So we set the flag and try all deliveries at a later time. + Logger::debug('Inbox delivery has a time out', ['inbox' => $inbox]); + $timeout = true; + } + } + + if ($timeout || !$result['success']) { $uri_ids[] = $post['uri-id']; } } @@ -99,7 +112,7 @@ class APDelivery return ['success' => empty($uri_ids), 'uri_ids' => $uri_ids]; } - private static function deliverToInbox(string $cmd, int $item_id, string $inbox, int $uid, array $receivers, int $uri_id) + private static function deliverToInbox(string $cmd, int $item_id, string $inbox, int $uid, array $receivers, int $uri_id): array { if (empty($item_id) && !empty($uri_id) && !empty($uid)) { $item = Post::selectFirst(['id', 'parent', 'origin'], ['uri-id' => $uri_id, 'uid' => [$uid, 0]], ['order' => ['uid' => true]]); @@ -113,6 +126,7 @@ class APDelivery } $success = true; + $timeout = false; if ($cmd == Delivery::MAIL) { $data = ActivityPub\Transmitter::createActivityFromMail($item_id); @@ -132,7 +146,12 @@ class APDelivery } else { $data = ActivityPub\Transmitter::createCachedActivityFromItem($item_id); if (!empty($data)) { - $success = HTTPSignature::transmit($data, $inbox, $uid); + $response = HTTPSignature::post($data, $inbox, $uid); + $success = $response->isSuccess(); + $timeout = $response->isTimeout(); + if (!$success) { + Logger::debug('Delivery failed', ['retcode' => $response->getReturnCode(), 'timeout' => $timeout, 'uri-id' => $uri_id, 'uid' => $uid, 'item_id' => $item_id, 'cmd' => $cmd, 'inbox' => $inbox]); + } if ($uri_id) { if ($success) { Post\Delivery::remove($uri_id, $inbox); @@ -151,7 +170,7 @@ class APDelivery Post\DeliveryData::incrementQueueDone($uri_id, Post\DeliveryData::ACTIVITYPUB); } - return $success; + return ['success' => $success, 'timeout' => $timeout]; } private static function setSuccess(array $receivers, bool $success) From 30bcb24af7a416be14bff255eb1a1514b03e73ae Mon Sep 17 00:00:00 2001 From: Michael Date: Sat, 14 May 2022 06:06:38 +0000 Subject: [PATCH 2/8] Display the runtime --- src/Worker/APDelivery.php | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/src/Worker/APDelivery.php b/src/Worker/APDelivery.php index e06fca12dc..e341787e21 100644 --- a/src/Worker/APDelivery.php +++ b/src/Worker/APDelivery.php @@ -146,11 +146,13 @@ class APDelivery } else { $data = ActivityPub\Transmitter::createCachedActivityFromItem($item_id); if (!empty($data)) { + $timestamp = microtime(true); $response = HTTPSignature::post($data, $inbox, $uid); + $runtime = microtime(true) - $timestamp; $success = $response->isSuccess(); $timeout = $response->isTimeout(); if (!$success) { - Logger::debug('Delivery failed', ['retcode' => $response->getReturnCode(), 'timeout' => $timeout, 'uri-id' => $uri_id, 'uid' => $uid, 'item_id' => $item_id, 'cmd' => $cmd, 'inbox' => $inbox]); + Logger::debug('Delivery failed', ['retcode' => $response->getReturnCode(), 'timeout' => $timeout, 'runtime' => round($runtime, 3), 'uri-id' => $uri_id, 'uid' => $uid, 'item_id' => $item_id, 'cmd' => $cmd, 'inbox' => $inbox]); } if ($uri_id) { if ($success) { From a8839517fe20402fbfecb340d5f1b2ddbaa21227 Mon Sep 17 00:00:00 2001 From: Michael Date: Sat, 14 May 2022 06:36:43 +0000 Subject: [PATCH 3/8] Fix workerqueue entries with wrong priority --- src/Core/Worker.php | 2 +- src/Model/Item.php | 4 ++-- 2 files changed, 3 insertions(+), 3 deletions(-) diff --git a/src/Core/Worker.php b/src/Core/Worker.php index 45811d40a7..e29cf765a4 100644 --- a/src/Core/Worker.php +++ b/src/Core/Worker.php @@ -1322,7 +1322,7 @@ class Worker $found = DBA::exists('workerqueue', ['command' => $command, 'parameter' => $parameters, 'done' => false]); $added = 0; - if (!in_array($priority, PRIORITIES)) { + if (!is_int($priority) || !in_array($priority, PRIORITIES)) { Logger::warning('Invalid priority', ['priority' => $priority, 'command' => $command, 'callstack' => System::callstack(20)]); $priority = PRIORITY_MEDIUM; } diff --git a/src/Model/Item.php b/src/Model/Item.php index 492442188a..a1cccb2544 100644 --- a/src/Model/Item.php +++ b/src/Model/Item.php @@ -725,7 +725,7 @@ class Item return GRAVITY_UNKNOWN; // Should not happen } - public static function insert(array $item, bool $notify = false, bool $post_local = true) + public static function insert(array $item, int $notify = 0, bool $post_local = true) { $orig_item = $item; @@ -739,7 +739,7 @@ class Item $item['protocol'] = Conversation::PARCEL_DIRECT; $item['direction'] = Conversation::PUSH; - if (in_array($notify, PRIORITIES)) { + if (is_int($notify) && in_array($notify, PRIORITIES)) { $priority = $notify; } } else { From f8d929d94e4485ecd1457b0accdef97aa8f3c95b Mon Sep 17 00:00:00 2001 From: Michael Date: Sat, 14 May 2022 09:53:12 +0000 Subject: [PATCH 4/8] Ensure to set the network timeout --- src/Util/HTTPSignature.php | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/Util/HTTPSignature.php b/src/Util/HTTPSignature.php index b76c12f591..4a4f6a5710 100644 --- a/src/Util/HTTPSignature.php +++ b/src/Util/HTTPSignature.php @@ -306,7 +306,7 @@ class HTTPSignature $headers['Content-Type'] = 'application/activity+json'; - $postResult = DI::httpClient()->post($target, $content, $headers); + $postResult = DI::httpClient()->post($target, $content, $headers, DI::config()->get('system', 'curl_timeout')); $return_code = $postResult->getReturnCode(); Logger::info('Transmit to ' . $target . ' returned ' . $return_code); From 43dbd1c396d7b3baedfea909a43e808d57785b98 Mon Sep 17 00:00:00 2001 From: Michael Date: Sat, 14 May 2022 11:09:59 +0000 Subject: [PATCH 5/8] Add additional timeout checks --- src/Worker/APDelivery.php | 10 ++++++++++ 1 file changed, 10 insertions(+) diff --git a/src/Worker/APDelivery.php b/src/Worker/APDelivery.php index e341787e21..ce39398374 100644 --- a/src/Worker/APDelivery.php +++ b/src/Worker/APDelivery.php @@ -23,6 +23,7 @@ namespace Friendica\Worker; use Friendica\Core\Logger; use Friendica\Core\Worker; +use Friendica\DI; use Friendica\Model\Contact; use Friendica\Model\GServer; use Friendica\Model\Post; @@ -152,6 +153,15 @@ class APDelivery $success = $response->isSuccess(); $timeout = $response->isTimeout(); if (!$success) { + $xrd_timeout = DI::config()->get('system', 'xrd_timeout'); + if (!$timeout && $xrd_timeout && ($runtime > $xrd_timeout)) { + $timeout = true; + } + $curl_timeout = DI::config()->get('system', 'curl_timeout'); + if (!$timeout && $curl_timeout && ($runtime > $curl_timeout)) { + $timeout = true; + } + Logger::debug('Delivery failed', ['retcode' => $response->getReturnCode(), 'timeout' => $timeout, 'runtime' => round($runtime, 3), 'uri-id' => $uri_id, 'uid' => $uid, 'item_id' => $item_id, 'cmd' => $cmd, 'inbox' => $inbox]); } if ($uri_id) { From fbdb73cdd6dc2c274fb7273b39f71d900fd20fa2 Mon Sep 17 00:00:00 2001 From: Michael Date: Sat, 14 May 2022 11:18:48 +0000 Subject: [PATCH 6/8] Improved log levels --- src/Worker/APDelivery.php | 34 ++++++++++++++++++---------------- 1 file changed, 18 insertions(+), 16 deletions(-) diff --git a/src/Worker/APDelivery.php b/src/Worker/APDelivery.php index ce39398374..ba0a36be80 100644 --- a/src/Worker/APDelivery.php +++ b/src/Worker/APDelivery.php @@ -66,7 +66,7 @@ class APDelivery return; } - Logger::info('Invoked', ['cmd' => $cmd, 'inbox' => $inbox, 'id' => $item_id, 'uri-id' => $uri_id, 'uid' => $uid]); + Logger::debug('Invoked', ['cmd' => $cmd, 'inbox' => $inbox, 'id' => $item_id, 'uri-id' => $uri_id, 'uid' => $uid]); if (empty($uri_id)) { $result = self::deliver($inbox); @@ -99,7 +99,7 @@ class APDelivery if ($result['timeout']) { // In a timeout situation we assume that every delivery to that inbox will time out. // So we set the flag and try all deliveries at a later time. - Logger::debug('Inbox delivery has a time out', ['inbox' => $inbox]); + Logger::info('Inbox delivery has a time out', ['inbox' => $inbox]); $timeout = true; } } @@ -118,7 +118,7 @@ class APDelivery if (empty($item_id) && !empty($uri_id) && !empty($uid)) { $item = Post::selectFirst(['id', 'parent', 'origin'], ['uri-id' => $uri_id, 'uid' => [$uid, 0]], ['order' => ['uid' => true]]); if (empty($item['id'])) { - Logger::debug('Item not found, removing delivery', ['uri-id' => $uri_id, 'uid' => $uid, 'cmd' => $cmd, 'inbox' => $inbox]); + Logger::notice('Item not found, removing delivery', ['uri-id' => $uri_id, 'uid' => $uid, 'cmd' => $cmd, 'inbox' => $inbox]); Post\Delivery::remove($uri_id, $inbox); return true; } else { @@ -148,21 +148,23 @@ class APDelivery $data = ActivityPub\Transmitter::createCachedActivityFromItem($item_id); if (!empty($data)) { $timestamp = microtime(true); - $response = HTTPSignature::post($data, $inbox, $uid); - $runtime = microtime(true) - $timestamp; - $success = $response->isSuccess(); - $timeout = $response->isTimeout(); + $response = HTTPSignature::post($data, $inbox, $uid); + $runtime = microtime(true) - $timestamp; + $success = $response->isSuccess(); + $timeout = $response->isTimeout(); if (!$success) { - $xrd_timeout = DI::config()->get('system', 'xrd_timeout'); - if (!$timeout && $xrd_timeout && ($runtime > $xrd_timeout)) { - $timeout = true; - } - $curl_timeout = DI::config()->get('system', 'curl_timeout'); - if (!$timeout && $curl_timeout && ($runtime > $curl_timeout)) { - $timeout = true; + if ($response->getReturnCode() == 500) { + $xrd_timeout = DI::config()->get('system', 'xrd_timeout'); + if (!$timeout && $xrd_timeout && ($runtime > $xrd_timeout)) { + $timeout = true; + } + $curl_timeout = DI::config()->get('system', 'curl_timeout'); + if (!$timeout && $curl_timeout && ($runtime > $curl_timeout)) { + $timeout = true; + } } - Logger::debug('Delivery failed', ['retcode' => $response->getReturnCode(), 'timeout' => $timeout, 'runtime' => round($runtime, 3), 'uri-id' => $uri_id, 'uid' => $uid, 'item_id' => $item_id, 'cmd' => $cmd, 'inbox' => $inbox]); + Logger::info('Delivery failed', ['retcode' => $response->getReturnCode(), 'timeout' => $timeout, 'runtime' => round($runtime, 3), 'uri-id' => $uri_id, 'uid' => $uid, 'item_id' => $item_id, 'cmd' => $cmd, 'inbox' => $inbox]); } if ($uri_id) { if ($success) { @@ -176,7 +178,7 @@ class APDelivery self::setSuccess($receivers, $success); - Logger::info('Delivered', ['uri-id' => $uri_id, 'uid' => $uid, 'item_id' => $item_id, 'cmd' => $cmd, 'inbox' => $inbox, 'success' => $success]); + Logger::debug('Delivered', ['uri-id' => $uri_id, 'uid' => $uid, 'item_id' => $item_id, 'cmd' => $cmd, 'inbox' => $inbox, 'success' => $success]); if ($success && in_array($cmd, [Delivery::POST])) { Post\DeliveryData::incrementQueueDone($uri_id, Post\DeliveryData::ACTIVITYPUB); From 689b71c6962c25e63abc717d465016a3021b68c9 Mon Sep 17 00:00:00 2001 From: Michael Date: Sat, 14 May 2022 11:34:00 +0000 Subject: [PATCH 7/8] Added check for server failure --- src/Worker/APDelivery.php | 56 ++++++++++++++++++++------------------- 1 file changed, 29 insertions(+), 27 deletions(-) diff --git a/src/Worker/APDelivery.php b/src/Worker/APDelivery.php index ba0a36be80..9e2f259f34 100644 --- a/src/Worker/APDelivery.php +++ b/src/Worker/APDelivery.php @@ -88,28 +88,28 @@ class APDelivery private static function deliver(string $inbox):array { - $uri_ids = []; - $posts = Post\Delivery::selectForInbox($inbox); - $timeout = false; + $uri_ids = []; + $posts = Post\Delivery::selectForInbox($inbox); + $serverfail = false; foreach ($posts as $post) { - if (!$timeout) { + if (!$serverfail) { $result = self::deliverToInbox($post['command'], 0, $inbox, $post['uid'], $post['receivers'], $post['uri-id']); - if ($result['timeout']) { + if ($result['serverfailure']) { // In a timeout situation we assume that every delivery to that inbox will time out. // So we set the flag and try all deliveries at a later time. - Logger::info('Inbox delivery has a time out', ['inbox' => $inbox]); - $timeout = true; + Logger::info('Inbox delivery has a server failure', ['inbox' => $inbox]); + $serverfail = true; } } - if ($timeout || !$result['success']) { + if ($serverfail || !$result['success']) { $uri_ids[] = $post['uri-id']; } } - Logger::debug('Inbox delivery done', ['inbox' => $inbox, 'posts' => count($posts), 'failed' => count($uri_ids)]); + Logger::debug('Inbox delivery done', ['inbox' => $inbox, 'posts' => count($posts), 'failed' => count($uri_ids), 'serverfailure' => $serverfail]); return ['success' => empty($uri_ids), 'uri_ids' => $uri_ids]; } @@ -126,8 +126,8 @@ class APDelivery } } - $success = true; - $timeout = false; + $success = true; + $serverfail = false; if ($cmd == Delivery::MAIL) { $data = ActivityPub\Transmitter::createActivityFromMail($item_id); @@ -147,24 +147,26 @@ class APDelivery } else { $data = ActivityPub\Transmitter::createCachedActivityFromItem($item_id); if (!empty($data)) { - $timestamp = microtime(true); - $response = HTTPSignature::post($data, $inbox, $uid); - $runtime = microtime(true) - $timestamp; - $success = $response->isSuccess(); - $timeout = $response->isTimeout(); + $timestamp = microtime(true); + $response = HTTPSignature::post($data, $inbox, $uid); + $runtime = microtime(true) - $timestamp; + $success = $response->isSuccess(); + $serverfail = $response->isTimeout(); if (!$success) { - if ($response->getReturnCode() == 500) { - $xrd_timeout = DI::config()->get('system', 'xrd_timeout'); - if (!$timeout && $xrd_timeout && ($runtime > $xrd_timeout)) { - $timeout = true; - } - $curl_timeout = DI::config()->get('system', 'curl_timeout'); - if (!$timeout && $curl_timeout && ($runtime > $curl_timeout)) { - $timeout = true; - } + if (!$serverfail && ($response->getReturnCode() == 500)) { + $serverfail = true; } - Logger::info('Delivery failed', ['retcode' => $response->getReturnCode(), 'timeout' => $timeout, 'runtime' => round($runtime, 3), 'uri-id' => $uri_id, 'uid' => $uid, 'item_id' => $item_id, 'cmd' => $cmd, 'inbox' => $inbox]); + $xrd_timeout = DI::config()->get('system', 'xrd_timeout'); + if (!$serverfail && $xrd_timeout && ($runtime > $xrd_timeout)) { + $serverfail = true; + } + $curl_timeout = DI::config()->get('system', 'curl_timeout'); + if (!$serverfail && $curl_timeout && ($runtime > $curl_timeout)) { + $serverfail = true; + } + + Logger::info('Delivery failed', ['retcode' => $response->getReturnCode(), 'serverfailure' => $serverfail, 'runtime' => round($runtime, 3), 'uri-id' => $uri_id, 'uid' => $uid, 'item_id' => $item_id, 'cmd' => $cmd, 'inbox' => $inbox]); } if ($uri_id) { if ($success) { @@ -184,7 +186,7 @@ class APDelivery Post\DeliveryData::incrementQueueDone($uri_id, Post\DeliveryData::ACTIVITYPUB); } - return ['success' => $success, 'timeout' => $timeout]; + return ['success' => $success, 'serverfailure' => $serverfail]; } private static function setSuccess(array $receivers, bool $success) From f0bfa9a6901dfbdcd0383657a1cbac00a47991aa Mon Sep 17 00:00:00 2001 From: Michael Date: Sat, 14 May 2022 13:49:01 +0000 Subject: [PATCH 8/8] Each 5xx error is a server fail --- src/Worker/APDelivery.php | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/Worker/APDelivery.php b/src/Worker/APDelivery.php index 9e2f259f34..051bde0a0c 100644 --- a/src/Worker/APDelivery.php +++ b/src/Worker/APDelivery.php @@ -153,7 +153,7 @@ class APDelivery $success = $response->isSuccess(); $serverfail = $response->isTimeout(); if (!$success) { - if (!$serverfail && ($response->getReturnCode() == 500)) { + if (!$serverfail && ($response->getReturnCode() >= 500) && ($response->getReturnCode() <= 599)) { $serverfail = true; }