Commit 070500a9 authored by ale's avatar ale

Improve logging of all requests in a uniform manner

parent 7e23df34
Pipeline #3586 passed with stages
in 2 minutes
......@@ -297,24 +297,50 @@ func (s *Server) getUser(ctx context.Context, service *service, username string)
// Authenticate a user with the parameters specified in the incoming AuthRequest.
func (s *Server) Authenticate(ctx context.Context, req *auth.Request) *auth.Response {
var errmsg string
resp, err := s.doAuthenticate(ctx, req)
if err != nil {
errmsg = fmt.Sprintf(" error=%v", err)
resp = newError()
}
// Log the request.
var ipstr string
if req.DeviceInfo != nil && req.DeviceInfo.RemoteAddr != "" {
ipstr = fmt.Sprintf(" ip=%s", req.DeviceInfo.RemoteAddr)
}
log.Printf("auth: user=%s service=%s status=%s%s%s", req.Username, req.Service, resp.Status.String(), ipstr, errmsg)
// Increment the request counter.
authRequestsCounter.With(prometheus.Labels{
"service": req.Service,
"status": resp.Status.String(),
}).Inc()
return resp
}
var (
errServiceUnknown = errors.New("unknown service")
errUserUnknown = errors.New("unknown user")
errRatelimited = errors.New("ratelimited")
)
// Function with the actual authentication API logic - we return either a
// successful Response, or an error. The Authenticate() wrapper turns the
// latter into a Response with Status: Error, but this function stays
// readable.
func (s *Server) doAuthenticate(ctx context.Context, req *auth.Request) (*auth.Response, error) {
start := time.Now()
svc, ok := s.getService(req.Service)
if !ok {
log.Printf("unknown service %s", req.Service)
return newError()
return nil, errServiceUnknown
}
user, ok := s.getUser(ctx, svc, req.Username)
if !ok {
// User is unknown to all backends. Do not proceed
// further, but log and increment stats counters.
log.Printf("unknown user %s", req.Username)
authRequestsCounter.With(prometheus.Labels{
"service": req.Service,
"status": "unknown_user",
})
return newError()
// User is unknown to all backends.
return nil, errUserUnknown
}
// Apply rate limiting and blacklisting _before_ invoking the
......@@ -323,31 +349,20 @@ func (s *Server) Authenticate(ctx context.Context, req *auth.Request) *auth.Resp
ratelimitCounter.With(prometheus.Labels{
"service": req.Service,
}).Inc()
return newError()
return nil, errRatelimited
}
resp, err := s.authenticateUser(req, svc, user)
if err != nil {
resp = newError()
log.Printf("auth: user=%s service=%s status=%s error=%s", req.Username, req.Service, resp.Status.String(), err)
} else {
// Log the request and response.
log.Printf("auth: user=%s service=%s status=%s", req.Username, req.Service, resp.Status.String())
}
// Notify blacklists of the result.
svc.notifyBlacklists(user, req, resp)
// Increment stats counters.
authRequestsCounter.With(prometheus.Labels{
"service": req.Service,
"status": resp.Status.String(),
}).Inc()
authRequestLatency.With(prometheus.Labels{
"service": req.Service,
}).Observe(time.Since(start).Seconds() * 1000)
return resp
// Notify blacklists of the result.
svc.notifyBlacklists(user, req, resp)
return resp, err
}
// Authenticate a user. Returning an error should result in an
......
......@@ -2,6 +2,7 @@ package server
import (
"fmt"
"log"
"strings"
"sync"
"time"
......@@ -144,6 +145,7 @@ func (b *Blacklist) Incr(key string) {
d.counter++
b.r.set(key, d)
} else if d.counter == limitp1 {
log.Printf("blacklisted %s", key)
b.bl[key] = time.Now().Unix() + b.blTime
}
b.r.mx.Unlock()
......@@ -255,7 +257,7 @@ func (b *authBlacklist) Allow(user *backend.User, req *auth.Request) bool {
}
func (b *authBlacklist) Incr(user *backend.User, req *auth.Request, resp *auth.Response) {
if b.onFailure && resp.Status == auth.StatusOK {
if b.onFailure && resp != nil && resp.Status == auth.StatusOK {
return
}
b.bl.Incr(b.key(user, req))
......
Markdown is supported
0% or
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment