Ceph RGW get object 出现 EPIPE 错误分
2023-09-09 本文已影响0人
酱油王0901
August 9 3:00 PM时有同事发现读取集群 bigdata-hdd-1 时出现 Unable to execute HTTP request: Read timed out，具体如图所示：
另一套集群上出现了 op status 返回 -104
查看 log 发现 http status 返回码都是正常的，但是 op status 返回 -32 或者 -104，其中 -32 对应的是 EPIPE，即 broken pipe， -104 对应的是 ECONNRESET， 即 connection reset by peer。
故障模拟
首先在存储集群中通过 S3 上传一个 1G的文件
~/go/src/ceph (test ✗) s3cmd ls s3://test/1024/
2023-08-09 11:01 1073741824 s3://test/1024/1024M
对象下载过程中突然中断的情况
使用 s3cmd get 下载对象，下载途中直接中断下载，查看 log 发现 op status 返回 -104
~/go/src/ceph (test ✗) s3cmd get s3://test/1024/1024M
download: 's3://test/1024/1024M' -> './1024M' [1 of 1]
251723776 of 1073741824 23% in 1s 226.81 MB/s^CSee ya!
2023-08-10T16:12:38.005+0800 7f6b00980700 4 write_data failed: Connection reset by peer
2023-08-10T16:12:38.005+0800 7f6b00980700 0 req 12767011379465063231 1.450000048s s3:get_obj iterate_obj() failed with -104
2023-08-10T16:12:38.023+0800 7f6bfa373700 1 -- 127.0.0.1:0/361935705 <== osd.2 v2:127.0.0.1:6818/1674143 18 ==== osd_op_reply(2986 19f29ec1-3a45-4f4c-899f-3dd118c9c64b.4321.1__multipart_1024/1024M.2~6cS9fAXKYh6CcB7MOKFZG-SSt8UCoUb.25 [read 0~4194304 out=4194304b] v0'0 uv8 ondisk = 0) v8 ==== 246+0+4194304 (crc 0 0 0) 0x562a8f9a6000 con 0x562a8f5f7800
2023-08-10T16:12:38.028+0800 7f6bfab74700 1 -- 127.0.0.1:0/361935705 <== osd.1 v2:127.0.0.1:6810/1669942 15 ==== osd_op_reply(2987 19f29ec1-3a45-4f4c-899f-3dd118c9c64b.4321.1__shadow_1024/1024M.2~6cS9fAXKYh6CcB7MOKFZG-SSt8UCoUb.25_1 [read 0~4194304 out=4194304b] v0'0 uv9 ondisk = 0) v8 ==== 245+0+4194304 (crc 0 0 0) 0x562a908e1b00 con 0x562a8f5f6c00
2023-08-10T16:12:38.030+0800 7f6bfab74700 1 -- 127.0.0.1:0/361935705 <== osd.1 v2:127.0.0.1:6810/1669942 16 ==== osd_op_reply(2988 19f29ec1-3a45-4f4c-899f-3dd118c9c64b.4321.1__shadow_1024/1024M.2~6cS9fAXKYh6CcB7MOKFZG-SSt8UCoUb.25_2 [read 0~4194304 out=4194304b] v0'0 uv2 ondisk = 0) v8 ==== 245+0+4194304 (crc 0 0 0) 0x562a908e1b00 con 0x562a8f5f6c00
2023-08-10T16:12:38.032+0800 7f6bfa373700 1 -- 127.0.0.1:0/361935705 <== osd.2 v2:127.0.0.1:6818/1674143 19 ==== osd_op_reply(2989 19f29ec1-3a45-4f4c-899f-3dd118c9c64b.4321.1__shadow_1024/1024M.2~6cS9fAXKYh6CcB7MOKFZG-SSt8UCoUb.25_3 [read 0~3145728 out=3145728b] v0'0 uv6 ondisk = 0) v8 ==== 245+0+3145728 (crc 0 0 0) 0x562a8f9a6000 con 0x562a8f5f7800
2023-08-10T16:12:38.032+0800 7f6bc4307700 2 req 12767011379465063231 1.476999879s s3:get_obj completing
2023-08-10T16:12:38.033+0800 7f6bc4307700 2 req 12767011379465063231 1.478000045s s3:get_obj op status=-104
2023-08-10T16:12:38.033+0800 7f6bc4307700 2 req 12767011379465063231 1.478000045s s3:get_obj http status=200
2023-08-10T16:12:38.033+0800 7f6bc4307700 1 ====== req done req=0x7f6c1662c680 op status=-104 http_status=200 latency=1.478000045s ======
2023-08-10T16:12:38.033+0800 7f6bc4307700 1 beast: 0x7f6c1662c680: 10.9.9.150 - testid [10/Aug/2023:16:12:36.555 +0800] "GET /test/1024/1024M HTTP/1.1" 200 374341632 - - - latency=1.478000045s
设置 http client 超时
http client 读取部分数据后主动断开连接
package main
import (
"bytes"
"context"
"crypto/tls"
"fmt"
"log"
"net/http"
"time"
"github.com/aws/aws-sdk-go-v2/aws"
"github.com/aws/aws-sdk-go-v2/config"
"github.com/aws/aws-sdk-go-v2/credentials"
"github.com/aws/aws-sdk-go-v2/service/s3"
)
func main() {
var (
accessKey = "testy"
secretKey = "testy"
bucket = "test"
endpoint = "http://10.9.9.150:8000"
key = "1024/1024M"
)
appCreds := aws.NewCredentialsCache(credentials.NewStaticCredentialsProvider(
accessKey, secretKey, ""))
tr := &http.Transport{
TLSClientConfig: &tls.Config{InsecureSkipVerify: true},
}
httpClient := &http.Client{Timeout: time.Second, Transport: tr} // 设置 http client timeout 为 1s
cfg, err := config.LoadDefaultConfig(context.TODO(),
config.WithCredentialsProvider(appCreds),
config.WithRegion("us-east-1"),
config.WithHTTPClient(httpClient),
config.WithEndpointResolver(
aws.EndpointResolverFunc(
func(service, region string) (aws.Endpoint, error) {
return aws.Endpoint{
Source: aws.EndpointSourceCustom,
URL: endpoint,
}, nil
})),
)
if err != nil {
log.Fatal(err)
}
client := s3.NewFromConfig(cfg, func(o *s3.Options) {
o.UsePathStyle = true
})
obj, err := client.GetObject(context.Background(),
&s3.GetObjectInput{
Bucket: aws.String(bucket),
Key: &key,
})
if err != nil {
log.Fatal(err)
}
fmt.Println(obj)
buf := new(bytes.Buffer)
n, err := buf.ReadFrom(obj.Body)
if err != nil {
log.Println(err)
}
fmt.Println(n)
}
2023/08/10 16:21:40 context deadline exceeded (Client.Timeout or context cancellation while reading body)
110100480
2023-08-10T16:22:22.580+0800 7f6bfa373700 1 -- 127.0.0.1:0/361935705 <== osd.2 v2:127.0.0.1:6818/1674143 1 ==== osd_op_reply(4685 19f29ec1-3a45-4f4c-899f-3dd118c9c64b.4321.1__multipart_1024/1024M.2~6cS9fAXKYh6CcB7MOKFZG-SSt8UCoUb.8 [read 0~4194304 out=4194304b] v0'0 uv3 ondisk = 0) v8 ==== 245+0+4194304 (crc 0 0 0) 0x562a8f9a6000 con 0x562a8e89ac00
2023-08-10T16:22:22.580+0800 7f6b171ad700 1 -- 127.0.0.1:0/361935705 --> [v2:127.0.0.1:6818/1674143,v1:127.0.0.1:6819/1674143] -- osd_op(unknown.0.0:4696 8.1c 8:3b28b7c5:::19f29ec1-3a45-4f4c-899f-3dd118c9c64b.4321.1__shadow_1024%2f1024M.2~6cS9fAXKYh6CcB7MOKFZG-SSt8UCoUb.9_2:head [read 0~4194304] snapc 0=[] ondisk+read+known_if_redirected e33) v8 -- 0x562a90f94400 con 0x562a8e89ac00
2023-08-10T16:22:22.582+0800 7f6b9029f700 4 write_data failed: Broken pipe
2023-08-10T16:22:22.582+0800 7f6b9029f700 0 req 10021019180289276815 1.049999952s s3:get_obj iterate_obj() failed with -32
2023-08-10T16:22:22.585+0800 7f6bfa373700 1 -- 127.0.0.1:0/361935705 <== osd.2 v2:127.0.0.1:6818/1674143 2 ==== osd_op_reply(4696 19f29ec1-3a45-4f4c-899f-3dd118c9c64b.4321.1__shadow_1024/1024M.2~6cS9fAXKYh6CcB7MOKFZG-SSt8UCoUb.9_2 [read 0~4194304 out=4194304b] v0'0 uv1ondisk = 0) v8 ==== 244+0+4194304 (crc 0 0 0) 0x562a8f9a6000 con 0x562a8e89ac00
2023-08-10T16:22:22.594+0800 7f6bfa373700 1 -- 127.0.0.1:0/361935705 <== osd.2 v2:127.0.0.1:6818/1674143 3 ==== osd_op_reply(4695 19f29ec1-3a45-4f4c-899f-3dd118c9c64b.4321.1__shadow_1024/1024M.2~6cS9fAXKYh6CcB7MOKFZG-SSt8UCoUb.9_1 [read 0~4194304 out=4194304b] v0'0 uv3ondisk = 0) v8 ==== 244+0+4194304 (crc 0 0 0) 0x562a8f9a6000 con 0x562a8e89ac00
2023-08-10T16:22:22.609+0800 7f6bfa373700 1 -- 127.0.0.1:0/361935705 <== osd.2 v2:127.0.0.1:6818/1674143 4 ==== osd_op_reply(4688 19f29ec1-3a45-4f4c-899f-3dd118c9c64b.4321.1__shadow_1024/1024M.2~6cS9fAXKYh6CcB7MOKFZG-SSt8UCoUb.8_2 [read 0~4194304 out=4194304b] v0'0 uv1ondisk = 0) v8 ==== 244+0+4194304 (crc 0 0 0) 0x562a8f9a6000 con 0x562a8e89ac00
2023-08-10T16:22:22.624+0800 7f6bfa373700 1 -- 127.0.0.1:0/361935705 <== osd.2 v2:127.0.0.1:6818/1674143 5 ==== osd_op_reply(4689 19f29ec1-3a45-4f4c-899f-3dd118c9c64b.4321.1__shadow_1024/1024M.2~6cS9fAXKYh6CcB7MOKFZG-SSt8UCoUb.8_3 [read 0~3145728 out=3145728b] v0'0 uv2ondisk = 0) v8 ==== 244+0+3145728 (crc 0 0 0) 0x562a8f9a6000 con 0x562a8e89ac00
2023-08-10T16:22:22.625+0800 7f6bb22e3700 2 req 10021019180289276815 1.092999935s s3:get_obj completing
2023-08-10T16:22:22.625+0800 7f6bb22e3700 2 req 10021019180289276815 1.092999935s s3:get_obj op status=-32
2023-08-10T16:22:22.625+0800 7f6bb22e3700 2 req 10021019180289276815 1.092999935s s3:get_obj http status=200
2023-08-10T16:22:22.625+0800 7f6bb22e3700 1 ====== req done req=0x7f6c1662c680 op status=-32 http_status=200 latency=1.092999935s ======
2023-08-10T16:22:22.625+0800 7f6bb22e3700 1 beast: 0x7f6c1662c680: 10.9.8.72 - testid [10/Aug/2023:16:22:21.532 +0800] "GET /test/1024/1024M?x-id=GetObject HTTP/1.1" 200 110100480 - "aws-sdk-go-v2/1.17.3 os/linux lang/go/1.20.4 md/GOOS/linux md/GOARCH/amd64 api/s3/1.30.0" - latency=1.092999935s
设置读取 body 写超时
package main
import (
"context"
"crypto/tls"
"fmt"
"io"
"log"
"net/http"
"time"
"github.com/aws/aws-sdk-go-v2/aws"
"github.com/aws/aws-sdk-go-v2/config"
"github.com/aws/aws-sdk-go-v2/credentials"
"github.com/aws/aws-sdk-go-v2/service/s3"
)
func main() {
var (
accessKey = "testy"
secretKey = "testy"
bucket = "test"
endpoint = "http://10.9.9.150:8000"
key = "1024/1024M"
)
appCreds := aws.NewCredentialsCache(credentials.NewStaticCredentialsProvider(
accessKey, secretKey, ""))
tr := &http.Transport{
TLSClientConfig: &tls.Config{InsecureSkipVerify: true},
}
httpClient := &http.Client{Transport: tr}
cfg, err := config.LoadDefaultConfig(context.TODO(),
config.WithCredentialsProvider(appCreds),
config.WithRegion("us-east-1"),
config.WithHTTPClient(httpClient),
config.WithEndpointResolver(
aws.EndpointResolverFunc(
func(service, region string) (aws.Endpoint, error) {
return aws.Endpoint{
Source: aws.EndpointSourceCustom,
URL: endpoint,
}, nil
})),
)
if err != nil {
log.Fatal(err)
}
client := s3.NewFromConfig(cfg, func(o *s3.Options) {
o.UsePathStyle = true
})
obj, err := client.GetObject(
context.Background(),
&s3.GetObjectInput{
Bucket: aws.String(bucket),
Key: &key,
})
if err != nil {
log.Fatal(err)
}
// fmt.Println(obj)
ctx, cancelFunc := context.WithTimeout(context.Background(), time.Second) // 设置写超时
defer cancelFunc()
w := &writer{
ctx: ctx,
w: io.Discard,
}
n, err := io.Copy(w, obj.Body)
if err != nil {
log.Println(err)
}
fmt.Println(n)
}
type writer struct {
ctx context.Context
w io.Writer
}
func (w writer) Write(p []byte) (n int, err error) {
if err = w.ctx.Err(); err != nil {
return
}
if n, err = w.w.Write(p); err != nil {
return
}
err = w.ctx.Err()
return
}
2023/08/10 16:26:30 context deadline exceeded
346030080
2023-08-10T16:27:12.516+0800 7f6bfab74700 1 -- 127.0.0.1:0/361935705 <== osd.2 v2:127.0.0.1:6818/1674143 1 ==== osd_op_reply(5475 19f29ec1-3a45-4f4c-899f-3dd118c9c64b.4321.1__shadow_1024/1024M.2~6cS9fAXKYh6CcB7MOKFZG-SSt8UCoUb.24_2 [read 0~4194304 out=4194304b] v0'0 uv7 ondisk = 0) v8 ==== 245+0+4194304 (crc 0 0 0) 0x562a90ae8b40 con 0x562a8f5f6400
2023-08-10T16:27:12.517+0800 7f6b86a8c700 2 req 1794005993485243593 1.243999958s s3:get_obj completing
2023-08-10T16:27:12.517+0800 7f6b86a8c700 2 req 1794005993485243593 1.243999958s s3:get_obj op status=-104
2023-08-10T16:27:12.517+0800 7f6b86a8c700 2 req 1794005993485243593 1.243999958s s3:get_obj http status=200
2023-08-10T16:27:12.517+0800 7f6b86a8c700 1 ====== req done req=0x7f6c1662c680 op status=-104 http_status=200 latency=1.243999958s ======
2023-08-10T16:27:12.517+0800 7f6b86a8c700 1 beast: 0x7f6c1662c680: 10.9.8.72 - testid [10/Aug/2023:16:27:11.273 +0800] "GET /test/1024/1024M?x-id=GetObject HTTP/1.1" 200 350224384 - "aws-sdk-go-v2/1.17.3 os/linux lang/go/1.20.4 md/GOOS/linux md/GOARCH/amd64 api/s3/1.30.0" - latency=1.243999958s
设置 connection 超时
import boto3
import time
from botocore.config import Config
access_key = 'testy'
secret_key = 'testy'
region_name = 'us-east-1'
endpoint_url = "http://10.9.9.150:8000"
timeout_seconds = 0.001 # 设置读超时时间为 1ms
s3_config = Config(
read_timeout=timeout_seconds
)
s3_client = boto3.client('s3',
aws_access_key_id=access_key,
aws_secret_access_key=secret_key,
region_name=region_name,
endpoint_url=endpoint_url,
config=s3_config)
bucket_name = 'test'
object_key = "1024/1024M"
try:
start_time = time.time()
response = s3_client.get_object(Bucket=bucket_name, Key=object_key)
object_content = response['Body'].read()
end_time = time.time()
download_time = end_time - start_time
download_size = len(object_content)
print(f"Download cost time：{download_time:.2f} s")
print(f"Download object size：{download_size} bytes")
except Exception as e:
print("Download failed：", e)
Download failed： Read timeout on endpoint URL: "http://10.9.9.150:8000/test/1024/1024M"
2023-08-10T16:36:49.563+0800 7f6b1f1bd700 1 -- 127.0.0.1:0/361935705 --> [v2:127.0.0.1:6802/1665735,v1:127.0.0.1:6803/1665735] -- osd_op(unknown.0.0:7027 8.14 8:28efcc63:::19f29ec1-3a45-4f4c-899f-3dd118c9c64b.4321.1__multipart_1024%2f1024M.2~6cS9fAXKYh6CcB7MOKFZG-SSt8UCoUb.2:head [read 0~4194304] snapc 0=[] ondisk+read+known_if_redirected e33) v8 -- 0x562a90fef400 con 0x562a8e89b000
2023-08-10T16:36:49.564+0800 7f6b231c5700 4 write_data failed: Broken pipe
2023-08-10T16:36:49.564+0800 7f6b231c5700 0 req 3025750671678495499 0.017000001s s3:get_obj iterate_obj() failed with -32
2023-08-10T16:36:49.564+0800 7f6bfa373700 1 -- 127.0.0.1:0/361935705 <== osd.0 v2:127.0.0.1:6802/1665735 7 ==== osd_op_reply(7025 19f29ec1-3a45-4f4c-899f-3dd118c9c64b.4321.1__shadow_1024/1024M.2~6cS9fAXKYh6CcB7MOKFZG-SSt8UCoUb.1_2 [read 0~4194304 out=4194304b] v0'0 uv1ondisk = 0) v8 ==== 244+0+4194304 (crc 0 0 0) 0x562a8f9a6000 con 0x562a8e89b000
2023-08-10T16:36:49.566+0800 7f6bfa373700 1 -- 127.0.0.1:0/361935705 <== osd.0 v2:127.0.0.1:6802/1665735 8 ==== osd_op_reply(7026 19f29ec1-3a45-4f4c-899f-3dd118c9c64b.4321.1__shadow_1024/1024M.2~6cS9fAXKYh6CcB7MOKFZG-SSt8UCoUb.1_3 [read 0~3145728 out=3145728b] v0'0 uv1ondisk = 0) v8 ==== 244+0+3145728 (crc 0 0 0) 0x562a8f9a6000 con 0x562a8e89b000
2023-08-10T16:36:49.569+0800 7f6bfa373700 1 -- 127.0.0.1:0/361935705 <== osd.0 v2:127.0.0.1:6802/1665735 9 ==== osd_op_reply(7027 19f29ec1-3a45-4f4c-899f-3dd118c9c64b.4321.1__multipart_1024/1024M.2~6cS9fAXKYh6CcB7MOKFZG-SSt8UCoUb.2 [read 0~4194304 out=4194304b] v0'0 uv2 ondisk = 0) v8 ==== 245+0+4194304 (crc 0 0 0) 0x562a8f9a6000 con 0x562a8e89b000
2023-08-10T16:36:49.570+0800 7f6b1c9b8700 2 req 3025750671678495499 0.023000000s s3:get_obj completing
2023-08-10T16:36:49.570+0800 7f6b1c9b8700 2 req 3025750671678495499 0.023000000s s3:get_obj op status=-32
2023-08-10T16:36:49.570+0800 7f6b1c9b8700 2 req 3025750671678495499 0.023000000s s3:get_obj http status=200
2023-08-10T16:36:49.570+0800 7f6b1c9b8700 1 ====== req done req=0x7f6c1662c680 op status=-32 http_status=200 latency=0.023000000s ======
2023-08-10T16:36:49.571+0800 7f6b1c9b8700 1 beast: 0x7f6c1662c680: 10.9.8.72 - testid [10/Aug/2023:16:36:49.546 +0800] "GET /test/1024/1024M HTTP/1.1" 200 0 - "Boto3/1.26.115 Python/3.10.0 Linux/3.10.0-1127.el7.x86_64 Botocore/1.29.115" - latency=0.023000000s
原因分析
bigdata 客户端默认读超时时间是 5s，如果 5s 内没有返回数据则会断开连接，从而返回 EPIPE，但是底层 http status 都是 200，说明底层数据读取正常，只是读取较慢。通过查看监控数据发现存储压力很大，而且存储空间使用率已经很高了(>90%)，因此可以在 hdd 集群上将客户端读超时时间设置的大一些，存储端 log 显示基本上都在 20s 以内返回。
