OpenID authentication fails web error 500 "error" / readonrest logging "Sideserver error: "

BlueIcarus · April 12, 2021, 7:22am

Hi,

We are using readonlyrest for a couple of years now. One of the options we wanted for a long time was the integration with a OpenID provider. This is now available (for future reference we use this version: Enterprise-1.27.0_es7.6.1).

We have configured the RoR configuration as described on this page: https://github.com/beshu-tech/readonlyrest-docs/tree/master/kibana.
Our OpenID provide is a private Keycloak instance.

We however can’t seem to get it working. What I have on information of my installation is mentioned below. I have redacted some values or replaced them with other placeholders for security reasons as you might image.

I have tried to do my utmost best to add information to this post but I can’t post my logging as I’m restricted to 2 links in a post (and just the logging already contains more urls). I also tried to upload a zip file but that is also denied. I have now uploaded the files to WeTransfer (as that was the only solution I could find)/l https://wetransfer.com/downloads/0d39bcb815eb4d0adae72f44b9eb127420210412072016/d01d6e6329f3d061c931fc50c53e1d8c20210412072034/af8a44?utm_campaign=WT_email_tracking&utm_content=general&utm_medium=download_button&utm_source=notify_recipient_email

As a response in Keycloak (after the user is redirected back from Keycloak) he/she will get a page that just states error (it’s a HTTP 500 response). From the page itself I can’t really seem to figure out whats going on there. It appears to me that the token that is passed back from Keycloak to RoR but RoR can’t seem to read it? I might be mistaking here as I can’t really evaluate whats going on there. I hope someone can help and knows how to resolve these issues. We are really hoping to get this working in the short therm as we have a organization with hundreds of people that will be using the SSO process.

sscarduzio · April 12, 2021, 9:44am

Dear @BlueIcarus, thanks for supporting ROR!
The sideserver proxy does not have any information to share about the cause of the 500 error in the OIDC side server. Ideally, two things would move us forward:

set up “readonlyrest_kbn.logLevel: debug” in kibana.yml, and also “logging.json: false” for better readability since you are at it.
Please update your ROR Enterprise to the latest version, we re now at 1.29.0, and we made some fixes in that area lately.

BlueIcarus · April 13, 2021, 5:54am

Dear @sscarduzio, thank you for your swift response.

I did all of those things for you.

I changed the logformat to non-json. Below the logging I have now after testing it again;
I upgraded ROR to version 1.29.0 (in both Elasticsearch and Kibana).

log [05:43:56.561] [warning][legacy-plugins] Skipping non-plugin directory at /usr/share/kibana/src/legacy/core_plugins/console_legacy
log [05:43:56.574] [warning][legacy-plugins] Skipping non-plugin directory at /usr/share/kibana/src/legacy/core_plugins/kbn_doc_views
log [05:43:56.739] [warning][legacy-plugins] Skipping non-plugin directory at /usr/share/kibana/src/legacy/core_plugins/markdown_vis
log [05:43:56.740] [warning][legacy-plugins] Skipping non-plugin directory at /usr/share/kibana/src/legacy/core_plugins/metric_vis
log [05:43:56.741] [warning][legacy-plugins] Skipping non-plugin directory at /usr/share/kibana/src/legacy/core_plugins/metrics
log [05:43:56.747] [warning][legacy-plugins] Skipping non-plugin directory at /usr/share/kibana/src/legacy/core_plugins/table_vis
log [05:43:56.747] [warning][legacy-plugins] Skipping non-plugin directory at /usr/share/kibana/src/legacy/core_plugins/tagcloud
log [05:43:56.852] [warning][legacy-plugins] Skipping non-plugin directory at /usr/share/kibana/src/legacy/core_plugins/vega
log [05:43:56.852] [warning][legacy-plugins] Skipping non-plugin directory at /usr/share/kibana/src/legacy/core_plugins/vis_default_editor
log [05:43:56.858] [warning][legacy-plugins] Skipping non-plugin directory at /usr/share/kibana/src/legacy/core_plugins/vis_type_timelion
log [05:43:56.861] [warning][legacy-plugins] Skipping non-plugin directory at /usr/share/kibana/src/legacy/core_plugins/vis_type_vislib
log [05:43:56.861] [warning][legacy-plugins] Skipping non-plugin directory at /usr/share/kibana/src/legacy/core_plugins/vis_type_xy
log [05:43:57.924] [info][plugins-system] Setting up [36] plugins: [taskManager,siem,licensing,infra,code,encryptedSavedObjects,timelion,features,usageCollection,metrics,canvas,apm_oss,translations,reporting,uiActions,data,navigation,newsfeed,status_page,share,inspector,expressions,visualizations,embeddable,advancedUiActions,dashboard_embeddable_container,kibana_legacy,management,dev_tools,home,spaces,cloud,apm,graph,eui_utils,bfetch]
log [05:43:57.925] [info][plugins][taskManager] Setting up plugin
log [05:43:57.941] [info][plugins][siem] Setting up plugin
log [05:43:57.942] [info][licensing][plugins] Setting up plugin
log [05:43:57.945] [info][infra][plugins] Setting up plugin
log [05:43:57.946] [info][code][plugins] Setting up plugin
log [05:43:57.947] [info][encryptedSavedObjects][plugins] Setting up plugin
log [05:43:57.948] [warning][config][encryptedSavedObjects][plugins] Generating a random key for xpack.encryptedSavedObjects.encryptionKey. To be able to decrypt encrypted saved objects attributes after restart, please set xpack.encryptedSavedObjects.encryptionKey in kibana.yml
log [05:43:57.952] [info][plugins][timelion] Setting up plugin
log [05:43:57.953] [info][features][plugins] Setting up plugin
log [05:43:57.955] [info][plugins][usageCollection] Setting up plugin
log [05:43:57.956] [info][metrics][plugins] Setting up plugin
log [05:43:57.957] [info][canvas][plugins] Setting up plugin
log [05:43:57.964] [info][apm_oss][plugins] Setting up plugin
log [05:43:57.964] [info][plugins][translations] Setting up plugin
log [05:43:57.965] [info][data][plugins] Setting up plugin
log [05:43:57.971] [info][plugins][share] Setting up plugin
log [05:43:57.973] [info][home][plugins] Setting up plugin
log [05:43:57.979] [info][plugins][spaces] Setting up plugin
log [05:43:57.984] [info][cloud][plugins] Setting up plugin
log [05:43:57.986] [info][apm][plugins] Setting up plugin
log [05:43:57.991] [info][graph][plugins] Setting up plugin
log [05:43:57.994] [info][bfetch][plugins] Setting up plugin
log [05:43:58.003] [info][savedobjects-service] Waiting until all Elasticsearch nodes are compatible with Kibana before starting saved objects migrations…
log [05:43:58.032] [info][savedobjects-service] Starting saved objects migrations
log [05:43:58.068] [info][savedobjects-service] Creating index .kibana_task_manager_103.
log [05:43:58.167] [info][savedobjects-service] Migrating .kibana_task_manager_102 saved objects to .kibana_task_manager_103
log [05:43:58.233] [info][savedobjects-service] Pointing alias .kibana_task_manager to .kibana_task_manager_103.
log [05:43:58.294] [info][savedobjects-service] Finished in 226ms.
log [05:43:58.296] [info][plugins-system] Starting [21] plugins: [taskManager,siem,licensing,infra,code,encryptedSavedObjects,timelion,features,usageCollection,metrics,canvas,apm_oss,translations,data,share,home,spaces,cloud,apm,graph,bfetch]
log [05:44:00.343] [info][status][plugin:kibana@7.6.1] Status changed from uninitialized to green - Ready
log [05:44:00.630] [info][plugins][taskManager][taskManager] TaskManager is identified by the Kibana UUID: 0095aa3b-36e5-4503-b0ab-82331cd5a5bc
log [05:44:00.351] [info][status][plugin:elasticsearch@7.6.1] Status changed from uninitialized to yellow - Waiting for Elasticsearch
log [05:44:00.352] [info][status][plugin:elasticsearch@7.6.1] Status changed from yellow to green - Ready
log [05:44:00.355] [info][status][plugin:xpack_main@7.6.1] Status changed from uninitialized to green - Ready
log [05:44:00.379] [info][kibana-monitoring][monitoring] Starting monitoring stats collection
log [05:44:00.380] [info][status][plugin:monitoring@7.6.1] Status changed from uninitialized to green - Ready
log [05:44:00.389] [info][status][plugin:spaces@7.6.1] Status changed from uninitialized to green - Ready
log [05:44:00.392] [info][status][plugin:searchprofiler@7.6.1] Status changed from uninitialized to green - Ready
log [05:44:00.399] [info][status][plugin:tilemap@7.6.1] Status changed from uninitialized to green - Ready
log [05:44:00.401] [info][status][plugin:grokdebugger@7.6.1] Status changed from uninitialized to green - Ready
log [05:44:00.407] [info][status][plugin:dashboard_mode@7.6.1] Status changed from uninitialized to green - Ready
log [05:44:00.411] [info][status][plugin:logstash@7.6.1] Status changed from uninitialized to green - Ready
log [05:44:00.424] [info][status][plugin:beats_management@7.6.1] Status changed from uninitialized to green - Ready
log [05:44:00.457] [info][status][plugin:apm_oss@7.6.1] Status changed from uninitialized to green - Ready
log [05:44:00.474] [info][status][plugin:apm@7.6.1] Status changed from uninitialized to green - Ready
log [05:44:00.501] [info][status][plugin:maps@7.6.1] Status changed from uninitialized to green - Ready
log [05:44:00.507] [info][status][plugin:interpreter@7.6.1] Status changed from uninitialized to green - Ready
log [05:44:00.518] [info][status][plugin:canvas@7.6.1] Status changed from uninitialized to green - Ready
log [05:44:00.522] [info][status][plugin:license_management@7.6.1] Status changed from uninitialized to green - Ready
log [05:44:00.525] [info][status][plugin:index_management@7.6.1] Status changed from uninitialized to green - Ready
log [05:44:00.557] [info][status][plugin:console@7.6.1] Status changed from uninitialized to green - Ready
log [05:44:00.560] [info][status][plugin:console_extensions@7.6.1] Status changed from uninitialized to green - Ready
log [05:44:00.568] [info][status][plugin:index_lifecycle_management@7.6.1] Status changed from uninitialized to green - Ready
log [05:44:00.586] [info][status][plugin:kuery_autocomplete@7.6.1] Status changed from uninitialized to green - Ready
log [05:44:00.596] [info][status][plugin:metrics@7.6.1] Status changed from uninitialized to green - Ready
log [05:44:00.626] [info][status][plugin:infra@7.6.1] Status changed from uninitialized to green - Ready
log [05:44:00.632] [info][status][plugin:task_manager@7.6.1] Status changed from uninitialized to green - Ready
log [05:44:00.634] [info][status][plugin:rollup@7.6.1] Status changed from uninitialized to green - Ready
log [05:44:00.668] [info][status][plugin:transform@7.6.1] Status changed from uninitialized to green - Ready
log [05:44:00.672] [info][status][plugin:encryptedSavedObjects@7.6.1] Status changed from uninitialized to green - Ready
log [05:44:00.691] [info][status][plugin:actions@7.6.1] Status changed from uninitialized to green - Ready
log [05:44:00.720] [info][status][plugin:alerting@7.6.1] Status changed from uninitialized to green - Ready
log [05:44:00.800] [info][status][plugin:siem@7.6.1] Status changed from uninitialized to green - Ready
log [05:44:00.818] [info][status][plugin:remote_clusters@7.6.1] Status changed from uninitialized to green - Ready
log [05:44:00.822] [info][status][plugin:cross_cluster_replication@7.6.1] Status changed from uninitialized to green - Ready
log [05:44:00.855] [info][status][plugin:upgrade_assistant@7.6.1] Status changed from uninitialized to green - Ready
log [05:44:00.875] [info][status][plugin:uptime@7.6.1] Status changed from uninitialized to green - Ready
log [05:44:00.879] [info][status][plugin:oss_telemetry@7.6.1] Status changed from uninitialized to green - Ready
log [05:44:00.883] [info][status][plugin:file_upload@7.6.1] Status changed from uninitialized to green - Ready
log [05:44:00.886] [info][status][plugin:data@7.6.1] Status changed from uninitialized to green - Ready
log [05:44:00.892] [info][status][plugin:lens@7.6.1] Status changed from uninitialized to green - Ready
log [05:44:00.934] [info][status][plugin:snapshot_restore@7.6.1] Status changed from uninitialized to green - Ready
log [05:44:00.939] [info][readonlyrest_kbn:init] Kibana version: 7.6.1
log [05:44:00.939] [info][readonlyrest_kbn:init] ReadonlyREST plugin version: enterprise-1.29.0_es7.6.1
log [05:44:00.945] [info][readonlyrest_kbn:OIDCExpressServer] OIDC Settings
{
“buttonName”: “OpenID Login”,
“type”: “oidc”,
“issuer”: “link_https://keycloak.internal.company.com/auth/realms/master”,
“authorizationURL”: “link_https://keycloak.internal.company.com/auth/realms/master/protocol/openid-connect/auth”,
“tokenURL”: “link_https://keycloak.internal.company.com/auth/realms/master/protocol/openid-connect/token”,
“userInfoURL”: “link_https://keycloak.internal.company.com/auth/realms/master/protocol/openid-connect/userinfo”,
“clientID”: “kibana”,
“clientSecret”: “kibana_secret”,
“scope”: “openid profile roles role_list_openid email”,
“usernameParameter”: “preferred_username”,
“groupsParameter”: “group-membership”,
“kibanaExternalHost”: “kibana.internal.company.com:8001”,
“logoutUrl”: “link_https://keycloak.internal.company.com/auth/realms/master/protocol/openid-connect/logout”,
“routePrefix”: “/ror_kbn_sso_oidc_kc”,
“name”: “oidc_kc”,
“callbackURL”: “link_http://kibana.internal.company.com:8001/ror_kbn_sso_oidc_kc/callback”
}
log [05:44:00.948] [info][readonlyrest_kbn:readonlyrest_kbn:sideserver] will start a sideserver for route prefix /ror_kbn_sso_oidc_kc on port: 8002
log [05:44:00.951] [info][readonlyrest_kbn:readonlyrest_kbn:sideserver(DBG)] Launching init function for ss /ror_kbn_sso_oidc_kc
log [05:44:00.956] [info][readonlyrest_kbn:readonlyrest_kbn:sideserver] sideserver for route prefix /ror_kbn_sso_oidc_kc initialised.
log [05:44:00.960] [info][readonlyrest_kbn:IndexBasedSessionManager(DBG)] Trying to create an index for the session manager: .readonlyrest_kbn_sessions
log [05:44:00.961] [info][readonlyrest_kbn:OIDCExpressServer(DBG)] Listening on port 8002
log [05:44:01.075] [info][readonlyrest_kbn:IndexBasedSessionManager] The index .readonlyrest_kbn_sessions already existed.
log [05:44:01.078] [info][readonlyrest_kbn:initAuth] ROR Session cookie will be named: rorCookie), with expiration in 4320 minutes
log [05:44:01.130] [info][status][plugin:readonlyrest_kbn@1.29.0] Status changed from uninitialized to green - Ready
log [05:44:01.139] [info][status][plugin:input_control_vis@7.6.1] Status changed from uninitialized to green - Ready
log [05:44:01.143] [info][status][plugin:kibana_react@7.6.1] Status changed from uninitialized to green - Ready
log [05:44:01.146] [info][status][plugin:management@7.6.1] Status changed from uninitialized to green - Ready
log [05:44:01.148] [info][status][plugin:navigation@7.6.1] Status changed from uninitialized to green - Ready
log [05:44:01.153] [info][status][plugin:region_map@7.6.1] Status changed from uninitialized to green - Ready
log [05:44:01.166] [info][status][plugin:telemetry@7.6.1] Status changed from uninitialized to green - Ready
log [05:44:01.253] [info][status][plugin:timelion@7.6.1] Status changed from uninitialized to green - Ready
log [05:44:01.256] [info][status][plugin:ui_metric@7.6.1] Status changed from uninitialized to green - Ready
log [05:44:01.259] [info][status][plugin:markdown_vis@7.6.1] Status changed from uninitialized to green - Ready
log [05:44:01.261] [info][status][plugin:metric_vis@7.6.1] Status changed from uninitialized to green - Ready
log [05:44:01.264] [info][status][plugin:table_vis@7.6.1] Status changed from uninitialized to green - Ready
log [05:44:01.267] [info][status][plugin:tagcloud@7.6.1] Status changed from uninitialized to green - Ready
log [05:44:01.269] [info][status][plugin:vega@7.6.1] Status changed from uninitialized to green - Ready
log [05:44:01.273] [warning][browser-driver][reporting] Enabling the Chromium sandbox provides an additional layer of protection.
log [05:44:01.869] [info][status][plugin:reporting@7.6.1] Status changed from uninitialized to green - Ready
log [05:44:01.914] [info][listening] Server running at link_http://kibana.internal.company.com:8001
log [05:44:02.182] [info][server][Kibana][http] http server running at link_http://kibana.internal.company.com:8001
log [05:44:04.877] [info][readonlyrest_kbn:init(DBG)] [patchClientParams] changed reporting index to .reporting-*
log [05:44:04.987] [error][plugins][taskManager][taskManager] Failed to mark Task vis_telemetry “oss_telemetry-vis_telemetry” as running: Task has been claimed by another Kibana service
log [05:44:05.387] [info][readonlyrest_kbn:getIdentityFromCookie(DBG)] Didn’t find sid2session for sid: 593cce2d-5c33-4e5e-bc93-241d7d73a0bb so I delete cookie. State was: {“rorCookie”:{“sid”:“593cce2d-5c33-4e5e-bc93-241d7d73a0bb”,“username”:“testuser”,“kibanaIndex”:“.kibana”,“kibanaAccess”:“unrestricted”,“expiresAt”:1618551845381}}
log [05:44:05.388] [info][readonlyrest_kbn:getIdentityFromCookie(DBG)] Didn’t find sid2session for sid: 593cce2d-5c33-4e5e-bc93-241d7d73a0bb so I delete cookie. sid2session was: undefined
log [05:44:07.890] [info][readonlyrest_kbn:init(DBG)] [patchClientParams] changed reporting index to .reporting-*
log [05:44:10.905] [info][readonlyrest_kbn:init(DBG)] [patchClientParams] changed reporting index to .reporting-*
log [05:44:13.924] [info][readonlyrest_kbn:init(DBG)] [patchClientParams] changed reporting index to .reporting-*
log [05:44:16.076] [info][readonlyrest_kbn:readonlyrest_kbn:sideserver-PROXY(DBG)] >>> redirecting get /ror_kbn_sso_oidc_kc/login-ep to link_https://keycloak.internal.company.com/auth/realms/master/protocol/openid-connect/auth?response_type=code&client_id=kibana&redirect_uri=http%3A%2F%2Fkibana.internal.company.com%3A8001%2Fror_kbn_sso_oidc_kc%2Fcallback&scope=openid%20openid%20profile%20roles%20role_list_openid%20email&state=ZXRyle64JUa4IB8uAdGDP0Ih
log [05:44:16.368] [error][readonlyrest_kbn:readonlyrest_kbn:sideserver-PROXY] Sideserver error:
log [05:44:16.369] [error][readonlyrest_kbn:readonlyrest_kbn:sideserver-PROXY] { message: ‘Request failed with status code 500’,
name: ‘Error’,
description: undefined,
number: undefined,
fileName: undefined,
lineNumber: undefined,
columnNumber: undefined,
stack:
‘Error: Request failed with status code 500\n at createError (/usr/share/kibana/plugins/readonlyrest_kbn/node_modules/axios/lib/core/createError.js:16:15)\n at settle (/usr/share/kibana/plugins/readonlyrest_kbn/node_modules/axios/lib/core/settle.js:17:12)\n at IncomingMessage.handleStreamEnd (/usr/share/kibana/plugins/readonlyrest_kbn/node_modules/axios/lib/adapters/http.js:260:11)\n at IncomingMessage.emit (events.js:203:15)\n at endReadableNT (_stream_readable.js:1145:12)\n at process._tickCallback (internal/process/next_tick.js:63:19)’,
config:
{ url: ‘link_http://kibana.internal.company.com:8002/callback’,
method: ‘get’,
data: ‘’,
headers:
{ Accept:
‘text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,image/apng,/;q=0.8,application/signed-exchange;v=b3;q=0.9’,
‘accept-encoding’: ‘gzip, deflate’,
‘accept-language’: ‘nl,en-US;q=0.9,en;q=0.8,de;q=0.7’,
connection: ‘keep-alive’,
cookie:
‘rorCookie_oidc_kc=s%3AXEyT1xcS6AjbFpYdFsMLmulZVME1QdLa.bgS7chuQXgYURw7P5I6LmQvf%2FLrt6cV208rNVm1QTSs’,
‘user-agent’:
‘Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/89.0.4389.114 Safari/537.36’ },
params:
{ state: ‘ZXRyle64JUa4IB8uAdGDP0Ih’,
session_state: ‘8ceaa877-11e0-4289-8953-da224ab01e36’,
code:
‘18449787-405a-4998-af87-a9d37dde1bd6.8ceaa877-11e0-4289-8953-da224ab01e36.a25e0bfd-4b44-4e06-a7be-be815a2b7289’ },
transformRequest: [ [Function: transformRequest] ],
transformResponse: [ [Function: transformResponse] ],
timeout: 0,
adapter: [Function: httpAdapter],
xsrfCookieName: ‘XSRF-TOKEN’,
xsrfHeaderName: ‘X-XSRF-TOKEN’,
maxContentLength: -1,
maxBodyLength: -1,
maxRedirects: 0,
validateStatus: [Function: validateStatus] },
code: undefined }
log [05:44:16.739] [error][readonlyrest_kbn:onPreResponse] got an error [404] Not Found for path /favicon.ico
log [05:44:16.740] [error][readonlyrest_kbn:onPreResponse] index not found, will return the useful error.

I hope this helps.

PS. I had to change the links in this logging to link_http/link_https to post the logging. The original logging/configuration (of course) contains proper http/https links.

sscarduzio · April 13, 2021, 10:01am

Dear @BlueIcarus, I upgraded your forum privileges and added you to Enterprise users group. So you hopefully won’t have issues. I will review your case now.

sscarduzio · April 13, 2021, 5:53pm

@BlueIcarus I can’t see anything wrong with your settings, the log are not helpful as the 500 error is coming from the library well before any ROR code is executed.

I will keep on looking if anything is different in how you set up the Keycloak client compared to my working version. In the meantime, can you make sure you are not in this situation?

sscarduzio · April 18, 2021, 8:34pm

I managed to make the library print what is wrong, I will send you a new build in a private message here in the forum. Please check your inbox.

BlueIcarus · April 19, 2021, 5:17am

Hi. I have downloaded the custom version. I will deploy it asap and will report back to you with more details. I will also look into the other issue you mentioned in your posts.

BlueIcarus · April 19, 2021, 6:17am

Hi @sscarduzio. First of thankt you for the great help! I have found the cause of this issue by using your custom version of the plugin.

The short problem/answer:
The browser was responding with the error message Unable to verify authorization request state. which is strange. The logs did not give me any more details. I at first had the idea that my Keycloak configuration was still broken. But that was not the case. After I kept testing it a bit more I noticed my Kibana instance was crashing and restarting. The /var/log/messages mentioned failed to obtain access token (Error: unable to get local issuer certificate). In the previous versions of the plugin, Kibana did not log anything nor did it crash. The problem described here has to do with the fact that I’m using a ‘self-signed-certificate’ on my Keycloak installation. Solving this is very simpel. I just added a extra NODE paramater NODE_EXTRA_CA_CERTS="${DIR}/cacert.pem" to Kibana and added my custom CA to that file, and that solved the problem.

The long(er) answer:
As mentioned in the short answer my Kibana instance crashed which it did not do before. Here is the important part of the /var/log/messages logs:

Apr 19 07:34:36 {_HOSTNAME_} kibana: /usr/share/kibana/plugins/readonlyrest_kbn/server/routes/lib/constants.js:89
Apr 19 07:34:36 {_HOSTNAME_} kibana: throw err;
Apr 19 07:34:36 {_HOSTNAME_} kibana: ^
Apr 19 07:34:36 {_HOSTNAME_} kibana: failed to obtain access token (Error: unable to get local issuer certificate)
Apr 19 07:34:36 {_HOSTNAME_} kibana: at /usr/share/kibana/plugins/readonlyrest_kbn/node_modules/passport-openidconnect/lib/strategy.js:93:38
Apr 19 07:34:36 {_HOSTNAME_} kibana: at /usr/share/kibana/plugins/readonlyrest_kbn/node_modules/oauth/lib/oauth2.js:191:18
Apr 19 07:34:36 {_HOSTNAME_} kibana: at ClientRequest.<anonymous> (/usr/share/kibana/plugins/readonlyrest_kbn/node_modules/oauth/lib/oauth2.js:162:5)
Apr 19 07:34:36 {_HOSTNAME_} kibana: at ClientRequest.emit (events.js:198:13)
Apr 19 07:34:36 {_HOSTNAME_} kibana: at TLSSocket.socketErrorListener (_http_client.js:401:9)
Apr 19 07:34:36 {_HOSTNAME_} kibana: at TLSSocket.emit (events.js:198:13)
Apr 19 07:34:36 {_HOSTNAME_} kibana: at emitErrorNT (internal/streams/destroy.js:91:8)
Apr 19 07:34:36 {_HOSTNAME_} kibana: at emitErrorAndCloseNT (internal/streams/destroy.js:59:3)
Apr 19 07:34:36 {_HOSTNAME_} kibana: at process._tickCallback (internal/process/next_tick.js:63:19)
Apr 19 07:34:36 {_HOSTNAME_} systemd: kibana.service: main process exited, code=exited, status=1/FAILURE
Apr 19 07:34:36 {_HOSTNAME_} systemd: Unit kibana.service entered failed state.
Apr 19 07:34:36 {_HOSTNAME_} systemd: kibana.service failed.
Apr 19 07:34:39 {_HOSTNAME_} systemd: kibana.service holdoff time over, scheduling restart.
Apr 19 07:34:39 {_HOSTNAME_} systemd: Stopped Kibana.

And this is the important part of the Kibana logging:

  log   [05:38:59.124] [error][readonlyrest_kbn:OIDCExpressServer] oidc_kc error:
  log   [05:38:59.125] [error][readonlyrest_kbn:OIDCExpressServer] {"message":"Unable to verify authorization request state."}

At first these messages don’t seem to be related to each other but they of course are. The “Unable to verify authorization request state” is of course correct because the page that is returning the data, is not using a trusted HTTPS certificate. The message from the /var/log/messages gave me a ‘aha’ moment. I know that Kibana uses node so I knew what to look for and what to change.

I added the parameter NODE_EXTRA_CA_CERTS="${DIR}/cacert.pem" to the file bin/kibana and created a cacert.pem that contained my own custom CA. I finally restarted Kibana en tried again and the login worked as I was expecting it to.

Some more details about the Node configuration:
The parameter NODE_EXTRA_CA_CERTS is a ENVIRONMENT variable that can be set for NODE applications (Command-line API | Node.js v19.5.0 Documentation). You can do this in many places, like the kibana ‘binary/script’ or for instance in the configuration of the Kibana system daemon. (Its a environment variable so as long as the service itself can read the variable, it will work). You can also use the NODE argument (that can be added to the NODE_OPTIONS environment variable) --use-openssl-ca to tell node to use the local systems openssl library in stead of the node ‘build in’ version ca list (Command-line API | Node.js v19.5.0 Documentation).

I hope this helps people that might have the same challenge that I had with my configuration. I would suggest adding some details about this scenario to the documentation.

sscarduzio · April 21, 2021, 8:38pm

Amazing analysis @BlueIcarus! Glad it works now.
Yes there is a bit more work to be done on this.

By the way, I’m working on a keyclak native connector that requires less configuration and uses the official library from Keycloak. Will notify you when I have something.