Less logs but better logs

This commit is contained in:
Alex 2020-01-26 19:47:38 +01:00
parent c1f0247586
commit 94eafa2a9b
5 changed files with 73 additions and 26 deletions

View file

@ -134,7 +134,9 @@ func (c *client) serve() {
Logger.Printf("Error reading Message : %s\n\t%x", err.Error(), messagePacket.bytes) Logger.Printf("Error reading Message : %s\n\t%x", err.Error(), messagePacket.bytes)
continue 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 // TODO: Use a implementation to limit runnuning request by client
// solution 1 : when the buffered output channel is full, send a busy // solution 1 : when the buffered output channel is full, send a busy
@ -172,12 +174,16 @@ func (c *client) serve() {
// * close client connection // * close client connection
// * signal to server that client shutdown is ok // * signal to server that client shutdown is ok
func (c *client) close() { func (c *client) close() {
Logger.Printf("client %d close()", c.Numero) if DEBUG {
Logger.Printf("client %d close()", c.Numero)
}
close(c.closing) close(c.closing)
// stop reading from client // stop reading from client
c.rwc.SetReadDeadline(time.Now().Add(time.Millisecond)) 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 // signals to all currently running request processor to stop
c.mutex.Lock() c.mutex.Lock()
@ -186,11 +192,15 @@ func (c *client) close() {
go request.Abandon() go request.Abandon()
} }
c.mutex.Unlock() 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 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 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.writeDone // Wait for the last message sent to be written
c.rwc.Close() // close client connection c.rwc.Close() // close client connection
@ -201,7 +211,9 @@ func (c *client) close() {
func (c *client) writeMessage(m *ldap.LDAPMessage) { func (c *client) writeMessage(m *ldap.LDAPMessage) {
data, _ := m.Write() 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.Write(data.Bytes())
c.bw.Flush() c.bw.Flush()
} }

View file

@ -8,6 +8,8 @@ import (
var Logger logger var Logger logger
const DEBUG = false
// Logger represents log.Logger functions from the standard library // Logger represents log.Logger functions from the standard library
type logger interface { type logger interface {
Fatal(v ...interface{}) Fatal(v ...interface{})

View file

@ -148,10 +148,11 @@ func (h *RouteMux) ServeLDAP(s UserState, w ResponseWriter, r *Message) {
} }
if route.label != "" { if route.label != "" {
Logger.Printf("") if DEBUG {
Logger.Printf(" ROUTE MATCH ; %s", route.label) Logger.Printf("")
Logger.Printf("") Logger.Printf(" ROUTE MATCH ; %s", route.label)
// Logger.Printf(" ROUTE MATCH ; %s", runtime.FuncForPC(reflect.ValueOf(route.handler).Pointer()).Name()) Logger.Printf("")
}
} }
route.handler(s, w, r) route.handler(s, w, r)

58
main.go
View file

@ -1,5 +1,6 @@
package main package main
// @FIXME: Panics if invalid keys are in consul (consulToDN in util.go)
// @FIXME: Implement missing search filters (in applyFilter) // @FIXME: Implement missing search filters (in applyFilter)
// @FIXME: Add an initial prefix to the consul key value // @FIXME: Add an initial prefix to the consul key value
@ -22,6 +23,8 @@ import (
message "github.com/vjeantet/goldap/message" message "github.com/vjeantet/goldap/message"
) )
const DEBUG = false
type ConfigFile struct { type ConfigFile struct {
Suffix string `json:"suffix"` Suffix string `json:"suffix"`
BindAddress string `json:"bind_address"` BindAddress string `json:"bind_address"`
@ -43,6 +46,7 @@ type Config struct {
} }
type Server struct { type Server struct {
logger *log.Logger
config Config config Config
kv *consul.KV kv *consul.KV
} }
@ -108,7 +112,7 @@ func readConfig() Config {
} }
func main() { func main() {
ldap.Logger = log.New(os.Stdout, "[server] ", log.LstdFlags) ldap.Logger = log.New(os.Stdout, "[ldapserver] ", log.LstdFlags)
config := readConfig() config := readConfig()
@ -124,7 +128,11 @@ func main() {
kv := consul_client.KV() kv := consul_client.KV()
// Create gobottin server // 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() err = gobottin.init()
if err != nil { if err != nil {
panic(err) panic(err)
@ -219,7 +227,7 @@ func (server *Server) init() error {
return err 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.", "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_dn,
admin_pass_str, admin_pass_str,
@ -314,7 +322,12 @@ func (server *Server) handleBind(s ldap.UserState, w ldap.ResponseWriter, m *lda
res := ldap.NewBindResponse(result_code) res := ldap.NewBindResponse(result_code)
if err != nil { if err != nil {
res.SetDiagnosticMessage(err.Error()) 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) 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) { func (server *Server) handleSearchInternal(state *State, w ldap.ResponseWriter, r *message.SearchRequest) (int, error) {
log.Printf("-- SEARCH REQUEST: --") if DEBUG {
log.Printf("Request BaseDn=%s", r.BaseObject()) server.logger.Printf("-- SEARCH REQUEST: --")
log.Printf("Request Filter=%s", r.Filter()) server.logger.Printf("Request BaseDn=%s", r.BaseObject())
log.Printf("Request FilterString=%s", r.FilterString()) server.logger.Printf("Request Filter=%s", r.Filter())
log.Printf("Request Attributes=%s", r.Attributes()) server.logger.Printf("Request FilterString=%s", r.FilterString())
log.Printf("Request TimeLimit=%d", r.TimeLimit().Int()) 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{}) { 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") 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 { if err != nil {
return ldap.LDAPResultOperationsError, err return ldap.LDAPResultOperationsError, err
} }
log.Printf("in %s: %#v", basePath+"/", data) if DEBUG {
log.Printf("%#v", entries) server.logger.Printf("in %s: %#v", basePath+"/", data)
server.logger.Printf("%#v", entries)
}
for dn, entry := range entries { for dn, entry := range entries {
// Filter out if we don't match requested filter // 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 { if err != nil {
res.SetDiagnosticMessage(err.Error()) 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)) w.Write(message.AddResponse(res))
} }
@ -599,7 +621,7 @@ func (server *Server) handleAddInternal(state *State, r *message.AddRequest) (in
for _, mb := range memberGroups { for _, mb := range memberGroups {
if mb == dn { if mb == dn {
alreadyMember = true 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) member, dn)
break break
} }
@ -681,6 +703,11 @@ func (server *Server) handleDelete(s ldap.UserState, w ldap.ResponseWriter, m *l
if err != nil { if err != nil {
res.SetDiagnosticMessage(err.Error()) 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)) w.Write(message.DelResponse(res))
} }
@ -768,6 +795,11 @@ func (server *Server) handleModify(s ldap.UserState, w ldap.ResponseWriter, m *l
if err != nil { if err != nil {
res.SetDiagnosticMessage(err.Error()) 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)) w.Write(message.ModifyResponse(res))
} }

View file

@ -40,8 +40,9 @@ func consulToDN(key string) (string, string) {
} }
dn = cpath + dn dn = cpath + dn
} }
log.Printf("Consul key %s does not end with attribute=something", key) // TODO don't panic, handle this
panic("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) { func parseValue(value []byte) ([]string, error) {
@ -64,7 +65,6 @@ func parseConsulResult(data []*consul.KVPair) (map[string]Entry, error) {
aggregator := map[string]Entry{} aggregator := map[string]Entry{}
for _, kv := range data { for _, kv := range data {
log.Printf("(parseConsulResult) %s %s", kv.Key, string(kv.Value))
dn, attr := consulToDN(kv.Key) dn, attr := consulToDN(kv.Key)
if _, exists := aggregator[dn]; !exists { if _, exists := aggregator[dn]; !exists {
aggregator[dn] = Entry{} aggregator[dn] = Entry{}