Add debug log flag

Author: dennis-tra

cmd/pcp/pcp.go

@@ -42,6 +42,18 @@ func main() {
 			receive.Command,
 			send.Command,
 		},
+		Before: func(c *cli.Context) error {
+			if c.Bool("debug") {
+				log.SetLevel(log.DebugLevel)
+			}
+			return nil
+		},
+		Flags: []cli.Flag{
+			&cli.BoolFlag{
+				Name:  "debug",
+				Usage: "enables debug log output",
+			},
+		},
 	}
 
 	sigs := make(chan os.Signal, 1)

internal/log/log.go

@@ -5,17 +5,35 @@ import (
 	"io"
 	"os"
 	"strings"
+	"time"
 
 	"golang.org/x/crypto/ssh/terminal"
 )
 
+type Level uint8
+
+const (
+	DebugLevel Level = iota
+	InfoLevel
+	WarningLevel
+	ErrorLevel
+)
+
+var level Level
+
+func SetLevel(l Level) {
+	level = l
+}
+
 // Out represents the writer to print the log messages to.
 // This is used for tests.
 var Out io.Writer = os.Stderr
 
 var tWidth int
 
 func init() {
+	level = InfoLevel
+
 	var err error
 	tWidth, _, err = terminal.GetSize(int(os.Stdout.Fd()))
 	if err != nil {
@@ -26,55 +44,111 @@ func init() {
 	}
 }
 
+func printTimestamp() {
+	if level > DebugLevel {
+		return
+	}
+	fmt.Printf("[%s] ", time.Now().Format(time.RFC3339))
+}
+
 func Info(a ...interface{}) {
+	if level > InfoLevel {
+		return
+	}
+	printTimestamp()
 	fmt.Fprint(Out, a...)
 }
 
 func Infoln(a ...interface{}) {
+	if level > InfoLevel {
+		return
+	}
+	printTimestamp()
 	fmt.Fprintln(Out, a...)
 }
 
 func Infor(format string, a ...interface{}) {
-	blank := fmt.Sprintf("\r%s\r", strings.Repeat(" ", tWidth))
-	fmt.Fprint(Out, fmt.Sprintf("%s%s", blank, fmt.Sprintf(format, a...)))
+	if level > InfoLevel {
+		return
+	}
+
+	if level > DebugLevel {
+		blank := fmt.Sprintf("\r%s\r", strings.Repeat(" ", tWidth))
+		printTimestamp()
+		fmt.Fprint(Out, fmt.Sprintf("%s%s", blank, fmt.Sprintf(format, a...)))
+	} else {
+		printTimestamp()
+		fmt.Fprintln(Out, fmt.Sprintf(format, a...))
+	}
 }
 
 func Infof(format string, a ...interface{}) {
+	if level > InfoLevel {
+		return
+	}
+	printTimestamp()
 	fmt.Fprintf(Out, format, a...)
 }
 
 func Debug(a ...interface{}) {
+	if level > DebugLevel {
+		return
+	}
+	printTimestamp()
 	fmt.Fprint(Out, a...)
 }
 
 func Debugln(a ...interface{}) {
+	if level > DebugLevel {
+		return
+	}
+	printTimestamp()
 	fmt.Fprintln(Out, a...)
 }
 
 func Debugf(format string, a ...interface{}) {
+	if level > DebugLevel {
+		return
+	}
+	printTimestamp()
 	fmt.Fprintf(Out, format, a...)
 }
 
 func Warning(a ...interface{}) {
+	if level > WarningLevel {
+		return
+	}
+	printTimestamp()
 	fmt.Fprint(Out, a...)
 }
 
 func Warningln(a ...interface{}) {
+	if level > WarningLevel {
+		return
+	}
+	printTimestamp()
 	fmt.Fprintln(Out, a...)
 }
 
 func Warningf(format string, a ...interface{}) {
+	if level > WarningLevel {
+		return
+	}
+	printTimestamp()
 	fmt.Fprintf(Out, format, a...)
 }
 
 func Error(a ...interface{}) {
+	printTimestamp()
 	fmt.Fprint(Out, a...)
 }
 
 func Errorln(a ...interface{}) {
+	printTimestamp()
 	fmt.Fprintln(Out, a...)
 }
 
 func Errorf(format string, a ...interface{}) {
+	printTimestamp()
 	fmt.Fprintf(Out, format, a...)
 }

pkg/dht/advertiser.go

@@ -53,6 +53,7 @@ func (a *Advertiser) Advertise(chanID int) error {
 	}
 	defer a.ServiceStopped()
 
+	log.Debugln("DHT - Waiting for public IP...")
 	for {
 		// Only advertise in the DHT if we have a public addr.
 		if !a.HasPublicAddr() {
@@ -63,7 +64,11 @@ func (a *Advertiser) Advertise(chanID int) error {
 				continue
 			}
 		}
+		log.Debugln("DHT - Identified a public IP in", a.Addrs())
+		break
+	}
 
+	for {
 		err := a.provide(a.ServiceContext(), a.DiscoveryID(chanID))
 		if err == context.Canceled {
 			break
@@ -97,6 +102,8 @@ func (a *Advertiser) Shutdown() {
 // closest peers to the key/CID before it goes on to provide the record to them.
 // Not setting a timeout here will make the DHT wander forever.
 func (a *Advertiser) provide(ctx context.Context, id string) error {
+	log.Debugln("DHT - Advertising", id)
+	defer log.Debugln("DHT - Advertising", id, "done")
 	cID, err := strToCid(id)
 	if err != nil {
 		return err

pkg/dht/discoverer.go

@@ -4,6 +4,8 @@ import (
 	"context"
 	"time"
 
+	"github.com/dennis-tra/pcp/internal/log"
+
 	"github.com/libp2p/go-libp2p-core/host"
 	"github.com/libp2p/go-libp2p-core/peer"
 	ma "github.com/multiformats/go-multiaddr"
@@ -36,19 +38,23 @@ func (d *Discoverer) Discover(chanID int, handler func(info peer.AddrInfo)) erro
 	}
 
 	for {
-		cID, err := strToCid(d.DiscoveryID(chanID))
+		did := d.DiscoveryID(chanID)
+		log.Debugln("DHT - Discovering ", did)
+		cID, err := strToCid(did)
 		if err != nil {
 			return err
 		}
 
 		// Find new provider with a timeout, so the discovery ID is renewed if necessary.
 		ctx, cancel := context.WithTimeout(d.ServiceContext(), provideTimeout)
 		for pi := range d.dht.FindProvidersAsync(ctx, cID, 100) {
+			log.Debugln("DHT - Found peer ", pi.ID)
 			pi.Addrs = onlyPublic(pi.Addrs)
 			if isRoutable(pi) {
 				go handler(pi)
 			}
 		}
+		log.Debugln("DHT - Discovering", did, " done.")
 
 		// cannot defer cancel in this for loop
 		cancel()
@@ -76,6 +82,9 @@ func onlyPublic(addrs []ma.Multiaddr) []ma.Multiaddr {
 	for _, addr := range addrs {
 		if manet.IsPublicAddr(addr) {
 			routable = append(routable, addr)
+			log.Debugf("\tpublic - %s\n", addr.String())
+		} else {
+			log.Debugf("\tprivate - %s\n", addr.String())
 		}
 	}
 	return routable

pkg/dht/protocol.go

@@ -48,7 +48,7 @@ type protocol struct {
 
 func newProtocol(h host.Host, dht wrap.IpfsDHT) *protocol {
 	bootstrap[h.ID()] = &sync.Once{}
-	return &protocol{Host: h, dht: dht, Service: service.New()}
+	return &protocol{Host: h, dht: dht, Service: service.New("DHT")}
 }
 
 // Bootstrap connects to a set of bootstrap nodes to connect

pkg/mdns/advertiser.go

@@ -4,6 +4,8 @@ import (
 	"context"
 	"time"
 
+	"github.com/dennis-tra/pcp/internal/log"
+
 	"github.com/libp2p/go-libp2p-core/host"
 	"github.com/libp2p/go-libp2p/p2p/discovery"
 )
@@ -26,17 +28,22 @@ func (a *Advertiser) Advertise(chanID int) error {
 	defer a.ServiceStopped()
 
 	for {
+		did := a.DiscoveryID(chanID)
+		log.Debugln("mDNS - Advertising ", did)
 		ctx, cancel := context.WithTimeout(a.ServiceContext(), time.Minute)
-		mdns, err := discovery.NewMdnsService(ctx, a, a.interval, a.DiscoveryID(chanID))
+		mdns, err := discovery.NewMdnsService(ctx, a, a.interval, did)
 		if err != nil {
+			cancel()
 			return err
 		}
 
 		select {
 		case <-a.SigShutdown():
+			log.Debugln("mDNS - Advertising", did, " done - shutdown signal")
 			cancel()
 			return mdns.Close()
 		case <-ctx.Done():
+			log.Debugln("mDNS - Advertising", did, "done -", ctx.Err())
 			cancel()
 			if ctx.Err() == context.DeadlineExceeded {
 				_ = mdns.Close()

pkg/mdns/discoverer.go

@@ -32,16 +32,19 @@ func (d *Discoverer) Discover(chanID int, handler func(info peer.AddrInfo)) erro
 		entriesCh := make(chan *mdns.ServiceEntry, 16)
 		go d.drainEntriesChan(entriesCh, handler)
 
+		did := d.DiscoveryID(chanID)
+		log.Debugln("mDNS - Discovering", did)
 		qp := &mdns.QueryParam{
 			Domain:  "local",
 			Entries: entriesCh,
-			Service: d.DiscoveryID(chanID),
+			Service: did,
 			Timeout: time.Second * 5,
 		}
 
 		err := mdns.Query(qp)
+		log.Debugln("mDNS - Discovering", did, " done.")
 		if err != nil {
-			log.Warningln("mdns lookup error", err)
+			log.Warningln("mDNS - query error", err)
 		}
 		close(entriesCh)
 
@@ -65,6 +68,8 @@ func (d *Discoverer) drainEntriesChan(entries chan *mdns.ServiceEntry, handler f
 			continue
 		}
 
+		log.Debugln("mDNS - Found peer", pi.ID)
+
 		if pi.ID == d.ID() {
 			continue
 		}
@@ -114,6 +119,9 @@ func onlyPrivate(addrs []ma.Multiaddr) []ma.Multiaddr {
 	for _, addr := range addrs {
 		if manet.IsPrivateAddr(addr) {
 			routable = append(routable, addr)
+			log.Debugf("\tprivate - %s\n", addr.String())
+		} else {
+			log.Debugf("\tpublic - %s\n", addr.String())
 		}
 	}
 	return routable

pkg/mdns/protocol.go

@@ -32,7 +32,7 @@ func newProtocol(h host.Host) *protocol {
 	return &protocol{
 		Host:     h,
 		interval: time.Second,
-		Service:  service.New(),
+		Service:  service.New("mDNS"),
 	}
 }