openshiftio / openshift.io

Red Hat OpenShift.io is an end-to-end development environment for planning, building and deploying modern applications.
https://openshift.io
97 stars 66 forks source link

Intermittent/recurring failures in completing execution of build pipeline - maven throttling? #2408

Closed ldimaggi closed 6 years ago

ldimaggi commented 6 years ago

Seeing this problem intermittently - a build pipeline fails - is this an example of the maven throttling?

[INFO] Results:
[INFO] 
[INFO] Tests run: 2, Failures: 0, Errors: 0, Skipped: 0
[INFO] 
[INFO] 
[INFO] --- maven-jar-plugin:3.0.2:jar (default-jar) @ testmar11519934883485 ---
[INFO] Building jar: /home/jenkins/workspace/estmar11519934883485_master-TPLS5CCTUEFQZRZDVO6RZYVYVDLQHZ5QOYUQ3XV5G5FX3A5X2WSQ/target/testmar11519934883485-1.0.1.jar
[INFO] 
[INFO] --- vertx-maven-plugin:1.0.13:package (vmp) @ testmar11519934883485 ---
[INFO] Executing: /bin/sh -c cd '/home/jenkins/workspace/estmar11519934883485_master-TPLS5CCTUEFQZRZDVO6RZYVYVDLQHZ5QOYUQ3XV5G5FX3A5X2WSQ' && 'git' 'whatchanged' '--until=2018-03-01 20:17:39 +0000' '--date=iso' '--' '/home/jenkins/workspace/estmar11519934883485_master-TPLS5CCTUEFQZRZDVO6RZYVYVDLQHZ5QOYUQ3XV5G5FX3A5X2WSQ'
[INFO] Working directory: /home/jenkins/workspace/estmar11519934883485_master-TPLS5CCTUEFQZRZDVO6RZYVYVDLQHZ5QOYUQ3XV5G5FX3A5X2WSQ
[INFO] 
[INFO] --- fabric8-maven-plugin:3.5.28:build (fmp) @ testmar11519934883485 ---
[INFO] F8: Using OpenShift build with strategy S2I
[INFO] F8: Running generator vertx
[INFO] F8: vertx: Using Docker image registry.access.redhat.com/redhat-openjdk-18/openjdk18-openshift as base / builder
[INFO] Copying files to /home/jenkins/workspace/estmar11519934883485_master-TPLS5CCTUEFQZRZDVO6RZYVYVDLQHZ5QOYUQ3XV5G5FX3A5X2WSQ/target/docker/testmar11519934883485/1.0.1/build/maven
[INFO] Building tar: /home/jenkins/workspace/estmar11519934883485_master-TPLS5CCTUEFQZRZDVO6RZYVYVDLQHZ5QOYUQ3XV5G5FX3A5X2WSQ/target/docker/testmar11519934883485/1.0.1/tmp/docker-build.tar
[INFO] F8: [testmar11519934883485:1.0.1] "vertx": Created docker source tar /home/jenkins/workspace/estmar11519934883485_master-TPLS5CCTUEFQZRZDVO6RZYVYVDLQHZ5QOYUQ3XV5G5FX3A5X2WSQ/target/docker/testmar11519934883485/1.0.1/tmp/docker-build.tar
[INFO] F8: Creating BuildServiceConfig testmar11519934883485-s2i for Source build
[INFO] F8: Creating ImageStream testmar11519934883485
[INFO] F8: Starting Build testmar11519934883485-s2i
EXITCODE   0[ERROR] F8: Failed to execute the build [Unable to build the image using the OpenShift build service]
[INFO] ------------------------------------------------------------------------
[INFO] BUILD FAILURE
[INFO] ------------------------------------------------------------------------
[INFO] Total time: 05:52 min
[INFO] Finished at: 2018-03-01T20:22:43+00:00
[INFO] Final Memory: 35M/71M
[INFO] ------------------------------------------------------------------------
[ERROR] Failed to execute goal io.fabric8:fabric8-maven-plugin:3.5.28:build (fmp) on project testmar11519934883485: Failed to execute the build: Unable to build the image using the OpenShift build service: An error has occurred. timeout: Socket closed -> [Help 1]
org.apache.maven.lifecycle.LifecycleExecutionException: Failed to execute goal io.fabric8:fabric8-maven-plugin:3.5.28:build (fmp) on project testmar11519934883485: Failed to execute the build
    at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:212)
    at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:153)
    at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:145)
    at org.apache.maven.lifecycle.internal.LifecycleModuleBuilder.buildProject(LifecycleModuleBuilder.java:116)
    at org.apache.maven.lifecycle.internal.LifecycleModuleBuilder.buildProject(LifecycleModuleBuilder.java:80)
    at org.apache.maven.lifecycle.internal.builder.singlethreaded.SingleThreadedBuilder.build(SingleThreadedBuilder.java:51)
    at org.apache.maven.lifecycle.internal.LifecycleStarter.execute(LifecycleStarter.java:128)
    at org.apache.maven.DefaultMaven.doExecute(DefaultMaven.java:307)
    at org.apache.maven.DefaultMaven.doExecute(DefaultMaven.java:193)
    at org.apache.maven.DefaultMaven.execute(DefaultMaven.java:106)
    at org.apache.maven.cli.MavenCli.execute(MavenCli.java:863)
    at org.apache.maven.cli.MavenCli.doMain(MavenCli.java:288)
    at org.apache.maven.cli.MavenCli.main(MavenCli.java:199)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:498)
    at org.codehaus.plexus.classworlds.launcher.Launcher.launchEnhanced(Launcher.java:289)
    at org.codehaus.plexus.classworlds.launcher.Launcher.launch(Launcher.java:229)
    at org.codehaus.plexus.classworlds.launcher.Launcher.mainWithExitCode(Launcher.java:415)
    at org.codehaus.plexus.classworlds.launcher.Launcher.main(Launcher.java:356)
Caused by: org.apache.maven.plugin.MojoExecutionException: Failed to execute the build
    at io.fabric8.maven.plugin.mojo.build.BuildMojo.buildAndTag(BuildMojo.java:245)
    at io.fabric8.maven.docker.BuildMojo.executeInternal(BuildMojo.java:44)
    at io.fabric8.maven.plugin.mojo.build.BuildMojo.executeInternal(BuildMojo.java:222)
    at io.fabric8.maven.docker.AbstractDockerMojo.execute(AbstractDockerMojo.java:223)
    at io.fabric8.maven.plugin.mojo.build.BuildMojo.execute(BuildMojo.java:193)
    at org.apache.maven.plugin.DefaultBuildPluginManager.executeMojo(DefaultBuildPluginManager.java:134)
    at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:207)
    ... 20 more
Caused by: io.fabric8.maven.core.service.Fabric8ServiceException: Unable to build the image using the OpenShift build service
    at io.fabric8.maven.core.service.openshift.OpenshiftBuildService.build(OpenshiftBuildService.java:114)
    at io.fabric8.maven.plugin.mojo.build.BuildMojo.buildAndTag(BuildMojo.java:242)
    ... 26 more
Caused by: io.fabric8.kubernetes.client.KubernetesClientException: An error has occurred.
    at io.fabric8.kubernetes.client.KubernetesClientException.launderThrowable(KubernetesClientException.java:62)
    at io.fabric8.kubernetes.client.KubernetesClientException.launderThrowable(KubernetesClientException.java:53)
    at io.fabric8.openshift.client.dsl.internal.BuildConfigOperationsImpl.fromInputStream(BuildConfigOperationsImpl.java:276)
    at io.fabric8.openshift.client.dsl.internal.BuildConfigOperationsImpl.fromFile(BuildConfigOperationsImpl.java:231)
    at io.fabric8.openshift.client.dsl.internal.BuildConfigOperationsImpl.fromFile(BuildConfigOperationsImpl.java:68)
    at io.fabric8.maven.core.service.openshift.OpenshiftBuildService.startBuild(OpenshiftBuildService.java:319)
    at io.fabric8.maven.core.service.openshift.OpenshiftBuildService.build(OpenshiftBuildService.java:104)
    ... 27 more
Caused by: java.net.SocketTimeoutException: timeout
    at okio.Okio$4.newTimeoutException(Okio.java:230)
    at okio.AsyncTimeout.exit(AsyncTimeout.java:285)
    at okio.AsyncTimeout$2.read(AsyncTimeout.java:241)
    at okio.RealBufferedSource.indexOf(RealBufferedSource.java:345)
    at okio.RealBufferedSource.readUtf8LineStrict(RealBufferedSource.java:217)
    at okio.RealBufferedSource.readUtf8LineStrict(RealBufferedSource.java:211)
    at okhttp3.internal.http1.Http1Codec.readResponseHeaders(Http1Codec.java:189)
    at okhttp3.internal.http.CallServerInterceptor.intercept(CallServerInterceptor.java:55)
    at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:92)
    at okhttp3.internal.connection.ConnectInterceptor.intercept(ConnectInterceptor.java:45)
    at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:92)
    at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:67)
    at okhttp3.internal.cache.CacheInterceptor.intercept(CacheInterceptor.java:93)
    at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:92)
    at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:67)
    at okhttp3.internal.http.BridgeInterceptor.intercept(BridgeInterceptor.java:93)
    at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:92)
    at okhttp3.internal.http.RetryAndFollowUpInterceptor.intercept(RetryAndFollowUpInterceptor.java:120)
    at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:92)
    at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:67)
    at io.fabric8.openshift.client.internal.OpenShiftOAuthInterceptor.intercept(OpenShiftOAuthInterceptor.java:64)
    at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:92)
    at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:67)
    at okhttp3.RealCall.getResponseWithInterceptorChain(RealCall.java:185)
    at okhttp3.RealCall.execute(RealCall.java:69)
    at io.fabric8.kubernetes.client.dsl.base.OperationSupport.handleResponse(OperationSupport.java:377)
    at io.fabric8.kubernetes.client.dsl.base.OperationSupport.handleResponse(OperationSupport.java:359)
    at io.fabric8.openshift.client.dsl.internal.BuildConfigOperationsImpl.fromInputStream(BuildConfigOperationsImpl.java:274)
    ... 31 more
Caused by: java.net.SocketException: Socket closed
    at java.net.SocketInputStream.read(SocketInputStream.java:204)
    at java.net.SocketInputStream.read(SocketInputStream.java:141)
    at sun.security.ssl.InputRecord.readFully(InputRecord.java:465)
    at sun.security.ssl.InputRecord.read(InputRecord.java:503)
    at sun.security.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:983)
    at sun.security.ssl.SSLSocketImpl.readDataRecord(SSLSocketImpl.java:940)
    at sun.security.ssl.AppInputStream.read(AppInputStream.java:105)
    at okio.Okio$2.read(Okio.java:139)
    at okio.AsyncTimeout$2.read(AsyncTimeout.java:237)
    ... 56 more
[ERROR] 
[ERROR] Re-run Maven using the -X switch to enable full debug logging.
[ERROR] 
[ERROR] For more information about the errors and possible solutions, please read the following articles:
[ERROR] [Help 1] http://cwiki.apache.org/confluence/display/MAVEN/MojoExecutionException
[Pipeline] }
[Pipeline] // stage
[Pipeline] }
[Pipeline] // container
[Pipeline] }
[Pipeline] // node
[Pipeline] }
[Pipeline] // podTemplate
[Pipeline] End of Pipeline
ldimaggi commented 6 years ago

Issue found/encountered by EE tests.

xyntrix commented 6 years ago

have we checked the xml files that get created to make sure the maven central named object isn't getting over-written on subsequent runs? i recall something about the maven config xml getting corrupted sometimes..

ldimaggi commented 6 years ago

Is this example of maven throttling? Saw a couple of build fail with this error.

[INFO] Copying 1 resource
[INFO] 
[INFO] --- fabric8-maven-plugin:3.5.28:resource (fmp) @ testmar21519999723302 ---
Mar 02, 2018 2:35:06 PM org.apache.maven.wagon.providers.http.httpclient.impl.execchain.RetryExec execute
INFO: I/O exception (java.net.SocketException) caught when processing request to {s}->https://repo.maven.apache.org:443: Connection reset
Mar 02, 2018 2:35:06 PM org.apache.maven.wagon.providers.http.httpclient.impl.execchain.RetryExec execute
INFO: Retrying request to {s}->https://repo.maven.apache.org:443
Mar 02, 2018 2:35:06 PM org.apache.maven.wagon.providers.http.httpclient.impl.execchain.RetryExec execute
INFO: I/O exception (java.net.SocketException) caught when processing request to {s}->https://repo.maven.apache.org:443: Connection reset
Mar 02, 2018 2:35:06 PM org.apache.maven.wagon.providers.http.httpclient.impl.execchain.RetryExec execute
INFO: Retrying request to {s}->https://repo.maven.apache.org:443
Mar 02, 2018 2:35:06 PM org.apache.maven.wagon.providers.http.httpclient.impl.execchain.RetryExec execute
INFO: I/O exception (java.net.SocketException) caught when processing request to {s}->https://repo.maven.apache.org:443: Connection reset
Mar 02, 2018 2:35:06 PM org.apache.maven.wagon.providers.http.httpclient.impl.execchain.RetryExec execute
INFO: Retrying request to {s}->https://repo.maven.apache.org:443
EXITCODE   0[INFO] ------------------------------------------------------------------------
[INFO] BUILD FAILURE
xyntrix commented 6 years ago

to help debug, we should try to find out what ip that's resolving to within the container. maybe we need to add a static set of ips to /etc/hosts? is this resolving to ipv6 vs ipv4? etc. with the low amount of concurrency here, even with a proxy in front, we may continue to have dependency fetch problems.

Looks like the CDN for this is fastly, at least for my workstation.. (may not be the same from a container..)

$ host repo.maven.apache.org
repo.maven.apache.org is an alias for repo.apache.maven.org.
repo.apache.maven.org is an alias for maven.map.fastly.net.
maven.map.fastly.net has address 151.101.24.215
$ host repo.apache.maven.org.
repo.apache.maven.org is an alias for maven.map.fastly.net.
maven.map.fastly.net has address 151.101.24.215
$ host maven.map.fastly.net.
maven.map.fastly.net has address 151.101.24.215

i've tried reaching out to the sonatype ops team to see if they can provide insight/logs from their side.

dns resolve/route ipv6 issue?

Based on this.. I tried a local test going from 1 connection to 2:

1c 1r:

[mmclane@mmclane ~]$ ab repo.maven.apache.org/maven2/
This is ApacheBench, Version 2.3 <$Revision: 1430300 $>
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Licensed to The Apache Software Foundation, http://www.apache.org/

Benchmarking repo.maven.apache.org (be patient).....done

Server Software:        
Server Hostname:        repo.maven.apache.org
Server Port:            80

Document Path:          /maven2/
Document Length:        111745 bytes

Concurrency Level:      1
Time taken for tests:   0.119 seconds
Complete requests:      1
Failed requests:        0
Write errors:           0
Total transferred:      112248 bytes
HTML transferred:       111745 bytes
Requests per second:    8.40 [#/sec] (mean)
Time per request:       119.072 [ms] (mean)
Time per request:       119.072 [ms] (mean, across all concurrent requests)
Transfer rate:          920.60 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:       18   18   0.0     18      18
Processing:   101  101   0.0    101     101
Waiting:       31   31   0.0     31      31
Total:        119  119   0.0    119     119

2c 10r

[mmclane@mmclane ~]$ ab -c2 -n10 -k https://repo.maven.apache.org/maven2/
This is ApacheBench, Version 2.3 <$Revision: 1430300 $>
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Licensed to The Apache Software Foundation, http://www.apache.org/

Benchmarking repo.maven.apache.org (be patient)...apr_pollset_poll: The timeout specified has expired (70007)

I'm blocked at a concurrency of 2 here. We would likely experience similar blocking from fastly, with a proxy such as nexus in place.

xyntrix commented 6 years ago

I performed a curl and noticed my connection was no longer blocked, so, I thought maybe this has something to do with user agent filtering. On further troubleshooting, this seems to be related to keepalives. If I fetch 1 page with keepalives on, stop my client, then make another request -- the request times out. If I disable keepalives and make a subsequent request -- it's fine. So this makes me think there could be a bug on Fastly's CDN with regard to keepalive behavior -- or with how the Maven backends respond to keepalives. Either way, I'm able to reproduce this timeout problem %100 with concurrency of 1 now, just by enabling keepalives:

mmclane@mmclane ~]$ ab -H "User-Agent: curl/7.29.0" -c1 -n1 -k https://repo.maven.apache.org/maven2/
This is ApacheBench, Version 2.3 <$Revision: 1430300 $>
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Licensed to The Apache Software Foundation, http://www.apache.org/

Benchmarking repo.maven.apache.org (be patient)...apr_pollset_poll: The timeout specified has expired (70007)

[mmclane@mmclane ~]$ ab -H "User-Agent: curl/7.29.0" -c1 -n1 https://repo.maven.apache.org/maven2/
This is ApacheBench, Version 2.3 <$Revision: 1430300 $>
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Licensed to The Apache Software Foundation, http://www.apache.org/

Benchmarking repo.maven.apache.org (be patient).....done

Server Software:        
Server Hostname:        repo.maven.apache.org
Server Port:            443
SSL/TLS Protocol:       TLSv1.2,ECDHE-RSA-AES128-GCM-SHA256,2048,128

Document Path:          /maven2/
Document Length:        111745 bytes

Concurrency Level:      1
Time taken for tests:   0.159 seconds
Complete requests:      1
Failed requests:        0
Write errors:           0
Total transferred:      112249 bytes
HTML transferred:       111745 bytes
Requests per second:    6.30 [#/sec] (mean)
Time per request:       158.752 [ms] (mean)
Time per request:       158.752 [ms] (mean, across all concurrent requests)
Transfer rate:          690.50 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:       70   70   0.0     70      70
Processing:    88   88   0.0     88      88
Waiting:       21   21   0.0     21      21
Total:        159  159   0.0    159     159
xyntrix commented 6 years ago

Varnish (Fastly) just hangs. In at least one attempt, I received about 200 bytes of content before the hang happened. This is very clearly unexpected CDN behavior.

1 client concurrency - looking to issue 2 requests:

[mmclane@mmclane ~]$ ab -v 2 -H "User-Agent: curl/7.29.0" -c1 -n2 -k https://repo.maven.apache.org/maven2/
This is ApacheBench, Version 2.3 <$Revision: 1430300 $>
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Licensed to The Apache Software Foundation, http://www.apache.org/

Benchmarking repo.maven.apache.org (be patient)...INFO: GET header == 
---
GET /maven2/ HTTP/1.0
Connection: Keep-Alive
User-Agent: curl/7.29.0
Host: repo.maven.apache.org
Accept: */*

---

Certificate version: 3
Valid from: Mar  8 12:00:00 2013 GMT
Valid to  : Mar  8 12:00:00 2023 GMT
Public key is 2048 bits
The issuer name is /C=US/O=DigiCert Inc/OU=www.digicert.com/CN=DigiCert Global Root CA
The subject name is /C=US/O=DigiCert Inc/CN=DigiCert SHA2 Secure Server CA
Extension Count: 7
Peer certificate
Certificate version: 3
Valid from: Jul 19 00:00:00 2017 GMT
Valid to  : Sep  3 12:00:00 2020 GMT
Public key is 2048 bits
The issuer name is /C=US/O=DigiCert Inc/CN=DigiCert SHA2 Secure Server CA
The subject name is /C=US/ST=MD/L=Fulton/O=Sonatype, Inc/CN=repo.maven.apache.org
Extension Count: 9
Transport Protocol      :TLSv1.2
Cipher Suite Protocol   :TLSv1/SSLv3
Cipher Suite Name       :ECDHE-RSA-AES128-GCM-SHA256
Cipher Suite Cipher Bits:128 (128)
SSL-Session:
    Protocol  : TLSv1.2
    Cipher    : ECDHE-RSA-AES128-GCM-SHA256
    Session-ID: {snip}
    Session-ID-ctx: 
    Master-Key: {snip}
    Key-Arg   : None
    Krb5 Principal: None
    PSK identity: None
    PSK identity hint: None
    TLS session ticket lifetime hint: 7200 (seconds)
    TLS session ticket:
{snip}

    Start Time: 1520018002
    Timeout   : 300 (sec)
    Verify return code: 20 (unable to get local issuer certificate)
LOG: header received:
HTTP/1.1 200 OK
Last-Modified: Tue, 12 Dec 2017 10:09:37 GMT
ETag: "dca483743a0284cbb4ee1b19c6a80a12"
Content-Type: text/html
Via: 1.1 varnish
Fastly-Debug-Digest: 9648f889e542c791069a3712497fbde4749f85854bc0f9a7409e5b5c0130957f
Content-Length: 111745
Accept-Ranges: bytes
Date: Fri, 02 Mar 2018 19:13:22 GMT
Via: 1.1 varnish
Age: 5151510
Connection: keep-alive
X-Served-By: cache-iad2147-IAD, cache-lax8637-LAX
X-Cache: HIT, HIT
X-Cache-Hits: 9, 201
X-Timer: S1520018003.719628,VS0,VE0

apr_pollset_poll: The timeout specified has expired (70007)
ldimaggi commented 6 years ago

Another failure:


[INFO] Copying files to /home/jenkins/workspace/estmar21520017994802_master-YUVNSMPLMJDFIZCK6ZAWDGG6LUMO6JA3QWTZTZJ2POFPLECKVF2Q/target/docker/testmar21520017994802/1.0.1/build/maven
[INFO] Building tar: /home/jenkins/workspace/estmar21520017994802_master-YUVNSMPLMJDFIZCK6ZAWDGG6LUMO6JA3QWTZTZJ2POFPLECKVF2Q/target/docker/testmar21520017994802/1.0.1/tmp/docker-build.tar
[INFO] F8: [testmar21520017994802:1.0.1] "vertx": Created docker source tar /home/jenkins/workspace/estmar21520017994802_master-YUVNSMPLMJDFIZCK6ZAWDGG6LUMO6JA3QWTZTZJ2POFPLECKVF2Q/target/docker/testmar21520017994802/1.0.1/tmp/docker-build.tar
[INFO] F8: Creating BuildServiceConfig testmar21520017994802-s2i for Source build
[INFO] F8: Creating ImageStream testmar21520017994802
[INFO] F8: Starting Build testmar21520017994802-s2i
EXITCODE   0[ERROR] F8: Failed to execute the build [Unable to build the image using the OpenShift build service]
[INFO] ------------------------------------------------------------------------
[INFO] BUILD FAILURE
[INFO] ------------------------------------------------------------------------
[INFO] Total time: 05:56 min
[INFO] Finished at: 2018-03-02T19:28:17+00:00
[INFO] Final Memory: 35M/73M
[INFO] ------------------------------------------------------------------------
[ERROR] Failed to execute goal io.fabric8:fabric8-maven-plugin:3.5.28:build (fmp) on project testmar21520017994802: Failed to execute the build: Unable to build the image using the OpenShift build service: An error has occurred. timeout: Socket closed -> [Help 1]
org.apache.maven.lifecycle.LifecycleExecutionException: Failed to execute goal io.fabric8:fabric8-maven-plugin:3.5.28:build (fmp) on project testmar21520017994802: Failed to execute the build
    at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:212)
    at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:153)
    at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:145)
    at org.apache.maven.lifecycle.internal.LifecycleModuleBuilder.buildProject(LifecycleModuleBuilder.java:116)
    at org.apache.maven.lifecycle.internal.LifecycleModuleBuilder.buildProject(LifecycleModuleBuilder.java:80)
    at org.apache.maven.lifecycle.internal.builder.singlethreaded.SingleThreadedBuilder.build(SingleThreadedBuilder.java:51)
    at org.apache.maven.lifecycle.internal.LifecycleStarter.execute(LifecycleStarter.java:128)
    at org.apache.maven.DefaultMaven.doExecute(DefaultMaven.java:307)
    at org.apache.maven.DefaultMaven.doExecute(DefaultMaven.java:193)
    at org.apache.maven.DefaultMaven.execute(DefaultMaven.java:106)
    at org.apache.maven.cli.MavenCli.execute(MavenCli.java:863)
    at org.apache.maven.cli.MavenCli.doMain(MavenCli.java:288)
    at org.apache.maven.cli.MavenCli.main(MavenCli.java:199)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:498)
    at org.codehaus.plexus.classworlds.launcher.Launcher.launchEnhanced(Launcher.java:289)
    at org.codehaus.plexus.classworlds.launcher.Launcher.launch(Launcher.java:229)
    at org.codehaus.plexus.classworlds.launcher.Launcher.mainWithExitCode(Launcher.java:415)
    at org.codehaus.plexus.classworlds.launcher.Launcher.main(Launcher.java:356)
Caused by: org.apache.maven.plugin.MojoExecutionException: Failed to execute the build
    at io.fabric8.maven.plugin.mojo.build.BuildMojo.buildAndTag(BuildMojo.java:245)
    at io.fabric8.maven.docker.BuildMojo.executeInternal(BuildMojo.java:44)
    at io.fabric8.maven.plugin.mojo.build.BuildMojo.executeInternal(BuildMojo.java:222)
    at io.fabric8.maven.docker.AbstractDockerMojo.execute(AbstractDockerMojo.java:223)
    at io.fabric8.maven.plugin.mojo.build.BuildMojo.execute(BuildMojo.java:193)
    at org.apache.maven.plugin.DefaultBuildPluginManager.executeMojo(DefaultBuildPluginManager.java:134)
    at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:207)
    ... 20 more
Caused by: io.fabric8.maven.core.service.Fabric8ServiceException: Unable to build the image using the OpenShift build service
    at io.fabric8.maven.core.service.openshift.OpenshiftBuildService.build(OpenshiftBuildService.java:114)
    at io.fabric8.maven.plugin.mojo.build.BuildMojo.buildAndTag(BuildMojo.java:242)
    ... 26 more
Caused by: io.fabric8.kubernetes.client.KubernetesClientException: An error has occurred.
    at io.fabric8.kubernetes.client.KubernetesClientException.launderThrowable(KubernetesClientException.java:62)
    at io.fabric8.kubernetes.client.KubernetesClientException.launderThrowable(KubernetesClientException.java:53)
    at io.fabric8.openshift.client.dsl.internal.BuildConfigOperationsImpl.fromInputStream(BuildConfigOperationsImpl.java:276)
    at io.fabric8.openshift.client.dsl.internal.BuildConfigOperationsImpl.fromFile(BuildConfigOperationsImpl.java:231)
    at io.fabric8.openshift.client.dsl.internal.BuildConfigOperationsImpl.fromFile(BuildConfigOperationsImpl.java:68)
    at io.fabric8.maven.core.service.openshift.OpenshiftBuildService.startBuild(OpenshiftBuildService.java:319)
    at io.fabric8.maven.core.service.openshift.OpenshiftBuildService.build(OpenshiftBuildService.java:104)
    ... 27 more
Caused by: java.net.SocketTimeoutException: timeout
    at okio.Okio$4.newTimeoutException(Okio.java:230)
    at okio.AsyncTimeout.exit(AsyncTimeout.java:285)
    at okio.AsyncTimeout$2.read(AsyncTimeout.java:241)
    at okio.RealBufferedSource.indexOf(RealBufferedSource.java:345)
    at okio.RealBufferedSource.readUtf8LineStrict(RealBufferedSource.java:217)
    at okio.RealBufferedSource.readUtf8LineStrict(RealBufferedSource.java:211)
    at okhttp3.internal.http1.Http1Codec.readResponseHeaders(Http1Codec.java:189)
    at okhttp3.internal.http.CallServerInterceptor.intercept(CallServerInterceptor.java:55)
    at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:92)
    at okhttp3.internal.connection.ConnectInterceptor.intercept(ConnectInterceptor.java:45)
    at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:92)
    at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:67)
    at okhttp3.internal.cache.CacheInterceptor.intercept(CacheInterceptor.java:93)
    at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:92)
    at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:67)
    at okhttp3.internal.http.BridgeInterceptor.intercept(BridgeInterceptor.java:93)
    at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:92)
    at okhttp3.internal.http.RetryAndFollowUpInterceptor.intercept(RetryAndFollowUpInterceptor.java:120)
    at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:92)
    at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:67)
    at io.fabric8.openshift.client.internal.OpenShiftOAuthInterceptor.intercept(OpenShiftOAuthInterceptor.java:64)
    at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:92)
    at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:67)
    at okhttp3.RealCall.getResponseWithInterceptorChain(RealCall.java:185)
    at okhttp3.RealCall.execute(RealCall.java:69)
    at io.fabric8.kubernetes.client.dsl.base.OperationSupport.handleResponse(OperationSupport.java:377)
    at io.fabric8.kubernetes.client.dsl.base.OperationSupport.handleResponse(OperationSupport.java:359)
    at io.fabric8.openshift.client.dsl.internal.BuildConfigOperationsImpl.fromInputStream(BuildConfigOperationsImpl.java:274)
    ... 31 more
Caused by: java.net.SocketException: Socket closed
    at java.net.SocketInputStream.read(SocketInputStream.java:204)
    at java.net.SocketInputStream.read(SocketInputStream.java:141)
    at sun.security.ssl.InputRecord.readFully(InputRecord.java:465)
    at sun.security.ssl.InputRecord.read(InputRecord.java:503)
    at sun.security.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:983)
    at sun.security.ssl.SSLSocketImpl.readDataRecord(SSLSocketImpl.java:940)
    at sun.security.ssl.AppInputStream.read(AppInputStream.java:105)
    at okio.Okio$2.read(Okio.java:139)
    at okio.AsyncTimeout$2.read(AsyncTimeout.java:237)
    ... 56 more
[ERROR] 
ldimaggi commented 6 years ago

The failures are all occurring on the starter-us-east-2a cluster today.

xyntrix commented 6 years ago
[mmclane@mmclane ~]$ ab -v 2 -H "User-Agent: curl/7.29.0" -c1 -n1 -k https://repo.maven.apache.org/maven2/
This is ApacheBench, Version 2.3 <$Revision: 1430300 $>
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Licensed to The Apache Software Foundation, http://www.apache.org/

Benchmarking repo.maven.apache.org (be patient)...INFO: GET header == 
---
GET /maven2/ HTTP/1.0
Connection: Keep-Alive
User-Agent: curl/7.29.0
Host: repo.maven.apache.org
Accept: */*

---

Certificate version: 3
Valid from: Mar  8 12:00:00 2013 GMT
Valid to  : Mar  8 12:00:00 2023 GMT
Public key is 2048 bits
The issuer name is /C=US/O=DigiCert Inc/OU=www.digicert.com/CN=DigiCert Global Root CA
The subject name is /C=US/O=DigiCert Inc/CN=DigiCert SHA2 Secure Server CA
Extension Count: 7
Peer certificate
Certificate version: 3
Valid from: Jul 19 00:00:00 2017 GMT
Valid to  : Sep  3 12:00:00 2020 GMT
Public key is 2048 bits
The issuer name is /C=US/O=DigiCert Inc/CN=DigiCert SHA2 Secure Server CA
The subject name is /C=US/ST=MD/L=Fulton/O=Sonatype, Inc/CN=repo.maven.apache.org
Extension Count: 9
Transport Protocol      :TLSv1.2
Cipher Suite Protocol   :TLSv1/SSLv3
Cipher Suite Name       :ECDHE-RSA-AES128-GCM-SHA256
Cipher Suite Cipher Bits:128 (128)
SSL-Session:
    Protocol  : TLSv1.2
    Cipher    : ECDHE-RSA-AES128-GCM-SHA256
    Session-ID: 85A866A786E8A3B2BC2D158DAAF1B054F3C750920D26B007EA1EBAFBA6EB1CFD
    Session-ID-ctx: 
    Master-Key: D4CD0B44541C9F55EEB514B8FED30A85233B2F856CA3C24537D26EE0F66CF354B963EC9B764B46DB5839DAEB71224F86
    Key-Arg   : None
    Krb5 Principal: None
    PSK identity: None
    PSK identity hint: None
    TLS session ticket lifetime hint: 7200 (seconds)
    TLS session ticket:
    0000 - c3 90 1d 0d 71 25 2f 26-b1 06 28 8a 45 24 c8 7e   ....q%/&..(.E$.~
    0010 - 00 e5 3a 32 d7 b0 d6 e5-7e a2 b3 93 4a 82 da 0e   ..:2....~...J...
    0020 - 63 36 14 6e 67 5b fb 66-e7 96 0f 64 dc e0 22 37   c6.ng[.f...d.."7
    0030 - fe 31 90 72 1a 23 ae be-f3 31 42 75 9f de 43 33   .1.r.#...1Bu..C3
    0040 - 38 4b 0e 14 e8 8a b4 9f-d7 85 bb c0 f3 76 9f ce   8K...........v..
    0050 - eb f5 05 c1 df e6 9e 28-1e 2d ae 21 bd f2 d2 70   .......(.-.!...p
    0060 - b6 ab e9 88 87 39 50 66-b0 c8 98 78 9f 13 c4 28   .....9Pf...x...(
    0070 - ba 05 9b e1 ab 28 7f bd-69 7f e2 b9 cd 71 8c 31   .....(..i....q.1
    0080 - f9 d5 83 2e 4d b3 05 a8-3a 68 77 7b 56 79 78 14   ....M...:hw{Vyx.
    0090 - 4f 59 3e b7 13 8d c4 c6-db 17 1d 30 08 47 9a      OY>........0.G.
    00a0 - <SPACES/NULS>

    Start Time: 1520021038
    Timeout   : 300 (sec)
    Verify return code: 20 (unable to get local issuer certificate)
LOG: header received:
HTTP/1.1 200 OK
Last-Modified: Tue, 12 Dec 2017 10:09:37 GMT
ETag: "dca483743a0284cbb4ee1b19c6a80a12"
Content-Type: text/html
Via: 1.1 varnish
Fastly-Debug-Digest: 9648f889e542c791069a3712497fbde4749f85854bc0f9a7409e5b5c0130957f
Content-Length: 111745
Accept-Ranges: bytes
Date: Fri, 02 Mar 2018 20:03:58 GMT
Via: 1.1 varnish
Age: 5154546
Connection: keep-alive
X-Served-By: cache-iad2147-IAD, cache-lax8637-LAX
X-Cache: HIT, HIT
X-Cache-Hits: 9, 219
X-Timer: S1520021039.727752,VS0,VE0

<!DOCTYPE html>
<html>

<head>
    <title>Central Repository: </title>
    <meta name="viewport" content="width=device-width, initial-scale=1.0">
    <style>
body {
    background: #fff;
}
    </style>
</head>

<body>
    <header>
        <h1></h1>
    </header>
    <hr/>
    <main>
        <pre id="contents">
<a href="../">../</a>
<a href="HTTPClient/" title="HTTPClient/">HTTPClient/</a>                                                      -         -      
<a href="abbot/" title="abbot/">abbot/</a>                                                           -         -      
<a href="acegisecurity/" title="acegisecurity/">acegisecurity/</a>                                                   -         -      
<a href="activation/" title="activation/">activation/</a>                                                      -         -      
<a href="activecluster/" title="activecluster/">activecluster/</a>                                                   -         -      
<a href="activeio/" title="activeio/">activeio/</a>                                                        -         -      
<a href="activemq/" title="activemq/">activemq/</a>                                                        -         -      
<a href="activemq-jaxb/" title="activemq-jaxb/">activemq-jaxb/</a>                                                   -         -      
<a href="activesoap/" title="activesoap/">activesoap/</a>                                                      -         -      
<a href="activespace/" title="activespace/">activespace/</a>                          
{...hangs...}
xyntrix commented 6 years ago

Digging a little deeper here: if we use alternative maven mirrors, we don't see timeouts. See github: https://github.com/openshiftio/openshift.io/issues/2457 on the request to get different mirrors added to the default maven config.

Basically this boils down to: Fastly's CDN for the maven content results in quite frequent timeouts and/or http protocol violations (confusing the maven client).

It looks like if a client sends in an http/1.0 request, with keepalives, and the server is going to send a chunked response back -- instead, it just hangs. This is exactly the symptoms described in this old varnish trac ticket: https://varnish-cache.org/trac/ticket/524 (Varnish 2.0.4). Perhaps this is a regression? Except that Fastly is likely running very old Varnish code.

According to Fastly's site they are running a forked version of Varnish 2.1 (latest Varnish is 5.2.1). https://docs.fastly.com/guides/vcl/guide-to-vcl

Varnish 2.1 was released Jan-2011

Also, irrespective of what protocol standards Varnish is actually following -- varnish appears to always send a http/1.1 response as a static header. This design was detailed here: http://varnish-cache.org/trac/ticket/641#comment:5

We've tried reaching out to Fastly.. nothing helpful as of yet.

In the mean time the following actions will likely improve this state:

xyntrix commented 6 years ago

As an additional reference, may be worth reviewing Maven's http client library (Wagon). There are some specific historical issues here: https://issues.apache.org/jira/browse/WAGON-486?focusedCommentId=15948630&page=com.atlassian.jira.plugin.system.issuetabpanels%3Acomment-tabpanel#comment-15948630

xyntrix commented 6 years ago

and for reference, how to enable more detailed http logging: https://hc.apache.org/httpcomponents-client-ga/logging.html

ldimaggi commented 6 years ago

Closing as duplicate of #3178