app_not_installed error right after app uninstallation

[mironov]

Issue summary

Before opening this issue, I have:

• Upgraded to the latest version of the package
  • shopify_api version: 14.3.0
  • Ruby version: 3.3.1
  • Operating system: linux
• Set log_level: :debug in my configuration, if applicable
• Found a reliable way to reproduce the problem that indicates it's a problem with the package
• Looked for similar issues in this repository
• Checked that this isn't an issue with a Shopify API
  • If it is, please create a post in the Shopify community forums or report it to Shopify Partner Support

I believe this has started after switching to the new token exchange API.

When user uninstalls our app, that executes a background job that destroys the shop record. Shortly after, a request to our web app comes with the token of that shop:

/?embedded=1&hmac=[FILTERED]&host=[FILTERED]&id_token=[FILTERED]&locale=en-IN&session=[FILTERED]&shop=[FILTERED]&timestamp=1717860610

That results in the following error:

A 400 error (ShopifyAPI::Errors::HttpResponseError) occurred during the token exchange. Response: {"error"=>"app_not_installed", "error_description"=>"The application is not installed on this shop."}

I believe it is happening on the following lines: https://github.com/Shopify/shopify-api-ruby/blob/main/lib/shopify_api/auth/token_exchange.rb#L53-L68

However, it is not handled because error is not invalid_subject_token but app_not_installed. The error bubbles up to our controller.

If that is helpful, here is the id of the error: edf7bd5b-4f17-4bf8-a35e-0bba570eb2bd-1717860642.

Expected behavior

I think the error should be handled gracefully, and InvalidJwtTokenError should be bubbled up instead.

Actual behavior

Error is not handled.

Steps to reproduce the problem

I can't reliably reproduce this but from the logs I see the same order of steps is happening.

1. Store deletes the app
2. A new request is made on behalf of the app

Debug logs

2024-06-08T15:30:32.075385759Z stdout F 2024-06-08T15:30:32.075Z pid=1 tid=mld class=AppUninstalledJob jid=6dc42735a3e7905cbe9b146b INFO: start
2024-06-08T15:30:32.791104951Z stdout F 2024-06-08T15:30:32.790Z pid=1 tid=mld class=AppUninstalledJob jid=6dc42735a3e7905cbe9b146b INFO: AppUninstalledJob started for shop '[FILTERED]'
2024-06-08T15:30:32.82917927Z stdout F 2024-06-08T15:30:32.828Z pid=1 tid=mld class=AppUninstalledJob jid=6dc42735a3e7905cbe9b146b elapsed=0.754 INFO: done

2024-06-08T15:30:42.57039813Z stdout F I, [2024-06-08T15:30:42.570193 #1]  INFO -- : [90cf4e4db7f98c7a800c914cf24f27f2] Started GET "/?embedded=1&hmac=[FILTERED]&host=[FILTERED]&id_token=[FILTERED]&locale=en-IN&session=[FILTERED]&shop=[FILTERED]&timestamp=1717860610" for 10.244.0.236 at 2024-06-08 15:30:42 +0000
2024-06-08T15:30:42.571995737Z stdout F I, [2024-06-08T15:30:42.571796 #1]  INFO -- : [90cf4e4db7f98c7a800c914cf24f27f2] Processing by HomeController#index as HTML
2024-06-08T15:30:42.572186116Z stdout F I, [2024-06-08T15:30:42.571911 #1]  INFO -- : [90cf4e4db7f98c7a800c914cf24f27f2]   Parameters: {"embedded"=>"1", "hmac"=>"[FILTERED]", "host"=>"[FILTERED]", "id_token"=>"[FILTERED]", "locale"=>"en-IN", "session"=>"[FILTERED]", "shop"=>"[FILTERED]", "timestamp"=>"1717860610"}
2024-06-08T15:30:42.575700054Z stdout F I, [2024-06-08T15:30:42.575504 #1]  INFO -- : [90cf4e4db7f98c7a800c914cf24f27f2] [ ShopifyApp | INFO | Shop Not Found ] Performing Token Exchange for [[FILTERED]] - (Offline)
2024-06-08T15:30:42.731111381Z stdout F E, [2024-06-08T15:30:42.730768 #1] ERROR -- : [90cf4e4db7f98c7a800c914cf24f27f2] [ ShopifyApp | ERROR | Shop Not Found ] A 400 error (ShopifyAPI::Errors::HttpResponseError) occurred during the token exchange. Response: {"error"=>"app_not_installed", "error_description"=>"The application is not installed on this shop."}
2024-06-08T15:30:42.733025618Z stdout F E, [2024-06-08T15:30:42.732248 #1] ERROR -- : [90cf4e4db7f98c7a800c914cf24f27f2] {"error_reference":"If you report this error, please include this id: edf7bd5b-4f17-4bf8-a35e-0bba570eb2bd-1717860642."}
2024-06-08T15:30:43.024100912Z stdout F I, [2024-06-08T15:30:43.023860 #1]  INFO -- : [90cf4e4db7f98c7a800c914cf24f27f2] Completed 400 Bad Request in 451ms (Views: 1.9ms | ActiveRecord: 0.7ms | Allocations: 23613)

[sle-c]

Hi @mironov

Thank you for reporting this issue. I'm able to reproduce the issue by uninstalling the app and and close the setting page.

We'll look more into this issue to figure out why the page doesn't navigate away after app uninstallation.

Si

[zzooeeyy]

Hi @mironov, thank you for raising this issue. We have applied a fix and this problem should no longer occur..

[mironov]

@zzooeeyy @sle-c Thank you for the fix!

[mironov]

@zzooeeyy I just saw another instance of this error in our logs:

"2024-10-06T00:54:17.169956075Z stdout F I, [2024-10-06T00:54:17.169687 #1]  INFO -- : [aed6cf6b720f210d85d1e4a751af2f42] [ ShopifyApp | INFO | Shop Not Found ] Performing Token Exchange for [REDACTED.myshopify.com] - (Offline)"
"2024-10-06T00:54:17.322243784Z stdout F E, [2024-10-06T00:54:17.321943 #1] ERROR -- : [aed6cf6b720f210d85d1e4a751af2f42] [ ShopifyApp | ERROR | Shop Not Found ] A 400 error (ShopifyAPI::Errors::HttpResponseError) occurred during the token exchange. Response: {\"error\"=>\"app_not_installed\", \"error_description\"=>\"The application is not installed on this shop.\"}"
"2024-10-06T00:54:17.323561812Z stdout F E, [2024-10-06T00:54:17.323083 #1] ERROR -- : [aed6cf6b720f210d85d1e4a751af2f42] {\"error_reference\":\"If you report this error, please include this id: 0730c855-ff3a-4066-80c1-2c18096ca941-1728176057.\"}"

Could it be that the issue is not fully resolved?
I'm using 14.5.0