ipn/ipnlocal, wgengine/magicsock, logpolicy: quiet more logs

Updates #1548

Change-Id: Ied169f872e93be2857890211f2e018307d4aeadc
Signed-off-by: Brad Fitzpatrick <bradfitz@tailscale.com>

ipn/ipnlocal/local.go

@@ -607,7 +607,7 @@ func (b *LocalBackend) setClientStatus(st controlclient.Status) {
 			if strings.TrimSpace(diff) == "" {
 				b.logf("[v1] netmap diff: (none)")
 			} else {
-				b.logf("netmap diff:\n%v", diff)
+				b.logf("[v1] netmap diff:\n%v", diff)
 			}
 		}
 

logpolicy/logpolicy.go

@@ -571,6 +571,16 @@ func New(collection string) *Policy {
 	}
 }
 
+// dialLog is used by NewLogtailTransport to log the happy path of its
+// own dialing.
+//
+// By default it goes nowhere and is only enabled when
+// tailscaled's in verbose mode.
+//
+// log.Printf isn't used so its own logs don't loop back into logtail
+// in the happy path, thus generating more logs.
+var dialLog = log.New(io.Discard, "logtail: ", log.LstdFlags|log.Lmsgprefix)
+
 // SetVerbosityLevel controls the verbosity level that should be
 // written to stderr. 0 is the default (not verbose). Levels 1 or higher
 // are increasingly verbose.
@@ -578,6 +588,9 @@ func New(collection string) *Policy {
 // It should not be changed concurrently with log writes.
 func (p *Policy) SetVerbosityLevel(level int) {
 	p.Logtail.SetVerbosityLevel(level)
+	if level > 0 {
+		dialLog.SetOutput(os.Stderr)
+	}
 }
 
 // Close immediately shuts down the logger.
@@ -624,7 +637,7 @@ func NewLogtailTransport(host string) *http.Transport {
 		c, err := nd.DialContext(ctx, netw, addr)
 		d := time.Since(t0).Round(time.Millisecond)
 		if err == nil {
-			log.Printf("logtail: dialed %q in %v", addr, d)
+			dialLog.Printf("dialed %q in %v", addr, d)
 			return c, nil
 		}
 
@@ -637,10 +650,10 @@ func NewLogtailTransport(host string) *http.Transport {
 					err = errors.New(res.Status)
 				}
 				if err != nil {
-					log.Printf("logtail: CONNECT response from tailscaled: %v", err)
+					log.Printf("logtail: CONNECT response error from tailscaled: %v", err)
 					c.Close()
 				} else {
-					log.Printf("logtail: connected via tailscaled")
+					dialLog.Printf("connected via tailscaled")
 					return c, nil
 				}
 			}

wgengine/magicsock/magicsock.go

@@ -2111,12 +2111,12 @@ func (c *Conn) enqueueCallMeMaybe(derpAddr netaddr.IPPort, de *endpoint) {
 	defer c.mu.Unlock()
 
 	if !c.lastEndpointsTime.After(time.Now().Add(-endpointsFreshEnoughDuration)) {
-		c.logf("magicsock: want call-me-maybe but endpoints stale; restunning")
+		c.logf("[v1] magicsock: want call-me-maybe but endpoints stale; restunning")
 		if c.onEndpointRefreshed == nil {
 			c.onEndpointRefreshed = map[*endpoint]func(){}
 		}
 		c.onEndpointRefreshed[de] = func() {
-			c.logf("magicsock: STUN done; sending call-me-maybe to %v %v", de.discoShort, de.publicKey.ShortString())
+			c.logf("[v1] magicsock: STUN done; sending call-me-maybe to %v %v", de.discoShort, de.publicKey.ShortString())
 			c.enqueueCallMeMaybe(derpAddr, de)
 		}
 		// TODO(bradfitz): make a new 'reSTUNQuickly' method