[MRESOLVER-153] resolver-status.properties file is corrupted due to concurrent writes

[jira-importer]

Guy Brand opened MRESOLVER-153 and commented

In our integration tests which run with Maven 4.0.0-alpha-1-SNAPSHOT after this commit, we face the following error:

[main] [INFO] ------------------------------------------------------------------------
[main] [INFO] BUILD FAILURE
[main] [INFO] ------------------------------------------------------------------------
[main] [INFO] Total time: 0.243 s
[main] [INFO] Finished at: 2020-12-23T13:48:59+01:00
[main] [INFO] ------------------------------------------------------------------------
[main] [ERROR] Malformed \uxxxx encoding.
java.lang.IllegalArgumentException: Malformed \uxxxx encoding.
 at java.util.Properties.loadConvert (Properties.java:675)
 at java.util.Properties.load0 (Properties.java:451)
 at java.util.Properties.load (Properties.java:404)
 at org.eclipse.aether.internal.impl.TrackingFileManager.read (TrackingFileManager.java:56)
 at org.eclipse.aether.internal.impl.DefaultUpdateCheckManager.read (DefaultUpdateCheckManager.java:511)
 at org.eclipse.aether.internal.impl.DefaultUpdateCheckManager.checkMetadata (DefaultUpdateCheckManager.java:250)
 at org.eclipse.aether.internal.impl.DefaultMetadataResolver.resolve (DefaultMetadataResolver.java:302)
 at org.eclipse.aether.internal.impl.DefaultMetadataResolver.resolveMetadata (DefaultMetadataResolver.java:181)
 at org.eclipse.aether.internal.impl.DefaultRepositorySystem.resolveMetadata (DefaultRepositorySystem.java:277)
 at org.apache.maven.plugin.version.internal.DefaultPluginVersionResolver.resolveFromRepository (DefaultPluginVersionResolver.java:134)
 at org.apache.maven.plugin.version.internal.DefaultPluginVersionResolver.resolve (DefaultPluginVersionResolver.java:97)
 at org.apache.maven.lifecycle.internal.LifecyclePluginResolver.resolveMissingPluginVersions (LifecyclePluginResolver.java:67)
 at org.apache.maven.lifecycle.internal.DefaultLifecycleTaskSegmentCalculator.calculateTaskSegments (DefaultLifecycleTaskSegmentCalculator.java:104)
 at org.apache.maven.lifecycle.internal.DefaultLifecycleTaskSegmentCalculator.calculateTaskSegments (DefaultLifecycleTaskSegmentCalculator.java:86)
 at org.apache.maven.lifecycle.internal.LifecycleStarter.execute (LifecycleStarter.java:92)
 at org.apache.maven.DefaultMaven.doExecute (DefaultMaven.java:321)
 at org.apache.maven.DefaultMaven.doExecute (DefaultMaven.java:206)
 at org.apache.maven.DefaultMaven.execute (DefaultMaven.java:119)
 at org.apache.maven.cli.MavenCli.execute (MavenCli.java:982)
 at org.apache.maven.cli.MavenCli.doMain (MavenCli.java:296)
 at org.apache.maven.cli.MavenCli.main (MavenCli.java:200)
 at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0 (Native Method)
 at jdk.internal.reflect.NativeMethodAccessorImpl.invoke (NativeMethodAccessorImpl.java:62)
 at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke (DelegatingMethodAccessorImpl.java:43)
 at java.lang.reflect.Method.invoke (Method.java:566)
 at org.codehaus.plexus.classworlds.launcher.Launcher.launchEnhanced (Launcher.java:282)
 at org.codehaus.plexus.classworlds.launcher.Launcher.launch (Launcher.java:225)
 at org.codehaus.plexus.classworlds.launcher.Launcher.mainWithExitCode (Launcher.java:406)
 at org.codehaus.plexus.classworlds.launcher.Launcher.main (Launcher.java:347)

It's not consistently failing and OSX based CI agents fail more often than Linux or Windows ones. After some investigations we saw that as part of https://issues.apache.org/jira/browse/MRESOLVER-132 the synchronization has been removed on the TrackingFileManager (#67). This now leads to concurrent writes on the resolver-status.properties file in our tests and causes the error during the Properties#load() method wich then throws the above error. See this screenshot on how these files look like (cannot add the text here as null characters aren't shown):

!screenshot-1.png!

When enabling debug log we also see that the DefaultMetadataResolver threads try to write concurrently to this file:

[DefaultMetadataResolver-0-0] [INFO] Downloading from custom-repo2: https://repo.maven.apache.org/maven2/mng-xxxx-concurrent-writes-to-resolver-status-file/plugin/maven-metadata.xml
[DefaultMetadataResolver-0-2] [INFO] Downloading from central-proxy: https://repo.maven.apache.org/maven2/mng-xxxx-concurrent-writes-to-resolver-status-file/plugin/maven-metadata.xml
[DefaultMetadataResolver-0-1] [INFO] Downloading from custom-repo: https://repository.apache.org/snapshots/mng-xxxx-concurrent-writes-to-resolver-status-file/plugin/maven-metadata.xml
[DefaultMetadataResolver-0-1] [DEBUG] Writing tracking file /.../core-it-suite/target/test-classes/mng-xxxx-concurrent-writes-to-resolver-status-file/repo/mng-xxxx-concurrent-writes-to-resolver-status-file/plugin/resolver-status.properties
[DefaultMetadataResolver-0-2] [DEBUG] Writing tracking file /.../core-it-suite/target/test-classes/mng-xxxx-concurrent-writes-to-resolver-status-file/repo/mng-xxxx-concurrent-writes-to-resolver-status-file/plugin/resolver-status.properties
[DefaultMetadataResolver-0-0] [DEBUG] Writing tracking file /.../core-it-suite/target/test-classes/mng-xxxx-concurrent-writes-to-resolver-status-file/repo/mng-xxxx-concurrent-writes-to-resolver-status-file/plugin/resolver-status.properties

We created a Maven integration test which reproduces the issue. The test is not always failing as in some runs the null characters are normalized to \u0000 Strings and then written back to the resolver-status.properties file which then can be read properly by the Properties#load() method. You can monitor the core-it-suite/target/test-classes/mng-xxxx-concurrent-writes-to-resolver-status-file/repo/mng-xxxx-concurrent-writes-to-resolver-status-file/plugin/resolver-status.properties file while running the test as there you'll see the corrupted updates.

Readding the thread synchronization to the TrackingFileManager would solve this race condition, as file locking is indeed not required as stated in MRESOLVER-132.

Can we get this change into a new Maven 4.0.0-alpha-1-SNAPSHOT version to be able to test the fix?

---

Affects: 1.6.1

Attachments:

• gdmr.txt (1.03 kB)
• gdmr.txt (1.03 kB)
• image-2021-06-05-10-00-08-542.png (11.43 kB)
• screenshot-1.png (13.84 kB)
• with-global-sync-context.txt (60.85 kB)
• without-global-sync-context.txt (153.88 kB)

Issue Links:

• MRESOLVER-177 Move pre-/post-processing of metadata from ResolveTask to DefaultMetadataResolver
  ("is fixed by")

• MRESOLVER-216 [ERROR] Malformed \uxxxx encoding.

• MRESOLVER-172 Make TrackingFileManager shared singleton component
  ("requires")

• MRESOLVER-176 Introduce explicit locking for tracking files
  ("requires")

• MRESOLVER-177 Move pre-/post-processing of metadata from ResolveTask to DefaultMetadataResolver
  ("requires")

Remote Links:

• GitHub Pull Request #101
  
• GitHub Pull Request #102
  
• GitHub Pull Request #103
  
• GitHub Pull Request #104
  
• GitHub Pull Request #114
  
• GitHub Pull Request #98
  

Backported to: 1.6.3

1 votes, 8 watchers

[jira-importer]

Michael Osipov commented

First of all, thank you for testing! Please provide the exact command you have supplied to Maven. I do not fully understand this statement:

Readding the thread synchronization to the TrackingFileManager would solve this race condition
To which thread synchronization do you refer exactly?

Looking at your IT (thanks) my best guess is that plugin-api 2.0 and maven-core 2.0 have intersecting dependencies and since five threads are used to download them they interleave. Since you understood the reasoning behind this reverting MRESOLVER-132 will cause more problems: it fails on bad-lock/non-lock FS, imposes double locks as well as expensive intern/canonical calculations.

• Can you try -Daether.metadataResolver.threads=1 for testing purposes?
• Why do you pass -Daether.updateCheckManager.sessionState=false? What happens when you leave this out?

[jira-importer]

Michael Osipov commented

Tamas Cservenak, this is an interesting case which I did not had in mind at all. Concurrency within one module with overlapping artifacts. I think we need to employ synchronization by default in Resolver. What is your opinion on the entire issue?

An alternative is to use custom file tracking managers depending on the sync context implementation.

[jira-importer]

Tamas Cservenak commented

Michael OsipovI agree, synchronization should be re-added to tracking file manager... will look into this a bit more after holidays, but I believe we could reuse some (if not same) of named locking for example. Also, if you have ideas, shoot.

[jira-importer]

Michael Osipov commented

I do not fully agree that the tracking file manager requires synchronization. It is required IF the default sync context is used which does not synchronize at all. The tracking file manager is always called within a synchronized block. Re-adding it by default would lead to the same non-sense I have described before. If am wrong with my analysis, please explain.

What I did previously is that I left the synchronized tracking file manager intact, but had a non-sync bundled with the Redis sync context to solve this. Should we go that route again?

[jira-importer]

Tamas Cservenak commented

Yup, did not meant to return (removed) FS locking or to make it use SyncContext, but more like "make it aware" of locking presence (or absence) as you say.
But doesn't this mean that Resolver (when used in Maven with more than 1 thread) should use some "default" locking, no? As otherwise any MT (not to mention MP) build is doomed to fail...

[jira-importer]

Michael Osipov commented

Yup, did not meant to return (removed) FS locking or to make it use SyncContext, but more like "make it aware" of locking presence (or absence) as you say.

That was my thought. I had this in my initial redisson version. Overridden the class by higher preference class loading. Ugly, but it works.

But doesn't this mean that Resolver (when used in Maven with more than 1 thread) should use some "default" locking, no? As otherwise any MT (not to mention MP) build is doomed to fail...

It is a bit worse than that. You may, as it seems, run into trouble even with one builder thread because depedencies are resolved with multiple threads even if one module is processed. This ticket is the proof for this. Yes, there should be default locking because, as just mentioned, every build is implicitly a MT build. Worse that that, those two JARs processed in parallel by Resolver could have been corrupted. So this bug, regardless of the tracking file manager change, was always there. I am sure that it is easier to reproduce as soon as you increase aether.connector.basic.threads and/or aether.metadataResolver.threads to a high number.

[jira-importer]

Guy Brand commented

Michael Osipov Regarding

Why do you pass -Daether.updateCheckManager.sessionState=false? What happens when you leave this out?

With this flag set, the problem is reproducible more often as it will check the dependencies every time and doesn't store it in the session.

Can you try -Daether.metadataResolver.threads=1 for testing purposes?

I executed a run of all our integration tests and they passed. We'll then keep this flag set until this is fixed in a future Maven nightly version.

Regarding the synchronization: There you already discussed on how to restore it. My two cents on that topic are the following:

There is the concept of a SyncContext and components as the TrackingFileManager rely on this to implement proper synchronization. Why having a DefaultSyncContext in place that does no synchronization at all? Having this noop SyncContext could produce other errors like the one I reported. Therefore instead of checking if the DefaultSyncContext is used in the TrackingFileManager, why not just implement basic synchronization in the DefaultSyncContext, rely on it and on top prevent similar errors on the other usages of SyncContext?

[jira-importer]

Tamas Cservenak commented

Brand work of providing functional sync context factory happens in MRESOLVER-145 FYI

[jira-importer]

Michael Osipov commented

Brand,
thanks for the update. The flag use makes sense.
You are right, of course, about the synchronization. That's the way it was for years and it was faulty. We had numerous tickets about that. As Tamas Cservenak said, we are working on it. My Redisson-based implementation does quite well, more to come from Tamás. You are cordially invited to review and test the PR. Let me make this clear, I think that synchronization in the TrackingFileManager is the wrong place to be. So I am grateful for your report and it happily proves the lack of proper synchronization.

Run this on Maven Core ITs and you see maven-metadata.xml fail quite quick:
rm -rf /tmp/repo* ; ~/apache-maven-4.0.0-alpha-1-SNAPSHOT/bin/mvn -Dmaven.repo.local=/tmp/repo4 clean install -T4C -DskipTests -Dorg.slf4j.simpleLogger.showThreadName=true -U -B.

[jira-importer]

Guy Brand commented

I'm happy to help out. We can run our set of tests with changes on master. We publish our own Maven nightlies based on the master branch to our own infrastructure. We may be able to do a custom snapshot from a branch where the new Maven resolver version is included. If you can provide such a branch we can use it for the tests.

[jira-importer]

Michael Osipov commented

Brand, if you you can start out by building from MRESOLVER-145 which is a custom Maven build. This is ongoing work, but should give the enough to make decisions.

[jira-importer]

Guy Brand commented

Michael Osipov Not sure how to do this as the referenced PR is from the Maven Resolver project and not from https://github.com/apache/maven from which we create our nightly snapshots via CI. If you can provide a custom branch on that repo with these changes I can trigger our suite based on these changes. Manually building it is not an option for us, as we have everything automated in CI and only rely on artifacts published by CI.

[jira-importer]

Michael Osipov commented

You can automate that. Clone from https://github.com/cstamas/maven-resolver/tree/named. Install locally, clone from Maven master. Update root POM with the resolver 1.7.0-SNAPSHOT. Build Maven, use that tarball to test your own builds.

[jira-importer]

Michael Osipov commented

I do observe this too once in a while:

[INFO] Running org.apache.maven.artifact.resolver.ArtifactResolverTest
[ERROR] Tests run: 7, Failures: 0, Errors: 1, Skipped: 0, Time elapsed: 0.415 s <<< FAILURE! - in org.apache.maven.artifact.resolver.ArtifactResolverTest
[ERROR] testResolutionOfAnArtifactWhereOneRemoteRepositoryIsBadButOneIsGood  Time elapsed: 0.064 s  <<< ERROR!
java.lang.IllegalArgumentException: Malformed \uxxxx encoding.
        at org.apache.maven.artifact.resolver.ArtifactResolverTest.testResolutionOfAnArtifactWhereOneRemoteRepositoryIsBadButOneIsGood(ArtifactResolverTest.java:189)

with

$ cat test-repositories/resolver/local-repository/org/apache/maven/l/1.0-SNAPSHOT/resolver-status.properties
#NOTE: This is a Maven Resolver internal implementation file, its format can be changed without prior notice.
#Sat Jan 23 18:59:22 CET 2021
maven-metadata-test.xml/@default-test-http\://foo.bar/repository/.lastUpdated=1611424762800
maven-metadata-test.xml.error=Could not transfer metadata org.apache.maven\:l\:1.0-SNAPSHOT/maven-metadata.xml from/to test (http\://foo.bar/repository)\: Cannot access http\://foo.bar/repository with type default using the available connector factories\: BasicRepositoryConnectorFactory
\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0

[jira-importer]

Guy Brand commented

Michael Osipov Did that happen on the MRESOLVER-145 custom Maven build you referenced above? I still could not add this automated step into our CI.