Serverless Spy Vs Spy Chapter 1: X-ray
Tags: serverless, xray, observability, telemetry
Published: 2022-12-01 11:27:58

There are several ways to perform espionage activities in the life of a serverless app, which all battle for your attention. Time for the advent of counterintelligence: We want answers! - And CDK/Source examples of how to use it! Here we go, Serverless spy vs spy in four chapters, each post published after you light the next candle.

## Series

- &#128367; [X-ray: Getting started with X-Ray on Lambda with TypeScript/Python/Go](https://www.tecracer.com/blog/2022/12/spy/xray/)
- &#128367; &#128367; ADOT: AWS Distro for OpenTelemetry Lambda
- &#128367; &#128367; &#128367; OTEL: Using Open Telemetry in Lambda
- &#128367; &#128367; &#128367; &#128367; AWS Lambda Telemetry API: Connecting Telemetry Systems with Lambda Service

## Serverless observability concepts


![Image description](https://dev-to-uploads.s3.amazonaws.com/uploads/articles/lc9atg6bu7fz3hxvsz3d.png)

This concept map shows the observability domain. With practical examples, I will explore the concepts one by one. Starting with X-Ray.

## The X-Ray Service and the X-Ray SDK


In serverless development, we have the problem of the "missing cloud profiler". We cannot look into the distributed Lambda Function/services to see where performance bottlenecks are.

Let`s assume we have a Function which is calling another Service:


![Image description](https://dev-to-uploads.s3.amazonaws.com/uploads/articles/gw9twznf066e4ryo42cj.png)


We test the function (1) and get results, how long it takes:

```
REPORT RequestId: c7e872b4-1fd4-492b-81f9-8cf22d67827b Duration: 83.23 ms Billed Duration: 84 ms Memory Size: 1024 MB Max Memory Used: 47 MB Init Duration: 172.27 ms
```

We know about warm/cold start and call again:


```
REPORT RequestId: 99b658c0-d946-4f17-bed1-890668051b74 Duration: 9.31 ms Billed Duration: 10 ms Memory Size: 1024 MB Max Memory Used: 47 MB
```


### The part-whole problem

What we do *not* know is how much time was spent in segment A and how much is spent in segment B. We only know A+B.


![Image description](https://dev-to-uploads.s3.amazonaws.com/uploads/articles/1hqrcxhjtecnfgvwwhq5.png)


So this is your espionage order! 

### The distribution problem

We could do some logging. But another problem comes into mind: The duration of each lambda call is statistically distributed. That means the value for a single call could be way off. So we have to look at a bunch of calls.

### The every-single-service problem

Now assume we are working with several AWS service calls.
With logging, we had to log before and after each call.

After solving all the problems, we have to create some software for analysis.

To solve this with logging alone, you need correlation IDs in each log and have to search all logs events. 


![Image description](https://dev-to-uploads.s3.amazonaws.com/uploads/articles/82wsnu81r5sd10qb74w4.png)


The correlation ID is called TraceID. And tracing gets all information about a request aggregated by request. In doing this, you can trace the call of a single session through all services.

X-Ray is the tracing solution on AWS.

## How X-Ray works


### The part-whole solution

In X-Ray, we have segments and sub-segments. We see A, B and A+B segments.


### The distribution solution

All services must send data about their communication to a central tracing service so we also have an overview of what is happening.

### The every-single-service problem

With the AWS SDK, the X-Ray SDK hooks itself into all AWS service calls. So we do not have to decorate each call, it is done automatically for you.

## Getting started

We use a modified simple lambda application from [tecRacer serverless sample application](https://github.com/tecracer/tRick-benchmarks/tree/master/serverless-standard). Get the modified source for this post from github:  [xraystarter](https://github.com/megaproaktiv/xraystarter) and leave a star :) 


![Image description](https://dev-to-uploads.s3.amazonaws.com/uploads/articles/3rvlq5klop29znz8zio0.png)

The simple architecture of the base serverless application.

1) The client uploads a file to an S3 bucket
2) The Lambda function gets an event
3) The Lambda service and the Lambda function write logs
4) The Lambda function writes the key of the file to dynamodb

As the examples are for three Lambda functions: TypeScript, Python and GO, we change the architecture a bit:


![Image description](https://dev-to-uploads.s3.amazonaws.com/uploads/articles/nzh0c4wustebfs7hpqnk.png)


I will walk you through deploying the application to see some X-Ray traces.


### Prerequisite:

- [AWS CDK ](https://aws.amazon.com/cdk/)
- [Task](https://taskfile.dev/)
- [Colima](https://github.com/abiosoft/colima) for Mac or Docker desktop
- Terminal with AWS credentials

You have to have the tools installed. With these tools on a mac, the steps are automated.

#### AWS CDK

This is the Infrastructure as Code tool.

#### Task

This is the better makefile to allow you to deploy the example.

#### Colima

We need a Docker daemon, as the Python and the TypeScript Lambda functions need more tools installed to be built. This is simplified with Docker, and the use of the CDK Constructs `NodejsFunction` and `PythonFunction`. The GO Lambda just needs GO to be build.

If you want to change it to a standard CDK `Lambda Function`, you can do a `task fastdeploy` in the Lambda directories to update just the Lambda Function code:

```
lambda
├── go
│   ├── Taskfile.yml
│   ├── dist
│   ├── go.mod
│   ├── go.sum
│   └── main
├── py
│   ├── Taskfile.yml
│   ├── __init__.py
│   ├── app.py
│   ├── dist
│   ├── package
│   └── requirements.txt
└── ts
    ├── Taskfile.yml
    ├── dist
    ├── index.ts
    ├── node_modules
    ├── package-lock.json
    ├── package.json
    ├── test
    └── tsconfig.json
```    

### Start Docker

Because of the Docker Desktop policies I replace Docker Desktop with Colima.

Do:

```
task colima
```

The Output is like:

```log
task: [colima] colima start
INFO[0000] starting colima
...
INFO[0022] starting ...                                  context=docker
INFO[0027] done
```

### Boostrap Account for cdk

If you use AWS CDK for the first time 

Do: 

```
task bootstrap
```

Output like:

```log
task: [bootstrap] npx cdk@2.51.1  bootstrap
Sending build context to Docker daemon  54.27kB
Step 1/12 : ARG IMAGE=public.ecr.aws/sam/build-nodejs14.x
...
 ⏳  Bootstrapping environment aws://123456789012/eu-central-1...
...
 ✅  Environment aws://123456789012/eu-central-1 bootstrapped.
```

### Deploy application

Do: 

```
task deploy
```

Output like:

```log
Step 1/12 : ARG IMAGE=public.ecr.aws/sam/build-nodejs14.x

 ✅  xraystarter

✨  Deployment time: 105.63s

Outputs:
xraystarter.BucketName = xraystarter-incoming0b397865-1hx8j3qf51d0x
xraystarter.LambdaNameGo = xraystarter-go
xraystarter.LambdaNamePy = xraystarter-py
xraystarter.LambdaNameTS = xraystarter-ts
xraystarter.TableName = items
Stack ARN:
arn:aws:cloudformation:eu-central-1:139008737997:stack/xraystarter/c289f610-6e4a-11ed-a2f1-02f07fd68fb2

✨  Total time: 110.91s
```

Now we are ready to use the application.

### Generate Traffic

Do: 

```
./test/traffic.sh
```

This puts files on the S3 bucket, and the Lambda Functions are triggered.
Stop after 2 cycles.


## A Look at X-Ray

### X-Ray Service Map

The first thing I look at is the **Service Map**.
You get there in the AWS Console choosing Cloudwatch -> X-Ray traces  -> Service Map:


![Image description](https://dev-to-uploads.s3.amazonaws.com/uploads/articles/pbatnqty7cecuj5tv8n2.png)

The map for all three lambdas first looked like this:


![Image description](https://dev-to-uploads.s3.amazonaws.com/uploads/articles/qes07hp794bc3b7gg2dz.png)


### Spy on an error: A Python Problem

#### Espionage

We see at first glance that the python Function `xraystarter-py` has a Problem! Now we can use the traces and the logs to find the cause of the problem.


![Image description](https://dev-to-uploads.s3.amazonaws.com/uploads/articles/f7o36u0zq8fndqxnbhtf.png)

You see that the invocation itself got an error. A click leads us to "View in CloudWatch Logs insights"


![Image description](https://dev-to-uploads.s3.amazonaws.com/uploads/articles/lp5ba2k2n0r6trefym0a.png)

With problems inside the application, you get all log events here. But because this is an problem *before* the function is executed, the error is published by the Lambda *service* and does not have an ID in the log event. Therefore we find the whole log stream itself.

With the `requestId` `b510437d-...` you find the log stream in Lambda *recent invocations*:


![Recent invocations 1](https://dev-to-uploads.s3.amazonaws.com/uploads/articles/lfpjf2ucc51nskxi995d.png)


In the log itself you find:

```
[ERROR] Runtime.ImportModuleError: Unable to import module 'app': No module named 'aws_xray_sdk'
Traceback (most recent call last):
```

Looks like the CDK construct from `aws-lambda-python-alpha` did not include the X-Ray library.
Well, its alpha, so OK:

```
import { PythonFunction } from '@aws-cdk/aws-lambda-python-alpha';
```

#### Solution

In the directory of the Python Lambda function we have a task `fastdeploy`, which updates just the function code, but with all libraries:

```
cd lambda/py
task fastdeploy
```

What it does:

1) Create a complete zip *with* the X-Ray sdk

```
      - pip install --target ./package -r requirements.txt
      - cd package && zip -r ../my-deployment-package.zip .
      - zip my-deployment-package.zip app.py
      - mv my-deployment-package.zip dist/app.zip
```

2) Update the function code

```
    vars:
      FN:
        sh: aws cloudformation list-exports --query "Exports[?Name == 'xraystarter-py-name'].Value" --output text
    cmds:
      - aws lambda update-function-code --function-name  {{.FN}} --zip-file fileb://dist/app.zip
```

The name of the Lambda Function is exported, so we get it with `cloudformation list-exports`.

See the `lambda/py/Taskfile.yml` for the code.

#### Run again

We wait 15 mins, so that the old data is not shown (if we filter on that time range). Then again create traffic:

Do:

```
./test/traffic.sh
```

Output:

```
So 27 Nov 2022 18:53:58 CET
upload: ./readme.md to s3://xraystarter-incoming0b397865-1hx8j3qf51d0x//test-20-0-0-0
So 27 Nov 2022 18:54:09 CET
upload: ./readme.md to s3://xraystarter-incoming0b397865-1hx8j3qf51d0x//test-20-0-0-1
```

#### Cleared Service Map


![Cleared Map](https://dev-to-uploads.s3.amazonaws.com/uploads/articles/3rp9yvk4wn8apz9fi9qi.png)


The (1) `xraystarter-py` has zero errors and writes to the `items` table (2). Node and Python SDK propagate the table name to X-Ray, and the GO X-Ray SDK behaves differently (3). But all Lambda Functions write to the same table.

## How to instrument X-Ray on Lambda

The XRay SDKs contains all function to send tracing information from the Lambda *Function* to the X-Ray server. Witch activated X-Ray, the Lambda *Service* sends information too.

### Step 1) Create Lambda Services with Y-Ray support

See `lib/xraystarter-stack.ts` for details.

#### Typescript

```
const fnTS = new NodejsFunction(this, "xraystarter-ts", {
  //...
  tracing: aws_lambda.Tracing.ACTIVE,
  //...
})
```    

#### Python

```ts
const fnPy = new PythonFunction(this, 'xraystarter-py', {
//...
  tracing: aws_lambda.Tracing.ACTIVE,
//...
});
```    

#### Go

```
const fnGO = new aws_lambda.Function(this, 'xraystarter-go', {
  //...
  tracing: aws_lambda.Tracing.ACTIVE,
  //...
});
```    

### Step 2) Load the X-Ray SDK

#### Typescript

```
import * as AWSXRay from 'aws-xray-sdk'
```

#### Python

```
from aws_xray_sdk.core import xray_recorder
from aws_xray_sdk.core import patch_all
```


#### Go

```go
import (
	"github.com/aws/aws-xray-sdk-go/instrumentation/awsv2"
	"github.com/aws/aws-xray-sdk-go/xray"

)
```

### Step 3) bind aws calls to xray

#### Typescript

In Ts you create a constant which replaces the normal creation of a client:

```
import * as AWS from 'aws-sdk';
//...
const dynamodb = new AWS.DynamoDB();
```

Patch AWS variable with: 

```
const AWS = AWSXRay.captureAWS(require('aws-sdk'));
```

You see in the node [xrays sdk](https://github.com/aws/aws-xray-sdk-node/blob/a9d0cf9cbd0328e40f30554f61b4bd5fac08bafc/packages/core/lib/patchers/aws_p.js) that each AWS service is customized with the `captureAWSRequest` function, which is responsible for the X-Ray calls.

```
  for (var prop in awssdk) {
    if (awssdk[prop].serviceIdentifier) {
      var Service = awssdk[prop];
      Service.prototype.customizeRequests(captureAWSRequest);
    }
```

#### Python

In python you just call a function to do the patching.

```
patch_all()
```

The nested magic is happening in the [patcher.py](https://github.com/aws/aws-xray-sdk-python/blob/master/aws_xray_sdk/core/patcher.py) function of the SDK.
 
A `def _patch_func(parent, func_name, func, modifier=lambda x: x):` 
calls a `setattr`:

```
setattr(parent, func_name, modifier(xray_recorder.capture(name=capture_name)(func)))
```


#### Go

In GO, you intercept the [middleware](https://aws.github.io/aws-sdk-go-v2/docs/middleware/).

In GO SDK V2, you can change the client request pipeline directly. This way, you can add behaviour before or after each step of an AWS api call.

```
	cfg, err := config.LoadDefaultConfig(context.TODO())
	if err != nil {
		panic("unable to load SDK config, " + err.Error())
	}
	// Using the Config value, create the DynamoDB client
	awsv2.AWSV2Instrumentor(&cfg.APIOptions)
	Client = dynamodb.NewFromConfig(cfg)
```


![middleware](https://dev-to-uploads.s3.amazonaws.com/uploads/articles/fioh3yl6jfwgxqpt77gl.png)


When you look at the [GO X-Ray SDK](https://github.com/aws/aws-xray-sdk-go/blob/v1.7.1/instrumentation/awsv2/awsv2.go) you can see in `func initializeMiddlewareAfter(stack *middleware.Stack)` how the calls to X-Ray are generated. The call to X-Ray happens in the deserialize step.

## Back to espionage order: Query traces

### Query Traces of a single service

In `CloudWatch > Traces` we now run a query for each service:


![query](https://dev-to-uploads.s3.amazonaws.com/uploads/articles/j2vjfpxyn7qclzg7ywlz.png)


1) Set filter
2) Run query

#### TypeScript

Query: `service(id(name: "xraystarter-ts", type: "AWS::Lambda"))`


![timeline ts](https://dev-to-uploads.s3.amazonaws.com/uploads/articles/tkyc19fnmz5ovvbk29od.png)


Segments Timeline

#### Python

Query: `service(id(name: "xraystarter-py", type: "AWS::Lambda"))`


![timeline py](https://dev-to-uploads.s3.amazonaws.com/uploads/articles/dmfp2l43o5tsyolci7ps.png)


Segments Timeline

#### GO

Query: `service(id(name: "xraystarter-go", type: "AWS::Lambda"))`


![timeline go](https://dev-to-uploads.s3.amazonaws.com/uploads/articles/hurtbd20nh4ji4xnehgz.png)


Segments Timeline

## Analyze traces

### Dwell Time

A surprise is a time spent in the Lambda service, which is 39...92 ms.
The next subsegment is a **dwell time**, which only appears if the lambda is called via SNS/S3.

You can optimize your Function code, but that would not affect the dwell time. Calling the Function directly from the console gives a trace with no dwell time:


![go-direct](https://dev-to-uploads.s3.amazonaws.com/uploads/articles/4rvaozywo3ilq5s1wsma.png)


### DynamoDB

Because the X-Ray trace is sent within the Lambda Function, you do not only measure the response time from DynamoDB but also the performance of the Function and the development language. But don`t take these times seriously because the execution time is also not constant.

An example for the GO Lambda:

TraceId | Call | Dynamodb Time
---|---|---
1-63847262-1f7b1f131c705dd37c779140 | Cold start with event 1 | 81ms
1-63847264-35ce354a5be7eaa51c808a04 | Warm start with same event 1 | 4ms
1-638472d9-0651242b5c645fd552266041 | Warm start with new event 2 | 32ms
1-63847361-4f18e808597dc00552100afe | Warm start with same event 2 | 25 ms


And the same for Python Lambda


TraceId | Call | Dynamodb Time
---|---|---
1-638475c3-0a4d8fcb05b4bb3c71bf0e28| Cold start with event 1 | 53ms
1-638475c7-3ca3074d4977478344f0191e| Warm start with same event 1 | 41ms
1-638475d8-4a0ef8842a7bf9b5663412fc | Warm start with new event 2 | 39ms
1-638475d8-4fa68a674581da2f6ba79d1a | Warm start with same event 2 | 34ms


## Conclusion

With X-Ray, you can have traceability and connect them to logs easily! As you dig deeper, you see additional overhead like the initialization or the dwell time. With the service map, you get a quick overview, and the references from traces to CloudWatch logs via Insights can help understand the whole microservice application.

This application is simple, so you can get X-Ray up and running and develop your own applications, which will be more complex. But the principle is the same.


If you need consulting for your serverless project, don’t hesitate to contact the sponsor of this blog, [tecRacer](https://www.tecracer.com/kontakt/).

For more AWS development stuff, follow me on dev https://dev.to/megaproaktiv.

## See also 

- Code on github: [xraystarter](https://github.com/megaproaktiv/xraystarter)
- [AWS GO SDK V2 Middleware](https://aws.github.io/aws-sdk-go-v2/docs/middleware/)
- [AWS Lambda/X-Ray documentation](https://docs.aws.amazon.com/lambda/latest/dg/services-xray.html)
- [One Observability Workshop](https://catalog.workshops.aws/observability/en-US)

## Thanks to

- Spy vs Spy - Comics which not everybody gets :)