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

Add thread-local log level #85

Merged
merged 6 commits into from Feb 10, 2023
Merged

Add thread-local log level #85

merged 6 commits into from Feb 10, 2023

Conversation

mperham
Copy link
Contributor

@mperham mperham commented Jan 15, 2023

This adds Logger#with_level which provides a thread-local log level so Threads can temporarily enable logging for a given block.

log = Logger.new
log.level = :info

Thread.new do
  log.with_level(:debug) do
    log.debug("Will log")
  end
end.join

log.debug("Won't log")

Fixes #84

lib/logger.rb Outdated
# logger.with_level(:debug) do
# logger.debug { "Hello" }
# end
def with_level(severity, &block)
Copy link
Contributor Author

Choose a reason for hiding this comment

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

Alternative name: at?

log.at(:debug) do
  log.debug("You'll see this")
end

Copy link
Member

Choose a reason for hiding this comment

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

I think with_level is much more clear what is going on.

Copy link
Contributor

Choose a reason for hiding this comment

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

&block is not needed, since you are only yielding and not capturing.

@ioquatix ioquatix self-requested a review February 7, 2023 00:44
@ioquatix
Copy link
Member

ioquatix commented Feb 7, 2023

Sorry, I did not see this. Please mention me or add me as a reviewer in the future, otherwise I don't know about it :)

Copy link
Member

@ioquatix ioquatix left a comment

Choose a reason for hiding this comment

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

LGTM.

Copy link
Contributor

@jeremyevans jeremyevans left a comment

Choose a reason for hiding this comment

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

I'm OK with the idea, but I'm against pollute Thread.current with this. Instead, add a instance variable storing a hash inside the logger keyed by Thread.current. This approach also makes it simple to change from a thread-local implementation to a fiber-local or global implementation by changing the key.

lib/logger/severity.rb Outdated Show resolved Hide resolved
lib/logger.rb Outdated
# logger.with_level(:debug) do
# logger.debug { "Hello" }
# end
def with_level(severity, &block)
Copy link
Contributor

Choose a reason for hiding this comment

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

&block is not needed, since you are only yielding and not capturing.

@ioquatix
Copy link
Member

ioquatix commented Feb 9, 2023

Thanks @jeremyevans, great review. What do you think about using Fiber[] instead of strictly fiber/thread local? I'm not sure anyone want's to use Thread.current as the key. The current implementation would be equivalent to Fiber.current.

It might make sense just to leave this as implementation dependent so that other loggers (e.g. the ones I maintain) can be fiber-specific or use fiber-storage instead.

@mperham
Copy link
Contributor Author

mperham commented Feb 9, 2023

Ok, refactored based on feedback.

Copy link
Contributor

@jeremyevans jeremyevans left a comment

Choose a reason for hiding this comment

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

Looks pretty good. One more implementation change requested.

lib/logger.rb Outdated Show resolved Hide resolved
lib/logger/severity.rb Outdated Show resolved Hide resolved
lib/logger.rb Outdated Show resolved Hide resolved
mperham and others added 2 commits February 9, 2023 16:50
Co-authored-by: Samuel Williams <samuel.williams@oriontransfer.co.nz>
@ioquatix
Copy link
Member

Sorry, one more change is required, we will need to add require 'fiber' for Fiber.current to work.

Copy link
Contributor

@jeremyevans jeremyevans left a comment

Choose a reason for hiding this comment

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

Couple of small things that could be fixed, but I don't think need to block merging.

CHANGELOG.md Outdated Show resolved Hide resolved
logger.with_level(DEBUG) do # verify reentrancy
assert_equal(logger.level, DEBUG)

Thread.new do
Copy link
Contributor

Choose a reason for hiding this comment

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

This tests for Thread-local, not explicitly for Fiber-local, but works since a new Thread is also a new Fiber. Not sure if we want to explicitly test for Fiber-localness. Could be done later.

@mperham
Copy link
Contributor Author

mperham commented Feb 10, 2023

Sorry, one more change is required, we will need to add require 'fiber' for Fiber.current to work.

Really? irb 3.2 works fine without it:

% irb
> Fiber.current
=> #<Fiber:0x00000001051c8698 (resumed)>

@jeremyevans
Copy link
Contributor

According to CI, logger supports Ruby 2.5+ (gem says Ruby 2.3+).

@mperham
Copy link
Contributor Author

mperham commented Feb 10, 2023

According to CI, logger supports Ruby 2.5+ (gem says Ruby 2.3+).

Right, looks like 3.1+ doesn't require "fiber" anymore.

@ioquatix ioquatix merged commit 7aabb0b into ruby:master Feb 10, 2023
matzbot pushed a commit to ruby/ruby that referenced this pull request Feb 10, 2023
@ioquatix
Copy link
Member

Thanks @mperham - I want to make one more PR and then we will try to cut a release.

@yahonda
Copy link

yahonda commented Feb 14, 2023

This commit introduces NoMethodError: undefined method []' for nil:NilClass`
reported at resque/resque#1856

sambostock added a commit to sambostock/mono_logger that referenced this pull request Feb 15, 2023
ruby/logger#85 added this to the `Logger` initializer.

Since we don't call `super` in `initialize`, we need to do it ourselves.

Not doing this leads to an error in `Logger#level`:

    # undefined method `[]' for nil:NilClass (NoMethodError):

    def level
      @level_override[Fiber.current] || @Level
      #              ^^^^^^^^^^^^^^^
    end
sambostock added a commit to sambostock/mono_logger that referenced this pull request Feb 15, 2023
ruby/logger#85 added this to the `Logger` initializer.

Since we don't call `super` in `initialize`, we need to do it ourselves.

Not doing this leads to an error in `Logger#level`:

```ruby

def level
  @level_override[Fiber.current] || @Level
  #              ^^^^^^^^^^^^^^^
end
```
sambostock added a commit to sambostock/mono_logger that referenced this pull request Feb 28, 2023
ruby/logger#85 added `@level_override` to the `Logger` initializer.

Since we didn't call `super` in `initialize`, the variable was
uninitialized, and we would run into a `NoMethodError` in `Logger#level`
on Ruby HEAD:

    def level
      @level_override[Fiber.current] || @Level
      #              ^^^^^^^^^^^^^^^ NoMethodError: undefined method `[]' for nil:NilClass
    end
kou added a commit to kou/jekyll that referenced this pull request Jun 25, 2023
logger 1.4.3 will have ruby/logger#85. It initializes a new instance
variable in `Logger#initialize`. `Jekyll::Stevenson < ::Logger`
doesn't use `super`. So the new instance variable isn't initialized in
`Jekyll::Stevenson`. And it causes an exception:

```text
/tmp/local/lib/ruby/3.3.0+0/logger.rb:385:in `level': undefined method `[]' for nil (NoMethodError)

    @level_override[Fiber.current] || @Level
                   ^^^^^^^^^^^^^^^
	from /tmp/local/lib/ruby/gems/3.3.0+0/gems/jekyll-4.3.2/lib/jekyll/log_adapter.rb:45:in `adjust_verbosity'
	from /tmp/local/lib/ruby/gems/3.3.0+0/gems/jekyll-4.3.2/lib/jekyll/configuration.rb:143:in `config_files'
	from /tmp/local/lib/ruby/gems/3.3.0+0/gems/jekyll-4.3.2/lib/jekyll.rb:118:in `configuration'
	from /tmp/local/lib/ruby/gems/3.3.0+0/gems/jekyll-4.3.2/lib/jekyll/command.rb:44:in `configuration_from_options'
	from /tmp/local/lib/ruby/gems/3.3.0+0/gems/jekyll-4.3.2/lib/jekyll/commands/serve.rb:83:in `block (2 levels) in init_with_program'
	from /tmp/local/lib/ruby/gems/3.3.0+0/gems/mercenary-0.4.0/lib/mercenary/command.rb:221:in `block in execute'
	from /tmp/local/lib/ruby/gems/3.3.0+0/gems/mercenary-0.4.0/lib/mercenary/command.rb:221:in `each'
	from /tmp/local/lib/ruby/gems/3.3.0+0/gems/mercenary-0.4.0/lib/mercenary/command.rb:221:in `execute'
	from /tmp/local/lib/ruby/gems/3.3.0+0/gems/mercenary-0.4.0/lib/mercenary/program.rb:44:in `go'
	from /tmp/local/lib/ruby/gems/3.3.0+0/gems/mercenary-0.4.0/lib/mercenary.rb:21:in `program'
	from /tmp/local/lib/ruby/gems/3.3.0+0/gems/jekyll-4.3.2/exe/jekyll:15:in `<top (required)>'
	from /tmp/local/bin/jekyll:25:in `load'
	from /tmp/local/bin/jekyll:25:in `<top (required)>'
	from /tmp/local/lib/ruby/3.3.0+0/bundler/cli/exec.rb:58:in `load'
	from /tmp/local/lib/ruby/3.3.0+0/bundler/cli/exec.rb:58:in `kernel_load'
	from /tmp/local/lib/ruby/3.3.0+0/bundler/cli/exec.rb:23:in `run'
	from /tmp/local/lib/ruby/3.3.0+0/bundler/cli.rb:492:in `exec'
	from /tmp/local/lib/ruby/3.3.0+0/bundler/vendor/thor/lib/thor/command.rb:27:in `run'
	from /tmp/local/lib/ruby/3.3.0+0/bundler/vendor/thor/lib/thor/invocation.rb:127:in `invoke_command'
	from /tmp/local/lib/ruby/3.3.0+0/bundler/vendor/thor/lib/thor.rb:392:in `dispatch'
	from /tmp/local/lib/ruby/3.3.0+0/bundler/cli.rb:34:in `dispatch'
	from /tmp/local/lib/ruby/3.3.0+0/bundler/vendor/thor/lib/thor/base.rb:485:in `start'
	from /tmp/local/lib/ruby/3.3.0+0/bundler/cli.rb:28:in `start'
	from /tmp/local/lib/ruby/gems/3.3.0+0/gems/bundler-2.5.0.dev/libexec/bundle:37:in `block in <top (required)>'
	from /tmp/local/lib/ruby/3.3.0+0/bundler/friendly_errors.rb:117:in `with_friendly_errors'
	from /tmp/local/lib/ruby/gems/3.3.0+0/gems/bundler-2.5.0.dev/libexec/bundle:29:in `<top (required)>'
	from /tmp/local/bin/bundle:25:in `load'
	from /tmp/local/bin/bundle:25:in `<main>'
```

How about using `super` instead of implementing our
`Jekyll::Stevenson#initialize` to reduce maintenance cost?
kou added a commit to kou/jekyll that referenced this pull request Jun 25, 2023
logger 1.4.3 will have ruby/logger#85. It initializes a new instance
variable in `Logger#initialize`. `Jekyll::Stevenson < ::Logger`
doesn't use `super`. So the new instance variable isn't initialized in
`Jekyll::Stevenson`. And it causes an exception:

```text
/tmp/local/lib/ruby/3.3.0+0/logger.rb:385:in `level': undefined method `[]' for nil (NoMethodError)

    @level_override[Fiber.current] || @Level
                   ^^^^^^^^^^^^^^^
	from /tmp/local/lib/ruby/gems/3.3.0+0/gems/jekyll-4.3.2/lib/jekyll/log_adapter.rb:45:in `adjust_verbosity'
	from /tmp/local/lib/ruby/gems/3.3.0+0/gems/jekyll-4.3.2/lib/jekyll/configuration.rb:143:in `config_files'
	from /tmp/local/lib/ruby/gems/3.3.0+0/gems/jekyll-4.3.2/lib/jekyll.rb:118:in `configuration'
	from /tmp/local/lib/ruby/gems/3.3.0+0/gems/jekyll-4.3.2/lib/jekyll/command.rb:44:in `configuration_from_options'
	from /tmp/local/lib/ruby/gems/3.3.0+0/gems/jekyll-4.3.2/lib/jekyll/commands/serve.rb:83:in `block (2 levels) in init_with_program'
	from /tmp/local/lib/ruby/gems/3.3.0+0/gems/mercenary-0.4.0/lib/mercenary/command.rb:221:in `block in execute'
	from /tmp/local/lib/ruby/gems/3.3.0+0/gems/mercenary-0.4.0/lib/mercenary/command.rb:221:in `each'
	from /tmp/local/lib/ruby/gems/3.3.0+0/gems/mercenary-0.4.0/lib/mercenary/command.rb:221:in `execute'
	from /tmp/local/lib/ruby/gems/3.3.0+0/gems/mercenary-0.4.0/lib/mercenary/program.rb:44:in `go'
	from /tmp/local/lib/ruby/gems/3.3.0+0/gems/mercenary-0.4.0/lib/mercenary.rb:21:in `program'
	from /tmp/local/lib/ruby/gems/3.3.0+0/gems/jekyll-4.3.2/exe/jekyll:15:in `<top (required)>'
	from /tmp/local/bin/jekyll:25:in `load'
	from /tmp/local/bin/jekyll:25:in `<top (required)>'
	from /tmp/local/lib/ruby/3.3.0+0/bundler/cli/exec.rb:58:in `load'
	from /tmp/local/lib/ruby/3.3.0+0/bundler/cli/exec.rb:58:in `kernel_load'
	from /tmp/local/lib/ruby/3.3.0+0/bundler/cli/exec.rb:23:in `run'
	from /tmp/local/lib/ruby/3.3.0+0/bundler/cli.rb:492:in `exec'
	from /tmp/local/lib/ruby/3.3.0+0/bundler/vendor/thor/lib/thor/command.rb:27:in `run'
	from /tmp/local/lib/ruby/3.3.0+0/bundler/vendor/thor/lib/thor/invocation.rb:127:in `invoke_command'
	from /tmp/local/lib/ruby/3.3.0+0/bundler/vendor/thor/lib/thor.rb:392:in `dispatch'
	from /tmp/local/lib/ruby/3.3.0+0/bundler/cli.rb:34:in `dispatch'
	from /tmp/local/lib/ruby/3.3.0+0/bundler/vendor/thor/lib/thor/base.rb:485:in `start'
	from /tmp/local/lib/ruby/3.3.0+0/bundler/cli.rb:28:in `start'
	from /tmp/local/lib/ruby/gems/3.3.0+0/gems/bundler-2.5.0.dev/libexec/bundle:37:in `block in <top (required)>'
	from /tmp/local/lib/ruby/3.3.0+0/bundler/friendly_errors.rb:117:in `with_friendly_errors'
	from /tmp/local/lib/ruby/gems/3.3.0+0/gems/bundler-2.5.0.dev/libexec/bundle:29:in `<top (required)>'
	from /tmp/local/bin/bundle:25:in `load'
	from /tmp/local/bin/bundle:25:in `<main>'
```

How about using `super` instead of implementing our
`Jekyll::Stevenson#initialize` to reduce maintenance cost?
kou added a commit to kou/jekyll that referenced this pull request Jun 25, 2023
logger 1.4.3 will have ruby/logger#85. It initializes a new instance
variable in `Logger#initialize`. `Jekyll::Stevenson < ::Logger`
doesn't use `super`. So the new instance variable isn't initialized in
`Jekyll::Stevenson`. And it causes an exception:

```text
/tmp/local/lib/ruby/3.3.0+0/logger.rb:385:in `level': undefined method `[]' for nil (NoMethodError)

    @level_override[Fiber.current] || @Level
                   ^^^^^^^^^^^^^^^
	from /tmp/local/lib/ruby/gems/3.3.0+0/gems/jekyll-4.3.2/lib/jekyll/log_adapter.rb:45:in `adjust_verbosity'
	from /tmp/local/lib/ruby/gems/3.3.0+0/gems/jekyll-4.3.2/lib/jekyll/configuration.rb:143:in `config_files'
	from /tmp/local/lib/ruby/gems/3.3.0+0/gems/jekyll-4.3.2/lib/jekyll.rb:118:in `configuration'
	from /tmp/local/lib/ruby/gems/3.3.0+0/gems/jekyll-4.3.2/lib/jekyll/command.rb:44:in `configuration_from_options'
	from /tmp/local/lib/ruby/gems/3.3.0+0/gems/jekyll-4.3.2/lib/jekyll/commands/serve.rb:83:in `block (2 levels) in init_with_program'
	from /tmp/local/lib/ruby/gems/3.3.0+0/gems/mercenary-0.4.0/lib/mercenary/command.rb:221:in `block in execute'
	from /tmp/local/lib/ruby/gems/3.3.0+0/gems/mercenary-0.4.0/lib/mercenary/command.rb:221:in `each'
	from /tmp/local/lib/ruby/gems/3.3.0+0/gems/mercenary-0.4.0/lib/mercenary/command.rb:221:in `execute'
	from /tmp/local/lib/ruby/gems/3.3.0+0/gems/mercenary-0.4.0/lib/mercenary/program.rb:44:in `go'
	from /tmp/local/lib/ruby/gems/3.3.0+0/gems/mercenary-0.4.0/lib/mercenary.rb:21:in `program'
	from /tmp/local/lib/ruby/gems/3.3.0+0/gems/jekyll-4.3.2/exe/jekyll:15:in `<top (required)>'
	from /tmp/local/bin/jekyll:25:in `load'
	from /tmp/local/bin/jekyll:25:in `<top (required)>'
	from /tmp/local/lib/ruby/3.3.0+0/bundler/cli/exec.rb:58:in `load'
	from /tmp/local/lib/ruby/3.3.0+0/bundler/cli/exec.rb:58:in `kernel_load'
	from /tmp/local/lib/ruby/3.3.0+0/bundler/cli/exec.rb:23:in `run'
	from /tmp/local/lib/ruby/3.3.0+0/bundler/cli.rb:492:in `exec'
	from /tmp/local/lib/ruby/3.3.0+0/bundler/vendor/thor/lib/thor/command.rb:27:in `run'
	from /tmp/local/lib/ruby/3.3.0+0/bundler/vendor/thor/lib/thor/invocation.rb:127:in `invoke_command'
	from /tmp/local/lib/ruby/3.3.0+0/bundler/vendor/thor/lib/thor.rb:392:in `dispatch'
	from /tmp/local/lib/ruby/3.3.0+0/bundler/cli.rb:34:in `dispatch'
	from /tmp/local/lib/ruby/3.3.0+0/bundler/vendor/thor/lib/thor/base.rb:485:in `start'
	from /tmp/local/lib/ruby/3.3.0+0/bundler/cli.rb:28:in `start'
	from /tmp/local/lib/ruby/gems/3.3.0+0/gems/bundler-2.5.0.dev/libexec/bundle:37:in `block in <top (required)>'
	from /tmp/local/lib/ruby/3.3.0+0/bundler/friendly_errors.rb:117:in `with_friendly_errors'
	from /tmp/local/lib/ruby/gems/3.3.0+0/gems/bundler-2.5.0.dev/libexec/bundle:29:in `<top (required)>'
	from /tmp/local/bin/bundle:25:in `load'
	from /tmp/local/bin/bundle:25:in `<main>'
```

How about using `super` instead of implementing our
`Jekyll::Stevenson#initialize` to reduce maintenance cost?
@jaynetics
Copy link

This commit introduces NoMethodError: undefined method []' for nil:NilClass`
reported at resque/resque#1856

Generally speaking, this breaks any logger subclass that does not call super in its initializer. jekyll is another gem affected by this on Ruby 3.3, and there might be more. @ioquatix i wonder whether avoiding this breaking change might be worth a little amendment, like extracting @level_override into def level_override; @level_override ||= {} end or so?

@mperham
Copy link
Contributor Author

mperham commented Jul 9, 2023

I don't believe adding additional complexity to work around 3rd party bugs is a good idea. Not calling super is a bug, no?

@skipkayhil
Copy link

I want to make one more PR and then we will try to cut a release.

Hey @ioquatix, did that other PR ever land? I'd love to see this released so we could potentially use it to replace the LoggerThreadSafeLevel patch in Rails

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

Successfully merging this pull request may close these issues.

Per-thread log level?
6 participants