S3 sink stopped working in 0.22 and lost events

[akunszt]

A note for the community

• Please vote on this issue by adding a 👍 reaction to the original issue to help the community and maintainers prioritize this request
• If you are interested in working on this issue or have submitted a pull request, please leave a comment

Problem

We are using Vector to archive incoming syslog messages on S3. After we upgraded from 0.20.0 to 0.22.2 the S3 sink stopped working and Vector dropped every incoming event. It received the events, put them into a disk buffer - which can't be too big because of the insane memory requirement on startup, but that's another issue -, tried to send them to S3, failed with the following error message and then dropped the events/cleared the disk buffer. We lost a few days of events before we noticed that they are missing from the archive.

2022-06-17T08:45:19.883623Z ERROR vector::topology::builder: msg="Healthcheck: Failed Reason." error=failed to construct request: Failed to load credentials from the credentials provider: An error occurred while loading credentials: Error response from IMDS (code: 301). Response { status: 301, version: HTTP/1.1, headers: {"content-type": "text/html; charset=utf-8", "location": "/latest/meta-data/iam/security-credentials/", "date": "Fri, 17 Jun 2022 08:45:19 GMT", "content-length": "78"}, body: SdkBody { inner: Once(Some(b"<a href=\"/latest/meta-data/iam/security-credentials/\">Moved Permanently</a>.\n\n")), retryable: true } } component_kind="sink" component_type="aws_s3" component_id=s3_archive component_name=s3_archive

The strange thing that if I curl the same URL from the pod then it works.

~ # curl -v http://169.254.169.254/latest/meta-data/iam/security-credentials/ ; echo
*   Trying 169.254.169.254:80...
* Connected to 169.254.169.254 (169.254.169.254) port 80 (#0)
> GET /latest/meta-data/iam/security-credentials/ HTTP/1.1
> Host: 169.254.169.254
> User-Agent: curl/7.79.1
> Accept: */*
> 
* Mark bundle as not supporting multiuse
< HTTP/1.1 200 OK
< Date: Fri, 17 Jun 2022 08:46:59 GMT
< Content-Length: 94
< Content-Type: text/plain; charset=utf-8
< 
* Connection #0 to host 169.254.169.254 left intact
arn:aws:iam::1234567890abcd:role/role-name

We enabled both IMDSv1 AND v2 on the instance. We are using KIAM which intercepts the requests sent to the IMDS but this setup was working fine in 0.20.0.

Also we are very worried about the silent loss of the events. We expected that the buffer won't be emptied if the destination is not available/reachable. We think this is the real issue. In the future we will migrate away from KIAM so if 0.22.2 and onwards doesn't support that setup anymore then we can live with it and use 0.20.0 for a while but the silent data loss is frightening.

Configuration

data_dir = "/var/lib/vector"

[api]
enabled = false

### sources
[sources.internal_metrics]
type = "internal_metrics"
scrape_interval_secs = 5

[sources.syslog]
type = "syslog"
address = "0.0.0.0:601"
connection_limit = 200
keepalive = { time_secs = 50 }
max_length = 102400
mode = "tcp"

### transforms

### sinks
[sinks.prometheus_exporter]
type = "prometheus_exporter"
inputs = [ "internal_metrics" ]
address = "0.0.0.0:9090"
flush_period_secs = 60

[sinks.s3_archive]
type = "aws_s3"
inputs = [ "syslog" ]
batch = { max_bytes = 536870912, timeout_secs = 600 }
bucket = "our-bucket"
buffer = { max_size = 1073741824, type = "disk", when_full = "block" }
compression = "gzip"
encoding = { codec = "text", timestamp_format = "rfc3339" }
filename_time_format = "%T"
healthcheck = { enabled = true }
key_prefix = "logs/foobar/year=%Y/month=%m/day=%d/"
region = "us-west-2"
server_side_encryption = "aws:kms"
ssekms_key_id = "alias/log-archive"

Version

vector 0.22.2 (x86_64-unknown-linux-musl 0024c92 2022-06-15)

Debug Output

No response

Example Data

No response

Additional Context

Vector is running in Kubernetes and uses EC2 instance roles which are provided by KIAM.

References

No response

[jszwedko]

Hi @akunszt !

Apologies that you ran into this. I can't see any difference between 0.22.0 and 0.22.2 that would have affected AWS credentials fetching. Is there any chance you could try reproducing again in isolation with VECTOR_LOG=aws_config=debug? That should print debug logs about the credentials fetching to help narrow down the issue.

Regarding the lost events, that is something that we are going to be putting a focus on over the next quarter by shoring up Vector's delivery guarantees. Vector used to prefer availability over delivery guarantees by not blocking on failed requests, but we have been switching the focus to be on guaranteeing delivery instead as it has become more clear that this is preferred in most cases. For example, there is some work happening now to avoid dropping events from the disk buffer if they are not successfully acknowledged (#12145) which would have affected this case. I feel bad you ran into it unexpectedly though, that is very unfortunate. In the mean time, I'd recommend monitoring component_received_events_total and components_sent_events_total for your sinks. Those numbers should match up (with some delay).

[akunszt]

Hi @jszwedko !

Thank you for the response. The S3 sink is working in 0.20.0 not in 0.22.0, so checking the difference between 0.22.0 and 0.22.2 is not useful in this case.

In 0.20.0 the VECTOR_LOG=aws_config=debug didn't create any output.
In 0.22.2 I received this:

2022-06-21T15:09:44.896310Z  INFO provide_credentials{provider=default_chain}: aws_config::meta::credentials::chain: provider in chain did not provide credentials provider=Environment context=environment variable not set
2022-06-21T15:09:44.896352Z DEBUG provide_credentials{provider=default_chain}:load_credentials{provider=Profile}: aws_config::fs_util: loaded home directory src="HOME"
2022-06-21T15:09:44.896368Z DEBUG provide_credentials{provider=default_chain}:load_credentials{provider=Profile}:load_config_file: aws_config::profile::parser::source: performing home directory substitution home="/root" path="~/.aws/config"
2022-06-21T15:09:44.896379Z DEBUG provide_credentials{provider=default_chain}:load_credentials{provider=Profile}:load_config_file: aws_config::profile::parser::source: home directory expanded before="~/.aws/config" after="/root/.aws/config"
2022-06-21T15:09:44.896429Z DEBUG provide_credentials{provider=default_chain}:load_credentials{provider=Profile}:load_config_file: aws_config::profile::parser::source: config file not found path=~/.aws/config
2022-06-21T15:09:44.896447Z DEBUG provide_credentials{provider=default_chain}:load_credentials{provider=Profile}:load_config_file: aws_config::profile::parser::source: config file loaded path=~/.aws/config size=0
2022-06-21T15:09:44.896458Z DEBUG provide_credentials{provider=default_chain}:load_credentials{provider=Profile}:load_credentials_file: aws_config::profile::parser::source: performing home directory substitution home="/root" path="~/.aws/credentials"
2022-06-21T15:09:44.896477Z DEBUG provide_credentials{provider=default_chain}:load_credentials{provider=Profile}:load_credentials_file: aws_config::profile::parser::source: home directory expanded before="~/.aws/credentials" after="/root/.aws/credentials"
2022-06-21T15:09:44.896487Z DEBUG provide_credentials{provider=default_chain}:load_credentials{provider=Profile}:load_credentials_file: aws_config::profile::parser::source: config file not found path=~/.aws/credentials
2022-06-21T15:09:44.896493Z DEBUG provide_credentials{provider=default_chain}:load_credentials{provider=Profile}:load_credentials_file: aws_config::profile::parser::source: config file loaded path=~/.aws/credentials size=0
2022-06-21T15:09:44.896511Z  INFO provide_credentials{provider=default_chain}: aws_config::meta::credentials::chain: provider in chain did not provide credentials provider=Profile context=No profiles were defined
2022-06-21T15:09:44.896529Z  INFO provide_credentials{provider=default_chain}: aws_config::meta::credentials::chain: provider in chain did not provide credentials provider=WebIdentityToken context=$AWS_WEB_IDENTITY_TOKEN_FILE was not set
2022-06-21T15:09:44.896543Z  INFO provide_credentials{provider=default_chain}: aws_config::meta::credentials::chain: provider in chain did not provide credentials provider=EcsContainer context=ECS provider not configured
2022-06-21T15:09:44.896558Z DEBUG provide_credentials{provider=default_chain}:load_credentials{provider=Ec2InstanceMetadata}: aws_config::imds::credentials: loading credentials from IMDS
2022-06-21T15:09:44.896567Z DEBUG provide_credentials{provider=default_chain}:load_credentials{provider=Ec2InstanceMetadata}: aws_config::fs_util: loaded home directory src="HOME"
2022-06-21T15:09:44.896576Z DEBUG provide_credentials{provider=default_chain}:load_credentials{provider=Ec2InstanceMetadata}:load_config_file: aws_config::profile::parser::source: performing home directory substitution home="/root" path="~/.aws/config"
2022-06-21T15:09:44.896585Z DEBUG provide_credentials{provider=default_chain}:load_credentials{provider=Ec2InstanceMetadata}:load_config_file: aws_config::profile::parser::source: home directory expanded before="~/.aws/config" after="/root/.aws/config"
2022-06-21T15:09:44.896595Z DEBUG provide_credentials{provider=default_chain}:load_credentials{provider=Ec2InstanceMetadata}:load_config_file: aws_config::profile::parser::source: config file not found path=~/.aws/config
2022-06-21T15:09:44.896609Z DEBUG provide_credentials{provider=default_chain}:load_credentials{provider=Ec2InstanceMetadata}:load_config_file: aws_config::profile::parser::source: config file loaded path=~/.aws/config size=0
2022-06-21T15:09:44.896619Z DEBUG provide_credentials{provider=default_chain}:load_credentials{provider=Ec2InstanceMetadata}:load_credentials_file: aws_config::profile::parser::source: performing home directory substitution home="/root" path="~/.aws/credentials"
2022-06-21T15:09:44.896628Z DEBUG provide_credentials{provider=default_chain}:load_credentials{provider=Ec2InstanceMetadata}:load_credentials_file: aws_config::profile::parser::source: home directory expanded before="~/.aws/credentials" after="/root/.aws/credentials"
2022-06-21T15:09:44.896644Z DEBUG provide_credentials{provider=default_chain}:load_credentials{provider=Ec2InstanceMetadata}:load_credentials_file: aws_config::profile::parser::source: config file not found path=~/.aws/credentials
2022-06-21T15:09:44.896650Z DEBUG provide_credentials{provider=default_chain}:load_credentials{provider=Ec2InstanceMetadata}:load_credentials_file: aws_config::profile::parser::source: config file loaded path=~/.aws/credentials size=0
2022-06-21T15:09:44.898362Z  WARN provide_credentials{provider=default_chain}: aws_config::meta::credentials::chain: provider failed to provide credentials provider=Ec2InstanceMetadata error=An error occurred while loading credentials: Error response from IMDS (code: 301). Response { status: 301, version: HTTP/1.1, headers: {"content-type": "text/html; charset=utf-8", "location": "/latest/meta-data/iam/security-credentials/", "date": "Tue, 21 Jun 2022 15:09:44 GMT", "content-length": "78"}, body: SdkBody { inner: Once(Some(b"<a href=\"/latest/meta-data/iam/security-credentials/\">Moved Permanently</a>.\n\n")), retryable: true } }

I don't see any new information. It tried to fetch the credentials from IMDS and it failed while the curl command in the same pod returned a real value on the /latest/meta-data/iam/security-credentials path.

About the event drop. If I understand correctly then I have to set acknowledgements.enabled=true but it won't work in this case until #12145 fixed. Did I understand it correctly?

Last but not least, thanks for the tip. We're in the beginning of introducing/evaluating Vector in various roles in our infrastructure and we don't have proper monitoring/alerting at the moment.

[jszwedko]

Thanks for adding the debug logs @akunszt ! Apologies, I misread 0.20.0 as 0.22.0 before. Version 0.21.0 swapped the AWS SDK Vector was using to the official AWS one which is likely the source of the difference you see here.

It's odd that curl (according to your curl -v output in the issue description) doesn't see the 301 redirect, but Vector does. Either way, it does seem like the SDK should be following the redirect. I'll open an issue upstream.

About the event drop. If I understand correctly then I have to set acknowledgements.enabled=true but it won't work in this case until #12145 fixed. Did I understand it correctly?

That's correct. This will be a focus of Q3 for us: to ensure that when end-to-end acknowledgements are enabled, there is no chance of data loss.

[jszwedko]

Opened issue on the AWS SDK here: awslabs/aws-sdk-rust#560

[jszwedko]

@akunszt also, could you try the latest nightly build of Vector? That is using a newer version of the AWS SDK. Binaries are here: https://packages.timber.io/vector/nightly/2022-06-21/

[rcoh]

(Hello, Russell from the Rust SDK Team): Since KIAM is deprecated I'd recommend switching to their recommended replacement.

My best guess is that the existence of the of the API token or the call to /latest/api/token is what's causing the redirect. Do you mind curling that URL and seeing that happens?

[jszwedko]

@akunszt The AWS SDK is switching to the canonical route, /latest/meta-data/iam/security-credentials/ so once we pull in that update during the next AWS SDK release, that should resolve your issue. Ref: smithy-lang/smithy-rs#1487

[akunszt]

@jszwedko and @rcoh!

Thank you for the support! We know KIAM is obsoleted and in maintenance mode only but it is still superior in a few areas to EKS Pod Identity Webhook and rely on those features widely. We are migrating away but it is a slow and tedious process as it affects all of our permissions - and we have many....

I ran a curl as you requested from the pod:

/ # curl -v http://169.254.169.254/latest/api/token
*   Trying 169.254.169.254:80...
* Connected to 169.254.169.254 (169.254.169.254) port 80 (#0)
> GET /latest/api/token HTTP/1.1
> Host: 169.254.169.254
> User-Agent: curl/7.79.1
> Accept: */*
> 
* Mark bundle as not supporting multiuse
< HTTP/1.1 405 Method Not Allowed
< Allow: OPTIONS, PUT
< Content-Length: 0
< Content-Type: text/plain
< Date: Mon, 27 Jun 2022 15:24:04 GMT
< Server: EC2ws
< 
* Connection #0 to host 169.254.169.254 left intact

[rcoh]

this needs to be PUT as the response notes in Allow:

[rcoh]

the trailing slash fix shipped today in v0.15.0!

[jszwedko]

Awesome, thanks @rcoh !

[jszwedko]

Closing as the fix for this was released in v0.23.0.