-
Notifications
You must be signed in to change notification settings - Fork 322
Add new best practices for structured logging and accepting loggers #370
New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
base: main
Are you sure you want to change the base?
Changes from all commits
File filter
Filter by extension
Conversations
Jump to
Diff view
Diff view
There are no files selected for viewing
Original file line number | Diff line number | Diff line change |
---|---|---|
@@ -1,7 +1,6 @@ | ||
# 001: Choosing log levels | ||
|
||
Best practice for selecting appropriate log levels in applications and | ||
libraries. | ||
Select appropriate log levels in applications and libraries. | ||
|
||
## Overview | ||
|
||
|
@@ -39,29 +38,30 @@ its logging environment. | |
|
||
#### For libraries | ||
|
||
Libraries should use **info level or lower** (info, debug, trace). Each level | ||
serves different purposes: | ||
Libraries should use **info level or lower** (info, debug, trace). | ||
|
||
Libraries **should not** log information on **warning or more severe levels**, | ||
unless it is a one-time (for example during startup) warning, that cannot lead | ||
to overwhelming log outputs. | ||
|
||
Each level serves different purposes: | ||
|
||
##### Trace Level | ||
- **Usage**: Log everything needed to diagnose hard-to-reproduce bugs | ||
- **Performance**: May impact performance; assume it won't be used in production | ||
- **Content**: Internal state, detailed operation flows, diagnostic information | ||
- **Usage**: Log everything needed to diagnose hard-to-reproduce bugs. | ||
- **Performance**: May impact performance; assume it won't be used in production. | ||
- **Content**: Internal state, detailed operation flows, diagnostic information. | ||
|
||
##### Debug Level | ||
- **Usage**: May be enabled in some production deployments | ||
- **Performance**: Should not significantly undermine production performance | ||
- **Content**: High-level operation overview, connection events, major decisions | ||
- **Usage**: May be enabled in some production deployments. | ||
- **Performance**: Should not significantly undermine production performance. | ||
- **Content**: High-level operation overview, connection events, major decisions. | ||
|
||
##### Info Level | ||
- **Usage**: Reserved for things that went wrong but can't be communicated | ||
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. I've not seen "info" level being used for things that went wrong. I would consider warn and error levels for things that went wrong. I use info for information like version, configuration, etc. that would help to diagnose "what software am I debugging" type questions. There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. This is guidance in particular for libraries which should avoid logging at levels higher than info to avoid spamming log systems; however, they still sometimes need to inform users that something might have went wrong. In this case, we decided that |
||
through other means like throwing from a method | ||
through other means, like throwing from a method. | ||
- **Examples**: Connection retry attempts, fallback mechanisms, recoverable | ||
failures | ||
- **Guideline**: Use sparingly - not for normal successful operations | ||
failures. | ||
- **Guideline**: Use sparingly - Don't use for normal successful operations. | ||
|
||
#### For applications | ||
|
||
|
@@ -133,6 +133,6 @@ logger.info("Response sent") | |
|
||
// ✅ Good: Use appropriate levels instead | ||
logger.debug("Processing request", metadata: ["path": "\(path)"]) | ||
logger.trace("Query", , metadata: ["path": "\(query)"]) | ||
logger.trace("Query", metadata: ["sql": "\(query)"]) | ||
logger.debug("Request completed", metadata: ["status": "\(status)"]) | ||
``` |
Original file line number | Diff line number | Diff line change |
---|---|---|
@@ -0,0 +1,96 @@ | ||
# 002: Structured logging | ||
|
||
Use metadata to create machine-readable, searchable log entries. | ||
|
||
## Overview | ||
|
||
Structured logging uses metadata to separate human-readable messages from | ||
machine-readable data. This practice makes logs easier to search, filter, and | ||
analyze programmatically while maintaining readability. | ||
|
||
### Motivation | ||
|
||
Traditional string-based logging embeds all information in the message text, | ||
making it more difficult for automated tools to parse and extract. | ||
Structured logging separates these concerns; messages provide human readable | ||
context while metadata provides structured data for tooling. | ||
|
||
### Example | ||
|
||
#### Recommended: Structured logging | ||
|
||
```swift | ||
// ✅ Structured - message provides context, metadata provides data | ||
logger.info( | ||
"Accepted connection", | ||
metadata: [ | ||
"connection.id": "\(id)", | ||
"connection.peer": "\(peer)", | ||
"connections.total": "\(count)" | ||
] | ||
) | ||
|
||
logger.error( | ||
"Database query failed", | ||
metadata: [ | ||
"query.retries": "\(retries)", | ||
"query.error": "\(error)", | ||
"query.duration": "\(duration)" | ||
] | ||
) | ||
``` | ||
|
||
### Advanced: Nested metadata for complex data | ||
|
||
```swift | ||
// ✅ Complex structured data | ||
logger.trace( | ||
"HTTP request started", | ||
metadata: [ | ||
"request.id": "\(requestId)", | ||
"request.method": "GET", | ||
"request.path": "/api/users", | ||
"request.headers": [ | ||
"user-agent": "\(userAgent)" | ||
], | ||
"client.ip": "\(clientIP)", | ||
"client.country": "\(country)" | ||
] | ||
) | ||
``` | ||
|
||
#### Avoid: Unstructured logging | ||
|
||
```swift | ||
// ❌ Not structured - hard to parse programmatically | ||
logger.info("Accepted connection \(id) from \(peer), total: \(count)") | ||
logger.error("Database query failed after \(retries) retries: \(error)") | ||
``` | ||
|
||
### Metadata key conventions | ||
|
||
Use hierarchical dot-notation for related fields: | ||
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. Yeah dots is a good recommendation I think... if some specific backend needs something else they can do what prometheus does in metrics for labels (nameAndLabelSanitizer) 👍 |
||
|
||
```swift | ||
// ✅ Good: Hierarchical keys | ||
logger.debug( | ||
"Database operation completed", | ||
metadata: [ | ||
"db.operation": "SELECT", | ||
"db.table": "users", | ||
"db.duration": "\(duration)", | ||
"db.rows": "\(rowCount)" | ||
] | ||
) | ||
|
||
// ✅ Good: Consistent prefixing | ||
logger.info( | ||
"HTTP response", | ||
metadata: [ | ||
"http.method": "POST", | ||
"http.status": "201", | ||
"http.path": "/api/users", | ||
"http.duration": "\(duration)" | ||
] | ||
) | ||
``` | ||
FranzBusch marked this conversation as resolved.
Show resolved
Hide resolved
|
Original file line number | Diff line number | Diff line change |
---|---|---|
@@ -0,0 +1,100 @@ | ||
# 003: Accepting loggers in libraries | ||
|
||
Accept loggers through method parameters to ensure proper metadata propagation. | ||
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. Would you consider splitting this one into a separate PR to allow us to discuss more, without blocking the other changes? I have more thoughts here. |
||
|
||
## Overview | ||
|
||
Libraries should accept logger instances through method parameters rather than | ||
storing them as instance variables. This practice ensures metadata (such as | ||
correlation IDs) is properly propagated down the call stack, while giving | ||
applications control over logging configuration. | ||
|
||
### Motivation | ||
|
||
When libraries accept loggers as method parameters, they enable automatic | ||
propagation of contextual metadata attached to the logger instance. This is | ||
especially important for distributed systems where correlation IDs must flow | ||
through the entire request processing pipeline. | ||
|
||
### Example | ||
|
||
#### Recommended: Accept logger through method parameters | ||
|
||
```swift | ||
// ✅ Good: Pass the logger through method parameters. | ||
struct RequestProcessor { | ||
func processRequest(_ request: HTTPRequest, logger: Logger) async throws -> HTTPResponse { | ||
// Add structured metadata that every log statement should contain. | ||
var logger = logger | ||
logger[metadataKey: "request.method"] = "\(request.method)" | ||
logger[metadataKey: "request.path"] = "\(request.path)" | ||
logger[metadataKey: "request.id"] = "\(request.id)" | ||
|
||
logger.debug("Processing request") | ||
|
||
// Pass the logger down to maintain metadata context. | ||
let validatedData = try validateRequest(request, logger: logger) | ||
let result = try await executeBusinessLogic(validatedData, logger: logger) | ||
|
||
logger.debug("Request processed successfully") | ||
return result | ||
} | ||
|
||
private func validateRequest(_ request: HTTPRequest, logger: Logger) throws -> ValidatedRequest { | ||
logger.debug("Validating request parameters") | ||
// Include validation logic that uses the same logger context. | ||
return ValidatedRequest(request) | ||
} | ||
|
||
private func executeBusinessLogic(_ data: ValidatedRequest, logger: Logger) async throws -> HTTPResponse { | ||
logger.debug("Executing business logic") | ||
|
||
// Further propagate the logger to other services. | ||
let dbResult = try await databaseService.query(data.query, logger: logger) | ||
|
||
logger.debug("Business logic completed") | ||
return HTTPResponse(data: dbResult) | ||
} | ||
} | ||
``` | ||
|
||
#### Alternative: Accept logger through initializer when appropriate | ||
|
||
```swift | ||
// ✅ Acceptable: Logger through initializer for long-lived components | ||
glbrntt marked this conversation as resolved.
Show resolved
Hide resolved
|
||
final class BackgroundJobProcessor { | ||
private let logger: Logger | ||
|
||
init(logger: Logger) { | ||
self.logger = logger | ||
} | ||
|
||
func run() async { | ||
// Execute some long running work | ||
logger.debug("Update about long running work") | ||
// Execute some more long running work | ||
} | ||
} | ||
``` | ||
|
||
#### Avoid: Libraries creating their own loggers | ||
|
||
Libraries might create their own loggers; however, this leads to two problems. | ||
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. Might be worth adding a caveat: libraries should default to creating a no-op logger if the user didn't pass one in, that makes it easier to ensure that the logger is always propagated through the library. There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. I intentionally didn't add this since I think this is a topic of contention right now. I personally think this is a bad pattern since I have seen many cases where the default parameter led to folks not passing in their logger and when debugging they didn't get log statements. I personally much rather prefer having a non-optional non-defaulted parameter since it requires users attention. However, I think there is design space here by leveraging structured concurrency more to avoid all these manual passings of loggers altogether. |
||
First, users of the library can't inject their own loggers which means they have | ||
no control in customizing the log level or log handler. Secondly, it breaks the | ||
metadata propagation since users can't pass in a logger with already attached | ||
metadata. | ||
|
||
```swift | ||
// ❌ Bad: Library creates its own logger | ||
final class MyLibrary { | ||
private let logger = Logger(label: "MyLibrary") // Loses all context | ||
} | ||
|
||
// ✅ Good: Library accepts logger from caller | ||
final class MyLibrary { | ||
func operation(logger: Logger) { | ||
// Maintains caller's context and metadata | ||
} | ||
} | ||
``` |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.