docker push failed due to "Error pushing to registry: Authentication is required." if build(buildconfig) created first

[nak3]

NOTE: It might be expected behaivor, but please allow me to file the report.

Env

# openshift version
openshift v1.0.5-200-gc1c80c0
kubernetes v1.1.0-alpha.0-1605-g44c91b1

Issue

• Please see Reproduce steps below.

_(Removed reprodce steps, because I wrote wrong steps. I updated below)_

[nak3]

OK, it is NOT related to deploymentConfig and "second time". I found the correct order.

Reproduce steps (updated):

• step-1. Extract buildconfig and imagestream

# oc new-app https://github.com/nak3/helloworld-v3.git -o json > helloworld-v3.json
# cat helloworld-v3.json | jq .items[0] > imageStream.json
# cat helloworld-v3.json | jq .items[1] > buildConfig.json

• step-2 cretae build(buildconfig) before imagestream.

# oc create -f buildConfig.json
# oc create -f imageStream.json

• step-3. Get the auth error.

# oc build-logs helloworld-v3-1
...
I0903 09:42:29.887911       1 cfg.go:44] Locating docker auth for image 172.30.123.155:5000/default/helloworld-v3:latest and type PUSH_DOCKERCFG_PATH
I0903 09:42:29.888014       1 cfg.go:52] Problem accessing /root/.docker/config.json: stat /root/.docker/config.json: no such file or directory
I0903 09:42:29.888057       1 sti.go:151] Pushing 172.30.123.155:5000/default/helloworld-v3:latest image ...
F0903 09:42:31.505566       1 builder.go:47] Build error: Failed to push image: Error pushing to registry: Authentication is required.

[nak3]

This will cause timing issue. For example, if you wrote BuildConifg ealier than ImageStream in the resource list like:

    "items": [
        {
            "kind": "BuildConfig",
            "apiVersion": "v1",
     ....
        {
            "kind": "ImageStream",
            "apiVersion": "v1",

I wrote the example json, and it 100% caused Auth error with this command.

oc create -f https://gist.githubusercontent.com/nak3/2cbdc3fe9ce6ffce8fe5/raw/56234e102fe6c142b70e4b5bb022b9b15bccd857/auth-error.json

[sosiouxme]

I get the same thing every time with origin master and:

oc new-app 'https://github.com/sosiouxme/example-header-server.git#d78af60c2ec4dcfa860b1007c89e41d6fdd75eea'

Repeating the build or re-creating the BC doesn't seem to make any difference.

[sosiouxme]

openshift ex diagnostics reveals errors in the registry logs:

time="2015-09-05T19:53:39Z" level=debug msg="authorizing request" http.request.host="172.30.90.128:5000" http.request.id=d4d7d357-d58c-4267-b451-edc7a6c8a639 http.request.method=POST http.request.remoteaddr="10.1.1.1:59360" http.request.uri="/v2/default/example-header-server/blobs/uploads/" http.request.useragent="docker/1.7.1 go/go1.4.2 kernel/3.10.0-229.11.1.el7.x86_64 os/linux arch/amd64" instance.id=091fdad7-7f84-4977-a397-e0607b27a6aa vars.name="default/example-header-server" 
time="2015-09-05T19:53:39Z" level=debug msg="Origin auth: checking for access to repository:default/example-header-server:pull" 
time="2015-09-05T19:53:39Z" level=error msg="OpenShift client error: User \"system:serviceaccount:default:builder\" cannot create localsubjectaccessreviews in project \"default\"" 
time="2015-09-05T19:53:39Z" level=error msg="error authorizing context: access denied" http.request.host="172.30.90.128:5000" http.request.id=d4d7d357-d58c-4267-b451-edc7a6c8a639 http.request.method=POST http.request.remoteaddr="10.1.1.1:59360" http.request.uri="/v2/default/example-header-server/blobs/uploads/" http.request.useragent="docker/1.7.1 go/go1.4.2 kernel/3.10.0-229.11.1.el7.x86_64 os/linux arch/amd64" instance.id=091fdad7-7f84-4977-a397-e0607b27a6aa vars.name="default/example-header-server" 
10.1.1.1 - - [05/Sep/2015:19:53:39 +0000] "POST /v2/default/example-header-server/blobs/uploads/ HTTP/1.1" 401 265 "" "docker/1.7.1 go/go1.4.2 kernel/3.10.0-229.11.1.el7.x86_64 os/linux arch/amd64"
time="2015-09-05T19:53:39Z" level=info msg="response completed" http.request.host="172.30.90.128:5000" http.request.id=d4d7d357-d58c-4267-b451-edc7a6c8a639 http.request.method=POST http.request.remoteaddr="10.1.1.1:59360" http.request.uri="/v2/default/example-header-server/blobs/uploads/" http.request.useragent="docker/1.7.1 go/go1.4.2 kernel/3.10.0-229.11.1.el7.x86_64 os/linux arch/amd64" http.response.contenttype="application/json; charset=utf-8" http.response.duration=15.874426ms http.response.written=0 instance.id=091fdad7-7f84-4977-a397-e0607b27a6aa 

"system:serviceaccount:default:builder" cannot create localsubjectaccessreviews in project "default" seems to be the central problem. Not sure if this is the same problem you're reporting or something else.

[liggitt]

Does this happen if you create a new project, or just in the default project?

[nak3]

I tested default project, but if I created a new project, I got the error. (However if I tested with F21 with latest origin source, the message was a little changed, although still authentication error.)

I0906 04:55:45.638278       1 cfg.go:52] Problem accessing /root/.docker/config.json: stat /root/.docker/config.json: no such file or directory
I0906 04:55:45.638307       1 sti.go:151] Pushing 172.30.233.38:5000/demoproject/helloworld-v3:latest image ...
F0906 04:55:45.681072       1 builder.go:47] Build error: Failed to push image: Post http://172.30.233.38:5000/v2/demoproject/helloworld-v3/blobs/uploads/: no basic auth credentials

[nak3]

If I used openshift ex diagsnotics, I got this message.

$ openshift ex diagnostics
[Note] Determining if client configuration exists for client/cluster diagnostics
Info:  Successfully read a client config file at '/home/knakayam/.kube/config'
[Note] Summary of diagnostics execution (version v1.0.5-264-g11321c4):
[Note] Errors seen: 1
While building the diagnostics, a panic was encountered.
This is a bug in diagnostics. Stack trace follows : 
runtime error: invalid memory address or nil pointer dereference

[nak3]

Different error message has bee appeared from newest sour code or docker 1.8.

I0907 17:14:15.979723       1 cfg.go:52] Problem accessing /root/.docker/config.json: stat /root/.docker/config.json: no such file or directory
I0907 17:14:15.979736       1 sti.go:151] Pushing 172.30.187.40:5000/demoproject/helloworld-v3:latest image ...
F0907 17:14:16.021194       1 builder.go:47] Build error: Failed to push image: Post http://172.30.187.40:5000/v2/demoproject/helloworld-v3/blobs/uploads/: no basic auth credentials

Following creation order (BuildConfig->ImageStream) causes above error.

oc create -f https://gist.githubusercontent.com/nak3/887503f9376ee2528d6a/raw/7f018a0a400dfbdb8a3014c66d07a7890453df63/bc.json

oc create -f https://gist.githubusercontent.com/nak3/64498d3e992d0c1492eb/raw/826acc37c68e1ffc6bcd27cbe6edee3e47a80054/is.json

[deads2k]

@bparees I remember similar errors happening when the build is started before an image stream has a IP for pushing. It happened because there was no way to auto-detect which dockercfg secrets might be valid and so none were chosen. The choice of secret was made (or not made) even though the information was present to know that there wasn't enough information to choose, but it was never re-checked.

Is this the same error with a different manifestation?

[bparees]

it could be. loglevel 5 build logs would give us more info about what, if any, push secret is being used by the build.

[nak3]

I couldn't find any clue after setting Loglevel 5.- https://paste.fedoraproject.org/265517/

After fixed openshift ex diagnostics, the outputs says "error authorizing context: authorization header with basic token required".

       time="2015-09-10T01:47:44Z" level=error msg="error authorizing context: authorization header with basic token required" http.request.host="172.30.102.58:5000" http.request.id=68318684-ce54-412f-8ed0-78464616ed79 http.request.method=GET http.request.remoteaddr="172.17.42.1:60110" http.request.uri="/v2/" http.request.useragent="docker/1.8.1.fc21 go/go1.4.2 kernel/4.1.5-100.fc21.x86_64 os/linux arch/amd64" instance.id=3c555917-9a63-4ad1-9304-746234f05cd8
       time="2015-09-10T01:51:45Z" level=error msg="error authorizing context: authorization header with basic token required" http.request.host="172.30.102.58:5000" http.request.id=8af0b0f6-a408-49b4-8700-cf36d875afa1 http.request.method=GET http.request.remoteaddr="172.17.42.1:60514" http.request.uri="/v2/" http.request.useragent="docker/1.8.1.fc21 go/go1.4.2 kernel/4.1.5-100.fc21.x86_64 os/linux arch/amd64" instance.id=3c555917-9a63-4ad1-9304-746234f05cd8

entire messages - https://paste.fedoraproject.org/265485/

[liggitt]

Can you include the JSON build definition and secrets from the namespace? (oc get builds,secrets -o json) Trying to figure out why the auth to the registry isn't getting propagated

[nak3]

Sure here is the output of oc get builds,secrets -n demoproject -o json https://paste.fedoraproject.org/265528/

[liggitt]

thanks, can you also include the JSON definitions of the pod created to run the build?

[deads2k]

The build's output stanza does not include a pushSecret value. If you do oc start-build to get a new build, does it have the pushSecret populated?

[nak3]

thanks, can you also include the JSON definitions of the pod created to run the build?

OK, here it is. https://paste.fedoraproject.org/265912/

The build's output stanza does not include a pushSecret value. If you do oc start-build to get a new build, does it have the pushSecret populated?

Yes, oc start-build worked(build was completed) and it has the pushSecret https://paste.fedoraproject.org/265920/

[nak3]

thanks, can you also include the JSON definitions of the pod created to run the build?

OK, here it is. https://paste.fedoraproject.org/265912/

Sorry my mistake. Here is the json definitions of the pod created to run the build (builder container pod)
https://paste.fedoraproject.org/265923/

[bparees]

no push secret populated. and "172.30.50.7:5000/demoproject/helloworld-v3:latest" definitely matches the current docker registry ip?

seems like maybe the issue is that something is getting mismatched between the ip you have credentials for and the ip we're trying to push to, which means we don't find an appropriate secret to attach to the pod.

is this consistently recreatable?

[nak3]

no push secret populated. and "172.30.50.7:5000/demoproject/helloworld-v3:latest" definitely matches the current docker registry ip?

Yes, it is match the current docker registry ip.

is this consistently recreatable?

Yes, it is recreatable. Following commnad will reproduce it. (Need to create bc.json first)

oc create -f https://gist.githubusercontent.com/nak3/887503f9376ee2528d6a/raw/7f018a0a400dfbdb8a3014c66d07a7890453df63/bc.json
oc create -f https://gist.githubusercontent.com/nak3/64498d3e992d0c1492eb/raw/826acc37c68e1ffc6bcd27cbe6edee3e47a80054/is.json

When I failed to build with this error, following messages output to server log. After failed to create secret with resolveImageSecret in pkg/build/generator/generator.go, it seems that it wouldn't try to create the secret again.

Failed log (bc -> is)

I0915 14:25:40.153218    2897 generator.go:404] Resolving ImageStreamReference php:latest of Kind ImageStreamTag in namespace openshift
I0915 14:25:40.155065    2897 generator.go:428] Resolved ImageStreamTag php:latest to image sha256:ea8cf49363284860de3b5650e713bfe10a8ad03d460151a4bf2025b6418d43b4 with reference openshift/php-55-centos7@sha256:ea8cf49363284860de3b5650e713bfe10a8ad03d460151a4bf2025b6418d43b4 in namespace openshift
I0915 14:25:40.159789    2897 generator.go:445] Resolving ImageStreamReference helloworld-v3:latest of Kind ImageStreamTag in namespace demoproject
I0915 14:25:40.160018    2897 generator.go:463] Error getting ImageStream demoproject/helloworld-v3: imageStream "helloworld-v3" not found
I0915 14:25:40.160029    2897 generator.go:493] Unable to resolve the image name for demoproject/&{ImageStreamTag  helloworld-v3:latest    }: imageStream "helloworld-v3" not found
I0915 14:25:40.160044    2897 generator.go:445] Resolving ImageStreamReference openshift/php-55-centos7@sha256:ea8cf49363284860de3b5650e713bfe10a8ad03d460151a4bf2025b6418d43b4 of Kind DockerImage in namespace demoproject
I0915 14:25:40.160152    2897 generator.go:506] No secrets found for pushing or pulling the DockerImage  demoproject/openshift/php-55-centos7@sha256:ea8cf49363284860de3b5650e713bfe10a8ad03d460151a4bf2025b6418d43b4
...
I0915 14:25:46.326024    2897 controller.go:79] Handling Build demoproject/helloworld-v3-1
I0915 14:25:46.328657    2897 admission.go:91] getting security context constraints for pod helloworld-v3-1-build (generate: ) in namespace demoproject with user info &{system:serviceaccount:demoproject:builder  [system:serviceaccounts system:serviceaccounts:demoproject]}
I0915 14:25:46.328683    2897 admission.go:100] getting security context constraints for pod helloworld-v3-1-build (generate: ) with service account info &{system:serviceaccount:demoproject:builder  [system:serviceaccounts system:serviceaccounts:demoproject]}
I0915 14:25:46.328695    2897 admission.go:374] validating pod helloworld-v3-1-build (generate: ) against providers

Success log (is -> bc)

I0915 14:28:02.809786    2897 generator.go:404] Resolving ImageStreamReference php:latest of Kind ImageStreamTag in namespace openshift
I0915 14:28:02.811467    2897 generator.go:428] Resolved ImageStreamTag php:latest to image sha256:ea8cf49363284860de3b5650e713bfe10a8ad03d460151a4bf2025b6418d43b4 with reference openshift/php-55-centos7@sha256:ea8cf49363284860de3b5650e713bfe10a8ad03d460151a4bf2025b6418d43b4 in namespace openshift
I0915 14:28:02.817672    2897 generator.go:445] Resolving ImageStreamReference helloworld-v3:latest of Kind ImageStreamTag in namespace demoproject
I0915 14:28:02.818299    2897 generator.go:474] Resolved ImageStreamTag demoproject/helloworld-v3:latest to repository 172.30.237.193:5000/demoproject/helloworld-v3
I0915 14:28:02.818445    2897 generator.go:445] Resolving ImageStreamReference openshift/php-55-centos7@sha256:ea8cf49363284860de3b5650e713bfe10a8ad03d460151a4bf2025b6418d43b4 of Kind DockerImage in namespace demoproject
I0915 14:28:02.818570    2897 generator.go:506] No secrets found for pushing or pulling the DockerImage  demoproject/openshift/php-55-centos7@sha256:ea8cf49363284860de3b5650e713bfe10a8ad03d460151a4bf2025b6418d43b4
...
I0915 14:28:02.822225    2897 controller.go:79] Handling Build demoproject/helloworld-v3-1
I0915 14:28:02.822324    2897 config_controller.go:20] Handling BuildConfig demoproject/helloworld-v3
I0915 14:28:02.837651    2897 admission.go:91] getting security context constraints for pod helloworld-v3-1-build (generate: ) in namespace demoproject with user info &{system:serviceaccount:demoproject:builder  [system:serviceaccounts system:serviceaccounts:demoproject]}
I0915 14:28:02.837677    2897 admission.go:100] getting security context constraints for pod helloworld-v3-1-build (generate: ) with service account info &{system:serviceaccount:demoproject:builder  [system:serviceaccounts system:serviceaccounts:demoproject]}
I0915 14:28:02.837689    2897 admission.go:374] validating pod helloworld-v3-1-build (generate: ) against providers

[bparees]

ok here's what's happening.

during the generation of the build object, we try to resolve the output IST so we can decide what secret we need to use with it. the resolution fails so we don't setup any push secret, but that does not (and should not) fail the creation of the build object.

So a build object gets created.

Then the build controller sees it and tries to process the build object. part of processing the build object requires resolving the output IST (so we know where to push). Since we can't do this (no IST yet), the build hangs in a retry state until the IST gets created.

Finally the IST gets created and the build proceeds, but the push secret was never set up.

The right fix for this is to resolve the output push location at the time we create the build also, but i think there are some flow challenges with doing that. Another option would be to update the push secret when we resolve the reference in the build controller, instead of when creating the build in the buildconfig controller.

either way it's a real bug, you need to create your IST before launching the build if you don't want to hit it, but since that's fairly easily worked around i'm lowering it to a sev3.

[liggitt]

also, a second build would work, even if the first encounters this bug, right?

[bparees]

yes that's what i meant by "fairly easily worked around" but i guess I didn't complete the thought.

[nak3]

@bparees Yes, that's also the reason I thought it might be better written documentation of template section.
After developers create a new template, it will pass their tests (with second build) and be released. That could cause mysterious situation for all users who use the template after release.

[jorgemoralespou]

@bparees I think this should be bumped in priority, as one thing we are doing is:

• Create the project and deploy resources in "copy&paste" format in learning material
• Create the project and deploy resources in "CI" environments

[david-strejc]

I don't know if it will help but:

• my first build of my template passed in namespace1
• my second build of the same template failed in namespace2 (I was still logged in as same user)
• my third build inside namespace3 failed - both of them failed with:

Error: build error: Failed to push image. Response from registry is: Post http://172.30.106.181:5000/v2/smith/redmine/blobs/uploads/: no basic auth credentials

I am using same template for deployments.

Edit: I've tried fourth build and it passed - same template nothing modified.

[mfojtik]

@jorgemoralespou @david-strejc prio bumped.

[msirovy]

thanks form EASY!!!

[bparees]

this issue exists to resolve exactly one problem, the one described here:
#4518 (comment)

please open a separate issue if you are having push issues under another scenario.

[paralin]

The no basic auth creds problem is still happening for me, and starting a new build doesnt always fix it.

[debianmaster]

facing the same issue

E0808 18:46:41.896388       1 cfg.go:57] Reading /var/run/secrets/openshift.io/push failed: read /var/run/secrets/openshift.io/push: is a directory
I0808 18:46:41.896421       1 sti.go:215] No push secret provided
I0808 18:46:41.896426       1 sti.go:217] Pushing 172.30.79.164:5000/development/welcome:latest image ...
F0808 18:46:41.908998       1 builder.go:59] Build error: Failed to push image. Response from registry is: Post http://172.30.79.164:5000/v2/development/welcome/blobs/uploads/: no basic auth credentials

[bparees]

@debianmaster are all your builds failing or just the first one?

[debianmaster]

@bparees all build not just first one, iam not able to do any s2i

[bparees]

@debianmaster then you have a different issue, not this one. likely your project/service account is missing the tokens that should be autogenerated. please open a new issue and tag @liggitt and @deads2k.

[mjudeikis]

So how this one is going on? still bumpt?

[bparees]

@Mangirdaz it's still an issue and we still want to fix it, it's not a trivial issue to resolve due to needing to refactor significant chunks of code and given that there are easy workarounds (wait a few seconds after creating a project before you create a build, or rerun your failed build), it's not a high priority.

[bparees]

we're now tracking this in bugzilla, closing this issue.
https://bugzilla.redhat.com/show_bug.cgi?id=1443163