newrelic / newrelic-java-agent

The New Relic Java agent
Apache License 2.0
202 stars 144 forks source link

Solr 9 failed to run with NR java agent #1085

Open lowang opened 1 year ago

lowang commented 1 year ago

Description

Solr fails to start, first WARN is

2022-11-17 15:46:09.172 WARN  (main) [] o.e.j.w.WebAppContext Failed startup of context o.e.j.w.WebAppContext@6de610c6{/solr,file:///opt/solr-9.0.0/server/solr-webapp/webapp/,UNAVAILABLE}{/opt/solr-9.0.0/server/solr-webapp/webapp} => java.lang.VerifyError: Bad type on operand stack
Exception Details:
java.lang.VerifyError: Bad type on operand stack
Exception Details:
  Location:
    org/eclipse/jetty/servlet/listener/ELContextCleaner.contextDestroyed(Ljavax/servlet/ServletContextEvent;)V @154: invokeinterface
  Reason:
    Type 'java/lang/Object' (current frame, stack[2]) is not assignable to 'java/lang/Throwable'
  Current Frame:
    bci: @154
    flags: { }
    locals: { 'org/eclipse/jetty/servlet/listener/ELContextCleaner', 'javax/servlet/ServletContextEvent', 'com/newrelic/agent/bridge/ExitTracer', integer, top, 'javax/servlet/ServletContextEvent', 'org/eclipse/jetty/servlet/listener/ELContextCleaner', 'java/lang/Object' }
    stack: { 'org/eclipse/jetty/util/log/Logger', 'java/lang/String', 'java/lang/Object' }
  Bytecode:
    0000000: 014d b200 262a 0601 100e b900 3a05 004d
    0000010: a700 0457 033e b800 3eb9 0044 0100 b200
    0000020: 4a03 124c 05bd 004e 5903 2ab6 0052 b600
    0000030: 5853 5904 127a 53b9 005f 0500 57a7 0016
    0000040: 3a04 b200 2619 0412 27b9 002d 0300 a700
    0000050: 0304 3e2a 2b3a 053a 0612 7cb8 0082 3a07
    0000060: 1906 1907 b600 863a 0819 0619 08b6 008a
    0000070: b200 8cb9 0092 0100 9900 11b2 008c 1294
    0000080: 03bd 0005 b900 9803 00a7 0029 3a07 a700
    0000090: 243a 07b2 008c 129a 1907 b900 9e03 00a7
    00000a0: 0013 3a07 b200 8c12 a003 bd00 05b9 0098
    00000b0: 0300 a700 0303 1d9f 0012 2cc6 000d 2c11
    00000c0: 00b1 01b9 0065 0300 b12c c600 0d2c 1100
    00000d0: b101 b900 6503 00b1 3a04 b200 2619 0412
    00000e0: 27b9 002d 0300 a700 032c c600 0d2c 1100
    00000f0: b101 b900 6503 00b1 2cc6 000b 592c 5fb9
    0000100: 0068 0200 bf
  Exception Handler Table:
    bci [2, 20] => handler: 19
    bci [89, 137] => handler: 140
    bci [89, 137] => handler: 145
    bci [89, 137] => handler: 145
    bci [89, 137] => handler: 145
    bci [89, 137] => handler: 162
    bci [22, 64] => handler: 64
    bci [201, 216] => handler: 216
    bci [2, 248] => handler: 248
  Stackmap Table:
    full_frame(@19,{Object[#3],Object[#110],Object[#97]},{Object[#30]})
    same_frame(@20)
    full_frame(@64,{Object[#3],Object[#110],Object[#97],Integer},{Object[#30]})
    append_frame(@81,Object[#30])
    chop_frame(@83,1)
    full_frame(@137,{Object[#3],Object[#110],Object[#97],Integer,Top,Object[#110],Object[#3],Object[#84],Object[#170]},{})
    full_frame(@140,{Object[#3],Object[#110],Object[#97],Integer,Top,Object[#110],Object[#3]},{Object[#113]})
    same_locals_1_stack_item_frame(@145,Object[#5])
    same_locals_1_stack_item_frame(@162,Object[#121])
    append_frame(@178,Object[#5])
    same_frame(@181)
    same_frame(@200)
    same_frame(@201)
    same_frame(@215)
    same_locals_1_stack_item_frame(@216,Object[#30])
    full_frame(@233,{Object[#3],Object[#110],Object[#97],Integer,Object[#30],Object[#110],Object[#3],Object[#5]},{})
    same_frame(@247)
    full_frame(@248,{Object[#3],Object[#110],Object[#97]},{Object[#30]})
    same_locals_1_stack_item_frame(@260,Object[#30])

    at java.lang.Class.getDeclaredConstructors0(Native Method) ~[?:?]
    at java.lang.Class.privateGetDeclaredConstructors(Unknown Source) ~[?:?]
    at java.lang.Class.getConstructor0(Unknown Source) ~[?:?]
    at java.lang.Class.getDeclaredConstructor(Unknown Source) ~[?:?]
    at org.eclipse.jetty.server.handler.ContextHandler$StaticContext.createInstance(ContextHandler.java:2881) ~[jetty-server-9.4.44.v20210927.jar:9.4.44.v20210927]
    at org.eclipse.jetty.servlet.ServletContextHandler$Context.createInstance(ServletContextHandler.java:1299) ~[jetty-servlet-9.4.44.v20210927.jar:9.4.44.v20210927]
    at org.eclipse.jetty.server.handler.ContextHandler$StaticContext.createListener(ContextHandler.java:2892) ~[jetty-server-9.4.44.v20210927.jar:9.4.44.v20210927]
    at org.eclipse.jetty.servlet.ListenerHolder.doStart(ListenerHolder.java:94) ~[jetty-servlet-9.4.44.v20210927.jar:9.4.44.v20210927]
    at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:73) ~[jetty-util-9.4.44.v20210927.jar:9.4.44.v20210927]
    at org.eclipse.jetty.servlet.ServletContextHandler.startContext(ServletContextHandler.java:369) ~[jetty-servlet-9.4.44.v20210927.jar:9.4.44.v20210927]
    at org.eclipse.jetty.webapp.WebAppContext.startWebapp(WebAppContext.java:1449) ~[jetty-webapp-9.4.44.v20210927.jar:9.4.44.v20210927]
    at org.eclipse.jetty.webapp.WebAppContext.startContext(WebAppContext.java:1414) ~[jetty-webapp-9.4.44.v20210927.jar:9.4.44.v20210927]
    at org.eclipse.jetty.server.handler.ContextHandler.doStart(ContextHandler.java:910) ~[jetty-server-9.4.44.v20210927.jar:9.4.44.v20210927]
    at org.eclipse.jetty.servlet.ServletContextHandler.doStart(ServletContextHandler.java:288) ~[jetty-servlet-9.4.44.v20210927.jar:9.4.44.v20210927]
    at org.eclipse.jetty.webapp.WebAppContext.doStart(WebAppContext.java:524) ~[jetty-webapp-9.4.44.v20210927.jar:9.4.44.v20210927]
    at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:73) ~[jetty-util-9.4.44.v20210927.jar:9.4.44.v20210927]
    at org.eclipse.jetty.util.component.ContainerLifeCycle.start(ContainerLifeCycle.java:169) ~[jetty-util-9.4.44.v20210927.jar:9.4.44.v20210927]
    at org.eclipse.jetty.util.component.ContainerLifeCycle.doStart(ContainerLifeCycle.java:117) ~[jetty-util-9.4.44.v20210927.jar:9.4.44.v20210927]
    at org.eclipse.jetty.server.handler.AbstractHandler.doStart(AbstractHandler.java:97) ~[jetty-server-9.4.44.v20210927.jar:9.4.44.v20210927]
    at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:73) ~[jetty-util-9.4.44.v20210927.jar:9.4.44.v20210927]
    at org.eclipse.jetty.util.component.ContainerLifeCycle.start(ContainerLifeCycle.java:169) ~[jetty-util-9.4.44.v20210927.jar:9.4.44.v20210927]
    at org.eclipse.jetty.util.component.ContainerLifeCycle.doStart(ContainerLifeCycle.java:110) ~[jetty-util-9.4.44.v20210927.jar:9.4.44.v20210927]
    at org.eclipse.jetty.server.handler.AbstractHandler.doStart(AbstractHandler.java:97) ~[jetty-server-9.4.44.v20210927.jar:9.4.44.v20210927]
    at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:73) ~[jetty-util-9.4.44.v20210927.jar:9.4.44.v20210927]
    at org.eclipse.jetty.util.component.ContainerLifeCycle.start(ContainerLifeCycle.java:169) ~[jetty-util-9.4.44.v20210927.jar:9.4.44.v20210927]
    at org.eclipse.jetty.util.component.ContainerLifeCycle.doStart(ContainerLifeCycle.java:117) ~[jetty-util-9.4.44.v20210927.jar:9.4.44.v20210927]
    at org.eclipse.jetty.server.handler.AbstractHandler.doStart(AbstractHandler.java:97) ~[jetty-server-9.4.44.v20210927.jar:9.4.44.v20210927]
    at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:73) ~[jetty-util-9.4.44.v20210927.jar:9.4.44.v20210927]
    at org.eclipse.jetty.util.component.ContainerLifeCycle.start(ContainerLifeCycle.java:169) ~[jetty-util-9.4.44.v20210927.jar:9.4.44.v20210927]
    at org.eclipse.jetty.util.component.ContainerLifeCycle.doStart(ContainerLifeCycle.java:110) ~[jetty-util-9.4.44.v20210927.jar:9.4.44.v20210927]
    at org.eclipse.jetty.server.handler.AbstractHandler.doStart(AbstractHandler.java:97) ~[jetty-server-9.4.44.v20210927.jar:9.4.44.v20210927]
    at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:73) ~[jetty-util-9.4.44.v20210927.jar:9.4.44.v20210927]
    at org.eclipse.jetty.util.component.ContainerLifeCycle.start(ContainerLifeCycle.java:169) ~[jetty-util-9.4.44.v20210927.jar:9.4.44.v20210927]
    at org.eclipse.jetty.util.component.ContainerLifeCycle.doStart(ContainerLifeCycle.java:110) ~[jetty-util-9.4.44.v20210927.jar:9.4.44.v20210927]
    at org.eclipse.jetty.server.handler.AbstractHandler.doStart(AbstractHandler.java:97) ~[jetty-server-9.4.44.v20210927.jar:9.4.44.v20210927]
    at org.eclipse.jetty.server.handler.gzip.GzipHandler.doStart(GzipHandler.java:426) ~[jetty-server-9.4.44.v20210927.jar:9.4.44.v20210927]
    at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:73) ~[jetty-util-9.4.44.v20210927.jar:9.4.44.v20210927]
    at org.eclipse.jetty.util.component.ContainerLifeCycle.start(ContainerLifeCycle.java:169) ~[jetty-util-9.4.44.v20210927.jar:9.4.44.v20210927]
    at org.eclipse.jetty.server.Server.start(Server.java:423) ~[jetty-server-9.4.44.v20210927.jar:9.4.44.v20210927]
    at org.eclipse.jetty.util.component.ContainerLifeCycle.doStart(ContainerLifeCycle.java:110) ~[jetty-util-9.4.44.v20210927.jar:9.4.44.v20210927]
    at org.eclipse.jetty.server.handler.AbstractHandler.doStart(AbstractHandler.java:97) ~[jetty-server-9.4.44.v20210927.jar:9.4.44.v20210927]
    at org.eclipse.jetty.server.Server.doStart(Server.java:387) ~[jetty-server-9.4.44.v20210927.jar:9.4.44.v20210927]
    at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:73) ~[jetty-util-9.4.44.v20210927.jar:9.4.44.v20210927]
    at org.eclipse.jetty.xml.XmlConfiguration.lambda$main$3(XmlConfiguration.java:1907) ~[jetty-xml-9.4.44.v20210927.jar:9.4.44.v20210927]
    at java.security.AccessController.doPrivileged(Unknown Source) ~[?:?]
    at org.eclipse.jetty.xml.XmlConfiguration.main(XmlConfiguration.java:1857) ~[jetty-xml-9.4.44.v20210927.jar:9.4.44.v20210927]
    at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
    at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(Unknown Source) ~[?:?]
    at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) ~[?:?]
    at java.lang.reflect.Method.invoke(Unknown Source) ~[?:?]
    at org.eclipse.jetty.start.Main.invokeMain(Main.java:218) ~[start.jar:9.4.44.v20210927]
    at org.eclipse.jetty.start.Main.start(Main.java:491) ~[start.jar:9.4.44.v20210927]
    at org.eclipse.jetty.start.Main.main(Main.java:77) ~[start.jar:9.4.44.v20210927]

then logs are full of:

2022-11-17 15:46:24.381 WARN  (qtp1824931880-53) [] o.e.j.i.ManagedSelector java.lang.VerifyError: Bad type on operand stack
Exception Details:
  Location:
    org/eclipse/jetty/server/Request.getParameters()Lorg/eclipse/jetty/util/MultiMap; @31: invokevirtual
  Reason:
    Type 'java/lang/Object' (current frame, stack[1]) is not assignable to 'java/lang/RuntimeException'
  Current Frame:
    bci: @31
    flags: { }
    locals: { 'org/eclipse/jetty/server/Request', 'java/lang/Object' }
    stack: { 'org/eclipse/jetty/util/log/Logger', 'java/lang/Object' }
  Bytecode:
    0000000: 2ab4 01d5 9a00 332a 04b5 01d5 2ab4 01d7
    0000010: c700 272a b701 daa7 0020 4cb2 01b0 2bb6
    0000020: 01dd 03bd 0005 b901 e003 00bb 01e2 5913
    0000030: 01e4 2bb7 01e7 bf2a b401 e9c7 0017 2ab7
    0000040: 01ec a700 104c bb01 e259 1301 ee2b b701
    0000050: e7bf 2ab4 01e9 b801 f09a 000d 2ab4 01e9
    0000060: b601 f39a 000e 2a2a b401 d7b5 01f5 a700
    0000070: 4c2a b401 d7b8 01f0 9a00 0d2a b401 d7b6
    0000080: 01f3 9a00 0e2a 2ab4 01e9 b501 f5a7 002d
    0000090: 2ab4 01f5 c700 262a bb01 f259 b701 f6b5
    00000a0: 01f5 2ab4 01f5 2ab4 01e9 b601 f957 2ab4
    00000b0: 01f5 2ab4 01d7 b601 f957 2ab4 01f5 4c2b
    00000c0: c700 09b2 009e a700 042b b0
  Exception Handler Table:
    bci [19, 23] => handler: 26
    bci [19, 23] => handler: 26
    bci [62, 66] => handler: 69
    bci [62, 66] => handler: 69
  Stackmap Table:
    same_locals_1_stack_item_frame(@26,Object[#5])
    same_frame(@55)
    same_locals_1_stack_item_frame(@69,Object[#5])
    same_frame(@82)
    same_frame(@102)
    same_frame(@113)
    same_frame(@133)
    same_frame(@144)
    same_frame(@186)
    append_frame(@201,Object[#498])
    same_locals_1_stack_item_frame(@202,Object[#498])

Cannot reach Solr UI on localhost:8983

Expected Behavior

Solr UI reachable via localhost:8983

Troubleshooting or NR Diag results

Steps to Reproduce

download and unzip newrelic-java.zip in current folder, then:

docker run --rm -it -p 8983:8983 -e SOLR_OPTS="-javaagent:/opt/newrelic/newrelic.jar" -e NEW_RELIC_APP_NAME="SolrCloud" -e NEW_RELIC_LICENSE_KEY=euXXXXXX -v $PWD/newrelic:/opt/newrelic solr:9

Your Environment

Eclipse Adoptium OpenJDK 64-Bit Server VM 17.0.5 17.0.5+8 Official solr:9 docker image.

Additional context

workato-integration[bot] commented 1 year ago

https://issues.newrelic.com/browse/NEWRELIC-5410

kford-newrelic commented 1 year ago

@lowang sorry to hear that you're running into issues - thanks for letting us know about this though

Have you successfully been using our agent with Solr before - perhaps different combinations of versions - or is this your first time using our agent?

Assuming that you've successfully been using our agent with Solr before, what changes/upgrades in your environment have been made recently?

Have you identified any other workarounds you're able to use?

lowang commented 1 year ago

@kford-newrelic unfortunately no, I'm stuck here. Since I'm using official Solr image I was hoping to get it working out of the box. Looking for your assistance how to proceed. Seems like JAVA_VERSION variable changed between Solr 8.6 & 9 versions from: 11.0.15 to jdk-17.0.5+8 but according to https://docs.newrelic.com/docs/apm/agents/java-agent/getting-started/compatibility-requirements-java-agent/ this is supported.

kford-newrelic commented 1 year ago

Are you able to try using Java 11?

Just want to see if we can rule in/out whether it's Java 17 related

lowang commented 1 year ago

@kford-newrelic I've build Solr image using java 11, according to https://github.com/apache/solr/tree/main/solr/docker#building-from-the-solr-binary-distribution

docker build --build-arg BASE_IMAGE=eclipse-temurin:11-jre-focal -f solr-9.1.0/docker/Dockerfile -t solr:9.1.0 - < solr-9.1.0.tgz

however result is the same.

kford-newrelic commented 1 year ago

@lowang sorry to hear that; we do have some customers using Solr 9 successfully, so we'd need to investigate more what's going on with the image/approach that you're using.

Unfortunately, we weren't able to get this on our roadmap for the next (Jan-Mar) quarter, so we can't give a commitment on when that can happen.

workato-integration[bot] commented 1 year ago

Jira CommentId: 149713 Commented by jkeller:

This can be repro'd by downloading the [Solr 9.1.1 binary,|#solr-911] adding the agent in the {{bin/solr.in.sh}} script (as shown below),  {code:java} SOLR_OPTS="$SOLR_OPTS -javaagent:/path/to/newrelic/newrelic.jar" {code} and starting the solr server demo project via {code:java} bin/solr start -e techproducts {code} You should see the {{VerifyError}} in the {{../solr-9.1.1/example/techproducts/logs/solr.log}}

kford-newrelic commented 1 year ago

From the list of major changes:

Solr now runs with the Java security manager enabled by default. Hadoop users may need to disable this.

It appears that disabling this may prevent this issue

Need to investigate further to understand the root cause of the conflict

rahmnathan commented 1 year ago

I also ran into this - confirmed that setting SOLR_SECURITY_MANAGER_ENABLED=false 'fixes' the issue.

JoshuaJackson-jobvite commented 6 months ago

So adding the following grants into the security manager gets you to the above message, assuming you're installing newrelic into /opt/newrelic.

grant {
  // allow the new relic agent
  permission java.io.FilePermission "/opt/newrelic${/}-", "read";
  permission java.io.FilePermission "/opt/newrelic", "read,";
  permission java.io.FilePermission "/proc/sys/kernel/random/boot_id", "read";             
  permission java.io.FilePermission "/proc/self/mountinfo", "read";
  permission java.io.FilePermission "/proc/self/cgroup", "read";
  permission java.io.FilePermission "/proc/cpuinfo", "read";
};

with solr.

JoshuaJackson-jobvite commented 6 months ago

Additionally this seems to be the same issue in #1416 where @jasonjkeller did an excellent analysis of the broader issues involved with the weaver/weaving, this appears from initial analysis to be the same.