APM agent/server connection breaks when using TLS (version 7.6.0)

[corilusserviceuser]

Describe the bug
After updating the apm-server to version 7.6.0 from 7.5.2 all communication between the APM-agents & APM-server fails due to TLS issues.

The agent keeps logging the following error:
2020-03-09 14:00:19.066 [elastic-apm-server-reporter] ERROR co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Failed to handle event of type TRANSACTION with this error: extension (5) should not be presented in certificate_request

To Reproduce
Steps to reproduce the behavior:

1. Use this config
   APM Server:
   'apm-server:
   host: "0.0.0.0:8200"

elasticsearch:
hosts: [ "<es_host>:9200", ]

ssl:
enabled: true
certificate : "/etc/apm-server/certs/apm.crt"
key : "/etc/apm-server/certs/apm.key"

queue:
mem:
events: 66560
flush.min_events: 2048
flush.timeout: 1s

max_procs: 2

setup.template.settings:
index:
number_of_shards: 1
number_of_replicas: 0
codec: best_compression

output.elasticsearch:
hosts: [ "https://<es_host>:9200", ]
ssl:
certificate_authorities: [ "/etc/apm-server/certs/intermediate_ca.crt" ]
certificate: "/etc/apm-server/certs/apm.crt"
key: "/etc/apm-server/certs/apm.key"
username: "apm_server"
compression_level: 6

indices:
- index: "apm-%{[observer.version]}-sourcemap"
when.contains:
processor.event: "sourcemap"

- index: "apm-%{[observer.version]}-error-%{+yyyy.MM.dd}"
  when.contains:
    processor.event: "error"

- index: "apm-%{[observer.version]}-transaction-%{+yyyy.MM.dd}"
  when.contains:
    processor.event: "transaction"

- index: "apm-%{[observer.version]}-span-%{+yyyy.MM.dd}"
  when.contains:
    processor.event: "span"

- index: "apm-%{[observer.version]}-metric-%{+yyyy.MM.dd}"
  when.contains:
    processor.event: "metric"

- index: "apm-%{[observer.version]}-onboarding-%{+yyyy.MM.dd}"
  when.contains:
    processor.event: "onboarding"

logging.to_files: true
logging.files:
path: /var/log/apm-server
name: apm-server
keepfiles: 50
permissions: 0640

xpack.security.enabled: true
xpack.monitoring.enabled: true
xpack.monitoring.elasticsearch:
username: "apm_system"
password: "<apm_system_pw>"
xpack.monitoring.elasticsearch.ssl.certificate_authority: /etc/apm-server/certs/intermediate.crt'

APM Agent:
Environment variables in Docker container:

• "ELASTIC_APM_ENVIRONMENT=qa"
• "ELASTIC_APM_SERVER_URLS=https://<apm_host>:8200",
• "ELASTIC_APM_VERIFY_SERVER_CERT=false"

2. Update the apm-server from 7.5.2 to 7.6.0
3. Then restart apm-server
4. Look at the docker error logs to see APM Agent logging the errors

Expected behavior
Expected behaviour is that in minor updates no changes in configuration should happen and that everything keeps working as before. This is probably due to a TLS library that apm-agent/server uses.

Debug logs

These are logs when the apm-server was on version 7.6.0. Around 14:07 I downgraded the apm-server from version 7.6.0 to 7.5.2 and everything started working again as can be seen in the logs.

2020-03-09 14:01:12.302 [apm-reporter] INFO co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Backing off for 36 seconds (+/-10%)
2020-03-09 14:01:46.969 [apm-remote-config-poller] ERROR co.elastic.apm.agent.report.HttpUtils - Exception when closing input stream of HttpURLConnection.
2020-03-09 14:01:46.969 [apm-remote-config-poller] ERROR co.elastic.apm.agent.configuration.ApmServerConfigurationSource - extension (5) should not be presented in certificate_request
2020-03-09 14:01:47.902 [apm-reporter] ERROR co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Failed to handle event of type SPAN with this error: extension (5) should not be presented in certificate_request
2020-03-09 14:01:47.902 [apm-reporter] INFO co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Backing off for 36 seconds (+/-10%)
2020-03-09 14:02:23.843 [apm-reporter] ERROR co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Failed to handle event of type TRANSACTION with this error: extension (5) should not be presented in certificate_request
2020-03-09 14:02:23.844 [apm-reporter] INFO co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Backing off for 36 seconds (+/-10%)
2020-03-09 14:02:59.845 [apm-reporter] ERROR co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Failed to handle event of type TRANSACTION with this error: extension (5) should not be presented in certificate_request
2020-03-09 14:02:59.845 [apm-reporter] INFO co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Backing off for 36 seconds (+/-10%)
2020-03-09 14:03:36.010 [apm-reporter] ERROR co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Failed to handle event of type TRANSACTION with this error: extension (5) should not be presented in certificate_request
2020-03-09 14:03:36.010 [apm-reporter] INFO co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Backing off for 36 seconds (+/-10%)
2020-03-09 14:04:10.534 [apm-reporter] ERROR co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Failed to handle event of type TRANSACTION with this error: extension (5) should not be presented in certificate_request
2020-03-09 14:04:10.535 [apm-reporter] INFO co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Backing off for 36 seconds (+/-10%)
2020-03-09 14:07:22.671 [apm-reporter] INFO co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Backing off for 0 seconds (+/-10%)
2020-03-09 14:07:22.671 [apm-reporter] ERROR co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Error sending data to APM server: Server returned HTTP response code: 503 for URL: https://10.4.0.38:8200/intake/v2/events, response code is 503
2020-03-09 14:07:22.671 [apm-reporter] WARN co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - {
  "accepted": 0,
  "errors": [
    {
      "message": "queue is full"
    }
  ]
}

2020-03-09 14:07:37.704 [apm-reporter] INFO co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Backing off for 1 seconds (+/-10%)
2020-03-09 14:07:38.680 [apm-reporter] ERROR co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Error sending data to APM server: Server returned HTTP response code: 503 for URL: https://10.4.0.38:8200/intake/v2/events, response code is 503
2020-03-09 14:07:38.680 [apm-reporter] WARN co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - {
  "accepted": 0,
  "errors": [
    {
      "message": "queue is full"
    }
  ]
}

2020-03-09 14:07:52.699 [apm-reporter] INFO co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Backing off for 4 seconds (+/-10%)
2020-03-09 14:07:56.609 [apm-reporter] ERROR co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Error sending data to APM server: Server returned HTTP response code: 503 for URL: https://10.4.0.38:8200/intake/v2/events, response code is 503
2020-03-09 14:07:56.609 [apm-reporter] WARN co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - {
  "accepted": 0,
  "errors": [
    {
      "message": "queue is full"
    }
  ]
}

2020-03-09 14:08:07.704 [apm-reporter] INFO co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Backing off for 9 seconds (+/-10%)
2020-03-09 14:08:17.090 [apm-reporter] ERROR co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Error sending data to APM server: Server returned HTTP response code: 503 for URL: https://10.4.0.38:8200/intake/v2/events, response code is 503
2020-03-09 14:08:17.090 [apm-reporter] WARN co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - {
  "accepted": 0,
  "errors": [
    {
      "message": "queue is full"
    }
  ]
}

2020-03-09 14:08:28.121 [apm-reporter] INFO co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Backing off for 16 seconds (+/-10%)
2020-03-09 14:08:44.674 [apm-reporter] ERROR co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Error sending data to APM server: Server returned HTTP response code: 503 for URL: https://10.4.0.38:8200/intake/v2/events, response code is 503
2020-03-09 14:08:44.674 [apm-reporter] WARN co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - {
  "accepted": 0,
  "errors": [
    {
      "message": "queue is full"
    }
  ]
}

2020-03-09 14:08:55.709 [apm-reporter] INFO co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Backing off for 25 seconds (+/-10%)
2020-03-09 14:09:18.887 [apm-reporter] ERROR co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Error sending data to APM server: Server returned HTTP response code: 503 for URL: https://10.4.0.38:8200/intake/v2/events, response code is 503
2020-03-09 14:09:18.887 [apm-reporter] WARN co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - {
  "accepted": 0,
  "errors": [
    {
      "message": "queue is full"
    }
  ]
}

2020-03-09 14:09:29.920 [apm-reporter] INFO co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Backing off for 36 seconds (+/-10%)
2020-03-09 14:10:07.918 [apm-reporter] ERROR co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Error sending data to APM server: Server returned HTTP response code: 503 for URL: https://10.4.0.38:8200/intake/v2/events, response code is 503
2020-03-09 14:10:07.919 [apm-reporter] WARN co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - {
  "accepted": 0,
  "errors": [
    {
      "message": "queue is full"
    }
  ]
}

[corilusserviceuser]

For some reason the apm-server configuration formatting fails, not sure why, sorry for this.

[graphaelli]

This looks a lot like golang/go#35722. 7.5.2 was built with go 1.12.12, 7.6.0 with 1.13.8 so that fits. Attempting to reproduce locally to verify.

[axw]

@corilusserviceuser this appears to be is an issue with OpenJDK, which is only now showing up because of a change in APM Server 7.6.0. It has been fixed in the JDK (https://bugs.openjdk.java.net/browse/JDK-8236039), but

We might want to have the Java agent set the maximum protocol to TLSv1.2 for older JVMs to work around this. Paging @felixbarny.

There are a couple of options to working around this in the mean time:

• set apm-server.ssl.supported_protocols: [TLSv1.1, TLSv1.2] in apm-server.yml
• pass -Djdk.tls.client.protocols=TLSv1.2 to your Java app(s)

[graphaelli]

Confirmed the issue with:

openjdk version "13.0.2" 2020-01-14
OpenJDK Runtime Environment (build 13.0.2+8)

and that both options @axw presented work around it.

I also confirmed that 7.6.1 built with go1.12.12 (after removing the lone errors.As) does not exhibit this behavior. Closing this out as we want to support TLS v1.3, don't intend to downgrade go back to 1.12, and the fix is already set for the next jdk. We can continue discussion of making this easier for java agent users in elastic/apm-agent-java#1080.

[graphaelli]

https://gist.github.com/graphaelli/4d5e517e5e08e9ecc96857aaff87729c documents a method for reproduction