SVNKit caches incorrect OPTIONS response

thomasaa · August 31, 2021, 1:59pm

SVNKit can get stuck in an inoperable state until JVM restarts. For example a request for revprops on rev 0:

OPTIONS request is rejected due to Apache server is down / starting up.
PROPFIND sends:

127.0.0.1 - - 2021-08-31 13:48:36 "PROPFIND /null/0 HTTP/1.1" 403 505 "-" "SVN/1.10.0 SVNKit/1.10.3 (http://svnkit.com/) r10808"

A correct request looks like:

127.0.0.1 - - 2021-08-31 13:49:04 "OPTIONS /svn/demo1 HTTP/1.1" 200 2023 "-" "SVN/1.10.0 SVNKit/1.10.3 (http://svnkit.com/) r10808"
127.0.0.1 - - 2021-08-31 13:49:04 "PROPFIND /svn/demo1/!svn/rev/0 HTTP/1.1" 207 1325 "-" "SVN/1.10.0 SVNKit/1.10.3 (http://svnkit.com/) r10808"

thomasaa · August 31, 2021, 2:00pm

To clarify, the OPTIONS request is not visible in access log because it happened before Apache was up.

dmitry.pavlenko · August 31, 2021, 8:09pm

Hello Thomas,
thanks for the report! Are you using HTTPv2 or HTTPv1 protocol (“svnkit.http.httpV2Enabled” JVM property false by default)?

I think, the problem happens here:

DavUtil.java:247

String propFindPath = connection.myRevStub + "/" + revision;

The connection is cached in the connection pool, not until JVM restart but still in the lifetime of the connection pool, which can be pretty long.

‘myRevStub’ comes from “SVN-Rev-Stub” header (DAVConnection.java:813) and is saved for the connection/connection pool lifetime. This happens on any HTTP request during “exchangeCapabilities()” phase, so during the first request all the data is cached.

Now I wonder what could the Apache server return in response to that first request. Clearly it wasn’t the case that Apache wasn’t listening the port, otherwise “Connection refused” would happen.

Do you have an ability to reproduce/debug the problem?

thomasaa · August 31, 2021, 9:05pm

Hello Dmitry,
I am running HTTPv2 and trying hard to keep the same connection for performance.

Actually, I believe Apache is not listening to the port. Was able to log these details:

2021-08-31T20:38:34,923 WARN Repository connection failed (backoff 2000ms) to http://demo.simonsoftcms.se/svn/demo1: Connection refused (Connection refused)
2021-08-31T20:38:36,928 WARN Repository connection failed (backoff 6000ms) to http://demo.simonsoftcms.se/svn/demo1: Connection refused (Connection refused)
2021-08-31T20:38:42,930 WARN Repository connection failed (backoff 18000ms) to http://demo.simonsoftcms.se/svn/demo1: Connection refused (Connection refused)
2021-08-31T20:39:00,936 WARN Repository connection failed (backoff 54000ms) to http://demo.simonsoftcms.se/svn/demo1: svn: E170001: PROPFIND of 'null/0': 403 Forbidden (http://demo.simonsoftcms.se:8091)

Any chance the “Connection refused” exception is ignored somewhere allowing null value to sneak into the cache?

Thanks

thomasaa · August 31, 2021, 9:43pm

Here is some good logging.

My interpretation of the stack traces is:

First connect attempts exchangeCapabilities. Fails.
Second connect skips excangeCapabilities and goes directly to doPropfind (despite having many null fields)

2021-08-31T21:37:36,225 [main] WARN  se.repos.indexing.standalone.IndexingDaemon - Repository connection failed: Connection refused (Connection refused)
se.simonsoft.cms.item.info.CmsConnectionException: Connection refused (Connection refused)
	at se.simonsoft.cms.backend.svnkit.errors.SvnkitErrorAnalyzerApacheSvn17.analyze(SvnkitErrorAnalyzerApacheSvn17.java:138) ~[repos-indexing-standalone-jar-with-dependencies-2.0.3-SNAPSHOT.jar:2.0.3-SNAPSHOT]
	at se.simonsoft.cms.backend.svnkit.errors.SvnkitErrorAnalyzerApacheSvn17.analyze(SvnkitErrorAnalyzerApacheSvn17.java:60) ~[repos-indexing-standalone-jar-with-dependencies-2.0.3-SNAPSHOT.jar:2.0.3-SNAPSHOT]
	at se.simonsoft.cms.backend.svnkit.info.change.CmsContentsReaderSvnkit.getRevisionProperties(CmsContentsReaderSvnkit.java:127) ~[repos-indexing-standalone-jar-with-dependencies-2.0.3-SNAPSHOT.jar:2.0.3-SNAPSHOT]
	at se.repos.indexing.standalone.IndexingDaemon.getRepoConfig(IndexingDaemon.java:258) [repos-indexing-standalone-jar-with-dependencies-2.0.3-SNAPSHOT.jar:2.0.3-SNAPSHOT]
	at se.repos.indexing.standalone.IndexingDaemon.indexingEnabled(IndexingDaemon.java:230) [repos-indexing-standalone-jar-with-dependencies-2.0.3-SNAPSHOT.jar:2.0.3-SNAPSHOT]
	at se.repos.indexing.standalone.IndexingDaemonPubSub.run(IndexingDaemonPubSub.java:136) [repos-indexing-standalone-jar-with-dependencies-2.0.3-SNAPSHOT.jar:2.0.3-SNAPSHOT]
	at se.repos.indexing.standalone.CommandLine.runDaemonPubSub(CommandLine.java:186) [repos-indexing-standalone-jar-with-dependencies-2.0.3-SNAPSHOT.jar:2.0.3-SNAPSHOT]
	at se.repos.indexing.standalone.CommandLine.main(CommandLine.java:99) [repos-indexing-standalone-jar-with-dependencies-2.0.3-SNAPSHOT.jar:2.0.3-SNAPSHOT]
Caused by: java.net.ConnectException: Connection refused (Connection refused)
	at java.net.PlainSocketImpl.socketConnect(Native Method) ~[?:?]
	at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:399) ~[?:?]
	at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:242) ~[?:?]
	at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:224) ~[?:?]
	at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392) ~[?:?]
	at java.net.Socket.connect(Socket.java:609) ~[?:?]
	at org.tmatesoft.svn.core.internal.util.SVNSocketFactory.connect(SVNSocketFactory.java:195) ~[repos-indexing-standalone-jar-with-dependencies-2.0.3-SNAPSHOT.jar:2.0.3-SNAPSHOT]
	at org.tmatesoft.svn.core.internal.util.SVNSocketFactory.createPlainSocket(SVNSocketFactory.java:90) ~[repos-indexing-standalone-jar-with-dependencies-2.0.3-SNAPSHOT.jar:2.0.3-SNAPSHOT]
	at org.tmatesoft.svn.core.internal.io.dav.http.HTTPConnection.connect(HTTPConnection.java:238) ~[repos-indexing-standalone-jar-with-dependencies-2.0.3-SNAPSHOT.jar:2.0.3-SNAPSHOT]
	at org.tmatesoft.svn.core.internal.io.dav.http.HTTPConnection.request(HTTPConnection.java:415) ~[repos-indexing-standalone-jar-with-dependencies-2.0.3-SNAPSHOT.jar:2.0.3-SNAPSHOT]
	at org.tmatesoft.svn.core.internal.io.dav.http.HTTPConnection.request(HTTPConnection.java:352) ~[repos-indexing-standalone-jar-with-dependencies-2.0.3-SNAPSHOT.jar:2.0.3-SNAPSHOT]
	at org.tmatesoft.svn.core.internal.io.dav.http.HTTPConnection.request(HTTPConnection.java:340) ~[repos-indexing-standalone-jar-with-dependencies-2.0.3-SNAPSHOT.jar:2.0.3-SNAPSHOT]
	at org.tmatesoft.svn.core.internal.io.dav.DAVConnection.performHttpRequest(DAVConnection.java:914) ~[repos-indexing-standalone-jar-with-dependencies-2.0.3-SNAPSHOT.jar:2.0.3-SNAPSHOT]
	at org.tmatesoft.svn.core.internal.io.dav.DAVConnection.exchangeCapabilities(DAVConnection.java:706) ~[repos-indexing-standalone-jar-with-dependencies-2.0.3-SNAPSHOT.jar:2.0.3-SNAPSHOT]
	at org.tmatesoft.svn.core.internal.io.dav.DAVConnection.open(DAVConnection.java:114) ~[repos-indexing-standalone-jar-with-dependencies-2.0.3-SNAPSHOT.jar:2.0.3-SNAPSHOT]
	at org.tmatesoft.svn.core.internal.io.dav.DAVRepository.openConnection(DAVRepository.java:1047) ~[repos-indexing-standalone-jar-with-dependencies-2.0.3-SNAPSHOT.jar:2.0.3-SNAPSHOT]
	at org.tmatesoft.svn.core.internal.io.dav.DAVRepository.getRevisionProperties(DAVRepository.java:241) ~[repos-indexing-standalone-jar-with-dependencies-2.0.3-SNAPSHOT.jar:2.0.3-SNAPSHOT]
	at se.simonsoft.cms.backend.svnkit.info.change.CmsContentsReaderSvnkit.getRevisionProperties(CmsContentsReaderSvnkit.java:125) ~[repos-indexing-standalone-jar-with-dependencies-2.0.3-SNAPSHOT.jar:2.0.3-SNAPSHOT]
	... 5 more
2021-08-31T21:37:38,236 [main] WARN  se.repos.indexing.standalone.IndexingDaemon - Repository connection failed (backoff 6000ms) to http://demo.simonsoftcms.se/svn/demo: Connection refused (Connection refused)
2021-08-31T21:37:38,236 [main] WARN  se.repos.indexing.standalone.IndexingDaemon - Repository connection failed: Connection refused (Connection refused)
se.simonsoft.cms.item.info.CmsConnectionException: Connection refused (Connection refused)
	at se.simonsoft.cms.backend.svnkit.errors.SvnkitErrorAnalyzerApacheSvn17.analyze(SvnkitErrorAnalyzerApacheSvn17.java:138) ~[repos-indexing-standalone-jar-with-dependencies-2.0.3-SNAPSHOT.jar:2.0.3-SNAPSHOT]
	at se.simonsoft.cms.backend.svnkit.errors.SvnkitErrorAnalyzerApacheSvn17.analyze(SvnkitErrorAnalyzerApacheSvn17.java:60) ~[repos-indexing-standalone-jar-with-dependencies-2.0.3-SNAPSHOT.jar:2.0.3-SNAPSHOT]
	at se.simonsoft.cms.backend.svnkit.info.change.CmsContentsReaderSvnkit.getRevisionProperties(CmsContentsReaderSvnkit.java:127) ~[repos-indexing-standalone-jar-with-dependencies-2.0.3-SNAPSHOT.jar:2.0.3-SNAPSHOT]
	at se.repos.indexing.standalone.IndexingDaemon.getRepoConfig(IndexingDaemon.java:258) [repos-indexing-standalone-jar-with-dependencies-2.0.3-SNAPSHOT.jar:2.0.3-SNAPSHOT]
	at se.repos.indexing.standalone.IndexingDaemon.indexingEnabled(IndexingDaemon.java:230) [repos-indexing-standalone-jar-with-dependencies-2.0.3-SNAPSHOT.jar:2.0.3-SNAPSHOT]
	at se.repos.indexing.standalone.IndexingDaemonPubSub.run(IndexingDaemonPubSub.java:136) [repos-indexing-standalone-jar-with-dependencies-2.0.3-SNAPSHOT.jar:2.0.3-SNAPSHOT]
	at se.repos.indexing.standalone.CommandLine.runDaemonPubSub(CommandLine.java:186) [repos-indexing-standalone-jar-with-dependencies-2.0.3-SNAPSHOT.jar:2.0.3-SNAPSHOT]
	at se.repos.indexing.standalone.CommandLine.main(CommandLine.java:99) [repos-indexing-standalone-jar-with-dependencies-2.0.3-SNAPSHOT.jar:2.0.3-SNAPSHOT]
Caused by: java.net.ConnectException: Connection refused (Connection refused)
	at java.net.PlainSocketImpl.socketConnect(Native Method) ~[?:?]
	at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:399) ~[?:?]
	at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:242) ~[?:?]
	at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:224) ~[?:?]
	at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392) ~[?:?]
	at java.net.Socket.connect(Socket.java:609) ~[?:?]
	at org.tmatesoft.svn.core.internal.util.SVNSocketFactory.connect(SVNSocketFactory.java:195) ~[repos-indexing-standalone-jar-with-dependencies-2.0.3-SNAPSHOT.jar:2.0.3-SNAPSHOT]
	at org.tmatesoft.svn.core.internal.util.SVNSocketFactory.createPlainSocket(SVNSocketFactory.java:90) ~[repos-indexing-standalone-jar-with-dependencies-2.0.3-SNAPSHOT.jar:2.0.3-SNAPSHOT]
	at org.tmatesoft.svn.core.internal.io.dav.http.HTTPConnection.connect(HTTPConnection.java:238) ~[repos-indexing-standalone-jar-with-dependencies-2.0.3-SNAPSHOT.jar:2.0.3-SNAPSHOT]
	at org.tmatesoft.svn.core.internal.io.dav.http.HTTPConnection.request(HTTPConnection.java:415) ~[repos-indexing-standalone-jar-with-dependencies-2.0.3-SNAPSHOT.jar:2.0.3-SNAPSHOT]
	at org.tmatesoft.svn.core.internal.io.dav.http.HTTPConnection.request(HTTPConnection.java:352) ~[repos-indexing-standalone-jar-with-dependencies-2.0.3-SNAPSHOT.jar:2.0.3-SNAPSHOT]
	at org.tmatesoft.svn.core.internal.io.dav.http.HTTPConnection.request(HTTPConnection.java:340) ~[repos-indexing-standalone-jar-with-dependencies-2.0.3-SNAPSHOT.jar:2.0.3-SNAPSHOT]
	at org.tmatesoft.svn.core.internal.io.dav.DAVConnection.performHttpRequest(DAVConnection.java:914) ~[repos-indexing-standalone-jar-with-dependencies-2.0.3-SNAPSHOT.jar:2.0.3-SNAPSHOT]
	at org.tmatesoft.svn.core.internal.io.dav.DAVConnection.doPropfind(DAVConnection.java:147) ~[repos-indexing-standalone-jar-with-dependencies-2.0.3-SNAPSHOT.jar:2.0.3-SNAPSHOT]
	at org.tmatesoft.svn.core.internal.io.dav.DAVUtil.getProperties(DAVUtil.java:71) ~[repos-indexing-standalone-jar-with-dependencies-2.0.3-SNAPSHOT.jar:2.0.3-SNAPSHOT]
	at org.tmatesoft.svn.core.internal.io.dav.DAVUtil.getResourceProperties(DAVUtil.java:77) ~[repos-indexing-standalone-jar-with-dependencies-2.0.3-SNAPSHOT.jar:2.0.3-SNAPSHOT]
	at org.tmatesoft.svn.core.internal.io.dav.DAVUtil.getBaselineProperties(DAVUtil.java:248) ~[repos-indexing-standalone-jar-with-dependencies-2.0.3-SNAPSHOT.jar:2.0.3-SNAPSHOT]
	at org.tmatesoft.svn.core.internal.io.dav.DAVRepository.getRevisionProperties(DAVRepository.java:245) ~[repos-indexing-standalone-jar-with-dependencies-2.0.3-SNAPSHOT.jar:2.0.3-SNAPSHOT]
	at se.simonsoft.cms.backend.svnkit.info.change.CmsContentsReaderSvnkit.getRevisionProperties(CmsContentsReaderSvnkit.java:125) ~[repos-indexing-standalone-jar-with-dependencies-2.0.3-SNAPSHOT.jar:2.0.3-SNAPSHOT]
	... 5 more

thomasaa · September 1, 2021, 10:23am

Could it be that openConnection should not set ‘myConnection’ until reaching the end of what it is supposed to achieve? When exiting via exception it leaves an ‘myConnection’ variable with a partially initialized instance.

thomasaa · September 2, 2021, 7:26am

What do you think about this diff?

I don’t have a working build environment for SVNKit. Can you apply this patch and trigger a snapshot build at your end?

Index: svnkit/src/main/java/org/tmatesoft/svn/core/internal/io/dav/DAVRepository.java
===================================================================
--- svnkit/src/main/java/org/tmatesoft/svn/core/internal/io/dav/DAVRepository.java	(revision 10812)
+++ svnkit/src/main/java/org/tmatesoft/svn/core/internal/io/dav/DAVRepository.java	(working copy)
@@ -1035,7 +1035,7 @@
         fireConnectionOpened();
         lock();
         if (myConnection == null) {
-
+            DAVConnection newConnection = null;
             final Set<SVNURL> attempted = new HashSet<SVNURL>();
             final SVNURL[] correctedUrl = new SVNURL[1];
             int attemptsLeft = 4;
@@ -1042,9 +1042,9 @@
             while (attemptsLeft-- > 0) {
                 SVNURL originalLocation = myLocation;
                 correctedUrl[0] = null;
-                myConnection = createDAVConnection(myConnectionFactory, this);
-                myConnection.setReportResponseSpooled(isSpoolResponse());
-                myConnection.open(this, correctedUrl);
+                newConnection = createDAVConnection(myConnectionFactory, this);
+                newConnection.setReportResponseSpooled(isSpoolResponse());
+                newConnection.open(this, correctedUrl);
 
                 if (correctedUrl[0] == null) {
                     break;
@@ -1067,6 +1067,7 @@
                 //setLocation() but avoid double locking
                 setLocationInternal(correctedUrl[0], false);
             }
+            myConnection = newConnection;
         }
     }

dmitry.pavlenko · September 2, 2021, 9:09pm

Hello Thomas, sorry for for the delay, I’ve applied the patch at r10813 of trunk. Thanks for it!

I’ve triggered a build (you can login as guest so see it).

You can also build it from sources with the following command:

./gradlew svnkit:clean svnkit:build -x svnkit:javadoc -x svnkit:test svnkit-cli:clean svnkit-cli:build svnkit-distribution:clean svnkit-distribution:build

https://teamcity.tmatesoft.com/buildConfiguration/svnkit_trunk_deploy/24967

thomasaa · September 3, 2021, 1:05pm

Thanks,
Did you add the auth requirement to the maven repo recently?

I was hoping my build server could pick up the build here (as we have done for many years):
https://maven.tmatesoft.com/content/repositories/snapshots/org/tmatesoft/svnkit/svnkit/

thomasaa · September 3, 2021, 1:28pm

I am trying to get an SVNKit build into a Maven repo in order to successfully build the whole artifact required to perform a real-world test.

It seems difficult to build SVNKit when the Tmatesoft Maven repo is inaccessible. Running the gradlew command above fails to retrieve javahl stuff from the Tmatesoft Maven repo.

ildar.khusainov · September 6, 2021, 4:38am

Hi Thomas,

our apologies for that inconvenience, the repository should no be available back. Besides that, the following path can be used for the same purpose:

Repository - Nexus Repository Manager

Please let me know if anything is still wrong.

thomasaa · September 7, 2021, 9:23am

Thanks, I was able to access your maven repo and I have confirmed that the patch resolved the issue.