Comments (14)
Hi @rikless,
We will need more information to be able to debug the problem. If this is your local machine, could you change getMessage()
with toString()
in this line?
from elastic-apm-laravel.
@arkaitzgarro it's in production, on Clever Cloud hosting.
I've tried to update with getMessage() but it doesn't changed the error message :(
from elastic-apm-laravel.
It looks like we are sending errors as transactions, and Elastic complains about it. Working on a fix.
from elastic-apm-laravel.
I was trying to understand what's happening, but I'm not sure. What I got so far is that: whenever a job fails, it emits an event JobFailed
that our collector listens to. Then it uses the captureThrowable
method to transform the exception to a payload line understandable by the intake API. Then sends it to the APM, but gets that error in response. What you don't see in the error log is the document
field containing what we're sending (I've made a #58 to dump the full response). Now my best guess at this point is that the payload is invalid, but looking at the expected schema (some references are missing, but you can find them in their repo; also example request is useful) I cannot really pinpoint what's wrong.
from elastic-apm-laravel.
@rikless I published a new version of the package (v1.5.2
) that should log the complete error description coming from Elastic. Could you give it a try, and share the error that you get back?
from elastic-apm-laravel.
Thank you all for your support !
2020-07-16T22:06:03.551Z: #4 /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/vendor/guzzlehttp/promises/src/Promise.php(246): GuzzleHttp\Promise\TaskQueue->run(true)
2020-07-16T22:06:03.552Z: #5 /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/vendor/guzzlehttp/promises/src/Promise.php(223): GuzzleHttp\Promise\Promise->invokeWaitFn()
2020-07-16T22:06:03.552Z: #9 /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/vendor/guzzlehttp/guzzle/src/Client.php(182): GuzzleHttp\Promise\Promise->wait()
2020-07-16T22:06:03.552Z: #16 /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/vendor/laravel/framework/src/Illuminate/Events/Dispatcher.php(226): Illuminate\Events\Dispatcher->Illuminate\Events\{closure}('Illuminate\\Queu...', Array)
2020-07-16T22:06:03.552Z: #6 /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/vendor/guzzlehttp/promises/src/Promise.php(267): GuzzleHttp\Promise\Promise->waitIfPending()
2020-07-16T22:06:03.552Z: #12 /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/vendor/philkra/elastic-apm-php-agent/src/Agent.php(271): PhilKra\Middleware\Connector->commit()
2020-07-16T22:06:03.552Z: #8 /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/vendor/guzzlehttp/promises/src/Promise.php(62): GuzzleHttp\Promise\Promise->waitIfPending()
2020-07-16T22:06:03.552Z: #15 /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/vendor/laravel/framework/src/Illuminate/Events/Dispatcher.php(381): AG\ElasticApmLaravel\Collectors\JobCollector->AG\ElasticApmLaravel\Collectors\{closure}(Object(Illuminate\Queue\Events\JobProcessed))
2020-07-16T22:06:03.552Z: #14 /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/vendor/arkaitzgarro/elastic-apm-laravel/src/Collectors/JobCollector.php(42): AG\ElasticApmLaravel\Collectors\JobCollector->send(Object(Illuminate\Queue\Jobs\RedisJob))
2020-07-16T22:06:03.552Z: #13 /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/vendor/arkaitzgarro/elastic-apm-laravel/src/Collectors/JobCollector.php(115): PhilKra\Agent->send()
2020-07-16T22:06:03.552Z: #19 /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/vendor/laravel/framework/src/Illuminate/Queue/Worker.php(306): Illuminate\Queue\Worker->process('redis', Object(Illuminate\Queue\Jobs\RedisJob), Object(Illuminate\Queue\WorkerOptions))
2020-07-16T22:06:03.552Z: #22 /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/vendor/laravel/framework/src/Illuminate/Queue/Console/WorkCommand.php(96): Illuminate\Queue\Console\WorkCommand->runWorker('redis', 'tube4')
2020-07-16T22:06:03.552Z: #11 /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/vendor/philkra/elastic-apm-php-agent/src/Middleware/Connector.php(91): GuzzleHttp\Client->__call('post', Array)
2020-07-16T22:06:03.552Z: #24 [internal function]: Laravel\Horizon\Console\WorkCommand->handle()
2020-07-16T22:06:03.552Z: #17 /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/vendor/laravel/framework/src/Illuminate/Queue/Worker.php(526): Illuminate\Events\Dispatcher->dispatch('Illuminate\\Queu...')
2020-07-16T22:06:03.552Z: #21 /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/vendor/laravel/framework/src/Illuminate/Queue/Console/WorkCommand.php(112): Illuminate\Queue\Worker->daemon('redis', 'tube4', Object(Illuminate\Queue\WorkerOptions))
2020-07-16T22:06:03.552Z: #7 /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/vendor/guzzlehttp/promises/src/Promise.php(225): GuzzleHttp\Promise\Promise->invokeWaitList()
2020-07-16T22:06:03.552Z: #18 /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/vendor/laravel/framework/src/Illuminate/Queue/Worker.php(358): Illuminate\Queue\Worker->raiseAfterJobEvent('redis', Object(Illuminate\Queue\Jobs\RedisJob))
2020-07-16T22:06:03.552Z: #23 /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/vendor/laravel/horizon/src/Console/WorkCommand.php(46): Illuminate\Queue\Console\WorkCommand->handle()
2020-07-16T22:06:03.552Z: #20 /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/vendor/laravel/framework/src/Illuminate/Queue/Worker.php(132): Illuminate\Queue\Worker->runJob(Object(Illuminate\Queue\Jobs\RedisJob), 'redis', Object(Illuminate\Queue\WorkerOptions))
2020-07-16T22:06:03.552Z: #10 /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/vendor/guzzlehttp/guzzle/src/Client.php(95): GuzzleHttp\Client->request('post', 'apm-server-blc2...', Array)
2020-07-16T22:06:03.553Z: #32 /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/vendor/laravel/framework/src/Illuminate/Console/Command.php(121): Symfony\Component\Console\Command\Command->run(Object(Symfony\Component\Console\Input\ArgvInput), Object(Illuminate\Console\OutputStyle))
2020-07-16T22:06:03.553Z: {
2020-07-16T22:06:03.553Z: #25 /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/vendor/laravel/framework/src/Illuminate/Container/BoundMethod.php(37): call_user_func_array(Array, Array)
2020-07-16T22:06:03.553Z: #39 {main} {"api_response":"{
2020-07-16T22:06:03.553Z: #28 /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/vendor/laravel/framework/src/Illuminate/Container/BoundMethod.php(39): Illuminate\Container\BoundMethod::callBoundMethod(Object(Illuminate\Foundation\Application), Array, Object(Closure))
2020-07-16T22:06:03.553Z: \"message\": \"did not recognize object type\",
2020-07-16T22:06:03.553Z: #31 /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/vendor/symfony/console/Command/Command.php(258): Illuminate\Console\Command->execute(Object(Symfony\Component\Console\Input\ArgvInput), Object(Illuminate\Console\OutputStyle))
2020-07-16T22:06:03.553Z: #38 /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/artisan(37): Illuminate\Foundation\Console\Kernel->handle(Object(Symfony\Component\Console\Input\ArgvInput), Object(Symfony\Component\Console\Output\ConsoleOutput))
2020-07-16T22:06:03.553Z: #30 /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/vendor/laravel/framework/src/Illuminate/Console/Command.php(134): Illuminate\Container\Container->call(Array)
2020-07-16T22:06:03.553Z: #29 /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/vendor/laravel/framework/src/Illuminate/Container/Container.php(592): Illuminate\Container\BoundMethod::call(Object(Illuminate\Foundation\Application), Array, Array, NULL)
2020-07-16T22:06:03.553Z: #33 /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/vendor/symfony/console/Application.php(911): Illuminate\Console\Command->run(Object(Symfony\Component\Console\Input\ArgvInput), Object(Symfony\Component\Console\Output\ConsoleOutput))
2020-07-16T22:06:03.553Z: #37 /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/vendor/laravel/framework/src/Illuminate/Foundation/Console/Kernel.php(129): Illuminate\Console\Application->run(Object(Symfony\Component\Console\Input\ArgvInput), Object(Symfony\Component\Console\Output\ConsoleOutput))
2020-07-16T22:06:03.553Z: \"accepted\": 0,
2020-07-16T22:06:03.553Z: #26 /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/vendor/laravel/framework/src/Illuminate/Container/Util.php(37): Illuminate\Container\BoundMethod::Illuminate\Container\{closure}()
2020-07-16T22:06:03.553Z: \"document\": \"{\\\"span\\\":{\\\"id\\\":\\\"ed0e75d311044898\\\",\\\"transaction_id\\\":\\\"34a6f46bda558605\\\",\\\"trace_id\\\":\\\"ba480d067a2be684b0fadb0e4629a879\\\",\\\"parent_id\\\":\\\"34a6f46bda558605\\\",\\\"type\\\":\\\"db.mysql.query\\\",\\\"action\\\":\\\"query\\\",\\\"context\\\":{\\\"custom\\\":[],\\\"labels\\\":[],\\\"db\\\":{\\\"statement\\\":\\\"select * from \\\\\\\"optins\\\\\\\" where \\\\\\\"optins\\\\\\\".\\\\\\\"id\\\\\\\" = ? limit 1\\\",\\\"type\\\":\\\"sql\\\"}},\\\"start\\\":355288.501,\\\"duration\\\":26.95,\\\"name\\\":\\\"SELECT optins\\\",\\\"stacktrace\\\":[],\\\"sync\\\":false,\\\"timestamp\\\":1594937518069464}}\"
2020-07-16T22:06:03.553Z: #27 /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/vendor/laravel/framework/src/Illuminate/Container/BoundMethod.php(95): Illuminate\Container\Util::unwrapIfClosure(Object(Closure))
2020-07-16T22:06:03.553Z: \"errors\": [
2020-07-16T22:06:03.553Z: #36 /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/vendor/laravel/framework/src/Illuminate/Console/Application.php(93): Symfony\Component\Console\Application->run(Object(Symfony\Component\Console\Input\ArgvInput), Object(Symfony\Component\Console\Output\ConsoleOutput))
2020-07-16T22:06:03.553Z: #35 /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/vendor/symfony/console/Application.php(140): Symfony\Component\Console\Application->doRun(Object(Symfony\Component\Console\Input\ArgvInput), Object(Symfony\Component\Console\Output\ConsoleOutput))
2020-07-16T22:06:03.553Z: #34 /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/vendor/symfony/console/Application.php(264): Symfony\Component\Console\Application->doRunCommand(Object(Laravel\Horizon\Console\WorkCommand), Object(Symfony\Component\Console\Input\ArgvInput), Object(Symfony\Component\Console\Output\ConsoleOutput))
2020-07-16T22:06:03.554Z: }
2020-07-16T22:06:03.554Z: "}
2020-07-16T22:06:03.554Z: }
2020-07-16T22:06:03.554Z: ]
2020-07-16T22:08:56.621Z: #5 /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/vendor/guzzlehttp/promises/src/Promise.php(223): GuzzleHttp\Promise\Promise->invokeWaitFn()
2020-07-16T22:08:56.621Z: "message": "did not recognize object type",
2020-07-16T22:08:56.621Z: {
2020-07-16T22:08:56.621Z: #7 /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/vendor/guzzlehttp/promises/src/Promise.php(225): GuzzleHttp\Promise\Promise->invokeWaitList()
2020-07-16T22:08:56.621Z: #6 /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/vendor/guzzlehttp/promises/src/Promise.php(267): GuzzleHttp\Promise\Promise->waitIfPending()
2020-07-16T22:08:56.621Z: [2020-07-16 22:08:56] production.ERROR: GuzzleHttp\Exception\ClientException: Client error: `POST *******
2020-07-16T22:08:56.621Z: "document": "{\"span\":{\ (truncated...)
2020-07-16T22:08:56.621Z: #3 /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/vendor/guzzlehttp/promises/src/TaskQueue.php(47): GuzzleHttp\Promise\Promise::GuzzleHttp\Promise\{closure}()
2020-07-16T22:08:56.621Z: #2 /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/vendor/guzzlehttp/promises/src/Promise.php(156): GuzzleHttp\Promise\Promise::callHandler(1, Object(GuzzleHttp\Psr7\Response), Array)
2020-07-16T22:08:56.621Z: Stack trace:
2020-07-16T22:08:56.621Z: #0 /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/vendor/guzzlehttp/guzzle/src/Middleware.php(65): GuzzleHttp\Exception\RequestException::create(Object(GuzzleHttp\Psr7\Request), Object(GuzzleHttp\Psr7\Response))
2020-07-16T22:08:56.621Z: in /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/vendor/guzzlehttp/guzzle/src/Exception/RequestException.php:113
2020-07-16T22:08:56.621Z: "accepted": 0,
2020-07-16T22:08:56.621Z: {
2020-07-16T22:08:56.621Z: #8 /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/vendor/guzzlehttp/promises/src/Promise.php(62): GuzzleHttp\Promise\Promise->waitIfPending()
2020-07-16T22:08:56.621Z: "errors": [
2020-07-16T22:08:56.621Z: #1 /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/vendor/guzzlehttp/promises/src/Promise.php(203): GuzzleHttp\Middleware::GuzzleHttp\{closure}(Object(GuzzleHttp\Psr7\Response))
2020-07-16T22:08:56.621Z: #4 /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/vendor/guzzlehttp/promises/src/Promise.php(246): GuzzleHttp\Promise\TaskQueue->run(true)
2020-07-16T22:08:56.622Z: #25 /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/vendor/laravel/framework/src/Illuminate/Container/BoundMethod.php(37): call_user_func_array(Array, Array)
2020-07-16T22:08:56.622Z: #15 /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/vendor/laravel/framework/src/Illuminate/Events/Dispatcher.php(381): AG\ElasticApmLaravel\Collectors\JobCollector->AG\ElasticApmLaravel\Collectors\{closure}(Object(Illuminate\Queue\Events\JobProcessed))
2020-07-16T22:08:56.622Z: #23 /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/vendor/laravel/horizon/src/Console/WorkCommand.php(46): Illuminate\Queue\Console\WorkCommand->handle()
2020-07-16T22:08:56.622Z: #14 /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/vendor/arkaitzgarro/elastic-apm-laravel/src/Collectors/JobCollector.php(42): AG\ElasticApmLaravel\Collectors\JobCollector->send(Object(Illuminate\Queue\Jobs\RedisJob))
2020-07-16T22:08:56.622Z: #13 /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/vendor/arkaitzgarro/elastic-apm-laravel/src/Collectors/JobCollector.php(115): PhilKra\Agent->send()
2020-07-16T22:08:56.622Z: #11 /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/vendor/philkra/elastic-apm-php-agent/src/Middleware/Connector.php(91): GuzzleHttp\Client->__call('post', Array)
2020-07-16T22:08:56.622Z: #27 /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/vendor/laravel/framework/src/Illuminate/Container/BoundMethod.php(95): Illuminate\Container\Util::unwrapIfClosure(Object(Closure))
2020-07-16T22:08:56.622Z: #21 /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/vendor/laravel/framework/src/Illuminate/Queue/Console/WorkCommand.php(112): Illuminate\Queue\Worker->daemon('redis', 'tube5', Object(Illuminate\Queue\WorkerOptions))
2020-07-16T22:08:56.622Z: #20 /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/vendor/laravel/framework/src/Illuminate/Queue/Worker.php(132): Illuminate\Queue\Worker->runJob(Object(Illuminate\Queue\Jobs\RedisJob), 'redis', Object(Illuminate\Queue\WorkerOptions))
2020-07-16T22:08:56.622Z: #26 /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/vendor/laravel/framework/src/Illuminate/Container/Util.php(37): Illuminate\Container\BoundMethod::Illuminate\Container\{closure}()
2020-07-16T22:08:56.622Z: #17 /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/vendor/laravel/framework/src/Illuminate/Queue/Worker.php(526): Illuminate\Events\Dispatcher->dispatch('Illuminate\\Queu...')
2020-07-16T22:08:56.622Z: #10 /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/vendor/guzzlehttp/guzzle/src/Client.php(95): GuzzleHttp\Client->request('post', 'apm-server-blc2...', Array)
2020-07-16T22:08:56.622Z: #9 /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/vendor/guzzlehttp/guzzle/src/Client.php(182): GuzzleHttp\Promise\Promise->wait()
2020-07-16T22:08:56.622Z: #16 /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/vendor/laravel/framework/src/Illuminate/Events/Dispatcher.php(226): Illuminate\Events\Dispatcher->Illuminate\Events\{closure}('Illuminate\\Queu...', Array)
2020-07-16T22:08:56.622Z: #28 /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/vendor/laravel/framework/src/Illuminate/Container/BoundMethod.php(39): Illuminate\Container\BoundMethod::callBoundMethod(Object(Illuminate\Foundation\Application), Array, Object(Closure))
2020-07-16T22:08:56.622Z: #22 /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/vendor/laravel/framework/src/Illuminate/Queue/Console/WorkCommand.php(96): Illuminate\Queue\Console\WorkCommand->runWorker('redis', 'tube5')
2020-07-16T22:08:56.622Z: #19 /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/vendor/laravel/framework/src/Illuminate/Queue/Worker.php(306): Illuminate\Queue\Worker->process('redis', Object(Illuminate\Queue\Jobs\RedisJob), Object(Illuminate\Queue\WorkerOptions))
2020-07-16T22:08:56.622Z: #24 [internal function]: Laravel\Horizon\Console\WorkCommand->handle()
2020-07-16T22:08:56.622Z: #12 /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/vendor/philkra/elastic-apm-php-agent/src/Agent.php(271): PhilKra\Middleware\Connector->commit()
2020-07-16T22:08:56.622Z: #18 /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/vendor/laravel/framework/src/Illuminate/Queue/Worker.php(358): Illuminate\Queue\Worker->raiseAfterJobEvent('redis', Object(Illuminate\Queue\Jobs\RedisJob))
2020-07-16T22:08:56.623Z: \"errors\": [
2020-07-16T22:08:56.623Z: }
2020-07-16T22:08:56.623Z: #31 /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/vendor/symfony/console/Command/Command.php(258): Illuminate\Console\Command->execute(Object(Symfony\Component\Console\Input\ArgvInput), Object(Illuminate\Console\OutputStyle))
2020-07-16T22:08:56.623Z: #37 /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/vendor/laravel/framework/src/Illuminate/Foundation/Console/Kernel.php(129): Illuminate\Console\Application->run(Object(Symfony\Component\Console\Input\ArgvInput), Object(Symfony\Component\Console\Output\ConsoleOutput))
2020-07-16T22:08:56.623Z: #34 /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/vendor/symfony/console/Application.php(264): Symfony\Component\Console\Application->doRunCommand(Object(Laravel\Horizon\Console\WorkCommand), Object(Symfony\Component\Console\Input\ArgvInput), Object(Symfony\Component\Console\Output\ConsoleOutput))
2020-07-16T22:08:56.623Z: }
2020-07-16T22:08:56.623Z: #30 /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/vendor/laravel/framework/src/Illuminate/Console/Command.php(134): Illuminate\Container\Container->call(Array)
2020-07-16T22:08:56.623Z: {
2020-07-16T22:08:56.623Z: #32 /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/vendor/laravel/framework/src/Illuminate/Console/Command.php(121): Symfony\Component\Console\Command\Command->run(Object(Symfony\Component\Console\Input\ArgvInput), Object(Illuminate\Console\OutputStyle))
2020-07-16T22:08:56.623Z: \"accepted\": 0,
2020-07-16T22:08:56.623Z: \"message\": \"did not recognize object type\",
2020-07-16T22:08:56.623Z: #29 /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/vendor/laravel/framework/src/Illuminate/Container/Container.php(592): Illuminate\Container\BoundMethod::call(Object(Illuminate\Foundation\Application), Array, Array, NULL)
2020-07-16T22:08:56.623Z: #33 /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/vendor/symfony/console/Application.php(911): Illuminate\Console\Command->run(Object(Symfony\Component\Console\Input\ArgvInput), Object(Symfony\Component\Console\Output\ConsoleOutput))
2020-07-16T22:08:56.623Z: #35 /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/vendor/symfony/console/Application.php(140): Symfony\Component\Console\Application->doRun(Object(Symfony\Component\Console\Input\ArgvInput), Object(Symfony\Component\Console\Output\ConsoleOutput))
2020-07-16T22:08:56.623Z: \"document\": \"{\\\"span\\\":{\\\"id\\\":\\\"da0079c75aaa9233\\\",\\\"transaction_id\\\":\\\"43384cc101432da9\\\",\\\"trace_id\\\":\\\"3bc036230942dfc9d4dd2e568204c3bb\\\",\\\"parent_id\\\":\\\"43384cc101432da9\\\",\\\"type\\\":\\\"db.mysql.query\\\",\\\"action\\\":\\\"query\\\",\\\"context\\\":{\\\"custom\\\":[],\\\"labels\\\":[],\\\"db\\\":{\\\"statement\\\":\\\"select * from \\\\\\\"tenants\\\\\\\" where \\\\\\\"tenants\\\\\\\".\\\\\\\"id\\\\\\\" = ? limit 1\\\",\\\"type\\\":\\\"sql\\\"}},\\\"start\\\":376127.517,\\\"duration\\\":17.7,\\\"name\\\":\\\"SELECT tenants\\\",\\\"stacktrace\\\":[],\\\"sync\\\":false,\\\"timestamp\\\":1594937712627416}}\"
2020-07-16T22:08:56.623Z: #39 {main} {"api_response":"{
2020-07-16T22:08:56.623Z: #38 /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/artisan(37): Illuminate\Foundation\Console\Kernel->handle(Object(Symfony\Component\Console\Input\ArgvInput), Object(Symfony\Component\Console\Output\ConsoleOutput))
2020-07-16T22:08:56.623Z: ]
2020-07-16T22:08:56.623Z: #36 /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/vendor/laravel/framework/src/Illuminate/Console/Application.php(93): Symfony\Component\Console\Application->run(Object(Symfony\Component\Console\Input\ArgvInput), Object(Symfony\Component\Console\Output\ConsoleOutput))
2020-07-16T22:08:56.624Z: "}
2020-07-16T22:09:03.201Z: (bas) CMDOUT (0)
2020-07-16T22:09:04.800Z: DIGEST-MD5 common mech free finished)
2020-07-16T22:10:02.701Z: (bas) CMDOUT (0)
2020-07-16T22:10:04.852Z: DIGEST-MD5 common mech free finished)
2020-07-16T22:10:53.920Z: #11 /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/vendor/philkra/elastic-apm-php-agent/src/Middleware/Connector.php(91): GuzzleHttp\Client->__call('post', Array)
2020-07-16T22:10:53.920Z: #12 /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/vendor/philkra/elastic-apm-php-agent/src/Agent.php(271): PhilKra\Middleware\Connector->commit()
2020-07-16T22:10:53.923Z: \"accepted\": 0,
2020-07-16T22:10:53.923Z: \"errors\": [
2020-07-16T22:10:53.919Z: in /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/vendor/guzzlehttp/guzzle/src/Exception/RequestException.php:113
2020-07-16T22:10:53.919Z: Stack trace:
2020-07-16T22:10:53.919Z: #0 /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/vendor/guzzlehttp/guzzle/src/Middleware.php(65): GuzzleHttp\Exception\RequestException::create(Object(GuzzleHttp\Psr7\Request), Object(GuzzleHttp\Psr7\Response))
2020-07-16T22:10:53.921Z: #20 /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/vendor/laravel/framework/src/Illuminate/Queue/Worker.php(132): Illuminate\Queue\Worker->runJob(Object(Illuminate\Queue\Jobs\RedisJob), 'redis', Object(Illuminate\Queue\WorkerOptions))
2020-07-16T22:10:53.921Z: #21 /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/vendor/laravel/framework/src/Illuminate/Queue/Console/WorkCommand.php(112): Illuminate\Queue\Worker->daemon('redis', 'tube5', Object(Illuminate\Queue\WorkerOptions))
2020-07-16T22:10:53.919Z: {
2020-07-16T22:10:53.919Z: "accepted": 0,
2020-07-16T22:10:53.919Z: "errors": [
2020-07-16T22:10:53.919Z: {
2020-07-16T22:10:53.919Z: "message": "did not recognize object type",
2020-07-16T22:10:53.919Z: "document": "{\"span\":{\ (truncated...)
2020-07-16T22:10:53.921Z: #16 /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/vendor/laravel/framework/src/Illuminate/Events/Dispatcher.php(226): Illuminate\Events\Dispatcher->Illuminate\Events\{closure}('Illuminate\\Queu...', Array)
2020-07-16T22:10:53.921Z: #17 /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/vendor/laravel/framework/src/Illuminate/Queue/Worker.php(526): Illuminate\Events\Dispatcher->dispatch('Illuminate\\Queu...')
2020-07-16T22:10:53.921Z: #23 /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/vendor/laravel/horizon/src/Console/WorkCommand.php(46): Illuminate\Queue\Console\WorkCommand->handle()
2020-07-16T22:10:53.921Z: #24 [internal function]: Laravel\Horizon\Console\WorkCommand->handle()
2020-07-16T22:10:53.921Z: #25 /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/vendor/laravel/framework/src/Illuminate/Container/BoundMethod.php(37): call_user_func_array(Array, Array)
2020-07-16T22:10:53.921Z: #26 /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/vendor/laravel/framework/src/Illuminate/Container/Util.php(37): Illuminate\Container\BoundMethod::Illuminate\Container\{closure}()
2020-07-16T22:10:53.923Z: "}
2020-07-16T22:10:53.920Z: #13 /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/vendor/arkaitzgarro/elastic-apm-laravel/src/Collectors/JobCollector.php(115): PhilKra\Agent->send()
2020-07-16T22:10:53.920Z: #14 /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/vendor/arkaitzgarro/elastic-apm-laravel/src/Collectors/JobCollector.php(42): AG\ElasticApmLaravel\Collectors\JobCollector->send(Object(Illuminate\Queue\Jobs\RedisJob))
2020-07-16T22:10:53.920Z: #15 /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/vendor/laravel/framework/src/Illuminate/Events/Dispatcher.php(381): AG\ElasticApmLaravel\Collectors\JobCollector->AG\ElasticApmLaravel\Collectors\{closure}(Object(Illuminate\Queue\Events\JobProcessed))
2020-07-16T22:10:53.922Z: #33 /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/vendor/symfony/console/Application.php(911): Illuminate\Console\Command->run(Object(Symfony\Component\Console\Input\ArgvInput), Object(Symfony\Component\Console\Output\ConsoleOutput))
2020-07-16T22:10:53.922Z: #34 /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/vendor/symfony/console/Application.php(264): Symfony\Component\Console\Application->doRunCommand(Object(Laravel\Horizon\Console\WorkCommand), Object(Symfony\Component\Console\Input\ArgvInput), Object(Symfony\Component\Console\Output\ConsoleOutput))
2020-07-16T22:10:53.922Z: #35 /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/vendor/symfony/console/Application.php(140): Symfony\Component\Console\Application->doRun(Object(Symfony\Component\Console\Input\ArgvInput), Object(Symfony\Component\Console\Output\ConsoleOutput))
2020-07-16T22:10:53.923Z: {
2020-07-16T22:10:53.923Z: \"message\": \"did not recognize object type\",
2020-07-16T22:10:53.923Z: \"document\": \"{\\\"span\\\":{\\\"id\\\":\\\"22d778e0fff986d0\\\",\\\"transaction_id\\\":\\\"a810e7e88614decc\\\",\\\"trace_id\\\":\\\"f26ef789c5eaecbfe8fd87872086c832\\\",\\\"parent_id\\\":\\\"a810e7e88614decc\\\",\\\"type\\\":\\\"db.mysql.query\\\",\\\"action\\\":\\\"query\\\",\\\"context\\\":{\\\"custom\\\":[],\\\"labels\\\":[],\\\"db\\\":{\\\"statement\\\":\\\"select * from \\\\\\\"tenants\\\\\\\" where \\\\\\\"tenants\\\\\\\".\\\\\\\"id\\\\\\\" = ? limit 1\\\",\\\"type\\\":\\\"sql\\\"}},\\\"start\\\":445413.068,\\\"duration\\\":18.49,\\\"name\\\":\\\"SELECT tenants\\\",\\\"stacktrace\\\":[],\\\"sync\\\":false,\\\"timestamp\\\":1594937899084170}}\"
2020-07-16T22:10:53.918Z: [2020-07-16 22:10:53] production.ERROR: GuzzleHttp\Exception\ClientException: Client error: `POST *******
2020-07-16T22:10:53.919Z: #4 /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/vendor/guzzlehttp/promises/src/Promise.php(246): GuzzleHttp\Promise\TaskQueue->run(true)
2020-07-16T22:10:53.920Z: #5 /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/vendor/guzzlehttp/promises/src/Promise.php(223): GuzzleHttp\Promise\Promise->invokeWaitFn()
2020-07-16T22:10:53.920Z: #6 /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/vendor/guzzlehttp/promises/src/Promise.php(267): GuzzleHttp\Promise\Promise->waitIfPending()
2020-07-16T22:10:53.921Z: #27 /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/vendor/laravel/framework/src/Illuminate/Container/BoundMethod.php(95): Illuminate\Container\Util::unwrapIfClosure(Object(Closure))
2020-07-16T22:10:53.922Z: #28 /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/vendor/laravel/framework/src/Illuminate/Container/BoundMethod.php(39): Illuminate\Container\BoundMethod::callBoundMethod(Object(Illuminate\Foundation\Application), Array, Object(Closure))
2020-07-16T22:10:53.922Z: #29 /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/vendor/laravel/framework/src/Illuminate/Container/Container.php(592): Illuminate\Container\BoundMethod::call(Object(Illuminate\Foundation\Application), Array, Array, NULL)
2020-07-16T22:10:53.922Z: #36 /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/vendor/laravel/framework/src/Illuminate/Console/Application.php(93): Symfony\Component\Console\Application->run(Object(Symfony\Component\Console\Input\ArgvInput), Object(Symfony\Component\Console\Output\ConsoleOutput))
2020-07-16T22:10:53.922Z: #37 /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/vendor/laravel/framework/src/Illuminate/Foundation/Console/Kernel.php(129): Illuminate\Console\Application->run(Object(Symfony\Component\Console\Input\ArgvInput), Object(Symfony\Component\Console\Output\ConsoleOutput))
2020-07-16T22:10:53.922Z: #38 /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/artisan(37): Illuminate\Foundation\Console\Kernel->handle(Object(Symfony\Component\Console\Input\ArgvInput), Object(Symfony\Component\Console\Output\ConsoleOutput))
2020-07-16T22:10:53.922Z: #39 {main} {"api_response":"{
2020-07-16T22:10:53.920Z: #7 /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/vendor/guzzlehttp/promises/src/Promise.php(225): GuzzleHttp\Promise\Promise->invokeWaitList()
2020-07-16T22:10:53.920Z: #8 /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/vendor/guzzlehttp/promises/src/Promise.php(62): GuzzleHttp\Promise\Promise->waitIfPending()
2020-07-16T22:10:53.920Z: #9 /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/vendor/guzzlehttp/guzzle/src/Client.php(182): GuzzleHttp\Promise\Promise->wait()
2020-07-16T22:10:53.920Z: #10 /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/vendor/guzzlehttp/guzzle/src/Client.php(95): GuzzleHttp\Client->request('post', 'apm-server-blc2...', Array)
2020-07-16T22:10:53.921Z: #22 /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/vendor/laravel/framework/src/Illuminate/Queue/Console/WorkCommand.php(96): Illuminate\Queue\Console\WorkCommand->runWorker('redis', 'tube5')
2020-07-16T22:10:53.919Z: #1 /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/vendor/guzzlehttp/promises/src/Promise.php(203): GuzzleHttp\Middleware::GuzzleHttp\{closure}(Object(GuzzleHttp\Psr7\Response))
2020-07-16T22:10:53.919Z: #2 /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/vendor/guzzlehttp/promises/src/Promise.php(156): GuzzleHttp\Promise\Promise::callHandler(1, Object(GuzzleHttp\Psr7\Response), Array)
2020-07-16T22:10:53.919Z: #3 /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/vendor/guzzlehttp/promises/src/TaskQueue.php(47): GuzzleHttp\Promise\Promise::GuzzleHttp\Promise\{closure}()
2020-07-16T22:10:53.923Z: }
2020-07-16T22:10:53.923Z: ]
2020-07-16T22:10:53.923Z: }
2020-07-16T22:10:53.921Z: #18 /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/vendor/laravel/framework/src/Illuminate/Queue/Worker.php(358): Illuminate\Queue\Worker->raiseAfterJobEvent('redis', Object(Illuminate\Queue\Jobs\RedisJob))
2020-07-16T22:10:53.921Z: #19 /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/vendor/laravel/framework/src/Illuminate/Queue/Worker.php(306): Illuminate\Queue\Worker->process('redis', Object(Illuminate\Queue\Jobs\RedisJob), Object(Illuminate\Queue\WorkerOptions))
2020-07-16T22:10:53.922Z: #30 /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/vendor/laravel/framework/src/Illuminate/Console/Command.php(134): Illuminate\Container\Container->call(Array)
2020-07-16T22:10:53.922Z: #31 /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/vendor/symfony/console/Command/Command.php(258): Illuminate\Console\Command->execute(Object(Symfony\Component\Console\Input\ArgvInput), Object(Illuminate\Console\OutputStyle))
2020-07-16T22:10:53.922Z: #32 /home/bas/app_a5d1fed8-fb86-4fd9-9474-0aee5c2d530a/vendor/laravel/framework/src/Illuminate/Console/Command.php(121): Symfony\Component\Console\Command\Command->run(Object(Symfony\Component\Console\Input\ArgvInput), Object(Illuminate\Console\OutputStyle))
from elastic-apm-laravel.
Hmm ok, so it's a span for DB queries what it's failing for your, not jobs as we thought. I would suggest that until we find out what's the issue, you disable the DB spans. Can you add APM_QUERYLOG=false
to your .env
file, and confirm that it doesn't show errors?
from elastic-apm-laravel.
Thank you @arkaitzgarro .
I'm doing it right now. But just to let you know that all my queries are ok on those jobs.
from elastic-apm-laravel.
It's confirmed. Without query logs, no error in logs.
from elastic-apm-laravel.
I think I figured out the cause of this. When I post to apm server manually, I get this error for any transaction or span when metadata is not included as well. I adjusted the logging you did in #58 to also include the request, and when I get the failure it doesn't have the metadata line. I'll look into it a bit more now (no promises beyond that 😅)but if that rings a bell at all let me know.
from elastic-apm-laravel.
@arkaitzgarro I didn't get a chance to really confirm, but at times what I seem to be experiencing is that the first job in a worker will post correctly, but then it doesn't reset the metadata and fails all subsequent jobs. I actually can't really see a good way to set that metadata because of the private nature of the Agent internals.
from elastic-apm-laravel.
Thanks for the investigations @cykirsch, it may be the case looking at the code. The agent puts a metadata event when it's initialised the first time, which only happens once for async workers, and then it does it again under a conditional inside the send method. Since the transaction store is reset after events has been sent, consequent transactions will miss the metadata.
Funny enough, @dstepe was already questioning the reasoning of this behaviour. I think metadata can/should always be set in the send method to make sure is always present, but this is a decision the agent should make, it's not something we will solve in this package.
from elastic-apm-laravel.
I'll start looking into this on the Agent side. The expectation is that "the first "event" in each ND-JSON stream contains metadata to fold into subsequent events" (https://github.com/elastic/apm/blob/master/specs/agents/metadata.md). Since each Agent::send()
call will create a new connection, the metadata should be included each time. It appears that the current send()
code is aware of this and attempts to add it if needed, so I'll need to do some testing to determine what's going on.
from elastic-apm-laravel.
@arkaitzgarro and @cykirsch, I believe I understand the problem, and may have a quick fix for you. The underlying issue is how events are captured. We currently employ two approaches. First, the Agent
class records started Transactions
and will push them on to the Connector
. Second, the Agent::putEvent()
method is called to create child Span
objects, and pushes them directly on to the Connector
.
The problem you have observed manifests when Span
objects are added using Agent::putEvent()
which occurs before the check for the empty payload and also before Transactions
from the Agent
are added. The end result is that the payload is never empty in that scenario so the Metadata
is never added after the initial creation.
This is another manifestation of what I believe are underlying design problems with the way event collection is being done. I'm already planning to rework event collection in the next major release of the agent package, but that won't help you right now.
I believe there is another potential issue with the EventDataCollector
objects. I don't see that they are being reset after sending and my observation is that they accumulate events between jobs and therefore the same event is sent multiple times.
I should have a PR soon that may offer an easy solution for both of these issues as a short term fix.
from elastic-apm-laravel.
Related Issues (20)
- Issue with Octane HOT 1
- Use of undefined constant LARAVEL_START - assumed 'LARAVEL_START' (this will throw an Error in a future version of PHP) HOT 3
- Did not collect data from Api routes HOT 1
- Return value of AG\ElasticApmLaravel\ServiceProvider::getAppConfig() must be of the type array, null returned HOT 4
- installation error HOT 2
- installation error HOT 7
- Logs for deprecated parameters
- Apm setup HOT 4
- Laravel 9? HOT 12
- Laravel Octane Support HOT 8
- Standard ELASTIC_APM_ENVIRONMENT value is not used correctly
- Build failing due to failure in the Command collector HOT 3
- Transaction not getting associated with Errors on Elastic Cloud APM HOT 1
- Send only Transactions associated with Exceptions to APM Server HOT 1
- Application ENV not picked up by agent HOT 1
- Need to include latest version of nipwaayoni/elastic-apm-php-agent HOT 2
- Jobs not tracked HOT 8
- AG\ElasticApmLaravel\Collectors\EventDataCollector::shouldIgnoreTransaction(): Argument #1 ($transaction_name) must be of type string, HOT 6
- Laravel Telescope Support HOT 1
- Is there a reason that this agent doesn't allow collecting stacktraces? HOT 2
Recommend Projects
-
React
A declarative, efficient, and flexible JavaScript library for building user interfaces.
-
Vue.js
🖖 Vue.js is a progressive, incrementally-adoptable JavaScript framework for building UI on the web.
-
Typescript
TypeScript is a superset of JavaScript that compiles to clean JavaScript output.
-
TensorFlow
An Open Source Machine Learning Framework for Everyone
-
Django
The Web framework for perfectionists with deadlines.
-
Laravel
A PHP framework for web artisans
-
D3
Bring data to life with SVG, Canvas and HTML. 📊📈🎉
-
Recommend Topics
-
javascript
JavaScript (JS) is a lightweight interpreted programming language with first-class functions.
-
web
Some thing interesting about web. New door for the world.
-
server
A server is a program made to process requests and deliver data to clients.
-
Machine learning
Machine learning is a way of modeling and interpreting data that allows a piece of software to respond intelligently.
-
Visualization
Some thing interesting about visualization, use data art
-
Game
Some thing interesting about game, make everyone happy.
Recommend Org
-
Facebook
We are working to build community through open source technology. NB: members must have two-factor auth.
-
Microsoft
Open source projects and samples from Microsoft.
-
Google
Google ❤️ Open Source for everyone.
-
Alibaba
Alibaba Open Source for everyone
-
D3
Data-Driven Documents codes.
-
Tencent
China tencent open source team.
from elastic-apm-laravel.