[elastic-apm-remote-config-poller] WARN org.stagemonitor.util.IOUtils - Read time out after 5000 millis

Elastic Observability APM
, ,
1

Hi,
my APM Java Agent runs with a Weblogic Server and logs every 5 seconds a timeout exception, although there has a connection to the APM server to get configuration changed in KIBANA (transaction_max_spans=100).

2022-07-11 17:25:38,588 [elastic-apm-remote-config-poller] WARN  org.stagemonitor.util.IOUtils - Read time out after 5000 millis
2022-07-11 17:26:13,622 [elastic-apm-remote-config-poller] INFO  co.elastic.apm.agent.configuration.ApmServerConfigurationSource - Received new configuration from APM Server: {transaction_max_spans=100}
2022-07-11 17:26:48,663 [elastic-apm-remote-config-poller] WARN  org.stagemonitor.util.IOUtils - Read time out after 5000 millis

I tried different versions and also debug mode, but I did not find the root cause.

Kibana version: v 7.17.1

Elasticsearch version: 7.17.1

APM Server version: docker.elastic.co/apm/apm-server:7.17.1 and docker.elastic.co/apm/apm-server:7.17.5

APM Agent language and version: elastic-apm-agent-1.28.4.jar, elastic-apm-agent-1.31.0.jar, elastic-apm-agent-1.33.0.jar

Browser version: Chrome

Original install method (e.g. download page, yum, deb, from source, etc.) and version: Docker HUP, https://artifacts.elastic.co/downloads/apm-server/, Central Repository: co/elastic/apm/elastic-apm-agent

Fresh install or upgraded from other version? Fresh

Is there anything special in your setup?

  • APM server runs inside a Podman container.
  • Java Agent runs with Weblogic server.

Description of the problem including expected versus actual behavior. Please include screenshots (if relevant):

Steps to reproduce:

  1. APM Server
    $ podman ps |grep apm_admin_svc
    2ca29d378e39  docker.elastic.co/apm/apm-server:7.17.5                            -environment cont...  4 hours ago  Up 3 hours ago  xx.yy.xx.yy:10000->10000/tcp              apm_admin_svc

    apm-server.yml (mounted inside container)
      apm-server:
        host: "0.0.0.0:10000"
        kibana:
          enabled: true
          host: "http://xx.yy.xx.yy:10006"
      queue:
        mem:
          events: 25600
      output.elasticsearch:
        hosts: ['http://arch-vm1:10002', 'http://arch-vm2:10002']
        worker: 5
      bulk_max_size: 5120
  1. APM Java Agent
    Start script contains the following:
    ########################
    # ELASTIC_APM setup
    export ELASTIC_APM_SERVER_URLS="http://xx.xx.xx:10000"
    #ELASTIC_APM_SECRET_TOKEN=
    export ELASTIC_APM_APPLICATION_PACKAGES="com.xxx"
    export ELASTIC_APM_SERVICE_NAME="${USER}-$(basename ${DOMAIN_HOME})"
    export ELASTIC_APM_ENVIRONMENT="${HOSTNAME}-${USER}-$(basename ${DOMAIN_HOME})"
    export ELASTIC_APM_SERVICE_NODE_NAME="${HOSTNAME}-${USER}-$(basename ${DOMAIN_HOME})"
    #export ELASTIC_APM_LOG_LEVEL="DEBUG"
    export JAVA_OPTIONS="${JAVA_OPTIONS} -javaagent:${DOMAIN_HOME}/elastic-apm-agent/elastic-apm-agent-1.28.4.jar"
    ########################

Provide logs and/or server output (if relevant):

2022-07-11 17:25:38,588 [elastic-apm-remote-config-poller] WARN  org.stagemonitor.util.IOUtils - Read time out after 5000 millis
java.net.SocketTimeoutException: Read time out after 5000 millis
        at weblogic.socket.NIOInputStream.readInternal(NIOInputStream.java:177) ~[?:?]
        at weblogic.socket.NIOInputStream.read(NIOInputStream.java:110) ~[?:?]
        at weblogic.socket.NIOInputStream.read(NIOInputStream.java:73) ~[?:?]
        at java.io.BufferedInputStream.fill(BufferedInputStream.java:246) ~[?:1.8.0_271]
        at java.io.BufferedInputStream.read(BufferedInputStream.java:265) ~[?:1.8.0_271]
        at weblogic.net.http.KeepAliveStream.read(KeepAliveStream.java:73) ~[?:?]
        at org.stagemonitor.util.IOUtils.consumeAndClose(IOUtils.java:66) [elastic-apm-agent-1.33.0.jar:1.33.0]
        at co.elastic.apm.agent.report.HttpUtils.consumeAndClose(HttpUtils.java:62) [elastic-apm-agent-1.33.0.jar:1.33.0]
        at co.elastic.apm.agent.report.ApmServerClient.execute(ApmServerClient.java:261) [elastic-apm-agent-1.33.0.jar:1.33.0]
        at co.elastic.apm.agent.configuration.ApmServerConfigurationSource.fetchConfig(ApmServerConfigurationSource.java:155) [elastic-apm-agent-1.33.0.jar:1.33.0]
        at co.elastic.apm.agent.configuration.ApmServerConfigurationSource.pollConfig(ApmServerConfigurationSource.java:122) [elastic-apm-agent-1.33.0.jar:1.33.0]
        at co.elastic.apm.agent.configuration.ApmServerConfigurationSource.access$000(ApmServerConfigurationSource.java:46) [elastic-apm-agent-1.33.0.jar:1.33.0]
        at co.elastic.apm.agent.configuration.ApmServerConfigurationSource$1.run(ApmServerConfigurationSource.java:108) [elastic-apm-agent-1.33.0.jar:1.33.0]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_271]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_271]
        at java.lang.Thread.run(Thread.java:748) [?:1.8.0_271]
2022-07-11 17:26:13,622 [elastic-apm-remote-config-poller] INFO  co.elastic.apm.agent.configuration.ApmServerConfigurationSource - Received new configuration from APM Server: {transaction_max_spans=100}
2022-07-11 17:26:48,663 [elastic-apm-remote-config-poller] WARN  org.stagemonitor.util.IOUtils - Read time out after 5000 millis
java.net.SocketTimeoutException: Read time out after 5000 millis
        at weblogic.socket.NIOInputStream.readInternal(NIOInputStream.java:177) ~[?:?]
        at weblogic.socket.NIOInputStream.read(NIOInputStream.java:110) ~[?:?]
        at weblogic.socket.NIOInputStream.read(NIOInputStream.java:73) ~[?:?]
        at java.io.BufferedInputStream.fill(BufferedInputStream.java:246) ~[?:1.8.0_271]
        at java.io.BufferedInputStream.read(BufferedInputStream.java:265) ~[?:1.8.0_271]
        at weblogic.net.http.KeepAliveStream.read(KeepAliveStream.java:73) ~[?:?]
        at org.stagemonitor.util.IOUtils.consumeAndClose(IOUtils.java:66) [elastic-apm-agent-1.33.0.jar:1.33.0]
        at co.elastic.apm.agent.report.HttpUtils.consumeAndClose(HttpUtils.java:62) [elastic-apm-agent-1.33.0.jar:1.33.0]
        at co.elastic.apm.agent.report.ApmServerClient.execute(ApmServerClient.java:261) [elastic-apm-agent-1.33.0.jar:1.33.0]
        at co.elastic.apm.agent.configuration.ApmServerConfigurationSource.fetchConfig(ApmServerConfigurationSource.java:155) [elastic-apm-agent-1.33.0.jar:1.33.0]
        at co.elastic.apm.agent.configuration.ApmServerConfigurationSource.pollConfig(ApmServerConfigurationSource.java:122) [elastic-apm-agent-1.33.0.jar:1.33.0]
        at co.elastic.apm.agent.configuration.ApmServerConfigurationSource.access$000(ApmServerConfigurationSource.java:46) [elastic-apm-agent-1.33.0.jar:1.33.0]
        at co.elastic.apm.agent.configuration.ApmServerConfigurationSource$1.run(ApmServerConfigurationSource.java:108) [elastic-apm-agent-1.33.0.jar:1.33.0]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_271]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_271]
        at java.lang.Thread.run(Thread.java:748) [?:1.8.0_271]
2

Is it repeatedly emitting the new configuration line?

3

I worked through the codebase and that exception is ignorable. You can turn it off by setting org.stagemonitor.util.IOUtils to not log using your log configuration. That class is logging it, but the Elastic class calling it is deliberately ignoring it and doesn't want it logged - just can't control the stagemonitor logging.

The functionality is just ensuring nothing is left unconsumed in the stream, so is reading until timeout - and low traffic means it hits that regularly, but it's not a functionally useful exception, so best to just suppress reporting it

4

No, the line "Received new configuration" occurred only one time. The SocketTimeoutException occurred every 5 seconds.

5

Thanks for this hins. First I could move the APM log messages from general console.log to a separate log file with parameter config-log-file. Now I need to finger out how to remove org.stagemonitor.util.IOUtils from log files in my application logging configuration.

6

I assume, there is no separate APM Agent config to hide the org.stagemonitor.util.IOUtils messages in log files.

7

No, it's in the stagemonitor code itself that logs this warning

8

This topic was automatically closed 20 days after the last reply. New replies are no longer allowed.