logger: Better colours and output

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 {

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)
+	sep := grey(":")
-	fullString := fmt.Sprintf("%s  %s : %s : %s : %s", time.Now().UTC().Format("2006-01-02T15:04:05Z"), logLevelDisplayNames[level], logType, object, message)
+	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")
 	}
 }

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

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))
+			logger.Log(irc.LogInfo, "startup", "Server running")
-			defer logger.Log(irc.LogInfo, "shutdown", "server", fmt.Sprintf("Oragono v%s exiting", irc.SemVer))
+			defer logger.Log(irc.LogInfo, "shutdown", fmt.Sprintf("Oragono v%s exiting", irc.SemVer))
 		}
 		server.Run()
 	}