消灭一条warning日志记录

客户的主站系统是一个基于Spring的单块系统,每天的流量大概在几千万,其所有的应用日志以及访问日志,都会上传到Splunk服务器上。随着服务数量的增加,日志的数量也越来越多,对应的Splunk的费用也越来越感人,鉴于主站的系统对日志的贡献最多,所以就从它入手降低无用日志的上传。

其中的一条无用的warning日志信息显示如下:

WARN org.apache.commons.httpclient.HttpMethodBase - Going to buffer response body of large or unknown size. Using getResponseBodyAsStream instead is recommended.

一周内这条warning的数量超过百万条,还是比较可观的。简单查询下其原因是httpclient里面的getResponseBody()调用触发的。

                int limit = getParams().getIntParameter(HttpMethodParams.BUFFER_WARN_TRIGGER_LIMIT, 1024*1024);
                if ((contentLength == -1) || (contentLength > limit)) {
                    LOG.warn("Going to buffer response body of large or unknown size. "
                            +"Using getResponseBodyAsStream instead is recommended.");
                }

看完这个后我们的理解是,有些请求的response body过大,超过缺省的1M(代码会从Content-Length header中获取这个大小),就会触发这个warning,当时没有意识到还有可能是确实不知道response body的长度。
相关的方法调用在代码中有10几处,当时我们也无法定位那段代码引发了这个问题,无脑修改的话,成本比较高,可能要增加一些测试用例,以及做回归测试。所以当时就想着用成本最低的方式修改,从配置文件中给BUFFER_WARN_TRIGGER_LIMIT赋一个更大的值,如20M,毕竟这是个遗留项目,熟悉代码的人以及比较少了。没有选择调整日志的级别是因为HttpMethodBase类是个超类,粗暴调整可能会掩盖其它有用的warning日志。
部署完成后比较日志数量发现并没有太大变化,不得不让我们重新回来审视这个问题的根本原因在哪里。幸好当时系统加了一个transactionID的功能,每次的请求过来时,在应用中用UUID生成一个transactionID写入应用日志,response返回时再写入access log。这样我们就在请求和对应的代码调用之间建立了联系。
功能上线后重新在splunk中搜索,立刻就定位了是在请求Google Map API时触发了这个warning,而且在本地可以稳定重现。

 ~> curl -I   "https://maps.google.com.au/maps/api/geocode/json?address=Sunnydale%2C+SA+5354&language=en_AU&sensor=false"
HTTP/1.1 200 OK
Content-Type: application/json; charset=UTF-8
Date: Fri, 18 Nov 2016 23:20:16 GMT
Expires: Sat, 19 Nov 2016 23:20:16 GMT
Cache-Control: public, max-age=86400
Access-Control-Allow-Origin: *
Server: mafe
X-XSS-Protection: 1; mode=block
X-Frame-Options: SAMEORIGIN
Alt-Svc: quic=":443"; ma=2592000; v="36,35,34"
Transfer-Encoding: chunked
Accept-Ranges: none
Vary: Accept-Encoding

然后发现原来返回是没有Content-Length的:(。
Content-Length header是客户端用于了解服务器返回body的大小,从而在获得等大的内容后,结束连接,节省开销。但在实际的应用中,Content-Length有可能无法准确反映返回body的大小,其值过大会导致pending,过小内容又会被截断。
Transfer-Encoding: chunked 是用来分块编码传输内容,每个分块中包含了长度值和数据,最后一个分块长度值是0,这样就可以准确知道边界了。
定位到问题在哪里之后就很容易解决了,最后只要改动一行代码:

-            String response = query.getResponseBodyAsString();
+            String response = IOUtils.toString(query.getResponseBodyAsStream());

回过头来反思整个过程,因为是遗留系统,所以处理的方式有些粗糙,如果当时我们遵循下面的过程也许会更好些:

  1. 定位问题,找到根本原因(有transactionID的配合会更方便),而不是盲目用生产环境来测试配置的正确性
  2. 在本地重现问题,应用解决方案,并与熟悉遗留系统的同事沟通
  3. 回归测试后部署staging,验证完成后部署上线
最后编辑于
©著作权归作者所有,转载或内容合作请联系作者
  • 序言:七十年代末,一起剥皮案震惊了整个滨河市,随后出现的几起案子,更是在滨河造成了极大的恐慌,老刑警刘岩,带你破解...
    沈念sama阅读 194,242评论 5 459
  • 序言:滨河连续发生了三起死亡事件,死亡现场离奇诡异,居然都是意外死亡,警方通过查阅死者的电脑和手机,发现死者居然都...
    沈念sama阅读 81,769评论 2 371
  • 文/潘晓璐 我一进店门,熙熙楼的掌柜王于贵愁眉苦脸地迎上来,“玉大人,你说我怎么就摊上这事。” “怎么了?”我有些...
    开封第一讲书人阅读 141,484评论 0 319
  • 文/不坏的土叔 我叫张陵,是天一观的道长。 经常有香客问我,道长,这世上最难降的妖魔是什么? 我笑而不...
    开封第一讲书人阅读 52,133评论 1 263
  • 正文 为了忘掉前任,我火速办了婚礼,结果婚礼上,老公的妹妹穿的比我还像新娘。我一直安慰自己,他们只是感情好,可当我...
    茶点故事阅读 61,007评论 4 355
  • 文/花漫 我一把揭开白布。 她就那样静静地躺着,像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上,一...
    开封第一讲书人阅读 46,080评论 1 272
  • 那天,我揣着相机与录音,去河边找鬼。 笑死,一个胖子当着我的面吹牛,可吹牛的内容都是我干的。 我是一名探鬼主播,决...
    沈念sama阅读 36,496评论 3 381
  • 文/苍兰香墨 我猛地睁开眼,长吁一口气:“原来是场噩梦啊……” “哼!你这毒妇竟也来了?” 一声冷哼从身侧响起,我...
    开封第一讲书人阅读 35,190评论 0 253
  • 序言:老挝万荣一对情侣失踪,失踪者是张志新(化名)和其女友刘颖,没想到半个月后,有当地人在树林里发现了一具尸体,经...
    沈念sama阅读 39,464评论 1 290
  • 正文 独居荒郊野岭守林人离奇死亡,尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 34,549评论 2 309
  • 正文 我和宋清朗相恋三年,在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 36,330评论 1 326
  • 序言:一个原本活蹦乱跳的男人离奇死亡,死状恐怖,灵堂内的尸体忽然破棺而出,到底是诈尸还是另有隐情,我是刑警宁泽,带...
    沈念sama阅读 32,205评论 3 312
  • 正文 年R本政府宣布,位于F岛的核电站,受9级特大地震影响,放射性物质发生泄漏。R本人自食恶果不足惜,却给世界环境...
    茶点故事阅读 37,567评论 3 298
  • 文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹,春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 28,889评论 0 17
  • 文/苍兰香墨 我抬头看了看天上的太阳。三九已至,却和暖如春,着一层夹袄步出监牢的瞬间,已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 30,160评论 1 250
  • 我被黑心中介骗来泰国打工, 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留,地道东北人。 一个月前我还...
    沈念sama阅读 41,475评论 2 341
  • 正文 我出身青楼,却偏偏与公主长得像,于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子,可洞房花烛夜当晚...
    茶点故事阅读 40,650评论 2 335

推荐阅读更多精彩内容

  • Spring Cloud为开发人员提供了快速构建分布式系统中一些常见模式的工具(例如配置管理,服务发现,断路器,智...
    卡卡罗2017阅读 134,494评论 18 139
  • 一:LoadRunner常见问题整理1.LR 脚本为空的解决方法:1.去掉ie设置中的第三方支持取消掉2.在系统属...
    0100阅读 4,016评论 0 11
  • 1. Java基础部分 基础部分的顺序:基本语法,类相关的语法,内部类的语法,继承相关的语法,异常的语法,线程的语...
    子非鱼_t_阅读 31,493评论 18 399
  • 原文链接:http://www.jianshu.com/p/6b816c609669 前传 出于兴趣最近开始研究k...
    悬笔e绝阅读 7,180评论 1 11
  • 组织:中国互动出版网(http://www.china-pub.com/) RFC文档中文翻译计划(http://...
    Palomar阅读 1,552评论 0 6