Significant resolution slowdown and "NTLM Credentials...'null:-1'" in debug log when no NTLM should be involved

The Problem I have recently experienced a massive (5-10x) gradle artifact resolution slowdown on one of my development machines. The problem only occurs with java 6 and authenticated artifactory repositories and might be caused by some local configuration option, but I have after extensive searching failed to locate the cause and am hoping for some help here.

Environment

The ailing machine is fast (16 core, 4GHz, SSD, 24G ram) and well connected (100/10+Mbit tested). The machine is running Ubuntu 12.04LTS and is not behind any proxies and nowhere near a windows network.

Gradle version (resetting JAVA_HOME from 1.6 to 7 in between):

mbjarland@jura:gradle-ntlm-issue$ ./gradlew -v
  ------------------------------------------------------------
Gradle 1.3
------------------------------------------------------------
  Gradle build time: Tuesday, November 20, 2012 11:37:38 AM UTC
Groovy: 1.8.6
Ant: Apache Ant(TM) version 1.8.4 compiled on May 22 2012
Ivy: 2.2.0
JVM: 1.6.0_34 (Sun Microsystems Inc. 20.9-b04)
OS: Linux 3.2.0-29-generic amd64
------------------------------------------
mbjarland@jura:gradle-ntlm-issue$ ./gradlew -v
  ------------------------------------------------------------
Gradle 1.3
------------------------------------------------------------
  Gradle build time: Tuesday, November 20, 2012 11:37:38 AM UTC
Groovy: 1.8.6
Ant: Apache Ant(TM) version 1.8.4 compiled on May 22 2012
Ivy: 2.2.0
JVM: 1.7.0_09 (Oracle Corporation 23.5-b02)
OS: Linux 3.2.0-29-generic amd64

The artifactory server is version 2.6.4, rev. 13153 (very recent if not latest) and is sitting on an ec2 instance with no weirdness involved.

The Symptoms I have extracted the problem into a sample project which can be found on github at:

https://github.com/mbjarland/gradle-ntlm-issue

The project is a simple groovy project with a couple of mixed groovy/java classes (which are not relevant for this issue).

As mentioned above, the issue only seems to occur on java 6. Build time comparison (where the java_6 and java_7 files just export JAVA_HOME):

mbjarland@jura:gradle-ntlm-issue$ source java_7
mbjarland@jura:gradle-ntlm-issue$ ./gradlew clean groovydoc
:clean
:compileJava UP-TO-DATE
:compileGroovy
:processResources UP-TO-DATE
:classes
:groovydoc
  BUILD SUCCESSFUL
  Total time: 6.916 secs
mbjarland@jura:gradle-ntlm-issue$ source java_6
mbjarland@jura:gradle-ntlm-issue$ ./gradlew clean groovydoc
:clean
:compileJava UP-TO-DATE
:compileGroovy
:processResources UP-TO-DATE
:classes
:groovydoc
  BUILD SUCCESSFUL
  Total time: 38.774 secs

Note the build times. The full debug log for the second build above can be found here. The difference in resolution times gets magnitudes worse with complex multi-project builds.

The slow builds are all resolving against an authenticated artifactory instance. The sample project has a gradle.properties file with credentials for a test user checked in and the artifactory repository is performing fine from other machines with similar (or as far as I can tell, identical) configurations and projects. As can be seen above, the same artifactory server is also performing fine from the same machine with JDK 7.

Looking at the debug log it seems that the to the following type of “error” is eating up my build times:

23:10:14.640 [DEBUG] [org.gradle.api.internal.externalresource.transport.http.HttpClientConfigurer]
 Using Credentials [username: test-user] and NTLM Credentials [user: test-user, domain: , workstation: JURA] for authenticating against 'null:-1'

doing a bit of grepping:

mbjarland@jura:gradle-ntlm-issue$ rm -rf ~/.gradle/
mbjarland@jura:gradle-ntlm-issue$ ./gradlew -d clean groovydoc | grep "and NTLM Credentials" | wc
     24
   505
  6189

Note that I remove my entire user_home/.gradle directory to make sure I don’t have any proxy settings or other junk in a user specific gradle.properties file.

We can see that there are 24 instances of the NTLM log line (see the full debug log for details) where each invocation takes about 1.3 seconds (as per the debug log) adding up to about 31 seconds of time spent with the NTLM lines. This is approximately the difference in build times.

I assume the NTLM line is gradle trying to authenticate against the artifactory server using NTLM? Further up in the debug log we can see the auth challenge from artifactory:

23:10:20.919 [DEBUG] [org.apache.http.impl.client.SystemDefaultHttpClient] artifacts.xxxxxxxx.com:80 requested authentication
23:10:20.920 [DEBUG] [org.apache.http.impl.client.TargetAuthenticationStrategy] Authentication schemes in the order of preference: [negotiate, Kerberos, NTLM, Digest, Basic]
23:10:20.920 [DEBUG] [org.apache.http.impl.client.TargetAuthenticationStrategy] Challenge for negotiate authentication scheme not available
23:10:20.921 [DEBUG] [org.apache.http.impl.client.TargetAuthenticationStrategy] Challenge for Kerberos authentication scheme not available
23:10:20.921 [DEBUG] [org.apache.http.impl.client.TargetAuthenticationStrategy] Challenge for NTLM authentication scheme not available
23:10:20.922 [DEBUG] [org.apache.http.impl.client.TargetAuthenticationStrategy] Challenge for Digest authentication scheme not available
23:10:20.924 [DEBUG] [org.apache.http.impl.client.SystemDefaultHttpClient] Selected authentication options: [BASIC]
...

and we can see that the http client implementation seems to select basic auth over NTLM. Which begs the question: where do these NTLM auth failures come from? Eh?

Another potential culprit would have been proxy some system properties (as per java documentation). I checked for GRADLE_OPTS or JAVA_OPTS which might affect this:

mbjarland@jura:gradle-ntlm-issue$ set | grep GRADLE
GRADLE_HOME=/usr/share/gradle/1.3
mbjarland@jura:gradle-ntlm-issue$ set | grep OPTS
SHELLOPTS=braceexpand:emacs:hashall:histexpand:history:interactive-comments:monitor

and also if perhaps system properties might snuck in some other way:

mbjarland@jura:gradle-ntlm-issue$ groovysh
 Groovy Shell (2.0.4, JVM: 1.6.0_34)
Type 'help' or '\h' for help.
-------------------------------------------------------------------------------------------------------------
groovy:000> System.properties['java.home']
===> /opt/java/64/jdk1.6.0_34/jre
groovy:000> System.properties.findAll { k, v -> k.toLowerCase().contains('http') }
===> {}
groovy:000> System.properties.findAll { k, v -> k.toLowerCase().contains('proxy') }
===> {}
groovy:000> System.properties.findAll { k, v -> k.toLowerCase().contains('ntlm') }
===> {}

I also did the above from a settings.gradle in the sample project with equally empty results.

So What Gives? I have to say I’m a bit stomped here. Some kind of NTLM auth failure is eating up my build time. It only happens on jdk 1.6 and seems to only happen on this specific machine.

I get the creeping feeling somebody will walk along and point out some painfully obvious detail I have overlooked and I’ll have to shamble away in shame. Until then I think I’ve run out of things to try.

First, thanks for the detailed report. You don’t need to worry specifically about the debug message mentioning NTLMCredentials: this is just indicating that we’re making those credentials available to the HttpClient connection, NOT that they are being used.

As you note, Basic authentication is being selected (because no NTLM challenge is received from the server), so the slowdown you observer cannot be caused by actual NTLM authentication.

So the question is: what exactly is happening on your Java6 machine that is so much faster on Java7?

  • The first issue is that we’re calling ‘org.gradle.api.internal.externalresource.transport.http.HttpTransport.getRepository()’ 4 different times for a single ‘maven’ repository: this means 4 different HttpClient instances are initialised. I’ve just confirmed this happens and it is certainly not intentional. But this would be happening on both Java7 and Java6 for the same Gradle version, so it would exacerbate any problem, but not cause it. * So something inside that ‘HttpTransport.getRepository()’ call is running slowly on your Java6 machine. While I suspect the creation and configuration of the HttpClient instances, only you can discover that for sure. You could setup a test Java project that does something similar to ‘org.gradle.api.internal.externalresource.transport.http.HttpClientHelper’: just copy the code and run it in isolation to Gradle. This will likely give you some hints about what is running slowly.

Please let us know if you discover what the real cause of your slowdown is.

Funny thing. I was going to run a profiler on the gradle process but am now unable to reproduce the issue. Will keep digging and report back if I manage to trigger the issue again.

@Matias, did you ever find the cause of this issue? I have received some reports on what might be the same problem from other people, but I am unable to reproduce it.

@Peter, unfortunately not.

Also, just did a quick check and could be my java (minor) versions are different, but I am unable to reproduce this now.

OK. Thanks for letting me know.