|
| 1 | +# Structured Logging Guide |
| 2 | + |
| 3 | +This guide explains the structured logging implementation in the Torrust Tracker Deploy project, which uses hierar### JSON Output Format |
| 4 | + |
| 5 | +When using `logging::init_json()` or `LogFormat::Json`, logs are output in JSON format suitable for log aggregation: |
| 6 | + |
| 7 | +````json |
| 8 | +{ |
| 9 | + "timestamp": "2024-09-16T17:00:00.000Z", |
| 10 | + "level": "INFO", |
| 11 | + "fields": { |
| 12 | + "command_type": "provision" |
| 13 | + }, |
| 14 | + "target": "torrust_tracker_deploy::commands::provision", |
| 15 | + "span": { |
| 16 | + "name": "provision_command" |
| 17 | + }, |
| 18 | + "spans": [{ "name": "provision_command", "command_type": "provision" }] |
| 19 | +} |
| 20 | +```ns to mirror our three-level architecture. |
| 21 | + |
| 22 | +## Architecture Overview |
| 23 | + |
| 24 | +Our structured logging follows a three-level hierarchy that mirrors the application architecture: |
| 25 | + |
| 26 | +```text |
| 27 | +Level 1: Commands (Top-level orchestration) |
| 28 | +├── Level 2: Steps (Mid-level execution units) |
| 29 | +│ └── Level 3: Remote Actions (Leaf-level operations) |
| 30 | +```` |
| 31 | + |
| 32 | +## Setting Up Logging |
| 33 | + |
| 34 | +### Basic Setup (Recommended) |
| 35 | + |
| 36 | +```rust |
| 37 | +use torrust_tracker_deploy::logging; |
| 38 | + |
| 39 | +fn main() { |
| 40 | + // Initialize pretty-printed logging for development |
| 41 | + logging::init(); |
| 42 | + |
| 43 | + // Your application code here... |
| 44 | +} |
| 45 | +``` |
| 46 | + |
| 47 | +### Alternative Formats |
| 48 | + |
| 49 | +```rust |
| 50 | +use torrust_tracker_deploy::logging; |
| 51 | + |
| 52 | +fn main() { |
| 53 | + // For production (JSON output) |
| 54 | + logging::init_json(); |
| 55 | + |
| 56 | + // For compact output |
| 57 | + logging::init_compact(); |
| 58 | + |
| 59 | + // Using the format helper |
| 60 | + logging::init_with_format(&LogFormat::Json); |
| 61 | +} |
| 62 | +``` |
| 63 | + |
| 64 | +### CLI Applications with Format Selection |
| 65 | + |
| 66 | +For CLI applications that want to support multiple formats: |
| 67 | + |
| 68 | +```rust |
| 69 | +use torrust_tracker_deploy::logging::{self, LogFormat}; |
| 70 | +use clap::Parser; |
| 71 | + |
| 72 | +#[derive(Parser)] |
| 73 | +struct Cli { |
| 74 | + #[arg(long, default_value = "pretty")] |
| 75 | + log_format: LogFormat, |
| 76 | +} |
| 77 | + |
| 78 | +fn main() { |
| 79 | + let cli = Cli::parse(); |
| 80 | + logging::init_with_format(&cli.log_format); |
| 81 | + |
| 82 | + // Your application code... |
| 83 | +} |
| 84 | +``` |
| 85 | + |
| 86 | +## Span Hierarchy Examples |
| 87 | + |
| 88 | +When you execute operations, you'll see nested spans in your logs: |
| 89 | + |
| 90 | +### Example: Provision Command |
| 91 | + |
| 92 | +```text |
| 93 | +2024-09-16T17:00:00.000Z TRACE provision_command: Starting infrastructure provisioning |
| 94 | +2024-09-16T17:00:00.100Z TRACE provision_command:render_opentofu_templates: Rendering OpenTofu templates |
| 95 | +2024-09-16T17:00:00.200Z TRACE provision_command:initialize_infrastructure: Initializing infrastructure |
| 96 | +2024-09-16T17:00:00.300Z TRACE provision_command:plan_infrastructure: Planning infrastructure deployment |
| 97 | +2024-09-16T17:00:00.400Z TRACE provision_command:apply_infrastructure: Applying infrastructure changes |
| 98 | +2024-09-16T17:00:00.500Z TRACE provision_command:get_instance_info: Retrieving instance information |
| 99 | +2024-09-16T17:00:00.600Z INFO provision_command: Infrastructure provisioned successfully |
| 100 | +``` |
| 101 | + |
| 102 | +### Example: Configure Command with Remote Actions |
| 103 | + |
| 104 | +```text |
| 105 | +2024-09-16T17:01:00.000Z TRACE configure_command: Starting system configuration |
| 106 | +2024-09-16T17:01:00.100Z TRACE configure_command:render_ansible_templates: Rendering Ansible templates |
| 107 | +2024-09-16T17:01:00.200Z TRACE configure_command:wait_ssh_connectivity: Waiting for SSH connectivity |
| 108 | +2024-09-16T17:01:00.300Z TRACE configure_command:wait_cloud_init: Waiting for cloud-init completion |
| 109 | +2024-09-16T17:01:00.400Z TRACE configure_command:wait_cloud_init:cloud_init_validation: Validating cloud-init status |
| 110 | +2024-09-16T17:01:00.500Z TRACE configure_command:install_docker: Installing Docker |
| 111 | +2024-09-16T17:01:00.600Z TRACE configure_command:validate_docker_installation: Validating Docker |
| 112 | +2024-09-16T17:01:00.700Z TRACE configure_command:validate_docker_installation:docker_validation: Checking Docker version |
| 113 | +2024-09-16T17:01:00.800Z INFO configure_command: System configured successfully |
| 114 | +``` |
| 115 | + |
| 116 | +## Span Fields Reference |
| 117 | + |
| 118 | +### Command Level (Level 1) |
| 119 | + |
| 120 | +- **command_type**: The type of command being executed |
| 121 | + - Values: `"provision"`, `"configure"`, `"test"` |
| 122 | + |
| 123 | +### Step Level (Level 2) |
| 124 | + |
| 125 | +- **step_type**: The category of step being executed |
| 126 | + - Values: `"infrastructure"`, `"rendering"`, `"connectivity"`, `"system"`, `"software"`, `"validation"` |
| 127 | +- **operation**: The specific operation being performed |
| 128 | + - Examples: `"init"`, `"plan"`, `"apply"`, `"info"` |
| 129 | +- **template_type**: For rendering steps |
| 130 | + - Values: `"opentofu"`, `"ansible"` |
| 131 | +- **component**: For software/validation steps |
| 132 | + - Values: `"docker"`, `"docker_compose"`, `"cloud_init"` |
| 133 | + |
| 134 | +### Remote Action Level (Level 3) |
| 135 | + |
| 136 | +- **action_type**: The type of remote action |
| 137 | + - Values: `"validation"` |
| 138 | +- **component**: The component being acted upon |
| 139 | + - Values: `"cloud_init"`, `"docker"`, `"docker_compose"` |
| 140 | +- **server_ip**: The target server IP address |
| 141 | + |
| 142 | +## Environment Variables |
| 143 | + |
| 144 | +Control logging behavior with environment variables: |
| 145 | + |
| 146 | +```bash |
| 147 | +# Show all trace-level logs for development |
| 148 | +export RUST_LOG=torrust_tracker_deploy=trace |
| 149 | + |
| 150 | +# Production logging (info and above) |
| 151 | +export RUST_LOG=torrust_tracker_deploy=info |
| 152 | + |
| 153 | +# Only errors and warnings |
| 154 | +export RUST_LOG=torrust_tracker_deploy=warn |
| 155 | + |
| 156 | +# Detailed logging for specific modules |
| 157 | +export RUST_LOG=torrust_tracker_deploy::commands=trace,torrust_tracker_deploy::steps=debug |
| 158 | +``` |
| 159 | + |
| 160 | +## JSON Output Format |
| 161 | + |
| 162 | +When using `logging_simple::init_json()`, logs are output in JSON format suitable for log aggregation: |
| 163 | + |
| 164 | +```json |
| 165 | +{ |
| 166 | + "timestamp": "2024-09-16T17:00:00.000Z", |
| 167 | + "level": "INFO", |
| 168 | + "fields": { |
| 169 | + "command_type": "provision" |
| 170 | + }, |
| 171 | + "target": "torrust_tracker_deploy::commands::provision", |
| 172 | + "span": { |
| 173 | + "name": "provision_command" |
| 174 | + }, |
| 175 | + "spans": [{ "name": "provision_command", "command_type": "provision" }] |
| 176 | +} |
| 177 | +``` |
| 178 | + |
| 179 | +## Best Practices |
| 180 | + |
| 181 | +### 1. Use Appropriate Log Levels |
| 182 | + |
| 183 | +- **TRACE**: Detailed flow information (span entry/exit) |
| 184 | +- **DEBUG**: Detailed information for debugging |
| 185 | +- **INFO**: General information about application progress |
| 186 | +- **WARN**: Warning messages about potential issues |
| 187 | +- **ERROR**: Error messages about failures |
| 188 | + |
| 189 | +### 2. Leverage Span Context |
| 190 | + |
| 191 | +The hierarchical spans automatically provide context. You don't need to repeat information that's already captured in the span fields. |
| 192 | + |
| 193 | +```rust |
| 194 | +// Good: Span fields provide context |
| 195 | +#[instrument(name = "docker_validation", fields(component = "docker"))] |
| 196 | +pub async fn validate_docker() { |
| 197 | + info!("Starting validation"); // Context is implicit from span |
| 198 | +} |
| 199 | + |
| 200 | +// Avoid: Redundant context information |
| 201 | +#[instrument(name = "docker_validation", fields(component = "docker"))] |
| 202 | +pub async fn validate_docker() { |
| 203 | + info!(component = "docker", "Starting Docker validation"); // Redundant |
| 204 | +} |
| 205 | +``` |
| 206 | + |
| 207 | +### 3. Filter in Production |
| 208 | + |
| 209 | +Use environment-specific filtering to reduce noise in production: |
| 210 | + |
| 211 | +```bash |
| 212 | +# Development: Show everything |
| 213 | +export RUST_LOG=trace |
| 214 | + |
| 215 | +# Production: Focus on important events |
| 216 | +export RUST_LOG=torrust_tracker_deploy=info,warn,error |
| 217 | +``` |
| 218 | + |
| 219 | +## Debugging |
| 220 | + |
| 221 | +### Viewing Span Relationships |
| 222 | + |
| 223 | +To see the full span hierarchy, use trace level logging: |
| 224 | + |
| 225 | +```bash |
| 226 | +RUST_LOG=torrust_tracker_deploy=trace cargo run --bin your-binary |
| 227 | +``` |
| 228 | + |
| 229 | +### Finding Specific Operations |
| 230 | + |
| 231 | +Filter logs for specific operations: |
| 232 | + |
| 233 | +```bash |
| 234 | +# Only infrastructure operations |
| 235 | +RUST_LOG=torrust_tracker_deploy=info cargo run | grep infrastructure |
| 236 | + |
| 237 | +# Only validation operations |
| 238 | +RUST_LOG=torrust_tracker_deploy=trace cargo run | grep validation |
| 239 | +``` |
| 240 | + |
| 241 | +### Performance Analysis |
| 242 | + |
| 243 | +The span timings help identify slow operations: |
| 244 | + |
| 245 | +```text |
| 246 | +2024-09-16T17:00:00.000Z TRACE provision_command: entered |
| 247 | +2024-09-16T17:00:05.234Z TRACE provision_command: exited // 5.234 seconds total |
| 248 | +``` |
0 commit comments