Java, Spring Boot 3.1.1 - The attached APM agent doesn't separate KafkaListeners and Scheduled tasks to separate transactions

SerhiiM · July 19, 2023, 10:16am

Kibana version: docker.elastic.co/kibana/kibana:8.7.0

Elasticsearch version: docker.elastic.co/elasticsearch/elasticsearch:8.7.0

APM Server version: docker.elastic.co/apm/apm-server:8.7.0

APM Agent language and version: java - co.elastic.apm.apm-agent-attach:1.39.0

Browser version: N/A

Original install method (e.g. download page, yum, deb, from source, etc.) and version: From Maven repository

Fresh install or upgraded from other version? Fresh install

Description of the problem including expected versus actual behavior. Please include screenshots (if relevant):
The attached agent collects the spans from services but for @Scheduled, @KafkaListener and @RetryableTopic all cations are collected as spans in one long transaction Application#main without details:

If I create my own transaction with apm-agent-api like:

@Scheduled(cron = "0 */1 * * * *")
public void check() throws InterruptedException {
        Transaction transaction = co.elastic.apm.api.ElasticApm.startTransaction();
        transaction.activate();
        transaction.setName("checkExpiredTickets42");
        transaction.setType("scheduled");
        ... script ...
        transaction.end();
    }

It creates separate Transaction and Warning:

[scheduling-1] WARN  co.elastic.apm.agent.impl.ActiveStack - Deactivating a context ('TicketsTask#checkExpiredTickets' 00-14f310d910f4ccb8315a1a1fc13691dc-2f40510285488d60-01 (45d40555)) which is not the currently active one ('checkExpiredTickets42' 00-98e8fc68e16c0ffb4994bf384568d847-4972ea87763ce49d-01 (15fafcfc)). This can happen when not properly deactivating a previous span or context.

Kafka listeners ganerate enother warnings:

[org.springframework.kafka.KafkaListenerEndpointContainer#0-retry-9000-3-C-1] WARN  co.elastic.apm.agent.impl.transaction.Span - Max spans (20000) for transaction 'CashierApplication#main' 00-7ae399be1cf8cae4fdfc882c5302661f-721bf1382278791e-01 (34e7fdc6) has been reached. For this transaction and possibly others, further spans will be dropped. See config param 'transaction_max_spans'.

Curernt Agent configuration:

enabled=true
#log_level=DEBUG
service_name=cashier-service
secret_token=secret
server_url=http://apm-server:8200
environment=dev
application_packages=com.company
recording=true
use_path_as_transaction_name=true
transaction_max_spans=20000
max_queue_size=100000
api_request_size=2mb
metrics_interval=5s
stack_trace_limit=-1
#capture_body=all
trace_methods=com.company.*
trace_methods_duration_threshold=1ms
span_stack_trace_min_duration=1ms
transaction_sample_rate=1
use_elastic_traceparent_header=true
enable_public_api_annotation_inheritance=true
use_jaxrs_path_as_transaction_name=true
log_ecs_reformatting=REPLACE
log_sending=true
enable_log_correlation=true
profiling_inferred_spans_enabled=true

What did I do wrong and what I should change?

Steps to reproduce:

Setup Spring Boot with @KafkaListere and @Sheduled actions
Setup Kafka Observability Stack
Observer the background processes and Kafka consumers

Jonas_Kunz · July 24, 2023, 10:38am

[scheduling-1] WARN co.elastic.apm.agent.impl.ActiveStack - Deactivating a context ('TicketsTask#checkExpiredTickets' 00-14f310d910f4ccb8315a1a1fc13691dc-2f40510285488d60-01 (45d40555)) which is not the currently active one ('checkExpiredTickets42' 00-98e8fc68e16c0ffb4994bf384568d847-4972ea87763ce49d-01 (15fafcfc)). This can happen when not properly deactivating a previous span or context.

This error message indicates that the manual instrumentation you added does not always deactivate the started transaction. This means, that the transaction wrongly stays active for that thread, which likely is part of a ThreadPool which is also used by your @KafkaListener, causing them to get mixed up.

The reason for this is very likely that you @Scheduled threw an exception:

@Scheduled(cron = "0 */1 * * * *")
public void check() throws InterruptedException {
        Transaction transaction = co.elastic.apm.api.ElasticApm.startTransaction();
        transaction.activate();
        transaction.setName("checkExpiredTickets42");
        transaction.setType("scheduled");
        ... script ...
        transaction.end();
    }

If the ...script... part throws an exception, transaction.end() will never be called. You should use try .. finally to make sure that transaction.end() is always called:

@Scheduled(cron = "0 */1 * * * *")
public void check() throws InterruptedException {
        Transaction transaction = co.elastic.apm.api.ElasticApm.startTransaction();
        transaction.activate();
        try {
            transaction.setName("checkExpiredTickets42");
            transaction.setType("scheduled");
            ... script ...
        } finally {
            transaction.end();
        }
    }

You can avoid these kind of problems by using annotations instead of code based instrumentation.

SerhiiM · July 24, 2023, 11:55am

Hello @Jonas_Kunz, thank you for your time.
I already experimented with the end of the transaction in the final case, it doesn't change the behaviour of the agent.

When I'm using @CaptureTransaction it doesn't work as it works only when the transaction has not started.
But as I display on the screenshot with the main transaction, It looks as if the Application#main transaction started with the application and never will be finished.
And I can't separate all background tasks into different transactions

Jonas_Kunz · July 24, 2023, 12:20pm

Sorry, I missed that all spans appear below Application#main.

I think the root cause here is that your trace_methods=com.company.* configuration is way to broad.

You should refine it so that your main method is not hit by it.
Alternatively you can configure disable_instrumentations=executor. This will disable transaction propagation across ExecutorServices.

SerhiiM · July 24, 2023, 1:44pm

Thanks, both variant helps with @Scheduled tasks I see it now in a separate tab, but the information about @KafkaListenets has completely disappeared from Kibana

Jonas_Kunz · July 26, 2023, 7:36am

The @KafkaListener methods should be shown as separate Transactions named Kafka record from .... In case you don't have those please provide the debug logs, so that we can check why the instrumentation is not working correctly for you.

SerhiiM · July 27, 2023, 12:27pm

I found this in debug log but can't find these transactions in Kibana...

cashier  | 2023-07-27 12:17:00,677 [elastic-apm-server-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving METRICSET_JSON_WRITER event (sequence 30254)
cashier  | 2023-07-27 12:17:01,312 [org.springframework.kafka.KafkaListenerEndpointContainer#1-0-C-1] DEBUG co.elastic.apm.agent.impl.transaction.AbstractSpan - increment references to '' 00-0a461e04069415430508b2fceb45d0fe-baa78f428091de4e-00 (1f4c96c5) (1)
cashier  | 2023-07-27 12:17:01,312 [org.springframework.kafka.KafkaListenerEndpointContainer#1-0-C-1] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - startTransaction '' 00-0a461e04069415430508b2fceb45d0fe-baa78f428091de4e-00 (1f4c96c5)
cashier  | 2023-07-27 12:17:01,312 [org.springframework.kafka.KafkaListenerEndpointContainer#1-0-C-1] DEBUG co.elastic.apm.agent.impl.ActiveStack - Activating 'Kafka record from close-events' 00-0a461e04069415430508b2fceb45d0fe-baa78f428091de4e-00 (1f4c96c5) on thread 303
cashier  | 2023-07-27 12:17:01,312 [org.springframework.kafka.KafkaListenerEndpointContainer#1-0-C-1] DEBUG co.elastic.apm.agent.impl.transaction.AbstractSpan - increment references to 'Kafka record from close-events' 00-0a461e04069415430508b2fceb45d0fe-baa78f428091de4e-00 (1f4c96c5) (2)
cashier  | 2023-07-27T12:17:01.313Z DEBUG 72 --- [ntainer#1-0-C-1] c.l.r.c.queue.CloseEventsConsumer    : ---> listener close-events got event - 648b19d43ab71706e11805b9
cashier  | 2023-07-27 12:17:01,313 [org.springframework.kafka.KafkaListenerEndpointContainer#1-0-C-1] DEBUG co.elastic.apm.agent.pluginapi.CaptureTransactionInstrumentation - Not creating transaction for method CloseEventsConsumer#process because there is already a transaction running ('Kafka record from close-events' 00-0a461e04069415430508b2fceb45d0fe-baa78f428091de4e-00 (1f4c96c5))
cashier  | 2023-07-27 12:17:01,313 [org.springframework.kafka.KafkaListenerEndpointContainer#1-0-C-1] DEBUG co.elastic.apm.agent.impl.transaction.Span - startSpan '' 00-0a461e04069415430508b2fceb45d0fe-baa78f428091de4e-00 (316c6514)
cashier  | 2023-07-27 12:17:01,313 [org.springframework.kafka.KafkaListenerEndpointContainer#1-0-C-1] DEBUG co.elastic.apm.agent.impl.transaction.AbstractSpan - increment references to 'Kafka record from close-events' 00-0a461e04069415430508b2fceb45d0fe-baa78f428091de4e-00 (1f4c96c5) (3)
cashier  | 2023-07-27 12:17:01,313 [org.springframework.kafka.KafkaListenerEndpointContainer#1-0-C-1] DEBUG co.elastic.apm.agent.impl.transaction.AbstractSpan - increment references to '' 00-0a461e04069415430508b2fceb45d0fe-baa78f428091de4e-00 (316c6514) (1)
cashier  | 2023-07-27 12:17:01,313 [org.springframework.kafka.KafkaListenerEndpointContainer#1-0-C-1] DEBUG co.elastic.apm.agent.impl.transaction.AbstractSpan - increment references to 'Kafka record from close-events' 00-0a461e04069415430508b2fceb45d0fe-baa78f428091de4e-00 (1f4c96c5) (4)
cashier  | 2023-07-27 12:17:01,314 [org.springframework.kafka.KafkaListenerEndpointContainer#1-0-C-1] DEBUG co.elastic.apm.agent.impl.ActiveStack - Activating 'database.tickets.aggregate' 00-0a461e04069415430508b2fceb45d0fe-baa78f428091de4e-00 (316c6514) on thread 303
cashier  | 2023-07-27 12:17:01,314 [org.springframework.kafka.KafkaListenerEndpointContainer#1-0-C-1] DEBUG co.elastic.apm.agent.impl.transaction.AbstractSpan - increment references to 'Kafka record from close-events' 00-0a461e04069415430508b2fceb45d0fe-baa78f428091de4e-00 (1f4c96c5) (5)
cashier  | 2023-07-27 12:17:01,314 [org.springframework.kafka.KafkaListenerEndpointContainer#1-0-C-1] DEBUG co.elastic.apm.agent.impl.transaction.AbstractSpan - increment references to 'database.tickets.aggregate' 00-0a461e04069415430508b2fceb45d0fe-baa78f428091de4e-00 (316c6514) (2)
cashier  | 2023-07-27 12:17:01,316 [org.springframework.kafka.KafkaListenerEndpointContainer#1-0-C-1] DEBUG co.elastic.apm.agent.impl.ActiveStack - Deactivating 'database.tickets.aggregate' 00-0a461e04069415430508b2fceb45d0fe-baa78f428091de4e-00 (316c6514) on thread 303
cashier  | 2023-07-27 12:17:01,316 [org.springframework.kafka.KafkaListenerEndpointContainer#1-0-C-1] DEBUG co.elastic.apm.agent.impl.transaction.AbstractSpan - decrement references to 'Kafka record from close-events' 00-0a461e04069415430508b2fceb45d0fe-baa78f428091de4e-00 (1f4c96c5) (4)
cashier  | 2023-07-27 12:17:01,316 [org.springframework.kafka.KafkaListenerEndpointContainer#1-0-C-1] DEBUG co.elastic.apm.agent.impl.transaction.AbstractSpan - decrement references to 'database.tickets.aggregate' 00-0a461e04069415430508b2fceb45d0fe-baa78f428091de4e-00 (316c6514) (1)
cashier  | 2023-07-27 12:17:01,316 [org.springframework.kafka.KafkaListenerEndpointContainer#1-0-C-1] DEBUG co.elastic.apm.agent.impl.transaction.AbstractSpan - increment references to 'Kafka record from close-events' 00-0a461e04069415430508b2fceb45d0fe-baa78f428091de4e-00 (1f4c96c5) (5)
cashier  | 2023-07-27 12:17:01,316 [org.springframework.kafka.KafkaListenerEndpointContainer#1-0-C-1] DEBUG co.elastic.apm.agent.impl.transaction.AbstractSpan - increment references to 'database.tickets.aggregate' 00-0a461e04069415430508b2fceb45d0fe-baa78f428091de4e-00 (316c6514) (2)
cashier  | 2023-07-27 12:17:01,316 [org.springframework.kafka.KafkaListenerEndpointContainer#1-0-C-1] DEBUG co.elastic.apm.agent.impl.transaction.AbstractSpan - increment references to 'Kafka record from close-events' 00-0a461e04069415430508b2fceb45d0fe-baa78f428091de4e-00 (1f4c96c5) (6)
cashier  | 2023-07-27 12:17:01,316 [org.springframework.kafka.KafkaListenerEndpointContainer#1-0-C-1] DEBUG co.elastic.apm.agent.impl.transaction.AbstractSpan - increment references to 'database.tickets.aggregate' 00-0a461e04069415430508b2fceb45d0fe-baa78f428091de4e-00 (316c6514) (3)
cashier  | 2023-07-27 12:17:01,316 [org.springframework.kafka.KafkaListenerEndpointContainer#1-0-C-1] DEBUG co.elastic.apm.agent.impl.transaction.AbstractSpan - decrement references to 'Kafka record from close-events' 00-0a461e04069415430508b2fceb45d0fe-baa78f428091de4e-00 (1f4c96c5) (5)
cashier  | 2023-07-27 12:17:01,316 [org.springframework.kafka.KafkaListenerEndpointContainer#1-0-C-1] DEBUG co.elastic.apm.agent.impl.transaction.AbstractSpan - decrement references to 'Kafka record from close-events' 00-0a461e04069415430508b2fceb45d0fe-baa78f428091de4e-00 (1f4c96c5) (4)
cashier  | 2023-07-27 12:17:01,316 [org.springframework.kafka.KafkaListenerEndpointContainer#1-0-C-1] DEBUG co.elastic.apm.agent.impl.transaction.AbstractSpan - decrement references to 'database.tickets.aggregate' 00-0a461e04069415430508b2fceb45d0fe-baa78f428091de4e-00 (316c6514) (2)
cashier  | 2023-07-27T12:17:01.316Z DEBUG 72 --- [ntainer#1-0-C-1] c.l.r.c.queue.CloseEventsConsumer    : ----> entities for tags [tag-1-1690460161308, tag-2-1690460161308] - 0
cashier  | 2023-07-27 12:17:01,318 [org.springframework.kafka.KafkaListenerEndpointContainer#1-0-C-1] DEBUG co.elastic.apm.agent.impl.ActiveStack - Deactivating 'Kafka record from close-events' 00-0a461e04069415430508b2fceb45d0fe-baa78f428091de4e-00 (1f4c96c5) on thread 303
cashier  | 2023-07-27 12:17:01,318 [org.springframework.kafka.KafkaListenerEndpointContainer#1-0-C-1] DEBUG co.elastic.apm.agent.impl.transaction.AbstractSpan - decrement references to 'Kafka record from close-events' 00-0a461e04069415430508b2fceb45d0fe-baa78f428091de4e-00 (1f4c96c5) (3)
cashier  | 2023-07-27 12:17:01,318 [org.springframework.kafka.KafkaListenerEndpointContainer#1-0-C-1] DEBUG co.elastic.apm.agent.impl.transaction.AbstractSpan - increment references to 'Kafka record from close-events' 00-0a461e04069415430508b2fceb45d0fe-baa78f428091de4e-00 (1f4c96c5) (4)
cashier  | 2023-07-27 12:17:01,318 [org.springframework.kafka.KafkaListenerEndpointContainer#1-0-C-1] DEBUG co.elastic.apm.agent.impl.transaction.AbstractSpan - increment references to 'database.tickets.aggregate' 00-0a461e04069415430508b2fceb45d0fe-baa78f428091de4e-00 (316c6514) (3)
cashier  | 2023-07-27 12:17:01,318 [org.springframework.kafka.KafkaListenerEndpointContainer#1-0-C-1] DEBUG co.elastic.apm.agent.impl.transaction.AbstractSpan - decrement references to 'Kafka record from close-events' 00-0a461e04069415430508b2fceb45d0fe-baa78f428091de4e-00 (1f4c96c5) (3)
cashier  | 2023-07-27 12:17:01,318 [org.springframework.kafka.KafkaListenerEndpointContainer#1-0-C-1] DEBUG co.elastic.apm.agent.impl.transaction.AbstractSpan - decrement references to 'database.tickets.aggregate' 00-0a461e04069415430508b2fceb45d0fe-baa78f428091de4e-00 (316c6514) (2)
cashier  | 2023-07-27 12:17:01,318 [org.springframework.kafka.KafkaListenerEndpointContainer#1-0-C-1] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - endSpan 'database.tickets.aggregate' 00-0a461e04069415430508b2fceb45d0fe-baa78f428091de4e-00 (316c6514)
cashier  | 2023-07-27 12:17:01,318 [org.springframework.kafka.KafkaListenerEndpointContainer#1-0-C-1] DEBUG co.elastic.apm.agent.impl.transaction.AbstractSpan - decrement references to 'Kafka record from close-events' 00-0a461e04069415430508b2fceb45d0fe-baa78f428091de4e-00 (1f4c96c5) (2)
cashier  | 2023-07-27 12:17:01,318 [org.springframework.kafka.KafkaListenerEndpointContainer#1-0-C-1] DEBUG co.elastic.apm.agent.impl.transaction.AbstractSpan - decrement references to 'database.tickets.aggregate' 00-0a461e04069415430508b2fceb45d0fe-baa78f428091de4e-00 (316c6514) (1)
cashier  | 2023-07-27 12:17:01,318 [org.springframework.kafka.KafkaListenerEndpointContainer#1-0-C-1] DEBUG co.elastic.apm.agent.impl.transaction.AbstractSpan - decrement references to 'Kafka record from close-events' 00-0a461e04069415430508b2fceb45d0fe-baa78f428091de4e-00 (1f4c96c5) (1)
cashier  | 2023-07-27 12:17:01,318 [org.springframework.kafka.KafkaListenerEndpointContainer#1-0-C-1] DEBUG co.elastic.apm.agent.impl.transaction.AbstractSpan - decrement references to 'database.tickets.aggregate' 00-0a461e04069415430508b2fceb45d0fe-baa78f428091de4e-00 (316c6514) (0)
cashier  | 2023-07-27 12:17:01,318 [org.springframework.kafka.KafkaListenerEndpointContainer#1-0-C-1] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - endTransaction 'Kafka record from close-events' 00-0a461e04069415430508b2fceb45d0fe-baa78f428091de4e-00 (1f4c96c5)
cashier  | 2023-07-27 12:17:01,318 [org.springframework.kafka.KafkaListenerEndpointContainer#1-0-C-1] DEBUG co.elastic.apm.agent.impl.transaction.AbstractSpan - decrement references to 'Kafka record from close-events' 00-0a461e04069415430508b2fceb45d0fe-baa78f428091de4e-00 (1f4c96c5) (0)
cashier  | 2023-07-27 12:17:01,320 [elastic-apm-server-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving BYTES_LOG event (sequence 30255)
cashier  | 2023-07-27 12:17:01,320 [elastic-apm-server-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving BYTES_LOG event (sequence 30256)
cashier  | 2023-07-27 12:17:01,320 [elastic-apm-server-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving BYTES_LOG event (sequence 30257)

Jonas_Kunz · July 27, 2023, 12:58pm

Did you select the correct transaction type filter in Kibana?
The Kafka transactions do not have the type messaging instead of request.
See the highlighted dropdown in my screenshot:

SerhiiM · July 27, 2023, 1:03pm

It would be too easy))
Kafka consumer get minimum 1 message per minute, but here I can't find it

Also, I tried to find it in Elastic search:

And it stop displaing in this section

Jonas_Kunz · July 31, 2023, 9:58am

That's really strange.

I would suggest you to do the following to debug this behaviour:
Enable trace-level logs on the APM agent. Unfortunately those will be very verbose. Those logs will also contain the actual JSON payload the APM agent is sending to the APM server.
Search those logs for the Kafka-transactions and verify that those are present. Then we can inspect those JSONs and see if something is off.

SerhiiM · August 1, 2023, 3:47pm

I see only one thing which repeats with some time and looks like an error:

{"log":"\u0009at java.lang.Thread.run(Thread.java:833) [?:?]\n","stream":"stdout","time":"2023-08-01T14:23:33.100350391Z"}
{"log":"2023-08-01 14:23:33,100 [org.springframework.kafka.KafkaListenerEndpointContainer#1-0-C-1] DEBUG co.elastic.apm.agent.impl.transaction.AbstractSpan - increment references to 'company.tickets.aggregate' 00-cf7c04e347408da2a71263d880093f21-3ff705e5d91cfb4f-00 (3639d4dc) (3)\n","stream":"stdout","time":"2023-08-01T14:23:33.100356086Z"}
{"log":"2023-08-01 14:23:33,100 [org.springframework.kafka.KafkaListenerEndpointContainer#1-0-C-1] TRACE co.elastic.apm.agent.impl.transaction.AbstractSpan - incrementing references at\n","stream":"stdout","time":"2023-08-01T14:23:33.10054987Z"}
{"log":"java.lang.RuntimeException: This is an expected exception. Is just used to record where the reference count has been incremented.\n","stream":"stdout","time":"2023-08-01T14:23:33.10055906Z"}
{"log":"\u0009at co.elastic.apm.agent.impl.transaction.AbstractSpan.incrementReferences(AbstractSpan.java:673) ~[elastic-apm-agent-4813494d137e1631bba301d5acab6e7b-e6256b9ad98d9992211305097d439d61.jar:1.39.0]\n","stream":"stdout","time":"2023-08-01T14:23:33.100563349Z"}
{"log":"\u0009at co.elastic.apm.agent.impl.transaction.Span.incrementReferences(Span.java:488) ~[elastic-apm-agent-4813494d137e1631bba301d5acab6e7b-e6256b9ad98d9992211305097d439d61.jar:1.39.0]\n","stream":"stdout","time":"2023-08-01T14:23:33.100567272Z"}
{"log":"\u0009at co.elastic.apm.agent.impl.transaction.SpanAtomicReference.compareAndSet(SpanAtomicReference.java:58) ~[elastic-apm-agent-4813494d137e1631bba301d5acab6e7b-e6256b9ad98d9992211305097d439d61.jar:1.39.0]\n","stream":"stdout","time":"2023-08-01T14:23:33.100570914Z"}
{"log":"\u0009at co.elastic.apm.agent.impl.transaction.Span.afterEnd(Span.java:290) ~[elastic-apm-agent-4813494d137e1631bba301d5acab6e7b-e6256b9ad98d9992211305097d439d61.jar:1.39.0]\n","stream":"stdout","time":"2023-08-01T14:23:33.100574464Z"}
{"log":"\u0009at co.elastic.apm.agent.impl.transaction.AbstractSpan.end(AbstractSpan.java:581) ~[elastic-apm-agent-4813494d137e1631bba301d5acab6e7b-e6256b9ad98d9992211305097d439d61.jar:1.39.0]\n","stream":"stdout","time":"2023-08-01T14:23:33.100577958Z"}
{"log":"\u0009at co.elastic.apm.agent.impl.transaction.AbstractSpan.end(AbstractSpan.java:559) ~[elastic-apm-agent-4813494d137e1631bba301d5acab6e7b-e6256b9ad98d9992211305097d439d61.jar:1.39.0]\n","stream":"stdout","time":"2023-08-01T14:23:33.100581498Z"}
{"log":"\u0009at co.elastic.apm.agent.mongodb.v4.ConnectionCommandInstrumentation$AdviceClass.onExit(ConnectionCommandInstrumentation.java:81) ~[elastic-apm-agent-4813494d137e1631bba301d5acab6e7b-e6256b9ad98d9992211305097d439d61.jar:1.39.0]\n","stream":"stdout","time":"2023-08-01T14:23:33.100585145Z"}
{"log":"\u0009at com.mongodb.internal.connection.DefaultServer$OperationCountTrackingConnection.command(DefaultServer.java:288) ~[mongodb-driver-core-4.9.1.jar:?]\n","stream":"stdout","time":"2023-08-01T14:23:33.100588685Z"}
{"log":"\u0009at com.mongodb.internal.operation.CommandOperationHelper.createReadCommandAndExecute(CommandOperationHelper.java:239) ~[mongodb-driver-core-4.9.1.jar:?]\n","stream":"stdout","time":"2023-08-01T14:23:33.100592053Z"}
{"log":"\u0009at com.mongodb.internal.operation.CommandOperationHelper.lambda$executeRetryableRead$4(CommandOperationHelper.java:220) ~[mongodb-driver-core-4.9.1.jar:?]\n","stream":"stdout","time":"2023-08-01T14:23:33.100596025Z"}
{"log":"\u0009at com.mongodb.internal.operation.OperationHelper.lambda$withSourceAndConnection$0(OperationHelper.java:358) ~[mongodb-driver-core-4.9.1.jar:?]\n","stream":"stdout","time":"2023-08-01T14:23:33.100599715Z"}
{"log":"\u0009at com.mongodb.internal.operation.OperationHelper.withSuppliedResource(OperationHelper.java:383) ~[mongodb-driver-core-4.9.1.jar:?]\n","stream":"stdout","time":"2023-08-01T14:23:33.100610363Z"}
{"log":"\u0009at com.mongodb.internal.operation.OperationHelper.lambda$withSourceAndConnection$1(OperationHelper.java:357) ~[mongodb-driver-core-4.9.1.jar:?]\n","stream":"stdout","time":"2023-08-01T14:23:33.100614423Z"}
{"log":"\u0009at com.mongodb.internal.operation.OperationHelper.withSuppliedResource(OperationHelper.java:383) ~[mongodb-driver-core-4.9.1.jar:?]\n","stream":"stdout","time":"2023-08-01T14:23:33.100618232Z"}
{"log":"\u0009at com.mongodb.internal.operation.OperationHelper.withSourceAndConnection(OperationHelper.java:356) ~[mongodb-driver-core-4.9.1.jar:?]\n","stream":"stdout","time":"2023-08-01T14:23:33.100621611Z"}
{"log":"\u0009at com.mongodb.internal.operation.CommandOperationHelper.lambda$executeRetryableRead$5(CommandOperationHelper.java:218) ~[mongodb-driver-core-4.9.1.jar:?]\n","stream":"stdout","time":"2023-08-01T14:23:33.1006253Z"}
{"log":"\u0009at com.mongodb.internal.async.function.RetryingSyncSupplier.get(RetryingSyncSupplier.java:67) ~[mongodb-driver-core-4.9.1.jar:?]\n","stream":"stdout","time":"2023-08-01T14:23:33.10062888Z"}
{"log":"\u0009at com.mongodb.internal.operation.CommandOperationHelper.executeRetryableRead(CommandOperationHelper.java:223) ~[mongodb-driver-core-4.9.1.jar:?]\n","stream":"stdout","time":"2023-08-01T14:23:33.10063226Z"}
{"log":"\u0009at com.mongodb.internal.operation.CommandOperationHelper.executeRetryableRead(CommandOperationHelper.java:204) ~[mongodb-driver-core-4.9.1.jar:?]\n","stream":"stdout","time":"2023-08-01T14:23:33.100636028Z"}
{"log":"\u0009at com.mongodb.internal.operation.AggregateOperationImpl.execute(AggregateOperationImpl.java:191) ~[mongodb-driver-core-4.9.1.jar:?]\n","stream":"stdout","time":"2023-08-01T14:23:33.100639649Z"}
{"log":"\u0009at com.mongodb.internal.operation.AggregateOperation.execute(AggregateOperation.java:152) ~[mongodb-driver-core-4.9.1.jar:?]\n","stream":"stdout","time":"2023-08-01T14:23:33.100643047Z"}
{"log":"\u0009at com.mongodb.internal.operation.AggregateOperation.execute(AggregateOperation.java:44) ~[mongodb-driver-core-4.9.1.jar:?]\n","stream":"stdout","time":"2023-08-01T14:23:33.100646419Z"}
{"log":"\u0009at com.mongodb.client.internal.MongoClientDelegate$DelegateOperationExecutor.execute(MongoClientDelegate.java:185) ~[mongodb-driver-sync-4.9.1.jar:?]\n","stream":"stdout","time":"2023-08-01T14:23:33.100649681Z"}
{"log":"\u0009at com.mongodb.client.internal.MongoIterableImpl.execute(MongoIterableImpl.java:130) ~[mongodb-driver-sync-4.9.1.jar:?]\n","stream":"stdout","time":"2023-08-01T14:23:33.10065317Z"}
{"log":"\u0009at com.mongodb.client.internal.MongoIterableImpl.iterator(MongoIterableImpl.java:90) ~[mongodb-driver-sync-4.9.1.jar:?]\n","stream":"stdout","time":"2023-08-01T14:23:33.100656939Z"}
{"log":"\u0009at com.mongodb.client.internal.MongoIterableImpl.first(MongoIterableImpl.java:101) ~[mongodb-driver-sync-4.9.1.jar:?]\n","stream":"stdout","time":"2023-08-01T14:23:33.100660347Z"}
{"log":"\u0009at com.company.retail.cashier.services.impl.EventServiceImpl.getEventsCountByGameAndTags(EventServiceImpl.java:179) ~[classes/:?]\n","stream":"stdout","time":"2023-08-01T14:23:33.100663558Z"}
{"log":"\u0009at com.company.retail.cashier.queue.CloseEventsConsumer.process(CloseEventsConsumer.java:87) ~[classes/:?]\n","stream":"stdout","time":"2023-08-01T14:23:33.100666783Z"}
{"log":"\u0009at com.company.retail.cashier.queue.CloseEventsConsumer.commonListenerForMultipleTopics(CloseEventsConsumer.java:77) ~[classes/:?]\n","stream":"stdout","time":"2023-08-01T14:23:33.100669967Z"}
{"log":"\u0009at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]\n","stream":"stdout","time":"2023-08-01T14:23:33.100673449Z"}
{"log":"\u0009at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77) ~[?:?]\n","stream":"stdout","time":"2023-08-01T14:23:33.100676601Z"}
{"log":"\u0009at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]\n","stream":"stdout","time":"2023-08-01T14:23:33.100686832Z"}
{"log":"\u0009at java.lang.reflect.Method.invoke(Method.java:568) ~[?:?]\n","stream":"stdout","time":"2023-08-01T14:23:33.100690516Z"}
{"log":"\u0009at org.springframework.messaging.handler.invocation.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:169) ~[spring-messaging-6.0.10.jar:6.0.10]\n","stream":"stdout","time":"2023-08-01T14:23:33.100693797Z"}
{"log":"\u0009at org.springframework.messaging.handler.invocation.InvocableHandlerMethod.invoke(InvocableHandlerMethod.java:119) ~[spring-messaging-6.0.10.jar:6.0.10]\n","stream":"stdout","time":"2023-08-01T14:23:33.100697357Z"}
{"log":"\u0009at org.springframework.kafka.listener.adapter.HandlerAdapter.invoke(HandlerAdapter.java:56) ~[spring-kafka-3.0.8.jar:3.0.8]\n","stream":"stdout","time":"2023-08-01T14:23:33.100700795Z"}
{"log":"\u0009at org.springframework.kafka.listener.adapter.MessagingMessageListenerAdapter.invokeHandler(MessagingMessageListenerAdapter.java:375) ~[spring-kafka-3.0.8.jar:3.0.8]\n","stream":"stdout","time":"2023-08-01T14:23:33.100704102Z"}
{"log":"\u0009at org.springframework.kafka.listener.adapter.RecordMessagingMessageListenerAdapter.onMessage(RecordMessagingMessageListenerAdapter.java:92) ~[spring-kafka-3.0.8.jar:3.0.8]\n","stream":"stdout","time":"2023-08-01T14:23:33.100707974Z"}
{"log":"\u0009at org.springframework.kafka.listener.adapter.RecordMessagingMessageListenerAdapter.onMessage(RecordMessagingMessageListenerAdapter.java:53) ~[spring-kafka-3.0.8.jar:3.0.8]\n","stream":"stdout","time":"2023-08-01T14:23:33.100711653Z"}
{"log":"\u0009at org.springframework.kafka.listener.adapter.KafkaBackoffAwareMessageListenerAdapter.invokeDelegateOnMessage(KafkaBackoffAwareMessageListenerAdapter.java:106) ~[spring-kafka-3.0.8.jar:3.0.8]\n","stream":"stdout","time":"2023-08-01T14:23:33.100715243Z"}
{"log":"\u0009at org.springframework.kafka.listener.adapter.KafkaBackoffAwareMessageListenerAdapter.onMessage(KafkaBackoffAwareMessageListenerAdapter.java:97) ~[spring-kafka-3.0.8.jar:3.0.8]\n","stream":"stdout","time":"2023-08-01T14:23:33.100719731Z"}
{"log":"\u0009at org.springframework.kafka.listener.adapter.KafkaBackoffAwareMessageListenerAdapter.onMessage(KafkaBackoffAwareMessageListenerAdapter.java:49) ~[spring-kafka-3.0.8.jar:3.0.8]\n","stream":"stdout","time":"2023-08-01T14:23:33.100723581Z"}
{"log":"\u0009at org.springframework.kafka.listener.KafkaMessageListenerContainer$ListenerConsumer.doInvokeOnMessage(KafkaMessageListenerContainer.java:2924) ~[spring-kafka-3.0.8.jar:3.0.8]\n","stream":"stdout","time":"2023-08-01T14:23:33.100727209Z"}
{"log":"\u0009at org.springframework.kafka.listener.KafkaMessageListenerContainer$ListenerConsumer.invokeOnMessage(KafkaMessageListenerContainer.java:2904) ~[spring-kafka-3.0.8.jar:3.0.8]\n","stream":"stdout","time":"2023-08-01T14:23:33.100730715Z"}
{"log":"\u0009at org.springframework.kafka.listener.KafkaMessageListenerContainer$ListenerConsumer.lambda$doInvokeRecordListener$58(KafkaMessageListenerContainer.java:2822) ~[spring-kafka-3.0.8.jar:3.0.8]\n","stream":"stdout","time":"2023-08-01T14:23:33.100734248Z"}
{"log":"\u0009at io.micrometer.observation.Observation.lambda$observe$4(Observation.java:544) ~[micrometer-observation-1.11.1.jar:1.11.1]\n","stream":"stdout","time":"2023-08-01T14:23:33.100737974Z"}
{"log":"\u0009at io.micrometer.observation.Observation.observeWithContext(Observation.java:603) [micrometer-observation-1.11.1.jar:1.11.1]\n","stream":"stdout","time":"2023-08-01T14:23:33.100741331Z"}
{"log":"\u0009at io.micrometer.observation.Observation.observe(Observation.java:544) [micrometer-observation-1.11.1.jar:1.11.1]\n","stream":"stdout","time":"2023-08-01T14:23:33.100744748Z"}
{"log":"\u0009at org.springframework.kafka.listener.KafkaMessageListenerContainer$ListenerConsumer.doInvokeRecordListener(KafkaMessageListenerContainer.java:2820) [spring-kafka-3.0.8.jar:3.0.8]\n","stream":"stdout","time":"2023-08-01T14:23:33.100748141Z"}
{"log":"\u0009at org.springframework.kafka.listener.KafkaMessageListenerContainer$ListenerConsumer.doInvokeWithRecords(KafkaMessageListenerContainer.java:2672) [spring-kafka-3.0.8.jar:3.0.8]\n","stream":"stdout","time":"2023-08-01T14:23:33.100755173Z"}
{"log":"\u0009at org.springframework.kafka.listener.KafkaMessageListenerContainer$ListenerConsumer.invokeRecordListener(KafkaMessageListenerContainer.java:2558) [spring-kafka-3.0.8.jar:3.0.8]\n","stream":"stdout","time":"2023-08-01T14:23:33.100760227Z"}
{"log":"\u0009at org.springframework.kafka.listener.KafkaMessageListenerContainer$ListenerConsumer.invokeListener(KafkaMessageListenerContainer.java:2200) [spring-kafka-3.0.8.jar:3.0.8]\n","stream":"stdout","time":"2023-08-01T14:23:33.100763934Z"}
{"log":"\u0009at org.springframework.kafka.listener.KafkaMessageListenerContainer$ListenerConsumer.invokeIfHaveRecords(KafkaMessageListenerContainer.java:1555) [spring-kafka-3.0.8.jar:3.0.8]\n","stream":"stdout","time":"2023-08-01T14:23:33.100768356Z"}
{"log":"\u0009at org.springframework.kafka.listener.KafkaMessageListenerContainer$ListenerConsumer.pollAndInvoke(KafkaMessageListenerContainer.java:1519) [spring-kafka-3.0.8.jar:3.0.8]\n","stream":"stdout","time":"2023-08-01T14:23:33.100772888Z"}
{"log":"\u0009at org.springframework.kafka.listener.KafkaMessageListenerContainer$ListenerConsumer.run(KafkaMessageListenerContainer.java:1394) [spring-kafka-3.0.8.jar:3.0.8]\n","stream":"stdout","time":"2023-08-01T14:23:33.100776463Z"}
{"log":"\u0009at java.util.concurrent.CompletableFuture$AsyncRun.run(CompletableFuture.java:1804) [?:?]\n","stream":"stdout","time":"2023-08-01T14:23:33.100779894Z"}
{"log":"\u0009at java.lang.Thread.run(Thread.java:833) [?:?]\n","stream":"stdout","time":"2023-08-01T14:23:33.10078306Z"}
{"log":"2023-08-01 14:23:33,100 [org.springframework.kafka.KafkaListenerEndpointContainer#1-0-C-1] DEBUG co.elastic.apm.agent.impl.transaction.AbstractSpan - decrement references to 'Kafka record from close-events-events' 00-cf7c04e347408da2a71263d880093f21-3ff705e5d91cfb4f-00 (490cb4b3) (5)\n","stream":"stdout","time":"2023-08-01T14:23:33.100786198Z"}
{"log":"2023-08-01 14:23:33,100 [org.springframework.kafka.KafkaListenerEndpointContainer#1-0-C-1] TRACE co.elastic.apm.agent.impl.transaction.AbstractSpan - decrementing references at\n","stream":"stdout","time":"2023-08-01T14:23:33.100908076Z"}
{"log":"java.lang.RuntimeException: This is an expected exception. Is just used to record where the reference count has been decremented.\n","stream":"stdout","time":"2023-08-01T14:23:33.100911994Z"}
{"log":"\u0009at co.elastic.apm.agent.impl.transaction.AbstractSpan.decrementReferences(AbstractSpan.java:685) ~[elastic-apm-agent-4813494d137e1631bba301d5acab6e7b-e6256b9ad98d9992211305097d439d61.jar:1.39.0]\n","stream":"stdout","time":"2023-08-01T14:23:33.100914058Z"}
{"log":"\u0009at co.elastic.apm.agent.impl.transaction.Span.afterEnd(Span.java:327) ~[elastic-apm-agent-4813494d137e1631bba301d5acab6e7b-e6256b9ad98d9992211305097d439d61.jar:1.39.0]\n","stream":"stdout","time":"2023-08-01T14:23:33.100916195Z"}
{"log":"\u0009at co.elastic.apm.agent.impl.transaction.AbstractSpan.end(AbstractSpan.java:581) ~[elastic-apm-agent-4813494d137e1631bba301d5acab6e7b-e6256b9ad98d9992211305097d439d61.jar:1.39.0]\n","stream":"stdout","time":"2023-08-01T14:23:33.100918148Z"}
{"log":"\u0009at co.elastic.apm.agent.impl.transaction.AbstractSpan.end(AbstractSpan.java:559) ~[elastic-apm-agent-4813494d137e1631bba301d5acab6e7b-e6256b9ad98d9992211305097d439d61.jar:1.39.0]\n","stream":"stdout","time":"2023-08-01T14:23:33.100920128Z"}
{"log":"\u0009at co.elastic.apm.agent.mongodb.v4.ConnectionCommandInstrumentation$AdviceClass.onExit(ConnectionCommandInstrumentation.java:81) ~[elastic-apm-agent-4813494d137e1631bba301d5acab6e7b-e6256b9ad98d9992211305097d439d61.jar:1.39.0]\n","stream":"stdout","time":"2023-08-01T14:23:33.100922128Z"}
{"log":"\u0009at com.mongodb.internal.connection.DefaultServer$OperationCountTrackingConnection.command(DefaultServer.java:288) ~[mongodb-driver-core-4.9.1.jar:?]\n","stream":"stdout","time":"2023-08-01T14:23:33.100924199Z"}
{"log":"\u0009at com.mongodb.internal.operation.CommandOperationHelper.createReadCommandAndExecute(CommandOperationHelper.java:239) ~[mongodb-driver-core-4.9.1.jar:?]\n","stream":"stdout","time":"2023-08-01T14:23:33.100928041Z"}
{"log":"\u0009at com.mongodb.internal.operation.CommandOperationHelper.lambda$executeRetryableRead$4(CommandOperationHelper.java:220) ~[mongodb-driver-core-4.9.1.jar:?]\n","stream":"stdout","time":"2023-08-01T14:23:33.100930036Z"}
{"log":"\u0009at com.mongodb.internal.operation.OperationHelper.lambda$withSourceAndConnection$0(OperationHelper.java:358) ~[mongodb-driver-core-4.9.1.jar:?]\n","stream":"stdout","time":"2023-08-01T14:23:33.100932015Z"}
{"log":"\u0009at com.mongodb.internal.operation.OperationHelper.withSuppliedResource(OperationHelper.java:383) ~[mongodb-driver-core-4.9.1.jar:?]\n","stream":"stdout","time":"2023-08-01T14:23:33.100933904Z"}
{"log":"\u0009at com.mongodb.internal.operation.OperationHelper.lambda$withSourceAndConnection$1(OperationHelper.java:357) ~[mongodb-driver-core-4.9.1.jar:?]\n","stream":"stdout","time":"2023-08-01T14:23:33.100936048Z"}
{"log":"\u0009at com.mongodb.internal.operation.OperationHelper.withSuppliedResource(OperationHelper.java:383) ~[mongodb-driver-core-4.9.1.jar:?]\n","stream":"stdout","time":"2023-08-01T14:23:33.100937935Z"}
{"log":"\u0009at com.mongodb.internal.operation.OperationHelper.withSourceAndConnection(OperationHelper.java:356) ~[mongodb-driver-core-4.9.1.jar:?]\n","stream":"stdout","time":"2023-08-01T14:23:33.100939788Z"}
{"log":"\u0009at com.mongodb.internal.operation.CommandOperationHelper.lambda$executeRetryableRead$5(CommandOperationHelper.java:218) ~[mongodb-driver-core-4.9.1.jar:?]\n","stream":"stdout","time":"2023-08-01T14:23:33.100941649Z"}
{"log":"\u0009at com.mongodb.internal.async.function.RetryingSyncSupplier.get(RetryingSyncSupplier.java:67) ~[mongodb-driver-core-4.9.1.jar:?]\n","stream":"stdout","time":"2023-08-01T14:23:33.100943579Z"}
{"log":"\u0009at com.mongodb.internal.operation.CommandOperationHelper.executeRetryableRead(CommandOperationHelper.java:223) ~[mongodb-driver-core-4.9.1.jar:?]\n","stream":"stdout","time":"2023-08-01T14:23:33.100945503Z"}
{"log":"\u0009at com.mongodb.internal.operation.CommandOperationHelper.executeRetryableRead(CommandOperationHelper.java:204) ~[mongodb-driver-core-4.9.1.jar:?]\n","stream":"stdout","time":"2023-08-01T14:23:33.100947491Z"}
{"log":"\u0009at com.mongodb.internal.operation.AggregateOperationImpl.execute(AggregateOperationImpl.java:191) ~[mongodb-driver-core-4.9.1.jar:?]\n","stream":"stdout","time":"2023-08-01T14:23:33.100949372Z"}
{"log":"\u0009at com.mongodb.internal.operation.AggregateOperation.execute(AggregateOperation.java:152) ~[mongodb-driver-core-4.9.1.jar:?]\n","stream":"stdout","time":"2023-08-01T14:23:33.100951224Z"}
{"log":"\u0009at com.mongodb.internal.operation.AggregateOperation.execute(AggregateOperation.java:44) ~[mongodb-driver-core-4.9.1.jar:?]\n","stream":"stdout","time":"2023-08-01T14:23:33.100953106Z"}
{"log":"\u0009at com.mongodb.client.internal.MongoClientDelegate$DelegateOperationExecutor.execute(MongoClientDelegate.java:185) ~[mongodb-driver-sync-4.9.1.jar:?]\n","stream":"stdout","time":"2023-08-01T14:23:33.100954932Z"}
{"log":"\u0009at com.mongodb.client.internal.MongoIterableImpl.execute(MongoIterableImpl.java:130) ~[mongodb-driver-sync-4.9.1.jar:?]\n","stream":"stdout","time":"2023-08-01T14:23:33.100956872Z"}
{"log":"\u0009at com.mongodb.client.internal.MongoIterableImpl.iterator(MongoIterableImpl.java:90) ~[mongodb-driver-sync-4.9.1.jar:?]\n","stream":"stdout","time":"2023-08-01T14:23:33.100958715Z"}
{"log":"\u0009at com.mongodb.client.internal.MongoIterableImpl.first(MongoIterableImpl.java:101) ~[mongodb-driver-sync-4.9.1.jar:?]\n","stream":"stdout","time":"2023-08-01T14:23:33.100960543Z"}
{"log":"\u0009at com.company.retail.cashier.services.impl.EventServiceImpl.getEventsCountByGameAndTags(EventServiceImpl.java:179) ~[classes/:?]\n","stream":"stdout","time":"2023-08-01T14:23:33.100962401Z"}
{"log":"\u0009at com.company.retail.cashier.queue.CloseEventsConsumer.process(CloseEventsConsumer.java:87) ~[classes/:?]\n","stream":"stdout","time":"2023-08-01T14:23:33.100965984Z"}
{"log":"\u0009at com.company.retail.cashier.queue.CloseEventsConsumer.commonListenerForMultipleTopics(CloseEventsConsumer.java:77) ~[classes/:?]\n","stream":"stdout","time":"2023-08-01T14:23:33.100967925Z"}
{"log":"\u0009at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]\n","stream":"stdout","time":"2023-08-01T14:23:33.100969895Z"}
{"log":"\u0009at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77) ~[?:?]\n","stream":"stdout","time":"2023-08-01T14:23:33.100971679Z"}
{"log":"\u0009at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]\n","stream":"stdout","time":"2023-08-01T14:23:33.100973492Z"}
{"log":"\u0009at java.lang.reflect.Method.invoke(Method.java:568) ~[?:?]\n","stream":"stdout","time":"2023-08-01T14:23:33.100975381Z"}
{"log":"\u0009at org.springframework.messaging.handler.invocation.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:169) ~[spring-messaging-6.0.10.jar:6.0.10]\n","stream":"stdout","time":"2023-08-01T14:23:33.100977231Z"}
{"log":"\u0009at org.springframework.messaging.handler.invocation.InvocableHandlerMethod.invoke(InvocableHandlerMethod.java:119) ~[spring-messaging-6.0.10.jar:6.0.10]\n","stream":"stdout","time":"2023-08-01T14:23:33.100979605Z"}
{"log":"\u0009at org.springframework.kafka.listener.adapter.HandlerAdapter.invoke(HandlerAdapter.java:56) ~[spring-kafka-3.0.8.jar:3.0.8]\n","stream":"stdout","time":"2023-08-01T14:23:33.100981553Z"}
{"log":"\u0009at org.springframework.kafka.listener.adapter.MessagingMessageListenerAdapter.invokeHandler(MessagingMessageListenerAdapter.java:375) ~[spring-kafka-3.0.8.jar:3.0.8]\n","stream":"stdout","time":"2023-08-01T14:23:33.100983405Z"}
{"log":"\u0009at org.springframework.kafka.listener.adapter.RecordMessagingMessageListenerAdapter.onMessage(RecordMessagingMessageListenerAdapter.java:92) ~[spring-kafka-3.0.8.jar:3.0.8]\n","stream":"stdout","time":"2023-08-01T14:23:33.100985306Z"}
{"log":"\u0009at org.springframework.kafka.listener.adapter.RecordMessagingMessageListenerAdapter.onMessage(RecordMessagingMessageListenerAdapter.java:53) ~[spring-kafka-3.0.8.jar:3.0.8]\n","stream":"stdout","time":"2023-08-01T14:23:33.100987248Z"}
{"log":"\u0009at org.springframework.kafka.listener.adapter.KafkaBackoffAwareMessageListenerAdapter.invokeDelegateOnMessage(KafkaBackoffAwareMessageListenerAdapter.java:106) ~[spring-kafka-3.0.8.jar:3.0.8]\n","stream":"stdout","time":"2023-08-01T14:23:33.100989399Z"}
{"log":"\u0009at org.springframework.kafka.listener.adapter.KafkaBackoffAwareMessageListenerAdapter.onMessage(KafkaBackoffAwareMessageListenerAdapter.java:97) ~[spring-kafka-3.0.8.jar:3.0.8]\n","stream":"stdout","time":"2023-08-01T14:23:33.10099153Z"}
{"log":"\u0009at org.springframework.kafka.listener.adapter.KafkaBackoffAwareMessageListenerAdapter.onMessage(KafkaBackoffAwareMessageListenerAdapter.java:49) ~[spring-kafka-3.0.8.jar:3.0.8]\n","stream":"stdout","time":"2023-08-01T14:23:33.10099367Z"}
{"log":"\u0009at org.springframework.kafka.listener.KafkaMessageListenerContainer$ListenerConsumer.doInvokeOnMessage(KafkaMessageListenerContainer.java:2924) ~[spring-kafka-3.0.8.jar:3.0.8]\n","stream":"stdout","time":"2023-08-01T14:23:33.100995867Z"}
{"log":"\u0009at org.springframework.kafka.listener.KafkaMessageListenerContainer$ListenerConsumer.invokeOnMessage(KafkaMessageListenerContainer.java:2904) ~[spring-kafka-3.0.8.jar:3.0.8]\n","stream":"stdout","time":"2023-08-01T14:23:33.100997814Z"}
{"log":"\u0009at org.springframework.kafka.listener.KafkaMessageListenerContainer$ListenerConsumer.lambda$doInvokeRecordListener$58(KafkaMessageListenerContainer.java:2822) ~[spring-kafka-3.0.8.jar:3.0.8]\n","stream":"stdout","time":"2023-08-01T14:23:33.100999834Z"}
{"log":"\u0009at io.micrometer.observation.Observation.lambda$observe$4(Observation.java:544) ~[micrometer-observation-1.11.1.jar:1.11.1]\n","stream":"stdout","time":"2023-08-01T14:23:33.101001832Z"}
{"log":"\u0009at io.micrometer.observation.Observation.observeWithContext(Observation.java:603) [micrometer-observation-1.11.1.jar:1.11.1]\n","stream":"stdout","time":"2023-08-01T14:23:33.101012968Z"}
{"log":"\u0009at io.micrometer.observation.Observation.observe(Observation.java:544) [micrometer-observation-1.11.1.jar:1.11.1]\n","stream":"stdout","time":"2023-08-01T14:23:33.101015416Z"}
{"log":"\u0009at org.springframework.kafka.listener.KafkaMessageListenerContainer$ListenerConsumer.doInvokeRecordListener(KafkaMessageListenerContainer.java:2820) [spring-kafka-3.0.8.jar:3.0.8]\n","stream":"stdout","time":"2023-08-01T14:23:33.101017325Z"}
{"log":"\u0009at org.springframework.kafka.listener.KafkaMessageListenerContainer$ListenerConsumer.doInvokeWithRecords(KafkaMessageListenerContainer.java:2672) [spring-kafka-3.0.8.jar:3.0.8]\n","stream":"stdout","time":"2023-08-01T14:23:33.101019255Z"}
{"log":"\u0009at org.springframework.kafka.listener.KafkaMessageListenerContainer$ListenerConsumer.invokeRecordListener(KafkaMessageListenerContainer.java:2558) [spring-kafka-3.0.8.jar:3.0.8]\n","stream":"stdout","time":"2023-08-01T14:23:33.101021332Z"}
{"log":"\u0009at org.springframework.kafka.listener.KafkaMessageListenerContainer$ListenerConsumer.invokeListener(KafkaMessageListenerContainer.java:2200) [spring-kafka-3.0.8.jar:3.0.8]\n","stream":"stdout","time":"2023-08-01T14:23:33.101023253Z"}
{"log":"\u0009at org.springframework.kafka.listener.KafkaMessageListenerContainer$ListenerConsumer.invokeIfHaveRecords(KafkaMessageListenerContainer.java:1555) [spring-kafka-3.0.8.jar:3.0.8]\n","stream":"stdout","time":"2023-08-01T14:23:33.101025175Z"}
{"log":"\u0009at org.springframework.kafka.listener.KafkaMessageListenerContainer$ListenerConsumer.pollAndInvoke(KafkaMessageListenerContainer.java:1519) [spring-kafka-3.0.8.jar:3.0.8]\n","stream":"stdout","time":"2023-08-01T14:23:33.101027099Z"}
{"log":"\u0009at org.springframework.kafka.listener.KafkaMessageListenerContainer$ListenerConsumer.run(KafkaMessageListenerContainer.java:1394) [spring-kafka-3.0.8.jar:3.0.8]\n","stream":"stdout","time":"2023-08-01T14:23:33.101029835Z"}
{"log":"\u0009at java.util.concurrent.CompletableFuture$AsyncRun.run(CompletableFuture.java:1804) [?:?]\n","stream":"stdout","time":"2023-08-01T14:23:33.101031845Z"}
{"log":"\u0009at java.lang.Thread.run(Thread.java:833) [?:?]\n","stream":"stdout","time":"2023-08-01T14:23:33.101033753Z"}

But it does not look like some critical

SerhiiM · August 2, 2023, 7:50am

Find out another error which happened only on application stop:

ashier  | 2023-08-02 07:42:23,128 [elastic-apm-init-instrumentation-shutdown-hook] INFO  co.elastic.apm.agent.bci.InstrumentationStatsLifecycleListener - Used instrumentation groups: [annotations-capture-transaction, concurrent, exception-handler, executor, executor-collection, fork-join, kafka, log-correlation, log-error, log-reformatting, logging, method-matching, micrometer, mongodb, mongodb-client, process, public-api, reactor, redisson, scheduled, servlet-api, servlet-api-async, spring-mvc, spring-resttemplate, spring-service-name, spring-view-render, ssl-context, urlconnection]
cashier  | 2023-08-02 07:42:23,129 [elastic-apm-circuit-breaker] INFO  co.elastic.apm.agent.impl.circuitbreaker.CircuitBreaker - Stopping the Circuit Breaker thread.
cashier  | 2023-08-02 07:42:24,035 [elastic-apm-shared] ERROR co.elastic.apm.agent.util.ExecutorUtils - null
cashier  | java.util.concurrent.CancellationException: null
cashier  | 	at java.util.concurrent.FutureTask.report(FutureTask.java:121) ~[?:?]
cashier  | 	at java.util.concurrent.FutureTask.get(FutureTask.java:191) ~[?:?]
cashier  | 	at co.elastic.apm.agent.util.ExecutorUtils.logException(ExecutorUtils.java:217) [elastic-apm-agent-4813494d137e1631bba301d5acab6e7b-e6256b9ad98d9992211305097d439d61.jar:1.39.0]
cashier  | 	at co.elastic.apm.agent.util.ExecutorUtils.access$100(ExecutorUtils.java:40) [elastic-apm-agent-4813494d137e1631bba301d5acab6e7b-e6256b9ad98d9992211305097d439d61.jar:1.39.0]
cashier  | 	at co.elastic.apm.agent.util.ExecutorUtils$1.afterExecute(ExecutorUtils.java:64) [elastic-apm-agent-4813494d137e1631bba301d5acab6e7b-e6256b9ad98d9992211305097d439d61.jar:1.39.0]
cashier  | 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1137) [?:?]
cashier  | 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) [?:?]
cashier  | 	at co.elastic.apm.agent.util.ExecutorUtils$2.run(ExecutorUtils.java:99) [elastic-apm-agent-4813494d137e1631bba301d5acab6e7b-e6256b9ad98d9992211305097d439d61.jar:1.39.0]
cashier  | 	at java.lang.Thread.run(Thread.java:833) [?:?]
cashier  | 2023-08-02 07:42:24,041 [elastic-apm-init-instrumentation-shutdown-hook] INFO  co.elastic.apm.agent.impl.ElasticApmTracer - Tracer switched to STOPPED state
cashier  | 2023-08-02 07:42:24,041 [elastic-apm-init-instrumentation-shutdown-hook] INFO  co.elastic.apm.agent.report.ApmServerReporter - dropped events because of full queue: 0
cashier  | 2023-08-02 07:42:24,050 [elastic-apm-init-instrumentation-shutdown-hook] INFO  co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Reported events: 950
cashier  | 2023-08-02 07:42:24,050 [elastic-apm-init-instrumentation-shutdown-hook] INFO  co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Dropped events: 0

Jonas_Kunz · August 2, 2023, 10:35am

The Trace-level errors you are seeing are not actual errors. Those are just logged to get a stack-trace for debugging purposes. The cancellation exception is also not a problem on shutdown.

What we are looking for is the payload being sent to the APM-server (JSONs). You can filter your log for messages from the co.elastic.apm.agent.report.serialize.DslJsonSerializer logs to find those.

SerhiiM · August 2, 2023, 10:50am

I see only these:

{"log":"2023-08-01 14:24:28,836 [elastic-apm-remote-config-poller] TRACE co.elastic.apm.agent.report.serialize.DslJsonSerializer - {\"service\":{\"name\":\"cashier-service\",\"environment\":\"dev\",\"agent\":{\"name\":\"java\",\"ephemeral_id\":\"a270beb6-63af-4807-951e-f407e5bf542c\",\"version\":\"1.39.0\"},\"language\":{\"name\":\"Java\",\"version\":\"17.0.8\"},\"runtime\":{\"name\":\"Java\",\"version\":\"17.0.8\"},\"version\":null},\"process\":{\"pid\":70,\"ppid\":1,\"title\":\"/opt/java/openjdk/bin/java\"},\"system\":{\"architecture\":\"amd64\",\"detected_hostname\":\"9dbeb659e33f\",\"platform\":\"Linux\"}}\n","stream":"stdout","time":"2023-08-01T14:24:28.836552937Z"}
{"log":"2023-08-01 14:24:33,250 [elastic-apm-server-reporter] TRACE co.elastic.apm.agent.report.serialize.DslJsonSerializer - {\"metadata\":{\"service\":{\"name\":\"cashier-service\",\"environment\":\"dev\",\"agent\":{\"name\":\"java\",\"ephemeral_id\":\"a270beb6-63af-4807-951e-f407e5bf542c\",\"version\":\"1.39.0\"},\"language\":{\"name\":\"Java\",\"version\":\"17.0.8\"},\"runtime\":{\"name\":\"Java\",\"version\":\"17.0.8\"},\"version\":null},\"process\":{\"pid\":70,\"ppid\":1,\"title\":\"/opt/java/openjdk/bin/java\"},\"system\":{\"architecture\":\"amd64\",\"detected_hostname\":\"9dbeb659e33f\",\"platform\":\"Linux\"}}}\n","stream":"stdout","time":"2023-08-01T14:24:33.251054Z"}
{"log":"2023-08-01 14:24:44,242 [elastic-apm-server-reporter] TRACE co.elastic.apm.agent.report.serialize.DslJsonSerializer - {\"metadata\":{\"service\":{\"name\":\"cashier-service\",\"environment\":\"dev\",\"agent\":{\"name\":\"java\",\"ephemeral_id\":\"a270beb6-63af-4807-951e-f407e5bf542c\",\"version\":\"1.39.0\"},\"language\":{\"name\":\"Java\",\"version\":\"17.0.8\"},\"runtime\":{\"name\":\"Java\",\"version\":\"17.0.8\"},\"version\":null},\"process\":{\"pid\":70,\"ppid\":1,\"title\":\"/opt/java/openjdk/bin/java\"},\"system\":{\"architecture\":\"amd64\",\"detected_hostname\":\"9dbeb659e33f\",\"platform\":\"Linux\"}}}\n","stream":"stdout","time":"2023-08-01T14:24:44.242845382Z"}
{"log":"2023-08-01 14:24:54,677 [elastic-apm-server-reporter] TRACE co.elastic.apm.agent.report.serialize.DslJsonSerializer - {\"metadata\":{\"service\":{\"name\":\"cashier-service\",\"environment\":\"dev\",\"agent\":{\"name\":\"java\",\"ephemeral_id\":\"a270beb6-63af-4807-951e-f407e5bf542c\",\"version\":\"1.39.0\"},\"language\":{\"name\":\"Java\",\"version\":\"17.0.8\"},\"runtime\":{\"name\":\"Java\",\"version\":\"17.0.8\"},\"version\":null},\"process\":{\"pid\":70,\"ppid\":1,\"title\":\"/opt/java/openjdk/bin/java\"},\"system\":{\"architecture\":\"amd64\",\"detected_hostname\":\"9dbeb659e33f\",\"platform\":\"Linux\"}}}\n","stream":"stdout","time":"2023-08-01T14:24:54.678190567Z"}
{"log":"2023-08-01 14:24:58,839 [elastic-apm-remote-config-poller] TRACE co.elastic.apm.agent.report.serialize.DslJsonSerializer - {\"service\":{\"name\":\"cashier-service\",\"environment\":\"dev\",\"agent\":{\"name\":\"java\",\"ephemeral_id\":\"a270beb6-63af-4807-951e-f407e5bf542c\",\"version\":\"1.39.0\"},\"language\":{\"name\":\"Java\",\"version\":\"17.0.8\"},\"runtime\":{\"name\":\"Java\",\"version\":\"17.0.8\"},\"version\":null},\"process\":{\"pid\":70,\"ppid\":1,\"title\":\"/opt/java/openjdk/bin/java\"},\"system\":{\"architecture\":\"amd64\",\"detected_hostname\":\"9dbeb659e33f\",\"platform\":\"Linux\"}}\n","stream":"stdout","time":"2023-08-01T14:24:58.839465818Z"}
{"log":"2023-08-01 14:25:04,502 [elastic-apm-server-reporter] TRACE co.elastic.apm.agent.report.serialize.DslJsonSerializer - {\"metadata\":{\"service\":{\"name\":\"cashier-service\",\"environment\":\"dev\",\"agent\":{\"name\":\"java\",\"ephemeral_id\":\"a270beb6-63af-4807-951e-f407e5bf542c\",\"version\":\"1.39.0\"},\"language\":{\"name\":\"Java\",\"version\":\"17.0.8\"},\"runtime\":{\"name\":\"Java\",\"version\":\"17.0.8\"},\"version\":null},\"process\":{\"pid\":70,\"ppid\":1,\"title\":\"/opt/java/openjdk/bin/java\"},\"system\":{\"architecture\":\"amd64\",\"detected_hostname\":\"9dbeb659e33f\",\"platform\":\"Linux\"}}}\n","stream":"stdout","time":"2023-08-01T14:25:04.506880374Z"}

Jonas_Kunz · August 2, 2023, 10:57am

The payload is multi-lined (ND-JSON). You'll also have to look at the log lines directly after those you showed.

SerhiiM · August 2, 2023, 11:11am

do you mean this?

{"log":"2023-08-01 14:25:04,502 [elastic-apm-server-reporter] TRACE co.elastic.apm.agent.report.serialize.DslJsonSerializer - {\"metadata\":{\"service\":{\"name\":\"cashier-service\",\"environment\":\"dev\",\"agent\":{\"name\":\"java\",\"ephemeral_id\":\"a270beb6-63af-4807-951e-f407e5bf542c\",\"version\":\"1.39.0\"},\"language\":{\"name\":\"Java\",\"version\":\"17.0.8\"},\"runtime\":{\"name\":\"Java\",\"version\":\"17.0.8\"},\"version\":null},\"process\":{\"pid\":70,\"ppid\":1,\"title\":\"/opt/java/openjdk/bin/java\"},\"system\":{\"architecture\":\"amd64\",\"detected_hostname\":\"9dbeb659e33f\",\"platform\":\"Linux\"}}}\n","stream":"stdout","time":"2023-08-01T14:25:04.506880374Z"}
{"log":"{\"log\":{\"@timestamp\":\"2023-08-01T14:24:55.225Z\",\"log.level\":\"DEBUG\",\"message\":\"Reporting 231 meters\", \"ecs.version\": \"1.2.0\",\"event.dataset\":\"cashier-service.apm-agent\",\"process.thread.name\":\"elastic-apm-shared\",\"log.logger\":\"co.elastic.apm.agent.micrometer.MicrometerMetricsReporter\"}}\n","stream":"stdout","time":"2023-08-01T14:25:04.506907096Z"}
{"log":"{\"metricset\":{\"timestamp\":1690899895225000,\"samples\":{\"process_uptime\":{\"value\":149.036},\"system_load_average_1m\":{\"value\":1.263671875},\"jvm_gc_overhead\":{\"value\":0.0002170417130977326},\"tomcat_sessions_alive_max\":{\"value\":0.0},\"system_cpu_count\":{\"value\":20.0},\"process_start_time\":{\"value\":1690899746.204},\"jvm_threads_daemon\":{\"value\":101.0},\"process_files_open\":{\"value\":785.0},\"jvm_classes_loaded\":{\"value\":22003.0},\"tomcat_sessions_rejected\":{\"value\":0.0},\"jvm_threads_started\":{\"value\":295.0},\"tomcat_sessions_expired\":{\"value\":0.0},\"tomcat_sessions_created\":{\"value\":0.0},\"tomcat_sessions_active_max\":{\"value\":0.0},\"process_cpu_usage\":{\"value\":0.005870482480278848},\"tomcat_sessions_active_current\":{\"value\":0.0},\"system_cpu_usage\":{\"value\":0.11479947063550391},\"spring_security_http_secured_requests_active.count\":{\"value\":0},\"spring_security_http_secured_requests_active.sum.us\":{\"value\":0.0},\"spring_security_http_secured_requests_active.histogram\":{\"values\":[],\"counts\":[]},\"jvm_gc_live_data_size\":{\"value\":169751040.0},\"jvm_threads_live\":{\"value\":271.0},\"jvm_classes_unloaded\":{\"value\":13.0},\"jvm_threads_peak\":{\"value\":276.0},\"jvm_gc_memory_promoted\":{\"value\":29299712.0},\"jvm_gc_memory_allocated\":{\"value\":1300234240.0},\"jvm_gc_max_data_size\":{\"value\":16760438784.0},\"process_files_max\":{\"value\":1048576.0}}}}\n","stream":"stdout","time":"2023-08-01T14:25:04.506924166Z"}
{"log":"{\"metricset\":{\"timestamp\":1690899895225000,\"tags\":{\"exception\":\"none\",\"name\":\"org.springframework.kafka.KafkaListenerEndpointContainer#0-6\",\"result\":\"success\"},\"samples\":{\"spring_kafka_listener.count\":{\"value\":0},\"spring_kafka_listener.sum.us\":{\"value\":0.0},\"spring_kafka_listener.histogram\":{\"values\":[],\"counts\":[]}}}}\n","stream":"stdout","time":"2023-08-01T14:25:04.506930293Z"}
{"log":"{\"metricset\":{\"timestamp\":1690899895225000,\"tags\":{\"cache\":\"ticket_shop\",\"cache_manager\":\"cacheManager\",\"name\":\"ticket_shop\"},\"samples\":{\"cache_puts\":{\"value\":0.0},\"cache_size\":{\"value\":0.0},\"cache_eviction_weight\":{\"value\":0.0},\"cache_evictions\":{\"value\":0.0}}}}\n","stream":"stdout","time":"2023-08-01T14:25:04.506933748Z"}
{"log":"{\"metricset\":{\"timestamp\":1690899895225000,\"tags\":{\"exception\":\"none\",\"name\":\"org.springframework.kafka.KafkaListenerEndpointContainer#0-retry-27000-3\",\"result\":\"success\"},\"samples\":{\"spring_kafka_listener.count\":{\"value\":0},\"spring_kafka_listener.sum.us\":{\"value\":0.0},\"spring_kafka_listener.histogram\":{\"values\":[],\"counts\":[]}}}}\n","stream":"stdout","time":"2023-08-01T14:25:04.506936492Z"}
{"log":"{\"metricset\":{\"timestamp\":1690899895225000,\"tags\":{\"cache\":\"ticket_operator\",\"cache_manager\":\"cacheManager\",\"name\":\"ticket_operator\",\"result\":\"hit\"},\"samples\":{\"cache_gets\":{\"value\":0.0}}}}\n","stream":"stdout","time":"2023-08-01T14:25:04.506939487Z"}
{"log":"{\"metricset\":{\"timestamp\":1690899895225000,\"tags\":{\"main_application_class\":\"com.leap.retail.cashier.CashierApplication\"},\"samples\":{\"application_ready_time\":{\"value\":5.404},\"application_started_time\":{\"value\":5.399}}}}\n","stream":"stdout","time":"2023-08-01T14:25:04.506942412Z"}
{"log":"{\"metricset\":{\"timestamp\":1690899895225000,\"tags\":{\"cluster_id\":\"64c9152694c8cc4de7d7c048\",\"collection\":\"mongockLock\",\"command\":\"listIndexes\",\"server_address\":\"retail_mongos:27017\",\"status\":\"SUCCESS\"},\"samples\":{\"mongodb_driver_commands.count\":{\"value\":3},\"mongodb_driver_commands.sum.us\":{\"value\":6063.247},\"mongodb_driver_commands.histogram\":{\"values\":[],\"counts\":[]}}}}\n","stream":"stdout","time":"2023-08-01T14:25:04.506944872Z"}
{"log":"{\"metricset\":{\"timestamp\":1690899895225000,\"tags\":{\"exception\":\"none\",\"name\":\"org.springframework.kafka.KafkaListenerEndpointContainer#0-retry-9000-1\",\"result\":\"success\"},\"samples\":{\"spring_kafka_listener.count\":{\"value\":0},\"spring_kafka_listener.sum.us\":{\"value\":0.0},\"spring_kafka_listener.histogram\":{\"values\":[],\"counts\":[]}}}}\n","stream":"stdout","time":"2023-08-01T14:25:04.506948785Z"}
{"log":"{\"metricset\":{\"timestamp\":1690899895225000,\"tags\":{\"security_security_reached_filter_section\":\"after\",\"spring_security_filterchain_position\":\"0\",\"spring_security_filterchain_size\":\"0\",\"spring_security_reached_filter_name\":\"none\"},\"samples\":{\"spring_security_filterchains_session_management_after\":{\"value\":23.0},\"spring_security_filterchains_requestcache_after\":{\"value\":23.0},\"spring_security_filterchains_access_exceptions_after\":{\"value\":23.0},\"spring_security_filterchains_authorization_after\":{\"value\":23.0},\"spring_security_filterchains_context_servlet_after\":{\"value\":23.0},\"spring_security_filterchains_authentication_bearer_after\":{\"value\":23.0},\"spring_security_filterchains_context_async_after\":{\"value\":23.0},\"spring_security_filterchains_context_holder_after\":{\"value\":23.0},\"spring_security_filterchains_authentication_anonymous_after\":{\"value\":23.0},\"spring_security_filterchains_header_after\":{\"value\":23.0},\"spring_security_filterchains_active.count\":{\"value\":0},\"spring_security_filterchains_active.sum.us\":{\"value\":0.0},\"spring_security_filterchains_active.histogram\":{\"values\":[],\"counts\":[]},\"spring_security_filterchains_logout_after\":{\"value\":23.0},\"spring_security_filterchains_session_url-encoding_after\":{\"value\":23.0}}}}\n","stream":"stdout","time":"2023-08-01T14:25:04.506955142Z"}
{"log":"{\"metricset\":{\"timestamp\":1690899895225000,\"tags\":{\"cache\":\"game_by_id\",\"cache_manager\":\"cacheManager\",\"name\":\"game_by_id\",\"result\":\"miss\"},\"samples\":{\"cache_gets\":{\"value\":0.0}}}}\n","stream":"stdout","time":"2023-08-01T14:25:04.506960654Z"}
{"log":"{\"metricset\":{\"timestamp\":1690899895225000,\"tags\":{\"cluster_id\":\"64c9152694c8cc4de7d7c048\",\"server_address\":\"retail_mongos:27017\"},\"samples\":{\"mongodb_driver_pool_checkedout\":{\"value\":0.0},\"mongodb_driver_pool_size\":{\"value\":1.0},\"mongodb_driver_pool_waitqueuesize\":{\"value\":0.0}}}}\n","stream":"stdout","time":"2023-08-01T14:25:04.506963409Z"}
{"log":"{\"metricset\":{\"timestamp\":1690899895225000,\"tags\":{\"exception\":\"none\",\"name\":\"org.springframework.kafka.KafkaListenerEndpointContainer#0-retry-1000-7\",\"result\":\"success\"},\"samples\":{\"spring_kafka_listener.count\":{\"value\":0},\"spring_kafka_listener.sum.us\":{\"value\":0.0},\"spring_kafka_listener.histogram\":{\"values\":[],\"counts\":[]}}}}\n","stream":"stdout","time":"2023-08-01T14:25:04.506967348Z"}
{"log":"{\"metricset\":{\"timestamp\":1690899895225000,\"tags\":{\"exception\":\"none\",\"name\":\"org.springframework.kafka.KafkaListenerEndpointContainer#0-retry-3000-2\",\"result\":\"success\"},\"samples\":{\"spring_kafka_listener.count\":{\"value\":0},\"spring_kafka_listener.sum.us\":{\"value\":0.0},\"spring_kafka_listener.histogram\":{\"values\":[],\"counts\":[]}}}}\n","stream":"stdout","time":"2023-08-01T14:25:04.506970088Z"}
{"log":"{\"metricset\":{\"timestamp\":1690899895225000,\"tags\":{\"exception\":\"none\",\"name\":\"org.springframework.kafka.KafkaListenerEndpointContainer#1-retry-27000-0\",\"result\":\"success\"},\"samples\":{\"spring_kafka_listener.count\":{\"value\":0},\"spring_kafka_listener.sum.us\":{\"value\":0.0},\"spring_kafka_listener.histogram\":{\"values\":[],\"counts\":[]}}}}\n","stream":"stdout","time":"2023-08-01T14:25:04.506973137Z"}
{"log":"{\"metricset\":{\"timestamp\":1690899895225000,\"tags\":{\"exception\":\"none\",\"name\":\"org.springframework.kafka.KafkaListenerEndpointContainer#0-retry-9000-9\",\"result\":\"success\"},\"samples\":{\"spring_kafka_listener.count\":{\"value\":0},\"spring_kafka_listener.sum.us\":{\"value\":0.0},\"spring_kafka_listener.histogram\":{\"values\":[],\"counts\":[]}}}}\n","stream":"stdout","time":"2023-08-01T14:25:04.506976018Z"}
{"log":"{\"metricset\":{\"timestamp\":1690899895225000,\"tags\":{\"id\":\"mapped\"},\"samples\":{\"jvm_buffer_count\":{\"value\":0.0},\"jvm_buffer_memory_used\":{\"value\":0.0},\"jvm_buffer_total_capacity\":{\"value\":0.0}}}}\n","stream":"stdout","time":"2023-08-01T14:25:04.506980764Z"}
{"log":"{\"metricset\":{\"timestamp\":1690899895225000,\"tags\":{\"exception\":\"none\",\"name\":\"org.springframework.kafka.KafkaListenerEndpointContainer#0-dlt-7\",\"result\":\"success\"},\"samples\":{\"spring_kafka_listener.count\":{\"value\":0},\"spring_kafka_listener.sum.us\":{\"value\":0.0},\"spring_kafka_listener.histogram\":{\"values\":[],\"counts\":[]}}}}\n","stream":"stdout","time":"2023-08-01T14:25:04.506983473Z"}
{"log":"{\"metricset\":{\"timestamp\":1690899895225000,\"tags\":{\"state\":\"terminated\"},\"samples\":{\"jvm_threads_states\":{\"value\":0.0}}}}\n","stream":"stdout","time":"2023-08-01T14:25:04.506986372Z"}
{"log":"{\"metricset\":{\"timestamp\":1690899895225000,\"tags\":{\"state\":\"blocked\"},\"samples\":{\"jvm_threads_states\":{\"value\":0.0}}}}\n","stream":"stdout","time":"2023-08-01T14:25:04.506988412Z"}
{"log":"{\"metricset\":{\"timestamp\":1690899895225000,\"tags\":{\"cluster_id\":\"64c9152694c8cc4de7d7c048\",\"collection\":\"mongockChangeLog\",\"command\":\"aggregate\",\"server_address\":\"retail_mongos:27017\",\"status\":\"SUCCESS\"},\"samples\":{\"mongodb_driver_commands.count\":{\"value\":1},\"mongodb_driver_commands.sum.us\":{\"value\":1318.75},\"mongodb_driver_commands.histogram\":{\"values\":[],\"counts\":[]}}}}\n","stream":"stdout","time":"2023-08-01T14:25:04.506990965Z"}
{"log":"{\"metricset\":{\"timestamp\":1690899895225000,\"tags\":{\"exception\":\"none\",\"name\":\"org.springframework.kafka.KafkaListenerEndpointContainer#0-7\",\"result\":\"success\"},\"samples\":{\"spring_kafka_listener.count\":{\"value\":0},\"spring_kafka_listener.sum.us\":{\"value\":0.0},\"spring_kafka_listener.histogram\":{\"values\":[],\"counts\":[]}}}}\n","stream":"stdout","time":"2023-08-01T14:25:04.506994066Z"}
{"log":"{\"metricset\":{\"timestamp\":1690899895225000,\"tags\":{\"compiler\":\"HotSpot 64-Bit Tiered Compilers\"},\"samples\":{\"jvm_compilation_time\":{\"value\":3341.0}}}}\n","stream":"stdout","time":"2023-08-01T14:25:04.506997787Z"}
{"log":"{\"metricset\":{\"timestamp\":1690899895225000,\"tags\":{\"exception\":\"none\",\"name\":\"org.springframework.kafka.KafkaListenerEndpointContainer#0-retry-3000-9\",\"result\":\"success\"},\"samples\":{\"spring_kafka_listener.count\":{\"value\":0},\"spring_kafka_listener.sum.us\":{\"value\":0.0},\"spring_kafka_listener.histogram\":{\"values\":[],\"counts\":[]}}}}\n","stream":"stdout","time":"2023-08-01T14:25:04.507000012Z"}
{"log":"{\"metricset\":{\"timestamp\":1690899895225000,\"tags\":{\"runtime\":\"OpenJDK Runtime Environment\",\"vendor\":\"Eclipse Adoptium\",\"version\":\"17.0.8+7\"},\"samples\":{\"jvm_info\":{\"value\":1.0}}}}\n","stream":"stdout","time":"2023-08-01T14:25:04.507003166Z"}
{"log":"{\"metricset\":{\"timestamp\":1690899895225000,\"tags\":{\"exception\":\"none\",\"name\":\"org.springframework.kafka.KafkaListenerEndpointContainer#0-retry-27000-2\",\"result\":\"success\"},\"samples\":{\"spring_kafka_listener.count\":{\"value\":0},\"spring_kafka_listener.sum.us\":{\"value\":0.0},\"spring_kafka_listener.histogram\":{\"values\":[],\"counts\":[]}}}}\n","stream":"stdout","time":"2023-08-01T14:25:04.50700582Z"}
{"log":"{\"metricset\":{\"timestamp\":1690899895225000,\"tags\":{\"cache\":\"ticket_master_shop\",\"cache_manager\":\"cacheManager\",\"name\":\"ticket_master_shop\"},\"samples\":{\"cache_puts\":{\"value\":0.0},\"cache_eviction_weight\":{\"value\":0.0},\"cache_evictions\":{\"value\":0.0},\"cache_size\":{\"value\":0.0}}}}\n","stream":"stdout","time":"2023-08-01T14:25:04.507008827Z"}
{"log":"{\"metricset\":{\"timestamp\":1690899895225000,\"tags\":{\"exception\":\"none\",\"name\":\"org.springframework.kafka.KafkaListenerEndpointContainer#0-retry-1000-0\",\"result\":\"success\"},\"samples\":{\"spring_kafka_listener.count\":{\"value\":0},\"spring_kafka_listener.sum.us\":{\"value\":0.0},\"spring_kafka_listener.histogram\":{\"values\":[],\"counts\":[]}}}}\n","stream":"stdout","time":"2023-08-01T14:25:04.507014015Z"}
{"log":"{\"metricset\":{\"timestamp\":1690899895225000,\"tags\":{\"action\":\"end of minor GC\",\"cause\":\"G1 Evacuation Pause\",\"gc\":\"G1 Young Generation\"},\"samples\":{\"jvm_gc_pause.count\":{\"value\":5},\"jvm_gc_pause.sum.us\":{\"value\":22000.0},\"jvm_gc_pause.histogram\":{\"values\":[],\"counts\":[]}}}}\n","stream":"stdout","time":"2023-08-01T14:25:04.507018905Z"}
{"log":"{\"metricset\":{\"timestamp\":1690899895225000,\"tags\":{\"exception\":\"none\",\"name\":\"org.springframework.kafka.KafkaListenerEndpointContainer#0-retry-3000-1\",\"result\":\"success\"},\"samples\":{\"spring_kafka_listener.count\":{\"value\":0},\"spring_kafka_listener.sum.us\":{\"value\":0.0},\"spring_kafka_listener.histogram\":{\"values\":[],\"counts\":[]}}}}\n","stream":"stdout","time":"2023-08-01T14:25:04.507021889Z"}
{"log":"{\"metricset\":{\"timestamp\":1690899895225000,\"tags\":{\"path\":\"/application/.\"},\"samples\":{\"disk_total\":{\"value\":100782034944.0},\"disk_free\":{\"value\":23450099712.0}}}}\n","stream":"stdout","time":"2023-08-01T14:25:04.507024639Z"}
{"log":"{\"metricset\":{\"timestamp\":1690899895225000,\"tags\":{\"exception\":\"none\",\"name\":\"org.springframework.kafka.KafkaListenerEndpointContainer#1-dlt-0\",\"result\":\"success\"},\"samples\":{\"spring_kafka_listener.count\":{\"value\":0},\"spring_kafka_listener.sum.us\":{\"value\":0.0},\"spring_kafka_listener.histogram\":{\"values\":[],\"counts\":[]}}}}\n","stream":"stdout","time":"2023-08-01T14:25:04.507026903Z"}
{"log":"{\"metricset\":{\"timestamp\":1690899895225000,\"tags\":{\"exception\":\"none\",\"name\":\"org.springframework.kafka.KafkaListenerEndpointContainer#0-retry-9000-2\",\"result\":\"success\"},\"samples\":{\"spring_kafka_listener.count\":{\"value\":0},\"spring_kafka_listener.sum.us\":{\"value\":0.0},\"spring_kafka_listener.histogram\":{\"values\":[],\"counts\":[]}}}}\n","stream":"stdout","time":"2023-08-01T14:25:04.507029902Z"}
{"log":"{\"metricset\":{\"timestamp\":1690899895225000,\"tags\":{\"exception\":\"none\",\"name\":\"org.springframework.kafka.KafkaListenerEndpointContainer#0-retry-1000-8\",\"result\":\"success\"},\"samples\":{\"spring_kafka_listener.count\":{\"value\":0},\"spring_kafka_listener.sum.us\":{\"value\":0.0},\"spring_kafka_listener.histogram\":{\"values\":[],\"counts\":[]}}}}\n","stream":"stdout","time":"2023-08-01T14:25:04.507032773Z"}
{"log":"{\"metricset\":{\"timestamp\":1690899895225000,\"tags\":{\"exception\":\"none\",\"name\":\"org.springframework.kafka.KafkaListenerEndpointContainer#1-retry-3000-0\",\"result\":\"success\"},\"samples\":{\"spring_kafka_listener.count\":{\"value\":0},\"spring_kafka_listener.sum.us\":{\"value\":0.0},\"spring_kafka_listener.histogram\":{\"values\":[],\"counts\":[]}}}}\n","stream":"stdout","time":"2023-08-01T14:25:04.507035595Z"}
{"log":"{\"metricset\":{\"timestamp\":1690899895225000,\"tags\":{\"cluster_id\":\"64c9152694c8cc4de7d7c048\",\"collection\":\"tickets\",\"command\":\"aggregate\",\"server_address\":\"retail_mongos:27017\",\"status\":\"SUCCESS\"},\"samples\":{\"mongodb_driver_commands.count\":{\"value\":3},\"mongodb_driver_commands.sum.us\":{\"value\":4947.227},\"mongodb_driver_commands.histogram\":{\"values\":[],\"counts\":[]}}}}\n","stream":"stdout","time":"2023-08-01T14:25:04.50703815Z"}
{"log":"{\"metricset\":{\"timestamp\":1690899895225000,\"tags\":{\"exception\":\"none\",\"name\":\"org.springframework.kafka.KafkaListenerEndpointContainer#0-dlt-6\",\"result\":\"success\"},\"samples\":{\"spring_kafka_listener.count\":{\"value\":0},\"spring_kafka_listener.sum.us\":{\"value\":0.0},\"spring_kafka_listener.histogram\":{\"values\":[],\"counts\":[]}}}}\n","stream":"stdout","time":"2023-08-01T14:25:04.507041736Z"}
{"log":"{\"metricset\":{\"timestamp\":1690899895225000,\"tags\":{\"cluster_id\":\"64c9152694c8cc4de7d7c048\",\"collection\":\"unknown\",\"command\":\"isMaster\",\"server_address\":\"retail_mongos:27017\",\"status\":\"SUCCESS\"},\"samples\":{\"mongodb_driver_commands.count\":{\"value\":23},\"mongodb_driver_commands.sum.us\":{\"value\":10011.007},\"mongodb_driver_commands.histogram\":{\"values\":[],\"counts\":[]}}}}\n","stream":"stdout","time":"2023-08-01T14:25:04.507044437Z"}
{"log":"{\"metricset\":{\"timestamp\":1690899895225000,\"tags\":{\"area\":\"heap\",\"id\":\"G1 Old Gen\"},\"samples\":{\"jvm_memory_max\":{\"value\":16760438784.0},\"jvm_memory_used\":{\"value\":169751040.0},\"jvm_memory_committed\":{\"value\":260046848.0}}}}\n","stream":"stdout","time":"2023-08-01T14:25:04.507051041Z"}
{"log":"{\"metricset\":{\"timestamp\":1690899895225000,\"tags\":{\"error\":\"none\"},\"samples\":{\"spring_security_http_secured_requests.count\":{\"value\":23},\"spring_security_http_secured_requests.sum.us\":{\"value\":389941.663},\"spring_security_http_secured_requests.histogram\":{\"values\":[],\"counts\":[]}}}}\n","stream":"stdout","time":"2023-08-01T14:25:04.507054213Z"}
{"log":"{\"metricset\":{\"timestamp\":1690899895225000,\"tags\":{\"exception\":\"none\",\"name\":\"org.springframework.kafka.KafkaListenerEndpointContainer#0-4\",\"result\":\"success\"},\"samples\":{\"spring_kafka_listener.count\":{\"value\":0},\"spring_kafka_listener.sum.us\":{\"value\":0.0},\"spring_kafka_listener.histogram\":{\"values\":[],\"counts\":[]}}}}\n","stream":"stdout","time":"2023-08-01T14:25:04.507056877Z"}
{"log":"{\"metricset\":{\"timestamp\":1690899895225000,\"tags\":{\"exception\":\"none\",\"name\":\"org.springframework.kafka.KafkaListenerEndpointContainer#0-retry-3000-8\",\"result\":\"success\"},\"samples\":{\"spring_kafka_listener.count\":{\"value\":0},\"spring_kafka_listener.sum.us\":{\"value\":0.0},\"spring_kafka_listener.histogram\":{\"values\":[],\"counts\":[]}}}}\n","stream":"stdout","time":"2023-08-01T14:25:04.507060057Z"}
{"log":"{\"metricset\":{\"timestamp\":1690899895225000,\"tags\":{\"exception\":\"none\",\"name\":\"org.springframework.kafka.KafkaListenerEndpointContainer#0-retry-1000-1\",\"result\":\"success\"},\"samples\":{\"spring_kafka_listener.count\":{\"value\":0},\"spring_kafka_listener.sum.us\":{\"value\":0.0},\"spring_kafka_listener.histogram\":{\"values\":[],\"counts\":[]}}}}\n","stream":"stdout","time":"2023-08-01T14:25:04.50706283Z"}
{"log":"{\"metricset\":{\"timestamp\":1690899895225000,\"tags\":{\"cache\":\"game_by_id\",\"cache_manager\":\"cacheManager\",\"name\":\"game_by_id\",\"result\":\"hit\"},\"samples\":{\"cache_gets\":{\"value\":0.0}}}}\n","stream":"stdout","time":"2023-08-01T14:25:04.507065972Z"}
{"log":"{\"metricset\":{\"timestamp\":1690899895225000,\"tags\":{\"exception\":\"none\",\"name\":\"org.springframework.kafka.KafkaListenerEndpointContainer#0-retry-27000-5\",\"result\":\"success\"},\"samples\":{\"spring_kafka_listener.count\":{\"value\":0},\"spring_kafka_listener.sum.us\":{\"value\":0.0},\"spring_kafka_listener.histogram\":{\"values\":[],\"counts\":[]}}}}\n","stream":"stdout","time":"2023-08-01T14:25:04.507068618Z"}
{"log":"{\"metricset\":{\"timestamp\":1690899895225000,\"tags\":{\"area\":\"nonheap\",\"id\":\"CodeCache\"},\"samples\":{\"jvm_memory_max\":{\"value\":50331648.0},\"jvm_memory_committed\":{\"value\":25559040.0},\"jvm_memory_used\":{\"value\":21824512.0}}}}\n","stream":"stdout","time":"2023-08-01T14:25:04.507071551Z"}
{"log":"{\"metricset\":{\"timestamp\":1690899895225000,\"tags\":{\"cache\":\"game_by_inner_id\",\"cache_manager\":\"cacheManager\",\"name\":\"game_by_inner_id\",\"result\":\"hit\"},\"samples\":{\"cache_gets\":{\"value\":0.0}}}}\n","stream":"stdout","time":"2023-08-01T14:25:04.507074475Z"}
{"log":"{\"metricset\":{\"timestamp\":1690899895225000,\"tags\":{\"exception\":\"none\",\"name\":\"org.springframework.kafka.KafkaListenerEndpointContainer#0-retry-3000-0\",\"result\":\"success\"},\"samples\":{\"spring_kafka_listener.count\":{\"value\":0},\"spring_kafka_listener.sum.us\":{\"value\":0.0},\"spring_kafka_listener.histogram\":{\"values\":[],\"counts\":[]}}}}\n","stream":"stdout","time":"2023-08-01T14:25:04.507077014Z"}
{"log":"{\"metricset\":{\"timestamp\":1690899895225000,\"tags\":{\"exception\":\"none\",\"name\":\"org.springframework.kafka.KafkaListenerEndpointContainer#0-retry-1000-9\",\"result\":\"success\"},\"samples\":{\"spring_kafka_listener.count\":{\"value\":0},\"spring_kafka_listener.sum.us\":{\"value\":0.0},\"spring_kafka_listener.histogram\":{\"values\":[],\"counts\":[]}}}}\n","stream":"stdout","time":"2023-08-01T14:25:04.507081563Z"}

Jonas_Kunz · August 2, 2023, 11:28am

Yes. There should also be corresponding messages with "{\"transaction\" corresponding to each transaction being sent to the APM-server. The ones you showed are for metrics. You'll have to look for those and see if you can find your Kafka-related transaction in them.

SerhiiM · August 2, 2023, 11:38am

I can't find them in the log. Only one which for kafkaListener factory init, as I see

{"log":"{\"transaction\":{\"timestamp\":1690899751410003,\"name\":\"KafkaCloseEventsConsumersConfig#kafkaCloseEventsListenerContainerFactory\",\"id\":\"6657e5124dbf1ebe\",\"trace_id\":\"2ea3724d12f42e35448b6e71b924d971\",\"type\":\"custom\",\"duration\":1.403,\"outcome\":\"success\",\"context\":{\"tags\":{}},\"span_count\":{\"dropped\":0,\"started\":0},\"dropped_spans_stats\":[],\"sample_rate\":1.0,\"sampled\":true}}\n","stream":"stdout","time":"2023-08-01T14:22:38.982512765Z"}

All else transactions for HTTP requests and Schedules tasks

Mb I need to add some specific package to application_packages or trace_methods settings??

Jonas_Kunz · August 2, 2023, 12:37pm

This means that while the transactions are recorded (as shown by the debug logs you posted earlier), they are not being sent to the APM-server.

I also found an explanation looking at your debug-logs again:

[org.springframework.kafka.KafkaListenerEndpointContainer#1-0-C-1] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - startTransaction '' 00-0a461e04069415430508b2fceb45d0fe-baa78f428091de4e-00 (1f4c96c5)

The -00 suffix in the printed W3C traceparent header shows that the trace is unsampled. If it were sampled, the suffix would be -01. And unsampled transation are not sent to the APM-server, they are discarded.

There are two possible reasons for your transactions being discarded:

Your Kafka-transactions are root-transactions (they have no parent) and you configured the sampling rate to something lower than 100%
Your Kafka-transactions are children of transactions from the service who sent those messages to Kafka and those services decided to not sample those traces.

I think we can exclude the first option because you configured transaction_sample_rate=1.

To verify the second hypothesis you can force the APM-agent to ignore external trace parents by setting trace_continuation_strategy=restart (documentation).
After setting this, you should start seeing your Kafka transactions as root transactions.

SerhiiM · August 2, 2023, 12:52pm

Yes, it helps with Kafka Transactions, but now my HTTP service-to-service transactions don't relate (( Can I have both with APM agent?