Jenkins 在使用 RevisionRepository 运行单元测试时弄乱了系统时间答案

【问题标题】：Jenkins messes up system time while running Unit tests with usage of RevisionRepositoryJenkins 在使用 RevisionRepository 运行单元测试时弄乱了系统时间
【发布时间】：2018-12-19 11:34:25
【问题描述】：

我们正在使用 spring Envers 支持为我们的应用程序修订框架。我们准备了一组集成测试，首先将数据插入数据库，然后用一些条件查询它，以检查版本控制是否正常工作。以毫秒延迟插入行，以确保两行不会具有相同的 RevisionTimestamp。当在本地环境中执行时，所有测试都可以正常工作，但是当转移到 Jenkins 时，它们会随机失败。经过调查我们发现，即使插入是由线程按顺序执行的，有时 RevisionTimestamp 也会向后设置。这是因为 Jenkins 上的系统时钟有时会被未知的力量向后移动。

这是一个日志示例：

2018-12-19 11:02:33.615 [main] INFO  d.e.s.l.u.b.core.TemporalHandler - Just before going into entityJpaRepository.findLastChangeRevision - 2018-12-19T11:02:33.615639 6847516000080345
2018-12-19 11:02:33.377 [main] INFO  d.e.s.l.u.b.core.TemporalHandler - Just after going into entityJpaRepository.findLastChangeRevision - 2018-12-19T11:02:33.377086 6847516058513093

请注意，第一个日志行的第一个时间戳高于第二行的第一个时间戳，但第一行的第二个时间戳低于第二行的第二个时间戳。

日志来自以下代码：

@Component("temporalHandler")
public class TemporalHandler<T extends Temporal<T, N>, N> implements EntityRevisionsTemporalApi<T, N> {
        private final static transient Logger log = LoggerFactory.getLogger(TemporalHandler.class);
        private static final long serialVersionUID = -7854492585050762415L;

        @PersistenceContext
        @Autowired
        public transient EntityManager em;

        protected transient GenericEntityRepository<?, N> entityJpaRepository;

        /**
         * Setting the entity repository instance dynamically by the consumer component
         *
         * @param entityJpaRepository instance of the entity repository that needs to be
         *                            audited
         */
        public void setEntityJpaRepository(GenericEntityRepository<?, N> entityJpaRepository) {
            this.entityJpaRepository = entityJpaRepository;
        }

        @SuppressWarnings({"unchecked", "hiding"})
        @Override
        public T getEntityLatestRevision(@NotNull N id) {
            try {
                log.info("Just before going into entityJpaRepository.findLastChangeRevision - " + LocalDateTime.now() + " " + System.nanoTime());
                var result = entityJpaRepository.findLastChangeRevision(id);
                log.info("Just after going into entityJpaRepository.findLastChangeRevision - " + LocalDateTime.now() + " " + System.nanoTime());
                return result
                        .map(r -> ((Revision<Integer, T>) r).getEntity())
                        .orElse(null);
            } finally {
                log.info("Just after going into result.map.orElse - " + LocalDateTime.now() + " " + System.nanoTime());
            }

        }
    }

和通用存储库：

@NoRepositoryBean
public interface GenericEntityRepository<T, N> extends RevisionRepository<T, N, Integer>, JpaRepository<T, N> {
}

我们已经尝试解决这个问题好几天了，但没有成功。我们 99% 确定它与 Jenkins 上的某些东西有关，但我们不知道那里可能有什么不同。在本地环境中，日志中的两个日期都是同步的，因此正如预期的那样，第一行的两个时间戳都在第二行的两个时间戳之前。

也许你们中的某个人会有线索，我们应该检查 Jenkins 什么？任何帮助将不胜感激。

谢谢。

@更新我们有更多的日志，我们知道，当时间改变时，但仍然不知道为什么会发生这种情况。签出此日志的最后 3 行：

2018-12-19 18:32:54.853 [main] DEBUG o.h.engine.internal.TwoPhaseLoad - Resolving associations for [org.hibernate.envers.DefaultRevisionEntity#152]
2018-12-19 18:32:54.853 [main] DEBUG o.h.engine.internal.TwoPhaseLoad - Done materializing entity [org.hibernate.envers.DefaultRevisionEntity#152]
2018-12-19 18:32:54.853 [main] TRACE o.h.e.j.internal.JdbcCoordinatorImpl - Starting after statement execution processing [ON_CLOSE]
2018-12-19 18:32:54.853 [main] TRACE o.h.e.i.StatefulPersistenceContext - Initializing non-lazy collections
2018-12-19 18:32:54.853 [main] TRACE o.h.engine.query.spi.QueryPlanCache - Located HQL query plan in cache (select e__ from entity.TestEntity_AUD e__ where e__.originalId.REV.id = (select max(e2__.originalId.REV.id) from entity.TestEntity_AUD e2__ where e2__.originalId.REV.id <= :revision and e__.originalId.id = e2__.originalId.id) and e__.REVTYPE <> :_p0 and e__.originalId.id = :_p1)
2018-12-19 18:32:54.853 [main] TRACE o.h.engine.query.spi.QueryPlanCache - Located HQL query plan in cache (select e__ from entity.TestEntity_AUD e__ where e__.originalId.REV.id = (select max(e2__.originalId.REV.id) from entity.TestEntity_AUD e2__ where e2__.originalId.REV.id <= :revision and e__.originalId.id = e2__.originalId.id) and e__.REVTYPE <> :_p0 and e__.originalId.id = :_p1)
2018-12-19 18:32:54.853 [main] TRACE o.hibernate.engine.internal.Cascade - Processing cascade ACTION_PERSIST_ON_FLUSH for: org.hibernate.envers.DefaultRevisionEntity
2018-12-19 18:32:54.853 [main] TRACE o.hibernate.engine.internal.Cascade - Done processing cascade ACTION_PERSIST_ON_FLUSH for: org.hibernate.envers.DefaultRevisionEntity
2018-12-19 18:32:54.853 [main] TRACE o.h.engine.query.spi.HQLQueryPlan - Find: select e__ from dk.eg.sd.loen.utility.bitemporal.entity.TestEntity_AUD e__ where e__.originalId.REV.id = (select max(e2__.originalId.REV.id) from entity.TestEntity_AUD e2__ where e2__.originalId.REV.id <= :revision and e__.originalId.id = e2__.originalId.id) and e__.REVTYPE <> :_p0 and e__.originalId.id = :_p1
2018-12-19 18:32:54.853 [main] TRACE o.h.engine.spi.QueryParameters - Named parameters: {_p1=1, _p0=DEL, revision=152}
2018-12-19 18:32:54.853 [main] TRACE o.h.e.j.internal.JdbcCoordinatorImpl - Registering last query statement [HikariProxyPreparedStatement@773469572 wrapping prep1068: select testentity0_.id as id1_1_, testentity0_.rev as rev2_1_, testentity0_.revtype as revtype3_1_, testentity0_.revision_system_time as revision4_1_, testentity0_.revision_system_time_mod as revision5_1_, testentity0_.revision_time as revision6_1_, testentity0_.revision_time_mod as revision7_1_, testentity0_.effective_end_time as effectiv8_1_, testentity0_.effective_end_time_mod as effectiv9_1_, testentity0_.effective_start_time as effecti10_1_, testentity0_.effective_start_time_mod as effecti11_1_, testentity0_.employee_id as employe12_1_, testentity0_.employee_id_mod as employe13_1_, testentity0_.first_name as first_n14_1_, testentity0_.first_name_mod as first_n15_1_, testentity0_.last_name as last_na16_1_, testentity0_.last_name_mod as last_na17_1_, testentity0_.salary as salary18_1_, testentity0_.salary_mod as salary_19_1_ from test_entity_aud testentity0_ where testentity0_.rev=(select max(testentity1_.rev) from test_entity_aud testentity1_ where testentity1_.rev<=? and testentity0_.id=testentity1_.id) and testentity0_.revtype<>? and testentity0_.id=?]
2018-12-19 18:32:54.631 [main] DEBUG o.h.engine.internal.TwoPhaseLoad - Resolving associations for [entity.TestEntity_AUD#component[id,REV]{REV=org.hibernate.envers.DefaultRevisionEntity#152, id=1}]
2018-12-19 18:32:54.632 [main] DEBUG o.h.engine.internal.TwoPhaseLoad - Done materializing entity [entity.TestEntity_AUD#component[id,REV]{REV=org.hibernate.envers.DefaultRevisionEntity#152, id=1}]

【问题讨论】：

标签： java unit-testing jenkins spring-data-jpa hibernate-envers

【解决方案1】：

什么是revisionTimestamp，它是日期格式吗？它的用途是什么？

根据分享的信息，我的想法如下：

如果您将时间戳用作唯一约束或用于排序，则不是最佳做法。

时间有时会在操作系统上倒退。
NTP 进程用于在您的计算机上同步时间。如果此过程在您的一台服务器上不同步，它可能会报告比实际时间更早的时间。如果您有多个服务器正在运行，则时间可能会有所不同。所有服务器的时钟可能没有达到毫秒精度。无法保证跨服务器订购。

有两种时钟：
单调时钟：报告经过的持续时间
挂钟：报告现在几点

可能的解决方案：
可能会考虑自动递增 id 或类似雪花的东西来进行版本控制。

增加我猜在连续插入之间的集成测试中的时间偏移量。

看看你是否可以依赖于在时间戳列创建的数据库

检查 LocalDateTime.now() 提供的精度级别

【讨论】：

RevisionTimestamp 用于保存有关创建或更新时间的信息。它由 UpdateTimestamp 注释设置，不用作 ID。类型是 java.sql.Timestamp。我已经尝试过增加每次更新之间的时间间隔，但它并没有解决问题。我必须检查是否有任何同步问题。当然，所有测试都是针对同一个 jvm 并在一个线程中运行的，所以我很确定它与多线程无关。看起来 Jenkins（或 Jenkins 服务器上的其他东西）正在使用系统时钟，hibernate 使用它来设置 UpdateTimestamp 注释字段

【解决方案2】：

我只能说与hibernate-envers直接相关的内容。我对 spring-data-envers 包装我们的库的确切方式或方式没有太多经验，因此我无法深入了解他们的合同提供什么或它们是如何工作的。

话虽如此，我更倾向于在这里与 Ankit 达成一致，这正是修订实体表 REVINFO 的设计的原因。

REVINFO
------------------------------------
REV      numeric   auto_increment PK
REVTSTMP timestamp

hibernate-envers 生成的所有审计行都有一个指向该表结构的外键，每个实体审计表中的 REV 列都指向该表中的一行。这意味着对于单个事务范围内的所有更改，将永远只有一个REV和REVTSTMP值。

当hibernate-envers 想要使用任何形式的订单返回实体的审计更改时，我们根本不使用REVTSTMP 列，我们使用REV 列。我们使用REV 列，因为它基于某些数据库生成的构造，因此保证了顺序确定性；无论是身份、auto_increment 还是序列支持的对象。

对于它的价值，REVTSTMP 列只是提供信息。它旨在为用户或应用程序提供有关审计更改何时发生的一些上下文，但当被要求提供更改的有序依赖项时，我们从不使用该列；相反，我们只依赖REV。

我建议修改您的测试以改为依赖REV。

【讨论】：