Verbose debug logging via the ConsolePrinter and printer package. (#404)

This:
 * adds a global -v flag for verbosity
 * refactors the "printer" package to have a DefaultPrinter and package
   functions that call it, similar to net/http's DefaultServeMux
 * adds printer tests
 * moves current users of Debugf to Printf
 * moves most users of the "log" package to use "printer"
 * demotes noticably noisy log messages to "Debugf", like "IGNORE"-
   and "NO_PURGE"-related messages

commands/commands.go

@@ -8,6 +8,7 @@ import (
 	"strings"
 
 	"github.com/StackExchange/dnscontrol/models"
+	"github.com/StackExchange/dnscontrol/pkg/printer"
 	"github.com/pkg/errors"
 	"github.com/urfave/cli"
 )
@@ -44,6 +45,13 @@ func Run(v string) int {
 	app.Name = "dnscontrol"
 	app.HideVersion = true
 	app.Usage = "dnscontrol is a compiler and DSL for managing dns zones"
+	app.Flags = []cli.Flag{
+		cli.BoolFlag{
+			Name:        "v",
+			Usage:       "Enable detailed logging",
+			Destination: &printer.DefaultPrinter.Verbose,
+		},
+	}
 	sort.Sort(cli.CommandsByName(commands))
 	app.Commands = commands
 	app.EnableBashCompletion = true

commands/getCerts.go

@@ -10,6 +10,7 @@ import (
 	"github.com/StackExchange/dnscontrol/models"
 	"github.com/StackExchange/dnscontrol/pkg/acme"
 	"github.com/StackExchange/dnscontrol/pkg/normalize"
+	"github.com/StackExchange/dnscontrol/pkg/printer"
 	"github.com/urfave/cli"
 )
 
@@ -88,7 +89,7 @@ func (args *GetCertsArgs) flags() []cli.Flag {
 	flags = append(flags, cli.BoolFlag{
 		Name:        "verbose",
 		Destination: &args.Verbose,
-		Usage:       "Enable detailed logging from acme library",
+		Usage:       "Enable detailed logging (deprecated: use the global -v flag)",
 	})
 	return flags
 }
@@ -150,7 +151,8 @@ func GetCerts(args GetCertsArgs) error {
 		return err
 	}
 	for _, cert := range certList {
-		_, err := client.IssueOrRenewCert(cert, args.RenewUnderDays, args.Verbose)
+		v := args.Verbose || printer.DefaultPrinter.Verbose
+		_, err := client.IssueOrRenewCert(cert, args.RenewUnderDays, v)
 		if err != nil {
 			return err
 		}

commands/previewPush.go

@@ -78,12 +78,12 @@ func (args *PushArgs) flags() []cli.Flag {
 
 // Preview implements the preview subcommand.
 func Preview(args PreviewArgs) error {
-	return run(args, false, false, printer.ConsolePrinter{})
+	return run(args, false, false, printer.DefaultPrinter)
 }
 
 // Push implements the push subcommand.
 func Push(args PushArgs) error {
-	return run(args.PreviewArgs, true, args.Interactive, printer.ConsolePrinter{})
+	return run(args.PreviewArgs, true, args.Interactive, printer.DefaultPrinter)
 }
 
 // run is the main routine common to preview/push
@@ -161,7 +161,7 @@ DomainLoop:
 		fmt.Fprintf(os.Stderr, "##teamcity[buildStatus status='SUCCESS' text='%d corrections']", totalCorrections)
 	}
 	notifier.Done()
-	out.Debugf("Done. %d corrections.\n", totalCorrections)
+	out.Printf("Done. %d corrections.\n", totalCorrections)
 	if anyErrors {
 		return errors.Errorf("Completed with errors")
 	}

pkg/js/js.go

@@ -2,10 +2,10 @@ package js
 
 import (
 	"encoding/json"
-	"fmt"
 	"io/ioutil"
 
 	"github.com/StackExchange/dnscontrol/models"
+	"github.com/StackExchange/dnscontrol/pkg/printer"
 	"github.com/StackExchange/dnscontrol/pkg/transform"
 
 	"github.com/robertkrimen/otto"
@@ -58,7 +58,7 @@ func require(call otto.FunctionCall) otto.Value {
 		throw(call.Otto, "require takes exactly one argument")
 	}
 	file := call.Argument(0).String()
-	fmt.Printf("requiring: %s\n", file)
+	printer.Debugf("requiring: %s\n", file)
 	data, err := ioutil.ReadFile(file)
 	if err != nil {
 		throw(call.Otto, err.Error())

pkg/printer/printer.go

@@ -3,6 +3,7 @@ package printer
 import (
 	"bufio"
 	"fmt"
+	"io"
 	"os"
 	"strings"
 
@@ -25,28 +26,56 @@ type CLI interface {
 // Printer is a simple abstraction for printing data. Can be passed to providers to give simple output capabilities.
 type Printer interface {
 	Debugf(fmt string, args ...interface{})
+	Printf(fmt string, args ...interface{})
 	Warnf(fmt string, args ...interface{})
 }
 
-var reader = bufio.NewReader(os.Stdin)
+// Debugf is called to print/format debug information.
+func Debugf(fmt string, args ...interface{}) {
+	DefaultPrinter.Debugf(fmt, args...)
+}
+
+// Printf is called to print/format information.
+func Printf(fmt string, args ...interface{}) {
+	DefaultPrinter.Printf(fmt, args...)
+}
+
+// Warnf is called to print/format a warning.
+func Warnf(fmt string, args ...interface{}) {
+	DefaultPrinter.Warnf(fmt, args...)
+}
+
+var (
+	// DefaultPrinter is the default Printer, used by Debugf, Printf, and Warnf.
+	DefaultPrinter = &ConsolePrinter{
+		Reader:  bufio.NewReader(os.Stdin),
+		Writer:  os.Stdout,
+		Verbose: false,
+	}
+)
 
 // ConsolePrinter is a handle for the console printer.
-type ConsolePrinter struct{}
+type ConsolePrinter struct {
+	Reader *bufio.Reader
+	Writer io.Writer
+
+	Verbose bool
+}
 
 // StartDomain is called at the start of each domain.
 func (c ConsolePrinter) StartDomain(domain string) {
-	fmt.Printf("******************** Domain: %s\n", domain)
+	fmt.Fprintf(c.Writer, "******************** Domain: %s\n", domain)
 }
 
 // PrintCorrection is called to print/format each correction.
 func (c ConsolePrinter) PrintCorrection(i int, correction *models.Correction) {
-	fmt.Printf("#%d: %s\n", i+1, correction.Msg)
+	fmt.Fprintf(c.Writer, "#%d: %s\n", i+1, correction.Msg)
 }
 
 // PromptToRun prompts the user to see if they want to execute a correction.
 func (c ConsolePrinter) PromptToRun() bool {
-	fmt.Print("Run? (Y/n): ")
+	fmt.Fprint(c.Writer, "Run? (Y/n): ")
-	txt, err := reader.ReadString('\n')
+	txt, err := c.Reader.ReadString('\n')
 	run := true
 	if err != nil {
 		run = false
@@ -56,7 +85,7 @@ func (c ConsolePrinter) PromptToRun() bool {
 		run = false
 	}
 	if !run {
-		fmt.Println("Skipping")
+		fmt.Fprintln(c.Writer, "Skipping")
 	}
 	return run
 }
@@ -64,9 +93,9 @@ func (c ConsolePrinter) PromptToRun() bool {
 // EndCorrection is called at the end of each correction.
 func (c ConsolePrinter) EndCorrection(err error) {
 	if err != nil {
-		fmt.Println("FAILURE!", err)
+		fmt.Fprintln(c.Writer, "FAILURE!", err)
 	} else {
-		fmt.Println("SUCCESS!")
+		fmt.Fprintln(c.Writer, "SUCCESS!")
 	}
 }
 
@@ -76,7 +105,7 @@ func (c ConsolePrinter) StartDNSProvider(provider string, skip bool) {
 	if skip {
 		lbl = " (skipping)\n"
 	}
-	fmt.Printf("----- DNS Provider: %s...%s", provider, lbl)
+	fmt.Fprintf(c.Writer, "----- DNS Provider: %s...%s", provider, lbl)
 }
 
 // StartRegistrar is called at the start of each new registrar.
@@ -85,29 +114,36 @@ func (c ConsolePrinter) StartRegistrar(provider string, skip bool) {
 	if skip {
 		lbl = " (skipping)\n"
 	}
-	fmt.Printf("----- Registrar: %s...%s", provider, lbl)
+	fmt.Fprintf(c.Writer, "----- Registrar: %s...%s", provider, lbl)
 }
 
 // EndProvider is called at the end of each provider.
 func (c ConsolePrinter) EndProvider(numCorrections int, err error) {
 	if err != nil {
-		fmt.Println("ERROR")
+		fmt.Fprintln(c.Writer, "ERROR")
-		fmt.Printf("Error getting corrections: %s\n", err)
+		fmt.Fprintf(c.Writer, "Error getting corrections: %s\n", err)
 	} else {
 		plural := "s"
 		if numCorrections == 1 {
 			plural = ""
 		}
-		fmt.Printf("%d correction%s\n", numCorrections, plural)
+		fmt.Fprintf(c.Writer, "%d correction%s\n", numCorrections, plural)
 	}
 }
 
 // Debugf is called to print/format debug information.
 func (c ConsolePrinter) Debugf(format string, args ...interface{}) {
-	fmt.Printf(format, args...)
+	if c.Verbose {
+		fmt.Fprintf(c.Writer, format, args...)
+	}
+}
+
+// Printf is called to print/format information.
+func (c ConsolePrinter) Printf(format string, args ...interface{}) {
+	fmt.Fprintf(c.Writer, format, args...)
 }
 
 // Warnf is called to print/format a warning.
 func (c ConsolePrinter) Warnf(format string, args ...interface{}) {
-	fmt.Printf("WARNING: "+format, args...)
+	fmt.Fprintf(c.Writer, "WARNING: "+format, args...)
 }

pkg/printer/printer_test.go

@@ -0,0 +1,47 @@
+package printer
+
+import (
+	"bytes"
+	"testing"
+
+	"github.com/stretchr/testify/assert"
+)
+
+// TestDefaultPrinter checks that the DefaultPrinter properly controls output from the package-level
+// Warnf/Printf/Debugf functions.
+func TestDefaultPrinter(t *testing.T) {
+	old := DefaultPrinter
+	defer func() {
+		DefaultPrinter = old
+	}()
+
+	output := &bytes.Buffer{}
+	DefaultPrinter = &ConsolePrinter{
+		Writer:  output,
+		Verbose: true,
+	}
+
+	Warnf("warn\n")
+	Printf("output\n")
+	Debugf("debugging\n")
+	assert.Equal(t, "WARNING: warn\noutput\ndebugging\n", output.String())
+}
+
+func TestVerbose(t *testing.T) {
+	output := &bytes.Buffer{}
+	p := ConsolePrinter{
+		Writer:  output,
+		Verbose: false,
+	}
+
+	// Test that verbose output is suppressed.
+	p.Warnf("a dire warning!\n")
+	p.Printf("output\n")
+	p.Debugf("debugging\n")
+	assert.Equal(t, "WARNING: a dire warning!\noutput\n", output.String())
+
+	// Test that Verbose output can be dynamically enabled.
+	p.Verbose = true
+	p.Debugf("more debugging\n")
+	assert.Equal(t, "WARNING: a dire warning!\noutput\nmore debugging\n", output.String())
+}

providers/activedir/domains.go

@@ -3,12 +3,12 @@ package activedir
 import (
 	"encoding/json"
 	"fmt"
-	"log"
 	"os"
 	"strings"
 	"time"
 
 	"github.com/StackExchange/dnscontrol/models"
+	"github.com/StackExchange/dnscontrol/pkg/printer"
 	"github.com/StackExchange/dnscontrol/providers/diff"
 	"github.com/TomOnTime/utfutil"
 	"github.com/pkg/errors"
@@ -34,7 +34,7 @@ func (c *adProvider) GetDomainCorrections(dc *models.DomainConfig) ([]*models.Co
 
 	dc.Filter(func(r *models.RecordConfig) bool {
 		if r.Type != "A" && r.Type != "CNAME" {
-			log.Printf("WARNING: Active Directory only manages A and CNAME records. Won't consider %s %s", r.Type, r.GetLabelFQDN())
+			printer.Warnf("Active Directory only manages A and CNAME records. Won't consider %s %s\n", r.Type, r.GetLabelFQDN())
 			return false
 		}
 		return true
@@ -81,8 +81,8 @@ func (c *adProvider) readZoneDump(domainname string) ([]byte, error) {
 	// File not found is considered an error.
 	dat, err := utfutil.ReadFile(zoneDumpFilename(domainname), utfutil.WINDOWS)
 	if err != nil {
-		fmt.Println("Powershell to generate zone dump:")
+		printer.Printf("Powershell to generate zone dump:\n")
-		fmt.Println(c.generatePowerShellZoneDump(domainname))
+		printer.Printf("%v\n", c.generatePowerShellZoneDump(domainname))
 	}
 	return dat, err
 }
@@ -135,8 +135,6 @@ func (c *adProvider) powerShellRecord(command string) error {
 }
 
 func (c *adProvider) getExistingRecords(domainname string) ([]*models.RecordConfig, error) {
-	// log.Printf("getExistingRecords(%s)\n", domainname)
-
 	// Get the JSON either from adzonedump or by running a PowerShell script.
 	data, err := c.getRecords(domainname)
 	if err != nil {
@@ -174,7 +172,7 @@ func (r *RecordConfigJson) unpackRecord(origin string) *models.RecordConfig {
 	case "NS", "SOA":
 		return nil
 	default:
-		log.Printf("Warning: Record of type %s found in AD zone. Will be ignored.", rc.Type)
+		printer.Warnf("Record of type %s found in AD zone. Will be ignored.\n", rc.Type)
 		return nil
 	}
 	return &rc

providers/cloudflare/cloudflareProvider.go

@@ -9,6 +9,7 @@ import (
 	"time"
 
 	"github.com/StackExchange/dnscontrol/models"
+	"github.com/StackExchange/dnscontrol/pkg/printer"
 	"github.com/StackExchange/dnscontrol/pkg/transform"
 	"github.com/StackExchange/dnscontrol/providers"
 	"github.com/StackExchange/dnscontrol/providers/diff"
@@ -61,7 +62,7 @@ type CloudflareApi struct {
 }
 
 func labelMatches(label string, matches []string) bool {
-	// log.Printf("DEBUG: labelMatches(%#v, %#v)\n", label, matches)
+	printer.Debugf("DEBUG: labelMatches(%#v, %#v)\n", label, matches)
 	for _, tst := range matches {
 		if label == tst {
 			return true
@@ -106,7 +107,7 @@ func (c *CloudflareApi) GetDomainCorrections(dc *models.DomainConfig) ([]*models
 		rec := records[i]
 		// Delete ignore labels
 		if labelMatches(dnsutil.TrimDomainName(rec.Original.(*cfRecord).Name, dc.Name), c.ignoredLabels) {
-			fmt.Printf("ignored_label: %s\n", rec.Original.(*cfRecord).Name)
+			printer.Debugf("ignored_label: %s\n", rec.Original.(*cfRecord).Name)
 			records = append(records[:i], records[i+1:]...)
 		}
 	}
@@ -183,7 +184,7 @@ func checkNSModifications(dc *models.DomainConfig) {
 	for _, rec := range dc.Records {
 		if rec.Type == "NS" && rec.GetLabelFQDN() == dc.Name {
 			if !strings.HasSuffix(rec.GetTargetField(), ".ns.cloudflare.com.") {
-				log.Printf("Warning: cloudflare does not support modifying NS records on base domain. %s will not be added.", rec.GetTargetField())
+				printer.Warnf("cloudflare does not support modifying NS records on base domain. %s will not be added.\n", rec.GetTargetField())
 			}
 			continue
 		}
@@ -327,7 +328,7 @@ func newCloudflare(m map[string]string, metadata json.RawMessage) (providers.DNS
 			api.ignoredLabels = append(api.ignoredLabels, l)
 		}
 		if len(api.ignoredLabels) > 0 {
-			log.Println("Warning: Cloudflare 'ignored_labels' configuration is deprecated and might be removed. Please use the IGNORE domain directive to achieve the same effect.")
+			printer.Warnf("Cloudflare 'ignored_labels' configuration is deprecated and might be removed. Please use the IGNORE domain directive to achieve the same effect.\n")
 		}
 		// parse provider level metadata
 		if len(parsedMeta.IPConversions) > 0 {

providers/diff/diff.go

@@ -2,10 +2,10 @@ package diff
 
 import (
 	"fmt"
-	"log"
 	"sort"
 
 	"github.com/StackExchange/dnscontrol/models"
+	"github.com/StackExchange/dnscontrol/pkg/printer"
 )
 
 // Correlation stores a difference between two domains.
@@ -73,7 +73,7 @@ func (d *differ) IncrementalDiff(existing []*models.RecordConfig) (unchanged, cr
 	desiredByNameAndType := map[models.RecordKey][]*models.RecordConfig{}
 	for _, e := range existing {
 		if d.matchIgnored(e.GetLabel()) {
-			log.Printf("Ignoring record %s %s due to IGNORE", e.GetLabel(), e.Type)
+			printer.Debugf("Ignoring record %s %s due to IGNORE\n", e.GetLabel(), e.Type)
 		} else {
 			k := e.Key()
 			existingByNameAndType[k] = append(existingByNameAndType[k], e)
@@ -91,7 +91,7 @@ func (d *differ) IncrementalDiff(existing []*models.RecordConfig) (unchanged, cr
 	if d.dc.KeepUnknown {
 		for k := range existingByNameAndType {
 			if _, ok := desiredByNameAndType[k]; !ok {
-				log.Printf("Ignoring record set %s %s due to NO_PURGE", k.Type, k.NameFQDN)
+				printer.Debugf("Ignoring record set %s %s due to NO_PURGE\n", k.Type, k.NameFQDN)
 				delete(existingByNameAndType, k)
 			}
 		}

providers/gandi/gandiProvider.go

@@ -3,10 +3,10 @@ package gandi
 import (
 	"encoding/json"
 	"fmt"
-	"log"
 	"sort"
 
 	"github.com/StackExchange/dnscontrol/models"
+	"github.com/StackExchange/dnscontrol/pkg/printer"
 	"github.com/StackExchange/dnscontrol/providers"
 	"github.com/StackExchange/dnscontrol/providers/diff"
 	"github.com/pkg/errors"
@@ -92,7 +92,7 @@ func (c *GandiApi) GetDomainCorrections(dc *models.DomainConfig) ([]*models.Corr
 	recordsToKeep := make([]*models.RecordConfig, 0, len(dc.Records))
 	for _, rec := range dc.Records {
 		if rec.TTL < 300 {
-			log.Printf("WARNING: Gandi does not support ttls < 300. Setting %s from %d to 300", rec.GetLabelFQDN(), rec.TTL)
+			printer.Warnf("Gandi does not support ttls < 300. Setting %s from %d to 300\n", rec.GetLabelFQDN(), rec.TTL)
 			rec.TTL = 300
 		}
 		if rec.TTL > 2592000 {
@@ -103,7 +103,7 @@ func (c *GandiApi) GetDomainCorrections(dc *models.DomainConfig) ([]*models.Corr
 		}
 		if rec.Type == "NS" && rec.GetLabel() == "@" {
 			if !strings.HasSuffix(rec.GetTargetField(), ".gandi.net.") {
-				log.Printf("WARNING: Gandi does not support changing apex NS records. %s will not be added.", rec.GetTargetField())
+				printer.Warnf("Gandi does not support changing apex NS records. %s will not be added.\n", rec.GetTargetField())
 			}
 			continue
 		}
@@ -147,7 +147,7 @@ func (c *GandiApi) GetDomainCorrections(dc *models.DomainConfig) ([]*models.Corr
 			&models.Correction{
 				Msg: msg,
 				F: func() error {
-					fmt.Printf("CREATING ZONE: %v\n", dc.Name)
+					printer.Printf("CREATING ZONE: %v\n", dc.Name)
 					return c.createGandiZone(dc.Name, domaininfo.ZoneId, expectedRecordSets)
 				},
 			})

providers/gandi/livedns.go

@@ -3,11 +3,11 @@ package gandi
 import (
 	"encoding/json"
 	"fmt"
-	"log"
 	"strings"
 	"time"
 
 	"github.com/StackExchange/dnscontrol/models"
+	"github.com/StackExchange/dnscontrol/pkg/printer"
 	"github.com/StackExchange/dnscontrol/providers"
 	"github.com/StackExchange/dnscontrol/providers/diff"
 	"github.com/google/uuid"
@@ -18,9 +18,6 @@ import (
 	gandilivezone "github.com/prasmussen/gandi-api/live_dns/zone"
 )
 
-// Enable/disable debug output:
-const debug = false
-
 var liveFeatures = providers.DocumentationNotes{
 	providers.CanUseCAA:              providers.Can(),
 	providers.CanUsePTR:              providers.Can(),
@@ -131,9 +128,8 @@ func (c *liveClient) createZone(domainname string, records []*gandiliverecord.In
 		return err
 	}
 	infos.Name = fmt.Sprintf("zone created by dnscontrol for %s on %s", domainname, time.Now().Format(time.RFC3339))
-	if debug {
+	printer.Debugf("DEBUG: createZone SharingID=%v\n", infos.SharingID)
-		fmt.Printf("DEBUG: createZone SharingID=%v\n", infos.SharingID)
+
-	}
 	// duplicate zone Infos
 	status, err := c.zoneManager.Create(*infos)
 	if err != nil {
@@ -143,7 +139,7 @@ func (c *liveClient) createZone(domainname string, records []*gandiliverecord.In
 	if err != nil {
 		// gandi might take some time to make the new zone available
 		for i := 0; i < 10; i++ {
-			log.Printf("INFO: zone info not yet available. Delay and retry: %s", err.Error())
+			printer.Printf("zone info not yet available. Delay and retry: %s\n", err.Error())
 			time.Sleep(100 * time.Millisecond)
 			zoneInfos, err = c.zoneManager.InfoByUUID(*status.UUID)
 			if err == nil {
@@ -223,7 +219,7 @@ func (c *liveClient) recordsToInfo(records models.Records) (models.Records, []*g
 
 	for _, rec := range records {
 		if rec.TTL < 300 {
-			log.Printf("WARNING: Gandi does not support ttls < 300. %s will not be set to %d.", rec.GetLabelFQDN(), rec.TTL)
+			printer.Warnf("Gandi does not support ttls < 300. %s will not be set to %d.\n", rec.GetLabelFQDN(), rec.TTL)
 			rec.TTL = 300
 		}
 		if rec.TTL > 2592000 {
@@ -231,7 +227,7 @@ func (c *liveClient) recordsToInfo(records models.Records) (models.Records, []*g
 		}
 		if rec.Type == "NS" && rec.GetLabel() == "@" {
 			if !strings.HasSuffix(rec.GetTargetField(), ".gandi.net.") {
-				log.Printf("WARNING: Gandi does not support changing apex NS records. %s will not be added.", rec.GetTargetField())
+				printer.Warnf("Gandi does not support changing apex NS records. %s will not be added.\n", rec.GetTargetField())
 			}
 			continue
 		}
@@ -250,8 +246,8 @@ func (c *liveClient) recordsToInfo(records models.Records) (models.Records, []*g
 			recordSets[rec.GetLabel()][rec.Type] = r
 		} else {
 			if r.TTL != int64(rec.TTL) {
-				log.Printf(
+				printer.Warnf(
-					"WARNING: Gandi liveDNS API does not support different TTL for the couple fqdn/type. Will use TTL of %d for %s %s",
+					"Gandi liveDNS API does not support different TTL for the couple fqdn/type. Will use TTL of %d for %s %s\n",
 					r.TTL,
 					r.Type,
 					r.Name,

providers/namecheap/namecheapProvider.go

@@ -3,7 +3,6 @@ package namecheap
 import (
 	"encoding/json"
 	"fmt"
-	"log"
 	"sort"
 	"strings"
 	"time"
@@ -11,6 +10,7 @@ import (
 	"golang.org/x/net/publicsuffix"
 
 	"github.com/StackExchange/dnscontrol/models"
+	"github.com/StackExchange/dnscontrol/pkg/printer"
 	"github.com/StackExchange/dnscontrol/providers"
 	"github.com/StackExchange/dnscontrol/providers/diff"
 	nc "github.com/billputer/go-namecheap"
@@ -98,7 +98,7 @@ func doWithRetry(f func() error) {
 			if currentRetry >= maxRetries {
 				return
 			}
-			log.Printf("Namecheap rate limit exceeded. Waiting %s to retry.", sleepTime)
+			printer.Printf("Namecheap rate limit exceeded. Waiting %s to retry.\n", sleepTime)
 			time.Sleep(sleepTime)
 		} else {
 			return