feat: improve logging

CHANGELOG.md

@@ -19,17 +19,21 @@ and this project adheres to [Semantic Versioning][].
 
 * `a2s_info_ping_seconds` metric with A2S_INFO response time in seconds
 * read/idle/write timeouts in http server listener
+* extend logging
 * `.golangci.yml` config and fix linting issues
 * automatically turn on colors in log if terminal is used
 * simple css style for index page
 * 32x32 and 64x64 winres icons for cli
 
 ### Changed
 
+* fixed the `game` label previously could use the server description,
+  now only the `folder` from `a2s`
 * update Grafana dashboard panels
 * replaced `github.com/rumblefrog/go-a2s` with `github.com/woozymasta/a2s`
 * replaced `github.com/sirupsen/logrus` with `github.com/rs/zerolog`
 * internal dependencies for cli are moved to `internal/`
+* logs are output to `stdout` rather than `stderr`
 
 [0.3.0]: https://github.com/WoozyMasta/dayz-exporter/compare/v0.2.0...v0.3.0
 

cli/args.go

@@ -31,7 +31,7 @@ func parseArgs() {
 	case "--get-env", "-e":
 		printExampleConfig(".env file", exampleEnv)
 	default:
-		fmt.Println("Unknown command. Use --help for a list of available commands.")
+		fmt.Fprintf(os.Stderr, "Unknown command. Use --help for a list of available commands.")
 		os.Exit(0)
 	}
 }

cli/auth.go

@@ -4,37 +4,54 @@ import (
 	"encoding/base64"
 	"net/http"
 	"strings"
+
+	"github.com/rs/zerolog/log"
 )
 
 // Middleware for Basic Auth
-func basicAuthMiddleware(mux http.Handler, config Listen) http.Handler {
+func basicAuthMiddleware(next http.Handler, config Listen) http.Handler {
 	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
-		// exclude probes
+		// exclude probes if config.HealthAuth == false
 		if !config.HealthAuth && strings.HasPrefix(r.URL.Path, "/health") {
-			mux.ServeHTTP(w, r)
+			log.Trace().Msg("Health check endpoint, skipping auth")
+			next.ServeHTTP(w, r)
 			return
 		}
 
 		auth := r.Header.Get("Authorization")
 		if auth == "" || !strings.HasPrefix(auth, "Basic ") {
+			log.Warn().Msg("No or invalid 'Authorization' header, returning 401")
 			w.Header().Set("WWW-Authenticate", `Basic realm="Restricted"`)
 			http.Error(w, "Unauthorized", http.StatusUnauthorized)
 			return
 		}
 
 		payload, err := base64.StdEncoding.DecodeString(auth[len("Basic "):])
 		if err != nil {
+			log.Error().Err(err).Msg("Failed to decode base64 authorization header")
 			http.Error(w, "Unauthorized", http.StatusUnauthorized)
 			return
 		}
 
 		pair := strings.SplitN(string(payload), ":", 2)
-		if len(pair) != 2 || pair[0] != config.Username || pair[1] != config.Password {
+		if len(pair) != 2 {
+			log.Debug().Msg("Malformed auth header, returning 401")
+			w.Header().Set("WWW-Authenticate", `Basic realm="Restricted"`)
+			http.Error(w, "Unauthorized", http.StatusUnauthorized)
+			return
+		}
+
+		username, password := pair[0], pair[1]
+		if username != config.Username || password != config.Password {
+			log.Warn().
+				Str("username", username).
+				Msg("Authorization failed, wrong username or password")
 			w.Header().Set("WWW-Authenticate", `Basic realm="Restricted"`)
 			http.Error(w, "Unauthorized", http.StatusUnauthorized)
 			return
 		}
 
-		mux.ServeHTTP(w, r)
+		log.Debug().Msg("User authorized successfully")
+		next.ServeHTTP(w, r)
 	})
 }

cli/config.go

@@ -56,14 +56,23 @@ type Rcon struct {
 // Steam A2S query connection settings
 type Logging struct {
 	Level  string `yaml:"level,omitempty" env:"LEVEL, default=info"`
-	Format string `yaml:"format,omitempty" env:"FORMAT, default=json"`
-	Output string `yaml:"output,omitempty" env:"OUTPUT, default=stderr"`
+	Format string `yaml:"format,omitempty" env:"FORMAT, default=text"`
+	Output string `yaml:"output,omitempty" env:"OUTPUT, default=stdout"`
 }
 
 // config loader
 func loadConfig() (*Config, error) {
 	var config Config
 
+	// initial prepare log level from env for debuging purpose
+	if lvl := os.Getenv("DAYZ_EXPORTER_LOG_LEVEL"); lvl != "" {
+		if logLevel, err := zerolog.ParseLevel(lvl); err == nil {
+			log.Logger = log.Level(logLevel)
+		}
+	} else {
+		log.Logger = log.Level(zerolog.InfoLevel)
+	}
+
 	// load config from file if is exists
 	if path, ok := getConfigPath(); ok {
 		configFile, err := os.Open(path)
@@ -122,6 +131,7 @@ func getConfigPath() (string, bool) {
 		return defaultConfigPath, true
 	}
 
+	log.Trace().Msg("Config file not provided and not found default, work with defaults and environment variables")
 	return "", false
 }
 

cli/example.config.yaml

@@ -35,4 +35,4 @@ rcon:
 logging:
   level: info  # Logging level. Options: 'debug', 'info', 'warn', 'error' (DAYZ_EXPORTER_LOG_LEVEL)
   format: text  # Logging format. Options: 'text' (human-readable) or 'json' (structured) (DAYZ_EXPORTER_LOG_FORMAT)
-  output: stderr  # Output destination for logs. Options: 'stderr' (default) or 'stdout' or a file path (DAYZ_EXPORTER_LOG_OUTPUT)
+  output: stdout  # Output destination for logs. Options: 'stdout' (default) or 'stderr' or a file path (DAYZ_EXPORTER_LOG_OUTPUT)

cli/main.go

@@ -5,6 +5,7 @@ import (
 	"net/http"
 	"time"
 
+	"github.com/rs/zerolog/hlog"
 	"github.com/rs/zerolog/log"
 	"github.com/woozymasta/dayz-exporter/internal/service"
 )
@@ -32,7 +33,7 @@ func runApp() {
 		log.Fatal().Msgf("Failed to establish connections to RCON port %s:%d", config.Rcon.IP, config.Rcon.Port)
 	}
 
-	// init router
+	// create mux
 	mux := http.NewServeMux()
 
 	// handle metrics
@@ -44,17 +45,37 @@ func runApp() {
 	mux.HandleFunc("/health/liveness", connection.livenessHandler)
 	mux.HandleFunc("/health/readiness", connection.readinessHandler)
 
-	// add auth middleware if password set
 	var handler http.Handler = mux
+
+	// add basic auth if password is set
 	if config.Listen.Password != "" {
-		handler = basicAuthMiddleware(mux, config.Listen)
+		handler = basicAuthMiddleware(handler, config.Listen)
 	}
 
-	// serve
+	// wrap all with zerolog/hlog
+	// hlog.NewHandler -> hlog.AccessHandler -> hlog.RemoteAddrHandler -> ...
+	handler = hlog.NewHandler(log.Logger)(
+		hlog.AccessHandler(func(r *http.Request, status, size int, duration time.Duration) {
+			log.Info().
+				Str("method", r.Method).
+				Str("url", r.URL.String()).
+				Str("remote", r.RemoteAddr).
+				Int("status", status).
+				Int("size", size).
+				Dur("duration", duration).
+				Msg("HTTP request completed")
+		})(
+			hlog.RemoteAddrHandler("ip")(
+				hlog.UserAgentHandler("user_agent")(
+					hlog.RefererHandler("referer")(handler),
+				),
+			),
+		),
+	)
+
 	addr := fmt.Sprintf("%s:%d", config.Listen.IP, config.Listen.Port)
 	log.Info().Msgf("Starting metrics server at %s", addr)
 
-	// create HTTP-server with timeouts
 	server := &http.Server{
 		Addr:              addr,
 		Handler:           handler,
@@ -65,6 +86,6 @@ func runApp() {
 	}
 
 	if err := server.ListenAndServe(); err != nil && err != http.ErrServerClosed {
-		log.Fatal().Err(err)
+		log.Fatal().Err(err).Msg("Metrics server failed")
 	}
 }

cli/rcon.go

@@ -91,20 +91,22 @@ func setupConnection(cfg *Config) (*connection, error) {
 func (c *connection) updateServerMetrics() error {
 	info, err := c.query.GetInfo()
 	if err != nil {
-		return fmt.Errorf("failed to get A2S info query response: %w", err)
+		log.Error().Err(err).Msg("Failed to get A2S info query response")
+		return err
 	}
 
 	c.collector.UpdateServerMetrics(info)
+	log.Trace().Msg("Server A2S metrics updated")
 
-	log.Trace().Msgf("metrics updated: server A2S info")
 	return nil
 }
 
 // get and update players metrics from BattleEye RCON
 func (c *connection) updatePlayersMetrics() error {
 	data, err := c.rcon.Send("players")
 	if err != nil {
-		return fmt.Errorf("failed to send 'players' command: %w", err)
+		log.Error().Err(err).Msg("Failed to send 'players' command")
+		return err
 	}
 
 	playersData := beparser.Parse(data, "players")
@@ -113,28 +115,32 @@ func (c *connection) updatePlayersMetrics() error {
 			players.SetCountryCode(c.geo)
 		}
 		c.collector.UpdatePlayerMetrics(players)
-	} else {
-		return fmt.Errorf("unexpected data type for 'players' response")
+		log.Trace().Msg("Player metrics updated")
+
+		return nil
 	}
 
-	log.Trace().Msgf("metrics updated: players data")
-	return nil
+	log.Warn().Msg("Unexpected data type for 'players' response")
+	return fmt.Errorf("unexpected data type for 'players' response")
 }
 
 // get and update bans metrics from BattleEye RCON
 func (c *connection) updateBansMetrics() error {
 	if !c.bans {
+		log.Debug().Msg("Ban metrics disabled, skipping update")
 		return nil
 	}
 
 	_, err := c.rcon.Send("loadBans")
 	if err != nil {
-		return fmt.Errorf("failed to send 'loadBans' command: %w", err)
+		log.Error().Err(err).Msg("Failed to send 'loadBans' command")
+		return err
 	}
 
 	data, err := c.rcon.Send("bans")
 	if err != nil {
-		return fmt.Errorf("failed to send 'bans' command: %w", err)
+		log.Error().Err(err).Msg("Failed to send 'bans' command")
+		return err
 	}
 
 	bansData := beparser.Parse(data, "bans")
@@ -143,12 +149,12 @@ func (c *connection) updateBansMetrics() error {
 			bans.SetCountryCode(c.geo)
 		}
 		c.collector.UpdateBansMetrics(bans)
-	} else {
-		return fmt.Errorf("unexpected data type for 'bans' response")
+		log.Trace().Msg("Bans metrics updated")
+		return nil
 	}
 
-	log.Trace().Msgf("metrics updated: bans data")
-	return nil
+	log.Warn().Msg("Unexpected data type for 'bans' response")
+	return fmt.Errorf("unexpected data type for 'bans' response")
 }
 
 // http handler for update metrics for each request
@@ -176,20 +182,23 @@ func (c *connection) metricsHandler() http.HandlerFunc {
 // error handler in http connection
 func (c *connection) handleError(w http.ResponseWriter, err error, context string) {
 	if err != nil {
-		log.Error().Err(err)
+		log.Error().Err(err).Str("context", context).Msg("Error updating metrics")
 	}
 
 	defer func() {
+		log.Debug().Msg("Resetting metrics and closing connections")
 		c.collector.ResetMetrics()
 
 		if err := c.query.Close(); err != nil {
-			log.Error().Msgf("Cant close query connection")
+			log.Error().Msg("Cant close query connection")
 		}
 		if err := c.rcon.Close(); err != nil {
-			log.Error().Msgf("Cant close rcon connection")
+			log.Error().Msg("Cant close rcon connection")
 		}
-		if err := c.geo.Close(); err != nil {
-			log.Error().Msgf("Cant close geo ip database file")
+		if c.geo != nil {
+			if err := c.geo.Close(); err != nil {
+				log.Error().Msg("Cant close geo ip database file")
+			}
 		}
 	}()
 

cli/routs.go

@@ -4,6 +4,7 @@ import (
 	_ "embed"
 	"internal/vars"
 	"net/http"
+	"strings"
 
 	"github.com/rs/zerolog/log"
 )
@@ -18,44 +19,57 @@ const docsURL = "https://woozymasta.github.io/dayz-exporter/"
 // check is alive
 func (c *connection) livenessHandler(w http.ResponseWriter, r *http.Request) {
 	if r.Method != "GET" {
+		log.Debug().Str("method", r.Method).Msg("Method not allowed on liveness")
 		w.WriteHeader(http.StatusMethodNotAllowed)
 		return
 	}
 
 	if !c.rcon.IsAlive() {
+		log.Warn().Msg("BattleEye RCON not connected")
 		http.Error(w, "BattleEye RCON not connected", http.StatusServiceUnavailable)
 		return
 	}
 
+	log.Trace().Msg("Liveness check OK")
 	w.WriteHeader(http.StatusOK)
 	if _, err := w.Write([]byte("OK")); err != nil {
-		log.Error().Msgf("liveness probe: %v", err)
+		log.Error().Err(err).Msg("Error writing liveness response")
 	}
 }
 
 // simple OK if up and ready to handle requests
 func (c *connection) readinessHandler(w http.ResponseWriter, r *http.Request) {
 	if r.Method != "GET" {
+		log.Debug().Str("method", r.Method).Msg("Method not allowed on readiness")
 		w.WriteHeader(http.StatusMethodNotAllowed)
 		return
 	}
 
+	log.Trace().Msg("Readiness check OK")
 	w.WriteHeader(http.StatusOK)
 	if _, err := w.Write([]byte("OK")); err != nil {
-		log.Error().Msgf("readiness probe: %v", err)
+		log.Error().Err(err).Msg("Error writing readiness response")
 	}
 }
 
 func (c *connection) rootHandler(w http.ResponseWriter, r *http.Request) {
 	if r.Method != "GET" {
+		log.Debug().Str("method", r.Method).Msg("Method not allowed on index page")
 		w.WriteHeader(http.StatusMethodNotAllowed)
 		return
 	}
 
-	game := c.info.Game
-	if game == "" {
-		game = c.info.Folder
+	var serverInfo strings.Builder
+	serverInfo.WriteString("server: " + c.info.Name + "\n")
+	if c.info.Game != "" {
+		serverInfo.WriteString("description: " + c.info.Game + "\n")
 	}
+	serverInfo.WriteString(
+		"map: " + c.info.Map + "\n" +
+			"game: " + c.info.Folder + "\n" +
+			"os: " + c.info.Environment.String() + "\n" +
+			"version: " + c.info.Version,
+	)
 
 	w.Header().Set("Content-Type", "text/html")
 	w.WriteHeader(http.StatusOK)
@@ -85,11 +99,7 @@ func (c *connection) rootHandler(w http.ResponseWriter, r *http.Request) {
 		<hr/>
 		<p>Game server information:</p>
 		<pre>
-server: ` + c.info.Name + `
-map: ` + c.info.Map + `
-game: ` + game + `
-os: ` + c.info.Environment.String() + `
-version: ` + c.info.Version + `
+` + serverInfo.String() + `
 		</pre>
 		<p>Exporter information:</p>
 		<pre>