Make discovery logging a bit better (fixes #1188)

internal/discover/client_udp.go

@@ -94,7 +94,7 @@ func (d *UDPClient) broadcast(pkt []byte) {
 
 	conn, err := net.ListenUDP(d.url.Scheme, d.listenAddress)
 	for err != nil {
-		l.Warnf("Global UDP discovery (%s): %v; trying again in %v", d.url, err, d.errorRetryInterval)
+		l.Warnf("discover %s: broadcast: %v; trying again in %v", d.url, err, d.errorRetryInterval)
 		select {
 		case <-d.stop:
 			return
@@ -106,7 +106,7 @@ func (d *UDPClient) broadcast(pkt []byte) {
 
 	remote, err := net.ResolveUDPAddr(d.url.Scheme, d.url.Host)
 	for err != nil {
-		l.Warnf("Global UDP discovery (%s): %v; trying again in %v", d.url, err, d.errorRetryInterval)
+		l.Warnf("discover %s: broadcast: %v; trying again in %v", d.url, err, d.errorRetryInterval)
 		select {
 		case <-d.stop:
 			return
@@ -125,13 +125,13 @@ func (d *UDPClient) broadcast(pkt []byte) {
 			var ok bool
 
 			if debug {
-				l.Debugf("Global UDP discovery (%s): send announcement -> %v\n%s", d.url, remote, hex.Dump(pkt))
+				l.Debugf("discover %s: broadcast: Sending self announcement to %v", d.url, remote)
 			}
 
 			_, err := conn.WriteTo(pkt, remote)
 			if err != nil {
 				if debug {
-					l.Debugf("discover %s: warning: %s", d.url, err)
+					l.Debugf("discover %s: broadcast: Failed to send self announcement: %s", d.url, err)
 				}
 				ok = false
 			} else {
@@ -141,7 +141,7 @@ func (d *UDPClient) broadcast(pkt []byte) {
 
 				res := d.Lookup(d.id)
 				if debug {
-					l.Debugf("discover %s: external lookup check: %v", d.url, res)
+					l.Debugf("discover %s: broadcast: Self-lookup returned: %v", d.url, res)
 				}
 				ok = len(res) > 0
 			}
@@ -163,7 +163,7 @@ func (d *UDPClient) Lookup(device protocol.DeviceID) []string {
 	extIP, err := net.ResolveUDPAddr(d.url.Scheme, d.url.Host)
 	if err != nil {
 		if debug {
-			l.Debugf("discover %s: %v; no external lookup", d.url, err)
+			l.Debugf("discover %s: Lookup(%s): %s", d.url, device, err)
 		}
 		return nil
 	}
@@ -171,7 +171,7 @@ func (d *UDPClient) Lookup(device protocol.DeviceID) []string {
 	conn, err := net.DialUDP(d.url.Scheme, d.listenAddress, extIP)
 	if err != nil {
 		if debug {
-			l.Debugf("discover %s: %v; no external lookup", d.url, err)
+			l.Debugf("discover %s: Lookup(%s): %s", d.url, device, err)
 		}
 		return nil
 	}
@@ -180,7 +180,7 @@ func (d *UDPClient) Lookup(device protocol.DeviceID) []string {
 	err = conn.SetDeadline(time.Now().Add(5 * time.Second))
 	if err != nil {
 		if debug {
-			l.Debugf("discover %s: %v; no external lookup", d.url, err)
+			l.Debugf("discover %s: Lookup(%s): %s", d.url, device, err)
 		}
 		return nil
 	}
@@ -189,7 +189,7 @@ func (d *UDPClient) Lookup(device protocol.DeviceID) []string {
 	_, err = conn.Write(buf)
 	if err != nil {
 		if debug {
-			l.Debugf("discover %s: %v; no external lookup", d.url, err)
+			l.Debugf("discover %s: Lookup(%s): %s", d.url, device, err)
 		}
 		return nil
 	}
@@ -202,20 +202,16 @@ func (d *UDPClient) Lookup(device protocol.DeviceID) []string {
 			return nil
 		}
 		if debug {
-			l.Debugf("discover %s: %v; no external lookup", d.url, err)
+			l.Debugf("discover %s: Lookup(%s): %s", d.url, device, err)
 		}
 		return nil
 	}
 
-	if debug {
-		l.Debugf("discover %s: read external:\n%s", d.url, hex.Dump(buf[:n]))
-	}
-
 	var pkt Announce
 	err = pkt.UnmarshalXDR(buf[:n])
 	if err != nil && err != io.EOF {
 		if debug {
-			l.Debugln("discover %s:", d.url, err)
+			l.Debugf("discover %s: Lookup(%s): %s\n%s", d.url, device, err, hex.Dump(buf[:n]))
 		}
 		return nil
 	}
@@ -225,6 +221,9 @@ func (d *UDPClient) Lookup(device protocol.DeviceID) []string {
 		deviceAddr := net.JoinHostPort(net.IP(a.IP).String(), strconv.Itoa(int(a.Port)))
 		addrs = append(addrs, deviceAddr)
 	}
+	if debug {
+		l.Debugf("discover %s: Lookup(%s) result: %v", d.url, device, addrs)
+	}
 	return addrs
 }
 

internal/discover/discover.go

@@ -72,7 +72,7 @@ func (d *Discoverer) StartLocal(localPort int, localMCAddr string) {
 		bb, err := beacon.NewBroadcast(localPort)
 		if err != nil {
 			if debug {
-				l.Debugln(err)
+				l.Debugln("discover: Start local v4:", err)
 			}
 			l.Infoln("Local discovery over IPv4 unavailable")
 		} else {
@@ -85,7 +85,7 @@ func (d *Discoverer) StartLocal(localPort int, localMCAddr string) {
 		mb, err := beacon.NewMulticast(localMCAddr)
 		if err != nil {
 			if debug {
-				l.Debugln(err)
+				l.Debugln("discover: Start local v6:", err)
 			}
 			l.Infoln("Local discovery over IPv6 unavailable")
 		} else {
@@ -247,10 +247,10 @@ func (d *Discoverer) announcementPkt() *Announce {
 		for _, astr := range d.listenAddrs {
 			addr, err := net.ResolveTCPAddr("tcp", astr)
 			if err != nil {
-				l.Warnln("%v: not announcing %s", err, astr)
+				l.Warnln("discover: %v: not announcing %s", err, astr)
 				continue
 			} else if debug {
-				l.Debugf("discover: announcing %s: %#v", astr, addr)
+				l.Debugf("discover: resolved %s as %#v", astr, addr)
 			}
 			if len(addr.IP) == 0 || addr.IP.IsUnspecified() {
 				addrs = append(addrs, Address{Port: uint16(addr.Port)})
@@ -295,16 +295,19 @@ func (d *Discoverer) recvAnnouncements(b beacon.Interface) {
 	for {
 		buf, addr := b.Recv()
 
-		if debug {
-			l.Debugf("discover: read announcement from %s:\n%s", addr, hex.Dump(buf))
-		}
-
 		var pkt Announce
 		err := pkt.UnmarshalXDR(buf)
 		if err != nil && err != io.EOF {
+			if debug {
+				l.Debugf("discover: Failed to unmarshal local announcement from %s:\n%s", addr, hex.Dump(buf))
+			}
 			continue
 		}
 
+		if debug {
+			l.Debugf("discover: Received local announcement from %s for %s", addr, protocol.DeviceIDFromBytes(pkt.This.ID))
+		}
+
 		var newDevice bool
 		if bytes.Compare(pkt.This.ID, d.myID[:]) != 0 {
 			newDevice = d.registerDevice(addr, pkt.This)
@@ -352,7 +355,7 @@ func (d *Discoverer) registerDevice(addr net.Addr, device Device) bool {
 	}
 
 	if debug {
-		l.Debugf("discover: register: %v -> %v", id, current)
+		l.Debugf("discover: Caching %s addresses: %v", id, current)
 	}
 
 	d.registry[id] = current
@@ -375,7 +378,7 @@ func (d *Discoverer) filterCached(c []CacheEntry) []CacheEntry {
 	for i := 0; i < len(c); {
 		if ago := time.Since(c[i].Seen); ago > d.cacheLifetime {
 			if debug {
-				l.Debugf("removing cached address %s: seen %v ago", c[i].Address, ago)
+				l.Debugf("discover: Removing cached address %s - seen %v ago", c[i].Address, ago)
 			}
 			c[i] = c[len(c)-1]
 			c = c[:len(c)-1]