Java NR agent v6.0.0 crashes jboss 10

boonew2 commented 4 years ago

Description

When starting a jboss/keycloak:8.0.2 docker container with the NR agent the container crashes

(I have minimal java knowledge so I'm not sure that the issue is directly with jboss)

Expected Behavior

I would be able to pull the latest NR agent and still have the container start

Troubleshooting or [NR Diag]

2020-08-31 09:54:47ERROR: WFLYCTL0013: Operation ("parallel-extension-add") failed - address: ([])
2020-08-31 09:54:47java.lang.RuntimeException: WFLYCTL0079: Failed initializing module org.jboss.as.logging
2020-08-31 09:54:47at org.jboss.as.controller@10.0.3.Final//org.jboss.as.controller.extension.ParallelExtensionAddHandler$1.execute(ParallelExtensionAddHandler.java:115)
2020-08-31 09:54:47at org.jboss.as.controller@10.0.3.Final//org.jboss.as.controller.AbstractOperationContext.executeStep(AbstractOperationContext.java:999)
2020-08-31 09:54:47at org.jboss.as.controller@10.0.3.Final//org.jboss.as.controller.AbstractOperationContext.processStages(AbstractOperationContext.java:743)
2020-08-31 09:54:47at org.jboss.as.controller@10.0.3.Final//org.jboss.as.controller.AbstractOperationContext.executeOperation(AbstractOperationContext.java:467)
2020-08-31 09:54:47at org.jboss.as.controller@10.0.3.Final//org.jboss.as.controller.OperationContextImpl.executeOperation(OperationContextImpl.java:1413)
2020-08-31 09:54:47at org.jboss.as.controller@10.0.3.Final//org.jboss.as.controller.ModelControllerImpl.boot(ModelControllerImpl.java:495)
2020-08-31 09:54:47at org.jboss.as.controller@10.0.3.Final//org.jboss.as.controller.AbstractControllerService.boot(AbstractControllerService.java:472)
2020-08-31 09:54:47at org.jboss.as.controller@10.0.3.Final//org.jboss.as.controller.AbstractControllerService.boot(AbstractControllerService.java:434)
2020-08-31 09:54:47at org.jboss.as.server@10.0.3.Final//org.jboss.as.server.ServerService.boot(ServerService.java:435)
2020-08-31 09:54:47at org.jboss.as.server@10.0.3.Final//org.jboss.as.server.ServerService.boot(ServerService.java:394)
2020-08-31 09:54:47at org.jboss.as.controller@10.0.3.Final//org.jboss.as.controller.AbstractControllerService$1.run(AbstractControllerService.java:374)
2020-08-31 09:54:47at java.base/java.lang.Thread.run(Thread.java:834)
2020-08-31 09:54:47Caused by: java.util.concurrent.ExecutionException: java.lang.IllegalStateException: WFLYLOG0078: The logging subsystem requires the log manager to be org.jboss.logmanager.LogManager. The subsystem has not be initialized and cannot be used. To use JBoss Log Manager you must add the system property "java.util.logging.manager" and set it to "org.jboss.logmanager.LogManager"
2020-08-31 09:54:47at java.base/java.util.concurrent.FutureTask.report(FutureTask.java:122)
2020-08-31 09:54:47at java.base/java.util.concurrent.FutureTask.get(FutureTask.java:191)
2020-08-31 09:54:47at org.jboss.as.controller@10.0.3.Final//org.jboss.as.controller.extension.ParallelExtensionAddHandler$1.execute(ParallelExtensionAddHandler.java:107)
2020-08-31 09:54:47... 11 more
2020-08-31 09:54:47Caused by: java.lang.IllegalStateException: WFLYLOG0078: The logging subsystem requires the log manager to be org.jboss.logmanager.LogManager. The subsystem has not be initialized and cannot be used. To use JBoss Log Manager you must add the system property "java.util.logging.manager" and set it to "org.jboss.logmanager.LogManager"
2020-08-31 09:54:47at org.jboss.as.logging@10.0.3.Final//org.jboss.as.logging.LoggingExtension.initialize(LoggingExtension.java:195)
2020-08-31 09:54:41Aug 31, 2020 4:54:41 PM org.wildfly.security.Version <clinit>
2020-08-31 09:54:41INFO: ELY00001: WildFly Elytron version 1.10.4.Final
2020-08-31 09:54:40OpenJDK 64-Bit Server VM warning: Sharing is only supported for boot loader classes because bootstrap classpath has been appended
2020-08-31 09:54:37Aug 31, 2020 4:54:37 PM org.jboss.vfs.TempFileProvider create
2020-08-31 09:54:37INFO: VFS000002: Failed to clean existing content for temp file provider of type temp. Enable DEBUG level log to find what caused this
2020-08-31 09:54:37Aug 31, 2020 4:54:37 PM org.jboss.as.server.ApplicationServerService start
2020-08-31 09:54:37INFO: WFLYSRV0049: Keycloak 8.0.2 (WildFly Core 10.0.3.Final) starting
2020-08-31 09:54:36Aug 31, 2020 4:54:36 PM org.jboss.threads.Version <clinit>
2020-08-31 09:54:36INFO: JBoss Threads version 2.3.3.Final
2020-08-31 09:54:36Aug 31, 2020 4:54:36 PM org.jboss.msc.service.ServiceContainerImpl <clinit>
2020-08-31 09:54:36INFO: JBoss MSC version 1.4.11.Final
2020-08-31 09:54:34WARNING: Failed to load the specified log manager class org.jboss.logmanager.LogManager
2020-08-31 09:54:30OpenJDK 64-Bit Server VM warning: Sharing is only supported for boot loader classes because bootstrap classpath has been appended
2020-08-31 09:54:30WARNING: An illegal reflective access operation has occurred
2020-08-31 09:54:30WARNING: Illegal reflective access by com.newrelic.weave.weavepackage.NewClassAppender (file:/opt/newrelic/newrelic.jar) to method java.net.URLClassLoader.addURL(java.net.URL)
2020-08-31 09:54:30WARNING: Please consider reporting this to the maintainers of com.newrelic.weave.weavepackage.NewClassAppender
2020-08-31 09:54:30WARNING: Use --illegal-access=warn to enable warnings of further illegal reflective access operations
2020-08-31 09:54:30WARNING: All illegal access operations will be denied in a future release

Steps to Reproduce

I think this is about the minimal setup of my project (replace the agent version to 5.9.0 to fix the startup error) Dockerfile:

FROM jboss/keycloak:8.0.2
USER root
RUN microdnf install -y unzip && microdnf clean all
RUN curl -O https://download.newrelic.com/newrelic/java-agent/newrelic-agent/6.0.0/newrelic-java.zip
RUN unzip newrelic-java.zip -d /opt
USER 1000
ENV NEW_RELIC_BROWSER_MONITORING_AUTO_INSTRUMENT false
ENV NEW_RELIC_LOG_LEVEL off
COPY --chown=jboss:root fs /
RUN chmod +x /opt/jboss/tools/start.sh && chmod +x /opt/jboss/startup-scripts/*.sh
ENTRYPOINT /opt/jboss/tools/start.sh

fs/opt/jboss/startup-scripts/001-add_nr.sh

    JAVA_AGENT='-javaagent:/opt/newrelic/newrelic.jar'
    echo "NEW_RELIC_AGENT_ENABLED set to true; adding $JAVA_AGENT to JAVA_OPTS..."
    echo "JAVA_OPTS=\"\$JAVA_OPTS $JAVA_AGENT\"" >> $JBOSS_HOME/bin/standalone.conf

fs/opt/jboss/tools/start.sh

exec /opt/jboss/tools/docker-entrypoint.sh $@

docker-compose.yml

version: '2.0'
volumes:
  db:
networks:
  keycloak:
services:
  app:
    container_name: keycloak-app
    depends_on:
      - db
    environment:
      NEW_RELIC_APP_NAME: keycloak
      NEW_RELIC_LICENSE_KEY: 'fake'
      DB_ADDR: db
      DB_DATABASE: keycloak
      DB_PASSWORD: password
      DB_PORT: '5432'
      DB_USER: keycloak
      DB_VENDOR: postgres
    ports:
      - '8443:8443'
      - '9990:9990'
    build:
      context: ./build/app
    links:
      - db
    networks:
      keycloak:
  db:
    container_name: keycloak-db
    environment:
      POSTGRES_DB: keycloak
      POSTGRES_PASSWORD: password
      POSTGRES_USER: keycloak
    expose:
      - '5432'
    image: postgres:11.5
    networks:
      keycloak:
    restart: always
    volumes:
      - db:/var/lib/postgresql/data:rw

Your Environment

Included in docker files docker-compose up --build

Additional context

boonew2 commented 4 years ago

Error looks pretty similar to an older forum post: https://discuss.newrelic.com/t/wildfly-18-openj9-nr-5-7-failed-initializing-module-org-jboss-as-logging/85724

I didn't see anything in the release notes that called out a breaking change, but please let me know if i missed that.

breedx-nr commented 4 years ago

Hi @boonew2 , thanks for the bug report.

We'd like to attempt to reproduce this using your wonderful steps...but can you clarify a few things for us?

How does fs/opt/jboss/startup-scripts/001-add_nr.sh make it into the container? It's probably just me, but I'm not seeing it at the moment. Same with fs/opt/jboss/tools/start.sh. I'm not seeing a volume mount nor am I seeing a relevant COPY in the Dockerfile. [edit] I see the COPY now. Sorry.
It's cool that 5.9.0 doesn't have this problem, but we do have a few releases between 5.9.0 and 6.0.0. Would it be possible to try 5.14.0 and 5.13.0 to see if those also have the same issue?

Thanks again!

breedx-nr commented 4 years ago

Confirmed that it doesn't happen without the agent and confirmed that it can be reproduced with the above steps.

boonew2 commented 4 years ago

Just verified that 5.14.0 works. I would have included that instead of 5.9.0 but i got bitten by the alphabetical sorting when browsing https://download.newrelic.com/newrelic/java-agent/newrelic-agent/ 🤦

We had the build pulling current and got bit by the update on the 26th when deploying

Also thanks for the quick response!

breedx-nr commented 4 years ago

I think this is related: https://issues.redhat.com/browse/WFLY-895 Looking into a workaround, but no luck yet.

breedx-nr commented 4 years ago

I believe that I have a workaround for you, @boonew2 .

Can you try changing the 001-add_nr.sh (above) to:

JAVA_AGENT='-Dorg.wildfly.logging.skipLogManagerCheck=true -javaagent:/opt/newrelic/newrelic.jar'
echo "NEW_RELIC_AGENT_ENABLED set to true; adding $JAVA_AGENT to JAVA_OPTS..."
echo "JAVA_OPTS=\"\$JAVA_OPTS $JAVA_AGENT\"" >> $JBOSS_HOME/bin/standalone.conf

Note the addition of a system property that causes the check to be skipped -- this is the workaround that succeeded for me.

There is a lot of prior art out there about jboss LogManager not playing nicely with java agents...going back about 7 years. It seems to have been amplified around the time that java modules were introduced.

I tried about 20 different permutations of the recommended changes, but the above is the only thing that worked for me. Please let us know if this works for you as well. Good luck! 🍀 🤞

boonew2 commented 4 years ago

Yup, that seems to fix it; thanks a ton for quick response on this!

I couldn't quite tell from the linked issues where most the finger pointing was settling on ( wildfly, java modules, agents, ...), but if you don't think this is bug in the new relic agent and it would need to get properly resolved elsewhere feel free to close

breedx-nr commented 4 years ago

@boonew2 Thanks for confirming that this workaround worked for you.

Yeah, there are a lot of moving parts to this, but since I think other agents are also implicated and since this workaround modifies jboss behavior, I think we can close it out. Thanks again.

newrelic / newrelic-java-agent