rework logging code

main.go

@@ -43,7 +43,14 @@ var Commit = func() string {
 
 func main() {
 	var err error
-	zapLogger, _ := zap.NewDevelopment()
+
+	var zapLogger *zap.Logger
+	if config.ErupeConfig.DevMode {
+		zapLogger, _ = zap.NewDevelopment()
+	} else {
+		zapLogger, _ = zap.NewProduction()
+	}
+
 	defer zapLogger.Sync()
 	logger := zapLogger.Named("main")
 
@@ -76,20 +83,20 @@ func main() {
 		})
 
 		if err != nil {
-			preventClose(fmt.Sprintf("Failed to create Discord bot: %s", err.Error()))
+			preventClose(fmt.Sprintf("Discord: Failed to start, %s", err.Error()))
 		}
 
 		// Discord bot
 		err = bot.Start()
 
 		if err != nil {
-			preventClose(fmt.Sprintf("Failed to start Discord bot: %s", err.Error()))
+			preventClose(fmt.Sprintf("Discord: Failed to start, %s", err.Error()))
 		}
 
 		discordBot = bot
-		logger.Info("Discord bot is enabled")
+		logger.Info("Discord: Started successfully")
 	} else {
-		logger.Info("Discord bot is disabled")
+		logger.Info("Discord: Disabled")
 	}
 
 	// Create the postgres DB pool.
@@ -104,15 +111,15 @@ func main() {
 
 	db, err := sqlx.Open("postgres", connectString)
 	if err != nil {
-		preventClose(fmt.Sprintf("Failed to open SQL database: %s", err.Error()))
+		preventClose(fmt.Sprintf("Database: Failed to open, %s", err.Error()))
 	}
 
 	// Test the DB connection.
 	err = db.Ping()
 	if err != nil {
-		preventClose(fmt.Sprintf("Failed to ping database: %s", err.Error()))
+		preventClose(fmt.Sprintf("Database: Failed to ping, %s", err.Error()))
 	}
-	logger.Info("Connected to database")
+	logger.Info("Database: Started successfully")
 
 	// Clear stale data
 	_ = db.MustExec("DELETE FROM sign_sessions")
@@ -120,9 +127,9 @@ func main() {
 
 	// Clean the DB if the option is on.
 	if config.ErupeConfig.DevMode && config.ErupeConfig.DevModeOptions.CleanDB {
-		logger.Info("Cleaning DB")
+		logger.Info("Database: Started clearing...")
 		cleanDB(db)
-		logger.Info("Done cleaning DB")
+		logger.Info("Database: Finished clearing")
 	}
 
 	logger.Info(fmt.Sprintf("Server Time: %s", channelserver.TimeAdjusted().String()))
@@ -141,9 +148,11 @@ func main() {
 			})
 		err = entranceServer.Start()
 		if err != nil {
-			preventClose(fmt.Sprintf("Failed to start entrance server: %s", err.Error()))
+			preventClose(fmt.Sprintf("Entrance: Failed to start, %s", err.Error()))
 		}
-		logger.Info("Started entrance server")
+		logger.Info("Entrance: Started successfully")
+	} else {
+		logger.Info("Entrance: Disabled")
 	}
 
 	// Sign server.
@@ -158,9 +167,11 @@ func main() {
 			})
 		err = signServer.Start()
 		if err != nil {
-			preventClose(fmt.Sprintf("Failed to start sign server: %s", err.Error()))
+			preventClose(fmt.Sprintf("Sign: Failed to start, %s", err.Error()))
 		}
-		logger.Info("Started sign server")
+		logger.Info("Sign: Started successfully")
+	} else {
+		logger.Info("Sign: Disabled")
 	}
 
 	// New Sign server
@@ -174,9 +185,11 @@ func main() {
 			})
 		err = newSignServer.Start()
 		if err != nil {
-			preventClose(fmt.Sprintf("Failed to start sign-v2 server: %s", err.Error()))
+			preventClose(fmt.Sprintf("SignV2: Failed to start, %s", err.Error()))
 		}
-		logger.Info("Started new sign server")
+		logger.Info("SignV2: Started successfully")
+	} else {
+		logger.Info("SignV2: Disabled")
 	}
 
 	var channels []*channelserver.Server
@@ -205,11 +218,11 @@ func main() {
 				c.GlobalID = fmt.Sprintf("%02d%02d", j+1, i+1)
 				err = c.Start()
 				if err != nil {
-					preventClose(fmt.Sprintf("Failed to start channel server: %s", err.Error()))
+					preventClose(fmt.Sprintf("Channel: Failed to start, %s", err.Error()))
 				} else {
 					channelQuery += fmt.Sprintf(`INSERT INTO servers (server_id, season, current_players, world_name, world_description, land) VALUES (%d, %d, 0, '%s', '%s', %d);`, sid, si%3, ee.Name, ee.Description, i+1)
 					channels = append(channels, &c)
-					logger.Info(fmt.Sprintf("Started channel server %d on port %d", count, ce.Port))
+					logger.Info(fmt.Sprintf("Channel %d (%d): Started successfully", count, ce.Port))
 					ci++
 					count++
 				}
@@ -233,7 +246,14 @@ func main() {
 	signal.Notify(c, os.Interrupt, syscall.SIGTERM)
 	<-c
 
-	logger.Info("Shutting down...")
+	for i := 0; i < 10; i++ {
+		message := fmt.Sprintf("Shutting down in %d...", 10-i)
+		for _, c := range channels {
+			c.BroadcastChatMessage(message)
+		}
+		logger.Info(message)
+		time.Sleep(time.Second)
+	}
 
 	if config.ErupeConfig.Channel.Enabled {
 		for _, c := range channels {

server/channelserver/handlers_cast_binary.go

@@ -38,16 +38,18 @@ var commands map[string]config.Command
 
 func init() {
 	commands = make(map[string]config.Command)
-	zapLogger, _ := zap.NewDevelopment()
+	zapConfig := zap.NewDevelopmentConfig()
+	zapConfig.DisableCaller = true
+	zapLogger, _ := zapConfig.Build()
 	defer zapLogger.Sync()
 	logger := zapLogger.Named("commands")
 	cmds := config.ErupeConfig.Commands
 	for _, cmd := range cmds {
 		commands[cmd.Name] = cmd
 		if cmd.Enabled {
-			logger.Info(fmt.Sprintf("%s command is enabled, prefix: %s", cmd.Name, cmd.Prefix))
+			logger.Info(fmt.Sprintf("Command %s: Enabled, prefix: %s", cmd.Name, cmd.Prefix))
 		} else {
-			logger.Info(fmt.Sprintf("%s command is disabled", cmd.Name))
+			logger.Info(fmt.Sprintf("Command %s: Disabled", cmd.Name))
 		}
 	}
 }

server/entranceserver/entrance_server.go

@@ -111,7 +111,9 @@ func (s *Server) handleEntranceServerConnection(conn net.Conn) {
 		return
 	}
 
-	s.logger.Debug("Got entrance server command:\n", zap.String("raw", hex.Dump(pkt)))
+	if s.erupeConfig.DevMode && s.erupeConfig.DevModeOptions.LogInboundMessages {
+		fmt.Printf("[Client] -> [Server]\nData [%d bytes]:\n%s\n", len(pkt), hex.Dump(pkt))
+	}
 
 	local := false
 	if strings.Split(conn.RemoteAddr().String(), ":")[0] == "127.0.0.1" {

server/entranceserver/make_resp.go

@@ -2,6 +2,8 @@ package entranceserver
 
 import (
 	"encoding/binary"
+	"encoding/hex"
+	"fmt"
 	"net"
 
 	"erupe-ce/common/stringsupport"
@@ -92,6 +94,11 @@ func makeHeader(data []byte, respType string, entryCount uint16, key byte) []byt
 func makeSv2Resp(config *config.Config, s *Server, local bool) []byte {
 	serverInfos := config.Entrance.Entries
 	rawServerData := encodeServerInfo(config, s, local)
+
+	if s.erupeConfig.DevMode && s.erupeConfig.DevModeOptions.LogOutboundMessages {
+		fmt.Printf("[Server] -> [Client]\nData [%d bytes]:\n%s\n", len(rawServerData), hex.Dump(rawServerData))
+	}
+
 	bf := byteframe.NewByteFrame()
 	bf.WriteBytes(makeHeader(rawServerData, "SV2", uint16(len(serverInfos)), 0x00))
 	return bf.Data()
@@ -109,11 +116,15 @@ func makeUsrResp(pkt []byte, s *Server) []byte {
 		err := s.db.QueryRow("SELECT(SELECT server_id FROM sign_sessions WHERE char_id=$1) AS _", cid).Scan(&sid)
 		if err != nil {
 			resp.WriteBytes(make([]byte, 4))
-			continue
 		} else {
 			resp.WriteUint16(sid)
 			resp.WriteUint16(0)
 		}
 	}
+
+	if s.erupeConfig.DevMode && s.erupeConfig.DevModeOptions.LogOutboundMessages {
+		fmt.Printf("[Server] -> [Client]\nData [%d bytes]:\n%s\n", len(resp.Data()), hex.Dump(resp.Data()))
+	}
+
 	return makeHeader(resp.Data(), "USR", userEntries, 0x00)
 }

server/signserver/session.go

@@ -3,6 +3,7 @@ package signserver
 import (
 	"database/sql"
 	"encoding/hex"
+	"fmt"
 	"net"
 	"sync"
 
@@ -23,6 +24,11 @@ type Session struct {
 
 func (s *Session) work() {
 	pkt, err := s.cryptConn.ReadPacket()
+
+	if s.server.erupeConfig.DevMode && s.server.erupeConfig.DevModeOptions.LogInboundMessages {
+		fmt.Printf("\n[Client] -> [Server]\nData [%d bytes]:\n%s\n", len(pkt), hex.Dump(pkt))
+	}
+
 	if err != nil {
 		return
 	}
@@ -33,8 +39,6 @@ func (s *Session) work() {
 }
 
 func (s *Session) handlePacket(pkt []byte) error {
-	sugar := s.logger.Sugar()
-
 	bf := byteframe.NewByteFrameFromBytes(pkt)
 	reqType := string(bf.ReadNullTerminatedBytes())
 	switch reqType {
@@ -50,13 +54,16 @@ func (s *Session) handlePacket(pkt []byte) error {
 		characterID := int(bf.ReadUint32())
 		_ = int(bf.ReadUint32()) // login_token_number
 		s.server.deleteCharacter(characterID, loginTokenString)
-		sugar.Infof("Deleted character ID: %v\n", characterID)
+		s.logger.Info("Deleted character", zap.Int("CharacterID", characterID))
 		err := s.cryptConn.SendPacket([]byte{0x01}) // DEL_SUCCESS
 		if err != nil {
 			return nil
 		}
 	default:
-		sugar.Infof("Got unknown request type %s, data:\n%s\n", reqType, hex.Dump(bf.DataFromCurrent()))
+		s.logger.Warn("Unknown sign request", zap.String("reqType", reqType))
+		if s.server.erupeConfig.DevMode && s.server.erupeConfig.DevModeOptions.LogInboundMessages {
+			fmt.Printf("\n[Client] -> [Server]\nData [%d bytes]:\n%s\n", len(pkt), hex.Dump(pkt))
+		}
 	}
 
 	return nil
@@ -66,14 +73,7 @@ func (s *Session) handleDSGNRequest(bf *byteframe.ByteFrame) error {
 
 	reqUsername := string(bf.ReadNullTerminatedBytes())
 	reqPassword := string(bf.ReadNullTerminatedBytes())
-	reqSkey := string(bf.ReadNullTerminatedBytes())
+	_ = string(bf.ReadNullTerminatedBytes()) // Unk
-
-	s.server.logger.Info(
-		"Got sign in request",
-		zap.String("reqUsername", reqUsername),
-		zap.String("reqPassword", reqPassword),
-		zap.String("reqSkey", reqSkey),
-	)
 
 	newCharaReq := false
 
@@ -90,14 +90,14 @@ func (s *Session) handleDSGNRequest(bf *byteframe.ByteFrame) error {
 	var serverRespBytes []byte
 	switch {
 	case err == sql.ErrNoRows:
-		s.logger.Info("Account not found", zap.String("reqUsername", reqUsername))
+		s.logger.Info("User not found", zap.String("Username", reqUsername))
 		serverRespBytes = makeSignInFailureResp(SIGN_EAUTH)
 
 		if s.server.erupeConfig.DevMode && s.server.erupeConfig.DevModeOptions.AutoCreateAccount {
-			s.logger.Info("Creating account", zap.String("reqUsername", reqUsername), zap.String("reqPassword", reqPassword))
+			s.logger.Info("Creating user", zap.String("Username", reqUsername))
 			err = s.server.registerDBAccount(reqUsername, reqPassword)
 			if err != nil {
-				s.logger.Info("Error on creating new account", zap.Error(err))
+				s.logger.Error("Error registering new user", zap.Error(err))
 				serverRespBytes = makeSignInFailureResp(SIGN_EABORT)
 				break
 			}
@@ -108,7 +108,7 @@ func (s *Session) handleDSGNRequest(bf *byteframe.ByteFrame) error {
 		var id int
 		err = s.server.db.QueryRow("SELECT id FROM users WHERE username = $1", reqUsername).Scan(&id)
 		if err != nil {
-			s.logger.Info("Error on querying account id", zap.Error(err))
+			s.logger.Error("Error getting new user ID", zap.Error(err))
 			serverRespBytes = makeSignInFailureResp(SIGN_EABORT)
 			break
 		}
@@ -117,15 +117,15 @@ func (s *Session) handleDSGNRequest(bf *byteframe.ByteFrame) error {
 		break
 	case err != nil:
 		serverRespBytes = makeSignInFailureResp(SIGN_EABORT)
-		s.logger.Warn("Got error on SQL query", zap.Error(err))
+		s.logger.Error("Error getting user details", zap.Error(err))
 		break
 	default:
 		if bcrypt.CompareHashAndPassword([]byte(password), []byte(reqPassword)) == nil {
-			s.logger.Info("Passwords match!")
+			s.logger.Debug("Passwords match!")
 			if newCharaReq {
 				err = s.server.newUserChara(reqUsername)
 				if err != nil {
-					s.logger.Info("Error on adding new character to account", zap.Error(err))
+					s.logger.Error("Error adding new character to user", zap.Error(err))
 					serverRespBytes = makeSignInFailureResp(SIGN_EABORT)
 					break
 				}
@@ -139,12 +139,16 @@ func (s *Session) handleDSGNRequest(bf *byteframe.ByteFrame) error {
 			// }
 			serverRespBytes = s.makeSignInResp(id)
 		} else {
-			s.logger.Info("Passwords don't match!")
+			s.logger.Warn("Incorrect password")
 			serverRespBytes = makeSignInFailureResp(SIGN_EPASS)
 		}
 
 	}
 
+	if s.server.erupeConfig.DevMode && s.server.erupeConfig.DevModeOptions.LogOutboundMessages {
+		fmt.Printf("\n[Server] -> [Client]\nData [%d bytes]:\n%s\n", len(serverRespBytes), hex.Dump(serverRespBytes))
+	}
+
 	err = s.cryptConn.SendPacket(serverRespBytes)
 	if err != nil {
 		return err

server/signserver/sign_server.go

@@ -55,7 +55,7 @@ func (s *Server) Start() error {
 
 // Shutdown exits the server gracefully.
 func (s *Server) Shutdown() {
-	s.logger.Debug("Shutting down")
+	s.logger.Debug("Shutting down...")
 
 	s.Lock()
 	s.isShuttingDown = true
@@ -86,14 +86,14 @@ func (s *Server) acceptClients() {
 }
 
 func (s *Server) handleConnection(conn net.Conn) {
-	s.logger.Info("Got connection to sign server", zap.String("remoteaddr", conn.RemoteAddr().String()))
+	s.logger.Debug("New connection", zap.String("RemoteAddr", conn.RemoteAddr().String()))
 	defer conn.Close()
 
 	// Client initalizes the connection with a one-time buffer of 8 NULL bytes.
 	nullInit := make([]byte, 8)
 	_, err := io.ReadFull(conn, nullInit)
 	if err != nil {
-		s.logger.Error("Error initialising sign server connection", zap.Error(err))
+		s.logger.Error("Error initializing connection", zap.Error(err))
 		return
 	}