Un-rescuable ShopifyApp::LoginProtection::ShopifyDomainNotFound error every time there is an invalid JWT token error

[dansundy]

Description

After upgrading to version 20.1.1 we are seeing a ShopifyApp::LoginProtection::ShopifyDomainNotFound error every time there is an invalid JWT token error: ShopifyAPI::Errors::InvalidJwtTokenError. The former error can't seem to be rescued or handled in any way and the request returns a 500 level error even if the latter 401 is handled and returned to the front end. I've sifted through the Shopify App gem's login protection concern without seeing any way to avoid this with my configuration.

Steps to Reproduce

Send a request with an invalid (e.g. expired) JWT token.

Expected behavior:

The server returns a 401 level error to the front end.

Actual behavior:

The server return a 500 level error to the front end.

Reproduces how often:

The ShopifyApp::LoginProtection::ShopifyDomainNotFound error happens every time a ShopifyAPI::Errors::InvalidJwtTokenError happens. I can't figure out if it is happening after or simultaneously somehow.

Browsers

• Firefox

Gem versions

• Shopify app gem v20.1.1 in production
• Also tested locally with v20.2.0

Additional Information

Stack trace for ShopifyApp::LoginProtection::ShopifyDomainNotFound:

Stack trace[Hide framework code]
ShopifyApp::LoginProtection::ShopifyDomainNotFound: ShopifyApp::LoginProtection::ShopifyDomainNotFound
…ib/shopify_app/controller_concerns/login_protection.rb:  197:in `current_shopify_domain'
…lib/shopify_app/controller_concerns/frame_ancestors.rb:   10:in `block (3 levels) in <module
….1/lib/action_dispatch/http/content_security_policy.rb:  341:in `instance_exec'
….1/lib/action_dispatch/http/content_security_policy.rb:  341:in `resolve_source'
….1/lib/action_dispatch/http/content_security_policy.rb:  328:in `block in build_directive'
….1/lib/action_dispatch/http/content_security_policy.rb:  328:in `map'
….1/lib/action_dispatch/http/content_security_policy.rb:  328:in `build_directive'
….1/lib/action_dispatch/http/content_security_policy.rb:  317:in `block in build_directives'
….1/lib/action_dispatch/http/content_security_policy.rb:  312:in `each'
….1/lib/action_dispatch/http/content_security_policy.rb:  312:in `map'
….1/lib/action_dispatch/http/content_security_policy.rb:  312:in `build_directives'
….1/lib/action_dispatch/http/content_security_policy.rb:  288:in `build'
….1/lib/action_dispatch/http/content_security_policy.rb:   44:in `call'
…/new_relic/agent/instrumentation/middleware_tracing.rb:  100:in `call'
…/3.1.0/gems/rack-2.2.4/lib/rack/session/abstract/id.rb:  266:in `context'
…/3.1.0/gems/rack-2.2.4/lib/rack/session/abstract/id.rb:  260:in `call'
…/new_relic/agent/instrumentation/middleware_tracing.rb:  100:in `call'
…pack-7.0.3.1/lib/action_dispatch/middleware/cookies.rb:  697:in `call'
…/new_relic/agent/instrumentation/middleware_tracing.rb:  100:in `call'
…ck-7.0.3.1/lib/action_dispatch/middleware/callbacks.rb:   27:in `block in call'
…/activesupport-7.0.3.1/lib/active_support/callbacks.rb:   99:in `run_callbacks'
…ck-7.0.3.1/lib/action_dispatch/middleware/callbacks.rb:   26:in `call'
…/new_relic/agent/instrumentation/middleware_tracing.rb:  100:in `call'
…3.1/lib/action_dispatch/middleware/debug_exceptions.rb:   28:in `call'
…/new_relic/agent/instrumentation/middleware_tracing.rb:  100:in `call'
<truncated 15 additional frames>
…k-7.0.3.1/lib/action_dispatch/middleware/request_id.rb:   26:in `call'
…/new_relic/agent/instrumentation/middleware_tracing.rb:  100:in `call'
…ruby/3.1.0/gems/rack-2.2.4/lib/rack/method_override.rb:   24:in `call'
…/new_relic/agent/instrumentation/middleware_tracing.rb:  100:in `call'
…pp-20.1.1/lib/shopify_app/middleware/jwt_middleware.rb:   24:in `call_next'
…pp-20.1.1/lib/shopify_app/middleware/jwt_middleware.rb:   18:in `call'
…/new_relic/agent/instrumentation/middleware_tracing.rb:  100:in `call'
…/bundle/ruby/3.1.0/gems/rack-2.2.4/lib/rack/runtime.rb:   22:in `call'
…/new_relic/agent/instrumentation/middleware_tracing.rb:  100:in `call'
…ack-7.0.3.1/lib/action_dispatch/middleware/executor.rb:   14:in `call'
…/new_relic/agent/instrumentation/middleware_tracing.rb:  100:in `call'
…npack-7.0.3.1/lib/action_dispatch/middleware/static.rb:   23:in `call'
…/new_relic/agent/instrumentation/middleware_tracing.rb:  100:in `call'
…bundle/ruby/3.1.0/gems/rack-2.2.4/lib/rack/sendfile.rb:  110:in `call'
…/new_relic/agent/instrumentation/middleware_tracing.rb:  100:in `call'
…1/lib/action_dispatch/middleware/host_authorization.rb:  131:in `call'
…/new_relic/agent/instrumentation/middleware_tracing.rb:  100:in `call'
…e/ruby/3.1.0/gems/railties-7.0.3.1/lib/rails/engine.rb:  530:in `call'
…/new_relic/agent/instrumentation/middleware_tracing.rb:  100:in `call'
…e/ruby/3.1.0/gems/puma-5.6.5/lib/puma/configuration.rb:  252:in `call'
…/bundle/ruby/3.1.0/gems/puma-5.6.5/lib/puma/request.rb:   77:in `block in handle_request'
…dle/ruby/3.1.0/gems/puma-5.6.5/lib/puma/thread_pool.rb:  340:in `with_force_shutdown'
…/bundle/ruby/3.1.0/gems/puma-5.6.5/lib/puma/request.rb:   76:in `handle_request'
…r/bundle/ruby/3.1.0/gems/puma-5.6.5/lib/puma/server.rb:  443:in `process_client'
…dle/ruby/3.1.0/gems/puma-5.6.5/lib/puma/thread_pool.rb:  147:in `block in spawn_thread'

Stack trace for ShopifyAPI::Errors::InvalidJwtTokenError

ShopifyAPI::Errors::InvalidJwtTokenError: Failed to parse session token '<the JWT token>'
…shopify_api-11.1.0/lib/shopify_api/auth/jwt_payload.rb:   79:in `rescue in decode_token'
…shopify_api-11.1.0/lib/shopify_api/auth/jwt_payload.rb:   75:in `decode_token'
…10451/lib/types/private/methods/call_validation_2_7.rb:  764:in `bind_call'
…10451/lib/types/private/methods/call_validation_2_7.rb:  764:in `block in create_validator_method_medium2'
…shopify_api-11.1.0/lib/shopify_api/auth/jwt_payload.rb:   20:in `initialize'
…10451/lib/types/private/methods/call_validation_2_7.rb:  424:in `bind_call'
…10451/lib/types/private/methods/call_validation_2_7.rb:  424:in `block in create_validator_procedure_fast1'
…ib/shopify_app/controller_concerns/login_protection.rb:   83:in `new'
…ib/shopify_app/controller_concerns/login_protection.rb:   83:in `add_top_level_redirection_headers'
…ib/shopify_app/controller_concerns/login_protection.rb:  111:in `redirect_to_login'
…ib/shopify_app/controller_concerns/login_protection.rb:   25:in `activate_shopify_session'
…/activesupport-7.0.3.1/lib/active_support/callbacks.rb:  127:in `block in run_callbacks'
…0/gems/actiontext-7.0.3.1/lib/action_text/rendering.rb:   20:in `with_renderer'
….1.0/gems/actiontext-7.0.3.1/lib/action_text/engine.rb:   69:in `block (4 levels) in <class
…/activesupport-7.0.3.1/lib/active_support/callbacks.rb:  127:in `instance_exec'
…/activesupport-7.0.3.1/lib/active_support/callbacks.rb:  127:in `block in run_callbacks'
…/activesupport-7.0.3.1/lib/active_support/callbacks.rb:  138:in `run_callbacks'
…ctionpack-7.0.3.1/lib/abstract_controller/callbacks.rb:  233:in `process_action'
…tionpack-7.0.3.1/lib/action_controller/metal/rescue.rb:   22:in `process_action'
…7.0.3.1/lib/action_controller/metal/instrumentation.rb:   67:in `block in process_action'
…ivesupport-7.0.3.1/lib/active_support/notifications.rb:  206:in `block in instrument'
…0.3.1/lib/active_support/notifications/instrumenter.rb:   24:in `instrument'
…ivesupport-7.0.3.1/lib/active_support/notifications.rb:  206:in `instrument'
…7.0.3.1/lib/action_controller/metal/instrumentation.rb:   66:in `process_action'
…-7.0.3.1/lib/action_controller/metal/params_wrapper.rb:  259:in `process_action'
<truncated 56 additional frames>
…k-7.0.3.1/lib/action_dispatch/middleware/request_id.rb:   26:in `call'
…/new_relic/agent/instrumentation/middleware_tracing.rb:  100:in `call'
…ruby/3.1.0/gems/rack-2.2.4/lib/rack/method_override.rb:   24:in `call'
…/new_relic/agent/instrumentation/middleware_tracing.rb:  100:in `call'
…pp-20.1.1/lib/shopify_app/middleware/jwt_middleware.rb:   24:in `call_next'
…pp-20.1.1/lib/shopify_app/middleware/jwt_middleware.rb:   18:in `call'
…/new_relic/agent/instrumentation/middleware_tracing.rb:  100:in `call'
…/bundle/ruby/3.1.0/gems/rack-2.2.4/lib/rack/runtime.rb:   22:in `call'
…/new_relic/agent/instrumentation/middleware_tracing.rb:  100:in `call'
…ack-7.0.3.1/lib/action_dispatch/middleware/executor.rb:   14:in `call'
…/new_relic/agent/instrumentation/middleware_tracing.rb:  100:in `call'
…npack-7.0.3.1/lib/action_dispatch/middleware/static.rb:   23:in `call'
…/new_relic/agent/instrumentation/middleware_tracing.rb:  100:in `call'
…bundle/ruby/3.1.0/gems/rack-2.2.4/lib/rack/sendfile.rb:  110:in `call'
…/new_relic/agent/instrumentation/middleware_tracing.rb:  100:in `call'
…1/lib/action_dispatch/middleware/host_authorization.rb:  131:in `call'
…/new_relic/agent/instrumentation/middleware_tracing.rb:  100:in `call'
…e/ruby/3.1.0/gems/railties-7.0.3.1/lib/rails/engine.rb:  530:in `call'
…/new_relic/agent/instrumentation/middleware_tracing.rb:  100:in `call'
…e/ruby/3.1.0/gems/puma-5.6.5/lib/puma/configuration.rb:  252:in `call'
…/bundle/ruby/3.1.0/gems/puma-5.6.5/lib/puma/request.rb:   77:in `block in handle_request'
…dle/ruby/3.1.0/gems/puma-5.6.5/lib/puma/thread_pool.rb:  340:in `with_force_shutdown'
…/bundle/ruby/3.1.0/gems/puma-5.6.5/lib/puma/request.rb:   76:in `handle_request'
…r/bundle/ruby/3.1.0/gems/puma-5.6.5/lib/puma/server.rb:  443:in `process_client'
…dle/ruby/3.1.0/gems/puma-5.6.5/lib/puma/thread_pool.rb:  147:in `block in spawn_thread'

Security

• I have redacted any private information from my logs or code snippets.

[netwire88]

There are lots of bugs with the latest release (v21.1.1), we are noticing many and have started trying to document them via #1539

For example, calling current_shopify_domain in LoginProtection causes:

uninitialized constant ShopifyAPI::Auth::Oauth::SessionCookie

        cookie_name = ShopifyAPI::Auth::Oauth::SessionCookie::SESSION_COOKIE_NAME
                                             ^^^^^^^^^^^^^^^
Did you mean?  ShopifyAPI::Auth::Session

[nelsonwittwer]

We appreciate the feedback on this! We will add this to our list for this week

[nelsonwittwer]

Can you confirm what version you are upgrading from?

[dansundy]

Thanks for looking into it @nelsonwittwer.

This was a big update that spanned multiple versions but I believe the last version of the shopify_app gem that we had in production was 18.1.2. Sorry that I can't be more granular about where this started popping up.

[nelsonwittwer]

v18 to v19+ had a few breaking changes that are hard to navigate that our docs didn't do a good enough job outlining how to upgrade.

This week I'm specifically working on updating documentation for that path. Hopefully that will help you out; if it doesn't, I'd love to dive in more as I'm sure other developers are having similar problems.

[netwire88]

Thanks @nelsonwittwer , any updated documentation regarding upgrade path will be helpful - especially about how we should use shopify_app for deep linking into the app (app uses Turbolinks).

[uurcank]

Same error is happening for me. current_shopify_store is not set and it breaks the oauth flow.

[dansundy]

I suspected this didn't have anything to do with the version bump and can confirm. I created a reduced test case here: https://github.com/dansundy/app_gem_error_test

This was created with a freshly generated app from the shopify_app gem. Version 21.2.0. Nothing has been added except:

1. A few lines of code to attempt to rescue the error in the AuthenticatedController
2. An adjustment to the token to invalidate it in app/views/home/index.html.erb
3. A few lines to output the response status in index.html.erb

I hope that helps @nelsonwittwer. Let me know if you have any problems with this

[gcaprio]

I just upgraded an app from 19.1.1 to 20.2.0 and am not receiving this error with almost every call:

2022-11-15T00:24:05.549870+00:00 app[web.1]: [9c955853-e457-4e67-b41e-977884af2451] ShopifyApp::ShopifyDomainNotFound (ShopifyApp::ShopifyDomainNotFound):
2022-11-15T00:24:05.549871+00:00 app[web.1]: [9c955853-e457-4e67-b41e-977884af2451]
2022-11-15T00:24:05.549872+00:00 app[web.1]: [9c955853-e457-4e67-b41e-977884af2451] shopify_app (20.2.0) lib/shopify_app/controller_concerns/login_protection.rb:193:in current_shopify_domain' 2022-11-15T00:24:05.549873+00:00 app[web.1]: [9c955853-e457-4e67-b41e-977884af2451] shopify_app (20.2.0) lib/shopify_app/controller_concerns/frame_ancestors.rb:10:in block (3 levels) in module:FrameAncestors'

Any progress or updates on a fix? If I'm following this is a JWT issue, so should the stale tokens just expire out after a while ?

[nelsonwittwer]

turns out this problem was masking a few other problems 🤦 . I've got a fix proposed with #1580 that will address the 500 responses and return an expected 401.

[nelsonwittwer]

Shout out to @dansundy for creating an environment to reproduce the issue! I request the highest of fives! ✋ 5️⃣