From efd3764337246d034d6324c56c6a87587d016f35 Mon Sep 17 00:00:00 2001 From: Shivaram Lingamneni Date: Sat, 11 Jan 2025 20:07:04 -0800 Subject: [PATCH] add unique connection ID to debug logs (#2207) Fixes #2206 --- default.yaml | 2 +- irc/client.go | 14 +++++++++----- irc/gateways.go | 2 +- irc/getters.go | 2 ++ irc/nickserv.go | 19 +++++++++++-------- irc/server.go | 17 ++++++++++++++--- traditional.yaml | 2 +- 7 files changed, 39 insertions(+), 19 deletions(-) diff --git a/default.yaml b/default.yaml index 491bc95b..f3b5cd0b 100644 --- a/default.yaml +++ b/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 diff --git a/irc/client.go b/irc/client.go index bb5badde..e94685b2 100644 --- a/irc/client.go +++ b/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 } diff --git a/irc/gateways.go b/irc/gateways.go index 08adac93..e8ab60ab 100644 --- a/irc/gateways.go +++ b/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() diff --git a/irc/getters.go b/irc/getters.go index abedb246..c64532a3 100644 --- a/irc/getters.go +++ b/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 { diff --git a/irc/nickserv.go b/irc/nickserv.go index 3e859160..117569b2 100644 --- a/irc/nickserv.go +++ b/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)) + } } } diff --git a/irc/server.go b/irc/server.go index ce75ecd8..3eeac086 100644 --- a/irc/server.go +++ b/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 diff --git a/traditional.yaml b/traditional.yaml index 73165adc..3090f664 100644 --- a/traditional.yaml +++ b/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