|
| 1 | +# Task-Specific Logging System |
| 2 | + |
| 3 | +## Overview |
| 4 | + |
| 5 | +S7Tools now includes a comprehensive task-specific logging system that captures all activity related to individual task executions. Each task gets its own dedicated logging infrastructure with multiple log channels and both in-memory and file-based storage. |
| 6 | + |
| 7 | +## Architecture |
| 8 | + |
| 9 | +### Components |
| 10 | + |
| 11 | +1. **TaskLogger** (`S7Tools.Core/Models/Jobs/TaskLogger.cs`) |
| 12 | + - Metadata container for task-specific logging |
| 13 | + - Tracks logger instances, file paths, and statistics |
| 14 | + - Attached to each `TaskExecution` instance |
| 15 | + |
| 16 | +2. **TaskLoggerFactory** (`S7Tools/Services/Logging/TaskLoggerFactory.cs`) |
| 17 | + - Creates and manages task-specific loggers |
| 18 | + - Provides three logging channels per task: |
| 19 | + - **Main Logger**: General task operations |
| 20 | + - **Protocol Logger**: TCP/socat communication |
| 21 | + - **Process Logger**: Socat stdout/stderr output |
| 22 | + |
| 23 | +3. **Integration with EnhancedTaskScheduler** |
| 24 | + - Automatically creates logger when task starts |
| 25 | + - Logs all task lifecycle events |
| 26 | + - Finalizes and saves logs when task completes |
| 27 | + |
| 28 | +## Features |
| 29 | + |
| 30 | +### Multiple Log Channels |
| 31 | + |
| 32 | +Each task execution has **three separate log channels**: |
| 33 | + |
| 34 | +| Channel | Purpose | Log Level | Max Entries | |
| 35 | +|---------|---------|-----------|-------------| |
| 36 | +| **Main** | General task operations, progress, errors | Debug | 10,000 | |
| 37 | +| **Protocol** | TCP/socat communication details | Trace | 50,000 | |
| 38 | +| **Process** | Socat process stdout/stderr | Debug | 20,000 | |
| 39 | + |
| 40 | +### Dual Storage |
| 41 | + |
| 42 | +Each log channel has **two storage targets**: |
| 43 | + |
| 44 | +1. **In-Memory DataStore** |
| 45 | + - Circular buffer for real-time UI display |
| 46 | + - Fast access for monitoring |
| 47 | + - Thread-safe concurrent access |
| 48 | + - Configured max entries per channel |
| 49 | + |
| 50 | +2. **File Storage** |
| 51 | + - Persistent log files on disk |
| 52 | + - Automatic directory creation |
| 53 | + - Organized by task name and timestamp |
| 54 | + |
| 55 | +### Log Organization |
| 56 | + |
| 57 | +Logs are organized in directories per task: |
| 58 | + |
| 59 | +``` |
| 60 | +Logs/ |
| 61 | +└── Tasks/ |
| 62 | + └── {TaskName}_{Timestamp}_{TaskId}/ |
| 63 | + ├── main.log # General operations |
| 64 | + ├── protocol.log # TCP/socat communication |
| 65 | + └── process.log # Socat stdout/stderr |
| 66 | +``` |
| 67 | + |
| 68 | +Example: |
| 69 | +``` |
| 70 | +Logs/Tasks/MemoryDump_20251113_143022_a3b5c7d9/ |
| 71 | +├── main.log |
| 72 | +├── protocol.log |
| 73 | +└── process.log |
| 74 | +``` |
| 75 | + |
| 76 | +## Usage |
| 77 | + |
| 78 | +### Automatic Integration |
| 79 | + |
| 80 | +The system is **automatically integrated** into task execution: |
| 81 | + |
| 82 | +1. **Task Start**: |
| 83 | + - `EnhancedTaskScheduler` creates logger via `TaskLoggerFactory` |
| 84 | + - Logger attached to `TaskExecution.Logger` |
| 85 | + - All three channels initialized |
| 86 | + |
| 87 | +2. **During Execution**: |
| 88 | + - Main logger captures task lifecycle events |
| 89 | + - Protocol logger ready for TCP/socat communication |
| 90 | + - Process logger ready for socat output |
| 91 | + |
| 92 | +3. **Task Completion**: |
| 93 | + - Logger finalized automatically |
| 94 | + - All logs flushed to files |
| 95 | + - Statistics calculated (total entries, file size) |
| 96 | + |
| 97 | +### Accessing Task Logs |
| 98 | + |
| 99 | +```csharp |
| 100 | +// Get task execution |
| 101 | +TaskExecution task = await taskScheduler.GetTaskAsync(taskId); |
| 102 | + |
| 103 | +// Access logger metadata |
| 104 | +TaskLogger? logger = task.Logger; |
| 105 | +if (logger != null) |
| 106 | +{ |
| 107 | + Console.WriteLine($"Main log: {logger.MainLogFilePath}"); |
| 108 | + Console.WriteLine($"Protocol log: {logger.ProtocolLogFilePath}"); |
| 109 | + Console.WriteLine($"Process log: {logger.ProcessLogFilePath}"); |
| 110 | + Console.WriteLine($"Total entries: {logger.TotalLogEntries}"); |
| 111 | + Console.WriteLine($"Total size: {logger.TotalLogFilesSize} bytes"); |
| 112 | +} |
| 113 | +``` |
| 114 | + |
| 115 | +### Accessing In-Memory Logs |
| 116 | + |
| 117 | +```csharp |
| 118 | +// Get in-memory DataStore for real-time UI |
| 119 | +ILogDataStore? mainStore = (ILogDataStore?)taskLoggerFactory.GetTaskDataStore( |
| 120 | + taskId, |
| 121 | + TaskLogType.Main); |
| 122 | + |
| 123 | +if (mainStore != null) |
| 124 | +{ |
| 125 | + var recentLogs = mainStore.Entries.TakeLast(100); |
| 126 | + foreach (var log in recentLogs) |
| 127 | + { |
| 128 | + Console.WriteLine($"[{log.Timestamp}] {log.Level}: {log.Message}"); |
| 129 | + } |
| 130 | +} |
| 131 | +``` |
| 132 | + |
| 133 | +## Configuration |
| 134 | + |
| 135 | +### TaskLoggerFactory Settings |
| 136 | + |
| 137 | +```csharp |
| 138 | +// Default settings (can be customized) |
| 139 | +- Main Logger: Debug level, 10,000 entries |
| 140 | +- Protocol Logger: Trace level, 50,000 entries |
| 141 | +- Process Logger: Debug level, 20,000 entries |
| 142 | +``` |
| 143 | + |
| 144 | +### Enable/Disable Log Channels |
| 145 | + |
| 146 | +```csharp |
| 147 | +// Create logger with specific channels |
| 148 | +var logger = await taskLoggerFactory.CreateTaskLoggerAsync( |
| 149 | + taskId, |
| 150 | + taskName, |
| 151 | + captureProtocol: true, // Enable protocol logging |
| 152 | + captureProcessOutput: true, // Enable process logging |
| 153 | + cancellationToken); |
| 154 | +``` |
| 155 | + |
| 156 | +## Log Content Examples |
| 157 | + |
| 158 | +### Main Log |
| 159 | + |
| 160 | +``` |
| 161 | +[2025-11-13 14:30:22.123] [Information] Task execution started: MemoryDump (ID: a3b5c7d9) at 2025-11-13 14:30:22 |
| 162 | +[2025-11-13 14:30:22.456] [Information] Job profile loaded: S7-1200 Full Dump |
| 163 | +[2025-11-13 14:30:22.789] [Information] Starting bootloader execution |
| 164 | +[2025-11-13 14:30:23.012] [Information] Progress: Socat Setup - 10.0% |
| 165 | +[2025-11-13 14:30:24.345] [Information] Progress: Power Cycle - 20.0% |
| 166 | +[2025-11-13 14:30:26.678] [Information] Progress: Handshake - 30.0% |
| 167 | +[2025-11-13 14:30:30.901] [Information] Progress: Memory Dump - 80.0% |
| 168 | +[2025-11-13 14:30:32.234] [Information] Bootloader dump completed. Size: 65536 bytes |
| 169 | +[2025-11-13 14:30:32.567] [Information] Output saved to: /path/to/dump-a3b5c7d9.bin |
| 170 | +[2025-11-13 14:30:32.890] [Information] Task completed successfully. Execution time: 00:00:10.5 |
| 171 | +``` |
| 172 | + |
| 173 | +### Protocol Log (Future Enhancement) |
| 174 | + |
| 175 | +When socat/TCP communication is instrumented: |
| 176 | + |
| 177 | +``` |
| 178 | +[2025-11-13 14:30:23.456] [Trace] TCP connection established: 192.168.1.100:102 |
| 179 | +[2025-11-13 14:30:23.789] [Trace] TX: 03 00 00 16 11 E0 00 00 00 01 00 C1 02 10 00 C2 02 03 00 C0 01 0A |
| 180 | +[2025-11-13 14:30:23.912] [Trace] RX: 03 00 00 1B 02 F0 80 32 03 00 00 00 01 00 08 00 00 F0 00 00 01 00 01 03 C0 |
| 181 | +[2025-11-13 14:30:24.045] [Trace] Handshake acknowledged |
| 182 | +``` |
| 183 | + |
| 184 | +### Process Log (Future Enhancement) |
| 185 | + |
| 186 | +When socat stdout/stderr is captured: |
| 187 | + |
| 188 | +``` |
| 189 | +[2025-11-13 14:30:23.234] [Debug] socat[12345] I socat Version 1.7.4.0 |
| 190 | +[2025-11-13 14:30:23.567] [Debug] socat[12345] I socket(1, 2, 0) -> 3 |
| 191 | +[2025-11-13 14:30:23.890] [Debug] socat[12345] I starting data transfer loop with FDs [3,3] and [4,4] |
| 192 | +[2025-11-13 14:30:32.123] [Debug] socat[12345] I transferred 65536 bytes from 3 to 4 |
| 193 | +``` |
| 194 | + |
| 195 | +## Next Steps: Socat Output Capture |
| 196 | + |
| 197 | +To complete the process logging, integrate socat stdout/stderr capture: |
| 198 | + |
| 199 | +### 1. Modify SocatService.StartSocatAsync |
| 200 | + |
| 201 | +```csharp |
| 202 | +// In SocatService.cs |
| 203 | +public async Task<SocatProcessInfo> StartSocatAsync( |
| 204 | + SocatConfiguration configuration, |
| 205 | + string serialDevice, |
| 206 | + ILogger? processLogger = null, // NEW: Optional process logger |
| 207 | + CancellationToken cancellationToken = default) |
| 208 | +{ |
| 209 | + // ... existing code ... |
| 210 | +
|
| 211 | + // Attach process logger to stdout/stderr handlers |
| 212 | + process.OutputDataReceived += (_, e) => |
| 213 | + { |
| 214 | + if (e.Data != null) |
| 215 | + { |
| 216 | + outputBuilder!.AppendLine(e.Data); |
| 217 | + _logger.LogTrace("Socat output: {Output}", e.Data); |
| 218 | + processLogger?.LogDebug("socat[{ProcessId}] {Output}", process.Id, e.Data); // NEW |
| 219 | + } |
| 220 | + }; |
| 221 | + |
| 222 | + process.ErrorDataReceived += (_, e) => |
| 223 | + { |
| 224 | + if (e.Data != null) |
| 225 | + { |
| 226 | + errorBuilder!.AppendLine(e.Data); |
| 227 | + _logger.LogWarning("Socat error: {Error}", e.Data); |
| 228 | + processLogger?.LogWarning("socat[{ProcessId}] ERROR: {Error}", process.Id, e.Data); // NEW |
| 229 | + } |
| 230 | + }; |
| 231 | + |
| 232 | + // ... rest of code ... |
| 233 | +} |
| 234 | +``` |
| 235 | + |
| 236 | +### 2. Pass Process Logger from Bootloader |
| 237 | + |
| 238 | +```csharp |
| 239 | +// In BootloaderService.DumpAsync |
| 240 | +var socatInfo = await _socat.StartSocatAsync( |
| 241 | + profiles.Socat, |
| 242 | + profiles.Serial.Device, |
| 243 | + taskLogger?.ProcessLogger, // Pass process logger |
| 244 | + cancellationToken); |
| 245 | +``` |
| 246 | + |
| 247 | +### 3. Protocol Logging (TCP Communication) |
| 248 | + |
| 249 | +For protocol-level logging, instrument the PLC client: |
| 250 | + |
| 251 | +```csharp |
| 252 | +// In PlcClient or transport layer |
| 253 | +public async Task<byte[]> SendCommandAsync(byte[] command, ILogger? protocolLogger = null) |
| 254 | +{ |
| 255 | + protocolLogger?.LogTrace("TX: {Hex}", BitConverter.ToString(command)); |
| 256 | + |
| 257 | + var response = await _transport.SendAsync(command); |
| 258 | + |
| 259 | + protocolLogger?.LogTrace("RX: {Hex}", BitConverter.ToString(response)); |
| 260 | + |
| 261 | + return response; |
| 262 | +} |
| 263 | +``` |
| 264 | + |
| 265 | +## Benefits |
| 266 | + |
| 267 | +### For Users |
| 268 | + |
| 269 | +- **Complete Task Audit Trail**: Every task execution fully logged |
| 270 | +- **Troubleshooting**: Detailed logs help diagnose failures |
| 271 | +- **Real-Time Monitoring**: In-memory logs for live UI updates |
| 272 | +- **Historical Analysis**: Persistent files for post-mortem |
| 273 | + |
| 274 | +### For Developers |
| 275 | + |
| 276 | +- **Debugging**: Detailed protocol and process logs |
| 277 | +- **Testing**: Easy verification of task behavior |
| 278 | +- **Metrics**: Track task performance and statistics |
| 279 | +- **Compliance**: Comprehensive audit trails |
| 280 | + |
| 281 | +### For Operations |
| 282 | + |
| 283 | +- **Monitoring**: Real-time view of task execution |
| 284 | +- **Alerting**: Detect failures from log patterns |
| 285 | +- **Reporting**: Generate reports from log data |
| 286 | +- **Forensics**: Investigate past task executions |
| 287 | + |
| 288 | +## Implementation Status |
| 289 | + |
| 290 | +### ✅ Completed |
| 291 | + |
| 292 | +- [x] TaskLogger model |
| 293 | +- [x] TaskLoggerFactory service |
| 294 | +- [x] ITaskLoggerFactory interface |
| 295 | +- [x] Integration with EnhancedTaskScheduler |
| 296 | +- [x] In-memory DataStore per channel |
| 297 | +- [x] File logging per channel |
| 298 | +- [x] Automatic logger lifecycle management |
| 299 | +- [x] DI registration |
| 300 | + |
| 301 | +### 🔄 Next Steps |
| 302 | + |
| 303 | +- [ ] Integrate process logger with SocatService |
| 304 | +- [ ] Integrate protocol logger with PLC client |
| 305 | +- [ ] Add UI for viewing task logs |
| 306 | +- [ ] Add log export functionality |
| 307 | +- [ ] Add log search and filtering |
| 308 | +- [ ] Add log retention policies |
| 309 | + |
| 310 | +## Testing |
| 311 | + |
| 312 | +To test the system: |
| 313 | + |
| 314 | +1. **Create and run a task**: |
| 315 | + ```bash |
| 316 | + # Run application |
| 317 | + dotnet run --project src/S7Tools --configuration Debug |
| 318 | + |
| 319 | + # Create job, queue task |
| 320 | + ``` |
| 321 | + |
| 322 | +2. **Check log directory**: |
| 323 | + ```bash |
| 324 | + # After task completes, check logs |
| 325 | + ls -la Logs/Tasks/ |
| 326 | + ls -la Logs/Tasks/{TaskName}_{Timestamp}_{TaskId}/ |
| 327 | + |
| 328 | + # View main log |
| 329 | + cat Logs/Tasks/{TaskName}_{Timestamp}_{TaskId}/main.log |
| 330 | + ``` |
| 331 | + |
| 332 | +3. **Verify in-memory logs**: |
| 333 | + - Access via TaskLoggerFactory.GetTaskDataStore() |
| 334 | + - Display in UI (future enhancement) |
| 335 | + |
| 336 | +## Architecture Compliance |
| 337 | + |
| 338 | +This implementation follows S7Tools architectural principles: |
| 339 | + |
| 340 | +- ✅ **Clean Architecture**: Core models, App services, Infrastructure separation |
| 341 | +- ✅ **Dependency Injection**: All services registered in DI |
| 342 | +- ✅ **MVVM Ready**: In-memory DataStores support UI binding |
| 343 | +- ✅ **Thread Safety**: Semaphore-protected operations |
| 344 | +- ✅ **Dispose Pattern**: Proper resource cleanup |
| 345 | +- ✅ **Logging Integration**: Uses existing LogDataStore infrastructure |
| 346 | + |
| 347 | +## Related Documentation |
| 348 | + |
| 349 | +- [Task Execution Model](../src/S7Tools.Core/Models/Jobs/TaskExecution.cs) |
| 350 | +- [Task Scheduler](../src/S7Tools/Services/Tasking/EnhancedTaskScheduler.cs) |
| 351 | +- [LogDataStore](../src/S7Tools.Infrastructure.Logging/Core/Storage/LogDataStore.cs) |
| 352 | +- [System Patterns](./patterns/system-patterns.md) |
| 353 | + |
| 354 | +--- |
| 355 | + |
| 356 | +**Created**: 2025-11-13 |
| 357 | +**Status**: ✅ Core Implementation Complete |
| 358 | +**Next Phase**: UI Integration & Process Capture |
0 commit comments