OEM Enhancer causing Jenkins job to freeze

Hi all,

We are using ODB enhancer in one of our jobs on jenkins, built via ant. Recently we started to encounter situation, where this job's execution gets stuck for ever on Jenkins. This is causing us a lot of problems with our CI.

<java classpath="${project.root.dir}lib/*;${project.root.dir}/temp/*;${dist.dir}" classname="com.objectdb.Enhancer" fork="true">
    <arg line="-s ${dist.dir}/our/entities/package/"/>
</java>

Is it possible to enable some detailed logging for enhancer? To see where exactly it gets stuck during it's execution?

Also, our Jenkins machine doesn't have access to internet, could this be an issue?

Thank you

Usually the Enhancer doesn't need access to the Internet. Sometimes, however, an attempt to access the Internet may happen during xml validation by the Java XML parser, if external XML schema is specified in XML files.

Please try to generate a Java thread dump that will show where exactly the process is stuck.

Hello,

we have succeeded to simulate the problem again and have created dump for you.

I have attatched the thread dump listing.

I you need the whole dump I can provide it.

Thank you

Marta

The relevant stack trace in this thread dump is:

"main" prio=5 tid=1 RUNNABLE
at org.apache.log4j.Priority.<clinit>(Priority.java:45)
at java.lang.Class.forName0(Native Method)
at java.lang.Class.forName(Class.java:169)
at org.apache.commons.logging.impl.Log4JLogger.class$(Log4JLogger.java:55)
    Local Variable: java.lang.String#20504
at org.apache.commons.logging.impl.Log4JLogger.<clinit>(Log4JLogger.java:80)
at java.lang.Class.forName0(Native Method)
at java.lang.Class.forName(Class.java:247)
at org.apache.commons.logging.impl.LogFactoryImpl.createLogFromClass(LogFactoryImpl.java:1081)
    Local Variable: java.lang.String#20480
    Local Variable: java.lang.Object[]#14005
    Local Variable: sun.misc.Launcher$AppClassLoader#1
at org.apache.commons.logging.impl.LogFactoryImpl.discoverLogImplementation(LogFactoryImpl.java:914)
at org.apache.commons.logging.impl.LogFactoryImpl.newInstance(LogFactoryImpl.java:604)
at org.apache.commons.logging.impl.LogFactoryImpl.getInstance(LogFactoryImpl.java:336)
    Local Variable: java.lang.String#20429
at org.apache.commons.logging.impl.LogFactoryImpl.getInstance(LogFactoryImpl.java:310)
    Local Variable: org.apache.commons.logging.impl.LogFactoryImpl#1
at org.apache.commons.logging.LogFactory.getLog(LogFactory.java:685)
at eu.ysoft.commons.logging.LogFactory.getLog(LogFactory.java:32)
at eu.ysoft.safeq.core.cache.entity.CacheableDriverProperty.<clinit>(CacheableDriverProperty.java:24)
at sun.misc.Unsafe.ensureClassInitialized(Native Method)
at sun.reflect.UnsafeFieldAccessorFactory.newFieldAccessor(UnsafeFieldAccessorFactory.java:25)
    Local Variable: class java.net.InetSocketAddress
at sun.reflect.ReflectionFactory.newFieldAccessor(ReflectionFactory.java:122)
    Local Variable: sun.reflect.ReflectionFactory#1
at java.lang.reflect.Field.acquireFieldAccessor(Field.java:918)
at java.lang.reflect.Field.getFieldAccessor(Field.java:899)
at java.lang.reflect.Field.get(Field.java:358)
at com.objectdb.o.ANT.r(ANT.java:198)
    Local Variable: java.lang.String#22728
at com.objectdb.o.ANT.q(ANT.java:154)
    Local Variable: java.lang.reflect.Field#627
    Local Variable: java.lang.reflect.Field[]#39
at com.objectdb.o.SCM.r(SCM.java:229)
    Local Variable: com.objectdb.o.ANT#1
    Local Variable: class eu.ysoft.safeq.core.cache.entity.CacheableDriverProperty
at com.objectdb.o.JEW.aK(JEW.java:185)
    Local Variable: com.objectdb.o.SCM#1
at com.objectdb.o.JEL.A(JEL.java:433)
    Local Variable: com.objectdb.o.JEW[]#1
    Local Variable: java.lang.String#17766
    Local Variable: com.objectdb.o.ALS#34
    Local Variable: com.objectdb.o.ALS#33
    Local Variable: com.objectdb.o.JEW#8
    Local Variable: com.objectdb.o.JEL#1
at com.objectdb.o.JEN.k(JEN.java:93)
    Local Variable: com.objectdb.o.JEN#1
at com.objectdb.Enhancer.main(Enhancer.java:32)
    Local Variable: java.lang.String[]#1275

ObjectDB uses Java reflection to analyze classes for enhancement. The thread dump was taken while the Enhancer was analyzing the class eu.ysoft.safeq.core.cache.entity.CacheableDriverProperty.

Maybe something in that class causes the problem. The stack trace mentions InetSocketAddress (maybe as the type of one of the fields), and maybe it is related to network operations. Initialization of the classes for Java reflection also includes running a static initializer of eu.ysoft.safeq.core.cache.entity.CacheableDriverProperty with many log initializations.

The exact problem is unclear, but you can see in the stack trace that the operation is inside your code. Your application code is invoked by ObjectDB (through Java reflection which runs the static initializer of CacheableDriverProperty), and maybe that code is not expected to run in that environment during enhancement.

Hi,

We found out that issue is caused by classloader deadlock. Problem occurs during logging class initialization from static block(variable) when there are multiple logging frameworks present on classpath.

Nice description of this issue can be found here: http://stackoverflow.com/questions/15543521/mixed-usage-of-log4j-and-commons-logging-causes-a-class-loading-deadlock

This is interesting, thank you for this update.

Since now we know that this deadlock is not related to ObjectDB, strange that you noticed it only during enhancement and not when you start your application (since it may happen every time that this class is loaded and initialized).

Anyway, fixing this should be good for both enhancement and application initialization.