2018年8月30日,那是一个大雨滂沱的早上
收到用户反馈,产品页面打开异常。。。
什么?!好好的页面怎么会异常呢?!
脸上笑呵呵,心里MMP
还是怀着忐忑的心情打开iTerm2,熟练的命令,迅速ssh到生产服务器查看日志,看到了XX异常,一看就知道是用户填的XX太长了,悬着的心突然就放松了,于是联系用户,OVER。
顺手拿了张纸巾
抹了抹额头上的汗珠
满足地喝了一大口水。
外面的雨还在下,仿佛是从天上掉下的一串珠子,砸在地上
“嘈嘈切切错杂弹,大珠小珠落玉盘”。
然后就在准备关闭iTerm2的时候,tail -f的日志里突然多了一屏幕错误,这个时候隐约有种不好的预感,就好像下班了背包走到电梯口,碰到老板开会回来,把你叫回来一起加班。
虽然不愿意承认,但是怀着对未知世界的探索欲望,开始了这个错误日志的解决探索之路。。。
错误日志是这样的:

好吧,一脸蒙蔽,先问了一下用户,操作是否有遇到问题,答案是没有。。。这就奇怪了
百度之,发现大神们给出了两种思路:
用户在发起请求之后突然关闭了请求——我的用户才没有这么高级的操作,排除
nginx的超时时间太短了——有可能,需要去检查一下
cat etc/nginx/nginx.conf,发现nginx的超时时间是65秒,这么长时间,用户做了什么操作会超时呢?
于是用错误日志里的唯一标识去查看tomcat访问日志,发现是查询产品详情的请求,这个理论也不存在超时的可能啊,难道是数据库有问题了?去试了一下数据库,没问题。
奇怪啊,继续看tomcat日志,发现在请求刚进入一秒之后,就超时了。。。怎么可能!于是排除nginx的超时时间配置。
去百度多看了几篇文章,发现都是上面的说法,难道真的是第一种,我的用户已经黑客附体?
于是我自己打算自己进入页面,模拟验证一下是否是客户取消请求导致。
左手按着F5,右手马上点chrome的取消X号,发现后台日志又多了一条同样的错误日志。于是初步判定为是用户自己取消了。
可是,还是哪里不对啊!页面都是嵌入微信的,用户怎么会在电脑上打开并取消呢?
查看nginx的access日志,根据UA判断,发现只有我刚模拟的那次,其他的请求都是手机端发起:
"Mozilla/5.0 (iPhone; CPU iPhone OS 11_4_1 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15G77 MicroMessenger/6.7.1 NetType/4G Language/zh_CN"
难道真的黑客附体了?都已经伪造UA了?理智告诉我不可能!
于是我在手机上打开页面,访问了一下页面,发现同样的内容重复了两次,并且时间所差无几。于是联想到,页面的代码为了绕过微信的某限制,在进入时,reload了一次。

所以怀疑是reload导致的这个问题:在第一次请求未结束之前,就reload了。并且在nginx的日志中查看得到,两次请求其中一个是200,另一个是499。于是百度了499是啥,果然跟现象吻合。于是断定问题是这样产生的。

之后在模拟的时候,检查了这种操作对于网络的影响情况,使用命令:
netstat -n | awk '/^tcp/ {++state[$NF]} END {for(key in state) print key,"\t",state[key]}'

发现出现了这个错误之后,TIME_WAIT的数量会增多,然后过一段时间,TIME_WAIT会恢复(借此温习了一下tcp的三次握手)。
看了一下出错的几率:

还比较小,加上页面的特殊性,决定暂不修改,暂定为正常的异常。
好吧,问题暂时解决了
雨也停了