Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Incorrect scope written to User session repository #1848

Open
5 tasks done
fairknowe opened this issue May 15, 2024 · 1 comment
Open
5 tasks done

Incorrect scope written to User session repository #1848

fairknowe opened this issue May 15, 2024 · 1 comment

Comments

@fairknowe
Copy link

Issue summary

Before opening this issue, I have:

  • Upgraded to the latest version of the package
    • shopify_app version: 22.2.1
    • Ruby version: 3.3.0
    • Operating system: Debian 12
  • 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

The demonstration app used for this issue report is based on the Ruby Shopify App Template, where sample products can be created with the click of a button.

The requested App installation scope is write_products:

# shopify.app.toml
# This file stores configurations for your Shopify app.
scopes = "write_products"

Two users are considered, the Store (Account) owner, and a Staff person who has only 'View' permissions on Products.

Expected behavior

Since the Store owner has full permissions on Products, the User session repository scope should be 'write_products`. However, the Staff person with limited 'View' permissions should only have 'read_products' in their session repository scope.

Actual behavior

Querying the User session repository scopes for the Store owner returns 'write_products', as expected. Querying the User session repository scopes for the Staff person also returns 'write_products', which is not expected.

The Store owner is able to generate Products through the App without error. However, the Staff person cannot, indicating the user's 'View' permissions are enforced on Shopify's backend.

The scene shots of the browser logs, below, illustrate the outcomes.

Store owner:
Screenshot 2024-05-15 at 9 56 00 AM

Staff person:
Screenshot 2024-05-15 at 9 56 29 AM

Steps to reproduce the problem

I can provide the demo app code if necessary.

Debug logs

// Rails development log for issue demonstration
2024-05-15 10:22:38 -0400 : INFO : Started POST "/api/auth" for 174.92.27.151 at 2024-05-15 10:22:38 -0400
2024-05-15 10:22:38 -0400 : INFO : Processing by ShopifyApp::SessionsController#create as HTML
2024-05-15 10:22:38 -0400 : INFO :   Parameters: {"authenticity_token"=>"[FILTERED]", "shop"=>"got-any-store.myshopify.com"}
2024-05-15 10:22:38 -0400 : DEBUG : [ ShopifyApp | DEBUG | Shop Not Found ] Starting OAuth - Redirecting to begin auth
2024-05-15 10:22:38 -0400 : DEBUG : [ ShopifyApp | DEBUG | Shop Not Found ] Embedded URL within / authenticate
2024-05-15 10:22:38 -0400 : DEBUG : [ ShopifyApp | DEBUG | Shop Not Found ] Starting OAuth with the following callback URL: api/auth/callback
2024-05-15 10:22:38 -0400 : DEBUG :   �[1m�[36mShop Load (5.2ms)�[0m  �[1m�[34mSELECT "shops".* FROM "shops" WHERE "shops"."shopify_domain" = $1 LIMIT $2�[0m  [["shopify_domain", "got-any-store.myshopify.com"], ["LIMIT", 1]]
2024-05-15 10:22:38 -0400 : DEBUG : [ ShopifyApp | DEBUG | Shop Not Found ] Redirecting to auth_route - https://got-any-store.myshopify.com/admin/oauth/authorize?client_id=16736ca5957faf119fef3f77dd8a14f5&scope=write_products&redirect_uri=https%3A%2F%2Ffki.ngrok.io%2Fapi%2Fauth%2Fcallback&state=12GlaJHMYD2PmvB&grant_options%5B%5D=
2024-05-15 10:22:38 -0400 : INFO : Redirected to https://got-any-store.myshopify.com/admin/oauth/authorize?client_id=16736ca5957faf119fef3f77dd8a14f5&scope=write_products&redirect_uri=https%3A%2F%2Ffki.ngrok.io%2Fapi%2Fauth%2Fcallback&state=12GlaJHMYD2PmvB&grant_options%5B%5D=
2024-05-15 10:22:38 -0400 : INFO : Completed 302 Found in 296ms (ActiveRecord: 58.2ms | Allocations: 88746)


2024-05-15 10:22:46 -0400 : INFO : Started GET "/api/auth/callback?code=f6e3ba2e5728d568c72a239891b7b827&hmac=dea956a29ed8e840d94767baff70130cf0dbebf3c4ac406b662282ae75a69c1d&host=YWRtaW4uc2hvcGlmeS5jb20vc3RvcmUvZ290LWFueS1zdG9yZQ&shop=got-any-store.myshopify.com&state=12GlaJHMYD2PmvB&timestamp=1715782966" for 174.92.27.151 at 2024-05-15 10:22:46 -0400
2024-05-15 10:22:46 -0400 : INFO : Processing by ShopifyApp::CallbackController#callback as HTML
2024-05-15 10:22:46 -0400 : INFO :   Parameters: {"code"=>"f6e3ba2e5728d568c72a239891b7b827", "hmac"=>"dea956a29ed8e840d94767baff70130cf0dbebf3c4ac406b662282ae75a69c1d", "host"=>"YWRtaW4uc2hvcGlmeS5jb20vc3RvcmUvZ290LWFueS1zdG9yZQ", "shop"=>"got-any-store.myshopify.com", "state"=>"12GlaJHMYD2PmvB", "timestamp"=>"1715782966"}
2024-05-15 10:22:47 -0400 : DEBUG : [ ShopifyApp | DEBUG | Shop Not Found ] Storing offline store session - session: offline_got-any-store.myshopify.com
2024-05-15 10:22:47 -0400 : DEBUG :   �[1m�[36mShop Load (5.3ms)�[0m  �[1m�[34mSELECT "shops".* FROM "shops" WHERE "shops"."shopify_domain" = $1 LIMIT $2�[0m  [["shopify_domain", "got-any-store.myshopify.com"], ["LIMIT", 1]]
2024-05-15 10:22:47 -0400 : DEBUG :   �[1m�[36mTRANSACTION (5.1ms)�[0m  �[1m�[35mBEGIN�[0m
2024-05-15 10:22:47 -0400 : DEBUG :   �[1m�[36mShop Exists? (4.3ms)�[0m  �[1m�[34mSELECT 1 AS one FROM "shops" WHERE LOWER("shops"."shopify_domain") = LOWER($1) LIMIT $2�[0m  [["shopify_domain", "got-any-store.myshopify.com"], ["LIMIT", 1]]
2024-05-15 10:22:47 -0400 : DEBUG :   �[1m�[36mShop Create (8.2ms)�[0m  �[1m�[32mINSERT INTO "shops" ("shopify_domain", "shopify_token", "created_at", "updated_at", "access_scopes") VALUES ($1, $2, $3, $4, $5) RETURNING "id"�[0m  [["shopify_domain", "got-any-store.myshopify.com"], ["shopify_token", "[FILTERED]"], ["created_at", "2024-05-15 14:22:47.257198"], ["updated_at", "2024-05-15 14:22:47.257198"], ["access_scopes", "write_products"]]
2024-05-15 10:22:47 -0400 : DEBUG :   �[1m�[36mTRANSACTION (3.6ms)�[0m  �[1m�[35mCOMMIT�[0m
2024-05-15 10:22:47 -0400 : DEBUG : [ ShopifyApp | DEBUG | Shop Not Found ] Saving Shopify user ID to cookie
2024-05-15 10:22:47 -0400 : DEBUG :   �[1m�[36mUser Load (5.9ms)�[0m  �[1m�[34mSELECT "users".* FROM "users" WHERE "users"."shopify_user_id" = $1 LIMIT $2�[0m  [["shopify_user_id", 77780451571], ["LIMIT", 1]]
2024-05-15 10:22:47 -0400 : INFO : Redirected to https://fki.ngrok.io/api/auth?host=YWRtaW4uc2hvcGlmeS5jb20vc3RvcmUvZ290LWFueS1zdG9yZQ&shop=got-any-store.myshopify.com
2024-05-15 10:22:47 -0400 : INFO : Completed 302 Found in 539ms (ActiveRecord: 63.9ms | Allocations: 27426)


2024-05-15 10:22:47 -0400 : INFO : Started GET "/api/auth?host=YWRtaW4uc2hvcGlmeS5jb20vc3RvcmUvZ290LWFueS1zdG9yZQ&shop=got-any-store.myshopify.com" for 174.92.27.151 at 2024-05-15 10:22:47 -0400
2024-05-15 10:22:47 -0400 : INFO : Processing by ShopifyApp::SessionsController#new as HTML
2024-05-15 10:22:47 -0400 : INFO :   Parameters: {"host"=>"YWRtaW4uc2hvcGlmeS5jb20vc3RvcmUvZ290LWFueS1zdG9yZQ", "shop"=>"got-any-store.myshopify.com"}
2024-05-15 10:22:47 -0400 : DEBUG : [ ShopifyApp | DEBUG | Shop Not Found ] Starting OAuth - Redirecting to begin auth
2024-05-15 10:22:47 -0400 : DEBUG : [ ShopifyApp | DEBUG | Shop Not Found ] Embedded URL within / authenticate
2024-05-15 10:22:47 -0400 : DEBUG : [ ShopifyApp | DEBUG | Shop Not Found ] Starting OAuth with the following callback URL: api/auth/callback
2024-05-15 10:22:47 -0400 : DEBUG :   �[1m�[36mShop Load (6.6ms)�[0m  �[1m�[34mSELECT "shops".* FROM "shops" WHERE "shops"."shopify_domain" = $1 LIMIT $2�[0m  [["shopify_domain", "got-any-store.myshopify.com"], ["LIMIT", 1]]
2024-05-15 10:22:47 -0400 : DEBUG :   �[1m�[36mCACHE Shop Load (0.0ms)�[0m  �[1m�[34mSELECT "shops".* FROM "shops" WHERE "shops"."shopify_domain" = $1 LIMIT $2�[0m  [["shopify_domain", "got-any-store.myshopify.com"], ["LIMIT", 1]]
2024-05-15 10:22:47 -0400 : DEBUG :   �[1m�[36mCACHE Shop Load (0.0ms)�[0m  �[1m�[34mSELECT "shops".* FROM "shops" WHERE "shops"."shopify_domain" = $1 LIMIT $2�[0m  [["shopify_domain", "got-any-store.myshopify.com"], ["LIMIT", 1]]
2024-05-15 10:22:47 -0400 : DEBUG : [ ShopifyApp | DEBUG | Shop Not Found ] Redirecting to auth_route - https://got-any-store.myshopify.com/admin/oauth/authorize?client_id=16736ca5957faf119fef3f77dd8a14f5&scope=write_products&redirect_uri=https%3A%2F%2Ffki.ngrok.io%2Fapi%2Fauth%2Fcallback&state=OydyfRptuHMlIEh&grant_options%5B%5D=per-user
2024-05-15 10:22:47 -0400 : INFO : Redirected to https://got-any-store.myshopify.com/admin/oauth/authorize?client_id=16736ca5957faf119fef3f77dd8a14f5&scope=write_products&redirect_uri=https%3A%2F%2Ffki.ngrok.io%2Fapi%2Fauth%2Fcallback&state=OydyfRptuHMlIEh&grant_options%5B%5D=per-user
2024-05-15 10:22:47 -0400 : INFO : Completed 302 Found in 78ms (ActiveRecord: 6.6ms | Allocations: 4698)


2024-05-15 10:22:48 -0400 : INFO : Started GET "/api/auth/callback?code=758996e0561c97785c254801dbba47a0&hmac=5dd7a2be794d06b49da54b0cf595957538e11cbed30dfea46a4aca3e2e09d8f4&host=YWRtaW4uc2hvcGlmeS5jb20vc3RvcmUvZ290LWFueS1zdG9yZQ&shop=got-any-store.myshopify.com&state=OydyfRptuHMlIEh&timestamp=1715782968" for 174.92.27.151 at 2024-05-15 10:22:48 -0400
2024-05-15 10:22:48 -0400 : INFO : Processing by ShopifyApp::CallbackController#callback as HTML
2024-05-15 10:22:48 -0400 : INFO :   Parameters: {"code"=>"758996e0561c97785c254801dbba47a0", "hmac"=>"5dd7a2be794d06b49da54b0cf595957538e11cbed30dfea46a4aca3e2e09d8f4", "host"=>"YWRtaW4uc2hvcGlmeS5jb20vc3RvcmUvZ290LWFueS1zdG9yZQ", "shop"=>"got-any-store.myshopify.com", "state"=>"OydyfRptuHMlIEh", "timestamp"=>"1715782968"}
2024-05-15 10:22:48 -0400 : DEBUG : [ ShopifyApp | DEBUG | Shop Not Found ] Storing online user session - session: got-any-store.myshopify.com_77780451571
2024-05-15 10:22:48 -0400 : DEBUG :   �[1m�[36mUser Load (5.6ms)�[0m  �[1m�[34mSELECT "users".* FROM "users" WHERE "users"."shopify_user_id" = $1 LIMIT $2�[0m  [["shopify_user_id", 77780451571], ["LIMIT", 1]]
2024-05-15 10:22:48 -0400 : DEBUG :   �[1m�[36mTRANSACTION (6.5ms)�[0m  �[1m�[35mBEGIN�[0m
2024-05-15 10:22:48 -0400 : DEBUG :   �[1m�[36mUser Create (19.7ms)�[0m  �[1m�[32mINSERT INTO "users" ("shopify_user_id", "shopify_domain", "shopify_token", "created_at", "updated_at", "access_scopes", "expires_at") VALUES ($1, $2, $3, $4, $5, $6, $7) RETURNING "id"�[0m  [["shopify_user_id", 77780451571], ["shopify_domain", "got-any-store.myshopify.com"], ["shopify_token", "[FILTERED]"], ["created_at", "2024-05-15 14:22:48.644984"], ["updated_at", "2024-05-15 14:22:48.644984"], ["access_scopes", "write_products"], ["expires_at", "2024-05-16 14:22:47.604496"]]
2024-05-15 10:22:48 -0400 : DEBUG :   �[1m�[36mTRANSACTION (5.7ms)�[0m  �[1m�[35mCOMMIT�[0m
2024-05-15 10:22:48 -0400 : DEBUG : [ ShopifyApp | DEBUG | Shop Not Found ] Saving Shopify user ID to cookie
2024-05-15 10:22:48 -0400 : DEBUG :   �[1m�[36mShop Load (6.9ms)�[0m  �[1m�[34mSELECT "shops".* FROM "shops" WHERE "shops"."shopify_domain" = $1 LIMIT $2�[0m  [["shopify_domain", "got-any-store.myshopify.com"], ["LIMIT", 1]]
2024-05-15 10:22:48 -0400 : INFO : [ActiveJob] Enqueued ShopifyApp::WebhooksManagerJob (Job ID: d7f94730-0f01-4af4-9800-3c832bf633ed) to Async(webhooks_manager)
2024-05-15 10:22:48 -0400 : INFO : Redirected to https://admin.shopify.com/store/got-any-store/apps/16736ca5957faf119fef3f77dd8a14f5
2024-05-15 10:22:48 -0400 : INFO : Completed 302 Found in 334ms (ActiveRecord: 50.9ms | Allocations: 13942)


2024-05-15 10:22:48 -0400 : INFO : [ActiveJob] [ShopifyApp::WebhooksManagerJob] [d7f94730-0f01-4af4-9800-3c832bf633ed] Performing ShopifyApp::WebhooksManagerJob (Job ID: d7f94730-0f01-4af4-9800-3c832bf633ed) from Async(webhooks_manager) enqueued at 2024-05-15T14:22:48.698462066Z
2024-05-15 10:22:48 -0400 : DEBUG : [ActiveJob] [ShopifyApp::WebhooksManagerJob] [d7f94730-0f01-4af4-9800-3c832bf633ed] [ ShopifyApp | DEBUG | got-any-store.myshopify.com ] Creating webhooks [{:topic=>"app/uninstalled", :address=>"api/toy_webhooks/app_uninstalled"}, {:topic=>"products/create", :address=>"api/toy_webhooks/app_uninstalled"}, {:topic=>"products/update", :address=>"api/toy_webhooks/app_uninstalled"}, {:topic=>"products/delete", :address=>"api/toy_webhooks/app_uninstalled"}, {:topic=>"shop/redact", :address=>"api/webhooks/shop_redact"}, {:topic=>"customers/redact", :address=>"api/webhooks/customers_redact"}, {:topic=>"customers/data_request", :address=>"api/webhooks/customers_data_request"}]
2024-05-15 10:22:51 -0400 : INFO : Started GET "/?embedded=1&hmac=386130feb6504aa5257b650791535f125610a383fd7181acd8920cdb21a68709&host=YWRtaW4uc2hvcGlmeS5jb20vc3RvcmUvZ290LWFueS1zdG9yZQ&id_token=[FILTERED]&locale=en-CA&session=ac07244e9939d5ac6d2e0e411b1f1044263c48220f29b0b156b06f0761a7138d&shop=got-any-store.myshopify.com&timestamp=1715782970" for 174.92.27.151 at 2024-05-15 10:22:51 -0400
2024-05-15 10:22:51 -0400 : INFO : Processing by HomeController#index as HTML
2024-05-15 10:22:51 -0400 : INFO :   Parameters: {"embedded"=>"1", "hmac"=>"386130feb6504aa5257b650791535f125610a383fd7181acd8920cdb21a68709", "host"=>"YWRtaW4uc2hvcGlmeS5jb20vc3RvcmUvZ290LWFueS1zdG9yZQ", "id_token"=>"[FILTERED]", "locale"=>"en-CA", "session"=>"ac07244e9939d5ac6d2e0e411b1f1044263c48220f29b0b156b06f0761a7138d", "shop"=>"got-any-store.myshopify.com", "timestamp"=>"1715782970"}
2024-05-15 10:22:51 -0400 : DEBUG :   �[1m�[36mShop Load (12.0ms)�[0m  �[1m�[34mSELECT "shops".* FROM "shops" WHERE "shops"."shopify_domain" = $1 LIMIT $2�[0m  [["shopify_domain", "got-any-store.myshopify.com"], ["LIMIT", 1]]
2024-05-15 10:22:51 -0400 : DEBUG :   �[1m�[36mCACHE Shop Load (0.0ms)�[0m  �[1m�[34mSELECT "shops".* FROM "shops" WHERE "shops"."shopify_domain" = $1 LIMIT $2�[0m  [["shopify_domain", "got-any-store.myshopify.com"], ["LIMIT", 1]]
2024-05-15 10:22:51 -0400 : INFO : [HomeController] - Line 29: in HomeController#index. shopify_user_id: 77780451571
2024-05-15 10:22:51 -0400 : DEBUG :   Rendering text template
2024-05-15 10:22:51 -0400 : INFO :   Rendered text template (Duration: 0.0ms | Allocations: 3)
2024-05-15 10:22:51 -0400 : INFO : Completed 200 OK in 40ms (Views: 3.2ms | ActiveRecord: 12.0ms | Allocations: 4850)


2024-05-15 10:22:51 -0400 : INFO : [ActiveJob] [ShopifyApp::WebhooksManagerJob] [d7f94730-0f01-4af4-9800-3c832bf633ed] Performed ShopifyApp::WebhooksManagerJob (Job ID: d7f94730-0f01-4af4-9800-3c832bf633ed) from Async(webhooks_manager) in 3136.51ms
2024-05-15 10:22:56 -0400 : INFO : Started GET "/api/products/count" for 174.92.27.151 at 2024-05-15 10:22:56 -0400
2024-05-15 10:22:56 -0400 : INFO : Started GET "/api/current/user" for 174.92.27.151 at 2024-05-15 10:22:56 -0400
2024-05-15 10:22:56 -0400 : INFO : Processing by ProductsController#count as */*
2024-05-15 10:22:56 -0400 : DEBUG : [ ShopifyApp | DEBUG | Shop Not Found ] Loading session by user_id - user: 77780451571
2024-05-15 10:22:56 -0400 : INFO : Processing by UserController#current as */*
2024-05-15 10:22:56 -0400 : DEBUG : [ ShopifyApp | DEBUG | Shop Not Found ] Loading session by user_id - user: 77780451571
2024-05-15 10:22:56 -0400 : DEBUG :   �[1m�[36mUser Load (18.8ms)�[0m  �[1m�[34mSELECT "users".* FROM "users" WHERE "users"."shopify_user_id" = $1 LIMIT $2�[0m  [["shopify_user_id", 77780451571], ["LIMIT", 1]]
2024-05-15 10:22:56 -0400 : DEBUG : [ ShopifyApp | DEBUG | Shop Not Found ] Activating Shopify session
2024-05-15 10:22:56 -0400 : DEBUG :   �[1m�[36mUser Load (3.4ms)�[0m  �[1m�[34mSELECT "users".* FROM "users" WHERE "users"."shopify_user_id" = $1 LIMIT $2�[0m  [["shopify_user_id", 77780451571], ["LIMIT", 1]]
2024-05-15 10:22:56 -0400 : DEBUG : [ ShopifyApp | DEBUG | Shop Not Found ] Activating Shopify session
2024-05-15 10:22:56 -0400 : INFO : [UserController] - Line 7: in UsersController#current. params: {"controller"=>"user", "action"=>"current"}
2024-05-15 10:22:56 -0400 : INFO : [UserController] - Line 10: in AuthenticatedController#current_user_id. current_shopify_session scope: write_products
2024-05-15 10:22:56 -0400 : INFO : [UserController] - Line 16: in AuthenticatedController#current_user_id. user_id: 77780451571
2024-05-15 10:22:56 -0400 : INFO : [UserController] - Line 17: in AuthenticatedController#current_user_id. associated_user_scope: write_products
2024-05-15 10:22:56 -0400 : INFO : [UserController] - Line 10: in UsersController#current. shopify_user_id: 77780451571
2024-05-15 10:22:56 -0400 : DEBUG :   �[1m�[36mUser Load (3.6ms)�[0m  �[1m�[34mSELECT "users".* FROM "users" WHERE "users"."shopify_user_id" = $1 LIMIT $2�[0m  [["shopify_user_id", 77780451571], ["LIMIT", 1]]
2024-05-15 10:22:56 -0400 : DEBUG :   ↳ app/controllers/user_controller.rb:11:in `current'
2024-05-15 10:22:56 -0400 : INFO : [UserController] - Line 12: in UsersController#current. user: #<User id: 1, shopify_user_id: 77780451571, shopify_domain: "got-any-store.myshopify.com", shopify_token: [FILTERED], created_at: "2024-05-15 10:22:48.644984000 -0400", updated_at: "2024-05-15 10:22:48.644984000 -0400", access_scopes: "write_products", expires_at: "2024-05-16 10:22:47.604496000 -0400">
2024-05-15 10:22:56 -0400 : DEBUG : [ ShopifyApp | DEBUG | got-any-store.myshopify.com ] Deactivating session
2024-05-15 10:22:56 -0400 : INFO : Completed 200 OK in 136ms (Views: 0.5ms | ActiveRecord: 44.7ms | Allocations: 7156)


2024-05-15 10:22:56 -0400 : INFO : [ ShopifyApp | INFO | Shop Not Found ] Installed store  - got-any-store.myshopify.com deduced from user session
2024-05-15 10:22:56 -0400 : DEBUG : [ ShopifyApp | DEBUG | got-any-store.myshopify.com ] Deactivating session
2024-05-15 10:22:56 -0400 : INFO : Completed 200 OK in 300ms (Views: 0.3ms | ActiveRecord: 18.7ms | Allocations: 11087)


2024-05-15 10:22:56 -0400 : INFO : [ ShopifyApp | INFO | Shop Not Found ] Installed store  - got-any-store.myshopify.com deduced from user session
2024-05-15 10:25:11 -0400 : INFO : Started GET "/?embedded=1&hmac=3f33e8d41d546290e34fb52629700374eeb6642abf54fb0ac5cbae149f114ed3&host=YWRtaW4uc2hvcGlmeS5jb20vc3RvcmUvZ290LWFueS1zdG9yZQ&id_token=[FILTERED]&locale=en-CA&session=55b5540252df0900b52784e1f6a1fada457a78da3046147b5d94c40c863fb73d&shop=got-any-store.myshopify.com&timestamp=1715783110" for 174.92.27.151 at 2024-05-15 10:25:11 -0400
2024-05-15 10:25:11 -0400 : INFO : Processing by HomeController#index as HTML
2024-05-15 10:25:11 -0400 : INFO :   Parameters: {"embedded"=>"1", "hmac"=>"3f33e8d41d546290e34fb52629700374eeb6642abf54fb0ac5cbae149f114ed3", "host"=>"YWRtaW4uc2hvcGlmeS5jb20vc3RvcmUvZ290LWFueS1zdG9yZQ", "id_token"=>"[FILTERED]", "locale"=>"en-CA", "session"=>"55b5540252df0900b52784e1f6a1fada457a78da3046147b5d94c40c863fb73d", "shop"=>"got-any-store.myshopify.com", "timestamp"=>"1715783110"}
2024-05-15 10:25:11 -0400 : DEBUG :   �[1m�[36mShop Load (6.7ms)�[0m  �[1m�[34mSELECT "shops".* FROM "shops" WHERE "shops"."shopify_domain" = $1 LIMIT $2�[0m  [["shopify_domain", "got-any-store.myshopify.com"], ["LIMIT", 1]]
2024-05-15 10:25:11 -0400 : DEBUG :   �[1m�[36mCACHE Shop Load (0.1ms)�[0m  �[1m�[34mSELECT "shops".* FROM "shops" WHERE "shops"."shopify_domain" = $1 LIMIT $2�[0m  [["shopify_domain", "got-any-store.myshopify.com"], ["LIMIT", 1]]
2024-05-15 10:25:11 -0400 : INFO : [HomeController] - Line 29: in HomeController#index. shopify_user_id: 89301123315
2024-05-15 10:25:11 -0400 : DEBUG :   Rendering text template
2024-05-15 10:25:11 -0400 : INFO :   Rendered text template (Duration: 0.0ms | Allocations: 1)
2024-05-15 10:25:11 -0400 : INFO : Completed 200 OK in 30ms (Views: 0.8ms | ActiveRecord: 6.7ms | Allocations: 3261)


2024-05-15 10:25:15 -0400 : INFO : Started GET "/api/products/count" for 174.92.27.151 at 2024-05-15 10:25:15 -0400
2024-05-15 10:25:15 -0400 : INFO : Started GET "/api/current/user" for 174.92.27.151 at 2024-05-15 10:25:15 -0400
2024-05-15 10:25:15 -0400 : INFO : Processing by ProductsController#count as */*
2024-05-15 10:25:15 -0400 : DEBUG : [ ShopifyApp | DEBUG | Shop Not Found ] Loading session by user_id - user: 89301123315
2024-05-15 10:25:15 -0400 : INFO : Processing by UserController#current as */*
2024-05-15 10:25:15 -0400 : DEBUG : [ ShopifyApp | DEBUG | Shop Not Found ] Loading session by user_id - user: 89301123315
2024-05-15 10:25:15 -0400 : DEBUG :   �[1m�[36mUser Load (2.2ms)�[0m  �[1m�[34mSELECT "users".* FROM "users" WHERE "users"."shopify_user_id" = $1 LIMIT $2�[0m  [["shopify_user_id", 89301123315], ["LIMIT", 1]]
2024-05-15 10:25:15 -0400 : DEBUG : [ ShopifyApp | DEBUG | Shop Not Found ] Loading session by user_id - user: 89301123315
2024-05-15 10:25:15 -0400 : DEBUG :   �[1m�[36mCACHE User Load (0.0ms)�[0m  �[1m�[34mSELECT "users".* FROM "users" WHERE "users"."shopify_user_id" = $1 LIMIT $2�[0m  [["shopify_user_id", 89301123315], ["LIMIT", 1]]
2024-05-15 10:25:15 -0400 : DEBUG : [ ShopifyApp | DEBUG | Shop Not Found ] Loading session by user_id - user: 89301123315
2024-05-15 10:25:15 -0400 : DEBUG :   �[1m�[36mUser Load (10.2ms)�[0m  �[1m�[34mSELECT "users".* FROM "users" WHERE "users"."shopify_user_id" = $1 LIMIT $2�[0m  [["shopify_user_id", 89301123315], ["LIMIT", 1]]
2024-05-15 10:25:15 -0400 : DEBUG :   �[1m�[36mCACHE User Load (0.0ms)�[0m  �[1m�[34mSELECT "users".* FROM "users" WHERE "users"."shopify_user_id" = $1 LIMIT $2�[0m  [["shopify_user_id", 89301123315], ["LIMIT", 1]]
2024-05-15 10:25:15 -0400 : DEBUG : [ ShopifyApp | DEBUG | Shop Not Found ] Loading session by user_id - user: 89301123315
2024-05-15 10:25:15 -0400 : DEBUG : [ ShopifyApp | DEBUG | Shop Not Found ] No session found, redirecting to login
2024-05-15 10:25:15 -0400 : DEBUG :   �[1m�[36mCACHE User Load (0.0ms)�[0m  �[1m�[34mSELECT "users".* FROM "users" WHERE "users"."shopify_user_id" = $1 LIMIT $2�[0m  [["shopify_user_id", 89301123315], ["LIMIT", 1]]
2024-05-15 10:25:15 -0400 : DEBUG : [ ShopifyApp | DEBUG | Shop Not Found ] Adding top level redirection headers
2024-05-15 10:25:15 -0400 : DEBUG : [ ShopifyApp | DEBUG | Shop Not Found ] Loading session by user_id - user: 89301123315
2024-05-15 10:25:15 -0400 : DEBUG : [ ShopifyApp | DEBUG | Shop Not Found ] Setting current shop session
2024-05-15 10:25:15 -0400 : DEBUG :   �[1m�[36mCACHE User Load (0.0ms)�[0m  �[1m�[34mSELECT "users".* FROM "users" WHERE "users"."shopify_user_id" = $1 LIMIT $2�[0m  [["shopify_user_id", 89301123315], ["LIMIT", 1]]
2024-05-15 10:25:15 -0400 : DEBUG : [ ShopifyApp | DEBUG | Shop Not Found ] Loading session by user_id - user: 89301123315
2024-05-15 10:25:15 -0400 : DEBUG : [ ShopifyApp | DEBUG | Shop Not Found ] No session found, redirecting to login
2024-05-15 10:25:15 -0400 : DEBUG :   �[1m�[36mCACHE User Load (0.0ms)�[0m  �[1m�[34mSELECT "users".* FROM "users" WHERE "users"."shopify_user_id" = $1 LIMIT $2�[0m  [["shopify_user_id", 89301123315], ["LIMIT", 1]]
2024-05-15 10:25:15 -0400 : DEBUG : [ ShopifyApp | DEBUG | Shop Not Found ] Adding top level redirection headers
2024-05-15 10:25:15 -0400 : DEBUG : [ ShopifyApp | DEBUG | Shop Not Found ] Setting Reauthorize-Url to /api/auth?shop=got-any-store.myshopify.com
2024-05-15 10:25:15 -0400 : DEBUG : [ ShopifyApp | DEBUG | Shop Not Found ] Setting current shop session
2024-05-15 10:25:15 -0400 : DEBUG : [ ShopifyApp | DEBUG | Shop Not Found ] Login redirect request is a XHR
2024-05-15 10:25:15 -0400 : DEBUG : [ ShopifyApp | DEBUG | Shop Not Found ] Loading session by user_id - user: 89301123315
2024-05-15 10:25:15 -0400 : INFO : Completed 401 Unauthorized in 54ms (ActiveRecord: 2.3ms | Allocations: 9558)


2024-05-15 10:25:15 -0400 : DEBUG :   �[1m�[36mCACHE User Load (0.0ms)�[0m  �[1m�[34mSELECT "users".* FROM "users" WHERE "users"."shopify_user_id" = $1 LIMIT $2�[0m  [["shopify_user_id", 89301123315], ["LIMIT", 1]]
2024-05-15 10:25:15 -0400 : DEBUG : [ ShopifyApp | DEBUG | Shop Not Found ] Setting Reauthorize-Url to /api/auth?shop=got-any-store.myshopify.com
2024-05-15 10:25:15 -0400 : DEBUG : [ ShopifyApp | DEBUG | Shop Not Found ] Login redirect request is a XHR
2024-05-15 10:25:15 -0400 : INFO : Completed 401 Unauthorized in 51ms (ActiveRecord: 10.2ms | Allocations: 10947)


2024-05-15 10:25:16 -0400 : INFO : Started GET "/api/auth?shop=got-any-store.myshopify.com" for 174.92.27.151 at 2024-05-15 10:25:16 -0400
2024-05-15 10:25:16 -0400 : INFO : Processing by ShopifyApp::SessionsController#new as HTML
2024-05-15 10:25:16 -0400 : INFO :   Parameters: {"shop"=>"got-any-store.myshopify.com"}
2024-05-15 10:25:16 -0400 : DEBUG : [ ShopifyApp | DEBUG | Shop Not Found ] Starting OAuth - Redirecting to begin auth
2024-05-15 10:25:16 -0400 : DEBUG : [ ShopifyApp | DEBUG | Shop Not Found ] Embedded URL within / authenticate
2024-05-15 10:25:16 -0400 : DEBUG : [ ShopifyApp | DEBUG | Shop Not Found ] Starting OAuth with the following callback URL: api/auth/callback
2024-05-15 10:25:16 -0400 : DEBUG :   �[1m�[36mShop Load (6.4ms)�[0m  �[1m�[34mSELECT "shops".* FROM "shops" WHERE "shops"."shopify_domain" = $1 LIMIT $2�[0m  [["shopify_domain", "got-any-store.myshopify.com"], ["LIMIT", 1]]
2024-05-15 10:25:16 -0400 : DEBUG :   �[1m�[36mCACHE Shop Load (0.0ms)�[0m  �[1m�[34mSELECT "shops".* FROM "shops" WHERE "shops"."shopify_domain" = $1 LIMIT $2�[0m  [["shopify_domain", "got-any-store.myshopify.com"], ["LIMIT", 1]]
2024-05-15 10:25:16 -0400 : DEBUG :   �[1m�[36mCACHE Shop Load (0.0ms)�[0m  �[1m�[34mSELECT "shops".* FROM "shops" WHERE "shops"."shopify_domain" = $1 LIMIT $2�[0m  [["shopify_domain", "got-any-store.myshopify.com"], ["LIMIT", 1]]
2024-05-15 10:25:16 -0400 : DEBUG : [ ShopifyApp | DEBUG | Shop Not Found ] Redirecting to auth_route - https://got-any-store.myshopify.com/admin/oauth/authorize?client_id=16736ca5957faf119fef3f77dd8a14f5&scope=write_products&redirect_uri=https%3A%2F%2Ffki.ngrok.io%2Fapi%2Fauth%2Fcallback&state=DFmAamWlG7io80z&grant_options%5B%5D=per-user
2024-05-15 10:25:16 -0400 : INFO : Redirected to https://got-any-store.myshopify.com/admin/oauth/authorize?client_id=16736ca5957faf119fef3f77dd8a14f5&scope=write_products&redirect_uri=https%3A%2F%2Ffki.ngrok.io%2Fapi%2Fauth%2Fcallback&state=DFmAamWlG7io80z&grant_options%5B%5D=per-user
2024-05-15 10:25:16 -0400 : INFO : Completed 302 Found in 42ms (ActiveRecord: 6.5ms | Allocations: 4563)


2024-05-15 10:25:17 -0400 : INFO : Started GET "/api/auth/callback?code=64a4fdf0065b3313a7220c483296965c&hmac=2ec5d8f8780b7c528be5be5259d62660c7ecb07284e58d4762be6096722417c5&host=YWRtaW4uc2hvcGlmeS5jb20vc3RvcmUvZ290LWFueS1zdG9yZQ&shop=got-any-store.myshopify.com&state=DFmAamWlG7io80z&timestamp=1715783117" for 174.92.27.151 at 2024-05-15 10:25:17 -0400
2024-05-15 10:25:17 -0400 : INFO : Processing by ShopifyApp::CallbackController#callback as HTML
2024-05-15 10:25:17 -0400 : INFO :   Parameters: {"code"=>"64a4fdf0065b3313a7220c483296965c", "hmac"=>"2ec5d8f8780b7c528be5be5259d62660c7ecb07284e58d4762be6096722417c5", "host"=>"YWRtaW4uc2hvcGlmeS5jb20vc3RvcmUvZ290LWFueS1zdG9yZQ", "shop"=>"got-any-store.myshopify.com", "state"=>"DFmAamWlG7io80z", "timestamp"=>"1715783117"}
2024-05-15 10:25:17 -0400 : DEBUG : [ ShopifyApp | DEBUG | Shop Not Found ] Storing online user session - session: got-any-store.myshopify.com_89301123315
2024-05-15 10:25:17 -0400 : DEBUG :   �[1m�[36mUser Load (3.0ms)�[0m  �[1m�[34mSELECT "users".* FROM "users" WHERE "users"."shopify_user_id" = $1 LIMIT $2�[0m  [["shopify_user_id", 89301123315], ["LIMIT", 1]]
2024-05-15 10:25:17 -0400 : DEBUG :   �[1m�[36mTRANSACTION (7.3ms)�[0m  �[1m�[35mBEGIN�[0m
2024-05-15 10:25:17 -0400 : DEBUG :   �[1m�[36mUser Create (18.2ms)�[0m  �[1m�[32mINSERT INTO "users" ("shopify_user_id", "shopify_domain", "shopify_token", "created_at", "updated_at", "access_scopes", "expires_at") VALUES ($1, $2, $3, $4, $5, $6, $7) RETURNING "id"�[0m  [["shopify_user_id", 89301123315], ["shopify_domain", "got-any-store.myshopify.com"], ["shopify_token", "[FILTERED]"], ["created_at", "2024-05-15 14:25:17.675754"], ["updated_at", "2024-05-15 14:25:17.675754"], ["access_scopes", "write_products"], ["expires_at", "2024-05-16 14:25:16.662013"]]
2024-05-15 10:25:17 -0400 : DEBUG :   �[1m�[36mTRANSACTION (5.8ms)�[0m  �[1m�[35mCOMMIT�[0m
2024-05-15 10:25:17 -0400 : DEBUG : [ ShopifyApp | DEBUG | Shop Not Found ] Saving Shopify user ID to cookie
2024-05-15 10:25:17 -0400 : DEBUG :   �[1m�[36mShop Load (4.1ms)�[0m  �[1m�[34mSELECT "shops".* FROM "shops" WHERE "shops"."shopify_domain" = $1 LIMIT $2�[0m  [["shopify_domain", "got-any-store.myshopify.com"], ["LIMIT", 1]]
2024-05-15 10:25:17 -0400 : INFO : [ActiveJob] Enqueued ShopifyApp::WebhooksManagerJob (Job ID: fa6a6977-8e27-441b-a56a-90589bf39168) to Async(webhooks_manager)
2024-05-15 10:25:17 -0400 : INFO : Redirected to https://admin.shopify.com/store/got-any-store/apps/16736ca5957faf119fef3f77dd8a14f5
2024-05-15 10:25:17 -0400 : INFO : Completed 302 Found in 280ms (ActiveRecord: 38.3ms | Allocations: 9003)


2024-05-15 10:25:17 -0400 : INFO : [ActiveJob] [ShopifyApp::WebhooksManagerJob] [fa6a6977-8e27-441b-a56a-90589bf39168] Performing ShopifyApp::WebhooksManagerJob (Job ID: fa6a6977-8e27-441b-a56a-90589bf39168) from Async(webhooks_manager) enqueued at 2024-05-15T14:25:17.722308457Z
2024-05-15 10:25:17 -0400 : DEBUG : [ActiveJob] [ShopifyApp::WebhooksManagerJob] [fa6a6977-8e27-441b-a56a-90589bf39168] [ ShopifyApp | DEBUG | got-any-store.myshopify.com ] Creating webhooks [{:topic=>"app/uninstalled", :address=>"api/toy_webhooks/app_uninstalled"}, {:topic=>"products/create", :address=>"api/toy_webhooks/app_uninstalled"}, {:topic=>"products/update", :address=>"api/toy_webhooks/app_uninstalled"}, {:topic=>"products/delete", :address=>"api/toy_webhooks/app_uninstalled"}, {:topic=>"shop/redact", :address=>"api/webhooks/shop_redact"}, {:topic=>"customers/redact", :address=>"api/webhooks/customers_redact"}, {:topic=>"customers/data_request", :address=>"api/webhooks/customers_data_request"}]
2024-05-15 10:25:18 -0400 : INFO : [ActiveJob] [ShopifyApp::WebhooksManagerJob] [fa6a6977-8e27-441b-a56a-90589bf39168] Performed ShopifyApp::WebhooksManagerJob (Job ID: fa6a6977-8e27-441b-a56a-90589bf39168) from Async(webhooks_manager) in 1125.41ms
2024-05-15 10:25:20 -0400 : INFO : Started GET "/?embedded=1&hmac=bc51dee6d713f8570fb502ce8c821629bf6e40ae9ca584de3839c1cb1f16ac8a&host=YWRtaW4uc2hvcGlmeS5jb20vc3RvcmUvZ290LWFueS1zdG9yZQ&id_token=[FILTERED]&locale=en-CA&session=55b5540252df0900b52784e1f6a1fada457a78da3046147b5d94c40c863fb73d&shop=got-any-store.myshopify.com&timestamp=1715783119" for 174.92.27.151 at 2024-05-15 10:25:20 -0400
2024-05-15 10:25:20 -0400 : INFO : Processing by HomeController#index as HTML
2024-05-15 10:25:20 -0400 : INFO :   Parameters: {"embedded"=>"1", "hmac"=>"bc51dee6d713f8570fb502ce8c821629bf6e40ae9ca584de3839c1cb1f16ac8a", "host"=>"YWRtaW4uc2hvcGlmeS5jb20vc3RvcmUvZ290LWFueS1zdG9yZQ", "id_token"=>"[FILTERED]", "locale"=>"en-CA", "session"=>"55b5540252df0900b52784e1f6a1fada457a78da3046147b5d94c40c863fb73d", "shop"=>"got-any-store.myshopify.com", "timestamp"=>"1715783119"}
2024-05-15 10:25:20 -0400 : DEBUG :   �[1m�[36mShop Load (8.7ms)�[0m  �[1m�[34mSELECT "shops".* FROM "shops" WHERE "shops"."shopify_domain" = $1 LIMIT $2�[0m  [["shopify_domain", "got-any-store.myshopify.com"], ["LIMIT", 1]]
2024-05-15 10:25:20 -0400 : DEBUG :   �[1m�[36mCACHE Shop Load (0.0ms)�[0m  �[1m�[34mSELECT "shops".* FROM "shops" WHERE "shops"."shopify_domain" = $1 LIMIT $2�[0m  [["shopify_domain", "got-any-store.myshopify.com"], ["LIMIT", 1]]
2024-05-15 10:25:20 -0400 : INFO : [HomeController] - Line 29: in HomeController#index. shopify_user_id: 89301123315
2024-05-15 10:25:20 -0400 : DEBUG :   Rendering text template
2024-05-15 10:25:20 -0400 : INFO :   Rendered text template (Duration: 0.0ms | Allocations: 1)
2024-05-15 10:25:20 -0400 : INFO : Completed 200 OK in 72ms (Views: 0.7ms | ActiveRecord: 8.7ms | Allocations: 3264)


2024-05-15 10:25:24 -0400 : INFO : Started GET "/api/products/count" for 174.92.27.151 at 2024-05-15 10:25:24 -0400
2024-05-15 10:25:24 -0400 : INFO : Processing by ProductsController#count as */*
2024-05-15 10:25:24 -0400 : DEBUG : [ ShopifyApp | DEBUG | Shop Not Found ] Loading session by user_id - user: 89301123315
2024-05-15 10:25:24 -0400 : INFO : Started GET "/api/current/user" for 174.92.27.151 at 2024-05-15 10:25:24 -0400
2024-05-15 10:25:24 -0400 : DEBUG :   �[1m�[36mUser Load (3.0ms)�[0m  �[1m�[34mSELECT "users".* FROM "users" WHERE "users"."shopify_user_id" = $1 LIMIT $2�[0m  [["shopify_user_id", 89301123315], ["LIMIT", 1]]
2024-05-15 10:25:24 -0400 : DEBUG : [ ShopifyApp | DEBUG | Shop Not Found ] Activating Shopify session
2024-05-15 10:25:24 -0400 : INFO : Processing by UserController#current as */*
2024-05-15 10:25:24 -0400 : DEBUG : [ ShopifyApp | DEBUG | Shop Not Found ] Loading session by user_id - user: 89301123315
2024-05-15 10:25:24 -0400 : DEBUG :   �[1m�[36mUser Load (3.2ms)�[0m  �[1m�[34mSELECT "users".* FROM "users" WHERE "users"."shopify_user_id" = $1 LIMIT $2�[0m  [["shopify_user_id", 89301123315], ["LIMIT", 1]]
2024-05-15 10:25:24 -0400 : DEBUG : [ ShopifyApp | DEBUG | Shop Not Found ] Activating Shopify session
2024-05-15 10:25:24 -0400 : INFO : [UserController] - Line 7: in UsersController#current. params: {"controller"=>"user", "action"=>"current"}
2024-05-15 10:25:24 -0400 : INFO : [UserController] - Line 10: in AuthenticatedController#current_user_id. current_shopify_session scope: write_products
2024-05-15 10:25:24 -0400 : INFO : [UserController] - Line 16: in AuthenticatedController#current_user_id. user_id: 89301123315
2024-05-15 10:25:24 -0400 : INFO : [UserController] - Line 17: in AuthenticatedController#current_user_id. associated_user_scope: write_products
2024-05-15 10:25:24 -0400 : INFO : [UserController] - Line 10: in UsersController#current. shopify_user_id: 89301123315
2024-05-15 10:25:24 -0400 : DEBUG :   �[1m�[36mUser Load (4.8ms)�[0m  �[1m�[34mSELECT "users".* FROM "users" WHERE "users"."shopify_user_id" = $1 LIMIT $2�[0m  [["shopify_user_id", 89301123315], ["LIMIT", 1]]
2024-05-15 10:25:24 -0400 : DEBUG :   ↳ app/controllers/user_controller.rb:11:in `current'
2024-05-15 10:25:24 -0400 : INFO : [UserController] - Line 12: in UsersController#current. user: #<User id: 2, shopify_user_id: 89301123315, shopify_domain: "got-any-store.myshopify.com", shopify_token: [FILTERED], created_at: "2024-05-15 10:25:17.675754000 -0400", updated_at: "2024-05-15 10:25:17.675754000 -0400", access_scopes: "write_products", expires_at: "2024-05-16 10:25:16.662013000 -0400">
2024-05-15 10:25:24 -0400 : DEBUG : [ ShopifyApp | DEBUG | got-any-store.myshopify.com ] Deactivating session
2024-05-15 10:25:24 -0400 : INFO : Completed 200 OK in 24ms (Views: 0.3ms | ActiveRecord: 8.0ms | Allocations: 2226)


2024-05-15 10:25:24 -0400 : INFO : [ ShopifyApp | INFO | Shop Not Found ] Installed store  - got-any-store.myshopify.com deduced from user session
2024-05-15 10:25:24 -0400 : DEBUG : [ ShopifyApp | DEBUG | got-any-store.myshopify.com ] Deactivating session
2024-05-15 10:25:24 -0400 : INFO : Completed 200 OK in 267ms (Views: 0.3ms | ActiveRecord: 3.0ms | Allocations: 8466)


2024-05-15 10:25:24 -0400 : INFO : [ ShopifyApp | INFO | Shop Not Found ] Installed store  - got-any-store.myshopify.com deduced from user session
2024-05-15 10:26:08 -0400 : INFO : Started GET "/?embedded=1&hmac=98b3d71456d05213383440b8bbb6315879ff8ca0bb7cfeb764fcc06fe94b15c8&host=YWRtaW4uc2hvcGlmeS5jb20vc3RvcmUvZ290LWFueS1zdG9yZQ&id_token=[FILTERED]&locale=en-CA&session=55b5540252df0900b52784e1f6a1fada457a78da3046147b5d94c40c863fb73d&shop=got-any-store.myshopify.com&timestamp=1715783167" for 174.92.27.151 at 2024-05-15 10:26:08 -0400
2024-05-15 10:26:08 -0400 : INFO : Processing by HomeController#index as HTML
2024-05-15 10:26:08 -0400 : INFO :   Parameters: {"embedded"=>"1", "hmac"=>"98b3d71456d05213383440b8bbb6315879ff8ca0bb7cfeb764fcc06fe94b15c8", "host"=>"YWRtaW4uc2hvcGlmeS5jb20vc3RvcmUvZ290LWFueS1zdG9yZQ", "id_token"=>"[FILTERED]", "locale"=>"en-CA", "session"=>"55b5540252df0900b52784e1f6a1fada457a78da3046147b5d94c40c863fb73d", "shop"=>"got-any-store.myshopify.com", "timestamp"=>"1715783167"}
2024-05-15 10:26:08 -0400 : DEBUG :   �[1m�[36mShop Load (4.4ms)�[0m  �[1m�[34mSELECT "shops".* FROM "shops" WHERE "shops"."shopify_domain" = $1 LIMIT $2�[0m  [["shopify_domain", "got-any-store.myshopify.com"], ["LIMIT", 1]]
2024-05-15 10:26:08 -0400 : DEBUG :   �[1m�[36mCACHE Shop Load (0.0ms)�[0m  �[1m�[34mSELECT "shops".* FROM "shops" WHERE "shops"."shopify_domain" = $1 LIMIT $2�[0m  [["shopify_domain", "got-any-store.myshopify.com"], ["LIMIT", 1]]
2024-05-15 10:26:08 -0400 : INFO : [HomeController] - Line 29: in HomeController#index. shopify_user_id: 89301123315
2024-05-15 10:26:08 -0400 : DEBUG :   Rendering text template
2024-05-15 10:26:08 -0400 : INFO :   Rendered text template (Duration: 0.0ms | Allocations: 1)
2024-05-15 10:26:08 -0400 : INFO : Completed 200 OK in 37ms (Views: 1.0ms | ActiveRecord: 4.4ms | Allocations: 3264)


2024-05-15 10:26:12 -0400 : INFO : Started GET "/api/current/user" for 174.92.27.151 at 2024-05-15 10:26:12 -0400
2024-05-15 10:26:12 -0400 : INFO : Started GET "/api/products/count" for 174.92.27.151 at 2024-05-15 10:26:12 -0400
2024-05-15 10:26:12 -0400 : INFO : Processing by ProductsController#count as */*
2024-05-15 10:26:12 -0400 : INFO : Processing by UserController#current as */*
2024-05-15 10:26:12 -0400 : DEBUG : [ ShopifyApp | DEBUG | Shop Not Found ] Loading session by user_id - user: 89301123315
2024-05-15 10:26:12 -0400 : DEBUG : [ ShopifyApp | DEBUG | Shop Not Found ] Loading session by user_id - user: 89301123315
2024-05-15 10:26:12 -0400 : DEBUG :   �[1m�[36mUser Load (5.1ms)�[0m  �[1m�[34mSELECT "users".* FROM "users" WHERE "users"."shopify_user_id" = $1 LIMIT $2�[0m  [["shopify_user_id", 89301123315], ["LIMIT", 1]]
2024-05-15 10:26:12 -0400 : DEBUG : [ ShopifyApp | DEBUG | Shop Not Found ] Activating Shopify session
2024-05-15 10:26:12 -0400 : INFO : [UserController] - Line 7: in UsersController#current. params: {"controller"=>"user", "action"=>"current"}
2024-05-15 10:26:12 -0400 : DEBUG :   �[1m�[36mUser Load (8.7ms)�[0m  �[1m�[34mSELECT "users".* FROM "users" WHERE "users"."shopify_user_id" = $1 LIMIT $2�[0m  [["shopify_user_id", 89301123315], ["LIMIT", 1]]
2024-05-15 10:26:12 -0400 : INFO : [UserController] - Line 10: in AuthenticatedController#current_user_id. current_shopify_session scope: write_products
2024-05-15 10:26:12 -0400 : DEBUG : [ ShopifyApp | DEBUG | Shop Not Found ] Activating Shopify session
2024-05-15 10:26:12 -0400 : INFO : [UserController] - Line 16: in AuthenticatedController#current_user_id. user_id: 89301123315
2024-05-15 10:26:12 -0400 : INFO : [UserController] - Line 17: in AuthenticatedController#current_user_id. associated_user_scope: write_products
2024-05-15 10:26:12 -0400 : INFO : [UserController] - Line 10: in UsersController#current. shopify_user_id: 89301123315
2024-05-15 10:26:12 -0400 : DEBUG :   �[1m�[36mUser Load (4.0ms)�[0m  �[1m�[34mSELECT "users".* FROM "users" WHERE "users"."shopify_user_id" = $1 LIMIT $2�[0m  [["shopify_user_id", 89301123315], ["LIMIT", 1]]
2024-05-15 10:26:12 -0400 : DEBUG :   ↳ app/controllers/user_controller.rb:11:in `current'
2024-05-15 10:26:12 -0400 : INFO : [UserController] - Line 12: in UsersController#current. user: #<User id: 2, shopify_user_id: 89301123315, shopify_domain: "got-any-store.myshopify.com", shopify_token: [FILTERED], created_at: "2024-05-15 10:25:17.675754000 -0400", updated_at: "2024-05-15 10:25:17.675754000 -0400", access_scopes: "write_products", expires_at: "2024-05-16 10:25:16.662013000 -0400">
2024-05-15 10:26:12 -0400 : DEBUG : [ ShopifyApp | DEBUG | got-any-store.myshopify.com ] Deactivating session
2024-05-15 10:26:12 -0400 : INFO : Completed 200 OK in 34ms (Views: 0.4ms | ActiveRecord: 9.0ms | Allocations: 3884)


2024-05-15 10:26:12 -0400 : INFO : [ ShopifyApp | INFO | Shop Not Found ] Installed store  - got-any-store.myshopify.com deduced from user session
2024-05-15 10:26:13 -0400 : DEBUG : [ ShopifyApp | DEBUG | got-any-store.myshopify.com ] Deactivating session
2024-05-15 10:26:13 -0400 : INFO : Completed 200 OK in 236ms (Views: 0.3ms | ActiveRecord: 8.7ms | Allocations: 5688)


2024-05-15 10:26:13 -0400 : INFO : [ ShopifyApp | INFO | Shop Not Found ] Installed store  - got-any-store.myshopify.com deduced from user session
2024-05-15 10:27:02 -0400 : INFO : Started POST "/api/products/create" for 174.92.27.151 at 2024-05-15 10:27:02 -0400
2024-05-15 10:27:02 -0400 : INFO : Processing by ProductsController#create as */*
2024-05-15 10:27:02 -0400 : INFO :   Parameters: {"count"=>2, "product"=>{"count"=>2}}
2024-05-15 10:27:02 -0400 : DEBUG : [ ShopifyApp | DEBUG | Shop Not Found ] Loading session by user_id - user: 77780451571
2024-05-15 10:27:02 -0400 : DEBUG :   �[1m�[36mUser Load (4.1ms)�[0m  �[1m�[34mSELECT "users".* FROM "users" WHERE "users"."shopify_user_id" = $1 LIMIT $2�[0m  [["shopify_user_id", 77780451571], ["LIMIT", 1]]
2024-05-15 10:27:02 -0400 : DEBUG : [ ShopifyApp | DEBUG | Shop Not Found ] Activating Shopify session
2024-05-15 10:27:02 -0400 : INFO : [ProductCreator] - Line 24: in ProductCreator#call. session: #<ShopifyAPI::Auth::Session:0x00007fb565ee8de8 @id="ee36ccd3-1ffd-442a-9f78-c72f407bcefc", @shop="got-any-store.myshopify.com", @state=nil, @access_token="shpua_d645b0ab727141fa93056cda2e965a30", @scope=#<ShopifyAPI::Auth::AuthScopes:0x00007fb5643df2e0 @compressed_scopes=#<Set: {"write_products"}>, @expanded_scopes=#<Set: {"write_products", "read_products"}>>, @associated_user_scope=#<ShopifyAPI::Auth::AuthScopes:0x00007fb5643de688 @compressed_scopes=#<Set: {"write_products"}>, @expanded_scopes=#<Set: {"write_products", "read_products"}>>, @expires=Thu, 16 May 2024 10:22:47.604496000 EDT -04:00, @associated_user=<ShopifyAPI::Auth::AssociatedUser account_owner=false collaborator=false email="" email_verified=false first_name="" id=77780451571 last_name="" locale="">, @is_online=true, @shopify_session_id=nil>
2024-05-15 10:27:03 -0400 : INFO : [ProductCreator] - Line 38: in ProductCreator#call, response.body: {"data"=>{"productCreate"=>{"product"=>{"title"=>"cold lake", "id"=>"gid://shopify/Product/8682780557555"}}}, "extensions"=>{"cost"=>{"requestedQueryCost"=>10, "actualQueryCost"=>10, "throttleStatus"=>{"maximumAvailable"=>2000.0, "currentlyAvailable"=>1990, "restoreRate"=>100.0}}}}
2024-05-15 10:27:03 -0400 : INFO : [ProductCreator] - Line 46: in ProductCreator#call, created_product: {"title"=>"cold lake", "id"=>"gid://shopify/Product/8682780557555"}
2024-05-15 10:27:03 -0400 : INFO : [ProductCreator] - Line 38: in ProductCreator#call, response.body: {"data"=>{"productCreate"=>{"product"=>{"title"=>"billowing field", "id"=>"gid://shopify/Product/8682780590323"}}}, "extensions"=>{"cost"=>{"requestedQueryCost"=>10, "actualQueryCost"=>10, "throttleStatus"=>{"maximumAvailable"=>2000.0, "currentlyAvailable"=>1990, "restoreRate"=>100.0}}}}
2024-05-15 10:27:03 -0400 : INFO : [ProductCreator] - Line 46: in ProductCreator#call, created_product: {"title"=>"billowing field", "id"=>"gid://shopify/Product/8682780590323"}
2024-05-15 10:27:03 -0400 : DEBUG : [ ShopifyApp | DEBUG | got-any-store.myshopify.com ] Deactivating session
2024-05-15 10:27:03 -0400 : INFO : Completed 200 OK in 1087ms (Views: 0.3ms | ActiveRecord: 4.0ms | Allocations: 17015)


2024-05-15 10:27:03 -0400 : INFO : [ ShopifyApp | INFO | Shop Not Found ] Installed store  - got-any-store.myshopify.com deduced from user session
2024-05-15 10:27:03 -0400 : INFO : Started GET "/api/products/count" for 174.92.27.151 at 2024-05-15 10:27:03 -0400
2024-05-15 10:27:04 -0400 : INFO : Processing by ProductsController#count as */*
2024-05-15 10:27:04 -0400 : DEBUG : [ ShopifyApp | DEBUG | Shop Not Found ] Loading session by user_id - user: 77780451571
2024-05-15 10:27:04 -0400 : DEBUG :   �[1m�[36mUser Load (2.9ms)�[0m  �[1m�[34mSELECT "users".* FROM "users" WHERE "users"."shopify_user_id" = $1 LIMIT $2�[0m  [["shopify_user_id", 77780451571], ["LIMIT", 1]]
2024-05-15 10:27:04 -0400 : DEBUG : [ ShopifyApp | DEBUG | Shop Not Found ] Activating Shopify session
2024-05-15 10:27:04 -0400 : DEBUG : [ ShopifyApp | DEBUG | got-any-store.myshopify.com ] Deactivating session
2024-05-15 10:27:04 -0400 : INFO : Completed 200 OK in 219ms (Views: 0.2ms | ActiveRecord: 2.8ms | Allocations: 2918)


2024-05-15 10:27:04 -0400 : INFO : [ ShopifyApp | INFO | Shop Not Found ] Installed store  - got-any-store.myshopify.com deduced from user session
2024-05-15 10:27:12 -0400 : INFO : Started POST "/api/toy_webhooks/app_uninstalled" for 35.239.101.188 at 2024-05-15 10:27:12 -0400
2024-05-15 10:27:12 -0400 : INFO : Processing by AppWebhooksController#receive as */*
2024-05-15 10:27:12 -0400 : INFO :   Parameters: {"admin_graphql_api_id"=>"gid://shopify/Product/8682780590323", "body_html"=>nil, "created_at"=>"2024-05-15T10:27:03-04:00", "handle"=>"billowing-field", "id"=>8682780590323, "product_type"=>"", "published_at"=>nil, "template_suffix"=>nil, "title"=>"billowing field", "updated_at"=>"2024-05-15T10:27:04-04:00", "vendor"=>"Got Any? Store", "status"=>"active", "published_scope"=>"web", "tags"=>"", "variants"=>[{"admin_graphql_api_id"=>"gid://shopify/ProductVariant/45651499090163", "barcode"=>nil, "compare_at_price"=>nil, "created_at"=>"2024-05-15T10:27:03-04:00", "fulfillment_service"=>"manual", "id"=>45651499090163, "inventory_management"=>nil, "inventory_policy"=>"deny", "position"=>1, "price"=>"0.00", "product_id"=>8682780590323, "sku"=>"", "taxable"=>true, "title"=>"Default Title", "updated_at"=>"2024-05-15T10:27:03-04:00", "option1"=>"Default Title", "option2"=>nil, "option3"=>nil, "grams"=>0, "image_id"=>nil, "weight"=>0.0, "weight_unit"=>"kg", "inventory_item_id"=>47750895108339, "inventory_quantity"=>0, "old_inventory_quantity"=>0, "requires_shipping"=>true}], "options"=>[{"name"=>"Title", "id"=>11120018424051, "product_id"=>8682780590323, "position"=>1, "values"=>["Default Title"]}], "images"=>[], "image"=>nil, "variant_gids"=>[{"admin_graphql_api_id"=>"gid://shopify/ProductVariant/45651499090163"}], "type"=>"app_uninstalled", "app_webhook"=>{"admin_graphql_api_id"=>"gid://shopify/Product/8682780590323", "body_html"=>nil, "created_at"=>"2024-05-15T10:27:03-04:00", "handle"=>"billowing-field", "id"=>8682780590323, "product_type"=>"", "published_at"=>nil, "template_suffix"=>nil, "title"=>"billowing field", "updated_at"=>"2024-05-15T10:27:04-04:00", "vendor"=>"Got Any? Store", "status"=>"active", "published_scope"=>"web", "tags"=>"", "variants"=>[{"admin_graphql_api_id"=>"gid://shopify/ProductVariant/45651499090163", "barcode"=>nil, "compare_at_price"=>nil, "created_at"=>"2024-05-15T10:27:03-04:00", "fulfillment_service"=>"manual", "id"=>45651499090163, "inventory_management"=>nil, "inventory_policy"=>"deny", "position"=>1, "price"=>"0.00", "product_id"=>8682780590323, "sku"=>"", "taxable"=>true, "title"=>"Default Title", "updated_at"=>"2024-05-15T10:27:03-04:00", "option1"=>"Default Title", "option2"=>nil, "option3"=>nil, "grams"=>0, "image_id"=>nil, "weight"=>0.0, "weight_unit"=>"kg", "inventory_item_id"=>47750895108339, "inventory_quantity"=>0, "old_inventory_quantity"=>0, "requires_shipping"=>true}], "options"=>[{"name"=>"Title", "id"=>11120018424051, "product_id"=>8682780590323, "position"=>1, "values"=>["Default Title"]}], "images"=>[], "image"=>nil, "variant_gids"=>[{"admin_graphql_api_id"=>"gid://shopify/ProductVariant/45651499090163"}]}}
2024-05-15 10:27:12 -0400 : INFO : Completed 200 OK in 1ms (ActiveRecord: 0.0ms | Allocations: 164)


2024-05-15 10:27:12 -0400 : INFO : Started POST "/api/toy_webhooks/app_uninstalled" for 104.155.169.253 at 2024-05-15 10:27:12 -0400
2024-05-15 10:27:12 -0400 : INFO : Processing by AppWebhooksController#receive as */*
2024-05-15 10:27:12 -0400 : INFO :   Parameters: {"admin_graphql_api_id"=>"gid://shopify/Product/8682780557555", "body_html"=>nil, "created_at"=>"2024-05-15T10:27:03-04:00", "handle"=>"cold-lake", "id"=>8682780557555, "product_type"=>"", "published_at"=>nil, "template_suffix"=>nil, "title"=>"cold lake", "updated_at"=>"2024-05-15T10:27:03-04:00", "vendor"=>"Got Any? Store", "status"=>"active", "published_scope"=>"web", "tags"=>"", "variants"=>[{"admin_graphql_api_id"=>"gid://shopify/ProductVariant/45651499057395", "barcode"=>nil, "compare_at_price"=>nil, "created_at"=>"2024-05-15T10:27:03-04:00", "fulfillment_service"=>"manual", "id"=>45651499057395, "inventory_management"=>nil, "inventory_policy"=>"deny", "position"=>1, "price"=>"0.00", "product_id"=>8682780557555, "sku"=>"", "taxable"=>true, "title"=>"Default Title", "updated_at"=>"2024-05-15T10:27:03-04:00", "option1"=>"Default Title", "option2"=>nil, "option3"=>nil, "grams"=>0, "image_id"=>nil, "weight"=>0.0, "weight_unit"=>"kg", "inventory_item_id"=>47750895075571, "inventory_quantity"=>0, "old_inventory_quantity"=>0, "requires_shipping"=>true}], "options"=>[{"name"=>"Title", "id"=>11120018391283, "product_id"=>8682780557555, "position"=>1, "values"=>["Default Title"]}], "images"=>[], "image"=>nil, "variant_gids"=>[{"admin_graphql_api_id"=>"gid://shopify/ProductVariant/45651499057395"}], "type"=>"app_uninstalled", "app_webhook"=>{"admin_graphql_api_id"=>"gid://shopify/Product/8682780557555", "body_html"=>nil, "created_at"=>"2024-05-15T10:27:03-04:00", "handle"=>"cold-lake", "id"=>8682780557555, "product_type"=>"", "published_at"=>nil, "template_suffix"=>nil, "title"=>"cold lake", "updated_at"=>"2024-05-15T10:27:03-04:00", "vendor"=>"Got Any? Store", "status"=>"active", "published_scope"=>"web", "tags"=>"", "variants"=>[{"admin_graphql_api_id"=>"gid://shopify/ProductVariant/45651499057395", "barcode"=>nil, "compare_at_price"=>nil, "created_at"=>"2024-05-15T10:27:03-04:00", "fulfillment_service"=>"manual", "id"=>45651499057395, "inventory_management"=>nil, "inventory_policy"=>"deny", "position"=>1, "price"=>"0.00", "product_id"=>8682780557555, "sku"=>"", "taxable"=>true, "title"=>"Default Title", "updated_at"=>"2024-05-15T10:27:03-04:00", "option1"=>"Default Title", "option2"=>nil, "option3"=>nil, "grams"=>0, "image_id"=>nil, "weight"=>0.0, "weight_unit"=>"kg", "inventory_item_id"=>47750895075571, "inventory_quantity"=>0, "old_inventory_quantity"=>0, "requires_shipping"=>true}], "options"=>[{"name"=>"Title", "id"=>11120018391283, "product_id"=>8682780557555, "position"=>1, "values"=>["Default Title"]}], "images"=>[], "image"=>nil, "variant_gids"=>[{"admin_graphql_api_id"=>"gid://shopify/ProductVariant/45651499057395"}]}}
2024-05-15 10:27:12 -0400 : INFO : Completed 200 OK in 1ms (ActiveRecord: 0.0ms | Allocations: 79)


2024-05-15 10:27:18 -0400 : INFO : Started POST "/api/products/create" for 174.92.27.151 at 2024-05-15 10:27:18 -0400
2024-05-15 10:27:18 -0400 : INFO : Processing by ProductsController#create as */*
2024-05-15 10:27:18 -0400 : INFO :   Parameters: {"count"=>2, "product"=>{"count"=>2}}
2024-05-15 10:27:18 -0400 : DEBUG : [ ShopifyApp | DEBUG | Shop Not Found ] Loading session by user_id - user: 89301123315
2024-05-15 10:27:18 -0400 : DEBUG :   �[1m�[36mUser Load (3.9ms)�[0m  �[1m�[34mSELECT "users".* FROM "users" WHERE "users"."shopify_user_id" = $1 LIMIT $2�[0m  [["shopify_user_id", 89301123315], ["LIMIT", 1]]
2024-05-15 10:27:18 -0400 : DEBUG : [ ShopifyApp | DEBUG | Shop Not Found ] Activating Shopify session
2024-05-15 10:27:18 -0400 : INFO : [ProductCreator] - Line 24: in ProductCreator#call. session: #<ShopifyAPI::Auth::Session:0x00007fb566654c58 @id="fc64b260-cf3a-4929-8007-6deb9c8aa09d", @shop="got-any-store.myshopify.com", @state=nil, @access_token="shpua_758a57f87fd915085c6c242fcbf61526", @scope=#<ShopifyAPI::Auth::AuthScopes:0x00007fb537caaed8 @compressed_scopes=#<Set: {"write_products"}>, @expanded_scopes=#<Set: {"write_products", "read_products"}>>, @associated_user_scope=#<ShopifyAPI::Auth::AuthScopes:0x00007fb537caa910 @compressed_scopes=#<Set: {"write_products"}>, @expanded_scopes=#<Set: {"write_products", "read_products"}>>, @expires=Thu, 16 May 2024 10:25:16.662013000 EDT -04:00, @associated_user=<ShopifyAPI::Auth::AssociatedUser account_owner=false collaborator=false email="" email_verified=false first_name="" id=89301123315 last_name="" locale="">, @is_online=true, @shopify_session_id=nil>
2024-05-15 10:27:18 -0400 : INFO : [ProductCreator] - Line 38: in ProductCreator#call, response.body: {"errors"=>[{"message"=>"Access denied for productCreate field. Required access: `write_products` access scope. Also: The user must have a permission to create products.", "locations"=>[{"line"=>2, "column"=>3}], "path"=>["productCreate"], "extensions"=>{"code"=>"ACCESS_DENIED", "documentation"=>"https://shopify.dev/api/usage/access-scopes", "requiredAccess"=>"`write_products` access scope. Also: The user must have a permission to create products."}}], "data"=>{"productCreate"=>nil}, "extensions"=>{"cost"=>{"requestedQueryCost"=>10, "actualQueryCost"=>10, "throttleStatus"=>{"maximumAvailable"=>2000.0, "currentlyAvailable"=>1990, "restoreRate"=>100.0}}}}
2024-05-15 10:27:18 -0400 : DEBUG : [ ShopifyApp | DEBUG | got-any-store.myshopify.com ] Deactivating session
2024-05-15 10:27:18 -0400 : INFO : Completed 200 OK in 218ms (Views: 0.3ms | ActiveRecord: 3.9ms | Allocations: 3104)


2024-05-15 10:27:18 -0400 : INFO : [ ShopifyApp | INFO | Shop Not Found ] Installed store  - got-any-store.myshopify.com deduced from user session
@matteodepalo
Copy link
Contributor

Hi @fairknowe, thank you for opening this issue. This looks like an inconsistency coming from the API. I'll put it in our backlog so that we can take a look.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@matteodepalo @fairknowe