Broken auth for Elasticsearch sink after version 0.32.1

[nhlushak]

Does anyone experienced issues with authorising Elasticsearch sink after version 0.32.1?

Tried upgrading straight from 0.30.0 to 0.42.0 and my previously fine working config just not accepting auth credentials for elasticsearch in any form. Rolling back to 0.32.1 fixes it. Creds separately working well.
Found zero posts about it both in discord and github. It could not be just mine issue I am sure.

To be clear, behind opensearch sink we use AWS Opensearch 1.3 with enabled Elasticsearch 7.10 API compatibility.

[jszwedko]

Hey! I'm not seeing anything that seems relevant in the release notes for v0.33.0. Are you using AWS authentication? Can you share:

• Your configuration
• Log output

You could also try enabling debug logs for the AWS SDK by setting the VECTOR_LOG environment variable to aws_config=trace,aws_smithy_runtime=debug . This may provide more clues.

[nhlushak]

@jszwedko Of course!

I've also checked changelogs for anything related to it and did not succeed either.

Speaking of AWS SDK behaviour, I use built in basic auth for my Opensearch, so I don't think there will be anything useful.

Here is my configuration file:

# General
##########################################################
[acknowledgements]
enabled = true

[api]
enabled = true
address = "0.0.0.0:8686"
##########################################################

# Sources
##########################################################
[sources.s3-queue]
type = "aws_s3"
strategy = "sqs"
compression = "auto"
region = "${REGION:-us-west-2}"
sqs.queue_url = "${QUEUE_URL:-https://sqs.us-west-2.amazonaws.com/111111111/s3-notifications-alb-logs-prod}"
sqs.poll_secs = 20
##########################################################

# Transforms
##########################################################
[transforms.s3-events-transformed]
type = "remap"
inputs = [ "s3-queue" ]
source = '''
. = parse_json!(.message)
.env = "${ENV:-dev}"
.tag = "waf"
.timestamp = from_unix_timestamp!(.timestamp, unit: "milliseconds")

# Parse httpRequest headers to more convenient format
headers_transformed = {}

for_each(array!(.httpRequest.headers)) -> |_index, header| {
  headers_transformed = set!(headers_transformed, [downcase!(header.name)], header.value)
}

.httpRequest.headers = headers_transformed
'''
##########################################################

# Sinks
##########################################################
[sinks.opensearch]
type = "elasticsearch"
api_version = "v7"
inputs = ["s3-events-transformed"]
endpoints = ["${OPENSEARCH_ENDPOINT:-https://user:password@example.com}"]
mode = "bulk"
bulk.index = "logs-waf-v2-{{ env }}-%Y-%m-%d"
compression = "gzip"

[sinks.loki]
type = "loki"
inputs = [ "s3-events-transformed" ]
endpoint = "${LOKI_ENDPOINT:-http://127.0.0.1:3100}"
out_of_order_action = "accept"
encoding.codec = "json"
remove_timestamp = true
batch.max_bytes = 3000000
tenant_id = "{{ env }}"

[sinks.loki.labels]
tag = "{{ tag }}"
env = "{{ env }}"
action = "{{ action }}"
terminating_rule_id = "{{ terminatingRuleId }}"
country = "{{ httpRequest.country }}"
host = "{{ httpRequest.headers.host }}"
request_method = "{{ httpRequest.httpMethod }}"
http_source_name = "{{ httpSourceName }}"
http_source_id = "{{ httpSourceId }}"
webacl_id = "{{ webaclId }}"
##########################################################

# Metrics export
##########################################################
[sources.internal_metrics]
type = "internal_metrics"

[sinks.internal_metrics_exporter]
type = "prometheus_exporter"
inputs = [ "internal_metrics" ]
address = "0.0.0.0:9100"
##########################################################

# Console sink for debug purposes
##########################################################
#[sinks.console]
#type = "console"
#inputs = [ "s3-events-transformed" ]
#target = "stdout"
#encoding.codec = "json"

And here is log output running this config on 0.32.1 version:

2024-11-07T18:05:27.462761Z  INFO vector::app: Log level is enabled. level="vector=info,codec=info,vrl=info,file_source=info,tower_limit=info,rdkafka=info,buffers=info,lapin=info,kube=info"
2024-11-07T18:05:27.462782Z  WARN vector::app: DEPRECATED The openssl legacy provider provides algorithms and key sizes no longer recommended for use. Set `--openssl-legacy-provider=false` or `VECTOR_OPENSSL_LEGACY_PROVIDER=false` to disable. See https://vector.dev/highlights/2023-08-15-0-32-0-upgrade-guide/#legacy-openssl for details.
2024-11-07T18:05:27.463044Z  INFO vector::app: Loaded openssl provider. provider="legacy"
2024-11-07T18:05:27.463060Z  INFO vector::app: Loaded openssl provider. provider="default"
2024-11-07T18:05:27.463592Z  INFO vector::app: Loading configs. paths=["/etc/vector/vector.toml"]
2024-11-07T18:05:27.465716Z  WARN vector::config: Source has acknowledgements enabled by a sink, but acknowledgements are not supported by this source. Silent data loss could occur. source="internal_metrics" sink="internal_metrics_exporter"
2024-11-07T18:05:27.676191Z  INFO vector::topology::running: Running healthchecks.
2024-11-07T18:05:27.676250Z  INFO vector: Vector has started. debug="false" version="0.32.1" arch="aarch64" revision="9965884 2023-08-21 14:52:38.330227446"
2024-11-07T18:05:27.676315Z  INFO vector::topology::builder: Healthcheck passed.
2024-11-07T18:05:27.676389Z  INFO vector::sinks::prometheus::exporter: Building HTTP server. address=0.0.0.0:9100
2024-11-07T18:05:27.676806Z  INFO vector::internal_events::api: API server running. address=0.0.0.0:8686 playground=http://0.0.0.0:8686/playground
2024-11-07T18:05:27.834839Z  INFO vector::topology::builder: Healthcheck passed.
2024-11-07T18:05:27.840846Z  INFO vector::topology::builder: Healthcheck passed.

And on version 0.33.0, running with the very same config and Opensearch credentials:

2024-11-07T18:07:41.223279Z  INFO vector::app: Log level is enabled. level="vector=info,codec=info,vrl=info,file_source=info,tower_limit=info,rdkafka=info,buffers=info,lapin=info,kube=info"
2024-11-07T18:07:41.223586Z  INFO vector::app: Loading configs. paths=["/etc/vector/vector.toml"]
2024-11-07T18:07:41.225459Z  WARN vector::config: Source has acknowledgements enabled by a sink, but acknowledgements are not supported by this source. Silent data loss could occur. source="internal_metrics" sink="internal_metrics_exporter"
2024-11-07T18:07:41.335735Z  INFO vector::topology::running: Running healthchecks.
2024-11-07T18:07:41.335820Z  INFO vector: Vector has started. debug="false" version="0.33.0" arch="aarch64" revision="89605fb 2023-09-27 14:18:24.180809939"
2024-11-07T18:07:41.336397Z  INFO vector::internal_events::api: API server running. address=0.0.0.0:8686 playground=http://0.0.0.0:8686/playground
2024-11-07T18:07:41.336453Z  INFO vector::topology::builder: Healthcheck passed.
2024-11-07T18:07:41.336605Z  INFO vector::sinks::prometheus::exporter: Building HTTP server. address=0.0.0.0:9100
2024-11-07T18:07:41.494605Z  INFO vector::topology::builder: Healthcheck passed.
2024-11-07T18:07:41.497105Z ERROR vector::topology::builder: msg="Healthcheck failed." error=Unexpected status: 401 Unauthorized component_kind="sink" component_type="elasticsearch" component_id=opensearch component_name=opensearch
2024-11-07T18:07:43.947924Z ERROR sink{component_kind="sink" component_id=opensearch component_type=elasticsearch component_name=opensearch}:request{request_id=1}: vector::sinks::util::retries: Not retriable; dropping the request. reason="client-side error, 401 Unauthorized: Unauthorized" internal_log_rate_limit=true
2024-11-07T18:07:43.947954Z ERROR sink{component_kind="sink" component_id=opensearch component_type=elasticsearch component_name=opensearch}:request{request_id=1}: vector_common::internal_event::service: Service call failed. No retries or retries exhausted. error=None request_id=1 error_type="request_failed" stage="sending" internal_log_rate_limit=true
2024-11-07T18:07:43.947961Z ERROR sink{component_kind="sink" component_id=opensearch component_type=elasticsearch component_name=opensearch}:request{request_id=1}: vector_common::internal_event::component_events_dropped: Events dropped intentional=false count=1313 reason="Service call failed. No retries or retries exhausted." internal_log_rate_limit=true
2024-11-07T18:07:44.074284Z ERROR sink{component_kind="sink" component_id=opensearch component_type=elasticsearch component_name=opensearch}:request{request_id=2}: vector::sinks::util::retries: Internal log [Not retriable; dropping the request.] is being suppressed to avoid flooding.
2024-11-07T18:07:44.074311Z ERROR sink{component_kind="sink" component_id=opensearch component_type=elasticsearch component_name=opensearch}:request{request_id=2}: vector_common::internal_event::service: Internal log [Service call failed. No retries or retries exhausted.] is being suppressed to avoid flooding.
2024-11-07T18:07:44.074317Z ERROR sink{component_kind="sink" component_id=opensearch component_type=elasticsearch component_name=opensearch}:request{request_id=2}: vector_common::internal_event::component_events_dropped: Internal log [Events dropped] is being suppressed to avoid flooding.

[jszwedko]

Thanks for checking! This is pretty strange. I don't suppose you could stick an HTTP proxy in the middle (like mitmproxy) to capture the HTTP requests to observe the differences between the two Vector versions? I'm trying to spin up an OpenSearch instance to see if I can reproduce.

[jszwedko]

You could also try enabling trace level logs. I believe HTTP header info should be logged which might give some clues.

[jszwedko]

I setup an OpenSearch 1.3 instance to try to reproduce this but I couldn't get basic auth working on v0.32.1 or v0.33.0 of Vector. Both receive the response:

2024-11-08T17:46:41.953539Z ERROR sink{component_kind="sink" component_id=sink0 component_type=elasticsearch component_name=sink0}:request{request_id=1}: vector::sinks::util::retries: Not retriable; dropping the request. reason="client-side error, 403 Forbidden: {\"message\":\"'xxxxxx' not a valid key=value pair (missing equal-sign) in Authorization header: 'Basic xxxxxx'.\"}" internal_log_rate_limit=true

Could you provide more details about how you are configuring the credentials in Vector and how you set them up in OpenSearch?

[nhlushak]

Sorry, got caught up in work errands. Sure.

So, in AWS Opensearch we use fine-grained access control with internal user database.

And here is permission role config for Vector's user:

From Vector's side of things, like I mentioned earlier, we simply pass an endpoint with embedded login:password via environment variable into endpoints attribute of elasticsearch sink.

endpoints = ["${OPENSEARCH_ENDPOINT:-https://user:password@example.com}"]

What I observed also, is that audit log for Opensearch registers it's connection attempts, but it looks like requests from Vector are missing credential details from:

{
    "audit_cluster_name": "xxxxxxxxxxxx:logs",
    "audit_node_name": "xxxxxxxxxxxx",
    "audit_rest_request_method": "GET",
    "audit_category": "FAILED_LOGIN",
    "audit_request_origin": "REST",
    "audit_node_id": "xxxxxxxxxxxx",
    "audit_request_layer": "REST",
    "audit_rest_request_path": "/_cluster/health",
    "@timestamp": "2024-11-11T09:21:51.704+00:00",
    "audit_request_effective_user_is_admin": false,
    "audit_format_version": 4,
    "audit_request_remote_address": "__IP__",
    "audit_rest_request_headers": {
        "Connection": [
            "close"
        ],
        "User-Agent": [
            "Vector/0.33.0 (aarch64-unknown-linux-musl 89605fb 2023-09-27 14:18:24.180809939)"
        ],
        "Host": [
            "logs.example.com"
        ],
        "Accept-Encoding": [
            "identity"
        ]
    },
    "audit_request_effective_user": "<NONE>"
}
{
    "audit_cluster_name": "xxxxxxxxxx:logs",
    "audit_rest_request_params": {
        "timeout": "60s"
    },
    "audit_node_name": "xxxxxxxxxxxx",
    "audit_rest_request_method": "POST",
    "audit_category": "FAILED_LOGIN",
    "audit_request_origin": "REST",
    "audit_node_id": "xxxxxxxxxxxx",
    "audit_request_layer": "REST",
    "audit_rest_request_path": "/_bulk",
    "@timestamp": "2024-11-11T09:22:07.255+00:00",
    "audit_request_effective_user_is_admin": false,
    "audit_format_version": 4,
    "audit_request_remote_address": "__IP__",
    "audit_rest_request_headers": {
        "Connection": [
            "close"
        ],
        "User-Agent": [
            "Vector/0.33.0 (aarch64-unknown-linux-musl 89605fb 2023-09-27 14:18:24.180809939)"
        ],
        "Host": [
            "logs.example.com"
        ],
        "Accept-Encoding": [
            "gzip"
        ],
        "Content-Encoding": [
            "gzip"
        ],
        "Content-Length": [
            "5298"
        ],
        "Content-Type": [
            "application/x-ndjson"
        ]
    },
    "audit_request_effective_user": "<NONE>"
}

On the contrary, here is curl request for cluster health, using the same login info, but broken password:

{
    "audit_cluster_name": "xxxxxxxxxxxx:logs",
    "audit_node_name": "xxxxxxxxxxxx",
    "audit_rest_request_method": "GET",
    "audit_category": "FAILED_LOGIN",
    "audit_request_origin": "REST",
    "audit_node_id": "xxxxxxxxxxxx",
    "audit_request_layer": "REST",
    "audit_rest_request_path": "/_cluster/health",
    "@timestamp": "2024-11-11T09:26:23.482+00:00",
    "audit_request_effective_user_is_admin": false,
    "audit_format_version": 4,
    "audit_request_remote_address": "__IP__",
    "audit_rest_request_headers": {
        "Accept": [
            "*/*"
        ],
        "Connection": [
            "close"
        ],
        "User-Agent": [
            "curl/8.7.1"
        ],
        "Host": [
            "logs.example.com"
        ]
    },
    "audit_request_effective_user": "vector"
}

Instead of having "<NONE>" in audit_request_effective_user field it logged username i had in my request.

Hope it will lead you onto something.

[nhlushak]

@jszwedko Did you get a chance to find any clues to such behaviour?