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.

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

Better log levels in the message publisher #343

Merged
merged 2 commits into from
Feb 26, 2020
Merged

Better log levels in the message publisher #343

merged 2 commits into from
Feb 26, 2020

Conversation

sdwolfz
Copy link
Contributor

@sdwolfz sdwolfz commented Feb 19, 2020

Having the entire payload logged at the "INFO" level is not ideal due to
the following reasons:

  • PII data might be contained there and there is no way to fitler it out
  • Payload might be big enough that logging aggregators might struggle with
    the sheer amount of data
  • Since the log level is shared by reusing the rails/sinatra logger, INFO level
    might be too verbose for hutch but WARN level not verbose enough for the other.

While initially I considered implementing a feature to allow for filtering
the payload for PII or triming the output, a quick solution to all problems
listed above is to split the logging into two, the INFO level handing the
generic part of the log, with the message ID injected for easy tracking
and in case the payload is needed, log level can be set to DEBUG, which
should only be needed in development/testing environments.

lib/hutch/publisher.rb Outdated Show resolved Hide resolved
@sdwolfz
Copy link
Contributor Author

sdwolfz commented Feb 19, 2020

I pushed a commit to fix the tests on older ruby versions; filter is an alias of select. Please review them independently.

lib/hutch/publisher.rb Outdated Show resolved Hide resolved
@@ -184,7 +184,7 @@ def bindings

filtered = api_client.bindings.
reject { |b| b['destination'] == b['routing_key'] }.
filter { |b| b['source'] == @config[:mq_exchange] && b['vhost'] == @config[:mq_vhost] }
select { |b| b['source'] == @config[:mq_exchange] && b['vhost'] == @config[:mq_vhost] }
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

How is this change relevant?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This fixes build failures for older ruby versions, see travis builds: https://travis-ci.org/gocardless/hutch/jobs/652451121?utm_medium=notification&utm_source=github_status

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Understood, thanks.

Copy link
Member

@michaelklishin michaelklishin left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Actually, should we log publishes at debug level? Publishes can happen at a rate of hundreds or thousands per second, I really doubt it makes much sense to log at info level regardless of message size.

@sdwolfz
Copy link
Contributor Author

sdwolfz commented Feb 25, 2020

Actually, should we log publishes at debug level? Publishes can happen at a rate of hundreds or thousands per second, I really doubt it makes much sense to log at info level regardless of message size.

I'm fine with any solution as long as the current verbosity goes down. Just let me know what changes you want me to make.

@michaelklishin
Copy link
Member

@sdwolfz let's keep the changes you have but change publish logging level to debug. Thank you.

@sdwolfz
Copy link
Contributor Author

sdwolfz commented Feb 25, 2020

@sdwolfz let's keep the changes you have but change publish logging level to debug. Thank you.

Are you sure you want to have two logging.debug calls there? I could revert the entire change and not pass the message_id anymore, just having the info call replaced with debug.

@michaelklishin
Copy link
Member

Good point. I think simply switching to debug logging would be best.

Having the entire payload logged at the "INFO" level is not ideal due to
the following reasons:
- PII data might be contained there and there is no way to fitler it out
- Payload might be big enough that logging aggregators might struggle with
the sheer amount of data
- Since the log level is shared by reusing the rails/sinatra logger, INFO
level might be too verbose for hutch but WARN level not verbose enough for
the other.

While initially I considered implementing a feature to allow for filtering
the payload for PII or triming the output, a quick solution to all problems
listed above is to change the logging statement to DEBUG, which should only
be needed in development/testing environments.
@sdwolfz
Copy link
Contributor Author

sdwolfz commented Feb 26, 2020

@michaelklishin all done! ♻️ 🙏

@michaelklishin michaelklishin merged commit 10e71d4 into ruby-amqp:master Feb 26, 2020
@michaelklishin
Copy link
Member

Thank you!

@sdwolfz
Copy link
Contributor Author

sdwolfz commented Feb 27, 2020

Cheers mate!

Any hint on when this will be released to rubygems?

@michaelklishin
Copy link
Member

We haven't updated release notes in a while so it will take some time. Hopefully in the next few days.

@sdwolfz sdwolfz deleted the better_logging branch February 27, 2020 13:03
@sdwolfz
Copy link
Contributor Author

sdwolfz commented Mar 2, 2020

@michaelklishin Can I help with that? I assume I need to open a PR with changelog lines for all PRs since the last tag.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

3 participants