In this step, we will add additional detail to our traces to provide more information about the operations they are tracking. We will do this by adding custom attributes and log events to our spans.
Attributes are key-value pairs that contain metadata that are used to annotate a span and provide details about the operation it is tracking. For example, you might create attributes that hold a customer ID, or information about the environment that the request is operating in, or the specific version of the service.
Attributes have the following rules:
In general, spans can be created freely and it’s the implementors responsibility to annotate them with the appropriate attributes. OpenTelemetry provides Semantic Conventions which are known naming conventions for metadata that is typically present in common operations. It’s recommended to use semantic attribute naming wherever possible to standardize common metadata across systems.
Let’s look at two different ways to add custom attributes to our tracing
The Node.js OpenTelemetry SDK allows you to perform configuration via environment variables defined in the OpenTelemetry specification. This includes the OTEL_RESOURCE_ATTRIBUTES environment variable that is used to set attributes at the Resource level. We will use this environment variable to set the name and version of our two services.
Edit the docker-compose.yml file and go the the environment: section of the web: service
Add the following to this section:
web:
...
environment:
- OTEL_RESOURCE_ATTRIBUTES=service.name=web-service,service.version=2.0.0
This sets the name of the service as “web” and the version to “2.0.0”. Now do the same for the Users service
Add the following to the environment: section of the users: service
users:
...
environment:
- OTEL_RESOURCE_ATTRIBUTES=service.name=users-service,service.version=2.0.0
Resource level attributes won’t show in the trace data in your console but we will be able to see these when we have the data sending to Cloud Observability.
Before we can add custom attributes to our spans, we need to be able to get and create spans in our code. In OpenTelemetry, a tracer is used to perform tracing operations such as creating spans. The tracer is available in the API which must be imported before we can use it. The API also provides the means to get active spans from the current context which we will use.
In /src folder of the web service, update the index.js file. Add the following at the top of the file:
// import the OpenTelemetry api library
const api = require("@opentelemetry/api");
// create a tracer and name it after your package
const tracer = api.trace.getTracer("myInstrumentation");
This adds the OpenTelemetry API library and acquires a tracer. In the app.get("/", (req, res) => { call in the main() function, add the following after let weather = req.query.weather;:
// access the current span from the active context
let activeSpan = api.trace.getSpan(api.context.active());
// add an attribute
activeSpan.setAttribute("nbLoop", nbLoop);
activeSpan.setAttribute("weather", weather);
This code gets the current span from the active context and then sets a couple custom attributes on the span. In this case, we are setting some values from the request which helps us better understand the context when this operation is executed.
Test these updates by making requests to http://localhost:4000?loop=3 and http://localhost:4000?weather=rain in your browser. You should see trace data in the console like this:
web | {
web | traceId: '92a27d2a91e69a27977a1b28136d342b',
web | parentId: undefined,
web | name: 'GET /',
web | id: '176654c010e2f7ab',
web | kind: 1,
web | timestamp: 1666291780810700,
web | duration: 9386,
web | attributes: {
web | 'http.url': 'http://localhost:4000/?loop=3',
web | 'http.host': 'localhost:4000',
web | 'net.host.name': 'localhost',
web | 'http.method': 'GET',
web | 'http.target': '/',
web | 'http.flavor': '1.1',
web | 'net.transport': 'ip_tcp',
web | nbLoop: '3',
web | 'net.host.ip': '172.30.0.5',
web | 'net.host.port': 80,
web | 'net.peer.ip': '172.30.0.1',
web | 'net.peer.port': 58410,
web | 'http.status_code': 200,
web | 'http.status_text': 'OK',
web | 'http.route': ''
web | },
web | status: { code: 1 },
web | events: []
web | }
... | ...
web | {
web | traceId: 'f5c9b2df6398fd267781d5c3f88857d9',
web | parentId: undefined,
web | name: 'GET /',
web | id: '9f71b48505509423',
web | kind: 1,
web | timestamp: 1666291934957818,
web | duration: 1511860,
web | attributes: {
web | 'http.url': 'http://localhost:4000/?weather=rain',
web | 'http.host': 'localhost:4000',
web | 'net.host.name': 'localhost',
web | 'http.method': 'GET',
web | 'http.target': '/',
web | 'http.flavor': '1.1',
web | 'net.transport': 'ip_tcp',
web | weather: 'rain',
web | 'net.host.ip': '172.30.0.5',
web | 'net.host.port': 80,
web | 'net.peer.ip': '172.30.0.1',
web | 'net.peer.port': 56750,
web | 'http.status_code': 202,
web | 'http.status_text': 'ACCEPTED',
web | 'http.route': ''
web | },
web | status: { code: 1 },
web | events: []
web | }
Notice the loop: '3' and weather: rain key value pairs that now appear in your GET / spans.
Attributes are great for adding metadata to your spans and resources but they do not reflect any time-based events. This is where logs and log events come in. A log is a timestamped text record that is either structured (ideally) or unstructured and contains information about an event that has occurred. Logs are traditionally an independent data source but they may also be attached to spans as log events. Let’s add a log event to one of the calls in our Web service.
In the same file we have been editing, add the following at the top of the app.get("/api/data", (req, res) => { call in the main() function:
// access the current span from the active context
let activeSpan = api.trace.getSpan(api.context.active());
// log an event and include some structured data
activeSpan.addEvent(`Making request to ${USERS_SERVICE_URL}/api/data`);
This code gets a span from the current context like we did previously. It then adds an event to the span indicating that the a request is being map to a specific endpoint.
Test this be making a request to http://localhost:4000/api/data. In your console you should see span with name GET /api/data that looks like this:
web | {
web | traceId: '092ba5e8e9746077800176c04eb1364f',
web | parentId: undefined,
web | name: 'GET /api/data',
web | id: '26e81a49dbb09e5c',
web | kind: 1,
web | timestamp: 1666292148811205,
web | duration: 73091,
web | attributes: {
web | 'http.url': 'http://localhost:4000/api/data',
web | 'http.host': 'localhost:4000',
web | 'net.host.name': 'localhost',
web | 'http.method': 'GET',
web | 'http.target': '/api/data',
web | 'http.flavor': '1.1',
web | 'net.transport': 'ip_tcp',
web | 'net.host.ip': '172.30.0.5',
web | 'net.host.port': 80,
web | 'net.peer.ip': '172.30.0.1',
web | 'net.peer.port': 63158,
web | 'http.status_code': 200,
web | 'http.status_text': 'OK',
web | 'http.route': '/api/data'
web | },
web | status: { code: 1 },
web | events: [
web | {
web | name: 'Making request to http://service/api/data',
web | attributes: {},
web | time: [Array]
web | }
web | ]
web | }
Notice the events array now has the event that we added.
So far we have been adding attributes and log events to existing spans. You will likely also want to add your own spans in certain cases such as when you want to track work inside a child method separate from the calling parent. Let’s do that to one of the methods in our Web service.
The generateWork function in the Web service runs a loop X times based on the value passed to the function. This function is called when the nbLoop value is present in the request to the main endpoint of the Web service. Let’s update this function so that it creates a span for each iteration in the loop.
Replace the existing generateWork() function with the code below:
async function generateWork(nb) {
for (let i = 0; i < Number(nb); i++) {
// create a new span
// the current span is automatically used as parent unless one
// is explicitly provided as an argument
// the span you create then automatically becomes the current one
let span = tracer.startSpan("generateWork");
// add an attribute
span.setAttribute("iterations.current", i + 1);
span.setAttribute("iterations.total", nb);
// log an event and include some structured data
span.addEvent(`*** DOING SOMETHING ${i}`);
// wait for 50ms to simulate doing some work
await sleep(50);
// don't forget to always end the span to flush data out
span.end();
}
}
The difference in this updated code is that we create a span by calling the startSpan() method on the tracer. This method takes a string value that sets the name of the span. We then add a couple attributes to the span to capture which iteration in the loop this span represents as well as how many total iterations there are. Next we add an event to the span indicating that work is being done and again which iteration is current. Finally after the work is done we call span.end() to complete the span and flush the data.
Let’s test this by making a request to http://localhost:4000?loop=3 again. You should now see 3 new spans in your console, one for each iteration of the loop. It should look something like this:
web | traceId: 'c90e23722e18618beca7ca17c31d8203',
web | parentId: '52a6854222c243fb',
web | name: 'generateWork',
web | id: 'c63270baee0b834b',
web | kind: 0,
web | timestamp: 1666292576516609,
web | duration: 50650,
web | attributes: { 'iterations.current': 0, 'iterations.total': '3' },
web | status: { code: 0 },
web | events: [ { name: '*** DOING SOMETHING 0', attributes: {}, time: [Array] } ]
web | }
web | {
web | traceId: 'c90e23722e18618beca7ca17c31d8203',
web | parentId: '52a6854222c243fb',
web | name: 'generateWork',
web | id: '5b0e16e694d99843',
web | kind: 0,
web | timestamp: 1666292576567400,
web | duration: 50460,
web | attributes: { 'iterations.current': 1, 'iterations.total': '3' },
web | status: { code: 0 },
web | events: [ { name: '*** DOING SOMETHING 1', attributes: {}, time: [Array] } ]
web | }
web | {
web | traceId: 'c90e23722e18618beca7ca17c31d8203',
web | parentId: '52a6854222c243fb',
web | name: 'generateWork',
web | id: 'b9a8a6ec169d6a77',
web | kind: 0,
web | timestamp: 1666292576617949,
web | duration: 51567,
web | attributes: { 'iterations.current': 2, 'iterations.total': '3' },
web | status: { code: 0 },
web | events: [ { name: '*** DOING SOMETHING 2', attributes: {}, time: [Array] } ]
web | }
Notice the name of the spans are the same but the attribute iterations.current and the log event are different.
In this step we learned how to add custom attributes and log events to both existing and new spans. Up to this point, our telemetry data has only been exporting to console. This is useful for debugging as you instrument your code but it does not work for production system observability. For that, we will leverage an OpenTelemetry Collector and ultimately send our data to the Cloud Observability SaaS. Let’s see how that works
next: Exporting Data