Dockerfile-maven: Google container registry support unnecessarily causes build delays

[jeremyweber-np]

Attempts to get google credentials take 30 seconds to fail. This is an issue in our environment, where the build time is relatively short, so a 30 second delay is more noticeable. It would be nice to disable gcr support if it is not needed.

[mattnworb]

Can you explain more why it takes 30 seconds for the authentication requests to fail? Do you block and drop requests to google or something like that? Are you running on GCE?

The assumption when adding this originally is that in an environment with no Google auth then it would fail fast and silently.

[jeremyweber-np]

Its my work environment and I home now, so will explain best I can without having direct access to the env. Local build environment where the behavior was observed is a mac, running mvn 3.5 and the latest docker version 17.0.6.0 I think. The delay is at https://github.com/spotify/dockerfile-maven/blob/master/plugin/src/main/java/com/spotify/plugin/dockerfile/AbstractDockerMojo.java#L448 - i am not aware of anything internally on my side that would cause the delay before failure.

[freesoft]

Read https://developers.google.com/identity/protocols/application-default-credentials and found an interesting part.

The credentials you retrieved might require you to specify the scopes you need explicitly. Check for this case, and inject the requested scopes if required.

Collection COMPUTE_SCOPES =
Collections.singletonList(ComputeScopes.COMPUTE);
if (credential.createScopedRequired()) {
credential = credential.createScoped(COMPUTE_SCOPES);
}

and I don't see those Scope handling in AbstractDockerMojo. Maybe this is it? Haven't tested anything yet though.

[freesoft]

Also documentation says 5 cases that default credential is going to work otherwise it returns error. It doesn't specify anything about if there is going to be a delay before getting exception though. Check 5 items in "How the Application Default Credentials work" and check what's your case.

[mattnworb]

@freesoft the scope handling occurs in https://github.com/spotify/docker-client/blob/master/src/main/java/com/spotify/docker/client/auth/gcr/ContainerRegistryAuthSupplier.java

[jeremyweber-np]

Ive drilled down further. The delay comes when failing all the way back to checking for creds against the google compute engine, specifically this line:

https://github.com/google/google-auth-library-java/blob/5d566150b4af1b30940994bcac50cacc0537da10/oauth2_http/java/com/google/auth/oauth2/ComputeEngineCredentials.java#L133

[mattnworb]

@jeremyweber-np by any chance does the metadata.google.internal hostname resolve to something in your environment? For instance if you run dig metadata.google.internal or host metadata.google.internal.

[jeremyweber-np]

Nope:

dig metadata.google.internal
; <<>> DiG 9.8.3-P1 <<>> metadata.google.internal
;; global options: +cmd
;; connection timed out; no servers could be reached

[mattnworb]

@jeremyweber-np thanks for being willing to answer questions to help me learn more about this. I can't really reproduce this in my own environment so it is very helpful to learn more about yours.

I've run the plugin on a project using dockerfile-maven-plugin after making sure I have no gcloud credentials stored (gcloud auth revoke, gcloud auth application-default revoke, etc.) and it fails almost immediately with [ERROR] repository gcr.io/my-test-project/base-image not found: does not exist or no pull access (the image specified in the FROM in my Dockerfile).

Hope you wouldn't mind answering a few more questions.

As far as I can tell, the HttpTransportFactory instance used in the ComputeEngineCredentials class just wraps around the java.net http client. The main thing NetHttpTransport does is build a java.net.URLConnection in buildRequest() and later consume the inputStream.

1. Do you happen to set any system properties related to http.proxyHost or anything else like http.proxy in your environment? I believe HttpUrlConnection will use these automatically if enabled.

2. Do you see the same 30 second delay if you run a simple class with a main method that invokes GoogleCredentials.getApplicationDefault() like:

import com.google.auth.oauth2.GoogleCredentials;
import java.io.IOException;

public class ApplicationDefaultCredentialsTest {

  public static void main(String[] args) throws IOException {
    final GoogleCredentials credentials = GoogleCredentials.getApplicationDefault();
    System.out.printf("loaded credentials: %s\n", credentials);
  }
}

1. What about if you run a class like this, which tries to recreate what I think ComputeEngineCredentials is doing under the covers?

import java.io.BufferedReader;
import java.io.InputStreamReader;
import java.net.HttpURLConnection;
import java.net.URL;

public class MetadataServerTest {

  public static void main(String[] args) throws Exception {
    final String url = "http://metadata.google.internal";

    HttpURLConnection conn = (HttpURLConnection) new URL(url).openConnection();
    conn.setRequestMethod("GET");
    conn.connect();

    System.out.printf("Response from %s: %d %s\n", url, conn.getResponseCode(),
        conn.getResponseMessage());

    try (BufferedReader reader = new BufferedReader(new InputStreamReader(conn.getInputStream()))) {
      String line = null;
      while ((line = reader.readLine()) != null) {
        System.out.println(line);
      }
    }
  }
}

I would expect this to fail (almost immediately) with:

Exception in thread "main" java.net.UnknownHostException: metadata.google.internal

I've verified when running this in GCE though that it connects to the metadata server ok:

mattbrown@foobar:~$ java MetadataServerTest
Response code/message from http://metadata.google.internal: 200 OK
Headers: {null=[HTTP/1.0 200 OK], Date=[Thu, 06 Jul 2017 01:58:35 GMT], Content-Type=[application/text], Metadata-Flavor=[Google], Server=[BaseHTTP/0.3 Python/2.7.9]}
Response body:
0.1/
computeMetadata/

[jeremyweber-np]

No worries, interested in getting to the bottom of this.

1 - No proxy set
2 - 30 second delay with this stack

java.io.IOException: The Application Default Credentials are not available. They are available if running in Google Compute Engine. Otherwise, the environment variable GOOGLE_APPLICATION_CREDENTIALS must be defined pointing to a file defining the credentials. See https://developers.google.com/accounts/docs/application-default-credentials for more information.
    at com.google.auth.oauth2.DefaultCredentialsProvider.getDefaultCredentials(DefaultCredentialsProvider.java:111)
    at com.google.auth.oauth2.GoogleCredentials.getApplicationDefault(GoogleCredentials.java:103)
    at com.google.auth.oauth2.GoogleCredentials.getApplicationDefault(GoogleCredentials.java:76)
    at com.spotify.plugin.dockerfile.ApplicationDefaultCredentialsTest.main(ApplicationDefaultCredentialsTest.java:30)

3 -

Exception in thread "main" java.net.UnknownHostException: metadata.google.internal
    at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:184)
    at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)
    at java.net.Socket.connect(Socket.java:589)
    at java.net.Socket.connect(Socket.java:538)
    at sun.net.NetworkClient.doConnect(NetworkClient.java:180)
    at sun.net.www.http.HttpClient.openServer(HttpClient.java:432)
    at sun.net.www.http.HttpClient.openServer(HttpClient.java:527)
    at sun.net.www.http.HttpClient.<init>(HttpClient.java:211)
    at sun.net.www.http.HttpClient.New(HttpClient.java:308)
    at sun.net.www.http.HttpClient.New(HttpClient.java:326)
    at sun.net.www.protocol.http.HttpURLConnection.getNewHttpClient(HttpURLConnection.java:1169)
    at sun.net.www.protocol.http.HttpURLConnection.plainConnect0(HttpURLConnection.java:1105)
    at sun.net.www.protocol.http.HttpURLConnection.plainConnect(HttpURLConnection.java:999)
    at sun.net.www.protocol.http.HttpURLConnection.connect(HttpURLConnection.java:933)
    at com.spotify.plugin.dockerfile.MetadataServerTest.main(MetadataServerTest.java:34)

I suspect that this endpoint is only available from within the GCE platform. Are you running your tests on gce? Or have credentials cached in some way? I will also attempt this from my home network just to rule out something in my work environment causing the issue.

[mattnworb]

You are correct that ComputeEngineCredentials is expecting that that hostname will only resolve within GCE. It also has some other checks to make sure that the response actually comes from the GCE Metadata Service in case the code is running in an environment where that hostname resolves to a real address and a HTTP response is returned.

To clarify, when I tested, I did so both on my local laptop and on a GCE instance. On my local laptop I cleared out any gcloud credentials and ApplicationDefaultCredentialsTest fails immediately, with the same exception message you get. The MetadataServerTest also fails immediately with UnknownHostException.

[mattnworb]

@jeremyweber-np would it be possible for you to try to take a thread dump for test 2 above when it is stuck inside the thirty second delay? IIRC it should be sufficient to do kill -QUIT <pid> while it is running / delayed.

[jeremyweber-np]

Here you go...

test.dump.zip

[mattnworb]

Thanks @jeremyweber-np - interesting that the main thread seems to be inside Inet6AddressImpl.lookupAllHostAddr:

"main" #1 prio=5 os_prio=31 tid=0x00007fcadb801800 nid=0x1703 runnable [0x0000700000219000]
   java.lang.Thread.State: RUNNABLE
    at java.net.Inet6AddressImpl.lookupAllHostAddr(Native Method)
    at java.net.InetAddress$2.lookupAllHostAddr(InetAddress.java:928)
    at java.net.InetAddress.getAddressesFromNameService(InetAddress.java:1323)
    at java.net.InetAddress.getAllByName0(InetAddress.java:1276)
    at java.net.InetAddress.getAllByName(InetAddress.java:1192)
    at java.net.InetAddress.getAllByName(InetAddress.java:1126)
    at java.net.InetAddress.getByName(InetAddress.java:1076)
    at java.net.InetSocketAddress.<init>(InetSocketAddress.java:220)
    at sun.net.NetworkClient.doConnect(NetworkClient.java:180)
    at sun.net.www.http.HttpClient.openServer(HttpClient.java:432)
    at sun.net.www.http.HttpClient.openServer(HttpClient.java:527)
    - locked <0x000000076abc5868> (a sun.net.www.http.HttpClient)
    at sun.net.www.http.HttpClient.<init>(HttpClient.java:211)
    at sun.net.www.http.HttpClient.New(HttpClient.java:308)
    at sun.net.www.http.HttpClient.New(HttpClient.java:326)
    at sun.net.www.protocol.http.HttpURLConnection.getNewHttpClient(HttpURLConnection.java:1169)
    at sun.net.www.protocol.http.HttpURLConnection.plainConnect0(HttpURLConnection.java:1105)
    at sun.net.www.protocol.http.HttpURLConnection.plainConnect(HttpURLConnection.java:999)
    at sun.net.www.protocol.http.HttpURLConnection.connect(HttpURLConnection.java:933)
    at com.spotify.plugin.dockerfile.MetadataServerTest.main(MetadataServerTest.java:35)

[mattnworb]

Wait sorry, looks like that was for MetadataServerTest. Wasn't it ApplicationDefaultCredentialsTest that has the 30 second delay?

[jeremyweber-np]

Wait sorry, looks like that was for MetadataServerTest. Wasn't it ApplicationDefaultCredentialsTest that has the 30 second delay?

They both have the same delay. Havent had a chance to try this from home yet... Hopefully this weekend, but in any event it would seem reasonable to allow the user to turn this off if not needed. Thoughts?

[mattnworb]

but in any event it would seem reasonable to allow the user to turn this off if not needed.

Agreed! See my comments yesterday in #35

[mattnworb]

FWIW support for -Ddockerfile.googleContainerRegistryEnabled=false or <googleContainerRegistryEnabled>false</googleContainerRegistryEnabled> is now merged into master (#43)

[jeremyweber-np]

@mattnworb - thanks for getting that in. I was just about to fix up the PR. FWIW - the issue doesn't occur on my home network. It fails fast, no idea why this is an issue at work, but happy to have a work around.

[mattnworb]

One thing I would look more into is your DNS setup, and why resolving metadata.google.internal from within Java seems to take 30 seconds - this is what the stacktrace posted above for the two tests seem to be stuck in. It makes me curious if either your corporate environment in general or the Java VM specifically is configured to use a resolver(s) that takes 30 seconds to time out before returning NXDOMAIN.

One strategy you could take is to take additional thread dumps while the code above is "stuck" for 30 seconds to see if the main thread is consistently stuck in ava.net.Inet6AddressImpl.lookupAllHostAddr(Native Method).

[mattnworb]

Closing as there was no more activity or insight into this, and it couldn't be reproduced by others.