# What?

![Log Screenshot](https://code.amazon.com/packages/TwitchGoRequestLog/blobs/heads/mainline/--/doc/log_screenshot.png?raw=1)

This package provides detailed request logs using AWS CloudWatch.
Out of the box, you get structured per-request logs, including information about timing, errors, and request body.

Features:

- Log a percentage of all requests (default 0.1%, can be adjusted)
- Optional: per-method sample rate
- SLO tracking
- Optional logging of headers from GraphQL (`Client-ID` and `User-ID`)

# What is logged?

By default, the following fields are logged for every request:

- Request receipt time, total duration, send time
- Method name
- Status code (if using twirp hook)
- Request body
- Error (if present)
- Request ID, if present (uses the [FultonTwirpMiddleware](https://code.amazon.com/packages/FultonTwirpMiddleware/trees/mainline) package. Defaults to the `Request-ID` header.)
- TraceID, if present (pulled from the `X-Amz-Trace-Id` header)
- Name of handling host

You can optionally log UserID and ClientID (pulled from standard GraphQL headers).

If you use the [request ID middleware](https://code.amazon.com/packages/FultonTwirpMiddleware/blobs/mainline/--/request_id.go) from the `FultonTwirpMiddleware` package, request ID be logged.

You can also add any arbitrary fields you'd like to the logs.
We've used this for things like recording the timings of specific code regions.

You can also specify a set of endpoints to only log a percentage of requests.
Note that if you specify SLO for endpoints, any requests that are out of SLO will also be logged.

# Implementing

### Setup package & log group

Include `TwitchGoRequestLog = 1.1;` in your service's `Config`.

Set up your Cloudwatch Log Group and make sure your service has permission to write to it:

```yaml
Resources:
  Type: AWS::Logs::LogGroup
  RequestLogGroup:
    Properties:
      LogGroupName:
        { "Fn::Sub": "MyCoolService-${ResourcePrefix}-Request-Logs" }
      RetentionInDays: 60
# Make sure your service role has "logs:CreateLogStream" and "logs:PutLogEvents" on the above resource.
# Your service role may already have "logs:*" access.
```

(Instructions given for CloudFormation. If you're using CDK, you should know how to create a log group).

### Initialize logger

Set up the logger wherever you initialise your service:

```golang
import (
    "golang.a2z.com/TwitchGoRequestLog/requestlog"
)

//...

// see documentation of requestlog.Configs for more information about these options
requestLogger, err := requestlog.New(requestlog.Configs{
    LogGroupName:       "myLogGroup",
    LogGroupRegion:     "us-west-2",
    ErrorLogger:        bs.logger, // logger from fulton bootstrap
    DefaultSampleRate:  1, // log all requests
    MethodSampleRate:   map[string]float{"GetThing": 0.01} // log 1% of GetThing requests
    MethodSLOs:         map[string]time.Duration{
        "GetThing": 80 * time.Millisecond,
        "SetThing": 200 * time.Millisecond,
    },
    LogClientID:        true,
    LogUserID:          false, // don't log user IDs - consider your service's data classification before enabling this.
})
if err != nil {
    log.Fatalf("error setting up logger: %s\n", err.Error())
}

// ...
// on service close:
err := requestLogger.Close()
```

### Logging via middleware

It is strongly recommended to integrate with this package via its Twirp hooks.

Add the middleware to your HTTP server (this attaches the trace to the context).
This depends on how your service's server is set up.
For a default Fulton service, it looks like this:

```
- handler := handlers.LimitRequestSizes(mux, maxRequestSize)

+ handler := requestlog.ContextMiddleware(handlers.LimitRequestSizes(mux, maxRequestSize))
```

Then include the logger's Twirp hooks wherever you include your hooks normally

```golang
twirpMiddleware := twirp.ChainHooks(
    requestlog.EventHook(requestLogger),
    // requestlog.SLOHook(bs.SampleReporter, requestLogger), // OPTIONAL: include this to emit SLO metrics
    metricsMiddleware.ServerHooks(),
    errorLoggingMiddleware.ServerHooks(),
)

```

If you include the `SLOHook`, new metrics in the `Service/Region,Service,Stage,Substage,Operation` dimension set will be emitted:

- `SLOPassed` - emitted for every request that passes SLO.
- `SLOFailed` - emitted for every request that fails SLO.
- `SLOPercent` - for every request, emits 1 if SLO is passed, otherwise emit 0. Useful when using the `Average` aggregation.

![SLO Metrics](https://code.amazon.com/packages/TwitchGoRequestLog/blobs/heads/mainline/--/doc/slo_metrics.png?raw=1)

For the purposes of this library, there are two requirements to pass SLO:

- Duration is less than or equal to the defined SLO
- No 500-level error occurred.

Make sure you fill out the `MethodSLOs` in the config before enabling this.

### Using trace

Include the request body in your each of your Twirp method definitions:

```golang
func (s *Server) GetThing(ctx context.Context, request *serviceapi.GetThingRequest) (*serviceapi.GetThingResponse, error) {
    requestlog.GetTrace(ctx).Body = request
    //...
}
```

If you want to include any custom fields, this is also the place to do it.

```golang
func (s *Server) GetThing(ctx context.Context, request *serviceapi.GetThingRequest) (*serviceapi.GetThingResponse, error) {
    trace := requestlog.GetTrace(ctx)
    trace.Body = request
    trace.CustomFields = map[string]string{"req_items": len(request.GetItems())}
    //...
}
```

The `CustomFields` member is an `interface{}` that gets JSON-marshalled and added to the log.

### Logging via direct invocation

You can also use the request logger by calling its methods directly. This is only recommended for non-Twirp use cases (e.g. logging for event handlers).

```golang
func (e *handler) wrappedHandleEvent(ctx context.Context, event proto.Message) {
    return e.requestLogWrapper(ctx, event, "my_event", e.handleEvent)
}

func (e *handler) requestLogWrapper(ctx context.Context, event proto.Message, method string, handleEvent func(context.Context, proto.Message) (*result, error)) {
	ctx = WithEventStart(ctx)

    // Commit log event at the end, add custom fields to trace if you like
	customFields := myCustomFields{}
	defer func() {
		trace := requestlog.GetTrace(ctx)
		trace.CustomFields = customFields

		if r := recover(); r != nil {
			customFields.Panic = fmt.Sprintf("%v", r)
            trace.CustomFields = customFields
			e.requestLog.LogEvent(ctx, method)
			panic(r)
		}

		e.requestLog.LogEvent(ctx, method)
	}()

    result, err := handleEvent(ctx, event)

    // Enhance context after handling
    ctx = WithEventHandled(ctx)
    if err != nil {
        ctx = WithEventError(ctx, err)
    }

    // Any other custom logic or metric-ing you want to do here ...
    customFields.Result = result
    e.reporter.Report("success", 1.0, telemetry.UnitCount)
}

func (e *handler) handleEvent(ctx context.Context, event proto.Message) (*result, error) {
    ...
}
```

# Help!

If you need help with this package or want to contribute, please reach out to an engineer from the Knowledge Graph team.
If you're not sure who to contact, try a service channel like [#category-db](https://twitch.slack.com/archives/CPWAW0YD6).

# Contributing

If changes need to be made to this library, submit a CR and request a review from the `twitch-vx-live-infra` team.
As this library doesn't have an associated pipeline, the changes will need to be manually built into `Twitch/live`.
Once your changes have been merged, head to `build.amazon.com` to build the package into `Twitch/live`.
