Freemarker日志优化输出

满小满

已于 2022-10-27 19:45:23 修改

阅读量1.6k

点赞数

分类专栏：后台 java 文章标签： java 服务器 freemarker

于 2022-10-25 12:05:12 首次发布

本文链接：https://blog.csdn.net/mjm_1251162714/article/details/127507031

版权

java 同时被 2 个专栏收录

9 篇文章 0 订阅

订阅专栏

后台

5 篇文章 0 订阅

订阅专栏

Freemarker错误日志优化

场景：生产服务有个短信内容填充功能，具体是录入一个模板如：您的验证码为${验证码}，传入参数"验证码":“123456”。通过freemarker模板引擎填充参数进入到模板，最终生成一条完整的短信内容：您的验证码为123456。但是当传入的参数名称对应不上模板的变量名称时候，freemarker工具会自己先抛出一次异常，之后服务主动catch又输出了一次异常，由于生产该模块访问量巨大导致了服务生成了大量的冗余文件，看的糟心，于是想对该部分代码进行优化处理。假如没耐心的小伙伴可以掠过排查过程，直接看freemarker的使用以及总结

freemarker的使用

先简单介绍下freemarker的基本使用，即如何录入模板填充内容，直接上代码

import freemarker.cache.StringTemplateLoader;
import freemarker.template.Configuration;
import freemarker.template.Template;

@SpringBootTest
@RunWith(SpringRunner.class)
public class SmsTest {

    @Resource
    private Configuration configuration;

    @Test
    public void templateTest() {
        try (StringWriter writer = new StringWriter()) {
            StringTemplateLoader stringLoader = new StringTemplateLoader();
            //1、录入模板
            stringLoader.putTemplate("smsTemplate", "您的验证码为${验证码}");
            configuration.setTemplateLoader(stringLoader);
            Template template = configuration.getTemplate("smsTemplate", "utf-8");
            Map<String, String> param = new HashMap<>();
            param.put("验证码", "123456");
            //传入参数和变量名称不一致情况 param.put("code","123456")
            //2、填充内容
            template.process(param, writer);
            String destContent = writer.toString();
            System.out.println(destContent);
        }catch (Exception e) {
            System.out.println("异常：" + e);
        }
    }
}

上图中正常使用freemarker填充内容，且传入的参数和模板变量是一致的，理想状态是的情况，当时当传入的变量名称不对，如修改 param.put(“验证码”,“123456”) 该行代码修改为 param.put(“code”,“123456”)后，在填充内容进去的时候程序输出了两次错误信息。

2022-10-25 10:05:34 ERROR [server-name,,,] freemarker.runtime.error(59) Error executing FreeMarker template
freemarker.core.InvalidReferenceException: The following has evaluated to null or missing:
==> 验证码  [in template "smsTemplate" at line 1, column 9]

----
Tip: If the failing expression is known to legally refer to something that's sometimes null or missing, either specify a default value like myOptionalVar!myDefault, or use <#if myOptionalVar??>when-present<#else>when-missing</#if>. (These only cover the last step of the expression; to cover the whole expression, use parenthesis: (myOptionalVar.foo)!myDefault, (myOptionalVar.foo)??
----

----
FTL stack trace ("~" means nesting-related):
	- Failed at: ${验证码}  [in template "smsTemplate" at line 1, column 7]
----
	at freemarker.core.InvalidReferenceException.getInstance(InvalidReferenceException.java:134)
	at freemarker.core.EvalUtil.coerceModelToTextualCommon(EvalUtil.java:467)
	at freemarker.core.EvalUtil.coerceModelToStringOrMarkup(EvalUtil.java:389)
	at freemarker.core.EvalUtil.coerceModelToStringOrMarkup(EvalUtil.java:358)
	at freemarker.core.DollarVariable.calculateInterpolatedStringOrMarkup(DollarVariable.java:100)
	at freemarker.core.DollarVariable.accept(DollarVariable.java:63)
	at freemarker.core.Environment.visit(Environment.java:330)
	at freemarker.core.Environment.visit(Environment.java:336)
	at freemarker.core.Environment.process(Environment.java:309)
	at freemarker.template.Template.process(Template.java:384)
	at servername.templateTest(SmsTest.java:39)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
	at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
	at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
	at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
	at org.springframework.test.context.junit4.statements.RunBeforeTestMethodCallbacks.evaluate(RunBeforeTestMethodCallbacks.java:75)
	at org.springframework.test.context.junit4.statements.RunAfterTestMethodCallbacks.evaluate(RunAfterTestMethodCallbacks.java:86)
	at org.springframework.test.context.junit4.statements.SpringRepeat.evaluate(SpringRepeat.java:84)
	at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:325)
	at org.springframework.test.context.junit4.SpringJUnit4ClassRunner.runChild(SpringJUnit4ClassRunner.java:252)
	at org.springframework.test.context.junit4.SpringJUnit4ClassRunner.runChild(SpringJUnit4ClassRunner.java:94)
	at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
	at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
	at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
	at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
	at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
	at org.springframework.test.context.junit4.statements.RunBeforeTestClassCallbacks.evaluate(RunBeforeTestClassCallbacks.java:61)
	at org.springframework.test.context.junit4.statements.RunAfterTestClassCallbacks.evaluate(RunAfterTestClassCallbacks.java:70)
	at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
	at org.springframework.test.context.junit4.SpringJUnit4ClassRunner.run(SpringJUnit4ClassRunner.java:191)
	at org.junit.runner.JUnitCore.run(JUnitCore.java:137)
	at com.intellij.junit4.JUnit4IdeaTestRunner.startRunnerWithArgs(JUnit4IdeaTestRunner.java:69)
	at com.intellij.rt.junit.IdeaTestRunner$Repeater.startRunnerWithArgs(IdeaTestRunner.java:33)
	at com.intellij.rt.junit.JUnitStarter.prepareStreamsAndStart(JUnitStarter.java:220)
	at com.intellij.rt.junit.JUnitStarter.main(JUnitStarter.java:53)
《================================ 以下是捕获的异常 =========================》
异常：freemarker.core.InvalidReferenceException: The following has evaluated to null or missing:
==> 验证码  [in template "smsTemplate" at line 1, column 9]

----
Tip: If the failing expression is known to legally refer to something that's sometimes null or missing, either specify a default value like myOptionalVar!myDefault, or use <#if myOptionalVar??>when-present<#else>when-missing</#if>. (These only cover the last step of the expression; to cover the whole expression, use parenthesis: (myOptionalVar.foo)!myDefault, (myOptionalVar.foo)??
----

----
FTL stack trace ("~" means nesting-related):
	- Failed at: ${验证码}  [in template "smsTemplate" at line 1, column 7]
----

从上图日志可以看出，总共打印了两次错误信息输出。一次是freemarker自己输出了一次错误信息，一次是我们服务自己捕获并输出的错误信息。这一个简单的模板填充就输出了一堆冗余日志，属实浪费资源，该类型日志多了还不利于排查其他问题。于是想着如何才能关闭freemarker的错误信息输出。

排查过程

1、根据输出的错误日志可以看到，freemarker工具类是主动抛出的InvalidReferenceException异常，进入该源码可以看到静态方法封装了错误信息存放入errDescBuilder变量中，InvalidReferenceException继承了TemplateException。

static InvalidReferenceException getInstance(Expression blamed, Environment env) {
        if (env != null && env.getFastInvalidReferenceExceptions()) {
            return FAST_INSTANCE;
        } else if (blamed == null) {
            return new InvalidReferenceException(env);
        } else {
            _ErrorDescriptionBuilder errDescBuilder = (new _ErrorDescriptionBuilder("The following has evaluated to null or missing:")).blame(blamed);
            if (endsWithDollarVariable(blamed)) {
                errDescBuilder.tips(new Object[]{"Variable references must not start with \"$\", unless the \"$\" is really part of the variable name.", TIP});
            } else if (blamed instanceof Dot) {
                String rho = ((Dot)blamed).getRHO();
                String nameFixTip = null;
                if ("size".equals(rho)) {
                    nameFixTip = "To query the size of a collection or map use ?size, like myList?size";
                } else if ("length".equals(rho)) {
                    nameFixTip = "To query the length of a string use ?length, like myString?size";
                }

                errDescBuilder.tips(nameFixTip == null ? new Object[]{"It's the step after the last dot that caused this error, not those before it.", TIP} : new Object[]{"It's the step after the last dot that caused this error, not those before it.", nameFixTip, TIP});
            } else if (blamed instanceof DynamicKeyName) {
                errDescBuilder.tips(new Object[]{"It's the final [] step that caused this error, not those before it.", TIP});
            } else if (blamed instanceof Identifier && ((Identifier)blamed).getName().equals("JspTaglibs")) {
                errDescBuilder.tips(new Object[]{"The \"JspTaglibs\" variable isn't a core FreeMarker feature; it's only available when templates are invoked through freemarker.ext.servlet.FreemarkerServlet (or other custom FreeMarker-JSP integration solution).", TIP});
            } else {
                errDescBuilder.tip(TIP);
            }

            return new InvalidReferenceException(errDescBuilder, env, blamed);
        }
    }

2、源码中确定了freemarker自己组装了错误抛出，现还需要知道是哪块代码打印了错误信息，我们可以通过源码一步步逆推回去逐步分析，这里省略了枯燥逆推过程，赶兴趣的小伙伴可以自己断点调式，

/**
     * Processes the template to which this environment belongs to.
     */
    public void process() throws TemplateException, IOException {
        Object savedEnv = threadEnv.get();
        threadEnv.set(this);
        try {
            // Cached values from a previous execution are possibly outdated.
            clearCachedValues();
            try {
                doAutoImportsAndIncludes(this);
                visit(getTemplate().getRootTreeNode());
                // It's here as we must not flush if there was an exception.
                if (getAutoFlush()) {
                    out.flush();
                }
            } finally {
                // It's just to allow the GC to free memory...
                clearCachedValues();
            }
        } finally {
            threadEnv.set(savedEnv);
        }
    }

    /**
     * "Visit" the template element.
     */
    void visit(TemplateElement element) throws IOException, TemplateException {
        // ATTENTION: This method body is manually "inlined" into visit(TemplateElement[]); keep them in sync!
        pushElement(element);
        try {
            TemplateElement[] templateElementsToVisit = element.accept(this);
            if (templateElementsToVisit != null) {
                for (TemplateElement el : templateElementsToVisit) {
                    if (el == null) {
                        break;  // Skip unused trailing buffer capacity 
                    }
                    visit(el);
                }
            }
        } catch (TemplateException te) {
            handleTemplateException(te);
        } finally {
            popElement();
        }
        // ATTENTION: This method body above is manually "inlined" into visit(TemplateElement[]); keep them in sync!
    }

3、process是freemarker填充内容时候条用的方法，process会调用visit方法对模板分析填充，当抛出InvalidReferenceException异常的时候visi方法会捕获该异常，并执行handleTemplateException方法，进入handleTemplateException方法查看具体的代码实现

    private void handleTemplateException(TemplateException templateException)
           throws TemplateException {
       if (templateException instanceof TemplateModelException
               && ((TemplateModelException) templateException).getReplaceWithCause()
               && templateException.getCause() instanceof TemplateException) {
           templateException = (TemplateException) templateException.getCause();
       }
       
       // Logic to prevent double-handling of the exception in
       // nested visit() calls.
       if (lastThrowable == templateException) {
           throw templateException;
       }
       lastThrowable = templateException;

       if (getLogTemplateExceptions() && LOG.isErrorEnabled()
               && !isInAttemptBlock() /* because then the AttemptExceptionReporter will report this */) {
           LOG.error("Error executing FreeMarker template", templateException);
       }

       try {
           // Stop exception is not passed to the handler, but
           // explicitly rethrown.
           if (templateException instanceof StopException) {
               throw templateException;
           }
   
           // Finally, pass the exception to the handler
           getTemplateExceptionHandler().handleTemplateException(templateException, this, out);
       } catch (TemplateException e) {
           // Note that if the TemplateExceptionHandler doesn't rethrow the exception, we don't get in there.
           if (isInAttemptBlock()) {
               this.getAttemptExceptionReporter().report(templateException, this);
           }
           throw e;
       }
   }

4、由源码中可知当getLogTemplateExceptions() 为真，LOG.isErrorEnabled()为真，isInAttemptBlock() 为假的时候，工具类输出了具体的错误信息。那么只要让这里的条件有一个不成立即不会输出错入日志。getLogTemplateExceptions是用来判断是否输出模板错误信息的，LOG.isErrorEnabled()是工具类不输出错误信息。freemarker工具自身记录了模板错误信息，当getLogTemplateExceptions方法为true的时候会输出一遍模板错误信息，现在只要让这个方法为false即可处理这个问题。

    public boolean getLogTemplateExceptions() {
        return this.logTemplateExceptions != null ? this.logTemplateExceptions : (this.parent != null ? this.parent.getLogTemplateExceptions() : true);
    }

5、logTemplateExceptions 该属性默认是true，工具类默认是记录并主动输出一遍异常。可以看出这个logTemplateExceptions 应该是一个配置项，只要找到在哪里设置的配置设置为false即可
在这里插入图片描述
6、找到freemarker的配置demo，如下图中settings配置是用来传递具体配置信息进来的，传入key为logTemplateExceptions或者log_template_exception都可以，值为false

@ConfigurationProperties(
    prefix = "spring.freemarker"
)
public class FreeMarkerProperties extends AbstractTemplateViewResolverProperties {
    public static final String DEFAULT_TEMPLATE_LOADER_PATH = "classpath:/templates/";
    public static final String DEFAULT_PREFIX = "";
    public static final String DEFAULT_SUFFIX = ".ftl";
    private Map<String, String> settings = new HashMap();
    private String[] templateLoaderPath = new String[]{"classpath:/templates/"};
    private boolean preferFileSystemAccess = true;

    public FreeMarkerProperties() {
        super("", ".ftl");
    }

    public Map<String, String> getSettings() {
        return this.settings;
    }

    public void setSettings(Map<String, String> settings) {
        this.settings = settings;
    }

    public String[] getTemplateLoaderPath() {
        return this.templateLoaderPath;
    }

    public boolean isPreferFileSystemAccess() {
        return this.preferFileSystemAccess;
    }

    public void setPreferFileSystemAccess(boolean preferFileSystemAccess) {
        this.preferFileSystemAccess = preferFileSystemAccess;
    }

    public void setTemplateLoaderPath(String... templateLoaderPaths) {
        this.templateLoaderPath = templateLoaderPaths;
    }
}

7、springboot配置文件中加入该配置属性

# freemarker不输出模板错误信息
spring.freemarker.settings.logTemplateExceptions=false

总结

freemarker自身已经记录了错误的详细内容，当我们服务自身又捕获输出异常就会有两个重复的错误信息输出到日志当中，可以在配置项目中设置freemarker为默认不输出错误信息，具体的是springboot配置文件中添加spring.freemarker.settings.logTemplateExceptions=false。freemarker的其他配置也可以参考官方文档，官方文档链接http://freemarker.foofun.cn/pgui_misc_logging.html