Troubleshooting of HTTP service "feign death" in golang

Research on lnmpr source code 2020-11-10 14:21:45
troubleshooting http service feign death


Problem description

Afternoon 15 P.m. ,QA Feedback grayscale environment a large number of requests timed out .kibana Query the gray gateway log , There are some requests whose response time exceeds 60 second ,HTTP Status code 504. Further analysis of the log , all 504 The upstream address of the request is xxxx:80.

Currently, the service has two environments deployed ,k8s + kvm,k8s Upstream of the environment ingress( namely Nginx) port 80,kvm Upstream of the environment Golang Service port 19001. And ,k8s Environment this service only deploys one pod. It's just k8s Is there a problem with environmental services ?

Log in to k8s Service terminal , Manual curl request (healthCheck Interface , There is no complex business processing , Direct return data ), No response was found to the request , And it's blocked all the time . There's a good chance that Golang There's something wrong with the service .

The screening process

healthCheck The interface logic is very simple , Why is it blocked ? Did the service not receive the request ?tcpdump Grab the bag and have a look :

//xxxx by k8s entrance ingress Address
curl http://xxxx/v1/healthCheck -H "Host:studentlive.xueersi.com"
// Three handshakes
10:20:21.940968 IP xxxx.40970 > server.19001: Flags [S], seq 3201212889, win 29200, length 0
10:20:21.941003 IP server.19001 > xxxx.40970: Flags [S.], seq 1905160768, ack 3201212890, win 28960, length 0
10:20:21.941175 IP xxxx.40970 > server.19001: Flags [.], ack 1905160769, win 58, length 0
// send out HTTP Request data
10:20:21.941219 IP xxxx.40970 > server.19001: Flags [P.], seq 3201212890:3201213201, ack 1905160769, win 58, length 311
10:20:21.941223 IP server.19001 > xxxx.40970: Flags [.], ack 3201213201, win 59, length 0
// The client actively disconnects
10:21:21.945740 IP xxxx.40970 > server.19001: Flags [F.], seq 3201213201, ack 1905160769, win 58, length 0
10:21:21.985062 IP server.19001 > xxxx.40970: Flags [.], ack 3201213202, win 59, length 0

You can see , Three handshakes succeeded , The client sends it HTTP data , The server also returns normally ACk; But no more , Client waiting 60 Seconds later , Actively disconnected .(Nginx To configure :proxy_read_timeout=60 second ).

Why does the server not respond to the client request ? Sure dlv Tracking debugging request processing flow , Let's see which link is blocking ; in addition , The services are on pprof, You can first look at the current service status .

curl http://localhost:17009/debug/pprof/
<td>16391</td><td><a href=goroutine?debug&#61;1>goroutine</a></td>
……

There are a lot of coprocesses , Yes 1.6w, The gray environment has been cut off at present ; In theory, there shouldn't be so many corollaries .

Continue to use pprof View the process statistics details :

go tool pprof http://localhost:17009/debug/pprof/goroutine
(pprof) traces
----------+-------------------------------------------------------
7978 runtime.gopark
runtime.goparkunlock
runtime.chansend
runtime.chansend1
git.100tal.com/wangxiao_go_lib/xesLogger/log4go.(*FileLogTraceWriter).LogWrite
git.100tal.com/wangxiao_go_lib/xesLogger/log4go.Logger.LogTraceMap
git.100tal.com/wangxiao_go_lib/xesLogger/log4go.LogTraceMap
git.100tal.com/wangxiao_go_lib/xesLogger/builders.(*TraceBuilder).LoggerX
git.100tal.com/wangxiao_go_lib/xesLogger.Ix
git.100tal.com/wangxiao_go_lib/xesGoKit/middleware.Logger.func1
github.com/gin-gonic/gin.(*Context).Next
github.com/gin-gonic/gin.(*Engine).handleHTTPRequest
github.com/gin-gonic/gin.(*Engine).ServeHTTP
net/http.serverHandler.ServeHTTP
net/http.(*conn).serve

You can see , Lots of coprocessors are logging (LogWrite) When , blocked ( The pipeline is blocked runtime.chansend), Triggered a coroutine switch .

Code Review

Through the above investigation , We can basically confirm that the request is blocked in the log ; Next, we need to find out why logging blocks requests . The logic of writing a log is like this :

// How to log ; Just writing pipes
func (w *FileLogTraceWriter) LogWrite(rec *LogRecord) {
w.rec <- rec
}
func NewFileLogTraceWriter(fname string, rotate bool) *FileLogTraceWriter {
// Zixie Cheng , Read data from a pipe and write to buffer
go func() {
for {
select {
case rec, ok := <-w.rec:
}
}
}
// Zixie Cheng , from buffer Read data and write to file
go func() {
for {
select {
case lb, ok := <-w.out:
}
}
}
}

We see ,HTTP Processing requests , When writing a journal , call LogWrite Method to write the log to the pipeline . And in initialization FileLogTraceWriter When , It will start the subprocess to read log data from the pipeline in an endless loop . The log write pipeline is blocked , It's very likely that there is something wrong with this subprocess .

Find these two subprocess stacks :

1 runtime.gopark
runtime.selectgo
git.100tal.com/wangxiao_go_lib/xesLogger/log4go.NewFileLogTraceWriter.func2

NewFileLogTraceWriter.func2 Blocked in select It's about ;NewFileLogTraceWriter.func1 There's no coprocessor .

The problem is clear , The subprocess that consumes logs from the pipeline exited for some reason . The coroutine has two logic , When something goes wrong , direct return, Will lead to the end of the collaboration . It's a pity that there is no log collection in the gray environment , It took too long for the log to exist , We can't determine the real reason for the coprocessor to quit .

in addition , It is normal to check the status of log files :

// Log path , The authority is normal
# ll /home/logs/xeslog/talcamp/talcamp.log
-rw-r--r-- 1 root root 0 Nov 10 00:00 /home/logs/xeslog/talcamp/talcamp.log
// The service opens the log file normally
# lsof -p 67 | grep "talcamp.log"
9 /home/www/talcamp/bin/talcamp /home/logs/xeslog/talcamp/talcamp.log

Non blocking modification

HTTP Request processing protocol , Write a log by writing a pipeline , It's just to not block yourself . But found , When pipeline consumers are abnormal , It will still cause obstruction .web service , Writing a journal is inevitable and not necessary , How to ensure that the log will not be blocked HTTP How about the request processing ? In fact, writing pipes can also be non blocking :

You can check if you are interested runtime/chan.go Document learning .

// Nonblocking write implementation
// compiler implements
//
// select {
// case c <- v:
// ... foo
// default:
// ... bar
// }
//
// as
//
// if selectnbsend(c, v) {
// ... foo
// } else {
// ... bar
// }
//
func selectnbsend(c *hchan, elem unsafe.Pointer) (selected bool) {
return chansend(c, elem, false, getcallerpc())
}
// Nonblocking read implementation
//compiler implements
//
// select {
// case v = <-c:
// ... foo
// default:
// ... bar
// }
//
// as
//
// if selectnbrecv(&v, c) {
// ... foo
// } else {
// ... bar
// }
//
func selectnbrecv(elem unsafe.Pointer, c *hchan) (selected bool) {
selected, _ = chanrecv(c, elem, false)
return
}

see Golang SDK Source code , be based on select It can realize non blocking read and write of pipeline (chanrecv And chansend function , The third parameter identifies whether the current coroutine is blocked ). in addition , We can also change it a little bit , Read and write pipeline with timeout time .

版权声明
本文为[Research on lnmpr source code]所创,转载请带上原文链接,感谢

  1. [front end -- JavaScript] knowledge point (IV) -- memory leakage in the project (I)
  2. This mechanism in JS
  3. Vue 3.0 source code learning 1 --- rendering process of components
  4. Learning the realization of canvas and simple drawing
  5. gin里获取http请求过来的参数
  6. vue3的新特性
  7. Get the parameters from HTTP request in gin
  8. New features of vue3
  9. vue-cli 引入腾讯地图(最新 api,rocketmq原理面试
  10. Vue 学习笔记(3,免费Java高级工程师学习资源
  11. Vue 学习笔记(2,Java编程视频教程
  12. Vue cli introduces Tencent maps (the latest API, rocketmq)
  13. Vue learning notes (3, free Java senior engineer learning resources)
  14. Vue learning notes (2, Java programming video tutorial)
  15. 【Vue】—props属性
  16. 【Vue】—创建组件
  17. [Vue] - props attribute
  18. [Vue] - create component
  19. 浅谈vue响应式原理及发布订阅模式和观察者模式
  20. On Vue responsive principle, publish subscribe mode and observer mode
  21. 浅谈vue响应式原理及发布订阅模式和观察者模式
  22. On Vue responsive principle, publish subscribe mode and observer mode
  23. Xiaobai can understand it. It only takes 4 steps to solve the problem of Vue keep alive cache component
  24. Publish, subscribe and observer of design patterns
  25. Summary of common content added in ES6 + (II)
  26. No.8 Vue element admin learning (III) vuex learning and login method analysis
  27. Write a mini webpack project construction tool
  28. Shopping cart (front-end static page preparation)
  29. Introduction to the fluent platform
  30. Webpack5 cache
  31. The difference between drop-down box select option and datalist
  32. CSS review (III)
  33. Node.js学习笔记【七】
  34. Node.js learning notes [VII]
  35. Vue Router根据后台数据加载不同的组件(思考-&gt;实现-&gt;不止于实现)
  36. Vue router loads different components according to background data (thinking - & gt; Implementation - & gt; (more than implementation)
  37. 【JQuery框架,Java编程教程视频下载
  38. [jQuery framework, Java programming tutorial video download
  39. Vue Router根据后台数据加载不同的组件(思考-&gt;实现-&gt;不止于实现)
  40. Vue router loads different components according to background data (thinking - & gt; Implementation - & gt; (more than implementation)
  41. 【Vue,阿里P8大佬亲自教你
  42. 【Vue基础知识总结 5,字节跳动算法工程师面试经验
  43. [Vue, Ali P8 teaches you personally
  44. [Vue basic knowledge summary 5. Interview experience of byte beating Algorithm Engineer
  45. 【问题记录】- 谷歌浏览器 Html生成PDF
  46. [problem record] - PDF generated by Google browser HTML
  47. 【问题记录】- 谷歌浏览器 Html生成PDF
  48. [problem record] - PDF generated by Google browser HTML
  49. 【JavaScript】查漏补缺 —数组中reduce()方法
  50. [JavaScript] leak checking and defect filling - reduce() method in array
  51. 【重识 HTML (3),350道Java面试真题分享
  52. 【重识 HTML (2),Java并发编程必会的多线程你竟然还不会
  53. 【重识 HTML (1),二本Java小菜鸟4面字节跳动被秒成渣渣
  54. [re recognize HTML (3) and share 350 real Java interview questions
  55. [re recognize HTML (2). Multithreading is a must for Java Concurrent Programming. How dare you not
  56. [re recognize HTML (1), two Java rookies' 4-sided bytes beat and become slag in seconds
  57. 【重识 HTML ,nginx面试题阿里
  58. 【重识 HTML (4),ELK原来这么简单
  59. [re recognize HTML, nginx interview questions]
  60. [re recognize HTML (4). Elk is so simple