diff --git a/irc/commands.go b/irc/commands.go index ed811508..b24b4044 100644 --- a/irc/commands.go +++ b/irc/commands.go @@ -5,7 +5,9 @@ package irc -import "github.com/DanielOaks/girc-go/ircmsg" +import ( + "github.com/DanielOaks/girc-go/ircmsg" +) // Command represents a command accepted from a client. type Command struct { diff --git a/irc/logger.go b/irc/logger.go index db2dff8f..9fc8bf7d 100644 --- a/irc/logger.go +++ b/irc/logger.go @@ -44,26 +44,6 @@ var ( } ) -// ClientLogger is a logger dedicated to a single client. This is a convenience class that -// automagically adds the client nick to logged messages. -type ClientLogger struct { - client *Client -} - -// NewClientLogger returns a new ClientLogger. -func NewClientLogger(client *Client) ClientLogger { - logger := ClientLogger{ - client: client, - } - return logger -} - -// Log logs the given message with the given details. -func (logger *ClientLogger) Log(level LogLevel, logType, object, message string) { - object = fmt.Sprintf("%s : %s", logger.client.nick, object) - logger.client.server.logger.Log(level, logType, object, message) -} - // Logger is the main interface used to log debug/info/error messages. type Logger struct { loggers []SingleLogger @@ -100,9 +80,9 @@ func NewLogger(config []LoggingConfig) (*Logger, error) { } // Log logs the given message with the given details. -func (logger *Logger) Log(level LogLevel, logType, object, message string) { +func (logger *Logger) Log(level LogLevel, logType string, messageParts ...string) { for _, singleLogger := range logger.loggers { - singleLogger.Log(level, logType, object, message) + singleLogger.Log(level, logType, messageParts...) } } @@ -123,7 +103,7 @@ type SingleLogger struct { } // Log logs the given message with the given details. -func (logger *SingleLogger) Log(level LogLevel, logType, object, message string) { +func (logger *SingleLogger) Log(level LogLevel, logType string, messageParts ...string) { // no logging enabled if !(logger.MethodSTDERR || logger.MethodFile.Enabled) { return @@ -141,11 +121,13 @@ func (logger *SingleLogger) Log(level LogLevel, logType, object, message string) } // assemble full line + timeGrey := ansi.ColorFunc("243") grey := ansi.ColorFunc("8") alert := ansi.ColorFunc("232+b:red") warn := ansi.ColorFunc("black:214") - info := ansi.ColorFunc("33") + info := ansi.ColorFunc("117") debug := ansi.ColorFunc("78") + section := ansi.ColorFunc("229") levelDisplay := logLevelDisplayNames[level] if level == LogError { @@ -158,14 +140,23 @@ func (logger *SingleLogger) Log(level LogLevel, logType, object, message string) levelDisplay = debug(levelDisplay) } - fullStringFormatted := fmt.Sprintf("%s %s : %s : %s : %s", grey(time.Now().UTC().Format("2006-01-02T15:04:05Z")), levelDisplay, logType, object, message) - fullString := fmt.Sprintf("%s %s : %s : %s : %s", time.Now().UTC().Format("2006-01-02T15:04:05Z"), logLevelDisplayNames[level], logType, object, message) + sep := grey(":") + fullStringFormatted := fmt.Sprintf("%s %s %s %s %s %s ", timeGrey(time.Now().UTC().Format("2006-01-02T15:04:05Z")), sep, levelDisplay, sep, section(logType), sep) + fullStringRaw := fmt.Sprintf("%s : %s : %s : ", time.Now().UTC().Format("2006-01-02T15:04:05Z"), logLevelDisplayNames[level], section(logType)) + for i, p := range messageParts { + fullStringFormatted += p + fullStringRaw += p + if i != len(messageParts)-1 { + fullStringFormatted += " " + sep + " " + fullStringRaw += " : " + } + } // output if logger.MethodSTDERR { fmt.Fprintln(os.Stderr, fullStringFormatted) } if logger.MethodFile.Enabled { - logger.MethodFile.Writer.WriteString(fullString + "\n") + logger.MethodFile.Writer.WriteString(fullStringRaw + "\n") } } diff --git a/irc/server.go b/irc/server.go index ceee423e..d7ac1e8f 100644 --- a/irc/server.go +++ b/irc/server.go @@ -219,6 +219,7 @@ func NewServer(configFilename string, config *Config, logger *Logger) (*Server, } // open data store + server.logger.Log(LogDebug, "startup", "Opening datastore") db, err := buntdb.Open(config.Datastore.Path) if err != nil { return nil, fmt.Errorf("Failed to open datastore: %s", err.Error()) @@ -241,10 +242,12 @@ func NewServer(configFilename string, config *Config, logger *Logger) (*Server, } // load *lines + server.logger.Log(LogDebug, "startup", "Loading D/Klines") server.loadDLines() server.loadKLines() // load password manager + server.logger.Log(LogDebug, "startup", "Loading passwords") err = server.store.View(func(tx *buntdb.Tx) error { saltString, err := tx.Get(keySalt) if err != nil { @@ -264,6 +267,7 @@ func NewServer(configFilename string, config *Config, logger *Logger) (*Server, return nil, fmt.Errorf("Could not load salt: %s", err.Error()) } + server.logger.Log(LogDebug, "startup", "Loading MOTD") if config.Server.MOTD != "" { file, err := os.Open(config.Server.MOTD) if err == nil { @@ -378,7 +382,7 @@ func (server *Server) Shutdown() { server.clients.ByNickMutex.RUnlock() if err := server.store.Close(); err != nil { - server.logger.Log(LogError, "shutdown", "db", fmt.Sprintln("Server.Shutdown store.Close: error:", err)) + server.logger.Log(LogError, "shutdown", fmt.Sprintln("Could not close datastore:", err)) } } @@ -395,10 +399,10 @@ func (server *Server) Run() { done = true case <-server.rehashSignal: - // eventually we expect to use HUP to reload config + server.logger.Log(LogInfo, "rehash", "Rehashing due to SIGHUP") err := server.rehash() if err != nil { - server.logger.Log(LogError, "rehash", "server", fmt.Sprintln("Failed to rehash:", err.Error())) + server.logger.Log(LogError, "rehash", fmt.Sprintln("Failed to rehash:", err.Error())) } case conn := <-server.newConns: @@ -450,6 +454,8 @@ func (server *Server) Run() { continue } + server.logger.Log(LogDebug, "localconnect-ip", fmt.Sprintf("Client connecting from %v", ipaddr)) + go NewClient(server, conn.Conn, conn.IsTLS) continue } @@ -497,7 +503,7 @@ func (server *Server) createListener(addr string, tlsMap map[string]*tls.Config) server.listeners[addr] = li // start listening - server.logger.Log(LogInfo, "listeners", "listener", fmt.Sprintf("listening on %s using %s.", addr, tlsString)) + server.logger.Log(LogInfo, "listeners", fmt.Sprintf("listening on %s using %s.", addr, tlsString)) // setup accept goroutine go func() { @@ -549,7 +555,7 @@ func (server *Server) createListener(addr string, tlsMap map[string]*tls.Config) server.listenerUpdateMutex.Unlock() // print notice - server.logger.Log(LogInfo, "listeners", "listener", fmt.Sprintf("updated listener %s using %s.", addr, tlsString)) + server.logger.Log(LogInfo, "listeners", fmt.Sprintf("updated listener %s using %s.", addr, tlsString)) } default: // no events waiting for us, fall-through and continue @@ -596,7 +602,7 @@ func (server *Server) wslisten(addr string, tlsMap map[string]*TLSListenConfig) if listenTLS { tlsString = "TLS" } - server.logger.Log(LogInfo, "listeners", "listener", fmt.Sprintf("websocket listening on %s using %s.", addr, tlsString)) + server.logger.Log(LogInfo, "listeners", fmt.Sprintf("websocket listening on %s using %s.", addr, tlsString)) if listenTLS { err = http.ListenAndServeTLS(addr, config.Cert, config.Key, nil) @@ -604,7 +610,7 @@ func (server *Server) wslisten(addr string, tlsMap map[string]*TLSListenConfig) err = http.ListenAndServe(addr, nil) } if err != nil { - server.logger.Log(LogError, "listeners", "listener", fmt.Sprintf("listenAndServe error [%s]: %s", tlsString, err)) + server.logger.Log(LogError, "listeners", fmt.Sprintf("listenAndServe error [%s]: %s", tlsString, err)) } }() } @@ -651,6 +657,8 @@ func (server *Server) tryRegister(c *Client) { c.RplISupport() server.MOTD(c) c.Send(nil, c.nickMaskString, RPL_UMODEIS, c.nick, c.ModeString()) + + server.logger.Log(LogDebug, "localconnect", fmt.Sprintf("Client registered [%s]", c.nick)) } // MOTD serves the Message of the Day. @@ -1399,11 +1407,13 @@ func (server *Server) rehash() error { // REHASH func rehashHandler(server *Server, client *Client, msg ircmsg.IrcMessage) bool { + server.logger.Log(LogInfo, "rehash", fmt.Sprintf("REHASH command used by %s", client.nick)) err := server.rehash() if err == nil { client.Send(nil, server.name, RPL_REHASHING, client.nick, "ircd.yaml", "Rehashing") } else { + server.logger.Log(LogError, "rehash", fmt.Sprintln("Failed to rehash:", err.Error())) client.Send(nil, server.name, ERR_UNKNOWNERROR, client.nick, "REHASH", err.Error()) } return false diff --git a/oragono.go b/oragono.go index 52652724..264a3f67 100644 --- a/oragono.go +++ b/oragono.go @@ -90,14 +90,17 @@ Options: } } else if arguments["run"].(bool) { rand.Seed(time.Now().UTC().UnixNano()) + if !arguments["--quiet"].(bool) { + logger.Log(irc.LogInfo, "startup", fmt.Sprintf("Oragono v%s starting", irc.SemVer)) + } server, err := irc.NewServer(configfile, config, logger) if err != nil { - logger.Log(irc.LogError, "startup", "server", fmt.Sprintf("Could not load server: %s", err.Error())) + logger.Log(irc.LogError, "startup", fmt.Sprintf("Could not load server: %s", err.Error())) return } if !arguments["--quiet"].(bool) { - logger.Log(irc.LogInfo, "startup", "server", fmt.Sprintf("Oragono v%s running", irc.SemVer)) - defer logger.Log(irc.LogInfo, "shutdown", "server", fmt.Sprintf("Oragono v%s exiting", irc.SemVer)) + logger.Log(irc.LogInfo, "startup", "Server running") + defer logger.Log(irc.LogInfo, "shutdown", fmt.Sprintf("Oragono v%s exiting", irc.SemVer)) } server.Run() }