GitHub/ergo
3
0
Fork 0
mirror of https://github.com/ergochat/ergo.git synced 2025-01-21 01:34:20 +01:00
Code Issues Projects Releases Wiki Activity

add unique connection ID to debug logs (#2207)

Browse Source 
Fixes #2206
This commit is contained in:
Shivaram Lingamneni 2025-01-11 20:07:04 -08:00 committed by GitHub
parent 375079e636
commit efd3764337
No known key found for this signature in database
GPG Key ID: B5690EEEBB952194
7 changed files with 39 additions and 19 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

2
default.yaml
View File

@ -776,7 +776,7 @@ logging:
# be logged, even if you explicitly include it # be logged, even if you explicitly include it
# #
# useful types include: # 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 # server server startup, rehash, and shutdown events
# accounts account registration and authentication # accounts account registration and authentication
# channels channel creation and operations # channels channel creation and operations

14
irc/client.go
View File

@ -152,6 +152,8 @@ const (
type Session struct { type Session struct {
client *Client client *Client
connID string // identifies the connection in debug logs
deviceID string deviceID string
ctime time.Time ctime time.Time
@ -334,7 +336,8 @@ func (server *Server) RunClient(conn IRCConn) {
return 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() now := time.Now().UTC()
// give them 1k of grace over the limit: // give them 1k of grace over the limit:
@ -374,6 +377,7 @@ func (server *Server) RunClient(conn IRCConn) {
proxiedIP: proxiedIP, proxiedIP: proxiedIP,
isTor: wConn.Tor, isTor: wConn.Tor,
hideSTS: wConn.Tor || wConn.HideSTS, hideSTS: wConn.Tor || wConn.HideSTS,
connID: connID,
} }
session.sasl.Initialize() session.sasl.Initialize()
client.sessions = []*Session{session} client.sessions = []*Session{session}
@ -670,7 +674,7 @@ func (client *Client) run(session *Session) {
} }
if client.server.logger.IsLoggingRawIO() { 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: // special-cased handling of PROXY protocol, see `handleProxyCommand` for details:
@ -1287,7 +1291,7 @@ func (client *Client) destroy(session *Session) {
if !shouldDestroy { 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.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 // 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) { func (session *Session) sendBytes(line []byte, blocking bool) (err error) {
if session.client.server.logger.IsLoggingRawIO() { if session.client.server.logger.IsLoggingRawIO() {
logline := string(line[:len(line)-2]) // strip "\r\n" 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 { if blocking {
@ -1506,7 +1510,7 @@ func (session *Session) sendBytes(line []byte, blocking bool) (err error) {
err = session.socket.Write(line) err = session.socket.Write(line)
} }
if err != nil { 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 return err
} }

2
irc/gateways.go
View File

@ -92,7 +92,7 @@ func (client *Client) ApplyProxiedIP(session *Session, proxiedIP net.IP, tls boo
client.server.connectionLimiter.RemoveClient(flatip.FromNetIP(session.realIP)) client.server.connectionLimiter.RemoveClient(flatip.FromNetIP(session.realIP))
// given IP is sane! override the client's current IP // 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() client.stateMutex.Lock()
defer client.stateMutex.Unlock() defer client.stateMutex.Unlock()

2
irc/getters.go
View File

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

19
irc/nickserv.go
View File

@ -1310,23 +1310,26 @@ func nsClientsListHandler(service *ircService, server *Server, client *Client, p
service.Notice(rb, fmt.Sprintf(client.t("Client %d:"), session.sessionID)) service.Notice(rb, fmt.Sprintf(client.t("Client %d:"), session.sessionID))
} }
if session.deviceID != "" { 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("IP address: %s"), session.ip.String()))
service.Notice(rb, fmt.Sprintf(client.t("Hostname: %s"), session.hostname)) service.Notice(rb, fmt.Sprintf(client.t("Hostname: %s"), session.hostname))
if hasPrivs { 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("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("Last active: %s"), session.atime.Format(time.RFC1123)))
if session.certfp != "" { 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 { for _, capStr := range session.caps {
if capStr != "" { 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))
}
} }
} }

17
irc/server.go
View File

@ -95,6 +95,7 @@ type Server struct {
stats Stats stats Stats
semaphores ServerSemaphores semaphores ServerSemaphores
flock flock.Flocker flock flock.Flocker
connIDCounter atomic.Uint64
defcon atomic.Uint32 defcon atomic.Uint32
} }
@ -302,7 +303,7 @@ func (server *Server) checkBanScriptExemptSASL(config *Config, session *Session)
return authSuccess return authSuccess
} }
if output.Result == IPBanned || output.Result == IPRequireSASL { 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 != "" { if output.BanMessage != "" {
session.client.requireSASLMessage = output.BanMessage session.client.requireSASLMessage = output.BanMessage
} }
@ -386,7 +387,7 @@ func (server *Server) tryRegister(c *Client, session *Session) (exiting bool) {
if isBanned { if isBanned {
c.setKlined() c.setKlined()
c.Quit(info.BanMessage(c.t("You are banned from this server (%s)")), nil) 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 return true
} }
} }
@ -418,7 +419,7 @@ func (server *Server) playRegistrationBurst(session *Session) {
c := session.client c := session.client
// continue registration // continue registration
d := c.Details() 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)) 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 != "" { if d.account != "" {
server.sendLoginSnomask(d.nickMask, d.accountName) server.sendLoginSnomask(d.nickMask, d.accountName)
@ -1124,6 +1125,16 @@ func (server *Server) UnfoldName(cfname string) (name string) {
return server.clients.UnfoldNick(cfname) 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 // elistMatcher takes and matches ELIST conditions
type elistMatcher struct { type elistMatcher struct {
MinClientsActive bool MinClientsActive bool

2
traditional.yaml
View File

@ -747,7 +747,7 @@ logging:
# be logged, even if you explicitly include it # be logged, even if you explicitly include it
# #
# useful types include: # 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 # server server startup, rehash, and shutdown events
# accounts account registration and authentication # accounts account registration and authentication
# channels channel creation and operations # channels channel creation and operations