action.go

package logs

import (
	"encoding/json"
	"sync"
	"time"
)

//Call LogOutgoingAPIRequest() after calling an API end-point as part of a handler,
//to capture the details
//and add it to the current handler log story for reporting/metrics
func LogOutgoingAPIRequest(url string, method string, requestBody string, responseBody string, responseCode int, startTime time.Time) error {
	endTime := time.Now()
	log := ApiCallLog{
		URL:          url,
		Method:       method,
		ResponseCode: responseCode,
	}
	if requestBody != "" {
		log.Request = &BodyLog{
			BodySize: len(requestBody),
			Body:     requestBody,
		}
	}
	if responseBody != "" {
		log.Response = &BodyLog{
			BodySize: len(responseBody),
			Body:     responseBody,
		}
	}

	actionListMutex.Lock()
	actionList = append(actionList, ActionLog{
		StartTime: startTime,
		EndTime:   endTime,
		DurMs:     endTime.Sub(startTime).Milliseconds(),
		Type:      ActionTypeApiCall,
		ApiCall:   &log,
	})
	actionListMutex.Unlock()

	return nil
} //LogOutgoingAPIRequest()

//Call LogSQL() after executing any SQL query
//to capture the details
//and add it to the current handler log story for reporting/metrics
func LogSQL(
	startTime time.Time,
	sql string,
	rowsCount int, //optional nr of rows to report, else 0
	ids []int64, //optional list of ids to report, else nil
	err error, //only if failed, else nil
) {
	endTime := time.Now()
	log := SQLQueryLog{
		SQL:       sql,
		RowCount:  rowsCount,
		InsertIDs: ids,
	}
	if err != nil {
		log.Error = err.Error()
	}
	actionListMutex.Lock()
	actionList = append(actionList, ActionLog{
		StartTime: startTime,
		EndTime:   endTime,
		DurMs:     endTime.Sub(startTime).Milliseconds(),
		Type:      ActionTypeSqlQuery,
		SQLQuery:  &log,
	})
	actionListMutex.Unlock()
}

//Call LogSQSSent() after sending an SQS event
//to capture the details
//and add it to the current handler log story for reporting/metrics
func LogSQSSent(startTime time.Time, queueName string, messageType string, request interface{}) {
	//do not log internal events sent to audit/api-log
	if queueName == "API_LOGS" || queueName == "AUDIT" {
		return
	}

	endTime := time.Now()
	log := SQSSentLog{
		QueueName:   queueName,
		MessageType: messageType,
	}
	if request != nil {
		if requestString, ok := request.(string); ok {
			log.Request = &BodyLog{
				BodySize: len(requestString), //do not marshal, else we have double escaped JSON
				Body:     requestString,
			}
		} else {
			jsonRequest, _ := json.Marshal(request)
			log.Request = &BodyLog{
				BodySize: len(jsonRequest),
				Body:     string(jsonRequest),
			}
		}
	}
	actionListMutex.Lock()
	actionList = append(actionList, ActionLog{
		StartTime: startTime,
		EndTime:   endTime,
		DurMs:     endTime.Sub(startTime).Milliseconds(),
		Type:      ActionTypeSqsSent,
		SQSSent:   &log,
	})
	actionListMutex.Unlock()
}

func LogSearch(startTime time.Time, index string, query string) {
	endTime := time.Now()
	actionListMutex.Lock()
	actionList = append(actionList, ActionLog{
		StartTime: startTime,
		EndTime:   endTime,
		DurMs:     endTime.Sub(startTime).Milliseconds(),
		Type:      ActionTypeSearch,
		Search: &SearchLog{
			Index: index,
			Query: query,
		},
	})
	actionListMutex.Unlock()
}

//Call LogSleep() after doing time.Sleep()
//to capture the details
//and add it to the current handler log story for reporting/metrics
func LogSleep(startTime time.Time) {
	endTime := time.Now()
	actionListMutex.Lock()
	actionList = append(actionList, ActionLog{
		StartTime: startTime,
		EndTime:   endTime,
		DurMs:     endTime.Sub(startTime).Milliseconds(),
		Type:      ActionTypeSleep,
	})
	actionListMutex.Unlock()
}

var (
	actionListMutex sync.Mutex
	actionList      = []ActionLog{}
)

type ActionLog struct {
	StartTime time.Time    `json:"start_time"`
	EndTime   time.Time    `json:"end_time"`
	DurMs     int64        `json:"duration_ms"` //duration in milliseconds
	Type      ActionType   `json:"type" doc:"Type is api-call|sqs-sent|sql-query|sleep"`
	ApiCall   *ApiCallLog  `json:"api_call,omitempty"`
	SQSSent   *SQSSentLog  `json:"sqs_sent,omitempty"`
	SQLQuery  *SQLQueryLog `json:"sql_query,omitempty"`
	Search    *SearchLog   `json:"search"`
}

func (action ActionLog) Relative(relTime time.Time) RelativeActionLog {
	return RelativeActionLog{
		StartMs:  action.StartTime.Sub(relTime).Milliseconds(),
		EndMs:    action.EndTime.Sub(relTime).Milliseconds(),
		DurMs:    action.DurMs,
		Type:     action.Type,
		ApiCall:  action.ApiCall,
		SQSSent:  action.SQSSent,
		SQLQuery: action.SQLQuery,
	}
}

type RelativeActionLog struct {
	StartMs  int64        `json:"start_ms" doc:"Start time in milliseconds after start timestamp"`
	EndMs    int64        `json:"end_ms" doc:"End time in milliseconds after start timestamp"`
	DurMs    int64        `json:"duration_ms"` //duration in milliseconds
	Type     ActionType   `json:"type" doc:"Type is api-call|sqs-sent|sql-query|sleep" search:"keyword"`
	ApiCall  *ApiCallLog  `json:"api_call,omitempty"`
	SQSSent  *SQSSentLog  `json:"sqs_sent,omitempty"`
	SQLQuery *SQLQueryLog `json:"sql_query,omitempty"`
}

type ActionType string

var ActionTypeList = []ActionType{
	ActionTypeNone,
	ActionTypeApiCall,
	ActionTypeSqsSent,
	ActionTypeSqlQuery,
	ActionTypeSearch,
	ActionTypeSleep,
}

const (
	ActionTypeNone     ActionType = "none"
	ActionTypeApiCall  ActionType = "api-call"
	ActionTypeSqsSent  ActionType = "sqs-sent"
	ActionTypeSqlQuery ActionType = "sql-query"
	ActionTypeSearch   ActionType = "search"
	ActionTypeSleep    ActionType = "sleep"
)

//APICallLog captures details of an outgoing API call made from a handler
type ApiCallLog struct {
	URL          string   `json:"url" search:"keyword"`
	Method       string   `json:"method" search:"keyword"`
	ResponseCode int      `json:"response_code" search:"keyword"`
	Request      *BodyLog `json:"request,omitempty"`
	Response     *BodyLog `json:"response,omitempty"`
}

type BodyLog struct {
	BodySize int    `json:"body_size"`
	Body     string `json:"body"`
}

//SQSSentLog captures details of an SQS event sent from a handler
type SQSSentLog struct {
	QueueName   string   `json:"queue_name" search:"keyword"`
	MessageType string   `json:"message_type" search:"keyword"`
	Request     *BodyLog `json:"request,omitempty"`
}

//SQLQueryLog captures details of an SQL query executed from a handler resulting in either rows returned, ids inserted or an error
type SQLQueryLog struct {
	SQL       string  `json:"sql"`
	RowCount  int     `json:"row_count,omitempty"`
	InsertIDs []int64 `json:"insert_ids,omitempty"`
	Error     string  `json:"error,omitempty"`
}

type SearchLog struct {
	Index string `json:"index"`
	Query string `json:"query"`
}

//compile the relative action list that took place during this handler
//copy then reset actionList for the next handler
//we copy it with relation to this API's start..end time, rather than full timestamps, which are hard to read in the list
//start and end are current total handler period that actions should be inside that
func relativeActionList(startTime, endTime time.Time) []RelativeActionLog {
	actionListMutex.Lock()
	defer func() {
		//after copy/discard, reset (global!) action list for the next handler
		actionList = []ActionLog{}
		actionListMutex.Unlock()
	}()

	cfg := currentLogConfig()
	if !cfg.ActionsKeep {
		return nil
	}

	//todo: runtime config: load temporary from REDIS after N seconds
	//which will allow us to monitor better for a short while during trouble shooting
	//then something like this to reload every 5min (5min could also be part of config)
	//	if dynamicExpireTime.Before(time.Now()) {
	//		dynamicApiConfig := apiConfig //loaded from env at startup
	//		...look for keys in REDIS and override ...
	//		dynamicExpireTime = time.Now().Add(time.Minute*5)
	//	}
	//	do this in go routing with sleep... so handlers do not have to check :-)
	//	and it can also be used for api-log part that is not action list, e.g. for api-log req/res body len etc...
	relActionList := []RelativeActionLog{}
	for _, action := range actionList {
		if action.EndTime.Before(startTime) || action.StartTime.After(endTime) {
			continue //not expected - skip actions outside log window
		}

		//apply reduction filters to limit string lengths
		switch action.Type {
		case ActionTypeNone:
		case ActionTypeSqlQuery:
			if action.SQLQuery != nil && len(action.SQLQuery.SQL) > int(cfg.ActionsMaxSQLLength) {
				action.SQLQuery.SQL = action.SQLQuery.SQL[:cfg.ActionsMaxSQLLength]
			}
		case ActionTypeSqsSent:
			if action.SQSSent != nil && action.SQSSent.Request != nil && len(action.SQSSent.Request.Body) > int(cfg.ActionsMaxSQSReqBodyLength) {
				action.SQSSent.Request.Body = action.SQSSent.Request.Body[:cfg.ActionsMaxSQSReqBodyLength]
			}
		case ActionTypeApiCall:
			if action.ApiCall != nil {
				if action.ApiCall.Request != nil && len(action.ApiCall.Request.Body) > int(cfg.ActionsMaxAPIReqBodyLength) {
					action.ApiCall.Request.Body = action.ApiCall.Request.Body[:cfg.ActionsMaxAPIReqBodyLength]
				}
				if action.ApiCall.Response != nil && len(action.ApiCall.Response.Body) > int(cfg.ActionsMaxAPIResBodyLength) {
					action.ApiCall.Response.Body = action.ApiCall.Response.Body[:cfg.ActionsMaxAPIResBodyLength]
				}
			}
		case ActionTypeSearch:
			if action.Search != nil {
				if len(action.Search.Query) > int(cfg.ActionsMaxSearchQueryLength) {
					action.Search.Query = action.Search.Query[:cfg.ActionsMaxSearchQueryLength]
				}
			}
		}

		//make relative and append to the list
		relActionList = append(relActionList, action.Relative(startTime))
	}

	//also append to the list any nonAction periods greater than thresholdMs
	//to indicate significant gaps in the action list that we did not account for
	thresholdMs := int64(50)
	//make period list, remove all action periods, then we're left with non-action periods :-)
	nonActionPeriods := NewPeriods(startTime, endTime)
	for _, action := range actionList {
		nonActionPeriods = nonActionPeriods.Without(Period{Start: action.StartTime, End: action.EndTime})
	}
	for _, nonAction := range nonActionPeriods {
		if nonAction.Duration().Milliseconds() > thresholdMs {
			relActionList = append(relActionList, ActionLog{
				StartTime: nonAction.Start,
				EndTime:   nonAction.End,
				DurMs:     nonAction.Duration().Milliseconds(),
				Type:      ActionTypeNone,
			}.Relative(startTime))
		}
	}
	return relActionList
}