ecotoneframework / ecotone-dev

Ecotone Framework Development - This is Monorepo which contains all official public modules
https://docs.ecotone.tech
Other
37 stars 16 forks source link

Warning: Ecotone\Messaging\Handler\Logger\LoggingService::log(): OpenTelemetry: pre hook threw exception #387

Closed lifinsky closed 6 days ago

lifinsky commented 6 days ago

Ecotone version(s) affected: 1.231.0-latest

Description
Warning: Ecotone\Messaging\Handler\Logger\LoggingService::log(): OpenTelemetry: pre hook threw exception, class=Ecotone\Messaging\Handler\Logger\LoggingService function=log message=Cannot use object of type Ecotone\Messaging\Support\GenericMessage as array in Unknown on line 0

How to reproduce
When using OpenTelemetry in consumers (ecotone run), Symfony framework with Monolog

when@local:
    monolog:
        handlers:
            main:
                type: stream
                path: '%kernel.logs_dir%/%kernel.environment%.log'
                level: debug
                channels: ['!event', '!deprecation']
            console:
                type: console
                process_psr_3_messages: false
                channels: ['!event', '!doctrine', '!deprecation']
            deprecation:
                type: stream
                channels: [ deprecation ]
                path: '%kernel.logs_dir%/%kernel.environment%.deprecations.log'

Context

2024-10-15 15:43:14 Warning: Ecotone\Messaging\Handler\Logger\LoggingService::log(): OpenTelemetry: pre hook threw exception, class=Ecotone\Messaging\Handler\Logger\LoggingService function=log message=Cannot use object of type Ecotone\Messaging\Support\GenericMessage as array in Unknown on line 0
2024-10-15 15:43:14 #31 /app/vendor/ecotone/ecotone/src/Messaging/Endpoint/PollingConsumer/PollToGatewayTaskExecutor.php(37): Ecotone\Messaging\Endpoint\PollingConsumer\InterceptedGateway->execute(Array)
2024-10-15 15:43:14 #32 /app/vendor/ecotone/ecotone/src/Messaging/Scheduling/SyncTaskScheduler.php(43): Ecotone\Messaging\Endpoint\PollingConsumer\PollToGatewayTaskExecutor->execute(Object(Ecotone\Messaging\Endpoint\PollingMetadata))
2024-10-15 15:43:14 #33 /app/vendor/ecotone/ecotone/src/Messaging/Endpoint/PollingConsumer/ScheduledTaskConsumer.php(31): Ecotone\Messaging\Scheduling\SyncTaskScheduler->schedule(Object(Ecotone\Messaging\Endpoint\PollingConsumer\PollToGatewayTaskExecutor), Object(Ecotone\Messaging\Scheduling\PeriodicTrigger))
2024-10-15 15:43:14 #34 /app/vendor/ecotone/ecotone/src/Messaging/Endpoint/PollingConsumer/InterceptedConsumer.php(52): Ecotone\Messaging\Endpoint\PollingConsumer\ScheduledTaskConsumer->run()
2024-10-15 15:43:14 #35 /app/vendor/ecotone/ecotone/src/Messaging/Endpoint/PollingConsumer/InterceptedConsumerRunner.php(35): Ecotone\Messaging\Endpoint\PollingConsumer\InterceptedConsumer->run()
2024-10-15 15:43:14 #36 /app/vendor/ecotone/ecotone/src/Messaging/Config/MessagingSystemContainer.php(102): Ecotone\Messaging\Endpoint\PollingConsumer\InterceptedConsumerRunner->runEndpointWithExecutionPollingMetadata(Object(Ecotone\Messaging\Endpoint\ExecutionPollingMetadata))
2024-10-15 15:43:14 #37 /app/vendor/ecotone/ecotone/src/Messaging/Config/Annotation/ModuleConfiguration/MessagingCommands/MessagingBaseCommand.php(43): Ecotone\Messaging\Config\MessagingSystemContainer->run('integration_wal...', Object(Ecotone\Messaging\Endpoint\ExecutionPollingMetadata))
2024-10-15 15:43:14 #38 /app/vendor/ecotone/ecotone/src/Messaging/Handler/Processor/MethodInvoker/MethodInvoker.php(38): Ecotone\Messaging\Config\Annotation\ModuleConfiguration\MessagingCommands\MessagingBaseCommand->runAsynchronousEndpointCommand('integration_wal...', Object(Ecotone\Messaging\Config\MessagingSystemContainer), NULL, NULL, NULL, NULL, false, false)
2024-10-15 15:43:14 #39 /app/vendor/ecotone/ecotone/src/Messaging/Handler/Processor/MethodInvokerProcessor.php(25): Ecotone\Messaging\Handler\Processor\MethodInvoker\MethodInvoker->execute(Object(Ecotone\Messaging\Support\GenericMessage))
2024-10-15 15:43:14 #40 /app/vendor/ecotone/ecotone/src/Messaging/Handler/RequestReplyProducer.php(28): Ecotone\Messaging\Handler\Processor\MethodInvokerProcessor->process(Object(Ecotone\Messaging\Support\GenericMessage))
2024-10-15 15:43:14 #41 /app/vendor/ecotone/ecotone/src/Messaging/Channel/DirectChannel.php(39): Ecotone\Messaging\Handler\RequestReplyProducer->handle(Object(Ecotone\Messaging\Support\GenericMessage))
2024-10-15 15:43:14 #42 /app/vendor/ecotone/ecotone/src/Messaging/Handler/Router/Router.php(59): Ecotone\Messaging\Channel\DirectChannel->send(Object(Ecotone\Messaging\Support\GenericMessage))
2024-10-15 15:43:14 #43 /app/vendor/ecotone/ecotone/src/Messaging/Channel/DirectChannel.php(39): Ecotone\Messaging\Handler\Router\Router->handle(Object(Ecotone\Messaging\Support\GenericMessage))
2024-10-15 15:43:14 #44 /app/vendor/ecotone/ecotone/src/Messaging/Handler/Gateway/GatewayInternalProcessor.php(63): Ecotone\Messaging\Channel\DirectChannel->send(Object(Ecotone\Messaging\Support\GenericMessage))
2024-10-15 15:43:14 #45 /app/vendor/ecotone/ecotone/src/Messaging/Handler/Processor/MethodInvoker/AroundMethodInvocation.php(57): Ecotone\Messaging\Handler\Gateway\GatewayInternalProcessor->process(Object(Ecotone\Messaging\Support\GenericMessage))
2024-10-15 15:43:14 #46 /app/vendor/ecotone/ecotone/src/Modelling/MessageHandling/MetadataPropagator/MessageHeadersPropagatorInterceptor.php(35): Ecotone\Messaging\Handler\Processor\MethodInvoker\AroundMethodInvocation->proceed()
2024-10-15 15:43:14 #47 /app/vendor/ecotone/ecotone/src/Messaging/Handler/Processor/MethodInvoker/AroundMethodInvocation.php(67): Ecotone\Modelling\MessageHandling\MetadataPropagator\MessageHeadersPropagatorInterceptor->storeHeaders(Object(Ecotone\Messaging\Handler\Processor\MethodInvoker\AroundMethodInvocation), Object(Ecotone\Messaging\Support\GenericMessage), NULL)
2024-10-15 15:43:14 #48 /app/vendor/ecotone/ecotone/src/Messaging/Handler/Processor/MethodInvoker/AroundMessageProcessor.php(33): Ecotone\Messaging\Handler\Processor\MethodInvoker\AroundMethodInvocation->proceed()
2024-10-15 15:43:14 #49 /app/vendor/ecotone/ecotone/src/Messaging/Handler/Processor/ChainedMessageProcessor.php(24): Ecotone\Messaging\Handler\Processor\MethodInvoker\AroundMessageProcessor->process(Object(Ecotone\Messaging\Support\GenericMessage))
2024-10-15 15:43:14 #50 /app/vendor/ecotone/ecotone/src/Messaging/Handler/Gateway/Gateway.php(78): Ecotone\Messaging\Handler\Processor\ChainedMessageProcessor->process(Object(Ecotone\Messaging\Support\GenericMessage))
2024-10-15 15:43:14 #51 /app/var/cache/local/ecotone/Ecotone_Messaging_Gateway_MessagingEntrypointWithHeadersPropagation.php(23): Ecotone\Messaging\Handler\Gateway\Gateway->execute(Array)
2024-10-15 15:43:14 #52 /app/vendor/ecotone/ecotone/src/Messaging/Config/ConsoleCommandRunner.php(57): Ecotone\__Proxy__\Ecotone_Messaging_Gateway_MessagingEntrypointWithHeadersPropagation->sendWithHeaders(Array, Array, 'ecotone.channel...')
2024-10-15 15:43:14 #53 /app/vendor/ecotone/ecotone/src/Messaging/Config/MessagingSystemContainer.php(57): Ecotone\Messaging\Config\ConsoleCommandRunner->run(Array)
2024-10-15 15:43:14 #54 /app/vendor/ecotone/ecotone/src/Messaging/Config/Annotation/ModuleConfiguration/MessagingCommands/MessagingBaseCommand.php(17): Ecotone\Messaging\Config\MessagingSystemContainer->runConsoleCommand('ecotone:run', Array)
2024-10-15 15:43:14 #55 /app/vendor/ecotone/ecotone/src/Messaging/Handler/Processor/MethodInvoker/MethodInvoker.php(38): Ecotone\Messaging\Config\Annotation\ModuleConfiguration\MessagingCommands\MessagingBaseCommand->executeConsoleCommand('ecotone:run', Array, Object(Ecotone\Messaging\Config\MessagingSystemContainer))
2024-10-15 15:43:14 #56 /app/vendor/ecotone/ecotone/src/Messaging/Handler/Processor/MethodInvokerProcessor.php(25): Ecotone\Messaging\Handler\Processor\MethodInvoker\MethodInvoker->execute(Object(Ecotone\Messaging\Support\GenericMessage))
2024-10-15 15:43:14 #57 /app/vendor/ecotone/ecotone/src/Messaging/Handler/RequestReplyProducer.php(28): Ecotone\Messaging\Handler\Processor\MethodInvokerProcessor->process(Object(Ecotone\Messaging\Support\GenericMessage))
2024-10-15 15:43:14 #58 /app/vendor/ecotone/ecotone/src/Messaging/Channel/DirectChannel.php(39): Ecotone\Messaging\Handler\RequestReplyProducer->handle(Object(Ecotone\Messaging\Support\GenericMessage))
2024-10-15 15:43:14 #59 /app/vendor/ecotone/ecotone/src/Messaging/Handler/Gateway/GatewayInternalProcessor.php(63): Ecotone\Messaging\Channel\DirectChannel->send(Object(Ecotone\Messaging\Support\GenericMessage))
2024-10-15 15:43:14 #60 /app/vendor/ecotone/ecotone/src/Messaging/Handler/Gateway/Gateway.php(78): Ecotone\Messaging\Handler\Gateway\GatewayInternalProcessor->process(Object(Ecotone\Messaging\Support\GenericMessage))
2024-10-15 15:43:14 #61 /app/var/cache/local/ecotone/Ecotone_Messaging_Gateway_ConsoleCommandRunner.php(18): Ecotone\Messaging\Handler\Gateway\Gateway->execute(Array)
2024-10-15 15:43:14 #62 /app/vendor/ecotone/symfony-bundle/DependencyInjection/MessagingEntrypointCommand.php(63): Ecotone\__Proxy__\Ecotone_Messaging_Gateway_ConsoleCommandRunner->execute('ecotone:run', Array)
lifinsky commented 6 days ago
services:
    ...
    OpenTelemetry\API\Trace\TracerProviderInterface:
        class: 'OpenTelemetry\API\Globals'
        factory: [ 'OpenTelemetry\API\Globals', 'tracerProvider' ]
lifinsky commented 6 days ago
    #[ServiceContext]
    public function traceConfiguration(): TracingConfiguration
    {
        return TracingConfiguration::createWithDefaults()
            ->withForceFlushOnBusExecution(false)
            ->withForceFlushOnAsynchronousMessageHandled(false)
        ;
    }
dgafka commented 6 days ago

@jlabedo are you able to take a look on this?

lifinsky commented 6 days ago

After this release 1.231.0

lifinsky commented 6 days ago

Should we replace LoggerInterface to LoggingGateway?

jlabedo commented 6 days ago

@lifinsky the error is mentioning a "prehook" from opentelemetry, are you using the opentelemetry php extension (opentelemetry.so) ?

lifinsky commented 6 days ago

@lifinsky the error is mentioning a "prehook" from opentelemetry, are you using the opentelemetry php extension (opentelemetry.so) ?

yes, opentelemetry extension

lifinsky commented 6 days ago
php --re opentelemetry | head -1
Extension [ <persistent> extension #40 opentelemetry version 1.1.0 ]
lifinsky commented 6 days ago
"open-telemetry/api": "^1.0",
"open-telemetry/context": "^1.0",
"open-telemetry/exporter-otlp": "^1.0",
"open-telemetry/opentelemetry-auto-guzzle": "^0.0.2",
"open-telemetry/opentelemetry-auto-pdo": "^0.0.12",
"open-telemetry/opentelemetry-auto-psr3": "^0.0.6",
"open-telemetry/opentelemetry-auto-psr15": "^1.0",
"open-telemetry/opentelemetry-auto-psr18": "^1.0",
"open-telemetry/opentelemetry-auto-symfony": "^1.0@beta",
"open-telemetry/opentelemetry-logger-monolog": "^1.0",
"open-telemetry/sdk": "^1.0",
"open-telemetry/transport-grpc": "^1.0",
jlabedo commented 6 days ago

First, I think it is redundant to use open-telemetry/opentelemetry-auto-psr3 and open-telemetry/opentelemetry-logger-monolog at the same time.

Then, I think it is an issue with open-telemetry/opentelemetry-auto-psr3 that does not check the value of the params passed to the logger interface. Ecotone Logging gateway extends the PSR 3 Logger Interface, enabling it to pass GenericMessage or an array, this is valid for me.

Moreover, the logging gateway is already passing events to opentelemetry, so you may have some double events here if you use open-telemetry/opentelemetry-auto-psr3 and ecotone opentelemetry package

Here is the problematic extended interface:

interface LoggingGateway extends LoggerInterface
{
    public function info(Stringable|string $message, array|Message|null $context = [], array $additionalContext = []): void;
    public function error(Stringable|string $message, array|Message|null $context = [], array $additionalContext = []): void;
    public function critical(Stringable|string $message, array|Message|null $context = [], array $additionalContext = []): void;
}

PS: Does not relate to the issue but I did get very bad performance issues with opentelemetry auto instrumentation with opentelemetry extension (it does some magic), please let me know if you have good results.

lifinsky commented 6 days ago

@jlabedo Thanks, after removing "opentelemetry-auto-psr3" everything works. What else do you think is superfluous in auto instrumentations?

jlabedo commented 4 days ago

@jlabedo Thanks, after removing "opentelemetry-auto-psr3" everything works. What else do you think is superfluous in auto instrumentations?

Nothing superfluous to me. Let me know if you have any other issue.