Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Set the default log level to info instead of debug #75

Closed
wants to merge 1 commit into from
Closed

Set the default log level to info instead of debug #75

wants to merge 1 commit into from

Conversation

coreydaley
Copy link
Member

@openshift-ci-robot openshift-ci-robot added the size/XS Denotes a PR that changes 0-9 lines, ignoring generated files. label Apr 16, 2018
@coreydaley
Copy link
Member Author

@openshift/sig-developer-experience ptal

@bparees
Copy link
Contributor

bparees commented Apr 16, 2018

before we do this i'd love to know if there's a middle ground alternative because we have to debug registry push failures a lot (often not because of an actual issue in the registry that we could fix, but rather permission issues) and the debug info is super helpful when that happens.

forcing people to redeploy their registry and recreate the failure so we can get logs is going to be painful.

/cc @dmage @legionus @smarterclayton

@openshift-docker
Copy link

openshift-docker commented Apr 16, 2018 via email

Copy link
Member

@dmage dmage left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I like the idea, but at first we need to fix how we log our errors. And unfortunately the upstream code needs to be fixed too. Otherwise we will not be able to explain the next "blob unknown to registry" error (did we tried to pull the blob from another registry? which one? and what about the local storage? etc.). The worst part: usually it's not the registry problem, but we still need to explain it.

Copy link
Contributor

@legionus legionus left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

All that is now in the log is necessary for investigations of various kinds of failures. Problems with the pullthrough, storage backend, authentication require the logging of different entities. In the current situation, all debug messages must be info, but all of them should remain in the log.

If there are problems with the disk space or expiration, then we should think about using the log server (syslog).

NAK

@bparees
Copy link
Contributor

bparees commented Apr 16, 2018

All that is now in the log is necessary for investigations of various kinds of failures.

I'm guessing we don't have this level of control due to the docker distribution code, but it seems like a better solution would buffer the log messages and then only log the output if the overall request failed. Is such a thing possible for us here?

@smarterclayton
Copy link
Contributor

We have a general log level policy, we do not ship components to customers that log at debug level excessively. Just because code has bugs doesn't mean that customer environments can tolerate logging everything in the world just on the off chance you catch a bug. Your error paths should certainly be logged by default. Important rejections or situational info can certainly be logged.

But logging everything just because it's convenient for you causes problems for operators.

@smarterclayton
Copy link
Contributor

Pulling some examples out so we can have more concrete discussion:

One patch call:

time="2018-04-29T04:48:07.597026622Z" level=debug msg="authorizing request" go.version=go1.9.2 http.request.host="docker-registry.default.svc:5000" http.request.id=1cca32b2-5198-4aad-aefb-51842d8701cf http.request.method=PATCH http.request.remoteaddr="10.128.0.1:38984" http.request.uri="/v2/e2e-test-prometheus-nfl7f/origin-nodejs-sample/blobs/uploads/37660d7e-c059-4274-97a3-63c0e60d351d?_state=iTCdR69SU3khiuOmBm8Cy-chLaqX6LfKqtEfcVtnAk97Ik5hbWUiOiJlMmUtdGVzdC1wcm9tZXRoZXVzLW5mbDdmL29yaWdpbi1ub2RlanMtc2FtcGxlIiwiVVVJRCI6IjM3NjYwZDdlLWMwNTktNDI3NC05N2EzLTYzYzBlNjBkMzUxZCIsIk9mZnNldCI6MCwiU3RhcnRlZEF0IjoiMjAxOC0wNC0yOVQwNDo0ODowNy41NzAyODk1MzlaIn0%3D" http.request.useragent="docker/1.13.1 go/go1.9.2 kernel/3.10.0-862.el7.x86_64 os/linux arch/amd64 UpstreamClient(go-dockerclient)" instance.id=ddca745a-9226-4b65-8a74-c4f703d49019 vars.name=e2e-test-prometheus-nfl7f/origin-nodejs-sample vars.uuid=37660d7e-c059-4274-97a3-63c0e60d351d
time="2018-04-29T04:48:07.60313847Z" level=debug msg="Origin auth: checking for access to repository:e2e-test-prometheus-nfl7f/origin-nodejs-sample:pull" go.version=go1.9.2 http.request.host="docker-registry.default.svc:5000" http.request.id=1cca32b2-5198-4aad-aefb-51842d8701cf http.request.method=PATCH http.request.remoteaddr="10.128.0.1:38984" http.request.uri="/v2/e2e-test-prometheus-nfl7f/origin-nodejs-sample/blobs/uploads/37660d7e-c059-4274-97a3-63c0e60d351d?_state=iTCdR69SU3khiuOmBm8Cy-chLaqX6LfKqtEfcVtnAk97Ik5hbWUiOiJlMmUtdGVzdC1wcm9tZXRoZXVzLW5mbDdmL29yaWdpbi1ub2RlanMtc2FtcGxlIiwiVVVJRCI6IjM3NjYwZDdlLWMwNTktNDI3NC05N2EzLTYzYzBlNjBkMzUxZCIsIk9mZnNldCI6MCwiU3RhcnRlZEF0IjoiMjAxOC0wNC0yOVQwNDo0ODowNy41NzAyODk1MzlaIn0%3D" http.request.useragent="docker/1.13.1 go/go1.9.2 kernel/3.10.0-862.el7.x86_64 os/linux arch/amd64 UpstreamClient(go-dockerclient)" instance.id=ddca745a-9226-4b65-8a74-c4f703d49019 openshift.auth.user="system:serviceaccount:e2e-test-prometheus-nfl7f:builder" openshift.auth.userid=552a0e64-4b68-11e8-8474-0e0e85ffbd0a vars.name=e2e-test-prometheus-nfl7f/origin-nodejs-sample vars.uuid=37660d7e-c059-4274-97a3-63c0e60d351d
time="2018-04-29T04:48:07.611276793Z" level=debug msg="Origin auth: checking for access to repository:e2e-test-prometheus-nfl7f/origin-nodejs-sample:push" go.version=go1.9.2 http.request.host="docker-registry.default.svc:5000" http.request.id=1cca32b2-5198-4aad-aefb-51842d8701cf http.request.method=PATCH http.request.remoteaddr="10.128.0.1:38984" http.request.uri="/v2/e2e-test-prometheus-nfl7f/origin-nodejs-sample/blobs/uploads/37660d7e-c059-4274-97a3-63c0e60d351d?_state=iTCdR69SU3khiuOmBm8Cy-chLaqX6LfKqtEfcVtnAk97Ik5hbWUiOiJlMmUtdGVzdC1wcm9tZXRoZXVzLW5mbDdmL29yaWdpbi1ub2RlanMtc2FtcGxlIiwiVVVJRCI6IjM3NjYwZDdlLWMwNTktNDI3NC05N2EzLTYzYzBlNjBkMzUxZCIsIk9mZnNldCI6MCwiU3RhcnRlZEF0IjoiMjAxOC0wNC0yOVQwNDo0ODowNy41NzAyODk1MzlaIn0%3D" http.request.useragent="docker/1.13.1 go/go1.9.2 kernel/3.10.0-862.el7.x86_64 os/linux arch/amd64 UpstreamClient(go-dockerclient)" instance.id=ddca745a-9226-4b65-8a74-c4f703d49019 openshift.auth.user="system:serviceaccount:e2e-test-prometheus-nfl7f:builder" openshift.auth.userid=552a0e64-4b68-11e8-8474-0e0e85ffbd0a vars.name=e2e-test-prometheus-nfl7f/origin-nodejs-sample vars.uuid=37660d7e-c059-4274-97a3-63c0e60d351d
time="2018-04-29T04:48:07.615496482Z" level=debug msg="(*linkedBlobStore).Resume" go.version=go1.9.2 http.request.host="docker-registry.default.svc:5000" http.request.id=1cca32b2-5198-4aad-aefb-51842d8701cf http.request.method=PATCH http.request.remoteaddr="10.128.0.1:38984" http.request.uri="/v2/e2e-test-prometheus-nfl7f/origin-nodejs-sample/blobs/uploads/37660d7e-c059-4274-97a3-63c0e60d351d?_state=iTCdR69SU3khiuOmBm8Cy-chLaqX6LfKqtEfcVtnAk97Ik5hbWUiOiJlMmUtdGVzdC1wcm9tZXRoZXVzLW5mbDdmL29yaWdpbi1ub2RlanMtc2FtcGxlIiwiVVVJRCI6IjM3NjYwZDdlLWMwNTktNDI3NC05N2EzLTYzYzBlNjBkMzUxZCIsIk9mZnNldCI6MCwiU3RhcnRlZEF0IjoiMjAxOC0wNC0yOVQwNDo0ODowNy41NzAyODk1MzlaIn0%3D" http.request.useragent="docker/1.13.1 go/go1.9.2 kernel/3.10.0-862.el7.x86_64 os/linux arch/amd64 UpstreamClient(go-dockerclient)" instance.id=ddca745a-9226-4b65-8a74-c4f703d49019 openshift.auth.user="system:serviceaccount:e2e-test-prometheus-nfl7f:builder" openshift.auth.userid=552a0e64-4b68-11e8-8474-0e0e85ffbd0a vars.name=e2e-test-prometheus-nfl7f/origin-nodejs-sample vars.uuid=37660d7e-c059-4274-97a3-63c0e60d351d
time="2018-04-29T04:48:07.615628749Z" level=debug msg="filesystem.GetContent(\"/docker/registry/v2/repositories/e2e-test-prometheus-nfl7f/origin-nodejs-sample/_uploads/37660d7e-c059-4274-97a3-63c0e60d351d/startedat\")" go.version=go1.9.2 http.request.host="docker-registry.default.svc:5000" http.request.id=1cca32b2-5198-4aad-aefb-51842d8701cf http.request.method=PATCH http.request.remoteaddr="10.128.0.1:38984" http.request.uri="/v2/e2e-test-prometheus-nfl7f/origin-nodejs-sample/blobs/uploads/37660d7e-c059-4274-97a3-63c0e60d351d?_state=iTCdR69SU3khiuOmBm8Cy-chLaqX6LfKqtEfcVtnAk97Ik5hbWUiOiJlMmUtdGVzdC1wcm9tZXRoZXVzLW5mbDdmL29yaWdpbi1ub2RlanMtc2FtcGxlIiwiVVVJRCI6IjM3NjYwZDdlLWMwNTktNDI3NC05N2EzLTYzYzBlNjBkMzUxZCIsIk9mZnNldCI6MCwiU3RhcnRlZEF0IjoiMjAxOC0wNC0yOVQwNDo0ODowNy41NzAyODk1MzlaIn0%3D" http.request.useragent="docker/1.13.1 go/go1.9.2 kernel/3.10.0-862.el7.x86_64 os/linux arch/amd64 UpstreamClient(go-dockerclient)" instance.id=ddca745a-9226-4b65-8a74-c4f703d49019 openshift.auth.user="system:serviceaccount:e2e-test-prometheus-nfl7f:builder" openshift.auth.userid=552a0e64-4b68-11e8-8474-0e0e85ffbd0a trace.duration="62.438µs" trace.file=/tmp/openshift/build-rpms/rpm/BUILD/origin-dockerregistry-3.10.0/_output/local/go/src/github.com/openshift/image-registry/vendor/github.com/docker/distribution/registry/storage/driver/base/base.go trace.func="github.com/openshift/image-registry/vendor/github.com/docker/distribution/registry/storage/driver/base.(*Base).GetContent" trace.id=2cb7c4b2-06d9-4523-af17-39ad8ff6c24e trace.line=82 vars.name=e2e-test-prometheus-nfl7f/origin-nodejs-sample vars.uuid=37660d7e-c059-4274-97a3-63c0e60d351d
time="2018-04-29T04:48:07.615758334Z" level=debug msg="filesystem.Writer(\"/docker/registry/v2/repositories/e2e-test-prometheus-nfl7f/origin-nodejs-sample/_uploads/37660d7e-c059-4274-97a3-63c0e60d351d/data\", true)" go.version=go1.9.2 http.request.host="docker-registry.default.svc:5000" http.request.id=1cca32b2-5198-4aad-aefb-51842d8701cf http.request.method=PATCH http.request.remoteaddr="10.128.0.1:38984" http.request.uri="/v2/e2e-test-prometheus-nfl7f/origin-nodejs-sample/blobs/uploads/37660d7e-c059-4274-97a3-63c0e60d351d?_state=iTCdR69SU3khiuOmBm8Cy-chLaqX6LfKqtEfcVtnAk97Ik5hbWUiOiJlMmUtdGVzdC1wcm9tZXRoZXVzLW5mbDdmL29yaWdpbi1ub2RlanMtc2FtcGxlIiwiVVVJRCI6IjM3NjYwZDdlLWMwNTktNDI3NC05N2EzLTYzYzBlNjBkMzUxZCIsIk9mZnNldCI6MCwiU3RhcnRlZEF0IjoiMjAxOC0wNC0yOVQwNDo0ODowNy41NzAyODk1MzlaIn0%3D" http.request.useragent="docker/1.13.1 go/go1.9.2 kernel/3.10.0-862.el7.x86_64 os/linux arch/amd64 UpstreamClient(go-dockerclient)" instance.id=ddca745a-9226-4b65-8a74-c4f703d49019 openshift.auth.user="system:serviceaccount:e2e-test-prometheus-nfl7f:builder" openshift.auth.userid=552a0e64-4b68-11e8-8474-0e0e85ffbd0a trace.duration="48.137µs" trace.file=/tmp/openshift/build-rpms/rpm/BUILD/origin-dockerregistry-3.10.0/_output/local/go/src/github.com/openshift/image-registry/vendor/github.com/docker/distribution/registry/storage/driver/base/base.go trace.func="github.com/openshift/image-registry/vendor/github.com/docker/distribution/registry/storage/driver/base.(*Base).Writer" trace.id=fb31b6e7-a523-43e3-928c-6669ca659aef trace.line=124 vars.name=e2e-test-prometheus-nfl7f/origin-nodejs-sample vars.uuid=37660d7e-c059-4274-97a3-63c0e60d351d
time="2018-04-29T04:48:08.662104538Z" level=debug msg="filesystem.PutContent(\"/docker/registry/v2/repositories/e2e-test-prometheus-nfl7f/origin-nodejs-sample/_uploads/37660d7e-c059-4274-97a3-63c0e60d351d/hashstates/sha256/1889774\")" go.version=go1.9.2 http.request.host="docker-registry.default.svc:5000" http.request.id=1cca32b2-5198-4aad-aefb-51842d8701cf http.request.method=PATCH http.request.remoteaddr="10.128.0.1:38984" http.request.uri="/v2/e2e-test-prometheus-nfl7f/origin-nodejs-sample/blobs/uploads/37660d7e-c059-4274-97a3-63c0e60d351d?_state=iTCdR69SU3khiuOmBm8Cy-chLaqX6LfKqtEfcVtnAk97Ik5hbWUiOiJlMmUtdGVzdC1wcm9tZXRoZXVzLW5mbDdmL29yaWdpbi1ub2RlanMtc2FtcGxlIiwiVVVJRCI6IjM3NjYwZDdlLWMwNTktNDI3NC05N2EzLTYzYzBlNjBkMzUxZCIsIk9mZnNldCI6MCwiU3RhcnRlZEF0IjoiMjAxOC0wNC0yOVQwNDo0ODowNy41NzAyODk1MzlaIn0%3D" http.request.useragent="docker/1.13.1 go/go1.9.2 kernel/3.10.0-862.el7.x86_64 os/linux arch/amd64 UpstreamClient(go-dockerclient)" instance.id=ddca745a-9226-4b65-8a74-c4f703d49019 openshift.auth.user="system:serviceaccount:e2e-test-prometheus-nfl7f:builder" openshift.auth.userid=552a0e64-4b68-11e8-8474-0e0e85ffbd0a trace.duration=2.232426ms trace.file=/tmp/openshift/build-rpms/rpm/BUILD/origin-dockerregistry-3.10.0/_output/local/go/src/github.com/openshift/image-registry/vendor/github.com/docker/distribution/registry/storage/driver/base/base.go trace.func="github.com/openshift/image-registry/vendor/github.com/docker/distribution/registry/storage/driver/base.(*Base).PutContent" trace.id=5d38c900-3377-4b2d-a77b-c2d2b3b63319 trace.line=95 vars.name=e2e-test-prometheus-nfl7f/origin-nodejs-sample vars.uuid=37660d7e-c059-4274-97a3-63c0e60d351d
time="2018-04-29T04:48:08.797908028Z" level=debug msg="filesystem.PutContent(\"/docker/registry/v2/repositories/e2e-test-prometheus-nfl7f/origin-nodejs-sample/_uploads/37660d7e-c059-4274-97a3-63c0e60d351d/hashstates/sha256/1889774\")" go.version=go1.9.2 http.request.host="docker-registry.default.svc:5000" http.request.id=1cca32b2-5198-4aad-aefb-51842d8701cf http.request.method=PATCH http.request.remoteaddr="10.128.0.1:38984" http.request.uri="/v2/e2e-test-prometheus-nfl7f/origin-nodejs-sample/blobs/uploads/37660d7e-c059-4274-97a3-63c0e60d351d?_state=iTCdR69SU3khiuOmBm8Cy-chLaqX6LfKqtEfcVtnAk97Ik5hbWUiOiJlMmUtdGVzdC1wcm9tZXRoZXVzLW5mbDdmL29yaWdpbi1ub2RlanMtc2FtcGxlIiwiVVVJRCI6IjM3NjYwZDdlLWMwNTktNDI3NC05N2EzLTYzYzBlNjBkMzUxZCIsIk9mZnNldCI6MCwiU3RhcnRlZEF0IjoiMjAxOC0wNC0yOVQwNDo0ODowNy41NzAyODk1MzlaIn0%3D" http.request.useragent="docker/1.13.1 go/go1.9.2 kernel/3.10.0-862.el7.x86_64 os/linux arch/amd64 UpstreamClient(go-dockerclient)" instance.id=ddca745a-9226-4b65-8a74-c4f703d49019 openshift.auth.user="system:serviceaccount:e2e-test-prometheus-nfl7f:builder" openshift.auth.userid=552a0e64-4b68-11e8-8474-0e0e85ffbd0a trace.duration=1.929814ms trace.file=/tmp/openshift/build-rpms/rpm/BUILD/origin-dockerregistry-3.10.0/_output/local/go/src/github.com/openshift/image-registry/vendor/github.com/docker/distribution/registry/storage/driver/base/base.go trace.func="github.com/openshift/image-registry/vendor/github.com/docker/distribution/registry/storage/driver/base.(*Base).PutContent" trace.id=b27f5059-b550-4875-b951-7cc6aebe95f8 trace.line=95 vars.name=e2e-test-prometheus-nfl7f/origin-nodejs-sample vars.uuid=37660d7e-c059-4274-97a3-63c0e60d351d
time="2018-04-29T04:48:08.797990811Z" level=info msg="response completed" go.version=go1.9.2 http.request.host="docker-registry.default.svc:5000" http.request.id=1cca32b2-5198-4aad-aefb-51842d8701cf http.request.method=PATCH http.request.remoteaddr="10.128.0.1:38984" http.request.uri="/v2/e2e-test-prometheus-nfl7f/origin-nodejs-sample/blobs/uploads/37660d7e-c059-4274-97a3-63c0e60d351d?_state=iTCdR69SU3khiuOmBm8Cy-chLaqX6LfKqtEfcVtnAk97Ik5hbWUiOiJlMmUtdGVzdC1wcm9tZXRoZXVzLW5mbDdmL29yaWdpbi1ub2RlanMtc2FtcGxlIiwiVVVJRCI6IjM3NjYwZDdlLWMwNTktNDI3NC05N2EzLTYzYzBlNjBkMzUxZCIsIk9mZnNldCI6MCwiU3RhcnRlZEF0IjoiMjAxOC0wNC0yOVQwNDo0ODowNy41NzAyODk1MzlaIn0%3D" http.request.useragent="docker/1.13.1 go/go1.9.2 kernel/3.10.0-862.el7.x86_64 os/linux arch/amd64 UpstreamClient(go-dockerclient)" http.response.duration=1.202845632s http.response.status=202 http.response.written=0 instance.id=ddca745a-9226-4b65-8a74-c4f703d49019

Filesystem ones seem definitely not useful for the vast majority of debugging unless we have a fundamental error. The origin one might be useful, but only if it captured the result (which it doesn't look like it does?). Authorizing request doesn't seem useful for debugging.

Head request:

time="2018-04-29T04:48:07.853869505Z" level=debug msg="authorizing request" go.version=go1.9.2 http.request.host="docker-registry.default.svc:5000" http.request.id=b8687702-44cd-4e4b-bc8c-debb20f2028d http.request.method=HEAD http.request.remoteaddr="10.128.0.1:39016" http.request.uri="/v2/e2e-test-prometheus-nfl7f/origin-nodejs-sample/blobs/sha256:7cc928e84921433ebeca4314a11912f541b1d4ec82048bd904eab44399d96a65" http.request.useragent="docker/1.13.1 go/go1.9.2 kernel/3.10.0-862.el7.x86_64 os/linux arch/amd64 UpstreamClient(go-dockerclient)" instance.id=ddca745a-9226-4b65-8a74-c4f703d49019 vars.digest="sha256:7cc928e84921433ebeca4314a11912f541b1d4ec82048bd904eab44399d96a65" vars.name=e2e-test-prometheus-nfl7f/origin-nodejs-sample
time="2018-04-29T04:48:07.85874142Z" level=debug msg="Origin auth: checking for access to repository:e2e-test-prometheus-nfl7f/origin-nodejs-sample:pull" go.version=go1.9.2 http.request.host="docker-registry.default.svc:5000" http.request.id=b8687702-44cd-4e4b-bc8c-debb20f2028d http.request.method=HEAD http.request.remoteaddr="10.128.0.1:39016" http.request.uri="/v2/e2e-test-prometheus-nfl7f/origin-nodejs-sample/blobs/sha256:7cc928e84921433ebeca4314a11912f541b1d4ec82048bd904eab44399d96a65" http.request.useragent="docker/1.13.1 go/go1.9.2 kernel/3.10.0-862.el7.x86_64 os/linux arch/amd64 UpstreamClient(go-dockerclient)" instance.id=ddca745a-9226-4b65-8a74-c4f703d49019 openshift.auth.user="system:serviceaccount:e2e-test-prometheus-nfl7f:builder" openshift.auth.userid=552a0e64-4b68-11e8-8474-0e0e85ffbd0a vars.digest="sha256:7cc928e84921433ebeca4314a11912f541b1d4ec82048bd904eab44399d96a65" vars.name=e2e-test-prometheus-nfl7f/origin-nodejs-sample
time="2018-04-29T04:48:07.860878913Z" level=debug msg=GetBlob go.version=go1.9.2 http.request.host="docker-registry.default.svc:5000" http.request.id=b8687702-44cd-4e4b-bc8c-debb20f2028d http.request.method=HEAD http.request.remoteaddr="10.128.0.1:39016" http.request.uri="/v2/e2e-test-prometheus-nfl7f/origin-nodejs-sample/blobs/sha256:7cc928e84921433ebeca4314a11912f541b1d4ec82048bd904eab44399d96a65" http.request.useragent="docker/1.13.1 go/go1.9.2 kernel/3.10.0-862.el7.x86_64 os/linux arch/amd64 UpstreamClient(go-dockerclient)" instance.id=ddca745a-9226-4b65-8a74-c4f703d49019 openshift.auth.user="system:serviceaccount:e2e-test-prometheus-nfl7f:builder" openshift.auth.userid=552a0e64-4b68-11e8-8474-0e0e85ffbd0a vars.digest="sha256:7cc928e84921433ebeca4314a11912f541b1d4ec82048bd904eab44399d96a65" vars.name=e2e-test-prometheus-nfl7f/origin-nodejs-sample
time="2018-04-29T04:48:07.860921179Z" level=debug msg="(*pullthroughBlobStore).Stat: starting with dgst=sha256:7cc928e84921433ebeca4314a11912f541b1d4ec82048bd904eab44399d96a65" go.version=go1.9.2 http.request.host="docker-registry.default.svc:5000" http.request.id=b8687702-44cd-4e4b-bc8c-debb20f2028d http.request.method=HEAD http.request.remoteaddr="10.128.0.1:39016" http.request.uri="/v2/e2e-test-prometheus-nfl7f/origin-nodejs-sample/blobs/sha256:7cc928e84921433ebeca4314a11912f541b1d4ec82048bd904eab44399d96a65" http.request.useragent="docker/1.13.1 go/go1.9.2 kernel/3.10.0-862.el7.x86_64 os/linux arch/amd64 UpstreamClient(go-dockerclient)" instance.id=ddca745a-9226-4b65-8a74-c4f703d49019 openshift.auth.user="system:serviceaccount:e2e-test-prometheus-nfl7f:builder" openshift.auth.userid=552a0e64-4b68-11e8-8474-0e0e85ffbd0a vars.digest="sha256:7cc928e84921433ebeca4314a11912f541b1d4ec82048bd904eab44399d96a65" vars.name=e2e-test-prometheus-nfl7f/origin-nodejs-sample
time="2018-04-29T04:48:07.860968489Z" level=debug msg="(*blobDescriptorService).Stat: starting with digest=sha256:7cc928e84921433ebeca4314a11912f541b1d4ec82048bd904eab44399d96a65" go.version=go1.9.2 http.request.host="docker-registry.default.svc:5000" http.request.id=b8687702-44cd-4e4b-bc8c-debb20f2028d http.request.method=HEAD http.request.remoteaddr="10.128.0.1:39016" http.request.uri="/v2/e2e-test-prometheus-nfl7f/origin-nodejs-sample/blobs/sha256:7cc928e84921433ebeca4314a11912f541b1d4ec82048bd904eab44399d96a65" http.request.useragent="docker/1.13.1 go/go1.9.2 kernel/3.10.0-862.el7.x86_64 os/linux arch/amd64 UpstreamClient(go-dockerclient)" instance.id=ddca745a-9226-4b65-8a74-c4f703d49019 openshift.auth.user="system:serviceaccount:e2e-test-prometheus-nfl7f:builder" openshift.auth.userid=552a0e64-4b68-11e8-8474-0e0e85ffbd0a vars.digest="sha256:7cc928e84921433ebeca4314a11912f541b1d4ec82048bd904eab44399d96a65" vars.name=e2e-test-prometheus-nfl7f/origin-nodejs-sample
time="2018-04-29T04:48:07.861019547Z" level=debug msg="(*pullthroughBlobStore).ServeBlob: starting with dgst=sha256:7cc928e84921433ebeca4314a11912f541b1d4ec82048bd904eab44399d96a65" go.version=go1.9.2 http.request.host="docker-registry.default.svc:5000" http.request.id=b8687702-44cd-4e4b-bc8c-debb20f2028d http.request.method=HEAD http.request.remoteaddr="10.128.0.1:39016" http.request.uri="/v2/e2e-test-prometheus-nfl7f/origin-nodejs-sample/blobs/sha256:7cc928e84921433ebeca4314a11912f541b1d4ec82048bd904eab44399d96a65" http.request.useragent="docker/1.13.1 go/go1.9.2 kernel/3.10.0-862.el7.x86_64 os/linux arch/amd64 UpstreamClient(go-dockerclient)" instance.id=ddca745a-9226-4b65-8a74-c4f703d49019 openshift.auth.user="system:serviceaccount:e2e-test-prometheus-nfl7f:builder" openshift.auth.userid=552a0e64-4b68-11e8-8474-0e0e85ffbd0a vars.digest="sha256:7cc928e84921433ebeca4314a11912f541b1d4ec82048bd904eab44399d96a65" vars.name=e2e-test-prometheus-nfl7f/origin-nodejs-sample
time="2018-04-29T04:48:07.861060374Z" level=debug msg="(*blobDescriptorService).Stat: starting with digest=sha256:7cc928e84921433ebeca4314a11912f541b1d4ec82048bd904eab44399d96a65" go.version=go1.9.2 http.request.host="docker-registry.default.svc:5000" http.request.id=b8687702-44cd-4e4b-bc8c-debb20f2028d http.request.method=HEAD http.request.remoteaddr="10.128.0.1:39016" http.request.uri="/v2/e2e-test-prometheus-nfl7f/origin-nodejs-sample/blobs/sha256:7cc928e84921433ebeca4314a11912f541b1d4ec82048bd904eab44399d96a65" http.request.useragent="docker/1.13.1 go/go1.9.2 kernel/3.10.0-862.el7.x86_64 os/linux arch/amd64 UpstreamClient(go-dockerclient)" instance.id=ddca745a-9226-4b65-8a74-c4f703d49019 openshift.auth.user="system:serviceaccount:e2e-test-prometheus-nfl7f:builder" openshift.auth.userid=552a0e64-4b68-11e8-8474-0e0e85ffbd0a vars.digest="sha256:7cc928e84921433ebeca4314a11912f541b1d4ec82048bd904eab44399d96a65" vars.name=e2e-test-prometheus-nfl7f/origin-nodejs-sample
time="2018-04-29T04:48:07.861168202Z" level=debug msg="filesystem.URLFor(\"/docker/registry/v2/blobs/sha256/7c/7cc928e84921433ebeca4314a11912f541b1d4ec82048bd904eab44399d96a65/data\")" go.version=go1.9.2 http.request.host="docker-registry.default.svc:5000" http.request.id=b8687702-44cd-4e4b-bc8c-debb20f2028d http.request.method=HEAD http.request.remoteaddr="10.128.0.1:39016" http.request.uri="/v2/e2e-test-prometheus-nfl7f/origin-nodejs-sample/blobs/sha256:7cc928e84921433ebeca4314a11912f541b1d4ec82048bd904eab44399d96a65" http.request.useragent="docker/1.13.1 go/go1.9.2 kernel/3.10.0-862.el7.x86_64 os/linux arch/amd64 UpstreamClient(go-dockerclient)" instance.id=ddca745a-9226-4b65-8a74-c4f703d49019 openshift.auth.user="system:serviceaccount:e2e-test-prometheus-nfl7f:builder" openshift.auth.userid=552a0e64-4b68-11e8-8474-0e0e85ffbd0a trace.duration="17.711µs" trace.file=/tmp/openshift/build-rpms/rpm/BUILD/origin-dockerregistry-3.10.0/_output/local/go/src/github.com/openshift/image-registry/vendor/github.com/docker/distribution/registry/storage/driver/base/base.go trace.func="github.com/openshift/image-registry/vendor/github.com/docker/distribution/registry/storage/driver/base.(*Base).URLFor" trace.id=8f52e8d9-21c0-4d55-8222-06849fb00dd7 trace.line=189 vars.digest="sha256:7cc928e84921433ebeca4314a11912f541b1d4ec82048bd904eab44399d96a65" vars.name=e2e-test-prometheus-nfl7f/origin-nodejs-sample
time="2018-04-29T04:48:07.861239906Z" level=debug msg="(*blobDescriptorService).Stat: starting with digest=sha256:7cc928e84921433ebeca4314a11912f541b1d4ec82048bd904eab44399d96a65" go.version=go1.9.2 http.request.host="docker-registry.default.svc:5000" http.request.id=b8687702-44cd-4e4b-bc8c-debb20f2028d http.request.method=HEAD http.request.remoteaddr="10.128.0.1:39016" http.request.uri="/v2/e2e-test-prometheus-nfl7f/origin-nodejs-sample/blobs/sha256:7cc928e84921433ebeca4314a11912f541b1d4ec82048bd904eab44399d96a65" http.request.useragent="docker/1.13.1 go/go1.9.2 kernel/3.10.0-862.el7.x86_64 os/linux arch/amd64 UpstreamClient(go-dockerclient)" instance.id=ddca745a-9226-4b65-8a74-c4f703d49019 openshift.auth.user="system:serviceaccount:e2e-test-prometheus-nfl7f:builder" openshift.auth.userid=552a0e64-4b68-11e8-8474-0e0e85ffbd0a vars.digest="sha256:7cc928e84921433ebeca4314a11912f541b1d4ec82048bd904eab44399d96a65" vars.name=e2e-test-prometheus-nfl7f/origin-nodejs-sample
time="2018-04-29T04:48:07.861355184Z" level=info msg="response completed" go.version=go1.9.2 http.request.host="docker-registry.default.svc:5000" http.request.id=b8687702-44cd-4e4b-bc8c-debb20f2028d http.request.method=HEAD http.request.remoteaddr="10.128.0.1:39016" http.request.uri="/v2/e2e-test-prometheus-nfl7f/origin-nodejs-sample/blobs/sha256:7cc928e84921433ebeca4314a11912f541b1d4ec82048bd904eab44399d96a65" http.request.useragent="docker/1.13.1 go/go1.9.2 kernel/3.10.0-862.el7.x86_64 os/linux arch/amd64 UpstreamClient(go-dockerclient)" http.response.contenttype=application/octet-stream http.response.duration=9.071113ms http.response.status=200 http.response.written=0 instance.id=ddca745a-9226-4b65-8a74-c4f703d49019

None of the store level ones seem useful.

Do we have better examples of normal path debug you wanted to see? If they are all under our control, just bump them to info, because they're not a sufficiently significant portion of the workload. If they're not, which ones have been most impactful?

Just doing a completely unscientific pass over things that I doubt we'd ever care about, I was down to about 1/3 by excluding the top 10 or so boring messages.

Does logrus allow us to omit any of the extra variables that we could just log once at startup?

@legionus
Copy link
Contributor

We have a general log level policy, we do not ship components to customers that log at debug level excessively.

I can change of our log records from debug to info if someone will feels better after it. This information is now needed and is used in investigations of user failures.

Filesystem ones seem definitely not useful for the vast majority of debugging unless we have a fundamental error.

No. This information is important because our users sometimes have problems with the storage. I have several times this year faced with the investigation of problems related to nfs and glusterfs.

None of the store level ones seem useful.

And for me this log says that the system:serviceaccount:e2e-test-prometheus-nfl7f:builder user has checked access to the blog and this blob is found locally and not on another server. This means that this blob will not be sent to the server. It is important to know if a pull error occurs later.

Do we have better examples of normal path debug you wanted to see?

Due to bad design of docker/distribution cache, pullthrough and image prunning, errors can occur at each stage of the request processing. We can not give the docker client a real error. Therefore, we need detailed logging on the server side.

If they are all under our control, just bump them to info, because they're not a sufficiently significant portion of the workload.

No. We control only the middlewares. The whole logic of parsing the request and preparing the answer is not under our control. Also we do not control the logic of the cache, BlobStore and everything that licks below the our middlewares. Basically we do not control everything inside docker/distribution. We control a very small area of code.

Just doing a completely unscientific pass over things that I doubt we'd ever care about, I was down to about 1/3 by excluding the top 10 or so boring messages.

After that "throwing out" of records it is necessary to carry out the detailed analysis and to spend testing there will be no information for investigation of breakages. If your goal is simply to reduce the logs, then you set loglevel=error and you will get beautiful, small and useless logs.

Does logrus allow us to omit any of the extra variables that we could just log once at startup?

No and the construction of the logger takes place outside our control area.

P.S. Let me fork the docker/distribution and I'll make the logs smaller and more informative.

@legionus
Copy link
Contributor

I have another solution: let's set the loglevel to error, but if client hits some problem, we will require set the debug loglevel and reproducing the error again and only after that we will start investigating the problem.

@openshift-ci-robot
Copy link
Contributor

[APPROVALNOTIFIER] This PR is NOT APPROVED

This pull-request has been approved by: coreydaley
To fully approve this pull request, please assign additional approvers.
We suggest the following additional approver: legionus

Assign the PR to them by writing /assign @legionus in a comment when ready.

The full list of commands accepted by this bot can be found here.

The pull request process is described here

Needs approval from an approver in each of these files:

Approvers can indicate their approval by writing /approve in a comment
Approvers can cancel approval by writing /approve cancel in a comment

@coreydaley
Copy link
Member Author

The loglevel in this PR has now been set to error per @legionus comment above.

@bparees
Copy link
Contributor

bparees commented Apr 30, 2018

I have another solution: let's set the loglevel to error

why error and not info? I agree w/ the implied sentiment that any setting other than debug means we are signing up for a bad support experience, but is there a reason to completely cripple ourselves or was this just a sarcastic suggestion?

@legionus
Copy link
Contributor

legionus commented May 2, 2018

why error and not info?

$ git grep '\.GetLogger([^)]\+)\.' |sed -n -e 's/^.*\.\(Fatal\|Error\|Warn\|Info\|Debug\)f\?(.*/\1/p' |sort |uniq -c
     41 Debug
     49 Error
      6 Fatal
     18 Info
      1 Warn

I agree w/ the implied sentiment that any setting other than debug means we are signing up for a bad support experience.

Yes. We will highly degrade the quality of the support if we change the loglevel. I'm completely against it. I never put lgtm on this PR. You or Clayton can approve it and this will be your decision.

You know, that our users can not give us registry logs even now. They either can not collect logs, or they send for an incorrect period of time. So as a result we ask all the logs that they have and we ourselves are looking for the right place.

If we ask users to re-deploy the registry with debug loglevel and ask to reproduce the error, it means throwing away more than 80% of the error reports, because users simply can not do it correctly. What can I say, not all support engineers can do this correctly.

And honestly, I do not understand what problem we are solving this PR.
Will we make them more understandable by hiding most of the log? No.
Will we save disk space? A little. Logs are now being rotated.

but is there a reason to completely cripple ourselves or was this just a sarcastic suggestion?

Damn, it seems you know me too well. The reason for my sarcastic proposal is that since you guys want to take away the necessary logs, then for me there is no difference what loglevel will be specified. Let it be an error or even fatal. Why not. In any case, I will need to ask to reproduce the error with the debug loglevel. So the initial loglevel is not important.

@legionus legionus mentioned this pull request May 3, 2018
@openshift-ci-robot
Copy link
Contributor

@coreydaley: The following test failed, say /retest to rerun them all:

Test name Commit Details Rerun command
ci/prow/e2e a7c3be9 link /test e2e

Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the kubernetes/test-infra repository. I understand the commands that are listed here.

@coreydaley
Copy link
Member Author

@bparees should i just close this PR?

@bparees
Copy link
Contributor

bparees commented Jun 19, 2018

@bparees should i just close this PR?

yeah i think so.

though this is the change we're still going to have to make once @legionus implements the rest of his changes, but he can do this too as part of his PR that delivers it.

@coreydaley coreydaley closed this Jun 20, 2018
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
size/XS Denotes a PR that changes 0-9 lines, ignoring generated files.
Projects
None yet
Development

Successfully merging this pull request may close these issues.

None yet

7 participants