Better logging

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

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 - %s - hex=%x", c.Numero, message.ProtocolOpName(), messagePacket)
-			Logger.Printf("<<< %d - %#v", c.Numero, message)
+		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.Tracef("client %d close()", c.Numero)
-		Logger.Printf("client %d close()", c.Numero)
-	}
 	close(c.closing)
 
 	// stop reading from client
 	c.rwc.SetReadDeadline(time.Now().Add(time.Millisecond))
-	if DEBUG {
+	Logger.Tracef("client %d close() - stop reading from client", c.Numero)
-		Logger.Printf("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.Tracef("client %d close() - Abandon signal sent to processors", c.Numero)
-		Logger.Printf("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.Tracef("client [%d] request processors ended", c.Numero)
-		Logger.Printf("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 - %s - hex=%x", c.Numero, m.ProtocolOpName(), data.Bytes())
-		Logger.Printf(">>> %d - %#v", c.Numero, m)
+	Logger.Tracef(">>> [%d] %#v", c.Numero, m)
-	}
+
 	c.bw.Write(data.Bytes())
 	c.bw.Flush()
 }

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)
-)

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)

ldapserver/route.go

@@ -148,11 +148,9 @@ func (h *RouteMux) ServeLDAP(s UserState, w ResponseWriter, r *Message) {
 		}
 
 		if route.label != "" {
-			if DEBUG {
+			Logger.Tracef("")
-				Logger.Printf("")
+			Logger.Tracef(" ROUTE MATCH ; %s", route.label)
-				Logger.Printf(" ROUTE MATCH ; %s", route.label)
+			Logger.Tracef("")
-				Logger.Printf("")
-			}
 		}
 
 		route.handler(s, w, r)

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
 }

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()))

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.Tracef("-- SEARCH REQUEST: --")
-		server.logger.Printf("Request BaseDn=%s", r.BaseObject())
+	server.logger.Tracef("Request BaseDn=%s", r.BaseObject())
-		server.logger.Printf("Request Filter=%s", r.Filter())
+	server.logger.Tracef("Request Filter=%s", r.Filter())
-		server.logger.Printf("Request FilterString=%s", r.FilterString())
+	server.logger.Tracef("Request FilterString=%s", r.FilterString())
-		server.logger.Printf("Request Attributes=%s", r.Attributes())
+	server.logger.Tracef("Request Attributes=%s", r.Attributes())
-		server.logger.Printf("Request TimeLimit=%d", r.TimeLimit().Int())
+	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.Tracef("in %s: %#v", basePath+"/", data)
-		server.logger.Printf("%#v", entries)
+	server.logger.Tracef("%#v", entries)
-	}
 
 	for dn, entry := range entries {
 		// Filter out if we don't match requested filter

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

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) {

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 {