lib/connections, lib/model: Additional connection info in logs (fixes #4499)

GitHub-Pull-Request: https://github.com/syncthing/syncthing/pull/4665

lib/connections/service.go

@@ -163,7 +163,7 @@ next:
 		// because there are implementations out there that don't support
 		// protocol negotiation (iOS for one...).
 		if !cs.NegotiatedProtocolIsMutual || cs.NegotiatedProtocol != s.bepProtocolName {
-			l.Infof("Peer %s did not negotiate bep/1.0", c.RemoteAddr())
+			l.Infof("Peer at %s did not negotiate bep/1.0", c)
 		}
 
 		// We should have received exactly one certificate from the other
@@ -171,7 +171,7 @@ next:
 		// connection.
 		certs := cs.PeerCertificates
 		if cl := len(certs); cl != 1 {
-			l.Infof("Got peer certificate list of length %d != 1 from %s; protocol error", cl, c.RemoteAddr())
+			l.Infof("Got peer certificate list of length %d != 1 from peer at %s; protocol error", cl, c)
 			c.Close()
 			continue
 		}
@@ -182,7 +182,7 @@ next:
 		// though, especially in the presence of NAT hairpinning, multiple
 		// clients between the same NAT gateway, and global discovery.
 		if remoteID == s.myID {
-			l.Infof("Connected to myself (%s) - should not happen", remoteID)
+			l.Infof("Connected to myself (%s) at %s - should not happen", remoteID, c)
 			c.Close()
 			continue
 		}
@@ -206,7 +206,7 @@ next:
 				warningFor(remoteID, msg)
 			} else {
 				// It's something else - connection reset or whatever
-				l.Infof("Failed to exchange Hello messages with %s (%s): %s", remoteID, c.RemoteAddr(), err)
+				l.Infof("Failed to exchange Hello messages with %s at %s: %s", remoteID, c, err)
 			}
 			c.Close()
 			continue
@@ -256,7 +256,7 @@ next:
 			// Incorrect certificate name is something the user most
 			// likely wants to know about, since it's an advanced
 			// config. Warn instead of Info.
-			l.Warnf("Bad certificate from %s (%v): %v", remoteID, c.RemoteAddr(), err)
+			l.Warnf("Bad certificate from %s at %s: %v", remoteID, c, err)
 			c.Close()
 			continue next
 		}
@@ -268,11 +268,10 @@ next:
 		wr := s.limiter.newWriteLimiter(c, isLAN)
 		rd := s.limiter.newReadLimiter(c, isLAN)
 
-		name := fmt.Sprintf("%s-%s (%s)", c.LocalAddr(), c.RemoteAddr(), c.Type())
-		protoConn := protocol.NewConnection(remoteID, rd, wr, s.model, name, deviceCfg.Compression)
+		protoConn := protocol.NewConnection(remoteID, rd, wr, s.model, c.String(), deviceCfg.Compression)
 		modelConn := completeConn{c, protoConn}
 
-		l.Infof("Established secure connection to %s at %s (%s)", remoteID, name, tlsCipherSuiteNames[c.ConnectionState().CipherSuite])
+		l.Infof("Established secure connection to %s at %s (%s)", remoteID, c, tlsCipherSuiteNames[c.ConnectionState().CipherSuite])
 
 		s.model.AddConnection(modelConn, hello)
 		continue next
@@ -779,11 +778,9 @@ func dialParallel(deviceID protocol.DeviceID, dialTargets []dialTarget) (interna
 		}()
 
 		// Wait for the first connection, or for channel closure.
-		conn, ok := <-res
-
+		if conn, ok := <-res; ok {
 			// Got a connection, means more might come back, hence spawn a
 			// routine that will do the discarding.
-		if ok {
 			l.Debugln("connected to", deviceID, prio, "using", conn, conn.priority)
 			go func(deviceID protocol.DeviceID, prio int) {
 				wg.Wait()
@@ -793,10 +790,9 @@ func dialParallel(deviceID protocol.DeviceID, dialTargets []dialTarget) (interna
 				}
 			}(deviceID, prio)
 			return conn, ok
-		} else {
+		}
 		// Failed to connect, report that fact.
 		l.Debugln("failed to connect to", deviceID, prio)
 	}
-	}
 	return internalConn{}, false
 }

lib/connections/structs.go

@@ -28,6 +28,7 @@ type Connection interface {
 	Transport() string
 	RemoteAddr() net.Addr
 	Priority() int
+	String() string
 }
 
 // completeConn is the aggregation of an internalConn and the
@@ -114,7 +115,7 @@ func (c internalConn) Transport() string {
 }
 
 func (c internalConn) String() string {
-	return fmt.Sprintf("%s-%s/%s", c.LocalAddr(), c.RemoteAddr(), c.connType.String())
+	return fmt.Sprintf("%s-%s/%s", c.LocalAddr(), c.RemoteAddr(), c.Type())
 }
 
 type dialerFactory interface {

lib/model/model.go

@@ -1290,7 +1290,7 @@ func (m *Model) Closed(conn protocol.Connection, err error) {
 	delete(m.closed, device)
 	m.pmut.Unlock()
 
-	l.Infof("Connection to %s closed: %v", device, err)
+	l.Infof("Connection to %s at %s closed: %v", device, conn.Name(), err)
 	events.Default.Log(events.DeviceDisconnected, map[string]string{
 		"id":    device.String(),
 		"error": err.Error(),
@@ -1565,7 +1565,7 @@ func (m *Model) AddConnection(conn connections.Connection, hello protocol.HelloR
 
 	events.Default.Log(events.DeviceConnected, event)
 
-	l.Infof(`Device %s client is "%s %s" named "%s"`, deviceID, hello.ClientName, hello.ClientVersion, hello.DeviceName)
+	l.Infof(`Device %s client is "%s %s" named "%s" at %s`, deviceID, hello.ClientName, hello.ClientVersion, hello.DeviceName, conn)
 
 	conn.Start()
 	m.pmut.Unlock()
@@ -1644,11 +1644,10 @@ func (m *Model) receivedFile(folder string, file protocol.FileInfo) {
 
 func sendIndexes(conn protocol.Connection, folder string, fs *db.FileSet, ignores *ignore.Matcher, startSequence int64, dbLocation string, dropSymlinks bool) {
 	deviceID := conn.ID()
-	name := conn.Name()
 	var err error
 
-	l.Debugf("sendIndexes for %s-%s/%q starting (slv=%d)", deviceID, name, folder, startSequence)
-	defer l.Debugf("sendIndexes for %s-%s/%q exiting: %v", deviceID, name, folder, err)
+	l.Debugf("Starting sendIndexes for %s to %s at %s (slv=%d)", folder, deviceID, conn, startSequence)
+	defer l.Debugf("Exiting sendIndexes for %s to %s at %s: %v", folder, deviceID, conn, err)
 
 	minSequence, err := sendIndexTo(startSequence, conn, folder, fs, ignores, dbLocation, dropSymlinks)
 
@@ -1684,12 +1683,14 @@ func sendIndexes(conn protocol.Connection, folder string, fs *db.FileSet, ignore
 
 func sendIndexTo(minSequence int64, conn protocol.Connection, folder string, fs *db.FileSet, ignores *ignore.Matcher, dbLocation string, dropSymlinks bool) (int64, error) {
 	deviceID := conn.ID()
-	name := conn.Name()
 	batch := make([]protocol.FileInfo, 0, maxBatchSizeFiles)
 	batchSizeBytes := 0
 	initial := minSequence == 0
 	maxSequence := minSequence
 	var err error
+	debugMsg := func(t string) string {
+		return fmt.Sprintf("Sending indexes for %s to %s at %s: %d files (<%d bytes) (%s)", folder, deviceID, conn, len(batch), batchSizeBytes, t)
+	}
 
 	sorter := NewIndexSorter(dbLocation)
 	defer sorter.Close()
@@ -1722,13 +1723,13 @@ func sendIndexTo(minSequence int64, conn protocol.Connection, folder string, fs
 				if err = conn.Index(folder, batch); err != nil {
 					return false
 				}
-				l.Debugf("sendIndexes for %s-%s/%q: %d files (<%d bytes) (initial index)", deviceID, name, folder, len(batch), batchSizeBytes)
+				l.Debugln(debugMsg("initial index"))
 				initial = false
 			} else {
 				if err = conn.IndexUpdate(folder, batch); err != nil {
 					return false
 				}
-				l.Debugf("sendIndexes for %s-%s/%q: %d files (<%d bytes) (batched update)", deviceID, name, folder, len(batch), batchSizeBytes)
+				l.Debugln(debugMsg("batched update"))
 			}
 
 			batch = make([]protocol.FileInfo, 0, maxBatchSizeFiles)
@@ -1743,12 +1744,12 @@ func sendIndexTo(minSequence int64, conn protocol.Connection, folder string, fs
 	if initial && err == nil {
 		err = conn.Index(folder, batch)
 		if err == nil {
-			l.Debugf("sendIndexes for %s-%s/%q: %d files (small initial index)", deviceID, name, folder, len(batch))
+			l.Debugln(debugMsg("small initial index"))
 		}
 	} else if len(batch) > 0 && err == nil {
 		err = conn.IndexUpdate(folder, batch)
 		if err == nil {
-			l.Debugf("sendIndexes for %s-%s/%q: %d files (last batch)", deviceID, name, folder, len(batch))
+			l.Debugln(debugMsg("last batch"))
 		}
 	}
 

lib/model/model_test.go

@@ -288,6 +288,10 @@ func (f *fakeConnection) Name() string {
 	return ""
 }
 
+func (f *fakeConnection) String() string {
+	return ""
+}
+
 func (f *fakeConnection) Option(string) string {
 	return ""
 }