【问题经验】请求头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、网关等等这些中间节点都是考虑的内容。