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. 【计算机网络 12(1),尚学堂马士兵Java视频教程
  2. 【程序猿历程,史上最全的Java面试题集锦在这里
  3. 【程序猿历程(1),Javaweb视频教程百度云
  4. Notes on MySQL 45 lectures (1-7)
  5. [computer network 12 (1), Shang Xuetang Ma soldier java video tutorial
  6. The most complete collection of Java interview questions in history is here
  7. [process of program ape (1), JavaWeb video tutorial, baidu cloud
  8. Notes on MySQL 45 lectures (1-7)
  9. 精进 Spring Boot 03:Spring Boot 的配置文件和配置管理,以及用三种方式读取配置文件
  10. Refined spring boot 03: spring boot configuration files and configuration management, and reading configuration files in three ways
  11. 精进 Spring Boot 03:Spring Boot 的配置文件和配置管理,以及用三种方式读取配置文件
  12. Refined spring boot 03: spring boot configuration files and configuration management, and reading configuration files in three ways
  13. 【递归,Java传智播客笔记
  14. [recursion, Java intelligence podcast notes
  15. [adhere to painting for 386 days] the beginning of spring of 24 solar terms
  16. K8S系列第八篇(Service、EndPoints以及高可用kubeadm部署)
  17. K8s Series Part 8 (service, endpoints and high availability kubeadm deployment)
  18. 【重识 HTML (3),350道Java面试真题分享
  19. 【重识 HTML (2),Java并发编程必会的多线程你竟然还不会
  20. 【重识 HTML (1),二本Java小菜鸟4面字节跳动被秒成渣渣
  21. [re recognize HTML (3) and share 350 real Java interview questions
  22. [re recognize HTML (2). Multithreading is a must for Java Concurrent Programming. How dare you not
  23. [re recognize HTML (1), two Java rookies' 4-sided bytes beat and become slag in seconds
  24. 造轮子系列之RPC 1:如何从零开始开发RPC框架
  25. RPC 1: how to develop RPC framework from scratch
  26. 造轮子系列之RPC 1:如何从零开始开发RPC框架
  27. RPC 1: how to develop RPC framework from scratch
  28. 一次性捋清楚吧,对乱糟糟的,Spring事务扩展机制
  29. 一文彻底弄懂如何选择抽象类还是接口,连续四年百度Java岗必问面试题
  30. Redis常用命令
  31. 一双拖鞋引发的血案,狂神说Java系列笔记
  32. 一、mysql基础安装
  33. 一位程序员的独白:尽管我一生坎坷,Java框架面试基础
  34. Clear it all at once. For the messy, spring transaction extension mechanism
  35. A thorough understanding of how to choose abstract classes or interfaces, baidu Java post must ask interview questions for four consecutive years
  36. Redis common commands
  37. A pair of slippers triggered the murder, crazy God said java series notes
  38. 1、 MySQL basic installation
  39. Monologue of a programmer: despite my ups and downs in my life, Java framework is the foundation of interview
  40. 【大厂面试】三面三问Spring循环依赖,请一定要把这篇看完(建议收藏)
  41. 一线互联网企业中,springboot入门项目
  42. 一篇文带你入门SSM框架Spring开发,帮你快速拿Offer
  43. 【面试资料】Java全集、微服务、大数据、数据结构与算法、机器学习知识最全总结,283页pdf
  44. 【leetcode刷题】24.数组中重复的数字——Java版
  45. 【leetcode刷题】23.对称二叉树——Java版
  46. 【leetcode刷题】22.二叉树的中序遍历——Java版
  47. 【leetcode刷题】21.三数之和——Java版
  48. 【leetcode刷题】20.最长回文子串——Java版
  49. 【leetcode刷题】19.回文链表——Java版
  50. 【leetcode刷题】18.反转链表——Java版
  51. 【leetcode刷题】17.相交链表——Java&python版
  52. 【leetcode刷题】16.环形链表——Java版
  53. 【leetcode刷题】15.汉明距离——Java版
  54. 【leetcode刷题】14.找到所有数组中消失的数字——Java版
  55. 【leetcode刷题】13.比特位计数——Java版
  56. oracle控制用户权限命令
  57. 三年Java开发,继阿里,鲁班二期Java架构师
  58. Oracle必须要启动的服务
  59. 万字长文!深入剖析HashMap,Java基础笔试题大全带答案
  60. 一问Kafka就心慌?我却凭着这份,图灵学院vip课程百度云