Repeated skydns log: incomplete CNAME chain: rcode is not equal to success

[jimmidyson]

Continuously:

2015-10-16 09:40:53.821119 I | skydns: incomplete CNAME chain: rcode is not equal to success
2015-10-16 09:41:08.831796 I | skydns: incomplete CNAME chain: rcode is not equal to success
2015-10-16 09:41:08.847089 I | skydns: incomplete CNAME chain: rcode is not equal to success
2015-10-16 09:41:23.810062 I | skydns: incomplete CNAME chain: rcode is not equal to success
2015-10-16 09:41:23.817699 I | skydns: incomplete CNAME chain: rcode is not equal to success
2015-10-16 09:41:38.807745 I | skydns: incomplete CNAME chain: rcode is not equal to success
2015-10-16 09:41:38.836402 I | skydns: incomplete CNAME chain: rcode is not equal to success
2015-10-16 09:41:53.817832 I | skydns: incomplete CNAME chain: rcode is not equal to success
2015-10-16 09:41:53.820592 I | skydns: incomplete CNAME chain: rcode is not equal to success
2015-10-16 09:42:08.815018 I | skydns: incomplete CNAME chain: rcode is not equal to success
2015-10-16 09:42:08.817311 I | skydns: incomplete CNAME chain: rcode is not equal to success
2015-10-16 09:42:23.841105 I | skydns: incomplete CNAME chain: rcode is not equal to success
2015-10-16 09:42:23.844855 I | skydns: incomplete CNAME chain: rcode is not equal to success

[jimmidyson]

With latest master I also get repeated:

E1022 13:29:39.107558    2085 proxysocket.go:93] Couldn't find an endpoint for default/kubernetes:: missing service entry
E1022 13:29:39.107583    2085 proxysocket.go:138] Failed to connect to balancer: missing service entry

[jimmidyson]

Here's my beautiful logs: https://gist.github.com/jimmidyson/5857bdfe1b5d4274bdb5

[0xmichalis]

@jimmidyson can you help me reproduce this? It would be helpful to have at least all the services you have in your etcd.

[jimmidyson]

Forget the one i reported earlier today - that seemed to be something transient when I upgraded to master. Solved by deleting the kubernetes & kubernetes-ro services & letting them be automatically recreated.

Do you get the skydns log message at all?

[0xmichalis]

No. Running on a fresh etcd and just following the sample app flow I don't see anything from the dns server.

[jimmidyson]

Same log previously reported in #2482 (comment). @ncdc - Do you still get that log message?

[0xmichalis]

I finally got to hit this by execing in a pod and trying to curl another endpoint. Trying to debug this though I still don't see it repeatedly in my logs for no apparent reason...

[pweil-]

Thanks @Kargakis. Let me know today if you feel like this should remain a blocker bug

[0xmichalis]

I finally got to hit this by execing in a pod and trying to curl another endpoint. Trying to debug this though I still don't see it repeatedly in my logs for no apparent reason...

SkyDNS is hitting NXDOMAIN and rcode is not equal to success surfaces for OpenShift (at least in my case).

2015-11-02 14:50:14.476762 I | skydns: Nameserver: 10.0.2.3:53, Rcode: 3
2015-11-02 14:50:14.476891 I | skydns: Asked for web.portal.frontend.
2015-11-02 14:50:14.476943 I | skydns: incomplete CNAME chain: rcode is not equal to success

bash-4.2$ nslookup frontend.test.svc.cluster.local
;; Got SERVFAIL reply from 10.0.2.15, trying next server
;; Got SERVFAIL reply from 10.0.2.15, trying next server
Server:     10.0.2.15
Address:    10.0.2.15#53

Name:   frontend.test.svc.cluster.local
Address: 172.30.210.9

I suspect this is happening because the kubernetes service which is skydns in disguise exposes three ports

[vagrant@openshiftdev sample-app]$ oc describe svc/kubernetes
Name:           kubernetes
Namespace:      default
Labels:         component=apiserver,provider=kubernetes
Selector:       <none>
Type:           ClusterIP
IP:         172.30.0.1
Port:           https   443/TCP
Endpoints:      10.0.2.15:8443
Port:           dns 53/UDP
Endpoints:      10.0.2.15:53
Port:           dns-tcp 53/TCP
Endpoints:      10.0.2.15:53
Session Affinity:   None
No events.

If I try to resolve a domain not known by SkyDNS, it will try three times with SkyDNS before moving to the next nameserver

bash-4.2$ cat /etc/resolv.conf 
nameserver 10.0.2.15
nameserver 10.0.2.3
search test.svc.cluster.local svc.cluster.local cluster.local brq.redhat.com local
options ndots:5

bash-4.2$ nslookup google.com
;; Got SERVFAIL reply from 10.0.2.15, trying next server
;; Got SERVFAIL reply from 10.0.2.15, trying next server
;; Got SERVFAIL reply from 10.0.2.15, trying next server
Server:     10.0.2.3
Address:    10.0.2.3#53

Non-authoritative answer:
Name:   google.com
Address: 173.194.113.41
...

Thanks @Kargakis. Let me know today if you feel like this should remain a blocker bug

I don't think this is a blocker bug. @jimmidyson It would be helpful to debug what you are seeing if you added some more logging in Godeps/_workspace/src/github.com/skynetservices/skydns/server/forwarding.go. More specifically what I did:

if err == nil {
+       logf("Nameserver: %s, Rcode: %d", s.config.Nameservers[nsid], r.Rcode)
+       for _, q := range r.Question {
+           logf("Asked for %s", q.Name)
+           }
        if r.Rcode != dns.RcodeSuccess {
            return nil, fmt.Errorf("rcode is not equal to success")
        }

[smarterclayton]

This started happening after the skydns on sept15th. The record format SkyDNS expected changed, which meant skydns was suddenly performing CNAME resolutions on things that should have been absolute. Fixed in #5613

[smarterclayton]

p1 because it can result in multi-second delays to resolve.