From 8a4700d09542db93564e108651bdf44730a50453 Mon Sep 17 00:00:00 2001 From: Jordan Schulz Date: Mon, 28 Aug 2023 18:36:07 -0500 Subject: [PATCH 1/4] Catch down network exception and non-object responses in fetch --- src/Collections/TerminusCollection.php | 21 ++++++++++++++++++++- src/Request/Request.php | 10 +++++++++- 2 files changed, 29 insertions(+), 2 deletions(-) diff --git a/src/Collections/TerminusCollection.php b/src/Collections/TerminusCollection.php index da2ffb2ea..4788fa410 100644 --- a/src/Collections/TerminusCollection.php +++ b/src/Collections/TerminusCollection.php @@ -9,15 +9,18 @@ use Pantheon\Terminus\Models\TerminusModel; use Pantheon\Terminus\Request\RequestAwareInterface; use Pantheon\Terminus\Request\RequestAwareTrait; +use Psr\Log\LoggerAwareInterface; +use Psr\Log\LoggerAwareTrait; /** * Class TerminusCollection * @package Pantheon\Terminus\Collections */ -abstract class TerminusCollection implements ContainerAwareInterface, RequestAwareInterface +abstract class TerminusCollection implements ContainerAwareInterface, RequestAwareInterface, LoggerAwareInterface { use ContainerAwareTrait; use RequestAwareTrait; + use LoggerAwareTrait; /** * @var array @@ -91,6 +94,22 @@ public function all() public function fetch() { foreach ($this->getData() as $id => $model_data) { + if (!is_object($model_data)) { + // For some reason I can't replicate, occasionally $model_data is just a string here. + $trace = debug_backtrace(); + $error_message = "Fetch failed {file}:{line} model_data expected as object but returned as {type}."; + $context = [ + 'file' => $trace[0]['file'], + 'line' => $trace[0]['line'], + 'type' => gettype($model_data), + ]; + if (is_string($model_data)) { + $error_message .= " String value: {string}"; + $context['string'] = strlen($model_data) > 250 ? substr($model_data, 0, 250) . '...' : $model_data; + } + $this->logger->error($error_message, $context); + break; + } if (!isset($model_data->id)) { $model_data->id = $id; } diff --git a/src/Request/Request.php b/src/Request/Request.php index b045fd13b..be42f268b 100755 --- a/src/Request/Request.php +++ b/src/Request/Request.php @@ -244,12 +244,20 @@ private function createRetryDecider(): callable } } + if (is_object($response) && is_object($response->getBody()) && $response->getBody()->getContents() !== '') { + $error = $response->getBody()->getContents(); + } elseif (null !== $exception && '' != $exception->getMessage()) { + $error = $exception->getMessage(); + } else { + $error = "Undefined"; + } + $this->logger->error( "HTTP request {method} {uri} has failed with error {error}.", [ 'method' => $request->getMethod(), 'uri' => $request->getUri(), - 'error' => $response->getBody()->getContents(), + 'error' => $error, ] ); From 7857a372d61f013d6d238cfd058dfa272d6c0785 Mon Sep 17 00:00:00 2001 From: Jordan Schulz Date: Mon, 11 Sep 2023 16:37:48 -0700 Subject: [PATCH 2/4] Handle more unexpected data types --- src/Collections/TerminusCollection.php | 12 +++++++----- 1 file changed, 7 insertions(+), 5 deletions(-) diff --git a/src/Collections/TerminusCollection.php b/src/Collections/TerminusCollection.php index 4788fa410..a034b7af6 100644 --- a/src/Collections/TerminusCollection.php +++ b/src/Collections/TerminusCollection.php @@ -96,17 +96,19 @@ public function fetch() foreach ($this->getData() as $id => $model_data) { if (!is_object($model_data)) { // For some reason I can't replicate, occasionally $model_data is just a string here. - $trace = debug_backtrace(); + $bad_data = print_r($model_data, true); + if (is_string($bad_data) && strlen($bad_data) > 250) { + $bad_data = substr($bad_data, 0, 250) . ' ...'; + } $error_message = "Fetch failed {file}:{line} model_data expected as object but returned as {type}."; + $error_message .= "\nUnexpected value: {bad_data}"; + $trace = debug_backtrace(); $context = [ 'file' => $trace[0]['file'], 'line' => $trace[0]['line'], 'type' => gettype($model_data), + 'bad_data' => $bad_data ]; - if (is_string($model_data)) { - $error_message .= " String value: {string}"; - $context['string'] = strlen($model_data) > 250 ? substr($model_data, 0, 250) . '...' : $model_data; - } $this->logger->error($error_message, $context); break; } From b62cbb97d027a0889fd7c8eac9396ebe4a842223 Mon Sep 17 00:00:00 2001 From: Brian Weaver <87093053+namespacebrian@users.noreply.github.com> Date: Wed, 20 Sep 2023 16:02:15 -0400 Subject: [PATCH 3/4] Address comments on #2492 (#2501) * Adjust handling of TerminusCollection items lacking useful data * Add comment clarifying handling of null response object --- src/Collections/TerminusCollection.php | 12 ++++++++++-- src/Request/Request.php | 1 + 2 files changed, 11 insertions(+), 2 deletions(-) diff --git a/src/Collections/TerminusCollection.php b/src/Collections/TerminusCollection.php index a034b7af6..c2c427d0a 100644 --- a/src/Collections/TerminusCollection.php +++ b/src/Collections/TerminusCollection.php @@ -109,8 +109,16 @@ public function fetch() 'type' => gettype($model_data), 'bad_data' => $bad_data ]; - $this->logger->error($error_message, $context); - break; + + // verbose logging for debugging + $this->logger->debug($error_message, $context); + + // less information for more user-facing messages, but a problem has occurred and we're skipping this + // item so we should still surface a user-facing message + $this->logger->warn("Model data missing for {id}", ['id' => $id,]); + + // skip this item since it lacks useful data + continue; } if (!isset($model_data->id)) { $model_data->id = $id; diff --git a/src/Request/Request.php b/src/Request/Request.php index be42f268b..1ec7274a4 100755 --- a/src/Request/Request.php +++ b/src/Request/Request.php @@ -244,6 +244,7 @@ private function createRetryDecider(): callable } } + // It's been observed in the wild that sometimes $response is null. Get a different error message in that case. if (is_object($response) && is_object($response->getBody()) && $response->getBody()->getContents() !== '') { $error = $response->getBody()->getContents(); } elseif (null !== $exception && '' != $exception->getMessage()) { From 4e9fc5a01628a7368e05b8f26075241dd42189cb Mon Sep 17 00:00:00 2001 From: Jordan Schulz Date: Fri, 22 Sep 2023 16:08:25 -0700 Subject: [PATCH 4/4] Variable and comment cleanup --- src/Collections/TerminusCollection.php | 18 ++++++++++-------- src/Request/Request.php | 2 +- 2 files changed, 11 insertions(+), 9 deletions(-) diff --git a/src/Collections/TerminusCollection.php b/src/Collections/TerminusCollection.php index c2c427d0a..33130314b 100644 --- a/src/Collections/TerminusCollection.php +++ b/src/Collections/TerminusCollection.php @@ -95,19 +95,21 @@ public function fetch() { foreach ($this->getData() as $id => $model_data) { if (!is_object($model_data)) { - // For some reason I can't replicate, occasionally $model_data is just a string here. - $bad_data = print_r($model_data, true); - if (is_string($bad_data) && strlen($bad_data) > 250) { - $bad_data = substr($bad_data, 0, 250) . ' ...'; + // This should always be an object, however occasionally it is returning as a string + // We need more information about what it is and to handle the error + $model_data_str = print_r($model_data, true); + $error_maxlength = 250; + if (is_string($model_data_str) && strlen($model_data_str) > $error_maxlength) { + $model_data_str = substr($model_data_str, 0, $error_maxlength) . ' ...'; } - $error_message = "Fetch failed {file}:{line} model_data expected as object but returned as {type}."; - $error_message .= "\nUnexpected value: {bad_data}"; + $error_message = "Fetch failed {file}:{line} \$model_data expected as object but returned as {type}."; + $error_message .= "\nUnexpected value: {model_data_str}"; $trace = debug_backtrace(); $context = [ 'file' => $trace[0]['file'], 'line' => $trace[0]['line'], 'type' => gettype($model_data), - 'bad_data' => $bad_data + 'model_data_str' => $model_data_str ]; // verbose logging for debugging @@ -115,7 +117,7 @@ public function fetch() // less information for more user-facing messages, but a problem has occurred and we're skipping this // item so we should still surface a user-facing message - $this->logger->warn("Model data missing for {id}", ['id' => $id,]); + $this->logger->warning("Model data missing for {id}", ['id' => $id,]); // skip this item since it lacks useful data continue; diff --git a/src/Request/Request.php b/src/Request/Request.php index 1ec7274a4..b2525b8df 100755 --- a/src/Request/Request.php +++ b/src/Request/Request.php @@ -244,7 +244,7 @@ private function createRetryDecider(): callable } } - // It's been observed in the wild that sometimes $response is null. Get a different error message in that case. + // Response can be null if there is a network disconnect. Get a different error message in that case. if (is_object($response) && is_object($response->getBody()) && $response->getBody()->getContents() !== '') { $error = $response->getBody()->getContents(); } elseif (null !== $exception && '' != $exception->getMessage()) {