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

(FACT-3468) Don't mutate global logger state #2722

Merged
merged 8 commits into from
May 31, 2024

Conversation

joshcooper
Copy link
Contributor

@joshcooper joshcooper commented May 21, 2024

  • Resolvers now create their Facter::Log the same way, in the BaseResolver.
  • We now set expectations on the Logger and Facter::Log class variables instead of replacing them with instance spies.
  • Fixes a NoMethodError when an aggregate fact is evaluated more than once

See commits for details

Fixes #2721

@joshcooper joshcooper force-pushed the logging branch 2 times, most recently from 7390fe8 to cd3d660 Compare May 22, 2024 16:15
@joshcooper joshcooper changed the title Don't mutate global logger state (FACT-3468) Don't mutate global logger state May 22, 2024
@joshcooper joshcooper added the bug Something isn't working label May 22, 2024
…method

Previously, some resolvers eagerly created a Log, while others relied on the
BaseResolver to lazily create it.

Now eagerly create the Log in the BaseResolver's init_resolver method, which all
derived resolvers already call. This preserves the behavior where the derived class'
name is printed in the log message:

    DEBUG Facter::Resolvers::LsbRelease - Command lsb_release ...

This is because `Log.new(self)` refers to the derived resolver class, e.g.
Facter::Resolvers::LsbRelease, not the BaseResolver.

The base_resolver_spec tests were modified because they were testing that
Facter::Log.new was called a certain way. Instead test the behavior that
`BaseResolver.log` method returns an instance of Facter::Log and calling the
method multiple times returns the same object.
Previously, many tests set an instance_spy logger on their resolver's `log` class
variable. But only some of those tests cleared the instance_spy at the end.
Therefore, the spy could leak from one test to another, see where one case was
fixed in 06b1d5b.

To prevent that from happening again, just let the resolver use its log. Since
we're not using instance spies, we have to set the expectation on the log before
calling the method that causes the log to be written to.

One motivation for installing a spy is to prevent messages from being written to
the terminal. But this accomplishes the same thing but installing a global
Logger in spec_helper that just writes to a StringIO in memory.
Previously if an aggregate fact was evaluated twice it would attempt to log a
warning but its `log` method was never defined, leading to NoMethodError.

It appears this was broken in ee582c5 when the
Legacy logger was removed. This commit adds a private `log` method to lazily
create the log as is done elsewhere and adds a test.

Since string literals are frozen, we need to dup prior to modifying it.
Previously, tests were clearing out Facter's global logger after each test.

Now just set expectations on the logger. Since we're no longer using an
instance_spy, the expectation needs to be set on the Logger before calling
the subject.
Previously, the Collection's class variable was cleared after each test. Now
resolve the logger and set expectations on the log. We have to use `send`
because the `log` method is private.
Previously, we were overwriting the global logger with an instance spy. In some
cases we were not clearing it when we were done or we set it to a new instance
of Logger.new(STDOUT). In the first case, the instance spy could leak across to
other tests. In the second case, we've replaced the global logger with a
different instance instead of replacing it with the original instance.

All of this can be avoided by just getting the logger and setting expectations
on it. Since it's a "class instance variable" we have to use `:@@logger` syntax.

Since the global logger is not a spy, then we have to set the expectation before
calling the method that triggers the message to be sent such as:

        expect(logger).to receive(:debug).with('...')
        log.debug('debug_message')
Previously, we were stubbing Facter::Log.new to return our instance_spy. But we
can just pass the instance_spy as an keyword argument to the `execute` method.

Confusingly the `execute` method takes a `logger` keyword argument, but
internally it creates a `Facter::Log` object, so the argument should really be
called `log`, but that's part of the execution API and can't be changed.
If gethostname returned nil, then we called `empty?` on nil which raised a
NoMethodError. Instead check for nil and don't attempt to resolve the hostname
fact.

Also cleanup some tests which were writing errors to the log unnecessarily.
@joshcooper joshcooper force-pushed the logging branch 2 times, most recently from 85f476f to 27e7fd5 Compare May 23, 2024 15:52
@joshcooper joshcooper marked this pull request as ready for review May 23, 2024 16:05
@joshcooper joshcooper requested a review from a team as a code owner May 23, 2024 16:05
@cthorn42 cthorn42 merged commit ba0a262 into puppetlabs:main May 31, 2024
18 checks passed
@joshcooper joshcooper deleted the logging branch June 6, 2024 18:03
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working
Projects
None yet
Development

Successfully merging this pull request may close these issues.

Facter tests mutate the global logger state
2 participants