diff --git a/config.go b/config.go index 01c7939..94804e9 100644 --- a/config.go +++ b/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 } diff --git a/example.yaml b/example.yaml index 1036aef..0e678ba 100644 --- a/example.yaml +++ b/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. diff --git a/go.mod b/go.mod index b61a14c..d2e7d50 100644 --- a/go.mod +++ b/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 +) diff --git a/go.sum b/go.sum index dfc2ce6..e859ca2 100644 --- a/go.sum +++ b/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= diff --git a/main.go b/main.go index e690fed..2187337 100644 --- a/main.go +++ b/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) diff --git a/protocol.go b/protocol.go index 81d8977..7d9be6c 100644 --- a/protocol.go +++ b/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) } diff --git a/server.go b/server.go index af24be1..09edcc9 100644 --- a/server.go +++ b/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() } }