add unique connection ID to debug logs (#2207)

Fixes #2206

default.yaml

@@ -776,7 +776,7 @@ logging:
         # be logged, even if you explicitly include it
         #
         # useful types include:
-        #   *               everything (usually used with exclusing some types below)
+        #   *               everything (usually used with excluding some types below)
         #   server          server startup, rehash, and shutdown events
         #   accounts        account registration and authentication
         #   channels        channel creation and operations

irc/client.go

@@ -152,6 +152,8 @@ const (
 type Session struct {
 	client *Client
 
+	connID string // identifies the connection in debug logs
+
 	deviceID string
 
 	ctime      time.Time
@@ -334,7 +336,8 @@ func (server *Server) RunClient(conn IRCConn) {
 		return
 	}
 
-	server.logger.Info("connect-ip", fmt.Sprintf("Client connecting: real IP %v, proxied IP %v", realIP, proxiedIP))
+	connID := server.generateConnectionID()
+	server.logger.Info("connect-ip", connID, fmt.Sprintf("Client connecting: real IP %v, proxied IP %v", realIP, proxiedIP))
 
 	now := time.Now().UTC()
 	// give them 1k of grace over the limit:
@@ -374,6 +377,7 @@ func (server *Server) RunClient(conn IRCConn) {
 		proxiedIP:  proxiedIP,
 		isTor:      wConn.Tor,
 		hideSTS:    wConn.Tor || wConn.HideSTS,
+		connID:     connID,
 	}
 	session.sasl.Initialize()
 	client.sessions = []*Session{session}
@@ -670,7 +674,7 @@ func (client *Client) run(session *Session) {
 		}
 
 		if client.server.logger.IsLoggingRawIO() {
-			client.server.logger.Debug("userinput", client.nick, "<- ", line)
+			client.server.logger.Debug("userinput", session.connID, client.nick, "<-", line)
 		}
 
 		// special-cased handling of PROXY protocol, see `handleProxyCommand` for details:
@@ -1287,7 +1291,7 @@ func (client *Client) destroy(session *Session) {
 		if !shouldDestroy {
 			client.server.snomasks.Send(sno.LocalDisconnects, fmt.Sprintf(ircfmt.Unescape("Client session disconnected for [a:%s] [h:%s] [ip:%s]"), details.accountName, session.rawHostname, source))
 		}
-		client.server.logger.Info("connect-ip", fmt.Sprintf("disconnecting session of %s from %s", details.nick, source))
+		client.server.logger.Info("connect-ip", session.connID, fmt.Sprintf("Disconnecting session of %s from %s", details.nick, source))
 	}
 
 	// decrement stats if we have no more sessions, even if the client will not be destroyed
@@ -1497,7 +1501,7 @@ func (session *Session) SendRawMessage(message ircmsg.Message, blocking bool) er
 func (session *Session) sendBytes(line []byte, blocking bool) (err error) {
 	if session.client.server.logger.IsLoggingRawIO() {
 		logline := string(line[:len(line)-2]) // strip "\r\n"
-		session.client.server.logger.Debug("useroutput", session.client.Nick(), " ->", logline)
+		session.client.server.logger.Debug("useroutput", session.connID, session.client.Nick(), "->", logline)
 	}
 
 	if blocking {
@@ -1506,7 +1510,7 @@ func (session *Session) sendBytes(line []byte, blocking bool) (err error) {
 		err = session.socket.Write(line)
 	}
 	if err != nil {
-		session.client.server.logger.Info("quit", "send error to client", fmt.Sprintf("%s [%d]", session.client.Nick(), session.sessionID), err.Error())
+		session.client.server.logger.Info("quit", session.connID, "send error to client", session.client.Nick(), err.Error())
 	}
 	return err
 }

irc/gateways.go

@@ -92,7 +92,7 @@ func (client *Client) ApplyProxiedIP(session *Session, proxiedIP net.IP, tls boo
 	client.server.connectionLimiter.RemoveClient(flatip.FromNetIP(session.realIP))
 
 	// given IP is sane! override the client's current IP
-	client.server.logger.Info("connect-ip", "Accepted proxy IP for client", proxiedIP.String())
+	client.server.logger.Info("connect-ip", session.connID, "Accepted proxy IP for client", proxiedIP.String())
 
 	client.stateMutex.Lock()
 	defer client.stateMutex.Unlock()

irc/getters.go

@@ -54,6 +54,7 @@ type SessionData struct {
 	certfp    string
 	deviceID  string
 	connInfo  string
+	connID    string
 	sessionID int64
 	caps      []string
 }
@@ -74,6 +75,7 @@ func (client *Client) AllSessionData(currentSession *Session, hasPrivs bool) (da
 			hostname:  session.rawHostname,
 			certfp:    session.certfp,
 			deviceID:  session.deviceID,
+			connID:    session.connID,
 			sessionID: session.sessionID,
 		}
 		if session.proxiedIP != nil {

irc/nickserv.go

@@ -1310,23 +1310,26 @@ func nsClientsListHandler(service *ircService, server *Server, client *Client, p
 			service.Notice(rb, fmt.Sprintf(client.t("Client %d:"), session.sessionID))
 		}
 		if session.deviceID != "" {
-			service.Notice(rb, fmt.Sprintf(client.t("Device ID:   %s"), session.deviceID))
+			service.Notice(rb, fmt.Sprintf(client.t("Device ID:    %s"), session.deviceID))
 		}
-		service.Notice(rb, fmt.Sprintf(client.t("IP address:  %s"), session.ip.String()))
-		service.Notice(rb, fmt.Sprintf(client.t("Hostname:    %s"), session.hostname))
+		service.Notice(rb, fmt.Sprintf(client.t("IP address:   %s"), session.ip.String()))
+		service.Notice(rb, fmt.Sprintf(client.t("Hostname:     %s"), session.hostname))
 		if hasPrivs {
-			service.Notice(rb, fmt.Sprintf(client.t("Connection:  %s"), session.connInfo))
+			service.Notice(rb, fmt.Sprintf(client.t("Connection:   %s"), session.connInfo))
 		}
-		service.Notice(rb, fmt.Sprintf(client.t("Created at:  %s"), session.ctime.Format(time.RFC1123)))
-		service.Notice(rb, fmt.Sprintf(client.t("Last active: %s"), session.atime.Format(time.RFC1123)))
+		service.Notice(rb, fmt.Sprintf(client.t("Created at:   %s"), session.ctime.Format(time.RFC1123)))
+		service.Notice(rb, fmt.Sprintf(client.t("Last active:  %s"), session.atime.Format(time.RFC1123)))
 		if session.certfp != "" {
-			service.Notice(rb, fmt.Sprintf(client.t("Certfp:      %s"), session.certfp))
+			service.Notice(rb, fmt.Sprintf(client.t("Certfp:       %s"), session.certfp))
 		}
 		for _, capStr := range session.caps {
 			if capStr != "" {
-				service.Notice(rb, fmt.Sprintf(client.t("IRCv3 CAPs:  %s"), capStr))
+				service.Notice(rb, fmt.Sprintf(client.t("IRCv3 CAPs:   %s"), capStr))
 			}
 		}
+		if hasPrivs {
+			service.Notice(rb, fmt.Sprintf(client.t("Debug log ID: %s"), session.connID))
+		}
 	}
 }
 

irc/server.go

@@ -95,6 +95,7 @@ type Server struct {
 	stats             Stats
 	semaphores        ServerSemaphores
 	flock             flock.Flocker
+	connIDCounter     atomic.Uint64
 	defcon            atomic.Uint32
 }
 
@@ -302,7 +303,7 @@ func (server *Server) checkBanScriptExemptSASL(config *Config, session *Session)
 		return authSuccess
 	}
 	if output.Result == IPBanned || output.Result == IPRequireSASL {
-		server.logger.Info("connect-ip", "Rejecting unauthenticated client due to ip-check-script", ipaddr.String())
+		server.logger.Info("connect-ip", session.connID, "Rejecting unauthenticated client due to ip-check-script", ipaddr.String())
 		if output.BanMessage != "" {
 			session.client.requireSASLMessage = output.BanMessage
 		}
@@ -386,7 +387,7 @@ func (server *Server) tryRegister(c *Client, session *Session) (exiting bool) {
 		if isBanned {
 			c.setKlined()
 			c.Quit(info.BanMessage(c.t("You are banned from this server (%s)")), nil)
-			server.logger.Info("connect", "Client rejected by k-line", c.NickMaskString())
+			server.logger.Info("connect", session.connID, "Client rejected by k-line", c.NickMaskString())
 			return true
 		}
 	}
@@ -418,7 +419,7 @@ func (server *Server) playRegistrationBurst(session *Session) {
 	c := session.client
 	// continue registration
 	d := c.Details()
-	server.logger.Info("connect", fmt.Sprintf("Client connected [%s] [u:%s] [r:%s]", d.nick, d.username, d.realname))
+	server.logger.Info("connect", session.connID, fmt.Sprintf("Client connected [%s] [u:%s] [r:%s]", d.nick, d.username, d.realname))
 	server.snomasks.Send(sno.LocalConnects, fmt.Sprintf("Client connected [%s] [u:%s] [h:%s] [ip:%s] [r:%s]", d.nick, d.username, session.rawHostname, session.IP().String(), d.realname))
 	if d.account != "" {
 		server.sendLoginSnomask(d.nickMask, d.accountName)
@@ -1124,6 +1125,16 @@ func (server *Server) UnfoldName(cfname string) (name string) {
 	return server.clients.UnfoldNick(cfname)
 }
 
+// generateConnectionID generates a unique string identifier for an incoming connection.
+// this identifier is only used for debug logging.
+func (server *Server) generateConnectionID() string {
+	id := server.connIDCounter.Add(1)
+	// pad with leading zeroes to a minimum length of 5 hex digits. this enhances greppability;
+	// the identifier length will be 6 for the first 1048576 connections, which is less important
+	// but makes the log slightly easier to read
+	return fmt.Sprintf("s%05x", id)
+}
+
 // elistMatcher takes and matches ELIST conditions
 type elistMatcher struct {
 	MinClientsActive bool

traditional.yaml

@@ -747,7 +747,7 @@ logging:
         # be logged, even if you explicitly include it
         #
         # useful types include:
-        #   *               everything (usually used with exclusing some types below)
+        #   *               everything (usually used with excluding some types below)
         #   server          server startup, rehash, and shutdown events
         #   accounts        account registration and authentication
         #   channels        channel creation and operations