Added json logging

config.go

@@ -8,10 +8,11 @@ import (
 	"crypto/tls"
 	"fmt"
 	"io/ioutil"
-	"log"
 	"net"
 	"path/filepath"
 
+	"github.com/rs/zerolog"
+	"github.com/rs/zerolog/log"
 	"go.etcd.io/bbolt"
 	"gopkg.in/yaml.v3"
 )
@@ -30,6 +31,7 @@ type Resource struct {
 type Config struct {
 	MaxQueue   int             `yaml:"max_queue"`
 	MaxPacket  int64           `yaml:"max_packet"`
+	LogLevel   string          `yaml:"log_level"`
 	RawBind    string          `yaml:"raw-bind"`
 	TlsBind    string          `yaml:"tls-bind"`
 	TlsKey     string          `yaml:"tls-key"`
@@ -52,12 +54,30 @@ func readConfig(filename string, config *Config) error {
 	}
 
 	if len(config.Authorized) < 1 {
-		log.Fatal("`authorized` is not defined or is empty.")
+		log.Fatal().Msg("`authorized` is not defined or is empty.")
 	} else if config.MaxPacket < MAX_BODY_LEN {
-		log.Fatal("`max_packet` is not defined or is less than 1Mb.")
+		log.Fatal().Msg("`max_packet` is not defined or is less than 1Mb.")
+	} else if len(config.LogLevel) < 1 {
+		log.Fatal().Msg("`log_level` is not defined or is empty.")
 	}
 
 	MAX_BODY_LEN = config.MaxPacket
+
+	// setup logger.
+	zerolog.TimeFieldFormat = zerolog.TimeFormatUnix
+	switch {
+	case config.LogLevel == "fatal":
+		zerolog.SetGlobalLevel(zerolog.FatalLevel)
+	case config.LogLevel == "error":
+		zerolog.SetGlobalLevel(zerolog.ErrorLevel)
+	case config.LogLevel == "warn":
+		zerolog.SetGlobalLevel(zerolog.WarnLevel)
+	case config.LogLevel == "info":
+		zerolog.SetGlobalLevel(zerolog.InfoLevel)
+	default:
+		zerolog.SetGlobalLevel(zerolog.DebugLevel)
+	}
+
 	return nil
 }
 
@@ -79,25 +99,25 @@ func (c *Config) GetListeners() (net.Listener, net.Listener) {
 	var err error
 
 	if c.RawBind == "" && c.TlsBind == "" {
-		log.Fatal("`bind` and `tls-bind` are not defined or empty.")
+		log.Fatal().Msg("`bind` and `tls-bind` are not defined or empty.")
 	}
 
 	if c.RawBind != "" {
 		lraw, err = net.Listen("tcp", c.RawBind)
 		if err != nil {
-			log.Fatal(err)
+			log.Fatal().Err(err).Send()
 		}
 	}
 
 	if exists(c.TlsCert) && exists(c.TlsKey) && c.TlsBind != "" {
 		cert, err := tls.LoadX509KeyPair(c.TlsCert, c.TlsKey)
 		if err != nil {
-			log.Fatal(err)
+			log.Fatal().Err(err).Send()
 		}
 		tlsConfig := &tls.Config{Certificates: []tls.Certificate{cert}}
 		ltls, err = tls.Listen("tcp", c.TlsBind, tlsConfig)
 		if err != nil {
-			log.Fatal(err)
+			log.Fatal().Err(err).Send()
 		}
 	}
 
@@ -110,7 +130,7 @@ func (c *Config) LoadResources() (map[string][]*bbolt.DB, map[string]*bbolt.DB)
 	var err error = nil
 
 	if len(c.Resources) < 1 && c.UploadDir == "" {
-		log.Fatal("`resources` is empty or not defined in the config file")
+		log.Fatal().Msg("`resources` is empty or not defined in the config file")
 	}
 
 	resources[GENERIC_DB] = []*bbolt.DB{}
@@ -129,15 +149,15 @@ func (c *Config) LoadResources() (map[string][]*bbolt.DB, map[string]*bbolt.DB)
 		for _, file := range res.Files {
 			dbFile, err := filepath.Abs(file)
 			if err != nil {
-				log.Fatal(err)
+				log.Fatal().Err(err).Send()
 			}
 
 			db, err := OpenDatabase(dbFile)
 			if err != nil {
-				log.Fatal(err)
+				log.Fatal().Err(err).Send()
 			}
 			search = append(search, db)
-			log.Println(key, ":", dbFile)
+			log.Debug().Msgf("%s : %s", key, dbFile)
 		}
 
 		resources[key] = search
@@ -146,9 +166,9 @@ func (c *Config) LoadResources() (map[string][]*bbolt.DB, map[string]*bbolt.DB)
 	if c.UploadDir != "" {
 		c.UploadDir, err = filepath.Abs(c.UploadDir)
 		if err != nil {
-			log.Fatal(err)
+			log.Fatal().Err(err).Send()
 		} else if !exists(c.UploadDir) {
-			log.Fatal(c.UploadDir, "does not exists!")
+			log.Fatal().Msgf("'%s' does not exists!", c.UploadDir)
 		}
 
 		search := resources[GENERIC_DB]
@@ -161,12 +181,12 @@ func (c *Config) LoadResources() (map[string][]*bbolt.DB, map[string]*bbolt.DB)
 
 			db, err := OpenDatabase(dbFile)
 			if err != nil {
-				log.Fatal(err)
+				log.Fatal().Err(err).Send()
 			}
 
 			search = append(search, db)
 			shared[key] = db
-			log.Println(key, ":", dbFile)
+			log.Info().Msgf("%s : %s", key, dbFile)
 		}
 		resources[GENERIC_DB] = search
 	}

example.yaml

@@ -8,6 +8,9 @@ max_queue: 1024
 # Max packet size in bytes.
 max_packet: 5242880 # 5Mb
 
+# Available log levels: fatal, error, warn, info, debug
+log_level: "debug"
+
 # Bind address for raw tcp socket
 raw-bind: ":25000"
 # Bind address for TLS tcp socket.

go.mod

@@ -3,9 +3,14 @@ module rz-silhouette-server
 go 1.20
 
 require (
+	github.com/rs/zerolog v1.29.0
 	go.etcd.io/bbolt v1.3.7
 	google.golang.org/protobuf v1.30.0
 	gopkg.in/yaml.v3 v3.0.1
 )
 
-require golang.org/x/sys v0.6.0 // indirect
+require (
+	github.com/mattn/go-colorable v0.1.12 // indirect
+	github.com/mattn/go-isatty v0.0.14 // indirect
+	golang.org/x/sys v0.6.0 // indirect
+)

go.sum

@@ -1,11 +1,23 @@
+github.com/coreos/go-systemd/v22 v22.3.3-0.20220203105225-a9a7ef127534/go.mod h1:Y58oyj3AT4RCenI/lSvhwexgC+NSVTIJ3seZv2GcEnc=
 github.com/davecgh/go-spew v1.1.1 h1:vj9j/u1bqnvCEfJOwUhtlOARqs3+rkHYY13jYWTU97c=
+github.com/godbus/dbus/v5 v5.0.4/go.mod h1:xhWf0FNVPg57R7Z0UbKHbJfkEywrmjJnf7w5xrFpKfA=
 github.com/golang/protobuf v1.5.0/go.mod h1:FsONVRAS9T7sI+LIUmWTfcYkHO4aIWwzhcaSAoJOfIk=
 github.com/google/go-cmp v0.5.5 h1:Khx7svrCpmxxtHBq5j2mp/xVjsi8hQMfNLvJFAlrGgU=
 github.com/google/go-cmp v0.5.5/go.mod h1:v8dTdLbMG2kIc/vJvl+f65V22dbkXbowE6jgT/gNBxE=
+github.com/mattn/go-colorable v0.1.12 h1:jF+Du6AlPIjs2BiUiQlKOX0rt3SujHxPnksPKZbaA40=
+github.com/mattn/go-colorable v0.1.12/go.mod h1:u5H1YNBxpqRaxsYJYSkiCWKzEfiAb1Gb520KVy5xxl4=
+github.com/mattn/go-isatty v0.0.14 h1:yVuAays6BHfxijgZPzw+3Zlu5yQgKGP2/hcQbHb7S9Y=
+github.com/mattn/go-isatty v0.0.14/go.mod h1:7GGIvUiUoEMVVmxf/4nioHXj79iQHKdU27kJ6hsGG94=
+github.com/pkg/errors v0.9.1/go.mod h1:bwawxfHBFNV+L2hUp1rHADufV3IMtnDRdf1r5NINEl0=
 github.com/pmezard/go-difflib v1.0.0 h1:4DBwDE0NGyQoBHbLQYPwSUPoCMWR5BEzIk/f1lZbAQM=
+github.com/rs/xid v1.4.0/go.mod h1:trrq9SKmegXys3aeAKXMUTdJsYXVwGY3RLcfgqegfbg=
+github.com/rs/zerolog v1.29.0 h1:Zes4hju04hjbvkVkOhdl2HpZa+0PmVwigmo8XoORE5w=
+github.com/rs/zerolog v1.29.0/go.mod h1:NILgTygv/Uej1ra5XxGf82ZFSLk58MFGAUS2o6usyD0=
 github.com/stretchr/testify v1.8.1 h1:w7B6lhMri9wdJUVmEZPGGhZzrYTPvgJArz7wNPgYKsk=
 go.etcd.io/bbolt v1.3.7 h1:j+zJOnnEjF/kyHlDDgGnVL/AIqIJPq8UoB2GSNfkUfQ=
 go.etcd.io/bbolt v1.3.7/go.mod h1:N9Mkw9X8x5fupy0IKsmuqVtoGDyxsaDlbk4Rd05IAQw=
+golang.org/x/sys v0.0.0-20210630005230-0f9fa26af87c/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
+golang.org/x/sys v0.0.0-20210927094055-39ccf1dd6fa6/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
 golang.org/x/sys v0.6.0 h1:MVltZSvRTcU2ljQOhs94SXPftV6DCNnZViHeQps87pQ=
 golang.org/x/sys v0.6.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
 golang.org/x/xerrors v0.0.0-20191204190536-9bdfabe68543 h1:E7g+9GITq07hpfrRu66IVDexMakfv52eLZ2CXBWiKr4=

main.go

@@ -5,7 +5,6 @@ package main
 
 import (
 	"flag"
-	"log"
 )
 
 func main() {
@@ -15,7 +14,7 @@ func main() {
 	flag.Parse()
 
 	if err := readConfig(configPath, &config); err != nil {
-		log.Fatal(err)
+		panic(err)
 	}
 
 	server := NewServer(&config)

protocol.go

@@ -7,10 +7,10 @@ import (
 	"bytes"
 	"encoding/binary"
 	"io"
-	"log"
 	"net"
 	"time"
 
+	"github.com/rs/zerolog/log"
 	"google.golang.org/protobuf/proto"
 )
 
@@ -27,13 +27,13 @@ func readFromConn(conn net.Conn, expected int64) ([]byte, bool) {
 	if err == io.EOF {
 		return nil, false
 	} else if err != nil {
-		log.Printf("%s: %s\n", conn.RemoteAddr(), err)
+		log.Info().Stringer("ip", conn.RemoteAddr()).Err(err).Send()
 		return nil, false
 	}
 
 	b := buffer.Bytes()
 	if len(b) != int(expected) {
-		log.Printf("%s: Expected %d but received only %d\n", conn.RemoteAddr(), expected, len(b))
+		log.Info().Stringer("ip", conn.RemoteAddr()).Msgf("Expected %d but received only %d", expected, len(b))
 		return nil, false
 	}
 	return b, true
@@ -42,25 +42,25 @@ func readFromConn(conn net.Conn, expected int64) ([]byte, bool) {
 func readIncomingRequest(conn net.Conn) *Request {
 	header, ok := readFromConn(conn, HEADER_SIZE)
 	if !ok {
-		log.Printf("%s: Failed to receive packet size..\n", conn.RemoteAddr())
+		log.Info().Stringer("ip", conn.RemoteAddr()).Msg("Failed to receive packet size.")
 		return nil
 	}
 
 	packetSize := int64(binary.BigEndian.Uint32(header))
 	if packetSize > MAX_BODY_LEN {
-		log.Printf("%s: Expected small body size (%d) but received %d\n", conn.RemoteAddr(), MAX_BODY_LEN, packetSize)
+		log.Info().Stringer("ip", conn.RemoteAddr()).Msgf("Expected small body size (%d) but received %d", MAX_BODY_LEN, packetSize)
 		return nil
 	}
 
 	packet, ok := readFromConn(conn, packetSize)
 	if !ok {
-		log.Printf("%s: Failed to receive packet..\n", conn.RemoteAddr())
+		log.Info().Stringer("ip", conn.RemoteAddr()).Msg("Failed to receive packet")
 		return nil
 	}
 
 	req := &Request{}
 	if err := proto.Unmarshal(packet, req); err != nil {
-		log.Printf("%s: Failed to decode request packet (%s).\n", conn.RemoteAddr(), err)
+		log.Info().Stringer("ip", conn.RemoteAddr()).Err(err).Msg("Failed to decode request")
 		return nil
 	}
 
@@ -75,10 +75,10 @@ func writeToConn(conn net.Conn, buffer []byte) bool {
 	if err == io.EOF {
 		return false
 	} else if err != nil {
-		log.Printf("%s: %s\n", conn.RemoteAddr(), err)
+		log.Info().Stringer("ip", conn.RemoteAddr()).Err(err).Send()
 		return false
 	} else if int(written) != len(buffer) {
-		log.Printf("%s: Failed to send all the bytes\n", conn.RemoteAddr())
+		log.Info().Stringer("ip", conn.RemoteAddr()).Msg("Failed to send all the bytes")
 		return false
 	}
 	return true
@@ -91,7 +91,7 @@ func writeOutgoingResponse(conn net.Conn, body proto.Message, status Status) boo
 	if body != nil {
 		message, err = proto.Marshal(body)
 		if err != nil {
-			log.Printf("%s: Failed to encode response message (%s).\n", conn.RemoteAddr(), err)
+			log.Info().Stringer("ip", conn.RemoteAddr()).Err(err).Msg("Failed to encode body")
 			return false
 		}
 	}
@@ -103,7 +103,7 @@ func writeOutgoingResponse(conn net.Conn, body proto.Message, status Status) boo
 
 	packet, err := proto.Marshal(&resp)
 	if err != nil {
-		log.Printf("%s: Failed to encode response packet (%s).\n", conn.RemoteAddr(), err)
+		log.Info().Stringer("ip", conn.RemoteAddr()).Err(err).Msg("Failed to encode response")
 		return false
 	}
 
@@ -112,7 +112,7 @@ func writeOutgoingResponse(conn net.Conn, body proto.Message, status Status) boo
 	if writeToConn(conn, header) && writeToConn(conn, packet) {
 		return true
 	}
-	log.Printf("%s: Failed to send response packet.\n", conn.RemoteAddr())
+	log.Info().Stringer("ip", conn.RemoteAddr()).Msg("Failed to send response packet")
 	return false
 }
 
@@ -126,7 +126,12 @@ func handlePingRequest(server *Server, conn net.Conn, request *Request) {
 func handleBinaryRequest(server *Server, conn net.Conn, request *Request) {
 	var binary = Binary{}
 	if err := proto.Unmarshal(request.Message, &binary); err != nil {
-		log.Printf("%s: Failed to decode binary message (%s).\n", conn.RemoteAddr(), err)
+		log.Info().
+			Stringer("ip", conn.RemoteAddr()).
+			Str("psk", request.Psk).
+			Stringer("route", request.Route).
+			Err(err).
+			Send()
 		return
 	}
 
@@ -152,7 +157,11 @@ func handleBinaryRequest(server *Server, conn net.Conn, request *Request) {
 func handleSignatureRequest(server *Server, conn net.Conn, request *Request) {
 	var signature = Signature{}
 	if err := proto.Unmarshal(request.Message, &signature); err != nil {
-		log.Printf("%s: Failed to decode signature message (%s).\n", conn.RemoteAddr(), err)
+		log.Info().Stringer("ip", conn.RemoteAddr()).
+			Str("psk", request.Psk).
+			Stringer("route", request.Route).
+			Err(err).
+			Send()
 		return
 	}
 
@@ -168,7 +177,11 @@ func handleShareBinRequest(server *Server, conn net.Conn, request *Request) {
 
 	var bin = ShareBin{}
 	if err := proto.Unmarshal(request.Message, &bin); err != nil {
-		log.Printf("%s: Failed to decode share bin message (%v).\n", conn.RemoteAddr(), err)
+		log.Info().Stringer("ip", conn.RemoteAddr()).
+			Str("psk", request.Psk).
+			Stringer("route", request.Route).
+			Err(err).
+			Send()
 		return
 	}
 
@@ -187,19 +200,32 @@ func handleShareBinRequest(server *Server, conn net.Conn, request *Request) {
 	writeOutgoingResponse(conn, nil, Status_SHARE_WAS_SUCCESSFUL)
 }
 
+func logRequest(conn net.Conn, request *Request, start time.Time) {
+	end := time.Now()
+	log.Warn().
+		Stringer("ip", conn.RemoteAddr()).
+		Str("psk", request.Psk).
+		Stringer("route", request.Route).
+		TimeDiff("duration", end, start).
+		Send()
+}
+
 func handleConnection(server *Server, conn net.Conn) {
+	var start = time.Now()
 	var request *Request = nil
+
 	defer conn.Close()
 
 	request = readIncomingRequest(conn)
 	if request == nil {
 		return
-	} else if !server.IsAuthorized(request) {
+	}
+
+	if !server.IsAuthorized(request) {
 		writeOutgoingResponse(conn, nil, Status_CLIENT_BAD_PRE_SHARED_KEY)
+		logRequest(conn, request, start)
+
 		return
-	} else {
-		name := Route_name[int32(request.Route)]
-		log.Printf("%s '%s' has connected (%s).\n", conn.RemoteAddr(), request.Psk, name)
 	}
 
 	switch request.Route {
@@ -212,7 +238,6 @@ func handleConnection(server *Server, conn net.Conn) {
 	case Route_SHARE_BIN:
 		handleShareBinRequest(server, conn, request)
 	default:
-		log.Printf("%s: failed to understand the route id %d.\n", conn.RemoteAddr(), int32(request.Route))
 	}
-
+	logRequest(conn, request, start)
 }

server.go

@@ -5,13 +5,13 @@ package main
 
 import (
 	"fmt"
-	"log"
 	"net"
 	"runtime"
 	"strings"
 	"sync"
 	"time"
 
+	"github.com/rs/zerolog/log"
 	"go.etcd.io/bbolt"
 )
 
@@ -78,7 +78,7 @@ func (s *Server) GetSymbol(psk string, sig *Signature) *Symbol {
 	for _, db := range dbs {
 		sym, err := DbGetSymbol(db, key)
 		if err != nil {
-			log.Println(psk, err)
+			log.Error().Str("psk", psk).Err(err).Send()
 			continue
 		} else if sym != nil {
 			return sym
@@ -98,7 +98,7 @@ func (s *Server) SetSymbol(psk string, sig *Signature, sym *Symbol) {
 	for _, db := range dbs {
 		found, err := DbHasSymbol(db, key)
 		if err != nil {
-			log.Println(psk, err)
+			log.Error().Str("psk", psk).Err(err).Send()
 			continue
 		} else if found {
 			// don't do anything if the hints are known.
@@ -108,7 +108,7 @@ func (s *Server) SetSymbol(psk string, sig *Signature, sym *Symbol) {
 
 	db := s.GetShareDB(psk)
 	if db == nil {
-		log.Println(psk, "tried to upload hints but db was not found.")
+		log.Error().Str("psk", psk).Msg("tried to upload hints but db was not found")
 		return
 	}
 
@@ -128,9 +128,9 @@ func (s *Server) SetSymbol(psk string, sig *Signature, sym *Symbol) {
 	err := DbSetSymbol(db, key, psk, sym)
 	s.mutex.Unlock()
 	if err != nil {
-		log.Println(psk, err)
+		log.Error().Str("psk", psk).Err(err).Send()
 	} else {
-		log.Printf("'%s' added '%s|%d|%s' symbol\n", psk, sig.Arch, sig.Bits, sym.Name)
+		log.Warn().Str("psk", psk).Str("arch", sig.Arch).Uint32("bits", sig.Bits).Str("name", sym.Name).Send()
 	}
 }
 
@@ -140,7 +140,7 @@ func (s *Server) GetHints(psk string, bin *Binary, sec *SectionHash) []*Hint {
 	for _, db := range dbs {
 		hints, err := DbGetHints(db, key)
 		if err != nil {
-			log.Println(psk, err)
+			log.Error().Str("psk", psk).Err(err).Send()
 			continue
 		} else if hints != nil {
 			return hints
@@ -158,7 +158,7 @@ func (s *Server) SetHints(psk string, bin *ShareBin, sec *ShareSection) {
 	for _, db := range dbs {
 		found, err := DbHasHints(db, key)
 		if err != nil {
-			log.Println(psk, err)
+			log.Error().Str("psk", psk).Err(err).Send()
 			continue
 		} else if found {
 			// don't do anything if the hints are known.
@@ -168,7 +168,7 @@ func (s *Server) SetHints(psk string, bin *ShareBin, sec *ShareSection) {
 
 	db := s.GetShareDB(psk)
 	if db == nil {
-		log.Println(psk, "tried to upload hints but db was not found.")
+		log.Error().Str("psk", psk).Msg("tried to upload hints but db was not found")
 		return
 	}
 
@@ -176,9 +176,9 @@ func (s *Server) SetHints(psk string, bin *ShareBin, sec *ShareSection) {
 	err := DbSetHints(db, key, psk, sec.Name, sec.Hints)
 	s.mutex.Unlock()
 	if err != nil {
-		log.Println(psk, err)
+		log.Error().Str("psk", psk).Err(err).Send()
 	} else {
-		log.Printf("'%s' added '%s' and %d hints\n", psk, sec.Name, len(sec.Hints))
+		log.Warn().Str("psk", psk).Str("section", sec.Name).Int("hints", len(sec.Hints)).Send()
 	}
 }
 
@@ -206,19 +206,19 @@ func (s *Server) Worker() {
 }
 
 func (s *Server) Listen(listener net.Listener) {
-	log.Printf("listening at %s\n", listener.Addr())
+	log.Warn().Msgf("listening at %s", listener.Addr())
 
 	defer listener.Close()
 	for {
 		conn, err := listener.Accept()
 		if err != nil {
-			log.Println(err)
+			log.Error().Err(err).Send()
 			continue
 		}
 		select {
 		case s.queue <- conn:
 		default:
-			log.Printf("%s connected but channel was full.\n", conn.RemoteAddr())
+			log.Error().Stringer("ip", conn.RemoteAddr()).Msg("client connected but channel was full")
 			conn.Close()
 		}
 	}