[SUPPORT|kbn_pro] Kibana sometimes get into crash loop with RoR related errors

deimantastumas · October 12, 2023, 1:09pm

Hello, we started noticing that our Kibana sometimes crashes and cannot fully restart as it gets into crash loop:

Oct 12 15:23:31 laaskb002ppvjay kibana[23145]: [ROR] - serve.js - intercepting config
Oct 12 15:23:32 laaskb002ppvjay kibana[23145]: [15:23:32:206] [warning][plugins][ReadonlyREST][unsupportedFeaturesNotifier] logging.verbose config parameter declared in kibana.yml is not supported yet. It will be ignored
Oct 12 15:23:45 laaskb002ppvjay kibana[23145]: Unhandled Promise rejection detected:
Oct 12 15:23:45 laaskb002ppvjay kibana[23145]: Error: LicenseService is not initialised yet: empty ActivationKey
Oct 12 15:23:45 laaskb002ppvjay kibana[23145]: at i.e (/usr/share/kibana/plugins/readonlyrestkbn/proxy/core/license/LicenseService.js:1:4534)
Oct 12 15:23:45 laaskb002ppvjay kibana[23145]: at i.e (/usr/share/kibana/plugins/readonlyrestkbn/proxy/core/license/LicenseService.js:1:6855)
Oct 12 15:23:45 laaskb002ppvjay kibana[23145]: at e (/usr/share/kibana/plugins/readonlyrestkbn/proxy/preKibanaProxy/customMiddleware.js:1:1415)
Oct 12 15:23:45 laaskb002ppvjay kibana[23145]: at tryCatch (/usr/share/kibana/plugins/readonlyrestkbn/node_modules/regenerator-runtime/runtime.js:45:40)
Oct 12 15:23:45 laaskb002ppvjay kibana[23145]: at Generator.invoke [as _invoke] (/usr/share/kibana/plugins/readonlyrestkbn/node_modules/regenerator-runtime/runtime.js:274:22)
Oct 12 15:23:45 laaskb002ppvjay kibana[23145]: at Generator.prototype.<computed> [as next] (/usr/share/kibana/plugins/readonlyrestkbn/node_modules/regenerator-runtime/runtime.js:97:21)
Oct 12 15:23:45 laaskb002ppvjay kibana[23145]: at asyncGeneratorStep (/usr/share/kibana/plugins/readonlyrestkbn/node_modules/@babel/runtime/helpers/asyncToGenerator.js:3:24)
Oct 12 15:23:45 laaskb002ppvjay kibana[23145]: at _next (/usr/share/kibana/plugins/readonlyrestkbn/node_modules/@babel/runtime/helpers/asyncToGenerator.js:25:9)
Oct 12 15:23:45 laaskb002ppvjay kibana[23145]: at /usr/share/kibana/plugins/readonlyrestkbn/node_modules/@babel/runtime/helpers/asyncToGenerator.js:32:7
Oct 12 15:23:45 laaskb002ppvjay kibana[23145]: at new Promise (<anonymous>)
Oct 12 15:23:45 laaskb002ppvjay kibana[23145]: at e.<anonymous> (/usr/share/kibana/plugins/readonlyrestkbn/node_modules/@babel/runtime/helpers/asyncToGenerator.js:21:12)
Oct 12 15:23:45 laaskb002ppvjay kibana[23145]: at e (/usr/share/kibana/plugins/readonlyrestkbn/proxy/preKibanaProxy/customMiddleware.js:1:1821)
Oct 12 15:23:45 laaskb002ppvjay kibana[23145]: at e (/usr/share/kibana/plugins/readonlyrestkbn/proxy/preKibanaProxy/preKibanaProxy.js:1:9183)
Oct 12 15:23:45 laaskb002ppvjay kibana[23145]: at tryCatch (/usr/share/kibana/plugins/readonlyrestkbn/node_modules/regenerator-runtime/runtime.js:45:40)
Oct 12 15:23:45 laaskb002ppvjay kibana[23145]: at Generator.invoke [as _invoke] (/usr/share/kibana/plugins/readonlyrestkbn/node_modules/regenerator-runtime/runtime.js:274:22)
Oct 12 15:23:45 laaskb002ppvjay kibana[23145]: at Generator.prototype.<computed> [as next] (/usr/share/kibana/plugins/readonlyrestkbn/node_modules/regenerator-runtime/runtime.js:97:21)
Oct 12 15:23:45 laaskb002ppvjay kibana[23145]: Terminating process...
Oct 12 15:23:45 laaskb002ppvjay systemd[1]: kibana.service: main process exited, code=exited, status=1/FAILURE
Oct 12 15:23:45 laaskb002ppvjay systemd[1]: Unit kibana.service entered failed state.
Oct 12 15:23:45 laaskb002ppvjay systemd[1]: kibana.service failed.
Oct 12 15:23:48 laaskb002ppvjay systemd[1]: kibana.service holdoff time over, scheduling restart.

We’ve looked into source code and noticed that by changing the default value of activationKey in LicenseService.js, Kibana starts properly:

(0, _defineProperty2.default)(this, "activationKey", {
            'license': {
                'edition': 'kbn_pro',
            }
        });

Note, that after enough restarts the Kibana can finally start and longer crashes.

ROR Version: 1.50.0 (The issue was reproduced with 1.52.0 too)

Kibana Version: 7.17.12

Elasticsearch Version: 7.17.12

Steps to reproduce the issue
We don’t have a good way of reproducing it. It just happens randomly.

{“customer_id”: “a2d8a38b-1070-4845-aa8e-6f38fb585857”, “subscription_id”: “c6f3569d-3d8e-46ce-ac53-92f19301b69e”}

Dzuming · October 12, 2023, 6:41pm

Hi, thanks for the message.
Could you provide your kibana.yml config? Also which method of passing the activation key do you use?

deimantastumas · October 13, 2023, 7:41am

Hey, sure!

kibana.yml:

# File managed by Puppet.
---
elasticsearch.hosts: ...
elasticsearch.password: ...
elasticsearch.pingTimeout: 2000
elasticsearch.requestTimeout: 45000
elasticsearch.shardTimeout: 0
elasticsearch.startupTimeout: 10000
elasticsearch.username: kibana
kibana.defaultAppId: discover
kibana.index: ".kibana"
logging.dest: "/var/log/kibana/kibana.log"
logging.verbose: false
monitoring.enabled: true
readonlyrest_kbn.cookiePass: ...
readonlyrest_kbn.session_timeout_minutes: 10080
readonlyrest_kbn.sessions_probe_interval_seconds: 604800
readonlyrest_kbn.sessions_refresh_after: 1000
readonlyrest_kbn.store_sessions_in_index: true
readonlyrest_kbn.whitelistedPaths: '[".*/api/status$", ".*/_prometheus/metrics$"]'
server.host: laas.d1.adform.zone
server.maxPayloadBytes: 1058576
server.name: laaskb001d1vteo
server.port: 443
server.publicBaseUrl: https://laas.d1.adform.zone
server.ssl.certificate: "/etc/ssl/private/kibana.crt"
server.ssl.enabled: true
server.ssl.key: "/etc/ssl/private/kibana.key"
server.ssl.redirectHttpFromPort: 80
xpack.ml.enabled: false
xpack.reporting.enabled: true
xpack.reporting.encryptionKey: no_encryption_key
xpack.reporting.queue.indexInterval: day
xpack.security.enabled: false
xpack.security.session.idleTimeout: 604800000
xpack.spaces.enabled: true
xpack.watcher.enabled: false

The activation key is already in the appropriate ES index, so RoR automatically picks it up from there. I also tried supplying the activation key via env vars and the explicit file in the plugin, but still sometimes got the LicenseService errors.

Dzuming · October 15, 2023, 6:35am

Hi, thanks for the config. Could you increase log levels via readonlyrest_kbn.logLevel: 'trace' in the kibana.yml, reproduce this issue and send logs? Thank you.

deimantastumas · October 19, 2023, 1:10pm

Oct 19 15:52:21 laaskb001prvjay systemd[1]: Started Kibana.
Oct 19 15:52:24 laaskb001prvjay kibana[18883]: [ROR] - serve.js - intercepting config
Oct 19 15:52:24 laaskb001prvjay kibana[18883]: [15:52:24:943] [debug][plugins][ReadonlyREST][LoggerFactory] Setting log destination to: /var/log/kibana/kibana.log folder
Oct 19 15:52:24 laaskb001prvjay kibana[18883]: [15:52:24:943] [debug][plugins][ReadonlyREST][LoggerFactory] Setting logLevel to: TRACE
Oct 19 15:52:24 laaskb001prvjay kibana[18883]: [15:52:24:944] [trace][plugins][ReadonlyREST][kibanaConfigInterceptor] Found configuration object:
Oct 19 15:52:24 laaskb001prvjay kibana[18883]: {
Oct 19 15:52:24 laaskb001prvjay kibana[18883]: "elasticsearch": {
Oct 19 15:52:24 laaskb001prvjay kibana[18883]: "hosts": "http://laas-elasticsearch-data.service.dk1.discovery.pr.adform.zone:9200",
Oct 19 15:52:24 laaskb001prvjay kibana[18883]: "password": "...",
Oct 19 15:52:24 laaskb001prvjay kibana[18883]: "pingTimeout": 2000,
Oct 19 15:52:24 laaskb001prvjay kibana[18883]: "requestTimeout": 45000,
Oct 19 15:52:24 laaskb001prvjay kibana[18883]: "shardTimeout": 0,
Oct 19 15:52:24 laaskb001prvjay kibana[18883]: "startupTimeout": 10000,
Oct 19 15:52:24 laaskb001prvjay kibana[18883]: "username": "..."
Oct 19 15:52:24 laaskb001prvjay kibana[18883]: },
Oct 19 15:52:24 laaskb001prvjay kibana[18883]: "kibana": {
Oct 19 15:52:24 laaskb001prvjay kibana[18883]: "defaultAppId": "discover",
Oct 19 15:52:24 laaskb001prvjay kibana[18883]: "index": ".kibana"
Oct 19 15:52:24 laaskb001prvjay kibana[18883]: },
Oct 19 15:52:24 laaskb001prvjay kibana[18883]: "logging": {
Oct 19 15:52:24 laaskb001prvjay kibana[18883]: "dest": "/var/log/kibana/kibana.log",
Oct 19 15:52:24 laaskb001prvjay kibana[18883]: "verbose": false
Oct 19 15:52:24 laaskb001prvjay kibana[18883]: },
Oct 19 15:52:24 laaskb001prvjay kibana[18883]: "monitoring": {
Oct 19 15:52:24 laaskb001prvjay kibana[18883]: "enabled": true
Oct 19 15:52:24 laaskb001prvjay kibana[18883]: },
Oct 19 15:52:24 laaskb001prvjay kibana[18883]: "readonlyrest_kbn": {
Oct 19 15:52:24 laaskb001prvjay kibana[18883]: "cookiePass": "...",
Oct 19 15:52:24 laaskb001prvjay kibana[18883]: "session_timeout_minutes": 10080,
Oct 19 15:52:24 laaskb001prvjay kibana[18883]: "sessions_probe_interval_seconds": 604800,
Oct 19 15:52:24 laaskb001prvjay kibana[18883]: "sessions_refresh_after": 1000,
Oct 19 15:52:24 laaskb001prvjay kibana[18883]: "store_sessions_in_index": true,
Oct 19 15:52:24 laaskb001prvjay kibana[18883]: "whitelistedPaths": "[\".*/api/status$\", \".*/_prometheus/metrics$\"]",
Oct 19 15:52:24 laaskb001prvjay kibana[18883]: "logLevel": "trace"
Oct 19 15:52:24 laaskb001prvjay kibana[18883]: },
Oct 19 15:52:25 laaskb001prvjay kibana[18883]: "server": {
Oct 19 15:52:25 laaskb001prvjay kibana[18883]: "host": "laas.pr.adform.zone",
Oct 19 15:52:25 laaskb001prvjay kibana[18883]: "maxPayloadBytes": 1058576,
Oct 19 15:52:25 laaskb001prvjay kibana[18883]: "name": "laaskb001prvjay",
Oct 19 15:52:25 laaskb001prvjay kibana[18883]: "port": 443,
Oct 19 15:52:25 laaskb001prvjay kibana[18883]: "publicBaseUrl": "https://laas.pr.adform.zone",
Oct 19 15:52:25 laaskb001prvjay kibana[18883]: "ssl": {
Oct 19 15:52:25 laaskb001prvjay kibana[18883]: "certificate": "/etc/ssl/private/kibana.crt",
Oct 19 15:52:25 laaskb001prvjay kibana[18883]: "enabled": true,
Oct 19 15:52:25 laaskb001prvjay kibana[18883]: "key": "/etc/ssl/private/kibana.key",
Oct 19 15:52:25 laaskb001prvjay kibana[18883]: "redirectHttpFromPort": 80
Oct 19 15:52:25 laaskb001prvjay kibana[18883]: }
Oct 19 15:52:25 laaskb001prvjay kibana[18883]: },
Oct 19 15:52:25 laaskb001prvjay kibana[18883]: "xpack": {
Oct 19 15:52:25 laaskb001prvjay kibana[18883]: "ml": {
Oct 19 15:52:25 laaskb001prvjay kibana[18883]: "enabled": false
Oct 19 15:52:25 laaskb001prvjay kibana[18883]: },
Oct 19 15:52:25 laaskb001prvjay kibana[18883]: "reporting": {
Oct 19 15:52:25 laaskb001prvjay kibana[18883]: "enabled": true,
Oct 19 15:52:25 laaskb001prvjay kibana[18883]: "encryptionKey": "no_encryption_key",
Oct 19 15:52:25 laaskb001prvjay kibana[18883]: "queue": {
Oct 19 15:52:25 laaskb001prvjay kibana[18883]: "indexInterval": "day"
Oct 19 15:52:25 laaskb001prvjay kibana[18883]: }
Oct 19 15:52:25 laaskb001prvjay kibana[18883]: },
Oct 19 15:52:25 laaskb001prvjay kibana[18883]: "security": {
Oct 19 15:52:25 laaskb001prvjay kibana[18883]: "enabled": false,
Oct 19 15:52:25 laaskb001prvjay kibana[18883]: "session": {
Oct 19 15:52:25 laaskb001prvjay kibana[18883]: "idleTimeout": 604800000
Oct 19 15:52:25 laaskb001prvjay kibana[18883]: }
Oct 19 15:52:25 laaskb001prvjay kibana[18883]: },
Oct 19 15:52:25 laaskb001prvjay kibana[18883]: "spaces": {
Oct 19 15:52:25 laaskb001prvjay kibana[18883]: "enabled": true
Oct 19 15:52:25 laaskb001prvjay kibana[18883]: },
Oct 19 15:52:25 laaskb001prvjay kibana[18883]: "watcher": {
Oct 19 15:52:25 laaskb001prvjay kibana[18883]: "enabled": false
Oct 19 15:52:25 laaskb001prvjay kibana[18883]: }
Oct 19 15:52:25 laaskb001prvjay kibana[18883]: },
Oct 19 15:52:25 laaskb001prvjay kibana[18883]: "plugins": {
Oct 19 15:52:25 laaskb001prvjay kibana[18883]: "paths": []
Oct 19 15:52:25 laaskb001prvjay kibana[18883]: },
Oct 19 15:52:25 laaskb001prvjay kibana[18883]: "pid": {
Oct 19 15:52:25 laaskb001prvjay kibana[18883]: "file": "/run/kibana/kibana.pid"
Oct 19 15:52:25 laaskb001prvjay kibana[18883]: },
Oct 19 15:52:25 laaskb001prvjay kibana[18883]: "deprecation": {
Oct 19 15:52:25 laaskb001prvjay kibana[18883]: "skip_deprecated_settings": [
Oct 19 15:52:25 laaskb001prvjay kibana[18883]: "logging.dest"
Oct 19 15:52:25 laaskb001prvjay kibana[18883]: ]
Oct 19 15:52:25 laaskb001prvjay kibana[18883]: }
Oct 19 15:52:25 laaskb001prvjay kibana[18883]: }
Oct 19 15:52:25 laaskb001prvjay kibana[18883]: [15:52:24:944] [warning][plugins][ReadonlyREST][unsupportedFeaturesNotifier] logging.verbose config parameter declared in kibana.yml is not supported yet. It will be ignored
Oct 19 15:52:25 laaskb001prvjay kibana[18883]: [15:52:24:948] [debug][plugins][ReadonlyREST][kibanaConfigInterceptor] Overriding 'server.ssl.enabled' from true to false
Oct 19 15:52:25 laaskb001prvjay kibana[18883]: [15:52:24:949] [debug][plugins][ReadonlyREST][kibanaConfigInterceptor] Overriding 'xpack.reporting.index' from undefined to .reporting-5pz8oo2vkpd
Oct 19 15:52:25 laaskb001prvjay kibana[18883]: [15:52:24:949] [debug][plugins][ReadonlyREST][kibanaConfigInterceptor] Overriding 'server.port' from 443 to 51448
Oct 19 15:52:25 laaskb001prvjay kibana[18883]: [15:52:24:949] [debug][plugins][ReadonlyREST][kibanaConfigInterceptor] Overriding 'server.host' from laas.pr.adform.zone to 127.0.0.1
Oct 19 15:52:25 laaskb001prvjay kibana[18883]: [15:52:24:950] [debug][plugins][ReadonlyREST][kibanaConfigInterceptor] Overriding 'telemetry.enabled' from undefined to false
Oct 19 15:52:25 laaskb001prvjay kibana[18883]: [15:52:24:950] [debug][plugins][ReadonlyREST][kibanaConfigInterceptor] Overriding 'elasticsearch.hosts' from http://laas-elasticsearch-data.service.dk1.discovery.pr.adform.zone:9200 to [http://localhost:57652]
Oct 19 15:52:25 laaskb001prvjay kibana[18883]: [15:52:24:950] [debug][plugins][ReadonlyREST][kibanaConfigInterceptor] Overriding 'elasticsearch.requestHeadersWhitelist' from undefined to ["authorization","cookie","x-ror-current-group"]
Oct 19 15:52:25 laaskb001prvjay kibana[18883]: [15:52:25:039] [debug][plugins][ReadonlyREST][LicenseService] Trying to get cluster UUID
Oct 19 15:52:36 laaskb001prvjay kibana[18883]: [15:52:36:345] [debug][plugins][ReadonlyREST][LicenseService] Polling for new activation key in index...
Oct 19 15:52:36 laaskb001prvjay kibana[18883]: [15:52:36:348] [debug][plugins][ReadonlyREST][LicenseService] Trying to get cluster UUID
Oct 19 15:52:36 laaskb001prvjay kibana[18883]: Unhandled Promise rejection detected:
Oct 19 15:52:36 laaskb001prvjay kibana[18883]: Error: LicenseService is not initialised yet: empty ActivationKey
Oct 19 15:52:36 laaskb001prvjay kibana[18883]: at i.e (/usr/share/kibana/plugins/readonlyrestkbn/proxy/core/license/LicenseService.js:1:4534)
Oct 19 15:52:36 laaskb001prvjay kibana[18883]: at i.e (/usr/share/kibana/plugins/readonlyrestkbn/proxy/core/license/LicenseService.js:1:6855)
Oct 19 15:52:36 laaskb001prvjay kibana[18883]: at e (/usr/share/kibana/plugins/readonlyrestkbn/proxy/preKibanaProxy/customMiddleware.js:1:1415)
Oct 19 15:52:36 laaskb001prvjay kibana[18883]: at tryCatch (/usr/share/kibana/plugins/readonlyrestkbn/node_modules/regenerator-runtime/runtime.js:45:40)
Oct 19 15:52:36 laaskb001prvjay kibana[18883]: at Generator.invoke [as _invoke] (/usr/share/kibana/plugins/readonlyrestkbn/node_modules/regenerator-runtime/runtime.js:274:22)
Oct 19 15:52:36 laaskb001prvjay kibana[18883]: at Generator.prototype.<computed> [as next] (/usr/share/kibana/plugins/readonlyrestkbn/node_modules/regenerator-runtime/runtime.js:97:21)
Oct 19 15:52:36 laaskb001prvjay kibana[18883]: at asyncGeneratorStep (/usr/share/kibana/plugins/readonlyrestkbn/node_modules/@babel/runtime/helpers/asyncToGenerator.js:3:24)
Oct 19 15:52:36 laaskb001prvjay kibana[18883]: at _next (/usr/share/kibana/plugins/readonlyrestkbn/node_modules/@babel/runtime/helpers/asyncToGenerator.js:25:9)
Oct 19 15:52:36 laaskb001prvjay kibana[18883]: at /usr/share/kibana/plugins/readonlyrestkbn/node_modules/@babel/runtime/helpers/asyncToGenerator.js:32:7
Oct 19 15:52:36 laaskb001prvjay kibana[18883]: at new Promise (<anonymous>)
Oct 19 15:52:36 laaskb001prvjay kibana[18883]: at e.<anonymous> (/usr/share/kibana/plugins/readonlyrestkbn/node_modules/@babel/runtime/helpers/asyncToGenerator.js:21:12)
Oct 19 15:52:36 laaskb001prvjay kibana[18883]: at e (/usr/share/kibana/plugins/readonlyrestkbn/proxy/preKibanaProxy/customMiddleware.js:1:1821)
Oct 19 15:52:36 laaskb001prvjay kibana[18883]: at e (/usr/share/kibana/plugins/readonlyrestkbn/proxy/preKibanaProxy/preKibanaProxy.js:1:9183)
Oct 19 15:52:36 laaskb001prvjay kibana[18883]: at tryCatch (/usr/share/kibana/plugins/readonlyrestkbn/node_modules/regenerator-runtime/runtime.js:45:40)
Oct 19 15:52:36 laaskb001prvjay kibana[18883]: at Generator.invoke [as _invoke] (/usr/share/kibana/plugins/readonlyrestkbn/node_modules/regenerator-runtime/runtime.js:274:22)
Oct 19 15:52:36 laaskb001prvjay kibana[18883]: at Generator.prototype.<computed> [as next] (/usr/share/kibana/plugins/readonlyrestkbn/node_modules/regenerator-runtime/runtime.js:97:21)
Oct 19 15:52:36 laaskb001prvjay kibana[18883]: Terminating process...
Oct 19 15:52:36 laaskb001prvjay systemd[1]: kibana.service: main process exited, code=exited, status=1/FAILURE
Oct 19 15:52:36 laaskb001prvjay systemd[1]: Unit kibana.service entered failed state.
Oct 19 15:52:36 laaskb001prvjay systemd[1]: kibana.service failed.

It’s quite odd that it overrides the correct ES host to something incorrect:

Oct 19 15:52:25 laaskb001prvjay kibana[18883]: [15:52:24:950] [debug][plugins][ReadonlyREST][kibanaConfigInterceptor] Overriding 'elasticsearch.hosts' from http://laas-elasticsearch-data.service.dk1.discovery.pr.adform.zone:9200 to [http://localhost:57652]

deimantastumas · December 1, 2023, 11:42am

@Dzuming Hey, any updates?

Dzuming · December 1, 2023, 5:05pm

Hi, I sent you a private message with the pre-release build some time ago, I assume you didn’t receive any message about it? Are you able to open it? https://forum.readonlyrest.com/t/re-support-kbn-pro-kibana-sometimes-get-into-crash-loop-with-ror-related-errors/2430

Generally, I couldn’t reproduce it, however, I changed the code to not initialize ROR until license service initialization finished. The fix is included in the newest 1.53.0 version of the ROR.

deimantastumas · December 4, 2023, 6:57am

Hey, must have missed the message, sorry! We updated to the latest RoR version during our latest Kibana migration from 7.x to 8.x and we didn’t get any errors regarding LicenseService.

Thank you!