forked from open-telemetry/opentelemetry-rust
-
Notifications
You must be signed in to change notification settings - Fork 0
/
Copy pathsimple_log_processor.rs
425 lines (362 loc) · 16.4 KB
/
simple_log_processor.rs
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
186
187
188
189
190
191
192
193
194
195
196
197
198
199
200
201
202
203
204
205
206
207
208
209
210
211
212
213
214
215
216
217
218
219
220
221
222
223
224
225
226
227
228
229
230
231
232
233
234
235
236
237
238
239
240
241
242
243
244
245
246
247
248
249
250
251
252
253
254
255
256
257
258
259
260
261
262
263
264
265
266
267
268
269
270
271
272
273
274
275
276
277
278
279
280
281
282
283
284
285
286
287
288
289
290
291
292
293
294
295
296
297
298
299
300
301
302
303
304
305
306
307
308
309
310
311
312
313
314
315
316
317
318
319
320
321
322
323
324
325
326
327
328
329
330
331
332
333
334
335
336
337
338
339
340
341
342
343
344
345
346
347
348
349
350
351
352
353
354
355
356
357
358
359
360
361
362
363
364
365
366
367
368
369
370
371
372
373
374
375
376
377
378
379
380
381
382
383
384
385
386
387
388
389
390
391
392
393
394
395
396
397
398
399
400
401
402
403
404
405
406
407
408
409
410
411
412
413
414
415
416
417
418
419
420
421
422
423
424
425
//! # OpenTelemetry Simple Log Processor
//! The `SimpleLogProcessor` is one implementation of the `LogProcessor` interface.
//!
//! It forwards log records to the exporter immediately after they are emitted
//! (or one exporter after another if applicable). This processor is
//! **synchronous** and is designed for debugging or testing purposes. It is
//! **not suitable for production** environments due to its lack of batching,
//! performance optimizations, or support for high-throughput scenarios.
//!
//! ## Diagram
//!
//! ```ascii
//! +-----+---------------+ +-----------------------+ +-------------------+
//! | | | | | | |
//! | SDK | Logger.emit() +---> (Simple)LogProcessor +---> LogExporter |
//! +-----+---------------+ +-----------------------+ +-------------------+
//! ```
use crate::error::{OTelSdkError, OTelSdkResult};
use crate::logs::log_processor::LogProcessor;
use crate::{
logs::{LogBatch, LogExporter, SdkLogRecord},
Resource,
};
use opentelemetry::{otel_debug, otel_error, otel_warn, InstrumentationScope};
use std::fmt::Debug;
use std::sync::atomic::AtomicBool;
use std::sync::Mutex;
/// A [`LogProcessor`] designed for testing and debugging purpose, that immediately
/// exports log records as they are emitted. Log records are exported synchronously
/// in the same thread that emits the log record.
/// When using this processor with the OTLP Exporter, the following exporter
/// features are supported:
/// - `grpc-tonic`: This requires LoggerProvider to be created within a tokio
/// runtime. Logs can be emitted from any thread, including tokio runtime
/// threads.
/// - `reqwest-blocking-client`: LoggerProvider may be created anywhere, but
/// logs must be emitted from a non-tokio runtime thread.
/// - `reqwest-client`: LoggerProvider may be created anywhere, but logs must be
/// emitted from a tokio runtime thread.
///
/// ## Example
///
/// ### Using a SimpleLogProcessor
///
/// ```rust
/// use opentelemetry_sdk::logs::{SimpleLogProcessor, SdkLoggerProvider, LogExporter};
/// use opentelemetry::global;
/// use opentelemetry_sdk::logs::InMemoryLogExporter;
///
/// let exporter = InMemoryLogExporter::default(); // Replace with an actual exporter
/// let provider = SdkLoggerProvider::builder()
/// .with_simple_exporter(exporter)
/// .build();
///
/// ```
///
#[derive(Debug)]
pub struct SimpleLogProcessor<T: LogExporter> {
exporter: Mutex<T>,
is_shutdown: AtomicBool,
}
impl<T: LogExporter> SimpleLogProcessor<T> {
pub(crate) fn new(exporter: T) -> Self {
SimpleLogProcessor {
exporter: Mutex::new(exporter),
is_shutdown: AtomicBool::new(false),
}
}
}
impl<T: LogExporter> LogProcessor for SimpleLogProcessor<T> {
fn emit(&self, record: &mut SdkLogRecord, instrumentation: &InstrumentationScope) {
// noop after shutdown
if self.is_shutdown.load(std::sync::atomic::Ordering::Relaxed) {
// this is a warning, as the user is trying to log after the processor has been shutdown
otel_warn!(
name: "SimpleLogProcessor.Emit.ProcessorShutdown",
);
return;
}
let result = self
.exporter
.lock()
.map_err(|_| OTelSdkError::InternalFailure("SimpleLogProcessor mutex poison".into()))
.and_then(|exporter| {
let log_tuple = &[(record as &SdkLogRecord, instrumentation)];
futures_executor::block_on(exporter.export(LogBatch::new(log_tuple)))
});
// Handle errors with specific static names
match result {
Err(OTelSdkError::InternalFailure(_)) => {
// logging as debug as this is not a user error
otel_debug!(
name: "SimpleLogProcessor.Emit.MutexPoisoning",
);
}
Err(err) => {
otel_error!(
name: "SimpleLogProcessor.Emit.ExportError",
error = format!("{}",err)
);
}
_ => {}
}
}
fn force_flush(&self) -> OTelSdkResult {
Ok(())
}
fn shutdown(&self) -> OTelSdkResult {
self.is_shutdown
.store(true, std::sync::atomic::Ordering::Relaxed);
if let Ok(exporter) = self.exporter.lock() {
exporter.shutdown()
} else {
Err(OTelSdkError::InternalFailure(
"SimpleLogProcessor mutex poison at shutdown".into(),
))
}
}
fn set_resource(&self, resource: &Resource) {
if let Ok(mut exporter) = self.exporter.lock() {
exporter.set_resource(resource);
}
}
}
#[cfg(all(test, feature = "testing", feature = "logs"))]
mod tests {
use crate::logs::log_processor::tests::MockLogExporter;
use crate::logs::{LogBatch, LogExporter, SdkLogRecord};
use crate::{
error::OTelSdkResult,
logs::{InMemoryLogExporterBuilder, LogProcessor, SdkLoggerProvider, SimpleLogProcessor},
Resource,
};
use opentelemetry::InstrumentationScope;
use opentelemetry::KeyValue;
use std::sync::atomic::{AtomicUsize, Ordering};
use std::sync::{Arc, Mutex};
use std::time::Duration;
#[derive(Debug, Clone)]
struct LogExporterThatRequiresTokio {
export_count: Arc<AtomicUsize>,
}
impl LogExporterThatRequiresTokio {
/// Creates a new instance of `LogExporterThatRequiresTokio`.
fn new() -> Self {
LogExporterThatRequiresTokio {
export_count: Arc::new(AtomicUsize::new(0)),
}
}
/// Returns the number of logs stored in the exporter.
fn len(&self) -> usize {
self.export_count.load(Ordering::Acquire)
}
}
impl LogExporter for LogExporterThatRequiresTokio {
async fn export(&self, batch: LogBatch<'_>) -> OTelSdkResult {
// Simulate minimal dependency on tokio by sleeping asynchronously for a short duration
tokio::time::sleep(Duration::from_millis(50)).await;
for _ in batch.iter() {
self.export_count.fetch_add(1, Ordering::Acquire);
}
Ok(())
}
}
#[test]
fn test_set_resource_simple_processor() {
let exporter = MockLogExporter {
resource: Arc::new(Mutex::new(None)),
};
let processor = SimpleLogProcessor::new(exporter.clone());
let _ = SdkLoggerProvider::builder()
.with_log_processor(processor)
.with_resource(
Resource::builder_empty()
.with_attributes([
KeyValue::new("k1", "v1"),
KeyValue::new("k2", "v3"),
KeyValue::new("k3", "v3"),
KeyValue::new("k4", "v4"),
KeyValue::new("k5", "v5"),
])
.build(),
)
.build();
assert_eq!(exporter.get_resource().unwrap().into_iter().count(), 5);
}
#[test]
fn test_simple_shutdown() {
let exporter = InMemoryLogExporterBuilder::default()
.keep_records_on_shutdown()
.build();
let processor = SimpleLogProcessor::new(exporter.clone());
let mut record: SdkLogRecord = SdkLogRecord::new();
let instrumentation: InstrumentationScope = Default::default();
processor.emit(&mut record, &instrumentation);
processor.shutdown().unwrap();
let is_shutdown = processor
.is_shutdown
.load(std::sync::atomic::Ordering::Relaxed);
assert!(is_shutdown);
processor.emit(&mut record, &instrumentation);
assert_eq!(1, exporter.get_emitted_logs().unwrap().len());
assert!(exporter.is_shutdown_called());
}
#[test]
fn test_simple_processor_sync_exporter_without_runtime() {
let exporter = InMemoryLogExporterBuilder::default().build();
let processor = SimpleLogProcessor::new(exporter.clone());
let mut record: SdkLogRecord = SdkLogRecord::new();
let instrumentation: InstrumentationScope = Default::default();
processor.emit(&mut record, &instrumentation);
assert_eq!(exporter.get_emitted_logs().unwrap().len(), 1);
}
#[tokio::test(flavor = "multi_thread", worker_threads = 1)]
async fn test_simple_processor_sync_exporter_with_runtime() {
let exporter = InMemoryLogExporterBuilder::default().build();
let processor = SimpleLogProcessor::new(exporter.clone());
let mut record: SdkLogRecord = SdkLogRecord::new();
let instrumentation: InstrumentationScope = Default::default();
processor.emit(&mut record, &instrumentation);
assert_eq!(exporter.get_emitted_logs().unwrap().len(), 1);
}
#[tokio::test(flavor = "multi_thread")]
async fn test_simple_processor_sync_exporter_with_multi_thread_runtime() {
let exporter = InMemoryLogExporterBuilder::default().build();
let processor = Arc::new(SimpleLogProcessor::new(exporter.clone()));
let mut handles = vec![];
for _ in 0..10 {
let processor_clone = Arc::clone(&processor);
let handle = tokio::spawn(async move {
let mut record: SdkLogRecord = SdkLogRecord::new();
let instrumentation: InstrumentationScope = Default::default();
processor_clone.emit(&mut record, &instrumentation);
});
handles.push(handle);
}
for handle in handles {
handle.await.unwrap();
}
assert_eq!(exporter.get_emitted_logs().unwrap().len(), 10);
}
#[tokio::test(flavor = "current_thread")]
async fn test_simple_processor_sync_exporter_with_current_thread_runtime() {
let exporter = InMemoryLogExporterBuilder::default().build();
let processor = SimpleLogProcessor::new(exporter.clone());
let mut record: SdkLogRecord = SdkLogRecord::new();
let instrumentation: InstrumentationScope = Default::default();
processor.emit(&mut record, &instrumentation);
assert_eq!(exporter.get_emitted_logs().unwrap().len(), 1);
}
#[test]
fn test_simple_processor_async_exporter_without_runtime() {
// Use `catch_unwind` to catch the panic caused by missing Tokio runtime
let result = std::panic::catch_unwind(|| {
let exporter = LogExporterThatRequiresTokio::new();
let processor = SimpleLogProcessor::new(exporter.clone());
let mut record: SdkLogRecord = SdkLogRecord::new();
let instrumentation: InstrumentationScope = Default::default();
// This will panic because an tokio async operation within exporter without a runtime.
processor.emit(&mut record, &instrumentation);
});
// Verify that the panic occurred and check the panic message for the absence of a Tokio runtime
assert!(
result.is_err(),
"The test should fail due to missing Tokio runtime, but it did not."
);
let panic_payload = result.unwrap_err();
let panic_message = panic_payload
.downcast_ref::<String>()
.map(|s| s.as_str())
.or_else(|| panic_payload.downcast_ref::<&str>().copied())
.unwrap_or("No panic message");
assert!(
panic_message.contains("no reactor running")
|| panic_message.contains("must be called from the context of a Tokio 1.x runtime"),
"Expected panic message about missing Tokio runtime, but got: {}",
panic_message
);
}
#[tokio::test(flavor = "multi_thread", worker_threads = 4)]
#[ignore]
// This test demonstrates a potential deadlock scenario in a multi-threaded Tokio runtime.
// It spawns Tokio tasks equal to the number of runtime worker threads (4) to emit log events.
// Each task attempts to acquire a mutex on the exporter in `SimpleLogProcessor::emit`.
// Only one task obtains the lock, while the others are blocked, waiting for its release.
//
// The task holding the lock invokes the LogExporterThatRequiresTokio, which performs an
// asynchronous operation (e.g., network I/O simulated by `tokio::sleep`). This operation
// requires yielding control back to the Tokio runtime to make progress.
//
// However, all worker threads are occupied:
// - One thread is executing the async exporter operation
// - Three threads are blocked waiting for the mutex
//
// This leads to a deadlock as there are no available threads to drive the async operation
// to completion, preventing the mutex from being released. Consequently, neither the blocked
// tasks nor the exporter can proceed.
async fn test_simple_processor_async_exporter_with_all_runtime_worker_threads_blocked() {
let exporter = LogExporterThatRequiresTokio::new();
let processor = Arc::new(SimpleLogProcessor::new(exporter.clone()));
let concurrent_emit = 4; // number of worker threads
let mut handles = vec![];
// try send `concurrent_emit` events concurrently
for _ in 0..concurrent_emit {
let processor_clone = Arc::clone(&processor);
let handle = tokio::spawn(async move {
let mut record: SdkLogRecord = SdkLogRecord::new();
let instrumentation: InstrumentationScope = Default::default();
processor_clone.emit(&mut record, &instrumentation);
});
handles.push(handle);
}
// below code won't get executed
for handle in handles {
handle.await.unwrap();
}
assert_eq!(exporter.len(), concurrent_emit);
}
#[tokio::test(flavor = "multi_thread", worker_threads = 1)]
// This test uses a multi-threaded runtime setup with a single worker thread. Note that even
// though only one worker thread is created, it is distinct from the main thread. The processor
// emits a log event, and the exporter performs an async operation that requires the runtime.
// The single worker thread handles this operation without deadlocking, as long as no other
// tasks occupy the runtime.
async fn test_simple_processor_async_exporter_with_runtime() {
let exporter = LogExporterThatRequiresTokio::new();
let processor = SimpleLogProcessor::new(exporter.clone());
let mut record: SdkLogRecord = SdkLogRecord::new();
let instrumentation: InstrumentationScope = Default::default();
processor.emit(&mut record, &instrumentation);
assert_eq!(exporter.len(), 1);
}
#[tokio::test(flavor = "multi_thread")]
// This test uses a multi-threaded runtime setup with the default number of worker threads.
// The processor emits a log event, and the exporter, which requires the runtime for its async
// operations, can access one of the available worker threads to complete its task. As there
// are multiple threads, the exporter can proceed without blocking other tasks, ensuring the
// test completes successfully.
async fn test_simple_processor_async_exporter_with_multi_thread_runtime() {
let exporter = LogExporterThatRequiresTokio::new();
let processor = SimpleLogProcessor::new(exporter.clone());
let mut record: SdkLogRecord = SdkLogRecord::new();
let instrumentation: InstrumentationScope = Default::default();
processor.emit(&mut record, &instrumentation);
assert_eq!(exporter.len(), 1);
}
#[tokio::test(flavor = "current_thread")]
#[ignore]
// This test uses a current-thread runtime, where all operations run on the main thread.
// The processor emits a log event while the runtime is blocked using `futures::block_on`
// to complete the export operation. The exporter, which performs an async operation and
// requires the runtime, cannot progress because the main thread is already blocked.
// This results in a deadlock, as the runtime cannot move forward.
async fn test_simple_processor_async_exporter_with_current_thread_runtime() {
let exporter = LogExporterThatRequiresTokio::new();
let processor = SimpleLogProcessor::new(exporter.clone());
let mut record: SdkLogRecord = SdkLogRecord::new();
let instrumentation: InstrumentationScope = Default::default();
processor.emit(&mut record, &instrumentation);
assert_eq!(exporter.len(), 1);
}
}