search

ClickHouse / ClickHouse

ClickHouse® is a real-time analytics DBMS
https://clickhouse.com
Apache License 2.0
37.59k stars 6.9k forks source link

Request hangs: timeout and retries in AWSHttpResourceClient #58119

Open mneedham opened 10 months ago

mneedham commented 10 months ago

I'm trying to query some log data in an S3 bucket, but it seems to be trying to lookup security credentials and then times out.

The bucket contains 10 files with 100,000 lines each.

SELECT *
FROM s3('https://logs-mv.clickhouse.com.s3.amazonaws.com/*.log', LineAsString)
LIMIT 10

This is the trace output:

Query id: e8186fbe-0423-4eb5-ae3c-6159c3163d03

2023.12.21 10:49:15.897026 [ 17941683 ] {} <Trace> LOCAL-Session: 18103bd7-7a46-4b2b-a453-abb17f9e1bf4 Creating query context from session context, user_id: 94309d50-4f52-5250-31bd-74fecac179db, parent context user: default
2023.12.21 10:49:15.897125 [ 17941683 ] {e8186fbe-0423-4eb5-ae3c-6159c3163d03} <Debug> executeQuery: (from 0.0.0.0:0, user: ) SELECT * FROM s3('https://logs-mv.clickhouse.com.s3.amazonaws.com/*.log', LineAsString) LIMIT 10 ; (stage: Complete)
2023.12.21 10:49:15.897316 [ 17941683 ] {e8186fbe-0423-4eb5-ae3c-6159c3163d03} <Trace> NamedCollectionsUtils: Loaded 0 collections from config
2023.12.21 10:49:15.897730 [ 17941683 ] {e8186fbe-0423-4eb5-ae3c-6159c3163d03} <Trace> NamedCollectionsUtils: Loaded 0 collections from SQL
2023.12.21 10:49:15.897891 [ 17941683 ] {e8186fbe-0423-4eb5-ae3c-6159c3163d03} <Trace> ContextAccess (default): Access granted: CREATE TEMPORARY TABLE, S3 ON *.*
2023.12.21 10:49:15.910515 [ 17941683 ] {e8186fbe-0423-4eb5-ae3c-6159c3163d03} <Warning> AwsAuthSTSAssumeRoleWebIdentityCredentialsProvider: Token file must be specified to use STS AssumeRole web identity creds provider.
2023.12.21 10:49:15.910571 [ 17941683 ] {e8186fbe-0423-4eb5-ae3c-6159c3163d03} <Information> AWSClient: SSOBearerTokenProvider: Setting sso bearerToken provider to read config from default
2023.12.21 10:49:15.910580 [ 17941683 ] {e8186fbe-0423-4eb5-ae3c-6159c3163d03} <Trace> SSOCredentialsProvider: Setting sso credentials provider to read config from default
2023.12.21 10:49:15.910585 [ 17941683 ] {e8186fbe-0423-4eb5-ae3c-6159c3163d03} <Debug> S3CredentialsProviderChain: The environment variable value AWS_CONTAINER_CREDENTIALS_RELATIVE_URI is
2023.12.21 10:49:15.910589 [ 17941683 ] {e8186fbe-0423-4eb5-ae3c-6159c3163d03} <Debug> S3CredentialsProviderChain: The environment variable value AWS_CONTAINER_CREDENTIALS_FULL_URI is
2023.12.21 10:49:15.910593 [ 17941683 ] {e8186fbe-0423-4eb5-ae3c-6159c3163d03} <Debug> S3CredentialsProviderChain: The environment variable value AWS_EC2_METADATA_DISABLED is
2023.12.21 10:49:15.910640 [ 17941683 ] {e8186fbe-0423-4eb5-ae3c-6159c3163d03} <Information> AWSClient: AWSHttpResourceClient: Creating AWSHttpResourceClient with max connections 2 and scheme http
2023.12.21 10:49:15.910650 [ 17941683 ] {e8186fbe-0423-4eb5-ae3c-6159c3163d03} <Information> AWSInstanceProfileCredentialsProvider: Creating Instance with injected EC2MetadataClient and refresh rate.
2023.12.21 10:49:15.910655 [ 17941683 ] {e8186fbe-0423-4eb5-ae3c-6159c3163d03} <Information> S3CredentialsProviderChain: Added EC2 metadata service credentials provider to the provider chain.
2023.12.21 10:49:15.910686 [ 17941683 ] {e8186fbe-0423-4eb5-ae3c-6159c3163d03} <Information> AWSClient: Aws::Config::AWSConfigFileProfileConfigLoader: Initializing config loader against fileName /Users/markhneedham/.aws/credentials and using profilePrefix = 0
2023.12.21 10:49:15.910693 [ 17941683 ] {e8186fbe-0423-4eb5-ae3c-6159c3163d03} <Information> AWSClient: ProfileConfigFileAWSCredentialsProvider: Setting provider to read credentials from /Users/markhneedham/.aws/credentials for credentials file and /Users/markhneedham/.aws/config for the config file , for use with profile default
2023.12.21 10:49:15.910766 [ 17941683 ] {e8186fbe-0423-4eb5-ae3c-6159c3163d03} <Information> AWSInstanceProfileCredentialsProvider: Credentials have expired attempting to repull from EC2 Metadata Service.
2023.12.21 10:49:15.910812 [ 17941683 ] {e8186fbe-0423-4eb5-ae3c-6159c3163d03} <Trace> AWSEC2InstanceProfileConfigLoader: Calling EC2MetadataService to get token.
2023.12.21 10:49:17.041157 [ 17941683 ] {e8186fbe-0423-4eb5-ae3c-6159c3163d03} <Information> AWSClient: Failed to make request to: http://169.254.169.254/latest/api/token: Poco::Exception. Code: 1000, e.code() = 0, Timeout: connect timed out: 169.254.169.254:80, Stack trace (when copying this message, always include the lines below):

<Empty trace>
 (version 23.12.1.956 (official build))
2023.12.21 10:49:17.041199 [ 17941683 ] {e8186fbe-0423-4eb5-ae3c-6159c3163d03} <Information> AWSClient: AWSHttpResourceClient: Http request to retrieve credentials failed
2023.12.21 10:49:17.041214 [ 17941683 ] {e8186fbe-0423-4eb5-ae3c-6159c3163d03} <Information> AWSClient: AWSHttpResourceClient: Request failed, now waiting 0 ms before attempting again.
2023.12.21 10:49:18.171137 [ 17941683 ] {e8186fbe-0423-4eb5-ae3c-6159c3163d03} <Information> AWSClient: Failed to make request to: http://169.254.169.254/latest/api/token: Poco::Exception. Code: 1000, e.code() = 0, Timeout: connect timed out: 169.254.169.254:80, Stack trace (when copying this message, always include the lines below):

<Empty trace>
 (version 23.12.1.956 (official build))
2023.12.21 10:49:18.171168 [ 17941683 ] {e8186fbe-0423-4eb5-ae3c-6159c3163d03} <Information> AWSClient: AWSHttpResourceClient: Http request to retrieve credentials failed
2023.12.21 10:49:18.171176 [ 17941683 ] {e8186fbe-0423-4eb5-ae3c-6159c3163d03} <Information> AWSClient: AWSHttpResourceClient: Can not retrieve resource from http://169.254.169.254/latest/api/token
2023.12.21 10:49:18.171182 [ 17941683 ] {e8186fbe-0423-4eb5-ae3c-6159c3163d03} <Trace> AWSEC2InstanceProfileConfigLoader: Calling EC2MetadataService to get token failed, falling back to less secure way. HTTP response code: REQUEST_NOT_MADE
2023.12.21 10:49:18.171203 [ 17941683 ] {e8186fbe-0423-4eb5-ae3c-6159c3163d03} <Trace> AWSEC2InstanceProfileConfigLoader: Getting default credentials for ec2 instance from http://169.254.169.254
2023.12.21 10:49:19.301918 [ 17941683 ] {e8186fbe-0423-4eb5-ae3c-6159c3163d03} <Information> AWSClient: Failed to make request to: http://169.254.169.254/latest/meta-data/iam/security-credentials: Poco::Exception. Code: 1000, e.code() = 0, Timeout: connect timed out: 169.254.169.254:80, Stack trace (when copying this message, always include the lines below):

<Empty trace>
 (version 23.12.1.956 (official build))
2023.12.21 10:49:19.301966 [ 17941683 ] {e8186fbe-0423-4eb5-ae3c-6159c3163d03} <Information> AWSClient: AWSHttpResourceClient: Http request to retrieve credentials failed
2023.12.21 10:49:19.301976 [ 17941683 ] {e8186fbe-0423-4eb5-ae3c-6159c3163d03} <Information> AWSClient: AWSHttpResourceClient: Request failed, now waiting 0 ms before attempting again.
2023.12.21 10:49:20.431836 [ 17941683 ] {e8186fbe-0423-4eb5-ae3c-6159c3163d03} <Information> AWSClient: Failed to make request to: http://169.254.169.254/latest/meta-data/iam/security-credentials: Poco::Exception. Code: 1000, e.code() = 0, Timeout: connect timed out: 169.254.169.254:80, Stack trace (when copying this message, always include the lines below):

<Empty trace>
 (version 23.12.1.956 (official build))
2023.12.21 10:49:20.431878 [ 17941683 ] {e8186fbe-0423-4eb5-ae3c-6159c3163d03} <Information> AWSClient: AWSHttpResourceClient: Http request to retrieve credentials failed
2023.12.21 10:49:20.431885 [ 17941683 ] {e8186fbe-0423-4eb5-ae3c-6159c3163d03} <Information> AWSClient: AWSHttpResourceClient: Can not retrieve resource from http://169.254.169.254/latest/meta-data/iam/security-credentials
2023.12.21 10:49:20.431919 [ 17941683 ] {e8186fbe-0423-4eb5-ae3c-6159c3163d03} <Information> AWSClient: Aws::Config::AWSProfileConfigLoaderBase: Failed to reload configuration.
2023.12.21 10:49:20.432045 [ 17941683 ] {e8186fbe-0423-4eb5-ae3c-6159c3163d03} <Information> AWSClient: Aws::Config::ConfigFileProfileFSM: Unknown property: aws_access_key_id in the profile: dev-internal
2023.12.21 10:49:20.432050 [ 17941683 ] {e8186fbe-0423-4eb5-ae3c-6159c3163d03} <Information> AWSClient: Aws::Config::ConfigFileProfileFSM: Unknown property: aws_secret_access_key in the profile: dev-internal
2023.12.21 10:49:20.432054 [ 17941683 ] {e8186fbe-0423-4eb5-ae3c-6159c3163d03} <Information> AWSClient: Aws::Config::ConfigFileProfileFSM: Unknown property: aws_session_token in the profile: dev-internal
2023.12.21 10:49:20.432073 [ 17941683 ] {e8186fbe-0423-4eb5-ae3c-6159c3163d03} <Information> AWSClient: Aws::Config::ConfigFileProfileFSM: Unknown property: aws_access_key_id in the profile: s3queue
2023.12.21 10:49:20.432077 [ 17941683 ] {e8186fbe-0423-4eb5-ae3c-6159c3163d03} <Information> AWSClient: Aws::Config::ConfigFileProfileFSM: Unknown property: aws_secret_access_key in the profile: s3queue
2023.12.21 10:49:20.432079 [ 17941683 ] {e8186fbe-0423-4eb5-ae3c-6159c3163d03} <Information> AWSClient: Aws::Config::ConfigFileProfileFSM: Unknown property: aws_session_token in the profile: s3queue
2023.12.21 10:49:20.432089 [ 17941683 ] {e8186fbe-0423-4eb5-ae3c-6159c3163d03} <Information> AWSClient: Aws::Config::ConfigFileProfileFSM: Unknown property: aws_access_key_id in the profile: mv_transformation
2023.12.21 10:49:20.432275 [ 17941683 ] {e8186fbe-0423-4eb5-ae3c-6159c3163d03} <Information> AWSClient: Aws::Config::ConfigFileProfileFSM: Unknown property: aws_secret_access_key in the profile: mv_transformation
2023.12.21 10:49:20.432284 [ 17941683 ] {e8186fbe-0423-4eb5-ae3c-6159c3163d03} <Information> AWSClient: Aws::Config::ConfigFileProfileFSM: Unknown property: aws_session_token in the profile: mv_transformation
2023.12.21 10:49:20.432330 [ 17941683 ] {e8186fbe-0423-4eb5-ae3c-6159c3163d03} <Information> AWSClient: Aws::Config::AWSProfileConfigLoaderBase: Successfully reloaded configuration.
2023.12.21 10:49:20.433404 [ 17941683 ] {e8186fbe-0423-4eb5-ae3c-6159c3163d03} <Trace> S3Client: Provider type: AWS
2023.12.21 10:49:20.433411 [ 17941683 ] {e8186fbe-0423-4eb5-ae3c-6159c3163d03} <Trace> S3Client: API mode of the S3 client: AWS
2023.12.21 10:49:20.434394 [ 17941699 ] {e8186fbe-0423-4eb5-ae3c-6159c3163d03} <Information> S3Client: Resolving region for bucket logs-mv.clickhouse.com
2023.12.21 10:49:20.840957 [ 17941699 ] {e8186fbe-0423-4eb5-ae3c-6159c3163d03} <Trace> HTTPSessionAdapter: Created HTTP(S) session with s3.amazonaws.com:443 (16.182.106.64:443)
2023.12.21 10:49:20.966522 [ 17941699 ] {e8186fbe-0423-4eb5-ae3c-6159c3163d03} <Information> S3Client: Found region us-east-1 for bucket logs-mv.clickhouse.com
2023.12.21 10:49:21.413635 [ 17941683 ] {e8186fbe-0423-4eb5-ae3c-6159c3163d03} <Trace> InterpreterSelectQuery: FetchColumns -> Complete
2023.12.21 10:49:21.416753 [ 17941702 ] {e8186fbe-0423-4eb5-ae3c-6159c3163d03} <Information> S3Client: Resolving region for bucket logs-mv.clickhouse.com
2023.12.21 10:49:21.862291 [ 17941702 ] {e8186fbe-0423-4eb5-ae3c-6159c3163d03} <Information> S3Client: Found region us-east-1 for bucket logs-mv.clickhouse.com
2023.12.21 10:49:22.400971 [ 17941683 ] {e8186fbe-0423-4eb5-ae3c-6159c3163d03} <Debug> StorageS3: Reading in 1 streams, 12 threads per stream
→ Progress: 0.00 rows, 0.00 B (0.00 rows/s., 0.00 B/s.)                                                                                                                                                                                                                                   0%2023.12.21 10:49:22.402032 [ 17941701 ] {e8186fbe-0423-4eb5-ae3c-6159c3163d03} <Trace> FormatFactory: Using ParallelReadBuffer with 4 workers with chunks of 10485760 bytes
2023.12.21 10:49:22.402093 [ 17941701 ] {e8186fbe-0423-4eb5-ae3c-6159c3163d03} <Trace> ParallelReadBuffer: Parallel reading is used
2023.12.21 10:49:22.402340 [ 17941701 ] {e8186fbe-0423-4eb5-ae3c-6159c3163d03} <Trace> ParallelParsingInputFormat: Parallel parsing is used
2023.12.21 10:49:22.402492 [ 17941700 ] {e8186fbe-0423-4eb5-ae3c-6159c3163d03} <Information> S3Client: Resolving region for bucket logs-mv.clickhouse.com
2023.12.21 10:49:22.402594 [ 17941704 ] {e8186fbe-0423-4eb5-ae3c-6159c3163d03} <Trace> FormatFactory: Using ParallelReadBuffer with 4 workers with chunks of 10485760 bytes
2023.12.21 10:49:22.402619 [ 17941704 ] {e8186fbe-0423-4eb5-ae3c-6159c3163d03} <Trace> ParallelReadBuffer: Parallel reading is used
2023.12.21 10:49:22.402698 [ 17941704 ] {e8186fbe-0423-4eb5-ae3c-6159c3163d03} <Trace> ParallelParsingInputFormat: Parallel parsing is used
← Progress: 0.00 rows, 0.00 B (0.00 rows/s., 0.00 B/s.)                                                                                                                                                                                                           (0.0 CPU, 64.55 MB RAM) 0%2023.12.21 10:49:22.855677 [ 17941700 ] {e8186fbe-0423-4eb5-ae3c-6159c3163d03} <Information> S3Client: Found region us-east-1 for bucket logs-mv.clickhouse.com
↗ Progress: 0.00 rows, 0.00 B (0.00 rows/s., 0.00 B/s.)                                                                                                                                                                                                           (0.0 CPU, 64.55 MB RAM) 0%2023.12.21 10:49:23.191441 [ 17941707 ] {e8186fbe-0423-4eb5-ae3c-6159c3163d03} <Trace> HTTPSessionAdapter: Created HTTP(S) session with s3.amazonaws.com:443 (16.182.106.64:443)
→ Progress: 0.00 rows, 0.00 B (0.00 rows/s., 0.00 B/s.)                                                                                                                                                                                                           (0.0 CPU, 64.55 MB RAM) 0%2023.12.21 10:49:23.227141 [ 17941706 ] {e8186fbe-0423-4eb5-ae3c-6159c3163d03} <Trace> HTTPSessionAdapter: Created HTTP(S) session with s3.amazonaws.com:443 (16.182.106.64:443)
2023.12.21 10:49:23.227175 [ 17941708 ] {e8186fbe-0423-4eb5-ae3c-6159c3163d03} <Trace> HTTPSessionAdapter: Created HTTP(S) session with s3.amazonaws.com:443 (16.182.106.64:443)
2023.12.21 10:49:23.227219 [ 17941710 ] {e8186fbe-0423-4eb5-ae3c-6159c3163d03} <Trace> HTTPSessionAdapter: Created HTTP(S) session with s3.amazonaws.com:443 (16.182.106.64:443)
2023.12.21 10:49:23.227332 [ 17941709 ] {e8186fbe-0423-4eb5-ae3c-6159c3163d03} <Trace> HTTPSessionAdapter: Created HTTP(S) session with s3.amazonaws.com:443 (16.182.106.64:443)
┌─line───────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────┐
│ 54.36.149.41 - - [22/Jan/2019:03:56:14 +0330] "GET /filter/27|13%20%D9%85%DA%AF%D8%A7%D9%BE%DB%8C%DA%A9%D8%B3%D9%84,27|%DA%A9%D9%85%D8%AA%D8%B1%20%D8%A7%D8%B2%205%20%D9%85%DA%AF%D8%A7%D9%BE%DB%8C%DA%A9%D8%B3%D9%84,p53 HTTP/1.1" 200 30577 "-" "Mozilla/5.0 (compatible; AhrefsBot/6.1; +http://ahrefs.com/robot/)" "-" │
│ 31.56.96.51 - - [22/Jan/2019:03:56:16 +0330] "GET /image/60844/productModel/200x200 HTTP/1.1" 200 5667 "https://www.zanbil.ir/m/filter/b113" "Mozilla/5.0 (Linux; Android 6.0; ALE-L21 Build/HuaweiALE-L21) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/66.0.3359.158 Mobile Safari/537.36" "-" │
│ 31.56.96.51 - - [22/Jan/2019:03:56:16 +0330] "GET /image/61474/productModel/200x200 HTTP/1.1" 200 5379 "https://www.zanbil.ir/m/filter/b113" "Mozilla/5.0 (Linux; Android 6.0; ALE-L21 Build/HuaweiALE-L21) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/66.0.3359.158 Mobile Safari/537.36" "-" │
│ 40.77.167.129 - - [22/Jan/2019:03:56:17 +0330] "GET /image/14925/productModel/100x100 HTTP/1.1" 200 1696 "-" "Mozilla/5.0 (compatible; bingbot/2.0; +http://www.bing.com/bingbot.htm)" "-"                                                                 │
│ 91.99.72.15 - - [22/Jan/2019:03:56:17 +0330] "GET /product/31893/62100/%D8%B3%D8%B4%D9%88%D8%A7%D8%B1-%D8%AE%D8%A7%D9%86%DA%AF%DB%8C-%D9%BE%D8%B1%D9%86%D8%B3%D9%84%DB%8C-%D9%85%D8%AF%D9%84-PR257AT HTTP/1.1" 200 41483 "-" "Mozilla/5.0 (Windows NT 6.2; Win64; x64; rv:16.0)Gecko/16.0 Firefox/16.0" "-" │
│ 40.77.167.129 - - [22/Jan/2019:03:56:17 +0330] "GET /image/23488/productModel/150x150 HTTP/1.1" 200 2654 "-" "Mozilla/5.0 (compatible; bingbot/2.0; +http://www.bing.com/bingbot.htm)" "-"                                                                 │
│ 40.77.167.129 - - [22/Jan/2019:03:56:18 +0330] "GET /image/45437/productModel/150x150 HTTP/1.1" 200 3688 "-" "Mozilla/5.0 (compatible; bingbot/2.0; +http://www.bing.com/bingbot.htm)" "-"                                                                 │
│ 40.77.167.129 - - [22/Jan/2019:03:56:18 +0330] "GET /image/576/article/100x100 HTTP/1.1" 200 14776 "-" "Mozilla/5.0 (compatible; bingbot/2.0; +http://www.bing.com/bingbot.htm)" "-"                                                                       │
│ 66.249.66.194 - - [22/Jan/2019:03:56:18 +0330] "GET /filter/b41,b665,c150%7C%D8%A8%D8%AE%D8%A7%D8%B1%D9%BE%D8%B2,p56 HTTP/1.1" 200 34277 "-" "Mozilla/5.0 (compatible; Googlebot/2.1; +http://www.google.com/bot.html)" "-"                                │
│ 40.77.167.129 - - [22/Jan/2019:03:56:18 +0330] "GET /image/57710/productModel/100x100 HTTP/1.1" 200 1695 "-" "Mozilla/5.0 (compatible; bingbot/2.0; +http://www.bing.com/bingbot.htm)" "-"                                                                 │
└────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────┘
← Progress: 0.00 rows, 0.00 B (0.00 rows/s., 0.00 B/s.)                                                                                                                                                                                                           (0.0 CPU, 64.70 MB RAM) 0%2023.12.21 10:49:24.360932 [ 17941683 ] {e8186fbe-0423-4eb5-ae3c-6159c3163d03} <Debug> executeQuery: Read 10 rows, 2.29 KiB in 8.463809 sec., 1.181501142098079 rows/sec., 276.94 B/sec.
2023.12.21 10:49:26.092463 [ 17941710 ] {e8186fbe-0423-4eb5-ae3c-6159c3163d03} <Debug> ReadBufferFromS3: Caught exception while reading S3 object. Bucket: logs-mv.clickhouse.com, Key: access_ab.log, Version: Latest, Offset: 0, Attempt: 1/4, Message: Cannot read from istream at offset 0
2023.12.21 10:54:39.067699 [ 17941710 ] {e8186fbe-0423-4eb5-ae3c-6159c3163d03} <Information> AWSInstanceProfileCredentialsProvider: Credentials have expired attempting to repull from EC2 Metadata Service.
2023.12.21 10:54:39.067824 [ 17941710 ] {e8186fbe-0423-4eb5-ae3c-6159c3163d03} <Trace> AWSEC2InstanceProfileConfigLoader: Calling EC2MetadataService to get token.
2023.12.21 10:54:39.227136 [ 17941710 ] {e8186fbe-0423-4eb5-ae3c-6159c3163d03} <Information> AWSClient: Failed to make request to: http://169.254.169.254/latest/api/token: Poco::Exception. Code: 1000, e.code() = 65, Net Exception: No route to host: 169.254.169.254:80, Stack trace (when copying this message, always include the lines below):

<Empty trace>
 (version 23.12.1.956 (official build))
2023.12.21 10:54:39.227178 [ 17941710 ] {e8186fbe-0423-4eb5-ae3c-6159c3163d03} <Information> AWSClient: AWSHttpResourceClient: Http request to retrieve credentials failed
2023.12.21 10:54:39.227185 [ 17941710 ] {e8186fbe-0423-4eb5-ae3c-6159c3163d03} <Information> AWSClient: AWSHttpResourceClient: Request failed, now waiting 0 ms before attempting again.
2023.12.21 10:54:39.342758 [ 17941710 ] {e8186fbe-0423-4eb5-ae3c-6159c3163d03} <Information> AWSClient: Failed to make request to: http://169.254.169.254/latest/api/token: Poco::Exception. Code: 1000, e.code() = 64, Net Exception: Host is down: 169.254.169.254:80, Stack trace (when copying this message, always include the lines below):

<Empty trace>
 (version 23.12.1.956 (official build))
2023.12.21 10:54:39.342790 [ 17941710 ] {e8186fbe-0423-4eb5-ae3c-6159c3163d03} <Information> AWSClient: AWSHttpResourceClient: Http request to retrieve credentials failed
2023.12.21 10:54:39.342797 [ 17941710 ] {e8186fbe-0423-4eb5-ae3c-6159c3163d03} <Information> AWSClient: AWSHttpResourceClient: Can not retrieve resource from http://169.254.169.254/latest/api/token
2023.12.21 10:54:39.342803 [ 17941710 ] {e8186fbe-0423-4eb5-ae3c-6159c3163d03} <Trace> AWSEC2InstanceProfileConfigLoader: Calling EC2MetadataService to get token failed, falling back to less secure way. HTTP response code: REQUEST_NOT_MADE
2023.12.21 10:54:39.342851 [ 17941710 ] {e8186fbe-0423-4eb5-ae3c-6159c3163d03} <Trace> AWSEC2InstanceProfileConfigLoader: Getting default credentials for ec2 instance from http://169.254.169.254
2023.12.21 10:54:39.457925 [ 17941710 ] {e8186fbe-0423-4eb5-ae3c-6159c3163d03} <Information> AWSClient: Failed to make request to: http://169.254.169.254/latest/meta-data/iam/security-credentials: Poco::Exception. Code: 1000, e.code() = 64, Net Exception: Host is down: 169.254.169.254:80, Stack trace (when copying this message, always include the lines below):

<Empty trace>
 (version 23.12.1.956 (official build))
2023.12.21 10:54:39.457960 [ 17941710 ] {e8186fbe-0423-4eb5-ae3c-6159c3163d03} <Information> AWSClient: AWSHttpResourceClient: Http request to retrieve credentials failed
2023.12.21 10:54:39.457967 [ 17941710 ] {e8186fbe-0423-4eb5-ae3c-6159c3163d03} <Information> AWSClient: AWSHttpResourceClient: Request failed, now waiting 0 ms before attempting again.
2023.12.21 10:54:39.574295 [ 17941710 ] {e8186fbe-0423-4eb5-ae3c-6159c3163d03} <Information> AWSClient: Failed to make request to: http://169.254.169.254/latest/meta-data/iam/security-credentials: Poco::Exception. Code: 1000, e.code() = 64, Net Exception: Host is down: 169.254.169.254:80, Stack trace (when copying this message, always include the lines below):

<Empty trace>
 (version 23.12.1.956 (official build))
2023.12.21 10:54:39.574321 [ 17941710 ] {e8186fbe-0423-4eb5-ae3c-6159c3163d03} <Information> AWSClient: AWSHttpResourceClient: Http request to retrieve credentials failed
2023.12.21 10:54:39.574330 [ 17941710 ] {e8186fbe-0423-4eb5-ae3c-6159c3163d03} <Information> AWSClient: AWSHttpResourceClient: Can not retrieve resource from http://169.254.169.254/latest/meta-data/iam/security-credentials
2023.12.21 10:54:39.574356 [ 17941710 ] {e8186fbe-0423-4eb5-ae3c-6159c3163d03} <Information> AWSClient: Aws::Config::AWSProfileConfigLoaderBase: Failed to reload configuration.
2023.12.21 10:54:39.574488 [ 17941710 ] {e8186fbe-0423-4eb5-ae3c-6159c3163d03} <Information> AWSClient: Aws::Config::ConfigFileProfileFSM: Unknown property: aws_access_key_id in the profile: dev-internal
2023.12.21 10:54:39.574493 [ 17941710 ] {e8186fbe-0423-4eb5-ae3c-6159c3163d03} <Information> AWSClient: Aws::Config::ConfigFileProfileFSM: Unknown property: aws_secret_access_key in the profile: dev-internal
2023.12.21 10:54:39.574496 [ 17941710 ] {e8186fbe-0423-4eb5-ae3c-6159c3163d03} <Information> AWSClient: Aws::Config::ConfigFileProfileFSM: Unknown property: aws_session_token in the profile: dev-internal
2023.12.21 10:54:39.574508 [ 17941710 ] {e8186fbe-0423-4eb5-ae3c-6159c3163d03} <Information> AWSClient: Aws::Config::ConfigFileProfileFSM: Unknown property: aws_access_key_id in the profile: s3queue
2023.12.21 10:54:39.574515 [ 17941710 ] {e8186fbe-0423-4eb5-ae3c-6159c3163d03} <Information> AWSClient: Aws::Config::ConfigFileProfileFSM: Unknown property: aws_secret_access_key in the profile: s3queue
2023.12.21 10:54:39.574519 [ 17941710 ] {e8186fbe-0423-4eb5-ae3c-6159c3163d03} <Information> AWSClient: Aws::Config::ConfigFileProfileFSM: Unknown property: aws_session_token in the profile: s3queue
2023.12.21 10:54:39.574532 [ 17941710 ] {e8186fbe-0423-4eb5-ae3c-6159c3163d03} <Information> AWSClient: Aws::Config::ConfigFileProfileFSM: Unknown property: aws_access_key_id in the profile: mv_transformation
2023.12.21 10:54:39.574535 [ 17941710 ] {e8186fbe-0423-4eb5-ae3c-6159c3163d03} <Information> AWSClient: Aws::Config::ConfigFileProfileFSM: Unknown property: aws_secret_access_key in the profile: mv_transformation
2023.12.21 10:54:39.574656 [ 17941710 ] {e8186fbe-0423-4eb5-ae3c-6159c3163d03} <Information> AWSClient: Aws::Config::ConfigFileProfileFSM: Unknown property: aws_session_token in the profile: mv_transformation
2023.12.21 10:54:39.574691 [ 17941710 ] {e8186fbe-0423-4eb5-ae3c-6159c3163d03} <Information> AWSClient: Aws::Config::AWSProfileConfigLoaderBase: Successfully reloaded configuration.
2023.12.21 10:54:52.023327 [ 17941683 ] {e8186fbe-0423-4eb5-ae3c-6159c3163d03} <Debug> MemoryTracker: Peak memory usage (for query): 61.70 MiB.

10 rows in set. Elapsed: 336.143 sec.

So it finds the rows quite quickly, but then waits another 5 minutes before completing. I'm having the same issue when trying to process this bucket using the S3Queue table engine.

CheSema commented 10 months ago

As we checked, many connections were unstable during that period of time. A lot of retries happened. I did not find here the problem.

But I need to check what would happen with the query if that retries happen at AWSHttpResourceClient. And what timeouts/tries does it use.

CheSema commented 10 months ago

related issue https://github.com/ClickHouse/ClickHouse/issues/58160

CheSema commented 10 months ago

Here I have to introduce set of metrics which helps to unswer to the questions:

Also: