Adding Debug Logs #1545

klenotiw · 2022-10-21T12:42:51Z

What this PR does

This is intended to add logs to critical areas of the code to ease the pain of debugging.

closes https://github.com/Shopify/first-party-library-planning/issues/482

Reviewer's guide to testing

Read through all of the logs. If you are really cool you can test some logs out by using a testing app.

Things to focus on

Does this PR follow our logging approach?
Read logging messages to makes sure they sound clear and make sense.
Should we add logs anywhere else?
Do the logs fall in the correct level?

Checklist

Before submitting the PR, please consider if any of the following are needed:

Update CHANGELOG.md if the changes would impact users
Update README.md, if appropriate.
Update any relevant pages in /docs, if necessary
For security fixes, the Disclosure Policy must be followed.

lib/shopify_app/controller_concerns/login_protection.rb

nelsonwittwer

Looking good so far! Do you think you could include docs for configuring logging for our users who aren't familiar with how rails logging config works.

lib/shopify_app/controller_concerns/login_protection.rb

lib/shopify_app/managers/webhooks_manager.rb

app/controllers/shopify_app/sessions_controller.rb

lib/shopify_app/controller_concerns/login_protection.rb

lib/shopify_app/session/jwt.rb

lib/shopify_app/controller_concerns/redirect_for_embedded.rb

README.md

docs/shopify_app/logging.md

lib/shopify_app/utils.rb

app/controllers/shopify_app/callback_controller.rb

docs/shopify_app/logging.md

lib/generators/shopify_app/install/templates/shopify_app.rb.tt

lib/shopify_app/session/session_repository.rb

lib/shopify_app/utils.rb

README.md

app/controllers/shopify_app/extension_verification_controller.rb

nelsonwittwer · 2022-11-08T15:12:07Z

app/controllers/shopify_app/sessions_controller.rb

        if embedded_param?
+          ShopifyApp::Utils::Logger.debug("Embedded param")


I wonder if we can give more context on this. What is an embedded param and how was it determined?

Oh I think this is telling the session_controller if the app is embedded or not? At one point we wanted to log all of the conditionals in the authenticate method. Do you think we should just remove these logs?

nelsonwittwer · 2022-11-08T15:13:04Z

app/controllers/shopify_app/sessions_controller.rb

          redirect_for_embedded
        else
          start_oauth
        end
      elsif top_level?
+        ShopifyApp::Utils::Logger.debug("Top level redirect")


I'm not familiar with what a top level redirect is. If we are logging it, I'd love to give a clue as to why this is important.

I think this was suppose to help debug the redirect loops. I think the top level is the last redirect but I could be wrong. But we are already logging inside redirect_auth_to_top_level so I think we can just remove this? (and it looks like its in the wrong place)

docs/shopify_app/logging.md

lib/shopify_app/controller_concerns/ensure_billing.rb

lib/shopify_app/controller_concerns/login_protection.rb

lib/shopify_app/controller_concerns/webhook_verification.rb

lib/shopify_app/session/session_repository.rb

andyw8 · 2022-11-08T16:15:47Z

@nelsonwittwer These are lots of good suggestions about what to log, but I wonder if we should try get a first iteration out and then refine it?

andyw8 · 2022-11-08T16:17:14Z

Also, I wonder if we should make a 'quiet' release first, and enable it on some internal apps, before we publicize this in the README?

klenotiw · 2022-11-09T16:04:01Z

test/test_helper.rb

@@ -47,6 +47,7 @@ def before_setup
    ShopifyApp::InMemorySessionStore.clear
    ShopifyAppConfigurer.call
    Rails.application.reload_routes!
+    ShopifyApp.configuration.log_level = :warn


I had to set a log_level for our tests. I decided on warn instead of off because some tests are expecting to see some logs come through. All of those tests are rescued errors so I figured warn was the best level. LMK what you think

lib/generators/shopify_app/install/templates/shopify_app.rb.tt

lib/shopify_app/logger.rb

andyw8 · 2022-11-09T21:02:32Z

We also need a CHANGELOG entry.

lib/shopify_app/logger.rb

klenotiw · 2022-11-09T21:41:19Z

docs/shopify_app/logging.md

+
+## Upgrading
+
+Make sure to add the `config.log_level` setting to your configuration file so you can start changing the log level to your preference. If `log_level` isn't found if your configuration settings then it will default to the `:info` level.


Also added this upgrading section. (wasn't sure if this is the best place)

teddyhwang

I'm not sure if it's necessary but it would be nice to have the same log language as we do across the libraries so that we can have the same tone and content

teddyhwang · 2022-11-10T18:39:39Z

lib/shopify_app/controller_concerns/ensure_billing.rb

@@ -55,6 +56,7 @@ def has_active_payment?(session)
    end

    def has_subscription?(session)
+      ShopifyApp::Logger.debug("Checking if has subscription")


checking if what has subscription?

Maybe "Checking if session has subscription" would have better? Nelson wanted to have these logs here because has_active_payment? had a lot of conditionals.

I don't think that's what is happening. Seeing the two lines below, I think we're making a API call using the session to check if the shop has a subscription (please validate though I'm only guessing)

Yeah as far as I can tell thats whats happening, "Checking if shop has subscription" would probably be more clear.

lib/shopify_app/controller_concerns/login_protection.rb

teddyhwang · 2022-11-10T18:40:36Z

lib/shopify_app/controller_concerns/login_protection.rb

@@ -32,6 +35,7 @@ def activate_shopify_session
        ShopifyAPI::Context.activate_session(current_shopify_session)
        yield
      ensure
+        ShopifyApp::Logger.debug("Deactivating Session")


How come for some logs we capitalize each word like it's a title? Is this a format that we're doing in the node library as well /cc @paulomarg

No, we've used sentence case pretty much everywhere for node!

ok just went through and tried to clean that up

lib/shopify_app/controller_concerns/login_protection.rb

CHANGELOG.md

app/controllers/concerns/shopify_app/ensure_authenticated_links.rb

app/controllers/shopify_app/callback_controller.rb

app/controllers/shopify_app/extension_verification_controller.rb

teddyhwang · 2022-11-10T20:56:52Z

app/controllers/shopify_app/sessions_controller.rb

        if embedded_param?
+          ShopifyApp::Logger.debug("Embedded param")


Do we really need this level of detail? If so, I would change the messaging to something like

Suggested change

ShopifyApp::Logger.debug("Embedded param")

ShopifyApp::Logger.debug("Detected embedded parameter and redirecting to ____")

I say we just remove this since we already have a log in redirect_for_embedded. I think the original idea was to separate out all of the conditionals in the authenticate method.

teddyhwang · 2022-11-10T20:57:26Z

app/controllers/shopify_app/sessions_controller.rb

          redirect_for_embedded
        else
          start_oauth
        end
      elsif top_level?
+        ShopifyApp::Logger.debug("Top level redirect")


this log is not informative enough for me to understand what is happening

These logs were just to break up the conditionals in the authenticate method but I guess we can just remove them?

teddyhwang · 2022-11-10T20:59:27Z

lib/shopify_app/controller_concerns/ensure_billing.rb

@@ -55,6 +56,7 @@ def has_active_payment?(session)
    end

    def has_subscription?(session)
+      ShopifyApp::Logger.debug("Checking if has subscription")


I don't think that's what is happening. Seeing the two lines below, I think we're making a API call using the session to check if the shop has a subscription (please validate though I'm only guessing)

teddyhwang · 2022-11-10T21:00:34Z

lib/shopify_app/controller_concerns/login_protection.rb

@@ -16,8 +16,11 @@ module LoginProtection
    ACCESS_TOKEN_REQUIRED_HEADER = "X-Shopify-API-Request-Failure-Unauthorized"

    def activate_shopify_session
+      ShopifyApp::Logger.debug("Activating Shopify session")


Some of these method names are not ideal. What does activate shopify session mean here? Feel free to be more descriptive with the log and not just take the method name because the method name may not be even the ideal name to begin with

Maybe moving that log down to line 35 would be better. From what I can tell it sets the active session in the context.

lib/shopify_app/controller_concerns/login_protection.rb

lib/shopify_app/session/jwt.rb

lib/shopify_app/session/session_repository.rb

lib/shopify_app/controller_concerns/login_protection.rb

klenotiw · 2022-11-15T15:42:28Z

@nelsonwittwer and @andyw8 I think this is ready for another round of reviews. Sorry this is taking a minute, I really appreciate the help.

klenotiw commented Oct 21, 2022

View reviewed changes

lib/shopify_app/controller_concerns/login_protection.rb Outdated Show resolved Hide resolved

klenotiw requested a review from nelsonwittwer October 21, 2022 19:49

This comment was marked as resolved.

Sign in to view

klenotiw marked this pull request as ready for review October 24, 2022 13:21

nelsonwittwer reviewed Oct 24, 2022

View reviewed changes

lib/shopify_app/controller_concerns/login_protection.rb Outdated Show resolved Hide resolved

lib/shopify_app/controller_concerns/login_protection.rb Outdated Show resolved Hide resolved

lib/shopify_app/managers/webhooks_manager.rb Outdated Show resolved Hide resolved

This comment was marked as resolved.

Sign in to view

andyw8 reviewed Oct 28, 2022

View reviewed changes

app/controllers/shopify_app/sessions_controller.rb Outdated Show resolved Hide resolved

klenotiw commented Nov 2, 2022

View reviewed changes

lib/shopify_app/controller_concerns/login_protection.rb Outdated Show resolved Hide resolved

klenotiw commented Nov 2, 2022

View reviewed changes

lib/shopify_app/session/jwt.rb Outdated Show resolved Hide resolved

klenotiw commented Nov 2, 2022

View reviewed changes

lib/shopify_app/controller_concerns/redirect_for_embedded.rb Show resolved Hide resolved

This comment was marked as resolved.

Sign in to view

klenotiw requested review from nelsonwittwer and andyw8 November 2, 2022 21:10

klenotiw mentioned this pull request Nov 4, 2022

Renaming some Controller Concerns #1565

Closed

4 tasks

andyw8 reviewed Nov 7, 2022

View reviewed changes

README.md Outdated Show resolved Hide resolved

andyw8 reviewed Nov 7, 2022

View reviewed changes

docs/shopify_app/logging.md Outdated Show resolved Hide resolved

andyw8 reviewed Nov 7, 2022

View reviewed changes

lib/shopify_app/utils.rb Outdated Show resolved Hide resolved

andyw8 reviewed Nov 7, 2022

View reviewed changes

app/controllers/shopify_app/callback_controller.rb Outdated Show resolved Hide resolved

andyw8 reviewed Nov 7, 2022

View reviewed changes

docs/shopify_app/logging.md Outdated Show resolved Hide resolved

andyw8 reviewed Nov 7, 2022

View reviewed changes

lib/generators/shopify_app/install/templates/shopify_app.rb.tt Outdated Show resolved Hide resolved

andyw8 reviewed Nov 7, 2022

View reviewed changes

lib/shopify_app/session/session_repository.rb Outdated Show resolved Hide resolved

andyw8 reviewed Nov 7, 2022

View reviewed changes

lib/shopify_app/utils.rb Outdated Show resolved Hide resolved

nelsonwittwer requested changes Nov 8, 2022

View reviewed changes

klenotiw commented Nov 9, 2022

View reviewed changes

klenotiw requested review from nelsonwittwer and andyw8 November 9, 2022 17:13

klenotiw commented Nov 9, 2022

View reviewed changes

lib/generators/shopify_app/install/templates/shopify_app.rb.tt Outdated Show resolved Hide resolved

andyw8 reviewed Nov 9, 2022

View reviewed changes

lib/shopify_app/logger.rb Outdated Show resolved Hide resolved

andyw8 reviewed Nov 9, 2022

View reviewed changes

lib/shopify_app/logger.rb Outdated Show resolved Hide resolved

andyw8 reviewed Nov 9, 2022

View reviewed changes

lib/shopify_app/logger.rb Outdated Show resolved Hide resolved

klenotiw commented Nov 9, 2022

View reviewed changes

lib/shopify_app/logger.rb Show resolved Hide resolved

klenotiw commented Nov 9, 2022

View reviewed changes

teddyhwang reviewed Nov 10, 2022

View reviewed changes

andyw8 reviewed Nov 10, 2022

View reviewed changes

CHANGELOG.md Outdated Show resolved Hide resolved

paulomarg reviewed Nov 10, 2022

View reviewed changes

CHANGELOG.md Outdated Show resolved Hide resolved

teddyhwang reviewed Nov 10, 2022

View reviewed changes

andyw8 reviewed Nov 11, 2022

View reviewed changes

lib/shopify_app/controller_concerns/login_protection.rb Outdated Show resolved Hide resolved

klenotiw requested a review from andyw8 November 15, 2022 15:41

nelsonwittwer approved these changes Nov 15, 2022

View reviewed changes

add debug logs

92f127e

klenotiw force-pushed the klenotiw/add-log-levels branch from 38976f2 to 92f127e Compare November 15, 2022 20:42

klenotiw merged commit f338d67 into main Nov 15, 2022

klenotiw deleted the klenotiw/add-log-levels branch November 15, 2022 20:44

klenotiw mentioned this pull request Nov 15, 2022

Adding Deprecation Logs #1581

Merged

4 tasks

shopify-shipit bot temporarily deployed to rubygems December 9, 2022 17:09 Inactive

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Adding Debug Logs #1545

Adding Debug Logs #1545

klenotiw commented Oct 21, 2022 •

edited

Loading

This comment was marked as resolved.

nelsonwittwer left a comment

This comment was marked as resolved.

This comment was marked as resolved.

nelsonwittwer Nov 8, 2022

klenotiw Nov 9, 2022

nelsonwittwer Nov 8, 2022

klenotiw Nov 9, 2022

andyw8 commented Nov 8, 2022

andyw8 commented Nov 8, 2022

klenotiw Nov 9, 2022 •

edited

Loading

andyw8 commented Nov 9, 2022

klenotiw Nov 9, 2022

teddyhwang left a comment

teddyhwang Nov 10, 2022

klenotiw Nov 10, 2022

teddyhwang Nov 10, 2022

klenotiw Nov 15, 2022

teddyhwang Nov 10, 2022

paulomarg Nov 10, 2022

klenotiw Nov 10, 2022

teddyhwang Nov 10, 2022

klenotiw Nov 14, 2022 •

edited

Loading

teddyhwang Nov 10, 2022

klenotiw Nov 14, 2022

teddyhwang Nov 10, 2022

teddyhwang Nov 10, 2022

klenotiw Nov 15, 2022

klenotiw commented Nov 15, 2022

		if embedded_param?
		ShopifyApp::Utils::Logger.debug("Embedded param")


		## Upgrading

		Make sure to add the `config.log_level` setting to your configuration file so you can start changing the log level to your preference. If `log_level` isn't found if your configuration settings then it will default to the `:info` level.

		if embedded_param?
		ShopifyApp::Logger.debug("Embedded param")

	ShopifyApp::Logger.debug("Embedded param")
	ShopifyApp::Logger.debug("Detected embedded parameter and redirecting to ____")

Adding Debug Logs #1545

Adding Debug Logs #1545

Conversation

klenotiw commented Oct 21, 2022 • edited Loading

What this PR does

Reviewer's guide to testing

Things to focus on

Checklist

This comment was marked as resolved.

nelsonwittwer left a comment

Choose a reason for hiding this comment

This comment was marked as resolved.

This comment was marked as resolved.

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

andyw8 commented Nov 8, 2022

andyw8 commented Nov 8, 2022

klenotiw Nov 9, 2022 • edited Loading

Choose a reason for hiding this comment

andyw8 commented Nov 9, 2022

Choose a reason for hiding this comment

teddyhwang left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

klenotiw Nov 14, 2022 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

klenotiw commented Nov 15, 2022

klenotiw commented Oct 21, 2022 •

edited

Loading

klenotiw Nov 9, 2022 •

edited

Loading

klenotiw Nov 14, 2022 •

edited

Loading