Skip to content
New issue

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

Sign up for GitHub

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

Already on GitHub? Sign in to your account

Jump to bottom

[Bug]: Upgrading to 1.4.1 out of memory issue #2902

Open
styoo4001 opened this issue Oct 18, 2024 · 11 comments
Open

[Bug]: Upgrading to 1.4.1 out of memory issue #2902

styoo4001 opened this issue Oct 18, 2024 · 11 comments
Labels
🐛 bug Something isn't working

Comments

@styoo4001
Copy link

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 styoo4001 added the 🐛 bug Something isn't working label Oct 18, 2024
@bwoebi
Copy link
Collaborator

bwoebi commented Oct 18, 2024

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
Copy link
Collaborator

bwoebi commented Oct 18, 2024

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

@styoo4001
Copy link
Author

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

@bwoebi bwoebi mentioned this issue Oct 21, 2024
Closed
@styoo4001
Copy link
Author

@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

@bwoebi
Copy link
Collaborator

bwoebi commented Oct 22, 2024

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.

@TheLevti
Copy link
Contributor

TheLevti commented Dec 9, 2024 •
edited
Loading

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
Copy link
Contributor

@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.

@bwoebi
Copy link
Collaborator

bwoebi commented Jan 2, 2025

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?

@TheLevti
Copy link
Contributor

TheLevti commented Jan 2, 2025

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.

@bwoebi
Copy link
Collaborator

bwoebi commented Jan 2, 2025

$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.

@TheLevti
Copy link
Contributor

TheLevti commented Jan 3, 2025

$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.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
🐛 bug Something isn't working
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@bwoebi @TheLevti @styoo4001