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 {@Resourceprivate Configuration configuration;@Testpublic 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 handlergetTemplateExceptionHandler().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

Freemarker日志优化输出相关推荐

iOS 10、Xcode 8 遇到部分问题解决记录（包括控制台日志不输出）
iOS 10.Xcode 8 遇到部分问题解决记录(包括控制台日志不输出) 参考文章: (1)iOS 10.Xcode 8 遇到部分问题解决记录(包括控制台日志不输出) (2)https://www. ...
shell脚本提取服务器一段时间的日志并输出异常结果
shell脚本提取服务器一段时间的日志并输出异常结果参考文章: (1)shell脚本提取服务器一段时间的日志并输出异常结果 (2)https://www.cnblogs.com/cheerjude/ ...
实例介绍,如何在开发中将各层日志归类输出.
最近开发的模块中,日志文件的输出很郁闷,基于xml配置的,先不说好坏,至少个人很不适应那种配置方式,所以今天谈一下日志分层控制输出. 在开发中,大多都基于一定的框架模式,框架模式降低了模块间的耦合性. ...
linux 输出gc日志,Tomcat输出保存JVM GC日志文件
当系统出现问题时,分析java虚拟机GC日志可以帮助我们定位问题,一般来说, 我们可以通过制定JVM参数使tomcat保存GC日志文件,具体实现如下: Windows下找到tomcat的解压目录,进 ...
SpringBoot的日志管理(输出级别，输出到文件)
场景 SpringBoot实战项目搭建专栏地址: https://blog.csdn.net/BADAO_LIUMANG_QIZHI/column/info/35688 1.SpringBoot使用默 ...
修改Keepalived配置文件位置以及重定向Keepalived日志的输出路径
欢迎支持笔者新作:<深入理解Kafka:核心设计与实践原理>和<RabbitMQ实战指南>,同时欢迎关注笔者的微信公众号:朱小厮的博客. 欢迎跳转到本文的原文链接:https: ...
Unity3D打包后日志文件输出目录
Unity3D打包后日志文件输出目录,包括日志文件和崩溃时记录文件 C:\Users\Administrator\AppData\LocalLow\长沙迪迈科股份有限公司\镍矿探秘其中". ...
pycharm console日志如何输出到txt_日志记录——logging模块
Logging:日志记录是为了跟踪记录软件运行时,发生的事件,包括出错,提示信息等等. log日志级别:日志级别大小关系为:CRITICAL > ERROR > WARNING > ...
SpringBoot默认日志配置输出级别
点击关注公众号,实用技术文章及时了解来源:blog.csdn.net/csdn18740599042 /article/details/109031005 Springboot默认配置我们在测试类 ...

Freemarker日志优化输出

Freemarker错误日志优化

freemarker的使用

排查过程

总结

Freemarker日志优化输出相关推荐

最新文章

热门文章