Дженкинс портит системное время при запуске модульных тестов с использованием RevisionRepository

Question

Мы работаем над пересмотром фреймворка для нашего приложения с помощью поддержки Spring Envers.Мы подготовили набор интеграционных тестов, которые сначала вставляют данные в базу данных, а затем запрашивают ее с некоторыми условиями, чтобы убедиться, что управление версиями работает нормально.Строки вставляются с задержкой в ​​миллисекунды, чтобы гарантировать, что две строки не будут иметь одинаковый RevisionTimestamp.Все тесты работают нормально, когда они выполняются в локальной среде, но когда они перемещаются в Jenkins, они случайно дают сбой.После исследования мы выяснили, что, хотя вставки выполняются последовательно в потоке, иногда RevisionTimestamp устанавливается в обратном направлении.Это связано с тем, что системные часы на Дженкинсе иногда перемещаются назад неизвестной силой.

Вот пример журнала:

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% уверены, что это что-то связано с Дженкинсом, но мы понятия не имеем, что там может быть иначе.В локальных средах обе даты из журнала синхронизированы, поэтому, как и ожидалось, обе отметки времени из первой строки располагаются перед обеими отметками времени со второй.

Может быть, кто-то из вас поймет, что мы должны проверить на Дженкинса?Любая помощь будет оценена.

Thx.

@ Update У нас есть еще несколько журналов, мы знаем, когда время меняется, но все еще не знаем, почему это могло произойти.Оформить заказ на последние 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}]

Answer 1

Я могу говорить только по теме hibernate-envers.У меня нет большого опыта в том, как именно или как spring-data-envers оборачивает нашу библиотеку, поэтому я не могу углубляться в то, что предоставляют их контракты или как они работают.

С учетом сказанного, яЯ очень склонен согласиться с Ankit в этом вопросе, и именно поэтому дизайн таблицы сущностей ревизий REVINFO такой, какой она есть.

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

Все строки аудита, которые генерирует hibernate-envers, имеютвнешний ключ обратно к этой структуре таблицы, столбец REV в каждой из таблиц аудита сущности указывает на строку в этой таблице.Это означает, что для всех изменений в рамках одной транзакции всегда будут только значения ONE REV и REVTSTMP.

Когда hibernate-envers хочет вернуть аудиторские изменения для организаций, использующих любую форму заказа, мы вообще не используем столбец REVTSTMP, мы используем столбец REV.Мы используем столбец REV, потому что он гарантированно будет детерминированным по порядку, потому что он основан на некоторой конструкции, сгенерированной базой данных;будь то идентификатор, объект auto_increment или объект с последовательной поддержкой.

Для чего стоит, столбец REVTSTMP просто информационный.Он предназначен для предоставления пользователю или приложению некоторого контекста о том, когда произошло изменение аудита, но мы никогда не используем этот столбец, когда его просят предоставить упорядоченную зависимость изменений;вместо этого мы полагаемся исключительно на REV.

. Я бы предложил изменить ваши тесты, чтобы вместо этого использовать REV.

Answer 2

Что такое revisionTimestamp, формат даты и для чего он используется?

Из предоставленной информации я думаю следующее:

Если вы используете метку времени как уникальнуюограничение или для заказа это не лучшая практика.

Иногда в операционных системах время может идти вспять.
NTP Процесс используется для синхронизации времени на вашем компьютере.Если этот процесс не синхронизирован на одном из ваших серверов, он может сообщить о более раннем времени, чем фактическое время.Если у вас работает несколько серверов, время может отличаться.Все серверы могут не синхронизироваться друг с другом с точностью до миллисекунды.Заказ не будет гарантирован на разных серверах.

Существует два вида часов:
Монотонные часы: истекшая продолжительность отчета
Настенные часы: сообщают, сколько времени

Возможные решения:
Вероятно, обратите внимание на автоматическое увеличение идентификаторов или что-то вроде снежинок для управления версиями.

Увеличение смещения по времени, которое я предполагаю в интеграционных тестах между последовательными вставками.

Посмотрите, можете ли вы полагаться на базы данных, созданные в столбце метки времени

Проверьте, какой уровень точности LocalDateTime.now () предлагает