# Ops Exercises

## Bastion Logs

Bastion is our front-router, which means it is the entrypoint into our system for all requests to 99designs.com (and other domains). It is bastion's job to direct requests to other 99designs services according to the path in the request URL (e.g., `/accounts/login` goes to the `accounts` service). You might have heard the term reverse-proxy before - this is essentially what bastion does. The service where the request is sent is often called a "backend."

For every request, Bastion logs information about both the request received and the response sent back that can be used to see things like:

- The client's IP
- The URL (sometimes called the "path" or "route")
- The backend that handled the request
- The HTTP code of the response (e.g., `200` for OK, `5xx` for server errors)
- How long the response took to send

Bastion logs are structured in JSON lines format, where each line is a separate JSON object. Each JSON object looks something like this:

{
  "id": "01FC4YB069ME1S3MDCGYJM61HA",
  "request": {
    "99seshID": "01FC4MW5GWT5MJ0KT6BZAGQ4B5",
    "acceptEncoding": "gzip, deflate, br",
    "clientIp": "200.100.205.30",
    "cookieLength": 2486,
    "effectiveUserId": "xxx",
    "geoIpCountry": "ID",
    "host": "99designs.com",
    "method": "GET",
    "remoteAddress": "103.162.205.30:24080",
    "sid": "017b0658-f38c-fe53-b414-7342c668445e",
    "url": "/app/graphql",
    "userAgent": "Mozilla/5.0 (Windows NT 6.1; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/92.0.4515.107 Safari/537.36",
    "userId": "xxx",
    "vid": "01746002-0f02-3321-1b31-841e73ff9ea3"
  },
  "response": {
    "backend": "spa_backend",
    "bodyBytes": 0,
    "code": 101,
    "duration": 0.004678575,
    "hostname": "ip-10-2-1-84.ec2.internal",
    "timeToFirstByte": 0.004677327,
    "version": "c3b967c4dd958439b32d91d5701597853fe958b3"
  },
  "time": "2021-08-03T12:44:00+10:00"
}

You can view these logs with the `99cli logs` command:

aws-vault exec platform -- 99cli logs --filter '{$.response.backend = "start"}' --from="2021-08-08 09:30:00" --to="2021-08-08 09:50:00" --format '{{ .request.clientIp }}' /bastion/access.log | sort | uniq -c | sort -hr

The above example will show how many requests were made by each unique IP to the `start` backend. The `/bastion/access.log` refers to a `log group` configured in AWS that receives logs from all of our running Bastion instances.

Start by copying the `99cli` command above and adjusting the `from` and `to` values to search from "10 minutes ago" to "1 year in the future".

1. How would you find the top user agents that are hitting the `blog` backend?

2. What about the most popular urls for the `accounts` backend?

3. Go to https://99designs.com.au/user/profile, login and note your user ID in the URL bar.

Adjust the `filter` and `format` options to show logs for your user ID, printing the backend and the URL.

Note: Since we want to see every request in this case, there's no need to pipe the output to `sort` or `uniq`.

## Dashboards

As you've seen above, while we can answer some questions using `99cli` and filtering logs, the whole process is a bit fiddly. Usually much of the same information is available on dashboards in our Datadog tool: https://app.datadoghq.com/

All services should have dashboards available that show important metrics relating to the health of a service. Things like:

- Request volume
- Response time
- Error counts
- Resource usage (Container count, CPU, Memory, Connections, Network Bandwidth)
- Aggregated trace information (more on this in the next section)

Scenario: It's just after midnight on the 28th of July, and you receive an alert complaining about a high number of open connections from Bastion. This links you to the following dashboard in Datadog:
https://app.datadoghq.com/dashboard/6ha-bjk-iuj/bastion?from_ts=1627393584926&to_ts=1627403066407&live=false

1. Which backend(s) does Bastion have high numbers of connections to, relative to the other backends?

2. With the backend(s) in mind, do any other graphs stick out? What are they telling you about the health of the backend services?

3. What are some other places you might look to dig into this further?

## Traces

Bastion logs are useful for finding out about the types of requests that are coming in and which backend is serving them, but they don't give you much insight into what the backend actually did with the request apart from generic things like duration and error code. For this we can use tracing.

Tracing relies on services sending events when they do something interesting. These events are called `spans`, as they usually wrap an operation that the service is performing. Which spans are sent can be service-specific, as usually the service needs to be instrumented specifically to send them. The most basic span a service sends is usually from the start to the end of a response to a single request. A service might also send a span every time it queries its database, so you know how much of the response time was spent querying data.

The real power with traces comes when different services are all sending spans as they handle a particular request. For one request, `bastion` might forward the request to `projects`, which then talks to another service `messages` to get some data. If all these services are sending spans, our tooling can collate them and show the interaction between services. This lets you answer questions like: why is this particular route sometimes very slow?

While the Bastion logs (and dashboards) can tell you *which* backend is having performance problems, they don't usually give you insight into *why* when the problem is deeper inside a service or dependent on the exact shape of a request. Traces allow you to drill down on a per-request level to find the exact service or operation that is responsible for the problem.

Here's a live example you can find in production:

1. From the Bastion dashboard, find the "top resources" pane:
https://app.datadoghq.com/dashboard/6ha-bjk-iuj/bastion

2. Click on `GET /profiles/*`, which is usually the top resource, then click `View related traces` in the context menu.

3. Click on one of the lines in the table to see the flame graph for this request. In tracing, a single request consists of many nested "spans" sent from each service that does work to handle the request. Datadog collates these into the view you see here. Hover over or click on each span to get further information.

What does the flame graph tell you about the relationship between `workbench` and `bastion`?

5. Now, let's try to find some slow requests... close the current trace and look to the left of the list of spans. There you'll see facet controls that you can use to select a subset of spans. Try moving the lower bound for `Duration` up to around 2/3rds of the max duration shown (most likely a few seconds).

6. The list of spans now just shows the slower requests. Click on a span to get more detail. The flame graph probably looks quite different, and can be difficult to read with a large number of spans.

7. Click on the "Span List" tab to get an aggregated list of spans with their count and durations. Can you identify why this response is taking longer? Hint: there are N+1 reasons.