【问题经验】请求头Accept-Language:*导致freemarker异常 NegativeArraySizeException

1 现象

     现象很简单,日志里不停打印异常,请求url很普通就是首页,抛出异常是NegativeArraySizeException

Caused by: org.springframework.context.ApplicationContextException: Could not load FreeMarker template for URL [/templates/index.ftl]; nested exception is java.io.IOException: There was an error loading the template on an earlier attempt; it is attached as a cause
        at org.springframework.web.servlet.view.freemarker.FreeMarkerView.checkResource(FreeMarkerView.java:219)
        at org.springframework.web.servlet.view.UrlBasedViewResolver.loadView(UrlBasedViewResolver.java:509)
        at org.springframework.web.servlet.view.AbstractCachingViewResolver.createView(AbstractCachingViewResolver.java:244)
        at org.springframework.web.servlet.view.UrlBasedViewResolver.createView(UrlBasedViewResolver.java:472)
        at org.springframework.web.servlet.view.AbstractCachingViewResolver.resolveViewName(AbstractCachingViewResolver.java:146)
        at org.springframework.web.servlet.DispatcherServlet.resolveViewName(DispatcherServlet.java:1296)
        at org.springframework.web.servlet.DispatcherServlet.render(DispatcherServlet.java:1234)
        at org.springframework.web.servlet.DispatcherServlet.processDispatchResult(DispatcherServlet.java:1037)
        at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:980)
        at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:897)
        at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:970)
        ... 45 more
Caused by: java.io.IOException: There was an error loading the template on an earlier attempt; it is attached as a cause
        at freemarker.cache.TemplateCache.throwLoadFailedException(TemplateCache.java:399)
        at freemarker.cache.TemplateCache.getTemplate(TemplateCache.java:279)
        at freemarker.cache.TemplateCache.getTemplate(TemplateCache.java:235)
        at freemarker.template.Configuration.getTemplate(Configuration.java:578)
        at freemarker.template.Configuration.getTemplate(Configuration.java:550)
        at org.springframework.web.servlet.view.freemarker.FreeMarkerView.getTemplate(FreeMarkerView.java:351)
        at org.springframework.web.servlet.view.freemarker.FreeMarkerView.checkResource(FreeMarkerView.java:204)
        ... 55 more
Caused by: java.io.IOException: There was an error loading the template on an earlier attempt; it is attached as a cause
        at freemarker.cache.TemplateCache.throwLoadFailedException(TemplateCache.java:399)
        at freemarker.cache.TemplateCache.getTemplate(TemplateCache.java:275)
        ... 60 more
Caused by: java.lang.NegativeArraySizeException
        at java.lang.AbstractStringBuilder.<init>(AbstractStringBuilder.java:68)
        at java.lang.StringBuffer.<init>(StringBuffer.java:128)
        at freemarker.cache.TemplateCache.concatPath(TemplateCache.java:697)
        at freemarker.cache.TemplateCache.acquireTemplateSource(TemplateCache.java:664)
        at freemarker.cache.TemplateCache.findTemplateSource(TemplateCache.java:622)
        at freemarker.cache.TemplateCache.getTemplate(TemplateCache.java:346)

2 解决方案

    确认一下项目的freemarker版本是不是2.3.19以下(包括2.3.19),请求头是不是包含Accept-Language:* 。freemarker在2.3.20已经解决了这个问题,直接升级freemarker版本(2.3.20以上的版本)就可以解决问题

3 分析过程

    注:如果只是想解决问题,升级版本就好了,以下内容不用看了。

    公司的项目是4个机房、每个机房部署4台机器,这个问题是通过日志发现。现象是:有一个机房(下文称机房A)不停的打印这个异常,另外3个机房却没有。

    3.1 调用栈

 问题的直接原因就是模版path里面有字符"*",然后freemarker把"/*"去掉。变量lastAsterisk初始化为-1,用"/"分割后没有匹配到"*",所以lastAsterisk一直是-1,最后concatPath(tokenPath, 0, lastAsterisk)就抛出了NegativeArraySizeException异常。直接原因是清楚的但是为什么这个请求能踩到这个坑里面,还得继续分析,才能对症修改

public class TemplateCache {
    ......    
    private Object acquireTemplateSource(String path) throws IOException{
        int asterisk = path.indexOf(ASTERISK);
        // Shortcut in case there is no acquisition
        if(asterisk == -1)
        {
            return templateLoader.findTemplateSource(path);
        }
        StringTokenizer tok = new StringTokenizer(path, "/");
        int lastAsterisk = -1;
        List tokpath = new ArrayList();
        while(tok.hasMoreTokens())
        {
            String pathToken = tok.nextToken();
            if(pathToken.equals(ASTERISKSTR))
            {
                if(lastAsterisk != -1)
                {
                    tokpath.remove(lastAsterisk);
                }
                lastAsterisk = tokpath.size();
            }
            tokpath.add(pathToken);
        }
        //笔者注:这个场景是lastAsterisk为负数,然后抛了异常
        String basePath = concatPath(tokpath, 0, lastAsterisk);
        ......
    }
    ......
}

    3.2 对比不同机房的应用配置

    不同机房表现不一样首先想到的就是机房的应用配置不同,所以我们拉下来各个机房的配置项,对比并未发现freemarker配置的有什么不同。进一步猜测是不是编译打包的问题,所以我们直接解压项目的部署包里面的配置项,也并未发现异常。

    3.3 尝试复现

     既然配置未发现异常,我们就尝试复现,用http请求工具请求同样的url。奇怪的是返回结果正常,并未抛出异常。但是这个日志还是在不停的打,只不过我们自己发出的请求并未异常。复现过程中,还出现过一个奇怪现象,机房A(有问题的机房)中,3台机器在执行一次模拟请求后,日志不在打印。就一台机器(下文称机器A-1)还是一直打异常。

      简单的发请求并未复现,应该是有问题的请求上带了什么header信息,我们就加日志把请求头打出来。发现有问题的请求带了4、5个请求头:

GET / HTTP/1.1
Accept: */*
Accept-Language: *
Accept-Encoding: gzip, deflate
Connection: close

第一眼看上去都是比较普通的请求头, 不像有问题。不过还是尝试逐个添加请求头发模拟请求,最后发现"Accept-Language: *"请求头会导致异常。仔细分析以下这个跟freemarker的源码对上了,因为模版路径是这样拼成的:模版文件路径 + "_" + locale。locale就是来自于请求头"Accept-Language"。所以有问题的请求路径就是 /templates/index_*.ftl正好踩中freemarker的坑。

    问题上基本就是这样,现在还有2个疑点没有想通:

  • (1) 为什么另外3个机房没有问题?
  • (2) 为什么机房A中其它机器执行一次模拟请求后就正常了,而机器A-1却怎么也不正常? 

从疑点(2)"机房A中其它机器执行一次模拟请求后就正常了"这个现象判断,大概率是因为这个请求有缓存,执行一次模拟请求正常后,之后的这个页面请求都能命中缓存所以就不打印异常日志了(freemarker的缓存使用可以参考freemarker缓存)。那么疑点(1)疑点(2)归为一个点就是为啥机器A-1一直不能命中缓存?同一个机房的配置肯定是相同的这个毋庸置疑。机器A-1怎么没有缓存?最后祭出杀手锏jvm dump分析,dump一份机器A-1的内存现场下来,打开看看freemarker的缓存配置果然没有生效。

cacheLimit为0就意味着springmvc不缓存视图,默认是1024(参考freemarker缓存)。最后看了发布记录才知道,之前的同事为了查其它的问题把缓存关掉了(cacheLimit设置为0),并且只发布了机器A-1。这就是机器A-1命不中缓存的原因。

    至此所有问题疑点都清楚,原本准备提report给freemarker官网。然后在看看高版本有没有问题的时候发现已经解决,从2.3.20版本开始已经没有问题。所以呢,把freemarker版本升到2.3.20以上即可!

if (lastAsterisk == -1) {  // if there was no real "*" step after all
    return TemplateLookupResult.from(path, findTemplateSource(path));
}

4 总结

    问题原因就是:Accept-Language请求头的值为"*"时会踩到低版本freemarker(2.3.20以上没有问题)的一个坑里面。在这个问题分析过程总结以下几点经验:

  • (1) 分析问题一定不要放过任何一个现象,这些现象要么给我们带来思路、启发,要么就是要解释清楚为什么有这个现象(不同机房为什么表现不一样,同一机房不同机器又为什么不一样);
  • (2) 复现问题不要想当然认为都是常见配置,就不去尝试,遇到过太多次常见配置导致的问题(本例中Accept-Language);
  • (3) 当一个问题不好复现时,我们要构造尽量跟原请求一致的模拟请求:请求头、请求经过的路径都要无限接近。请求有没有过cdn、ng、网关等等这些中间节点都是考虑的内容。

 

  • 0
    点赞
  • 0
    收藏
    觉得还不错? 一键收藏
  • 0
    评论

“相关推荐”对你有帮助么?

  • 非常没帮助
  • 没帮助
  • 一般
  • 有帮助
  • 非常有帮助
提交
评论
添加红包

请填写红包祝福语或标题

红包个数最小为10个

红包金额最低5元

当前余额3.43前往充值 >
需支付:10.00
成就一亿技术人!
领取后你会自动成为博主和红包主的粉丝 规则
hope_wisdom
发出的红包
实付
使用余额支付
点击重新获取
扫码支付
钱包余额 0

抵扣说明:

1.余额是钱包充值的虚拟货币,按照1:1的比例进行支付金额的抵扣。
2.余额无法直接购买下载,可以购买VIP、付费专栏及课程。

余额充值