From da2c37bb955bbdfceb95bbcc48e1267716152804 Mon Sep 17 00:00:00 2001 From: Alex Auvolat Date: Sat, 1 Feb 2020 15:05:44 +0100 Subject: [PATCH] Better logging --- README.md | 7 +++++ ldapserver/client.go | 37 +++++++++++-------------- ldapserver/logger.go | 32 +++++----------------- ldapserver/packet.go | 2 +- ldapserver/route.go | 8 +++--- ldapserver/server.go | 2 +- main.go | 64 +++++++++++++++++++++++++++++--------------- read.go | 22 +++++++-------- ssha.go | 3 ++- util.go | 2 +- write.go | 2 +- 11 files changed, 92 insertions(+), 89 deletions(-) diff --git a/README.md b/README.md index 671a79a..c7e09b2 100644 --- a/README.md +++ b/README.md @@ -35,6 +35,13 @@ bind to the admin entity and that allows the admin entity to do everything. # Configuration of Bottin +## Logging + +Bottin supports all of the log levels of [logrus](https://github.com/sirupsen/logrus). +The log level can be specified in the key `log_level` of the json config file, +or in the environment variable `BOTTIN_LOG_LEVEL`. +By default, the log level is set to `info`. + ## The LDAP suffix Bottin only handles LDAP entries under a given path, which is typically of diff --git a/ldapserver/client.go b/ldapserver/client.go index 681aa76..7ab043d 100644 --- a/ldapserver/client.go +++ b/ldapserver/client.go @@ -134,9 +134,12 @@ func (c *client) serve() { Logger.Printf("Error reading Message : %s\n\t%x", err.Error(), messagePacket.bytes) continue } - if TRACE { - //Logger.Printf("<<< %d - %s - hex=%x", c.Numero, message.ProtocolOpName(), messagePacket) - Logger.Printf("<<< %d - %#v", c.Numero, message) + + //Logger.Printf("<<< %d - %s - hex=%x", c.Numero, message.ProtocolOpName(), messagePacket) + if br, ok := message.ProtocolOp().(ldap.BindRequest); ok { + Logger.Debugf("<<< [%d] (bind request for %s)", c.Numero, br.Name()) + } else { + Logger.Debugf("<<< [%d] %#v", c.Numero, message) } // TODO: Use a implementation to limit runnuning request by client @@ -175,47 +178,39 @@ func (c *client) serve() { // * close client connection // * signal to server that client shutdown is ok func (c *client) close() { - if DEBUG { - Logger.Printf("client %d close()", c.Numero) - } + Logger.Tracef("client %d close()", c.Numero) close(c.closing) // stop reading from client c.rwc.SetReadDeadline(time.Now().Add(time.Millisecond)) - if DEBUG { - Logger.Printf("client %d close() - stop reading from client", c.Numero) - } + Logger.Tracef("client %d close() - stop reading from client", c.Numero) // signals to all currently running request processor to stop c.mutex.Lock() for messageID, request := range c.requestList { - Logger.Printf("Client %d close() - sent abandon signal to request[messageID = %d]", c.Numero, messageID) + Logger.Debugf("Client %d close() - sent abandon signal to request[messageID = %d]", c.Numero, messageID) go request.Abandon() } c.mutex.Unlock() - if DEBUG { - Logger.Printf("client %d close() - Abandon signal sent to processors", c.Numero) - } + Logger.Tracef("client %d close() - Abandon signal sent to processors", c.Numero) c.wg.Wait() // wait for all current running request processor to end close(c.chanOut) // No more message will be sent to client, close chanOUT - if DEBUG { - Logger.Printf("client [%d] request processors ended", c.Numero) - } + Logger.Tracef("client [%d] request processors ended", c.Numero) <-c.writeDone // Wait for the last message sent to be written c.rwc.Close() // close client connection - Logger.Printf("client [%d] connection closed", c.Numero) + Logger.Debugf("client [%d] connection closed", c.Numero) c.srv.wg.Done() // signal to server that client shutdown is ok } func (c *client) writeMessage(m *ldap.LDAPMessage) { data, _ := m.Write() - if TRACE { - //Logger.Printf(">>> %d - %s - hex=%x", c.Numero, m.ProtocolOpName(), data.Bytes()) - Logger.Printf(">>> %d - %#v", c.Numero, m) - } + + //Logger.Printf(">>> %d - %s - hex=%x", c.Numero, m.ProtocolOpName(), data.Bytes()) + Logger.Tracef(">>> [%d] %#v", c.Numero, m) + c.bw.Write(data.Bytes()) c.bw.Flush() } diff --git a/ldapserver/logger.go b/ldapserver/logger.go index 9f145cf..9286956 100644 --- a/ldapserver/logger.go +++ b/ldapserver/logger.go @@ -1,36 +1,18 @@ package ldapserver import ( - "io/ioutil" - "log" "os" + + log "github.com/sirupsen/logrus" ) -var Logger logger +var Logger *log.Logger -const DEBUG = false -const TRACE = false - -// Logger represents log.Logger functions from the standard library -type logger interface { - Fatal(v ...interface{}) - Fatalf(format string, v ...interface{}) - Fatalln(v ...interface{}) - - Panic(v ...interface{}) - Panicf(format string, v ...interface{}) - Panicln(v ...interface{}) - - Print(v ...interface{}) - Printf(format string, v ...interface{}) - Println(v ...interface{}) -} func init() { - Logger = log.New(os.Stdout, "", log.LstdFlags) + Logger = log.New() + Logger.SetOutput(os.Stdout) + Logger.SetFormatter(&log.TextFormatter{}) + Logger.SetLevel(log.InfoLevel) } -var ( - // DiscardingLogger can be used to disable logging output - DiscardingLogger = log.New(ioutil.Discard, "", 0) -) diff --git a/ldapserver/packet.go b/ldapserver/packet.go index 24d01ed..bd0f6e5 100644 --- a/ldapserver/packet.go +++ b/ldapserver/packet.go @@ -86,7 +86,7 @@ func readTagAndLength(conn *bufio.Reader, bytes *[]byte) (ret ldap.TagAndLength, // } // We are expecting the LDAP sequence tag 0x30 as first byte if b != 0x30 { - panic(fmt.Sprintf("Expecting 0x30 as first byte, but got %#x instead", b)) + return nil, fmt.Errorf("Expecting 0x30 as first byte, but got %#x instead", b) } b, err = readBytes(conn, bytes, 1) diff --git a/ldapserver/route.go b/ldapserver/route.go index ec09f7d..6ced938 100644 --- a/ldapserver/route.go +++ b/ldapserver/route.go @@ -148,11 +148,9 @@ func (h *RouteMux) ServeLDAP(s UserState, w ResponseWriter, r *Message) { } if route.label != "" { - if DEBUG { - Logger.Printf("") - Logger.Printf(" ROUTE MATCH ; %s", route.label) - Logger.Printf("") - } + Logger.Tracef("") + Logger.Tracef(" ROUTE MATCH ; %s", route.label) + Logger.Tracef("") } route.handler(s, w, r) diff --git a/ldapserver/server.go b/ldapserver/server.go index 3640d0a..d4f2128 100644 --- a/ldapserver/server.go +++ b/ldapserver/server.go @@ -36,7 +36,7 @@ func NewServer() *Server { // If a handler already exists for pattern, Handle panics func (s *Server) Handle(h Handler) { if s.Handler != nil { - panic("LDAP: multiple Handler registrations") + Logger.Fatal("LDAP: multiple Handler registrations") } s.Handler = h } diff --git a/main.go b/main.go index fde10b2..f9aef52 100644 --- a/main.go +++ b/main.go @@ -12,7 +12,6 @@ import ( "flag" "fmt" "io/ioutil" - "log" "os" "os/signal" "syscall" @@ -20,10 +19,9 @@ import ( ldap "./ldapserver" consul "github.com/hashicorp/consul/api" message "github.com/vjeantet/goldap/message" + log "github.com/sirupsen/logrus" ) -const DEBUG = false - const ATTR_USERPASSWORD = "userpassword" const ATTR_MEMBER = "member" const ATTR_MEMBEROF = "memberof" @@ -42,6 +40,7 @@ type ConfigFile struct { TLSCertFile string `json:"tls_cert_file"` TLSKeyFile string `json:"tls_key_file"` TLSServerName string `json:"tls_server_name"` + LogLevel string `json:"log_level"` } type Config struct { @@ -49,6 +48,7 @@ type Config struct { Bind string BindSecure string ConsulHost string + LogLevel log.Level Acl ACL @@ -69,7 +69,7 @@ type Entry map[string][]string var configFlag = flag.String("config", "./config.json", "Configuration file path") -func readConfig() Config { +func readConfig(logger *log.Logger) Config { config_file := ConfigFile{ Bind: "0.0.0.0:389", BindSecure: "0.0.0.0:636", @@ -77,17 +77,25 @@ func readConfig() Config { bytes, err := ioutil.ReadFile(*configFlag) if err != nil { - panic(err) + logger.Fatal(err) } err = json.Unmarshal(bytes, &config_file) if err != nil { - panic(err) + logger.Fatal(err) } acl, err := ParseACL(config_file.Acl) if err != nil { - panic(err) + logger.Fatal(err) + } + + log_level := log.InfoLevel + if config_file.LogLevel != "" { + log_level, err = log.ParseLevel(config_file.LogLevel) + if err != nil { + logger.Fatal(err) + } } ret := Config{ @@ -96,20 +104,21 @@ func readConfig() Config { BindSecure: config_file.BindSecure, ConsulHost: config_file.ConsulHost, Acl: acl, + LogLevel: log_level, } if config_file.TLSCertFile != "" && config_file.TLSKeyFile != "" && config_file.TLSServerName != "" { cert_txt, err := ioutil.ReadFile(config_file.TLSCertFile) if err != nil { - panic(err) + logger.Fatal(err) } key_txt, err := ioutil.ReadFile(config_file.TLSKeyFile) if err != nil { - panic(err) + logger.Fatal(err) } cert, err := tls.X509KeyPair(cert_txt, key_txt) if err != nil { - panic(err) + logger.Fatal(err) } ret.TLSConfig = &tls.Config{ MinVersion: tls.VersionTLS10, @@ -125,9 +134,23 @@ func readConfig() Config { func main() { flag.Parse() - ldap.Logger = log.New(os.Stdout, "[ldapserver] ", log.LstdFlags) + logger := log.New() + logger.SetOutput(os.Stdout) + logger.SetFormatter(&log.TextFormatter{}) - config := readConfig() + config := readConfig(logger) + + if log_level := os.Getenv("BOTTIN_LOG_LEVEL"); log_level != "" { + level, err := log.ParseLevel(log_level) + if err != nil { + logger.Fatal(err) + } + logger.SetLevel(level) + } else { + logger.SetLevel(config.LogLevel) + } + + ldap.Logger = logger // Connect to Consul consul_config := consul.DefaultConfig() @@ -136,19 +159,19 @@ func main() { } consul_client, err := consul.NewClient(consul_config) if err != nil { - panic(err) + logger.Fatal(err) } kv := consul_client.KV() // Create bottin server bottin := Server{ - logger: log.New(os.Stdout, "[bottin] ", log.LstdFlags), + logger: logger, config: config, kv: kv, } err = bottin.init() if err != nil { - panic(err) + logger.Fatal(err) } // Create routes @@ -177,7 +200,7 @@ func main() { go func() { err := ldapServer.ListenAndServe(config.Bind) if err != nil { - panic(err) + logger.Fatal(err) } }() } @@ -194,16 +217,16 @@ func main() { go func() { err := ldapServerSecure.ListenAndServe(config.BindSecure, secureConn) if err != nil { - panic(err) + logger.Fatal(err) } }() } else { - log.Printf("Warning: no valid TLS configuration was provided, not binding on %s", config.BindSecure) + logger.Warnf("Warning: no valid TLS configuration was provided, not binding on %s", config.BindSecure) } } if ldapServer == nil && ldapServerSecure == nil { - panic("Not doing anything.") + logger.Fatal("Not doing anything.") } // When CTRL+C, SIGINT and SIGTERM signal occurs @@ -381,7 +404,7 @@ func (server *Server) handleStartTLS(s ldap.UserState, w ldap.ResponseWriter, m w.Write(res) if err := tlsConn.Handshake(); err != nil { - log.Printf("StartTLS Handshake error %v", err) + server.logger.Printf("StartTLS Handshake error %v", err) res.SetDiagnosticMessage(fmt.Sprintf("StartTLS Handshake error : \"%s\"", err.Error())) res.SetResultCode(ldap.LDAPResultOperationsError) w.Write(res) @@ -400,7 +423,6 @@ func (server *Server) handleBind(s ldap.UserState, w ldap.ResponseWriter, m *lda res := ldap.NewBindResponse(result_code) if err != nil { res.SetDiagnosticMessage(err.Error()) - server.logger.Printf("Failed bind for %s: %s", string(r.Name()), err.Error()) } if result_code == ldap.LDAPResultSuccess { server.logger.Printf("Successfully bound to %s", string(r.Name())) diff --git a/read.go b/read.go index 15a2a0b..f95f5f3 100644 --- a/read.go +++ b/read.go @@ -80,14 +80,13 @@ func (server *Server) handleSearch(s ldap.UserState, w ldap.ResponseWriter, m *l } func (server *Server) handleSearchInternal(state *State, w ldap.ResponseWriter, r *message.SearchRequest) (int, error) { - if DEBUG { - server.logger.Printf("-- SEARCH REQUEST: --") - server.logger.Printf("Request BaseDn=%s", r.BaseObject()) - server.logger.Printf("Request Filter=%s", r.Filter()) - server.logger.Printf("Request FilterString=%s", r.FilterString()) - server.logger.Printf("Request Attributes=%s", r.Attributes()) - server.logger.Printf("Request TimeLimit=%d", r.TimeLimit().Int()) - } + + server.logger.Tracef("-- SEARCH REQUEST: --") + server.logger.Tracef("Request BaseDn=%s", r.BaseObject()) + server.logger.Tracef("Request Filter=%s", r.Filter()) + server.logger.Tracef("Request FilterString=%s", r.FilterString()) + server.logger.Tracef("Request Attributes=%s", r.Attributes()) + server.logger.Tracef("Request TimeLimit=%d", r.TimeLimit().Int()) if !server.config.Acl.Check(&state.login, "read", string(r.BaseObject()), []string{}) { return ldap.LDAPResultInsufficientAccessRights, fmt.Errorf("Please specify a base object on which you have read rights") @@ -111,10 +110,9 @@ func (server *Server) handleSearchInternal(state *State, w ldap.ResponseWriter, if err != nil { return ldap.LDAPResultOperationsError, err } - if DEBUG { - server.logger.Printf("in %s: %#v", basePath+"/", data) - server.logger.Printf("%#v", entries) - } + + server.logger.Tracef("in %s: %#v", basePath+"/", data) + server.logger.Tracef("%#v", entries) for dn, entry := range entries { // Filter out if we don't match requested filter diff --git a/ssha.go b/ssha.go index 0443dd0..15b8e1d 100644 --- a/ssha.go +++ b/ssha.go @@ -6,8 +6,9 @@ import ( "crypto/sha1" "encoding/base64" "fmt" - "log" "strings" + + log "github.com/sirupsen/logrus" ) // Encode encodes the []byte of raw password diff --git a/util.go b/util.go index d7c42d7..d778bc2 100644 --- a/util.go +++ b/util.go @@ -3,12 +3,12 @@ package main import ( "encoding/json" "fmt" - "log" "strings" "time" uuid "github.com/google/uuid" consul "github.com/hashicorp/consul/api" + log "github.com/sirupsen/logrus" ) func dnToConsul(dn string) (string, error) { diff --git a/write.go b/write.go index 868761f..492ac99 100644 --- a/write.go +++ b/write.go @@ -337,7 +337,7 @@ func (server *Server) handleModifyInternal(state *State, r *message.ModifyReques continue } if itemDN != dn { - panic("itemDN != dn in handleModifyInternal") + logger.Fatal("itemDN != dn in handleModifyInternal") } vals, err := parseValue(item.Value) if err != nil {