From 94eafa2a9ba34d2cbcd678fff5a0dcbfcfa40e7c Mon Sep 17 00:00:00 2001 From: Alex Auvolat Date: Sun, 26 Jan 2020 19:47:38 +0100 Subject: [PATCH] Less logs but better logs --- ldapserver/client.go | 24 +++++++++++++----- ldapserver/logger.go | 2 ++ ldapserver/route.go | 9 ++++--- main.go | 58 ++++++++++++++++++++++++++++++++++---------- util.go | 6 ++--- 5 files changed, 73 insertions(+), 26 deletions(-) diff --git a/ldapserver/client.go b/ldapserver/client.go index 501af2a..085041f 100644 --- a/ldapserver/client.go +++ b/ldapserver/client.go @@ -134,7 +134,9 @@ func (c *client) serve() { Logger.Printf("Error reading Message : %s\n\t%x", err.Error(), messagePacket.bytes) continue } - Logger.Printf("<<< %d - %s - hex=%x", c.Numero, message.ProtocolOpName(), messagePacket) + if DEBUG { + Logger.Printf("<<< %d - %s - hex=%x", c.Numero, message.ProtocolOpName(), messagePacket) + } // TODO: Use a implementation to limit runnuning request by client // solution 1 : when the buffered output channel is full, send a busy @@ -172,12 +174,16 @@ func (c *client) serve() { // * close client connection // * signal to server that client shutdown is ok func (c *client) close() { - Logger.Printf("client %d close()", c.Numero) + if DEBUG { + Logger.Printf("client %d close()", c.Numero) + } close(c.closing) // stop reading from client c.rwc.SetReadDeadline(time.Now().Add(time.Millisecond)) - Logger.Printf("client %d close() - stop reading from client", c.Numero) + if DEBUG { + Logger.Printf("client %d close() - stop reading from client", c.Numero) + } // signals to all currently running request processor to stop c.mutex.Lock() @@ -186,11 +192,15 @@ func (c *client) close() { go request.Abandon() } c.mutex.Unlock() - Logger.Printf("client %d close() - Abandon signal sent to processors", c.Numero) + if DEBUG { + 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 - Logger.Printf("client [%d] request processors ended", c.Numero) + if DEBUG { + 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 @@ -201,7 +211,9 @@ func (c *client) close() { func (c *client) writeMessage(m *ldap.LDAPMessage) { data, _ := m.Write() - Logger.Printf(">>> %d - %s - hex=%x", c.Numero, m.ProtocolOpName(), data.Bytes()) + if DEBUG { + Logger.Printf(">>> %d - %s - hex=%x", c.Numero, m.ProtocolOpName(), data.Bytes()) + } c.bw.Write(data.Bytes()) c.bw.Flush() } diff --git a/ldapserver/logger.go b/ldapserver/logger.go index fdac2f4..70352e3 100644 --- a/ldapserver/logger.go +++ b/ldapserver/logger.go @@ -8,6 +8,8 @@ import ( var Logger logger +const DEBUG = false + // Logger represents log.Logger functions from the standard library type logger interface { Fatal(v ...interface{}) diff --git a/ldapserver/route.go b/ldapserver/route.go index d5bd00a..ec09f7d 100644 --- a/ldapserver/route.go +++ b/ldapserver/route.go @@ -148,10 +148,11 @@ func (h *RouteMux) ServeLDAP(s UserState, w ResponseWriter, r *Message) { } if route.label != "" { - Logger.Printf("") - Logger.Printf(" ROUTE MATCH ; %s", route.label) - Logger.Printf("") - // Logger.Printf(" ROUTE MATCH ; %s", runtime.FuncForPC(reflect.ValueOf(route.handler).Pointer()).Name()) + if DEBUG { + Logger.Printf("") + Logger.Printf(" ROUTE MATCH ; %s", route.label) + Logger.Printf("") + } } route.handler(s, w, r) diff --git a/main.go b/main.go index 8894f26..26d46b3 100644 --- a/main.go +++ b/main.go @@ -1,5 +1,6 @@ package main +// @FIXME: Panics if invalid keys are in consul (consulToDN in util.go) // @FIXME: Implement missing search filters (in applyFilter) // @FIXME: Add an initial prefix to the consul key value @@ -22,6 +23,8 @@ import ( message "github.com/vjeantet/goldap/message" ) +const DEBUG = false + type ConfigFile struct { Suffix string `json:"suffix"` BindAddress string `json:"bind_address"` @@ -43,6 +46,7 @@ type Config struct { } type Server struct { + logger *log.Logger config Config kv *consul.KV } @@ -108,7 +112,7 @@ func readConfig() Config { } func main() { - ldap.Logger = log.New(os.Stdout, "[server] ", log.LstdFlags) + ldap.Logger = log.New(os.Stdout, "[ldapserver] ", log.LstdFlags) config := readConfig() @@ -124,7 +128,11 @@ func main() { kv := consul_client.KV() // Create gobottin server - gobottin := Server{config: config, kv: kv} + gobottin := Server{ + logger: log.New(os.Stdout, "[gobottin] ", log.LstdFlags), + config: config, + kv: kv, + } err = gobottin.init() if err != nil { panic(err) @@ -219,7 +227,7 @@ func (server *Server) init() error { return err } - log.Printf( + server.logger.Printf( "It seems to be a new installation, we created a default user for you:\n\n dn: %s\n password: %s\n\nWe didn't use true random, you should replace it as soon as possible.", admin_dn, admin_pass_str, @@ -314,7 +322,12 @@ func (server *Server) handleBind(s ldap.UserState, w ldap.ResponseWriter, m *lda res := ldap.NewBindResponse(result_code) if err != nil { res.SetDiagnosticMessage(err.Error()) - log.Printf("Failed bind for %s: %s", string(r.Name()), 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())) + } else { + server.logger.Printf("Failed to bind to %s (%s)", string(r.Name()), err) } w.Write(res) } @@ -365,12 +378,14 @@ 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) { - log.Printf("-- SEARCH REQUEST: --") - log.Printf("Request BaseDn=%s", r.BaseObject()) - log.Printf("Request Filter=%s", r.Filter()) - log.Printf("Request FilterString=%s", r.FilterString()) - log.Printf("Request Attributes=%s", r.Attributes()) - log.Printf("Request TimeLimit=%d", r.TimeLimit().Int()) + 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()) + } 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") @@ -394,8 +409,10 @@ func (server *Server) handleSearchInternal(state *State, w ldap.ResponseWriter, if err != nil { return ldap.LDAPResultOperationsError, err } - log.Printf("in %s: %#v", basePath+"/", data) - log.Printf("%#v", entries) + if DEBUG { + server.logger.Printf("in %s: %#v", basePath+"/", data) + server.logger.Printf("%#v", entries) + } for dn, entry := range entries { // Filter out if we don't match requested filter @@ -511,6 +528,11 @@ func (server *Server) handleAdd(s ldap.UserState, w ldap.ResponseWriter, m *ldap if err != nil { res.SetDiagnosticMessage(err.Error()) } + if code == ldap.LDAPResultSuccess { + server.logger.Printf("Successfully added %s", string(r.Entry())) + } else { + server.logger.Printf("Failed to add %s (%s)", string(r.Entry()), err) + } w.Write(message.AddResponse(res)) } @@ -599,7 +621,7 @@ func (server *Server) handleAddInternal(state *State, r *message.AddRequest) (in for _, mb := range memberGroups { if mb == dn { alreadyMember = true - log.Printf("Warning: inconsistency detected, %s was memberOf %s at a time when it didn't exist!", + server.logger.Printf("Warning: inconsistency detected, %s was memberOf %s at a time when it didn't exist!", member, dn) break } @@ -681,6 +703,11 @@ func (server *Server) handleDelete(s ldap.UserState, w ldap.ResponseWriter, m *l if err != nil { res.SetDiagnosticMessage(err.Error()) } + if code == ldap.LDAPResultSuccess { + server.logger.Printf("Successfully deleted %s", string(r)) + } else { + server.logger.Printf("Failed to delete %s (%s)", string(r), err) + } w.Write(message.DelResponse(res)) } @@ -768,6 +795,11 @@ func (server *Server) handleModify(s ldap.UserState, w ldap.ResponseWriter, m *l if err != nil { res.SetDiagnosticMessage(err.Error()) } + if code == ldap.LDAPResultSuccess { + server.logger.Printf("Successfully modified %s", string(r.Object())) + } else { + server.logger.Printf("Failed to modifiy %s (%s)", string(r.Object()), err) + } w.Write(message.ModifyResponse(res)) } diff --git a/util.go b/util.go index 30f9681..d8ae58e 100644 --- a/util.go +++ b/util.go @@ -40,8 +40,9 @@ func consulToDN(key string) (string, string) { } dn = cpath + dn } - log.Printf("Consul key %s does not end with attribute=something", key) - panic("TODO don't panic handle this") + // TODO don't panic, handle this + log.Panicf("Consul key %s does not end with attribute=something", key) + panic("unreachable") } func parseValue(value []byte) ([]string, error) { @@ -64,7 +65,6 @@ func parseConsulResult(data []*consul.KVPair) (map[string]Entry, error) { aggregator := map[string]Entry{} for _, kv := range data { - log.Printf("(parseConsulResult) %s %s", kv.Key, string(kv.Value)) dn, attr := consulToDN(kv.Key) if _, exists := aggregator[dn]; !exists { aggregator[dn] = Entry{}