From 8925273d37bff3b2eba1c861590a67aaad6090f0 Mon Sep 17 00:00:00 2001 From: denniscunningham <129115982+denniscunningham@users.noreply.github.com> Date: Thu, 3 Aug 2023 23:50:58 -0400 Subject: [PATCH] DB connection and transaction processing improvements (#2640) * Modify TransactionWraper::inTransaction to handle nested closables; remove logging that includes secrets; make DB initializatio failures clearer * Cleanup exception handling; update Hikari and JDBI libraries * Fix test --- .../ddp/db/TransactionWrapper.java | 88 ++++++++----------- .../ddp/exception/DDPInternalError.java | 11 +++ .../org/broadinstitute/dsm/DSMServer.java | 60 ++++++++----- .../ddp/db/TransactionWrapperTest.java | 6 +- pepper-apis/parent-pom.xml | 4 +- pepper-apis/pom.xml | 4 +- 6 files changed, 92 insertions(+), 81 deletions(-) create mode 100644 pepper-apis/ddp-common/src/main/java/org/broadinstitute/ddp/exception/DDPInternalError.java diff --git a/pepper-apis/ddp-common/src/main/java/org/broadinstitute/ddp/db/TransactionWrapper.java b/pepper-apis/ddp-common/src/main/java/org/broadinstitute/ddp/db/TransactionWrapper.java index 981d1d0117..6b5a6fa8d7 100644 --- a/pepper-apis/ddp-common/src/main/java/org/broadinstitute/ddp/db/TransactionWrapper.java +++ b/pepper-apis/ddp-common/src/main/java/org/broadinstitute/ddp/db/TransactionWrapper.java @@ -14,6 +14,7 @@ import lombok.extern.slf4j.Slf4j; import org.broadinstitute.ddp.constants.ConfigFile; import org.broadinstitute.ddp.exception.DDPException; +import org.broadinstitute.ddp.exception.DDPInternalError; import org.broadinstitute.ddp.exception.InvalidConfigurationException; import org.broadinstitute.ddp.util.ConfigManager; import org.jdbi.v3.core.ConnectionException; @@ -168,21 +169,19 @@ public static synchronized void init(DbConfiguration... dbConfigs) { } for (DbConfiguration dbConfig : dbConfigs) { - if (gTxnWrapper.containsKey(dbConfig.getDb())) { - TransactionWrapper transactionWrapper = gTxnWrapper.get(dbConfig.getDb()); - int maxConnections = dbConfig.getMaxConnections(); - String dbUrl = dbConfig.getDbUrl(); + TransactionWrapper.DB db = dbConfig.getDb(); + int maxConnections = dbConfig.getMaxConnections(); + String dbUrl = dbConfig.getDbUrl(); + + if (gTxnWrapper.containsKey(db)) { + TransactionWrapper transactionWrapper = gTxnWrapper.get(db); if (transactionWrapper.maxConnections != maxConnections || !transactionWrapper.dbUrl.equals(dbUrl)) { - throw new RuntimeException("init() has already been called with " - + transactionWrapper.maxConnections + " and " - + transactionWrapper.dbUrl + "; " + "you cannot re-initialize " - + "it with different params " + maxConnections - + " and " + dbUrl); + throw new DDPInternalError("init() has already been called with different parameters: DB=" + db.name()); } else { - log.warn("TransactionWrapper has already been initialized."); + log.warn("TransactionWrapper has already been initialized for {}", db.name()); } } - gTxnWrapper.put(dbConfig.getDb(), new TransactionWrapper(dbConfig.getMaxConnections(), dbConfig.getDbUrl(), dbConfig.getDb())); + gTxnWrapper.put(db, new TransactionWrapper(maxConnections, dbUrl, db)); } isInitialized = true; } @@ -201,7 +200,7 @@ public static synchronized DB getDB() { } /** - * If there's only a single db initialized, return the {@link TransactionWrapper} for it. Otherwise + * If there's only a single db initialized, return the {@link TransactionWrapper} for it, otherwise * an exception is thrown. */ public static synchronized TransactionWrapper getInstance() { @@ -236,10 +235,10 @@ public static synchronized void reloadDbPoolConfiguration(boolean useCache) thro StringBuilder invalidConfigMessage = new StringBuilder(); for (DB db : dbs) { if (!cfg.hasPath(db.getDbUrlConfigKey())) { - invalidConfigMessage.append("Config does not have " + db.getDbUrlConfigKey() + " for " + getDB()); + invalidConfigMessage.append("Config does not have " + db.getDbUrlConfigKey() + " for " + db.name()); } if (!cfg.hasPath(db.getDbPoolSizeConfigKey())) { - invalidConfigMessage.append("Config does not have " + db.getDbPoolSizeConfigKey() + " for " + getDB()); + invalidConfigMessage.append("Config does not have " + db.getDbPoolSizeConfigKey() + " for " + db.name()); } } @@ -284,27 +283,15 @@ private static boolean isAuthException(ConnectionException e) { public static R withTxn(DB db, HandleCallback callback) throws X { // hopefully temporary code to detect long-running connections long startTime = System.currentTimeMillis(); - try { - try (Handle h = openJdbiWithAuthRetry(db)) { - R res = h.inTransaction(callback); - long endTime = System.currentTimeMillis(); - // 30s threshold - if (endTime - startTime > 30000) { - logger.warn("DB transaction open for > 30s\n {}", - stackTraceToString(Thread.currentThread().getStackTrace())); - } - return res; - } - } catch (ConnectionException e) { - throw new DDPException(COULD_NOT_GET_CONNECTION, e); - } catch (Exception e) { + try (Handle h = openJdbiWithAuthRetry(db)) { + return h.inTransaction(callback); + } finally { long endTime = System.currentTimeMillis(); // 30s threshold if (endTime - startTime > 30000) { - logger.warn("DB transaction open for > 30s. Exception: {}\n {}", e.getMessage(), + logger.warn("DB transaction open for > 30s\n {}", stackTraceToString(Thread.currentThread().getStackTrace())); } - throw e; } } @@ -342,14 +329,12 @@ private static Handle openJdbiWithAuthRetry(DB db) { } reloadDbPoolConfiguration(false); } else { - throw new DDPException(COULD_NOT_GET_CONNECTION, e); + throw new DDPInternalError(COULD_NOT_GET_CONNECTION, e); } - } catch (InvalidConfigurationException e) { - log.error("Database connection configuration is invalid. Proceeding with original configuration values."); } } // if here, we've tried a few times, but are still unable to get a connection. - throw new DDPException(COULD_NOT_GET_CONNECTION); + throw new DDPInternalError(COULD_NOT_GET_CONNECTION); } /** @@ -366,22 +351,13 @@ public static void useTxn(DB db, HandleConsumer callbac long startTime = System.currentTimeMillis(); try (Handle h = openJdbiWithAuthRetry(db)) { h.useTransaction(callback); + } finally { long endTime = System.currentTimeMillis(); // 30s threshold if (endTime - startTime > 30000) { logger.warn("DB transaction open for > 30s\n {}", stackTraceToString(Thread.currentThread().getStackTrace())); } - } catch (ConnectionException e) { - throw new DDPException(COULD_NOT_GET_CONNECTION, e); - } catch (Exception e) { - long endTime = System.currentTimeMillis(); - // 30s threshold - if (endTime - startTime > 30000) { - logger.warn("DB transaction open for > 30s. Exception: {}\n {}", e.getMessage(), - stackTraceToString(Thread.currentThread().getStackTrace())); - } - throw e; } } @@ -421,12 +397,21 @@ private static String stackTraceToString(StackTraceElement[] stackTrace) { */ @Deprecated public static R inTransaction(ConnectionConsumer callback) throws X { - try (Connection conn = openJdbiWithAuthRetry(getDB()).getConnection()) { - return callback.withConnection(conn); - } catch (ConnectionException e) { - throw new DDPException(COULD_NOT_GET_CONNECTION, e); - } catch (SQLException e) { - throw new DDPException("Error handling connection", e); + // temporary code to detect long-running connections + long startTime = System.currentTimeMillis(); + try (Handle handle = openJdbiWithAuthRetry(getDB())) { + try (Connection conn = handle.getConnection()) { + return callback.withConnection(conn); + } catch (SQLException e) { + throw new DDPInternalError("Error handling connection", e); + } + } finally { + long endTime = System.currentTimeMillis(); + // 30s threshold + if (endTime - startTime > 30000) { + logger.warn("DB transaction open for > 30s\n {}", + stackTraceToString(Thread.currentThread().getStackTrace())); + } } } @@ -446,6 +431,9 @@ private HikariDataSource createDataSource(int maxConnections, String dbUrl, DB d config.setMaxLifetime(TimeUnit.SECONDS.toMillis(14400)); // 4 hours, which is half the default wait_timeout of mysql config.setPoolName(db.name()); + log.info("Created data source for {} with maxConnections={}, connectionTimeout={}s, maxLifetime={}s", + db.name(), maxConnections, 5, 14400); + // todo arz leverage allowPoolSuspension and mxbeans to fully automate password rotation return new HikariDataSource(config); diff --git a/pepper-apis/ddp-common/src/main/java/org/broadinstitute/ddp/exception/DDPInternalError.java b/pepper-apis/ddp-common/src/main/java/org/broadinstitute/ddp/exception/DDPInternalError.java new file mode 100644 index 0000000000..349e0449e2 --- /dev/null +++ b/pepper-apis/ddp-common/src/main/java/org/broadinstitute/ddp/exception/DDPInternalError.java @@ -0,0 +1,11 @@ +package org.broadinstitute.ddp.exception; + +public class DDPInternalError extends RuntimeException { + public DDPInternalError(String message) { + super(message); + } + + public DDPInternalError(String message, Throwable e) { + super(message, e); + } +} diff --git a/pepper-apis/dsm-core/src/main/java/org/broadinstitute/dsm/DSMServer.java b/pepper-apis/dsm-core/src/main/java/org/broadinstitute/dsm/DSMServer.java index 61baad40db..9dba1f4766 100644 --- a/pepper-apis/dsm-core/src/main/java/org/broadinstitute/dsm/DSMServer.java +++ b/pepper-apis/dsm-core/src/main/java/org/broadinstitute/dsm/DSMServer.java @@ -47,6 +47,7 @@ import org.apache.http.HttpHeaders; import org.apache.http.HttpStatus; import org.broadinstitute.ddp.db.TransactionWrapper; +import org.broadinstitute.ddp.exception.DDPInternalError; import org.broadinstitute.ddp.util.LiquibaseUtil; import org.broadinstitute.dsm.db.dao.ddp.onchistory.OncHistoryDetailDaoImpl; @@ -222,39 +223,44 @@ public class DSMServer { private static final String gaeDeployDir = "appengine/deploy"; private static final Duration defaultBootWait = Duration.ofMinutes(10); private static Map ddpConfigurationLookup = new HashMap<>(); - private static AtomicBoolean isReady = new AtomicBoolean(false); + private static final AtomicBoolean isReady = new AtomicBoolean(false); private static Auth0Util auth0Util; public static void main(String[] args) { // immediately lock isReady so that ah/start route will wait synchronized (isReady) { - logger.info("Starting up DSM"); - //config without secrets - Config cfg = ConfigFactory.load(); - //secrets from vault in a config file - File vaultConfigInCwd = new File(vaultConf); - File vaultConfigInDeployDir = new File(gaeDeployDir, vaultConf); - File vaultConfig = vaultConfigInCwd.exists() ? vaultConfigInCwd : vaultConfigInDeployDir; - logger.info("Reading config values from " + vaultConfig.getAbsolutePath()); - cfg = cfg.withFallback(ConfigFactory.parseFile(vaultConfig)); - - if (cfg.hasPath(GCP_PATH_TO_SERVICE_ACCOUNT)) { - if (StringUtils.isNotBlank(cfg.getString("portal.googleProjectCredentials"))) { - System.setProperty("GOOGLE_APPLICATION_CREDENTIALS", cfg.getString("portal.googleProjectCredentials")); + try { + logger.info("Starting up DSM"); + //config without secrets + Config cfg = ConfigFactory.load(); + //secrets from vault in a config file + File vaultConfigInCwd = new File(vaultConf); + File vaultConfigInDeployDir = new File(gaeDeployDir, vaultConf); + File vaultConfig = vaultConfigInCwd.exists() ? vaultConfigInCwd : vaultConfigInDeployDir; + logger.info("Reading config values from " + vaultConfig.getAbsolutePath()); + cfg = cfg.withFallback(ConfigFactory.parseFile(vaultConfig)); + + if (cfg.hasPath(GCP_PATH_TO_SERVICE_ACCOUNT)) { + if (StringUtils.isNotBlank(cfg.getString("portal.googleProjectCredentials"))) { + System.setProperty("GOOGLE_APPLICATION_CREDENTIALS", cfg.getString("portal.googleProjectCredentials")); + } } - } - new DSMConfig(cfg); + new DSMConfig(cfg); - String preferredSourceIPHeader = null; - if (cfg.hasPath(ApplicationConfigConstants.PREFERRED_SOURCE_IP_HEADER)) { - preferredSourceIPHeader = cfg.getString(ApplicationConfigConstants.PREFERRED_SOURCE_IP_HEADER); + String preferredSourceIPHeader = null; + if (cfg.hasPath(ApplicationConfigConstants.PREFERRED_SOURCE_IP_HEADER)) { + preferredSourceIPHeader = cfg.getString(ApplicationConfigConstants.PREFERRED_SOURCE_IP_HEADER); + } + JettyConfig.setupJetty(preferredSourceIPHeader); + DSMServer server = new DSMServer(); + server.configureServer(cfg); + isReady.set(true); + logger.info("DSM Startup Complete"); + } catch (Exception e) { + logger.error("Error starting DSM server {}", e.toString()); + e.printStackTrace(); } - JettyConfig.setupJetty(preferredSourceIPHeader); - DSMServer server = new DSMServer(); - server.configureServer(cfg); - isReady.set(true); - logger.info("DSM Startup Complete"); } } @@ -1064,6 +1070,12 @@ private void setupRouteGenericErrorHandlers() { response.status(500); response.body(exception.getMessage()); }); + exception(DDPInternalError.class, (exception, request, response) -> { + logger.error("Internal error {}", exception.toString()); + exception.printStackTrace(); + response.status(500); + response.body(exception.getMessage()); + }); exception(AuthorizationException.class, (exception, request, response) -> { response.status(403); response.body(exception.getMessage()); diff --git a/pepper-apis/dss-core/src/test/java/org/broadinstitute/ddp/db/TransactionWrapperTest.java b/pepper-apis/dss-core/src/test/java/org/broadinstitute/ddp/db/TransactionWrapperTest.java index 8ed332da80..c7d637584b 100644 --- a/pepper-apis/dss-core/src/test/java/org/broadinstitute/ddp/db/TransactionWrapperTest.java +++ b/pepper-apis/dss-core/src/test/java/org/broadinstitute/ddp/db/TransactionWrapperTest.java @@ -14,7 +14,7 @@ import com.typesafe.config.Config; import lombok.extern.slf4j.Slf4j; -import org.broadinstitute.ddp.exception.DDPException; +import org.broadinstitute.ddp.exception.DDPInternalError; import org.broadinstitute.ddp.util.ConfigManager; import org.broadinstitute.ddp.util.DBTestContainer; import org.broadinstitute.ddp.util.LiquibaseUtil; @@ -272,7 +272,7 @@ public void testJdbi_withTxn_outOfConnections() { }); return null; }); - } catch (DDPException e) { + } catch (DDPInternalError e) { assertTrue(e.getCause().getMessage().matches(".*Connection is not available.*")); } } @@ -381,7 +381,7 @@ public void testJdbi_useTxn_outOfConnections() { fail("this callback should not have ran"); }); }); - } catch (DDPException e) { + } catch (DDPInternalError e) { assertTrue(e.getCause().getMessage().matches(".*Connection is not available.*")); } } diff --git a/pepper-apis/parent-pom.xml b/pepper-apis/parent-pom.xml index 0d3d36d261..7ad41e97df 100644 --- a/pepper-apis/parent-pom.xml +++ b/pepper-apis/parent-pom.xml @@ -14,7 +14,7 @@ src/test/java/org/broadinstitute/ddp/ target/surefire-reports/ target/jacoco.exec - 3.1.1 + 3.39.1 7.1.4 3.0.3 4.8.0 @@ -167,7 +167,7 @@ com.zaxxer HikariCP - 3.4.2 + 5.0.1 org.liquibase diff --git a/pepper-apis/pom.xml b/pepper-apis/pom.xml index 041ce3a157..178dbd7d43 100644 --- a/pepper-apis/pom.xml +++ b/pepper-apis/pom.xml @@ -18,7 +18,7 @@ ${project.groupId}:${project.artifactId} target/surefire-reports/ dpp-common,dsm-core,dss-core - 3.28.0 + 3.39.1 7.1.4 3.0.3 4.8.0 @@ -260,7 +260,7 @@ com.zaxxer HikariCP - 3.4.2 + 5.0.1 org.liquibase