Runtime injection of detailed method trace fails for a CDI bean #16007

JDUNNIN · 2021-02-23T11:07:17Z

Describe the bug

Trace injection may generate non-valid byte codes. For example:

ERROR ] TRAS3000E: Runtime injection of detailed method trace failed for class com.ibm.zosconnect.engine.impl.ZosAssetFactoryManager with exception java.lang.reflect.UndeclaredThrowableException
at com.sun.proxy.$Proxy0.retransformClasses(Unknown Source)
at com.ibm.ws.ras.instrument.internal.main.LibertyRuntimeTransformer.retransformClass(LibertyRuntimeTransformer.java:250)
at [internal classes]
at com.ibm.zosconnect.engine.impl.ZosAssetFactoryManager.(ZosAssetFactoryManager.java:28)
at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:83)
at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:57)
at java.lang.reflect.Constructor.newInstance(Constructor.java:437)
at org.apache.felix.scr.impl.inject.internal.ComponentConstructorImpl.newInstance(ComponentConstructorImpl.java:312)
at [internal classes]
Caused by: java.lang.reflect.InvocationTargetException
... 16 more
Caused by: java.lang.VerifyError
... 18 more

Steps to Reproduce

Start the server with problem classes. A project which reproduces the problem with a test class is attached. See also the linked ASM issue.

Expected behavior

Correct byte codes should be generated. A VerifyError should not occur.

Diagnostic information:

(WebSphere Application Server 20.0.0.6/wlp-1.0.41.cl200620200528-0414) on IBM J9 VM, version 8.0.6.10 - pxa6480sr6fp10-20200408_01(SR6 FP10) (en_US)

WebSphere Application Server, Liberty Profile, v21.0.0.6 and higher, up to at least v22.0.0.12.

The problem occurs in classes from z/OS Connect, in versions up to at least v3.0.57.0.

** Additional information:**

This seemed to be a problem in ASM (both 9.3 and 9.4 reproduce the problem), and an issue was raised:
https://gitlab.ow2.org/asm/asm/-/issues/317986

ASM helpfully reviewed the issue and discovered a step in Liberty code generation which is adding the incorrect stack frame. From the ASM issue:

Eric Bruneton
[@ebruneton](https://gitlab.ow2.org/ebruneton) · [5 days ago](https://gitlab.ow2.org/asm/asm/-/issues/317986#note_89449)
Thanks for the detailed report! COMPUTE_MAXS does not generate any frames. For me the invalid frame is generated by
OpenLiberty, here:
https://github.com/OpenLiberty/open-liberty/blob/2fd4a880754c37a988c5ed9ac4f1ea5988e465d6/dev/com.ibm.ws.ras.instrument/src/com/ibm/ws/ras/instrument/internal/bci/AbstractRasMethodAdapter.java#L432.
You can see that the FULL frame is generated from the constructor parameters, and only from these parameters. But this is
incorrect. In your case this is missing the local variable from the ASTORE 1 instruction (instruction #1). In summary, I think
this is a bug in OpenLiberty.

My best sense is that a problem occurs in particular with ZosAssetFactoryManager because of the presence of other injected code. In the problem method:

  public com.ibm.zosconnect.engine.impl.ZosAssetFactoryManager();
    descriptor: ()V
    flags: ACC_PUBLIC
    Code:
      stack=6, locals=2, args_size=1
         0: invokestatic  #57                 // Method $jacocoInit:()[Z
         3: astore_1
         4: aload_0
         5: invokespecial #10                 // Method java/lang/Object."<init>":()V

Note that injected invocation of $jacocoInit. I'm thinking the Liberty trace does not account for this added injected code, and as a result generates an incorrect stack frame.

The text was updated successfully, but these errors were encountered:

Azquelt · 2021-03-04T15:05:25Z

I talked to @JDUNNIN but was unable to reproduce the problem in my environment using their code and the same Java and liberty version, so there seems to be something a little more subtle going on.

We do have CDI bean classes within liberty which are instrumented successfully and indeed when I tried to reproduce the problem, I could see trace messaged emitted by the class.

Based on this, I don't think the problem is related to CDI, and I'm transferring this to @cbridgha who's more familiar with our trace instrumentation, but I'm happy to answer any questions which might come up regarding CDI.

JDUNNIN · 2021-06-09T14:53:12Z

Hi @cbridgha have you got any update on this at all? This will start to become a bigger problem for us in next couple of months.

JDUNNIN · 2021-08-31T10:15:51Z

Hi - using WebSphere Application Server 21.0.0.6 our tracing now is coming out and no exceptions/FFDCs being thrown. Not sure if it got fixed at the version bump or if it was other tweaks devs made since this issue opened but I think it can be closed now. Thanks for investigation earlier @Azquelt

JDUNNIN · 2021-10-05T15:07:12Z

Re-opening as the issue is present still - I can only think I must have tested it wrong.

JDUNNIN · 2021-10-06T10:50:08Z

Currently using version:

product = WebSphere Application Server 21.0.0.6, <my product extension redacted> (wlp-1.0.53.cl210620210527-1900)
wlp.install.dir = /opt/ibm/wlp/
server.output.dir = /opt/ibm/wlp/output/defaultServer/
java.home = /opt/ibm/java/jre
java.version = 1.8.0_291
java.runtime = Java(TM) SE Runtime Environment (8.0.6.31 - pxa6480sr6fp31-20210510_01(SR6 FP31))
os = Linux (5.10.25-linuxkit; amd64) (en_US)
process = [email protected]

JDUNNIN · 2021-10-12T07:23:15Z

Stack trace for failure:

[10/12/21 7:18:49:665 UTC] 00000042 id=00000000 bm.ws.ras.instrument.internal.main.LibertyRuntimeTransformer E TRAS3000E: Runtime injection of detailed method trace failed for class com.ibm.myproduct.engine.impl.OperationResource with exception java.lang.reflect.UndeclaredThrowableException
	at com.sun.proxy.$Proxy0.retransformClasses(Unknown Source)
	at com.ibm.ws.ras.instrument.internal.main.LibertyRuntimeTransformer.retransformClass(LibertyRuntimeTransformer.java:250)
	at com.ibm.ws.ras.instrument.internal.main.LibertyRuntimeTransformer.traceStateChanged(LibertyRuntimeTransformer.java:222)
	at com.ibm.ws.logging.internal.osgi.Activator$RuntimeTransformerComponentListener.traceComponentUpdated(Activator.java:117)
	at com.ibm.websphere.ras.TrConfigurator.traceComponentUpdated(TrConfigurator.java:232)
	at com.ibm.websphere.ras.TraceComponent.setTraceSpec(TraceComponent.java:294)
	at com.ibm.websphere.ras.Tr.registerTraceComponent(Tr.java:790)
	at com.ibm.websphere.ras.Tr.register(Tr.java:191)
	at com.ibm.myproduct.engine.impl.OperationResource.<clinit>(OperationResource.java:65535)
	at com.ibm.myproduct.engine.impl.OperationManagerImpl.lambda$loadAllOperations$0(OperationManagerImpl.java:86)
	at com.ibm.myproduct.engine.impl.OperationManagerImpl$$Lambda$128/0x00000000eca01e30.accept(Unknown Source)
	at java.util.ArrayList.forEach(ArrayList.java:1270)
	at com.ibm.myproduct.engine.impl.OperationManagerImpl.loadAllOperations(OperationManagerImpl.java:76)
	at com.ibm.myproduct.engine.impl.OperationManagerImpl.postConstruct(OperationManagerImpl.java:56)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:90)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:55)
	at java.lang.reflect.Method.invoke(Method.java:508)
	at org.jboss.weld.injection.producer.DefaultLifecycleCallbackInvoker.invokeMethods(DefaultLifecycleCallbackInvoker.java:83)
	at org.jboss.weld.injection.producer.DefaultLifecycleCallbackInvoker.postConstruct(DefaultLifecycleCallbackInvoker.java:66)
	at org.jboss.weld.injection.producer.BasicInjectionTarget.postConstruct(BasicInjectionTarget.java:122)
	at org.jboss.weld.bean.ManagedBean.create(ManagedBean.java:174)
	at org.jboss.weld.contexts.AbstractContext.get(AbstractContext.java:96)
	at org.jboss.weld.bean.ContextualInstanceStrategy$DefaultContextualInstanceStrategy.get(ContextualInstanceStrategy.java:100)
	at org.jboss.weld.bean.ContextualInstanceStrategy$ApplicationScopedContextualInstanceStrategy.get(ContextualInstanceStrategy.java:140)
	at org.jboss.weld.bean.ContextualInstance.get(ContextualInstance.java:67)
	at org.jboss.weld.event.ObserverMethodImpl.getReceiver(ObserverMethodImpl.java:360)
	at org.jboss.weld.event.ObserverMethodImpl.getReceiverIfExists(ObserverMethodImpl.java:347)
	at org.jboss.weld.event.ObserverMethodImpl.sendEvent(ObserverMethodImpl.java:305)
	at org.jboss.weld.event.ObserverMethodImpl.notify(ObserverMethodImpl.java:286)
	at javax.enterprise.inject.spi.ObserverMethod.notify(ObserverMethod.java:124)
	at org.jboss.weld.util.Observers.notify(Observers.java:166)
	at org.jboss.weld.event.ObserverNotifier.notifySyncObservers(ObserverNotifier.java:285)
	at org.jboss.weld.event.ObserverNotifier.notify(ObserverNotifier.java:273)
	at org.jboss.weld.event.ObserverNotifier.fireEvent(ObserverNotifier.java:177)
	at org.jboss.weld.bootstrap.BeanDeploymentModule.fireEvent(BeanDeploymentModule.java:93)
	at org.jboss.weld.bootstrap.WeldStartup.endInitialization(WeldStartup.java:582)
	at org.jboss.weld.bootstrap.WeldBootstrap.endInitialization(WeldBootstrap.java:100)
	at com.ibm.ws.cdi.impl.CDIContainerImpl.endInitialization(CDIContainerImpl.java:184)
	at com.ibm.ws.cdi.liberty.CDIRuntimeImpl.applicationStarting(CDIRuntimeImpl.java:481)
	at com.ibm.ws.container.service.state.internal.ApplicationStateManager.fireStarting(ApplicationStateManager.java:51)
	at com.ibm.ws.container.service.state.internal.StateChangeServiceImpl.fireApplicationStarting(StateChangeServiceImpl.java:50)
	at com.ibm.ws.app.manager.module.internal.SimpleDeployedAppInfoBase.preDeployApp(SimpleDeployedAppInfoBase.java:547)
	at com.ibm.ws.app.manager.module.internal.SimpleDeployedAppInfoBase.installApp(SimpleDeployedAppInfoBase.java:508)
	at com.ibm.ws.app.manager.module.internal.DeployedAppInfoBase.deployApp(DeployedAppInfoBase.java:349)
	at com.ibm.ws.app.manager.war.internal.WARApplicationHandlerImpl.install(WARApplicationHandlerImpl.java:65)
	at com.ibm.ws.app.manager.internal.statemachine.StartAction.execute(StartAction.java:149)
	at com.ibm.ws.app.manager.internal.statemachine.ApplicationStateMachineImpl.enterState(ApplicationStateMachineImpl.java:1352)
	at com.ibm.ws.app.manager.internal.statemachine.ApplicationStateMachineImpl.run(ApplicationStateMachineImpl.java:897)
	at com.ibm.ws.threading.internal.ExecutorServiceImpl$RunnableWrapper.run(ExecutorServiceImpl.java:238)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1160)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
	at java.lang.Thread.run(Thread.java:822)
Caused by: java.lang.reflect.InvocationTargetException
	at sun.reflect.GeneratedMethodAccessor15.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:55)
	at java.lang.reflect.Method.invoke(Method.java:508)
	at com.ibm.ws.kernel.launch.internal.TraceInstrumentation.invoke(TraceInstrumentation.java:80)
	... 53 more
Caused by: java.lang.VerifyError
	at sun.instrument.InstrumentationImpl.retransformClasses(InstrumentationImpl.java:163)
	... 57 more

JDUNNIN · 2022-04-25T10:07:58Z

We are still hitting this at 22.0.0.3

product = WebSphere Application Server 22.0.0.3 wlp-1.0.62.cl220320220302-1100
java.version = 1.8.0_321
java.runtime = Java(TM) SE Runtime Environment (8.0.7.6 - pxa6480sr7fp6-20220330_01(SR7 FP6))
os = Linux (5.10.16.3-microsoft-standard-WSL2; amd64) (en_US)

tbitonti · 2022-11-09T19:23:12Z

See the included "notes/notes-09-Nov-2022.txt" for more information.
traceInjection_09-Nov-2022.zip

tbitonti · 2022-11-09T19:23:58Z

Followups will depend on the prognosis of having the ASM issue accepted, and on the timeliness of a fix to ASM.

tbitonti · 2022-11-10T18:05:13Z

Per ObjectWorks, this is a Liberty bug:

Thanks for the detailed report! COMPUTE_MAXS does not generate any frames. For me the invalid frame is generated by OpenLiberty, here:

https://github.com/OpenLiberty/open-liberty/blob/2fd4a880754c37a988c5ed9ac4f1ea5988e465d6/dev/com.ibm.ws.ras.instrument/src/com/ibm/ws/ras/instrument/internal/bci/AbstractRasMethodAdapter.java#L432.

You can see that the FULL frame is generated from the constructor parameters, and only from these parameters. But this is incorrect. In your case this is missing the local variable from the ASTORE 1 instruction (instruction #1). In summary, I think this is a bug in OpenLiberty.

tbitonti · 2022-11-15T17:41:25Z

My best sense is that a problem occurs in particular with ZosAssetFactoryManager because of the presence of other injected code. In the problem method:

public com.ibm.zosconnect.engine.impl.ZosAssetFactoryManager();
descriptor: ()V
flags: ACC_PUBLIC
Code:
stack=6, locals=2, args_size=1
0: invokestatic #57 // Method $jacocoInit:()[Z
3: astore_1
4: aload_0
5: invokespecial #10 // Method java/lang/Object."":()V

Note that injected invocation of $jacocoInit. I'm thinking the Liberty trace does not account for this added injected code, and as a result generates an incorrect stack frame.

tbitonti · 2023-01-10T18:37:46Z

The customer confirmed that removal of the JaCoCo injected code fixes the problem.

JDUNNIN added the bug This bug is not present in a released version of Open Liberty label Feb 23, 2021

LibbyBot added the Needs member attention label Feb 23, 2021

tevans78 added in:CDI team:MicroProfileUK labels Feb 23, 2021

tevans78 assigned Azquelt Mar 1, 2021

Azquelt assigned cbridgha and unassigned Azquelt Mar 4, 2021

Azquelt removed in:CDI team:MicroProfileUK labels Mar 4, 2021

JDUNNIN closed this as completed Aug 31, 2021

JDUNNIN reopened this Oct 5, 2021

tbitonti assigned tbitonti and unassigned cbridgha Jun 7, 2022

tbitonti added the release bug This bug is present in a released version of Open Liberty label Nov 9, 2022

tbitonti mentioned this issue Dec 1, 2022

Rerun runtime trace injection if problem byte codes are detected. #23562

Merged

tbitonti closed this as completed Feb 7, 2023

LibbyBot added the release:23002 label Feb 23, 2023

jimblye added this to Open Liberty Kernel Team May 21, 2024

jimblye moved this to Completed Tasks in Open Liberty Kernel Team May 21, 2024

JDUNNIN mentioned this issue Nov 5, 2024

TRAS3000E: Runtime injection of detailed method trace failed for class abc #30070

Open

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Runtime injection of detailed method trace fails for a CDI bean #16007

Runtime injection of detailed method trace fails for a CDI bean #16007

JDUNNIN commented Feb 23, 2021 •

edited by tbitonti

Loading

Azquelt commented Mar 4, 2021

JDUNNIN commented Jun 9, 2021

JDUNNIN commented Aug 31, 2021

JDUNNIN commented Oct 5, 2021

JDUNNIN commented Oct 6, 2021

JDUNNIN commented Oct 12, 2021

JDUNNIN commented Apr 25, 2022

tbitonti commented Nov 9, 2022

tbitonti commented Nov 9, 2022

tbitonti commented Nov 10, 2022

tbitonti commented Nov 15, 2022

tbitonti commented Jan 10, 2023

Runtime injection of detailed method trace fails for a CDI bean #16007

Runtime injection of detailed method trace fails for a CDI bean #16007

Comments

JDUNNIN commented Feb 23, 2021 • edited by tbitonti Loading

Azquelt commented Mar 4, 2021

JDUNNIN commented Jun 9, 2021

JDUNNIN commented Aug 31, 2021

JDUNNIN commented Oct 5, 2021

JDUNNIN commented Oct 6, 2021

JDUNNIN commented Oct 12, 2021

JDUNNIN commented Apr 25, 2022

tbitonti commented Nov 9, 2022

tbitonti commented Nov 9, 2022

tbitonti commented Nov 10, 2022

tbitonti commented Nov 15, 2022

tbitonti commented Jan 10, 2023

JDUNNIN commented Feb 23, 2021 •

edited by tbitonti

Loading