rest engine TimeoutHandler did not working as expected

abnerwei commented 3 years ago

goctl init project

goctl api new greet
cd greet
go mod init
go mod tidy
go run greet.go -f etc/greet-api.yaml

use ab or wrk

为了方便测试，在 logic 处理中添加了适当的sleep模拟业务流程，默认 rest server timeout为 3s
func (l *GreetLogic) Greet(req types.Request) (*types.Response, error) {
// 450ms
time.Sleep(450 * time.Millisecond)
return &types.Response{}, nil
}
$ wrk -c1 -t1 -d3s http://127.0.0.1:8888/from/me -H 'Connection: close'
正常延时情况下返回大量503错误

More Logs

Starting server at 0.0.0.0:8888... 
{"@timestamp":"2020-12-16T00:39:50.049+08","level":"info","content":"200 - /from/me - 127.0.0.1:53530 -  - 451.7ms","trace":"d3b96fb6a8d8f3e6","span":"0"} 
{"@timestamp":"2020-12-16T00:39:50.501+08","level":"info","content":"200 - /from/me - 127.0.0.1:53531 -  - 451.0ms","trace":"41c99a3fc87572e5","span":"0"}
{"@timestamp":"2020-12-16T00:39:50.957+08","level":"info","content":"200 - /from/me - 127.0.0.1:53532 -  - 455.4ms","trace":"47ec434b2ccf4cd2","span":"0"}
{"@timestamp":"2020-12-16T00:39:51.414+08","level":"info","content":"200 - /from/me - 127.0.0.1:53533 -  - 455.5ms","trace":"577cf89a269a14ae","span":"0"}
{"@timestamp":"2020-12-16T00:39:51.869+08","level":"info","content":"200 - /from/me - 127.0.0.1:53534 -  - 454.2ms","trace":"4059f76b3dca8ce4","span":"0"}
{"@timestamp":"2020-12-16T00:39:52.322+08","level":"info","content":"200 - /from/me - 127.0.0.1:53535 -  - 452.1ms","trace":"4e0e12e7189e1168","span":"0"}
{"@timestamp":"2020-12-16T00:39:52.671+08","level":"error","content":"loghandler.go:135 503 - /from/me - 127.0.0.1:53536 -  - 347.8ms\nGET /from/me HTTP/1.1\r\nHost: 127.0.0.1:8888\r\nConnection: close\r\nConnection: close\r\n\r\n","trace":"3730280e45ce1072","span":"0"}

开启 Verbose 日志详情可以看到返回 Request Timeout

{"@timestamp":"2020-12-16T00:45:36.891+08","level":"info","content":"503 - 127.0.0.1:54087 - 350.5ms\n=\u003e GET /from/me HTTP/1.1\r\nHost: 127.0.0.1:8888\r\n\r\n\n\u003c= Request Timeout","trace":"6ffbaddf98033934","span":"0"}

Tips: 经过反复测试结合 shedding_stat 日志发现 miss 请求数总是和wrk --connections 参数基本一致，wrk -c20 -t1 -d3s http://127.0.0.1:8888/from/me -H 'Connection: close' 会丢失将近20条请求
{"@timestamp":"2020-12-17T09:58:00.460+08","level":"stat","content":"(api) shedding_stat [1m], cpu: 0, total: 240, pass: 220, drop: 0"}

kevwan commented 3 years ago

我怀疑 wrk 的问题哈，我用 hey 测试没问题，你也试试，我觉得如果 hey 这样测试没问题

$ hey -z 3s -c 20 http://127.0.0.1:8888/from/me -H 'Connection: close'

Summary:
  Total:    3.1803 secs
  Slowest:  0.4567 secs
  Fastest:  0.4508 secs
  Average:  0.4539 secs
  Requests/sec: 44.0215

  Total data:   1960 bytes
  Size/request: 14 bytes

Response time histogram:
  0.451 [1] |■
  0.451 [15]    |■■■■■■■■■■■■■■■■■■
  0.452 [8] |■■■■■■■■■
  0.453 [11]    |■■■■■■■■■■■■■
  0.453 [5] |■■■■■■
  0.454 [15]    |■■■■■■■■■■■■■■■■■■
  0.454 [19]    |■■■■■■■■■■■■■■■■■■■■■■
  0.455 [16]    |■■■■■■■■■■■■■■■■■■■
  0.456 [34]    |■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■
  0.456 [6] |■■■■■■■
  0.457 [10]    |■■■■■■■■■■■■

Latency distribution:
  10% in 0.4512 secs
  25% in 0.4526 secs
  50% in 0.4542 secs
  75% in 0.4551 secs
  90% in 0.4557 secs
  95% in 0.4563 secs
  99% in 0.4567 secs

Details (average, fastest, slowest):
  DNS+dialup:   0.0001 secs, 0.4508 secs, 0.4567 secs
  DNS-lookup:   0.0000 secs, 0.0000 secs, 0.0000 secs
  req write:    0.0000 secs, 0.0000 secs, 0.0002 secs
  resp wait:    0.4535 secs, 0.4506 secs, 0.4566 secs
  resp read:    0.0001 secs, 0.0000 secs, 0.0005 secs

Status code distribution:
  [200] 140 responses

abnerwei commented 3 years ago

从测试结果看 wrk 基于 epoll(Linux) 和 kqueue(MacOS)都复现了问题，其他工具 ab、hey、locust都没有问题。初步判断是 wrk工具问题。

从 WireShark 抓包来看，是 wrk 客户端主动断开连接导致的 503错误，框架应该没有问题 😀

对了，研究过程中发现 core/logx/logs_test.go#245, wireConsole = false, 再次调用log.Close()会导致单元测试报错 ErrLogNotInitialized

zeromicro / go-zero

rest engine TimeoutHandler did not working as expected #294