Merge pull request #1868 from molecula/security-logging

FB1109: authn/z audit logging
This commit is contained in:
reese 2022-01-15 12:43:32 -06:00 committed by GitHub
commit 80f9ddaa02
No known key found for this signature in database
GPG key ID: 4AEE18F83AFDEB23
6 changed files with 163 additions and 112 deletions

View file

@ -54,7 +54,7 @@ type Handler struct {
logger logger.Logger
querylogger logger.Logger
queryLogger logger.Logger
// Keeps the query argument validators for each handler
validators map[string]*queryValidationSpec
@ -152,7 +152,7 @@ func OptHandlerLogger(logger logger.Logger) handlerOption {
func OptHandlerQueryLogger(logger logger.Logger) handlerOption {
return func(h *Handler) error {
h.querylogger = logger
h.queryLogger = logger
return nil
}
}
@ -285,13 +285,8 @@ const (
contextKeyQueryRequest contextKeyQuery = iota
contextKeyQueryError
contextKeyGroupMembership
contextKeyPermission
)
func GetContextKeyPermission() contextKeyQuery {
return contextKeyPermission
}
// addQueryContext puts the results of handler.readQueryRequest into the Context for use by
// both other middleware and any handlers.
func (h *Handler) addQueryContext(next http.Handler) http.Handler {
@ -573,82 +568,112 @@ func (h *Handler) chkAuthN(handler http.HandlerFunc) http.HandlerFunc {
func (h *Handler) chkAuthZ(handler http.HandlerFunc, perm authz.Permission) http.HandlerFunc {
return func(w http.ResponseWriter, r *http.Request) {
lperm := perm
if h.auth != nil {
uinfo, err := h.auth.Authenticate(getToken(r))
if err != nil {
http.Error(w, errors.Wrap(err, "authenticating").Error(), http.StatusForbidden)
return
}
if h.permissions == nil {
h.logger.Errorf("authentication is turned on without authorization permissions set")
http.Error(w, "authorizing", http.StatusInternalServerError)
return
}
ctx := context.WithValue(r.Context(), contextKeyGroupMembership, uinfo.Groups)
if h.permissions.IsAdmin(uinfo.Groups) {
ctx = context.WithValue(ctx, contextKeyPermission, authz.Admin)
handler.ServeHTTP(w, r.WithContext(ctx))
return
} else if lperm == authz.Admin {
http.Error(w, "Insufficient permissions: user does not have admin permission", http.StatusForbidden)
return
}
var queryString string
queryRequest := r.Context().Value(contextKeyQueryRequest)
if req, ok := queryRequest.(*pilosa.QueryRequest); ok {
queryString = req.Query
q, err := pql.ParseString(queryString)
if err != nil {
http.Error(w, errors.Wrap(err, "parsing query string").Error(), http.StatusBadRequest)
return
}
if q.WriteCallN() > 0 {
lperm = authz.Write
}
}
queryString = strings.Replace(queryString, "\n", "", -1)
if r.Method == "POST" {
h.querylogger.Infof("User ID: %s, User Name: %s, Endpoint: %s, Index: %s, Query: %s, Err: %v", uinfo.UserID, uinfo.UserName, r.URL.Path, "indexName", queryString, err)
}
ctx = context.WithValue(r.Context(), contextKeyGroupMembership, uinfo.Groups)
indexName, ok := mux.Vars(r)["index"]
if !ok {
indexName = r.URL.Query().Get("index")
}
if indexName != "" {
p, err := h.permissions.GetPermissions(uinfo, indexName)
ctx = context.WithValue(r.Context(), contextKeyPermission, p)
if err != nil {
w.Header().Add("Content-Type", "text/plain")
http.Error(w, errors.Wrap(err, "Insufficient Permissions").Error(), http.StatusForbidden)
return
}
if !p.Satisfies(lperm) {
w.Header().Add("Content-Type", "text/plain")
http.Error(w, fmt.Sprintf("Insufficient permissions: user has %s permissions, but request requires %s permission", p, lperm), http.StatusForbidden)
return
}
}
handler.ServeHTTP(w, r.WithContext(ctx))
} else {
// if auth isn't turned on, just serve the request
if h.auth == nil {
handler.ServeHTTP(w, r)
return
}
// make a copy of the requested permissions
lperm := perm
// check if the user is authenticated
uinfo, err := h.auth.Authenticate(getToken(r))
if err != nil {
http.Error(w, errors.Wrap(err, "authenticating").Error(), http.StatusForbidden)
return
}
// put the user's groups in the context
ctx := context.WithValue(r.Context(), contextKeyGroupMembership, uinfo.Groups)
// unlikely h.permissions will be nil, but we'll check to be safe
if h.permissions == nil {
h.logger.Errorf("authentication is turned on without authorization permissions set")
http.Error(w, "authorizing", http.StatusInternalServerError)
return
}
// figure out what the user is querying for
queryString := ""
queryRequest := r.Context().Value(contextKeyQueryRequest)
if req, ok := queryRequest.(*pilosa.QueryRequest); ok {
queryString = req.Query
q, err := pql.ParseString(queryString)
if err != nil {
http.Error(w, errors.Wrap(err, "parsing query string").Error(), http.StatusBadRequest)
return
}
// if there are write calls, and the needed perms don't already
// satisfy write permissions, then make them write permissions
if q.WriteCallN() > 0 && !lperm.Satisfies(authz.Write) {
lperm = authz.Write
}
}
// make the query string pretty
queryString = strings.Replace(queryString, "\n", "", -1)
// figure out if we should log this query
toLog := true
for _, ep := range []string{"/status", "/metrics", "/info", "/internal"} {
if strings.HasPrefix(r.URL.Path, ep) {
toLog = false
break
}
}
if toLog {
h.queryLogger.Infof("%v, %v, %v, %v, %v, %v", GetIP(r), r.UserAgent(), r.URL.Path, uinfo.UserID, uinfo.UserName, queryString)
}
// if they're an admin, they can do whatever they want
if h.permissions.IsAdmin(uinfo.Groups) {
handler.ServeHTTP(w, r.WithContext(ctx))
return
} else if lperm == authz.Admin {
// if they're not an admin, and they need to be, we can just
// error right here
http.Error(w, "Insufficient permissions: user does not have admin permission", http.StatusForbidden)
return
}
// try to get the index name
indexName, ok := mux.Vars(r)["index"]
if !ok {
indexName = r.URL.Query().Get("index")
}
// if we have an index name, then we check the user permissions
// against that index
if indexName != "" {
p, err := h.permissions.GetPermissions(uinfo, indexName)
if err != nil {
w.Header().Add("Content-Type", "text/plain")
http.Error(w, errors.Wrap(err, "Insufficient Permissions").Error(), http.StatusForbidden)
return
}
// if they're not permitted to access this index, error
if !p.Satisfies(lperm) {
w.Header().Add("Content-Type", "text/plain")
http.Error(w, "Insufficient permissions", http.StatusForbidden)
return
}
}
handler.ServeHTTP(w, r.WithContext(ctx))
}
}
func GetIP(r *http.Request) string {
forwarded := r.Header.Get("X-FORWARDED-FOR")
if forwarded != "" {
return forwarded
}
return r.RemoteAddr
}
// statikHandler implements the http.Handler interface, and responds to
// requests for static assets with the appropriate file contents embedded
// in a statik filesystem.

View file

@ -220,7 +220,7 @@ func TestAuthentication(t *testing.T) {
h := Handler{
logger: logger.NewStandardLogger(os.Stdout),
querylogger: logger.NewStandardLogger(os.Stdout),
queryLogger: logger.NewStandardLogger(os.Stdout),
auth: a,
}

View file

@ -67,7 +67,7 @@ type Server struct { // nolint: maligned
systemInfo SystemInfo
gcNotifier GCNotifier
logger logger.Logger
querylogger logger.Logger
queryLogger logger.Logger
snapshotQueue SnapshotQueue
nodeID string
@ -115,7 +115,7 @@ func OptServerLogger(l logger.Logger) ServerOption {
func OptServerQueryLogger(l logger.Logger) ServerOption {
return func(s *Server) error {
s.querylogger = l
s.queryLogger = l
return nil
}
}

View file

@ -27,6 +27,7 @@ import (
"google.golang.org/grpc/codes"
"google.golang.org/grpc/credentials"
"google.golang.org/grpc/metadata"
"google.golang.org/grpc/peer"
"google.golang.org/grpc/reflection"
"google.golang.org/grpc/status"
)
@ -36,6 +37,7 @@ type GRPCHandler struct {
api *pilosa.API
perms *authz.GroupPermissions
logger logger.Logger
queryLogger logger.Logger
stats stats.StatsClient
inspectDeprecated sync.Once
}
@ -59,6 +61,11 @@ func (h *GRPCHandler) WithPerms(perms *authz.GroupPermissions) *GRPCHandler {
return h
}
func (h *GRPCHandler) WithQueryLogger(logger logger.Logger) *GRPCHandler {
h.queryLogger = logger
return h
}
// errorToStatusError appends an appropriate grpc status code
// to the error (returning it as a status.Error).
func errToStatusError(err error) error {
@ -166,6 +173,7 @@ func (h *GRPCHandler) QuerySQL(req *pb.QuerySQLRequest, stream pb.Pilosa_QuerySQ
if err != nil {
return errors.Wrap(err, "parsing SQL")
}
allowed := h.perms.GetAuthorizedIndexList(uinfo.(*authn.UserInfo).Groups, authz.Read)
if !h.perms.IsAdmin(uinfo.(*authn.UserInfo).Groups) {
if !isAllowed(parsed.Tables, allowed) {
@ -1431,8 +1439,9 @@ type grpcServer struct {
auth *authn.Auth
perms *authz.GroupPermissions
logger logger.Logger
stats stats.StatsClient
logger logger.Logger
queryLogger logger.Logger
stats stats.StatsClient
}
type grpcServerOption func(s *grpcServer) error
@ -1486,6 +1495,13 @@ func OptGRPCServerPerm(gp *authz.GroupPermissions) grpcServerOption {
}
}
func OptGRPCServerQueryLogger(logger logger.Logger) grpcServerOption {
return func(s *grpcServer) error {
s.queryLogger = logger
return nil
}
}
func (s *grpcServer) Serve() error {
s.logger.Infof("enabled grpc listening on %s", s.ln.Addr())
@ -1545,7 +1561,7 @@ func NewGRPCServer(opts ...grpcServerOption) (*grpcServer, error) {
if server.auth != nil {
gopts = append(gopts, grpc.UnaryInterceptor(
func(ctx context.Context, req interface{}, info *grpc.UnaryServerInfo, handler grpc.UnaryHandler) (interface{}, error) {
ctx, err := Valid(ctx, server.auth)
ctx, err := Valid(ctx, info.FullMethod, server.auth, req, server.queryLogger)
if err != nil {
return nil, err
}
@ -1554,18 +1570,18 @@ func NewGRPCServer(opts ...grpcServerOption) (*grpcServer, error) {
))
gopts = append(gopts, grpc.StreamInterceptor(
func(srv interface{}, ss grpc.ServerStream, info *grpc.StreamServerInfo, handler grpc.StreamHandler) error {
ctx, err := Valid(ss.Context(), server.auth)
ctx, err := Valid(ss.Context(), info.FullMethod, server.auth, srv, server.queryLogger)
if err != nil {
return err
}
return handler(srv, newWrappedStream(ss, ctx))
return handler(srv, &wrappedStream{ss, ctx})
},
))
}
// create grpc server
server.grpcServer = grpc.NewServer(gopts...)
grpcHandler := NewGRPCHandler(server.api).WithLogger(server.logger).WithStats(server.stats)
grpcHandler := NewGRPCHandler(server.api).WithLogger(server.logger).WithStats(server.stats).WithQueryLogger(server.queryLogger)
// add server permissions if we've got 'em
if server.perms != nil {
@ -1591,6 +1607,7 @@ type wrappedStream struct {
func (w *wrappedStream) Context() context.Context {
return w.uiContext
}
func (w *wrappedStream) RecvMsg(m interface{}) error {
return w.ServerStream.RecvMsg(m)
}
@ -1599,39 +1616,46 @@ func (w *wrappedStream) SendMsg(m interface{}) error {
return w.ServerStream.SendMsg(m)
}
func newWrappedStream(s grpc.ServerStream, ctx context.Context) grpc.ServerStream {
return &wrappedStream{s, ctx}
}
func Valid(ctx context.Context, auth *authn.Auth) (context.Context, error) {
func Valid(ctx context.Context, method string, auth *authn.Auth, req interface{}, logger logger.Logger) (context.Context, error) {
md, ok := metadata.FromIncomingContext(ctx)
if !ok {
return ctx, status.Errorf(codes.InvalidArgument, "missing metadata")
}
authorization, ok := md["authorization"]
authorization, ok := md["authorization"]
if !ok {
c, ok := md["cookie"]
if !ok {
c, there := md["cookie"]
if !there {
return ctx, status.Errorf(codes.InvalidArgument, "missing authorization token")
}
cookies := strings.Split(c[0], "; ")
for _, cookie := range cookies {
if strings.HasPrefix(cookie, "molecula-chip") {
authorization = strings.Split(cookie, "molecula-chip=")[1:]
break
}
}
if len(authorization) == 0 {
return ctx, status.Errorf(codes.InvalidArgument, "missing authorization token")
}
}
if len(authorization) == 0 {
return ctx, status.Errorf(codes.InvalidArgument, "missing authorization token")
}
token := strings.TrimPrefix(authorization[0], "Bearer ")
userinfo, err := auth.Authenticate(token)
uinfo, err := auth.Authenticate(token)
if err != nil {
return ctx, status.Errorf(codes.Unauthenticated, err.Error())
}
return context.WithValue(ctx, "userinfo", userinfo), nil
p, ok := peer.FromContext(ctx)
ip := ""
if ok {
ip = p.Addr.String()
}
ua, ok := md["user-agent"]
if !ok {
ua = []string{""}
}
logger.Infof("GRPC: %v, %v, %v, %v, %v, %v", ip, ua, method, uinfo.UserID, uinfo.UserName, req)
return context.WithValue(ctx, "userinfo", uinfo), nil
}

View file

@ -18,6 +18,7 @@ import (
pilosa "github.com/molecula/featurebase/v2"
"github.com/molecula/featurebase/v2/authn"
"github.com/molecula/featurebase/v2/authz"
"github.com/molecula/featurebase/v2/logger"
"github.com/molecula/featurebase/v2/pql"
pb "github.com/molecula/featurebase/v2/proto"
"github.com/molecula/featurebase/v2/server"
@ -1375,8 +1376,7 @@ func setUpTestQuerySQLUnary(ctx context.Context, t *testing.T) (gh *server.GRPCH
t.Helper()
m := test.RunCommand(t)
gh = server.NewGRPCHandler(m.API)
gh = server.NewGRPCHandler(m.API).WithQueryLogger(logger.NewStandardLogger(os.Stdout))
// grouper
grouper := m.MustCreateIndex(t, "grouper", pilosa.IndexOptions{Keys: false, TrackExistence: true})
m.MustCreateField(t, grouper.Name(), "color", pilosa.OptFieldKeys())

View file

@ -70,9 +70,9 @@ type Command struct {
done chan struct{}
logOutput io.Writer
querylogOutput io.Writer
queryLogOutput io.Writer
logger loggerLogger
querylogger loggerLogger
queryLogger loggerLogger
Handler pilosa.Handler
grpcServer *grpcServer
@ -476,7 +476,7 @@ func (m *Command) SetupServer() error {
pilosa.OptServerOpenTranslateReader(http.GetOpenTranslateReaderWithLockerFunc(c, &sync.Mutex{})),
pilosa.OptServerOpenIDAllocator(pilosa.OpenIDAllocator),
pilosa.OptServerLogger(m.logger),
pilosa.OptServerQueryLogger(m.querylogger),
pilosa.OptServerQueryLogger(m.queryLogger),
pilosa.OptServerSystemInfo(gopsutil.NewSystemInfo()),
pilosa.OptServerGCNotifier(gcnotify.NewActiveGCNotifier()),
pilosa.OptServerStatsClient(statsClient),
@ -545,11 +545,12 @@ func (m *Command) SetupServer() error {
err = m.setupQueryLogger()
if err != nil {
return errors.Wrap(err, "setting up querylogger")
return errors.Wrap(err, "setting up queryLogger")
}
m.querylogger.Infof("Group with admin level access: %v", p.Admin)
m.querylogger.Infof("Permissions: %+v", p.Permissions)
m.queryLogger.Infof("Featurebase Server Started")
m.queryLogger.Infof("Group with admin level access: %v", p.Admin)
m.queryLogger.Infof("Permissions: %+v", p.Permissions)
// disable postgres binding if auth is enabled
m.Config.Postgres.Bind = ""
@ -569,13 +570,14 @@ func (m *Command) SetupServer() error {
OptGRPCServerStats(statsClient),
OptGRPCServerAuth(m.auth),
OptGRPCServerPerm(&p),
OptGRPCServerQueryLogger(m.queryLogger),
)
m.Handler, err = http.NewHandler(
http.OptHandlerAllowedOrigins(m.Config.Handler.AllowedOrigins),
http.OptHandlerAPI(m.API),
http.OptHandlerLogger(m.logger),
http.OptHandlerQueryLogger(m.querylogger),
http.OptHandlerQueryLogger(m.queryLogger),
http.OptHandlerFileSystem(&statik.FileSystem{}),
http.OptHandlerListener(m.ln, m.Config.Advertise),
http.OptHandlerCloseTimeout(m.closeTimeout),
@ -642,16 +644,16 @@ func (m *Command) setupQueryLogger() error {
return errors.Wrap(err, "opening file")
}
}
m.querylogOutput = f
m.queryLogOutput = f
m.querylogger = logger.NewStandardLogger(m.querylogOutput)
m.queryLogger = logger.NewStandardLogger(m.queryLogOutput)
sighup := make(chan os.Signal, 1)
signal.Notify(sighup, syscall.SIGHUP)
go func() {
for range sighup {
if err := f.Reopen(); err != nil {
m.querylogger.Infof("reopen: %s\n", err.Error())
m.queryLogger.Infof("reopen: %s\n", err.Error())
}
}
}()