api-logs.go

package logs

import (
	"net/http"
	"sort"
	"strconv"
	"strings"
	"time"

	"github.com/aws/aws-lambda-go/events"
	"gitlab.com/uafrica/go-utils/errors"
	"gitlab.com/uafrica/go-utils/logger"
	"gitlab.com/uafrica/go-utils/queues"
)

var producer queues.Producer

func Init(p queues.Producer) {
	producer = p
}

//Call this at the end of an API request handler to capture the req/res as well as all actions taken during the processing
//(note: action list is only reset when this is called - so must be called after each handler, else action list has to be reset at the start)
func LogIncomingAPIRequest(startTime time.Time, requestID string, claim map[string]interface{}, req events.APIGatewayProxyRequest, res events.APIGatewayProxyResponse) error {
	if producer == nil {
		return errors.Errorf("logs queue producer not set")
	}

	//todo: filter out some noisy (method+path)
	logger.Debugf("claim: %+v", claim)

	endTime := time.Now()

	var authType string
	var authUsername string
	if req.RequestContext.Identity.CognitoAuthenticationType != "" {
		authType = "cognito"
		split := strings.Split(req.RequestContext.Identity.CognitoAuthenticationProvider, ":")
		if len(split) > 0 {
			authUsername = split[len(split)-1] //= part after last ':'
		}
	} else {
		authType = "iam"
		split := strings.Split(req.RequestContext.Identity.UserArn, ":user/")
		if len(split) > 0 {
			authUsername = split[len(split)-1] //= part after ':user/'
		}
	}

	username, _ := claim["Username"].(string)
	accountID, _ := claim["AccountID"].(int64)
	if accountID == 0 {
		if accountIDParam, ok := req.QueryStringParameters["account_id"]; ok {
			if i64, err := strconv.ParseInt(accountIDParam, 10, 64); err == nil && i64 > 0 {
				accountID = i64
			}
		}
	}
	apiLog := ApiLog{
		StartTime:           startTime,
		EndTime:             endTime,
		DurMs:               endTime.Sub(startTime).Milliseconds(),
		Method:              req.HTTPMethod,
		Address:             req.RequestContext.DomainName,
		Path:                req.Path,
		ResponseCode:        res.StatusCode,
		RequestID:           requestID,
		InitialAuthType:     authType,
		InitialAuthUsername: authUsername,
		SourceIP:            req.RequestContext.Identity.SourceIP,
		UserAgent:           req.RequestContext.Identity.UserAgent,
		Username:            username,
		AccountID:           accountID,
		Request: ApiLogRequest{
			Headers:         req.Headers,
			QueryParameters: req.QueryStringParameters,
			BodySize:        len(req.Body),
			Body:            req.Body,
		},
		Response: ApiLogResponse{
			Headers:  res.Headers,
			BodySize: len(res.Body),
			Body:     res.Body,
		},
		Actions: nil,
	}

	//compile action list
	apiLog.Actions = relativeActionList(apiLog.StartTime, apiLog.EndTime)

	//sort action list on startTime, cause actions are added when they end, i.e. ordered by end time
	//and all non-actions were appended at the end of the list
	sort.Slice(apiLog.Actions, func(i, j int) bool { return apiLog.Actions[i].StartMs < apiLog.Actions[j].StartMs })

	//also copy multi-value query parameters to the log as CSV array values
	for n, as := range req.MultiValueQueryStringParameters {
		apiLog.Request.QueryParameters[n] = "[" + strings.Join(as, ",") + "]"
	}

	//todo: filter out excessive req/res body content per (method+path)
	//todo: also need to do for all actions...
	if apiLog.Method == http.MethodGet {
		apiLog.Response.Body = "<not logged>"
	}

	logger.Debugf("Send api-log to SQS: %+v", apiLog)

	//todo: filter out sensitive values (e.g. OTP)
	if _, err := producer.NewEvent("API_LOGS").
		Type("api-log").
		RequestID(apiLog.RequestID).
		Send(apiLog); err != nil {
		return errors.Wrapf(err, "failed to send api-log")
	}
	return nil
} //LogIncomingAPIRequest()

//ApiLog is the SQS event details struct encoded as JSON document, sent to SQS, to be logged for each API handler executed.
type ApiLog struct {
	StartTime           time.Time           `json:"start_time"`
	EndTime             time.Time           `json:"end_time"`
	DurMs               int64               `json:"duration_ms"` //duration in milliseconds
	Method              string              `json:"method"`
	Address             string              `json:"address"` //server address for incoming and outgoing
	Path                string              `json:"path"`
	ResponseCode        int                 `json:"response_code"`
	RequestID           string              `json:"request_id"`
	InitialAuthUsername string              `json:"initial_auth_username,omitempty"`
	InitialAuthType     string              `json:"initial_auth_type,omitempty"`
	AccountID           int64               `json:"account_id,omitempty"`
	Username            string              `json:"username,omitempty"`
	SourceIP            string              `json:"source_ip,omitempty"`  //only logged for incoming API
	UserAgent           string              `json:"user_agent,omitempty"` //only for incoming, indicate type of browser when UI
	RelevantID          string              `json:"relevant_id,omitempty"`
	Request             ApiLogRequest       `json:"request"`
	Response            ApiLogResponse      `json:"response"`
	Actions             []RelativeActionLog `json:"actions,omitempty"`
}

type ApiLogRequest struct {
	Headers         map[string]string `json:"headers,omitempty"`
	QueryParameters map[string]string `json:"query_parameters,omitempty"`
	BodySize        int               `json:"body_size" search:"long"` //set even when body is truncated/omitted
	Body            string            `json:"body,omitempty"`          //json body as a string
}

type ApiLogResponse struct {
	Headers  map[string]string `json:"headers,omitempty"`
	BodySize int               `json:"body_size"`      //set even when body is truncated/omitted
	Body     string            `json:"body,omitempty"` //json content as a string
}