Auth failure and Invalid site errors after charge decline

seriousdev
Excursionist
17 0 2

I've built a Shopify app(non embedded app) using shopify_app gem in Ruby on Rails. The app had been working fine on my end(both locally and on heroku), but when I submitted it for review it started to show errors related to Authentication and CSRF token.

I've never faced them in development environment or my production environment on heroku. The app I submitted for review is also hosted on heroku but it has been showing errors which I don't understand and haven't been able to resolve since many days.

Here is my config/initializers/shopify_app.rb file content

 

 

 

 

 

 

ShopifyApp.configure do |config|
  config.application_name = ENV.fetch('APP_NAME')
  config.api_key = ENV.fetch('SHOPIFY_API_KEY', '').presence || raise('Missing SHOPIFY_API_KEY')
  config.secret = ENV.fetch('SHOPIFY_API_SECRET', '').presence || raise('Missing SHOPIFY_API_SECRET')
  config.old_secret = ''
  config.scope = 'read_products,write_products,read_script_tags,write_script_tags,read_orders'
  config.embedded_app = false
  config.after_authenticate_job = false
  config.api_version = ENV['API_VERSION'] || '2020-10'
  config.shop_session_repository = 'Shop'
  config.allow_jwt_authentication = true
  config.allow_cookie_authentication = true
  config.enable_same_site_none = Rails.env.production?
  
  config.webhooks = [
    {
      topic: 'orders/paid',
      address: "#{ENV['BASE_URL']}/webhooks/shopify/orders/payment"
    }  ]
end

 

 

 

 

 

 

 My shopify app engine is mounted at '/', see this in the routes.rb

 

 

 

 

 

 

mount ShopifyApp::Engine, at: '/'

 

 

 

 

 

 

 These are the steps which cause the authentication failure error:

1. Visit the app url i.e https://app.bulb-y.com/login

2. Enter the store to which the app is to be installed.

3. Install the app by clicking Install

4. In this step you're prompted to Accept the Charge, click on Cancel to decline the charges.

5. The merchant is redirect to https://store_url.myshopify.com/admin/apps (which is outside my app server's code)

6. The merchant clicks on the app and it opens a new tab which fails with authentication error(invalid_site, auth failure).

These errors have occurred only with the app review team and never occurred with my staging app even when I did the same actions again and again.

See this screencast by the app review team, when I do the same thing with my app on staging version it does not reproduce at all. I've made a recording of my testing of the staging app see this recording here.

Following are the logs for the app tested by the app review team, I've added some comments to make it a bit readable:

 

 

 

 

 

# Merchant is Logged In and Visits the app at /login path

# then he enters his Store, where the app is to be installed

2021-04-14T19:22:11.165071+00:00 heroku[router]: at=info method=GET path="/?hmac=727ae62852b7a66eae3c09b00ac6f501665ed1496d4efcfd6b049404959a1fb9&shop=rubicktest3.myshopify.com&timestamp=1618428129" host=app.bulb-y.com request_id=be1a9a57-408c-4c59-b0ab-9d676aff9eba fwd="111.125.122.1" dyno=web.1 connect=0ms service=69ms status=302 bytes=1318 protocol=https
2021-04-14T19:22:11.432473+00:00 app[web.1]: I, [2021-04-14T19:22:11.432369 #4]  INFO -- : [f2e30ae3-fa2a-4040-b4e3-2d5b27391c16] Started GET "/login?shop=rubicktest3.myshopify.com" for 111.125.122.1 at 2021-04-14 19:22:11 +0000
2021-04-14T19:22:11.437617+00:00 app[web.1]: I, [2021-04-14T19:22:11.437524 #4]  INFO -- : [f2e30ae3-fa2a-4040-b4e3-2d5b27391c16] Processing by ShopifyApp::SessionsController#new as HTML
2021-04-14T19:22:11.437794+00:00 app[web.1]: I, [2021-04-14T19:22:11.437696 #4]  INFO -- : [f2e30ae3-fa2a-4040-b4e3-2d5b27391c16]   Parameters: {"shop"=>"rubicktest3.myshopify.com"}
2021-04-14T19:22:11.575590+00:00 app[web.1]: I, [2021-04-14T19:22:11.575464 #4]  INFO -- : [f2e30ae3-fa2a-4040-b4e3-2d5b27391c16] Redirected to https://app.bulb-y.com/auth/shopify
2021-04-14T19:22:11.578761+00:00 app[web.1]: I, [2021-04-14T19:22:11.578684 #4]  INFO -- : [f2e30ae3-fa2a-4040-b4e3-2d5b27391c16] Completed 302 Found in 141ms (Allocations: 837)
2021-04-14T19:22:11.583736+00:00 heroku[router]: at=info method=GET path="/login?shop=rubicktest3.myshopify.com" host=app.bulb-y.com request_id=f2e30ae3-fa2a-4040-b4e3-2d5b27391c16 fwd="111.125.122.1" dyno=web.1 connect=0ms service=154ms status=302 bytes=1399 protocol=https
2021-04-14T19:22:11.892636+00:00 app[web.1]: I, [2021-04-14T19:22:11.892496 #4]  INFO -- : [2ad19977-7c10-4766-a48a-758e259e66bd] Started GET "/auth/shopify" for 111.125.122.1 at 2021-04-14 19:22:11 +0000
2021-04-14T19:22:11.893423+00:00 app[web.1]: I, [2021-04-14T19:22:11.893337 #4]  INFO -- omniauth: (shopify) Setup endpoint detected, running now.
2021-04-14T19:22:11.894252+00:00 app[web.1]: I, [2021-04-14T19:22:11.894190 #4]  INFO -- omniauth: (shopify) Request phase initiated.
2021-04-14T19:22:11.926445+00:00 heroku[router]: at=info method=GET path="/auth/shopify" host=app.bulb-y.com request_id=2ad19977-7c10-4766-a48a-758e259e66bd fwd="111.125.122.1" dyno=web.1 connect=0ms service=81ms status=302 bytes=1876 protocol=https

# Authentication is done

2021-04-14T19:22:48.177103+00:00 app[web.1]: I, [2021-04-14T19:22:48.176963 #4]  INFO -- : [86b49c0d-49c8-442f-b032-1e96d921103d] Started GET "/auth/shopify/callback?code=2b5d21b9007b8564ccbe60be18856c34&hmac=f52fec246b51ebc40a647380219b713d0e6de476d2b832eeedc54a6297821950&host=cnViaWNrdGVzdDMubXlzaG9waWZ5LmNvbS9hZG1pbg&shop=rubicktest3.myshopify.com&state=11860f1cea1c640470ebe68ddb6048d2d1ea5dad1079af82&timestamp=1618428167" for 111.125.122.1 at 2021-04-14 19:22:48 +0000
2021-04-14T19:22:48.177800+00:00 app[web.1]: I, [2021-04-14T19:22:48.177735 #4]  INFO -- omniauth: (shopify) Setup endpoint detected, running now.
2021-04-14T19:22:48.178666+00:00 app[web.1]: I, [2021-04-14T19:22:48.178613 #4]  INFO -- omniauth: (shopify) Callback phase initiated.

# Shopify callback executing

2021-04-14T19:22:48.458436+00:00 app[web.1]: I, [2021-04-14T19:22:48.458296 #4]  INFO -- : [86b49c0d-49c8-442f-b032-1e96d921103d] Processing by ShopifyApp::CallbackController#callback as HTML
2021-04-14T19:22:48.458528+00:00 app[web.1]: I, [2021-04-14T19:22:48.458446 #4]  INFO -- : [86b49c0d-49c8-442f-b032-1e96d921103d]   Parameters: {"code"=>"2b5d21b9007b8564ccbe60be18856c34", "hmac"=>"f52fec246b51ebc40a647380219b713d0e6de476d2b832eeedc54a6297821950", "host"=>"cnViaWNrdGVzdDMubXlzaG9waWZ5LmNvbS9hZG1pbg", "shop"=>"rubicktest3.myshopify.com", "state"=>"11860f1cea1c640470ebe68ddb6048d2d1ea5dad1079af82", "timestamp"=>"1618428167"}
2021-04-14T19:22:48.553861+00:00 app[web.1]: D, [2021-04-14T19:22:48.553268 #4] DEBUG -- : [86b49c0d-49c8-442f-b032-1e96d921103d]   Shop Load (6.8ms)  SELECT "shops".* FROM "shops" WHERE "shops"."shopify_domain" = $1 LIMIT $2  [["shopify_domain", "rubicktest3.myshopify.com"], ["LIMIT", 1]]
2021-04-14T19:22:48.635719+00:00 app[web.1]: D, [2021-04-14T19:22:48.635544 #4] DEBUG -- : [86b49c0d-49c8-442f-b032-1e96d921103d]    (2.8ms)  BEGIN
2021-04-14T19:22:48.645466+00:00 app[web.1]: D, [2021-04-14T19:22:48.645276 #4] DEBUG -- : [86b49c0d-49c8-442f-b032-1e96d921103d]   Shop Exists? (1.5ms)  SELECT 1 AS one FROM "shops" WHERE LOWER("shops"."shopify_domain") = LOWER($1) LIMIT $2  [["shopify_domain", "rubicktest3.myshopify.com"], ["LIMIT", 1]]
2021-04-14T19:22:48.673060+00:00 app[web.1]: D, [2021-04-14T19:22:48.672941 #4] DEBUG -- : [86b49c0d-49c8-442f-b032-1e96d921103d]   Shop Create (6.6ms)  INSERT INTO "shops" ("shopify_domain", "shopify_token", "created_at", "updated_at") VALUES ($1, $2, $3, $4) RETURNING "id"  [["shopify_domain", "rubicktest3.myshopify.com"], ["shopify_token", "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"], ["created_at", "2021-04-14 19:22:48.645835"], ["updated_at", "2021-04-14 19:22:48.645835"]]
2021-04-14T19:22:49.017085+00:00 app[web.1]: [WARNING] The default rounding mode will change from `ROUND_HALF_EVEN` to `ROUND_HALF_UP` in the next major release. Set it explicitly using `Money.rounding_mode=` to avoid potential problems.
2021-04-14T19:22:51.629345+00:00 app[web.1]: D, [2021-04-14T19:22:51.629184 #4] DEBUG -- : [86b49c0d-49c8-442f-b032-1e96d921103d]   Shop Exists? (5.2ms)  SELECT 1 AS one FROM "shops" WHERE LOWER("shops"."shopify_domain") = LOWER($1) AND "shops"."id" != $2 LIMIT $3  [["shopify_domain", "rubicktest3.myshopify.com"], ["id", 17], ["LIMIT", 1]]
2021-04-14T19:22:51.639683+00:00 app[web.1]: D, [2021-04-14T19:22:51.639559 #4] DEBUG -- : [86b49c0d-49c8-442f-b032-1e96d921103d]   Shop Update (8.1ms)  UPDATE "shops" SET "updated_at" = $1, "shop_name" = $2, "shop_currency" = $3, "bulby_product_id" = $4, "bulby_variant_id" = $5, "bulby_product_price" = $6, "bulby_product_price_usd" = $7, "email" = $8 WHERE "shops"."id" = $9  [["updated_at", "2021-04-14 19:22:51.629760"], ["shop_name", "Rubicktest3"], ["shop_currency", "USD"], ["bulby_product_id", "6714814791843"], ["bulby_variant_id", "39829869592739"], ["bulby_product_price", "7.00"], ["bulby_product_price_usd", "6.99"], ["email", "rubicktesting01@gmail.com"], ["id", 17]]
2021-04-14T19:22:51.644824+00:00 app[web.1]: D, [2021-04-14T19:22:51.644701 #4] DEBUG -- : [86b49c0d-49c8-442f-b032-1e96d921103d]   Shop Load (4.2ms)  SELECT "shops".* FROM "shops" WHERE "shops"."shopify_domain" = $1 LIMIT $2  [["shopify_domain", "rubicktest3.myshopify.com"], ["LIMIT", 1]]
2021-04-14T19:22:52.440822+00:00 app[web.1]: D, [2021-04-14T19:22:52.440516 #4] DEBUG -- : [86b49c0d-49c8-442f-b032-1e96d921103d]   Shop Exists? (9.5ms)  SELECT 1 AS one FROM "shops" WHERE LOWER("shops"."shopify_domain") = LOWER($1) AND "shops"."id" != $2 LIMIT $3  [["shopify_domain", "rubicktest3.myshopify.com"], ["id", 17], ["LIMIT", 1]]
2021-04-14T19:22:52.451207+00:00 app[web.1]: D, [2021-04-14T19:22:52.450989 #4] DEBUG -- : [86b49c0d-49c8-442f-b032-1e96d921103d]   Shop Update (6.8ms)  UPDATE "shops" SET "product_active" = $1, "updated_at" = $2 WHERE "shops"."id" = $3  [["product_active", false], ["updated_at", "2021-04-14 19:22:52.442220"], ["id", 17]]
2021-04-14T19:22:52.637778+00:00 app[web.1]: D, [2021-04-14T19:22:52.637631 #4] DEBUG -- : [86b49c0d-49c8-442f-b032-1e96d921103d]    (10.4ms)  COMMIT
2021-04-14T19:22:52.646161+00:00 app[web.1]: D, [2021-04-14T19:22:52.646041 #4] DEBUG -- : [86b49c0d-49c8-442f-b032-1e96d921103d]   Shop Load (7.1ms)  SELECT "shops".* FROM "shops" WHERE "shops"."shopify_domain" = $1 LIMIT $2  [["shopify_domain", "rubicktest3.myshopify.com"], ["LIMIT", 1]]
2021-04-14T19:22:52.668667+00:00 app[web.1]: I, [2021-04-14T19:22:52.652244 #4]  INFO -- : [86b49c0d-49c8-442f-b032-1e96d921103d] [ActiveJob] Enqueued ShopifyApp::WebhooksManagerJob (Job ID: 90f39077-17b1-4ab6-8a54-082949ae916b) to Async(default)
2021-04-14T19:22:52.672124+00:00 app[web.1]: I, [2021-04-14T19:22:52.671991 #4]  INFO -- : [86b49c0d-49c8-442f-b032-1e96d921103d] Redirected to https://app.bulb-y.com/?hmac=727ae62852b7a66eae3c09b00ac6f501665ed1496d4efcfd6b049404959a1fb9&shop=rubicktest3.myshopify.com&timestamp=1618428129
2021-04-14T19:22:52.675832+00:00 app[web.1]: I, [2021-04-14T19:22:52.675661 #4]  INFO -- : [86b49c0d-49c8-442f-b032-1e96d921103d] Completed 302 Found in 4212ms (ActiveRecord: 122.8ms | Allocations: 35971)
2021-04-14T19:22:52.680446+00:00 app[web.1]: I, [2021-04-14T19:22:52.668540 #4]  INFO -- : [ActiveJob] [ShopifyApp::WebhooksManagerJob] [90f39077-17b1-4ab6-8a54-082949ae916b] Performing ShopifyApp::WebhooksManagerJob (Job ID: 90f39077-17b1-4ab6-8a54-082949ae916b) from Async(default) enqueued at 2021-04-14T19:22:52Z
2021-04-14T19:22:52.687720+00:00 app[web.1]: /app/vendor/bundle/ruby/2.7.0/gems/activejob-6.0.3.6/lib/active_job/execution.rb:40: warning: Using the last argument as keyword parameters is deprecated; maybe ** should be added to the call
2021-04-14T19:22:52.687903+00:00 app[web.1]: /app/vendor/bundle/ruby/2.7.0/gems/shopify_app-17.2.1/lib/shopify_app/jobs/webhooks_manager_job.rb:8: warning: The called method `perform' is defined here
2021-04-14T19:22:52.697504+00:00 heroku[router]: at=info method=GET path="/auth/shopify/callback?code=2b5d21b9007b8564ccbe60be18856c34&hmac=f52fec246b51ebc40a647380219b713d0e6de476d2b832eeedc54a6297821950&host=cnViaWNrdGVzdDMubXlzaG9waWZ5LmNvbS9hZG1pbg&shop=rubicktest3.myshopify.com&state=11860f1cea1c640470ebe68ddb6048d2d1ea5dad1079af82&timestamp=1618428167" host=app.bulb-y.com request_id=86b49c0d-49c8-442f-b032-1e96d921103d fwd="111.125.122.1" dyno=web.1 connect=0ms service=4527ms status=302 bytes=1478 protocol=https
2021-04-14T19:22:52.976851+00:00 app[web.1]: I, [2021-04-14T19:22:52.976742 #4]  INFO -- : [9a848ec9-b22a-486f-a485-cc2c26f3ce36] Started GET "/?hmac=727ae62852b7a66eae3c09b00ac6f501665ed1496d4efcfd6b049404959a1fb9&shop=rubicktest3.myshopify.com&timestamp=1618428129" for 111.125.122.1 at 2021-04-14 19:22:52 +0000
2021-04-14T19:22:52.978498+00:00 app[web.1]: I, [2021-04-14T19:22:52.978427 #4]  INFO -- : [9a848ec9-b22a-486f-a485-cc2c26f3ce36] Processing by OrdersController#index as HTML
2021-04-14T19:22:52.980442+00:00 app[web.1]: I, [2021-04-14T19:22:52.980336 #4]  INFO -- : [9a848ec9-b22a-486f-a485-cc2c26f3ce36]   Parameters: {"hmac"=>"727ae62852b7a66eae3c09b00ac6f501665ed1496d4efcfd6b049404959a1fb9", "shop"=>"rubicktest3.myshopify.com", "timestamp"=>"1618428129"}
2021-04-14T19:22:53.004255+00:00 app[web.1]: D, [2021-04-14T19:22:53.004129 #4] DEBUG -- : [9a848ec9-b22a-486f-a485-cc2c26f3ce36]   Shop Load (6.6ms)  SELECT "shops".* FROM "shops" WHERE "shops"."id" = $1 LIMIT $2  [["id", 17], ["LIMIT", 1]]
2021-04-14T19:22:53.005603+00:00 app[web.1]: D, [2021-04-14T19:22:53.005523 #4] DEBUG -- : [9a848ec9-b22a-486f-a485-cc2c26f3ce36]   CACHE Shop Load (0.0ms)  SELECT "shops".* FROM "shops" WHERE "shops"."id" = $1 LIMIT $2  [["id", 17], ["LIMIT", 1]]
2021-04-14T19:22:53.008489+00:00 app[web.1]: D, [2021-04-14T19:22:53.008369 #4] DEBUG -- : [9a848ec9-b22a-486f-a485-cc2c26f3ce36]   Shop Load (2.1ms)  SELECT "shops".* FROM "shops" WHERE "shops"."shopify_domain" = $1 LIMIT $2  [["shopify_domain", "rubicktest3.myshopify.com"], ["LIMIT", 1]]
2021-04-14T19:22:53.009469+00:00 app[web.1]: D, [2021-04-14T19:22:53.009379 #4] DEBUG -- : [9a848ec9-b22a-486f-a485-cc2c26f3ce36]   CACHE Shop Load (0.0ms)  SELECT "shops".* FROM "shops" WHERE "shops"."id" = $1 LIMIT $2  [["id", 17], ["LIMIT", 1]]
2021-04-14T19:22:53.010710+00:00 app[web.1]: D, [2021-04-14T19:22:53.010623 #4] DEBUG -- : [9a848ec9-b22a-486f-a485-cc2c26f3ce36]   CACHE Shop Load (0.0ms)  SELECT "shops".* FROM "shops" WHERE "shops"."id" = $1 LIMIT $2  [["id", 17], ["LIMIT", 1]]
2021-04-14T19:22:53.011424+00:00 app[web.1]: D, [2021-04-14T19:22:53.011340 #4] DEBUG -- : [9a848ec9-b22a-486f-a485-cc2c26f3ce36]   CACHE Shop Load (0.0ms)  SELECT "shops".* FROM "shops" WHERE "shops"."shopify_domain" = $1 LIMIT $2  [["shopify_domain", "rubicktest3.myshopify.com"], ["LIMIT", 1]]
2021-04-14T19:22:53.012060+00:00 app[web.1]: D, [2021-04-14T19:22:53.011977 #4] DEBUG -- : [9a848ec9-b22a-486f-a485-cc2c26f3ce36]   CACHE Shop Load (0.0ms)  SELECT "shops".* FROM "shops" WHERE "shops"."id" = $1 LIMIT $2  [["id", 17], ["LIMIT", 1]]
2021-04-14T19:22:53.015308+00:00 app[web.1]: D, [2021-04-14T19:22:53.014738 #4] DEBUG -- : [9a848ec9-b22a-486f-a485-cc2c26f3ce36]   CACHE Shop Load (0.0ms)  SELECT "shops".* FROM "shops" WHERE "shops"."shopify_domain" = $1 LIMIT $2  [["shopify_domain", "rubicktest3.myshopify.com"], ["LIMIT", 1]]

# App is installed and my app's code is going to generate a Recurring Charge plan for approval

2021-04-14T19:22:53.563676+00:00 app[web.1]: D, [2021-04-14T19:22:53.563539 #4] DEBUG -- : [9a848ec9-b22a-486f-a485-cc2c26f3ce36]   RecurringCharge Load (11.9ms)  SELECT "recurring_charges".* FROM "recurring_charges" WHERE "recurring_charges"."shop_domain" = $1 LIMIT $2  [["shop_domain", "rubicktest3.myshopify.com"], ["LIMIT", 1]]
2021-04-14T19:22:53.637627+00:00 app[web.1]: D, [2021-04-14T19:22:53.637497 #4] DEBUG -- : [9a848ec9-b22a-486f-a485-cc2c26f3ce36]    (4.9ms)  BEGIN
2021-04-14T19:22:53.650868+00:00 app[web.1]: D, [2021-04-14T19:22:53.650738 #4] DEBUG -- : [9a848ec9-b22a-486f-a485-cc2c26f3ce36]   RecurringCharge Create (11.8ms)  INSERT INTO "recurring_charges" ("recurring_charge_id", "shop_domain", "name", "price", "return_url", "decorated_return_url", "confirmation_url", "capped_amount", "balance_used", "api_client_id", "charge_created_at", "charge_updated_at", "created_at", "updated_at", "balance_remaining") VALUES ($1, $2, $3, $4, $5, $6, $7, $8, $9, $10, $11, $12, $13, $14, $15) RETURNING "id"  [["recurring_charge_id", "22312419491"], ["shop_domain", "rubicktest3.myshopify.com"], ["name", "Free Plan"], ["price", "0.00"], ["return_url", "https://app.bulb-y.com/billing/callback?shop_domain=rubicktest3.myshopify.com"], ["decorated_return_url", "https://app.bulb-y.com/billing/callback?charge_id=22312419491&shop_domain=rubicktest3.myshopify.com"], ["confirmation_url", "https://rubicktest3.myshopify.com/admin/charges/22312419491/confirm_recurring_application_charge?signature=BAh7BzoHaWRsKwijgOwxBQA6EmF1dG9fYWN0aXZhdGVG--ad7e1bbd4fa4119cf0f3e1ee79d458b02892dc39"], ["capped_amount", "250.00"], ["balance_used", "0.0"], ["api_client_id", "5059625"], ["charge_created_at", "2021-04-14 19:22:53"], ["charge_updated_at", "2021-04-14 19:22:53"], ["created_at", "2021-04-14 19:22:53.629889"], ["updated_at", "2021-04-14 19:22:53.629889"], ["balance_remaining", "250.0"]]
2021-04-14T19:22:53.655007+00:00 app[web.1]: D, [2021-04-14T19:22:53.654882 #4] DEBUG -- : [9a848ec9-b22a-486f-a485-cc2c26f3ce36]    (3.1ms)  COMMIT

# My app has redirected the merchant to the Approve Subscription screen

2021-04-14T19:22:53.655566+00:00 app[web.1]: I, [2021-04-14T19:22:53.655496 #4]  INFO -- : [9a848ec9-b22a-486f-a485-cc2c26f3ce36] Redirected to https://rubicktest3.myshopify.com/admin/charges/22312419491/confirm_recurring_application_charge?signature=BAh7BzoHaWRsKwijgOwxBQA6EmF1dG9fYWN0aXZhdGVG--ad7e1bbd4fa4119cf0f3e1ee79d458b02892dc39

# The merchant cancels the charge and goes to the /admin/apps route on their store
# merchant clicks on the app again and this causes some authentication errors (See the logs below and the video attached above)

2021-04-14T19:22:53.655865+00:00 app[web.1]: I, [2021-04-14T19:22:53.655795 #4]  INFO -- : [9a848ec9-b22a-486f-a485-cc2c26f3ce36] Filter chain halted as :recurring_plan_check rendered or redirected
2021-04-14T19:22:53.656297+00:00 app[web.1]: I, [2021-04-14T19:22:53.656229 #4]  INFO -- : [9a848ec9-b22a-486f-a485-cc2c26f3ce36] Completed 302 Found in 676ms (ActiveRecord: 68.4ms | Allocations: 20403)
2021-04-14T19:22:53.662822+00:00 heroku[router]: at=info method=GET path="/?hmac=727ae62852b7a66eae3c09b00ac6f501665ed1496d4efcfd6b049404959a1fb9&shop=rubicktest3.myshopify.com&timestamp=1618428129" host=app.bulb-y.com request_id=9a848ec9-b22a-486f-a485-cc2c26f3ce36 fwd="111.125.122.1" dyno=web.1 connect=4ms service=704ms status=302 bytes=1581 protocol=https
2021-04-14T19:22:54.449703+00:00 app[web.1]: I, [2021-04-14T19:22:54.449550 #4]  INFO -- : [ActiveJob] [ShopifyApp::WebhooksManagerJob] [90f39077-17b1-4ab6-8a54-082949ae916b] Performed ShopifyApp::WebhooksManagerJob (Job ID: 90f39077-17b1-4ab6-8a54-082949ae916b) from Async(default) in 1761.93ms
2021-04-14T19:23:29.624714+00:00 app[web.1]: I, [2021-04-14T19:23:29.624594 #4]  INFO -- : [5f6476eb-9822-482f-befc-298f9cdd7328] Started GET "/?hmac=7841678a95b64da5e1bfc5653ad8c0259e7a693e5deb39bedefcfbff1ab6e50a&host=cnViaWNrdGVzdDMubXlzaG9waWZ5LmNvbS9hZG1pbg&locale=en&new_design_language=true&session=f4bd61107f1c2b94efb73f66a296182478b243b011defe0e23d94a1626d82337&shop=rubicktest3.myshopify.com&timestamp=1618428207" for 111.125.122.1 at 2021-04-14 19:23:29 +0000
2021-04-14T19:23:29.626376+00:00 app[web.1]: I, [2021-04-14T19:23:29.626282 #4]  INFO -- : [5f6476eb-9822-482f-befc-298f9cdd7328] Processing by OrdersController#index as HTML
2021-04-14T19:23:29.626491+00:00 app[web.1]: I, [2021-04-14T19:23:29.626431 #4]  INFO -- : [5f6476eb-9822-482f-befc-298f9cdd7328]   Parameters: {"hmac"=>"7841678a95b64da5e1bfc5653ad8c0259e7a693e5deb39bedefcfbff1ab6e50a", "host"=>"cnViaWNrdGVzdDMubXlzaG9waWZ5LmNvbS9hZG1pbg", "locale"=>"en", "new_design_language"=>"true", "session"=>"f4bd61107f1c2b94efb73f66a296182478b243b011defe0e23d94a1626d82337", "shop"=>"rubicktest3.myshopify.com", "timestamp"=>"1618428207"}
2021-04-14T19:23:29.637422+00:00 app[web.1]: I, [2021-04-14T19:23:29.637238 #4]  INFO -- : [5f6476eb-9822-482f-befc-298f9cdd7328] Redirected to https://app.bulb-y.com/login?return_to=%2F%3Fhmac%3D7841678a95b64da5e1bfc5653ad8c0259e7a693e5deb39bedefcfbff1ab6e50a%26host%3DcnViaWNrdGVzdDMubXlzaG9waWZ5LmNvbS9hZG1pbg%26locale%3Den%26new_design_language%3Dtrue%26session%3Df4bd61107f1c2b94efb73f66a296182478b243b011defe0e23d94a1626d82337%26shop%3Drubicktest3.myshopify.com%26timestamp%3D1618428207&shop=rubicktest3.myshopify.com
2021-04-14T19:23:29.637716+00:00 app[web.1]: I, [2021-04-14T19:23:29.637635 #4]  INFO -- : [5f6476eb-9822-482f-befc-298f9cdd7328] Completed 302 Found in 2ms (ActiveRecord: 0.0ms | Allocations: 397)
2021-04-14T19:23:29.648821+00:00 heroku[router]: at=info method=GET path="/?hmac=7841678a95b64da5e1bfc5653ad8c0259e7a693e5deb39bedefcfbff1ab6e50a&host=cnViaWNrdGVzdDMubXlzaG9waWZ5LmNvbS9hZG1pbg&locale=en&new_design_language=true&session=f4bd61107f1c2b94efb73f66a296182478b243b011defe0e23d94a1626d82337&shop=rubicktest3.myshopify.com&timestamp=1618428207" host=app.bulb-y.com request_id=5f6476eb-9822-482f-befc-298f9cdd7328 fwd="111.125.122.1" dyno=web.1 connect=0ms service=23ms status=302 bytes=2283 protocol=https
2021-04-14T19:23:29.924594+00:00 app[web.1]: I, [2021-04-14T19:23:29.924479 #4]  INFO -- : [5c36a940-5af4-445e-b428-1a92a1c79a15] Started GET "/login?return_to=%2F%3Fhmac%3D7841678a95b64da5e1bfc5653ad8c0259e7a693e5deb39bedefcfbff1ab6e50a%26host%3DcnViaWNrdGVzdDMubXlzaG9waWZ5LmNvbS9hZG1pbg%26locale%3Den%26new_design_language%3Dtrue%26session%3Df4bd61107f1c2b94efb73f66a296182478b243b011defe0e23d94a1626d82337%26shop%3Drubicktest3.myshopify.com%26timestamp%3D1618428207&shop=rubicktest3.myshopify.com" for 111.125.122.1 at 2021-04-14 19:23:29 +0000
2021-04-14T19:23:29.926206+00:00 app[web.1]: I, [2021-04-14T19:23:29.926132 #4]  INFO -- : [5c36a940-5af4-445e-b428-1a92a1c79a15] Processing by ShopifyApp::SessionsController#new as HTML
2021-04-14T19:23:29.927359+00:00 app[web.1]: I, [2021-04-14T19:23:29.927292 #4]  INFO -- : [5c36a940-5af4-445e-b428-1a92a1c79a15]   Parameters: {"return_to"=>"/?hmac=7841678a95b64da5e1bfc5653ad8c0259e7a693e5deb39bedefcfbff1ab6e50a&host=cnViaWNrdGVzdDMubXlzaG9waWZ5LmNvbS9hZG1pbg&locale=en&new_design_language=true&session=f4bd61107f1c2b94efb73f66a296182478b243b011defe0e23d94a1626d82337&shop=rubicktest3.myshopify.com&timestamp=1618428207", "shop"=>"rubicktest3.myshopify.com"}
2021-04-14T19:23:29.928779+00:00 app[web.1]: I, [2021-04-14T19:23:29.928719 #4]  INFO -- : [5c36a940-5af4-445e-b428-1a92a1c79a15] Redirected to https://app.bulb-y.com/auth/shopify
2021-04-14T19:23:29.936007+00:00 app[web.1]: I, [2021-04-14T19:23:29.935892 #4]  INFO -- : [5c36a940-5af4-445e-b428-1a92a1c79a15] Completed 302 Found in 8ms (ActiveRecord: 0.0ms | Allocations: 317)
2021-04-14T19:23:29.942611+00:00 heroku[router]: at=info method=GET path="/login?return_to=%2F%3Fhmac%3D7841678a95b64da5e1bfc5653ad8c0259e7a693e5deb39bedefcfbff1ab6e50a%26host%3DcnViaWNrdGVzdDMubXlzaG9waWZ5LmNvbS9hZG1pbg%26locale%3Den%26new_design_language%3Dtrue%26session%3Df4bd61107f1c2b94efb73f66a296182478b243b011defe0e23d94a1626d82337%26shop%3Drubicktest3.myshopify.com%26timestamp%3D1618428207&shop=rubicktest3.myshopify.com" host=app.bulb-y.com request_id=5c36a940-5af4-445e-b428-1a92a1c79a15 fwd="111.125.122.1" dyno=web.1 connect=0ms service=18ms status=302 bytes=1705 protocol=https
2021-04-14T19:23:30.200507+00:00 app[web.1]: I, [2021-04-14T19:23:30.200394 #4]  INFO -- : [e21b155b-1310-4963-8520-dde9896cdda8] Started GET "/auth/shopify" for 111.125.122.1 at 2021-04-14 19:23:30 +0000
2021-04-14T19:23:30.201103+00:00 app[web.1]: I, [2021-04-14T19:23:30.201026 #4]  INFO -- omniauth: (shopify) Setup endpoint detected, running now.
2021-04-14T19:23:30.201378+00:00 app[web.1]: I, [2021-04-14T19:23:30.201312 #4]  INFO -- omniauth: (shopify) Request phase initiated.
2021-04-14T19:23:30.201700+00:00 app[web.1]: E, [2021-04-14T19:23:30.201628 #4] ERROR -- omniauth: (shopify) Authentication failure! invalid_site encountered.
2021-04-14T19:23:30.208579+00:00 heroku[router]: at=info method=GET path="/auth/shopify" host=app.bulb-y.com request_id=e21b155b-1310-4963-8520-dde9896cdda8 fwd="111.125.122.1" dyno=web.1 connect=0ms service=10ms status=302 bytes=677 protocol=https
2021-04-14T19:23:30.464475+00:00 app[web.1]: I, [2021-04-14T19:23:30.464364 #4]  INFO -- : [37e81fb2-579e-4756-b8be-e3ba6b05ed65] Started GET "/auth/failure?message=invalid_site&strategy=shopify" for 111.125.122.1 at 2021-04-14 19:23:30 +0000
2021-04-14T19:23:30.467931+00:00 app[web.1]: I, [2021-04-14T19:23:30.467779 #4]  INFO -- : [37e81fb2-579e-4756-b8be-e3ba6b05ed65] Processing by OrdersController#index as HTML
2021-04-14T19:23:30.468067+00:00 app[web.1]: I, [2021-04-14T19:23:30.468011 #4]  INFO -- : [37e81fb2-579e-4756-b8be-e3ba6b05ed65]   Parameters: {"message"=>"invalid_site", "strategy"=>"shopify"}
2021-04-14T19:23:30.469811+00:00 app[web.1]: I, [2021-04-14T19:23:30.469709 #4]  INFO -- : [37e81fb2-579e-4756-b8be-e3ba6b05ed65] Redirected to https://app.bulb-y.com/login?return_to=%2Fauth%2Ffailure%3Fmessage%3Dinvalid_site%26strategy%3Dshopify
2021-04-14T19:23:30.470158+00:00 app[web.1]: I, [2021-04-14T19:23:30.470065 #4]  INFO -- : [37e81fb2-579e-4756-b8be-e3ba6b05ed65] Completed 302 Found in 2ms (ActiveRecord: 0.0ms | Allocations: 259)
2021-04-14T19:23:30.477555+00:00 heroku[router]: at=info method=GET path="/auth/failure?message=invalid_site&strategy=shopify" host=app.bulb-y.com request_id=37e81fb2-579e-4756-b8be-e3ba6b05ed65 fwd="111.125.122.1" dyno=web.1 connect=0ms service=14ms status=302 bytes=1256 protocol=https
2021-04-14T19:23:30.736564+00:00 app[web.1]: I, [2021-04-14T19:23:30.736456 #4]  INFO -- : [f451b6cf-90e8-4af3-b425-40570ca4ff96] Started GET "/login?return_to=%2Fauth%2Ffailure%3Fmessage%3Dinvalid_site%26strategy%3Dshopify" for 111.125.122.1 at 2021-04-14 19:23:30 +0000
2021-04-14T19:23:30.741100+00:00 app[web.1]: I, [2021-04-14T19:23:30.740701 #4]  INFO -- : [f451b6cf-90e8-4af3-b425-40570ca4ff96] Processing by ShopifyApp::SessionsController#new as HTML
2021-04-14T19:23:30.741530+00:00 app[web.1]: I, [2021-04-14T19:23:30.741167 #4]  INFO -- : [f451b6cf-90e8-4af3-b425-40570ca4ff96]   Parameters: {"return_to"=>"/auth/failure?message=invalid_site&strategy=shopify"}
2021-04-14T19:23:30.794387+00:00 app[web.1]: I, [2021-04-14T19:23:30.794267 #4]  INFO -- : [f451b6cf-90e8-4af3-b425-40570ca4ff96]   Rendering vendor/bundle/ruby/2.7.0/gems/shopify_app-17.2.1/app/views/shopify_app/sessions/new.html.erb
2021-04-14T19:23:30.807729+00:00 app[web.1]: I, [2021-04-14T19:23:30.807619 #4]  INFO -- : [f451b6cf-90e8-4af3-b425-40570ca4ff96]   Rendered vendor/bundle/ruby/2.7.0/gems/shopify_app-17.2.1/app/views/shopify_app/partials/_layout_styles.html.erb (Duration: 4.5ms | Allocations: 258)
2021-04-14T19:23:30.811995+00:00 app[web.1]: I, [2021-04-14T19:23:30.811892 #4]  INFO -- : [f451b6cf-90e8-4af3-b425-40570ca4ff96]   Rendered vendor/bundle/ruby/2.7.0/gems/shopify_app-17.2.1/app/views/shopify_app/partials/_typography_styles.html.erb (Duration: 2.9ms | Allocations: 109)
2021-04-14T19:23:30.817393+00:00 app[web.1]: I, [2021-04-14T19:23:30.817297 #4]  INFO -- : [f451b6cf-90e8-4af3-b425-40570ca4ff96]   Rendered vendor/bundle/ruby/2.7.0/gems/shopify_app-17.2.1/app/views/shopify_app/partials/_card_styles.html.erb (Duration: 3.9ms | Allocations: 108)
2021-04-14T19:23:30.822457+00:00 app[web.1]: I, [2021-04-14T19:23:30.822358 #4]  INFO -- : [f451b6cf-90e8-4af3-b425-40570ca4ff96]   Rendered vendor/bundle/ruby/2.7.0/gems/shopify_app-17.2.1/app/views/shopify_app/partials/_button_styles.html.erb (Duration: 3.9ms | Allocations: 188)
2021-04-14T19:23:30.826453+00:00 app[web.1]: I, [2021-04-14T19:23:30.826363 #4]  INFO -- : [f451b6cf-90e8-4af3-b425-40570ca4ff96]   Rendered vendor/bundle/ruby/2.7.0/gems/shopify_app-17.2.1/app/views/shopify_app/partials/_form_styles.html.erb (Duration: 2.7ms | Allocations: 134)
2021-04-14T19:23:30.827630+00:00 app[web.1]: I, [2021-04-14T19:23:30.827569 #4]  INFO -- : [f451b6cf-90e8-4af3-b425-40570ca4ff96]   Rendered vendor/bundle/ruby/2.7.0/gems/shopify_app-17.2.1/app/views/shopify_app/sessions/new.html.erb (Duration: 33.1ms | Allocations: 3277)
2021-04-14T19:23:30.828087+00:00 app[web.1]: I, [2021-04-14T19:23:30.828030 #4]  INFO -- : [f451b6cf-90e8-4af3-b425-40570ca4ff96] Completed 200 OK in 86ms (Views: 35.2ms | ActiveRecord: 0.0ms | Allocations: 4214)
2021-04-14T19:23:30.836763+00:00 heroku[router]: at=info method=GET path="/login?return_to=%2Fauth%2Ffailure%3Fmessage%3Dinvalid_site%26strategy%3Dshopify" host=app.bulb-y.com request_id=f451b6cf-90e8-4af3-b425-40570ca4ff96 fwd="111.125.122.1" dyno=web.1 connect=2ms service=103ms status=200 bytes=10637 protocol=https
2021-04-14T19:23:45.412278+00:00 app[web.1]: I, [2021-04-14T19:23:45.412098 #4]  INFO -- : [9d490932-bcf7-4dde-b8d9-2007435d950c] Started POST "/login" for 111.125.122.1 at 2021-04-14 19:23:45 +0000
2021-04-14T19:23:45.418245+00:00 app[web.1]: I, [2021-04-14T19:23:45.418158 #4]  INFO -- : [9d490932-bcf7-4dde-b8d9-2007435d950c] Processing by ShopifyApp::SessionsController#create as HTML
2021-04-14T19:23:45.425101+00:00 app[web.1]: I, [2021-04-14T19:23:45.424993 #4]  INFO -- : [9d490932-bcf7-4dde-b8d9-2007435d950c]   Parameters: {"authenticity_token"=>"SgEjRIZU1BdlBd5+ZkNDzcKJe9FSaoysbtB7kY/ndulV4dUz+JmnfmDAOkOLBOzgUKZ82gGF9YgVCB4kzO8NWQ==", "shop"=>"rubicktest3.myshopify.com"}
2021-04-14T19:23:45.426865+00:00 app[web.1]: W, [2021-04-14T19:23:45.426802 #4]  WARN -- : [9d490932-bcf7-4dde-b8d9-2007435d950c] Can't verify CSRF token authenticity.
2021-04-14T19:23:45.429208+00:00 app[web.1]: I, [2021-04-14T19:23:45.429144 #4]  INFO -- : [9d490932-bcf7-4dde-b8d9-2007435d950c] Completed 422 Unprocessable Entity in 4ms (ActiveRecord: 0.0ms | Allocations: 275)
2021-04-14T19:23:45.439360+00:00 app[web.1]: F, [2021-04-14T19:23:45.439192 #4] FATAL -- : [9d490932-bcf7-4dde-b8d9-2007435d950c]
2021-04-14T19:23:45.439362+00:00 app[web.1]: [9d490932-bcf7-4dde-b8d9-2007435d950c] ActionController::InvalidAuthenticityToken (ActionController::InvalidAuthenticityToken):
2021-04-14T19:23:45.439362+00:00 app[web.1]: [9d490932-bcf7-4dde-b8d9-2007435d950c]
2021-04-14T19:23:45.439363+00:00 app[web.1]: [9d490932-bcf7-4dde-b8d9-2007435d950c] actionpack (6.0.3.6) lib/action_controller/metal/request_forgery_protection.rb:215:in `handle_unverified_request'
2021-04-14T19:23:45.439364+00:00 app[web.1]: [9d490932-bcf7-4dde-b8d9-2007435d950c] actionpack (6.0.3.6) lib/action_controller/metal/request_forgery_protection.rb:247:in `handle_unverified_request'
2021-04-14T19:23:45.439364+00:00 app[web.1]: [9d490932-bcf7-4dde-b8d9-2007435d950c] devise (4.7.3) lib/devise/controllers/helpers.rb:255:in `handle_unverified_request'
2021-04-14T19:23:45.439365+00:00 app[web.1]: [9d490932-bcf7-4dde-b8d9-2007435d950c] actionpack (6.0.3.6) lib/action_controller/metal/request_forgery_protection.rb:242:in `verify_authenticity_token'
2021-04-14T19:23:45.439365+00:00 app[web.1]: [9d490932-bcf7-4dde-b8d9-2007435d950c] activesupport (6.0.3.6) lib/active_support/callbacks.rb:428:in `block in make_lambda'
2021-04-14T19:23:45.439366+00:00 app[web.1]: [9d490932-bcf7-4dde-b8d9-2007435d950c] activesupport (6.0.3.6) lib/active_support/callbacks.rb:200:in `block (2 levels) in halting'
2021-04-14T19:23:45.439366+00:00 app[web.1]: [9d490932-bcf7-4dde-b8d9-2007435d950c] actionpack (6.0.3.6) lib/abstract_controller/callbacks.rb:34:in `block (2 levels) in <module:Callbacks>'
2021-04-14T19:23:45.439367+00:00 app[web.1]: [9d490932-bcf7-4dde-b8d9-2007435d950c] activesupport (6.0.3.6) lib/active_support/callbacks.rb:201:in `block in halting'
2021-04-14T19:23:45.439367+00:00 app[web.1]: [9d490932-bcf7-4dde-b8d9-2007435d950c] activesupport (6.0.3.6) lib/active_support/callbacks.rb:513:in `block in invoke_before'
2021-04-14T19:23:45.439368+00:00 app[web.1]: [9d490932-bcf7-4dde-b8d9-2007435d950c] activesupport (6.0.3.6) lib/active_support/callbacks.rb:513:in `each'
2021-04-14T19:23:45.439368+00:00 app[web.1]: [9d490932-bcf7-4dde-b8d9-2007435d950c] activesupport (6.0.3.6) lib/active_support/callbacks.rb:513:in `invoke_before'
2021-04-14T19:23:45.439369+00:00 app[web.1]: [9d490932-bcf7-4dde-b8d9-2007435d950c] activesupport (6.0.3.6) lib/active_support/callbacks.rb:134:in `run_callbacks'
2021-04-14T19:23:45.439369+00:00 app[web.1]: [9d490932-bcf7-4dde-b8d9-2007435d950c] actionpack (6.0.3.6) lib/abstract_controller/callbacks.rb:41:in `process_action'
2021-04-14T19:23:45.439370+00:00 app[web.1]: [9d490932-bcf7-4dde-b8d9-2007435d950c] actionpack (6.0.3.6) lib/action_controller/metal/rescue.rb:22:in `process_action'
2021-04-14T19:23:45.439370+00:00 app[web.1]: [9d490932-bcf7-4dde-b8d9-2007435d950c] actionpack (6.0.3.6) lib/action_controller/metal/instrumentation.rb:33:in `block in process_action'
2021-04-14T19:23:45.439370+00:00 app[web.1]: [9d490932-bcf7-4dde-b8d9-2007435d950c] activesupport (6.0.3.6) lib/active_support/notifications.rb:180:in `block in instrument'
2021-04-14T19:23:45.439371+00:00 app[web.1]: [9d490932-bcf7-4dde-b8d9-2007435d950c] activesupport (6.0.3.6) lib/active_support/notifications/instrumenter.rb:24:in `instrument'
2021-04-14T19:23:45.439371+00:00 app[web.1]: [9d490932-bcf7-4dde-b8d9-2007435d950c] activesupport (6.0.3.6) lib/active_support/notifications.rb:180:in `instrument'
2021-04-14T19:23:45.439372+00:00 app[web.1]: [9d490932-bcf7-4dde-b8d9-2007435d950c] actionpack (6.0.3.6) lib/action_controller/metal/instrumentation.rb:32:in `process_action'
2021-04-14T19:23:45.439372+00:00 app[web.1]: [9d490932-bcf7-4dde-b8d9-2007435d950c] actionpack (6.0.3.6) lib/action_controller/metal/params_wrapper.rb:245:in `process_action'
2021-04-14T19:23:45.439372+00:00 app[web.1]: [9d490932-bcf7-4dde-b8d9-2007435d950c] activerecord (6.0.3.6) lib/active_record/railties/controller_runtime.rb:27:in `process_action'
2021-04-14T19:23:45.439373+00:00 app[web.1]: [9d490932-bcf7-4dde-b8d9-2007435d950c] actionpack (6.0.3.6) lib/abstract_controller/base.rb:136:in `process'
2021-04-14T19:23:45.439373+00:00 app[web.1]: [9d490932-bcf7-4dde-b8d9-2007435d950c] actionview (6.0.3.6) lib/action_view/rendering.rb:39:in `process'
2021-04-14T19:23:45.439374+00:00 app[web.1]: [9d490932-bcf7-4dde-b8d9-2007435d950c] actionpack (6.0.3.6) lib/action_controller/metal.rb:190:in `dispatch'
2021-04-14T19:23:45.439374+00:00 app[web.1]: [9d490932-bcf7-4dde-b8d9-2007435d950c] actionpack (6.0.3.6) lib/action_controller/metal.rb:254:in `dispatch'
2021-04-14T19:23:45.439374+00:00 app[web.1]: [9d490932-bcf7-4dde-b8d9-2007435d950c] actionpack (6.0.3.6) lib/action_dispatch/routing/route_set.rb:50:in `dispatch'
2021-04-14T19:23:45.439375+00:00 app[web.1]: [9d490932-bcf7-4dde-b8d9-2007435d950c] actionpack (6.0.3.6) lib/action_dispatch/routing/route_set.rb:33:in `serve'
2021-04-14T19:23:45.439376+00:00 app[web.1]: [9d490932-bcf7-4dde-b8d9-2007435d950c] actionpack (6.0.3.6) lib/action_dispatch/journey/router.rb:49:in `block in serve'
2021-04-14T19:23:45.439376+00:00 app[web.1]: [9d490932-bcf7-4dde-b8d9-2007435d950c] actionpack (6.0.3.6) lib/action_dispatch/journey/router.rb:32:in `each'
2021-04-14T19:23:45.439376+00:00 app[web.1]: [9d490932-bcf7-4dde-b8d9-2007435d950c] actionpack (6.0.3.6) lib/action_dispatch/journey/router.rb:32:in `serve'
2021-04-14T19:23:45.439383+00:00 app[web.1]: [9d490932-bcf7-4dde-b8d9-2007435d950c] actionpack (6.0.3.6) lib/action_dispatch/routing/route_set.rb:834:in `call'
2021-04-14T19:23:45.439383+00:00 app[web.1]: [9d490932-bcf7-4dde-b8d9-2007435d950c] railties (6.0.3.6) lib/rails/engine.rb:527:in `call'
2021-04-14T19:23:45.439384+00:00 app[web.1]: [9d490932-bcf7-4dde-b8d9-2007435d950c] railties (6.0.3.6) lib/rails/railtie.rb:190:in `public_send'
2021-04-14T19:23:45.439384+00:00 app[web.1]: [9d490932-bcf7-4dde-b8d9-2007435d950c] railties (6.0.3.6) lib/rails/railtie.rb:190:in `method_missing'
2021-04-14T19:23:45.439385+00:00 app[web.1]: [9d490932-bcf7-4dde-b8d9-2007435d950c] actionpack (6.0.3.6) lib/action_dispatch/routing/mapper.rb:19:in `block in <class:Constraints>'
2021-04-14T19:23:45.439385+00:00 app[web.1]: [9d490932-bcf7-4dde-b8d9-2007435d950c] actionpack (6.0.3.6) lib/action_dispatch/routing/mapper.rb:48:in `serve'
2021-04-14T19:23:45.439385+00:00 app[web.1]: [9d490932-bcf7-4dde-b8d9-2007435d950c] actionpack (6.0.3.6) lib/action_dispatch/journey/router.rb:49:in `block in serve'
2021-04-14T19:23:45.439387+00:00 app[web.1]: [9d490932-bcf7-4dde-b8d9-2007435d950c] actionpack (6.0.3.6) lib/action_dispatch/journey/router.rb:32:in `each'
2021-04-14T19:23:45.439387+00:00 app[web.1]: [9d490932-bcf7-4dde-b8d9-2007435d950c] actionpack (6.0.3.6) lib/action_dispatch/journey/router.rb:32:in `serve'
2021-04-14T19:23:45.439388+00:00 app[web.1]: [9d490932-bcf7-4dde-b8d9-2007435d950c] actionpack (6.0.3.6) lib/action_dispatch/routing/route_set.rb:834:in `call'
2021-04-14T19:23:45.439388+00:00 app[web.1]: [9d490932-bcf7-4dde-b8d9-2007435d950c] omniauth (1.9.1) lib/omniauth/strategy.rb:192:in `call!'
2021-04-14T19:23:45.439388+00:00 app[web.1]: [9d490932-bcf7-4dde-b8d9-2007435d950c] omniauth (1.9.1) lib/omniauth/strategy.rb:169:in `call'
2021-04-14T19:23:45.439389+00:00 app[web.1]: [9d490932-bcf7-4dde-b8d9-2007435d950c] omniauth (1.9.1) lib/omniauth/builder.rb:45:in `call'
2021-04-14T19:23:45.439389+00:00 app[web.1]: [9d490932-bcf7-4dde-b8d9-2007435d950c] warden (1.2.9) lib/warden/manager.rb:36:in `block in call'
2021-04-14T19:23:45.439389+00:00 app[web.1]: [9d490932-bcf7-4dde-b8d9-2007435d950c] warden (1.2.9) lib/warden/manager.rb:34:in `catch'
2021-04-14T19:23:45.439390+00:00 app[web.1]: [9d490932-bcf7-4dde-b8d9-2007435d950c] warden (1.2.9) lib/warden/manager.rb:34:in `call'
2021-04-14T19:23:45.439390+00:00 app[web.1]: [9d490932-bcf7-4dde-b8d9-2007435d950c] rack (2.2.3) lib/rack/tempfile_reaper.rb:15:in `call'
2021-04-14T19:23:45.439391+00:00 app[web.1]: [9d490932-bcf7-4dde-b8d9-2007435d950c] rack (2.2.3) lib/rack/etag.rb:27:in `call'
2021-04-14T19:23:45.439391+00:00 app[web.1]: [9d490932-bcf7-4dde-b8d9-2007435d950c] rack (2.2.3) lib/rack/conditional_get.rb:40:in `call'
2021-04-14T19:23:45.439391+00:00 app[web.1]: [9d490932-bcf7-4dde-b8d9-2007435d950c] rack (2.2.3) lib/rack/head.rb:12:in `call'
2021-04-14T19:23:45.439392+00:00 app[web.1]: [9d490932-bcf7-4dde-b8d9-2007435d950c] actionpack (6.0.3.6) lib/action_dispatch/http/content_security_policy.rb:18:in `call'
2021-04-14T19:23:45.439393+00:00 app[web.1]: [9d490932-bcf7-4dde-b8d9-2007435d950c] rack (2.2.3) lib/rack/session/abstract/id.rb:266:in `context'
2021-04-14T19:23:45.439393+00:00 app[web.1]: [9d490932-bcf7-4dde-b8d9-2007435d950c] rack (2.2.3) lib/rack/session/abstract/id.rb:260:in `call'
2021-04-14T19:23:45.439393+00:00 app[web.1]: [9d490932-bcf7-4dde-b8d9-2007435d950c] actionpack (6.0.3.6) lib/action_dispatch/middleware/cookies.rb:648:in `call'
2021-04-14T19:23:45.439394+00:00 app[web.1]: [9d490932-bcf7-4dde-b8d9-2007435d950c] actionpack (6.0.3.6) lib/action_dispatch/middleware/callbacks.rb:27:in `block in call'
2021-04-14T19:23:45.439394+00:00 app[web.1]: [9d490932-bcf7-4dde-b8d9-2007435d950c] activesupport (6.0.3.6) lib/active_support/callbacks.rb:101:in `run_callbacks'
2021-04-14T19:23:45.439394+00:00 app[web.1]: [9d490932-bcf7-4dde-b8d9-2007435d950c] actionpack (6.0.3.6) lib/action_dispatch/middleware/callbacks.rb:26:in `call'
2021-04-14T19:23:45.439395+00:00 app[web.1]: [9d490932-bcf7-4dde-b8d9-2007435d950c] actionpack (6.0.3.6) lib/action_dispatch/middleware/actionable_exceptions.rb:18:in `call'
2021-04-14T19:23:45.439395+00:00 app[web.1]: [9d490932-bcf7-4dde-b8d9-2007435d950c] actionpack (6.0.3.6) lib/action_dispatch/middleware/debug_exceptions.rb:32:in `call'
2021-04-14T19:23:45.439396+00:00 app[web.1]: [9d490932-bcf7-4dde-b8d9-2007435d950c] actionpack (6.0.3.6) lib/action_dispatch/middleware/show_exceptions.rb:33:in `call'
2021-04-14T19:23:45.439396+00:00 app[web.1]: [9d490932-bcf7-4dde-b8d9-2007435d950c] railties (6.0.3.6) lib/rails/rack/logger.rb:37:in `call_app'
2021-04-14T19:23:45.439396+00:00 app[web.1]: [9d490932-bcf7-4dde-b8d9-2007435d950c] railties (6.0.3.6) lib/rails/rack/logger.rb:26:in `block in call'
2021-04-14T19:23:45.439397+00:00 app[web.1]: [9d490932-bcf7-4dde-b8d9-2007435d950c] activesupport (6.0.3.6) lib/active_support/tagged_logging.rb:80:in `block in tagged'
2021-04-14T19:23:45.439397+00:00 app[web.1]: [9d490932-bcf7-4dde-b8d9-2007435d950c] activesupport (6.0.3.6) lib/active_support/tagged_logging.rb:28:in `tagged'
2021-04-14T19:23:45.439397+00:00 app[web.1]: [9d490932-bcf7-4dde-b8d9-2007435d950c] activesupport (6.0.3.6) lib/active_support/tagged_logging.rb:80:in `tagged'
2021-04-14T19:23:45.439398+00:00 app[web.1]: [9d490932-bcf7-4dde-b8d9-2007435d950c] railties (6.0.3.6) lib/rails/rack/logger.rb:26:in `call'
2021-04-14T19:23:45.439398+00:00 app[web.1]: [9d490932-bcf7-4dde-b8d9-2007435d950c] actionpack (6.0.3.6) lib/action_dispatch/middleware/remote_ip.rb:81:in `call'
2021-04-14T19:23:45.439398+00:00 app[web.1]: [9d490932-bcf7-4dde-b8d9-2007435d950c] actionpack (6.0.3.6) lib/action_dispatch/middleware/request_id.rb:27:in `call'
2021-04-14T19:23:45.439402+00:00 app[web.1]: [9d490932-bcf7-4dde-b8d9-2007435d950c] rack (2.2.3) lib/rack/method_override.rb:24:in `call'
2021-04-14T19:23:45.439402+00:00 app[web.1]: [9d490932-bcf7-4dde-b8d9-2007435d950c] shopify_app (17.2.1) lib/shopify_app/middleware/jwt_middleware.rb:23:in `call_next'
2021-04-14T19:23:45.439403+00:00 app[web.1]: [9d490932-bcf7-4dde-b8d9-2007435d950c] shopify_app (17.2.1) lib/shopify_app/middleware/jwt_middleware.rb:11:in `call'
2021-04-14T19:23:45.439403+00:00 app[web.1]: [9d490932-bcf7-4dde-b8d9-2007435d950c] shopify_app (17.2.1) lib/shopify_app/middleware/same_site_cookie_middleware.rb:11:in `call'
2021-04-14T19:23:45.439403+00:00 app[web.1]: [9d490932-bcf7-4dde-b8d9-2007435d950c] rack (2.2.3) lib/rack/runtime.rb:22:in `call'
2021-04-14T19:23:45.439404+00:00 app[web.1]: [9d490932-bcf7-4dde-b8d9-2007435d950c] activesupport (6.0.3.6) lib/active_support/cache/strategy/local_cache_middleware.rb:29:in `call'
2021-04-14T19:23:45.439404+00:00 app[web.1]: [9d490932-bcf7-4dde-b8d9-2007435d950c] actionpack (6.0.3.6) lib/action_dispatch/middleware/executor.rb:14:in `call'
2021-04-14T19:23:45.439404+00:00 app[web.1]: [9d490932-bcf7-4dde-b8d9-2007435d950c] actionpack (6.0.3.6) lib/action_dispatch/middleware/static.rb:126:in `call'
2021-04-14T19:23:45.439405+00:00 app[web.1]: [9d490932-bcf7-4dde-b8d9-2007435d950c] rack (2.2.3) lib/rack/sendfile.rb:110:in `call'
2021-04-14T19:23:45.439405+00:00 app[web.1]: [9d490932-bcf7-4dde-b8d9-2007435d950c] actionpack (6.0.3.6) lib/action_dispatch/middleware/host_authorization.rb:76:in `call'
2021-04-14T19:23:45.439406+00:00 app[web.1]: [9d490932-bcf7-4dde-b8d9-2007435d950c] rack-cors (1.1.1) lib/rack/cors.rb:100:in `call'
2021-04-14T19:23:45.439406+00:00 app[web.1]: [9d490932-bcf7-4dde-b8d9-2007435d950c] railties (6.0.3.6) lib/rails/engine.rb:527:in `call'
2021-04-14T19:23:45.439407+00:00 app[web.1]: [9d490932-bcf7-4dde-b8d9-2007435d950c] puma (4.3.7) lib/puma/configuration.rb:228:in `call'
2021-04-14T19:23:45.439407+00:00 app[web.1]: [9d490932-bcf7-4dde-b8d9-2007435d950c] puma (4.3.7) lib/puma/server.rb:713:in `handle_request'
2021-04-14T19:23:45.439407+00:00 app[web.1]: [9d490932-bcf7-4dde-b8d9-2007435d950c] puma (4.3.7) lib/puma/server.rb:472:in `process_client'
2021-04-14T19:23:45.439408+00:00 app[web.1]: [9d490932-bcf7-4dde-b8d9-2007435d950c] puma (4.3.7) lib/puma/server.rb:328:in `block in run'
2021-04-14T19:23:45.439408+00:00 app[web.1]: [9d490932-bcf7-4dde-b8d9-2007435d950c] puma (4.3.7) lib/puma/thread_pool.rb:134:in `block in spawn_thread'
2021-04-14T19:23:45.450279+00:00 heroku[router]: at=info method=POST path="/login" host=app.bulb-y.com request_id=9d490932-bcf7-4dde-b8d9-2007435d950c fwd="111.125.122.1" dyno=web.1 connect=0ms service=100ms status=422 bytes=2058 protocol=https
2021-04-14T19:25:35.651800+00:00 app[web.1]: I, [2021-04-14T19:25:35.651690 #4]  INFO -- : [10c2df83-2365-4ee9-84ac-3e9fe5d230f0] Started POST "/webhooks/shopify/app/uninstall" for 34.71.223.237 at 2021-04-14 19:25:35 +0000
2021-04-14T19:25:35.656632+00:00 app[web.1]: I, [2021-04-14T19:25:35.655071 #4]  INFO -- : [10c2df83-2365-4ee9-84ac-3e9fe5d230f0] Processing by Webhooks::Shopify::ShopifyAppController#uninstall as */*
2021-04-14T19:25:35.657112+00:00 app[web.1]: I, [2021-04-14T19:25:35.657023 #4]  INFO -- : [10c2df83-2365-4ee9-84ac-3e9fe5d230f0]   Parameters: {"id"=>50396102819, "name"=>"Rubicktest3", "email"=>"rubicktesting01@gmail.com", "domain"=>"rubicktest3.myshopify.com", "province"=>"Michigan", "country"=>"US", "address1"=>"3281  Wildrose Lane", "zip"=>"48227", "city"=>"Detroit", "source"=>nil, "phone"=>"313-838-7138", "latitude"=>42.3787402, "longitude"=>-83.1970511, "primary_locale"=>"en", "address2"=>"69th avenue", "created_at"=>"2020-10-22T04:34:56+08:00", "updated_at"=>"2021-03-24T02:22:10+08:00", "country_code"=>"US", "country_name"=>"United States", "currency"=>"USD", "customer_email"=>"rubicktesting01@gmail.com", "timezone"=>"(GMT+08:00) Asia/Manila", "iana_timezone"=>"Asia/Manila", "shop_owner"=>"Rubick Test", "money_format"=>"$<span class=\"ymq-money\">{{amount}}</span>", "money_with_currency_format"=>"$<span class=\"ymq-money\">{{amount}}</span> USD", "weight_unit"=>"lb", "province_code"=>"MI", "taxes_included"=>false, "auto_configure_tax_inclusivity"=>nil, "tax_shipping"=>nil, "county_taxes"=>true, "plan_display_name"=>"staff", "plan_name"=>"staff", "has_discounts"=>true, "has_gift_cards"=>false, "myshopify_domain"=>"rubicktest3.myshopify.com", "google_apps_domain"=>nil, "google_apps_login_enabled"=>nil, "money_in_emails_format"=>"${{amount}}", "money_with_currency_in_emails_format"=>"${{amount}} USD", "eligible_for_payments"=>true, "requires_extra_payments_agreement"=>false, "password_enabled"=>"[FILTERED]", "has_storefront"=>true, "eligible_for_card_reader_giveaway"=>true, "finances"=>true, "primary_location_id"=>57135071395, "cookie_consent_level"=>"implicit", "visitor_tracking_consent_preference"=>"allow_all", "force_ssl"=>true, "checkout_api_supported"=>true, "multi_location_enabled"=>true, "setup_required"=>false, "pre_launch_enabled"=>false, "enabled_presentment_currencies"=>["USD"], "shopify_app"=>{"id"=>50396102819, "name"=>"Rubicktest3", "email"=>"rubicktesting01@gmail.com", "domain"=>"rubicktest3.myshopify.com", "province"=>"Michigan", "country"=>"US", "address1"=>"3281  Wildrose Lane", "zip"=>"48227", "city"=>"Detroit", "source"=>nil, "phone"=>"313-838-7138", "latitude"=>42.3787402, "longitude"=>-83.1970511, "primary_locale"=>"en", "address2"=>"69th avenue", "created_at"=>"2020-10-22T04:34:56+08:00", "updated_at"=>"2021-03-24T02:22:10+08:00", "country_code"=>"US", "country_name"=>"United States", "currency"=>"USD", "customer_email"=>"rubicktesting01@gmail.com", "timezone"=>"(GMT+08:00) Asia/Manila", "iana_timezone"=>"Asia/Manila", "shop_owner"=>"Rubick Test", "money_format"=>"$<span class=\"ymq-money\">{{amount}}</span>", "money_with_currency_format"=>"$<span class=\"ymq-money\">{{amount}}</span> USD", "weight_unit"=>"lb", "province_code"=>"MI", "taxes_included"=>false, "auto_configure_tax_inclusivity"=>nil, "tax_shipping"=>nil, "county_taxes"=>true, "plan_display_name"=>"staff", "plan_name"=>"staff", "has_discounts"=>true, "has_gift_cards"=>false, "myshopify_domain"=>"rubicktest3.myshopify.com", "google_apps_domain"=>nil, "google_apps_login_enabled"=>nil, "money_in_emails_format"=>"${{amount}}", "money_with_currency_in_emails_format"=>"${{amount}} USD", "eligible_for_payments"=>true, "requires_extra_payments_agreement"=>false, "password_enabled"=>"[FILTERED]", "has_storefront"=>true, "eligible_for_card_reader_giveaway"=>true, "finances"=>true, "primary_location_id"=>57135071395, "cookie_consent_level"=>"implicit", "visitor_tracking_consent_preference"=>"allow_all", "force_ssl"=>true, "checkout_api_supported"=>true, "multi_location_enabled"=>true, "setup_required"=>false, "pre_launch_enabled"=>false, "enabled_presentment_currencies"=>["USD"]}}
2021-04-14T19:25:35.672658+00:00 app[web.1]: D, [2021-04-14T19:25:35.671568 #4] DEBUG -- : [10c2df83-2365-4ee9-84ac-3e9fe5d230f0]   Shop Load (1.9ms)  SELECT "shops".* FROM "shops" WHERE "shops"."shopify_domain" IS NULL LIMIT $1  [["LIMIT", 1]]
2021-04-14T19:25:35.679664+00:00 app[web.1]: D, [2021-04-14T19:25:35.679533 #4] DEBUG -- : [10c2df83-2365-4ee9-84ac-3e9fe5d230f0]   Shop Load (6.9ms)  SELECT "shops".* FROM "shops" WHERE "shops"."shopify_domain" = $1 LIMIT $2  [["shopify_domain", "rubicktest3.myshopify.com"], ["LIMIT", 1]]
2021-04-14T19:25:35.687758+00:00 app[web.1]: D, [2021-04-14T19:25:35.687634 #4] DEBUG -- : [10c2df83-2365-4ee9-84ac-3e9fe5d230f0]    (6.0ms)  BEGIN
2021-04-14T19:25:35.692481+00:00 app[web.1]: D, [2021-04-14T19:25:35.692362 #4] DEBUG -- : [10c2df83-2365-4ee9-84ac-3e9fe5d230f0]   Shop Exists? (4.3ms)  SELECT 1 AS one FROM "shops" WHERE LOWER("shops"."shopify_domain") = LOWER($1) AND "shops"."id" != $2 LIMIT $3  [["shopify_domain", "rubicktest3.myshopify.com"], ["id", 17], ["LIMIT", 1]]
2021-04-14T19:25:35.697053+00:00 app[web.1]: D, [2021-04-14T19:25:35.696790 #4] DEBUG -- : [10c2df83-2365-4ee9-84ac-3e9fe5d230f0]    (3.3ms)  COMMIT
2021-04-14T19:25:35.697423+00:00 app[web.1]: --------------------------------------------------------------------------------------------------------------------------------------------
2021-04-14T19:25:35.697572+00:00 app[web.1]: Uninstalled App For rubicktest3.myshopify.com
2021-04-14T19:25:35.697596+00:00 app[web.1]: --------------------------------------------------------------------------------------------------------------------------------------------
2021-04-14T19:25:35.721295+00:00 app[web.1]: I, [2021-04-14T19:25:35.721162 #4]  INFO -- : [10c2df83-2365-4ee9-84ac-3e9fe5d230f0] No template found for Webhooks::Shopify::ShopifyAppController#uninstall, rendering head :no_content
2021-04-14T19:25:35.739808+00:00 app[web.1]: I, [2021-04-14T19:25:35.739674 #4]  INFO -- : [10c2df83-2365-4ee9-84ac-3e9fe5d230f0] Completed 204 No Content in 82ms (ActiveRecord: 22.3ms | Allocations: 3795)
2021-04-14T19:25:35.742421+00:00 heroku[router]: at=info method=POST path="/webhooks/shopify/app/uninstall" host=app.bulb-y.com request_id=10c2df83-2365-4ee9-84ac-3e9fe5d230f0 fwd="34.71.223.237" dyno=web.1 connect=0ms service=99ms status=204 bytes=372 protocol=https
2021-04-14T19:25:43.596619+00:00 app[web.1]: I, [2021-04-14T19:25:43.596498 #4]  INFO -- : [50340842-533c-4760-b928-84dc49ac8304] Started GET "/?hmac=05ebf878a437f544e245adba1e1d7c044208d5f3766247b02ff4d1babfe3cb41&shop=rubicktest3.myshopify.com&timestamp=1618428342" for 111.125.122.1 at 2021-04-14 19:25:43 +0000
2021-04-14T19:25:43.598270+00:00 app[web.1]: I, [2021-04-14T19:25:43.598191 #4]  INFO -- : [50340842-533c-4760-b928-84dc49ac8304] Processing by OrdersController#index as HTML
2021-04-14T19:25:43.600382+00:00 app[web.1]: I, [2021-04-14T19:25:43.600311 #4]  INFO -- : [50340842-533c-4760-b928-84dc49ac8304]   Parameters: {"hmac"=>"05ebf878a437f544e245adba1e1d7c044208d5f3766247b02ff4d1babfe3cb41", "shop"=>"rubicktest3.myshopify.com", "timestamp"=>"1618428342"}
2021-04-14T19:25:43.607485+00:00 app[web.1]: D, [2021-04-14T19:25:43.607379 #4] DEBUG -- : [50340842-533c-4760-b928-84dc49ac8304]   Shop Load (1.7ms)  SELECT "shops".* FROM "shops" WHERE "shops"."id" = $1 LIMIT $2  [["id", 17], ["LIMIT", 1]]
2021-04-14T19:25:43.608643+00:00 app[web.1]: D, [2021-04-14T19:25:43.608582 #4] DEBUG -- : [50340842-533c-4760-b928-84dc49ac8304]   CACHE Shop Load (0.0ms)  SELECT "shops".* FROM "shops" WHERE "shops"."id" = $1 LIMIT $2  [["id", 17], ["LIMIT", 1]]
2021-04-14T19:25:43.611451+00:00 app[web.1]: D, [2021-04-14T19:25:43.611366 #4] DEBUG -- : [50340842-533c-4760-b928-84dc49ac8304]   Shop Load (2.1ms)  SELECT "shops".* FROM "shops" WHERE "shops"."shopify_domain" = $1 LIMIT $2  [["shopify_domain", "rubicktest3.myshopify.com"], ["LIMIT", 1]]
2021-04-14T19:25:43.612339+00:00 app[web.1]: D, [2021-04-14T19:25:43.612278 #4] DEBUG -- : [50340842-533c-4760-b928-84dc49ac8304]   CACHE Shop Load (0.0ms)  SELECT "shops".* FROM "shops" WHERE "shops"."id" = $1 LIMIT $2  [["id", 17], ["LIMIT", 1]]
2021-04-14T19:25:43.613100+00:00 app[web.1]: D, [2021-04-14T19:25:43.613041 #4] DEBUG -- : [50340842-533c-4760-b928-84dc49ac8304]   CACHE Shop Load (0.0ms)  SELECT "shops".* FROM "shops" WHERE "shops"."id" = $1 LIMIT $2  [["id", 17], ["LIMIT", 1]]
2021-04-14T19:25:43.613847+00:00 app[web.1]: D, [2021-04-14T19:25:43.613786 #4] DEBUG -- : [50340842-533c-4760-b928-84dc49ac8304]   CACHE Shop Load (0.0ms)  SELECT "shops".* FROM "shops" WHERE "shops"."shopify_domain" = $1 LIMIT $2  [["shopify_domain", "rubicktest3.myshopify.com"], ["LIMIT", 1]]
2021-04-14T19:25:43.614340+00:00 app[web.1]: D, [2021-04-14T19:25:43.614282 #4] DEBUG -- : [50340842-533c-4760-b928-84dc49ac8304]   CACHE Shop Load (0.0ms)  SELECT "shops".* FROM "shops" WHERE "shops"."id" = $1 LIMIT $2  [["id", 17], ["LIMIT", 1]]
2021-04-14T19:25:43.614865+00:00 app[web.1]: D, [2021-04-14T19:25:43.614802 #4] DEBUG -- : [50340842-533c-4760-b928-84dc49ac8304]   CACHE Shop Load (0.0ms)  SELECT "shops".* FROM "shops" WHERE "shops"."shopify_domain" = $1 LIMIT $2  [["shopify_domain", "rubicktest3.myshopify.com"], ["LIMIT", 1]]
2021-04-14T19:25:43.829578+00:00 app[web.1]: I, [2021-04-14T19:25:43.829441 #4]  INFO -- : [50340842-533c-4760-b928-84dc49ac8304] Redirected to https://app.bulb-y.com/login?shop=rubicktest3.myshopify.com
2021-04-14T19:25:43.835554+00:00 app[web.1]: I, [2021-04-14T19:25:43.835454 #4]  INFO -- : [50340842-533c-4760-b928-84dc49ac8304] Completed 302 Found in 235ms (ActiveRecord: 4.0ms | Allocations: 3365)

 

 

 

 

 

 
I've deployed both of these apps form the same codebase and both have same config(except the database and the obvious stuff for two separate apps). The only difference would be that the app in review has test charges disabled, while the staging app has enabled the test charges flag.

I've inquired the app review team whether they're using a browser which blocks/disables cookies, and they responded that no they've not disabled cookies.

Kindly, help me out in finding and fixing this problem. Thanks a lot.

Replies 15 (15)

jam_chan
Shopify Partner
891 23 171

When I submitted my app last month, the tester was testing with Chrome incognito tab. By default, Chrome disables 3rd party cookies in incognito tabs. Well, I didn't expect the tester was using incognito tabs to test my app! I don't think the docs mentioned it. My development environment was using an ordinary Chrome tab so I was stuck in the error for a long time. My tab enables 3rd party by default. 

Even worse is the error. When the session id cannot be passed in Django, the browser just retries. It looks like an infinite loop on the server-side! So I spend 1 - 2 weeks stuck in the process. Most of the time I am just waiting for the tester to try again. 

After that, I changed my embedded app to a standalone app in 1 day and it passed app reviews yesterday. If you're interested in knowing more, you can read my blog post - What I wish someone to tell me when building a Shopify App with Django

 

BYOB - Build Your Own Bundles, SPO - SEO App to research keywords & edit social link preview
seriousdev
Excursionist
17 0 2

@jam_chan thanks for sharing your knowledge and experience. In my case however, I have tested it on Brave browser(normal and incognito modes), Safari, Chrome(normal and incognito modes), but I have not been able to reproduce this error, yet it happens every time with the tester going through this flow. 

It has happened for almost like 4 times already with the tester but has never occurred while I tested in all the mentioned browsers(normal or incognito mode).
It does appear like that it has something to do with cookies but even in Chrome incognito tab I could not reproduce this issue.

jam_chan
Shopify Partner
891 23 171

I also tested with my chrome incognito tab but it was ok at the beginning. After a checking, I found that my 3rd party cookie was whitelisted for some reasons (which I don't know). So the session could be persisted. 

While it may not be your case, I suggest u install sentry and hotjar to get more information of the production errors. Usually, this kind of errors is related to production settings and data

BYOB - Build Your Own Bundles, SPO - SEO App to research keywords & edit social link preview
policenauts
Shopify Partner
206 10 66

@seriousdev this is not the answer you want to hear, but I ran into an infinite cookies loop rejection last year submitting an app built with Shopify CLI (shopify_app gem), deployed to Heroku as well. I also could not reproduce this on my end. 

In the end, I rolled my own user db, OAuth and Billing code because at least I can control and understand everything happening during the installation process. Good luck. 

Lastly, you might have better luck raising this as an issue in the shopify_app github repo. 

seriousdev
Excursionist
17 0 2

@selina10261 the authentication failure error was resolved after I updated my app from Shopify partners dashboard to be a Non Embedded app. I've also set my app to be a non-embedded app in my app's config in config/initializers/shopify_app.rb file.

seriousdev
Excursionist
17 0 2

Sorry, I made a mistake in my post above. The reply I got from the tester about the Cookies was that they had disabled 3rd party cookies, because Shopify does not allow Embeddded apps with 3rd party cookies.

The problem here is that My app is NOT AN EMBEDDED APP, and it relies on Cookies for authentication. I believe that this could be the reason for Authentication failure and Invalid site errors.

@jam_chan, @policenauts what do you guys think, could this be the reason of all this problem?

and would it help that my app is NON EMBEDDED? would it be acceptable this way that it is a NON EMBEDDED app and uses Cookies?

jam_chan
Shopify Partner
891 23 171
If it is a standalone app, there is no 3rd party cookie issue since your
app doesn't live in a iframe. Your cookie can work without problems unless
the user block your site cookie.

I turned my app from embedded to standalone and the session can persist.
BYOB - Build Your Own Bundles, SPO - SEO App to research keywords & edit social link preview
seriousdev
Excursionist
17 0 2

Do you have any guess or idea what could cause the auth failure when merchant goes to https://his-store.myshopify/admin/apps and then clicks on the app? It definitely says invalid site but it does not make sense how could it just become invalid like that.

Also, doing this on my end does not encounter any error, even on Chrome incognito mode. It is very strange that this happens only on their end.
I've posted this issue on shopify_app gem's github repo as well.

jam_chan
Shopify Partner
891 23 171

Perhaps you didn't change the app to non-embedded. By default, all apps are embedded apps when it's created. You have to change the settings in the app setup page. From the screencast, your app is staying in the iframe. If it's a non-embedded app, it's going to open a new tab

BYOB - Build Your Own Bundles, SPO - SEO App to research keywords & edit social link preview
seriousdev
Excursionist
17 0 2

oh man! I had forgotten to change the app to Non embedded on the Shopify partners portal for the production version of the app, that's what was causing the issue. Thanks you've caught the issue precisely!

However, even if the authenticated issue is resolved the app is not behaving as expected. When it is run in Chrome incognito(3rd party cookies disabled) it becomes an embedded app(strange because now it is declared Non-embedded both in the code and the Shopify app settings).
Here is the response I received from the review team

seriousdev_0-1619595361878.png

 

I have no idea what is wrong with it and cannot even know how to debug this!

jam_chan
Shopify Partner
891 23 171
If you don't turn force_redirect to false in app bridge, it will be
redirected to iframe.

Hey man, you have to read the sample code base. Your understanding is not
deep enough to troubleshoot
BYOB - Build Your Own Bundles, SPO - SEO App to research keywords & edit social link preview
seriousdev
Excursionist
17 0 2

true, my understanding is not good at the moment, as it's my first experience with this whole platform and developing my first app. I'm open to read anything that helps. Is there a link to documentation you're referring to?

Plus I'm not using Shopify app bridge anywhere. When I created the project the app-bridge code was throwing errors(this error) I couldn't find a fix anywhere for it and I did not have to use it specifically so I deleted that javascript code and then my app worked fine afterwards.

Is there a way to disable this redirect without introducing app bridge because apparently it just breaks on the very first line(tested by creating a fresh project as well and it throws the same error). Or do I need to include it to fix this issue?
The code crashes as it fails to find an html element with an id 'shopify-app-init'. There's no place where I could find about this thing and ended up deleting it, as it wasn't being used anyways.

jam_chan
Shopify Partner
891 23 171

You can read some docs here:

https://shopify.dev/concepts/apps/building-embedded-apps-using-session-tokens

https://shopify.dev/tutorials/authenticate-your-app-using-session-tokens

https://shopify.dev/tutorials/authenticate-with-oauth

App bridge is used by embedded apps to bypass 3rd party cookies via session token auth. It is the tool to generate the token, think of it working like the token generator hardware for logging in to your bank (common in Hong Kong). If you are developing a standalone app, App bridge is not necessary. If I don't remember wrong, App bridge must live under the Shopify portal. Otherwise, it will cause an error on the browser console.

If you're not using it, it won't cause a force redirect. 

My experience is limited to App bridge, Django, python. If your error is related to Ruby (like wrong routing), I've no knowledge in this area.

BYOB - Build Your Own Bundles, SPO - SEO App to research keywords & edit social link preview
jam_chan
Shopify Partner
891 23 171

The code crashes as it fails to find an html element with an id 'shopify-app-init'.

Finally, I suggest you better utilize your IDE, just use the find-everywhere feature to find this id. My IDE atom can help me to identify this element without a few seconds. 

BYOB - Build Your Own Bundles, SPO - SEO App to research keywords & edit social link preview
seriousdev
Excursionist
17 0 2

the code to generate this div is there and it is generated by default(I have not changed anything in it to make it break) but it does not render the element with that DOM id. That's is why the javascript fails to find that element and runs into a crash. However, it's crashing in a fresh generated project as well so it has nothing to do with me breaking it.