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

Improve Loggers.useConsoleLoggers() thread safety #3174

Merged

Conversation

alexismanin
Copy link
Contributor

@alexismanin alexismanin commented Aug 30, 2022

Fix for #3170

Rework ConsoleLoggerFactory cache to provide a more consistent behavior.

Notes:

  • As a cache strategy, I've chosen synchronized keyword + WeakHashMap combination. I've made this choice as a tradeoff between code complexity and proper cache eviction. There might be better solutions, maybe you have suggestions ?
    • I've thought about using StampedLock instead of synchronized, but I decided to leave it aside and provide a simpler code for first review
  • I've added a regression test for the concurrent error, but I would appreciate advise on how I could improve it because:
    • Failure is inconsistent due to the concurrent nature of the problem. I could add a loop to the test, to force failure behavior, but I'm afraid that it would make it too long to execute.
    • Maybe it is too heavy, as it starts its own thread-pool.
  • Independently from the current issue, I've seen that there's a duplicated function format used both on console logger and JDK logger. I wonder if it is really needed on JdkLogger, because this work should be done internally by the logger. If you agree, I can rework that as a bonus in this PR.

@alexismanin alexismanin requested a review from a team as a code owner August 30, 2022 06:22
Currently, Loggers.ConsoleLoggerFactory.apply method uses a plain HashMap as a cache, without using any external synchonisation mechanism.
It can cause ConcurrentModificationException error when a user tries to acquire a logger

See reactor#3170.
Add a test to ensure that console logger factory cache does not return loggers with outdated "verbose" attribute

See reactor#3170.
@alexismanin alexismanin force-pushed the 3170-consoleLoggerThreadSafety branch from 9caec6e to 831aa6d Compare August 30, 2022 19:33
Fix both unit tests previously introduced by reworking cache management:
 - Synchronize cache access to avoid concurrent modification error (TODO: performance may be improved by using a stamped lock, at the cost of code complexity)
 - Use "verbose" attribute as a part of the cache key, to avoid cache corruptions
 - Use new key as a basis for cache entry eviction: replace HashMap with WeakHashMap, to give a chance to remove unused loggers

Fixes reactor#3170.
Warn user about expected thread-safety guarantee when providing a custom logger factory function

See reactor#3170.
@alexismanin alexismanin force-pushed the 3170-consoleLoggerThreadSafety branch from 831aa6d to a7f6a83 Compare August 30, 2022 20:43
@alexismanin
Copy link
Contributor Author

I've reworked my "enhancement" commit, because the way I've used WeakHashMap initially was totally flawed.

I've ensured a saner behavior by using the following snippet repeatedly:

package reactor.util;

import reactor.util.Logger;
import reactor.util.Loggers;

public class ConsoleLoggerLeak {

	public static void main(String[] args) {
		Loggers.useConsoleLoggers();

		long i = 0;
		while (true) {
			Logger logger = Loggers.getLogger(Long.toString(i));
			if (i++ % 1_000_000 == 0) {
				System.out.print("\r"+logger.getName());
			}
			Logger bis = Loggers.getLogger(Long.toString(i-1));
			if (bis != logger) throw new IllegalStateException("Not cached !");
		}
	}
}

Copy link
Member

@simonbasle simonbasle left a comment

Choose a reason for hiding this comment

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

good improvement on the WeakHashMap usage. found one improvement around ConsoleLoggerKey.verbose

this.log = log;
this.err = err;
this.verbose = verbose;
this.verbose = identifier.verbose;
Copy link
Member

Choose a reason for hiding this comment

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

why duplicate the verbose field? local field could be removed in favor of this.identifier.verbose wdyt?

Copy link
Contributor Author

Choose a reason for hiding this comment

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

It was just a commodity to avoid changing all if (verbose) with if (identifier.verbose).

But both solutions work for me. If you confirm you want it replaced, I will amend my commit to do the switch.

Copy link
Member

Choose a reason for hiding this comment

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

yeah I think it makes sense to have only one field. please just add a new commit to the branch. I'll squash everything when merging anyway (but I like the effort to have meaningful small commits in the PR branch 👍 )

@simonbasle simonbasle added this to the 3.4.23 milestone Aug 31, 2022
@simonbasle simonbasle added type/bug A general bug type/documentation A documentation update labels Aug 31, 2022
The information is already available through the logger key.
@simonbasle simonbasle changed the title 3170 console logger thread safety Improve Loggers.useConsoleLoggers() thread safety Sep 1, 2022
@simonbasle simonbasle merged commit 91ce8ed into reactor:3.4.x Sep 1, 2022
@reactorbot
Copy link

@simonbasle this PR seems to have been merged on a maintenance branch, please ensure the change is merge-forwarded to intermediate maintenance branches and up to main 🙇

simonbasle added a commit that referenced this pull request Sep 1, 2022
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
type/bug A general bug type/documentation A documentation update
Projects
None yet
Development

Successfully merging this pull request may close these issues.

3 participants