[
https://issues.apache.org/jira/browse/QPID-8291?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16806273#comment-16806273
]
Alex Rudyy commented on QPID-8291:
----------------------------------
Thanks for reporting some inconsistency with logging of various exceptions in
Qpid Broker-J and legacy JMS client for AMQP 0-x. The Qpid Broker-J project
source code should indeed have a more consistent exception logging.
As per your report #1 {{ReplicatedEnvironmentFacade}} has {{TimeoutException}}
exception being reported with {{INFO}} log level in method
{{ReplicatedEnvironmentFacade#submitEnvironmentTask}}. The method is used to
invoke operations on underlying instance of BDB JE {{Environment}}. Your
pointed out that {{TimeoutException}} is logged with {{WARN}} level in method
{{BDBHAVirtualHostNodeImpl#resolveFuture}} which is used to get results for
operations invoked on the same executor. The handling of {{TimeoutException}}
is indeed inconsistent here. Though, it might be more correct to re-throw the
{{TimeoutException}} wrapped into business exception to let the caller know
that operation has timed out.
Your second report of inconsistency with logging of {{SQLException}} thrown
from {{Connection#close}} is also valid. Though, log level {{WARN}} is more
appropriate from my point of view, as broker does not need the connection being
opened any-more. The broker closes it in order to release the resources
associated with the connection on RDBMS side. The broker core functionality
should not be affected and it can continue to operate. Though, it still would
be useful to report the exception for further analysis using log level {{WARN}}.
In your third report I would prefer to use {{WARN}} log level on logging of
exceptions thrown on various stream closes, as neither of those exceptions
impacts broker or client core functionality.
The forth report is interesting. The exception {{InvalidNameException}} cannot
be thrown in pointed code, as the name returned from {{X500Principal#getName()}
is {{RFC2253}} compatible. It might be thrown if JVM is affected by the bug
with generating of RFC2253 compatible names. In this case, it would be better
to upgrade or downgrade java to version not affected by the defect. Though, log
level {{WARN}} looks more appropriate for me to use, as broker core
functionality is not affected and it can continue to operate with plain non-TLS
based connections.
Please note that you reported several orthogonal issues with inconsistent
exception logging. Every of those issues deserves a separate JIRA.
> Inconsistent log level practices in source code
> -----------------------------------------------
>
> Key: QPID-8291
> URL: https://issues.apache.org/jira/browse/QPID-8291
> Project: Qpid
> Issue Type: Improvement
> Components: Broker-J
> Affects Versions: qpid-java-6.1.7
> Reporter: Anuhan Torgonshar
> Priority: Major
> Labels: easyfix
>
> Hi,
> I found there are inconsistent log level practices in the Qpid project, and
> we suspect some of them should be fixed.
> We select 4 problematic practices to report.
> The detail code as well as the modification suggestions are shown below.
> {code:java}
> ***************** Report1 *********************************
> the problematic snippet:
> ============ ReplicatedEnvironmentFacade.java ===================
> file path:
> qpid-java-6.1.7\bdbstore\src\main\java\org\apache\qpid\server\store\berkeleydb\replication\ReplicatedEnvironmentFacade.java
> logging statement line: 916
> modification suggestion: change log level to WARN
> 890 try
> 891 {
> 892 return future.get(timeout, TimeUnit.SECONDS);
> 893 }
> 894 catch (InterruptedException e)
> 895 {
> 896 Thread.currentThread().interrupt();
> 897 }
> 898 catch (ExecutionException e)
> 899 {
> 900 Throwable cause = e.getCause();
> 901 if (cause instanceof Error)
> 902 {
> 903 throw (Error) cause;
> 904 }
> 905 else if (cause instanceof RuntimeException)
> 906 {
> 907 throw (RuntimeException) cause;
> 908 }
> 909 else
> 910 {
> 911 throw new ConnectionScopedRuntimeException("Unexpected
> exception while " + action, e);
> 912 }
> 913 }
> 914 catch (TimeoutException e)
> 915 {
> 916 LOGGER.info("{} on {} timed out after {} seconds", action,
> _prettyGroupNodeName, timeout);
> 917 }
> the similar snippet:
> ============ SelectorThread.java ===============================
> file path:
> qpid-java-6.1.7\broker-core\src\main\java\org\apache\qpid\server\transport\SelectorThread.java
> logging statement line: 464
> 449 try
> 450 {
> 451 result.get(ACCEPT_CANCELATION_TIMEOUT, TimeUnit.MILLISECONDS);
> 452 }
> 453 catch (InterruptedException e)
> 454 {
> 455 LOGGER.warn("Cancellation of accepting socket was
> interrupted");
> 456 Thread.currentThread().interrupt();
> 457 }
> 458 catch (ExecutionException e)
> 459 {
> 460 LOGGER.warn("Cancellation of accepting socket failed",
> e.getCause());
> 461 }
> 462 catch (TimeoutException e)
> 463 {
> 464 LOGGER.warn("Cancellation of accepting socket timed out");
> 465 }
> ============ BDBHAVirtualHostNodeImpl.java ====================
> file path:
> qpid-java-6.1.7\bdbstore\src\main\java\org\apache\qpid\server\virtualhostnode\berkeleydb\BDBHAVirtualHostNodeImpl.java
> logging statement line: 912
> 906 try
> 907 {
> 908 future.get(MUTATE_JE_TIMEOUT_MS, TimeUnit.MILLISECONDS);
> 909 }
> 910 catch (TimeoutException e)
> 911 {
> 912 LOGGER.warn(timeoutLogMessage);
> 913 }
> ***************** Report2 *********************************
> the problematic snippet:
> ============ AbstractJDBCPreferenceStore.java ===================
> file path:
> qpid-java-6.1.7\broker-core\src\main\java\org\apache\qpid\server\store\preferences\AbstractJDBCPreferenceStore.java
>
> logging statement line: 334
> modification suggestion: change log level to ERROR
> 325 try
> 326 {
> 327 if (connection != null)
> 328 {
> 329 connection.close();
> 330 }
> 331 }
> 332 catch (SQLException e)
> 333 {
> 334 getLogger().warn("Failed to close JDBC connection", e);
> 335 }
> the similar snippets:
> ============ JdbcUtils.java ==================================
> file path:
> qpid-java-6.1.7\broker-core\src\main\java\org\apache\qpid\server\store\JdbcUtils.java
> logging statement line: 42
> 36 try
> 37 {
> 38 conn.close();
> 39 }
> 40 catch (SQLException e)
> 41 {
> 42 logger.error("Problem closing connection", e);
> 43 }
> ***************** Report3 *********************************
> the problematic snippet:
> ============ DojoHelper.java =================================
> file path:
> qpid-java-6.1.7\broker-plugins\management-http\src\main\java\org\apache\qpid\server\management\plugin\DojoHelper.java
> logging statement line: 75
> modification suggestion: change log level to ERROR
> 69 try
> 70 {
> 71 propertyStream.close();
> 72 }
> 73 catch (IOException e)
> 74 {
> 75 _logger.warn("Exception closing InputStream for "
> + VERSION_FILE + " resource:", e);
> 76 }
> the similar snippet:
> ============ CallbackHandlerRegistry.java =======================
> file path:
> qpid-java-6.1.7\client\src\main\java\org\apache\qpid\client\security\CallbackHandlerRegistry.java
> logging statement line: 112
> 105 try
> 106 {
> 107 is.close();
> 108
> 109 }
> 110 catch (IOException e)
> 111 {
> 112 _logger.error("Unable to close properties stream: " +
> e, e);
> 113 }
> ============ DynamicSaslRegistrar.java =========================
> file path:
> qpid-java-6.1.7\client\src\main\java\org\apache\qpid\client\security\DynamicSaslRegistrar.java
> logging statement line: 143
> 136 try
> 137 {
> 138 is.close();
> 139
> 140 }
> 141 catch (IOException e)
> 142 {
> 143 _logger.error("Unable to close properties stream: " +
> e, e);
> 144 }
> ***************** Report4 *********************************
> the problematic snippet:
> ============ SSLUtil.java ====================================
> file path:
> qpid-java-6.1.7\common\src\main\java\org\apache\qpid\transport\network\security\ssl\SSLUtil.java
> logging statement line: 231
> modification suggestion: change log level to ERROR
> 206 try
> 207 {
> 208 LdapName ln = new LdapName(dn);
> 209 for(Rdn rdn : ln.getRdns())
> 210 {
> 211 if("CN".equalsIgnoreCase(rdn.getType()))
> 212 {
> 213 cnStr = rdn.getValue().toString();
> 214 }
> 215 else if("DC".equalsIgnoreCase(rdn.getType()))
> 216 {
> 217 if(dcStr == null)
> 218 {
> 219 dcStr = rdn.getValue().toString();
> 220 }
> 221 else
> 222 {
> 223 dcStr = rdn.getValue().toString() + '.' +
> dcStr;
> 224 }
> 225 }
> 226 }
> 227 return cnStr == null || cnStr.length()==0 ? "" : dcStr ==
> null ? cnStr : cnStr + '@' + dcStr;
> 228 }
> 229 catch (InvalidNameException e)
> 230 {
> 231 LOGGER.warn("Invalid name: '{}'", dn);
> 232 return "";
> 233 }
> the similar snippet:
> ============ NonJavaTrustStoreImpl.java ==========================
> file path:
> qpid-java-6.1.7\broker-core\src\main\java\org\apache\qpid\server\security\NonJavaTrustStoreImpl.java
> logging statement line: 163
> 147 try
> 148 {
> 149 LdapName ldapDN = new LdapName(dn);
> 150 name = dn;
> 151 for (Rdn rdn : ldapDN.getRdns())
> 152 {
> 153 if (rdn.getType().equalsIgnoreCase("CN"))
> 154 {
> 155 name = String.valueOf(rdn.getValue());
> 156 break;
> 157 }
> 158 }
> 159
> 160 }
> 161 catch (InvalidNameException e)
> 162 {
> 163 LOGGER.error("Error getting subject name from certificate");
> 164 name = null;
> 165 }
> ============ NonJavaKeyStoreImpl.java =========================
> file path:
> qpid-java-6.1.7\broker-core\src\main\java\org\apache\qpid\server\security\NonJavaKeyStoreImpl.java
> logging statement line: 132
> 115 try
> 116 {
> 117 String dn =
> _certificate.getSubjectX500Principal().getName();
> 118 LdapName ldapDN = new LdapName(dn);
> 119 String name = dn;
> 120 for (Rdn rdn : ldapDN.getRdns())
> 121 {
> 122 if (rdn.getType().equalsIgnoreCase("CN"))
> 123 {
> 124 name = String.valueOf(rdn.getValue());
> 125 break;
> 126 }
> 127 }
> 128 return name;
> 129 }
> 130 catch (InvalidNameException e)
> 131 {
> 132 LOGGER.error("Error getting subject name from
> certificate");
> 133 return null;
> 134 }
> {code}
> We will highly appreciate your feedback!
>
--
This message was sent by Atlassian JIRA
(v7.6.3#76005)
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscr...@qpid.apache.org
For additional commands, e-mail: dev-h...@qpid.apache.org
