From 29e89b16a047c34a25c8c6ef8cfd84b12066e4a1 Mon Sep 17 00:00:00 2001 From: Daniel Oaks Date: Mon, 6 Mar 2017 15:50:23 +1000 Subject: [PATCH] logger: Very initial working new logs --- irc/client.go | 4 ++-- irc/config.go | 7 +++++++ irc/logger.go | 11 +++++++++-- irc/server.go | 44 ++++++++++++++++++++++---------------------- oragono.go | 18 +++++++++++------- 5 files changed, 51 insertions(+), 33 deletions(-) diff --git a/irc/client.go b/irc/client.go index 1bc1e420..644b6200 100644 --- a/irc/client.go +++ b/irc/client.go @@ -402,7 +402,7 @@ func (client *Client) AllNickmasks() []string { // SetNickname sets the very first nickname for the client. func (client *Client) SetNickname(nickname string) error { if client.HasNick() { - Log.error.Printf("%s nickname already set!", client.nickMaskString) + client.server.logger.Log(LogError, "nick", client.nick, fmt.Sprintf("%s nickname already set, something is wrong with server consistency", client.nickMaskString)) return ErrNickAlreadySet } @@ -543,7 +543,7 @@ var ( "NOTICE": true, RPL_WHOISCHANNELS: true, - RPL_USERHOST: true, + RPL_USERHOST: true, } ) diff --git a/irc/config.go b/irc/config.go index 1e380eaf..03777ba5 100644 --- a/irc/config.go +++ b/irc/config.go @@ -355,8 +355,10 @@ func LoadConfig(filename string) (config *Config, err error) { if config.Limits.LineLen.Tags < 512 || config.Limits.LineLen.Rest < 512 { return nil, errors.New("Line lengths must be 512 or greater (check the linelen section under server->limits)") } + var newLogConfigs []LoggingConfig for _, logConfig := range config.Logging { // methods + logConfig.Methods = make(map[string]bool) for _, method := range strings.Split(logConfig.Method, " ") { if len(method) > 0 { logConfig.Methods[strings.ToLower(method)] = true @@ -374,6 +376,8 @@ func LoadConfig(filename string) (config *Config, err error) { logConfig.Level = level // types + logConfig.Types = make(map[string]bool) + logConfig.ExcludedTypes = make(map[string]bool) for _, typeStr := range strings.Split(logConfig.TypeString, " ") { if len(typeStr) == 0 { continue @@ -391,7 +395,10 @@ func LoadConfig(filename string) (config *Config, err error) { if len(logConfig.Types) < 1 { return nil, errors.New("Logger has no types to log") } + + newLogConfigs = append(newLogConfigs, logConfig) } + config.Logging = newLogConfigs return config, nil } diff --git a/irc/logger.go b/irc/logger.go index ecbfe373..d520c812 100644 --- a/irc/logger.go +++ b/irc/logger.go @@ -34,6 +34,12 @@ var ( "error": LogError, "errors": LogError, } + logLevelDisplayNames = map[LogLevel]string{ + LogDebug: "debug", + LogInfo: "info", + LogWarn: "warning", + LogError: "error", + } ) // ClientLogger is a logger dedicated to a single client. This is a convenience class that @@ -77,7 +83,7 @@ func NewLogger(config []LoggingConfig) (*Logger, error) { ExcludedTypes: logConfig.ExcludedTypes, } if sLogger.MethodFile.Enabled { - file, err := os.OpenFile(sLogger.MethodFile.Filename, os.O_APPEND, 0666) + file, err := os.OpenFile(sLogger.MethodFile.Filename, os.O_CREATE|os.O_APPEND|os.O_WRONLY, 0666) if err != nil { return nil, fmt.Errorf("Could not open log file %s [%s]", sLogger.MethodFile.Filename, err.Error()) } @@ -85,6 +91,7 @@ func NewLogger(config []LoggingConfig) (*Logger, error) { sLogger.MethodFile.File = file sLogger.MethodFile.Writer = writer } + logger.loggers = append(logger.loggers, sLogger) } return &logger, nil @@ -132,7 +139,7 @@ func (logger *SingleLogger) Log(level LogLevel, logType, object, message string) } // assemble full line - fullString := fmt.Sprintf("%s : %s : %s : %s", time.Now().UTC().Format("2006-01-02T15:04:05.999Z"), 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) // output if logger.MethodSTDERR { diff --git a/irc/server.go b/irc/server.go index 329e11cc..ceee423e 100644 --- a/irc/server.go +++ b/irc/server.go @@ -136,18 +136,17 @@ type clientConn struct { } // NewServer returns a new Oragono server. -func NewServer(configFilename string, config *Config) *Server { +func NewServer(configFilename string, config *Config, logger *Logger) (*Server, error) { casefoldedName, err := Casefold(config.Server.Name) if err != nil { - log.Println(fmt.Sprintf("Server name isn't valid: [%s]", config.Server.Name), err.Error()) - return nil + return nil, fmt.Errorf("Server name isn't valid [%s]: %s", config.Server.Name, err.Error()) } // startup check that we have HELP entries for every command for name := range Commands { _, exists := Help[strings.ToLower(name)] if !exists { - log.Fatal("Help entry does not exist for ", name) + return nil, fmt.Errorf("Help entry does not exist for command %s", name) } } @@ -162,20 +161,20 @@ func NewServer(configFilename string, config *Config) *Server { operClasses, err := config.OperatorClasses() if err != nil { - log.Fatal("Error loading oper classes:", err.Error()) + return nil, fmt.Errorf("Error loading oper classes: %s", err.Error()) } opers, err := config.Operators(operClasses) if err != nil { - log.Fatal("Error loading operators:", err.Error()) + return nil, fmt.Errorf("Error loading operators: %s", err.Error()) } connectionLimits, err := NewConnectionLimits(config.Server.ConnectionLimits) if err != nil { - log.Fatal("Error loading connection limits:", err.Error()) + return nil, fmt.Errorf("Error loading connection limits: %s", err.Error()) } connectionThrottle, err := NewConnectionThrottle(config.Server.ConnectionThrottle) if err != nil { - log.Fatal("Error loading connection throttler:", err.Error()) + return nil, fmt.Errorf("Error loading connection throttler: %s", err.Error()) } server := &Server{ @@ -204,6 +203,7 @@ func NewServer(configFilename string, config *Config) *Server { }, }, listeners: make(map[string]ListenerInterface), + logger: logger, monitoring: make(map[string][]Client), name: config.Server.Name, nameCasefolded: casefoldedName, @@ -221,7 +221,7 @@ func NewServer(configFilename string, config *Config) *Server { // open data store db, err := buntdb.Open(config.Datastore.Path) if err != nil { - log.Fatal(fmt.Sprintf("Failed to open datastore: %s", err.Error())) + return nil, fmt.Errorf("Failed to open datastore: %s", err.Error()) } server.store = db @@ -229,7 +229,7 @@ func NewServer(configFilename string, config *Config) *Server { err = server.store.View(func(tx *buntdb.Tx) error { version, _ := tx.Get(keySchemaVersion) if version != latestDbSchema { - log.Println(fmt.Sprintf("Database must be updated. Expected schema v%s, got v%s.", latestDbSchema, version)) + logger.Log(LogError, "startup", "server", fmt.Sprintf("Database must be updated. Expected schema v%s, got v%s.", latestDbSchema, version)) return errDbOutOfDate } return nil @@ -237,7 +237,7 @@ func NewServer(configFilename string, config *Config) *Server { if err != nil { // close the db db.Close() - return nil + return nil, errDbOutOfDate } // load *lines @@ -261,7 +261,7 @@ func NewServer(configFilename string, config *Config) *Server { return nil }) if err != nil { - log.Fatal(fmt.Sprintf("Could not load salt: %s", err.Error())) + return nil, fmt.Errorf("Could not load salt: %s", err.Error()) } if config.Server.MOTD != "" { @@ -309,11 +309,11 @@ func NewServer(configFilename string, config *Config) *Server { // start API if enabled if server.restAPI.Enabled { - Log.info.Printf("%s rest API started on %s .", server.name, server.restAPI.Listen) + logger.Log(LogInfo, "startup", "server", fmt.Sprintf("%s rest API started on %s.", server.name, server.restAPI.Listen)) server.startRestAPI() } - return server + return server, nil } // setISupport sets up our RPL_ISUPPORT reply. @@ -378,7 +378,7 @@ func (server *Server) Shutdown() { server.clients.ByNickMutex.RUnlock() if err := server.store.Close(); err != nil { - Log.error.Println("Server.Shutdown store.Close: error:", err) + server.logger.Log(LogError, "shutdown", "db", fmt.Sprintln("Server.Shutdown store.Close: error:", err)) } } @@ -398,7 +398,7 @@ func (server *Server) Run() { // eventually we expect to use HUP to reload config err := server.rehash() if err != nil { - Log.error.Println("Failed to rehash:", err.Error()) + server.logger.Log(LogError, "rehash", "server", fmt.Sprintln("Failed to rehash:", err.Error())) } case conn := <-server.newConns: @@ -497,7 +497,7 @@ func (server *Server) createListener(addr string, tlsMap map[string]*tls.Config) server.listeners[addr] = li // start listening - Log.info.Printf("%s listening on %s using %s.", server.name, addr, tlsString) + server.logger.Log(LogInfo, "listeners", "listener", fmt.Sprintf("listening on %s using %s.", addr, tlsString)) // setup accept goroutine go func() { @@ -549,7 +549,7 @@ func (server *Server) createListener(addr string, tlsMap map[string]*tls.Config) server.listenerUpdateMutex.Unlock() // print notice - Log.info.Printf("%s updated listener %s using %s.", server.name, addr, tlsString) + server.logger.Log(LogInfo, "listeners", "listener", fmt.Sprintf("updated listener %s using %s.", addr, tlsString)) } default: // no events waiting for us, fall-through and continue @@ -565,7 +565,7 @@ func (server *Server) createListener(addr string, tlsMap map[string]*tls.Config) func (server *Server) wslisten(addr string, tlsMap map[string]*TLSListenConfig) { http.HandleFunc("/", func(w http.ResponseWriter, r *http.Request) { if r.Method != "GET" { - Log.error.Printf("%s method not allowed", server.name) + server.logger.Log(LogError, "ws", addr, fmt.Sprintf("%s method not allowed", r.Method)) return } @@ -578,7 +578,7 @@ func (server *Server) wslisten(addr string, tlsMap map[string]*TLSListenConfig) ws, err := upgrader.Upgrade(w, r, nil) if err != nil { - Log.error.Printf("%s websocket upgrade error: %s", server.name, err) + server.logger.Log(LogError, "ws", addr, fmt.Sprintf("%s websocket upgrade error: %s", server.name, err)) return } @@ -596,7 +596,7 @@ func (server *Server) wslisten(addr string, tlsMap map[string]*TLSListenConfig) if listenTLS { tlsString = "TLS" } - Log.info.Printf("%s websocket listening on %s using %s.", server.name, addr, tlsString) + server.logger.Log(LogInfo, "listeners", "listener", fmt.Sprintf("websocket listening on %s using %s.", addr, tlsString)) if listenTLS { err = http.ListenAndServeTLS(addr, config.Cert, config.Key, nil) @@ -604,7 +604,7 @@ func (server *Server) wslisten(addr string, tlsMap map[string]*TLSListenConfig) err = http.ListenAndServe(addr, nil) } if err != nil { - Log.error.Printf("%s listenAndServe (%s) error: %s", server.name, tlsString, err) + server.logger.Log(LogError, "listeners", "listener", fmt.Sprintf("listenAndServe error [%s]: %s", tlsString, err)) } }() } diff --git a/oragono.go b/oragono.go index cc2e1931..52652724 100644 --- a/oragono.go +++ b/oragono.go @@ -43,6 +43,11 @@ Options: log.Fatal("Config file did not load successfully:", err.Error()) } + logger, err := irc.NewLogger(config.Logging) + if err != nil { + log.Fatal("Logger did not load successfully:", err.Error()) + } + if arguments["genpasswd"].(bool) { fmt.Print("Enter Password: ") bytePassword, err := terminal.ReadPassword(int(syscall.Stdin)) @@ -52,7 +57,7 @@ Options: password := string(bytePassword) encoded, err := irc.GenerateEncodedPassword(password) if err != nil { - log.Fatalln("encoding error:", err) + log.Fatal("encoding error:", err.Error()) } fmt.Print("\n") fmt.Println(encoded) @@ -84,16 +89,15 @@ Options: } } } else if arguments["run"].(bool) { - irc.Log.SetLevel(config.Server.Log) rand.Seed(time.Now().UTC().UnixNano()) - server := irc.NewServer(configfile, config) - if server == nil { - log.Println("Could not load server") + 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())) return } if !arguments["--quiet"].(bool) { - log.Println(fmt.Sprintf("Oragono v%s running", irc.SemVer)) - defer log.Println(irc.SemVer, "exiting") + 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)) } server.Run() }