Let’s face it: we’ve all been there. You’re debugging your serverless app in production, diving into CloudWatch logs, and suddenly you’re swimming in a sea of disconnected log statements that tell you… absolutely nothing useful. Oh, and your AWS bill? It’s crying in the corner because your logging costs just surpassed your actual compute costs. 🙈
According to AWS Well-Architected Framework, observability is a key pillar of operational excellence. Yet somehow, most of us are still logging like it’s 1999. You know the pattern:
console.log("Starting function...");
console.log("Fetching user data...");
console.log("User data fetched!");
console.log("Calling API...");
console.log("API called!");
console.log("Done!");Sound familiar? Well – what’s wrong with this? This approach has several drawbacks:
- Inconsistent Information: Different log statements might contain varying levels of detail, making it harder to standardize monitoring and alerting.
- Cost Impact: Each log statement generates a CloudWatch entry, potentially leading to situations where logging costs exceed the Lambda execution costs themselves.
- Fragmented Context: When debugging issues at scale, you need to correlate multiple log lines to understand the complete transaction flow.
- Distributed Logging: Good luck trying to understand what is happening in transactions that involve multiple lambdas.
Don’t worry, you’re not alone. About 80% of Lambda functions I’ve reviewed follow this “breadcrumb” logging pattern. It’s like trying to solve a murder mystery where all the clues are “someone walked here” – technically true, but not exactly helpful!
The AWS Well-Architected Framework recommends implementing instrumentation to monitor application, business, and operations activities. But here’s the kicker – it never said “log every breath your function takes.” In fact, the framework emphasizes the importance of meaningful, actionable telemetry data.
Today, we’re going to turn your logs from a chaotic stream of consciousness into a beautiful, structured story. We’ll explore how to create a single, powerful log entry that captures everything you need to know about a transaction. And the best part? Your AWS bill will thank you, your future self will thank you, and the poor soul who has to debug your function at 3 AM will definitely thank you.
Ready to log like it’s 2024? Let’s dive in!
The Traditional Approach and Its Problems
Many developers implement logging by placing log statements around each high-level action in their Lambda functions. It might look something like this:
const handler = async (event) => {
console.log('Starting process for user:', event.userId);
try {
console.log('Fetching user data from database');
const userData = await db.getUser(event.userId);
console.log('Calling external API');
const apiResponse = await externalService.getData(userData.preferences);
console.log('Updating user record');
await db.updateUser(event.userId, { lastAccess: new Date() });
console.log('Process completed successfully');
return { statusCode: 200, body: apiResponse };
} catch (error) {
console.error('Error processing request:', error);
return { statusCode: 500, body: error.message };
}
};The Single Statement Solution
Instead of multiple log statements, we can use a single, structured log entry that captures all relevant information about the transaction. This approach provides a complete picture of what happened during the Lambda execution.
Before we do that, we have to establish what we log. What I like to do is to follow the SOAP framework. The SOAP framework makes logging crystal clear: Subject (who’s doing it), Operation (what they’re trying to do), Aftermath (how it turned out), and Path (the full journey of what happened). With these four elements in your log, you’ve got everything you need to understand any transaction in your system.
The best part? SOAP helps you keep your logs clean (get it..? Yes, I am proud of this one). No more messy debugging sessions – just pure, clear insights into your system’s behavior. This isn’t just logging – it’s your system telling you exactly what went down, who did it, and how it all played out!
Here’s an example of what such a log statement might look like:
{
"cold_start": true,
"function_name": "user-data-processor",
"function_memory_size": 128,
"function_arn": "arn:aws:lambda:us-east-1:123456789012:function:user-data-processor",
"function_request_id": "12345-67890-abcde",
"xray_trace_id": "1-5759e988-bd862e3fe1be46a994272793",
"timestamp": "2024-12-28T10:15:30.123Z",
"service": "user-processing-service",
"level": "INFO",
"message": "Processing user data transaction completed",
"transaction": {
"consumer": {
"userId": "user123",
"userName": "jane.doe",
"userType": "premium",
"email": "jane.doe@example.com"
},
"operation": {
"name": "processUserData",
"version": "1.2",
"trigger": "API_GATEWAY",
"baggage": {
"correlationId": "corr-123-abc",
"originService": "user-api"
}
},
"outcome": {
"status": "success",
"code": "USER_DATA_PROCESSED",
"message": "Successfully processed user data"
},
"duration": 1234,
"context": {
"getUser": {
"type": "database",
"operation": "SELECT",
"duration": 150,
"query": "SELECT * FROM users WHERE id = ?",
"parameters": ["user123"],
"success": true,
"recordsAffected": 1,
"subsegment": "db-get-user"
},
"externalApiCall": {
"request": {
"url": "https://api.external-service.com/data",
"method": "POST",
"headers": {
"content-type": "application/json",
"x-api-version": "2.0",
"x-correlation-id": "corr-123-abc"
},
"body": {
"userId": "user123",
"preferences": ["email", "push"]
}
},
"response": {
"duration": 450,
"statusCode": 200,
"body": {
"status": "success",
"preferences": {
"email": true,
"push": false
}
}
},
"subsegment": "external-api-preferences"
},
"updateUser": {
"type": "database",
"operation": "UPDATE",
"duration": 100,
"query": "UPDATE users SET last_access = NOW() WHERE id = ?",
"parameters": ["user123"],
"success": true,
"recordsAffected": 1,
"subsegment": "db-update-user"
}
},
"metrics": {
"databaseLatency": 250,
"apiLatency": 450,
"totalProcessingTime": 1234
}
}
}Implementing the Solution: The Context Object Pattern
There are MANY ways to implement this, but I wanted to give you at least one example. One way to do this is to use a context object that accumulates information throughout the Lambda execution. See the code below for inspiration, but obviously don’t just copy and paste it in prod.
// transaction-context.js
class TransactionContext {
constructor(event, tracer) {
this.timestamp = new Date().toISOString();
this.correlationId = event.headers?.['x-correlation-id'] || `corr-${uuidv4()}`;
this.traceId = process.env._X_AMZN_TRACE_ID;
this.consumer = {
userId: event.requestContext?.authorizer?.userId,
userName: event.requestContext?.authorizer?.userName,
userType: event.requestContext?.authorizer?.userType,
email: event.requestContext?.authorizer?.email
};
this.operation = {
name: 'processUserData',
version: '1.2',
trigger: event.requestContext?.eventSource || 'UNKNOWN',
baggage: {
correlationId: this.correlationId,
originService: event.headers?.['x-origin-service'] || 'unknown'
}
};
this.context = {};
this.startTime = Date.now();
this.tracer = tracer;
this.metrics = {
databaseLatency: 0,
apiLatency: 0,
totalProcessingTime: 0
};
}
addDatabaseOperation(name, operationType, query, parameters) {
const start = Date.now();
const subsegment = this.tracer.getSegment()?.addNewSubsegment(`db-${name}`);
if (subsegment) {
subsegment.addAnnotation('operation', operationType);
subsegment.addAnnotation('query', query);
}
return {
complete: (success = true, recordsAffected = 0) => {
const duration = Date.now() - start;
this.metrics.databaseLatency += duration;
this.context[name] = {
type: 'database',
operation: operationType,
duration,
query,
parameters,
success,
recordsAffected,
subsegment: `db-${name}`
};
if (subsegment) {
subsegment.addMetadata('results', { success, recordsAffected });
subsegment.close();
}
}
};
}
addExternalCall(name, url, method, headers, body) {
const start = Date.now();
const subsegment = this.tracer.getSegment()?.addNewSubsegment(`ext-${name}`);
// Add correlation ID to headers
headers['x-correlation-id'] = this.correlationId;
if (subsegment) {
subsegment.addAnnotation('method', method);
subsegment.addAnnotation('url', url);
}
this.context[name] = {
request: {
url,
method,
headers,
body
}
};
return {
complete: (statusCode, responseBody) => {
const duration = Date.now() - start;
this.metrics.apiLatency += duration;
this.context[name].response = {
duration,
statusCode,
body: responseBody
};
if (subsegment) {
subsegment.addMetadata('response', { statusCode, duration });
subsegment.close();
}
}
};
}
log(status = 'success', code = 'SUCCESS', message = 'Operation completed successfully') {
this.metrics.totalProcessingTime = Date.now() - this.startTime;
return {
timestamp: this.timestamp,
correlationId: this.correlationId,
xrayTraceId: this.traceId,
consumer: this.consumer,
operation: this.operation,
outcome: {
status,
code,
message
},
duration: this.metrics.totalProcessingTime,
context: this.context,
metrics: this.metrics
};
}
}Using this context object, your Lambda handler becomes cleaner and more informative:
// Initialize resources outside the handler
const db = new Database();
const externalService = new ExternalService(process.env.EXTERNAL_API_URL);
// handler.js
const middy = require('@middy/core');
const { injectLambdaContext } = require('@aws-lambda-powertools/logger');
const { captureLambdaHandler } = require('@aws-lambda-powertools/tracer');
const { logMetrics } = require('@aws-lambda-powertools/metrics');
const { logger, tracer, metrics } = require('./logger');
const baseHandler = async (event) => {
const ctx = new TransactionContext(event, tracer);
try {
tracer.putAnnotation('correlationId', ctx.correlationId);
/**
* In each operation, you would do something like this:
* const getUserOp = ctx.addDatabaseOperation(
* 'getUser',
* 'SELECT',
* 'SELECT * FROM users WHERE id = ?',
* [event.userId]
* );
* <operation>
* getUserOp.complete(true, 1);
*/
const userData = await db.getUser(event.userId);
const apiResponse = await externalService.getData(userData.preferences);
await db.updateUser(event.userId, { lastAccess: new Date() });
// Add custom metrics
metrics.addMetric('SuccessfulProcessing', 1, 'Count');
metrics.addMetadata('correlationId', ctx.correlationId);
// Log the entire transaction
logger.info('Transaction completed successfully', ctx.log(
'success',
'USER_DATA_PROCESSED',
'Successfully processed user data'
));
return {
statusCode: 200,
headers: {
'x-correlation-id': ctx.correlationId
},
body: JSON.stringify(apiResponse)
};
} catch (error) {
metrics.addMetric('FailedProcessing', 1, 'Count');
logger.error('Transaction failed', {
...ctx.log(
'error',
'PROCESSING_FAILED',
error.message
),
error: error.stack
});
return {
statusCode: 500,
headers: {
'x-correlation-id': ctx.correlationId
},
body: JSON.stringify({ message: error.message })
};
}
};
// Export the handler with all middleware
exports.handler = middy(baseHandler)
.use(injectLambdaContext(logger))
.use(captureLambdaHandler(tracer))
.use(logMetrics(metrics));Conclusion
Remember when we started this journey, talking about Lambda functions sprinkled with more console.log statements than a junior developer’s first debugging session? Well, now you know better! Our SOAP framework (Subject, Operation, Aftermath, Path) shows that all you need is one perfectly structured log entry to tell the complete story of what’s happening in your system.
Of course, debug statements still have their place – they’re invaluable when you need to dive deep into specific issues. Just make sure to use the right log levels and activate them only when needed. And while this article focused on reducing log noise through structured logging, don’t forget about other logging best practices like sampling, using appropriate log levels for different environments, and implementing proper log retention policies.
The key takeaway? Stop treating your Lambda logs like a diary and start treating them like a well-organized story. Your future self (and your AWS bill) will thank you! 🚀
Leave a Reply