那些让人喜欢的注释和日志

最新推荐文章于 2020-12-19 11:28:11 发布

lang20150928

最新推荐文章于 2020-12-19 11:28:11 发布

阅读量313

点赞数

分类专栏：其他文章标签： java

本文链接：https://blog.csdn.net/m0_37607945/article/details/105359167

版权

其他专栏收录该内容

54 篇文章 0 订阅

订阅专栏

去年有幸拿到公司质量之星的奖励，然后质量体系部就要求每一个获奖的同学呢能就某一个点谈谈自己的见解，我当时想了一个主题：那些让人喜欢的注释和日志。其实无非就是java的注释规范和日志规范。每一个熟悉java的同学应当对阿里巴巴开发手册有一定的了解吧，本人对这个规范比较推崇。

如果真要说心得，那就是直接按照阿里的规范就好了。可能这个主题分享不用几分钟就结束了。
在这里插入图片描述
后来我想到了一个词，叫知行合一，很多时候，我们并非不知道，但难的就是如何能做到。本人呢，也就结合"那些让我喜欢的注释和日志"进行深入探讨这个手册的内容。

那些让人喜欢的注释

作为Java程序员，对于下面这个问题应该不会陌生

能谈谈你对HashMap的认识吗

如果你以前对这个问题没有深入的思考，想要学习一下，你会怎么去做呢？
可能绝大多数的人会想到百度
在这里插入图片描述
当然也有人查询专业书籍，比如

还可能去查询官方文档
https://docs.oracle.com/javase/tutorial/collections/implementations/map.html

我上面说这个的意思是啥呢？其实我们忽略了一个很重要的学习途径，那就是看注释。或者说我们对注释的作用还缺乏深入的理解。
在IDE编辑窗口中，可以很方便的查看一个类的注释。
比如IDEA：
在这里插入图片描述
比如Eclipse

可以看到从这个弹出的框体中显示了HashMap这个类的注释。
那么我们来看一下HashMap类的注释。

先引申一点，很多同学英语不好，对英语很排斥，可以通过翻译软件来协助，比如谷歌翻译、有道翻译等等、当然，下定决心拿下英语才是最终解决之道。
在这里插入图片描述
通过这些注释，可以快速的了解HashMap这个类的作用以及使用方法，包括一些实现逻辑和使用注意事项。从某种程度上也说明了注释的作用。我们为啥要注释呢？不需要注释不可以吗？仅仅是因为别人让你写注释你就要写注释吗？如果我们连为啥要写注释都不清楚或者排斥写注释的话，就不可能写出符合规范的注释，或者说好的注释。

那么为啥要写注释呢？本人认为有以下几点：

使用者或维护者快速理解：这个类是用来干啥的，有什么作用，该如何用，有哪些注意事项
编写者官方声明：写注释的过程就给一个类做介绍，如何简单而又不失重点，很有挑战性

如果你不想别人快速理解这个类的用途，或者自己写完了看都不想看，那么你可以不写注释了。

在我工作中，还遇到如下的几种排斥写注释的理由：

好的代码是自解释的，不需要注释
业务逻辑多变，注释往往是错的

针对第一个理由，本人觉得别人使用你的代码或接口，为什么非要去读你的源码呢？在IDE里面编辑的时候就能提示如何使用或注意事项不更方便吗？节省别人的时间，这是一种负责任的表现。节省一个调用者一分钟，那么十个调用者呢？那就是十分钟。如果十个方法不写注释，十个调用者来调用，你不写注释和写注释，就是一百分钟的差距。无论对于公司还是团队，这都是不可估量的。所以，代码自解释不是不写注释的理由。

针对第二个理由，注释往往是错的，这是因为注释的不规范或者对注释的不重视导致的，注释没有错，这个怪注释往往是错的思维很让人费解。

针对此类情形，可以参考阿里开发手册如下说明：
在这里插入图片描述

最后还有一个是本人自己的心得，很多时候对业务理解不清，然后想动手去写注释，发现无从下手。这也说明一个问题，我们对自己写的代码理解不透，所以写不出注释。

上面几个原因都不是我们拒绝注释的理由。

在阿里巴巴Java开发手册中，就很明确对注释的要求，如下：

对于注释的要求：第一、能够准备反应设计思维和代码逻辑；第二、能够描述业务含义，使别的程序员能够迅速了解代码背后的信息。完全没有注释的大段代码对于阅读者形同天书，注释是给自己看的，即使隔很长时间，也能清晰理解当时的思路；注释也是给继任者看的，使其能够快速接替自己的工作。

在jdk中，绝大多数常用的类的注释都是写的非常棒的。下面我们从中学习一下：

类上的注解

继续分析HashMap中的注释是如何符合代码规范的。

/**
 * Hash table based implementation of the <tt>Map</tt> interface.  This
 * implementation provides all of the optional map operations, and permits
 * <tt>null</tt> values and the <tt>null</tt> key.  (The <tt>HashMap</tt>
 * class is roughly equivalent to <tt>Hashtable</tt>, except that it is
 * unsynchronized and permits nulls.)  This class makes no guarantees as to
 * the order of the map; in particular, it does not guarantee that the order
 * will remain constant over time.
 *
 *  此处省略一万行
 *
 * <p>This class is a member of the
 * <a href="{@docRoot}/../technotes/guides/collections/index.html">
 * Java Collections Framework</a>.
 *
 * @param <K> the type of keys maintained by this map
 * @param <V> the type of mapped values
 *
 * @author  Doug Lea
 * @author  Josh Bloch
 * @author  Arthur van Hoff
 * @author  Neal Gafter
 * @see     Object#hashCode()
 * @see     Collection
 * @see     Map
 * @see     TreeMap
 * @see     Hashtable
 * @since   1.2
 */

上面的注释都符合哪些规范呢？

【强制】类、类属性、类方法的注释必须使用 Javadoc 规范，使用/*内容/格式，不得使用 // xxx 方式
【强制】所有的类都必须添加创建者和创建日期。

类上注解包括以下几个部分：类的用途、该怎么用、需要注意事项、是谁提供的，什么时候提供的

方法上的注解

/**
 * If the specified key is not already associated with a value (or is mapped
 * to {@code null}) associates it with the given value and returns
 * {@code null}, else returns the current value.
 *
 * @implSpec
 * The default implementation is equivalent to, for this {@code
 * map}:
 *
 * <pre> {@code
 * V v = map.get(key);
 * if (v == null)
 *     v = map.put(key, value);
 *
 * return v;
 * }</pre>
 *
 * <p>The default implementation makes no guarantees about synchronization
 * or atomicity properties of this method. Any implementation providing
 * atomicity guarantees must override this method and document its
 * concurrency properties.
 *
 * @param key key with which the specified value is to be associated
 * @param value value to be associated with the specified key
 * @return the previous value associated with the specified key, or
 *         {@code null} if there was no mapping for the key.
 *         (A {@code null} return can also indicate that the map
 *         previously associated {@code null} with the key,
 *         if the implementation supports null values.)
 * @throws UnsupportedOperationException if the {@code put} operation
 *         is not supported by this map
 *         (<a href="{@docRoot}/java/util/Collection.html#optional-restrictions">optional</a>)
 * @throws ClassCastException if the key or value is of an inappropriate
 *         type for this map
 *         (<a href="{@docRoot}/java/util/Collection.html#optional-restrictions">optional</a>)
 * @throws NullPointerException if the specified key or value is null,
 *         and this map does not permit null keys or values
 *         (<a href="{@docRoot}/java/util/Collection.html#optional-restrictions">optional</a>)
 * @throws IllegalArgumentException if some property of the specified key
 *         or value prevents it from being stored in this map
 *         (<a href="{@docRoot}/java/util/Collection.html#optional-restrictions">optional</a>)
 * @since 1.8
 */
default V putIfAbsent(K key, V value) {
    V v = get(key);
    if (v == null) {
        v = put(key, value);
    }

    return v;
}

在这里插入图片描述
上面这个方法的注释详细包括了这个方法的用途、参数说明、返回说明以及可能出现的异常。

这也完全符合阿里开发手册的规范：
【强制】所有的抽象方法（包括接口中的方法）必须要用 Javadoc 注释、除了返回值、参数、异常说明外，还必须指出该方法做什么事情，实现什么功能。

另外，在代码中不可避免的会存在一些过期的方法，我们会加上@Deprecated注解。那么这样就够了吗？看看jdk中是如果做的。
在这里插入图片描述
这里详细的说明了Thread.suspend()这个方法为啥被废弃的原因，这是非常值得借鉴的。
初始之外呢，针对常用的静态工具类方法，jdk也提供了良好的注释。

所有的抽象方法（包括接口中的方法）必须要用 Javadoc 注释、除了返回值、参数、
异常说明外，还必须指出该方法做什么事情，实现什么功能。常用的工具类方法按照相同的方法，另外对于被废弃使用的方法请说明废弃的原因

枚举类上的注解

经常有人会问，java中的线程存在几个状态？
然后你去百度，可能结果如下：
在这里插入图片描述
可是这个答案就真的对吗？
当我们查看jdk中java.lang.Thread.State这个枚举类的时候：

public enum State {
    /**
     * Thread state for a thread which has not yet started.
     */
    NEW,

    /**
     * Thread state for a runnable thread.  A thread in the runnable
     * state is executing in the Java virtual machine but it may
     * be waiting for other resources from the operating system
     * such as processor.
     */
    RUNNABLE,

    /**
     * Thread state for a thread blocked waiting for a monitor lock.
     * A thread in the blocked state is waiting for a monitor lock
     * to enter a synchronized block/method or
     * reenter a synchronized block/method after calling
     * {@link Object#wait() Object.wait}.
     */
    BLOCKED,

    /**
     * Thread state for a waiting thread.
     * A thread is in the waiting state due to calling one of the
     * following methods:
     * <ul>
     *   <li>{@link Object#wait() Object.wait} with no timeout</li>
     *   <li>{@link #join() Thread.join} with no timeout</li>
     *   <li>{@link LockSupport#park() LockSupport.park}</li>
     * </ul>
     *
     * <p>A thread in the waiting state is waiting for another thread to
     * perform a particular action.
     *
     * For example, a thread that has called <tt>Object.wait()</tt>
     * on an object is waiting for another thread to call
     * <tt>Object.notify()</tt> or <tt>Object.notifyAll()</tt> on
     * that object. A thread that has called <tt>Thread.join()</tt>
     * is waiting for a specified thread to terminate.
     */
    WAITING,

    /**
     * Thread state for a waiting thread with a specified waiting time.
     * A thread is in the timed waiting state due to calling one of
     * the following methods with a specified positive waiting time:
     * <ul>
     *   <li>{@link #sleep Thread.sleep}</li>
     *   <li>{@link Object#wait(long) Object.wait} with timeout</li>
     *   <li>{@link #join(long) Thread.join} with timeout</li>
     *   <li>{@link LockSupport#parkNanos LockSupport.parkNanos}</li>
     *   <li>{@link LockSupport#parkUntil LockSupport.parkUntil}</li>
     * </ul>
     */
    TIMED_WAITING,

    /**
     * Thread state for a terminated thread.
     * The thread has completed execution.
     */
    TERMINATED;
}

在这里插入图片描述
很明显，是有出入的。
首先分类不一样，其次解释也不一样。
就选取一点，关于RUNNABLE的解释：

百度博客：线程对象创建后，其他线程(比如main线程）调用了该对象的start()方法。该状态的线程位于可运行线程池中，等待被线程调度选中，获取cpu 的使用权。

jdk注解：

/**
 * Thread state for a runnable thread.  A thread in the runnable
 * state is executing in the Java virtual machine but it may
 * be waiting for other resources from the operating system
 * such as processor.
 */
RUNNABLE,

可运行线程的线程状态。处于可运行状态的线程正在Java虚拟机中执行，但是它可能正在等待来自操作系统（例如处理器）的其他资源。

博客中说的等待被线程调度选中在jdk中指的是NEW这个状态

如果不是看了这个注解，或者没有注解，那是不是每个人都可以有自己关于线程状态的看法？这也从另一方面说明了注解的重要性–官方说明。

【强制】所有的枚举类型字段必须要有注释，说明每个数据项的用途。

方法内的注释

针对方法内的注解，更多是给代码编写者以及后来维护者看的，当然有意了解实现原理的也同样。
首先看一下如下的方法实现

private void setHeadAndPropagate(Node node, int propagate) {
    Node h = head; // Record old head for check below
    setHead(node);
    /*
     * Try to signal next queued node if:
     *   Propagation was indicated by caller,
     *     or was recorded (as h.waitStatus either before
     *     or after setHead) by a previous operation
     *     (note: this uses sign-check of waitStatus because
     *      PROPAGATE status may transition to SIGNAL.)
     * and
     *   The next node is waiting in shared mode,
     *     or we don't know, because it appears null
     *
     * The conservatism in both of these checks may cause
     * unnecessary wake-ups, but only when there are multiple
     * racing acquires/releases, so most need signals now or soon
     * anyway.
     */
    if (propagate > 0 || h == null || h.waitStatus < 0 ||
        (h = head) == null || h.waitStatus < 0) {
        Node s = node.next;
        if (s == null || s.isShared())
            doReleaseShared();
    }
}

上面的多行注释没啥问题，但是对于单行注释呢，本人不是很赞同放在代码的后面。为啥呢？对于很多时候单行代码比较长的时候，如果注释不换行就不方便阅读了，如果换行就会让人以后注解是针对后面的代码的。

改成如下的方式，会更好一点：

private void setHeadAndPropagate(Node node, int propagate) {
	// Record old head for check below
    Node h = head; 
    setHead(node);
    /*
     * Try to signal next queued node if:
     *   Propagation was indicated by caller,
     *     or was recorded (as h.waitStatus either before
     *     or after setHead) by a previous operation
     *     (note: this uses sign-check of waitStatus because
     *      PROPAGATE status may transition to SIGNAL.)
     * and
     *   The next node is waiting in shared mode,
     *     or we don't know, because it appears null
     *
     * The conservatism in both of these checks may cause
     * unnecessary wake-ups, but only when there are multiple
     * racing acquires/releases, so most need signals now or soon
     * anyway.
     */
    if (propagate > 0 || h == null || h.waitStatus < 0 ||
        (h = head) == null || h.waitStatus < 0) {
        Node s = node.next;
        if (s == null || s.isShared())
            doReleaseShared();
    }
}

再看看如下代码：

private void cancelAcquire(Node node) {
    // Ignore if node doesn't exist
    if (node == null)
        return;

    node.thread = null;

    // Skip cancelled predecessors
    Node pred = node.prev;
    while (pred.waitStatus > 0)
        node.prev = pred = pred.prev;

    // predNext is the apparent node to unsplice. CASes below will
    // fail if not, in which case, we lost race vs another cancel
    // or signal, so no further action is necessary.
    Node predNext = pred.next;

    // Can use unconditional write instead of CAS here.
    // After this atomic step, other Nodes can skip past us.
    // Before, we are free of interference from other threads.
    node.waitStatus = Node.CANCELLED;

    // If we are the tail, remove ourselves.
    if (node == tail && compareAndSetTail(node, pred)) {
        compareAndSetNext(pred, predNext, null);
    } else {
        // If successor needs signal, try to set pred's next-link
        // so it will get one. Otherwise wake it up to propagate.
        int ws;
        if (pred != head &&
            ((ws = pred.waitStatus) == Node.SIGNAL ||
             (ws <= 0 && compareAndSetWaitStatus(pred, ws, Node.SIGNAL))) &&
            pred.thread != null) {
            Node next = node.next;
            if (next != null && next.waitStatus <= 0)
                compareAndSetNext(pred, predNext, next);
        } else {
            unparkSuccessor(node);
        }

        node.next = node; // help GC
    }
}

对于上面这段代码，我们也不建议，毕竟多行注释使用单行注释的方式很不好。

【强制】方法内部单行注释，在被注释语句上方另起一行，使用//注释。方法内部多行注释使用/* */注释，注意与代码对齐。

类属性的注释

/**
 * The default initial capacity - MUST be a power of two.
 */
static final int DEFAULT_INITIAL_CAPACITY = 1 << 4; // aka 16

/**
 * The maximum capacity, used if a higher value is implicitly specified
 * by either of the constructors with arguments.
 * MUST be a power of two <= 1<<30.
 */
static final int MAXIMUM_CAPACITY = 1 << 30;

/**
 * The load factor used when none specified in constructor.
 */
static final float DEFAULT_LOAD_FACTOR = 0.75f;

针对于类内属性的注释：主要说明这个属性的用途以及一些限制

额外注释

在jdk中有些类比如HashMap或者ConcurrentHashMap中，存在如下的一些注释：
在这里插入图片描述
这些注释详细的说明了HashMap实现的设计思路，对于代码编写者和代码维护者都是非常不错的。因为这种设计思路对于使用者来说并不需要特别关注，而且一般都相当负责，所以不建议放到类上面的注解中，也不是针对于某一个方法的实现，所以像代码块一样放在类中。个人建议，对于某些使用非常频繁的类可以添加这样的注释。

那些让人喜欢的日志

本文不探讨如何配置日志依赖，如何使用日志级别，只是从一些点探索一下我认为的好日志是什么样的。
比如SpringBoot项目启动的时候，控制台就会打印如下的日志：


  .   ____          _            __ _ _
 /\\ / ___'_ __ _ _(_)_ __  __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
 \\/  ___)| |_)| | | | | || (_| |  ) ) ) )
  '  |____| .__|_| |_|_| |_\__, | / / / /
 =========|_|==============|___/=/_/_/_/
 :: Spring Boot ::        (v2.2.5.RELEASE)

2020-04-14 14:09:53.126  INFO 12404 --- [           main] com.example.durid.demo.DemoApplication   : Starting DemoApplication on B940 with PID 12404 (D:\20191030\demo\target\classes started by Administrator in D:\20191030\demo)
2020-04-14 14:09:53.133  INFO 12404 --- [           main] com.example.durid.demo.DemoApplication   : No active profile set, falling back to default profiles: default
2020-04-14 14:09:56.554  INFO 12404 --- [           main] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat initialized with port(s): 8083 (http)
2020-04-14 14:09:56.573  INFO 12404 --- [           main] o.apache.catalina.core.StandardService   : Starting service [Tomcat]
2020-04-14 14:09:56.573  INFO 12404 --- [           main] org.apache.catalina.core.StandardEngine  : Starting Servlet engine: [Apache Tomcat/9.0.31]
2020-04-14 14:09:56.717  INFO 12404 --- [           main] o.a.c.c.C.[Tomcat].[localhost].[/]       : Initializing Spring embedded WebApplicationContext
2020-04-14 14:09:56.717  INFO 12404 --- [           main] o.s.web.context.ContextLoader            : Root WebApplicationContext: initialization completed in 3442 ms
2020-04-14 14:09:58.347  INFO 12404 --- [           main] o.s.s.concurrent.ThreadPoolTaskExecutor  : Initializing ExecutorService 'applicationTaskExecutor'
2020-04-14 14:09:58.724  INFO 12404 --- [           main] c.e.durid.demo.config.DynamicDataSource  : 当前数据源为dataSourceOne
2020-04-14 14:09:58.733  INFO 12404 --- [           main] c.e.durid.demo.config.DynamicDataSource  : 当前数据源为dataSourceOne
2020-04-14 14:09:58.819  INFO 12404 --- [           main] o.s.b.a.e.web.EndpointLinksResolver      : Exposing 13 endpoint(s) beneath base path '/actuator'
2020-04-14 14:09:58.958  INFO 12404 --- [           main] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat started on port(s): 8083 (http) with context path ''
2020-04-14 14:09:58.963  INFO 12404 --- [           main] com.example.durid.demo.DemoApplication   : Started DemoApplication in 6.537 seconds (JVM running for 7.299)

在这里插入图片描述
从上面的日志，我们能了解到什么？首先，项目启动正常，没有问题。第二点，使用的tomcat容器，端口是8083,当前的版本是default.
仅仅几行的日志，至少包含以上三个信息。也就是说，日志其实就像一个人的脸色一样，反应一个人的健康状态或者心情状态，能让你用最少的成本去了解程序目前的运行情况。

然后通过浏览器发起请求：http://localhost:8083/otheruser/list
这时候控制台多了以下的日志：

2020-04-14 14:27:39.035  INFO 4212 --- [nio-8083-exec-1] o.s.web.servlet.DispatcherServlet        : Initializing Servlet 'dispatcherServlet'
2020-04-14 14:27:39.048  INFO 4212 --- [nio-8083-exec-1] o.s.web.servlet.DispatcherServlet        : Completed initialization in 13 ms
2020-04-14 14:27:39.150  INFO 4212 --- [nio-8083-exec-1] c.e.durid.demo.config.DynamicDataSource  : 当前数据源为dataSourceOne
2020-04-14 14:27:39.434  INFO 4212 --- [nio-8083-exec-1] com.alibaba.druid.pool.DruidDataSource   : {dataSource-1} inited
Tue Apr 14 14:27:39 CST 2020 WARN: Establishing SSL connection without server's identity verification is not recommended. According to MySQL 5.5.45+, 5.6.26+ and 5.7.6+ requirements SSL connection must be established by default if explicit option isn't set. For compliance with existing applications not using SSL the verifyServerCertificate property is set to 'false'. You need either to explicitly disable SSL by setting useSSL=false, or set useSSL=true and provide truststore for server certificate verification.

在这里插入图片描述
上面部分启动了DispatcherServlet并初始化，关键我们看看下面那段红色日志

Tue Apr 14 14:27:39 CST 2020 WARN: Establishing SSL connection without server’s identity verification is not recommended. According to MySQL 5.5.45+, 5.6.26+ and 5.7.6+ requirements SSL connection must be established by default if explicit option isn’t set. For compliance with existing applications not using SSL the verifyServerCertificate property is set to ‘false’. You need either to explicitly disable SSL by setting useSSL=false, or set useSSL=true and provide truststore for server certificate verification.

如何解决这个问题呢？
从日志中你能发现什么端倪吗？
在这里插入图片描述
原来的配置如下:

spring.datasource.druid.one.url=jdbc:mysql://127.0.0.1:3306/ms_user
spring.datasource.druid.two.url=jdbc:mysql://127.0.0.1:3306/ms_class

修改我们的配置文件里面关于数据源的url配置（在后面添加useSSL=false）

spring.datasource.druid.one.url=jdbc:mysql://127.0.0.1:3306/ms_user?useSSL=false
spring.datasource.druid.two.url=jdbc:mysql://127.0.0.1:3306/ms_class?useSSL=false

重启并再次请求，就会发现这个红色日志没有了。
有没有觉得这个日志非常贴心呀！
不但告诉你这里有问题，而且告诉你该如何解决问题！

好的日志能突出问题，并尽可能节省你的时间

在这里插入图片描述
不知道在测试的时候遇到这样的异常，大家心里有事没有啥想法啊？

如果我们想知道一个网络请求达到服务器之后的流程是什么样的？我们该怎么办呢？百度？查阅文档？查看源码？应该说最方便的还是分析日志。

logging.level.org.springframework=debug
logging.level.com.example.durid.demo.mapper=TRACE
logging.level.com.example.mybatis.demo.mapper=TRACE

重启项目，发起一个请求（通过postman）
在这里插入图片描述
此时控制台日志如下：

2020-04-14 15:40:51.816  INFO 11112 --- [nio-8083-exec-1] o.a.c.c.C.[Tomcat].[localhost].[/]       : Initializing Spring DispatcherServlet 'dispatcherServlet'
2020-04-14 15:40:51.816  INFO 11112 --- [nio-8083-exec-1] o.s.web.servlet.DispatcherServlet        : Initializing Servlet 'dispatcherServlet'
2020-04-14 15:40:51.816 DEBUG 11112 --- [nio-8083-exec-1] o.s.web.servlet.DispatcherServlet        : Detected StandardServletMultipartResolver
2020-04-14 15:40:51.837 DEBUG 11112 --- [nio-8083-exec-1] o.s.web.servlet.DispatcherServlet        : enableLoggingRequestDetails='false': request parameters and headers will be masked to prevent unsafe logging of potentially sensitive data
2020-04-14 15:40:51.837  INFO 11112 --- [nio-8083-exec-1] o.s.web.servlet.DispatcherServlet        : Completed initialization in 21 ms
2020-04-14 15:40:51.868 DEBUG 11112 --- [nio-8083-exec-1] o.s.web.servlet.DispatcherServlet        : POST "/user/add", parameters={}
2020-04-14 15:40:51.879 DEBUG 11112 --- [nio-8083-exec-1] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped to com.example.durid.demo.controller.UserController#add(User)
2020-04-14 15:40:52.043 DEBUG 11112 --- [nio-8083-exec-1] m.m.a.RequestResponseBodyMethodProcessor : Read "application/json;charset=UTF-8" to [com.example.durid.demo.entity.User@371fdb37]
2020-04-14 15:40:52.065 DEBUG 11112 --- [nio-8083-exec-1] o.s.j.d.DataSourceTransactionManager     : Creating new transaction with name [com.example.durid.demo.service.impl.UserServiceImpl.add]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT
2020-04-14 15:40:52.065  INFO 11112 --- [nio-8083-exec-1] c.e.durid.demo.config.DynamicDataSource  : 当前数据源为dataSourceOne
2020-04-14 15:40:52.146  INFO 11112 --- [nio-8083-exec-1] com.alibaba.druid.pool.DruidDataSource   : {dataSource-1} inited
2020-04-14 15:40:52.612 DEBUG 11112 --- [nio-8083-exec-1] o.s.j.d.DataSourceTransactionManager     : Acquired Connection [com.mysql.jdbc.JDBC4Connection@65094d54] for JDBC transaction
2020-04-14 15:40:52.617 DEBUG 11112 --- [nio-8083-exec-1] o.s.j.d.DataSourceTransactionManager     : Switching JDBC Connection [com.mysql.jdbc.JDBC4Connection@65094d54] to manual commit
2020-04-14 15:40:52.776 DEBUG 11112 --- [nio-8083-exec-1] c.e.durid.demo.mapper.UserMapper.insert  : ==>  Preparing: insert into user (id, username, password, money, role, reg_time ) values (?, ?, ?, ?, ?, ? ) 
2020-04-14 15:40:52.820 DEBUG 11112 --- [nio-8083-exec-1] c.e.durid.demo.mapper.UserMapper.insert  : ==> Parameters: null, steven(String), 123456(String), 100(BigDecimal), user(String), 2020-04-14 15:40:52.634(Timestamp)
2020-04-14 15:40:52.862 DEBUG 11112 --- [nio-8083-exec-1] c.e.durid.demo.mapper.UserMapper.insert  : <==    Updates: 1
2020-04-14 15:40:52.866 DEBUG 11112 --- [nio-8083-exec-1] o.s.j.d.DataSourceTransactionManager     : Initiating transaction commit
2020-04-14 15:40:52.866 DEBUG 11112 --- [nio-8083-exec-1] o.s.j.d.DataSourceTransactionManager     : Committing JDBC transaction on Connection [com.mysql.jdbc.JDBC4Connection@65094d54]
2020-04-14 15:40:52.913 DEBUG 11112 --- [nio-8083-exec-1] o.s.j.d.DataSourceTransactionManager     : Releasing JDBC Connection [com.mysql.jdbc.JDBC4Connection@65094d54] after transaction
2020-04-14 15:40:52.924 DEBUG 11112 --- [nio-8083-exec-1] m.m.a.RequestResponseBodyMethodProcessor : Using 'application/json', given [*/*] and supported [application/json, application/*+json, application/json, application/*+json]
2020-04-14 15:40:52.925 DEBUG 11112 --- [nio-8083-exec-1] m.m.a.RequestResponseBodyMethodProcessor : Writing [true]
2020-04-14 15:40:52.948 DEBUG 11112 --- [nio-8083-exec-1] o.s.web.servlet.DispatcherServlet        : Completed 200 OK

从这个日志中可以很清晰的看出整个请求的一个流程

初始化DispatcherServlet ，当然只在第一次发起请求时执行（懒加载）
接收到一个post请求 “/user/add”
这个请求映射到方法UserController#add(User)
读取json数据并转换为User对象
创建一个新的事务
使用的数据源是dataSourceOne并且进行数据源初始化
获取数据库连接
将数据库连接自动提交改成手动提交（整个事务关键之处）
数据库操作日志
初始化事务提交
进行事务提交
释放数据库连接
使用json序列化返回数据
请求成功返回
看到这个日志，不知道大家有什么感觉？当我们在工作中，发起一个请求之后，如果遇到了一些问题，能否从日志就看出目前流程到哪了呢？下面分析一下Spring框架里面是如何打印这些日志的。
比如创建事务的时候

if (debugEnabled) {
	logger.debug("Creating new transaction with name [" + definition.getName() + "]: " + definition);
}

效果如下：

Creating new transaction with name [com.example.durid.demo.service.impl.UserServiceImpl.add]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT

如果是我们来写的话，你会考虑打印出definition的相关信息吗？
比如如果出现了异常修改一个事务方法将事务修改为readOnly

@Transactional(readOnly = true)
@Override
public boolean add(User user) {
	user.setPassword("123456");
	user.setRegTime(new Date());
    return userMapper.insert(user) == 1;
}

然后发起调用
在这里插入图片描述

2020-04-14 15:55:40.280  INFO 13180 --- [nio-8083-exec-1] o.a.c.c.C.[Tomcat].[localhost].[/]       : Initializing Spring DispatcherServlet 'dispatcherServlet'
2020-04-14 15:55:40.280  INFO 13180 --- [nio-8083-exec-1] o.s.web.servlet.DispatcherServlet        : Initializing Servlet 'dispatcherServlet'
2020-04-14 15:55:40.280 DEBUG 13180 --- [nio-8083-exec-1] o.s.web.servlet.DispatcherServlet        : Detected StandardServletMultipartResolver
2020-04-14 15:55:40.298 DEBUG 13180 --- [nio-8083-exec-1] o.s.web.servlet.DispatcherServlet        : enableLoggingRequestDetails='false': request parameters and headers will be masked to prevent unsafe logging of potentially sensitive data
2020-04-14 15:55:40.298  INFO 13180 --- [nio-8083-exec-1] o.s.web.servlet.DispatcherServlet        : Completed initialization in 18 ms
2020-04-14 15:55:40.322 DEBUG 13180 --- [nio-8083-exec-1] o.s.web.servlet.DispatcherServlet        : POST "/user/add", parameters={}
2020-04-14 15:55:40.329 DEBUG 13180 --- [nio-8083-exec-1] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped to com.example.durid.demo.controller.UserController#add(User)
2020-04-14 15:55:40.505 DEBUG 13180 --- [nio-8083-exec-1] m.m.a.RequestResponseBodyMethodProcessor : Read "application/json;charset=UTF-8" to [com.example.durid.demo.entity.User@715ca4d7]
2020-04-14 15:55:40.523 DEBUG 13180 --- [nio-8083-exec-1] o.s.j.d.DataSourceTransactionManager     : Creating new transaction with name [com.example.durid.demo.service.impl.UserServiceImpl.add]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT,readOnly
2020-04-14 15:55:40.524  INFO 13180 --- [nio-8083-exec-1] c.e.durid.demo.config.DynamicDataSource  : 当前数据源为dataSourceOne
2020-04-14 15:55:40.758  INFO 13180 --- [nio-8083-exec-1] com.alibaba.druid.pool.DruidDataSource   : {dataSource-1} inited
2020-04-14 15:55:41.210 DEBUG 13180 --- [nio-8083-exec-1] o.s.j.d.DataSourceTransactionManager     : Acquired Connection [com.mysql.jdbc.JDBC4Connection@1e087590] for JDBC transaction
2020-04-14 15:55:41.214 DEBUG 13180 --- [nio-8083-exec-1] o.s.jdbc.datasource.DataSourceUtils      : Setting JDBC Connection [com.mysql.jdbc.JDBC4Connection@1e087590] read-only
2020-04-14 15:55:41.216 DEBUG 13180 --- [nio-8083-exec-1] o.s.j.d.DataSourceTransactionManager     : Switching JDBC Connection [com.mysql.jdbc.JDBC4Connection@1e087590] to manual commit
2020-04-14 15:55:41.280 DEBUG 13180 --- [nio-8083-exec-1] c.e.durid.demo.mapper.UserMapper.insert  : ==>  Preparing: insert into user (id, username, password, money, role, reg_time ) values (?, ?, ?, ?, ?, ? ) 
2020-04-14 15:55:41.333 DEBUG 13180 --- [nio-8083-exec-1] c.e.durid.demo.mapper.UserMapper.insert  : ==> Parameters: null, steven(String), 123456(String), 100(BigDecimal), user(String), 2020-04-14 15:55:41.232(Timestamp)
2020-04-14 15:55:41.488 DEBUG 13180 --- [nio-8083-exec-1] o.s.b.f.xml.XmlBeanDefinitionReader      : Loaded 11 bean definitions from class path resource [org/springframework/jdbc/support/sql-error-codes.xml]
2020-04-14 15:55:41.490 DEBUG 13180 --- [nio-8083-exec-1] o.s.b.f.s.DefaultListableBeanFactory     : Creating shared instance of singleton bean 'DB2'
2020-04-14 15:55:41.498 DEBUG 13180 --- [nio-8083-exec-1] o.s.b.f.s.DefaultListableBeanFactory     : Creating shared instance of singleton bean 'Derby'
2020-04-14 15:55:41.499 DEBUG 13180 --- [nio-8083-exec-1] o.s.b.f.s.DefaultListableBeanFactory     : Creating shared instance of singleton bean 'H2'
2020-04-14 15:55:41.500 DEBUG 13180 --- [nio-8083-exec-1] o.s.b.f.s.DefaultListableBeanFactory     : Creating shared instance of singleton bean 'HDB'
2020-04-14 15:55:41.504 DEBUG 13180 --- [nio-8083-exec-1] o.s.b.f.s.DefaultListableBeanFactory     : Creating shared instance of singleton bean 'HSQL'
2020-04-14 15:55:41.505 DEBUG 13180 --- [nio-8083-exec-1] o.s.b.f.s.DefaultListableBeanFactory     : Creating shared instance of singleton bean 'Informix'
2020-04-14 15:55:41.505 DEBUG 13180 --- [nio-8083-exec-1] o.s.b.f.s.DefaultListableBeanFactory     : Creating shared instance of singleton bean 'MS-SQL'
2020-04-14 15:55:41.506 DEBUG 13180 --- [nio-8083-exec-1] o.s.b.f.s.DefaultListableBeanFactory     : Creating shared instance of singleton bean 'MySQL'
2020-04-14 15:55:41.509 DEBUG 13180 --- [nio-8083-exec-1] o.s.b.f.s.DefaultListableBeanFactory     : Creating shared instance of singleton bean 'Oracle'
2020-04-14 15:55:41.510 DEBUG 13180 --- [nio-8083-exec-1] o.s.b.f.s.DefaultListableBeanFactory     : Creating shared instance of singleton bean 'PostgreSQL'
2020-04-14 15:55:41.513 DEBUG 13180 --- [nio-8083-exec-1] o.s.b.f.s.DefaultListableBeanFactory     : Creating shared instance of singleton bean 'Sybase'
2020-04-14 15:55:41.514 DEBUG 13180 --- [nio-8083-exec-1] o.s.jdbc.support.SQLErrorCodesFactory    : Looking up default SQLErrorCodes for DataSource [com.example.durid.demo.config.DynamicDataSource@4613311f]
2020-04-14 15:55:41.523 DEBUG 13180 --- [nio-8083-exec-1] o.s.jdbc.support.SQLErrorCodesFactory    : SQL error codes for 'MySQL' found
2020-04-14 15:55:41.523 DEBUG 13180 --- [nio-8083-exec-1] o.s.jdbc.support.SQLErrorCodesFactory    : Caching SQL error codes for DataSource [com.example.durid.demo.config.DynamicDataSource@4613311f]: database product name is 'MySQL'
2020-04-14 15:55:41.523 DEBUG 13180 --- [nio-8083-exec-1] s.j.s.SQLErrorCodeSQLExceptionTranslator : Unable to translate SQLException with Error code '0', will now try the fallback translator
2020-04-14 15:55:41.523 DEBUG 13180 --- [nio-8083-exec-1] o.s.j.s.SQLStateSQLExceptionTranslator   : Extracted SQL state class 'S1' from value 'S1009'
2020-04-14 15:55:41.526 DEBUG 13180 --- [nio-8083-exec-1] o.s.j.d.DataSourceTransactionManager     : Initiating transaction rollback
2020-04-14 15:55:41.526 DEBUG 13180 --- [nio-8083-exec-1] o.s.j.d.DataSourceTransactionManager     : Rolling back JDBC transaction on Connection [com.mysql.jdbc.JDBC4Connection@1e087590]
2020-04-14 15:55:41.527 DEBUG 13180 --- [nio-8083-exec-1] o.s.jdbc.datasource.DataSourceUtils      : Resetting read-only flag of JDBC Connection [com.mysql.jdbc.JDBC4Connection@1e087590]
2020-04-14 15:55:41.528 DEBUG 13180 --- [nio-8083-exec-1] o.s.j.d.DataSourceTransactionManager     : Releasing JDBC Connection [com.mysql.jdbc.JDBC4Connection@1e087590] after transaction
2020-04-14 15:55:41.534 DEBUG 13180 --- [nio-8083-exec-1] o.s.web.servlet.DispatcherServlet        : Failed to complete request: org.springframework.dao.TransientDataAccessResourceException: 
### Error updating database.  Cause: java.sql.SQLException: Connection is read-only. Queries leading to data modification are not allowed
### The error may exist in file [D:\20191030\demo\target\classes\sqlmapper\UserMapper.xml]
### The error may involve com.example.durid.demo.mapper.UserMapper.insert-Inline
### The error occurred while setting parameters
### SQL: insert into user (id, username, password,        money, role, reg_time       )     values (?, ?, ?,        ?, ?, ?       )
### Cause: java.sql.SQLException: Connection is read-only. Queries leading to data modification are not allowed
; Connection is read-only. Queries leading to data modification are not allowed; nested exception is java.sql.SQLException: Connection is read-only. Queries leading to data modification are not allowed
2020-04-14 15:55:41.558 ERROR 13180 --- [nio-8083-exec-1] o.a.c.c.C.[.[.[/].[dispatcherServlet]    : Servlet.service() for servlet [dispatcherServlet] in context with path [] threw exception [Request processing failed; nested exception is org.springframework.dao.TransientDataAccessResourceException: 
### Error updating database.  Cause: java.sql.SQLException: Connection is read-only. Queries leading to data modification are not allowed
### The error may exist in file [D:\20191030\demo\target\classes\sqlmapper\UserMapper.xml]
### The error may involve com.example.durid.demo.mapper.UserMapper.insert-Inline
### The error occurred while setting parameters
### SQL: insert into user (id, username, password,        money, role, reg_time       )     values (?, ?, ?,        ?, ?, ?       )
### Cause: java.sql.SQLException: Connection is read-only. Queries leading to data modification are not allowed
; Connection is read-only. Queries leading to data modification are not allowed; nested exception is java.sql.SQLException: Connection is read-only. Queries leading to data modification are not allowed] with root cause

java.sql.SQLException: Connection is read-only. Queries leading to data modification are not allowed
	at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:964) ~[mysql-connector-java-5.1.42.jar:5.1.42]
	at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:897) ~[mysql-connector-java-5.1.42.jar:5.1.42]
	at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:886) ~[mysql-connector-java-5.1.42.jar:5.1.42]
	at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:860) ~[mysql-connector-java-5.1.42.jar:5.1.42]
	at com.mysql.jdbc.PreparedStatement.execute(PreparedStatement.java:1134) ~[mysql-connector-java-5.1.42.jar:5.1.42]
	at com.alibaba.druid.pool.DruidPooledPreparedStatement.execute(DruidPooledPreparedStatement.java:497) ~[druid-1.1.17.jar:1.1.17]
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.8.0_121]
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[na:1.8.0_121]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.8.0_121]
	at java.lang.reflect.Method.invoke(Method.java:498) ~[na:1.8.0_121]
	at org.apache.ibatis.logging.jdbc.PreparedStatementLogger.invoke(PreparedStatementLogger.java:59) ~[mybatis-3.5.3.jar:3.5.3]
	at com.sun.proxy.$Proxy102.execute(Unknown Source) ~[na:na]
	at org.apache.ibatis.executor.statement.PreparedStatementHandler.update(PreparedStatementHandler.java:47) ~[mybatis-3.5.3.jar:3.5.3]
	at org.apache.ibatis.executor.statement.RoutingStatementHandler.update(RoutingStatementHandler.java:74) ~[mybatis-3.5.3.jar:3.5.3]
	at org.apache.ibatis.executor.SimpleExecutor.doUpdate(SimpleExecutor.java:50) ~[mybatis-3.5.3.jar:3.5.3]
	at org.apache.ibatis.executor.BaseExecutor.update(BaseExecutor.java:117) ~[mybatis-3.5.3.jar:3.5.3]
	at org.apache.ibatis.executor.CachingExecutor.update(CachingExecutor.java:76) ~[mybatis-3.5.3.jar:3.5.3]
	at org.apache.ibatis.session.defaults.DefaultSqlSession.update(DefaultSqlSession.java:197) ~[mybatis-3.5.3.jar:3.5.3]
	at org.apache.ibatis.session.defaults.DefaultSqlSession.insert(DefaultSqlSession.java:184) ~[mybatis-3.5.3.jar:3.5.3]
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.8.0_121]
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[na:1.8.0_121]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.8.0_121]
	at java.lang.reflect.Method.invoke(Method.java:498) ~[na:1.8.0_121]
	at org.mybatis.spring.SqlSessionTemplate$SqlSessionInterceptor.invoke(SqlSessionTemplate.java:426) ~[mybatis-spring-2.0.3.jar:2.0.3]
	at com.sun.proxy.$Proxy87.insert(Unknown Source) ~[na:na]
	at org.mybatis.spring.SqlSessionTemplate.insert(SqlSessionTemplate.java:271) ~[mybatis-spring-2.0.3.jar:2.0.3]
	at org.apache.ibatis.binding.MapperMethod.execute(MapperMethod.java:62) ~[mybatis-3.5.3.jar:3.5.3]
	at org.apache.ibatis.binding.MapperProxy.invoke(MapperProxy.java:93) ~[mybatis-3.5.3.jar:3.5.3]
	at com.sun.proxy.$Proxy91.insert(Unknown Source) ~[na:na]
	at com.example.durid.demo.service.impl.UserServiceImpl.add(UserServiceImpl.java:25) ~[classes/:na]
	at com.example.durid.demo.service.impl.UserServiceImpl$$FastClassBySpringCGLIB$$723951fd.invoke(<generated>) ~[classes/:na]
	at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:218) ~[spring-core-5.2.4.RELEASE.jar:5.2.4.RELEASE]
	at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:769) ~[spring-aop-5.2.4.RELEASE.jar:5.2.4.RELEASE]
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163) ~[spring-aop-5.2.4.RELEASE.jar:5.2.4.RELEASE]
	at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:747) ~[spring-aop-5.2.4.RELEASE.jar:5.2.4.RELEASE]
	at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:366) ~[spring-tx-5.2.4.RELEASE.jar:5.2.4.RELEASE]
	at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:99) ~[spring-tx-5.2.4.RELEASE.jar:5.2.4.RELEASE]
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) ~[spring-aop-5.2.4.RELEASE.jar:5.2.4.RELEASE]
	at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:747) ~[spring-aop-5.2.4.RELEASE.jar:5.2.4.RELEASE]
	at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:689) ~[spring-aop-5.2.4.RELEASE.jar:5.2.4.RELEASE]
	at com.example.durid.demo.service.impl.UserServiceImpl$$EnhancerBySpringCGLIB$$836c367d.add(<generated>) ~[classes/:na]
	at com.example.durid.demo.controller.UserController.add(UserController.java:43) ~[classes/:na]
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.8.0_121]
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[na:1.8.0_121]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.8.0_121]
	at java.lang.reflect.Method.invoke(Method.java:498) ~[na:1.8.0_121]
	at org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:190) ~[spring-web-5.2.4.RELEASE.jar:5.2.4.RELEASE]
	at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:138) ~[spring-web-5.2.4.RELEASE.jar:5.2.4.RELEASE]
	at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:106) ~[spring-webmvc-5.2.4.RELEASE.jar:5.2.4.RELEASE]
	at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:879) ~[spring-webmvc-5.2.4.RELEASE.jar:5.2.4.RELEASE]
	at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:793) ~[spring-webmvc-5.2.4.RELEASE.jar:5.2.4.RELEASE]
	at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:87) ~[spring-webmvc-5.2.4.RELEASE.jar:5.2.4.RELEASE]
	at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:1040) ~[spring-webmvc-5.2.4.RELEASE.jar:5.2.4.RELEASE]
	at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:943) ~[spring-webmvc-5.2.4.RELEASE.jar:5.2.4.RELEASE]
	at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:1006) ~[spring-webmvc-5.2.4.RELEASE.jar:5.2.4.RELEASE]
	at org.springframework.web.servlet.FrameworkServlet.doPost(FrameworkServlet.java:909) ~[spring-webmvc-5.2.4.RELEASE.jar:5.2.4.RELEASE]
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:660) ~[tomcat-embed-core-9.0.31.jar:9.0.31]
	at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:883) ~[spring-webmvc-5.2.4.RELEASE.jar:5.2.4.RELEASE]
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:741) ~[tomcat-embed-core-9.0.31.jar:9.0.31]
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:231) ~[tomcat-embed-core-9.0.31.jar:9.0.31]
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.31.jar:9.0.31]
	at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:53) ~[tomcat-embed-websocket-9.0.31.jar:9.0.31]
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[tomcat-embed-core-9.0.31.jar:9.0.31]
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.31.jar:9.0.31]
	at org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:100) ~[spring-web-5.2.4.RELEASE.jar:5.2.4.RELEASE]
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119) ~[spring-web-5.2.4.RELEASE.jar:5.2.4.RELEASE]
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[tomcat-embed-core-9.0.31.jar:9.0.31]
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.31.jar:9.0.31]
	at org.springframework.web.filter.FormContentFilter.doFilterInternal(FormContentFilter.java:93) ~[spring-web-5.2.4.RELEASE.jar:5.2.4.RELEASE]
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119) ~[spring-web-5.2.4.RELEASE.jar:5.2.4.RELEASE]
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[tomcat-embed-core-9.0.31.jar:9.0.31]
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.31.jar:9.0.31]
	at org.springframework.boot.actuate.metrics.web.servlet.WebMvcMetricsFilter.doFilterInternal(WebMvcMetricsFilter.java:109) ~[spring-boot-actuator-2.2.5.RELEASE.jar:2.2.5.RELEASE]
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119) ~[spring-web-5.2.4.RELEASE.jar:5.2.4.RELEASE]
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[tomcat-embed-core-9.0.31.jar:9.0.31]
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.31.jar:9.0.31]
	at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:201) ~[spring-web-5.2.4.RELEASE.jar:5.2.4.RELEASE]
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119) ~[spring-web-5.2.4.RELEASE.jar:5.2.4.RELEASE]
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[tomcat-embed-core-9.0.31.jar:9.0.31]
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.31.jar:9.0.31]
	at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:202) ~[tomcat-embed-core-9.0.31.jar:9.0.31]
	at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:96) [tomcat-embed-core-9.0.31.jar:9.0.31]
	at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:541) [tomcat-embed-core-9.0.31.jar:9.0.31]
	at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:139) [tomcat-embed-core-9.0.31.jar:9.0.31]
	at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:92) [tomcat-embed-core-9.0.31.jar:9.0.31]
	at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:74) [tomcat-embed-core-9.0.31.jar:9.0.31]
	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:343) [tomcat-embed-core-9.0.31.jar:9.0.31]
	at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:367) [tomcat-embed-core-9.0.31.jar:9.0.31]
	at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:65) [tomcat-embed-core-9.0.31.jar:9.0.31]
	at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:868) [tomcat-embed-core-9.0.31.jar:9.0.31]
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1639) [tomcat-embed-core-9.0.31.jar:9.0.31]
	at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49) [tomcat-embed-core-9.0.31.jar:9.0.31]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [na:1.8.0_121]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [na:1.8.0_121]
	at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) [tomcat-embed-core-9.0.31.jar:9.0.31]
	at java.lang.Thread.run(Thread.java:745) [na:1.8.0_121]

2020-04-14 15:55:41.572 DEBUG 13180 --- [nio-8083-exec-1] o.s.web.servlet.DispatcherServlet        : "ERROR" dispatch for POST "/error", parameters={}
2020-04-14 15:55:41.577 DEBUG 13180 --- [nio-8083-exec-1] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped to org.springframework.boot.autoconfigure.web.servlet.error.BasicErrorController#error(HttpServletRequest)
2020-04-14 15:55:41.607 DEBUG 13180 --- [nio-8083-exec-1] o.s.w.s.m.m.a.HttpEntityMethodProcessor  : Using 'application/json', given [*/*] and supported [application/json, application/*+json, application/json, application/*+json]
2020-04-14 15:55:41.608 DEBUG 13180 --- [nio-8083-exec-1] o.s.w.s.m.m.a.HttpEntityMethodProcessor  : Writing [{timestamp=Tue Apr 14 15:55:41 CST 2020, status=500, error=Internal Server Error, message=
### Erro (truncated)...]
2020-04-14 15:55:41.664 DEBUG 13180 --- [nio-8083-exec-1] o.s.web.servlet.DispatcherServlet        : Exiting from "ERROR" dispatch, status 500

通过日志不难看出现在的事务信息如下：

Creating new transaction with name [com.example.durid.demo.service.impl.UserServiceImpl.add]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT,readOnly

此处本人稍微提一点，为了代码简洁，建议使用以下的方式：

logger.debug("Creating new transaction with name ["{}"]: {}" ,definition.getName(),definition);

以下为阿里规约中对应的内容：
在这里插入图片描述

对于日志，目的是为了方便对程序运行情况的分析，因此打印日志必须是有用的消息，无论是何种级别的日志，都需要仔细考虑携带有价值的唯一标识，对，唯一标识（definition.getName()），和重要信息（definition），这样对故障的查找和分析才有作用，比如以下的日志作用就大打折扣了：

logger.debug("Creating new transaction");

通过对Spring的日志的介绍，本人是希望我们的开发人员能在重要的流程节点输出包含有效信息的日志，而不是遇到了异常，要么通过查询数据库（如果事务未提交或异常回滚了，还查不到），要么通过debug，且不说这首先需要熟悉代码，在多线程的情况下，debug通常很难达到实际的效果，通过有效的日志，无疑节省人力和时间。