How to debug the aws_cloudwatch_logs sink? #16627

samidalouche · 2023-02-28T12:31:32Z

samidalouche
Feb 28, 2023

Hi,

Config:

[sources.journald]
type = "journald"

[sinks.cloudwatch_logs]
type = "aws_cloudwatch_logs"
inputs = ["journald"]
create_missing_group = true
create_missing_stream = true
group_name = "test"
stream_name = "test"
region = "us-east-1"
compression = "gzip"
encoding.codec = "json"

Output with debug enabled (VECTOR_LOG=debug)

Feb 28 12:18:42 ip-10-24-196-120.ec2.internal systemd[1]: Starting Vector...
Feb 28 12:18:42 ip-10-24-196-120.ec2.internal vector[6501]: 2023-02-28T12:18:42.427853Z  INFO vector::app: Internal log rate limit configured. internal_log_rate_secs=10
Feb 28 12:18:42 ip-10-24-196-120.ec2.internal vector[6501]: √ Loaded ["/etc/vector/vector.toml"]
Feb 28 12:18:42 ip-10-24-196-120.ec2.internal vector[6501]: 2023-02-28T12:18:42.429599Z DEBUG vector::topology::builder: Building new source. component=journald
Feb 28 12:18:42 ip-10-24-196-120.ec2.internal vector[6501]: 2023-02-28T12:18:42.430028Z DEBUG vector::topology::builder: Building new sink. component=cloudwatch_logs
Feb 28 12:18:42 ip-10-24-196-120.ec2.internal vector[6501]: 2023-02-28T12:18:42.437812Z DEBUG aws_config::fs_util: loaded home directory src="HOME"
Feb 28 12:18:42 ip-10-24-196-120.ec2.internal vector[6501]: 2023-02-28T12:18:42.437872Z DEBUG load_config_file{file=Default(Config)}: aws_config::profile::parser::source: performing home directory substitution home="/var/lib/vector" path="~/.aws/config"
Feb 28 12:18:42 ip-10-24-196-120.ec2.internal vector[6501]: 2023-02-28T12:18:42.437916Z DEBUG load_config_file{file=Default(Config)}: aws_config::profile::parser::source: home directory expanded before="~/.aws/config" after="/var/lib/vector/.aws/config"
Feb 28 12:18:42 ip-10-24-196-120.ec2.internal vector[6501]: 2023-02-28T12:18:42.437952Z DEBUG load_config_file{file=Default(Config)}: aws_config::profile::parser::source: config file not found path=~/.aws/config
Feb 28 12:18:42 ip-10-24-196-120.ec2.internal vector[6501]: 2023-02-28T12:18:42.437971Z DEBUG load_config_file{file=Default(Config)}: aws_config::profile::parser::source: config file loaded path=Some("/var/lib/vector/.aws/config") size=0
Feb 28 12:18:42 ip-10-24-196-120.ec2.internal vector[6501]: 2023-02-28T12:18:42.438024Z DEBUG load_config_file{file=Default(Credentials)}: aws_config::profile::parser::source: performing home directory substitution home="/var/lib/vector" path="~/.aws/credentials"
Feb 28 12:18:42 ip-10-24-196-120.ec2.internal vector[6501]: 2023-02-28T12:18:42.438046Z DEBUG load_config_file{file=Default(Credentials)}: aws_config::profile::parser::source: home directory expanded before="~/.aws/credentials" after="/var/lib/vector/.aws/credentials"
Feb 28 12:18:42 ip-10-24-196-120.ec2.internal vector[6501]: 2023-02-28T12:18:42.438069Z DEBUG load_config_file{file=Default(Credentials)}: aws_config::profile::parser::source: config file not found path=~/.aws/credentials
Feb 28 12:18:42 ip-10-24-196-120.ec2.internal vector[6501]: 2023-02-28T12:18:42.438084Z DEBUG load_config_file{file=Default(Credentials)}: aws_config::profile::parser::source: config file loaded path=Some("/var/lib/vector/.aws/credentials") size=0
Feb 28 12:18:42 ip-10-24-196-120.ec2.internal vector[6501]: 2023-02-28T12:18:42.457393Z DEBUG vector_core::tls::settings: Fetching system root certs.
Feb 28 12:18:42 ip-10-24-196-120.ec2.internal vector[6501]: 2023-02-28T12:18:42.463618Z DEBUG vector_core::tls::settings: Fetching system root certs.
Feb 28 12:18:42 ip-10-24-196-120.ec2.internal vector[6501]: 2023-02-28T12:18:42.480119Z DEBUG vector_core::tls::settings: Fetching system root certs.
Feb 28 12:18:42 ip-10-24-196-120.ec2.internal vector[6501]: 2023-02-28T12:18:42.486291Z DEBUG vector_core::tls::settings: Fetching system root certs.
Feb 28 12:18:42 ip-10-24-196-120.ec2.internal vector[6501]: √ Component configuration
Feb 28 12:18:42 ip-10-24-196-120.ec2.internal vector[6501]: 2023-02-28T12:18:42.493384Z DEBUG send_operation{operation="DescribeLogGroups" service="cloudwatchlogs"}:async_map_request{name="retrieve_credentials"}:lazy_load_credentials: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: "environment variable not set" }))
Feb 28 12:18:42 ip-10-24-196-120.ec2.internal vector[6501]: 2023-02-28T12:18:42.493453Z DEBUG send_operation{operation="DescribeLogGroups" service="cloudwatchlogs"}:async_map_request{name="retrieve_credentials"}:lazy_load_credentials:provide_credentials{provider=default_chain}:load_credentials{provider=Profile}: aws_config::fs_util: loaded home directory src="HOME"
Feb 28 12:18:42 ip-10-24-196-120.ec2.internal vector[6501]: 2023-02-28T12:18:42.493494Z DEBUG send_operation{operation="DescribeLogGroups" service="cloudwatchlogs"}:async_map_request{name="retrieve_credentials"}:lazy_load_credentials:provide_credentials{provider=default_chain}:load_credentials{provider=Profile}:load_config_file{file=Default(Config)}: aws_config::profile::parser::source: performing home directory substitution home="/var/lib/vector" path="~/.aws/config"
Feb 28 12:18:42 ip-10-24-196-120.ec2.internal vector[6501]: 2023-02-28T12:18:42.493523Z DEBUG send_operation{operation="DescribeLogGroups" service="cloudwatchlogs"}:async_map_request{name="retrieve_credentials"}:lazy_load_credentials:provide_credentials{provider=default_chain}:load_credentials{provider=Profile}:load_config_file{file=Default(Config)}: aws_config::profile::parser::source: home directory expanded before="~/.aws/config" after="/var/lib/vector/.aws/config"
Feb 28 12:18:42 ip-10-24-196-120.ec2.internal vector[6501]: 2023-02-28T12:18:42.493557Z DEBUG send_operation{operation="DescribeLogGroups" service="cloudwatchlogs"}:async_map_request{name="retrieve_credentials"}:lazy_load_credentials:provide_credentials{provider=default_chain}:load_credentials{provider=Profile}:load_config_file{file=Default(Config)}: aws_config::profile::parser::source: config file not found path=~/.aws/config
Feb 28 12:18:42 ip-10-24-196-120.ec2.internal vector[6501]: 2023-02-28T12:18:42.493583Z DEBUG send_operation{operation="DescribeLogGroups" service="cloudwatchlogs"}:async_map_request{name="retrieve_credentials"}:lazy_load_credentials:provide_credentials{provider=default_chain}:load_credentials{provider=Profile}:load_config_file{file=Default(Config)}: aws_config::profile::parser::source: config file loaded path=Some("/var/lib/vector/.aws/config") size=0
Feb 28 12:18:42 ip-10-24-196-120.ec2.internal vector[6501]: 2023-02-28T12:18:42.493615Z DEBUG send_operation{operation="DescribeLogGroups" service="cloudwatchlogs"}:async_map_request{name="retrieve_credentials"}:lazy_load_credentials:provide_credentials{provider=default_chain}:load_credentials{provider=Profile}:load_config_file{file=Default(Credentials)}: aws_config::profile::parser::source: performing home directory substitution home="/var/lib/vector" path="~/.aws/credentials"
Feb 28 12:18:42 ip-10-24-196-120.ec2.internal vector[6501]: 2023-02-28T12:18:42.493645Z DEBUG send_operation{operation="DescribeLogGroups" service="cloudwatchlogs"}:async_map_request{name="retrieve_credentials"}:lazy_load_credentials:provide_credentials{provider=default_chain}:load_credentials{provider=Profile}:load_config_file{file=Default(Credentials)}: aws_config::profile::parser::source: home directory expanded before="~/.aws/credentials" after="/var/lib/vector/.aws/credentials"
Feb 28 12:18:42 ip-10-24-196-120.ec2.internal vector[6501]: 2023-02-28T12:18:42.493674Z DEBUG send_operation{operation="DescribeLogGroups" service="cloudwatchlogs"}:async_map_request{name="retrieve_credentials"}:lazy_load_credentials:provide_credentials{provider=default_chain}:load_credentials{provider=Profile}:load_config_file{file=Default(Credentials)}: aws_config::profile::parser::source: config file not found path=~/.aws/credentials
Feb 28 12:18:42 ip-10-24-196-120.ec2.internal vector[6501]: 2023-02-28T12:18:42.493693Z DEBUG send_operation{operation="DescribeLogGroups" service="cloudwatchlogs"}:async_map_request{name="retrieve_credentials"}:lazy_load_credentials:provide_credentials{provider=default_chain}:load_credentials{provider=Profile}:load_config_file{file=Default(Credentials)}: aws_config::profile::parser::source: config file loaded path=Some("/var/lib/vector/.aws/credentials") size=0
Feb 28 12:18:42 ip-10-24-196-120.ec2.internal vector[6501]: 2023-02-28T12:18:42.493742Z DEBUG send_operation{operation="DescribeLogGroups" service="cloudwatchlogs"}:async_map_request{name="retrieve_credentials"}:lazy_load_credentials:provide_credentials{provider=default_chain}: aws_config::meta::credentials::chain: provider in chain did not provide credentials provider=Profile context=the credential provider was not enabled: No profiles were defined (CredentialsNotLoaded(CredentialsNotLoaded { source: NoProfilesDefined }))
Feb 28 12:18:42 ip-10-24-196-120.ec2.internal vector[6501]: 2023-02-28T12:18:42.493795Z DEBUG send_operation{operation="DescribeLogGroups" service="cloudwatchlogs"}:async_map_request{name="retrieve_credentials"}:lazy_load_credentials:provide_credentials{provider=default_chain}: aws_config::meta::credentials::chain: provider in chain did not provide credentials provider=WebIdentityToken context=the credential provider was not enabled: $AWS_WEB_IDENTITY_TOKEN_FILE was not set (CredentialsNotLoaded(CredentialsNotLoaded { source: "$AWS_WEB_IDENTITY_TOKEN_FILE was not set" }))
Feb 28 12:18:42 ip-10-24-196-120.ec2.internal vector[6501]: 2023-02-28T12:18:42.493835Z DEBUG send_operation{operation="DescribeLogGroups" service="cloudwatchlogs"}:async_map_request{name="retrieve_credentials"}:lazy_load_credentials:provide_credentials{provider=default_chain}: aws_config::meta::credentials::chain: provider in chain did not provide credentials provider=EcsContainer context=the credential provider was not enabled: ECS provider not configured (CredentialsNotLoaded(CredentialsNotLoaded { source: "ECS provider not configured" }))
Feb 28 12:18:42 ip-10-24-196-120.ec2.internal vector[6501]: 2023-02-28T12:18:42.493859Z DEBUG send_operation{operation="DescribeLogGroups" service="cloudwatchlogs"}:async_map_request{name="retrieve_credentials"}:lazy_load_credentials:provide_credentials{provider=default_chain}:load_credentials{provider=Ec2InstanceMetadata}: aws_config::imds::credentials: loading credentials from IMDS
Feb 28 12:18:42 ip-10-24-196-120.ec2.internal vector[6501]: 2023-02-28T12:18:42.494141Z DEBUG send_operation{operation="DescribeLogGroups" service="cloudwatchlogs"}:async_map_request{name="retrieve_credentials"}:lazy_load_credentials:provide_credentials{provider=default_chain}:load_credentials{provider=Ec2InstanceMetadata}:send_operation{operation="get" service="imds"}:async_map_request{name="attach_imds_token"}:send_operation{operation="get-token" service="imds"}:dispatch: hyper::client::connect::http: connecting to 169.254.169.254:80
Feb 28 12:18:42 ip-10-24-196-120.ec2.internal vector[6501]: 2023-02-28T12:18:42.494958Z DEBUG send_operation{operation="DescribeLogGroups" service="cloudwatchlogs"}:async_map_request{name="retrieve_credentials"}:lazy_load_credentials:provide_credentials{provider=default_chain}:load_credentials{provider=Ec2InstanceMetadata}:send_operation{operation="get" service="imds"}:async_map_request{name="attach_imds_token"}:send_operation{operation="get-token" service="imds"}:dispatch: hyper::client::connect::http: connected to 169.254.169.254:80
Feb 28 12:18:42 ip-10-24-196-120.ec2.internal vector[6501]: 2023-02-28T12:18:42.495272Z DEBUG hyper::proto::h1::io: flushed 242 bytes
Feb 28 12:18:42 ip-10-24-196-120.ec2.internal vector[6501]: 2023-02-28T12:18:42.496325Z DEBUG hyper::proto::h1::io: parsed 6 headers
Feb 28 12:18:42 ip-10-24-196-120.ec2.internal vector[6501]: 2023-02-28T12:18:42.496345Z DEBUG hyper::proto::h1::conn: incoming body is content-length (56 bytes)
Feb 28 12:18:42 ip-10-24-196-120.ec2.internal vector[6501]: 2023-02-28T12:18:42.496388Z DEBUG hyper::proto::h1::conn: incoming body completed
Feb 28 12:18:42 ip-10-24-196-120.ec2.internal vector[6501]: 2023-02-28T12:18:42.496703Z DEBUG send_operation{operation="DescribeLogGroups" service="cloudwatchlogs"}:async_map_request{name="retrieve_credentials"}:lazy_load_credentials:provide_credentials{provider=default_chain}:load_credentials{provider=Ec2InstanceMetadata}:send_operation{operation="get" service="imds"}:dispatch: hyper::client::connect::http: connecting to 169.254.169.254:80
Feb 28 12:18:42 ip-10-24-196-120.ec2.internal vector[6501]: 2023-02-28T12:18:42.496883Z DEBUG send_operation{operation="DescribeLogGroups" service="cloudwatchlogs"}:async_map_request{name="retrieve_credentials"}:lazy_load_credentials:provide_credentials{provider=default_chain}:load_credentials{provider=Ec2InstanceMetadata}:send_operation{operation="get" service="imds"}:dispatch: hyper::client::connect::http: connected to 169.254.169.254:80
Feb 28 12:18:42 ip-10-24-196-120.ec2.internal vector[6501]: 2023-02-28T12:18:42.496979Z DEBUG hyper::proto::h1::io: flushed 307 bytes
Feb 28 12:18:42 ip-10-24-196-120.ec2.internal vector[6501]: 2023-02-28T12:18:42.497665Z DEBUG hyper::proto::h1::io: parsed 8 headers
Feb 28 12:18:42 ip-10-24-196-120.ec2.internal vector[6501]: 2023-02-28T12:18:42.497680Z DEBUG hyper::proto::h1::conn: incoming body is content-length (21 bytes)
Feb 28 12:18:42 ip-10-24-196-120.ec2.internal vector[6501]: 2023-02-28T12:18:42.497699Z DEBUG hyper::proto::h1::conn: incoming body completed
Feb 28 12:18:42 ip-10-24-196-120.ec2.internal vector[6501]: 2023-02-28T12:18:42.497854Z DEBUG send_operation{operation="DescribeLogGroups" service="cloudwatchlogs"}:async_map_request{name="retrieve_credentials"}:lazy_load_credentials:provide_credentials{provider=default_chain}:load_credentials{provider=Ec2InstanceMetadata}: aws_config::imds::credentials: loaded profile profile=export-s3-kinesis-dev
Feb 28 12:18:42 ip-10-24-196-120.ec2.internal vector[6501]: 2023-02-28T12:18:42.497935Z DEBUG send_operation{operation="DescribeLogGroups" service="cloudwatchlogs"}:async_map_request{name="retrieve_credentials"}:lazy_load_credentials:provide_credentials{provider=default_chain}:load_credentials{provider=Ec2InstanceMetadata}:send_operation{operation="get" service="imds"}:dispatch: hyper::client::connect::http: connecting to 169.254.169.254:80
Feb 28 12:18:42 ip-10-24-196-120.ec2.internal vector[6501]: 2023-02-28T12:18:42.498482Z DEBUG send_operation{operation="DescribeLogGroups" service="cloudwatchlogs"}:async_map_request{name="retrieve_credentials"}:lazy_load_credentials:provide_credentials{provider=default_chain}:load_credentials{provider=Ec2InstanceMetadata}:send_operation{operation="get" service="imds"}:dispatch: hyper::client::connect::http: connected to 169.254.169.254:80
Feb 28 12:18:42 ip-10-24-196-120.ec2.internal vector[6501]: 2023-02-28T12:18:42.498589Z DEBUG hyper::proto::h1::io: flushed 328 bytes
Feb 28 12:18:42 ip-10-24-196-120.ec2.internal vector[6501]: 2023-02-28T12:18:42.499196Z DEBUG hyper::proto::h1::io: parsed 8 headers
Feb 28 12:18:42 ip-10-24-196-120.ec2.internal vector[6501]: 2023-02-28T12:18:42.499227Z DEBUG hyper::proto::h1::conn: incoming body is content-length (1586 bytes)
Feb 28 12:18:42 ip-10-24-196-120.ec2.internal vector[6501]: 2023-02-28T12:18:42.499243Z DEBUG hyper::proto::h1::conn: incoming body completed
Feb 28 12:18:42 ip-10-24-196-120.ec2.internal vector[6501]: 2023-02-28T12:18:42.499431Z DEBUG send_operation{operation="DescribeLogGroups" service="cloudwatchlogs"}:async_map_request{name="retrieve_credentials"}:lazy_load_credentials:provide_credentials{provider=default_chain}: aws_config::meta::credentials::chain: loaded credentials provider=Ec2InstanceMetadata
Feb 28 12:18:42 ip-10-24-196-120.ec2.internal vector[6501]: 2023-02-28T12:18:42.499463Z  INFO send_operation{operation="DescribeLogGroups" service="cloudwatchlogs"}:async_map_request{name="retrieve_credentials"}: aws_credential_types::cache::lazy_caching: credentials cache miss occurred; retrieved new AWS credentials (took 6.121907ms)
Feb 28 12:18:42 ip-10-24-196-120.ec2.internal vector[6501]: 2023-02-28T12:18:42.501041Z DEBUG hyper::client::connect::dns: resolving host="logs.us-east-1.amazonaws.com"
Feb 28 12:18:42 ip-10-24-196-120.ec2.internal vector[6501]: 2023-02-28T12:18:42.502033Z DEBUG send_operation{operation="DescribeLogGroups" service="cloudwatchlogs"}:dispatch: hyper::client::connect::http: connecting to 10.24.74.235:443
Feb 28 12:18:42 ip-10-24-196-120.ec2.internal vector[6501]: 2023-02-28T12:18:42.503667Z DEBUG send_operation{operation="DescribeLogGroups" service="cloudwatchlogs"}:dispatch: hyper::client::connect::http: connected to 10.24.74.235:443
Feb 28 12:18:42 ip-10-24-196-120.ec2.internal vector[6501]: 2023-02-28T12:18:42.506991Z DEBUG hyper::proto::h1::io: flushed 2027 bytes
Feb 28 12:18:42 ip-10-24-196-120.ec2.internal vector[6501]: 2023-02-28T12:18:42.510841Z DEBUG hyper::proto::h1::io: parsed 5 headers
Feb 28 12:18:42 ip-10-24-196-120.ec2.internal vector[6501]: 2023-02-28T12:18:42.510871Z DEBUG hyper::proto::h1::conn: incoming body is content-length (229 bytes)
Feb 28 12:18:42 ip-10-24-196-120.ec2.internal vector[6501]: 2023-02-28T12:18:42.510907Z DEBUG hyper::proto::h1::conn: incoming body completed
Feb 28 12:18:42 ip-10-24-196-120.ec2.internal vector[6501]: 2023-02-28T12:18:42.511302Z ERROR vector::topology::builder: msg="Healthcheck failed." error=DescribeLogGroups failed: service error component_kind="sink" component_type="aws_cloudwatch_logs" component_id=cloudwatch_logs component_name=cloudwatch_logs
Feb 28 12:18:42 ip-10-24-196-120.ec2.internal vector[6501]: x Health check for "cloudwatch_logs" failed: DescribeLogGroups failed: service error
Feb 28 12:18:42 ip-10-24-196-120.ec2.internal systemd[1]: vector.service: control process exited, code=exited status=78
Feb 28 12:18:42 ip-10-24-196-120.ec2.internal systemd[1]: Failed to start Vector.
Feb 28 12:18:42 ip-10-24-196-120.ec2.internal systemd[1]: Unit vector.service entered failed state.
Feb 28 12:18:42 ip-10-24-196-120.ec2.internal systemd[1]: vector.service failed.

My first reaction is that it must be some sort of permission issue, but aws logs describe-log-groups --region us-east-1 works fine on the same machine (no other credentials defined than the IAM role attached to the EC2 instance, and the role has the CloudWatchAgentServerPolicy attached).

Is there any additional logs I can enable to make the debugging easier? Any idea that you would suggest?

Worth mentioing: I have a very similar set up working on another machine, using a different AMI. Could it potentially be related to IMDSv2 not being supported, or something similar?

Thanks

jszwedko · 2023-02-28T12:39:41Z

jszwedko
Feb 28, 2023
Maintainer

Hi @samidalouche ,

You could try setting RUST_LOG=aws_config=debug to get additional credential loading logs, but from the output there it doesn't seem like loading the credentials failed. The error seems to be an opaque error from AWS ("service error"). You could also try setting RUST_LOG=aws_smithy_http=trace to get all request/responses sent to AWS. This might help highlight the error.

The new AWS SDK only supports IMDSv2.

5 replies

samidalouche Feb 28, 2023
Author

Thanks. I tried setting the http logs, but nothing interesting pops in the logs.

Feb 28 12:42:33 ip-10-24-196-120.ec2.internal systemd[1]: Starting Vector...
Feb 28 12:42:33 ip-10-24-196-120.ec2.internal vector[19516]: 2023-02-28T12:42:33.718719Z  INFO vector::app: Internal log rate limit configured. internal_log_rate_secs=10
Feb 28 12:42:33 ip-10-24-196-120.ec2.internal vector[19516]: √ Loaded ["/etc/vector/vector.toml"]
Feb 28 12:42:33 ip-10-24-196-120.ec2.internal vector[19516]: 2023-02-28T12:42:33.720550Z DEBUG vector::topology::builder: Building new source. component=journald
Feb 28 12:42:33 ip-10-24-196-120.ec2.internal vector[19516]: 2023-02-28T12:42:33.720986Z DEBUG vector::topology::builder: Building new sink. component=cloudwatch_logs
Feb 28 12:42:33 ip-10-24-196-120.ec2.internal vector[19516]: 2023-02-28T12:42:33.728803Z DEBUG aws_config::fs_util: loaded home directory src="HOME"
Feb 28 12:42:33 ip-10-24-196-120.ec2.internal vector[19516]: 2023-02-28T12:42:33.728862Z DEBUG load_config_file{file=Default(Config)}: aws_config::profile::parser::source: performing home directory substitution home="/var/lib/vector" path="~/.aws/config"
Feb 28 12:42:33 ip-10-24-196-120.ec2.internal vector[19516]: 2023-02-28T12:42:33.728907Z DEBUG load_config_file{file=Default(Config)}: aws_config::profile::parser::source: home directory expanded before="~/.aws/config" after="/var/lib/vector/.aws/config"
Feb 28 12:42:33 ip-10-24-196-120.ec2.internal vector[19516]: 2023-02-28T12:42:33.728944Z DEBUG load_config_file{file=Default(Config)}: aws_config::profile::parser::source: config file not found path=~/.aws/config
Feb 28 12:42:33 ip-10-24-196-120.ec2.internal vector[19516]: 2023-02-28T12:42:33.728964Z DEBUG load_config_file{file=Default(Config)}: aws_config::profile::parser::source: config file loaded path=Some("/var/lib/vector/.aws/config") size=0
Feb 28 12:42:33 ip-10-24-196-120.ec2.internal vector[19516]: 2023-02-28T12:42:33.729016Z DEBUG load_config_file{file=Default(Credentials)}: aws_config::profile::parser::source: performing home directory substitution home="/var/lib/vector" path="~/.aws/credentials"
Feb 28 12:42:33 ip-10-24-196-120.ec2.internal vector[19516]: 2023-02-28T12:42:33.729036Z DEBUG load_config_file{file=Default(Credentials)}: aws_config::profile::parser::source: home directory expanded before="~/.aws/credentials" after="/var/lib/vector/.aws/credentials"
Feb 28 12:42:33 ip-10-24-196-120.ec2.internal vector[19516]: 2023-02-28T12:42:33.729059Z DEBUG load_config_file{file=Default(Credentials)}: aws_config::profile::parser::source: config file not found path=~/.aws/credentials
Feb 28 12:42:33 ip-10-24-196-120.ec2.internal vector[19516]: 2023-02-28T12:42:33.729074Z DEBUG load_config_file{file=Default(Credentials)}: aws_config::profile::parser::source: config file loaded path=Some("/var/lib/vector/.aws/credentials") size=0
Feb 28 12:42:33 ip-10-24-196-120.ec2.internal vector[19516]: 2023-02-28T12:42:33.748092Z DEBUG vector_core::tls::settings: Fetching system root certs.
Feb 28 12:42:33 ip-10-24-196-120.ec2.internal vector[19516]: 2023-02-28T12:42:33.754306Z DEBUG vector_core::tls::settings: Fetching system root certs.
Feb 28 12:42:33 ip-10-24-196-120.ec2.internal vector[19516]: 2023-02-28T12:42:33.770749Z DEBUG vector_core::tls::settings: Fetching system root certs.
Feb 28 12:42:33 ip-10-24-196-120.ec2.internal vector[19516]: 2023-02-28T12:42:33.777019Z DEBUG vector_core::tls::settings: Fetching system root certs.
Feb 28 12:42:33 ip-10-24-196-120.ec2.internal vector[19516]: √ Component configuration
Feb 28 12:42:33 ip-10-24-196-120.ec2.internal vector[19516]: 2023-02-28T12:42:33.784175Z DEBUG send_operation{operation="DescribeLogGroups" service="cloudwatchlogs"}:async_map_request{name="retrieve_credentials"}:lazy_load_credentials: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: "environment variable not set" }))
Feb 28 12:42:33 ip-10-24-196-120.ec2.internal vector[19516]: 2023-02-28T12:42:33.784245Z DEBUG send_operation{operation="DescribeLogGroups" service="cloudwatchlogs"}:async_map_request{name="retrieve_credentials"}:lazy_load_credentials:provide_credentials{provider=default_chain}:load_credentials{provider=Profile}: aws_config::fs_util: loaded home directory src="HOME"
Feb 28 12:42:33 ip-10-24-196-120.ec2.internal vector[19516]: 2023-02-28T12:42:33.784288Z DEBUG send_operation{operation="DescribeLogGroups" service="cloudwatchlogs"}:async_map_request{name="retrieve_credentials"}:lazy_load_credentials:provide_credentials{provider=default_chain}:load_credentials{provider=Profile}:load_config_file{file=Default(Config)}: aws_config::profile::parser::source: performing home directory substitution home="/var/lib/vector" path="~/.aws/config"
Feb 28 12:42:33 ip-10-24-196-120.ec2.internal vector[19516]: 2023-02-28T12:42:33.784318Z DEBUG send_operation{operation="DescribeLogGroups" service="cloudwatchlogs"}:async_map_request{name="retrieve_credentials"}:lazy_load_credentials:provide_credentials{provider=default_chain}:load_credentials{provider=Profile}:load_config_file{file=Default(Config)}: aws_config::profile::parser::source: home directory expanded before="~/.aws/config" after="/var/lib/vector/.aws/config"
Feb 28 12:42:33 ip-10-24-196-120.ec2.internal vector[19516]: 2023-02-28T12:42:33.784356Z DEBUG send_operation{operation="DescribeLogGroups" service="cloudwatchlogs"}:async_map_request{name="retrieve_credentials"}:lazy_load_credentials:provide_credentials{provider=default_chain}:load_credentials{provider=Profile}:load_config_file{file=Default(Config)}: aws_config::profile::parser::source: config file not found path=~/.aws/config
Feb 28 12:42:33 ip-10-24-196-120.ec2.internal vector[19516]: 2023-02-28T12:42:33.784380Z DEBUG send_operation{operation="DescribeLogGroups" service="cloudwatchlogs"}:async_map_request{name="retrieve_credentials"}:lazy_load_credentials:provide_credentials{provider=default_chain}:load_credentials{provider=Profile}:load_config_file{file=Default(Config)}: aws_config::profile::parser::source: config file loaded path=Some("/var/lib/vector/.aws/config") size=0
Feb 28 12:42:33 ip-10-24-196-120.ec2.internal vector[19516]: 2023-02-28T12:42:33.784412Z DEBUG send_operation{operation="DescribeLogGroups" service="cloudwatchlogs"}:async_map_request{name="retrieve_credentials"}:lazy_load_credentials:provide_credentials{provider=default_chain}:load_credentials{provider=Profile}:load_config_file{file=Default(Credentials)}: aws_config::profile::parser::source: performing home directory substitution home="/var/lib/vector" path="~/.aws/credentials"
Feb 28 12:42:33 ip-10-24-196-120.ec2.internal vector[19516]: 2023-02-28T12:42:33.784442Z DEBUG send_operation{operation="DescribeLogGroups" service="cloudwatchlogs"}:async_map_request{name="retrieve_credentials"}:lazy_load_credentials:provide_credentials{provider=default_chain}:load_credentials{provider=Profile}:load_config_file{file=Default(Credentials)}: aws_config::profile::parser::source: home directory expanded before="~/.aws/credentials" after="/var/lib/vector/.aws/credentials"
Feb 28 12:42:33 ip-10-24-196-120.ec2.internal vector[19516]: 2023-02-28T12:42:33.784470Z DEBUG send_operation{operation="DescribeLogGroups" service="cloudwatchlogs"}:async_map_request{name="retrieve_credentials"}:lazy_load_credentials:provide_credentials{provider=default_chain}:load_credentials{provider=Profile}:load_config_file{file=Default(Credentials)}: aws_config::profile::parser::source: config file not found path=~/.aws/credentials
Feb 28 12:42:33 ip-10-24-196-120.ec2.internal vector[19516]: 2023-02-28T12:42:33.784490Z DEBUG send_operation{operation="DescribeLogGroups" service="cloudwatchlogs"}:async_map_request{name="retrieve_credentials"}:lazy_load_credentials:provide_credentials{provider=default_chain}:load_credentials{provider=Profile}:load_config_file{file=Default(Credentials)}: aws_config::profile::parser::source: config file loaded path=Some("/var/lib/vector/.aws/credentials") size=0
Feb 28 12:42:33 ip-10-24-196-120.ec2.internal vector[19516]: 2023-02-28T12:42:33.784538Z DEBUG send_operation{operation="DescribeLogGroups" service="cloudwatchlogs"}:async_map_request{name="retrieve_credentials"}:lazy_load_credentials:provide_credentials{provider=default_chain}: aws_config::meta::credentials::chain: provider in chain did not provide credentials provider=Profile context=the credential provider was not enabled: No profiles were defined (CredentialsNotLoaded(CredentialsNotLoaded { source: NoProfilesDefined }))
Feb 28 12:42:33 ip-10-24-196-120.ec2.internal vector[19516]: 2023-02-28T12:42:33.784588Z DEBUG send_operation{operation="DescribeLogGroups" service="cloudwatchlogs"}:async_map_request{name="retrieve_credentials"}:lazy_load_credentials:provide_credentials{provider=default_chain}: aws_config::meta::credentials::chain: provider in chain did not provide credentials provider=WebIdentityToken context=the credential provider was not enabled: $AWS_WEB_IDENTITY_TOKEN_FILE was not set (CredentialsNotLoaded(CredentialsNotLoaded { source: "$AWS_WEB_IDENTITY_TOKEN_FILE was not set" }))
Feb 28 12:42:33 ip-10-24-196-120.ec2.internal vector[19516]: 2023-02-28T12:42:33.784629Z DEBUG send_operation{operation="DescribeLogGroups" service="cloudwatchlogs"}:async_map_request{name="retrieve_credentials"}:lazy_load_credentials:provide_credentials{provider=default_chain}: aws_config::meta::credentials::chain: provider in chain did not provide credentials provider=EcsContainer context=the credential provider was not enabled: ECS provider not configured (CredentialsNotLoaded(CredentialsNotLoaded { source: "ECS provider not configured" }))
Feb 28 12:42:33 ip-10-24-196-120.ec2.internal vector[19516]: 2023-02-28T12:42:33.784656Z DEBUG send_operation{operation="DescribeLogGroups" service="cloudwatchlogs"}:async_map_request{name="retrieve_credentials"}:lazy_load_credentials:provide_credentials{provider=default_chain}:load_credentials{provider=Ec2InstanceMetadata}: aws_config::imds::credentials: loading credentials from IMDS
Feb 28 12:42:33 ip-10-24-196-120.ec2.internal vector[19516]: 2023-02-28T12:42:33.784938Z DEBUG send_operation{operation="DescribeLogGroups" service="cloudwatchlogs"}:async_map_request{name="retrieve_credentials"}:lazy_load_credentials:provide_credentials{provider=default_chain}:load_credentials{provider=Ec2InstanceMetadata}:send_operation{operation="get" service="imds"}:async_map_request{name="attach_imds_token"}:send_operation{operation="get-token" service="imds"}:dispatch: hyper::client::connect::http: connecting to 169.254.169.254:80
Feb 28 12:42:33 ip-10-24-196-120.ec2.internal vector[19516]: 2023-02-28T12:42:33.785461Z DEBUG send_operation{operation="DescribeLogGroups" service="cloudwatchlogs"}:async_map_request{name="retrieve_credentials"}:lazy_load_credentials:provide_credentials{provider=default_chain}:load_credentials{provider=Ec2InstanceMetadata}:send_operation{operation="get" service="imds"}:async_map_request{name="attach_imds_token"}:send_operation{operation="get-token" service="imds"}:dispatch: hyper::client::connect::http: connected to 169.254.169.254:80
Feb 28 12:42:33 ip-10-24-196-120.ec2.internal vector[19516]: 2023-02-28T12:42:33.785699Z DEBUG hyper::proto::h1::io: flushed 242 bytes
Feb 28 12:42:33 ip-10-24-196-120.ec2.internal vector[19516]: 2023-02-28T12:42:33.787070Z DEBUG hyper::proto::h1::io: parsed 6 headers
Feb 28 12:42:33 ip-10-24-196-120.ec2.internal vector[19516]: 2023-02-28T12:42:33.787089Z DEBUG hyper::proto::h1::conn: incoming body is content-length (56 bytes)
Feb 28 12:42:33 ip-10-24-196-120.ec2.internal vector[19516]: 2023-02-28T12:42:33.787128Z DEBUG hyper::proto::h1::conn: incoming body completed
Feb 28 12:42:33 ip-10-24-196-120.ec2.internal vector[19516]: 2023-02-28T12:42:33.787421Z DEBUG send_operation{operation="DescribeLogGroups" service="cloudwatchlogs"}:async_map_request{name="retrieve_credentials"}:lazy_load_credentials:provide_credentials{provider=default_chain}:load_credentials{provider=Ec2InstanceMetadata}:send_operation{operation="get" service="imds"}:dispatch: hyper::client::connect::http: connecting to 169.254.169.254:80
Feb 28 12:42:33 ip-10-24-196-120.ec2.internal vector[19516]: 2023-02-28T12:42:33.787575Z DEBUG send_operation{operation="DescribeLogGroups" service="cloudwatchlogs"}:async_map_request{name="retrieve_credentials"}:lazy_load_credentials:provide_credentials{provider=default_chain}:load_credentials{provider=Ec2InstanceMetadata}:send_operation{operation="get" service="imds"}:dispatch: hyper::client::connect::http: connected to 169.254.169.254:80
Feb 28 12:42:33 ip-10-24-196-120.ec2.internal vector[19516]: 2023-02-28T12:42:33.787659Z DEBUG hyper::proto::h1::io: flushed 307 bytes
Feb 28 12:42:33 ip-10-24-196-120.ec2.internal vector[19516]: 2023-02-28T12:42:33.788499Z DEBUG hyper::proto::h1::io: parsed 8 headers
Feb 28 12:42:33 ip-10-24-196-120.ec2.internal vector[19516]: 2023-02-28T12:42:33.788516Z DEBUG hyper::proto::h1::conn: incoming body is content-length (21 bytes)
Feb 28 12:42:33 ip-10-24-196-120.ec2.internal vector[19516]: 2023-02-28T12:42:33.788535Z DEBUG hyper::proto::h1::conn: incoming body completed
Feb 28 12:42:33 ip-10-24-196-120.ec2.internal vector[19516]: 2023-02-28T12:42:33.788640Z DEBUG send_operation{operation="DescribeLogGroups" service="cloudwatchlogs"}:async_map_request{name="retrieve_credentials"}:lazy_load_credentials:provide_credentials{provider=default_chain}:load_credentials{provider=Ec2InstanceMetadata}: aws_config::imds::credentials: loaded profile profile=export-s3-kinesis-dev
Feb 28 12:42:33 ip-10-24-196-120.ec2.internal vector[19516]: 2023-02-28T12:42:33.788719Z DEBUG send_operation{operation="DescribeLogGroups" service="cloudwatchlogs"}:async_map_request{name="retrieve_credentials"}:lazy_load_credentials:provide_credentials{provider=default_chain}:load_credentials{provider=Ec2InstanceMetadata}:send_operation{operation="get" service="imds"}:dispatch: hyper::client::connect::http: connecting to 169.254.169.254:80
Feb 28 12:42:33 ip-10-24-196-120.ec2.internal vector[19516]: 2023-02-28T12:42:33.788914Z DEBUG send_operation{operation="DescribeLogGroups" service="cloudwatchlogs"}:async_map_request{name="retrieve_credentials"}:lazy_load_credentials:provide_credentials{provider=default_chain}:load_credentials{provider=Ec2InstanceMetadata}:send_operation{operation="get" service="imds"}:dispatch: hyper::client::connect::http: connected to 169.254.169.254:80
Feb 28 12:42:33 ip-10-24-196-120.ec2.internal vector[19516]: 2023-02-28T12:42:33.788995Z DEBUG hyper::proto::h1::io: flushed 328 bytes
Feb 28 12:42:33 ip-10-24-196-120.ec2.internal vector[19516]: 2023-02-28T12:42:33.789685Z DEBUG hyper::proto::h1::io: parsed 8 headers
Feb 28 12:42:33 ip-10-24-196-120.ec2.internal vector[19516]: 2023-02-28T12:42:33.789717Z DEBUG hyper::proto::h1::conn: incoming body is content-length (1586 bytes)
Feb 28 12:42:33 ip-10-24-196-120.ec2.internal vector[19516]: 2023-02-28T12:42:33.789733Z DEBUG hyper::proto::h1::conn: incoming body completed
Feb 28 12:42:33 ip-10-24-196-120.ec2.internal vector[19516]: 2023-02-28T12:42:33.789877Z DEBUG send_operation{operation="DescribeLogGroups" service="cloudwatchlogs"}:async_map_request{name="retrieve_credentials"}:lazy_load_credentials:provide_credentials{provider=default_chain}: aws_config::meta::credentials::chain: loaded credentials provider=Ec2InstanceMetadata
Feb 28 12:42:33 ip-10-24-196-120.ec2.internal vector[19516]: 2023-02-28T12:42:33.789908Z  INFO send_operation{operation="DescribeLogGroups" service="cloudwatchlogs"}:async_map_request{name="retrieve_credentials"}: aws_credential_types::cache::lazy_caching: credentials cache miss occurred; retrieved new AWS credentials (took 5.794587ms)
Feb 28 12:42:33 ip-10-24-196-120.ec2.internal vector[19516]: 2023-02-28T12:42:33.791281Z DEBUG hyper::client::connect::dns: resolving host="logs.us-east-1.amazonaws.com"
Feb 28 12:42:33 ip-10-24-196-120.ec2.internal vector[19516]: 2023-02-28T12:42:33.794258Z DEBUG send_operation{operation="DescribeLogGroups" service="cloudwatchlogs"}:dispatch: hyper::client::connect::http: connecting to 10.24.74.235:443
Feb 28 12:42:33 ip-10-24-196-120.ec2.internal vector[19516]: 2023-02-28T12:42:33.795742Z DEBUG send_operation{operation="DescribeLogGroups" service="cloudwatchlogs"}:dispatch: hyper::client::connect::http: connected to 10.24.74.235:443
Feb 28 12:42:33 ip-10-24-196-120.ec2.internal vector[19516]: 2023-02-28T12:42:33.798480Z DEBUG hyper::proto::h1::io: flushed 2027 bytes
Feb 28 12:42:33 ip-10-24-196-120.ec2.internal vector[19516]: 2023-02-28T12:42:33.803202Z DEBUG hyper::proto::h1::io: parsed 5 headers
Feb 28 12:42:33 ip-10-24-196-120.ec2.internal vector[19516]: 2023-02-28T12:42:33.803244Z DEBUG hyper::proto::h1::conn: incoming body is content-length (229 bytes)
Feb 28 12:42:33 ip-10-24-196-120.ec2.internal vector[19516]: 2023-02-28T12:42:33.803288Z DEBUG hyper::proto::h1::conn: incoming body completed
Feb 28 12:42:33 ip-10-24-196-120.ec2.internal vector[19516]: 2023-02-28T12:42:33.803672Z ERROR vector::topology::builder: msg="Healthcheck failed." error=DescribeLogGroups failed: service error component_kind="sink" component_type="aws_cloudwatch_logs" component_id=cloudwatch_logs component_name=cloudwatch_logs
Feb 28 12:42:33 ip-10-24-196-120.ec2.internal vector[19516]: x Health check for "cloudwatch_logs" failed: DescribeLogGroups failed: service error
Feb 28 12:42:33 ip-10-24-196-120.ec2.internal systemd[1]: vector.service: control process exited, code=exited status=78
Feb 28 12:42:33 ip-10-24-196-120.ec2.internal systemd[1]: Failed to start Vector.
Feb 28 12:42:33 ip-10-24-196-120.ec2.internal systemd[1]: Unit vector.service entered failed state.
Feb 28 12:42:33 ip-10-24-196-120.ec2.internal systemd[1]: vector.service failed.

jszwedko Feb 28, 2023
Maintainer

Did you try RUST_LOG=aws_smithy_http=trace too? I'm not seeing the AWS SDK logs I was expecting to see in that output. It should have the HTTP requests and responses.

samidalouche Feb 28, 2023
Author

Did you try RUST_LOG=aws_smithy_http=trace too? I'm not seeing the AWS SDK logs I was expecting to see in that output. It should have the HTTP requests and responses.

Yes, I have RUST_LOG=aws_smithy_http=trace in /etc/default/vector, but it apparently does not have much of an effect. I will try running vector outside of systemd in case I can get this to work

samidalouche Feb 28, 2023
Author

OK, for some reason systemd was not passing the env variable correctly. This is what I get now

2023-02-28T13:07:03.668298Z  INFO vector::app: Internal log rate limit configured. internal_log_rate_secs=10
2023-02-28T13:07:03.668508Z  INFO vector::app: Log level is enabled. level="debug"
2023-02-28T13:07:03.668608Z  INFO vector::app: Loading configs. paths=["/etc/vector/vector.toml"]
2023-02-28T13:07:03.669451Z DEBUG vector::config::loading: No secret placeholder found, skipping secret resolution.
2023-02-28T13:07:03.670096Z DEBUG vector::topology::builder: Building new source. component=journald
2023-02-28T13:07:03.670366Z DEBUG vector::topology::builder: Building new sink. component=cloudwatch_logs
2023-02-28T13:07:03.678088Z DEBUG aws_config::fs_util: loaded home directory src="HOME"
2023-02-28T13:07:03.678138Z DEBUG load_config_file{file=Default(Config)}: aws_config::profile::parser::source: performing home directory substitution home="/var/lib/vector" path="~/.aws/config"
2023-02-28T13:07:03.678175Z DEBUG load_config_file{file=Default(Config)}: aws_config::profile::parser::source: home directory expanded before="~/.aws/config" after="/var/lib/vector/.aws/config"
2023-02-28T13:07:03.678201Z DEBUG load_config_file{file=Default(Config)}: aws_config::profile::parser::source: config file not found path=~/.aws/config
2023-02-28T13:07:03.678217Z DEBUG load_config_file{file=Default(Config)}: aws_config::profile::parser::source: config file loaded path=Some("/var/lib/vector/.aws/config") size=0
2023-02-28T13:07:03.678239Z DEBUG load_config_file{file=Default(Credentials)}: aws_config::profile::parser::source: performing home directory substitution home="/var/lib/vector" path="~/.aws/credentials"
2023-02-28T13:07:03.678249Z DEBUG load_config_file{file=Default(Credentials)}: aws_config::profile::parser::source: home directory expanded before="~/.aws/credentials" after="/var/lib/vector/.aws/credentials"
2023-02-28T13:07:03.678268Z DEBUG load_config_file{file=Default(Credentials)}: aws_config::profile::parser::source: config file not found path=~/.aws/credentials
2023-02-28T13:07:03.678277Z DEBUG load_config_file{file=Default(Credentials)}: aws_config::profile::parser::source: config file loaded path=Some("/var/lib/vector/.aws/credentials") size=0
2023-02-28T13:07:03.696523Z DEBUG vector_core::tls::settings: Fetching system root certs.
2023-02-28T13:07:03.702621Z DEBUG vector_core::tls::settings: Fetching system root certs.
2023-02-28T13:07:03.719496Z DEBUG vector_core::tls::settings: Fetching system root certs.
2023-02-28T13:07:03.725626Z DEBUG vector_core::tls::settings: Fetching system root certs.
2023-02-28T13:07:03.732238Z  INFO vector::topology::running: Running healthchecks.
2023-02-28T13:07:03.732298Z DEBUG vector::topology::running: Connecting changed/added component(s).
2023-02-28T13:07:03.732325Z DEBUG vector::topology::running: Configuring outputs for source. component=journald
2023-02-28T13:07:03.732371Z DEBUG vector::topology::running: Configuring output for component. component=journald output_id=None
2023-02-28T13:07:03.732406Z DEBUG vector::topology::running: Connecting inputs for sink. component=cloudwatch_logs
2023-02-28T13:07:03.732434Z DEBUG vector::topology::running: Adding component input to fanout. component=cloudwatch_logs fanout_id=journald
2023-02-28T13:07:03.732479Z DEBUG vector::topology::running: Spawning new source. key=journald
2023-02-28T13:07:03.732530Z DEBUG vector::topology::running: Registered new allocation group. component_kind="source" component_type="journald" component_id="journald" group_id="2"
2023-02-28T13:07:03.732584Z DEBUG vector::topology::running: Registered new allocation group. component_kind="sink" component_type="aws_cloudwatch_logs" component_id="cloudwatch_logs" group_id="3"
2023-02-28T13:07:03.732704Z DEBUG send_operation{operation="DescribeLogGroups" service="cloudwatchlogs"}:async_map_request{name="retrieve_credentials"}:lazy_load_credentials: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: "environment variable not set" }))
2023-02-28T13:07:03.732812Z  INFO vector: Vector has started. debug="false" version="0.28.0" arch="x86_64" revision="971c594 2023-02-27"
2023-02-28T13:07:03.732830Z DEBUG send_operation{operation="DescribeLogGroups" service="cloudwatchlogs"}:async_map_request{name="retrieve_credentials"}:lazy_load_credentials:provide_credentials{provider=default_chain}:load_credentials{provider=Profile}: aws_config::fs_util: loaded home directory src="HOME"
2023-02-28T13:07:03.732841Z  INFO vector::app: API is disabled, enable by setting `api.enabled` to `true` and use commands like `vector top`.
2023-02-28T13:07:03.732854Z DEBUG send_operation{operation="DescribeLogGroups" service="cloudwatchlogs"}:async_map_request{name="retrieve_credentials"}:lazy_load_credentials:provide_credentials{provider=default_chain}:load_credentials{provider=Profile}:load_config_file{file=Default(Config)}: aws_config::profile::parser::source: performing home directory substitution home="/var/lib/vector" path="~/.aws/config"
2023-02-28T13:07:03.732870Z DEBUG send_operation{operation="DescribeLogGroups" service="cloudwatchlogs"}:async_map_request{name="retrieve_credentials"}:lazy_load_credentials:provide_credentials{provider=default_chain}:load_credentials{provider=Profile}:load_config_file{file=Default(Config)}: aws_config::profile::parser::source: home directory expanded before="~/.aws/config" after="/var/lib/vector/.aws/config"
2023-02-28T13:07:03.732896Z DEBUG send_operation{operation="DescribeLogGroups" service="cloudwatchlogs"}:async_map_request{name="retrieve_credentials"}:lazy_load_credentials:provide_credentials{provider=default_chain}:load_credentials{provider=Profile}:load_config_file{file=Default(Config)}: aws_config::profile::parser::source: config file not found path=~/.aws/config
2023-02-28T13:07:03.732908Z DEBUG send_operation{operation="DescribeLogGroups" service="cloudwatchlogs"}:async_map_request{name="retrieve_credentials"}:lazy_load_credentials:provide_credentials{provider=default_chain}:load_credentials{provider=Profile}:load_config_file{file=Default(Config)}: aws_config::profile::parser::source: config file loaded path=Some("/var/lib/vector/.aws/config") size=0
2023-02-28T13:07:03.732891Z DEBUG source{component_kind="source" component_id=journald component_type=journald component_name=journald}: vector::topology::builder: Source pump supervisor starting.
2023-02-28T13:07:03.732935Z DEBUG send_operation{operation="DescribeLogGroups" service="cloudwatchlogs"}:async_map_request{name="retrieve_credentials"}:lazy_load_credentials:provide_credentials{provider=default_chain}:load_credentials{provider=Profile}:load_config_file{file=Default(Credentials)}: aws_config::profile::parser::source: performing home directory substitution home="/var/lib/vector" path="~/.aws/credentials"
2023-02-28T13:07:03.732948Z DEBUG send_operation{operation="DescribeLogGroups" service="cloudwatchlogs"}:async_map_request{name="retrieve_credentials"}:lazy_load_credentials:provide_credentials{provider=default_chain}:load_credentials{provider=Profile}:load_config_file{file=Default(Credentials)}: aws_config::profile::parser::source: home directory expanded before="~/.aws/credentials" after="/var/lib/vector/.aws/credentials"
2023-02-28T13:07:03.732968Z DEBUG send_operation{operation="DescribeLogGroups" service="cloudwatchlogs"}:async_map_request{name="retrieve_credentials"}:lazy_load_credentials:provide_credentials{provider=default_chain}:load_credentials{provider=Profile}:load_config_file{file=Default(Credentials)}: aws_config::profile::parser::source: config file not found path=~/.aws/credentials
2023-02-28T13:07:03.732979Z DEBUG source{component_kind="source" component_id=journald component_type=journald component_name=journald}: vector::topology::builder: Source pump starting.
2023-02-28T13:07:03.732978Z DEBUG send_operation{operation="DescribeLogGroups" service="cloudwatchlogs"}:async_map_request{name="retrieve_credentials"}:lazy_load_credentials:provide_credentials{provider=default_chain}:load_credentials{provider=Profile}:load_config_file{file=Default(Credentials)}: aws_config::profile::parser::source: config file loaded path=Some("/var/lib/vector/.aws/credentials") size=0
2023-02-28T13:07:03.733000Z DEBUG source{component_kind="source" component_id=journald component_type=journald component_name=journald}: vector::topology::builder: Source starting.
2023-02-28T13:07:03.733009Z DEBUG send_operation{operation="DescribeLogGroups" service="cloudwatchlogs"}:async_map_request{name="retrieve_credentials"}:lazy_load_credentials:provide_credentials{provider=default_chain}: aws_config::meta::credentials::chain: provider in chain did not provide credentials provider=Profile context=the credential provider was not enabled: No profiles were defined (CredentialsNotLoaded(CredentialsNotLoaded { source: NoProfilesDefined }))
2023-02-28T13:07:03.733044Z DEBUG send_operation{operation="DescribeLogGroups" service="cloudwatchlogs"}:async_map_request{name="retrieve_credentials"}:lazy_load_credentials:provide_credentials{provider=default_chain}: aws_config::meta::credentials::chain: provider in chain did not provide credentials provider=WebIdentityToken context=the credential provider was not enabled: $AWS_WEB_IDENTITY_TOKEN_FILE was not set (CredentialsNotLoaded(CredentialsNotLoaded { source: "$AWS_WEB_IDENTITY_TOKEN_FILE was not set" }))
2023-02-28T13:07:03.733069Z DEBUG send_operation{operation="DescribeLogGroups" service="cloudwatchlogs"}:async_map_request{name="retrieve_credentials"}:lazy_load_credentials:provide_credentials{provider=default_chain}: aws_config::meta::credentials::chain: provider in chain did not provide credentials provider=EcsContainer context=the credential provider was not enabled: ECS provider not configured (CredentialsNotLoaded(CredentialsNotLoaded { source: "ECS provider not configured" }))
2023-02-28T13:07:03.733082Z DEBUG send_operation{operation="DescribeLogGroups" service="cloudwatchlogs"}:async_map_request{name="retrieve_credentials"}:lazy_load_credentials:provide_credentials{provider=default_chain}:load_credentials{provider=Ec2InstanceMetadata}: aws_config::imds::credentials: loading credentials from IMDS
2023-02-28T13:07:03.733143Z DEBUG sink{component_kind="sink" component_id=cloudwatch_logs component_type=aws_cloudwatch_logs component_name=cloudwatch_logs}: vector::topology::builder: Sink starting.
2023-02-28T13:07:03.733424Z DEBUG send_operation{operation="DescribeLogGroups" service="cloudwatchlogs"}:async_map_request{name="retrieve_credentials"}:lazy_load_credentials:provide_credentials{provider=default_chain}:load_credentials{provider=Ec2InstanceMetadata}:send_operation{operation="get" service="imds"}:async_map_request{name="attach_imds_token"}:send_operation{operation="get-token" service="imds"}:dispatch: hyper::client::connect::http: connecting to 169.254.169.254:80
2023-02-28T13:07:03.733791Z DEBUG sink{component_kind="sink" component_id=cloudwatch_logs component_type=aws_cloudwatch_logs component_name=cloudwatch_logs}: vector::utilization: utilization=0.23245269692928106
2023-02-28T13:07:03.733853Z DEBUG send_operation{operation="DescribeLogGroups" service="cloudwatchlogs"}:async_map_request{name="retrieve_credentials"}:lazy_load_credentials:provide_credentials{provider=default_chain}:load_credentials{provider=Ec2InstanceMetadata}:send_operation{operation="get" service="imds"}:async_map_request{name="attach_imds_token"}:send_operation{operation="get-token" service="imds"}:dispatch: hyper::client::connect::http: connected to 169.254.169.254:80
2023-02-28T13:07:03.733911Z  INFO source{component_kind="source" component_id=journald component_type=journald component_name=journald}: vector::sources::journald: Starting journalctl.
2023-02-28T13:07:03.734088Z DEBUG hyper::proto::h1::io: flushed 242 bytes
2023-02-28T13:07:03.735492Z DEBUG hyper::proto::h1::io: parsed 6 headers
2023-02-28T13:07:03.735513Z DEBUG hyper::proto::h1::conn: incoming body is content-length (56 bytes)
2023-02-28T13:07:03.735546Z DEBUG hyper::proto::h1::conn: incoming body completed
2023-02-28T13:07:03.735780Z DEBUG send_operation{operation="DescribeLogGroups" service="cloudwatchlogs"}:async_map_request{name="retrieve_credentials"}:lazy_load_credentials:provide_credentials{provider=default_chain}:load_credentials{provider=Ec2InstanceMetadata}:send_operation{operation="get" service="imds"}:dispatch: hyper::client::connect::http: connecting to 169.254.169.254:80
2023-02-28T13:07:03.735957Z DEBUG send_operation{operation="DescribeLogGroups" service="cloudwatchlogs"}:async_map_request{name="retrieve_credentials"}:lazy_load_credentials:provide_credentials{provider=default_chain}:load_credentials{provider=Ec2InstanceMetadata}:send_operation{operation="get" service="imds"}:dispatch: hyper::client::connect::http: connected to 169.254.169.254:80
2023-02-28T13:07:03.736040Z DEBUG hyper::proto::h1::io: flushed 307 bytes
2023-02-28T13:07:03.736928Z DEBUG hyper::proto::h1::io: parsed 8 headers
2023-02-28T13:07:03.736938Z DEBUG hyper::proto::h1::conn: incoming body is content-length (21 bytes)
2023-02-28T13:07:03.736948Z DEBUG hyper::proto::h1::conn: incoming body completed
2023-02-28T13:07:03.737027Z DEBUG send_operation{operation="DescribeLogGroups" service="cloudwatchlogs"}:async_map_request{name="retrieve_credentials"}:lazy_load_credentials:provide_credentials{provider=default_chain}:load_credentials{provider=Ec2InstanceMetadata}: aws_config::imds::credentials: loaded profile profile=export-s3-kinesis-dev
2023-02-28T13:07:03.737089Z DEBUG send_operation{operation="DescribeLogGroups" service="cloudwatchlogs"}:async_map_request{name="retrieve_credentials"}:lazy_load_credentials:provide_credentials{provider=default_chain}:load_credentials{provider=Ec2InstanceMetadata}:send_operation{operation="get" service="imds"}:dispatch: hyper::client::connect::http: connecting to 169.254.169.254:80
2023-02-28T13:07:03.737232Z DEBUG send_operation{operation="DescribeLogGroups" service="cloudwatchlogs"}:async_map_request{name="retrieve_credentials"}:lazy_load_credentials:provide_credentials{provider=default_chain}:load_credentials{provider=Ec2InstanceMetadata}:send_operation{operation="get" service="imds"}:dispatch: hyper::client::connect::http: connected to 169.254.169.254:80
2023-02-28T13:07:03.737289Z DEBUG hyper::proto::h1::io: flushed 328 bytes
2023-02-28T13:07:03.737976Z DEBUG hyper::proto::h1::io: parsed 8 headers
2023-02-28T13:07:03.737983Z DEBUG hyper::proto::h1::conn: incoming body is content-length (1586 bytes)
2023-02-28T13:07:03.737991Z DEBUG hyper::proto::h1::conn: incoming body completed
2023-02-28T13:07:03.738082Z DEBUG send_operation{operation="DescribeLogGroups" service="cloudwatchlogs"}:async_map_request{name="retrieve_credentials"}:lazy_load_credentials:provide_credentials{provider=default_chain}: aws_config::meta::credentials::chain: loaded credentials provider=Ec2InstanceMetadata
2023-02-28T13:07:03.738097Z  INFO send_operation{operation="DescribeLogGroups" service="cloudwatchlogs"}:async_map_request{name="retrieve_credentials"}: aws_credential_types::cache::lazy_caching: credentials cache miss occurred; retrieved new AWS credentials (took 5.422127ms)
2023-02-28T13:07:03.738364Z DEBUG hyper::client::connect::dns: resolving host="logs.us-east-1.amazonaws.com"
2023-02-28T13:07:03.739406Z DEBUG send_operation{operation="DescribeLogGroups" service="cloudwatchlogs"}:dispatch: hyper::client::connect::http: connecting to 10.24.74.235:443
2023-02-28T13:07:03.741290Z DEBUG send_operation{operation="DescribeLogGroups" service="cloudwatchlogs"}:dispatch: hyper::client::connect::http: connected to 10.24.74.235:443
2023-02-28T13:07:03.745742Z DEBUG hyper::proto::h1::io: flushed 2027 bytes
2023-02-28T13:07:03.760493Z DEBUG hyper::proto::h1::io: parsed 5 headers
2023-02-28T13:07:03.760524Z DEBUG hyper::proto::h1::conn: incoming body is content-length (229 bytes)
2023-02-28T13:07:03.760550Z DEBUG hyper::proto::h1::conn: incoming body completed
2023-02-28T13:07:03.760914Z ERROR vector::topology::builder: msg="Healthcheck failed." error=DescribeLogGroups failed: service error component_kind="sink" component_type="aws_cloudwatch_logs" component_id=cloudwatch_logs component_name=cloudwatch_logs
2023-02-28T13:07:04.748483Z DEBUG sink{component_kind="sink" component_id=cloudwatch_logs component_type=aws_cloudwatch_logs component_name=cloudwatch_logs}:request{request_id=1}: tower::buffer::worker: service.ready=true processing request
2023-02-28T13:07:04.748555Z DEBUG sink{component_kind="sink" component_id=cloudwatch_logs component_type=aws_cloudwatch_logs component_name=cloudwatch_logs}:request{request_id=1}: tower::buffer::worker: service.ready=true processing request
2023-02-28T13:07:04.748576Z  INFO sink{component_kind="sink" component_id=cloudwatch_logs component_type=aws_cloudwatch_logs component_name=cloudwatch_logs}:request{request_id=1}: vector::sinks::aws_cloudwatch_logs::service: Sending events. events=1
2023-02-28T13:07:04.748689Z DEBUG sink{component_kind="sink" component_id=cloudwatch_logs component_type=aws_cloudwatch_logs component_name=cloudwatch_logs}:request{request_id=1}:send_operation{operation="DescribeLogStreams" service="cloudwatchlogs"}:async_map_request{name="retrieve_credentials"}: aws_credential_types::cache::lazy_caching: loaded credentials from cache
2023-02-28T13:07:04.748882Z DEBUG hyper::client::connect::dns: resolving host="logs.us-east-1.amazonaws.com"
2023-02-28T13:07:04.751857Z DEBUG sink{component_kind="sink" component_id=cloudwatch_logs component_type=aws_cloudwatch_logs component_name=cloudwatch_logs}:request{request_id=1}:send_operation{operation="DescribeLogStreams" service="cloudwatchlogs"}:dispatch: hyper::client::connect::http: connecting to 10.24.74.235:443
2023-02-28T13:07:04.753458Z DEBUG sink{component_kind="sink" component_id=cloudwatch_logs component_type=aws_cloudwatch_logs component_name=cloudwatch_logs}:request{request_id=1}:send_operation{operation="DescribeLogStreams" service="cloudwatchlogs"}:dispatch: hyper::client::connect::http: connected to 10.24.74.235:443
2023-02-28T13:07:04.756574Z DEBUG hyper::proto::h1::io: flushed 2051 bytes
2023-02-28T13:07:04.760384Z DEBUG hyper::proto::h1::io: parsed 5 headers
2023-02-28T13:07:04.760398Z DEBUG hyper::proto::h1::conn: incoming body is content-length (229 bytes)
2023-02-28T13:07:04.760420Z DEBUG hyper::proto::h1::conn: incoming body completed
2023-02-28T13:07:04.760874Z ERROR sink{component_kind="sink" component_id=cloudwatch_logs component_type=aws_cloudwatch_logs component_name=cloudwatch_logs}:request{request_id=1}: vector::sinks::util::retries: Non-retriable error; dropping the request. error=CloudwatchError::Describe: service error internal_log_rate_limit=true
2023-02-28T13:07:04.760896Z ERROR sink{component_kind="sink" component_id=cloudwatch_logs component_type=aws_cloudwatch_logs component_name=cloudwatch_logs}:request{request_id=1}: vector::sinks::util::retries: Internal log [Non-retriable error; dropping the request.] is being rate limited.
2023-02-28T13:07:04.760964Z ERROR sink{component_kind="sink" component_id=cloudwatch_logs component_type=aws_cloudwatch_logs component_name=cloudwatch_logs}:request{request_id=1}: vector_common::internal_event::service: Service call failed. No retries or retries exhausted. error=Some(Describe(ServiceError(ServiceError { source: DescribeLogStreamsError { kind: Unhandled(Unhandled { source: Error { code: Some("InvalidSignatureException"), message: Some("The request signature we calculated does not match the signature you provided. Check your AWS Secret Access Key and signing method. Consult the service documentation for details."), request_id: Some("32115e36-1bec-4aab-ba30-5a5772f166d8"), extras: {} } }), meta: Error { code: Some("InvalidSignatureException"), message: Some("The request signature we calculated does not match the signature you provided. Check your AWS Secret Access Key and signing method. Consult the service documentation for details."), request_id: Some("32115e36-1bec-4aab-ba30-5a5772f166d8"), extras: {} } }, raw: Response { inner: Response { status: 400, version: HTTP/1.1, headers: {"x-amzn-requestid": "32115e36-1bec-4aab-ba30-5a5772f166d8", "content-type": "application/x-amz-json-1.1", "content-length": "229", "date": "Tue, 28 Feb 2023 13:07:04 GMT", "connection": "close"}, body: SdkBody { inner: Once(Some(b"{\"__type\":\"InvalidSignatureException\",\"message\":\"The request signature we calculated does not match the signature you provided. Check your AWS Secret Access Key and signing method. Consult the service documentation for details.\"}")), retryable: true } }, properties: SharedPropertyBag(Mutex { data: PropertyBag, poisoned: false, .. }) } }))) request_id=1 error_type="request_failed" stage="sending" internal_log_rate_limit=true
2023-02-28T13:07:04.761018Z ERROR sink{component_kind="sink" component_id=cloudwatch_logs component_type=aws_cloudwatch_logs component_name=cloudwatch_logs}:request{request_id=1}: vector_common::internal_event::component_events_dropped: Events dropped intentional=false count=1 reason="Service call failed. No retries or retries exhausted." internal_log_rate_limit=true
2023-02-28T13:07:08.734221Z DEBUG sink{component_kind="sink" component_id=cloudwatch_logs component_type=aws_cloudwatch_logs component_name=cloudwatch_logs}: vector::utilization: utilization=0.023258036189545455
2023-02-28T13:07:13.734358Z DEBUG sink{component_kind="sink" component_id=cloudwatch_logs component_type=aws_cloudwatch_logs component_name=cloudwatch_logs}: vector::utilization: utilization=0.0023260383324464873
2023-02-28T13:07:18.734162Z DEBUG sink{component_kind="sink" component_id=cloudwatch_logs component_type=aws_cloudwatch_logs component_name=cloudwatch_logs}: vector::utilization: utilization=0.00023275809930297628
2023-02-28T13:07:23.734235Z DEBUG sink{component_kind="sink" component_id=cloudwatch_logs component_type=aws_cloudwatch_logs component_name=cloudwatch_logs}: vector::utilization: utilization=0.00002347470701020368
2023-02-28T13:07:28.734034Z DEBUG sink{component_kind="sink" component_id=cloudwatch_logs component_type=aws_cloudwatch_logs component_name=cloudwatch_logs}: vector::utilization: utilization=0.000002473295716926779

samidalouche Feb 28, 2023
Author

"The request signature we calculated does not match the signature you provided. Check your AWS Secret Access Key and signing method. Consult the service documentation for details."

2023-02-28T13:07:04.760420Z DEBUG hyper::proto::h1::conn: incoming body completed
2023-02-28T13:07:04.760874Z ERROR sink{component_kind="sink" component_id=cloudwatch_logs component_type=aws_cloudwatch_logs component_name=cloudwatch_logs}:request{request_id=1}: vector::sinks::util::retries: Non-retriable error; dropping the request. error=CloudwatchError::Describe: service error internal_log_rate_limit=true
2023-02-28T13:07:04.760896Z ERROR sink{component_kind="sink" component_id=cloudwatch_logs component_type=aws_cloudwatch_logs component_name=cloudwatch_logs}:request{request_id=1}: vector::sinks::util::retries: Internal log [Non-retriable error; dropping the request.] is being rate limited.
2023-02-28T13:07:04.760964Z ERROR sink{component_kind="sink" component_id=cloudwatch_logs component_type=aws_cloudwatch_logs component_name=cloudwatch_logs}:request{request_id=1}: vector_common::internal_event::service: Service call failed. No retries or retries exhausted. error=Some(Describe(ServiceError(ServiceError { source: DescribeLogStreamsError { kind: Unhandled(Unhandled { source: Error { code: Some("InvalidSignatureException"), message: Some("The request signature we calculated does not match the signature you provided. Check your AWS Secret Access Key and signing method. Consult the service documentation for details."), request_id: Some("32115e36-1bec-4aab-ba30-5a5772f166d8"), extras: {} } }), meta: Error { code: Some("InvalidSignatureException"), message: Some("The request signature we calculated does not match the signature you provided. Check your AWS Secret Access Key and signing method. Consult the service documentation for details."), request_id: Some("32115e36-1bec-4aab-ba30-5a5772f166d8"), extras: {} } }, raw: Response { inner: Response { status: 400, version: HTTP/1.1, headers: {"x-amzn-requestid": "32115e36-1bec-4aab-ba30-5a5772f166d8", "content-type": "application/x-amz-json-1.1", "content-length": "229", "date": "Tue, 28 Feb 2023 13:07:04 GMT", "connection": "close"}, body: SdkBody { inner: Once(Some(b"{\"__type\":\"InvalidSignatureException\",\"message\":\"The request signature we calculated does not match the signature you provided. Check your AWS Secret Access Key and signing method. Consult the service documentation for details.\"}")), retryable: true } }, properties: SharedPropertyBag(Mutex { data: PropertyBag, poisoned: false, .. }) } }))) request_id=1 error_type="request_failed" stage="sending" internal_log_rate_limit=true
2023-02-28T13:07:04.761018Z ERROR sink{component_kind="sink" component_id=cloudwatch_logs component_type=aws_cloudwatch_logs component_name=cloudwatch_logs}:request{request_id=1}: vector_common::internal_event::component_events_dropped: Events dropped intentional=false count=1 reason="Service call failed. No retries or retries exhausted." internal_log_rate_limit=true

rnhurt · 2023-02-28T14:50:38Z

rnhurt
Feb 28, 2023

I'm having a similar issue with DescribeLogGroups failing the healthcheck (#16629).

I'm running AL2 on a Gravaton (ARM) EC2 instance, if that helps.

0 replies

samidalouche · 2023-02-28T15:05:55Z

samidalouche
Feb 28, 2023
Author

I rebuilt using the machine using

yum install -y vector-0.27.1-1

And everything works fine now.. So definitely a regression

1 reply

rnhurt Feb 28, 2023

I did the same on my system and it's working correctly now.

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

How to debug the aws_cloudwatch_logs sink? #16627

{{title}}

{{editor}}'s edit

{{editor}}'s edit

Replies: 3 comments 6 replies

{{title}}

{{title}}

{{title}}

{{title}}

{{title}}

{{title}}

{{editor}}'s edit

{{editor}}'s edit

{{title}}

{{title}}

{{title}}

Select a reply

How to debug the aws_cloudwatch_logs sink? #16627

samidalouche Feb 28, 2023

Replies: 3 comments · 6 replies

jszwedko Feb 28, 2023 Maintainer

samidalouche Feb 28, 2023 Author

jszwedko Feb 28, 2023 Maintainer

samidalouche Feb 28, 2023 Author

samidalouche Feb 28, 2023 Author

samidalouche Feb 28, 2023 Author

rnhurt Feb 28, 2023

samidalouche Feb 28, 2023 Author

rnhurt Feb 28, 2023

samidalouche
Feb 28, 2023

Replies: 3 comments 6 replies

jszwedko
Feb 28, 2023
Maintainer

samidalouche Feb 28, 2023
Author

jszwedko Feb 28, 2023
Maintainer

samidalouche Feb 28, 2023
Author

samidalouche Feb 28, 2023
Author

samidalouche Feb 28, 2023
Author

rnhurt
Feb 28, 2023

samidalouche
Feb 28, 2023
Author