tracing_th/
builder.rs

1use anyhow::Result;
2use std::ffi::{c_ulonglong, c_void, CString};
3use tracing::Level;
4use tracing_subscriber::Layer;
5
6use crate::define::VAL_FETCH_PAIR;
7use crate::visitor::{PrintlnVisitor, PrintlnVisitorInner};
8use std::ptr::null;
9use th_rs::define::{
10    TH_LogLine, ThCommon, TH_LOG_LEVEL_TH_LEVEL_DEBUG, TH_LOG_LEVEL_TH_LEVEL_ERROR,
11    TH_LOG_LEVEL_TH_LEVEL_INFO, TH_LOG_LEVEL_TH_LEVEL_TRACE, TH_LOG_LEVEL_TH_LEVEL_WARN,
12};
13use th_rs::helper::th_common;
14type ThLoggerType = Box<dyn Fn(&PrintlnVisitorInner) + Sync + Send>;
15
16#[derive(Default)]
17pub struct Builder {
18    logger: Option<ThLoggerType>,
19    helper: Option<th_common::Helper>,
20}
21impl Builder {
22    pub fn common(mut self, common_p: *const c_void) -> Self {
23        if common_p.is_null() {
24            panic!("Common must be set in th")
25        }
26        let common_p = common_p as *const ThCommon;
27
28        let print_log = unsafe { (*common_p).print_log_ex.expect("Logger must be set in th") };
29        let common_ctx = unsafe { (*common_p).ctx } as c_ulonglong;
30
31        self.helper = Some(th_common::Helper::new(common_p));
32        self.logger = Some(Box::new(move |log_line: &PrintlnVisitorInner| {
33            let span_pair = CString::new(log_line.span_pair.as_str()).unwrap_or_default();
34            let code = CString::new(log_line.code.as_str()).unwrap_or_default();
35            let body = log_line.body.to_plaint_string();
36            let body = CString::new(body.as_str()).unwrap_or_default();
37            let l = CString::new(log_line.line.as_str()).unwrap_or_default();
38            let file = CString::new(log_line.file.as_str()).unwrap_or_default();
39
40            let mut line: TH_LogLine = unsafe { std::mem::zeroed() };
41            line.span_parsed = log_line.span_parsed as _;
42            line.span_pair = if span_pair.is_empty() {
43                null()
44            } else {
45                span_pair.as_ptr()
46            };
47            line.code = if code.is_empty() {
48                null()
49            } else {
50                code.as_ptr()
51            };
52            line.body = if body.is_empty() {
53                null()
54            } else {
55                body.as_ptr()
56            };
57            line.level = log_line.level;
58            line.date = log_line.date;
59            line.line = if l.is_empty() { null() } else { l.as_ptr() };
60            line.file = if file.is_empty() {
61                null()
62            } else {
63                file.as_ptr()
64            };
65
66            line.file = if file.is_empty() {
67                null()
68            } else {
69                file.as_ptr()
70            };
71
72            unsafe { print_log(common_ctx as *mut c_void, std::ptr::addr_of!(line)) };
73        }));
74
75        self
76    }
77    pub fn build(self) -> Result<ThLayer> {
78        let Some(logger) = self.logger else {
79            anyhow::bail!("Logger must be set")
80        };
81        let Some(helper) = self.helper else {
82            anyhow::bail!("Logger must be set")
83        };
84        Ok(ThLayer { logger, helper })
85    }
86}
87
88pub struct ThLayer {
89    logger: ThLoggerType,
90    helper: th_common::Helper,
91}
92
93impl ThLayer {
94    pub fn builder() -> Builder {
95        Builder::default()
96    }
97}
98
99impl<S> Layer<S> for ThLayer
100where
101    S: tracing::Subscriber,
102    S: for<'lookup> tracing_subscriber::registry::LookupSpan<'lookup>,
103{
104    fn on_new_span(
105        &self,
106        attrs: &tracing::span::Attributes<'_>,
107        id: &tracing::span::Id,
108        ctx: tracing_subscriber::layer::Context<'_, S>,
109    ) {
110        let Some(span) = ctx.span(id) else {
111            return;
112        };
113
114        let mut inner = PrintlnVisitorInner {
115            is_span: true,
116            ..Default::default()
117        };
118
119        let mut visitor = PrintlnVisitor::new(&mut inner);
120
121        attrs.record(&mut visitor);
122
123        if inner.span_pair == VAL_FETCH_PAIR {
124            match self.helper.logger_get_this_span() {
125                Ok(span_pair) if !span_pair.is_empty() => {
126                    let _ = std::mem::replace(&mut inner.span_pair, span_pair);
127                }
128                _ => {
129                    return;
130                }
131            }
132        }
133
134        let mut extensions = span.extensions_mut();
135        extensions.insert(inner);
136    }
137
138    #[allow(non_snake_case)]
139    fn on_event(&self, event: &tracing::Event<'_>, ctx: tracing_subscriber::layer::Context<'_, S>) {
140        let mut inner = PrintlnVisitorInner {
141            is_span: false,
142            line: event.metadata().line().unwrap_or_default().to_string(),
143            file: event.metadata().file().unwrap_or_default().to_string(),
144            level: match *event.metadata().level() {
145                Level::TRACE => TH_LOG_LEVEL_TH_LEVEL_TRACE,
146                Level::DEBUG => TH_LOG_LEVEL_TH_LEVEL_DEBUG,
147                Level::INFO => TH_LOG_LEVEL_TH_LEVEL_INFO,
148                Level::WARN => TH_LOG_LEVEL_TH_LEVEL_WARN,
149                Level::ERROR => TH_LOG_LEVEL_TH_LEVEL_ERROR,
150            },
151
152            ..Default::default()
153        };
154
155        // for
156        let mut visitor = PrintlnVisitor::new(&mut inner);
157        event.record(&mut visitor);
158        let mut no_print = false;
159        if inner.span_pair_addr > 0 {
160            no_print = true;
161        }
162        // if span exist cover the event
163        if let Some(span) = ctx.event_span(event) {
164            if let Some(storage) = span.extensions().get::<PrintlnVisitorInner>() {
165                // override
166                let _ = std::mem::replace(&mut inner.span_pair, storage.span_pair.clone());
167                if inner.span_pair_addr > 0 {
168                    unsafe {
169                        std::ptr::write(
170                            inner.span_pair_addr as *mut String,
171                            storage.span_pair.clone(),
172                        );
173                    }
174                }
175
176                // set if no present
177                if inner.code.is_empty() {
178                    let _ = std::mem::replace(&mut inner.code, storage.code.clone());
179                }
180                inner.body.extent(&storage.body);
181                inner.span_parsed = true;
182            }
183        }
184        if no_print {
185            return;
186        }
187
188        (self.logger)(&inner);
189    }
190}
191
192#[cfg(test)]
193mod tests {
194
195    use crate::{define::SPAN_PAIR, visitor::LogBodys};
196
197    use super::*;
198    use cyberex::void::{opacue_to_mut, opacue_to_ref};
199    use rusty_fork::rusty_fork_test;
200    use std::{
201        collections::HashMap,
202        ffi::CStr,
203        mem,
204        ptr::{addr_of, addr_of_mut},
205    };
206    use th_rs::define::ThResultCallback;
207    use tracing::Instrument;
208    use tracing_subscriber::prelude::*;
209    use uuid::Uuid;
210    #[derive(Default)]
211    struct TestLogCtx {
212        logstr: String,
213        inner: PrintlnVisitorInner,
214    }
215    impl TestLogCtx {
216        pub fn clear(&mut self) {
217            let _ = std::mem::take(self);
218        }
219        pub fn logstr(&self) -> String {
220            self.logstr.clone()
221        }
222    }
223
224    unsafe extern "C" fn test_do_etc(
225        _ctx: *mut ::std::os::raw::c_void,
226        _json_data: *const ::std::os::raw::c_char,
227        result_cb: ThResultCallback,
228        user_data: ::std::os::raw::c_longlong,
229    ) {
230        if let Some(cb) = result_cb {
231            let raw = r#"{"code":"0","data":{"id": "value", "id2": "value2"}, "msg": ""}"#;
232            let cs = std::ffi::CString::new(raw).unwrap();
233            cb(0, cs.as_ptr(), raw.len(), user_data);
234        }
235    }
236
237    unsafe extern "C" fn test_th_log(
238        ctx: *mut ::std::os::raw::c_void,
239        line: *const TH_LogLine,
240    ) -> *const ::std::os::raw::c_char {
241        let line = opacue_to_ref(line);
242        let body = CStr::from_ptr(line.body);
243        let level = line.level;
244
245        let body = body.to_string_lossy();
246
247        let ctx = opacue_to_mut::<TestLogCtx>(ctx.cast());
248
249        ctx.inner.body = LogBodys::new(body.to_string());
250        if !line.code.is_null() {
251            ctx.inner.code = CStr::from_ptr(line.code).to_string_lossy().to_string();
252        }
253        if !line.span_pair.is_null() {
254            ctx.inner.span_pair = CStr::from_ptr(line.span_pair).to_string_lossy().to_string();
255        }
256        ctx.inner.level = line.level;
257        ctx.inner.date = line.date;
258
259        if !line.line.is_null() {
260            ctx.inner.line = CStr::from_ptr(line.line).to_string_lossy().to_string();
261        }
262        if !line.file.is_null() {
263            ctx.inner.file = CStr::from_ptr(line.file).to_string_lossy().to_string();
264        }
265
266        let logstr = format!("[tracing-th] {} {}", level, body);
267        println!("{}", logstr);
268        ctx.logstr = logstr;
269
270        std::ptr::null::<_>()
271    }
272
273    rusty_fork_test! {
274        #[test]
275        fn test_case() {
276            let mut ctx = TestLogCtx::default();
277            let mut x: ThCommon = unsafe { mem::zeroed() };
278            x.ctx = addr_of_mut!(ctx).cast();
279            x.print_log_ex = Some(test_th_log);
280            x.do_etc_ex = Some(test_do_etc);
281
282            let layer = ThLayer::builder()
283                .common(addr_of!(x).cast())
284                .build()
285                .unwrap();
286
287
288            tracing_subscriber::registry().with(layer).init();
289
290            // tracing::info!(a_bool = true, answer = 42, message = "first example");
291            tracing::info!("first example");
292
293            assert_eq!(ctx.logstr, "[tracing-th] 2 first example");
294
295            ctx.clear();
296            tracing::error!(a_bool = true, answer = 42, message = "second example");
297            assert_eq!(
298                ctx.logstr(),
299                "[tracing-th] 4 second example, a_bool: true, answer: 42"
300            );
301
302            ctx.clear();
303            tracing::trace!(message = "second example", a_bool = true, answer = 42);
304            assert_eq!(
305                ctx.logstr(),
306                "[tracing-th] 0 second example, a_bool: true, answer: 42"
307            );
308            ctx.clear();
309            let span_pair = "bizCode";
310            let body = "hello tracing";
311            let code = 404.to_string();
312            let date = 123u64;
313
314            tracing::trace!(message = body, span_pair = span_pair);
315            assert_eq!(ctx.inner.span_pair, "");// bizcode only effect in span
316            assert_eq!(ctx.inner.body.to_plaint_string(), body);
317            assert_eq!(ctx.inner.level, 0);
318            ctx.clear();
319
320            tracing::info!(body, span_pair = span_pair);
321            assert_eq!(ctx.inner.span_pair, "");// bizcode only effect in span
322            assert_eq!(ctx.inner.body.to_plaint_string(), body);
323            assert_eq!(ctx.inner.level, 2);
324            ctx.clear();
325
326            tracing::info!(body = body, span_pair = span_pair, code = code);
327            assert_eq!(ctx.inner.span_pair, "");// bizcode only effect in span
328            assert_eq!(ctx.inner.body.to_plaint_string(), body);
329            assert_eq!(ctx.inner.level, 2);
330            assert_eq!(ctx.inner.code, code);
331            ctx.clear();
332
333            tracing::info!(body = body, span_pair = span_pair, code = code, date = date);
334            assert_eq!(ctx.inner.span_pair, "");// bizcode only effect in span
335            assert_eq!(ctx.inner.body.to_plaint_string(), body);
336            assert_eq!(ctx.inner.level, 2);
337            assert_eq!(ctx.inner.code, code);
338            assert_eq!(ctx.inner.date, date);
339            ctx.clear();
340
341            tracing::info!(
342                span_pair = span_pair,
343                code = code,
344                date = date,
345                body
346            );
347            assert_eq!(ctx.inner.span_pair, "");// bizcode only effect in span
348            assert_eq!(ctx.inner.body.to_plaint_string(), body);
349            assert_eq!(ctx.inner.level, 2);
350            assert_eq!(ctx.inner.code, code);
351            assert_eq!(ctx.inner.date, date);
352            assert_eq!(ctx.inner.span_pair, "");// series_id only effect in span
353            ctx.clear();
354
355            tracing::info!(
356                span_pair = span_pair,
357                code = code,
358                date = date,
359                "body with format {} {}", "hello", "wrold"
360            );
361            assert_eq!(ctx.inner.span_pair, "");// bizcode only effect in span
362            assert_eq!(ctx.inner.body.to_plaint_string(), "body with format hello wrold");
363            assert_eq!(ctx.inner.level, 2);
364            assert_eq!(ctx.inner.code, code);
365            assert_eq!(ctx.inner.date, date);
366            ctx.clear();
367
368
369        }
370
371    }
372    rusty_fork_test! {
373        #[test]
374        fn test_case_span() {
375            let mut ctx = TestLogCtx::default();
376            let mut x: ThCommon = unsafe { mem::zeroed() };
377            x.ctx = addr_of_mut!(ctx).cast();
378            x.print_log_ex = Some(test_th_log);
379
380
381            let layer = ThLayer::builder()
382                .common(addr_of!(x).cast())
383                .build()
384                .unwrap();
385
386            tracing_subscriber::registry().with(layer).init();
387            ctx.clear();
388
389            tracing::info!(
390                body = "no-effect",
391                span_pair = "no-effect-seriesId",
392
393            );
394            assert_eq!(ctx.inner.body.to_plaint_string(), "no-effect");
395            assert_eq!(ctx.inner.span_pair, ""); // seriesId is only set when in span
396            assert_eq!(ctx.inner.span_pair, ""); // seriesId is only set when in span
397
398            let biz_code = Uuid::new_v4().to_string();
399
400            {
401                let outer_span =
402                    tracing::info_span!("span1", span_pair = biz_code);
403
404                let span1_guard = outer_span.enter();
405                // Some code...
406                // outer_span.record("other_field", 2);
407                tracing::info!(body = "haha", code = "0");
408
409                assert_eq!(ctx.inner.body.to_plaint_string(), "haha");
410                assert_eq!(ctx.inner.span_pair, biz_code);
411                assert_eq!(ctx.inner.code, "0");
412
413                ctx.clear();
414
415                tracing::info!("kaka");
416                assert_eq!(ctx.inner.body.to_plaint_string(), "kaka");
417                assert_eq!(ctx.inner.span_pair, biz_code);
418
419                ctx.clear();
420                drop(span1_guard);
421                tracing::info!("haha");
422                assert_eq!(ctx.inner.body.to_plaint_string(), "haha");
423                assert_eq!(ctx.inner.span_pair, "");
424            }
425            // muti span
426            {
427                let outer_span = tracing::info_span!("span1", span_pair = biz_code);
428                let _span1_guard = outer_span.enter();
429
430                let inner_span = tracing::info_span!("span2", span_pair = "biz2");
431                let span2_guard = inner_span.enter();
432
433                tracing::info!("haha");
434                assert_eq!(ctx.inner.body.to_plaint_string(), "haha");
435                assert_eq!(ctx.inner.span_pair, "biz2");
436
437                tracing::info!(body = "info again", span_pair = "my_seriesId");
438                assert_eq!(ctx.inner.body.to_plaint_string(), "info again");
439                assert_eq!(ctx.inner.span_pair, "biz2");
440                // due to span no contain `seriesId`, here will no got the seriesId thought the event contain it
441
442                drop(span2_guard);
443                tracing::info!("wawa");
444                assert_eq!(ctx.inner.body.to_plaint_string(), "wawa");
445                assert_eq!(ctx.inner.span_pair, biz_code);
446
447                ctx.clear();
448            }
449        }
450    }
451
452    rusty_fork_test! {
453        #[test]
454        fn test_tokio_span() {
455            tokio::runtime::Builder::new_multi_thread()
456            .enable_all()
457            .build()
458            .unwrap()
459            .block_on( async {
460                    let mut ctx = TestLogCtx::default();
461                    let mut x: ThCommon = unsafe { mem::zeroed() };
462                    x.ctx = addr_of_mut!(ctx).cast();
463                    x.print_log_ex = Some(test_th_log);
464
465                    let layer = ThLayer::builder()
466                        .common(addr_of!(x).cast())
467                        .build()
468                        .unwrap();
469
470                    tracing_subscriber::registry().with(layer).init();
471
472                    let my_future = async {
473                        tracing::info!("Working..");
474                        assert_eq!(ctx.inner.span_pair, "asynctask");
475                        assert_eq!(ctx.inner.body.to_plaint_string(), "Working..");
476
477                        tokio::time::sleep(std::time::Duration::from_secs(1)).await;
478                        tracing::error!("Done..");
479
480                        assert_eq!(ctx.inner.span_pair, "asynctask");
481                        assert_eq!(ctx.inner.body.to_plaint_string(), "Done..");
482                    };
483
484                    let my_future2 = async {
485                        tracing::info!("Working..");
486                        assert_eq!(ctx.inner.span_pair, "asynctask2");
487                        assert_eq!(ctx.inner.body.to_plaint_string(), "Working..");
488
489                        tokio::time::sleep(std::time::Duration::from_secs(1)).await;
490                        tracing::error!("Done..");
491
492                        assert_eq!(ctx.inner.span_pair, "asynctask2");
493                        assert_eq!(ctx.inner.body.to_plaint_string(), "Done..");
494                    };
495
496                    let task1 = my_future.instrument(tracing::info_span!(
497                        "my_future",
498                        span_pair = "asynctask",
499
500                    ));
501                    let task2 = my_future2.instrument(tracing::info_span!(
502                        "my_future",
503                        span_pair = "asynctask2",
504
505                    ));
506                    tokio::join!(task1, task2);
507            })
508                }
509
510
511
512    }
513    rusty_fork_test! {
514        #[test]
515        fn test_case_get_span_field() {
516            let mut ctx = TestLogCtx::default();
517            let mut x: ThCommon = unsafe { mem::zeroed() };
518            x.ctx = addr_of_mut!(ctx).cast();
519            x.print_log_ex = Some(test_th_log);
520
521            let layer = ThLayer::builder()
522                .common(addr_of!(x).cast())
523                .build()
524                .unwrap();
525
526            tracing_subscriber::registry().with(layer).init();
527
528            {
529                let span_pair = Uuid::new_v4().to_string();
530
531
532                let outer_span = tracing::info_span!("outer", span_pair = span_pair);
533                let _guard = outer_span.enter();
534                let span_pair_out = String::new();
535                tracing::info!(
536                   _unsafe_get_span_pair_ = (std::ptr::addr_of!(span_pair_out) as usize),
537                );
538
539                assert_eq!(ctx.logstr().len(), 0);
540                assert_eq!(span_pair, span_pair);
541            }
542
543            {
544                let span_pair = Uuid::new_v4().to_string();
545                let outer_span = tracing::info_span!("outer", span_pair = span_pair);
546                let _guard = outer_span.enter();
547                for _ in 0..1000 {
548                    let span_pair_out = String::new();
549                    tracing::info!(_unsafe_get_span_pair_ = (std::ptr::addr_of!(span_pair_out) as usize));
550                    assert_eq!(ctx.logstr().len(), 0);
551                    assert_eq!(span_pair_out, span_pair);
552                }
553            }
554
555            for _ in 0..1000 {
556                let span_pair = Uuid::new_v4().to_string();
557                let outer_span = tracing::info_span!("outer", span_pair = span_pair);
558                let _guard = outer_span.enter();
559                let span_pair_out = String::new();
560                tracing::info!(_unsafe_get_span_pair_ = (std::ptr::addr_of!(span_pair_out) as usize));
561                assert_eq!(ctx.logstr().len(), 0);
562                assert_eq!(span_pair_out, span_pair);
563            }
564
565            let span_pair_out = String::new();
566            tracing::trace!(_unsafe_get_span_pair_ = (std::ptr::addr_of!(span_pair_out) as usize));
567            assert_eq!(span_pair_out, "");
568            assert_eq!(ctx.logstr().len(), 0);
569        }
570    }
571    rusty_fork_test! {
572
573        #[test]
574        fn test_case_fetch_span_pair() {
575            let mut ctx = TestLogCtx::default();
576            let mut x: ThCommon = unsafe { mem::zeroed() };
577            x.ctx = addr_of_mut!(ctx).cast();
578            x.print_log_ex = Some(test_th_log);
579            x.do_etc_ex = Some(test_do_etc);
580
581            let layer = ThLayer::builder()
582                .common(addr_of!(x).cast())
583                .build()
584                .unwrap();
585
586            tracing_subscriber::registry().with(layer).init();
587
588            let sp = tracing::info_span!("", { SPAN_PAIR } = { VAL_FETCH_PAIR });
589            let _ga = sp.enter();
590
591            tracing::info!("hh");
592
593            let v: HashMap<String, String> = serde_json::from_str(&ctx.inner.span_pair).unwrap();
594
595
596            assert_eq!(
597                HashMap::from([
598                    ("id".to_string(), "value".to_string()),
599                    ("id2".to_string(), "value2".to_string())
600                ]),
601                v
602            );
603        }
604    }
605
606    #[test]
607    fn test_case_tracing_span_fix_field() {
608        let mut ctx = TestLogCtx::default();
609        let mut x: ThCommon = unsafe { mem::zeroed() };
610        x.ctx = addr_of_mut!(ctx).cast();
611        x.print_log_ex = Some(test_th_log);
612        x.do_etc_ex = Some(test_do_etc);
613
614        let layer = ThLayer::builder()
615            .common(addr_of!(x).cast())
616            .build()
617            .unwrap();
618
619        tracing_subscriber::registry().with(layer).init();
620
621        let span = tracing::info_span!("SpanName", source_id = "push");
622        {
623            let _guard = span.enter();
624
625            tracing::info!("first example");
626
627            assert_eq!(ctx.logstr, "[tracing-th] 2 first example, source_id: push");
628        }
629        {
630            tracing::info!("first example");
631
632            assert_eq!(ctx.logstr, "[tracing-th] 2 first example");
633        }
634    }
635}
tracing_th/builder.rs

tracing_th/
builder.rs
