search

ManageIQ / manageiq-ui-classic

Classic UI of ManageIQ
Apache License 2.0
50 stars 358 forks source link

Login with OpenID Connect fails with "\xC5\" from ASCII-8BIT to UTF-8 #7689

Closed omersiar closed 3 years ago

omersiar commented 3 years ago

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>]"
}
{
    "@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"
}
"@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: unnamed (2)

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

omersiar commented 3 years ago

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

omersiar commented 3 years ago

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 commented 3 years ago 
/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 commented 3 years ago

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

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

Fryguy commented 3 years ago

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 commented 3 years ago

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 commented 3 years ago

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 commented 3 years ago

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 commented 3 years ago

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

omersiar commented 3 years ago 
[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":"banane@sanane.local","iss":"https://127.0.0.1:443/idauth/oidc/endpoint/OP","aud":"Y2xvdWRmb3Jtcwo=","exp":1616187788,"iat":1616144588,"sub":"banane@sanane.local","preferred_username":"onra ASK\xc4\xb0N","name":"onra","nonce":"IGOEj-iDp6LdZ4EgAXpAN4uLyUdGg75Vg4hpm2aBxFs","display_name":"Onra ASK\xc4\xb0N","given_name":"Onra","family_name":"Onra","email":"banane@sanane.com","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 commented 3 years ago

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 commented 3 years ago

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 commented 3 years ago

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

omersiar commented 3 years ago

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 commented 3 years ago

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 commented 3 years ago

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.