Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Elastic APM PHP Agent SerializationException due to malformed UTF-8 characters #945

Closed
Yourcloud-host opened this issue May 4, 2023 · 12 comments · Fixed by #1120
Closed
Labels
agent-php bug Something isn't working

Comments

@Yourcloud-host
Copy link

We have encountered a SerializationException error with the Elastic APM PHP Agent when using it alongside the Wordfence plugins in our WordPress installation. The error message indicates that there are malformed UTF-8 characters in the data being processed by the agent, which causes the serialization to JSON format to fail.

Here is the relevant error message:
[ERROR] [Interception] [InterceptionManager.php:178] [interceptedCallPostHook] postHook has let a Throwable to escape {"throwable":{"type":"Elastic\Apm\Impl\BackendComm\SerializationException","value_as_string":"Elastic\Apm\Impl\Util\JsonException: json_encode() failed. json_last_error_msg(): Malformed UTF-8 characters, possibly incorrectly encoded.

\n#0 /opt/elastic/apm-agent-php/src/ElasticApm/Impl/BackendComm/SerializationUtil.php(55): Elastic\Apm\Impl\Util\JsonUtil::encode(Object(Elastic\Apm\Impl\Span))
\n#1 /opt/elastic/apm-agent-php/src/ElasticApm/Impl/BackendComm/EventSender.php(114): Elastic\Apm\Impl\BackendComm\SerializationUtil::serializeAsJson(Object(Elastic\Apm\Impl\Span))
\n#2 /opt/elastic/apm-agent-php/src/ElasticApm/Impl/Tracer.php(485): Elastic\Apm\Impl\BackendComm\EventSender->consume(Object(Elastic\Apm\Impl\Metadata), Array, Array, NULL, NULL)
\n#3 /opt/elastic/apm-agent-php/src/ElasticApm/Impl/Tracer.php(496): Elastic\Apm\Impl\Tracer->sendEventsToApmServer(Array, Array, NULL, NULL)
\n#4 /opt/elastic/apm-agent-php/src/ElasticApm/Impl/Span.php(271): Elastic\Apm\Impl\Tracer->sendSpanToApmServer(Object(Elastic\Apm\Impl\Span))
\n#5 /opt/elastic/apm-agent-php/src/ElasticApm/Impl/AutoInstrument/Util/AutoInstrumentationUtil.php(83): Elastic\Apm\Impl\Span->endSpanEx(5, NULL)
\n#6 /opt/elastic/apm-agent-php/src/ElasticApm/Impl/AutoInstrument/Util/AutoInstrumentationUtil.php(116): Elastic\Apm\Impl\AutoInstrument\Util\AutoInstrumentationUtil::endSpan(3, Object(Elastic\Apm\Impl\Span), false, Object(mysqli_result))
\n#7 /opt/elastic/apm-agent-php/src/ElasticApm/Impl/AutoInstrument/InterceptionManager.php(172): Elastic\Apm\Impl\AutoInstrument\Util\AutoInstrumentationUtil::Elastic\Apm\Impl\AutoInstrument\Util\{closure}(2, false, Object(mysqli_result))
\n#8 /opt/elastic/apm-agent-php/src/ElasticApm/Impl/AutoInstrument/PhpPartFacade.php(185): Elastic\Apm\Impl\AutoInstrument\InterceptionManager->interceptedCallPostHook(1, false, Object(mysqli_result))
\n#9 [internal function]: Elastic\Apm\Impl\AutoInstrument\PhpPartFacade::interceptedCallPostHook(false, Object(mysqli_result))
\n#10 /var/www/html/wp-includes/class-wpdb.php(2431): mysqli_query(Object(mysqli), 'SELECT * FROM ...') \n#11 \/var\/www\/html\/wp-includes\/class-wpdb.php(2320): wpdb->_do_query('SELECT * FROM ...')
\n#12 /var/www/html/wp-content/plugins/query-monitor/classes/DB.php(29): wpdb->query('SELECT * FROM ...') \n#13 \/var\/www\/html\/wp-includes\/class-wpdb.php(3018): QM_DB->query('SELECT * FROM ...')
\n#14 /var/www/html/wp-content/plugins/wordfence/models/block/wfBlock.php(979): wpdb->get_row('SELECT * FROM `...', 'ARRAY_A')
\n#15 /var/www/html/wp-content/plugins/wordfence/lib/wordfenceClass.php(1215): wfBlock::lockoutForIP('172.71.182.209')
\n#16 /var/www/html/wp-content/plugins/wordfence/wordfence.php(119): wordfence::install_actions()
\n#17 /var/www/html/wp-settings.php(453): include_once('/var/www/html/w...')
\n#18 /var/www/html/wp-config.php(98): require_once('/var/www/html/w...')
\n#19 /var/www/html/wp-load.php(50): require_once('/var/www/html/w...')
\n#20 /var/www/html/wp-blog-header.php(13): require_once('/var/www/html/w...')
\n#21 /var/www/html/index.php(17): require('/var/www/html/w...')

We have tried updating all plugins and the Elastic APM PHP Agent to their latest versions, but the issue persists. We would like to report this bug and seek guidance on how to resolve it.

Possible solutions we have tried:
Identifying and correcting/removing the invalid UTF-8 characters in the data processed by the Elastic APM PHP Agent. However, we were unable to locate the specific data causing the issue.

Modifying the Elastic APM PHP Agent source code to use a custom json_encode() function that handles invalid UTF-8 characters by ignoring or replacing them. While this may work as a temporary solution, it could cause issues with future updates and may not be officially supported by Elastic.

We are looking for a more permanent and supported solution to this problem. Any assistance or guidance would be greatly appreciated.

Environment:
Elastic APM PHP Agent version: 1.8.3
WordPress version: 6.2
Wordfence plugin version: 7.9.2
PHP version: 8.2
Web server: Nginx

Please let us know if you need any additional information to help diagnose and resolve this issue. Thank you.

@Yourcloud-host Yourcloud-host added the bug Something isn't working label May 4, 2023
@Yourcloud-host
Copy link
Author

Good day, unfortunately, we haven't found a solution yet for this error. We have updated to APM PHP 1.8.4, but we are still experiencing the same error in the WordPress Docker environment.

[Elastic APM PHP Tracer] 2023-06-12 08:18:28.031479+00:00 [PID: 152] [TID: 152] [CRITICAL] [Bootstrap] [BootstrapStageLogger.php:225] [callAndSwallowThrowable] Handling shutdown call let a throwable escape - skipping the rest of the steps. Elastic\Apm\Impl\BackendComm\SerializationException: Serialization failed. JsonUtil::encode() failed. {"$jsonEncodable type":"array","causedBy":{"type":"Elastic\Apm\Impl\Util\JsonException","value_as_string":"Elastic\Apm\Impl\Util\JsonException: json_encode() failed. json_last_error_msg(): Malformed UTF-8 characters, possibly incorrectly encoded. dataType: array in /opt/elastic/apm-agent-php/src/ElasticApm/Impl/Util/JsonUtil.php:49\nStack trace:\n#0 /opt/elastic/apm-agent-php/src/ElasticApm/Impl/Log/LoggableToEncodedJson.php(63): Elastic\Apm\Impl\Util\JsonUtil::encode(Array, true)\n#1 /opt/elastic/apm-agent-php/src/ElasticApm/Impl/Log/LoggableToString.php(48): Elastic\Apm\Impl\Log\LoggableToEncodedJson::convert(Object(Elastic\Apm\Impl\Log\AdhocLoggableObject), true, 1000)\n#2 /opt/elastic/apm-agent-php/src/ElasticApm/Impl/Util/ExceptionUtil.php(60): Elastic\Apm\Impl\Log\LoggableToString::convert(Object(Elastic\Apm\Impl\Log\AdhocLoggableObject), true)\n#3 /opt/elastic/apm-agent-php/src/ElasticApm/Impl/BackendComm/SerializationUtil.php(59): Elastic\Apm\Impl\Util\ExceptionUtil::buildMessage('Serialization f...', Array)\n#4 /opt/elastic/apm-agent-php/src/ElasticApm/Impl/BackendComm/EventSender.php(114): Elastic\Apm\Impl\BackendComm\SerializationUtil::serializeAsJson(Object(Elastic\Apm\Impl\Span))\n#5 /opt/elastic/apm-agent-php/src/ElasticApm/Impl/Tracer.php(485): Elastic\Apm\Impl\BackendComm\EventSender->consume(Object(Elastic\Apm\Impl\Metadata), Array, Array, NULL, NULL)\n#6 /opt/elastic/apm-agent-php/src/ElasticApm/Impl/Tracer.php(496): Elastic\Apm\Impl\Tracer->sendEventsToApmServer(Array, Array, NULL, NULL)\n#7 /opt/elastic/apm-agent-php/src/ElasticApm/Impl/ExecutionSegment.php(623): Elastic\Apm\Impl\Tracer->sendSpanToApmServer(Object(Elastic\Apm\Impl\Span))\n#8 /opt/elastic/apm-agent-php/src/ElasticApm/Impl/ExecutionSegment.php(484): Elastic\Apm\Impl\ExecutionSegment->flushPendingCompositeChild()\n#9 /opt/elastic/ap

m-agent-php/src/ElasticApm/Impl/Transaction.php(511): Elastic\Apm\Impl\ExecutionSegment->endExecutionSegment(NULL)\n#10 /opt/elastic/apm-agent-php/src/ElasticApm/Impl/AutoInstrument/TransactionForExtensionRequest.php(389): Elastic\Apm\Impl\Transaction->end()\n#11 /opt/elastic/apm-agent-php/src/ElasticApm/Impl/AutoInstrument/PhpPartFacade.php(478): Elastic\Apm\Impl\AutoInstrument\TransactionForExtensionRequest->onShutdown()\n#12 /opt/elastic/apm-agent-php/src/ElasticApm/Impl/AutoInstrument/PhpPartFacade.php(261): Elastic\Apm\Impl\AutoInstrument\PhpPartFacade::Elastic\Apm\Impl\AutoInstrument\{closure}(Object(Elastic\Apm\Impl\AutoInstrument\TransactionForExtensionRequest))\n#13 /opt/elastic/apm-agent-php/src/ElasticApm/Impl/AutoInstrument/PhpPartFacade.php(219): Elastic\Apm\Impl\AutoInstrument\PhpPartFacade::Elastic\Apm\Impl\AutoInstrument\{closure}(Object(Elastic\Apm\Impl\AutoInstrument\PhpPartFacade))\n#14 /opt/elastic/apm-agent-php/src/ElasticApm/Impl/AutoInstrument/PhpPartFacade.php(248): Elastic\Apm\Impl\AutoInstrument\PhpPartFacade::callAndSwallowThrowable('shutdown', Object(Closure))\n#15 /opt/elastic/apm-agent-php/src/ElasticApm/Impl/AutoInstrument/PhpPartFacade.php(475): Elastic\Apm\Impl\AutoInstrument\PhpPartFacade::callWithTransactionForExtensionRequest('shutdown', Object(Closure))\n#16 [internal function]: Elastic\Apm\Impl\AutoInstrument\PhpPartFacade::shutdown()\n#17 {main}"}}

[Elastic APM PHP Tracer] 2023-06-12 08:18:28.031479+00:00 [PID: 152] [TID: 152] [CRITICAL] [Bootstrap] [BootstrapStageLogger.php:225] [callAndSwallowThrowable] Stack trace:

[Elastic APM PHP Tracer] 2023-06-12 08:18:28.031479+00:00 [PID: 152] [TID: 152] [CRITICAL] [Bootstrap] [BootstrapStageLogger.php:225] [callAndSwallowThrowable] #0 /opt/elastic/apm-agent-php/src/ElasticApm/Impl/BackendComm/EventSender.php(114): Elastic\Apm\Impl\BackendComm\SerializationUtil::serializeAsJson(Object(Elastic\Apm\Impl\Span))

[Elastic APM PHP Tracer] 2023-06-12 08:18:28.031479+00:00 [PID: 152] [TID: 152] [CRITICAL] [Bootstrap] [BootstrapStageLogger.php:225] [callAndSwallowThrowable] #1 /opt/elastic/apm-agent-php/src/ElasticApm/Impl/Tracer.php(485): Elastic\Apm\Impl\BackendComm\EventSender->consume(Object(Elastic\Apm\Impl\Metadata), Array, Array, NULL, NULL)

[Elastic APM PHP Tracer] 2023-06-12 08:18:28.031479+00:00 [PID: 152] [T

ID: 152] [CRITICAL] [Bootstrap] [BootstrapStageLogger.php:225] [callAndSwallowThrowable] #2 /opt/elastic/apm-agent-php/src/ElasticApm/Impl/Tracer.php(496): Elastic\Apm\Impl\Tracer->sendEventsToApmServer(Array, Array, NULL, NULL)

[Elastic APM PHP Tracer] 2023-06-12 08:18:28.031479+00:00 [PID: 152] [TID: 152] [CRITICAL] [Bootstrap] [BootstrapStageLogger.php:225] [callAndSwallowThrowable] #3 /opt/elastic/apm-agent-php/src/ElasticApm/Impl/ExecutionSegment.php(623): Elastic\Apm\Impl\Tracer->sendSpanToApmServer(Object(Elastic\Apm\Impl\Span))

[Elastic APM PHP Tracer] 2023-06-12 08:18:28.031479+00:00 [PID: 152] [TID: 152] [CRITICAL] [Bootstrap] [BootstrapStageLogger.php:225] [callAndSwallowThrowable] #4 /opt/elastic/apm-agent-php/src/ElasticApm/Impl/ExecutionSegment.php(484): Elastic\Apm\Impl\ExecutionSegment->flushPendingCompositeChild()

[Elastic APM PHP Tracer] 2023-06-12 08:18:28.031479+00:00 [PID: 152] [TID: 152] [CRITICAL] [Bootstrap] [BootstrapStageLogger.php:225] [callAndSwallowThrowable] #5 /opt/elastic/apm-agent-php/src/ElasticApm/Impl/Transaction.php(511): Elastic\Apm\Impl\ExecutionSegment->endExecutionSegment(NULL)

[Elastic APM PHP Tracer] 2023-06-12 08:18:28.031479+00:00 [PID: 152] [TID: 152] [CRITICAL] [Bootstrap] [BootstrapStageLogger.php:225] [callAndSwallowThrowable] #6 /opt/elastic/apm-agent-php/src/ElasticApm/Impl/AutoInstrument/TransactionForExtensionRequest.php(389): Elastic\Apm\Impl\Transaction->end()

[Elastic APM PHP Tracer] 2023-06-12 08:18:28.031479+00:00 [PID: 152] [TID: 152] [CRITICAL] [Bootstrap] [BootstrapStageLogger.php:225] [callAndSwallowThrowable] #7 /opt/elastic/apm-agent-php/src/ElasticApm/Impl/AutoInstrument/PhpPartFacade.php(478): Elastic\Apm\Impl\AutoInstrument\TransactionForExtensionRequest->onShutdown()

[Elastic APM PHP Tracer] 2023-06-12 08:18:28.031479+00:00 [PID: 152] [TID: 152] [CRITICAL] [Bootstrap] [BootstrapStageLogger.php:225] [callAndSwallowThrowable] #8 /opt/elastic/apm-agent-php/src/ElasticApm/Impl/AutoInstrument/PhpPartFacade.php(261): Elastic\Apm\Impl\AutoInstrument\PhpPartFacade::Elastic\Apm\Impl\AutoInstrument{closure}(Object(Elastic\Apm\Impl\AutoInstrument\TransactionForExtensionRequest))

[Elastic APM PHP Tracer] 2023-06-12 08:18:28.031479+00:00 [

PID: 152] [TID: 152] [CRITICAL] [Bootstrap] [BootstrapStageLogger.php:225] [callAndSwallowThrowable] #9 /opt/elastic/apm-agent-php/src/ElasticApm/Impl/AutoInstrument/PhpPartFacade.php(219): Elastic\Apm\Impl\AutoInstrument\PhpPartFacade::Elastic\Apm\Impl\AutoInstrument{closure}(Object(Elastic\Apm\Impl\AutoInstrument\PhpPartFacade))

[Elastic APM PHP Tracer] 2023-06-12 08:18:28.031479+00:00 [PID: 152] [TID: 152] [CRITICAL] [Bootstrap] [BootstrapStageLogger.php:225] [callAndSwallowThrowable] #10 /opt/elastic/apm-agent-php/src/ElasticApm/Impl/AutoInstrument/PhpPartFacade.php(248): Elastic\Apm\Impl\AutoInstrument\PhpPartFacade::callAndSwallowThrowable('shutdown', Object(Closure))

[Elastic APM PHP Tracer] 2023-06-12 08:18:28.031479+00:00 [PID: 152] [TID: 152] [CRITICAL] [Bootstrap] [BootstrapStageLogger.php:225] [callAndSwallowThrowable] #11 /opt/elastic/apm-agent-php/src/ElasticApm/Impl/AutoInstrument/PhpPartFacade.php(475): Elastic\Apm\Impl\AutoInstrument\PhpPartFacade::callWithTransactionForExtensionRequest('shutdown', Object(Closure))

[Elastic APM PHP Tracer] 2023-06-12 08:18:28.031479+00:00 [PID: 152] [TID: 152] [CRITICAL] [Bootstrap] [BootstrapStageLogger.php:225] [callAndSwallowThrowable] #12 [internal function]: Elastic\Apm\Impl\AutoInstrument\PhpPartFacade::shutdown()

[Elastic APM PHP Tracer] 2023-06-12 08:18:28.031479+00:00 [PID: 152] [TID: 152] [CRITICAL] [Bootstrap] [BootstrapStageLogger.php:225] [callAndSwallowThrowable] #13 {main}

+++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++

this is a error message from elastic APM self
#0 Elastic\Apm\Impl\AutoInstrument\PhpPartFacade::interceptedCallPostHook() called at [FILE NAME N/A:0]
#1 curl_exec() called at [/var/www/html/wp-includes/Requests/src/Transport/Curl.php:204]
#2 WpOrg\Requests\Transport\Curl->request() called at [/var/www/html/wp-includes/Requests/src/Requests.php:469]
#3 WpOrg\Requests\Requests::request() called at [/var/www/html/wp-includes/class-wp-http.php:396]
#4 WP_Http->request() called at [/var/www/html/wp-includes/class-wp-http.php:616]
#5 WP_Http->post() called at [/var/www/html/wp-includes/http.php:179]
#6 wp_remote_post() called at [/var/www/html/wp-content/themes/astra/inc/theme-update/class-astra-theme-background-updater.php:182]
#7 Astra_Theme_Background_Updater->test_cron() called at [/var/www/html/wp-content/themes/astra/inc/theme-update/class-astra-theme-background-updater.php:208]
#8 Astra_Theme_Background_Updater->install_actions() called at [/var/www/html/wp-includes/class-wp-hook.php:308]
#9 WP_Hook->apply_filters() called at [/var/www/html/wp-includes/class-wp-hook.php:332]
#10 WP_Hook->do_action() called at [/var/www/html/wp-includes/plugin.php:565]
#11 do_action_ref_array() called at [/var/www/html/wp-includes/class-wp.php:797]
#12 WP->main() called at [/var/www/html/wp-includes/functions.php:1334]
#13 wp() called at [/var/www/html/wp-blog-header.php:16]
#14 require() called at [/var/www/html/index.php:17]

We are looking for a way to make the PHP agent work correctly with the WordPress Docker environment. If you need more information, please let us know. Thank you.

Environment:
Elastic 8.5
Elastic APM PHP Agent version: 1.8.4
WordPress version: 6.2.2
Wordfence plugin version: 7.9.3
PHP version: 8.2
Web server: Nginx

@GHostlyFOX
Copy link

GHostlyFOX commented Jul 20, 2023

Try this:

In file: apm-agent-php/src/ElasticApm/Impl/Util/JsonUtil.php

Add function:

public static function utf8ize( $mixed ) {
        if (is_array($mixed)) {
            foreach ($mixed as $key => $value) {
                $mixed[$key] = self::utf8ize($value);
            }
        } elseif (is_string($mixed)) {
            return mb_convert_encoding($mixed, "UTF-8", "UTF-8");
        }
	return $mixed;
    }

In function encode() replace:

$encodedData = json_encode($data, $options);

with

$encodedData = json_encode(self::utf8ize($data), $options);

As a result, the class will look like this:

final class JsonUtil
{
    use StaticClassTrait;
    
    public static function utf8ize( $mixed ) {
        if (is_array($mixed)) {
            foreach ($mixed as $key => $value) {
                $mixed[$key] = self::utf8ize($value);
            }
        } elseif (is_string($mixed)) {
            return mb_convert_encoding($mixed, "UTF-8", "UTF-8");
        }
	return $mixed;
    }

    /**
     * @param mixed $data
     * @param bool  $prettyPrint
     *
     * @return string
     *
     * @throws JsonException
     */
    public static function encode($data, bool $prettyPrint = false): string
    {
        $options = 0;
        $options |= $prettyPrint ? JSON_PRETTY_PRINT : 0;
        $encodedData = json_encode(self::utf8ize($data), $options);
        if ($encodedData === false) {
            throw new JsonException(
                'json_encode() failed'
                . '. json_last_error_msg(): ' . json_last_error_msg()
                . '. dataType: ' . DbgUtil::getType($data)
            );
        }
        return $encodedData;
    }
}

@pawan-1999
Copy link

Hi Team,

Even I am facing the same issue. still, the above issue persists any solution or workaround for it?

@Yourcloud-host
Copy link
Author

Thank you for the response. We haven't had the time to implement it in our Docker as we are currently on vacation. We'll pick this up on August 21st, and we will definitely get back to you. Thank you, and you'll hear from us again.

@SergeyKleyman
Copy link
Contributor

@GHostlyFOX

Thank you for providing your solution. Could you please clarify what is the purpose of the following line:

mb_convert_encoding($mixed, "UTF-8", "UTF-8");

@daflyinbed
Copy link

utf8ize didn't works for me, so I added
$options |= JSON_UNESCAPED_UNICODE|JSON_INVALID_UTF8_IGNORE;

@SergeyKleyman
Copy link
Contributor

@daflyinbed
Thank you for the suggestion.
Could you please clarify if JSON_UNESCAPED_UNICODE is necessary to resolve the issue of malformed UTF-8 characters or is it just to reduce the size of the encoded string?

@daflyinbed
Copy link

@SergeyKleyman It's not necessary. I wrote it in passing.

@SergeyKleyman
Copy link
Contributor

@daflyinbed
Thank you for the clarification.
@daflyinbed @GHostlyFOX @Yourcloud-host @pawan-1999
Please try the fix implemented by #1043 before we release it (the packages can be downloaded from https://github.com/elastic/apm-agent-php/suites/15385900250/artifacts/878658623) and let us know how it resolves this issue.

@daflyinbed
Copy link

#1043 works for me

@titzel24
Copy link

@SergeyKleyman Thanks for fixing 🙏

But are there still any plans to also release this?

@SergeyKleyman
Copy link
Contributor

Fixed by #1120

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
agent-php bug Something isn't working
Projects
None yet
6 participants