Manageiq-ui-classic: Login with OpenID Connect fails with "\xC5\" from ASCII-8BIT to UTF-8

[omersiar]

Dear All,

The installation is podified and httpd configured to have OIDC for SSO access. Identification Provider has two different LDAP configurations.

Users logging in with DOMAIN-A configuration -which does not have non-ascii characters in LDAP Group users- are able to login, but in contrast, DOMAIN-B users which they have non-ascii characters in their Group name fails to do so.

I'm not certain if it's all about Turkish chars are braking the login mechanism, this is just my premature assumption regarding the error message, so please not solely focus on chars being in Turkish.

traceback I found

{
    "@timestamp": "2021-03-18T13:56:40.403568 ",
    "hostname": "8-ui-c544c5c5-f5cbl",
    "pid": 7,
    "tid": "2ae5593a9918",
    "level": "err",
    "message": "[Encoding::UndefinedConversionError]: \"\\xC4\" from ASCII-8BIT to UTF-8  Method:[block (2 levels) in <class:LogProxy>]"
}

```javascript
{
"@timestamp": "2021-03-18T13:57:46.674280 ",
"hostname": "8-ui-c544c5c5-f5cbl",
"pid": 7,
"tid": "2ae55939e11c",
"level": "err",
"message": "MIQ(dashboard_controller-login): \"\xC4\" from ASCII-8BIT to UTF-8"
}

```javascript
"@timestamp":"2021-03-18T13:56:40.403797 ","hostname":"8-ui-c544c5c5-f5cbl","pid":7,"tid":"2ae5593a9918","level":"err","message":"/opt/IBM/infrastructure-management-gemset/gems/json-2.5.1/lib/json/common.rb:312:in `generate'\n/opt/IBM/infrastructure-management-gemset/gems/json-2.5.1/lib/json/common.rb:312:in `generate'\n/var/www/miq/vmdb/lib/vmdb/loggers/container_logger.rb:43:in `call'\n/usr/share/ruby/logger.rb:582:in `format_message'\n/usr/share/ruby/logger.rb:472:in `add'\n/opt/IBM/infrastructure-management-gemset/gems/activerecord-session_store-1.1.3/lib/active_record/session_store/extension/logger_silencer.rb:38:in `add_with_threadsafety'\n/opt/IBM/infrastructure-management-gemset/gems/activesupport-5.2.4.4/lib/active_support/logger.rb:27:in `block (2 levels) in broadcast'\n/usr/share/ruby/logger.rb:525:in `info'\n/var/www/miq/vmdb/lib/vmdb/loggers/audit_logger.rb:4:in `success'\n/var/www/miq/vmdb/app/models/audit_event.rb:17:in `generate'\n/var/www/miq/vmdb/app/models/audit_event.rb:22:in `success'\n/var/www/miq/vmdb/app/models/authenticator/base.rb:339:in `audit_success'\n/var/www/miq/vmdb/app/models/authenticator/base.rb:72:in `authenticate'\n/var/www/miq/vmdb/app/models/user.rb:210:in `authenticate'\n/opt/IBM/infrastructure-management-gemset/bundler/gems/bluecf-ui-classic-701df99728eb/app/services/user_validation_service.rb:94:in `validate_user_kick_off_task'\n/opt/IBM/infrastructure-management-gemset/bundler/gems/bluecf-ui-classic-701df99728eb/app/services/user_validation_service.rb:18:in `validate_user'\n/opt/IBM/infrastructure-management-gemset/bundler/gems/bluecf-ui-classic-701df99728eb/app/controllers/dashboard_controller.rb:671:in `validate_user'\n/opt/IBM/infrastructure-management-gemset/bundler/gems/bluecf-ui-classic-701df99728eb/app/controllers/dashboard_controller.rb:720:in `identity_provider_login'\n/opt/IBM/infrastructure-management-gemset/bundler/gems/bluecf-ui-classic-701df99728eb/app/controllers/dashboard_controller.rb:494:in `oidc_login'\n/opt/IBM/infrastructure-management-gemset/gems/actionpack-5.2.4.4/lib/action_controller/metal/basic_implicit_render.rb:6:in `send_action'\n/opt/IBM/infrastructure-management-gemset/gems/actionpack-5.2.4.4/lib/abstract_controller/base.rb:194:in `process_action'\n/opt/IBM/infrastructure-management-gemset/gems/actionpack-5.2.4.4/lib/action_controller/metal/rendering.rb:30:in `process_action'\n/opt/IBM/infrastructure-management-gemset/gems/actionpack-5.2.4.4/lib/abstract_controller/callbacks.rb:42:in `block in process_action'\n/opt/IBM/infrastructure-management-gemset/gems/activesupport-5.2.4.4/lib/active_support/callbacks.rb:132:in `run_callbacks'\n/opt/IBM/infrastructure-management-gemset/gems/actionpack-5.2.4.4/lib/abstract_controller/callbacks.rb:41:in `process_action'\n/opt/IBM/infrastructure-management-gemset/gems/actionpack-5.2.4.4/lib/action_controller/metal/rescue.rb:22:in `process_action'\n/opt/IBM/infrastructure-management-gemset/gems/actionpack-5.2.4.4/lib/action_controller/metal/instrumentation.rb:34:in `block in process_action'\n/opt/IBM/infrastructure-management-gemset/gems/activesupport-5.2.4.4/lib/active_support/notifications.rb:168:in `block in instrument'\n/opt/IBM/infrastructure-management-gemset/gems/activesupport-5.2.4.4/lib/active_support/notifications/instrumenter.rb:23:in `instrument'\n/opt/IBM/infrastructure-management-gemset/gems/activesupport-5.2.4.4/lib/active_support/notifications.rb:168:in `instrument'\n/opt/IBM/infrastructure-management-gemset/gems/actionpack-5.2.4.4/lib/action_controller/metal/instrumentation.rb:32:in `process_action'\n/opt/IBM/infrastructure-management-gemset/gems/actionpack-5.2.4.4/lib/action_controller/metal/params_wrapper.rb:256:in `process_action'\n/opt/IBM/infrastructure-management-gemset/gems/activerecord-5.2.4.4/lib/active_record/railties/controller_runtime.rb:24:in `process_action'\n/opt/IBM/infrastructure-management-gemset/gems/actionpack-5.2.4.4/lib/abstract_controller/base.rb:134:in `process'\n/opt/IBM/infrastructure-management-gemset/gems/actionview-5.2.4.4/lib/action_view/rendering.rb:32:in `process'\n/opt/IBM/infrastructure-management-gemset/gems/actionpack-5.2.4.4/lib/action_controller/metal.rb:191:in `dispatch'\n/opt/IBM/infrastructure-management-gemset/gems/actionpack-5.2.4.4/lib/action_controller/metal.rb:252:in `dispatch'\n/opt/IBM/infrastructure-management-gemset/gems/actionpack-5.2.4.4/lib/action_dispatch/routing/route_set.rb:52:in `dispatch'\n/opt/IBM/infrastructure-management-gemset/gems/actionpack-5.2.4.4/lib/action_dispatch/routing/route_set.rb:34:in `serve'\n/opt/IBM/infrastructure-management-gemset/gems/actionpack-5.2.4.4/lib/action_dispatch/journey/router.rb:52:in `block in serve'\n/opt/IBM/infrastructure-management-gemset/gems/actionpack-5.2.4.4/lib/action_dispatch/journey/router.rb:35:in `each'\n/opt/IBM/infrastructure-management-gemset/gems/actionpack-5.2.4.4/lib/action_dispatch/journey/router.rb:35:in `serve'\n/opt/IBM/infrastructure-management-gemset/gems/actionpack-5.2.4.4/lib/action_dispatch/routing/route_set.rb:840:in `call'\n/opt/IBM/infrastructure-management-gemset/bundler/gems/bluecf-graphql-f6cfe42626d1/lib/manageiq/graphql/rest_api_proxy.rb:18:in `call'\n/var/www/miq/vmdb/lib/request_started_on_middleware.rb:12:in `call'\n/opt/IBM/infrastructure-management-gemset/gems/rack-2.2.3/lib/rack/tempfile_reaper.rb:15:in `call'\n/opt/IBM/infrastructure-management-gemset/gems/rack-2.2.3/lib/rack/etag.rb:27:in `call'\n/opt/IBM/infrastructure-management-gemset/gems/rack-2.2.3/lib/rack/conditional_get.rb:27:in `call'\n/opt/IBM/infrastructure-management-gemset/gems/rack-2.2.3/lib/rack/head.rb:12:in `call'\n/opt/IBM/infrastructure-management-gemset/gems/actionpack-5.2.4.4/lib/action_dispatch/http/content_security_policy.rb:18:in `call'\n/opt/IBM/infrastructure-management-gemset/gems/rack-2.2.3/lib/rack/session/abstract/id.rb:266:in `context'\n/opt/IBM/infrastructure-management-gemset/gems/rack-2.2.3/lib/rack/session/abstract/id.rb:260:in `call'\n/opt/IBM/infrastructure-management-gemset/gems/actionpack-5.2.4.4/lib/action_dispatch/middleware/cookies.rb:670:in `call'\n/opt/IBM/infrastructure-management-gemset/gems/actionpack-5.2.4.4/lib/action_dispatch/middleware/callbacks.rb:28:in `block in call'\n/opt/IBM/infrastructure-management-gemset/gems/activesupport-5.2.4.4/lib/active_support/callbacks.rb:98:in `run_callbacks'\n/opt/IBM/infrastructure-management-gemset/gems/actionpack-5.2.4.4/lib/action_dispatch/middleware/callbacks.rb:26:in `call'\n/opt/IBM/infrastructure-management-gemset/gems/actionpack-5.2.4.4/lib/action_dispatch/middleware/debug_exceptions.rb:61:in `call'\n/opt/IBM/infrastructure-management-gemset/gems/actionpack-5.2.4.4/lib/action_dispatch/middleware/show_exceptions.rb:33:in `call'\n/opt/IBM/infrastructure-management-gemset/gems/railties-5.2.4.4/lib/rails/rack/logger.rb:38:in `call_app'\n/opt/IBM/infrastructure-management-gemset/gems/railties-5.2.4.4/lib/rails/rack/logger.rb:28:in `call'\n/opt/IBM/infrastructure-management-gemset/gems/actionpack-5.2.4.4/lib/action_dispatch/middleware/remote_ip.rb:81:in `call'\n/opt/IBM/infrastructure-management-gemset/gems/actionpack-5.2.4.4/lib/action_dispatch/middleware/request_id.rb:27:in `call'\n/opt/IBM/infrastructure-management-gemset/gems/rack-2.2.3/lib/rack/method_override.rb:24:in `call'\n/opt/IBM/infrastructure-management-gemset/gems/rack-2.2.3/lib/rack/runtime.rb:22:in `call'\n/opt/IBM/infrastructure-management-gemset/gems/activesupport-5.2.4.4/lib/active_support/cache/strategy/local_cache_middleware.rb:29:in `call'\n/opt/IBM/infrastructure-management-gemset/gems/actionpack-5.2.4.4/lib/action_dispatch/middleware/executor.rb:14:in `call'\n/opt/IBM/infrastructure-management-gemset/gems/rack-2.2.3/lib/rack/sendfile.rb:110:in `call'\n/opt/IBM/infrastructure-management-gemset/gems/secure_headers-3.9.0/lib/secure_headers/middleware.rb:12:in `call'\n/opt/IBM/infrastructure-management-gemset/gems/railties-5.2.4.4/lib/rails/engine.rb:524:in `call'\n/opt/IBM/infrastructure-management-gemset/gems/puma-4.3.7/lib/puma/configuration.rb:228:in `call'\n/opt/IBM/infrastructure-management-gemset/gems/puma-4.3.7/lib/puma/server.rb:713:in `handle_request'\n/opt/IBM/infrastructure-management-gemset/gems/puma-4.3.7/lib/puma/server.rb:472:in `process_client'\n/opt/IBM/infrastructure-management-gemset/gems/puma-4.3.7/lib/puma/server.rb:328:in `block in run'\n/opt/IBM/infrastructure-management-gemset/gems/puma-4.3.7/lib/puma/thread_pool.rb:134:in `block in spawn_thread'"}

SS:

I also have log files that I captured from UI-pods which I can not share in public domain.

[omersiar]

https://github.com/ManageIQ/manageiq/issues/21128

[omersiar]

It seems app/controllers/dashboard_controller.rb has some functions regarding to User's group, also I can see that the user is created in Access Control regardless if they were able to login or not.

[omersiar]

/opt/IBM/infrastructure-management-gemset/gems/json-2.5.1/lib/json/common.rb:312:in `generate'
/opt/IBM/infrastructure-management-gemset/gems/json-2.5.1/lib/json/common.rb:312:in `generate'
/var/www/miq/vmdb/lib/vmdb/loggers/container_logger.rb:43:in `call'
/usr/share/ruby/logger.rb:582:in `format_message'
/usr/share/ruby/logger.rb:472:in `add'
/opt/IBM/infrastructure-management-gemset/gems/activerecord-session_store-1.1.3/lib/active_record/session_store/extension/logger_silencer.rb:38:in `add_with_threadsafety'
/opt/IBM/infrastructure-management-gemset/gems/activesupport-5.2.4.4/lib/active_support/logger.rb:27:in `block (2 levels) in broadcast'
/usr/share/ruby/logger.rb:525:in `info'
/var/www/miq/vmdb/lib/vmdb/loggers/audit_logger.rb:4:in `success'
/var/www/miq/vmdb/app/models/audit_event.rb:17:in `generate'
/var/www/miq/vmdb/app/models/audit_event.rb:22:in `success'
/var/www/miq/vmdb/app/models/authenticator/base.rb:339:in `audit_success'
/var/www/miq/vmdb/app/models/authenticator/base.rb:72:in `authenticate'
/var/www/miq/vmdb/app/models/user.rb:210:in `authenticate'
/opt/IBM/infrastructure-management-gemset/bundler/gems/bluecf-ui-classic-701df99728eb/app/services/user_validation_service.rb:94:in `validate_user_kick_off_task'
/opt/IBM/infrastructure-management-gemset/bundler/gems/bluecf-ui-classic-701df99728eb/app/services/user_validation_service.rb:18:in `validate_user'
/opt/IBM/infrastructure-management-gemset/bundler/gems/bluecf-ui-classic-701df99728eb/app/controllers/dashboard_controller.rb:671:in `validate_user'
/opt/IBM/infrastructure-management-gemset/bundler/gems/bluecf-ui-classic-701df99728eb/app/controllers/dashboard_controller.rb:720:in `identity_provider_login'
/opt/IBM/infrastructure-management-gemset/bundler/gems/bluecf-ui-classic-701df99728eb/app/controllers/dashboard_controller.rb:494:in `oidc_login'
/opt/IBM/infrastructure-management-gemset/gems/actionpack-5.2.4.4/lib/action_controller/metal/basic_implicit_render.rb:6:in `send_action'
/opt/IBM/infrastructure-management-gemset/gems/actionpack-5.2.4.4/lib/abstract_controller/base.rb:194:in `process_action'
/opt/IBM/infrastructure-management-gemset/gems/actionpack-5.2.4.4/lib/action_controller/metal/rendering.rb:30:in `process_action'
/opt/IBM/infrastructure-management-gemset/gems/actionpack-5.2.4.4/lib/abstract_controller/callbacks.rb:42:in `block in process_action'
/opt/IBM/infrastructure-management-gemset/gems/activesupport-5.2.4.4/lib/active_support/callbacks.rb:132:in `run_callbacks'
/opt/IBM/infrastructure-management-gemset/gems/actionpack-5.2.4.4/lib/abstract_controller/callbacks.rb:41:in `process_action'
/opt/IBM/infrastructure-management-gemset/gems/actionpack-5.2.4.4/lib/action_controller/metal/rescue.rb:22:in `process_action'
/opt/IBM/infrastructure-management-gemset/gems/actionpack-5.2.4.4/lib/action_controller/metal/instrumentation.rb:34:in `block in process_action'
/opt/IBM/infrastructure-management-gemset/gems/activesupport-5.2.4.4/lib/active_support/notifications.rb:168:in `block in instrument'
/opt/IBM/infrastructure-management-gemset/gems/activesupport-5.2.4.4/lib/active_support/notifications/instrumenter.rb:23:in `instrument'
/opt/IBM/infrastructure-management-gemset/gems/activesupport-5.2.4.4/lib/active_support/notifications.rb:168:in `instrument'
/opt/IBM/infrastructure-management-gemset/gems/actionpack-5.2.4.4/lib/action_controller/metal/instrumentation.rb:32:in `process_action'
/opt/IBM/infrastructure-management-gemset/gems/actionpack-5.2.4.4/lib/action_controller/metal/params_wrapper.rb:256:in `process_action'
/opt/IBM/infrastructure-management-gemset/gems/activerecord-5.2.4.4/lib/active_record/railties/controller_runtime.rb:24:in `process_action'
/opt/IBM/infrastructure-management-gemset/gems/actionpack-5.2.4.4/lib/abstract_controller/base.rb:134:in `process'
/opt/IBM/infrastructure-management-gemset/gems/actionview-5.2.4.4/lib/action_view/rendering.rb:32:in `process'
/opt/IBM/infrastructure-management-gemset/gems/actionpack-5.2.4.4/lib/action_controller/metal.rb:191:in `dispatch'
/opt/IBM/infrastructure-management-gemset/gems/actionpack-5.2.4.4/lib/action_controller/metal.rb:252:in `dispatch'
/opt/IBM/infrastructure-management-gemset/gems/actionpack-5.2.4.4/lib/action_dispatch/routing/route_set.rb:52:in `dispatch'
/opt/IBM/infrastructure-management-gemset/gems/actionpack-5.2.4.4/lib/action_dispatch/routing/route_set.rb:34:in `serve'
/opt/IBM/infrastructure-management-gemset/gems/actionpack-5.2.4.4/lib/action_dispatch/journey/router.rb:52:in `block in serve'
/opt/IBM/infrastructure-management-gemset/gems/actionpack-5.2.4.4/lib/action_dispatch/journey/router.rb:35:in `each'
/opt/IBM/infrastructure-management-gemset/gems/actionpack-5.2.4.4/lib/action_dispatch/journey/router.rb:35:in `serve'
/opt/IBM/infrastructure-management-gemset/gems/actionpack-5.2.4.4/lib/action_dispatch/routing/route_set.rb:840:in `call'
/opt/IBM/infrastructure-management-gemset/bundler/gems/bluecf-graphql-f6cfe42626d1/lib/manageiq/graphql/rest_api_proxy.rb:18:in `call'
/var/www/miq/vmdb/lib/request_started_on_middleware.rb:12:in `call'
/opt/IBM/infrastructure-management-gemset/gems/rack-2.2.3/lib/rack/tempfile_reaper.rb:15:in `call'
/opt/IBM/infrastructure-management-gemset/gems/rack-2.2.3/lib/rack/etag.rb:27:in `call'
/opt/IBM/infrastructure-management-gemset/gems/rack-2.2.3/lib/rack/conditional_get.rb:27:in `call'
/opt/IBM/infrastructure-management-gemset/gems/rack-2.2.3/lib/rack/head.rb:12:in `call'
/opt/IBM/infrastructure-management-gemset/gems/actionpack-5.2.4.4/lib/action_dispatch/http/content_security_policy.rb:18:in `call'
/opt/IBM/infrastructure-management-gemset/gems/rack-2.2.3/lib/rack/session/abstract/id.rb:266:in `context'
/opt/IBM/infrastructure-management-gemset/gems/rack-2.2.3/lib/rack/session/abstract/id.rb:260:in `call'
/opt/IBM/infrastructure-management-gemset/gems/actionpack-5.2.4.4/lib/action_dispatch/middleware/cookies.rb:670:in `call'
/opt/IBM/infrastructure-management-gemset/gems/actionpack-5.2.4.4/lib/action_dispatch/middleware/callbacks.rb:28:in `block in call'
/opt/IBM/infrastructure-management-gemset/gems/activesupport-5.2.4.4/lib/active_support/callbacks.rb:98:in `run_callbacks'
/opt/IBM/infrastructure-management-gemset/gems/actionpack-5.2.4.4/lib/action_dispatch/middleware/callbacks.rb:26:in `call'
/opt/IBM/infrastructure-management-gemset/gems/actionpack-5.2.4.4/lib/action_dispatch/middleware/debug_exceptions.rb:61:in `call'
/opt/IBM/infrastructure-management-gemset/gems/actionpack-5.2.4.4/lib/action_dispatch/middleware/show_exceptions.rb:33:in `call'
/opt/IBM/infrastructure-management-gemset/gems/railties-5.2.4.4/lib/rails/rack/logger.rb:38:in `call_app'
/opt/IBM/infrastructure-management-gemset/gems/railties-5.2.4.4/lib/rails/rack/logger.rb:28:in `call'
/opt/IBM/infrastructure-management-gemset/gems/actionpack-5.2.4.4/lib/action_dispatch/middleware/remote_ip.rb:81:in `call'
/opt/IBM/infrastructure-management-gemset/gems/actionpack-5.2.4.4/lib/action_dispatch/middleware/request_id.rb:27:in `call'
/opt/IBM/infrastructure-management-gemset/gems/rack-2.2.3/lib/rack/method_override.rb:24:in `call'
/opt/IBM/infrastructure-management-gemset/gems/rack-2.2.3/lib/rack/runtime.rb:22:in `call'
/opt/IBM/infrastructure-management-gemset/gems/activesupport-5.2.4.4/lib/active_support/cache/strategy/local_cache_middleware.rb:29:in `call'
/opt/IBM/infrastructure-management-gemset/gems/actionpack-5.2.4.4/lib/action_dispatch/middleware/executor.rb:14:in `call'
/opt/IBM/infrastructure-management-gemset/gems/rack-2.2.3/lib/rack/sendfile.rb:110:in `call'
/opt/IBM/infrastructure-management-gemset/gems/secure_headers-3.9.0/lib/secure_headers/middleware.rb:12:in `call'
/opt/IBM/infrastructure-management-gemset/gems/railties-5.2.4.4/lib/rails/engine.rb:524:in `call'
/opt/IBM/infrastructure-management-gemset/gems/puma-4.3.7/lib/puma/configuration.rb:228:in `call'
/opt/IBM/infrastructure-management-gemset/gems/puma-4.3.7/lib/puma/server.rb:713:in `handle_request'
/opt/IBM/infrastructure-management-gemset/gems/puma-4.3.7/lib/puma/server.rb:472:in `process_client'
/opt/IBM/infrastructure-management-gemset/gems/puma-4.3.7/lib/puma/server.rb:328:in `block in run'
/opt/IBM/infrastructure-management-gemset/gems/puma-4.3.7/lib/puma/thread_pool.rb:134:in `block in spawn_thread'

[omersiar]

We have confirmed that the users without Turkish chars in their username or group are able to login.

You can test with these: İ Ğ Ş Ç Ö Ü ö ç ş ı ü ğ

[Fryguy]

I can basically reproduce this locally without needing the auth parts by doing the following in a Rails console

$ CONTAINER=true be rails c
[1] pry(main)> s = "İ Ğ Ş Ç Ö Ü ö ç ş ı ü ğ"
=> "İ Ğ Ş Ç Ö Ü ö ç ş ı ü ğ"
[2] pry(main)> s.force_encoding("ASCII-8BIT")
=> "\xC4\xB0 \xC4\x9E \xC5\x9E \xC3\x87 \xC3\x96 \xC3\x9C \xC3\xB6 \xC3\xA7 \xC5\x9F \xC4\xB1 \xC3\xBC \xC4\x9F"
[3] pry(main)> $audit_log.success(s)
Traceback (most recent call last):
    38: from bin/rails:4:in `<main>'
    37: from bin/rails:4:in `require'
    36: from ~/.gem/ruby/2.6.6/gems/railties-5.2.5/lib/rails/commands.rb:18:in `<top (required)>'
    35: from ~/.gem/ruby/2.6.6/gems/railties-5.2.5/lib/rails/command.rb:46:in `invoke'
    34: from ~/.gem/ruby/2.6.6/gems/railties-5.2.5/lib/rails/command/base.rb:69:in `perform'
    33: from ~/.gem/ruby/2.6.6/gems/thor-1.1.0/lib/thor.rb:392:in `dispatch'
    32: from ~/.gem/ruby/2.6.6/gems/thor-1.1.0/lib/thor/invocation.rb:127:in `invoke_command'
    31: from ~/.gem/ruby/2.6.6/gems/thor-1.1.0/lib/thor/command.rb:27:in `run'
    30: from ~/.gem/ruby/2.6.6/gems/railties-5.2.5/lib/rails/commands/console/console_command.rb:96:in `perform'
    29: from ~/.gem/ruby/2.6.6/gems/railties-5.2.5/lib/rails/commands/console/console_command.rb:19:in `start'
    28: from ~/.gem/ruby/2.6.6/gems/railties-5.2.5/lib/rails/commands/console/console_command.rb:64:in `start'
     9: from (pry):3:in `<main>'
     8: from ~/dev/manageiq/lib/vmdb/loggers/audit_logger.rb:4:in `success'
     7: from ~/.rubies/ruby-2.6.6/lib/ruby/2.6.0/logger.rb:525:in `info'
     6: from ~/.gem/ruby/2.6.6/gems/activesupport-5.2.5/lib/active_support/logger.rb:27:in `block (2 levels) in broadcast'
     5: from ~/.gem/ruby/2.6.6/gems/activerecord-session_store-1.1.3/lib/active_record/session_store/extension/logger_silencer.rb:38:in `add_with_threadsafety'
     4: from ~/.rubies/ruby-2.6.6/lib/ruby/2.6.0/logger.rb:472:in `add'
     3: from ~/.rubies/ruby-2.6.6/lib/ruby/2.6.0/logger.rb:582:in `format_message'
     2: from ~/dev/manageiq/lib/vmdb/loggers/container_logger.rb:43:in `call'
     1: from ~/.gem/ruby/2.6.6/gems/json-2.5.1/lib/json/common.rb:312:in `generate'
~/.gem/ruby/2.6.6/gems/json-2.5.1/lib/json/common.rb:312:in `generate': "\xC4" from ASCII-8BIT to UTF-8 (Encoding::UndefinedConversionError)

What I still can't figure out is how an ASCII-8BIT string even gets into the system.

[omersiar]

What is the offender here? Active Support's logger? I have already checked json library before, it seemed it does the force_encoding but could not find it right now.

Edit:
https://github.com/flori/json/search?q=force_encoding

[Fryguy]

It's definitely our logger at fault...specifically our container logger, which converts the log messages to JSON for display in STDOUT. When passing an ASCII-UTF8 encoded string with multibyte characters, the JSON generator doesn't like it.

In fact, if I simplify further, under the covers, the JSON library is just calling String#encode, so this also fails.

[2] pry(main)> s = "İ Ğ Ş Ç Ö Ü ö ç ş ı ü ğ"
=> "İ Ğ Ş Ç Ö Ü ö ç ş ı ü ğ"
[3] pry(main)> s.force_encoding("ASCII-8BIT")
=> "\xC4\xB0 \xC4\x9E \xC5\x9E \xC3\x87 \xC3\x96 \xC3\x9C \xC3\xB6 \xC3\xA7 \xC5\x9F \xC4\xB1 \xC3\xBC \xC4\x9F"
[4] pry(main)> s.encode("UTF-8")
Traceback (most recent call last):
    30: from bin/rails:4:in `<main>'
    29: from bin/rails:4:in `require'
    28: from ~/.gem/ruby/2.6.6/gems/railties-5.2.5/lib/rails/commands.rb:18:in `<top (required)>'
    27: from ~/.gem/ruby/2.6.6/gems/railties-5.2.5/lib/rails/command.rb:46:in `invoke'
    26: from ~/.gem/ruby/2.6.6/gems/railties-5.2.5/lib/rails/command/base.rb:69:in `perform'
    25: from ~/.gem/ruby/2.6.6/gems/thor-1.1.0/lib/thor.rb:392:in `dispatch'
    24: from ~/.gem/ruby/2.6.6/gems/thor-1.1.0/lib/thor/invocation.rb:127:in `invoke_command'
    23: from ~/.gem/ruby/2.6.6/gems/thor-1.1.0/lib/thor/command.rb:27:in `run'
    22: from ~/.gem/ruby/2.6.6/gems/railties-5.2.5/lib/rails/commands/console/console_command.rb:96:in `perform'
    21: from ~/.gem/ruby/2.6.6/gems/railties-5.2.5/lib/rails/commands/console/console_command.rb:19:in `start'
    20: from ~/.gem/ruby/2.6.6/gems/railties-5.2.5/lib/rails/commands/console/console_command.rb:64:in `start'
     1: from (pry):3:in `<main>'
(pry):3:in `encode': "\xC4" from ASCII-8BIT to UTF-8 (Encoding::UndefinedConversionError)

[Fryguy]

What I can't yet figure out is how an ASCII-8BIT string is coming into the system at all. It might be through the request headers, but I though request headers were already UTF-8

[Fryguy]

Ok, I figured it out... it seems request headers always come in as ASCII-8BIT for some reason. TIL.

[omersiar]

[Fri Mar 19 09:03:08.516501 2021] [auth_openidc:debug] [pid 22:tid 140430079399680] src/proto.c(1631): [client 10.128.4.1:57302] oidc_proto_parse_idtoken: successfully parsed (and possibly decrypted) JWT with header={"typ":"JWT","alg":"RS256"}, and payload={"hash":"b9c8398c6b4ea31362c122ed77d657ed9f16d2c6","realmName":"customRealm","uniqueSecurityName":"[email protected]","iss":"https://127.0.0.1:443/idauth/oidc/endpoint/OP","aud":"Y2xvdWRmb3Jtcwo=","exp":1616187788,"iat":1616144588,"sub":"[email protected]","preferred_username":"onra ASK\xc4\xb0N","name":"onra","nonce":"IGOEj-iDp6LdZ4EgAXpAN4uLyUdGg75Vg4hpm2aBxFs","display_name":"Onra ASK\xc4\xb0N","given_name":"Onra","family_name":"Onra","email":"[email protected]","domain":"sanane.local","teamRoleMappings":["icp:TURKISH:admin","icp:default:member","icp:default:teamadmin"],"groups":["Y\xc3\xb6netimi","","Enterprise Vault Archive Group 6 Months PG","SSL VPN Users","Yava\xc5\x9fl\xc4\xb1k"," M\xc3\xbcd\xc3\xbcrl\xc3\xbc\xc4\x9f\xc3\xbc",Fi\xc5\x9f Say\xc4\xb1lar\xc4\xb1"]}, referer: https://cp-console.apps.mcm.core.banane.com/oidc/login.jsp

:) I was busy obfuscating the log, you found out already.

[Fryguy]

I don't think so, because Rails is probably always going to mark headers as ASCII-8BIT as per the RFC.

I am looking at 2 fixes at the moment -

1. Ensure we UTF-8 encode the header values, which seems to work in tests, locally.
2. Ensure that if our logs get a ASCII-UTF8 string, we force it to utf-8 before logging

[omersiar]

Do you think of any workaround that I can make in current environment? It will take a little time to big blue prepares new images for this issue and the project is stuck at this moment.

[Fryguy]

The only thing I think that might work as a workaround is to disable the audit log.

[omersiar]

How? I could not find it in advanced configuration :(

:log:
  :level_aws: info
  :level_ansible_tower: info
  :level_azure: warn
  :level_kube: info
  :level_lenovo: info
  :level_rhevm: info
  :level_redfish: info
  :collection:
    :include_automate_models_and_dialogs: true
    :archive:
      :pattern: 
    :current:
      :pattern:
      - log/*.log
      - log/apache/*.log
      - log/*.txt
      - config/*
      - "/var/log/syslog*"
      - "/var/log/daemon.log*"
      - "/etc/default/ntp*"
      - "/var/log/messages*"
      - "/var/log/cron*"
      - "/var/log/tower/*.log"
      - BUILD
      - GUID
      - VERSION
    :ping_depot: true
    :ping_depot_timeout: 20
  :level: info
  :level_rails: info
  :level_api: info
  :level_automation: info
  :level_azure_stack: info
  :level_cn_monitoring: info
  :level_fog: info
  :level_mw: info
  :level_nuage: info
  :level_policy: info
  :level_scvmm: info
  :level_vcloud: info
  :level_vim: warn
  :level_remote_console: info

[Fryguy]

Ugh - I just checked the loggers code and we've literally never had a setting for this logger 😑

Even so, I just realized that I don't think we could disable the logger anyway, as we always log in DEBUG mode in the podified environment.

[Fryguy]

I was able to duplicate the issue with a KeyCloak OIDC server running locally and also verified that the fix in ManageIQ/manageiq#21171 works. There are a handful of other places in the code I want to verify before calling that a done deal.