APM An internal server error occurred

[Sirius (Jorge Alfredo Sánchez Lamas)]

Hello,

Can please advise on below error between APM and java agent ...

Kibana version :7.3.2
Elasticsearch version :7.3.2
APM Server version : 7.4
APM Agent language and version : elastic-apm-agent-1.10.0.jar

I am running java agent like:

java -javaagent:/export/home/gdlsajor/apm/elastic-apm-agent-1.10.0.jar
-Delastic.apm.service_name=test
-Delastic.apm.server_urls=http://10...***:8200/
-Delastic.apm.application_packages=ca.com.elastic

Output:

2019-10-28 10:29:06.657 [main] INFO co.elastic.apm.agent.configuration.StartupInfo - Starting Elastic APM 1.10.0 as test on Java 1.8.0_222 (Oracle Corporation) Linux 3.10.0-1062.1.2.el7.x86_64
2019-10-28 10:29:06.792 [apm-server-healthcheck] INFO co.elastic.apm.agent.report.ApmServerHealthChecker - Elastic APM server is available: { "build_date": "2019-09-27T06:58:27Z", "build_sha": "971d864356e4438bf4a799a1fa052cfd0ce680b4", "version": "7.4.0"}
2019-10-28 10:29:06.857 [apm-remote-config-poller] ERROR co.elastic.apm.agent.configuration.ApmServerConfigurationSource - Remote configuration is not available. Check the connection between APM Server and Kibana.
Usage: java [-options] class [args...]

From APM I am getting:

2019-10-28T10:29:06.851-0700 ERROR [request] middleware/log_middleware.go:74 service unavailable {"request_id": "db423b5a-d6f5-48b6-b855-828ee9f54f71", "method": "POST", "URL": "/config/v1/agents", "content_length": 419, "remote_address": "10.10.177.166", "user-agent": "elasticapm-java/1.10.0", "response_code": 503, "error": "{"statusCode":500,"error":"Internal Server Error","message":"An internal server error occurred"}"}

This is my apm-server.yml configuration, user for Kibana logging has full access 'super user' role:

Summary

################### APM Server Configuration #########################
apm-server:
host: "10...***:8200"

rum:
enabled: true
event_rate:
limit: 300
lru_size: 1000

kibana:
enabled: true
host: "kb******.com:5601"
protocol: "https"
username: "user"
password: "password"
ssl.enabled: true
ssl.certificate_authorities: ["../ca.crt"]
ssl.certificate: "../ce.crt"
ssl.key: "../sslkey.key"

#-- General RUM settings
allow_origins : ['']
library_pattern: "node_modules|bower_components|~"
exclude_from_grouping: "^/webpack"
source_mapping:
elasticsearch:
cache:
expiration: 5m
index_pattern: "apm--sourcemap*"
#-------------------------- Elasticsearch output ------------------------------
output.elasticsearch:
hosts: ["es******.com:9200"]
enabled: true
protocol: "https"
username: "myuser"
password: "mypasswd"
ssl.enabled: true
ssl.certificate_authorities: ["../ca.crt"]
ssl.certificate: "../cert.crt"
ssl.key: "../eskey.key"
#============================== X-pack Monitoring ===============================
monitoring.enabled: true

Regards,
Jorge

[jalvz (Juan Alvarez)]

Hello there,

Can you please check the first 100 lines or so of the apm-server log?
It should tell you if it could establish a connection with Kibana or not, either something like "successfully obtained connection to Kibana" or "failed to obtain connection to Kibana".
If it was successful: does the error keep happening? can you check Kibana logs at that same timestamp?

If not, either Kibana is not reachable from your apm server machine or something is off with the configuration (or we have a bug!). Can you rule out connectivity/config issue with curl or some other way?
With curl I think it should be something like this, but double-check the syntax and that files are in the right format:

curl -v --cert ../ce.cert --cacert ../ca.crt --key ../sslkey.key -u user:passwd "https//kb******.com:5601"

Hope that helps!

[Sirius (Jorge Alfredo Sánchez Lamas)]

Hello,

I think no issues with connectivity config, here my curl output :

I get a successfully Kibana connection message at the moment to startup APM server, below the output:

Summary

INFO instance/beat.go:607 Home path: [/es1/app/elkstack/apm/apm-server-7.4.0-linux-x86_64] Config path: [/es1/app/elkstack/apm/apm-server-7.4.0-linux-x86_64] Data path: [/es1/app/elkstack/apm/apm-server-7.4.0-linux-x86_64/data] Logs path: [/es1/app/elkstack/apm/apm-server-7.4.0-linux-x86_64/logs]
INFO instance/beat.go:615 Beat ID: b2d29c67-d212-420c-9ee2-bb74ad1be7b5
INFO [seccomp] seccomp/seccomp.go:124 Syscall filter successfully installed
INFO [beat] instance/beat.go:903 Beat info {"system_info": {"beat": {"path": {"config": "/es1/app/elkstack/apm/apm-server-7.4.0-linux-x86_64", "data": "/es1/app/elkstack/apm/apm-server-7.4.0-linux-x86_64/data", "home": "/es1/app/elkstack/apm/apm-server-7.4.0-linux-x86_64", "logs": "/es1/app/elkstack/apm/apm-server-7.4.0-linux-x86_64/logs"}, "type": "apm-server", "uuid": "b2d29c67-d212-420c-9ee2-bb74ad1be7b5"}}}
INFO [beat] instance/beat.go:912 Build info {"system_info": {"build": {"commit": "971d864356e4438bf4a799a1fa052cfd0ce680b4", "libbeat": "7.4.0", "time": "2019-09-27T06:58:27.000Z", "version": "7.4.0"}}}
INFO [beat] instance/beat.go:915 Go runtime info {"system_info": {"go": {"os":"linux","arch":"amd64","max_procs":4,"version":"go1.12.9"}}}
INFO [beat] instance/beat.go:919 Host info {"system_info": {"host": {"architecture":"x86_64","boot_time":"2019-10-24T06:11:23-07:00","containerized":false,"name":"sacvl****","ip":["127...1/8","::1/128","10.10.41.237/22","fe80::7997:b56e:803:d8e1/64","10.9.9.175/16","fe80::5054:ff:fe51:a27f/64","172.18.0.1/16","fe80::42:adff:fea3:8160/64","172.17.0.1/16","fe80::42:6eff:fe85:ca41/64","fe80::7005:ffff:fe2e:53e4/64","fe80::247a:c5ff:fe1e:803f/64","fe80::8c59:64ff:fecd:763b/64","fe80::c8a:afff:fefb:18b6/64"],"kernel_version":"3.10.0-957.27.2.el7.x86_64","mac":["52:54:00:82:8f:c1","52:54:00:51:a2:7f","02:42:ad:a3:81:60","02:42:6e:85:ca:41","72:05:ff:2e:53:e4","26:7a:c5:1e:80:3f","8e:59:64:cd:76:3b","0e:8a:af:fb:18:b6"],"os":{"family":"redhat","platform":"centos","name":"CentOS Linux","version":"7 (Core)","major":7,"minor":6,"patch":1810,"codename":"Core"},"timezone":"PDT","timezone_offset_sec":-25200,"id":"4c7598854cfa40ddac9551cf56f67ba9"}}}
INFO [beat] instance/beat.go:948 Process info {"system_info": {"process": {"capabilities": {"inheritable":null,"permitted":["chown","dac_override","dac_read_search","fowner","fsetid","kill","setgid","setuid","setpcap","linux_immutable","net_bind_service","net_broadcast","net_admin","net_raw","ipc_lock","ipc_owner","sys_module","sys_rawio","sys_chroot","sys_ptrace","sys_pacct","sys_admin","sys_boot","sys_nice","sys_resource","sys_time","sys_tty_config","mknod","lease","audit_write","audit_control","setfcap","mac_override","mac_admin","syslog","wake_alarm","block_suspend"],"effective":["chown","dac_override","dac_read_search","fowner","fsetid","kill","setgid","setuid","setpcap","linux_immutable","net_bind_service","net_broadcast","net_admin","net_raw","ipc_lock","ipc_owner","sys_module","sys_rawio","sys_chroot","sys_ptrace","sys_pacct","sys_admin","sys_boot","sys_nice","sys_resource","sys_time","sys_tty_config","mknod","lease","audit_write","audit_control","setfcap","mac_override","mac_admin","syslog","wake_alarm","block_suspend"],"bounding":["chown","dac_override","dac_read_search","fowner","fsetid","kill","setgid","setuid","setpcap","linux_immutable","net_bind_service","net_broadcast","net_admin","net_raw","ipc_lock","ipc_owner","sys_module","sys_rawio","sys_chroot","sys_ptrace","sys_pacct","sys_admin","sys_boot","sys_nice","sys_resource","sys_time","sys_tty_config","mknod","lease","audit_write","audit_control","setfcap","mac_override","mac_admin","syslog","wake_alarm","block_suspend"],"ambient":null}, "cwd": "/es1/app/elkstack/apm/apm-server-7.4.0-linux-x86_64", "exe": "/es1/app/elkstack/apm/apm-server-7.4.0-linux-x86_64/apm-server", "name": "apm-server", "pid": 11691, "ppid": 11690, "seccomp": {"mode":"filter"}, "start_time": "2019-10-29T14:17:11.880-0700"}}}
INFO instance/beat.go:292 Setup Beat: apm-server; Version: 7.4.0
INFO elasticsearch/client.go:170 Elasticsearch url: https://es1s1..com:9200
INFO [publisher] pipeline/module.go:97 Beat name: sacvl****
INFO [beater] beater/beater.go:102 Falling back to elasticsearch output for sourcemap storage
INFO [beater] beater/beater.go:124 Registering pipeline callback
INFO elasticsearch/client.go:170 Elasticsearch url: https://es1s1..com:9200
INFO instance/beat.go:422 apm-server start running.
INFO [beater] beater/beater.go:259 self instrumentation is disabled
INFO [handler] api/mux.go:91 Path / added to request handler
INFO elasticsearch/client.go:170 Elasticsearch url: https://es1s1..com:9200
INFO [handler] api/mux.go:91 Path /assets/v1/sourcemaps added to request handler
INFO [agentcfg] agentcfg/cache.go:42 Cache creation with default expiration 30s.
INFO [handler] api/mux.go:91 Path /config/v1/agents added to request handler
INFO kibana/client.go:117 Kibana url: https://kb1s1..com:5601
INFO [handler] api/mux.go:91 Path /intake/v2/rum/events added to request handler
INFO [handler] api/mux.go:91 Path /intake/v2/events added to request handler
INFO [beater] beater/server.go:79 Starting apm-server [971d864356e4438bf4a799a1fa052cfd0ce680b4 built 2019-09-27 06:58:27 +0000 UTC]. Hit CTRL-C to stop it.
INFO [beater] beater/server.go:80 Listening on: 10.10.41.237:8200
INFO [beater] beater/server.go:83 RUM endpoints enabled!
WARN [beater] beater/server.go:86 CORS related setting apm-server.rum.allow_origins allows all origins. Consider more restrictive setting for production use.
INFO [beater] beater/server.go:106 SSL disabled.
INFO [request] middleware/log_middleware.go:76 request ok {"request_id": "59348144-9063-4d39-bef6-95c81d5ce2ed", "method": "GET", "URL": "/", "content_length": 0, "remote_address": "10.10.41.237", "user-agent": "", "response_code": 200}
INFO [onboarding] beater/onboarding.go:32 Publishing onboarding document
INFO [kibana] kibana/connecting_client.go:80 Successfully obtained connection to Kibana.
INFO elasticsearch/client.go:743 Attempting to connect to Elasticsearch version 7.3.2

So, the issue occurs when java agent is launched, just in case I did this oher test by setting "ssl.verification_mode: none" but no luck, issue persist..,, should be a bug ?

Thanks & Regards,
Jorge

[jalvz (Juan Alvarez)]

Hi,

Thanks for digging and ruling that out. Lets go back to the original error, then:

@Sirius

2019-10-28T10:29:06.851-0700 ERROR [request] middleware/log_middleware.go:74 service unavailable {"request_id": "db423b5a-d6f5-48b6-b855-828ee9f54f71", "method": "POST", "URL": "/config/v1/agents", "content_length": 419, "remote_address": "10.10.177.166", "user-agent": "elasticapm-java/1.10.0", "response_code": 503, "error": "{"statusCode":500,"error":"Internal Server Error","message":"An internal server error occurred"}"}

The 503 error you see there comes from apm-server, and that is originated from the 500 ("An internal server error occurred"), that comes from Kibana.
So we need the corresponding Kibana logs at that timestamp to see what happened.

One possible cause is that Kibana takes longer to start up than apm-server, so if you deploy them about the same time, it could happen that apm-server fires a request to Kibana and Kibana is not ready to respond yet.
So it is also important to know : do you see that error just one or a couple of times? Or can you reproduce consistently?

[Sirius (Jorge Alfredo Sánchez Lamas)]

Hello Juan,

Regarding to the question, I am able to reproduce the issue many times, this is the first time configuring APM server so I've not been able to run a succesfull test, I am stuck here.

"One possible cause is that Kibana takes longer to start up than apm-server, so if you deploy them about the same time" ... Kibana is deployed and running fine since weeks ago, I would rule out this possibility.

Here's my Kibana output when APM server is starting :

Summary

{"type":"response","@timestamp":"2019-10-31T00:15:15Z","tags":["api"],"pid":7,"method":"get","statusCode":200,"req":{"url":"/api/status","method":"get","headers":{"host":"kb1s1..com:5601","user-agent":"Go-http-client/1.1","accept":"application/json","content-type":"application/json","kbn-xsrf":"1","accept-encoding":"gzip"},"remoteAddress":"10...","userAgent":"10...**"},"res":{"statusCode":200,"responseTime":161,"contentLength":9},"message":"GET /api/status 200 161ms - 9.0B"}

Running the java agent, I am getting this output from Kibana:

Summary

{"type":"error","@timestamp":"2019-10-31T00:16:45Z","tags":,"pid":7,"level":"error","error":{"message":"Authorization Exception","name":"Error","stack":"Authorization Exception :: {"path":"/.apm-agent-configuration","query":{},"statusCode":403,"response":""}\n at respond (/usr/share/kibana/node_modules/elasticsearch/src/lib/transport.js:315:15)\n at checkRespForFailure (/usr/share/kibana/node_modules/elasticsearch/src/lib/transport.js:274:7)\n at HttpConnector. (/usr/share/kibana/node_modules/elasticsearch/src/lib/connectors/http.js:166:7)\n at IncomingMessage.wrapper (/usr/share/kibana/node_modules/elasticsearch/node_modules/lodash/lodash.js:4929:19)\n at IncomingMessage.emit (events.js:194:15)\n at endReadableNT (_stream_readable.js:1103:12)\n at process._tickCallback (internal/process/next_tick.js:63:19)"},"url":{"protocol":null,"slashes":null,"auth":null,"host":null,"port":null,"hostname":null,"hash":null,"search":null,"query":{},"pathname":"/api/apm/settings/agent-configuration/search","path":"/api/apm/settings/agent-configuration/search","href":"/api/apm/settings/agent-configuration/search"},"message":"Authorization Exception"}
{"type":"response","@timestamp":"2019-10-31T00:16:45Z","tags":["access:apm"],"pid":7,"method":"post","statusCode":500,"req":{"url":"/api/apm/settings/agent-configuration/search","method":"post","headers":{"host":"kb1s1..com:5601","user-agent":"Go-http-client/1.1","content-length":"27","accept":"application/json","content-type":"application/json","kbn-version":"7.3.2","kbn-xsrf":"1","accept-encoding":"gzip"},"remoteAddress":"10...","userAgent":"10...**"},"res":{"statusCode":500,"responseTime":79,"contentLength":9},"message":"POST /api/apm/settings/agent-configuration/search 500 79ms - 9.0B"}

Any advise/observation please ?

Thanks & Regards,
Jorge

[jalvz (Juan Alvarez)]

Hello, that Kibana log helps.
Agent configuration settings are written to an special index named .apm-agent-configuration. It seems that Kibana doesn't have access to that index.
To confirm that: go to Kibana dev tools and make a GET .apm-agent-configuration/_search. I expect it to fail, but it should not.

If you go to the Security Settings in Kibana maybe you can find further insights about why.

[Sirius (Jorge Alfredo Sánchez Lamas)]

Hi Juan, but going to Security Settings I think there are not much to explore, I just see only for user and roles administration, should I expected to see other features ? (my Kibana is free version) .

Ok, then the users configured in APM to connect with ES and Kibana have "superuser" role, asper me it means to have all privileges. I do not what else could I check in secuity, any idea ?

You're right GET .apm-agent-configuration/_search fails because index expected doesn't exist. I created it manually PUT .apm-agent-configuration and ran again APM server and Java agent but not any difference encountered, same issue

Thanks & Regards,
Jorge

[jalvz (Juan Alvarez)]

Hi,

I asked for help to my colleagues working on Kibana, and it seems you are hitting this issue: https://github.com/elastic/kibana/issues/45610

I am sorry for that - it has been fixed in 7.4, so you would need to upgrade your Kibana and Elasticsearch. Be sure to DELETE the .apm-agent-configuration index before upgrading so that Kibana can create it properly.

Sorry again for the inconvenience!

[Sirius (Jorge Alfredo Sánchez Lamas)]

Thanks so mucho for you support Juan, upgrading Elastic, Kibana and APM to 7.4 works fine now !!