first effort to improve logging in external-dns to provide with basic needed logging (#174)

* continue on controller loop error

* add logging in source

* use formatter on logChanges for endpoints

* fix log messages, log skipped records

* add logging in aws, uppercase the rest

* respect google dry run policy

* add ing/svc namespace/name on logging

* fix error logging on template failure

* fix bugs, propagate template error

* log if nothing is being updated, debug log skipped endpoints

* change zone-not-found logging order

CHANGELOG.md

@@ -1,4 +1,5 @@
 Features:
+  - Improved logging
   - Generate DNS Name from template for services/ingress if annotation is missing but `--fqdn-template` is specified
   - Route 53: Support creation of records in multiple hosted zones.
   - Route 53: Support creation of ALIAS records when endpoint target is a ELB/ALB.

controller/controller.go

@@ -71,13 +71,13 @@ func (c *Controller) Run(stopChan <-chan struct{}) {
 	for {
 		err := c.RunOnce()
 		if err != nil {
-			log.Fatal(err)
+			log.Error(err)
 		}
 
 		select {
 		case <-time.After(c.Interval):
 		case <-stopChan:
-			log.Infoln("terminating main controller loop")
+			log.Infoln("Terminating main controller loop")
 			return
 		}
 	}

endpoint/endpoint.go

@@ -17,6 +17,7 @@ limitations under the License.
 package endpoint
 
 import (
+	"fmt"
 	"strings"
 )
 
@@ -55,3 +56,7 @@ func (e *Endpoint) MergeLabels(labels map[string]string) {
 		}
 	}
 }
+
+func (e *Endpoint) String() string {
+	return fmt.Sprintf("%s: %s -> %s", e.RecordType, e.DNSName, e.Target)
+}

internal/testutils/endpoint_test.go

@@ -55,9 +55,9 @@ func ExampleSameEndpoints() {
 		fmt.Println(ep)
 	}
 	// Output:
-	// &{abc.com 1.2.3.4 A map[]}
+	// A: abc.com -> 1.2.3.4
-	// &{abc.com something TXT map[]}
+	// TXT: abc.com -> something
-	// &{bbc.com foo.com CNAME map[]}
+	// CNAME: bbc.com -> foo.com
-	// &{example.org load-balancer.org  map[]}
+	// : example.org -> load-balancer.org
-	// &{example.org load-balancer.org TXT map[]}
+	// TXT: example.org -> load-balancer.org
 }

plan/plan.go

@@ -17,6 +17,7 @@ limitations under the License.
 package plan
 
 import (
+	log "github.com/Sirupsen/logrus"
 	"github.com/kubernetes-incubator/external-dns/endpoint"
 )
 
@@ -71,7 +72,10 @@ func (p *Plan) Calculate() *Plan {
 			desired.RecordType = current.RecordType // inherit the type from the dns provider
 			desired.MergeLabels(current.Labels)     // inherit the labels from the dns provider, including Owner ID
 			changes.UpdateNew = append(changes.UpdateNew, desired)
+			continue
 		}
+
+		log.Debugf("Skipping endpoint %v because target has not changed", desired)
 	}
 
 	// Ensure all undesired records are removed. Each current record that cannot

plan/policy.go

@@ -16,6 +16,10 @@ limitations under the License.
 
 package plan
 
+import (
+	log "github.com/Sirupsen/logrus"
+)
+
 // Policy allows to apply different rules to a set of changes.
 type Policy interface {
 	Apply(changes *Changes) *Changes
@@ -40,6 +44,7 @@ type UpsertOnlyPolicy struct{}
 
 // Apply applies the upsert-only policy which strips out any deletions.
 func (p *UpsertOnlyPolicy) Apply(changes *Changes) *Changes {
+	log.Debugf("Records to be excluded from the delete list due to upsert-only policy: %v", changes.Delete)
 	return &Changes{
 		Create:    changes.Create,
 		UpdateOld: changes.UpdateOld,

provider/aws.go

@@ -201,11 +201,10 @@ func (p *AWSProvider) submitChanges(changes []*route53.Change) error {
 	changesByZone := changesByZone(zones, changes)
 
 	for z, cs := range changesByZone {
-		if p.DryRun {
+		for _, c := range cs {
-			for _, c := range cs {
+			log.Infof("Changing records: %s %s", aws.StringValue(c.Action), c.String())
-				log.Infof("Changing records: %s %s", aws.StringValue(c.Action), c.String())
+		}
-			}
+		if !p.DryRun {
-		} else {
 			params := &route53.ChangeResourceRecordSetsInput{
 				HostedZoneId: aws.String(z),
 				ChangeBatch: &route53.ChangeBatch{
@@ -233,14 +232,18 @@ func changesByZone(zones map[string]*route53.HostedZone, changeSet []*route53.Ch
 	for _, c := range changeSet {
 		hostname := ensureTrailingDot(aws.StringValue(c.ResourceRecordSet.Name))
 
-		if zone := suitableZone(hostname, zones); zone != nil {
+		zone := suitableZone(hostname, zones)
-			changes[aws.StringValue(zone.Id)] = append(changes[aws.StringValue(zone.Id)], c)
+		if zone == nil {
+			log.Debugf("Skipping record %s because no hosted zone matching record DNS Name was detected ", c.String())
+			continue
 		}
+		changes[aws.StringValue(zone.Id)] = append(changes[aws.StringValue(zone.Id)], c)
 	}
 
 	// separating a change could lead to empty sub changes, remove them here.
 	for zone, change := range changes {
 		if len(change) == 0 {
+			log.Infof("No records to be changed in zone: %s", aws.StringValue(zones[zone].Name))
 			delete(changes, zone)
 		}
 	}

provider/google.go

@@ -248,24 +248,24 @@ func (p *googleProvider) ApplyChanges(zone string, changes *plan.Changes) error
 
 // submitChange takes a zone and a Change and sends it to Google.
 func (p *googleProvider) submitChange(zone string, change *dns.Change) error {
-	if p.dryRun {
-		for _, del := range change.Deletions {
-			log.Infof("Del records: %s %s %s", del.Name, del.Type, del.Rrdatas)
-		}
-		for _, add := range change.Additions {
-			log.Infof("Add records: %s %s %s", add.Name, add.Type, add.Rrdatas)
-		}
-
-		return nil
-	}
 
 	if len(change.Additions) == 0 && len(change.Deletions) == 0 {
+		log.Infoln("Received empty list of records for creation and deletion")
 		return nil
 	}
 
-	_, err := p.changesClient.Create(p.project, zone, change).Do()
+	for _, del := range change.Deletions {
-	if err != nil {
+		log.Infof("Del records: %s %s %s", del.Name, del.Type, del.Rrdatas)
-		return err
+	}
+	for _, add := range change.Additions {
+		log.Infof("Add records: %s %s %s", add.Name, add.Type, add.Rrdatas)
+	}
+
+	if !p.dryRun {
+		_, err := p.changesClient.Create(p.project, zone, change).Do()
+		if err != nil {
+			return err
+		}
 	}
 
 	return nil

registry/noop.go

@@ -41,6 +41,5 @@ func (im *NoopRegistry) Records(zone string) ([]*endpoint.Endpoint, error) {
 
 // ApplyChanges propagates changes to the dns provider
 func (im *NoopRegistry) ApplyChanges(zone string, changes *plan.Changes) error {
-	logChanges(changes)
 	return im.provider.ApplyChanges(zone, changes)
 }

registry/registry.go

@@ -35,21 +35,11 @@ type Registry interface {
 func filterOwnedRecords(ownerID string, eps []*endpoint.Endpoint) []*endpoint.Endpoint {
 	filtered := []*endpoint.Endpoint{}
 	for _, ep := range eps {
-		if ep.Labels[endpoint.OwnerLabelKey] == ownerID {
+		if endpointOwner, ok := ep.Labels[endpoint.OwnerLabelKey]; !ok || endpointOwner != ownerID {
-			filtered = append(filtered, ep)
+			log.Debugf("Skipping endpoint %v because owner id does not match, found: %s, required: %s", ep, endpointOwner, ownerID)
+			continue
 		}
+		filtered = append(filtered, ep)
 	}
 	return filtered
 }
-
-func logChanges(changes *plan.Changes) {
-	for _, change := range changes.Create {
-		log.Infof("Creating %s %s -> %s ..", change.RecordType, change.DNSName, change.Target)
-	}
-	for _, change := range changes.UpdateNew {
-		log.Infof("Updating %s %s -> %s ..", change.RecordType, change.DNSName, change.Target)
-	}
-	for _, change := range changes.Delete {
-		log.Infof("Deleting %s %s -> %s ..", change.RecordType, change.DNSName, change.Target)
-	}
-}

registry/txt.go

@@ -109,7 +109,6 @@ func (im *TXTRegistry) ApplyChanges(zone string, changes *plan.Changes) error {
 		txt := endpoint.NewEndpoint(im.mapper.toTXTName(r.DNSName), im.getTXTLabel(), "TXT")
 		filteredChanges.Delete = append(filteredChanges.Delete, txt)
 	}
-	logChanges(filteredChanges)
 	return im.provider.ApplyChanges(zone, filteredChanges)
 }
 

source/ingress.go

@@ -18,6 +18,7 @@ package source
 
 import (
 	"bytes"
+	"fmt"
 	"strings"
 	"text/template"
 
@@ -71,7 +72,9 @@ func (sc *ingressSource) Endpoints() ([]*endpoint.Endpoint, error) {
 	for _, ing := range ingresses.Items {
 		// Check controller annotation to see if we are responsible.
 		controller, ok := ing.Annotations[controllerAnnotationKey]
-		if ok && controller != controllerAnnotationValue { //TODO(ideahitme): log the skip
+		if ok && controller != controllerAnnotationValue {
+			log.Debugf("Skipping ingress %s/%s because controller value does not match, found: %s, required: %s",
+				ing.Namespace, ing.Name, controller, controllerAnnotationValue)
 			continue
 		}
 
@@ -79,23 +82,31 @@ func (sc *ingressSource) Endpoints() ([]*endpoint.Endpoint, error) {
 
 		// apply template if host is missing on ingress
 		if len(ingEndpoints) == 0 && sc.fqdntemplate != nil {
-			ingEndpoints = sc.endpointsFromTemplate(&ing)
+			ingEndpoints, err = sc.endpointsFromTemplate(&ing)
+			if err != nil {
+				return nil, err
+			}
 		}
 
+		if len(ingEndpoints) == 0 {
+			log.Debugf("No endpoints could be generated from ingress %s/%s", ing.Namespace, ing.Name)
+			continue
+		}
+
+		log.Debugf("Endpoints generated from ingress: %s/%s: %v", ing.Namespace, ing.Name, ingEndpoints)
 		endpoints = append(endpoints, ingEndpoints...)
 	}
 
 	return endpoints, nil
 }
 
-func (sc *ingressSource) endpointsFromTemplate(ing *v1beta1.Ingress) []*endpoint.Endpoint {
+func (sc *ingressSource) endpointsFromTemplate(ing *v1beta1.Ingress) ([]*endpoint.Endpoint, error) {
 	var endpoints []*endpoint.Endpoint
 
 	var buf bytes.Buffer
 	err := sc.fqdntemplate.Execute(&buf, ing)
 	if err != nil {
-		log.Errorf("failed to apply template: %v", err)
+		return nil, fmt.Errorf("failed to apply template on ingress %s: %v", ing.String(), err)
-		return nil
 	}
 
 	hostname := buf.String()
@@ -108,7 +119,7 @@ func (sc *ingressSource) endpointsFromTemplate(ing *v1beta1.Ingress) []*endpoint
 		}
 	}
 
-	return endpoints
+	return endpoints, nil
 }
 
 // endpointsFromIngress extracts the endpoints from ingress object

source/service.go

@@ -18,6 +18,7 @@ package source
 
 import (
 	"bytes"
+	"fmt"
 	"strings"
 	"text/template"
 
@@ -74,7 +75,9 @@ func (sc *serviceSource) Endpoints() ([]*endpoint.Endpoint, error) {
 	for _, svc := range services.Items {
 		// Check controller annotation to see if we are responsible.
 		controller, ok := svc.Annotations[controllerAnnotationKey]
-		if ok && controller != controllerAnnotationValue { //TODO(ideahitme): log the skip
+		if ok && controller != controllerAnnotationValue {
+			log.Debugf("Skipping service %s/%s because controller value does not match, found: %s, required: %s",
+				svc.Namespace, svc.Name, controller, controllerAnnotationValue)
 			continue
 		}
 
@@ -87,26 +90,31 @@ func (sc *serviceSource) Endpoints() ([]*endpoint.Endpoint, error) {
 
 		// apply template if none of the above is found
 		if len(svcEndpoints) == 0 && sc.fqdntemplate != nil {
-			svcEndpoints = sc.endpointsFromTemplate(&svc)
+			svcEndpoints, err = sc.endpointsFromTemplate(&svc)
+			if err != nil {
+				return nil, err
+			}
 		}
 
-		if len(svcEndpoints) != 0 {
+		if len(svcEndpoints) == 0 {
-			endpoints = append(endpoints, svcEndpoints...)
+			log.Debugf("No endpoints could be generated from service %s/%s", svc.Namespace, svc.Name)
+			continue
 		}
+
+		log.Debugf("Endpoints generated from service: %s/%s: %v", svc.Namespace, svc.Name, svcEndpoints)
+		endpoints = append(endpoints, svcEndpoints...)
 	}
 
 	return endpoints, nil
 }
 
-func (sc *serviceSource) endpointsFromTemplate(svc *v1.Service) []*endpoint.Endpoint {
+func (sc *serviceSource) endpointsFromTemplate(svc *v1.Service) ([]*endpoint.Endpoint, error) {
 	var endpoints []*endpoint.Endpoint
 
 	var buf bytes.Buffer
-
 	err := sc.fqdntemplate.Execute(&buf, svc)
 	if err != nil {
-		log.Errorf("failed to apply template: %v", err)
+		return nil, fmt.Errorf("failed to apply template on service %s: %v", svc.String(), err)
-		return nil
 	}
 
 	hostname := buf.String()
@@ -120,7 +128,7 @@ func (sc *serviceSource) endpointsFromTemplate(svc *v1.Service) []*endpoint.Endp
 		}
 	}
 
-	return endpoints
+	return endpoints, nil
 }
 
 // endpointsFromService extracts the endpoints from a service object

source/service_test.go

@@ -79,6 +79,7 @@ func testServiceEndpoints(t *testing.T) {
 		annotations     map[string]string
 		lbs             []string
 		expected        []*endpoint.Endpoint
+		expectError     bool
 	}{
 		{
 			"no annotated services return no endpoints",
@@ -91,6 +92,7 @@ func testServiceEndpoints(t *testing.T) {
 			map[string]string{},
 			[]string{"1.2.3.4"},
 			[]*endpoint.Endpoint{},
+			false,
 		},
 		{
 			"annotated services return an endpoint with target IP",
@@ -107,6 +109,7 @@ func testServiceEndpoints(t *testing.T) {
 			[]*endpoint.Endpoint{
 				{DNSName: "foo.example.org", Target: "1.2.3.4"},
 			},
+			false,
 		},
 		{
 			"annotated services return an endpoint with target hostname",
@@ -123,6 +126,7 @@ func testServiceEndpoints(t *testing.T) {
 			[]*endpoint.Endpoint{
 				{DNSName: "foo.example.org", Target: "lb.example.com"},
 			},
+			false,
 		},
 		{
 			"annotated services can omit trailing dot",
@@ -140,6 +144,7 @@ func testServiceEndpoints(t *testing.T) {
 				{DNSName: "foo.example.org", Target: "1.2.3.4"},
 				{DNSName: "foo.example.org", Target: "lb.example.com"},
 			},
+			false,
 		},
 		{
 			"our controller type is dns-controller",
@@ -157,6 +162,7 @@ func testServiceEndpoints(t *testing.T) {
 			[]*endpoint.Endpoint{
 				{DNSName: "foo.example.org", Target: "1.2.3.4"},
 			},
+			false,
 		},
 		{
 			"different controller types are ignored even (with template specified)",
@@ -172,6 +178,7 @@ func testServiceEndpoints(t *testing.T) {
 			},
 			[]string{"1.2.3.4"},
 			[]*endpoint.Endpoint{},
+			false,
 		},
 		{
 			"services are found in target namespace",
@@ -188,6 +195,7 @@ func testServiceEndpoints(t *testing.T) {
 			[]*endpoint.Endpoint{
 				{DNSName: "foo.example.org", Target: "1.2.3.4"},
 			},
+			false,
 		},
 		{
 			"services that are not in target namespace are ignored",
@@ -202,6 +210,7 @@ func testServiceEndpoints(t *testing.T) {
 			},
 			[]string{"1.2.3.4"},
 			[]*endpoint.Endpoint{},
+			false,
 		},
 		{
 			"services are found in all namespaces",
@@ -218,6 +227,7 @@ func testServiceEndpoints(t *testing.T) {
 			[]*endpoint.Endpoint{
 				{DNSName: "foo.example.org", Target: "1.2.3.4"},
 			},
+			false,
 		},
 		{
 			"no external entrypoints return no endpoints",
@@ -232,6 +242,7 @@ func testServiceEndpoints(t *testing.T) {
 			},
 			[]string{},
 			[]*endpoint.Endpoint{},
+			false,
 		},
 		{
 			"multiple external entrypoints return multiple endpoints",
@@ -249,6 +260,7 @@ func testServiceEndpoints(t *testing.T) {
 				{DNSName: "foo.example.org", Target: "1.2.3.4"},
 				{DNSName: "foo.example.org", Target: "8.8.8.8"},
 			},
+			false,
 		},
 		{
 			"services annotated with legacy mate annotations are ignored in default mode",
@@ -263,6 +275,7 @@ func testServiceEndpoints(t *testing.T) {
 			},
 			[]string{"1.2.3.4"},
 			[]*endpoint.Endpoint{},
+			false,
 		},
 		{
 			"services annotated with legacy mate annotations return an endpoint in compatibility mode",
@@ -279,6 +292,7 @@ func testServiceEndpoints(t *testing.T) {
 			[]*endpoint.Endpoint{
 				{DNSName: "foo.example.org", Target: "1.2.3.4"},
 			},
+			false,
 		},
 		{
 			"services annotated with legacy molecule annotations return an endpoint in compatibility mode",
@@ -297,6 +311,7 @@ func testServiceEndpoints(t *testing.T) {
 			[]*endpoint.Endpoint{
 				{DNSName: "foo.example.org", Target: "1.2.3.4"},
 			},
+			false,
 		},
 		{
 			"not annotated services with set fqdntemplate return an endpoint with target IP",
@@ -312,6 +327,7 @@ func testServiceEndpoints(t *testing.T) {
 				{DNSName: "foo.bar.example.com", Target: "1.2.3.4"},
 				{DNSName: "foo.bar.example.com", Target: "elb.com"},
 			},
+			false,
 		},
 		{
 			"not annotated services with unknown tmpl field should not return anything",
@@ -324,6 +340,7 @@ func testServiceEndpoints(t *testing.T) {
 			map[string]string{},
 			[]string{"1.2.3.4"},
 			[]*endpoint.Endpoint{},
+			true,
 		},
 		{
 			"compatibility annotated services with tmpl. compatibility takes precedence",
@@ -340,6 +357,7 @@ func testServiceEndpoints(t *testing.T) {
 			[]*endpoint.Endpoint{
 				{DNSName: "mate.example.org", Target: "1.2.3.4"},
 			},
+			false,
 		},
 	} {
 		t.Run(tc.title, func(t *testing.T) {
@@ -379,9 +397,13 @@ func testServiceEndpoints(t *testing.T) {
 			client, _ := NewServiceSource(kubernetes, tc.targetNamespace, tc.fqdntemplate, tc.compatibility)
 
 			endpoints, err := client.Endpoints()
-			if err != nil {
+
+			if !tc.expectError && err != nil {
 				t.Fatal(err)
 			}
+			if tc.expectError && err == nil {
+				t.Fatal("expected error")
+			}
 
 			// Validate returned endpoints against desired endpoints.
 			validateEndpoints(t, endpoints, tc.expected)