diff --git a/cmd/run.go b/cmd/run.go index f7bdda68..e9510024 100644 --- a/cmd/run.go +++ b/cmd/run.go @@ -2,6 +2,7 @@ package cmd import ( "context" + "fmt" "os" "os/signal" "syscall" @@ -147,7 +148,8 @@ var runCmd = &cobra.Command{ } // Verify that the pool is properly populated - logger.Info().Msgf("There are %d clients in the pool", pool.Size()) + logger.Info().Str("count", fmt.Sprint(pool.Size())).Msg( + "There are clients available in the pool") if pool.Size() != poolSize { logger.Error().Msg( "The pool size is incorrect, either because " + diff --git a/network/client.go b/network/client.go index 08309370..c3fae80b 100644 --- a/network/client.go +++ b/network/client.go @@ -1,6 +1,7 @@ package network import ( + "fmt" "net" "time" @@ -91,7 +92,8 @@ func NewClient( if err := client.Conn.SetReadDeadline(time.Now().Add(client.ReceiveDeadline)); err != nil { logger.Error().Err(err).Msg("Failed to set receive deadline") } else { - logger.Debug().Msgf("Receive deadline set to %s", client.ReceiveDeadline) + logger.Debug().Str("duration", fmt.Sprint(client.ReceiveDeadline.Seconds())).Msg( + "Set receive deadline") } } @@ -103,7 +105,8 @@ func NewClient( if err := client.Conn.SetWriteDeadline(time.Now().Add(client.SendDeadline)); err != nil { logger.Error().Err(err).Msg("Failed to set send deadline") } else { - logger.Debug().Msgf("Send deadline set to %s", client.SendDeadline) + logger.Debug().Str("duration", fmt.Sprint(client.SendDeadline)).Msg( + "Set send deadline") } } @@ -122,7 +125,7 @@ func NewClient( client.ReceiveChunkSize = receiveChunkSize } - logger.Debug().Msgf("New client created: %s", client.Address) + logger.Debug().Str("address", client.Address).Msg("New client created") client.ID = GetID(conn.LocalAddr().Network(), conn.LocalAddr().String(), DefaultSeed, logger) return &client @@ -132,10 +135,15 @@ func NewClient( func (c *Client) Send(data []byte) (int, *gerr.GatewayDError) { sent, err := c.Conn.Write(data) if err != nil { - c.logger.Error().Err(err).Msgf("Couldn't send data to the server: %s", err) + c.logger.Error().Err(err).Msg("Couldn't send data to the server") return 0, gerr.ErrClientSendFailed.Wrap(err) } - c.logger.Debug().Msgf("Sent %d bytes to %s", len(data), c.Address) + c.logger.Debug().Fields( + map[string]interface{}{ + "length": sent, + "address": c.Address, + }, + ).Msg("Sent data to server") return sent, nil } @@ -170,7 +178,7 @@ func (c *Client) Receive() (int, []byte, *gerr.GatewayDError) { // Close closes the connection to the server. func (c *Client) Close() { - c.logger.Debug().Msgf("Closing connection to %s", c.Address) + c.logger.Debug().Str("address", c.Address).Msg("Closing connection to server") if c.Conn != nil { c.Conn.Close() } @@ -183,21 +191,29 @@ func (c *Client) Close() { // IsConnected checks if the client is still connected to the server. func (c *Client) IsConnected() bool { if c == nil { - c.logger.Debug().Str( - "reason", "client is nil").Msgf("Connection to %s is closed", c.Address) + c.logger.Debug().Fields( + map[string]interface{}{ + "address": c.Address, + "reason": "client is nil", + }).Msg("Connection to server is closed") return false } if c != nil && c.Conn == nil || c.ID == "" { - c.logger.Debug().Str( - "reason", "connection is nil or invalid", - ).Msgf("Connection to %s is closed", c.Address) + c.logger.Debug().Fields( + map[string]interface{}{ + "address": c.Address, + "reason": "connection is nil or invalid", + }).Msg("Connection to server is closed") return false } if n, err := c.Read([]byte{}); n == 0 && err != nil { - c.logger.Debug().Str( - "reason", "read 0 bytes").Msgf("Connection to %s is closed, ", c.Address) + c.logger.Debug().Fields( + map[string]interface{}{ + "address": c.Address, + "reason": "read 0 bytes", + }).Msg("Connection to server is closed") return false } diff --git a/network/proxy.go b/network/proxy.go index 2e39911f..097bf587 100644 --- a/network/proxy.go +++ b/network/proxy.go @@ -61,6 +61,8 @@ func NewProxy( // Connect maps a server connection from the available connection pool to a incoming connection. // It returns an error if the pool is exhausted. If the pool is elastic, it creates a new client // and maps it to the incoming connection. +// +//nolint:funlen func (pr *ProxyImpl) Connect(gconn gnet.Conn) *gerr.GatewayDError { var clientID string // Get the first available client from the pool. @@ -86,7 +88,7 @@ func (pr *ProxyImpl) Connect(gconn gnet.Conn) *gerr.GatewayDError { pr.ClientConfig.SendDeadline, pr.logger, ) - pr.logger.Debug().Msgf("Reused the client %s by putting it back in the pool", client.ID) + pr.logger.Debug().Str("id", client.ID[:7]).Msg("Reused the client connection") } else { return gerr.ErrPoolExhausted } @@ -107,13 +109,26 @@ func (pr *ProxyImpl) Connect(gconn gnet.Conn) *gerr.GatewayDError { // This should never happen. return err } - pr.logger.Debug().Msgf( - "Client %s has been assigned to %s", client.ID, gconn.RemoteAddr().String()) + pr.logger.Debug().Fields( + map[string]interface{}{ + "function": "proxy.connect", + "client": client.ID[:7], + "server": gconn.RemoteAddr().String(), + }, + ).Msg("Client has been assigned") - pr.logger.Debug().Str("function", "proxy.connect").Msgf( - "There are %d available clients", pr.availableConnections.Size()) - pr.logger.Debug().Str("function", "proxy.connect").Msgf( - "There are %d busy clients", pr.busyConnections.Size()) + pr.logger.Debug().Fields( + map[string]interface{}{ + "function": "proxy.connect", + "count": pr.availableConnections.Size(), + }, + ).Msg("Available client connections") + pr.logger.Debug().Fields( + map[string]interface{}{ + "function": "proxy.connect", + "count": pr.availableConnections.Size(), + }, + ).Msg("Busy client connections") return nil } @@ -147,10 +162,18 @@ func (pr *ProxyImpl) Disconnect(gconn gnet.Conn) *gerr.GatewayDError { return gerr.ErrClientNotFound } - pr.logger.Debug().Str("function", "proxy.disconnect").Msgf( - "There are %d available clients", pr.availableConnections.Size()) - pr.logger.Debug().Str("function", "proxy.disconnect").Msgf( - "There are %d busy clients", pr.busyConnections.Size()) + pr.logger.Debug().Fields( + map[string]interface{}{ + "function": "proxy.disconnect", + "count": pr.availableConnections.Size(), + }, + ).Msg("Available client connections") + pr.logger.Debug().Fields( + map[string]interface{}{ + "function": "proxy.disconnect", + "count": pr.availableConnections.Size(), + }, + ).Msg("Busy client connections") return nil } @@ -224,12 +247,17 @@ func (pr *ProxyImpl) PassThrough(gconn gnet.Conn) *gerr.GatewayDError { // If the hook modified the request, use the modified request. if result != nil { if req, ok := result["request"].([]byte); ok { - pr.logger.Debug().Msgf( - "Hook modified request from %d to %d bytes", len(request), len(req)) + pr.logger.Debug().Fields( + map[string]interface{}{ + "function": "proxy.passthrough", + "from": len(request), + "to": len(req), + }, + ).Msg("Hook modified request") request = req } if errMsg, ok := result["error"].(string); ok && errMsg != "" { - pr.logger.Error().Msgf("Error in hook: %s", errMsg) + pr.logger.Error().Str("error", errMsg).Msg("Error in hook") } } @@ -266,7 +294,7 @@ func (pr *ProxyImpl) PassThrough(gconn gnet.Conn) *gerr.GatewayDError { "function": "proxy.passthrough", "local": client.Conn.LocalAddr().String(), "remote": client.Conn.RemoteAddr().String(), - }).Msgf("Client disconnected") + }).Msg("Client disconnected") client.Close() client = NewClient( @@ -302,17 +330,22 @@ func (pr *ProxyImpl) PassThrough(gconn gnet.Conn) *gerr.GatewayDError { plugin.OnEgressTraffic, pr.hookConfig.Verification) if err != nil { - pr.logger.Error().Err(err).Msgf("Error running hook: %v", err) + pr.logger.Error().Err(err).Msg("Error running hook") } // If the hook returns a response, use it instead of the original response. if result != nil { if resp, ok := result["response"].([]byte); ok { - pr.logger.Debug().Msgf( - "Hook modified response from %d to %d bytes", len(response), len(resp)) + pr.logger.Debug().Fields( + map[string]interface{}{ + "function": "proxy.passthrough", + "from": len(response), + "to": len(resp), + }, + ).Msg("Hook modified response") response = resp } if errMsg, ok := result["error"].(string); ok && errMsg != "" { - pr.logger.Error().Msgf("Error in hook: %s", errMsg) + pr.logger.Error().Str("error", errMsg).Msg("Error in hook") } } diff --git a/network/server.go b/network/server.go index 0b737e87..b3094345 100644 --- a/network/server.go +++ b/network/server.go @@ -3,6 +3,7 @@ package network import ( "context" "errors" + "fmt" "io" "os" "time" @@ -80,7 +81,8 @@ func (s *Server) OnBoot(engine gnet.Engine) gnet.Action { // OnOpen is called when a new connection is opened. It calls the OnOpening and OnOpened hooks. // It also checks if the server is at the soft or hard limit and closes the connection if it is. func (s *Server) OnOpen(gconn gnet.Conn) ([]byte, gnet.Action) { - s.logger.Debug().Msgf("GatewayD is opening a connection from %s", gconn.RemoteAddr().String()) + s.logger.Debug().Str("from", gconn.RemoteAddr().String()).Msg( + "GatewayD is opening a connection") // Run the OnOpening hooks. onOpeningData := map[string]interface{}{ @@ -143,7 +145,8 @@ func (s *Server) OnOpen(gconn gnet.Conn) ([]byte, gnet.Action) { // It also recycles the connection back to the available connection pool, unless the pool // is elastic and reuse is disabled. func (s *Server) OnClose(gconn gnet.Conn, err error) gnet.Action { - s.logger.Debug().Msgf("GatewayD is closing a connection from %s", gconn.RemoteAddr().String()) + s.logger.Debug().Str("from", gconn.RemoteAddr().String()).Msg( + "GatewayD is closing a connection") // Run the OnClosing hooks. data := map[string]interface{}{ @@ -257,7 +260,8 @@ func (s *Server) OnShutdown(engine gnet.Engine) { // OnTick is called every TickInterval. It calls the OnTick hooks. func (s *Server) OnTick() (time.Duration, gnet.Action) { s.logger.Debug().Msg("GatewayD is ticking...") - s.logger.Info().Msgf("Active connections: %d", s.engine.CountConnections()) + s.logger.Info().Str("count", fmt.Sprint(s.engine.CountConnections())).Msg( + "Active client connections") // Run the OnTick hooks. _, err := s.hooksConfig.Run( @@ -276,7 +280,7 @@ func (s *Server) OnTick() (time.Duration, gnet.Action) { // Run starts the server and blocks until the server is stopped. It calls the OnRun hooks. func (s *Server) Run() error { - s.logger.Info().Msgf("GatewayD is running with PID %d", os.Getpid()) + s.logger.Info().Str("pid", fmt.Sprint(os.Getpid())).Msg("GatewayD is running") // Try to resolve the address and log an error if it can't be resolved addr, err := Resolve(s.Network, s.Address, s.logger) @@ -298,7 +302,7 @@ func (s *Server) Run() error { if result != nil { if errMsg, ok := result["error"].(string); ok && errMsg != "" { - s.logger.Error().Msgf("Error in hook: %s", errMsg) + s.logger.Error().Str("error", errMsg).Msg("Error in hook") } if address, ok := result["address"].(string); ok { @@ -359,11 +363,12 @@ func NewServer( if addr != "" { server.Address = addr - logger.Debug().Msgf("Resolved address to %s", addr) - logger.Info().Msgf("GatewayD is listening on %s", addr) + logger.Debug().Str("address", addr).Msg("Resolved address") + logger.Info().Str("address", addr).Msg("GatewayD is listening") } else { logger.Error().Msg("Failed to resolve address") - logger.Warn().Msgf("GatewayD is listening on %s (unresolved address)", server.Address) + logger.Warn().Str("address", server.Address).Msg( + "GatewayD is listening on an unresolved address") } // Get the current limits. @@ -375,7 +380,7 @@ func NewServer( logger.Debug().Msg("Soft limit is not set, using the current system soft limit") } else { server.SoftLimit = softLimit - logger.Debug().Msgf("Soft limit is set to %d", softLimit) + logger.Debug().Str("value", fmt.Sprint(softLimit)).Msg("Set soft limit") } if hardLimit == 0 { @@ -383,7 +388,7 @@ func NewServer( logger.Debug().Msg("Hard limit is not set, using the current system hard limit") } else { server.HardLimit = hardLimit - logger.Debug().Msgf("Hard limit is set to %d", hardLimit) + logger.Debug().Str("value", fmt.Sprint(hardLimit)).Msg("Set hard limit") } if tickInterval == 0 { diff --git a/network/utils.go b/network/utils.go index 6cdebbfd..b6923031 100644 --- a/network/utils.go +++ b/network/utils.go @@ -17,8 +17,8 @@ func GetRLimit(logger zerolog.Logger) syscall.Rlimit { if err := syscall.Getrlimit(syscall.RLIMIT_NOFILE, &limits); err != nil { //nolint:nosnakecase logger.Error().Err(err).Msg("Failed to get rlimit") } - logger.Debug().Msgf("Current system soft limit: %d", limits.Cur) - logger.Debug().Msgf("Current system hard limit: %d", limits.Max) + logger.Debug().Str("value", fmt.Sprint(limits.Cur)).Msg("Current system soft limit") + logger.Debug().Str("value", fmt.Sprint(limits.Max)).Msg("Current system hard limit") return limits } @@ -54,7 +54,7 @@ func Resolve(network, address string, logger zerolog.Logger) (string, *gerr.Gate } return "", gerr.ErrResolveFailed.Wrap(err) default: - logger.Error().Msgf("Network %s is not supported", network) + logger.Error().Str("network", network).Msg("Network is not supported") return "", gerr.ErrNetworkNotSupported } } diff --git a/plugin/hooks.go b/plugin/hooks.go index 67afba8e..916fe5dc 100644 --- a/plugin/hooks.go +++ b/plugin/hooks.go @@ -78,7 +78,12 @@ func (h *HookConfig) Add(hookType HookType, prio Priority, hook HookDef) { h.hooks[hookType] = map[Priority]HookDef{prio: hook} } else { if _, ok := h.hooks[hookType][prio]; ok { - h.Logger.Warn().Msgf("Hook %s replaced with priority %d.", hookType, prio) + h.Logger.Warn().Fields( + map[string]interface{}{ + "hookType": hookType, + "priority": prio, + }, + ).Msg("Hook is replaced") } h.hooks[hookType][prio] = hook } diff --git a/plugin/registry.go b/plugin/registry.go index af14e37a..9b4f8d6e 100644 --- a/plugin/registry.go +++ b/plugin/registry.go @@ -106,7 +106,7 @@ func (reg *RegistryImpl) LoadPlugins(pluginConfig *koanf.Koanf) { // Add each plugin to the registry. for priority, name := range plugins { - reg.hooksConfig.Logger.Debug().Msgf("Loading plugin: %s", name) + reg.hooksConfig.Logger.Debug().Str("name", name).Msg("Loading plugin") plugin := &Impl{ ID: Identifier{ Name: name, @@ -114,7 +114,7 @@ func (reg *RegistryImpl) LoadPlugins(pluginConfig *koanf.Koanf) { } if enabled, ok := pluginConfig.Get(name + ".enabled").(bool); !ok || !enabled { - reg.hooksConfig.Logger.Debug().Msgf("Plugin is disabled or is not set: %s", name) + reg.hooksConfig.Logger.Debug().Str("name", name).Msg("Plugin is disabled or is not set") continue } else { plugin.Enabled = enabled @@ -122,14 +122,16 @@ func (reg *RegistryImpl) LoadPlugins(pluginConfig *koanf.Koanf) { if localPath, ok := pluginConfig.Get( name + ".localPath").(string); !ok || localPath == "" { - reg.hooksConfig.Logger.Debug().Msgf("Local file of plugin doesn't exist or is not set: %s", name) + reg.hooksConfig.Logger.Debug().Str("name", name).Msg( + "Local file of plugin doesn't exist or is not set") continue } else { plugin.LocalPath = localPath } if checksum, ok := pluginConfig.Get(name + ".checksum").(string); !ok || checksum == "" { - reg.hooksConfig.Logger.Debug().Msgf("Checksum of plugin doesn't exist or is not set: %s", name) + reg.hooksConfig.Logger.Debug().Str("name", name).Msg( + "Checksum of plugin doesn't exist or is not set") continue } else { plugin.ID.Checksum = checksum @@ -141,8 +143,12 @@ func (reg *RegistryImpl) LoadPlugins(pluginConfig *koanf.Koanf) { reg.hooksConfig.Logger.Debug().Err(err).Msg("Failed to calculate checksum") continue } else if sum != plugin.ID.Checksum { - reg.hooksConfig.Logger.Debug().Msgf( - "Checksum mismatch: %s != %s", sum, plugin.ID.Checksum) + reg.hooksConfig.Logger.Debug().Fields( + map[string]interface{}{ + "calculated": sum, + "expected": plugin.ID.Checksum, + }, + ).Msg("Checksum mismatch") continue } @@ -174,7 +180,7 @@ func (reg *RegistryImpl) LoadPlugins(pluginConfig *koanf.Koanf) { }, ) - reg.hooksConfig.Logger.Debug().Msgf("Plugin loaded: %s", plugin.ID.Name) + reg.hooksConfig.Logger.Debug().Str("name", plugin.ID.Name).Msg("Plugin loaded") if _, err := plugin.Start(); err != nil { reg.hooksConfig.Logger.Debug().Err(err).Msg("Failed to start plugin") } @@ -213,14 +219,15 @@ func (reg *RegistryImpl) LoadPlugins(pluginConfig *koanf.Koanf) { if val, ok := value.(string); ok { plugin.Config[key] = val } else { - reg.hooksConfig.Logger.Debug().Msgf("Failed to decode plugin config: %s", key) + reg.hooksConfig.Logger.Debug().Str("key", key).Msg( + "Failed to decode plugin config") } } reg.Add(plugin) reg.RegisterHooks(plugin.ID) - reg.hooksConfig.Logger.Debug().Msgf("Plugin metadata loaded: %s", plugin.ID.Name) + reg.hooksConfig.Logger.Debug().Str("name", plugin.ID.Name).Msg("Plugin metadata loaded") } } @@ -229,7 +236,8 @@ func (reg *RegistryImpl) LoadPlugins(pluginConfig *koanf.Koanf) { //nolint:funlen func (reg *RegistryImpl) RegisterHooks(id Identifier) { pluginImpl := reg.Get(id) - reg.hooksConfig.Logger.Debug().Msgf("Registering hooks for plugin: %s", pluginImpl.ID.Name) + reg.hooksConfig.Logger.Debug().Str("name", pluginImpl.ID.Name).Msg( + "Registering hooks for plugin") var pluginV1 pluginV1.GatewayDPluginServiceClient var err *gerr.GatewayDError if pluginV1, err = pluginImpl.Dispense(); err != nil { @@ -279,10 +287,10 @@ func (reg *RegistryImpl) RegisterHooks(id Identifier) { case OnNewClient: hookFunc = pluginV1.OnNewClient default: - reg.hooksConfig.Logger.Warn().Msgf("Unknown hook type: %s", hook) + reg.hooksConfig.Logger.Warn().Str("hook", string(hook)).Msg("Unknown hook type") continue } - reg.hooksConfig.Logger.Debug().Msgf("Registering hook: %s", hook) + reg.hooksConfig.Logger.Debug().Str("hook", string(hook)).Msg("Registering hook") reg.hooksConfig.Add(hook, pluginImpl.Priority, hookFunc) } }