Skip to content

Commit

Permalink
implement audit log tracing (minio#12)
Browse files Browse the repository at this point in the history
This commit adds support for tracing
audit log events.

Therefore, this commit removes the global
HTTP write timeout. The problem with server-wide
timeouts is that as a HTTP handler you cannot
adjust/opt-out of the timeout. This makes it
impossible to implement long-running server tasks
like tracing logs.

Instead, this commit implements a custom timeout
handler - similar to https://golang.org/pkg/net/http#TimeoutHandler
The custom timeout handler and Go's TimeoutHandler
differ in implementation details. See documentation.

Now, each HTTP handler that requires a (write) timeout
must be wrapped by a timeout handler. The server-wide
write-timeout is explicitly set to 0.

Further, this commit implements a audit log tracing CLI
that prints a human-readable text output to a TTY and JSON
otherwise.
  • Loading branch information
Andreas Auernhammer authored Jan 30, 2020
1 parent a5b760d commit ff44277
Show file tree
Hide file tree
Showing 8 changed files with 426 additions and 24 deletions.
55 changes: 50 additions & 5 deletions audit.go
Original file line number Diff line number Diff line change
Expand Up @@ -64,7 +64,7 @@ func (l *SystemLog) RemoveOutput(out io.Writer) {
l.lock.Lock()
defer l.lock.Unlock()

var output = make([]io.Writer, 0, len(l.output))
output := make([]io.Writer, 0, len(l.output))
for i := range l.output {
if out != l.output[i] {
output = append(output, l.output[i])
Expand All @@ -90,6 +90,7 @@ type auditResponseWriter struct {
URL url.URL // The request URL
Identity Identity // The request X.509 identity
RequestHeader http.Header // The request headers
Time time.Time // The time when we receive the request

logger *log.Logger
written bool // Set to true on first write
Expand All @@ -100,11 +101,15 @@ func (w *auditResponseWriter) Header() http.Header {
}

func (w *auditResponseWriter) WriteHeader(statusCode int) {
const format = `{"time":"%s","request":{"path":"%s","identity":"%s"},"response":{"code":%d}}`
w.logger.Printf(format, time.Now().Format(time.RFC3339), w.URL.Path, w.Identity, statusCode)
if !w.written {
w.written = true

now := time.Now().UTC()
const format = `{"time":"%s","request":{"path":"%s","identity":"%s"},"response":{"code":%d, "time":%d}}`
w.logger.Printf(format, now.Format(time.RFC3339), w.URL.Path, w.Identity, statusCode, now.Sub(w.Time.UTC()))

w.ResponseWriter.WriteHeader(statusCode)
w.written = true
w.ResponseWriter.WriteHeader(statusCode)
}
}

func (w *auditResponseWriter) Write(b []byte) (int, error) {
Expand All @@ -119,3 +124,43 @@ func (w *auditResponseWriter) Flush() {
flusher.Flush()
}
}

// A flushWriter wraps and io.Writer and performs
// a flush operation after every write call if the
// wrapped io.Writer implements http.Flusher.
//
// A flushWriter is useful when (even small) data
// should reach the receiver as soon as possible.
// For example, in case of audit logging.
type flushWriter struct {
io.Writer
http.Flusher
}

// newFlushWriter returns a new flushWriter that
// wraps w and flushes everything written to it
// as soon as possible if w implements http.Flusher.
func newFlushWriter(w io.Writer) flushWriter {
fw := flushWriter{Writer: w}
if flusher, ok := w.(http.Flusher); ok {
fw.Flusher = flusher
}
return fw
}

func (w flushWriter) Write(p []byte) (int, error) {
n, err := w.Writer.Write(p)
if w.Flusher != nil {
// TODO(aead): Flushing after every write may
// be not very efficient (benchmarks required!)
// since we perform one/multiple system calls
// per write.
// However, buffering does not seem possible
// since a flushWriter is in particularly used for
// audit log tracing and we cannot afford loosing
// an audit event.
// Therefore, no (more) efficient solution known, yet.
w.Flusher.Flush()
}
return n, err
}
15 changes: 15 additions & 0 deletions client.go
Original file line number Diff line number Diff line change
Expand Up @@ -287,6 +287,21 @@ func (c *Client) ForgetIdentity(id Identity) error {
return nil
}

func (c *Client) TraceAuditLog() (io.ReadCloser, error) {
req, err := http.NewRequest(http.MethodGet, fmt.Sprintf("%s/v1/log/audit/trace", c.addr), nil)
if err != nil {
return nil, err
}
resp, err := c.httpClient.Do(req)
if err != nil {
return nil, err
}
if resp.StatusCode != http.StatusOK {
return nil, c.parseErrorResponse(resp)
}
return resp.Body, nil
}

func (c *Client) parseErrorResponse(resp *http.Response) error {
if resp.Body == nil {
return nil
Expand Down
155 changes: 155 additions & 0 deletions cmd/kes/audit.go
Original file line number Diff line number Diff line change
@@ -0,0 +1,155 @@
package main

import (
"bufio"
"crypto/tls"
"encoding/json"
"flag"
"fmt"
"net/http"
"os"
"os/signal"
"runtime"
"syscall"
"time"

"github.com/fatih/color"
"github.com/minio/kes"
)

const auditCmdUsage = `usage: %s <command>
trace Trace the audit log output.
-h, --help Show list of command-line options.
`

func audit(args []string) error {
cli := flag.NewFlagSet(args[0], flag.ExitOnError)
cli.Usage = func() {
fmt.Fprintf(cli.Output(), auditCmdUsage, cli.Name())
}

cli.Parse(args[1:])
if args = cli.Args(); len(args) == 0 {
cli.Usage()
os.Exit(2)
}

switch args[0] {
case "trace":
return auditTrace(args)
default:
cli.Usage()
os.Exit(2)
return nil // for the compiler
}
}

const auditTraceCmdUsage = `Trace and print audit log events.
Connects to a KES server as audit log device and print an audit
log event for each request/response pair processed by the server.
It will print the audit log events as readable text representation
when writing to a tty. Otherwise it will print events as
line-separated JSON (nd-json)
usage: %s [flags]
--json Print audit log events as JSON.
-k, --insecure Skip X.509 certificate validation during TLS handshake.
-h, --help Show list of command-line options.
`

func auditTrace(args []string) error {
cli := flag.NewFlagSet(args[0], flag.ExitOnError)
cli.Usage = func() {
fmt.Fprintf(cli.Output(), auditTraceCmdUsage, cli.Name())
}

var jsonOutput bool
var insecureSkipVerify bool
cli.BoolVar(&jsonOutput, "json", false, "Print audit log events as JSON")
cli.BoolVar(&insecureSkipVerify, "k", false, "Skip X.509 certificate validation during TLS handshake")
cli.BoolVar(&insecureSkipVerify, "insecure", false, "Skip X.509 certificate validation during TLS handshake")
if args = parseCommandFlags(cli, args[1:]); len(args) != 0 {
cli.Usage()
os.Exit(2)
}

certificates, err := loadClientCertificates()
if err != nil {
return err
}
client := kes.NewClient(serverAddr(), &tls.Config{
InsecureSkipVerify: insecureSkipVerify,
Certificates: certificates,
})

reader, err := client.TraceAuditLog()
if err != nil {
return err
}
defer reader.Close()

sigCh := make(chan os.Signal)
signal.Notify(sigCh, syscall.SIGINT, syscall.SIGTERM)
go func() {
<-sigCh
if err := reader.Close(); err != nil {
fmt.Fprintln(cli.Output(), err)
}
}()

type AuditEntry struct {
Time time.Time `json:"time"`
Request struct {
Path string `json:"path"`
Identity kes.Identity `json:"identity"`
} `json:"request"`
Response struct {
Code int `json:"code"`
Time time.Duration `json:"time"`
} `json:"response"`
}

isTerminal := isTerm(os.Stdout)
scanner := bufio.NewScanner(reader)
for scanner.Scan() {
if err = scanner.Err(); err != nil {
return err
}
if isTerminal && !jsonOutput {
var entry AuditEntry
if err = json.Unmarshal(scanner.Bytes(), &entry); err != nil {
return err
}
if len(entry.Request.Identity) > 7 { // only show a short identity - similar to git commits
entry.Request.Identity = entry.Request.Identity[:7]
}

var status string
var identity string
if runtime.GOOS == "windows" { // don't colorize on windows
status = fmt.Sprintf("[%d %s]", entry.Response.Code, http.StatusText(entry.Response.Code))
identity = entry.Request.Identity.String()
} else {
if entry.Response.Code == http.StatusOK {
status = color.GreenString("[%d %s]", entry.Response.Code, http.StatusText(entry.Response.Code))
} else {
status = color.RedString("[%d %s]", entry.Response.Code, http.StatusText(entry.Response.Code))
}
identity = color.YellowString(entry.Request.Identity.String())
}

const format = "%s %s %-25s %10s\n"
fmt.Printf(format, identity, status, entry.Request.Path, entry.Response.Time.Truncate(1*time.Microsecond))
} else {
fmt.Println(scanner.Text())
}
}
return nil

}
3 changes: 3 additions & 0 deletions cmd/kes/main.go
Original file line number Diff line number Diff line change
Expand Up @@ -22,6 +22,7 @@ const usage = `usage: %s <command>
key Manage secret keys.
policy Manage the kes server policies.
identity Assign policies to identities.
audit Manage the kes server audit logs.
tool Run specific key and identity management tools.
Expand Down Expand Up @@ -51,6 +52,8 @@ func main() {
err = identity(args)
case "policy":
err = policy(args)
case "audit":
err = audit(args)
case "tool":
err = tool(args)
default:
Expand Down
Loading

0 comments on commit ff44277

Please sign in to comment.