Uploaded image for project: 'ZK'
  1. ZK
  2. ZK-5703

Debug messages shouldn't be created is debug is disabled, may cause side effects

XMLWordPrintable

    • Icon: Bug Bug
    • Resolution: Unresolved
    • Icon: Major Major
    • None
    • 10.0.0
    • None
    • Security Level: Jimmy
    • None

      reproducing

      A number of log debug calls in ZK are built with the following pattern:
      https://github.com/search?q=repo%3Azkoss%2Fzk+debug%28debugInfo%29%3B&type=code

      		String debugInfo = MessageFormat.format(...);
		if (_log.isDebugEnabled()) {
			_log.debug(debugInfo);
		}

      current result

      provide user example:
      debug info formatter tries to call toString on one a hibernate entity, which tries to read a lazy value without an active hibernate session.

      Caused by: org.hibernate.LazyInitializationException: could not initialize proxy [[anonymized for tracker]#3] - no Session
 at org.hibernate.proxy.AbstractLazyInitializer.initialize(AbstractLazyInitializer.java:175) ~[hibernate-core-5.4.33.Final.jar:5.4.33.Final]
 at org.hibernate.proxy.AbstractLazyInitializer.getImplementation(AbstractLazyInitializer.java:315) ~[hibernate-core-5.4.33.Final.jar:5.4.33.Final]
 at org.hibernate.proxy.pojo.bytebuddy.ByteBuddyInterceptor.intercept(ByteBuddyInterceptor.java:45) ~[hibernate-core-5.4.33.Final.jar:5.4.33.Final]
 at org.hibernate.proxy.ProxyConfiguration$InterceptorDispatcher.intercept(ProxyConfiguration.java:95) ~[hibernate-core-5.4.33.Final.jar:5.4.33.Final]
 at [anonymized for tracker].$HibernateProxy$ [anonymized for tracker].toString(Unknown Source) ~[classes/:?]
 at java.base/java.lang.String.valueOf(String.java:2951) ~[?:?]
 at  [anonymized for tracker].toString(ExecutionSetFolder.java:165) ~[classes/:?]
 at java.base/java.lang.String.valueOf(String.java:2951) ~[?:?]
 at java.base/java.lang.StringBuilder.append(StringBuilder.java:172) ~[?:?]
 at org.zkoss.bind.impl.PropertyImpl.toString(PropertyImpl.java:50) ~[zkbind-10.0.0.jar:10.0.0]
 at java.base/java.lang.String.valueOf(String.java:2951) ~[?:?]
 at java.base/java.lang.StringBuilder.append(StringBuilder.java:172) ~[?:?]
 at java.base/java.util.AbstractCollection.toString(AbstractCollection.java:473) ~[?:?]
 at java.base/java.text.MessageFormat.subformat(MessageFormat.java:1302) ~[?:?]
 at java.base/java.text.MessageFormat.format(MessageFormat.java:885) ~[?:?]
 at java.base/java.text.Format.format(Format.java:158) ~[?:?]
 at java.base/java.text.MessageFormat.format(MessageFormat.java:860) ~[?:?]
 at org.zkoss.bind.impl.BinderImpl.doSaveAfter(BinderImpl.java:2258) ~[zkbind-10.0.0.jar:10.0.0]
 at org.zkoss.bind.impl.BinderImpl.doCommand(BinderImpl.java:1841) ~[zkbind-10.0.0.jar:10.0.0]

      expected result

      Building the debugInfo happens regardless of whether debug is enabled or not.
      ZK shouldn't build messages unless debug logs need to be generated.

      		if (_log.isDebugEnabled()) {
			String debugInfo = MessageFormat.format(...);
			_log.debug(debugInfo);
		}

      In addition, it is possible for the debugInfo formatting to cause exceptions.

      debug information

      there might be more log entries than provided in the search above

      workaround

      -

            Unassigned Unassigned
            MDuchemin MDuchemin
            Votes:
            0 Vote for this issue
            Watchers:
            1 Start watching this issue

              Created:
              Updated: