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

Kubedns logging #36013

Merged
merged 2 commits into from
Nov 6, 2016
Merged

Kubedns logging #36013

merged 2 commits into from
Nov 6, 2016

Conversation

bowei
Copy link
Member

@bowei bowei commented Nov 1, 2016

fixes
#29053

may resolve #29054, but depends on what the specific ask is


This change is Reviewable

@k8s-github-robot k8s-github-robot added size/XL Denotes a PR that changes 500-999 lines, ignoring generated files. release-note-label-needed labels Nov 1, 2016
@k8s-ci-robot
Copy link
Contributor

Jenkins verification failed for commit 39e5d426c3d01344c221fa97e9eb409cb92a52f0. Full PR test history.

The magic incantation to run this job again is @k8s-bot verify test this. Please help us cut down flakes by linking to an open flake issue when you hit one in your PR.

@bowei
Copy link
Member Author

bowei commented Nov 1, 2016

@thockin

@thockin thockin assigned MrHohn and unassigned lavalamp Nov 2, 2016
@thockin
Copy link
Member

thockin commented Nov 2, 2016

I took a quick look. Assigned to @MrHohn.

Can you post a snippet of logs here?

@thockin thockin added release-note-none Denotes a PR that doesn't merit a release note. and removed release-note-label-needed labels Nov 2, 2016
@bowei
Copy link
Member Author

bowei commented Nov 2, 2016

v(2)

I1102 02:49:28.492030       1 dns.go:42] version: v1.5.0-alpha.2.320+c45624e3473292-dirty
I1102 02:49:28.492372       1 server.go:94] Using https://10.0.0.1:443 for kubernetes master, kubernetes API: <nil>
I1102 02:49:28.499400       1 server.go:100] FLAG: --alsologtostderr="false"
I1102 02:49:28.499420       1 server.go:100] FLAG: --dns-bind-address="0.0.0.0"
...
I1102 02:49:28.499498       1 server.go:100] FLAG: --vmodule=""
I1102 02:49:28.499663       1 server.go:142] Starting SkyDNS server (0.0.0.0:10053)
I1102 02:49:28.499961       1 server.go:152] Skydns metrics enabled (/metrics:10055)
I1102 02:49:28.499976       1 dns.go:144] Starting endpointsController
I1102 02:49:28.499980       1 dns.go:147] Starting serviceController
I1102 02:49:28.499982       1 dns.go:157] Waiting for Kubernetes service
I1102 02:49:28.499986       1 dns.go:163] Waiting for service: default/kubernetes
I1102 02:49:28.500056       1 logs.go:41] skydns: ready for queries on cluster.local. for tcp://0.0.0.0:10053 [rcache 0]
I1102 02:49:28.500064       1 logs.go:41] skydns: ready for queries on cluster.local. for udp://0.0.0.0:10053 [rcache 0]
I1102 02:49:28.530095       1 dns.go:246] newService default-http-backend
I1102 02:49:28.530320       1 dns.go:356] Added SRV record &{Host:default-http-backend.kube-system.svc.cluster.local. Port:80 Priority:10 Weight:10 Text: Mail:false Ttl:30 TargetStrip:0 Group: Key:}
I1102 02:49:28.530430       1 dns.go:246] newService kubernetes-dashboard
I1102 02:49:28.530517       1 dns.go:246] newService kube-dns
I1102 02:49:28.530646       1 dns.go:356] Added SRV record &{Host:kube-dns.kube-system.svc.cluster.local. Port:53 Priority:10 Weight:10 Text: Mail:false Ttl:30 TargetStrip:0 Group: Key:}
I1102 02:49:28.530732       1 dns.go:356] Added SRV record &{Host:kube-dns.kube-system.svc.cluster.local. Port:53 Priority:10 Weight:10 Text: Mail:false Ttl:30 TargetStrip:0 Group: Key:}
...
I1102 02:49:28.531267       1 dns.go:356] Added SRV record &{Host:monitoring-influxdb.kube-system.svc.cluster.local. Port:8083 Priority:10 Weight:10 Text: Mail:false Ttl:30 TargetStrip:0 Group: Key:}
I1102 02:49:28.531393       1 dns.go:356] Added SRV record &{Host:monitoring-influxdb.kube-system.svc.cluster.local. Port:8086 Priority:10 Weight:10 Text: Mail:false Ttl:30 TargetStrip:0 Group: Key:}
I1102 02:49:28.532949       1 server.go:113] Setting up Healthz Handler (/readiness)
I1102 02:49:28.533025       1 server.go:118] Setting up cache handler (/cache)
I1102 02:49:28.533061       1 server.go:107] Status HTTP port 8081
I1102 02:54:28.500594       1 dns.go:246] newService monitoring-influxdb
I1102 02:54:28.500713       1 dns.go:356] Added SRV record &{Host:monitoring-influxdb.kube-system.svc.cluster.local. Port:8083 Priority:10 Weight:10 Text: Mail:false Ttl:30 TargetStrip:0 Group: Key:}
I1102 02:54:28.500743       1 dns.go:356] Added SRV record &{Host:monitoring-influxdb.kube-system.svc.cluster.local. Port:8086 Priority:10 Weight:10 Text: Mail:false Ttl:30 TargetStrip:0 Group: Key:}
I1102 02:54:28.500770       1 dns.go:246] newService default-http-backend
I1102 02:54:28.500792       1 dns.go:356] Added SRV record &{Host:default-http-backend.kube-system.svc.cluster.local. Port:80 Priority:10 Weight:10 Text: Mail:false Ttl:30 TargetStrip:0 Group: Key:}
...
I1102 02:54:28.500884       1 dns.go:356] Added SRV record &{Host:kube-dns.kube-system.svc.cluster.local. Port:53 Priority:10 Weight:10 Text: Mail:false Ttl:30 TargetStrip:0 Group: Key:}
I1102 02:54:28.500915       1 dns.go:246] newService kubernetes
I1102 02:54:28.500935       1 dns.go:356] Added SRV record &{Host:kubernetes.default.svc.cluster.local. Port:443 Priority:10 Weight:10 Text: Mail:false Ttl:30 TargetStrip:0 Group: Key:}

v(3)

I1102 06:10:49.747533       1 dns.go:42] version: v1.5.0-alpha.2.320+c45624e3473292-dirty
I1102 06:10:49.748365       1 server.go:94] Using https://10.0.0.1:443 for kubernetes master, kubernetes API: <nil>
I1102 06:10:49.750104       1 server.go:100] FLAG: --alsologtostderr="false"
...
I1102 06:10:49.751432       1 server.go:100] FLAG: --vmodule=""
I1102 06:10:49.751738       1 server.go:142] Starting SkyDNS server (0.0.0.0:10053)
I1102 06:10:49.753805       1 server.go:152] Skydns metrics enabled (/metrics:10055)
I1102 06:10:49.753894       1 dns.go:144] Starting endpointsController
I1102 06:10:49.753952       1 dns.go:147] Starting serviceController
I1102 06:10:49.754004       1 dns.go:157] Waiting for Kubernetes service
I1102 06:10:49.754060       1 dns.go:163] Waiting for service: default/kubernetes
I1102 06:10:49.755078       1 logs.go:41] skydns: ready for queries on cluster.local. for tcp://0.0.0.0:10053 [rcache 0]
I1102 06:10:49.757299       1 logs.go:41] skydns: ready for queries on cluster.local. for udp://0.0.0.0:10053 [rcache 0]
I1102 06:10:49.756394       1 reflector.go:202] Starting reflector *api.Endpoints (5m0s) from pkg/dns/dns.go:145
I1102 06:10:49.757653       1 reflector.go:240] Listing and watching *api.Endpoints from pkg/dns/dns.go:145
I1102 06:10:49.756580       1 reflector.go:202] Starting reflector *api.Service (5m0s) from pkg/dns/dns.go:148
I1102 06:10:49.758172       1 reflector.go:240] Listing and watching *api.Service from pkg/dns/dns.go:148
I1102 06:10:49.784963       1 dns.go:246] newService kube-dns
I1102 06:10:49.785151       1 dns.go:356] Added SRV record &{Host:kube-dns.kube-system.svc.cluster.local. Port:53 Priority:10 Weight:10 Text: Mail:false Ttl:30 TargetStrip:0 Group: Key:}
...
I1102 06:10:51.326316       1 dns.go:487] Query for "kubernetes.default.svc.cluster.local.", exact: false
I1102 06:10:51.326366       1 dns.go:603] Found 1 records for [local cluster svc default kubernetes] in the cache
I1102 06:10:51.326651       1 dns.go:487] Query for "kubernetes.default.svc.cluster.local.", exact: false
I1102 06:10:51.326667       1 dns.go:603] Found 1 records for [local cluster svc default kubernetes] in the cache
I1102 06:10:51.326976       1 dns.go:487] Query for "kubernetes.default.svc.cluster.local.", exact: false

v(4)

I1102 06:19:26.556571       1 dns.go:487] Query for "kubernetes.default.svc.cluster.local.", exact: false
I1102 06:19:26.556582       1 dns.go:487] Query for "kubernetes.default.svc.cluster.local.", exact: false
I1102 06:19:26.556598       1 dns.go:712] not a federation query: len(["kubernetes" "default" "svc" "cluster" "local"]) != 4+len(["local" "cluster"])
I1102 06:19:26.556606       1 dns.go:712] not a federation query: len(["kubernetes" "default" "svc" "cluster" "local"]) != 4+len(["local" "cluster"])
I1102 06:19:26.556620       1 dns.go:603] Found 1 records for [local cluster svc default kubernetes] in the cache
I1102 06:19:26.556626       1 dns.go:603] Found 1 records for [local cluster svc default kubernetes] in the cache
I1102 06:19:26.556628       1 dns.go:610] getRecordsForPath retval=[{Host:10.0.0.1 Port:0 Priority:10 Weight:10 Text: Mail:false Ttl:30 TargetStrip:0 Group: Key:/skydns/local/cluster/svc/default/kubernetes/3234633364383235}], path=[local cluster svc default kubernetes]
I1102 06:19:26.556634       1 dns.go:610] getRecordsForPath retval=[{Host:10.0.0.1 Port:0 Priority:10 Weight:10 Text: Mail:false Ttl:30 TargetStrip:0 Group: Key:/skydns/local/cluster/svc/default/kubernetes/3234633364383235}], path=[local cluster svc default kubernetes]
I1102 06:19:26.556656       1 dns.go:516] Records for kubernetes.default.svc.cluster.local.: [{10.0.0.1 0 10 10  false 30 0  /skydns/local/cluster/svc/default/kubernetes/3234633364383235}]
I1102 06:19:26.556645       1 dns.go:516] Records for kubernetes.default.svc.cluster.local.: [{10.0.0.1 0 10 10  false 30 0  /skydns/local/cluster/svc/default/kubernetes/3234633364383235}]
I1102 06:19:26.557034       1 dns.go:487] Query for "kubernetes.default.svc.cluster.local.", exact: false
I1102 06:19:26.557076       1 dns.go:712] not a federation query: len(["kubernetes" "default" "svc" "cluster" "local"]) != 4+len(["local" "cluster"])
I1102 06:19:26.557090       1 dns.go:603] Found 1 records for [local cluster svc default kubernetes] in the cache
I1102 06:19:26.557096       1 dns.go:610] getRecordsForPath retval=[{Host:10.0.0.1 Port:0 Priority:10 Weight:10 Text: Mail:false Ttl:30 TargetStrip:0 Group: Key:/skydns/local/cluster/svc/default/kubernetes/3234633364383235}], path=[local cluster svc default kubernetes]
I1102 06:19:26.557107       1 dns.go:516] Records for kubernetes.default.svc.cluster.local.: [{10.0.0.1 0 10 10  false 30 0  /skydns/local/cluster/svc/default/kubernetes/3234633364383235}]
I1102 06:19:26.557704       1 dns.go:487] Query for "kubernetes.default.svc.cluster.local.", exact: false
I1102 06:19:26.557778       1 dns.go:712] not a federation query: len(["kubernetes" "default" "svc" "cluster" "local"]) != 4+len(["local" "cluster"])
I1102 06:19:26.557853       1 dns.go:603] Found 1 records for [local cluster svc default kubernetes] in the cache
I1102 06:19:26.557898       1 dns.go:610] getRecordsForPath retval=[{Host:10.0.0.1 Port:0 Priority:10 Weight:10 Text: Mail:false Ttl:30 TargetStrip:0 Group: Key:/skydns/local/cluster/svc/default/kubernetes/3234633364383235}], path=[local cluster svc default kubernetes]
I1102 06:19:26.557972       1 dns.go:516] Records for kubernetes.default.svc.cluster.local.: [{10.0.0.1 0 10 10  false 30 0  /skydns/local/cluster/svc/default/kubernetes/3234633364383235}]

Copy link
Member

@MrHohn MrHohn left a comment

Choose a reason for hiding this comment

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

Looks good. Add comments basically for nits.

server.SetDefaults(skydnsConfig)
s := server.New(d.kd, skydnsConfig)
if err := metrics.Metrics(); err != nil {
glog.Fatalf("skydns: %s", err)
glog.Fatalf("Skydns metrics error: %s", err)
} else if metrics.Port != "" {
Copy link
Member

Choose a reason for hiding this comment

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

Do we need to give a warning if metrics.Port is not set?

Copy link
Member Author

Choose a reason for hiding this comment

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

ok -- added info log

@@ -230,7 +243,9 @@ func assertIsService(obj interface{}) (*kapi.Service, bool) {

func (kd *KubeDNS) newService(obj interface{}) {
if service, ok := assertIsService(obj); ok {
glog.V(4).Infof("Add/Updated for service %v", service.Name)
glog.V(2).Infof("newService %v", service.Name)
Copy link
Member

Choose a reason for hiding this comment

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

Would New service: %v better?

Copy link
Member Author

Choose a reason for hiding this comment

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

done

@@ -63,7 +63,8 @@ func ReverseArray(arr []string) []string {
func GetSkyMsg(ip string, port int) (*msg.Service, string) {
msg := NewServiceRecord(ip, port)
hash := HashServiceRecord(msg)
glog.V(2).Infof("DNS Record:%s, hash:%s", fmt.Sprintf("%v", msg), hash)
glog.V(5).Infof("Created new DNS record: %s, hash:%s",
Copy link
Member

Choose a reason for hiding this comment

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

I think this function construct a new record but not actually create one?

Copy link
Member Author

Choose a reason for hiding this comment

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

changed to "constructed"

"github.com/skynetservices/skydns/msg"
)

func TestTreeCache(t *testing.T) {
Copy link
Member

Choose a reason for hiding this comment

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

Should we also test SetSubCache() here?

Saw the TODO says we should combine it with SetEntry() in future. May be wait til then?

Copy link
Member Author

Choose a reason for hiding this comment

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

add a test


retval := []skymsg.Service{}
for _, val := range records {
retval = append(retval, *val)
}

glog.V(2).Infof("records:%v, retval:%v, path:%v", records, retval, path)
glog.V(4).Infof("getRecordsForPath retval=%+v, path=%v", retval, path)
Copy link
Member

@MrHohn MrHohn Nov 3, 2016

Choose a reason for hiding this comment

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

I guess it also make sense to make it identical to the function name as it is V4?

Copy link
Member Author

Choose a reason for hiding this comment

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

it is the same?

@@ -676,34 +709,39 @@ func (kd *KubeDNS) getPodIP(path []string) (string, error) {
// We can add support for wildcard queries later, if needed.
func (kd *KubeDNS) isFederationQuery(path []string) bool {
if len(path) != 4+len(kd.domainPath) {
glog.V(2).Infof("not a federation query: len(%q) != 4+len(%q)", path, kd.domainPath)
glog.V(4).Infof("not a federation query: len(%q) != 4+len(%q)", path, kd.domainPath)
Copy link
Member

Choose a reason for hiding this comment

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

nit: first letter capital

Copy link
Member Author

Choose a reason for hiding this comment

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

done

func TestTreeCache(t *testing.T) {
tc := NewTreeCache()

{
Copy link
Member

Choose a reason for hiding this comment

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

Why put this in a block?

Copy link
Member Author

Choose a reason for hiding this comment

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

limit variable scoping

t.Error("should not affect p3.p1.")
}
if tc.DeletePath("p1", "p2") {
t.Fatal()
Copy link
Member

Choose a reason for hiding this comment

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

May be add a bit error message when fail?

Copy link
Member Author

Choose a reason for hiding this comment

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

ok

{"key3", []string{"p1", "p3"}},
} {
if _, ok := tc.GetEntry(testCase.k, testCase.p...); ok {
t.Error()
Copy link
Member

Choose a reason for hiding this comment

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

Should have error message.

Copy link
Member Author

Choose a reason for hiding this comment

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

ok

--v=2 is low noise (record changes), can be default
--v=3 will shows per request logging

Note: due to the code path with which we integrate with
skydns, we don't see non-PILLAR_DOMAIN requests, so these
will never be logged.
@MrHohn
Copy link
Member

MrHohn commented Nov 3, 2016

/lgtm

@MrHohn
Copy link
Member

MrHohn commented Nov 3, 2016

@k8s-bot gci gce e2e test this, issue: #34665

@k8s-github-robot k8s-github-robot added the lgtm "Looks good to me", indicates that a PR is ready to be merged. label Nov 3, 2016
@k8s-ci-robot
Copy link
Contributor

Jenkins GCI GCE e2e failed for commit d9557d4. Full PR test history.

The magic incantation to run this job again is @k8s-bot gci gce e2e test this. Please help us cut down flakes by linking to an open flake issue when you hit one in your PR.

@bowei
Copy link
Member Author

bowei commented Nov 4, 2016

gci gce e2e test this

@bowei
Copy link
Member Author

bowei commented Nov 4, 2016

@k8s-bot gci gce e2e test this

@thockin thockin added this to the v1.5 milestone Nov 4, 2016
@k8s-github-robot
Copy link

@k8s-bot test this [submit-queue is verifying that this PR is safe to merge]

@k8s-github-robot
Copy link

Automatic merge from submit-queue

@k8s-github-robot k8s-github-robot merged commit 5e8b22f into kubernetes:master Nov 6, 2016
@bowei bowei deleted the kubedns-logging branch February 21, 2017 19:11
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
lgtm "Looks good to me", indicates that a PR is ready to be merged. release-note-none Denotes a PR that doesn't merit a release note. size/XL Denotes a PR that changes 500-999 lines, ignoring generated files.
Projects
None yet
Development

Successfully merging this pull request may close these issues.

kubedns logging is missing important items
7 participants