Application deployment fails when setting trace_methods #474

TeroPihlaja · 2019-02-04T09:44:29Z

Describe the bug
Application deployment fails when setting trace_methods to "all"

trace_methods=com.vilant.*#*

Payara 5.183
Oracle java version "1.8.0_172"

Debug logs
Attach your debug logs.
See the documentation
about how to enable debug logging.

Click to expand

[2019-02-04T11:39:47.785+0200] [Payara 5.183] [SEVERE] [] [javax.enterprise.system.tools.deployment.common] [tid: _ThreadID=27 _ThreadName=RunLevelControllerThread-1549273153767] [timeMillis: 1549273187785] [levelValue: 1000] [[
  Exception while invoking class org.glassfish.ejb.startup.EjbDeployer load method
java.lang.RuntimeException: EJB Container initialization error
        at org.glassfish.ejb.startup.EjbApplication.loadContainers(EjbApplication.java:237)
        at org.glassfish.ejb.startup.EjbDeployer.load(EjbDeployer.java:293)
        at org.glassfish.ejb.startup.EjbDeployer.load(EjbDeployer.java:103)
        at org.glassfish.internal.data.ModuleInfo.load(ModuleInfo.java:209)
        at org.glassfish.internal.data.ApplicationInfo.load(ApplicationInfo.java:318)
        at com.sun.enterprise.v3.server.ApplicationLifecycle.prepare(ApplicationLifecycle.java:496)
        at com.sun.enterprise.v3.server.ApplicationLoaderService.processApplication(ApplicationLoaderService.java:418)
        at com.sun.enterprise.v3.server.ApplicationLoaderService.postConstruct(ApplicationLoaderService.java:248)
        at org.jvnet.hk2.internal.ClazzCreator.postConstructMe(ClazzCreator.java:327)
        at org.jvnet.hk2.internal.ClazzCreator.create(ClazzCreator.java:375)
        at org.jvnet.hk2.internal.SystemDescriptor.create(SystemDescriptor.java:487)
        at org.glassfish.hk2.runlevel.internal.AsyncRunLevelContext.findOrCreate(AsyncRunLevelContext.java:305)
        at org.glassfish.hk2.runlevel.RunLevelContext.findOrCreate(RunLevelContext.java:89)
        at org.jvnet.hk2.internal.Utilities.createService(Utilities.java:2126)
        at org.jvnet.hk2.internal.ServiceHandleImpl.getService(ServiceHandleImpl.java:116)
        at org.jvnet.hk2.internal.ServiceHandleImpl.getService(ServiceHandleImpl.java:90)
        at org.glassfish.hk2.runlevel.internal.CurrentTaskFuture$QueueRunner.oneJob(CurrentTaskFuture.java:1237)
        at org.glassfish.hk2.runlevel.internal.CurrentTaskFuture$QueueRunner.run(CurrentTaskFuture.java:1168)
        at org.glassfish.hk2.runlevel.internal.CurrentTaskFuture$UpOneLevel.run(CurrentTaskFuture.java:786)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at java.lang.Thread.run(Thread.java:748)
Caused by: java.lang.VerifyError: Stack map does not match the one at exception handler 95
Exception Details:
  Location:
    com/vilant/integration/db/Point._persistence_post_clone()Ljava/lang/Object; @95: astore_3
  Reason:
    Type 'com/vilant/integration/db/Point' (current frame, locals[1]) is not assignable to 'co/elastic/apm/agent/impl/transaction/AbstractSpan' (stack map, locals[1])
  Current Frame:
    bci: @84
    flags: { }
    locals: { 'com/vilant/integration/db/Point', 'com/vilant/integration/db/Point', 'com/vilant/integration/db/Point' }
    stack: { 'java/lang/Throwable' }
  Stackmap Frame:
    bci: @95
    flags: { }
    locals: { 'com/vilant/integration/db/Point', 'co/elastic/apm/agent/impl/transaction/AbstractSpan' }
    stack: { 'java/lang/Throwable' }
  Bytecode:
    0x0000000: 014c b200 6ec6 002d b200 6eb6 0074 4d2c
    0x0000010: c700 15b2 006e b600 7812 9eb6 0080 b600
    0x0000020: 834c a700 102c b600 8712 9eb6 008c b600
    0x0000030: 8d4c a700 06b6 0090 2a4d 2cb7 0030 2c01
    0x0000040: b500 342c 01b5 0038 2c01 b500 3c2c 01b5
    0x0000050: 0040 2c4c 572b a700 034d 014e a700 064e
    0x0000060: 014d 2bc6 000e 2b2d b600 94b6 0097 b600
    0x0000070: 9aa7 0006 b600 902d c600 052d bf2c b0
  Exception Handler Table:
    bci [2, 53] => handler: 53
    bci [58, 89] => handler: 95
    bci [98, 116] => handler: 116
  Stackmap Table:
    append_frame(@2,Object[#104])
    append_frame(@37,Object[#104])
    chop_frame(@50,1)
    same_locals_1_stack_item_frame(@53,Object[#102])
    same_frame(@56)
    append_frame(@58,Object[#2])
    full_frame(@89,{Object[#2],Object[#104]},{Object[#160]})
    same_locals_1_stack_item_frame(@95,Object[#102])
    append_frame(@98,Object[#160],Object[#102])
    same_frame(@113)
    same_locals_1_stack_item_frame(@116,Object[#102])
    same_frame(@119)
    same_frame(@125)
        at java.lang.Class.forName0(Native Method)
        at java.lang.Class.forName(Class.java:264)
        at com.sun.proxy.$Proxy333.<clinit>(Unknown Source)
        at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
        at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
        at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
        at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
        at com.sun.ejb.containers.BaseContainer.instantiateEJBLocalBusinessObjectImpl(BaseContainer.java:3875)
        at com.sun.ejb.containers.StatelessSessionContainer.initializeHome(StatelessSessionContainer.java:236)
        at com.sun.ejb.containers.StatelessContainerFactory.createContainer(StatelessContainerFactory.java:63)
        at org.glassfish.ejb.startup.EjbApplication.loadContainers(EjbApplication.java:225)
        ... 21 more
]]

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

TeroPihlaja · 2019-02-04T09:45:40Z

Elastic APM agent version is 1.3.0.

eyalkoren · 2019-02-04T09:55:45Z

Should be fixed with #432.
Please try this snapshot: https://github.com/elastic/apm-agent-java/files/2825540/elastic-apm-agent-1.3.1-SNAPSHOT.jar.zip

eyalkoren · 2019-02-04T10:02:51Z

@TeroPihlaja Also, please be very aware to what you define to be traced using this configuration. Such a wide wildcard would probably be OK of debugging, but not so for production. It's advisable to be (much) more specific in what you choose to instrument. The instrumentation overhead may still remain negligible, but sending and storing spans for ALL methods may be way too much.

TeroPihlaja · 2019-02-04T10:29:48Z

Hello,

Yes, I believe that option needs tuning for production.

Looks like same/similar error with the snapshot:

[2019-02-04T12:26:59.193+0200] [Payara 5.183] [SEVERE] [] [javax.enterprise.system.tools.deployment.common] [tid: _ThreadID=28 _ThreadName=RunLevelControllerThread-1549275988312] [timeMillis: 1549276019193] [levelValue: 1000] [[
  Exception while invoking class org.glassfish.ejb.startup.EjbDeployer load method
java.lang.RuntimeException: EJB Container initialization error
        at org.glassfish.ejb.startup.EjbApplication.loadContainers(EjbApplication.java:237)
        at org.glassfish.ejb.startup.EjbDeployer.load(EjbDeployer.java:293)
        at org.glassfish.ejb.startup.EjbDeployer.load(EjbDeployer.java:103)
        at org.glassfish.internal.data.ModuleInfo.load(ModuleInfo.java:209)
        at org.glassfish.internal.data.ApplicationInfo.load(ApplicationInfo.java:318)
        at com.sun.enterprise.v3.server.ApplicationLifecycle.prepare(ApplicationLifecycle.java:496)
        at com.sun.enterprise.v3.server.ApplicationLoaderService.processApplication(ApplicationLoaderService.java:418)
        at com.sun.enterprise.v3.server.ApplicationLoaderService.postConstruct(ApplicationLoaderService.java:248)
        at org.jvnet.hk2.internal.ClazzCreator.postConstructMe(ClazzCreator.java:327)
        at org.jvnet.hk2.internal.ClazzCreator.create(ClazzCreator.java:375)
        at org.jvnet.hk2.internal.SystemDescriptor.create(SystemDescriptor.java:487)
        at org.glassfish.hk2.runlevel.internal.AsyncRunLevelContext.findOrCreate(AsyncRunLevelContext.java:305)
        at org.glassfish.hk2.runlevel.RunLevelContext.findOrCreate(RunLevelContext.java:89)
        at org.jvnet.hk2.internal.Utilities.createService(Utilities.java:2126)
        at org.jvnet.hk2.internal.ServiceHandleImpl.getService(ServiceHandleImpl.java:116)
        at org.jvnet.hk2.internal.ServiceHandleImpl.getService(ServiceHandleImpl.java:90)
        at org.glassfish.hk2.runlevel.internal.CurrentTaskFuture$QueueRunner.oneJob(CurrentTaskFuture.java:1237)
        at org.glassfish.hk2.runlevel.internal.CurrentTaskFuture$QueueRunner.run(CurrentTaskFuture.java:1168)
        at org.glassfish.hk2.runlevel.internal.CurrentTaskFuture$UpOneLevel.run(CurrentTaskFuture.java:786)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at java.lang.Thread.run(Thread.java:748)
Caused by: java.lang.VerifyError: Stack map does not match the one at exception handler 101
Exception Details:
  Location:
    com/vilant/integration/db/Point._persistence_post_clone()Ljava/lang/Object; @101: astore_3
  Reason:
    Type 'com/vilant/integration/db/Point' (current frame, locals[1]) is not assignable to 'co/elastic/apm/agent/impl/transaction/AbstractSpan' (stack map, locals[1])
  Current Frame:
    bci: @90
    flags: { }
    locals: { 'com/vilant/integration/db/Point', 'com/vilant/integration/db/Point', 'com/vilant/integration/db/Point' }
    stack: { 'java/lang/Throwable' }
  Stackmap Frame:
    bci: @101
    flags: { }
    locals: { 'com/vilant/integration/db/Point', 'co/elastic/apm/agent/impl/transaction/AbstractSpan' }
    stack: { 'java/lang/Throwable' }
  Bytecode:
    0x0000000: 014c b200 6ec6 0033 b200 6eb6 0074 4d2c
    0x0000010: c700 18b2 006e b600 7812 a0b6 0080 b600
    0x0000020: 83c0 0068 4ca7 0013 2cb6 0089 12a0 b600
    0x0000030: 8eb6 008f c000 684c a700 06b6 0092 2a4d
    0x0000040: 2cb7 0030 2c01 b500 342c 01b5 0038 2c01
    0x0000050: b500 3c2c 01b5 0040 2c4c 572b a700 034d
    0x0000060: 014e a700 064e 014d 2bc6 0013 2b2d b600
    0x0000070: 9657 2bb6 0099 c000 68b6 009c a700 06b6
    0x0000080: 0092 2dc6 0005 2dbf 2cb0
  Exception Handler Table:
    bci [2, 59] => handler: 59
    bci [64, 95] => handler: 101
    bci [104, 127] => handler: 127
  Stackmap Table:
    append_frame(@2,Object[#104])
    append_frame(@40,Object[#133])
    chop_frame(@56,1)
    same_locals_1_stack_item_frame(@59,Object[#102])
    same_frame(@62)
    append_frame(@64,Object[#2])
    full_frame(@95,{Object[#2],Object[#104]},{Object[#162]})
    same_locals_1_stack_item_frame(@101,Object[#102])
    append_frame(@104,Object[#162],Object[#102])
    same_frame(@124)
    same_locals_1_stack_item_frame(@127,Object[#102])
    same_frame(@130)
    same_frame(@136)

        at java.lang.Class.forName0(Native Method)
        at java.lang.Class.forName(Class.java:264)
        at com.sun.proxy.$Proxy342.<clinit>(Unknown Source)
        at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
        at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
        at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
        at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
        at com.sun.ejb.containers.BaseContainer.instantiateEJBLocalBusinessObjectImpl(BaseContainer.java:3875)
        at com.sun.ejb.containers.StatelessSessionContainer.initializeHome(StatelessSessionContainer.java:236)
        at com.sun.ejb.containers.StatelessContainerFactory.createContainer(StatelessContainerFactory.java:63)
        at org.glassfish.ejb.startup.EjbApplication.loadContainers(EjbApplication.java:225)
        ... 21 more
]]

felixbarny · 2019-02-04T14:22:47Z

We believe this is a problem with the byte code EclipseLink generates for the generated _persistence_post_clone method. We will add an option to ignore certain methods and add _persistence* by default. Are you using the latest version of EclipseLink?

TeroPihlaja · 2019-02-04T14:24:57Z

This project is using EclipseLink, version: Eclipse Persistence Services - 2.7.3.v20180807-4be1041

eyalkoren · 2019-02-04T15:32:53Z

@TeroPihlaja please test this one:
elastic-apm-agent-1.3.1-SNAPSHOT.jar.zip

TeroPihlaja · 2019-02-05T07:17:02Z

Seems to work!

eyalkoren · 2019-02-05T07:47:43Z

That's great to hear! You can continue using this snapshot for evaluation and the next release will include the fix.

eyalkoren added [zube]: Inbox and removed [zube]: Inbox labels Feb 4, 2019

felixbarny assigned eyalkoren Feb 4, 2019

eyalkoren mentioned this issue Feb 4, 2019

Adding configurable method-name blacklist for trace_methods #476

Merged

eyalkoren closed this as completed Feb 5, 2019

zube bot added [zube]: Done and removed [zube]: In Progress labels Feb 5, 2019

zube bot reopened this Feb 5, 2019

zube bot added [zube]: In Progress and removed [zube]: Done labels Feb 5, 2019

eyalkoren closed this as completed Feb 5, 2019

zube bot added [zube]: Done and removed [zube]: In Progress labels Feb 5, 2019

alvarolobato removed the [zube]: Done label Feb 18, 2019

SylvainJuge added bug Bugs and removed type: bug labels Feb 2, 2021

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Application deployment fails when setting trace_methods #474

Application deployment fails when setting trace_methods #474

TeroPihlaja commented Feb 4, 2019

TeroPihlaja commented Feb 4, 2019

eyalkoren commented Feb 4, 2019

eyalkoren commented Feb 4, 2019

TeroPihlaja commented Feb 4, 2019

felixbarny commented Feb 4, 2019

TeroPihlaja commented Feb 4, 2019

eyalkoren commented Feb 4, 2019

TeroPihlaja commented Feb 5, 2019

eyalkoren commented Feb 5, 2019

Application deployment fails when setting trace_methods #474

Application deployment fails when setting trace_methods #474

Comments

TeroPihlaja commented Feb 4, 2019

TeroPihlaja commented Feb 4, 2019

eyalkoren commented Feb 4, 2019

eyalkoren commented Feb 4, 2019

TeroPihlaja commented Feb 4, 2019

felixbarny commented Feb 4, 2019

TeroPihlaja commented Feb 4, 2019

eyalkoren commented Feb 4, 2019

TeroPihlaja commented Feb 5, 2019

eyalkoren commented Feb 5, 2019