From a6a907269b97491957ab2554af7127d2f4428503 Mon Sep 17 00:00:00 2001 From: paduin Date: Tue, 21 Nov 2023 13:30:56 +0100 Subject: [PATCH 1/7] added logging for debugging --- .../server/FederatedHMSHandler.java | 30 +++++++++++++++---- 1 file changed, 25 insertions(+), 5 deletions(-) diff --git a/waggle-dance-core/src/main/java/com/hotels/bdp/waggledance/server/FederatedHMSHandler.java b/waggle-dance-core/src/main/java/com/hotels/bdp/waggledance/server/FederatedHMSHandler.java index 77b2d3c90..2e61c8846 100644 --- a/waggle-dance-core/src/main/java/com/hotels/bdp/waggledance/server/FederatedHMSHandler.java +++ b/waggle-dance-core/src/main/java/com/hotels/bdp/waggledance/server/FederatedHMSHandler.java @@ -31,13 +31,13 @@ import com.facebook.fb303.FacebookBase; import com.facebook.fb303.fb_status; -import com.jcabi.aspects.Loggable; - +import com.google.common.base.Stopwatch; import com.hotels.bdp.waggledance.conf.WaggleDanceConfiguration; import com.hotels.bdp.waggledance.mapping.model.DatabaseMapping; import com.hotels.bdp.waggledance.mapping.service.MappingEventListener; import com.hotels.bdp.waggledance.mapping.service.impl.NotifyingFederationService; import com.hotels.bdp.waggledance.metrics.Monitored; +import com.jcabi.aspects.Loggable; @Monitored @Component @@ -1371,7 +1371,7 @@ public void alter_partitions_with_environment_context( mapping .getClient() .alter_partitions_with_environment_context(mapping.transformInboundDatabaseName(db_name), tbl_name, - mapping.transformInboundPartitions(new_parts), environment_context); + mapping.transformInboundPartitions(new_parts), environment_context); } @Override @@ -1383,7 +1383,7 @@ public void alter_table_with_cascade(String dbname, String tbl_name, Table new_t mapping .getClient() .alter_table_with_cascade(mapping.transformInboundDatabaseName(dbname), tbl_name, - mapping.transformInboundTable(new_tbl), cascade); + mapping.transformInboundTable(new_tbl), cascade); } @Override @@ -1616,14 +1616,34 @@ public GetTableResult get_table_req(GetTableRequest req) throws MetaException, N @Loggable(value = Loggable.DEBUG, skipResult = true, name = INVOCATION_LOG_NAME) public GetTablesResult get_table_objects_by_name_req(GetTablesRequest req) throws MetaException, InvalidOperationException, UnknownDBException, TException { + StringBuilder message = new StringBuilder(); + Stopwatch stopWatch = Stopwatch.createStarted(); + + message.append("get_table_objects_by_name_req: req=" + req.toString() + "\n"); DatabaseMapping mapping = databaseMappingService.databaseMapping(req.getDbName()); + message.append(" databaseMapping took:" + stopWatch.elapsed().toMillis() + "\n"); + stopWatch.reset().start(); + List filteredTables = databaseMappingService.filterTables(req.getDbName(), req.getTblNames(), mapping); req.setTblNames(filteredTables); + message.append(" filtered tables 1st call took: " + stopWatch.elapsed().toMillis() + "\n"); + stopWatch.reset().start(); + GetTablesResult result = mapping .getClient() .get_table_objects_by_name_req(mapping.transformInboundGetTablesRequest(req)); + message.append(" HMS call took: " + stopWatch.elapsed().toMillis() + "\n"); + stopWatch.reset().start(); + result.setTables(mapping.getMetastoreFilter().filterTables(result.getTables())); - return mapping.transformOutboundGetTablesResult(result); + message.append(" filtered tables 2nd call took: " + stopWatch.elapsed().toMillis() + "\n"); + stopWatch.reset().start(); + + GetTablesResult getTablesResult = mapping.transformOutboundGetTablesResult(result); + message.append(" transform outbound took: " + stopWatch.elapsed().toMillis() + "\n"); + stopWatch.stop(); + LOG.error(message.toString()); + return getTablesResult; } @Override From a9675277d3e74be6e1275f411fc4da6d7179d6ea Mon Sep 17 00:00:00 2001 From: paduin Date: Tue, 21 Nov 2023 17:43:46 +0100 Subject: [PATCH 2/7] Fixing logging --- .../waggledance/server/FederatedHMSHandler.java | 14 ++++++++------ 1 file changed, 8 insertions(+), 6 deletions(-) diff --git a/waggle-dance-core/src/main/java/com/hotels/bdp/waggledance/server/FederatedHMSHandler.java b/waggle-dance-core/src/main/java/com/hotels/bdp/waggledance/server/FederatedHMSHandler.java index 2e61c8846..7b304a369 100644 --- a/waggle-dance-core/src/main/java/com/hotels/bdp/waggledance/server/FederatedHMSHandler.java +++ b/waggle-dance-core/src/main/java/com/hotels/bdp/waggledance/server/FederatedHMSHandler.java @@ -1616,32 +1616,34 @@ public GetTableResult get_table_req(GetTableRequest req) throws MetaException, N @Loggable(value = Loggable.DEBUG, skipResult = true, name = INVOCATION_LOG_NAME) public GetTablesResult get_table_objects_by_name_req(GetTablesRequest req) throws MetaException, InvalidOperationException, UnknownDBException, TException { + long total = System.currentTimeMillis(); StringBuilder message = new StringBuilder(); Stopwatch stopWatch = Stopwatch.createStarted(); - message.append("get_table_objects_by_name_req: req=" + req.toString() + "\n"); + message.append("get_table_objects_by_name_req: req=" + req.toString() + ", "); DatabaseMapping mapping = databaseMappingService.databaseMapping(req.getDbName()); - message.append(" databaseMapping took:" + stopWatch.elapsed().toMillis() + "\n"); + message.append("DatabaseMapping took:" + stopWatch.elapsed().toMillis() + ", "); stopWatch.reset().start(); List filteredTables = databaseMappingService.filterTables(req.getDbName(), req.getTblNames(), mapping); req.setTblNames(filteredTables); - message.append(" filtered tables 1st call took: " + stopWatch.elapsed().toMillis() + "\n"); + message.append("Filtered tables 1st call took: " + stopWatch.elapsed().toMillis() + ", "); stopWatch.reset().start(); GetTablesResult result = mapping .getClient() .get_table_objects_by_name_req(mapping.transformInboundGetTablesRequest(req)); - message.append(" HMS call took: " + stopWatch.elapsed().toMillis() + "\n"); + message.append("HMS call took: " + stopWatch.elapsed().toMillis() + ", "); stopWatch.reset().start(); result.setTables(mapping.getMetastoreFilter().filterTables(result.getTables())); - message.append(" filtered tables 2nd call took: " + stopWatch.elapsed().toMillis() + "\n"); + message.append("Filtered tables 2nd call took: " + stopWatch.elapsed().toMillis() + ", "); stopWatch.reset().start(); GetTablesResult getTablesResult = mapping.transformOutboundGetTablesResult(result); - message.append(" transform outbound took: " + stopWatch.elapsed().toMillis() + "\n"); + message.append("Transform outbound took: " + stopWatch.elapsed().toMillis()+", "); stopWatch.stop(); + message.append("Total get_table_objects_by_name_req took: " + (System.currentTimeMillis() - total)); LOG.error(message.toString()); return getTablesResult; } From 55cb71470ff3fe4fe3c6f75b5b75d7e7a41367cf Mon Sep 17 00:00:00 2001 From: paduin Date: Mon, 27 Nov 2023 14:09:58 +0100 Subject: [PATCH 3/7] removing shutdown (always throws an exception) and fix log --- .../waggledance/client/ThriftMetastoreClientManager.java | 9 --------- .../HiveCompatibleThriftHiveMetastoreIfaceFactory.java | 4 ++-- 2 files changed, 2 insertions(+), 11 deletions(-) diff --git a/waggle-dance-core/src/main/java/com/hotels/bdp/waggledance/client/ThriftMetastoreClientManager.java b/waggle-dance-core/src/main/java/com/hotels/bdp/waggledance/client/ThriftMetastoreClientManager.java index c20c87cfd..c7a0c67af 100644 --- a/waggle-dance-core/src/main/java/com/hotels/bdp/waggledance/client/ThriftMetastoreClientManager.java +++ b/waggle-dance-core/src/main/java/com/hotels/bdp/waggledance/client/ThriftMetastoreClientManager.java @@ -246,15 +246,6 @@ public void close() { return; } isConnected = false; - try { - if (client != null) { - client.shutdown(); - } - } catch (TException e) { - LOG.debug("Unable to shutdown metastore client. Will try closing transport directly.", e); - } - // Transport would have got closed via client.shutdown(), so we don't need this, but - // just in case, we make this call. if ((transport != null) && transport.isOpen()) { transport.close(); transport = null; diff --git a/waggle-dance-core/src/main/java/com/hotels/bdp/waggledance/client/compatibility/HiveCompatibleThriftHiveMetastoreIfaceFactory.java b/waggle-dance-core/src/main/java/com/hotels/bdp/waggledance/client/compatibility/HiveCompatibleThriftHiveMetastoreIfaceFactory.java index e0e84f46d..3ce8ee3f5 100644 --- a/waggle-dance-core/src/main/java/com/hotels/bdp/waggledance/client/compatibility/HiveCompatibleThriftHiveMetastoreIfaceFactory.java +++ b/waggle-dance-core/src/main/java/com/hotels/bdp/waggledance/client/compatibility/HiveCompatibleThriftHiveMetastoreIfaceFactory.java @@ -66,8 +66,8 @@ public Object invoke(Object proxy, Method method, Object[] args) throws Throwabl } catch (Throwable t) { log .warn( - "Unable to invoke compatibility for metastore client method {}. Will rethrow original exception, logging exception from invocation handler", - method.getName(), t); + "Unable to invoke compatibility for metastore client method "+method.getName()+". Will rethrow original exception, logging exception from invocation handler", + t); } throw delegateException.getCause(); } From 7052959392788d373dc1fbd214107c7707b02e9c Mon Sep 17 00:00:00 2001 From: paduin Date: Thu, 30 Nov 2023 10:13:32 +0100 Subject: [PATCH 4/7] removed logging --- .../server/FederatedHMSHandler.java | 30 +++---------------- 1 file changed, 4 insertions(+), 26 deletions(-) diff --git a/waggle-dance-core/src/main/java/com/hotels/bdp/waggledance/server/FederatedHMSHandler.java b/waggle-dance-core/src/main/java/com/hotels/bdp/waggledance/server/FederatedHMSHandler.java index 7b304a369..9305fffd5 100644 --- a/waggle-dance-core/src/main/java/com/hotels/bdp/waggledance/server/FederatedHMSHandler.java +++ b/waggle-dance-core/src/main/java/com/hotels/bdp/waggledance/server/FederatedHMSHandler.java @@ -31,13 +31,13 @@ import com.facebook.fb303.FacebookBase; import com.facebook.fb303.fb_status; -import com.google.common.base.Stopwatch; +import com.jcabi.aspects.Loggable; + import com.hotels.bdp.waggledance.conf.WaggleDanceConfiguration; import com.hotels.bdp.waggledance.mapping.model.DatabaseMapping; import com.hotels.bdp.waggledance.mapping.service.MappingEventListener; import com.hotels.bdp.waggledance.mapping.service.impl.NotifyingFederationService; import com.hotels.bdp.waggledance.metrics.Monitored; -import com.jcabi.aspects.Loggable; @Monitored @Component @@ -1383,7 +1383,7 @@ public void alter_table_with_cascade(String dbname, String tbl_name, Table new_t mapping .getClient() .alter_table_with_cascade(mapping.transformInboundDatabaseName(dbname), tbl_name, - mapping.transformInboundTable(new_tbl), cascade); + mapping.transformInboundTable(new_tbl), cascade); } @Override @@ -1616,36 +1616,14 @@ public GetTableResult get_table_req(GetTableRequest req) throws MetaException, N @Loggable(value = Loggable.DEBUG, skipResult = true, name = INVOCATION_LOG_NAME) public GetTablesResult get_table_objects_by_name_req(GetTablesRequest req) throws MetaException, InvalidOperationException, UnknownDBException, TException { - long total = System.currentTimeMillis(); - StringBuilder message = new StringBuilder(); - Stopwatch stopWatch = Stopwatch.createStarted(); - - message.append("get_table_objects_by_name_req: req=" + req.toString() + ", "); DatabaseMapping mapping = databaseMappingService.databaseMapping(req.getDbName()); - message.append("DatabaseMapping took:" + stopWatch.elapsed().toMillis() + ", "); - stopWatch.reset().start(); - List filteredTables = databaseMappingService.filterTables(req.getDbName(), req.getTblNames(), mapping); req.setTblNames(filteredTables); - message.append("Filtered tables 1st call took: " + stopWatch.elapsed().toMillis() + ", "); - stopWatch.reset().start(); - GetTablesResult result = mapping .getClient() .get_table_objects_by_name_req(mapping.transformInboundGetTablesRequest(req)); - message.append("HMS call took: " + stopWatch.elapsed().toMillis() + ", "); - stopWatch.reset().start(); - result.setTables(mapping.getMetastoreFilter().filterTables(result.getTables())); - message.append("Filtered tables 2nd call took: " + stopWatch.elapsed().toMillis() + ", "); - stopWatch.reset().start(); - - GetTablesResult getTablesResult = mapping.transformOutboundGetTablesResult(result); - message.append("Transform outbound took: " + stopWatch.elapsed().toMillis()+", "); - stopWatch.stop(); - message.append("Total get_table_objects_by_name_req took: " + (System.currentTimeMillis() - total)); - LOG.error(message.toString()); - return getTablesResult; + return mapping.transformOutboundGetTablesResult(result); } @Override From 7a3ff717eb9c2b9c19e74a1822706845e2be0cb6 Mon Sep 17 00:00:00 2001 From: paduin Date: Thu, 30 Nov 2023 10:27:53 +0100 Subject: [PATCH 5/7] changelog --- CHANGELOG.md | 5 +++++ 1 file changed, 5 insertions(+) diff --git a/CHANGELOG.md b/CHANGELOG.md index 5a7d16689..f8efe50e3 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -1,4 +1,9 @@ +## [3.11.7] - 2023-11-30 +### Changed +- Fixed exeption logging in log statement +- Removed client.shutdown() call, this always throws an exception and the code ends up closing the transport directly. + ## [3.11.6] - 2023-10-24 ### Fixed - Switch to ExecutorService instead of the default `ForkJoinPool` for `MetastoreMappingImpl.isAvailable()` calls. Using `ForkJoinPool` may cause threads to wait on each other. From 0a80f96e726ea15858f0334d1d10fa8143346992 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Javier=20S=C3=A1nchez=20Beltr=C3=A1n?= <36443689+javsanbel2@users.noreply.github.com> Date: Thu, 30 Nov 2023 10:39:58 +0100 Subject: [PATCH 6/7] Update CHANGELOG.md --- CHANGELOG.md | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index f8efe50e3..b12d177cf 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -1,7 +1,7 @@ ## [3.11.7] - 2023-11-30 ### Changed -- Fixed exeption logging in log statement +- Fixed exception that was not logging in a log statement. - Removed client.shutdown() call, this always throws an exception and the code ends up closing the transport directly. ## [3.11.6] - 2023-10-24 From 267f040b8e4b79033fa976df59d5706a3257f03c Mon Sep 17 00:00:00 2001 From: Patrick Duin Date: Thu, 30 Nov 2023 10:55:03 +0100 Subject: [PATCH 7/7] Update CHANGELOG.md --- CHANGELOG.md | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index b12d177cf..867c17d6f 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -1,7 +1,7 @@ ## [3.11.7] - 2023-11-30 ### Changed -- Fixed exception that was not logging in a log statement. +- Fixed log statement that was not logging the exception correctly. - Removed client.shutdown() call, this always throws an exception and the code ends up closing the transport directly. ## [3.11.6] - 2023-10-24