dd-trace-php icon indicating copy to clipboard operation
dd-trace-php copied to clipboard

Published 20 hours ago • verified publisher icon DataDog

[Bug]: Upgrading to 1.4.1 out of memory issue

Open styoo4001 opened this issue 1 year ago • 14 comments
trafficstars

Bug report

Bug report

Hello,

Our company has been utilizing DataDog effectively, and we are running services in a Kubernetes environment.

Recently, after deploying a specific API server feature, approximately 30 minutes later, CPU usage significantly spiked, leading to an increase in pod scaling and a sharp rise in memory consumption, causing some pods to crash (out of memory). Notably, the php-fpm process did not exhibit any abnormal behavior.

After rolling back to last week's ArgoCD deployment image, the system stabilized. Initially, we assumed the issue was related to the deployed code, and we thoroughly investigated various aspects. However, we couldn't find any evidence in APM or DataDog profiler. Crucially, the profiler showed that the application's memory usage was below 1GB, but under certain conditions, pod memory usage spiked from 1GB to 8GB within a minute.

Eventually, we discovered that the issue stemmed from the trace version being set to latest when building the deployment image. After changing it to last week's version (1.3.1) and redeploying, the system stabilized.

We confirmed that the issue was resolved following this change.

usual condition image Image

Image

Image

left : usual condition , right : unusual

Image

Image

My php settings are:

extension=ddtrace.so
datadog.trace.request_init_hook=/opt/datadog-php/dd-trace-sources/bridge/dd_wrap_autoloader.php
datadog.trace.cli_enabled=On
datadog.trace.generate_root_span=Off
datadog.trace.auto_flush_enabled=On

PHP version

8.1.13

Tracer or profiler version

1.4.1

Installed extensions

No response

Output of phpinfo()

No response

Upgrading from

1.3.1

PHP version

8.1.13

Tracer or profiler version

1.4.1

Installed extensions

No response

Output of phpinfo()

No response

Upgrading from

No response

styoo4001 avatar Oct 18 '24 02:10 styoo4001

Hey @styoo4001,

I'm really puzzled as to what could be the cause of that. By chance, is it possible for you to enable logging and send the logs to us?

datadog.trace.log_level=trace
datadog.trace.log_file=/path/to/file.log

I.e. we'd be interested in the logs in the very timeframe of the memory spike.

bwoebi avatar Oct 18 '24 11:10 bwoebi

Alternatively, using the https://github.com/DataDog/ddprof native profiler and sharing the memory profiles with us could also be very interesting!

bwoebi avatar Oct 18 '24 11:10 bwoebi

@bwoebi
I'll try to recreate it. And I'll change the log settings and then attach the log content!

styoo4001 avatar Oct 21 '24 05:10 styoo4001

@bwoebi

A new version has already come out, I'm not sure if this log will help, but I've attached it. There are so many logs that I only attach a portion of the log when the memory went up

[22-Oct-2024 02:15:03 UTC] [ddtrace] [debug] [sidecar] ddtelemetry::worker: Handling action AddPoint((1.0, ContextKey(0, Count), [Tag { value: "integration_name:datadog" }]))
[22-Oct-2024 02:15:03 UTC] [ddtrace] [debug] [sidecar] ddtelemetry::worker: Handling action AddPoint((7.0, ContextKey(1, Count), [Tag { value: "level:trace" }]))
[22-Oct-2024 02:15:03 UTC] [ddtrace] [debug] [sidecar] ddtelemetry::worker: Handling action AddPoint((2.0, ContextKey(1, Count), [Tag { value: "level:debug" }]))
[22-Oct-2024 02:15:03 UTC] [ddtrace] [debug] [sidecar] ddtelemetry::worker: Handling action AddPoint((1.0, ContextKey(1, Count), [Tag { value: "level:info" }]))
[22-Oct-2024 02:15:03 UTC] [ddtrace] [debug] [sidecar] ddtelemetry::worker: Handling action AddPoint((1.0, ContextKey(1, Count), [Tag { value: "level:warn" }]))
[22-Oct-2024 02:15:03 UTC] [ddtrace] [debug] [sidecar] ddtelemetry::worker: Handling action Lifecycle(Stop)
[22-Oct-2024 02:15:03 UTC] [ddtrace] [trace] [sidecar] tarpc::server: Expired requests: Closed, Inbound: Pending
[22-Oct-2024 02:15:03 UTC] [ddtrace] [trace] [sidecar] tarpc::server: poll_flush
[22-Oct-2024 02:15:04 UTC] [ddtrace] [debug] [sidecar] ddtelemetry::worker: Handling action Lifecycle(FlushMetricAggr)
[22-Oct-2024 02:15:05 UTC] [ddtrace] [trace] [sidecar] datadog_remote_config::fetch::fetcher: Submitting remote config request: ClientGetConfigsRequest { client: Some(Client { state: Some(ClientState { root_version: 1, targets_version: 97430535, config_states: [ConfigState { id: "29.recommended.json", version: 1, product: "ASM_DD", apply_state: 2, apply_error: "" }], has_error: false, error: "", backend_client_state: [101, 121, 74, 50, 90, 88, 74, 122, 97, 87, 57, 117, 73, 106, 111, 121, 76, 67, 74, 122, 100, 71, 70, 48, 90, 83, 73, 54, 101, 121, 74, 109, 97, 87, 120, 108, 88, 50, 104, 104, 99, 50, 104, 108, 99, 121, 73, 54, 101, 121, 74, 107, 89, 88, 82, 104, 90, 71, 57, 110, 76, 122, 89, 53, 77, 122, 85, 50, 78, 83, 57, 66, 82, 48, 86, 79, 86, 70, 57, 68, 84, 48, 53, 71, 83, 85, 99, 118, 89, 50, 57, 117, 90, 109, 108, 110, 100, 88, 74, 104, 100, 71, 108, 118, 98, 108, 57, 118, 99, 109, 82, 108, 99, 105, 57, 106, 77, 71, 74, 107, 78, 122, 77, 49, 89, 84, 69, 119, 90, 109, 69, 120, 77, 68, 70, 105, 90, 84, 104, 105, 90, 87, 85, 48, 90, 109, 85, 49, 78, 87, 70, 106, 78, 68, 82, 109, 77, 106, 99, 119, 77, 50, 85, 52, 79, 68, 65, 48, 77, 68, 81, 120, 78, 109, 78, 107, 89, 109, 74, 104, 89, 106, 107, 48, 77, 84, 77, 49, 77, 68, 86, 109, 90, 106, 78, 108, 77, 87, 86, 107, 73, 106, 112, 98, 73, 106, 78, 109, 100, 51, 78, 108, 77, 84, 100, 111, 89, 49, 70, 120, 99, 69, 90, 108, 77, 122, 104, 54, 87, 87, 57, 79, 85, 108, 78, 108, 82, 84, 74, 86, 89, 107, 57, 49, 100, 85, 74, 87, 85, 107, 108, 88, 77, 88, 100, 71, 84, 50, 70, 117, 97, 88, 99, 57, 73, 108, 48, 115, 73, 109, 82, 104, 100, 71, 70, 107, 98, 50, 99, 118, 78, 106, 107, 122, 78, 84, 89, 49, 76, 48, 70, 81, 84, 86, 57, 84, 81, 85, 49, 81, 84, 69, 108, 79, 82, 121, 57, 122, 89, 87, 49, 119, 98, 71, 86, 121, 89, 50, 57, 117, 90, 109, 108, 110, 76, 122, 104, 107, 90, 109, 89, 122, 79, 71, 73, 53, 89, 84, 69, 50, 90, 87, 73, 121, 89, 84, 65, 121, 79, 71, 81, 52, 77, 84, 74, 108, 90, 87, 73, 53, 90, 87, 81, 119, 77, 50, 81, 121, 78, 122, 104, 107, 78, 84, 85, 120, 77, 84, 103, 51, 77, 84, 82, 109, 77, 84, 81, 52, 90, 68, 78, 105, 78, 109, 90, 104, 79, 71, 85, 50, 90, 68, 100, 104, 90, 68, 89, 51, 78, 87, 85, 105, 79, 108, 115, 105, 83, 110, 108, 90, 83, 85, 112, 66, 85, 71, 90, 77, 90, 49, 82, 81, 100, 67, 116, 52, 84, 86, 104, 109, 84, 87, 70, 49, 100, 109, 108, 76, 77, 85, 111, 49, 81, 84, 74, 83, 82, 106, 78, 81, 78, 87, 99, 52, 84, 50, 112, 81, 99, 110, 66, 116, 86, 84, 48, 105, 88, 83, 119, 105, 90, 87, 49, 119, 98, 71, 57, 53, 90, 87, 85, 118, 81, 86, 78, 78, 88, 48, 82, 69, 76, 122, 73, 53, 76, 110, 74, 108, 89, 50, 57, 116, 98, 87, 86, 117, 90, 71, 86, 107, 76, 109, 112, 122, 98, 50, 52, 118, 89, 50, 57, 117, 90, 109, 108, 110, 73, 106, 112, 98, 73, 107, 78, 52, 98, 70, 74, 66, 98, 68, 78, 74, 98, 87, 111, 49, 90, 109, 74, 108, 76, 48, 53, 120, 81, 51, 78, 66, 85, 70, 89, 118, 89, 48, 53, 70, 82, 70, 112, 48, 89, 49, 108, 104, 77, 85, 108, 53, 100, 71, 100, 105, 99, 70, 100, 80, 87, 85, 48, 57, 73, 108, 49, 57, 102, 88, 48, 61] }), id: "b752e8a8-5dc9-4b41-9306-1f4f5d817e82", products: ["APM_TRACING", "LIVE_DEBUGGING", "ASM_FEATURES", "ASM_DATA", "ASM_DD", "ASM"], is_tracer: true, client_tracer: Some(ClientTracer { runtime_id: "de0dd7e2-05fe-4fb1-b995-72dba082b1c4", language: "php", tracer_version: "1.4.1", service: "order-group-api2", extra_services: [], env: "dev", app_version: "0", tags: [] }), is_agent: false, client_agent: None, last_seen: 0, capabilities: [32, 8, 247, 254] }), cached_target_files: [TargetFileMeta { path: "employee/ASM_DD/29.recommended.json/config", length: 304537, hashes: [TargetFileHash { algorithm: "sha256", hash: "0b1951025dc89a3e5f6defcda82b003d5fdc3440d9b5c61ad48cad81ba563983" }] }] }
[22-Oct-2024 02:15:05 UTC] [ddtrace] [trace] [sidecar] hyper::client::pool: checkout waiting for idle connection: ("http", (delete ip):(delete port))
[22-Oct-2024 02:15:05 UTC] [ddtrace] [trace] [sidecar] hyper_util::client::legacy::connect::http: Http::connect; scheme=Some("http"), host=Some("(delete ip)"), port=Some(Port((delete port)))
[22-Oct-2024 02:15:05 UTC] [ddtrace] [debug] [sidecar] hyper_util::client::legacy::connect::http: connecting to (delete ip):(delete port)
[22-Oct-2024 02:15:05 UTC] [ddtrace] [debug] [sidecar] hyper_util::client::legacy::connect::http: connected to (delete ip):(delete port)
[22-Oct-2024 02:15:05 UTC] [ddtrace] [trace] [sidecar] hyper::client::conn: client handshake Http1
[22-Oct-2024 02:15:05 UTC] [ddtrace] [trace] [sidecar] hyper::client::client: handshake complete, spawning background dispatcher task
[22-Oct-2024 02:15:05 UTC] [ddtrace] [trace] [sidecar] hyper::proto::h1::conn: flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Busy }
[22-Oct-2024 02:15:05 UTC] [ddtrace] [trace] [sidecar] hyper::client::pool: checkout dropped for ("http", (delete ip):(delete port))
[22-Oct-2024 02:15:05 UTC] [ddtrace] [trace] [sidecar] encode_headers: hyper::proto::h1::role: Client::encode method=POST, body=Some(Known(2847))
[22-Oct-2024 02:15:05 UTC] [ddtrace] [trace] [sidecar] hyper::proto::h1::encode: sized write, len = 2847
[22-Oct-2024 02:15:05 UTC] [ddtrace] [trace] [sidecar] hyper::proto::h1::io: buffer.flatten self.len=310 buf.len=2847
[22-Oct-2024 02:15:05 UTC] [ddtrace] [debug] [sidecar] hyper::proto::h1::io: flushed 3157 bytes
[22-Oct-2024 02:15:05 UTC] [ddtrace] [trace] [sidecar] hyper::proto::h1::conn: flushed({role=client}): State { reading: Init, writing: KeepAlive, keep_alive: Busy }
[22-Oct-2024 02:15:05 UTC] [ddtrace] [trace] [sidecar] hyper::proto::h1::conn: Conn::read_head
[22-Oct-2024 02:15:05 UTC] [ddtrace] [trace] [sidecar] hyper::proto::h1::io: received 4096 bytes
[22-Oct-2024 02:15:05 UTC] [ddtrace] [trace] [sidecar] parse_headers: hyper::proto::h1::role: Response.parse bytes=4096
[22-Oct-2024 02:15:05 UTC] [ddtrace] [trace] [sidecar] parse_headers: hyper::proto::h1::role: Response.parse Complete(243)
[22-Oct-2024 02:15:05 UTC] [ddtrace] [debug] [sidecar] hyper::proto::h1::io: parsed 5 headers
[22-Oct-2024 02:15:05 UTC] [ddtrace] [debug] [sidecar] hyper::proto::h1::conn: incoming body is chunked encoding
[22-Oct-2024 02:15:05 UTC] [ddtrace] [trace] [sidecar] hyper::proto::h1::decode: decode; state=Chunked { state: Start, chunk_len: 0, extensions_cnt: 0 }
[22-Oct-2024 02:15:05 UTC] [ddtrace] [trace] [sidecar] hyper::proto::h1::decode: Read chunk start
[22-Oct-2024 02:15:05 UTC] [ddtrace] [trace] [sidecar] hyper::proto::h1::decode: Read chunk hex size
[22-Oct-2024 02:15:05 UTC] [ddtrace] [trace] [sidecar] hyper::proto::h1::decode: Read chunk hex size
[22-Oct-2024 02:15:05 UTC] [ddtrace] [trace] [sidecar] hyper::proto::h1::decode: Read chunk hex size
[22-Oct-2024 02:15:05 UTC] [ddtrace] [trace] [sidecar] hyper::proto::h1::decode: Read chunk hex size
[22-Oct-2024 02:15:05 UTC] [ddtrace] [trace] [sidecar] hyper::proto::h1::decode: Chunk size is 33126
[22-Oct-2024 02:15:05 UTC] [ddtrace] [debug] [sidecar] hyper::proto::h1::decode: incoming chunked header: 0x8166 (33126 bytes)
[22-Oct-2024 02:15:05 UTC] [ddtrace] [trace] [sidecar] hyper::proto::h1::decode: Chunked read, remaining=33126
[22-Oct-2024 02:15:05 UTC] [ddtrace] [trace] [sidecar] hyper::proto::h1::conn: flushed({role=client}): State { reading: Body(Chunked { state: Body, chunk_len: 29279, extensions_cnt: 0 }), writing: KeepAlive, keep_alive: Busy }
[22-Oct-2024 02:15:05 UTC] [ddtrace] [trace] [sidecar] hyper::proto::h1::decode: decode; state=Chunked { state: Body, chunk_len: 29279, extensions_cnt: 0 }
[22-Oct-2024 02:15:05 UTC] [ddtrace] [trace] [sidecar] hyper::proto::h1::decode: Chunked read, remaining=29279
[22-Oct-2024 02:15:05 UTC] [ddtrace] [trace] [sidecar] hyper::proto::h1::conn: flushed({role=client}): State { reading: Body(Chunked { state: Body, chunk_len: 29279, extensions_cnt: 0 }), writing: KeepAlive, keep_alive: Busy }
[22-Oct-2024 02:15:05 UTC] [ddtrace] [trace] [sidecar] hyper::proto::h1::decode: decode; state=Chunked { state: Body, chunk_len: 29279, extensions_cnt: 0 }
[22-Oct-2024 02:15:05 UTC] [ddtrace] [trace] [sidecar] hyper::proto::h1::decode: Chunked read, remaining=29279
[22-Oct-2024 02:15:05 UTC] [ddtrace] [trace] [sidecar] hyper::proto::h1::io: received 8192 bytes
[22-Oct-2024 02:15:05 UTC] [ddtrace] [trace] [sidecar] hyper::proto::h1::conn: flushed({role=client}): State { reading: Body(Chunked { state: Body, chunk_len: 21087, extensions_cnt: 0 }), writing: KeepAlive, keep_alive: Busy }
[22-Oct-2024 02:15:05 UTC] [ddtrace] [trace] [sidecar] hyper::proto::h1::decode: decode; state=Chunked { state: Body, chunk_len: 21087, extensions_cnt: 0 }
[22-Oct-2024 02:15:05 UTC] [ddtrace] [trace] [sidecar] hyper::proto::h1::decode: Chunked read, remaining=21087
[22-Oct-2024 02:15:05 UTC] [ddtrace] [trace] [sidecar] hyper::proto::h1::io: received 16384 bytes
[22-Oct-2024 02:15:05 UTC] [ddtrace] [trace] [sidecar] hyper::proto::h1::conn: flushed({role=client}): State { reading: Body(Chunked { state: Body, chunk_len: 4703, extensions_cnt: 0 }), writing: KeepAlive, keep_alive: Busy }
[22-Oct-2024 02:15:05 UTC] [ddtrace] [trace] [sidecar] hyper::proto::h1::decode: decode; state=Chunked { state: Body, chunk_len: 4703, extensions_cnt: 0 }
[22-Oct-2024 02:15:05 UTC] [ddtrace] [trace] [sidecar] hyper::proto::h1::decode: Chunked read, remaining=4703
[22-Oct-2024 02:15:05 UTC] [ddtrace] [trace] [sidecar] hyper::proto::h1::io: received 4710 bytes
[22-Oct-2024 02:15:05 UTC] [ddtrace] [trace] [sidecar] hyper::proto::h1::conn: flushed({role=client}): State { reading: Body(Chunked { state: BodyCr, chunk_len: 0, extensions_cnt: 0 }), writing: KeepAlive, keep_alive: Busy }
[22-Oct-2024 02:15:05 UTC] [ddtrace] [trace] [sidecar] hyper::proto::h1::decode: decode; state=Chunked { state: BodyCr, chunk_len: 0, extensions_cnt: 0 }
[22-Oct-2024 02:15:05 UTC] [ddtrace] [trace] [sidecar] hyper::proto::h1::decode: Read chunk hex size
[22-Oct-2024 02:15:05 UTC] [ddtrace] [trace] [sidecar] hyper::proto::h1::decode: Read chunk hex size
[22-Oct-2024 02:15:05 UTC] [ddtrace] [trace] [sidecar] hyper::proto::h1::decode: Chunk size is 0
[22-Oct-2024 02:15:05 UTC] [ddtrace] [trace] [sidecar] hyper::proto::h1::decode: end of chunked
[22-Oct-2024 02:15:05 UTC] [ddtrace] [debug] [sidecar] hyper::proto::h1::conn: incoming body completed
[22-Oct-2024 02:15:05 UTC] [ddtrace] [trace] [sidecar] hyper::proto::h1::conn: maybe_notify; read_from_io blocked
[22-Oct-2024 02:15:05 UTC] [ddtrace] [trace] [sidecar] hyper::proto::h1::conn: flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Idle }
[22-Oct-2024 02:15:05 UTC] [ddtrace] [trace] [sidecar] hyper::proto::h1::conn: flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Idle }
[22-Oct-2024 02:15:05 UTC] [ddtrace] [trace] [sidecar] hyper::client::pool: pool dropped, dropping pooled (("http", (delete ip):(delete port)))
[22-Oct-2024 02:15:05 UTC] [ddtrace] [trace] [sidecar] hyper::proto::h1::dispatch: client tx closed
[22-Oct-2024 02:15:05 UTC] [ddtrace] [trace] [sidecar] hyper::proto::h1::conn: State::close_read()
[22-Oct-2024 02:15:05 UTC] [ddtrace] [trace] [sidecar] hyper::proto::h1::conn: State::close_write()
[22-Oct-2024 02:15:05 UTC] [ddtrace] [trace] [sidecar] hyper::proto::h1::conn: flushed({role=client}): State { reading: Closed, writing: Closed, keep_alive: Disabled }
[22-Oct-2024 02:15:05 UTC] [ddtrace] [trace] [sidecar] hyper::proto::h1::conn: shut down IO complete
[22-Oct-2024 02:15:05 UTC] [ddtrace] [debug] [sidecar] datadog_remote_config::fetch::fetcher: Received remote config of length 33126, containing ["datadog/693565/AGENT_CONFIG/configuration_order/c0bd735a10fa101be8bee4fe55ac44f2703e88040416cdbbab9413505ff3e1ed", "employee/ASM_DD/29.recommended.json/config", "datadog/693565/APM_SAMPLING/samplerconfig/8dff38b9a16eb2a028d812eeb9ed03d278d55118714f148d3b6fa8e6d7ad675e"] paths for target Target { service: "order-group-api2", env: "dev", app_version: "0", tags: [] }
[22-Oct-2024 02:15:05 UTC] [ddtrace] [warn] [sidecar] datadog_remote_config::fetch::fetcher: Failed parsing remote config path: datadog/693565/AGENT_CONFIG/configuration_order/c0bd735a10fa101be8bee4fe55ac44f2703e88040416cdbbab9413505ff3e1ed - Unknown product AGENT_CONFIG
[22-Oct-2024 02:15:05 UTC] [ddtrace] [warn] [sidecar] datadog_remote_config::fetch::fetcher: Failed parsing remote config path: datadog/693565/APM_SAMPLING/samplerconfig/8dff38b9a16eb2a028d812eeb9ed03d278d55118714f148d3b6fa8e6d7ad675e - Unknown product APM_SAMPLING
[22-Oct-2024 02:15:05 UTC] [ddtrace] [debug] [sidecar] ddtelemetry::worker: Handling action Lifecycle(FlushMetricAggr)
[22-Oct-2024 02:15:05 UTC] [ddtrace] [debug] [sidecar] ddtelemetry::worker: Handling action Lifecycle(FlushMetricAggr)
[22-Oct-2024 02:15:05 UTC] [ddtrace] [debug] [sidecar] ddtelemetry::worker: Handling action Lifecycle(FlushMetricAggr)
[22-Oct-2024 02:15:05 UTC] [ddtrace] [debug] [sidecar] ddtelemetry::worker: Handling action Lifecycle(FlushData)
[22-Oct-2024 02:15:05 UTC] [ddtrace] [debug] [sidecar] ddtelemetry::worker: Prepared payload: Telemetry { api_version: V2, tracer_time: 1729563305, runtime_id: "cd4a516f-60a4-4caf-8564-95fb3ea8a9a0", seq_id: 34, application: Application { service_name: "background_sender-php-service", service_version: None, env: Some("none"), language_name: "php", language_version: "8.1.13", tracer_version: "1.4.1", runtime_name: None, runtime_version: None, runtime_patches: None }, host: Host { hostname: "order-group-api2-5fdfbb7c55-r69jg", container_id: Some("a6f919a8368e0a5a05fe2a66a235e7259c4fc200ca3692f0f3c1315d97afc07c"), os: Some("linux"), os_version: Some("5.10.226-214.879.amzn2.x86_64"), kernel_name: None, kernel_release: None, kernel_version: None }, payload: AppHeartbeat(()) }
[22-Oct-2024 02:15:05 UTC] [ddtrace] [trace] [sidecar] hyper::client::pool: take? ("http", (delete ip):(delete port)): expiration = Some(30s)
[22-Oct-2024 02:15:05 UTC] [ddtrace] [trace] [sidecar] hyper::client::pool: removing closed connection for ("http", (delete ip):(delete port))
[22-Oct-2024 02:15:05 UTC] [ddtrace] [trace] [sidecar] hyper::client::pool: checkout waiting for idle connection: ("http", (delete ip):(delete port))
[22-Oct-2024 02:15:05 UTC] [ddtrace] [trace] [sidecar] hyper_util::client::legacy::connect::http: Http::connect; scheme=Some("http"), host=Some("(delete ip)"), port=Some(Port((delete port)))
[22-Oct-2024 02:15:05 UTC] [ddtrace] [debug] [sidecar] hyper_util::client::legacy::connect::http: connecting to (delete ip):(delete port)
[22-Oct-2024 02:15:05 UTC] [ddtrace] [debug] [sidecar] hyper_util::client::legacy::connect::http: connected to (delete ip):(delete port)
[22-Oct-2024 02:15:05 UTC] [ddtrace] [trace] [sidecar] hyper::client::conn: client handshake Http1
[22-Oct-2024 02:15:05 UTC] [ddtrace] [trace] [sidecar] hyper::client::client: handshake complete, spawning background dispatcher task
[22-Oct-2024 02:15:05 UTC] [ddtrace] [trace] [sidecar] hyper::proto::h1::conn: flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Busy }
[22-Oct-2024 02:15:05 UTC] [ddtrace] [trace] [sidecar] hyper::client::pool: checkout dropped for ("http", (delete ip):(delete port))
[22-Oct-2024 02:15:05 UTC] [ddtrace] [trace] [sidecar] encode_headers: hyper::proto::h1::role: Client::encode method=POST, body=Some(Known(487))
[22-Oct-2024 02:15:05 UTC] [ddtrace] [trace] [sidecar] hyper::proto::h1::io: buffer.flatten self.len=474 buf.len=487
[22-Oct-2024 02:15:05 UTC] [ddtrace] [debug] [sidecar] hyper::proto::h1::io: flushed 961 bytes
[22-Oct-2024 02:15:05 UTC] [ddtrace] [trace] [sidecar] hyper::proto::h1::conn: flushed({role=client}): State { reading: Init, writing: KeepAlive, keep_alive: Busy }
[22-Oct-2024 02:15:05 UTC] [ddtrace] [debug] [sidecar] ddtelemetry::worker: Handling action Lifecycle(FlushMetricAggr)
[22-Oct-2024 02:15:06 UTC] [ddtrace] [trace] [sidecar] hyper::proto::h1::conn: Conn::read_head
[22-Oct-2024 02:15:06 UTC] [ddtrace] [trace] [sidecar] hyper::proto::h1::io: received 445 bytes
[22-Oct-2024 02:15:06 UTC] [ddtrace] [trace] [sidecar] parse_headers: hyper::proto::h1::role: Response.parse bytes=445
[22-Oct-2024 02:15:06 UTC] [ddtrace] [trace] [sidecar] parse_headers: hyper::proto::h1::role: Response.parse Complete(443)
[22-Oct-2024 02:15:06 UTC] [ddtrace] [debug] [sidecar] hyper::proto::h1::io: parsed 9 headers
[22-Oct-2024 02:15:06 UTC] [ddtrace] [debug] [sidecar] hyper::proto::h1::conn: incoming body is content-length (2 bytes)
[22-Oct-2024 02:15:06 UTC] [ddtrace] [trace] [sidecar] hyper::proto::h1::decode: decode; state=Length(2)
[22-Oct-2024 02:15:06 UTC] [ddtrace] [debug] [sidecar] hyper::proto::h1::conn: incoming body completed
[22-Oct-2024 02:15:06 UTC] [ddtrace] [trace] [sidecar] hyper::proto::h1::conn: maybe_notify; read_from_io blocked
[22-Oct-2024 02:15:06 UTC] [ddtrace] [trace] [sidecar] hyper::proto::h1::conn: flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Idle }
[22-Oct-2024 02:15:06 UTC] [ddtrace] [trace] [sidecar] hyper::proto::h1::conn: flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Idle }
[22-Oct-2024 02:15:06 UTC] [ddtrace] [trace] [sidecar] hyper::client::pool: put; add idle connection for ("http", (delete ip):(delete port))
[22-Oct-2024 02:15:06 UTC] [ddtrace] [debug] [sidecar] hyper::client::pool: pooling idle connection for ("http", (delete ip):(delete port))
[22-Oct-2024 02:15:06 UTC] [ddtrace] [debug] [sidecar] ddtelemetry::worker: Prepared payload: Telemetry { api_version: V2, tracer_time: 1729563306, runtime_id: "cd4a516f-60a4-4caf-8564-95fb3ea8a9a0", seq_id: 35, application: Application { service_name: "background_sender-php-service", service_version: None, env: Some("none"), language_name: "php", language_version: "8.1.13", tracer_version: "1.4.1", runtime_name: None, runtime_version: None, runtime_patches: None }, host: Host { hostname: "order-group-api2-5fdfbb7c55-r69jg", container_id: Some("a6f919a8368e0a5a05fe2a66a235e7259c4fc200ca3692f0f3c1315d97afc07c"), os: Some("linux"), os_version: Some("5.10.226-214.879.amzn2.x86_64"), kernel_name: None, kernel_release: None, kernel_version: None }, payload: MessageBatch([GenerateMetrics(GenerateMetrics { series: [Serie { namespace: Tracers, metric: "trace_api.responses", points: [(1729563245, 2.0), (1729563255, 2.0), (1729563265, 2.0), (1729563275, 1.0)], tags: [Tag { value: "status_code:2xx" }], common: true, _type: Count, interval: 10 }, Serie { namespace: Tracers, metric: "trace_api.requests", points: [(1729563245, 2.0), (1729563255, 2.0), (1729563265, 2.0), (1729563275, 1.0)], tags: [], common: true, _type: Count, interval: 10 }] })]) }
[22-Oct-2024 02:15:06 UTC] [ddtrace] [trace] [sidecar] hyper::client::pool: take? ("http", (delete ip):(delete port)): expiration = Some(30s)
[22-Oct-2024 02:15:06 UTC] [ddtrace] [debug] [sidecar] hyper::client::pool: reuse idle connection for ("http", (delete ip):(delete port))
[22-Oct-2024 02:15:06 UTC] [ddtrace] [trace] [sidecar] encode_headers: hyper::proto::h1::role: Client::encode method=POST, body=Some(Known(948))
[22-Oct-2024 02:15:06 UTC] [ddtrace] [trace] [sidecar] hyper::proto::h1::io: buffer.flatten self.len=474 buf.len=948
[22-Oct-2024 02:15:06 UTC] [ddtrace] [debug] [sidecar] hyper::proto::h1::io: flushed 1422 bytes
[22-Oct-2024 02:15:06 UTC] [ddtrace] [trace] [sidecar] hyper::proto::h1::conn: flushed({role=client}): State { reading: Init, writing: KeepAlive, keep_alive: Busy }
[22-Oct-2024 02:15:06 UTC] [ddtrace] [debug] [sidecar] ddtelemetry::worker: Handling action Lifecycle(FlushMetricAggr)
[22-Oct-2024 02:15:06 UTC] [ddtrace] [debug] [sidecar] ddtelemetry::worker: Handling action Lifecycle(FlushData)
[22-Oct-2024 02:15:06 UTC] [ddtrace] [debug] [sidecar] ddtelemetry::worker: Prepared payload: Telemetry { api_version: V2, tracer_time: 1729563306, runtime_id: "bebd5120-6829-43f5-9484-c11726c5cc2c", seq_id: 37, application: Application { service_name: "background_sender-php-service", service_version: None, env: Some("none"), language_name: "php", language_version: "8.1.13", tracer_version: "1.4.1", runtime_name: None, runtime_version: None, runtime_patches: None }, host: Host { hostname: "order-group-api2-5fdfbb7c55-r69jg", container_id: Some("a6f919a8368e0a5a05fe2a66a235e7259c4fc200ca3692f0f3c1315d97afc07c"), os: Some("linux"), os_version: Some("5.10.226-214.879.amzn2.x86_64"), kernel_name: None, kernel_release: None, kernel_version: None }, payload: AppHeartbeat(()) }
[22-Oct-2024 02:15:06 UTC] [ddtrace] [trace] [sidecar] hyper::client::pool: take? ("http", (delete ip):(delete port)): expiration = Some(30s)
[22-Oct-2024 02:15:06 UTC] [ddtrace] [trace] [sidecar] hyper::client::pool: removing closed connection for ("http", (delete ip):(delete port))
[22-Oct-2024 02:15:06 UTC] [ddtrace] [trace] [sidecar] hyper::client::pool: checkout waiting for idle connection: ("http", (delete ip):(delete port))
[22-Oct-2024 02:15:06 UTC] [ddtrace] [trace] [sidecar] hyper_util::client::legacy::connect::http: Http::connect; scheme=Some("http"), host=Some("(delete ip)"), port=Some(Port((delete port)))
[22-Oct-2024 02:15:06 UTC] [ddtrace] [debug] [sidecar] hyper_util::client::legacy::connect::http: connecting to (delete ip):(delete port)
[22-Oct-2024 02:15:06 UTC] [ddtrace] [debug] [sidecar] hyper_util::client::legacy::connect::http: connected to (delete ip):(delete port)
[22-Oct-2024 02:15:06 UTC] [ddtrace] [trace] [sidecar] hyper::client::conn: client handshake Http1
[22-Oct-2024 02:15:06 UTC] [ddtrace] [trace] [sidecar] hyper::client::client: handshake complete, spawning background dispatcher task
[22-Oct-2024 02:15:06 UTC] [ddtrace] [trace] [sidecar] hyper::proto::h1::conn: flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Busy }
[22-Oct-2024 02:15:06 UTC] [ddtrace] [trace] [sidecar] hyper::client::pool: checkout dropped for ("http", (delete ip):(delete port))
[22-Oct-2024 02:15:06 UTC] [ddtrace] [trace] [sidecar] encode_headers: hyper::proto::h1::role: Client::encode method=POST, body=Some(Known(487))
[22-Oct-2024 02:15:06 UTC] [ddtrace] [trace] [sidecar] hyper::proto::h1::io: buffer.flatten self.len=474 buf.len=487
[22-Oct-2024 02:15:06 UTC] [ddtrace] [debug] [sidecar] hyper::proto::h1::io: flushed 961 bytes
[22-Oct-2024 02:15:06 UTC] [ddtrace] [trace] [sidecar] hyper::proto::h1::conn: flushed({role=client}): State { reading: Init, writing: KeepAlive, keep_alive: Busy }
[22-Oct-2024 02:15:06 UTC] [ddtrace] [debug] [sidecar] ddtelemetry::worker: Handling action Lifecycle(FlushMetricAggr)
[22-Oct-2024 02:15:06 UTC] [ddtrace] [debug] [sidecar] ddtelemetry::worker: Handling action Lifecycle(FlushMetricAggr)
[22-Oct-2024 02:15:06 UTC] [ddtrace] [trace] [sidecar] hyper::proto::h1::conn: Conn::read_head
[22-Oct-2024 02:15:06 UTC] [ddtrace] [trace] [sidecar] hyper::proto::h1::io: received 445 bytes
[22-Oct-2024 02:15:06 UTC] [ddtrace] [trace] [sidecar] parse_headers: hyper::proto::h1::role: Response.parse bytes=445
[22-Oct-2024 02:15:06 UTC] [ddtrace] [trace] [sidecar] parse_headers: hyper::proto::h1::role: Response.parse Complete(443)
[22-Oct-2024 02:15:06 UTC] [ddtrace] [debug] [sidecar] hyper::proto::h1::io: parsed 9 headers
[22-Oct-2024 02:15:06 UTC] [ddtrace] [debug] [sidecar] hyper::proto::h1::conn: incoming body is content-length (2 bytes)
[22-Oct-2024 02:15:06 UTC] [ddtrace] [trace] [sidecar] hyper::proto::h1::decode: decode; state=Length(2)
[22-Oct-2024 02:15:06 UTC] [ddtrace] [debug] [sidecar] hyper::proto::h1::conn: incoming body completed
[22-Oct-2024 02:15:06 UTC] [ddtrace] [trace] [sidecar] hyper::proto::h1::conn: maybe_notify; read_from_io blocked
[22-Oct-2024 02:15:06 UTC] [ddtrace] [trace] [sidecar] hyper::proto::h1::conn: flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Idle }
[22-Oct-2024 02:15:06 UTC] [ddtrace] [trace] [sidecar] hyper::proto::h1::conn: flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Idle }
[22-Oct-2024 02:15:06 UTC] [ddtrace] [trace] [sidecar] hyper::client::pool: put; add idle connection for ("http", (delete ip):(delete port))
[22-Oct-2024 02:15:06 UTC] [ddtrace] [debug] [sidecar] hyper::client::pool: pooling idle connection for ("http", (delete ip):(delete port))
[22-Oct-2024 02:15:06 UTC] [ddtrace] [debug] [sidecar] ddtelemetry::worker: Handling action Lifecycle(FlushMetricAggr)
[22-Oct-2024 02:15:06 UTC] [ddtrace] [trace] [sidecar] hyper::proto::h1::conn: flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Idle }
[22-Oct-2024 02:15:06 UTC] [ddtrace] [debug] [sidecar] ddtelemetry::worker: Handling action Lifecycle(FlushMetricAggr)
[22-Oct-2024 02:15:06 UTC] [ddtrace] [debug] [sidecar] ddtelemetry::worker: Handling action Lifecycle(FlushMetricAggr)
[22-Oct-2024 02:15:06 UTC] [ddtrace] [trace] [sidecar] hyper::proto::h1::conn: Conn::read_head
[22-Oct-2024 02:15:06 UTC] [ddtrace] [trace] [sidecar] hyper::proto::h1::io: received 445 bytes
[22-Oct-2024 02:15:06 UTC] [ddtrace] [trace] [sidecar] parse_headers: hyper::proto::h1::role: Response.parse bytes=445
[22-Oct-2024 02:15:06 UTC] [ddtrace] [trace] [sidecar] parse_headers: hyper::proto::h1::role: Response.parse Complete(443)
[22-Oct-2024 02:15:06 UTC] [ddtrace] [debug] [sidecar] hyper::proto::h1::io: parsed 9 headers
[22-Oct-2024 02:15:06 UTC] [ddtrace] [debug] [sidecar] hyper::proto::h1::conn: incoming body is content-length (2 bytes)
[22-Oct-2024 02:15:06 UTC] [ddtrace] [trace] [sidecar] hyper::proto::h1::decode: decode; state=Length(2)
[22-Oct-2024 02:15:06 UTC] [ddtrace] [debug] [sidecar] hyper::proto::h1::conn: incoming body completed
[22-Oct-2024 02:15:06 UTC] [ddtrace] [trace] [sidecar] hyper::proto::h1::conn: maybe_notify; read_from_io blocked
[22-Oct-2024 02:15:06 UTC] [ddtrace] [trace] [sidecar] hyper::proto::h1::conn: flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Idle }
[22-Oct-2024 02:15:06 UTC] [ddtrace] [trace] [sidecar] hyper::proto::h1::conn: flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Idle }
[22-Oct-2024 02:15:06 UTC] [ddtrace] [trace] [sidecar] hyper::client::pool: put; add idle connection for ("http", (delete ip):(delete port))
[22-Oct-2024 02:15:06 UTC] [ddtrace] [debug] [sidecar] hyper::client::pool: pooling idle connection for ("http", (delete ip):(delete port))
[22-Oct-2024 02:15:06 UTC] [ddtrace] [debug] [sidecar] ddtelemetry::worker: Prepared payload: Telemetry { api_version: V2, tracer_time: 1729563306, runtime_id: "bebd5120-6829-43f5-9484-c11726c5cc2c", seq_id: 38, application: Application { service_name: "background_sender-php-service", service_version: None, env: Some("none"), language_name: "php", language_version: "8.1.13", tracer_version: "1.4.1", runtime_name: None, runtime_version: None, runtime_patches: None }, host: Host { hostname: "order-group-api2-5fdfbb7c55-r69jg", container_id: Some("a6f919a8368e0a5a05fe2a66a235e7259c4fc200ca3692f0f3c1315d97afc07c"), os: Some("linux"), os_version: Some("5.10.226-214.879.amzn2.x86_64"), kernel_name: None, kernel_release: None, kernel_version: None }, payload: MessageBatch([GenerateMetrics(GenerateMetrics { series: [Serie { namespace: Tracers, metric: "trace_api.responses", points: [(1729563246, 2.0), (1729563256, 2.0), (1729563266, 2.0), (1729563276, 1.0), (1729563296, 1.0)], tags: [Tag { value: "status_code:2xx" }], common: true, _type: Count, interval: 10 }, Serie { namespace: Tracers, metric: "trace_api.requests", points: [(1729563246, 2.0), (1729563256, 2.0), (1729563266, 2.0), (1729563276, 1.0), (1729563296, 1.0)], tags: [], common: true, _type: Count, interval: 10 }] })]) }
[22-Oct-2024 02:15:06 UTC] [ddtrace] [trace] [sidecar] hyper::client::pool: take? ("http", (delete ip):(delete port)): expiration = Some(30s)
[22-Oct-2024 02:15:06 UTC] [ddtrace] [debug] [sidecar] hyper::client::pool: reuse idle connection for ("http", (delete ip):(delete port))
[22-Oct-2024 02:15:06 UTC] [ddtrace] [trace] [sidecar] encode_headers: hyper::proto::h1::role: Client::encode method=POST, body=Some(Known(982))
[22-Oct-2024 02:15:06 UTC] [ddtrace] [trace] [sidecar] hyper::proto::h1::io: buffer.flatten self.len=474 buf.len=982
[22-Oct-2024 02:15:06 UTC] [ddtrace] [debug] [sidecar] hyper::proto::h1::io: flushed 1456 bytes
[22-Oct-2024 02:15:06 UTC] [ddtrace] [trace] [sidecar] hyper::proto::h1::conn: flushed({role=client}): State { reading: Init, writing: KeepAlive, keep_alive: Busy }
[22-Oct-2024 02:15:06 UTC] [ddtrace] [debug] [sidecar] ddtelemetry::worker: Handling action Lifecycle(FlushMetricAggr)
[22-Oct-2024 02:15:06 UTC] [ddtrace] [trace] [sidecar] hyper::proto::h1::conn: Conn::read_head
[22-Oct-2024 02:15:06 UTC] [ddtrace] [trace] [sidecar] hyper::proto::h1::io: received 445 bytes
[22-Oct-2024 02:15:06 UTC] [ddtrace] [trace] [sidecar] parse_headers: hyper::proto::h1::role: Response.parse bytes=445
[22-Oct-2024 02:15:06 UTC] [ddtrace] [trace] [sidecar] parse_headers: hyper::proto::h1::role: Response.parse Complete(443)
[22-Oct-2024 02:15:06 UTC] [ddtrace] [debug] [sidecar] hyper::proto::h1::io: parsed 9 headers
[22-Oct-2024 02:15:06 UTC] [ddtrace] [debug] [sidecar] hyper::proto::h1::conn: incoming body is content-length (2 bytes)
[22-Oct-2024 02:15:06 UTC] [ddtrace] [trace] [sidecar] hyper::proto::h1::decode: decode; state=Length(2)
[22-Oct-2024 02:15:06 UTC] [ddtrace] [debug] [sidecar] hyper::proto::h1::conn: incoming body completed
[22-Oct-2024 02:15:06 UTC] [ddtrace] [trace] [sidecar] hyper::proto::h1::conn: maybe_notify; read_from_io blocked
[22-Oct-2024 02:15:06 UTC] [ddtrace] [trace] [sidecar] hyper::proto::h1::conn: flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Idle }
[22-Oct-2024 02:15:06 UTC] [ddtrace] [trace] [sidecar] hyper::proto::h1::conn: flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Idle }
[22-Oct-2024 02:15:06 UTC] [ddtrace] [trace] [sidecar] hyper::client::pool: put; add idle connection for ("http", (delete ip):(delete port))
[22-Oct-2024 02:15:06 UTC] [ddtrace] [debug] [sidecar] hyper::client::pool: pooling idle connection for ("http", (delete ip):(delete port))
[22-Oct-2024 02:15:06 UTC] [ddtrace] [debug] [sidecar] ddtelemetry::worker: Handling action Lifecycle(FlushMetricAggr)
[22-Oct-2024 02:15:06 UTC] [ddtrace] [trace] [sidecar] hyper::proto::h1::conn: flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Idle }
[22-Oct-2024 02:15:06 UTC] [ddtrace] [debug] [sidecar] ddtelemetry::worker: Handling action Lifecycle(FlushMetricAggr)
[22-Oct-2024 02:15:06 UTC] [ddtrace] [debug] [sidecar] ddtelemetry::worker: Handling action Lifecycle(FlushMetricAggr)
[22-Oct-2024 02:15:07 UTC] [ddtrace] [trace] [sidecar] hyper::proto::h1::io: received 0 bytes
[22-Oct-2024 02:15:07 UTC] [ddtrace] [trace] [sidecar] hyper::proto::h1::conn: found EOF on idle connection, closing
[22-Oct-2024 02:15:07 UTC] [ddtrace] [trace] [sidecar] hyper::proto::h1::conn: State::close_read()
[22-Oct-2024 02:15:07 UTC] [ddtrace] [trace] [sidecar] hyper::proto::h1::conn: flushed({role=client}): State { reading: Closed, writing: Init, keep_alive: Disabled }
[22-Oct-2024 02:15:07 UTC] [ddtrace] [trace] [sidecar] hyper::proto::h1::conn: shut down IO complete
[22-Oct-2024 02:15:07 UTC] [ddtrace] [debug] [sidecar] ddtelemetry::worker: Handling action Lifecycle(FlushMetricAggr)
[22-Oct-2024 02:15:07 UTC] [ddtrace] [debug] [sidecar] ddtelemetry::worker: Handling action Lifecycle(FlushMetricAggr)
[22-Oct-2024 02:15:07 UTC] [ddtrace] [debug] [sidecar] ddtelemetry::worker: Handling action Lifecycle(FlushMetricAggr)
[22-Oct-2024 02:15:07 UTC] [ddtrace] [debug] [sidecar] ddtelemetry::worker: Handling action Lifecycle(FlushMetricAggr)
[22-Oct-2024 02:15:07 UTC] [ddtrace] [debug] [sidecar] ddtelemetry::worker: Handling action Lifecycle(FlushMetricAggr)
[22-Oct-2024 02:15:07 UTC] [ddtrace] [trace] [sidecar] hyper::proto::h1::io: received 0 bytes
[22-Oct-2024 02:15:07 UTC] [ddtrace] [trace] [sidecar] hyper::proto::h1::conn: found EOF on idle connection, closing
[22-Oct-2024 02:15:07 UTC] [ddtrace] [trace] [sidecar] hyper::proto::h1::conn: State::close_read()
[22-Oct-2024 02:15:07 UTC] [ddtrace] [trace] [sidecar] hyper::proto::h1::conn: flushed({role=client}): State { reading: Closed, writing: Init, keep_alive: Disabled }
[22-Oct-2024 02:15:07 UTC] [ddtrace] [trace] [sidecar] hyper::proto::h1::conn: shut down IO complete
[22-Oct-2024 02:15:08 UTC] [ddtrace] [debug] [sidecar] ddtelemetry::worker: Handling action Lifecycle(FlushMetricAggr)
[22-Oct-2024 02:15:08 UTC] [ddtrace] [trace] [sidecar] tarpc::server: OpenTelemetry subscriber not installed; making unsampled child context.
[22-Oct-2024 02:15:08 UTC] [ddtrace] [debug] [sidecar] RPC{rpc.trace_id=00 rpc.deadline=2024-10-22T02:15:18.317903957Z otel.kind="server"}: tarpc::server: ReceiveRequest
[22-Oct-2024 02:15:08 UTC] [ddtrace] [trace] [sidecar] tarpc::server: poll_flush
[22-Oct-2024 02:15:08 UTC] [ddtrace] [trace] [sidecar] tarpc::server: Expired requests: Pending, Inbound: Pending
[22-Oct-2024 02:15:08 UTC] [ddtrace] [trace] [sidecar] tarpc::server: poll_flush
[22-Oct-2024 02:15:08 UTC] [ddtrace] [info] [sidecar] RPC{rpc.trace_id=00 rpc.deadline=2024-10-22T02:15:18.317903957Z otel.kind="server" otel.name="SidecarInterface.enqueue_actions"}: tarpc::server: BeginRequest
[22-Oct-2024 02:15:08 UTC] [ddtrace] [info] [sidecar] RPC{rpc.trace_id=00 rpc.deadline=2024-10-22T02:15:18.317903957Z otel.kind="server" otel.name="SidecarInterface.enqueue_actions"}: tarpc::server: CompleteRequest
[22-Oct-2024 02:15:08 UTC] [ddtrace] [debug] [sidecar] RPC{rpc.trace_id=00 rpc.deadline=2024-10-22T02:15:18.317903957Z otel.kind="server" otel.name="SidecarInterface.enqueue_actions"}: tarpc::server: DiscardingResponse
[22-Oct-2024 02:15:08 UTC] [ddtrace] [trace] [sidecar] tarpc::server: Expired requests: Pending, Inbound: Pending
[22-Oct-2024 02:15:08 UTC] [ddtrace] [trace] [sidecar] tarpc::server: Expired requests: Closed, Inbound: Pending
[22-Oct-2024 02:15:08 UTC] [ddtrace] [trace] [sidecar] tarpc::server: poll_flush
[22-Oct-2024 02:15:08 UTC] [ddtrace] [debug] [sidecar] ddtelemetry::worker: Handling action AddPoint((1.0, ContextKey(0, Count), []))
[22-Oct-2024 02:15:08 UTC] [ddtrace] [debug] [sidecar] ddtelemetry::worker: Handling action AddPoint((1.0, ContextKey(1, Count), [Tag { value: "status_code:2xx" }]))
[22-Oct-2024 02:15:08 UTC] [ddtrace] [trace] [sidecar] tarpc::server: Expired requests: Closed, Inbound: Pending
[22-Oct-2024 02:15:08 UTC] [ddtrace] [trace] [sidecar] tarpc::server: poll_flush
[22-Oct-2024 02:15:08 UTC] [ddtrace] [trace] [sidecar] tarpc::server: OpenTelemetry subscriber not installed; making unsampled child context.
[22-Oct-2024 02:15:08 UTC] [ddtrace] [debug] [sidecar] RPC{rpc.trace_id=00 rpc.deadline=2024-10-22T02:15:18.322884897Z otel.kind="server"}: tarpc::server: ReceiveRequest
[22-Oct-2024 02:15:08 UTC] [ddtrace] [trace] [sidecar] tarpc::server: poll_flush
[22-Oct-2024 02:15:08 UTC] [ddtrace] [trace] [sidecar] tarpc::server: Expired requests: Pending, Inbound: Pending
[22-Oct-2024 02:15:08 UTC] [ddtrace] [trace] [sidecar] tarpc::server: poll_flush
[22-Oct-2024 02:15:08 UTC] [ddtrace] [info] [sidecar] RPC{rpc.trace_id=00 rpc.deadline=2024-10-22T02:15:18.322884897Z otel.kind="server" otel.name="SidecarInterface.enqueue_actions"}: tarpc::server: BeginRequest
[22-Oct-2024 02:15:08 UTC] [ddtrace] [info] [sidecar] RPC{rpc.trace_id=00 rpc.deadline=2024-10-22T02:15:18.322884897Z otel.kind="server" otel.name="SidecarInterface.enqueue_actions"}: tarpc::server: CompleteRequest
[22-Oct-2024 02:15:08 UTC] [ddtrace] [debug] [sidecar] RPC{rpc.trace_id=00 rpc.deadline=2024-10-22T02:15:18.322884897Z otel.kind="server" otel.name="SidecarInterface.enqueue_actions"}: tarpc::server: DiscardingResponse
[22-Oct-2024 02:15:08 UTC] [ddtrace] [trace] [sidecar] tarpc::server: Expired requests: Pending, Inbound: Pending
[22-Oct-2024 02:15:08 UTC] [ddtrace] [trace] [sidecar] tarpc::server: Expired requests: Closed, Inbound: Pending
[22-Oct-2024 02:15:08 UTC] [ddtrace] [trace] [sidecar] tarpc::server: poll_flush
[22-Oct-2024 02:15:08 UTC] [ddtrace] [trace] [sidecar] tarpc::server: Expired requests: Closed, Inbound: Pending
[22-Oct-2024 02:15:08 UTC] [ddtrace] [trace] [sidecar] tarpc::server: poll_flush
[22-Oct-2024 02:15:08 UTC] [ddtrace] [debug] [sidecar] ddtelemetry::worker: Handling action AddPoint((1.0, ContextKey(0, Count), []))
[22-Oct-2024 02:15:08 UTC] [ddtrace] [debug] [sidecar] ddtelemetry::worker: Handling action AddPoint((1.0, ContextKey(1, Count), [Tag { value: "status_code:2xx" }]))
[22-Oct-2024 02:15:08 UTC] [ddtrace] [trace] [sidecar] tarpc::server: OpenTelemetry subscriber not installed; making unsampled child context.
[22-Oct-2024 02:15:08 UTC] [ddtrace] [debug] [sidecar] RPC{rpc.trace_id=00 rpc.deadline=2024-10-22T02:15:18.570814619Z otel.kind="server"}: tarpc::server: ReceiveRequest
[22-Oct-2024 02:15:08 UTC] [ddtrace] [trace] [sidecar] tarpc::server: poll_flush
[22-Oct-2024 02:15:08 UTC] [ddtrace] [trace] [sidecar] tarpc::server: OpenTelemetry subscriber not installed; making unsampled child context.
[22-Oct-2024 02:15:08 UTC] [ddtrace] [debug] [sidecar] RPC{rpc.trace_id=00 rpc.deadline=2024-10-22T02:15:18.570910355Z otel.kind="server"}: tarpc::server: ReceiveRequest
[22-Oct-2024 02:15:08 UTC] [ddtrace] [trace] [sidecar] tarpc::server: poll_flush
[22-Oct-2024 02:15:08 UTC] [ddtrace] [trace] [sidecar] tarpc::server: OpenTelemetry subscriber not installed; making unsampled child context.
[22-Oct-2024 02:15:08 UTC] [ddtrace] [debug] [sidecar] RPC{rpc.trace_id=00 rpc.deadline=2024-10-22T02:15:18.570923553Z otel.kind="server"}: tarpc::server: ReceiveRequest
[22-Oct-2024 02:15:08 UTC] [ddtrace] [trace] [sidecar] tarpc::server: poll_flush
[22-Oct-2024 02:15:08 UTC] [ddtrace] [trace] [sidecar] tarpc::server: OpenTelemetry subscriber not installed; making unsampled child context.
[22-Oct-2024 02:15:08 UTC] [ddtrace] [debug] [sidecar] RPC{rpc.trace_id=00 rpc.deadline=2024-10-22T02:15:18.570931145Z otel.kind="server"}: tarpc::server: ReceiveRequest
[22-Oct-2024 02:15:08 UTC] [ddtrace] [trace] [sidecar] tarpc::server: poll_flush
[22-Oct-2024 02:15:08 UTC] [ddtrace] [trace] [sidecar] tarpc::server: OpenTelemetry subscriber not installed; making unsampled child context.
[22-Oct-2024 02:15:08 UTC] [ddtrace] [debug] [sidecar] RPC{rpc.trace_id=00 rpc.deadline=2024-10-22T02:15:18.570936905Z otel.kind="server"}: tarpc::server: ReceiveRequest
[22-Oct-2024 02:15:08 UTC] [ddtrace] [trace] [sidecar] tarpc::server: poll_flush
[22-Oct-2024 02:15:08 UTC] [ddtrace] [trace] [sidecar] tarpc::server: OpenTelemetry subscriber not installed; making unsampled child context.
[22-Oct-2024 02:15:08 UTC] [ddtrace] [debug] [sidecar] RPC{rpc.trace_id=00 rpc.deadline=2024-10-22T02:15:18.570943063Z otel.kind="server"}: tarpc::server: ReceiveRequest
[22-Oct-2024 02:15:08 UTC] [ddtrace] [trace] [sidecar] tarpc::server: poll_flush
[22-Oct-2024 02:15:08 UTC] [ddtrace] [trace] [sidecar] tarpc::server: OpenTelemetry subscriber not installed; making unsampled child context.
[22-Oct-2024 02:15:08 UTC] [ddtrace] [debug] [sidecar] RPC{rpc.trace_id=00 rpc.deadline=2024-10-22T02:15:18.570949920Z otel.kind="server"}: tarpc::server: ReceiveRequest
[22-Oct-2024 02:15:08 UTC] [ddtrace] [trace] [sidecar] tarpc::server: poll_flush
[22-Oct-2024 02:15:08 UTC] [ddtrace] [trace] [sidecar] tarpc::server: Expired requests: Pending, Inbound: Pending
[22-Oct-2024 02:15:08 UTC] [ddtrace] [trace] [sidecar] tarpc::server: poll_flush
[22-Oct-2024 02:15:08 UTC] [ddtrace] [info] [sidecar] RPC{rpc.trace_id=00 rpc.deadline=2024-10-22T02:15:18.570814619Z otel.kind="server" otel.name="SidecarInterface.set_remote_config_data"}: tarpc::server: BeginRequest
[22-Oct-2024 02:15:08 UTC] [ddtrace] [debug] [sidecar] RPC{rpc.trace_id=00 rpc.deadline=2024-10-22T02:15:18.570814619Z otel.kind="server" otel.name="SidecarInterface.set_remote_config_data"}: datadog_sidecar::service::sidecar_server: Registered remote config metadata: instance InstanceId { session_id: "81fdbf3d-6dfd-4efe-b8ba-60eabd1299f3", runtime_id: "81fdbf3d-6dfd-4efe-b8ba-60eabd1299f3" }, queue_id: QueueId { inner: 16718066906658404163 }, service: order-group-api2, env: dev, version: 0
[22-Oct-2024 02:15:08 UTC] [ddtrace] [trace] [sidecar] RPC{rpc.trace_id=00 rpc.deadline=2024-10-22T02:15:18.570814619Z otel.kind="server" otel.name="SidecarInterface.set_remote_config_data"}: datadog_remote_config::fetch::multitarget: Adding remote config runtime: Target { service: "order-group-api2", env: "dev", app_version: "0", tags: [] } with runtime id 81fdbf3d-6dfd-4efe-b8ba-60eabd1299f3
[22-Oct-2024 02:15:08 UTC] [ddtrace] [info] [sidecar] RPC{rpc.trace_id=00 rpc.deadline=2024-10-22T02:15:18.570814619Z otel.kind="server" otel.name="SidecarInterface.set_remote_config_data"}: tarpc::server: CompleteRequest
[22-Oct-2024 02:15:08 UTC] [ddtrace] [debug] [sidecar] RPC{rpc.trace_id=00 rpc.deadline=2024-10-22T02:15:18.570814619Z otel.kind="server" otel.name="SidecarInterface.set_remote_config_data"}: tarpc::server: DiscardingResponse
[22-Oct-2024 02:15:08 UTC] [ddtrace] [info] [sidecar] RPC{rpc.trace_id=00 rpc.deadline=2024-10-22T02:15:18.570910355Z otel.kind="server" otel.name="SidecarInterface.set_remote_config_data"}: tarpc::server: BeginRequest
[22-Oct-2024 02:15:08 UTC] [ddtrace] [debug] [sidecar] RPC{rpc.trace_id=00 rpc.deadline=2024-10-22T02:15:18.570910355Z otel.kind="server" otel.name="SidecarInterface.set_remote_config_data"}: datadog_sidecar::service::sidecar_server: Registered remote config metadata: instance InstanceId { session_id: "81fdbf3d-6dfd-4efe-b8ba-60eabd1299f3", runtime_id: "81fdbf3d-6dfd-4efe-b8ba-60eabd1299f3" }, queue_id: QueueId { inner: 16718066906658404163 }, service: order-group-api2, env: dev, version: 0
[22-Oct-2024 02:15:08 UTC] [ddtrace] [trace] [sidecar] RPC{rpc.trace_id=00 rpc.deadline=2024-10-22T02:15:18.570910355Z otel.kind="server" otel.name="SidecarInterface.set_remote_config_data"}: datadog_remote_config::fetch::multitarget: Adding remote config runtime: Target { service: "order-group-api2", env: "dev", app_version: "0", tags: [] } with runtime id 81fdbf3d-6dfd-4efe-b8ba-60eabd1299f3
[22-Oct-2024 02:15:08 UTC] [ddtrace] [trace] [sidecar] RPC{rpc.trace_id=00 rpc.deadline=2024-10-22T02:15:18.570910355Z otel.kind="server" otel.name="SidecarInterface.set_remote_config_data"}: datadog_remote_config::fetch::multitarget: Removing remote config runtime: Target { service: "order-group-api2", env: "dev", app_version: "0", tags: [] } with runtime id 81fdbf3d-6dfd-4efe-b8ba-60eabd1299f3
[22-Oct-2024 02:15:08 UTC] [ddtrace] [info] [sidecar] RPC{rpc.trace_id=00 rpc.deadline=2024-10-22T02:15:18.570910355Z otel.kind="server" otel.name="SidecarInterface.set_remote_config_data"}: tarpc::server: CompleteRequest
[22-Oct-2024 02:15:08 UTC] [ddtrace] [debug] [sidecar] RPC{rpc.trace_id=00 rpc.deadline=2024-10-22T02:15:18.570910355Z otel.kind="server" otel.name="SidecarInterface.set_remote_config_data"}: tarpc::server: DiscardingResponse
[22-Oct-2024 02:15:08 UTC] [ddtrace] [info] [sidecar] RPC{rpc.trace_id=00 rpc.deadline=2024-10-22T02:15:18.570923553Z otel.kind="server" otel.name="SidecarInterface.set_remote_config_data"}: tarpc::server: BeginRequest
[22-Oct-2024 02:15:08 UTC] [ddtrace] [debug] [sidecar] RPC{rpc.trace_id=00 rpc.deadline=2024-10-22T02:15:18.570923553Z otel.kind="server" otel.name="SidecarInterface.set_remote_config_data"}: datadog_sidecar::service::sidecar_server: Registered remote config metadata: instance InstanceId { session_id: "81fdbf3d-6dfd-4efe-b8ba-60eabd1299f3", runtime_id: "81fdbf3d-6dfd-4efe-b8ba-60eabd1299f3" }, queue_id: QueueId { inner: 16718066906658404163 }, service: order-group-api2, env: dev, version: 0
[22-Oct-2024 02:15:08 UTC] [ddtrace] [trace] [sidecar] RPC{rpc.trace_id=00 rpc.deadline=2024-10-22T02:15:18.570923553Z otel.kind="server" otel.name="SidecarInterface.set_remote_config_data"}: datadog_remote_config::fetch::multitarget: Adding remote config runtime: Target { service: "order-group-api2", env: "dev", app_version: "0", tags: [] } with runtime id 81fdbf3d-6dfd-4efe-b8ba-60eabd1299f3
[22-Oct-2024 02:15:08 UTC] [ddtrace] [trace] [sidecar] RPC{rpc.trace_id=00 rpc.deadline=2024-10-22T02:15:18.570923553Z otel.kind="server" otel.name="SidecarInterface.set_remote_config_data"}: datadog_remote_config::fetch::multitarget: Removing remote config runtime: Target { service: "order-group-api2", env: "dev", app_version: "0", tags: [] } with runtime id 81fdbf3d-6dfd-4efe-b8ba-60eabd1299f3
[22-Oct-2024 02:15:08 UTC] [ddtrace] [info] [sidecar] RPC{rpc.trace_id=00 rpc.deadline=2024-10-22T02:15:18.570923553Z otel.kind="server" otel.name="SidecarInterface.set_remote_config_data"}: tarpc::server: CompleteRequest
[22-Oct-2024 02:15:08 UTC] [ddtrace] [debug] [sidecar] RPC{rpc.trace_id=00 rpc.deadline=2024-10-22T02:15:18.570923553Z otel.kind="server" otel.name="SidecarInterface.set_remote_config_data"}: tarpc::server: DiscardingResponse
[22-Oct-2024 02:15:08 UTC] [ddtrace] [info] [sidecar] RPC{rpc.trace_id=00 rpc.deadline=2024-10-22T02:15:18.570931145Z otel.kind="server" otel.name="SidecarInterface.set_remote_config_data"}: tarpc::server: BeginRequest
[22-Oct-2024 02:15:08 UTC] [ddtrace] [debug] [sidecar] RPC{rpc.trace_id=00 rpc.deadline=2024-10-22T02:15:18.570931145Z otel.kind="server" otel.name="SidecarInterface.set_remote_config_data"}: datadog_sidecar::service::sidecar_server: Registered remote config metadata: instance InstanceId { session_id: "81fdbf3d-6dfd-4efe-b8ba-60eabd1299f3", runtime_id: "81fdbf3d-6dfd-4efe-b8ba-60eabd1299f3" }, queue_id: QueueId { inner: 16718066906658404163 }, service: order-group-api2, env: dev, version: 0
[22-Oct-2024 02:15:08 UTC] [ddtrace] [trace] [sidecar] RPC{rpc.trace_id=00 rpc.deadline=2024-10-22T02:15:18.570931145Z otel.kind="server" otel.name="SidecarInterface.set_remote_config_data"}: datadog_remote_config::fetch::multitarget: Adding remote config runtime: Target { service: "order-group-api2", env: "dev", app_version: "0", tags: [] } with runtime id 81fdbf3d-6dfd-4efe-b8ba-60eabd1299f3
[22-Oct-2024 02:15:08 UTC] [ddtrace] [trace] [sidecar] RPC{rpc.trace_id=00 rpc.deadline=2024-10-22T02:15:18.570931145Z otel.kind="server" otel.name="SidecarInterface.set_remote_config_data"}: datadog_remote_config::fetch::multitarget: Removing remote config runtime: Target { service: "order-group-api2", env: "dev", app_version: "0", tags: [] } with runtime id 81fdbf3d-6dfd-4efe-b8ba-60eabd1299f3
[22-Oct-2024 02:15:08 UTC] [ddtrace] [info] [sidecar] RPC{rpc.trace_id=00 rpc.deadline=2024-10-22T02:15:18.570931145Z otel.kind="server" otel.name="SidecarInterface.set_remote_config_data"}: tarpc::server: CompleteRequest
[22-Oct-2024 02:15:08 UTC] [ddtrace] [debug] [sidecar] RPC{rpc.trace_id=00 rpc.deadline=2024-10-22T02:15:18.570931145Z otel.kind="server" otel.name="SidecarInterface.set_remote_config_data"}: tarpc::server: DiscardingResponse
[22-Oct-2024 02:15:08 UTC] [ddtrace] [info] [sidecar] RPC{rpc.trace_id=00 rpc.deadline=2024-10-22T02:15:18.570936905Z otel.kind="server" otel.name="SidecarInterface.set_remote_config_data"}: tarpc::server: BeginRequest
[22-Oct-2024 02:15:08 UTC] [ddtrace] [debug] [sidecar] RPC{rpc.trace_id=00 rpc.deadline=2024-10-22T02:15:18.570936905Z otel.kind="server" otel.name="SidecarInterface.set_remote_config_data"}: datadog_sidecar::service::sidecar_server: Registered remote config metadata: instance InstanceId { session_id: "81fdbf3d-6dfd-4efe-b8ba-60eabd1299f3", runtime_id: "81fdbf3d-6dfd-4efe-b8ba-60eabd1299f3" }, queue_id: QueueId { inner: 16718066906658404163 }, service: order-group-api2, env: dev, version: 0
[22-Oct-2024 02:15:08 UTC] [ddtrace] [trace] [sidecar] RPC{rpc.trace_id=00 rpc.deadline=2024-10-22T02:15:18.570936905Z otel.kind="server" otel.name="SidecarInterface.set_remote_config_data"}: datadog_remote_config::fetch::multitarget: Adding remote config runtime: Target { service: "order-group-api2", env: "dev", app_version: "0", tags: [] } with runtime id 81fdbf3d-6dfd-4efe-b8ba-60eabd1299f3
[22-Oct-2024 02:15:08 UTC] [ddtrace] [trace] [sidecar] RPC{rpc.trace_id=00 rpc.deadline=2024-10-22T02:15:18.570936905Z otel.kind="server" otel.name="SidecarInterface.set_remote_config_data"}: datadog_remote_config::fetch::multitarget: Removing remote config runtime: Target { service: "order-group-api2", env: "dev", app_version: "0", tags: [] } with runtime id 81fdbf3d-6dfd-4efe-b8ba-60eabd1299f3
[22-Oct-2024 02:15:08 UTC] [ddtrace] [info] [sidecar] RPC{rpc.trace_id=00 rpc.deadline=2024-10-22T02:15:18.570936905Z otel.kind="server" otel.name="SidecarInterface.set_remote_config_data"}: tarpc::server: CompleteRequest
[22-Oct-2024 02:15:08 UTC] [ddtrace] [debug] [sidecar] RPC{rpc.trace_id=00 rpc.deadline=2024-10-22T02:15:18.570936905Z otel.kind="server" otel.name="SidecarInterface.set_remote_config_data"}: tarpc::server: DiscardingResponse
[22-Oct-2024 02:15:08 UTC] [ddtrace] [info] [sidecar] RPC{rpc.trace_id=00 rpc.deadline=2024-10-22T02:15:18.570943063Z otel.kind="server" otel.name="SidecarInterface.set_remote_config_data"}: tarpc::server: BeginRequest
[22-Oct-2024 02:15:08 UTC] [ddtrace] [debug] [sidecar] RPC{rpc.trace_id=00 rpc.deadline=2024-10-22T02:15:18.570943063Z otel.kind="server" otel.name="SidecarInterface.set_remote_config_data"}: datadog_sidecar::service::sidecar_server: Registered remote config metadata: instance InstanceId { session_id: "81fdbf3d-6dfd-4efe-b8ba-60eabd1299f3", runtime_id: "81fdbf3d-6dfd-4efe-b8ba-60eabd1299f3" }, queue_id: QueueId { inner: 16718066906658404163 }, service: order-group-api2, env: dev, version: 0
[22-Oct-2024 02:15:08 UTC] [ddtrace] [trace] [sidecar] RPC{rpc.trace_id=00 rpc.deadline=2024-10-22T02:15:18.570943063Z otel.kind="server" otel.name="SidecarInterface.set_remote_config_data"}: datadog_remote_config::fetch::multitarget: Adding remote config runtime: Target { service: "order-group-api2", env: "dev", app_version: "0", tags: [] } with runtime id 81fdbf3d-6dfd-4efe-b8ba-60eabd1299f3
[22-Oct-2024 02:15:08 UTC] [ddtrace] [trace] [sidecar] RPC{rpc.trace_id=00 rpc.deadline=2024-10-22T02:15:18.570943063Z otel.kind="server" otel.name="SidecarInterface.set_remote_config_data"}: datadog_remote_config::fetch::multitarget: Removing remote config runtime: Target { service: "order-group-api2", env: "dev", app_version: "0", tags: [] } with runtime id 81fdbf3d-6dfd-4efe-b8ba-60eabd1299f3
[22-Oct-2024 02:15:08 UTC] [ddtrace] [info] [sidecar] RPC{rpc.trace_id=00 rpc.deadline=2024-10-22T02:15:18.570943063Z otel.kind="server" otel.name="SidecarInterface.set_remote_config_data"}: tarpc::server: CompleteRequest
[22-Oct-2024 02:15:08 UTC] [ddtrace] [debug] [sidecar] RPC{rpc.trace_id=00 rpc.deadline=2024-10-22T02:15:18.570943063Z otel.kind="server" otel.name="SidecarInterface.set_remote_config_data"}: tarpc::server: DiscardingResponse
[22-Oct-2024 02:15:08 UTC] [ddtrace] [info] [sidecar] RPC{rpc.trace_id=00 rpc.deadline=2024-10-22T02:15:18.570949920Z otel.kind="server" otel.name="SidecarInterface.set_remote_config_data"}: tarpc::server: BeginRequest
[22-Oct-2024 02:15:08 UTC] [ddtrace] [debug] [sidecar] RPC{rpc.trace_id=00 rpc.deadline=2024-10-22T02:15:18.570949920Z otel.kind="server" otel.name="SidecarInterface.set_remote_config_data"}: datadog_sidecar::service::sidecar_server: Registered remote config metadata: instance InstanceId { session_id: "81fdbf3d-6dfd-4efe-b8ba-60eabd1299f3", runtime_id: "81fdbf3d-6dfd-4efe-b8ba-60eabd1299f3" }, queue_id: QueueId { inner: 16718066906658404163 }, service: order-group-api2, env: dev, version: 0
[22-Oct-2024 02:15:08 UTC] [ddtrace] [trace] [sidecar] RPC{rpc.trace_id=00 rpc.deadline=2024-10-22T02:15:18.570949920Z otel.kind="server" otel.name="SidecarInterface.set_remote_config_data"}: datadog_remote_config::fetch::multitarget: Adding remote config runtime: Target { service: "order-group-api2", env: "dev", app_version: "0", tags: [] } with runtime id 81fdbf3d-6dfd-4efe-b8ba-60eabd1299f3
[22-Oct-2024 02:15:08 UTC] [ddtrace] [trace] [sidecar] RPC{rpc.trace_id=00 rpc.deadline=2024-10-22T02:15:18.570949920Z otel.kind="server" otel.name="SidecarInterface.set_remote_config_data"}: datadog_remote_config::fetch::multitarget: Removing remote config runtime: Target { service: "order-group-api2", env: "dev", app_version: "0", tags: [] } with runtime id 81fdbf3d-6dfd-4efe-b8ba-60eabd1299f3
[22-Oct-2024 02:15:08 UTC] [ddtrace] [info] [sidecar] RPC{rpc.trace_id=00 rpc.deadline=2024-10-22T02:15:18.570949920Z otel.kind="server" otel.name="SidecarInterface.set_remote_config_data"}: tarpc::server: CompleteRequest
[22-Oct-2024 02:15:08 UTC] [ddtrace] [debug] [sidecar] RPC{rpc.trace_id=00 rpc.deadline=2024-10-22T02:15:18.570949920Z otel.kind="server" otel.name="SidecarInterface.set_remote_config_data"}: tarpc::server: DiscardingResponse
[22-Oct-2024 02:15:08 UTC] [ddtrace] [trace] [sidecar] tarpc::server: Expired requests: Pending, Inbound: Pending
[22-Oct-2024 02:15:08 UTC] [ddtrace] [trace] [sidecar] tarpc::server: Expired requests: Pending, Inbound: Pending
[22-Oct-2024 02:15:08 UTC] [ddtrace] [trace] [sidecar] tarpc::server: Expired requests: Pending, Inbound: Pending
[22-Oct-2024 02:15:08 UTC] [ddtrace] [trace] [sidecar] tarpc::server: Expired requests: Pending, Inbound: Pending
[22-Oct-2024 02:15:08 UTC] [ddtrace] [trace] [sidecar] tarpc::server: Expired requests: Pending, Inbound: Pending
[22-Oct-2024 02:15:08 UTC] [ddtrace] [trace] [sidecar] tarpc::server: Expired requests: Pending, Inbound: Pending
[22-Oct-2024 02:15:08 UTC] [ddtrace] [trace] [sidecar] tarpc::server: Expired requests: Pending, Inbound: Pending
[22-Oct-2024 02:15:08 UTC] [ddtrace] [trace] [sidecar] tarpc::server: Expired requests: Closed, Inbound: Pending
[22-Oct-2024 02:15:08 UTC] [ddtrace] [trace] [sidecar] tarpc::server: poll_flush
[22-Oct-2024 02:15:08 UTC] [ddtrace] [trace] [sidecar] tarpc::server: Expired requests: Closed, Inbound: Pending
[22-Oct-2024 02:15:08 UTC] [ddtrace] [trace] [sidecar] tarpc::server: poll_flush
[22-Oct-2024 02:15:08 UTC] [ddtrace] [trace] [sidecar] tarpc::server: OpenTelemetry subscriber not installed; making unsampled child context.
[22-Oct-2024 02:15:08 UTC] [ddtrace] [debug] [sidecar] RPC{rpc.trace_id=00 rpc.deadline=2024-10-22T02:15:18.571293069Z otel.kind="server"}: tarpc::server: ReceiveRequest
[22-Oct-2024 02:15:08 UTC] [ddtrace] [trace] [sidecar] tarpc::server: poll_flush
[22-Oct-2024 02:15:08 UTC] [ddtrace] [trace] [sidecar] tarpc::server: OpenTelemetry subscriber not installed; making unsampled child context.
[22-Oct-2024 02:15:08 UTC] [ddtrace] [debug] [sidecar] RPC{rpc.trace_id=00 rpc.deadline=2024-10-22T02:15:18.571419347Z otel.kind="server"}: tarpc::server: ReceiveRequest
[22-Oct-2024 02:15:08 UTC] [ddtrace] [trace] [sidecar] tarpc::server: poll_flush
[22-Oct-2024 02:15:08 UTC] [ddtrace] [trace] [sidecar] tarpc::server: OpenTelemetry subscriber not installed; making unsampled child context.
[22-Oct-2024 02:15:08 UTC] [ddtrace] [debug] [sidecar] RPC{rpc.trace_id=00 rpc.deadline=2024-10-22T02:15:18.571428025Z otel.kind="server"}: tarpc::server: ReceiveRequest
[22-Oct-2024 02:15:08 UTC] [ddtrace] [trace] [sidecar] tarpc::server: poll_flush
[22-Oct-2024 02:15:08 UTC] [ddtrace] [trace] [sidecar] tarpc::server: Expired requests: Pending, Inbound: Pending
[22-Oct-2024 02:15:08 UTC] [ddtrace] [trace] [sidecar] tarpc::server: poll_flush
[22-Oct-2024 02:15:08 UTC] [ddtrace] [info] [sidecar] RPC{rpc.trace_id=00 rpc.deadline=2024-10-22T02:15:18.571293069Z otel.kind="server" otel.name="SidecarInterface.enqueue_actions"}: tarpc::server: BeginRequest
[22-Oct-2024 02:15:08 UTC] [ddtrace] [info] [sidecar] RPC{rpc.trace_id=00 rpc.deadline=2024-10-22T02:15:18.571293069Z otel.kind="server" otel.name="SidecarInterface.enqueue_actions"}: tarpc::server: CompleteRequest
[22-Oct-2024 02:15:08 UTC] [ddtrace] [debug] [sidecar] RPC{rpc.trace_id=00 rpc.deadline=2024-10-22T02:15:18.571293069Z otel.kind="server" otel.name="SidecarInterface.enqueue_actions"}: tarpc::server: DiscardingResponse
[22-Oct-2024 02:15:08 UTC] [ddtrace] [info] [sidecar] RPC{rpc.trace_id=00 rpc.deadline=2024-10-22T02:15:18.571419347Z otel.kind="server" otel.name="SidecarInterface.register_service_and_flush_queued_actions"}: tarpc::server: BeginRequest
[22-Oct-2024 02:15:08 UTC] [ddtrace] [info] [sidecar] RPC{rpc.trace_id=00 rpc.deadline=2024-10-22T02:15:18.571419347Z otel.kind="server" otel.name="SidecarInterface.register_service_and_flush_queued_actions"}: tarpc::server: CompleteRequest
[22-Oct-2024 02:15:08 UTC] [ddtrace] [debug] [sidecar] RPC{rpc.trace_id=00 rpc.deadline=2024-10-22T02:15:18.571419347Z otel.kind="server" otel.name="SidecarInterface.register_service_and_flush_queued_actions"}: tarpc::server: DiscardingResponse
[22-Oct-2024 02:15:08 UTC] [ddtrace] [info] [sidecar] RPC{rpc.trace_id=00 rpc.deadline=2024-10-22T02:15:18.571428025Z otel.kind="server" otel.name="SidecarInterface.enqueue_actions"}: tarpc::server: BeginRequest
[22-Oct-2024 02:15:08 UTC] [ddtrace] [trace] [sidecar] RPC{rpc.trace_id=00 rpc.deadline=2024-10-22T02:15:18.571428025Z otel.kind="server" otel.name="SidecarInterface.enqueue_actions"}: datadog_remote_config::fetch::multitarget: Removing remote config runtime: Target { service: "order-group-api2", env: "dev", app_version: "0", tags: [] } with runtime id 81fdbf3d-6dfd-4efe-b8ba-60eabd1299f3
[22-Oct-2024 02:15:08 UTC] [ddtrace] [info] [sidecar] RPC{rpc.trace_id=00 rpc.deadline=2024-10-22T02:15:18.571428025Z otel.kind="server" otel.name="SidecarInterface.enqueue_actions"}: tarpc::server: CompleteRequest
[22-Oct-2024 02:15:08 UTC] [ddtrace] [debug] [sidecar] RPC{rpc.trace_id=00 rpc.deadline=2024-10-22T02:15:18.571428025Z otel.kind="server" otel.name="SidecarInterface.enqueue_actions"}: tarpc::server: DiscardingResponse
[22-Oct-2024 02:15:08 UTC] [ddtrace] [trace] [sidecar] tarpc::server: Expired requests: Pending, Inbound: Pending
[22-Oct-2024 02:15:08 UTC] [ddtrace] [trace] [sidecar] tarpc::server: Expired requests: Pending, Inbound: Pending
[22-Oct-2024 02:15:08 UTC] [ddtrace] [trace] [sidecar] tarpc::server: Expired requests: Pending, Inbound: Pending
[22-Oct-2024 02:15:08 UTC] [ddtrace] [trace] [sidecar] tarpc::server: Expired requests: Closed, Inbound: Pending
[22-Oct-2024 02:15:08 UTC] [ddtrace] [trace] [sidecar] tarpc::server: poll_flush
[22-Oct-2024 02:15:08 UTC] [ddtrace] [debug] [sidecar] ddtelemetry::worker: Handling action AddPoint((1.0, ContextKey(0, Count), [Tag { value: "integration_name:datadog" }]))
[22-Oct-2024 02:15:08 UTC] [ddtrace] [trace] [sidecar] tarpc::server: Expired requests: Closed, Inbound: Pending
[22-Oct-2024 02:15:08 UTC] [ddtrace] [trace] [sidecar] tarpc::server: poll_flush
[22-Oct-2024 02:15:08 UTC] [ddtrace] [debug] [sidecar] ddtelemetry::worker: Handling action AddPoint((7.0, ContextKey(1, Count), [Tag { value: "level:trace" }]))
[22-Oct-2024 02:15:08 UTC] [ddtrace] [debug] [sidecar] ddtelemetry::worker: Handling action AddPoint((2.0, ContextKey(1, Count), [Tag { value: "level:debug" }]))
[22-Oct-2024 02:15:08 UTC] [ddtrace] [debug] [sidecar] ddtelemetry::worker: Handling action AddPoint((1.0, ContextKey(1, Count), [Tag { value: "level:info" }]))
[22-Oct-2024 02:15:08 UTC] [ddtrace] [debug] [sidecar] ddtelemetry::worker: Handling action AddPoint((1.0, ContextKey(1, Count), [Tag { value: "level:warn" }]))
[22-Oct-2024 02:15:08 UTC] [ddtrace] [debug] [sidecar] ddtelemetry::worker: Handling action Lifecycle(Stop)
[22-Oct-2024 02:15:08 UTC] [ddtrace] [trace] [sidecar] tarpc::server: OpenTelemetry subscriber not installed; making unsampled child context.
[22-Oct-2024 02:15:08 UTC] [ddtrace] [debug] [sidecar] RPC{rpc.trace_id=00 rpc.deadline=2024-10-22T02:15:18.587733704Z otel.kind="server"}: tarpc::server: ReceiveRequest
[22-Oct-2024 02:15:08 UTC] [ddtrace] [trace] [sidecar] tarpc::server: poll_flush
[22-Oct-2024 02:15:08 UTC] [ddtrace] [trace] [sidecar] tarpc::server: OpenTelemetry subscriber not installed; making unsampled child context.
[22-Oct-2024 02:15:08 UTC] [ddtrace] [debug] [sidecar] RPC{rpc.trace_id=00 rpc.deadline=2024-10-22T02:15:18.587795963Z otel.kind="server"}: tarpc::server: ReceiveRequest
[22-Oct-2024 02:15:08 UTC] [ddtrace] [trace] [sidecar] tarpc::server: poll_flush
[22-Oct-2024 02:15:08 UTC] [ddtrace] [trace] [sidecar] tarpc::server: OpenTelemetry subscriber not installed; making unsampled child context.
[22-Oct-2024 02:15:08 UTC] [ddtrace] [debug] [sidecar] RPC{rpc.trace_id=00 rpc.deadline=2024-10-22T02:15:18.587805997Z otel.kind="server"}: tarpc::server: ReceiveRequest
[22-Oct-2024 02:15:08 UTC] [ddtrace] [trace] [sidecar] tarpc::server: poll_flush
[22-Oct-2024 02:15:08 UTC] [ddtrace] [trace] [sidecar] tarpc::server: OpenTelemetry subscriber not installed; making unsampled child context.
[22-Oct-2024 02:15:08 UTC] [ddtrace] [debug] [sidecar] RPC{rpc.trace_id=00 rpc.deadline=2024-10-22T02:15:18.587814824Z otel.kind="server"}: tarpc::server: ReceiveRequest
[22-Oct-2024 02:15:08 UTC] [ddtrace] [trace] [sidecar] tarpc::server: poll_flush
[22-Oct-2024 02:15:08 UTC] [ddtrace] [trace] [sidecar] tarpc::server: OpenTelemetry subscriber not installed; making unsampled child context.
[22-Oct-2024 02:15:08 UTC] [ddtrace] [debug] [sidecar] RPC{rpc.trace_id=00 rpc.deadline=2

styoo4001 avatar Oct 22 '24 03:10 styoo4001

The new version is not fixing memory growth issues though. There's nothing suspicious inside these logs sadly.

Would you be willing to run the native profiler? I'm pretty certain that one will help us more. And tell us which service & what time.

bwoebi avatar Oct 22 '24 14:10 bwoebi

Seeing the same. Since we updated from 1.3.x to 1.4.x. Also latest 1.5.x does not solve it.

Our pods started to get OOM killed after a while, very clearly visible after the upgrade.

TheLevti avatar Dec 09 '24 08:12 TheLevti

@styoo4001 are you maybe calling $tracer->reset();? We figured out that removing this call after each manual trace inside daemons (infinite command execution), memory usage, cpu usage and network usage are flat as flat can be.

I am not sure right now why we added it, but I remember there has been another memory leak in the past where calling reset would fix it.

TheLevti avatar Dec 13 '24 09:12 TheLevti

I'm currently a bit lost with this as we haven't been seeing unbounded memory growth in our test applications / environments.

@TheLevti I'm not sure whether I read your message right - if you remove the $tracer->reset() call, it works? Or is this just one cause of memory leaks and you still have another memory leak?

bwoebi avatar Jan 02 '25 12:01 bwoebi

I'm currently a bit lost with this as we haven't been seeing unbounded memory growth in our test applications / environments.

@TheLevti I'm not sure whether I read your message right - if you remove the $tracer->reset() call, it works? Or is this just one cause of memory leaks and you still have another memory leak?

We have many long running processes/jobs so we had to disable auto flush and auto root span creation. In the past this caused a slow OOM death as we initially could not figure out from where the leak is coming. After running some tracing, we discovered that the dd-trace library is leaking memory for those long running jobs. For us the leak was fixed by calling $tracer->reset(); after we close the root span.

Now with the new versions in 1.4.1+ we started to get a new memory leak in all our long running processes once we upgraded from 1.3.x. After some debugging we discovered that removing $tracer->reset(); fixed the leak and also removed a lot of unnecessary cpu and network load. Apparently the original leak has been fixed in some version so this reset call is not necessary.

Besides that there is missing documentation about the reset() method and what effects it has.

TheLevti avatar Jan 02 '25 13:01 TheLevti

$tracer->reset() essentially disables tracing and re-enables it again. This entails removing a lot of stuff from the runtime and re-adding it again afterwards.

We might have messed up something with the disabling&enabling. I'll try whether I can reproduce or spot something weird in 1.4.

Thank you for following up.

bwoebi avatar Jan 02 '25 18:01 bwoebi

$tracer->reset() essentially disables tracing and re-enables it again. This entails removing a lot of stuff from the runtime and re-adding it again afterwards.

We might have messed up something with the disabling&enabling. I'll try whether I can reproduce or spot something weird in 1.4.

Thank you for following up.

Thank you! Just as a note, this might be not related to the author's issue though as I am not sure if he also used ->reset(). Removing ->reset() resolved the leak for us and right now we have no issue.

TheLevti avatar Jan 03 '25 10:01 TheLevti

Hello all,

I'm bumping this issue as we observed a similar memory leak problem on a long running Symfony Command that was optimized to have a very stable memory footprint.

Started seeing massive leaks that we ended up tracing down to the dd-trace-php.

After a lot of investigation, and thanks to this issue, we were able to confirm the issue is present on every version from tag 1.4.1 to 1.8.3.

Last known working version is indeed the 1.3.1.

From what i gathered during my tests, the php garbage collector simply does not collect / release anything for us during a long script, even though references are appropriately unset & cleared whenever possible during the iterations, from version 1.4.1 and up, which causes massive memory leaks and ends up having the script killed in production.

Although we are also running in GKE in production, the bug is reproducible locally.

This can be seen easily by dumping the gc_status() at each iteration, and seeing that nothing is collected nor released.

If we remove dd-trace-php, the garbage collector works normally and memory footprint is stable again. If we lower dd-trace-php version to 1.3.1, the garbage collector starts working again,

Debian 12.5 PHP 8.1.28 Symfony 6.4 with doctrine & mongo odm

MartinSBelieve avatar Apr 30 '25 16:04 MartinSBelieve

@MartinSBelieve do you only run the tracer or also the profiler?

realFlowControl avatar May 02 '25 12:05 realFlowControl

@realFlowControl only the tracer, not the profiler, as far as i'm aware, it's installed with php datadog-setup.php --php-bin=all , so no --enable-profiling

Since downgrading to 1.3.1 was not really an option, I started back over on 1.8.3 and started deactivating various instrumentations to see which one was blocking garbage collection.

After disabling the mongo & mongodb ones, i got the garbage collection to work again, so maybe a ref is kept somewhere preventing the clearing of memory by php.

DD_TRACE_MONGO_ENABLED=false
DD_TRACE_MONGODB_ENABLED=false

edit: tested again to pinpoint the issue, it is actually only DD_TRACE_MONGODB_ENABLED that blocks gc from happening

There still was a small memory leak, but i did what was listed on the doc about long running php scripts and disabled the main rootspan and added autoflush, and it seems to be ok memory wise.

So i'm back with a stable memory footprint, although i did have to disable stuff to get there.

Sorry again for hijacking the thread, i realize there is not much link with the original issue ...

MartinSBelieve avatar May 02 '25 15:05 MartinSBelieve