记一次,排查错误所遇到的问题,和学习到的内容。

上周五,刚上线的项目出现了503 ,查看日志发现如下内容:

System.Exception: Request api/blogpost/zzkDocs
<html>^M
<head><title>500 Internal Server Error</title></head>^M
<body bgcolor="white">^M
<center><h1>500 Internal Server Error</h1></center>^M
<hr><center>nginx/1.10.3 (Ubuntu)</center>^M
</body>^M
</html>^M
---> Newtonsoft.Json.JsonReaderException: Unexpected character encountered while parsing value: <. Path '', line 0, position 0.
at Newtonsoft.Json.JsonTextReader.ParseValue()
at Newtonsoft.Json.JsonReader.ReadForType(JsonContract contract, Boolean hasConverter)
at Newtonsoft.Json.Serialization.JsonSerializerInternalReader.Deserialize(JsonReader reader, Type objectType, Boolean checkAdditionalContent)
at Newtonsoft.Json.JsonSerializer.DeserializeInternal(JsonReader reader, Type objectType)
at Newtonsoft.Json.JsonConvert.DeserializeObject(String value, Type type, JsonSerializerSettings settings)
at Newtonsoft.Json.JsonConvert.DeserializeObject[T](String value, JsonSerializerSettings settings)
at System.Net.Http.HttpClientExtensions.<ReadAsAsync>d__2`1.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
at CNBlogs.Zzk.ServiceAgent.ZzkDocumentManager`1.<GetZzkDocAsync>d__8.MoveNext() in /home/xiaokang/CNBlogsZzk/CNBlogsZzk/src/CNBlogs.Zzk.ServiceAgent/ZzkDocumentManager.cs:line 33

 

 日志报错的是NewtonJson 对文档进行Josn格式序列化的时候报错,报错内容是第0行,第0列的字符无法匹配,在google找了很多这样的错误,然而都没有办法解决。后来我才恍然大悟,我忽视了日志里面的:

<html>^M
<head><title>500 Internal Server Error</title></head>^M
<body bgcolor="white">^M
<center><h1>500 Internal Server Error</h1></center>^M
<hr><center>nginx/1.10.3 (Ubuntu)</center>^M
</body>^M
</html>^M

 

 原来是本来请求的文档却反馈了503的html,这样当然没有办法转成json。站点是从另外一台服务器上获取的文档。于是打开提供数据的服务器,查看nginx日志终于发现了日志中存在786 worker_connections are not enough while connecting to upstream:

Nginx 日志 worker_connections are not enough while connecting to upstream_服务器

顾名思义就是连接数已经超过最大了768个限制了。问题查找到这里终于明白问题的出处了,因为我的提供数据的服务器使用了nginx代理服务器,nginx的配置文件限制了最大连接数为768个。那么出现这个问题要么是并发连接数量很大,要么是tcp连接请求完数据之后没有释放。我一开始就把注意力放在后者。tcp连接没有正常关闭,导致连接数越来越多。

这里又去重新回顾了tcp连接的三次握手和四次握手。

Nginx 日志 worker_connections are not enough while connecting to upstream_服务器_02

这张图是一个完整的tcp建立和断开连接的过程。Tcp建立的时候经历了三次握手,断开经历了四次握手。

三次握手:

第一次:A服务器向B服务器发送SYN包,表示我要和你建立连接,进入SYN-SEND状态。第二次:B服务器接受到SYN包,发送SYN+ACK报文到B服务器。第三次:B服务器发送ACK报文到A服务器,AB服务器进入ESTABLISED 状态。

四次握手:

 

第一次:A服务器向B服务器发送FIN报文进入FIN-WAIT1状态,表示我要断开连接。B服务器没有立刻发送FIN+ACK报文,因为B服务器可能还有数据需要传送所以第二次握手先发送ACK报文,A服务器进入FIN-WAIT2状态,B服务器进入CLOSE-WAIT状态。第三次:B服务器发送完数据之后,再发送FIN报文,表示可以断开连接。第四次,A服务器接受FIN报文,发送ACK报文给B,进入TIME-WAIT状态,B接受ACK报文,关闭连接。

 

A服务器能不能发送完ACK之后不进入TIME_WAIT就直接进入CLOSE状态呢?不行的,这个是为了TCP协议的可靠性,由于网络原因,ACK可能会发送失败,那么这个时候,被动一方会主动重新发送一次FIN,这个时候如果主动方在TIME_WAIT状态,则还会再发送一次ACK,从而保证可靠性。

 

这里再介绍一个概念,就是Keep-Alive 长连接。在HTTP 1.1版本的请求中,Keep-alive 是默认的。客户端发送keep-alive请求即表示,我主动断开服务器才可以断开,否在我们的连接一直建立。那为何要这样呢?因为每一次tcp的建立都要消耗资源,如果请求完立即关闭tcp连接,下次还要重新建立,这样服务器的负担就大大增加。当然这样也有弊端,建立的tcp不断开,占有的端口不释放,那么随着并发量很大,就会出现tcp连接无法建立的情况,就如同上面的错误一样。所以对于并发量大的短请求应当取消keep-alive。

于是我猜想报错的原因就是所有的请求都是keep-alive导致短时间内不能释放,然而我的站点并没有那么大的并发量,怎么想也不可能爆满啊。干脆设置一些keep-alive的时间限制,设置一个较短的时间,比如20s,20s之内tcp不再发送http请求,就关闭这条tcp连接。这样可以很好解决keep-alive的弊端。

然后这样的设置根本无济于事,因为问题的原因可能不再并发量这里,于是我又把注意力转移到tcp连接的TIME-WAIT上。因为很多时候,站点负荷大是因为出现了大量的TIME-WAIT的tcp连接。tcp连接主动关闭的一方会进入TIME-WAIT状态,这个状态会持续比较久的时间,这样如果有大量的tcp处于TIME-WAIT状态:

  • 网络情况不好时,如果主动方无TIME_WAIT等待,关闭前个连接后,主动方与被动方又建立起新的TCP连接,这时被动方重传或延时过来的FIN包过来后会直接影响新的TCP连接;
  • 同样网络情况不好并且无TIME_WAIT等待,关闭连接后无新连接,当接收到被动方重传或延迟的FIN包后,会给被动方回一个RST包,可能会影响被动方其它的服务连接。
  • 过多的话会占用内存,一个time_await占用4k大小

我查看netstat -net | grep xxxxxx 当我多次连续点击请求按钮,果然有出现很多tcp连接,很快处于TIME-WAIT状态,但是我太天真了,Linux系统对于TIME-WAIT 有一个处理机制TIME-WAIT的tcp连接很快被回收关闭,并没有占有很长时间。

 

于是再回头查看自己的代码,因为我的请求是使用HttpClient发送的,如果HttpClient不是static的,那么每个请求都会创建一个HttpClient,这样每次的请求都会新建一个连接,可是发现代码并没有错。

 

最后绝望的我去查看了站点的日志,发现果然出现503的时候请求量高的惊人,再仔细查看发现,这些请求都是广告请求!!原来出现worker_connections are not enough while connecting to upstream 不是什么tcp连接的问题,也不是nginx配置的问题,这些地方不会出问题的。出问题的地方要么是你的代码,要么就是真的有很多请求。把广告请求屏蔽就好了。

 

这里再留一个问题,我的项目是用asp.net core2.0写的,使用nginx作转发。打开netstat发现有很多localhost与localhost之间的tcp连接,一度让我以为这是问题的所在。现在还不知道为什么会有这些处于TIME-WAIT的本地tcp连接:

Nginx 日志 worker_connections are not enough while connecting to upstream_json_03