why patch standard Logger -- conflicting with other gems patch to infinite loop

[jrochkind]

I am trying to debug something really odd that seems to involve Yell and the Rails6 zeitwerk auto-loader. If/when I get to the bottom of it, it yell is implicated, I will post a different report.

However, in trying to debug, I ran into something I didn't expect. In an area of code that I was not expecting to be using yell at all, but just using a standard ruby and/or Rails logger, I was still finding Yell in my stack trace.

Then I discovered yell is patching the ruby stdlib Logger class with custom behavior: https://github.com/rudionrails/yell/blob/master/lib/core_ext/logger.rb

I think in 2020 this is considered pretty bad behavior. It can cause unexpected problems. It is at least plausibly responsible for the really odd and hard to figure out problem I am currently banging my head against.

Is it really necessary? Why can't Yell simply provide the custom Yell logger, and leave stdlib logger untouched?

[rudionrails]

HI @jrochkind

this overloading was done to ensure backwards compatibility (https://github.com/rudionrails/yell/blob/master/spec/compatibility/level_spec.rb).

In case your request is related to a problem with Yell, it would be best to remove the library from your project. Try your code again and if the problem still exists, please provide the stacktrace for further investigation.

[jrochkind]

Hi, thanks for the response.

I'm not sure what you mean by "backwards compatibility" -- apparently you are trying to make sure that ordinary ruby Logger instances can act in some way as if they were Yell instances? That isn't normally what's meant by "backwards compatibility".

I wonder if you would consider a future yell release that does not do this patching, or makes it optional opt-in in some way? It would probably have to be a major version release, as it could break some apps, for sure.

I am having a lot of trouble getting to the bottom of the problem in my project -- it exhibits in a very odd way, I haven't been been able to demonstrate it in a simplified reproduction outside of my very complex project.

In my project, yell is not a direct dependency, but a transitive dependency -- a dependency of a dependency. And removing it would make the direct dependency stop working entirely. So it's not so easy to to remove.

One thing I have discovered is that putting an explicit require 'yell' into my project makes the problem go away. This is what makes me think this problem is somehow related to rails auto-loading. It may very well be a bug in Rails auto-loading, but it's very hard to track down, and I believe would not be appearing at all if weren't for the patching. (While I initially suspected it was Rails6-specific, I can actually reproduce it in my app under Rails 5.2 also).

I'll put the stack trace below, it's pretty impenetrable. But it's occuring from a portion of my app I didn't think was using yell at all, the only reason yell is involved at all is because of the patching, such that yell is involved in any use of any logger anywhere. :(

# these top lines repeat several thousand times, it's some kind of infinite loop, ending in a:
# SystemStackError:
#    stack level too deep

# /Users/jrochkind/.gem/ruby/2.6.6/gems/honeybadger-4.6.0/lib/honeybadger/breadcrumbs/logging.rb:17:in `add'
# /Users/jrochkind/.gem/ruby/2.6.6/gems/yell-2.2.2/lib/core_ext/logger.rb:12:in `add_with_yell'
# /Users/jrochkind/.gem/ruby/2.6.6/gems/honeybadger-4.6.0/lib/honeybadger/breadcrumbs/logging.rb:17:in `add'
# /Users/jrochkind/.gem/ruby/2.6.6/gems/yell-2.2.2/lib/core_ext/logger.rb:12:in `add_with_yell'
# /Users/jrochkind/.gem/ruby/2.6.6/gems/honeybadger-4.6.0/lib/honeybadger/breadcrumbs/logging.rb:17:in `add'
# /Users/jrochkind/.gem/ruby/2.6.6/gems/yell-2.2.2/lib/core_ext/logger.rb:12:in `add_with_yell'
# /Users/jrochkind/.gem/ruby/2.6.6/gems/honeybadger-4.6.0/lib/honeybadger/breadcrumbs/logging.rb:17:in `add'
# /Users/jrochkind/.gem/ruby/2.6.6/gems/activesupport-6.0.2.2/lib/active_support/logger_thread_safe_level.rb:53:in `add'
# /Users/jrochkind/.gem/ruby/2.6.6/gems/activesupport-6.0.2.2/lib/active_support/log_subscriber.rb:119:in `debug'
# /Users/jrochkind/.gem/ruby/2.6.6/gems/honeybadger-4.6.0/lib/honeybadger/breadcrumbs/logging.rb:42:in `block (2 levels) in <module:LogSubscriberInjector>'
# /Users/jrochkind/.gem/ruby/2.6.6/gems/activerecord-6.0.2.2/lib/active_record/log_subscriber.rb:97:in `debug'
# /Users/jrochkind/.gem/ruby/2.6.6/gems/activerecord-6.0.2.2/lib/active_record/log_subscriber.rb:45:in `sql'
# /Users/jrochkind/.gem/ruby/2.6.6/gems/activesupport-6.0.2.2/lib/active_support/subscriber.rb:145:in `finish'
# /Users/jrochkind/.gem/ruby/2.6.6/gems/activesupport-6.0.2.2/lib/active_support/log_subscriber.rb:107:in `finish'
# /Users/jrochkind/.gem/ruby/2.6.6/gems/activesupport-6.0.2.2/lib/active_support/notifications/fanout.rb:160:in `finish'
# /Users/jrochkind/.gem/ruby/2.6.6/gems/activesupport-6.0.2.2/lib/active_support/notifications/fanout.rb:62:in `block in finish'
# /Users/jrochkind/.gem/ruby/2.6.6/gems/activesupport-6.0.2.2/lib/active_support/notifications/fanout.rb:62:in `each'
# /Users/jrochkind/.gem/ruby/2.6.6/gems/activesupport-6.0.2.2/lib/active_support/notifications/fanout.rb:62:in `finish'
# /Users/jrochkind/.gem/ruby/2.6.6/gems/activesupport-6.0.2.2/lib/active_support/notifications/instrumenter.rb:45:in `finish_with_state'
# /Users/jrochkind/.gem/ruby/2.6.6/gems/activesupport-6.0.2.2/lib/active_support/notifications/instrumenter.rb:30:in `instrument'
# /Users/jrochkind/.gem/ruby/2.6.6/gems/activerecord-6.0.2.2/lib/active_record/connection_adapters/abstract_adapter.rb:708:in `log'
# /Users/jrochkind/.gem/ruby/2.6.6/gems/activerecord-6.0.2.2/lib/active_record/connection_adapters/postgresql_adapter.rb:684:in `exec_cache'
# /Users/jrochkind/.gem/ruby/2.6.6/gems/activerecord-6.0.2.2/lib/active_record/connection_adapters/postgresql_adapter.rb:655:in `execute_and_clear'
# /Users/jrochkind/.gem/ruby/2.6.6/gems/activerecord-6.0.2.2/lib/active_record/connection_adapters/postgresql/database_statements.rb:98:in `exec_query'
# /Users/jrochkind/.gem/ruby/2.6.6/gems/activerecord-6.0.2.2/lib/active_record/connection_adapters/abstract/database_statements.rb:491:in `select_prepared'
# /Users/jrochkind/.gem/ruby/2.6.6/gems/activerecord-6.0.2.2/lib/active_record/connection_adapters/abstract/database_statements.rb:68:in `select_all'
# /Users/jrochkind/.gem/ruby/2.6.6/gems/activerecord-6.0.2.2/lib/active_record/connection_adapters/abstract/query_cache.rb:107:in `select_all'
# /Users/jrochkind/.gem/ruby/2.6.6/gems/activerecord-6.0.2.2/lib/active_record/relation/calculations.rb:193:in `block in pluck'
# /Users/jrochkind/.gem/ruby/2.6.6/gems/activerecord-6.0.2.2/lib/active_record/relation.rb:828:in `skip_query_cache_if_necessary'
# /Users/jrochkind/.gem/ruby/2.6.6/gems/activerecord-6.0.2.2/lib/active_record/relation/calculations.rb:193:in `pluck'
# /Users/jrochkind/.gem/ruby/2.6.6/gems/activerecord-6.0.2.2/lib/active_record/internal_metadata.rb:28:in `[]'
# /Users/jrochkind/.gem/ruby/2.6.6/gems/activerecord-6.0.2.2/lib/active_record/tasks/database_tasks.rb:348:in `schema_up_to_date?'
# /Users/jrochkind/.gem/ruby/2.6.6/gems/activerecord-6.0.2.2/lib/active_record/migration.rb:595:in `block in load_schema_if_pending!'
# /Users/jrochkind/.gem/ruby/2.6.6/gems/activerecord-6.0.2.2/lib/active_record/migration.rb:594:in `all?'
# /Users/jrochkind/.gem/ruby/2.6.6/gems/activerecord-6.0.2.2/lib/active_record/migration.rb:594:in `load_schema_if_pending!'
# /Users/jrochkind/.gem/ruby/2.6.6/gems/activerecord-6.0.2.2/lib/active_record/migration.rb:615:in `block in maintain_test_schema!'
# /Users/jrochkind/.gem/ruby/2.6.6/gems/activerecord-6.0.2.2/lib/active_record/migration.rb:867:in `suppress_messages'
# /Users/jrochkind/.gem/ruby/2.6.6/gems/activerecord-6.0.2.2/lib/active_record/migration.rb:620:in `method_missing'
# /Users/jrochkind/.gem/ruby/2.6.6/gems/activerecord-6.0.2.2/lib/active_record/migration.rb:615:in `maintain_test_schema!'
# ./spec/rails_helper.rb:44:in `<main>'
# /Users/jrochkind/.gem/ruby/2.6.6/gems/bootsnap-1.4.6/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:23:in `require'
# /Users/jrochkind/.gem/ruby/2.6.6/gems/bootsnap-1.4.6/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:23:in `block in require_with_bootsnap_lfi'
# /Users/jrochkind/.gem/ruby/2.6.6/gems/bootsnap-1.4.6/lib/bootsnap/load_path_cache/loaded_features_index.rb:92:in `register'
# /Users/jrochkind/.gem/ruby/2.6.6/gems/bootsnap-1.4.6/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:22:in `require_with_bootsnap_lfi'
# /Users/jrochkind/.gem/ruby/2.6.6/gems/bootsnap-1.4.6/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:31:in `require'
# /Users/jrochkind/.gem/ruby/2.6.6/gems/zeitwerk-2.3.0/lib/zeitwerk/kernel.rb:23:in `require'
# ./spec/util_spec.rb:1:in `<main>'
# /Users/jrochkind/.gem/ruby/2.6.6/gems/bootsnap-1.4.6/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:55:in `load'
# /Users/jrochkind/.gem/ruby/2.6.6/gems/bootsnap-1.4.6/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:55:in `load'

[jrochkind]

It looks like it could be some kind of a competition between something else also trying to override the default log method, the honeybadger gem. Perhaps in the context of auto-loading, there is some inconsistency or race condition in exactly what the log method refers to.

[jrochkind]

OK, yeah, so this is interesting.

Both yell and honeybadger are trying to add custom behavior on to ::Logger#add, and then call original implementation.

yell does so using the old alias_method and old_* technique.

honeybadger does so with the newer (ruby 2.0) Module prepend, prepending this module

In my app exhibiting the problem, somehow when yell code calls add_without_yell on line 12, it ends up invoking the honeybadger implementation.

And then when honeybadger calls super on line 17, it ends up calling the yell implementation.

Both were trying to call 'original' implementation, but neither ever gets there, they just call themselves in infinite loop.

I am not sure why; I can't so far reproduce this outside of my particular complex app. It is apparently some kind of race condition in exactly how they wind up loaded in my app. Although I'm still trying to reproduce.

1. It strikes me that if honeybadger used the more modern Module#prepend technique, this would possibly not be happening. It might be a conflict between the module-prepend approach and the older alias-method-juggling approach. Would you be amenable to a PR changing to that, @rudionrails ? Yell says it supports ruby starting at 2.3, and Module#prepend has been available since before then.

2. I would still prefer if this patching was not automatic, if it was opt-in. I don't think it's a good idea, and would like to use Yell's custom logger implementations without patching the stdlib Logger. The code with the least bugs is the code you don't even have, patching stdlib can be dangerous, I'm having to debug functionality that ended up interacting poorly with another gem, when I didn't even want that functionality at all, I'd rather if I could use yell without it. But i realize this is a larger conversation, and would be a change for yell possibly requiring a new major version release.

[jrochkind]

I can't manage to reproduce this in an isolated app outside of my own complicated app. Something in my app is resulting in a race condition in how yell's patching of ::Logger and honeybadger's patching of ::Logger are loaded, so they inconsistently refer to each other and cause an infinite loop.

I think I'm going to give up on reproducing, just banging my head against the wall.

But I think it's quite likely that #61 would solve it, and it seems to me to be a code cleanup either way. Curious your thoughts, thanks!