S2I build fails on Openshift 3.6 when building Java application from catalog image redhat-openjdk-18/openjdk18-openshift:

I0308 06:19:26.851609       1 tar.go:296] Adding to tar: /tmp/s2i-build856971515/upload/src/src/test/java/ServiceApplicationTests.java
--
  | I0308 06:19:26.852546       1 sti.go:684] tar: /tmp: Cannot open: Permission denied
  | I0308 06:19:26.852580       1 sti.go:684] tar: Error is not recoverable: exiting now
  | I0308 06:19:26.932662       1 docker.go:1049] Waiting for container "1b9f319d37271d70e47340208e2a142937700f232048761fb324629ce7585515" to stop ...
  | I0308 06:19:26.948436       1 docker.go:985] Removing container "1b9f319d37271d70e47340208e2a142937700f232048761fb324629ce7585515" ...
  | I0308 06:19:26.963770       1 docker.go:995] Removed container "1b9f319d37271d70e47340208e2a142937700f232048761fb324629ce7585515"
  | I0308 06:19:26.964172       1 cleanup.go:31] Temporary directory "/tmp/s2i-build856971515" will be saved, not deleted
  | F0308 06:19:27.007414       1 helpers.go:119] error: build error: non-zero (13) exit code from registry.access.redhat.com/redhat-openjdk-18/openjdk18-openshift@sha256:5ffd5b1ec8e4264cdd62a3063ee56e370a973e0777da9c8c6f3a5f12e22fe6d5

Version

openshift 3.6.173.0.96 kubernetes 1.6.1+5115d708d7 docker 1.12.6 ( docker-1.12.6-71.git3e8e77d.el7.x86_64) (VM where build fails) Linux 3.10.0-693.17.1.el7.x86_64

Reproduce

Openshift web console -> Catalog -> select image openjdk18-openshift Set Git URL + build option BUILD_LOGLEVEL=“5” Start build, following build events generated until failure:

• Successfully assigned myservice-2-build to nyapp25.op.com
• Build sbx/myservice-2 is now running
• Created container
• Started container
• Container image “openshift3/ose-sti-builder:v3.6.173.0.96” already present on machine
• Build sbx/myservice-2 failed…

Looking deeper at system logs using dmesg -TwL, the following events are generated for the duration of the build until it fails. I don’t believe this is related to the root cause since after we inspected the same log on a healthy node we observed the same events.

[Thu Mar  8 01:19:20 2018] SELinux: mount invalid.  Same superblock, different security settings for (dev mqueue, type mqueue)
[Thu Mar  8 01:19:20 2018] IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready
[Thu Mar  8 01:19:20 2018] IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
[Thu Mar  8 01:19:21 2018] device vethb38cb0b0 entered promiscuous mode
[Thu Mar  8 01:19:23 2018] SELinux: mount invalid.  Same superblock, different security settings for (dev mqueue, type mqueue)
[Thu Mar  8 01:19:24 2018] device vethb38cb0b0 left promiscuous mode

Additional Information

Comparing app nodes where build succeeds (nyapp02) and fails (nyapp25) we could not find any major differences except for one package json-glib-1.2.6-1.el7.x86_64, which was missing on the app node where the build fails, but the error persists even after restoring the package.

nyapp02.opp.com    v1.6.1+5115d708d7  OpenShift Enterprise  3.10.0-693.17.1.el7.x86_64
nyapp25.opp.com    v1.6.1+5115d708d7  OpenShift Enterprise  3.10.0-693.17.1.el7.x86_64

Full Build Log…

I0308 06:19:25.540352       1 builder.go:72] redacted build: {"kind":"Build","apiVersion":"v1","metadata":{"name":"myservice-1","namespace":"sbx","selfLink":"/apis/build.openshift.io/v1/namespaces/sbx/builds/fundservice-1","uid":"a4fecd65-2298-11e8-a020-0050568b39b9","resourceVersion":"22753036","creationTimestamp":"2018-03-08T06:19:23Z","labels":{"app":"fundservice","buildconfig":"fundservice","openshift.io/build-config.name":"fundservice","openshift.io/build.start-policy":"Serial"},"annotations":{"openshift.io/build-config.name":"fundservice","openshift.io/build.number":"1"},"ownerReferences":[{"apiVersion":"build.openshift.io/v1","kind":"BuildConfig","name":"fundservice","uid":"a4ede0ec-2298-11e8-9b10-0050568b7d0a","controller":true}]},"spec":{"serviceAccount":"builder","source":{"type":"Git","git":{"uri":"http://git.acme.com/scm/ea/consul-discovery-fundservice.git","ref":"master"}},"strategy":{"type":"Source","sourceStrategy":{"from":{"kind":"DockerImage","name":"registry.access.redhat.com/redhat-openjdk-18/openjdk18-openshift@sha256:5ffd5b1ec8e4264cdd62a3063ee56e370a973e0777da9c8c6f3a5f12e22fe6d5"},"env":[{"name":"MAVEN_MIRROR_URL","value":"http://artifactory.den.acme.com/libs-release"},{"name":"BUILD_LOGLEVEL","value":"5"}]}},"output":{"to":{"kind":"DockerImage","name":"10.172.198.246:5000/sbx/fundservice:latest"},"pushSecret":{"name":"builder-dockercfg-jtfsr"}},"resources":{},"postCommit":{},"nodeSelector":null,"triggeredBy":[{"message":"Image change","imageChangeBuild":{"imageID":"registry.access.redhat.com/redhat-openjdk-18/openjdk18-openshift@sha256:5ffd5b1ec8e4264cdd62a3063ee56e370a973e0777da9c8c6f3a5f12e22fe6d5","fromRef":{"kind":"ImageStreamTag","namespace":"openshift","name":"redhat-openjdk18-openshift:1.1"}}}]},"status":{"phase":"New","outputDockerImageReference":"10.172.198.246:5000/sbx/fundservice:latest","config":{"kind":"BuildConfig","namespace":"sbx","name":"fundservice"},"output":{}}}
I0308 06:19:25.541153       1 builder.go:83] Master version "v3.6.173.0.96", Builder version "v3.6.173.0.96"
I0308 06:19:25.542304       1 util.go:197] found cgroup parent kubepods-burstable-poda5035c05_2298_11e8_a020_0050568b39b9.slice
I0308 06:19:25.542430       1 builder.go:174] Running build with cgroup limits: api.CGroupLimits{MemoryLimitBytes:2147483648, CPUShares:0, CPUPeriod:0, CPUQuota:0, MemorySwap:2147483648, Parent:"kubepods-burstable-poda5035c05_2298_11e8_a020_0050568b39b9.slice"}
Cloning "http://git.acme.com/scm/ea/consul-discovery-fundservice.git" ...
I0308 06:19:25.543279       1 source.go:138] git ls-remote --heads http://git.acme.com/scm/ea/consul-discovery-fundservice.git
I0308 06:19:25.543343       1 repository.go:385] Executing git ls-remote --heads http://git.acme.com/scm/ea/consul-discovery-fundservice.git
I0308 06:19:25.801447       1 source.go:141] 8c92b1fccbfa07270788e11f3072e8f4f27c85fb	refs/heads/master
I0308 06:19:25.801500       1 source.go:240] Cloning source from http://git.acme.com/scm/ea/consul-discovery-fundservice.git
I0308 06:19:25.801521       1 repository.go:385] Executing git clone http://git.acme.com/scm/ea/consul-discovery-fundservice.git /tmp/s2i-build856971515/upload/src
I0308 06:19:26.274836       1 repository.go:385] Executing git checkout master --
I0308 06:19:26.283585       1 repository.go:385] Executing git submodule update --init --recursive
I0308 06:19:26.356192       1 repository.go:385] Executing git rev-parse --abbrev-ref HEAD
I0308 06:19:26.360575       1 repository.go:385] Executing git rev-parse --verify HEAD
I0308 06:19:26.364604       1 repository.go:385] Executing git --no-pager show -s --format=%an HEAD
I0308 06:19:26.369014       1 repository.go:385] Executing git --no-pager show -s --format=%ae HEAD
I0308 06:19:26.390492       1 repository.go:385] Executing git --no-pager show -s --format=%cn HEAD
I0308 06:19:26.395159       1 repository.go:385] Executing git --no-pager show -s --format=%ce HEAD
I0308 06:19:26.399803       1 repository.go:385] Executing git --no-pager show -s --format=%ad HEAD
I0308 06:19:26.404383       1 repository.go:385] Executing git --no-pager show -s --format=%<(80,trunc)%s HEAD
I0308 06:19:26.408811       1 repository.go:385] Executing git config --get remote.origin.url
	Commit:	8c92b1fccbfa07270788e11f3072e8f4f27c85fb (Added instance ID and namespace to REST responses)
	Date:	Sun Feb 25 23:40:46 2018 -0500
I0308 06:19:26.412774       1 repository.go:385] Executing git rev-parse --abbrev-ref HEAD
I0308 06:19:26.416788       1 repository.go:385] Executing git rev-parse --verify HEAD
I0308 06:19:26.420667       1 repository.go:385] Executing git --no-pager show -s --format=%an HEAD
I0308 06:19:26.425103       1 repository.go:385] Executing git --no-pager show -s --format=%ae HEAD
I0308 06:19:26.429522       1 repository.go:385] Executing git --no-pager show -s --format=%cn HEAD
I0308 06:19:26.433958       1 repository.go:385] Executing git --no-pager show -s --format=%ce HEAD
I0308 06:19:26.438708       1 repository.go:385] Executing git --no-pager show -s --format=%ad HEAD
I0308 06:19:26.443092       1 repository.go:385] Executing git --no-pager show -s --format=%<(80,trunc)%s HEAD
I0308 06:19:26.447632       1 repository.go:385] Executing git config --get remote.origin.url
I0308 06:19:26.539605       1 sti.go:241] With force pull false, setting policies to if-not-present
I0308 06:19:26.539662       1 sti.go:248] The value of ALLOWED_UIDS is [1-]
I0308 06:19:26.539688       1 sti.go:256] The value of DROP_CAPS is [KILL,MKNOD,SETGID,SETUID,SYS_CHROOT]
I0308 06:19:26.539713       1 cfg.go:39] Locating docker auth for image registry.access.redhat.com/redhat-openjdk-18/openjdk18-openshift@sha256:5ffd5b1ec8e4264cdd62a3063ee56e370a973e0777da9c8c6f3a5f12e22fe6d5 and type PULL_DOCKERCFG_PATH
I0308 06:19:26.539733       1 cfg.go:49] Getting docker auth in paths : []
I0308 06:19:26.539788       1 config.go:131] looking for config.json at /var/lib/origin/config.json
I0308 06:19:26.539848       1 config.go:131] looking for config.json at /var/lib/origin/config.json
I0308 06:19:26.539864       1 config.go:131] looking for config.json at /root/.docker/config.json
I0308 06:19:26.539929       1 config.go:131] looking for config.json at /.docker/config.json
I0308 06:19:26.540029       1 cfg.go:39] Locating docker auth for image 10.172.198.246:5000/sbx/fundservice:latest and type PUSH_DOCKERCFG_PATH
I0308 06:19:26.540039       1 cfg.go:49] Getting docker auth in paths : [/var/run/secrets/openshift.io/push]
I0308 06:19:26.540049       1 config.go:131] looking for config.json at /var/run/secrets/openshift.io/push/config.json
I0308 06:19:26.540143       1 config.go:101] looking for .dockercfg at /var/run/secrets/openshift.io/push/.dockercfg
I0308 06:19:26.540563       1 config.go:112] found .dockercfg at /var/run/secrets/openshift.io/push/.dockercfg
I0308 06:19:26.540631       1 cfg.go:62] Using serviceaccount user for Docker authentication for image 10.172.198.246:5000/sbx/fundservice:latest
I0308 06:19:26.547139       1 docker.go:504] Using locally available image "registry.access.redhat.com/redhat-openjdk-18/openjdk18-openshift@sha256:5ffd5b1ec8e..."
I0308 06:19:26.551264       1 sti.go:290] Creating a new S2I builder with config: "Builder Name:\t\t\tJava Applications\nBuilder Image:\t\t\tregistry.access.redhat.com/redhat-openjdk-18/openjdk18-openshift@sha256:5ffd5b1ec8e4264cdd62a3063ee56e370a973e0777da9c8c6f3a5f12e22fe6d5\nSource:\t\t\t\t/tmp/s2i-build856971515/upload/src\nOutput Image Tag:\t\tsbx/fundservice-1:a0ad275c\nEnvironment:\t\t\tOPENSHIFT_BUILD_NAME=fundservice-1,OPENSHIFT_BUILD_NAMESPACE=sbx,OPENSHIFT_BUILD_SOURCE=http://git.acme.com/scm/ea/consul-discovery-fundservice.git,OPENSHIFT_BUILD_REFERENCE=master,OPENSHIFT_BUILD_COMMIT=8c92b1fccbfa07270788e11f3072e8f4f27c85fb,MAVEN_MIRROR_URL=http://artifactory.den.acme.com/libs-release,BUILD_LOGLEVEL=5\nLabels:\t\t\t\tio.openshift.build.name=\"fundservice-1\",io.openshift.build.namespace=\"sbx\"\nIncremental Build:\t\tdisabled\nRemove Old Build:\t\tdisabled\nBuilder Pull Policy:\t\tif-not-present\nPrevious Image Pull Policy:\talways\nQuiet:\t\t\t\tdisabled\nLayered Build:\t\t\tdisabled\nS2I Scripts URL:\t\t//redacted@\nWorkdir:\t\t\t/tmp/s2i-build856971515\nDocker NetworkMode:\t\tcontainer:d0a13d5abff26d1a0c6411fff03edf0b4c6dbb699d0e8c69e5d5578ff3acce43\nDocker Endpoint:\t\tunix:///var/run/docker.sock\n"
I0308 06:19:26.555487       1 docker.go:504] Using locally available image "registry.access.redhat.com/redhat-openjdk-18/openjdk18-openshift@sha256:5ffd5b1ec8e..."
I0308 06:19:26.566834       1 docker.go:504] Using locally available image "registry.access.redhat.com/redhat-openjdk-18/openjdk18-openshift@sha256:5ffd5b1ec8e..."
I0308 06:19:26.566884       1 docker.go:735] Image sha256:4fba0e27a948945066537b40ec80c53e363cc8d66884ed4c6f978a950db77c1e contains io.openshift.s2i.scripts-url set to "image:///usr/local/s2i"
I0308 06:19:26.566925       1 scm.go:20] DownloadForSource /tmp/s2i-build856971515/upload/src
I0308 06:19:26.567219       1 git.go:215] makePathAbsolute /tmp/s2i-build856971515/upload/src
I0308 06:19:26.567249       1 scm.go:27] return from ParseFile file exists true proto specified false use copy false
I0308 06:19:26.567261       1 scm.go:39] new source from parse file /tmp/s2i-build856971515/upload/src
I0308 06:19:26.567301       1 sti.go:303] Starting S2I build from sbx/fundservice-1 BuildConfig ...
I0308 06:19:26.567349       1 sti.go:200] Preparing to build sbx/fundservice-1:a0ad275c
I0308 06:19:26.568046       1 download.go:30] Copying sources from "/tmp/s2i-build856971515/upload/src" to "/tmp/s2i-build856971515/upload/src"
I0308 06:19:26.568199       1 install.go:249] Using "assemble" installed from "image:///usr/local/s2i/assemble"
I0308 06:19:26.568244       1 install.go:249] Using "run" installed from "image:///usr/local/s2i/run"
I0308 06:19:26.568286       1 install.go:249] Using "save-artifacts" installed from "image:///usr/local/s2i/save-artifacts"
I0308 06:19:26.568388       1 ignore.go:63] .s2iignore file does not exist
I0308 06:19:26.568415       1 sti.go:209] Clean build will be performed
I0308 06:19:26.568425       1 sti.go:212] Performing source build from file:///tmp/s2i-build856971515/upload/src
I0308 06:19:26.568444       1 sti.go:223] Running "assemble" in "sbx/fundservice-1:a0ad275c"
I0308 06:19:26.568456       1 sti.go:559] Using image name registry.access.redhat.com/redhat-openjdk-18/openjdk18-openshift@sha256:5ffd5b1ec8e4264cdd62a3063ee56e370a973e0777da9c8c6f3a5f12e22fe6d5
I0308 06:19:26.572345       1 docker.go:504] Using locally available image "registry.access.redhat.com/redhat-openjdk-18/openjdk18-openshift@sha256:5ffd5b1ec8e..."
I0308 06:19:26.572415       1 sti.go:447] No user environment provided (no environment file found in application sources)
I0308 06:19:26.572574       1 sti.go:672] starting the source uploading ...
I0308 06:19:26.572635       1 tar.go:201] Adding "/tmp/s2i-build856971515/upload" to tar ...
I0308 06:19:26.572773       1 tar.go:296] Adding to tar: /tmp/s2i-build856971515/upload/scripts as scripts
I0308 06:19:26.580652       1 docker.go:735] Image sha256:4fba0e27a948945066537b40ec80c53e363cc8d66884ed4c6f978a950db77c1e contains io.openshift.s2i.scripts-url set to "image:///usr/local/s2i"
I0308 06:19:26.580687       1 docker.go:810] Base directory for S2I scripts is '/usr/local/s2i'. Untarring destination is '/tmp'.
I0308 06:19:26.580714       1 docker.go:966] Setting "/bin/sh -c tar -C /tmp -xf - && /usr/local/s2i/assemble" command for container ...
I0308 06:19:26.581087       1 docker.go:975] Creating container with options {Name:"s2i_registry_access_redhat_com_redhat_openjdk_18_openjdk18_openshift_sha256_5ffd5b1ec8e4264cdd62a3063ee56e370a973e0777da9c8c6f3a5f12e22fe6d5_c3bf3941" Config:{Hostname: Domainname: User: AttachStdin:false AttachStdout:true AttachStderr:false ExposedPorts:map[] Tty:false OpenStdin:true StdinOnce:true Env:[OPENSHIFT_BUILD_NAME=fundservice-1 OPENSHIFT_BUILD_NAMESPACE=sbx OPENSHIFT_BUILD_SOURCE=http://git.acme.com/scm/ea/consul-discovery-fundservice.git OPENSHIFT_BUILD_REFERENCE=master OPENSHIFT_BUILD_COMMIT=8c92b1fccbfa07270788e11f3072e8f4f27c85fb MAVEN_MIRROR_URL=http://artifactory.den.acme.com/libs-release BUILD_LOGLEVEL=5] Cmd:[/bin/sh -c tar -C /tmp -xf - && /usr/local/s2i/assemble] ArgsEscaped:false Image:registry.access.redhat.com/redhat-openjdk-18/openjdk18-openshift@sha256:5ffd5b1ec8e4264cdd62a3063ee56e370a973e0777da9c8c6f3a5f12e22fe6d5 Volumes:map[] WorkingDir: Entrypoint:[] NetworkDisabled:false MacAddress: OnBuild:[] Labels:map[] StopSignal:} HostConfig:&{Binds:[] ContainerIDFile: LogConfig:{Type: Config:map[]} NetworkMode:container:d0a13d5abff26d1a0c6411fff03edf0b4c6dbb699d0e8c69e5d5578ff3acce43 PortBindings:map[] RestartPolicy:{Name: MaximumRetryCount:0} AutoRemove:false VolumeDriver: VolumesFrom:[] CapAdd:[] CapDrop:[KILL MKNOD SETGID SETUID SYS_CHROOT] DNS:[] DNSOptions:[] DNSSearch:[] ExtraHosts:[] GroupAdd:[] IpcMode: Cgroup: Links:[] OomScoreAdj:0 PidMode: Privileged:false PublishAllPorts:false ReadonlyRootfs:false SecurityOpt:[] StorageOpt:map[] Tmpfs:map[] UTSMode: UsernsMode: ShmSize:67108864 Sysctls:map[] ConsoleSize:[0 0] Isolation: Resources:{CPUShares:0 Memory:2147483648 CgroupParent:kubepods-burstable-poda5035c05_2298_11e8_a020_0050568b39b9.slice BlkioWeight:0 BlkioWeightDevice:[] BlkioDeviceReadBps:[] BlkioDeviceWriteBps:[] BlkioDeviceReadIOps:[] BlkioDeviceWriteIOps:[] CPUPeriod:0 CPUQuota:0 CpusetCpus: CpusetMems: Devices:[] DiskQuota:0 KernelMemory:0 MemoryReservation:0 MemorySwap:2147483648 M
emorySwappiness:<nil> OomKillDisable:<nil> PidsLimit:0 Ulimits:[] CPUCount:0 CPUPercent:0 IOMaximumIOps:0 IOMaximumBandwidth:0 NetworkMaximumBandwidth:0}}} ...
I0308 06:19:26.627249       1 docker.go:1007] Attaching to container "1b9f319d37271d70e47340208e2a142937700f232048761fb324629ce7585515" ...
I0308 06:19:26.629396       1 docker.go:1018] Starting container "1b9f319d37271d70e47340208e2a142937700f232048761fb324629ce7585515" ...
I0308 06:19:26.842435       1 tar.go:296] Adding to tar: /tmp/s2i-build856971515/upload/src as src
I0308 06:19:26.842603       1 tar.go:296] Adding to tar: /tmp/s2i-build856971515/upload/src/.git as src/.git

I0308 06:19:26.851401       1 tar.go:296] Adding to tar: /tmp/s2i-build856971515/upload/src/src/test/java/ofi/consul/discovery as src/src/test/java/ofi/consul/discovery
I0308 06:19:26.851497       1 tar.go:296] Adding to tar: /tmp/s2i-build856971515/upload/src/src/test/java/ofi/consul/discovery/consulfundservice as src/src/test/java/ofi/consul/discovery/consulfundservice
I0308 06:19:26.851609       1 tar.go:296] Adding to tar: /tmp/s2i-build856971515/upload/ src/test/java/ServiceApplicationTests.java
I0308 06:19:26.852546       1 sti.go:684] tar: /tmp: Cannot open: Permission denied
I0308 06:19:26.852580       1 sti.go:684] tar: Error is not recoverable: exiting now
I0308 06:19:26.932662       1 docker.go:1049] Waiting for container "1b9f319d37271d70e47340208e2a142937700f232048761fb324629ce7585515" to stop ...
I0308 06:19:26.948436       1 docker.go:985] Removing container "1b9f319d37271d70e47340208e2a142937700f232048761fb324629ce7585515" ...
I0308 06:19:26.963770       1 docker.go:995] Removed container "1b9f319d37271d70e47340208e2a142937700f232048761fb324629ce7585515"
I0308 06:19:26.964172       1 cleanup.go:31] Temporary directory "/tmp/s2i-build856971515" will be saved, not deleted
F0308 06:19:27.007414       1 helpers.go:119] error: build error: non-zero (13) exit code from registry.access.redhat.com/redhat-openjdk-18/openjdk18-openshift@sha256:5ffd5b1ec8e4264cdd62a3063ee56e370a973e0777da9c8c6f3a5f12e22fe6d5