From bd28730c7dd7676be01ad077093037d6f9e9911a Mon Sep 17 00:00:00 2001 From: Ken Stevens Date: Sun, 30 Oct 2022 14:38:25 -0400 Subject: [PATCH] improved logging (#4217) Co-authored-by: Ken Stevens --- .../fhir/jpa/migrate/HapiMigrationLock.java | 3 +- .../uhn/fhir/jpa/migrate/HapiMigratorIT.java | 37 +++++++++++++++++++ 2 files changed, 39 insertions(+), 1 deletion(-) diff --git a/hapi-fhir-sql-migrate/src/main/java/ca/uhn/fhir/jpa/migrate/HapiMigrationLock.java b/hapi-fhir-sql-migrate/src/main/java/ca/uhn/fhir/jpa/migrate/HapiMigrationLock.java index 68a4b4643d2..19144c4683f 100644 --- a/hapi-fhir-sql-migrate/src/main/java/ca/uhn/fhir/jpa/migrate/HapiMigrationLock.java +++ b/hapi-fhir-sql-migrate/src/main/java/ca/uhn/fhir/jpa/migrate/HapiMigrationLock.java @@ -55,7 +55,7 @@ public class HapiMigrationLock implements AutoCloseable { return; } retryCount++; - ourLog.info("Waiting for lock on " + this); + ourLog.info("Waiting for lock on {}. Retry {}/{}", myMigrationStorageSvc.getMigrationTablename(), retryCount, MAX_RETRY_ATTEMPTS); Thread.sleep(SLEEP_MILLIS_BETWEEN_LOCK_RETRIES); } catch (InterruptedException ex) { // Ignore - if interrupted, we still need to wait for lock to become available @@ -72,6 +72,7 @@ public class HapiMigrationLock implements AutoCloseable { try { return myMigrationStorageSvc.insertLockRecord(myLockDescription); } catch (Exception e) { + ourLog.warn("Failed to insert lock record: {}", e.getMessage()); return false; } } diff --git a/hapi-fhir-sql-migrate/src/test/java/ca/uhn/fhir/jpa/migrate/HapiMigratorIT.java b/hapi-fhir-sql-migrate/src/test/java/ca/uhn/fhir/jpa/migrate/HapiMigratorIT.java index 109b4174e6b..cffe8a8cfd9 100644 --- a/hapi-fhir-sql-migrate/src/test/java/ca/uhn/fhir/jpa/migrate/HapiMigratorIT.java +++ b/hapi-fhir-sql-migrate/src/test/java/ca/uhn/fhir/jpa/migrate/HapiMigratorIT.java @@ -1,6 +1,8 @@ package ca.uhn.fhir.jpa.migrate; import ca.uhn.fhir.interceptor.api.HookParams; +import ca.uhn.fhir.jpa.migrate.dao.MigrationQueryBuilder; +import ca.uhn.fhir.jpa.migrate.entity.HapiMigrationEntity; import ca.uhn.fhir.jpa.migrate.taskdef.BaseTask; import ca.uhn.test.concurrency.IPointcutLatch; import ca.uhn.test.concurrency.PointcutLatch; @@ -108,6 +110,41 @@ class HapiMigratorIT { assertThat(result2.succeededTasks, hasSize(1)); } + @Test + void test_twoSequentialCalls_noblock() throws InterruptedException, ExecutionException { + + ExecutorService executor = Executors.newSingleThreadExecutor(); + LatchMigrationTask latchMigrationTask = new LatchMigrationTask("first", "1"); + + HapiMigrator migrator = buildMigrator(latchMigrationTask); + assertEquals(0, countLockRecords()); + + { + latchMigrationTask.setExpectedCount(1); + Future future = executor.submit(() -> migrator.migrate()); + latchMigrationTask.awaitExpected(); + assertEquals(1, countLockRecords()); + latchMigrationTask.release("1"); + + MigrationResult result = future.get(); + assertEquals(0, countLockRecords()); + assertThat(result.succeededTasks, hasSize(1)); + } + + { + Future future = executor.submit(() -> migrator.migrate()); + + MigrationResult result = future.get(); + assertEquals(0, countLockRecords()); + assertThat(result.succeededTasks, hasSize(0)); + } + + } + + private int countLockRecords() { + return myJdbcTemplate.queryForObject("SELECT COUNT(*) FROM " + MIGRATION_TABLENAME + " WHERE \"installed_rank\" = " + HapiMigrationStorageSvc.LOCK_PID, Integer.class); + } + @Nonnull private HapiMigrator buildMigrator(LatchMigrationTask theLatchMigrationTask) { HapiMigrator retval = buildMigrator();