search

awslabs / aws-sdk-rust

AWS SDK for the Rust Programming Language
https://awslabs.github.io/aws-sdk-rust/
Apache License 2.0
3.02k stars 248 forks source link

PutMetricData fails with status code 408 #1189

Closed acjay closed 1 month ago

acjay commented 1 month ago

Describe the bug

We're using CloudWatch metrics and we are experiencing errors with PutMetricData (via the Rust aws_sdk_cloudwatch crate) when sending metric payloads that seem to be well below the documented maximums.

Expected Behavior

The metrics to be accepted successfully.

Current Behavior

The debug error looks like the following, after what appears to be a 10 second time out:

Err(ServiceError(ServiceError { source: Unhandled(Unhandled { source: XmlDecodeError { kind: Custom("no root element") }, meta: ErrorMetadata { code: None, message: None, extras: None } }), raw: Response { status: StatusCode(408), headers: Headers { headers: {"content-length": HeaderValue { _private: H0("0") }, "date": HeaderValue { _private: H0("Mon, 09 Sep 2024 20:55:45 GMT") }, "connection": HeaderValue { _private: H0("close") }} }, body: SdkBody { inner: Once(Some(b"")), retryable: true }, extensions: Extensions { extensions_02x: Extensions, extensions_1x: Extensions } } }))

Reproduction Steps

This program shows PutMetricData failing when using a MetricDatum with 125 value/count entries and then succeeding with the same data set truncated to 100 entries.

use aws_sdk_cloudwatch::config::BehaviorVersion;
use aws_sdk_cloudwatch::types::Dimension;
use aws_sdk_cloudwatch::types::MetricDatum;
use aws_sdk_cloudwatch::types::StandardUnit;
use itertools::Itertools;
use tokio::time::Instant;

#[tokio::main]
async fn main() {
    let aws_config = aws_config::defaults(BehaviorVersion::latest()).load().await;
    let cw_client = aws_sdk_cloudwatch::Client::new(&aws_config);

    let values: Vec<f64> = vec![
        98541.0, 67026.0, 96172.0, 81257.0, 78637.0, 79622.0, 83649.0, 64732.0, 79871.0, 80260.0,
        80244.0, 99961.0, 102978.0, 78736.0, 79897.0, 79404.0, 100405.0, 80017.0, 79846.0, 83623.0,
        236806.0, 95570.0, 80385.0, 96966.0, 81295.0, 80134.0, 80069.0, 99614.0, 83302.0, 97889.0,
        79993.0, 80895.0, 80265.0, 79640.0, 78472.0, 80432.0, 97514.0, 80307.0, 84168.0, 80746.0,
        100452.0, 97142.0, 100383.0, 84088.0, 81623.0, 79927.0, 158122.0, 80490.0, 96406.0,
        96826.0, 96377.0, 80365.0, 81757.0, 97900.0, 78214.0, 80996.0, 78191.0, 63341.0, 80673.0,
        79601.0, 80193.0, 72833.0, 83016.0, 97199.0, 80191.0, 64229.0, 96476.0, 98516.0, 100234.0,
        96348.0, 83757.0, 83779.0, 66457.0, 101027.0, 98412.0, 205606.0, 81428.0, 99704.0, 96764.0,
        80619.0, 79670.0, 80629.0, 80585.0, 82882.0, 79790.0, 96866.0, 98877.0, 99769.0, 80609.0,
        96559.0, 79826.0, 73419.0, 80898.0, 79546.0, 96888.0, 78647.0, 78940.0, 96223.0, 80476.0,
        95708.0, 79921.0, 95619.0, 79476.0, 64980.0, 79883.0, 79628.0, 98414.0, 66497.0, 80538.0,
        98805.0, 81404.0, 65983.0, 78924.0, 83488.0, 96061.0, 77200.0, 98165.0, 81412.0, 62855.0,
        80378.0, 83776.0, 80089.0, 95655.0, 80388.0, 79382.0,
    ];
    let counts: Vec<f64> = vec![
        1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 2.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0,
        1.0, 1.0, 1.0, 1.0, 2.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0,
        1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 2.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0,
        1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0,
        1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0,
        1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0,
        1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0,
    ];
    test(
        "Test 1, Original data",
        vec![(values, counts, "TestMessage")],
        &cw_client,
    )
    .await;

    let values: Vec<f64> = vec![
        98541.0, 67026.0, 96172.0, 81257.0, 78637.0, 79622.0, 83649.0, 64732.0, 79871.0, 80260.0,
        80244.0, 99961.0, 102978.0, 78736.0, 79897.0, 79404.0, 100405.0, 80017.0, 79846.0, 83623.0,
        236806.0, 95570.0, 80385.0, 96966.0, 81295.0, 80134.0, 80069.0, 99614.0, 83302.0, 97889.0,
        79993.0, 80895.0, 80265.0, 79640.0, 78472.0, 80432.0, 97514.0, 80307.0, 84168.0, 80746.0,
        100452.0, 97142.0, 100383.0, 84088.0, 81623.0, 79927.0, 158122.0, 80490.0, 96406.0,
        96826.0, 96377.0, 80365.0, 81757.0, 97900.0, 78214.0, 80996.0, 78191.0, 63341.0, 80673.0,
        79601.0, 80193.0, 72833.0, 83016.0, 97199.0, 80191.0, 64229.0, 96476.0, 98516.0, 100234.0,
        96348.0, 83757.0, 83779.0, 66457.0, 101027.0, 98412.0, 205606.0, 81428.0, 99704.0, 96764.0,
        80619.0, 79670.0, 80629.0, 80585.0, 82882.0, 79790.0, 96866.0, 98877.0, 99769.0, 80609.0,
        96559.0, 79826.0, 73419.0, 80898.0, 79546.0, 96888.0, 78647.0, 78940.0, 96223.0, 80476.0,
        95708.0,
    ];
    let counts: Vec<f64> = vec![
        1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 2.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0,
        1.0, 1.0, 1.0, 1.0, 2.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0,
        1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 2.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0,
        1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0,
        1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0,
        1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0, 1.0,
    ];
    test(
        "Test 2, truncated to 100 pairs",
        vec![(values.clone(), counts.clone(), "TestMessage")],
        &cw_client,
    )
    .await;

    test(
        "Test 3, two sets, truncated to 100 pairs",
        vec![
            (values.clone(), counts.clone(), "TestMessage"),
            (values, counts, "OtherMessage"),
        ],
        &cw_client,
    )
    .await;
}

async fn test(
    label: &str,
    metrics: Vec<(Vec<f64>, Vec<f64>, &str)>,
    cw_client: &aws_sdk_cloudwatch::Client,
) {
    println!("{label}:");
    let start = Instant::now();
    let total_pairs: usize = metrics
        .iter()
        .map(|(values, _, _)| values.len())
        .sum::<usize>();
    let total_count: f64 = metrics
        .iter()
        .map(|(_, counts, _)| counts.iter().sum::<f64>())
        .sum::<f64>();
    let metric_datums = metrics
        .into_iter()
        .map(|(values, counts, name)| {
            MetricDatum::builder()
                .metric_name("ProcessingTime")
                .dimensions(Dimension::builder().name("MessageName").value(name).build())
                .dimensions(
                    Dimension::builder()
                        .name("ProcessingContext")
                        .value("test")
                        .build(),
                )
                .set_values(Some(values))
                .set_counts(Some(counts))
                .unit(StandardUnit::Milliseconds)
                .build()
        })
        .collect_vec();
    let metric_datum_count = metric_datums.len();

    let res = cw_client
        .put_metric_data()
        .namespace("Playground")
        .set_metric_data(Some(metric_datums))
        .send()
        .await;

    println!("Metric datums: {metric_datum_count}");
    println!("Total value/count pairs: {total_pairs}");
    println!("Total datapoint count: {total_count}");
    println!("Elapsed time: {}ms", start.elapsed().as_millis());
    println!("Result: {res:#?}");
    println!("------");
}

Possible Solution

No response

Additional Information/Context

No response

Version

├── aws-config v1.5.5
│   ├── aws-credential-types v1.2.1
│   │   ├── aws-smithy-async v1.2.1
│   │   ├── aws-smithy-runtime-api v1.7.2
│   │   │   ├── aws-smithy-async v1.2.1 (*)
│   │   │   ├── aws-smithy-types v1.2.6
│   │   ├── aws-smithy-types v1.2.6 (*)
│   ├── aws-runtime v1.4.2
│   │   ├── aws-credential-types v1.2.1 (*)
│   │   ├── aws-sigv4 v1.2.3
│   │   │   ├── aws-credential-types v1.2.1 (*)
│   │   │   ├── aws-smithy-http v0.60.11
│   │   │   │   ├── aws-smithy-runtime-api v1.7.2 (*)
│   │   │   │   ├── aws-smithy-types v1.2.6 (*)
│   │   │   ├── aws-smithy-runtime-api v1.7.2 (*)
│   │   │   ├── aws-smithy-types v1.2.6 (*)
│   │   ├── aws-smithy-async v1.2.1 (*)
│   │   ├── aws-smithy-http v0.60.11 (*)
│   │   ├── aws-smithy-runtime v1.7.1
│   │   │   ├── aws-smithy-async v1.2.1 (*)
│   │   │   ├── aws-smithy-http v0.60.11 (*)
│   │   │   ├── aws-smithy-runtime-api v1.7.2 (*)
│   │   │   ├── aws-smithy-types v1.2.6 (*)
│   │   ├── aws-smithy-runtime-api v1.7.2 (*)
│   │   ├── aws-smithy-types v1.2.6 (*)
│   │   ├── aws-types v1.3.3
│   │   │   ├── aws-credential-types v1.2.1 (*)
│   │   │   ├── aws-smithy-async v1.2.1 (*)
│   │   │   ├── aws-smithy-runtime-api v1.7.2 (*)
│   │   │   ├── aws-smithy-types v1.2.6 (*)
│   ├── aws-sdk-sso v1.39.0
│   │   ├── aws-credential-types v1.2.1 (*)
│   │   ├── aws-runtime v1.4.2 (*)
│   │   ├── aws-smithy-async v1.2.1 (*)
│   │   ├── aws-smithy-http v0.60.11 (*)
│   │   ├── aws-smithy-json v0.60.7
│   │   │   └── aws-smithy-types v1.2.6 (*)
│   │   ├── aws-smithy-runtime v1.7.1 (*)
│   │   ├── aws-smithy-runtime-api v1.7.2 (*)
│   │   ├── aws-smithy-types v1.2.6 (*)
│   │   ├── aws-types v1.3.3 (*)
│   ├── aws-sdk-ssooidc v1.40.0
│   │   ├── aws-credential-types v1.2.1 (*)
│   │   ├── aws-runtime v1.4.2 (*)
│   │   ├── aws-smithy-async v1.2.1 (*)
│   │   ├── aws-smithy-http v0.60.11 (*)
│   │   ├── aws-smithy-json v0.60.7 (*)
│   │   ├── aws-smithy-runtime v1.7.1 (*)
│   │   ├── aws-smithy-runtime-api v1.7.2 (*)
│   │   ├── aws-smithy-types v1.2.6 (*)
│   │   ├── aws-types v1.3.3 (*)
│   ├── aws-sdk-sts v1.39.0
│   │   ├── aws-credential-types v1.2.1 (*)
│   │   ├── aws-runtime v1.4.2 (*)
│   │   ├── aws-smithy-async v1.2.1 (*)
│   │   ├── aws-smithy-http v0.60.11 (*)
│   │   ├── aws-smithy-json v0.60.7 (*)
│   │   ├── aws-smithy-query v0.60.7
│   │   │   ├── aws-smithy-types v1.2.6 (*)
│   │   ├── aws-smithy-runtime v1.7.1 (*)
│   │   ├── aws-smithy-runtime-api v1.7.2 (*)
│   │   ├── aws-smithy-types v1.2.6 (*)
│   │   ├── aws-smithy-xml v0.60.8
│   │   ├── aws-types v1.3.3 (*)
│   ├── aws-smithy-async v1.2.1 (*)
│   ├── aws-smithy-http v0.60.11 (*)
│   ├── aws-smithy-json v0.60.7 (*)
│   ├── aws-smithy-runtime v1.7.1 (*)
│   ├── aws-smithy-runtime-api v1.7.2 (*)
│   ├── aws-smithy-types v1.2.6 (*)
│   ├── aws-types v1.3.3 (*)
├── aws-sdk-cloudwatch v1.46.0
│   ├── aws-credential-types v1.2.1 (*)
│   ├── aws-runtime v1.4.2 (*)
│   ├── aws-smithy-async v1.2.1 (*)
│   ├── aws-smithy-compression v0.0.1
│   │   ├── aws-smithy-runtime-api v1.7.2 (*)
│   │   ├── aws-smithy-types v1.2.6 (*)
│   ├── aws-smithy-http v0.60.11 (*)
│   ├── aws-smithy-json v0.60.7 (*)
│   ├── aws-smithy-query v0.60.7 (*)
│   ├── aws-smithy-runtime v1.7.1 (*)
│   ├── aws-smithy-runtime-api v1.7.2 (*)
│   ├── aws-smithy-types v1.2.6 (*)
│   ├── aws-smithy-xml v0.60.8 (*)
│   ├── aws-types v1.3.3 (*)
├── aws-sdk-secretsmanager v1.43.0
│   ├── aws-credential-types v1.2.1 (*)
│   ├── aws-runtime v1.4.2 (*)
│   ├── aws-smithy-async v1.2.1 (*)
│   ├── aws-smithy-http v0.60.11 (*)
│   ├── aws-smithy-json v0.60.7 (*)
│   ├── aws-smithy-runtime v1.7.1 (*)
│   ├── aws-smithy-runtime-api v1.7.2 (*)
│   ├── aws-smithy-types v1.2.6 (*)
│   ├── aws-types v1.3.3 (*)
├── aws-sdk-sns v1.40.0
│   ├── aws-credential-types v1.2.1 (*)
│   ├── aws-runtime v1.4.2 (*)
│   ├── aws-smithy-async v1.2.1 (*)
│   ├── aws-smithy-http v0.60.11 (*)
│   ├── aws-smithy-json v0.60.7 (*)
│   ├── aws-smithy-query v0.60.7 (*)
│   ├── aws-smithy-runtime v1.7.1 (*)
│   ├── aws-smithy-runtime-api v1.7.2 (*)
│   ├── aws-smithy-types v1.2.6 (*)
│   ├── aws-smithy-xml v0.60.8 (*)
│   ├── aws-types v1.3.3 (*)
├── aws-sdk-ssm v1.44.0
│   ├── aws-credential-types v1.2.1 (*)
│   ├── aws-runtime v1.4.2 (*)
│   ├── aws-smithy-async v1.2.1 (*)
│   ├── aws-smithy-http v0.60.11 (*)
│   ├── aws-smithy-json v0.60.7 (*)
│   ├── aws-smithy-runtime v1.7.1 (*)
│   ├── aws-smithy-runtime-api v1.7.2 (*)
│   ├── aws-smithy-types v1.2.6 (*)
│   ├── aws-types v1.3.3 (*)
│   ├── aws-config v1.5.5 (*)
│   ├── aws-sdk-sns v1.40.0 (*)
│   ├── aws-sdk-sqs v1.39.0
│   │   ├── aws-credential-types v1.2.1 (*)
│   │   ├── aws-runtime v1.4.2 (*)
│   │   ├── aws-smithy-async v1.2.1 (*)
│   │   ├── aws-smithy-http v0.60.11 (*)
│   │   ├── aws-smithy-json v0.60.7 (*)
│   │   ├── aws-smithy-runtime v1.7.1 (*)
│   │   ├── aws-smithy-runtime-api v1.7.2 (*)
│   │   ├── aws-smithy-types v1.2.6 (*)
│   │   ├── aws-types v1.3.3 (*)

### Environment details (OS name and version, etc.)

macOS 14.4.1

### Logs

2024-09-10T15:21:10.542828Z DEBUG aws_runtime::fs_util: loaded home directory src="HOME"
2024-09-10T15:21:10.543403Z DEBUG load_config_file{file=Default(Config)}: aws_runtime::env_config::source: performing home directory substitution home="/Users/alanjohnson" path="~/.aws/config"
2024-09-10T15:21:10.543538Z DEBUG load_config_file{file=Default(Config)}: aws_runtime::env_config::source: home directory expanded before="~/.aws/config" after="/Users/alanjohnson/.aws/config"
2024-09-10T15:21:10.544144Z DEBUG load_config_file{file=Default(Config)}: aws_runtime::env_config::source: config file loaded path=Some("/Users/alanjohnson/.aws/config") size=43
2024-09-10T15:21:10.544295Z DEBUG load_config_file{file=Default(Credentials)}: aws_runtime::env_config::source: performing home directory substitution home="/Users/alanjohnson" path="~/.aws/credentials"
2024-09-10T15:21:10.544308Z DEBUG load_config_file{file=Default(Credentials)}: aws_runtime::env_config::source: home directory expanded before="~/.aws/credentials" after="/Users/alanjohnson/.aws/credentials"
2024-09-10T15:21:10.544556Z DEBUG load_config_file{file=Default(Credentials)}: aws_runtime::env_config::source: config file loaded path=Some("/Users/alanjohnson/.aws/credentials") size=116
2024-09-10T15:21:10.547326Z DEBUG aws_sdk_sts::endpoint_lib: loading default partitions
2024-09-10T15:21:10.673923Z DEBUG hyper_rustls::config: with_native_roots processed 149 valid and 0 invalid certs    
2024-09-10T15:21:10.674641Z DEBUG aws_sdk_cloudwatch::endpoint_lib: loading default partitions
Test 1, Original data:
2024-09-10T15:21:10.675167Z DEBUG invoke{service=cloudwatch operation=PutMetricData sdk_invocation_id=9065388}:apply_configuration: aws_smithy_runtime::client::orchestrator: timeout settings for this operation: TimeoutConfig { connect_timeout: Set(3.1s), read_timeout: Disabled, operation_timeout: Disabled, operation_attempt_timeout: Disabled }
2024-09-10T15:21:10.675300Z DEBUG invoke{service=cloudwatch operation=PutMetricData sdk_invocation_id=9065388}:try_op: aws_smithy_runtime_api::client::interceptors::context: entering 'serialization' phase
2024-09-10T15:21:10.675614Z DEBUG invoke{service=cloudwatch operation=PutMetricData sdk_invocation_id=9065388}:try_op: aws_smithy_runtime_api::client::interceptors::context: entering 'before transmit' phase
2024-09-10T15:21:10.675751Z DEBUG invoke{service=cloudwatch operation=PutMetricData sdk_invocation_id=9065388}:try_op: aws_smithy_runtime::client::retries::strategy::standard: no client rate limiter configured, so no token is required for the initial request.
2024-09-10T15:21:10.675775Z DEBUG invoke{service=cloudwatch operation=PutMetricData sdk_invocation_id=9065388}:try_op: aws_smithy_runtime::client::orchestrator: retry strategy has OKed initial request
2024-09-10T15:21:10.675816Z DEBUG invoke{service=cloudwatch operation=PutMetricData sdk_invocation_id=9065388}:try_op: aws_smithy_runtime::client::orchestrator: beginning attempt #1
2024-09-10T15:21:10.675894Z DEBUG invoke{service=cloudwatch operation=PutMetricData sdk_invocation_id=9065388}:try_op:try_attempt: aws_smithy_runtime::client::orchestrator::endpoints: resolving endpoint endpoint_params=EndpointResolverParams(TypeErasedBox[!Clone]:Params { region: Some("us-east-1"), use_dual_stack: false, use_fips: false, endpoint: None }) endpoint_prefix=None
2024-09-10T15:21:10.675924Z DEBUG invoke{service=cloudwatch operation=PutMetricData sdk_invocation_id=9065388}:try_op:try_attempt: aws_smithy_runtime::client::orchestrator::endpoints: will use endpoint Endpoint { url: "https://monitoring.us-east-1.amazonaws.com", headers: {}, properties: {} }
2024-09-10T15:21:10.676142Z DEBUG invoke{service=cloudwatch operation=PutMetricData sdk_invocation_id=9065388}:try_op:try_attempt:lazy_load_identity:provide_credentials{provider=default_chain}: aws_config::meta::credentials::chain: provider in chain did not provide credentials provider=Environment context=the credential provider was not enabled: environment variable not set (CredentialsNotLoaded(CredentialsNotLoaded { source: Some("environment variable not set") }))
2024-09-10T15:21:10.676216Z  INFO invoke{service=cloudwatch operation=PutMetricData sdk_invocation_id=9065388}:try_op:try_attempt:lazy_load_identity:provide_credentials{provider=default_chain}:load_credentials{provider=Profile}: aws_config::profile::credentials: constructed abstract provider from config file chain=ProfileChain { base: AccessKey(Credentials { provider_name: "ProfileFile", access_key_id: "AKIA4MTWH4NFKYP2U4W4", secret_access_key: "** redacted **", expires_after: "never" }), chain: [] }
2024-09-10T15:21:10.676239Z DEBUG invoke{service=cloudwatch operation=PutMetricData sdk_invocation_id=9065388}:try_op:try_attempt:lazy_load_identity:provide_credentials{provider=default_chain}:load_credentials{provider=Profile}: aws_config::profile::credentials::exec: first credentials will be loaded from AccessKey(Credentials { provider_name: "ProfileFile", access_key_id: "AKIA4MTWH4NFKYP2U4W4", secret_access_key: "** redacted **", expires_after: "never" }) base=AccessKey(Credentials { provider_name: "ProfileFile", access_key_id: "AKIA4MTWH4NFKYP2U4W4", secret_access_key: "** redacted **", expires_after: "never" })
2024-09-10T15:21:10.676271Z  INFO invoke{service=cloudwatch operation=PutMetricData sdk_invocation_id=9065388}:try_op:try_attempt:lazy_load_identity:provide_credentials{provider=default_chain}:load_credentials{provider=Profile}: aws_config::profile::credentials: loaded base credentials creds=Credentials { provider_name: "ProfileFile", access_key_id: "AKIA4MTWH4NFKYP2U4W4", secret_access_key: "** redacted **", expires_after: "never" }
2024-09-10T15:21:10.676293Z DEBUG invoke{service=cloudwatch operation=PutMetricData sdk_invocation_id=9065388}:try_op:try_attempt:lazy_load_identity:provide_credentials{provider=default_chain}: aws_config::meta::credentials::chain: loaded credentials provider=Profile
2024-09-10T15:21:10.676316Z DEBUG invoke{service=cloudwatch operation=PutMetricData sdk_invocation_id=9065388}:try_op:try_attempt:lazy_load_identity: aws_smithy_runtime::client::identity::cache::lazy: identity cache miss occurred; added new identity (took 201µs) new_expiration=2024-09-10T15:36:10.676086Z valid_for=899.99977s partition=IdentityCachePartition(7)
2024-09-10T15:21:10.676346Z DEBUG invoke{service=cloudwatch operation=PutMetricData sdk_invocation_id=9065388}:try_op:try_attempt: aws_smithy_runtime::client::identity::cache::lazy: loaded identity
2024-09-10T15:21:10.676638Z DEBUG invoke{service=cloudwatch operation=PutMetricData sdk_invocation_id=9065388}:try_op:try_attempt: aws_smithy_runtime_api::client::interceptors::context: entering 'transmit' phase
2024-09-10T15:21:10.676663Z DEBUG invoke{service=cloudwatch operation=PutMetricData sdk_invocation_id=9065388}:try_op:try_attempt: aws_smithy_runtime::client::http::hyper_014: new TCP connector created in 1µs
2024-09-10T15:21:10.676821Z DEBUG invoke{service=cloudwatch operation=PutMetricData sdk_invocation_id=9065388}:try_op:try_attempt: aws_smithy_runtime::client::http::body::minimum_throughput: applying minimum upload throughput check future options=MinimumThroughputBodyOptions { minimum_throughput: Throughput { bytes_read: 1, per_time_elapsed: 1s }, grace_period: 5s, check_window: 1s }
2024-09-10T15:21:10.677060Z DEBUG hyper::client::connect::dns: resolving host="monitoring.us-east-1.amazonaws.com"
2024-09-10T15:21:10.689072Z DEBUG invoke{service=cloudwatch operation=PutMetricData sdk_invocation_id=9065388}:try_op:try_attempt: hyper::client::connect::http: connecting to 44.213.98.188:443
2024-09-10T15:21:10.702958Z DEBUG invoke{service=cloudwatch operation=PutMetricData sdk_invocation_id=9065388}:try_op:try_attempt: hyper::client::connect::http: connected to 44.213.98.188:443
2024-09-10T15:21:10.703015Z DEBUG invoke{service=cloudwatch operation=PutMetricData sdk_invocation_id=9065388}:try_op:try_attempt: rustls::client::hs: No cached session for DnsName("monitoring.us-east-1.amazonaws.com")    
2024-09-10T15:21:10.703263Z DEBUG invoke{service=cloudwatch operation=PutMetricData sdk_invocation_id=9065388}:try_op:try_attempt: rustls::client::hs: Not resuming any session    
2024-09-10T15:21:10.728856Z DEBUG invoke{service=cloudwatch operation=PutMetricData sdk_invocation_id=9065388}:try_op:try_attempt: rustls::client::hs: Using ciphersuite TLS13_AES_128_GCM_SHA256    
2024-09-10T15:21:10.728886Z DEBUG invoke{service=cloudwatch operation=PutMetricData sdk_invocation_id=9065388}:try_op:try_attempt: rustls::client::tls13: Not resuming    
2024-09-10T15:21:10.729050Z DEBUG invoke{service=cloudwatch operation=PutMetricData sdk_invocation_id=9065388}:try_op:try_attempt: rustls::client::tls13: TLS1.3 encrypted extensions: [ServerNameAck, Protocols([ProtocolName(687474702f312e31)])]    
2024-09-10T15:21:10.729073Z DEBUG invoke{service=cloudwatch operation=PutMetricData sdk_invocation_id=9065388}:try_op:try_attempt: rustls::client::hs: ALPN protocol is Some(b"http/1.1")    
2024-09-10T15:21:10.732142Z DEBUG hyper::proto::h1::io: flushed 1988 bytes
2024-09-10T15:21:20.743555Z DEBUG hyper::proto::h1::io: parsed 3 headers
2024-09-10T15:21:20.743623Z DEBUG hyper::proto::h1::conn: incoming body is empty
2024-09-10T15:21:20.743704Z DEBUG rustls::common_state: Sending warning alert CloseNotify    
2024-09-10T15:21:20.743882Z DEBUG invoke{service=cloudwatch operation=PutMetricData sdk_invocation_id=9065388}:try_op:try_attempt: aws_smithy_runtime_api::client::interceptors::context: entering 'before deserialization' phase
2024-09-10T15:21:20.744195Z DEBUG invoke{service=cloudwatch operation=PutMetricData sdk_invocation_id=9065388}:try_op:try_attempt: aws_smithy_runtime_api::client::interceptors::context: entering 'deserialization' phase
2024-09-10T15:21:20.744428Z DEBUG invoke{service=cloudwatch operation=PutMetricData sdk_invocation_id=9065388}:try_op:try_attempt:deserialization:deserialize_nonstreaming: aws_sdk_cloudwatch::operation::put_metric_data: request_id=None
2024-09-10T15:21:20.744561Z DEBUG invoke{service=cloudwatch operation=PutMetricData sdk_invocation_id=9065388}:try_op:try_attempt: aws_smithy_runtime_api::client::interceptors::context: entering 'after deserialization' phase
2024-09-10T15:21:20.744699Z DEBUG invoke{service=cloudwatch operation=PutMetricData sdk_invocation_id=9065388}:try_op: aws_smithy_runtime::client::retries::strategy::standard: attempt #1 succeeded, no retry necessary
2024-09-10T15:21:20.744726Z DEBUG invoke{service=cloudwatch operation=PutMetricData sdk_invocation_id=9065388}:try_op: aws_smithy_runtime::client::orchestrator: a retry is either unnecessary or not possible, exiting attempt loop
Metric datums: 1
Total value/count pairs: 125
Total datapoint count: 128
Elapsed time: 10069ms
Result: Err(
    ServiceError(
        ServiceError {
            source: Unhandled(
                Unhandled {
                    source: XmlDecodeError {
                        kind: Custom(
                            "no root element",
                        ),
                    },
                    meta: ErrorMetadata {
                        code: None,
                        message: None,
                        extras: None,
                    },
                },
            ),
            raw: Response {
                status: StatusCode(
                    408,
                ),
                headers: Headers {
                    headers: {
                        "content-length": HeaderValue {
                            _private: H0(
                                "0",
                            ),
                        },
                        "date": HeaderValue {
                            _private: H0(
                                "Tue, 10 Sep 2024 15:21:15 GMT",
                            ),
                        },
                        "connection": HeaderValue {
                            _private: H0(
                                "close",
                            ),
                        },
                    },
                },
                body: SdkBody {
                    inner: Once(
                        Some(
                            b"",
                        ),
                    ),
                    retryable: true,
                },
                extensions: Extensions {
                    extensions_02x: Extensions,
                    extensions_1x: Extensions,
                },
            },
        },
    ),
)
------
Test 2, truncated to 100 pairs:
2024-09-10T15:21:20.745278Z DEBUG invoke{service=cloudwatch operation=PutMetricData sdk_invocation_id=4888433}:apply_configuration: aws_smithy_runtime::client::orchestrator: timeout settings for this operation: TimeoutConfig { connect_timeout: Set(3.1s), read_timeout: Disabled, operation_timeout: Disabled, operation_attempt_timeout: Disabled }
2024-09-10T15:21:20.745377Z DEBUG invoke{service=cloudwatch operation=PutMetricData sdk_invocation_id=4888433}:try_op: aws_smithy_runtime_api::client::interceptors::context: entering 'serialization' phase
2024-09-10T15:21:20.745784Z DEBUG invoke{service=cloudwatch operation=PutMetricData sdk_invocation_id=4888433}:try_op: aws_smithy_runtime_api::client::interceptors::context: entering 'before transmit' phase
2024-09-10T15:21:20.745894Z DEBUG invoke{service=cloudwatch operation=PutMetricData sdk_invocation_id=4888433}:try_op: aws_smithy_runtime::client::retries::strategy::standard: no client rate limiter configured, so no token is required for the initial request.
2024-09-10T15:21:20.745918Z DEBUG invoke{service=cloudwatch operation=PutMetricData sdk_invocation_id=4888433}:try_op: aws_smithy_runtime::client::orchestrator: retry strategy has OKed initial request
2024-09-10T15:21:20.745947Z DEBUG invoke{service=cloudwatch operation=PutMetricData sdk_invocation_id=4888433}:try_op: aws_smithy_runtime::client::orchestrator: beginning attempt #1
2024-09-10T15:21:20.745994Z DEBUG invoke{service=cloudwatch operation=PutMetricData sdk_invocation_id=4888433}:try_op:try_attempt: aws_smithy_runtime::client::orchestrator::endpoints: resolving endpoint endpoint_params=EndpointResolverParams(TypeErasedBox[!Clone]:Params { region: Some("us-east-1"), use_dual_stack: false, use_fips: false, endpoint: None }) endpoint_prefix=None
2024-09-10T15:21:20.746045Z DEBUG invoke{service=cloudwatch operation=PutMetricData sdk_invocation_id=4888433}:try_op:try_attempt: aws_smithy_runtime::client::orchestrator::endpoints: will use endpoint Endpoint { url: "https://monitoring.us-east-1.amazonaws.com", headers: {}, properties: {} }
2024-09-10T15:21:20.746222Z DEBUG invoke{service=cloudwatch operation=PutMetricData sdk_invocation_id=4888433}:try_op:try_attempt: aws_smithy_runtime::client::identity::cache::lazy: loaded identity from cache buffer_time=10s cached_expiration=None now=SystemTime { tv_sec: 1725981680, tv_nsec: 746195000 }
2024-09-10T15:21:20.747332Z DEBUG invoke{service=cloudwatch operation=PutMetricData sdk_invocation_id=4888433}:try_op:try_attempt: aws_smithy_runtime_api::client::interceptors::context: entering 'transmit' phase
2024-09-10T15:21:20.747398Z DEBUG invoke{service=cloudwatch operation=PutMetricData sdk_invocation_id=4888433}:try_op:try_attempt: aws_smithy_runtime::client::http::body::minimum_throughput: applying minimum upload throughput check future options=MinimumThroughputBodyOptions { minimum_throughput: Throughput { bytes_read: 1, per_time_elapsed: 1s }, grace_period: 5s, check_window: 1s }
2024-09-10T15:21:20.747594Z DEBUG hyper::client::connect::dns: resolving host="monitoring.us-east-1.amazonaws.com"
2024-09-10T15:21:20.749485Z DEBUG invoke{service=cloudwatch operation=PutMetricData sdk_invocation_id=4888433}:try_op:try_attempt: hyper::client::connect::http: connecting to 44.213.98.188:443
2024-09-10T15:21:20.765099Z DEBUG invoke{service=cloudwatch operation=PutMetricData sdk_invocation_id=4888433}:try_op:try_attempt: hyper::client::connect::http: connected to 44.213.98.188:443
2024-09-10T15:21:20.765189Z DEBUG invoke{service=cloudwatch operation=PutMetricData sdk_invocation_id=4888433}:try_op:try_attempt: rustls::client::hs: No cached session for DnsName("monitoring.us-east-1.amazonaws.com")    
2024-09-10T15:21:20.765268Z DEBUG invoke{service=cloudwatch operation=PutMetricData sdk_invocation_id=4888433}:try_op:try_attempt: rustls::client::hs: Not resuming any session    
2024-09-10T15:21:20.779675Z DEBUG invoke{service=cloudwatch operation=PutMetricData sdk_invocation_id=4888433}:try_op:try_attempt: rustls::client::hs: Using ciphersuite TLS13_AES_128_GCM_SHA256    
2024-09-10T15:21:20.779718Z DEBUG invoke{service=cloudwatch operation=PutMetricData sdk_invocation_id=4888433}:try_op:try_attempt: rustls::client::tls13: Not resuming    
2024-09-10T15:21:20.779879Z DEBUG invoke{service=cloudwatch operation=PutMetricData sdk_invocation_id=4888433}:try_op:try_attempt: rustls::client::tls13: TLS1.3 encrypted extensions: [ServerNameAck, Protocols([ProtocolName(687474702f312e31)])]    
2024-09-10T15:21:20.779911Z DEBUG invoke{service=cloudwatch operation=PutMetricData sdk_invocation_id=4888433}:try_op:try_attempt: rustls::client::hs: ALPN protocol is Some(b"http/1.1")    
2024-09-10T15:21:20.780826Z DEBUG hyper::proto::h1::io: flushed 9653 bytes
2024-09-10T15:21:20.808177Z DEBUG hyper::proto::h1::io: parsed 4 headers
2024-09-10T15:21:20.808213Z DEBUG hyper::proto::h1::conn: incoming body is content-length (212 bytes)
2024-09-10T15:21:20.808287Z DEBUG hyper::proto::h1::conn: incoming body completed
2024-09-10T15:21:20.808357Z DEBUG invoke{service=cloudwatch operation=PutMetricData sdk_invocation_id=4888433}:try_op:try_attempt: aws_smithy_runtime_api::client::interceptors::context: entering 'before deserialization' phase
2024-09-10T15:21:20.808374Z DEBUG hyper::client::pool: pooling idle connection for ("https", monitoring.us-east-1.amazonaws.com)
2024-09-10T15:21:20.808501Z DEBUG invoke{service=cloudwatch operation=PutMetricData sdk_invocation_id=4888433}:try_op:try_attempt: aws_smithy_runtime_api::client::interceptors::context: entering 'deserialization' phase
2024-09-10T15:21:20.808629Z DEBUG invoke{service=cloudwatch operation=PutMetricData sdk_invocation_id=4888433}:try_op:try_attempt:deserialization:deserialize_nonstreaming: aws_sdk_cloudwatch::operation::put_metric_data: request_id=Some("dc29e6dc-9770-4b03-9074-6fde9d5265f5")
2024-09-10T15:21:20.808676Z DEBUG invoke{service=cloudwatch operation=PutMetricData sdk_invocation_id=4888433}:try_op:try_attempt: aws_smithy_runtime_api::client::interceptors::context: entering 'after deserialization' phase
2024-09-10T15:21:20.808768Z DEBUG invoke{service=cloudwatch operation=PutMetricData sdk_invocation_id=4888433}:try_op: aws_smithy_runtime::client::retries::strategy::standard: attempt #1 succeeded, no retry necessary
2024-09-10T15:21:20.808788Z DEBUG invoke{service=cloudwatch operation=PutMetricData sdk_invocation_id=4888433}:try_op: aws_smithy_runtime::client::orchestrator: a retry is either unnecessary or not possible, exiting attempt loop
Metric datums: 1
Total value/count pairs: 100
Total datapoint count: 103
Elapsed time: 63ms
Result: Ok(
    PutMetricDataOutput {
        _request_id: Some(
            "dc29e6dc-9770-4b03-9074-6fde9d5265f5",
        ),
    },
)
------
Test 3, two sets, truncated to 100 pairs:
2024-09-10T15:21:20.809123Z DEBUG invoke{service=cloudwatch operation=PutMetricData sdk_invocation_id=6870417}:apply_configuration: aws_smithy_runtime::client::orchestrator: timeout settings for this operation: TimeoutConfig { connect_timeout: Set(3.1s), read_timeout: Disabled, operation_timeout: Disabled, operation_attempt_timeout: Disabled }
2024-09-10T15:21:20.809203Z DEBUG invoke{service=cloudwatch operation=PutMetricData sdk_invocation_id=6870417}:try_op: aws_smithy_runtime_api::client::interceptors::context: entering 'serialization' phase
2024-09-10T15:21:20.809719Z DEBUG invoke{service=cloudwatch operation=PutMetricData sdk_invocation_id=6870417}:try_op: aws_smithy_runtime_api::client::interceptors::context: entering 'before transmit' phase
2024-09-10T15:21:20.809827Z DEBUG invoke{service=cloudwatch operation=PutMetricData sdk_invocation_id=6870417}:try_op: aws_smithy_runtime::client::retries::strategy::standard: no client rate limiter configured, so no token is required for the initial request.
2024-09-10T15:21:20.809841Z DEBUG invoke{service=cloudwatch operation=PutMetricData sdk_invocation_id=6870417}:try_op: aws_smithy_runtime::client::orchestrator: retry strategy has OKed initial request
2024-09-10T15:21:20.809868Z DEBUG invoke{service=cloudwatch operation=PutMetricData sdk_invocation_id=6870417}:try_op: aws_smithy_runtime::client::orchestrator: beginning attempt #1
2024-09-10T15:21:20.809908Z DEBUG invoke{service=cloudwatch operation=PutMetricData sdk_invocation_id=6870417}:try_op:try_attempt: aws_smithy_runtime::client::orchestrator::endpoints: resolving endpoint endpoint_params=EndpointResolverParams(TypeErasedBox[!Clone]:Params { region: Some("us-east-1"), use_dual_stack: false, use_fips: false, endpoint: None }) endpoint_prefix=None
2024-09-10T15:21:20.809944Z DEBUG invoke{service=cloudwatch operation=PutMetricData sdk_invocation_id=6870417}:try_op:try_attempt: aws_smithy_runtime::client::orchestrator::endpoints: will use endpoint Endpoint { url: "https://monitoring.us-east-1.amazonaws.com", headers: {}, properties: {} }
2024-09-10T15:21:20.810095Z DEBUG invoke{service=cloudwatch operation=PutMetricData sdk_invocation_id=6870417}:try_op:try_attempt: aws_smithy_runtime::client::identity::cache::lazy: loaded identity from cache buffer_time=10s cached_expiration=None now=SystemTime { tv_sec: 1725981680, tv_nsec: 810084000 }
2024-09-10T15:21:20.810522Z DEBUG invoke{service=cloudwatch operation=PutMetricData sdk_invocation_id=6870417}:try_op:try_attempt: aws_smithy_runtime_api::client::interceptors::context: entering 'transmit' phase
2024-09-10T15:21:20.810583Z DEBUG invoke{service=cloudwatch operation=PutMetricData sdk_invocation_id=6870417}:try_op:try_attempt: aws_smithy_runtime::client::http::body::minimum_throughput: applying minimum upload throughput check future options=MinimumThroughputBodyOptions { minimum_throughput: Throughput { bytes_read: 1, per_time_elapsed: 1s }, grace_period: 5s, check_window: 1s }
2024-09-10T15:21:20.810637Z DEBUG invoke{service=cloudwatch operation=PutMetricData sdk_invocation_id=6870417}:try_op:try_attempt: hyper::client::pool: reuse idle connection for ("https", monitoring.us-east-1.amazonaws.com)
2024-09-10T15:21:20.814691Z DEBUG hyper::proto::h1::io: flushed 2410 bytes
2024-09-10T15:21:30.825957Z DEBUG hyper::proto::h1::io: parsed 3 headers
2024-09-10T15:21:30.826056Z DEBUG hyper::proto::h1::conn: incoming body is empty
2024-09-10T15:21:30.826187Z DEBUG rustls::common_state: Sending warning alert CloseNotify    
2024-09-10T15:21:30.826654Z DEBUG invoke{service=cloudwatch operation=PutMetricData sdk_invocation_id=6870417}:try_op:try_attempt: aws_smithy_runtime_api::client::interceptors::context: entering 'before deserialization' phase
2024-09-10T15:21:30.827140Z DEBUG invoke{service=cloudwatch operation=PutMetricData sdk_invocation_id=6870417}:try_op:try_attempt: aws_smithy_runtime_api::client::interceptors::context: entering 'deserialization' phase
2024-09-10T15:21:30.827424Z DEBUG invoke{service=cloudwatch operation=PutMetricData sdk_invocation_id=6870417}:try_op:try_attempt:deserialization:deserialize_nonstreaming: aws_sdk_cloudwatch::operation::put_metric_data: request_id=None
2024-09-10T15:21:30.827575Z DEBUG invoke{service=cloudwatch operation=PutMetricData sdk_invocation_id=6870417}:try_op:try_attempt: aws_smithy_runtime_api::client::interceptors::context: entering 'after deserialization' phase
2024-09-10T15:21:30.827909Z DEBUG invoke{service=cloudwatch operation=PutMetricData sdk_invocation_id=6870417}:try_op: aws_smithy_runtime::client::retries::strategy::standard: attempt #1 succeeded, no retry necessary
2024-09-10T15:21:30.827991Z DEBUG invoke{service=cloudwatch operation=PutMetricData sdk_invocation_id=6870417}:try_op: aws_smithy_runtime::client::orchestrator: a retry is either unnecessary or not possible, exiting attempt loop
Metric datums: 2
Total value/count pairs: 200
Total datapoint count: 206
Elapsed time: 10019ms
Result: Err(
    ServiceError(
        ServiceError {
            source: Unhandled(
                Unhandled {
                    source: XmlDecodeError {
                        kind: Custom(
                            "no root element",
                        ),
                    },
                    meta: ErrorMetadata {
                        code: None,
                        message: None,
                        extras: None,
                    },
                },
            ),
            raw: Response {
                status: StatusCode(
                    408,
                ),
                headers: Headers {
                    headers: {
                        "content-length": HeaderValue {
                            _private: H0(
                                "0",
                            ),
                        },
                        "date": HeaderValue {
                            _private: H0(
                                "Tue, 10 Sep 2024 15:21:25 GMT",
                            ),
                        },
                        "connection": HeaderValue {
                            _private: H0(
                                "close",
                            ),
                        },
                    },
                },
                body: SdkBody {
                    inner: Once(
                        Some(
                            b"",
                        ),
                    ),
                    retryable: true,
                },
                extensions: Extensions {
                    extensions_02x: Extensions,
                    extensions_1x: Extensions,
                },
            },
        },
    ),
)
------
ysaito1001 commented 1 month ago

Hi @acjay, thank you for reporting this. This is due to a bug in request compression we introduced back in May. We are looking into it to come up with a fix for it.

In the meantime, you can workaround the bug by disabling request compression through configuration, i.e., in the above code in Reproduction Steps, change

let aws_config = aws_config::defaults(BehaviorVersion::latest()).load().await;

to

let aws_config = aws_config::defaults(BehaviorVersion::latest()).disable_request_compression(true).load().await;
acjay commented 1 month ago

Thanks! I thought I was losing my mind. Even in lieu of a fix, it would help a lot to have had a better error message, perhaps with a recommendation to disable compression.

ysaito1001 commented 1 month ago

Fix merged to main in smithy-rs, pending to be released.

ysaito1001 commented 1 month ago

The fix was released on release-2024-09-27. Let us know if you still encounter the issue after upgrading aws-sdk-cloudwatch to 1.49.0 or greater.

github-actions[bot] commented 1 month ago

Comments on closed issues are hard for our team to see. If you need more assistance, please either tag a team member or open a new issue that references this one. If you wish to keep having a conversation with other community members under this issue feel free to do so.